Closed termocontrole closed 6 years ago
Hi @termocontrole ,
From your logs looks like you are having problems on modbus module. It's getting connected to edge hub, but I can see that it's keeping having TLS Handshake failures.
Also, there was a time that you went Out of memory, which can be a problem that you are not able to send message to IoT Hub.
So, here is what I recommend: 1-1st turn Debug logs following this blog post: https://docs.microsoft.com/en-us/azure/iot-edge/troubleshoot 2 - I see that you have just 1 modbus module and 1 route. So, just to make sure your route is not broke, why don't you just use the default route? (Just to make sure you can receive the messages on the cloud). The default route is: "routes": { "r1": "FROM /* INTO $upstream" }
So, uninstall everything, make sure you have enough memory on your device (cleaning up logs) and do a deployment turning Debug logs and changing the route to the above.
3rd - Make sure you are using the latest version of both Device SDK and edge hub.
Let us know how it goes,
Thanks,
Angelo Ribeiro.
Hi @aribeironovaes,
I followed your instructions and reinstalled everything, but this time with the debug logs on.
First, the debug logs helps a lot to understand what is going on with edgeAgent
and edgeHub
containers.
Second, things are working, the data is send from modbus
container to edgeHub
and to the IoT Hub. I'm using Stream Analytics to measure the amount of data that is coming, because IoT Hub gauge doesn't seem reliable. Using Stream Analytics, all data sent by IoT Edge is received by IoT Hub.
So, thank you very much for that.
But there is still somethings that I want to understand better:
edgeHub logs:
2018-03-27 13:51:03.528 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Mqtt.MessagingServiceClient] - Sending message for device Id TC-IoT-Edge/modbus
2018-03-27 13:51:03.529 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.RoutingEdgeHub] - Received message from TC-IoT-Edge/modbus
2018-03-27 13:51:03.627 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Getting next batch for endpoint iothub starting from 45 with batch size 10.
2018-03-27 13:51:03.628 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Obtained next batch for endpoint iothub with batch size 1. Next start offset = 46.
2018-03-27 13:51:03.629 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Getting next batch for endpoint iothub starting from 46 with batch size 10.
2018-03-27 13:51:03.629 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Obtained next batch for endpoint iothub with batch size 0. Next start offset = 46.
2018-03-27 13:51:03.858 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudProxy] - Sending message for device TC-IoT-Edge/modbus
2018-03-27 13:51:04.998 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudConnection] - Getting new token for TC-IoT-Edge/modbus.
2018-03-27 13:51:04.999 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudConnection] - Existing token not found for TC-IoT-Edge/modbus. Getting new token from the client...
2018-03-27 13:51:05.000 +00:00 [WRN] [ProtocolGateway] - Closing connection for device: TC-IoT-Edge/modbus, Microsoft.Azure.Devices.Edge.Hub.Core.EdgeHubConnectionException: Connection closed for device TC-IoT-Edge/modbus.,
2018-03-27 13:51:05.001 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Mqtt.MessagingServiceClient] - Disposing MessagingServiceClient for device Id TC-IoT-Edge/modbus because of exception - Microsoft.Azure.Devices.Edge.Hub.Core.EdgeHubConnectionException: Connection closed for device TC-IoT-Edge/modbus.
2018-03-27 13:51:05.002 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Mqtt.DeviceProxy] - Closing device proxy for device Id TC-IoT-Edge/modbus
2018-03-27 13:51:05.002 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Core.ConnectionManager] - Device connection removed for device TC-IoT-Edge/modbus
2018-03-27 13:51:05.003 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.EdgeHubConnection] - Updating device TC-IoT-Edge/modbus connection status to Disconnected
2018-03-27 13:51:05.213 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudConnection] - Obtained new token for client TC-IoT-Edge/modbus that expires in 00:59:59.7868522
2018-03-27 13:51:05.213 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudConnection] - Updated cloud connection for client TC-IoT-Edge/modbus
2018-03-27 13:51:05.213 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Core.ConnectionManager] - New cloud connection created for device TC-IoT-Edge/modbus
2018-03-27 13:51:05.213 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Core.Authenticator] - Successfully authenticated device TC-IoT-Edge/modbus
2018-03-27 13:51:05.214 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Mqtt.SasTokenDeviceIdentityProvider] - Successfully generated identity for clientId TC-IoT-Edge/modbus and username HIDDEN
2018-03-27 13:51:05.214 +00:00 [INF] [ProtocolGateway] - ClientAuthenticated, TC-IoT-Edge/modbus, 5c147a81
2018-03-27 13:51:05.214 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.ConnectionManager] - Obtained cloud connection for device TC-IoT-Edge/modbus
2018-03-27 13:51:05.216 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudProxy] - Binding cloud listener for device TC-IoT-Edge/modbus
2018-03-27 13:51:05.216 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Core.ConnectionManager] - New device connection for device TC-IoT-Edge/modbus
2018-03-27 13:51:05.216 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.EdgeHubConnection] - Updating device TC-IoT-Edge/modbus connection status to Connected
2018-03-27 13:51:05.225 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Core.Device.DeviceMessageHandler] - Bind device proxy for device TC-IoT-Edge/modbus
2018-03-27 13:51:05.225 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Mqtt.MessagingServiceClient] - Binding message channel for device Id TC-IoT-Edge/modbus
2018-03-27 13:51:05.226 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Mqtt.SessionStatePersistenceProvider] - Adding subscription $iothub/twin/res/# for client TC-IoT-Edge/modbus.
2018-03-27 13:51:05.226 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Mqtt.SessionStatePersistenceProvider] - Adding subscription devices/TC-IoT-Edge/modules/modbus/# for client TC-IoT-Edge/modbus.
2018-03-27 13:51:05.227 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Mqtt.SessionStatePersistenceProvider] - Adding subscription $iothub/twin/PATCH/properties/desired/# for client TC-IoT-Edge/modbus.
2018-03-27 13:51:05.228 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Mqtt.SessionStateStoragePersistenceProvider] - Set subscriptions from session state for TC-IoT-Edge/modbus
2018-03-27 13:51:05.244 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudProxy] - Updating reported properties for device TC-IoT-Edge/$edgeHub
2018-03-27 13:51:05.244 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.TwinManager] - Successfully sent reported properties to cloud for TC-IoT-Edge/$edgeHub and reported properties version 0
2018-03-27 13:51:05.246 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.TwinManager] - Updated cached reported property for TC-IoT-Edge/$edgeHub at reported property version 841 cloudVerified True
2018-03-27 13:51:07.360 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudProxy] - Updating reported properties for device TC-IoT-Edge/$edgeHub
2018-03-27 13:51:07.361 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.TwinManager] - Successfully sent reported properties to cloud for TC-IoT-Edge/$edgeHub and reported properties version 0
2018-03-27 13:51:07.365 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.TwinManager] - Updated cached reported property for TC-IoT-Edge/$edgeHub at reported property version 841 cloudVerified True
2018-03-27 13:53:34.732 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Mqtt.MessagingServiceClient] - Sending message for device Id TC-IoT-Edge/modbus
2018-03-27 13:53:34.732 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.RoutingEdgeHub] - Received message from TC-IoT-Edge/modbus
2018-03-27 13:53:34.734 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Getting next batch for endpoint iothub starting from 46 with batch size 10.
2018-03-27 13:53:34.735 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Obtained next batch for endpoint iothub with batch size 1. Next start offset = 47.
2018-03-27 13:53:34.735 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Getting next batch for endpoint iothub starting from 47 with batch size 10.
2018-03-27 13:53:34.736 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Obtained next batch for endpoint iothub with batch size 0. Next start offset = 47.
2018-03-27 13:53:34.941 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudProxy] - Sending message for device TC-IoT-Edge/modbus
2018-03-27 13:54:46.035 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Storage.RocksDb.DbStoreProvider] - Starting compaction of stores
2018-03-27 13:54:46.038 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Storage.RocksDb.DbStoreProvider] - Starting compaction of store checkpoints
2018-03-27 13:54:46.070 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Storage.RocksDb.DbStoreProvider] - Starting compaction of store sessions
2018-03-27 13:54:46.089 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Storage.RocksDb.DbStoreProvider] - Starting compaction of store twins
2018-03-27 13:54:46.105 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Storage.RocksDb.DbStoreProvider] - Starting compaction of store iothub
2018-03-27 13:54:46.120 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Storage.RocksDb.DbStoreProvider] - Starting compaction of store messages
2018-03-27 13:54:46.139 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Storage.RocksDb.DbStoreProvider] - Starting compaction of store default
2018-03-27 13:56:05.749 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Mqtt.MessagingServiceClient] - Sending message for device Id TC-IoT-Edge/modbus
2018-03-27 13:56:05.749 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.RoutingEdgeHub] - Received message from TC-IoT-Edge/modbus
2018-03-27 13:56:05.752 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Getting next batch for endpoint iothub starting from 47 with batch size 10.
2018-03-27 13:56:05.847 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Obtained next batch for endpoint iothub with batch size 1. Next start offset = 48.
2018-03-27 13:56:05.848 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Getting next batch for endpoint iothub starting from 48 with batch size 10.
2018-03-27 13:56:05.848 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Obtained next batch for endpoint iothub with batch size 0. Next start offset = 48.
2018-03-27 13:56:06.292 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudProxy] - Sending message for device TC-IoT-Edge/modbus
2018-03-27 13:56:23.803 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Started task to cleanup processed and stale messages for endpoint iothub
2018-03-27 13:56:23.803 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Checkpoint for endpoint iothub is 47
2018-03-27 13:56:23.917 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Cleaned up 12 messages from queue for endpoint iothub and 12 messages from message store.
2018-03-27 13:56:23.918 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Total messages cleaned up from queue for endpoint iothub = 48, and total messages cleaned up for message store = 48.
2018-03-27 13:58:36.761 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Mqtt.MessagingServiceClient] - Sending message for device Id TC-IoT-Edge/modbus
2018-03-27 13:58:36.762 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.RoutingEdgeHub] - Received message from TC-IoT-Edge/modbus
2018-03-27 13:58:36.764 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Getting next batch for endpoint iothub starting from 48 with batch size 10.
2018-03-27 13:58:36.766 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Obtained next batch for endpoint iothub with batch size 1. Next start offset = 49.
2018-03-27 13:58:36.767 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Getting next batch for endpoint iothub starting from 49 with batch size 10.
2018-03-27 13:58:36.866 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Obtained next batch for endpoint iothub with batch size 0. Next start offset = 49.
2018-03-27 13:58:37.107 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudProxy] - Sending message for device TC-IoT-Edge/modbus
2018-03-27 14:01:07.779 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Mqtt.MessagingServiceClient] - Sending message for device Id TC-IoT-Edge/modbus
2018-03-27 14:01:07.779 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.RoutingEdgeHub] - Received message from TC-IoT-Edge/modbus
2018-03-27 14:01:07.781 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Getting next batch for endpoint iothub starting from 49 with batch size 10.
2018-03-27 14:01:07.881 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Obtained next batch for endpoint iothub with batch size 1. Next start offset = 50.
2018-03-27 14:01:07.882 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Getting next batch for endpoint iothub starting from 50 with batch size 10.
2018-03-27 14:01:07.883 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Obtained next batch for endpoint iothub with batch size 0. Next start offset = 50.
2018-03-27 14:01:08.164 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudProxy] - Sending message for device TC-IoT-Edge/modbus
2018-03-27 14:03:38.789 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Mqtt.MessagingServiceClient] - Sending message for device Id TC-IoT-Edge/modbus
2018-03-27 14:03:38.790 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.RoutingEdgeHub] - Received message from TC-IoT-Edge/modbus
2018-03-27 14:03:38.792 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Getting next batch for endpoint iothub starting from 50 with batch size 10.
2018-03-27 14:03:38.794 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Obtained next batch for endpoint iothub with batch size 1. Next start offset = 51.
2018-03-27 14:03:38.795 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Getting next batch for endpoint iothub starting from 51 with batch size 10.
2018-03-27 14:03:38.796 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Obtained next batch for endpoint iothub with batch size 0. Next start offset = 51.
2018-03-27 14:03:39.069 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudProxy] - Sending message for device TC-IoT-Edge/modbus
2018-03-27 14:06:09.808 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Mqtt.MessagingServiceClient] - Sending message for device Id TC-IoT-Edge/modbus
2018-03-27 14:06:09.808 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.RoutingEdgeHub] - Received message from TC-IoT-Edge/modbus
2018-03-27 14:06:09.811 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Getting next batch for endpoint iothub starting from 51 with batch size 10.
2018-03-27 14:06:09.813 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Obtained next batch for endpoint iothub with batch size 1. Next start offset = 52.
2018-03-27 14:06:09.813 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Getting next batch for endpoint iothub starting from 52 with batch size 10.
2018-03-27 14:06:09.814 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Obtained next batch for endpoint iothub with batch size 0. Next start offset = 52.
2018-03-27 14:06:10.053 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudProxy] - Sending message for device TC-IoT-Edge/modbus
2018-03-27 14:08:40.809 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Mqtt.MessagingServiceClient] - Sending message for device Id TC-IoT-Edge/modbus
2018-03-27 14:08:40.809 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.RoutingEdgeHub] - Received message from TC-IoT-Edge/modbus
2018-03-27 14:08:40.811 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Getting next batch for endpoint iothub starting from 52 with batch size 10.
2018-03-27 14:08:40.904 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Obtained next batch for endpoint iothub with batch size 1. Next start offset = 53.
2018-03-27 14:08:40.904 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Getting next batch for endpoint iothub starting from 53 with batch size 10.
2018-03-27 14:08:40.904 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Obtained next batch for endpoint iothub with batch size 0. Next start offset = 53.
2018-03-27 14:08:41.135 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudProxy] - Sending message for device TC-IoT-Edge/modbus
2018-03-27 14:11:11.818 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Mqtt.MessagingServiceClient] - Sending message for device Id TC-IoT-Edge/modbus
2018-03-27 14:11:11.818 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.RoutingEdgeHub] - Received message from TC-IoT-Edge/modbus
2018-03-27 14:11:11.909 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Getting next batch for endpoint iothub starting from 53 with batch size 10.
2018-03-27 14:11:11.911 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Obtained next batch for endpoint iothub with batch size 1. Next start offset = 54.
2018-03-27 14:11:11.911 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Getting next batch for endpoint iothub starting from 54 with batch size 10.
2018-03-27 14:11:11.912 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Obtained next batch for endpoint iothub with batch size 0. Next start offset = 54.
2018-03-27 14:11:12.392 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudProxy] - Sending message for device TC-IoT-Edge/modbus
2018-03-27 14:13:42.913 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Mqtt.MessagingServiceClient] - Sending message for device Id TC-IoT-Edge/modbus
2018-03-27 14:13:42.914 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.RoutingEdgeHub] - Received message from TC-IoT-Edge/modbus
2018-03-27 14:13:42.916 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Getting next batch for endpoint iothub starting from 54 with batch size 10.
2018-03-27 14:13:42.918 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Obtained next batch for endpoint iothub with batch size 1. Next start offset = 55.
2018-03-27 14:13:42.919 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Getting next batch for endpoint iothub starting from 55 with batch size 10.
2018-03-27 14:13:42.920 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Obtained next batch for endpoint iothub with batch size 0. Next start offset = 55.
2018-03-27 14:13:43.167 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudProxy] - Sending message for device TC-IoT-Edge/modbus
2018-03-27 14:16:13.928 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Mqtt.MessagingServiceClient] - Sending message for device Id TC-IoT-Edge/modbus
2018-03-27 14:16:13.929 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.RoutingEdgeHub] - Received message from TC-IoT-Edge/modbus
2018-03-27 14:16:13.931 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Getting next batch for endpoint iothub starting from 55 with batch size 10.
2018-03-27 14:16:13.933 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Obtained next batch for endpoint iothub with batch size 1. Next start offset = 56.
2018-03-27 14:16:13.935 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Getting next batch for endpoint iothub starting from 56 with batch size 10.
2018-03-27 14:16:14.033 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Obtained next batch for endpoint iothub with batch size 0. Next start offset = 56.
2018-03-27 14:16:14.229 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudProxy] - Sending message for device TC-IoT-Edge/modbus
2018-03-27 14:18:44.948 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Mqtt.MessagingServiceClient] - Sending message for device Id TC-IoT-Edge/modbus
2018-03-27 14:18:44.949 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.RoutingEdgeHub] - Received message from TC-IoT-Edge/modbus
2018-03-27 14:18:44.951 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Getting next batch for endpoint iothub starting from 56 with batch size 10.
2018-03-27 14:18:45.049 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Obtained next batch for endpoint iothub with batch size 1. Next start offset = 57.
2018-03-27 14:18:45.049 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Getting next batch for endpoint iothub starting from 57 with batch size 10.
2018-03-27 14:18:45.050 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Obtained next batch for endpoint iothub with batch size 0. Next start offset = 57.
2018-03-27 14:18:45.312 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudProxy] - Sending message for device TC-IoT-Edge/modbus
2018-03-27 14:21:15.948 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Mqtt.MessagingServiceClient] - Sending message for device Id TC-IoT-Edge/modbus
2018-03-27 14:21:15.948 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.RoutingEdgeHub] - Received message from TC-IoT-Edge/modbus
2018-03-27 14:21:15.951 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Getting next batch for endpoint iothub starting from 57 with batch size 10.
2018-03-27 14:21:15.953 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Obtained next batch for endpoint iothub with batch size 1. Next start offset = 58.
2018-03-27 14:21:15.954 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Getting next batch for endpoint iothub starting from 58 with batch size 10.
2018-03-27 14:21:15.955 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Obtained next batch for endpoint iothub with batch size 0. Next start offset = 58.
2018-03-27 14:21:16.199 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudProxy] - Sending message for device TC-IoT-Edge/modbus
2018-03-27 14:23:46.968 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Mqtt.MessagingServiceClient] - Sending message for device Id TC-IoT-Edge/modbus
2018-03-27 14:23:46.968 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.RoutingEdgeHub] - Received message from TC-IoT-Edge/modbus
2018-03-27 14:23:46.971 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Getting next batch for endpoint iothub starting from 58 with batch size 10.
2018-03-27 14:23:47.078 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Obtained next batch for endpoint iothub with batch size 1. Next start offset = 59.
2018-03-27 14:23:47.085 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Getting next batch for endpoint iothub starting from 59 with batch size 10.
2018-03-27 14:23:47.086 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Obtained next batch for endpoint iothub with batch size 0. Next start offset = 59.
2018-03-27 14:23:47.335 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudProxy] - Sending message for device TC-IoT-Edge/modbus
2018-03-27 14:26:17.989 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Mqtt.MessagingServiceClient] - Sending message for device Id TC-IoT-Edge/modbus
2018-03-27 14:26:18.083 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.RoutingEdgeHub] - Received message from TC-IoT-Edge/modbus
2018-03-27 14:26:18.087 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Getting next batch for endpoint iothub starting from 59 with batch size 10.
2018-03-27 14:26:18.089 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Obtained next batch for endpoint iothub with batch size 1. Next start offset = 60.
2018-03-27 14:26:18.090 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Getting next batch for endpoint iothub starting from 60 with batch size 10.
2018-03-27 14:26:18.095 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Obtained next batch for endpoint iothub with batch size 0. Next start offset = 60.
2018-03-27 14:26:18.273 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudProxy] - Sending message for device TC-IoT-Edge/modbus
2018-03-27 14:26:53.925 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Started task to cleanup processed and stale messages for endpoint iothub
2018-03-27 14:26:53.925 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Checkpoint for endpoint iothub is 59
2018-03-27 14:26:54.079 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Cleaned up 12 messages from queue for endpoint iothub and 12 messages from message store.
2018-03-27 14:26:54.079 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Total messages cleaned up from queue for endpoint iothub = 60, and total messages cleaned up for message store = 60.
2018-03-27 14:28:49.098 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Mqtt.MessagingServiceClient] - Sending message for device Id TC-IoT-Edge/modbus
2018-03-27 14:28:49.099 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.RoutingEdgeHub] - Received message from TC-IoT-Edge/modbus
2018-03-27 14:28:49.101 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Getting next batch for endpoint iothub starting from 60 with batch size 10.
2018-03-27 14:28:49.103 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Obtained next batch for endpoint iothub with batch size 1. Next start offset = 61.
2018-03-27 14:28:49.103 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Getting next batch for endpoint iothub starting from 61 with batch size 10.
2018-03-27 14:28:49.104 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Obtained next batch for endpoint iothub with batch size 0. Next start offset = 61.
2018-03-27 14:28:49.323 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudProxy] - Sending message for device TC-IoT-Edge/modbus
2018-03-27 14:31:20.122 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Mqtt.MessagingServiceClient] - Sending message for device Id TC-IoT-Edge/modbus
2018-03-27 14:31:20.123 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.RoutingEdgeHub] - Received message from TC-IoT-Edge/modbus
2018-03-27 14:31:20.126 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Getting next batch for endpoint iothub starting from 61 with batch size 10.
2018-03-27 14:31:20.204 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Obtained next batch for endpoint iothub with batch size 1. Next start offset = 62.
2018-03-27 14:31:20.204 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Getting next batch for endpoint iothub starting from 62 with batch size 10.
2018-03-27 14:31:20.204 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Obtained next batch for endpoint iothub with batch size 0. Next start offset = 62.
2018-03-27 14:31:20.471 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudProxy] - Sending message for device TC-IoT-Edge/modbus
2018-03-27 14:33:51.154 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Mqtt.MessagingServiceClient] - Sending message for device Id TC-IoT-Edge/modbus
2018-03-27 14:33:51.155 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.RoutingEdgeHub] - Received message from TC-IoT-Edge/modbus
2018-03-27 14:33:51.160 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Getting next batch for endpoint iothub starting from 62 with batch size 10.
2018-03-27 14:33:51.261 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Obtained next batch for endpoint iothub with batch size 1. Next start offset = 63.
2018-03-27 14:33:51.263 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Getting next batch for endpoint iothub starting from 63 with batch size 10.
2018-03-27 14:33:51.264 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Obtained next batch for endpoint iothub with batch size 0. Next start offset = 63.
2018-03-27 14:33:51.497 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudProxy] - Sending message for device TC-IoT-Edge/modbus
2018-03-27 14:36:22.169 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Mqtt.MessagingServiceClient] - Sending message for device Id TC-IoT-Edge/modbus
2018-03-27 14:36:22.169 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.RoutingEdgeHub] - Received message from TC-IoT-Edge/modbus
2018-03-27 14:36:22.174 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Getting next batch for endpoint iothub starting from 63 with batch size 10.
2018-03-27 14:36:22.176 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Obtained next batch for endpoint iothub with batch size 1. Next start offset = 64.
2018-03-27 14:36:22.176 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Getting next batch for endpoint iothub starting from 64 with batch size 10.
2018-03-27 14:36:22.177 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Obtained next batch for endpoint iothub with batch size 0. Next start offset = 64.
2018-03-27 14:36:22.360 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudProxy] - Sending message for device TC-IoT-Edge/modbus
2018-03-27 14:38:53.189 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Mqtt.MessagingServiceClient] - Sending message for device Id TC-IoT-Edge/modbus
2018-03-27 14:38:53.189 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.RoutingEdgeHub] - Received message from TC-IoT-Edge/modbus
2018-03-27 14:38:53.194 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Getting next batch for endpoint iothub starting from 64 with batch size 10.
2018-03-27 14:38:53.287 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Obtained next batch for endpoint iothub with batch size 1. Next start offset = 65.
2018-03-27 14:38:53.295 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Getting next batch for endpoint iothub starting from 65 with batch size 10.
2018-03-27 14:38:53.296 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Obtained next batch for endpoint iothub with batch size 0. Next start offset = 65.
2018-03-27 14:38:53.524 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudProxy] - Sending message for device TC-IoT-Edge/modbus
2018-03-27 14:41:24.209 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Mqtt.MessagingServiceClient] - Sending message for device Id TC-IoT-Edge/modbus
2018-03-27 14:41:24.209 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.RoutingEdgeHub] - Received message from TC-IoT-Edge/modbus
2018-03-27 14:41:24.312 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Getting next batch for endpoint iothub starting from 65 with batch size 10.
2018-03-27 14:41:24.316 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Obtained next batch for endpoint iothub with batch size 1. Next start offset = 66.
2018-03-27 14:41:24.318 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Getting next batch for endpoint iothub starting from 66 with batch size 10.
2018-03-27 14:41:24.319 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Obtained next batch for endpoint iothub with batch size 0. Next start offset = 66.
2018-03-27 14:41:24.504 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudProxy] - Sending message for device TC-IoT-Edge/modbus
2018-03-27 14:43:55.320 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Mqtt.MessagingServiceClient] - Sending message for device Id TC-IoT-Edge/modbus
2018-03-27 14:43:55.320 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.RoutingEdgeHub] - Received message from TC-IoT-Edge/modbus
2018-03-27 14:43:55.323 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Getting next batch for endpoint iothub starting from 66 with batch size 10.
2018-03-27 14:43:55.327 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Obtained next batch for endpoint iothub with batch size 1. Next start offset = 67.
2018-03-27 14:43:55.328 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Getting next batch for endpoint iothub starting from 67 with batch size 10.
2018-03-27 14:43:55.328 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Obtained next batch for endpoint iothub with batch size 0. Next start offset = 67.
2018-03-27 14:43:55.681 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudProxy] - Sending message for device TC-IoT-Edge/modbus
2018-03-27 14:46:26.332 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Mqtt.MessagingServiceClient] - Sending message for device Id TC-IoT-Edge/modbus
2018-03-27 14:46:26.333 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.RoutingEdgeHub] - Received message from TC-IoT-Edge/modbus
2018-03-27 14:46:26.335 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Getting next batch for endpoint iothub starting from 67 with batch size 10.
2018-03-27 14:46:26.433 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Obtained next batch for endpoint iothub with batch size 1. Next start offset = 68.
2018-03-27 14:46:26.440 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Getting next batch for endpoint iothub starting from 68 with batch size 10.
2018-03-27 14:46:26.441 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Obtained next batch for endpoint iothub with batch size 0. Next start offset = 68.
2018-03-27 14:46:26.663 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudProxy] - Sending message for device TC-IoT-Edge/modbus
2018-03-27 14:48:57.343 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Mqtt.MessagingServiceClient] - Sending message for device Id TC-IoT-Edge/modbus
2018-03-27 14:48:57.343 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.RoutingEdgeHub] - Received message from TC-IoT-Edge/modbus
2018-03-27 14:48:57.346 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Getting next batch for endpoint iothub starting from 68 with batch size 10.
2018-03-27 14:48:57.348 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Obtained next batch for endpoint iothub with batch size 1. Next start offset = 69.
2018-03-27 14:48:57.348 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Getting next batch for endpoint iothub starting from 69 with batch size 10.
2018-03-27 14:48:57.349 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Obtained next batch for endpoint iothub with batch size 0. Next start offset = 69.
2018-03-27 14:48:57.638 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudProxy] - Sending message for device TC-IoT-Edge/modbus
2018-03-27 14:49:05.007 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudConnection] - Getting new token for TC-IoT-Edge/modbus.
2018-03-27 14:49:05.017 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudConnection] - Existing token not found for TC-IoT-Edge/modbus. Getting new token from the client...
2018-03-27 14:49:05.018 +00:00 [WRN] [ProtocolGateway] - Closing connection for device: TC-IoT-Edge/modbus, Microsoft.Azure.Devices.Edge.Hub.Core.EdgeHubConnectionException: Connection closed for device TC-IoT-Edge/modbus.,
2018-03-27 14:49:05.019 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Mqtt.MessagingServiceClient] - Disposing MessagingServiceClient for device Id TC-IoT-Edge/modbus because of exception - Microsoft.Azure.Devices.Edge.Hub.Core.EdgeHubConnectionException: Connection closed for device TC-IoT-Edge/modbus.
2018-03-27 14:49:05.019 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Mqtt.DeviceProxy] - Closing device proxy for device Id TC-IoT-Edge/modbus
2018-03-27 14:49:05.019 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Core.ConnectionManager] - Device connection removed for device TC-IoT-Edge/modbus
2018-03-27 14:49:05.020 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.EdgeHubConnection] - Updating device TC-IoT-Edge/modbus connection status to Disconnected
2018-03-27 14:49:05.288 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudProxy] - Updating reported properties for device TC-IoT-Edge/$edgeHub
2018-03-27 14:49:05.288 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.TwinManager] - Successfully sent reported properties to cloud for TC-IoT-Edge/$edgeHub and reported properties version 0
2018-03-27 14:49:05.291 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.TwinManager] - Updated cached reported property for TC-IoT-Edge/$edgeHub at reported property version 841 cloudVerified True
2018-03-27 14:49:05.297 +00:00 [WRN] [ProtocolGateway] - TLS handshake failed., System.IO.IOException: Channel is closed, 09c67dc6
2018-03-27 14:49:05.312 +00:00 [ERR] [DotNetty.Common.ResourceLeakDetector] - LEAK: IByteBuffer.Release() was not called before it's garbage-collected. Enable advanced leak reporting to find out where the leak occurred. To enable advanced leak reporting, set environment variable io.netty.leakDetection.level to advanced or set ResourceLeakDetector.Level in code. See http://netty.io/wiki/reference-counted-objects.html for more information.
2018-03-27 14:49:05.611 +00:00 [WRN] [ProtocolGateway] - TLS handshake failed., System.IO.IOException: Channel is closed, 352bfabd
2018-03-27 14:49:06.223 +00:00 [WRN] [ProtocolGateway] - TLS handshake failed., System.IO.IOException: Channel is closed, 50ded65c
2018-03-27 14:49:07.291 +00:00 [WRN] [ProtocolGateway] - TLS handshake failed., System.IO.IOException: Channel is closed, 6f15790f
2018-03-27 14:49:08.976 +00:00 [WRN] [ProtocolGateway] - TLS handshake failed., System.IO.IOException: Channel is closed, 0a1cd124
2018-03-27 14:49:12.794 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudConnection] - Obtained new token for client TC-IoT-Edge/modbus that expires in 01:00:00.2050982
2018-03-27 14:49:12.795 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudConnection] - Updated cloud connection for client TC-IoT-Edge/modbus
2018-03-27 14:49:12.795 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Core.ConnectionManager] - New cloud connection created for device TC-IoT-Edge/modbus
2018-03-27 14:49:12.796 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Core.Authenticator] - Successfully authenticated device TC-IoT-Edge/modbus
2018-03-27 14:49:12.796 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Mqtt.SasTokenDeviceIdentityProvider] - Successfully generated identity for clientId TC-IoT-Edge/modbus and username HIDDEN
2018-03-27 14:49:12.797 +00:00 [INF] [ProtocolGateway] - ClientAuthenticated, TC-IoT-Edge/modbus, 0f6f8e19
2018-03-27 14:49:12.797 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.ConnectionManager] - Obtained cloud connection for device TC-IoT-Edge/modbus
2018-03-27 14:49:12.799 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudProxy] - Binding cloud listener for device TC-IoT-Edge/modbus
2018-03-27 14:49:12.799 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Core.ConnectionManager] - New device connection for device TC-IoT-Edge/modbus
2018-03-27 14:49:12.800 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.EdgeHubConnection] - Updating device TC-IoT-Edge/modbus connection status to Connected
2018-03-27 14:49:12.802 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Core.Device.DeviceMessageHandler] - Bind device proxy for device TC-IoT-Edge/modbus
2018-03-27 14:49:12.802 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Mqtt.MessagingServiceClient] - Binding message channel for device Id TC-IoT-Edge/modbus
2018-03-27 14:49:12.803 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Mqtt.SessionStatePersistenceProvider] - Adding subscription $iothub/twin/res/# for client TC-IoT-Edge/modbus.
2018-03-27 14:49:12.803 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Mqtt.SessionStatePersistenceProvider] - Adding subscription devices/TC-IoT-Edge/modules/modbus/# for client TC-IoT-Edge/modbus.
2018-03-27 14:49:12.804 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Mqtt.SessionStatePersistenceProvider] - Adding subscription $iothub/twin/PATCH/properties/desired/# for client TC-IoT-Edge/modbus.
2018-03-27 14:49:12.806 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Mqtt.SessionStateStoragePersistenceProvider] - Set subscriptions from session state for TC-IoT-Edge/modbus
2018-03-27 14:49:12.942 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudProxy] - Updating reported properties for device TC-IoT-Edge/$edgeHub
2018-03-27 14:49:12.942 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.TwinManager] - Successfully sent reported properties to cloud for TC-IoT-Edge/$edgeHub and reported properties version 0
2018-03-27 14:49:12.944 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.TwinManager] - Updated cached reported property for TC-IoT-Edge/$edgeHub at reported property version 841 cloudVerified True
2018-03-27 14:51:28.349 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Mqtt.MessagingServiceClient] - Sending message for device Id TC-IoT-Edge/modbus
2018-03-27 14:51:28.350 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.RoutingEdgeHub] - Received message from TC-IoT-Edge/modbus
2018-03-27 14:51:28.352 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Getting next batch for endpoint iothub starting from 69 with batch size 10.
2018-03-27 14:51:28.455 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Obtained next batch for endpoint iothub with batch size 1. Next start offset = 70.
2018-03-27 14:51:28.456 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Getting next batch for endpoint iothub starting from 70 with batch size 10.
2018-03-27 14:51:28.456 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Obtained next batch for endpoint iothub with batch size 0. Next start offset = 70.
2018-03-27 14:51:28.642 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudProxy] - Sending message for device TC-IoT-Edge/modbus
If you look at my edgeHub logs, you are going to see that the modbus token is renewed every one hour, because the token is set to expire every one hour, is this default? Can I change the validity of this token somewhere?
Another question is that sometimes appers TLS handshake failed
but does't seem to cause trouble to the data. Do you have any thoughts about this?
Thank you very much.
Hi @termocontrole ,
Great that it's working. So, to answer your question regarding token renew, this will depend on the client the modbus module is using. I don't have a lot of details on the modbus module, you would have to follow up with the modbus team to check which client they are using (c#, C, or if they are connecting directly using other non Azure IoT SDKs). When the client generates the token based on the shared key, they will establish the expiration time. Some client may let you configure that, but you would have to follow up on the specific client SDK github.
I'm not sure about the TLS handshake, it can be just a side effect of the token expiring.
Hope this helps, and let us know if there is anything else on this github issue that we can help.
Thanks,
Angelo Ribeiro.
Hi @aribeironovaes,
Cool, I understand better now, I'm going to see with the modbus team.
Thank you.
Hi,
As far as I know, there is no place to explicitly configure the token expiration time in current C# Microsoft.Azure.Devices.Client SDK. Modbus module is written based on the sample TempSensor module as a template. So I checked the sample tempSensor module log that I collected a couple weeks ago and found tempSensor module also renew its token every one hour.
2018-03-08 06:34:26.020 +00:00 [WRN] - Closing connection for device: MyDevice/tempSensor, Microsoft.Azure.Devices.Edge.Hub.Core.EdgeHubConnectionException: Connection closed for device MyDevice/tempSensor.,
2018-03-08 06:34:26.028 +00:00 [INF] - Disposing MessagingServiceClient for device Id MyDevice/tempSensor because of exception - Microsoft.Azure.Devices.Edge.Hub.Core.EdgeHubConnectionException: Connection closed for device MyDevice/tempSensor.
2018-03-08 06:34:26.060 +00:00 [INF] - Closing device proxy for device Id MyDevice/tempSensor
2018-03-08 06:34:26.061 +00:00 [INF] - Device connection removed for device MyDevice/tempSensor
2018-03-08 06:34:27.277 +00:00 [INF] - Obtained new token for client MyDevice/tempSensor that expires in 00:59:59.7226014
2018-03-08 06:34:27.277 +00:00 [INF] - New cloud connection created for device MyDevice/tempSensor
2018-03-08 06:34:27.277 +00:00 [INF] - Successfully authenticated device MyDevice/tempSensor
2018-03-08 06:34:27.277 +00:00 [INF] - Successfully generated identity for clientId MyDevice/tempSensor and username iotedgevm/MyDevice/tempSensor/api-version=2017-06-30&DeviceClientType=Microsoft.Azure.Devices.Client%2F1.17.0-preview-001%20%28.NET%20Core%204.6.0.0%3B%20Linux%204.13.0-1011-azure%20%2314-Ubuntu%20SMP%20Thu%20Feb%2015%2016%3A15%3A39%20UTC%202018%3B%20X64%29
2018-03-08 06:34:27.277 +00:00 [INF] - ClientAuthenticated, MyDevice/tempSensor, 57acaea7
2018-03-08 06:34:27.294 +00:00 [INF] - New device connection for device MyDevice/tempSensor
2018-03-08 06:34:27.294 +00:00 [INF] - Bind device proxy for device MyDevice/tempSensor
2018-03-08 06:34:27.294 +00:00 [INF] - Binding message channel for device Id MyDevice/tempSensor
2018-03-08 06:34:27.295 +00:00 [INF] - Set subscriptions from session state for MyDevice/tempSensor
2018-03-08 06:36:46.234 +00:00 [INF] - Started task to cleanup processed and stale messages for endpoint iothub
2018-03-08 06:36:46.284 +00:00 [INF] - Cleaned up 365 messages from queue for endpoint iothub and 365 messages from message store.
2018-03-08 07:07:16.286 +00:00 [INF] - Started task to cleanup processed and stale messages for endpoint iothub
2018-03-08 07:07:16.357 +00:00 [INF] - Cleaned up 366 messages from queue for endpoint iothub and 366 messages from message store.
2018-03-08 07:32:27.000 +00:00 [INF] - Existing token not found for MyDevice/tempSensor. Getting new token from the client...
2018-03-08 07:32:27.000 +00:00 [WRN] - Closing connection for device: MyDevice/tempSensor, Microsoft.Azure.Devices.Edge.Hub.Core.EdgeHubConnectionException: Connection closed for device MyDevice/tempSensor.,
2018-03-08 07:32:27.000 +00:00 [INF] - Disposing MessagingServiceClient for device Id MyDevice/tempSensor because of exception - Microsoft.Azure.Devices.Edge.Hub.Core.EdgeHubConnectionException: Connection closed for device MyDevice/tempSensor.
2018-03-08 07:32:27.000 +00:00 [INF] - Closing device proxy for device Id MyDevice/tempSensor
So I think it might worth checking with the Microsoft.Azure.Devices.Client SDK team if this is a expected behavior.
Thanks, Stephen
Hi,
Thank you @606simps.
So seems that this token expiration time is default and maybe it's not configurable. If that's true, it's ok for me, but I'm still thinking if it's this that is causing the TLS handshake failure
and if there is any consequence of that happening or if this is the expected behavior as pointed by @606simps.
I don't know what is the Microsoft.Azure.Devices.Client SDK team repo to open an issue referring to this, I found two that could be: Azure SDK for NET or Azure IoT SDK C. I think is the second one, but I'm not sure.
So, does anyone know where or with whom I can get this information?
Thank you very much.
Hi,
The github is: https://github.com/Azure/azure-iot-sdk-csharp (for modules they have a modules_preview branch).
Thanks,
Angelo Ribeiro
On Fri, Mar 30, 2018 at 9:48 AM, termocontrole notifications@github.com wrote:
Hi,
Thank you @606simps https://github.com/606simps.
So seems that this token expiration time is default and maybe it's not configurable. If that's true, it's ok for me, but I'm still thinking if it's this that is causing the TLS handshake failure and if there is any consequence of that happening or if this is the expected behavior as pointed by @606simps https://github.com/606simps.
I don't know what is the Microsoft.Azure.Devices.Client SDK team repo to open an issue referring to this, I found two that could be: Azure SDK for NET https://github.com/Azure/azure-sdk-for-net or Azure IoT SDK C https://github.com/Azure/azure-iot-sdk-c. I think is the second one, but I'm not sure.
So, does anyone know where or with whom I can get this information?
Thank you very much.
— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub https://github.com/Azure/iot-edge/issues/545#issuecomment-377567734, or mute the thread https://github.com/notifications/unsubscribe-auth/AI75b3yIU5YgkGZkX-TCLtrn45MiROUVks5tjmHsgaJpZM4SsI9c .
Angelo Ribeiro Msc - Federal University of Pernambuco Team in Training Alumni Triple Crowned! :)
Thank you @aribeironovaes, I opened an issue there.
Closing as this issue seems to be resolved. Please reopen if you continue to run into it. Thanks!
Hi @myagley,
Unfortunately the problem wasn't solved, it is still happening, mainly the TLS Handshake failure
and System Exception
. I only opened an issue with the Azure IoT SDK CSharp team to see if they could help, but seems that they can't, since they requested the attention of some IoT Edge team members, in this case you and @damonbarry.
Please, can you help there? (issue)
Well, it seems I can't reopen the issue :(
Thank you very much.
@termocontrole
The TLS handshake failed
failures are transient, coming from a lower layer when we close the connection at a higher layer, and nothing to worry about.
The exceptions seen on platforms at the low end of our HW requirements (like Pi) are being tracked in #475.
Thanks @damonbarry for the clarifications, I will follow that issue.
Hi,
I´m using a Raspberry Pi with Azure IoT Edge V2 and the modbus module, in the beginning the modbus module had some issues, but we were abble to track and solve it.
Now the messages are not correctly sent to IoT Hub, a lot of messages seems to be missed: some times it connects and send data to Hub, other times doesn´t connect and there are times that seems to be connected but doesn´t send any data to the endpoint.
I don´t know how to debug the IoT Edge V2 or turn the debug flags on to better understand whats heppening.
Here is my logs from 13-03 to 15-03:
13-03 - IoT Edge connected in portal but sending no data.
14-03 - IoT Edge connected in portal but sending no data.
15-03 - Warning: Your device is disconnected from this IoT Hub. The information displayed below is not up to date. You can go to the device twin to see the last update time. If you have not set up your IoT Edge device, please follow IoT Edge QuickStart instructions. If you have already set up your device, please check device connectivity.
edgeAgent:
edgeHub:
Can someone help me?
Thank you