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

Wilderness Labs nRF24L01 Wireless field gateway Meadow client

After a longish pause in development work on my nrf24L01 AdaFruit.IO and Azure IOT Hub field gateways I figured a client based on my port of the techfooninja nRF24 library to Wilderness Labs Meadow would be a good test.

This sample client is an Wilderness Labs Meadow with a Sensiron SHT31 Temperature & humidity sensor (supported by meadow foundation), and a generic nRF24L01 device connected with jumper cables.

Bill of materials (prices as at March 2020)

  • Wilderness Labs Meadow 7F Micro device USD50
  • Seeedstudio Temperature and Humidity Sensor(SHT31) USD11.90
  • Seeedstudio 4 pin Male Jumper to Grove 4 pin Conversion Cable USD2.90
  • 2.4G Wireless Module nRF24L01+PA USD9.90

The initial version of the code was pretty basic with limited error handling and no power conservation support.

namespace devMobile.IoT.FieldGateway.Client
{
   using System;
   using System.Text;
   using System.Threading;

   using Radios.RF24;

   using Meadow;
   using Meadow.Devices;
   using Meadow.Foundation.Leds;
   using Meadow.Foundation.Sensors.Atmospheric;
   using Meadow.Hardware;
   using Meadow.Peripherals.Leds;

   public class MeadowClient : App<F7Micro, MeadowClient>
   {
      private const string BaseStationAddress = "Base1";
      private const string DeviceAddress = "WLAB1";
      private const byte nRF24Channel = 15;
      private RF24 Radio = new RF24();
      private readonly TimeSpan periodTime = new TimeSpan(0, 0, 60);
      private readonly Sht31D sensor;
      private readonly ILed Led;

      public MeadowClient()
      {
         Led = new Led(Device, Device.Pins.OnboardLedGreen);

         try
         {
            sensor = new Sht31D(Device.CreateI2cBus());

            var config = new Meadow.Hardware.SpiClockConfiguration(
                           2000,
                           SpiClockConfiguration.Mode.Mode0);

            ISpiBus spiBus = Device.CreateSpiBus(
               Device.Pins.SCK,
               Device.Pins.MOSI,
               Device.Pins.MISO, config);

            Radio.OnDataReceived += Radio_OnDataReceived;
            Radio.OnTransmitFailed += Radio_OnTransmitFailed;
            Radio.OnTransmitSuccess += Radio_OnTransmitSuccess;

            Radio.Initialize(Device, spiBus, Device.Pins.D09, Device.Pins.D10, Device.Pins.D11);
            //Radio.Address = Encoding.UTF8.GetBytes(Environment.MachineName);
            Radio.Address = Encoding.UTF8.GetBytes(DeviceAddress);

            Radio.Channel = nRF24Channel;
            Radio.PowerLevel = PowerLevel.Low;
            Radio.DataRate = DataRate.DR250Kbps;
            Radio.IsEnabled = true;

            Radio.IsAutoAcknowledge = true;
            Radio.IsDyanmicAcknowledge = false;
            Radio.IsDynamicPayload = true;

            Console.WriteLine($"Address: {Encoding.UTF8.GetString(Radio.Address)}");
            Console.WriteLine($"PowerLevel: {Radio.PowerLevel}");
            Console.WriteLine($"IsAutoAcknowledge: {Radio.IsAutoAcknowledge}");
            Console.WriteLine($"Channel: {Radio.Channel}");
            Console.WriteLine($"DataRate: {Radio.DataRate}");
            Console.WriteLine($"IsDynamicAcknowledge: {Radio.IsDyanmicAcknowledge}");
            Console.WriteLine($"IsDynamicPayload: {Radio.IsDynamicPayload}");
            Console.WriteLine($"IsEnabled: {Radio.IsEnabled}");
            Console.WriteLine($"Frequency: {Radio.Frequency}");
            Console.WriteLine($"IsInitialized: {Radio.IsInitialized}");
            Console.WriteLine($"IsPowered: {Radio.IsPowered}");
         }
         catch (Exception ex)
         {
            Console.WriteLine(ex.Message);
         }

         while (true)
         {
            sensor.Update();

            Console.WriteLine($"{DateTime.UtcNow:HH:mm:ss}-TX T:{sensor.Temperature:0.0}C H:{sensor.Humidity:0}%");

            Led.IsOn = true;

            string values = "T " + sensor.Temperature.ToString("F1") + ",H " + sensor.Humidity.ToString("F0");

            // Stuff the 2 byte header ( payload type & deviceIdentifierLength ) + deviceIdentifier into payload
            byte[] payload = new byte[1 + Radio.Address.Length + values.Length];
            payload[0] = (byte)((1 << 4) | Radio.Address.Length);
            Array.Copy(Radio.Address, 0, payload, 1, Radio.Address.Length);
            Encoding.UTF8.GetBytes(values, 0, values.Length, payload, Radio.Address.Length + 1);

            Radio.SendTo(Encoding.UTF8.GetBytes(BaseStationAddress), payload);

            Thread.Sleep(periodTime);
         }
      }

      private void Radio_OnDataReceived(byte[] data)
      {
         // Display as Unicode
         string unicodeText = Encoding.UTF8.GetString(data);
         Console.WriteLine($"{DateTime.UtcNow:HH:mm:ss}-RX Unicode Length {0} Unicode Length {1} Unicode text {2}", data.Length, unicodeText.Length, unicodeText);

         // display as hex
         Console.WriteLine($"{DateTime.UtcNow:HH:mm:ss}-RX Hex Length {data.Length} Payload {BitConverter.ToString(data)}");
      }

      private void Radio_OnTransmitSuccess()
      {
         Led.IsOn = false;

         Console.WriteLine($"{DateTime.UtcNow:HH:mm:ss}-TX Succeeded!");
      }

      private void Radio_OnTransmitFailed()
      {
         Console.WriteLine($"{DateTime.UtcNow:HH:mm:ss}-TX failed!");
      }
   }
}

After sorting out power to the SHT31 (I had to push the jumper cable further into the back of the jumper cable plug). I could see temperature and humidity values getting uploaded to Adafruit.IO.

Visual Studio 2019 debug output

Adafruit.IO “automagically” provisions new feeds which is helpful when building a proof of concept (PoC)

Adafruit.IO feed with default feed IDs

I then modified the feed configuration to give it a user friendly name.

Feed Configuration

All up configuration took about 10 minutes.

Meadow device temperature and humidity

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 MQTT+TLS Overheads

An Azure IoT Hub has a series of metrics and one I had been using was “Total Device Data Usage”. To better understand what it was displaying I modified my Azure IoT Hub MQTT Test Application to display the size of the JOSN payload.

MQTTNet based client displaying payload length

The size of the packets sent and the total device data appeared to map pretty well but I was also interested in the Transport Layer Security (TLS) and Messaging Queuing Telemetry Transport (MQTT) overheads.

Azure IoT Hub Metrics

To get an idea of the overheads I fired up LiveTcpUdpWatch by Nirsoft and noted down the traffic measure on port 8883.

Conenction LiveTcpUdpWatch main screen

Launching the MQTTNet client sending every 30 seconds resulted in traffic like this

4179b - Establishing connection
4284b - 105b
4317b - 33b
4386b - 69b
4455b - 69b
4524b - 69b
4593b - 69b
4662b - 69b
4731b - 69b
4800b - 69b
4869b - 69b
4938b - 69b
5007b - 69b
5076b - 69b
5145b - 69b
5214b - 69b
5288b - 69b

So it looks like my very rough numbers are close to the numbers discussed in the above article. I need to explore the impact of keep-alive messages and other background operations.

Azure IOT Hub and Event Grid Part2

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

I was using Advanced Message Queueing Protocol (AMQP) so I modified the configuration file so I could try all the available options.

C# TransportType enumeration

namespace Microsoft.Azure.Devices.Client
{
	//
	// Summary:
	//     Transport types supported by DeviceClient - AMQP/TCP, HTTP 1.1, MQTT/TCP, AMQP/WS,
	//     MQTT/WS
	public enum TransportType
	{
		//
		// Summary:
		//     Advanced Message Queuing Protocol transport. Try Amqp over TCP first and fallback
		//     to Amqp over WebSocket if that fails
		Amqp = 0,
		//
		// Summary:
		//     HyperText Transfer Protocol version 1 transport.
		Http1 = 1,
		//
		// Summary:
		//     Advanced Message Queuing Protocol transport over WebSocket only.
		Amqp_WebSocket_Only = 2,
		//
		// Summary:
		//     Advanced Message Queuing Protocol transport over native TCP only
		Amqp_Tcp_Only = 3,
		//
		// Summary:
		//     Message Queuing Telemetry Transport. Try Mqtt over TCP first and fallback to
		//     Mqtt over WebSocket if that fails
		Mqtt = 4,
		//
		// Summary:
		//     Message Queuing Telemetry Transport over Websocket only.
		Mqtt_WebSocket_Only = 5,
		//
		// Summary:
		//     Message Queuing Telemetry Transport over native TCP only
		Mqtt_Tcp_Only = 6
	}
}

Windows 10 IoT Core LoRa Telemetry Field gateway config.json file

{
   "AzureIoTHubDeviceConnectionString": "HostName=FieldGatewayHub.azure-devices.net;DeviceId=LoRa915MHz;SharedAccessKey=y12345678901234567890123456789012345678/arg=",

   "AzureIoTHubTransportType-Amqp": "amqp",
   "AzureIoTHubTransportType-Http1": "Http1",
   "AzureIoTHubTransportType-Amqp_WebSocket_Only": "Amqp_WebSocket_Only",
   "AzureIoTHubTransportType-Amqp_Tcp_Only": "Amqp_Tcp_Only",
   "AzureIoTHubTransportType-Mqtt": "Mqtt",
   "AzureIoTHubTransportType-Mqtt_WebSocket_Only": "Mqtt_WebSocket_Only",
   "AzureIoTHubTransportType-Amqp": "Mqtt_Tcp_Only",

   "AzureIoTHubTransportType": "Mqtt_Tcp_Only",
   "SensorIDIsDeviceIDSensorID": false,
   "Address": "LoRaIoT1",
   "Frequency": 915000000.0,
   "PABoost": true
}

So in alphabetical order here are my not terribly scientific results

AMQP

Device ETW

Device Telemetry messages

{
"id":"07e9a772-d86a-963d-139a-9d2ea2a0866c",
"topic":"/SUBSCRIPTIONS/12345678-9012-3456-7890-D12345678901/RESOURCEGROUPS/AZUREIOTHUBEVENTGRIDAZUREFUNCTION/PROVIDERS/MICROSOFT.DEVICES/IOTHUBS/FIELDGATEWAYHUB",
"subject":"devices/LoRa915MHz",
"eventType":"Microsoft.Devices.DeviceTelemetry","eventTime":"2020-01-25T00:57:18.477Z",
"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-25T00:57:18.477Z",
"iothub-message-source":"Telemetry"},
"body":"eyJQYWNrZXRTTlIiOiIxMC4wIiwiUGFja2V0UlNTSSI6LTcxLCJSU1NJIjotMTEwLCJEZXZpY2VBZGRyZXNzQkNEIjoiNEQtNjEtNjQtNzUtNjktNkUtNkYtMzIiLCJhdCI6Ijg0LjAiLCJhaCI6IjUwIiwid3NhIjoiMSIsIndzZyI6IjMiLCJ3ZCI6IjE5My44OCIsInIiOiIwLjAwIn0="},
"dataVersion":"",
"metadataVersion":"1"
}
…
{
"id":"ca8e8531-10da-ec99-aad7-49e68f3f9500","topic":"/SUBSCRIPTIONS/712345678-9012-3456-7890-D12345678901/RESOURCEGROUPS/AZUREIOTHUBEVENTGRIDAZUREFUNCTION/PROVIDERS/MICROSOFT.DEVICES/IOTHUBS/FIELDGATEWAYHUB",
"subject":"devices/LoRa915MHz",
"eventType":"Microsoft.Devices.DeviceTelemetry",
"eventTime":"2020-01-25T01:02:23.377Z",
"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-25T01:02:23.377Z",
"iothub-message-source":"Telemetry"},
"body":"eyJQYWNrZXRTTlIiOiI5LjgiLCJQYWNrZXRSU1NJIjotNzAsIlJTU0kiOi0xMDgsIkRldmljZUFkZHJlc3NCQ0QiOiI0RC02MS02NC03NS02OS02RS02Ri0zMiIsImF0IjoiODUuMSIsImFoIjoiNTEiLCJ3c2EiOiIxIiwid3NnIjoiMyIsIndkIjoiMjM5LjI1IiwiciI6IjAuMDAifQ=="},
"dataVersion":"",
"metadataVersion":"1"
}

Device connectivity messages

{
"id":"d8a393ff-6549-69d2-d728-37eee2437693",
"source":"/SUBSCRIPTIONS/12345678-9012-3456-7890-D12345678901/RESOURCEGROUPS/AZUREIOTHUBEVENTGRIDAZUREFUNCTION/PROVIDERS/MICROSOFT.DEVICES/IOTHUBS/FIELDGATEWAYHUB",
"specversion":"1.0",
"type":"Microsoft.Devices.DeviceConnected",
"dataschema":"#",
"subject":"devices/LoRa915MHz",
"time":"2020-01-25T01:01:28.4887191Z","data":{"deviceConnectionStateEventInfo":{"sequenceNumber":"000000000000000001D5CDC11D3AACA90000000700000000000000000000001E"},
"hubName":"FieldGatewayHub",
"deviceId":"LoRa915MHz"}
}

{
"id":"b345d18a-bdf5-3397-35c1-fd5c35046d85",
"source":"/SUBSCRIPTIONS/12345678-9012-3456-7890-D12345678901/RESOURCEGROUPS/AZUREIOTHUBEVENTGRIDAZUREFUNCTION/PROVIDERS/MICROSOFT.DEVICES/IOTHUBS/FIELDGATEWAYHUB",
"specversion":"1.0",
"type":"Microsoft.Devices.DeviceDisconnected",
"dataschema":"#",
"subject":"devices/LoRa915MHz",
"time":"2020-01-25T01:02:24.9605306Z",
"data":{"deviceConnectionStateEventInfo":{"sequenceNumber":"000000000000000001D5CDC11D3AACA90000000700000000000000000000001F"},
"hubName":"FieldGatewayHub",
"deviceId":"LoRa915MHz"}
}

The first telemetry data arrived 00:57:18, the DeviceConnected arrived 01:01:28 so approximately a 4 minute delay, the DeviceDisconnected arrived within a minute of me shutting the device down.

Amqp-Tcp-Only

Device Telemetry messages

{
"id":"b8cdbc73-5cb8-134c-a328-beed47be5f27",
"topic":"/SUBSCRIPTIONS/12345678-9012-3456-7890-D12345678901/RESOURCEGROUPS/AZUREIOTHUBEVENTGRIDAZUREFUNCTION/PROVIDERS/MICROSOFT.DEVICES/IOTHUBS/FIELDGATEWAYHUB","subject":"devices/LoRa915MHz",
"eventType":"Microsoft.Devices.DeviceTelemetry",
"eventTime":"2020-01-25T04:16:48.732Z",
"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-25T04:16:48.732Z",
"iothub-message-source":"Telemetry"},
"body":"eyJQYWNrZXRTTlIiOiI5LjUiLCJQYWNrZXRSU1NJIjotNzIsIlJTU0kiOi0xMDcsIkRldmljZUFkZHJlc3NCQ0QiOiI0RC02MS02NC03NS02OS02RS02Ri0zMiIsImF0IjoiODYuNSIsImFoIjoiNDUiLCJ3c2EiOiIxIiwid3NnIjoiMiIsIndkIjoiOTkuNzUiLCJyIjoiMC4wMCJ9"},
"dataVersion":"",
"metadataVersion":"1"
}
...
{
"id":"56aaf46d-e1ee-9419-2621-aa97c0564778",
"topic":"/SUBSCRIPTIONS/12345678-9012-3456-7890-D12345678901/RESOURCEGROUPS/AZUREIOTHUBEVENTGRIDAZUREFUNCTION/PROVIDERS/MICROSOFT.DEVICES/IOTHUBS/FIELDGATEWAYHUB",
"subject":"devices/LoRa915MHz",
"eventType":"Microsoft.Devices.DeviceTelemetry",
"eventTime":"2020-01-25T04:21:53.402Z",
"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-25T04:21:53.402Z",
"iothub-message-source":"Telemetry"},
"body":"eyJQYWNrZXRTTlIiOiI5LjUiLCJQYWNrZXRSU1NJIjotNzEsIlJTU0kiOi0xMDksIkRldmljZUFkZHJlc3NCQ0QiOiI0RC02MS02NC03NS02OS02RS02Ri0zMiIsImF0IjoiODQuOSIsImFoIjoiNDYiLCJ3c2EiOiIzIiwid3NnIjoiNyIsIndkIjoiMjE3LjUwIiwiciI6IjAuMDAifQ=="},
"dataVersion":"",
"metadataVersion":"1"
}

Device connectivity messages

{
"id":"a157468c-7d65-00b1-73d6-12e43fd1356b",
"source":"/SUBSCRIPTIONS/12345678-9012-3456-7890-D12345678901/RESOURCEGROUPS/AZUREIOTHUBEVENTGRIDAZUREFUNCTION/PROVIDERS/MICROSOFT.DEVICES/IOTHUBS/FIELDGATEWAYHUB",
"specversion":"1.0",
"type":"Microsoft.Devices.DeviceConnected",
"dataschema":"#",
"subject":"devices/LoRa915MHz",
"time":"2020-01-25T04:20:39.7309538Z",
"data":{"deviceConnectionStateEventInfo":{"sequenceNumber":"000000000000000001D5CDC11D3AACA900000007000000000000000000000026"},
"hubName":"FieldGatewayHub",
"deviceId":"LoRa915MHz"}
}

{
"id":"2e6d7e57-3db3-9e1d-c01b-b0f787b16e05",
"source":"/SUBSCRIPTIONS/12345678-9012-3456-7890-D12345678901/RESOURCEGROUPS/AZUREIOTHUBEVENTGRIDAZUREFUNCTION/PROVIDERS/MICROSOFT.DEVICES/IOTHUBS/FIELDGATEWAYHUB",
"specversion":"1.0",
"type":"Microsoft.Devices.DeviceDisconnected",
"dataschema":"#",
"subject":"devices/LoRa915MHz",
"time":"2020-01-25T04:22:33.5276985Z",
"data":{"deviceConnectionStateEventInfo":{"sequenceNumber":"000000000000000001D5CDC11D3AACA900000007000000000000000000000027"},
"hubName":"FieldGatewayHub",
"deviceId":"LoRa915MHz"}
}

The first telemetry data arrived 04:16:48, the DeviceConnected arrived 04:20:39 so approximately a 4 minute delay, the DeviceDisconnected arrived within a minute of me shutting the device down.

Amqp WebSocket Only

Device Telemetry messages

{
"id":"f82943da-425c-f49c-49b0-13ff2609544b",
"source":"/SUBSCRIPTIONS/12345678-9012-3456-7890-D12345678901/RESOURCEGROUPS/AZUREIOTHUBEVENTGRIDAZUREFUNCTION/PROVIDERS/MICROSOFT.DEVICES/IOTHUBS/FIELDGATEWAYHUB",
"specversion":"1.0",
"type":"Microsoft.Devices.DeviceTelemetry",
"dataschema":"#",
"subject":"devices/LoRa915MHz",
"time":"2020-01-25T04:05:36.723Z",
"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-25T04:05:36.723Z",
"iothub-message-source":"Telemetry"},
"body":"eyJQYWNrZXRTTlIiOiI5LjMiLCJQYWNrZXRSU1NJIjotNzEsIlJTU0kiOi0xMDksIkRldmljZUFkZHJlc3NCQ0QiOiI0RC02MS02NC03NS02OS02RS02Ri0zMiIsImF0IjoiODUuMyIsImFoIjoiNDMiLCJ3c2EiOiIyIiwid3NnIjoiMyIsIndkIjoiMjcyLjYzIiwiciI6IjAuMDAifQ=="}
}
...
{
"id":"8419d4f7-3340-8e29-6370-29f95d40e68c",
"source":"/SUBSCRIPTIONS/12345678-9012-3456-7890-D12345678901/RESOURCEGROUPS/AZUREIOTHUBEVENTGRIDAZUREFUNCTION/PROVIDERS/MICROSOFT.DEVICES/IOTHUBS/FIELDGATEWAYHUB",
"specversion":"1.0",
"type":"Microsoft.Devices.DeviceTelemetry",
"dataschema":"#",
"subject":"devices/LoRa915MHz",
"time":"2020-01-25T04:11:42.684Z",
"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-25T04:11:42.684Z",
"iothub-message-source":"Telemetry"},
"body":"eyJQYWNrZXRTTlIiOiI5LjgiLCJQYWNrZXRSU1NJIjotNzEsIlJTU0kiOi0xMTIsIkRldmljZUFkZHJlc3NCQ0QiOiI0RC02MS02NC03NS02OS02RS02Ri0zMiIsImF0IjoiODcuMyIsImFoIjoiNDMiLCJ3c2EiOiIxIiwid3NnIjoiMyIsIndkIjoiMjcuMDAiLCJyIjoiMC4wMCJ9"}
}

Device connectivity messages

{
"id":"7f10a3e3-0c2c-2b18-e38c-d5ea498304ab",
"source":"/SUBSCRIPTIONS/12345678-9012-3456-7890-D12345678901/RESOURCEGROUPS/AZUREIOTHUBEVENTGRIDAZUREFUNCTION/PROVIDERS/MICROSOFT.DEVICES/IOTHUBS/FIELDGATEWAYHUB",
"specversion":"1.0",
"type":"Microsoft.Devices.DeviceConnected",
"dataschema":"#",
"subject":"devices/LoRa915MHz",
"time":"2020-01-25T04:09:52.5786541Z",
"data":{"deviceConnectionStateEventInfo":{"sequenceNumber":"000000000000000001D5CDC11D3AACA900000007000000000000000000000024"},
"hubName":"FieldGatewayHub",
"deviceId":"LoRa915MHz"}
}

{"id":"474a695b-8c4f-e3fe-0b1b-b6bc6b6d4dbe",
"source":"/SUBSCRIPTIONS/12345678-9012-3456-7890-D12345678901/RESOURCEGROUPS/AZUREIOTHUBEVENTGRIDAZUREFUNCTION/PROVIDERS/MICROSOFT.DEVICES/IOTHUBS/FIELDGATEWAYHUB",
"specversion":"1.0",
"type":"Microsoft.Devices.DeviceDisconnected",
"dataschema":"#",
"subject":"devices/LoRa915MHz",
"time":"2020-01-25T04:11:53.076926Z",
"data":{"deviceConnectionStateEventInfo":{"sequenceNumber":"000000000000000001D5CDC11D3AACA900000007000000000000000000000025"},
"hubName":"FieldGatewayHub",
"deviceId":"LoRa915MHz"}
}

The first telemetry data arrived 04:05:36, DeviceConnected arrived 04:09:52 so approximately a 4 minute delay, the DeviceDisconnected arrived within a minute of me shutting the device down.

HTTP

I waited for 20 minutes and there wasn’t a DeviceConnected message which I sort of expected as HTTP is a connectionless protocol.

MQTT

Device ETW

Device Telemetry messages

{
"id":"bc26c412-c694-3954-5888-baa118cc9f88",
"source":"/SUBSCRIPTIONS/12345678-9012-3456-7890-D12345678901/RESOURCEGROUPS/AZUREIOTHUBEVENTGRIDAZUREFUNCTION/PROVIDERS/MICROSOFT.DEVICES/IOTHUBS/FIELDGATEWAYHUB",
"specversion":"1.0",
"type":"Microsoft.Devices.DeviceTelemetry",
"dataschema":"#",
"subject":"devices/LoRa915MHz","time":"2020-01-25T01:11:33.493Z",
"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-25T01:11:33.493Z",
"iothub-message-source":"Telemetry"},
"body":"eyJQYWNrZXRTTlIiOiI5LjUiLCJQYWNrZXRSU1NJIjotNzEsIlJTU0kiOi0xMTEsIkRldmljZUFkZHJlc3NCQ0QiOiI0RC02MS02NC03NS02OS02RS02Ri0zMiIsImF0IjoiODUuNiIsImFoIjoiNTAiLCJ3c2EiOiIyIiwid3NnIjoiNCIsIndkIjoiMjg1LjAwIiwiciI6IjAuMDAifQ=="}
}
...
{
"id":"de95b90f-ac96-5c76-7a46-00f5a0eef8cf",
"source":"/SUBSCRIPTIONS/12345678-9012-3456-7890-D12345678901/RESOURCEGROUPS/AZUREIOTHUBEVENTGRIDAZUREFUNCTION/PROVIDERS/MICROSOFT.DEVICES/IOTHUBS/FIELDGATEWAYHUB",
"specversion":"1.0",
"type":"Microsoft.Devices.DeviceTelemetry",
"dataschema":"#",
"subject":"devices/LoRa915MHz",
"time":"2020-01-25T01:12:12.101Z",
"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-25T01:12:12.101Z",
"iothub-message-source":"Telemetry"},
"body":"eyJQYWNrZXRTTlIiOiIxMC4wIiwiUGFja2V0UlNTSSI6LTU4LCJSU1NJIjotMTA5LCJEZXZpY2VBZGRyZXNzQkNEIjoiMDEtMjMtMjktMDctMjMtMEMtODgtNjMtRUUiLCJoIjoiMzQiLCJ0IjoiNDEuOCIsInMiOiI0IiwidiI6IjQuMDcifQ=="}
}

Device connectivity messages

{
"id":"f8f5ee54-394d-05e3-784d-87bc648e8267",
"source":"/SUBSCRIPTIONS/12345678-9012-3456-7890-D12345678901/RESOURCEGROUPS/AZUREIOTHUBEVENTGRIDAZUREFUNCTION/PROVIDERS/MICROSOFT.DEVICES/IOTHUBS/FIELDGATEWAYHUB",
"specversion":"1.0",
"type":"Microsoft.Devices.DeviceConnected",
"dataschema":"#",
"subject":"devices/LoRa915MHz",
"time":"2020-01-25T01:11:25.2530139Z",
"data":{"deviceConnectionStateEventInfo":{"sequenceNumber":"000000000000000001D5CDC11D3AACA900000007000000000000000000000020"},
"hubName":"FieldGatewayHub",
"deviceId":"LoRa915MHz"}
}

{
"id":"82d6aa6c-4c71-9623-a4ac-9e562345afad",
"source":"/SUBSCRIPTIONS/12345678-9012-3456-7890-D12345678901/RESOURCEGROUPS/AZUREIOTHUBEVENTGRIDAZUREFUNCTION/PROVIDERS/MICROSOFT.DEVICES/IOTHUBS/FIELDGATEWAYHUB",
"specversion":"1.0",
"type":"Microsoft.Devices.DeviceDisconnected",
"dataschema":"#",
"subject":"devices/LoRa915MHz",
"time":"2020-01-25T01:12:26.6368519Z",
"data":{"deviceConnectionStateEventInfo":{"sequenceNumber":"000000000000000001D5CDC11D3AACA900000007000000000000000000000021"},
"hubName":"FieldGatewayHub",
"deviceId":"LoRa915MHz"}
}

The first telemetry data arrived 01:11:33, the DeviceConnected arrived 01:11:25 so they arrived in order and within 10 seconds, the DeviceDisconnected arrived within a 15 seconds of me shutting the device down.

Mqtt-TCP-Only

Device ETW

Device Telemetry messages

{
"id":"bb86bfd9-6d12-4a27-2444-bd6953be7ffd",
"topic":"/SUBSCRIPTIONS/12345678-9012-3456-7890-D12345678901/RESOURCEGROUPS/AZUREIOTHUBEVENTGRIDAZUREFUNCTION/PROVIDERS/MICROSOFT.DEVICES/IOTHUBS/FIELDGATEWAYHUB",
"subject":"devices/LoRa915MHz",
"eventType":"Microsoft.Devices.DeviceTelemetry",
"eventTime":"2020-01-25T04:42:15.345Z",
"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-25T04:42:15.345Z","iothub-message-source":"Telemetry"},"body":"eyJQYWNrZXRTTlIiOiIxMC44IiwiUGFja2V0UlNTSSI6LTcxLCJSU1NJIjotMTA4LCJEZXZpY2VBZGRyZXNzQkNEIjoiNEQtNjEtNjQtNzUtNjktNkUtNkYtMzIiLCJhdCI6Ijg2LjkiLCJhaCI6IjQ1Iiwid3NhIjoiMSIsIndzZyI6IjMiLCJ3ZCI6IjI5LjYzIiwiciI6IjAuMDAifQ=="},"dataVersion":"","metadataVersion":"1"
}
...
{
"id":"c5991ed8-42f2-437a-9161-a526248c955f",
"topic":"/SUBSCRIPTIONS/12345678-9012-3456-7890-D12345678901/RESOURCEGROUPS/AZUREIOTHUBEVENTGRIDAZUREFUNCTION/PROVIDERS/MICROSOFT.DEVICES/IOTHUBS/FIELDGATEWAYHUB","subject":"devices/LoRa915MHz",
"eventType":"Microsoft.Devices.DeviceTelemetry",
"eventTime":"2020-01-25T04:44:16.986Z",
"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-25T04:44:16.986Z",
"iothub-message-source":"Telemetry"},
"body":"eyJQYWNrZXRTTlIiOiIxMC4wIiwiUGFja2V0UlNTSSI6LTcxLCJSU1NJIjotMTEyLCJEZXZpY2VBZGRyZXNzQkNEIjoiNEQtNjEtNjQtNzUtNjktNkUtNkYtMzIiLCJhdCI6Ijg4LjIiLCJhaCI6IjQ0Iiwid3NhIjoiMiIsIndzZyI6IjMiLCJ3ZCI6IjYxLjUwIiwiciI6IjAuMDAifQ=="},
"dataVersion":"",
"metadataVersion":"1"}
}

Device connectivity messages

{
"id":"7861f3c1-5f1d-e9a1-c214-19feea2bf1a3","source":"/SUBSCRIPTIONS/12345678-9012-3456-7890-D12345678901/RESOURCEGROUPS/AZUREIOTHUBEVENTGRIDAZUREFUNCTION/PROVIDERS/MICROSOFT.DEVICES/IOTHUBS/FIELDGATEWAYHUB",
"specversion":"1.0",
"type":"Microsoft.Devices.DeviceConnected",
"dataschema":"#",
"subject":"devices/LoRa915MHz",
"time":"2020-01-25T04:42:06.0123436Z",
"data":{"deviceConnectionStateEventInfo":{"sequenceNumber":"000000000000000001D5CDC11D3AACA90000000700000000000000000000002A"},
"hubName":"FieldGatewayHub",
"deviceId":"LoRa915MHz"}
}

{
"id":"c2090a7b-c827-73cc-d1e8-7d49fe4a03a1",
"source":"/SUBSCRIPTIONS/12345678-9012-3456-7890-D12345678901/RESOURCEGROUPS/AZUREIOTHUBEVENTGRIDAZUREFUNCTION/PROVIDERS/MICROSOFT.DEVICES/IOTHUBS/FIELDGATEWAYHUB",
"specversion":"1.0",
"type":"Microsoft.Devices.DeviceDisconnected",
"dataschema":"#",
"subject":"devices/LoRa915MHz",
"time":"2020-01-25T04:44:48.816748Z",
"data":{"deviceConnectionStateEventInfo":{"sequenceNumber":"000000000000000001D5CDC11D3AACA90000000700000000000000000000002B"},
"hubName":"FieldGatewayHub",
"deviceId":"LoRa915MHz"}
}

The first telemetry data arrived 04:42:15, the DeviceConnected arrived 04:42:06 so they arrived in order and within 10 seconds, the DeviceDisconnected arrived within a 20 seconds of me shutting device down.

Mqtt-Web-Socket-Only

Device ETW

Device Telemetry messages

{
"id":"3afa1a9c-f30d-d051-077e-cd25cc3b2245",
"source":"/SUBSCRIPTIONS/12345678-9012-3456-7890-D12345678901/RESOURCEGROUPS/AZUREIOTHUBEVENTGRIDAZUREFUNCTION/PROVIDERS/MICROSOFT.DEVICES/IOTHUBS/FIELDGATEWAYHUB",
"specversion":"1.0",
"type":"Microsoft.Devices.DeviceTelemetry",
"dataschema":"#",
"subject":"devices/LoRa915MHz",
"time":"2020-01-25T04:36:08.871Z",
"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-25T04:36:08.871Z",
"iothub-message-source":"Telemetry"},
"body":"eyJQYWNrZXRTTlIiOiI5LjUiLCJQYWNrZXRSU1NJIjotNzAsIlJTU0kiOi0xMTIsIkRldmljZUFkZHJlc3NCQ0QiOiI0RC02MS02NC03NS02OS02RS02Ri0zMiIsImF0IjoiODMuOCIsImFoIjoiNDciLCJ3c2EiOiIwIiwid3NnIjoiMSIsIndkIjoiMzQ3LjI1IiwiciI6IjAuMDAifQ=="}
}
...
{
"id":"fa082b67-db32-312d-e716-1b1d37f57d94",
"source":"/SUBSCRIPTIONS/12345678-9012-3456-7890-D12345678901/RESOURCEGROUPS/AZUREIOTHUBEVENTGRIDAZUREFUNCTION/PROVIDERS/MICROSOFT.DEVICES/IOTHUBS/FIELDGATEWAYHUB",
"specversion":"1.0",
"type":"Microsoft.Devices.DeviceTelemetry",
"dataschema":"#",
"subject":"devices/LoRa915MHz",
"time":"2020-01-25T04:37:09.516Z",
"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-25T04:37:09.516Z",
"iothub-message-source":"Telemetry"},
"body":"eyJQYWNrZXRTTlIiOiI5LjgiLCJQYWNrZXRSU1NJIjotNzEsIlJTU0kiOi0xMTEsIkRldmljZUFkZHJlc3NCQ0QiOiI0RC02MS02NC03NS02OS02RS02Ri0zMiIsImF0IjoiODQuNCIsImFoIjoiNDciLCJ3c2EiOiIxIiwid3NnIjoiMiIsIndkIjoiMzU4LjUwIiwiciI6IjAuMDAifQ=="}
}

Device connectivity messages

{
"id":"245e4d68-06e6-4d76-1167-39a9a67b01ac",
"source":"/SUBSCRIPTIONS/12345678-9012-3456-7890-D12345678901/RESOURCEGROUPS/AZUREIOTHUBEVENTGRIDAZUREFUNCTION/PROVIDERS/MICROSOFT.DEVICES/IOTHUBS/FIELDGATEWAYHUB",
"specversion":"1.0",
"type":"Microsoft.Devices.DeviceConnected",
"dataschema":"#",
"subject":"devices/LoRa915MHz","time":"2020-01-25T04:36:03.8275263Z",
"data":{"deviceConnectionStateEventInfo":{"sequenceNumber":"000000000000000001D5CDC11D3AACA900000007000000000000000000000028"},
"hubName":"FieldGatewayHub",
"deviceId":"LoRa915MHz"}
}

{
"id":"9612e8af-84e0-a679-4c7d-28c5e968da3c",
"source":"/SUBSCRIPTIONS/12345678-9012-3456-7890-D12345678901/RESOURCEGROUPS/AZUREIOTHUBEVENTGRIDAZUREFUNCTION/PROVIDERS/MICROSOFT.DEVICES/IOTHUBS/FIELDGATEWAYHUB",
"specversion":"1.0",
"type":"Microsoft.Devices.DeviceDisconnected",
"dataschema":"#",
"subject":"devices/LoRa915MHz",
"time":"2020-01-25T04:37:47.5794771Z",
"data":{"deviceConnectionStateEventInfo":{"sequenceNumber":"000000000000000001D5CDC11D3AACA900000007000000000000000000000029"},
"hubName":"FieldGatewayHub",
"deviceId":"LoRa915MHz"}
}

The first telemetry data arrived 04:36:08, the DeviceConnected arrived 04:36:03 so they arrived in order and within 10 seconds, the DeviceDisconnected arrived within a 30 seconds of me shutting device down.

Summary

My LoRa sensors nodes are sending data roughly every minute which reduces the precision of the times.

It looks like for AMQP based messaging it can take 4-5 minutes for a Devices.DeviceConnected message to arrive, for based MQTT messaging it’s 5-10 seconds.