no reconnect after 24 hours #124

jp-embedded · 2018-04-04T07:48:10Z

I am having the exact same issue as #39 with v1.3.1

liuszeng · 2018-04-04T18:43:19Z

Do you have any SDK logs captured while the issue happened?

Thanks,
Liusu

jp-embedded · 2018-04-05T07:33:23Z

I have not saved the log, but I can post a new log later (takes 24 hours to reproduce)
However, as in #39 there is really no info in the log. It just silently stops receiving subscribed messages.

liuszeng · 2018-04-05T17:46:08Z

Hi @jp-embedded ,

Thank you for providing the information.

In the meantime, can you also enable AWS IoT CloudWatch log since the client side log may not be that informative?

Thanks,
Liusu

jp-embedded · 2018-04-06T10:06:19Z

I will have a look at the CloudWatch log...
Below is the client log.
I have also tried the shadowUpdate method. This fails as well after 24 hours with a timeout respones

version check:

$ cat /usr/local/lib/python2.7/dist-packages/AWSIoTPythonSDK/__init__.py
__version__ = "1.3.1"

test command:

$ python basicPubSub.py -e "xxxxxxxxxx.iot.eu-west-1.amazonaws.com" -r "VeriSign-Class 3-Public-Primary-Certification-Authority-G5.pem" -w -m subscribe -t'$aws/things/sensor1/shadow/update'

I have just replaced 'print' with 'logger.debug' in basicPubSub.py
initial part of endport url replaced with 'xxxxxxxxx'

As the log shows, it stops receiving messages after 24 hours. If I restart the python command, it works again. I have just included the beginning and end of the log. The middle part is left out.

log:

2018-04-05 08:00:44,834 - AWSIoTPythonSDK.core.protocol.internal.clients - DEBUG - Initializing MQTT layer...
2018-04-05 08:00:44,835 - AWSIoTPythonSDK.core.protocol.internal.clients - DEBUG - Registering internal event callbacks to MQTT layer...
2018-04-05 08:00:44,835 - AWSIoTPythonSDK.core.protocol.mqtt_core - INFO - MqttCore initialized
2018-04-05 08:00:44,835 - AWSIoTPythonSDK.core.protocol.mqtt_core - INFO - Client id: basicPubSub
2018-04-05 08:00:44,835 - AWSIoTPythonSDK.core.protocol.mqtt_core - INFO - Protocol version: MQTTv3.1.1
2018-04-05 08:00:44,835 - AWSIoTPythonSDK.core.protocol.mqtt_core - INFO - Authentication type: SigV4 WebSocket
2018-04-05 08:00:44,835 - AWSIoTPythonSDK.core.protocol.mqtt_core - INFO - Configuring endpoint...
2018-04-05 08:00:44,835 - AWSIoTPythonSDK.core.protocol.mqtt_core - INFO - Configuring certificates...
2018-04-05 08:00:44,835 - AWSIoTPythonSDK.core.protocol.mqtt_core - INFO - Configuring reconnect back off timing...
2018-04-05 08:00:44,836 - AWSIoTPythonSDK.core.protocol.mqtt_core - INFO - Base quiet time: 1.000000 sec
2018-04-05 08:00:44,836 - AWSIoTPythonSDK.core.protocol.mqtt_core - INFO - Max quiet time: 32.000000 sec
2018-04-05 08:00:44,836 - AWSIoTPythonSDK.core.protocol.mqtt_core - INFO - Stable connection time: 20.000000 sec
2018-04-05 08:00:44,836 - AWSIoTPythonSDK.core.protocol.mqtt_core - INFO - Configuring offline requests queueing: max queue size: -1
2018-04-05 08:00:44,836 - AWSIoTPythonSDK.core.protocol.mqtt_core - INFO - Configuring offline requests queue draining interval: 0.500000 sec
2018-04-05 08:00:44,836 - AWSIoTPythonSDK.core.protocol.mqtt_core - INFO - Configuring connect/disconnect time out: 10.000000 sec
2018-04-05 08:00:44,836 - AWSIoTPythonSDK.core.protocol.mqtt_core - INFO - Configuring MQTT operation time out: 5.000000 sec
2018-04-05 08:00:44,836 - AWSIoTPythonSDK.core.protocol.mqtt_core - INFO - Performing sync connect...
2018-04-05 08:00:44,836 - AWSIoTPythonSDK.core.protocol.mqtt_core - INFO - Performing async connect...
2018-04-05 08:00:44,836 - AWSIoTPythonSDK.core.protocol.mqtt_core - INFO - Keep-alive: 600.000000 sec
2018-04-05 08:00:44,836 - AWSIoTPythonSDK.core.protocol.internal.workers - DEBUG - Event consuming thread started
2018-04-05 08:00:44,836 - AWSIoTPythonSDK.core.protocol.mqtt_core - DEBUG - Passing in general notification callbacks to internal client...
2018-04-05 08:00:44,836 - AWSIoTPythonSDK.core.protocol.internal.clients - DEBUG - Filling in fixed event callbacks: CONNACK, DISCONNECT, MESSAGE
2018-04-05 08:00:44,915 - AWSIoTPythonSDK.core.protocol.connection.cores - DEBUG - IAM credentials from custom config.
2018-04-05 08:00:44,915 - AWSIoTPythonSDK.core.protocol.connection.cores - DEBUG - IAM credentials from env var.
2018-04-05 08:00:44,915 - AWSIoTPythonSDK.core.protocol.connection.cores - DEBUG - No AWS Session Token found.
2018-04-05 08:00:44,915 - AWSIoTPythonSDK.core.protocol.connection.cores - DEBUG - IAM credentials from file.
2018-04-05 08:00:44,915 - AWSIoTPythonSDK.core.protocol.connection.cores - DEBUG - createWebsocketEndpoint: Websocket URL: wss://xxxxxxxxx.iot.eu-west-1.amazonaws.com:443/mqtt?X-Amz-Algorithm=AWS4-HMAC-SHA256&X-Amz-Credential=AKIAIFPEDCAFY6RDN6IA%2F20180405%2Feu-west-1%2Fiotdata%2Faws4_request&X-Amz-Date=20180405T080044Z&X-Amz-Expires=86400&X-Amz-SignedHeaders=host&X-Amz-Signature=f4f5e18659f1caffd67b8502bb3250bb4ae1e345ab18962874a4a747a16f68de
2018-04-05 08:00:44,918 - AWSIoTPythonSDK.core.protocol.internal.clients - DEBUG - Starting network I/O thread...
2018-04-05 08:00:44,957 - AWSIoTPythonSDK.core.protocol.internal.workers - DEBUG - Produced [connack] event
2018-04-05 08:00:44,959 - AWSIoTPythonSDK.core.protocol.internal.workers - DEBUG - Dispatching [connack] event
2018-04-05 08:00:44,959 - AWSIoTPythonSDK.core.protocol.internal.workers - DEBUG - No need for recovery
2018-04-05 08:00:44,959 - AWSIoTPythonSDK.core.protocol.internal.clients - DEBUG - Invoking custom event callback...
2018-04-05 08:00:44,982 - AWSIoTPythonSDK.core.protocol.mqtt_core - INFO - Performing sync subscribe...
2018-04-05 08:00:44,982 - AWSIoTPythonSDK.core.protocol.internal.workers - DEBUG - Adding a new subscription record: $aws/things/sensor1/shadow/update qos: 1
2018-04-05 08:00:44,982 - AWSIoTPythonSDK.core.protocol.internal.clients - DEBUG - Filling in custom suback event callback...
2018-04-05 08:00:44,998 - AWSIoTPythonSDK.core.protocol.internal.workers - DEBUG - Produced [suback] event
2018-04-05 08:00:45,000 - AWSIoTPythonSDK.core.protocol.internal.workers - DEBUG - Dispatching [suback] event
2018-04-05 08:00:45,000 - AWSIoTPythonSDK.core.protocol.internal.clients - DEBUG - Invoking custom event callback...
2018-04-05 08:00:45,000 - AWSIoTPythonSDK.core.protocol.internal.clients - DEBUG - This custom event callback is for pub/sub/unsub, removing it after invocation...
2018-04-05 08:00:53,448 - AWSIoTPythonSDK.core.protocol.internal.workers - DEBUG - Produced [message] event
2018-04-05 08:00:53,448 - AWSIoTPythonSDK.core.protocol.internal.workers - DEBUG - Dispatching [message] event
2018-04-05 08:00:53,449 - AWSIoTPythonSDK.core - DEBUG - Received a new message:
2018-04-05 08:00:53,449 - AWSIoTPythonSDK.core - DEBUG - {"state":{"reported":{"hum":41.7,"temp":21.1,"relay":true,"pir":false},"desired":{"hum":41.7,"temp":21.1,"pir":false}}}
2018-04-05 08:00:53,449 - AWSIoTPythonSDK.core - DEBUG - from topic:
2018-04-05 08:00:53,449 - AWSIoTPythonSDK.core - DEBUG - $aws/things/sensor1/shadow/update
2018-04-05 08:00:53,449 - AWSIoTPythonSDK.core - DEBUG - --------------


2018-04-05 08:00:53,449 - AWSIoTPythonSDK.core.protocol.internal.clients - DEBUG - Invoking custom event callback...
2018-04-05 08:00:57,471 - AWSIoTPythonSDK.core.protocol.internal.workers - DEBUG - Produced [message] event
2018-04-05 08:00:57,471 - AWSIoTPythonSDK.core.protocol.internal.workers - DEBUG - Dispatching [message] event
2018-04-05 08:00:57,471 - AWSIoTPythonSDK.core - DEBUG - Received a new message:
2018-04-05 08:00:57,471 - AWSIoTPythonSDK.core - DEBUG - {"state":{"reported":{"hum":41.7,"temp":21.1,"relay":true,"pir":true},"desired":{"hum":41.7,"temp":21.1,"pir":true}}}
2018-04-05 08:00:57,471 - AWSIoTPythonSDK.core - DEBUG - from topic:
2018-04-05 08:00:57,471 - AWSIoTPythonSDK.core - DEBUG - $aws/things/sensor1/shadow/update
2018-04-05 08:00:57,471 - AWSIoTPythonSDK.core - DEBUG - --------------


2018-04-05 08:00:57,471 - AWSIoTPythonSDK.core.protocol.internal.clients - DEBUG - Invoking custom event callback...
2018-04-05 08:01:04,957 - AWSIoTPythonSDK.core.protocol.connection.cores - DEBUG - stableConnection: Resetting the backoff time to: 1 sec.
2018-04-05 08:01:15,504 - AWSIoTPythonSDK.core.protocol.internal.workers - DEBUG - Produced [message] event
2018-04-05 08:01:15,507 - AWSIoTPythonSDK.core.protocol.internal.workers - DEBUG - Dispatching [message] event
2018-04-05 08:01:15,507 - AWSIoTPythonSDK.core - DEBUG - Received a new message:
2018-04-05 08:01:15,507 - AWSIoTPythonSDK.core - DEBUG - {"state":{"reported":{"hum":41.7,"temp":21.1,"relay":true,"pir":false},"desired":{"hum":41.7,"temp":21.1,"pir":false}}}
2018-04-05 08:01:15,507 - AWSIoTPythonSDK.core - DEBUG - from topic:
2018-04-05 08:01:15,507 - AWSIoTPythonSDK.core - DEBUG - $aws/things/sensor1/shadow/update
2018-04-05 08:01:15,507 - AWSIoTPythonSDK.core - DEBUG - --------------


2018-04-05 08:01:15,507 - AWSIoTPythonSDK.core.protocol.internal.clients - DEBUG - Invoking custom event callback...
2018-04-05 08:01:51,886 - AWSIoTPythonSDK.core.protocol.internal.workers - DEBUG - Produced [message] event
2018-04-05 08:01:51,886 - AWSIoTPythonSDK.core.protocol.internal.workers - DEBUG - Dispatching [message] event
2018-04-05 08:01:51,886 - AWSIoTPythonSDK.core - DEBUG - Received a new message:
2018-04-05 08:01:51,886 - AWSIoTPythonSDK.core - DEBUG - {"state":{"reported":{"hum":41.7,"temp":21.1,"relay":true,"pir":false},"desired":{"hum":41.7,"temp":21.1,"pir":false}}}
2018-04-05 08:01:51,886 - AWSIoTPythonSDK.core - DEBUG - from topic:
2018-04-05 08:01:51,886 - AWSIoTPythonSDK.core - DEBUG - $aws/things/sensor1/shadow/update
2018-04-05 08:01:51,886 - AWSIoTPythonSDK.core - DEBUG - --------------


2018-04-05 08:01:51,887 - AWSIoTPythonSDK.core.protocol.internal.clients - DEBUG - Invoking custom event callback...
2018-04-05 08:02:52,276 - AWSIoTPythonSDK.core.protocol.internal.workers - DEBUG - Produced [message] event
2018-04-05 08:02:52,278 - AWSIoTPythonSDK.core.protocol.internal.workers - DEBUG - Dispatching [message] event
2018-04-05 08:02:52,278 - AWSIoTPythonSDK.core - DEBUG - Received a new message:
2018-04-05 08:02:52,278 - AWSIoTPythonSDK.core - DEBUG - {"state":{"reported":{"hum":41.7,"temp":21.1,"relay":true,"pir":false},"desired":{"hum":41.7,"temp":21.1,"pir":false}}}
2018-04-05 08:02:52,279 - AWSIoTPythonSDK.core - DEBUG - from topic:
2018-04-05 08:02:52,279 - AWSIoTPythonSDK.core - DEBUG - $aws/things/sensor1/shadow/update
2018-04-05 08:02:52,279 - AWSIoTPythonSDK.core - DEBUG - --------------

--- lots of similar output left out ---

2018-04-06 07:59:00,350 - AWSIoTPythonSDK.core.protocol.internal.clients - DEBUG - Invoking custom event callback...
2018-04-06 07:59:08,648 - AWSIoTPythonSDK.core.protocol.internal.workers - DEBUG - Produced [message] event
2018-04-06 07:59:08,648 - AWSIoTPythonSDK.core.protocol.internal.workers - DEBUG - Dispatching [message] event
2018-04-06 07:59:08,648 - AWSIoTPythonSDK.core - DEBUG - Received a new message:
2018-04-06 07:59:08,648 - AWSIoTPythonSDK.core - DEBUG - {"state":{"reported":{"hum":36.4,"temp":21.2,"relay":true,"pir":true},"desired":{"hum":36.4,"temp":21.2,"pir":true}}}
2018-04-06 07:59:08,648 - AWSIoTPythonSDK.core - DEBUG - from topic:
2018-04-06 07:59:08,648 - AWSIoTPythonSDK.core - DEBUG - $aws/things/sensor1/shadow/update
2018-04-06 07:59:08,649 - AWSIoTPythonSDK.core - DEBUG - --------------


2018-04-06 07:59:08,649 - AWSIoTPythonSDK.core.protocol.internal.clients - DEBUG - Invoking custom event callback...
2018-04-06 07:59:10,656 - AWSIoTPythonSDK.core.protocol.internal.workers - DEBUG - Produced [message] event
2018-04-06 07:59:10,657 - AWSIoTPythonSDK.core.protocol.internal.workers - DEBUG - Dispatching [message] event
2018-04-06 07:59:10,657 - AWSIoTPythonSDK.core - DEBUG - Received a new message:
2018-04-06 07:59:10,657 - AWSIoTPythonSDK.core - DEBUG - {"state":{"reported":{"hum":36.4,"temp":21.2,"relay":true,"pir":false},"desired":{"hum":36.4,"temp":21.2,"pir":false}}}
2018-04-06 07:59:10,658 - AWSIoTPythonSDK.core - DEBUG - from topic:
2018-04-06 07:59:10,658 - AWSIoTPythonSDK.core - DEBUG - $aws/things/sensor1/shadow/update
2018-04-06 07:59:10,658 - AWSIoTPythonSDK.core - DEBUG - --------------


2018-04-06 07:59:10,658 - AWSIoTPythonSDK.core.protocol.internal.clients - DEBUG - Invoking custom event callback...
2018-04-06 07:59:22,688 - AWSIoTPythonSDK.core.protocol.internal.workers - DEBUG - Produced [message] event
2018-04-06 07:59:22,688 - AWSIoTPythonSDK.core.protocol.internal.workers - DEBUG - Dispatching [message] event
2018-04-06 07:59:22,688 - AWSIoTPythonSDK.core - DEBUG - Received a new message:
2018-04-06 07:59:22,689 - AWSIoTPythonSDK.core - DEBUG - {"state":{"reported":{"hum":36.4,"temp":21.2,"relay":true,"pir":true},"desired":{"hum":36.4,"temp":21.2,"pir":true}}}
2018-04-06 07:59:22,689 - AWSIoTPythonSDK.core - DEBUG - from topic:
2018-04-06 07:59:22,689 - AWSIoTPythonSDK.core - DEBUG - $aws/things/sensor1/shadow/update
2018-04-06 07:59:22,689 - AWSIoTPythonSDK.core - DEBUG - --------------


2018-04-06 07:59:22,689 - AWSIoTPythonSDK.core.protocol.internal.clients - DEBUG - Invoking custom event callback...
2018-04-06 07:59:42,734 - AWSIoTPythonSDK.core.protocol.internal.workers - DEBUG - Produced [message] event
2018-04-06 07:59:42,744 - AWSIoTPythonSDK.core.protocol.internal.workers - DEBUG - Dispatching [message] event
2018-04-06 07:59:42,744 - AWSIoTPythonSDK.core - DEBUG - Received a new message:
2018-04-06 07:59:42,744 - AWSIoTPythonSDK.core - DEBUG - {"state":{"reported":{"hum":36.4,"temp":21.2,"relay":true,"pir":false},"desired":{"hum":36.4,"temp":21.2,"pir":false}}}
2018-04-06 07:59:42,744 - AWSIoTPythonSDK.core - DEBUG - from topic:
2018-04-06 07:59:42,744 - AWSIoTPythonSDK.core - DEBUG - $aws/things/sensor1/shadow/update
2018-04-06 07:59:42,745 - AWSIoTPythonSDK.core - DEBUG - --------------


2018-04-06 07:59:42,745 - AWSIoTPythonSDK.core.protocol.internal.clients - DEBUG - Invoking custom event callback...
2018-04-06 07:59:46,748 - AWSIoTPythonSDK.core.protocol.internal.workers - DEBUG - Produced [message] event
2018-04-06 07:59:46,750 - AWSIoTPythonSDK.core.protocol.internal.workers - DEBUG - Dispatching [message] event
2018-04-06 07:59:46,750 - AWSIoTPythonSDK.core - DEBUG - Received a new message:
2018-04-06 07:59:46,750 - AWSIoTPythonSDK.core - DEBUG - {"state":{"reported":{"hum":36.4,"temp":21.2,"relay":true,"pir":true},"desired":{"hum":36.4,"temp":21.2,"pir":true}}}
2018-04-06 07:59:46,750 - AWSIoTPythonSDK.core - DEBUG - from topic:
2018-04-06 07:59:46,750 - AWSIoTPythonSDK.core - DEBUG - $aws/things/sensor1/shadow/update
2018-04-06 07:59:46,750 - AWSIoTPythonSDK.core - DEBUG - --------------


2018-04-06 07:59:46,750 - AWSIoTPythonSDK.core.protocol.internal.clients - DEBUG - Invoking custom event callback...

jp-embedded · 2018-04-06T14:27:06Z

What exactly do you want me to enable in AWS IoT CloudWatch log?

liuszeng · 2018-04-06T17:49:31Z

Hi @jp-embedded ,

Thank you very much for providing the detailed information. I found several things in the log:

There is no explicit logs for an disconnect event, which should happen when the server closes the WebSocket connection after 24-hour window. Can you confirm on that? Log outputs should be similar to the following:

...Produced [disconnect] event...

SDK reconnect logic is triggered by disconnect event produced by the underneath Python Paho MQTT client. If there is no log for disconnect event, it means that the disconnect has not been detected by the Paho yet.

I see you are using default keep-alive configuration (600 seconds). Since your client only listens on incoming messages and does not perform any outbound publishes, Paho's decision on whether the client is connected depends on the PINGREQ/PINGRESP mechanism from MQTT with a keep-alive interval of 10 minutes. Were you able to see any disconnect event detected after around 1.5 * keep-alive interval after the 24-hour window? Does the client eventually get reconnected?

With point 1 and 2 bear in mind, I would recommend you to configure the keep-alive shorter so that the disconnect event can be detected earlier. Can you try with the new configuration and see if the issue still exists?

As for cloudwatch logs, you can use the following instructions to enable it:
https://docs.aws.amazon.com/iot/latest/developerguide/cloud-watch-logs.html

It is a collection of server side logs published to the user account, which can, to some extent, expose what is happening on the server side when issue happens.

Thanks,
Liusu

jp-embedded · 2018-04-09T11:50:11Z

There is no disconnect messages at all in the log

$ grep disconnect out.log.1
2018-04-05 08:00:44,836 - AWSIoTPythonSDK.core.protocol.mqtt_core - INFO - Configuring connect/disconnect time out: 10.000000 sec

I have tried with a modified script which sends shadow updates every 5 minutes. This script fails the same way as basicPubSub.py. After 24 hours, it silently stops receiving and the update messages times out.

I have not tested if it is only the disconnect after 24 hours that are not detected or if it is disconnect in general that is not detected. I think I will try to test that later.

I have restarted the test now with keep-alive set to 120 and couldwatch logging enabled.

jp-embedded · 2018-04-10T12:47:14Z

same result with keep-alive set to 120:

I have got 3 iot logs. Here is the last part of them:

log "sensor1":

2018-04-10 12:22:00.347 TRACEID:cf542e0b-f947-e48b-4108-967ed6346169 PRINCIPALID:sensor1 [INFO] EVENT:UpdateThingShadow TOPICNAME:$aws/things/sensor1/shadow/update THINGNAME:sensor1
2018-04-10 12:23:00.725 TRACEID:3c9d7c2a-7e8e-0dce-9153-39126f3cf122 PRINCIPALID:sensor1 [INFO] EVENT:UpdateThingShadow TOPICNAME:$aws/things/sensor1/shadow/update THINGNAME:sensor1
2018-04-10 12:23:59.122 TRACEID:f863c3c8-6a0a-5f8f-0b39-92803825b8e9 PRINCIPALID:sensor1 [INFO] EVENT:UpdateThingShadow TOPICNAME:$aws/things/sensor1/shadow/update THINGNAME:sensor1
2018-04-10 12:24:59.524 TRACEID:0a19f23c-c3d3-05a0-1591-11ee9c3079ff PRINCIPALID:sensor1 [INFO] EVENT:UpdateThingShadow TOPICNAME:$aws/things/sensor1/shadow/update THINGNAME:sensor1
2018-04-10 12:25:59.922 TRACEID:9545ea57-f433-2709-9d01-4bef66c6c824 PRINCIPALID:sensor1 [INFO] EVENT:UpdateThingShadow TOPICNAME:$aws/things/sensor1/shadow/update THINGNAME:sensor1
2018-04-10 12:27:00.322 TRACEID:9134d104-aa36-6750-91ae-8f35eb33fe6e PRINCIPALID:sensor1 [INFO] EVENT:UpdateThingShadow TOPICNAME:$aws/things/sensor1/shadow/update THINGNAME:sensor1
2018-04-10 12:28:00.739 TRACEID:6632a2fb-16ac-824a-26e8-2f3964f4744f PRINCIPALID:sensor1 [INFO] EVENT:UpdateThingShadow TOPICNAME:$aws/things/sensor1/shadow/update THINGNAME:sensor1
2018-04-10 12:28:59.110 TRACEID:5cd79f80-b43a-4455-d521-e6ca9096bdfd PRINCIPALID:sensor1 [INFO] EVENT:UpdateThingShadow TOPICNAME:$aws/things/sensor1/shadow/update THINGNAME:sensor1
2018-04-10 12:29:59.512 TRACEID:33864fbc-1b05-9916-e7b7-3ebd5c20413c PRINCIPALID:sensor1 [INFO] EVENT:UpdateThingShadow TOPICNAME:$aws/things/sensor1/shadow/update THINGNAME:sensor1
2018-04-10 12:30:59.913 TRACEID:df9ab6c2-dd34-d2af-4999-905b0430248d PRINCIPALID:sensor1 [INFO] EVENT:UpdateThingShadow TOPICNAME:$aws/things/sensor1/shadow/update THINGNAME:sensor1
2018-04-10 12:32:00.310 TRACEID:10ab7e34-490b-4bf5-4f9e-5c517cf9f1a8 PRINCIPALID:sensor1 [INFO] EVENT:UpdateThingShadow TOPICNAME:$aws/things/sensor1/shadow/update THINGNAME:sensor1
2018-04-10 12:33:00.707 TRACEID:63e35e36-fe70-2c7b-ee9b-bda9a03251cf PRINCIPALID:sensor1 [INFO] EVENT:UpdateThingShadow TOPICNAME:$aws/things/sensor1/shadow/update THINGNAME:sensor1
2018-04-10 12:33:59.142 TRACEID:348c5c17-4dde-bfac-0d01-9ca6ad5b8839 PRINCIPALID:sensor1 [INFO] EVENT:UpdateThingShadow TOPICNAME:$aws/things/sensor1/shadow/update THINGNAME:sensor1
2018-04-10 12:34:59.505 TRACEID:54e96aae-be08-e531-27f4-be58950ec3cf PRINCIPALID:sensor1 [INFO] EVENT:UpdateThingShadow TOPICNAME:$aws/things/sensor1/shadow/update THINGNAME:sensor1
2018-04-10 12:35:59.903 TRACEID:6b898ecd-224a-a638-bb8a-ca6ef8eabe51 PRINCIPALID:sensor1 [INFO] EVENT:UpdateThingShadow TOPICNAME:$aws/things/sensor1/shadow/update THINGNAME:sensor1
2018-04-10 12:37:00.306 TRACEID:a0b9118f-2ac8-bff6-33d2-d4248da05816 PRINCIPALID:sensor1 [INFO] EVENT:UpdateThingShadow TOPICNAME:$aws/things/sensor1/shadow/update THINGNAME:sensor1
2018-04-10 12:38:00.680 TRACEID:e2fdffd5-8068-2167-1101-595f06eccaf3 PRINCIPALID:sensor1 [INFO] EVENT:UpdateThingShadow TOPICNAME:$aws/things/sensor1/shadow/update THINGNAME:sensor1
2018-04-10 12:38:59.114 TRACEID:313defe7-1050-0599-7b1d-e7fcda033298 PRINCIPALID:sensor1 [INFO] EVENT:UpdateThingShadow TOPICNAME:$aws/things/sensor1/shadow/update THINGNAME:sensor1
2018-04-10 12:39:59.505 TRACEID:bb11cc95-4943-d874-ea6a-77e32e1e0f1d PRINCIPALID:sensor1 [INFO] EVENT:UpdateThingShadow TOPICNAME:$aws/things/sensor1/shadow/update THINGNAME:sensor1
2018-04-10 12:40:59.903 TRACEID:d6f3c14c-95c8-0664-9d1a-8443f34dc2cf PRINCIPALID:sensor1 [INFO] EVENT:UpdateThingShadow TOPICNAME:$aws/things/sensor1/shadow/update THINGNAME:sensor1

log AIDAJCUXHXXZJIF7ZDZQQ:

2018-04-10 12:28:59.114 TRACEID:5cd79f80-b43a-4455-d521-e6ca9096bdfd PRINCIPALID:AIDAJCUXHXXZJIF7ZDZQQ [INFO] EVENT:PublishEvent MESSAGE: IpAddress: 90.185.72.42 SourcePort: 26344
2018-04-10 12:29:59.516 TRACEID:33864fbc-1b05-9916-e7b7-3ebd5c20413c PRINCIPALID:AIDAJCUXHXXZJIF7ZDZQQ [INFO] EVENT:PublishEvent TOPICNAME:$aws/things/sensor1/shadow/update MESSAGE:PublishIn Status: SUCCESS
2018-04-10 12:29:59.516 TRACEID:33864fbc-1b05-9916-e7b7-3ebd5c20413c PRINCIPALID:AIDAJCUXHXXZJIF7ZDZQQ [INFO] EVENT:PublishEvent MESSAGE: IpAddress: 90.185.72.42 SourcePort: 26344
2018-04-10 12:30:59.917 TRACEID:df9ab6c2-dd34-d2af-4999-905b0430248d PRINCIPALID:AIDAJCUXHXXZJIF7ZDZQQ [INFO] EVENT:PublishEvent TOPICNAME:$aws/things/sensor1/shadow/update MESSAGE:PublishIn Status: SUCCESS
2018-04-10 12:30:59.917 TRACEID:df9ab6c2-dd34-d2af-4999-905b0430248d PRINCIPALID:AIDAJCUXHXXZJIF7ZDZQQ [INFO] EVENT:PublishEvent MESSAGE: IpAddress: 90.185.72.42 SourcePort: 26344
2018-04-10 12:32:00.315 TRACEID:10ab7e34-490b-4bf5-4f9e-5c517cf9f1a8 PRINCIPALID:AIDAJCUXHXXZJIF7ZDZQQ [INFO] EVENT:PublishEvent TOPICNAME:$aws/things/sensor1/shadow/update MESSAGE:PublishIn Status: SUCCESS
2018-04-10 12:32:00.315 TRACEID:10ab7e34-490b-4bf5-4f9e-5c517cf9f1a8 PRINCIPALID:AIDAJCUXHXXZJIF7ZDZQQ [INFO] EVENT:PublishEvent MESSAGE: IpAddress: 90.185.72.42 SourcePort: 26344
2018-04-10 12:33:00.710 TRACEID:63e35e36-fe70-2c7b-ee9b-bda9a03251cf PRINCIPALID:AIDAJCUXHXXZJIF7ZDZQQ [INFO] EVENT:PublishEvent TOPICNAME:$aws/things/sensor1/shadow/update MESSAGE:PublishIn Status: SUCCESS
2018-04-10 12:33:00.710 TRACEID:63e35e36-fe70-2c7b-ee9b-bda9a03251cf PRINCIPALID:AIDAJCUXHXXZJIF7ZDZQQ [INFO] EVENT:PublishEvent MESSAGE: IpAddress: 90.185.72.42 SourcePort: 26344
2018-04-10 12:33:59.145 TRACEID:348c5c17-4dde-bfac-0d01-9ca6ad5b8839 PRINCIPALID:AIDAJCUXHXXZJIF7ZDZQQ [INFO] EVENT:PublishEvent TOPICNAME:$aws/things/sensor1/shadow/update MESSAGE:PublishIn Status: SUCCESS
2018-04-10 12:33:59.145 TRACEID:348c5c17-4dde-bfac-0d01-9ca6ad5b8839 PRINCIPALID:AIDAJCUXHXXZJIF7ZDZQQ [INFO] EVENT:PublishEvent MESSAGE: IpAddress: 90.185.72.42 SourcePort: 26344
2018-04-10 12:34:59.510 TRACEID:54e96aae-be08-e531-27f4-be58950ec3cf PRINCIPALID:AIDAJCUXHXXZJIF7ZDZQQ [INFO] EVENT:PublishEvent TOPICNAME:$aws/things/sensor1/shadow/update MESSAGE:PublishIn Status: SUCCESS
2018-04-10 12:34:59.510 TRACEID:54e96aae-be08-e531-27f4-be58950ec3cf PRINCIPALID:AIDAJCUXHXXZJIF7ZDZQQ [INFO] EVENT:PublishEvent MESSAGE: IpAddress: 90.185.72.42 SourcePort: 26344
2018-04-10 12:35:59.907 TRACEID:6b898ecd-224a-a638-bb8a-ca6ef8eabe51 PRINCIPALID:AIDAJCUXHXXZJIF7ZDZQQ [INFO] EVENT:PublishEvent TOPICNAME:$aws/things/sensor1/shadow/update MESSAGE:PublishIn Status: SUCCESS
2018-04-10 12:35:59.907 TRACEID:6b898ecd-224a-a638-bb8a-ca6ef8eabe51 PRINCIPALID:AIDAJCUXHXXZJIF7ZDZQQ [INFO] EVENT:PublishEvent MESSAGE: IpAddress: 90.185.72.42 SourcePort: 26344
2018-04-10 12:37:00.311 TRACEID:a0b9118f-2ac8-bff6-33d2-d4248da05816 PRINCIPALID:AIDAJCUXHXXZJIF7ZDZQQ [INFO] EVENT:PublishEvent TOPICNAME:$aws/things/sensor1/shadow/update MESSAGE:PublishIn Status: SUCCESS
2018-04-10 12:37:00.311 TRACEID:a0b9118f-2ac8-bff6-33d2-d4248da05816 PRINCIPALID:AIDAJCUXHXXZJIF7ZDZQQ [INFO] EVENT:PublishEvent MESSAGE: IpAddress: 90.185.72.42 SourcePort: 26344
2018-04-10 12:38:00.710 TRACEID:e2fdffd5-8068-2167-1101-595f06eccaf3 PRINCIPALID:AIDAJCUXHXXZJIF7ZDZQQ [INFO] EVENT:PublishEvent TOPICNAME:$aws/things/sensor1/shadow/update MESSAGE:PublishIn Status: SUCCESS
2018-04-10 12:38:00.710 TRACEID:e2fdffd5-8068-2167-1101-595f06eccaf3 PRINCIPALID:AIDAJCUXHXXZJIF7ZDZQQ [INFO] EVENT:PublishEvent MESSAGE: IpAddress: 90.185.72.42 SourcePort: 26344
2018-04-10 12:38:59.135 TRACEID:313defe7-1050-0599-7b1d-e7fcda033298 PRINCIPALID:AIDAJCUXHXXZJIF7ZDZQQ [INFO] EVENT:PublishEvent TOPICNAME:$aws/things/sensor1/shadow/update MESSAGE:PublishIn Status: SUCCESS
2018-04-10 12:38:59.135 TRACEID:313defe7-1050-0599-7b1d-e7fcda033298 PRINCIPALID:AIDAJCUXHXXZJIF7ZDZQQ [INFO] EVENT:PublishEvent MESSAGE: IpAddress: 90.185.72.42 SourcePort: 26344
2018-04-10 12:39:59.508 TRACEID:bb11cc95-4943-d874-ea6a-77e32e1e0f1d PRINCIPALID:AIDAJCUXHXXZJIF7ZDZQQ [INFO] EVENT:PublishEvent TOPICNAME:$aws/things/sensor1/shadow/update MESSAGE:PublishIn Status: SUCCESS
2018-04-10 12:39:59.508 TRACEID:bb11cc95-4943-d874-ea6a-77e32e1e0f1d PRINCIPALID:AIDAJCUXHXXZJIF7ZDZQQ [INFO] EVENT:PublishEvent MESSAGE: IpAddress: 90.185.72.42 SourcePort: 26344
2018-04-10 12:40:59.906 TRACEID:d6f3c14c-95c8-0664-9d1a-8443f34dc2cf PRINCIPALID:AIDAJCUXHXXZJIF7ZDZQQ [INFO] EVENT:PublishEvent TOPICNAME:$aws/things/sensor1/shadow/update MESSAGE:PublishIn Status: SUCCESS
2018-04-10 12:40:59.906 TRACEID:d6f3c14c-95c8-0664-9d1a-8443f34dc2cf PRINCIPALID:AIDAJCUXHXXZJIF7ZDZQQ [INFO] EVENT:PublishEvent MESSAGE: IpAddress: 90.185.72.42 SourcePort: 26344

log AIDAINN64S2TX5QWEFIVE:

2018-04-10 11:24:59.582 TRACEID:b3b4e68b-97b3-0c51-cd83-1ac4f5a640ba PRINCIPALID:AIDAINN64S2TX5QWEFIVE [INFO] EVENT:PublishOut MESSAGE: IpAddress: 54.217.201.236 SourcePort: 45135
2018-04-10 11:26:00.003 TRACEID:b9eb4de6-5673-b6fe-4976-f5807235733c PRINCIPALID:AIDAINN64S2TX5QWEFIVE [INFO] EVENT:PublishOut TOPICNAME:$aws/things/sensor1/shadow/update MESSAGE:PublishOut Status: SUCCESS
2018-04-10 11:26:00.003 TRACEID:b9eb4de6-5673-b6fe-4976-f5807235733c PRINCIPALID:AIDAINN64S2TX5QWEFIVE [INFO] EVENT:PublishOut MESSAGE: IpAddress: 54.217.201.236 SourcePort: 45135
2018-04-10 11:27:00.381 TRACEID:8aae685d-eee6-2cd5-71f9-405f39e49449 PRINCIPALID:AIDAINN64S2TX5QWEFIVE [INFO] EVENT:PublishOut TOPICNAME:$aws/things/sensor1/shadow/update MESSAGE:PublishOut Status: SUCCESS
2018-04-10 11:27:00.381 TRACEID:8aae685d-eee6-2cd5-71f9-405f39e49449 PRINCIPALID:AIDAINN64S2TX5QWEFIVE [INFO] EVENT:PublishOut MESSAGE: IpAddress: 54.217.201.236 SourcePort: 45135
2018-04-10 11:28:00.791 TRACEID:6115511a-172f-b7d4-5500-0ead5708349d PRINCIPALID:AIDAINN64S2TX5QWEFIVE [INFO] EVENT:PublishOut TOPICNAME:$aws/things/sensor1/shadow/update MESSAGE:PublishOut Status: SUCCESS
2018-04-10 11:28:00.791 TRACEID:6115511a-172f-b7d4-5500-0ead5708349d PRINCIPALID:AIDAINN64S2TX5QWEFIVE [INFO] EVENT:PublishOut MESSAGE: IpAddress: 54.217.201.236 SourcePort: 45135
2018-04-10 11:28:59.205 TRACEID:48e6c22c-3faa-1650-f95a-d98445a3634f PRINCIPALID:AIDAINN64S2TX5QWEFIVE [INFO] EVENT:PublishOut TOPICNAME:$aws/things/sensor1/shadow/update MESSAGE:PublishOut Status: SUCCESS
2018-04-10 11:28:59.205 TRACEID:48e6c22c-3faa-1650-f95a-d98445a3634f PRINCIPALID:AIDAINN64S2TX5QWEFIVE [INFO] EVENT:PublishOut MESSAGE: IpAddress: 54.217.201.236 SourcePort: 45135
2018-04-10 11:29:59.571 TRACEID:ff059e8b-6d7f-5b48-5e29-96a423bb00f6 PRINCIPALID:AIDAINN64S2TX5QWEFIVE [INFO] EVENT:PublishOut TOPICNAME:$aws/things/sensor1/shadow/update MESSAGE:PublishOut Status: SUCCESS
2018-04-10 11:29:59.571 TRACEID:ff059e8b-6d7f-5b48-5e29-96a423bb00f6 PRINCIPALID:AIDAINN64S2TX5QWEFIVE [INFO] EVENT:PublishOut MESSAGE: IpAddress: 54.217.201.236 SourcePort: 45135
2018-04-10 11:30:59.969 TRACEID:0026dfe3-119e-0d80-6135-a89ef12c5daa PRINCIPALID:AIDAINN64S2TX5QWEFIVE [INFO] EVENT:PublishOut TOPICNAME:$aws/things/sensor1/shadow/update MESSAGE:PublishOut Status: SUCCESS
2018-04-10 11:30:59.969 TRACEID:0026dfe3-119e-0d80-6135-a89ef12c5daa PRINCIPALID:AIDAINN64S2TX5QWEFIVE [INFO] EVENT:PublishOut MESSAGE: IpAddress: 54.217.201.236 SourcePort: 45135
2018-04-10 11:32:00.398 TRACEID:b8f1507f-d2a9-7c53-b3a4-17616a8b75a6 PRINCIPALID:AIDAINN64S2TX5QWEFIVE [INFO] EVENT:PublishOut TOPICNAME:$aws/things/sensor1/shadow/update MESSAGE:PublishOut Status: SUCCESS
2018-04-10 11:32:00.398 TRACEID:b8f1507f-d2a9-7c53-b3a4-17616a8b75a6 PRINCIPALID:AIDAINN64S2TX5QWEFIVE [INFO] EVENT:PublishOut MESSAGE: IpAddress: 54.217.201.236 SourcePort: 45135
2018-04-10 11:33:00.770 TRACEID:c6a2fd22-81cb-8d7b-fa99-b883a6be0c70 PRINCIPALID:AIDAINN64S2TX5QWEFIVE [INFO] EVENT:PublishOut TOPICNAME:$aws/things/sensor1/shadow/update MESSAGE:PublishOut Status: SUCCESS
2018-04-10 11:33:00.770 TRACEID:c6a2fd22-81cb-8d7b-fa99-b883a6be0c70 PRINCIPALID:AIDAINN64S2TX5QWEFIVE [INFO] EVENT:PublishOut MESSAGE: IpAddress: 54.217.201.236 SourcePort: 45135
2018-04-10 11:33:59.162 TRACEID:d930476e-df3e-75a3-4874-7d526066557e PRINCIPALID:AIDAINN64S2TX5QWEFIVE [ERROR] EVENT:PublishOut TOPICNAME:$aws/things/sensor1/shadow/update MESSAGE:PublishOut Status: AUTHORIZATION_ERROR Failure reason:AUTHORIZATION_FAILURE
2018-04-10 11:33:59.162 TRACEID:d930476e-df3e-75a3-4874-7d526066557e PRINCIPALID:AIDAINN64S2TX5QWEFIVE [INFO] EVENT:PublishOut MESSAGE: IpAddress: 54.217.201.236 SourcePort: 45135
2018-04-10 11:34:35.863 TRACEID:c40ad4c2-451c-4667-0c93-53943fea6b23 PRINCIPALID:AIDAINN64S2TX5QWEFIVE [INFO] EVENT:MQTT Client Disconnect MESSAGE:Disconnect Status: SUCCESS
2018-04-10 11:34:35.863 TRACEID:c40ad4c2-451c-4667-0c93-53943fea6b23 PRINCIPALID:AIDAINN64S2TX5QWEFIVE [INFO] EVENT:MQTT Client Disconnect MESSAGE: IpAddress: 54.217.201.236 SourcePort: 45135

last part of basicPubSub.py log:

2018-04-10 11:26:20,269 - AWSIoTPythonSDK.core.protocol.internal.clients - DEBUG - Invoking custom event callback...
2018-04-10 11:27:20,646 - AWSIoTPythonSDK.core.protocol.internal.workers - DEBUG - Produced [message] event
2018-04-10 11:27:20,649 - AWSIoTPythonSDK.core.protocol.internal.workers - DEBUG - Dispatching [message] event
2018-04-10 11:27:20,649 - AWSIoTPythonSDK.core - DEBUG - Received a new message:
2018-04-10 11:27:20,649 - AWSIoTPythonSDK.core - DEBUG - {"state":{"reported":{"hum":39.7,"temp":22.3,"relay":false,"pir":false},"desired":{"hum":39.7,"temp":22.3,"pir":false}}}
2018-04-10 11:27:20,649 - AWSIoTPythonSDK.core - DEBUG - from topic:
2018-04-10 11:27:20,649 - AWSIoTPythonSDK.core - DEBUG - $aws/things/sensor1/shadow/update
2018-04-10 11:27:20,649 - AWSIoTPythonSDK.core - DEBUG - --------------


2018-04-10 11:27:20,649 - AWSIoTPythonSDK.core.protocol.internal.clients - DEBUG - Invoking custom event callback...
2018-04-10 11:28:21,058 - AWSIoTPythonSDK.core.protocol.internal.workers - DEBUG - Produced [message] event
2018-04-10 11:28:21,061 - AWSIoTPythonSDK.core.protocol.internal.workers - DEBUG - Dispatching [message] event
2018-04-10 11:28:21,061 - AWSIoTPythonSDK.core - DEBUG - Received a new message:
2018-04-10 11:28:21,061 - AWSIoTPythonSDK.core - DEBUG - {"state":{"reported":{"hum":39.9,"temp":22.6,"relay":false,"pir":false},"desired":{"hum":39.9,"temp":22.6,"pir":false}}}
2018-04-10 11:28:21,061 - AWSIoTPythonSDK.core - DEBUG - from topic:
2018-04-10 11:28:21,061 - AWSIoTPythonSDK.core - DEBUG - $aws/things/sensor1/shadow/update
2018-04-10 11:28:21,061 - AWSIoTPythonSDK.core - DEBUG - --------------


2018-04-10 11:28:21,061 - AWSIoTPythonSDK.core.protocol.internal.clients - DEBUG - Invoking custom event callback...
2018-04-10 11:29:19,473 - AWSIoTPythonSDK.core.protocol.internal.workers - DEBUG - Produced [message] event
2018-04-10 11:29:19,474 - AWSIoTPythonSDK.core.protocol.internal.workers - DEBUG - Dispatching [message] event
2018-04-10 11:29:19,474 - AWSIoTPythonSDK.core - DEBUG - Received a new message:
2018-04-10 11:29:19,474 - AWSIoTPythonSDK.core - DEBUG - {"state":{"reported":{"hum":40,"temp":22.6,"relay":false,"pir":false},"desired":{"hum":40,"temp":22.6,"pir":false}}}
2018-04-10 11:29:19,474 - AWSIoTPythonSDK.core - DEBUG - from topic:
2018-04-10 11:29:19,474 - AWSIoTPythonSDK.core - DEBUG - $aws/things/sensor1/shadow/update
2018-04-10 11:29:19,474 - AWSIoTPythonSDK.core - DEBUG - --------------


2018-04-10 11:29:19,474 - AWSIoTPythonSDK.core.protocol.internal.clients - DEBUG - Invoking custom event callback...
2018-04-10 11:30:19,841 - AWSIoTPythonSDK.core.protocol.internal.workers - DEBUG - Produced [message] event
2018-04-10 11:30:19,850 - AWSIoTPythonSDK.core.protocol.internal.workers - DEBUG - Dispatching [message] event
2018-04-10 11:30:19,850 - AWSIoTPythonSDK.core - DEBUG - Received a new message:
2018-04-10 11:30:19,850 - AWSIoTPythonSDK.core - DEBUG - {"state":{"reported":{"hum":40,"temp":22.6,"relay":false,"pir":false},"desired":{"hum":40,"temp":22.6,"pir":false}}}
2018-04-10 11:30:19,850 - AWSIoTPythonSDK.core - DEBUG - from topic:
2018-04-10 11:30:19,850 - AWSIoTPythonSDK.core - DEBUG - $aws/things/sensor1/shadow/update
2018-04-10 11:30:19,850 - AWSIoTPythonSDK.core - DEBUG - --------------


2018-04-10 11:30:19,850 - AWSIoTPythonSDK.core.protocol.internal.clients - DEBUG - Invoking custom event callback...
2018-04-10 11:31:20,241 - AWSIoTPythonSDK.core.protocol.internal.workers - DEBUG - Produced [message] event
2018-04-10 11:31:20,249 - AWSIoTPythonSDK.core.protocol.internal.workers - DEBUG - Dispatching [message] event
2018-04-10 11:31:20,249 - AWSIoTPythonSDK.core - DEBUG - Received a new message:
2018-04-10 11:31:20,249 - AWSIoTPythonSDK.core - DEBUG - {"state":{"reported":{"hum":40,"temp":22.6,"relay":false,"pir":false},"desired":{"hum":40,"temp":22.6,"pir":false}}}
2018-04-10 11:31:20,249 - AWSIoTPythonSDK.core - DEBUG - from topic:
2018-04-10 11:31:20,249 - AWSIoTPythonSDK.core - DEBUG - $aws/things/sensor1/shadow/update
2018-04-10 11:31:20,249 - AWSIoTPythonSDK.core - DEBUG - --------------


2018-04-10 11:31:20,249 - AWSIoTPythonSDK.core.protocol.internal.clients - DEBUG - Invoking custom event callback...
2018-04-10 11:32:20,671 - AWSIoTPythonSDK.core.protocol.internal.workers - DEBUG - Produced [message] event
2018-04-10 11:32:20,672 - AWSIoTPythonSDK.core.protocol.internal.workers - DEBUG - Dispatching [message] event
2018-04-10 11:32:20,672 - AWSIoTPythonSDK.core - DEBUG - Received a new message:
2018-04-10 11:32:20,672 - AWSIoTPythonSDK.core - DEBUG - {"state":{"reported":{"hum":40,"temp":22.6,"relay":false,"pir":false},"desired":{"hum":40,"temp":22.6,"pir":false}}}
2018-04-10 11:32:20,672 - AWSIoTPythonSDK.core - DEBUG - from topic:
2018-04-10 11:32:20,673 - AWSIoTPythonSDK.core - DEBUG - $aws/things/sensor1/shadow/update
2018-04-10 11:32:20,673 - AWSIoTPythonSDK.core - DEBUG - --------------


2018-04-10 11:32:20,673 - AWSIoTPythonSDK.core.protocol.internal.clients - DEBUG - Invoking custom event callback...
2018-04-10 11:33:21,044 - AWSIoTPythonSDK.core.protocol.internal.workers - DEBUG - Produced [message] event
2018-04-10 11:33:21,045 - AWSIoTPythonSDK.core.protocol.internal.workers - DEBUG - Dispatching [message] event
2018-04-10 11:33:21,045 - AWSIoTPythonSDK.core - DEBUG - Received a new message:
2018-04-10 11:33:21,045 - AWSIoTPythonSDK.core - DEBUG - {"state":{"reported":{"hum":40,"temp":22.6,"relay":false,"pir":false},"desired":{"hum":40,"temp":22.6,"pir":false}}}
2018-04-10 11:33:21,045 - AWSIoTPythonSDK.core - DEBUG - from topic:
2018-04-10 11:33:21,046 - AWSIoTPythonSDK.core - DEBUG - $aws/things/sensor1/shadow/update
2018-04-10 11:33:21,046 - AWSIoTPythonSDK.core - DEBUG - --------------


2018-04-10 11:33:21,046 - AWSIoTPythonSDK.core.protocol.internal.clients - DEBUG - Invoking custom event callback...

liuszeng · 2018-04-10T17:25:14Z

Hi @jp-embedded ,

Thank you very much for providing the information. The following lines in cloudwatch logs look suspicious:

...
2018-04-10 11:33:59.162 TRACEID:d930476e-df3e-75a3-4874-7d526066557e PRINCIPALID:AIDAINN64S2TX5QWEFIVE [ERROR] EVENT:PublishOut TOPICNAME:$aws/things/sensor1/shadow/update MESSAGE:PublishOut Status: AUTHORIZATION_ERROR Failure reason:AUTHORIZATION_FAILURE
2018-04-10 11:33:59.162 TRACEID:d930476e-df3e-75a3-4874-7d526066557e PRINCIPALID:AIDAINN64S2TX5QWEFIVE [INFO] EVENT:PublishOut MESSAGE: IpAddress: 54.217.201.236 SourcePort: 45135
2018-04-10 11:34:35.863 TRACEID:c40ad4c2-451c-4667-0c93-53943fea6b23 PRINCIPALID:AIDAINN64S2TX5QWEFIVE [INFO] EVENT:MQTT Client Disconnect MESSAGE:Disconnect Status: SUCCESS
2018-04-10 11:34:35.863 TRACEID:c40ad4c2-451c-4667-0c93-53943fea6b23 PRINCIPALID:AIDAINN64S2TX5QWEFIVE [INFO] EVENT:MQTT Client Disconnect MESSAGE: IpAddress: 54.217.201.236 SourcePort: 45135
...

We will dig into that and let you know about the updates.

Thanks,
Liusu

liuszeng · 2018-04-19T21:33:40Z

Hi @jp-embedded ,

Finally, I was able to spot the issue:

What happens when WebSocket connection gets passed 24-hour window?
The remote server will cut the authorization of the connection such that the client can no longer use that connection to send/receive any MQTT packets. However, the server is NOT closing the connection. This means, the read result of the client side socket.read(...) will be in the size of 0, without raising any errors.
Why isn't the MQTT PINGREQ/PINGRESP working to detect the disconnect?
When the above case happens, the following line is preventing paho from entering the keep-alive check/reconnect logic:
https://github.com/aws/aws-iot-device-sdk-python/blob/master/AWSIoTPythonSDK/core/protocol/connection/cores.py#L307
How to mitigate this?
As a work-around for now, you can change the above line to the following:

...
import errno
...

dataChunk = self._sslSocket.read(self._remainedLength)
if not dataChunk:
    raise socket.error(errno.ECONNABORTED, 0)
...

We will try to incorporate this into the SDK bug-fix releases.

Hope the above helps and unblocks you.

Thanks,
Liusu

jp-embedded · 2018-04-20T06:42:35Z

thanks!

liuszeng · 2018-06-29T00:22:52Z

Addressed in v1.4.0.

liuszeng added the bug This issue is a bug. label Apr 19, 2018

ghost mentioned this issue Jun 18, 2018

Processor time continues to be used after a failing connect command #136

Closed

liuszeng closed this as completed Jun 29, 2018

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

no reconnect after 24 hours #124

no reconnect after 24 hours #124

jp-embedded commented Apr 4, 2018

liuszeng commented Apr 4, 2018

jp-embedded commented Apr 5, 2018

liuszeng commented Apr 5, 2018

jp-embedded commented Apr 6, 2018 •

edited by liuszeng

Loading

jp-embedded commented Apr 6, 2018

liuszeng commented Apr 6, 2018

jp-embedded commented Apr 9, 2018 •

edited by liuszeng

Loading

jp-embedded commented Apr 10, 2018 •

edited by liuszeng

Loading

liuszeng commented Apr 10, 2018 •

edited

Loading

liuszeng commented Apr 19, 2018

jp-embedded commented Apr 20, 2018

liuszeng commented Jun 29, 2018

no reconnect after 24 hours #124

no reconnect after 24 hours #124

Comments

jp-embedded commented Apr 4, 2018

liuszeng commented Apr 4, 2018

jp-embedded commented Apr 5, 2018

liuszeng commented Apr 5, 2018

jp-embedded commented Apr 6, 2018 • edited by liuszeng Loading

jp-embedded commented Apr 6, 2018

liuszeng commented Apr 6, 2018

jp-embedded commented Apr 9, 2018 • edited by liuszeng Loading

jp-embedded commented Apr 10, 2018 • edited by liuszeng Loading

liuszeng commented Apr 10, 2018 • edited Loading

liuszeng commented Apr 19, 2018

jp-embedded commented Apr 20, 2018

liuszeng commented Jun 29, 2018

jp-embedded commented Apr 6, 2018 •

edited by liuszeng

Loading

jp-embedded commented Apr 9, 2018 •

edited by liuszeng

Loading

jp-embedded commented Apr 10, 2018 •

edited by liuszeng

Loading

liuszeng commented Apr 10, 2018 •

edited

Loading