Random crashes with multiple http requests

[burner-]

Basic Infos

After long consideration I decide to make issue of that. I am still not sure is that problem at my code or at core but I am out of options and because all happened at core I start believe that this problem can be at core. All suggestions are welcome to narrow down this problem.

Problem is reproducible with this project https://github.com/burner-/ESPRelayThermostat and if you dont want wait long time that problem come just refresh web page multiple times.

Hardware

Hardware: nodemcu 1.0
Core Version: 10.9.2016 version of git

Description

Problem is that all other things work fine but when I load that web page it randomly crash at different locations in core librarys. Some times it also just stuck without wdt reset. Every time crash is at core. Most of crashes are are at area where http library serve files from filesystem. Usual when it reset or stuck without callstack it serving dynamic data, not file from filesystem. Only connected thing is ds18b20 sensor and power come from usb 3 port directly to nodemcu so issue should not be at regulator/power issue.
Some times it looks like there is some kind race condition between udp and http client or even at http client but this is just guessing.

Settings in IDE

Module: ?Generic ESP8266 Module?
Flash Size: ?4MB/1MB?
CPU Frequency: ?80Mhz?
Flash Mode: ?qio?
Flash Frequency: ?40Mhz?
Upload Using: ?OTA / SERIAL?
Reset Method: ?ck / nodemcu?

Sketch

https://github.com/burner-/ESPRelayThermostat

At attachment there is list of some crashes.
crashlist.txt

[bebo-dot-dev]

You said

"you dont want wait long time that problem come just refresh web page multiple times"

Which page exactly in your github code is it that you're refreshing when you experience this crash?

If it's https://github.com/burner-/ESPRelayThermostat/blob/master/data/index.html that you're talking about, my suggestion is that you inline all js and css directly into this html doc, gzip the html doc and serve that gzipped doc.

At the moment, 1 request for this page will actually result in 6 requests because of the css and js resources being included and the crash you're seeing could be the result of these multiple requests overwhelming the device. 1 request with a single compressed response would be a better idea.

[burner-]

That is just workaround not fix. Yes with less loads it is less likely that it crash. But crashes and random stuck come with all pages. So I think it is preferred to first fix problem. Then optimize that all files are at one bundle. Another way it is like first hide that random problem to even more rare and then try to fix it.

[bebo-dot-dev]

Sure you've got a valid point there and I'm certain that you've identified an actual problem here.

I've seen these symptoms myself on occasion too and I chose to implement the workaround rather than going after the actual problem and the workaround does seem to have settled things down to a reasonably stable level for my use cases.

That said, attempting to locate the underlying cause of this problem is worth pursuing.

[burner-]

Looks that in ESP8266WebServer/src/Parsing.cpp there is malloc at readBytesWithTimeout. It returns to line 180. at row 207 there is free. But if content lenght is 0 then it does not free that allocation at all? I try move that free out from that if. It did not help (at least not resolve all crashes) but is that also one bug?

[bebo-dot-dev]

I agree this code path does look odd and it seems to be an improvement if the free on this line

Arduino/libraries/ESP8266WebServer/src/Parsing.cpp

Line 207 in 4897e00

free(plainBuf);

is moved below out of the if (contentLength > 0) { conditional block because that would ensure it's always freed.

The readBytesWithTimeout call / plainBuf allocation is all in the context of
if (method == HTTP_POST || method == HTTP_PUT || method == HTTP_PATCH || method == HTTP_DELETE){
and where the header sent is not multipart/form-data so it feels like a bit of a narrow case and it's not the bug where there's a crash experienced on page refresh (GET request) but I'd say you've still found a valid bug / memory leak here.

[burner-]

Do you know reason why with nodemcu 1.0 Debug menu item is missing under tools? Is it bug or feature :)

[burner-]

I now add debug parameters to boards.txt for nodemcu. Looks that some of crashes are "just random" and probably there is several different bugs at core. Anyhow probably is best to start from somewhere.
Looks that this is quite common. ? One thing what I dont understand how this flashRead ends to yield. And looks that some times yield is not safe to call and it will cause crash? But many arduino libraries trust that it is better to call yield too often than not at all? So is is good to cause panic when it is not allowed or better to just ignore that yield if it does not come at appropriate moment?

I start feeling that we are at so deep waters that we need @igrr to save us :)

Edit: I noted that row numbers does not match -> this has nothing to do with clock frequency

Request: /favicon.ico
Arguments:
request handler not found
Fatal exception 0(IllegalInstructionCause):
epc1=0x80000005, epc2=0x00000000, epc3=0x00000000, excvaddr=0x00000000, depc=0x00000000

Panic C:\Arduino\arduino-1.6.11\hardware\esp8266com\esp8266\libraries\ESP8266WiFi\src\include/DataSource.h:72 const uint8_t* BufferedStreamDataSource::get_buffer(size_t) [with TStream = Stream; uint8_t = unsigned char; size_t = unsigned int]

ctx: cont
sp: 3fff2c40 end: 3fff3110 offset: 01a0

stack>>>
3fff2de0: 756b6361 00000000 00002710 40213844
3fff2df0: 40211f42 00112000 00000100 3fff4bac
3fff2e00: 00112100 00000100 00112000 402146ea
3fff2e10: 3fff2ed0 00000003 0000001f 40001e4b
3fff2e20: 3fff4bac 00000000 00112000 00000000
3fff2e30: 3fff4000 3fff495c 00112000 3fff4b98
3fff2e40: 3fff4000 3fff495c 00112000 402067d8
3fff2e50: 00000100 3fff4784 00000000 00000100
3fff2e60: 00000002 00000000 0000000a 00000100
3fff2e70: 3fff4000 00012000 00000009 4020441d
3fff2e80: 00000000 00000080 00000000 00002e23
3fff2e90: 00000000 00000000 40203f04 00000000
3fff2ea0: 3fff4784 00000000 00000020 0000017d
3fff2eb0: 40001da0 ffffffff 00000002 40001db4
3fff2ec0: 40001f46 0000000b 00001f40 3ffe90a8
3fff2ed0: 3fff2f30 3fff2f50 3fff4000 40205c7e
3fff2ee0: 3fff65ec 00000000 3fff2ef4 3fff2ef0
3fff2ef0: 00000010 0000001c 00000000 401008cc
3fff2f00: 0000001c 0000057f 3fff2000 3fff2000
3fff2f10: 00000010 0000001c 00000000 3ffe90a8
3fff2f20: 00000000 3fff2f50 3fff4000 402039eb
3fff2f30: 00000010 0000001c 00000000 401008cc
3fff2f40: 00000010 3fff3ffc 00000001 40213fb5
3fff2f50: 3ffe904c 0000000c 3fff2ffc 3ffe90a8
3fff2f60: 00000010 3fff2ff0 3fff2ff0 40212e5f
3fff2f70: 3fff659c 0000000f 3fff2ff0 40212eab
3fff2f80: 3fff65ec 0000058d 0000058d 4010020c
3fff2f90: 00000000 3fff3134 3fff3030 402151a9
3fff2fa0: 3ffe90a8 00000000 3fff2fc0 40211fe4
3fff2fb0: 00000000 00000000 3fff3030 40209f53
3fff2fc0: 00000000 00000000 00000000 3fff20e4
3fff2fd0: 00000010 3fff3030 3fff3030 40212e5f
3fff2fe0: 3fff694c 0000000c 3fff3030 40212eab
3fff2ff0: 3fff65ec 0000000f 0000000f 3fff6764
3fff3000: 0000000f 0000000c 3fff3030 40212fe4
3fff3010: 00000000 00000018 3fff1408 3fff20e4
3fff3020: 00000000 3fff1448 3fff1408 4020a074
3fff3030: 3fff665c 0000000f 0000000c 4021243d
3fff3040: 3ffea288 3fff1448 3fff1408 40214a62
3fff3050: 00000000 00000000 3fff2028 4020e0f6
3fff3060: 00000000 3fff1448 3fff1408 4020e1e6
3fff3070: 3fff1cdc 3fff1448 00000001 4021243d
3fff3080: 3ffe9c70 00000002 00000000 4020d5d4
3fff3090: 0000000f 00000001 3fff2028 4021252c
3fff30a0: 00000000 00000000 3fff1408 3fff20e4
3fff30b0: 00000001 3fff142c 3fff1408 4020e438
3fff30c0: 3ffe9f30 00000000 000003e8 4020adb8
3fff30d0: 00000000 3fff6b34 3fff20dd 40209cf8
3fff30e0: 3fffdad0 00000000 3fff20dd 4020aecb
3fff30f0: 3fffdad0 00000000 3fff20dd 40213818
3fff3100: feefeffe feefeffe 3fff20f0 40100984
<<<stack<<<

ets Jan 8 2013,rst cause:4, boot mode:(3,6)

wdt reset
load 0x4010f000, len 1384, room 16
tail 8
chksum 0x2d
csum 0x2d
v00000000

~ld

Decoding 39 results
0x40213844: yield at C:\Arduino\arduino-1.6.11\hardware\esp8266com\esp8266\cores\esp8266/core_esp8266_main.cpp line 56
0x40211f42: EspClass::flashRead(unsigned int, unsigned int, unsigned int) at C:\Arduino\arduino-1.6.11\hardware\esp8266com\esp8266\cores\esp8266/Esp.cpp line 517
0x402146ea: spiffs_hal_read(unsigned int, unsigned int, unsigned char) at C:\Arduino\arduino-1.6.11\hardware\esp8266com\esp8266\cores\esp8266/spiffs_hal.cpp line 67
0x402067d8: spiffs_phys_rd at C:\Arduino\arduino-1.6.11\hardware\esp8266com\esp8266\cores\esp8266\spiffs/spiffs_cache.c line 145
0x4020441d: spiffs_obj_lu_find_entry_visitor at C:\Arduino\arduino-1.6.11\hardware\esp8266com\esp8266\cores\esp8266\spiffs/spiffs_nucleus.c line 941
0x40203f04: spiffs_object_find_object_index_header_by_name_v at C:\Arduino\arduino-1.6.11\hardware\esp8266com\esp8266\cores\esp8266\spiffs/spiffs_nucleus.c line 941
0x40205c7e: spiffs_object_find_object_index_header_by_name at C:\Arduino\arduino-1.6.11\hardware\esp8266com\esp8266\cores\esp8266\spiffs/spiffs_nucleus.c line 1465
0x401008cc: realloc at C:\Arduino\arduino-1.6.11\hardware\esp8266com\esp8266\cores\esp8266\umm_malloc/umm_malloc.c line 1714
0x402039eb: SPIFFS_stat at C:\Arduino\arduino-1.6.11\hardware\esp8266com\esp8266\cores\esp8266\spiffs/spiffs_hydrogen.c line 980
0x401008cc: realloc at C:\Arduino\arduino-1.6.11\hardware\esp8266com\esp8266\cores\esp8266\umm_malloc/umm_malloc.c line 1714
0x40213fb5: SPIFFSImpl::exists(char const_) at C:\Arduino\arduino-1.6.11\hardware\esp8266com\esp8266\cores\esp8266/spiffs_api.cpp line 63
0x40212e5f: String::changeBuffer(unsigned int) at C:\Arduino\arduino-1.6.11\hardware\esp8266com\esp8266\cores\esp8266/WString.cpp line 688
0x40212eab: String::reserve(unsigned int) at C:\Arduino\arduino-1.6.11\hardware\esp8266com\esp8266\cores\esp8266/WString.cpp line 688
0x4010020c: umm_free at C:\Arduino\arduino-1.6.11\hardware\esp8266com\esp8266\cores\esp8266\umm_malloc/umm_malloc.c line 1287
0x402151a9: fs::FS::exists(char const) at C:\Arduino\arduino-1.6.11\hardware\esp8266com\esp8266\cores\esp8266/FS.cpp line 214
0x40211fe4: fs::FS::exists(String const&) at C:\Arduino\arduino-1.6.11\hardware\esp8266com\esp8266\cores\esp8266/FS.cpp line 188
0x40209f53: handleFileRead(String) at C:\Users\tapsa\AppData\Local\Temp\build77afdee0e66bc23a5274dacbf19b7a58.tmp\sketch/global.h line 156
0x40212e5f: String::changeBuffer(unsigned int) at C:\Arduino\arduino-1.6.11\hardware\esp8266com\esp8266\cores\esp8266/WString.cpp line 688
0x40212eab: String::reserve(unsigned int) at C:\Arduino\arduino-1.6.11\hardware\esp8266com\esp8266\cores\esp8266/WString.cpp line 688
0x40212fe4: String::operator=(String const&) at C:\Arduino\arduino-1.6.11\hardware\esp8266com\esp8266\cores\esp8266/WString.cpp line 688
0x4020a074: handle_unknown() at C:\Users\tapsa\AppData\Local\Temp\build77afdee0e66bc23a5274dacbf19b7a58.tmp\sketch/global.h line 156
0x4021243d: Print::write(char const_) at C:\Arduino\arduino-1.6.11\hardware\esp8266com\esp8266\cores\esp8266/Print.cpp line 99
0x40214a62: std::_Function_handler ::_M_invoke(std::_Any_data const&) at C:\Users\tapsa\AppData\Local\Temp\build77afdee0e66bc23a5274dacbf19b7a58.tmp\sketch/global.h line 156
0x4020e0f6: std::function ::operator()() const at c:\arduino\arduino-1.6.11\hardware\esp8266com\esp8266\tools\xtensa-lx106-elf\xtensa-lx106-elf\include\c++\4.8.2/functional line 2331
0x4020e1e6: ESP8266WebServer::handleRequest() at C:\Arduino\arduino-1.6.11\hardware\esp8266com\esp8266\libraries\ESP8266WebServer\src\detail/RequestHandlersImpl.h line 53
0x4021243d: Print::write(char const) at C:\Arduino\arduino-1.6.11\hardware\esp8266com\esp8266\cores\esp8266/Print.cpp line 99
0x4020d5d4: FunctionRequestHandler::canHandle(HTTPMethod, String) at C:\Arduino\arduino-1.6.11\hardware\esp8266com\esp8266\libraries\ESP8266WebServer\src\detail/RequestHandlersImpl.h line 53
0x4021252c: Print::println() at C:\Arduino\arduino-1.6.11\hardware\esp8266com\esp8266\cores\esp8266/Print.cpp line 99
0x4020e438: ESP8266WebServer::handleClient() at C:\Arduino\arduino-1.6.11\hardware\esp8266com\esp8266\libraries\ESP8266WebServer\src\detail/RequestHandlersImpl.h line 53
0x4020adb8: handleScada() at C:\Users\tapsa\AppData\Local\Temp\build77afdee0e66bc23a5274dacbf19b7a58.tmp\sketch/global.h line 156
0x40209cf8: handleOTA() at C:\Users\tapsa\AppData\Local\Temp\build77afdee0e66bc23a5274dacbf19b7a58.tmp\sketch/global.h line 156
0x4020aecb: loop at C:\Users\tapsa\AppData\Local\Temp\build77afdee0e66bc23a5274dacbf19b7a58.tmp\sketch/global.h line 156
0x40213818: loop_wrapper at C:\Arduino\arduino-1.6.11\hardware\esp8266com\esp8266\cores\esp8266/core_esp8266_main.cpp line 56
0x40100984: cont_norm at C:\Arduino\arduino-1.6.11\hardware\esp8266com\esp8266\cores\esp8266/cont.S line 109

[bebo-dot-dev]

The only time I can say I've experienced seemingly random crashes and completely unexplained behaviour is when the power supply has been unstable. If it's a NodeMCU dev kit board with USB power you're working with, I'm afraid I don't have any experience with these types of boards.

[burner-]

I am not so sure are they completely random. after I comment out that panic() under yield then it stats looking that there is just lot of different kind exceptions that network stack try read or write wrong memory areas (LoadStoreAlignmentCause, StoreProhibitedCause)

[devyte]

@burner- I experienced this myself. I believe it's a combination of sync WifiServer and lwip 1.4, and it happens when the server receives a request when a previous request isn't done yet (browser quick refresh, concurrent requests of webpage elements, etc).
Please test:

• PR lwip2: lighter implementation #3362 (lwip2)
• ESPAsyncWebServer (similar api as ESP8266WebServer, but not a drop-in replacement)

[eighthree]

Will second @devyte 's comment on " when the server receives a request when a previous request isn't done yet (browser quick refresh, concurrent requests of webpage elements, etc).".

When I stress test my esp8266 project that serves a page with websockets, spamming requests causes my esp to gradually lose ram until it resets.

[devyte]

@eighthree what does your stress test look like?

[eighthree]

@devyte

Some context...

• using websockets on a page served up by the esp8266 to switch between modes on an LED strip
• the same page also loads 2 json files generated by the esp, modes.json which is loaded once and cached in localStorage because of its size and settings.json is loaded every time the page is loaded
• using tcpCleanup (see: memory leak 184 bytes at a time #1923 (comment) ) and monitoring it's output on serial

The stress test...

• Send consecutive websocket requests to change modes (click button to change, wait a few seconds, click another)
• Reload page multiple times
• Connect to the esp via multiple browsers, phone/desktop browser
• The tcpCleanup output doesn't necessarily indicate an impending crash although it can -- sometimes it will crash even when it reports having sufficient ram:

tcpCleanup completed RAM: 22280 change -88

• The serial monitor doesn't always return an exception I can decode, and sometimes it just freezes and I have to reset the hardware manually

Typical errors found when the esp crashes

dev 1153

 ets Jan  8 2013,rst cause:4, boot mode:(3,6)

wdt reseta
load 0x4010f000, len 1384, room 16 
tail 8
chksum 0x2d
csum 0x2d
v00000000
~ld

 ets Jan  8 2013,rst cause:2, boot mode:(1,7)


 ets Jan  8 2013,rst cause:4, boot mode:(1,7)

wdt reset

Exception 29: StoreProhibited: A store referenced a page mapped with an attribute that does not permit stores
Decoding 23 results
0x402378ef: pp_attach at ?? line ?
0x40226012: ieee80211_alloc_proberesp at ?? line ?
0x40225f30: ieee80211_alloc_proberesp at ?? line ?
0x401011de: pp_post at ?? line ?
0x40227824: scan_profile_check at ?? line ?
0x402260df: ieee80211_send_proberesp at ?? line ?
0x401007ec: calloc at C:\Users\eight\Documents\Arduino\hardware\esp8266com\esp8266\cores\esp8266\umm_malloc/umm_malloc.c line 1693
0x40222c30: hostap_input at ?? line ?
0x40222b03: hostap_input at ?? line ?
0x40228a43: sta_input at ?? line ?
0x40228aae: sta_input at ?? line ?
0x4022a771: cnx_node_search at ?? line ?
0x4022233f: hostap_input at ?? line ?
0x40236b70: ppRecycleRxPkt at ?? line ?
0x40104cfe: wdt_feed at ?? line ?
0x40236ea6: pp_tx_idle_timeout at ?? line ?
0x4023679b: ppPeocessRxPktHdr at ?? line ?
0x4021424f: loop_task at C:\Users\eight\Documents\Arduino\hardware\esp8266com\esp8266\cores\esp8266/core_esp8266_main.cpp line 57


Fatal exception 29(StoreProhibitedCause):
epc1=0x4000e1c3, epc2=0x00000000, epc3=0x00000000, excvaddr=0x00000018, depc=0x00000000

Exception (29):
epc1=0x4000e1c3 epc2=0x00000000 epc3=0x00000000 excvaddr=0x00000018 depc=0x00000000

ctx: sys 
sp: 3ffffc50 end: 3fffffb0 offset: 01a0

>>>stack>>>
3ffffdf0:  00006d30 4021df94 00000000 00000030  
3ffffe00:  40226012 40225f30 3fff4e94 00000008  
3ffffe10:  40237900 00000001 40227824 3ffffed0  
3ffffe20:  00000018 3fff13f8 3fff1374 00000000  
3ffffe30:  402260df 3ff20a00 3fff4e94 3ffed826  
3ffffe40:  3ffed80c 3ffffed0 3ffffed0 3fff5144  
3ffffe50:  00000038 7269616c 3fff2f54 3ffed80c  
3ffffe60:  00000000 3fff9b1c 00000038 401007ec  
3ffffe70:  3ffed816 3fff5344 40222c30 3ff20a00  
3ffffe80:  3fff4e94 3fff9b24 00000015 40222b03  
3ffffe90:  3fff21b0 3fff4adc 00000000 40228a43  
3ffffea0:  00000000 028afb88 40228aae 3fff4adc  
3ffffeb0:  3fff4ac4 ffffffc7 00000000 ffffffff  
3ffffec0:  40000f58 00000000 00000020 00000000  
3ffffed0:  00000000 10310b0b 00640100 00000051  
3ffffee0:  3ffede74 00000095 3ffede95 3ffede68  
3ffffef0:  3ffede9b 3ffede74 00000003 3ffedea6  
3fffff00:  4022a771 ffffffa3 00000000 3ffedec9  
3fffff10:  4022233f 3ffed80c 3fff0948 3fff4e94  
3fffff20:  00000000 3ffed816 3ffed82c 00000000  
3fffff30:  40236b70 00000000 00000000 3ffed816  
3fffff40:  40104cfe 00000064 3fff0948 3fff5344  
3fffff50:  3ffed800 00000000 00000003 40236ea6  
3fffff60:  3fff0948 3ffed800 3fffdcc0 3ffed038  
3fffff70:  3ffed81c 3fff5144 00000040 3ffed038  
3fffff80:  00000040 3fff0948 00000000 3fff3040  
3fffff90:  4023679b 3fffdab0 00000000 4021424f  
3fffffa0:  3ffed038 40000f49 3fffdab0 40000f49  
<<<stack<<<

 ets Jan  8 2013,rst cause:2, boot mode:(1,7)
 ets Jan  8 2013,rst cause:4, boot mode:(1,7)

wdt reset

Exception 29: StoreProhibited: A store referenced a page mapped with an attribute that does not permit stores
Decoding 23 results
0x4021df94: igmp_timer at core/timers.c line 217
0x40226012: ieee80211_alloc_proberesp at ?? line ?
0x40225f30: ieee80211_alloc_proberesp at ?? line ?
0x40237900: pp_attach at ?? line ?
0x40227824: scan_profile_check at ?? line ?
0x402260df: ieee80211_send_proberesp at ?? line ?
0x401007ec: calloc at C:\Users\eight\Documents\Arduino\hardware\esp8266com\esp8266\cores\esp8266\umm_malloc/umm_malloc.c line 1693
0x40222c30: hostap_input at ?? line ?
0x40222b03: hostap_input at ?? line ?
0x40228a43: sta_input at ?? line ?
0x40228aae: sta_input at ?? line ?
0x4022a771: cnx_node_search at ?? line ?
0x4022233f: hostap_input at ?? line ?
0x40236b70: ppRecycleRxPkt at ?? line ?
0x40104cfe: wdt_feed at ?? line ?
0x40236ea6: pp_tx_idle_timeout at ?? line ?
0x4023679b: ppPeocessRxPktHdr at ?? line ?
0x4021424f: loop_task at C:\Users\eight\Documents\Arduino\hardware\esp8266com\esp8266\cores\esp8266/core_esp8266_main.cpp line 57

[d-a-v]

@eighthree with latest master, can you enable all debug logs and show the serial console before the crash ?

[mongozmaki]

I had a similar problem. I found the bug and will submit a fix today.
Cheers

[eighthree]

@d-a-v I had all the debug options enabled but serial does not show anything other than what i've posted.

Tested the fix @mongozmaki mentioned but still having the same issue.

[devyte]

@burner- @eighthree a lot has changed since this was last discussed. Is the issue still valid with latest git and lwip2?

[devyte]

No response in a long time. Closing.