MQTT does not auto renew SAS token.

[mmoles-Growlink]

Expected Behavior

MQTT Tokens should renew before they expire. RenewalBuffer should start the process early to ensure tokens dont expire.

Current Behavior

Defaults are 60min token with 15% renewal timer (9m) , so it should try to renew after 51 minutes, but EVERY 70 minutes, i get 'Unable to re-authenticate Device/Module, dropping client connection.' and then it recreates the connection. When I manually define the SAS token length to 30m and renewal of 50%, it becomes every 40 minutes. So, the renewal timer is doing nothing, and the timeout is 10 minutes.

Steps to Reproduce

I just created a module that would send and receives messages to another module and then just duplicated it and used routes to point them at each other.

var mqttTransportSettings = new MqttTransportSettings( TransportType.Mqtt_Tcp_Only );
 ITransportSettings[] settings = { mqttTransportSettings };
 var clientOptions = new ClientOptions
 {
     SasTokenRenewalBuffer = 50,
     SasTokenTimeToLive = TimeSpan.FromMinutes( 30 )
 };
 var moduleClient = await ModuleClient.CreateFromEnvironmentAsync( settings, clientOptions );
 await moduleClient.OpenAsync();

 await moduleClient.SetInputMessageHandlerAsync( "onEveryLoopRec", onEveryLoopRec, moduleClient );

Device Information

• Host OS [e.g. Ubuntu 22.04, Windows Server IoT 2019]: Raspbian 11 (bullseye)
• Architecture [e.g. amd64, arm32, arm64]: arm32
• Container OS [e.g. Linux containers, Windows containers]: Linux

Runtime Versions

• aziot-edged 1.4.10
• Edge Agent [image tag (e.g. 1.0.0)]: 1.4 and 1.5
• Edge Hub [image tag (e.g. 1.0.0)]: 1.4 and 1.5
• Docker/Moby : 20.10.24+azure-1

Logs

edge-hub logs

<6> 2025-03-30 16:29:46.537 +00:00 [INF] - Error authenticating token for Room-aaaabbbb/TestMod5 because the token is expired or could not be parsed
<6> 2025-03-30 16:29:46.548 +00:00 [INF] - Credentials for client Room-aaaabbbb/TestMod5 are not valid.
<4> 2025-03-30 16:29:46.549 +00:00 [WRN] - Reauthenticating client Room-aaaabbbb/TestMod5 failed, removing client connection
<6> 2025-03-30 16:29:46.549 +00:00 [INF] - Unable to re-authenticate Room-aaaabbbb/TestMod5, dropping client connection.
<6> 2025-03-30 16:29:46.550 +00:00 [INF] - Removing device connection for device Room-aaaabbbb/TestMod5 with removeCloudConnection flag 'True'.
<4> 2025-03-30 16:29:46.551 +00:00 [WRN] - "Closing connection for device: Room-aaaabbbb/TestMod5, Microsoft.Azure.Devices.Edge.Hub.Core.EdgeHubConnectionException: Connection closed for device Room-aaaabbbb/TestMod5., "
<6> 2025-03-30 16:29:46.551 +00:00 [INF] - Disposing MessagingServiceClient for device Id Room-aaaabbbb/TestMod5 because of exception - Microsoft.Azure.Devices.Edge.Hub.Core.EdgeHubConnectionException: Connection closed for device Room-aaaabbbb/TestMod5.
<6> 2025-03-30 16:29:46.552 +00:00 [INF] - Closing device proxy for device Id Room-aaaabbbb/TestMod5
<6> 2025-03-30 16:29:46.591 +00:00 [INF] - Closing receiver in cloud proxy 6fec5de3-b2d3-4dd4-85ff-439882903ff5 for Room-aaaabbbb/TestMod5
<6> 2025-03-30 16:29:46.591 +00:00 [INF] - Closed cloud proxy 6fec5de3-b2d3-4dd4-85ff-439882903ff5 for Room-aaaabbbb/TestMod5
<6> 2025-03-30 16:29:46.596 +00:00 [INF] - Device connection removed for device Room-aaaabbbb/TestMod5
<6> 2025-03-30 16:29:46.608 +00:00 [INF] - Error authenticating token for Room-aaaabbbb/TestMod6 because the token is expired or could not be parsed
<6> 2025-03-30 16:29:46.608 +00:00 [INF] - Credentials for client Room-aaaabbbb/TestMod6 are not valid.
<4> 2025-03-30 16:29:46.609 +00:00 [WRN] - Reauthenticating client Room-aaaabbbb/TestMod6 failed, removing client connection
<6> 2025-03-30 16:29:46.609 +00:00 [INF] - Unable to re-authenticate Room-aaaabbbb/TestMod6, dropping client connection.
<6> 2025-03-30 16:29:46.609 +00:00 [INF] - Removing device connection for device Room-aaaabbbb/TestMod6 with removeCloudConnection flag 'True'.
<4> 2025-03-30 16:29:46.610 +00:00 [WRN] - "Closing connection for device: Room-aaaabbbb/TestMod6, Microsoft.Azure.Devices.Edge.Hub.Core.EdgeHubConnectionException: Connection closed for device Room-aaaabbbb/TestMod6., "
<6> 2025-03-30 16:29:46.611 +00:00 [INF] - Disposing MessagingServiceClient for device Id Room-aaaabbbb/TestMod6 because of exception - Microsoft.Azure.Devices.Edge.Hub.Core.EdgeHubConnectionException: Connection closed for device Room-aaaabbbb/TestMod6.
<6> 2025-03-30 16:29:46.611 +00:00 [INF] - Closing device proxy for device Id Room-aaaabbbb/TestMod6
<6> 2025-03-30 16:29:46.666 +00:00 [INF] - Closing receiver in cloud proxy 16657ccf-ef87-4538-8bc5-695f01e211fb for Room-aaaabbbb/TestMod6
<6> 2025-03-30 16:29:46.667 +00:00 [INF] - Closed cloud proxy 16657ccf-ef87-4538-8bc5-695f01e211fb for Room-aaaabbbb/TestMod6
<6> 2025-03-30 16:29:46.667 +00:00 [INF] - Device connection removed for device Room-aaaabbbb/TestMod6
<6> 2025-03-30 16:29:47.608 +00:00 [INF] - Updated reported properties for Room-aaaabbbb/$edgeHub
<6> 2025-03-30 16:29:48.067 +00:00 [INF] - Client Room-aaaabbbb/TestMod5 in device scope authenticated locally.
<6> 2025-03-30 16:29:48.084 +00:00 [INF] - Successfully generated identity for clientId Room-aaaabbbb/TestMod5 and username GrowPiaaaabbbb/Room-aaaabbbb/TestMod5/?api-version=2020-09-30&DeviceClientType=.NET%2F1.42.0%20%28.NET%207.0.20%3B%20Linux%206.1.21-v8%2B%20%231642%20SMP%20PREEMPT%20Mon%20Apr%20%203%2017%3A24%3A16%20BST%202023%3B%20Arm%29
<6> 2025-03-30 16:29:48.085 +00:00 [INF] - "ClientAuthenticated, Room-aaaabbbb/TestMod5, 295d7947"
<6> 2025-03-30 16:29:48.088 +00:00 [INF] - New device connection for device Room-aaaabbbb/TestMod5
<6> 2025-03-30 16:29:48.089 +00:00 [INF] - Client Room-aaaabbbb/TestMod5 connected to edgeHub, processing existing subscriptions.
<6> 2025-03-30 16:29:48.090 +00:00 [INF] - Bind device proxy for device Room-aaaabbbb/TestMod5
<6> 2025-03-30 16:29:48.091 +00:00 [INF] - Binding message channel for device Id Room-aaaabbbb/TestMod5
<6> 2025-03-30 16:29:48.100 +00:00 [INF] - Processing pending subscriptions for Room-aaaabbbb/TestMod5
<6> 2025-03-30 16:29:48.101 +00:00 [INF] - Processing subscriptions TwinResponse, ModuleMessages, Methods for client Room-aaaabbbb/TestMod5.
<6> 2025-03-30 16:29:48.101 +00:00 [INF] - Attempting to connect to IoT Hub for client Room-aaaabbbb/TestMod5 via AMQP...
<6> 2025-03-30 16:29:48.105 +00:00 [INF] - Set subscriptions from session state for Room-aaaabbbb/TestMod5
<6> 2025-03-30 16:29:48.112 +00:00 [INF] - Processing subscriptions TwinResponse, ModuleMessages, Methods for client Room-aaaabbbb/TestMod5.
<6> 2025-03-30 16:29:48.113 +00:00 [INF] - Set subscriptions from session state for Room-aaaabbbb/TestMod5
<6> 2025-03-30 16:29:48.128 +00:00 [INF] - Processing subscriptions TwinResponse, ModuleMessages, Methods for client Room-aaaabbbb/TestMod5.
<6> 2025-03-30 16:29:48.138 +00:00 [INF] - Set subscriptions from session state for Room-aaaabbbb/TestMod5
<4> 2025-03-30 16:29:48.185 +00:00 [WRN] - Module Room-aaaabbbb/TestMod6 is not connected
<4> 2025-03-30 16:29:48.228 +00:00 [WRN] - Module Room-aaaabbbb/TestMod6 is not connected
<6> 2025-03-30 16:29:48.251 +00:00 [INF] - Cloud connection for Room-aaaabbbb/TestMod5 is True
<6> 2025-03-30 16:29:48.251 +00:00 [INF] - Connection status for Room-aaaabbbb/TestMod5 changed to ConnectionEstablished
<6> 2025-03-30 16:29:48.251 +00:00 [INF] - Client Room-aaaabbbb/TestMod5 connected to cloud, processing existing subscriptions.
<6> 2025-03-30 16:29:48.252 +00:00 [INF] - Skipping Room-aaaabbbb/TestMod5 for subscription processing, as it is currently being processed.
<6> 2025-03-30 16:29:48.252 +00:00 [INF] - Created cloud proxy for client Room-aaaabbbb/TestMod5 via AMQP, with client operation timeout 20 seconds.
<6> 2025-03-30 16:29:48.252 +00:00 [INF] - Initialized cloud proxy 58e7ca72-8877-46b3-acc2-a206db6673a9 for Room-aaaabbbb/TestMod5
<6> 2025-03-30 16:29:48.254 +00:00 [INF] - Created cloud connection for client Room-aaaabbbb/TestMod5
<6> 2025-03-30 16:29:48.336 +00:00 [INF] - Processing pending subscriptions for Room-aaaabbbb/TestMod5
<6> 2025-03-30 16:29:48.336 +00:00 [INF] - Processing pending subscriptions for Room-aaaabbbb/TestMod5
<6> 2025-03-30 16:29:48.336 +00:00 [INF] - Processing pending subscriptions for Room-aaaabbbb/TestMod5
<6> 2025-03-30 16:29:48.336 +00:00 [INF] - Processing pending subscriptions for Room-aaaabbbb/TestMod5
<6> 2025-03-30 16:29:48.336 +00:00 [INF] - Processing pending subscriptions for Room-aaaabbbb/TestMod5
<6> 2025-03-30 16:29:49.107 +00:00 [INF] - Client Room-aaaabbbb/TestMod6 in device scope authenticated locally.
<6> 2025-03-30 16:29:49.108 +00:00 [INF] - Successfully generated identity for clientId Room-aaaabbbb/TestMod6 and username GrowPiaaaabbbb/Room-aaaabbbb/TestMod6/?api-version=2020-09-30&DeviceClientType=.NET%2F1.42.0%20%28.NET%207.0.20%3B%20Linux%206.1.21-v8%2B%20%231642%20SMP%20PREEMPT%20Mon%20Apr%20%203%2017%3A24%3A16%20BST%202023%3B%20Arm%29
<6> 2025-03-30 16:29:49.124 +00:00 [INF] - "ClientAuthenticated, Room-aaaabbbb/TestMod6, 16be85c6"
<6> 2025-03-30 16:29:49.129 +00:00 [INF] - New device connection for device Room-aaaabbbb/TestMod6
<6> 2025-03-30 16:29:49.129 +00:00 [INF] - Client Room-aaaabbbb/TestMod6 connected to edgeHub, processing existing subscriptions.
<6> 2025-03-30 16:29:49.130 +00:00 [INF] - Bind device proxy for device Room-aaaabbbb/TestMod6
<6> 2025-03-30 16:29:49.130 +00:00 [INF] - Binding message channel for device Id Room-aaaabbbb/TestMod6
<6> 2025-03-30 16:29:49.131 +00:00 [INF] - Processing pending subscriptions for Room-aaaabbbb/TestMod6
<6> 2025-03-30 16:29:49.131 +00:00 [INF] - Attempting to connect to IoT Hub for client Room-aaaabbbb/TestMod6 via AMQP...
<6> 2025-03-30 16:29:49.133 +00:00 [INF] - Processing subscriptions TwinResponse, ModuleMessages, Methods for client Room-aaaabbbb/TestMod6.
<6> 2025-03-30 16:29:49.141 +00:00 [INF] - Set subscriptions from session state for Room-aaaabbbb/TestMod6
<6> 2025-03-30 16:29:49.155 +00:00 [INF] - Processing subscriptions TwinResponse, ModuleMessages, Methods for client Room-aaaabbbb/TestMod6.
<6> 2025-03-30 16:29:49.160 +00:00 [INF] - Set subscriptions from session state for Room-aaaabbbb/TestMod6
<6> 2025-03-30 16:29:49.161 +00:00 [INF] - Processing subscriptions TwinResponse, ModuleMessages, Methods for client Room-aaaabbbb/TestMod6.
<6> 2025-03-30 16:29:49.164 +00:00 [INF] - Set subscriptions from session state for Room-aaaabbbb/TestMod6
<6> 2025-03-30 16:29:49.631 +00:00 [INF] - Cloud connection for Room-aaaabbbb/TestMod6 is True
<6> 2025-03-30 16:29:49.631 +00:00 [INF] - Connection status for Room-aaaabbbb/TestMod6 changed to ConnectionEstablished
<6> 2025-03-30 16:29:49.631 +00:00 [INF] - Client Room-aaaabbbb/TestMod6 connected to cloud, processing existing subscriptions.
<6> 2025-03-30 16:29:49.631 +00:00 [INF] - Skipping Room-aaaabbbb/TestMod6 for subscription processing, as it is currently being processed.
<6> 2025-03-30 16:29:49.631 +00:00 [INF] - Created cloud proxy for client Room-aaaabbbb/TestMod6 via AMQP, with client operation timeout 20 seconds.
<6> 2025-03-30 16:29:49.632 +00:00 [INF] - Initialized cloud proxy 0dbf975d-3b81-4759-b4e3-25a61bd53711 for Room-aaaabbbb/TestMod6
<6> 2025-03-30 16:29:49.632 +00:00 [INF] - Created cloud connection for client Room-aaaabbbb/TestMod6
<6> 2025-03-30 16:29:49.690 +00:00 [INF] - Processing pending subscriptions for Room-aaaabbbb/TestMod6
<6> 2025-03-30 16:29:49.690 +00:00 [INF] - Processing pending subscriptions for Room-aaaabbbb/TestMod6
<6> 2025-03-30 16:29:49.691 +00:00 [INF] - Processing pending subscriptions for Room-aaaabbbb/TestMod6
<6> 2025-03-30 16:29:49.691 +00:00 [INF] - Processing pending subscriptions for Room-aaaabbbb/TestMod6
<6> 2025-03-30 16:29:49.691 +00:00 [INF] - Processing pending subscriptions for Room-aaaabbbb/TestMod6
<6> 2025-03-30 16:29:53.282 +00:00 [INF] - Updated reported properties for Room-aaaabbbb/$edgeHub
<6> 2025-03-30 16:31:02.188 +00:00 [INF] - "Request starting HTTP/1.1 GET http://edgehub:9600/metrics - -"
<6> 2025-03-30 16:31:02.782 +00:00 [INF] - "Request finished HTTP/1.1 GET http://edgehub:9600/metrics - - - 200 - text/plain;+version=0.0.4;+charset=utf-8 593.5390ms"
<6> 2025-03-30 16:31:54.309 +00:00 [INF] - New token received on the Cbs link
<6> 2025-03-30 16:31:54.310 +00:00 [INF] - Token updated for Room-aaaabbbb/TestMod3
<6> 2025-03-30 16:32:02.288 +00:00 [INF] - New token received on the Cbs link
<6> 2025-03-30 16:32:02.291 +00:00 [INF] - Token updated for Room-aaaabbbb/TestMod4
<6> 2025-03-30 16:32:50.943 +00:00 [INF] - Updated reported properties for Room-aaaabbbb/ModuleLNM
<6> 2025-03-30 16:32:56.493 +00:00 [INF] - Updated reported properties for Room-aaaabbbb/ModuleLNM
<6> 2025-03-30 16:33:02.100 +00:00 [INF] - Updated reported properties for Room-aaaabbbb/ModuleBMS
<6> 2025-03-30 16:33:02.693 +00:00 [INF] - Updated reported properties for Room-aaaabbbb/ModuleBRM
<6> 2025-03-30 16:34:46.535 +00:00 [INF] - Entering periodic task to reauthenticate connected clients
<6> 2025-03-30 16:34:46.539 +00:00 [INF] - Error authenticating token for Room-aaaabbbb/EdgeProxy because the token is expired or could not be parsed
<6> 2025-03-30 16:34:46.539 +00:00 [INF] - Credentials for client Room-aaaabbbb/EdgeProxy are not valid.
<4> 2025-03-30 16:34:46.554 +00:00 [WRN] - Reauthenticating client Room-aaaabbbb/EdgeProxy failed, removing client connection
<6> 2025-03-30 16:34:46.557 +00:00 [INF] - Unable to re-authenticate Room-aaaabbbb/EdgeProxy, dropping client connection.
<6> 2025-03-30 16:34:46.557 +00:00 [INF] - Removing device connection for device Room-aaaabbbb/EdgeProxy with removeCloudConnection flag 'True'.
<4> 2025-03-30 16:34:46.558 +00:00 [WRN] - "Closing connection for device: Room-aaaabbbb/EdgeProxy, Microsoft.Azure.Devices.Edge.Hub.Core.EdgeHubConnectionException: Connection closed for device Room-aaaabbbb/EdgeProxy., "
<6> 2025-03-30 16:34:46.558 +00:00 [INF] - Disposing MessagingServiceClient for device Id Room-aaaabbbb/EdgeProxy because of exception - Microsoft.Azure.Devices.Edge.Hub.Core.EdgeHubConnectionException: Connection closed for device Room-aaaabbbb/EdgeProxy.
<6> 2025-03-30 16:34:46.559 +00:00 [INF] - Closing device proxy for device Id Room-aaaabbbb/EdgeProxy
<6> 2025-03-30 16:34:46.600 +00:00 [INF] - Closing receiver in cloud proxy f2cc1d77-5feb-417e-92c2-48518c1c3322 for Room-aaaabbbb/EdgeProxy
<6> 2025-03-30 16:34:46.600 +00:00 [INF] - Closed cloud proxy f2cc1d77-5feb-417e-92c2-48518c1c3322 for Room-aaaabbbb/EdgeProxy
<6> 2025-03-30 16:34:46.600 +00:00 [INF] - Device connection removed for device Room-aaaabbbb/EdgeProxy
<6> 2025-03-30 16:34:47.106 +00:00 [INF] - Client Room-aaaabbbb/EdgeProxy in device scope authenticated locally.
<6> 2025-03-30 16:34:47.111 +00:00 [INF] - Successfully generated identity for clientId Room-aaaabbbb/EdgeProxy and username GrowPiaaaabbbb/Room-aaaabbbb/EdgeProxy/?api-version=2020-09-30&DeviceClientType=.NET%2F1.32.0-preview-001%20%28.NET%207.0.20%3B%20Linux%206.1.21-v8%2B%20%231642%20SMP%20PREEMPT%20Mon%20Apr%20%203%2017%3A24%3A16%20BST%202023%3B%20Arm%29
<6> 2025-03-30 16:34:47.111 +00:00 [INF] - "ClientAuthenticated, Room-aaaabbbb/EdgeProxy, 62554ca4"
<6> 2025-03-30 16:34:47.115 +00:00 [INF] - New device connection for device Room-aaaabbbb/EdgeProxy
<6> 2025-03-30 16:34:47.116 +00:00 [INF] - Client Room-aaaabbbb/EdgeProxy connected to edgeHub, processing existing subscriptions.
<6> 2025-03-30 16:34:47.120 +00:00 [INF] - Bind device proxy for device Room-aaaabbbb/EdgeProxy
<6> 2025-03-30 16:34:47.120 +00:00 [INF] - Binding message channel for device Id Room-aaaabbbb/EdgeProxy
<6> 2025-03-30 16:34:47.121 +00:00 [INF] - Attempting to connect to IoT Hub for client Room-aaaabbbb/EdgeProxy via AMQP...
<6> 2025-03-30 16:34:47.123 +00:00 [INF] - Processing pending subscriptions for Room-aaaabbbb/EdgeProxy
<6> 2025-03-30 16:34:47.131 +00:00 [INF] - Processing subscriptions TwinResponse, Methods for client Room-aaaabbbb/EdgeProxy.
<6> 2025-03-30 16:34:47.132 +00:00 [INF] - Set subscriptions from session state for Room-aaaabbbb/EdgeProxy
<6> 2025-03-30 16:34:47.139 +00:00 [INF] - Processing subscriptions TwinResponse, Methods for client Room-aaaabbbb/EdgeProxy.
<6> 2025-03-30 16:34:47.141 +00:00 [INF] - Set subscriptions from session state for Room-aaaabbbb/EdgeProxy
<6> 2025-03-30 16:34:47.275 +00:00 [INF] - Cloud connection for Room-aaaabbbb/EdgeProxy is True
<6> 2025-03-30 16:34:47.276 +00:00 [INF] - Connection status for Room-aaaabbbb/EdgeProxy changed to ConnectionEstablished
<6> 2025-03-30 16:34:47.280 +00:00 [INF] - Client Room-aaaabbbb/EdgeProxy connected to cloud, processing existing subscriptions.
<6> 2025-03-30 16:34:47.280 +00:00 [INF] - Skipping Room-aaaabbbb/EdgeProxy for subscription processing, as it is currently being processed.
<6> 2025-03-30 16:34:47.280 +00:00 [INF] - Created cloud proxy for client Room-aaaabbbb/EdgeProxy via AMQP, with client operation timeout 20 seconds.
<6> 2025-03-30 16:34:47.280 +00:00 [INF] - Initialized cloud proxy d6c5f07e-767c-434d-bf84-462e0fcb92b5 for Room-aaaabbbb/EdgeProxy
<6> 2025-03-30 16:34:47.280 +00:00 [INF] - Created cloud connection for client Room-aaaabbbb/EdgeProxy
<6> 2025-03-30 16:34:47.327 +00:00 [INF] - Processing pending subscriptions for Room-aaaabbbb/EdgeProxy
<6> 2025-03-30 16:34:47.327 +00:00 [INF] - Processing pending subscriptions for Room-aaaabbbb/EdgeProxy
<6> 2025-03-30 16:34:47.327 +00:00 [INF] - Processing pending subscriptions for Room-aaaabbbb/EdgeProxy
<6> 2025-03-30 16:34:47.575 +00:00 [INF] - Updated reported properties for Room-aaaabbbb/$edgeHub
<6> 2025-03-30 16:34:53.151 +00:00 [INF] - Updated reported properties for Room-aaaabbbb/$edgeHub
<6> 2025-03-30 16:36:03.943 +00:00 [INF] - "Request starting HTTP/1.1 GET http://edgehub:9600/metrics - -"
<6> 2025-03-30 16:36:04.399 +00:00 [INF] - "Request finished HTTP/1.1 GET http://edgehub:9600/metrics - - - 200 - text/plain;+version=0.0.4;+charset=utf-8 455.9493ms"
<6> 2025-03-30 16:37:37.305 +00:00 [INF] - New token received on the Cbs link
<6> 2025-03-30 16:37:37.306 +00:00 [INF] - Token updated for Room-aaaabbbb/TestMod1
<6> 2025-03-30 16:37:42.252 +00:00 [INF] - New token received on the Cbs link
<6> 2025-03-30 16:37:42.255 +00:00 [INF] - Token updated for Room-aaaabbbb/TestMod2
<6> 2025-03-30 16:37:50.581 +00:00 [INF] - Updated reported properties for Room-aaaabbbb/ModuleLNM
<6> 2025-03-30 16:37:56.096 +00:00 [INF] - Updated reported properties for Room-aaaabbbb/ModuleLNM
<6> 2025-03-30 16:38:01.673 +00:00 [INF] - Updated reported properties for Room-aaaabbbb/ModuleBMS
<6> 2025-03-30 16:38:02.206 +00:00 [INF] - Updated reported properties for Room-aaaabbbb/ModuleBRM
<6> 2025-03-30 16:39:46.531 +00:00 [INF] - Entering periodic task to reauthenticate connected clients
<6> 2025-03-30 16:41:05.628 +00:00 [INF] - "Request starting HTTP/1.1 GET http://edgehub:9600/metrics - -"
<6> 2025-03-30 16:41:06.051 +00:00 [INF] - "Request finished HTTP/1.1 GET http://edgehub:9600/metrics - - - 200 - text/plain;+version=0.0.4;+charset=utf-8 422.7002ms"
<6> 2025-03-30 16:42:50.559 +00:00 [INF] - Updated reported properties for Room-aaaabbbb/ModuleLNM
<6> 2025-03-30 16:42:56.171 +00:00 [INF] - Updated reported properties for Room-aaaabbbb/ModuleLNM
<6> 2025-03-30 16:43:01.748 +00:00 [INF] - Updated reported properties for Room-aaaabbbb/ModuleBMS
<6> 2025-03-30 16:43:02.312 +00:00 [INF] - Updated reported properties for Room-aaaabbbb/ModuleBRM
<6> 2025-03-30 16:43:33.722 +00:00 [INF] - Started task to cleanup processed and stale messages for endpoint Room-aaaabbbb/TestMod2/onEverySixtySecondsRec
<6> 2025-03-30 16:43:33.840 +00:00 [INF] - Cleaned up 36 messages from queue for endpoint Room-aaaabbbb/TestMod2/onEverySixtySecondsRec and 36 messages from message store.
<6> 2025-03-30 16:43:33.841 +00:00 [INF] - Started task to cleanup processed and stale messages for endpoint Room-aaaabbbb/ModuleBMS/configurationUpdated
<6> 2025-03-30 16:43:33.841 +00:00 [INF] - Cleaned up 0 messages from queue for endpoint Room-aaaabbbb/ModuleBMS/configurationUpdated and 0 messages from message store.
<6> 2025-03-30 16:43:33.841 +00:00 [INF] - Started task to cleanup processed and stale messages for endpoint Room-aaaabbbb/ModuleLNM/SharedDeviceBroadcast
<6> 2025-03-30 16:43:37.579 +00:00 [INF] - Cleaned up 900 messages from queue for endpoint Room-aaaabbbb/ModuleLNM/SharedDeviceBroadcast and 900 messages from message store.
<6> 2025-03-30 16:43:37.579 +00:00 [INF] - Started task to cleanup processed and stale messages for endpoint Room-aaaabbbb/ModuleLNM/SharedDosingRecipeBroadcast
<6> 2025-03-30 16:43:37.580 +00:00 [INF] - Cleaned up 0 messages from queue for endpoint Room-aaaabbbb/ModuleLNM/SharedDosingRecipeBroadcast and 0 messages from message store.
<6> 2025-03-30 16:43:37.580 +00:00 [INF] - Started task to cleanup processed and stale messages for endpoint Room-aaaabbbb/TestMod5/onEveryThirtySecondsRec
<6> 2025-03-30 16:43:37.814 +00:00 [INF] - Cleaned up 72 messages from queue for endpoint Room-aaaabbbb/TestMod5/onEveryThirtySecondsRec and 72 messages from message store.
<6> 2025-03-30 16:43:37.815 +00:00 [INF] - Started task to cleanup processed and stale messages for endpoint Room-aaaabbbb/TestMod3/onEveryThirtySecondsRec
<6> 2025-03-30 16:43:38.134 +00:00 [INF] - Cleaned up 71 messages from queue for endpoint Room-aaaabbbb/TestMod3/onEveryThirtySecondsRec and 71 messages from message store.
<6> 2025-03-30 16:43:38.134 +00:00 [INF] - Started task to cleanup processed and stale messages for endpoint Room-aaaabbbb/ModuleLNM/configurationUpdated
<6> 2025-03-30 16:43:38.135 +00:00 [INF] - Cleaned up 0 messages from queue for endpoint Room-aaaabbbb/ModuleLNM/configurationUpdated and 0 messages from message store.
<6> 2025-03-30 16:43:38.135 +00:00 [INF] - Started task to cleanup processed and stale messages for endpoint Room-aaaabbbb/TestMod2/onEveryLoopRec
<6> 2025-03-30 16:44:20.313 +00:00 [INF] - Cleaned up 10720 messages from queue for endpoint Room-aaaabbbb/TestMod2/onEveryLoopRec and 10720 messages from message store.
<6> 2025-03-30 16:44:20.314 +00:00 [INF] - Started task to cleanup processed and stale messages for endpoint Room-aaaabbbb/ModuleCM/ModuleEMDetected
<6> 2025-03-30 16:44:20.315 +00:00 [INF] - Cleaned up 0 messages from queue for endpoint Room-aaaabbbb/ModuleCM/ModuleEMDetected and 0 messages from message store.
<6> 2025-03-30 16:44:20.316 +00:00 [INF] - Started task to cleanup processed and stale messages for endpoint Room-aaaabbbb/ModuleREM/configurationUpdated
<6> 2025-03-30 16:44:20.316 +00:00 [INF] - Cleaned up 0 messages from queue for endpoint Room-aaaabbbb/ModuleREM/configurationUpdated and 0 messages from message store.
<6> 2025-03-30 16:44:20.320 +00:00 [INF] - Started task to cleanup processed and stale messages for endpoint Room-aaaabbbb/ModuleLNM/RouteReadRequest
<6> 2025-03-30 16:44:20.321 +00:00 [INF] - Cleaned up 0 messages from queue for endpoint Room-aaaabbbb/ModuleLNM/RouteReadRequest and 0 messages from message store.
<6> 2025-03-30 16:44:20.321 +00:00 [INF] - Started task to cleanup processed and stale messages for endpoint Room-aaaabbbb/TestMod6/onEveryThirtySecondsRec
<6> 2025-03-30 16:44:20.693 +00:00 [INF] - Cleaned up 72 messages from queue for endpoint Room-aaaabbbb/TestMod6/onEveryThirtySecondsRec and 72 messages from message store.
<6> 2025-03-30 16:44:20.693 +00:00 [INF] - Started task to cleanup processed and stale messages for endpoint Room-aaaabbbb/TestMod1/onEverySixtySecondsRec
<6> 2025-03-30 16:44:20.812 +00:00 [INF] - Cleaned up 36 messages from queue for endpoint Room-aaaabbbb/TestMod1/onEverySixtySecondsRec and 36 messages from message store.
<6> 2025-03-30 16:44:20.812 +00:00 [INF] - Started task to cleanup processed and stale messages for endpoint Room-aaaabbbb/TestMod3/onEverySecondRec
<6> 2025-03-30 16:44:29.872 +00:00 [INF] - Cleaned up 2146 messages from queue for endpoint Room-aaaabbbb/TestMod3/onEverySecondRec and 2146 messages from message store.
<6> 2025-03-30 16:44:29.873 +00:00 [INF] - Started task to cleanup processed and stale messages for endpoint Room-aaaabbbb/TestMod3/onEverySixtySecondsRec
<6> 2025-03-30 16:44:29.990 +00:00 [INF] - Cleaned up 36 messages from queue for endpoint Room-aaaabbbb/TestMod3/onEverySixtySecondsRec and 36 messages from message store.
<6> 2025-03-30 16:44:29.990 +00:00 [INF] - Started task to cleanup processed and stale messages for endpoint Room-aaaabbbb/TestMod5/onFiveMinutesRec
<6> 2025-03-30 16:44:30.011 +00:00 [INF] - Cleaned up 7 messages from queue for endpoint Room-aaaabbbb/TestMod5/onFiveMinutesRec and 7 messages from message store.
<6> 2025-03-30 16:44:30.011 +00:00 [INF] - Started task to cleanup processed and stale messages for endpoint Room-aaaabbbb/TestMod3/onEveryLoopRec
<6> 2025-03-30 16:44:46.531 +00:00 [INF] - Entering periodic task to reauthenticate connected clients
<6> 2025-03-30 16:45:13.267 +00:00 [INF] - Cleaned up 10719 messages from queue for endpoint Room-aaaabbbb/TestMod3/onEveryLoopRec and 10719 messages from message store.
<6> 2025-03-30 16:45:13.270 +00:00 [INF] - Started task to cleanup processed and stale messages for endpoint Room-aaaabbbb/ModuleBRM/configurationUpdated
<6> 2025-03-30 16:45:13.273 +00:00 [INF] - Cleaned up 0 messages from queue for endpoint Room-aaaabbbb/ModuleBRM/configurationUpdated and 0 messages from message store.
<6> 2025-03-30 16:45:13.273 +00:00 [INF] - Started task to cleanup processed and stale messages for endpoint Room-aaaabbbb/ModuleLNM/RfBroadcastPayload
<6> 2025-03-30 16:45:30.841 +00:00 [INF] - Cleaned up 4290 messages from queue for endpoint Room-aaaabbbb/ModuleLNM/RfBroadcastPayload and 4290 messages from message store.
<6> 2025-03-30 16:45:30.843 +00:00 [INF] - Started task to cleanup processed and stale messages for endpoint iothub
<6> 2025-03-30 16:45:31.219 +00:00 [INF] - Cleaned up 103 messages from queue for endpoint iothub and 103 messages from message store.
<6> 2025-03-30 16:45:31.220 +00:00 [INF] - Started task to cleanup processed and stale messages for endpoint Room-aaaabbbb/ModuleREM/sharedCommands
<6> 2025-03-30 16:45:31.220 +00:00 [INF] - Cleaned up 0 messages from queue for endpoint Room-aaaabbbb/ModuleREM/sharedCommands and 0 messages from message store.
<6> 2025-03-30 16:45:31.221 +00:00 [INF] - Started task to cleanup processed and stale messages for endpoint Room-aaaabbbb/TestMod6/onEveryLoopRec
<6> 2025-03-30 16:46:07.155 +00:00 [INF] - "Request starting HTTP/1.1 GET http://edgehub:9600/metrics - -"
<6> 2025-03-30 16:46:08.093 +00:00 [INF] - "Request finished HTTP/1.1 GET http://edgehub:9600/metrics - - - 200 - text/plain;+version=0.0.4;+charset=utf-8 937.6774ms"
<6> 2025-03-30 16:46:15.679 +00:00 [INF] - Cleaned up 10702 messages from queue for endpoint Room-aaaabbbb/TestMod6/onEveryLoopRec and 10702 messages from message store.
<6> 2025-03-30 16:46:15.679 +00:00 [INF] - Started task to cleanup processed and stale messages for endpoint Room-aaaabbbb/TestMod4/onEverySecondRec
<6> 2025-03-30 16:46:24.743 +00:00 [INF] - Cleaned up 2145 messages from queue for endpoint Room-aaaabbbb/TestMod4/onEverySecondRec and 2145 messages from message store.
<6> 2025-03-30 16:46:24.743 +00:00 [INF] - Started task to cleanup processed and stale messages for endpoint Room-aaaabbbb/TestMod6/onEverySecondRec
<6> 2025-03-30 16:46:33.098 +00:00 [INF] - Cleaned up 2141 messages from queue for endpoint Room-aaaabbbb/TestMod6/onEverySecondRec and 2141 messages from message store.
<6> 2025-03-30 16:46:33.099 +00:00 [INF] - Started task to cleanup processed and stale messages for endpoint Room-aaaabbbb/TestMod6/onEverySixtySecondsRec
<6> 2025-03-30 16:46:33.243 +00:00 [INF] - Cleaned up 36 messages from queue for endpoint Room-aaaabbbb/TestMod6/onEverySixtySecondsRec and 36 messages from message store.
<6> 2025-03-30 16:46:33.243 +00:00 [INF] - Started task to cleanup processed and stale messages for endpoint Room-aaaabbbb/TestMod2/onEveryThirtySecondsRec
<6> 2025-03-30 16:46:33.536 +00:00 [INF] - Cleaned up 71 messages from queue for endpoint Room-aaaabbbb/TestMod2/onEveryThirtySecondsRec and 71 messages from message store.
<6> 2025-03-30 16:46:33.536 +00:00 [INF] - Started task to cleanup processed and stale messages for endpoint Room-aaaabbbb/TestMod5/onEverySecondRec
<6> 2025-03-30 16:46:41.984 +00:00 [INF] - Cleaned up 2140 messages from queue for endpoint Room-aaaabbbb/TestMod5/onEverySecondRec and 2140 messages from message store.
<6> 2025-03-30 16:46:41.984 +00:00 [INF] - Started task to cleanup processed and stale messages for endpoint Room-aaaabbbb/TestMod5/onEveryLoopRec
<6> 2025-03-30 16:47:24.485 +00:00 [INF] - Cleaned up 10672 messages from queue for endpoint Room-aaaabbbb/TestMod5/onEveryLoopRec and 10672 messages from message store.
<6> 2025-03-30 16:47:24.486 +00:00 [INF] - Started task to cleanup processed and stale messages for endpoint Room-aaaabbbb/TestMod1/onEveryLoopRec
<6> 2025-03-30 16:47:50.740 +00:00 [INF] - Updated reported properties for Room-aaaabbbb/ModuleLNM
<6> 2025-03-30 16:47:56.429 +00:00 [INF] - Updated reported properties for Room-aaaabbbb/ModuleLNM
<6> 2025-03-30 16:48:02.285 +00:00 [INF] - Updated reported properties for Room-aaaabbbb/ModuleBMS
<6> 2025-03-30 16:48:02.978 +00:00 [INF] - Updated reported properties for Room-aaaabbbb/ModuleBRM
<6> 2025-03-30 16:48:10.886 +00:00 [INF] - Cleaned up 10699 messages from queue for endpoint Room-aaaabbbb/TestMod1/onEveryLoopRec and 10699 messages from message store.
<6> 2025-03-30 16:48:10.886 +00:00 [INF] - Started task to cleanup processed and stale messages for endpoint Room-aaaabbbb/TestMod6/onFiveMinutesRec
<6> 2025-03-30 16:48:10.899 +00:00 [INF] - Cleaned up 7 messages from queue for endpoint Room-aaaabbbb/TestMod6/onFiveMinutesRec and 7 messages from message store.
<6> 2025-03-30 16:48:10.900 +00:00 [INF] - Started task to cleanup processed and stale messages for endpoint Room-aaaabbbb/TestMod4/onEveryThirtySecondsRec
<6> 2025-03-30 16:48:11.288 +00:00 [INF] - Cleaned up 72 messages from queue for endpoint Room-aaaabbbb/TestMod4/onEveryThirtySecondsRec and 72 messages from message store.
<6> 2025-03-30 16:48:11.288 +00:00 [INF] - Started task to cleanup processed and stale messages for endpoint Room-aaaabbbb/ModuleRSM/UdpRfPayloadReceived
<6> 2025-03-30 16:48:11.291 +00:00 [INF] - Cleaned up 0 messages from queue for endpoint Room-aaaabbbb/ModuleRSM/UdpRfPayloadReceived and 0 messages from message store.
<6> 2025-03-30 16:48:11.298 +00:00 [INF] - Started task to cleanup processed and stale messages for endpoint Room-aaaabbbb/TestMod1/onEverySecondRec
<6> 2025-03-30 16:48:20.320 +00:00 [INF] - Cleaned up 2142 messages from queue for endpoint Room-aaaabbbb/TestMod1/onEverySecondRec and 2142 messages from message store.
<6> 2025-03-30 16:48:20.320 +00:00 [INF] - Started task to cleanup processed and stale messages for endpoint Room-aaaabbbb/TestMod2/onEverySecondRec
<6> 2025-03-30 16:48:29.678 +00:00 [INF] - Cleaned up 2141 messages from queue for endpoint Room-aaaabbbb/TestMod2/onEverySecondRec and 2141 messages from message store.
<6> 2025-03-30 16:48:29.678 +00:00 [INF] - Started task to cleanup processed and stale messages for endpoint Room-aaaabbbb/TestMod4/onEverySixtySecondsRec
<6> 2025-03-30 16:48:29.778 +00:00 [INF] - Cleaned up 36 messages from queue for endpoint Room-aaaabbbb/TestMod4/onEverySixtySecondsRec and 36 messages from message store.
<6> 2025-03-30 16:48:29.779 +00:00 [INF] - Started task to cleanup processed and stale messages for endpoint Room-aaaabbbb/ModuleBRM/udpinput
<6> 2025-03-30 16:48:29.779 +00:00 [INF] - Cleaned up 0 messages from queue for endpoint Room-aaaabbbb/ModuleBRM/udpinput and 0 messages from message store.
<6> 2025-03-30 16:48:29.780 +00:00 [INF] - Started task to cleanup processed and stale messages for endpoint Room-aaaabbbb/TestMod1/onFiveMinutesRec
<6> 2025-03-30 16:48:29.808 +00:00 [INF] - Cleaned up 7 messages from queue for endpoint Room-aaaabbbb/TestMod1/onFiveMinutesRec and 7 messages from message store.
<6> 2025-03-30 16:48:29.808 +00:00 [INF] - Started task to cleanup processed and stale messages for endpoint Room-aaaabbbb/TestMod4/onFiveMinutesRec
<6> 2025-03-30 16:48:29.875 +00:00 [INF] - Cleaned up 7 messages from queue for endpoint Room-aaaabbbb/TestMod4/onFiveMinutesRec and 7 messages from message store.
<6> 2025-03-30 16:48:29.875 +00:00 [INF] - Started task to cleanup processed and stale messages for endpoint Room-aaaabbbb/TestMod3/onFiveMinutesRec
<6> 2025-03-30 16:48:29.884 +00:00 [INF] - Cleaned up 7 messages from queue for endpoint Room-aaaabbbb/TestMod3/onFiveMinutesRec and 7 messages from message store.
<6> 2025-03-30 16:48:29.885 +00:00 [INF] - Started task to cleanup processed and stale messages for endpoint Room-aaaabbbb/TestMod2/onFiveMinutesRec
<6> 2025-03-30 16:48:29.895 +00:00 [INF] - Cleaned up 7 messages from queue for endpoint Room-aaaabbbb/TestMod2/onFiveMinutesRec and 7 messages from message store.
<6> 2025-03-30 16:48:29.895 +00:00 [INF] - Started task to cleanup processed and stale messages for endpoint Room-aaaabbbb/TestMod5/onEverySixtySecondsRec
<6> 2025-03-30 16:48:30.004 +00:00 [INF] - Cleaned up 36 messages from queue for endpoint Room-aaaabbbb/TestMod5/onEverySixtySecondsRec and 36 messages from message store.
<6> 2025-03-30 16:48:30.004 +00:00 [INF] - Started task to cleanup processed and stale messages for endpoint Room-aaaabbbb/ModuleEM/configurationUpdated
<6> 2025-03-30 16:48:30.006 +00:00 [INF] - Cleaned up 0 messages from queue for endpoint Room-aaaabbbb/ModuleEM/configurationUpdated and 0 messages from message store.
<6> 2025-03-30 16:48:30.007 +00:00 [INF] - Started task to cleanup processed and stale messages for endpoint Room-aaaabbbb/ModuleRSM/configurationUpdated
<6> 2025-03-30 16:48:30.007 +00:00 [INF] - Cleaned up 0 messages from queue for endpoint Room-aaaabbbb/ModuleRSM/configurationUpdated and 0 messages from message store.
<6> 2025-03-30 16:48:30.007 +00:00 [INF] - Started task to cleanup processed and stale messages for endpoint Room-aaaabbbb/TestMod1/onEveryThirtySecondsRec
<6> 2025-03-30 16:48:30.332 +00:00 [INF] - Cleaned up 72 messages from queue for endpoint Room-aaaabbbb/TestMod1/onEveryThirtySecondsRec and 72 messages from message store.
<6> 2025-03-30 16:48:30.334 +00:00 [INF] - Started task to cleanup processed and stale messages for endpoint Room-aaaabbbb/TestMod4/onEveryLoopRec
<6> 2025-03-30 16:49:12.724 +00:00 [INF] - Cleaned up 10685 messages from queue for endpoint Room-aaaabbbb/TestMod4/onEveryLoopRec and 10685 messages from message store.
<6> 2025-03-30 16:49:46.538 +00:00 [INF] - Entering periodic task to reauthenticate connected clients
<6> 2025-03-30 16:51:09.560 +00:00 [INF] - "Request starting HTTP/1.1 GET http://edgehub:9600/metrics - -"
<6> 2025-03-30 16:51:10.211 +00:00 [INF] - "Request finished HTTP/1.1 GET http://edgehub:9600/metrics - - - 200 - text/plain;+version=0.0.4;+charset=utf-8 650.9369ms"
<6> 2025-03-30 16:52:37.998 +00:00 [INF] - New token received on the Cbs link
<6> 2025-03-30 16:52:37.999 +00:00 [INF] - Token updated for Room-aaaabbbb/TestMod1
<6> 2025-03-30 16:52:38.316 +00:00 [INF] - New token received on the Cbs link
<6> 2025-03-30 16:52:38.316 +00:00 [INF] - Token updated for Room-aaaabbbb/TestMod1
<6> 2025-03-30 16:52:43.248 +00:00 [INF] - New token received on the Cbs link
<6> 2025-03-30 16:52:43.251 +00:00 [INF] - Token updated for Room-aaaabbbb/TestMod2
<6> 2025-03-30 16:52:50.580 +00:00 [INF] - Updated reported properties for Room-aaaabbbb/ModuleLNM
<6> 2025-03-30 16:52:56.159 +00:00 [INF] - Updated reported properties for Room-aaaabbbb/ModuleLNM
<6> 2025-03-30 16:53:01.876 +00:00 [INF] - Updated reported properties for Room-aaaabbbb/ModuleBMS
<6> 2025-03-30 16:53:02.462 +00:00 [INF] - Updated reported properties for Room-aaaabbbb/ModuleBRM
<6> 2025-03-30 16:54:46.532 +00:00 [INF] - Entering periodic task to reauthenticate connected clients
<6> 2025-03-30 16:56:11.377 +00:00 [INF] - "Request starting HTTP/1.1 GET http://edgehub:9600/metrics - -"
<6> 2025-03-30 16:56:11.942 +00:00 [INF] - "Request finished HTTP/1.1 GET http://edgehub:9600/metrics - - - 200 - text/plain;+version=0.0.4;+charset=utf-8 565.2967ms"
<6> 2025-03-30 16:57:50.574 +00:00 [INF] - Updated reported properties for Room-aaaabbbb/ModuleLNM
<6> 2025-03-30 16:57:56.120 +00:00 [INF] - Updated reported properties for Room-aaaabbbb/ModuleLNM
<6> 2025-03-30 16:58:01.762 +00:00 [INF] - Updated reported properties for Room-aaaabbbb/ModuleBMS
<6> 2025-03-30 16:58:02.360 +00:00 [INF] - Updated reported properties for Room-aaaabbbb/ModuleBRM
<6> 2025-03-30 16:59:46.533 +00:00 [INF] - Entering periodic task to reauthenticate connected clients
<6> 2025-03-30 17:01:13.142 +00:00 [INF] - "Request starting HTTP/1.1 GET http://edgehub:9600/metrics - -"
<6> 2025-03-30 17:01:13.734 +00:00 [INF] - "Request finished HTTP/1.1 GET http://edgehub:9600/metrics - - - 200 - text/plain;+version=0.0.4;+charset=utf-8 591.7453ms"
<6> 2025-03-30 17:01:55.326 +00:00 [INF] - New token received on the Cbs link
<6> 2025-03-30 17:01:55.327 +00:00 [INF] - Token updated for Room-aaaabbbb/TestMod3
<6> 2025-03-30 17:02:03.003 +00:00 [INF] - New token received on the Cbs link
<6> 2025-03-30 17:02:03.003 +00:00 [INF] - Token updated for Room-aaaabbbb/TestMod4
<6> 2025-03-30 17:02:03.244 +00:00 [INF] - New token received on the Cbs link
<6> 2025-03-30 17:02:03.245 +00:00 [INF] - Token updated for Room-aaaabbbb/TestMod4
<6> 2025-03-30 17:02:50.678 +00:00 [INF] - Updated reported properties for Room-aaaabbbb/ModuleLNM
<6> 2025-03-30 17:02:56.185 +00:00 [INF] - Updated reported properties for Room-aaaabbbb/ModuleLNM
<6> 2025-03-30 17:03:01.853 +00:00 [INF] - Updated reported properties for Room-aaaabbbb/ModuleBMS
<6> 2025-03-30 17:03:02.444 +00:00 [INF] - Updated reported properties for Room-aaaabbbb/ModuleBRM
<6> 2025-03-30 17:04:46.532 +00:00 [INF] - Entering periodic task to reauthenticate connected clients
<6> 2025-03-30 17:04:46.540 +00:00 [INF] - Error authenticating token for Room-aaaabbbb/ModuleBRM because the token is expired or could not be parsed
<6> 2025-03-30 17:04:46.541 +00:00 [INF] - Credentials for client Room-aaaabbbb/ModuleBRM are not valid.
<4> 2025-03-30 17:04:46.541 +00:00 [WRN] - Reauthenticating client Room-aaaabbbb/ModuleBRM failed, removing client connection
<6> 2025-03-30 17:04:46.541 +00:00 [INF] - Unable to re-authenticate Room-aaaabbbb/ModuleBRM, dropping client connection.
<6> 2025-03-30 17:04:46.541 +00:00 [INF] - Removing device connection for device Room-aaaabbbb/ModuleBRM with removeCloudConnection flag 'True'.
<4> 2025-03-30 17:04:46.542 +00:00 [WRN] - "Closing connection for device: Room-aaaabbbb/ModuleBRM, Microsoft.Azure.Devices.Edge.Hub.Core.EdgeHubConnectionException: Connection closed for device Room-aaaabbbb/ModuleBRM., "
<6> 2025-03-30 17:04:46.542 +00:00 [INF] - Disposing MessagingServiceClient for device Id Room-aaaabbbb/ModuleBRM because of exception - Microsoft.Azure.Devices.Edge.Hub.Core.EdgeHubConnectionException: Connection closed for device Room-aaaabbbb/ModuleBRM.
<6> 2025-03-30 17:04:46.542 +00:00 [INF] - Closing device proxy for device Id Room-aaaabbbb/ModuleBRM
<6> 2025-03-30 17:04:46.619 +00:00 [INF] - Closing receiver in cloud proxy 180082d1-c429-464a-bdbf-9942d6902d43 for Room-aaaabbbb/ModuleBRM
<6> 2025-03-30 17:04:46.624 +00:00 [INF] - Closed cloud proxy 180082d1-c429-464a-bdbf-9942d6902d43 for Room-aaaabbbb/ModuleBRM
<6> 2025-03-30 17:04:46.624 +00:00 [INF] - Device connection removed for device Room-aaaabbbb/ModuleBRM
<6> 2025-03-30 17:04:47.638 +00:00 [INF] - Updated reported properties for Room-aaaabbbb/$edgeHub
<6> 2025-03-30 17:04:47.814 +00:00 [INF] - Client Room-aaaabbbb/ModuleBRM in device scope authenticated locally.
<6> 2025-03-30 17:04:47.818 +00:00 [INF] - Successfully generated identity for clientId Room-aaaabbbb/ModuleBRM and username GrowPiaaaabbbb/Room-aaaabbbb/ModuleBRM/?api-version=2020-09-30&DeviceClientType=.NET%2F1.41.3%20%28.NET%207.0.16%3B%20Linux%206.1.21-v8%2B%20%231642%20SMP%20PREEMPT%20Mon%20Apr%20%203%2017%3A24%3A16%20BST%202023%3B%20Arm%29
<6> 2025-03-30 17:04:47.818 +00:00 [INF] - "ClientAuthenticated, Room-aaaabbbb/ModuleBRM, 4da2f729"
<6> 2025-03-30 17:04:47.843 +00:00 [INF] - New device connection for device Room-aaaabbbb/ModuleBRM
<6> 2025-03-30 17:04:47.843 +00:00 [INF] - Client Room-aaaabbbb/ModuleBRM connected to edgeHub, processing existing subscriptions.
<6> 2025-03-30 17:04:47.845 +00:00 [INF] - Bind device proxy for device Room-aaaabbbb/ModuleBRM
<6> 2025-03-30 17:04:47.845 +00:00 [INF] - Binding message channel for device Id Room-aaaabbbb/ModuleBRM
<6> 2025-03-30 17:04:47.858 +00:00 [INF] - Processing pending subscriptions for Room-aaaabbbb/ModuleBRM
<6> 2025-03-30 17:04:47.864 +00:00 [INF] - Processing subscriptions TwinResponse, Methods, ModuleMessages for client Room-aaaabbbb/ModuleBRM.
<6> 2025-03-30 17:04:47.865 +00:00 [INF] - Attempting to connect to IoT Hub for client Room-aaaabbbb/ModuleBRM via AMQP...
<6> 2025-03-30 17:04:47.867 +00:00 [INF] - Set subscriptions from session state for Room-aaaabbbb/ModuleBRM
<6> 2025-03-30 17:04:47.887 +00:00 [INF] - Processing subscriptions TwinResponse, Methods, ModuleMessages for client Room-aaaabbbb/ModuleBRM.
<6> 2025-03-30 17:04:47.888 +00:00 [INF] - Set subscriptions from session state for Room-aaaabbbb/ModuleBRM
<6> 2025-03-30 17:04:47.889 +00:00 [INF] - Processing subscriptions TwinResponse, Methods, ModuleMessages for client Room-aaaabbbb/ModuleBRM.
<6> 2025-03-30 17:04:47.898 +00:00 [INF] - Set subscriptions from session state for Room-aaaabbbb/ModuleBRM
<6> 2025-03-30 17:04:48.428 +00:00 [INF] - Cloud connection for Room-aaaabbbb/ModuleBRM is True
<6> 2025-03-30 17:04:48.431 +00:00 [INF] - Connection status for Room-aaaabbbb/ModuleBRM changed to ConnectionEstablished
<6> 2025-03-30 17:04:48.431 +00:00 [INF] - Client Room-aaaabbbb/ModuleBRM connected to cloud, processing existing subscriptions.
<6> 2025-03-30 17:04:48.431 +00:00 [INF] - Skipping Room-aaaabbbb/ModuleBRM for subscription processing, as it is currently being processed.
<6> 2025-03-30 17:04:48.436 +00:00 [INF] - Created cloud proxy for client Room-aaaabbbb/ModuleBRM via AMQP, with client operation timeout 20 seconds.
<6> 2025-03-30 17:04:48.438 +00:00 [INF] - Initialized cloud proxy 8cdea5ec-ca95-4ea8-96be-eb6f4edd72c8 for Room-aaaabbbb/ModuleBRM
<6> 2025-03-30 17:04:48.438 +00:00 [INF] - Created cloud connection for client Room-aaaabbbb/ModuleBRM
<6> 2025-03-30 17:04:48.532 +00:00 [INF] - Processing pending subscriptions for Room-aaaabbbb/ModuleBRM
<6> 2025-03-30 17:04:48.532 +00:00 [INF] - Processing pending subscriptions for Room-aaaabbbb/ModuleBRM
<6> 2025-03-30 17:04:48.533 +00:00 [INF] - Processing pending subscriptions for Room-aaaabbbb/ModuleBRM
<6> 2025-03-30 17:04:48.533 +00:00 [INF] - Processing pending subscriptions for Room-aaaabbbb/ModuleBRM
<6> 2025-03-30 17:04:48.533 +00:00 [INF] - Processing pending subscriptions for Room-aaaabbbb/ModuleBRM
<6> 2025-03-30 17:04:53.485 +00:00 [INF] - Updated reported properties for Room-aaaabbbb/$edgeHub
<6> 2025-03-30 17:06:14.853 +00:00 [INF] - "Request starting HTTP/1.1 GET http://edgehub:9600/metrics - -"
<6> 2025-03-30 17:06:15.167 +00:00 [INF] - "Request finished HTTP/1.1 GET http://edgehub:9600/metrics - - - 200 - text/plain;+version=0.0.4;+charset=utf-8 314.4187ms"
<6> 2025-03-30 17:07:39.287 +00:00 [INF] - New token received on the Cbs link
<6> 2025-03-30 17:07:39.296 +00:00 [INF] - Token updated for Room-aaaabbbb/TestMod1
<6> 2025-03-30 17:07:44.255 +00:00 [INF] - New token received on the Cbs link
<6> 2025-03-30 17:07:44.256 +00:00 [INF] - Token updated for Room-aaaabbbb/TestMod2
<6> 2025-03-30 17:07:50.538 +00:00 [INF] - Updated reported properties for Room-aaaabbbb/ModuleLNM
<6> 2025-03-30 17:07:56.079 +00:00 [INF] - Updated reported properties for Room-aaaabbbb/ModuleLNM
<6> 2025-03-30 17:08:01.645 +00:00 [INF] - Updated reported properties for Room-aaaabbbb/ModuleBMS
<6> 2025-03-30 17:08:02.251 +00:00 [INF] - Updated reported properties for Room-aaaabbbb/ModuleBRM
<6> 2025-03-30 17:09:46.529 +00:00 [INF] - Entering periodic task to reauthenticate connected clients
<6> 2025-03-30 17:09:46.536 +00:00 [INF] - Error authenticating token for Room-aaaabbbb/TestMod5 because the token is expired or could not be parsed

Additional Information

Logs are a bit of a mess because there are a dozen MQTT issues I am trying to figure a work around for, so I am having to test AMQP.
In the logs, due to limited space, I removed all the AMQP Warning messages that look like this
<4> 2025-03-30 21:08:11.153 +00:00 [WRN] - Received unknown feedback message from Room-aaaabbbb/TestMod1 with lock token 54318960-5ea7-4841-b314-f5ae530e142f and status Complete. Abandoning message.

Any module that starts with :
Module are on Azure.Devices.Client 1.41.3 and using Mqtt_Tcp_Only default ClientOptions.
TestMod are on 1.42.0
TestMod 1\2 are Amqp_Tcp_Only 30min with 50% renewal.
TestMod 3\4 are Amqp_Tcp_Only 1hr with 50% renewal
TestMod 5\6 Mqtt_Tcp_Only with 30m with 50% renewal.

The Timing is like clockwork.

<6> 2025-03-30 17:09:46.538 +00:00 [INF] - Unable to re-authenticate Room-aaaabbbb/TestMod5, dropping client connection.
<6> 2025-03-30 17:49:46.540 +00:00 [INF] - Unable to re-authenticate Room-aaaabbbb/TestMod5, dropping client connection.
<6> 2025-03-30 18:29:46.538 +00:00 [INF] - Unable to re-authenticate Room-aaaabbbb/TestMod5, dropping client connection.
<6> 2025-03-30 19:09:46.534 +00:00 [INF] - Unable to re-authenticate Room-aaaabbbb/TestMod5, dropping client connection.
<6> 2025-03-30 19:49:46.542 +00:00 [INF] - Unable to re-authenticate Room-aaaabbbb/TestMod5, dropping client connection.
<6> 2025-03-30 20:29:46.544 +00:00 [INF] - Unable to re-authenticate Room-aaaabbbb/TestMod5, dropping client connection.
<6> 2025-03-30 21:09:46.541 +00:00 [INF] - Unable to re-authenticate Room-aaaabbbb/TestMod5, dropping client connection.

[arsing]

var mqttTransportSettings = new AmqpTransportSettings( TransportType.Mqtt_Tcp_Only );

This is trying to create an AMQP transport with MQTT transport type, which based on the SDK code should throw an error. I assume you meant new MqttTransportSettings.

---

The MQTT transport doesn't support renewing a token for an active connection, only the AMQP transport does. The MQTT transport needs to disconnect and reconnect to provide the new token, so that is expected.

For the .Net SDK (and Java SDK) specifically, the renewal setting is ignored and the disconnection + reconnection happens at token lifetime + 10 minutes, which is what you see.

This is all documented at https://learn.microsoft.com/en-us/azure/iot-hub/iot-hub-troubleshoot-connectivity#mqtt-device-disconnect-behavior-with-azure-iot-sdks

[mmoles-Growlink]

Sorry, yes, that was a typo when copying stuff over here.

Thank you for the information, it's frustrating having spent so long trying to figure this issue out, all for it to be undocumented in the SDK itself.

  //
  // Summary:
  //     The time buffer before expiry when the token should be renewed, expressed as
  //     a percentage of the time to live. Acceptable values lie between 0 and 100 (including
  //     the endpoints). Eg. if set to a value of 30, the token will be renewed when it
  //     has 30% or less of its lifespan left. If unset the token will be renewed when
  //     it has 15% or less of its lifespan left.
  //
  // Remarks:
  //     This is used only for SAS token authenticated clients through either the Microsoft.Azure.Devices.Client.DeviceClient.CreateFromConnectionString(System.String,Microsoft.Azure.Devices.Client.ClientOptions)
  //     flow, the Microsoft.Azure.Devices.Client.ModuleClient.CreateFromConnectionString(System.String,Microsoft.Azure.Devices.Client.ClientOptions)
  //     flow or the Microsoft.Azure.Devices.Client.ModuleClient.CreateFromEnvironmentAsync(Microsoft.Azure.Devices.Client.ClientOptions)
  //     flow.
  public int SasTokenRenewalBuffer { get; set; }


    //
    // Summary:
    //     The suggested time to live value for tokens generated for SAS authenticated clients.
    //     The System.TimeSpan provided should be a positive value, signifying that it is
    //     not possible to generate tokens that have already expired. If unset the generated
    //     SAS tokens will be valid for 1 hour.
    //
    // Remarks:
    //     This is used only for SAS token authenticated clients through either the Microsoft.Azure.Devices.Client.DeviceClient.CreateFromConnectionString(System.String,Microsoft.Azure.Devices.Client.ClientOptions)
    //     flow, the Microsoft.Azure.Devices.Client.ModuleClient.CreateFromConnectionString(System.String,Microsoft.Azure.Devices.Client.ClientOptions)
    //     flow or the Microsoft.Azure.Devices.Client.ModuleClient.CreateFromEnvironmentAsync(Microsoft.Azure.Devices.Client.ClientOptions)
    //     flow.
    public TimeSpan SasTokenTimeToLive { get; set; }

In the documentation, you linked it says Token Renewal : 85% of lifespan, configurable. That's obviously not true for MQTT. Documentation and SDK needs to be updated to state that SasTokenRenewalBuffer is AMQP only. Also that SasTokenTimeToLive is actually X + 10 minutes.

I am confused about the the documentation and the column "Token renewal". I knew defaults were 85% and it says configurable, but nothing happens at 85% and it is not configurable. What is "token renewal" then?

In their example -

.NET device SDK with a 1200 seconds (20 minutes) token lifespan and renewal set to happen at 90% of lifespan. disconnects happen every 30 minutes

What is renewal doing? After 30 minutes the connection has to fail, close, dispose, and THEN it generates a new identity and then creates a new connection.

[arsing]

My interpretation of that table and the text around it was that the renewal setting is ignored, or at least ineffective in the sense that it produces no noticeable difference in behavior.

I'll find someone who knows what the SDK does / is meant to do.

[mmoles-Growlink]

Any updates on this?