search

Azure / azure-iot-sdk-python

A Python SDK for connecting devices to Microsoft Azure IoT services
MIT License
424 stars 379 forks source link

Disconnect without reconnect in rc13 #399

Closed oerpli closed 4 years ago

oerpli commented 4 years ago

Up until v2.0rc12 I sometimes had the issue with the (spurious) OutOfMemory error related to connection problems. Since updating to rc13 last week, I did not find those issues anymore, but instead had the following:

02:09:14|pipeline| ERROR |pipeline_stages:_on_mqtt_discon | MQTTTransportStage: _on_mqtt_disconnect called: Paho returned rc==1 caused by None
02:09:14|pipeline| WARNI |pipeline_stages:_on_mqtt_discon | MQTTTransportStage: disconnection was unexpected
02:09:14|pipeline| ERROR |handle_exceptio:handle_backgrou | Exception caught in background thread.  Unable to handle.
02:09:14|pipeline| ERROR |handle_exceptio:handle_backgrou | ['azure.iot.device.common.transport_exceptions.ConnectionDroppedError: None caused by Paho returned rc==1 caused by None\n']

From then on, the connection seemed to be dead with no more messages being sent. Should this exception be handled by the user (me) or should the reconnect be done by the SDK?

BertKleewein commented 4 years ago

Hi @oerpli

The reconnection should happen automatically, Are you able to privately share full logs with me?

Setting the logging level to INFO or even DEBUG would help. I really only need to see the _on_mqtt_disconnected message onward. There is a piece of code called the ReconnectStage which should detect this condition and reconnect. It sound like this reconnection code isn't being triggered (or is failing) and I'd like to figure out why.

-Bert

oerpli commented 4 years ago

I would like to share more, but that's all I have at the moment. I logged my application with logging level INFO, but after my excerpt all remaining log was from my code. (see next comment)

I restarted the process today and changed the logging level to DEBUG - I will add more, if there is something in the log then.

oerpli commented 4 years ago

Just noticed that the logging level of 3rd party code (the SDK) was set to WARNING when the bug above occurred. So not sure whether the IoT SDK emitted any more messages.

Since yesterday it's running with DEBUG but there haven't been any issues yet. I will post an update as soon as I know more.

MiguelCHR commented 4 years ago

Hi, i am having the same issue i will also try to catch something with debug

mounir-futurefacts commented 4 years ago

Experiencing the same error:

MQTTTransportStage: _on_mqtt_disconnect called: Paho returned rc==1 caused by None
MQTTTransportStage: disconnection was unexpected
Exception caught in background thread.  Unable to handle.
['azure.iot.device.common.transport_exceptions.ConnectionDroppedError: None caused by Paho returned rc==1 caused by None\n']

The code hangs and after keyboardinterrupt (hours later) we can see in which code segment:

 ^CTraceback (most recent call last):
  File "pull_data.py", line 288, in <module>
    db_data = write_data(socket.data, db_data, devices, now)
  File "pull_data.py", line 202, in write_data
    iothub_client.send_message(message)
  File "<string>", line 1, in send_message
  File "/home/user/anaconda3/lib/python3.7/site-packages/azure/iot/device/iothub/sync_clients.py", line 156, in send_message
    handle_result(callback)
  File "/home/user/anaconda3/lib/python3.7/site-packages/azure/iot/device/iothub/sync_clients.py", line 30, in handle_result
    return callback.wait_for_completion()
  File "/home/user/anaconda3/lib/python3.7/site-packages/azure/iot/device/common/evented_callback.py", line 67, in wait_for_completion
    self.completion_event.wait(*args, **kwargs)
  File "/home/user/anaconda3/lib/python3.7/threading.py", line 552, in wait
    signaled = self._cond.wait(timeout)
  File "/home/user/anaconda3/lib/python3.7/threading.py", line 296, in wait
    waiter.acquire()
KeyboardInterrupt
mounir-futurefacts commented 4 years ago

A more detailed log this time (@BertKleewein):

2019-11-28 14:17:49,353:INFO:Sending message to Hub...
2019-11-28 14:17:49,354:INFO:MQTTTransportStage(MQTTPublishOperation): publishing on devices/my-devices/messages/events/%24.ct=application%2Fjson&%24.ce=utf-8
2019-11-28 14:17:49,354:INFO:publishing on devices/my-devices/messages/events/%24.ct=application%2Fjson&%24.ce=utf-8
2019-11-28 14:18:14,871:ERROR:failed to receive on socket: [Errno 104] Connection reset by peer
2019-11-28 14:18:14,872:INFO:disconnected with result code: 1
2019-11-28 14:18:14,873:INFO:Forcing paho disconnect to prevent it from automatically reconnecting
2019-11-28 14:18:14,873:ERROR:MQTTTransportStage: _on_mqtt_disconnect called: Paho returned rc==1 caused by None
2019-11-28 14:18:14,874:INFO:ReconnectStage: disconnected, but not virtually connected.  Not triggering reconnect timer.
2019-11-28 14:18:14,874:WARNING:MQTTTransportStage: disconnection was unexpected
2019-11-28 14:18:14,874:ERROR:Exception caught in background thread.  Unable to handle.
2019-11-28 14:18:14,874:ERROR:['azure.iot.device.common.transport_exceptions.ConnectionDroppedError: None caused by Paho returned rc==1 caused by None\n']
2019-11-28 14:18:14,874:INFO:Connection State - Disconnected
2019-11-28 14:18:14,874:INFO:Cleared all pending method requests due to disconnect
mounir-futurefacts commented 4 years ago

I keep encountering this error every few hours when running a script that sends device to cloud messages (250 devices, sequentially). Here is the full DEBUG level error log. I really need this to work on production level soon, so would love to hear an update or maybe some workaround. Thanks

DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:OpTimeoutStage(MQTTPublishOperation): passing to next stage.
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:MQTTTransportStage(MQTTPublishOperation): running
INFO:azure.iot.device.common.pipeline.pipeline_stages_mqtt:MQTTTransportStage(MQTTPublishOperation): publishing on devices/devices/messages/events/%24.ct=application%2Fjson&%24.ce=utf-8
INFO:azure.iot.device.common.mqtt_transport:publishing on devices/devices/messages/events/%24.ct=application%2Fjson&%24.ce=utf-8
DEBUG:paho:Sending PUBLISH (d0, q1, r0, m2914), 'b'devices/devices/messages/events/%24.ct=application%2Fjson&%24.ce=utf-8'', ... (187 bytes)
DEBUG:azure.iot.device.common.mqtt_transport:_mqtt_client.publish returned rc=0
DEBUG:azure.iot.device.common.mqtt_transport:Waiting for response on MID: 2914
DEBUG:paho:Sending PINGREQ
DEBUG:paho:Sending PUBLISH (d1, q1, r0, m2914), 'b'devices/devices/messages/events/%24.ct=application%2Fjson&%24.ce=utf-8'', ... (187 bytes)
ERROR:paho:failed to receive on socket: [Errno 104] Connection reset by peer
INFO:azure.iot.device.common.mqtt_transport:disconnected with result code: 1
DEBUG:azure.iot.device.common.mqtt_transport:  File "/home/user/anaconda3/lib/python3.7/threading.py", line 890, in _bootstrap
    self._bootstrap_inner()
  File "/home/user/anaconda3/lib/python3.7/threading.py", line 926, in _bootstrap_inner
    self.run()
  File "/home/user/anaconda3/lib/python3.7/threading.py", line 870, in run
    self._target(*self._args, **self._kwargs)
  File "/home/user/anaconda3/lib/python3.7/site-packages/paho/mqtt/client.py", line 3428, in _thread_main
    self.loop_forever(retry_first_connection=True)
  File "/home/user/anaconda3/lib/python3.7/site-packages/paho/mqtt/client.py", line 1782, in loop_forever
    rc = self.loop(timeout, max_packets)
  File "/home/user/anaconda3/lib/python3.7/site-packages/paho/mqtt/client.py", line 1177, in loop
    rc = self.loop_read(max_packets)
  File "/home/user/anaconda3/lib/python3.7/site-packages/paho/mqtt/client.py", line 1570, in loop_read
    return self._loop_rc_handle(rc)
  File "/home/user/anaconda3/lib/python3.7/site-packages/paho/mqtt/client.py", line 2230, in _loop_rc_handle
    self.on_disconnect(self, self._userdata, rc)
  File "/home/user/anaconda3/lib/python3.7/site-packages/azure/iot/device/common/mqtt_transport.py", line 186, in on_disconnect
    logger.debug("".join(traceback.format_stack()))

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
DEBUG:azure.iot.device.common.pipeline.pipeline_thread:Starting _on_mqtt_disconnected in pipeline thread
ERROR:azure.iot.device.common.pipeline.pipeline_stages_mqtt:MQTTTransportStage: _on_mqtt_disconnect called: Paho returned rc==1 caused by None
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:ReconnectStage: on_disconnected
INFO:azure.iot.device.common.pipeline.pipeline_stages_base:ReconnectStage: disconnected, but not virtually connected.  Not triggering reconnect timer.
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:PipelineRootStage: on_disconnected.  on_disconnected_handler=<function IoTHubPipeline.__init__.<locals>._on_disconnected at 0x7fe954945c20>
DEBUG:azure.iot.device.common.pipeline.pipeline_thread:Starting _on_disconnected in callback thread
WARNING:azure.iot.device.common.pipeline.pipeline_stages_mqtt:MQTTTransportStage: disconnection was unexpected
ERROR:azure.iot.device.common.handle_exceptions:Exception caught in background thread.  Unable to handle.
ERROR:azure.iot.device.common.handle_exceptions:['azure.iot.device.common.transport_exceptions.ConnectionDroppedError: None caused by Paho returned rc==1 caused by None\n']
INFO:azure.iot.device.iothub.sync_clients:Connection State - Disconnected
INFO:azure.iot.device.iothub.sync_clients:Cleared all pending method requests due to disconnect
DEBUG:azure.iot.device.iothub.auth.base_renewable_token_authentication_provider:Timed SAS update for (devices,None)
INFO:azure.iot.device.iothub.auth.base_renewable_token_authentication_provider:Generating new SAS token for (devices,None) that expires 3600 seconds in the future
DEBUG:azure.iot.device.iothub.auth.base_renewable_token_authentication_provider:Canceling token update timer for (devices,None)
DEBUG:azure.iot.device.iothub.auth.base_renewable_token_authentication_provider:Scheduling token update for (devices,None) for 3480 seconds in the future
DEBUG:azure.iot.device.iothub.auth.base_renewable_token_authentication_provider:sending token update notification for (devices, None)
DEBUG:azure.iot.device.common.pipeline.pipeline_thread:Starting on_sas_token_updated in pipeline thread
INFO:azure.iot.device.iothub.pipeline.pipeline_stages_iothub:UseAuthProviderStage: New sas token received.  Passing down UpdateSasTokenOperation.
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:UseAuthProviderStage(UpdateSasTokenOperation): passing to next stage.
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:TwinRequestResponseStage(UpdateSasTokenOperation): running
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:TwinRequestResponseStage(UpdateSasTokenOperation): passing to next stage.
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:CoordinateRequestAndResponseStage(UpdateSasTokenOperation): running
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:CoordinateRequestAndResponseStage(UpdateSasTokenOperation): passing to next stage.
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:IoTHubMQTTTranslationStage(UpdateSasTokenOperation): running
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:IoTHubMQTTTranslationStage(UpdateSasTokenOperation): passing to next stage.
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:ReconnectStage(UpdateSasTokenOperation): running
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:ReconnectStage(UpdateSasTokenOperation): passing to next stage.
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:AutoConnectStage(UpdateSasTokenOperation): running
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:AutoConnectStage(UpdateSasTokenOperation): passing to next stage.
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:ConnectionLockStage(UpdateSasTokenOperation): running
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:ConnectionLockStage(UpdateSasTokenOperation): passing to next stage.
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:RetryStage(UpdateSasTokenOperation): running
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:RetryStage(UpdateSasTokenOperation): passing to next stage.
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:OpTimeoutStage(UpdateSasTokenOperation): running
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:OpTimeoutStage(UpdateSasTokenOperation): passing to next stage.
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:MQTTTransportStage(UpdateSasTokenOperation): running
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_mqtt:MQTTTransportStage(UpdateSasTokenOperation): saving sas token and completing
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:MQTTTransportStage(UpdateSasTokenOperation): completing without error
DEBUG:azure.iot.device.iothub.pipeline.pipeline_stages_iothub:UseAuthProviderStage(UpdateSasTokenOperation): token update operation is complete
DEBUG:azure.iot.device.iothub.auth.base_renewable_token_authentication_provider:Timed SAS update for (devices,None)
INFO:azure.iot.device.iothub.auth.base_renewable_token_authentication_provider:Generating new SAS token for (devices,None) that expires 3600 seconds in the future
DEBUG:azure.iot.device.iothub.auth.base_renewable_token_authentication_provider:Canceling token update timer for (devices,None)
DEBUG:azure.iot.device.iothub.auth.base_renewable_token_authentication_provider:Scheduling token update for (devices,None) for 3480 seconds in the future
DEBUG:azure.iot.device.iothub.auth.base_renewable_token_authentication_provider:sending token update notification for (devices, None)
DEBUG:azure.iot.device.common.pipeline.pipeline_thread:Starting on_sas_token_updated in pipeline thread
INFO:azure.iot.device.iothub.pipeline.pipeline_stages_iothub:UseAuthProviderStage: New sas token received.  Passing down UpdateSasTokenOperation.
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:UseAuthProviderStage(UpdateSasTokenOperation): passing to next stage.
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:TwinRequestResponseStage(UpdateSasTokenOperation): running
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:TwinRequestResponseStage(UpdateSasTokenOperation): passing to next stage.
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:CoordinateRequestAndResponseStage(UpdateSasTokenOperation): running
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:CoordinateRequestAndResponseStage(UpdateSasTokenOperation): passing to next stage.
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:IoTHubMQTTTranslationStage(UpdateSasTokenOperation): running
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:IoTHubMQTTTranslationStage(UpdateSasTokenOperation): passing to next stage.
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:ReconnectStage(UpdateSasTokenOperation): running
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:ReconnectStage(UpdateSasTokenOperation): passing to next stage.
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:AutoConnectStage(UpdateSasTokenOperation): running
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:AutoConnectStage(UpdateSasTokenOperation): passing to next stage.
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:ConnectionLockStage(UpdateSasTokenOperation): running
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:ConnectionLockStage(UpdateSasTokenOperation): passing to next stage.
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:RetryStage(UpdateSasTokenOperation): running
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:RetryStage(UpdateSasTokenOperation): passing to next stage.
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:OpTimeoutStage(UpdateSasTokenOperation): running
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:OpTimeoutStage(UpdateSasTokenOperation): passing to next stage.
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:MQTTTransportStage(UpdateSasTokenOperation): running
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_mqtt:MQTTTransportStage(UpdateSasTokenOperation): saving sas token and completing
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:MQTTTransportStage(UpdateSasTokenOperation): completing without error
DEBUG:azure.iot.device.iothub.pipeline.pipeline_stages_iothub:UseAuthProviderStage(UpdateSasTokenOperation): token update operation is complete
DEBUG:azure.iot.device.iothub.auth.base_renewable_token_authentication_provider:Timed SAS update for (devices,None)
BertKleewein commented 4 years ago

@mounir-futurefacts - I think I see the problem here (and a hole in our testing).

INFO:azure.iot.device.common.pipeline.pipeline_stages_base:ReconnectStage: disconnected, but not virtually connected.  Not triggering reconnect timer.

Your first send_message call was causing the client to connect automatically, and that's the way it's supposed to work, but that code path wasn't setting the flag that triggered the automatic reconnect logic.

You should be able to work around this by calling connect() on the client object before you start sending messages.

mounir-futurefacts commented 4 years ago

@BertKleewein - thanks, this seems to be the problem indeed. I have not tested it with a single call to the connect() method, but since I updated my code yesterday to manually connect and reconnect every x messages it is now running for 24hrs straight with no problems.

You probably want to update the quickstarts (at least the simulated device quickstart which I used as a starting point for my project) to use the connect() method before sending messages. Created a pull request for the code that I used.

oerpli commented 4 years ago

Is this an issue that should be handled by the user (of the SDK) or by the SDK itself? In case of the latter - is there a timeline when it will be done?

BertKleewein commented 4 years ago

@oerpli - this _hould be done by the SDK. Calling connect from the client is just a workaround and only needs to be called one single time. If you're not seeing a line in the log (level INFO) that says ReconnectStage: disconnected, but not virtually connected. Not triggering reconnect timer. then your issue has a different cause.

LouanDuToitS3 commented 4 years ago

@BertKleewein - Hi, after running fine for 48 hours with the released V2 I got:

2019-12-19T13:06:15.223826117Z Traceback (most recent call last):
2019-12-19T13:06:15.223830512Z   File "/usr/lib/python3.6/threading.py", line 916, in _bootstrap_inner
2019-12-19T13:06:15.223833200Z     self.run()
2019-12-19T13:06:15.223835405Z   File "/usr/lib/python3.6/threading.py", line 864, in run
2019-12-19T13:06:15.223837631Z     self._target(*self._args, **self._kwargs)
2019-12-19T13:06:15.223839747Z   File "/usr/local/lib/python3.6/dist-packages/paho/mqtt/client.py", line 3428, in _thread_main
2019-12-19T13:06:15.223841888Z     self.loop_forever(retry_first_connection=True)
2019-12-19T13:06:15.223844001Z   File "/usr/local/lib/python3.6/dist-packages/paho/mqtt/client.py", line 1782, in loop_forever
2019-12-19T13:06:15.223846164Z     rc = self.loop(timeout, max_packets)
2019-12-19T13:06:15.223848182Z   File "/usr/local/lib/python3.6/dist-packages/paho/mqtt/client.py", line 1177, in loop
2019-12-19T13:06:15.223850282Z     rc = self.loop_read(max_packets)
2019-12-19T13:06:15.223852358Z   File "/usr/local/lib/python3.6/dist-packages/paho/mqtt/client.py", line 1568, in loop_read
2019-12-19T13:06:15.223858128Z     rc = self._packet_read()
2019-12-19T13:06:15.223862615Z   File "/usr/local/lib/python3.6/dist-packages/paho/mqtt/client.py", line 2271, in _packet_read
2019-12-19T13:06:15.223865276Z     byte = self._sock_recv(1)
2019-12-19T13:06:15.223867305Z   File "/usr/local/lib/python3.6/dist-packages/paho/mqtt/client.py", line 660, in _sock_recv
2019-12-19T13:06:15.223869622Z     return self._sock.recv(bufsize)
2019-12-19T13:06:15.223875624Z AttributeError: 'NoneType' object has no attribute 'recv'

So for me this issue persist....

Kyrylo-Iarosh commented 4 years ago

Hi guys,

Also observed this issue several times during our custom module development.

MQTTTransportStage: _on_mqtt_disconnect called: Paho returned rc==1 caused by None
MQTTTransportStage: disconnection was unexpected
Exception caught in background thread.  Unable to handle.
['azure.iot.device.common.transport_exceptions.ConnectionDroppedError: None caused by Paho returned rc==1 caused by None\n']

Unfortunately (or luckily), cannot reproduce it now with debug log level. Issue happens quite unpredictable and not on a regular basis. I will share logs when observe it again.

oerpli commented 4 years ago

As a quick update: I added the .connect() and haven't had a single issue since the last restart (around mid December).

msjaber commented 4 years ago

This is weird. Whenever I try to run receive_message.py or receive_direct_method.py, it keeps disconnecting every few seconds.

Here's the log if it helps:

DEBUG:asyncio:Using selector: KqueueSelector
INFO:azure.iot.device.iothub.auth.sk_authentication_provider:Using Shared Key authentication for {ugv-a.azure-devices.net, ugv-black, None}
DEBUG:azure.iot.device.common.pipeline.pipeline_thread:Starting run_op in pipeline thread
DEBUG:azure.iot.device.common.pipeline.pipeline_thread:Creating pipeline executor
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:PipelineRootStage(SetAuthProviderOperation): running
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:PipelineRootStage(SetAuthProviderOperation): passing to next stage.
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:UseAuthProviderStage(SetAuthProviderOperation): running
INFO:azure.iot.device.iothub.auth.base_renewable_token_authentication_provider:Generating new SAS token for (ugv-black,None) that expires 3600 seconds in the future
DEBUG:azure.iot.device.iothub.auth.base_renewable_token_authentication_provider:Scheduling token update for (ugv-black,None) for 3480 seconds in the future
DEBUG:azure.iot.device.iothub.auth.base_renewable_token_authentication_provider:sending token update notification for (ugv-black, None)
DEBUG:azure.iot.device.common.pipeline.pipeline_thread:Already in pipeline thread for _on_sas_token_updated
INFO:azure.iot.device.iothub.pipeline.pipeline_stages_iothub:UseAuthProviderStage: New sas token received.  Passing down UpdateSasTokenOperation.
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:UseAuthProviderStage(UpdateSasTokenOperation): passing to next stage.
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:IoTHubHTTPTranslationStage(UpdateSasTokenOperation): running
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:IoTHubHTTPTranslationStage(UpdateSasTokenOperation): passing to next stage.
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:HTTPTransportStage(UpdateSasTokenOperation): running
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_http:HTTPTransportStage(UpdateSasTokenOperation): saving sas token and completing
DEBUG:azure.iot.device.common.pipeline.pipeline_ops_base:UpdateSasTokenOperation: completing without error
DEBUG:azure.iot.device.iothub.pipeline.pipeline_stages_iothub:UseAuthProviderStage(UpdateSasTokenOperation): token update operation is complete
DEBUG:azure.iot.device.common.pipeline.pipeline_ops_base:SetAuthProviderOperation: creating worker op of type SetIoTHubConnectionArgsOperation
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:UseAuthProviderStage(SetIoTHubConnectionArgsOperation): passing to next stage.
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:IoTHubHTTPTranslationStage(SetIoTHubConnectionArgsOperation): running
DEBUG:azure.iot.device.iothub.pipeline.pipeline_stages_iothub_http:Gateway Hostname not present. Setting Hostname to: None
DEBUG:azure.iot.device.common.pipeline.pipeline_ops_base:SetIoTHubConnectionArgsOperation: creating worker op of type SetHTTPConnectionArgsOperation
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:IoTHubHTTPTranslationStage(SetHTTPConnectionArgsOperation): passing to next stage.
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:HTTPTransportStage(SetHTTPConnectionArgsOperation): running
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_http:HTTPTransportStage(SetHTTPConnectionArgsOperation): got connection args
DEBUG:azure.iot.device.common.http_transport:creating a SSL context
DEBUG:azure.iot.device.common.pipeline.pipeline_ops_base:SetHTTPConnectionArgsOperation: completing without error
DEBUG:azure.iot.device.common.pipeline.pipeline_ops_base:SetIoTHubConnectionArgsOperation: Worker op (SetHTTPConnectionArgsOperation) has been completed
DEBUG:azure.iot.device.common.pipeline.pipeline_ops_base:SetIoTHubConnectionArgsOperation: completing without error
DEBUG:azure.iot.device.common.pipeline.pipeline_ops_base:SetAuthProviderOperation: Worker op (SetIoTHubConnectionArgsOperation) has been completed
DEBUG:azure.iot.device.common.pipeline.pipeline_ops_base:SetAuthProviderOperation: completing without error
DEBUG:azure.iot.device.common.pipeline.pipeline_thread:Starting <azure.iot.device.common.evented_callback.EventedCallback object at 0x10da4ce10> in callback thread
DEBUG:azure.iot.device.common.pipeline.pipeline_thread:Creating callback executor
DEBUG:azure.iot.device.common.evented_callback:Callback completed with result None
DEBUG:azure.iot.device.common.pipeline.pipeline_thread:Starting run_op in pipeline thread
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:PipelineRootStage(SetAuthProviderOperation): running
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:PipelineRootStage(SetAuthProviderOperation): passing to next stage.
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:UseAuthProviderStage(SetAuthProviderOperation): running
DEBUG:azure.iot.device.common.pipeline.pipeline_ops_base:SetAuthProviderOperation: creating worker op of type SetIoTHubConnectionArgsOperation
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:UseAuthProviderStage(SetIoTHubConnectionArgsOperation): passing to next stage.
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:TwinRequestResponseStage(SetIoTHubConnectionArgsOperation): running
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:TwinRequestResponseStage(SetIoTHubConnectionArgsOperation): passing to next stage.
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:CoordinateRequestAndResponseStage(SetIoTHubConnectionArgsOperation): running
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:CoordinateRequestAndResponseStage(SetIoTHubConnectionArgsOperation): passing to next stage.
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:IoTHubMQTTTranslationStage(SetIoTHubConnectionArgsOperation): running
DEBUG:azure.iot.device.common.pipeline.pipeline_ops_base:SetIoTHubConnectionArgsOperation: creating worker op of type SetMQTTConnectionArgsOperation
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:IoTHubMQTTTranslationStage(SetMQTTConnectionArgsOperation): passing to next stage.
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:ReconnectStage(SetMQTTConnectionArgsOperation): running
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:ReconnectStage(SetMQTTConnectionArgsOperation): passing to next stage.
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:AutoConnectStage(SetMQTTConnectionArgsOperation): running
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:AutoConnectStage(SetMQTTConnectionArgsOperation): passing to next stage.
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:ConnectionLockStage(SetMQTTConnectionArgsOperation): running
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:ConnectionLockStage(SetMQTTConnectionArgsOperation): passing to next stage.
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:RetryStage(SetMQTTConnectionArgsOperation): running
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:RetryStage(SetMQTTConnectionArgsOperation): passing to next stage.
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:OpTimeoutStage(SetMQTTConnectionArgsOperation): running
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:OpTimeoutStage(SetMQTTConnectionArgsOperation): passing to next stage.
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:MQTTTransportStage(SetMQTTConnectionArgsOperation): running
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_mqtt:MQTTTransportStage(SetMQTTConnectionArgsOperation): got connection args
INFO:azure.iot.device.common.mqtt_transport:creating mqtt client
INFO:azure.iot.device.common.mqtt_transport:Creating client for connecting using MQTT over TCP
DEBUG:azure.iot.device.common.mqtt_transport:creating a SSL context
DEBUG:azure.iot.device.common.mqtt_transport:Created MQTT protocol client, assigned callbacks
DEBUG:azure.iot.device.common.pipeline.pipeline_ops_base:SetMQTTConnectionArgsOperation: completing without error
DEBUG:azure.iot.device.common.pipeline.pipeline_ops_base:SetIoTHubConnectionArgsOperation: Worker op (SetMQTTConnectionArgsOperation) has been completed
DEBUG:azure.iot.device.common.pipeline.pipeline_ops_base:SetIoTHubConnectionArgsOperation: completing without error
DEBUG:azure.iot.device.common.pipeline.pipeline_ops_base:SetAuthProviderOperation: Worker op (SetIoTHubConnectionArgsOperation) has been completed
DEBUG:azure.iot.device.common.pipeline.pipeline_ops_base:SetAuthProviderOperation: completing without error
DEBUG:azure.iot.device.common.pipeline.pipeline_thread:Starting <azure.iot.device.common.evented_callback.EventedCallback object at 0x10da77990> in callback thread
DEBUG:azure.iot.device.common.evented_callback:Callback completed with result None
INFO:azure.iot.device.iothub.aio.async_clients:Connecting to Hub...
DEBUG:azure.iot.device.iothub.pipeline.iothub_pipeline:Starting ConnectOperation on the pipeline
DEBUG:azure.iot.device.common.pipeline.pipeline_thread:Starting run_op in pipeline thread
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:PipelineRootStage(ConnectOperation): running
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:PipelineRootStage(ConnectOperation): passing to next stage.
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:UseAuthProviderStage(ConnectOperation): running
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:UseAuthProviderStage(ConnectOperation): passing to next stage.
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:TwinRequestResponseStage(ConnectOperation): running
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:TwinRequestResponseStage(ConnectOperation): passing to next stage.
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:CoordinateRequestAndResponseStage(ConnectOperation): running
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:CoordinateRequestAndResponseStage(ConnectOperation): passing to next stage.
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:IoTHubMQTTTranslationStage(ConnectOperation): running
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:IoTHubMQTTTranslationStage(ConnectOperation): passing to next stage.
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:ReconnectStage(ConnectOperation): running
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:ReconnectStage(ConnectOperation): passing to next stage.
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:AutoConnectStage(ConnectOperation): running
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:AutoConnectStage(ConnectOperation): passing to next stage.
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:ConnectionLockStage(ConnectOperation): running
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:ConnectionLockStage(ConnectOperation): blocking
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:ConnectionLockStage(ConnectOperation): passing to next stage.
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:RetryStage(ConnectOperation): running
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:RetryStage(ConnectOperation): passing to next stage.
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:OpTimeoutStage(ConnectOperation): running
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:OpTimeoutStage(ConnectOperation): passing to next stage.
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:MQTTTransportStage(ConnectOperation): running
INFO:azure.iot.device.common.pipeline.pipeline_stages_mqtt:MQTTTransportStage(ConnectOperation): connecting
INFO:azure.iot.device.common.mqtt_transport:connecting to mqtt broker
INFO:azure.iot.device.common.mqtt_transport:Connect using port 8883 (TCP)
DEBUG:paho:Sending CONNECT (u1, p1, wr0, wq0, wf0, c0, k60) client_id=b'ugv-black'
DEBUG:azure.iot.device.common.mqtt_transport:_mqtt_client.connect returned rc=0
DEBUG:paho:Received CONNACK (1, 0)
INFO:azure.iot.device.common.mqtt_transport:connected with result code: 0
DEBUG:azure.iot.device.common.pipeline.pipeline_thread:Starting _on_mqtt_connected in pipeline thread
INFO:azure.iot.device.common.pipeline.pipeline_stages_mqtt:_on_mqtt_connected called
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:MQTTTransportStage(ConnectedEvent): pushing event up to OpTimeoutStage
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:OpTimeoutStage(ConnectedEvent): pushing event up to RetryStage
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:RetryStage(ConnectedEvent): pushing event up to ConnectionLockStage
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:ConnectionLockStage(ConnectedEvent): pushing event up to AutoConnectStage
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:AutoConnectStage(ConnectedEvent): pushing event up to ReconnectStage
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:ReconnectStage(ConnectedEvent): pushing event up to IoTHubMQTTTranslationStage
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:IoTHubMQTTTranslationStage(ConnectedEvent): pushing event up to CoordinateRequestAndResponseStage
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:CoordinateRequestAndResponseStage(ConnectedEvent): pushing event up to TwinRequestResponseStage
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:TwinRequestResponseStage(ConnectedEvent): pushing event up to UseAuthProviderStage
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:UseAuthProviderStage(ConnectedEvent): pushing event up to PipelineRootStage
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:PipelineRootStage: ConnectedEvent received. Calling on_connected_handler
DEBUG:azure.iot.device.common.pipeline.pipeline_thread:Starting _on_connected in callback thread
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_mqtt:completing connect op
INFO:azure.iot.device.iothub.aio.async_clients:Connection State - Connected
DEBUG:azure.iot.device.common.pipeline.pipeline_ops_base:ConnectOperation: completing without error
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:ConnectionLockStage(ConnectOperation): op succeeded.  Unblocking queue
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:ConnectionLockStage(ConnectOperation): unblocking and releasing queued ops.
INFO:azure.iot.device.common.pipeline.pipeline_stages_base:ConnectionLockStage(ConnectOperation): processing 0 items in queue
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:ConnectionLockStage(ConnectOperation): unblock is complete
DEBUG:azure.iot.device.common.pipeline.pipeline_thread:Starting on_complete in callback thread
DEBUG:azure.iot.device.common.async_adapter:Callback completed with result None
INFO:azure.iot.device.iothub.aio.async_clients:Successfully connected to Hub
Press Q to quit
INFO:azure.iot.device.iothub.aio.async_clients:Enabling feature:methods...
DEBUG:azure.iot.device.iothub.pipeline.iothub_pipeline:enable_feature methods called
DEBUG:azure.iot.device.common.pipeline.pipeline_thread:Starting run_op in pipeline thread
INFO:azure.iot.device.iothub.aio.async_clients:Waiting for method request...
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:PipelineRootStage(EnableFeatureOperation): running
INFO:azure.iot.device.iothub.aio.async_clients:Waiting for method request...
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:PipelineRootStage(EnableFeatureOperation): passing to next stage.
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:UseAuthProviderStage(EnableFeatureOperation): running
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:UseAuthProviderStage(EnableFeatureOperation): passing to next stage.
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:TwinRequestResponseStage(EnableFeatureOperation): running
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:TwinRequestResponseStage(EnableFeatureOperation): passing to next stage.
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:CoordinateRequestAndResponseStage(EnableFeatureOperation): running
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:CoordinateRequestAndResponseStage(EnableFeatureOperation): passing to next stage.
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:IoTHubMQTTTranslationStage(EnableFeatureOperation): running
DEBUG:azure.iot.device.common.pipeline.pipeline_ops_base:EnableFeatureOperation: creating worker op of type MQTTSubscribeOperation
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:IoTHubMQTTTranslationStage(MQTTSubscribeOperation): passing to next stage.
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:ReconnectStage(MQTTSubscribeOperation): running
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:ReconnectStage(MQTTSubscribeOperation): passing to next stage.
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:AutoConnectStage(MQTTSubscribeOperation): running
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:AutoConnectStage(MQTTSubscribeOperation): passing to next stage.
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:ConnectionLockStage(MQTTSubscribeOperation): running
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:ConnectionLockStage(MQTTSubscribeOperation): passing to next stage.
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:RetryStage(MQTTSubscribeOperation): running
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:RetryStage(MQTTSubscribeOperation): passing to next stage.
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:OpTimeoutStage(MQTTSubscribeOperation): running
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:OpTimeoutStage(MQTTSubscribeOperation): Creating timer
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:OpTimeoutStage(MQTTSubscribeOperation): Sending down
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:OpTimeoutStage(MQTTSubscribeOperation): passing to next stage.
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:MQTTTransportStage(MQTTSubscribeOperation): running
INFO:azure.iot.device.common.pipeline.pipeline_stages_mqtt:MQTTTransportStage(MQTTSubscribeOperation): subscribing to $iothub/methods/POST/#
INFO:azure.iot.device.common.mqtt_transport:subscribing to $iothub/methods/POST/# with qos 1
DEBUG:paho:Sending SUBSCRIBE (d0, m1) [(b'$iothub/methods/POST/#', 1)]
DEBUG:azure.iot.device.common.mqtt_transport:_mqtt_client.subscribe returned rc=0
DEBUG:azure.iot.device.common.mqtt_transport:Waiting for response on MID: 1
DEBUG:paho:Received SUBACK
INFO:azure.iot.device.common.mqtt_transport:suback received for 1
DEBUG:azure.iot.device.common.mqtt_transport:Response received for recognized MID: 1 - triggering callback
DEBUG:azure.iot.device.common.pipeline.pipeline_thread:Starting on_subscribed in pipeline thread
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_mqtt:MQTTTransportStage(MQTTSubscribeOperation): SUBACK received. completing op.
DEBUG:azure.iot.device.common.pipeline.pipeline_ops_base:MQTTSubscribeOperation: completing without error
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:OpTimeoutStage(MQTTSubscribeOperation): Cancelling timer
DEBUG:azure.iot.device.common.pipeline.pipeline_ops_base:EnableFeatureOperation: Worker op (MQTTSubscribeOperation) has been completed
DEBUG:azure.iot.device.common.pipeline.pipeline_ops_base:EnableFeatureOperation: completing without error
DEBUG:azure.iot.device.common.pipeline.pipeline_thread:Starting on_complete in callback thread
DEBUG:azure.iot.device.common.async_adapter:Callback completed with result None
INFO:azure.iot.device.iothub.aio.async_clients:Successfully enabled feature:methods
INFO:azure.iot.device.iothub.aio.async_clients:Waiting for method request...
INFO:azure.iot.device.common.mqtt_transport:disconnected with result code: 1
DEBUG:azure.iot.device.common.mqtt_transport:  File "/usr/local/Cellar/python/3.7.5/Frameworks/Python.framework/Versions/3.7/lib/python3.7/threading.py", line 890, in _bootstrap
    self._bootstrap_inner()
  File "/usr/local/Cellar/python/3.7.5/Frameworks/Python.framework/Versions/3.7/lib/python3.7/threading.py", line 926, in _bootstrap_inner
    self.run()
  File "/usr/local/Cellar/python/3.7.5/Frameworks/Python.framework/Versions/3.7/lib/python3.7/threading.py", line 870, in run
    self._target(*self._args, **self._kwargs)
  File "/usr/local/lib/python3.7/site-packages/paho/mqtt/client.py", line 3428, in _thread_main
    self.loop_forever(retry_first_connection=True)
  File "/usr/local/lib/python3.7/site-packages/paho/mqtt/client.py", line 1782, in loop_forever
    rc = self.loop(timeout, max_packets)
  File "/usr/local/lib/python3.7/site-packages/paho/mqtt/client.py", line 1177, in loop
    rc = self.loop_read(max_packets)
  File "/usr/local/lib/python3.7/site-packages/paho/mqtt/client.py", line 1570, in loop_read
    return self._loop_rc_handle(rc)
  File "/usr/local/lib/python3.7/site-packages/paho/mqtt/client.py", line 2230, in _loop_rc_handle
    self.on_disconnect(self, self._userdata, rc)
  File "/usr/local/lib/python3.7/site-packages/azure/iot/device/common/mqtt_transport.py", line 186, in on_disconnect
    logger.debug("".join(traceback.format_stack()))

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
DEBUG:azure.iot.device.common.pipeline.pipeline_thread:Starting _on_mqtt_disconnected in pipeline thread
ERROR:azure.iot.device.common.pipeline.pipeline_stages_mqtt:MQTTTransportStage: _on_mqtt_disconnect called: Paho returned rc==1 caused by None
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:MQTTTransportStage(DisconnectedEvent): pushing event up to OpTimeoutStage
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:OpTimeoutStage(DisconnectedEvent): pushing event up to RetryStage
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:RetryStage(DisconnectedEvent): pushing event up to ConnectionLockStage
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:ConnectionLockStage(DisconnectedEvent): pushing event up to AutoConnectStage
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:AutoConnectStage(DisconnectedEvent): pushing event up to ReconnectStage
INFO:azure.iot.device.common.pipeline.pipeline_stages_base:ReconnectStage: disconnected but virtually connected.  Triggering reconnect timer.
INFO:azure.iot.device.common.pipeline.pipeline_stages_base:ReconnectStage: Setting reconnect timer
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:ReconnectStage(DisconnectedEvent): pushing event up to IoTHubMQTTTranslationStage
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:IoTHubMQTTTranslationStage(DisconnectedEvent): pushing event up to CoordinateRequestAndResponseStage
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:CoordinateRequestAndResponseStage(DisconnectedEvent): pushing event up to TwinRequestResponseStage
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:TwinRequestResponseStage(DisconnectedEvent): pushing event up to UseAuthProviderStage
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:UseAuthProviderStage(DisconnectedEvent): pushing event up to PipelineRootStage
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
WARNING:azure.iot.device.common.pipeline.pipeline_stages_mqtt:MQTTTransportStage: disconnection was unexpected
INFO:azure.iot.device.iothub.aio.async_clients:Connection State - Disconnected
ERROR:azure.iot.device.common.handle_exceptions:Exception caught in background thread.  Unable to handle.
INFO:azure.iot.device.iothub.aio.async_clients:Cleared all pending method requests due to disconnect
ERROR:azure.iot.device.common.handle_exceptions:['azure.iot.device.common.transport_exceptions.ConnectionDroppedError: None caused by Paho returned rc==1 caused by None\n']
DEBUG:azure.iot.device.common.pipeline.pipeline_thread:Starting on_reconnect_timer_expired in pipeline thread
INFO:azure.iot.device.common.pipeline.pipeline_stages_base:ReconnectStage: reconnect timer expired.  Sending connect op down
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:ReconnectStage: Sending connect operation down
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:ReconnectStage(ConnectOperation): passing to next stage.
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:AutoConnectStage(ConnectOperation): running
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:AutoConnectStage(ConnectOperation): passing to next stage.
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:ConnectionLockStage(ConnectOperation): running
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:ConnectionLockStage(ConnectOperation): blocking
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:ConnectionLockStage(ConnectOperation): passing to next stage.
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:RetryStage(ConnectOperation): running
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:RetryStage(ConnectOperation): passing to next stage.
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:OpTimeoutStage(ConnectOperation): running
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:OpTimeoutStage(ConnectOperation): passing to next stage.
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:MQTTTransportStage(ConnectOperation): running
INFO:azure.iot.device.common.pipeline.pipeline_stages_mqtt:MQTTTransportStage(ConnectOperation): connecting
INFO:azure.iot.device.common.mqtt_transport:connecting to mqtt broker
INFO:azure.iot.device.common.mqtt_transport:Connect using port 8883 (TCP)
DEBUG:paho:Sending CONNECT (u1, p1, wr0, wq0, wf0, c0, k60) client_id=b'ugv-black'
DEBUG:azure.iot.device.common.mqtt_transport:_mqtt_client.connect returned rc=0
DEBUG:paho:Received CONNACK (1, 0)
INFO:azure.iot.device.common.mqtt_transport:connected with result code: 0
DEBUG:azure.iot.device.common.pipeline.pipeline_thread:Starting _on_mqtt_connected in pipeline thread
INFO:azure.iot.device.common.pipeline.pipeline_stages_mqtt:_on_mqtt_connected called
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:MQTTTransportStage(ConnectedEvent): pushing event up to OpTimeoutStage
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:OpTimeoutStage(ConnectedEvent): pushing event up to RetryStage
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:RetryStage(ConnectedEvent): pushing event up to ConnectionLockStage
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:ConnectionLockStage(ConnectedEvent): pushing event up to AutoConnectStage
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:AutoConnectStage(ConnectedEvent): pushing event up to ReconnectStage
INFO:azure.iot.device.common.pipeline.pipeline_stages_base:ReconnectStage: Clearing reconnect timer
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:ReconnectStage(ConnectedEvent): pushing event up to IoTHubMQTTTranslationStage
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:IoTHubMQTTTranslationStage(ConnectedEvent): pushing event up to CoordinateRequestAndResponseStage
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:CoordinateRequestAndResponseStage(ConnectedEvent): pushing event up to TwinRequestResponseStage
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:TwinRequestResponseStage(ConnectedEvent): pushing event up to UseAuthProviderStage
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:UseAuthProviderStage(ConnectedEvent): pushing event up to PipelineRootStage
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:PipelineRootStage: ConnectedEvent received. Calling on_connected_handler
DEBUG:azure.iot.device.common.pipeline.pipeline_thread:Starting _on_connected in callback thread
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_mqtt:completing connect op
DEBUG:azure.iot.device.common.pipeline.pipeline_ops_base:ConnectOperation: completing without error
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:ConnectionLockStage(ConnectOperation): op succeeded.  Unblocking queue
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:ConnectionLockStage(ConnectOperation): unblocking and releasing queued ops.
INFO:azure.iot.device.common.pipeline.pipeline_stages_base:ConnectionLockStage(ConnectOperation): processing 0 items in queue
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:ConnectionLockStage(ConnectOperation): unblock is complete
DEBUG:azure.iot.device.common.pipeline.pipeline_stages_base:ReconnectStage: reconnect successful
INFO:azure.iot.device.iothub.aio.async_clients:Connection State - Connected
BertKleewein commented 4 years ago

@msjaber - From this log, I see the disconnects and I see the library reconnecting. It looks like the python library is behaving as it should given what it can control. If the library sees the connection drop, it tries to reconnect.

I don't see anything in that log showing a cause for the frequent disconnects. It looks like the library is reconnecting successfully but something else is causing the connection to drop again, which causes the library to reconnect, and so on. The thing causing the connection to drop could be anything: a buggy device driver, a loose cable in your PC, a misbehaving switch or cable at any of the dozens of hops between your location and the Azure data center, or even, gasp, a problem with one of the Azure machines which backs your IoTHub instance.

The other thing, which comes up more often than you might think, is when 2 different clients are connecting using the same device credentials. If there's 2 processes both trying to connect as the same device, they can ping-pong back and forth. One process would connect, which causes the second process to disconnect, then when the second process reconnects, it causes the first process to disconnect, and so on.

The library is doing its best to remain connected, but something else about the network is causing this extra traffic. The reconnect code is currently very aggressive, meaning it will always try to reconnect fairly soon after the disconnect (I think 10 seconds). There's no notion (yet) of backing off on re-connection frequency o possibly even giving up after some number of failures.

LouanDuToitS3 commented 4 years ago

As a quick update: I added the .connect() and haven't had a single issue since the last restart (around mid December).

Unfortunately this does not resolve the issue for me. The module remains disconnected, which leads me to believe that the SDK itself still believes it is connected. Therefore even if a method is made available to query the status of the connection a "connected" response will probably be returned.

lokijota commented 4 years ago

Same here. Added the connect() call and just get sequences of the following:

MQTTTransportStage: _on_mqtt_disconnect called: Paho returned rc==1 caused by None MQTTTransportStage: disconnection was unexpected Exception caught in background thread. Unable to handle. ['azure.iot.device.common.transport_exceptions.ConnectionDroppedError: None caused by Paho returned rc==1 caused by None\n'] failed to receive on socket: [Errno 104] Connection reset by peer M

BertKleewein commented 4 years ago

Unfortunately this does not resolve the issue for me. The module remains disconnected, which leads me to believe that the SDK itself still believes it is connected. Therefore even if a method is made available to query the status of the connection a "connected" response will probably be returned.

@LouanDuToitS3 - this may be true, but in my experience, it's more likely that the SDK knows that it's disconnected, but the logic to automatically reconnect is not working correctly.

BertKleewein commented 4 years ago

Same here. Added the connect() call and just get sequences of the following:

failed to receive on socket: [Errno 104] Connection reset by peer

@lokijota - There are many reasons why this message might come up. Since you're seeing this repeatedly, it tells me that the SDK keeps trying to reconnect and something upstream (the iothub server possibly) keeps disconnecting you. Most recently, I'm looking at a case where using send_message to send a too-big message (256 KB) causes this to happen (part of #441 ). Can you tell me what you're doing with the device client before this happens?

LouanDuToitS3 commented 4 years ago

Unfortunately this does not resolve the issue for me. The module remains disconnected, which leads me to believe that the SDK itself still believes it is connected. Therefore even if a method is made available to query the status of the connection a "connected" response will probably be returned.

@LouanDuToitS3 - this may be true, but in my experience, it's more likely that the SDK knows that it's disconnected, but the logic to automatically reconnect is not working correctly.

@BertKleewein But then, would calling connect() not resolve the issue, because it does not.

BertKleewein commented 4 years ago

But then, would calling connect() not resolve the issue, because it does not.

@LouanDuToitS3: Good point. Can you send me the debug output you get after you call connect? This could help figure out the cause. Also, for what it's worth, I'm trying to figure out why the 2.0.1 release isn't on pypi.

lokijota commented 4 years ago

Same here. Added the connect() call and just get sequences of the following:

MQTTTransportStage: _on_mqtt_disconnect called: Paho returned rc==1 caused by None MQTTTransportStage: disconnection was unexpected Exception caught in background thread. Unable to handle. ['azure.iot.device.common.transport_exceptions.ConnectionDroppedError: None caused by Paho returned rc==1 caused by None\n'] failed to receive on socket: [Errno 104] Connection reset by peer

This is fixed from my end. I was sending contents of CSV files and by mistake a pretty large one was left in the folder - causing the send_message to fail. A better error message would have been helpful, in any case. //hint, hint :-)

LouanDuToitS3 commented 4 years ago

But then, would calling connect() not resolve the issue, because it does not.

@LouanDuToitS3: Good point. Can you send me the debug output you get after you call connect? This could help figure out the cause. Also, for what it's worth, I'm trying to figure out why the 2.0.1 release isn't on pypi.

@BertKleewein Give me a couple of days, I will shift some priorities, and get what I can. I run the code with "info" level debug only, so will enable "debug" level. Problem is we send 100's of messages a minute, so the logs gets very big, very quickly.

elliotchaim commented 4 years ago

I am also having this issue. 3x Python modules on the same device all experienced this issue around the same time, which was after around 3 days of being Up. I'm using IoT Edge for what its worth. Error from the logs of one of these modules below:

MQTTTransportStage: _on_mqtt_disconnect called: Paho returned rc==1 caused by None
ReauthorizeConnectionOperation: completing with error Paho returned rc==1 caused by None
ConnectionLockStage(ReauthorizeConnectionOperation): op failed.  Unblocking queue with error: Paho returned rc==1 caused by None
ConnectionLockStage(ReauthorizeConnectionOperation): failing MQTTPublishOperation op because of error
MQTTPublishOperation: completing with error Paho returned rc==1 caused by None
SendOutputEventOperation: completing with error Paho returned rc==1 caused by None
UpdateSasTokenOperation: completing with error Paho returned rc==1 caused by None
UseAuthProviderStage(UpdateSasTokenOperation): token update operation failed.  Error=Paho returned rc==1 caused by None
Exception caught in background thread.  Unable to handle.
Callback completed with error Paho returned rc==1 caused by None
azure.iot.device.common.transport_exceptions.ConnectionDroppedError: Paho returned rc==1 caused by None
['azure.iot.device.common.transport_exceptions.ConnectionDroppedError: Paho returned rc==1 caused by None\n']
Unexpected error Lost connection to IoTHub caused by Paho returned rc==1 caused by None 
Traceback (most recent call last):
  File "/usr/local/lib/python3.7/site-packages/azure/iot/device/iothub/aio/async_clients.py", line 29, in handle_result
    return await callback.completion()
  File "/usr/local/lib/python3.7/site-packages/azure/iot/device/common/async_adapter.py", line 93, in completion
    return await self.future
azure.iot.device.common.transport_exceptions.ConnectionDroppedError: Paho returned rc==1 caused by None

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

Traceback (most recent call last):
  File "./main.py", line 52, in <module>
    asyncio.run(main())
  File "/usr/local/lib/python3.7/asyncio/runners.py", line 43, in run
    return loop.run_until_complete(main)
  File "/usr/local/lib/python3.7/asyncio/base_events.py", line 583, in run_until_complete
    return future.result()
  File "./main.py", line 43, in main
    await asyncio.gather(sensor_listener(module_client))
  File "./main.py", line 39, in sensor_listener
    await module_client.send_message_to_output(message, "output")
  File "/usr/local/lib/python3.7/site-packages/azure/iot/device/iothub/aio/async_clients.py", line 429, in send_message_to_output
    await handle_result(callback)
  File "/usr/local/lib/python3.7/site-packages/azure/iot/device/iothub/aio/async_clients.py", line 31, in handle_result
    raise exceptions.ConnectionDroppedError(message="Lost connection to IoTHub", cause=e)
azure.iot.device.exceptions.ConnectionDroppedError: Lost connection to IoTHub caused by Paho returned rc==1 caused by None

From reading this thread, I found this PR for samples: https://github.com/Azure-Samples/azure-iot-samples-python/pull/18

Noticed that in the PR (which is still open) he is calling client.connect() without using await, whereas I was using await. Then I noticed this line from the error log: Exception caught in background thread. Unable to handle.. I will try without the await to see if anything changes.

LouanDuToitS3 commented 4 years ago

@BertKleewein - Hi, after running fine for 48 hours with the released V2 I got:

2019-12-19T13:06:15.223826117Z Traceback (most recent call last):
2019-12-19T13:06:15.223830512Z   File "/usr/lib/python3.6/threading.py", line 916, in _bootstrap_inner
2019-12-19T13:06:15.223833200Z     self.run()
2019-12-19T13:06:15.223835405Z   File "/usr/lib/python3.6/threading.py", line 864, in run
2019-12-19T13:06:15.223837631Z     self._target(*self._args, **self._kwargs)
2019-12-19T13:06:15.223839747Z   File "/usr/local/lib/python3.6/dist-packages/paho/mqtt/client.py", line 3428, in _thread_main
2019-12-19T13:06:15.223841888Z     self.loop_forever(retry_first_connection=True)
2019-12-19T13:06:15.223844001Z   File "/usr/local/lib/python3.6/dist-packages/paho/mqtt/client.py", line 1782, in loop_forever
2019-12-19T13:06:15.223846164Z     rc = self.loop(timeout, max_packets)
2019-12-19T13:06:15.223848182Z   File "/usr/local/lib/python3.6/dist-packages/paho/mqtt/client.py", line 1177, in loop
2019-12-19T13:06:15.223850282Z     rc = self.loop_read(max_packets)
2019-12-19T13:06:15.223852358Z   File "/usr/local/lib/python3.6/dist-packages/paho/mqtt/client.py", line 1568, in loop_read
2019-12-19T13:06:15.223858128Z     rc = self._packet_read()
2019-12-19T13:06:15.223862615Z   File "/usr/local/lib/python3.6/dist-packages/paho/mqtt/client.py", line 2271, in _packet_read
2019-12-19T13:06:15.223865276Z     byte = self._sock_recv(1)
2019-12-19T13:06:15.223867305Z   File "/usr/local/lib/python3.6/dist-packages/paho/mqtt/client.py", line 660, in _sock_recv
2019-12-19T13:06:15.223869622Z     return self._sock.recv(bufsize)
2019-12-19T13:06:15.223875624Z AttributeError: 'NoneType' object has no attribute 'recv'

So for me this issue persist....

Hi @BertKleewein , still getting exactly this issue with v2.0.1. I tried to run the pipeline with debug level logging. The problem is that it is too verbose. I send at least 30 messages per second via device messaging, and it normally takes a good couple of hours for the issue to occur.

In the code I check the "connected" property of the client before sending, and if not connected I call connect. Problem is that in the error state the client still reports that it is connected.

BertKleewein commented 4 years ago

2.1.1 has fixes for issues where client.connected was set incorrectly. This issue should be resolved. If you discover any new connection problems after upgrading to 2.1.1, please open a new issue.

az-iot-builder-01 commented 4 years ago

@BertKleewein, @oerpli, @MiguelCHR, @mounir-futurefacts, @LouanDuToitS3, @Kyrylo-Iarosh, @msjaber, @lokijota, @elliotchaim, thank you for your contribution to our open-sourced project! Please help us improve by filling out this 2-minute customer satisfaction survey