Error calling ShadowGet in shadow client's onOnline callback

[sidpat]

Hi,

I am trying to get the shadow document whenever the client connects or reconnects (to sync my device) using onOnline callback function:-

def onConnect():
    print("connected to aws")
    myDeviceShadow.shadowGet(customCallback_get, 10)

But I keep getting connectTimeoutException errors. I believe this due to thread Lock and Event objects. Dont know if this is a bug or by design, and would appreciate some information on this. In any case, how am I supposed to solve my problem? I am using AWSIoTPythonSDK 1.2.0.

Here is the console output with logs:-

2017-10-14 19:28:31,567 - AWSIoTPythonSDK.core.protocol.internal.clients - DEBUG - Initializing MQTT layer...
2017-10-14 19:28:31,569 - AWSIoTPythonSDK.core.protocol.internal.clients - DEBUG - Registering internal event callbacks to MQTT layer...
2017-10-14 19:28:31,570 - AWSIoTPythonSDK.core.protocol.internal.workers - DEBUG - Event consuming thread started
2017-10-14 19:28:31,571 - AWSIoTPythonSDK.core.protocol.mqtt_core - INFO - MqttCore initialized
2017-10-14 19:28:31,572 - AWSIoTPythonSDK.core.protocol.mqtt_core - INFO - Client id: did001-oubocnasokqwec
2017-10-14 19:28:31,573 - AWSIoTPythonSDK.core.protocol.mqtt_core - INFO - Protocol version: MQTTv3.1.1
2017-10-14 19:28:31,574 - AWSIoTPythonSDK.core.protocol.mqtt_core - INFO - Authentication type: TLSv1.2 certificate based Mutual Auth.
2017-10-14 19:28:31,575 - AWSIoTPythonSDK.core.protocol.mqtt_core - INFO - Configuring offline requests queueing: max queue size: 0
2017-10-14 19:28:31,576 - AWSIoTPythonSDK.core.protocol.mqtt_core - INFO - Configuring offline requests queue draining interval: 0.100000 sec
2017-10-14 19:28:31,577 - AWSIoTPythonSDK.core.protocol.mqtt_core - INFO - Configuring endpoint...
2017-10-14 19:28:31,578 - AWSIoTPythonSDK.core.protocol.mqtt_core - INFO - Configuring certificates...
2017-10-14 19:28:31,579 - AWSIoTPythonSDK.core.protocol.mqtt_core - INFO - Configuring reconnect back off timing...
2017-10-14 19:28:31,580 - AWSIoTPythonSDK.core.protocol.mqtt_core - INFO - Base quiet time: 1.000000 sec
2017-10-14 19:28:31,580 - AWSIoTPythonSDK.core.protocol.mqtt_core - INFO - Max quiet time: 32.000000 sec
2017-10-14 19:28:31,581 - AWSIoTPythonSDK.core.protocol.mqtt_core - INFO - Stable connection time: 20.000000 sec
2017-10-14 19:28:31,582 - AWSIoTPythonSDK.core.protocol.mqtt_core - INFO - Configuring connect/disconnect time out: 10.000000 sec
2017-10-14 19:28:31,583 - AWSIoTPythonSDK.core.protocol.mqtt_core - INFO - Configuring MQTT operation time out: 5.000000 sec
2017-10-14 19:28:31,583 - AWSIoTPythonSDK.core.protocol.mqtt_core - INFO - Configuring offline requests queueing: max queue size: -1
2017-10-14 19:28:31,584 - AWSIoTPythonSDK.core.protocol.mqtt_core - INFO - Configuring offline requests queue draining interval: 0.100000 sec
2017-10-14 19:28:31,585 - AWSIoTPythonSDK.core.protocol.mqtt_core - INFO - Configuring last will...
2017-10-14 19:28:31,586 - AWSIoTPythonSDK.core.protocol.mqtt_core - INFO - Performing sync connect...
2017-10-14 19:28:31,586 - AWSIoTPythonSDK.core.protocol.mqtt_core - INFO - Performing async connect...
2017-10-14 19:28:31,587 - AWSIoTPythonSDK.core.protocol.mqtt_core - INFO - Keep-alive: 10.000000 sec
2017-10-14 19:28:31,588 - AWSIoTPythonSDK.core.protocol.mqtt_core - DEBUG - Passing in general notification callbacks to internal client...
2017-10-14 19:28:31,589 - AWSIoTPythonSDK.core.protocol.internal.clients - DEBUG - Filling in fixed event callbacks: CONNACK, DISCONNECT, MESSAGE
2017-10-14 19:28:33,527 - AWSIoTPythonSDK.core.protocol.internal.clients - DEBUG - Starting network I/O thread...
2017-10-14 19:28:33,896 - AWSIoTPythonSDK.core.protocol.internal.workers - DEBUG - Produced [connack] event
2017-10-14 19:28:33,896 - AWSIoTPythonSDK.core.protocol.internal.workers - DEBUG - Dispatching [connack] event
2017-10-14 19:28:33,899 - AWSIoTPythonSDK.core.protocol.internal.workers - DEBUG - No need for recovery
2017-10-14 19:28:33,900 - AWSIoTPythonSDK.core.protocol.internal.clients - DEBUG - Invoking custom event callback...
2017-10-14 19:28:33,901 - AWSIoTPythonSDK.core.protocol.mqtt_core - INFO - Performing sync subscribe...
2017-10-14 19:28:33,902 - AWSIoTPythonSDK.core.protocol.internal.workers - DEBUG - Adding a new subscription record: $aws/things/did001/shadow/get/accepted qos: 0
2017-10-14 19:28:33,903 - AWSIoTPythonSDK.core.protocol.internal.clients - DEBUG - Filling in custom suback event callback...

connected to aws

2017-10-14 19:28:38,904 - AWSIoTPythonSDK.core.protocol.internal.clients - DEBUG - Removing custom event callback...
2017-10-14 19:28:38,905 - AWSIoTPythonSDK.core.protocol.mqtt_core - ERROR - Subscribe timed out
2017-10-14 19:28:38,906 - AWSIoTPythonSDK.core.protocol.internal.workers - DEBUG - Produced [suback] event
Exception in thread Thread-4:
Traceback (most recent call last):
  File "//anaconda/envs/py36/lib/python3.6/threading.py", line 916, in _bootstrap_inner
    self.run()
  File "//anaconda/envs/py36/lib/python3.6/threading.py", line 864, in run
    self._target(*self._args, **self._kwargs)
  File "//anaconda/envs/py36/lib/python3.6/site-packages/AWSIoTPythonSDK/core/protocol/internal/workers.py", line 137, in _dispatch
    self._dispatch_one()
  File "//anaconda/envs/py36/lib/python3.6/site-packages/AWSIoTPythonSDK/core/protocol/internal/workers.py", line 143, in _dispatch_one
    self._internal_async_client.invoke_event_callback(mid, data=data)
  File "//anaconda/envs/py36/lib/python3.6/site-packages/AWSIoTPythonSDK/core/protocol/internal/clients.py", line 217, in invoke_event_callback
    event_callback(mid, data)
  File "//anaconda/envs/py36/lib/python3.6/site-packages/AWSIoTPythonSDK/core/protocol/internal/clients.py", line 137, in combined_on_connect_callback
    self.on_online()
  File "<ipython-input-3-94cb016356de>", line 80, in onConnect
    myDeviceShadow.shadowGet(customCallback_get, 10)
  File "//anaconda/envs/py36/lib/python3.6/site-packages/AWSIoTPythonSDK/core/shadow/deviceShadow.py", line 242, in shadowGet
    self._shadowManagerHandler.basicShadowSubscribe(self._shadowName, "get", self.generalCallback)
  File "//anaconda/envs/py36/lib/python3.6/site-packages/AWSIoTPythonSDK/core/shadow/shadowManager.py", line 70, in basicShadowSubscribe
    self._mqttCoreHandler.subscribe(currentShadowAction.getTopicAccept(), 0, srcCallback)
  File "//anaconda/envs/py36/lib/python3.6/site-packages/AWSIoTPythonSDK/core/protocol/mqtt_core.py", line 259, in subscribe
    raise subscribeTimeoutException()
AWSIoTPythonSDK.exception.AWSIoTExceptions.subscribeTimeoutException

2017-10-14 19:28:43,529 - AWSIoTPythonSDK.core.protocol.mqtt_core - ERROR - Connect timed out

[hedeshianaws]

@sidpat So this looks like a behavior change that was introduced with the async client support. Unfortunately, the dev who made the change is unable to comment whether or not this behavior is intended. My guess is that we are running into a recursive locking issue. I'll do some investigation to see if there is a workaround possible and get back to you.

[hedeshianaws]

Alright, I have a root cause, and it is just as I suspected. Callback invocation routine grabs the client's lock here:

https://github.com/aws/aws-iot-device-sdk-python/blob/master/AWSIoTPythonSDK/core/protocol/internal/clients.py#L210

If within your callback, you call subscribe to get the shadow topic, you hang indefinitely here (or until timeout):

https://github.com/aws/aws-iot-device-sdk-python/blob/master/AWSIoTPythonSDK/core/protocol/internal/clients.py#L176

Oops. This looks like a pretty big oversight in the design, and I'm afraid simply removing the lock on line 210 won't really be a workable solution. In fact, this affects all functions (publish, subscribe, etc...) and not just shadow operations.

You can try this as a workaround:

from threading import Thread

def _onConnect():
    print("getting the shadow")
    myDeviceShadow.shadowGet(customCallback_get, 10)

def onConnect():
    print("connected to aws")
    thread = Thread(target = _onConnect)
    thread.start()

I realize this is far from ideal as it introduces additional threading complexity and means you will have to exercise extreme care with _onConnect() and the rest of your application. You may also be able do do something else like set a flag or semaphore from the callback and do the shadowGet somewhere else.

[hedeshianaws]

@sidpat Word from the devs is that this design change is actually intentional. I've added an internal item in our queue to make sure this behavior is properly documented in the README, and it should be available on the next point release. Please feel free to open a new issue if you have additional questions.

[sidpat]

@hedeshianaws, Thanks for the update. Your workaround solution works, but I cant make changes that are "far from ideal". And if the devs have made discussed code design intentionally, then how according to the devs can I achieve my goal of - 'getting the shadow document whenever the client connects or reconnects (to sync my device)' without potentially risky workarounds? This is a basic requirement of most if not all IoT devices. I would suggest reopening this issue until properly addressed in the sdk. Hope you understand the importance of the problem here and convey it to the devs.

Thanks,
Sid

[hedeshianaws]

then how according to the devs can I achieve my goal of - 'getting the shadow document whenever the client connects or reconnects (to sync my device)'

There are a large number of ways you can accomplish what you want, and it all depends on how you architect your program. The only restriction is that you cannot call a synchronous API from within the callback context since the lock is already held, and would result in a recursive deadlock condition.

Options include setting a flag or sentinel from the callback which you process from your main thread / loop. Or if you don't want to do that, you can post an event to an event queue and process it in your own thread.

potentially risky workarounds

You're reading way too much into this.