Azure-docs: EdgeHub throwing some TLS error

Created on 25 Sep 2018 · 3Comments · Source: MicrosoftDocs/azure-docs

EdgeHub throwing some TLS handshake error

I am having a custom python module and edgeHub and edgeAgent running on my raspberry pi.
EdgeHub is throwing some error. It has some TLS handshaking going on and then reports OutOfMemory exception before getting restarted by edgeAgent. And also my python module throws some sort of errors.

The same setup is running fine in x-86 linux machine.
And it was also working in raspberry last friday but due to some reason I restarted everything and new hub image was downloaded from than I am getting the error.

The difference

Earlier edgeHub log:

[2018-09-20 09:45:39 : Starting Edge Hub
[09/20/2018 09:45:39.233 AM] Edge Hub Main()
2018-09-20 09:45:40.922 +00:00 [INF] - Starting Edge Hub
2018-09-20 09:45:40.934 +00:00 [INF] - Version - 1.0.1.15962126 (6e5e86dcf0c9a3732fc72a64d9ec9b0fcb2d6fad)
2018-09-20 09:45:40.934 +00:00 [INF] - 
        █████╗ ███████╗██╗   ██╗██████╗ ███████╗
       ██╔══██╗╚══███╔╝██║   ██║██╔══██╗██╔════╝
       ███████║  ███╔╝ ██║   ██║██████╔╝█████╗
       ██╔══██║ ███╔╝  ██║   ██║██╔══██╗██╔══╝
       ██║  ██║███████╗╚██████╔╝██║  ██║███████╗
       ╚═╝  ╚═╝╚══════╝ ╚═════╝ ╚═╝  ╚═╝╚══════╝

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

2018-09-20 09:45:40.934 +00:00 [INF] - Installing intermediate certificates.
2018-09-20 09:45:41.025 +00:00 [INF] - Attempting to connect to IoT Hub for client LM_1850/$edgeHub via AMQP...
2018-09-20 09:45:41.088 +00:00 [INF] - Connected to IoT Hub for client LM_1850/$edgeHub via AMQP, with client operation timeout 60000.
2018-09-20 09:45:41.095 +00:00 [INF] - Created cloud connection for client LM_1850/$edgeHub
2018-09-20 09:45:41.096 +00:00 [INF] - New cloud connection created for device LM_1850/$edgeHub
2018-09-20 09:45:41.102 +00:00 [INF] - Initializing configuration
.................

Current edgeHub log:

[2018-09-25 06:38:08 +00:00]: Starting Edge Hub
[09/25/2018 06:38:10.248 AM] Edge Hub Main()
2018-09-25 06:38:40.636 +00:00 [INF] - Created persistent store at /tmp/edgeHub
2018-09-25 06:38:41.255 +00:00 [INF] - Starting Edge Hub
2018-09-25 06:38:41.284 +00:00 [INF] - Version - 1.0.2.16940264 (f6fcdb2e24ac2af977e748e9f2b8a37245b92738)
2018-09-25 06:38:41.288 +00:00 [INF] - 
        █████╗ ███████╗██╗   ██╗██████╗ ███████╗
       ██╔══██╗╚══███╔╝██║   ██║██╔══██╗██╔════╝
       ███████║  ███╔╝ ██║   ██║██████╔╝█████╗
       ██╔══██║ ███╔╝  ██║   ██║██╔══██╗██╔══╝
       ██║  ██║███████╗╚██████╔╝██║  ██║███████╗
       ╚═╝  ╚═╝╚══════╝ ╚═════╝ ╚═╝  ╚═╝╚══════╝

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

2018-09-25 06:38:41.290 +00:00 [INF] - Installing intermediate certificates.
2018-09-25 06:38:41.697 +00:00 [INF] - Started task to cleanup processed and stale messages
2018-09-25 06:38:41.697 +00:00 [INF] - Created new message store
2018-09-25 06:38:42.633 +00:00 [INF] - Created device scope identities cache
2018-09-25 06:38:42.704 +00:00 [INF] - Starting refresh of device scope identities cache
2018-09-25 06:38:42.944 +00:00 [INF] - Initializing configuration
2018-09-25 06:38:43.192 +00:00 [INF] - New device connection for device RPI_129/$edgeHub
2018-09-25 06:38:43.762 +00:00 [INF] - Attempting to connect to IoT Hub for client RPI_129/$edgeHub via AMQP...
.................

As you can see in the logs the version of edgeHub is changed. From (1.0.1.15962126) to (1.0.2.16940264)

EdgeHub error logs:

[2018-09-24 13:48:37 +00:00]: Starting Edge Hub
[09/24/2018 01:48:38.665 PM] Edge Hub Main()
2018-09-24 13:48:52.285 +00:00 [INF] - Created persistent store at /tmp/edgeHub
2018-09-24 13:48:52.622 +00:00 [INF] - Starting Edge Hub
2018-09-24 13:48:52.626 +00:00 [INF] - Version - 1.0.2.16940264 (f6fcdb2e24ac2af977e748e9f2b8a37245b92738)
2018-09-24 13:48:52.628 +00:00 [INF] - 
        █████╗ ███████╗██╗   ██╗██████╗ ███████╗
       ██╔══██╗╚══███╔╝██║   ██║██╔══██╗██╔════╝
       ███████║  ███╔╝ ██║   ██║██████╔╝█████╗
       ██╔══██║ ███╔╝  ██║   ██║██╔══██╗██╔══╝
       ██║  ██║███████╗╚██████╔╝██║  ██║███████╗
       ╚═╝  ╚═╝╚══════╝ ╚═════╝ ╚═╝  ╚═╝╚══════╝

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

2018-09-24 13:48:52.628 +00:00 [INF] - Installing intermediate certificates.
2018-09-24 13:48:52.719 +00:00 [INF] - Created device scope identities cache
2018-09-24 13:48:52.756 +00:00 [INF] - Starting refresh of device scope identities cache
2018-09-24 13:48:52.864 +00:00 [INF] - Created new message store
2018-09-24 13:48:52.865 +00:00 [INF] - Started task to cleanup processed and stale messages
2018-09-24 13:48:53.601 +00:00 [INF] - Initializing configuration
2018-09-24 13:48:53.726 +00:00 [INF] - New device connection for device RPI_65/$edgeHub
2018-09-24 13:48:54.047 +00:00 [INF] - Attempting to connect to IoT Hub for client RPI_65/$edgeHub via AMQP...
2018-09-24 13:48:54.412 +00:00 [INF] - Created cloud proxy for client RPI_65/$edgeHub via AMQP, with client operation timeout 20000.
2018-09-24 13:48:54.444 +00:00 [INF] - Initialized cloud proxy 8394c01f-19d4-454e-ab35-1d5ee207dc28 for RPI_65/$edgeHub
2018-09-24 13:48:54.449 +00:00 [INF] - Created cloud connection for client RPI_65/$edgeHub
2018-09-24 13:48:54.501 +00:00 [INF] - Processing subscription DesiredPropertyUpdates for client RPI_65/$edgeHub.
2018-09-24 13:48:55.076 +00:00 [INF] - Processing subscription Methods for client RPI_65/$edgeHub.
2018-09-24 13:49:00.393 +00:00 [INF] - Cloud connection for RPI_65/$edgeHub is True
2018-09-24 13:49:00.444 +00:00 [INF] - Connection status for RPI_65/$edgeHub changed to ConnectionEstablished
2018-09-24 13:49:00.466 +00:00 [INF] - Exiting disconnected state
2018-09-24 13:49:00.478 +00:00 [INF] - Entering connected state
2018-09-24 13:49:00.485 +00:00 [INF] - Processing subscriptions for client RPI_65/$edgeHub.
2018-09-24 13:49:00.538 +00:00 [INF] - Processing subscription DesiredPropertyUpdates for client RPI_65/$edgeHub.
2018-09-24 13:49:00.553 +00:00 [INF] - Processing subscription Methods for client RPI_65/$edgeHub.
2018-09-24 13:49:06.465 +00:00 [INF] - Obtained edge hub config from module twin
2018-09-24 13:49:07.843 +00:00 [INF] - Set the following 1 route(s) in edge hub
2018-09-24 13:49:07.849 +00:00 [INF] - PythonMqttModuleToIoTHub: FROM /messages/modules/PythonMqttModule/outputs/* INTO $upstream
2018-09-24 13:49:07.855 +00:00 [INF] - Updated message store TTL to 7200 seconds
2018-09-24 13:49:07.857 +00:00 [INF] - Updated the edge hub store and forward configuration
2018-09-24 13:49:07.860 +00:00 [INF] - Initialized edge hub configuration
2018-09-24 13:49:07.950 +00:00 [INF] - Starting timer to authenticate connections with a period of 300 seconds
2018-09-24 13:49:08.492 +00:00 [INF] - Starting protocol heads - (MQTT, AMQP, HTTP)
2018-09-24 13:49:08.518 +00:00 [INF] - Starting MQTT head
2018-09-24 13:49:08.996 +00:00 [INF] - Initializing TLS endpoint on port 8883 for MQTT head.
2018-09-24 13:49:09.474 +00:00 [INF] - Starting AMQP head
2018-09-24 13:49:09.537 +00:00 [INF] - Started MQTT head
2018-09-24 13:49:10.055 +00:00 [INF] - Started AMQP head
2018-09-24 13:49:10.070 +00:00 [INF] - Starting HTTP head
2018-09-24 13:49:10.674 +00:00 [INF] - User profile is available. Using '"/home/edgehubuser/.aspnet/DataProtection-Keys"' as key repository; keys will not be encrypted at rest.
2018-09-24 13:49:10.832 +00:00 [INF] - Creating key {3ce912a5-1157-44ac-865c-cf38bf173fe5} with creation date 2018-09-24 13:49:10Z, activation date 2018-09-24 13:49:10Z, and expiration date 2018-12-23 13:49:10Z.
2018-09-24 13:49:10.958 +00:00 [WRN] - No XML encryptor configured. Key {3ce912a5-1157-44ac-865c-cf38bf173fe5} may be persisted to storage in unencrypted form.
2018-09-24 13:49:11.009 +00:00 [INF] - Writing data to file '"/home/edgehubuser/.aspnet/DataProtection-Keys/key-3ce912a5-1157-44ac-865c-cf38bf173fe5.xml"'.
2018-09-24 13:49:12.991 +00:00 [WRN] - Overriding address(es) '"http://+:80"'. Binding to endpoints defined in "UseKestrel()" instead.
2018-09-24 13:49:13.124 +00:00 [INF] - Started HTTP head
2018-09-24 13:49:20.239 +00:00 [INF] - Client RPI_65/PythonMqttModule in device scope authenticated locally.
2018-09-24 13:49:20.250 +00:00 [INF] - Successfully generated identity for clientId RPI_65/PythonMqttModule and username snapbricks-IoTHub.azure-devices.net/RPI_65/PythonMqttModule/?api-version=2017-11-08-preview&DeviceClientType=iothubclient%2f1.2.5%20(native%3b%20Linux%3b%20armv7l)
2018-09-24 13:49:20.266 +00:00 [INF] - ClientAuthenticated, RPI_65/PythonMqttModule, 42c4538d
2018-09-24 13:49:20.786 +00:00 [WRN] - Failed to release a message: PooledUnsafeDirectByteBuffer(freed)
DotNetty.Common.Utilities.IllegalReferenceCountException: refCnt: 0, decrement: 1
   at DotNetty.Buffers.AbstractReferenceCountedByteBuffer.Release0(Int32 decrement)
   at DotNetty.Buffers.AbstractReferenceCountedByteBuffer.Release()
   at DotNetty.Common.Utilities.ReferenceCountUtil.Release(Object msg)
   at DotNetty.Common.Utilities.ReferenceCountUtil.SafeRelease(Object msg)
2018-09-24 13:49:20.974 +00:00 [WRN] - Closing connection for device: RPI_65/PythonMqttModule, scope: ExceptionCaught, System.OutOfMemoryException: Exception of type 'System.OutOfMemoryException' was thrown.
   at DotNetty.Buffers.HeapArena.NewChunk(Int32 pageSize, Int32 maxOrder, Int32 pageShifts, Int32 chunkSize)
   at DotNetty.Buffers.PoolArena`1.AllocateNormal(PooledByteBuffer`1 buf, Int32 reqCapacity, Int32 normCapacity)
   at DotNetty.Buffers.PoolArena`1.Allocate(PoolThreadCache`1 cache, PooledByteBuffer`1 buf, Int32 reqCapacity)
   at DotNetty.Buffers.PooledByteBufferAllocator.NewHeapBuffer(Int32 initialCapacity, Int32 maxCapacity)
   at DotNetty.Buffers.AbstractByteBufferAllocator.HeapBuffer(Int32 initialCapacity)
   at DotNetty.Buffers.UnsafeByteBufferUtil.GetBytes(AbstractByteBuffer buf, Byte* addr, Int32 index, Stream output, Int32 length)
   at DotNetty.Buffers.PooledUnsafeDirectByteBuffer.GetBytes(Int32 index, Stream output, Int32 length)
   at DotNetty.Buffers.AbstractByteBuffer.ReadBytes(Stream destination, Int32 length)
   at DotNetty.Handlers.Tls.TlsHandler.Wrap(IChannelHandlerContext context)
   at DotNetty.Handlers.Tls.TlsHandler.Flush(IChannelHandlerContext context)
   at DotNetty.Transport.Channels.AbstractChannelHandlerContext.InvokeFlush0(), 42c4538d
2018-09-24 13:49:20.983 +00:00 [INF] - Disposing MessagingServiceClient for device Id RPI_65/PythonMqttModule because of exception - System.OutOfMemoryException: Exception of type 'System.OutOfMemoryException' was thrown.
   at DotNetty.Buffers.HeapArena.NewChunk(Int32 pageSize, Int32 maxOrder, Int32 pageShifts, Int32 chunkSize)
   at DotNetty.Buffers.PoolArena`1.AllocateNormal(PooledByteBuffer`1 buf, Int32 reqCapacity, Int32 normCapacity)
   at DotNetty.Buffers.PoolArena`1.Allocate(PoolThreadCache`1 cache, PooledByteBuffer`1 buf, Int32 reqCapacity)
   at DotNetty.Buffers.PooledByteBufferAllocator.NewHeapBuffer(Int32 initialCapacity, Int32 maxCapacity)
   at DotNetty.Buffers.AbstractByteBufferAllocator.HeapBuffer(Int32 initialCapacity)
   at DotNetty.Buffers.UnsafeByteBufferUtil.GetBytes(AbstractByteBuffer buf, Byte* addr, Int32 index, Stream output, Int32 length)
   at DotNetty.Buffers.PooledUnsafeDirectByteBuffer.GetBytes(Int32 index, Stream output, Int32 length)
   at DotNetty.Buffers.AbstractByteBuffer.ReadBytes(Stream destination, Int32 length)
   at DotNetty.Handlers.Tls.TlsHandler.Wrap(IChannelHandlerContext context)
   at DotNetty.Handlers.Tls.TlsHandler.Flush(IChannelHandlerContext context)
   at DotNetty.Transport.Channels.AbstractChannelHandlerContext.InvokeFlush0()
2018-09-24 13:49:21.025 +00:00 [INF] - Failed to close IoT Hub Client cleanly., System.NullReferenceException: Object reference not set to an instance of an object.
   at Microsoft.Azure.Devices.Edge.Hub.Core.Device.DeviceMessageHandler.CloseAsync() in /home/vsts/work/1/s/edge-hub/src/Microsoft.Azure.Devices.Edge.Hub.Core/device/DeviceMessageHandler.cs:line 77
   at Microsoft.Azure.Devices.ProtocolGateway.Mqtt.MqttAdapter.CloseServiceConnection(IChannelHandlerContext context, Exception cause, PublishPacket will), 42c4538d
2018-09-24 13:49:51.361 +00:00 [WRN] - TLS handshake failed., System.IO.IOException: Channel is closed, 635ca113
2018-09-24 13:50:56.337 +00:00 [WRN] - TLS handshake failed., System.IO.IOException: Channel is closed, 5a86c214
2018-09-24 13:53:05.334 +00:00 [WRN] - TLS handshake failed., System.IO.IOException: Channel is closed, 0560018a
2018-09-24 13:54:08.012 +00:00 [INF] - Reauthenticating connected clients

.............

Module error logs:

Error: Time:Tue Sep 25 06:25:25 2018 File:/usr/sdk/src/c/umqtt/src/mqtt_client.c Func:mqtt_client_connect Line:989 Error: io_open failed
Error: Time:Tue Sep 25 06:25:25 2018 File:/usr/sdk/src/c/iothub_client/src/iothubtransport_mqtt_common.c Func:SendMqttConnectMsg Line:2037 failure connecting to address raspberrypi.
Error: Time:Tue Sep 25 06:25:29 2018 File:/usr/sdk/src/c/c-utility/adapters/socketio_berkeley.c Func:wait_for_connection Line:383 Failure: connect failure 111.
Error: Time:Tue Sep 25 06:25:29 2018 File:/usr/sdk/src/c/c-utility/adapters/socketio_berkeley.c Func:socketio_open Line:767 wait_for_connection failed
Error: Time:Tue Sep 25 06:25:29 2018 File:/usr/sdk/src/c/c-utility/adapters/tlsio_openssl.c Func:on_underlying_io_open_complete Line:748 Invalid tlsio_state. Expected state is TLSIO_STATE_OPENING_UNDERLYING_IO.
Error: Time:Tue Sep 25 06:25:29 2018 File:/usr/sdk/src/c/c-utility/adapters/tlsio_openssl.c Func:tlsio_openssl_open Line:1246 Failed opening the underlying I/O.
Error: Time:Tue Sep 25 06:25:29 2018 File:/usr/sdk/src/c/umqtt/src/mqtt_client.c Func:mqtt_client_connect Line:989 Error: io_open failed
Error: Time:Tue Sep 25 06:25:29 2018 File:/usr/sdk/src/c/iothub_client/src/iothubtransport_mqtt_common.c Func:SendMqttConnectMsg Line:2037 failure connecting to address raspberrypi.
Error: Time:Tue Sep 25 06:25:37 2018 File:/usr/sdk/src/c/c-utility/adapters/socketio_berkeley.c Func:wait_for_connection Line:383 Failure: connect failure 111.
Error: Time:Tue Sep 25 06:25:37 2018 File:/usr/sdk/src/c/c-utility/adapters/socketio_berkeley.c Func:socketio_open Line:767 wait_for_connection failed
Error: Time:Tue Sep 25 06:25:37 2018 File:/usr/sdk/src/c/c-utility/adapters/tlsio_openssl.c Func:on_underlying_io_open_complete Line:748 Invalid tlsio_state. Expected state is TLSIO_STATE_OPENING_UNDERLYING_IO.
Error: Time:Tue Sep 25 06:25:37 2018 File:/usr/sdk/src/c/c-utility/adapters/tlsio_openssl.c Func:tlsio_openssl_open Line:1246 Failed opening the underlying I/O.
Error: Time:Tue Sep 25 06:25:37 2018 File:/usr/sdk/src/c/umqtt/src/mqtt_client.c Func:mqtt_client_connect Line:989 Error: io_open failed
Error: Time:Tue Sep 25 06:25:37 2018 File:/usr/sdk/src/c/iothub_client/src/iothubtransport_mqtt_common.c Func:SendMqttConnectMsg Line:2037 failure connecting to address raspberrypi.
Error: Time:Tue Sep 25 06:25:53 2018 File:/usr/sdk/src/c/c-utility/adapters/socketio_berkeley.c Func:wait_for_connection Line:383 Failure: connect failure 111.
Error: Time:Tue Sep 25 06:25:53 2018 File:/usr/sdk/src/c/c-utility/adapters/socketio_berkeley.c Func:socketio_open Line:767 wait_for_connection failed
Error: Time:Tue Sep 25 06:25:53 2018 File:/usr/sdk/src/c/c-utility/adapters/tlsio_openssl.c Func:on_underlying_io_open_complete Line:748 Invalid tlsio_state. Expected state is TLSIO_STATE_OPENING_UNDERLYING_IO.
Error: Time:Tue Sep 25 06:25:53 2018 File:/usr/sdk/src/c/c-utility/adapters/tlsio_openssl.c Func:tlsio_openssl_open Line:1246 Failed opening the underlying I/O.
Error: Time:Tue Sep 25 06:25:53 2018 File:/usr/sdk/src/c/umqtt/src/mqtt_client.c Func:mqtt_client_connect Line:989 Error: io_open failed
Error: Time:Tue Sep 25 06:25:53 2018 File:/usr/sdk/src/c/iothub_client/src/iothubtransport_mqtt_common.c Func:SendMqttConnectMsg Line:2037 failure connecting to address raspberrypi.

[x] I also tried by setting the Environment variable "OptimizeForPerformance" to "false" for the EdgeHub and still facing the same issue. Please let me know what am I doing wrong or anything has been changed from your side as soon as possible.

cxp in-progress iot-edgsvc product-issue triaged

Source

SarithaMaran

Most helpful comment

@sergaz-msft @MarileeTurscak-MSFT
The issue was resolved by setting the Environment variable "OptimizeForPerformance" to "false" for the EdgeHub as provided in the troubleshooting section of the documentation. Previously the variable was not actually set (I added on portal but it was not reflected in the edgeHub module), but on re-pull of edgeHub it started working.
Thanks!

SarithaMaran on 26 Sep 2018

🎉3

All 3 comments

@SarithaMaran
Thanks for your feedback! We will investigate and update as appropriate.

MarileeTurscak-MSFT on 25 Sep 2018

SarithaMaran on 26 Sep 2018

🎉3

Thank you for letting us know the resolution for this @SarithaMaran :)!

We will now proceed to close this thread. If there are further questions regarding this matter, please tag me in your reply. We will gladly continue the discussion and we will reopen the issue.