Locking phone with iOS app open/in background causes WLED to crash when playlist is selected

SK360 · January 24, 2022, 4:52pm

WLED has been rebooting on me sometimes when selecting a playlist. It isn’t consistent and I finally figured out how to reproduce. This is running on a QuinLED Diguno with SK6812 and White mode set to Accurate

To reproduce:

Open iOS app and connect to lights
Swipe away from WLED to put app into background
Lock phone
Unlock phone
Reopen WLED which is still connected to lights
Select Playlist (Presets seem to be fine)

This reboots WLED for me 100% of the time. If I open the app and first back out to the light selection screen and reconnect to my lights I am able to select a playlist without issue.

Side note, selecting a Playlist through HomeAssistant is also a 100% way to trigger a reboot for me, presets work fine.

Running on 0.13.0-b6 build 2112080

I opened an issue on Github but curious to see if others see the same behavior with the latest beta

github.com/Aircoookie/WLED

Locking phone with iOS app open/in background causes WLED to crash when playlist is selected.

opened 03:28AM - 24 Jan 22 UTC

SK360

bug

### What happened? WLED has been rebooting on me sometimes when selecting a p…laylist. It isn't consistent and I finally figured out how to reproduce. This is running on a QuinLED Diguno with SK6812 and White mode set to Accurate ### To Reproduce Bug - Open iOS app and connect to lights - Swipe away from WLED to put app into background - Lock phone - Unlock phone - Reopen WLED which is still connected to lights - Select Playlist (Presets seem to be fine) This reboots WLED for me 100% of the time. If I open the app and first back out to the light selection screen and reconnect to my lights I am able to select a playlist without issue. Side note, selecting a Playlist through HomeAssistant is also a 100% way to trigger a reboot for me, presets work fine. ### Expected Behavior Playlist is loaded, WLED doesn't reboot. ### Install Method Binary from WLED.me ### What version of WLED? 0.13.0-b6 build 2112080 ### Which microcontroller/board are you seeing the problem on? ESP32 ### Relevant log/trace output presets.json: {"0":{} ,"2":{"n":"Rainbow","on":true,"bri":57,"transition":7,"mainseg":0,"seg":[{"id":0,"start":0,"stop":212,"grp":1,"spc":0,"of":0,"on":true,"bri":255,"cct":127,"col":[[255,255,255,0],[0,0,0,0],[0,0,0,0]],"fx":9,"sx":126,"ix":128,"pal":0,"sel":true,"rev":false,"mi":false},{"stop":0},{"stop":0},{"stop":0},{"stop":0},{"stop":0},{"stop":0},{"stop":0},{"stop":0},{"stop":0},{"stop":0},{"stop":0},{"stop":0},{"stop":0},{"stop":0},{"stop":0},{"stop":0},{"stop":0},{"stop":0},{"stop":0},{"stop":0},{"stop":0},{"stop":0},{"stop":0},{"stop":0},{"stop":0},{"stop":0},{"stop":0},{"stop":0},{"stop":0},{"stop":0},{"stop":0}]} ,"4":{"playlist":{"ps":[3],"dur":[380],"transition":[7],"repeat":1,"r":false,"end":1},"on":true,"n":"Test"} ,"1":{"n":"Uplighting","on":true,"bri":15,"transition":7,"mainseg":0,"seg":[{"id":0,"start":0,"stop":212,"grp":1,"spc":0,"of":0,"on":true,"bri":255,"cct":127,"col":[[255,255,255,0],[0,0,0,0],[0,0,0,0]],"fx":0,"sx":126,"ix":128,"pal":0,"sel":true,"rev":false,"mi":false},{"stop":0},{"stop":0},{"stop":0},{"stop":0},{"stop":0},{"stop":0},{"stop":0},{"stop":0},{"stop":0},{"stop":0},{"stop":0},{"stop":0},{"stop":0},{"stop":0},{"stop":0},{"stop":0},{"stop":0},{"stop":0},{"stop":0},{"stop":0},{"stop":0},{"stop":0},{"stop":0},{"stop":0},{"stop":0},{"stop":0},{"stop":0},{"stop":0},{"stop":0},{"stop":0},{"stop":0}]},"3":{"n":"TetrixWhite","on":true,"bri":15,"transition":7,"mainseg":0,"seg":[{"id":0,"start":0,"stop":212,"grp":1,"spc":0,"of":0,"on":true,"bri":255,"cct":127,"col":[[255,255,255,0],[0,0,0,0],[0,0,0,0]],"fx":44,"sx":115,"ix":164,"pal":0,"sel":true,"rev":false,"mi":false},{"stop":0},{"stop":0},{"stop":0},{"stop":0},{"stop":0},{"stop":0},{"stop":0},{"stop":0},{"stop":0},{"stop":0},{"stop":0},{"stop":0},{"stop":0},{"stop":0},{"stop":0},{"stop":0},{"stop":0},{"stop":0},{"stop":0},{"stop":0},{"stop":0},{"stop":0},{"stop":0},{"stop":0},{"stop":0},{"stop":0},{"stop":0},{"stop":0},{"stop":0},{"stop":0},{"stop":0}]}} ### Anything else? This is 100% not a power issue, there are 212 SK6812 5v LED's connected via a 18a Meanwell power supply and has been run at 100% full white for hours, these presets in the playlist are all low brightness. ### Code of Conduct - [X] I agree to follow this project's Code of Conduct

This is 100% not a power issue, there are 212 SK6812 5v LED’s connected via a 18a Meanwell power supply and has been run at 100% full white for hours, these presets in the playlist are all low brightness.

tonyno · January 24, 2022, 10:23pm

Which ESP? 8266 or 32?

SK360 · January 24, 2022, 10:57pm

It’s the QuinLED-ESP32

SK360 · January 25, 2022, 4:11am

There’s something funky going on with network calls to it. It’s now rebooting sometimes on homeassistant adjusting the brightness from an automation as well. I’ve never had issues like this with an ESP8266

blazoncek · January 25, 2022, 1:14pm

get a debug build, attach serial (usb) to esp and monitor serial output from esp.
when you see a reboot copy/paste serial output.

no way to know what’s happening otherwise

SK360 · January 25, 2022, 1:32pm

Was thinking of how to log it, that makes sense. Not sure that will be possible based on the USB port orientation on the Diguno since it points right into the fuse however. Maybe I can jump it temporarily

blazoncek · January 25, 2022, 3:53pm

You can just unplug ESP from dig-uno there is no need for hardware to find this kind of software bug.

SK360 · January 25, 2022, 4:07pm

Good idea, didn’t even think of it. I have it plugged in on my desk and have managed to reproduce the reboots. I need to compile a debug version now to pull the logs.

blazoncek · January 25, 2022, 4:25pm

you can grab pre-compiled debug builds from @srg74

or

SK360 · January 25, 2022, 4:52pm

I just compiled and of course can’t get it to crash now. There’s a call to /presets.json every 8 seconds are so which I assume is the HA integration polling it. Here is a log from when I selected the Playlist (ID 4) from HomeAssistant and it didn’t crash.

Not-Found HTTP call:
URI: /presets.json
FileRead: /presets.json
Serialized HTTP
{"ps":4,"v":true}
Playlist unloaded.
Playlist unloaded.
Playlist loaded.
JSON buffer released. (14)
JSON buffer size: 697
JSON buffer released. (17)
Playlist unloaded.
JSON buffer released. (9)
JSON buffer size: 1713
JSON buffer released. (17)
JSON buffer released. (12)
Not-Found HTTP call:
URI: /presets.json
FileRead: /presets.json
JSON buffer size: 1713
JSON buffer released. (17)
Not-Found HTTP call:
URI: /presets.json
FileRead: /presets.json
JSON buffer size: 1713
JSON buffer released. (17)
Local time: 11:47
---DEBUG INFO---
Runtime: 360061
Unix time: 1643129227,061
Free heap: 185252
Wifi state: 3
State time: 0
NTP last sync: 999000000
Client IP: 192.168.1.10
Loops/sec: 3462
Max UM time[ms]: 1
Not-Found HTTP call:
URI: /presets.json
FileRead: /presets.json
JSON buffer size: 1713
JSON buffer released. (17)

When I swipe away from WLED as I described in my steps to reproduce and reopen the app there is a call to /win which I don’t see any other time

JSON buffer released. (9)
JSON buffer released. (12)
Not-Found HTTP call:
URI: /win
API req: /win

I was able to get a locking json buffer failed message selecting a playlist through HA but WLED didn’t crash

JSON buffer size: 697
JSON buffer released. (17)
JSON buffer released. (12)
Serialized HTTP
{"ps":4,"v":true}
Playlist unloaded.
ERROR: Locking JSON buffer failed! (14)
JSON buffer released. (14)
JSON buffer size: 697
JSON buffer released. (17)

I saw you had a few commits related to JSON buffer that got merged since b6 got release cut. I wonder if they had an impact on the issue I was seeing? I can always try a debug build from when b6 was cut and see if the issues come back

blazoncek · January 25, 2022, 4:55pm

polling for presets.json is demanding on the esp

blazoncek · January 25, 2022, 4:56pm

If you are willing, testdrive my fork dev branch.
It does have some experimental mitigations for crashes.

SK360 · January 25, 2022, 4:59pm

I am able to get locking json buffer failed quite often now and the WebUI of WLED comes up Red and says connection to light failed

Playlist unloaded.
ERROR: Locking JSON buffer failed! (11)
JSON buffer released. (11)
Playlist unloaded.
Local time: 11:59
ERROR: Locking JSON buffer failed! (11)
JSON buffer released. (11)
Playlist unloaded.

I have not been able to get it to crash however.

I will go checkout your fork

blazoncek · January 25, 2022, 5:03pm

Locking error would usually mean concurrent requests. 11 is websocket.

SK360 · January 25, 2022, 5:17pm

Yeah I get 11 when I do it through the WLED interface but getting Locking failed on 14 when I try to select a playlist via HA every time now.

Looking in the WLED integration for HA it looks like its default scan is setup to be 10 seconds

SCAN_INTERVAL = timedelta(seconds=10)

SK360 · January 25, 2022, 5:23pm

I also have been having WLED reboot sometimes when I restart HomeAssistant and I managed to catch that crash just now

JSON buffer released. (17)
---DEBUG INFO---
Runtime: 2460484
Unix time: 1643131327,484
Free heap: 186752
Wifi state: 3
State time: 0
NTP last sync: 999000000
Client IP: 192.168.1.10
Loops/sec: 3122
Max UM time[ms]: 1
Not-Found HTTP call:
URI: /presets.json
FileRead: /presets.json
JSON buffer size: 1712
JSON buffer released. (17)
CORRUPT HEAP: Bad head at 0x3ffdd008. Expected 0xabba1234 got 0x3ffdd108
assertion "head != NULL" failed: file "/home/runner/work/esp32-arduino-lib-builder/esp32-arduino-lib-builder/esp-idf/components/heap/multi_heap_poisoning.c", line 214, function: multi_heap_free
abort() was called at PC 0x40158407 on core 0
ets Jul 29 2019 12:21:46

rst:0x7 (TG0WDT_SYS_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:1
load:0x3fff0018,len:4
load:0x3fff001c,len:1044
load:0x40078000,len:8896
load:0x40080400,len:5816
entry 0x400806ac

---WLED 0.13.0-b6 2112080 INIT---
esp32 v3.2.3-14-gd3e562907
heap 277476
Registering usermods ...
Reading config
Reading settings from /wsec.json...
JSON buffer released. (3)
Reading settings from /cfg.json...
Removing all.
Successfully inited strip 0 (len 104) with type 30 and pins 3,255 (itype 20)
Successfully inited strip 1 (len 108) with type 30 and pins 16,255 (itype 20)
Starting usermod config.
JSON buffer released. (1)
Initializing strip
Playlist unloaded.
JSON buffer released. (9)
Usermods setup
Access point disabled.
Connecting to Making Wifi Great Again...
Local time: 01:28

Connected! IP address: 192.168.1.10
Init STA interfaces
mDNS started

blazoncek · January 25, 2022, 5:45pm

14 is regular HTTP /json request.
Corrupt heap (after a buffer release) means some incorrect memory allocations happened.
17 would be JSON handling. so somewhere in web server callback.
but FileRead /presets.json gets me baffled
it shouldn’t be there

blazoncek · January 25, 2022, 5:47pm

that’s often!

SK360 · January 25, 2022, 6:10pm

This is using your dev branch, I got it to crash by selecting playlists through the WLED web interface

Apply preset JSON buffer requested.
Deserializing state
Playlist unloaded.
JSON buffer released. (9)
WS JSON send buffer requested.
JSON buffer size: 1783 for WS request.
JSON buffer released. (12)
Sending WS data assertion "inconsistent oversize vs. space" failed: file "/home/runner/work/esp32-arduino-lib-builder/esp32-arduino-lib-builder/esp-idf/components/lwip/lwip/src/core/tcp_out.c", line 473, function: tcp_write
abort() was called at PC 0x40158f67 on core 0

Backtrace: 0x4008e20c:0x3ffb6160 0x4008e43d:0x3ffb6180 0x40158f67:0x3ffb61a0 0x401793a7:0x3ffb61d0 0x4010d85b:0x3ffb6240 0x4016c740:0x3ffb6260 0x4008a955:0x3ffb6290

Rebooting...
ets Jul 29 2019 12:21:46

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:1
load:0x3fff0018,len:4
load:0x3fff001c,len:1044
load:0x40078000,len:8896
load:0x40080400,len:5816
entry 0x400806ac

---WLED 0.13.1-bl6 2201231 INIT---
esp32 v3.2.3-14-gd3e562907
heap 272388
Registering usermods ...
Reading config
Reading settings from /wsec.json...
JSON buffer released. (3)
Reading settings from /cfg.json...
Removing all.
Successfully inited strip 0 (len 104) with type 30 and pins 3,255 (itype 20)
Successfully inited strip 1 (len 108) with type 30 and pins 16,255 (itype 20)
Starting usermod config.
JSON buffer released. (1)
Initializing strip
Usermods setup
lastReconnectAttempt == 0
Access point disabled (init).
Connecting to Making Wifi Great Again...
Apply preset JSON buffer requested.
Deserializing state
Playlist unloaded.
JSON buffer released. (9)
Local time: 01:28

Connected! IP address: 192.168.1.10
Init STA interfaces
mDNS started
WS JSON send buffer requested.
JSON buffer size: 1783 for WS request.
JSON buffer released. (12)
Sending WS data to a single client.
WS client connected.
WS JSON receive buffer requested.
JSON buffer released. (11)
WS JSON send buffer requested.
JSON buffer size: 1783 for WS request.
JSON buffer released. (12)
Sending WS data to a single client.
Not-Found HTTP call:
URI: /presets.json
FileRead: /presets.json
JSON buffer size: 1782 for request: 3
JSON buffer released. (17)
Not-Found HTTP call:
URI: /presets.json

SK360 · January 25, 2022, 6:14pm

And heres a crash that just happened adjusting the brightness slider in HA

Deserializing state
JSON buffer released. (14)
JSON buffer size: 717 for request: 1
JSON buffer released. (17)
CORRUPT HEAP: multi_heap.c:187 detected at 0x3ffd80c0
abort() was called at PC 0x4008d3de on core 1

Backtrace: 0x4008e20c:0x3ffda070 0x4008e43d:0x3ffda090 0x4008d3de:0x3ffda0b0 0x4008d98d:0x3ffda0d0 0x4008de8a:0x3ffda0f0 0x4008596a:0x3ffda110 0x40086141:0x3ffda130 0x4000bec7:0x3ffda150 0x4018d249:0x3ffda170 0x40111bd9:0x3ffda190 0x4019dee3:0x3ffda1b0 0x40112b57:0x3ffda1d0 0x40112b99:0x3ffda1f0 0x401132d2:0x3ffda210 0x4011330d:0x3ffda240 0x4010dce9:0x3ffda260 0x4010de6c:0x3ffda290 0x4010e445:0x3ffda2b0 0x4008a955:0x3ffda2e0

Rebooting...
ets Jul 29 2019 12:21:46

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:1
load:0x3fff0018,len:4
load:0x3fff001c,len:1044
load:0x40078000,len:8896
load:0x40080400,len:5816
entry 0x400806ac

---WLED 0.13.1-bl6 2201231 INIT---
esp32 v3.2.3-14-gd3e562907
heap 277380
Registering usermods ...
Reading config
Reading settings from /wsec.json...
JSON buffer released. (3)
Reading settings from /cfg.json...
Removing all.
Successfully inited strip 0 (len 104) with type 30 and pins 3,255 (itype 20)
Successfully inited strip 1 (len 108) with type 30 and pins 16,255 (itype 20)
Starting usermod config.
JSON buffer released. (1)
Initializing strip
Usermods setup
lastReconnectAttempt == 0
Access point disabled (init).
Connecting to Making Wifi Great Again...
Apply preset JSON buffer requested.
Deserializing state
Playlist unloaded.
JSON buffer released. (9)
Local time: 01:28

Also interesting that my playlists are no longer working at all with any build past the b6 release cut, they load the first preset but never go to the next. I think its time to go back to bed

Topic		Replies	Views
Playlist turns off wled Issues	10	917	July 13, 2023
Starting the default playlist	9	3587	September 20, 2021
App Issues Issues	4	783	May 18, 2024
IOS app is scrambled, even after full delete and reinstall Issues	4	518	June 15, 2023
Problem with Wled UI Questions	6	711	December 24, 2024

Locking phone with iOS app open/in background causes WLED to crash when playlist is selected

Related topics