Edgehub should be able to recover after a connection timeout
Edgehub get stuck in a loop with System.TimeoutException. Where only solution is to restart edgeHub manually with iotedge restart edgeHub over vpn connection. After restart, the connection is established immediately.
After further investigation in the logs, it seems like the "loop" is fixed by itself some times. But this particular time it took over 24 hours. There is no indication of internet being down for all that period.
Hard to reproduce, happens at no particular reason, OpenVPN logs is hard to read, but it could be that it happens when internet connection is lost. But we are able to connect via VPN later and the issue is still there.
We have the IoT-edge running on several vessels around the world, where most of them has poor internet connection (satellite internet). On the vessels with the worst internet, this error occurs several times per week.
The vessel which the logs is coming from gave no messages to IoTHub for over 24hours due to this issue.
The modules are dependent on edgeHub for sending data to the IoTHub.
iotedge check
IotEdge check
Configuration checks
--------------------
โ config.yaml is well-formed - OK
โ config.yaml has well-formed connection string - OK
โ container engine is installed and functional - OK
โ config.yaml has correct hostname - OK
โ config.yaml has correct URIs for daemon mgmt endpoint - OK
โ latest security daemon - OK
โ host time is close to real time - OK
โ container time is close to host time - OK
โผ DNS server - Warning
Container engine is not configured with DNS server setting, which may impact connectivity to IoT Hub.
Please see https://aka.ms/iotedge-prod-checklist-dns for best practices.
You can ignore this warning if you are setting DNS server per module in the Edge deployment.
โผ production readiness: certificates - Warning
Device is using self-signed, automatically generated certs.
Please see https://aka.ms/iotedge-prod-checklist-certs for best practices.
โ production readiness: certificates expiry - OK
โ production readiness: container engine - OK
โ production readiness: logs policy - OK
Connectivity checks
-------------------
โ host can connect to and perform TLS handshake with IoT Hub AMQP port - OK
โ host can connect to and perform TLS handshake with IoT Hub HTTPS / WebSockets port - OK
โ host can connect to and perform TLS handshake with IoT Hub MQTT port - OK
โ container on the default network can connect to IoT Hub AMQP port - OK
โ container on the default network can connect to IoT Hub HTTPS / WebSockets port - OK
โ container on the default network can connect to IoT Hub MQTT port - OK
โ container on the IoT Edge module network can connect to IoT Hub AMQP port - OK
โ container on the IoT Edge module network can connect to IoT Hub HTTPS / WebSockets port - OK
โ container on the IoT Edge module network can connect to IoT Hub MQTT port - OK
โ Edge Hub can bind to ports on host - OK
21 check(s) succeeded.
2 check(s) raised warnings. Re-run with --verbose for more details.
iotedge version]: iotedge 1.0.8 (208b2204fd30e856d00b280112422130c104b9f0)docker version]: Client:
Version: 3.0.8
API version: 1.40
Go version: go1.12.10
Git commit: 2355349d
Built: Wed Oct 23 17:47:59 2019
OS/Arch: linux/amd64
Experimental: false
Server:
Engine:
Version: 3.0.8
API version: 1.40 (minimum version 1.12)
Go version: go1.12.10
Git commit: adfac69
Built: Wed Oct 23 17:54:47 2019
OS/Arch: linux/amd64
Experimental: false
containerd:
Version: v1.2.10
GitCommit: b34a5c8af56e510852c35414db4c1f4fa6172339
runc:
Version: 1.0.0-rc8+dev
GitCommit: 3e425f80a8c931f88e6d94a8c831b9d5aa481657
docker-init:
Version: 0.18.0
GitCommit: fec3683
iotedged logs
<Paste here between the triple backticks>
edge-agent logs nothing special
Nothing special happening
edge-hub logs
2020-02-26T20:19:48.529155923Z <6> 2020-02-26 20:19:48.528 +00:00 [INF] - Reauthenticating connected clients
2020-02-26T20:20:06.460746518Z <6> 2020-02-26 20:20:06.460 +00:00 [INF] - Starting periodic operation Get EdgeHub config...
2020-02-26T20:20:07.345158048Z <6> 2020-02-26 20:20:07.344 +00:00 [INF] - Obtained edge hub config from module twin
2020-02-26T20:20:07.361067471Z <6> 2020-02-26 20:20:07.360 +00:00 [INF] - Successfully completed periodic operation Get EdgeHub config
2020-02-26T20:20:07.592663397Z <6> 2020-02-26 20:20:07.592 +00:00 [INF] - Starting refresh of device scope identities cache
2020-02-26T20:20:07.646055775Z <6> 2020-02-26 20:20:07.641 +00:00 [INF] - Closing cloud proxy 71def03b-1218-413e-86b3-782f9c27803c for Generated-637139084222529777/rawrfborderrouter because of inactivity
2020-02-26T20:20:08.380260485Z <6> 2020-02-26 20:20:08.379 +00:00 [INF] - Updated reported properties for Generated-637139084222529777/$edgeHub
2020-02-26T20:20:08.769482724Z <6> 2020-02-26 20:20:08.769 +00:00 [INF] - Closing receiver in cloud proxy 71def03b-1218-413e-86b3-782f9c27803c for Generated-637139084222529777/rawrfborderrouter
2020-02-26T20:20:08.770957000Z <6> 2020-02-26 20:20:08.770 +00:00 [INF] - Closed cloud proxy 71def03b-1218-413e-86b3-782f9c27803c for Generated-637139084222529777/rawrfborderrouter
2020-02-26T20:20:15.299421806Z <6> 2020-02-26 20:20:15.299 +00:00 [INF] - Started task to cleanup processed and stale messages for endpoint iothub
2020-02-26T20:20:15.570685867Z <6> 2020-02-26 20:20:15.570 +00:00 [INF] - Cleaned up 316 messages from queue for endpoint iothub and 316 messages from message store.
2020-02-26T20:24:48.528335845Z <6> 2020-02-26 20:24:48.527 +00:00 [INF] - Reauthenticating connected clients
2020-02-26T20:29:48.527003225Z <6> 2020-02-26 20:29:48.526 +00:00 [INF] - Reauthenticating connected clients
2020-02-26T20:34:48.526009643Z <6> 2020-02-26 20:34:48.525 +00:00 [INF] - Reauthenticating connected clients
2020-02-26T20:39:48.526494107Z <6> 2020-02-26 20:39:48.526 +00:00 [INF] - Reauthenticating connected clients
2020-02-26T20:41:50.077472455Z <6> 2020-02-26 20:41:50.077 +00:00 [INF] - New token received on the Cbs link
2020-02-26T20:41:50.078705984Z <6> 2020-02-26 20:41:50.077 +00:00 [INF] - Token updated for Generated-637139084222529777/analytics
2020-02-26T20:44:48.525972877Z <6> 2020-02-26 20:44:48.525 +00:00 [INF] - Reauthenticating connected clients
2020-02-26T20:46:49.437242211Z <6> 2020-02-26 20:46:49.436 +00:00 [INF] - Exiting connected state
2020-02-26T20:46:49.439147062Z <6> 2020-02-26 20:46:49.438 +00:00 [INF] - Entering unreachable state
2020-02-26T20:47:50.487767755Z <6> 2020-02-26 20:47:50.487 +00:00 [INF] - Entering disconnected state
2020-02-26T20:47:50.489301697Z <6> 2020-02-26 20:47:50.489 +00:00 [INF] - Cloud connection for Generated-637139084222529777/$edgeHub is False
2020-02-26T20:47:50.489584118Z <6> 2020-02-26 20:47:50.489 +00:00 [INF] - Connection status for Generated-637139084222529777/$edgeHub changed to Disconnected
2020-02-26T20:47:50.499995957Z <6> 2020-02-26 20:47:50.499 +00:00 [INF] - Cloud connection for Generated-637139084222529777/api is False
2020-02-26T20:47:50.500215039Z <6> 2020-02-26 20:47:50.500 +00:00 [INF] - Connection status for Generated-637139084222529777/api changed to Disconnected
2020-02-26T20:47:50.501264151Z <6> 2020-02-26 20:47:50.501 +00:00 [INF] - Cloud connection for Generated-637139084222529777/analytics is False
2020-02-26T20:47:50.501617560Z <6> 2020-02-26 20:47:50.501 +00:00 [INF] - Connection status for Generated-637139084222529777/analytics changed to Disconnected
2020-02-26T20:47:50.581940477Z <6> 2020-02-26 20:47:50.503 +00:00 [INF] - Retrying cloud proxy operation SendMessageAsync for Generated-637139084222529777/analytics.
2020-02-26T20:47:50.582084075Z Microsoft.Azure.Devices.Client.Exceptions.IotHubCommunicationException: Transient network error occurred, please retry. ---> System.TimeoutException: The operation did not complete within the allocated time 00:01:00 for object message.
2020-02-26T20:47:50.582131012Z at Microsoft.Azure.Amqp.AsyncResult.End[TAsyncResult](IAsyncResult result)
2020-02-26T20:47:50.582204110Z at Microsoft.Azure.Amqp.SendingAmqpLink.EndSendMessage(IAsyncResult result)
2020-02-26T20:47:50.582216162Z at System.Threading.Tasks.TaskFactory`1.FromAsyncCoreLogic(IAsyncResult iar, Func`2 endFunction, Action`1 endAction, Task`1 promise, Boolean requiresSynchronization)
2020-02-26T20:47:50.582288562Z --- End of stack trace from previous location where exception was thrown ---
2020-02-26T20:47:50.582300791Z at Microsoft.Azure.Devices.Client.Transport.Amqp.AmqpLinkHelper.SendAmqpMessageAsync(SendingAmqpLink sendingAmqpLink, AmqpMessage message, TimeSpan timeout)
2020-02-26T20:47:50.582372268Z at Microsoft.Azure.Devices.Client.Transport.Amqp.AmqpUnit.SendMessageAsync(AmqpMessage message, TimeSpan timeout)
2020-02-26T20:47:50.582384540Z at Microsoft.Azure.Devices.Client.Transport.Amqp.AmqpUnit.SendEventAsync(AmqpMessage message, TimeSpan timeout)
2020-02-26T20:47:50.582455367Z at Microsoft.Azure.Devices.Client.Transport.Amqp.AmqpTransportHandler.SendEventAsync(Message message, CancellationToken cancellationToken)
2020-02-26T20:47:50.582467782Z at Microsoft.Azure.Devices.Client.Transport.ErrorDelegatingHandler.<>c__DisplayClass22_0.<<ExecuteWithErrorHandlingAsync>b__0>d.MoveNext()
2020-02-26T20:47:50.582481376Z --- End of stack trace from previous location where exception was thrown ---
2020-02-26T20:47:50.582548148Z at Microsoft.Azure.Devices.Client.Transport.ErrorDelegatingHandler.ExecuteWithErrorHandlingAsync[T](Func`1 asyncOperation)
2020-02-26T20:47:50.582559981Z --- End of inner exception stack trace ---
2020-02-26T20:47:50.582630373Z at Microsoft.Azure.Devices.Client.Transport.ErrorDelegatingHandler.ExecuteWithErrorHandlingAsync[T](Func`1 asyncOperation)
2020-02-26T20:47:50.582642723Z at Microsoft.Azure.Devices.Client.Transport.RetryDelegatingHandler.<>c__DisplayClass14_0.<<SendEventAsync>b__0>d.MoveNext()
2020-02-26T20:47:50.582656076Z --- End of stack trace from previous location where exception was thrown ---
2020-02-26T20:47:50.582723097Z at Microsoft.Azure.Devices.Client.Transport.RetryDelegatingHandler.SendEventAsync(Message message, CancellationToken cancellationToken)
2020-02-26T20:47:50.582735359Z at Microsoft.Azure.Devices.Client.InternalClient.SendEventAsync(Message message)
2020-02-26T20:47:50.582806359Z at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ConnectivityAwareClient.<>c__DisplayClass30_0.<<InvokeFunc>b__0>d.MoveNext() in /home/vsts/work/1/s/edge-hub/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/ConnectivityAwareClient.cs:line 184
2020-02-26T20:47:50.582897481Z --- End of stack trace from previous location where exception was thrown ---
2020-02-26T20:47:50.582969893Z 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 144
2020-02-26T20:47:50.583042509Z 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 172
2020-02-26T20:47:50.583063450Z 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 134
2020-02-26T20:47:50.583139997Z 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 140
2020-02-26T20:47:50.583214131Z at Microsoft.Azure.Devices.Edge.Hub.Core.Cloud.RetryingCloudProxy.<>c__DisplayClass22_0.<<ExecuteOperation>b__0>d.MoveNext() in /home/vsts/work/1/s/edge-hub/src/Microsoft.Azure.Devices.Edge.Hub.Core/cloud/RetryingCloudProxy.cs:line 58
2020-02-26T20:47:50.583227520Z --- End of stack trace from previous location where exception was thrown ---
2020-02-26T20:47:50.583297601Z at Microsoft.Azure.Devices.Edge.Hub.Core.Cloud.RetryingCloudProxy.ExecuteOperation[T](Func`2 func, String operation) in /home/vsts/work/1/s/edge-hub/src/Microsoft.Azure.Devices.Edge.Hub.Core/cloud/RetryingCloudProxy.cs:line 71
2020-02-26T20:47:50.597337016Z <6> 2020-02-26 20:47:50.597 +00:00 [INF] - Attempting to connect to IoT Hub for client Generated-637139084222529777/analytics via AMQP...
2020-02-26T20:48:50.507762184Z <6> 2020-02-26 20:48:50.507 +00:00 [INF] - Closing receiver in cloud proxy 5fd48ab7-bc44-4446-b6aa-9bc52800682a for Generated-637139084222529777/$edgeHub
2020-02-26T20:48:50.507898068Z <6> 2020-02-26 20:48:50.507 +00:00 [INF] - Closed cloud proxy 5fd48ab7-bc44-4446-b6aa-9bc52800682a for Generated-637139084222529777/$edgeHub
2020-02-26T20:48:50.508172203Z <6> 2020-02-26 20:48:50.507 +00:00 [INF] - Closing receiver in cloud proxy 1c8ccb6c-6ba0-4db4-b57e-b5bfea1fac7f for Generated-637139084222529777/analytics
2020-02-26T20:48:50.508366276Z <6> 2020-02-26 20:48:50.508 +00:00 [INF] - Closed cloud proxy 1c8ccb6c-6ba0-4db4-b57e-b5bfea1fac7f for Generated-637139084222529777/analytics
2020-02-26T20:48:50.514119549Z <6> 2020-02-26 20:48:50.513 +00:00 [INF] - Closing receiver in cloud proxy bd70c1fa-aa43-46ce-9496-350270699d9a for Generated-637139084222529777/api
2020-02-26T20:48:50.514173170Z <6> 2020-02-26 20:48:50.513 +00:00 [INF] - Closed cloud proxy bd70c1fa-aa43-46ce-9496-350270699d9a for Generated-637139084222529777/api
2020-02-26T20:48:50.618429691Z <4> 2020-02-26 20:48:50.612 +00:00 [WRN] - Error creating cloud connection for client Generated-637139084222529777/analytics
2020-02-26T20:48:50.618496728Z Microsoft.Azure.Devices.Client.Exceptions.IotHubCommunicationException: The operation did not complete within the allocated time 00:01:00 for object session61. ---> System.TimeoutException: The operation did not complete within the allocated time 00:01:00 for object session61.
2020-02-26T20:48:50.618508947Z at Microsoft.Azure.Amqp.AsyncResult.End[TAsyncResult](IAsyncResult result)
2020-02-26T20:48:50.618518047Z at Microsoft.Azure.Amqp.AmqpObject.OpenAsyncResult.End(IAsyncResult result)
2020-02-26T20:48:50.618527091Z at Microsoft.Azure.Amqp.AmqpObject.EndOpen(IAsyncResult result)
2020-02-26T20:48:50.618564938Z at System.Threading.Tasks.TaskFactory`1.FromAsyncCoreLogic(IAsyncResult iar, Func`2 endFunction, Action`1 endAction, Task`1 promise, Boolean requiresSynchronization)
2020-02-26T20:48:50.618575277Z --- End of stack trace from previous location where exception was thrown ---
2020-02-26T20:48:50.618583655Z at Microsoft.Azure.Devices.Client.Transport.Amqp.AmqpUnit.OpenAsync(TimeSpan timeout)
2020-02-26T20:48:50.618592081Z at Microsoft.Azure.Devices.Client.Transport.Amqp.AmqpTransportHandler.OpenAsync(CancellationToken cancellationToken)
2020-02-26T20:48:50.618600510Z --- End of inner exception stack trace ---
2020-02-26T20:48:50.618618234Z at Microsoft.Azure.Devices.Client.Transport.Amqp.AmqpTransportHandler.OpenAsync(CancellationToken cancellationToken)
2020-02-26T20:48:50.618628407Z at Microsoft.Azure.Devices.Client.Transport.ProtocolRoutingDelegatingHandler.OpenAsync(CancellationToken cancellationToken)
2020-02-26T20:48:50.618637133Z at Microsoft.Azure.Devices.Client.Transport.ErrorDelegatingHandler.<>c__DisplayClass22_0.<<ExecuteWithErrorHandlingAsync>b__0>d.MoveNext()
2020-02-26T20:48:50.618646542Z --- End of stack trace from previous location where exception was thrown ---
2020-02-26T20:48:50.618654800Z at Microsoft.Azure.Devices.Client.Transport.ErrorDelegatingHandler.ExecuteWithErrorHandlingAsync[T](Func`1 asyncOperation)
2020-02-26T20:48:50.618663246Z at Microsoft.Azure.Devices.Client.Transport.RetryDelegatingHandler.<>c__DisplayClass32_0.<<OpenAsyncInternal>b__0>d.MoveNext()
2020-02-26T20:48:50.618672333Z --- End of stack trace from previous location where exception was thrown ---
2020-02-26T20:48:50.618682437Z at Microsoft.Azure.Devices.Client.Transport.RetryDelegatingHandler.EnsureOpenedAsync(CancellationToken cancellationToken)
2020-02-26T20:48:50.618700634Z at Microsoft.Azure.Devices.Client.InternalClient.OpenAsync()
2020-02-26T20:48:50.618709433Z at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ModuleClientWrapper.OpenAsync() in /home/vsts/work/1/s/edge-hub/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/ModuleClientWrapper.cs:line 48
2020-02-26T20:48:50.618718422Z at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ConnectivityAwareClient.<>c__DisplayClass30_0.<<InvokeFunc>b__0>d.MoveNext() in /home/vsts/work/1/s/edge-hub/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/ConnectivityAwareClient.cs:line 184
2020-02-26T20:48:50.618727957Z --- End of stack trace from previous location where exception was thrown ---
2020-02-26T20:48:50.618736277Z 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 144
2020-02-26T20:48:50.618745602Z 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 172
2020-02-26T20:48:50.618754784Z at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ConnectivityAwareClient.OpenAsync() in /home/vsts/work/1/s/edge-hub/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/ConnectivityAwareClient.cs:line 62
2020-02-26T20:48:50.618779084Z at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudConnection.ConnectToIoTHub(ITokenProvider newTokenProvider) in /home/vsts/work/1/s/edge-hub/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/CloudConnection.cs:line 127
2020-02-26T20:48:50.618789696Z at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudConnection.CreateNewCloudProxyAsync(ITokenProvider newTokenProvider) in /home/vsts/work/1/s/edge-hub/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/CloudConnection.cs:line 102
2020-02-26T20:48:50.618801214Z at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudConnection.Create(IIdentity identity, Action`2 connectionStatusChangedHandler, ITransportSettings[] transportSettings, IMessageConverterProvider messageConverterProvider, IClientProvider clientProvider, ICloudListener cloudListener, ITokenProvider tokenProvider, TimeSpan idleTimeout, Boolean closeOnIdleTimeout, TimeSpan operationTimeout, String productInfo) in /home/vsts/work/1/s/edge-hub/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/CloudConnection.cs:line 91
2020-02-26T20:48:50.618819166Z at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudConnectionProvider.<>c__DisplayClass16_1.<<Connect>b__2>d.MoveNext() in /home/vsts/work/1/s/edge-hub/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/CloudConnectionProvider.cs:line 139
2020-02-26T20:48:50.618829128Z --- End of stack trace from previous location where exception was thrown ---
2020-02-26T20:48:50.618846072Z at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudConnectionProvider.Connect(IIdentity identity, Action`2 connectionStatusChangedHandler) in /home/vsts/work/1/s/edge-hub/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/CloudConnectionProvider.cs:line 133
2020-02-26T20:48:50.622631160Z <6> 2020-02-26 20:48:50.619 +00:00 [INF] - Error getting cloud connection for device Generated-637139084222529777/analytics
Please let me know if anything is unclear. And keep up the good work
@mathiash98 - thanks for reporting the issue.
We have made a number of improvements related to EdgeHub re-connections in the latest RC release - https://github.com/Azure/azure-iotedge/releases/tag/1.0.9-rc5. Can you try that out to see if that resolves your problem?
@varunpuranik I have deployed edgeHub and edgeAgent to 1.0.9-rc5. I will report back in a few days to see if it has been fixed ๐ Is there a release timeframe for the next version? We would prefer to not stay on a release candidate
Version 1.0.9-rc5 has been running without issues for 5 days at 8 vessels and 2 offices, where 4 of the vessels have particular bad internet connection.
I consider this issue to be closed. Thanks!
@mathiash98, we want to get 1.0.9 out in the next week or so. We're going through the final phases of customer validation. Thanks for being a part of it!
Most helpful comment
Version 1.0.9-rc5 has been running without issues for 5 days at 8 vessels and 2 offices, where 4 of the vessels have particular bad internet connection.
I consider this issue to be closed. Thanks!