Custom Modules are getting disconnected from edgeHub frequently

Question

Hi,

When we upgraded edgeHub and edgeAgent from version 1.1.19 to 1.5.3, we noticed that all the custom modules connect when edgeHub starts. However, after about an hour, the modules disconnect and reconnect after 20 minutes. This process keeps happening repeatedly.

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

The modules are getting reconnected but the status in the IoT Edge Hub Section is still showing disconnected.

Below are the logs of the edgeHub module

<6> 2024-09-18 05:27:41.289 +00:00 [INF] - "Closing connection for device: <deviceid>/<custommodule>, , "

<6> 2024-09-18 05:27:41.289 +00:00 [INF] - Disposing MessagingServiceClient for device Id <deviceid>/<custommodule>because of exception -

<6> 2024-09-18 05:27:41.289 +00:00 [INF] - Setting device proxy inactive for device Id <deviceid>/<custommodule>

<6> 2024-09-18 05:27:41.289 +00:00 [INF] - Removing device connection for device <deviceid>/<custommodule>with removeCloudConnection flag 'True'.

<6> 2024-09-18 05:27:41.344 +00:00 [INF] - Client <deviceid>/<custommodule>in device scope authenticated locally.

<6> 2024-09-18 05:27:41.345 +00:00 [INF] - Successfully generated identity for clientId <deviceid>/<custommodule>and username iothub-eus2-dev-001.azure-devices.net/<deviceid>/<custommodule>/?api-version=2019-10-01&DeviceClientType=azure-iot-device-iothub-py%2F2.8.0%283.8.17%3BLinux%20%23163-Ubuntu%20SMP%20Fri%20Mar%2017%2018%3A26%3A02%20UTC%202023%3Bx86_64%29

<6> 2024-09-18 05:27:41.345 +00:00 [INF] - "ClientAuthenticated, <deviceid>/<custommodule>, 25ded387"

<6> 2024-09-18 05:27:41.345 +00:00 [INF] - New device connection for device <deviceid>/<custommodule>

<6> 2024-09-18 05:27:41.345 +00:00 [INF] - Client <deviceid>/<custommodule>r connected to edgeHub, processing existing subscriptions.

<6> 2024-09-18 05:27:41.345 +00:00 [INF] - Bind device proxy for device <deviceid>/<custommodule>

<6> 2024-09-18 05:27:41.345 +00:00 [INF] - Binding message channel for device Id <deviceid>/<custommodule>

<6> 2024-09-18 05:27:41.345 +00:00 [INF] - Processing pending subscriptions for <deviceid>/<custommodule>

<6> 2024-09-18 05:27:41.345 +00:00 [INF] - Attempting to connect to IoT Hub for client <deviceid>/<custommodule>via AMQP...

<6> 2024-09-18 05:27:41.358 +00:00 [INF] - Closing receiver in cloud proxy bc05704b-2a16-40c8-bc3e-fae4db184ebd for <deviceid>/<custommodule>

<6> 2024-09-18 05:27:41.358 +00:00 [INF] - Closed cloud proxy bc05704b-2a16-40c8-bc3e-fae4db184ebd for <deviceid>/<custommodule>

<6> 2024-09-18 05:27:41.358 +00:00 [INF] - Device connection removed for device <deviceid>/<custommodule>

<6> 2024-09-18 05:27:41.358 +00:00 [INF] - Remove device connection for device <deviceid>/<custommodule>

<6> 2024-09-18 05:27:41.510 +00:00 [INF] - Cloud connection for <deviceid>/<custommodule>is True

<6> 2024-09-18 05:27:41.510 +00:00 [INF] - Connection status for <deviceid>/<custommodule>changed to ConnectionEstablished

<6> 2024-09-18 05:27:41.510 +00:00 [INF] - Client <deviceid>/<custommodule>connected to cloud, processing existing subscriptions.

<6> 2024-09-18 05:27:41.510 +00:00 [INF] - Skipping <deviceid>/<custommodule>for subscription processing, as it is currently being processed.

<6> 2024-09-18 05:27:41.510 +00:00 [INF] - Created cloud proxy for client <deviceid>/<custommodule>via AMQP, with client operation timeout 20 seconds.

<6> 2024-09-18 05:27:41.510 +00:00 [INF] - Initialized cloud proxy 7b9ee43a-e16f-45cd-9285-3962f5ccbf5c for <deviceid>/<custommodule>

<6> 2024-09-18 05:27:41.510 +00:00 [INF] - Created cloud connection for client <deviceid>/<custommodule>

<6> 2024-09-18 05:27:44.020 +00:00 [INF] - Updated reported properties for <deviceid>/$edgeHub

<4> 2024-09-18 05:28:11.289 +00:00 [WRN] - Did not receive ack for message d89939d2-32a4-4764-afc3-fa0ef5d84ffe from device/module <deviceid>/<custommodule>

<4> 2024-09-18 05:28:11.289 +00:00 [WRN] - **Error sending messages to module <deviceid>/<custommodule>

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 498

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-09-18 05:31:43.236 +00:00 [INF] - Entering periodic task to reauthenticate connected clients

<6> 2024-09-18 05:36:43.236 +00:00 [INF] - Entering periodic task to reauthenticate connected clients

<6> 2024-09-18 05:36:43.236 +00:00 [INF] - Error authenticating token for <deviceid>/blobstorageiotedge because the token is expired or could not be parsed

<6> 2024-09-18 05:36:43.236 +00:00 [INF] - Credentials for client <deviceid>/blobstorageiotedge are not valid.

<4> 2024-09-18 05:36:43.236 +00:00 [WRN] - Reauthenticating client <deviceid>/blobstorageiotedge failed, removing client connection

<6> 2024-09-18 05:36:43.236 +00:00 [INF] - Unable to re-authenticate <deviceid>/blobstorageiotedge, dropping client connection.

<6> 2024-09-18 05:36:43.236 +00:00 [INF] - Removing device connection for device <deviceid>/blobstorageiotedge with removeCloudConnection flag 'True'.

<4> 2024-09-18 05:36:43.237 +00:00 [WRN] - "Closing connection for device: <deviceid>/blobstorageiotedge, Microsoft.Azure.Devices.Edge.Hub.Core.EdgeHubConnectionException: Connection closed for device <deviceid>/blobstorageiotedge., "

<6> 2024-09-18 05:36:43.237 +00:00 [INF] - Disposing MessagingServiceClient for device Id <deviceid>/blobstorageiotedge because of exception - Microsoft.Azure.Devices.Edge.Hub.Core.EdgeHubConnectionException: Connection closed for device <deviceid>/blobstorageiotedge.

<6> 2024-09-18 05:36:43.237 +00:00 [INF] - Closing device proxy for device Id <deviceid>/blobstorageiotedge

<6> 2024-09-18 05:36:43.297 +00:00 [INF] - Closing receiver in cloud proxy 641d6314-9200-4797-9e5d-cdc1c5fceed6 for <deviceid>/blobstorageiotedge

<6> 2024-09-18 05:36:43.297 +00:00 [INF] - Closed cloud proxy 641d6314-9200-4797-9e5d-cdc1c5fceed6 for <deviceid>/blobstorageiotedge

<6> 2024-09-18 05:36:43.297 +00:00 [INF] - Device connection removed for device <deviceid>/blobstorageiotedge How to resolve this issue?

Thanks,

karthik