Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

EdgeHub - TimeoutException: Message completion response not received #7203

Open
furier opened this issue Jan 22, 2024 · 5 comments
Open

EdgeHub - TimeoutException: Message completion response not received #7203

furier opened this issue Jan 22, 2024 · 5 comments
Assignees
@lfitchett
Labels
customer-reported iotedge

Comments

@furier
Copy link

furier commented Jan 22, 2024 •
edited

Expected Behavior

EdgeHub should be able to send messages to other modules without timeout exceptions

Current Behavior

EdgeHub using Microsoft.Azure.Devices.Edge.Hub.Core.Device.DeviceMessageHandler.SendMessageAsync causes TimeoutException when trying to send messages between modules.

This causes incoming messages from the cloud to device to not be received by the consumer (end) module. Usually, a reboot of the edgeHub causes the pending messages to flow to the consumer module but shortly after the same exception occurs and we end up in the same error state where messages do not flow to it's final destination.

<4> 2024-01-22 11:07:38.932 +00:00 [WRN] - Error sending messages to module <deviceid>/<moduleid>
System.TimeoutException: Message completion response not received
   at Microsoft.Azure.Devices.Edge.Hub.Core.Device.DeviceMessageHandler.SendMessageAsync(IMessage message, String input) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.Core/device/DeviceMessageHandler.cs:line 501
   at Microsoft.Azure.Devices.Edge.Hub.Core.Routing.ModuleEndpoint.ModuleMessageProcessor.ProcessAsync(ICollection`1 routingMessages, IDeviceProxy dp, CancellationToken token) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.Core/routing/ModuleEndpoint.cs:line 166

Context (Environment)

Output of iotedge check

Click here 
Configuration checks (aziot-identity-service)
---------------------------------------------
√ keyd configuration is well-formed - OK
√ certd configuration is well-formed - OK
√ tpmd configuration is well-formed - OK
√ identityd configuration is well-formed - OK
√ daemon configurations up-to-date with config.toml - OK
√ identityd config toml file specifies a valid hostname - OK
‼ aziot-identity-service package is up-to-date - Warning
    Installed aziot-identity-service package has version 1.4.6 but 1.4.7 is the latest stable version available.
    Please see https://aka.ms/aziot-update-runtime for update instructions.
√ host time is close to reference time - OK
√ preloaded certificates are valid - OK
√ keyd is running - OK
√ certd is running - OK
√ identityd is running - OK
√ read all preloaded certificates from the Certificates Service - OK
√ read all preloaded key pairs from the Keys Service - OK
√ check all EST server URLs utilize HTTPS - OK
√ ensure all preloaded certificates match preloaded private keys with the same ID - OK

Connectivity checks (aziot-identity-service)
--------------------------------------------
‼ host can connect to and perform TLS handshake with iothub AMQP port - Warning
    Could not retrieve iothub_hostname from provisioning file.
    Please specify the backing IoT Hub name using --iothub-hostname switch if you have that information.
    Since no hostname is provided, all hub connectivity tests will be skipped.
‼ host can connect to and perform TLS handshake with iothub HTTPS / WebSockets port - Warning
    Could not retrieve iothub_hostname from provisioning file.
    Please specify the backing IoT Hub name using --iothub-hostname switch if you have that information.
    Since no hostname is provided, all hub connectivity tests will be skipped.
‼ host can connect to and perform TLS handshake with iothub MQTT port - Warning
    Could not retrieve iothub_hostname from provisioning file.
    Please specify the backing IoT Hub name using --iothub-hostname switch if you have that information.
    Since no hostname is provided, all hub connectivity tests will be skipped.
√ host can connect to and perform TLS handshake with DPS endpoint - OK

Configuration checks
--------------------
√ aziot-edged configuration is well-formed - OK
√ configuration up-to-date with config.toml - OK
√ container engine is installed and functional - OK
√ configuration has correct URIs for daemon mgmt endpoint - OK
‼ aziot-edge package is up-to-date - Warning
    Installed IoT Edge daemon has version 1.4.20 but 1.4.27 is the latest stable version available.
    Please see https://aka.ms/iotedge-update-runtime for update instructions.
√ container time is close to host time - OK
√ DNS server - OK
√ production readiness: logs policy - OK
√ production readiness: Edge Agent's storage directory is persisted on the host filesystem - OK
√ production readiness: Edge Hub's storage directory is persisted on the host filesystem - OK
√ proxy settings are consistent in aziot-edged, aziot-identityd, moby daemon and config.toml - OK

Connectivity checks
-------------------
26 check(s) succeeded.
5 check(s) raised warnings. Re-run with --verbose for more details.
7 check(s) were skipped due to errors from other checks. Re-run with --verbose for more details.

Device Information

  • Host OS: Windows 11
  • Architecture: amd64
  • Container OS: Windows containers

Runtime Versions

  • aziot-edged: 1.4.20
  • Edge Agent: mcr.microsoft.com/azureiotedge-agent:1.4
  • Edge Hub: mcr.microsoft.com/azureiotedge-hub:1.4
  • Docker/Moby: 20.10.25

When trying to execute the command docker -H npipe:////./pipe/iotedge_moby_engine version it outputs protocol not available

Logs

aziot-edged logs 

Jan 22 11:08:06 MY-EFLOW aziot-edged[1341]: 2024-01-22T11:08:06Z [INFO] - <-- GET /modules?api-version=2022-08-03 {"accept": "application/json", "host": "mgmt.sock:80", "connection": "close"}
Jan 22 11:08:06 MY-EFLOW aziot-edged[1341]: 2024-01-22T11:08:06Z [INFO] - --> 200 {"content-type": "application/json"}
Jan 22 11:08:07 MY-EFLOW aziot-edged[1341]: 2024-01-22T11:08:07Z [INFO] - Error while serving HTTP connection: connection closed before message completed
Jan 22 11:08:10 MY-EFLOW aziot-edged[1341]: 2024-01-22T11:08:10Z [INFO] - Watchdog checking Edge runtime status
Jan 22 11:08:10 MY-EFLOW aziot-edged[1341]: 2024-01-22T11:08:10Z [INFO] - Edge runtime is running
Jan 22 11:08:11 MY-EFLOW aziot-edged[1341]: 2024-01-22T11:08:11Z [INFO] - <-- GET /modules?api-version=2022-08-03 {"accept": "application/json", "host": "mgmt.sock:80", "connection": "close"}
Jan 22 11:08:11 MY-EFLOW aziot-edged[1341]: 2024-01-22T11:08:11Z [INFO] - --> 200 {"content-type": "application/json"}
Jan 22 11:08:12 MY-EFLOW aziot-edged[1341]: 2024-01-22T11:08:12Z [INFO] - <-- GET /modules/?api-version=2018-06-28 {"host": "unix:///var/run/iotedge/mgmt.sock", "connection": "Close"}
Jan 22 11:08:12 MY-EFLOW aziot-edged[1341]: 2024-01-22T11:08:12Z [INFO] - --> 200 {"content-type": "application/json"}
Jan 22 11:08:16 MY-EFLOW aziot-edged[1341]: 2024-01-22T11:08:16Z [INFO] - <-- GET /modules?api-version=2022-08-03 {"accept": "application/json", "host": "mgmt.sock:80", "connection": "close"}
Jan 22 11:08:16 MY-EFLOW aziot-edged[1341]: 2024-01-22T11:08:16Z [INFO] - --> 200 {"content-type": "application/json"}
Jan 22 11:09:10 MY-EFLOW aziot-edged[1341]: 2024-01-22T11:09:10Z [INFO] - Watchdog checking Edge runtime status
Jan 22 11:09:10 MY-EFLOW aziot-edged[1341]: 2024-01-22T11:09:10Z [INFO] - Edge runtime is running
Jan 22 11:09:11 MY-EFLOW aziot-edged[1341]: 2024-01-22T11:09:11Z [INFO] - <-- GET /modules?api-version=2022-08-03 {"accept": "application/json", "host": "mgmt.sock:80", "connection": "close"}
Jan 22 11:09:11 MY-EFLOW aziot-edged[1341]: 2024-01-22T11:09:11Z [INFO] - --> 200 {"content-type": "application/json"}
Jan 22 11:09:16 MY-EFLOW aziot-edged[1341]: 2024-01-22T11:09:16Z [INFO] - <-- GET /modules?api-version=2022-08-03 {"accept": "application/json", "host": "mgmt.sock:80", "connection": "close"}
Jan 22 11:09:16 MY-EFLOW aziot-edged[1341]: 2024-01-22T11:09:16Z [INFO] - --> 200 {"content-type": "application/json"}
edge-agent logs 

<6> 2024-01-22 10:20:06.819 +00:00 [INF] - Obtained Edge agent twin from IoTHub with desired properties version 67 and reported properties version 207.
<6> 2024-01-22 10:22:07.190 +00:00 [INF] - Obtained Edge agent twin from IoTHub with desired properties version 67 and reported properties version 207.
<6> 2024-01-22 10:23:12.016 +00:00 [INF] - Starting compaction of stores
<6> 2024-01-22 10:23:12.016 +00:00 [INF] - Starting compaction of store deploymentConfig
<6> 2024-01-22 10:23:12.016 +00:00 [INF] - Starting compaction of store moduleState
<6> 2024-01-22 10:23:12.016 +00:00 [INF] - Starting compaction of store default
<6> 2024-01-22 10:23:12.016 +00:00 [INF] - Starting compaction of store Metrics
<6> 2024-01-22 10:23:16.197 +00:00 [INF] - Starting periodic operation Metrics Scrape...
<6> 2024-01-22 10:23:16.197 +00:00 [INF] - Scraping Metrics
<6> 2024-01-22 10:23:16.197 +00:00 [INF] - Scraping endpoint http://edgeHub:9600/metrics
<6> 2024-01-22 10:23:16.199 +00:00 [INF] - Scraping endpoint http://edgeAgent:9600/metrics
<6> 2024-01-22 10:23:16.201 +00:00 [INF] - Storing Metrics
<6> 2024-01-22 10:23:16.204 +00:00 [INF] - Scraped and Stored Metrics
<6> 2024-01-22 10:23:16.204 +00:00 [INF] - Successfully completed periodic operation Metrics Scrape
<6> 2024-01-22 10:24:07.619 +00:00 [INF] - Obtained Edge agent twin from IoTHub with desired properties version 67 and reported properties version 207.
<6> 2024-01-22 10:24:23.639 +00:00 [INF] - Starting periodic operation refresh twin config...
<6> 2024-01-22 10:24:23.665 +00:00 [INF] - Obtained Edge agent twin from IoTHub with desired properties version 67 and reported properties version 207.
<6> 2024-01-22 10:24:23.665 +00:00 [INF] - Successfully completed periodic operation refresh twin config
<6> 2024-01-22 10:26:50.303 +00:00 [INF] - Obtained Edge agent twin from IoTHub with desired properties version 67 and reported properties version 207.
<6> 2024-01-22 10:28:50.694 +00:00 [INF] - Obtained Edge agent twin from IoTHub with desired properties version 67 and reported properties version 207.
<6> 2024-01-22 10:30:51.389 +00:00 [INF] - Obtained Edge agent twin from IoTHub with desired properties version 67 and reported properties version 207.
edge-hub logs 

Error grabbing logs: error unmarshalling log entry (size=14858): proto: LogEntry: illegal tag 0 (wire type 6)
iotedge logs edgeHub --tail 500 

<6> 2024-01-22 10:07:58.629 +00:00 [INF] - Cleaned up 6 messages from queue for endpoint iothub and 6 messages from message store.
<6> 2024-01-22 10:07:58.629 +00:00 [INF] - Started task to cleanup processed and stale messages for endpoint E5C856BC-0391-47BF-B5C8-5471AE025FEE/moduleClientBridge/C2D
<6> 2024-01-22 10:07:58.629 +00:00 [INF] - Cleaned up 0 messages from queue for endpoint E5C856BC-0391-47BF-B5C8-5471AE025FEE/moduleClientBridge/C2D and 0 messages from message store.
<6> 2024-01-22 10:07:58.629 +00:00 [INF] - Started task to cleanup processed and stale messages for endpoint E5C856BC-0391-47BF-B5C8-5471AE025FEE/healthReporter/C2D
<6> 2024-01-22 10:07:58.629 +00:00 [INF] - Cleaned up 8 messages from queue for endpoint E5C856BC-0391-47BF-B5C8-5471AE025FEE/healthReporter/C2D and 8 messages from message store.
<6> 2024-01-22 10:07:58.629 +00:00 [INF] - Started task to cleanup processed and stale messages for endpoint iothub_Pri0
<6> 2024-01-22 10:07:58.629 +00:00 [INF] - Cleaned up 0 messages from queue for endpoint iothub_Pri0 and 0 messages from message store.
<6> 2024-01-22 10:07:58.841 +00:00 [INF] - Entering periodic task to reauthenticate connected clients
<4> 2024-01-22 10:08:47.264 +00:00 [WRN] - Did not receive ack for message 9c06b90f-40b9-4583-b1a1-cb711e7c183e from device/module E5C856BC-0391-47BF-B5C8-5471AE025FEE/moduleClientBridge
<4> 2024-01-22 10:08:47.264 +00:00 [WRN] - Error sending messages to module E5C856BC-0391-47BF-B5C8-5471AE025FEE/moduleClientBridge
System.TimeoutException: Message completion response not received
   at Microsoft.Azure.Devices.Edge.Hub.Core.Device.DeviceMessageHandler.SendMessageAsync(IMessage message, String input) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.Core/device/DeviceMessageHandler.cs:line 501
   at Microsoft.Azure.Devices.Edge.Hub.Core.Routing.ModuleEndpoint.ModuleMessageProcessor.ProcessAsync(ICollection`1 routingMessages, IDeviceProxy dp, CancellationToken token) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.Core/routing/ModuleEndpoint.cs:line 166
<4> 2024-01-22 10:10:17.263 +00:00 [WRN] - Did not receive ack for message d225c157-9be3-4e90-9683-e2fb1b6b046a from device/module E5C856BC-0391-47BF-B5C8-5471AE025FEE/moduleClientBridge
<4> 2024-01-22 10:10:17.263 +00:00 [WRN] - Error sending messages to module E5C856BC-0391-47BF-B5C8-5471AE025FEE/moduleClientBridge
System.TimeoutException: Message completion response not received
   at Microsoft.Azure.Devices.Edge.Hub.Core.Device.DeviceMessageHandler.SendMessageAsync(IMessage message, String input) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.Core/device/DeviceMessageHandler.cs:line 501
   at Microsoft.Azure.Devices.Edge.Hub.Core.Routing.ModuleEndpoint.ModuleMessageProcessor.ProcessAsync(ICollection`1 routingMessages, IDeviceProxy dp, CancellationToken token) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.Core/routing/ModuleEndpoint.cs:line 166
<6> 2024-01-22 10:12:58.835 +00:00 [INF] - Entering periodic task to reauthenticate connected clients
<4> 2024-01-22 10:13:17.272 +00:00 [WRN] - Did not receive ack for message 49f01195-9e36-4151-ac4c-a7eadb96b037 from device/module E5C856BC-0391-47BF-B5C8-5471AE025FEE/moduleClientBridge
<4> 2024-01-22 10:13:17.272 +00:00 [WRN] - Error sending messages to module E5C856BC-0391-47BF-B5C8-5471AE025FEE/moduleClientBridge
System.TimeoutException: Message completion response not received
   at Microsoft.Azure.Devices.Edge.Hub.Core.Device.DeviceMessageHandler.SendMessageAsync(IMessage message, String input) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.Core/device/DeviceMessageHandler.cs:line 501
   at Microsoft.Azure.Devices.Edge.Hub.Core.Routing.ModuleEndpoint.ModuleMessageProcessor.ProcessAsync(ICollection`1 routingMessages, IDeviceProxy dp, CancellationToken token) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.Core/routing/ModuleEndpoint.cs:line 166
<4> 2024-01-22 10:16:17.276 +00:00 [WRN] - Did not receive ack for message ad9d7934-57e9-4cf3-9b19-e22345029fb8 from device/module E5C856BC-0391-47BF-B5C8-5471AE025FEE/moduleClientBridge
<4> 2024-01-22 10:16:17.276 +00:00 [WRN] - Error sending messages to module E5C856BC-0391-47BF-B5C8-5471AE025FEE/moduleClientBridge
System.TimeoutException: Message completion response not received
   at Microsoft.Azure.Devices.Edge.Hub.Core.Device.DeviceMessageHandler.SendMessageAsync(IMessage message, String input) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.Core/device/DeviceMessageHandler.cs:line 501
   at Microsoft.Azure.Devices.Edge.Hub.Core.Routing.ModuleEndpoint.ModuleMessageProcessor.ProcessAsync(ICollection`1 routingMessages, IDeviceProxy dp, CancellationToken token) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.Core/routing/ModuleEndpoint.cs:line 166
<6> 2024-01-22 10:17:58.836 +00:00 [INF] - Entering periodic task to reauthenticate connected clients
<4> 2024-01-22 10:19:17.280 +00:00 [WRN] - Did not receive ack for message a801b19e-c3d0-4d39-8aa9-8ad6fa90dbca from device/module E5C856BC-0391-47BF-B5C8-5471AE025FEE/moduleClientBridge
<4> 2024-01-22 10:19:17.280 +00:00 [WRN] - Error sending messages to module E5C856BC-0391-47BF-B5C8-5471AE025FEE/moduleClientBridge
System.TimeoutException: Message completion response not received
   at Microsoft.Azure.Devices.Edge.Hub.Core.Device.DeviceMessageHandler.SendMessageAsync(IMessage message, String input) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.Core/device/DeviceMessageHandler.cs:line 501
   at Microsoft.Azure.Devices.Edge.Hub.Core.Routing.ModuleEndpoint.ModuleMessageProcessor.ProcessAsync(ICollection`1 routingMessages, IDeviceProxy dp, CancellationToken token) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.Core/routing/ModuleEndpoint.cs:line 166
<6> 2024-01-22 10:19:23.323 +00:00 [INF] - Exiting connected state
<6> 2024-01-22 10:19:23.323 +00:00 [INF] - Entering unreachable state
<6> 2024-01-22 10:19:23.580 +00:00 [INF] - Entering connected state
<4> 2024-01-22 10:20:47.282 +00:00 [WRN] - Did not receive ack for message 820898c3-39d8-4318-970a-72a2ac4a3607 from device/module E5C856BC-0391-47BF-B5C8-5471AE025FEE/moduleClientBridge
<4> 2024-01-22 10:20:47.282 +00:00 [WRN] - Error sending messages to module E5C856BC-0391-47BF-B5C8-5471AE025FEE/moduleClientBridge
System.TimeoutException: Message completion response not received
   at Microsoft.Azure.Devices.Edge.Hub.Core.Device.DeviceMessageHandler.SendMessageAsync(IMessage message, String input) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.Core/device/DeviceMessageHandler.cs:line 501
   at Microsoft.Azure.Devices.Edge.Hub.Core.Routing.ModuleEndpoint.ModuleMessageProcessor.ProcessAsync(ICollection`1 routingMessages, IDeviceProxy dp, CancellationToken token) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.Core/routing/ModuleEndpoint.cs:line 166
<6> 2024-01-22 10:22:58.837 +00:00 [INF] - Entering periodic task to reauthenticate connected clients
<6> 2024-01-22 10:23:16.198 +00:00 [INF] - "Request starting HTTP/1.1 GET http://172.18.0.6:9600/metrics - -"
<6> 2024-01-22 10:23:16.199 +00:00 [INF] - "Request finished HTTP/1.1 GET http://172.18.0.6:9600/metrics - - - 200 - text/plain;+version=0.0.4;+charset=utf-8 0.2208ms"
<4> 2024-01-22 10:23:47.283 +00:00 [WRN] - Did not receive ack for message d60605e0-6bda-4dd5-a2bd-f66dc355cc54 from device/module E5C856BC-0391-47BF-B5C8-5471AE025FEE/moduleClientBridge
<4> 2024-01-22 10:23:47.283 +00:00 [WRN] - Error sending messages to module E5C856BC-0391-47BF-B5C8-5471AE025FEE/moduleClientBridge
System.TimeoutException: Message completion response not received
   at Microsoft.Azure.Devices.Edge.Hub.Core.Device.DeviceMessageHandler.SendMessageAsync(IMessage message, String input) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.Core/device/DeviceMessageHandler.cs:line 501
   at Microsoft.Azure.Devices.Edge.Hub.Core.Routing.ModuleEndpoint.ModuleMessageProcessor.ProcessAsync(ICollection`1 routingMessages, IDeviceProxy dp, CancellationToken token) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.Core/routing/ModuleEndpoint.cs:line 166
<6> 2024-01-22 10:24:08.458 +00:00 [INF] - Starting periodic operation Get EdgeHub config...
<6> 2024-01-22 10:24:08.555 +00:00 [INF] - Obtained edge hub config from module twin
<6> 2024-01-22 10:24:08.704 +00:00 [INF] - Updated reported properties for E5C856BC-0391-47BF-B5C8-5471AE025FEE/$edgeHub
<4> 2024-01-22 10:24:38.555 +00:00 [WRN] - Did not receive ack for message 2a9a715e-afb8-4329-a47d-16c8ca99da79 from device/module E5C856BC-0391-47BF-B5C8-5471AE025FEE/moduleClientBridge
<4> 2024-01-22 10:24:38.555 +00:00 [WRN] - Error sending messages to module E5C856BC-0391-47BF-B5C8-5471AE025FEE/moduleClientBridge
System.TimeoutException: Message completion response not received
   at Microsoft.Azure.Devices.Edge.Hub.Core.Device.DeviceMessageHandler.SendMessageAsync(IMessage message, String input) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.Core/device/DeviceMessageHandler.cs:line 501
   at Microsoft.Azure.Devices.Edge.Hub.Core.Routing.ModuleEndpoint.ModuleMessageProcessor.ProcessAsync(ICollection`1 routingMessages, IDeviceProxy dp, CancellationToken token) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.Core/routing/ModuleEndpoint.cs:line 166
<6> 2024-01-22 10:24:38.555 +00:00 [INF] - Set the following 4 route(s) in edge hub
<6> 2024-01-22 10:24:38.555 +00:00 [INF] - bridgeMachineData2upstream: FROM /messages/modules/moduleClientBridge/outputs/package into $upstream
<6> 2024-01-22 10:24:38.555 +00:00 [INF] - bridgeNotificationTask2upstream: FROM /messages/modules/moduleClientBridge/outputs/notificationTask INTO $upstream
<6> 2024-01-22 10:24:38.555 +00:00 [INF] - messageFromCloud2downstream: FROM /messages/modules/cloudToDeviceMessageReceiver/outputs/C2D INTO BrokeredEndpoint("/modules/moduleClientBridge/inputs/C2D")
<6> 2024-01-22 10:24:38.555 +00:00 [INF] - messageFromCloud2healthReporter: FROM /messages/modules/cloudToDeviceMessageReceiver/outputs/healthReporter INTO BrokeredEndpoint("/modules/healthReporter/inputs/C2D")
<6> 2024-01-22 10:24:38.555 +00:00 [INF] - Updated message store TTL to 259200 seconds
<6> 2024-01-22 10:24:38.555 +00:00 [INF] - Updated the edge hub store and forward configuration
<6> 2024-01-22 10:24:38.555 +00:00 [INF] - Successfully completed periodic operation Get EdgeHub config
<4> 2024-01-22 10:25:09.565 +00:00 [WRN] - Did not receive ack for message 6289441b-85b4-43ae-9fc5-162344048cc6 from device/module E5C856BC-0391-47BF-B5C8-5471AE025FEE/moduleClientBridge
<4> 2024-01-22 10:25:09.565 +00:00 [WRN] - Error sending messages to module E5C856BC-0391-47BF-B5C8-5471AE025FEE/moduleClientBridge
System.TimeoutException: Message completion response not received
   at Microsoft.Azure.Devices.Edge.Hub.Core.Device.DeviceMessageHandler.SendMessageAsync(IMessage message, String input) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.Core/device/DeviceMessageHandler.cs:line 501
   at Microsoft.Azure.Devices.Edge.Hub.Core.Routing.ModuleEndpoint.ModuleMessageProcessor.ProcessAsync(ICollection`1 routingMessages, IDeviceProxy dp, CancellationToken token) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.Core/routing/ModuleEndpoint.cs:line 166
<4> 2024-01-22 10:25:41.586 +00:00 [WRN] - Did not receive ack for message ad35087d-577f-47ac-b8e9-c26394fe5ded from device/module E5C856BC-0391-47BF-B5C8-5471AE025FEE/moduleClientBridge
<4> 2024-01-22 10:25:41.587 +00:00 [WRN] - Error sending messages to module E5C856BC-0391-47BF-B5C8-5471AE025FEE/moduleClientBridge
System.TimeoutException: Message completion response not received
   at Microsoft.Azure.Devices.Edge.Hub.Core.Device.DeviceMessageHandler.SendMessageAsync(IMessage message, String input) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.Core/device/DeviceMessageHandler.cs:line 501
   at Microsoft.Azure.Devices.Edge.Hub.Core.Routing.ModuleEndpoint.ModuleMessageProcessor.ProcessAsync(ICollection`1 routingMessages, IDeviceProxy dp, CancellationToken token) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.Core/routing/ModuleEndpoint.cs:line 166
<6> 2024-01-22 10:26:42.265 +00:00 [INF] - "Request starting HTTP/1.1 GET http://edgehub:9600/metrics - -"
<6> 2024-01-22 10:26:42.265 +00:00 [INF] - "Request finished HTTP/1.1 GET http://edgehub:9600/metrics - - - 200 - text/plain;+version=0.0.4;+charset=utf-8 0.2397ms"
<4> 2024-01-22 10:26:52.041 +00:00 [WRN] - Did not receive ack for message b173ebbc-4f5f-43ea-badd-87b55e368bf7 from device/module E5C856BC-0391-47BF-B5C8-5471AE025FEE/moduleClientBridge
<4> 2024-01-22 10:26:52.042 +00:00 [WRN] - Error sending messages to module E5C856BC-0391-47BF-B5C8-5471AE025FEE/moduleClientBridge
System.TimeoutException: Message completion response not received
   at Microsoft.Azure.Devices.Edge.Hub.Core.Device.DeviceMessageHandler.SendMessageAsync(IMessage message, String input) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.Core/device/DeviceMessageHandler.cs:line 501
   at Microsoft.Azure.Devices.Edge.Hub.Core.Routing.ModuleEndpoint.ModuleMessageProcessor.ProcessAsync(ICollection`1 routingMessages, IDeviceProxy dp, CancellationToken token) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.Core/routing/ModuleEndpoint.cs:line 166
<4> 2024-01-22 10:27:37.351 +00:00 [WRN] - Did not receive ack for message b6434a9d-8375-4543-98b5-b57989e32552 from device/module E5C856BC-0391-47BF-B5C8-5471AE025FEE/moduleClientBridge
<4> 2024-01-22 10:27:37.352 +00:00 [WRN] - Error sending messages to module E5C856BC-0391-47BF-B5C8-5471AE025FEE/moduleClientBridge
System.TimeoutException: Message completion response not received
   at Microsoft.Azure.Devices.Edge.Hub.Core.Device.DeviceMessageHandler.SendMessageAsync(IMessage message, String input) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.Core/device/DeviceMessageHandler.cs:line 501
   at Microsoft.Azure.Devices.Edge.Hub.Core.Routing.ModuleEndpoint.ModuleMessageProcessor.ProcessAsync(ICollection`1 routingMessages, IDeviceProxy dp, CancellationToken token) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.Core/routing/ModuleEndpoint.cs:line 166
<6> 2024-01-22 10:29:28.705 +00:00 [INF] - Exiting connected state
<6> 2024-01-22 10:29:28.705 +00:00 [INF] - Entering unreachable state
<6> 2024-01-22 10:29:29.054 +00:00 [INF] - Entering connected state
<4> 2024-01-22 10:30:08.929 +00:00 [WRN] - Did not receive ack for message 0e0d5886-9eac-4469-b3fb-8d2167878bbb from device/module E5C856BC-0391-47BF-B5C8-5471AE025FEE/moduleClientBridge
<4> 2024-01-22 10:30:08.929 +00:00 [WRN] - Error sending messages to module E5C856BC-0391-47BF-B5C8-5471AE025FEE/moduleClientBridge
System.TimeoutException: Message completion response not received
   at Microsoft.Azure.Devices.Edge.Hub.Core.Device.DeviceMessageHandler.SendMessageAsync(IMessage message, String input) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.Core/device/DeviceMessageHandler.cs:line 501
   at Microsoft.Azure.Devices.Edge.Hub.Core.Routing.ModuleEndpoint.ModuleMessageProcessor.ProcessAsync(ICollection`1 routingMessages, IDeviceProxy dp, CancellationToken token) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.Core/routing/ModuleEndpoint.cs:line 166
<6> 2024-01-22 10:36:42.989 +00:00 [INF] - "Request starting HTTP/1.1 GET http://edgehub:9600/metrics - -"
<6> 2024-01-22 10:36:42.990 +00:00 [INF] - "Request finished HTTP/1.1 GET http://edgehub:9600/metrics - - - 200 - text/plain;+version=0.0.4;+charset=utf-8 0.2237ms"
<4> 2024-01-22 10:37:38.934 +00:00 [WRN] - Did not receive ack for message 3515e5f4-f090-4e3e-97e2-ad478c9c19aa from device/module E5C856BC-0391-47BF-B5C8-5471AE025FEE/moduleClientBridge
<4> 2024-01-22 10:37:38.935 +00:00 [WRN] - Error sending messages to module E5C856BC-0391-47BF-B5C8-5471AE025FEE/moduleClientBridge
System.TimeoutException: Message completion response not received
   at Microsoft.Azure.Devices.Edge.Hub.Core.Device.DeviceMessageHandler.SendMessageAsync(IMessage message, String input) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.Core/device/DeviceMessageHandler.cs:line 501
   at Microsoft.Azure.Devices.Edge.Hub.Core.Routing.ModuleEndpoint.ModuleMessageProcessor.ProcessAsync(ICollection`1 routingMessages, IDeviceProxy dp, CancellationToken token) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.Core/routing/ModuleEndpoint.cs:line 166
<6> 2024-01-22 10:37:58.627 +00:00 [INF] - Started task to cleanup processed and stale messages for endpoint iothub
<6> 2024-01-22 10:37:58.632 +00:00 [INF] - Cleaned up 6 messages from queue for endpoint iothub and 6 messages from message store.
<6> 2024-01-22 10:37:58.632 +00:00 [INF] - Started task to cleanup processed and stale messages for endpoint E5C856BC-0391-47BF-B5C8-5471AE025FEE/moduleClientBridge/C2D
<6> 2024-01-22 10:37:58.633 +00:00 [INF] - Cleaned up 0 messages from queue for endpoint E5C856BC-0391-47BF-B5C8-5471AE025FEE/moduleClientBridge/C2D and 0 messages from message store.
<6> 2024-01-22 10:37:58.633 +00:00 [INF] - Started task to cleanup processed and stale messages for endpoint E5C856BC-0391-47BF-B5C8-5471AE025FEE/healthReporter/C2D
<6> 2024-01-22 10:37:58.633 +00:00 [INF] - Cleaned up 6 messages from queue for endpoint E5C856BC-0391-47BF-B5C8-5471AE025FEE/healthReporter/C2D and 6 messages from message store.
<6> 2024-01-22 10:37:58.633 +00:00 [INF] - Started task to cleanup processed and stale messages for endpoint iothub_Pri0
<6> 2024-01-22 10:37:58.634 +00:00 [INF] - Cleaned up 0 messages from queue for endpoint iothub_Pri0 and 0 messages from message store.
<6> 2024-01-22 10:37:58.835 +00:00 [INF] - Entering periodic task to reauthenticate connected clients
<4> 2024-01-22 10:39:08.931 +00:00 [WRN] - Did not receive ack for message fb709d60-8fc1-409c-aa80-86d0a6069b46 from device/module E5C856BC-0391-47BF-B5C8-5471AE025FEE/moduleClientBridge
<4> 2024-01-22 10:39:08.931 +00:00 [WRN] - Error sending messages to module E5C856BC-0391-47BF-B5C8-5471AE025FEE/moduleClientBridge
System.TimeoutException: Message completion response not received
   at Microsoft.Azure.Devices.Edge.Hub.Core.Device.DeviceMessageHandler.SendMessageAsync(IMessage message, String input) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.Core/device/DeviceMessageHandler.cs:line 501
   at Microsoft.Azure.Devices.Edge.Hub.Core.Routing.ModuleEndpoint.ModuleMessageProcessor.ProcessAsync(ICollection`1 routingMessages, IDeviceProxy dp, CancellationToken token) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.Core/routing/ModuleEndpoint.cs:line 166
<4> 2024-01-22 10:40:38.934 +00:00 [WRN] - Did not receive ack for message 71963b60-4edd-4636-a2e0-92b1c5a6a25e from device/module E5C856BC-0391-47BF-B5C8-5471AE025FEE/moduleClientBridge
<4> 2024-01-22 10:40:38.935 +00:00 [WRN] - Error sending messages to module E5C856BC-0391-47BF-B5C8-5471AE025FEE/moduleClientBridge
System.TimeoutException: Message completion response not received
   at Microsoft.Azure.Devices.Edge.Hub.Core.Device.DeviceMessageHandler.SendMessageAsync(IMessage message, String input) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.Core/device/DeviceMessageHandler.cs:line 501
   at Microsoft.Azure.Devices.Edge.Hub.Core.Routing.ModuleEndpoint.ModuleMessageProcessor.ProcessAsync(ICollection`1 routingMessages, IDeviceProxy dp, CancellationToken token) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.Core/routing/ModuleEndpoint.cs:line 166
<6> 2024-01-22 10:41:43.332 +00:00 [INF] - "Request starting HTTP/1.1 GET http://edgehub:9600/metrics - -"
<6> 2024-01-22 10:41:43.333 +00:00 [INF] - "Request finished HTTP/1.1 GET http://edgehub:9600/metrics - - - 200 - text/plain;+version=0.0.4;+charset=utf-8 0.2475ms"
<4> 2024-01-22 10:42:08.935 +00:00 [WRN] - Did not receive ack for message 170aeaa8-c8f9-4334-884a-6753d0291c0a from device/module E5C856BC-0391-47BF-B5C8-5471AE025FEE/moduleClientBridge
<4> 2024-01-22 10:42:08.935 +00:00 [WRN] - Error sending messages to module E5C856BC-0391-47BF-B5C8-5471AE025FEE/moduleClientBridge
System.TimeoutException: Message completion response not received
   at Microsoft.Azure.Devices.Edge.Hub.Core.Device.DeviceMessageHandler.SendMessageAsync(IMessage message, String input) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.Core/device/DeviceMessageHandler.cs:line 501
   at Microsoft.Azure.Devices.Edge.Hub.Core.Routing.ModuleEndpoint.ModuleMessageProcessor.ProcessAsync(ICollection`1 routingMessages, IDeviceProxy dp, CancellationToken token) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.Core/routing/ModuleEndpoint.cs:line 166
<6> 2024-01-22 10:42:58.835 +00:00 [INF] - Entering periodic task to reauthenticate connected clients
<6> 2024-01-22 10:43:19.000 +00:00 [INF] - New token received on the Cbs link
<6> 2024-01-22 10:43:19.000 +00:00 [INF] - Token updated for E5C856BC-0391-47BF-B5C8-5471AE025FEE/cloudSyncStorage
<6> 2024-01-22 10:43:19.183 +00:00 [INF] - New token received on the Cbs link
<6> 2024-01-22 10:43:19.183 +00:00 [INF] - Token updated for E5C856BC-0391-47BF-B5C8-5471AE025FEE/cloudSyncStorage
<6> 2024-01-22 10:43:24.997 +00:00 [INF] - New token received on the Cbs link
<6> 2024-01-22 10:43:24.997 +00:00 [INF] - Token updated for E5C856BC-0391-47BF-B5C8-5471AE025FEE/IoTEdgeMetricsCollector
<6> 2024-01-22 10:43:25.112 +00:00 [INF] - New token received on the Cbs link
<6> 2024-01-22 10:43:25.112 +00:00 [INF] - Token updated for E5C856BC-0391-47BF-B5C8-5471AE025FEE/IoTEdgeMetricsCollector
<4> 2024-01-22 10:43:38.931 +00:00 [WRN] - Did not receive ack for message 97bc4042-ea66-4f6e-907d-31491690d093 from device/module E5C856BC-0391-47BF-B5C8-5471AE025FEE/moduleClientBridge
<4> 2024-01-22 10:43:38.932 +00:00 [WRN] - Error sending messages to module E5C856BC-0391-47BF-B5C8-5471AE025FEE/moduleClientBridge
System.TimeoutException: Message completion response not received
   at Microsoft.Azure.Devices.Edge.Hub.Core.Device.DeviceMessageHandler.SendMessageAsync(IMessage message, String input) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.Core/device/DeviceMessageHandler.cs:line 501
   at Microsoft.Azure.Devices.Edge.Hub.Core.Routing.ModuleEndpoint.ModuleMessageProcessor.ProcessAsync(ICollection`1 routingMessages, IDeviceProxy dp, CancellationToken token) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.Core/routing/ModuleEndpoint.cs:line 166
<6> 2024-01-22 10:43:43.996 +00:00 [INF] - New token received on the Cbs link
<6> 2024-01-22 10:43:43.996 +00:00 [INF] - Token updated for E5C856BC-0391-47BF-B5C8-5471AE025FEE/moduleClientBridge
<6> 2024-01-22 10:43:44.000 +00:00 [INF] - New token received on the Cbs link
<6> 2024-01-22 10:43:44.000 +00:00 [INF] - Token updated for E5C856BC-0391-47BF-B5C8-5471AE025FEE/moduleClientBridge
<6> 2024-01-22 10:43:44.113 +00:00 [INF] - New token received on the Cbs link
<6> 2024-01-22 10:43:44.113 +00:00 [INF] - Token updated for E5C856BC-0391-47BF-B5C8-5471AE025FEE/moduleClientBridge
<6> 2024-01-22 10:45:04.110 +00:00 [INF] - New token received on the Cbs link
<6> 2024-01-22 10:45:04.110 +00:00 [INF] - Token updated for E5C856BC-0391-47BF-B5C8-5471AE025FEE/cloudToDeviceMessageReceiver
<6> 2024-01-22 10:45:04.372 +00:00 [INF] - New token received on the Cbs link
<6> 2024-01-22 10:45:04.372 +00:00 [INF] - Token updated for E5C856BC-0391-47BF-B5C8-5471AE025FEE/healthReporter
<4> 2024-01-22 10:45:08.935 +00:00 [WRN] - Did not receive ack for message d2963699-ce6a-4f5c-b4de-2388093af7e0 from device/module E5C856BC-0391-47BF-B5C8-5471AE025FEE/moduleClientBridge
<4> 2024-01-22 10:45:08.935 +00:00 [WRN] - Error sending messages to module E5C856BC-0391-47BF-B5C8-5471AE025FEE/moduleClientBridge
System.TimeoutException: Message completion response not received
   at Microsoft.Azure.Devices.Edge.Hub.Core.Device.DeviceMessageHandler.SendMessageAsync(IMessage message, String input) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.Core/device/DeviceMessageHandler.cs:line 501
   at Microsoft.Azure.Devices.Edge.Hub.Core.Routing.ModuleEndpoint.ModuleMessageProcessor.ProcessAsync(ICollection`1 routingMessages, IDeviceProxy dp, CancellationToken token) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.Core/routing/ModuleEndpoint.cs:line 166
<4> 2024-01-22 10:46:38.933 +00:00 [WRN] - Did not receive ack for message 1b6f6a9f-6f44-4990-91dd-9a2cfcf1b796 from device/module E5C856BC-0391-47BF-B5C8-5471AE025FEE/moduleClientBridge
<4> 2024-01-22 10:46:38.933 +00:00 [WRN] - Error sending messages to module E5C856BC-0391-47BF-B5C8-5471AE025FEE/moduleClientBridge
System.TimeoutException: Message completion response not received
   at Microsoft.Azure.Devices.Edge.Hub.Core.Device.DeviceMessageHandler.SendMessageAsync(IMessage message, String input) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.Core/device/DeviceMessageHandler.cs:line 501
   at Microsoft.Azure.Devices.Edge.Hub.Core.Routing.ModuleEndpoint.ModuleMessageProcessor.ProcessAsync(ICollection`1 routingMessages, IDeviceProxy dp, CancellationToken token) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.Core/routing/ModuleEndpoint.cs:line 166
<6> 2024-01-22 10:46:43.650 +00:00 [INF] - "Request starting HTTP/1.1 GET http://edgehub:9600/metrics - -"
<6> 2024-01-22 10:46:43.650 +00:00 [INF] - "Request finished HTTP/1.1 GET http://edgehub:9600/metrics - - - 200 - text/plain;+version=0.0.4;+charset=utf-8 0.2298ms"
<6> 2024-01-22 10:47:58.835 +00:00 [INF] - Entering periodic task to reauthenticate connected clients
<4> 2024-01-22 10:48:08.932 +00:00 [WRN] - Did not receive ack for message 35d3419f-1407-4ea2-8ca2-7a70187f364e from device/module E5C856BC-0391-47BF-B5C8-5471AE025FEE/moduleClientBridge
<4> 2024-01-22 10:48:08.932 +00:00 [WRN] - Error sending messages to module E5C856BC-0391-47BF-B5C8-5471AE025FEE/moduleClientBridge
System.TimeoutException: Message completion response not received
   at Microsoft.Azure.Devices.Edge.Hub.Core.Device.DeviceMessageHandler.SendMessageAsync(IMessage message, String input) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.Core/device/DeviceMessageHandler.cs:line 501
   at Microsoft.Azure.Devices.Edge.Hub.Core.Routing.ModuleEndpoint.ModuleMessageProcessor.ProcessAsync(ICollection`1 routingMessages, IDeviceProxy dp, CancellationToken token) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.Core/routing/ModuleEndpoint.cs:line 166
<4> 2024-01-22 10:49:38.932 +00:00 [WRN] - Did not receive ack for message f6dd87a2-316b-4da5-9079-36f73b687c1e from device/module E5C856BC-0391-47BF-B5C8-5471AE025FEE/moduleClientBridge
<4> 2024-01-22 10:49:38.932 +00:00 [WRN] - Error sending messages to module E5C856BC-0391-47BF-B5C8-5471AE025FEE/moduleClientBridge
System.TimeoutException: Message completion response not received
   at Microsoft.Azure.Devices.Edge.Hub.Core.Device.DeviceMessageHandler.SendMessageAsync(IMessage message, String input) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.Core/device/DeviceMessageHandler.cs:line 501
   at Microsoft.Azure.Devices.Edge.Hub.Core.Routing.ModuleEndpoint.ModuleMessageProcessor.ProcessAsync(ICollection`1 routingMessages, IDeviceProxy dp, CancellationToken token) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.Core/routing/ModuleEndpoint.cs:line 166
<6> 2024-01-22 10:52:58.840 +00:00 [INF] - Entering periodic task to reauthenticate connected clients
<4> 2024-01-22 10:54:08.931 +00:00 [WRN] - Did not receive ack for message 7613c6bc-482c-42b1-b88b-87bf633464bb from device/module E5C856BC-0391-47BF-B5C8-5471AE025FEE/moduleClientBridge
<4> 2024-01-22 10:54:08.932 +00:00 [WRN] - Error sending messages to module E5C856BC-0391-47BF-B5C8-5471AE025FEE/moduleClientBridge
System.TimeoutException: Message completion response not received
   at Microsoft.Azure.Devices.Edge.Hub.Core.Device.DeviceMessageHandler.SendMessageAsync(IMessage message, String input) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.Core/device/DeviceMessageHandler.cs:line 501
   at Microsoft.Azure.Devices.Edge.Hub.Core.Routing.ModuleEndpoint.ModuleMessageProcessor.ProcessAsync(ICollection`1 routingMessages, IDeviceProxy dp, CancellationToken token) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.Core/routing/ModuleEndpoint.cs:line 166
<4> 2024-01-22 11:01:38.932 +00:00 [WRN] - Did not receive ack for message 8ce4f092-9e03-4b1c-a092-31f28453c67c from device/module E5C856BC-0391-47BF-B5C8-5471AE025FEE/moduleClientBridge
<4> 2024-01-22 11:01:38.932 +00:00 [WRN] - Error sending messages to module E5C856BC-0391-47BF-B5C8-5471AE025FEE/moduleClientBridge
System.TimeoutException: Message completion response not received
   at Microsoft.Azure.Devices.Edge.Hub.Core.Device.DeviceMessageHandler.SendMessageAsync(IMessage message, String input) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.Core/device/DeviceMessageHandler.cs:line 501
   at Microsoft.Azure.Devices.Edge.Hub.Core.Routing.ModuleEndpoint.ModuleMessageProcessor.ProcessAsync(ICollection`1 routingMessages, IDeviceProxy dp, CancellationToken token) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.Core/routing/ModuleEndpoint.cs:line 166
<6> 2024-01-22 11:01:45.701 +00:00 [INF] - "Request starting HTTP/1.1 GET http://edgehub:9600/metrics - -"
<6> 2024-01-22 11:01:45.702 +00:00 [INF] - "Request finished HTTP/1.1 GET http://edgehub:9600/metrics - - - 200 - text/plain;+version=0.0.4;+charset=utf-8 1.3139ms"
<6> 2024-01-22 11:02:58.837 +00:00 [INF] - Entering periodic task to reauthenticate connected clients
<4> 2024-01-22 11:03:08.933 +00:00 [WRN] - Did not receive ack for message 80043f63-1a8f-4aad-8db9-5f6ac2810ee1 from device/module E5C856BC-0391-47BF-B5C8-5471AE025FEE/moduleClientBridge
<4> 2024-01-22 11:03:08.933 +00:00 [WRN] - Error sending messages to module E5C856BC-0391-47BF-B5C8-5471AE025FEE/moduleClientBridge
System.TimeoutException: Message completion response not received
   at Microsoft.Azure.Devices.Edge.Hub.Core.Device.DeviceMessageHandler.SendMessageAsync(IMessage message, String input) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.Core/device/DeviceMessageHandler.cs:line 501
   at Microsoft.Azure.Devices.Edge.Hub.Core.Routing.ModuleEndpoint.ModuleMessageProcessor.ProcessAsync(ICollection`1 routingMessages, IDeviceProxy dp, CancellationToken token) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.Core/routing/ModuleEndpoint.cs:line 166
<4> 2024-01-22 11:04:38.934 +00:00 [WRN] - Did not receive ack for message 6673b06a-8ffa-47d1-96d9-68d833df2d3b from device/module E5C856BC-0391-47BF-B5C8-5471AE025FEE/moduleClientBridge
<4> 2024-01-22 11:04:38.934 +00:00 [WRN] - Error sending messages to module E5C856BC-0391-47BF-B5C8-5471AE025FEE/moduleClientBridge
System.TimeoutException: Message completion response not received
   at Microsoft.Azure.Devices.Edge.Hub.Core.Device.DeviceMessageHandler.SendMessageAsync(IMessage message, String input) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.Core/device/DeviceMessageHandler.cs:line 501
   at Microsoft.Azure.Devices.Edge.Hub.Core.Routing.ModuleEndpoint.ModuleMessageProcessor.ProcessAsync(ICollection`1 routingMessages, IDeviceProxy dp, CancellationToken token) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.Core/routing/ModuleEndpoint.cs:line 166
<6> 2024-01-22 11:05:11.192 +00:00 [INF] - Starting refresh of device scope identities cache
<6> 2024-01-22 11:05:11.747 +00:00 [INF] - Not changed node: E5C856BC-0391-47BF-B5C8-5471AE025FEE
<6> 2024-01-22 11:05:11.747 +00:00 [INF] - Not changed node: E5C856BC-0391-47BF-B5C8-5471AE025FEE/$edgeAgent
<6> 2024-01-22 11:05:11.747 +00:00 [INF] - Not changed node: E5C856BC-0391-47BF-B5C8-5471AE025FEE/$edgeHub
<6> 2024-01-22 11:05:11.747 +00:00 [INF] - Not changed node: E5C856BC-0391-47BF-B5C8-5471AE025FEE/cloudSyncStorage
<6> 2024-01-22 11:05:11.748 +00:00 [INF] - Not changed node: E5C856BC-0391-47BF-B5C8-5471AE025FEE/cloudToDeviceMessageReceiver
<6> 2024-01-22 11:05:11.748 +00:00 [INF] - Not changed node: E5C856BC-0391-47BF-B5C8-5471AE025FEE/moduleClientBridge
<6> 2024-01-22 11:05:11.748 +00:00 [INF] - Not changed node: E5C856BC-0391-47BF-B5C8-5471AE025FEE/IoTEdgeMetricsCollector
<6> 2024-01-22 11:05:11.748 +00:00 [INF] - Not changed node: E5C856BC-0391-47BF-B5C8-5471AE025FEE/DefenderIotMicroAgent
<6> 2024-01-22 11:05:11.748 +00:00 [INF] - Not changed node: E5C856BC-0391-47BF-B5C8-5471AE025FEE/healthReporter
<6> 2024-01-22 11:05:11.748 +00:00 [INF] - Done refreshing device scope identities cache. Waiting for 60 minutes.
<4> 2024-01-22 11:06:08.931 +00:00 [WRN] - Did not receive ack for message e6b94114-71a4-42d6-9947-00a1e4eda315 from device/module E5C856BC-0391-47BF-B5C8-5471AE025FEE/moduleClientBridge
<4> 2024-01-22 11:06:08.932 +00:00 [WRN] - Error sending messages to module E5C856BC-0391-47BF-B5C8-5471AE025FEE/moduleClientBridge
System.TimeoutException: Message completion response not received
   at Microsoft.Azure.Devices.Edge.Hub.Core.Device.DeviceMessageHandler.SendMessageAsync(IMessage message, String input) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.Core/device/DeviceMessageHandler.cs:line 501
   at Microsoft.Azure.Devices.Edge.Hub.Core.Routing.ModuleEndpoint.ModuleMessageProcessor.ProcessAsync(ICollection`1 routingMessages, IDeviceProxy dp, CancellationToken token) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.Core/routing/ModuleEndpoint.cs:line 166
<6> 2024-01-22 11:06:46.044 +00:00 [INF] - "Request starting HTTP/1.1 GET http://edgehub:9600/metrics - -"
<6> 2024-01-22 11:06:46.045 +00:00 [INF] - "Request finished HTTP/1.1 GET http://edgehub:9600/metrics - - - 200 - text/plain;+version=0.0.4;+charset=utf-8 0.2286ms"
<4> 2024-01-22 11:07:38.932 +00:00 [WRN] - Did not receive ack for message f70ede96-03d2-40a7-b72b-4a5365ba1f9e from device/module E5C856BC-0391-47BF-B5C8-5471AE025FEE/moduleClientBridge
<4> 2024-01-22 11:07:38.932 +00:00 [WRN] - Error sending messages to module E5C856BC-0391-47BF-B5C8-5471AE025FEE/moduleClientBridge
System.TimeoutException: Message completion response not received
   at Microsoft.Azure.Devices.Edge.Hub.Core.Device.DeviceMessageHandler.SendMessageAsync(IMessage message, String input) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.Core/device/DeviceMessageHandler.cs:line 501
   at Microsoft.Azure.Devices.Edge.Hub.Core.Routing.ModuleEndpoint.ModuleMessageProcessor.ProcessAsync(ICollection`1 routingMessages, IDeviceProxy dp, CancellationToken token) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.Core/routing/ModuleEndpoint.cs:line 166
<6> 2024-01-22 11:07:58.204 +00:00 [INF] - Starting compaction of stores
<6> 2024-01-22 11:07:58.204 +00:00 [INF] - Starting compaction of store iothub
<6> 2024-01-22 11:07:58.204 +00:00 [INF] - Starting compaction of store checkpoints
<6> 2024-01-22 11:07:58.204 +00:00 [INF] - Starting compaction of store E5C856BC-0391-47BF-B5C8-5471AE025FEE/moduleClientBridge/C2D
<6> 2024-01-22 11:07:58.204 +00:00 [INF] - Starting compaction of store twins
<6> 2024-01-22 11:07:58.204 +00:00 [INF] - Starting compaction of store MetadataStore
<6> 2024-01-22 11:07:58.204 +00:00 [INF] - Starting compaction of store default
<6> 2024-01-22 11:07:58.204 +00:00 [INF] - Starting compaction of store DeviceScopeCache
<6> 2024-01-22 11:07:58.204 +00:00 [INF] - Starting compaction of store EdgeTwin
<6> 2024-01-22 11:07:58.204 +00:00 [INF] - Starting compaction of store E5C856BC-0391-47BF-B5C8-5471AE025FEE/healthReporter/C2D
<6> 2024-01-22 11:07:58.204 +00:00 [INF] - Starting compaction of store iothub_Pri0
<6> 2024-01-22 11:07:58.204 +00:00 [INF] - Starting compaction of store messages
<6> 2024-01-22 11:07:58.627 +00:00 [INF] - Started task to cleanup processed and stale messages for endpoint iothub
<6> 2024-01-22 11:07:58.631 +00:00 [INF] - Cleaned up 6 messages from queue for endpoint iothub and 6 messages from message store.
<6> 2024-01-22 11:07:58.631 +00:00 [INF] - Started task to cleanup processed and stale messages for endpoint E5C856BC-0391-47BF-B5C8-5471AE025FEE/moduleClientBridge/C2D
<6> 2024-01-22 11:07:58.631 +00:00 [INF] - Cleaned up 0 messages from queue for endpoint E5C856BC-0391-47BF-B5C8-5471AE025FEE/moduleClientBridge/C2D and 0 messages from message store.
<6> 2024-01-22 11:07:58.632 +00:00 [INF] - Started task to cleanup processed and stale messages for endpoint E5C856BC-0391-47BF-B5C8-5471AE025FEE/healthReporter/C2D
<6> 2024-01-22 11:07:58.633 +00:00 [INF] - Cleaned up 6 messages from queue for endpoint E5C856BC-0391-47BF-B5C8-5471AE025FEE/healthReporter/C2D and 6 messages from message store.
<6> 2024-01-22 11:07:58.633 +00:00 [INF] - Started task to cleanup processed and stale messages for endpoint iothub_Pri0
<6> 2024-01-22 11:07:58.633 +00:00 [INF] - Cleaned up 0 messages from queue for endpoint iothub_Pri0 and 0 messages from message store.
<6> 2024-01-22 11:07:58.834 +00:00 [INF] - Entering periodic task to reauthenticate connected clients
<4> 2024-01-22 11:09:08.933 +00:00 [WRN] - Did not receive ack for message 3aea4fa2-2a08-45a3-b64d-90ff1bdb11a5 from device/module E5C856BC-0391-47BF-B5C8-5471AE025FEE/moduleClientBridge
<4> 2024-01-22 11:09:08.933 +00:00 [WRN] - Error sending messages to module E5C856BC-0391-47BF-B5C8-5471AE025FEE/moduleClientBridge
System.TimeoutException: Message completion response not received
   at Microsoft.Azure.Devices.Edge.Hub.Core.Device.DeviceMessageHandler.SendMessageAsync(IMessage message, String input) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.Core/device/DeviceMessageHandler.cs:line 501
   at Microsoft.Azure.Devices.Edge.Hub.Core.Routing.ModuleEndpoint.ModuleMessageProcessor.ProcessAsync(ICollection`1 routingMessages, IDeviceProxy dp, CancellationToken token) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.Core/routing/ModuleEndpoint.cs:line 166
<6> 2024-01-22 11:09:22.333 +00:00 [INF] - Exiting connected state
<6> 2024-01-22 11:09:22.333 +00:00 [INF] - Entering unreachable state
<6> 2024-01-22 11:09:22.558 +00:00 [INF] - Entering connected state
<4> 2024-01-22 11:10:38.932 +00:00 [WRN] - Did not receive ack for message 55019276-48fe-44e5-b33b-e680b4b7fa77 from device/module E5C856BC-0391-47BF-B5C8-5471AE025FEE/moduleClientBridge
<4> 2024-01-22 11:10:38.932 +00:00 [WRN] - Error sending messages to module E5C856BC-0391-47BF-B5C8-5471AE025FEE/moduleClientBridge
System.TimeoutException: Message completion response not received
   at Microsoft.Azure.Devices.Edge.Hub.Core.Device.DeviceMessageHandler.SendMessageAsync(IMessage message, String input) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.Core/device/DeviceMessageHandler.cs:line 501
   at Microsoft.Azure.Devices.Edge.Hub.Core.Routing.ModuleEndpoint.ModuleMessageProcessor.ProcessAsync(ICollection`1 routingMessages, IDeviceProxy dp, CancellationToken token) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.Core/routing/ModuleEndpoint.cs:line 166
<4> 2024-01-22 11:16:38.933 +00:00 [WRN] - Did not receive ack for message 0e93b77e-2bd3-4af1-89a2-1dd2a9be8c35 from device/module E5C856BC-0391-47BF-B5C8-5471AE025FEE/moduleClientBridge
<4> 2024-01-22 11:16:38.933 +00:00 [WRN] - Error sending messages to module E5C856BC-0391-47BF-B5C8-5471AE025FEE/moduleClientBridge
System.TimeoutException: Message completion response not received
   at Microsoft.Azure.Devices.Edge.Hub.Core.Device.DeviceMessageHandler.SendMessageAsync(IMessage message, String input) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.Core/device/DeviceMessageHandler.cs:line 501
   at Microsoft.Azure.Devices.Edge.Hub.Core.Routing.ModuleEndpoint.ModuleMessageProcessor.ProcessAsync(ICollection`1 routingMessages, IDeviceProxy dp, CancellationToken token) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.Core/routing/ModuleEndpoint.cs:line 166
<6> 2024-01-22 11:16:46.894 +00:00 [INF] - "Request starting HTTP/1.1 GET http://edgehub:9600/metrics - -"
<6> 2024-01-22 11:16:46.894 +00:00 [INF] - "Request finished HTTP/1.1 GET http://edgehub:9600/metrics - - - 200 - text/plain;+version=0.0.4;+charset=utf-8 0.2326ms"
<6> 2024-01-22 11:17:58.840 +00:00 [INF] - Entering periodic task to reauthenticate connected clients
<4> 2024-01-22 11:18:08.932 +00:00 [WRN] - Did not receive ack for message da48506c-29e8-455a-867f-f44c07436049 from device/module E5C856BC-0391-47BF-B5C8-5471AE025FEE/moduleClientBridge
<4> 2024-01-22 11:18:08.932 +00:00 [WRN] - Error sending messages to module E5C856BC-0391-47BF-B5C8-5471AE025FEE/moduleClientBridge
System.TimeoutException: Message completion response not received
   at Microsoft.Azure.Devices.Edge.Hub.Core.Device.DeviceMessageHandler.SendMessageAsync(IMessage message, String input) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.Core/device/DeviceMessageHandler.cs:line 501
   at Microsoft.Azure.Devices.Edge.Hub.Core.Routing.ModuleEndpoint.ModuleMessageProcessor.ProcessAsync(ICollection`1 routingMessages, IDeviceProxy dp, CancellationToken token) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.Core/routing/ModuleEndpoint.cs:line 166
<6> 2024-01-22 11:19:22.416 +00:00 [INF] - Exiting connected state
<6> 2024-01-22 11:19:22.416 +00:00 [INF] - Entering unreachable state
<6> 2024-01-22 11:19:22.656 +00:00 [INF] - Entering connected state
<4> 2024-01-22 11:19:38.931 +00:00 [WRN] - Did not receive ack for message f2698cda-3184-4dd6-8cb6-e1357f05f3c0 from device/module E5C856BC-0391-47BF-B5C8-5471AE025FEE/moduleClientBridge
<4> 2024-01-22 11:19:38.932 +00:00 [WRN] - Error sending messages to module E5C856BC-0391-47BF-B5C8-5471AE025FEE/moduleClientBridge
System.TimeoutException: Message completion response not received
   at Microsoft.Azure.Devices.Edge.Hub.Core.Device.DeviceMessageHandler.SendMessageAsync(IMessage message, String input) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.Core/device/DeviceMessageHandler.cs:line 501
   at Microsoft.Azure.Devices.Edge.Hub.Core.Routing.ModuleEndpoint.ModuleMessageProcessor.ProcessAsync(ICollection`1 routingMessages, IDeviceProxy dp, CancellationToken token) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.Core/routing/ModuleEndpoint.cs:line 166
<4> 2024-01-22 11:21:08.930 +00:00 [WRN] - Did not receive ack for message 459d599c-f449-4efa-b6d1-00c3964c5741 from device/module E5C856BC-0391-47BF-B5C8-5471AE025FEE/moduleClientBridge
<4> 2024-01-22 11:21:08.931 +00:00 [WRN] - Error sending messages to module E5C856BC-0391-47BF-B5C8-5471AE025FEE/moduleClientBridge
System.TimeoutException: Message completion response not received
   at Microsoft.Azure.Devices.Edge.Hub.Core.Device.DeviceMessageHandler.SendMessageAsync(IMessage message, String input) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.Core/device/DeviceMessageHandler.cs:line 501
   at Microsoft.Azure.Devices.Edge.Hub.Core.Routing.ModuleEndpoint.ModuleMessageProcessor.ProcessAsync(ICollection`1 routingMessages, IDeviceProxy dp, CancellationToken token) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.Core/routing/ModuleEndpoint.cs:line 166
<6> 2024-01-22 11:22:58.835 +00:00 [INF] - Entering periodic task to reauthenticate connected clients
<6> 2024-01-22 11:23:16.204 +00:00 [INF] - "Request starting HTTP/1.1 GET http://172.18.0.6:9600/metrics - -"
<6> 2024-01-22 11:23:16.205 +00:00 [INF] - "Request finished HTTP/1.1 GET http://172.18.0.6:9600/metrics - - - 200 - text/plain;+version=0.0.4;+charset=utf-8 0.2210ms"
<4> 2024-01-22 11:24:08.935 +00:00 [WRN] - Did not receive ack for message 4fed49ef-d1d2-4918-a7b4-6ef7fa82533c from device/module E5C856BC-0391-47BF-B5C8-5471AE025FEE/moduleClientBridge
<4> 2024-01-22 11:24:08.935 +00:00 [WRN] - Error sending messages to module E5C856BC-0391-47BF-B5C8-5471AE025FEE/moduleClientBridge
System.TimeoutException: Message completion response not received
   at Microsoft.Azure.Devices.Edge.Hub.Core.Device.DeviceMessageHandler.SendMessageAsync(IMessage message, String input) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.Core/device/DeviceMessageHandler.cs:line 501
   at Microsoft.Azure.Devices.Edge.Hub.Core.Routing.ModuleEndpoint.ModuleMessageProcessor.ProcessAsync(ICollection`1 routingMessages, IDeviceProxy dp, CancellationToken token) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.Core/routing/ModuleEndpoint.cs:line 166
<6> 2024-01-22 11:24:38.558 +00:00 [INF] - Starting periodic operation Get EdgeHub config...
<6> 2024-01-22 11:24:40.485 +00:00 [INF] - Obtained edge hub config from module twin
<6> 2024-01-22 11:24:40.642 +00:00 [INF] - Updated reported properties for E5C856BC-0391-47BF-B5C8-5471AE025FEE/$edgeHub
<4> 2024-01-22 11:25:10.483 +00:00 [WRN] - Did not receive ack for message ec361528-4cf4-4acb-9ec9-c6e484b95bc8 from device/module E5C856BC-0391-47BF-B5C8-5471AE025FEE/moduleClientBridge
<4> 2024-01-22 11:25:10.483 +00:00 [WRN] - Error sending messages to module E5C856BC-0391-47BF-B5C8-5471AE025FEE/moduleClientBridge
System.TimeoutException: Message completion response not received
   at Microsoft.Azure.Devices.Edge.Hub.Core.Device.DeviceMessageHandler.SendMessageAsync(IMessage message, String input) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.Core/device/DeviceMessageHandler.cs:line 501
   at Microsoft.Azure.Devices.Edge.Hub.Core.Routing.ModuleEndpoint.ModuleMessageProcessor.ProcessAsync(ICollection`1 routingMessages, IDeviceProxy dp, CancellationToken token) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.Core/routing/ModuleEndpoint.cs:line 166
<6> 2024-01-22 11:25:10.483 +00:00 [INF] - Set the following 4 route(s) in edge hub
<6> 2024-01-22 11:25:10.483 +00:00 [INF] - bridgeMachineData2upstream: FROM /messages/modules/moduleClientBridge/outputs/package into $upstream
<6> 2024-01-22 11:25:10.483 +00:00 [INF] - bridgeNotificationTask2upstream: FROM /messages/modules/moduleClientBridge/outputs/notificationTask INTO $upstream
<6> 2024-01-22 11:25:10.483 +00:00 [INF] - messageFromCloud2downstream: FROM /messages/modules/cloudToDeviceMessageReceiver/outputs/C2D INTO BrokeredEndpoint("/modules/moduleClientBridge/inputs/C2D")
<6> 2024-01-22 11:25:10.483 +00:00 [INF] - messageFromCloud2healthReporter: FROM /messages/modules/cloudToDeviceMessageReceiver/outputs/healthReporter INTO BrokeredEndpoint("/modules/healthReporter/inputs/C2D")
<6> 2024-01-22 11:25:10.483 +00:00 [INF] - Updated message store TTL to 259200 seconds
<6> 2024-01-22 11:25:10.483 +00:00 [INF] - Updated the edge hub store and forward configuration
<6> 2024-01-22 11:25:10.483 +00:00 [INF] - Successfully completed periodic operation Get EdgeHub config
<4> 2024-01-22 11:25:41.482 +00:00 [WRN] - Did not receive ack for message 1ecdd86c-73cf-4925-9b56-326b1c28b773 from device/module E5C856BC-0391-47BF-B5C8-5471AE025FEE/moduleClientBridge
<4> 2024-01-22 11:25:41.482 +00:00 [WRN] - Error sending messages to module E5C856BC-0391-47BF-B5C8-5471AE025FEE/moduleClientBridge
System.TimeoutException: Message completion response not received
   at Microsoft.Azure.Devices.Edge.Hub.Core.Device.DeviceMessageHandler.SendMessageAsync(IMessage message, String input) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.Core/device/DeviceMessageHandler.cs:line 501
   at Microsoft.Azure.Devices.Edge.Hub.Core.Routing.ModuleEndpoint.ModuleMessageProcessor.ProcessAsync(ICollection`1 routingMessages, IDeviceProxy dp, CancellationToken token) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.Core/routing/ModuleEndpoint.cs:line 166
<4> 2024-01-22 11:26:13.638 +00:00 [WRN] - Did not receive ack for message 74a10280-0de4-427f-86a8-097dcf863bd1 from device/module E5C856BC-0391-47BF-B5C8-5471AE025FEE/moduleClientBridge
<4> 2024-01-22 11:26:13.639 +00:00 [WRN] - Error sending messages to module E5C856BC-0391-47BF-B5C8-5471AE025FEE/moduleClientBridge
System.TimeoutException: Message completion response not received
   at Microsoft.Azure.Devices.Edge.Hub.Core.Device.DeviceMessageHandler.SendMessageAsync(IMessage message, String input) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.Core/device/DeviceMessageHandler.cs:line 501
   at Microsoft.Azure.Devices.Edge.Hub.Core.Routing.ModuleEndpoint.ModuleMessageProcessor.ProcessAsync(ICollection`1 routingMessages, IDeviceProxy dp, CancellationToken token) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.Core/routing/ModuleEndpoint.cs:line 166
<4> 2024-01-22 11:26:47.267 +00:00 [WRN] - Did not receive ack for message 1606d701-3987-4d9c-bcbc-b6c47dfddd8f from device/module E5C856BC-0391-47BF-B5C8-5471AE025FEE/moduleClientBridge
<4> 2024-01-22 11:26:47.267 +00:00 [WRN] - Error sending messages to module E5C856BC-0391-47BF-B5C8-5471AE025FEE/moduleClientBridge
System.TimeoutException: Message completion response not received
   at Microsoft.Azure.Devices.Edge.Hub.Core.Device.DeviceMessageHandler.SendMessageAsync(IMessage message, String input) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.Core/device/DeviceMessageHandler.cs:line 501
   at Microsoft.Azure.Devices.Edge.Hub.Core.Routing.ModuleEndpoint.ModuleMessageProcessor.ProcessAsync(ICollection`1 routingMessages, IDeviceProxy dp, CancellationToken token) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.Core/routing/ModuleEndpoint.cs:line 166
<6> 2024-01-22 11:27:58.834 +00:00 [INF] - Entering periodic task to reauthenticate connected clients
<4> 2024-01-22 11:28:11.371 +00:00 [WRN] - Did not receive ack for message 86feccfe-f2ea-439f-be2b-3d74aba2acd6 from device/module E5C856BC-0391-47BF-B5C8-5471AE025FEE/moduleClientBridge
<4> 2024-01-22 11:28:11.371 +00:00 [WRN] - Error sending messages to module E5C856BC-0391-47BF-B5C8-5471AE025FEE/moduleClientBridge
System.TimeoutException: Message completion response not received
   at Microsoft.Azure.Devices.Edge.Hub.Core.Device.DeviceMessageHandler.SendMessageAsync(IMessage message, String input) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.Core/device/DeviceMessageHandler.cs:line 501
   at Microsoft.Azure.Devices.Edge.Hub.Core.Routing.ModuleEndpoint.ModuleMessageProcessor.ProcessAsync(ICollection`1 routingMessages, IDeviceProxy dp, CancellationToken token) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.Core/routing/ModuleEndpoint.cs:line 166
<6> 2024-01-22 11:32:58.836 +00:00 [INF] - Entering periodic task to reauthenticate connected clients
<4> 2024-01-22 11:33:35.935 +00:00 [WRN] - Did not receive ack for message a6bd435e-e64a-48bf-85c9-76a5c1335e19 from device/module E5C856BC-0391-47BF-B5C8-5471AE025FEE/moduleClientBridge
<4> 2024-01-22 11:33:35.936 +00:00 [WRN] - Error sending messages to module E5C856BC-0391-47BF-B5C8-5471AE025FEE/moduleClientBridge
System.TimeoutException: Message completion response not received
   at Microsoft.Azure.Devices.Edge.Hub.Core.Device.DeviceMessageHandler.SendMessageAsync(IMessage message, String input) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.Core/device/DeviceMessageHandler.cs:line 501
   at Microsoft.Azure.Devices.Edge.Hub.Core.Routing.ModuleEndpoint.ModuleMessageProcessor.ProcessAsync(ICollection`1 routingMessages, IDeviceProxy dp, CancellationToken token) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.Core/routing/ModuleEndpoint.cs:line 166
<6> 2024-01-22 11:34:19.997 +00:00 [INF] - New token received on the Cbs link
<6> 2024-01-22 11:34:19.998 +00:00 [INF] - Token updated for E5C856BC-0391-47BF-B5C8-5471AE025FEE/cloudSyncStorage
<6> 2024-01-22 11:34:22.833 +00:00 [INF] - Exiting connected state
<6> 2024-01-22 11:34:22.833 +00:00 [INF] - Entering unreachable state
<6> 2024-01-22 11:34:23.070 +00:00 [INF] - Entering connected state
<6> 2024-01-22 11:34:25.999 +00:00 [INF] - New token received on the Cbs link
<6> 2024-01-22 11:34:25.999 +00:00 [INF] - Token updated for E5C856BC-0391-47BF-B5C8-5471AE025FEE/IoTEdgeMetricsCollector
<6> 2024-01-22 11:34:44.996 +00:00 [INF] - New token received on the Cbs link
<6> 2024-01-22 11:34:44.996 +00:00 [INF] - Token updated for E5C856BC-0391-47BF-B5C8-5471AE025FEE/moduleClientBridge

PS: I had to manually try and delete stuff from the logs that was repetitive to make the post fit within 65k characters... and the bug may be related to this issue #7036 (comment)
@jlian
Copy link
Member

jlian commented Jan 23, 2024

Do we have any details/log for the receiving module?

@lfitchett (on-call) please help take a look

@furier
Copy link
Author

furier commented Jan 23, 2024 •
edited

Unfortunaetely the support-bundle command has the same content for the custom modules for the same timeframe as the edge-hub logs

cloudToDeviceMessageReceiver_log.txt 

Error grabbing logs: log message is too large (168194932 > 1000000)
moduleClientBridge_log.txt 

Error grabbing logs: log message is too large (11078150 > 1000000)

Ill try and see tomorrow if I can dig up any log files, but generally the only things logged inside those are our own log statements and there are no warnings or exceptions logged as a result of unhandles exceptions etc that could explain this behaviour. From my understanding they are sent from the cloudToDeviceMessageReceiver module to the moduleClientBridge module via routes which uses the edgeHub module for that communication and they just get somewhere betwwen sending them from the cloudToDeviceMessageReceiver module and receiving them to the moduleClientBridge module.

@jlian
Copy link
Member

jlian commented Jan 30, 2024

@furier any updates? How urgent is this?

@furier
Copy link
Author

furier commented Jan 31, 2024

@jlian it is pretty urgent, we have been struggling with multiple problems with edge and eflow-vm since December and our customer (we are consultants) is starting to rattle the cage and ask if we need to drop azure iot edge and go for a different solution due to all the stability issues we are facing and this is just one of them.

I tried to recover some logs from our custom modules, but not able to through the propper channels like the support-bundle command, Get-EflowLogs and iotedge logs <module> since we just get the type of error messages like Error grabbing logs: log message is too large (168194932 > 1000000)

Diving into /var/lib/docker/containers/<container-id>/local-logs/container.log I am unable to locate logs from the same timeframe as the other logs, now it just shows todays date and it is partially binary because of some compression i guess.

@furier
Copy link
Author

furier commented Feb 20, 2024 •
edited

Hey @jilan,

Not sure if you've had any breakthroughs, but from my side, the issue's been out of sight since we stopped the regular system reboots. However, I'm pretty sure it's not actually resolved, just not being provoked. We will reintroduce the frequent rebooting schedule to see if the issue becomes more prevalent again.

Are there any updates or insights you've come across? If there’s anything specific you need from me to further the investigation, I’m available to help out. Just a heads up, accessing old logs might not be possible anymore. But I’m here to help with anything else you might find useful.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@lfitchett lfitchett

Labels
customer-reported iotedge
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@furier @jlian @lfitchett