AWS IDT MQTT case, got unexpected alert message, mbedtls returned -0x7880

Hi,
i’m running the AWS IDT MQTT cases, it always failed as AWS cloud respond an alert message[1:0], mbedtls_ssl_handle_message_type() returned -30848 (-0x7880).

Following is related log:

1028 13463 [RunTests_task] mbedTLS: |2| 0x41eb44: => read

1029 13465 [RunTests_task] mbedTLS: |2| 0x41eb44: => read record

1030 13469 [RunTests_task] mbedTLS: |2| 0x41eb44: => fetch input

1031 13471 [RunTests_task] mbedTLS: |2| 0x41eb44: in_left: 0, nb_want: 5

1032 13551 [RunTests_task] mbedTLS: |2| 0x41eb44: in_left: 0, nb_want: 5

1033 13551 [RunTests_task] mbedTLS: |2| 0x41eb44: ssl->f_recv(_timeout)() returned 5 (-0xfffffffb)

1034 13553 [RunTests_task] mbedTLS: |2| 0x41eb44: <= fetch input

1035 13556 [RunTests_task] mbedTLS: |4| 0x41eb44: dumping 'input record header' (5 bytes)

1036 13560 [RunTests_task] mbedTLS: |4| 0x41eb44: 0000:  15 03 03 00 1a                                   .....

1037 13565 [RunTests_task] mbedTLS: |3| 0x41eb44: input record: msgtype = 21, version = [3:3], msglen = 26

1038 13570 [RunTests_task] mbedTLS: |2| 0x41eb44: => fetch input

1039 13573 [RunTests_task] mbedTLS: |2| 0x41eb44: in_left: 5, nb_want: 31

1040 13576 [RunTests_task] mbedTLS: |2| 0x41eb44: in_left: 5, nb_want: 31

1041 13580 [RunTests_task] mbedTLS: |2| 0x41eb44: ssl->f_recv(_timeout)() returned 26 (-0xffffffe6)

1042 13584 [RunTests_task] mbedTLS: |2| 0x41eb44: <= fetch input

1043 13587 [RunTests_task] mbedTLS: |4| 0x41eb44: dumping 'input record from network' (31 bytes)

1044 13591 [RunTests_task] mbedTLS: |4| 0x41eb44: 0000:  15 03 03 00 1a 00 00 00 00 00 00 00 01 3b 8e 02  .............1045 13597 [RunTests_task] mbedTLS: |4| 0x41eb44: 0010:  40 6f e9 74 6b 81 bd e7 33 3c 70 59 da 62 41     @o.tk...3<pY.1046 13602 [RunTests_task] mbedTLS: |2| 0x41eb44: => decrypt buf

1047 13605 [RunTests_task] mbedTLS: |4| 0x41eb44: dumping 'additional data for AEAD' (13 bytes)

1048 13609 [RunTests_task] mbedTLS: |4| 0x41eb44: 0000:  00 00 00 00 00 00 00 01 15 03 03 00 02           .............1049 13614 [RunTests_task] mbedTLS: |4| 0x41eb44: dumping 'IV used' (12 bytes)

1050 13618 [RunTests_task] mbedTLS: |4| 0x41eb44: 0000:  3b 7e 0a f5 00 00 00 00 00 00 00 01              ;~..........
1051 13623 [RunTests_task] mbedTLS: |4| 0x41eb44: dumping 'TAG used' (16 bytes)

1052 13626 [RunTests_task] mbedTLS: |4| 0x41eb44: 0000:  02 40 6f e9 74 6b 81 bd e7 33 3c 70 59 da 62 41  .@o.tk...3<pY1053 13632 [RunTests_task] mbedTLS: |2| 0x41eb44: <= decrypt buf

1054 13634 [RunTests_task] mbedTLS: |4| 0x41eb44: dumping 'input payload after decrypt' (2 bytes)

1055 13639 [RunTests_task] mbedTLS: |4| 0x41eb44: 0000:  01 00                                            ..

1056 13644 [RunTests_task] mbedTLS: |2| 0x41eb44: got an alert message, type: [1:0]

1057 13647 [RunTests_task] mbedTLS: |2| 0x41eb44: is a close notify message

1058 13651 [RunTests_task] mbedTLS: |1| 0x41eb44: mbedtls_ssl_handle_message_type() returned -30848 (-0x7880)

1059 13656 [RunTests_task] mbedTLS: |1| 0x41eb44: mbedtls_ssl_read_record() returned -30848 (-0x7880)

1060 13660 [RunTests_task] mbedTLS: |2| 0x41eb44: => write close notify

1061 13663 [RunTests_task] mbedTLS: |2| 0x41eb44: => send alert message

1062 13667 [RunTests_task] mbedTLS: |3| 0x41eb44: send alert level=1 message=0

1063 13670 [RunTests_task] mbedTLS: |2| 0x41eb44: => write record

1064 13673 [RunTests_task] mbedTLS: |2| 0x41eb44: => encrypt buf

1065 13676 [RunTests_task] mbedTLS: |4| 0x41eb44: dumping 'before encrypt: output payload' (2 bytes)

1066 13681 [RunTests_task] mbedTLS: |4| 0x41eb44: 0000:  01 00                                            ..

1067 13686 [RunTests_task] mbedTLS: |4| 0x41eb44: dumping 'additional data for AEAD' (13 bytes)

1068 13690 [RunTests_task] mbedTLS: |4| 0x41eb44: 0000:  00 00 00 00 00 00 00 02 15 03 03 00 02           .............1069 13695 [RunTests_task] mbedTLS: |4| 0x41eb44: dumping 'IV used (internal)' (12 bytes)

1070 13699 [RunTests_task] mbedTLS: |4| 0x41eb44: 0000:  02 db b0 4b 00 00 00 00 00 00 00 02              ...K........
1071 13704 [RunTests_task] mbedTLS: |4| 0x41eb44: dumping 'IV used (transmitted)' (8 bytes)

1072 13708 [RunTests_task] mbedTLS: |4| 0x41eb44: 0000:  00 00 00 00 00 00 00 02                          ........

1073 13713 [RunTests_task] mbedTLS: |3| 0x41eb44: before encrypt: msglen = 10, including 0 bytes of padding

1074 13718 [RunTests_task] mbedTLS: |4| 0x41eb44: dumping 'after encrypt: tag' (16 bytes)

1075 13722 [RunTests_task] mbedTLS: |4| 0x41eb44: 0000:  41 6b 91 c8 2c 1d 57 d5 da ef 46 73 75 3d 8a 14  Ak..,.W...Fsu1076 13727 [RunTests_task] mbedTLS: |2| 0x41eb44: <= encrypt buf

1077 13730 [RunTests_task] mbedTLS: |3| 0x41eb44: output record: msgtype = 21, version = [3:3], msglen = 26

1078 13735 [RunTests_task] mbedTLS: |4| 0x41eb44: dumping 'output record sent to network' (31 bytes)

1079 13740 [RunTests_task] mbedTLS: |4| 0x41eb44: 0000:  15 03 03 00 1a 00 00 00 00 00 00 00 02 5f c1 41  .............1080 13745 [RunTests_task] mbedTLS: |4| 0x41eb44: 0010:  6b 91 c8 2c 1d 57 d5 da ef 46 73 75 3d 8a 14     k..,.W...Fsu=1081 13750 [RunTests_task] mbedTLS: |2| 0x41eb44: => flush output

1082 13753 [RunTests_task] mbedTLS: |2| 0x41eb44: message length: 31, out_left: 31

1083 13757 [RunTests_task] mbedTLS: |2| 0x41eb44: ssl->f_send() returned 31 (-0xffffffe1)

1084 13761 [RunTests_task] mbedTLS: |2| 0x41eb44: <= flush output

1085 13764 [RunTests_task] mbedTLS: |2| 0x41eb44: <= write record

1086 13767 [RunTests_task] mbedTLS: |2| 0x41eb44: <= send alert message

1087 13770 [RunTests_task] mbedTLS: |2| 0x41eb44: <= write close notify

1088 13773 [RunTests_task] mbedTLS: |2| 0x41eb44: => free

1089 13776 [RunTests_task] mbedTLS: |2| 0x41eb44: <= free

1090 13779 [RunTests_task] [ERROR] Failed to receive data over network. bytesReceived=-30848
1091 13782 [RunTests_task] [ERROR] A single byte was not read from the transport: transportStatus=-30848.
1092 13787 [RunTests_task] [ERROR] CONNACK recv failed with status = MQTTRecvFailed.
1093 13791 [RunTests_task] [ERROR] MQTT connection failed with status = MQTTRecvFailed.
Failed to send data over network. bytesSent=-27648.
1095 13855 [RunTests_task] [ERROR] Transport send failed. Error code=-27648.
1096 13856 [RunTests_task] [ERROR] Transport send failed for DISCONNECT packet.

@Rashed Talukder can you help look at this?

Seems you are not getting a CONNACK. Is your policy setup correctly? Can you share your policy document?

Also, increase the MQTT log level to debug in your config file and share the logs.

@aggarg thanks for your reply.
i have enabled the mqtt log:

991 13497 [RunTests_task] [DEBUG] Client ID for MQTT for MQTT connection={idt-6737131878841795756} 
994 13507 [RunTests_task] [DEBUG] Encoded size for length 99 is 1 bytes.
995 13510 [RunTests_task] [DEBUG] CONNECT packet remaining length=99 and packet size=101.
996 13514 [RunTests_task] [DEBUG] CONNECT packet size is 101 and remaining length is 99.
997 13518 [RunTests_task] [DEBUG] Encoded size for length 99 is 1 bytes.
998 13521 [RunTests_task] [DEBUG] Length of serialized CONNECT packet is 101.
1037 13693 [RunTests_task] [DEBUG] BytesSent=101, BytesRemaining=0
1038 13696 [RunTests_task] [DEBUG] Successfully sent packet at time 27386.
1039 13699 [RunTests_task] [DEBUG] Sent 101 bytes of CONNECT packet.

i found cliend had sent the “Hello world” with test topic to server. While when receving the response, serve gracefully close the connection, so client get the alert message.

Which policy do you specify ? I used the IDT, I think the tester framework will automatically creat the resouce for testing, right ? i see the log when the test is starting:

"Applying policy retrieved from /XXX/devicetester_freertos_linux/tests/FRQ_1.6.1/policies/thingPolicy.json.\n"
XXX$ cat /XXX/devicetester_freertos_linux/tests/FRQ_1.6.1/policies/thingPolicy.json
{
	"Version": "2012-10-17",
	"Statement": [
		{
			"Effect": "Allow",
			"Action": "iot:*",
			"Resource": "*"
		}
	]
}

This looks correct. Thank you for sharing.

Are these the complete logs you get or are there more? This seems like you are not getting the CONNACK - can you try increasing the time you wait for CONNACK?

@aggarg yes, it’s complete logs for mqtt . it didn’t recive the CONNAK, you can see the my first log, the ssl just receive the alert message immediately .

i double the CONNACK_RECV_TIMEOUT_MS, it reported same error. i think there is nothing about the timeout. the tls can receive the close notify message soon. Do you know the scenario when AWS IOT will send close notify message? How to debug in server side?

@aggarg , in a summary, i found client can establish with AWS IOT endpoint via TLS, i can see the handshake procedure finishes successfully, but once client send any data to server, server will close the connection.

Does anything listed here help: https://docs.aws.amazon.com/iot/latest/developerguide/diagnosing-connectivity-issues.html

That strongly indicates some issue with your certificate (or attached policy). How did you create your device certificate? Lets first test that certificate in isolation to narrow down the problem. You can use mosquitto client for that:

mosquitto_pub --cert <device_cert> --key <device_priv_key> --cafile <root_ca_file> -h <aws_iot_endpoint> -t "/topic/example" -m "Hello world" -d

Thanks.

@aggarg the device certificate/policy is auto-created by IDT when running the cases. you can see the related logs:
time=“2021-10-15T17:33:54+08:00” level=info msg=“Setting client credentials …”
time=“2021-10-15T17:33:54+08:00” level=info msg=“Setting ‘idt-4135510899960087841’ as thing name …”
time=“2021-10-15T17:33:54+08:00” level=info msg=“Setting iot endpoint …”
time=“2021-10-15T17:33:54+08:00” level=info msg="Test setup finished "

And I can see the random thing-name “idt-4135510899960087841” in the AWS IOT web page. i check the corresponding policy, it allow all action and * resouse.

Another link that may help - Lifecycle events - AWS IoT Core

Hi jun.luo,

Can you please share a zip of the IDT logs from your test run.
You can find it under the following folder devicetester-extract-location/results/{idt-execution-id}
Link with notes on IDT test result logs.
https://docs.aws.amazon.com/freertos/latest/userguide/results-logs.html

Thanks,
Pradheesh.

fcea100f-2d9a-11ec-8fc5-080027b9f0bd.7z (77.1 KB)
@pradheCloud @aggarg Above is my IDT log. Please help to check.

i’m really looking forward to your help, thanks.

@rtel thanks, i check the doc, can’t find any clue.

My understanding is that because i’m running the cases under IOT Device Tester, so the device certificate and private key is auto-created by the IDT and updated in aws_clientcredential_keys.h(keyCLIENT_CERTIFICATE_PEM/keyCLIENT_PRIVATE_KEY_PEM)
And meanwhile when running the cases, i check the policy attached with the thing in the AWS IOT web page, the policy allow “" for action "iot:”, so i can’t find any problem with the certificate and policy. You can correct me if my understanding is wrong.

You are absolutely right. Looking at your logs, it seems that the SSL handshake is successful but the MQTT connection is not which seems strange given the fact that IDT is creating cert and policy. Is possible for you to capture network traffic? Also share your complete IDT config?

Which hardware platform are you using?

Thanks.

@aggarg Thanks.This is the configs:
configs.zip (5.2 KB)

i’m running the IDT to qualify my own company private chip. I think it should there is nothing with the hardware because this is the problem on the application.

@aggarg Thanks very much for your great support.
On the remote debug session, after re-run the cases, the issue disappeared.

The issue happen again. And the we find the root cause from the error log:“Could not initialize PKCS #11. Failed to seed the DRBG” .
The root cause is we call the vDevModeKeyProvisioning() later than the SYSTEM_Init(), so some resource is not ready when we use it.
@aggarg i update here