azure-iot-sdk-python icon indicating copy to clipboard operation
azure-iot-sdk-python copied to clipboard

Published 20 hours ago • verified publisher icon Azure

Connecting to EdgeHub fails after several successful messages

Open pebneter opened this issue 3 years ago • 10 comments

  • OS and version used: Windows 11, 21H2 (OS Build 22000.493)
  • Python version: Python 3.10.2
  • pip version: pip 22.0.4
  • list of installed packages:
Package                    Version
-------------------------- ---------
altgraph                   0.17.2
applicationinsights        0.11.10
atomicwrites               1.4.0
attrs                      21.4.0
azure-iot-device           2.11.0
azure-iot-edge-runtime-ctl 1.0.0rc17
bcrypt                     3.2.0
cached-property            1.5.2
certifi                    2021.10.8
cffi                       1.15.0
chardet                    3.0.4
charset-normalizer         2.0.11
click                      8.0.3
colorama                   0.4.4
cryptography               36.0.1
decorator                  5.1.1
deprecation                2.1.0
docker                     2.6.0
docker-compose             1.24.0
docker-pycreds             0.4.0
dockerpty                  0.4.1
docopt                     0.6.2
future                     0.18.2
idna                       2.7
iniconfig                  1.1.1
iotedgehubdev              0.11.1
janus                      1.0.0
jsonpath-rw                1.4.0
jsonschema                 2.6.0
packaging                  21.3
paho-mqtt                  1.6.1
paramiko                   2.9.2
pefile                     2021.9.3
pip                        22.0.4
pluggy                     1.0.0
ply                        3.11
psutil                     5.9.0
py                         1.11.0
pycparser                  2.21
pyinstaller                4.9
pyinstaller-hooks-contrib  2022.2
PyNaCl                     1.5.0
pyOpenSSL                  21.0.0
pyparsing                  3.0.7
pypiwin32                  223
PySocks                    1.7.1
pytest                     7.0.1
python-dotenv              0.19.2
python-slugify             6.1.1
pywin32                    303
pywin32-ctypes             0.2.0
PyYAML                     4.2b4
requests                   2.27.1
requests-unixsocket        0.3.0
setuptools                 60.5.0
six                        1.16.0
text-unidecode             1.3
texttable                  0.9.1
tomli                      2.0.1
typing_extensions          4.0.1
urllib3                    1.26.8
websocket-client           0.59.0
wheel                      0.37.1
  • cloned repo: (https://github.com/Azure/azure-iot-sdk-python/blob/main/azure-iot-device/samples/simple_send_message.py)

Context

  • Azure IoT Hub
  • Azure IoT Edge device
    • Ubuntu 20.04.4 LTS
    • IoT Edge version 1.2.9
    • Symmetric Key Authentication
    • Installed certificates to enable communication with IoT device
  • Azure IoT device
    • Python on Windows
    • Symmetric Key Autenthication
    • Uses MQTT over WS

This is new issue, branching off from this one: https://github.com/Azure/azure-iot-sdk-python/issues/990#issuecomment-1112724888

Current behaviour

I'm using the sample here to simulate an IoT device on the windows machine, with only the connection string and logging setup changed: https://github.com/Azure/azure-iot-sdk-python/blob/main/azure-iot-device/samples/simple_send_message.py I can run the script and send a message successfully. I can do this several times (the number varies between 3 and 7 or 8 successful attempts). After that, the script cannot connect anymore.

What I'm also observing, but I'm not sure if it is the same issue: I have another script that sends trivial messages through the same Edge Hub. It runs fine for several hours, but stops working without warning. I have modified it that it restarts on exceptions, and usually the messages can get through to the hub after several hours of downtime without.

I did setup a completely new edgeHub to see if it is an issue with the old Edge device, but the error also happens with the new one.

Expected behaviour

I can run the script successfully an unlimited number of time

Evidence

Python logs

Logfile of the device client with the last successful connect (ends at Client shutdown complete) and the subscequent failing connect attempt.


2022-05-03 08:59:20,223 [DEBUG] Using proactor: IocpProactor
2022-05-03 08:59:20,224 [DEBUG] Starting run_op in pipeline thread
2022-05-03 08:59:20,225 [DEBUG] Creating pipeline executor
2022-05-03 08:59:20,226 [DEBUG] Gateway Hostname Present. Setting Hostname to: [hidden hostname]
2022-05-03 08:59:20,226 [DEBUG] HTTPTransportStage(InitializePipelineOperation): got connection args
2022-05-03 08:59:20,226 [DEBUG] creating a SSL context
2022-05-03 08:59:20,240 [DEBUG] InitializePipelineOperation: completing without error
2022-05-03 08:59:20,240 [DEBUG] Starting <azure.iot.device.common.evented_callback.EventedCallback object at 0x000001A45D919600> in callback thread
2022-05-03 08:59:20,240 [DEBUG] Creating callback executor
2022-05-03 08:59:20,241 [DEBUG] Callback completed with result None
2022-05-03 08:59:20,241 [DEBUG] Starting run_op in pipeline thread
2022-05-03 08:59:20,241 [DEBUG] SasTokenStage: Scheduling automatic SAS Token renewal at epoch time: 1651564640
2022-05-03 08:59:20,242 [DEBUG] Gateway Hostname Present. Setting Hostname to: [hidden hostname]
2022-05-03 08:59:20,242 [DEBUG] MQTTTransportStage(InitializePipelineOperation): got connection args
2022-05-03 08:59:20,242 [DEBUG] creating mqtt client
2022-05-03 08:59:20,242 [INFO] Creating client for connecting using MQTT over TCP
2022-05-03 08:59:20,242 [DEBUG] creating a SSL context
2022-05-03 08:59:20,243 [DEBUG] configuring SSL context with default certs
2022-05-03 08:59:20,251 [DEBUG] Created MQTT protocol client, assigned callbacks
2022-05-03 08:59:20,252 [DEBUG] InitializePipelineOperation: completing without error
2022-05-03 08:59:20,252 [DEBUG] Starting <azure.iot.device.common.evented_callback.EventedCallback object at 0x000001A45D91A4D0> in callback thread
2022-05-03 08:59:20,252 [DEBUG] Callback completed with result None
2022-05-03 08:59:20,252 [DEBUG] Creating new event loop - CLIENT_INTERNAL_LOOP
2022-05-03 08:59:20,252 [DEBUG] Using proactor: IocpProactor
2022-05-03 08:59:20,255 [INFO] Connecting to Hub...
2022-05-03 08:59:20,256 [DEBUG] Starting ConnectOperation on the pipeline
2022-05-03 08:59:20,256 [DEBUG] Starting run_op in pipeline thread
2022-05-03 08:59:20,256 [DEBUG] ReconnectStage(ConnectOperation): State changes DISCONNECTED -> CONNECTING. Sending op down
2022-05-03 08:59:20,256 [DEBUG] ConnectionLockStage(ConnectOperation): blocking
2022-05-03 08:59:20,256 [DEBUG] MQTTTransportStage(ConnectOperation): connecting
2022-05-03 08:59:20,256 [DEBUG] MQTTTransportStage(ConnectOperation): Starting watchdog
2022-05-03 08:59:20,257 [DEBUG] connecting to mqtt broker
2022-05-03 08:59:20,257 [INFO] Connect using port 8883 (TCP)
2022-05-03 08:59:20,347 [DEBUG] Sending CONNECT (u1, p1, wr0, wq0, wf0, c0, k60) client_id=b'python-test-device'
2022-05-03 08:59:20,347 [DEBUG] _mqtt_client.connect returned rc=0
2022-05-03 08:59:20,354 [DEBUG] Received CONNACK (0, 0)
2022-05-03 08:59:20,354 [INFO] connected with result code: 0
2022-05-03 08:59:20,354 [DEBUG] Starting _on_mqtt_connected in pipeline thread
2022-05-03 08:59:20,354 [INFO] _on_mqtt_connected called
2022-05-03 08:59:20,354 [DEBUG] ReconnectStage(ConnectedEvent): State changes CONNECTING -> CONNECTED. Connection established
2022-05-03 08:59:20,354 [DEBUG] PipelineRootStage: ConnectedEvent received. Calling on_connected_handler
2022-05-03 08:59:20,354 [DEBUG] Starting _on_connected in callback thread
2022-05-03 08:59:20,354 [DEBUG] MQTTTransportStage: completing connect op
2022-05-03 08:59:20,355 [INFO] Connection State - Connected
2022-05-03 08:59:20,355 [DEBUG] MQTTTransportStage(ConnectOperation): cancelling watchdog
2022-05-03 08:59:20,355 [DEBUG] ConnectOperation: completing without error
2022-05-03 08:59:20,355 [DEBUG] ConnectionLockStage(ConnectOperation): op succeeded.  Unblocking queue
2022-05-03 08:59:20,355 [DEBUG] ConnectionLockStage(ConnectOperation): unblocking and releasing queued ops.
2022-05-03 08:59:20,355 [DEBUG] ConnectionLockStage(ConnectOperation): processing 0 items in queue for error=None
2022-05-03 08:59:20,355 [DEBUG] Starting on_complete in callback thread
2022-05-03 08:59:20,356 [DEBUG] Callback completed with result None
2022-05-03 08:59:20,356 [INFO] Successfully connected to Hub
2022-05-03 08:59:20,356 [INFO] Sending message to Hub...
2022-05-03 08:59:20,357 [DEBUG] Starting SendD2CMessageOperation on the pipeline
2022-05-03 08:59:20,357 [DEBUG] Starting run_op in pipeline thread
2022-05-03 08:59:20,357 [DEBUG] SendD2CMessageOperation: creating worker op of type MQTTPublishOperation
2022-05-03 08:59:20,357 [DEBUG] MQTTTransportStage(MQTTPublishOperation): publishing on devices/python-test-device/messages/events/
2022-05-03 08:59:20,357 [INFO] publishing on devices/python-test-device/messages/events/
2022-05-03 08:59:20,358 [DEBUG] Sending PUBLISH (d0, q1, r0, m1), 'b'devices/python-test-device/messages/events/'', ... (36 bytes)
2022-05-03 08:59:20,358 [DEBUG] _mqtt_client.publish returned rc=0
2022-05-03 08:59:20,359 [DEBUG] Waiting for response on MID: 1
2022-05-03 08:59:20,364 [DEBUG] Received PUBACK (Mid: 1)
2022-05-03 08:59:20,364 [INFO] payload published for 1
2022-05-03 08:59:20,364 [DEBUG] Response received for recognized MID: 1 - triggering callback
2022-05-03 08:59:20,364 [DEBUG] Starting on_complete in pipeline thread
2022-05-03 08:59:20,364 [DEBUG] MQTTTransportStage(MQTTPublishOperation): PUBACK received. completing op.
2022-05-03 08:59:20,364 [DEBUG] MQTTPublishOperation: completing without error
2022-05-03 08:59:20,364 [DEBUG] SendD2CMessageOperation: Worker op (MQTTPublishOperation) has been completed
2022-05-03 08:59:20,364 [DEBUG] SendD2CMessageOperation: completing without error
2022-05-03 08:59:20,364 [DEBUG] Starting on_complete in callback thread
2022-05-03 08:59:20,365 [DEBUG] Callback completed with result None
2022-05-03 08:59:20,365 [INFO] Successfully sent message to Hub
2022-05-03 08:59:20,366 [INFO] Initiating client shutdown
2022-05-03 08:59:20,366 [INFO] Disconnecting from Hub...
2022-05-03 08:59:20,366 [DEBUG] Executing initial disconnect
2022-05-03 08:59:20,366 [DEBUG] Starting DisconnectOperation on the pipeline
2022-05-03 08:59:20,366 [DEBUG] Starting run_op in pipeline thread
2022-05-03 08:59:20,366 [DEBUG] ReconnectStage(DisconnectOperation): State changes CONNECTED -> DISCONNECTING. Sending op down.
2022-05-03 08:59:20,367 [DEBUG] ConnectionLockStage(DisconnectOperation): blocking
2022-05-03 08:59:20,367 [DEBUG] MQTTTransportStage(DisconnectOperation): disconnecting
2022-05-03 08:59:20,367 [INFO] disconnecting MQTT client
2022-05-03 08:59:20,367 [DEBUG] Sending DISCONNECT
2022-05-03 08:59:20,367 [INFO] disconnected with result code: 0
2022-05-03 08:59:20,367 [DEBUG] Starting _on_mqtt_disconnected in pipeline thread
2022-05-03 08:59:20,368 [DEBUG] _mqtt_client.disconnect returned rc=0
2022-05-03 08:59:20,368 [DEBUG] Cancelling all pending operations
2022-05-03 08:59:20,368 [INFO] MQTTTransportStage: _on_mqtt_disconnect called
2022-05-03 08:59:20,368 [DEBUG] ReconnectStage(DisconnectedEvent): State changes DISCONNECTING -> DISCONNECTED. Not attempting to reconnect (User-initiated disconnect)
2022-05-03 08:59:20,369 [DEBUG] PipelineRootStage: DisconnectedEvent received. Calling on_disconnected_handler
2022-05-03 08:59:20,369 [DEBUG] Starting _on_disconnected in callback thread
2022-05-03 08:59:20,369 [DEBUG] MQTTTransportStage: Expected disconnect - completing pending disconnect op
2022-05-03 08:59:20,369 [INFO] Connection State - Disconnected
2022-05-03 08:59:20,369 [DEBUG] DisconnectOperation: completing without error
2022-05-03 08:59:20,369 [INFO] Cleared all pending method requests due to disconnect
2022-05-03 08:59:20,369 [DEBUG] ConnectionLockStage(DisconnectOperation): op succeeded.  Unblocking queue
2022-05-03 08:59:20,370 [DEBUG] ConnectionLockStage(DisconnectOperation): unblocking and releasing queued ops.
2022-05-03 08:59:20,370 [DEBUG] ConnectionLockStage(DisconnectOperation): processing 0 items in queue for error=None
2022-05-03 08:59:20,370 [DEBUG] Starting on_complete in callback thread
2022-05-03 08:59:20,370 [DEBUG] Callback completed with result None
2022-05-03 08:59:20,370 [DEBUG] Successfully executed initial disconnect
2022-05-03 08:59:20,370 [DEBUG] Stopping handlers...
2022-05-03 08:59:20,370 [DEBUG] Successfully stopped handlers
2022-05-03 08:59:20,370 [DEBUG] Executing secondary disconnect...
2022-05-03 08:59:20,371 [DEBUG] Starting DisconnectOperation on the pipeline
2022-05-03 08:59:20,371 [DEBUG] Starting run_op in pipeline thread
2022-05-03 08:59:20,371 [DEBUG] ReconnectStage(DisconnectOperation): State is already DISCONNECTED. Sending op down
2022-05-03 08:59:20,371 [INFO] ConnectionLockStage(DisconnectOperation): Transport is already disconnected.  Completing.
2022-05-03 08:59:20,371 [DEBUG] DisconnectOperation: completing without error
2022-05-03 08:59:20,371 [DEBUG] Starting on_complete in callback thread
2022-05-03 08:59:20,371 [DEBUG] Callback completed with result None
2022-05-03 08:59:20,372 [DEBUG] Successfully executed secondary disconnect
2022-05-03 08:59:20,372 [INFO] Successfully disconnected from Hub
2022-05-03 08:59:20,372 [DEBUG] Beginning pipeline shutdown operation
2022-05-03 08:59:20,372 [DEBUG] Commencing shutdown of pipeline
2022-05-03 08:59:20,372 [DEBUG] Starting run_op in pipeline thread
2022-05-03 08:59:20,372 [DEBUG] Cancelling SAS Token update alarm
2022-05-03 08:59:20,373 [INFO] Forcing paho disconnect to prevent it from automatically reconnecting
2022-05-03 08:59:20,373 [DEBUG] Done forcing paho disconnect
2022-05-03 08:59:20,373 [DEBUG] Cancelling all pending operations
2022-05-03 08:59:20,373 [DEBUG] ShutdownPipelineOperation: completing without error
2022-05-03 08:59:20,373 [DEBUG] Starting on_complete in callback thread
2022-05-03 08:59:20,373 [DEBUG] Callback completed with result None
2022-05-03 08:59:20,374 [DEBUG] Completed pipeline shutdown operation
2022-05-03 08:59:20,374 [INFO] Client shutdown complete
2022-05-03 08:59:24,422 [DEBUG] Using proactor: IocpProactor
2022-05-03 08:59:24,422 [DEBUG] Starting run_op in pipeline thread
2022-05-03 08:59:24,422 [DEBUG] Creating pipeline executor
2022-05-03 08:59:24,422 [DEBUG] Gateway Hostname Present. Setting Hostname to: [hidden hostname]
2022-05-03 08:59:24,422 [DEBUG] HTTPTransportStage(InitializePipelineOperation): got connection args
2022-05-03 08:59:24,422 [DEBUG] creating a SSL context
2022-05-03 08:59:24,444 [DEBUG] InitializePipelineOperation: completing without error
2022-05-03 08:59:24,444 [DEBUG] Starting <azure.iot.device.common.evented_callback.EventedCallback object at 0x000001D662119600> in callback thread
2022-05-03 08:59:24,444 [DEBUG] Creating callback executor
2022-05-03 08:59:24,444 [DEBUG] Callback completed with result None
2022-05-03 08:59:24,445 [DEBUG] Starting run_op in pipeline thread
2022-05-03 08:59:24,445 [DEBUG] SasTokenStage: Scheduling automatic SAS Token renewal at epoch time: 1651564644
2022-05-03 08:59:24,446 [DEBUG] Gateway Hostname Present. Setting Hostname to: [hidden hostname]
2022-05-03 08:59:24,446 [DEBUG] MQTTTransportStage(InitializePipelineOperation): got connection args
2022-05-03 08:59:24,446 [DEBUG] creating mqtt client
2022-05-03 08:59:24,446 [INFO] Creating client for connecting using MQTT over TCP
2022-05-03 08:59:24,446 [DEBUG] creating a SSL context
2022-05-03 08:59:24,446 [DEBUG] configuring SSL context with default certs
2022-05-03 08:59:24,454 [DEBUG] Created MQTT protocol client, assigned callbacks
2022-05-03 08:59:24,454 [DEBUG] InitializePipelineOperation: completing without error
2022-05-03 08:59:24,454 [DEBUG] Starting <azure.iot.device.common.evented_callback.EventedCallback object at 0x000001D66211A4D0> in callback thread
2022-05-03 08:59:24,454 [DEBUG] Callback completed with result None
2022-05-03 08:59:24,455 [DEBUG] Creating new event loop - CLIENT_INTERNAL_LOOP
2022-05-03 08:59:24,455 [DEBUG] Using proactor: IocpProactor
2022-05-03 08:59:24,457 [INFO] Connecting to Hub...
2022-05-03 08:59:24,458 [DEBUG] Starting ConnectOperation on the pipeline
2022-05-03 08:59:24,458 [DEBUG] Starting run_op in pipeline thread
2022-05-03 08:59:24,458 [DEBUG] ReconnectStage(ConnectOperation): State changes DISCONNECTED -> CONNECTING. Sending op down
2022-05-03 08:59:24,458 [DEBUG] ConnectionLockStage(ConnectOperation): blocking
2022-05-03 08:59:24,459 [DEBUG] MQTTTransportStage(ConnectOperation): connecting
2022-05-03 08:59:24,459 [DEBUG] MQTTTransportStage(ConnectOperation): Starting watchdog
2022-05-03 08:59:24,459 [DEBUG] connecting to mqtt broker
2022-05-03 08:59:24,459 [INFO] Connect using port 8883 (TCP)
2022-05-03 09:00:24,460 [DEBUG] Starting watchdog_function in pipeline thread
2022-05-03 09:00:24,476 [INFO] Forcing paho disconnect to prevent it from automatically reconnecting
2022-05-03 09:00:24,476 [DEBUG] Done forcing paho disconnect
2022-05-03 09:00:24,476 [INFO] transport.connect raised error
2022-05-03 09:00:24,479 [INFO] Traceback (most recent call last):
  File "C:\Users\pebneter\AppData\Local\Programs\Python\Python310\lib\site-packages\azure\iot\device\common\mqtt_transport.py", line 390, in connect
    rc = self._mqtt_client.connect(
  File "C:\Users\pebneter\AppData\Local\Programs\Python\Python310\lib\site-packages\paho\mqtt\client.py", line 914, in connect
    return self.reconnect()
  File "C:\Users\pebneter\AppData\Local\Programs\Python\Python310\lib\site-packages\paho\mqtt\client.py", line 1073, in reconnect
    sock.do_handshake()
  File "C:\Users\pebneter\AppData\Local\Programs\Python\Python310\lib\ssl.py", line 1341, in do_handshake
    self._sslobj.do_handshake()
TimeoutError: _ssl.c:980: The handshake operation timed out

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "C:\Users\pebneter\AppData\Local\Programs\Python\Python310\lib\site-packages\azure\iot\device\common\pipeline\pipeline_stages_mqtt.py", line 189, in _run_op
    self.transport.connect(password=password)
  File "C:\Users\pebneter\AppData\Local\Programs\Python\Python310\lib\site-packages\azure\iot\device\common\mqtt_transport.py", line 413, in connect
    raise exceptions.ConnectionFailedError() from e
azure.iot.device.common.transport_exceptions.ConnectionFailedError

2022-05-03 09:00:24,479 [DEBUG] MQTTTransportStage(ConnectOperation): cancelling watchdog
2022-05-03 09:00:24,479 [DEBUG] ConnectOperation: completing with error 
2022-05-03 09:00:24,479 [DEBUG] ConnectionLockStage(ConnectOperation): op failed.  Unblocking queue with error: 
2022-05-03 09:00:24,479 [DEBUG] ConnectionLockStage(ConnectOperation): unblocking and releasing queued ops.
2022-05-03 09:00:24,479 [DEBUG] ConnectionLockStage(ConnectOperation): processing 0 items in queue for error=
2022-05-03 09:00:24,479 [DEBUG] ReconnectStage(ConnectOperation): failed, state change CONNECTING -> DISCONNECTED
2022-05-03 09:00:24,479 [DEBUG] Starting on_complete in callback thread
2022-05-03 09:00:24,479 [DEBUG] Connection watchdog expired, but pending op is not the same op
2022-05-03 09:00:24,480 [INFO] Callback completed with error 
2022-05-03 09:00:24,480 [INFO] ['azure.iot.device.common.transport_exceptions.ConnectionFailedError\n']

EdgeHub logs

It seems like the second attempt is not even showing up in these logs

<7> 2022-05-03 06:59:20.349 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.IDeviceScopeIdentitiesCache] - Getting service identity for python-test-device
<6> 2022-05-03 06:59:20.349 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Core.DeviceScopeAuthenticator] - Client python-test-device in device scope authenticated locally.
<7> 2022-05-03 06:59:20.349 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Authenticator] - Client python-test-device authentication successful
<6> 2022-05-03 06:59:20.350 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Mqtt.DeviceIdentityProvider] - Successfully generated identity for clientId python-test-device and username iothubrag4.azure-devices.net/python-test-device/?api-version=2019-10-01&DeviceClientType=azure-iot-device-iothub-py%2F2.11.0%283.10.2%3BWindows%2010.0.22000%3BAMD64%29
<6> 2022-05-03 06:59:20.352 +00:00 [INF] [EdgeHub] - ClientAuthenticated, python-test-device, 0b2c609d
<6> 2022-05-03 06:59:20.357 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Core.ConnectionManager] - New device connection for device python-test-device
<6> 2022-05-03 06:59:20.357 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Core.SubscriptionProcessor] - Client python-test-device connected to edgeHub, processing existing subscriptions.
<7> 2022-05-03 06:59:20.357 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.ConnectionManager] - Obtained cloud connection for device python-test-device
<7> 2022-05-03 06:59:20.357 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.EdgeHubConnection] - Updating device python-test-device connection status to Connected
<7> 2022-05-03 06:59:20.358 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Twin.StoringTwinManager] - Updating reported properties for connectivity-poc-edge-device-01/$edgeHub
<6> 2022-05-03 06:59:20.358 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Core.Device.DeviceMessageHandler] - Bind device proxy for device python-test-device
<6> 2022-05-03 06:59:20.358 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Mqtt.MessagingServiceClient] - Binding message channel for device Id python-test-device
<7> 2022-05-03 06:59:20.359 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Mqtt.MessageAddressConverter] - Message address devices/python-test-device/messages/events/ matches more than one topic. Picking first matching topic.
<7> 2022-05-03 06:59:20.359 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Mqtt.MessagingServiceClient] - Processing message for device Id python-test-device
<7> 2022-05-03 06:59:20.359 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.RoutingEdgeHub] - Received message from python-test-device
<7> 2022-05-03 06:59:20.360 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Getting next batch for endpoint iothub starting from 27220 with batch size 100.
<7> 2022-05-03 06:59:20.360 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Obtained next batch for endpoint iothub with batch size 1. Next start offset = 27221.
<7> 2022-05-03 06:59:20.361 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Getting next batch for endpoint iothub starting from 27221 with batch size 99.
<7> 2022-05-03 06:59:20.361 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Obtained next batch for endpoint iothub with batch size 0. Next start offset = 27221.
<7> 2022-05-03 06:59:20.361 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.CloudEndpoint] - Sending 1 message(s) upstream.
<7> 2022-05-03 06:59:20.361 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.CloudEndpoint] - Sending 1 message(s) upstream, divided into 1 groups. Processing maximum 10 groups in parallel.
<7> 2022-05-03 06:59:20.361 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.ConnectionManager] - Obtained cloud connection for device python-test-device
<7> 2022-05-03 06:59:20.362 +00:00 [DBG] [DotNetty.Handlers.Logging.LoggingHandler] - [id: 0x5c8e98a1, [::ffff:172.18.0.3]:39778 => [::ffff:40.113.176.174]:8883] WRITE: PublishPacket[Type=PUBLISH, QualityOfService=AtLeastOnce, Duplicate=False, Retain=False], 36B
         +-------------------------------------------------+
         |  0  1  2  3  4  5  6  7  8  9  a  b  c  d  e  f |
+--------+-------------------------------------------------+----------------+
|100000000| 54 68 69 73 20 69 73 20 61 20 6D 65 73 73 61 67 |This is a messag|
|100000010| 65 20 74 68 61 74 20 69 73 20 62 65 69 6E 67 20 |e that is being |
|100000020| 73 65 6E 74                                     |sent            |
+--------+-------------------------------------------------+----------------+
<7> 2022-05-03 06:59:20.362 +00:00 [DBG] [DotNetty.Handlers.Logging.LoggingHandler] - [id: 0x5c8e98a1, [::ffff:172.18.0.3]:39778 => [::ffff:40.113.176.174]:8883] FLUSH
<7> 2022-05-03 06:59:20.362 +00:00 [DBG] [DotNetty.Handlers.Logging.LoggingHandler] - [id: 0x5c8e98a1, [::ffff:172.18.0.3]:39778 => [::ffff:40.113.176.174]:8883] FLUSH
<7> 2022-05-03 06:59:20.362 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Routing.CloudEndpoint] - Finished processing messages to upstream
<6> 2022-05-03 06:59:20.367 +00:00 [INF] [EdgeHub] - Closing connection for device: python-test-device, ,
<6> 2022-05-03 06:59:20.368 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Mqtt.MessagingServiceClient] - Disposing MessagingServiceClient for device Id python-test-device because of exception -
<6> 2022-05-03 06:59:20.368 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Mqtt.DeviceProxy] - Setting device proxy inactive for device Id python-test-device
<6> 2022-05-03 06:59:20.368 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Core.ConnectionManager] - Removing device connection for device python-test-device with removeCloudConnection flag 'True'.
<7> 2022-05-03 06:59:20.368 +00:00 [DBG] [DotNetty.Handlers.Logging.LoggingHandler] - [id: 0x5c8e98a1, [::ffff:172.18.0.3]:39778 => [::ffff:40.113.176.174]:8883] WRITE: DisconnectPacket[Type=DISCONNECT, QualityOfService=AtMostOnce, Duplicate=False, Retain=False]
<7> 2022-05-03 06:59:20.368 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ConnectivityAwareClient] - Received connection status changed callback with connection status Disabled and reason Client_Close for python-test-device
<7> 2022-05-03 06:59:20.368 +00:00 [DBG] [DotNetty.Handlers.Logging.LoggingHandler] - [id: 0x5c8e98a1, [::ffff:172.18.0.3]:39778 => [::ffff:40.113.176.174]:8883] FLUSH
<7> 2022-05-03 06:59:20.485 +00:00 [DBG] [DotNetty.Handlers.Logging.LoggingHandler] - [id: 0x5c8e98a1, [::ffff:172.18.0.3]:39778 => [::ffff:40.113.176.174]:8883] RECEIVED_COMPLETE
<7> 2022-05-03 06:59:20.485 +00:00 [DBG] [DotNetty.Handlers.Logging.LoggingHandler] - [id: 0x5c8e98a1, [::ffff:172.18.0.3]:39778 => [::ffff:40.113.176.174]:8883] READ
<7> 2022-05-03 06:59:20.485 +00:00 [DBG] [DotNetty.Handlers.Logging.LoggingHandler] - [id: 0x5c8e98a1, [::ffff:172.18.0.3]:39778 => [::ffff:40.113.176.174]:8883] READ
<7> 2022-05-03 06:59:20.486 +00:00 [DBG] [DotNetty.Handlers.Logging.LoggingHandler] - [id: 0x5c8e98a1, [::ffff:172.18.0.3]:39778 :> [::ffff:40.113.176.174]:8883] INACTIVE
<7> 2022-05-03 06:59:20.486 +00:00 [DBG] [DotNetty.Handlers.Logging.LoggingHandler] - [id: 0x5c8e98a1, [::ffff:172.18.0.3]:39778 :> [::ffff:40.113.176.174]:8883] CLOSE
<7> 2022-05-03 06:59:20.486 +00:00 [DBG] [DotNetty.Handlers.Logging.LoggingHandler] - [id: 0x5c8e98a1, [::ffff:172.18.0.3]:39778 :> [::ffff:40.113.176.174]:8883] UNREGISTERED
<7> 2022-05-03 06:59:20.489 +00:00 [DBG] [DotNetty.Handlers.Logging.LoggingHandler] - [id: 0x5c8e98a1, [::ffff:172.18.0.3]:39778 :> [::ffff:40.113.176.174]:8883] HANDLER_REMOVED
<7> 2022-05-03 06:59:21.367 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ConnectivityAwareClient] - Operation SendEventAsync failed for python-test-device
System.InvalidOperationException: Invalid transport state: Closed
   at Microsoft.Azure.Devices.Client.Transport.Mqtt.MqttTransportHandler.EnsureValidState(Boolean throwIfNotOpen)
   at Microsoft.Azure.Devices.Client.Transport.Mqtt.MqttTransportHandler.SendEventAsync(Message message, CancellationToken cancellationToken)
   at Microsoft.Azure.Devices.Client.Transport.ErrorDelegatingHandler.<>c__DisplayClass27_0.<<ExecuteWithErrorHandlingAsync>b__0>d.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at Microsoft.Azure.Devices.Client.Transport.ErrorDelegatingHandler.ExecuteWithErrorHandlingAsync[T](Func`1 asyncOperation)
   at Microsoft.Azure.Devices.Client.Transport.RetryDelegatingHandler.<>c__DisplayClass15_0.<<SendEventAsync>b__0>d.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at Microsoft.Azure.Devices.Client.Transport.RetryDelegatingHandler.SendEventAsync(Message message, CancellationToken cancellationToken)
   at Microsoft.Azure.Devices.Client.InternalClient.SendEventAsync(Message message)
   at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ConnectivityAwareClient.<>c__DisplayClass30_0.<<InvokeFunc>b__0>d.MoveNext() in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/ConnectivityAwareClient.cs:line 194
--- 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, Boolean useForConnectivityCheck) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/ConnectivityAwareClient.cs:line 145
<7> 2022-05-03 06:59:21.377 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudProxy] - Error sending message for python-test-device in cloud proxy 26e74931-94f4-47cf-b0f6-f8a0d98bdb0d
System.InvalidOperationException: Invalid transport state: Closed
   at Microsoft.Azure.Devices.Client.Transport.Mqtt.MqttTransportHandler.EnsureValidState(Boolean throwIfNotOpen)
   at Microsoft.Azure.Devices.Client.Transport.Mqtt.MqttTransportHandler.SendEventAsync(Message message, CancellationToken cancellationToken)
   at Microsoft.Azure.Devices.Client.Transport.ErrorDelegatingHandler.<>c__DisplayClass27_0.<<ExecuteWithErrorHandlingAsync>b__0>d.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at Microsoft.Azure.Devices.Client.Transport.ErrorDelegatingHandler.ExecuteWithErrorHandlingAsync[T](Func`1 asyncOperation)
   at Microsoft.Azure.Devices.Client.Transport.RetryDelegatingHandler.<>c__DisplayClass15_0.<<SendEventAsync>b__0>d.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at Microsoft.Azure.Devices.Client.Transport.RetryDelegatingHandler.SendEventAsync(Message message, CancellationToken cancellationToken)
   at Microsoft.Azure.Devices.Client.InternalClient.SendEventAsync(Message message)
   at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ConnectivityAwareClient.<>c__DisplayClass30_0.<<InvokeFunc>b__0>d.MoveNext() in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/ConnectivityAwareClient.cs:line 194
--- 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, Boolean useForConnectivityCheck) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/ConnectivityAwareClient.cs:line 145
   at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ConnectivityAwareClient.InvokeFunc[T](Func`1 func, String operation, Boolean useForConnectivityCheck) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/ConnectivityAwareClient.cs:line 181
   at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudProxy.SendMessageAsync(IMessage inputMessage) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/CloudProxy.cs:line 157
<6> 2022-05-03 06:59:21.379 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Core.Cloud.RetryingCloudProxy] - Retrying cloud proxy operation SendMessageAsync for python-test-device.
System.InvalidOperationException: Invalid transport state: Closed
   at Microsoft.Azure.Devices.Client.Transport.Mqtt.MqttTransportHandler.EnsureValidState(Boolean throwIfNotOpen)
   at Microsoft.Azure.Devices.Client.Transport.Mqtt.MqttTransportHandler.SendEventAsync(Message message, CancellationToken cancellationToken)
   at Microsoft.Azure.Devices.Client.Transport.ErrorDelegatingHandler.<>c__DisplayClass27_0.<<ExecuteWithErrorHandlingAsync>b__0>d.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at Microsoft.Azure.Devices.Client.Transport.ErrorDelegatingHandler.ExecuteWithErrorHandlingAsync[T](Func`1 asyncOperation)
   at Microsoft.Azure.Devices.Client.Transport.RetryDelegatingHandler.<>c__DisplayClass15_0.<<SendEventAsync>b__0>d.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at Microsoft.Azure.Devices.Client.Transport.RetryDelegatingHandler.SendEventAsync(Message message, CancellationToken cancellationToken)
   at Microsoft.Azure.Devices.Client.InternalClient.SendEventAsync(Message message)
   at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ConnectivityAwareClient.<>c__DisplayClass30_0.<<InvokeFunc>b__0>d.MoveNext() in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/ConnectivityAwareClient.cs:line 194
--- 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, Boolean useForConnectivityCheck) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/ConnectivityAwareClient.cs:line 145
   at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ConnectivityAwareClient.InvokeFunc[T](Func`1 func, String operation, Boolean useForConnectivityCheck) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/ConnectivityAwareClient.cs:line 181
   at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudProxy.SendMessageAsync(IMessage inputMessage) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/CloudProxy.cs:line 157
   at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudProxy.SendMessageAsync(IMessage inputMessage) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/CloudProxy.cs:line 165
   at Microsoft.Azure.Devices.Edge.Hub.Core.Cloud.RetryingCloudProxy.<>c__DisplayClass24_0.<<ExecuteOperation>b__0>d.MoveNext() in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.Core/cloud/RetryingCloudProxy.cs:line 64
--- End of stack trace from previous location where exception was thrown ---
   at Microsoft.Azure.Devices.Edge.Hub.Core.Cloud.RetryingCloudProxy.ExecuteOperation[T](Func`2 func, String operation) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.Core/cloud/RetryingCloudProxy.cs:line 76
<7> 2022-05-03 06:59:21.380 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Cloud.RetryingCloudProxy] - Getting new cloud proxy for client python-test-device since current cloud proxy is not active
<7> 2022-05-03 06:59:21.380 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.IDeviceScopeIdentitiesCache] - Getting service identity for python-test-device
<7> 2022-05-03 06:59:21.380 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudConnection] - Creating cloud connection for client python-test-device using EdgeHub credentials
<6> 2022-05-03 06:59:21.381 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudConnection] - Attempting to connect to IoT Hub for client python-test-device via MQTT...
<7> 2022-05-03 06:59:21.413 +00:00 [DBG] [DotNetty.Handlers.Logging.LoggingHandler] - [id: 0x1f6d6dcd] HANDLER_ADDED
<7> 2022-05-03 06:59:21.413 +00:00 [DBG] [DotNetty.Handlers.Logging.LoggingHandler] - [id: 0x1f6d6dcd] REGISTERED
<7> 2022-05-03 06:59:21.413 +00:00 [DBG] [DotNetty.Handlers.Logging.LoggingHandler] - [id: 0x1f6d6dcd] CONNECT: 40.113.176.174:8883
<7> 2022-05-03 06:59:21.437 +00:00 [DBG] [DotNetty.Handlers.Logging.LoggingHandler] - [id: 0x1f6d6dcd, [::ffff:172.18.0.3]:39780 => [::ffff:40.113.176.174]:8883] ACTIVE
<7> 2022-05-03 06:59:21.438 +00:00 [DBG] [DotNetty.Handlers.Logging.LoggingHandler] - [id: 0x1f6d6dcd, [::ffff:172.18.0.3]:39780 => [::ffff:40.113.176.174]:8883] WRITE: ConnectPacket[Type=CONNECT, QualityOfService=AtMostOnce, Duplicate=False, Retain=False]
<7> 2022-05-03 06:59:21.438 +00:00 [DBG] [DotNetty.Handlers.Logging.LoggingHandler] - [id: 0x1f6d6dcd, [::ffff:172.18.0.3]:39780 => [::ffff:40.113.176.174]:8883] FLUSH
<7> 2022-05-03 06:59:21.439 +00:00 [DBG] [DotNetty.Handlers.Logging.LoggingHandler] - [id: 0x1f6d6dcd, [::ffff:172.18.0.3]:39780 => [::ffff:40.113.176.174]:8883] READ
<7> 2022-05-03 06:59:21.467 +00:00 [DBG] [DotNetty.Handlers.Logging.LoggingHandler] - [id: 0x1f6d6dcd, [::ffff:172.18.0.3]:39780 => [::ffff:40.113.176.174]:8883] RECEIVED_COMPLETE
<7> 2022-05-03 06:59:21.467 +00:00 [DBG] [DotNetty.Handlers.Logging.LoggingHandler] - [id: 0x1f6d6dcd, [::ffff:172.18.0.3]:39780 => [::ffff:40.113.176.174]:8883] READ
<7> 2022-05-03 06:59:21.467 +00:00 [DBG] [DotNetty.Handlers.Logging.LoggingHandler] - [id: 0x1f6d6dcd, [::ffff:172.18.0.3]:39780 => [::ffff:40.113.176.174]:8883] READ
<7> 2022-05-03 06:59:21.468 +00:00 [DBG] [DotNetty.Handlers.Logging.LoggingHandler] - [id: 0x1f6d6dcd, [::ffff:172.18.0.3]:39780 => [::ffff:40.113.176.174]:8883] RECEIVED_COMPLETE
<7> 2022-05-03 06:59:21.468 +00:00 [DBG] [DotNetty.Handlers.Logging.LoggingHandler] - [id: 0x1f6d6dcd, [::ffff:172.18.0.3]:39780 => [::ffff:40.113.176.174]:8883] READ
<7> 2022-05-03 06:59:21.468 +00:00 [DBG] [DotNetty.Handlers.Logging.LoggingHandler] - [id: 0x1f6d6dcd, [::ffff:172.18.0.3]:39780 => [::ffff:40.113.176.174]:8883] READ
<7> 2022-05-03 06:59:21.494 +00:00 [DBG] [DotNetty.Handlers.Logging.LoggingHandler] - [id: 0x1f6d6dcd, [::ffff:172.18.0.3]:39780 => [::ffff:40.113.176.174]:8883] USER_EVENT: TlsHandshakeCompletionEvent(SUCCESS)
<7> 2022-05-03 06:59:21.496 +00:00 [DBG] [DotNetty.Handlers.Logging.LoggingHandler] - [id: 0x1f6d6dcd, [::ffff:172.18.0.3]:39780 => [::ffff:40.113.176.174]:8883] READ
<7> 2022-05-03 06:59:21.497 +00:00 [DBG] [DotNetty.Handlers.Logging.LoggingHandler] - [id: 0x1f6d6dcd, [::ffff:172.18.0.3]:39780 => [::ffff:40.113.176.174]:8883] RECEIVED_COMPLETE
<7> 2022-05-03 06:59:21.497 +00:00 [DBG] [DotNetty.Handlers.Logging.LoggingHandler] - [id: 0x1f6d6dcd, [::ffff:172.18.0.3]:39780 => [::ffff:40.113.176.174]:8883] READ
<7> 2022-05-03 06:59:21.497 +00:00 [DBG] [DotNetty.Handlers.Logging.LoggingHandler] - [id: 0x1f6d6dcd, [::ffff:172.18.0.3]:39780 => [::ffff:40.113.176.174]:8883] READ
<7> 2022-05-03 06:59:21.548 +00:00 [DBG] [DotNetty.Handlers.Logging.LoggingHandler] - [id: 0x1f6d6dcd, [::ffff:172.18.0.3]:39780 => [::ffff:40.113.176.174]:8883] RECEIVED: ConnAckPacket[Type=CONNACK, QualityOfService=AtMostOnce, Duplicate=False, Retain=False]
<7> 2022-05-03 06:59:21.549 +00:00 [DBG] [DotNetty.Handlers.Logging.LoggingHandler] - [id: 0x1f6d6dcd, [::ffff:172.18.0.3]:39780 => [::ffff:40.113.176.174]:8883] WRITE: SubscribePacket[Type=SUBSCRIBE, QualityOfService=AtLeastOnce, Duplicate=False, Retain=False]
<7> 2022-05-03 06:59:21.549 +00:00 [DBG] [DotNetty.Handlers.Logging.LoggingHandler] - [id: 0x1f6d6dcd, [::ffff:172.18.0.3]:39780 => [::ffff:40.113.176.174]:8883] FLUSH
<7> 2022-05-03 06:59:21.549 +00:00 [DBG] [DotNetty.Handlers.Logging.LoggingHandler] - [id: 0x1f6d6dcd, [::ffff:172.18.0.3]:39780 => [::ffff:40.113.176.174]:8883] RECEIVED_COMPLETE
<7> 2022-05-03 06:59:21.549 +00:00 [DBG] [DotNetty.Handlers.Logging.LoggingHandler] - [id: 0x1f6d6dcd, [::ffff:172.18.0.3]:39780 => [::ffff:40.113.176.174]:8883] READ
<7> 2022-05-03 06:59:21.549 +00:00 [DBG] [DotNetty.Handlers.Logging.LoggingHandler] - [id: 0x1f6d6dcd, [::ffff:172.18.0.3]:39780 => [::ffff:40.113.176.174]:8883] READ
<7> 2022-05-03 06:59:21.550 +00:00 [DBG] [DotNetty.Handlers.Logging.LoggingHandler] - [id: 0x1f6d6dcd, [::ffff:172.18.0.3]:39780 => [::ffff:40.113.176.174]:8883] WRITE: SubscribePacket[Type=SUBSCRIBE, QualityOfService=AtLeastOnce, Duplicate=False, Retain=False]
<7> 2022-05-03 06:59:21.550 +00:00 [DBG] [DotNetty.Handlers.Logging.LoggingHandler] - [id: 0x1f6d6dcd, [::ffff:172.18.0.3]:39780 => [::ffff:40.113.176.174]:8883] FLUSH
<7> 2022-05-03 06:59:21.587 +00:00 [DBG] [DotNetty.Handlers.Logging.LoggingHandler] - [id: 0x1f6d6dcd, [::ffff:172.18.0.3]:39780 => [::ffff:40.113.176.174]:8883] RECEIVED: SubAckPacket[Type=SUBACK, QualityOfService=AtMostOnce, Duplicate=False, Retain=False]
<7> 2022-05-03 06:59:21.587 +00:00 [DBG] [DotNetty.Handlers.Logging.LoggingHandler] - [id: 0x1f6d6dcd, [::ffff:172.18.0.3]:39780 => [::ffff:40.113.176.174]:8883] RECEIVED_COMPLETE
<7> 2022-05-03 06:59:21.587 +00:00 [DBG] [DotNetty.Handlers.Logging.LoggingHandler] - [id: 0x1f6d6dcd, [::ffff:172.18.0.3]:39780 => [::ffff:40.113.176.174]:8883] READ
<7> 2022-05-03 06:59:21.587 +00:00 [DBG] [DotNetty.Handlers.Logging.LoggingHandler] - [id: 0x1f6d6dcd, [::ffff:172.18.0.3]:39780 => [::ffff:40.113.176.174]:8883] READ
<7> 2022-05-03 06:59:21.600 +00:00 [DBG] [DotNetty.Handlers.Logging.LoggingHandler] - [id: 0x1f6d6dcd, [::ffff:172.18.0.3]:39780 => [::ffff:40.113.176.174]:8883] RECEIVED: SubAckPacket[Type=SUBACK, QualityOfService=AtMostOnce, Duplicate=False, Retain=False]
<7> 2022-05-03 06:59:21.600 +00:00 [DBG] [DotNetty.Handlers.Logging.LoggingHandler] - [id: 0x1f6d6dcd, [::ffff:172.18.0.3]:39780 => [::ffff:40.113.176.174]:8883] RECEIVED_COMPLETE
<7> 2022-05-03 06:59:21.600 +00:00 [DBG] [DotNetty.Handlers.Logging.LoggingHandler] - [id: 0x1f6d6dcd, [::ffff:172.18.0.3]:39780 => [::ffff:40.113.176.174]:8883] READ
<7> 2022-05-03 06:59:21.600 +00:00 [DBG] [DotNetty.Handlers.Logging.LoggingHandler] - [id: 0x1f6d6dcd, [::ffff:172.18.0.3]:39780 => [::ffff:40.113.176.174]:8883] READ
<7> 2022-05-03 06:59:21.601 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ConnectivityAwareClient] - Received connection status changed callback with connection status Connected and reason Connection_Ok for python-test-device
<7> 2022-05-03 06:59:21.601 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.DeviceConnectivityManager] - IotHub call succeeded
<6> 2022-05-03 06:59:21.605 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ConnectivityAwareClient] - Cloud connection for python-test-device is True
<6> 2022-05-03 06:59:21.605 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Core.ConnectionManager] - Connection status for python-test-device changed to ConnectionEstablished
<7> 2022-05-03 06:59:21.605 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.ConnectionManager] - Invoking cloud connection established event for python-test-device
<6> 2022-05-03 06:59:21.605 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Core.SubscriptionProcessor] - Client python-test-device connected to cloud, processing existing subscriptions.
<7> 2022-05-03 06:59:21.605 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ConnectivityAwareClient] - Operation OpenAsync succeeded for python-test-device
<6> 2022-05-03 06:59:21.605 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudConnection] - Created cloud proxy for client python-test-device via MQTT, with client operation timeout 20 seconds.
<6> 2022-05-03 06:59:21.606 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudProxy] - Initialized cloud proxy 6b39b089-3f50-4100-9593-738fbefdcf83 for python-test-device
<6> 2022-05-03 06:59:21.606 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudConnection] - Created cloud connection for client python-test-device
<7> 2022-05-03 06:59:21.606 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.ConnectionManager] - Obtained cloud connection for device python-test-device
<7> 2022-05-03 06:59:21.608 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.ConnectionManager] - Obtained cloud connection for device python-test-device
<7> 2022-05-03 06:59:21.608 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Cloud.RetryingCloudProxy] - Get new cloud proxy for client python-test-device
<7> 2022-05-03 06:59:21.613 +00:00 [DBG] [DotNetty.Handlers.Logging.LoggingHandler] - [id: 0x1f6d6dcd, [::ffff:172.18.0.3]:39780 => [::ffff:40.113.176.174]:8883] WRITE: PublishPacket[Type=PUBLISH, QualityOfService=AtLeastOnce, Duplicate=False, Retain=False], 36B
         +-------------------------------------------------+
         |  0  1  2  3  4  5  6  7  8  9  a  b  c  d  e  f |
+--------+-------------------------------------------------+----------------+
|100000000| 54 68 69 73 20 69 73 20 61 20 6D 65 73 73 61 67 |This is a messag|
|100000010| 65 20 74 68 61 74 20 69 73 20 62 65 69 6E 67 20 |e that is being |
|100000020| 73 65 6E 74                                     |sent            |
+--------+-------------------------------------------------+----------------+
<7> 2022-05-03 06:59:21.613 +00:00 [DBG] [DotNetty.Handlers.Logging.LoggingHandler] - [id: 0x1f6d6dcd, [::ffff:172.18.0.3]:39780 => [::ffff:40.113.176.174]:8883] FLUSH
<7> 2022-05-03 06:59:21.613 +00:00 [DBG] [DotNetty.Handlers.Logging.LoggingHandler] - [id: 0x1f6d6dcd, [::ffff:172.18.0.3]:39780 => [::ffff:40.113.176.174]:8883] FLUSH
<7> 2022-05-03 06:59:21.908 +00:00 [DBG] [DotNetty.Handlers.Logging.LoggingHandler] - [id: 0x1f6d6dcd, [::ffff:172.18.0.3]:39780 => [::ffff:40.113.176.174]:8883] RECEIVED: PubAckPacket[Type=PUBACK, QualityOfService=AtMostOnce, Duplicate=False, Retain=False]
<7> 2022-05-03 06:59:21.908 +00:00 [DBG] [DotNetty.Handlers.Logging.LoggingHandler] - [id: 0x1f6d6dcd, [::ffff:172.18.0.3]:39780 => [::ffff:40.113.176.174]:8883] RECEIVED_COMPLETE
<7> 2022-05-03 06:59:21.908 +00:00 [DBG] [DotNetty.Handlers.Logging.LoggingHandler] - [id: 0x1f6d6dcd, [::ffff:172.18.0.3]:39780 => [::ffff:40.113.176.174]:8883] READ
<7> 2022-05-03 06:59:21.908 +00:00 [DBG] [DotNetty.Handlers.Logging.LoggingHandler] - [id: 0x1f6d6dcd, [::ffff:172.18.0.3]:39780 => [::ffff:40.113.176.174]:8883] READ
<7> 2022-05-03 06:59:21.909 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.DeviceConnectivityManager] - IotHub call succeeded
<7> 2022-05-03 06:59:21.909 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ConnectivityAwareClient] - Operation SendEventAsync succeeded for python-test-device
<7> 2022-05-03 06:59:21.913 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudProxy] - Sending message for python-test-device
<7> 2022-05-03 06:59:21.914 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Getting next batch for endpoint iothub starting from 27221 with batch size 100.
<7> 2022-05-03 06:59:21.914 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Obtained next batch for endpoint iothub with batch size 0. Next start offset = 27221.
<7> 2022-05-03 06:59:26.124 +00:00 [DBG] [DotNetty.Handlers.Logging.LoggingHandler] - [id: 0x4597ef45, [::ffff:172.18.0.3]:39744 => [::ffff:40.113.176.174]:8883] WRITE: PingReqPacket[Type=PINGREQ, QualityOfService=AtMostOnce, Duplicate=False, Retain=False]
<7> 2022-05-03 06:59:26.124 +00:00 [DBG] [DotNetty.Handlers.Logging.LoggingHandler] - [id: 0x4597ef45, [::ffff:172.18.0.3]:39744 => [::ffff:40.113.176.174]:8883] FLUSH
<7> 2022-05-03 06:59:26.149 +00:00 [DBG] [DotNetty.Handlers.Logging.LoggingHandler] - [id: 0x4597ef45, [::ffff:172.18.0.3]:39744 => [::ffff:40.113.176.174]:8883] RECEIVED: PingRespPacket[Type=PINGRESP, QualityOfService=AtMostOnce, Duplicate=False, Retain=False]
<7> 2022-05-03 06:59:26.149 +00:00 [DBG] [DotNetty.Handlers.Logging.LoggingHandler] - [id: 0x4597ef45, [::ffff:172.18.0.3]:39744 => [::ffff:40.113.176.174]:8883] RECEIVED_COMPLETE
<7> 2022-05-03 06:59:26.149 +00:00 [DBG] [DotNetty.Handlers.Logging.LoggingHandler] - [id: 0x4597ef45, [::ffff:172.18.0.3]:39744 => [::ffff:40.113.176.174]:8883] READ
<7> 2022-05-03 06:59:26.149 +00:00 [DBG] [DotNetty.Handlers.Logging.LoggingHandler] - [id: 0x4597ef45, [::ffff:172.18.0.3]:39744 => [::ffff:40.113.176.174]:8883] READ
<7> 2022-05-03 06:59:31.912 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Getting next batch for endpoint iothub starting from 27221 with batch size 100.
<7> 2022-05-03 06:59:31.912 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Obtained next batch for endpoint iothub with batch size 0. Next start offset = 27221.
<7> 2022-05-03 06:59:41.915 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Getting next batch for endpoint iothub starting from 27221 with batch size 100.
<7> 2022-05-03 06:59:41.915 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Obtained next batch for endpoint iothub with batch size 0. Next start offset = 27221.
<7> 2022-05-03 06:59:51.918 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Getting next batch for endpoint iothub starting from 27221 with batch size 100.
<7> 2022-05-03 06:59:51.918 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Obtained next batch for endpoint iothub with batch size 0. Next start offset = 27221.
<7> 2022-05-03 07:00:01.920 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Getting next batch for endpoint iothub starting from 27221 with batch size 100.
<7> 2022-05-03 07:00:01.920 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Obtained next batch for endpoint iothub with batch size 0. Next start offset = 27221.
<7> 2022-05-03 07:00:11.918 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Getting next batch for endpoint iothub starting from 27221 with batch size 100.
<7> 2022-05-03 07:00:11.918 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Obtained next batch for endpoint iothub with batch size 0. Next start offset = 27221.
<7> 2022-05-03 07:00:21.922 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Getting next batch for endpoint iothub starting from 27221 with batch size 100.
<7> 2022-05-03 07:00:21.922 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Obtained next batch for endpoint iothub with batch size 0. Next start offset = 27221.
<7> 2022-05-03 07:00:31.921 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Getting next batch for endpoint iothub starting from 27221 with batch size 100.
<7> 2022-05-03 07:00:31.922 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.Core.Storage.MessageStore] - Obtained next batch for endpoint iothub with batch size 0. Next start offset = 27221.

pebneter avatar May 03 '22 07:05 pebneter

@pebneter

Can you post your script you're running that would generate those logs? Also, which version of EdgeHub are you running? 1.0, 1.1 or 1.2?

cartertinney avatar May 04 '22 00:05 cartertinney

Runtime version is 1.2.9 The script is from here: https://github.com/Azure/azure-iot-sdk-python/blob/main/azure-iot-device/samples/simple_send_message.py. Just set the logging level to debug, otherwise no change.

pebneter avatar May 04 '22 08:05 pebneter

@pebneter Could you try using EdgeHub 1.1? We've seen reports recently of issues with using 1.2 - still not sure why that might be, we're investigating, but in the meantime, could you try that and let us know if that resolves the issue?

cartertinney avatar May 06 '22 18:05 cartertinney

Ok, I will try with 1.1.

pebneter avatar May 13 '22 14:05 pebneter

Relates with: https://stackoverflow.com/questions/71767695/azure-iot-device-loosing-connection-to-transparent-edge-gateway-device

asergaz avatar May 16 '22 12:05 asergaz

I setup a new edge device using the runtime 1.1 and used it in the exact same setup as before the verion 1.2.9.

So far I have not been able to reproduce the error with this version. So this is a strong hint it is a bug in the runtime 1.2.x. I re-routed some other machines that run longer to use the 1.1 runtime device. I will report later how that evolves.

pebneter avatar May 17 '22 12:05 pebneter

Excellent. Thank you very much @pebneter. We will work on attempting to get to the bottom of why this issue is appearing in 1.2, but for now I would suggest sticking with 1.1. We will post an update here when we know more.

cartertinney avatar May 17 '22 16:05 cartertinney

A device connected to the Edge with runtime 1.1 has been running fine for 24 hours with no signs of issues.

pebneter avatar May 18 '22 09:05 pebneter

@pebneter, checking in, are you still functioning okay on 1.1?

cartertinney avatar May 24 '22 21:05 cartertinney

@cartertinney Yes has been working flawlessly since downgrading to 1.1

pebneter avatar May 25 '22 05:05 pebneter

Closing since 1.1 workaround is working (for now)

cartertinney avatar Aug 16 '22 18:08 cartertinney

The issue is for me still very relevant, because we want to move to version 1.3 of edgeHub. I did tests with a version 1.3, and the issue was still present.

pebneter avatar Aug 17 '22 06:08 pebneter

@pebneter - I'd recommend you moving to 1.4: https://github.com/Azure/azure-iotedge/releases/tag/1.4.0

@cartertinney - 1.1 is almost at the End of Life. The workaround isn't enough.

@jlian for visibility.

gauravIoTEdge avatar Sep 22 '22 22:09 gauravIoTEdge

You need to reopen this issue. Upgrading the platform to 1.4 will not solve the problem. I suspect that with the changes introduced in 1.2 (with the new identity service) something has corrupted the re-authentication flow between a python module and edgeHub.

@gauravIoTEdge and @jlian for comments please.

lucarv avatar Sep 28 '22 12:09 lucarv

Well, I agree we need to to get to the bottom of this.

Just to be clear though - my suggestion of upgrading to 1.4 [rather than 1.3] was a general one because that is our LTS support version.

gauravIoTEdge avatar Sep 28 '22 15:09 gauravIoTEdge

@damonbarry and @varunpuranik for visibility

gauravIoTEdge avatar Sep 28 '22 16:09 gauravIoTEdge

@pebneter - please open this issue on the iotedge repo: https://github.com/Azure/iotedge

We'll take a look.

gauravIoTEdge avatar Sep 28 '22 16:09 gauravIoTEdge

It might take a few days, but I will test with 1.4 and create one it the problem is still present.

pebneter avatar Sep 30 '22 13:09 pebneter

Hi there, so I made some tests with edge 1.4 and the situation has not improved. I can easily break the connectivity by starting/stopping my client script a couple of times. Doing the same with 1.1 does not trigger any issue. I will not create a new ticket immediately, but follow the open issues on https://github.com/Azure/iotedge

pebneter avatar Oct 06 '22 08:10 pebneter

@pebneter @varunpuranik @gauravIoTEdge What is the status of this issue? It is actually super easy to reproduce and I am surprised it has not been detected/fixed before, since we are already on edge 1.4 and this has been broken since 1.2

A module written in Python (latest, but I have tested with earlier versions too) will fail to renew the SAS token. If you want to reproduce, just create a module and let it run until the SAS token needs to be renewed. It will fail 100% of the time. Below is the flow on a simple python module created with VSC scaffolding with the addition of python logging:

DEBUG:azure.iot.device.common.pipeline.pipeline_thread:Starting renew_token in pipeline thread
INFO:azure.iot.device.common.pipeline.pipeline_stages_base:SasTokenStage: Renewing SAS Token...
DEBUG:urllib3.connectionpool:http://localhost:None "POST /modules/sample/genid/638010619771297413/sign?api-version=2022-08-03 HTTP/1.1" 200 57
INFO:azure.iot.device.common.pipeline.pipeline_stages_base:SasTokenStage: Starting reauthorization process for new SAS token
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:ConnectionStateStage(ReauthorizeConnectionOperation): State changes CONNECTED -> REAUTHORIZING. Sending op down.
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_mqtt:MQTTTransportStage(ReauthorizeConnectionOperation): reauthorizing. Will issue disconnect and then a connect
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_mqtt:MQTTTransportStage(DisconnectOperation): disconnecting
INFO:azure.iot.device.common.mqtt_transport:disconnecting MQTT client
DEBUG:paho:Sending DISCONNECT
INFO:azure.iot.device.common.mqtt_transport:disconnected with result code: 0
DEBUG:azure.iot.device.common.pipeline.pipeline_thread:Starting _on_mqtt_disconnected in pipeline thread
DEBUG:azure.iot.device.common.mqtt_transport:_mqtt_client.disconnect returned rc=0
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:Cancelling SAS Token update alarm
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:SasTokenStage: Scheduling automatic SAS Token renewal at epoch time: 1665475620
INFO:azure.iot.device.common.pipeline.pipeline_stages_mqtt:MQTTTransportStage: _on_mqtt_disconnect called
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:ConnectionStateStage(DisconnectedEvent): Not attempting to reconnect (Reauthorization in progress)
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:PipelineRootStage: DisconnectedEvent received. Calling on_disconnected_handler
DEBUG:azure.iot.device.common.pipeline.pipeline_thread:Starting _on_disconnected in callback thread
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_mqtt:MQTTTransportStage: Expected disconnect - completing pending disconnect op
DEBUG:azure.iot.device.common.pipeline.pipeline_ops_base:DisconnectOperation: completing without error
DEBUG:azure.iot.device.common.pipeline.pipeline_ops_base:ReauthorizeConnectionOperation: creating worker op of type ConnectOperation
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_mqtt:MQTTTransportStage(ConnectOperation): connecting
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_mqtt:MQTTTransportStage(ConnectOperation): Starting watchdog
INFO:azure.iot.device.iothub.abstract_clients:Connection State - Disconnected
INFO:azure.iot.device.iothub.abstract_clients:Cleared all pending method requests due to disconnect
DEBUG:azure.iot.device.common.mqtt_transport:connecting to mqtt broker
INFO:azure.iot.device.common.mqtt_transport:Connect using port 8883 (TCP)
DEBUG:azure.iot.device.common.pipeline.pipeline_thread:Starting watchdog_function in pipeline thread
INFO:azure.iot.device.common.mqtt_transport:Forcing paho disconnect to prevent it from automatically reconnecting
DEBUG:azure.iot.device.common.mqtt_transport:Done forcing paho disconnect
INFO:azure.iot.device.common.pipeline.pipeline_stages_mqtt:transport.connect raised error
INFO:azure.iot.device.common.pipeline.pipeline_stages_mqtt:Traceback (most recent call last):
  File "/usr/local/lib/python3.7/site-packages/azure/iot/device/common/mqtt_transport.py", line 397, in connect
    host=self._hostname, port=8883, keepalive=self._keep_alive
  File "/usr/local/lib/python3.7/site-packages/paho/mqtt/client.py", line 914, in connect
    return self.reconnect()
  File "/usr/local/lib/python3.7/site-packages/paho/mqtt/client.py", line 1073, in reconnect
    sock.do_handshake()
  File "/usr/local/lib/python3.7/ssl.py", line 1139, in do_handshake
    self._sslobj.do_handshake()
socket.timeout: _ssl.c:1074: The handshake operation timed out

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "/usr/local/lib/python3.7/site-packages/azure/iot/device/common/pipeline/pipeline_stages_mqtt.py", line 206, in _run_op
    self.transport.connect(password=password)
  File "/usr/local/lib/python3.7/site-packages/azure/iot/device/common/mqtt_transport.py", line 419, in connect
    raise exceptions.ConnectionFailedError() from e
azure.iot.device.common.transport_exceptions.ConnectionFailedError

This repeats cyclically as the module continues to attempt connecting. Restarting the module DOESN'T solve the issue. You need to restart edgeHub to remove the deadlock.

On edgeHub (currently 1.4), this is what is captured when the error occurred (I have removed some debug lines because they were no relevant):

<7> 2022-10-11 07:08:43.554 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.DeviceConnectivityManager] - IotHub call succeeded
<7> 2022-10-11 07:08:43.554 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ConnectivityAwareClient] - Operation SendEventAsync succeeded for 6f4d3d12106d43b7a6fa33e98c6df045/sample
<7> 2022-10-11 07:08:43.554 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudProxy] - Sending message for 6f4d3d12106d43b7a6fa33e98c6df045/sample
<6> 2022-10-11 07:09:00.732 +00:00 [INF] [EdgeHub] - "Closing connection for device: 6f4d3d12106d43b7a6fa33e98c6df045/sample, , "
<6> 2022-10-11 07:09:00.733 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Mqtt.MessagingServiceClient] - Disposing MessagingServiceClient for device Id 6f4d3d12106d43b7a6fa33e98c6df045/sample because of exception -
<6> 2022-10-11 07:09:00.733 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Mqtt.DeviceProxy] - Setting device proxy inactive for device Id 6f4d3d12106d43b7a6fa33e98c6df045/sample
<6> 2022-10-11 07:09:00.733 +00:00 [INF] [Microsoft.Azure.Devices.Edge.Hub.Core.ConnectionManager] - Removing device connection for device 6f4d3d12106d43b7a6fa33e98c6df045/sample with removeCloudConnection flag 'True'.
<7> 2022-10-11 07:09:00.733 +00:00 [DBG] [DotNetty.Handlers.Logging.LoggingHandler] - "[id: 0x74841ffb, [::ffff:172.18.0.4]:59684 => [::ffff:40.113.176.164]:8883] WRITE: DisconnectPacket[Type=DISCONNECT, QualityOfService=AtMostOnce, Duplicate=False, Retain=False]"
<7> 2022-10-11 07:09:00.733 +00:00 [DBG] [DotNetty.Handlers.Logging.LoggingHandler] - "[id: 0x74841ffb, [::ffff:172.18.0.4]:59684 => [::ffff:40.113.176.164]:8883] FLUSH"
<7> 2022-10-11 07:09:00.733 +00:00 [DBG] [Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ConnectivityAwareClient] - Received connection status changed callback with connection status Disabled and reason Client_Close for 6f4d3d12106d43b7a6fa33e98c6df045/sample
<7> 2022-10-11 07:09:00.738 +00:00 [DBG] [DotNetty.Handlers.Logging.LoggingHandler] - "[id: 0x74841ffb, [::ffff:172.18.0.4]:59684 => [::ffff:40.113.176.164]:8883] RECEIVED_COMPLETE"
<7> 2022-10-11 07:09:00.738 +00:00 [DBG] [DotNetty.Handlers.Logging.LoggingHandler] - "[id: 0x74841ffb, [::ffff:172.18.0.4]:59684 => [::ffff:40.113.176.164]:8883] READ"
<7> 2022-10-11 07:09:00.738 +00:00 [DBG] [DotNetty.Handlers.Logging.LoggingHandler] - "[id: 0x74841ffb, [::ffff:172.18.0.4]:59684 => [::ffff:40.113.176.164]:8883] READ"
<7> 2022-10-11 07:09:00.738 +00:00 [DBG] [DotNetty.Handlers.Logging.LoggingHandler] - "[id: 0x74841ffb, [::ffff:172.18.0.4]:59684 :> [::ffff:40.113.176.164]:8883] INACTIVE"
<7> 2022-10-11 07:09:00.738 +00:00 [DBG] [DotNetty.Handlers.Logging.LoggingHandler] - "[id: 0x74841ffb, [::ffff:172.18.0.4]:59684 :> [::ffff:40.113.176.164]:8883] CLOSE"
<7> 2022-10-11 07:09:00.738 +00:00 [DBG] [DotNetty.Handlers.Logging.LoggingHandler] - "[id: 0x74841ffb, [::ffff:172.18.0.4]:59684 :> [::ffff:40.113.176.164]:8883] UNREGISTERED"
<7> 2022-10-11 07:09:00.738 +00:00 [DBG] [DotNetty.Handlers.Logging.LoggingHandler] - "[id: 0x74841ffb, [::ffff:172.18.0.4]:59684 :> [::ffff:40.113.176.164]:8883] HANDLER_REMOVED"
<7> 2022-10-11 07:09:29.438 +00:00 [DBG] [DotNetty.Handlers.Logging.LoggingHandler] - "[id: 0x3d209f7e, [::ffff:172.18.0.4]:43198 => [::ffff:40.113.176.164]:8883] FLUSH"

lucarv avatar Oct 11 '22 07:10 lucarv