MQTT does not auto renew SAS token.
- Dominant language
- C#
- Stars
- 1.5k
- Forks
- 473
- Avg merge
- 2d 17h
- Merged PRs (30d)
- 7
Description
## 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.
```
Contributor guide
No contributing guide indexed for this repository
Assessment
This issue has not been assessed yet.