Unnecessary multiple downloads of twin data when setting on_twin_desired_properties_patch_received

[marcosatti]

Context

Windows 11
Python 3.10.4

Package             Version
------------------- ---------
aiodns              3.0.0
aiohttp             3.8.1
aiosignal           1.2.0
argparse-addons     0.8.0
async-timeout       4.0.2
attrs               21.4.0
azure-iot-device    2.11.0
bincopy             17.10.1
Brotli              1.0.9
cchardet            2.1.7
certifi             2021.10.8
cffi                1.15.0
charset-normalizer  2.0.12
deprecation         2.1.0
frozenlist          1.3.0
grpcio              1.45.0
grpcio-tools        1.45.0
humanfriendly       10.0
idna                3.3
janus               1.0.0
marshmallow         3.15.0
multidict           6.0.2
packaging           21.3
paho-mqtt           1.6.1
pip                 22.0.4
protobuf            3.20.1
pycares             4.1.2
pycparser           2.21
pyelftools          0.28
pyparsing           3.0.8
pyreadline3         3.4.1
PySocks             1.7.1
requests            2.27.1
requests-unixsocket 0.3.0
setuptools          62.1.0
six                 1.16.0
types-protobuf      3.19.18
typing_extensions   4.2.0
urllib3             1.26.9
wheel               0.37.1
yarl                1.7.2

We are using the async client.

Description of the issue

We are on a resource constraint network (very low speed & metered connection), so using as minimal internet as possible is one of our goals making our products. I've noticed that upon setting the on_twin_desired_properties_patch_received handler on the client, when initially connecting it will download 2 copies of the current twin - I would only expect one copy to be downloaded. This adds up quickly when lots of new devices are connected over time.

Without setting the on_twin_desired_properties_patch_received handler we do not get this issue, but also lose out on the automatic twin updates and have to poll instead which is potentially more inefficient in the long term.

Notice in the logs towards the bottom there is:

2022-05-04 20:42:55,035 - paho - DEBUG - Received PUBLISH (d0, q0, r0, m0), '$iothub/twin/res/200/?$rid=64fd660a-794b-4f97-89a1-bb07a3d96f9f', ...  (1429 bytes)
...
2022-05-04 20:42:55,082 - paho - DEBUG - Received PUBLISH (d0, q0, r0, m0), '$iothub/twin/res/200/?$rid=64fd660a-794b-4f97-89a1-bb07a3d96f9f', ...  (1429 bytes)

This is done presumably because of the previous queue up of 2 twin requests after reconnecting:

2022-05-04 20:42:54,972 - azure.iot.device.iothub.pipeline.pipeline_stages_iothub - INFO - {}: Reconnected.  Getting twin
2022-05-04 20:42:54,972 - azure.iot.device.iothub.pipeline.pipeline_stages_iothub - INFO - EnsureDesiredPropertiesStage: sending twin GET to ensure freshness
2022-05-04 20:42:54,972 - azure.iot.device.common.pipeline.pipeline_stages_base - DEBUG - CoordinateRequestAndResponseStage(RequestAndResponseOperation): adding request 64fd660a-794b-4f97-89a1-bb07a3d96f9f to pending list
2022-05-04 20:42:54,972 - azure.iot.device.common.pipeline.pipeline_stages_base - DEBUG - CoordinateRequestAndResponseStage(RequestAndResponseOperation): Sending twin request to GET resource /
2022-05-04 20:42:54,972 - azure.iot.device.common.pipeline.pipeline_ops_base - DEBUG - RequestOperation: creating worker op of type MQTTPublishOperation
2022-05-04 20:42:54,972 - azure.iot.device.common.pipeline.pipeline_stages_base - DEBUG - ConnectionLockStage(MQTTPublishOperation): pipeline is blocked waiting for a prior connect/disconnect/reauthorize to complete.  queueing.
2022-05-04 20:42:54,972 - azure.iot.device.common.pipeline.pipeline_stages_base - DEBUG - PipelineRootStage: ConnectedEvent received. Calling on_connected_handler
2022-05-04 20:42:54,972 - azure.iot.device.common.pipeline.pipeline_thread - DEBUG - Starting _on_connected in callback thread
2022-05-04 20:42:54,972 - azure.iot.device.common.pipeline.pipeline_stages_base - INFO - CoordinateRequestAndResponseStage: ConnectedEvent: re-publishing request 64fd660a-794b-4f97-89a1-bb07a3d96f9f for GET twin 
2022-05-04 20:42:54,972 - azure.iot.device.iothub.abstract_clients - INFO - Connection State - Connected
2022-05-04 20:42:54,972 - azure.iot.device.common.pipeline.pipeline_stages_base - DEBUG - CoordinateRequestAndResponseStage(RequestAndResponseOperation): Sending twin request to GET resource /

Code sample exhibiting the issue

    async def initialise(self) -> None:
        self._main_loop = asyncio.get_running_loop()
        self._logger.info("Initialising IoT hub device client")
        self._client = IoTHubDeviceClient.create_from_connection_string(self._connection_string, auto_connect=False)
        self._logger.info("Initialised IoT hub device client")

        async with self.ensure_connection():
            self._client.on_twin_desired_properties_patch_received = self._handle_twin_desired_properties_patch_received_proxy
            self._logger.debug("Initialised on twin desired properties patch received handler")
            self._client.on_method_request_received = self._handle_method_request_received_proxy
            self._logger.debug("Initialised on method request received handler")
            self._client.on_message_received = self._handle_message_received_proxy
            self._logger.debug("Initialised on message received handler")

        # Bug happens during this stage (this is test code, not our actual code).
        async with self.ensure_connection():
            await asyncio.sleep(3.0)

    @asynccontextmanager
    async def ensure_connection(self) -> None:
        self._logger.debug("Opening IoT hub client connection")
        assert not self._client.connected, "Connection should not be active outside of this context manager"
        await self._client.connect()
        assert self._client.connected
        self._logger.debug("Waiting for connection to settle")
        await asyncio.sleep(1.0)
        self._logger.debug("Opened IoT hub client connection")
        try:
            yield
        finally:
            self._logger.debug("Closing IoT hub client connection")
            assert self._client.connected
            await self._client.disconnect()
            assert not self._client.connected
            self._logger.debug("Closed IoT hub client connection")

Console log of the issue

2022-05-04 20:42:53,137 - gateway3_iot.device_client.device.Field 54115f0080000002 - INFO - Initialising IoT hub device client
2022-05-04 20:42:53,137 - azure.iot.device.common.pipeline.pipeline_thread - DEBUG - Starting run_op in pipeline thread
2022-05-04 20:42:53,137 - azure.iot.device.common.pipeline.pipeline_stages_http - DEBUG - Gateway Hostname not present. Setting Hostname to: ...
2022-05-04 20:42:53,137 - azure.iot.device.common.pipeline.pipeline_stages_http - DEBUG - HTTPTransportStage(InitializePipelineOperation): got connection args
2022-05-04 20:42:53,137 - azure.iot.device.common.http_transport - DEBUG - creating a SSL context
2022-05-04 20:42:53,152 - azure.iot.device.common.pipeline.pipeline_ops_base - DEBUG - InitializePipelineOperation: completing without error
2022-05-04 20:42:53,152 - azure.iot.device.common.pipeline.pipeline_thread - DEBUG - Starting <azure.iot.device.common.evented_callback.EventedCallback object at 0x000001CEC997D000> in callback thread
2022-05-04 20:42:53,152 - azure.iot.device.common.evented_callback - DEBUG - Callback completed with result None
2022-05-04 20:42:53,152 - azure.iot.device.common.pipeline.pipeline_thread - DEBUG - Starting run_op in pipeline thread
2022-05-04 20:42:53,152 - azure.iot.device.common.pipeline.pipeline_stages_base - DEBUG - SasTokenStage: Scheduling automatic SAS Token renewal at epoch time: 1651671653
2022-05-04 20:42:53,152 - azure.iot.device.common.pipeline.pipeline_stages_mqtt - DEBUG - Gateway Hostname not present. Setting Hostname to: ...
2022-05-04 20:42:53,152 - azure.iot.device.common.pipeline.pipeline_stages_mqtt - DEBUG - MQTTTransportStage(InitializePipelineOperation): got connection args
2022-05-04 20:42:53,152 - azure.iot.device.common.mqtt_transport - DEBUG - creating mqtt client
2022-05-04 20:42:53,152 - azure.iot.device.common.mqtt_transport - INFO - Creating client for connecting using MQTT over TCP
2022-05-04 20:42:53,152 - azure.iot.device.common.mqtt_transport - DEBUG - creating a SSL context
2022-05-04 20:42:53,152 - azure.iot.device.common.mqtt_transport - DEBUG - configuring SSL context with default certs
2022-05-04 20:42:53,168 - azure.iot.device.common.mqtt_transport - DEBUG - Created MQTT protocol client, assigned callbacks
2022-05-04 20:42:53,168 - azure.iot.device.common.pipeline.pipeline_ops_base - DEBUG - InitializePipelineOperation: completing without error
2022-05-04 20:42:53,168 - azure.iot.device.common.pipeline.pipeline_thread - DEBUG - Starting <azure.iot.device.common.evented_callback.EventedCallback object at 0x000001CEC9981B10> in callback thread
2022-05-04 20:42:53,168 - azure.iot.device.common.evented_callback - DEBUG - Callback completed with result None
2022-05-04 20:42:53,168 - gateway3_iot.device_client.device.Field 54115f0080000002 - INFO - Initialised IoT hub device client
2022-05-04 20:42:53,168 - gateway3_iot.device_client.device.Field 54115f0080000002 - DEBUG - Opening IoT hub client connection
2022-05-04 20:42:53,168 - azure.iot.device.iothub.aio.async_clients - INFO - Connecting to Hub...
2022-05-04 20:42:53,168 - azure.iot.device.iothub.pipeline.mqtt_pipeline - DEBUG - Starting ConnectOperation on the pipeline
2022-05-04 20:42:53,168 - azure.iot.device.common.pipeline.pipeline_thread - DEBUG - Starting run_op in pipeline thread
2022-05-04 20:42:53,168 - azure.iot.device.common.pipeline.pipeline_stages_base - DEBUG - ReconnectStage(ConnectOperation): State changes DISCONNECTED -> CONNECTING. Sending op down
2022-05-04 20:42:53,168 - azure.iot.device.common.pipeline.pipeline_stages_base - DEBUG - ConnectionLockStage(ConnectOperation): blocking
2022-05-04 20:42:53,168 - azure.iot.device.common.pipeline.pipeline_stages_mqtt - DEBUG - MQTTTransportStage(ConnectOperation): connecting
2022-05-04 20:42:53,168 - azure.iot.device.common.pipeline.pipeline_stages_mqtt - DEBUG - MQTTTransportStage(ConnectOperation): Starting watchdog
2022-05-04 20:42:53,168 - azure.iot.device.common.mqtt_transport - DEBUG - connecting to mqtt broker
2022-05-04 20:42:53,168 - azure.iot.device.common.mqtt_transport - INFO - Connect using port 8883 (TCP)
2022-05-04 20:42:53,184 - asyncio - DEBUG - <_ProactorSocketTransport fd=1296> received EOF
2022-05-04 20:42:53,184 - asyncio - DEBUG - <asyncio.sslproto.SSLProtocol object at 0x000001CEC99825F0> received EOF
2022-05-04 20:42:53,497 - paho - DEBUG - Sending CONNECT (u1, p1, wr0, wq0, wf0, c0, k60) client_id=b'54115f0080000002'
2022-05-04 20:42:53,497 - azure.iot.device.common.mqtt_transport - DEBUG - _mqtt_client.connect returned rc=0
2022-05-04 20:42:53,544 - paho - DEBUG - Received CONNACK (1, 0)
2022-05-04 20:42:53,544 - azure.iot.device.common.mqtt_transport - INFO - connected with result code: 0
2022-05-04 20:42:53,544 - azure.iot.device.common.pipeline.pipeline_thread - DEBUG - Starting _on_mqtt_connected in pipeline thread
2022-05-04 20:42:53,544 - azure.iot.device.common.pipeline.pipeline_stages_mqtt - INFO - _on_mqtt_connected called
2022-05-04 20:42:53,544 - azure.iot.device.common.pipeline.pipeline_stages_base - DEBUG - ReconnectStage(ConnectedEvent): State changes CONNECTING -> CONNECTED. Connection established
2022-05-04 20:42:53,544 - azure.iot.device.common.pipeline.pipeline_stages_base - DEBUG - PipelineRootStage: ConnectedEvent received. Calling on_connected_handler
2022-05-04 20:42:53,544 - azure.iot.device.common.pipeline.pipeline_thread - DEBUG - Starting _on_connected in callback thread
2022-05-04 20:42:53,544 - azure.iot.device.common.pipeline.pipeline_stages_mqtt - DEBUG - MQTTTransportStage: completing connect op
2022-05-04 20:42:53,544 - azure.iot.device.iothub.abstract_clients - INFO - Connection State - Connected
2022-05-04 20:42:53,560 - azure.iot.device.common.pipeline.pipeline_stages_mqtt - DEBUG - MQTTTransportStage(ConnectOperation): cancelling watchdog
2022-05-04 20:42:53,560 - azure.iot.device.common.pipeline.pipeline_ops_base - DEBUG - ConnectOperation: completing without error
2022-05-04 20:42:53,560 - azure.iot.device.common.pipeline.pipeline_stages_base - DEBUG - ConnectionLockStage(ConnectOperation): op succeeded.  Unblocking queue
2022-05-04 20:42:53,560 - azure.iot.device.common.pipeline.pipeline_stages_base - DEBUG - ConnectionLockStage(ConnectOperation): unblocking and releasing queued ops.
2022-05-04 20:42:53,560 - azure.iot.device.common.pipeline.pipeline_stages_base - DEBUG - ConnectionLockStage(ConnectOperation): processing 0 items in queue for error=None
2022-05-04 20:42:53,560 - azure.iot.device.common.pipeline.pipeline_thread - DEBUG - Starting on_complete in callback thread
2022-05-04 20:42:53,560 - azure.iot.device.common.async_adapter - DEBUG - Callback completed with result None
2022-05-04 20:42:53,560 - azure.iot.device.iothub.aio.async_clients - INFO - Successfully connected to Hub
2022-05-04 20:42:53,560 - gateway3_iot.device_client.device.Field 54115f0080000002 - DEBUG - Waiting for connection to settle
2022-05-04 20:42:54,564 - gateway3_iot.device_client.device.Field 54115f0080000002 - DEBUG - Opened IoT hub client connection
2022-05-04 20:42:54,564 - azure.iot.device.iothub.sync_handler_manager - DEBUG - Creating new handler runner for handler: _on_twin_desired_properties_patch_received
2022-05-04 20:42:54,564 - azure.iot.device.iothub.aio.async_handler_manager - DEBUG - HANDLER RUNNER (_on_twin_desired_properties_patch_received): Starting runner
2022-05-04 20:42:54,564 - azure.iot.device.iothub.aio.async_clients - INFO - Enabling feature:twin_patches...
2022-05-04 20:42:54,564 - azure.iot.device.iothub.pipeline.mqtt_pipeline - DEBUG - enable_feature twin_patches called
2022-05-04 20:42:54,564 - azure.iot.device.common.pipeline.pipeline_thread - DEBUG - Starting run_op in pipeline thread
2022-05-04 20:42:54,568 - azure.iot.device.iothub.pipeline.pipeline_stages_iothub - DEBUG - EnsureDesiredPropertiesStage: enabling twin patches.  setting last_version_seen
2022-05-04 20:42:54,568 - azure.iot.device.common.pipeline.pipeline_ops_base - DEBUG - EnableFeatureOperation: creating worker op of type MQTTSubscribeOperation
2022-05-04 20:42:54,568 - azure.iot.device.common.pipeline.pipeline_stages_base - DEBUG - OpTimeoutStage(MQTTSubscribeOperation): Creating timer
2022-05-04 20:42:54,568 - azure.iot.device.common.pipeline.pipeline_stages_base - DEBUG - OpTimeoutStage(MQTTSubscribeOperation): Sending down
2022-05-04 20:42:54,568 - azure.iot.device.common.pipeline.pipeline_stages_mqtt - DEBUG - MQTTTransportStage(MQTTSubscribeOperation): subscribing to $iothub/twin/PATCH/properties/desired/#
2022-05-04 20:42:54,568 - azure.iot.device.common.mqtt_transport - INFO - subscribing to $iothub/twin/PATCH/properties/desired/# with qos 1
2022-05-04 20:42:54,568 - paho - DEBUG - Sending SUBSCRIBE (d0, m1) [(b'$iothub/twin/PATCH/properties/desired/#', 1)]
2022-05-04 20:42:54,568 - azure.iot.device.common.mqtt_transport - DEBUG - _mqtt_client.subscribe returned rc=0
2022-05-04 20:42:54,568 - azure.iot.device.common.mqtt_transport - DEBUG - Waiting for response on MID: 1
2022-05-04 20:42:54,611 - paho - DEBUG - Received SUBACK
2022-05-04 20:42:54,611 - azure.iot.device.common.mqtt_transport - INFO - suback received for 1
2022-05-04 20:42:54,611 - azure.iot.device.common.mqtt_transport - DEBUG - Response received for recognized MID: 1 - triggering callback
2022-05-04 20:42:54,611 - azure.iot.device.common.pipeline.pipeline_thread - DEBUG - Starting on_complete in pipeline thread
2022-05-04 20:42:54,611 - azure.iot.device.common.pipeline.pipeline_stages_mqtt - DEBUG - MQTTTransportStage(MQTTSubscribeOperation): SUBACK received. completing op.
2022-05-04 20:42:54,611 - azure.iot.device.common.pipeline.pipeline_ops_base - DEBUG - MQTTSubscribeOperation: completing without error
2022-05-04 20:42:54,611 - azure.iot.device.common.pipeline.pipeline_stages_base - DEBUG - OpTimeoutStage(MQTTSubscribeOperation): Cancelling timer
2022-05-04 20:42:54,611 - azure.iot.device.common.pipeline.pipeline_ops_base - DEBUG - EnableFeatureOperation: Worker op (MQTTSubscribeOperation) has been completed
2022-05-04 20:42:54,611 - azure.iot.device.common.pipeline.pipeline_ops_base - DEBUG - EnableFeatureOperation: completing without error
2022-05-04 20:42:54,611 - azure.iot.device.common.pipeline.pipeline_thread - DEBUG - Starting on_complete in callback thread
2022-05-04 20:42:54,611 - azure.iot.device.common.async_adapter - DEBUG - Callback completed with result None
2022-05-04 20:42:54,611 - azure.iot.device.iothub.aio.async_clients - INFO - Successfully enabled feature:twin_patches
2022-05-04 20:42:54,611 - gateway3_iot.device_client.device.Field 54115f0080000002 - DEBUG - Initialised on twin desired properties patch received handler
2022-05-04 20:42:54,611 - azure.iot.device.iothub.sync_handler_manager - DEBUG - Creating new handler runner for handler: _on_method_request_received
2022-05-04 20:42:54,611 - azure.iot.device.iothub.aio.async_handler_manager - DEBUG - HANDLER RUNNER (_on_method_request_received): Starting runner
2022-05-04 20:42:54,611 - azure.iot.device.iothub.aio.async_clients - INFO - Enabling feature:methods...
2022-05-04 20:42:54,611 - azure.iot.device.iothub.pipeline.mqtt_pipeline - DEBUG - enable_feature methods called
2022-05-04 20:42:54,611 - azure.iot.device.common.pipeline.pipeline_thread - DEBUG - Starting run_op in pipeline thread
2022-05-04 20:42:54,611 - azure.iot.device.common.pipeline.pipeline_ops_base - DEBUG - EnableFeatureOperation: creating worker op of type MQTTSubscribeOperation
2022-05-04 20:42:54,611 - azure.iot.device.common.pipeline.pipeline_stages_base - DEBUG - OpTimeoutStage(MQTTSubscribeOperation): Creating timer
2022-05-04 20:42:54,627 - azure.iot.device.common.pipeline.pipeline_stages_base - DEBUG - OpTimeoutStage(MQTTSubscribeOperation): Sending down
2022-05-04 20:42:54,627 - azure.iot.device.common.pipeline.pipeline_stages_mqtt - DEBUG - MQTTTransportStage(MQTTSubscribeOperation): subscribing to $iothub/methods/POST/#
2022-05-04 20:42:54,627 - azure.iot.device.common.mqtt_transport - INFO - subscribing to $iothub/methods/POST/# with qos 1
2022-05-04 20:42:54,627 - paho - DEBUG - Sending SUBSCRIBE (d0, m2) [(b'$iothub/methods/POST/#', 1)]
2022-05-04 20:42:54,627 - azure.iot.device.common.mqtt_transport - DEBUG - _mqtt_client.subscribe returned rc=0
2022-05-04 20:42:54,627 - azure.iot.device.common.mqtt_transport - DEBUG - Waiting for response on MID: 2
2022-05-04 20:42:54,668 - paho - DEBUG - Received SUBACK
2022-05-04 20:42:54,668 - azure.iot.device.common.mqtt_transport - INFO - suback received for 2
2022-05-04 20:42:54,674 - azure.iot.device.common.mqtt_transport - DEBUG - Response received for recognized MID: 2 - triggering callback
2022-05-04 20:42:54,674 - azure.iot.device.common.pipeline.pipeline_thread - DEBUG - Starting on_complete in pipeline thread
2022-05-04 20:42:54,674 - azure.iot.device.common.pipeline.pipeline_stages_mqtt - DEBUG - MQTTTransportStage(MQTTSubscribeOperation): SUBACK received. completing op.
2022-05-04 20:42:54,674 - azure.iot.device.common.pipeline.pipeline_ops_base - DEBUG - MQTTSubscribeOperation: completing without error
2022-05-04 20:42:54,674 - azure.iot.device.common.pipeline.pipeline_stages_base - DEBUG - OpTimeoutStage(MQTTSubscribeOperation): Cancelling timer
2022-05-04 20:42:54,674 - azure.iot.device.common.pipeline.pipeline_ops_base - DEBUG - EnableFeatureOperation: Worker op (MQTTSubscribeOperation) has been completed
2022-05-04 20:42:54,674 - azure.iot.device.common.pipeline.pipeline_ops_base - DEBUG - EnableFeatureOperation: completing without error
2022-05-04 20:42:54,674 - azure.iot.device.common.pipeline.pipeline_thread - DEBUG - Starting on_complete in callback thread
2022-05-04 20:42:54,674 - azure.iot.device.common.async_adapter - DEBUG - Callback completed with result None
2022-05-04 20:42:54,674 - azure.iot.device.iothub.aio.async_clients - INFO - Successfully enabled feature:methods
2022-05-04 20:42:54,674 - gateway3_iot.device_client.device.Field 54115f0080000002 - DEBUG - Initialised on method request received handler
2022-05-04 20:42:54,674 - azure.iot.device.iothub.sync_handler_manager - DEBUG - Creating new handler runner for handler: _on_message_received
2022-05-04 20:42:54,674 - azure.iot.device.iothub.aio.async_clients - INFO - Enabling feature:c2d...
2022-05-04 20:42:54,674 - azure.iot.device.iothub.aio.async_handler_manager - DEBUG - HANDLER RUNNER (_on_message_received): Starting runner
2022-05-04 20:42:54,674 - azure.iot.device.iothub.pipeline.mqtt_pipeline - DEBUG - enable_feature c2d called
2022-05-04 20:42:54,674 - azure.iot.device.common.pipeline.pipeline_thread - DEBUG - Starting run_op in pipeline thread
2022-05-04 20:42:54,674 - azure.iot.device.common.pipeline.pipeline_ops_base - DEBUG - EnableFeatureOperation: creating worker op of type MQTTSubscribeOperation
2022-05-04 20:42:54,674 - azure.iot.device.common.pipeline.pipeline_stages_base - DEBUG - OpTimeoutStage(MQTTSubscribeOperation): Creating timer
2022-05-04 20:42:54,674 - azure.iot.device.common.pipeline.pipeline_stages_base - DEBUG - OpTimeoutStage(MQTTSubscribeOperation): Sending down
2022-05-04 20:42:54,674 - azure.iot.device.common.pipeline.pipeline_stages_mqtt - DEBUG - MQTTTransportStage(MQTTSubscribeOperation): subscribing to devices/54115f0080000002/messages/devicebound/#
2022-05-04 20:42:54,674 - azure.iot.device.common.mqtt_transport - INFO - subscribing to devices/54115f0080000002/messages/devicebound/# with qos 1
2022-05-04 20:42:54,674 - paho - DEBUG - Sending SUBSCRIBE (d0, m3) [(b'devices/54115f0080000002/messages/devicebound/#', 1)]
2022-05-04 20:42:54,674 - azure.iot.device.common.mqtt_transport - DEBUG - _mqtt_client.subscribe returned rc=0
2022-05-04 20:42:54,674 - azure.iot.device.common.mqtt_transport - DEBUG - Waiting for response on MID: 3
2022-05-04 20:42:54,721 - paho - DEBUG - Received SUBACK
2022-05-04 20:42:54,721 - azure.iot.device.common.mqtt_transport - INFO - suback received for 3
2022-05-04 20:42:54,721 - azure.iot.device.common.mqtt_transport - DEBUG - Response received for recognized MID: 3 - triggering callback
2022-05-04 20:42:54,721 - azure.iot.device.common.pipeline.pipeline_thread - DEBUG - Starting on_complete in pipeline thread
2022-05-04 20:42:54,721 - azure.iot.device.common.pipeline.pipeline_stages_mqtt - DEBUG - MQTTTransportStage(MQTTSubscribeOperation): SUBACK received. completing op.
2022-05-04 20:42:54,721 - azure.iot.device.common.pipeline.pipeline_ops_base - DEBUG - MQTTSubscribeOperation: completing without error
2022-05-04 20:42:54,721 - azure.iot.device.common.pipeline.pipeline_stages_base - DEBUG - OpTimeoutStage(MQTTSubscribeOperation): Cancelling timer
2022-05-04 20:42:54,721 - azure.iot.device.common.pipeline.pipeline_ops_base - DEBUG - EnableFeatureOperation: Worker op (MQTTSubscribeOperation) has been completed
2022-05-04 20:42:54,721 - azure.iot.device.common.pipeline.pipeline_ops_base - DEBUG - EnableFeatureOperation: completing without error
2022-05-04 20:42:54,721 - azure.iot.device.common.pipeline.pipeline_thread - DEBUG - Starting on_complete in callback thread
2022-05-04 20:42:54,721 - azure.iot.device.common.async_adapter - DEBUG - Callback completed with result None
2022-05-04 20:42:54,721 - azure.iot.device.iothub.aio.async_clients - INFO - Successfully enabled feature:c2d
2022-05-04 20:42:54,721 - gateway3_iot.device_client.device.Field 54115f0080000002 - DEBUG - Initialised on message received handler
2022-05-04 20:42:54,721 - gateway3_iot.device_client.device.Field 54115f0080000002 - DEBUG - Closing IoT hub client connection
2022-05-04 20:42:54,721 - azure.iot.device.iothub.aio.async_clients - INFO - Disconnecting from Hub...
2022-05-04 20:42:54,721 - azure.iot.device.iothub.aio.async_clients - DEBUG - Executing initial disconnect
2022-05-04 20:42:54,737 - azure.iot.device.iothub.pipeline.mqtt_pipeline - DEBUG - Starting DisconnectOperation on the pipeline
2022-05-04 20:42:54,737 - azure.iot.device.common.pipeline.pipeline_thread - DEBUG - Starting run_op in pipeline thread
2022-05-04 20:42:54,737 - azure.iot.device.common.pipeline.pipeline_stages_base - DEBUG - ReconnectStage(DisconnectOperation): State changes CONNECTED -> DISCONNECTING. Sending op down.
2022-05-04 20:42:54,737 - asyncio - WARNING - Executing <Task pending name='Task-39' coro=<_handle_exceptions() running at src\python\grpcio\grpc\_cython\_cygrpc/aio/server.pyx.pxi:679> wait_for=<Future pending cb=[_chain_future.<locals>._call_check_cancel() at C:\Program Files\Python310\lib\asyncio\futures.py:384, Task.task_wakeup()] created at C:\Program Files\Python310\lib\asyncio\base_events.py:429> cb=[_add_callback_handler.<locals>.handle_callbacks()] created at C:\Program Files\Python310\lib\asyncio\events.py:80> took 0.172 seconds
2022-05-04 20:42:54,737 - azure.iot.device.common.pipeline.pipeline_stages_base - DEBUG - ConnectionLockStage(DisconnectOperation): blocking
2022-05-04 20:42:54,737 - azure.iot.device.common.pipeline.pipeline_stages_mqtt - DEBUG - MQTTTransportStage(DisconnectOperation): disconnecting
2022-05-04 20:42:54,737 - azure.iot.device.common.mqtt_transport - INFO - disconnecting MQTT client
2022-05-04 20:42:54,737 - paho - DEBUG - Sending DISCONNECT
2022-05-04 20:42:54,737 - azure.iot.device.common.mqtt_transport - INFO - disconnected with result code: 0
2022-05-04 20:42:54,737 - azure.iot.device.common.pipeline.pipeline_thread - DEBUG - Starting _on_mqtt_disconnected in pipeline thread
2022-05-04 20:42:54,737 - azure.iot.device.common.mqtt_transport - DEBUG - _mqtt_client.disconnect returned rc=0
2022-05-04 20:42:54,737 - azure.iot.device.common.mqtt_transport - DEBUG - Cancelling all pending operations
2022-05-04 20:42:54,737 - azure.iot.device.common.pipeline.pipeline_stages_mqtt - INFO - MQTTTransportStage: _on_mqtt_disconnect called
2022-05-04 20:42:54,737 - azure.iot.device.common.pipeline.pipeline_stages_base - DEBUG - ReconnectStage(DisconnectedEvent): State changes DISCONNECTING -> DISCONNECTED. Not attempting to reconnect (User-initiated disconnect)
2022-05-04 20:42:54,737 - azure.iot.device.common.pipeline.pipeline_stages_base - DEBUG - PipelineRootStage: DisconnectedEvent received. Calling on_disconnected_handler
2022-05-04 20:42:54,737 - azure.iot.device.common.pipeline.pipeline_thread - DEBUG - Starting _on_disconnected in callback thread
2022-05-04 20:42:54,737 - azure.iot.device.common.pipeline.pipeline_stages_mqtt - DEBUG - MQTTTransportStage: Expected disconnect - completing pending disconnect op
2022-05-04 20:42:54,737 - azure.iot.device.iothub.abstract_clients - INFO - Connection State - Disconnected
2022-05-04 20:42:54,737 - azure.iot.device.common.pipeline.pipeline_ops_base - DEBUG - DisconnectOperation: completing without error
2022-05-04 20:42:54,737 - azure.iot.device.iothub.abstract_clients - INFO - Cleared all pending method requests due to disconnect
2022-05-04 20:42:54,737 - azure.iot.device.common.pipeline.pipeline_stages_base - DEBUG - ConnectionLockStage(DisconnectOperation): op succeeded.  Unblocking queue
2022-05-04 20:42:54,737 - azure.iot.device.common.pipeline.pipeline_stages_base - DEBUG - ConnectionLockStage(DisconnectOperation): unblocking and releasing queued ops.
2022-05-04 20:42:54,737 - azure.iot.device.common.pipeline.pipeline_stages_base - DEBUG - ConnectionLockStage(DisconnectOperation): processing 0 items in queue for error=None
2022-05-04 20:42:54,737 - azure.iot.device.common.pipeline.pipeline_thread - DEBUG - Starting on_complete in callback thread
2022-05-04 20:42:54,737 - azure.iot.device.common.async_adapter - DEBUG - Callback completed with result None
2022-05-04 20:42:54,752 - azure.iot.device.iothub.aio.async_clients - DEBUG - Successfully executed initial disconnect
2022-05-04 20:42:54,752 - azure.iot.device.iothub.aio.async_clients - DEBUG - Stopping handlers...
2022-05-04 20:42:54,752 - azure.iot.device.iothub.aio.async_handler_manager - DEBUG - Adding HandlerRunnerKillerSentinel to inbox corresponding to _on_message_received handler runner
2022-05-04 20:42:54,752 - azure.iot.device.iothub.aio.async_handler_manager - DEBUG - Waiting for _on_message_received handler runner to exit...
2022-05-04 20:42:54,752 - azure.iot.device.iothub.aio.async_handler_manager - DEBUG - HANDLER RUNNER (_on_message_received): HandlerRunnerKillerSentinel found in inbox. Exiting.
2022-05-04 20:42:54,752 - azure.iot.device.iothub.aio.async_handler_manager - DEBUG - HANDLER RUNNER (_on_message_received): Task successfully completed without exception
2022-05-04 20:42:54,752 - azure.iot.device.iothub.aio.async_handler_manager - DEBUG - Handler runner for _on_message_received has been stopped
2022-05-04 20:42:54,752 - azure.iot.device.iothub.aio.async_handler_manager - DEBUG - Adding HandlerRunnerKillerSentinel to inbox corresponding to _on_method_request_received handler runner
2022-05-04 20:42:54,752 - azure.iot.device.iothub.aio.async_handler_manager - DEBUG - Waiting for _on_method_request_received handler runner to exit...
2022-05-04 20:42:54,752 - azure.iot.device.iothub.aio.async_handler_manager - DEBUG - HANDLER RUNNER (_on_method_request_received): HandlerRunnerKillerSentinel found in inbox. Exiting.
2022-05-04 20:42:54,752 - azure.iot.device.iothub.aio.async_handler_manager - DEBUG - HANDLER RUNNER (_on_method_request_received): Task successfully completed without exception
2022-05-04 20:42:54,752 - azure.iot.device.iothub.aio.async_handler_manager - DEBUG - Handler runner for _on_method_request_received has been stopped
2022-05-04 20:42:54,752 - azure.iot.device.iothub.aio.async_handler_manager - DEBUG - Adding HandlerRunnerKillerSentinel to inbox corresponding to _on_twin_desired_properties_patch_received handler runner
2022-05-04 20:42:54,752 - azure.iot.device.iothub.aio.async_handler_manager - DEBUG - Waiting for _on_twin_desired_properties_patch_received handler runner to exit...
2022-05-04 20:42:54,752 - azure.iot.device.iothub.aio.async_handler_manager - DEBUG - HANDLER RUNNER (_on_twin_desired_properties_patch_received): HandlerRunnerKillerSentinel found in inbox. Exiting.
2022-05-04 20:42:54,752 - azure.iot.device.iothub.aio.async_handler_manager - DEBUG - HANDLER RUNNER (_on_twin_desired_properties_patch_received): Task successfully completed without exception
2022-05-04 20:42:54,752 - azure.iot.device.iothub.aio.async_handler_manager - DEBUG - Handler runner for _on_twin_desired_properties_patch_received has been stopped
2022-05-04 20:42:54,752 - azure.iot.device.iothub.aio.async_clients - DEBUG - Successfully stopped handlers
2022-05-04 20:42:54,752 - azure.iot.device.iothub.aio.async_clients - DEBUG - Executing secondary disconnect...
2022-05-04 20:42:54,752 - azure.iot.device.iothub.pipeline.mqtt_pipeline - DEBUG - Starting DisconnectOperation on the pipeline
2022-05-04 20:42:54,752 - azure.iot.device.common.pipeline.pipeline_thread - DEBUG - Starting run_op in pipeline thread
2022-05-04 20:42:54,752 - azure.iot.device.common.pipeline.pipeline_stages_base - DEBUG - ReconnectStage(DisconnectOperation): State is already DISCONNECTED. Sending op down
2022-05-04 20:42:54,752 - azure.iot.device.common.pipeline.pipeline_stages_base - INFO - ConnectionLockStage(DisconnectOperation): Transport is already disconnected.  Completing.
2022-05-04 20:42:54,752 - azure.iot.device.common.pipeline.pipeline_ops_base - DEBUG - DisconnectOperation: completing without error
2022-05-04 20:42:54,752 - azure.iot.device.common.pipeline.pipeline_thread - DEBUG - Starting on_complete in callback thread
2022-05-04 20:42:54,752 - azure.iot.device.common.async_adapter - DEBUG - Callback completed with result None
2022-05-04 20:42:54,769 - azure.iot.device.iothub.aio.async_clients - DEBUG - Successfully executed secondary disconnect
2022-05-04 20:42:54,769 - azure.iot.device.iothub.aio.async_clients - INFO - Successfully disconnected from Hub
2022-05-04 20:42:54,769 - gateway3_iot.device_client.device.Field 54115f0080000002 - DEBUG - Closed IoT hub client connection
2022-05-04 20:42:54,769 - gateway3_iot.device_client.device.Field 54115f0080000002 - DEBUG - Opening IoT hub client connection
2022-05-04 20:42:54,769 - azure.iot.device.iothub.aio.async_clients - INFO - Connecting to Hub...
2022-05-04 20:42:54,769 - azure.iot.device.iothub.pipeline.mqtt_pipeline - DEBUG - Starting ConnectOperation on the pipeline
2022-05-04 20:42:54,769 - azure.iot.device.common.pipeline.pipeline_thread - DEBUG - Starting run_op in pipeline thread
2022-05-04 20:42:54,769 - azure.iot.device.common.pipeline.pipeline_stages_base - DEBUG - ReconnectStage(ConnectOperation): State changes DISCONNECTED -> CONNECTING. Sending op down
2022-05-04 20:42:54,769 - azure.iot.device.common.pipeline.pipeline_stages_base - DEBUG - ConnectionLockStage(ConnectOperation): blocking
2022-05-04 20:42:54,769 - azure.iot.device.common.pipeline.pipeline_stages_mqtt - DEBUG - MQTTTransportStage(ConnectOperation): connecting
2022-05-04 20:42:54,769 - azure.iot.device.common.pipeline.pipeline_stages_mqtt - DEBUG - MQTTTransportStage(ConnectOperation): Starting watchdog
2022-05-04 20:42:54,769 - azure.iot.device.common.mqtt_transport - DEBUG - connecting to mqtt broker
2022-05-04 20:42:54,769 - azure.iot.device.common.mqtt_transport - INFO - Connect using port 8883 (TCP)
2022-05-04 20:42:54,909 - paho - DEBUG - Sending CONNECT (u1, p1, wr0, wq0, wf0, c0, k60) client_id=b'54115f0080000002'
2022-05-04 20:42:54,909 - azure.iot.device.common.mqtt_transport - DEBUG - _mqtt_client.connect returned rc=0
2022-05-04 20:42:54,972 - paho - DEBUG - Received CONNACK (1, 0)
2022-05-04 20:42:54,972 - azure.iot.device.common.mqtt_transport - INFO - connected with result code: 0
2022-05-04 20:42:54,972 - azure.iot.device.common.pipeline.pipeline_thread - DEBUG - Starting _on_mqtt_connected in pipeline thread
2022-05-04 20:42:54,972 - azure.iot.device.common.pipeline.pipeline_stages_mqtt - INFO - _on_mqtt_connected called
2022-05-04 20:42:54,972 - azure.iot.device.common.pipeline.pipeline_stages_base - DEBUG - ReconnectStage(ConnectedEvent): State changes CONNECTING -> CONNECTED. Connection established
2022-05-04 20:42:54,972 - azure.iot.device.iothub.pipeline.pipeline_stages_iothub - INFO - {}: Reconnected.  Getting twin
2022-05-04 20:42:54,972 - azure.iot.device.iothub.pipeline.pipeline_stages_iothub - INFO - EnsureDesiredPropertiesStage: sending twin GET to ensure freshness
2022-05-04 20:42:54,972 - azure.iot.device.common.pipeline.pipeline_stages_base - DEBUG - CoordinateRequestAndResponseStage(RequestAndResponseOperation): adding request 64fd660a-794b-4f97-89a1-bb07a3d96f9f to pending list
2022-05-04 20:42:54,972 - azure.iot.device.common.pipeline.pipeline_stages_base - DEBUG - CoordinateRequestAndResponseStage(RequestAndResponseOperation): Sending twin request to GET resource /
2022-05-04 20:42:54,972 - azure.iot.device.common.pipeline.pipeline_ops_base - DEBUG - RequestOperation: creating worker op of type MQTTPublishOperation
2022-05-04 20:42:54,972 - azure.iot.device.common.pipeline.pipeline_stages_base - DEBUG - ConnectionLockStage(MQTTPublishOperation): pipeline is blocked waiting for a prior connect/disconnect/reauthorize to complete.  queueing.
2022-05-04 20:42:54,972 - azure.iot.device.common.pipeline.pipeline_stages_base - DEBUG - PipelineRootStage: ConnectedEvent received. Calling on_connected_handler
2022-05-04 20:42:54,972 - azure.iot.device.common.pipeline.pipeline_thread - DEBUG - Starting _on_connected in callback thread
2022-05-04 20:42:54,972 - azure.iot.device.common.pipeline.pipeline_stages_base - INFO - CoordinateRequestAndResponseStage: ConnectedEvent: re-publishing request 64fd660a-794b-4f97-89a1-bb07a3d96f9f for GET twin 
2022-05-04 20:42:54,972 - azure.iot.device.iothub.abstract_clients - INFO - Connection State - Connected
2022-05-04 20:42:54,972 - azure.iot.device.common.pipeline.pipeline_stages_base - DEBUG - CoordinateRequestAndResponseStage(RequestAndResponseOperation): Sending twin request to GET resource /
2022-05-04 20:42:54,972 - azure.iot.device.iothub.aio.async_handler_manager - DEBUG - HANDLER RUNNER (_on_message_received): Starting runner
2022-05-04 20:42:54,972 - azure.iot.device.common.pipeline.pipeline_ops_base - DEBUG - RequestOperation: creating worker op of type MQTTPublishOperation
2022-05-04 20:42:54,972 - azure.iot.device.iothub.aio.async_handler_manager - DEBUG - HANDLER RUNNER (_on_method_request_received): Starting runner
2022-05-04 20:42:54,972 - azure.iot.device.common.pipeline.pipeline_stages_base - DEBUG - ConnectionLockStage(MQTTPublishOperation): pipeline is blocked waiting for a prior connect/disconnect/reauthorize to complete.  queueing.
2022-05-04 20:42:54,972 - azure.iot.device.iothub.aio.async_handler_manager - DEBUG - HANDLER RUNNER (_on_twin_desired_properties_patch_received): Starting runner
2022-05-04 20:42:54,972 - azure.iot.device.common.pipeline.pipeline_stages_mqtt - DEBUG - MQTTTransportStage: completing connect op
2022-05-04 20:42:54,972 - azure.iot.device.common.pipeline.pipeline_stages_mqtt - DEBUG - MQTTTransportStage(ConnectOperation): cancelling watchdog
2022-05-04 20:42:54,988 - azure.iot.device.common.pipeline.pipeline_ops_base - DEBUG - ConnectOperation: completing without error
2022-05-04 20:42:54,988 - azure.iot.device.common.pipeline.pipeline_stages_base - DEBUG - ConnectionLockStage(ConnectOperation): op succeeded.  Unblocking queue
2022-05-04 20:42:54,988 - azure.iot.device.common.pipeline.pipeline_stages_base - DEBUG - ConnectionLockStage(ConnectOperation): unblocking and releasing queued ops.
2022-05-04 20:42:54,988 - azure.iot.device.common.pipeline.pipeline_stages_base - DEBUG - ConnectionLockStage(ConnectOperation): processing 2 items in queue for error=None
2022-05-04 20:42:54,988 - azure.iot.device.common.pipeline.pipeline_stages_base - DEBUG - ConnectionLockStage(ConnectOperation): releasing MQTTPublishOperation op.
2022-05-04 20:42:54,988 - azure.iot.device.common.pipeline.pipeline_stages_mqtt - DEBUG - MQTTTransportStage(MQTTPublishOperation): publishing on $iothub/twin/GET/?$rid=64fd660a-794b-4f97-89a1-bb07a3d96f9f
2022-05-04 20:42:54,988 - azure.iot.device.common.mqtt_transport - INFO - publishing on $iothub/twin/GET/?$rid=64fd660a-794b-4f97-89a1-bb07a3d96f9f
2022-05-04 20:42:54,988 - paho - DEBUG - Sending PUBLISH (d0, q1, r0, m4), 'b'$iothub/twin/GET/?$rid=64fd660a-794b-4f97-89a1-bb07a3d96f9f'', ... (1 bytes)
2022-05-04 20:42:54,988 - azure.iot.device.common.mqtt_transport - DEBUG - _mqtt_client.publish returned rc=0
2022-05-04 20:42:54,988 - azure.iot.device.common.mqtt_transport - DEBUG - Waiting for response on MID: 4
2022-05-04 20:42:54,988 - azure.iot.device.common.pipeline.pipeline_stages_base - DEBUG - ConnectionLockStage(ConnectOperation): releasing MQTTPublishOperation op.
2022-05-04 20:42:54,988 - azure.iot.device.common.pipeline.pipeline_stages_mqtt - DEBUG - MQTTTransportStage(MQTTPublishOperation): publishing on $iothub/twin/GET/?$rid=64fd660a-794b-4f97-89a1-bb07a3d96f9f
2022-05-04 20:42:54,988 - azure.iot.device.common.mqtt_transport - INFO - publishing on $iothub/twin/GET/?$rid=64fd660a-794b-4f97-89a1-bb07a3d96f9f
2022-05-04 20:42:54,988 - paho - DEBUG - Sending PUBLISH (d0, q1, r0, m5), 'b'$iothub/twin/GET/?$rid=64fd660a-794b-4f97-89a1-bb07a3d96f9f'', ... (1 bytes)
2022-05-04 20:42:54,988 - azure.iot.device.common.mqtt_transport - DEBUG - _mqtt_client.publish returned rc=0
2022-05-04 20:42:54,988 - azure.iot.device.common.mqtt_transport - DEBUG - Waiting for response on MID: 5
2022-05-04 20:42:54,988 - azure.iot.device.common.pipeline.pipeline_thread - DEBUG - Starting on_complete in callback thread
2022-05-04 20:42:54,988 - azure.iot.device.common.async_adapter - DEBUG - Callback completed with result None
2022-05-04 20:42:54,988 - azure.iot.device.iothub.aio.async_clients - INFO - Successfully connected to Hub
2022-05-04 20:42:54,988 - gateway3_iot.device_client.device.Field 54115f0080000002 - DEBUG - Waiting for connection to settle
2022-05-04 20:42:55,035 - paho - DEBUG - Received PUBACK (Mid: 4)
2022-05-04 20:42:55,035 - azure.iot.device.common.mqtt_transport - INFO - payload published for 4
2022-05-04 20:42:55,035 - azure.iot.device.common.mqtt_transport - DEBUG - Response received for recognized MID: 4 - triggering callback
2022-05-04 20:42:55,035 - azure.iot.device.common.pipeline.pipeline_thread - DEBUG - Starting on_complete in pipeline thread
2022-05-04 20:42:55,035 - azure.iot.device.common.pipeline.pipeline_stages_mqtt - DEBUG - MQTTTransportStage(MQTTPublishOperation): PUBACK received. completing op.
2022-05-04 20:42:55,035 - paho - DEBUG - Received PUBLISH (d0, q0, r0, m0), '$iothub/twin/res/200/?$rid=64fd660a-794b-4f97-89a1-bb07a3d96f9f', ...  (1429 bytes)
2022-05-04 20:42:55,035 - azure.iot.device.common.pipeline.pipeline_ops_base - DEBUG - MQTTPublishOperation: completing without error
2022-05-04 20:42:55,035 - azure.iot.device.common.mqtt_transport - INFO - message received on $iothub/twin/res/200/?$rid=64fd660a-794b-4f97-89a1-bb07a3d96f9f
2022-05-04 20:42:55,035 - azure.iot.device.common.pipeline.pipeline_ops_base - DEBUG - RequestOperation: Worker op (MQTTPublishOperation) has been completed
2022-05-04 20:42:55,035 - azure.iot.device.common.pipeline.pipeline_thread - DEBUG - Starting _on_mqtt_message_received in pipeline thread
2022-05-04 20:42:55,035 - azure.iot.device.common.pipeline.pipeline_ops_base - DEBUG - RequestOperation: completing without error
2022-05-04 20:42:55,035 - azure.iot.device.common.pipeline.pipeline_stages_base - DEBUG - CoordinateRequestAndResponseStage(RequestAndResponseOperation): Finished sending twin request to GET resource /
2022-05-04 20:42:55,035 - azure.iot.device.common.pipeline.pipeline_stages_mqtt - DEBUG - MQTTTransportStage: message received on topic $iothub/twin/res/200/?$rid=64fd660a-794b-4f97-89a1-bb07a3d96f9f
2022-05-04 20:42:55,035 - azure.iot.device.common.pipeline.pipeline_stages_base - DEBUG - CoordinateRequestAndResponseStage(ResponseEvent): Handling event with request_id 64fd660a-794b-4f97-89a1-bb07a3d96f9f
2022-05-04 20:42:55,035 - azure.iot.device.common.pipeline.pipeline_stages_base - DEBUG - CoordinateRequestAndResponseStage(RequestAndResponseOperation): Completing twin request to GET resource / with status 200
2022-05-04 20:42:55,035 - azure.iot.device.common.pipeline.pipeline_ops_base - DEBUG - RequestAndResponseOperation: completing without error
2022-05-04 20:42:55,035 - azure.iot.device.iothub.pipeline.pipeline_stages_iothub - DEBUG - TwinRequestResponseStage(RequestAndResponseOperation): Got response for GetTwinOperation
2022-05-04 20:42:55,035 - azure.iot.device.common.pipeline.pipeline_ops_base - DEBUG - GetTwinOperation: completing without error
2022-05-04 20:42:55,035 - azure.iot.device.iothub.pipeline.pipeline_stages_iothub - DEBUG - <azure.iot.device.iothub.pipeline.pipeline_stages_iothub.EnsureDesiredPropertiesStage object at 0x000001CEC9981AB0> Twin GET response received.  Checking versions
2022-05-04 20:42:55,035 - azure.iot.device.iothub.pipeline.pipeline_stages_iothub - DEBUG - EnsureDesiredPropertiesStage: old version = -1, new version = 1
2022-05-04 20:42:55,035 - azure.iot.device.iothub.pipeline.pipeline_stages_iothub - DEBUG - EnsureDesiredPropertiesStage: Version changed.  Sending up new patch event
2022-05-04 20:42:55,035 - azure.iot.device.common.pipeline.pipeline_thread - DEBUG - Starting _on_pipeline_event in callback thread
2022-05-04 20:42:55,035 - azure.iot.device.iothub.inbox_manager - DEBUG - twin patch message sent to inbox
2022-05-04 20:42:55,035 - azure.iot.device.iothub.aio.async_handler_manager - DEBUG - HANDLER RUNNER (_on_twin_desired_properties_patch_received): Invoking handler
2022-05-04 20:42:55,035 - azure.iot.device.iothub.aio.loop_management - DEBUG - Creating new event loop - CLIENT_HANDLER_LOOP
2022-05-04 20:42:55,035 - asyncio - DEBUG - Using proactor: IocpProactor
2022-05-04 20:42:55,050 - azure.iot.device.iothub.sync_handler_manager - DEBUG - HANDLER (CLIENT_EVENT): Successfully completed invocation
2022-05-04 20:42:55,050 - gateway3_iot.device_client.device.Field 54115f0080000002 - DEBUG - Twin Desired Properties Patch Received callback invoked
... (uses twin event) ...
2022-05-04 20:42:55,069 - paho - DEBUG - Received PUBACK (Mid: 5)
2022-05-04 20:42:55,082 - azure.iot.device.common.mqtt_transport - INFO - payload published for 5
2022-05-04 20:42:55,082 - azure.iot.device.common.mqtt_transport - DEBUG - Response received for recognized MID: 5 - triggering callback
2022-05-04 20:42:55,082 - azure.iot.device.common.pipeline.pipeline_thread - DEBUG - Starting on_complete in pipeline thread
2022-05-04 20:42:55,082 - azure.iot.device.common.pipeline.pipeline_stages_mqtt - DEBUG - MQTTTransportStage(MQTTPublishOperation): PUBACK received. completing op.
2022-05-04 20:42:55,082 - azure.iot.device.common.pipeline.pipeline_ops_base - DEBUG - MQTTPublishOperation: completing without error
2022-05-04 20:42:55,082 - azure.iot.device.common.pipeline.pipeline_ops_base - DEBUG - RequestOperation: Worker op (MQTTPublishOperation) has been completed
2022-05-04 20:42:55,082 - azure.iot.device.common.pipeline.pipeline_ops_base - DEBUG - RequestOperation: completing without error
2022-05-04 20:42:55,082 - azure.iot.device.common.pipeline.pipeline_stages_base - DEBUG - CoordinateRequestAndResponseStage(RequestAndResponseOperation): Finished sending twin request to GET resource /
2022-05-04 20:42:55,082 - paho - DEBUG - Received PUBLISH (d0, q0, r0, m0), '$iothub/twin/res/200/?$rid=64fd660a-794b-4f97-89a1-bb07a3d96f9f', ...  (1429 bytes)
2022-05-04 20:42:55,082 - azure.iot.device.common.mqtt_transport - INFO - message received on $iothub/twin/res/200/?$rid=64fd660a-794b-4f97-89a1-bb07a3d96f9f
2022-05-04 20:42:55,082 - azure.iot.device.common.pipeline.pipeline_thread - DEBUG - Starting _on_mqtt_message_received in pipeline thread
2022-05-04 20:42:55,082 - azure.iot.device.common.pipeline.pipeline_stages_mqtt - DEBUG - MQTTTransportStage: message received on topic $iothub/twin/res/200/?$rid=64fd660a-794b-4f97-89a1-bb07a3d96f9f
2022-05-04 20:42:55,082 - azure.iot.device.common.pipeline.pipeline_stages_base - DEBUG - CoordinateRequestAndResponseStage(ResponseEvent): Handling event with request_id 64fd660a-794b-4f97-89a1-bb07a3d96f9f
2022-05-04 20:42:55,082 - azure.iot.device.common.pipeline.pipeline_stages_base - INFO - CoordinateRequestAndResponseStage(ResponseEvent): request_id 64fd660a-794b-4f97-89a1-bb07a3d96f9f not found in pending list.  Nothing to do.  Dropping
2022-05-04 20:42:55,976 - gateway3_iot.device_client.device.Field 54115f0080000002 - DEBUG - Opened IoT hub client connection
2022-05-04 20:42:58,990 - gateway3_iot.device_client.device.Field 54115f0080000002 - DEBUG - Closing IoT hub client connection

[marcosatti]

I found a workaround that might be useful to other people:

self._client = IoTHubDeviceClient.create_from_connection_string(self._connection_string, auto_connect=False)

async with self.ensure_connection():
    # Do this first which forces the client to download a copy of the current twin.
    self._twin = await self._client.get_twin()
    await asyncio.sleep(1.0)
    # Then add the twin patch handler.
    self._client.on_twin_desired_properties_patch_received = self._handle_twin_desired_properties_patch_received_proxy

Doing it this way doesn't trigger the internal Sending twin request to GET resource / requests to happen when setting the event handler.

Edit:
Although the workaround works for this case, every subsequent connect (ie: sending a message) will unfortunately trigger the bug anyway, so its not much use to us :( . We have now opted to not use the event handler and simply poll every hour.

[cartertinney]

@marcosatti

We have successfully been able to reproduce this issue, and are now working on a fix. Thank you very much for the sample code - it helped a lot.

To be clear, one full twin retrieval is the expected behavior upon re-establishing a connection. However, it happening twice is incorrect, and that is the aspect we will be fixing.

[cartertinney]

@marcosatti

Issue has finally been fixed. The changes will be part of the next release.