NLog and Application Insights Revisited

Just a few small changes to my NLog sample logging to Azure Application Insights.

I modified the application so I could provide the InstrumentationKey via the command line or the ApplicationInsights.Config file.(I have a minimalist config for this sample)

namespace devMobile.Azure.ApplicationInsightsNLogClient
{
   class Program
   {
      private static Logger log = LogManager.GetLogger(System.Reflection.MethodBase.GetCurrentMethod().DeclaringType.ToString());

      static void Main(string[] args)
      {
         if ((args.Length != 0) && (args.Length != 1))
         {
            Console.WriteLine("Usage ApplicationInsightsNLogClient");
            Console.WriteLine("      ApplicationInsightsNLogClient <instrumentationKey>");
            return;
         }

         if (args.Length == 1)
         {
            TelemetryConfiguration.Active.InstrumentationKey = args[0];
         }

         log.Trace("This is an nLog Trace message");
         log.Debug("This is an nLog Debug message");
         log.Info("This is an nLog Info message");
         log.Warn("This is an nLog Warning message");
         log.Error("This is an nLog Error message");
         log.Fatal("This is an nLog Fatal message");

         TelemetryConfiguration.Active.TelemetryChannel.Flush();

			Console.WriteLine("Press <enter> to exit>");
			Console.ReadLine();
		}
	}
}

Code for my sample console application is here.

Azure Function Log4Net configuration Revisted

In a previous post I showed how I configured Apache Log4Net and Azure Application Insights to work with an Azure Function, this is the code updated to .Net Core V3.1.

With the different versions of the libraries involved (Early April 2020) this was what I found worked for me so YMMV.

Initially the logging to Application Insights wasn’t working even though it was configured in the ApplicationIngisghts.config file. After some experimentation I found setting the APPINSIGHTS_INSTRUMENTATIONKEY environment variable was the only way I could get it to work.

namespace ApplicationInsightsAzureFunctionLog4NetClient
{
	using System;
	using System.IO;
	using System.Reflection;
	using log4net;
	using log4net.Config;
	using Microsoft.ApplicationInsights;
	using Microsoft.ApplicationInsights.Extensibility;
	using Microsoft.Azure.WebJobs;

	public static class ApplicationInsightsTimer
	{
		[FunctionName("ApplicationInsightsTimerLog4Net")]
		public static void Run([TimerTrigger("0 */1 * * * *")]TimerInfo myTimer, ExecutionContext executionContext)
		{
         ILog log = log4net.LogManager.GetLogger(System.Reflection.MethodBase.GetCurrentMethod().DeclaringType);

         using (TelemetryConfiguration telemetryConfiguration = TelemetryConfiguration.CreateDefault())
         {
            TelemetryClient telemetryClient = new TelemetryClient(telemetryConfiguration);
 
            var logRepository = LogManager.GetRepository(Assembly.GetEntryAssembly());
            XmlConfigurator.Configure(logRepository, new FileInfo(Path.Combine(executionContext.FunctionAppDirectory, "log4net.config")));

            log.Debug("This is a Log4Net Debug message");
            log.Info("This is a Log4Net Info message");
            log.Warn("This is a Log4Net Warning message");
            log.Error("This is a Log4Net Error message");
            log.Fatal("This is a Log4Net Fatal message");

            telemetryClient.Flush();
         }
      }
   }
}

I did notice that there were a number of exceptions which warrant further investigation.

'func.exe' (CoreCLR: clrhost): Loaded 'C:\Users\BrynLewis\source\repos\AzureApplicationInsightsClients\ApplicationInsightsAzureFunctionLog4NetClient\bin\Debug\netcoreapp3.1\bin\log4net.dll'. 
Exception thrown: 'System.IO.FileNotFoundException' in System.Private.CoreLib.dll
Exception thrown: 'System.IO.FileNotFoundException' in System.Private.CoreLib.dll
Exception thrown: 'System.IO.FileNotFoundException' in System.Private.CoreLib.dll
Exception thrown: 'System.IO.FileNotFoundException' in System.Private.CoreLib.dll
Exception thrown: 'System.IO.FileNotFoundException' in System.Private.CoreLib.dll
Exception thrown: 'System.IO.FileNotFoundException' in System.Private.CoreLib.dll
'func.exe' (CoreCLR: clrhost): Loaded 'C:\Users\BrynLewis\AppData\Local\AzureFunctionsTools\Releases\2.47.1\cli_x64\System.Xml.XmlDocument.dll'. 
'func.exe' (CoreCLR: clrhost): Loaded 'C:\Users\BrynLewis\source\repos\AzureApplicationInsightsClients\ApplicationInsightsAzureFunctionLog4NetClient\bin\Debug\netcoreapp3.1\bin\Microsoft.ApplicationInsights.Log4NetAppender.dll'. 
'func.exe' (CoreCLR: clrhost): Loaded 'C:\Users\BrynLewis\AppData\Local\AzureFunctionsTools\Releases\2.47.1\cli_x64\System.Reflection.TypeExtensions.dll'. 
Application Insights Telemetry: {"name":"Microsoft.ApplicationInsights.64b1950b90bb46aaa36c26f5dce0cad3.Message","time":"2020-04-09T09:22:33.2274370Z","iKey":"1234567890123-1234-12345-123456789012","tags":{"ai.cloud.roleInstance":"DESKTOP-C9IPNQ1","ai.operation.id":"bc6c4d10cebd954c9d815ad06add2582","ai.operation.parentId":"|bc6c4d10cebd954c9d815ad06add2582.d8fa83b88b175348.","ai.operation.name":"ApplicationInsightsTimerLog4Net","ai.location.ip":"0.0.0.0","ai.internal.sdkVersion":"log4net:2.13.1-12554","ai.internal.nodeName":"DESKTOP-C9IPNQ1"},"data":{"baseType":"MessageData","baseData":{"ver":2,"message":"This is a Log4Net Info message","severityLevel":"Information","properties":{"Domain":"NOT AVAILABLE","InvocationId":"91063ef9-70d0-4318-a1e0-e49ade07c51b","ThreadName":"14","ClassName":"?","LogLevel":"Information","ProcessId":"15824","Category":"Function.ApplicationInsightsTimerLog4Net","MethodName":"?","Identity":"NOT AVAILABLE","FileName":"?","LoggerName":"ApplicationInsightsAzureFunctionLog4NetClient.ApplicationInsightsTimer","LineNumber":"?"}}}}

The latest code for my Azure Function Log4net to Applications Insights sample is available on here.

Apache Log4net .NET Core and Application Insights

In the previous post I revisited my sample .NET application that used Apache log4net and Azure Application Insights. This post updates the application to .NET Core V3.1.

I had to remove the ability to set the instrumentation key via the command line as I couldn’t get it to work.

I tried initialising the logger after loading the telemetry configuration, passing the InstrumentationKey in as a parameter of the TelemetryConfiguration constructor etc. and it made no difference.

The only other option that appeared to work was setting the instrumentation key via an Environment Variable called APPINSIGHTS_INSTRUMENTATIONKEY

   class Program
   {
      private static ILog log = log4net.LogManager.GetLogger(System.Reflection.MethodBase.GetCurrentMethod().DeclaringType);

      static void Main(string[] args)
      {
         using (TelemetryConfiguration telemetryConfiguration = TelemetryConfiguration.CreateDefault())
         {
            TelemetryClient telemetryClient = new TelemetryClient(telemetryConfiguration);

            var logRepository = LogManager.GetRepository(Assembly.GetEntryAssembly());
            XmlConfigurator.Configure(logRepository, new FileInfo(Path.Combine(Environment.CurrentDirectory, "log4net.config")));

            log.Debug("This is a Log4Net Debug message");
            log.Info("This is a Log4Net Info message");
            log.Warn("This is a Log4Net Warning message");
            log.Error("This is a Log4Net Error message");
            log.Fatal("This is a Log4Net Fatal message");

            telemetryClient.Flush();
         }

         Console.WriteLine("Press <enter> to exit");
         Console.ReadLine();
      }
   }

I updated the Log4Net setup to use the ManagedColoredConsoleAppender which required a couple of modifications to the Log4Net.config file. (Initially it was failing because I was using the non US spelling of log4net.Appender.ManagedColoredConsoleAppender)

 <appender name="ColoredConsoleAppender" type="log4net.Appender.ManagedColoredConsoleAppender">
      <mapping>
         <level value="ERROR" />
         <foreColor value="White" />
         <backColor value="Red" />
      </mapping>
      <mapping>
         <level value="DEBUG" />
         <backColor value="Green" />
      </mapping>
      <layout type="log4net.Layout.PatternLayout">
         <conversionPattern value="%date [%thread] %-5level %logger [%property{NDC}] - %message%newline" />
      </layout>
   </appender>

I did notice that after a several seconds while waiting for the enter key to be pressed there were a number of exceptions which warrants further investigation.

devMobile.Azure.ApplicationInsightsLog4NetCoreClient.Program: 2020-04-08 17:14:23,455 [1] FATAL devMobile.Azure.ApplicationInsightsLog4NetCoreClient.Program – This is a Log4Net Fatal message
‘ApplicationInsightsLog4NetCoreClient.exe’ (CoreCLR: clrhost): Loaded ‘C:\Program Files\dotnet\shared\Microsoft.NETCore.App\3.1.3\System.Security.Cryptography.Encoding.dll’.
Exception thrown: ‘System.Threading.Tasks.TaskCanceledException’ in System.Private.CoreLib.dll
Exception thrown: ‘System.Threading.Tasks.TaskCanceledException’ in System.Private.CoreLib.dll
Exception thrown: ‘System.Threading.Tasks.TaskCanceledException’ in System.Private.CoreLib.dll
Exception thrown: ‘System.Threading.Tasks.TaskCanceledException’ in System.Private.CoreLib.dll
Exception thrown: ‘System.Threading.Tasks.TaskCanceledException’ in System.Net.Http.dll
Exception thrown: ‘System.Threading.Tasks.TaskCanceledException’ in System.Private.CoreLib.dll
Exception thrown: ‘System.Threading.Tasks.TaskCanceledException’ in System.Private.CoreLib.dll
Exception thrown: ‘System.Threading.Tasks.TaskCanceledException’ in System.Private.CoreLib.dll
Exception thrown: ‘System.Threading.Tasks.TaskCanceledException’ in System.Net.Http.dll
Exception thrown: ‘System.Threading.Tasks.TaskCanceledException’ in System.Private.CoreLib.dll
Exception thrown: ‘System.Threading.Tasks.TaskCanceledException’ in System.Net.Http.dll
Exception thrown: ‘System.Threading.Tasks.TaskCanceledException’ in System.Private.CoreLib.dll
Exception thrown: ‘System.Threading.Tasks.TaskCanceledException’ in System.Private.CoreLib.dll
Exception thrown: ‘System.Threading.Tasks.TaskCanceledException’ in System.Private.CoreLib.dll
The program ‘[13920] ApplicationInsightsLog4NetCoreClient.exe’ has exited with code 0 (0x0).
The program ‘[13920] ApplicationInsightsLog4NetCoreClient.exe: Program Trace’ has exited with code 0 (0x0).

A sample project is available here.

“Don’t forget to flush” .Net Core Application Insights

This post updates a previous post “Don’t forget to flush Application insights Revisited” for .Net Core 3.X and shows the small change required by the deprecation of on of the TelemetryClient constructor overloads.

warning CS0618: ‘TelemetryClient.TelemetryClient()’ is obsolete: ‘We do not recommend using TelemetryConfiguration.Active on .NET Core. See https://github.com/microsoft/ApplicationInsights-dotnet/issues/1152 for more details’

   class Program
   {
      static void Main(string[] args)
      {
#if INSTRUMENTATION_KEY_TELEMETRY_CONFIGURATION
         if (args.Length != 1)
         {
            Console.WriteLine("Usage AzureApplicationInsightsClientConsole <instrumentationKey>");
            return;
         }

         TelemetryConfiguration telemetryConfiguration = new TelemetryConfiguration(args[0]);
         TelemetryClient telemetryClient = new TelemetryClient(telemetryConfiguration);
         telemetryClient.TrackTrace("INSTRUMENTATION_KEY_TELEMETRY_CONFIGURATION", SeverityLevel.Information);
#endif
#if INSTRUMENTATION_KEY_APPLICATION_INSIGHTS_CONFIG
         TelemetryConfiguration telemetryConfiguration = TelemetryConfiguration.CreateDefault();
         TelemetryClient telemetryClient = new TelemetryClient(telemetryConfiguration);
         telemetryClient.TrackTrace("INSTRUMENTATION_KEY_APPLICATION_INSIGHTS_CONFIG", SeverityLevel.Information);
#endif
         telemetryClient.Context.User.Id = Environment.UserName;
         telemetryClient.Context.Device.Id = Environment.MachineName;
         telemetryClient.Context.Operation.Name = "Test harness";

         telemetryClient.TrackTrace("This is a .Net Core AI API Verbose message", SeverityLevel.Verbose);
         telemetryClient.TrackTrace("This is a .Net Core AI API Information message", SeverityLevel.Information);
         telemetryClient.TrackTrace("This is a .Net Core AI API Warning message", SeverityLevel.Warning);
         telemetryClient.TrackTrace("This is a .Net Core AI API Error message", SeverityLevel.Error);
         telemetryClient.TrackTrace("This is a .Net Core AI API Critical message", SeverityLevel.Critical);

         telemetryClient.Flush();

         telemetryConfiguration.Dispose(); // In real-world use a using or similar approach to ensure cleaned up

         Console.WriteLine("Press <enter> to exit");
         Console.ReadLine();
      }
   }

A sample project is available here

Apache Log4net and Application Insights Revisited

In a previous post I showed how we configured a client’s application to use Apache log4net and Azure Application Insights.

I modified the code to allow the Instrumentation Key input via a command line parameter or from the ApplicationInsights.config file.

class Program
{
   private static ILog log = log4net.LogManager.GetLogger(System.Reflection.MethodBase.GetCurrentMethod().DeclaringType);

   static void Main(string[] args)
   {
      if (( args.Length != 0) && (args.Length != 1 ))
      {
         Console.WriteLine("Usage AzureApplicationInsightsClientConsole");
         Console.WriteLine("      AzureApplicationInsightsClientConsole <instrumentationKey>");
         return;
      }

      if (args.Length == 1)
      {
         TelemetryConfiguration.Active.InstrumentationKey = args[0];
      }

      log.Debug("This is a Log4Net Debug message");
      log.Info("This is a Log4Net Info message");
      log.Warn("This is a Log4Net Warning message");
      log.Error("This is an Log4Net Error message");
      log.Fatal("This is a Log4Net Fatal message");

      TelemetryConfiguration.Active.TelemetryChannel.Flush();

      Console.WriteLine("Press <enter> to exit>");
      Console.ReadLine();
   }
}

I updated the Log4Net setup to use the ManagedColoredConsoleAppender which required a couple of modifications to the Log4Net.config file. (I had to remove HighIntensity)

 <appender name="ColoredConsoleAppender" type="log4net.Appender.ManagedColoredConsoleAppender">
      <mapping>
         <level value="ERROR" />
         <foreColor value="White" />
         <backColor value="Red" />
      </mapping>
      <mapping>
         <level value="DEBUG" />
         <backColor value="Green" />
      </mapping>
      <layout type="log4net.Layout.PatternLayout">
         <conversionPattern value="%date [%thread] %-5level %logger [%property{NDC}] - %message%newline" />
      </layout>
   </appender>

A sample project is available here.

“Don’t forget to flush” Application Insights Revisited

This post revisits a previous post “Don’t forget to flush” Application insights and shows how to configure the instrumentation key in code or via the ApplicationInsights.config file.

 class Program
   {
      static void Main(string[] args)
      {
#if INSTRUMENTATION_KEY_TELEMETRY_CONFIGURATION
         if (args.Length != 1)
         {
            Console.WriteLine("Usage AzureApplicationInsightsClientConsole <instrumentationKey>");
            return;
         }

         TelemetryConfiguration telemetryConfiguration = new TelemetryConfiguration(args[0]);
         TelemetryClient telemetryClient = new TelemetryClient(telemetryConfiguration);
         telemetryClient.TrackTrace("INSTRUMENTATION_KEY_TELEMETRY_CONFIGURATION", SeverityLevel.Information);
#endif
#if INSTRUMENTATION_KEY_APPLICATION_INSIGHTS_CONFIG
         TelemetryClient telemetryClient = new TelemetryClient();
         telemetryClient.TrackTrace("INSTRUMENTATION_KEY_APPLICATION_INSIGHTS_CONFIG", SeverityLevel.Information);
#endif
         telemetryClient.TrackTrace("This is an AI API Verbose message", SeverityLevel.Verbose);
         telemetryClient.TrackTrace("This is an AI API Information message", SeverityLevel.Information);
         telemetryClient.TrackTrace("This is an AI API Warning message", SeverityLevel.Warning);
         telemetryClient.TrackTrace("This is an AI API Error message", SeverityLevel.Error);
         telemetryClient.TrackTrace("This is an AI API Critical message", SeverityLevel.Critical);

         telemetryClient.Flush();

         Console.WriteLine("Press <enter> to exit");
         Console.ReadLine();
      }

A sample project is available here

Azure IoT Hub, Event Grid to Application Insights

For a second Proof of Concept (PoC) I wanted to upload sensor data from my MQTT LoRa Telemetry Field Gateway to an Azure IoT Hub, then using Azure EventGrid subscribe to the stream of telemetry data events, logging the payloads in Azure Application Insights (the aim was minimal code so no database etc.).

The first step was to create and deploy a simple Azure Function for unpacking the telemetry event payload.

Azure IoT Hub Azure Function Handler

Then wire the Azure function to the Microsoft.Devices.Device.Telemetry Event Type

Azure IoT Hub Event Metrics

On the Windows 10 IoT Core device in the Event Tracing Window(ETW) logging on the device I could see LoRa messages arriving and being unpacked.

Windows 10 Device ETW showing message payload

Then in Application Insights after some mucking around with code I could see in a series of Trace statements the event payload as it was unpacked.

{"id":"29108ebf-e5d5-7b95-e739-7d9048209d53","topic":"/SUBSCRIPTIONS/12345678-9012-3456-7890-123456789012/RESOURCEGROUPS/AZUREIOTHUBEVENTGRIDAZUREFUNCTION/PROVIDERS/MICROSOFT.DEVICES/IOTHUBS/FIELDGATEWAYHUB",
"subject":"devices/MQTTNetClient",
"eventType":"Microsoft.Devices.DeviceTelemetry",
"eventTime":"2020-02-01T04:30:51.427Z",
"data":
{
 "properties":{},
"systemProperties":{"iothub-connection-device-id":"MQTTNetClient","iothub-connection-auth-method":"{\"scope\":\"device\",\"type\":\"sas\",\"issuer\":\"iothub\",\"acceptingIpFilterRule\":null}",
"iothub-connection-auth-generation-id":"637149890997219611",
"iothub-enqueuedtime":"2020-02-01T04:30:51.427Z",
"iothub-message-source":"Telemetry"
},
"body":"eyJPZmZpY2VUZW1wZXJhdHVyZSI6IjIyLjUiLCJPZmZpY2VIdW1pZGl0eSI6IjkyIn0="
},
"dataVersion":"",
"metadataVersion":"1"
}
Application Insights logging with message unpacking
Application Insights logging message payload

Then in the last log entry the decoded message payload

/*
    Copyright ® 2020 Feb devMobile Software, All Rights Reserved
 
    MIT License

    Permission is hereby granted, free of charge, to any person obtaining a copy
    of this software and associated documentation files (the "Software"), to deal
    in the Software without restriction, including without limitation the rights
    to use, copy, modify, merge, publish, distribute, sublicense, and/or sell
    copies of the Software, and to permit persons to whom the Software is
    furnished to do so, subject to the following conditions:

    The above copyright notice and this permission notice shall be included in all
    copies or substantial portions of the Software.

    THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR
    IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY,
    FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE
    AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER
    LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM,
    OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN THE
    SOFTWARE

    Default URL for triggering event grid function in the local environment.
    http://localhost:7071/runtime/webhooks/EventGrid?functionName=functionname
 */
namespace EventGridProcessorAzureIotHub
{
   using System;
   using System.IO;
   using System.Reflection;

   using Microsoft.Azure.WebJobs;
   using Microsoft.Azure.EventGrid.Models;
   using Microsoft.Azure.WebJobs.Extensions.EventGrid;

   using log4net;
   using log4net.Config;
   using Newtonsoft.Json;

   public static class Telemetry
    {
        [FunctionName("Telemetry")]
        public static void Run([EventGridTrigger]Microsoft.Azure.EventGrid.Models.EventGridEvent eventGridEvent, ExecutionContext executionContext )//, TelemetryClient telemetryClient)
        {
			ILog log = log4net.LogManager.GetLogger(System.Reflection.MethodBase.GetCurrentMethod().DeclaringType);

		   var logRepository = LogManager.GetRepository(Assembly.GetEntryAssembly());
			XmlConfigurator.Configure(logRepository, new FileInfo(Path.Combine(executionContext.FunctionAppDirectory, "log4net.config")));

         log.Info($"eventGridEvent.Data-{eventGridEvent}");

         log.Info($"eventGridEvent.Data.ToString()-{eventGridEvent.Data.ToString()}");

        IotHubDeviceTelemetryEventData iOThubDeviceTelemetryEventData = (IotHubDeviceTelemetryEventData)JsonConvert.DeserializeObject(eventGridEvent.Data.ToString(), typeof(IotHubDeviceTelemetryEventData));

         log.Info($"iOThubDeviceTelemetryEventData.Body.ToString()-{iOThubDeviceTelemetryEventData.Body.ToString()}");

         byte[] base64EncodedBytes = System.Convert.FromBase64String(iOThubDeviceTelemetryEventData.Body.ToString());

         log.Info($"System.Text.Encoding.UTF8.GetString(-{System.Text.Encoding.UTF8.GetString(base64EncodedBytes)}");
      }
	}
}

Overall it took roughly half a page of code (mainly generated by a tool) to unpack and log the contents of an Azure IoT Hub EventGrid payload to Application Insights.

Azure IOT Hub and Event Grid Part1

I have one an Azure IoT Hub LoRa Telemetry Field Gateway running in my office and I wanted to process the data collected by the sensors around my property without using a Software as a Service(SaaS) Internet of Things (IoT) package.

Rather than lots of screen grabs of my configuration steps I figured people reading this series of posts would be able to figure the details out themselves.

Raspberry PI with M2M LoRa Hat

I created an Azure Resource Group for this project, and created an Azure IoT Hub.

Azure Resource Group with IoT Hub

I then provisioned an Azure IoT Hub device so I could get the connection string for my Windows 10 Azure IoT Hub LoRa Telemetry Field gateway.

LoRa Field Gateway Provisioned in Azure IoT Hub

I downloaded the JSON configuration file template from my Windows 10 device (which is created on first startup after installation) and configured the Azure IoT Hub connection string.

{
   "AzureIoTHubDeviceConnectionString": "HostName=FieldGatewayHub.azure-devices.net;DeviceId=LoRa915MHz;SharedAccessKey=123456789012345678901234567890123456789/arg=",
   "AzureIoTHubTransportType": "amqp",
   "SensorIDIsDeviceIDSensorID": false,
   "Address": "LoRaIoT1",
   "Frequency": 915000000.0,
   "PABoost": true
}

I then uploaded this to my Windows 10 IoT Core device and restarted the Azure IoT Hub Field gateway so it picked up the new settings.

I could then see on the device messages from sensor nodes being unpacked and uploaded to my Azure IoT Hub.

ETW logging on device

In the Azure IoT Hub metrics I graphed the number of devices connected and the number of telemetry messages sent and could see my device connect then start uploading telemetry.

Azure IoT Hub metrics

One of my customers uses Azure Event Grid for application integration and I wanted to explore using it in an IoT solution. The first step was to create an Event Grid Domain.

I then used the Azure IoT Hub Events tab to wire up these events.

  • Microsoft.Devices.DeviceConnected
  • Microsoft.Devices.DeviceDisconnected
  • Microsoft.Devices.DeviceTelemetry
Azure IoT Hub Event Metrics

To confirm my event subscriptions were successful I previously found the “simplest” approach was to use an Azure storage queue endpoint. I had to create an Azure Storage Account with two Azure Storage Queues one for device connectivity (.DeviceConnected & .DeviceDisconnected) events and the other for device telemetry (.DeviceTelemetry) events.

I created a couple of other subscriptions so I could compare the different Event schemas (Event Grid Schema & Cloud Event Schema v1.0). At this stage I didn’t configure any Filters or Additional Features.

Azure IoT Hub Telemetry Event Metrics

I use Cerebrate Cerculean for monitoring and managing a couple of other customer projects so I used it to inspect the messages in the storage queues.

Cerebrate Ceculean Storage queue Inspector

The message are quite verbose

{
"id":"b48b6376-b7f4-ee7d-82d9-12345678901a",
"source":"/SUBSCRIPTIONS/12345678-901234789-0123-456789012345/RESOURCEGROUPS/AZUREIOTHUBEVENTGRIDAZUREFUNCTION/PROVIDERS/MICROSOFT.DEVICES/IOTHUBS/FIELDGATEWAYHUB",
"specversion":"1.0",
"type":"Microsoft.Devices.DeviceTelemetry",
"dataschema":"#",
"subject":"devices/LoRa915MHz",
"time":"2020-01-24T04:27:30.842Z","data":
{"properties":{},
"systemProperties":{"iothub-connection-device-id":"LoRa915MHz",
"iothub-connection-auth-method":"{\"scope\":\"device\",\"type\":\"sas\",\"issuer\":\"iothub\",\"acceptingIpFilterRule\":null}",
"iothub-connection-auth-generation-id":"637149227434620853",
"iothub-enqueuedtime":"2020-01-24T04:27:30.842Z",
"iothub-message-source":"Telemetry"},
"body":"eyJQYWNrZXRTTlIiOiIxMC4wIiwiUGFja2V0UlNTSSI6LTY5LCJSU1NJIjotMTA5LCJEZXZpY2VBZGRyZXNzQkNEIjoiNEQtNjEtNjQtNzUtNjktNkUtNkYtMzIiLCJhdCI6Ijc2LjYiLCJhaCI6IjU4Iiwid3NhIjoiMiIsIndzZyI6IjUiLCJ3ZCI6IjMyMi44OCIsInIiOiIwLjAwIn0="
}
}

The message payload is base64 encoded, so I used an online tool to decode it.

{
 PacketSNR":"10.0",
"PacketRSSI":-69,
"RSSI":-109,
"DeviceAddressBCD":"4D-61-64-75-69-6E-6F-32",
"at":"76.6",
"ah":"58",
"wsa":"2",
"wsg":"5",
"wd":"322.88",
"r":"0.00"
}

Without writing any code (I will script the configuration) I could upload sensor data to an Azure IoT Hub, subscribe to a selection of events the Azure IoT Hub publishes and then inspect them in an Azure Storage Queue.

I did notice that the .DeviceConnected and .DeviceDisconnected events did take a while to arrive. When I started the field gateway application on the device I would get several DeviceTelemetry events before the DeviceConnected event arrived.

Azure IoT Hub SAS Tokens revisited yet again

Based my previous post on SAS Token Expiry I wrote a test harness to better understand DateTimeOffset

using System;

namespace UnixEpochTester
{
   class Program
   {
      static void Main(string[] args)
      {
         Console.WriteLine($"DIY                {new DateTime(1970, 1, 1, 0, 0, 0, DateTimeKind.Utc)}");
         Console.WriteLine($"DateTime.UnixEpoch {DateTime.UnixEpoch} {DateTime.UnixEpoch.Kind}");
         Console.WriteLine();

         TimeSpan fromUnixEpochNow = DateTime.UtcNow - DateTime.UnixEpoch;
         Console.WriteLine($"Epoc now {fromUnixEpochNow} {fromUnixEpochNow.TotalSeconds.ToString("f0")} sec");
         Console.WriteLine();

         TimeSpan fromUnixEpochFixed = new DateTime(2019, 11, 30, 2, 0, 0, DateTimeKind.Utc) - DateTime.UnixEpoch;
         Console.WriteLine($"Epoc  {fromUnixEpochFixed} {fromUnixEpochFixed.TotalSeconds.ToString("f0")} sec");
         Console.WriteLine();

         DateTimeOffset dateTimeOffset = new DateTimeOffset( new DateTime( 2019,11,30,2,0,0, DateTimeKind.Utc));
         Console.WriteLine($"Epoc DateTimeOffset {fromUnixEpochFixed} {dateTimeOffset.ToUnixTimeSeconds()}");
         Console.WriteLine();

         TimeSpan fromEpochStart = new DateTime(2019, 11, 30, 2, 0, 0, DateTimeKind.Utc) - DateTime.UnixEpoch;
         Console.WriteLine($"Epoc DateTimeOffset {fromEpochStart} {fromEpochStart.TotalSeconds.ToString("F0")}");
         Console.WriteLine();


         // https://www.epochconverter.com/ matches
         // https://www.unixtimestamp.com/index.php matches

         Console.WriteLine("Press ENTER to exit");
         Console.ReadLine();
      }
   }
}

I validated my numbers against a couple of online calculators and they matched which was a good start.

DateTimeOffset test harness

As I was testing my Azure MQTT Test Client I had noticed some oddness with MQTT connection timeouts.

string token = generateSasToken($"{server}/devices/{clientId}", password, "", new TimeSpan(0,5,0));
1/12/2019 1:29:52 PM> Device: [MQTTLoRa915MHz], Data:[{"OfficeTemperature":"22.391","OfficeHumidity":"93"}]
1/12/2019 1:30:22 PM> Device: [MQTTLoRa915MHz], Data:[{"OfficeTemperature":"22.29","OfficeHumidity":"64"}]
...
1/12/2019 1:43:56 PM> Device: [MQTTLoRa915MHz], Data:[{"OfficeTemperature":"22.591","OfficeHumidity":"98"}]
1/12/2019 1:44:26 PM> Device: [MQTTLoRa915MHz], Data:[{"OfficeTemperature":"22.754","OfficeHumidity":"68"}]


string token = generateSasToken($"{server}/devices/{clientId}", password, "", new TimeSpan(0,5,0));
1/12/2019 1:29:52 PM> Device: [MQTTLoRa915MHz], Data:[{"OfficeTemperature":"22.391","OfficeHumidity":"93"}]
1/12/2019 1:30:22 PM> Device: [MQTTLoRa915MHz], Data:[{"OfficeTemperature":"22.29","OfficeHumidity":"64"}]
...
1/12/2019 2:01:37 PM> Device: [MQTTLoRa915MHz], Data:[{"OfficeTemperature":"22.334","OfficeHumidity":"79"}]
1/12/2019 2:02:07 PM> Device: [MQTTLoRa915MHz], Data:[{"OfficeTemperature":"22.503","OfficeHumidity":"49"}]


string token = generateSasToken($"{server}/devices/{clientId}", password, "", new TimeSpan(0,5,0));
2/12/2019 9:27:21 PM> Device: [MQTTLoRa915MHz], Data:[{"OfficeTemperature":"22.196","OfficeHumidity":"61"}]
2/12/2019 9:27:51 PM> Device: [MQTTLoRa915MHz], Data:[{"OfficeTemperature":"22.788","OfficeHumidity":"91"}]
...
2/12/2019 9:36:24 PM> Device: [MQTTLoRa915MHz], Data:[{"OfficeTemperature":"22.670","OfficeHumidity":"64"}]
2/12/2019 9:36:54 PM> Device: [MQTTLoRa915MHz], Data:[{"OfficeTemperature":"22.836","OfficeHumidity":"94"}]


string token = generateSasToken($"{server}/devices/{clientId}", password, "", new TimeSpan(0,5,0));
2/12/2019 9:40:52 PM> Device: [MQTTLoRa915MHz], Data:[{"OfficeTemperature":"22.46","OfficeHumidity":"92"}]
2/12/2019 9:41:22 PM> Device: [MQTTLoRa915MHz], Data:[{"OfficeTemperature":"22.443","OfficeHumidity":"62"}]
...
2/12/2019 9:50:55 PM> Device: [MQTTLoRa915MHz], Data:[{"OfficeTemperature":"22.742","OfficeHumidity":"95"}]


string token = generateSasToken($"{server}/devices/{clientId}", password, "", new TimeSpan(0,10,0));
approx 15min as only 30 sec resolution
1/12/2019 12:50:23 PM> Device: [MQTTLoRa915MHz], Data:[{"OfficeTemperature":"22.630","OfficeHumidity":"65"}]
1/12/2019 12:50:53 PM> Device: [MQTTLoRa915MHz], Data:[{"OfficeTemperature":"22.798","OfficeHumidity":"95"}]
...
1/12/2019 1:03:59 PM> Device: [MQTTLoRa915MHz], Data:[{"OfficeTemperature":"22.677","OfficeHumidity":"41"}]
1/12/2019 1:04:30 PM> Device: [MQTTLoRa915MHz], Data:[{"OfficeTemperature":"22.26","OfficeHumidity":"72"}]


string token = generateSasToken($"{server}/devices/{clientId}", password, "", new TimeSpan(0,10,0));
approx 15min as only 30 sec resolution
1/12/2019 1:09:30 PM> Device: [MQTTLoRa915MHz], Data:[{"OfficeTemperature":"22.106","OfficeHumidity":"72"}]
1/12/2019 1:10:00 PM> Device: [MQTTLoRa915MHz], Data:[{"OfficeTemperature":"22.463","OfficeHumidity":"42"}]
...
1/12/2019 1:23:35 PM> Device: [MQTTLoRa915MHz], Data:[{"OfficeTemperature":"22.366","OfficeHumidity":"77"}]
1/12/2019 1:24:05 PM> Device: [MQTTLoRa915MHz], Data:[{"OfficeTemperature":"22.537","OfficeHumidity":"47"}]

The dataset with the 5 minute expiry which remained connected for approximately 30 mins was hopefully a configuration issue.

The updated SAS Token code not uses ToUnixTimeSeconds to eliminate the scope for local vs. UTC issues.

      public static string generateSasToken(string resourceUri, string key, string policyName, TimeSpan timeToLive)
      {
         DateTimeOffset expiryDateTimeOffset = new DateTimeOffset(DateTime.UtcNow.Add(timeToLive));

         string expiryEpoch = expiryDateTimeOffset.ToUnixTimeSeconds().ToString();
         string stringToSign = WebUtility.UrlEncode(resourceUri) + "\n" + expiryEpoch;

         HMACSHA256 hmac = new HMACSHA256(Convert.FromBase64String(key));
         string signature = Convert.ToBase64String(hmac.ComputeHash(Encoding.UTF8.GetBytes(stringToSign)));

         string token = $"SharedAccessSignature sr={WebUtility.UrlEncode(resourceUri)}&sig={WebUtility.UrlEncode(signature)}&se={expiryEpoch}";

         if (!String.IsNullOrEmpty(policyName))
         {
            token += "&skn=" + policyName;
         }

         return token;
      }

I need to test the expiry of my SAS Tokens some more especially with the client running on my development machine (NZT which is currently UTC+13) and in Azure (UTC timezone)

Azure IoT Hub MQTT LoRa Field Gateway

Back in April I started working on an MQTT LoRa Field gateway which was going to support a selection of different Software as a service(SaaS) Internet of Things IoT) platforms.

I now have a working Azure IoT Hub plug-in (Azure IoT Central support as planned as well) with the first iteration focused on Device to Cloud (D2C) messaging. In a future iteration I will add Cloud to Device messaging(C2D).

My applications use a lightweight, easy to implemented protocol which is intended for hobbyist and educational use rather than commercial applications (I have been working on a more secure version as yet another side project)

I have a number of sample Arduino with Dragino LoRa Shield for Arduino, MakerFabs Maduino, Dragino LoRa Mini Dev, M2M Low power Node and Netduino with Elecrow LoRa RFM95 Shield etc. clients. These work with both my platform specific (Adafruit.IO, Azure IoT Hub/Central) gateways and protocol specific field gateways.

Azure IoT Hub Device Explorer Data Display

When the application is first started it creates a minimal configuration file which should be downloaded, the missing information filled out, then uploaded using the File explorer in the Windows device portal.

{
  "MQTTUserName": "YourIoTHubHub.azure-devices.net/MQTTLoRa915MHz/api-version=2018-06-30",
  "MQTTPassword": "SharedAccessSignature sr=YourIoTHubHub.azure-devices.net%2Fdevices%2FMQTTLoRa915MHz&sig=123456789012345678901234567890123456789012345%3D&se=1574673583",
  "MQTTClientID": "MQTTLoRa915MHz",
  "MQTTServer": "YourIoTHubHub.azure-devices.net",
  "Address": "LoRaIoT1",
  "Frequency": 915000000.0,
  "MessageHandlerAssembly": "Mqtt.IoTCore.FieldGateway.LoRa.AzureIoTHub",
  "PlatformSpecificConfiguration": ""
}

The application logs debugging information to the Windows 10 IoT Core ETW logging Microsoft-Windows-Diagnostics-LoggingChannel

MQTT LoRa Gateway with Azure IoT Hub plug-in

The message handler uploads all values in an inbound messages in one MQTT message.

namespace devMobile.Mqtt.IoTCore.FieldGateway
{
   using System;
   using System.Diagnostics;
   using System.Text;
   using Windows.Foundation.Diagnostics;

   using devMobile.IoT.Rfm9x;
   using MQTTnet;
   using MQTTnet.Client;
   using Newtonsoft.Json.Linq;
   using Newtonsoft.Json;

   public class MessageHandler : IMessageHandler
   {
      private LoggingChannel Logging { get; set; }
      private IMqttClient MqttClient { get; set; }
      private Rfm9XDevice Rfm9XDevice { get; set; }
      private string PlatformSpecificConfiguration { get; set; }

      void IMessageHandler.Initialise(LoggingChannel logging, IMqttClient mqttClient, Rfm9XDevice rfm9XDevice, string platformSpecificConfiguration)
      {
         LoggingFields processInitialiseLoggingFields = new LoggingFields();

         this.Logging = logging;
         this.MqttClient = mqttClient;
         this.Rfm9XDevice = rfm9XDevice;
         this.PlatformSpecificConfiguration = platformSpecificConfiguration;
      }

      async void IMessageHandler.Rfm9XOnReceive(Rfm9XDevice.OnDataReceivedEventArgs e)
      {
         LoggingFields processReceiveLoggingFields = new LoggingFields();
         char[] sensorReadingSeparators = { ',' };
         char[] sensorIdAndValueSeparators = { ' ' };

         processReceiveLoggingFields.AddString("PacketSNR", e.PacketSnr.ToString("F1"));
         processReceiveLoggingFields.AddInt32("PacketRSSI", e.PacketRssi);
         processReceiveLoggingFields.AddInt32("RSSI", e.Rssi);

         string addressBcdText = BitConverter.ToString(e.Address);
         processReceiveLoggingFields.AddInt32("DeviceAddressLength", e.Address.Length);
         processReceiveLoggingFields.AddString("DeviceAddressBCD", addressBcdText);

         string messageText;
         try
         {
            messageText = UTF8Encoding.UTF8.GetString(e.Data);
            processReceiveLoggingFields.AddString("MessageText", messageText);
         }
         catch (Exception ex)
         {
            processReceiveLoggingFields.AddString("Exception", ex.ToString());
            this.Logging.LogEvent("PayloadProcess failure converting payload to text", processReceiveLoggingFields, LoggingLevel.Warning);
            return;
         }

         // Chop up the CSV text
         string[] sensorReadings = messageText.Split(sensorReadingSeparators, StringSplitOptions.RemoveEmptyEntries);
         if (sensorReadings.Length < 1)
         {
            this.Logging.LogEvent("PayloadProcess payload contains no sensor readings", processReceiveLoggingFields, LoggingLevel.Warning);
            return;
         }

         JObject payloadJObject = new JObject();

         JObject feeds = new JObject();

         // Chop up each sensor read into an ID & value
         foreach (string sensorReading in sensorReadings)
         {
            string[] sensorIdAndValue = sensorReading.Split(sensorIdAndValueSeparators, StringSplitOptions.RemoveEmptyEntries);

            // Check that there is an id & value
            if (sensorIdAndValue.Length != 2)
            {
               this.Logging.LogEvent("PayloadProcess payload invalid format", processReceiveLoggingFields, LoggingLevel.Warning);
               return;
            }

            string sensorId = string.Concat(addressBcdText, sensorIdAndValue[0]);
            string value = sensorIdAndValue[1];

            feeds.Add(sensorId.ToLower(), value);
         }
         payloadJObject.Add("feeds", feeds);

         string topic = $"devices/{MqttClient.Options.ClientId}/messages/events/";

         try
         {
            var message = new MqttApplicationMessageBuilder()
               .WithTopic(topic)
               .WithPayload(JsonConvert.SerializeObject(payloadJObject))
               .WithAtLeastOnceQoS()
               .Build();
            Debug.WriteLine(" {0:HH:mm:ss} MQTT Client PublishAsync start", DateTime.UtcNow);
            await MqttClient.PublishAsync(message);
            Debug.WriteLine(" {0:HH:mm:ss} MQTT Client PublishAsync finish", DateTime.UtcNow);

            this.Logging.LogEvent("PublishAsync Azure IoTHub payload", processReceiveLoggingFields, LoggingLevel.Information);
         }
         catch (Exception ex)
         {
            processReceiveLoggingFields.AddString("Exception", ex.ToString());
            this.Logging.LogEvent("PublishAsync Azure IoTHub payload", processReceiveLoggingFields, LoggingLevel.Error);
         }
      }

      void IMessageHandler.MqttApplicationMessageReceived(MqttApplicationMessageReceivedEventArgs e)
      {
         LoggingFields processReceiveLoggingFields = new LoggingFields();

         processReceiveLoggingFields.AddString("ClientId", e.ClientId);
#if DEBUG
         processReceiveLoggingFields.AddString("Payload", e.ApplicationMessage.ConvertPayloadToString());
#endif
         processReceiveLoggingFields.AddString("QualityOfServiceLevel", e.ApplicationMessage.QualityOfServiceLevel.ToString());
         processReceiveLoggingFields.AddBoolean("Retain", e.ApplicationMessage.Retain);
         processReceiveLoggingFields.AddString("Topic", e.ApplicationMessage.Topic);

         this.Logging.LogEvent("MqttApplicationMessageReceived topic not processed", processReceiveLoggingFields, LoggingLevel.Error);
      }

      void IMessageHandler.Rfm9xOnTransmit(Rfm9XDevice.OnDataTransmitedEventArgs e)
      {
      }
   }
}

The formatting of the username and generation of password are password are a bit awkward and will be fixed in a future refactoring. Along with regenerating the SAS connection token just before it is due to expire.