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.

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

When EdgeHub disconnects from IoT Hub, Desired Properties are being lost #1654

Closed
grzegorski opened this issue Aug 30, 2019 · 13 comments
Closed
Labels
area:edgehub Issue with Edge Hub customer-reported iotedge needinfo Needs more info from issue reporter / updates from PR submitter

Comments

@grzegorski
Copy link

Expected Behavior

IoT Edge device is running in some locations where upstream connectivity can be challenging.
Our module reads configuration from desired properties.
Expected behavior is that when EdgeHub losses cloud connectivity for whatever reason. Desired Properties for all modules are maintained and refreshed when the connectivity is resumed.

Current Behavior

We noticed that Desired Properties are lost occasionally, normally after network connectivity issues , causing modules to loose parameters that are read from there.

Steps to Reproduce

1.Deploy IoT Edge modules with upstream connectivity over Web Sockets
2.When the cloud connection over Web Sockets fails, UpdateReportedPropertiesAsync method times out and module loses Desired Properties and doesn't recover

Device (Host) Operating System

Ubuntu Server 18.04

Architecture

amd64

Runtime Versions

iotedged

1.0.8

Edge Agent

1.0.8

Edge Hub

1.0.8

Docker

3.0.6

<Run `docker version` (`docker -H npipe:////./pipe/iotedge_moby_engine version` for Moby on Windows) and paste here>

Client:
Version: 3.0.6
API version: 1.40
Go version: go1.12.5
Git commit: a63faebc
Built: Wed Jun 19 22:56:37 2019
OS/Arch: linux/amd64
Experimental: false

Server:
Engine:
Version: 3.0.5
API version: 1.40 (minimum version 1.12)
Go version: go1.12.1
Git commit: dbe4a30
Built: Thu Apr 18 22:07:58 2019
OS/Arch: linux/amd64
Experimental: false
containerd:
Version: v1.2.5
GitCommit: bb71b10fd8f58240ca47fbb579b9d1028eea7c84
runc:
Version: 1.0.0-rc6+dev
GitCommit: 2b18fe1d885ee5083ef9f0838fee39b62d653e30
docker-init:
Version: 0.18.0
GitCommit: fec3683

Logs

module logs
2019-08-13 15:25:40.344 +00:00 [WRN]: Value for LOG_LEVEL not found. Using defaultValue [information]
2019-08-13 15:25:40.347 +00:00 [INF]: Log Level: information
2019-08-13 15:25:40.348 +00:00 [WRN]: Value for BATCH_INTERVAL_MS not found. Using defaultValue [5000]



edge-agent logs
<Paste here>
edge-hub logs
<4> 2019-08-13 15:21:35.629 +00:00 [WRN] - Could not get an active Iot Hub connection for client abz-iotedge-01/opcMapper
<6> 2019-08-13 15:21:39.470 +00:00 [INF] - Attempting to connect to IoT Hub for client abz-iotedge-01/opcMapper via AMQP over WebSockets...
<6> 2019-08-13 15:21:40.068 +00:00 [INF] - Started task to cleanup processed and stale messages for endpoint abz-iotedge-01/iotHubRelay/input_raw
<6> 2019-08-13 15:21:42.402 +00:00 [INF] - Cleaned up 956 messages from queue for endpoint abz-iotedge-01/iotHubRelay/input_raw and 199 messages from message store.
<6> 2019-08-13 15:22:12.400 +00:00 [INF] - Started task to cleanup processed and stale messages for endpoint iothub
<6> 2019-08-13 15:22:14.122 +00:00 [INF] - Cleaned up 650 messages from queue for endpoint iothub and 650 messages from message store.
<4> 2019-08-13 15:22:39.473 +00:00 [WRN] - Error creating cloud connection for client abz-iotedge-01/opcMapper
Microsoft.Azure.Devices.Client.Exceptions.IotHubCommunicationException: The operation did not complete within the allocated time 00:01:00 for object session354. ---> System.TimeoutException: The operation did not complete within the allocated time 00:01:00 for object session354.
   at Microsoft.Azure.Amqp.AsyncResult.End[TAsyncResult](IAsyncResult result)
   at Microsoft.Azure.Amqp.AmqpObject.OpenAsyncResult.End(IAsyncResult result)
   at Microsoft.Azure.Amqp.AmqpObject.EndOpen(IAsyncResult result)
   at System.Threading.Tasks.TaskFactory`1.FromAsyncCoreLogic(IAsyncResult iar, Func`2 endFunction, Action`1 endAction, Task`1 promise, Boolean requiresSynchronization)
--- End of stack trace from previous location where exception was thrown ---
   at Microsoft.Azure.Devices.Client.Transport.Amqp.AmqpUnit.OpenAsync(TimeSpan timeout)
   at Microsoft.Azure.Devices.Client.Transport.Amqp.AmqpTransportHandler.OpenAsync(CancellationToken cancellationToken)
   --- End of inner exception stack trace ---
   at Microsoft.Azure.Devices.Client.Transport.Amqp.AmqpTransportHandler.OpenAsync(CancellationToken cancellationToken)
   at Microsoft.Azure.Devices.Client.Transport.ProtocolRoutingDelegatingHandler.OpenAsync(CancellationToken cancellationToken)
   at Microsoft.Azure.Devices.Client.Transport.ErrorDelegatingHandler.<>c__DisplayClass22_0.<<ExecuteWithErrorHandlingAsync>b__0>d.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at Microsoft.Azure.Devices.Client.Transport.ErrorDelegatingHandler.ExecuteWithErrorHandlingAsync[T](Func`1 asyncOperation)
   at Microsoft.Azure.Devices.Client.Transport.RetryDelegatingHandler.<>c__DisplayClass32_0.<<OpenAsyncInternal>b__0>d.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at Microsoft.Azure.Devices.Client.Transport.RetryDelegatingHandler.EnsureOpenedAsync(CancellationToken cancellationToken)
   at Microsoft.Azure.Devices.Client.InternalClient.OpenAsync()
   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
   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 174
--- 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 134
   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 162
   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
   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
   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
   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
--- End of stack trace from previous location where exception was thrown ---
   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
<6> 2019-08-13 15:22:39.489 +00:00 [INF] - Error getting cloud connection for device abz-iotedge-01/opcMapper
Microsoft.Azure.Devices.Client.Exceptions.IotHubCommunicationException: The operation did not complete within the allocated time 00:01:00 for object session354. ---> System.TimeoutException: The operation did not complete within the allocated time 00:01:00 for object session354.
   at Microsoft.Azure.Amqp.AsyncResult.End[TAsyncResult](IAsyncResult result)
   at Microsoft.Azure.Amqp.AmqpObject.OpenAsyncResult.End(IAsyncResult result)
   at Microsoft.Azure.Amqp.AmqpObject.EndOpen(IAsyncResult result)
   at System.Threading.Tasks.TaskFactory`1.FromAsyncCoreLogic(IAsyncResult iar, Func`2 endFunction, Action`1 endAction, Task`1 promise, Boolean requiresSynchronization)
--- End of stack trace from previous location where exception was thrown ---
   at Microsoft.Azure.Devices.Client.Transport.Amqp.AmqpUnit.OpenAsync(TimeSpan timeout)
   at Microsoft.Azure.Devices.Client.Transport.Amqp.AmqpTransportHandler.OpenAsync(CancellationToken cancellationToken)
   --- End of inner exception stack trace ---
   at Microsoft.Azure.Devices.Client.Transport.Amqp.AmqpTransportHandler.OpenAsync(CancellationToken cancellationToken)
   at Microsoft.Azure.Devices.Client.Transport.ProtocolRoutingDelegatingHandler.OpenAsync(CancellationToken cancellationToken)
   at Microsoft.Azure.Devices.Client.Transport.ErrorDelegatingHandler.<>c__DisplayClass22_0.<<ExecuteWithErrorHandlingAsync>b__0>d.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at Microsoft.Azure.Devices.Client.Transport.ErrorDelegatingHandler.ExecuteWithErrorHandlingAsync[T](Func`1 asyncOperation)
   at Microsoft.Azure.Devices.Client.Transport.RetryDelegatingHandler.<>c__DisplayClass32_0.<<OpenAsyncInternal>b__0>d.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at Microsoft.Azure.Devices.Client.Transport.RetryDelegatingHandler.EnsureOpenedAsync(CancellationToken cancellationToken)
   at Microsoft.Azure.Devices.Client.InternalClient.OpenAsync()
   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
   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 174
--- 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 134
   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 162
   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
   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
   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
   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
--- End of stack trace from previous location where exception was thrown ---
   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
<4> 2019-08-13 15:22:39.500 +00:00 [WRN] - Could not get an active Iot Hub connection for client abz-iotedge-01/opcMapper
<6> 2019-08-13 15:22:44.120 +00:00 [INF] - Started task to cleanup processed and stale messages for endpoint abz-iotedge-01/opcMapper/input_MapMessage
<6> 2019-08-13 15:22:45.897 +00:00 [INF] - Cleaned up 477 messages from queue for endpoint abz-iotedge-01/opcMapper/input_MapMessage and 477 messages from message store.
<6> 2019-08-13 15:22:47.673 +00:00 [INF] - Attempting to connect to IoT Hub for client abz-iotedge-01/opcMapper via AMQP over WebSockets...
<6> 2019-08-13 15:23:32.331 +00:00 [INF] - Retrying cloud proxy operation UpdateReportedPropertiesAsync for abz-iotedge-01/$edgeHub.
Microsoft.Azure.Devices.Client.Exceptions.IotHubCommunicationException: The operation has timed out. ---> System.TimeoutException: The operation has timed out.
   at Microsoft.Azure.Devices.Client.Transport.Amqp.AmqpTransportHandler.RoundTripTwinMessage(AmqpMessage amqpMessage, CancellationToken cancellationToken)
   at Microsoft.Azure.Devices.Client.Transport.Amqp.AmqpTransportHandler.SendTwinPatchAsync(TwinCollection reportedProperties, CancellationToken cancellationToken)
   --- End of inner exception stack trace ---
   at Microsoft.Azure.Devices.Client.Transport.Amqp.AmqpTransportHandler.SendTwinPatchAsync(TwinCollection reportedProperties, CancellationToken cancellationToken)
   at Microsoft.Azure.Devices.Client.Transport.ErrorDelegatingHandler.<>c__DisplayClass22_0.<<ExecuteWithErrorHandlingAsync>b__0>d.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at Microsoft.Azure.Devices.Client.Transport.ErrorDelegatingHandler.ExecuteWithErrorHandlingAsync[T](Func`1 asyncOperation)
   at Microsoft.Azure.Devices.Client.Transport.RetryDelegatingHandler.<>c__DisplayClass25_0.<<SendTwinPatchAsync>b__0>d.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at Microsoft.Azure.Devices.Client.Transport.RetryDelegatingHandler.SendTwinPatchAsync(TwinCollection reportedProperties, CancellationToken cancellationToken)
   at Microsoft.Azure.Devices.Client.InternalClient.UpdateReportedPropertiesAsync(TwinCollection reportedProperties)
   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 174
--- 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 134
   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 162
   at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudProxy.UpdateReportedPropertiesAsync(IMessage reportedPropertiesMessage) in /home/vsts/work/1/s/edge-hub/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/CloudProxy.cs:line 171
   at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudProxy.UpdateReportedPropertiesAsync(IMessage reportedPropertiesMessage) in /home/vsts/work/1/s/edge-hub/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/CloudProxy.cs:line 177
   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
--- End of stack trace from previous location where exception was thrown ---
   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
<6> 2019-08-13 15:23:32.346 +00:00 [INF] - Attempting to connect to IoT Hub for client abz-iotedge-01/$edgeHub via AMQP over WebSockets...
<4> 2019-08-13 15:23:47.680 +00:00 [WRN] - Error creating cloud connection for client abz-iotedge-01/opcMapper
Microsoft.Azure.Devices.Client.Exceptions.IotHubCommunicationException: The operation did not complete within the allocated time 00:01:00 for object session355. ---> System.TimeoutException: The operation did not complete within the allocated time 00:01:00 for object session355.
   at Microsoft.Azure.Amqp.AsyncResult.End[TAsyncResult](IAsyncResult result)
   at Microsoft.Azure.Amqp.AmqpObject.OpenAsyncResult.End(IAsyncResult result)
   at Microsoft.Azure.Amqp.AmqpObject.EndOpen(IAsyncResult result)
   at System.Threading.Tasks.TaskFactory`1.FromAsyncCoreLogic(IAsyncResult iar, Func`2 endFunction, Action`1 endAction, Task`1 promise, Boolean requiresSynchronization)
--- End of stack trace from previous location where exception was thrown ---
   at Microsoft.Azure.Devices.Client.Transport.Amqp.AmqpUnit.OpenAsync(TimeSpan timeout)
   at Microsoft.Azure.Devices.Client.Transport.Amqp.AmqpTransportHandler.OpenAsync(CancellationToken cancellationToken)
   --- End of inner exception stack trace ---
   at Microsoft.Azure.Devices.Client.Transport.Amqp.AmqpTransportHandler.OpenAsync(CancellationToken cancellationToken)
   at Microsoft.Azure.Devices.Client.Transport.ProtocolRoutingDelegatingHandler.OpenAsync(CancellationToken cancellationToken)
   at Microsoft.Azure.Devices.Client.Transport.ErrorDelegatingHandler.<>c__DisplayClass22_0.<<ExecuteWithErrorHandlingAsync>b__0>d.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at Microsoft.Azure.Devices.Client.Transport.ErrorDelegatingHandler.ExecuteWithErrorHandlingAsync[T](Func`1 asyncOperation)
   at Microsoft.Azure.Devices.Client.Transport.RetryDelegatingHandler.<>c__DisplayClass32_0.<<OpenAsyncInternal>b__0>d.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at Microsoft.Azure.Devices.Client.Transport.RetryDelegatingHandler.EnsureOpenedAsync(CancellationToken cancellationToken)
   at Microsoft.Azure.Devices.Client.InternalClient.OpenAsync()
   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
   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 174
--- 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 134
   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 162
   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
   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
   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
   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
--- End of stack trace from previous location where exception was thrown ---
   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
<6> 2019-08-13 15:23:47.693 +00:00 [INF] - Error getting cloud connection for device abz-iotedge-01/opcMapper
Microsoft.Azure.Devices.Client.Exceptions.IotHubCommunicationException: The operation did not complete within the allocated time 00:01:00 for object session355. ---> System.TimeoutException: The operation did not complete within the allocated time 00:01:00 for object session355.
   at Microsoft.Azure.Amqp.AsyncResult.End[TAsyncResult](IAsyncResult result)
   at Microsoft.Azure.Amqp.AmqpObject.OpenAsyncResult.End(IAsyncResult result)
   at Microsoft.Azure.Amqp.AmqpObject.EndOpen(IAsyncResult result)
   at System.Threading.Tasks.TaskFactory`1.FromAsyncCoreLogic(IAsyncResult iar, Func`2 endFunction, Action`1 endAction, Task`1 promise, Boolean requiresSynchronization)
--- End of stack trace from previous location where exception was thrown ---
   at Microsoft.Azure.Devices.Client.Transport.Amqp.AmqpUnit.OpenAsync(TimeSpan timeout)
   at Microsoft.Azure.Devices.Client.Transport.Amqp.AmqpTransportHandler.OpenAsync(CancellationToken cancellationToken)
   --- End of inner exception stack trace ---
   at Microsoft.Azure.Devices.Client.Transport.Amqp.AmqpTransportHandler.OpenAsync(CancellationToken cancellationToken)
   at Microsoft.Azure.Devices.Client.Transport.ProtocolRoutingDelegatingHandler.OpenAsync(CancellationToken cancellationToken)
   at Microsoft.Azure.Devices.Client.Transport.ErrorDelegatingHandler.<>c__DisplayClass22_0.<<ExecuteWithErrorHandlingAsync>b__0>d.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at Microsoft.Azure.Devices.Client.Transport.ErrorDelegatingHandler.ExecuteWithErrorHandlingAsync[T](Func`1 asyncOperation)
   at Microsoft.Azure.Devices.Client.Transport.RetryDelegatingHandler.<>c__DisplayClass32_0.<<OpenAsyncInternal>b__0>d.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at Microsoft.Azure.Devices.Client.Transport.RetryDelegatingHandler.EnsureOpenedAsync(CancellationToken cancellationToken)
   at Microsoft.Azure.Devices.Client.InternalClient.OpenAsync()
   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
   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 174
--- 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 134
   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 162
   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
   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
   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
   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
--- End of stack trace from previous location where exception was thrown ---
   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
<4> 2019-08-13 15:23:47.702 +00:00 [WRN] - Could not get an active Iot Hub connection for client abz-iotedge-01/opcMapper
<6> 2019-08-13 15:24:02.020 +00:00 [INF] - Attempting to connect to IoT Hub for client abz-iotedge-01/opcMapper via AMQP over WebSockets...
<4> 2019-08-13 15:24:32.347 +00:00 [WRN] - Error creating cloud connection for client abz-iotedge-01/$edgeHub
Microsoft.Azure.Devices.Client.Exceptions.IotHubCommunicationException: The operation did not complete within the allocated time 00:01:00 for object session356. ---> System.TimeoutException: The operation did not complete within the allocated time 00:01:00 for object session356.
   at Microsoft.Azure.Amqp.AsyncResult.End[TAsyncResult](IAsyncResult result)
   at Microsoft.Azure.Amqp.AmqpObject.OpenAsyncResult.End(IAsyncResult result)
   at Microsoft.Azure.Amqp.AmqpObject.EndOpen(IAsyncResult result)
   at System.Threading.Tasks.TaskFactory`1.FromAsyncCoreLogic(IAsyncResult iar, Func`2 endFunction, Action`1 endAction, Task`1 promise, Boolean requiresSynchronization)
--- End of stack trace from previous location where exception was thrown ---
   at Microsoft.Azure.Devices.Client.Transport.Amqp.AmqpUnit.OpenAsync(TimeSpan timeout)
   at Microsoft.Azure.Devices.Client.Transport.Amqp.AmqpTransportHandler.OpenAsync(CancellationToken cancellationToken)
   --- End of inner exception stack trace ---
   at Microsoft.Azure.Devices.Client.Transport.Amqp.AmqpTransportHandler.OpenAsync(CancellationToken cancellationToken)
   at Microsoft.Azure.Devices.Client.Transport.ProtocolRoutingDelegatingHandler.OpenAsync(CancellationToken cancellationToken)
   at Microsoft.Azure.Devices.Client.Transport.ErrorDelegatingHandler.<>c__DisplayClass22_0.<<ExecuteWithErrorHandlingAsync>b__0>d.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at Microsoft.Azure.Devices.Client.Transport.ErrorDelegatingHandler.ExecuteWithErrorHandlingAsync[T](Func`1 asyncOperation)
   at Microsoft.Azure.Devices.Client.Transport.RetryDelegatingHandler.<>c__DisplayClass32_0.<<OpenAsyncInternal>b__0>d.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at Microsoft.Azure.Devices.Client.Transport.RetryDelegatingHandler.EnsureOpenedAsync(CancellationToken cancellationToken)
   at Microsoft.Azure.Devices.Client.InternalClient.OpenAsync()
   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
   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 174
--- 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 134
   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 162
   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
   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
   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
   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
--- End of stack trace from previous location where exception was thrown ---
   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
<6> 2019-08-13 15:24:32.362 +00:00 [INF] - Error getting cloud connection for device abz-iotedge-01/$edgeHub
Microsoft.Azure.Devices.Client.Exceptions.IotHubCommunicationException: The operation did not complete within the allocated time 00:01:00 for object session356. ---> System.TimeoutException: The operation did not complete within the allocated time 00:01:00 for object session356.
   at Microsoft.Azure.Amqp.AsyncResult.End[TAsyncResult](IAsyncResult result)
   at Microsoft.Azure.Amqp.AmqpObject.OpenAsyncResult.End(IAsyncResult result)
   at Microsoft.Azure.Amqp.AmqpObject.EndOpen(IAsyncResult result)
   at System.Threading.Tasks.TaskFactory`1.FromAsyncCoreLogic(IAsyncResult iar, Func`2 endFunction, Action`1 endAction, Task`1 promise, Boolean requiresSynchronization)
--- End of stack trace from previous location where exception was thrown ---
   at Microsoft.Azure.Devices.Client.Transport.Amqp.AmqpUnit.OpenAsync(TimeSpan timeout)
   at Microsoft.Azure.Devices.Client.Transport.Amqp.AmqpTransportHandler.OpenAsync(CancellationToken cancellationToken)
   --- End of inner exception stack trace ---
   at Microsoft.Azure.Devices.Client.Transport.Amqp.AmqpTransportHandler.OpenAsync(CancellationToken cancellationToken)
   at Microsoft.Azure.Devices.Client.Transport.ProtocolRoutingDelegatingHandler.OpenAsync(CancellationToken cancellationToken)
   at Microsoft.Azure.Devices.Client.Transport.ErrorDelegatingHandler.<>c__DisplayClass22_0.<<ExecuteWithErrorHandlingAsync>b__0>d.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at Microsoft.Azure.Devices.Client.Transport.ErrorDelegatingHandler.ExecuteWithErrorHandlingAsync[T](Func`1 asyncOperation)
   at Microsoft.Azure.Devices.Client.Transport.RetryDelegatingHandler.<>c__DisplayClass32_0.<<OpenAsyncInternal>b__0>d.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at Microsoft.Azure.Devices.Client.Transport.RetryDelegatingHandler.EnsureOpenedAsync(CancellationToken cancellationToken)
   at Microsoft.Azure.Devices.Client.InternalClient.OpenAsync()
   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
   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 174
--- 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 134
   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 162
   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
   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
   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
   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
--- End of stack trace from previous location where exception was thrown ---
   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
<4> 2019-08-13 15:24:32.374 +00:00 [WRN] - Error calling IotHub for connectivity test
Microsoft.Azure.Devices.Edge.Hub.Core.EdgeHubIOException: Unable to create IoTHub connection ---> Microsoft.Azure.Devices.Client.Exceptions.IotHubCommunicationException: The operation did not complete within the allocated time 00:01:00 for object session356. ---> System.TimeoutException: The operation did not complete within the allocated time 00:01:00 for object session356.
   at Microsoft.Azure.Amqp.AsyncResult.End[TAsyncResult](IAsyncResult result)
   at Microsoft.Azure.Amqp.AmqpObject.OpenAsyncResult.End(IAsyncResult result)
   at Microsoft.Azure.Amqp.AmqpObject.EndOpen(IAsyncResult result)
   at System.Threading.Tasks.TaskFactory`1.FromAsyncCoreLogic(IAsyncResult iar, Func`2 endFunction, Action`1 endAction, Task`1 promise, Boolean requiresSynchronization)

Additional Information

@damonbarry
Copy link
Member

damonbarry commented Aug 30, 2019

@grzegorski Can you attach the full logs (drag and drop the files into a comment here) for edge hub and edge agent? The excerpt above shows that edge hub is having difficulty connecting (presumably because the network is unstable), but we need more context.

It would also be great to get more verbose debug logs for edge hub, but that would require reproducing the scenario again, and the log files would be a lot bigger.

Finally, when you say your module loses desired properties, is this the scenario?

  • Edge Hub establishes upstream connection
  • Module connects to Edge Hub
  • Module calls client.GetTwinAsync
  • Returned JSON includes:
    {
      "properties": {
        "desired": {
          "abc": 123,
          "xyz": 789
        }
      }
    }
    
  • Edge Hub loses upstream connection for some period of time
  • Edge Hub restores upstream connection
  • Module calls client.GetTwinAsync
  • Returned JSON is missing property properties.desired.abc:
    {
      "properties": {
        "desired": {
          "xyz": 789
        }
      }
    }
    

@bjorndeq
Copy link

bjorndeq commented Sep 3, 2019

We have experienced the same issue in a few of our running modules (not all of them) last weekend.
The device has been running for months and we have not seen this behavior yet, we updated from 1.0.7 to 1.0.8 last week.
The modules that lost their desired properties lost all of them.
Restarting the modules fixed the problem for now.
The EdgeAgent and EdgeHub are running on version 1.0.8.23694809

@arsing arsing added the needinfo Needs more info from issue reporter / updates from PR submitter label Sep 3, 2019
@grzegorski
Copy link
Author

@grzegorski
Copy link
Author

grzegorski commented Sep 5, 2019

The same has been observed again on other IoT Edge Device. Our module lost all the desired properties and stopped processing messages after EdgeHub lost connection with the cloud (over AMQP WebSocets).
edgeHub050919.log
edgeAgent050919.log

Another site this morning:
edgeHub.log
edgeAgent.log
opcMapper.log

<6> 2019-09-05 07:07:59.051 +00:00 [INF] - Retrying cloud proxy operation UpdateReportedPropertiesAsync for 1002-kilbourn-iotedge-01/$edgeHub.
Microsoft.Azure.Devices.Client.Exceptions.IotHubCommunicationException: The operation has timed out. ---> System.TimeoutException: The operation has timed out.
at Microsoft.Azure.Devices.Client.Transport.Amqp.AmqpTransportHandler.RoundTripTwinMessage(AmqpMessage amqpMessage, CancellationToken cancellationToken)
at Microsoft.Azure.Devices.Client.Transport.Amqp.AmqpTransportHandler.SendTwinPatchAsync(TwinCollection reportedProperties, CancellationToken cancellationToken)
--- End of inner exception stack trace ---
at Microsoft.Azure.Devices.Client.Transport.Amqp.AmqpTransportHandler.SendTwinPatchAsync(TwinCollection reportedProperties, CancellationToken cancellationToken)
at Microsoft.Azure.Devices.Client.Transport.ErrorDelegatingHandler.<>c__DisplayClass22_0.<b__0>d.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
at Microsoft.Azure.Devices.Client.Transport.ErrorDelegatingHandler.ExecuteWithErrorHandlingAsync[T](Func`1 asyncOperation)
at Microsoft.Azure.Devices.Client.Transport.RetryDelegatingHandler.<>c__DisplayClass25_0.<b__0>d.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
(..)

Custom Module Logs:

2019-09-05 07:04:06.793 +00:00 [WRN]: Value for LOG_LEVEL not found. Using defaultValue [information]
2019-09-05 07:04:06.794 +00:00 [INF]: Log Level: information
2019-09-05 07:04:06.794 +00:00 [WRN]: Value for BATCH_INTERVAL_MS not found. Using defaultValue [5000]
2019-09-05 07:04:06.794 +00:00 [INF]: Batch Interval (ms): 5000
2019-09-05 07:04:06.794 +00:00 [WRN]: Value for BATCH_COUNT not found. Using defaultValue [500]
2019-09-05 07:04:06.794 +00:00 [INF]: Batch Count: 500
2019-09-05 07:04:06.794 +00:00 [WRN]: Value for BATCH_SIZE_KB not found. Using defaultValue [250]
2019-09-05 07:04:06.794 +00:00 [INF]: Batch Size (kb): 250
2019-09-05 07:04:06.794 +00:00 [WRN]: Value for COMPRESS not found. Using defaultValue [True]
2019-09-05 07:04:06.794 +00:00 [INF]: Compress: true
2019-09-05 07:04:06.794 +00:00 [WRN]: Value for IOT_MESSAGE_VERSION not found. Using defaultValue [1]
2019-09-05 07:04:06.794 +00:00 [INF]: IoT Message Version: 1

Unhandled Exception: System.AggregateException: One or more errors occurred. (The CancellationTokenSource has been disposed.) ---> System.ObjectDisposedException: The CancellationTokenSource has been disposed.
at System.Threading.CancellationTokenSource.ThrowObjectDisposedException()
at OpcMapper.Program.SendMessages() in /app/Program.cs:line 309
at OpcMapper.Program.<>c.b__14_0(Object s) in /app/Program.cs:line 63
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.CancellationTokenSource.ExecuteCallbackHandlers(Boolean throwOnFirstException)
--- End of inner exception stack trace ---
at System.Threading.CancellationTokenSource.ExecuteCallbackHandlers(Boolean throwOnFirstException)
2019-09-05 10:23:05.866 +00:00 [INF]: IoT Hub module client initialized.

@damonbarry
Copy link
Member

@grzegorski I'm looking at the logs right now. Question: what version of the device SDK (Microsoft.Azure.Devices.Client) are you using in each of your modules (iotHubRelay, opcMapper, opcPublisher, tmgHeartbeat)?

@damonbarry
Copy link
Member

Looking at the last logs you uploaded (edgeAgent.log, edgeHub.log, opcMapper.log), I don't see any obvious problems in Edge Hub. Here's a timeline of events in the log, as far as I can tell:

Timestamp Event Notes
09-05 07:04:00 Lost cloud connection
09-05 07:04:06 Reestablished cloud connection
09-05 07:07:59 UpdateReportedPropertiesAsync failed for $edgeHub, retry... Appears to be a normal network hiccup, which we recover from
09-05 10:22:56 opcMapper module terminates connection to Edge Hub opcMapper module crashed due to ObjectDisposedException
09-05 10:23:05 opcMapper module reconnects to Edge Hub
09-05 10:24:05 iotHubRelay module disconnects from Edge Hub Perhaps iotHubRelay crashed, or was manually restarted? Hard to tell without logs...
09-05 10:24:13 iotHubRelay module reconnects to Edge Hub
09-05 10:31:16 Edge Hub & Agent modules restarted Looks like user intervention, e.g., systemctl stop iotedge
09-05 10:31:51 Edge Hub restarts systemctl start iotedged?

It would be good to address the ObjectDisposedException in opcMapper, but I'm not convinced that's contributing to your problem.

Are these warnings in opcMapper.log the reason why you say desired properties are being lost?

2019-09-05 07:04:06.793 +00:00 [WRN]: Value for LOG_LEVEL not found. Using defaultValue [information]
2019-09-05 07:04:06.794 +00:00 [WRN]: Value for BATCH_INTERVAL_MS not found. Using defaultValue [5000]
2019-09-05 07:04:06.794 +00:00 [WRN]: Value for BATCH_COUNT not found. Using defaultValue [500]
2019-09-05 07:04:06.794 +00:00 [WRN]: Value for BATCH_SIZE_KB not found. Using defaultValue [250]
2019-09-05 07:04:06.794 +00:00 [WRN]: Value for COMPRESS not found. Using defaultValue [True]
2019-09-05 07:04:06.794 +00:00 [WRN]: Value for IOT_MESSAGE_VERSION not found. Using defaultValue [1]

@sachidanand
Copy link

We are also facing same issue ... so is there any update on this fix ??

@github-actions
Copy link

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

@lt72
Copy link

lt72 commented Nov 6, 2019

@varunpuranik can you please take a look at this one?

@damonbarry
Copy link
Member

Based on the information in this issue, I don't think edge hub is actually losing desired properties. Rather I think the custom module (opcMapper) isn't handling twin updates as robustly as it should.

Specifically, the callback that receives incremental updates to the twin desired properties is only useful if you already have the previous version of the twin to compare against. So if you ever disconnect/reconnect, or if you discover a discontinuity in the twin version field, you need to get the full twin again. A great example of this can be found in our Edge Agent. The callback function that we register with the SDK (by calling ModuleClient.SetDesiredPropertyUpdateCallbackAsync) can be found here:

async Task OnDesiredPropertiesUpdated(TwinCollection desiredPropertiesPatch, object userContext)

In general, the algorithm we use to keep an up-to-date copy of desired properties is:

  • Get the full twin when the module first starts
  • Get the full twin at some interval afterward (we have a periodic task set up to do this, defaults to one hour)
  • Register a callback to receive twin update patches
  • When a patch is received:
    • Check its version. If the version is not currentVersion + 1, abandon the patch and do a full twin update
    • If the version is currentVersion + 1, merge the patch with your current copy of the twin (we use Newtonsoft.Json to do this)

The file EdgeAgentConnection.cs has nearly all the code to do this, and is fairly well organized. You should be able to adapt it to your needs pretty easily.

@lt72 lt72 added the area:edgehub Issue with Edge Hub label Nov 7, 2019
@grzegorski
Copy link
Author

grzegorski commented Nov 8, 2019

@damonbarry We observed issue today again. Our modules handle now the desired properties update and they didn't fail but EdgeHub and Edge Agent failed to update desired properties and stopped sending anything to the cloud. At the same time IoT Hub reported all connections to be OK.
See issue: #1974

@damonbarry
Copy link
Member

@grzegorski Thanks for opening #1974; we can track this latest instance in that issue.

@lt72
Copy link

lt72 commented Dec 5, 2019

Closing for now, using #1974 to track, please re-open as needed.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
area:edgehub Issue with Edge Hub customer-reported iotedge needinfo Needs more info from issue reporter / updates from PR submitter
Projects
None yet
Development

No branches or pull requests

7 participants