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.