.NET Core RAK811 LoRaWAN library Part3

The massive refactor

After refactoring my RAK3172 device library I have applied a similar approach to code on my RAK811 device library. My test-rig is a RaspberryPI 3B with a PI Supply RAK811 pHat and external antenna.

PI Supply RAK811 LoRaWAN pHat

In the new code a Thread reads lines of text from the SerialPort and processes them, checking for command responses, failures and downlink messages.

Unlike most of the devices I have worked with the RAK811 Join and Send commands are synchronous so return once the process has completed. The RAK811 responses also have quite a few empty, null prefixed or null suffixed lines which is a bit odd.

public void SerialPortProcessor()
{
	string line;

	while (CommandProcessResponses)
	{
		try
		{
#if DIAGNOSTICS
			Debug.WriteLine($" {DateTime.UtcNow:hh:mm:ss} ReadLine before");
#endif
			line = SerialDevice.ReadLine().Trim('\0').Trim();
#if DIAGNOSTICS
			Debug.WriteLine($" {DateTime.UtcNow:hh:mm:ss} ReadLine after:{line}");
#endif
			// consume empty lines
			if (String.IsNullOrWhiteSpace(line))
			{
				continue;
			}

			// Consume the response from set work mode
			if (line.StartsWith("?LoRa (R)") || line.StartsWith("RAK811 ") || line.StartsWith("UART1 ") || line.StartsWith("UART3 ") || line.StartsWith("LoRa work mode"))
			{
				continue;
			}

			// See if device successfully joined network
			if (line.StartsWith("OK Join Success"))
			{
				OnJoinCompletion?.Invoke(true);

				CommandResponseExpectedEvent.Set();

				continue;
			}

			if (line.StartsWith("at+recv="))
			{
				string[] payloadFields = line.Split("=,:".ToCharArray());

				byte port = byte.Parse(payloadFields[1]);
				int rssi = int.Parse(payloadFields[2]);
				int snr = int.Parse(payloadFields[3]);
				int length = int.Parse(payloadFields[4]);

				if (this.OnMessageConfirmation != null)
				{
					OnMessageConfirmation?.Invoke(rssi, snr);
				}
				if (length > 0)
				{
					string payload = payloadFields[5];

					if (this.OnReceiveMessage != null)
					{
						OnReceiveMessage.Invoke(port, rssi, snr, payload);
					}
				}
				continue;
			}

			switch (line)
			{
				case "OK":
				case "Initialization OK":
				case "OK Wake Up":
				case "OK Sleep":
					CommandResult = Result.Success;
					break;

				case "ERROR: 1":
					CommandResult = Result.ATCommandUnsuported;
					break;
				case "ERROR: 2":
					CommandResult = Result.ATCommandInvalidParameter;
					break;
				case "ERROR: 3": //There is an error when reading or writing flash.
				case "ERROR: 4": //There is an error when reading or writing through IIC.
					CommandResult = Result.ErrorReadingOrWritingFlash;
					break;
				case "ERROR: 5": //There is an error when sending through UART
					CommandResult = Result.ATCommandInvalidParameter;
					break;
				case "ERROR: 41": //The BLE works in an invalid state, so that it can’t be operated.
					CommandResult = Result.ResponseInvalid;
					break;
				case "ERROR: 80":
					CommandResult = Result.LoRaBusy;
					break;
				case "ERROR: 81":
					CommandResult = Result.LoRaServiceIsUnknown;
					break;
				case "ERROR: 82":
					CommandResult = Result.LoRaParameterInvalid;
					break;
				case "ERROR: 83":
					CommandResult = Result.LoRaFrequencyInvalid;
					break;
				case "ERROR: 84":
					CommandResult = Result.LoRaDataRateInvalid;
					break;
				case "ERROR: 85":
					CommandResult = Result.LoRaFrequencyAndDataRateInvalid;
					break;
				case "ERROR: 86":
					CommandResult = Result.LoRaDeviceNotJoinedNetwork;
					break;
				case "ERROR: 87":
					CommandResult = Result.LoRaPacketToLong;
					break;
				case "ERROR: 88":
					CommandResult = Result.LoRaServiceIsClosedByServer;
					break;
				case "ERROR: 89":
					CommandResult = Result.LoRaRegionUnsupported;
					break;
				case "ERROR: 90":
					CommandResult = Result.LoRaDutyCycleRestricted;
					break;
				case "ERROR: 91":
					CommandResult = Result.LoRaNoValidChannelFound;
					break;
				case "ERROR: 92":
					CommandResult = Result.LoRaNoFreeChannelFound;
					break;
				case "ERROR: 93":
					CommandResult = Result.StatusIsError;
					break;
				case "ERROR: 94":
					CommandResult = Result.LoRaTransmitTimeout;
					break;
				case "ERROR: 95":
					CommandResult = Result.LoRaRX1Timeout;
					break;
				case "ERROR: 96":
					CommandResult = Result.LoRaRX2Timeout;
					break;
				case "ERROR: 97":
					CommandResult = Result.LoRaRX1ReceiveError;
					break;
				case "ERROR: 98":
					CommandResult = Result.LoRaRX2ReceiveError;
					break;
				case "ERROR: 99":
					CommandResult = Result.LoRaJoinFailed;
					break;
				case "ERROR: 100":
					CommandResult = Result.LoRaDownlinkRepeated;
					break;
				case "ERROR: 101":
					CommandResult = Result.LoRaPayloadSizeNotValidForDataRate;
					break;
				case "ERROR: 102":
					CommandResult = Result.LoRaTooManyDownlinkFramesLost;
					break;
				case "ERROR: 103":
					CommandResult = Result.LoRaAddressFail;
					break;
				case "ERROR: 104":
					CommandResult = Result.LoRaMicVerifyError;
					break;
				default:
					CommandResult = Result.ResponseInvalid;
					break;
			}
		}
		catch (TimeoutException)
		{
			// Intentionally ignored, not certain this is a good idea
		}

		CommandResponseExpectedEvent.Set();
	}
}

After a lot of testing I think my thread based approach works reliably. Initially, I was having some signal strength issues because I had forgotten to configure the external antenna. I need to add some validation to the metrics and payload field unpacking (though I’m not certain what todo if they are the wrong format).

.NET Core RAK3172 LoRaWAN library Part5

The massive refactor

After getting Activation By Personalisation(ABP) and Over The Air Activation(OTAA) working on my RAK3172 test rig I was looking at the code and SerialDataReceivedEventHandler was really ugly.

Raspberry Pi3 with Grove Base Hat and RAK3172 Breakout (using UART2)

After some experimentation in the BreakOutSerial project I decided to reimplement the RAK3172 command processing. In the new code a Thread reads lines of text from the SerialPort and processes them. I have replaced the Join and Send(Confirmed) methods with ones that block only while the command are sent to the RAK3172. Then, when completed the OnJoinCompletion or OnMessagesConfirmation event handlers are called.

private Result SendCommand(string command)
{
	if (command == null)
	{
		throw new ArgumentNullException(nameof(command));
	}

	if (command == string.Empty)
	{
		throw new ArgumentException($"command cannot be empty", nameof(command));
	}

	serialDevice.WriteLine(command);

	this.CommandResponseExpectedEvent.Reset();

	if (!this.CommandResponseExpectedEvent.WaitOne(CommandTimeoutDefaultmSec, false))
	{
		return Result.Timeout;
	}

	return CommandResult;
}

private void SerialPortProcessor()
{
	string line;

	while (CommandProcessResponses)
	{
		try
		{
#if DIAGNOSTICS
			Debug.WriteLine($" {DateTime.UtcNow:hh:mm:ss} ReadLine before");
#endif
			line = serialDevice.ReadLine();
#if DIAGNOSTICS
			Debug.WriteLine($" {DateTime.UtcNow:hh:mm:ss} ReadLine after:{line}");
#endif

			// See if device successfully joined network
			if (line.StartsWith("+EVT:JOINED"))
			{
				OnJoinCompletion?.Invoke(true);

				continue;
			}

			// See if device failed ot join network
			if (line.StartsWith("+EVT:JOIN FAILED"))
			{
				OnJoinCompletion?.Invoke(false);

				continue;
			}

			// Applicable only if confirmed messages enabled 
			if (line.StartsWith("+EVT:SEND CONFIRMED OK"))
			{
				OnMessageConfirmation?.Invoke();

				continue;
			}

			// Check for A/B/C downlink message
			if (line.StartsWith("+EVT:RX_1") || line.StartsWith("+EVT:RX_2") || line.StartsWith("+EVT:RX_3") || line.StartsWith("+EVT:RX_C"))
			{
				// TODO beef up validation, nto certain what todo if borked
				string[] metricsFields= line.Split(' ', ',');

				int rssi = int.Parse(metricsFields[3]);
				int snr = int.Parse(metricsFields[6]);

				line = serialDevice.ReadLine();

#if DIAGNOSTICS
				Debug.WriteLine($" {DateTime.UtcNow:HH:mm:ss} UNICAST :{line}");
#endif
				line = serialDevice.ReadLine();
#if DIAGNOSTICS
				Debug.WriteLine($" {DateTime.UtcNow:HH:mm:ss} Payload:{line}");
#endif
				// TODO beef up validation, nto certain what todo if borked
				string[] payloadFields = line.Split(':');

				byte port = byte.Parse(payloadFields[1]);
				string payload = payloadFields[2];

				OnReceiveMessage?.Invoke(port, rssi, snr, payload);

				continue;
			}

#if DIAGNOSTICS
           Debug.WriteLine($" {DateTime.UtcNow:hh:mm:ss} ReadLine Result");
#endif
			line = serialDevice.ReadLine();
#if DIAGNOSTICS
             Debug.WriteLine($" {DateTime.UtcNow:hh:mm:ss} ReadLine Result:{line}");
#endif
			switch (line)
			{
				case "OK":
					CommandResult = Result.Success;
					break;
				case "AT_ERROR":
					CommandResult = Result.AtError;
					break;
				case "AT_PARAM_ERROR":
					CommandResult = Result.ParameterError;
					break;
				case "AT_BUSY_ERROR":
					CommandResult = Result.BusyError;
					break;
				case "AT_TEST_PARAM_OVERFLOW":
					CommandResult = Result.ParameterOverflow;
					break;
				case "AT_NO_NETWORK_JOINED":
					CommandResult = Result.NotJoined;
					break;
				case "AT_RX_ERROR":
					CommandResult = Result.ReceiveError;
					break;
				case "AT_DUTYCYLE_RESTRICTED":
					CommandResult = Result.DutyCycleRestricted;
					break;
				default:
					CommandResult = Result.Undefined;
					break;
			}

			CommandResponseExpectedEvent.Set();
		}
		catch (TimeoutException)
		{
			// Intentionally ignored, not certain this is a good idea
		}
	}
}

After a lot of testing I think my thread based approach works reliably. I also had to modify the code to shutdown the command processor thread and free any non managed resources.

/// <summary>
/// Ensures unmanaged serial port and thread resources are released in a "responsible" manner.
/// </summary>
public void Dispose()
{
	CommandProcessResponses = false;

	if (CommandResponsesProcessorThread != null)
	{
		CommandResponsesProcessorThread.Join();
		CommandResponsesProcessorThread = null;
	}

	if (serialDevice != null)
	{
		serialDevice.Dispose();
		serialDevice = null;
	}
}

I need to add some validation to the metrics and payload field unpacking (though I’m not certain what todo if they are the wrong format) and review the handling of multi-line event messages.

.NET Core RAK3172 LoRaWAN library Part4

Starting again with Threads

After getting Activation By Personalisation(ABP) and Over The Air Activation(OTAA) working on my RAK3172 test rig I was looking at the code and SerialDataReceivedEventHandler was really ugly.

Raspberry Pi3 with Grove Base Hat and RAK3172 Breakout (using UART2)

After some experimentation in the BreakOutSerial project I decided to reimplement the RAK3172 command processing. In the new code a Thread reads lines of text from the SerialPort and processes them. I have replaced the Join and Send(Confirmed) methods with ones that block only while the command are sent to the RAK3172. Then, when completed the OnJoinCompletion or OnMessagesConfirmation event handlers are called.

private Result SendCommand(string command)
{
   if (command == null)
   {
      throw new ArgumentNullException(nameof(command));
   }

   if (command == string.Empty)
   {
      throw new ArgumentException($"command invalid length cannot be empty", nameof(command));
    }

   serialDevice.ReadTimeout = (int)CommandTimeoutDefault.TotalMilliseconds;
   serialDevice.WriteLine(command);

   this.atExpectedEvent.Reset();

   if (!this.atExpectedEvent.WaitOne((int)CommandTimeoutDefault.TotalMilliseconds, false))
      return Result.Timeout;

   return result;
}

public void SerialPortProcessor()
{
   string line;

   while (true)
   {
      this.serialDevice.ReadTimeout = -1;

      Debug.WriteLine("ReadLine before");
      line = serialDevice.ReadLine();
      Debug.WriteLine($"ReadLine after:{line}");

            // check for +EVT:JOINED
      if (line.StartsWith("+EVT:JOINED"))
      {
            OnJoinCompletion?.Invoke(true);

            continue;
      }

      if (line.StartsWith("+EVT:JOIN FAILED"))
      {
	     OnJoinCompletion?.Invoke(false);

         continue;
      }

      if (line.StartsWith("+EVT:SEND CONFIRMED OK"))
      {
         OnMessageConfirmation?.Invoke();

         continue;
      }

      // Check for A/B/C downlink message
      if (line.StartsWith("+EVT:RX_1") || line.StartsWith("+EVT:RX_2") || line.StartsWith("+EVT:RX_3") || line.StartsWith("+EVT:RX_C"))
      {
         string[] fields1 = line.Split(' ', ',');

         int rssi = int.Parse(fields1[3]);
         int snr = int.Parse(fields1[6]);
 
         line = serialDevice.ReadLine();
         Console.WriteLine($"{DateTime.UtcNow:HH:mm:ss} UNICAST :{line}");

         line = serialDevice.ReadLine();
         Console.WriteLine($"{DateTime.UtcNow:HH:mm:ss} Payload:{line}");

         string[] fields2 = line.Split(':');

         int port = int.Parse(fields2[1]);
         string payload = fields2[2];

         OnReceiveMessage?.Invoke(port, rssi, snr, payload);

         continue;
      }

      try
      {
         this.serialDevice.ReadTimeout = 3000;

         Debug.WriteLine("ReadLine Result");
         line = serialDevice.ReadLine();
         Debug.WriteLine($"ReadLine Result after:{line}");

         switch (line)
         {
            case "OK":
               result = Result.Success;
               break;
         case "AT_ERROR":
               result = Result.Error;
               break;
         case "AT_PARAM_ERROR":
               result = Result.ParameterError;
               break;
         case "AT_BUSY_ERROR":
               result = Result.BusyError;
               break;
         case "AT_TEST_PARAM_OVERFLOW":
               result = Result.ParameterOverflow;
               break;
         case "AT_NO_NETWORK_JOINED":
               result = Result.NotJoined;
               break;
         case "AT_RX_ERROR":
               result = Result.ReceiveError;
               break;
         case "AT_DUTYCYLE_RESTRICTED":
               result = Result.DutyCycleRestricted;
               break;
         default:
               result = Result.Undefined;
               break;
         }
      }
      catch (TimeoutException) 
      {
         result = Result.Timeout;
      }
   atExpectedEvent.Set();
}

The code is not suitable for production but it confirmed my thread based approach works. I need to add code to shutdown the message processing thread in a controlled way, support for Class B & C devices, replace the OnJoinCompletionHandler timer magic numbers and soak test for 5-7 days.

Visual Studio Displaying RAK3172 device joining network then sending messages

In the Visual Studio 2019 debug output I could see messages getting sent and then after a short delay they were visible in the TTN console.

TTN Displaying RAK3172 device joining network then sending messages

Downlink messages NahYeah

While running my The Things IndustriesTTI) gateway I noticed an exception in the logs every so often

Exception of type 'Microsoft.Azure.Devices.Client.Exceptions.DeviceMessageLockLostException' was thrown.

My client subscribes to Message Queue Telemetry Transport Topics(MQTT) (using MQTTNet) for each TTI Application and establishes a connection (using an Azure DeviceClient) for each TTI Device to an Azure IoT Hub(s).

  • v3/{application id}@{tenant id}/devices/{device id}/up
  • v3/{application id}@{tenant id}/devices/{device id}/down/queued
  • v3/{application id}@{tenant id}/devices/{device id}/down/sent
  • v3/{application id}@{tenant id}/devices/{device id}/down/ack
  • v3/{application id}@{tenant id}/devices/{device id}/down/nack
  • v3/{application id}@{tenant id}/devices/{device id}/down/failed

The application subscribes to the queued, ack, nack, and failed topics so the progress of a downlink message can be monitored. For downlink messages the correlation_id “az:LockToken:” contains the message.LockToken so that they can be Abandoned, Completed or Rejected in the MQTT receive messageHandler.

Below is the logging from my application for an odd sequence of messages

*****Nothing much happening for a couple of hours the .'s represent approx 1 second. Wisnode 4 sends roughly every 5 minues

.....................................................................................................................................................................................................................................................................................................................
03:36:08 TTN Uplink message
 ApplicationID: application1
 DeviceID: wisnodetest04
 Port: 5
.....................................................................................................................................................................................................................................................................................................................
03:41:18 TTN Uplink message
 ApplicationID: application1
 DeviceID: wisnodetest04
 Port: 5
...........................................................................
03:42:34 Azure IoT Hub downlink message
 ApplicationID: application1
 DeviceID: wisnodetest04
 LockToken: 57ea0fad-b6b3-492e-b194-10c4ff3e53cb
 Body: vu8=

*****I then started sending 5 messages to Wisnode 5 same payload vu8=, port 71 thru 75 

***** 71 Queued
03:42:34 Queued: v3/application1@tenant1/devices/wisnodetest04/down/queued
 payload: {"end_device_ids":{"device_id":"wisnodetest04","application_ids":{"application_id":"application1"}},
	"correlation_ids":[
"az:LockToken:57ea0fad-b6b3-492e-b194-10c4ff3e53cb",
"as:downlink:01EXX9B1CA4DB68PKCDAK4SS4H"],
	"downlink_queued":{"f_port":71,"frm_payload":"vu8=","confirmed":true,"priority":"NORMAL",
	"correlation_ids":[
"az:LockToken:57ea0fad-b6b3-492e-b194-10c4ff3e53cb",
"as:downlink:01EXX9B1CA4DB68PKCDAK4SS4H"]}}
...
03:42:37 Azure IoT Hub downlink message
 ApplicationID: application1
 DeviceID: wisnodetest04
 LockToken: e2fef28c-fb1f-42cd-bb40-3ad8e6051da9
 Body: vu8=
.

***** 72 Queued
03:42:38 Queued: v3/application1@tenant1/devices/wisnodetest04/down/queued
 payload: {"end_device_ids":{"device_id":"wisnodetest04","application_ids":{"application_id":"application1"}},
	"correlation_ids":[
"az:LockToken:e2fef28c-fb1f-42cd-bb40-3ad8e6051da9",
"as:downlink:01EXX9B4RGSCJ4BN21GHPM85W5"],
	"downlink_queued":{"f_port":72,"frm_payload":"vu8=",
"confirmed":true,"priority":"NORMAL",
	"correlation_ids":[
"az:LockToken:e2fef28c-fb1f-42cd-bb40-3ad8e6051da9",
"as:downlink:01EXX9B4RGSCJ4BN21GHPM85W5"]}}
...
03:42:41 Azure IoT Hub downlink message
 ApplicationID: application1
 DeviceID: wisnodetest04
 LockToken: 70d61d71-9b24-44d2-b54b-7cc08da4d072
 Body: vu8=

***** 73 Queued
03:42:41 Queued: v3/application1@tenant1/devices/wisnodetest04/down/queued
 payload: {"end_device_ids":{"device_id":"wisnodetest04","application_ids":{"application_id":"application1"}},
	"correlation_ids":[
"az:LockToken:70d61d71-9b24-44d2-b54b-7cc08da4d072","as:downlink:01EXX9B800WF7FEP56J3EZ3M8A"],
	"downlink_queued":{"f_port":73,"frm_payload":"vu8=",
"confirmed":true,"priority":"NORMAL",
	"correlation_ids":[
"az:LockToken:70d61d71-9b24-44d2-b54b-7cc08da4d072",
"as:downlink:01EXX9B800WF7FEP56J3EZ3M8A"]}}
...

***** 74 Queued
03:42:45 Azure IoT Hub downlink message
 ApplicationID: application1
 DeviceID: wisnodetest04
 LockToken: 12537728-de4a-4489-ace5-92923e49b8e4
 Body: vu8=
.
03:42:45 Queued: v3/application1@tenant1/devices/wisnodetest04/down/queued
 payload: {"end_device_ids":{"device_id":"wisnodetest04","application_ids":{"application_id":"application1"}},
	"correlation_ids":[
"az:LockToken:12537728-de4a-4489-ace5-92923e49b8e4",
"as:downlink:01EXX9BBWA2YNCN2DFE5FC3BP3"],
	"downlink_queued":{
"f_port":74,"frm_payload":"vu8=",
"confirmed":true,"priority":"NORMAL",
	"correlation_ids":[
"az:LockToken:12537728-de4a-4489-ace5-92923e49b8e4",
"as:downlink:01EXX9BBWA2YNCN2DFE5FC3BP3"]}}
...

***** 75 Queued
03:42:48 Azure IoT Hub downlink message
 ApplicationID: application1
 DeviceID: wisnodetest04
 LockToken: 388efc11-4514-406e-8147-9109289095f4
 Body: vu8=

03:42:49 Queued: v3/application1@tenant1/devices/wisnodetest04/down/queued
 payload: {"end_device_ids":{"device_id":"wisnodetest04","application_ids":{"application_id":"application1"}},
	"correlation_ids":[
"az:LockToken:388efc11-4514-406e-8147-9109289095f4",
"as:downlink:01EXX9BFCM2G51EPYNWGDWPS0N"],
	"downlink_queued":{"f_port":75,"frm_payload":"vu8=",
"confirmed":true,"priority":"NORMAL",
	"correlation_ids":[
"az:LockToken:388efc11-4514-406e-8147-9109289095f4",
"as:downlink:01EXX9BFCM2G51EPYNWGDWPS0N"]}}

***** Waiting for Wisniode
..........................................................................................................................................................................
03:47:18 TTN Uplink message
 ApplicationID: application1
 DeviceID: wisnodetest04
 Port: 5

***** Waiting for Wisniode again, I think might have been such a long delay becuase TTI didn't get
..........................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................
***** 71 Nack'd
03:56:52 Nack: v3/application1@tenant1/devices/wisnodetest04/down/nack
 payload: {"end_device_ids":{"device_id":"wisnodetest04","application_ids":{"application_id":"application1"},
	"dev_eui":"60C5A8FFFE781691","join_eui":"70B3D57ED0000000","dev_addr":"26083BE1"},
	"correlation_ids":[
"as:downlink:01EXX9B1CA4DB68PKCDAK4SS4H",
"as:up:01EXXA572VHN7X7G5KFTHBQPNG",
"az:LockToken:57ea0fad-b6b3-492e-b194-10c4ff3e53cb",
"gs:conn:01EXRPTTFGFNTRGH7V8FTC3R0S",
"gs:up:host:01EXRPTTFTEXBNV87KZFYFWP5V",
"gs:uplink:01EXXA56VPK14XG5S8JB9Q0V0X",
"ns:uplink:01EXXA56VYCHGGPPN1K77REMNM",
"rpc:/ttn.lorawan.v3.GsNs/HandleUplink:01EXXA56VRG6811HRCF803VJ34"],
	"received_at":"2021-02-07T03:56:53.211893610Z",
	"downlink_nack":{
"session_key_id":"AXd6GPmneD3dKVoArcS36g==",
"f_port":71,"f_cnt":35,
"frm_payload":"vu8=",
"confirmed":true,"priority":"NORMAL",
	"correlation_ids":[
"az:LockToken:57ea0fad-b6b3-492e-b194-10c4ff3e53cb",
"as:downlink:01EXX9B1CA4DB68PKCDAK4SS4H"]}}

 Found az:LockToken:

03:56:52 TTN Uplink message
 ApplicationID: application1
 DeviceID: wisnodetest04
 Port: 5

03:56:52 Azure IoT Hub downlink message
 ApplicationID: application1
 DeviceID: wisnodetest04
 LockToken: 856f5a9b-bc37-435c-8de9-19d2213999f8
 Body: vu8=

03:56:53 Queued: v3/application1@tenant1/devices/wisnodetest04/down/queued
 payload: {
"end_device_ids":{"device_id":"wisnodetest04","application_ids":{"application_id":"application1"},
	"correlation_ids":[
"az:LockToken:856f5a9b-bc37-435c-8de9-19d2213999f8",
"as:downlink:01EXXA57JJWWYEDX3Z55TNSTP5"],
	"downlink_queued":{"f_port":71,
"frm_payload":"vu8=",
"confirmed":true,"priority":"NORMAL",
	"correlation_ids":
["az:LockToken:856f5a9b-bc37-435c-8de9-19d2213999f8",
"as:downlink:01EXXA57JJWWYEDX3Z55TNSTP5"]}}

......
***** 71 Ack'd
03:56:58 Ack: v3/application1@tenant1/devices/wisnodetest04/down/ack
 payload: {"end_device_ids":{"device_id":"wisnodetest04","application_ids":{"application_id":"application1"},
	"dev_eui":"60C5A8FFFE781691","join_eui":"70B3D57ED0000000","dev_addr":"26083BE1"},
	"correlation_ids":[
"as:downlink:01EXX9B1CA4DB68PKCDAK4SS4H",
"as:up:01EXXA5D45E77S19TXEV1E4GAJ",
"az:LockToken:57ea0fad-b6b3-492e-b194-10c4ff3e53cb",
"gs:conn:01EXRPTTFGFNTRGH7V8FTC3R0S",
"gs:up:host:01EXRPTTFTEXBNV87KZFYFWP5V",
"gs:uplink:01EXXA5CV73THH2RKEAC2T9MDP",
"ns:uplink:01EXXA5CVDCWPFBTXGGGB3T02W",
"rpc:/ttn.lorawan.v3.GsNs/HandleUplink:01EXXA5CVDEXDFBPYXC0J01Q3E"],
	"received_at":"2021-02-07T03:56:59.397330003Z",
	"downlink_ack":{
"session_key_id":"AXd6GPmneD3dKVoArcS36g==",
"f_port":71,"f_cnt":36,"frm_payload":"vu8=",
"confirmed":true,"priority":"NORMAL",
	"correlation_ids":[
"az:LockToken:57ea0fad-b6b3-492e-b194-10c4ff3e53cb",
"as:downlink:01EXX9B1CA4DB68PKCDAK4SS4H"]}}

 Found az:LockToken:
Exception of type 'Microsoft.Azure.Devices.Client.Exceptions.DeviceMessageLockLostException' was thrown.

03:56:59 TTN Uplink message
 ApplicationID: application1
 DeviceID: wisnodetest04
 Port: 0
......
03:57:04 Ack: v3/application1@tenant1/devices/wisnodetest04/down/ack
 payload: {"end_device_ids":{"device_id":"wisnodetest04","application_ids":{"application_id":"application1"},
"dev_eui":"60C5A8FFFE781691","join_eui":"70B3D57ED0000000","dev_addr":"26083BE1"},
"correlation_ids":[
"as:downlink:01EXX9B4RGSCJ4BN21GHPM85W5",
"as:up:01EXXA5K2FWGP9DGD7THWZ8HNR",
"az:LockToken:e2fef28c-fb1f-42cd-bb40-3ad8e6051da9",
"gs:conn:01EXRPTTFGFNTRGH7V8FTC3R0S",
"gs:up:host:01EXRPTTFTEXBNV87KZFYFWP5V",
"gs:uplink:01EXXA5JVDR102TKCWQ77P4YYF",
"ns:uplink:01EXXA5JVGNGMZN33FNT47G6PF",
"rpc:/ttn.lorawan.v3.GsNs/HandleUplink:01EXXA5JVGJFFQVEWX2M1XSFKK"],
"received_at":"2021-02-07T03:57:05.487910418Z","downlink_ack":{"session_key_id":"AXd6GPmneD3dKVoArcS36g==",
"f_port":72,"f_cnt":37,
"frm_payload":"vu8=",
"confirmed":true,"priority":"NORMAL","correlation_ids":
["az:LockToken:e2fef28c-fb1f-42cd-bb40-3ad8e6051da9","as:downlink:01EXX9B4RGSCJ4BN21GHPM85W5"]}}

The sequence of messages is a bit odd, in the Azure DeviceClient ReceiveMessageHandler a downlink message is published, then a queued message is received, then a nak and finally an ack, The exception was because my client was trying to Complete the delivery of a message that had already been Abandoned.

Application Insights & Configuration

As part of my The Things IndustriesTTI) Integration my current approach is to use an Azure web job and configure the Azure App Service host so it doesn’t get shutdown after a period of inactivity. This so my application won’t have to repeatedly use the TTI API to request the Application and Device configuration information to reload the cache (still not certain if this is going to be implemented with a ConcurrentDictionary or ObjectCache).

namespace devMobile.TheThingsNetwork.WorkerService
{
   using System.Collections.Generic;

   public class AzureDeviceProvisiongServiceSettings
   {
      public string IdScope { get; set; }
      public string GroupEnrollmentKey { get; set; }
   }

   public class AzureSettings
   {
      public string IoTHubConnectionString { get; set; }
      public AzureDeviceProvisiongServiceSettings DeviceProvisioningServiceSettings { get; set; }
   }

   public class ApplicationSetting
   {
      public AzureSettings AzureSettings { get; set; }

      public string MQTTAccessKey { get; set; }

      public byte? ApplicationPageSize { get; set; }

      public bool? DeviceIntegrationDefault { get; set; }
      public byte? DevicePageSize { get; set; }
   }

   public class TheThingsIndustries
   {
      public string MqttServerName { get; set; }
      public string MqttClientName { get; set; }

      public string Tennant { get; set; }
      public string ApiBaseUrl { get; set; }
      public string ApiKey { get; set; }

      public bool ApplicationIntegrationDefault { get; set; }
      public byte ApplicationPageSize { get; set; }

      public bool DeviceIntegrationDefault { get; set; }
      public byte DevicePageSize { get; set; }
   }

   public class ProgramSettings
   {
      public TheThingsIndustries TheThingsIndustries { get; set; }

      public AzureSettings AzureSettingsDefault { get; set; }

      public Dictionary<string, ApplicationSetting> Applications { get; set; }
   }
}

The amount of configuration required to support multiple TTI Applications containing many Devices is also starting to get out of hand.

I need to subscribe to a Message Queue Telemetry Transport Topics(MQTT using MQTTNet) for each Application and establish a connection (using an Azure DeviceClient) for each TTI Device to the configured Azure IoT Hub(s).

  • v3/{application id}@{tenant id}/devices/{device id}/up
  • v3/{application id}@{tenant id}/devices/{device id}/down/queued
  • v3/{application id}@{tenant id}/devices/{device id}/down/sent
  • v3/{application id}@{tenant id}/devices/{device id}/down/ack
  • v3/{application id}@{tenant id}/devices/{device id}/down/nack
  • v3/{application id}@{tenant id}/devices/{device id}/down/failed

The Azure DeviceClient has to be configured and OpenAsync called just before/after subscribing to the TTI Application /up topic so the SendEventAsync method can be called to send messages to the configured Azure IoT Hub(s). For downlink messages the SetReceiveMessageHandler method will need to be called just before/after subscribing to ../down/queued, ../down/sent,../down/ack,…/down/nack and ,…/down/failed downlink topics.

The ordering of downloading the Application and Device configuration so downlink messages can be sent and uplink message received as soon as possible (so no messages are lost) is important. I have considered making the downlink process multi-threaded so API calls are made concurrently but I’m not certain the additional complexity would be worth it, especially in initial versions.

I’m also currently not certain about how to register my program for Application and Device registry changes so it doesn’t have to be restarted when configuration changes. I have also considered reverting to an HTTP Integration so that I could use Azure Storage queues to buffer uplink and downlink messages. This may also introduce ordering issues when multiple threads are created for Azure Queue Trigger functions to process a message backlog.

For debugging the application and monitoring in production I was planning on using the Apache Log4Net library but now I’m not certain the additional configuration complexity and dependencies are worth it. The built in Microsoft.Extensions.Logging library with Azure Application Insights integration looks like a “light weight” alternative with sufficient functionality .

protected override async Task ExecuteAsync(CancellationToken stoppingToken)
{
   while (!stoppingToken.IsCancellationRequested)
   {
      _logger.LogDebug("Debug worker running at: {time}", DateTimeOffset.Now);
      _logger.LogInformation("Info worker running at: {time}", DateTimeOffset.Now);
      _logger.LogWarning("Warning worker running at: {time}", DateTimeOffset.Now);
      _logger.LogError("Error running at: {time}", DateTimeOffset.Now);

      using (_logger.BeginScope("TheThingsIndustries configuration"))
      {
         _logger.LogInformation("Tennant: {0}", _programSettings.TheThingsIndustries.Tennant);
         _logger.LogInformation("ApiBaseUrl: {0}", _programSettings.TheThingsIndustries.ApiBaseUrl);
         _logger.LogInformation("ApiKey: {0}", _programSettings.TheThingsIndustries.ApiKey);

         _logger.LogInformation("ApplicationPageSize: {0}", _programSettings.TheThingsIndustries.ApplicationPageSize);
         _logger.LogInformation("DevicePageSize: {0}", _programSettings.TheThingsIndustries.DevicePageSize);

         _logger.LogInformation("ApplicationIntegrationDefault: {0}", _programSettings.TheThingsIndustries.ApplicationIntegrationDefault);
         _logger.LogInformation("DeviceIntegrationDefault: {0}", _programSettings.TheThingsIndustries.DeviceIntegrationDefault);

         _logger.LogInformation("MQTTServerName: {0}", _programSettings.TheThingsIndustries.MqttServerName);
         _logger.LogInformation("MQTTClientName: {0}", _programSettings.TheThingsIndustries.MqttClientName);
      }

      using (_logger.BeginScope("Azure default configuration"))
      {
         if (_programSettings.AzureSettingsDefault.IoTHubConnectionString != null)
         {
            _logger.LogInformation("AzureSettingsDefault.IoTHubConnectionString: {0}", _programSettings.AzureSettingsDefault.IoTHubConnectionString);
         }

         if (_programSettings.AzureSettingsDefault.DeviceProvisioningServiceSettings != null)
         {
            _logger.LogInformation("AzureSettings.DeviceProvisioningServiceSettings.IdScope: {0}", _programSettings.AzureSettingsDefault.DeviceProvisioningServiceSettings.IdScope);
            _logger.LogInformation("AzureSettings.DeviceProvisioningServiceSettings.GroupEnrollmentKey: {0}", _programSettings.AzureSettingsDefault.DeviceProvisioningServiceSettings.GroupEnrollmentKey);
         }
      }
    
      foreach (var application in _programSettings.Applications)
      {
         using (_logger.BeginScope(new[] { new KeyValuePair<string, object>("Application", application.Key)}))
         {
            _logger.LogInformation("MQTTAccessKey: {0} ", application.Value.MQTTAccessKey);

            if (application.Value.ApplicationPageSize.HasValue)
            {
               _logger.LogInformation("ApplicationPageSize: {0} ", application.Value.ApplicationPageSize.Value);
            }

            if (application.Value.DeviceIntegrationDefault.HasValue)
            {
               _logger.LogInformation("DeviceIntegation: {0} ", application.Value.DeviceIntegrationDefault.Value);
            }

            if (application.Value.DevicePageSize.HasValue)
            {
               _logger.LogInformation("DevicePageSize: {0} ", application.Value.DevicePageSize.Value);
            }

            if (application.Value.AzureSettings.IoTHubConnectionString != null)
            {
               _logger.LogInformation("AzureSettings.IoTHubConnectionString: {0} ", application.Value.AzureSettings.IoTHubConnectionString);
            }

            if (application.Value.AzureSettings.DeviceProvisioningServiceSettings != null)
            {
               _logger.LogInformation("AzureSettings.DeviceProvisioningServiceSettings.IdScope: {0} ", application.Value.AzureSettings.DeviceProvisioningServiceSettings.IdScope);
               _logger.LogInformation("AzureSettings.DeviceProvisioningServiceSettings.GroupEnrollmentKey: {0} ", application.Value.AzureSettings.DeviceProvisioningServiceSettings.GroupEnrollmentKey);
            }
         }
      }

      await Task.Delay(300000, stoppingToken);
   }
}

The logging information formatting is sufficiently readable when running locally

Extensive use of the BeginScope method to include additional meta-data on logged records should make debugging easier.

This long post is to explain some of my design decisions and which ones are still to be decided