Every MQTTClient disconnect results in a disconnectTimeoutException

[daviian]

Using this code the disconnect on the MQTT Client always results in a disconnectTimeoutException

# Init AWSIoTMQTTClient
mqtt_client = AWSIoTMQTTClient(<THING_NAME>)

# AWSIoTMQTTClient configuration
mqtt_client.configureAutoReconnectBackoffTime(1, 128, 20)
mqtt_client.configureConnectDisconnectTimeout(10)  # 10 sec
mqtt_client.configureMQTTOperationTimeout(5)  # 5 sec
mqtt_client.disableMetricsCollection()  # Disable sending usage metrics

mqtt_client.configureEndpoint(<ENDPOINT_HOST>, 8883)
mqtt_client.configureCredentials(<ROOT_CA_PATH>, <PRIVATE_KEY_PATH>, <CERTIFICATE_PATH>)
mqtt_client.connect()

mqtt_client.subscribe('topic', 1, customCallback)

try:
    while True:
        time.sleep(1)
except KeyboardInterrupt:
        mqtt_client.disconnect()

Is this intended behaviour or am I doing something wrong?

[liuszeng]

Hi @daviian ,

Thank you very much for using AWS IoT Python SDK.

Can you attach the log output when you are experiencing this issue? Can you clarify which version of the SDK you are using? You can get the information using the following commands:

% python
>>> import AWSIoTPythonSDK
>>> AWSIoTPythonSDK.__version__

I tested with similar code snippet against v1.3.1 and got the following log output:

Code:

...
# Connect and subscribe to AWS IoT
myAWSIoTMQTTClient.connect()
if args.mode == 'both' or args.mode == 'subscribe':
    myAWSIoTMQTTClient.subscribe(topic, 1, customCallback)

try:
    while True:
        print("Sleeping...")
        time.sleep(1)
except KeyboardInterrupt:

Logs:

...
2018-01-17 20:30:26,654 - AWSIoTPythonSDK.core.protocol.internal.workers - DEBUG - Produced [suback] event
2018-01-17 20:30:26,657 - AWSIoTPythonSDK.core.protocol.internal.workers - DEBUG - Dispatching [suback] event
2018-01-17 20:30:26,657 - AWSIoTPythonSDK.core.protocol.internal.clients - DEBUG - Invoking custom event callback...
2018-01-17 20:30:26,658 - AWSIoTPythonSDK.core.protocol.internal.clients - DEBUG - This custom event callback is for pub/sub/unsub, removing it after invocation...
Sleeping...
Sleeping...
Sleeping...
^C2018-01-17 20:30:28,737 - AWSIoTPythonSDK.core.protocol.mqtt_core - INFO - Performing sync disconnect...
2018-01-17 20:30:28,737 - AWSIoTPythonSDK.core.protocol.mqtt_core - INFO - Performing async disconnect...
2018-01-17 20:30:28,737 - AWSIoTPythonSDK.core.protocol.internal.clients - DEBUG - Filling in custom disconnect event callback...
2018-01-17 20:30:28,737 - AWSIoTPythonSDK.core.protocol.internal.workers - DEBUG - Produced [disconnect] event
2018-01-17 20:30:28,738 - AWSIoTPythonSDK.core.protocol.internal.workers - DEBUG - Dispatching [disconnect] event
2018-01-17 20:30:28,738 - AWSIoTPythonSDK.core.protocol.internal.clients - DEBUG - Invoking custom event callback...
2018-01-17 20:30:28,738 - AWSIoTPythonSDK.core.protocol.internal.workers - DEBUG - Cleaning up before stopping event consuming
2018-01-17 20:30:28,738 - AWSIoTPythonSDK.core.protocol.internal.workers - DEBUG - Event queue cleared
2018-01-17 20:30:28,738 - AWSIoTPythonSDK.core.protocol.internal.clients - DEBUG - Stopping network I/O thread...
2018-01-17 20:30:28,738 - AWSIoTPythonSDK.core.protocol.internal.workers - DEBUG - Network thread stopped
2018-01-17 20:30:28,738 - AWSIoTPythonSDK.core.protocol.internal.workers - DEBUG - Event callbacks cleared
2018-01-17 20:30:28,738 - AWSIoTPythonSDK.core.protocol.internal.workers - DEBUG - Event consuming thread stopped
2018-01-17 20:30:28,738 - AWSIoTPythonSDK.core.protocol.internal.workers - DEBUG - Exiting dispatching loop...
2018-01-17 20:30:28,738 - AWSIoTPythonSDK.core.protocol.internal.workers - DEBUG - Waiting for event consumer to completely stop

[daviian]

My AWSIoTPythonSDK version is also 1.3.1

This is my log output:

2018-01-17 23:51:09,736 - AWSIoTPythonSDK.core.protocol.internal.workers - DEBUG - Start resubscribing
2018-01-17 23:51:09,736 - AWSIoTPythonSDK.core.protocol.internal.clients - DEBUG - Invoking custom event callback...
2018-01-17 23:51:09,737 - AWSIoTPythonSDK.core.protocol.internal.workers - DEBUG - Produced [suback] event
2018-01-17 23:51:09,737 - AWSIoTPythonSDK.core.protocol.internal.workers - DEBUG - Dispatching [suback] event
^C2018-01-17 23:51:09,975 - AWSIoTPythonSDK.core - INFO - Closing connection to GGC
2018-01-17 23:51:09,975 - AWSIoTPythonSDK.core.protocol.mqtt_core - INFO - Performing sync disconnect...
2018-01-17 23:51:09,975 - AWSIoTPythonSDK.core.protocol.mqtt_core - INFO - Performing async disconnect...
2018-01-17 23:51:09,975 - AWSIoTPythonSDK.core.protocol.internal.clients - DEBUG - Filling in custom disconnect event callback...
2018-01-17 23:51:09,975 - AWSIoTPythonSDK.core.protocol.internal.workers - DEBUG - Produced [disconnect] event
2018-01-17 23:51:09,975 - AWSIoTPythonSDK.core.protocol.internal.workers - DEBUG - Dispatching [disconnect] event
2018-01-17 23:51:09,975 - AWSIoTPythonSDK.core.protocol.internal.clients - DEBUG - Invoking custom event callback...
2018-01-17 23:51:09,975 - AWSIoTPythonSDK.core.protocol.internal.workers - DEBUG - Cleaning up before stopping event consuming
2018-01-17 23:51:09,975 - AWSIoTPythonSDK.core.protocol.internal.workers - DEBUG - Event queue cleared
2018-01-17 23:51:09,975 - AWSIoTPythonSDK.core.protocol.internal.clients - DEBUG - Stopping network I/O thread...
2018-01-17 23:51:09,976 - AWSIoTPythonSDK.core.protocol.internal.workers - DEBUG - Network thread stopped
2018-01-17 23:51:09,976 - AWSIoTPythonSDK.core.protocol.internal.workers - DEBUG - Event callbacks cleared
2018-01-17 23:51:09,976 - AWSIoTPythonSDK.core.protocol.internal.workers - DEBUG - Event consuming thread stopped
2018-01-17 23:51:09,976 - AWSIoTPythonSDK.core.protocol.internal.workers - DEBUG - Exiting dispatching loop...
2018-01-17 23:51:09,976 - AWSIoTPythonSDK.core.protocol.internal.workers - DEBUG - Waiting for event consumer to completely stop
2018-01-17 23:51:09,976 - AWSIoTPythonSDK.core.protocol.mqtt_core - INFO - Performing sync disconnect...
2018-01-17 23:51:09,976 - AWSIoTPythonSDK.core.protocol.mqtt_core - INFO - Performing async disconnect...
2018-01-17 23:51:09,976 - AWSIoTPythonSDK.core.protocol.internal.clients - DEBUG - Filling in custom disconnect event callback...
2018-01-17 23:51:09,981 - AWSIoTPythonSDK.core.protocol.internal.workers - DEBUG - Exiting dispatching loop...
2018-01-17 23:51:19,976 - AWSIoTPythonSDK.core.protocol.mqtt_core - ERROR - Disconnect timed out
Error in atexit._run_exitfuncs:
Traceback (most recent call last):
  File "<$HOME>/Development/master-thesis/thermal-sensor/ThermalSensor.py", line 145, in stop
    self._shadow_client.disconnect()
  File "<$HOME>/.local/lib/python3.6/site-packages/AWSIoTPythonSDK/MQTTLib.py", line 1244, in disconnect
    return self._AWSIoTMQTTClient.disconnect()
  File "<$HOME>/.local/lib/python3.6/site-packages/AWSIoTPythonSDK/MQTTLib.py", line 541, in disconnect
    return self._mqtt_core.disconnect()
  File "<$HOME>/.local/lib/python3.6/site-packages/AWSIoTPythonSDK/core/protocol/mqtt_core.py", line 221, in disconnect
    raise disconnectTimeoutException()
AWSIoTPythonSDK.exception.AWSIoTExceptions.disconnectTimeoutException

Maybe I should add some more information.
I use the MQTT Client and the Shadow Client at the same time. Thus the disconnect is happening twice. Once for each client. The first disconnect is the MQTT Client and the second one the Shadow Client.

[liuszeng]

Hi @daviian ,

Thank you for providing the information. That's really helpful.

You mentioned that you are using the shadow client and MQTT client at the same time. Can you elaborate more on that? Are those 2 separate connections to the server or you get the access to the underneath MQTT client from your shadow client using this API:
https://s3.amazonaws.com/aws-iot-device-sdk-python-docs/sphinx/html/index.html#AWSIoTPythonSDK.MQTTLib.AWSIoTMQTTShadowClient.getMQTTConnection

Thanks,
Liusu

[daviian]

Hi @liuszeng

I overlooked that method in the API und totally forgot that I can't connect twice with the same clientID. Until now I used two separate connections, but I've already changed it to use that method instead.
Disconnecting seems fixed now, but immediately ran into another issue.

Will close this and open a new one if necessary.
Appreciate your help!