Iotedge: edgeHub crashes on raspberry pi with what(): std::bad_alloc

Created on 3 Aug 2018 · 50Comments · Source: Azure/iotedge

Expected Behavior

edgeHub should run stable for a long time

Current Behavior

edgeHub reproducable crashes with:
terminate called after throwing an instance of 'std::bad_alloc'
what(): std::bad_alloc

Steps to Reproduce

We send data from a smartphone app to an raspberry pi based edge device (edgeHub) over Wifi (240 - 600 values / sec)
We analyse the data in a custom module
The system works fine for approx. 15 - 20 min
The edgeHub crashes with the error message: terminate called after throwing an instance of 'std::bad_alloc'
what(): std::bad_alloc

Context (Environment)

Device (Host) Operating System

Raspberry Pi 3
Linux EDGE-GW001 4.14.52-v7+ #1123 SMP Wed Jun 27 17:35:49 BST 2018 armv7l GNU/Linux

Architecture

arm32

Container Operating System

Raspian stretch

Runtime Versions

dotnet:
Microsoft .NET Core Shared Framework Host
Version : 2.0.9
Build : 1632fa1589b0eee3277a8841ce1770e554ece037

java:
openjdk version "1.8.0_171"
OpenJDK Runtime Environment (build 1.8.0_171-8u171-b11-1~deb9u1-b11)
OpenJDK Client VM (build 25.171-b11, mixed mode)

iotedged

iotedge 1.0.0 (52ef77db24126bf473265fc09c53d35290a2dd6b)

Edge Agent

mcr.microsoft.com/azureiotedge-agent:1.0

Edge Hub

mcr.microsoft.com/azureiotedge-hub:1.0

Docker

Docker version 18.06.0-dev, build daf021fe

Logs

edgeHub:

2018-08-03 06:50:49.384 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Getting next batch for endpoint GW001/Scoring/input1 starting from 17776 with batch size 10.
2018-08-03 06:50:49.385 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Obtained next batch for endpoint GW001/Scoring/input1 with batch size 1. Next start offset = 17777.
2018-08-03 06:50:49.386 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.ModuleEndpoint] - Sending 1 message(s) to module GW001/Scoring.
2018-08-03 06:50:49.387 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Device.DeviceMessageHandler] - Sent message with correlation ID ed27a144-72ba-45a2-aacd-8d64c37d07a4 to GW001/Scoring
2018-08-03 06:50:49.413 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Device.DeviceMessageHandler] - Received feedback Complete for message ed27a144-72ba-45a2-aacd-8d64c37d07a4 from device/module GW001/Scoring
2018-08-03 06:50:49.423 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Getting next batch for endpoint GW001/Scoring/input1 starting from 17777 with batch size 10.
2018-08-03 06:50:49.423 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Obtained next batch for endpoint GW001/Scoring/input1 with batch size 0. Next start offset = 17777.
2018-08-03 06:50:49.512 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Mqtt.MessagingServiceClient] - Sending message for device Id Sensor1
2018-08-03 06:50:49.513 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.RoutingEdgeHub] - Received message from Sensor1
2018-08-03 06:50:49.514 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Getting next batch for endpoint GW001/Scoring/input1 starting from 17777 with batch size 10.
2018-08-03 06:50:49.573 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Obtained next batch for endpoint GW001/Scoring/input1 with batch size 1. Next start offset = 17778.
2018-08-03 06:50:49.574 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.ModuleEndpoint] - Sending 1 message(s) to module GW001/Scoring.
2018-08-03 06:50:49.574 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Device.DeviceMessageHandler] - Sent message with correlation ID 941749f8-bfbd-4268-b3c3-2181f645e154 to GW001/Scoring
2018-08-03 06:50:49.583 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Device.DeviceMessageHandler] - Received feedback Complete for message 941749f8-bfbd-4268-b3c3-2181f645e154 from device/module GW001/Scoring
2018-08-03 06:50:49.586 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Getting next batch for endpoint GW001/Scoring/input1 starting from 17778 with batch size 10.
2018-08-03 06:50:49.587 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Obtained next batch for endpoint GW001/Scoring/input1 with batch size 0. Next start offset = 17778.
2018-08-03 06:50:50.379 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Mqtt.MessagingServiceClient] - Sending message for device Id Sensor1
2018-08-03 06:50:50.379 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.RoutingEdgeHub] - Received message from Sensor1
2018-08-03 06:50:50.384 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Getting next batch for endpoint GW001/Scoring/input1 starting from 17778 with batch size 10.
2018-08-03 06:50:50.386 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Obtained next batch for endpoint GW001/Scoring/input1 with batch size 1. Next start offset = 17779.
2018-08-03 06:50:50.387 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.ModuleEndpoint] - Sending 1 message(s) to module GW001/Scoring.
2018-08-03 06:50:50.387 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Device.DeviceMessageHandler] - Sent message with correlation ID b2353b2b-265b-4cd2-ac65-ad49aa690e97 to GW001/Scoring
2018-08-03 06:50:50.403 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Device.DeviceMessageHandler] - Received feedback Complete for message b2353b2b-265b-4cd2-ac65-ad49aa690e97 from device/module GW001/Scoring
2018-08-03 06:50:50.405 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Getting next batch for endpoint GW001/Scoring/input1 starting from 17779 with batch size 10.
2018-08-03 06:50:50.406 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Obtained next batch for endpoint GW001/Scoring/input1 with batch size 0. Next start offset = 17779.
2018-08-03 06:50:50.481 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Mqtt.MessagingServiceClient] - Sending message for device Id Sensor1
2018-08-03 06:50:50.481 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.RoutingEdgeHub] - Received message from Sensor1
2018-08-03 06:50:50.484 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Getting next batch for endpoint GW001/Scoring/input1 starting from 17779 with batch size 10.
2018-08-03 06:50:50.485 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Obtained next batch for endpoint GW001/Scoring/input1 with batch size 1. Next start offset = 17780.
2018-08-03 06:50:50.486 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.ModuleEndpoint] - Sending 1 message(s) to module GW001/Scoring.
2018-08-03 06:50:50.486 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Device.DeviceMessageHandler] - Sent message with correlation ID 8588edcb-b98a-486c-be54-fab1ff365109 to GW001/Scoring
2018-08-03 06:50:50.503 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Device.DeviceMessageHandler] - Received feedback Complete for message 8588edcb-b98a-486c-be54-fab1ff365109 from device/module GW001/Scoring
2018-08-03 06:50:50.505 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Getting next batch for endpoint GW001/Scoring/input1 starting from 17780 with batch size 10.
2018-08-03 06:50:50.506 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Obtained next batch for endpoint GW001/Scoring/input1 with batch size 0. Next start offset = 17780.
2018-08-03 06:50:51.379 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Mqtt.MessagingServiceClient] - Sending message for device Id Sensor1
2018-08-03 06:50:51.379 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.RoutingEdgeHub] - Received message from Sensor1
2018-08-03 06:50:51.382 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Getting next batch for endpoint GW001/Scoring/input1 starting from 17780 with batch size 10.
2018-08-03 06:50:51.500 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Obtained next batch for endpoint GW001/Scoring/input1 with batch size 1. Next start offset = 17781.
2018-08-03 06:50:51.501 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.ModuleEndpoint] - Sending 1 message(s) to module GW001/Scoring.
2018-08-03 06:50:51.502 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Device.DeviceMessageHandler] - Sent message with correlation ID 7a5e449c-00c1-4918-96e8-10cf50a19310 to GW001/Scoring
2018-08-03 06:50:51.514 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Device.DeviceMessageHandler] - Received feedback Complete for message 7a5e449c-00c1-4918-96e8-10cf50a19310 from device/module GW001/Scoring
2018-08-03 06:50:51.516 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Getting next batch for endpoint GW001/Scoring/input1 starting from 17781 with batch size 10.
2018-08-03 06:50:51.516 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Obtained next batch for endpoint GW001/Scoring/input1 with batch size 0. Next start offset = 17781.
2018-08-03 06:50:51.530 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Mqtt.MessagingServiceClient] - Sending message for device Id Sensor1
2018-08-03 06:50:51.530 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.RoutingEdgeHub] - Received message from Sensor1
2018-08-03 06:50:51.531 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Getting next batch for endpoint GW001/Scoring/input1 starting from 17781 with batch size 10.
2018-08-03 06:50:51.533 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Obtained next batch for endpoint GW001/Scoring/input1 with batch size 1. Next start offset = 17782.
2018-08-03 06:50:51.534 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.ModuleEndpoint] - Sending 1 message(s) to module GW001/Scoring.
2018-08-03 06:50:51.534 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Device.DeviceMessageHandler] - Sent message with correlation ID 8ae638f4-02f2-45a5-8597-823dba282fe3 to GW001/Scoring
2018-08-03 06:50:51.542 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Device.DeviceMessageHandler] - Received feedback Complete for message 8ae638f4-02f2-45a5-8597-823dba282fe3 from device/module GW001/Scoring
2018-08-03 06:50:51.548 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Getting next batch for endpoint GW001/Scoring/input1 starting from 17782 with batch size 10.
2018-08-03 06:50:51.549 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Obtained next batch for endpoint GW001/Scoring/input1 with batch size 0. Next start offset = 17782.
2018-08-03 06:50:52.380 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Mqtt.MessagingServiceClient] - Sending message for device Id Sensor1
2018-08-03 06:50:52.380 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.RoutingEdgeHub] - Received message from Sensor1
2018-08-03 06:50:52.383 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Getting next batch for endpoint GW001/Scoring/input1 starting from 17782 with batch size 10.
2018-08-03 06:50:52.385 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Obtained next batch for endpoint GW001/Scoring/input1 with batch size 1. Next start offset = 17783.
2018-08-03 06:50:52.386 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.ModuleEndpoint] - Sending 1 message(s) to module GW001/Scoring.
2018-08-03 06:50:52.387 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Device.DeviceMessageHandler] - Sent message with correlation ID 7f965cb9-564c-4897-a513-d14065bd8801 to GW001/Scoring
2018-08-03 06:50:52.403 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Device.DeviceMessageHandler] - Received feedback Complete for message 7f965cb9-564c-4897-a513-d14065bd8801 from device/module GW001/Scoring
2018-08-03 06:50:52.405 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Getting next batch for endpoint GW001/Scoring/input1 starting from 17783 with batch size 10.
2018-08-03 06:50:52.406 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Obtained next batch for endpoint GW001/Scoring/input1 with batch size 0. Next start offset = 17783.
2018-08-03 06:50:52.499 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Mqtt.MessagingServiceClient] - Sending message for device Id Sensor1
2018-08-03 06:50:52.499 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.RoutingEdgeHub] - Received message from Sensor1
2018-08-03 06:50:52.502 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Getting next batch for endpoint GW001/Scoring/input1 starting from 17783 with batch size 10.
2018-08-03 06:50:52.504 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Obtained next batch for endpoint GW001/Scoring/input1 with batch size 1. Next start offset = 17784.
2018-08-03 06:50:52.505 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.ModuleEndpoint] - Sending 1 message(s) to module GW001/Scoring.
2018-08-03 06:50:52.506 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Device.DeviceMessageHandler] - Sent message with correlation ID e64b2c8b-ca41-42d9-93d2-ef285f5235ef to GW001/Scoring
2018-08-03 06:50:52.633 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Device.DeviceMessageHandler] - Received feedback Complete for message e64b2c8b-ca41-42d9-93d2-ef285f5235ef from device/module GW001/Scoring
2018-08-03 06:50:52.635 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Getting next batch for endpoint GW001/Scoring/input1 starting from 17784 with batch size 10.
2018-08-03 06:50:52.636 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Obtained next batch for endpoint GW001/Scoring/input1 with batch size 0. Next start offset = 17784.
2018-08-03 06:50:53.268 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.CloudEndpoint] - Sending 10 message(s) upstream.
2018-08-03 06:50:53.268 +00:00 [ERR] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.CloudEndpoint] - Received message does not contain a device Id
2018-08-03 06:50:53.268 +00:00 [ERR] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.CloudEndpoint] - Received message does not contain a device Id
2018-08-03 06:50:53.269 +00:00 [ERR] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.CloudEndpoint] - Received message does not contain a device Id
2018-08-03 06:50:53.269 +00:00 [ERR] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.CloudEndpoint] - Received message does not contain a device Id
2018-08-03 06:50:53.269 +00:00 [ERR] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.CloudEndpoint] - Received message does not contain a device Id
2018-08-03 06:50:53.269 +00:00 [ERR] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.CloudEndpoint] - Received message does not contain a device Id
2018-08-03 06:50:53.269 +00:00 [ERR] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.CloudEndpoint] - Received message does not contain a device Id
2018-08-03 06:50:53.270 +00:00 [ERR] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.CloudEndpoint] - Received message does not contain a device Id
2018-08-03 06:50:53.270 +00:00 [ERR] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.CloudEndpoint] - Received message does not contain a device Id
2018-08-03 06:50:53.270 +00:00 [ERR] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.CloudEndpoint] - Received message does not contain a device Id
2018-08-03 06:50:53.375 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Mqtt.MessagingServiceClient] - Sending message for device Id Sensor1
2018-08-03 06:50:53.376 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.RoutingEdgeHub] - Received message from Sensor1
2018-08-03 06:50:53.378 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Getting next batch for endpoint GW001/Scoring/input1 starting from 17784 with batch size 10.
2018-08-03 06:50:53.380 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Obtained next batch for endpoint GW001/Scoring/input1 with batch size 1. Next start offset = 17785.
2018-08-03 06:50:53.380 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.ModuleEndpoint] - Sending 1 message(s) to module GW001/Scoring.
2018-08-03 06:50:53.381 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Device.DeviceMessageHandler] - Sent message with correlation ID bcbfc024-65ca-467d-b71d-8376f5e311d5 to GW001/Scoring
2018-08-03 06:50:53.394 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Device.DeviceMessageHandler] - Received feedback Complete for message bcbfc024-65ca-467d-b71d-8376f5e311d5 from device/module GW001/Scoring
2018-08-03 06:50:53.396 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Getting next batch for endpoint GW001/Scoring/input1 starting from 17785 with batch size 10.
2018-08-03 06:50:53.397 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Obtained next batch for endpoint GW001/Scoring/input1 with batch size 0. Next start offset = 17785.
2018-08-03 06:50:53.518 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Mqtt.MessagingServiceClient] - Sending message for device Id Sensor1
2018-08-03 06:50:53.519 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.RoutingEdgeHub] - Received message from Sensor1
2018-08-03 06:50:53.521 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Getting next batch for endpoint GW001/Scoring/input1 starting from 17785 with batch size 10.
2018-08-03 06:50:53.524 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Obtained next batch for endpoint GW001/Scoring/input1 with batch size 1. Next start offset = 17786.
2018-08-03 06:50:53.638 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.ModuleEndpoint] - Sending 1 message(s) to module GW001/Scoring.
2018-08-03 06:50:53.639 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Device.DeviceMessageHandler] - Sent message with correlation ID c55fac11-c170-4d96-8d39-04fd362e70f0 to GW001/Scoring
2018-08-03 06:50:53.653 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Device.DeviceMessageHandler] - Received feedback Complete for message c55fac11-c170-4d96-8d39-04fd362e70f0 from device/module GW001/Scoring
2018-08-03 06:50:53.654 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Getting next batch for endpoint GW001/Scoring/input1 starting from 17786 with batch size 10.
2018-08-03 06:50:53.655 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Obtained next batch for endpoint GW001/Scoring/input1 with batch size 0. Next start offset = 17786.
terminate called after throwing an instance of 'std::bad_alloc'
  what():  std::bad_alloc
[2018-08-03 06:51:08 +00:00]: Starting Edge Hub
[08/03/2018 06:51:09.533 AM] Edge Hub Main()
2018-08-03 06:51:10.947 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Edged.WorkloadClient] - Making a Http call to unix:///var/run/iotedge/workload.sock to CreateServerCertificateAsync
2018-08-03 06:51:12.325 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Connecting socket /var/run/iotedge/workload.sock
2018-08-03 06:51:12.348 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Connected socket /var/run/iotedge/workload.sock
2018-08-03 06:51:12.380 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Sending request http://workload.sock/modules/%24edgeHub/genid/636662374498110148/certificate/server?api-version=2018-06-28
2018-08-03 06:51:12.677 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Response received Created
2018-08-03 06:51:13.086 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Edged.WorkloadClient] - Received a valid Http response from unix:///var/run/iotedge/workload.sock for CreateServerCertificateAsync
2018-08-03 06:51:17.285 +00:00 [INF] [EdgeHub] - Starting Edge Hub
2018-08-03 06:51:17.289 +00:00 [INF] [EdgeHub] - Version - 1.0.0.14487025 (52ef77db24126bf473265fc09c53d35290a2dd6b)
2018-08-03 06:51:17.302 +00:00 [INF] [EdgeHub] -
        █████╗ ███████╗██╗   ██╗██████╗ ███████╗
       ██╔══██╗╚══███╔╝██║   ██║██╔══██╗██╔════╝
       ███████║  ███╔╝ ██║   ██║██████╔╝█████╗
       ██╔══██║ ███╔╝  ██║   ██║██╔══██╗██╔══╝
       ██║  ██║███████╗╚██████╔╝██║  ██║███████╗
       ╚═╝  ╚═╝╚══════╝ ╚═════╝ ╚═╝  ╚═╝╚══════╝

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

2018-08-03 06:51:17.302 +00:00 [INF] [EdgeHub] - Installing intermediate certificates.
2018-08-03 06:51:17.583 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.DeviceConnectivityManager] - Created DeviceConnectivityManager with connected check frequency 00:05:00 and disconnected check frequency 00:02:00
2018-08-03 06:51:17.872 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudConnection] - Attempting to connect to IoT Hub for client GW001/$edgeHub via AMQP...
2018-08-03 06:51:18.216 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudConnection] - Connected to IoT Hub for client GW001/$edgeHub via AMQP, with client operation timeout 60000.
2018-08-03 06:51:18.254 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudConnection] - Updated cloud connection for client GW001/$edgeHub
2018-08-03 06:51:18.258 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudConnection] - Created cloud connection for client GW001/$edgeHub
2018-08-03 06:51:18.265 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Core.ConnectionManager] - New cloud connection created for device GW001/$edgeHub
2018-08-03 06:51:18.305 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.DeviceConnectivityManager] - CloudProxy to test device connectivity set
2018-08-03 06:51:18.305 +00:00 [INF] [EdgeHub] - Initializing configuration
2018-08-03 06:51:28.908 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Service.Modules.RoutingModule] - Created persistent store at /tmp/edgeHub
2018-08-03 06:51:29.063 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Started task to cleanup processed and stale messages
2018-08-03 06:51:29.063 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Created new message store
2018-08-03 06:51:29.360 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudProxy] - Binding cloud listener for device GW001/$edgeHub
2018-08-03 06:51:29.397 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Core.ConnectionManager] - New device connection for device GW001/$edgeHub
2018-08-03 06:51:29.417 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.RoutingEdgeHub] - Adding subscription DesiredPropertyUpdates for client GW001/$edgeHub.
2018-08-03 06:51:33.877 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ConnectivityAwareClient] - Received connection status changed callback with connection status Connected and reason Connection_Ok
2018-08-03 06:51:34.723 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.DeviceConnectivityManager] - IotHub call succeeded
2018-08-03 06:51:34.781 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.DeviceConnectivityManager] - Entering connected state
2018-08-03 06:51:34.797 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.TwinManager] - ConnectionEstablished for GW001/$edgeHub
2018-08-03 06:51:34.848 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.TwinManager] - Processing ConnectionEstablished for device GW001/$edgeHub
2018-08-03 06:51:34.907 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ConnectivityAwareClient] - Operation UpdateReportedPropertiesAsync succeeded
2018-08-03 06:51:34.915 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudProxy] - Updating reported properties for device GW001/$edgeHub
2018-08-03 06:51:34.924 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.TwinManager] - Successfully sent reported properties to cloud for GW001/$edgeHub and reported properties version 0
2018-08-03 06:51:35.157 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.TwinManager] - Updated cached reported property for GW001/$edgeHub at reported property version 2123 cloudVerified True
2018-08-03 06:51:35.200 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.EdgeHubConnection] - Established IoT Hub connection for edge hub GW001/$edgeHub
2018-08-03 06:51:35.244 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.TwinManager] - Getting twin for GW001/$edgeHub on ConnectionEstablished
2018-08-03 06:51:35.707 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.DeviceConnectivityManager] - IotHub call succeeded
2018-08-03 06:51:35.717 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ConnectivityAwareClient] - Operation GetTwinAsync succeeded
2018-08-03 06:51:35.726 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudProxy] - Getting twin for device GW001/$edgeHub
2018-08-03 06:51:35.753 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.TwinManager] - Successfully got twin for GW001/$edgeHub from cloud at desired version 276 reported version 2132
2018-08-03 06:51:35.820 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.TwinManager] - Updating cached twin for GW001/$edgeHub from desired version 275 to 276 and reported version 2123 to 2132
2018-08-03 06:51:35.832 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.TwinManager] - Sending desired property update for GW001/$edgeHub old desired version 275 cloud desired version 276
2018-08-03 06:51:35.855 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.TwinManager] - Sending diff {
  "routes": {
    "route_2": "FROM /messages/* INTO BrokeredEndpoint(\"/modules/Scoring/inputs/input1\")",
    "route_3": null
  },
  "storeAndForwardConfiguration": {
    "timeToLiveSecs": 7200
  },
  "$version": 276
} to GW001/$edgeHub
2018-08-03 06:51:35.955 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.DeviceConnectivityManager] - IotHub call succeeded
2018-08-03 06:51:35.956 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ConnectivityAwareClient] - Operation GetTwinAsync succeeded
2018-08-03 06:51:35.956 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudProxy] - Getting twin for device GW001/$edgeHub
2018-08-03 06:51:35.957 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.TwinManager] - Successfully got twin for GW001/$edgeHub from cloud at desired version 276 reported version 2132
2018-08-03 06:51:35.963 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.TwinManager] - Local twin for GW001/$edgeHub at higher or equal desired version 276 compared to cloud 276 or reported version 2132 compared to cloud 2132
2018-08-03 06:51:37.278 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.DeviceConnectivityManager] - IotHub call succeeded
2018-08-03 06:51:37.279 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ConnectivityAwareClient] - Operation UpdateReportedPropertiesAsync succeeded
2018-08-03 06:51:37.279 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudProxy] - Updating reported properties for device GW001/$edgeHub
2018-08-03 06:51:37.279 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.TwinManager] - Successfully sent reported properties to cloud for GW001/$edgeHub and reported properties version 0
2018-08-03 06:51:37.281 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.TwinManager] - Updated cached reported property for GW001/$edgeHub at reported property version 2132 cloudVerified True
2018-08-03 06:51:37.283 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Core.EdgeHubConnection] - Obtained edge hub config from module twin
2018-08-03 06:51:37.322 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Core.EdgeHubConnection] - Obtained edge hub config patch update from module twin
2018-08-03 06:51:38.086 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Added sequential store for endpoint iothub
2018-08-03 06:51:38.154 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Added sequential store for endpoint GW001/Scoring/input1
2018-08-03 06:51:38.169 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Core.Config.ConfigUpdater] - Set the following 2 route(s) in edge hub
2018-08-03 06:51:38.176 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Core.Config.ConfigUpdater] - route_1: FROM /* INTO $upstream
2018-08-03 06:51:38.176 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Core.Config.ConfigUpdater] - route_2: FROM /messages/* INTO BrokeredEndpoint("/modules/Scoring/inputs/input1")
2018-08-03 06:51:38.179 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Getting next batch for endpoint GW001/Scoring/input1 starting from 17786 with batch size 10.
2018-08-03 06:51:38.179 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Getting next batch for endpoint iothub starting from 0 with batch size 10.
2018-08-03 06:51:38.182 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Updated message store TTL to 7200 seconds
2018-08-03 06:51:38.185 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Core.Config.ConfigUpdater] - Updated the edge hub store and forward configuration
2018-08-03 06:51:38.187 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Core.Config.ConfigUpdater] - Initialized edge hub configuration
2018-08-03 06:51:38.211 +00:00 [DBG] [EdgeHub] - Waiting on shutdown handler to trigger
2018-08-03 06:51:38.232 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Obtained next batch for endpoint GW001/Scoring/input1 with batch size 0. Next start offset = 17786.
2018-08-03 06:51:38.377 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Obtained next batch for endpoint iothub with batch size 10. Next start offset = 29293.
2018-08-03 06:51:38.504 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.CloudEndpoint] - Sending 10 message(s) upstream.
2018-08-03 06:51:38.539 +00:00 [ERR] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.CloudEndpoint] - Received message does not contain a device Id
2018-08-03 06:51:38.540 +00:00 [ERR] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.CloudEndpoint] - Received message does not contain a device Id
2018-08-03 06:51:38.541 +00:00 [ERR] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.CloudEndpoint] - Received message does not contain a device Id
2018-08-03 06:51:38.541 +00:00 [ERR] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.CloudEndpoint] - Received message does not contain a device Id
2018-08-03 06:51:38.541 +00:00 [ERR] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.CloudEndpoint] - Received message does not contain a device Id
2018-08-03 06:51:38.541 +00:00 [ERR] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.CloudEndpoint] - Received message does not contain a device Id
2018-08-03 06:51:38.542 +00:00 [ERR] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.CloudEndpoint] - Received message does not contain a device Id
2018-08-03 06:51:38.542 +00:00 [ERR] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.CloudEndpoint] - Received message does not contain a device Id
2018-08-03 06:51:38.542 +00:00 [ERR] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.CloudEndpoint] - Received message does not contain a device Id
2018-08-03 06:51:38.542 +00:00 [ERR] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.CloudEndpoint] - Received message does not contain a device Id

Additional Information

top:

Tasks: 121 total,   1 running,  75 sleeping,   0 stopped,   0 zombie
%Cpu(s):  6.6 us,  2.4 sy,  0.0 ni, 90.8 id,  0.2 wa,  0.0 hi,  0.0 si,  0.0 st
KiB Mem :   949452 total,    47500 free,   297480 used,   604472 buff/cache
KiB Swap:   102396 total,    95484 free,     6912 used.   552104 avail Mem

  PID USER      PR  NI    VIRT    RES    SHR S  %CPU %MEM     TIME+ COMMAND
18492 devicea+  20   0 2055236 156836  55304 S  14.6 16.5   2:00.36 dotnet
20599 root      20   0  369708  53240  10004 S   8.6  5.6   1:02.04 java
  705 root      20   0  981344  82332  26212 S   7.0  8.7  86:46.93 dockerd
20516 root      20   0  793292   2748   2200 S   1.7  0.3   0:09.85 docker-containe
 1175 root      20   0  270672  59796  35908 S   1.3  6.3  11:16.38 dotnet
20664 devicea+  20   0    8256   3000   2540 R   1.0  0.3   0:00.27 top
  709 iotedge   20   0   49084  11120   8536 S   0.7  1.2   3:09.75 iotedged
 1153 root      20   0  793292   3484   3036 S   0.7  0.4   0:54.10 docker-containe
  766 root      20   0  966888  15916  10188 S   0.3  1.7   4:24.87 docker-containe
18474 root      20   0  793228   2908   2200 S   0.3  0.3   0:01.39 docker-containe
19379 root      20   0       0      0      0 I   0.3  0.0   0:00.39 kworker/u8:2

edgehub customer-reported iotedge

Source

ts4iot

Most helpful comment

We may have finally found the root cause of this issue. :confetti_ball: This PR has the fix: #1299. It's still a little early in testing but we are pretty confident this is causing the memory pressure on constrained devices. We will be backporting this to the 1.0.8 branch.

myagley on 6 Jun 2019

🎉2

All 50 comments

Hi @ts4iot - did you try to set the OptimizeForPerformance environment variable to false, as explained here - https://docs.microsoft.com/en-us/azure/iot-edge/troubleshoot#stability-issues-on-resource-constrained-devices
That should take care of this problem. If you are seeing this in spite of setting this flag, then let us know.
Also, from the logs, looks like the EdgeHub is not able to parse the MQTT messages properly. Are you using some Azure IoT Device SDK?

varunpuranik on 3 Aug 2018

Hi,
thanks for the fast response. The variable OptimizeForPerformance is set to false.
We use: com.microsoft.azure.sdk.iot:iot-device-client:1.13.1 in our smartphone app.

Attached a code snippet that shows how we send the data from the app to the edgeHub:

public void writeRecord()
{
    if (outerObject != null) {
        try {
            outerObject.add("records", recordArray);
            Message msg = new Message(outerObject.toString());
            msg.setProperty("messageCount", Long.toString(msgId));
            EventCallback eventCallback = new EventCallback();
            client.sendEventAsync(msg, eventCallback,msg);
            msgId++;
        } catch (Exception e) {
        }
    }
}

As far as I understand the device Id mentioned in this error message "Received message does not contain a device Id" should come from the connection context.

ts4iot on 3 Aug 2018

Regarding handling the error message "Received message does not contain a device Id", I believe the supported ModuleClient (or DeviceClient) version should be 1.17.x (or greater) if you intend to communicate with the Edge. Here is a link to the nuget package: https://www.nuget.org/packages/Microsoft.Azure.Devices.Client/

Here is a link which describes how to migrate your code to the newer supported APIs: https://azure.microsoft.com/en-us/blog/iot-edge-ga-migration/ . You might find this useful in general.

Another point if you are using a module checkout some of the sample code created for you when follow these instructions: https://docs.microsoft.com/en-us/azure/iot-edge/how-to-develop-csharp-module

Can you try upgrading and see if this fixes your issue?

mrohera on 3 Aug 2018

Our Scoring module is based on Java (not C#). Inside the scoring module we use a H2O machine learning model which is a POJO. The Scoring module uses the ModuleClient of the Java IoT SDK (version of the java iot sdk is comparable to the smartphone app com.microsoft.azure.sdk.iot:iot-device-client:1.13.1) to communicate with the edgeHub.

Attached the information how we build the docker container:

FROM azureiotedge/azureiotedge-module-base:1.0.0-preview006-linux-arm32v7
USER root
RUN apt-get update && apt-get install -y --no-install-recommends apt-utils
RUN apt-get -y install nano
RUN apt-get install -y openjdk-8-jdk
RUN apt-get -y install git-core
RUN apt-get -y install sudo
RUN apt-get -y install build-essential
RUN git clone git://git.drogon.net/wiringPi
WORKDIR /wiringPi
RUN git pull origin
RUN ./build
WORKDIR /app
RUN echo EntryPoint
COPY ./addons /app
RUN chown -R moduleuser:moduleuser .
USER moduleuser
ENV PATH=$PATH:.
ARG EXE_DIR=.
CMD ["run.sh"]

ts4iot on 3 Aug 2018

Ah sorry about, I misread your issue above.

I just verified that that you are at the correct SDK version which has module support enabled. I personally have not tried the Java SDK with Edge to comment on this more effectively. I did notice some samples here that I intend to try: https://github.com/Azure/azure-iot-sdk-java/tree/master/device/iot-device-samples.

mrohera on 4 Aug 2018

@timtay-microsoft who may be able to help with this as well.

mrohera on 4 Aug 2018

As you can see at the end of my first post, the edgeHub process (dotnet) consumes 2GB of virtual memory (swap space). Is there a way to limit the amount of memory the edgeHub process consumes?

ts4iot on 4 Aug 2018

When the edgeHub crashes, our scoring module does not automatically reconnect to the edgeHub. The smartphone app which uses the same Java IoT SDK automatically reconnects to the edgeHub after restart. It seems that the reconnection procedure from the ModuleClient (used in the Scoring module) works in a different way than the DeviceClient (used in the smartphone app). We use in both components com.microsoft.azure.sdk.iot:iot-device-client:1.13.1.

Attached a log from the Scoring module when i force a edgeHub restart:

13:49:22.305 [pool-2-thread-3] INFO  com.tsystems.smartmon.process.FeatureGenerator - aggregated Bucket:[0.14312837125, 0.026111761875, 10.403629625]
13:49:22.306 [pool-2-thread-3] INFO  com.tsystems.smartmon.process.FeatureGenerator - Aggregating Bucket: Bucket [timestamp=15335633596, values=[Measure [deviceId=device001, time=1533563359606, values={X=0.1328782, Y=0.044891283, Z=10.41358}], Measure [deviceId=device001, time=1533563359618, values={X=0.1340753, Y=0.044891283, Z=10.386047}], Measure [deviceId=device001, time=1533563359630, values={X=0.13587095, Y=0.025737667, Z=10.410587}], Measure [deviceId=device001, time=1533563359642, values={X=0.14844051, Y=0.022146367, Z=10.429143}], Measure [deviceId=device001, time=1533563359655, values={X=0.14065935, Y=0.034715924, Z=10.439917}], Measure [deviceId=device001, time=1533563359667, values={X=0.14963761, Y=0.038307227, Z=10.416573}], Measure [deviceId=device001, time=1533563359679, values={X=0.15023616, Y=0.029927522, Z=10.403405}]]]
13:49:22.306 [pool-2-thread-3] INFO  com.tsystems.smartmon.process.FeatureGenerator - aggregated Bucket:[0.14168544, 0.034373896142857144, 10.414178857142856]
13:49:22.307 [pool-2-thread-3] INFO  com.tsystems.smartmon.process.FeatureGenerator - Aggregating Bucket: Bucket [timestamp=15335633597, values=[Measure [deviceId=device001, time=1533563359703, values={X=0.15263036, Y=0.035913024, Z=10.407595}], Measure [deviceId=device001, time=1533563359716, values={X=0.1388637, Y=0.020949265, Z=10.457274}], Measure [deviceId=device001, time=1533563359727, values={X=0.13587095, Y=0.02873042, Z=10.416573}], Measure [deviceId=device001, time=1533563359740, values={X=0.14664486, Y=0.046088383, Z=10.441113}], Measure [deviceId=device001, time=1533563359751, values={X=0.15263036, Y=0.031124622, Z=10.402207}], Measure [deviceId=device001, time=1533563359763, values={X=0.15622166, Y=0.025737667, Z=10.392033}], Measure [deviceId=device001, time=1533563359776, values={X=0.12808979, Y=0.044891283, Z=10.406996}], Measure [deviceId=device001, time=1533563359787, values={X=0.14963761, Y=0.02873042, Z=10.419566}], Measure [deviceId=device001, time=1533563359799, values={X=0.13587095, Y=0.032920275, Z=10.424355}]]]
13:49:22.308 [pool-2-thread-3] INFO  com.tsystems.smartmon.process.FeatureGenerator - aggregated Bucket:[0.14405113777777778, 0.03278726211111111, 10.418634666666668]
13:49:22.308 [pool-2-thread-3] INFO  com.tsystems.smartmon.process.FeatureGenerator - iSAX Values: [3, 3, 3, 3, 3, 3, 3, 3, 3, 3, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6, 6]
13:49:22.316 [pool-2-thread-3] INFO  com.tsystems.smartmon.process.FeatureGenerator - Scoring result: ScoringResult [score=0.006567885632962678, deviceId=device001, timestamp=2018-08-06 13:49:18.800]
13:49:22.316 [pool-2-thread-3] INFO  com.tsystems.smartmon.process.BucketManager - Created Window: [15335633589, 15335633590, 15335633591, 15335633592, 15335633593, 15335633594, 15335633595, 15335633596, 15335633597, 15335633598]
13:49:22.316 [pool-2-thread-3] INFO  com.tsystems.smartmon.process.FeatureGenerator - Waiting for Buckets.
13:49:22.317 [pool-2-thread-1] INFO  com.microsoft.azure.sdk.iot.device.Message - The message with messageid 8b99532f-a807-4d88-ac6d-69e9451c6307 has expiry time as 5000 milliseconds and the message will expire on Mon Aug 06 13:49:27 GMT 2018, method name is setExpiryTime
ScoringResult [score=0.006567885632962678, deviceId=device001, timestamp=2018-08-06 13:49:18.800]
13:49:22.317 [pool-2-thread-1] INFO  com.tsystems.smartmon.source.MQTTSource - Sending Prediction: ScoringResult [score=0.006567885632962678, deviceId=device001, timestamp=2018-08-06 13:49:18.800]
13:49:22.616 [MQTT Rec: GW001/Scoring] INFO  com.microsoft.azure.sdk.iot.device.transport.IotHubTransport - The messages in progress are buffered to be sent again due to a connection loss, method name is handleDisconnection
13:49:22.618 [MQTT Rec: GW001/Scoring] INFO  com.tsystems.smartmon.source.MQTTSource - CONNECTION STATUS UPDATE: DISCONNECTED_RETRYING
13:49:22.619 [MQTT Rec: GW001/Scoring] INFO  com.tsystems.smartmon.source.MQTTSource - CONNECTION STATUS REASON: NO_NETWORK
13:49:22.619 [MQTT Rec: GW001/Scoring] INFO  com.tsystems.smartmon.source.MQTTSource - CONNECTION STATUS THROWABLE: Mqtt connection lost
13:49:23.317 [pool-2-thread-3] INFO  com.tsystems.smartmon.process.FeatureGenerator - Waiting for Buckets.
13:49:24.317 [pool-2-thread-3] INFO  com.tsystems.smartmon.process.FeatureGenerator - Waiting for Buckets.
13:49:25.318 [pool-2-thread-3] INFO  com.tsystems.smartmon.process.FeatureGenerator - Waiting for Buckets.
13:49:26.318 [pool-2-thread-3] INFO  com.tsystems.smartmon.process.FeatureGenerator - Waiting for Buckets.
13:49:27.188 [MQTT Rec: GW001/Scoring] INFO  com.tsystems.smartmon.source.MQTTSource - CONNECTION STATUS UPDATE: DISCONNECTED
13:49:27.189 [MQTT Rec: GW001/Scoring] INFO  com.tsystems.smartmon.source.MQTTSource - CONNECTION STATUS REASON: BAD_CREDENTIAL
13:49:27.189 [MQTT Rec: GW001/Scoring] INFO  com.tsystems.smartmon.source.MQTTSource - CONNECTION STATUS THROWABLE: Unable to establish MQTT connection
13:49:27.319 [pool-2-thread-3] INFO  com.tsystems.smartmon.process.FeatureGenerator - Waiting for Buckets.
13:49:28.319 [pool-2-thread-3] INFO  com.tsystems.smartmon.process.FeatureGenerator - Waiting for Buckets.
13:49:29.320 [pool-2-thread-3] INFO  com.tsystems.smartmon.process.FeatureGenerator - Waiting for Buckets.
13:49:30.320 [pool-2-thread-3] INFO  com.tsystems.smartmon.process.FeatureGenerator - Waiting for Buckets.
13:49:31.321 [pool-2-thread-3] INFO  com.tsystems.smartmon.process.FeatureGenerator - Waiting for Buckets.
13:49:32.321 [pool-2-thread-3] INFO  com.tsystems.smartmon.process.FeatureGenerator - Waiting for Buckets.

Only a restart of the Scoring module solves the connection problem. So at the moment I have no workaround for the edgeHub crashes.

I know this problem should be addressed to the Java IoT SDK issues. @timtay-microsoft can you link that problem to Java IoT SDK issues?

ts4iot on 6 Aug 2018

@ts4iot the reconnection processes are the same between a ModuleClient instance and a DeviceClient instance. Do you have any logs from the Java SDK side for this case? Preferably with the connection status change callback registered? It will shed some more light on what type of exception your ModuleClient instance is getting upon this disconnection.

timtay-microsoft on 8 Aug 2018

Also, the Java SDK is in process of releasing a new Maven package that fixed a number of bugs around the Edgehub scenario. I highly recommend you upgrade when the package is released.

timtay-microsoft on 8 Aug 2018

Attached a more detailed logging of the reconnect attempts:

Scoring module (ModuleClient):

08:35:16.953 [pool-2-thread-3] INFO  com.tsystems.smartmon.process.FeatureGenerator - Waiting for Buckets.
ScoringResult [score=0.006567885632962678, deviceId=device001, timestamp=2018-08-09 08:35:12.300]
08:35:16.953 [pool-2-thread-1] INFO  com.tsystems.smartmon.source.MQTTSource - Sending Prediction: ScoringResult [score=0.006567885632962678, deviceId=device001, timestamp=2018-08-09 08:35:12.300]
08:35:17.904 [MQTT Rec: GW001/Scoring] INFO  com.tsystems.smartmon.source.MQTTSource - CONNECTION STATUS UPDATE: DISCONNECTED_RETRYING
08:35:17.905 [MQTT Rec: GW001/Scoring] INFO  com.tsystems.smartmon.source.MQTTSource - CONNECTION STATUS REASON: NO_NETWORK
08:35:17.906 [MQTT Rec: GW001/Scoring] INFO  com.tsystems.smartmon.source.MQTTSource - CONNECTION STATUS THROWABLE: Mqtt connection lost
com.microsoft.azure.sdk.iot.device.exceptions.ProtocolException: Mqtt connection lost
        at com.microsoft.azure.sdk.iot.device.transport.mqtt.exceptions.PahoExceptionTranslator.convertToMqttException(PahoExceptionTranslator.java:69)
        at com.microsoft.azure.sdk.iot.device.transport.mqtt.Mqtt.connectionLost(Mqtt.java:340)
        at org.eclipse.paho.client.mqttv3.internal.CommsCallback.connectionLost(CommsCallback.java:292)
        at org.eclipse.paho.client.mqttv3.internal.ClientComms.shutdownConnection(ClientComms.java:423)
        at org.eclipse.paho.client.mqttv3.internal.CommsReceiver.run(CommsReceiver.java:181)
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
        at java.util.concurrent.FutureTask.run(FutureTask.java:266)
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180)
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
        at java.lang.Thread.run(Thread.java:748)
Caused by: Connection lost (32109) - java.io.EOFException
        ... 8 more
Caused by: java.io.EOFException
        at java.io.DataInputStream.readByte(DataInputStream.java:267)
        at org.eclipse.paho.client.mqttv3.internal.wire.MqttInputStream.readMqttWireMessage(MqttInputStream.java:92)
        at org.eclipse.paho.client.mqttv3.internal.CommsReceiver.run(CommsReceiver.java:133)
        ... 7 more
08:35:17.953 [pool-2-thread-3] INFO  com.tsystems.smartmon.process.FeatureGenerator - Waiting for Buckets.
08:35:18.954 [pool-2-thread-3] INFO  com.tsystems.smartmon.process.FeatureGenerator - Waiting for Buckets.
08:35:19.954 [pool-2-thread-3] INFO  com.tsystems.smartmon.process.FeatureGenerator - Waiting for Buckets.
08:35:20.955 [pool-2-thread-3] INFO  com.tsystems.smartmon.process.FeatureGenerator - Waiting for Buckets.
08:35:21.955 [pool-2-thread-3] INFO  com.tsystems.smartmon.process.FeatureGenerator - Waiting for Buckets.
08:35:22.956 [pool-2-thread-3] INFO  com.tsystems.smartmon.process.FeatureGenerator - Waiting for Buckets.
08:35:23.956 [pool-2-thread-3] INFO  com.tsystems.smartmon.process.FeatureGenerator - Waiting for Buckets.
08:35:24.450 [MQTT Rec: GW001/Scoring] INFO  com.tsystems.smartmon.source.MQTTSource - CONNECTION STATUS UPDATE: DISCONNECTED
08:35:24.450 [MQTT Rec: GW001/Scoring] INFO  com.tsystems.smartmon.source.MQTTSource - CONNECTION STATUS REASON: BAD_CREDENTIAL
08:35:24.450 [MQTT Rec: GW001/Scoring] INFO  com.tsystems.smartmon.source.MQTTSource - CONNECTION STATUS THROWABLE: Unable to establish MQTT connection
com.microsoft.azure.sdk.iot.device.exceptions.ProtocolException: Unable to establish MQTT connection
        at com.microsoft.azure.sdk.iot.device.transport.mqtt.exceptions.PahoExceptionTranslator.convertToMqttException(PahoExceptionTranslator.java:41)
        at com.microsoft.azure.sdk.iot.device.transport.mqtt.Mqtt.connect(Mqtt.java:113)
        at com.microsoft.azure.sdk.iot.device.transport.mqtt.MqttMessaging.start(MqttMessaging.java:54)
        at com.microsoft.azure.sdk.iot.device.transport.mqtt.MqttIotHubConnection.open(MqttIotHubConnection.java:179)
        at com.microsoft.azure.sdk.iot.device.transport.IotHubTransport.openConnection(IotHubTransport.java:642)
        at com.microsoft.azure.sdk.iot.device.transport.IotHubTransport.singleReconnectAttempt(IotHubTransport.java:760)
        at com.microsoft.azure.sdk.iot.device.transport.IotHubTransport.reconnect(IotHubTransport.java:714)
        at com.microsoft.azure.sdk.iot.device.transport.IotHubTransport.handleDisconnection(IotHubTransport.java:672)
        at com.microsoft.azure.sdk.iot.device.transport.IotHubTransport.onConnectionLost(IotHubTransport.java:205)
        at com.microsoft.azure.sdk.iot.device.transport.mqtt.Mqtt.connectionLost(Mqtt.java:348)
        at org.eclipse.paho.client.mqttv3.internal.CommsCallback.connectionLost(CommsCallback.java:292)
        at org.eclipse.paho.client.mqttv3.internal.ClientComms.shutdownConnection(ClientComms.java:423)
        at org.eclipse.paho.client.mqttv3.internal.CommsReceiver.run(CommsReceiver.java:181)
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
        at java.util.concurrent.FutureTask.run(FutureTask.java:266)
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180)
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
        at java.lang.Thread.run(Thread.java:748)
Caused by: MqttException (0) - java.net.SocketException: Connection reset
        at org.eclipse.paho.client.mqttv3.internal.ExceptionHelper.createMqttException(ExceptionHelper.java:38)
        at org.eclipse.paho.client.mqttv3.internal.ClientComms$ConnectBG.run(ClientComms.java:715)
        ... 7 more
Caused by: java.net.SocketException: Connection reset
        at java.net.SocketInputStream.read(SocketInputStream.java:210)
        at java.net.SocketInputStream.read(SocketInputStream.java:141)
        at sun.security.ssl.InputRecord.readFully(InputRecord.java:465)
        at sun.security.ssl.InputRecord.read(InputRecord.java:503)
        at sun.security.ssl.SSLSocketImpl.readRecord(SSLSocketImpl.java:983)
        at sun.security.ssl.SSLSocketImpl.performInitialHandshake(SSLSocketImpl.java:1385)
        at sun.security.ssl.SSLSocketImpl.startHandshake(SSLSocketImpl.java:1413)
        at sun.security.ssl.SSLSocketImpl.startHandshake(SSLSocketImpl.java:1397)
        at org.eclipse.paho.client.mqttv3.internal.SSLNetworkModule.start(SSLNetworkModule.java:108)
        at org.eclipse.paho.client.mqttv3.internal.ClientComms$ConnectBG.run(ClientComms.java:701)
        ... 7 more
08:35:24.957 [pool-2-thread-3] INFO  com.tsystems.smartmon.process.FeatureGenerator - Waiting for Buckets.

Smartphone app (DeviceClient):

08-09 10:04:26.921 9339-9339/com.tsystems.datacollector D/dalvikvm: GC_FOR_ALLOC freed 1013K, 41% free 9602K/16004K, paused 29ms, total 29ms
08-09 10:04:28.793 9339-9406/com.tsystems.datacollector D/dalvikvm: GC_FOR_ALLOC freed 1011K, 40% free 9614K/16004K, paused 27ms, total 27ms
08-09 10:04:29.924 9339-9364/com.tsystems.datacollector I/dalvikvm: Could not find method java.lang.Exception.<init>, referenced from method com.microsoft.azure.sdk.iot.device.exceptions.DeviceClientException.<init>
08-09 10:04:29.924 9339-9364/com.tsystems.datacollector W/dalvikvm: VFY: unable to resolve direct method 42900: Ljava/lang/Exception;.<init> (Ljava/lang/String;Ljava/lang/Throwable;ZZ)V
08-09 10:04:29.924 9339-9364/com.tsystems.datacollector D/dalvikvm: VFY: replacing opcode 0x70 at 0x0000
08-09 10:04:29.924 9339-9364/com.tsystems.datacollector I/System.out: CONNECTION STATUS UPDATE: DISCONNECTED_RETRYING
    CONNECTION STATUS REASON: NO_NETWORK
    CONNECTION STATUS THROWABLE: Mqtt connection lost
08-09 10:04:29.924 9339-9364/com.tsystems.datacollector W/System.err: com.microsoft.azure.sdk.iot.device.exceptions.ProtocolException: Mqtt connection lost
        at com.microsoft.azure.sdk.iot.device.transport.mqtt.exceptions.PahoExceptionTranslator.convertToMqttException(PahoExceptionTranslator.java:69)
        at com.microsoft.azure.sdk.iot.device.transport.mqtt.Mqtt.connectionLost(Mqtt.java:340)
        at org.eclipse.paho.client.mqttv3.internal.CommsCallback.connectionLost(CommsCallback.java:292)
        at org.eclipse.paho.client.mqttv3.internal.ClientComms.shutdownConnection(ClientComms.java:423)
        at org.eclipse.paho.client.mqttv3.internal.CommsReceiver.run(CommsReceiver.java:181)
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:422)
        at java.util.concurrent.FutureTask.run(FutureTask.java:237)
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:152)
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:265)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1112)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:587)
08-09 10:04:29.934 9339-9364/com.tsystems.datacollector W/System.err:     at java.lang.Thread.run(Thread.java:841)
08-09 10:04:29.954 9339-9364/com.tsystems.datacollector W/System.err: Caused by: Verbindung wurde getrennt (32109) - javax.net.ssl.SSLException: Read error: ssl=0x63cbdbb8: I/O error during system call, Connection reset by peer
        ... 8 more
    Caused by: javax.net.ssl.SSLException: Read error: ssl=0x63cbdbb8: I/O error during system call, Connection reset by peer
08-09 10:04:29.974 9339-9364/com.tsystems.datacollector W/System.err:     at com.android.org.conscrypt.NativeCrypto.SSL_read(Native Method)
        at com.android.org.conscrypt.OpenSSLSocketImpl$SSLInputStream.read(OpenSSLSocketImpl.java:690)
        at libcore.io.Streams.readSingleByte(Streams.java:41)
        at com.android.org.conscrypt.OpenSSLSocketImpl$SSLInputStream.read(OpenSSLSocketImpl.java:674)
        at java.io.DataInputStream.readByte(DataInputStream.java:75)
        at org.eclipse.paho.client.mqttv3.internal.wire.MqttInputStream.readMqttWireMessage(MqttInputStream.java:92)
        at org.eclipse.paho.client.mqttv3.internal.CommsReceiver.run(CommsReceiver.java:133)
        ... 7 more
08-09 10:04:30.414 9339-9339/com.tsystems.datacollector D/dalvikvm: GC_FOR_ALLOC freed 988K, 40% free 9650K/16004K, paused 26ms, total 27ms
08-09 10:04:32.767 9339-9339/com.tsystems.datacollector D/dalvikvm: GC_FOR_ALLOC freed 997K, 40% free 9676K/16004K, paused 35ms, total 36ms
08-09 10:04:34.819 9339-9339/com.tsystems.datacollector D/dalvikvm: GC_FOR_ALLOC freed 1002K, 40% free 9698K/16004K, paused 27ms, total 27ms
08-09 10:04:37.031 9339-9339/com.tsystems.datacollector D/dalvikvm: GC_FOR_ALLOC freed 1020K, 40% free 9702K/16004K, paused 28ms, total 28ms
08-09 10:04:39.234 9339-9339/com.tsystems.datacollector D/dalvikvm: GC_FOR_ALLOC freed 1004K, 40% free 9721K/16004K, paused 33ms, total 33ms
08-09 10:04:41.406 9339-9339/com.tsystems.datacollector D/dalvikvm: GC_FOR_ALLOC freed 1000K, 40% free 9744K/16004K, paused 27ms, total 27ms
08-09 10:04:43.558 9339-9339/com.tsystems.datacollector D/dalvikvm: GC_FOR_ALLOC freed 1021K, 40% free 9747K/16004K, paused 26ms, total 26ms
08-09 10:04:45.721 9339-9339/com.tsystems.datacollector D/dalvikvm: GC_FOR_ALLOC freed 1003K, 39% free 9767K/16004K, paused 28ms, total 28ms
08-09 10:04:47.963 9339-9339/com.tsystems.datacollector D/dalvikvm: GC_FOR_ALLOC freed 1000K, 39% free 9791K/16004K, paused 27ms, total 28ms
08-09 10:04:50.035 9339-9339/com.tsystems.datacollector D/dalvikvm: GC_FOR_ALLOC freed 1023K, 39% free 9791K/16004K, paused 27ms, total 27ms
08-09 10:04:52.288 9339-9339/com.tsystems.datacollector D/dalvikvm: GC_FOR_ALLOC freed 1001K, 39% free 9813K/16004K, paused 27ms, total 27ms
08-09 10:04:54.460 9339-9339/com.tsystems.datacollector D/dalvikvm: GC_FOR_ALLOC freed 1003K, 39% free 9834K/16004K, paused 28ms, total 28ms
08-09 10:04:56.602 9339-9339/com.tsystems.datacollector D/dalvikvm: GC_FOR_ALLOC freed 991K, 39% free 9865K/16004K, paused 32ms, total 33ms
08-09 10:04:58.735 9339-9339/com.tsystems.datacollector D/dalvikvm: GC_FOR_ALLOC freed 1032K, 39% free 9857K/16004K, paused 34ms, total 34ms
08-09 10:05:00.987 9339-9339/com.tsystems.datacollector D/dalvikvm: GC_FOR_ALLOC freed 1002K, 39% free 9879K/16004K, paused 30ms, total 30ms
08-09 10:05:03.179 9339-9339/com.tsystems.datacollector D/dalvikvm: GC_FOR_ALLOC freed 998K, 39% free 9904K/16004K, paused 26ms, total 26ms
08-09 10:05:05.221 9339-9339/com.tsystems.datacollector D/dalvikvm: GC_FOR_ALLOC freed 990K, 38% free 9937K/16004K, paused 28ms, total 28ms
08-09 10:05:06.383 9339-9364/com.tsystems.datacollector I/System.out: CONNECTION STATUS UPDATE: CONNECTED
    CONNECTION STATUS REASON: CONNECTION_OK
    CONNECTION STATUS THROWABLE: null
08-09 10:05:06.733 9339-9339/com.tsystems.datacollector D/dalvikvm: GC_FOR_ALLOC freed 1049K, 39% free 9913K/16004K, paused 27ms, total 27ms
08-09 10:05:07.514 9339-9406/com.tsystems.datacollector D/dalvikvm: GC_FOR_ALLOC freed 1121K, 39% free 9814K/16004K, paused 33ms, total 34ms
08-09 10:05:07.834 9339-9405/com.tsystems.datacollector D/dalvikvm: GC_FOR_ALLOC freed 1059K, 39% free 9778K/16004K, paused 29ms, total 29ms

ts4iot on 9 Aug 2018

@ts4iot - To limit the memory being used by edgeHub, you can set it in the createOptions of the EdgeHub. Look in the HostConfig section of the container create options - https://docs.docker.com/v17.09/engine/api/v1.30/#operation/ContainerCreate

varunpuranik on 9 Aug 2018

Hi @varunpuranik - According to the description the memory limit should be set in bytes. I've set the createOptions of edgeHub as follows:

{
  "HostConfig": {
    "Memory": 100000000,
    "MemorySwap": 500000000,
    "PortBindings": {
      "8883/tcp": [
        {
          "HostPort": "8883"
        }
      ],
      "443/tcp": [
        {
          "HostPort": "443"
        }
      ],
      "5671/tcp": [
        {
          "HostPort": "5671"
        }
      ]
    }
  }
}

But it has no effect. The dotnet process consumes still 2GB virtual memory and app. 130MB phys. mem.

Tasks: 108 total,   2 running,  67 sleeping,   0 stopped,   0 zombie
%Cpu(s):  1.4 us,  0.7 sy,  0.0 ni, 97.7 id,  0.2 wa,  0.0 hi,  0.0 si,  0.0 st
KiB Mem :   949452 total,   360712 free,   216528 used,   372212 buff/cache
KiB Swap:   102396 total,    95996 free,     6400 used.   625564 avail Mem

  PID USER      PR  NI    VIRT    RES    SHR S  %CPU %MEM     TIME+ COMMAND
14848 devicea+  20   0 2004368 129428  53012 S   0.3 13.6   0:27.84 dotnet
13198 root      20   0  259964  58676  40064 S   2.0  6.2   0:28.96 dotnet
12060 root      20   0  972704  54648  26396 S   3.0  5.8   0:34.44 dockerd
13214 iotedge   20   0   49084  16476  14160 S   0.3  1.7   0:02.66 iotedged
12067 root      20   0  942312  15084  10544 S   0.3  1.6   0:04.97 docker-containe
  111 root      20   0   35116  12068  11844 S   0.3  1.3   2:58.95 systemd-journal
15456 devicea+  20   0    8112   3140   2636 R   1.0  0.3   0:00.22 top
13179 root      20   0  793228   2704   2080 S   0.3  0.3   0:00.75 docker-containe

The physical memory consumption of the dotnet process increases always to app. 175 MB before it crashes.

ts4iot on 9 Aug 2018

It looks like the reason the ModuleClient and DeviceClient are behaving differently is that they are encountering different exceptions. We should be able to fix that on our end because the SocketException that the moduleClient is encountering should be classified as retryable, but right now it isn't. I'll look into updating the Java SDK to correctly classify that exception.

timtay-microsoft on 9 Aug 2018

The fix for the Java SDK is checked into master now, and is slated to be released tomorrow, 8/10. Let me know if you still see issues with ModuleClient reconnection logic.

timtay-microsoft on 10 Aug 2018

@timtay-microsoft - with the master version I get the following error when the Scoring module tries to connect to the edgeHub:

14:43:42.245 [main] INFO  com.tsystems.smartmon.source.MQTTSource - Successfully set message callback.
14:43:42.246 [main] INFO  com.tsystems.smartmon.source.MQTTSource - Set server cert...
java.io.IOException: Could not open the connection
        at com.microsoft.azure.sdk.iot.device.DeviceIO.open(DeviceIO.java:164)
        at com.microsoft.azure.sdk.iot.device.InternalClient.open(InternalClient.java:130)
        at com.tsystems.smartmon.source.MQTTSource.start(MQTTSource.java:117)
        at com.tsystems.smartmon.App.main(App.java:50)
Caused by: com.microsoft.azure.sdk.iot.device.exceptions.ProtocolException: Unable to establish MQTT connection
        at com.microsoft.azure.sdk.iot.device.transport.mqtt.exceptions.PahoExceptionTranslator.convertToMqttException(PahoExceptionTranslator.java:75)
        at com.microsoft.azure.sdk.iot.device.transport.mqtt.Mqtt.connect(Mqtt.java:116)
        at com.microsoft.azure.sdk.iot.device.transport.mqtt.MqttMessaging.start(MqttMessaging.java:49)
        at com.microsoft.azure.sdk.iot.device.transport.mqtt.MqttIotHubConnection.open(MqttIotHubConnection.java:179)
        at com.microsoft.azure.sdk.iot.device.transport.IotHubTransport.openConnection(IotHubTransport.java:641)
        at com.microsoft.azure.sdk.iot.device.transport.IotHubTransport.open(IotHubTransport.java:277)
        at com.microsoft.azure.sdk.iot.device.DeviceIO.open(DeviceIO.java:160)
        ... 3 more
Caused by: Unable to connect to server (32103) - java.net.ConnectException: Connection refused (Connection refused)
        at org.eclipse.paho.client.mqttv3.internal.TCPNetworkModule.start(TCPNetworkModule.java:94)
        at org.eclipse.paho.client.mqttv3.internal.SSLNetworkModule.start(SSLNetworkModule.java:103)
        at org.eclipse.paho.client.mqttv3.internal.ClientComms$ConnectBG.run(ClientComms.java:701)
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
        at java.util.concurrent.FutureTask.run(FutureTask.java:266)
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180)
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
        at java.lang.Thread.run(Thread.java:748)
Caused by: java.net.ConnectException: Connection refused (Connection refused)
        at java.net.PlainSocketImpl.socketConnect(Native Method)
        at java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:350)
        at java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:206)
        at java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:188)
        at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:392)
        at java.net.Socket.connect(Socket.java:589)
        at org.eclipse.paho.client.mqttv3.internal.TCPNetworkModule.start(TCPNetworkModule.java:80)
        ... 9 more
14:43:42.589 [pool-2-thread-1] INFO  com.tsystems.smartmon.source.MQTTSource - Run MQTT Client
14:43:42.591 [pool-2-thread-2] INFO  com.tsystems.smartmon.converter.CollectorRunnable - Run Collector

In my current implementation I add the root cert of the edgeHub (from /var/lib/iotedge/hsm/certcs/edge_owner_ca*.pem) with the following command:

            IotHubAuthenticationProvider provider = clientConfig.getAuthenticationProvider();
            provider.setIotHubTrustedCert(this.ca);

to trusted certs. As connection string I use the connection string of the module with this attachment:

;GatewayHostName=172.18.0.1

With this configuration and com.microsoft.azure.sdk.iot:iot-device-client:1.13.1 the Scoring module can connect to the edgeHub.

ts4iot on 10 Aug 2018

@ts4iot are you getting a similar error when using MQTT_WS instead of MQTT?

timtay-microsoft on 10 Aug 2018

Attached the error message with MQTT_WS

18:16:19.184 [main] INFO  com.tsystems.smartmon.source.MQTTSource - Set server cert...
java.io.IOException: Could not open the connection
        at com.microsoft.azure.sdk.iot.device.DeviceIO.open(DeviceIO.java:164)
        at com.microsoft.azure.sdk.iot.device.InternalClient.open(InternalClient.java:130)
        at com.tsystems.smartmon.source.MQTTSource.start(MQTTSource.java:118)
        at com.tsystems.smartmon.App.main(App.java:50)
Caused by: com.microsoft.azure.sdk.iot.device.transport.mqtt.exceptions.MqttUnauthorizedException: Unable to establish MQTT connection
        at com.microsoft.azure.sdk.iot.device.transport.mqtt.exceptions.PahoExceptionTranslator.convertToMqttException(PahoExceptionTranslator.java:63)
        at com.microsoft.azure.sdk.iot.device.transport.mqtt.Mqtt.connect(Mqtt.java:116)
        at com.microsoft.azure.sdk.iot.device.transport.mqtt.MqttMessaging.start(MqttMessaging.java:49)
        at com.microsoft.azure.sdk.iot.device.transport.mqtt.MqttIotHubConnection.open(MqttIotHubConnection.java:179)
        at com.microsoft.azure.sdk.iot.device.transport.IotHubTransport.openConnection(IotHubTransport.java:641)
        at com.microsoft.azure.sdk.iot.device.transport.IotHubTransport.open(IotHubTransport.java:277)
        at com.microsoft.azure.sdk.iot.device.DeviceIO.open(DeviceIO.java:160)
        ... 3 more
Caused by: Not authorized to connect (5)
        at org.eclipse.paho.client.mqttv3.internal.ExceptionHelper.createMqttException(ExceptionHelper.java:28)
        at org.eclipse.paho.client.mqttv3.internal.ClientState.notifyReceivedAck(ClientState.java:988)
        at org.eclipse.paho.client.mqttv3.internal.CommsReceiver.run(CommsReceiver.java:145)
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
        at java.util.concurrent.FutureTask.run(FutureTask.java:266)
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180)
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
        at java.lang.Thread.run(Thread.java:748)
18:16:20.515 [pool-2-thread-1] INFO  com.tsystems.smartmon.source.MQTTSource - Run MQTT Client

ts4iot on 10 Aug 2018

And what kind of logs are you getting on the edgehub during this failure to connect?

timtay-microsoft on 10 Aug 2018

Attached the log of edgeHub with MQTT_WS:

2018-08-10 18:25:43.244 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ConnectivityAwareClient] - Received connection status changed callback with connection status Disabled and reason Client_Close
2018-08-10 18:25:54.265 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ConnectivityAwareClient] - Operation GetTwinAsync timed out
2018-08-10 18:25:54.265 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.DeviceConnectivityManager] - IotHub call timed out
2018-08-10 18:25:54.265 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.DeviceConnectivityManager] - Exiting connected state
2018-08-10 18:25:54.265 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.DeviceConnectivityManager] - Entering unreachable state
2018-08-10 18:25:54.265 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.DeviceConnectivityManager] - Calling IotHub to test connectivity
2018-08-10 18:25:54.266 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ConnectivityAwareClient] - Received connection status changed callback with connection status Connected and reason Connection_Ok
2018-08-10 18:25:54.266 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ConnectivityAwareClient] - Operation GetTwinAsync failed
System.TimeoutException: Operation timeout expired.
   at Microsoft.Azure.Devices.Client.InternalClient.<>c.<ApplyTimeoutTwin>b__64_2(Task`1 t)
   at System.Threading.Tasks.ContinuationResultTaskFromResultTask`2.InnerInvoke()
   at System.Threading.Tasks.Task.<>c.<.cctor>b__278_1(Object obj)
   at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state)
--- End of stack trace from previous location where exception was thrown ---
   at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state)
   at System.Threading.Tasks.Task.ExecuteWithThreadLocal(Task& currentTaskSlot)
--- End of stack trace from previous location where exception was thrown ---
   at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ConnectivityAwareClient.InvokeFunc[T](Func`1 func, String operation)
2018-08-10 18:25:54.276 +00:00 [WRN] [Microsoft.Azure.Devices.Edge.Hub.Core.TwinManager] - Error in connection established callback for client GW001/Scoring - System.TimeoutException Operation timeout expired.
2018-08-10 18:25:54.276 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.TwinManager] - Processing ConnectionEstablished for device GW001/Scoring
2018-08-10 18:25:54.277 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.TwinManager] - Getting twin for GW001/Scoring on ConnectionEstablished
2018-08-10 18:25:54.416 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.DeviceConnectivityManager] - IotHub call succeeded
2018-08-10 18:25:54.417 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.DeviceConnectivityManager] - Entering connected state
2018-08-10 18:25:54.417 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.TwinManager] - ConnectionEstablished for GW001/$edgeHub
2018-08-10 18:25:54.417 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.TwinManager] - ConnectionEstablished for GW001/Scoring
2018-08-10 18:25:54.418 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.TwinManager] - ConnectionEstablished for GW001/Scoring
2018-08-10 18:25:54.418 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.TwinManager] - ConnectionEstablished for GW001/Scoring
2018-08-10 18:25:54.418 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.TwinManager] - ConnectionEstablished for GW001/Scoring
2018-08-10 18:25:54.419 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.TwinManager] - ConnectionEstablished for GW001/Scoring
2018-08-10 18:25:54.419 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.TwinManager] - ConnectionEstablished for GW001/Scoring
2018-08-10 18:25:54.419 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.TwinManager] - ConnectionEstablished for GW001/Scoring
2018-08-10 18:25:54.420 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.TwinManager] - ConnectionEstablished for GW001/Scoring
2018-08-10 18:25:54.420 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.TwinManager] - ConnectionEstablished for GW001/Scoring
2018-08-10 18:25:54.420 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.TwinManager] - ConnectionEstablished for GW001/Scoring
2018-08-10 18:25:54.421 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.TwinManager] - ConnectionEstablished for GW001/Scoring
2018-08-10 18:25:54.421 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.TwinManager] - ConnectionEstablished for GW001/Scoring
2018-08-10 18:25:54.421 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.TwinManager] - ConnectionEstablished for GW001/Scoring
2018-08-10 18:25:54.482 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.TwinManager] - ConnectionEstablished for GW001/Scoring
2018-08-10 18:25:54.483 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ConnectivityAwareClient] - Operation UpdateReportedPropertiesAsync succeeded
2018-08-10 18:25:54.483 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudProxy] - Updating reported properties for device GW001/$edgeHub
2018-08-10 18:26:01.270 +00:00 [DBG] [Microsoft.AspNetCore.Server.Kestrel] - Connection id ""0HLFUTHSHH232"" started.
2018-08-10 18:26:02.053 +00:00 [INF] [Microsoft.AspNetCore.Hosting.Internal.WebHost] - Request starting HTTP/1.1 GET https://172.18.0.1/$iothub/websocket?iothub-no-client-cert=true
2018-08-10 18:26:02.054 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Http.Middleware.WebSocketHandlingMiddleware] - Request 0HLFUTHSHH232:00000001 received. CorrelationId 7227797d-325d-4d2f-8eb8-d40e9923153c
2018-08-10 18:26:02.054 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Http.WebSocketListenerRegistry] - SubProtocol: mqtt CorrelationId: 7227797d-325d-4d2f-8eb8-d40e9923153c
2018-08-10 18:26:02.058 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Mqtt.MqttWebSocketListener] - HostName: 172.18.0.1 CorrelationId 7227797d-325d-4d2f-8eb8-d40e9923153c
2018-08-10 18:26:02.146 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudConnection] - Attempting to connect to IoT Hub for client GW001/Scoring via AMQP...
2018-08-10 18:26:02.147 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudConnection] - Connected to IoT Hub for client GW001/Scoring via AMQP, with client operation timeout 60000.
2018-08-10 18:26:02.156 +00:00 [ERR] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudProxy] - Error closing cloud proxy for device GW001/Scoring
Microsoft.Azure.Devices.Client.Exceptions.AssertionFailedException: An unexpected failure occurred. Applications should not attempt to handle this error. For diagnostic purposes, this English message is associated with the failure: The number of devices should be greater than zero.
   at Microsoft.Azure.Devices.Client.Fx.AssertAndThrow(String description)
   at Microsoft.Azure.Devices.Client.IotHubDeviceScopeConnectionPool.RemoveDeviceFromConnection(IotHubDeviceMuxConnection iotHubDeviceMuxConnection, String deviceId)
   at Microsoft.Azure.Devices.Client.IotHubDeviceMuxConnection.Release(String deviceId)
   at Microsoft.Azure.Devices.Client.Transport.AmqpTransportHandler.CloseAsync()
   at Microsoft.Azure.Devices.Client.Transport.GateKeeperDelegatingHandler.CloseAsync()
   at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudProxy.CloseAsync() in /opt/vsts/work/1/s/edge-hub/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/CloudProxy.cs:line 45
2018-08-10 18:26:02.162 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.TwinManager] - ConnectionEstablished for GW001/Scoring
2018-08-10 18:26:02.162 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudConnection] - Updated cloud connection for client GW001/Scoring
2018-08-10 18:26:02.163 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Core.ConnectionManager] - New cloud connection created for device GW001/Scoring
2018-08-10 18:26:02.160 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ConnectivityAwareClient] - Operation GetTwinAsync failed
System.AggregateException: One or more errors occurred. (A task was canceled.) ---> System.Threading.Tasks.TaskCanceledException: A task was canceled.
   --- End of inner exception stack trace ---
   at System.Threading.Tasks.Task`1.GetResultCore(Boolean waitCompletionNotification)
   at System.Threading.Tasks.Task`1.get_Result()
   at Microsoft.Azure.Devices.Client.InternalClient.<>c.<ApplyTimeoutTwin>b__64_2(Task`1 t)
   at System.Threading.Tasks.ContinuationResultTaskFromResultTask`2.InnerInvoke()
   at System.Threading.Tasks.Task.<>c.<.cctor>b__278_1(Object obj)
   at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state)
--- End of stack trace from previous location where exception was thrown ---
   at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state)
   at System.Threading.Tasks.Task.ExecuteWithThreadLocal(Task& currentTaskSlot)
--- End of stack trace from previous location where exception was thrown ---
   at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ConnectivityAwareClient.InvokeFunc[T](Func`1 func, String operation)
---> (Inner Exception #0) System.Threading.Tasks.TaskCanceledException: A task was canceled.<---

2018-08-10 18:26:02.166 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudConnection] - Getting new token for GW001/Scoring.
2018-08-10 18:26:02.166 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudConnection] - New token requested by client GW001/Scoring, but using existing token as it is usable.
2018-08-10 18:26:02.177 +00:00 [WRN] [Microsoft.Azure.Devices.Edge.Hub.Core.TwinManager] - Error in connection established callback for client GW001/Scoring - System.AggregateException One or more errors occurred. (A task was canceled.)
2018-08-10 18:26:02.179 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.TwinManager] - Processing ConnectionEstablished for device GW001/Scoring
2018-08-10 18:26:02.179 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.TwinManager] - Getting twin for GW001/Scoring on ConnectionEstablished
2018-08-10 18:26:02.232 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ConnectivityAwareClient] - Operation OpenAsync failed
Microsoft.Azure.Devices.Client.Exceptions.UnauthorizedException: Put token failed. status-code: 401, status-description: The specified SAS token has an invalid signature. It does not match either the primary or secondary key..
   at Microsoft.Azure.Devices.Client.InternalClient.<>c.<ApplyTimeout>b__62_2(Task t)
   at System.Threading.Tasks.ContinuationTaskFromTask.InnerInvoke()
   at System.Threading.Tasks.Task.<>c.<.cctor>b__278_1(Object obj)
   at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state)
--- End of stack trace from previous location where exception was thrown ---
   at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state)
   at System.Threading.Tasks.Task.ExecuteWithThreadLocal(Task& currentTaskSlot)
--- End of stack trace from previous location where exception was thrown ---
   at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ConnectivityAwareClient.<>c__DisplayClass24_0.<<InvokeFunc>b__0>d.MoveNext() in /opt/vsts/work/1/s/edge-hub/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/ConnectivityAwareClient.cs:line 123
--- End of stack trace from previous location where exception was thrown ---
   at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ConnectivityAwareClient.InvokeFunc[T](Func`1 func, String operation) in /opt/vsts/work/1/s/edge-hub/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/ConnectivityAwareClient.cs:line 103
2018-08-10 18:26:02.242 +00:00 [WRN] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudProxy] - Error opening IotHub connection for device GW001/Scoring
Microsoft.Azure.Devices.Client.Exceptions.UnauthorizedException: Put token failed. status-code: 401, status-description: The specified SAS token has an invalid signature. It does not match either the primary or secondary key..
   at Microsoft.Azure.Devices.Client.InternalClient.<>c.<ApplyTimeout>b__62_2(Task t)
   at System.Threading.Tasks.ContinuationTaskFromTask.InnerInvoke()
   at System.Threading.Tasks.Task.<>c.<.cctor>b__278_1(Object obj)
   at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state)
--- End of stack trace from previous location where exception was thrown ---
   at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state)
   at System.Threading.Tasks.Task.ExecuteWithThreadLocal(Task& currentTaskSlot)
--- End of stack trace from previous location where exception was thrown ---
   at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ConnectivityAwareClient.<>c__DisplayClass24_0.<<InvokeFunc>b__0>d.MoveNext() in /opt/vsts/work/1/s/edge-hub/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/ConnectivityAwareClient.cs:line 123
--- End of stack trace from previous location where exception was thrown ---
   at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ConnectivityAwareClient.InvokeFunc[T](Func`1 func, String operation) in /opt/vsts/work/1/s/edge-hub/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/ConnectivityAwareClient.cs:line 103
   at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudProxy.OpenAsync() in /opt/vsts/work/1/s/edge-hub/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/CloudProxy.cs:line 60
2018-08-10 18:26:02.248 +00:00 [ERR] [Microsoft.Azure.Devices.Edge.Hub.Mqtt.DeviceIdentityProvider] - Unable to generate identity for clientId GW001/Scoring and username {Servername}/GW001/Scoring/?api-version=2018-06-30&DeviceClientType=com.microsoft.azure.sdk.iot.iot-device-client%2F1.13.1%20%281.8.0_171%3B%20Linux%3B%20arm%29
2018-08-10 18:26:02.248 +00:00 [INF] [ProtocolGateway] - ClientNotAuthenticated, Client ID: GW001/Scoring; Username: {Servername}/GW001/Scoring/?api-version=2018-06-30&DeviceClientType=com.microsoft.azure.sdk.iot.iot-device-client%2F1.13.1%20%281.8.0_171%3B%20Linux%3B%20arm%29, 6d0f6739
2018-08-10 18:26:02.249 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Mqtt.ServerWebSocketChannel] - Transport closed. CorrelationId 6d0f6739
2018-08-10 18:26:02.279 +00:00 [WRN] [Microsoft.Azure.Devices.Edge.Hub.Mqtt.ServerWebSocketChannel] - Error reading transport. CorrelationId 6d0f6739
System.Net.WebSockets.WebSocketException (0x80004005): The remote party closed the WebSocket connection without completing the close handshake. ---> System.Net.WebSockets.WebSocketException (0x80004005): An exception caused the WebSocket to enter the Aborted state. Please see the InnerException, if present, for more details.
   at System.Net.WebSockets.ManagedWebSocket.CloseWithReceiveErrorAndThrowAsync(WebSocketCloseStatus closeStatus, WebSocketError error, Exception innerException)
   at System.Net.WebSockets.ManagedWebSocket.HandleReceivedCloseAsync(MessageHeader header)
   at System.Net.WebSockets.ManagedWebSocket.ReceiveAsyncPrivate[TWebSocketReceiveResultGetter,TWebSocketReceiveResult](Memory`1 payloadBuffer, CancellationToken cancellationToken, TWebSocketReceiveResultGetter resultGetter)
   at System.Net.WebSockets.ManagedWebSocket.ReceiveAsyncPrivate[TWebSocketReceiveResultGetter,TWebSocketReceiveResult](Memory`1 payloadBuffer, CancellationToken cancellationToken, TWebSocketReceiveResultGetter resultGetter)
   at Microsoft.Azure.Devices.Edge.Hub.Mqtt.ServerWebSocketChannel.DoReadBytes(IByteBuffer byteBuffer) in /opt/vsts/work/1/s/edge-hub/src/Microsoft.Azure.Devices.Edge.Hub.Mqtt/ServerWebSocketChannel.cs:line 243
   at Microsoft.Azure.Devices.Edge.Hub.Mqtt.ServerWebSocketChannel.DoBeginRead() in /opt/vsts/work/1/s/edge-hub/src/Microsoft.Azure.Devices.Edge.Hub.Mqtt/ServerWebSocketChannel.cs:line 154
2018-08-10 18:26:02.297 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Mqtt.ServerWebSocketChannel] - Transport aborted. CorrelationId 6d0f6739
2018-08-10 18:26:02.299 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Http.Middleware.WebSocketHandlingMiddleware] - Request 0HLFUTHSHH232:00000001 completed. CorrelationId 7227797d-325d-4d2f-8eb8-d40e9923153c
2018-08-10 18:26:02.299 +00:00 [INF] [Microsoft.AspNetCore.Hosting.Internal.WebHost] - Request finished in 246.2507ms 101
2018-08-10 18:26:02.301 +00:00 [DBG] [Microsoft.AspNetCore.Server.Kestrel] - Connection id ""0HLFUTHSHH232"" disconnecting.
2018-08-10 18:26:02.302 +00:00 [DBG] [Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets] - Connection id ""0HLFUTHSHH232"" sending FIN.
2018-08-10 18:26:02.329 +00:00 [DBG] [Microsoft.AspNetCore.Server.Kestrel] - Connection id ""0HLFUTHSHH232"" stopped.
2018-08-10 18:26:02.316 +00:00 [WRN] [DotNetty.Transport.Channels.DefaultChannelPipeline] - An ExceptionCaught() event was fired, and it reached at the tail of the pipeline. It usually means the last handler in the pipeline did not handle the exception.
System.Net.WebSockets.WebSocketException (0x80004005): The remote party closed the WebSocket connection without completing the close handshake. ---> System.Net.WebSockets.WebSocketException (0x80004005): An exception caused the WebSocket to enter the Aborted state. Please see the InnerException, if present, for more details.
   at System.Net.WebSockets.ManagedWebSocket.CloseWithReceiveErrorAndThrowAsync(WebSocketCloseStatus closeStatus, WebSocketError error, Exception innerException)
   at System.Net.WebSockets.ManagedWebSocket.HandleReceivedCloseAsync(MessageHeader header)
   at System.Net.WebSockets.ManagedWebSocket.ReceiveAsyncPrivate[TWebSocketReceiveResultGetter,TWebSocketReceiveResult](Memory`1 payloadBuffer, CancellationToken cancellationToken, TWebSocketReceiveResultGetter resultGetter)
   at System.Net.WebSockets.ManagedWebSocket.ReceiveAsyncPrivate[TWebSocketReceiveResultGetter,TWebSocketReceiveResult](Memory`1 payloadBuffer, CancellationToken cancellationToken, TWebSocketReceiveResultGetter resultGetter)
   at Microsoft.Azure.Devices.Edge.Hub.Mqtt.ServerWebSocketChannel.DoReadBytes(IByteBuffer byteBuffer) in /opt/vsts/work/1/s/edge-hub/src/Microsoft.Azure.Devices.Edge.Hub.Mqtt/ServerWebSocketChannel.cs:line 243
   at Microsoft.Azure.Devices.Edge.Hub.Mqtt.ServerWebSocketChannel.DoBeginRead() in /opt/vsts/work/1/s/edge-hub/src/Microsoft.Azure.Devices.Edge.Hub.Mqtt/ServerWebSocketChannel.cs:line 154
2018-08-10 18:26:02.334 +00:00 [WRN] [Microsoft.Azure.Devices.Edge.Hub.Mqtt.ServerWebSocketChannel] - Error closing transport. CorrelationId 6d0f6739
System.Net.WebSockets.WebSocketException (0x80004005): The remote party closed the WebSocket connection without completing the close handshake. ---> System.Net.WebSockets.WebSocketException (0x80004005): An exception caused the WebSocket to enter the Aborted state. Please see the InnerException, if present, for more details.
   at System.Net.WebSockets.ManagedWebSocket.CloseWithReceiveErrorAndThrowAsync(WebSocketCloseStatus closeStatus, WebSocketError error, Exception innerException)
   at System.Net.WebSockets.ManagedWebSocket.HandleReceivedCloseAsync(MessageHeader header)
   at System.Net.WebSockets.ManagedWebSocket.ReceiveAsyncPrivate[TWebSocketReceiveResultGetter,TWebSocketReceiveResult](Memory`1 payloadBuffer, CancellationToken cancellationToken, TWebSocketReceiveResultGetter resultGetter)
   at System.Net.WebSockets.ManagedWebSocket.ReceiveAsyncPrivate[TWebSocketReceiveResultGetter,TWebSocketReceiveResult](Memory`1 payloadBuffer, CancellationToken cancellationToken, TWebSocketReceiveResultGetter resultGetter)
   at Microsoft.Azure.Devices.Edge.Hub.Mqtt.ServerWebSocketChannel.DoReadBytes(IByteBuffer byteBuffer) in /opt/vsts/work/1/s/edge-hub/src/Microsoft.Azure.Devices.Edge.Hub.Mqtt/ServerWebSocketChannel.cs:line 243
   at Microsoft.Azure.Devices.Edge.Hub.Mqtt.ServerWebSocketChannel.DoClose() in /opt/vsts/work/1/s/edge-hub/src/Microsoft.Azure.Devices.Edge.Hub.Mqtt/ServerWebSocketChannel.cs:line 120
2018-08-10 18:26:02.405 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Mqtt.ServerWebSocketChannel] - Transport aborted. CorrelationId 6d0f6739

ts4iot on 10 Aug 2018

When you create your ModuleClient instance, is it created with a connection string, or is it created from the environment using the HSM? The issue you are seeing in those logs suggests that there is something wrong with the sas token being sent to the edgehub.

And if you are providing the connection string manually, what is the format of that connection string?

timtay-microsoft on 10 Aug 2018

I create it with the connection string of the Scoring module from azure portal

ts4iot on 10 Aug 2018

Sorry this was my fault, the connectionstring of the module has changed in the meantime. Now the module connects to the edgeHub. Now I can test the reconnect. Can you please send an example how to get the connection information from HSM.

ts4iot on 10 Aug 2018

In order to use the HSM instead of a manual connection string, you construct your ModuleClient instance by calling ModuleClient.CreateFromEnvironment(). You should only do this for code that is deployed as an edge module, though, as that is the only time you will have the hsm.

timtay-microsoft on 10 Aug 2018

@timtay-microsoft - I've tested the reconnection behaviour of the master version. Unfortunately the behavior is the same as with version com.microsoft.azure.sdk.iot:iot-device-client:1.13.1.

Attached the log of the Scoring module with master version:

13:14:35.877 [pool-2-thread-3] INFO  com.tsystems.smartmon.process.FeatureGenerator - Waiting for Buckets.
13:14:36.742 [MQTT Rec: GW001/Scoring] INFO  com.tsystems.smartmon.source.MQTTSource - CONNECTION STATUS UPDATE: DISCONNECTED_RETRYING
13:14:36.744 [MQTT Rec: GW001/Scoring] INFO  com.tsystems.smartmon.source.MQTTSource - CONNECTION STATUS REASON: NO_NETWORK
13:14:36.744 [MQTT Rec: GW001/Scoring] INFO  com.tsystems.smartmon.source.MQTTSource - CONNECTION STATUS THROWABLE: Mqtt connection lost
com.microsoft.azure.sdk.iot.device.exceptions.ProtocolException: Mqtt connection lost
        at com.microsoft.azure.sdk.iot.device.transport.mqtt.exceptions.PahoExceptionTranslator.convertToMqttException(PahoExceptionTranslator.java:69)
        at com.microsoft.azure.sdk.iot.device.transport.mqtt.Mqtt.connectionLost(Mqtt.java:340)
        at org.eclipse.paho.client.mqttv3.internal.CommsCallback.connectionLost(CommsCallback.java:292)
        at org.eclipse.paho.client.mqttv3.internal.ClientComms.shutdownConnection(ClientComms.java:423)
        at org.eclipse.paho.client.mqttv3.internal.CommsReceiver.run(CommsReceiver.java:181)
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
        at java.util.concurrent.FutureTask.run(FutureTask.java:266)
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180)
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
        at java.lang.Thread.run(Thread.java:748)
Caused by: Connection lost (32109) - java.io.EOFException
        ... 8 more
Caused by: java.io.EOFException
        at java.io.DataInputStream.readByte(DataInputStream.java:267)
        at org.eclipse.paho.client.mqttv3.internal.wire.MqttInputStream.readMqttWireMessage(MqttInputStream.java:92)
        at org.eclipse.paho.client.mqttv3.internal.CommsReceiver.run(CommsReceiver.java:133)
        ... 7 more
13:14:36.878 [pool-2-thread-3] INFO  com.tsystems.smartmon.process.FeatureGenerator - Waiting for Buckets.
13:14:37.435 [MQTT Rec: GW001/Scoring] INFO  com.tsystems.smartmon.source.MQTTSource - CONNECTION STATUS UPDATE: DISCONNECTED
13:14:37.435 [MQTT Rec: GW001/Scoring] INFO  com.tsystems.smartmon.source.MQTTSource - CONNECTION STATUS REASON: BAD_CREDENTIAL
13:14:37.435 [MQTT Rec: GW001/Scoring] INFO  com.tsystems.smartmon.source.MQTTSource - CONNECTION STATUS THROWABLE: Unable to establish MQTT connection
com.microsoft.azure.sdk.iot.device.exceptions.ProtocolException: Unable to establish MQTT connection
        at com.microsoft.azure.sdk.iot.device.transport.mqtt.exceptions.PahoExceptionTranslator.convertToMqttException(PahoExceptionTranslator.java:41)
        at com.microsoft.azure.sdk.iot.device.transport.mqtt.Mqtt.connect(Mqtt.java:113)
        at com.microsoft.azure.sdk.iot.device.transport.mqtt.MqttMessaging.start(MqttMessaging.java:54)
        at com.microsoft.azure.sdk.iot.device.transport.mqtt.MqttIotHubConnection.open(MqttIotHubConnection.java:179)
        at com.microsoft.azure.sdk.iot.device.transport.IotHubTransport.openConnection(IotHubTransport.java:642)
        at com.microsoft.azure.sdk.iot.device.transport.IotHubTransport.singleReconnectAttempt(IotHubTransport.java:760)
        at com.microsoft.azure.sdk.iot.device.transport.IotHubTransport.reconnect(IotHubTransport.java:714)
        at com.microsoft.azure.sdk.iot.device.transport.IotHubTransport.handleDisconnection(IotHubTransport.java:672)
        at com.microsoft.azure.sdk.iot.device.transport.IotHubTransport.onConnectionLost(IotHubTransport.java:205)
        at com.microsoft.azure.sdk.iot.device.transport.mqtt.Mqtt.connectionLost(Mqtt.java:348)
        at org.eclipse.paho.client.mqttv3.internal.CommsCallback.connectionLost(CommsCallback.java:292)
        at org.eclipse.paho.client.mqttv3.internal.ClientComms.shutdownConnection(ClientComms.java:423)
        at org.eclipse.paho.client.mqttv3.internal.CommsReceiver.run(CommsReceiver.java:181)
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
        at java.util.concurrent.FutureTask.run(FutureTask.java:266)
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180)
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
        at java.lang.Thread.run(Thread.java:748)
Caused by: MqttException (0) - javax.net.ssl.SSLHandshakeException: Remote host closed connection during handshake
        at org.eclipse.paho.client.mqttv3.internal.ExceptionHelper.createMqttException(ExceptionHelper.java:38)
        at org.eclipse.paho.client.mqttv3.internal.ClientComms$ConnectBG.run(ClientComms.java:715)
        ... 7 more
Caused by: javax.net.ssl.SSLHandshakeException: Remote host closed connection during handshake
        at sun.security.ssl.SSLSocketImpl.readRecord(SSLSocketImpl.java:1002)
        at sun.security.ssl.SSLSocketImpl.performInitialHandshake(SSLSocketImpl.java:1385)
        at sun.security.ssl.SSLSocketImpl.startHandshake(SSLSocketImpl.java:1413)
        at sun.security.ssl.SSLSocketImpl.startHandshake(SSLSocketImpl.java:1397)
        at org.eclipse.paho.client.mqttv3.internal.SSLNetworkModule.start(SSLNetworkModule.java:108)
        at org.eclipse.paho.client.mqttv3.internal.websocket.WebSocketSecureNetworkModule.start(WebSocketSecureNetworkModule.java:61)
        at org.eclipse.paho.client.mqttv3.internal.ClientComms$ConnectBG.run(ClientComms.java:701)
        ... 7 more
Caused by: java.io.EOFException: SSL peer shut down incorrectly
        at sun.security.ssl.InputRecord.read(InputRecord.java:505)
        at sun.security.ssl.SSLSocketImpl.readRecord(SSLSocketImpl.java:983)
        ... 13 more
13:14:37.878 [pool-2-thread-3] INFO  com.tsystems.smartmon.process.FeatureGenerator - Waiting for Buckets.

ts4iot on 13 Aug 2018

This looks different from before. In that stacktrace, it is saying that the edgehub is rejecting your connection during the ssl handshake. Do you have any edgehub logs from this?

timtay-microsoft on 13 Aug 2018

To produce this error I force the edgehub to restart with the following command "iotedge restart edgeHub". Attached the log from the restart of the edgehub:

edgeHub:

2018-08-14 06:14:45.856 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Getting next batch for endpoint GW001/Scoring/input1 starting from 14196 with batch size 10.
2018-08-14 06:14:45.858 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Obtained next batch for endpoint GW001/Scoring/input1 with batch size 1. Next start offset = 14197.
2018-08-14 06:14:45.859 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.ModuleEndpoint] - Sending 1 message(s) to module GW001/Scoring.
2018-08-14 06:14:45.859 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Device.DeviceMessageHandler] - Sent message with correlation ID 045ef4a3-3c77-4e54-86b1-ee6c7ebee585 to GW001/Scoring
2018-08-14 06:14:45.897 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Device.DeviceMessageHandler] - Received feedback Complete for message 045ef4a3-3c77-4e54-86b1-ee6c7ebee585 from device/module GW001/Scoring
2018-08-14 06:14:45.898 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Getting next batch for endpoint GW001/Scoring/input1 starting from 14197 with batch size 10.
2018-08-14 06:14:45.899 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Obtained next batch for endpoint GW001/Scoring/input1 with batch size 0. Next start offset = 14197.
2018-08-14 06:14:46.023 +00:00 [DBG] [Microsoft.AspNetCore.Server.Kestrel] - Some connections failed to close gracefully during server shutdown.
2018-08-14 06:14:46.060 +00:00 [DBG] [Microsoft.AspNetCore.Server.Kestrel] - Connection id ""0HLG1LK0M3RJO"" disconnecting.
2018-08-14 06:14:46.076 +00:00 [DBG] [Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets] - Connection id ""0HLG1LK0M3RJO"" sending FIN.
2018-08-14 06:14:46.215 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Http.HttpProtocolHead] - Closed HTTP head
2018-08-14 06:14:46.233 +00:00 [WRN] [Microsoft.Azure.Devices.Edge.Hub.Mqtt.ServerWebSocketChannel] - Error reading transport. CorrelationId 31105d0a
System.Net.WebSockets.WebSocketException (0x80004005): The remote party closed the WebSocket connection without completing the close handshake. ---> System.IO.IOException: The read operation failed, see inner exception. ---> Microsoft.AspNetCore.Connections.ConnectionAbortedException: The connection was aborted
   at System.IO.Pipelines.PipeCompletion.ThrowLatchedException()
   at System.IO.Pipelines.Pipe.GetReadResult(ReadResult& result)
   at System.IO.Pipelines.Pipe.GetReadAsyncResult()
   at System.IO.Pipelines.Pipe.DefaultPipeReader.GetResult(Int16 token)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Adapter.Internal.RawStream.ReadAsyncInternal(Memory`1 destination)
   at System.Net.Security.SslStreamInternal.<FillBufferAsync>g__InternalFillBufferAsync|38_0[TReadAdapter](TReadAdapter adap, ValueTask`1 task, Int32 min, Int32 initial)
   at System.Net.Security.SslStreamInternal.ReadAsyncInternal[TReadAdapter](TReadAdapter adapter, Memory`1 buffer)
   --- End of inner exception stack trace ---
   at System.Net.Security.SslStreamInternal.ReadAsyncInternal[TReadAdapter](TReadAdapter adapter, Memory`1 buffer)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Adapter.Internal.AdaptedPipeline.ReadInputAsync(Stream stream)
   at System.IO.Pipelines.PipeCompletion.ThrowLatchedException()
   at System.IO.Pipelines.Pipe.GetReadResult(ReadResult& result)
   at System.IO.Pipelines.Pipe.GetReadAsyncResult()
   at System.IO.Pipelines.Pipe.DefaultPipeReader.GetResult(Int16 token)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.Http1MessageBody.PumpAsync()
   at System.IO.Pipelines.PipeCompletion.ThrowLatchedException()
   at System.IO.Pipelines.Pipe.GetReadResult(ReadResult& result)
   at System.IO.Pipelines.Pipe.GetReadAsyncResult()
   at System.IO.Pipelines.Pipe.DefaultPipeReader.GetResult(Int16 token)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.MessageBody.ReadAsync(Memory`1 buffer, CancellationToken cancellationToken)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.HttpRequestStream.ReadAsyncInternal(Memory`1 buffer, CancellationToken cancellationToken)
   at System.Net.WebSockets.ManagedWebSocket.EnsureBufferContainsAsync(Int32 minimumRequiredBytes, Boolean throwOnPrematureClosure)
   at System.Net.WebSockets.ManagedWebSocket.ReceiveAsyncPrivate[TWebSocketReceiveResultGetter,TWebSocketReceiveResult](Memory`1 payloadBuffer, CancellationToken cancellationToken, TWebSocketReceiveResultGetter resultGetter)
   at System.Net.WebSockets.ManagedWebSocket.ReceiveAsyncPrivate[TWebSocketReceiveResultGetter,TWebSocketReceiveResult](Memory`1 payloadBuffer, CancellationToken cancellationToken, TWebSocketReceiveResultGetter resultGetter)
   at Microsoft.Azure.Devices.Edge.Hub.Mqtt.ServerWebSocketChannel.DoReadBytes(IByteBuffer byteBuffer) in /opt/vsts/work/1/s/edge-hub/src/Microsoft.Azure.Devices.Edge.Hub.Mqtt/ServerWebSocketChannel.cs:line 243
   at Microsoft.Azure.Devices.Edge.Hub.Mqtt.ServerWebSocketChannel.DoBeginRead() in /opt/vsts/work/1/s/edge-hub/src/Microsoft.Azure.Devices.Edge.Hub.Mqtt/ServerWebSocketChannel.cs:line 154
2018-08-14 06:14:46.416 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Mqtt.ServerWebSocketChannel] - Transport aborted. CorrelationId 31105d0a
2018-08-14 06:14:46.442 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Http.Middleware.WebSocketHandlingMiddleware] - Request 0HLG1LK0M3RJO:00000001 completed. CorrelationId 6c99e9b3-802d-43fc-ba43-9e7158b577c0
2018-08-14 06:14:47.079 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Mqtt.MessagingServiceClient] - Sending message for device Id Sensor1
2018-08-14 06:14:47.089 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.RoutingEdgeHub] - Received message from Sensor1
2018-08-14 06:14:47.101 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Mqtt.MessagingServiceClient] - Sending message for device Id Sensor1
2018-08-14 06:14:47.102 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.RoutingEdgeHub] - Received message from Sensor1
2018-08-14 06:14:47.105 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Getting next batch for endpoint GW001/Scoring/input1 starting from 14197 with batch size 10.
2018-08-14 06:14:47.107 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Obtained next batch for endpoint GW001/Scoring/input1 with batch size 1. Next start offset = 14198.
2018-08-14 06:14:47.108 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.ModuleEndpoint] - Sending 1 message(s) to module GW001/Scoring.
2018-08-14 06:14:47.109 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Device.DeviceMessageHandler] - Sent message with correlation ID df16a588-facb-4795-9661-6c0c0ab1ee1d to GW001/Scoring
2018-08-14 06:14:47.131 +00:00 [INF] [Microsoft.AspNetCore.Hosting.Internal.WebHost] - Request finished in 95934.1676ms 101
2018-08-14 06:14:47.141 +00:00 [WRN] [ProtocolGateway] - Closing connection for device: GW001/Scoring, scope: ExceptionCaught, System.Net.WebSockets.WebSocketException (0x80004005): The remote party closed the WebSocket connection without completing the close handshake. ---> System.IO.IOException: The read operation failed, see inner exception. ---> Microsoft.AspNetCore.Connections.ConnectionAbortedException: The connection was aborted
   at System.IO.Pipelines.PipeCompletion.ThrowLatchedException()
   at System.IO.Pipelines.Pipe.GetReadResult(ReadResult& result)
   at System.IO.Pipelines.Pipe.GetReadAsyncResult()
   at System.IO.Pipelines.Pipe.DefaultPipeReader.GetResult(Int16 token)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Adapter.Internal.RawStream.ReadAsyncInternal(Memory`1 destination)
   at System.Net.Security.SslStreamInternal.<FillBufferAsync>g__InternalFillBufferAsync|38_0[TReadAdapter](TReadAdapter adap, ValueTask`1 task, Int32 min, Int32 initial)
   at System.Net.Security.SslStreamInternal.ReadAsyncInternal[TReadAdapter](TReadAdapter adapter, Memory`1 buffer)
   --- End of inner exception stack trace ---
   at System.Net.Security.SslStreamInternal.ReadAsyncInternal[TReadAdapter](TReadAdapter adapter, Memory`1 buffer)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Adapter.Internal.AdaptedPipeline.ReadInputAsync(Stream stream)
   at System.IO.Pipelines.PipeCompletion.ThrowLatchedException()
   at System.IO.Pipelines.Pipe.GetReadResult(ReadResult& result)
   at System.IO.Pipelines.Pipe.GetReadAsyncResult()
   at System.IO.Pipelines.Pipe.DefaultPipeReader.GetResult(Int16 token)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.Http1MessageBody.PumpAsync()
   at System.IO.Pipelines.PipeCompletion.ThrowLatchedException()
   at System.IO.Pipelines.Pipe.GetReadResult(ReadResult& result)
   at System.IO.Pipelines.Pipe.GetReadAsyncResult()
   at System.IO.Pipelines.Pipe.DefaultPipeReader.GetResult(Int16 token)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.MessageBody.ReadAsync(Memory`1 buffer, CancellationToken cancellationToken)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.HttpRequestStream.ReadAsyncInternal(Memory`1 buffer, CancellationToken cancellationToken)
   at System.Net.WebSockets.ManagedWebSocket.EnsureBufferContainsAsync(Int32 minimumRequiredBytes, Boolean throwOnPrematureClosure)
   at System.Net.WebSockets.ManagedWebSocket.ReceiveAsyncPrivate[TWebSocketReceiveResultGetter,TWebSocketReceiveResult](Memory`1 payloadBuffer, CancellationToken cancellationToken, TWebSocketReceiveResultGetter resultGetter)
   at System.Net.WebSockets.ManagedWebSocket.ReceiveAsyncPrivate[TWebSocketReceiveResultGetter,TWebSocketReceiveResult](Memory`1 payloadBuffer, CancellationToken cancellationToken, TWebSocketReceiveResultGetter resultGetter)
   at Microsoft.Azure.Devices.Edge.Hub.Mqtt.ServerWebSocketChannel.DoReadBytes(IByteBuffer byteBuffer) in /opt/vsts/work/1/s/edge-hub/src/Microsoft.Azure.Devices.Edge.Hub.Mqtt/ServerWebSocketChannel.cs:line 243
   at Microsoft.Azure.Devices.Edge.Hub.Mqtt.ServerWebSocketChannel.DoBeginRead() in /opt/vsts/work/1/s/edge-hub/src/Microsoft.Azure.Devices.Edge.Hub.Mqtt/ServerWebSocketChannel.cs:line 154, 31105d0a
2018-08-14 06:14:47.166 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Mqtt.MessagingServiceClient] - Disposing MessagingServiceClient for device Id GW001/Scoring because of exception - System.Net.WebSockets.WebSocketException (0x80004005): The remote party closed the WebSocket connection without completing the close handshake. ---> System.IO.IOException: The read operation failed, see inner exception. ---> Microsoft.AspNetCore.Connections.ConnectionAbortedException: The connection was aborted
   at System.IO.Pipelines.PipeCompletion.ThrowLatchedException()
   at System.IO.Pipelines.Pipe.GetReadResult(ReadResult& result)
   at System.IO.Pipelines.Pipe.GetReadAsyncResult()
   at System.IO.Pipelines.Pipe.DefaultPipeReader.GetResult(Int16 token)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Adapter.Internal.RawStream.ReadAsyncInternal(Memory`1 destination)
   at System.Net.Security.SslStreamInternal.<FillBufferAsync>g__InternalFillBufferAsync|38_0[TReadAdapter](TReadAdapter adap, ValueTask`1 task, Int32 min, Int32 initial)
   at System.Net.Security.SslStreamInternal.ReadAsyncInternal[TReadAdapter](TReadAdapter adapter, Memory`1 buffer)
   --- End of inner exception stack trace ---
   at System.Net.Security.SslStreamInternal.ReadAsyncInternal[TReadAdapter](TReadAdapter adapter, Memory`1 buffer)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Adapter.Internal.AdaptedPipeline.ReadInputAsync(Stream stream)
   at System.IO.Pipelines.PipeCompletion.ThrowLatchedException()
   at System.IO.Pipelines.Pipe.GetReadResult(ReadResult& result)
   at System.IO.Pipelines.Pipe.GetReadAsyncResult()
   at System.IO.Pipelines.Pipe.DefaultPipeReader.GetResult(Int16 token)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.Http1MessageBody.PumpAsync()
   at System.IO.Pipelines.PipeCompletion.ThrowLatchedException()
   at System.IO.Pipelines.Pipe.GetReadResult(ReadResult& result)
   at System.IO.Pipelines.Pipe.GetReadAsyncResult()
   at System.IO.Pipelines.Pipe.DefaultPipeReader.GetResult(Int16 token)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.MessageBody.ReadAsync(Memory`1 buffer, CancellationToken cancellationToken)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.HttpRequestStream.ReadAsyncInternal(Memory`1 buffer, CancellationToken cancellationToken)
   at System.Net.WebSockets.ManagedWebSocket.EnsureBufferContainsAsync(Int32 minimumRequiredBytes, Boolean throwOnPrematureClosure)
   at System.Net.WebSockets.ManagedWebSocket.ReceiveAsyncPrivate[TWebSocketReceiveResultGetter,TWebSocketReceiveResult](Memory`1 payloadBuffer, CancellationToken cancellationToken, TWebSocketReceiveResultGetter resultGetter)
   at System.Net.WebSockets.ManagedWebSocket.ReceiveAsyncPrivate[TWebSocketReceiveResultGetter,TWebSocketReceiveResult](Memory`1 payloadBuffer, CancellationToken cancellationToken, TWebSocketReceiveResultGetter resultGetter)
   at Microsoft.Azure.Devices.Edge.Hub.Mqtt.ServerWebSocketChannel.DoReadBytes(IByteBuffer byteBuffer) in /opt/vsts/work/1/s/edge-hub/src/Microsoft.Azure.Devices.Edge.Hub.Mqtt/ServerWebSocketChannel.cs:line 243
   at Microsoft.Azure.Devices.Edge.Hub.Mqtt.ServerWebSocketChannel.DoBeginRead() in /opt/vsts/work/1/s/edge-hub/src/Microsoft.Azure.Devices.Edge.Hub.Mqtt/ServerWebSocketChannel.cs:line 154
2018-08-14 06:14:47.201 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Mqtt.DeviceProxy] - Setting device proxy inactive for device Id GW001/Scoring
2018-08-14 06:14:47.223 +00:00 [WRN] [Microsoft.AspNetCore.Server.Kestrel] - Connection shutdown abnormally.
System.ObjectDisposedException: Cannot access a disposed object.
Object name: 'MemoryPoolBlock'.
   at System.Buffers.ThrowHelper.ThrowObjectDisposedException(ExceptionArgument argument)
   at System.Buffers.MemoryPoolBlock.Dispose()
   at System.IO.Pipelines.BufferSegment.ResetMemory()
   at System.IO.Pipelines.Pipe.CompletePipe()
   at System.IO.Pipelines.Pipe.CompleteReader(Exception exception)
   at System.IO.Pipelines.Pipe.DefaultPipeReader.Complete(Exception exception)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.Http1Connection.OnRequestProcessingEnding()
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.HttpProtocol.ProcessRequestsAsync[TContext](IHttpApplication`1 application)
2018-08-14 06:14:47.242 +00:00 [FTL] [Microsoft.AspNetCore.Server.Kestrel] - Unexpected exception in HttpConnection.ProcessRequestsAsync.
System.ObjectDisposedException: Cannot access a disposed object.
Object name: 'MemoryPoolBlock'.
   at System.Buffers.ThrowHelper.ThrowObjectDisposedException(ExceptionArgument argument)
   at System.Buffers.MemoryPoolBlock.Dispose()
   at System.IO.Pipelines.BufferSegment.ResetMemory()
   at System.IO.Pipelines.Pipe.CompletePipe()
   at System.IO.Pipelines.Pipe.CompleteReader(Exception exception)
   at System.IO.Pipelines.Pipe.DefaultPipeReader.Complete(Exception exception)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Adapter.Internal.AdaptedPipeline.ReadInputAsync(Stream stream)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Adapter.Internal.AdaptedPipeline.RunAsync(Stream stream)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.HttpConnection.ProcessRequestsAsync[TContext](IHttpApplication`1 httpApplication)
2018-08-14 06:14:47.264 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudProxy] - Closing receiver for device GW001/Scoring
2018-08-14 06:14:47.289 +00:00 [DBG] [Microsoft.AspNetCore.Server.Kestrel] - Connection id ""0HLG1LK0M3RJO"" stopped.
2018-08-14 06:14:47.318 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Mqtt.MessagingServiceClient] - Sending message for device Id Sensor1
2018-08-14 06:14:47.319 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.RoutingEdgeHub] - Received message from Sensor1
2018-08-14 06:14:47.623 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ConnectivityAwareClient] - Received connection status changed callback with connection status Disabled and reason Client_Close
2018-08-14 06:14:47.635 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudProxy] - Closed cloud proxy for device GW001/Scoring
2018-08-14 06:14:47.639 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Core.ConnectionManager] - Device connection removed for device GW001/Scoring
2018-08-14 06:14:47.652 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.EdgeHubConnection] - Updating device GW001/Scoring connection status to Disconnected
2018-08-14 06:14:47.668 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Core.Device.DeviceMessageHandler] - Remove device connection for device GW001/Scoring
2018-08-14 06:14:47.691 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Mqtt.ServerWebSocketChannel] - Transport closed. CorrelationId 31105d0a
2018-08-14 06:14:47.714 +00:00 [WRN] [DotNetty.Common.Utilities.ReferenceCountUtil] - Failed to release a message: PublishPacket[Type=PUBLISH, QualityOfService=AtLeastOnce, Duplicate=False, Retain=False]
DotNetty.Buffers.IllegalReferenceCountException: refCnt: 0, decrement: 1
   at DotNetty.Buffers.AbstractReferenceCountedByteBuffer.Release0(Int32 decrement)
   at DotNetty.Buffers.AbstractReferenceCountedByteBuffer.Release()
   at DotNetty.Codecs.Mqtt.Packets.PublishPacket.Release()
   at DotNetty.Common.Utilities.ReferenceCountUtil.SafeRelease(IReferenceCounted msg)
2018-08-14 06:14:47.809 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Mqtt.MessagingServiceClient] - Sending message for device Id Sensor1
2018-08-14 06:14:47.809 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.RoutingEdgeHub] - Received message from Sensor1
2018-08-14 06:14:47.842 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.DeviceConnectivityManager] - IotHub call succeeded
2018-08-14 06:14:47.843 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ConnectivityAwareClient] - Operation UpdateReportedPropertiesAsync succeeded
2018-08-14 06:14:47.843 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudProxy] - Updating reported properties for device GW001/$edgeHub
2018-08-14 06:14:47.843 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.TwinManager] - Successfully sent reported properties to cloud for GW001/$edgeHub and reported properties version 0
2018-08-14 06:14:47.846 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.TwinManager] - Updated cached reported property for GW001/$edgeHub at reported property version 3457 cloudVerified True
2018-08-14 06:14:48.323 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Mqtt.MessagingServiceClient] - Sending message for device Id Sensor1
2018-08-14 06:14:48.324 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.RoutingEdgeHub] - Received message from Sensor1
2018-08-14 06:14:49.003 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Mqtt.MessagingServiceClient] - Sending message for device Id Sensor1
2018-08-14 06:14:49.005 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.RoutingEdgeHub] - Received message from Sensor1
2018-08-14 06:14:49.326 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Mqtt.MessagingServiceClient] - Sending message for device Id Sensor1
2018-08-14 06:14:49.326 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.RoutingEdgeHub] - Received message from Sensor1
2018-08-14 06:14:49.844 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Mqtt.MessagingServiceClient] - Sending message for device Id Sensor1
2018-08-14 06:14:49.844 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.RoutingEdgeHub] - Received message from Sensor1
2018-08-14 06:14:50.366 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Mqtt.MessagingServiceClient] - Sending message for device Id Sensor1
2018-08-14 06:14:50.366 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.RoutingEdgeHub] - Received message from Sensor1
2018-08-14 06:14:50.981 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Mqtt.MessagingServiceClient] - Sending message for device Id Sensor1
2018-08-14 06:14:50.982 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.RoutingEdgeHub] - Received message from Sensor1
[2018-08-14 06:14:54 +00:00]: Starting Edge Hub
[08/14/2018 06:14:55.113 AM] Edge Hub Main()
2018-08-14 06:14:56.468 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Edged.WorkloadClient] - Making a Http call to unix:///var/run/iotedge/workload.sock to CreateServerCertificateAsync
2018-08-14 06:14:57.876 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Connecting socket /var/run/iotedge/workload.sock
2018-08-14 06:14:57.899 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Connected socket /var/run/iotedge/workload.sock
2018-08-14 06:14:57.932 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Sending request http://workload.sock/modules/%24edgeHub/genid/636662374498110148/certificate/server?api-version=2018-06-28
2018-08-14 06:14:58.238 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler] - Response received Created
2018-08-14 06:14:58.660 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Util.Edged.WorkloadClient] - Received a valid Http response from unix:///var/run/iotedge/workload.sock for CreateServerCertificateAsync
2018-08-14 06:15:02.932 +00:00 [INF] [EdgeHub] - Starting Edge Hub
2018-08-14 06:15:02.948 +00:00 [INF] [EdgeHub] - Version - 1.0.0.14487025 (52ef77db24126bf473265fc09c53d35290a2dd6b)
2018-08-14 06:15:02.950 +00:00 [INF] [EdgeHub] -
        █████╗ ███████╗██╗   ██╗██████╗ ███████╗
       ██╔══██╗╚══███╔╝██║   ██║██╔══██╗██╔════╝
       ███████║  ███╔╝ ██║   ██║██████╔╝█████╗
       ██╔══██║ ███╔╝  ██║   ██║██╔══██╗██╔══╝
       ██║  ██║███████╗╚██████╔╝██║  ██║███████╗
       ╚═╝  ╚═╝╚══════╝ ╚═════╝ ╚═╝  ╚═╝╚══════╝

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

2018-08-14 06:15:02.950 +00:00 [INF] [EdgeHub] - Installing intermediate certificates.
2018-08-14 06:15:03.232 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.DeviceConnectivityManager] - Created DeviceConnectivityManager with connected check frequency 00:05:00 and disconnected check frequency 00:02:00
2018-08-14 06:15:03.521 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudConnection] - Attempting to connect to IoT Hub for client GW001/$edgeHub via AMQP...
2018-08-14 06:15:03.871 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudConnection] - Connected to IoT Hub for client GW001/$edgeHub via AMQP, with client operation timeout 60000.
2018-08-14 06:15:03.910 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudConnection] - Updated cloud connection for client GW001/$edgeHub
2018-08-14 06:15:03.914 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudConnection] - Created cloud connection for client GW001/$edgeHub
2018-08-14 06:15:03.921 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Core.ConnectionManager] - New cloud connection created for device GW001/$edgeHub
2018-08-14 06:15:03.961 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.DeviceConnectivityManager] - CloudProxy to test device connectivity set
2018-08-14 06:15:03.962 +00:00 [INF] [EdgeHub] - Initializing configuration
2018-08-14 06:15:06.816 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Service.Modules.RoutingModule] - Created persistent store at /tmp/edgeHub
2018-08-14 06:15:06.964 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Created new message store
2018-08-14 06:15:06.967 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Started task to cleanup processed and stale messages
2018-08-14 06:15:07.269 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudProxy] - Binding cloud listener for device GW001/$edgeHub
2018-08-14 06:15:07.307 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Core.ConnectionManager] - New device connection for device GW001/$edgeHub
2018-08-14 06:15:07.327 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.RoutingEdgeHub] - Adding subscription DesiredPropertyUpdates for client GW001/$edgeHub.
2018-08-14 06:15:11.948 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ConnectivityAwareClient] - Received connection status changed callback with connection status Connected and reason Connection_Ok
2018-08-14 06:15:12.797 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.DeviceConnectivityManager] - IotHub call succeeded
2018-08-14 06:15:12.869 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.DeviceConnectivityManager] - Entering connected state
2018-08-14 06:15:12.887 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.TwinManager] - ConnectionEstablished for GW001/$edgeHub
2018-08-14 06:15:12.926 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.TwinManager] - Processing ConnectionEstablished for device GW001/$edgeHub
2018-08-14 06:15:12.984 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ConnectivityAwareClient] - Operation UpdateReportedPropertiesAsync succeeded
2018-08-14 06:15:12.992 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudProxy] - Updating reported properties for device GW001/$edgeHub
2018-08-14 06:15:13.000 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.TwinManager] - Successfully sent reported properties to cloud for GW001/$edgeHub and reported properties version 0
2018-08-14 06:15:13.240 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.TwinManager] - Updated cached reported property for GW001/$edgeHub at reported property version 3457 cloudVerified True
2018-08-14 06:15:13.284 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.EdgeHubConnection] - Established IoT Hub connection for edge hub GW001/$edgeHub
2018-08-14 06:15:13.333 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.TwinManager] - Getting twin for GW001/$edgeHub on ConnectionEstablished
2018-08-14 06:15:13.662 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.DeviceConnectivityManager] - IotHub call succeeded
2018-08-14 06:15:13.672 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ConnectivityAwareClient] - Operation GetTwinAsync succeeded
2018-08-14 06:15:13.681 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudProxy] - Getting twin for device GW001/$edgeHub
2018-08-14 06:15:13.709 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.TwinManager] - Successfully got twin for GW001/$edgeHub from cloud at desired version 357 reported version 3462
2018-08-14 06:15:13.778 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.TwinManager] - Updating cached twin for GW001/$edgeHub from desired version 357 to 357 and reported version 3457 to 3462
2018-08-14 06:15:13.790 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.TwinManager] - Sending desired property update for GW001/$edgeHub old desired version 357 cloud desired version 357
2018-08-14 06:15:13.840 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.DeviceConnectivityManager] - IotHub call succeeded
2018-08-14 06:15:13.841 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ConnectivityAwareClient] - Operation GetTwinAsync succeeded
2018-08-14 06:15:13.841 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudProxy] - Getting twin for device GW001/$edgeHub
2018-08-14 06:15:13.842 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.TwinManager] - Successfully got twin for GW001/$edgeHub from cloud at desired version 357 reported version 3462
2018-08-14 06:15:13.848 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.TwinManager] - Local twin for GW001/$edgeHub at higher or equal desired version 357 compared to cloud 357 or reported version 3462 compared to cloud 3462
2018-08-14 06:15:15.118 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.DeviceConnectivityManager] - IotHub call succeeded
2018-08-14 06:15:15.118 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ConnectivityAwareClient] - Operation UpdateReportedPropertiesAsync succeeded
2018-08-14 06:15:15.119 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudProxy] - Updating reported properties for device GW001/$edgeHub
2018-08-14 06:15:15.119 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.TwinManager] - Successfully sent reported properties to cloud for GW001/$edgeHub and reported properties version 0
2018-08-14 06:15:15.123 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.TwinManager] - Updated cached reported property for GW001/$edgeHub at reported property version 3462 cloudVerified True
2018-08-14 06:15:15.126 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Core.EdgeHubConnection] - Obtained edge hub config from module twin
2018-08-14 06:15:15.822 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Added sequential store for endpoint iothub
2018-08-14 06:15:15.897 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Added sequential store for endpoint GW001/Scoring/input1
2018-08-14 06:15:15.913 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Core.Config.ConfigUpdater] - Set the following 2 route(s) in edge hub
2018-08-14 06:15:15.920 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Core.Config.ConfigUpdater] - route_1: FROM /* INTO $upstream
2018-08-14 06:15:15.921 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Core.Config.ConfigUpdater] - route_2: FROM /messages/* INTO BrokeredEndpoint("/modules/Scoring/inputs/input1")
2018-08-14 06:15:15.923 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Getting next batch for endpoint GW001/Scoring/input1 starting from 14197 with batch size 10.
2018-08-14 06:15:15.923 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Getting next batch for endpoint iothub starting from 0 with batch size 10.
2018-08-14 06:15:15.928 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Updated message store TTL to 7200 seconds
2018-08-14 06:15:15.931 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Core.Config.ConfigUpdater] - Updated the edge hub store and forward configuration
2018-08-14 06:15:15.933 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Core.Config.ConfigUpdater] - Initialized edge hub configuration
2018-08-14 06:15:15.959 +00:00 [DBG] [EdgeHub] - Waiting on shutdown handler to trigger
2018-08-14 06:15:16.039 +00:00 [WRN] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Unable to find message with EdgeMessageId 7dfcd5e1-62bd-423c-ba97-7af59cd6e778
2018-08-14 06:15:16.122 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Obtained next batch for endpoint GW001/Scoring/input1 with batch size 9. Next start offset = 14206.
2018-08-14 06:15:16.122 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Obtained next batch for endpoint iothub with batch size 9. Next start offset = 12401.
2018-08-14 06:15:16.385 +00:00 [INF] [EdgeHub] - Starting protocol heads - (HTTP, MQTT, AMQP)
2018-08-14 06:15:16.389 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.CloudEndpoint] - Sending 9 message(s) upstream.
2018-08-14 06:15:16.397 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.ModuleEndpoint] - Sending 9 message(s) to module GW001/Scoring.
2018-08-14 06:15:16.404 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Http.HttpProtocolHead] - Starting HTTP head
2018-08-14 06:15:16.425 +00:00 [ERR] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.CloudEndpoint] - Received message does not contain a device Id
2018-08-14 06:15:16.432 +00:00 [ERR] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.ModuleEndpoint] - Module GW001/Scoring is not connected
2018-08-14 06:15:16.438 +00:00 [ERR] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.CloudEndpoint] - Received message does not contain a device Id
2018-08-14 06:15:16.439 +00:00 [ERR] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.CloudEndpoint] - Received message does not contain a device Id
2018-08-14 06:15:16.440 +00:00 [ERR] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.CloudEndpoint] - Received message does not contain a device Id
2018-08-14 06:15:16.440 +00:00 [ERR] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.CloudEndpoint] - Received message does not contain a device Id
2018-08-14 06:15:16.441 +00:00 [ERR] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.CloudEndpoint] - Received message does not contain a device Id
2018-08-14 06:15:16.442 +00:00 [ERR] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.CloudEndpoint] - Received message does not contain a device Id
2018-08-14 06:15:16.442 +00:00 [ERR] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.CloudEndpoint] - Received message does not contain a device Id
2018-08-14 06:15:16.443 +00:00 [ERR] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.CloudEndpoint] - Received message does not contain a device Id
2018-08-14 06:15:16.572 +00:00 [DBG] [Microsoft.AspNetCore.Hosting.Internal.WebHost] - Hosting starting
2018-08-14 06:15:17.045 +00:00 [INF] [Microsoft.AspNetCore.DataProtection.KeyManagement.XmlKeyManager] - User profile is available. Using '"/home/edgehubuser/.aspnet/DataProtection-Keys"' as key repository; keys will not be encrypted at rest.
2018-08-14 06:15:17.131 +00:00 [DBG] [Microsoft.AspNetCore.DataProtection.Repositories.FileSystemXmlRepository] - Reading data from file '"/home/edgehubuser/.aspnet/DataProtection-Keys/key-14fa3cdd-a763-412f-96f7-2e9aeff2e4a6.xml"'.
2018-08-14 06:15:17.200 +00:00 [DBG] [Microsoft.AspNetCore.DataProtection.KeyManagement.XmlKeyManager] - Found key {14fa3cdd-a763-412f-96f7-2e9aeff2e4a6}.
2018-08-14 06:15:17.298 +00:00 [DBG] [Microsoft.AspNetCore.DataProtection.KeyManagement.DefaultKeyResolver] - Considering key {14fa3cdd-a763-412f-96f7-2e9aeff2e4a6} with expiration date 2018-11-08 20:06:03Z as default key.
2018-08-14 06:15:17.393 +00:00 [DBG] [Microsoft.AspNetCore.DataProtection.TypeForwardingActivator] - Forwarded activator type request from "Microsoft.AspNetCore.DataProtection.AuthenticatedEncryption.ConfigurationModel.AuthenticatedEncryptorDescriptorDeserializer, Microsoft.AspNetCore.DataProtection, Version=2.1.1.0, Culture=neutral, PublicKeyToken=adb9793829ddae60" to "Microsoft.AspNetCore.DataProtection.AuthenticatedEncryption.ConfigurationModel.AuthenticatedEncryptorDescriptorDeserializer, Microsoft.AspNetCore.DataProtection, Culture=neutral, PublicKeyToken={token}"
2018-08-14 06:15:17.442 +00:00 [DBG] [Microsoft.AspNetCore.DataProtection.AuthenticatedEncryption.ManagedAuthenticatedEncryptorFactory] - Using managed symmetric algorithm '"System.Security.Cryptography.Aes"'.
2018-08-14 06:15:17.448 +00:00 [DBG] [Microsoft.AspNetCore.DataProtection.AuthenticatedEncryption.ManagedAuthenticatedEncryptorFactory] - Using managed keyed hash algorithm '"System.Security.Cryptography.HMACSHA256"'.
2018-08-14 06:15:17.532 +00:00 [DBG] [Microsoft.AspNetCore.DataProtection.KeyManagement.KeyRingProvider] - Using key {key} as the default key.
2018-08-14 06:15:17.538 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.ModuleEndpoint] - Sending 9 message(s) to module GW001/Scoring.
2018-08-14 06:15:17.539 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.CloudEndpoint] - Sending 9 message(s) upstream.
2018-08-14 06:15:17.540 +00:00 [ERR] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.CloudEndpoint] - Received message does not contain a device Id
2018-08-14 06:15:17.541 +00:00 [ERR] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.CloudEndpoint] - Received message does not contain a device Id
2018-08-14 06:15:17.541 +00:00 [ERR] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.CloudEndpoint] - Received message does not contain a device Id
2018-08-14 06:15:17.542 +00:00 [ERR] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.CloudEndpoint] - Received message does not contain a device Id
2018-08-14 06:15:17.543 +00:00 [ERR] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.CloudEndpoint] - Received message does not contain a device Id
2018-08-14 06:15:17.543 +00:00 [ERR] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.CloudEndpoint] - Received message does not contain a device Id
2018-08-14 06:15:17.544 +00:00 [ERR] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.CloudEndpoint] - Received message does not contain a device Id
2018-08-14 06:15:17.544 +00:00 [ERR] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.CloudEndpoint] - Received message does not contain a device Id
2018-08-14 06:15:17.545 +00:00 [ERR] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.CloudEndpoint] - Received message does not contain a device Id
2018-08-14 06:15:17.545 +00:00 [DBG] [Microsoft.AspNetCore.DataProtection.Internal.DataProtectionStartupFilter] - Key ring with default key {key} was loaded during application startup.
2018-08-14 06:15:17.547 +00:00 [ERR] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.ModuleEndpoint] - Module GW001/Scoring is not connected
2018-08-14 06:15:17.694 +00:00 [DBG] [Microsoft.AspNetCore.Mvc.MvcJsonOptions] - Compatibility switch "AllowInputFormatterExceptionMessages" in type "MvcJsonOptions" is using default value False
2018-08-14 06:15:17.903 +00:00 [DBG] [Microsoft.AspNetCore.Mvc.MvcOptions] - Compatibility switch "AllowCombiningAuthorizeFilters" in type "MvcOptions" is using default value False
2018-08-14 06:15:17.904 +00:00 [DBG] [Microsoft.AspNetCore.Mvc.MvcOptions] - Compatibility switch "AllowBindingHeaderValuesToNonStringModelTypes" in type "MvcOptions" is using default value False
2018-08-14 06:15:17.904 +00:00 [DBG] [Microsoft.AspNetCore.Mvc.MvcOptions] - Compatibility switch "AllowValidatingTopLevelNodes" in type "MvcOptions" is using default value False
2018-08-14 06:15:17.910 +00:00 [DBG] [Microsoft.AspNetCore.Mvc.MvcOptions] - Compatibility switch "InputFormatterExceptionPolicy" in type "MvcOptions" is using default value AllExceptions
2018-08-14 06:15:17.910 +00:00 [DBG] [Microsoft.AspNetCore.Mvc.MvcOptions] - Compatibility switch "SuppressBindingUndefinedValueToEnumType" in type "MvcOptions" is using default value False
2018-08-14 06:15:18.102 +00:00 [DBG] [Microsoft.AspNetCore.Mvc.RazorPages.RazorPagesOptions] - Compatibility switch "AllowAreas" in type "RazorPagesOptions" is using default value False
2018-08-14 06:15:18.102 +00:00 [DBG] [Microsoft.AspNetCore.Mvc.RazorPages.RazorPagesOptions] - Compatibility switch "AllowMappingHeadRequestsToGetHandler" in type "RazorPagesOptions" is using default value False
2018-08-14 06:15:18.528 +00:00 [DBG] [Microsoft.AspNetCore.Mvc.MvcViewOptions] - Compatibility switch "SuppressTempDataAttributePrefix" in type "MvcViewOptions" is using default value False
2018-08-14 06:15:18.871 +00:00 [DBG] [Microsoft.AspNetCore.Mvc.ModelBinding.ModelBinderFactory] - Registered model binder providers, in the following order: ["Microsoft.AspNetCore.Mvc.ModelBinding.Binders.BinderTypeModelBinderProvider", "Microsoft.AspNetCore.Mvc.ModelBinding.Binders.ServicesModelBinderProvider", "Microsoft.AspNetCore.Mvc.ModelBinding.Binders.BodyModelBinderProvider", "Microsoft.AspNetCore.Mvc.ModelBinding.Binders.HeaderModelBinderProvider", "Microsoft.AspNetCore.Mvc.ModelBinding.Binders.FloatingPointTypeModelBinderProvider", "Microsoft.AspNetCore.Mvc.ModelBinding.Binders.EnumTypeModelBinderProvider", "Microsoft.AspNetCore.Mvc.ModelBinding.Binders.SimpleTypeModelBinderProvider", "Microsoft.AspNetCore.Mvc.ModelBinding.Binders.CancellationTokenModelBinderProvider", "Microsoft.AspNetCore.Mvc.ModelBinding.Binders.ByteArrayModelBinderProvider", "Microsoft.AspNetCore.Mvc.ModelBinding.Binders.FormFileModelBinderProvider", "Microsoft.AspNetCore.Mvc.ModelBinding.Binders.FormCollectionModelBinderProvider", "Microsoft.AspNetCore.Mvc.ModelBinding.Binders.KeyValuePairModelBinderProvider", "Microsoft.AspNetCore.Mvc.ModelBinding.Binders.DictionaryModelBinderProvider", "Microsoft.AspNetCore.Mvc.ModelBinding.Binders.ArrayModelBinderProvider", "Microsoft.AspNetCore.Mvc.ModelBinding.Binders.CollectionModelBinderProvider", "Microsoft.AspNetCore.Mvc.ModelBinding.Binders.ComplexTypeModelBinderProvider"]
2018-08-14 06:15:19.286 +00:00 [WRN] [Microsoft.AspNetCore.Server.Kestrel] - Overriding address(es) '"http://+:80"'. Binding to endpoints defined in "UseKestrel()" instead.
2018-08-14 06:15:19.434 +00:00 [DBG] [Microsoft.AspNetCore.Hosting.Internal.WebHost] - Hosting started
2018-08-14 06:15:19.435 +00:00 [DBG] [Microsoft.AspNetCore.Hosting.Internal.WebHost] - Loaded hosting startup assembly "Microsoft.Azure.Devices.Edge.Hub.Service"
2018-08-14 06:15:19.437 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Http.HttpProtocolHead] - Started HTTP head
2018-08-14 06:15:19.464 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Mqtt.MqttProtocolHead] - Starting MQTT head
2018-08-14 06:15:19.719 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.CloudEndpoint] - Sending 9 message(s) upstream.
2018-08-14 06:15:19.720 +00:00 [ERR] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.CloudEndpoint] - Received message does not contain a device Id
2018-08-14 06:15:19.720 +00:00 [ERR] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.CloudEndpoint] - Received message does not contain a device Id
2018-08-14 06:15:19.721 +00:00 [ERR] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.CloudEndpoint] - Received message does not contain a device Id
2018-08-14 06:15:19.721 +00:00 [ERR] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.CloudEndpoint] - Received message does not contain a device Id
2018-08-14 06:15:19.721 +00:00 [ERR] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.CloudEndpoint] - Received message does not contain a device Id
2018-08-14 06:15:19.721 +00:00 [ERR] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.CloudEndpoint] - Received message does not contain a device Id
2018-08-14 06:15:19.722 +00:00 [ERR] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.CloudEndpoint] - Received message does not contain a device Id
2018-08-14 06:15:19.722 +00:00 [ERR] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.CloudEndpoint] - Received message does not contain a device Id
2018-08-14 06:15:19.722 +00:00 [ERR] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.CloudEndpoint] - Received message does not contain a device Id
2018-08-14 06:15:19.729 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.ModuleEndpoint] - Sending 9 message(s) to module GW001/Scoring.
2018-08-14 06:15:19.730 +00:00 [ERR] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.ModuleEndpoint] - Module GW001/Scoring is not connected
2018-08-14 06:15:20.333 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Mqtt.MqttProtocolHead] - Initializing TLS endpoint on port 8883 for MQTT head.
2018-08-14 06:15:20.455 +00:00 [DBG] [DotNetty.Transport.Channels.DefaultChannelId] - -Dio.netty.processId: 1863356 (auto-detected)
2018-08-14 06:15:20.521 +00:00 [DBG] [DotNetty.Transport.Channels.DefaultChannelId] - -Dio.netty.machineId: 02:42:AC:FF:FE:12:00:04 (auto-detected)
2018-08-14 06:15:20.545 +00:00 [DBG] [DotNetty.Buffers.PooledByteBufferAllocator] - -Dio.netty.allocator.numHeapArenas: 8
2018-08-14 06:15:20.545 +00:00 [DBG] [DotNetty.Buffers.PooledByteBufferAllocator] - -Dio.netty.allocator.pageSize: 8192
2018-08-14 06:15:20.545 +00:00 [DBG] [DotNetty.Buffers.PooledByteBufferAllocator] - -Dio.netty.allocator.maxOrder: 11
2018-08-14 06:15:20.546 +00:00 [DBG] [DotNetty.Buffers.PooledByteBufferAllocator] - -Dio.netty.allocator.chunkSize: 16777216
2018-08-14 06:15:20.546 +00:00 [DBG] [DotNetty.Buffers.PooledByteBufferAllocator] - -Dio.netty.allocator.tinyCacheSize: 512
2018-08-14 06:15:20.546 +00:00 [DBG] [DotNetty.Buffers.PooledByteBufferAllocator] - -Dio.netty.allocator.smallCacheSize: 256
2018-08-14 06:15:20.546 +00:00 [DBG] [DotNetty.Buffers.PooledByteBufferAllocator] - -Dio.netty.allocator.normalCacheSize: 64
2018-08-14 06:15:20.547 +00:00 [DBG] [DotNetty.Buffers.PooledByteBufferAllocator] - -Dio.netty.allocator.maxCachedBufferCapacity: 32768
2018-08-14 06:15:20.547 +00:00 [DBG] [DotNetty.Buffers.PooledByteBufferAllocator] - -Dio.netty.allocator.cacheTrimInterval: 8192
2018-08-14 06:15:20.587 +00:00 [DBG] [DotNetty.Buffers.ByteBufferUtil] - -Dio.netty.allocator.type: pooled
2018-08-14 06:15:20.610 +00:00 [DBG] [DotNetty.Common.ResourceLeakDetector] - io.netty.leakDetection.level: simple
2018-08-14 06:15:20.611 +00:00 [DBG] [DotNetty.Common.ResourceLeakDetector] - io.netty.leakDetection.maxRecords: 4
2018-08-14 06:15:20.800 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Amqp.AmqpProtocolHead] - Starting AMQP head
2018-08-14 06:15:20.845 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Mqtt.MqttProtocolHead] - Started MQTT head
2018-08-14 06:15:21.440 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Amqp.AmqpProtocolHead] - Started AMQP head
2018-08-14 06:15:23.829 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.CloudEndpoint] - Sending 9 message(s) upstream.
2018-08-14 06:15:23.829 +00:00 [ERR] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.CloudEndpoint] - Received message does not contain a device Id
2018-08-14 06:15:23.830 +00:00 [ERR] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.CloudEndpoint] - Received message does not contain a device Id
2018-08-14 06:15:23.830 +00:00 [ERR] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.CloudEndpoint] - Received message does not contain a device Id
2018-08-14 06:15:23.830 +00:00 [ERR] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.CloudEndpoint] - Received message does not contain a device Id
2018-08-14 06:15:23.831 +00:00 [ERR] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.CloudEndpoint] - Received message does not contain a device Id
2018-08-14 06:15:23.831 +00:00 [ERR] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.CloudEndpoint] - Received message does not contain a device Id
2018-08-14 06:15:23.831 +00:00 [ERR] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.CloudEndpoint] - Received message does not contain a device Id
2018-08-14 06:15:23.832 +00:00 [ERR] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.CloudEndpoint] - Received message does not contain a device Id
2018-08-14 06:15:23.832 +00:00 [ERR] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.CloudEndpoint] - Received message does not contain a device Id
2018-08-14 06:15:24.112 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.ModuleEndpoint] - Sending 9 message(s) to module GW001/Scoring.
2018-08-14 06:15:24.112 +00:00 [ERR] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.ModuleEndpoint] - Module GW001/Scoring is not connected
2018-08-14 06:15:25.598 +00:00 [DBG] [DotNetty.Buffers.AbstractByteBuffer] - -Dio.netty.buffer.bytebuf.checkAccessible: True
2018-08-14 06:15:26.195 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudConnection] - Attempting to connect to IoT Hub for client Sensor1 via AMQP...
2018-08-14 06:15:26.215 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudConnection] - Connected to IoT Hub for client Sensor1 via AMQP, with client operation timeout 60000.
2018-08-14 06:15:26.215 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.TwinManager] - ConnectionEstablished for Sensor1
2018-08-14 06:15:26.217 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.TwinManager] - Processing ConnectionEstablished for device Sensor1
2018-08-14 06:15:26.219 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudConnection] - Updated cloud connection for client Sensor1
2018-08-14 06:15:26.219 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudConnection] - Created cloud connection for client Sensor1
2018-08-14 06:15:26.220 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Core.ConnectionManager] - New cloud connection created for device Sensor1
2018-08-14 06:15:26.299 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudConnection] - Getting new token for Sensor1.
2018-08-14 06:15:26.330 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudConnection] - New token requested by client Sensor1, but using existing token as it is usable.
2018-08-14 06:15:26.596 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ConnectivityAwareClient] - Received connection status changed callback with connection status Connected and reason Connection_Ok
2018-08-14 06:15:26.755 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.DeviceConnectivityManager] - IotHub call succeeded
2018-08-14 06:15:26.755 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ConnectivityAwareClient] - Operation OpenAsync succeeded
2018-08-14 06:15:26.771 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.TokenCredentialsAuthenticator] - Authenticated Sensor1 with IotHub
2018-08-14 06:15:26.783 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Mqtt.DeviceIdentityProvider] - Successfully generated identity for clientId Sensor1 and username {Server}/Sensor1/?api-version=2018-06-30&DeviceClientType=com.microsoft.azure.sdk.iot.iot-device-client%2F1.13.1%20%280%3B%20Linux%3B%20armv7l%29
2018-08-14 06:15:26.803 +00:00 [INF] [ProtocolGateway] - ClientAuthenticated, Sensor1, 289e993a
2018-08-14 06:15:26.878 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.ConnectionManager] - Obtained cloud connection for device Sensor1
2018-08-14 06:15:27.092 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudProxy] - Binding cloud listener for device Sensor1
2018-08-14 06:15:27.093 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Core.ConnectionManager] - New device connection for device Sensor1
2018-08-14 06:15:27.110 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.EdgeHubConnection] - Updating device Sensor1 connection status to Connected
2018-08-14 06:15:27.151 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Core.Device.DeviceMessageHandler] - Bind device proxy for device Sensor1
2018-08-14 06:15:27.157 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Mqtt.MessagingServiceClient] - Binding message channel for device Id Sensor1
2018-08-14 06:15:27.273 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Mqtt.SessionStatePersistenceProvider] - Adding subscription devices/Sensor1/messages/devicebound/# for client Sensor1.
2018-08-14 06:15:27.276 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.RoutingEdgeHub] - Adding subscription C2D for client Sensor1.
2018-08-14 06:15:27.284 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudProxy] - Start listening for C2D messages for device Sensor1
2018-08-14 06:15:27.424 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Mqtt.SessionStateStoragePersistenceProvider] - Set subscriptions from session state for Sensor1
2018-08-14 06:15:27.814 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Mqtt.MessagingServiceClient] - Sending message for device Id Sensor1
2018-08-14 06:15:27.821 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.RoutingEdgeHub] - Received message from Sensor1
2018-08-14 06:15:28.102 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Mqtt.MessagingServiceClient] - Sending message for device Id Sensor1
2018-08-14 06:15:28.103 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.RoutingEdgeHub] - Received message from Sensor1
2018-08-14 06:15:28.107 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.DeviceConnectivityManager] - IotHub call succeeded
2018-08-14 06:15:28.107 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ConnectivityAwareClient] - Operation UpdateReportedPropertiesAsync succeeded
2018-08-14 06:15:28.108 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudProxy] - Updating reported properties for device GW001/$edgeHub
2018-08-14 06:15:28.108 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.TwinManager] - Successfully sent reported properties to cloud for GW001/$edgeHub and reported properties version 0
2018-08-14 06:15:28.109 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.TwinManager] - Updated cached reported property for GW001/$edgeHub at reported property version 3462 cloudVerified True
2018-08-14 06:15:28.117 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Mqtt.MessagingServiceClient] - Sending message for device Id Sensor1
2018-08-14 06:15:28.118 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.RoutingEdgeHub] - Received message from Sensor1
2018-08-14 06:15:28.122 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Mqtt.MessagingServiceClient] - Sending message for device Id Sensor1
2018-08-14 06:15:28.122 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.RoutingEdgeHub] - Received message from Sensor1
2018-08-14 06:15:28.125 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Mqtt.MessagingServiceClient] - Sending message for device Id Sensor1
2018-08-14 06:15:28.126 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.RoutingEdgeHub] - Received message from Sensor1
2018-08-14 06:15:28.130 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Mqtt.MessagingServiceClient] - Sending message for device Id Sensor1
2018-08-14 06:15:28.130 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.RoutingEdgeHub] - Received message from Sensor1

ScoringModule:

06:14:45.892 [pool-2-thread-2] INFO  com.tsystems.smartmon.process.BucketManager - #Buckets: 14
06:14:45.892 [pool-2-thread-2] INFO  com.tsystems.smartmon.process.BucketManager - #Buckets: 14
06:14:46.101 [MQTT Rec: GW001/Scoring] INFO  com.microsoft.azure.sdk.iot.device.transport.IotHubTransport - The messages in progress are buffered to be sent again due to a connection loss, method name is handleDisconnection
06:14:46.103 [MQTT Rec: GW001/Scoring] INFO  com.tsystems.smartmon.source.MQTTSource - CONNECTION STATUS UPDATE: DISCONNECTED_RETRYING
06:14:46.104 [MQTT Rec: GW001/Scoring] INFO  com.tsystems.smartmon.source.MQTTSource - CONNECTION STATUS REASON: NO_NETWORK
06:14:46.105 [MQTT Rec: GW001/Scoring] INFO  com.tsystems.smartmon.source.MQTTSource - CONNECTION STATUS THROWABLE: Mqtt connection lost
com.microsoft.azure.sdk.iot.device.exceptions.ProtocolException: Mqtt connection lost
        at com.microsoft.azure.sdk.iot.device.transport.mqtt.exceptions.PahoExceptionTranslator.convertToMqttException(PahoExceptionTranslator.java:75)
        at com.microsoft.azure.sdk.iot.device.transport.mqtt.Mqtt.connectionLost(Mqtt.java:346)
        at org.eclipse.paho.client.mqttv3.internal.CommsCallback.connectionLost(CommsCallback.java:292)
        at org.eclipse.paho.client.mqttv3.internal.ClientComms.shutdownConnection(ClientComms.java:423)
        at org.eclipse.paho.client.mqttv3.internal.CommsReceiver.run(CommsReceiver.java:181)
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
        at java.util.concurrent.FutureTask.run(FutureTask.java:266)
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180)
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
        at java.lang.Thread.run(Thread.java:748)
Caused by: Connection lost (32109) - java.io.EOFException
        ... 8 more
Caused by: java.io.EOFException
        at java.io.DataInputStream.readByte(DataInputStream.java:267)
        at org.eclipse.paho.client.mqttv3.internal.wire.MqttInputStream.readMqttWireMessage(MqttInputStream.java:92)
        at org.eclipse.paho.client.mqttv3.internal.CommsReceiver.run(CommsReceiver.java:133)
        ... 7 more
06:14:46.507 [pool-2-thread-3] INFO  com.tsystems.smartmon.process.BucketManager - Created Window: [15342272839, 15342272840, 15342272841, 15342272842, 15342272843, 15342272844, 15342272845, 15342272846, 15342272847, 15342272848]
06:14:46.507 [pool-2-thread-3] INFO  com.tsystems.smartmon.process.BucketManager - Created Window: [15342272840, 15342272841, 15342272842, 15342272843, 15342272844, 15342272845, 15342272846, 15342272847, 15342272848, 15342272849]

...

06:14:46.839 [MQTT Rec: GW001/Scoring] INFO  com.tsystems.smartmon.source.MQTTSource - CONNECTION STATUS REASON: BAD_CREDENTIAL
06:14:46.839 [MQTT Rec: GW001/Scoring] INFO  com.tsystems.smartmon.source.MQTTSource - CONNECTION STATUS THROWABLE: Unable to establish MQTT connection
com.microsoft.azure.sdk.iot.device.exceptions.ProtocolException: Unable to establish MQTT connection
        at com.microsoft.azure.sdk.iot.device.transport.mqtt.exceptions.PahoExceptionTranslator.convertToMqttException(PahoExceptionTranslator.java:47)
        at com.microsoft.azure.sdk.iot.device.transport.mqtt.Mqtt.connect(Mqtt.java:116)
        at com.microsoft.azure.sdk.iot.device.transport.mqtt.MqttMessaging.start(MqttMessaging.java:49)
        at com.microsoft.azure.sdk.iot.device.transport.mqtt.MqttIotHubConnection.open(MqttIotHubConnection.java:179)
        at com.microsoft.azure.sdk.iot.device.transport.IotHubTransport.openConnection(IotHubTransport.java:641)
        at com.microsoft.azure.sdk.iot.device.transport.IotHubTransport.singleReconnectAttempt(IotHubTransport.java:759)
        at com.microsoft.azure.sdk.iot.device.transport.IotHubTransport.reconnect(IotHubTransport.java:713)
        at com.microsoft.azure.sdk.iot.device.transport.IotHubTransport.handleDisconnection(IotHubTransport.java:671)
        at com.microsoft.azure.sdk.iot.device.transport.IotHubTransport.onConnectionLost(IotHubTransport.java:205)
        at com.microsoft.azure.sdk.iot.device.transport.mqtt.Mqtt.connectionLost(Mqtt.java:354)
        at org.eclipse.paho.client.mqttv3.internal.CommsCallback.connectionLost(CommsCallback.java:292)
        at org.eclipse.paho.client.mqttv3.internal.ClientComms.shutdownConnection(ClientComms.java:423)
        at org.eclipse.paho.client.mqttv3.internal.CommsReceiver.run(CommsReceiver.java:181)
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
        at java.util.concurrent.FutureTask.run(FutureTask.java:266)
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180)
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
        at java.lang.Thread.run(Thread.java:748)
Caused by: MqttException (0) - javax.net.ssl.SSLHandshakeException: Remote host closed connection during handshake
        at org.eclipse.paho.client.mqttv3.internal.ExceptionHelper.createMqttException(ExceptionHelper.java:38)
        at org.eclipse.paho.client.mqttv3.internal.ClientComms$ConnectBG.run(ClientComms.java:715)
        ... 7 more
Caused by: javax.net.ssl.SSLHandshakeException: Remote host closed connection during handshake
        at sun.security.ssl.SSLSocketImpl.readRecord(SSLSocketImpl.java:1002)
        at sun.security.ssl.SSLSocketImpl.performInitialHandshake(SSLSocketImpl.java:1385)
        at sun.security.ssl.SSLSocketImpl.startHandshake(SSLSocketImpl.java:1413)
        at sun.security.ssl.SSLSocketImpl.startHandshake(SSLSocketImpl.java:1397)
        at org.eclipse.paho.client.mqttv3.internal.SSLNetworkModule.start(SSLNetworkModule.java:108)
        at org.eclipse.paho.client.mqttv3.internal.websocket.WebSocketSecureNetworkModule.start(WebSocketSecureNetworkModule.java:61)
        at org.eclipse.paho.client.mqttv3.internal.ClientComms$ConnectBG.run(ClientComms.java:701)
        ... 7 more
Caused by: java.io.EOFException: SSL peer shut down incorrectly
        at sun.security.ssl.InputRecord.read(InputRecord.java:505)
        at sun.security.ssl.SSLSocketImpl.readRecord(SSLSocketImpl.java:983)
        ... 13 more
06:14:47.531 [pool-2-thread-3] INFO  com.tsystems.smartmon.process.FeatureGenerator - Waiting for Buckets.
06:14:48.531 [pool-2-thread-3] INFO  com.tsystems.smartmon.process.FeatureGenerator - Waiting for Buckets.

ts4iot on 14 Aug 2018

The Scoring module tries to reconnect during the edgehub shuts down. The exception of the 1st reconnection attempt prevents the Scoring module from further reconnects.

ts4iot on 14 Aug 2018

How consistently do you see this exact stacktrace? And do you see it outside of when you manually restart the iotedge runtime?

Caused by: MqttException (0) - javax.net.ssl.SSLHandshakeException: Remote host closed connection during handshake
        at org.eclipse.paho.client.mqttv3.internal.ExceptionHelper.createMqttException(ExceptionHelper.java:38)
        at org.eclipse.paho.client.mqttv3.internal.ClientComms$ConnectBG.run(ClientComms.java:715)
        ... 7 more
Caused by: javax.net.ssl.SSLHandshakeException: Remote host closed connection during handshake
        at sun.security.ssl.SSLSocketImpl.readRecord(SSLSocketImpl.java:1002)
        at sun.security.ssl.SSLSocketImpl.performInitialHandshake(SSLSocketImpl.java:1385)
        at sun.security.ssl.SSLSocketImpl.startHandshake(SSLSocketImpl.java:1413)
        at sun.security.ssl.SSLSocketImpl.startHandshake(SSLSocketImpl.java:1397)
        at org.eclipse.paho.client.mqttv3.internal.SSLNetworkModule.start(SSLNetworkModule.java:108)
        at org.eclipse.paho.client.mqttv3.internal.websocket.WebSocketSecureNetworkModule.start(WebSocketSecureNetworkModule.java:61)
        at org.eclipse.paho.client.mqttv3.internal.ClientComms$ConnectBG.run(ClientComms.java:701)
        ... 7 more
Caused by: java.io.EOFException: SSL peer shut down incorrectly
        at sun.security.ssl.InputRecord.read(InputRecord.java:505)
        at sun.security.ssl.SSLSocketImpl.readRecord(SSLSocketImpl.java:983)
        ... 13 more

I'm a little hesitant to declare all SSL exceptions as retryable in our SDK, and I'm even more hesitant to hardcode a check for the nested java.io.EOFException: SSL peer shut down incorrectly

timtay-microsoft on 17 Aug 2018

The error described at the very top of this thread can also be reproduced as follows:

Create "New IT Edge Solution" in Visual Studio Code using "C# Module" Template
Set "env": { "OptimizeForPerformance": { "value": "false" } } for edgeHub module (to make it runnable on a RaspberryPi)
Set "env": { "MessageCount": { "value": -1 }, "MessageDelay": { "value": "00:00:00.050" } } for tempSensor module (to create many messages in a short time - this makes it crash faster)
Build and Push for arm32v7
Deploy to RaspberryPi device

The memory consumption of the EdgeHub Module will rise over time and somewhere around 170MB EdgeHub crashes with the following message:
terminate called after throwing an instance of 'std::bad_alloc'
what(): std::bad_alloc

When EdgeHub recovers from the crash, the tempSensor starts Sending messages again but the SampleModule (which is supposed to receive the messages from tempSensor and pipe them to IotHub) does not receive any messages anymore.

We are using the latest IotEdge runtime and edgeHub 1.0.6

This sample Application crashes in less than an hour.
A project we would like to go productive with contains several custom modules and uses the OPC-Publisher Module crashes even faster.

BewaControl-ReneDivossen on 6 Feb 2019

Here comes some more insight:
The crash should not occur because of the memory used is greater than 170 MB but because of the virtual memory (address space) exceeding 2GB (2097152 KB) which is the maximum for the 32 bit Raspbian Pi --> The error std::bad_alloc occurs.

Upon startup the edgeHub consumes almost 2GB of virtual memory. As soon as messages are being generated, the virtual memory increases further .

By default, the messages are stored within the edgeHub container. I was hoping that moving them to a custom folder would get rid of the crashes.
To use a custom folder, I added "Binds": [ "/etc/iotedge/storage/:/iotedge/storage/" ] to edgeHub->settings->createOptions->HostConfig and added "storageFolder": { "value": "/iotedge/storage/" } to edgeHub->env.
In addition I had to manually provide access permission for folder "/etc/iotedge/storage" because otherwise edgeHub failed with "access denied".

The test solution I described in my previous comment ran for 14 hours sending one message every 2 seconds without crashing. Excited by this I deployed our real project again but unfortunately it crashed again with std::bad_alloc after 27 minutes.

BewaControl-ReneDivossen on 7 Feb 2019

One thing you can try is to choose either MQTT or AMQP for all clients (devices and modules) to connect to EdgeHub, and then turn off the other protocol head.
To do this, set the environment variable amqpSettings__enabled=false or mqttSettings__enabled=false (depending on whether you want to turn off AMQP or MQTT... also note the double underscores)
That should reduce the memory pressure on the system.

varunpuranik on 7 Feb 2019

👍1

Interesting finding that it seemed to work in your test setup and failed again. I have seen this behavior also in different setups. While my test ran flawlessly for days and now signs of any memory issues (I was separately logging memory consumption of the processes) another test on a separate Raspberry by someone else failed within seconds. Initial assumption was that there was a faulty setup / misconfiguration / ... on the second device but that hasn't been tested yet. As I saw the issue of @BewaControl-ReneDivossen I tested again and can pretty much replicate that behavior. That looks to me as the first series of test scenarios was more or less luck...

Excerpt of logs before std::bad_alloc:

 2019-02-07 06:47:23.446 +00:00 [INF] - New device connection for device Pi2/directMethodUrlModule
 2019-02-07 06:47:23.446 +00:00 [INF] - New device connection for device Pi2/PythonModule
 2019-02-07 06:47:23.448 +00:00 [INF] - New device connection for device Pi2/senseHatDisplay
 2019-02-07 06:47:23.448 +00:00 [INF] - New device connection for device Pi2/clearSenseHat
 2019-02-07 06:47:23.507 +00:00 [INF] - Bind device proxy for device Pi2/clearSenseHat
 2019-02-07 06:47:23.508 +00:00 [INF] - Bind device proxy for device Pi2/senseHatDisplay
 2019-02-07 06:47:23.507 +00:00 [INF] - Bind device proxy for device Pi2/PythonModule
 2019-02-07 06:47:23.507 +00:00 [INF] - Bind device proxy for device Pi2/directMethodUrlModule
 2019-02-07 06:47:23.514 +00:00 [INF] - Binding message channel for device Id Pi2/clearSenseHat
 2019-02-07 06:47:23.514 +00:00 [INF] - Binding message channel for device Id Pi2/PythonModule
 2019-02-07 06:47:23.515 +00:00 [INF] - Binding message channel for device Id Pi2/directMethodUrlModule
 2019-02-07 06:47:23.515 +00:00 [INF] - Binding message channel for device Id Pi2/senseHatDisplay
 2019-02-07 06:47:23.642 +00:00 [INF] - Attempting to connect to IoT Hub for client Pi2/directMethodUrlModule via AMQP...
 2019-02-07 06:47:23.839 +00:00 [INF] - Cloud connection for Pi2/directMethodUrlModule is True
 2019-02-07 06:47:23.839 +00:00 [INF] - Connection status for Pi2/directMethodUrlModule changed to ConnectionEstablished
 2019-02-07 06:47:23.839 +00:00 [INF] - Created cloud proxy for client Pi2/directMethodUrlModule via AMQP, with client operation timeout 20 seconds.
 2019-02-07 06:47:23.840 +00:00 [INF] - Initialized cloud proxy 5dff2173-d212-4b26-9af7-b6444d0c5d7a for Pi2/directMethodUrlModule
 2019-02-07 06:47:23.840 +00:00 [INF] - Created cloud connection for client Pi2/directMethodUrlModule
 2019-02-07 06:47:23.840 +00:00 [INF] - Processing subscription Methods for client Pi2/directMethodUrlModule.
 2019-02-07 06:47:24.044 +00:00 [INF] - Set subscriptions from session state for Pi2/directMethodUrlModule
 2019-02-07 06:47:24.045 +00:00 [INF] - Attempting to connect to IoT Hub for client Pi2/clearSenseHat via AMQP...
 2019-02-07 06:47:24.242 +00:00 [INF] - Cloud connection for Pi2/clearSenseHat is True
 2019-02-07 06:47:24.243 +00:00 [INF] - Connection status for Pi2/clearSenseHat changed to ConnectionEstablished
 2019-02-07 06:47:24.244 +00:00 [INF] - Created cloud proxy for client Pi2/clearSenseHat via AMQP, with client operation timeout 20 seconds.
 2019-02-07 06:47:24.245 +00:00 [INF] - Initialized cloud proxy dab71f39-cf07-46ff-a457-0ae9717da97d for Pi2/clearSenseHat
 2019-02-07 06:47:24.246 +00:00 [INF] - Created cloud connection for client Pi2/clearSenseHat
 2019-02-07 06:47:24.247 +00:00 [INF] - Processing subscription Methods for client Pi2/clearSenseHat.
 2019-02-07 06:47:24.464 +00:00 [INF] - Set subscriptions from session state for Pi2/clearSenseHat
 2019-02-07 06:47:24.466 +00:00 [INF] - Attempting to connect to IoT Hub for client Pi2/senseHatDisplay via AMQP...
 2019-02-07 06:47:24.672 +00:00 [INF] - Cloud connection for Pi2/senseHatDisplay is True
 2019-02-07 06:47:24.673 +00:00 [INF] - Connection status for Pi2/senseHatDisplay changed to ConnectionEstablished
 2019-02-07 06:47:24.673 +00:00 [INF] - Created cloud proxy for client Pi2/senseHatDisplay via AMQP, with client operation timeout 20 seconds.
 2019-02-07 06:47:24.674 +00:00 [INF] - Initialized cloud proxy 4dfe2984-dfb5-4861-8b63-7d3c82319ea9 for Pi2/senseHatDisplay
 2019-02-07 06:47:24.674 +00:00 [INF] - Created cloud connection for client Pi2/senseHatDisplay
 2019-02-07 06:47:24.675 +00:00 [INF] - Processing subscription Methods for client Pi2/senseHatDisplay.
 2019-02-07 06:47:24.829 +00:00 [INF] - Set subscriptions from session state for Pi2/senseHatDisplay
 2019-02-07 06:47:24.830 +00:00 [INF] - Processing subscription TwinResponse for client Pi2/PythonModule.
 2019-02-07 06:47:24.832 +00:00 [INF] - Processing subscription ModuleMessages for client Pi2/PythonModule.
 2019-02-07 06:47:24.832 +00:00 [INF] - Processing subscription DesiredPropertyUpdates for client Pi2/PythonModule.
 2019-02-07 06:47:24.834 +00:00 [INF] - Set subscriptions from session state for Pi2/PythonModule
 2019-02-07 06:48:21.362 +00:00 [INF] - Closing connection for device: Pi2/PythonModule, , 
 2019-02-07 06:48:21.370 +00:00 [INF] - Disposing MessagingServiceClient for device Id Pi2/PythonModule because of exception - 
 2019-02-07 06:48:21.391 +00:00 [INF] - Setting device proxy inactive for device Id Pi2/PythonModule
 2019-02-07 06:48:21.439 +00:00 [INF] - Device connection removed for device Pi2/PythonModule
 2019-02-07 06:48:21.441 +00:00 [INF] - Client Pi2/PythonModule in device scope authenticated locally.
 2019-02-07 06:48:21.442 +00:00 [INF] - Successfully generated identity for clientId Pi2/PythonModule and username iothubforstarters.azure-devices.net/Pi2/PythonModule/?api-version=2017-11-08-preview&DeviceClientType=iothubclient%2f1.2.12%20(native%3b%20Linux%3b%20armv7l)
 2019-02-07 06:48:21.443 +00:00 [INF] - ClientAuthenticated, Pi2/PythonModule, 5e6fb5c9
 2019-02-07 06:48:21.453 +00:00 [INF] - New device connection for device Pi2/PythonModule
 2019-02-07 06:48:21.457 +00:00 [INF] - Bind device proxy for device Pi2/PythonModule
 2019-02-07 06:48:21.458 +00:00 [INF] - Binding message channel for device Id Pi2/PythonModule
 2019-02-07 06:48:21.480 +00:00 [INF] - Remove device connection for device Pi2/PythonModule
 2019-02-07 06:50:47.731 +00:00 [INF] - Client Pi2/tempSensor in device scope authenticated locally.
 2019-02-07 06:50:47.731 +00:00 [INF] - Successfully generated identity for clientId Pi2/tempSensor and username raspberrypi/Pi2/tempSensor/?api-version=2018-06-30&DeviceClientType=.NET%2F1.19.0%20%28.NET%20Core%204.6.27019.06%3B%20Linux%204.14.79-v7%2B%20%231159%20SMP%20Sun%20Nov%204%2017%3A50%3A20%20GMT%202018%3B%20Arm%29
 2019-02-07 06:50:47.732 +00:00 [INF] - ClientAuthenticated, Pi2/tempSensor, 2a2a4ac9
 2019-02-07 06:50:47.735 +00:00 [INF] - New device connection for device Pi2/tempSensor
 2019-02-07 06:50:47.737 +00:00 [INF] - Bind device proxy for device Pi2/tempSensor
 2019-02-07 06:50:47.738 +00:00 [INF] - Binding message channel for device Id Pi2/tempSensor
 2019-02-07 06:50:47.976 +00:00 [INF] - Processing subscription TwinResponse for client Pi2/tempSensor.
 2019-02-07 06:50:47.977 +00:00 [INF] - Processing subscription DesiredPropertyUpdates for client Pi2/tempSensor.
 2019-02-07 06:50:47.979 +00:00 [INF] - Set subscriptions from session state for Pi2/tempSensor
 2019-02-07 06:50:50.155 +00:00 [INF] - Processing subscription TwinResponse for client Pi2/tempSensor.
 2019-02-07 06:50:50.156 +00:00 [INF] - Processing subscription DesiredPropertyUpdates for client Pi2/tempSensor.
 2019-02-07 06:50:50.158 +00:00 [INF] - Set subscriptions from session state for Pi2/tempSensor
 2019-02-07 06:52:07.924 +00:00 [INF] - Reauthenticating connected clients
 2019-02-07 06:57:07.837 +00:00 [INF] - Reauthenticating connected clients
 2019-02-07 07:02:07.893 +00:00 [INF] - Reauthenticating connected clients
 2019-02-07 07:07:07.841 +00:00 [INF] - Reauthenticating connected clients
 2019-02-07 07:12:07.836 +00:00 [INF] - Reauthenticating connected clients
 2019-02-07 07:16:57.459 +00:00 [INF] - Started task to cleanup processed and stale messages for endpoint iothub
 2019-02-07 07:17:07.858 +00:00 [INF] - Reauthenticating connected clients
 terminate called after throwing an instance of 'std::bad_alloc'
   what():  std::bad_alloc

 [2019-02-07 07:20:20 +00:00]: Starting Edge Hub
 [02/07/2019 07:20:21.068 AM] Edge Hub Main()
 [02/07/2019 07:20:28.008 AM] Found intermediate certificates: [CN=iotedged workload ca:03/18/2019 05:55:28],[CN=Test Edge Device CA:03/18/2019 05:55:28],[CN=Test Edge Owner CA:03/18/2019 05:55:28]
 2019-02-07 07:20:50.380 +00:00 [INF] - Created persistent store at /tmp/edgeHub
 2019-02-07 07:20:51.051 +00:00 [INF] - Starting Edge Hub

This behavior started after the following error in the logs:

2019-02-06 21:35:07.440 +00:00 [INF] - ClientAuthenticated, Pi2/PythonModule, 19176a58
2019-02-06 21:35:07.446 +00:00 [INF] - New device connection for device Pi2/PythonModule
2019-02-06 21:35:07.448 +00:00 [INF] - Bind device proxy for device Pi2/PythonModule
2019-02-06 21:35:07.449 +00:00 [INF] - Binding message channel for device Id Pi2/PythonModule
2019-02-06 21:37:35.336 +00:00 [INF] - Client Pi2/tempSensor in device scope authenticated locally.
2019-02-06 21:37:35.337 +00:00 [INF] - Successfully generated identity for clientId Pi2/tempSensor and username raspberrypi/Pi2/tempSensor/?api-version=2018-06-30&DeviceClientType=.NET%2F1.19.0%20%28.NET%20Core%204.6.27019.06%3B%20Linux%204.14.79-v7%2B%20%231159%20SMP%20Sun%20Nov%204%2017%3A50%3A20%20GMT%202018%3B%20Arm%29
2019-02-06 21:37:35.337 +00:00 [INF] - ClientAuthenticated, Pi2/tempSensor, 30f56156
2019-02-06 21:37:35.341 +00:00 [INF] - New device connection for device Pi2/tempSensor
2019-02-06 21:37:35.344 +00:00 [INF] - Bind device proxy for device Pi2/tempSensor
2019-02-06 21:37:35.345 +00:00 [INF] - Binding message channel for device Id Pi2/tempSensor
2019-02-06 21:37:35.537 +00:00 [INF] - Processing subscription TwinResponse for client Pi2/tempSensor.
2019-02-06 21:37:35.537 +00:00 [INF] - Processing subscription DesiredPropertyUpdates for client Pi2/tempSensor.
2019-02-06 21:37:35.540 +00:00 [INF] - Set subscriptions from session state for Pi2/tempSensor
2019-02-06 21:37:37.935 +00:00 [INF] - Processing subscription TwinResponse for client Pi2/tempSensor.
2019-02-06 21:37:37.936 +00:00 [INF] - Processing subscription DesiredPropertyUpdates for client Pi2/tempSensor.
2019-02-06 21:37:37.938 +00:00 [INF] - Set subscriptions from session state for Pi2/tempSensor
 terminate called after throwing an instance of 'std::system_error'
   what():  Resource temporarily unavailable

[2019-02-06 21:39:18 +00:00]: Starting Edge Hub
[02/06/2019 09:39:19.538 PM] Edge Hub Main()

Further logs are available for analysis.

Data generating module available here by @sebader

My test setup was running on a Raspberry Pi3 with Raspbian installed.

 PRETTY_NAME="Raspbian GNU/Linux 9 (stretch)"
 NAME="Raspbian GNU/Linux"
 VERSION_ID="9"
 VERSION="9 (stretch)"
 ID=raspbian
 ID_LIKE=debian
 HOME_URL="http://www.raspbian.org/"
 SUPPORT_URL="http://www.raspbian.org/RaspbianForums"
 BUG_REPORT_URL="http://www.raspbian.org/RaspbianBugs"

ChrRing on 8 Feb 2019

Hello @varunpuranik
thanks a lot for your comment. I turned off AMQP (MQTT is needed because OPC Publisher currently only supports MQTT when running as IotEdge module) and memory consumption is less than one third of before. Right now the edgeModule uses a bit more than 40 MB (but is slowly gaining). I'll let this run and see if / when the crash occurs again.

BewaControl-ReneDivossen on 8 Feb 2019

@hansgschossmann is there a switch in the publisher module for the transport protocol (MQTT or AMQP)?

sebader on 8 Feb 2019

Check the help for the --ih option. It accepts all TransportType enum names of the IoTHub client.

Outlook for Androidhttps://aka.ms/ghei36 herunterladen

From: Sebastian notifications@github.com
Sent: Friday, February 8, 2019 12:36:19 PM
To: Azure/iotedge
Cc: Hans Gschoßmann; Mention
Subject: Re: [Azure/iotedge] edgeHub crashes on raspberry pi with what(): std::bad_alloc (#119)

@hansgschossmannhttps://nam06.safelinks.protection.outlook.com/?url=https%3A%2F%2Fgithub.com%2Fhansgschossmann&data=02%7C01%7Cjohanng%40microsoft.com%7Cd30fdca37943443dcfb008d68db9a52b%7C72f988bf86f141af91ab2d7cd011db47%7C1%7C0%7C636852225810708106&sdata=%2FeqLSvXNeg3i1dVD2vXgBuY%2BmnF%2BQjmCplVm8yxMUPw%3D&reserved=0 is there a switch in the publisher module for the transport protocol (MQTT or AMQP)?

—
You are receiving this because you were mentioned.
Reply to this email directly, view it on GitHubhttps://nam06.safelinks.protection.outlook.com/?url=https%3A%2F%2Fgithub.com%2FAzure%2Fiotedge%2Fissues%2F119%23issuecomment-461775628&data=02%7C01%7Cjohanng%40microsoft.com%7Cd30fdca37943443dcfb008d68db9a52b%7C72f988bf86f141af91ab2d7cd011db47%7C1%7C0%7C636852225810718115&sdata=xoPQTx4sZTo4TlqzW9Zht3gYfcJCkEx6%2FU3JcS5Exzw%3D&reserved=0, or mute the threadhttps://nam06.safelinks.protection.outlook.com/?url=https%3A%2F%2Fgithub.com%2Fnotifications%2Funsubscribe-auth%2FAHxelkIoOS3BvpocUm9hO36RdCNBlrs-ks5vLWEzgaJpZM4VtgRH&data=02%7C01%7Cjohanng%40microsoft.com%7Cd30fdca37943443dcfb008d68db9a52b%7C72f988bf86f141af91ab2d7cd011db47%7C1%7C0%7C636852225810728123&sdata=QdQ8o6TZBWgeaZRmG3d1xtzNVhfZX%2FWsvINDFQWfk%2BU%3D&reserved=0.

hansgschossmann on 8 Feb 2019

The --ih option is overridden if OPC Publisher is used as IotEdge module.
I've created an Issue for that. See https://github.com/Azure/iot-edge-opc-publisher/issues/189

BewaControl-ReneDivossen on 8 Feb 2019

I was just realizing that this is in context of IoT Edge. When you run OPC Publisher as IoT Edge module it allows only to use Mqtt_Tcp_Only. Pls open an issue on the OPC Publisher github and I will allow also Amqp_Tcp_Only for this case.

From: BewaControl-ReneDivossen notifications@github.com
Sent: Freitag, 8. Februar 2019 13:56
To: Azure/iotedge iotedge@noreply.github.com
Cc: Hans Gschoßmann johanng@microsoft.com; Mention mention@noreply.github.com
Subject: Re: [Azure/iotedge] edgeHub crashes on raspberry pi with what(): std::bad_alloc (#119)

The --ih option is overridden if OPC Publisher is used as IotEdge module.
I've created an Issue for that. See Azure/iot-edge-opc-publisher#189https://nam06.safelinks.protection.outlook.com/?url=https%3A%2F%2Fgithub.com%2FAzure%2Fiot-edge-opc-publisher%2Fissues%2F189&data=02%7C01%7Cjohanng%40microsoft.com%7C1f5aa80b47fd450bd71208d68dc4b6fe%7C72f988bf86f141af91ab2d7cd011db47%7C1%7C0%7C636852273362034272&sdata=uvLPhzHO01TcqkvYUeHB0g%2BWkef%2BwnEhHsjuZU63E%2BM%3D&reserved=0

—
You are receiving this because you were mentioned.
Reply to this email directly, view it on GitHubhttps://nam06.safelinks.protection.outlook.com/?url=https%3A%2F%2Fgithub.com%2FAzure%2Fiotedge%2Fissues%2F119%23issuecomment-461794148&data=02%7C01%7Cjohanng%40microsoft.com%7C1f5aa80b47fd450bd71208d68dc4b6fe%7C72f988bf86f141af91ab2d7cd011db47%7C1%7C0%7C636852273362034272&sdata=P3k43QATBPJz3gKKpENCT3LUH1oQAgKPo2HUeG23Kow%3D&reserved=0, or mute the threadhttps://nam06.safelinks.protection.outlook.com/?url=https%3A%2F%2Fgithub.com%2Fnotifications%2Funsubscribe-auth%2FAHxelktoFtql6q4_XPRFQoa57hn81wfdks5vLXPFgaJpZM4VtgRH&data=02%7C01%7Cjohanng%40microsoft.com%7C1f5aa80b47fd450bd71208d68dc4b6fe%7C72f988bf86f141af91ab2d7cd011db47%7C1%7C0%7C636852273362034272&sdata=mgYwiABzczgZopPwzlIr0La1h1GZ8rLuoeYgy2I0qZY%3D&reserved=0.

hansgschossmann on 8 Feb 2019

PR for allowing AMQP when running as IoT Edge module is submitted: https://github.com/Azure/iot-edge-opc-publisher/pull/191

hansgschossmann on 8 Feb 2019

With AMQP turned off, an IotEdge application sending a message every 2 seconds has now been running on the Raspberry for 3,5 hours without crashing. Memory consumption of the edgeHub docker container increased from 45 MB to 67 MB during that time. So I guess at some point it will inevitably run out of memory or address space again. I'm hoping for a timely release of the next OpcPublisher version featuring AMQP so after crashing an automatic recovery of the modules should be possible.

BewaControl-ReneDivossen on 8 Feb 2019

The memory usage of EdgeHub when both protocols are enabled typically puts a lot of pressure on a device like Raspberry PI. But with one protocol head turned off, the memory pressure goes down as you saw. The increase in memory usage is not necessarily a leak, but just the way the Dotnet GC behaves, allowing the app to consume more memory when available before reclaiming it. But the expectation is that this should stabilize at some point, after which the EdgeHub should be able to run steadily for long periods of time.
If you see that EdgeHub crashes even with one protocol disabled, please let us know and we will investigate.

varunpuranik on 8 Feb 2019

@BewaControl-ReneDivossen pls try mcr.microsoft.com/iotedge/opc-publisher:latest it does use now Amqp_Tcp_Only as default for EdgeHub and allows you to switch to Mqtt_Tcp_Only via the --ih option. It would be great if you can test and let me know if it works as expected.

hansgschossmann on 8 Feb 2019

@hansgschossmann - I'll give it a try on monday.
@varunpuranik - I left the Edge Device running and I'll see if it survives the weekend without crashing.

BewaControl-ReneDivossen on 8 Feb 2019

@hansgschossmann I referenced opc-publisher:latest and I'm using Amqp as the only protocol now. It's running but automatic recovery does not work as expected. If I kill the edgeHub module using "docker stop" everything will recover nicely but if I kill the publisher module using "docker stop" it will not send messages anymore after coming up running again.

BewaControl-ReneDivossen on 11 Feb 2019

@varunpuranik With AMQP turned off, my sample IotEdge application sending a message every 2 seconds has been running on the Raspberry for almost 3 days without crashing. Memory consumption of the edgeHub docker container increased from 45 MB to 102 MB during that time. As you expected, the increase in memory slowed down at some point. Around 85 MB it stayed for a while but at some point it started increasing again.
Since automatic recovery is supposed to work more reliable with Amqp than with Mqtt (is that really the case?) I switched to AMQP now that OPCPublisher is supporting that protocol. I turned off the MQTT and the HTTP Head. I'll let this setting run for a while and then let you know how it behaved.

BewaControl-ReneDivossen on 11 Feb 2019

@varunpuranik With only AMQP turned on, the sample IotEdge application sending a message every 2 seconds has been running on the Raspberry for just about a day now without crashing. Memory consumption of the edgeHub docker container increased from around 80 MB to about 120 MB during that time. Right now it is oszillating around 120 MB.

It looks like we can go on developing our real application now. Once it is implemented I'll do a long term test. If we see any more crashes I'll get back to you.

For now I'm back to believing in IotEdge - Thank you !

To prevent other developers from becoming frustrated you should comment on the necessity/recommendation to turn off Protocol heads on arm32 devices in your Installation Guide on your Troubleshooting Page. So far Turning off Protocol Heads seems to be an undocumented feature.

BewaControl-ReneDivossen on 12 Feb 2019

@BewaControl-ReneDivossen - I am glad to hear that!

Please let us know if you run into any more issues, and we will be happy to help!

varunpuranik on 12 Feb 2019

Not meaning to crash this issue but I have a similar instability on my R Pi 3 where the edgeHub is restarted after receiving the terminate called after throwing an instance of 'std::system_error' what(): Resource temporarily unavailable log message.

I only have 2 simulated temperature sensor modules routing data to a stream analytics job and all 3 routing to the cloud hub at roughly 1 message/module/5 seconds, so 3 messages sent to the hub every 5 seconds.

The edgehub recovers okay and normal processing resumes after a few of these restarts but then the analytics module doesn't reconnect to the hub and that's how things remain. If I manually restart the edgehub the analytics job still does not reconnect.

All 3 heads (amqp, mqtt, and http) are enabled on the edgehub under the above testing. So, assuming this is related to all 3 being enabled on a Pi and so constraining resources too much, I have experimented with disabling both mqtt and http but disabling either seems to prevent the analytics module from initializing its module client - its log just stays on " Module client initializing ...".

I'm wondering if there's a desired property or environment variable I need to specify to force AMQP only in the ASA module but I can't find any documentation on what this could be. Does it even support this config change?