Iotedge: IotHub call timed out - direct methods stop working, D2C messages unaffected

[chriswaters78]

Hi,

This appears related to #534 but I am raising it as a new ticket as I have now collected some good DBG logs.

Expected Behavior

Direct Method calls can be made to a module reliably

Current Behavior

Direct Method calls start failing after some hours of running.

This happened on 3 remote sites simultaneously, there is no shared network between the sites (they are connected to the iothub via 3G routers). Direct methods continued working on a further 3 sites at that time.

D2C messages continue to work throughout for all devices (6 in total)

Restarting the affected module does not fix the issue.
Restarting the edgeHub module does not fix the issue.
Restarting the iotedge service via systemctl does fix the issue.

The point at which they stop corresponds with a time out entry in the edgeHub logs (DBG only). This was verified by polling the direct methods every 30 seconds and looking in the logs at the exact point they stopped.

Steps to Reproduce

Create a module with a direct method (module is based on the sample Temperature polling module).

Leave running, after hours / days, the direct method calls will return 'Timed out waiting for device to connect'. Connectivity will never be restored until the iotedge service itself is restarted

Context (Environment)

Ubuntu 18.04, amd64, linux containers

Runtime Versions

iotedged

iotedge 1.0.4 (2835ac47fbb944ba628a5cfe812ff394768842e0)

Edge Agent

1.0.0

Edge Hub

1.0.0

Docker

3.0.1

SDK and protocol of affected module

Microsoft.Azure.Devices.Client 1.18.1
Transport Type is Amqp_Tcp_Only

Logs

Here are the logs for the edgeHub of the first affected device. The last successful direct method call was
at 01:24:00 exactly. 30 seconds later, another call was made and failed.

The first line is the last successful call and then 18 seconds later we get a connection error. The logs then show a successful reconnection. D2C messages carry on working, but no further Direct Method calls can be made.

2018-12-13 01:24:00.357 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudProxy] - Received call method from cloud for device dellgw5000-8/modbus
2018-12-13 01:24:00.358 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.RoutingEdgeHub] - Received method invoke call from dellgw5000-8/modbus for dellgw5000-8/modbus with correlation ID 09bd6727-9ed7-4c18-9f5e-96e15de78c80
2018-12-13 01:24:00.358 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.InvokeMethodHandler] - Invoking method start on client dellgw5000-8/modbus.
2018-12-13 01:24:00.360 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudProxy] - Received call method from cloud for device dellgw5000-8/modbus
2018-12-13 01:24:00.360 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Device.DeviceMessageHandler] - Sent method invoke call from device/module dellgw5000-8/modbus for dellgw5000-8/modbus with correlation ID 09bd6727-9ed7-4c18-9f5e-96e15de78c80
2018-12-13 01:24:00.360 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.RoutingEdgeHub] - Received method invoke call from dellgw5000-8/modbus for dellgw5000-8/modbus with correlation ID 77d6160e-bfb6-43df-a9e1-0eb12923258b
2018-12-13 01:24:00.360 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.InvokeMethodHandler] - Invoking method start on client dellgw5000-8/modbus.
2018-12-13 01:24:00.396 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Device.DeviceMessageHandler] - Sent method invoke call from device/module dellgw5000-8/modbus for dellgw5000-8/modbus with correlation ID 77d6160e-bfb6-43df-a9e1-0eb12923258b
2018-12-13 01:24:00.498 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Device.DeviceMessageHandler] - Received response for method invoke call with correlation ID 09bd6727-9ed7-4c18-9f5e-96e15de78c80
2018-12-13 01:24:00.638 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Device.DeviceMessageHandler] - Received response for method invoke call with correlation ID 77d6160e-bfb6-43df-a9e1-0eb12923258b
2018-12-13 01:24:03.382 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Amqp.LinkHandlers.EventsLinkHandler] - EventsLinkHandler processed 1 messages for dellgw5000-8/modbus
2018-12-13 01:24:11.304 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Amqp.LinkHandlers.EventsLinkHandler] - EventsLinkHandler processed 1 messages for dellgw5000-8/modbus
2018-12-13 01:24:18.385 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ConnectivityAwareClient] - Operation SendEventAsync timed out for dellgw5000-8/modbus
2018-12-13 01:24:18.390 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.DeviceConnectivityManager] - IotHub call timed out
2018-12-13 01:24:18.393 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.DeviceConnectivityManager] - Exiting connected state
2018-12-13 01:24:18.396 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.DeviceConnectivityManager] - Entering unreachable state
2018-12-13 01:24:18.407 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.DeviceConnectivityManager] - Calling IotHub to test connectivity
2018-12-13 01:24:18.424 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.ConnectionManager] - Obtained cloud connection for device dellgw5000-8/$edgeHub
2018-12-13 01:24:18.542 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ConnectivityAwareClient] - Received connection status changed callback with connection status Disabled and reason Client_Close for dellgw5000-8/modbus
2018-12-13 01:24:18.452 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudProxy] - Error sending message for device dellgw5000-8/modbus in cloud proxy 67010973-120e-462c-b3c3-b30f8cc63911
System.TimeoutException: Operation timeout expired.
   at Microsoft.Azure.Devices.Client.InternalClient.<>c.<ApplyTimeout>b__62_2(Task t)
   at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state)
--- End of stack trace from previous location where exception was thrown ---
   at System.Threading.Tasks.Task.ExecuteWithThreadLocal(Task& currentTaskSlot)
--- End of stack trace from previous location where exception was thrown ---
   at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ConnectivityAwareClient.<>c__DisplayClass28_0.<<InvokeFunc>b__0>d.MoveNext() in /home/vsts/work/1/s/edge-hub/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/ConnectivityAwareClient.cs:line 172
--- End of stack trace from previous location where exception was thrown ---
   at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ConnectivityAwareClient.InvokeFunc[T](Func`1 func, String operation, Boolean useForConnectivityCheck) in /home/vsts/work/1/s/edge-hub/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/ConnectivityAwareClient.cs:line 132
   at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudProxy.SendMessageAsync(IMessage inputMessage) in /home/vsts/work/1/s/edge-hub/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/CloudProxy.cs:line 127
2018-12-13 01:24:18.606 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.CloudEndpoint] - Retrying sending message from dellgw5000-8/modbus to Iot Hub due to exception System.TimeoutException:Operation timeout expired..
2018-12-13 01:24:18.695 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.DeviceConnectivityManager] - IotHub call succeeded
2018-12-13 01:24:18.695 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.DeviceConnectivityManager] - Entering connected state
2018-12-13 01:24:18.696 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ConnectivityAwareClient] - Operation UpdateReportedPropertiesAsync succeeded for dellgw5000-8/$edgeHub
2018-12-13 01:24:18.696 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudProxy] - Updating reported properties for device dellgw5000-8/$edgeHub
2018-12-13 01:24:19.647 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.CloudEndpoint] - Sending 1 message(s) upstream.
2018-12-13 01:24:19.648 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.ConnectionManager] - Obtained cloud connection for device dellgw5000-8/modbus
2018-12-13 01:24:20.855 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Amqp.LinkHandlers.EventsLinkHandler] - EventsLinkHandler processed 1 messages for dellgw5000-8/modbus
2018-12-13 01:24:20.856 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.DeviceConnectivityManager] - IotHub call succeeded
2018-12-13 01:24:20.856 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ConnectivityAwareClient] - Operation SendEventAsync succeeded for dellgw5000-8/modbus
2018-12-13 01:24:20.857 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudProxy] - Sending message for device dellgw5000-8/modbus
2018-12-13 01:24:20.858 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Getting next batch for endpoint iothub starting from 57971 with batch size 10.
2018-12-13 01:24:20.859 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Obtained next batch for endpoint iothub with batch size 3. Next start offset = 57974.
2018-12-13 01:24:20.871 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.CloudEndpoint] - Sending 3 message(s) upstream.
2018-12-13 01:24:20.872 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.ConnectionManager] - Obtained cloud connection for device dellgw5000-8/modbus
2018-12-13 01:24:20.929 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.DeviceConnectivityManager] - IotHub call succeeded
2018-12-13 01:24:20.930 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ConnectivityAwareClient] - Operation SendEventAsync succeeded for dellgw5000-8/modbus
2018-12-13 01:24:20.930 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudProxy] - Sending message for device dellgw5000-8/modbus
2018-12-13 01:24:20.932 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.ConnectionManager] - Obtained cloud connection for device dellgw5000-8/modbus
2018-12-13 01:24:20.992 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.DeviceConnectivityManager] - IotHub call succeeded
2018-12-13 01:24:20.992 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ConnectivityAwareClient] - Operation SendEventAsync succeeded for dellgw5000-8/modbus
2018-12-13 01:24:20.994 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudProxy] - Sending message for device dellgw5000-8/modbus
2018-12-13 01:24:20.996 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.ConnectionManager] - Obtained cloud connection for device dellgw5000-8/modbus

Here are the edgehub logs for the second affected module, again last successful call was at 01:24:00 exactly, and this module is in a different location connecting to the iothub through a completely separate 3G network. The time stamps are almost identical so it seems this must relate to the IoT hub the devices connect to.

2018-12-13 01:24:00.357 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudProxy] - Received call method from cloud for device dellgw5000-5/modbus
2018-12-13 01:24:00.358 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.RoutingEdgeHub] - Received method invoke call from dellgw5000-5/modbus for dellgw5000-5/modbus with correlation ID 827009c5-13fd-4f1e-ae72-7314d0cdf9f0
2018-12-13 01:24:00.358 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.InvokeMethodHandler] - Invoking method start on client dellgw5000-5/modbus.
2018-12-13 01:24:00.361 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Device.DeviceMessageHandler] - Sent method invoke call from device/module dellgw5000-5/modbus for dellgw5000-5/modbus with correlation ID 827009c5-13fd-4f1e-ae72-7314d0cdf9f0
2018-12-13 01:24:00.499 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Device.DeviceMessageHandler] - Received response for method invoke call with correlation ID 827009c5-13fd-4f1e-ae72-7314d0cdf9f0
2018-12-13 01:24:03.382 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Amqp.LinkHandlers.EventsLinkHandler] - EventsLinkHandler processed 1 messages for dellgw5000-5/modbus
2018-12-13 01:24:08.409 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Amqp.LinkHandlers.EventsLinkHandler] - EventsLinkHandler processed 1 messages for dellgw5000-5/modbus
2018-12-13 01:24:13.443 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Amqp.LinkHandlers.EventsLinkHandler] - EventsLinkHandler processed 1 messages for dellgw5000-5/modbus
2018-12-13 01:24:18.341 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ConnectivityAwareClient] - Operation SendEventAsync timed out for dellgw5000-5/modbus
2018-12-13 01:24:18.344 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.DeviceConnectivityManager] - IotHub call timed out
2018-12-13 01:24:18.348 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.DeviceConnectivityManager] - Exiting connected state
2018-12-13 01:24:18.351 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.DeviceConnectivityManager] - Entering unreachable state
2018-12-13 01:24:18.363 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.DeviceConnectivityManager] - Calling IotHub to test connectivity
2018-12-13 01:24:18.380 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.ConnectionManager] - Obtained cloud connection for device dellgw5000-5/$edgeHub
2018-12-13 01:24:18.413 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ConnectivityAwareClient] - Received connection status changed callback with connection status Disabled and reason Client_Close for dellgw5000-5/modbus
2018-12-13 01:24:18.508 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Amqp.LinkHandlers.EventsLinkHandler] - EventsLinkHandler processed 1 messages for dellgw5000-5/modbus
2018-12-13 01:24:18.399 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudProxy] - Error sending message for device dellgw5000-5/modbus in cloud proxy f31de7ba-046b-49b6-b702-d435ddfe1a23
System.TimeoutException: Operation timeout expired.
   at Microsoft.Azure.Devices.Client.InternalClient.<>c.<ApplyTimeout>b__62_2(Task t)
   at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state)
--- End of stack trace from previous location where exception was thrown ---
   at System.Threading.Tasks.Task.ExecuteWithThreadLocal(Task& currentTaskSlot)
--- End of stack trace from previous location where exception was thrown ---
   at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ConnectivityAwareClient.<>c__DisplayClass28_0.<<InvokeFunc>b__0>d.MoveNext() in /home/vsts/work/1/s/edge-hub/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/ConnectivityAwareClient.cs:line 172
--- End of stack trace from previous location where exception was thrown ---
   at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ConnectivityAwareClient.InvokeFunc[T](Func`1 func, String operation, Boolean useForConnectivityCheck) in /home/vsts/work/1/s/edge-hub/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/ConnectivityAwareClient.cs:line 132
   at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudProxy.SendMessageAsync(IMessage inputMessage) in /home/vsts/work/1/s/edge-hub/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/CloudProxy.cs:line 127
2018-12-13 01:24:18.538 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.CloudEndpoint] - Retrying sending message from dellgw5000-5/modbus to Iot Hub due to exception System.TimeoutException:Operation timeout expired..
2018-12-13 01:24:18.688 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.DeviceConnectivityManager] - IotHub call succeeded
2018-12-13 01:24:18.689 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.DeviceConnectivityManager] - Entering connected state
2018-12-13 01:24:18.689 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ConnectivityAwareClient] - Operation UpdateReportedPropertiesAsync succeeded for dellgw5000-5/$edgeHub
2018-12-13 01:24:18.690 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudProxy] - Updating reported properties for device dellgw5000-5/$edgeHub
2018-12-13 01:24:19.581 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.CloudEndpoint] - Sending 1 message(s) upstream.
2018-12-13 01:24:19.581 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.ConnectionManager] - Obtained cloud connection for device dellgw5000-5/modbus
2018-12-13 01:24:20.900 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.DeviceConnectivityManager] - IotHub call succeeded
2018-12-13 01:24:20.900 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ConnectivityAwareClient] - Operation SendEventAsync succeeded for dellgw5000-5/modbus
2018-12-13 01:24:20.901 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudProxy] - Sending message for device dellgw5000-5/modbus
2018-12-13 01:24:20.904 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Getting next batch for endpoint iothub starting from 9917 with batch size 10.
2018-12-13 01:24:20.937 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Obtained next batch for endpoint iothub with batch size 4. Next start offset = 9921.
2018-12-13 01:24:20.950 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.CloudEndpoint] - Sending 4 message(s) upstream.
2018-12-13 01:24:20.951 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.ConnectionManager] - Obtained cloud connection for device dellgw5000-5/modbus
2018-12-13 01:24:21.013 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.DeviceConnectivityManager] - IotHub call succeeded
2018-12-13 01:24:21.014 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ConnectivityAwareClient] - Operation SendEventAsync succeeded for dellgw5000-5/modbus
2018-12-13 01:24:21.014 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudProxy] - Sending message for device dellgw5000-5/modbus
2018-12-13 01:24:21.015 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.ConnectionManager] - Obtained cloud connection for device dellgw5000-5/modbus
2018-12-13 01:24:21.083 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.DeviceConnectivityManager] - IotHub call succeeded
2018-12-13 01:24:21.084 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ConnectivityAwareClient] - Operation SendEventAsync succeeded for dellgw5000-5/modbus
2018-12-13 01:24:21.085 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudProxy] - Sending message for device dellgw5000-5/modbus
2018-12-13 01:24:21.086 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.ConnectionManager] - Obtained cloud connection for device dellgw5000-5/modbus
2018-12-13 01:24:21.151 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.DeviceConnectivityManager] - IotHub call succeeded
2018-12-13 01:24:21.154 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ConnectivityAwareClient] - Operation SendEventAsync succeeded for dellgw5000-5/modbus
2018-12-13 01:24:21.155 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudProxy] - Sending message for device dellgw5000-5/modbus
2018-12-13 01:24:21.155 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.ConnectionManager] - Obtained cloud connection for device dellgw5000-5/modbus
2018-12-13 01:24:21.223 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.DeviceConnectivityManager] - IotHub call succeeded
2018-12-13 01:24:21.224 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ConnectivityAwareClient] - Operation SendEventAsync succeeded for dellgw5000-5/modbus
2018-12-13 01:24:21.224 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudProxy] - Sending message for device dellgw5000-5/modbus
2018-12-13 01:24:21.228 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Getting next batch for endpoint iothub starting from 9921 with batch size 10.
2018-12-13 01:24:21.228 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Obtained next batch for endpoint iothub with batch size 0. Next start offset = 9921.

Additional Information

This is the message you get trying to call the direct method, you get the same error trying to invoke the method through the portal. This response is more or less instant.

Unhandled Exception: System.AggregateException: One or more errors occurred. (Device {"Message":"{\"errorCode\":404103,\"trackingId\":\"cb4fbbab938e44f5a66c59d823f4304b-G:5-TimeStamp:12/13/2018 13:11:23\",\"message\":\"Timed out waiting for device to connect.\",\"info\":{\"timeout\":\"00:00:00\"},\"timestampUtc\":\"2018-12-13T13:11:23.2129387Z\"}","ExceptionMessage":""} not registered) ---> Microsoft.Azure.Devices.Common.Exceptions.DeviceNotFoundException: Device {"Message":"{\"errorCode\":404103,\"trackingId\":\"cb4fbbab938e44f5a66c59d823f4304b-G:5-TimeStamp:12/13/2018 13:11:23\",\"message\":\"Timed out waiting for device to connect.\",\"info\":{\"timeout\":\"00:00:00\"},\"timestampUtc\":\"2018-12-13T13:11:23.2129387Z\"}","ExceptionMessage":""} not registered

I get the same message on a device running in my office if I disconnect it from the network. However, direct methods always start working again once I plug the cable back in.

If there is anything you would like me to test, I am happy to oblige. Also, any possible workarounds would be very helpful as we have a customer who is keen to go live as soon as possible with this.

[varunpuranik]

@chriswaters78 - Thanks for the issue. It looks like edgeHub is losing the Direct methods link to IoTHub and not recovering it as expected.
We will look into the issue. I will keep you posted on our progress.

[yfakariya]

I also faced a similar problem. Our application periodically sends direct method via IoT Hub, and then, the method invocation contiously failed with timeout exception. I found following edgeHub log at the time of the timeout exception had been occurred:

2018-12-15 20:59:21.613 +00:00 [WRN] [Microsoft.Azure.Devices.Edge.Hub.Amqp.LinkHandlers.SendingLinkHandler] - Error disposing message in ModuleMessages link for DEVICE_ID/MODULE_ID
System.NullReferenceException: Object reference not set to an instance of an object.
   at Microsoft.Azure.Devices.Client.InternalClient.<>c.<ApplyTimeout>b__61_1(Task t)
   at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state)
--- End of stack trace from previous location where exception was thrown ---
   at System.Threading.Tasks.Task.ExecuteWithThreadLocal(Task& currentTaskSlot)
--- End of stack trace from previous location where exception was thrown ---
   at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ConnectivityAwareClient.<>c__DisplayClass28_0.<<InvokeFunc>b__0>d.MoveNext() in /home/vsts/work/1/s/edge-hub/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/ConnectivityAwareClient.cs:line 172
--- End of stack trace from previous location where exception was thrown ---
   at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ConnectivityAwareClient.InvokeFunc[T](Func`1 func, String operation, Boolean useForConnectivityCheck) in /home/vsts/work/1/s/edge-hub/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/ConnectivityAwareClient.cs:line 132
   at Microsoft.Azure.Devices.Edge.Hub.Core.Device.DeviceMessageHandler.ProcessMessageFeedbackAsync(String messageId, FeedbackStatus feedbackStatus) in /home/vsts/work/1/s/edge-hub/src/Microsoft.Azure.Devices.Edge.Hub.Core/device/DeviceMessageHandler.cs:line 112
   at Microsoft.Azure.Devices.Edge.Hub.Amqp.LinkHandlers.SendingLinkHandler.DisposeMessageAsync(Delivery delivery) in /home/vsts/work/1/s/edge-hub/src/Microsoft.Azure.Devices.Edge.Hub.Amqp/linkhandlers/SendingLinkHandler.cs:line 104

My environment is IoT Edge 1.0.4 (iotedged, egeAgent, edgeHub) on Ubuntu 18.04.

I hope this helps investigation.

[chriswaters78]

An update on this, I upgraded to the latest 1.0.5 iotedge release and to the 1.19.0 Microsoft.Azure.Devices.Client SDK release a couple of days ago. I have not seen the issue since then so am hoping this is resolved. I will continue monitoring for a few more days to be sure.

[myagley]

The Edge Hub was just updated to 1.19.0 of the C# SDK itself in #698. This will be released in 1.0.6 at the end of the month. This change is most likely required to fully resolve the issue.

[yfakariya]

It looks that #698 was reverted in #724, and will be merged in #758. Can we get fixed version as 1.0.6?

[myagley]

There is a regression in the C# SDK that we are working to resolve. This is why it did not make it into the 1.0.6 release. We are still trying to get it into 1.0.7.

[myagley]

For reference, the SDK issue is https://github.com/Azure/azure-iot-sdk-csharp/issues/751

[yfakariya]

I understand it. Thank you.

[chriswaters78]

Yes I am still seeing this issue occasionally, seems a lot less frequent after updating my module to use the latest SDK though. Will test again once 1.0.7 is released and the edgeHub also uses the latest SDK.

[myagley]

The fix for https://github.com/Azure/azure-iot-sdk-csharp/issues/751 is code review in https://github.com/Azure/azure-iot-sdk-csharp/pull/795

[yfakariya]

I tested 1.0.7-rc1 last week, but I still faced timeout of direct method invocation.

I found that there were no stack traces that I had posted (https://github.com/Azure/iotedge/issues/646#issuecomment-447711936), but direct methods for some modules failed and for others were succeeded. After machine reboot, I could call direct method for time-outed modules.

For information, I did not find [DBG] log of [Microsoft.Azure.Devices.Edge.Hub.Core.SubscriptionProcessor] - Adding subscription Methods for client ... entries when I faced timeout, but I found the [DBG] log if timeout was not occurred. I guess there is another bug to fail establish AMQP link for modules when edge-hub is starting.

[sebader]

I'm seeing the same behavior (on 1.0.6). My long running test is running fine sometimes for days and at some point direct methods stop working - without any visible error message. It helps to restart just the edge hub (iotedge restart edgeHub). Once the module re-connects, direct methods to that module continue to work. It does not seem necessary to restart the whole system.
I have only tested this so far with edgeHub connecting to upstream via AMQP. Just set up a second test with UpstreamProtocol MQTT as well. The module uses AMQP.
Also, looks like https://github.com/Azure/azure-iot-sdk-csharp/pull/795 will not be merged. So any other fix on the way?

[myagley]

Hi Sebastian. Yes, we are very well aware of the issues with Direct Methods. The root cause is that the AMQP link between the Edge Hub and the IoT Hub is being dropped silently. The Edge Hub relies on the C# SDK for this connectivity, and restarting the Edge Hub re-establishes this link, fixing the issue.

This behavior on AMQP has been fixed in 1.19.0 of the C# SDK, but this version has a couple of issues, preventing IoT Edge from using it. The PR mentioned above is a fix for one of these issues and will be merged. We will get this updated as soon as a fix comes, and are planning to get a release candidate out shortly.

[sebader]

thanks for the update. Just worth mentioning (not sure if there is a dedicated issue for that): When connecting Edge Hub upstream via MQTT, stability of C2D direct methods into modules is even (much) more unstable than when using AMQP. In my test the module is connecting to Edge Hub via AMQP. Direct methods sometimes stop working already after a couple of minutes or latest after a couple of hours. Again, restart of Edge Hub helps for a while.

[jcoliz]

I am seeing something similar running 1.0.6 where single deployments from vscode do not reach the device, as if they were never sent.

[myagley]

@jcoliz can we see Edge Agent logs from this period. There is an improvement in the 1.0.7 release branch that has a fix for what sounds like is your issue: https://github.com/Azure/iotedge/commit/cb7af4090aca24d624e96ced572d6dc31b7c97c0

[BewaControl-ReneDivossen]

@myagley We have the same problem that Direct Methods called from a ServiceClient are not working anymore after a while. Direct Method calls from a ModuleClient on the same edgeDevice still work though.
I sure hope the fix will be delivered with the 1.0.7 Release.

[BewaControl-ReneDivossen]

Are there any news concerning this issue?
There seem to be some AMQP Fixes in the Microsoft.Azure.Devices.Client v1.29.0-preview-002.
Will these fixes be integrated into the 1.0.7 release ? Will this make the direct methods more stable ?
We really need the direct methods to work reliably!

[myagley]

This is the top priority bug to be fixed and the C# SDK team is working hard to address. We are holding the 1.0.7 release of IoT Edge until we get this fixed and can verify it.

There has been significant progress on the underlying issue and a long haul test plan is being run to verify. We are targeting a 1.0.7 release candidate by the end of the month but this is dependent on how this testing goes.

[yfakariya]

We ran our long haul testing with 1.0.7-rc2 last 5days, this issue looks be fixed. Thank you for hard work!

[zmsoft]

@myagley @yfakariya When the iot edge version is 1.0.6, docker images can use the local repository, but when the iot edge version is 1.0.7, it seems that a rule has been added that the mirror repository provided by azure must be used.The reason for using the local repository is that it is fast to debug and fast to pull.
How can I use the local image repository for the 1.0.7 version of iot edge?Many thanks.

[myagley]

This will be fixed in 1.0.8. The fix is here: #1200

[github-actions[bot]]

This issue is being marked as stale because it has been open for 30 days with no activity.

[lt72]

Closing this issue as it seems fixed. Please re-open as needed.

[Joehannus]

Please reopen this issue. We're still having this issue. We are currently using version 1.0.8.3 for the edge agent and edge hub.

Recently we added logic to an azure function to automatically perform direct methods in specific functional situations. In a first version we checked the connected status of a module (using the get module api), before sending a direct method. But we found out that a module can get into a disconnected state (for whatever reason). In that case the direct method would not be initated. Therefore we added logic to the device twin of the edge agent, because its reported properties contain the runtime status of each module. And used the run time status in stead of the connection status.

When it's connected and the module is in a running state - you can send these direct methods without any problems. But we also found out that allthough a module can be in a running state - you still can get timeouts on a direct method. Further analysis showed us that whenever these timeouts occur on a running module, that the module shows a disconnected state in IotHub (and also when calling the get module api).

Restarting the module seems to solve these issues.