crash in tcp stack

[kglowacki]

after 24h, heap free

ESC[0;32mI (68236646) meter_intv: warming[0] pm1.0=2 pm2.5=8 pm10=8ESC[0m
ESC[0;33mW (68236950) http: couldn't acquire lock for SSL requestESC[0m
ESC[0;33mW (68236950) http: error connectESC[0m
D (68236950) http: Cleaning SSL connection.ESC[0m
ESC[0;33mW (68236953) ota: error response code=0ESC[0m
D (68236957) ota: fetch_last_ota_info failed [0x1001]ESC[0m
D (68236962) ota: sleep for 60 secESC[0m
D (68237486) mem: stack min (1152) - task 'pmsX003'ESC[0m
ESC[0;32mI (68237486) meter_intv: warming[0] pm1.0=5 pm2.5=5 pm10=16ESC[0m
D (68238326) mem: stack min (1152) - task 'pmsX003'ESC[0m
ESC[0;32mI (68238327) meter_intv: warming[0] pm1.0=3 pm2.5=5 pm10=5ESC[0m
D (68238399) mem: stack min (1104) - task 'bmx280'ESC[0m
D (68238402) bmx280: sensor (0) => Temperature : 29.09 C, Pressure: 1000.18 hPa, Humidity 31.27ESC[0m
ESC[0;32mI (68238403) app: env (0): temp : 29.09 C, pressure: 1000.18 hPa, humidity: 31.27 %ESC[0m
D (68239166) mem: stack min (1152) - task 'pmsX003'ESC[0m
ESC[0;32mI (68239167) meter_intv: warming[0] pm1.0=0 pm2.5=0 pm10=0ESC[0m
Guru Meditation Error of type LoadProhibited occurred on core 0. Exception was unhandled.
Register dump:
PC : 0x40086f65 PS : 0x00060933 A0 : 0x80085999 A1 : 0x3ffbd810
ESC[0;33m0x40086f65: uxListRemove at /opt/esp/esp-idf/components/freertos/./list.c:218
ESC[0m
A2 : 0x3ffaebc0 A3 : 0x00060923 A4 : 0x00000000 A5 : 0x00000000
A6 : 0x00000000 A7 : 0x00000000 A8 : 0x00000000 A9 : 0x3ffaebc0
A10 : 0x3ffaebc0 A11 : 0x00060923 A12 : 0x00060920 A13 : 0x3ffbd884
A14 : 0x00000000 A15 : 0x00000000 SAR : 0x00000019 EXCCAUSE: 0x0000001c
EXCVADDR: 0x00000004 LBEG : 0x4000c2e0 LEND : 0x4000c2f6 LCOUNT : 0xffffffff

Backtrace: 0x40086f65:0x3ffbd810 0x40085996:0x3ffbd830 0x40083f55:0x3ffbd850 0x40124c32:0x3ffbd890 0x40114e92:0x3ffbd8b0 0x401140da:0x3ffbd8d0
ESC[0;33m0x40086f65: uxListRemove at /opt/esp/esp-idf/components/freertos/./list.c:218
ESC[0m
ESC[0;33m0x40085996: xTaskRemoveFromEventList at /opt/esp/esp-idf/components/freertos/./tasks.c:3442
ESC[0m
ESC[0;33m0x40083f55: xQueueGenericSend at /opt/esp/esp-idf/components/freertos/./queue.c:2034
ESC[0m
ESC[0;33m0x40124c32: sys_sem_signal at /opt/esp/esp-idf/components/lwip/port/freertos/sys_arch.c:554
ESC[0m
ESC[0;33m0x40114e92: lwip_netconn_do_delconn at /opt/esp/esp-idf/components/lwip/api/api_msg.c:1813 (discriminator 6)
ESC[0m
ESC[0;33m0x401140da: tcpip_thread at /opt/esp/esp-idf/components/lwip/api/tcpip.c:474
ESC[0m

CPU halted.

[kglowacki]

another occurrence in 1.0. this time I was enabling/disabling in 30 sec intervals and after a few hours got a crash (w/o backtrace resolved though), sequence of events:

1. wifi reconnects
2. we send a POST to aws-iot
3. moment after we try to fetch ota status (also via ssl)
4. ota request fails due to SSL being locked by aws-iot request
5. lwip_netconn_do_delconn causes crash - but was it caused by ota or aws request? there's no aws related logs?

D (21491840) wifi: wifi state changed: STA DISCONNECTEDESC[0m
ESC[0;32mI (21491842) wifi: reconnectESC[0m
D (21491845) wifi: - Connecting to access point "cosmos-test" ...ESC[0m
I (21491973) wifi: n:1 0, o:1 0, ap:255 255, sta:1 0, prof:1
I (21491974) wifi: state: init -> auth (b0)
I (21491976) wifi: state: auth -> assoc (0)
I (21491981) wifi: state: assoc -> run (10)
I (21492002) wifi: connected with cosmos-test, channel 1
ESC[0;32mI (21492004) wifi: SYSTEM_EVENT_STA_CONNECTED
ESC[0;32mI (21492027) wifi: SYSTEM_EVENT_STA_GOT_IP
ESC[0;32mI (21492028) wifi:

*** SENSOR IP (network 'cosmos-test') http://10.42.0.163

D (21492029) serv: restart
D (21492032) wifi: wifi state changed: STA CONNECTED
D (21492040) http: Secure
D (21492157) http: POST a32on3oilq3poc.iot.eu-west-1.amazonaws.com/things/test_device_1/shadow
D (21492158) http: [sock=1],connecting to server IP:34.249.64.174,Port:8443...
D (21493360) ota: Check for OTA updates...
D (21493360) mem: stack min (2308) - task 'ota'
ESC[0;32mI (21493360) ota: fetch ota info from https://openairproject.com/ota/index.txt
D (21493366) http: Secure
D (21493371) http: GET openairproject.com/ota/index.txt
D (21496081) mem: stack min (1108) - task 'bmx280'
D (21496084) bmx280: sensor (0) => Temperature : 28.23 C, Pressure: 1011.61 hPa, Humidity 39.75ESC[0m
ESC[0;32mI (21496085) app: env (0): temp : 28.23 C, pressure: 1011.61 hPa, humidity: 39.75 %ESC[0m
D (21497844) mem: stack min (2152) - task 'pm_meter_trigger'ESC[0m
ESC[0;32mI (21497844) app: start measurementESC[0m
D (21497844) rgbled: ->received commandESC[0m
ESC[0;32mI (21497847) meter_intv: enable_sensors
D (21497851) app: set pin 21 => 1
D (21497855) app: set pin 22 => 1
ESC[0;32mI (21497858) pmsX003: enable(1)ESC[0m
D (21497862) pmsX003: set pin 10 => 1ESC[0m
D (21500788) mem: stack min (1156) - task 'pmsX003'ESC[0m
ESC[0;32mI (21500788) meter_intv: warming[0] pm1.0=22 pm2.5=44 pm10=44ESC[0m
D (21501092) mem: stack min (1108) - task 'bmx280'ESC[0m
D (21501095) bmx280: sensor (0) => Temperature : 28.19 C, Pressure: 1011.63 hPa, Humidity 39.92ESC[0m
ESC[0;32mI (21501096) app: env (0): temp : 28.19 C, pressure: 1011.63 hPa, humidity: 39.92 %ESC[0m
D (21501629) mem: stack min (1156) - task 'pmsX003'ESC[0m
ESC[0;32mI (21501629) meter_intv: warming[0] pm1.0=98 pm2.5=106 pm10=136ESC[0m
I (21501982) wifi: pm start, type:0

D (21502471) mem: stack min (1156) - task 'pmsX003'
I (21502471) meter_intv: warming[0] pm1.0=68 pm2.5=86 pm10=86
D (21503313) mem: stack min (1156) - task 'pmsX003'
I (21503314) meter_intv: warming[0] pm1.0=78 pm2.5=120 pm10=120
W (21503373) http: couldn't acquire lock for SSL request
W (21503373) http: error connect
D (21503373) http: Cleaning SSL connection.
W (21503376) ota: error response code=0
D (21503380) ota: fetch_last_ota_info failed [0x1001]
D (21503385) ota: sleep for 60 sec
D (21504155) mem: stack min (1156) - task 'pmsX003'
I (21504155) meter_intv: warming[0] pm1.0=38 pm2.5=49 pm10=49
D (21504997) mem: stack min (1156) - task 'pmsX003'
I (21504997) meter_intv: warming[0] pm1.0=38 pm2.5=49 pm10=55
D (21505839) mem: stack min (1156) - task 'pmsX003'
I (21505839) meter_intv: warming[0] pm1.0=43 pm2.5=71 pm10=82
D (21506103) mem: stack min (1108) - task 'bmx280'
D (21506106) bmx280: sensor (0) => Temperature : 28.17 C, Pressure: 1011.64 hPa, Humidity 39.98
I (21506107) app: env (0): temp : 28.17 C, pressure: 1011.64 hPa, humidity: 39.98 %
D (21506681) mem: stack min (1156) - task 'pmsX003'
I (21506681) meter_intv: warming[0] pm1.0=36 pm2.5=53 pm10=61
D (21507523) mem: stack min (1156) - task 'pmsX003'
I (21507524) meter_intv: warming[0] pm1.0=42 pm2.5=56 pm10=73
D (21508365) mem: stack min (1156) - task 'pmsX003'
I (21508365) meter_intv: collect[0] pm1.0=29 pm2.5=46 pm10=46
D (21509206) mem: stack min (1156) - task 'pmsX003'
I (21509207) meter_intv: collect[0] pm1.0=38 pm2.5=51 pm10=58
D (21510050) mem: stack min (1156) - task 'pmsX003'
I (21510050) meter_intv: collect[0] pm1.0=36 pm2.5=52 pm10=57
Guru Meditation Error of type LoadProhibited occurred on core 0. Exception was unhandled.
Register dump:
PC : 0x40086f65 PS : 0x00060c33 A0 : 0x80085999 A1 : 0x3ffbd810
A2 : 0x3ffaebc0 A3 : 0x00060c23 A4 : 0x00000000 A5 : 0x00000000
A6 : 0x00000000 A7 : 0x00000000 A8 : 0x00000000 A9 : 0x3ffaebc0
A10 : 0x3ffaebc0 A11 : 0x00060c23 A12 : 0x00060c20 A13 : 0x3ffbd884
A14 : 0x00000000 A15 : 0x00000000 SAR : 0x00000010 EXCCAUSE: 0x0000001c
EXCVADDR: 0x00000004 LBEG : 0x4000c2e0 LEND : 0x4000c2f6 LCOUNT : 0xffffffff

Backtrace: 0x40086f65:0x3ffbd810 0x40085996:0x3ffbd830 0x40083f55:0x3ffbd850 0x40124c32:0x3ffbd890 0x40114e92:0x3ffbd8b0 0x401140da:0x3ffbd8d0

0x40086f65 is in uxListRemove (/opt/esp/esp-idf/components/freertos/./list.c:218).
213
214 pxItemToRemove->pxNext->pxPrevious = pxItemToRemove->pxPrevious;
215 pxItemToRemove->pxPrevious->pxNext = pxItemToRemove->pxNext;
216
217 /* Make sure the index is left pointing to a valid item. */
218 if( pxList->pxIndex == pxItemToRemove )
219 {
220 pxList->pxIndex = pxItemToRemove->pxPrevious;
221 }
222 else

0x40085996 is in xTaskRemoveFromEventList (/opt/esp/esp-idf/components/freertos/./tasks.c:3043).
3038 This function assumes that a check has already been made to ensure that
3039 pxEventList is not empty. */
3040 if ( ( listLIST_IS_EMPTY( pxEventList ) ) == pdFALSE ) {
3041 pxUnblockedTCB = ( TCB_t * ) listGET_OWNER_OF_HEAD_ENTRY( pxEventList );
3042 configASSERT( pxUnblockedTCB );
3043 ( void ) uxListRemove( &( pxUnblockedTCB->xEventListItem ) );
3044 } else {
3045 taskEXIT_CRITICAL_ISR(&xTaskQueueMutex);
3046 return pdFALSE;
3047 }

0x40083f55 is in xQueueGenericSend (/opt/esp/esp-idf/components/freertos/./queue.c:763).
758 {
759 /* If there was a task waiting for data to arrive on the
760 queue then unblock it now. */
761 if( listLIST_IS_EMPTY( &( pxQueue->xTasksWaitingToReceive ) ) == pdFALSE )
762 {
763 if( xTaskRemoveFromEventList( &( pxQueue->xTasksWaitingToReceive ) ) == pdTRUE )
764 {

0x40124c32 is in sys_sem_signal (/opt/esp/esp-idf/components/lwip/port/freertos/sys_arch.c:129).
124 /-----------------------------------------------------------------------------------/
125 // Signals a semaphore
126 void
127 sys_sem_signal(sys_sem_t *sem)
128 {
129 xSemaphoreGive(*sem);
130 }

0x40114e92 is in lwip_netconn_do_delconn (/opt/esp/esp-idf/components/lwip/api/api_msg.c:1084).
1079 which is wrong! errfd instead? */
1080 API_EVENT(msg->conn, NETCONN_EVT_RCVPLUS, 0);
1081 API_EVENT(msg->conn, NETCONN_EVT_SENDPLUS, 0);
1082 }
1083 if (sys_sem_valid(LWIP_API_MSG_SEM(msg))) {
1084 TCPIP_APIMSG_ACK(msg);
1085 }
1086 }

0x401140da is in tcpip_thread (/opt/esp/esp-idf/components/lwip/api/tcpip.c:122).
117 switch (msg->type) {
118 #if !LWIP_TCPIP_CORE_LOCKING
119 case TCPIP_MSG_API:
120
121 LWIP_DEBUGF(TCPIP_DEBUG, ("tcpip_thread: API message %p\n", (void *)msg));
122 msg->msg.api.function(msg->msg.api.msg);
123 break;
124 case TCPIP_MSG_API_CALL:
125
126 LWIP_DEBUGF(TCPIP_DEBUG, ("tcpip_thread: API CALL message %p\n", (void *)msg));

[kglowacki]

espressif/esp-idf#242