[X] I have updated my IDF branch (master or release) to the latest version and checked that the issue is present there.
[X] I have searched the issue tracker for a similar issue and not found a similar issue.
IDF version.
v5.1.2-89-g5c61c89308-dirty
Espressif SoC revision.
ESP32-S3 (QFN56) (revision v0.1)
Operating System used.
macOS
How did you build your project?
Command line with idf.py
If you are using Windows, please specify command line type.
None
Development Kit.
ESP32-S3-DevKitC-1
Power Supply used.
USB
What is the expected behavior?
AWS should reconnect after each failure of the underlying TLS connection
What is the actual behavior?
AWS reconnects once, but a subsequent TLS connection failure occurs right after completing recovery and this second time it did not trigger the same recovery procedure again.
Steps to reproduce.
Do not know what is causing the TLS connection to fail in the first place
Debug Logs.
1 I (263244) coreMQTT: Ack packet deserialized with result: MQTTSuccess.
2 I (263244) coreMQTT: State record updated. New state=MQTTPublishDone.
3 I (263244) AWS_OTA: PUBACK received for packet id 68.
4 I (263254) AWS_OTA: Sent PUBLISH packet to broker $aws/things/dev-johndoe/shadow/update to broker.
5 I (263264) coreMQTT: De-serialized incoming PUBLISH packet: DeserializerResult=MQTTSuccess.
6 I (263274) coreMQTT: State record updated. New state=MQTTPublishDone.
7 I (263274) coreMQTT: Invoking subscription callback of matching topic filter: TopicFilter=$aws/things/dev-johndoe/shadow/update/ documents, TopicName=$aws/things/dev-johndoe/shadow/update/documents
8 update_docs
9 I (263314) coreMQTT: De-serialized incoming PUBLISH packet: DeserializerResult=MQTTSuccess.
10 I (263324) coreMQTT: State record updated. New state=MQTTPublishDone.
11 I (263324) coreMQTT: Invoking subscription callback of matching topic filter: TopicFilter=$aws/things/dev-johndoe/shadow/update/ accepted, TopicName=$aws/things/dev-johndoe/shadow/update/accepted
12 update_acc
13 -processLoopWithTimeout
14 -processLoopWithTimeout
15 datetime 1718730362
16 timestamp 1718730362
17 save nvs_open 0
18 nvs_get_blob 0 16
19 nvs_set_blob 0
20 E (282964) CLOUD: done sending
21 save nvs_open 0
22 nvs_get_blob 0 16
23 E (283014) esp-tls-mbedtls: read error :-0x004C:
24 E (283014) esp-tls-mbedtls: read error :-0x004C:
25 E (283254) esp-tls-mbedtls: read error :-0x004C:
26 E (283294) esp-tls-mbedtls: read error :-0x004C:
27 W (283304) AWS_OTA: Publish failed. Retrying connection after 317 ms backoff.
28 nvs_set_blob 0
29 E (283614) esp-tls-mbedtls: read error :-0x004C:
30 W (283614) AWS_OTA: Publish failed. Retrying connection after 450 ms backoff.
31 E (284064) esp-tls-mbedtls: read error :-0x004C:
32 W (284064) AWS_OTA: Publish failed. Retrying connection after 1472 ms backoff.
33 -processLoopWithTimeout
34 E (285534) esp-tls-mbedtls: read error :-0x004C:
35 E (285534) AWS_OTA: Publish failed, all attempts exhausted.
36 E (285544) AWS_OTA: Failed to send PUBLISH packet to broker with error = 4.
37 E (285554) AWS_OTA: MQTT_ProcessLoop returned with status = Invalid MQTT Status code.
38 I (285564) AWS_OTA: Disconnecting the MQTT connection with a380i996o62146-ats.iot.us-east-2.amazonaws.com.
39 I (285574) coreMQTT: Disconnected from the broker.
40 W (285574) AWS_OTA: OTA Timer handle NULL for Timerid=0, can't stop.
41 W (285584) AWS_OTA: OTA Timer handle NULL for Timerid=1, can't stop.
42 I (285594) AWS_OTA: OTA Agent is suspended.
43 I (285594) AWS_OTA: Establishing a TLS session to a380i996o62146-ats.iot.us-east-2.amazonaws.com:8883.
44 I (285594) AWS_OTA: Current State=[Suspended], Event=[Suspend], New state=[Suspended]
45 I (287004) AWS_OTA: Creating an MQTT connection to a380i996o62146-ats.iot.us-east-2.amazonaws.com.
46 I (287234) coreMQTT: MQTT connection established with the broker.
47 I (287234) AWS_OTA: MQTT connection successfully established with broker.
48 I (287244) AWS_OTA: otaPal_GetPlatformImageState
49 I (287244) esp_ota_ops: aws_esp_ota_get_boot_flags: 1
50 I (287254) esp_ota_ops: [0] aflags/seq:0x2/0x1, pflags/seq:0xffffffff/0x0
51 I (287264) AWS_OTA: Current State=[RequestingJob], Event=[Resume], New state=[RequestingJob]
52 custom_mqtt_subscriptions: dev-johndoe $aws/things/
53 shadow_topic_str_delete_acc: dev-johndoe /shadow
54 shadow_topic_str_delete_acc: $aws/things/dev-johndoe/shadow/delete/accepted
55 E (287284) coreMQTT: Failed to register callback: Record for topic filter already exists: TopicFilter=$aws/things/dev-johndoe/sh adow/delete/accepted
56 I (287304) AWS_OTA: SUBSCRIBE topic $aws/things/dev-johndoe/shadow/delete/accepted to broker.
57 E (287324) coreMQTT: Failed to register callback: Record for topic filter already exists: TopicFilter=$aws/things/dev-johndoe/sh adow/delete/rejected
58 I (287544) AWS_OTA: Received SUBACK.
59 I (287544) AWS_OTA: SUBSCRIBE topic $aws/things/dev-johndoe/shadow/delete/rejected to broker.
60 E (287544) coreMQTT: Failed to register callback: Record for topic filter already exists: TopicFilter=$aws/things/dev-johndoe/sh adow/get/accepted
61 I (287834) AWS_OTA: Received SUBACK.
62 I (287844) AWS_OTA: SUBSCRIBE topic $aws/things/dev-johndoe/shadow/get/accepted to broker.
63 E (287844) coreMQTT: Failed to register callback: Record for topic filter already exists: TopicFilter=$aws/things/dev-johndoe/sh adow/get/rejected
64 I (287854) AWS_OTA: SUBSCRIBE topic $aws/things/dev-johndoe/shadow/get/rejected to broker.
65 E (287864) coreMQTT: Failed to register callback: Record for topic filter already exists: TopicFilter=$aws/things/dev-johndoe/sh adow/update/accepted
66 I (288124) AWS_OTA: Received SUBACK.
67 I (288134) AWS_OTA: SUBSCRIBE topic $aws/things/dev-johndoe/shadow/update/accepted to broker.
68 E (288134) coreMQTT: Failed to register callback: Record for topic filter already exists: TopicFilter=$aws/things/dev-johndoe/sh adow/update/rejected
69 I (288144) AWS_OTA: SUBSCRIBE topic $aws/things/dev-johndoe/shadow/update/rejected to broker.
70 I (288144) AWS_OTA: Received SUBACK.
71 E (288154) coreMQTT: Failed to register callback: Record for topic filter already exists: TopicFilter=$aws/things/dev-johndoe/sh adow/update/delta
72 I (288364) AWS_OTA: Received SUBACK.
73 I (288374) AWS_OTA: SUBSCRIBE topic $aws/things/dev-johndoe/shadow/update/delta to broker.
74 E (288374) coreMQTT: Failed to register callback: Record for topic filter already exists: TopicFilter=$aws/things/dev-johndoe/sh adow/update/documents
75 I (288384) AWS_OTA: SUBSCRIBE topic $aws/things/dev-johndoe/shadow/update/documents to broker.
76 I (288394) AWS_OTA: Received SUBACK.
77 I (288404) AWS_OTA: Sent PUBLISH packet to broker $aws/things/dev-johndoe/shadow/get to broker.
78 -custom_mqtt_subscriptions: is_up true
79 I (288414) AWS_OTA: SUBSCRIBE topic $aws/things/dev-johndoe/jobs/notify-next to broker.
80 E (288424) coreMQTT: Failed to register callback: Record for topic filter already exists: TopicFilter=$aws/things/+/jobs/#
81 W (288444) AWS_OTA: Failed to register a callback to subscription manager with error = 3.
82 I (288454) AWS_OTA: Subscribed to MQTT topic: $aws/things/dev-johndoe/jobs/notify-next
83 I (288634) coreMQTT: Ack packet deserialized with result: MQTTSuccess.
84 I (288634) coreMQTT: State record updated. New state=MQTTPublishDone.
85 I (288644) AWS_OTA: PUBACK received for packet id 81.
86 I (288654) coreMQTT: De-serialized incoming PUBLISH packet: DeserializerResult=MQTTSuccess.
87 I (288674) coreMQTT: State record updated. New state=MQTTPublishDone.
88 I (288674) coreMQTT: Invoking subscription callback of matching topic filter: TopicFilter=$aws/things/dev-johndoe/shadow/get/acc epted, TopicName=$aws/things/dev-johndoe/shadow/get/accepted
89 get_acc
90 auto
91 45
92 24
93 I (288844) AWS_OTA: Sent PUBLISH packet to broker $aws/things/dev-johndoe/jobs/$next/get to broker.
94 I (288854) AWS_OTA: Current State=[WaitingForJob], Event=[RequestJobDocument], New state=[WaitingForJob]
95 I (288844) AWS_OTA: Received SUBACK.
96 I (288884) AWS_OTA: Received SUBACK.
97 I (288894) AWS_OTA: Received SUBACK.
98 I (288894) coreMQTT: Ack packet deserialized with result: MQTTSuccess.
99 I (288904) coreMQTT: State record updated. New state=MQTTPublishDone.
100 I (288904) AWS_OTA: PUBACK received for packet id 83.
101 prvSensorTask msg 7
102 I (288924) flow_cntrl.c: exiting auto monitoring loop in monitor_task_event_source()
103 prvWifiTask msg 7
104 -processLoopWithTimeout
105 I (289914) coreMQTT: De-serialized incoming PUBLISH packet: DeserializerResult=MQTTSuccess.
106 I (289914) coreMQTT: State record updated. New state=MQTTPublishDone.
107 I (289914) coreMQTT: Invoking subscription callback of matching topic filter: TopicFilter=$aws/things/+/jobs/#, TopicName=$aws/t hings/dev-johndoe/jobs/$next/get/accepted
108 I (289934) AWS_OTA: No active job available in received job document: OtaJobParseErr_t=OtaJobParseErrNoActiveJobs
109 I (289944) AWS_OTA: otaPal_GetPlatformImageState
110 I (289944) esp_ota_ops: aws_esp_ota_get_boot_flags: 1
111 I (289954) esp_ota_ops: [0] aflags/seq:0x2/0x1, pflags/seq:0xffffffff/0x0
112 I (289964) AWS_OTA: Current State=[WaitingForJob], Event=[ReceivedJobDocument], New state=[CreatingFile]
113 W (290074) AWS_OTA: PINGRESP should not be handled by the application callback when using MQTT_ProcessLoop.
114 I (290074) AWS_OTA: Sent PUBLISH packet to broker $aws/things/dev-johndoe/shadow/update to broker.
115 I (290174) coreMQTT: Ack packet deserialized with result: MQTTSuccess.
116 I (290174) coreMQTT: State record updated. New state=MQTTPublishDone.
117 I (290174) AWS_OTA: PUBACK received for packet id 84.
118 I (290184) coreMQTT: De-serialized incoming PUBLISH packet: DeserializerResult=MQTTSuccess.
119 I (290194) coreMQTT: State record updated. New state=MQTTPublishDone.
120 I (290204) coreMQTT: Invoking subscription callback of matching topic filter: TopicFilter=$aws/things/dev-johndoe/shadow/update/ documents, TopicName=$aws/things/dev-johndoe/shadow/update/documents
121 update_docs
122 I (290234) coreMQTT: De-serialized incoming PUBLISH packet: DeserializerResult=MQTTSuccess.
123 I (290244) coreMQTT: State record updated. New state=MQTTPublishDone.
124 I (290254) coreMQTT: Invoking subscription callback of matching topic filter: TopicFilter=$aws/things/dev-johndoe/shadow/update/ accepted, TopicName=$aws/things/dev-johndoe/shadow/update/accepted
125 update_acc
126 E (296014) esp-tls-mbedtls: read error :-0x004C:
127 E (296014) esp-tls-mbedtls: read error :-0x004C:
128 E (296014) esp-tls-mbedtls: read error :-0x004C:
More Information.
Occurs every few days on our AWS connected device.
Answers checklist.
IDF version.
v5.1.2-89-g5c61c89308-dirty
Espressif SoC revision.
ESP32-S3 (QFN56) (revision v0.1)
Operating System used.
macOS
How did you build your project?
Command line with idf.py
If you are using Windows, please specify command line type.
None
Development Kit.
ESP32-S3-DevKitC-1
Power Supply used.
USB
What is the expected behavior?
AWS should reconnect after each failure of the underlying TLS connection
What is the actual behavior?
AWS reconnects once, but a subsequent TLS connection failure occurs right after completing recovery and this second time it did not trigger the same recovery procedure again.
Steps to reproduce.
Do not know what is causing the TLS connection to fail in the first place
Debug Logs.
More Information.
Occurs every few days on our AWS connected device.