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.

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

AWS_IO_TLS_ERROR_NEGOTIATION_FAILURE with 1.21.3 #551

Closed
twiking opened this issue Jun 18, 2024 · 7 comments
Closed

AWS_IO_TLS_ERROR_NEGOTIATION_FAILURE with 1.21.3 #551

twiking opened this issue Jun 18, 2024 · 7 comments
Labels
bug This issue is a bug. p2 This is a standard priority issue

Comments

@twiking
Copy link

twiking commented Jun 18, 2024

Describe the bug

I'm using aws-iot-device-sdk-v2 which has a dependency to aws-crt.

After reinstalling my project, aws-iot-device-sdk-v2 now installed aws-crt 1.21.3 instead of 1.21.2 which was release last week. After this I'm started to get AWS_IO_TLS_ERROR_NEGOTIATION_FAILURE when connecting to AWS IoT Core with mqtt5. When I tried to install [email protected] again, it started to work again. So it looks like something got broken when updating the submodules in this release #547

Expected Behavior

Connect to AWS IoT Core successfully

Current Behavior

Get AWS_IO_TLS_ERROR_NEGOTIATION_FAILURE when trying to connect

Reproduction Steps

Connect to AWS IoT Core by using mqtt5 from aws-iot-device-sdk-v2 with a fresh npm install, to install latest version of [email protected].

Possible Solution

No response

Additional Information/Context

No response

aws-crt-nodejs version used

1.21.3

nodejs version used

v20.14.0

Operating System and version

Debian

@twiking twiking added bug This issue is a bug. needs-triage This issue or PR still needs to be triaged. labels Jun 18, 2024
@bretambrose
Copy link
Contributor

bretambrose commented Jun 18, 2024

We have not seen any change in tls-related CI for aws-c-*, aws-crt-nodejs, or the SDK.

Can you provide more information:

  1. Minimal repro sample
  2. Trace logs when you run the repro sample
  3. If using mTLS, key properties (RSA vs. ECC, bits, etc..)

@jmklix jmklix added response-requested Waiting on additional info and feedback. Will move to 'closing-soon' in 7 days. p2 This is a standard priority issue and removed needs-triage This issue or PR still needs to be triaged. labels Jun 19, 2024
@twiking
Copy link
Author

twiking commented Jun 19, 2024

I'm using this example: https://github.com/aws/aws-iot-device-sdk-js-v2/blob/main/samples/node/pub_sub_mqtt5/index.ts
Using certs generated in AWS. I have tried all different security policies, IoTSecurityPolicy_TLS13_1_3_2022_10 etc.

[DEBUG] [2024-06-19T05:17:44Z] [0000ffffbef7c040] [tls-handler] - ctx: Certificate and key have been set, setting them up now.
[DEBUG] [2024-06-19T05:17:44Z] [0000ffffbef7c040] [tls-handler] - ctx: Setting ALPN list x-amzn-mqtt-ca
[DEBUG] [2024-06-19T05:17:44Z] [0000ffffbef7c040] [channel-bootstrap] - id=0x331e5660: acquiring bootstrap reference
[DEBUG] [2024-06-19T05:17:44Z] [0000ffffbef7c040] [mqtt5-general] - id=0x333b7870: aws_mqtt5_client_options_storage host name set to <hidden-endpoint>.iot.eu-north-1.amazonaws.com
[DEBUG] [2024-06-19T05:17:44Z] [0000ffffbef7c040] [mqtt5-general] - id=0x333b7870: aws_mqtt5_client_options_storage port set to 8883
[DEBUG] [2024-06-19T05:17:44Z] [0000ffffbef7c040] [mqtt5-general] - id=0x333b7870: aws_mqtt5_client_options_storage client bootstrap set to (0x331e5660)
[DEBUG] [2024-06-19T05:17:44Z] [0000ffffbef7c040] [mqtt5-general] - id=0x333b7870: aws_mqtt5_client_options_storage socket options set to: type = 0, domain = 0, connect_timeout_ms = 10000
[DEBUG] [2024-06-19T05:17:44Z] [0000ffffbef7c040] [mqtt5-general] - id=0x333b7870: aws_mqtt5_client_options_storage  tls options set:
[DEBUG] [2024-06-19T05:17:44Z] [0000ffffbef7c040] [mqtt5-general] - id=0x333b7870: aws_mqtt5_client_options_storage  tls options alpn not used
[DEBUG] [2024-06-19T05:17:44Z] [0000ffffbef7c040] [mqtt5-general] - id=0x333b7870: aws_mqtt5_client_options_storage  tls options SNI value set to "<hidden-endpoint>.iot.eu-north-1.amazonaws.com"
[DEBUG] [2024-06-19T05:17:44Z] [0000ffffbef7c040] [mqtt5-general] - id=0x333b7870: aws_mqtt5_client_options_storage  tls options tls context set to (0x331aa5d0)
[DEBUG] [2024-06-19T05:17:44Z] [0000ffffbef7c040] [mqtt5-general] - id=0x333b7870: aws_mqtt5_client_options_storage  tls options handshake timeout set to 10000
[DEBUG] [2024-06-19T05:17:44Z] [0000ffffbef7c040] [mqtt5-general] - id=0x333b7870: mqtt5_client_options_storage disabling websockets
[DEBUG] [2024-06-19T05:17:44Z] [0000ffffbef7c040] [mqtt5-general] - id=0x333b7870: aws_mqtt5_client_options_storage session behavior set to 0 (Clean session always)
[DEBUG] [2024-06-19T05:17:44Z] [0000ffffbef7c040] [mqtt5-general] - id=0x333b7870: aws_mqtt5_client_options_storage outbound topic aliasing behavior set to 0 (Outbound topic aliasing disabled)
[DEBUG] [2024-06-19T05:17:44Z] [0000ffffbef7c040] [mqtt5-general] - id=0x333b7870: aws_mqtt5_client_options_storage maximum outbound topic alias cache size set to 25
[DEBUG] [2024-06-19T05:17:44Z] [0000ffffbef7c040] [mqtt5-general] - id=0x333b7870: aws_mqtt5_client_options_storage inbound topic aliasing behavior set to 0 (Inbound topic aliasing behavior disabled)
[DEBUG] [2024-06-19T05:17:44Z] [0000ffffbef7c040] [mqtt5-general] - id=0x333b7870: aws_mqtt5_client_options_storage inbound topic alias cache size set to 25
[DEBUG] [2024-06-19T05:17:44Z] [0000ffffbef7c040] [mqtt5-general] - id=0x333b7870: aws_mqtt5_client_options_storage extended validation and flow control options set to 1 (AWS IoT Core flow control and packet validation)
[DEBUG] [2024-06-19T05:17:44Z] [0000ffffbef7c040] [mqtt5-general] - id=0x333b7870: aws_mqtt5_client_options_storage operation queue behavior set to 0 (Fail incomplete QoS 0 publishes)
[DEBUG] [2024-06-19T05:17:44Z] [0000ffffbef7c040] [mqtt5-general] - id=0x333b7870: aws_mqtt5_client_options_storage reconnect jitter mode set to 0
[DEBUG] [2024-06-19T05:17:44Z] [0000ffffbef7c040] [mqtt5-general] - id=0x333b7870: mqtt5_client_options_storage reconnect delay min set to 1000 ms, max set to 120000 ms
[DEBUG] [2024-06-19T05:17:44Z] [0000ffffbef7c040] [mqtt5-general] - id=0x333b7870: aws_mqtt5_client_options_storage minimum necessary connection time in order to reset the reconnect delay set to 30000 ms
[DEBUG] [2024-06-19T05:17:44Z] [0000ffffbef7c040] [mqtt5-general] - id=0x333b7870: aws_mqtt5_client_options_storage ping timeout interval set to 30000 ms
[DEBUG] [2024-06-19T05:17:44Z] [0000ffffbef7c040] [mqtt5-general] - id=0x333b7870: aws_mqtt5_client_options_storage connack timeout interval set to 20000 ms
[DEBUG] [2024-06-19T05:17:44Z] [0000ffffbef7c040] [mqtt5-general] - id=0x333b7870: aws_mqtt5_client_options_storage connect options:
[DEBUG] [2024-06-19T05:17:44Z] [0000ffffbef7c040] [mqtt5-general] - id=0x333b7a18: aws_mqtt5_packet_connect_view keep alive interval set to 240
[DEBUG] [2024-06-19T05:17:44Z] [0000ffffbef7c040] [mqtt5-general] - id=0x333b7a18: aws_mqtt5_packet_connect_view client id set to ""
[DEBUG] [2024-06-19T05:17:44Z] [0000ffffbef7c040] [mqtt5-general] - id=0x333b7a18: aws_mqtt5_packet_connect_view username set
[DEBUG] [2024-06-19T05:17:44Z] [0000ffffbef7c040] [mqtt5-general] - id=0x333b7a18: aws_mqtt5_packet_connect_view clean start set to 0
[DEBUG] [2024-06-19T05:17:44Z] [0000ffffbef7c040] [mqtt5-general] - id=0x333b7a18: aws_mqtt5_packet_connect_view set will to ((nil))
[DEBUG] [2024-06-19T05:17:44Z] [0000ffffbef7c040] [mqtt5-general] - id=0x333b7870: aws_mqtt5_client_options_storage lifecycle event handler user data set to (0x332d81c0)
[TRACE] [2024-06-19T05:17:44Z] [0000ffffbef7c040] [event-loop] - id=0x331e35b0: Scheduling task 0x333bd7f0 cross-thread for timestamp 0
[TRACE] [2024-06-19T05:17:44Z] [0000ffffbef7c040] [event-loop] - id=0x331e35b0: Waking up event-loop thread
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [event-loop] - id=0x331e35b0: wake up with 1 events to process.
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [event-loop] - id=0x331e35b0: activity on fd 33, invoking handler.
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [event-loop] - id=0x331e35b0: notified of cross-thread tasks to schedule
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [event-loop] - id=0x331e35b0: processing cross-thread tasks
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [event-loop] - id=0x331e35b0: task 0x333bd7f0 pulled to event-loop, scheduling now.
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [task-scheduler] - id=0x333bd7f0: Scheduling ChangeStateTask task for immediate execution
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [event-loop] - id=0x331e35b0: running scheduled tasks.
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [task-scheduler] - id=0x333bd7f0: Running ChangeStateTask task with <Running> status
[INFO] [2024-06-19T05:17:44Z] [0000fffa956cf040] [mqtt5-client] - id=0x333b5c10: changing desired client state from STOPPED to CONNECTED
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [event-loop] - id=0x331e35b0: scheduling task 0x333b5c40 in-thread for timestamp 11638208411299
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [task-scheduler] - id=0x333b5c40: Scheduling Mqtt5Service task for future execution at time 11638208411299
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [mqtt5-client] - id=0x333b5c10: scheduled service task for time 11638208411299
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [event-loop] - id=0x331e35b0: detected more scheduled tasks with the next occurring at 0, using timeout of 0.
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [event-loop] - id=0x331e35b0: waiting for a maximum of 0 ms
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [event-loop] - id=0x331e35b0: wake up with 0 events to process.
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [event-loop] - id=0x331e35b0: running scheduled tasks.
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [task-scheduler] - id=0x333b5c40: Running Mqtt5Service task with <Running> status
[DEBUG] [2024-06-19T05:17:44Z] [0000fffa956cf040] [mqtt5-client] - id=0x333b5c10: switching current state from STOPPED to CONNECTING
[INFO] [2024-06-19T05:17:44Z] [0000fffa956cf040] [mqtt5-client] - id=0x333b5c10: emitting connecting lifecycle event
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [channel-bootstrap] - id=0x331e5660: attempting to initialize a new client channel to <hidden-endpoint>.iot.eu-north-1.amazonaws.com:8883
[DEBUG] [2024-06-19T05:17:44Z] [0000fffa956cf040] [channel-bootstrap] - id=0x331e5660: acquiring bootstrap reference
[DEBUG] [2024-06-19T05:17:44Z] [0000fffa956cf040] [dns] - id=0x331fdf20: Host resolution requested for <hidden-endpoint>.iot.eu-north-1.amazonaws.com
[DEBUG] [2024-06-19T05:17:44Z] [0000fffa956cf040] [dns] - id=0x331fdf20: No cached entries found for <hidden-endpoint>.iot.eu-north-1.amazonaws.com starting new resolver thread.
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [event-loop] - id=0x331e35b0: no more scheduled tasks using default timeout.
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [event-loop] - id=0x331e35b0: waiting for a maximum of 100000 ms
[DEBUG] [2024-06-19T05:17:44Z] [0000fffa94ebf040] [dns] - static: resolving host <hidden-endpoint>.iot.eu-north-1.amazonaws.com
Attempting connect to AWS IoT
[DEBUG] [2024-06-19T05:17:44Z] [0000fffa94ebf040] [dns] - static: resolved record: <hidden-ip-1>
[DEBUG] [2024-06-19T05:17:44Z] [0000fffa94ebf040] [dns] - static: resolved record: <hidden-ip-2>
[DEBUG] [2024-06-19T05:17:44Z] [0000fffa94ebf040] [dns] - static: resolved record: <hidden-ip-3>
[DEBUG] [2024-06-19T05:17:44Z] [0000fffa94ebf040] [dns] - static: resolved record: <hidden-ip-4>
[DEBUG] [2024-06-19T05:17:44Z] [0000fffa94ebf040] [dns] - static: resolved record: <hidden-ip-5>
[DEBUG] [2024-06-19T05:17:44Z] [0000fffa94ebf040] [dns] - static: resolved record: <hidden-ip-6>
[DEBUG] [2024-06-19T05:17:44Z] [0000fffa94ebf040] [dns] - static, resolving host <hidden-endpoint>.iot.eu-north-1.amazonaws.com successful, returned 6 addresses
[DEBUG] [2024-06-19T05:17:44Z] [0000fffa94ebf040] [dns] - static: new address resolved <hidden-ip-1> for host <hidden-endpoint>.iot.eu-north-1.amazonaws.com caching
[DEBUG] [2024-06-19T05:17:44Z] [0000fffa94ebf040] [dns] - static: new address resolved <hidden-ip-2> for host <hidden-endpoint>.iot.eu-north-1.amazonaws.com caching
[DEBUG] [2024-06-19T05:17:44Z] [0000fffa94ebf040] [dns] - static: new address resolved <hidden-ip-3> for host <hidden-endpoint>.iot.eu-north-1.amazonaws.com caching
[DEBUG] [2024-06-19T05:17:44Z] [0000fffa94ebf040] [dns] - static: new address resolved <hidden-ip-4> for host <hidden-endpoint>.iot.eu-north-1.amazonaws.com caching
[DEBUG] [2024-06-19T05:17:44Z] [0000fffa94ebf040] [dns] - static: new address resolved <hidden-ip-5> for host <hidden-endpoint>.iot.eu-north-1.amazonaws.com caching
[DEBUG] [2024-06-19T05:17:44Z] [0000fffa94ebf040] [dns] - static: new address resolved <hidden-ip-6> for host <hidden-endpoint>.iot.eu-north-1.amazonaws.com caching
[TRACE] [2024-06-19T05:17:44Z] [0000fffa94ebf040] [dns] - static: remaining record count for host 3
[TRACE] [2024-06-19T05:17:44Z] [0000fffa94ebf040] [dns] - static: remaining record count for host 3
[TRACE] [2024-06-19T05:17:44Z] [0000fffa94ebf040] [dns] - static: vending address <hidden-ip-4> for host <hidden-endpoint>.iot.eu-north-1.amazonaws.com to caller
[TRACE] [2024-06-19T05:17:44Z] [0000fffa94ebf040] [dns] - static: vending address <hidden-ip-1> for host <hidden-endpoint>.iot.eu-north-1.amazonaws.com to caller
[DEBUG] [2024-06-19T05:17:44Z] [0000fffa94ebf040] [dns] - static, invoking resolution callback for host <hidden-endpoint>.iot.eu-north-1.amazonaws.com with 2 addresses
[TRACE] [2024-06-19T05:17:44Z] [0000fffa94ebf040] [channel-bootstrap] - id=0x331e5660: dns resolution completed. Kicking off connections on 2 addresses. First one back wins.
[TRACE] [2024-06-19T05:17:44Z] [0000fffa94ebf040] [channel-bootstrap] - acquiring client connection args, args=0xfff2f8001e40
[TRACE] [2024-06-19T05:17:44Z] [0000fffa94ebf040] [channel-bootstrap] - acquiring client connection args, args=0xfff2f8001e40
[TRACE] [2024-06-19T05:17:44Z] [0000fffa94ebf040] [event-loop] - id=0x331e35b0: Scheduling task 0xfff2fc004f50 cross-thread for timestamp 0
[TRACE] [2024-06-19T05:17:44Z] [0000fffa94ebf040] [event-loop] - id=0x331e35b0: Waking up event-loop thread
[TRACE] [2024-06-19T05:17:44Z] [0000fffa94ebf040] [event-loop] - id=0x331e35b0: Scheduling task 0xfff2fc005100 cross-thread for timestamp 0
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [event-loop] - id=0x331e35b0: wake up with 1 events to process.
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [event-loop] - id=0x331e35b0: activity on fd 33, invoking handler.
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [event-loop] - id=0x331e35b0: notified of cross-thread tasks to schedule
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [event-loop] - id=0x331e35b0: processing cross-thread tasks
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [event-loop] - id=0x331e35b0: task 0xfff2fc004f50 pulled to event-loop, scheduling now.
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [task-scheduler] - id=0xfff2fc004f50: Scheduling attempt_connection task for immediate execution
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [event-loop] - id=0x331e35b0: task 0xfff2fc005100 pulled to event-loop, scheduling now.
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [task-scheduler] - id=0xfff2fc005100: Scheduling attempt_connection task for immediate execution
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [event-loop] - id=0x331e35b0: running scheduled tasks.
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [task-scheduler] - id=0xfff2fc004f50: Running attempt_connection task with <Running> status
[DEBUG] [2024-06-19T05:17:44Z] [0000fffa956cf040] [socket] - id=0xfff2f8003d10 fd=35: initializing with domain 1 and type 0
[DEBUG] [2024-06-19T05:17:44Z] [0000fffa956cf040] [socket] - id=0xfff2f8003d10 fd=35: setting socket options to: keep-alive 0, keep idle 0, keep-alive interval 0, keep-alive probe count 0.
[DEBUG] [2024-06-19T05:17:44Z] [0000fffa956cf040] [socket] - id=0xfff2f8003d10 fd=35: beginning connect.
[DEBUG] [2024-06-19T05:17:44Z] [0000fffa956cf040] [socket] - id=0xfff2f8003d10 fd=35: connecting to endpoint <hidden-ip-4>:8883.
[DEBUG] [2024-06-19T05:17:44Z] [0000fffa956cf040] [socket] - id=0xfff2f8003d10 fd=35: connect failed with error code 101.
[INFO] [2024-06-19T05:17:44Z] [0000fffa956cf040] [dns] - id=0x331fdf20: recording failure for record <hidden-ip-4> for <hidden-endpoint>.iot.eu-north-1.amazonaws.com, moving to bad list
[DEBUG] [2024-06-19T05:17:44Z] [0000fffa956cf040] [dns] - static: purging address <hidden-ip-4> for host <hidden-endpoint>.iot.eu-north-1.amazonaws.com from the cache due to cache eviction or shutdown
[DEBUG] [2024-06-19T05:17:44Z] [0000fffa956cf040] [socket] - id=0xfff2f8003d10 fd=35: is still open, closing...
[DEBUG] [2024-06-19T05:17:44Z] [0000fffa956cf040] [socket] - id=0xfff2f8003d10 fd=35: closing
[DEBUG] [2024-06-19T05:17:44Z] [0000fffa956cf040] [channel-bootstrap] - id=0x331e5660: Socket connect attempt 1/2 failed with error 1049. More attempts ongoing...
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [channel-bootstrap] - releasing client connection args, args=0xfff2f8001e40
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [task-scheduler] - id=0xfff2fc005100: Running attempt_connection task with <Running> status
[DEBUG] [2024-06-19T05:17:44Z] [0000fffa956cf040] [socket] - id=0xfff2f8003d10 fd=35: initializing with domain 0 and type 0
[DEBUG] [2024-06-19T05:17:44Z] [0000fffa956cf040] [socket] - id=0xfff2f8003d10 fd=35: setting socket options to: keep-alive 0, keep idle 0, keep-alive interval 0, keep-alive probe count 0.
[DEBUG] [2024-06-19T05:17:44Z] [0000fffa956cf040] [socket] - id=0xfff2f8003d10 fd=35: beginning connect.
[DEBUG] [2024-06-19T05:17:44Z] [0000fffa956cf040] [socket] - id=0xfff2f8003d10 fd=35: connecting to endpoint <hidden-ip-1>:8883.
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [socket] - id=0xfff2f8003d10 fd=35: connection pending waiting on event-loop notification or timeout.
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [event-loop] - id=0x331e35b0: subscribing to events on fd 35
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [socket] - id=0xfff2f8003d10 fd=35: scheduling timeout task for 11648260575257.
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [event-loop] - id=0x331e35b0: scheduling task 0xfff2f8004900 in-thread for timestamp 11648260575257
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [task-scheduler] - id=0xfff2f8004900: Scheduling (null) task for future execution at time 11648260575257
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [event-loop] - id=0x331e35b0: detected more scheduled tasks with the next occurring at 9999996541, using timeout of 9999.
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [event-loop] - id=0x331e35b0: waiting for a maximum of 9999 ms
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [event-loop] - id=0x331e35b0: wake up with 1 events to process.
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [event-loop] - id=0x331e35b0: activity on fd 35, invoking handler.
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [socket] - fd=35: connection activity handler triggered
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [socket] - id=0xfff2f8003d10 fd=35: has not timed out yet proceeding with connection.
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [event-loop] - id=0x331e35b0: un-subscribing from events on fd 35
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [event-loop] - id=0x331e35b0: scheduling task 0xfff2f8004aa0 in-thread for timestamp 0
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [task-scheduler] - id=0xfff2f8004aa0: Scheduling epoll_event_loop_unsubscribe_cleanup task for immediate execution
[INFO] [2024-06-19T05:17:44Z] [0000fffa956cf040] [socket] - id=0xfff2f8003d10 fd=35: connection success
[DEBUG] [2024-06-19T05:17:44Z] [0000fffa956cf040] [socket] - id=0xfff2f8003d10 fd=35: assigning to event loop 0x331e35b0
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [event-loop] - id=0x331e35b0: subscribing to events on fd 35
[DEBUG] [2024-06-19T05:17:44Z] [0000fffa956cf040] [channel-bootstrap] - id=0x331e5660: client connection on socket 0xfff2f8003d10 completed with error 0.
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [channel-bootstrap] - id=0x331e5660: Successful connection, creating a new channel using socket 0xfff2f8003d10.
[DEBUG] [2024-06-19T05:17:44Z] [0000fffa956cf040] [channel] - id=0xfff2f80050e0: Beginning creation and setup of new channel.
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [event-loop] - id=0x331e35b0: scheduling task 0xfff2f8004dd0 in-thread for timestamp 0
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [task-scheduler] - id=0xfff2f8004dd0: Scheduling on_channel_setup_complete task for immediate execution
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [event-loop] - id=0x331e35b0: running scheduled tasks.
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [task-scheduler] - id=0xfff2f8004aa0: Running epoll_event_loop_unsubscribe_cleanup task with <Running> status
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [task-scheduler] - id=0xfff2f8004dd0: Running on_channel_setup_complete task with <Running> status
[DEBUG] [2024-06-19T05:17:44Z] [0000fffa956cf040] [channel] - id=0xfff2f80050e0: setup complete, notifying caller.
[DEBUG] [2024-06-19T05:17:44Z] [0000fffa956cf040] [channel] - id=0xfff2f80050e0: no message pool is currently stored in the event-loop local storage, adding 0xfff2f8004e20 with max message size 16384, message count 4, with 4 small blocks of 128 bytes.
[DEBUG] [2024-06-19T05:17:44Z] [0000fffa956cf040] [channel-bootstrap] - id=0x331e5660: channel 0xfff2f80050e0 setup succeeded: bootstrapping.
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [channel] - id=0xfff2f80050e0: creating new slot 0xfff2f8015850.
[DEBUG] [2024-06-19T05:17:44Z] [0000fffa956cf040] [socket-handler] - id=0xfff2f8004c10: Socket handler created with max_read_size of 16384
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [socket] -  id=0xfff2f8003d10 fd=35: subscribing to readable events
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [channel-bootstrap] - id=0x331e5660: Setting up socket handler on channel 0xfff2f80050e0 with handler 0xfff2f8004c10 on slot 0xfff2f8015850.
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [channel] - id=0xfff2f80050e0: creating new slot 0xfff2f80159e0.
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [channel-bootstrap] - id=0x331e5660: Setting up client TLS on channel 0xfff2f80050e0 with handler 0xfff2f8015a30 on slot 0xfff2f80159e0
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [tls-handler] - id=0xfff2f8015a30: Kicking off TLS negotiation.
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [channel] - id=0xfff2f80050e0: scheduling task with wrapper task id 0xfff2f8015a60.
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [event-loop] - id=0x331e35b0: scheduling task 0xfff2f8015a60 in-thread for timestamp 11648312092716
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [task-scheduler] - id=0xfff2f8015a60: Scheduling tls_timeout task for future execution at time 11648312092716
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [channel] - id=0xfff2f80050e0: acquired message 0xfff2f8011780 of capacity 226 from pool 0xfff2f8004e20. Requested size was 226
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [channel] - id=0xfff2f80050e0: sending write message of size 226, from slot 0xfff2f80159e0 to slot 0xfff2f8015850 with handler 0xfff2f8004c10.
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [socket-handler] - id=0xfff2f8004c10: writing message of size 226
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [socket] - id=0xfff2f8003d10 fd=35: processing write requests, called from aws_socket_write
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [socket] - id=0xfff2f8003d10 fd=35: dequeued write request of size 226, remaining to write 226
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [socket] - id=0xfff2f8003d10 fd=35: send written size 226
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [socket] - id=0xfff2f8003d10 fd=35: remaining write request to write 0
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [socket] - id=0xfff2f8003d10 fd=35: write request completed
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [event-loop] - id=0x331e35b0: scheduling task 0xfff2f8004740 in-thread for timestamp 0
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [task-scheduler] - id=0xfff2f8004740: Scheduling socket_written_task task for immediate execution
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [event-loop] - id=0x331e35b0: detected more scheduled tasks with the next occurring at 0, using timeout of 0.
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [event-loop] - id=0x331e35b0: waiting for a maximum of 0 ms
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [event-loop] - id=0x331e35b0: wake up with 1 events to process.
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [event-loop] - id=0x331e35b0: activity on fd 35, invoking handler.
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [socket] - id=0xfff2f8003d10 fd=35: is writable
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [socket] - id=0xfff2f8003d10 fd=35: processing write requests, invoked by the event-loop
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [event-loop] - id=0x331e35b0: running scheduled tasks.
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [task-scheduler] - id=0xfff2f8004740: Running socket_written_task task with <Running> status
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [socket-handler] - static: write of size 226, completed on channel 0xfff2f80050e0
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [event-loop] - id=0x331e35b0: detected more scheduled tasks with the next occurring at 9948015375, using timeout of 9948.
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [event-loop] - id=0x331e35b0: waiting for a maximum of 9948 ms
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [event-loop] - id=0x331e35b0: wake up with 1 events to process.
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [event-loop] - id=0x331e35b0: activity on fd 35, invoking handler.
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [socket] - id=0xfff2f8003d10 fd=35: is readable
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [socket-handler] - id=0xfff2f8004c10: socket on-readable with error code 0(AWS_ERROR_SUCCESS)
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [socket-handler] - id=0xfff2f8004c10: invoking read. Downstream window 18446744073709551615, max_to_read 16384
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [channel] - id=0xfff2f80050e0: acquired message 0xfff2f8011780 of capacity 16384 from pool 0xfff2f8004e20. Requested size was 16384
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [socket] - id=0xfff2f8003d10 fd=35: read of 7
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [socket-handler] - id=0xfff2f8004c10: read 7 from socket
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [channel] - id=0xfff2f80050e0: sending read message of size 7, from slot 0xfff2f8015850 to slot 0xfff2f80159e0 with handler 0xfff2f8015a30.
[WARN] [2024-06-19T05:17:44Z] [0000fffa956cf040] [tls-handler] - id=0xfff2f8015a30: negotiation failed with error TLS alert received (Error encountered in /aws-crt-nodejs/crt/s2n/tls/s2n_alerts.c:245)
[DEBUG] [2024-06-19T05:17:44Z] [0000fffa956cf040] [tls-handler] - id=0xfff2f8015a30: Alert code 70
[DEBUG] [2024-06-19T05:17:44Z] [0000fffa956cf040] [channel-bootstrap] - id=0x331e5660: tls negotiation result 1029 on channel 0xfff2f80050e0
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [channel] - id=0xfff2f80050e0: channel shutdown task is scheduled
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [channel] - id=0xfff2f80050e0: scheduling task with wrapper task id 0xfff2f80052e8.
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [event-loop] - id=0x331e35b0: scheduling task 0xfff2f80052e8 in-thread for timestamp 0
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [task-scheduler] - id=0xfff2f80052e8: Scheduling channel_shutdown task for immediate execution
[DEBUG] [2024-06-19T05:17:44Z] [0000fffa956cf040] [channel] - id=0xfff2f80050e0: Channel shutdown is already pending, not scheduling another.
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [channel] - id=0xfff2f80050e0: acquired message 0xfff2f8011780 of capacity 16377 from pool 0xfff2f8004e20. Requested size was 16377
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [socket] - id=0xfff2f8003d10 fd=35: read of 0
[INFO] [2024-06-19T05:17:44Z] [0000fffa956cf040] [socket] - id=0xfff2f8003d10 fd=35: zero read, socket is closed
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [socket-handler] - id=0xfff2f8004c10: total read on this tick 7
[DEBUG] [2024-06-19T05:17:44Z] [0000fffa956cf040] [channel] - id=0xfff2f80050e0: Channel shutdown is already pending, not scheduling another.
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [socket] - id=0xfff2f8003d10 fd=35: is writable
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [socket] - id=0xfff2f8003d10 fd=35: processing write requests, invoked by the event-loop
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [socket] - id=0xfff2f8003d10 fd=35: closed remotely
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [socket-handler] - id=0xfff2f8004c10: socket on-readable with error code 1051(AWS_IO_SOCKET_CLOSED)
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [socket-handler] - id=0xfff2f8004c10: invoking read. Downstream window 18446744073709551615, max_to_read 16384
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [channel] - id=0xfff2f80050e0: acquired message 0xfff2f8011780 of capacity 16384 from pool 0xfff2f8004e20. Requested size was 16384
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [socket] - id=0xfff2f8003d10 fd=35: read of 0
[INFO] [2024-06-19T05:17:44Z] [0000fffa956cf040] [socket] - id=0xfff2f8003d10 fd=35: zero read, socket is closed
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [socket-handler] - id=0xfff2f8004c10: total read on this tick 0
[DEBUG] [2024-06-19T05:17:44Z] [0000fffa956cf040] [channel] - id=0xfff2f80050e0: Channel shutdown is already pending, not scheduling another.
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [event-loop] - id=0x331e35b0: running scheduled tasks.
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [task-scheduler] - id=0xfff2f80052e8: Running channel_shutdown task with <Running> status
[DEBUG] [2024-06-19T05:17:44Z] [0000fffa956cf040] [channel] - id=0xfff2f80050e0: beginning shutdown process
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [channel] - id=0xfff2f80050e0: shutting down slot 0xfff2f8015850 (the first one) in the read direction
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [channel] - id=0xfff2f80050e0: shutting down slot 0xfff2f8015850, with handler 0xfff2f8004c10 in read direction with error code 1029
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [socket-handler] - id=0xfff2f8004c10: shutting down read direction with error_code 1029
[DEBUG] [2024-06-19T05:17:44Z] [0000fffa956cf040] [channel] - id=0xfff2f80050e0: handler 0xfff2f8004c10 shutdown in read dir completed.
[DEBUG] [2024-06-19T05:17:44Z] [0000fffa956cf040] [tls-handler] - id=0xfff2f8015a30: Shutting down read direction with error code 1029
[DEBUG] [2024-06-19T05:17:44Z] [0000fffa956cf040] [channel] - id=0xfff2f80050e0: handler 0xfff2f8015a30 shutdown in read dir completed.
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [event-loop] - id=0x331e35b0: scheduling task 0xfff2f8005108 in-thread for timestamp 0
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [task-scheduler] - id=0xfff2f8005108: Scheduling (null) task for immediate execution
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [event-loop] - id=0x331e35b0: detected more scheduled tasks with the next occurring at 0, using timeout of 0.
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [event-loop] - id=0x331e35b0: waiting for a maximum of 0 ms
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [event-loop] - id=0x331e35b0: wake up with 0 events to process.
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [event-loop] - id=0x331e35b0: running scheduled tasks.
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [task-scheduler] - id=0xfff2f8005108: Running (null) task with <Running> status
[DEBUG] [2024-06-19T05:17:44Z] [0000fffa956cf040] [tls-handler] - id=0xfff2f8015a30: Scheduling delayed write direction shutdown
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [channel] - id=0xfff2f80050e0: scheduling task with wrapper task id 0xfff2f8015c00.
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [event-loop] - id=0x331e35b0: scheduling task 0xfff2f8015c00 in-thread for timestamp 11638363867341
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [task-scheduler] - id=0xfff2f8015c00: Scheduling s2n_delayed_shutdown task for future execution at time 11638363867341
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [event-loop] - id=0x331e35b0: detected more scheduled tasks with the next occurring at 0, using timeout of 0.
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [event-loop] - id=0x331e35b0: waiting for a maximum of 0 ms
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [event-loop] - id=0x331e35b0: wake up with 0 events to process.
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [event-loop] - id=0x331e35b0: running scheduled tasks.
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [task-scheduler] - id=0xfff2f8015c00: Running s2n_delayed_shutdown task with <Running> status
[DEBUG] [2024-06-19T05:17:44Z] [0000fffa956cf040] [tls-handler] - id=0xfff2f8015a30: Delayed shut down in write direction
[DEBUG] [2024-06-19T05:17:44Z] [0000fffa956cf040] [channel] - id=0xfff2f80050e0: handler 0xfff2f8015a30 shutdown in write dir completed.
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [socket-handler] - id=0xfff2f8004c10: shutting down write direction with error_code 1029
[DEBUG] [2024-06-19T05:17:44Z] [0000fffa956cf040] [socket] - id=0xfff2f8003d10 fd=35: closing
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [event-loop] - id=0x331e35b0: un-subscribing from events on fd 35
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [event-loop] - id=0x331e35b0: scheduling task 0xfff2f8004d60 in-thread for timestamp 0
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [task-scheduler] - id=0xfff2f8004d60: Scheduling epoll_event_loop_unsubscribe_cleanup task for immediate execution
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [channel] - id=0xfff2f80050e0: scheduling task with wrapper task id 0xfff2f8004cb0.
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [event-loop] - id=0x331e35b0: scheduling task 0xfff2f8004cb0 in-thread for timestamp 0
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [task-scheduler] - id=0xfff2f8004cb0: Scheduling socket_handler_close task for immediate execution
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [event-loop] - id=0x331e35b0: detected more scheduled tasks with the next occurring at 0, using timeout of 0.
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [event-loop] - id=0x331e35b0: waiting for a maximum of 0 ms
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [event-loop] - id=0x331e35b0: wake up with 0 events to process.
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [event-loop] - id=0x331e35b0: running scheduled tasks.
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [task-scheduler] - id=0xfff2f8004d60: Running epoll_event_loop_unsubscribe_cleanup task with <Running> status
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [task-scheduler] - id=0xfff2f8004cb0: Running socket_handler_close task with <Running> status
[DEBUG] [2024-06-19T05:17:44Z] [0000fffa956cf040] [channel] - id=0xfff2f80050e0: handler 0xfff2f8004c10 shutdown in write dir completed.
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [event-loop] - id=0x331e35b0: scheduling task 0xfff2f8005108 in-thread for timestamp 0
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [task-scheduler] - id=0xfff2f8005108: Scheduling (null) task for immediate execution
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [event-loop] - id=0x331e35b0: detected more scheduled tasks with the next occurring at 0, using timeout of 0.
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [event-loop] - id=0x331e35b0: waiting for a maximum of 0 ms
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [event-loop] - id=0x331e35b0: wake up with 0 events to process.
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [event-loop] - id=0x331e35b0: running scheduled tasks.
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [task-scheduler] - id=0xfff2f8005108: Running (null) task with <Running> status
[DEBUG] [2024-06-19T05:17:44Z] [0000fffa956cf040] [channel] - id=0xfff2f80050e0: during shutdown, canceling task 0xfff2f8015a60
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [event-loop] - id=0x331e35b0: cancelling task 0xfff2f8015a60
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [task-scheduler] - id=0xfff2f8015a60: Running tls_timeout task with <Canceled> status
[DEBUG] [2024-06-19T05:17:44Z] [0000fffa956cf040] [channel-bootstrap] - id=0x331e5660: channel 0xfff2f80050e0 shutdown with error 1029.
[INFO] [2024-06-19T05:17:44Z] [0000fffa956cf040] [mqtt5-client] - id=0x333b5c10: emitting connection failure lifecycle event with error code 1029(aws-c-io: AWS_IO_TLS_ERROR_NEGOTIATION_FAILURE, TLS (SSL) negotiation failed)
[INFO] [2024-06-19T05:17:44Z] [0000fffa956cf040] [mqtt5-client] - id=0x333b5c10: channel tore down with error code 1029(aws-c-io: AWS_IO_TLS_ERROR_NEGOTIATION_FAILURE, TLS (SSL) negotiation failed)
[DEBUG] [2024-06-19T05:17:44Z] [0000fffa956cf040] [mqtt5-client] - id=0x333b5c10: switching current state from CONNECTING to PENDING_RECONNECT
[DEBUG] [2024-06-19T05:17:44Z] [0000fffa956cf040] [mqtt5-client] - id=0x333b5c10: next connection attempt in 266 milliseconds
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [event-loop] - id=0x331e35b0: scheduling task 0x333b5c40 in-thread for timestamp 11638630195924
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [task-scheduler] - id=0x333b5c40: Scheduling Mqtt5Service task for future execution at time 11638630195924
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [mqtt5-client] - id=0x333b5c10: scheduled service task for time 11638630195924
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [channel-bootstrap] - releasing client connection args, args=0xfff2f8001e40
[DEBUG] [2024-06-19T05:17:44Z] [0000fffa956cf040] [channel] - id=0xfff2f80050e0: destroying channel.
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [channel-bootstrap] - releasing client connection args, args=0xfff2f8001e40
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [channel-bootstrap] - destroying client connection args, args=0xfff2f8001e40
[DEBUG] [2024-06-19T05:17:44Z] [0000fffa956cf040] [channel-bootstrap] - id=0x331e5660: releasing bootstrap reference
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [event-loop] - id=0x331e35b0: detected more scheduled tasks with the next occurring at 265911542, using timeout of 265.
[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [event-loop] - id=0x331e35b0: waiting for a maximum of 265 ms
{
  error: CrtError: aws-c-io: AWS_IO_TLS_ERROR_NEGOTIATION_FAILURE, TLS (SSL) negotiation failed
      at <anonymous> (/shared/node_modules/aws-crt/lib/native/mqtt5.ts:292:143) {
    error: 1029,
    error_code: 1029,
    error_name: 'AWS_IO_TLS_ERROR_NEGOTIATION_FAILURE'
  }
}
Connection failure event: Error: aws-c-io: AWS_IO_TLS_ERROR_NEGOTIATION_FAILURE, TLS (SSL) negotiation failed

@github-actions github-actions bot removed the response-requested Waiting on additional info and feedback. Will move to 'closing-soon' in 7 days. label Jun 19, 2024
@bretambrose
Copy link
Contributor

[TRACE] [2024-06-19T05:17:44Z] [0000fffa956cf040] [channel] - id=0xfff2f80050e0: sending read message of size 7, from slot 0xfff2f8015850 to slot 0xfff2f80159e0 with handler 0xfff2f8015a30.
[WARN] [2024-06-19T05:17:44Z] [0000fffa956cf040] [tls-handler] - id=0xfff2f8015a30: negotiation failed with error TLS alert received (Error encountered in /aws-crt-nodejs/crt/s2n/tls/s2n_alerts.c:245)
[DEBUG] [2024-06-19T05:17:44Z] [0000fffa956cf040] [tls-handler] - id=0xfff2f8015a30: Alert code 70

The server is sending an alert in response to the initial client hello, and 70 is the protocol_version alert.

Can you attach a wireshark pcap of the client hello packet?

@twiking
Copy link
Author

twiking commented Jun 19, 2024

I have configured IoTSecurityPolicy_TLS13_1_3_2022_10 as security policy.

[email protected]: The protocol is TLSv1.3 for the Client Hello packet. Correct!
[email protected]: The protocol is TLSv1.2 for the Client Hello packet. Incorrect!

If I change the security policy to TLS 1.2, it of course works.
So incorrect TLS version seems to be chosen in [email protected].

Do you want any other details from the Client Hello packet?

@bretambrose
Copy link
Contributor

bretambrose commented Jun 19, 2024

I've created an internal ticket linked back to this issue. Oncall will dig in further when they have a chance.

Just to verify:

The issue only occurs when using a security policy that is TLS1.3 only.
With such a policy, the SDK was sending a client hello that included 1.3 as an option when the CRT version was 1.21.2
With CRT 1.21.3, the client hello does not include 1.3 as an option, leading to an empty set of possibilities on the server.

@bretambrose
Copy link
Contributor

We've reproed this internally. The client hello sent out is dramatically different between 1.21.2 and 1.21.3 but I don't know why yet. In particular, in v1.21.3:

  1. the 3 principal 1.3-only IoT policy cipher suites are missing (TLS_AES_128_GCM_SHA256, TLS_AWS_256_GCM_SHA256, and TLS_CHACHA20_POLY1305_SHA256)
  2. the supported_versions extension is not present
  3. the key_share extension is not present (don't know enough about TLS to know if this is actually a problem)
  4. the signature algorithms extension contains fewer options (may not be a problem)

Given that the TLS13 only policy only supports those three missing cipher suites, it appears that (1) is the fundamental problem: https://docs.aws.amazon.com/iot/latest/developerguide/transport-security.html#tls-policy-table

I am going to make a release of the SDK that pins the CRT to exactly 1.21.2 until we figure out and correct the root cause.

@xiazhvera
Copy link
Contributor

We have released the fix for TLS13. Please checkout the following releases.
aws-crt-nodejs: https://github.com/awslabs/aws-crt-nodejs/releases/tag/v1.21.8
aws-iot-device-sdk-js-v2: https://github.com/aws/aws-iot-device-sdk-js-v2/releases/tag/v1.20.1

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug This issue is a bug. p2 This is a standard priority issue
Projects
None yet
Development

No branches or pull requests

4 participants