search

Azure / iotedge

The IoT Edge OSS project
MIT License
1.46k stars 459 forks source link

5 mins restart delay on edgeHub #1334

Closed KevinKao809 closed 5 years ago

KevinKao809 commented 5 years ago

Any way to adjust edgeHub restart delay in 5 mins?

Expected Behavior

Current Behavior

2019-06-14 00:57:19.556 +00:00 [INF] - Module 'edgeHub' scheduled to restart after 05m:00s (04m:18s left).

Steps to Reproduce

1. 2. 3. 4.

Context (Environment)

Output of iotedge check --output json

Click here ```json // Paste here ```

Device (Host) Operating System

Architecture

Container Operating System

Runtime Versions

iotedged

Edge Agent

Edge Hub

Docker

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

Logs

iotedged logs ``` ```
edge-agent logs ``` ```
edge-hub logs ``` ```

Additional Information

myagley commented 5 years ago

Is this log from the Edge Agent? It looks like the Edge Hub is failing and the Edge Agent is trying to restart it. The Edge Agent uses an exponential backoff when restarting. I believe this is currently capped at 5 minutes. The backoff schedule isn't currently configurable.

Is it possible to see the Edge Hub logs to understand why it is failing?

KevinKao809 commented 5 years ago

Right, the logs come from edgeAgent, and delay start from 1:20, 2:40 and capped at 5 mins. We implemented device reboot features, and find this delay pattern after couple times reboot testing.

One issue reported here is that we do execute 'iotedge stop' command during reboot process, sometime, we can see the edgeHub change status to 'stopped', but sometime become 'failed'. For our expectation, the delay pattern shall not happen when device normal reboot, that is why we are asking anyhow to disable it.

ancaantochi commented 5 years ago

It is not possible to configure the backoff when restarting. If you can please share edgeHub logs when status is failed it would be helpful to identity why it gets into the backoff restart.

KevinKao809 commented 5 years ago

Hello, Below are step and log file about this case.

run systemctl restart iotedge waiting all module start and running repeat above step 10 times then, we can see the edgeHub be delay start up to 5 mins.

edgeAgent log:

<6> 2019-07-31 10:56:50.185 +00:00 [INF] - Experimental features configuration: {"Enabled":false,"DisableCloudSubscriptions":false,"EnableUploadLogs":false} <6> 2019-07-31 10:56:57.436 +00:00 [INF] - Started operation refresh twin config <6> 2019-07-31 10:56:58.759 +00:00 [INF] - Edge agent attempting to connect to IoT Hub via Amqp_Tcp_Only... <6> 2019-07-31 10:57:11.520 +00:00 [INF] - Created persistent store at /tmp/edgeAgent <6> 2019-07-31 10:57:24.751 +00:00 [INF] - Edge agent connected to IoT Hub via Amqp_Tcp_Only. <6> 2019-07-31 10:57:29.016 +00:00 [INF] - Initialized new module client with subscriptions enabled <4> 2019-07-31 10:57:30.577 +00:00 [WRN] - Empty edge agent config was received. Attempting to read config from backup file (backup.json) instead <6> 2019-07-31 10:57:31.006 +00:00 [INF] - Obtained Edge agent twin from IoTHub with desired properties version 5 and reported properties version 64. <6> 2019-07-31 10:57:31.145 +00:00 [INF] - Obtained edge agent config from backup config file - backup.json <6> 2019-07-31 10:57:33.065 +00:00 [INF] - Module 'moxa' scheduled to restart after 05m:00s (04m:02s left). <6> 2019-07-31 10:57:33.071 +00:00 [INF] - Module 'edgeHub' scheduled to restart after 05m:00s (04m:03s left). ----- edgeHub Log: ----- <7> 2019-07-31 10:48:45.544 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Edged.WorkloadClient] - Received a valid Http response from unix:///var/run/iotedge/workload.sock for Decrypt <7> 2019-07-31 10:48:45.585 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Edged.WorkloadClient] - Making a Http call to unix:///var/run/iotedge/workload.sock to Decrypt <7> 2019-07-31 10:48:45.590 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Connecting socket /var/run/iotedge/workload.sock <7> 2019-07-31 10:48:45.595 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Connected socket /var/run/iotedge/workload.sock <7> 2019-07-31 10:48:45.598 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Sending request http://workload.sock/modules/%24edgeHub/genid/636991296573155410/decrypt?api-version=2019-01-30 <7> 2019-07-31 10:48:45.871 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Response received OK <7> 2019-07-31 10:48:45.875 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Edged.WorkloadClient] - Received a valid Http response from unix:///var/run/iotedge/workload.sock for Decrypt <7> 2019-07-31 10:48:45.881 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Edged.WorkloadClient] - Making a Http call to unix:///var/run/iotedge/workload.sock to Decrypt <7> 2019-07-31 10:48:45.887 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Connecting socket /var/run/iotedge/workload.sock <7> 2019-07-31 10:48:45.890 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Connected socket /var/run/iotedge/workload.sock <7> 2019-07-31 10:48:45.894 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Sending request http://workload.sock/modules/%24edgeHub/genid/636991296573155410/decrypt?api-version=2019-01-30 <6> 2019-07-31 10:48:46.159 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Created new message store <6> 2019-07-31 10:48:46.165 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Started task to cleanup processed and stale messages <7> 2019-07-31 10:48:46.179 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Response received OK <7> 2019-07-31 10:48:46.187 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Edged.WorkloadClient] - Received a valid Http response from unix:///var/run/iotedge/workload.sock for Decrypt <6> 2019-07-31 10:48:46.612 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Core.IDeviceScopeIdentitiesCache] - Created device scope identities cache <7> 2019-07-31 10:48:46.672 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.IDeviceScopeIdentitiesCache] - Initializing device scope identities cache refresh task to run every 60 minutes. <6> 2019-07-31 10:48:46.907 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Core.IDeviceScopeIdentitiesCache] - Starting refresh of device scope identities cache <7> 2019-07-31 10:48:46.957 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ServiceProxy] - Created iterator to iterate all service identities in the scope of this IoT Edge device <7> 2019-07-31 10:48:47.939 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Edged.WorkloadClient] - Making a Http call to unix:///var/run/iotedge/workload.sock to SignAsync <7> 2019-07-31 10:48:49.042 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Connecting socket /var/run/iotedge/workload.sock <7> 2019-07-31 10:48:49.047 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Connected socket /var/run/iotedge/workload.sock <7> 2019-07-31 10:48:49.051 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Sending request http://workload.sock/modules/%24edgeHub/genid/636991296573155410/sign?api-version=2019-01-30 <7> 2019-07-31 10:48:49.323 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Response received OK <7> 2019-07-31 10:48:49.591 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Edged.WorkloadClient] - Received a valid Http response from unix:///var/run/iotedge/workload.sock for SignAsync <6> 2019-07-31 10:48:52.017 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.DeviceConnectivityManager] - Created DeviceConnectivityManager with connected check frequency 00:05:00 and disconnected check frequency 00:02:00 <6> 2019-07-31 10:48:53.249 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Core.Twin.StoringTwinManager] - Initialized storing twin manager <7> 2019-07-31 10:48:53.769 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.DeviceConnectivityManager] - ConnectionManager provided <6> 2019-07-31 10:48:53.898 +00:00 [INF] [EdgeHub] - Initializing configuration <6> 2019-07-31 10:48:54.980 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Core.ConnectionManager] - New device connection for device kevinEdge0719/$edgeHub <7> 2019-07-31 10:48:55.087 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.SubscriptionProcessor] - Adding subscription DesiredPropertyUpdates for client kevinEdge0719/$edgeHub. <7> 2019-07-31 10:48:55.463 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.SubscriptionProcessor] - Adding subscription Methods for client kevinEdge0719/$edgeHub. <7> 2019-07-31 10:48:57.412 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Twin.StoringTwinManager] - Updating reported properties for kevinEdge0719/$edgeHub <7> 2019-07-31 10:48:57.673 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.IDeviceScopeIdentitiesCache] - Getting service identity for kevinEdge0719/$edgeHub <7> 2019-07-31 10:48:58.111 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudConnection] - Creating cloud connection for client kevinEdge0719/$edgeHub using EdgeHub credentials <7> 2019-07-31 10:48:58.243 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Twin.StoringTwinManager] - Updating reported properties for kevinEdge0719/$edgeHub <6> 2019-07-31 10:49:01.124 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudConnection] - Attempting to connect to IoT Hub for client kevinEdge0719/$edgeHub via AMQP... <7> 2019-07-31 10:49:02.869 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Twin.StoringTwinManager] - Merged reported properties in store for kevinEdge0719/$edgeHub <7> 2019-07-31 10:49:02.871 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.DeviceScopeApiClient] - Got valid device scope result <7> 2019-07-31 10:49:03.092 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ServiceProxy] - Received scope result with 1 devices, 3 modules and null continuation link <7> 2019-07-31 10:49:04.113 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Twin.StoringTwinManager] - Storing reported properties in store for kevinEdge0719/$edgeHub with version 0 <7> 2019-07-31 10:49:04.257 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Twin.StoringTwinManager] - Updating reported properties in store with version 0 for kevinEdge0719/$edgeHub <7> 2019-07-31 10:49:04.700 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.EdgeHubConnection] - Initialized connection for kevinEdge0719/$edgeHub <7> 2019-07-31 10:49:04.896 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Twin.StoringTwinManager] - Syncing stored reported properties to cloud in kevinEdge0719/$edgeHub <7> 2019-07-31 10:49:05.011 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Twin.StoringTwinManager] - Found stored reported properties for kevinEdge0719/$edgeHub to sync to cloud <7> 2019-07-31 10:49:05.560 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Edged.WorkloadClient] - Making a Http call to unix:///var/run/iotedge/workload.sock to Encrypt <6> 2019-07-31 10:49:05.619 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Core.Config.ConfigUpdater] - Starting periodic operation Get EdgeHub config... <7> 2019-07-31 10:49:05.777 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Twin.StoringTwinManager] - Updating reported properties for kevinEdge0719/$edgeHub <7> 2019-07-31 10:49:06.742 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Connecting socket /var/run/iotedge/workload.sock <7> 2019-07-31 10:49:06.748 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Connected socket /var/run/iotedge/workload.sock <7> 2019-07-31 10:49:06.753 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Sending request http://workload.sock/modules/%24edgeHub/genid/636991296573155410/encrypt?api-version=2019-01-30 <7> 2019-07-31 10:49:07.045 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Response received OK <7> 2019-07-31 10:49:07.299 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Edged.WorkloadClient] - Received a valid Http response from unix:///var/run/iotedge/workload.sock for Encrypt <7> 2019-07-31 10:49:07.435 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Twin.StoringTwinManager] - Getting twin for kevinEdge0719/$edgeHub <7> 2019-07-31 10:49:07.987 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.IDeviceScopeIdentitiesCache] - kevinEdge0719 is in device scope, adding to cache. <6> 2019-07-31 10:49:08.016 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Core.Config.ConfigUpdater] - Started operation Get EdgeHub config <6> 2019-07-31 10:49:08.087 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Core.Config.ConfigUpdater] - Initialized edge hub configuration <7> 2019-07-31 10:49:08.115 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Edged.WorkloadClient] - Making a Http call to unix:///var/run/iotedge/workload.sock to Encrypt <7> 2019-07-31 10:49:08.123 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Connecting socket /var/run/iotedge/workload.sock <7> 2019-07-31 10:49:08.130 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Connected socket /var/run/iotedge/workload.sock <7> 2019-07-31 10:49:08.134 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Sending request http://workload.sock/modules/%24edgeHub/genid/636991296573155410/encrypt?api-version=2019-01-30 <7> 2019-07-31 10:49:08.399 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Response received OK <7> 2019-07-31 10:49:08.408 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Edged.WorkloadClient] - Received a valid Http response from unix:///var/run/iotedge/workload.sock for Encrypt <7> 2019-07-31 10:49:08.418 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.IDeviceScopeIdentitiesCache] - kevinEdge0719/$edgeAgent is in device scope, adding to cache. <7> 2019-07-31 10:49:08.425 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Edged.WorkloadClient] - Making a Http call to unix:///var/run/iotedge/workload.sock to Encrypt <7> 2019-07-31 10:49:08.432 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Connecting socket /var/run/iotedge/workload.sock <7> 2019-07-31 10:49:08.438 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Connected socket /var/run/iotedge/workload.sock <7> 2019-07-31 10:49:08.443 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Sending request http://workload.sock/modules/%24edgeHub/genid/636991296573155410/encrypt?api-version=2019-01-30 <7> 2019-07-31 10:49:08.723 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Response received OK <7> 2019-07-31 10:49:08.728 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Edged.WorkloadClient] - Received a valid Http response from unix:///var/run/iotedge/workload.sock for Encrypt <7> 2019-07-31 10:49:08.737 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.IDeviceScopeIdentitiesCache] - kevinEdge0719/$edgeHub is in device scope, adding to cache. <7> 2019-07-31 10:49:08.745 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Edged.WorkloadClient] - Making a Http call to unix:///var/run/iotedge/workload.sock to Encrypt <7> 2019-07-31 10:49:08.751 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Connecting socket /var/run/iotedge/workload.sock <7> 2019-07-31 10:49:08.756 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Connected socket /var/run/iotedge/workload.sock <7> 2019-07-31 10:49:08.766 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Sending request http://workload.sock/modules/%24edgeHub/genid/636991296573155410/encrypt?api-version=2019-01-30 <7> 2019-07-31 10:49:09.042 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Response received OK <7> 2019-07-31 10:49:09.046 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Edged.WorkloadClient] - Received a valid Http response from unix:///var/run/iotedge/workload.sock for Encrypt <7> 2019-07-31 10:49:09.053 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.IDeviceScopeIdentitiesCache] - kevinEdge0719/moxa is in device scope, adding to cache. <7> 2019-07-31 10:49:09.165 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.IDeviceScopeIdentitiesCache] - Done refreshing device scope identities cache. Waiting for 60 minutes. <6> 2019-07-31 10:49:09.355 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Core.ConnectionReauthenticator] - Starting timer to authenticate connections with a period of 300 seconds <7> 2019-07-31 10:49:09.474 +00:00 [DBG] [EdgeHub] - Waiting on shutdown handler to trigger <7> 2019-07-31 10:49:10.739 +00:00 [DBG] [DotNetty.Common.Internal.PlatformDependent] - -Dio.netty.noPreferDirect: True <6> 2019-07-31 10:49:12.437 +00:00 [INF] [EdgeHub] - Scheduling server certificate renewal for "2019-10-29T04:55:55.0067816Z". <7> 2019-07-31 10:49:12.442 +00:00 [DBG] [EdgeHub] - Scheduling server certificate renewal timer for "2019-08-25T07:20:36.0886880Z" (clamped to Int32.MaxValue). <6> 2019-07-31 10:49:12.535 +00:00 [INF] [EdgeHub] - Starting protocol heads - (MQTT) <6> 2019-07-31 10:49:12.777 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Mqtt.MqttProtocolHead] - Starting MQTT head <6> 2019-07-31 10:49:14.214 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Mqtt.MqttProtocolHead] - Initializing TLS endpoint on port 8883 for MQTT head. <7> 2019-07-31 10:49:14.731 +00:00 [DBG] [DotNetty.Transport.Channels.DefaultChannelId] - -Dio.netty.processId: 2393741 (auto-detected) <7> 2019-07-31 10:49:15.218 +00:00 [DBG] [DotNetty.Transport.Channels.DefaultChannelId] - -Dio.netty.machineId: 02:42:AC:FF:FE:13:00:02 (auto-detected) <7> 2019-07-31 10:49:15.374 +00:00 [DBG] [DotNetty.Buffers.PooledByteBufferAllocator] - -Dio.netty.allocator.numHeapArenas: 2 <7> 2019-07-31 10:49:15.378 +00:00 [DBG] [DotNetty.Buffers.PooledByteBufferAllocator] - -Dio.netty.allocator.numDirectArenas: 2 <7> 2019-07-31 10:49:15.381 +00:00 [DBG] [DotNetty.Buffers.PooledByteBufferAllocator] - -Dio.netty.allocator.pageSize: 8192 <7> 2019-07-31 10:49:15.383 +00:00 [DBG] [DotNetty.Buffers.PooledByteBufferAllocator] - -Dio.netty.allocator.maxOrder: 11 <7> 2019-07-31 10:49:15.385 +00:00 [DBG] [DotNetty.Buffers.PooledByteBufferAllocator] - -Dio.netty.allocator.chunkSize: 16777216 <7> 2019-07-31 10:49:15.389 +00:00 [DBG] [DotNetty.Buffers.PooledByteBufferAllocator] - -Dio.netty.allocator.tinyCacheSize: 512 <7> 2019-07-31 10:49:15.391 +00:00 [DBG] [DotNetty.Buffers.PooledByteBufferAllocator] - -Dio.netty.allocator.smallCacheSize: 256 <7> 2019-07-31 10:49:15.395 +00:00 [DBG] [DotNetty.Buffers.PooledByteBufferAllocator] - -Dio.netty.allocator.normalCacheSize: 64 <7> 2019-07-31 10:49:15.397 +00:00 [DBG] [DotNetty.Buffers.PooledByteBufferAllocator] - -Dio.netty.allocator.maxCachedBufferCapacity: 32768 <7> 2019-07-31 10:49:15.401 +00:00 [DBG] [DotNetty.Buffers.PooledByteBufferAllocator] - -Dio.netty.allocator.cacheTrimInterval: 8192 <7> 2019-07-31 10:49:15.716 +00:00 [DBG] [DotNetty.Buffers.ByteBufferUtil] - -Dio.netty.allocator.type: pooled <7> 2019-07-31 10:49:15.851 +00:00 [DBG] [DotNetty.Common.ResourceLeakDetector] - -Dio.netty.leakDetection.level: simple <7> 2019-07-31 10:49:15.854 +00:00 [DBG] [DotNetty.Common.ResourceLeakDetector] - -Dio.netty.leakDetection.targetRecords: 4 <6> 2019-07-31 10:49:17.950 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Mqtt.MqttProtocolHead] - Started MQTT head <7> 2019-07-31 10:49:19.100 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Edged.WorkloadClient] - Making a Http call to unix:///var/run/iotedge/workload.sock to SignAsync <7> 2019-07-31 10:49:19.103 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Connecting socket /var/run/iotedge/workload.sock <7> 2019-07-31 10:49:19.106 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Connected socket /var/run/iotedge/workload.sock <7> 2019-07-31 10:49:19.108 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Sending request http://workload.sock/modules/%24edgeHub/genid/636991296573155410/sign?api-version=2019-01-30 <7> 2019-07-31 10:49:19.387 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Response received OK <7> 2019-07-31 10:49:19.391 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Edged.WorkloadClient] - Received a valid Http response from unix:///var/run/iotedge/workload.sock for SignAsync <7> 2019-07-31 10:49:24.221 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ConnectivityAwareClient] - Received connection status changed callback with connection status Connected and reason Connection_Ok for kevinEdge0719/$edgeHub <7> 2019-07-31 10:49:24.593 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.DeviceConnectivityManager] - IotHub call succeeded <6> 2019-07-31 10:49:25.008 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.DeviceConnectivityManager] - Exiting disconnected state <6> 2019-07-31 10:49:25.066 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Core.Twin.StoringTwinManager] - Received device connected callback <7> 2019-07-31 10:49:25.101 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Twin.StoringTwinManager] - Syncing stored reported properties to cloud in kevinEdge0719/$edgeHub <6> 2019-07-31 10:49:25.270 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Core.SubscriptionProcessor] - Device connected to cloud, processing subscriptions for connected clients. <6> 2019-07-31 10:49:25.282 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Core.SubscriptionProcessor] - Processing subscriptions for client kevinEdge0719/$edgeHub. <6> 2019-07-31 10:49:25.380 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ConnectivityAwareClient] - Cloud connection for kevinEdge0719/$edgeHub is True <6> 2019-07-31 10:49:25.483 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Core.ConnectionManager] - Connection status for kevinEdge0719/$edgeHub changed to ConnectionEstablished <7> 2019-07-31 10:49:25.492 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.ConnectionManager] - Invoking cloud connection established event for kevinEdge0719/$edgeHub <7> 2019-07-31 10:49:25.501 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.ConnectionReauthenticator] - EdgeHub cloud connection established, refreshing device scope cache. <7> 2019-07-31 10:49:25.516 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.IDeviceScopeIdentitiesCache] - Received request to refresh cache. <7> 2019-07-31 10:49:25.562 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.IDeviceScopeIdentitiesCache] - Device scope identities refresh is ready because a refresh was signalled. <6> 2019-07-31 10:49:25.566 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Core.IDeviceScopeIdentitiesCache] - Starting refresh of device scope identities cache <7> 2019-07-31 10:49:25.569 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ServiceProxy] - Created iterator to iterate all service identities in the scope of this IoT Edge device <7> 2019-07-31 10:49:25.575 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Edged.WorkloadClient] - Making a Http call to unix:///var/run/iotedge/workload.sock to SignAsync <7> 2019-07-31 10:49:25.581 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Connecting socket /var/run/iotedge/workload.sock <7> 2019-07-31 10:49:25.585 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Connected socket /var/run/iotedge/workload.sock <7> 2019-07-31 10:49:25.588 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Sending request http://workload.sock/modules/%24edgeHub/genid/636991296573155410/sign?api-version=2019-01-30 <7> 2019-07-31 10:49:25.867 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Response received OK <7> 2019-07-31 10:49:25.872 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Edged.WorkloadClient] - Received a valid Http response from unix:///var/run/iotedge/workload.sock for SignAsync <6> 2019-07-31 10:49:25.928 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.DeviceConnectivityManager] - Entering connected state <7> 2019-07-31 10:49:25.978 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ConnectivityAwareClient] - Operation OpenAsync succeeded for kevinEdge0719/$edgeHub <6> 2019-07-31 10:49:26.014 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudConnection] - Created cloud proxy for client kevinEdge0719/$edgeHub via AMQP, with client operation timeout 20 seconds. <6> 2019-07-31 10:49:26.124 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudProxy] - Initialized cloud proxy 8ef2be69-32af-4c57-b78f-a4eefeae15e1 for kevinEdge0719/$edgeHub <6> 2019-07-31 10:49:26.154 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudConnection] - Created cloud connection for client kevinEdge0719/$edgeHub <7> 2019-07-31 10:49:26.402 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.ConnectionManager] - Obtained cloud connection for device kevinEdge0719/$edgeHub <7> 2019-07-31 10:49:26.719 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.SubscriptionProcessor] - Processing subscription DesiredPropertyUpdates for client kevinEdge0719/$edgeHub. <7> 2019-07-31 10:49:27.094 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.DeviceScopeApiClient] - Got valid device scope result <7> 2019-07-31 10:49:27.106 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ServiceProxy] - Received scope result with 1 devices, 3 modules and null continuation link <7> 2019-07-31 10:49:27.112 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Edged.WorkloadClient] - Making a Http call to unix:///var/run/iotedge/workload.sock to Encrypt <7> 2019-07-31 10:49:27.123 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Connecting socket /var/run/iotedge/workload.sock <7> 2019-07-31 10:49:27.125 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Connected socket /var/run/iotedge/workload.sock <7> 2019-07-31 10:49:27.128 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Sending request http://workload.sock/modules/%24edgeHub/genid/636991296573155410/encrypt?api-version=2019-01-30 <7> 2019-07-31 10:49:27.533 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Response received OK <7> 2019-07-31 10:49:27.544 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Edged.WorkloadClient] - Received a valid Http response from unix:///var/run/iotedge/workload.sock for Encrypt <7> 2019-07-31 10:49:27.556 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.IDeviceScopeIdentitiesCache] - kevinEdge0719 is in device scope, adding to cache. <7> 2019-07-31 10:49:27.561 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Edged.WorkloadClient] - Making a Http call to unix:///var/run/iotedge/workload.sock to Encrypt <7> 2019-07-31 10:49:27.574 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Connecting socket /var/run/iotedge/workload.sock <7> 2019-07-31 10:49:27.581 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Connected socket /var/run/iotedge/workload.sock <7> 2019-07-31 10:49:27.585 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Sending request http://workload.sock/modules/%24edgeHub/genid/636991296573155410/encrypt?api-version=2019-01-30 <7> 2019-07-31 10:49:27.864 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Response received OK <7> 2019-07-31 10:49:27.870 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Edged.WorkloadClient] - Received a valid Http response from unix:///var/run/iotedge/workload.sock for Encrypt <7> 2019-07-31 10:49:27.876 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.IDeviceScopeIdentitiesCache] - kevinEdge0719/$edgeAgent is in device scope, adding to cache. <7> 2019-07-31 10:49:27.880 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Edged.WorkloadClient] - Making a Http call to unix:///var/run/iotedge/workload.sock to Encrypt <7> 2019-07-31 10:49:27.886 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Connecting socket /var/run/iotedge/workload.sock <7> 2019-07-31 10:49:27.891 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Connected socket /var/run/iotedge/workload.sock <7> 2019-07-31 10:49:27.894 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Sending request http://workload.sock/modules/%24edgeHub/genid/636991296573155410/encrypt?api-version=2019-01-30 <7> 2019-07-31 10:49:28.152 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Response received OK <7> 2019-07-31 10:49:28.156 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Edged.WorkloadClient] - Received a valid Http response from unix:///var/run/iotedge/workload.sock for Encrypt <7> 2019-07-31 10:49:28.163 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.IDeviceScopeIdentitiesCache] - kevinEdge0719/$edgeHub is in device scope, adding to cache. <7> 2019-07-31 10:49:28.168 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Edged.WorkloadClient] - Making a Http call to unix:///var/run/iotedge/workload.sock to Encrypt <7> 2019-07-31 10:49:28.173 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Connecting socket /var/run/iotedge/workload.sock <7> 2019-07-31 10:49:28.177 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Connected socket /var/run/iotedge/workload.sock <7> 2019-07-31 10:49:28.181 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Sending request http://workload.sock/modules/%24edgeHub/genid/636991296573155410/encrypt?api-version=2019-01-30 <7> 2019-07-31 10:49:28.463 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Response received OK <7> 2019-07-31 10:49:28.467 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Edged.WorkloadClient] - Received a valid Http response from unix:///var/run/iotedge/workload.sock for Encrypt <7> 2019-07-31 10:49:28.473 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.IDeviceScopeIdentitiesCache] - kevinEdge0719/moxa is in device scope, adding to cache. <7> 2019-07-31 10:49:28.508 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.IDeviceScopeIdentitiesCache] - Done refreshing device scope identities cache. Waiting for 60 minutes. <7> 2019-07-31 10:49:28.742 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.ConnectionManager] - Obtained cloud connection for device kevinEdge0719/$edgeHub <7> 2019-07-31 10:49:29.200 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.ConnectionManager] - Obtained cloud connection for device kevinEdge0719/$edgeHub <7> 2019-07-31 10:49:30.032 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.ConnectionManager] - Obtained cloud connection for device kevinEdge0719/$edgeHub <7> 2019-07-31 10:49:30.140 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.SubscriptionProcessor] - Processing subscription DesiredPropertyUpdates for client kevinEdge0719/$edgeHub. <7> 2019-07-31 10:49:30.442 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ConnectivityAwareClient] - Operation SetDesiredPropertyUpdateCallbackAsync succeeded for kevinEdge0719/$edgeHub <7> 2019-07-31 10:49:30.445 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ConnectivityAwareClient] - Operation SetDesiredPropertyUpdateCallbackAsync succeeded for kevinEdge0719/$edgeHub <7> 2019-07-31 10:49:30.657 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.SubscriptionProcessor] - Processing subscription Methods for client kevinEdge0719/$edgeHub. <7> 2019-07-31 10:49:30.723 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.SubscriptionProcessor] - Processing subscription Methods for client kevinEdge0719/$edgeHub. <7> 2019-07-31 10:49:32.518 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.DeviceConnectivityManager] - IotHub call succeeded <7> 2019-07-31 10:49:32.717 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ConnectivityAwareClient] - Operation GetTwinAsync succeeded for kevinEdge0719/$edgeHub <7> 2019-07-31 10:49:32.745 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudProxy] - Getting twin for device kevinEdge0719/$edgeHub <7> 2019-07-31 10:49:32.945 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Twin.StoringTwinManager] - Got twin for kevinEdge0719/$edgeHub <7> 2019-07-31 10:49:33.098 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Twin.StoringTwinManager] - Got twin for kevinEdge0719/$edgeHub from cloud <7> 2019-07-31 10:49:33.324 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Twin.StoringTwinManager] - Updating twin in store for kevinEdge0719/$edgeHub <7> 2019-07-31 10:49:33.364 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Twin.StoringTwinManager] - Updated twin in store for kevinEdge0719/$edgeHub <6> 2019-07-31 10:49:36.857 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.CloudEndpoint] - Created cloud endpoint iothub with max batch size 10 and fan-out factor of 10. <7> 2019-07-31 10:49:37.074 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Twin.StoringTwinManager] - Updating reported properties for kevinEdge0719/$edgeHub <7> 2019-07-31 10:49:37.084 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Twin.StoringTwinManager] - Updating reported properties for kevinEdge0719/$edgeHub <7> 2019-07-31 10:49:37.118 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Twin.StoringTwinManager] - Merged reported properties in store for kevinEdge0719/$edgeHub <7> 2019-07-31 10:49:37.225 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.DeviceConnectivityManager] - IotHub call succeeded <7> 2019-07-31 10:49:37.228 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ConnectivityAwareClient] - Operation UpdateReportedPropertiesAsync succeeded for kevinEdge0719/$edgeHub <7> 2019-07-31 10:49:37.252 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudProxy] - Updating reported properties for device kevinEdge0719/$edgeHub <6> 2019-07-31 10:49:37.275 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Core.Twin.StoringTwinManager] - Updated reported properties for kevinEdge0719/$edgeHub <7> 2019-07-31 10:49:37.299 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Twin.StoringTwinManager] - Updated reported properties for kevinEdge0719/$edgeHub <7> 2019-07-31 10:49:37.480 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Twin.StoringTwinManager] - Found stored reported properties for kevinEdge0719/$edgeHub to sync to cloud <7> 2019-07-31 10:49:37.491 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Twin.StoringTwinManager] - Storing reported properties in store for kevinEdge0719/$edgeHub with version 0 <7> 2019-07-31 10:49:37.497 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Twin.StoringTwinManager] - Updating reported properties in store with version 0 for kevinEdge0719/$edgeHub <6> 2019-07-31 10:49:37.528 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Core.EdgeHubConnection] - Obtained edge hub config from module twin <7> 2019-07-31 10:49:37.992 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.DeviceConnectivityManager] - IotHub call succeeded <7> 2019-07-31 10:49:37.999 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ConnectivityAwareClient] - Operation SetMethodDefaultHandlerAsync succeeded for kevinEdge0719/$edgeHub <7> 2019-07-31 10:49:37.993 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.DeviceConnectivityManager] - IotHub call succeeded <7> 2019-07-31 10:49:38.007 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ConnectivityAwareClient] - Operation SetMethodDefaultHandlerAsync succeeded for kevinEdge0719/$edgeHub <7> 2019-07-31 10:49:38.151 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Twin.StoringTwinManager] - Twin for kevinEdge0719/$edgeHub synced at 07/31/2019 10:49:33 which is sooner than twin sync period 120 secs, skipping syncing twin <7> 2019-07-31 10:49:38.172 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.InvokeMethodHandler] - Processing pending method invoke requests for client kevinEdge0719/$edgeHub. <7> 2019-07-31 10:49:38.171 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.InvokeMethodHandler] - Processing pending method invoke requests for client kevinEdge0719/$edgeHub. <7> 2019-07-31 10:49:41.632 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Added sequential store for endpoint iothub <6> 2019-07-31 10:49:41.949 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Core.Config.ConfigUpdater] - Set the following 1 route(s) in edge hub <6> 2019-07-31 10:49:41.953 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Core.Config.ConfigUpdater] - route: FROM /messages/* INTO $upstream <6> 2019-07-31 10:49:42.032 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Updated message store TTL to 7200 seconds <6> 2019-07-31 10:49:42.047 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Core.Config.ConfigUpdater] - Updated the edge hub store and forward configuration <6> 2019-07-31 10:49:42.091 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Core.Config.ConfigUpdater] - Successfully completed periodic operation Get EdgeHub config <7> 2019-07-31 10:49:42.285 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Getting next batch for endpoint iothub starting from 6 with batch size 100. <7> 2019-07-31 10:49:42.418 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Obtained next batch for endpoint iothub with batch size 0. Next start offset = 6. <7> 2019-07-31 10:49:42.460 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Twin.StoringTwinManager] - Syncing stored reported properties to cloud in kevinEdge0719/$edgeHub <7> 2019-07-31 10:49:42.467 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Twin.StoringTwinManager] - Found stored reported properties for kevinEdge0719/$edgeHub to sync to cloud <7> 2019-07-31 10:49:42.476 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Twin.StoringTwinManager] - Updating reported properties for kevinEdge0719/$edgeHub <7> 2019-07-31 10:49:42.529 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.ConnectionManager] - Obtained cloud connection for device kevinEdge0719/$edgeHub <7> 2019-07-31 10:49:42.630 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Getting next batch for endpoint iothub starting from 6 with batch size 100. <7> 2019-07-31 10:49:42.632 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Obtained next batch for endpoint iothub with batch size 0. Next start offset = 6. <7> 2019-07-31 10:49:42.861 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.DeviceConnectivityManager] - IotHub call succeeded <7> 2019-07-31 10:49:42.863 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ConnectivityAwareClient] - Operation UpdateReportedPropertiesAsync succeeded for kevinEdge0719/$edgeHub <7> 2019-07-31 10:49:42.865 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudProxy] - Updating reported properties for device kevinEdge0719/$edgeHub <6> 2019-07-31 10:49:42.867 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Core.Twin.StoringTwinManager] - Updated reported properties for kevinEdge0719/$edgeHub <7> 2019-07-31 10:49:42.869 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Twin.StoringTwinManager] - Updated reported properties for kevinEdge0719/$edgeHub <7> 2019-07-31 10:49:52.598 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Getting next batch for endpoint iothub starting from 6 with batch size 100. <7> 2019-07-31 10:49:52.601 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Obtained next batch for endpoint iothub with batch size 0. Next start offset = 6. <7> 2019-07-31 10:49:56.020 +00:00 [DBG] [DotNetty.Buffers.AbstractByteBuffer] - -Dio.netty.buffer.bytebuf.checkAccessible: True <7> 2019-07-31 10:49:57.891 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.IDeviceScopeIdentitiesCache] - Getting service identity for kevinEdge0719/moxa <6> 2019-07-31 10:49:58.159 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Core.DeviceScopeAuthenticator] - Client kevinEdge0719/moxa in device scope authenticated locally. <7> 2019-07-31 10:49:58.181 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Authenticator] - Client kevinEdge0719/moxa authenticated successfully <6> 2019-07-31 10:49:58.381 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Mqtt.DeviceIdentityProvider] - Successfully generated identity for clientId kevinEdge0719/moxa and username thingspro-IoTHub-newTwin.azure-devices.net/kevinEdge0719/moxa/?api-version=2017-11-08-preview&DeviceClientType=iothubclient%2f1.3.3%20(native%3b%20Linux%3b%20armv7l) <6> 2019-07-31 10:49:58.449 +00:00 [INF] [EdgeHub] - ClientAuthenticated, kevinEdge0719/moxa, 05523c95 <6> 2019-07-31 10:49:59.107 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Core.ConnectionManager] - New device connection for device kevinEdge0719/moxa <7> 2019-07-31 10:49:59.163 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.EdgeHubConnection] - Updating device kevinEdge0719/moxa connection status to Connected <7> 2019-07-31 10:49:59.244 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Twin.StoringTwinManager] - Updating reported properties for kevinEdge0719/$edgeHub <7> 2019-07-31 10:49:59.249 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Twin.StoringTwinManager] - Updating reported properties for kevinEdge0719/$edgeHub <7> 2019-07-31 10:49:59.257 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Twin.StoringTwinManager] - Merged reported properties in store for kevinEdge0719/$edgeHub <7> 2019-07-31 10:49:59.264 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Twin.StoringTwinManager] - Storing reported properties in store for kevinEdge0719/$edgeHub with version 0 <7> 2019-07-31 10:49:59.269 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Twin.StoringTwinManager] - Updating reported properties in store with version 0 for kevinEdge0719/$edgeHub <7> 2019-07-31 10:49:59.274 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Twin.StoringTwinManager] - Syncing stored reported properties to cloud in kevinEdge0719/$edgeHub <7> 2019-07-31 10:49:59.281 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Twin.StoringTwinManager] - Found stored reported properties for kevinEdge0719/$edgeHub to sync to cloud <7> 2019-07-31 10:49:59.308 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Twin.StoringTwinManager] - Updating reported properties for kevinEdge0719/$edgeHub <7> 2019-07-31 10:49:59.312 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.ConnectionManager] - Obtained cloud connection for device kevinEdge0719/$edgeHub <6> 2019-07-31 10:49:59.349 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Core.Device.DeviceMessageHandler] - Bind device proxy for device kevinEdge0719/moxa <6> 2019-07-31 10:49:59.383 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Mqtt.MessagingServiceClient] - Binding message channel for device Id kevinEdge0719/moxa <7> 2019-07-31 10:49:59.613 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.DeviceConnectivityManager] - IotHub call succeeded <7> 2019-07-31 10:49:59.615 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ConnectivityAwareClient] - Operation UpdateReportedPropertiesAsync succeeded for kevinEdge0719/$edgeHub <7> 2019-07-31 10:49:59.620 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudProxy] - Updating reported properties for device kevinEdge0719/$edgeHub <6> 2019-07-31 10:49:59.623 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Core.Twin.StoringTwinManager] - Updated reported properties for kevinEdge0719/$edgeHub <7> 2019-07-31 10:49:59.626 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Twin.StoringTwinManager] - Updated reported properties for kevinEdge0719/$edgeHub <6> 2019-07-31 10:50:00.060 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Core.SubscriptionProcessor] - Processing subscriptions TwinResponse, DesiredPropertyUpdates, Methods for client kevinEdge0719/moxa. <7> 2019-07-31 10:50:00.069 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.IDeviceScopeIdentitiesCache] - Getting service identity for kevinEdge0719/moxa <7> 2019-07-31 10:50:00.072 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudConnection] - Creating cloud connection for client kevinEdge0719/moxa using EdgeHub credentials <6> 2019-07-31 10:50:00.079 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudConnection] - Attempting to connect to IoT Hub for client kevinEdge0719/moxa via AMQP... <6> 2019-07-31 10:50:00.212 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Mqtt.SessionStateStoragePersistenceProvider] - Set subscriptions from session state for kevinEdge0719/moxa <7> 2019-07-31 10:50:00.290 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Edged.WorkloadClient] - Making a Http call to unix:///var/run/iotedge/workload.sock to SignAsync <7> 2019-07-31 10:50:00.294 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Connecting socket /var/run/iotedge/workload.sock <7> 2019-07-31 10:50:00.299 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Connected socket /var/run/iotedge/workload.sock <7> 2019-07-31 10:50:00.301 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Sending request http://workload.sock/modules/%24edgeHub/genid/636991296573155410/sign?api-version=2019-01-30 <7> 2019-07-31 10:50:00.575 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Response received OK <7> 2019-07-31 10:50:00.580 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Edged.WorkloadClient] - Received a valid Http response from unix:///var/run/iotedge/workload.sock for SignAsync <7> 2019-07-31 10:50:00.937 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ConnectivityAwareClient] - Received connection status changed callback with connection status Connected and reason Connection_Ok for kevinEdge0719/moxa <7> 2019-07-31 10:50:00.941 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.DeviceConnectivityManager] - IotHub call succeeded <6> 2019-07-31 10:50:00.945 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ConnectivityAwareClient] - Cloud connection for kevinEdge0719/moxa is True <6> 2019-07-31 10:50:00.948 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Core.ConnectionManager] - Connection status for kevinEdge0719/moxa changed to ConnectionEstablished <7> 2019-07-31 10:50:00.951 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.ConnectionManager] - Invoking cloud connection established event for kevinEdge0719/moxa <7> 2019-07-31 10:50:00.955 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ConnectivityAwareClient] - Operation OpenAsync succeeded for kevinEdge0719/moxa <6> 2019-07-31 10:50:00.957 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudConnection] - Created cloud proxy for client kevinEdge0719/moxa via AMQP, with client operation timeout 20 seconds. <6> 2019-07-31 10:50:00.961 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudProxy] - Initialized cloud proxy fb1f20e2-fc06-4e8a-b9ec-f0eb98e086b5 for kevinEdge0719/moxa <6> 2019-07-31 10:50:00.964 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudConnection] - Created cloud connection for client kevinEdge0719/moxa <7> 2019-07-31 10:50:00.968 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.ConnectionManager] - Obtained cloud connection for device kevinEdge0719/moxa <7> 2019-07-31 10:50:00.971 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.SubscriptionProcessor] - Processing subscription TwinResponse for client kevinEdge0719/moxa. <7> 2019-07-31 10:50:00.991 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.SubscriptionProcessor] - Processing subscription DesiredPropertyUpdates for client kevinEdge0719/moxa. <7> 2019-07-31 10:50:01.047 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.RoutingEdgeHub] - GetTwin call received from kevinEdge0719/moxa <7> 2019-07-31 10:50:01.049 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Twin.StoringTwinManager] - Getting twin for kevinEdge0719/moxa <7> 2019-07-31 10:50:01.051 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.ConnectionManager] - Obtained cloud connection for device kevinEdge0719/moxa <7> 2019-07-31 10:50:01.179 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ConnectivityAwareClient] - Operation SetDesiredPropertyUpdateCallbackAsync succeeded for kevinEdge0719/moxa <7> 2019-07-31 10:50:01.184 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.SubscriptionProcessor] - Processing subscription Methods for client kevinEdge0719/moxa. <7> 2019-07-31 10:50:01.395 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.DeviceConnectivityManager] - IotHub call succeeded <7> 2019-07-31 10:50:01.397 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ConnectivityAwareClient] - Operation SetMethodDefaultHandlerAsync succeeded for kevinEdge0719/moxa <7> 2019-07-31 10:50:01.400 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.InvokeMethodHandler] - Processing pending method invoke requests for client kevinEdge0719/moxa. <7> 2019-07-31 10:50:01.420 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.DeviceConnectivityManager] - IotHub call succeeded <7> 2019-07-31 10:50:01.423 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ConnectivityAwareClient] - Operation GetTwinAsync succeeded for kevinEdge0719/moxa <7> 2019-07-31 10:50:01.425 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudProxy] - Getting twin for device kevinEdge0719/moxa <7> 2019-07-31 10:50:01.447 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Twin.StoringTwinManager] - Got twin for kevinEdge0719/moxa <7> 2019-07-31 10:50:01.449 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Twin.StoringTwinManager] - Got twin for kevinEdge0719/moxa from cloud <7> 2019-07-31 10:50:01.451 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Twin.StoringTwinManager] - Updating twin in store for kevinEdge0719/moxa <7> 2019-07-31 10:50:01.467 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Twin.StoringTwinManager] - Updated twin in store for kevinEdge0719/moxa <7> 2019-07-31 10:50:01.871 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Mqtt.DeviceProxy] - Sent twin update to kevinEdge0719/moxa <7> 2019-07-31 10:50:01.893 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Device.DeviceMessageHandler] - Processed GetTwin for kevinEdge0719/moxa <7> 2019-07-31 10:50:01.974 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Mqtt.MessagingServiceClient] - Getting twin for device Id kevinEdge0719/moxa <6> 2019-07-31 10:50:02.157 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Core.SubscriptionProcessor] - Processing subscriptions TwinResponse, DesiredPropertyUpdates, Methods for client kevinEdge0719/moxa. <7> 2019-07-31 10:50:02.176 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.ConnectionManager] - Obtained cloud connection for device kevinEdge0719/moxa <7> 2019-07-31 10:50:02.177 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.SubscriptionProcessor] - Processing subscription TwinResponse for client kevinEdge0719/moxa. <7> 2019-07-31 10:50:02.178 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.SubscriptionProcessor] - Processing subscription DesiredPropertyUpdates for client kevinEdge0719/moxa. <7> 2019-07-31 10:50:02.180 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ConnectivityAwareClient] - Operation SetDesiredPropertyUpdateCallbackAsync succeeded for kevinEdge0719/moxa <7> 2019-07-31 10:50:02.185 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.SubscriptionProcessor] - Processing subscription Methods for client kevinEdge0719/moxa. <6> 2019-07-31 10:50:02.192 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Mqtt.SessionStateStoragePersistenceProvider] - Set subscriptions from session state for kevinEdge0719/moxa <7> 2019-07-31 10:50:02.193 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.DeviceConnectivityManager] - IotHub call succeeded <7> 2019-07-31 10:50:02.197 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ConnectivityAwareClient] - Operation SetMethodDefaultHandlerAsync succeeded for kevinEdge0719/moxa <7> 2019-07-31 10:50:02.202 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.InvokeMethodHandler] - Processing pending method invoke requests for client kevinEdge0719/moxa. <7> 2019-07-31 10:50:02.616 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Getting next batch for endpoint iothub starting from 6 with batch size 100. <7> 2019-07-31 10:50:02.617 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Obtained next batch for endpoint iothub with batch size 0. Next start offset = 6. <7> 2019-07-31 10:50:02.626 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.RoutingEdgeHub] - Reported properties update message received from kevinEdge0719/moxa <7> 2019-07-31 10:50:02.627 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Twin.StoringTwinManager] - Updating reported properties for kevinEdge0719/moxa <7> 2019-07-31 10:50:02.628 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Twin.StoringTwinManager] - Updating reported properties for kevinEdge0719/moxa <7> 2019-07-31 10:50:03.540 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Twin.StoringTwinManager] - Merged reported properties in store for kevinEdge0719/moxa <7> 2019-07-31 10:50:03.546 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Twin.StoringTwinManager] - Storing reported properties in store for kevinEdge0719/moxa with version 0 <7> 2019-07-31 10:50:03.571 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Twin.StoringTwinManager] - Updating reported properties in store with version 0 for kevinEdge0719/moxa <7> 2019-07-31 10:50:03.669 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Mqtt.DeviceProxy] - Sent twin update to kevinEdge0719/moxa <7> 2019-07-31 10:50:03.680 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Mqtt.MessagingServiceClient] - Updating reported properties for device Id kevinEdge0719/moxa <7> 2019-07-31 10:50:04.639 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Twin.StoringTwinManager] - Syncing stored reported properties to cloud in kevinEdge0719/moxa <7> 2019-07-31 10:50:04.779 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Twin.StoringTwinManager] - Found stored reported properties for kevinEdge0719/moxa to sync to cloud <7> 2019-07-31 10:50:04.860 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Twin.StoringTwinManager] - Updating reported properties for kevinEdge0719/moxa <7> 2019-07-31 10:50:04.870 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.ConnectionManager] - Obtained cloud connection for device kevinEdge0719/moxa <7> 2019-07-31 10:50:05.394 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.DeviceConnectivityManager] - IotHub call succeeded <7> 2019-07-31 10:50:05.397 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ConnectivityAwareClient] - Operation UpdateReportedPropertiesAsync succeeded for kevinEdge0719/moxa <7> 2019-07-31 10:50:05.399 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudProxy] - Updating reported properties for device kevinEdge0719/moxa <6> 2019-07-31 10:50:05.402 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Core.Twin.StoringTwinManager] - Updated reported properties for kevinEdge0719/moxa <7> 2019-07-31 10:50:05.405 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Twin.StoringTwinManager] - Updated reported properties for kevinEdge0719/moxa <7> 2019-07-31 10:50:05.542 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Mqtt.MessagingServiceClient] - Processing message for device Id kevinEdge0719/moxa <7> 2019-07-31 10:50:05.578 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.RoutingEdgeHub] - Received message from kevinEdge0719/moxa <7> 2019-07-31 10:50:06.388 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Getting next batch for endpoint iothub starting from 6 with batch size 100. <7> 2019-07-31 10:50:06.539 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.RoutingEdgeHub] - Reported properties update message received from kevinEdge0719/moxa <7> 2019-07-31 10:50:06.542 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Twin.StoringTwinManager] - Updating reported properties for kevinEdge0719/moxa <7> 2019-07-31 10:50:06.546 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Twin.StoringTwinManager] - Updating reported properties for kevinEdge0719/moxa <7> 2019-07-31 10:50:06.614 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Twin.StoringTwinManager] - Merged reported properties in store for kevinEdge0719/moxa <7> 2019-07-31 10:50:06.624 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Twin.StoringTwinManager] - Storing reported properties in store for kevinEdge0719/moxa with version 0 <7> 2019-07-31 10:50:06.647 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Twin.StoringTwinManager] - Updating reported properties in store with version 0 for kevinEdge0719/moxa <7> 2019-07-31 10:50:06.670 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Mqtt.DeviceProxy] - Sent twin update to kevinEdge0719/moxa <7> 2019-07-31 10:50:06.673 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Mqtt.MessagingServiceClient] - Updating reported properties for device Id kevinEdge0719/moxa <7> 2019-07-31 10:50:06.677 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.RoutingEdgeHub] - Reported properties update message received from kevinEdge0719/moxa <7> 2019-07-31 10:50:06.681 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Twin.StoringTwinManager] - Updating reported properties for kevinEdge0719/moxa <7> 2019-07-31 10:50:06.705 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Twin.StoringTwinManager] - Updating reported properties for kevinEdge0719/moxa <7> 2019-07-31 10:50:06.767 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Twin.StoringTwinManager] - Merged reported properties in store for kevinEdge0719/moxa <7> 2019-07-31 10:50:06.777 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Twin.StoringTwinManager] - Storing reported properties in store for kevinEdge0719/moxa with version 0 <7> 2019-07-31 10:50:06.801 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Obtained next batch for endpoint iothub with batch size 1. Next start offset = 7. <7> 2019-07-31 10:50:06.806 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Getting next batch for endpoint iothub starting from 7 with batch size 99. <7> 2019-07-31 10:50:06.808 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Obtained next batch for endpoint iothub with batch size 0. Next start offset = 7. <7> 2019-07-31 10:50:06.804 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Twin.StoringTwinManager] - Updating reported properties in store with version 0 for kevinEdge0719/moxa <7> 2019-07-31 10:50:06.835 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Mqtt.DeviceProxy] - Sent twin update to kevinEdge0719/moxa <7> 2019-07-31 10:50:06.836 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Mqtt.MessagingServiceClient] - Updating reported properties for device Id kevinEdge0719/moxa <7> 2019-07-31 10:50:06.839 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.RoutingEdgeHub] - Reported properties update message received from kevinEdge0719/moxa <7> 2019-07-31 10:50:06.841 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Twin.StoringTwinManager] - Updating reported properties for kevinEdge0719/moxa <7> 2019-07-31 10:50:06.857 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Twin.StoringTwinManager] - Updating reported properties for kevinEdge0719/moxa <7> 2019-07-31 10:50:06.901 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Twin.StoringTwinManager] - Merged reported properties in store for kevinEdge0719/moxa <7> 2019-07-31 10:50:06.908 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Twin.StoringTwinManager] - Storing reported properties in store for kevinEdge0719/moxa with version 0 <7> 2019-07-31 10:50:06.920 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Twin.StoringTwinManager] - Updating reported properties in store with version 0 for kevinEdge0719/moxa <7> 2019-07-31 10:50:06.946 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Mqtt.DeviceProxy] - Sent twin update to kevinEdge0719/moxa <7> 2019-07-31 10:50:06.948 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Mqtt.MessagingServiceClient] - Updating reported properties for device Id kevinEdge0719/moxa <7> 2019-07-31 10:50:06.959 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.RoutingEdgeHub] - Reported properties update message received from kevinEdge0719/moxa <7> 2019-07-31 10:50:06.961 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Twin.StoringTwinManager] - Updating reported properties for kevinEdge0719/moxa <7> 2019-07-31 10:50:06.985 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Twin.StoringTwinManager] - Updating reported properties for kevinEdge0719/moxa <7> 2019-07-31 10:50:07.027 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Twin.StoringTwinManager] - Merged reported properties in store for kevinEdge0719/moxa <7> 2019-07-31 10:50:07.034 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Twin.StoringTwinManager] - Storing reported properties in store for kevinEdge0719/moxa with version 0 <7> 2019-07-31 10:50:07.051 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Twin.StoringTwinManager] - Updating reported properties in store with version 0 for kevinEdge0719/moxa <7> 2019-07-31 10:50:07.106 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Mqtt.DeviceProxy] - Sent twin update to kevinEdge0719/moxa <7> 2019-07-31 10:50:07.108 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Mqtt.MessagingServiceClient] - Updating reported properties for device Id kevinEdge0719/moxa <7> 2019-07-31 10:50:10.457 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Twin.StoringTwinManager] - Syncing stored reported properties to cloud in kevinEdge0719/moxa <7> 2019-07-31 10:50:10.482 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Twin.StoringTwinManager] - Found stored reported properties for kevinEdge0719/moxa to sync to cloud <7> 2019-07-31 10:50:10.500 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Twin.StoringTwinManager] - Updating reported properties for kevinEdge0719/moxa <7> 2019-07-31 10:50:10.502 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.ConnectionManager] - Obtained cloud connection for device kevinEdge0719/moxa <7> 2019-07-31 10:50:10.806 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.DeviceConnectivityManager] - IotHub call succeeded <7> 2019-07-31 10:50:10.810 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ConnectivityAwareClient] - Operation UpdateReportedPropertiesAsync succeeded for kevinEdge0719/moxa <7> 2019-07-31 10:50:10.812 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudProxy] - Updating reported properties for device kevinEdge0719/moxa <6> 2019-07-31 10:50:10.813 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Core.Twin.StoringTwinManager] - Updated reported properties for kevinEdge0719/moxa <7> 2019-07-31 10:50:10.815 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Twin.StoringTwinManager] - Updated reported properties for kevinEdge0719/moxa <7> 2019-07-31 10:50:16.394 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Getting next batch for endpoint iothub starting from 7 with batch size 100. <7> 2019-07-31 10:50:16.396 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Obtained next batch for endpoint iothub with batch size 0. Next start offset = 7. <7> 2019-07-31 10:50:17.001 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.CloudEndpoint] - Sending 1 message(s) upstream. <7> 2019-07-31 10:50:17.137 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.CloudEndpoint] - Sending 1 message(s) upstream, divided into 1 groups. Processing maximum 10 groups in parallel. <7> 2019-07-31 10:50:17.388 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.ConnectionManager] - Obtained cloud connection for device kevinEdge0719/moxa <7> 2019-07-31 10:50:18.584 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.CloudEndpoint] - Finished processing messages to upstream <7> 2019-07-31 10:50:18.909 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.DeviceConnectivityManager] - IotHub call succeeded <7> 2019-07-31 10:50:18.911 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ConnectivityAwareClient] - Operation SendEventAsync succeeded for kevinEdge0719/moxa <7> 2019-07-31 10:50:18.937 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudProxy] - Sending message for device kevinEdge0719/moxa <7> 2019-07-31 10:50:26.418 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Getting next batch for endpoint iothub starting from 7 with batch size 100. <7> 2019-07-31 10:50:26.419 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Obtained next batch for endpoint iothub with batch size 0. Next start offset = 7. <7> 2019-07-31 10:50:29.741 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Getting next batch for endpoint iothub starting from 7 with batch size 100. <7> 2019-07-31 10:50:29.743 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Obtained next batch for endpoint iothub with batch size 0. Next start offset = 7. <7> 2019-07-31 10:50:39.741 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Getting next batch for endpoint iothub starting from 7 with batch size 100. <7> 2019-07-31 10:50:39.744 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Obtained next batch for endpoint iothub with batch size 0. Next start offset = 7. <7> 2019-07-31 10:50:49.749 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Getting next batch for endpoint iothub starting from 7 with batch size 100. <7> 2019-07-31 10:50:49.751 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Obtained next batch for endpoint iothub with batch size 0. Next start offset = 7. <7> 2019-07-31 10:50:59.749 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Getting next batch for endpoint iothub starting from 7 with batch size 100. <7> 2019-07-31 10:50:59.752 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Obtained next batch for endpoint iothub with batch size 0. Next start offset = 7. <7> 2019-07-31 10:51:09.757 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Getting next batch for endpoint iothub starting from 7 with batch size 100. <7> 2019-07-31 10:51:09.759 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Obtained next batch for endpoint iothub with batch size 0. Next start offset = 7. <7> 2019-07-31 10:51:09.775 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Getting next batch for endpoint iothub starting from 7 with batch size 100. <7> 2019-07-31 10:51:09.778 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Obtained next batch for endpoint iothub with batch size 0. Next start offset = 7. <7> 2019-07-31 10:51:19.777 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Getting next batch for endpoint iothub starting from 7 with batch size 100. <7> 2019-07-31 10:51:19.778 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Obtained next batch for endpoint iothub with batch size 0. Next start offset = 7. <7> 2019-07-31 10:51:29.771 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Getting next batch for endpoint iothub starting from 7 with batch size 100. <7> 2019-07-31 10:51:29.772 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Obtained next batch for endpoint iothub with batch size 0. Next start offset = 7. <7> 2019-07-31 10:51:39.772 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Getting next batch for endpoint iothub starting from 7 with batch size 100. <7> 2019-07-31 10:51:39.775 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Obtained next batch for endpoint iothub with batch size 0. Next start offset = 7. <7> 2019-07-31 10:51:49.781 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Getting next batch for endpoint iothub starting from 7 with batch size 100. <7> 2019-07-31 10:51:49.784 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Obtained next batch for endpoint iothub with batch size 0. Next start offset = 7. <7> 2019-07-31 10:51:59.782 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Getting next batch for endpoint iothub starting from 7 with batch size 100. <7> 2019-07-31 10:51:59.785 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Obtained next batch for endpoint iothub with batch size 0. Next start offset = 7. <7> 2019-07-31 10:51:59.789 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Getting next batch for endpoint iothub starting from 7 with batch size 100. <7> 2019-07-31 10:51:59.792 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Obtained next batch for endpoint iothub with batch size 0. Next start offset = 7. <7> 2019-07-31 10:52:09.791 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Getting next batch for endpoint iothub starting from 7 with batch size 100. <7> 2019-07-31 10:52:09.793 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Obtained next batch for endpoint iothub with batch size 0. Next start offset = 7. <7> 2019-07-31 10:52:19.802 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Getting next batch for endpoint iothub starting from 7 with batch size 100. <7> 2019-07-31 10:52:19.806 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Obtained next batch for endpoint iothub with batch size 0. Next start offset = 7. <7> 2019-07-31 10:52:29.803 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Getting next batch for endpoint iothub starting from 7 with batch size 100. <7> 2019-07-31 10:52:29.806 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Obtained next batch for endpoint iothub with batch size 0. Next start offset = 7. <7> 2019-07-31 10:52:39.805 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Getting next batch for endpoint iothub starting from 7 with batch size 100. <7> 2019-07-31 10:52:39.808 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Obtained next batch for endpoint iothub with batch size 0. Next start offset = 7. <6> 2019-07-31 10:52:47.225 +00:00 [INF] [EdgeHub] - Termination requested, initiating shutdown. <6> 2019-07-31 10:52:47.322 +00:00 [INF] [EdgeHub] - Stopping the protocol heads... <6> 2019-07-31 10:52:47.428 +00:00 [INF] [EdgeHub] - Closing protocol heads - (MQTT) <6> 2019-07-31 10:52:47.608 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Mqtt.MqttProtocolHead] - Stopping <6> 2019-07-31 10:52:47.900 +00:00 [INF] [EdgeHub] - Waiting for cleanup to finish <4> 2019-07-31 10:52:48.464 +00:00 [WRN] [EdgeHub] - Closing connection for device: kevinEdge0719/moxa, Microsoft.Azure.Devices.ProtocolGateway.ProtocolGatewayException: Channel closed., <6> 2019-07-31 10:52:48.483 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Mqtt.MessagingServiceClient] - Disposing MessagingServiceClient for device Id kevinEdge0719/moxa because of exception - Microsoft.Azure.Devices.ProtocolGateway.ProtocolGatewayException: Channel closed. <6> 2019-07-31 10:52:48.519 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Mqtt.DeviceProxy] - Setting device proxy inactive for device Id kevinEdge0719/moxa <6> 2019-07-31 10:52:48.573 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Core.ConnectionManager] - Device connection removed for device kevinEdge0719/moxa <7> 2019-07-31 10:52:48.599 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.EdgeHubConnection] - Updating device kevinEdge0719/moxa connection status to Disconnected <7> 2019-07-31 10:52:48.602 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Twin.StoringTwinManager] - Updating reported properties for kevinEdge0719/$edgeHub <7> 2019-07-31 10:52:48.605 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Twin.StoringTwinManager] - Updating reported properties for kevinEdge0719/$edgeHub <7> 2019-07-31 10:52:48.611 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Twin.StoringTwinManager] - Merged reported properties in store for kevinEdge0719/$edgeHub <7> 2019-07-31 10:52:48.615 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Twin.StoringTwinManager] - Storing reported properties in store for kevinEdge0719/$edgeHub with version 0 <7> 2019-07-31 10:52:48.621 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Twin.StoringTwinManager] - Updating reported properties in store with version 0 for kevinEdge0719/$edgeHub <7> 2019-07-31 10:52:48.625 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Twin.StoringTwinManager] - Syncing stored reported properties to cloud in kevinEdge0719/$edgeHub <7> 2019-07-31 10:52:48.630 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Twin.StoringTwinManager] - Found stored reported properties for kevinEdge0719/$edgeHub to sync to cloud <7> 2019-07-31 10:52:48.638 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Twin.StoringTwinManager] - Updating reported properties for kevinEdge0719/$edgeHub <7> 2019-07-31 10:52:48.641 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.ConnectionManager] - Obtained cloud connection for device kevinEdge0719/$edgeHub <6> 2019-07-31 10:52:48.643 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Core.Device.DeviceMessageHandler] - Remove device connection for device kevinEdge0719/moxa <7> 2019-07-31 10:52:48.922 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.DeviceConnectivityManager] - IotHub call succeeded <7> 2019-07-31 10:52:48.924 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ConnectivityAwareClient] - Operation UpdateReportedPropertiesAsync succeeded for kevinEdge0719/$edgeHub <7> 2019-07-31 10:52:48.926 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudProxy] - Updating reported properties for device kevinEdge0719/$edgeHub <6> 2019-07-31 10:52:48.928 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Core.Twin.StoringTwinManager] - Updated reported properties for kevinEdge0719/$edgeHub <7> 2019-07-31 10:52:48.929 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Twin.StoringTwinManager] - Updated reported properties for kevinEdge0719/$edgeHub <7> 2019-07-31 10:52:49.797 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Getting next batch for endpoint iothub starting from 7 with batch size 100. <7> 2019-07-31 10:52:49.799 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Obtained next batch for endpoint iothub with batch size 0. Next start offset = 7. 2019-07-31 10:55:42 +00:00 Starting Edge Hub 2019-07-31 10:55:44.191 +00:00 Edge Hub Main() <7> 2019-07-31 10:55:49.385 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Edged.WorkloadClient] - Making a Http call to unix:///var/run/iotedge/workload.sock to CreateServerCertificateAsync <7> 2019-07-31 10:55:53.688 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Connecting socket /var/run/iotedge/workload.sock <7> 2019-07-31 10:55:53.758 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Connected socket /var/run/iotedge/workload.sock <7> 2019-07-31 10:55:53.861 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Sending request http://workload.sock/modules/%24edgeHub/genid/636991296573155410/certificate/server?api-version=2019-01-30 <7> 2019-07-31 10:56:03.472 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Response received Created <7> 2019-07-31 10:56:06.082 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Edged.WorkloadClient] - Received a valid Http response from unix:///var/run/iotedge/workload.sock for CreateServerCertificateAsync [07/31/2019 10:56:11.582 AM] Found intermediate certificates: [CN=iotedged workload ca:10/29/2019 04:58:25],[CN=Test Edge Device CA:10/29/2019 04:58:25],[CN=Test Edge Owner CA:10/29/2019 04:58:25] <7> 2019-07-31 10:56:11.665 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Edged.WorkloadClient] - Making a Http call to unix:///var/run/iotedge/workload.sock to TrustBundleAsync <7> 2019-07-31 10:56:11.810 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Connecting socket /var/run/iotedge/workload.sock <7> 2019-07-31 10:56:11.818 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Connected socket /var/run/iotedge/workload.sock <7> 2019-07-31 10:56:11.825 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Sending request http://workload.sock/trust-bundle?api-version=2019-01-30 <7> 2019-07-31 10:56:11.887 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Response received OK <7> 2019-07-31 10:56:12.058 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Edged.WorkloadClient] - Received a valid Http response from unix:///var/run/iotedge/workload.sock for TrustBundleAsync <6> 2019-07-31 10:56:27.994 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Service.Modules.RoutingModule] - Created persistent store at /tmp/edgeHub <7> 2019-07-31 10:56:29.147 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Edged.WorkloadClient] - Making a Http call to unix:///var/run/iotedge/workload.sock to Decrypt <7> 2019-07-31 10:56:29.419 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Connecting socket /var/run/iotedge/workload.sock <7> 2019-07-31 10:56:29.422 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Connected socket /var/run/iotedge/workload.sock <7> 2019-07-31 10:56:29.425 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Sending request http://workload.sock/modules/%24edgeHub/genid/636991296573155410/decrypt?api-version=2019-01-30 <7> 2019-07-31 10:56:29.688 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Response received OK <7> 2019-07-31 10:56:29.903 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Edged.WorkloadClient] - Received a valid Http response from unix:///var/run/iotedge/workload.sock for Decrypt <6> 2019-07-31 10:56:31.178 +00:00 [INF] [EdgeHub] - Initializing Edge Hub
ancaantochi commented 5 years ago

@KevinKao809,

When iotedge is restarted all modules get restarted and if the restart is repeated in a short period of time the restart delay will keep increasing. This is expected behavior. You can configure IntensiveCareTimeInMinutes by adding the env variable to edgeAgent, default value is 10 minutes. This value means how long the module has to be running before the delay is cleared.

As I understand from your description this is for testing environment, in a production environment restarting the device so often sounds like an issue with the device and that should be fixed first instead of configuring the modules to restart without backoff.

KevinKao809 commented 5 years ago

Hi Ancaantochi, Thanks your reply. Beside edgeHub delay start issue, we also found that when custom module connect to edgeHub, but edgeHub is not ready, custom module will delay by an exponential interval. May I know any way to let edgeAgent start edgeHub first before other modules?

KevinKao809 commented 5 years ago

@ancaantochi ,

I set IntensiveCareTimeInMinutes to 0 and 1, but doen't change any thing, I still saw the edgeHub be delay start from 1:20, 2:40 to 5 min. BTW, we found how to adjust exponential interval of custom module.

KevinKao809 commented 5 years ago

Hi, You can close this issue now. We understood the behavior is by design, and now no option to adjust the time.