[GreenGrass] Can't create new MQTT connection if the previous one was not closed

[ahmedwahdan]

Describe the bug I'm using greengrass demo to connect to greengrass core over EC2 instance. I'm using mobile phone as AP. If the hardware was restarted without closing the connection, I have to reboot the mobile phone!

Edit: Sometimes even with closing the connection, new connection can't be created.

System information

• ESP32
• VSCode
• Operating System [Windows]
• Version of Amazon FreeRTOS (201906.00_Major-539-g3a519702)
• Project [Greengrass]

Expected behavior This issue is not visible when using other demos, I think the issue may be related to using the MQTT_Agent instead of directly using MQTT v2 APIs directly

Thank you!

[sarenameas]

Hello ahmedwahdan,

How do you restart the hardware? Do you power cycle? Also where in the process do you restart? Could you show us some logs?

I am trying this out now.

[ahmedwahdan]

Hello Sarenameas, Sometimes after successful demo complete, and some times if I restart the esp32 (power reset) before closing the connection, the connection can't established again with the greengrass core. After receiving the greengrass core info from the cloud, It fails with Network Error

[sarenameas]

Could you please turn on logging in the TCP/IP stack in vendors\espressif\boards\esp32\aws_demos\config_files\FreeRTOSIPConfig.h by setting:

#define ipconfigHAS_DEBUG_PRINTF    1

Then please post the logs here.

[ahmedwahdan]

` make flash monitor Flashing binaries to serial port COM6 (app at offset 0x20000 )... esptool.py v2.6 Serial port COM6 Connecting..... Chip is ESP32D0WDQ6 (revision 1) Features: WiFi, BT, Dual Core, Coding Scheme None MAC: 30:ae:a4:22:ce:80 Uploading stub... Running stub... Stub running... Changing baud rate to 921600 Changed. Configuring flash size... Auto-detected Flash size: 4MB Compressed 23712 bytes to 14071... Wrote 23712 bytes (14071 compressed) at 0x00001000 in 0.2 seconds (effective 1100.8 kbit/s)... Hash of data verified. Compressed 1099136 bytes to 669493... Wrote 1099136 bytes (669493 compressed) at 0x00020000 in 10.6 seconds (effective 827.2 kbit/s)... Hash of data verified. Compressed 3072 bytes to 141... Wrote 3072 bytes (141 compressed) at 0x00008000 in 0.0 seconds (effective 1804.0 kbit/s)... Hash of data verified.

Leaving... Hard resetting via RTS pin... MONITOR --- idf_monitor on COM6 115200 --- --- Quit: Ctrl+] | Menu: Ctrl+T | Help: Ctrl+T followed by Ctrl+H --- ets Jun 8 2016 00:22:57

rst:0x1 (POWERON_RESET),boot:0x13 (SPI_FAST_FLASH_BOOT) configsip: 0, SPIWP:0xee clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00 mode:DIO, clock div:2 load:0x3fff0018,len:4 load:0x3fff001c,len:6252 load:0x40078000,len:11276 ho 0 tail 12 room 4 load:0x40080000,len:6084 0x40080000: _WindowOverflow4 at D:/Wahdan/AFR_08_19/amazon-freertos/freertos_kernel/portable/ThirdParty/GCC/Xtensa_ESP32/xtensa_vectors.S:1685

entry 0x4008032c 0x4008032c: _KernelExceptionVector at ??:?

I (30) boot: ESP-IDF v3.1.3-25-g36733db8d 2nd stage bootloader I (30) boot: compile time 13:22:56 I (31) boot: Enabling RNG early entropy source... I (36) boot: SPI Speed : 40MHz I (40) boot: SPI Mode : DIO I (44) boot: SPI Flash Size : 4MB I (48) boot: Partition Table: I (52) boot: ## Label Usage Type ST Offset Length I (59) boot: 0 nvs WiFi data 01 02 00010000 00006000 I (67) boot: 1 otadata OTA data 01 00 00016000 00002000 I (74) boot: 2 phy_init RF data 01 01 00018000 00001000 I (82) boot: 3 ota_0 OTA app 00 10 00020000 00177000 I (89) boot: 4 ota_1 OTA app 00 11 001a0000 00177000 I (97) boot: 5 storage WiFi data 01 02 00317000 00010000 I (104) boot: End of partition table I (108) esp_image: segment 0: paddr=0x00020020 vaddr=0x3f400020 size=0x2f4cc (193740) map I (185) esp_image: segment 1: paddr=0x0004f4f4 vaddr=0x3ffc0000 size=0x00b1c ( 2844) load I (187) esp_image: segment 2: paddr=0x00050018 vaddr=0x400d0018 size=0xc376c (800620) map 0x400d0018: _flash_cache_start at ??:?

I (472) esp_image: segment 3: paddr=0x0011378c vaddr=0x3ffc0b1c size=0x02424 ( 9252) load I (476) esp_image: segment 4: paddr=0x00115bb8 vaddr=0x40080000 size=0x00400 ( 1024) load 0x40080000: _WindowOverflow4 at D:/Wahdan/AFR_08_19/amazon-freertos/freertos_kernel/portable/ThirdParty/GCC/Xtensa_ESP32/xtensa_vectors.S:1685

I (479) esp_image: segment 5: paddr=0x00115fc0 vaddr=0x40080400 size=0x16598 ( 91544) load I (539) boot: Loaded app from partition at offset 0x20000 I (539) boot: ota rollback check done I (539) boot: Disabling RNG early entropy source... I (544) cpu_start: Pro cpu up. I (547) cpu_start: Single core mode I (552) heap_init: Initializing. RAM available for dynamic allocation: I (559) heap_init: At 3FFAFF10 len 000000F0 (0 KiB): DRAM I (565) heap_init: At 3FFD1258 len 0000EDA8 (59 KiB): DRAM I (571) heap_init: At 3FFE0440 len 00003BC0 (14 KiB): D/IRAM I (577) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM I (583) heap_init: At 40096998 len 00009668 (37 KiB): IRAM I (590) cpu_start: Pro cpu start user code I (272) cpu_start: Starting scheduler on PRO CPU. I (296) uart: queue free spaces: 10 0 1 [IP-task] prvIPTask started I (296) PKCS11: Initializing NVS partition: "storage" E (316) PKCS11: failed nvs get file size 4354 0 1 4 [main] Write certificate... 2 15 [main] Device credential provisioning succeeded. I (446) BTDM_INIT: BT controller compile version [3828e65]

I (446) system_api: Base MAC address is not set, read default base MAC address from BLK0 of EFUSE I (506) phy: phy_version: 4008, c9ae59f, Jan 25 2019, 16:54:06, 0, 0 3 56 [iot_thread] [INFO ][INIT][560] SDK successfully initialized. I (876) wifi: wifi driver task: 3ffdb480, prio:23, stack:3584, core=0 I (876) wifi: wifi firmware version: dbb148a I (876) wifi: config NVS flash: enabled I (876) wifi: config nano formating: disabled I (886) system_api: Base MAC address is not set, read default base MAC address from BLK0 of EFUSE I (886) system_api: Base MAC address is not set, read default base MAC address from BLK0 of EFUSE I (906) wifi: Init dynamic tx buffer num: 64 I (906) wifi: Init data frame dynamic rx buffer num: 64 I (906) wifi: Init management frame dynamic rx buffer num: 64 I (916) wifi: Init static rx buffer size: 1600 I (916) wifi: Init static rx buffer num: 16 I (926) wifi: Init dynamic rx buffer num: 64 I (936) wifi: mode : sta (30:ae:a4:22:ce:80) I (936) WIFI: SYSTEM_EVENT_STA_START I (1666) wifi: n:6 0, o:1 0, ap:255 255, sta:6 0, prof:1 I (2646) wifi: state: init -> auth (b0) I (2646) wifi: state: auth -> assoc (0) I (2656) wifi: state: assoc -> run (10) I (2796) wifi: connected with Wahdan, channel 6 I (2796) wifi: pm start, type: 1

I (2806) WIFI: SYSTEM_EVENT_STA_CONNECTED 4 301 [IP-task] prvInitialiseDHCP: start after 25 ticks 5 301 [IP-task] vDHCPProcess: discover 6 338 [IP-task] vDHCPProcess: offer c0a82bbeip 7 338 [IP-task] vDHCPProcess: reply c0a82bbeip I (5926) event: sta ip: 192.168.43.190, mask: 255.255.255.0, gw: 192.168.43.1 I (5926) WIFI: SYSTEM_EVENT_STA_GOT_IP 8 564 [IP-task] vDHCPProcess: offer c0a82bbeip 9 564 [IP-task] vDHCPProcess: acked c0a82bbeip 10 565 [iot_thread] [INFO ][DEMO][5650] Successfully initialized the demo. Network type for the demo: 1 11 565 [iot_thread] Attempting automated selection of Greengrass device 12 605 [iot_thread] prvProcessDNSCache: add: 'a3rcy4vytvmu2y-ats.iot.us-west-2.amazonaws.com' @ 22d5391fip 13 605 [iot_thread] FreeRTOS_connect: 64070 to 22d5391fip:8443 14 605 [iot_thread] Socket 64070 -> 22d5391fip:8443 State eCLOSED->eCONNECT_SYN 15 605 [IP-task] prvSocketSetMSS: 1400 bytes for 22d5391fip:8443 16 605 [IP-task] prvWinScaleFactor: uxRxWinSize 1 MSS 1400 Factor 0 17 605 [IP-task] Connect[22d5391fip:8443]: next timeout 1: 3000 ms 18 646 [IP-task] MSS change 1400 -> 1388 19 646 [IP-task] Change mss 1400 => 1388 20 646 [IP-task] TCP: active 64070 => 22d5391fip:8443 set ESTAB (scaling 1) 21 646 [IP-task] Socket 64070 -> 22d5391fip:8443 State eCONNECT_SYN->eESTABLISHED 22 707 [IP-task] MSS: sending 1388 23 1424 [iot_thread] About to close socket. 24 1424 [IP-task] Socket 64070 -> 22d5391fip:8443 State eESTABLISHED->eFIN_WAIT_1 25 1485 [IP-task] Socket 64070 -> 22d5391fip:8443 State eFIN_WAIT_1->eCLOSE_WAIT 26 1485 [IP-task] FreeRTOS_closesocket[64070 to 22d5391fip:8443]: buffers 60 socks 0 27 1486 [iot_thread] Socket closed. 28 1486 [iot_thread] Stack high watermark for discovery helper task: 5220. 29 1526 [iot_thread] prvProcessDNSCache: add: 'ec2-54-213-226-188.us-west-2.compute.amazonaws.com' @ 36d5e2bcip 30 1526 [iot_thread] FreeRTOS_connect: 24324 to 36d5e2bcip:8883 31 1526 [iot_thread] Socket 24324 -> 36d5e2bcip:8883 State eCLOSED->eCONNECT_SYN 32 1526 [IP-task] prvSocketSetMSS: 1400 bytes for 36d5e2bcip:8883 33 1526 [IP-task] prvWinScaleFactor: uxRxWinSize 1 MSS 1400 Factor 0 34 1526 [IP-task] Connect[36d5e2bcip:8883]: next timeout 1: 3000 ms 35 1567 [IP-task] MSS change 1400 -> 1388 36 1567 [IP-task] Change mss 1400 => 1388 37 1567 [IP-task] TCP: active 24324 => 36d5e2bcip:8883 set ESTAB (scaling 1) 38 1567 [IP-task] Socket 24324 -> 36d5e2bcip:8883 State eCONNECT_SYN->eESTABLISHED 39 1629 [IP-task] MSS: sending 1388 40 2039 [iot_thread] About to close socket. 41 2039 [IP-task] Socket 24324 -> 36d5e2bcip:8883 State eESTABLISHED->eFIN_WAIT_1 42 2079 [IP-task] Socket 24324 -> 36d5e2bcip:8883 State eFIN_WAIT_1->eLAST_ACK 43 2079 [IP-task] Socket 24324 -> 36d5e2bcip:8883 State eLAST_ACK->eCLOSE_WAIT 44 2080 [IP-task] FreeRTOS_closesocket[24324 to 36d5e2bcip:8883]: buffers 60 socks 0 45 2080 [iot_thread] Socket closed. 46 2080 [iot_thread] Stack high watermark for discovery helper task: 2612. 47 2080 [iot_thread] Greengrass device discovered. 48 2080 [iot_thread] Establishing MQTT communication to Greengrass... 49 2080 [iot_thread] prvProcessDNSCache: look-up: 'ec2-54-213-226-188.us-west-2.compute.amazonaws.com' @ 36d5e2bcip 50 2080 [iot_thread] FreeRTOS_gethostbyname: found 'ec2-54-213-226-188.us-west-2.compute.amazonaws.com' in cache: bce2d536ip 51 2080 [iot_thread] FreeRTOS_connect: 25012 to 36d5e2bcip:8883 52 2080 [iot_thread] Socket 25012 -> 36d5e2bcip:8883 State eCLOSED->eCONNECT_SYN 53 2080 [IP-task] prvSocketSetMSS: 1400 bytes for 36d5e2bcip:8883 54 2080 [IP-task] prvWinScaleFactor: uxRxWinSize 1 MSS 1400 Factor 0 55 2080 [IP-task] Connect[36d5e2bcip:8883]: next timeout 1: 3000 ms 56 2161 [IP-task] TCP: No active socket on port 24324 (36d5e2bcip:8883) 57 2161 [IP-task] MSS change 1400 -> 1388 58 2161 [IP-task] Change mss 1400 => 1388 59 2161 [IP-task] TCP: active 25012 => 36d5e2bcip:8883 set ESTAB (scaling 1) 60 2161 [IP-task] Socket 25012 -> 36d5e2bcip:8883 State eCONNECT_SYN->eESTABLISHED 61 2274 [IP-task] MSS: sending 1388 62 2674 [iot_thread] [INFO ][MQTT][26740] Establishing new MQTT connection. 63 2674 [iot_thread] [INFO ][MQTT][26740] Anonymous metrics (SDK language, SDK version) will be provided to AWS IoT. Recompile with AWS_IOT_MQTT_ENABLE_METRICS set to 0 to disable. 64 2674 [iot_thread] [INFO ][MQTT][26740] (MQTT connection 0x3fff6f44, CONNECT operation 0x3ffe9adc) Waiting for operation completion. 65 2735 [iot_thread] [INFO ][MQTT][27350] (MQTT connection 0x3fff6f44, CONNECT operation 0x3ffe9adc) Wait complete with result SUCCESS. 66 2735 [iot_thread] [INFO ][MQTT][27350] New MQTT connection 0x3ffe9ba0 established. 67 2735 [iot_thread] [INFO ][MQTT][27350] (MQTT connection 0x3fff6f44) MQTT PUBLISH operation queued. 68 2885 [iot_thread] [INFO ][MQTT][28850] (MQTT connection 0x3fff6f44) MQTT PUBLISH operation queued. 69 3035 [iot_thread] [INFO ][MQTT][30350] (MQTT connection 0x3fff6f44) MQTT PUBLISH operation queued. 70 3185 [iot_thread] Disconnecting from broker. 71 3185 [iot_thread] [INFO ][MQTT][31850] (MQTT connection 0x3fff6f44) Disconnecting connection. 72 3185 [iot_thread] [INFO ][MQTT][31850] (MQTT connection 0x3fff6f44, DISCONNECT operation 0x3fff8bf8) Waiting for operation completion. 73 3186 [iot_thread] [INFO ][MQTT][31860] (MQTT connection 0x3fff6f44, DISCONNECT operation 0x3fff8bf8) Wait complete with result SUCCESS. 74 3186 [iot_thread] [INFO ][MQTT][31860] (MQTT connection 0x3fff6f44) Connection disconnected. 75 3187 [iot_thread] [INFO ][MQTT][31870] (MQTT connection 0x3fff6f44) Network connection closed. 76 3226 [IP-task] Socket 25012 -> 36d5e2bcip:8883 State eESTABLISHED->eFIN_WAIT_1 77 3226 [IP-task] Socket 25012 -> 36d5e2bcip:8883 State eFIN_WAIT_1->eLAST_ACK 78 3226 [IP-task] Socket 25012 -> 36d5e2bcip:8883 State eLAST_ACK->eLAST_ACK 79 3228 [IP-task] FreeRTOS_closesocket[25012 to 36d5e2bcip:8883]: buffers 60 socks 0 80 3228 [iot_thread] [INFO ][MQTT][32280] (MQTT connection 0x3fff6f44) Network connection destroyed. 81 3228 [iot_thread] Disconnected from the broker. 82 3228 [iot_thread] Deleted Client. 83 3228 [iot_thread] Heap low watermark: 8872. Stack high watermark: 2612. 84 3228 [iot_thread] ----Demo finished---- 85 3267 [IP-task] TCP: No active socket on port 25012 (36d5e2bcip:8883) 86 3267 [IP-task] TCP: No active socket on port 25012 (36d5e2bcip:8883) ets Jun 8 2016 00:22:57

rst:0x1 (POWERON_RESET),boot:0x13 (SPI_FAST_FLASH_BOOT) flash read err, 1000 ets_main.c 371 ets Jun 8 2016 00:22:57

rst:0x10 (RTCWDT_RTC_RESET),boot:0x13 (SPI_FAST_FLASH_BOOT) configsip: 0, SPIWP:0xee clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00 mode:DIO, clock div:2 load:0x3fff0018,len:4 load:0x3fff001c,len:6252 load:0x40078000,len:11276 ho 0 tail 12 room 4 load:0x40080000,len:6084 0x40080000: _WindowOverflow4 at D:/Wahdan/AFR_08_19/amazon-freertos/freertos_kernel/portable/ThirdParty/GCC/Xtensa_ESP32/xtensa_vectors.S:1685

entry 0x4008032c 0x4008032c: _KernelExceptionVector at ??:?

I (31) boot: ESP-IDF v3.1.3-25-g36733db8d 2nd stage bootloader I (31) boot: compile time 13:22:56 I (31) boot: Enabling RNG early entropy source... I (36) boot: SPI Speed : 40MHz I (41) boot: SPI Mode : DIO I (45) boot: SPI Flash Size : 4MB I (49) boot: Partition Table: I (52) boot: ## Label Usage Type ST Offset Length I (60) boot: 0 nvs WiFi data 01 02 00010000 00006000 I (67) boot: 1 otadata OTA data 01 00 00016000 00002000 I (74) boot: 2 phy_init RF data 01 01 00018000 00001000 I (82) boot: 3 ota_0 OTA app 00 10 00020000 00177000 I (89) boot: 4 ota_1 OTA app 00 11 001a0000 00177000 I (97) boot: 5 storage WiFi data 01 02 00317000 00010000 I (104) boot: End of partition table I (109) esp_image: segment 0: paddr=0x00020020 vaddr=0x3f400020 size=0x2f4cc (193740) map I (186) esp_image: segment 1: paddr=0x0004f4f4 vaddr=0x3ffc0000 size=0x00b1c ( 2844) load I (187) esp_image: segment 2: paddr=0x00050018 vaddr=0x400d0018 size=0xc376c (800620) map 0x400d0018: _flash_cache_start at ??:?

I (472) esp_image: segment 3: paddr=0x0011378c vaddr=0x3ffc0b1c size=0x02424 ( 9252) load I (476) esp_image: segment 4: paddr=0x00115bb8 vaddr=0x40080000 size=0x00400 ( 1024) load 0x40080000: _WindowOverflow4 at D:/Wahdan/AFR_08_19/amazon-freertos/freertos_kernel/portable/ThirdParty/GCC/Xtensa_ESP32/xtensa_vectors.S:1685

I (480) esp_image: segment 5: paddr=0x00115fc0 vaddr=0x40080400 size=0x16598 ( 91544) load I (539) boot: Loaded app from partition at offset 0x20000 I (539) boot: ota rollback check done I (539) boot: Disabling RNG early entropy source... I (544) cpu_start: Pro cpu up. I (548) cpu_start: Single core mode I (552) heap_init: Initializing. RAM available for dynamic allocation: I (559) heap_init: At 3FFAFF10 len 000000F0 (0 KiB): DRAM I (565) heap_init: At 3FFD1258 len 0000EDA8 (59 KiB): DRAM I (571) heap_init: At 3FFE0440 len 00003BC0 (14 KiB): D/IRAM I (577) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM I (584) heap_init: At 40096998 len 00009668 (37 KiB): IRAM I (590) cpu_start: Pro cpu start user code I (272) cpu_start: Starting scheduler on PRO CPU. I (297) uart: queue free spaces: 10 0 1 [IP-task] prvIPTask started I (297) PKCS11: Initializing NVS partition: "storage" E (317) PKCS11: failed nvs get file size 4354 0 1 4 [main] Write certificate... 2 15 [main] Device credential provisioning succeeded. I (437) BTDM_INIT: BT controller compile version [3828e65]

I (437) system_api: Base MAC address is not set, read default base MAC address from BLK0 of EFUSE I (507) phy: phy_version: 4008, c9ae59f, Jan 25 2019, 16:54:06, 0, 0 3 55 [iot_thread] [INFO ][INIT][550] SDK successfully initialized. I (867) wifi: wifi driver task: 3ffdb13c, prio:23, stack:3584, core=0 I (867) wifi: wifi firmware version: dbb148a I (867) wifi: config NVS flash: enabled I (867) wifi: config nano formating: disabled I (877) system_api: Base MAC address is not set, read default base MAC address from BLK0 of EFUSE I (887) system_api: Base MAC address is not set, read default base MAC address from BLK0 of EFUSE I (897) wifi: Init dynamic tx buffer num: 64 I (897) wifi: Init data frame dynamic rx buffer num: 64 I (897) wifi: Init management frame dynamic rx buffer num: 64 I (907) wifi: Init static rx buffer size: 1600 I (917) wifi: Init static rx buffer num: 16 I (917) wifi: Init dynamic rx buffer num: 64 I (927) wifi: mode : sta (30:ae:a4:22:ce:80) I (927) WIFI: SYSTEM_EVENT_STA_START I (1657) wifi: n:6 0, o:1 0, ap:255 255, sta:6 0, prof:1 I (2637) wifi: state: init -> auth (b0) I (2647) wifi: state: auth -> assoc (0) I (2647) wifi: state: assoc -> run (10) I (2667) wifi: connected with Wahdan, channel 6 I (2667) wifi: pm start, type: 1

I (2677) WIFI: SYSTEM_EVENT_STA_CONNECTED 4 301 [IP-task] prvInitialiseDHCP: start after 25 ticks 5 301 [IP-task] vDHCPProcess: discover 6 302 [IP-task] vDHCPProcess: offer c0a82bbeip 7 302 [IP-task] vDHCPProcess: reply c0a82bbeip I (4797) event: sta ip: 192.168.43.190, mask: 255.255.255.0, gw: 192.168.43.1 I (4797) WIFI: SYSTEM_EVENT_STA_GOT_IP 8 450 [IP-task] vDHCPProcess: offer c0a82bbeip 9 451 [IP-task] vDHCPProcess: acked c0a82bbeip 10 451 [iot_thread] [INFO ][DEMO][4510] Successfully initialized the demo. Network type for the demo: 1 11 451 [iot_thread] Attempting automated selection of Greengrass device 12 452 [iot_thread] prvProcessDNSCache: add: 'a3rcy4vytvmu2y-ats.iot.us-west-2.amazonaws.com' @ 34221bf9ip 13 454 [iot_thread] FreeRTOS_connect: 64070 to 34221bf9ip:8443 14 454 [iot_thread] Socket 64070 -> 34221bf9ip:8443 State eCLOSED->eCONNECT_SYN 15 454 [IP-task] prvSocketSetMSS: 1400 bytes for 34221bf9ip:8443 16 454 [IP-task] prvWinScaleFactor: uxRxWinSize 1 MSS 1400 Factor 0 17 454 [IP-task] Connect[34221bf9ip:8443]: next timeout 1: 3000 ms 18 534 [IP-task] MSS change 1400 -> 1388 19 534 [IP-task] Change mss 1400 => 1388 20 534 [IP-task] TCP: active 64070 => 34221bf9ip:8443 set ESTAB (scaling 1) 21 534 [IP-task] Socket 64070 -> 34221bf9ip:8443 State eCONNECT_SYN->eESTABLISHED 22 635 [IP-task] MSS: sending 1388 23 1311 [iot_thread] About to close socket. 24 1311 [IP-task] Socket 64070 -> 34221bf9ip:8443 State eESTABLISHED->eFIN_WAIT_1 25 1351 [IP-task] Socket 64070 -> 34221bf9ip:8443 State eFIN_WAIT_1->eCLOSE_WAIT 26 1352 [IP-task] FreeRTOS_closesocket[64070 to 34221bf9ip:8443]: buffers 60 socks 0 27 1352 [iot_thread] Socket closed. 28 1352 [iot_thread] Stack high watermark for discovery helper task: 5136. 29 1354 [iot_thread] prvProcessDNSCache: add: 'ec2-54-213-226-188.us-west-2.compute.amazonaws.com' @ 36d5e2bcip 30 1354 [iot_thread] FreeRTOS_connect: 24324 to 36d5e2bcip:8883 31 1354 [iot_thread] Socket 24324 -> 36d5e2bcip:8883 State eCLOSED->eCONNECT_SYN 32 1354 [IP-task] prvSocketSetMSS: 1400 bytes for 36d5e2bcip:8883 33 1354 [IP-task] prvWinScaleFactor: uxRxWinSize 1 MSS 1400 Factor 0 34 1354 [IP-task] Connect[36d5e2bcip:8883]: next timeout 1: 3000 ms 35 1393 [IP-task] MSS change 1400 -> 1388 36 1393 [IP-task] Change mss 1400 => 1388 37 1393 [IP-task] TCP: active 24324 => 36d5e2bcip:8883 set ESTAB (scaling 1) 38 1393 [IP-task] Socket 24324 -> 36d5e2bcip:8883 State eCONNECT_SYN->eESTABLISHED 39 1454 [IP-task] MSS: sending 1388 40 1885 [iot_thread] About to close socket. 41 1885 [IP-task] Socket 24324 -> 36d5e2bcip:8883 State eESTABLISHED->eFIN_WAIT_1 42 1945 [IP-task] Socket 24324 -> 36d5e2bcip:8883 State eFIN_WAIT_1->eCLOSE_WAIT 43 1946 [IP-task] FreeRTOS_closesocket[24324 to 36d5e2bcip:8883]: buffers 60 socks 0 44 1946 [iot_thread] Socket closed. 45 1946 [iot_thread] Stack high watermark for discovery helper task: 2848. 46 1947 [iot_thread] Greengrass device discovered. 47 1947 [iot_thread] Establishing MQTT communication to Greengrass... 48 1947 [iot_thread] prvProcessDNSCache: look-up: 'ec2-54-213-226-188.us-west-2.compute.amazonaws.com' @ 36d5e2bcip 49 1947 [iot_thread] FreeRTOS_gethostbyname: found 'ec2-54-213-226-188.us-west-2.compute.amazonaws.com' in cache: bce2d536ip 50 1948 [iot_thread] FreeRTOS_connect: 25012 to 36d5e2bcip:8883 51 1948 [iot_thread] Socket 25012 -> 36d5e2bcip:8883 State eCLOSED->eCONNECT_SYN 52 1948 [IP-task] prvSocketSetMSS: 1400 bytes for 36d5e2bcip:8883 53 1948 [IP-task] prvWinScaleFactor: uxRxWinSize 1 MSS 1400 Factor 0 54 1948 [IP-task] Connect[36d5e2bcip:8883]: next timeout 1: 3000 ms 55 2007 [IP-task] MSS change 1400 -> 1388 56 2007 [IP-task] Change mss 1400 => 1388 57 2007 [IP-task] TCP: active 25012 => 36d5e2bcip:8883 set ESTAB (scaling 1) 58 2007 [IP-task] Socket 25012 -> 36d5e2bcip:8883 State eCONNECT_SYN->eESTABLISHED 59 2089 [IP-task] MSS: sending 1388 60 2581 [iot_thread] [INFO ][MQTT][25810] Establishing new MQTT connection. 61 2581 [iot_thread] [INFO ][MQTT][25810] Anonymous metrics (SDK language, SDK version) will be provided to AWS IoT. Recompile with AWS_IOT_MQTT_ENABLE_METRICS set to 0 to disable. 62 2581 [iot_thread] [INFO ][MQTT][25810] (MQTT connection 0x3fff6e74, CONNECT operation 0x3ffea374) Waiting for operation completion. 63 2642 [iot_thread] [INFO ][MQTT][26420] (MQTT connection 0x3fff6e74, CONNECT operation 0x3ffea374) Wait complete with result SUCCESS. 64 2642 [iot_thread] [INFO ][MQTT][26420] New MQTT connection 0x3ffe9b90 established. 65 2642 [iot_thread] [INFO ][MQTT][26420] (MQTT connection 0x3fff6e74) MQTT PUBLISH operation queued. 66 2792 [iot_thread] [INFO ][MQTT][27920] (MQTT connection 0x3fff6e74) MQTT PUBLISH operation queued. 67 2942 [iot_thread] [INFO ][MQTT][29420] (MQTT connection 0x3fff6e74) MQTT PUBLISH operation queued. 68 3092 [iot_thread] Disconnecting from broker. 69 3092 [iot_thread] [INFO ][MQTT][30920] (MQTT connection 0x3fff6e74) Disconnecting connection. 70 3092 [iot_thread] [INFO ][MQTT][30920] (MQTT connection 0x3fff6e74, DISCONNECT operation 0x3fff8494) Waiting for operation completion. 71 3093 [iot_thread] [INFO ][MQTT][30930] (MQTT connection 0x3fff6e74, DISCONNECT operation 0x3fff8494) Wait complete with result SUCCESS. 72 3093 [iot_thread] [INFO ][MQTT][30930] (MQTT connection 0x3fff6e74) Connection disconnected. 73 3093 [iot_thread] [INFO ][MQTT][30930] (MQTT connection 0x3fff6e74) Network connection closed. 74 3133 [IP-task] Socket 25012 -> 36d5e2bcip:8883 State eESTABLISHED->eFIN_WAIT_1 75 3134 [IP-task] Socket 25012 -> 36d5e2bcip:8883 State eFIN_WAIT_1->eLAST_ACK 76 3134 [IP-task] Socket 25012 -> 36d5e2bcip:8883 State eLAST_ACK->eLAST_ACK 77 3135 [IP-task] FreeRTOS_closesocket[25012 to 36d5e2bcip:8883]: buffers 60 socks 0 78 3135 [iot_thread] [INFO ][MQTT][31350] (MQTT connection 0x3fff6e74) Network connection destroyed. 79 3135 [iot_thread] Disconnected from the broker. 80 3135 [iot_thread] Deleted Client. 81 3135 [iot_thread] Heap low watermark: 9028. Stack high watermark: 2848. 82 3135 [iot_thread] ----Demo finished---- 83 3175 [IP-task] TCP: No active socket on port 25012 (36d5e2bcip:8883) ets Jun 8 2016 00:22:57

rst:0x1 (POWERON_RESET),boot:0x13 (SPI_FAST_FLASH_BOOT) configsip: 0, SPIWP:0xee clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00 mode:DIO, clock div:2 load:0x3fff0018,len:4 load:0x3fff001c,len:6252 load:0x40078000,len:11276 ho 0 tail 12 room 4 load:0x40080000,len:6084 0x40080000: _WindowOverflow4 at D:/Wahdan/AFR_08_19/amazon-freertos/freertos_kernel/portable/ThirdParty/GCC/Xtensa_ESP32/xtensa_vectors.S:1685

entry 0x4008032c 0x4008032c: _KernelExceptionVector at ??:?

I (30) boot: ESP-IDF v3.1.3-25-g36733db8d 2nd stage bootloader I (30) boot: compile time 13:22:56 I (31) boot: Enabling RNG early entropy source... I (36) boot: SPI Speed : 40MHz I (40) boot: SPI Mode : DIO I (44) boot: SPI Flash Size : 4MB I (48) boot: Partition Table: I (52) boot: ## Label Usage Type ST Offset Length I (59) boot: 0 nvs WiFi data 01 02 00010000 00006000 I (67) boot: 1 otadata OTA data 01 00 00016000 00002000 I (74) boot: 2 phy_init RF data 01 01 00018000 00001000 I (82) boot: 3 ota_0 OTA app 00 10 00020000 00177000 I (89) boot: 4 ota_1 OTA app 00 11 001a0000 00177000 I (97) boot: 5 storage WiFi data 01 02 00317000 00010000 I (104) boot: End of partition table I (108) esp_image: segment 0: paddr=0x00020020 vaddr=0x3f400020 size=0x2f4cc (193740) map I (185) esp_image: segment 1: paddr=0x0004f4f4 vaddr=0x3ffc0000 size=0x00b1c ( 2844) load I (187) esp_image: segment 2: paddr=0x00050018 vaddr=0x400d0018 size=0xc376c (800620) map 0x400d0018: _flash_cache_start at ??:?

I (472) esp_image: segment 3: paddr=0x0011378c vaddr=0x3ffc0b1c size=0x02424 ( 9252) load I (476) esp_image: segment 4: paddr=0x00115bb8 vaddr=0x40080000 size=0x00400 ( 1024) load 0x40080000: _WindowOverflow4 at D:/Wahdan/AFR_08_19/amazon-freertos/freertos_kernel/portable/ThirdParty/GCC/Xtensa_ESP32/xtensa_vectors.S:1685

I (479) esp_image: segment 5: paddr=0x00115fc0 vaddr=0x40080400 size=0x16598 ( 91544) load I (539) boot: Loaded app from partition at offset 0x20000 I (539) boot: ota rollback check done I (539) boot: Disabling RNG early entropy source... I (544) cpu_start: Pro cpu up. I (547) cpu_start: Single core mode I (552) heap_init: Initializing. RAM available for dynamic allocation: I (559) heap_init: At 3FFAFF10 len 000000F0 (0 KiB): DRAM I (565) heap_init: At 3FFD1258 len 0000EDA8 (59 KiB): DRAM I (571) heap_init: At 3FFE0440 len 00003BC0 (14 KiB): D/IRAM I (577) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM I (584) heap_init: At 40096998 len 00009668 (37 KiB): IRAM I (590) cpu_start: Pro cpu start user code I (272) cpu_start: Starting scheduler on PRO CPU. I (296) uart: queue free spaces: 10 0 1 [IP-task] prvIPTask started I (296) PKCS11: Initializing NVS partition: "storage" E (316) PKCS11: failed nvs get file size 4354 0 1 4 [main] Write certificate... 2 19 [main] Device credential provisioning succeeded. I (476) BTDM_INIT: BT controller compile version [3828e65]

I (476) system_api: Base MAC address is not set, read default base MAC address from BLK0 of EFUSE I (536) phy: phy_version: 4008, c9ae59f, Jan 25 2019, 16:54:06, 0, 0 3 58 [iot_thread] [INFO ][INIT][580] SDK successfully initialized. I (896) wifi: wifi driver task: 3ffdfd48, prio:23, stack:3584, core=0 I (896) wifi: wifi firmware version: dbb148a I (896) wifi: config NVS flash: enabled I (896) wifi: config nano formating: disabled I (906) system_api: Base MAC address is not set, read default base MAC address from BLK0 of EFUSE I (916) system_api: Base MAC address is not set, read default base MAC address from BLK0 of EFUSE I (926) wifi: Init dynamic tx buffer num: 64 I (926) wifi: Init data frame dynamic rx buffer num: 64 I (936) wifi: Init management frame dynamic rx buffer num: 64 I (936) wifi: Init static rx buffer size: 1600 I (946) wifi: Init static rx buffer num: 16 I (946) wifi: Init dynamic rx buffer num: 64 I (956) wifi: mode : sta (30:ae:a4:22:ce:80) I (956) WIFI: SYSTEM_EVENT_STA_START I (1686) wifi: n:6 0, o:1 0, ap:255 255, sta:6 0, prof:1 I (2666) wifi: state: init -> auth (b0) I (2676) wifi: state: auth -> assoc (0) I (2676) wifi: state: assoc -> run (10) I (2716) wifi: connected with Wahdan, channel 6 I (2716) wifi: pm start, type: 1

I (2716) WIFI: SYSTEM_EVENT_STA_CONNECTED 4 301 [IP-task] prvInitialiseDHCP: start after 25 ticks 5 301 [IP-task] vDHCPProcess: discover 6 302 [IP-task] vDHCPProcess: offer c0a82bbeip 7 302 [IP-task] vDHCPProcess: reply c0a82bbeip I (3356) event: sta ip: 192.168.43.190, mask: 255.255.255.0, gw: 192.168.43.1 I (3356) WIFI: SYSTEM_EVENT_STA_GOT_IP 8 307 [IP-task] vDHCPProcess: offer c0a82bbeip 9 307 [IP-task] vDHCPProcess: acked c0a82bbeip 10 307 [iot_thread] [INFO ][DEMO][3070] Successfully initialized the demo. Network type for the demo: 1 11 307 [iot_thread] Attempting automated selection of Greengrass device 12 365 [iot_thread] prvProcessDNSCache: add: 'a3rcy4vytvmu2y-ats.iot.us-west-2.amazonaws.com' @ 22d2df1eip 13 365 [iot_thread] FreeRTOS_connect: 64070 to 22d2df1eip:8443 14 365 [iot_thread] Socket 64070 -> 22d2df1eip:8443 State eCLOSED->eCONNECT_SYN 15 365 [IP-task] prvSocketSetMSS: 1400 bytes for 22d2df1eip:8443 16 365 [IP-task] prvWinScaleFactor: uxRxWinSize 1 MSS 1400 Factor 0 17 365 [IP-task] Connect[22d2df1eip:8443]: next timeout 1: 3000 ms 18 426 [IP-task] MSS change 1400 -> 1388 19 426 [IP-task] Change mss 1400 => 1388 20 426 [IP-task] TCP: active 64070 => 22d2df1eip:8443 set ESTAB (scaling 1) 21 426 [IP-task] Socket 64070 -> 22d2df1eip:8443 State eCONNECT_SYN->eESTABLISHED 22 487 [IP-task] MSS: sending 1388 23 529 [IP-task] SACK[64070,8443]: optlen 12 sending 2083 - 2777 24 1225 [iot_thread] About to close socket. 25 1225 [IP-task] Socket 64070 -> 22d2df1eip:8443 State eESTABLISHED->eFIN_WAIT_1 26 1286 [IP-task] Socket 64070 -> 22d2df1eip:8443 State eFIN_WAIT_1->eCLOSE_WAIT 27 1286 [IP-task] FreeRTOS_closesocket[64070 to 22d2df1eip:8443]: buffers 60 socks 0 28 1287 [iot_thread] Socket closed. 29 1287 [iot_thread] Stack high watermark for discovery helper task: 5192. 30 1288 [iot_thread] prvProcessDNSCache: add: 'ec2-54-213-226-188.us-west-2.compute.amazonaws.com' @ 36d5e2bcip 31 1289 [iot_thread] FreeRTOS_connect: 24324 to 36d5e2bcip:8883 32 1289 [iot_thread] Socket 24324 -> 36d5e2bcip:8883 State eCLOSED->eCONNECT_SYN 33 1289 [IP-task] prvSocketSetMSS: 1400 bytes for 36d5e2bcip:8883 34 1289 [IP-task] prvWinScaleFactor: uxRxWinSize 1 MSS 1400 Factor 0 35 1289 [IP-task] Connect[36d5e2bcip:8883]: next timeout 1: 3000 ms 36 1347 [IP-task] MSS change 1400 -> 1388 37 1347 [IP-task] Change mss 1400 => 1388 38 1347 [IP-task] TCP: active 24324 => 36d5e2bcip:8883 set ESTAB (scaling 1) 39 1348 [IP-task] Socket 24324 -> 36d5e2bcip:8883 State eCONNECT_SYN->eESTABLISHED 40 1409 [IP-task] MSS: sending 1388 41 1799 [iot_thread] About to close socket. 42 1799 [IP-task] Socket 24324 -> 36d5e2bcip:8883 State eESTABLISHED->eFIN_WAIT_1 43 1839 [IP-task] Socket 24324 -> 36d5e2bcip:8883 State eFIN_WAIT_1->eCLOSE_WAIT 44 1839 [IP-task] FreeRTOS_closesocket[24324 to 36d5e2bcip:8883]: buffers 60 socks 0 45 1839 [iot_thread] Socket closed. 46 1840 [iot_thread] Stack high watermark for discovery helper task: 2600. 47 1840 [iot_thread] Greengrass device discovered. 48 1840 [iot_thread] Establishing MQTT communication to Greengrass... 49 1840 [iot_thread] prvProcessDNSCache: look-up: 'ec2-54-213-226-188.us-west-2.compute.amazonaws.com' @ 36d5e2bcip 50 1840 [iot_thread] FreeRTOS_gethostbyname: found 'ec2-54-213-226-188.us-west-2.compute.amazonaws.com' in cache: bce2d536ip 51 1841 [iot_thread] FreeRTOS_connect: 25012 to 36d5e2bcip:8883 52 1841 [iot_thread] Socket 25012 -> 36d5e2bcip:8883 State eCLOSED->eCONNECT_SYN 53 1841 [IP-task] prvSocketSetMSS: 1400 bytes for 36d5e2bcip:8883 54 1841 [IP-task] prvWinScaleFactor: uxRxWinSize 1 MSS 1400 Factor 0 55 1841 [IP-task] Connect[36d5e2bcip:8883]: next timeout 1: 3000 ms 56 1890 [IP-task] eCONNECT_SYN: flags 0012 expected, not 0010 57 1890 [IP-task] Socket 25012 -> 36d5e2bcip:8883 State eCONNECT_SYN->eCLOSE_WAIT ets Jun 8 2016 00:22:57

rst:0x1 (POWERON_RESET),boot:0x13 (SPI_FAST_FLASH_BOOT) configsip: 0, SPIWP:0xee clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00 mode:DIO, clock div:2 load:0x3fff0018,len:4 load:0x3fff001c,len:6252 load:0x40078000,len:11276 ho 0 tail 12 room 4 load:0x40080000,len:6084 0x40080000: _WindowOverflow4 at D:/Wahdan/AFR_08_19/amazon-freertos/freertos_kernel/portable/ThirdParty/GCC/Xtensa_ESP32/xtensa_vectors.S:1685

entry 0x4008032c 0x4008032c: _KernelExceptionVector at ??:?

I (30) boot: ESP-IDF v3.1.3-25-g36733db8d 2nd stage bootloader I (31) boot: compile time 13:22:56 I (31) boot: Enabling RNG early entropy source... I (36) boot: SPI Speed : 40MHz I (40) boot: SPI Mode : DIO I (44) boot: SPI Flash Size : 4MB I (48) boot: Partition Table: I (52) boot: ## Label Usage Type ST Offset Length I (59) boot: 0 nvs WiFi data 01 02 00010000 00006000 I (67) boot: 1 otadata OTA data 01 00 00016000 00002000 I (74) boot: 2 phy_init RF data 01 01 00018000 00001000 I (82) boot: 3 ota_0 OTA app 00 10 00020000 00177000 I (89) boot: 4 ota_1 OTA app 00 11 001a0000 00177000 I (97) boot: 5 storage WiFi data 01 02 00317000 00010000 I (104) boot: End of partition table I (108) esp_image: segment 0: paddr=0x00020020 vaddr=0x3f400020 size=0x2f4cc (193740) map I (185) esp_image: segment 1: paddr=0x0004f4f4 vaddr=0x3ffc0000 size=0x00b1c ( 2844) load I (187) esp_image: segment 2: paddr=0x00050018 vaddr=0x400d0018 size=0xc376c (800620) map 0x400d0018: _flash_cache_start at ??:?

I (472) esp_image: segment 3: paddr=0x0011378c vaddr=0x3ffc0b1c size=0x02424 ( 9252) load I (476) esp_image: segment 4: paddr=0x00115bb8 vaddr=0x40080000 size=0x00400 ( 1024) load 0x40080000: _WindowOverflow4 at D:/Wahdan/AFR_08_19/amazon-freertos/freertos_kernel/portable/ThirdParty/GCC/Xtensa_ESP32/xtensa_vectors.S:1685

I (479) esp_image: segment 5: paddr=0x00115fc0 vaddr=0x40080400 size=0x16598 ( 91544) load I (539) boot: Loaded app from partition at offset 0x20000 I (539) boot: ota rollback check done I (539) boot: Disabling RNG early entropy source... I (544) cpu_start: Pro cpu up. I (547) cpu_start: Single core mode I (552) heap_init: Initializing. RAM available for dynamic allocation: I (559) heap_init: At 3FFAFF10 len 000000F0 (0 KiB): DRAM I (565) heap_init: At 3FFD1258 len 0000EDA8 (59 KiB): DRAM I (571) heap_init: At 3FFE0440 len 00003BC0 (14 KiB): D/IRAM I (577) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM I (584) heap_init: At 40096998 len 00009668 (37 KiB): IRAM I (590) cpu_start: Pro cpu start user code I (272) cpu_start: Starting scheduler on PRO CPU. I (296) uart: queue free spaces: 10 0 1 [IP-task] prvIPTask started I (296) PKCS11: Initializing NVS partition: "storage" E (306) PKCS11: failed nvs get file size 4354 0 1 4 [main] Write certificate... 2 19 [main] Device credential provisioning succeeded. I (476) BTDM_INIT: BT controller compile version [3828e65]

I (476) system_api: Base MAC address is not set, read default base MAC address from BLK0 of EFUSE I (536) phy: phy_version: 4008, c9ae59f, Jan 25 2019, 16:54:06, 0, 0 3 59 [iot_thread] [INFO ][INIT][580] SDK successfully initialized. I (906) wifi: wifi driver task: 3ffdb480, prio:23, stack:3584, core=0 I (906) wifi: wifi firmware version: dbb148a I (906) wifi: config NVS flash: enabled I (906) wifi: config nano formating: disabled I (906) system_api: Base MAC address is not set, read default base MAC address from BLK0 of EFUSE I (916) system_api: Base MAC address is not set, read default base MAC address from BLK0 of EFUSE I (936) wifi: Init dynamic tx buffer num: 64 I (936) wifi: Init data frame dynamic rx buffer num: 64 I (936) wifi: Init management frame dynamic rx buffer num: 64 I (946) wifi: Init static rx buffer size: 1600 I (946) wifi: Init static rx buffer num: 16 I (956) wifi: Init dynamic rx buffer num: 64 I (966) wifi: mode : sta (30:ae:a4:22:ce:80) I (966) WIFI: SYSTEM_EVENT_STA_START I (1686) wifi: n:6 0, o:1 0, ap:255 255, sta:6 0, prof:1 I (2676) wifi: state: init -> auth (b0) I (2686) wifi: state: auth -> assoc (0) I (2686) wifi: state: assoc -> run (10) I (2716) wifi: connected with Wahdan, channel 6 I (2716) wifi: pm start, type: 1

I (2716) WIFI: SYSTEM_EVENT_STA_CONNECTED 4 301 [IP-task] prvInitialiseDHCP: start after 25 ticks 5 301 [IP-task] vDHCPProcess: discover 6 302 [IP-task] vDHCPProcess: offer c0a82bbeip 7 302 [IP-task] vDHCPProcess: reply c0a82bbeip I (3496) event: sta ip: 192.168.43.190, mask: 255.255.255.0, gw: 192.168.43.1 I (3496) WIFI: SYSTEM_EVENT_STA_GOT_IP 8 321 [IP-task] vDHCPProcess: offer c0a82bbeip 9 321 [IP-task] vDHCPProcess: acked c0a82bbeip 10 322 [iot_thread] [INFO ][DEMO][3220] Successfully initialized the demo. Network type for the demo: 1 11 322 [iot_thread] Attempting automated selection of Greengrass device 12 324 [iot_thread] prvProcessDNSCache: add: 'a3rcy4vytvmu2y-ats.iot.us-west-2.amazonaws.com' @ 342273a8ip 13 325 [iot_thread] FreeRTOS_connect: 64070 to 342273a8ip:8443 14 325 [iot_thread] Socket 64070 -> 342273a8ip:8443 State eCLOSED->eCONNECT_SYN 15 325 [IP-task] prvSocketSetMSS: 1400 bytes for 342273a8ip:8443 16 325 [IP-task] prvWinScaleFactor: uxRxWinSize 1 MSS 1400 Factor 0 17 325 [IP-task] Connect[342273a8ip:8443]: next timeout 1: 3000 ms 18 403 [IP-task] MSS change 1400 -> 1388 19 403 [IP-task] Change mss 1400 => 1388 20 403 [IP-task] TCP: active 64070 => 342273a8ip:8443 set ESTAB (scaling 1) 21 403 [IP-task] Socket 64070 -> 342273a8ip:8443 State eCONNECT_SYN->eESTABLISHED 22 485 [IP-task] MSS: sending 1388 23 546 [IP-task] SACK[64070,8443]: optlen 12 sending 2083 - 2777 24 1462 [iot_thread] About to close socket. 25 1462 [IP-task] Socket 64070 -> 342273a8ip:8443 State eESTABLISHED->eFIN_WAIT_1 26 1492 [IP-task] Socket 64070 -> 342273a8ip:8443 State eFIN_WAIT_1->eCLOSE_WAIT 27 1492 [IP-task] FreeRTOS_closesocket[64070 to 342273a8ip:8443]: buffers 60 socks 0 28 1493 [iot_thread] Socket closed. 29 1493 [iot_thread] Stack high watermark for discovery helper task: 5140. 30 1506 [iot_thread] prvProcessDNSCache: add: 'ec2-54-213-226-188.us-west-2.compute.amazonaws.com' @ 36d5e2bcip 31 1507 [iot_thread] FreeRTOS_connect: 24324 to 36d5e2bcip:8883 32 1507 [iot_thread] Socket 24324 -> 36d5e2bcip:8883 State eCLOSED->eCONNECT_SYN 33 1507 [IP-task] prvSocketSetMSS: 1400 bytes for 36d5e2bcip:8883 34 1507 [IP-task] prvWinScaleFactor: uxRxWinSize 1 MSS 1400 Factor 0 35 1507 [IP-task] Connect[36d5e2bcip:8883]: next timeout 1: 3000 ms 36 1556 [IP-task] MSS change 1400 -> 1388 37 1556 [IP-task] Change mss 1400 => 1388 38 1556 [IP-task] TCP: active 24324 => 36d5e2bcip:8883 set ESTAB (scaling 1) 39 1556 [IP-task] Socket 24324 -> 36d5e2bcip:8883 State eCONNECT_SYN->eESTABLISHED 40 1617 [IP-task] MSS: sending 1388 41 2001 [iot_thread] About to close socket. 42 2001 [IP-task] Socket 24324 -> 36d5e2bcip:8883 State eESTABLISHED->eFIN_WAIT_1 43 2062 [IP-task] Socket 24324 -> 36d5e2bcip:8883 State eFIN_WAIT_1->eCLOSE_WAIT 44 2062 [IP-task] FreeRTOS_closesocket[24324 to 36d5e2bcip:8883]: buffers 60 socks 0 45 2062 [iot_thread] Socket closed. 46 2062 [iot_thread] Stack high watermark for discovery helper task: 2772. 47 2062 [iot_thread] Greengrass device discovered. 48 2062 [iot_thread] Establishing MQTT communication to Greengrass... 49 2062 [iot_thread] prvProcessDNSCache: look-up: 'ec2-54-213-226-188.us-west-2.compute.amazonaws.com' @ 36d5e2bcip 50 2062 [iot_thread] FreeRTOS_gethostbyname: found 'ec2-54-213-226-188.us-west-2.compute.amazonaws.com' in cache: bce2d536ip 51 2063 [iot_thread] FreeRTOS_connect: 25012 to 36d5e2bcip:8883 52 2063 [iot_thread] Socket 25012 -> 36d5e2bcip:8883 State eCLOSED->eCONNECT_SYN 53 2063 [IP-task] prvSocketSetMSS: 1400 bytes for 36d5e2bcip:8883 54 2063 [IP-task] prvWinScaleFactor: uxRxWinSize 1 MSS 1400 Factor 0 55 2063 [IP-task] Connect[36d5e2bcip:8883]: next timeout 1: 3000 ms 56 2123 [IP-task] eCONNECT_SYN: flags 0012 expected, not 0010 57 2123 [IP-task] Socket 25012 -> 36d5e2bcip:8883 State eCONNECT_SYN->eCLOSE_WAIT 58 2564 [iot_thread] [ERROR][NET][25640] Failed to establish new connection. 59 2564 [IP-task] FreeRTOS_closesocket[25012 to 36d5e2bcip:8883]: buffers 60 socks 0 60 2564 [iot_thread] [ERROR][MQTT][25640] Failed to establish new MQTT connection, error NETWORK ERROR. 61 2564 [iot_thread] ERROR: Could not connect to the Broker. 62 2564 [iot_thread] Heap low watermark: 8840. Stack high watermark: 2772. 63 2564 [iot_thread] ----Demo finished---- ets Jun 8 2016 00:22:57

rst:0x1 (POWERON_RESET),boot:0x13 (SPI_FAST_FLASH_BOOT) configsip: 0, SPIWP:0xee clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00 mode:DIO, clock div:2 load:0x3fff0018,len:4 load:0x3fff001c,len:6252 load:0x40078000,len:11276 ho 0 tail 12 room 4 load:0x40080000,len:6084 0x40080000: _WindowOverflow4 at D:/Wahdan/AFR_08_19/amazon-freertos/freertos_kernel/portable/ThirdParty/GCC/Xtensa_ESP32/xtensa_vectors.S:1685

entry 0x4008032c 0x4008032c: _KernelExceptionVector at ??:?

I (30) boot: ESP-IDF v3.1.3-25-g36733db8d 2nd stage bootloader I (30) boot: compile time 13:22:56 I (31) boot: Enabling RNG early entropy source... I (36) boot: SPI Speed : 40MHz I (40) boot: SPI Mode : DIO I (44) boot: SPI Flash Size : 4MB I (48) boot: Partition Table: I (52) boot: ## Label Usage Type ST Offset Length I (59) boot: 0 nvs WiFi data 01 02 00010000 00006000 I (67) boot: 1 otadata OTA data 01 00 00016000 00002000 I (74) boot: 2 phy_init RF data 01 01 00018000 00001000 I (82) boot: 3 ota_0 OTA app 00 10 00020000 00177000 I (89) boot: 4 ota_1 OTA app 00 11 001a0000 00177000 I (97) boot: 5 storage WiFi data 01 02 00317000 00010000 I (104) boot: End of partition table I (108) esp_image: segment 0: paddr=0x00020020 vaddr=0x3f400020 size=0x2f4cc (193740) map I (185) esp_image: segment 1: paddr=0x0004f4f4 vaddr=0x3ffc0000 size=0x00b1c ( 2844) load I (187) esp_image: segment 2: paddr=0x00050018 vaddr=0x400d0018 size=0xc376c (800620) map 0x400d0018: _flash_cache_start at ??:?

I (472) esp_image: segment 3: paddr=0x0011378c vaddr=0x3ffc0b1c size=0x02424 ( 9252) load I (476) esp_image: segment 4: paddr=0x00115bb8 vaddr=0x40080000 size=0x00400 ( 1024) load 0x40080000: _WindowOverflow4 at D:/Wahdan/AFR_08_19/amazon-freertos/freertos_kernel/portable/ThirdParty/GCC/Xtensa_ESP32/xtensa_vectors.S:1685

I (479) esp_image: segment 5: paddr=0x00115fc0 vaddr=0x40080400 size=0x16598 ( 91544) load I (539) boot: Loaded app from partition at offset 0x20000 I (539) boot: ota rollback check done I (539) boot: Disabling RNG early entropy source... I (544) cpu_start: Pro cpu up. I (547) cpu_start: Single core mode I (552) heap_init: Initializing. RAM available for dynamic allocation: I (559) heap_init: At 3FFAFF10 len 000000F0 (0 KiB): DRAM I (565) heap_init: At 3FFD1258 len 0000EDA8 (59 KiB): DRAM I (571) heap_init: At 3FFE0440 len 00003BC0 (14 KiB): D/IRAM I (577) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM I (584) heap_init: At 40096998 len 00009668 (37 KiB): IRAM I (590) cpu_start: Pro cpu start user code I (272) cpu_start: Starting scheduler on PRO CPU. I (296) uart: queue free spaces: 10 0 1 [IP-task] prvIPTask started I (296) PKCS11: Initializing NVS partition: "storage" E (306) PKCS11: failed nvs get file size 4354 0 1 7 [main] Write certificate... 2 18 [main] Device credential provisioning succeeded. I (466) BTDM_INIT: BT controller compile version [3828e65]

I (476) system_api: Base MAC address is not set, read default base MAC address from BLK0 of EFUSE I (536) phy: phy_version: 4008, c9ae59f, Jan 25 2019, 16:54:06, 0, 0 3 58 [iot_thread] [INFO ][INIT][580] SDK successfully initialized. I (896) wifi: wifi driver task: 3ffdb13c, prio:23, stack:3584, core=0 I (896) wifi: wifi firmware version: dbb148a I (896) wifi: config NVS flash: enabled I (906) wifi: config nano formating: disabled I (906) system_api: Base MAC address is not set, read default base MAC address from BLK0 of EFUSE I (916) system_api: Base MAC address is not set, read default base MAC address from BLK0 of EFUSE I (936) wifi: Init dynamic tx buffer num: 64 I (936) wifi: Init data frame dynamic rx buffer num: 64 I (936) wifi: Init management frame dynamic rx buffer num: 64 I (936) wifi: Init static rx buffer size: 1600 I (946) wifi: Init static rx buffer num: 16 I (946) wifi: Init dynamic rx buffer num: 64 I (956) wifi: mode : sta (30:ae:a4:22:ce:80) I (956) WIFI: SYSTEM_EVENT_STA_START I (1686) wifi: n:6 0, o:1 0, ap:255 255, sta:6 0, prof:1 I (2666) wifi: state: init -> auth (b0) I (2676) wifi: state: auth -> assoc (0) I (2686) wifi: state: assoc -> run (10) I (2716) wifi: connected with Wahdan, channel 6 I (2716) wifi: pm start, type: 1

I (2716) WIFI: SYSTEM_EVENT_STA_CONNECTED 4 301 [IP-task] prvInitialiseDHCP: start after 25 ticks 5 301 [IP-task] vDHCPProcess: discover 6 303 [IP-task] vDHCPProcess: offer c0a82bbeip 7 303 [IP-task] vDHCPProcess: reply c0a82bbeip I (3346) event: sta ip: 192.168.43.190, mask: 255.255.255.0, gw: 192.168.43.1 I (3346) WIFI: SYSTEM_EVENT_STA_GOT_IP 8 306 [IP-task] vDHCPProcess: offer c0a82bbeip 9 306 [IP-task] vDHCPProcess: acked c0a82bbeip 10 307 [iot_thread] [INFO ][DEMO][3070] Successfully initialized the demo. Network type for the demo: 1 11 307 [iot_thread] Attempting automated selection of Greengrass device 12 308 [iot_thread] prvProcessDNSCache: add: 'a3rcy4vytvmu2y-ats.iot.us-west-2.amazonaws.com' @ 22d2df1eip 13 310 [iot_thread] FreeRTOS_connect: 64070 to 22d2df1eip:8443 14 310 [iot_thread] Socket 64070 -> 22d2df1eip:8443 State eCLOSED->eCONNECT_SYN 15 310 [IP-task] prvSocketSetMSS: 1400 bytes for 22d2df1eip:8443 16 310 [IP-task] prvWinScaleFactor: uxRxWinSize 1 MSS 1400 Factor 0 17 310 [IP-task] Connect[22d2df1eip:8443]: next timeout 1: 3000 ms 18 377 [IP-task] MSS change 1400 -> 1388 19 377 [IP-task] Change mss 1400 => 1388 20 377 [IP-task] TCP: active 64070 => 22d2df1eip:8443 set ESTAB (scaling 1) 21 377 [IP-task] Socket 64070 -> 22d2df1eip:8443 State eCONNECT_SYN->eESTABLISHED 22 469 [IP-task] MSS: sending 1388 23 1248 [iot_thread] About to close socket. 24 1248 [IP-task] Socket 64070 -> 22d2df1eip:8443 State eESTABLISHED->eFIN_WAIT_1 25 1288 [IP-task] Socket 64070 -> 22d2df1eip:8443 State eFIN_WAIT_1->eCLOSE_WAIT 26 1289 [IP-task] FreeRTOS_closesocket[64070 to 22d2df1eip:8443]: buffers 60 socks 0 27 1289 [iot_thread] Socket closed. 28 1289 [iot_thread] Stack high watermark for discovery helper task: 5200. 29 1290 [iot_thread] prvProcessDNSCache: add: 'ec2-54-213-226-188.us-west-2.compute.amazonaws.com' @ 36d5e2bcip 30 1291 [iot_thread] FreeRTOS_connect: 24324 to 36d5e2bcip:8883 31 1291 [iot_thread] Socket 24324 -> 36d5e2bcip:8883 State eCLOSED->eCONNECT_SYN 32 1291 [IP-task] prvSocketSetMSS: 1400 bytes for 36d5e2bcip:8883 33 1291 [IP-task] prvWinScaleFactor: uxRxWinSize 1 MSS 1400 Factor 0 34 1291 [IP-task] Connect[36d5e2bcip:8883]: next timeout 1: 3000 ms 35 1329 [IP-task] MSS change 1400 -> 1388 36 1329 [IP-task] Change mss 1400 => 1388 37 1329 [IP-task] TCP: active 24324 => 36d5e2bcip:8883 set ESTAB (scaling 1) 38 1329 [IP-task] Socket 24324 -> 36d5e2bcip:8883 State eCONNECT_SYN->eESTABLISHED 39 1391 [IP-task] MSS: sending 1388 40 1780 [iot_thread] About to close socket. 41 1781 [IP-task] Socket 24324 -> 36d5e2bcip:8883 State eESTABLISHED->eFIN_WAIT_1 42 1841 [IP-task] Socket 24324 -> 36d5e2bcip:8883 State eFIN_WAIT_1->eCLOSE_WAIT 43 1842 [IP-task] FreeRTOS_closesocket[24324 to 36d5e2bcip:8883]: buffers 60 socks 0 44 1842 [iot_thread] Socket closed. 45 1842 [iot_thread] Stack high watermark for discovery helper task: 2768. 46 1842 [iot_thread] Greengrass device discovered. 47 1842 [iot_thread] Establishing MQTT communication to Greengrass... 48 1842 [iot_thread] prvProcessDNSCache: look-up: 'ec2-54-213-226-188.us-west-2.compute.amazonaws.com' @ 36d5e2bcip 49 1842 [iot_thread] FreeRTOS_gethostbyname: found 'ec2-54-213-226-188.us-west-2.compute.amazonaws.com' in cache: bce2d536ip 50 1843 [iot_thread] FreeRTOS_connect: 25012 to 36d5e2bcip:8883 51 1843 [iot_thread] Socket 25012 -> 36d5e2bcip:8883 State eCLOSED->eCONNECT_SYN 52 1843 [IP-task] prvSocketSetMSS: 1400 bytes for 36d5e2bcip:8883 53 1843 [IP-task] prvWinScaleFactor: uxRxWinSize 1 MSS 1400 Factor 0 54 1843 [IP-task] Connect[36d5e2bcip:8883]: next timeout 1: 3000 ms 55 1923 [IP-task] MSS change 1400 -> 1388 56 1923 [IP-task] Change mss 1400 => 1388 57 1923 [IP-task] TCP: active 25012 => 36d5e2bcip:8883 set ESTAB (scaling 1) 58 1923 [IP-task] Socket 25012 -> 36d5e2bcip:8883 State eCONNECT_SYN->eESTABLISHED 59 2438 [iot_thread] ERROR: Handshake failed with error code -29312 60 2438 [iot_thread] [ERROR][NET][24380] Failed to establish new connection. 61 2438 [IP-task] FreeRTOS_closesocket[25012 to 36d5e2bcip:8883]: buffers 60 socks 0 62 2439 [iot_thread] [ERROR][MQTT][24390] Failed to establish new MQTT connection, error NETWORK ERROR. 63 2439 [iot_thread] ERROR: Could not connect to the Broker. 64 2439 [iot_thread] Heap low watermark: 8848. Stack high watermark: 2768. 65 2439 [iot_thread] ----Demo finished---- I (83686) wifi: state: run -> init (7c0) `

[ahmedwahdan]

@sarenameas Any updates related to this issue?

[sarenameas]

Hey ahmedwahdan,

Apologies for the delay. We are under investigation. I asked for logs earlier because I could reproduce your issue, but I wanted to see if you had the same one as me; and you did!

This the log I wanted to see if you had also:

56 2123 [IP-task] eCONNECT_SYN: flags 0012 expected, not 0010

It appears the server is responding with just and ACK instead of a SYN-ACK for a new connection request. We are working on this now. We will get back to you on our findings.

Thanks for your patience.

[sarenameas]

Hello again,

This has been addressed now with PR #1413 .

Thanks for bringing this issue to the light.

[ahmedwahdan]

Thanks @sarenameas for the fix. Could you please explain what was the issue?

[ahmedwahdan]

I got this crash sometimes `10 892 [IP-task] vDHCPProcess: offer c0a80106ip 11 892 [IP-task] vDHCPProcess: acked c0a80106ip 12 893 [iot_thread] [INFO ][DEMO][8930] Successfully initialized the demo. Network type for the demo: 1 13 893 [iot_thread] [INFO ][MQTT][8930] MQTT library successfully initialized. 14 893 [iot_thread] [INFO ][DEMO][8930] Attempting automated selection of Greengrass device

15 923 [iot_thread] prvProcessDNSCache: add: 'a3rcy4vytvmu2y-ats.iot.us-west-2.amazonaws.com' @ 327087e0ip 16 923 [iot_thread] FreeRTOS_connect: 35869 to 327087e0ip:8443 17 923 [iot_thread] Socket 35869 -> 327087e0ip:8443 State eCLOSED->eCONNECT_SYN 18 923 [IP-task] prvSocketSetMSS: 1400 bytes for 327087e0ip:8443 19 923 [IP-task] prvWinScaleFactor: uxRxWinSize 1 MSS 1400 Factor 0 20 923 [IP-task] Connect[327087e0ip:8443]: next timeout 1: 3000 ms 21 1076 [IP-task] MSS change 1400 -> 1412 22 1076 [IP-task] TCP: active 35869 => 327087e0ip:8443 set ESTAB (scaling 1) 23 1076 [IP-task] Socket 35869 -> 327087e0ip:8443 State eCONNECT_SYN->eESTABLISHED 24 1076 [IP-task] MSS change 1400 -> 1412 25 1592 [iot_thread] ERROR: Handshake failed with error code -29312 26 1592 [iot_thread] About to close socket. CORRUPT HEAP: multi_heap.c:474 detected at 0x3ffef288 abort() was called at PC 0x40093dc9 on core 0 0x40093dc9: multi_heap_assert at D:/Wahdan/AFR_08_19/amazon-freertos/vendors/espressif/esp-idf/components/heap/multi_heap.c:377 (inlined by) multi_heap_free_impl at D:/Wahdan/AFR_08_19/amazon-freertos/vendors/espressif/esp-idf/components/heap/multi_heap.c:474

Backtrace: 0x400943e8:0x3ffddda0 0x400945b7:0x3ffdddc0 0x40093dc9:0x3ffddde0 0x400823de:0x3ffdde00 0x40091dca:0x3ffdde20 0x400ebb72:0x3ffdde40 0x400f129e:0x3ffdde60 0x400f14dc:0x3ffdde80 0x400 edf99:0x3ffddea0 0x400e9a4e:0x3ffddec0 0x400e9b8f:0x3ffddef0 0x400e9521:0x3ffddf20 0x400e996b:0x3ffddf50 0x400e2ff1:0x3ffddf80 0x400e309b:0x3ffddfc0 0x400efbf3:0x3ffddfe0 0x400edaa1:0x3ffde000

0x400943e8: invoke_abort at D:/Wahdan/AFR_08_19/amazon-freertos/vendors/espressif/esp-idf/components/esp32/panic.c:676

0x400945b7: abort at D:/Wahdan/AFR_08_19/amazon-freertos/vendors/espressif/esp-idf/components/esp32/panic.c:676

0x40093dc9: multi_heap_assert at D:/Wahdan/AFR_08_19/amazon-freertos/vendors/espressif/esp-idf/components/heap/multi_heap.c:377 (inlined by) multi_heap_free_impl at D:/Wahdan/AFR_08_19/amazon-freertos/vendors/espressif/esp-idf/components/heap/multi_heap.c:474

0x400823de: heap_caps_free at D:/Wahdan/AFR_08_19/amazon-freertos/vendors/espressif/esp-idf/components/heap/heap_caps.c:123

0x40091dca: vQueueDelete at D:/Wahdan/AFR_08_19/amazon-freertos/freertos_kernel/queue.c:2364

0x400ebb72: C_CloseSession at D:/Wahdan/AFR_08_19/amazon-freertos/libraries/abstractions/pkcs11/mbedtls/iot_pkcs11_mbedtls.c:628

0x400f129e: prvFreeContext at D:/Wahdan/AFR_08_19/amazon-freertos/libraries/freertos_plus/standard/tls/src/iot_tls.c:129

0x400f14dc: TLS_Recv at D:/Wahdan/AFR_08_19/amazon-freertos/libraries/freertos_plus/standard/tls/src/iot_tls.c:886

0x400edf99: SOCKETS_Recv at D:/Wahdan/AFR_08_19/amazon-freertos/libraries/abstractions/secure_sockets/freertos_plus_tcp/iot_secure_sockets.c:231

0x400e9a4e: GGD_SecureConnect_Disconnect at D:/Wahdan/AFR_08_19/amazon-freertos/libraries/freertos_plus/aws/greengrass/src/aws_helper_secure_connect.c:201

0x400e9b8f: GGD_SecureConnect_Connect at D:/Wahdan/AFR_08_19/amazon-freertos/libraries/freertos_plus/aws/greengrass/src/aws_helper_secure_connect.c:165

0x400e9521: GGD_JSONRequestStart at D:/Wahdan/AFR_08_19/amazon-freertos/libraries/freertos_plus/aws/greengrass/src/aws_greengrass_discovery.c:251

0x400e996b: GGD_GetGGCIPandCertificate at D:/Wahdan/AFR_08_19/amazon-freertos/libraries/freertos_plus/aws/greengrass/src/aws_greengrass_discovery.c:174

0x400e2ff1: _discoverGreengrassCore at D:/Wahdan/AFR_08_19/amazon-freertos/demos/greengrass_connectivity/aws_greengrass_discovery_demo.c:215

0x400e309b: vStartGreenGrassDiscoveryTask at D:/Wahdan/AFR_08_19/amazon-freertos/demos/greengrass_connectivity/aws_greengrass_discovery_demo.c:284

0x400efbf3: runDemoTask at D:/Wahdan/AFR_08_19/amazon-freertos/demos/demo_runner/iot_demo_freertos.c:372

0x400edaa1: _threadRoutineWrapper at D:/Wahdan/AFR_08_19/amazon-freertos/libraries/abstractions/platform/freertos/iot_threads_freertos.c:318

Rebooting... ets Jun 8 2016 00:22:57

rst:0xc (SW_CPU_RESET),boot:0x13 (SPI_FAST_FLASH_BOOT) configsip: 0, SPIWP:0xee clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00 mode:DIO, clock div:2 load:0x3fff0018,len:4 load:0x3fff001c,len:6252 load:0x40078000,len:11276 ho 0 tail 12 room 4 load:0x40080000,len:6084 0x40080000: _WindowOverflow4 at D:/Wahdan/AFR_08_19/amazon-freertos/freertos_kernel/portable/ThirdParty/GCC/Xtensa_ESP32/xtensa_vectors.S:1685

entry 0x4008032c 0x4008032c: _KernelExceptionVector at ??:?

`