Nofuss is causing a crash

[m-kozlowski]

Bug description
After upgrade to commit 1ed5f43 i was experiencing boot loops followed by failover AP mode.
Tried to disable features one by one over telnet and the issue went away after setting nofussEnabled=0

Device information

---8<-------

[657637] [MAIN] ESPURNA 1.15.0-dev (825c5750)
[657637] [MAIN] xose.perez@gmail.com
[657638] [MAIN] http://tinkerman.cat

[657639] [MAIN] CPU chip ID: 0x8CBCC1
[657642] [MAIN] CPU frequency: 80 MHz
[657646] [MAIN] SDK version: 2.2.2-dev(38a443e)
[657650] [MAIN] Core version: 2.7.4
[657656] [MAIN] Core revision: 2843a5ac
[657656] [MAIN] Build time: 1608502218
[657661] 
[657662] [MAIN] Flash chip ID: 0x144051
[657664] [MAIN] Flash speed: 40000000 Hz
[657668] [MAIN] Flash mode: DOUT
[657670] 
[657672] [MAIN] Flash size (CHIP)   :  1048576 bytes /  256 sectors (   0 to  255)
[657682] [MAIN] Flash size (SDK)    :  1048576 bytes /  256 sectors (   0 to  255)
[657686] [MAIN] Reserved            :     4096 bytes /    1 sectors (   0 to    0)
[657695] [MAIN] Firmware size       :   602032 bytes /  147 sectors (   1 to  147)
[657701] [MAIN] Max OTA size        :   421888 bytes /  103 sectors ( 148 to  250)
[657707] [MAIN] EEPROM size         :     4096 bytes /    1 sectors ( 251 to  251)
[657715] [MAIN] Reserved            :    16384 bytes /    4 sectors ( 252 to  255)
[657722] 
[657723] [MAIN] EEPROM sectors: 251, 250
[657732] [MAIN] EEPROM current: 251
[657732] 
[657733] [MAIN] EEPROM:  4096 bytes initially |   993 bytes used (24%) |  3103 bytes free (75%)
[657740] [MAIN] Heap  : 39048 bytes initially | 18936 bytes used (48%) | 20112 bytes free (51%)
[657749] [MAIN] Heap  : 18288 contiguous bytes available (9% fragmentation)
[657754] [MAIN] Stack :  4096 bytes initially |  1840 bytes used (44%) |  2256 bytes free (55%)
[657762] 
[657763] [MAIN] Boot version: 31
[657769] [MAIN] Boot mode: 1
[657770] [MAIN] Last reset reason: Power On
[657772] [MAIN] Last reset info: Power On
[657776] 
[657777] [MAIN] Board: ITEAD_SONOFF_BASIC
[657782] [MAIN] Support: ALEXA API BROKER BUTTON DEBUG_SERIAL DEBUG_TELNET DEBUG_WEB DOMOTICZ LED MDNS_SERVER MQTT NOFUSS NTP RELAY SCHEDULER SENSOR TELNET TERMINAL WEB 
[657795] [MAIN] OTA: ARDUINO ASYNCTCP WEB 
[657798] [MAIN] Sensors: DALLAS 
[657805] [MAIN] WebUI image: SENSOR
[657805] 
[657805] [MAIN] Firmware MD5: 78c8924cdf46657be9044668a3c8b71c
[657813] [MAIN] Power: 3486 mV
[657814] [MAIN] Power saving delay value: 10 ms
[657818] 

---8<-------

Crash report

Latest crash was at 5615 ms after boot
Reason of restart: 2

Exception (9):
epc1=0x4023ec90 epc2=0x00000000 epc3=0x00000000 excvaddr=0x00000741 depc=0x00000000

>>>stack>>>

ctx: todo
sp: 3ffffc20 end: 3fffffc0 offset: 0000
3ffffc20:  00000000 6567412d 8000746e 40237e88 
3ffffc24:  3ffffcf8 00000000 3ffffc60 4023aef8 
3ffffc28:  3fff57dc 3fffff34 3ffffc60 4023bf6c 
3ffffc2c:  3fff1788 3fffff34 3fff15e8 4022e684 
3ffffc30:  00000000 00000000 3fff6214 75707365 
3ffffc34:  00616e72 87fffd0f 3f000050 40012710 
3ffffc38:  0000002f 2c9f0300 8100050c 70747468 
3ffffc3c:  40102800 84ffc200 3fff645c 000000df 
3ffffc40:  0023a468 3fff61ec 000c001f 00ffffff 
3ffffc44:  4023a400 00000018 8000001c 00000000 
3ffffc48:  00000000 000000c8 ffffffff 00000000 
3ffffc4c:  00000000 4028000a 00000000 00000000 
<<<stack<<<

Exception: 9 (LoadStoreAlignmentCause: Load or store to an unaligned address)

epc1:     0x4023ec90: HTTPClient::connected() at /root/.platformio/packages/framework-arduinoespressif8266/libraries/ESP8266HTTPClient/src/ESP8266HTTPClient.cpp:475
epc2:     0x00000000
epc3:     0x00000000
excvaddr: 0x00000741
depc:     0x00000000

stack:

ctx: todo
sp:       0x3ffffc20
end:      0x3fffffc0
offset:   0x00000000

0x40237e88: String::operator=(__FlashStringHelper const*) at /root/.platformio/packages/framework-arduinoespressif8266/cores/esp8266/WString.cpp:294 (discriminator 1)
0x4023aef8: HTTPClient::disconnect(bool) at /root/.platformio/packages/framework-arduinoespressif8266/libraries/ESP8266HTTPClient/src/ESP8266HTTPClient.cpp:434
0x4023bf6c: HTTPClient::end() at /root/.platformio/packages/framework-arduinoespressif8266/libraries/ESP8266HTTPClient/src/ESP8266HTTPClient.cpp:425
0x3fff1788: ?? at /root/.platformio/packages/framework-arduinoespressif8266/cores/esp8266/Esp.cpp:93
0x3fff15e8: ?? at /usr/src/espurna/code/.pio/libdeps/itead-sonoff-basic-r2-dallas/NoFUSS/src/NoFUSSClient.cpp:212
0x4022e684: NoFUSSClientClass::_getPayload() at /usr/src/espurna/code/.pio/libdeps/itead-sonoff-basic-r2-dallas/NoFUSS/src/NoFUSSClient.cpp:74
0x40102800: rcReachRetryLimit at ??:?
0x4023a400: uart_read at /root/.platformio/packages/framework-arduinoespressif8266/cores/esp8266/uart.cpp:286
0x4028000a: sleep_reset_analog_rtcreg_8266 at ??:?

[mcspr]

So, by the 5second mark, board connects to the WiFi for the first time and immediately crashes after the very first nofuss HTTP request?
What is the HTTP answer there? Does it try to upgrade immediately? You can also add an early return in the .pio/libdeps/itead-sonoff-basic-r2-dallas/NoFUSS/src/NoFUSSClient.cpp::_checkUpdates(), so it does not actually call the esp8266 updater and just prints the response string. Then, tweaking update interval or manually calling the nofuss command should show what it decided to do

Did things change after switching from Core 2.7.1 to 2.7.4 (changed via platformio.ini platform = ...)? I noticed at least one patch related to the HTTP client lib:

• https://github.com/esp8266/Arduino/releases/tag/2.7.2
• bugfix2/ESP8266HTTPClient esp8266/Arduino#6476

[m-kozlowski]

So, by the 5second mark, board connects to the WiFi for the first time and immediately crashes after the very first nofuss HTTP request?

Yup. That what it looks like.

What is the HTTP answer there?

Empty json. and some headers...

* Connected to espurna (10.1.1.5) port 80 (#0)
> GET / HTTP/1.1
> Host: espurna
> User-Agent: curl/7.68.0
> Accept: */*
> X-ESP8266-DEVICE: ESPURNA_CORE
> X-ESP8266-VERSION: 1.15.0-dev
> X-ESP8266-BUILD: 1608503048
>
* Mark bundle as not supporting multiuse
< HTTP/1.1 200 OK
< date: Mon, 21 Dec 2020 16:06:15 GMT
< server: Apache
< expires: Thu, 19 Nov 1981 08:52:00 GMT
< cache-control: no-store, no-cache, must-revalidate
< pragma: no-cache
< set-cookie: PHPSESSID=qfemv689k6flf1f1k2luehmtgq; path=/
< vary: Accept-Encoding
< transfer-encoding: chunked
< content-type: text/html; charset=UTF-8
<
* Connection #0 to host espurna left intact
{}

Did things change after switching from Core 2.7.1 to 2.7.4

Will try and report back

[m-kozlowski]

Good catch!
There's no problem with espressif8266@2.5.1.
Went back to espressif8266@2.6.2 and the issue is back as well.

[mcspr]

Related to another patch from current development version?
esp8266/Arduino@47a57e1

And btw, Nofuss sets HTTP version to 1.0 i.e. curl --http1.0. Response above shows no content-lenght, but chunked won't happen on http HTTP/1.0, idk if it manages to break that way when getString() returns some garbage

[m-kozlowski]

Nofuss sets HTTP version to 1.0

Oh, didn't notice that. In that case response would be

< HTTP/1.1 200 OK
< date: Mon, 21 Dec 2020 19:33:59 GMT
< server: Apache
< expires: Thu, 19 Nov 1981 08:52:00 GMT
< cache-control: no-store, no-cache, must-revalidate
< pragma: no-cache
< set-cookie: PHPSESSID=5q6d11a4gtrajvjmg9qtqg319l; path=/
< vary: Accept-Encoding
< content-type: text/html; charset=UTF-8
< connection: close
<
* Closing connection 0
{}

Anyway, you nailed it - esp8266/Arduino@47a57e1 did the trick.