Azure / Azure/iotedge

Edge Hub removes module connection

Open
#4,678 13 comments 0 reactions 1 assignee Claimed by @vipeller View on GitHub
1.0.10 area:connectivity customer-reported iotedge no-issue-activity
Dominant language
C#
Stars
1.5k
Forks
473
Avg merge
2d 17h
Merged PRs (30d)
7

Description

### Preamble
I have many Edge devices working on production environment.
Every device has many modules that send data to the upstream and one module (named `apiconnector`) that sends the upstream to another API.

## The Problem
Since an upgrade to the version 1.0.10, I get sporadically errors regarding the apiconnector module.
The module is running but the input stream get cut from the edgeHub.
I saw in the logfile from edgeHub that the problem may be related to an error while updating the identity token.
Otherwise there is no retry procedure for such an error even if the edgeHub writes a warning every minutes that a module is disconnected.

## Expected Behavior
Running Edge modules receive the input stream in a reliable way. A transient update error for identity tokens doesn't effect the behavior of the modules.
After an error occurs the edgeHub should try to restore the an healthy state or report the error (for example to the edgeAgent)

## Current Behavior
An Edge module get disconnected from its input stream, but keep be running.

## Steps to Reproduce
Unable to reproduce... 😢

## Context (Environment)

(sorry, I cannot fill in all these Information, but I will give an update)

### Device Information
* Host OS [e.g. Ubuntu 18.04, Windows Server IoT 2019]: Windows 10 1803 Build 17763
* Architecture [e.g. amd64, arm32, arm64]: amd64
* Container OS [e.g. Linux containers, Windows containers]: Windows containers

### Runtime Versions
* aziot-edged [run `iotedge version`]:
* Edge Agent [image tag (e.g. 1.0.0)]: 1.0.10.4
* Edge Hub [image tag (e.g. 1.0.0)]: 1.0.10.4
* Docker/Moby [run `docker version`]: ?

Note: when using Windows containers on Windows, run `docker -H npipe:////./pipe/iotedge_moby_engine version` instead

## Logs

edge-hub logs

```

<6> 2021-03-22 13:23:01.039 +01:00 [INF] - Request starting HTTP/1.1 GET http://172.22.185.99:9600/metrics
<6> 2021-03-22 13:23:01.048 +01:00 [INF] - Request finished in 8.5752ms 200 text/plain; version=0.0.4; charset=utf-8
<6> 2021-03-22 13:26:07.889 +01:00 [INF] - Starting compaction of stores
<6> 2021-03-22 13:26:07.889 +01:00 [INF] - Starting compaction of store MetadataStore
<6> 2021-03-22 13:26:07.889 +01:00 [INF] - Starting compaction of store twins
<6> 2021-03-22 13:26:07.889 +01:00 [INF] - Starting compaction of store checkpoints
<6> 2021-03-22 13:26:07.890 +01:00 [INF] - Starting compaction of store GP731/apiconnector/input
<6> 2021-03-22 13:26:07.890 +01:00 [INF] - Starting compaction of store default
<6> 2021-03-22 13:26:07.890 +01:00 [INF] - Starting compaction of store iothub
<6> 2021-03-22 13:26:07.890 +01:00 [INF] - Starting compaction of store messages
<6> 2021-03-22 13:26:07.890 +01:00 [INF] - Starting compaction of store EdgeTwin
<6> 2021-03-22 13:26:07.890 +01:00 [INF] - Starting compaction of store sessions
<6> 2021-03-22 13:26:07.890 +01:00 [INF] - Starting compaction of store DeviceScopeCache
<6> 2021-03-22 13:26:09.150 +01:00 [INF] - Entering periodic task to reauthenticate connected clients
<6> 2021-03-22 13:27:27.981 +01:00 [INF] - Starting periodic operation Get EdgeHub config...
<6> 2021-03-22 13:27:28.107 +01:00 [INF] - Obtained edge hub config from module twin
<6> 2021-03-22 13:27:28.124 +01:00 [INF] - Set the following 2 route(s) in edge hub
<6> 2021-03-22 13:27:28.125 +01:00 [INF] - upstream: FROM /messages/modules/* INTO $upstream
<6> 2021-03-22 13:27:28.125 +01:00 [INF] - apiconnector: FROM /messages/modules/* INTO BrokeredEndpoint(\"/modules/apiconnector/inputs/input\")
<6> 2021-03-22 13:27:28.125 +01:00 [INF] - Updated message store TTL to 86400 seconds
<6> 2021-03-22 13:27:28.125 +01:00 [INF] - Updated the edge hub store and forward configuration
<6> 2021-03-22 13:27:28.125 +01:00 [INF] - Successfully completed periodic operation Get EdgeHub config
<6> 2021-03-22 13:27:28.282 +01:00 [INF] - Updated reported properties for GP731/$edgeHub
<6> 2021-03-22 13:31:09.142 +01:00 [INF] - Entering periodic task to reauthenticate connected clients
<6> 2021-03-22 13:36:09.158 +01:00 [INF] - Entering periodic task to reauthenticate connected clients
<6> 2021-03-22 13:38:57.088 +01:00 [INF] - New token received on the Cbs link
<6> 2021-03-22 13:38:57.088 +01:00 [INF] - Token updated for GP731/strippingribbedhose
<6> 2021-03-22 13:39:10.071 +01:00 [INF] - New token received on the Cbs link
<6> 2021-03-22 13:39:10.072 +01:00 [INF] - Token updated for GP731/localapi
<6> 2021-03-22 13:39:25.100 +01:00 [INF] - New token received on the Cbs link
<6> 2021-03-22 13:39:25.100 +01:00 [INF] - Token updated for GP731/coilmachine
<6> 2021-03-22 13:39:45.066 +01:00 [INF] - New token received on the Cbs link
<6> 2021-03-22 13:39:45.067 +01:00 [INF] - Token updated for GP731/weld
<6> 2021-03-22 13:40:07.042 +01:00 [INF] - New token requested by client GP731/strippingribbedhose, but using existing token as it is usable.
<6> 2021-03-22 13:40:20.054 +01:00 [INF] - New token requested by client GP731/localapi, but using existing token as it is usable.
<6> 2021-03-22 13:40:55.039 +01:00 [INF] - New token requested by client GP731/weld, but using existing token as it is usable.
<6> 2021-03-22 13:41:09.151 +01:00 [INF] - Entering periodic task to reauthenticate connected clients
<6> 2021-03-22 13:41:21.089 +01:00 [INF] - New token received on the Cbs link
<6> 2021-03-22 13:41:21.089 +01:00 [INF] - Token updated for GP731/newprogram
<6> 2021-03-22 13:41:33.072 +01:00 [INF] - New token received on the Cbs link
<6> 2021-03-22 13:41:33.073 +01:00 [INF] - Token updated for GP731/systemstate
<6> 2021-03-22 13:42:51.370 +01:00 [INF] - Started task to cleanup processed and stale messages for endpoint GP731/apiconnector/input
<6> 2021-03-22 13:42:53.090 +01:00 [INF] - Cleaned up 5472 messages from queue for endpoint GP731/apiconnector/input and 104 messages from message store.
<6> 2021-03-22 13:43:23.103 +01:00 [INF] - Started task to cleanup processed and stale messages for endpoint iothub
<6> 2021-03-22 13:43:25.116 +01:00 [INF] - Cleaned up 5478 messages from queue for endpoint iothub and 5368 messages from message store.
<6> 2021-03-22 13:46:09.153 +01:00 [INF] - Entering periodic task to reauthenticate connected clients
<6> 2021-03-22 13:46:46.013 +01:00 [INF] - Existing token not found for GP731/strippingribbedhose. Getting new token from the client...
<6> 2021-03-22 13:46:46.013 +01:00 [INF] - Connection status for GP731/strippingribbedhose changed to TokenNearExpiry
<6> 2021-03-22 13:46:46.014 +01:00 [INF] - Obtained new token for client GP731/strippingribbedhose that expires in 00:52:10.9859210
<6> 2021-03-22 13:46:59.013 +01:00 [INF] - Existing token not found for GP731/localapi. Getting new token from the client...
<6> 2021-03-22 13:46:59.013 +01:00 [INF] - Connection status for GP731/localapi changed to TokenNearExpiry
<6> 2021-03-22 13:46:59.016 +01:00 [INF] - Obtained new token for client GP731/localapi that expires in 00:52:10.9838802
<6> 2021-03-22 13:47:34.012 +01:00 [INF] - Existing token not found for GP731/weld. Getting new token from the client...
<6> 2021-03-22 13:47:34.013 +01:00 [INF] - Connection status for GP731/weld changed to TokenNearExpiry
<6> 2021-03-22 13:47:34.013 +01:00 [INF] - Obtained new token for client GP731/weld that expires in 00:52:10.9868077
<6> 2021-03-22 13:51:09.172 +01:00 [INF] - Entering periodic task to reauthenticate connected clients
<6> 2021-03-22 13:54:11.263 +01:00 [INF] - Starting refresh of device scope identities cache
<6> 2021-03-22 13:55:24.091 +01:00 [INF] - New token received on the Cbs link
<6> 2021-03-22 13:55:24.091 +01:00 [INF] - Token updated for GP731/apiconnector
<6> 2021-03-22 13:56:09.177 +01:00 [INF] - Entering periodic task to reauthenticate connected clients
<4> 2021-03-22 13:59:12.436 +01:00 [WRN] - Error while processing the service identity for GP731/apiconnector
System.TimeoutException: Operation timed out
at Microsoft.Azure.Devices.Edge.Util.TaskEx.TimeoutAfter[T](Task`1 task, TimeSpan timeout) in C:\\agent\\_work\\9\\s\\edge-util\\src\\Microsoft.Azure.Devices.Edge.Util\\TaskEx.cs:line 128
at Microsoft.Azure.Devices.Edge.Util.Edged.WorkloadClientVersioned.Execute[T](Func`1 func, String operation) in C:\\agent\\_work\\9\\s\\edge-util\\src\\Microsoft.Azure.Devices.Edge.Util\\edged\\WorkloadClientVersioned.cs:line 79
at Microsoft.Azure.Devices.Edge.Util.Edged.Version_2019_01_30.WorkloadClient.HandleException(Exception ex, String operation) in C:\\agent\\_work\\9\\s\\edge-util\\src\\Microsoft.Azure.Devices.Edge.Util\\edged\\version_2019_01_30\\WorkloadClient.cs:line 122
at Microsoft.Azure.Devices.Edge.Util.Edged.WorkloadClientVersioned.Execute[T](Func`1 func, String operation) in C:\\agent\\_work\\9\\s\\edge-util\\src\\Microsoft.Azure.Devices.Edge.Util\\edged\\WorkloadClientVersioned.cs:line 79
at Microsoft.Azure.Devices.Edge.Util.Edged.Version_2019_01_30.WorkloadClient.EncryptAsync(String initializationVector, String plainText) in C:\\agent\\_work\\9\\s\\edge-util\\src\\Microsoft.Azure.Devices.Edge.Util\\edged\\version_2019_01_30\\WorkloadClient.cs:line 67
at Microsoft.Azure.Devices.Edge.Storage.EncryptedStore`2.Put(TK key, TV value, CancellationToken cancellationToken) in C:\\agent\\_work\\9\\s\\edge-util\\src\\Microsoft.Azure.Devices.Edge.Storage\\EncryptedStore.cs:line 42
at Microsoft.Azure.Devices.Edge.Hub.Core.DeviceScopeIdentitiesCache.SaveServiceIdentityToStore(String id, StoredServiceIdentity storedServiceIdentity) in C:\\agent\\_work\\9\\s\\edge-hub\\src\\Microsoft.Azure.Devices.Edge.Hub.Core\\DeviceScopeIdentitiesCache.cs:line 262
at Microsoft.Azure.Devices.Edge.Hub.Core.DeviceScopeIdentitiesCache.HandleNewServiceIdentity(ServiceIdentity serviceIdentity) in C:\\agent\\_work\\9\\s\\edge-hub\\src\\Microsoft.Azure.Devices.Edge.Hub.Core\\DeviceScopeIdentitiesCache.cs:line 256
at Microsoft.Azure.Devices.Edge.Hub.Core.DeviceScopeIdentitiesCache.RefreshCache() in C:\\agent\\_work\\9\\s\\edge-hub\\src\\Microsoft.Azure.Devices.Edge.Hub.Core\\DeviceScopeIdentitiesCache.cs:line 167
<6> 2021-03-22 13:59:12.560 +01:00 [INF] - Service identity for GP731/apiconnector was removed from device scope, dropping client connection.
<6> 2021-03-22 13:59:12.560 +01:00 [INF] - Removing device connection for device GP731/apiconnector with removeCloudConnection flag 'True'.
<6> 2021-03-22 13:59:12.560 +01:00 [INF] - Closing AMQP device proxy for GP731/apiconnector because no handler was registered.
Microsoft.Azure.Devices.Edge.Hub.Core.EdgeHubConnectionException: Connection closed for device GP731/apiconnector.
<6> 2021-03-22 13:59:12.566 +01:00 [INF] - Closing link Events for GP731/apiconnector
<6> 2021-03-22 13:59:12.566 +01:00 [INF] - Closing link Events for GP731/apiconnector
<6> 2021-03-22 13:59:12.574 +01:00 [INF] - Closing link TwinSending for GP731/apiconnector
<6> 2021-03-22 13:59:12.575 +01:00 [INF] - Closing link TwinSending for GP731/apiconnector
<6> 2021-03-22 13:59:12.575 +01:00 [INF] - Closing link TwinReceiving for GP731/apiconnector
<6> 2021-03-22 13:59:12.575 +01:00 [INF] - Closing link TwinReceiving for GP731/apiconnector
<6> 2021-03-22 13:59:12.575 +01:00 [INF] - Closing link ModuleMessages for GP731/apiconnector
<6> 2021-03-22 13:59:12.575 +01:00 [INF] - Closing link ModuleMessages for GP731/apiconnector
<6> 2021-03-22 13:59:12.576 +01:00 [INF] - Closing receiver in cloud proxy fa703a1a-3f8f-47b3-af7e-8e196f01f6eb for GP731/apiconnector
<6> 2021-03-22 13:59:12.576 +01:00 [INF] - Closed cloud proxy fa703a1a-3f8f-47b3-af7e-8e196f01f6eb for GP731/apiconnector
<6> 2021-03-22 13:59:12.576 +01:00 [INF] - Device connection removed for device GP731/apiconnector
<6> 2021-03-22 13:59:12.693 +01:00 [INF] - New token received on the Cbs link
<6> 2021-03-22 13:59:12.693 +01:00 [INF] - Token updated for GP731/apiconnector
<6> 2021-03-22 13:59:12.695 +01:00 [INF] - Opened link Events for GP731/apiconnector
<6> 2021-03-22 13:59:12.699 +01:00 [INF] - Processing pending subscriptions for GP731/apiconnector
<6> 2021-03-22 13:59:12.699 +01:00 [INF] - Opened link TwinSending for GP731/apiconnector
<6> 2021-03-22 13:59:12.699 +01:00 [INF] - Opened link TwinReceiving for GP731/apiconnector
<6> 2021-03-22 13:59:12.700 +01:00 [INF] - Opened link ModuleMessages for GP731/apiconnector
<6> 2021-03-22 13:59:12.700 +01:00 [INF] - Attempting to connect to IoT Hub for client GP731/apiconnector via AMQP...
<6> 2021-03-22 13:59:12.731 +01:00 [INF] - New token requested by client GP731/apiconnector, but using existing token as it is usable.
<6> 2021-03-22 13:59:12.803 +01:00 [INF] - Cloud connection for GP731/apiconnector is True
<6> 2021-03-22 13:59:12.804 +01:00 [INF] - Connection status for GP731/apiconnector changed to ConnectionEstablished
<6> 2021-03-22 13:59:12.804 +01:00 [INF] - Client GP731/apiconnector connected to cloud, processing existing subscriptions.
<6> 2021-03-22 13:59:12.804 +01:00 [INF] - Created cloud proxy for client GP731/apiconnector via AMQP, with client operation timeout 20 seconds.
<6> 2021-03-22 13:59:12.805 +01:00 [INF] - Initialized cloud proxy daefa46d-2ffc-47f0-b229-8c20f4e816a4 for GP731/apiconnector
<6> 2021-03-22 13:59:12.805 +01:00 [INF] - Created cloud connection for client GP731/apiconnector
<6> 2021-03-22 13:59:12.826 +01:00 [INF] - Updated reported properties for GP731/$edgeHub
<6> 2021-03-22 13:59:12.846 +01:00 [INF] - Processing pending subscriptions for GP731/apiconnector
<6> 2021-03-22 13:59:12.846 +01:00 [INF] - Processing pending subscriptions for GP731/apiconnector
<4> 2021-03-22 13:59:42.507 +01:00 [WRN] - Did not receive ack for message d71be943-9bd7-4670-984c-14e4e4f67870 from device/module GP731/apiconnector
<4> 2021-03-22 13:59:42.513 +01:00 [WRN] - Error sending messages to module GP731/apiconnector
System.TimeoutException: Message completion response not received
at Microsoft.Azure.Devices.Edge.Hub.Core.Device.DeviceMessageHandler.SendMessageAsync(IMessage message, String input) in C:\\agent\\_work\\9\\s\\edge-hub\\src\\Microsoft.Azure.Devices.Edge.Hub.Core\\device\\DeviceMessageHandler.cs:line 450
at Microsoft.Azure.Devices.Edge.Hub.Core.Routing.ModuleEndpoint.ModuleMessageProcessor.ProcessAsync(ICollection`1 routingMessages, IDeviceProxy dp, CancellationToken token) in C:\\agent\\_work\\9\\s\\edge-hub\\src\\Microsoft.Azure.Devices.Edge.Hub.Core\\routing\\ModuleEndpoint.cs:line 167
<4> 2021-03-22 13:59:43.527 +01:00 [WRN] - Module GP731/apiconnector is not connected
<4> 2021-03-22 13:59:45.721 +01:00 [WRN] - Module GP731/apiconnector is not connected
<4> 2021-03-22 13:59:50.028 +01:00 [WRN] - Module GP731/apiconnector is not connected
<4> 2021-03-22 13:59:59.394 +01:00 [WRN] - Module GP731/apiconnector is not connected
<4> 2021-03-22 14:00:17.781 +01:00 [WRN] - Module GP731/apiconnector is not connected
<4> 2021-03-22 14:00:51.961 +01:00 [WRN] - Module GP731/apiconnector is not connected
<6> 2021-03-22 14:01:09.179 +01:00 [INF] - Entering periodic task to reauthenticate connected clients
<4> 2021-03-22 14:01:51.964 +01:00 [WRN] - Module GP731/apiconnector is not connected
<4> 2021-03-22 14:02:51.978 +01:00 [WRN] - Module GP731/apiconnector is not connected
<4> 2021-03-22 14:03:51.981 +01:00 [WRN] - Module GP731/apiconnector is not connected
<4> 2021-03-22 14:04:51.981 +01:00 [WRN] - Module GP731/apiconnector is not connected
<4> 2021-03-22 14:05:51.995 +01:00 [WRN] - Module GP731/apiconnector is not connected
<6> 2021-03-22 14:06:09.170 +01:00 [INF] - Entering periodic task to reauthenticate connected clients
<4> 2021-03-22 14:06:52.012 +01:00 [WRN] - Module GP731/apiconnector is not connected
<4> 2021-03-22 14:07:52.013 +01:00 [WRN] - Module GP731/apiconnector is not connected
<4> 2021-03-22 14:08:52.028 +01:00 [WRN] - Module GP731/apiconnector is not connected
<4> 2021-03-22 14:09:52.029 +01:00 [WRN] - Module GP731/apiconnector is not connected
<4> 2021-03-22 14:10:52.032 +01:00 [WRN] - Module GP731/apiconnector is not connected

```

## Additional Information

I never had such a situation with version 1.0.8.4 .

Contributor guide

No contributing guide indexed for this repository

Assessment

This issue has not been assessed yet.

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.