Skip to content

TLS negotiation error #538

Open
Open
@k-hay413

Description

@k-hay413

Describe the bug

When trying to connect to MQTT, TLS fails with SECURITY_STATUS -2146893816 on tls-handler and raise error code 1029.

Here are the relevant logs:

[TRACE] [2024-12-20T04:21:24Z] [00002848] [socket-handler] - id=0000025E35C6FE20: writing message of size 251
[TRACE] [2024-12-20T04:21:24Z] [00002848] [socket] - id=0000025E3FCD1730 handle=0000000000000250: queueing write of 251 bytes
[TRACE] [2024-12-20T04:21:24Z] [00002848] [event-loop] - id=0000025E3FC820A0: detected more scheduled tasks with the next occurring at 87775958323168, using timeout of 9871.
[TRACE] [2024-12-20T04:21:24Z] [00002848] [event-loop] - id=0000025E3FC820A0: waiting for a maximum of 9871 ms
[TRACE] [2024-12-20T04:21:24Z] [00002848] [event-loop] - id=0000025E3FC820A0: wake up with 1 events to process.
[TRACE] [2024-12-20T04:21:24Z] [00002848] [event-loop] - id=0000025E3FC820A0: invoking handler.
[TRACE] [2024-12-20T04:21:24Z] [00002848] [socket] - id=0000025E3FCD1730 handle=0000000000000250: Write Completion callback triggered
[TRACE] [2024-12-20T04:21:24Z] [00002848] [socket] - id=0000025E3FCD1730 handle=0000000000000250: Write of size 251 completed
[TRACE] [2024-12-20T04:21:24Z] [00002848] [socket-handler] - static: write of size 251, completed on channel 0000025E35D02B10
[TRACE] [2024-12-20T04:21:24Z] [00002848] [event-loop] - id=0000025E3FC820A0: running scheduled tasks.
[TRACE] [2024-12-20T04:21:24Z] [00002848] [event-loop] - id=0000025E3FC820A0: detected more scheduled tasks with the next occurring at 87775958323168, using timeout of 9871.
[TRACE] [2024-12-20T04:21:24Z] [00002848] [event-loop] - id=0000025E3FC820A0: waiting for a maximum of 9871 ms
[TRACE] [2024-12-20T04:21:24Z] [00002848] [event-loop] - id=0000025E3FC820A0: wake up with 1 events to process.
[TRACE] [2024-12-20T04:21:24Z] [00002848] [event-loop] - id=0000025E3FC820A0: invoking handler.
[TRACE] [2024-12-20T04:21:24Z] [00002848] [socket] - id=0000025E3FCD1730 handle=0000000000000250: socket readable event triggered
[TRACE] [2024-12-20T04:21:24Z] [00002848] [socket-handler] - id=0000025E35C6FE20: socket on-readable with error code 0(AWS_ERROR_SUCCESS)
[TRACE] [2024-12-20T04:21:24Z] [00002848] [socket-handler] - id=0000025E35C6FE20: invoking read. Downstream window 18446744073709551615, max_to_read 16384
[TRACE] [2024-12-20T04:21:24Z] [00002848] [channel] - id=0000025E35D02B10: acquired message 0000025E3FE3A0A0 of capacity 16384 from pool 0000025E3FC1D240. Requested size was 16384
[TRACE] [2024-12-20T04:21:24Z] [00002848] [socket] - id=0000025E3FCD1730 handle=0000000000000250: reading from socket
[TRACE] [2024-12-20T04:21:24Z] [00002848] [socket] - id=0000025E3FCD1730 handle=0000000000000250: read 100 bytes from socket
[TRACE] [2024-12-20T04:21:24Z] [00002848] [socket-handler] - id=0000025E35C6FE20: read 100 from socket
[TRACE] [2024-12-20T04:21:24Z] [00002848] [channel] - id=0000025E35D02B10: sending read message of size 100, from slot 0000025E3FCF6BD0 to slot 0000025E3FED9F90 with handler 0000025E3FE3E140.
[TRACE] [2024-12-20T04:21:24Z] [00002848] [tls-handler] - id=0000025E3FE3E140: processing incoming message of size 100
[TRACE] [2024-12-20T04:21:24Z] [00002848] [tls-handler] - id=0000025E3FE3E140: running step 2 of client-side negotiation (cipher change, key exchange etc...)
[TRACE] [2024-12-20T04:21:24Z] [00002848] [channel] - id=0000025E35D02B10: acquired message 0000025E3FE3A0A0 of capacity 16284 from pool 0000025E3FC1D240. Requested size was 16284
[TRACE] [2024-12-20T04:21:24Z] [00002848] [socket] - id=0000025E3FCD1730 handle=0000000000000250: reading from socket
[TRACE] [2024-12-20T04:21:24Z] [00002848] [socket] - id=0000025E3FCD1730 handle=0000000000000250: read 1460 bytes from socket
[TRACE] [2024-12-20T04:21:24Z] [00002848] [socket-handler] - id=0000025E35C6FE20: read 1460 from socket
[TRACE] [2024-12-20T04:21:24Z] [00002848] [channel] - id=0000025E35D02B10: sending read message of size 1460, from slot 0000025E3FCF6BD0 to slot 0000025E3FED9F90 with handler 0000025E3FE3E140.
[TRACE] [2024-12-20T04:21:24Z] [00002848] [tls-handler] - id=0000025E3FE3E140: processing incoming message of size 1460
[TRACE] [2024-12-20T04:21:24Z] [00002848] [tls-handler] - id=0000025E3FE3E140: running step 2 of client-side negotiation (cipher change, key exchange etc...)
[TRACE] [2024-12-20T04:21:24Z] [00002848] [tls-handler] - id=0000025E3FE3E140: Incomplete buffer recieved. Incomplete size is 3562. Waiting for more data.
[TRACE] [2024-12-20T04:21:24Z] [00002848] [channel] - id=0000025E35D02B10: acquired message 0000025E3FE3A0A0 of capacity 14824 from pool 0000025E3FC1D240. Requested size was 14824
[TRACE] [2024-12-20T04:21:24Z] [00002848] [socket] - id=0000025E3FCD1730 handle=0000000000000250: reading from socket
[TRACE] [2024-12-20T04:21:24Z] [00002848] [socket] - id=0000025E3FCD1730 handle=0000000000000250: read would block, scheduling 0 byte read and returning
[TRACE] [2024-12-20T04:21:24Z] [00002848] [socket-handler] - id=0000025E35C6FE20: total read on this tick 1560
[TRACE] [2024-12-20T04:21:24Z] [00002848] [socket-handler] - id=0000025E35C6FE20: out of data to read on socket. Waiting on event-loop notification.
[TRACE] [2024-12-20T04:21:24Z] [00002848] [event-loop] - id=0000025E3FC820A0: running scheduled tasks.
[TRACE] [2024-12-20T04:21:24Z] [00002848] [event-loop] - id=0000025E3FC820A0: detected more scheduled tasks with the next occurring at 87775958323168, using timeout of 9787.
[TRACE] [2024-12-20T04:21:24Z] [00002848] [event-loop] - id=0000025E3FC820A0: waiting for a maximum of 9787 ms
[TRACE] [2024-12-20T04:21:24Z] [00002848] [event-loop] - id=0000025E3FC820A0: wake up with 1 events to process.
[TRACE] [2024-12-20T04:21:24Z] [00002848] [event-loop] - id=0000025E3FC820A0: invoking handler.
[TRACE] [2024-12-20T04:21:24Z] [00002848] [socket] - id=0000025E3FCD1730 handle=0000000000000250: socket readable event triggered
[TRACE] [2024-12-20T04:21:24Z] [00002848] [socket-handler] - id=0000025E35C6FE20: socket on-readable with error code 0(AWS_ERROR_SUCCESS)
[TRACE] [2024-12-20T04:21:24Z] [00002848] [socket-handler] - id=0000025E35C6FE20: invoking read. Downstream window 18446744073709551615, max_to_read 16384
[TRACE] [2024-12-20T04:21:24Z] [00002848] [channel] - id=0000025E35D02B10: acquired message 0000025E3FE3A0A0 of capacity 16384 from pool 0000025E3FC1D240. Requested size was 16384
[TRACE] [2024-12-20T04:21:24Z] [00002848] [socket] - id=0000025E3FCD1730 handle=0000000000000250: reading from socket
[TRACE] [2024-12-20T04:21:24Z] [00002848] [socket] - id=0000025E3FCD1730 handle=0000000000000250: read 1460 bytes from socket
[TRACE] [2024-12-20T04:21:24Z] [00002848] [socket-handler] - id=0000025E35C6FE20: read 1460 from socket
[TRACE] [2024-12-20T04:21:24Z] [00002848] [channel] - id=0000025E35D02B10: sending read message of size 1460, from slot 0000025E3FCF6BD0 to slot 0000025E3FED9F90 with handler 0000025E3FE3E140.
[TRACE] [2024-12-20T04:21:24Z] [00002848] [tls-handler] - id=0000025E3FE3E140: processing incoming message of size 1460
[TRACE] [2024-12-20T04:21:24Z] [00002848] [tls-handler] - id=0000025E3FE3E140: running step 2 of client-side negotiation (cipher change, key exchange etc...)
[TRACE] [2024-12-20T04:21:24Z] [00002848] [tls-handler] - id=0000025E3FE3E140: Incomplete buffer recieved. Incomplete size is 2102. Waiting for more data.
[TRACE] [2024-12-20T04:21:24Z] [00002848] [channel] - id=0000025E35D02B10: acquired message 0000025E3FE3A0A0 of capacity 14924 from pool 0000025E3FC1D240. Requested size was 14924
[TRACE] [2024-12-20T04:21:24Z] [00002848] [socket] - id=0000025E3FCD1730 handle=0000000000000250: reading from socket
[TRACE] [2024-12-20T04:21:24Z] [00002848] [socket] - id=0000025E3FCD1730 handle=0000000000000250: read 2486 bytes from socket
[TRACE] [2024-12-20T04:21:24Z] [00002848] [socket-handler] - id=0000025E35C6FE20: read 2486 from socket
[TRACE] [2024-12-20T04:21:24Z] [00002848] [channel] - id=0000025E35D02B10: sending read message of size 2486, from slot 0000025E3FCF6BD0 to slot 0000025E3FED9F90 with handler 0000025E3FE3E140.
[TRACE] [2024-12-20T04:21:24Z] [00002848] [tls-handler] - id=0000025E3FE3E140: processing incoming message of size 2486
[TRACE] [2024-12-20T04:21:24Z] [00002848] [tls-handler] - id=0000025E3FE3E140: running step 2 of client-side negotiation (cipher change, key exchange etc...)
[ERROR] [2024-12-20T04:21:25Z] [00002848] [tls-handler] - id=0000025E3FE3E140: Error during negotiation. SECURITY_STATUS is -2146893816
[DEBUG] [2024-12-20T04:21:25Z] [00002848] [channel-bootstrap] - id=0000025E35D34C60: tls negotiation result 1029 on channel 0000025E35D02B10
[TRACE] [2024-12-20T04:21:25Z] [00002848] [channel] - id=0000025E35D02B10: channel shutdown task is scheduled
[TRACE] [2024-12-20T04:21:25Z] [00002848] [channel] - id=0000025E35D02B10: scheduling task with wrapper task id 0000025E35D02CF0.
[TRACE] [2024-12-20T04:21:25Z] [00002848] [event-loop] - id=0000025E3FC820A0: scheduling task 0000025E35D02CF0 in-thread for timestamp 0
[TRACE] [2024-12-20T04:21:25Z] [00002848] [task-scheduler] - id=0000025E35D02CF0: Scheduling channel_shutdown task for immediate execution
[DEBUG] [2024-12-20T04:21:25Z] [00002848] [channel] - id=0000025E35D02B10: Channel shutdown is already pending, not scheduling another.
[TRACE] [2024-12-20T04:21:25Z] [00002848] [socket-handler] - id=0000025E35C6FE20: total read on this tick 3946
[DEBUG] [2024-12-20T04:21:25Z] [00002848] [channel] - id=0000025E35D02B10: Channel shutdown is already pending, not scheduling another.
[TRACE] [2024-12-20T04:21:25Z] [00002848] [event-loop] - id=0000025E3FC820A0: running scheduled tasks.
[TRACE] [2024-12-20T04:21:25Z] [00002848] [task-scheduler] - id=0000025E35D02CF0: Running channel_shutdown task with <Running> status
[DEBUG] [2024-12-20T04:21:25Z] [00002848] [channel] - id=0000025E35D02B10: beginning shutdown process
[TRACE] [2024-12-20T04:21:25Z] [00002848] [channel] - id=0000025E35D02B10: shutting down slot 0000025E3FCF6BD0 (the first one) in the read direction
[TRACE] [2024-12-20T04:21:25Z] [00002848] [channel] - id=0000025E35D02B10: shutting down slot 0000025E3FCF6BD0, with handler 0000025E35C6FE20 in read direction with error code 1029
[TRACE] [2024-12-20T04:21:25Z] [00002848] [socket-handler] - id=0000025E35C6FE20: shutting down read direction with error_code 1029
[DEBUG] [2024-12-20T04:21:25Z] [00002848] [channel] - id=0000025E35D02B10: handler 0000025E35C6FE20 shutdown in read dir completed.
[DEBUG] [2024-12-20T04:21:25Z] [00002848] [channel] - id=0000025E35D02B10: handler 0000025E3FE3E140 shutdown in read dir completed.
[TRACE] [2024-12-20T04:21:25Z] [00002848] [event-loop] - id=0000025E3FC820A0: scheduling task 0000025E35D02B38 in-thread for timestamp 0
[TRACE] [2024-12-20T04:21:25Z] [00002848] [task-scheduler] - id=0000025E35D02B38: Scheduling (null) task for immediate execution
[TRACE] [2024-12-20T04:21:25Z] [00002848] [event-loop] - id=0000025E3FC820A0: detected more scheduled tasks with the next occurring at 0, using timeout of 0.
[TRACE] [2024-12-20T04:21:25Z] [00002848] [event-loop] - id=0000025E3FC820A0: waiting for a maximum of 0 ms
[TRACE] [2024-12-20T04:21:25Z] [00002848] [event-loop] - id=0000025E3FC820A0: running scheduled tasks.
[TRACE] [2024-12-20T04:21:25Z] [00002848] [task-scheduler] - id=0000025E35D02B38: Running (null) task with <Running> status
[DEBUG] [2024-12-20T04:21:25Z] [00002848] [tls-handler] - id=0000025E3FE3E140: Shutting down the write direction
[TRACE] [2024-12-20T04:21:25Z] [00002848] [channel] - id=0000025E35D02B10: acquired message 0000025E3FD50AF0 of capacity 7 from pool 0000025E3FC1D240. Requested size was 7
[TRACE] [2024-12-20T04:21:25Z] [00002848] [channel] - id=0000025E35D02B10: sending write message of size 7, from slot 0000025E3FED9F90 to slot 0000025E3FCF6BD0 with handler 0000025E35C6FE20.
[TRACE] [2024-12-20T04:21:25Z] [00002848] [socket-handler] - id=0000025E35C6FE20: writing message of size 7
[TRACE] [2024-12-20T04:21:25Z] [00002848] [socket] - id=0000025E3FCD1730 handle=0000000000000250: queueing write of 7 bytes
[DEBUG] [2024-12-20T04:21:25Z] [00002848] [channel] - id=0000025E35D02B10: handler 0000025E3FE3E140 shutdown in write dir completed.
[TRACE] [2024-12-20T04:21:25Z] [00002848] [socket-handler] - id=0000025E35C6FE20: shutting down write direction with error_code 1029
[DEBUG] [2024-12-20T04:21:25Z] [00002848] [socket] - id=0000025E3FCD1730 handle=0000000000000250: closing
[TRACE] [2024-12-20T04:21:25Z] [00002848] [channel] - id=0000025E35D02B10: scheduling task with wrapper task id 0000025E35C6FEC0.
[TRACE] [2024-12-20T04:21:25Z] [00002848] [event-loop] - id=0000025E3FC820A0: scheduling task 0000025E35C6FEC0 in-thread for timestamp 0
[TRACE] [2024-12-20T04:21:25Z] [00002848] [task-scheduler] - id=0000025E35C6FEC0: Scheduling socket_handler_close task for immediate execution
[TRACE] [2024-12-20T04:21:25Z] [00002848] [event-loop] - id=0000025E3FC820A0: detected more scheduled tasks with the next occurring at 0, using timeout of 0.
[TRACE] [2024-12-20T04:21:25Z] [00002848] [event-loop] - id=0000025E3FC820A0: waiting for a maximum of 0 ms
[TRACE] [2024-12-20T04:21:25Z] [00002848] [event-loop] - id=0000025E3FC820A0: wake up with 1 events to process.
[TRACE] [2024-12-20T04:21:25Z] [00002848] [event-loop] - id=0000025E3FC820A0: invoking handler.
[TRACE] [2024-12-20T04:21:25Z] [00002848] [socket-handler] - static: write of size 7, completed on channel 0000025E35D02B10
[TRACE] [2024-12-20T04:21:25Z] [00002848] [event-loop] - id=0000025E3FC820A0: running scheduled tasks.
[TRACE] [2024-12-20T04:21:25Z] [00002848] [task-scheduler] - id=0000025E35C6FEC0: Running socket_handler_close task with <Running> status
[DEBUG] [2024-12-20T04:21:25Z] [00002848] [channel] - id=0000025E35D02B10: handler 0000025E35C6FE20 shutdown in write dir completed.
[TRACE] [2024-12-20T04:21:25Z] [00002848] [event-loop] - id=0000025E3FC820A0: scheduling task 0000025E35D02B38 in-thread for timestamp 0
[TRACE] [2024-12-20T04:21:25Z] [00002848] [task-scheduler] - id=0000025E35D02B38: Scheduling (null) task for immediate execution
[TRACE] [2024-12-20T04:21:25Z] [00002848] [event-loop] - id=0000025E3FC820A0: detected more scheduled tasks with the next occurring at 0, using timeout of 0.
[TRACE] [2024-12-20T04:21:25Z] [00002848] [event-loop] - id=0000025E3FC820A0: waiting for a maximum of 0 ms
[TRACE] [2024-12-20T04:21:25Z] [00002848] [event-loop] - id=0000025E3FC820A0: running scheduled tasks.
[TRACE] [2024-12-20T04:21:25Z] [00002848] [task-scheduler] - id=0000025E35D02B38: Running (null) task with <Running> status
[DEBUG] [2024-12-20T04:21:25Z] [00002848] [channel] - id=0000025E35D02B10: during shutdown, canceling task 0000025E3FE3E170
[TRACE] [2024-12-20T04:21:25Z] [00002848] [event-loop] - id=0000025E3FC820A0: cancelling task 0000025E3FE3E170
[TRACE] [2024-12-20T04:21:25Z] [00002848] [task-scheduler] - id=0000025E3FE3E170: Running tls_timeout task with <Canceled> status
[DEBUG] [2024-12-20T04:21:25Z] [00002848] [channel-bootstrap] - id=0000025E35D34C60: channel 0000025E35D02B10 shutdown with error 1029.
[INFO] [2024-12-20T04:21:25Z] [00002848] [mqtt5-client] - id=0000025E3FCF84A0: emitting connection failure lifecycle event with error code 1029(aws-c-io: AWS_IO_TLS_ERROR_NEGOTIATION_FAILURE, TLS (SSL) negotiation failed)
[INFO] [2024-12-20T04:21:25Z] [00002848] [mqtt5-client] - id=0000025E3FCF84A0: channel tore down with error code 1029(aws-c-io: AWS_IO_TLS_ERROR_NEGOTIATION_FAILURE, TLS (SSL) negotiation failed)
[DEBUG] [2024-12-20T04:21:25Z] [00002848] [mqtt5-client] - id=0000025E3FCF84A0: switching current state from CONNECTING to PENDING_RECONNECT
[DEBUG] [2024-12-20T04:21:25Z] [00002848] [mqtt5-client] - id=0000025E3FCF84A0: next connection attempt in 925 milliseconds

Expected Behavior

Able to connect to MQTT

Current Behavior

TLS negotiation failing

Reproduction Steps

const main = async () => {
  const builder =
    iot.AwsIotMqtt5ClientConfigBuilder.newDirectMqttBuilderWithMtlsFromPath(
      host,
      certPath,
      keyPath
    );
  builder.withConnectProperties({
    30,
    clientId,
  });
  builder.withCertificateAuthorityFromPath(caPath);

  const config = builder.build();

  const client = new mqtt5.Mqtt5Client(config);

  client.on("connectionSuccess",()=>{
    console.log('connectionSuccess')
  })

  client.start();
};

main();

Possible Solution

No response

Additional Information/Context

I tried with the same certificates on another machine(Windows10 22H2) and the connection was successful.
SECURITY_STATUS -2146893816(0x80090008) indicates NTE_BAD_ALGID according to error code reference.

SDK version used

1.21.1

Environment details (OS name and version, etc.)

Windows10 2016 LTSB

Metadata

Metadata

Assignees

No one assigned

    Labels

    bugThis issue is a bug.needs-triageThis issue or PR still needs to be triaged.

    Type

    No type

    Projects

    No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions