AWS recovers from read error 0x004C once but not a second time (IDFGH-13081) (CA-339)

[MarkMendelsohn]

Answers checklist.

• I have read the documentation ESP-IDF Programming Guide and the issue is not addressed there.
• I have updated my IDF branch (master or release) to the latest version and checked that the issue is present there.
• 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.