Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

LWT (Will) with retain=True causes AWS_ERROR_MQTT_UNEXPECTED_HANGUP #113

Closed
2 tasks done
JoshM1994 opened this issue Sep 23, 2020 · 3 comments
Closed
2 tasks done

LWT (Will) with retain=True causes AWS_ERROR_MQTT_UNEXPECTED_HANGUP #113

JoshM1994 opened this issue Sep 23, 2020 · 3 comments
Labels
bug This issue is a bug.

Comments

@JoshM1994
Copy link

JoshM1994 commented Sep 23, 2020 •
edited
Loading

Confirm by changing [ ] to [x] below to ensure that it's a bug:

Known Issue

  • I'm using ATS data type endpoint: the endpoint should look like <prefix>-ats.iot.<region>.amazonaws.com

Describe the bug
When configuring an MQTT connection with a last will and testament (LWT), the .connect() future returns AWS_ERROR_MQTT_UNEXPECTED_HANGUP when the Will is configured with retain=True.

Could this be related to the updated way messages are queued in V2?

SDK version number
==1.5.0

Platform/OS/Device
Mac OS 10.15.6

To Reproduce (observed behavior)

  • Certificates have policy with iot:* so I do not believe it is a permissions issue
import awscrt
from awscrt import io, mqtt
from awsiot import iotshadow
from awsiot import mqtt_connection_builder
import os
import time

# Also verified to be an issue with us-west-2
MQTT_ENDPOINT="xxx-ats.iot.us-east-2.amazonaws.com"


event_loop_group = io.EventLoopGroup(1)
host_resolver = io.DefaultHostResolver(event_loop_group)
client_bootstrap = io.ClientBootstrap(event_loop_group, host_resolver)

mqtt_will: mqtt.Will = mqtt.Will(
    topic="joshtest/lwt",
    qos=mqtt.QoS.AT_LEAST_ONCE,
    payload=b"Mqtt Bridge (V2) lost connection",
    retain=True,
)

mqtt_conn: mqtt.Connection = mqtt_connection_builder.mtls_from_path(
    endpoint=MQTT_ENDPOINT,
    cert_filepath=os.path.join(
        "./certs", "certificate.pem.crt"
    ),
    pri_key_filepath=os.path.join(
        "./certs", "private.pem.key"
    ),
    client_bootstrap=client_bootstrap,
    ca_filepath=os.path.join("./certs", "AmazonRootCA1.pem"),
    client_id="josh-lwt-test",
    will=mqtt_will,
)

pub_future = mqtt_conn.connect()
pub_future.result()
print("connected")
while 1:
    time.sleep(1)

Expected behavior
When changing retain=True to retain=False on line 19, the connection is established and the print statement is executed

Logs/output

Traceback (most recent call last):
  File "mqtt_lwt.py", line 39, in <module>
    pub_future.result()
  File "/Users/xxx/.pyenv/versions/3.7.8/lib/python3.7/concurrent/futures/_base.py", line 435, in result
    return self.__get_result()
  File "/Users/xxx/.pyenv/versions/3.7.8/lib/python3.7/concurrent/futures/_base.py", line 384, in __get_result
    raise self._exception
awscrt.exceptions.AwsCrtError: AwsCrtError(name='AWS_ERROR_MQTT_UNEXPECTED_HANGUP', message='The connection was closed unexpectedly.', code=5134)

[DEBUG] [2020-09-23T18:12:10Z] [00007000091cf000] [channel] - id=0x7f8cec167e90: Beginning creation and setup of new channel.
[DEBUG] [2020-09-23T18:12:10Z] [00007000091cf000] [task-scheduler] - id=0x7f8cec12b160: Scheduling on_channel_setup_complete task for immediate execution
[DEBUG] [2020-09-23T18:12:10Z] [00007000091cf000] [task-scheduler] - id=0x7f8cec036340: Running kqueue_event_loop_clean_up_handle_data task with <Running> status
[DEBUG] [2020-09-23T18:12:10Z] [00007000091cf000] [task-scheduler] - id=0x7f8cec167bf0: Running kqueue_event_loop_subscribe task with <Running> status
[DEBUG] [2020-09-23T18:12:10Z] [00007000091cf000] [task-scheduler] - id=0x7f8cec12b160: Running on_channel_setup_complete task with <Running> status
[DEBUG] [2020-09-23T18:12:10Z] [00007000091cf000] [channel] - id=0x7f8cec167e90: setup complete, notifying caller.
[DEBUG] [2020-09-23T18:12:10Z] [00007000091cf000] [channel] - id=0x7f8cec167e90: no message pool is currently stored in the event-loop local storage, adding 0x7f8cec107200 with max message size 16384, message count 4, with 4 small blocks of 128 bytes.
[DEBUG] [2020-09-23T18:12:10Z] [00007000091cf000] [channel-bootstrap] - id=0x7f8ceae07970: channel 0x7f8cec167e90 setup succeeded: bootstrapping.
[DEBUG] [2020-09-23T18:12:10Z] [00007000091cf000] [socket-handler] - id=0x7f8cec1689a0: Socket handler created with max_read_size of 16384
[DEBUG] [2020-09-23T18:12:10Z] [00007000091cf000] [task-scheduler] - id=0x7f8cec168c00: Scheduling tls_timeout task for future execution at time 6697565445706
[DEBUG] [2020-09-23T18:12:10Z] [00007000091cf000] [tls-handler] - id=0x7f8cec168bd0: negotiation succeeded
[DEBUG] [2020-09-23T18:12:10Z] [00007000091cf000] [tls-handler] - id=0x7f8cec168bd0: negotiated protocol: x-amzn-mqtt-ca
[DEBUG] [2020-09-23T18:12:10Z] [00007000091cf000] [tls-handler] - id=0x7f8cec168bd0: Remote Server Name: 
[DEBUG] [2020-09-23T18:12:10Z] [00007000091cf000] [channel-bootstrap] - id=0x7f8ceae07970: tls negotiation result 0 on channel 0x7f8cec167e90
[DEBUG] [2020-09-23T18:12:10Z] [00007000091cf000] [mqtt-client] - id=0x7f8cec031e80: Connection successfully opened, sending CONNECT packet
[DEBUG] [2020-09-23T18:12:10Z] [00007000091cf000] [task-scheduler] - id=0x7f8cee0040d0: Scheduling mqtt_connack_timeout task for future execution at time 6696898016827
[DEBUG] [2020-09-23T18:12:10Z] [00007000091cf000] [mqtt-client] - id=0x7f8cec031e80: Adding will to connection on joshtest/lwt with payload Mqtt Bridge (V2) lost connection
[DEBUG] [2020-09-23T18:12:10Z] [00007000091cf000] [mqtt-client] - id=0x7f8cec031e80: Adding username ?SDK=PythonV2&Version=0.9.0 to connection
[ERROR] [2020-09-23T18:12:10Z] [00007000091cf000] [tls-handler] - id=0x7f8cec168bd0: error reported during SSLRead. OSStatus code -9805
[DEBUG] [2020-09-23T18:12:10Z] [00007000091cf000] [task-scheduler] - id=0x7f8cec1680a8: Scheduling channel_shutdown task for immediate execution
[INFO] [2020-09-23T18:12:10Z] [00007000091cf000] [socket] - id=0x7f8cec035d90 fd=8: zero read, socket is closed
[DEBUG] [2020-09-23T18:12:10Z] [00007000091cf000] [channel] - id=0x7f8cec167e90: Channel shutdown is already pending, not scheduling another.
[DEBUG] [2020-09-23T18:12:10Z] [00007000091cf000] [channel] - id=0x7f8cec167e90: Channel shutdown is already pending, not scheduling another.
[DEBUG] [2020-09-23T18:12:10Z] [00007000091cf000] [task-scheduler] - id=0x7f8cec1680a8: Running channel_shutdown task with <Running> status
[DEBUG] [2020-09-23T18:12:10Z] [00007000091cf000] [channel] - id=0x7f8cec167e90: beginning shutdown process
[DEBUG] [2020-09-23T18:12:10Z] [00007000091cf000] [channel] - id=0x7f8cec167e90: handler 0x7f8cec1689a0 shutdown in read dir completed.
[DEBUG] [2020-09-23T18:12:10Z] [00007000091cf000] [tls-handler] - id=0x7f8cec168bd0: shutting down read direction with error 0. Flushing queues.
[DEBUG] [2020-09-23T18:12:10Z] [00007000091cf000] [channel] - id=0x7f8cec167e90: handler 0x7f8cec168bd0 shutdown in read dir completed.
[DEBUG] [2020-09-23T18:12:10Z] [00007000091cf000] [channel] - id=0x7f8cec167e90: handler 0x7f8cec031ea8 shutdown in read dir completed.
[DEBUG] [2020-09-23T18:12:10Z] [00007000091cf000] [task-scheduler] - id=0x7f8cec167eb8: Scheduling (null) task for immediate execution
[DEBUG] [2020-09-23T18:12:10Z] [00007000091cf000] [task-scheduler] - id=0x7f8cec167eb8: Running (null) task with <Running> status
[INFO] [2020-09-23T18:12:10Z] [00007000091cf000] [mqtt-client] - id=0x7f8cec031e80: sending disconnect message as part of graceful shutdown.
[DEBUG] [2020-09-23T18:12:10Z] [00007000091cf000] [tls-handler] - id=0x7f8cec168bd0: SSLWrite failed with OSStatus error code -9805.
[DEBUG] [2020-09-23T18:12:10Z] [00007000091cf000] [mqtt-client] - id=0x7f8cec031e80: failed to send courteous disconnect io message
[DEBUG] [2020-09-23T18:12:10Z] [00007000091cf000] [channel] - id=0x7f8cec167e90: handler 0x7f8cec031ea8 shutdown in write dir completed.
[DEBUG] [2020-09-23T18:12:10Z] [00007000091cf000] [channel] - id=0x7f8cec167e90: handler 0x7f8cec168bd0 shutdown in write dir completed.
[DEBUG] [2020-09-23T18:12:10Z] [00007000091cf000] [socket] - id=0x7f8cec035d90 fd=8: closing
[DEBUG] [2020-09-23T18:12:10Z] [00007000091cf000] [task-scheduler] - id=0x7f8cec167c30: Scheduling kqueue_event_loop_clean_up_handle_data task for immediate execution
[DEBUG] [2020-09-23T18:12:10Z] [00007000091cf000] [task-scheduler] - id=0x7f8cec168a40: Scheduling socket_handler_close task for immediate execution
[DEBUG] [2020-09-23T18:12:10Z] [00007000091cf000] [task-scheduler] - id=0x7f8cec167c30: Running kqueue_event_loop_clean_up_handle_data task with <Running> status
[DEBUG] [2020-09-23T18:12:10Z] [00007000091cf000] [task-scheduler] - id=0x7f8cec168a40: Running socket_handler_close task with <Running> status
[DEBUG] [2020-09-23T18:12:10Z] [00007000091cf000] [channel] - id=0x7f8cec167e90: handler 0x7f8cec1689a0 shutdown in write dir completed.
[DEBUG] [2020-09-23T18:12:10Z] [00007000091cf000] [task-scheduler] - id=0x7f8cec167eb8: Scheduling (null) task for immediate execution
[DEBUG] [2020-09-23T18:12:10Z] [00007000091cf000] [task-scheduler] - id=0x7f8cec167eb8: Running (null) task with <Running> status
[DEBUG] [2020-09-23T18:12:10Z] [00007000091cf000] [channel] - id=0x7f8cec167e90: during shutdown, canceling task 0x7f8cec168c00
[DEBUG] [2020-09-23T18:12:10Z] [00007000091cf000] [task-scheduler] - id=0x7f8cec168c00: Running tls_timeout task with <Canceled> status
[DEBUG] [2020-09-23T18:12:10Z] [00007000091cf000] [channel] - id=0x7f8cec167e90: during shutdown, canceling task 0x7f8cee0040d0
[DEBUG] [2020-09-23T18:12:10Z] [00007000091cf000] [task-scheduler] - id=0x7f8cee0040d0: Running mqtt_connack_timeout task with <Canceled> status
Traceback (most recent call last):
[DEBUG] [2020-09-23T18:12:10Z] [00007000091cf000] [channel-bootstrap] - id=0x7f8ceae07970: channel 0x7f8cec167e90 shutdown with error 0.
[DEBUG] [2020-09-23T18:12:10Z] [00007000091cf000] [channel] - id=0x7f8cec167e90: destroying channel.
[DEBUG] [2020-09-23T18:12:10Z] [00007000091cf000] [channel-bootstrap] - id=0x7f8ceae07970: releasing bootstrap reference
  File "mqtt_lwt.py", line 38, in <module>
    pub_future.result()
  File "/Users/xxx/.pyenv/versions/3.7.8/lib/python3.7/concurrent/futures/_base.py", line 435, in result
    return self.__get_result()
  File "/Users/xxx/.pyenv/versions/3.7.8/lib/python3.7/concurrent/futures/_base.py", line 384, in __get_result
    raise self._exception
awscrt.exceptions.AwsCrtError: AwsCrtError(name='AWS_ERROR_MQTT_UNEXPECTED_HANGUP', message='The connection was closed unexpectedly.', code=5134)
[DEBUG] [2020-09-23T18:12:10Z] [000000010cec1dc0] [mqtt-client] - id=0x7f8cec031e80: user called disconnect.
[ERROR] [2020-09-23T18:12:10Z] [000000010cec1dc0] [mqtt-client] - id=0x7f8cec031e80: Connection is not open, and may not be closed
[DEBUG] [2020-09-23T18:12:10Z] [000000010cec1dc0] [mqtt-client] - id=0x7f8cec031e80: Destroying connection
[DEBUG] [2020-09-23T18:12:10Z] [000000010cec1dc0] [mqtt-topic-tree] - tree=0x7f8cec0320d8: Cleaning up topic tree
[DEBUG] [2020-09-23T18:12:10Z] [000000010cec1dc0] [mqtt-client] - client=0x7f8cec00e3e0: Cleaning up MQTT client
[DEBUG] [2020-09-23T18:12:10Z] [000000010cec1dc0] [channel-bootstrap] - id=0x7f8ceae07970: releasing bootstrap reference
[DEBUG] [2020-09-23T18:12:10Z] [000000010cec1dc0] [channel-bootstrap] - id=0x7f8ceae07970: releasing bootstrap reference
[DEBUG] [2020-09-23T18:12:10Z] [000000010cec1dc0] [channel-bootstrap] - id=0x7f8ceae07970: destroying

Additional context
The main error I am seeing in the logs above is:

[ERROR] [2020-09-23T18:12:10Z] [00007000091cf000] [tls-handler] - id=0x7f8cec168bd0: error reported during SSLRead. OSStatus code -9805

With retain=False, the above line does not appear:

[DEBUG] [2020-09-23T18:15:47Z] [000070000fb4f000] [mqtt-client] - id=0x7feac8ca14d0: Adding will to connection on joshtest/lwt with payload Mqtt Bridge (V2) lost connection
[DEBUG] [2020-09-23T18:15:47Z] [000070000fb4f000] [mqtt-client] - id=0x7feac8ca14d0: Adding username ?SDK=PythonV2&Version=0.9.0 to connection
[DEBUG] [2020-09-23T18:15:47Z] [000070000fb4f000] [task-scheduler] - id=0x7feac8ca1688: Scheduling mqtt_ping task for future execution at time 8111153746033
connected

When running on a Linux image, the error is slightly different but still gives the same AWS error:

[DEBUG] [2020-09-23T18:23:58Z] [0000ffff9c1041e0] [mqtt-client] - id=0xaaaad99bd3d0: Adding will to connection on joshtest/lwt with payload Mqtt Bridge (V2) lost connection
[DEBUG] [2020-09-23T18:23:58Z] [0000ffff9c1041e0] [mqtt-client] - id=0xaaaad99bd3d0: Adding username ?SDK=PythonV2&Version=0.6.2 to connection
[DEBUG] [2020-09-23T18:23:58Z] [0000ffff9c1041e0] [tls-handler] - id=0xffff94017a20: Alert code 0
[DEBUG] [2020-09-23T18:23:58Z] [0000ffff9c1041e0] [task-scheduler] - id=0xffff94006ac8: Scheduling channel_shutdown task for immediate execution
[INFO ] [2020-09-23T18:23:58Z] [0000ffff9c1041e0] [socket] - id=0xffff94004fd0 fd=6: zero read, socket is closed
[DEBUG] [2020-09-23T18:23:58Z] [0000ffff9c1041e0] [channel] - id=0xffff940068c0: Channel shutdown is already pending, not scheduling another.

[DEBUG] [2020-09-23T18:23:58Z] [0000ffff9c1041e0] [channel] - id=0xffff940068c0: destroying channel.
Traceback (most recent call last):
  File "mqtt_lwt.py", line 38, in <module>
    pub_future.result()
  File "/opt/xxx/current/usr/lib/python3.7/concurrent/futures/_base.py", line 435, in result
    return self.__get_result()
  File "/opt/xxx/current/usr/lib/python3.7/concurrent/futures/_base.py", line 384, in __get_result
    raise self._exception
awscrt.exceptions.AwsCrtError: AwsCrtError(name='AWS_ERROR_MQTT_UNEXPECTED_HANGUP', message='The connection was closed unexpectedly.', code=5134)
@JoshM1994 JoshM1994 added bug This issue is a bug. needs-triage This issue or PR still needs to be triaged. labels Sep 23, 2020
@ansonallard
Copy link

I had a similar issue. I'm not entirely sure if this is still the case, but this post states that "AWS IoT currently does not support retained messages".

@jmklix
Copy link
Member

jmklix commented Sep 23, 2020

Ansonallard is correct. As stated in the linked post and here this is not currently supported by the AWS IoT.

The MQTT specification provides a provision for the publisher to request that the broker retain the last message sent to a topic and send it to all future topic subscribers. AWS IoT doesn't support retained messages. If a request is made to retain messages, the connection is disconnected.

@jmklix jmklix closed this as completed Sep 23, 2020
@jmklix jmklix removed the needs-triage This issue or PR still needs to be triaged. label Sep 23, 2020
@JoshM1994
Copy link
Author

@jmklix @ansonallard Thank you both for the references. Seems like, at the absolute minimum, this should be referenced in the source code!

JoshM1994 referenced this issue in JoshM1994/aws-crt-python Sep 23, 2020
@JoshM1994
doc: Highlight that the retain option is not supported by AWS IoT
b66eece 
* Add a link to the AWS IoT documentation specifying that the retain flag will cause a disconnection
* https://github.com/aws/aws-iot-device-sdk-python-v2/issues/113\#issuecomment-697995436
@JoshM1994 JoshM1994 mentioned this issue Sep 23, 2020
Closed
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
bug This issue is a bug.
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@jmklix @JoshM1994 @ansonallard