search

aws / amazon-freertos

DEPRECATED - See README.md
https://aws.amazon.com/freertos/
MIT License
2.54k stars 1.1k forks source link

[BUG] `CORE_MQTT_MUTUAL_AUTH` Demo: Failed to establish new connection #3521

Closed laukik-hase closed 1 year ago

laukik-hase commented 1 year ago

Description

System information

Screenshots or console output

Actual Output ``` I (29) boot: ESP-IDF v4.2.2-276-g4e4142ef8 2nd stage bootloader I (29) boot: compile time 16:56:55 I (29) boot: chip revision: 3 I (33) boot_comm: chip revision: 3, min. bootloader chip revision: 0 I (41) boot.esp32: SPI Speed : 40MHz I (45) boot.esp32: SPI Mode : DIO I (49) boot.esp32: SPI Flash Size : 4MB I (54) boot: Enabling RNG early entropy source... I (59) boot: Partition Table: I (63) boot: ## Label Usage Type ST Offset Length I (70) boot: 0 nvs WiFi data 01 02 00010000 00006000 I (78) boot: 1 otadata OTA data 01 00 00016000 00002000 I (85) boot: 2 phy_init RF data 01 01 00018000 00001000 I (93) boot: 3 ota_0 OTA app 00 10 00020000 00177000 I (100) boot: 4 ota_1 OTA app 00 11 001a0000 00177000 I (108) boot: 5 storage WiFi data 01 02 00317000 00010000 I (115) boot: End of partition table I (120) boot: No factory image, trying OTA 0 I (124) boot_comm: chip revision: 3, min. application chip revision: 0 I (132) esp_image: segment 0: paddr=0x00020020 vaddr=0x3f400020 size=0x29090 (168080) map I (205) esp_image: segment 1: paddr=0x000490b8 vaddr=0x3ffbdb60 size=0x03994 ( 14740) load I (211) esp_image: segment 2: paddr=0x0004ca54 vaddr=0x40080000 size=0x035c4 ( 13764) load 0x40080000: _WindowOverflow4 at /home/laukik/work/amazon-freertos/build/../freertos_kernel/portable/ThirdParty/GCC/Xtensa_ESP32/xtensa_vectors.S:1821 I (218) esp_image: segment 3: paddr=0x00050020 vaddr=0x400d0020 size=0xa8f94 (692116) map 0x400d0020: _stext at ??:? I (484) esp_image: segment 4: paddr=0x000f8fbc vaddr=0x400835c4 size=0x19454 (103508) load 0x400835c4: esp_flash_init at /home/laukik/work/amazon-freertos/build/../vendors/espressif/esp-idf/components/spi_flash/esp_flash_api.c:116 (discriminator 3) I (545) boot: Loaded app from partition at offset 0x20000 I (621) boot: Set actual ota_seq=1 in otadata[0] I (621) boot: Disabling RNG early entropy source... I (622) cpu_start: Pro cpu up. I (625) cpu_start: Application information: I (630) cpu_start: Project name: amazon-freertos I (635) cpu_start: App version: 1 I (640) cpu_start: Compile time: Aug 8 2022 16:56:47 I (646) cpu_start: ELF file SHA256: 2e9b24952efbfaa1... I (652) cpu_start: ESP-IDF: v4.2.2-276-g4e4142ef8 I (658) cpu_start: Single core mode I (662) heap_init: Initializing. RAM available for dynamic allocation: I (669) heap_init: At 3FF80000 len 00002000 (8 KiB): RTCRAM I (675) heap_init: At 3FFAFF10 len 000000F0 (0 KiB): DRAM I (682) heap_init: At 3FFB6388 len 00001C78 (7 KiB): DRAM I (688) heap_init: At 3FFB9A20 len 00004108 (16 KiB): DRAM I (694) heap_init: At 3FFCA388 len 00015C78 (87 KiB): DRAM I (700) heap_init: At 3FFE0440 len 0001FBC0 (126 KiB): D/IRAM I (706) heap_init: At 40078000 len 00008000 (32 KiB): IRAM I (713) heap_init: At 4009CA18 len 000035E8 (13 KiB): IRAM I (719) cpu_start: Pro cpu start user code I (736) spi_flash: detected chip: generic I (737) spi_flash: flash i�0 0 [main] Initializing lwIP TCP stack I (757) PKCS11: Initializing NVS partition: "storage" E (767) PKCS11: failed nvs get file size 4354 0 1 4 [main] Write certificate... 2 6 [iot_thread] [INFO ][DEMO][60] ---------STARTING DEMO--------- I (807) BTDM_INIT: BT controller compile version [bfbbe1e] 3 6 [iot_thread] [INFO ][INIT][60] SDK successfully initialized. I (817) system_api: Base MAC address is not set I (817) system_api: read default base MAC address from EFUSE I (827) phy_init: phy_version 4660,0162888,Dec 23 2020 GAP procedure initiated: advertise; disc_mode=2 adv_channel_map=0 own_addr_type=0 adv_filter_policy=0 adv_itvl_min=187 adv_itvl_max=375 I (1227) wifi:wifi driver task: 3ffd7194, prio:23, stack:6656, core=0 I (1227) wifi:wifi firmware version: df5b09d I (1227) wifi:wifi certification version: v7.0 I (1227) wifi:config NVS flash: enabled I (1227) wifi:config nano formating: disabled I (1237) wifi:Init data frame dynamic rx buffer num: 32 I (1237) wifi:Init management frame dynamic rx buffer num: 32 I (1247) wifi:Init management short buffer num: 32 I (1247) wifi:Init dynamic tx buffer num: 32 I (1257) wifi:Init static rx buffer size: 1600 I (1257) wifi:Init static rx buffer num: 10 I (1257) wifi:Init dynamic rx buffer num: 32 I (1267) wifi_init: rx ba win: 6 I (1267) wifi_init: tcpip mbox: 32 I (1277) wifi_init: udp mbox: 6 I (1277) wifi_init: tcp mbox: 6 I (1277) wifi_init: tcp tx win: 5744 I (1287) wifi_init: tcp rx win: 5744 I (1287) wifi_init: tcp mss: 1440 I (1297) wifi_init: WiFi IRAM OP enabled I (1297) wifi_init: WiFi RX IRAM OP enabled I (1307) phy_init: phy_version 4660,0162888,Dec 23 2020 I (1317) wifi:mode : sta (3c:61:05:4c:33:e8) I (1317) WIFI: WIFI_EVENT_STA_START I (1327) wifi:new:<1,0>, old:<1,0>, ap:<255,255>, sta:<1,0>, prof:1 I (1787) wifi:state: init -> auth (b0) I (1797) wifi:state: auth -> assoc (0) I (1807) wifi:state: assoc -> run (10) I (1847) wifi:connected with ES_Staff, aid = 6, channel 1, BW20, bssid = b4:fb:e4:4d:7c:89 I (1847) wifi:security: WPA2-PSK, phy: bgn, rssi: -73 I (1847) wifi:pm start, type: 1 I (1857) WIFI: WIFI_EVENT_STA_CONNECTED I (2057) wifi:AP's beacon interval = 102400 us, DTIM period = 1 I (2747) esp_netif_handlers: sta ip: 192.168.20.234, mask: 255.255.255.0, gw: 192.168.20.1 I (2747) WIFI: SYSTEM_EVENT_STA_GOT_IP 4 200 [sys_evt] [INFO ][DEMO][2000] Connected to WiFi access point, ip address: 255.255.255.0. 5 201 [iot_thread] [INFO ][DEMO][2010] Successfully initialized the demo. Network type for the demo: 1 6 201 [iot_thread] [mqtt_demo_mutual_auth.c:763] [INFO] [MQTT_MutualAuth_Demo] Creating a TLS connection to a10y2vqnezxqbn-ats.iot.us-east-1.amazonaws.com:8883. E (3617) PKCS11: failed nvs get file size 4354 0 7 601 [iot_thread] ERROR: TLS handshake failed trying to connect. SSL - The connection indicated an EOF : 8 601 [iot_thread] TLS_Connect fail (0x7280, a10y2vqnezxqbn-ats.iot.us-east-1.amazonaws.com) 9 601 [iot_thread] [transport_secure_sockets.c:343] [ERROR] [Transport_Secure_Sockets] Failed to establish new connection. secureSocketStatus=-1. 10 602 [iot_thread] [mqtt_demo_mutual_auth.c:771] [WARN] [MQTT_MutualAuth_Demo] Connection to the broker failed. Attempting connection retry after backoff delay. 11 633 [iot_thread] [mqtt_demo_mutual_auth.c:708] [INFO] [MQTT_MutualAuth_Demo] Retry attempt 2 out of maximum retry attempts 5. 12 633 [iot_thread] [mqtt_demo_mutual_auth.c:763] [INFO] [MQTT_MutualAuth_Demo] Creating a TLS connection to a10y2vqnezxqbn-ats.iot.us-east-1.amazonaws.com:8883. E (7357) PKCS11: failed nvs get file size 4354 0 13 748 [iot_thread] ERROR: TLS handshake failed trying to connect. SSL - The connection indicated an EOF : 14 748 [iot_thread] TLS_Connect fail (0x7280, a10y2vqnezxqbn-ats.iot.us-east-1.amazonaws.com) 15 748 [iot_thread] [transport_secure_sockets.c:343] [ERROR] [Transport_Secure_Sockets] Failed to establish new connection. secureSocketStatus=-1. 16 749 [iot_thread] [mqtt_demo_mutual_auth.c:771] [WARN] [MQTT_MutualAuth_Demo] Connection to the broker failed. Attempting connection retry after backoff delay. 17 840 [iot_thread] [mqtt_demo_mutual_auth.c:708] [INFO] [MQTT_MutualAuth_Demo] Retry attempt 3 out of maximum retry attempts 5. 18 840 [iot_thread] [mqtt_demo_mutual_auth.c:763] [INFO] [MQTT_MutualAuth_Demo] Creating a TLS connection to a10y2vqnezxqbn-ats.iot.us-east-1.amazonaws.com:8883. E (9957) PKCS11: failed nvs get file size 4354 0 19 1244 [iot_thread] ERROR: TLS handshake failed trying to connect. SSL - The connection indicated an EOF : 20 1244 [iot_thread] TLS_Connect fail (0x7280, a10y2vqnezxqbn-ats.iot.us-east-1.amazonaws.com) 21 1244 [iot_thread] [transport_secure_sockets.c:343] [ERROR] [Transport_Secure_Sockets] Failed to establish new connection. secureSocketStatus=-1. 22 1244 [iot_thread] [mqtt_demo_mutual_auth.c:771] [WARN] [MQTT_MutualAuth_Demo] Connection to the broker failed. Attempting connection retry after backoff delay. 23 1393 [iot_thread] [mqtt_demo_mutual_auth.c:708] [INFO] [MQTT_MutualAuth_Demo] Retry attempt 4 out of maximum retry attempts 5. 24 1393 [iot_thread] [mqtt_demo_mutual_auth.c:763] [INFO] [MQTT_MutualAuth_Demo] Creating a TLS connection to a10y2vqnezxqbn-ats.iot.us-east-1.amazonaws.com:8883. E (15207) PKCS11: failed nvs get file size 4354 0 25 1496 [iot_thread] ERROR: TLS handshake failed trying to connect. SSL - The connection indicated an EOF : 26 1496 [iot_thread] TLS_Connect fail (0x7280, a10y2vqnezxqbn-ats.iot.us-east-1.amazonaws.com) 27 1496 [iot_thread] [transport_secure_sockets.c:343] [ERROR] [Transport_Secure_Sockets] Failed to establish new connection. secureSocketStatus=-1. 28 1496 [iot_thread] [mqtt_demo_mutual_auth.c:771] [WARN] [MQTT_MutualAuth_Demo] Connection to the broker failed. Attempting connection retry after backoff delay. 29 1642 [iot_thread] [mqtt_demo_mutual_auth.c:708] [INFO] [MQTT_MutualAuth_Demo] Retry attempt 5 out of maximum retry attempts 5. 30 1642 [iot_thread] [mqtt_demo_mutual_auth.c:763] [INFO] [MQTT_MutualAuth_Demo] Creating a TLS connection to a10y2vqnezxqbn-ats.iot.us-east-1.amazonaws.com:8883. E (17947) PKCS11: failed nvs get file size 4354 0 31 1771 [iot_thread] ERROR: TLS handshake failed trying to connect. SSL - The connection indicated an EOF : 32 1771 [iot_thread] TLS_Connect fail (0x7280, a10y2vqnezxqbn-ats.iot.us-east-1.amazonaws.com) 33 1771 [iot_thread] [transport_secure_sockets.c:343] [ERROR] [Transport_Secure_Sockets] Failed to establish new connection. secureSocketStatus=-1. 34 1772 [iot_thread] [mqtt_demo_mutual_auth.c:771] [WARN] [MQTT_MutualAuth_Demo] Connection to the broker failed. Attempting connection retry after backoff delay. 35 2156 [iot_thread] [mqtt_demo_mutual_auth.c:708] [INFO] [MQTT_MutualAuth_Demo] Retry attempt 6 out of maximum retry attempts 5. 36 2156 [iot_thread] [mqtt_demo_mutual_auth.c:763] [INFO] [MQTT_MutualAuth_Demo] Creating a TLS connection to a10y2vqnezxqbn-ats.iot.us-east-1.amazonaws.com:8883. E (22857) PKCS11: failed nvs get file size 4354 0 37 2261 [iot_thread] ERROR: TLS handshake failed trying to connect. SSL - The connection indicated an EOF : 38 2261 [iot_thread] TLS_Connect fail (0x7280, a10y2vqnezxqbn-ats.iot.us-east-1.amazonaws.com) 39 2261 [iot_thread] [transport_secure_sockets.c:343] [ERROR] [Transport_Secure_Sockets] Failed to establish new connection. secureSocketStatus=-1. 40 2263 [iot_thread] [mqtt_demo_mutual_auth.c:771] [WARN] [MQTT_MutualAuth_Demo] Connection to the broker failed. Attempting connection retry after backoff delay. 41 2263 [iot_thread] [mqtt_demo_mutual_auth.c:697] [ERROR] [MQTT_MutualAuth_Demo] All retry attempts have exhausted. Operation will not be retried 42 2263 [iot_thread] [mqtt_demo_mutual_auth.c:641] [INFO] [MQTT_MutualAuth_Demo] Demo failed at iteration 1. 43 2263 [iot_thread] [mqtt_demo_mutual_auth.c:644] [INFO] [MQTT_MutualAuth_Demo] Short delay before starting the next iteration.... 44 2763 [iot_thread] [mqtt_demo_mutual_auth.c:763] [INFO] [MQTT_MutualAuth_Demo] Creating a TLS connection to a10y2vqnezxqbn-ats.iot.us-east-1.amazonaws.com:8883. E (29507) PKCS11: failed nvs get file size 4354 0 45 3220 [iot_thread] ERROR: TLS handshake failed trying to connect. SSL - The connection indicated an EOF : 46 3220 [iot_thread] TLS_Connect fail (0x7280, a10y2vqnezxqbn-ats.iot.us-east-1.amazonaws.com) 47 3220 [iot_thread] [transport_secure_sockets.c:343] [ERROR] [Transport_Secure_Sockets] Failed to establish new connection. secureSocketStatus=-1. 48 3221 [iot_thread] [mqtt_demo_mutual_auth.c:771] [WARN] [MQTT_MutualAuth_Demo] Connection to the broker failed. Attempting connection retry after backoff delay. 49 3270 [iot_thread] [mqtt_demo_mutual_auth.c:708] [INFO] [MQTT_MutualAuth_Demo] Retry attempt 2 out of maximum retry attempts 5. 50 3270 [iot_thread] [mqtt_demo_mutual_auth.c:763] [INFO] [MQTT_MutualAuth_Demo] Creating a TLS connection to a10y2vqnezxqbn-ats.iot.us-east-1.amazonaws.com:8883. E (34037) PKCS11: failed nvs get file size 4354 0 51 3419 [iot_thread] ERROR: TLS handshake failed trying to connect. SSL - The connection indicated an EOF : 52 3419 [iot_thread] TLS_Connect fail (0x7280, a10y2vqnezxqbn-ats.iot.us-east-1.amazonaws.com) 53 3419 [iot_thread] [transport_secure_sockets.c:343] [ERROR] [Transport_Secure_Sockets] Failed to establish new connection. secureSocketStatus=-1. 54 3420 [iot_thread] [mqtt_demo_mutual_auth.c:771] [WARN] [MQTT_MutualAuth_Demo] Connection to the broker failed. Attempting connection retry after backoff delay. 55 3457 [iot_thread] [mqtt_demo_mutual_auth.c:708] [INFO] [MQTT_MutualAuth_Demo] Retry attempt 3 out of maximum retry attempts 5. 56 3457 [iot_thread] [mqtt_demo_mutual_auth.c:763] [INFO] [MQTT_MutualAuth_Demo] Creating a TLS connection to a10y2vqnezxqbn-ats.iot.us-east-1.amazonaws.com:8883. E (36267) PKCS11: failed nvs get file size 4354 0 57 3603 [iot_thread] ERROR: TLS handshake failed trying to connect. SSL - The connection indicated an EOF : 58 3603 [iot_thread] TLS_Connect fail (0x7280, a10y2vqnezxqbn-ats.iot.us-east-1.amazonaws.com) 59 3603 [iot_thread] [transport_secure_sockets.c:343] [ERROR] [Transport_Secure_Sockets] Failed to establish new connection. secureSocketStatus=-1. 60 3603 [iot_thread] [mqtt_demo_mutual_auth.c:771] [WARN] [MQTT_MutualAuth_Demo] Connection to the broker failed. Attempting connection retry after backoff delay. 61 3678 [iot_thread] [mqtt_demo_mutual_auth.c:708] [INFO] [MQTT_MutualAuth_Demo] Retry attempt 4 out of maximum retry attempts 5. 62 3678 [iot_thread] [mqtt_demo_mutual_auth.c:763] [INFO] [MQTT_MutualAuth_Demo] Creating a TLS connection to a10y2vqnezxqbn-ats.iot.us-east-1.amazonaws.com:8883. E (38317) PKCS11: failed nvs get file size 4354 0 63 3808 [iot_thread] ERROR: TLS handshake failed trying to connect. SSL - The connection indicated an EOF : 64 3808 [iot_thread] TLS_Connect fail (0x7280, a10y2vqnezxqbn-ats.iot.us-east-1.amazonaws.com) 65 3808 [iot_thread] [transport_secure_sockets.c:343] [ERROR] [Transport_Secure_Sockets] Failed to establish new connection. secureSocketStatus=-1. 66 3808 [iot_thread] [mqtt_demo_mutual_auth.c:771] [WARN] [MQTT_MutualAuth_Demo] Connection to the broker failed. Attempting connection retry after backoff delay. 67 4003 [iot_thread] [mqtt_demo_mutual_auth.c:708] [INFO] [MQTT_MutualAuth_Demo] Retry attempt 5 out of maximum retry attempts 5. 68 4003 [iot_thread] [mqtt_demo_mutual_auth.c:763] [INFO] [MQTT_MutualAuth_Demo] Creating a TLS connection to a10y2vqnezxqbn-ats.iot.us-east-1.amazonaws.com:8883. E (41927) PKCS11: failed nvs get file size 4354 0 69 4168 [iot_thread] ERROR: TLS handshake failed trying to connect. SSL - The connection indicated an EOF : 70 4168 [iot_thread] TLS_Connect fail (0x7280, a10y2vqnezxqbn-ats.iot.us-east-1.amazonaws.com) 71 4168 [iot_thread] [transport_secure_sockets.c:343] [ERROR] [Transport_Secure_Sockets] Failed to establish new connection. secureSocketStatus=-1. 72 4168 [iot_thread] [mqtt_demo_mutual_auth.c:771] [WARN] [MQTT_MutualAuth_Demo] Connection to the broker failed. Attempting connection retry after backoff delay. 73 4459 [iot_thread] [mqtt_demo_mutual_auth.c:708] [INFO] [MQTT_MutualAuth_Demo] Retry attempt 6 out of maximum retry attempts 5. 74 4459 [iot_thread] [mqtt_demo_mutual_auth.c:763] [INFO] [MQTT_MutualAuth_Demo] Creating a TLS connection to a10y2vqnezxqbn-ats.iot.us-east-1.amazonaws.com:8883. E (45817) PKCS11: failed nvs get file size 4354 0 75 4557 [iot_thread] ERROR: TLS handshake failed trying to connect. SSL - The connection indicated an EOF : 76 4557 [iot_thread] TLS_Connect fail (0x7280, a10y2vqnezxqbn-ats.iot.us-east-1.amazonaws.com) 77 4557 [iot_thread] [transport_secure_sockets.c:343] [ERROR] [Transport_Secure_Sockets] Failed to establish new connection. secureSocketStatus=-1. 78 4558 [iot_thread] [mqtt_demo_mutual_auth.c:771] [WARN] [MQTT_MutualAuth_Demo] Connection to the broker failed. Attempting connection retry after backoff delay. 79 4558 [iot_thread] [mqtt_demo_mutual_auth.c:697] [ERROR] [MQTT_MutualAuth_Demo] All retry attempts have exhausted. Operation will not be retried 80 4558 [iot_thread] [mqtt_demo_mutual_auth.c:641] [INFO] [MQTT_MutualAuth_Demo] Demo failed at iteration 2. 81 4558 [iot_thread] [mqtt_demo_mutual_auth.c:644] [INFO] [MQTT_MutualAuth_Demo] Short delay before starting the next iteration.... 82 5058 [iot_thread] [mqtt_demo_mutual_auth.c:763] [INFO] [MQTT_MutualAuth_Demo] Creating a TLS connection to a10y2vqnezxqbn-ats.iot.us-east-1.amazonaws.com:8883. E (51647) PKCS11: failed nvs get file size 4354 0 83 5140 [iot_thread] ERROR: TLS handshake failed trying to connect. SSL - The connection indicated an EOF : 84 5140 [iot_thread] TLS_Connect fail (0x7280, a10y2vqnezxqbn-ats.iot.us-east-1.amazonaws.com) 85 5140 [iot_thread] [transport_secure_sockets.c:343] [ERROR] [Transport_Secure_Sockets] Failed to establish new connection. secureSocketStatus=-1. 86 5141 [iot_thread] [mqtt_demo_mutual_auth.c:771] [WARN] [MQTT_MutualAuth_Demo] Connection to the broker failed. Attempting connection retry after backoff delay. 87 5169 [iot_thread] [mqtt_demo_mutual_auth.c:708] [INFO] [MQTT_MutualAuth_Demo] Retry attempt 2 out of maximum retry attempts 5. 88 5169 [iot_thread] [mqtt_demo_mutual_auth.c:763] [INFO] [MQTT_MutualAuth_Demo] Creating a TLS connection to a10y2vqnezxqbn-ats.iot.us-east-1.amazonaws.com:8883. E (53157) PKCS11: failed nvs get file size 4354 0 89 5292 [iot_thread] ERROR: TLS handshake failed trying to connect. SSL - The connection indicated an EOF : 90 5292 [iot_thread] TLS_Connect fail (0x7280, a10y2vqnezxqbn-ats.iot.us-east-1.amazonaws.com) 91 5292 [iot_thread] [transport_secure_sockets.c:343] [ERROR] [Transport_Secure_Sockets] Failed to establish new connection. secureSocketStatus=-1. 92 5292 [iot_thread] [mqtt_demo_mutual_auth.c:771] [WARN] [MQTT_MutualAuth_Demo] Connection to the broker failed. Attempting connection retry after backoff delay. 93 5351 [iot_thread] [mqtt_demo_mutual_auth.c:708] [INFO] [MQTT_MutualAuth_Demo] Retry attempt 3 out of maximum retry attempts 5. 94 5351 [iot_thread] [mqtt_demo_mutual_auth.c:763] [INFO] [MQTT_MutualAuth_Demo] Creating a TLS connection to a10y2vqnezxqbn-ats.iot.us-east-1.amazonaws.com:8883. E (54897) PKCS11: failed nvs get file size 4354 0 95 5738 [iot_thread] ERROR: TLS handshake failed trying to connect. SSL - The connection indicated an EOF : 96 5738 [iot_thread] TLS_Connect fail (0x7280, a10y2vqnezxqbn-ats.iot.us-east-1.amazonaws.com) 97 5738 [iot_thread] [transport_secure_sockets.c:343] [ERROR] [Transport_Secure_Sockets] Failed to establish new connection. secureSocketStatus=-1. 98 5739 [iot_thread] [mqtt_demo_mutual_auth.c:771] [WARN] [MQTT_MutualAuth_Demo] Connection to the broker failed. Attempting connection retry after backoff delay. 99 5884 [iot_thread] [mqtt_demo_mutual_auth.c:708] [INFO] [MQTT_MutualAuth_Demo] Retry attempt 4 out of maximum retry attempts 5. 100 5884 [iot_thread] [mqtt_demo_mutual_auth.c:763] [INFO] [MQTT_MutualAuth_Demo] Creating a TLS connection to a10y2vqnezxqbn-ats.iot.us-east-1.amazonaws.com:8883. E (60007) PKCS11: failed nvs get file size 4354 0 101 6238 [iot_thread] ERROR: TLS handshake failed trying to connect. SSL - The connection indicated an EOF : 102 6238 [iot_thread] TLS_Connect fail (0x7280, a10y2vqnezxqbn-ats.iot.us-east-1.amazonaws.com) 103 6238 [iot_thread] [transport_secure_sockets.c:343] [ERROR] [Transport_Secure_Sockets] Failed to establish new connection. secureSocketStatus=-1. 104 6239 [iot_thread] [mqtt_demo_mutual_auth.c:771] [WARN] [MQTT_MutualAuth_Demo] Connection to the broker failed. Attempting connection retry after backoff delay. 105 6528 [iot_thread] [mqtt_demo_mutual_auth.c:708] [INFO] [MQTT_MutualAuth_Demo] Retry attempt 5 out of maximum retry attempts 5. 106 6528 [iot_thread] [mqtt_demo_mutual_auth.c:763] [INFO] [MQTT_MutualAuth_Demo] Creating a TLS connection to a10y2vqnezxqbn-ats.iot.us-east-1.amazonaws.com:8883. E (67007) PKCS11: failed nvs get file size 4354 0 107 6954 [iot_thread] ERROR: TLS handshake failed trying to connect. SSL - The connection indicated an EOF : 108 6954 [iot_thread] TLS_Connect fail (0x7280, a10y2vqnezxqbn-ats.iot.us-east-1.amazonaws.com) 109 6954 [iot_thread] [transport_secure_sockets.c:343] [ERROR] [Transport_Secure_Sockets] Failed to establish new connection. secureSocketStatus=-1. 110 6955 [iot_thread] [mqtt_demo_mutual_auth.c:771] [WARN] [MQTT_MutualAuth_Demo] Connection to the broker failed. Attempting connection retry after backoff delay. 111 7141 [iot_thread] [mqtt_demo_mutual_auth.c:708] [INFO] [MQTT_MutualAuth_Demo] Retry attempt 6 out of maximum retry attempts 5. 112 7141 [iot_thread] [mqtt_demo_mutual_auth.c:763] [INFO] [MQTT_MutualAuth_Demo] Creating a TLS connection to a10y2vqnezxqbn-ats.iot.us-east-1.amazonaws.com:8883. E (73007) PKCS11: failed nvs get file size 4354 0 113 7541 [iot_thread] ERROR: TLS handshake failed trying to connect. SSL - The connection indicated an EOF : 114 7541 [iot_thread] TLS_Connect fail (0x7280, a10y2vqnezxqbn-ats.iot.us-east-1.amazonaws.com) 115 7541 [iot_thread] [transport_secure_sockets.c:343] [ERROR] [Transport_Secure_Sockets] Failed to establish new connection. secureSocketStatus=-1. 116 7541 [iot_thread] [mqtt_demo_mutual_auth.c:771] [WARN] [MQTT_MutualAuth_Demo] Connection to the broker failed. Attempting connection retry after backoff delay. 117 7543 [iot_thread] [mqtt_demo_mutual_auth.c:697] [ERROR] [MQTT_MutualAuth_Demo] All retry attempts have exhausted. Operation will not be retried 118 7543 [iot_thread] [mqtt_demo_mutual_auth.c:641] [INFO] [MQTT_MutualAuth_Demo] Demo failed at iteration 3. 119 7543 [iot_thread] [mqtt_demo_mutual_auth.c:644] [INFO] [MQTT_MutualAuth_Demo] Short delay before starting the next iteration.... 120 8043 [iot_thread] [mqtt_demo_mutual_auth.c:664] [INFO] [MQTT_MutualAuth_Demo] Demo run failed with 3 failed loops out of total 3 loops. RequiredSuccessCounts=2. 121 8043 [iot_thread] [INFO ][DEMO][80430] memory_metrics::freertos_heap::before::bytes::223760 122 8043 [iot_thread] [INFO ][DEMO][80430] memory_metrics::freertos_heap::after::bytes::90788 123 8043 [iot_thread] [INFO ][DEMO][80430] memory_metrics::demo_task_stack::before::bytes::5848 124 8043 [iot_thread] [INFO ][DEMO][80430] memory_metrics::demo_task_stack::after::bytes::2504 I (82177) wifi:state: run -> init (0) I (82177) wifi:pm stop, total sleep time: 36387666 us / 80323361 us I (82177) wifi:new:<1,0>, old:<1,0>, ap:<255,255>, sta:<1,0>, prof:1 I (82177) WIFI: WIFI_EVENT_STA_DISCONNECTED: 63 125 8143 [iot_thread] [ERROR][DEMO][81430] Error running demo. E (82187) wifi_init: Wi-Fi not stop I (82197) WIFI: WIFI_EVENT_STA_STOP I (82267) wifi:flush txq I (82267) wifi:stop sw txq I (82267) wifi:lmac stop hw txq I (82267) wifi:Deinit lldesc rx mblock:10 GAP procedure initiated: stop advertising. GAP procedure initiated: stop advertising. 126 8154 [iot_thread] [INFO ][INIT][81540] SDK cleanup done. 127 8154 [iot_thread] [INFO ][DEMO][81540] -------DEMO FINISHED------- ```
Expected Output ``` I (29) boot: ESP-IDF v4.2.2-273-g9e3992ead 2nd stage bootloader I (29) boot: compile time 17:05:32 I (29) boot: chip revision: 3 I (33) boot_comm: chip revision: 3, min. bootloader chip revision: 0 I (41) boot.esp32: SPI Speed : 40MHz I (45) boot.esp32: SPI Mode : DIO I (49) boot.esp32: SPI Flash Size : 4MB I (54) boot: Enabling RNG early entropy source... I (59) boot: Partition Table: I (63) boot: ## Label Usage Type ST Offset Length I (70) boot: 0 nvs WiFi data 01 02 00010000 00006000 I (78) boot: 1 otadata OTA data 01 00 00016000 00002000 I (85) boot: 2 phy_init RF data 01 01 00018000 00001000 I (93) boot: 3 ota_0 OTA app 00 10 00020000 00177000 I (100) boot: 4 ota_1 OTA app 00 11 001a0000 00177000 I (108) boot: 5 storage WiFi data 01 02 00317000 00010000 I (115) boot: End of partition table I (120) boot: No factory image, trying OTA 0 I (124) boot_comm: chip revision: 3, min. application chip revision: 0 I (132) esp_image: segment 0: paddr=0x00020020 vaddr=0x3f400020 size=0x29180 (168320) map I (205) esp_image: segment 1: paddr=0x000491a8 vaddr=0x3ffbdb60 size=0x03994 ( 14740) load I (211) esp_image: segment 2: paddr=0x0004cb44 vaddr=0x40080000 size=0x034d4 ( 13524) load 0x40080000: _WindowOverflow4 at /home/laukik/work/amazon-freertos/build/../freertos_kernel/portable/ThirdParty/GCC/Xtensa_ESP32/xtensa_vectors.S:1860 I (218) esp_image: segment 3: paddr=0x00050020 vaddr=0x400d0020 size=0xa8ed8 (691928) map 0x400d0020: _stext at ??:? I (484) esp_image: segment 4: paddr=0x000f8f00 vaddr=0x400834d4 size=0x197c8 (104392) load 0x400834d4: detect_spi_flash_chip at /home/laukik/work/amazon-freertos/build/../vendors/espressif/esp-idf/components/spi_flash/esp_flash_api.c:222 (discriminator 13) I (545) boot: Loaded app from partition at offset 0x20000 I (617) boot: Set actual ota_seq=1 in otadata[0] I (617) boot: Disabling RNG early entropy source... I (618) cpu_start: Pro cpu up. I (621) cpu_start: Application information: I (626) cpu_start: Project name: amazon-freertos I (631) cpu_start: App version: 1 I (636) cpu_start: Compile time: Aug 8 2022 17:05:18 I (642) cpu_start: ELF file SHA256: f7d404890b128cfb... I (648) cpu_start: ESP-IDF: v4.2.2-273-g9e3992ead I (654) cpu_start: Single core mode I (658) heap_init: Initializing. RAM available for dynamic allocation: I (665) heap_init: At 3FF80000 len 00002000 (8 KiB): RTCRAM I (671) heap_init: At 3FFAFF10 len 000000F0 (0 KiB): DRAM I (678) heap_init: At 3FFB6388 len 00001C78 (7 KiB): DRAM I (684) heap_init: At 3FFB9A20 len 00004108 (16 KiB): DRAM I (690) heap_init: At 3FFCA380 len 00015C80 (87 KiB): DRAM I (696) heap_init: At 3FFE0440 len 0001FBC0 (126 KiB): D/IRAM I (702) heap_init: At 40078000 len 00008000 (32 KiB): IRAM I (709) heap_init: At 4009CC9C len 00003364 (12 KiB): IRAM I (715) cpu_start: Pro cpu start user code I (732) spi_flash: detected chip: generic I (733) spi_flash: flash io0 0 [main] Initializing lwIP TCP stack I (753) PKCS11: Initializing NVS partition: "storage" E (803) PKCS11: failed nvs get file size 4354 0 1 14 [main] Write certificate... 2 28 [iot_thread] [INFO ][DEMO][280] ---------STARTING DEMO--------- I (1023) BTDM_INIT: BT controller compile version [bfbbe1e] 3 28 [iot_thread] [INFO ][INIT][280] SDK successfully initialized. I (1033) system_api: Base MAC address is not set I (1033) system_api: read default base MAC address from EFUSE I (1043) phy_init: phy_version 4660,0162888,Dec 23 2020 GAP procedure initiated: advertise; disc_mode=2 adv_channel_map=0 own_addr_type=0 adv_filter_policy=0 adv_itvl_min=187 adv_itvl_max=375 I (1443) wifi:wifi driver task: 3ffd7234, prio:23, stack:6656, core=0 I (1443) wifi:wifi firmware version: df5b09d I (1443) wifi:wifi certification version: v7.0 I (1443) wifi:config NVS flash: enabled I (1443) wifi:config nano formating: disabled I (1453) wifi:Init data frame dynamic rx buffer num: 32 I (1453) wifi:Init management frame dynamic rx buffer num: 32 I (1463) wifi:Init management short buffer num: 32 I (1463) wifi:Init dynamic tx buffer num: 32 I (1473) wifi:Init static rx buffer size: 1600 I (1473) wifi:Init static rx buffer num: 10 I (1473) wifi:Init dynamic rx buffer num: 32 I (1483) wifi_init: rx ba win: 6 I (1483) wifi_init: tcpip mbox: 32 I (1493) wifi_init: udp mbox: 6 I (1493) wifi_init: tcp mbox: 6 I (1493) wifi_init: tcp tx win: 5744 I (1503) wifi_init: tcp rx win: 5744 I (1503) wifi_init: tcp mss: 1440 I (1513) wifi_init: WiFi IRAM OP enabled I (1513) wifi_init: WiFi RX IRAM OP enabled I (1523) phy_init: phy_version 4660,0162888,Dec 23 2020 I (1533) wifi:mode : sta (3c:61:05:4c:33:e8) I (1533) WIFI: WIFI_EVENT_STA_START I (1543) wifi:new:<1,0>, old:<1,0>, ap:<255,255>, sta:<1,0>, prof:1 I (2023) wifi:state: init -> auth (b0) I (2023) wifi:state: auth -> assoc (0) I (3033) wifi:state: assoc -> init (400) I (3033) wifi:new:<1,0>, old:<1,0>, ap:<255,255>, sta:<1,0>, prof:1 I (3033) WIFI: WIFI_EVENT_STA_DISCONNECTED: 63 4 229 [sys_evt] [INFO ][DEMO][2290] Disconnected from WiFi access point, reason code: 0. I (4073) wifi:new:<1,0>, old:<1,0>, ap:<255,255>, sta:<1,0>, prof:1 I (4073) wifi:state: init -> auth (b0) I (4073) wifi:state: auth -> assoc (0) I (4083) wifi:state: assoc -> run (10) I (4133) wifi:connected with ES_Staff, aid = 1, channel 1, BW20, bssid = 68:d7:9a:7d:6c:24 I (4133) wifi:security: WPA2-PSK, phy: bgn, rssi: -70 I (4143) wifi:pm start, type: 1 I (4143) WIFI: WIFI_EVENT_STA_CONNECTED I (4173) wifi:AP's beacon interval = 102400 us, DTIM period = 1 I (4743) esp_netif_handlers: sta ip: 192.168.20.234, mask: 255.255.255.0, gw: 192.168.20.1 I (4743) WIFI: SYSTEM_EVENT_STA_GOT_IP 5 400 [sys_evt] [INFO ][DEMO][4000] Connected to WiFi access point, ip address: 255.255.255.0. 6 400 [iot_thread] [INFO ][DEMO][4000] Successfully initialized the demo. Network type for the demo: 1 7 400 [iot_thread] [mqtt_demo_mutual_auth.c:763] [INFO] [MQTT_MutualAuth_Demo] Creating a TLS connection to a10y2vqnezxqbn-ats.iot.us-east-1.amazonaws.com:8883. 8 403 [NetworkManager] [INFO ][DEMO][4030] Invoked callback for network state change event. 9 405 [NetworkManager] [INFO ][DEMO][4050] Invoked callback for network state change event. GAP procedure initiated: stop advertising. GAP procedure initiated: stop advertising. E (5373) PKCS11: failed nvs get file size 4354 0 10 825 [iot_thread] [mqtt_demo_mutual_auth.c:531] [INFO] [MQTT_MutualAuth_Demo] Creating an MQTT connection to a10y2vqnezxqbn-ats.iot.us-east-1.amazonaws.com. 11 855 [iot_thread] [core_mqtt.c:886] [INFO] [MQTT] Packet received. ReceivedBytes=2. 12 855 [iot_thread] [core_mqtt_serializer.c:970] [INFO] [MQTT] CONNACK session present bit not set. 13 855 [iot_thread] [core_mqtt_serializer.c:912] [INFO] [MQTT] Connection accepted. 14 855 [iot_thread] [core_mqtt.c:1563] [INFO] [MQTT] Received MQTT CONNACK successfully from broker. 15 855 [iot_thread] [core_mqtt.c:1829] [INFO] [MQTT] MQTT connection established with the broker. 16 855 [iot_thread] [mqtt_demo_mutual_auth.c:843] [INFO] [MQTT_MutualAuth_Demo] An MQTT connection is established with a10y2vqnezxqbn-ats.iot.us-east-1.amazonaws.com. 17 855 [iot_thread] [mqtt_demo_mutual_auth.c:908] [INFO] [MQTT_MutualAuth_Demo] Attempt to subscribe to the MQTT topic afr_ota_test/example/topic. 18 855 [iot_thread] [mqtt_demo_mutual_auth.c:922] [INFO] [MQTT_MutualAuth_Demo] SUBSCRIBE sent for topic afr_ota_test/example/topic to broker. 19 926 [iot_thread] [core_mqtt.c:886] [INFO] [MQTT] Packet received. ReceivedBytes=3. 20 926 [iot_thread] [mqtt_demo_mutual_auth.c:1076] [INFO] [MQTT_MutualAuth_Demo] Subscribed to the topic afr_ota_test/example/topic with maximum QoS 1. 21 926 [iot_thread] [mqtt_demo_mutual_auth.c:552] [INFO] [MQTT_MutualAuth_Demo] Publish to the MQTT topic afr_ota_test/example/topic. 22 929 [iot_thread] [mqtt_demo_mutual_auth.c:562] [INFO] [MQTT_MutualAuth_Demo] Attempt to receive publish message from broker. 23 1035 [iot_thread] [core_mqtt.c:886] [INFO] [MQTT] Packet received. ReceivedBytes=2. 24 1035 [iot_thread] [core_mqtt.c:1162] [INFO] [MQTT] Ack packet deserialized with result: MQTTSuccess. 25 1035 [iot_thread] [core_mqtt.c:1175] [INFO] [MQTT] State record updated. New state=MQTTPublishDone. 26 1035 [iot_thread] [mqtt_demo_mutual_auth.c:1054] [INFO] [MQTT_MutualAuth_Demo] PUBACK received for packet Id 2. 27 1036 [iot_thread] [core_mqtt.c:886] [INFO] [MQTT] Packet received. ReceivedBytes=42. 28 1036 [iot_thread] [core_mqtt.c:1045] [INFO] [MQTT] De-serialized incoming PUBLISH packet: DeserializerResult=MQTTSuccess. 29 1036 [iot_thread] [core_mqtt.c:1058] [INFO] [MQTT] State record updated. New state=MQTTPubAckSend. 30 1036 [iot_thread] [mqtt_demo_mutual_auth.c:1116] [INFO] [MQTT_MutualAuth_Demo] Incoming QoS : 1 31 1036 [iot_thread] [mqtt_demo_mutual_auth.c:1127] [INFO] [MQTT_MutualAuth_Demo] Incoming Publish Topic Name: afr_ota_test/example/topic matches subscribed topic.Incoming Publish Message : H32 1136 [iot_thread] [mqtt_demo_mutual_auth.c:572] [INFO] [MQTT_MutualAuth_Demo] Keeping Connection Idle... 33 1336 [iot_thread] [mqtt_demo_mutual_auth.c:552] [INFO] [MQTT_MutualAuth_Demo] Publish to the MQTT topic afr_ota_test/example/topic. 34 1336 [iot_thread] [mqtt_demo_mutual_auth.c:562] [INFO] [MQTT_MutualAuth_Demo] Attempt to receive publish message from broker. 35 1429 [iot_thread] [core_mqtt.c:886] [INFO] [MQTT] Packet received. ReceivedBytes=2. 36 1429 [iot_thread] [core_mqtt.c:1162] [INFO] [MQTT] Ack packet deserialized with result: MQTTSuccess. 37 1429 [iot_thread] [core_mqtt.c:1175] [INFO] [MQTT] State record updated. New state=MQTTPublishDone. 38 1429 [iot_thread] [mqtt_demo_mutual_auth.c:1054] [INFO] [MQTT_MutualAuth_Demo] PUBACK received for packet Id 3. 39 1430 [iot_thread] [core_mqtt.c:886] [INFO] [MQTT] Packet received. ReceivedBytes=42. 40 1430 [iot_thread] [core_mqtt.c:1045] [INFO] [MQTT] De-serialized incoming PUBLISH packet: DeserializerResult=MQTTSuccess. 41 1430 [iot_thread] [core_mqtt.c:1058] [INFO] [MQTT] State record updated. New state=MQTTPubAckSend. 42 1430 [iot_thread] [mqtt_demo_mutual_auth.c:1116] [INFO] [MQTT_MutualAuth_Demo] Incoming QoS : 1 43 1430 [iot_thread] [mqtt_demo_mutual_auth.c:1127] [INFO] [MQTT_MutualAuth_Demo] Incoming Publish Topic Name: afr_ota_test/example/topic matches subscribed topic.Incoming Publish Message : H44 1530 [iot_thread] [mqtt_demo_mutual_auth.c:572] [INFO] [MQTT_MutualAuth_Demo] Keeping Connection Idle... 45 1730 [iot_thread] [mqtt_demo_mutual_auth.c:552] [INFO] [MQTT_MutualAuth_Demo] Publish to the MQTT topic afr_ota_test/example/topic. 46 1730 [iot_thread] [mqtt_demo_mutual_auth.c:562] [INFO] [MQTT_MutualAuth_Demo] Attempt to receive publish message from broker. 47 1891 [iot_thread] [core_mqtt.c:886] [INFO] [MQTT] Packet received. ReceivedBytes=2. 48 1891 [iot_thread] [core_mqtt.c:1162] [INFO] [MQTT] Ack packet deserialized with result: MQTTSuccess. 49 1891 [iot_thread] [core_mqtt.c:1175] [INFO] [MQTT] State record updated. New state=MQTTPublishDone. 50 1891 [iot_thread] [mqtt_demo_mutual_auth.c:1054] [INFO] [MQTT_MutualAuth_Demo] PUBACK received for packet Id 4. 51 1893 [iot_thread] [core_mqtt.c:886] [INFO] [MQTT] Packet received. ReceivedBytes=42. 52 1893 [iot_thread] [core_mqtt.c:1045] [INFO] [MQTT] De-serialized incoming PUBLISH packet: DeserializerResult=MQTTSuccess. 53 1893 [iot_thread] [core_mqtt.c:1058] [INFO] [MQTT] State record updated. New state=MQTTPubAckSend. 54 1893 [iot_thread] [mqtt_demo_mutual_auth.c:1116] [INFO] [MQTT_MutualAuth_Demo] Incoming QoS : 1 55 1893 [iot_thread] [mqtt_demo_mutual_auth.c:1127] [INFO] [MQTT_MutualAuth_Demo] Incoming Publish Topic Name: afr_ota_test/example/topic matches subscribed topic.Incoming Publish Message : H56 1943 [iot_thread] [mqtt_demo_mutual_auth.c:572] [INFO] [MQTT_MutualAuth_Demo] Keeping Connection Idle... 57 2143 [iot_thread] [mqtt_demo_mutual_auth.c:552] [INFO] [MQTT_MutualAuth_Demo] Publish to the MQTT topic afr_ota_test/example/topic. 58 2143 [iot_thread] [mqtt_demo_mutual_auth.c:562] [INFO] [MQTT_MutualAuth_Demo] Attempt to receive publish message from broker. 59 2237 [iot_thread] [core_mqtt.c:886] [INFO] [MQTT] Packet received. ReceivedBytes=2. 60 2237 [iot_thread] [core_mqtt.c:1162] [INFO] [MQTT] Ack packet deserialized with result: MQTTSuccess. 61 2237 [iot_thread] [core_mqtt.c:1175] [INFO] [MQTT] State record updated. New state=MQTTPublishDone. 62 2237 [iot_thread] [mqtt_demo_mutual_auth.c:1054] [INFO] [MQTT_MutualAuth_Demo] PUBACK received for packet Id 5. 63 2239 [iot_thread] [core_mqtt.c:886] [INFO] [MQTT] Packet received. ReceivedBytes=42. 64 2239 [iot_thread] [core_mqtt.c:1045] [INFO] [MQTT] De-serialized incoming PUBLISH packet: DeserializerResult=MQTTSuccess. 65 2239 [iot_thread] [core_mqtt.c:1058] [INFO] [MQTT] State record updated. New state=MQTTPubAckSend. 66 2239 [iot_thread] [mqtt_demo_mutual_auth.c:1116] [INFO] [MQTT_MutualAuth_Demo] Incoming QoS : 1 67 2239 [iot_thread] [mqtt_demo_mutual_auth.c:1127] [INFO] [MQTT_MutualAuth_Demo] Incoming Publish Topic Name: afr_ota_test/example/topic matches subscribed topic.Incoming Publish Message : H68 2339 [iot_thread] [mqtt_demo_mutual_auth.c:572] [INFO] [MQTT_MutualAuth_Demo] Keeping Connection Idle... 69 2539 [iot_thread] [mqtt_demo_mutual_auth.c:552] [INFO] [MQTT_MutualAuth_Demo] Publish to the MQTT topic afr_ota_test/example/topic. 70 2539 [iot_thread] [mqtt_demo_mutual_auth.c:562] [INFO] [MQTT_MutualAuth_Demo] Attempt to receive publish message from broker. 71 2596 [iot_thread] [core_mqtt.c:886] [INFO] [MQTT] Packet received. ReceivedBytes=2. 72 2596 [iot_thread] [core_mqtt.c:1162] [INFO] [MQTT] Ack packet deserialized with result: MQTTSuccess. 73 2596 [iot_thread] [core_mqtt.c:1175] [INFO] [MQTT] State record updated. New state=MQTTPublishDone. 74 2596 [iot_thread] [mqtt_demo_mutual_auth.c:1054] [INFO] [MQTT_MutualAuth_Demo] PUBACK received for packet Id 6. 75 2598 [iot_thread] [core_mqtt.c:886] [INFO] [MQTT] Packet received. ReceivedBytes=42. 76 2598 [iot_thread] [core_mqtt.c:1045] [INFO] [MQTT] De-serialized incoming PUBLISH packet: DeserializerResult=MQTTSuccess. 77 2598 [iot_thread] [core_mqtt.c:1058] [INFO] [MQTT] State record updated. New state=MQTTPubAckSend. 78 2598 [iot_thread] [mqtt_demo_mutual_auth.c:1116] [INFO] [MQTT_MutualAuth_Demo] Incoming QoS : 1 79 2598 [iot_thread] [mqtt_demo_mutual_auth.c:1127] [INFO] [MQTT_MutualAuth_Demo] Incoming Publish Topic Name: afr_ota_test/example/topic matches subscribed topic.Incoming Publish Message : H80 2648 [iot_thread] [mqtt_demo_mutual_auth.c:572] [INFO] [MQTT_MutualAuth_Demo] Keeping Connection Idle... 81 2848 [iot_thread] [mqtt_demo_mutual_auth.c:580] [INFO] [MQTT_MutualAuth_Demo] Unsubscribe from the MQTT topic afr_ota_test/example/topic. 82 2892 [iot_thread] [core_mqtt.c:886] [INFO] [MQTT] Packet received. ReceivedBytes=2. 83 2892 [iot_thread] [mqtt_demo_mutual_auth.c:1085] [INFO] [MQTT_MutualAuth_Demo] Unsubscribed from the topic afr_ota_test/example/topic. 84 2942 [iot_thread] [mqtt_demo_mutual_auth.c:602] [INFO] [MQTT_MutualAuth_Demo] Disconnecting the MQTT connection with a10y2vqnezxqbn-ats.iot.us-east-1.amazonaws.com. 85 2942 [iot_thread] [core_mqtt.c:2149] [INFO] [MQTT] Disconnected from the broker. 86 2943 [iot_thread] [mqtt_demo_mutual_auth.c:631] [INFO] [MQTT_MutualAuth_Demo] Demo completed an iteration successfully. 87 2943 [iot_thread] [mqtt_demo_mutual_auth.c:632] [INFO] [MQTT_MutualAuth_Demo] Demo iteration 1 completed successfully. 88 2943 [iot_thread] [mqtt_demo_mutual_auth.c:644] [INFO] [MQTT_MutualAuth_Demo] Short delay before starting the next iteration.... 89 3443 [iot_thread] [mqtt_demo_mutual_auth.c:763] [INFO] [MQTT_MutualAuth_Demo] Creating a TLS connection to a10y2vqnezxqbn-ats.iot.us-east-1.amazonaws.com:8883. E (35713) PKCS11: failed nvs get file size 4354 0 90 3867 [iot_thread] [mqtt_demo_mutual_auth.c:531] [INFO] [MQTT_MutualAuth_Demo] Creating an MQTT connection to a10y2vqnezxqbn-ats.iot.us-east-1.amazonaws.com. 91 3906 [iot_thread] [core_mqtt.c:886] [INFO] [MQTT] Packet received. ReceivedBytes=2. 92 3906 [iot_thread] [core_mqtt_serializer.c:970] [INFO] [MQTT] CONNACK session present bit not set. 93 3906 [iot_thread] [core_mqtt_serializer.c:912] [INFO] [MQTT] Connection accepted. 94 3906 [iot_thread] [core_mqtt.c:1563] [INFO] [MQTT] Received MQTT CONNACK successfully from broker. 95 3906 [iot_thread] [core_mqtt.c:1829] [INFO] [MQTT] MQTT connection established with the broker. 96 3906 [iot_thread] [mqtt_demo_mutual_auth.c:843] [INFO] [MQTT_MutualAuth_Demo] An MQTT connection is established with a10y2vqnezxqbn-ats.iot.us-east-1.amazonaws.com. 97 3906 [iot_thread] [mqtt_demo_mutual_auth.c:908] [INFO] [MQTT_MutualAuth_Demo] Attempt to subscribe to the MQTT topic afr_ota_test/example/topic. 98 3907 [iot_thread] [mqtt_demo_mutual_auth.c:922] [INFO] [MQTT_MutualAuth_Demo] SUBSCRIBE sent for topic afr_ota_test/example/topic to broker. 99 3937 [iot_thread] [core_mqtt.c:886] [INFO] [MQTT] Packet received. ReceivedBytes=3. 100 3937 [iot_thread] [mqtt_demo_mutual_auth.c:1076] [INFO] [MQTT_MutualAuth_Demo] Subscribed to the topic afr_ota_test/example/topic with maximum QoS 1. 101 3987 [iot_thread] [mqtt_demo_mutual_auth.c:552] [INFO] [MQTT_MutualAuth_Demo] Publish to the MQTT topic afr_ota_test/example/topic. 102 3987 [iot_thread] [mqtt_demo_mutual_auth.c:562] [INFO] [MQTT_MutualAuth_Demo] Attempt to receive publish message from broker. 103 4062 [iot_thread] [core_mqtt.c:886] [INFO] [MQTT] Packet received. ReceivedBytes=2. 104 4062 [iot_thread] [core_mqtt.c:1162] [INFO] [MQTT] Ack packet deserialized with result: MQTTSuccess. 105 4062 [iot_thread] [core_mqtt.c:1175] [INFO] [MQTT] State record updated. New state=MQTTPublishDone. 106 4062 [iot_thread] [mqtt_demo_mutual_auth.c:1054] [INFO] [MQTT_MutualAuth_Demo] PUBACK received for packet Id 2. 107 4065 [iot_thread] [core_mqtt.c:886] [INFO] [MQTT] Packet received. ReceivedBytes=42. 108 4065 [iot_thread] [core_mqtt.c:1045] [INFO] [MQTT] De-serialized incoming PUBLISH packet: DeserializerResult=MQTTSuccess. 109 4065 [iot_thread] [core_mqtt.c:1058] [INFO] [MQTT] State record updated. New state=MQTTPubAckSend. 110 4065 [iot_thread] [mqtt_demo_mutual_auth.c:1116] [INFO] [MQTT_MutualAuth_Demo] Incoming QoS : 1 111 4065 [iot_thread] [mqtt_demo_mutual_auth.c:1127] [INFO] [MQTT_MutualAuth_Demo] Incoming Publish Topic Name: afr_ota_test/example/topic matches subscribed topic.Incoming Publish Message : 112 4165 [iot_thread] [mqtt_demo_mutual_auth.c:572] [INFO] [MQTT_MutualAuth_Demo] Keeping Connection Idle... 113 4365 [iot_thread] [mqtt_demo_mutual_auth.c:552] [INFO] [MQTT_MutualAuth_Demo] Publish to the MQTT topic afr_ota_test/example/topic. 114 4365 [iot_thread] [mqtt_demo_mutual_auth.c:562] [INFO] [MQTT_MutualAuth_Demo] Attempt to receive publish message from broker. 115 4432 [iot_thread] [core_mqtt.c:886] [INFO] [MQTT] Packet received. ReceivedBytes=2. 116 4432 [iot_thread] [core_mqtt.c:1162] [INFO] [MQTT] Ack packet deserialized with result: MQTTSuccess. 117 4432 [iot_thread] [core_mqtt.c:1175] [INFO] [MQTT] State record updated. New state=MQTTPublishDone. 118 4432 [iot_thread] [mqtt_demo_mutual_auth.c:1054] [INFO] [MQTT_MutualAuth_Demo] PUBACK received for packet Id 3. 119 4433 [iot_thread] [core_mqtt.c:886] [INFO] [MQTT] Packet received. ReceivedBytes=42. 120 4433 [iot_thread] [core_mqtt.c:1045] [INFO] [MQTT] De-serialized incoming PUBLISH packet: DeserializerResult=MQTTSuccess. 121 4433 [iot_thread] [core_mqtt.c:1058] [INFO] [MQTT] State record updated. New state=MQTTPubAckSend. 122 4433 [iot_thread] [mqtt_demo_mutual_auth.c:1116] [INFO] [MQTT_MutualAuth_Demo] Incoming QoS : 1 123 4433 [iot_thread] [mqtt_demo_mutual_auth.c:1127] [INFO] [MQTT_MutualAuth_Demo] Incoming Publish Topic Name: afr_ota_test/example/topic matches subscribed topic.Incoming Publish Message : 124 4435 [iot_thread] [mqtt_demo_mutual_auth.c:572] [INFO] [MQTT_MutualAuth_Demo] Keeping Connection Idle... 125 4635 [iot_thread] [mqtt_demo_mutual_auth.c:552] [INFO] [MQTT_MutualAuth_Demo] Publish to the MQTT topic afr_ota_test/example/topic. 126 4635 [iot_thread] [mqtt_demo_mutual_auth.c:562] [INFO] [MQTT_MutualAuth_Demo] Attempt to receive publish message from broker. 127 4758 [iot_thread] [core_mqtt.c:886] [INFO] [MQTT] Packet received. ReceivedBytes=2. 128 4758 [iot_thread] [core_mqtt.c:1162] [INFO] [MQTT] Ack packet deserialized with result: MQTTSuccess. 129 4758 [iot_thread] [core_mqtt.c:1175] [INFO] [MQTT] State record updated. New state=MQTTPublishDone. 130 4758 [iot_thread] [mqtt_demo_mutual_auth.c:1054] [INFO] [MQTT_MutualAuth_Demo] PUBACK received for packet Id 4. 131 4759 [iot_thread] [core_mqtt.c:886] [INFO] [MQTT] Packet received. ReceivedBytes=42. 132 4759 [iot_thread] [core_mqtt.c:1045] [INFO] [MQTT] De-serialized incoming PUBLISH packet: DeserializerResult=MQTTSuccess. 133 4759 [iot_thread] [core_mqtt.c:1058] [INFO] [MQTT] State record updated. New state=MQTTPubAckSend. 134 4759 [iot_thread] [mqtt_demo_mutual_auth.c:1116] [INFO] [MQTT_MutualAuth_Demo] Incoming QoS : 1 135 4759 [iot_thread] [mqtt_demo_mutual_auth.c:1127] [INFO] [MQTT_MutualAuth_Demo] Incoming Publish Topic Name: afr_ota_test/example/topic matches subscribed topic.Incoming Publish Message : 136 4809 [iot_thread] [mqtt_demo_mutual_auth.c:572] [INFO] [MQTT_MutualAuth_Demo] Keeping Connection Idle... 137 5009 [iot_thread] [mqtt_demo_mutual_auth.c:552] [INFO] [MQTT_MutualAuth_Demo] Publish to the MQTT topic afr_ota_test/example/topic. 138 5009 [iot_thread] [mqtt_demo_mutual_auth.c:562] [INFO] [MQTT_MutualAuth_Demo] Attempt to receive publish message from broker. 139 5081 [iot_thread] [core_mqtt.c:886] [INFO] [MQTT] Packet received. ReceivedBytes=2. 140 5082 [iot_thread] [core_mqtt.c:1162] [INFO] [MQTT] Ack packet deserialized with result: MQTTSuccess. 141 5082 [iot_thread] [core_mqtt.c:1175] [INFO] [MQTT] State record updated. New state=MQTTPublishDone. 142 5082 [iot_thread] [mqtt_demo_mutual_auth.c:1054] [INFO] [MQTT_MutualAuth_Demo] PUBACK received for packet Id 5. 143 5084 [iot_thread] [core_mqtt.c:886] [INFO] [MQTT] Packet received. ReceivedBytes=42. 144 5084 [iot_thread] [core_mqtt.c:1045] [INFO] [MQTT] De-serialized incoming PUBLISH packet: DeserializerResult=MQTTSuccess. 145 5084 [iot_thread] [core_mqtt.c:1058] [INFO] [MQTT] State record updated. New state=MQTTPubAckSend. 146 5084 [iot_thread] [mqtt_demo_mutual_auth.c:1116] [INFO] [MQTT_MutualAuth_Demo] Incoming QoS : 1 147 5084 [iot_thread] [mqtt_demo_mutual_auth.c:1127] [INFO] [MQTT_MutualAuth_Demo] Incoming Publish Topic Name: afr_ota_test/example/topic matches subscribed topic.Incoming Publish Message : 148 5184 [iot_thread] [mqtt_demo_mutual_auth.c:572] [INFO] [MQTT_MutualAuth_Demo] Keeping Connection Idle... 149 5384 [iot_thread] [mqtt_demo_mutual_auth.c:552] [INFO] [MQTT_MutualAuth_Demo] Publish to the MQTT topic afr_ota_test/example/topic. 150 5384 [iot_thread] [mqtt_demo_mutual_auth.c:562] [INFO] [MQTT_MutualAuth_Demo] Attempt to receive publish message from broker. 151 5473 [iot_thread] [core_mqtt.c:886] [INFO] [MQTT] Packet received. ReceivedBytes=2. 152 5473 [iot_thread] [core_mqtt.c:1162] [INFO] [MQTT] Ack packet deserialized with result: MQTTSuccess. 153 5473 [iot_thread] [core_mqtt.c:1175] [INFO] [MQTT] State record updated. New state=MQTTPublishDone. 154 5473 [iot_thread] [mqtt_demo_mutual_auth.c:1054] [INFO] [MQTT_MutualAuth_Demo] PUBACK received for packet Id 6. 155 5475 [iot_thread] [core_mqtt.c:886] [INFO] [MQTT] Packet received. ReceivedBytes=42. 156 5475 [iot_thread] [core_mqtt.c:1045] [INFO] [MQTT] De-serialized incoming PUBLISH packet: DeserializerResult=MQTTSuccess. 157 5475 [iot_thread] [core_mqtt.c:1058] [INFO] [MQTT] State record updated. New state=MQTTPubAckSend. 158 5475 [iot_thread] [mqtt_demo_mutual_auth.c:1116] [INFO] [MQTT_MutualAuth_Demo] Incoming QoS : 1 159 5475 [iot_thread] [mqtt_demo_mutual_auth.c:1127] [INFO] [MQTT_MutualAuth_Demo] Incoming Publish Topic Name: afr_ota_test/example/topic matches subscribed topic.Incoming Publish Message : 160 5575 [iot_thread] [mqtt_demo_mutual_auth.c:572] [INFO] [MQTT_MutualAuth_Demo] Keeping Connection Idle... 161 5775 [iot_thread] [mqtt_demo_mutual_auth.c:580] [INFO] [MQTT_MutualAuth_Demo] Unsubscribe from the MQTT topic afr_ota_test/example/topic. 162 5800 [iot_thread] [core_mqtt.c:886] [INFO] [MQTT] Packet received. ReceivedBytes=2. 163 5800 [iot_thread] [mqtt_demo_mutual_auth.c:1085] [INFO] [MQTT_MutualAuth_Demo] Unsubscribed from the topic afr_ota_test/example/topic. 164 5850 [iot_thread] [mqtt_demo_mutual_auth.c:602] [INFO] [MQTT_MutualAuth_Demo] Disconnecting the MQTT connection with a10y2vqnezxqbn-ats.iot.us-east-1.amazonaws.com. 165 5850 [iot_thread] [core_mqtt.c:2149] [INFO] [MQTT] Disconnected from the broker. 166 5851 [iot_thread] [mqtt_demo_mutual_auth.c:631] [INFO] [MQTT_MutualAuth_Demo] Demo completed an iteration successfully. 167 5851 [iot_thread] [mqtt_demo_mutual_auth.c:632] [INFO] [MQTT_MutualAuth_Demo] Demo iteration 2 completed successfully. 168 5851 [iot_thread] [mqtt_demo_mutual_auth.c:644] [INFO] [MQTT_MutualAuth_Demo] Short delay before starting the next iteration.... 169 6351 [iot_thread] [mqtt_demo_mutual_auth.c:763] [INFO] [MQTT_MutualAuth_Demo] Creating a TLS connection to a10y2vqnezxqbn-ats.iot.us-east-1.amazonaws.com:8883. E (64733) PKCS11: failed nvs get file size 4354 0 170 6760 [iot_thread] [mqtt_demo_mutual_auth.c:531] [INFO] [MQTT_MutualAuth_Demo] Creating an MQTT connection to a10y2vqnezxqbn-ats.iot.us-east-1.amazonaws.com. 171 6801 [iot_thread] [core_mqtt.c:886] [INFO] [MQTT] Packet received. ReceivedBytes=2. 172 6801 [iot_thread] [core_mqtt_serializer.c:970] [INFO] [MQTT] CONNACK session present bit not set. 173 6801 [iot_thread] [core_mqtt_serializer.c:912] [INFO] [MQTT] Connection accepted. 174 6801 [iot_thread] [core_mqtt.c:1563] [INFO] [MQTT] Received MQTT CONNACK successfully from broker. 175 6801 [iot_thread] [core_mqtt.c:1829] [INFO] [MQTT] MQTT connection established with the broker. 176 6801 [iot_thread] [mqtt_demo_mutual_auth.c:843] [INFO] [MQTT_MutualAuth_Demo] An MQTT connection is established with a10y2vqnezxqbn-ats.iot.us-east-1.amazonaws.com. 177 6801 [iot_thread] [mqtt_demo_mutual_auth.c:908] [INFO] [MQTT_MutualAuth_Demo] Attempt to subscribe to the MQTT topic afr_ota_test/example/topic. 178 6802 [iot_thread] [mqtt_demo_mutual_auth.c:922] [INFO] [MQTT_MutualAuth_Demo] SUBSCRIBE sent for topic afr_ota_test/example/topic to broker. 179 6831 [iot_thread] [core_mqtt.c:886] [INFO] [MQTT] Packet received. ReceivedBytes=3. 180 6832 [iot_thread] [mqtt_demo_mutual_auth.c:1076] [INFO] [MQTT_MutualAuth_Demo] Subscribed to the topic afr_ota_test/example/topic with maximum QoS 1. 181 6882 [iot_thread] [mqtt_demo_mutual_auth.c:552] [INFO] [MQTT_MutualAuth_Demo] Publish to the MQTT topic afr_ota_test/example/topic. 182 6882 [iot_thread] [mqtt_demo_mutual_auth.c:562] [INFO] [MQTT_MutualAuth_Demo] Attempt to receive publish message from broker. 183 6944 [iot_thread] [core_mqtt.c:886] [INFO] [MQTT] Packet received. ReceivedBytes=2. 184 6944 [iot_thread] [core_mqtt.c:1162] [INFO] [MQTT] Ack packet deserialized with result: MQTTSuccess. 185 6944 [iot_thread] [core_mqtt.c:1175] [INFO] [MQTT] State record updated. New state=MQTTPublishDone. 186 6944 [iot_thread] [mqtt_demo_mutual_auth.c:1054] [INFO] [MQTT_MutualAuth_Demo] PUBACK received for packet Id 2. 187 6945 [iot_thread] [core_mqtt.c:886] [INFO] [MQTT] Packet received. ReceivedBytes=42. 188 6945 [iot_thread] [core_mqtt.c:1045] [INFO] [MQTT] De-serialized incoming PUBLISH packet: DeserializerResult=MQTTSuccess. 189 6945 [iot_thread] [core_mqtt.c:1058] [INFO] [MQTT] State record updated. New state=MQTTPubAckSend. 190 6945 [iot_thread] [mqtt_demo_mutual_auth.c:1116] [INFO] [MQTT_MutualAuth_Demo] Incoming QoS : 1 191 6945 [iot_thread] [mqtt_demo_mutual_auth.c:1127] [INFO] [MQTT_MutualAuth_Demo] Incoming Publish Topic Name: afr_ota_test/example/topic matches subscribed topic.Incoming Publish Message : 192 6995 [iot_thread] [mqtt_demo_mutual_auth.c:572] [INFO] [MQTT_MutualAuth_Demo] Keeping Connection Idle... 193 7195 [iot_thread] [mqtt_demo_mutual_auth.c:552] [INFO] [MQTT_MutualAuth_Demo] Publish to the MQTT topic afr_ota_test/example/topic. 194 7195 [iot_thread] [mqtt_demo_mutual_auth.c:562] [INFO] [MQTT_MutualAuth_Demo] Attempt to receive publish message from broker. 195 7302 [iot_thread] [core_mqtt.c:886] [INFO] [MQTT] Packet received. ReceivedBytes=2. 196 7302 [iot_thread] [core_mqtt.c:1162] [INFO] [MQTT] Ack packet deserialized with result: MQTTSuccess. 197 7302 [iot_thread] [core_mqtt.c:1175] [INFO] [MQTT] State record updated. New state=MQTTPublishDone. 198 7302 [iot_thread] [mqtt_demo_mutual_auth.c:1054] [INFO] [MQTT_MutualAuth_Demo] PUBACK received for packet Id 3. 199 7304 [iot_thread] [core_mqtt.c:886] [INFO] [MQTT] Packet received. ReceivedBytes=42. 200 7304 [iot_thread] [core_mqtt.c:1045] [INFO] [MQTT] De-serialized incoming PUBLISH packet: DeserializerResult=MQTTSuccess. 201 7304 [iot_thread] [core_mqtt.c:1058] [INFO] [MQTT] State record updated. New state=MQTTPubAckSend. 202 7304 [iot_thread] [mqtt_demo_mutual_auth.c:1116] [INFO] [MQTT_MutualAuth_Demo] Incoming QoS : 1 203 7304 [iot_thread] [mqtt_demo_mutual_auth.c:1127] [INFO] [MQTT_MutualAuth_Demo] Incoming Publish Topic Name: afr_ota_test/example/topic matches subscribed topic.Incoming Publish Message : 204 7404 [iot_thread] [mqtt_demo_mutual_auth.c:572] [INFO] [MQTT_MutualAuth_Demo] Keeping Connection Idle... 205 7604 [iot_thread] [mqtt_demo_mutual_auth.c:552] [INFO] [MQTT_MutualAuth_Demo] Publish to the MQTT topic afr_ota_test/example/topic. 206 7604 [iot_thread] [mqtt_demo_mutual_auth.c:562] [INFO] [MQTT_MutualAuth_Demo] Attempt to receive publish message from broker. 207 7693 [iot_thread] [core_mqtt.c:886] [INFO] [MQTT] Packet received. ReceivedBytes=2. 208 7693 [iot_thread] [core_mqtt.c:1162] [INFO] [MQTT] Ack packet deserialized with result: MQTTSuccess. 209 7693 [iot_thread] [core_mqtt.c:1175] [INFO] [MQTT] State record updated. New state=MQTTPublishDone. 210 7693 [iot_thread] [mqtt_demo_mutual_auth.c:1054] [INFO] [MQTT_MutualAuth_Demo] PUBACK received for packet Id 4. 211 7695 [iot_thread] [core_mqtt.c:886] [INFO] [MQTT] Packet received. ReceivedBytes=42. 212 7695 [iot_thread] [core_mqtt.c:1045] [INFO] [MQTT] De-serialized incoming PUBLISH packet: DeserializerResult=MQTTSuccess. 213 7695 [iot_thread] [core_mqtt.c:1058] [INFO] [MQTT] State record updated. New state=MQTTPubAckSend. 214 7695 [iot_thread] [mqtt_demo_mutual_auth.c:1116] [INFO] [MQTT_MutualAuth_Demo] Incoming QoS : 1 215 7695 [iot_thread] [mqtt_demo_mutual_auth.c:1127] [INFO] [MQTT_MutualAuth_Demo] Incoming Publish Topic Name: afr_ota_test/example/topic matches subscribed topic.Incoming Publish Message : 216 7795 [iot_thread] [mqtt_demo_mutual_auth.c:572] [INFO] [MQTT_MutualAuth_Demo] Keeping Connection Idle... 217 7995 [iot_thread] [mqtt_demo_mutual_auth.c:552] [INFO] [MQTT_MutualAuth_Demo] Publish to the MQTT topic afr_ota_test/example/topic. 218 7995 [iot_thread] [mqtt_demo_mutual_auth.c:562] [INFO] [MQTT_MutualAuth_Demo] Attempt to receive publish message from broker. 219 8070 [iot_thread] [core_mqtt.c:886] [INFO] [MQTT] Packet received. ReceivedBytes=2. 220 8070 [iot_thread] [core_mqtt.c:1162] [INFO] [MQTT] Ack packet deserialized with result: MQTTSuccess. 221 8070 [iot_thread] [core_mqtt.c:1175] [INFO] [MQTT] State record updated. New state=MQTTPublishDone. 222 8070 [iot_thread] [mqtt_demo_mutual_auth.c:1054] [INFO] [MQTT_MutualAuth_Demo] PUBACK received for packet Id 5. 223 8072 [iot_thread] [core_mqtt.c:886] [INFO] [MQTT] Packet received. ReceivedBytes=42. 224 8072 [iot_thread] [core_mqtt.c:1045] [INFO] [MQTT] De-serialized incoming PUBLISH packet: DeserializerResult=MQTTSuccess. 225 8072 [iot_thread] [core_mqtt.c:1058] [INFO] [MQTT] State record updated. New state=MQTTPubAckSend. 226 8072 [iot_thread] [mqtt_demo_mutual_auth.c:1116] [INFO] [MQTT_MutualAuth_Demo] Incoming QoS : 1 227 8072 [iot_thread] [mqtt_demo_mutual_auth.c:1127] [INFO] [MQTT_MutualAuth_Demo] Incoming Publish Topic Name: afr_ota_test/example/topic matches subscribed topic.Incoming Publish Message : 228 8172 [iot_thread] [mqtt_demo_mutual_auth.c:572] [INFO] [MQTT_MutualAuth_Demo] Keeping Connection Idle... 229 8372 [iot_thread] [mqtt_demo_mutual_auth.c:552] [INFO] [MQTT_MutualAuth_Demo] Publish to the MQTT topic afr_ota_test/example/topic. 230 8372 [iot_thread] [mqtt_demo_mutual_auth.c:562] [INFO] [MQTT_MutualAuth_Demo] Attempt to receive publish message from broker. 231 8456 [iot_thread] [core_mqtt.c:886] [INFO] [MQTT] Packet received. ReceivedBytes=2. 232 8456 [iot_thread] [core_mqtt.c:1162] [INFO] [MQTT] Ack packet deserialized with result: MQTTSuccess. 233 8456 [iot_thread] [core_mqtt.c:1175] [INFO] [MQTT] State record updated. New state=MQTTPublishDone. 234 8456 [iot_thread] [mqtt_demo_mutual_auth.c:1054] [INFO] [MQTT_MutualAuth_Demo] PUBACK received for packet Id 6. 235 8476 [iot_thread] [core_mqtt.c:886] [INFO] [MQTT] Packet received. ReceivedBytes=42. 236 8476 [iot_thread] [core_mqtt.c:1045] [INFO] [MQTT] De-serialized incoming PUBLISH packet: DeserializerResult=MQTTSuccess. 237 8476 [iot_thread] [core_mqtt.c:1058] [INFO] [MQTT] State record updated. New state=MQTTPubAckSend. 238 8476 [iot_thread] [mqtt_demo_mutual_auth.c:1116] [INFO] [MQTT_MutualAuth_Demo] Incoming QoS : 1 239 8476 [iot_thread] [mqtt_demo_mutual_auth.c:1127] [INFO] [MQTT_MutualAuth_Demo] Incoming Publish Topic Name: afr_ota_test/example/topic matches subscribed topic.Incoming Publish Message : 240 8528 [iot_thread] [mqtt_demo_mutual_auth.c:572] [INFO] [MQTT_MutualAuth_Demo] Keeping Connection Idle... 241 8728 [iot_thread] [mqtt_demo_mutual_auth.c:580] [INFO] [MQTT_MutualAuth_Demo] Unsubscribe from the MQTT topic afr_ota_test/example/topic. 242 8766 [iot_thread] [core_mqtt.c:886] [INFO] [MQTT] Packet received. ReceivedBytes=2. 243 8766 [iot_thread] [mqtt_demo_mutual_auth.c:1085] [INFO] [MQTT_MutualAuth_Demo] Unsubscribed from the topic afr_ota_test/example/topic. 244 8816 [iot_thread] [mqtt_demo_mutual_auth.c:602] [INFO] [MQTT_MutualAuth_Demo] Disconnecting the MQTT connection with a10y2vqnezxqbn-ats.iot.us-east-1.amazonaws.com. 245 8816 [iot_thread] [core_mqtt.c:2149] [INFO] [MQTT] Disconnected from the broker. 246 8817 [iot_thread] [mqtt_demo_mutual_auth.c:631] [INFO] [MQTT_MutualAuth_Demo] Demo completed an iteration successfully. 247 8817 [iot_thread] [mqtt_demo_mutual_auth.c:632] [INFO] [MQTT_MutualAuth_Demo] Demo iteration 3 completed successfully. 248 8817 [iot_thread] [mqtt_demo_mutual_auth.c:644] [INFO] [MQTT_MutualAuth_Demo] Short delay before starting the next iteration.... 249 9317 [iot_thread] [mqtt_demo_mutual_auth.c:655] [INFO] [MQTT_MutualAuth_Demo] Demo run is successful with 3 successful loops out of total 3 loops. 250 9317 [iot_thread] [INFO ][DEMO][93170] memory_metrics::freertos_heap::before::bytes::223744 251 9317 [iot_thread] [INFO ][DEMO][93170] memory_metrics::freertos_heap::after::bytes::123652 252 9317 [iot_thread] [INFO ][DEMO][93170] memory_metrics::demo_task_stack::before::bytes::5848 253 9317 [iot_thread] [INFO ][DEMO][93170] memory_metrics::demo_task_stack::after::bytes::2408 I (94913) wifi:state: run -> init (0) I (94913) wifi:pm stop, total sleep time: 18329154 us / 90769674 us I (94913) wifi:new:<1,0>, old:<1,0>, ap:<255,255>, sta:<1,0>, prof:1 I (94913) WIFI: WIFI_EVENT_STA_DISCONNECTED: 63 254 9417 [iot_thread] [INFO ][DEMO][94170] Demo completed successfully. E (94923) wifi_init: Wi-Fi not stop I (94933) WIFI: WIFI_EVENT_STA_STOP I (94933) wifi:flush txq I (94933) wifi:stop sw txq I (94943) wifi:lmac stop hw txq I (94943) wifi:Deinit lldesc rx mblock:10 255 9421 [iot_thread] [INFO ][INIT][94210] SDK cleanup done. 256 9421 [iot_thread] [INFO ][DEMO][94210] -------DEMO FINISHED------- ```
ravibhagavandas commented 1 year ago

Hi @laukik-hase

I tried with the commit b3fde23 on main branch, but could not reproduce the issue. Please find attached logs for MQTT Mutual Auth demo on ESP32 WROOM board.

mqtt_success_logs.txt

7 601 [iot_thread] ERROR: TLS handshake failed trying to connect. SSL - The connection indicated an EOF : 8 601 [iot_thread] TLS_Connect fail (0x7280, a10y2vqnezxqbn-ats.iot.us-east-1.amazonaws.com)

The error 0x7280 in your log indicates a terminated connection by the server. Can you confirm if the certificate used is valid and registered with AWS IoT ? Also could you check if the policy attached to the certificate has sufficient permissions?

laukik-hase commented 1 year ago

Hello, @ravibhagavandas!

I have checked the AWS IoT configuration (thing, certificate and policy attached) and it is correct. I am confused why a configuration would work at https://github.com/aws/amazon-freertos/commit/8e69ca72d015e6285f49c90a202651a73acfc692 but fail at a commit just after it.

(Note: The demo also works on the 202203.00 release with the same config)

Apart from setting the appropriate parameters in aws_clientcredential.h and aws_clientcredential_keys.h, is anything else required for the mqtt_demo_mutual_auth on the latest main branch?

ravibhagavandas commented 1 year ago

Apart from setting the appropriate parameters in aws_clientcredential.h and aws_clientcredential_keys.h, is anything else required for the mqtt_demo_mutual_auth on the latest main branch?

Only these configuration files needs to be modified for the demo.

Could you enable mbedtls debug logs and share the logs for TLS handshake failure?

laukik-hase commented 1 year ago

PFA the Mbed TLS debug logs: mqtt_fail.log

On another note, increasing the mqttexampleTRANSPORT_SEND_RECV_TIMEOUT_MS to 1000 in mqtt_demo_mutual_auth.c makes the example run as expected.

n9wxu commented 1 year ago

We have seen changes to the timeout making a big difference in different regions.