IoT Edge device disconnects from IoT Hub after a few hours.

[baharw]

Expected Behavior

An IoT Edge device connected to an IoT Hub should remain connected as long as the IoT Edge is running on the device.

Current Behavior

After the IoT Device has run for 7-48 hours, the IoT Edge device loses connection. It will not attempt to connect again.

Steps to Reproduce

1. https://docs.microsoft.com/en-us/azure/iot-edge/tutorial-python-module - accept follow https://github.com/MicrosoftDocs/azure-docs/issues/19092#issuecomment-441049339 these instuction to build and run the module on RPi.
2. Monitor the telemetry using VS Code. You will eventually see the failure.

Context (Environment)

Device (Host) Operating System

pi@raspberrypi:~ $ cat /etc/os-release
PRETTY_NAME="Raspbian GNU/Linux 9 (stretch)"
NAME="Raspbian GNU/Linux"
VERSION_ID="9"
VERSION="9 (stretch)"
ID=raspbian
ID_LIKE=debian
HOME_URL="http://www.raspbian.org/"
SUPPORT_URL="http://www.raspbian.org/RaspbianForums"
BUG_REPORT_URL="http://www.raspbian.org/RaspbianBugs"
pi@raspberrypi:~ $

pi@raspberrypi:~ $ uname -a
Linux raspberrypi 4.14.79-v7+ #1159 SMP Sun Nov 4 17:50:20 GMT 2018 armv7l GNU/Linux

Architecture

arm32

Container Operating System

Linux

Runtime Versions

iotedge

pi@raspberrypi:~ $ iotedge -V
iotedge 1.0.4 (2835ac47fbb944ba628a5cfe812ff394768842e0)

Edge Agent

pi@raspberrypi:~ $ iotedge list
NAME STATUS DESCRIPTION CONFIG
PythonModule failed Failed (132) 4 minutes ago acrplay1.azurecr.io/pythonmodule:0.0.4-arm32v7
edgeHub running Up 6 hours mcr.microsoft.com/azureiotedge-hub:1.0
edgeAgent running Up 7 hours mcr.microsoft.com/azureiotedge-agent:1.0

Edge Hub

pi@raspberrypi:~ $ iotedge list
NAME STATUS DESCRIPTION CONFIG
PythonModule failed Failed (132) 4 minutes ago acrplay1.azurecr.io/pythonmodule:0.0.4-arm32v7
edgeHub running Up 6 hours mcr.microsoft.com/azureiotedge-hub:1.0
edgeAgent running Up 7 hours mcr.microsoft.com/azureiotedge-agent:1.0

Docker

pi@raspberrypi:~ $ sudo docker version
Client:
Version: 18.06.0-dev
API version: 1.37
Go version: go1.10.2
Git commit: daf021fe
Built: Wed Jun 27 00:53:52 2018
OS/Arch: linux/arm
Experimental: false
Orchestrator: swarm

Server:
Engine:
Version: dev
API version: 1.37 (minimum version 1.12)
Go version: go1.10.2
Git commit: 9aac187
Built: Tue Jun 26 23:27:27 2018
OS/Arch: linux/arm
Experimental: false

Logs

[2018-11-27 14:49:44 +00:00]: Starting Edge Hub
[11/27/2018 02:49:44.931 PM] Edge Hub Main()
[11/27/2018 02:49:53.676 PM] Found intermediate certificates.
2018-11-27 14:49:59.155 +00:00 [INF] - Created persistent store at /tmp/edgeHub
2018-11-27 14:49:59.516 +00:00 [INF] - Starting Edge Hub
2018-11-27 14:49:59.519 +00:00 [INF] -
█████╗ ███████╗██╗ ██╗██████╗ ███████╗
██╔══██╗╚══███╔╝██║ ██║██╔══██╗██╔════╝
███████║ ███╔╝ ██║ ██║██████╔╝█████╗
██╔══██║ ███╔╝ ██║ ██║██╔══██╗██╔══╝
██║ ██║███████╗╚██████╔╝██║ ██║███████╗
╚═╝ ╚═╝╚══════╝ ╚═════╝ ╚═╝ ╚═╝╚══════╝

██╗ ██████╗ ████████╗ ███████╗██████╗ ██████╗ ███████╗
██║██╔═══██╗╚══██╔══╝ ██╔════╝██╔══██╗██╔════╝ ██╔════╝
██║██║ ██║ ██║ █████╗ ██║ ██║██║ ███╗█████╗
██║██║ ██║ ██║ ██╔══╝ ██║ ██║██║ ██║██╔══╝
██║╚██████╔╝ ██║ ███████╗██████╔╝╚██████╔╝███████╗
╚═╝ ╚═════╝ ╚═╝ ╚══════╝╚═════╝ ╚═════╝ ╚══════╝

2018-11-27 14:49:59.527 +00:00 [INF] - Version - 1.0.4.18259757 (2835ac47fbb944ba628a5cfe812ff394768842e0)
2018-11-27 14:49:59.545 +00:00 [INF] - Loaded server certificate with expiration date of "2019-02-17T23:51:42.0000000+00:00"
2018-11-27 14:49:59.687 +00:00 [INF] - Created new message store
2018-11-27 14:49:59.687 +00:00 [INF] - Started task to cleanup processed and stale messages
2018-11-27 14:50:00.026 +00:00 [INF] - Created device scope identities cache
2018-11-27 14:50:00.070 +00:00 [INF] - Starting refresh of device scope identities cache
2018-11-27 14:50:00.514 +00:00 [INF] - Initializing configuration
2018-11-27 14:50:00.674 +00:00 [INF] - New device connection for device PreEdge-0001-PLV/$edgeHub
2018-11-27 14:50:01.014 +00:00 [INF] - Attempting to connect to IoT Hub for client PreEdge-0001-PLV/$edgeHub via AMQP...
2018-11-27 14:50:05.752 +00:00 [INF] - Exiting disconnected state
2018-11-27 14:50:05.769 +00:00 [INF] - Device connected to cloud, processing subscriptions for connected clients.
2018-11-27 14:50:05.785 +00:00 [INF] - Processing subscriptions for client PreEdge-0001-PLV/$edgeHub.
2018-11-27 14:50:05.820 +00:00 [INF] - Cloud connection for PreEdge-0001-PLV/$edgeHub is True
2018-11-27 14:50:05.834 +00:00 [INF] - Entering connected state
2018-11-27 14:50:05.852 +00:00 [INF] - Created cloud proxy for client PreEdge-0001-PLV/$edgeHub via AMQP, with client operation timeout 20000.
2018-11-27 14:50:05.886 +00:00 [INF] - Initialized cloud proxy bd94b0a6-299d-4c75-a219-69c3822dd8bd for PreEdge-0001-PLV/$edgeHub
2018-11-27 14:50:05.907 +00:00 [INF] - Created cloud connection for client PreEdge-0001-PLV/$edgeHub
2018-11-27 14:50:06.010 +00:00 [INF] - Processing subscription DesiredPropertyUpdates for client PreEdge-0001-PLV/$edgeHub.
2018-11-27 14:50:06.010 +00:00 [INF] - Processing subscription Methods for client PreEdge-0001-PLV/$edgeHub.
2018-11-27 14:50:06.027 +00:00 [INF] - Processing subscription DesiredPropertyUpdates for client PreEdge-0001-PLV/$edgeHub.
2018-11-27 14:50:06.475 +00:00 [INF] - Processing subscription Methods for client PreEdge-0001-PLV/$edgeHub.
2018-11-27 14:50:08.322 +00:00 [INF] - Obtained edge hub config from module twin
2018-11-27 14:50:09.072 +00:00 [INF] - Set the following 1 route(s) in edge hub
2018-11-27 14:50:09.079 +00:00 [INF] - PythonModuleToIoTHub: FROM /messages/* INTO $upstream
2018-11-27 14:50:09.086 +00:00 [INF] - Updated message store TTL to 7200 seconds
2018-11-27 14:50:09.089 +00:00 [INF] - Updated the edge hub store and forward configuration
2018-11-27 14:50:09.092 +00:00 [INF] - Initialized edge hub configuration
2018-11-27 14:50:09.181 +00:00 [INF] - Starting timer to authenticate connections with a period of 300 seconds
2018-11-27 14:50:09.653 +00:00 [INF] - Scheduling server certificate renewal for "2019-02-17T23:49:12.0006817Z".
2018-11-27 14:50:09.664 +00:00 [INF] - Starting protocol heads - (MQTT, AMQP, HTTP)
2018-11-27 14:50:09.701 +00:00 [INF] - Starting MQTT head
2018-11-27 14:50:10.224 +00:00 [INF] - Initializing TLS endpoint on port 8883 for MQTT head.
2018-11-27 14:50:10.665 +00:00 [INF] - Starting AMQP head
2018-11-27 14:50:10.725 +00:00 [INF] - Started MQTT head
2018-11-27 14:50:11.351 +00:00 [INF] - Started AMQP head
2018-11-27 14:50:11.366 +00:00 [INF] - Starting HTTP head
2018-11-27 14:50:11.995 +00:00 [INF] - User profile is available. Using '"/home/edgehubuser/.aspnet/DataProtection-Keys"' as key repository; keys will not be encrypted at rest.
2018-11-27 14:50:14.444 +00:00 [WRN] - Overriding address(es) '"http://+:80"'. Binding to endpoints defined in "UseKestrel()" instead.
2018-11-27 14:50:14.593 +00:00 [INF] - Started HTTP head
2018-11-27 14:50:15.009 +00:00 [INF] - Client PreEdge-0001-PLV/PythonModule in device scope authenticated locally.
2018-11-27 14:50:15.022 +00:00 [INF] - Successfully generated identity for clientId PreEdge-0001-PLV/PythonModule and username bwIoTHub-1.azure-devices.net/PreEdge-0001-PLV/PythonModule/?api-version=2017-11-08-preview&DeviceClientType=iothubclient%2f1.2.9%20(native%3b%20Linux%3b%20armv7l)
2018-11-27 14:50:15.039 +00:00 [INF] - ClientAuthenticated, PreEdge-0001-PLV/PythonModule, 44dbc288
2018-11-27 14:50:15.299 +00:00 [INF] - New device connection for device PreEdge-0001-PLV/PythonModule
2018-11-27 14:50:15.351 +00:00 [INF] - Bind device proxy for device PreEdge-0001-PLV/PythonModule
2018-11-27 14:50:15.357 +00:00 [INF] - Binding message channel for device Id PreEdge-0001-PLV/PythonModule
2018-11-27 14:50:15.480 +00:00 [INF] - Attempting to connect to IoT Hub for client PreEdge-0001-PLV/PythonModule via AMQP...
2018-11-27 14:50:15.696 +00:00 [INF] - Cloud connection for PreEdge-0001-PLV/PythonModule is True
2018-11-27 14:50:15.696 +00:00 [INF] - Created cloud proxy for client PreEdge-0001-PLV/PythonModule via AMQP, with client operation timeout 20000.
2018-11-27 14:50:15.697 +00:00 [INF] - Initialized cloud proxy 41162313-8185-4bca-ba42-0984029c87b2 for PreEdge-0001-PLV/PythonModule
2018-11-27 14:50:15.697 +00:00 [INF] - Created cloud connection for client PreEdge-0001-PLV/PythonModule
2018-11-27 14:50:15.697 +00:00 [INF] - Processing subscription TwinResponse for client PreEdge-0001-PLV/PythonModule.
2018-11-27 14:50:15.736 +00:00 [INF] - Processing subscription ModuleMessages for client PreEdge-0001-PLV/PythonModule.
2018-11-27 14:50:15.737 +00:00 [INF] - Processing subscription DesiredPropertyUpdates for client PreEdge-0001-PLV/PythonModule.
2018-11-27 14:50:15.832 +00:00 [INF] - Set subscriptions from session state for PreEdge-0001-PLV/PythonModule
2018-11-27 14:50:16.321 +00:00 [INF] - Processing subscription TwinResponse for client PreEdge-0001-PLV/PythonModule.
2018-11-27 14:50:16.322 +00:00 [INF] - Processing subscription ModuleMessages for client PreEdge-0001-PLV/PythonModule.
2018-11-27 14:50:16.323 +00:00 [INF] - Processing subscription DesiredPropertyUpdates for client PreEdge-0001-PLV/PythonModule.
2018-11-27 14:50:16.324 +00:00 [INF] - Set subscriptions from session state for PreEdge-0001-PLV/PythonModule
2018-11-27 14:55:04.758 +00:00 [INF] - Exiting connected state
2018-11-27 14:55:04.766 +00:00 [INF] - Entering unreachable state
2018-11-27 14:55:09.242 +00:00 [INF] - Reauthenticating connected clients
2018-11-27 14:55:24.884 +00:00 [INF] - Entering disconnected state
2018-11-27 14:55:24.888 +00:00 [INF] - Cloud connection for PreEdge-0001-PLV/$edgeHub is False
2018-11-27 14:55:24.970 +00:00 [INF] - Connection status for PreEdge-0001-PLV/$edgeHub changed to Disconnected
2018-11-27 14:55:25.068 +00:00 [INF] - Closing receiver in cloud proxy bd94b0a6-299d-4c75-a219-69c3822dd8bd for PreEdge-0001-PLV/$edgeHub
2018-11-27 14:55:25.071 +00:00 [INF] - Closed cloud proxy bd94b0a6-299d-4c75-a219-69c3822dd8bd for PreEdge-0001-PLV/$edgeHub
2018-11-27 14:55:25.072 +00:00 [INF] - Cloud connection for PreEdge-0001-PLV/PythonModule is False
2018-11-27 14:55:25.072 +00:00 [INF] - Connection status for PreEdge-0001-PLV/PythonModule changed to Disconnected
2018-11-27 14:55:25.077 +00:00 [INF] - Closing receiver in cloud proxy 41162313-8185-4bca-ba42-0984029c87b2 for PreEdge-0001-PLV/PythonModule
2018-11-27 14:55:25.077 +00:00 [INF] - Closed cloud proxy 41162313-8185-4bca-ba42-0984029c87b2 for PreEdge-0001-PLV/PythonModule
2018-11-27 14:55:28.116 +00:00 [INF] - Attempting to connect to IoT Hub for client PreEdge-0001-PLV/PythonModule via AMQP...
2018-11-27 14:55:48.163 +00:00 [ERR] - Error creating or updating the cloud proxy for client PreEdge-0001-PLV/PythonModule
System.TimeoutException: Operation timeout expired.
at Microsoft.Azure.Devices.Client.InternalClient.<>c.b__62_2(Task t)
at System.Threading.Tasks.ContinuationTaskFromTask.InnerInvoke()
at System.Threading.Tasks.Task.<>c.<.cctor>b__278_1(Object obj)
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.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state)
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.ModuleClientWrapper.OpenAsync() in /home/vsts/work/1/s/edge-hub/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/ModuleClientWrapper.cs:line 49
at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ConnectivityAwareClient.<>c__DisplayClass28_0.<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](Func1 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.CloudConnection.ConnectToIoTHub(IClientCredentials newCredentials) in /home/vsts/work/1/s/edge-hub/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/CloudConnection.cs:line 178 at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudConnection.GetCloudProxyAsync(IClientCredentials newCredentials) in /home/vsts/work/1/s/edge-hub/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/CloudConnection.cs:line 157 at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudConnection.<>c__DisplayClass26_0.<<CreateOrUpdateAsync>b__0>d.MoveNext() in /home/vsts/work/1/s/edge-hub/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/CloudConnection.cs:line 126 --- End of stack trace from previous location where exception was thrown --- at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudConnection.CreateOrUpdateAsync(IClientCredentials newCredentials) in /home/vsts/work/1/s/edge-hub/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/CloudConnection.cs:line 101 2018-11-27 14:55:48.385 +00:00 [INF] - Error getting cloud connection for device PreEdge-0001-PLV/PythonModule Microsoft.Azure.Devices.Edge.Hub.Core.EdgeHubConnectionException: Error updating identity for device PreEdge-0001-PLV/PythonModule ---> System.TimeoutException: Operation timeout expired. at Microsoft.Azure.Devices.Client.InternalClient.<>c.<ApplyTimeout>b__62_2(Task t) at System.Threading.Tasks.ContinuationTaskFromTask.InnerInvoke() at System.Threading.Tasks.Task.<>c.<.cctor>b__278_1(Object obj) 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.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state) 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.ModuleClientWrapper.OpenAsync() in /home/vsts/work/1/s/edge-hub/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/ModuleClientWrapper.cs:line 49 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](Func1 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.CloudConnection.ConnectToIoTHub(IClientCredentials newCredentials) in /home/vsts/work/1/s/edge-hub/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/CloudConnection.cs:line 178
at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudConnection.GetCloudProxyAsync(IClientCredentials newCredentials) in /home/vsts/work/1/s/edge-hub/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/CloudConnection.cs:line 157
at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudConnection.<>c__DisplayClass26_0.<b__0>d.MoveNext() in /home/vsts/work/1/s/edge-hub/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/CloudConnection.cs:line 126
--- End of stack trace from previous location where exception was thrown ---
at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudConnection.CreateOrUpdateAsync(IClientCredentials newCredentials) in /home/vsts/work/1/s/edge-hub/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/CloudConnection.cs:line 101
at Microsoft.Azure.Devices.Edge.Hub.Core.ConnectionManager.<>c__DisplayClass30_0.<b__0>d.MoveNext() in /home/vsts/work/1/s/edge-hub/src/Microsoft.Azure.Devices.Edge.Hub.Core/ConnectionManager.cs:line 173
--- End of inner exception stack trace ---
2018-11-27 14:55:48.404 +00:00 [WRN] - Could not get an active Iot Hub connection for device PreEdge-0001-PLV/PythonModule
2018-11-27 14:55:52.451 +00:00 [INF] - Attempting to connect to IoT Hub for client PreEdge-0001-PLV/PythonModule via AMQP...
2018-11-27 14:56:12.476 +00:00 [ERR] - Error creating or updating the cloud proxy for client PreEdge-0001-PLV/PythonModule
System.TimeoutException: Operation timeout expired.
at Microsoft.Azure.Devices.Client.InternalClient.<>c.b__62_2(Task t)
at System.Threading.Tasks.ContinuationTaskFromTask.InnerInvoke()
at System.Threading.Tasks.Task.<>c.<.cctor>b__278_1(Object obj)
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.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state)
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.ModuleClientWrapper.OpenAsync() in /home/vsts/work/1/s/edge-hub/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/ModuleClientWrapper.cs:line 49
at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ConnectivityAwareClient.<>c__DisplayClass28_0.<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](Func1 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.CloudConnection.ConnectToIoTHub(IClientCredentials newCredentials) in /home/vsts/work/1/s/edge-hub/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/CloudConnection.cs:line 178 at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudConnection.GetCloudProxyAsync(IClientCredentials newCredentials) in /home/vsts/work/1/s/edge-hub/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/CloudConnection.cs:line 157 at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudConnection.<>c__DisplayClass26_0.<<CreateOrUpdateAsync>b__0>d.MoveNext() in /home/vsts/work/1/s/edge-hub/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/CloudConnection.cs:line 126 --- End of stack trace from previous location where exception was thrown --- at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudConnection.CreateOrUpdateAsync(IClientCredentials newCredentials) in /home/vsts/work/1/s/edge-hub/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/CloudConnection.cs:line 101 2018-11-27 14:56:12.558 +00:00 [INF] - Error getting cloud connection for device PreEdge-0001-PLV/PythonModule Microsoft.Azure.Devices.Edge.Hub.Core.EdgeHubConnectionException: Error updating identity for device PreEdge-0001-PLV/PythonModule ---> System.TimeoutException: Operation timeout expired. at Microsoft.Azure.Devices.Client.InternalClient.<>c.<ApplyTimeout>b__62_2(Task t) at System.Threading.Tasks.ContinuationTaskFromTask.InnerInvoke() at System.Threading.Tasks.Task.<>c.<.cctor>b__278_1(Object obj) 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.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state) 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.ModuleClientWrapper.OpenAsync() in /home/vsts/work/1/s/edge-hub/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/ModuleClientWrapper.cs:line 49 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](Func1 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.CloudConnection.ConnectToIoTHub(IClientCredentials newCredentials) in /home/vsts/work/1/s/edge-hub/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/CloudConnection.cs:line 178
at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudConnection.GetCloudProxyAsync(IClientCredentials newCredentials) in /home/vsts/work/1/s/edge-hub/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/CloudConnection.cs:line 157
at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudConnection.<>c__DisplayClass26_0.<b__0>d.MoveNext() in /home/vsts/work/1/s/edge-hub/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/CloudConnection.cs:line 126
--- End of stack trace from previous location where exception was thrown ---
at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudConnection.CreateOrUpdateAsync(IClientCredentials newCredentials) in /home/vsts/work/1/s/edge-hub/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/CloudConnection.cs:line 101
at Microsoft.Azure.Devices.Edge.Hub.Core.ConnectionManager.<>c__DisplayClass30_0.<b__0>d.MoveNext() in /home/vsts/work/1/s/edge-hub/src/Microsoft.Azure.Devices.Edge.Hub.Core/ConnectionManager.cs:line 173
--- End of inner exception stack trace ---
2018-11-27 14:56:12.563 +00:00 [WRN] - Could not get an active Iot Hub connection for device PreEdge-0001-PLV/PythonModule
2018-11-27 14:56:21.507 +00:00 [INF] - Attempting to connect to IoT Hub for client PreEdge-0001-PLV/PythonModule via AMQP...
2018-11-27 14:56:22.063 +00:00 [INF] - Exiting disconnected state
2018-11-27 14:56:22.064 +00:00 [INF] - Device connected to cloud, processing subscriptions for connected clients.
2018-11-27 14:56:22.064 +00:00 [INF] - Processing subscriptions for client PreEdge-0001-PLV/$edgeHub.
2018-11-27 14:56:22.064 +00:00 [INF] - Attempting to connect to IoT Hub for client PreEdge-0001-PLV/$edgeHub via AMQP...
2018-11-27 14:56:22.067 +00:00 [INF] - Cloud connection for PreEdge-0001-PLV/$edgeHub is True
2018-11-27 14:56:22.083 +00:00 [INF] - Cloud connection for PreEdge-0001-PLV/PythonModule is True
2018-11-27 14:56:22.083 +00:00 [INF] - Cloud connection for PreEdge-0001-PLV/PythonModule is True
2018-11-27 14:56:22.083 +00:00 [INF] - Cloud connection for PreEdge-0001-PLV/PythonModule is True
2018-11-27 14:56:22.083 +00:00 [INF] - Cloud connection for PreEdge-0001-PLV/PythonModule is True
2018-11-27 14:56:22.084 +00:00 [INF] - Entering connected state
2018-11-27 14:56:22.085 +00:00 [INF] - Created cloud proxy for client PreEdge-0001-PLV/PythonModule via AMQP, with client operation timeout 20000.
2018-11-27 14:56:22.085 +00:00 [INF] - Initialized cloud proxy fe523d2c-c7ba-4b72-8d24-1ae85dbae085 for PreEdge-0001-PLV/PythonModule
2018-11-27 14:56:22.092 +00:00 [INF] - Closing receiver in cloud proxy 41162313-8185-4bca-ba42-0984029c87b2 for PreEdge-0001-PLV/PythonModule
2018-11-27 14:56:22.093 +00:00 [INF] - Closed cloud proxy 41162313-8185-4bca-ba42-0984029c87b2 for PreEdge-0001-PLV/PythonModule
2018-11-27 14:56:22.094 +00:00 [INF] - Starting refresh of device scope identities cache
2018-11-27 14:56:22.153 +00:00 [INF] - Cloud connection for PreEdge-0001-PLV/$edgeHub is True
2018-11-27 14:56:22.153 +00:00 [INF] - Created cloud proxy for client PreEdge-0001-PLV/$edgeHub via AMQP, with client operation timeout 20000.
2018-11-27 14:56:22.153 +00:00 [INF] - Initialized cloud proxy dd77d841-ae18-4fdb-886f-8fa55edd717c for PreEdge-0001-PLV/$edgeHub
2018-11-27 14:56:22.154 +00:00 [INF] - Closing receiver in cloud proxy bd94b0a6-299d-4c75-a219-69c3822dd8bd for PreEdge-0001-PLV/$edgeHub
2018-11-27 14:56:22.154 +00:00 [INF] - Closed cloud proxy bd94b0a6-299d-4c75-a219-69c3822dd8bd for PreEdge-0001-PLV/$edgeHub
2018-11-27 14:56:22.154 +00:00 [INF] - Processing subscription DesiredPropertyUpdates for client PreEdge-0001-PLV/$edgeHub.
2018-11-27 14:56:22.213 +00:00 [INF] - Processing subscription Methods for client PreEdge-0001-PLV/$edgeHub.
2018-11-27 14:56:22.273 +00:00 [INF] - Processing subscriptions for client PreEdge-0001-PLV/PythonModule.
2018-11-27 14:56:22.273 +00:00 [INF] - Processing subscription DesiredPropertyUpdates for client PreEdge-0001-PLV/PythonModule.
2018-11-27 14:56:22.334 +00:00 [INF] - Processing subscription ModuleMessages for client PreEdge-0001-PLV/PythonModule.
2018-11-27 14:56:22.334 +00:00 [INF] - Processing subscription TwinResponse for client PreEdge-0001-PLV/PythonModule.
2018-11-27 15:00:09.186 +00:00 [INF] - Reauthenticating connected clients
2018-11-27 15:05:09.186 +00:00 [INF] - Reauthenticating connected clients
2018-11-27 15:10:09.187 +00:00 [INF] - Reauthenticating connected clients
2018-11-27 15:15:09.187 +00:00 [INF] - Reauthenticating connected clients
2018-11-27 15:19:59.770 +00:00 [INF] - Started task to cleanup processed and stale messages for endpoint iothub
2018-11-27 15:20:00.021 +00:00 [INF] - Cleaned up 60 messages from queue for endpoint iothub and 60 messages from message store.
2018-11-27 15:20:09.188 +00:00 [INF] - Reauthenticating connected clients
2018-11-27 15:25:09.187 +00:00 [INF] - Reauthenticating connected clients
2018-11-27 15:30:09.187 +00:00 [INF] - Reauthenticating connected clients
2018-11-27 15:35:09.187 +00:00 [INF] - Reauthenticating connected clients
2018-11-27 15:38:14.683 +00:00 [INF] - Closing connection for device: PreEdge-0001-PLV/PythonModule, ,
2018-11-27 15:38:14.690 +00:00 [INF] - Disposing MessagingServiceClient for device Id PreEdge-0001-PLV/PythonModule because of exception -
2018-11-27 15:38:14.703 +00:00 [INF] - Setting device proxy inactive for device Id PreEdge-0001-PLV/PythonModule
2018-11-27 15:38:14.778 +00:00 [INF] - Device connection removed for device PreEdge-0001-PLV/PythonModule
2018-11-27 15:38:14.795 +00:00 [INF] - Remove device connection for device PreEdge-0001-PLV/PythonModule
2018-11-27 15:38:14.837 +00:00 [INF] - Client PreEdge-0001-PLV/PythonModule in device scope authenticated locally.
2018-11-27 15:38:14.837 +00:00 [INF] - Successfully generated identity for clientId PreEdge-0001-PLV/PythonModule and username bwIoTHub-1.azure-devices.net/PreEdge-0001-PLV/PythonModule/?api-version=2017-11-08-preview&DeviceClientType=iothubclient%2f1.2.9%20(native%3b%20Linux%3b%20armv7l)
2018-11-27 15:38:14.839 +00:00 [INF] - ClientAuthenticated, PreEdge-0001-PLV/PythonModule, 6cab741b
2018-11-27 15:38:14.844 +00:00 [INF] - New device connection for device PreEdge-0001-PLV/PythonModule
2018-11-27 15:38:14.852 +00:00 [INF] - Bind device proxy for device PreEdge-0001-PLV/PythonModule
2018-11-27 15:38:14.852 +00:00 [INF] - Binding message channel for device Id PreEdge-0001-PLV/PythonModule
2018-11-27 15:38:14.854 +00:00 [INF] - Processing subscription TwinResponse for client PreEdge-0001-PLV/PythonModule.
2018-11-27 15:38:14.856 +00:00 [INF] - Processing subscription ModuleMessages for client PreEdge-0001-PLV/PythonModule.
2018-11-27 15:38:14.857 +00:00 [INF] - Processing subscription DesiredPropertyUpdates for client PreEdge-0001-PLV/PythonModule.
2018-11-27 15:38:14.858 +00:00 [INF] - Set subscriptions from session state for PreEdge-0001-PLV/PythonModule
2018-11-27 15:40:09.189 +00:00 [INF] - Reauthenticating connected clients
2018-11-27 15:45:09.186 +00:00 [INF] - Reauthenticating connected clients
2018-11-27 15:50:09.186 +00:00 [INF] - Reauthenticating connected clients
2018-11-27 15:50:30.028 +00:00 [INF] - Started task to cleanup processed and stale messages for endpoint iothub
2018-11-27 15:50:30.278 +00:00 [INF] - Cleaned up 30 messages from queue for endpoint iothub and 30 messages from message store.
2018-11-27 15:55:09.189 +00:00 [INF] - Reauthenticating connected clients
2018-11-27 15:56:22.542 +00:00 [INF] - Starting refresh of device scope identities cache
2018-11-27 16:00:09.186 +00:00 [INF] - Reauthenticating connected clients
2018-11-27 16:05:09.189 +00:00 [INF] - Reauthenticating connected clients
2018-11-27 16:10:09.187 +00:00 [INF] - Reauthenticating connected clients
2018-11-27 16:15:09.191 +00:00 [INF] - Reauthenticating connected clients
2018-11-27 16:20:09.187 +00:00 [INF] - Reauthenticating connected clients
2018-11-27 16:21:00.276 +00:00 [INF] - Started task to cleanup processed and stale messages for endpoint iothub
2018-11-27 16:21:00.524 +00:00 [INF] - Cleaned up 31 messages from queue for endpoint iothub and 31 messages from message store.
2018-11-27 16:25:09.177 +00:00 [INF] - Reauthenticating connected clients
2018-11-27 16:26:15.588 +00:00 [INF] - Closing connection for device: PreEdge-0001-PLV/PythonModule, ,
2018-11-27 16:26:15.589 +00:00 [INF] - Disposing MessagingServiceClient for device Id PreEdge-0001-PLV/PythonModule because of exception -
2018-11-27 16:26:15.590 +00:00 [INF] - Setting device proxy inactive for device Id PreEdge-0001-PLV/PythonModule
2018-11-27 16:26:15.590 +00:00 [INF] - Device connection removed for device PreEdge-0001-PLV/PythonModule
2018-11-27 16:26:15.693 +00:00 [INF] - Remove device connection for device PreEdge-0001-PLV/PythonModule
2018-11-27 16:26:15.770 +00:00 [INF] - Client PreEdge-0001-PLV/PythonModule in device scope authenticated locally.
2018-11-27 16:26:15.771 +00:00 [INF] - Successfully generated identity for clientId PreEdge-0001-PLV/PythonModule and username bwIoTHub-1.azure-devices.net/PreEdge-0001-PLV/PythonModule/?api-version=2017-11-08-preview&DeviceClientType=iothubclient%2f1.2.9%20(native%3b%20Linux%3b%20armv7l)
2018-11-27 16:26:15.771 +00:00 [INF] - ClientAuthenticated, PreEdge-0001-PLV/PythonModule, 63580cf9
2018-11-27 16:26:15.773 +00:00 [INF] - New device connection for device PreEdge-0001-PLV/PythonModule
2018-11-27 16:26:15.836 +00:00 [INF] - Bind device proxy for device PreEdge-0001-PLV/PythonModule
2018-11-27 16:26:15.836 +00:00 [INF] - Binding message channel for device Id PreEdge-0001-PLV/PythonModule
2018-11-27 16:26:15.837 +00:00 [INF] - Processing subscription TwinResponse for client PreEdge-0001-PLV/PythonModule.
2018-11-27 16:26:15.837 +00:00 [INF] - Processing subscription ModuleMessages for client PreEdge-0001-PLV/PythonModule.
2018-11-27 16:26:15.838 +00:00 [INF] - Processing subscription DesiredPropertyUpdates for client PreEdge-0001-PLV/PythonModule.
2018-11-27 16:26:15.839 +00:00 [INF] - Set subscriptions from session state for PreEdge-0001-PLV/PythonModule
2018-11-27 16:30:09.182 +00:00 [INF] - Reauthenticating connected clients
2018-11-27 16:35:09.180 +00:00 [INF] - Reauthenticating connected clients
2018-11-27 16:40:09.176 +00:00 [INF] - Reauthenticating connected clients
2018-11-27 16:45:09.176 +00:00 [INF] - Reauthenticating connected clients
2018-11-27 16:49:59.166 +00:00 [INF] - Starting compaction of stores
2018-11-27 16:49:59.171 +00:00 [INF] - Starting compaction of store twins
2018-11-27 16:49:59.259 +00:00 [INF] - Starting compaction of store checkpoints
2018-11-27 16:49:59.326 +00:00 [INF] - Starting compaction of store iothub
2018-11-27 16:49:59.393 +00:00 [INF] - Starting compaction of store DeviceScopeCache
2018-11-27 16:49:59.547 +00:00 [INF] - Starting compaction of store messages
2018-11-27 16:49:59.586 +00:00 [INF] - Starting compaction of store sessions
2018-11-27 16:49:59.653 +00:00 [INF] - Starting compaction of store default
2018-11-27 16:50:09.178 +00:00 [INF] - Reauthenticating connected clients
2018-11-27 16:51:30.526 +00:00 [INF] - Started task to cleanup processed and stale messages for endpoint iothub
2018-11-27 16:51:30.769 +00:00 [INF] - Cleaned up 30 messages from queue for endpoint iothub and 30 messages from message store.
2018-11-27 16:55:09.178 +00:00 [INF] - Reauthenticating connected clients
2018-11-27 16:56:22.906 +00:00 [INF] - Starting refresh of device scope identities cache
2018-11-27 17:00:09.181 +00:00 [INF] - Reauthenticating connected clients
2018-11-27 17:05:09.178 +00:00 [INF] - Reauthenticating connected clients
2018-11-27 17:10:09.176 +00:00 [INF] - Reauthenticating connected clients
2018-11-27 17:14:16.588 +00:00 [INF] - Closing connection for device: PreEdge-0001-PLV/PythonModule, ,
2018-11-27 17:14:16.589 +00:00 [INF] - Disposing MessagingServiceClient for device Id PreEdge-0001-PLV/PythonModule because of exception -
2018-11-27 17:14:16.589 +00:00 [INF] - Setting device proxy inactive for device Id PreEdge-0001-PLV/PythonModule
2018-11-27 17:14:16.589 +00:00 [INF] - Device connection removed for device PreEdge-0001-PLV/PythonModule
2018-11-27 17:14:16.695 +00:00 [INF] - Remove device connection for device PreEdge-0001-PLV/PythonModule
2018-11-27 17:14:16.775 +00:00 [INF] - Client PreEdge-0001-PLV/PythonModule in device scope authenticated locally.
2018-11-27 17:14:16.776 +00:00 [INF] - Successfully generated identity for clientId PreEdge-0001-PLV/PythonModule and username bwIoTHub-1.azure-devices.net/PreEdge-0001-PLV/PythonModule/?api-version=2017-11-08-preview&DeviceClientType=iothubclient%2f1.2.9%20(native%3b%20Linux%3b%20armv7l)
2018-11-27 17:14:16.776 +00:00 [INF] - ClientAuthenticated, PreEdge-0001-PLV/PythonModule, 7e89e963
2018-11-27 17:14:16.778 +00:00 [INF] - New device connection for device PreEdge-0001-PLV/PythonModule
2018-11-27 17:14:16.784 +00:00 [INF] - Bind device proxy for device PreEdge-0001-PLV/PythonModule
2018-11-27 17:14:16.784 +00:00 [INF] - Binding message channel for device Id PreEdge-0001-PLV/PythonModule
2018-11-27 17:14:16.785 +00:00 [INF] - Processing subscription TwinResponse for client PreEdge-0001-PLV/PythonModule.
2018-11-27 17:14:16.786 +00:00 [INF] - Processing subscription ModuleMessages for client PreEdge-0001-PLV/PythonModule.
2018-11-27 17:14:16.786 +00:00 [INF] - Processing subscription DesiredPropertyUpdates for client PreEdge-0001-PLV/PythonModule.
2018-11-27 17:14:16.787 +00:00 [INF] - Set subscriptions from session state for PreEdge-0001-PLV/PythonModule
2018-11-27 17:15:09.176 +00:00 [INF] - Reauthenticating connected clients
2018-11-27 17:20:09.178 +00:00 [INF] - Reauthenticating connected clients
2018-11-27 17:22:00.786 +00:00 [INF] - Started task to cleanup processed and stale messages for endpoint iothub
2018-11-27 17:22:00.935 +00:00 [INF] - Cleaned up 31 messages from queue for endpoint iothub and 31 messages from message store.
2018-11-27 17:25:09.186 +00:00 [INF] - Reauthenticating connected clients
2018-11-27 17:30:09.186 +00:00 [INF] - Reauthenticating connected clients
2018-11-27 17:35:09.186 +00:00 [INF] - Reauthenticating connected clients
2018-11-27 17:40:09.186 +00:00 [INF] - Reauthenticating connected clients
2018-11-27 17:45:09.187 +00:00 [INF] - Reauthenticating connected clients
2018-11-27 17:50:09.189 +00:00 [INF] - Reauthenticating connected clients
2018-11-27 17:52:30.946 +00:00 [INF] - Started task to cleanup processed and stale messages for endpoint iothub
2018-11-27 17:52:31.183 +00:00 [INF] - Cleaned up 30 messages from queue for endpoint iothub and 30 messages from message store.
2018-11-27 17:55:09.189 +00:00 [INF] - Reauthenticating connected clients
2018-11-27 17:56:26.986 +00:00 [INF] - Starting refresh of device scope identities cache
2018-11-27 18:00:09.190 +00:00 [INF] - Reauthenticating connected clients
2018-11-27 18:02:17.588 +00:00 [INF] - Closing connection for device: PreEdge-0001-PLV/PythonModule, ,
2018-11-27 18:02:17.588 +00:00 [INF] - Disposing MessagingServiceClient for device Id PreEdge-0001-PLV/PythonModule because of exception -
2018-11-27 18:02:17.589 +00:00 [INF] - Setting device proxy inactive for device Id PreEdge-0001-PLV/PythonModule
2018-11-27 18:02:17.589 +00:00 [INF] - Device connection removed for device PreEdge-0001-PLV/PythonModule
2018-11-27 18:02:17.691 +00:00 [INF] - Remove device connection for device PreEdge-0001-PLV/PythonModule
2018-11-27 18:02:17.772 +00:00 [INF] - Client PreEdge-0001-PLV/PythonModule in device scope authenticated locally.
2018-11-27 18:02:17.773 +00:00 [INF] - Successfully generated identity for clientId PreEdge-0001-PLV/PythonModule and username bwIoTHub-1.azure-devices.net/PreEdge-0001-PLV/PythonModule/?api-version=2017-11-08-preview&DeviceClientType=iothubclient%2f1.2.9%20(native%3b%20Linux%3b%20armv7l)
2018-11-27 18:02:17.773 +00:00 [INF] - ClientAuthenticated, PreEdge-0001-PLV/PythonModule, 0dfbdd0b
2018-11-27 18:02:17.776 +00:00 [INF] - New device connection for device PreEdge-0001-PLV/PythonModule
2018-11-27 18:02:17.781 +00:00 [INF] - Bind device proxy for device PreEdge-0001-PLV/PythonModule
2018-11-27 18:02:17.782 +00:00 [INF] - Binding message channel for device Id PreEdge-0001-PLV/PythonModule
2018-11-27 18:02:17.783 +00:00 [INF] - Processing subscription TwinResponse for client PreEdge-0001-PLV/PythonModule.
2018-11-27 18:02:17.783 +00:00 [INF] - Processing subscription ModuleMessages for client PreEdge-0001-PLV/PythonModule.
2018-11-27 18:02:17.784 +00:00 [INF] - Processing subscription DesiredPropertyUpdates for client PreEdge-0001-PLV/PythonModule.
2018-11-27 18:02:17.785 +00:00 [INF] - Set subscriptions from session state for PreEdge-0001-PLV/PythonModule
2018-11-27 18:05:09.178 +00:00 [INF] - Reauthenticating connected clients
2018-11-27 18:10:09.180 +00:00 [INF] - Reauthenticating connected clients
2018-11-27 18:15:09.181 +00:00 [INF] - Reauthenticating connected clients
2018-11-27 18:20:09.180 +00:00 [INF] - Reauthenticating connected clients
2018-11-27 18:23:01.179 +00:00 [INF] - Started task to cleanup processed and stale messages for endpoint iothub
2018-11-27 18:23:01.407 +00:00 [INF] - Cleaned up 31 messages from queue for endpoint iothub and 31 messages from message store.
2018-11-27 18:25:09.179 +00:00 [INF] - Reauthenticating connected clients
2018-11-27 18:30:09.185 +00:00 [INF] - Reauthenticating connected clients
2018-11-27 18:35:09.184 +00:00 [INF] - Reauthenticating connected clients
2018-11-27 18:40:09.186 +00:00 [INF] - Reauthenticating connected clients
2018-11-27 18:45:09.186 +00:00 [INF] - Reauthenticating connected clients
2018-11-27 18:49:59.156 +00:00 [INF] - Starting compaction of stores
2018-11-27 18:49:59.156 +00:00 [INF] - Starting compaction of store twins
2018-11-27 18:49:59.208 +00:00 [INF] - Starting compaction of store checkpoints
2018-11-27 18:49:59.255 +00:00 [INF] - Starting compaction of store iothub
2018-11-27 18:49:59.423 +00:00 [INF] - Starting compaction of store DeviceScopeCache
2018-11-27 18:49:59.453 +00:00 [INF] - Starting compaction of store messages
2018-11-27 18:49:59.481 +00:00 [INF] - Starting compaction of store sessions
2018-11-27 18:49:59.512 +00:00 [INF] - Starting compaction of store default
2018-11-27 18:50:09.187 +00:00 [INF] - Reauthenticating connected clients
2018-11-27 18:50:18.702 +00:00 [INF] - Closing connection for device: PreEdge-0001-PLV/PythonModule, ,
2018-11-27 18:50:18.703 +00:00 [INF] - Disposing MessagingServiceClient for device Id PreEdge-0001-PLV/PythonModule because of exception -
2018-11-27 18:50:18.704 +00:00 [INF] - Setting device proxy inactive for device Id PreEdge-0001-PLV/PythonModule
2018-11-27 18:50:18.705 +00:00 [INF] - Device connection removed for device PreEdge-0001-PLV/PythonModule
2018-11-27 18:50:18.716 +00:00 [INF] - Remove device connection for device PreEdge-0001-PLV/PythonModule
2018-11-27 18:50:18.845 +00:00 [INF] - Client PreEdge-0001-PLV/PythonModule in device scope authenticated locally.
2018-11-27 18:50:18.846 +00:00 [INF] - Successfully generated identity for clientId PreEdge-0001-PLV/PythonModule and username bwIoTHub-1.azure-devices.net/PreEdge-0001-PLV/PythonModule/?api-version=2017-11-08-preview&DeviceClientType=iothubclient%2f1.2.9%20(native%3b%20Linux%3b%20armv7l)
2018-11-27 18:50:18.846 +00:00 [INF] - ClientAuthenticated, PreEdge-0001-PLV/PythonModule, 6a157e74
2018-11-27 18:50:18.848 +00:00 [INF] - New device connection for device PreEdge-0001-PLV/PythonModule
2018-11-27 18:50:18.853 +00:00 [INF] - Bind device proxy for device PreEdge-0001-PLV/PythonModule
2018-11-27 18:50:18.854 +00:00 [INF] - Binding message channel for device Id PreEdge-0001-PLV/PythonModule
2018-11-27 18:50:18.854 +00:00 [INF] - Processing subscription TwinResponse for client PreEdge-0001-PLV/PythonModule.
2018-11-27 18:50:18.855 +00:00 [INF] - Processing subscription ModuleMessages for client PreEdge-0001-PLV/PythonModule.
2018-11-27 18:50:18.856 +00:00 [INF] - Processing subscription DesiredPropertyUpdates for client PreEdge-0001-PLV/PythonModule.
2018-11-27 18:50:18.856 +00:00 [INF] - Set subscriptions from session state for PreEdge-0001-PLV/PythonModule
2018-11-27 18:53:31.417 +00:00 [INF] - Started task to cleanup processed and stale messages for endpoint iothub
2018-11-27 18:53:31.534 +00:00 [INF] - Cleaned up 30 messages from queue for endpoint iothub and 30 messages from message store.
2018-11-27 18:55:09.186 +00:00 [INF] - Reauthenticating connected clients
2018-11-27 18:56:27.606 +00:00 [INF] - Starting refresh of device scope identities cache
2018-11-27 19:00:09.186 +00:00 [INF] - Reauthenticating connected clients
2018-11-27 19:05:09.186 +00:00 [INF] - Reauthenticating connected clients
2018-11-27 19:10:09.187 +00:00 [INF] - Reauthenticating connected clients
2018-11-27 19:15:09.185 +00:00 [INF] - Reauthenticating connected clients
2018-11-27 19:20:09.187 +00:00 [INF] - Reauthenticating connected clients
2018-11-27 19:24:01.537 +00:00 [INF] - Started task to cleanup processed and stale messages for endpoint iothub
2018-11-27 19:24:01.677 +00:00 [INF] - Cleaned up 31 messages from queue for endpoint iothub and 31 messages from message store.
2018-11-27 19:25:09.187 +00:00 [INF] - Reauthenticating connected clients
2018-11-27 19:30:09.187 +00:00 [INF] - Reauthenticating connected clients
2018-11-27 19:35:09.186 +00:00 [INF] - Reauthenticating connected clients
2018-11-27 19:38:19.587 +00:00 [INF] - Closing connection for device: PreEdge-0001-PLV/PythonModule, ,
2018-11-27 19:38:19.588 +00:00 [INF] - Disposing MessagingServiceClient for device Id PreEdge-0001-PLV/PythonModule because of exception -
2018-11-27 19:38:19.588 +00:00 [INF] - Setting device proxy inactive for device Id PreEdge-0001-PLV/PythonModule
2018-11-27 19:38:19.588 +00:00 [INF] - Device connection removed for device PreEdge-0001-PLV/PythonModule
2018-11-27 19:38:19.770 +00:00 [INF] - Remove device connection for device PreEdge-0001-PLV/PythonModule
2018-11-27 19:38:19.846 +00:00 [INF] - Client PreEdge-0001-PLV/PythonModule in device scope authenticated locally.
2018-11-27 19:38:19.847 +00:00 [INF] - Successfully generated identity for clientId PreEdge-0001-PLV/PythonModule and username bwIoTHub-1.azure-devices.net/PreEdge-0001-PLV/PythonModule/?api-version=2017-11-08-preview&DeviceClientType=iothubclient%2f1.2.9%20(native%3b%20Linux%3b%20armv7l)
2018-11-27 19:38:19.847 +00:00 [INF] - ClientAuthenticated, PreEdge-0001-PLV/PythonModule, 040729a8
2018-11-27 19:38:19.849 +00:00 [INF] - New device connection for device PreEdge-0001-PLV/PythonModule
2018-11-27 19:38:19.854 +00:00 [INF] - Bind device proxy for device PreEdge-0001-PLV/PythonModule
2018-11-27 19:38:19.854 +00:00 [INF] - Binding message channel for device Id PreEdge-0001-PLV/PythonModule
2018-11-27 19:38:19.855 +00:00 [INF] - Processing subscription TwinResponse for client PreEdge-0001-PLV/PythonModule.
2018-11-27 19:38:19.856 +00:00 [INF] - Processing subscription ModuleMessages for client PreEdge-0001-PLV/PythonModule.
2018-11-27 19:38:19.856 +00:00 [INF] - Processing subscription DesiredPropertyUpdates for client PreEdge-0001-PLV/PythonModule.
2018-11-27 19:38:19.857 +00:00 [INF] - Set subscriptions from session state for PreEdge-0001-PLV/PythonModule
2018-11-27 19:40:09.187 +00:00 [INF] - Reauthenticating connected clients
2018-11-27 19:45:09.189 +00:00 [INF] - Reauthenticating connected clients
2018-11-27 19:50:09.187 +00:00 [INF] - Reauthenticating connected clients
2018-11-27 19:54:31.688 +00:00 [INF] - Started task to cleanup processed and stale messages for endpoint iothub
2018-11-27 19:54:31.909 +00:00 [INF] - Cleaned up 30 messages from queue for endpoint iothub and 30 messages from message store.
2018-11-27 19:55:09.187 +00:00 [INF] - Reauthenticating connected clients
2018-11-27 19:56:28.313 +00:00 [INF] - Starting refresh of device scope identities cache
2018-11-27 20:03:57.338 +00:00 [WRN] - Closing connection for device: PreEdge-0001-PLV/PythonModule, Microsoft.Azure.Devices.ProtocolGateway.ProtocolGatewayException: Keep Alive timed out.,
2018-11-27 20:03:57.339 +00:00 [INF] - Disposing MessagingServiceClient for device Id PreEdge-0001-PLV/PythonModule because of exception - Microsoft.Azure.Devices.ProtocolGateway.ProtocolGatewayException: Keep Alive timed out.
2018-11-27 20:03:57.339 +00:00 [INF] - Setting device proxy inactive for device Id PreEdge-0001-PLV/PythonModule
2018-11-27 20:03:57.340 +00:00 [INF] - Device connection removed for device PreEdge-0001-PLV/PythonModule
2018-11-27 20:03:57.403 +00:00 [INF] - Remove device connection for device PreEdge-0001-PLV/PythonModule

pi@raspberrypi:~ $ iotedge list
NAME STATUS DESCRIPTION CONFIG
PythonModule failed Failed (132) 12 hours ago acrplay1.azurecr.io/pythonmodule:0.0.4-arm32v7
edgeHub running Up 19 hours mcr.microsoft.com/azureiotedge-hub:1.0
edgeAgent running Up 20 hours mcr.microsoft.com/azureiotedge-agent:1.0
pi@raspberrypi:~ $

Additional Information

[myagley]

Hello. Thanks for the issue report.

I'm trying to understand the issue. It looks like the Edge Hub failed to connect to IoT Hub (TimeoutException), but then eventually connected. There are also several instances of the python module being disconnected, but this is expected. When using MQTT, the Edge Hub forces a sas token refresh for the module by closing the connection.

Is the issue that messages are not showing up in IoT Hub?

[baharw]

Hello. Thanks for the issue report.

I'm trying to understand the issue. It looks like the Edge Hub failed to connect to IoT Hub (TimeoutException), but then eventually connected. There are also several instances of the python module being disconnected, but this is expected. When using MQTT, the Edge Hub forces a sas token refresh for the module by closing the connection.

Is the issue that messages are not showing up in IoT Hub?

Yes, you are correct. There are several instances of the Edge Hub failed to connect. At the beginning of the test the device reconnects, however after 7-48 hours, the IoT Hub stops reconnecting. And the user module (in this case PythonModule) exits with

PythonModule failed Failed (132)

[baharw]

@myagley a few more things...

Below is the log item from the PythonModule

Error: Time:Thu Nov 29 13:11:39 2018 File:/usr/sdk/src/c/iothub_client/src/iothubtransport_mqtt_common.c Func:InitializeConnection Line:2195 mqtt_client timed out waiting for CONNACK

Also, digging through the source code, I discovered that the error is comming from lines 2179-2201 of https://github.com/Azure/azure-iot-sdk-c/blob/master/iothub_client/src/iothubtransport_mqtt_common.c#L2180

` //Note: in case retry_control_should_retry fails, the reconnection shall be attempted anyway (defaulting to policy IOTHUB_CLIENT_RETRY_IMMEDIATE)

        if (tickcounter_get_current_ms(transport_data->msgTickCounter, &transport_data- >connectTick) != 0)
        {
            transport_data->connectFailCount++;
            result = __FAILURE__;
        }
        else
        {
            ResetConnectionIfNecessary(transport_data);

            if (SendMqttConnectMsg(transport_data) != 0)
            {
                transport_data->connectFailCount++;
                result = __FAILURE__;
            }
            else
            {
                transport_data->mqttClientStatus = MQTT_CLIENT_STATUS_CONNECTING;
                transport_data->connectFailCount = 0;
                result = 0;
            }
        }
    }`

The connak timeout is set to 30 seconds in the same file.

#define DEFAULT_CONNACK_TIMEOUT 30 // 30 seconds

I am using the Free version of the IoT Hub to perfrom testing.

1. Is there some limitation on the free version that would lead to this error?

2. Should the timeout be increased?

Thank you for your help.

[myagley]

We believe the root cause for this issue is a deadlock in the dotnet core runtime on ARM32 devices. This has been fixed in version 1.0.6 of IoT Edge. I'm going to close this issue for now.