[Technical Question]

[Priyanka-L-Dalawai]

https://github.com/Azure/azure-iot-sdk-csharp/issues/2449#top https://github.com/Azure/azure-iot-sdk-csharp/issues/3044

Expected Behavior Edge hub routes message to the module Module processes and returns MessageResponse.Completed Edge hub does not retry message

Current Behavior Edge hub routes message to the module Module processes and returns MessageResponse.Completed Edge hub retries the message over and over, on 90-second intervals (blocking all other messages in queue)

device sdk version: latest PFA c# code sample.txt

[Priyanka-L-Dalawai]

@drwill-ms, @tmahmood-microsoft @abhipsaMisra @varunpuranik Please help me on this, as this is a blocker for production, Whenever the message load is high ack error occurs for every 5 mins, else after 3 days is what we observe , Tried downgrading from the latest to 1.40.0 still no luck

[Priyanka-L-Dalawai]

@tmahmood-microsoft Can you please help me with this on priority. As it is blocker for us It is this same issue https://github.com/Azure/azure-iot-sdk-csharp/issues/3044

[tmahmood-microsoft]

Hi @Priyanka-L-Dalawai Yes, I am looking into this and will keep you updated with progress on this.

[tmahmood-microsoft]

Hi @Priyanka-L-Dalawai so far I have not been able to reproduce it, even with the sample code you provided. Could you provide some more details as in if this behavior is observed constantly and even when sending very few messages? Do you observe the same behavior if you send messages to the module itself? for instance if module1 sends message to module1 itself (after updating the module routes)? Is there any more information that would help us reproduce this issue? Also, it would be very helpful if you could provide us with a truncated log file.

[Priyanka-L-Dalawai]

Hi We have 2 routes 1) OPC Publisher to Custom module 2) Custom module to IoT Hub If I comment sendeventasync method and keep only 1st route it works with no errors but data won't be sent to IoT hub If I keep sendeventasync with 2nd route and send data to IoT Hub, This error occurs continuously with total 1436 tags at a frequency of 1 second With frequency of 60 s it occurs after certain hours

Sample error:

<6> 2023-06-06 03:03:21.271 +00:00 [INF] - Skipping iotedge-680-connectedworker-prod-001/cn-cw-customiotedgemodule for subscription processing, as it is currently being processed. <6> 2023-06-06 03:03:21.271 +00:00 [INF] - Created cloud proxy for client iotedge-001/cn-cw-customiotedgemodule via AMQP, with client operation timeout 20 seconds. <6> 2023-06-06 03:03:21.271 +00:00 [INF] - Initialized cloud proxy ca4c6d5c-2607-49be-93ef-e18ae7417e06 for iotedge-001/cn-cw-customiotedgemodule <6> 2023-06-06 03:03:21.271 +00:00 [INF] - Created cloud connection for client iotedge-001/cn-cw-customiotedgemodule <6> 2023-06-06 03:03:21.271 +00:00 [INF] - Processing pending subscriptions for iotedge-001/cn-cw-customiotedgemodule <6> 2023-06-06 03:03:21.271 +00:00 [INF] - Processing pending subscriptions for iotedge-001/cn-cw-customiotedgemodule <6> 2023-06-06 03:03:21.271 +00:00 [INF] - Processing pending subscriptions for iotedge-001/cn-cw-customiotedgemodule <6> 2023-06-06 03:03:26.519 +00:00 [INF] - Updated reported properties for iotedge-001/$edgeHub <4> 2023-06-06 03:03:50.766 +00:00 [WRN] - Did not receive ack for message 8d5a8c60-eb46-4594-a3a0-a1fc98170b01 from device/module iotedge-001/cn-cw-customiotedgemodule <4> 2023-06-06 03:03:50.767 +00:00 [WRN] - Error sending messages to module iotedge-001/cn-cw-customiotedgemodule 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> 2023-06-06 03:04:50.890 +00:00 [WRN] - "Closing connection for device: iotedge-001/cn-cw-customiotedgemodule, Microsoft.Azure.Devices.ProtocolGateway.ProtocolGatewayException: Channel closed., " <6> 2023-06-06 03:04:50.890 +00:00 [INF] - Disposing MessagingServiceClient for device Id iotedge-001/cn-cw-customiotedgemodule because of exception - Microsoft.Azure.Devices.ProtocolGateway.ProtocolGatewayException: Channel closed. <6> 2023-06-06 03:04:50.891 +00:00 [INF] - Setting device proxy inactive for device Id iotedge-001/cn-cw-customiotedgemodule <6> 2023-06-06 03:04:50.892 +00:00 [INF] - Removing device connection for device iotdevic001/cn-cw-customiotedgemodule with removeCloudConnection flag 'True'. <6> 2023-06-06 03:04:50.948 +00:00 [INF] - Closing receiver in cloud proxy ca4c6d5c-2607-49be-93ef-e18ae7417e06 for iotdevic001/cn-cw-customiotedgemodule <6> 2023-06-06 03:04:50.948 +00:00 [INF] - Closed cloud proxy ca4c6d5c-2607-49be-93ef-e18ae7417e06 for iotdevic001/cn-cw-customiotedgemodule <6> 2023-06-06 03:04:50.948 +00:00 [INF] - Device connection removed for device iotdevic001/cn-cw-customiotedgemodule <6> 2023-06-06 03:04:50.948 +00:00 [INF] - Remove device connection for device iotdevic001/cn-cw-customiotedgemodule <6> 2023-06-06 03:04:51.011 +00:00 [INF] - Client iotdevic001/cn-cw-customiotedgemodule in device scope authenticated locally. <6> 2023-06-06 03:04:51.011 +00:00 [INF] - Successfully generated identity for clientId iotdevic001/cn-cw-customiotedgemodule and username a223es14ubuntu2046/iotdevic001/cn-cw-customiotedgemodule/?api-version=2020-09-30&DeviceClientType=.NET%2F1.42.0%20%28.NET%20Core%203.1.32%3B%20Linux%205.4.0-144-generic%20%23161-Ubuntu%20SMP%20Fri%20Feb%203%2014%3A49%3A04%20UTC%202023%3B%20X64%29 <6> 2023-06-06 03:04:51.011 +00:00 [INF] - "ClientAuthenticated, iotdevic001/cn-cw-customiotedgemodule, 40e19769" <6> 2023-06-06 03:04:51.012 +00:00 [INF] - New device connection for device iotdevic001/cn-cw-customiotedgemodule <6> 2023-06-06 03:04:51.012 +00:00 [INF] - Client iotdevic001/cn-cw-customiotedgemodule connected to edgeHub, processing existing subscriptions. <6> 2023-06-06 03:04:51.012 +00:00 [INF] - Bind device proxy for device iotdevic001/cn-cw-customiotedgemodule <6> 2023-06-06 03:04:51.012 +00:00 [INF] - Binding message channel for device Id iotdevic001/cn-cw-customiotedgemodule <6> 2023-06-06 03:04:51.012 +00:00 [INF] - Processing pending subscriptions for iotdevic001/cn-cw-customiotedgemodule <6> 2023-06-06 03:04:51.012 +00:00 [INF] - Attempting to connect to IoT Hub for client iotdevic001/cn-cw-customiotedgemodule via AMQP... <6> 2023-06-06 03:04:51.013 +00:00 [INF] - Processing subscriptions TwinResponse, ModuleMessages for client iotdevic001/cn-cw-customiotedgemodule. <6> 2023-06-06 03:04:51.013 +00:00 [INF] - Set subscriptions from session state for iotdevic001/cn-cw-customiotedgemodule <6> 2023-06-06 03:04:51.014 +00:00 [INF] - Processing subscriptions TwinResponse, ModuleMessages for client iotdevic001/cn-cw-customiotedgemodule. <6> 2023-06-06 03:04:51.014 +00:00 [INF] - Set subscriptions from session state for iotdevic001/cn-cw-customiotedgemodule <6> 2023-06-06 03:04:51.191 +00:00 [INF] - Cloud connection for iotdevic001/cn-cw-customiotedgemodule is True <6> 2023-06-06 03:04:51.191 +00:00 [INF] - Connection status for iotdevic001/cn-cw-customiotedgemodule changed to ConnectionEstablished <6> 2023-06-06 03:04:51.191 +00:00 [INF] - Client iotdevic001/cn-cw-customiotedgemodule connected to cloud, processing existing subscriptions. <6> 2023-06-06 03:04:51.191 +00:00 [INF] - Skipping iotdevic001/cn-cw-customiotedgemodule for subscription processing, as it is currently being processed. <6> 2023-06-06 03:04:51.191 +00:00 [INF] - Created cloud proxy for client iotdevic001/cn-cw-customiotedgemodule via AMQP, with client operation timeout 20 seconds. <6> 2023-06-06 03:04:51.191 +00:00 [INF] - Initialized cloud proxy f456a11b-26d0-416a-9063-c40ba3b0cb13 for iotdevic001/cn-cw-customiotedgemodule <6> 2023-06-06 03:04:51.191 +00:00 [INF] - Created cloud connection for client iotdevic001/cn-cw-customiotedgemodule <6> 2023-06-06 03:04:51.192 +00:00 [INF] - Processing pending subscriptions for iotdevic001/cn-cw-customiotedgemodule <6> 2023-06-06 03:04:51.192 +00:00 [INF] - Processing pending subscriptions for iotdevic001/cn-cw-customiotedgemodule <6> 2023-06-06 03:04:51.192 +00:00 [INF] - Processing pending subscriptions for iotdevic001/cn-cw-customiotedgemodule <6> 2023-06-06 03:04:51.233 +00:00 [INF] - Updated reported properties for iotdevic001/$edgeHub <6> 2023-06-06 03:04:56.501 +00:00 [INF] - Updated reported properties for iotdevic001/$edgeHub <4> 2023-06-06 03:05:20.767 +00:00 [WRN] - Did not receive ack for message f66aa425-59c6-4a42-8951-f92766d46031 from device/module iotdevic001/cn-cw-customiotedgemodule <4> 2023-06-06 03:05:20.767 +00:00 [WRN] - Error sending messages to module iotdevic001/cn-cw-customiotedgemodule 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> 2023-06-06 03:06:20.904 +00:00 [WRN] - "Closing connection for device: iotdevic001/cn-cw-customiotedgemodule, Microsoft.Azure.Devices.ProtocolGateway.ProtocolGatewayException: Channel closed., " <6> 2023-06-06 03:06:20.904 +00:00 [INF] - Disposing MessagingServiceClient for device Id iotdevic001/cn-cw-customiotedgemodule because of exception - Microsoft.Azure.Devices.ProtocolGateway.ProtocolGatewayException: Channel closed. <6> 2023-06-06 03:06:20.904 +00:00 [INF] - Setting device proxy inactive for device Id iotdevic001/cn-cw-customiotedgemodule <6> 2023-06-06 03:06:20.904 +00:00 [INF] - Removing device connection for device iotdevic001/cn-cw-customiotedgemodule with removeCloudConnection flag 'True'.

[tmahmood-microsoft]

Hi @Priyanka-L-Dalawai, can you also share the IoT hub name, it would be helpful for us to look at the azure hub logs and understand the behavior. Also, it would be very helpful if you could share a complete log file. It would allow us to investigate the behavior under larger load of messages.

[tmahmood-microsoft]

@Priyanka-L-Dalawai, based on the fact that when message frequency is 1s, the error occur constantly and not when message frequency is 60s, looks like you can either update message Ack timeout (default value: 30s) using environmental variable: 'MessageAckTimeoutSecs' or try completing the received earlier within PipeMessage() instead of after sending the processed message back to edgeHub. This should help resolve the issue. Please let me know if you have further questions or concerns.

[Priyanka-L-Dalawai]

Hi, Have already tried with MessageAckTimeoutSecs to 30 sec, still was getting ack error Will try second solution and keep you posted if I face issues @tmahmood-microsoft But when to send processed message back to hub in that case if I return response earlier?

[Priyanka-L-Dalawai]

@tmahmood-microsoft But when to send processed message back to hub in that case if I return response earlier?

[tmahmood-microsoft]

@Priyanka-L-Dalawai you can send the processed message back right after completing the message. For instance, you can assign the received message to a class variable and process it after returning from the message callback where the message is completed.

[tmahmood-microsoft]

Hi @Priyanka-L-Dalawai is this issue resolved for you? Should I close this github issue?

[Priyanka-L-Dalawai]

Hi, Still we are working on this issue. Will keep you posted on progress of it

[andyk-ms]

Hi @Priyanka-L-Dalawai We have provided help to decouple and incoming message from processing and looks like that resolved your issue. I am closing this for now and please feel free to re-open should you need any assistance.

[Priyanka-L-Dalawai]

Sure, Thanks @tmahmood-microsoft, @andyk-ms