search

xoseperez / espurna

Home automation firmware for ESP8266-based devices
http://tinkerman.cat
GNU General Public License v3.0
2.98k stars 637 forks source link

H801 crashes when changing colors using drag #2451

Closed luebbe closed 3 years ago

luebbe commented 3 years ago

Bug description The device (H801) reboots when the color is changed by dragging the brightness/saturation selector with the mouse over the square or by dragging the color selector. It does not crash when you just click on the desired color or brightness/saturation.

My guess is that there is a problem, when a color transition is triggered while there is still one in progress Therefore I also added the device to Home Assistant in order to see if the crash also occurs when the color selector in the HA UI is dragged and the commands are received via MQTT. But in this case it works fine. No crashes. The crash only occurs, when the selector is dragged on one of the two native Espurna color selector UI controls.

This is the log output

I started dragging after the [026028] [RELAY] #0 set to ON line.

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

load 0x4010f000, len 3584, room 16 
tail 0
chksum 0xb0
csum 0xb0
v2843a5ac
~ld
[000104] [MAIN] System OK
[000107] [MAIN] ESPURNA 1.15.0-dev.git88921220 built 2021-05-16 20:40:57
[000107] [MAIN] xose.perez@gmail.com
[000107] [MAIN] http://tinkerman.cat
[000109] [MAIN] CPU chip ID: 600194422440
[000112] [MAIN] SDK: 2.2.2-dev(38a443e)
[000116] [MAIN] Arduino Core: 2.7.4
[000119] [MAIN] Support: ALEXA API BUTTON DEBUG_SERIAL DEBUG_TELNET DEBUG_WEB DOMOTICZ HOMEASSISTANT LED MDNS MQTT NTP ARDUINO_OTA OTA_CLIENT RELAY SCHEDULER TELNET TERMINAL THINGSPEAK WEB
[000145] [TELNET] Listening on port 23
[000147] [WEBSERVER] Webserver running on port 80
[000150] [LIGHT] Provider: DIMMER
[000153] [LIGHT] Number of channels: 5
[000173] [RELAY] Number of relays: 1, boot mask: 0b1
[000174] [RELAY] #0 set to OFF
[000177] [BUTTON] Number of buttons: 0
[000180] [LED] Number of leds: 1
[000182] [MQTT] AsyncMqttClient, SSL DISABLED, Autoconnect ENABLED, Buffer size 1024 bytes
[000184] [MQTT] Client DISABLED, DISCONNECTED
[000211] [NTP] Startup delay: 3 (s), Update delay: 2266 (s)
[000230] [NTP] Server: 192.168.0.1, TZ: CET-1CEST,M3.5.0,M10.5.0/3
[000236] [THINGSPEAK] Async ENABLED, SSL DISABLED
[000319] [MAIN] Uptime: 00y 00d 00h 00m 00s
[000320] [MAIN] 24224 / 38928 bytes available (24216 contiguous)
[000321] [MAIN] VCC: 3523 mV
[000322] [WIFI] Initial
[000338] [WIFI] State Boot -> Idle
[000340] [WIFI] Mode changed to STA
[000351] [WIFI] State Idle -> Init
[000366] [WIFI] State Init -> Connect
[000368] [WIFI] Connecting
[000378] [WIFI] State Connect -> WaitConnected
[001174] [RELAY] Relay mask: 0b0
[004177] [WIFI] State WaitConnected -> Connected
[004178] [MQTT] MQTT brokers found: 0
[004181] [MDNS] OK
[004182] [WIFI] Connected to BSSID 2C:3A:FD:FE:7D:89 SSID onklan
[004193] [WIFI] State Connected -> Idle
[005004] [MQTT] Connecting to broker at 192.168.0.10:1883
[005004] [MQTT] Client ID: ESPURNA-422440
[005004] [MQTT] QoS: 0
[005004] [MQTT] Retain flag: Y
[005006] [MQTT] Keepalive time: 300 (s)
[005010] [MQTT] Will topic: h801-test/status
[005035] [MQTT] Subscribing to h801-test/light_json/set (PID 1)
[005036] [MQTT] Subscribing to h801-test/action/set (PID 2)
[005036] [MQTT] Subscribing to h801-test/led/+/set (PID 3)
[005041] [MQTT] Subscribing to h801-test/relay/+/set (PID 4)
[005046] [MQTT] Subscribing to h801-test/pulse/+/set (PID 5)
[005053] [MQTT] Subscribing to h801-test/brightness/set (PID 6)
[005058] [MQTT] Subscribing to h801-test/rgb/set (PID 7)
[005063] [MQTT] Subscribing to h801-test/hex/set (PID 8)
[005068] [MQTT] Subscribing to h801-test/hsv/set (PID 9)
[005073] [MQTT] Subscribing to h801-test/mired/set (PID 10)
[005079] [MQTT] Subscribing to h801-test/kelvin/set (PID 11)
[005084] [MQTT] Subscribing to h801-test/transition/set (PID 12)
[005090] [MQTT] Subscribing to h801-test/channel/+/set (PID 13)
[005096] [MQTT] Connected!
[007186] [NTP] Server     : 192.168.0.1
[007187] [NTP] Sync Time  : 2021-05-17 17:28:35 (UTC)
[007187] [NTP] UTC Time   : 2021-05-17 17:28:35
[007188] [NTP] Local Time : 2021-05-17 19:28:35 (CET-1CEST,M3.5.0,M10.5.0/3)
[008132] [MQTT] Sending h801-test/status => 1 (PID 1)
[008133] [MQTT] Sending h801-test/app => ESPURNA (PID 1)
[008134] [MQTT] Sending h801-test/version => 1.15.0-dev.git88921220 (PID 1)
[008140] [MQTT] Sending h801-test/board => HUACANXING_H801 (PID 1)
[008146] [MQTT] Sending h801-test/host => h801-test (PID 1)
[008151] [MQTT] Sending h801-test/desc => RGB Controller Dachstuhl oben (PID 1)
[008158] [MQTT] Sending h801-test/ssid => onklan (PID 1)
[008163] [MQTT] Sending h801-test/ip => 192.168.0.43 (PID 1)
[008169] [MQTT] Sending h801-test/mac => 60:01:94:42:24:40 (PID 1)
[008175] [MQTT] Sending h801-test/rssi => -41 (PID 1)
[008180] [MQTT] Sending h801-test/uptime => 8 (PID 1)
[008185] [MQTT] Sending h801-test/datetime => 2021-05-17 19:28:35 (PID 1)
[008192] [MQTT] Sending h801-test/freeheap => 18552 (PID 1)
[008197] [MQTT] Sending h801-test/loadavg => 0 (PID 1)
[008202] [MQTT] Sending h801-test/vcc => 3523 (PID 1)
[008207] [MQTT] Sending h801-test/light_json => {"state":"OFF"} (PID 1)
[008213] [MQTT] Sending h801-test/relay/0 => 0 (PID 1)
[008218] [MQTT] Sending h801-test/hex => #000000 (PID 1)
[008223] [MQTT] Sending h801-test/rgb => 0,0,0 (PID 1)
[008229] [MQTT] Sending h801-test/hsv => 0,0,0 (PID 1)
[008233] [MQTT] Sending h801-test/mired => 326 (PID 1)
[008238] [MQTT] Sending h801-test/channel/0 => 0 (PID 1)
[008244] [MQTT] Sending h801-test/channel/1 => 0 (PID 1)
[008249] [MQTT] Sending h801-test/channel/2 => 0 (PID 1)
[008254] [MQTT] Sending h801-test/channel/3 => 0 (PID 1)
[008259] [MQTT] Sending h801-test/channel/4 => 0 (PID 1)
[008264] [MQTT] Sending h801-test/brightness => 230 (PID 1)
[009669] [WEBSERVER] GET /index.html
[009828] [WEBSERVER] GET /auth
[009928] [WEBSOCKET] #1 connected, ip: 192.168.0.28, url: /ws
[026015] [RELAY] #0 scheduled ON in 0 ms
[026026] [MQTT] Sending h801-test/relay/0 => 1 (PID 1)
[026028] [RELAY] #0 set to ON
[026043] [LIGHT] Transition from 0.00 to 67 (step 1.34, 50 times)
[026044] [LIGHT] Transition from 0.00 to 206 (step 4.12, 50 times)
[026044] [LIGHT] Transition from 0.00 to 132 (step 2.64, 50 times)
[026049] [LIGHT] Scheduled transition for 500 (ms) every 10 (ms)
[026157] [MQTT] Sending h801-test/hex => #43CE84 (PID 1)
[026158] [MQTT] Sending h801-test/rgb => 67,206,132 (PID 1)
[026159] [MQTT] Sending h801-test/hsv => 148,67,81 (PID 1)
[026163] [MQTT] Sending h801-test/mired => 326 (PID 1)
[026168] [MQTT] Sending h801-test/channel/0 => 67 (PID 1)
[026173] [MQTT] Sending h801-test/channel/1 => 206 (PID 1)
[026178] [MQTT] Sending h801-test/channel/2 => 132 (PID 1)
[026184] [MQTT] Sending h801-test/channel/3 => 0 (PID 1)
[026189] [MQTT] Sending h801-test/channel/4 => 0 (PID 1)
[026197] [MQTT] Sending h801-test/brightness => 230 (PID 1)
[026202] [MQTT] Sending h801-test/light_json => {"state":"ON","brightness":230,"color":{"h":148,"s":67}} (PID 1)
[027029] [RELAY] Relay mask: 0b1
[031420] [LIGHT] Transition from 67.00 to 23 (step -1.00, 44 times)
[031421] [LIGHT] Transition from 206.00 to 215 (step 1.00, 9 times)
[031421] [LIGHT] Transition from 132.00 to 113 (step -1.00, 19 times)
[031427] [LIGHT] Scheduled transition for 500 (ms) every 10 (ms)
[031535] [MQTT] Sending h801-test/hex => #17D771 (PID 1)
[031536] [MQTT] Sending h801-test/rgb => 23,215,113 (PID 1)
[031537] [MQTT] Sending h801-test/hsv => 148,89,84 (PID 1)
[031540] [MQTT] Sending h801-test/mired => 326 (PID 1)
[031545] [MQTT] Sending h801-test/channel/0 => 23 (PID 1)
[031551] [MQTT] Sending h801-test/channel/1 => 215 (PID 1)
[031556] [MQTT] Sending h801-test/channel/2 => 113 (PID 1)
[031561] [MQTT] Sending h801-test/channel/3 => 0 (PID 1)
[031567] [MQTT] Sending h801-test/channel/4 => 0 (PID 1)
[031575] [MQTT] Sending h801-test/brightness => 235 (PID 1)
[031579] [MQTT] Sending h801-test/light_json => {"state":"ON","brightness":235,"color":{"h":148,"s":89}} (PID 1)
[031662] [LIGHT] Transition from 53.00 to 22 (step -1.00, 31 times)
[031663] [LIGHT] Transition from 215.00 to 211 (step -1.00, 4 times)
[031663] [LIGHT] Transition from 118.00 to 110 (step -1.00, 8 times)
[031669] [LIGHT] Scheduled transition for 500 (ms) every 10 (ms)
[031689] [LIGHT] Transition from 52.00 to 21 (step -1.00, 31 times)
[031690] [LIGHT] Transition from 214.00 to 201 (step -1.00, 12 times)
[031690] [LIGHT] Transition from 117.00 to 105 (step -1.00, 12 times)

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

load 0x4010f000, len 3584, room 16 
tail 0
chksum 0xb0
csum 0xb0
v2843a5ac
~ld
[000106] [MAIN] System OK
[000108] [MAIN] ESPURNA 1.15.0-dev.git88921220 built 2021-05-16 20:40:57
[000109] [MAIN] xose.perez@gmail.com
[000109] [MAIN] http://tinkerman.cat
[000110] [MAIN] CPU chip ID: 600194422440
[000114] [MAIN] SDK: 2.2.2-dev(38a443e)
[000117] [MAIN] Arduino Core: 2.7.4
[000121] [MAIN] Support: ALEXA API BUTTON DEBUG_SERIAL DEBUG_TELNET DEBUG_WEB DOMOTICZ HOMEASSISTANT LED MDNS MQTT NTP ARDUINO_OTA OTA_CLIENT RELAY SCHEDULER TELNET TERMINAL THINGSPEAK WEB
[000147] [TELNET] Listening on port 23
[000149] [WEBSERVER] Webserver running on port 80
[000152] [LIGHT] Provider: DIMMER
[000155] [LIGHT] Number of channels: 5
[000175] [RELAY] Number of relays: 1, boot mask: 0b1
[000176] [RELAY] #0 set to OFF
[000179] [BUTTON] Number of buttons: 0
[000181] [LED] Number of leds: 1
[000184] [MQTT] AsyncMqttClient, SSL DISABLED, Autoconnect ENABLED, Buffer size 1024 bytes
[000186] [MQTT] Client DISABLED, DISCONNECTED
[000213] [NTP] Startup delay: 3 (s), Update delay: 2745 (s)
[000232] [NTP] Server: 192.168.0.1, TZ: CET-1CEST,M3.5.0,M10.5.0/3
[000237] [THINGSPEAK] Async ENABLED, SSL DISABLED
[000321] [MAIN] Uptime: 00y 00d 00h 00m 00s
[000321] [MAIN] 24224 / 38928 bytes available (24216 contiguous)
[000322] [MAIN] VCC: 3523 mV
[000323] [WIFI] Initial
[000340] [WIFI] State Boot -> Idle
[000342] [WIFI] Mode changed to STA
[000353] [WIFI] State Idle -> Init
[000367] [WIFI] State Init -> Connect
[000369] [WIFI] Connecting
[000380] [WIFI] State Connect -> WaitConnected
[001176] [RELAY] Relay mask: 0b0
[004188] [WIFI] State WaitConnected -> Connected
[004189] [MQTT] MQTT brokers found: 0
[004192] [MDNS] OK
[004193] [WIFI] Connected to BSSID 2C:3A:FD:FE:7D:89 SSID onklan
[004204] [WIFI] State Connected -> Idle
[005005] [MQTT] Connecting to broker at 192.168.0.10:1883
[005006] [MQTT] Client ID: ESPURNA-422440
[005006] [MQTT] QoS: 0
[005006] [MQTT] Retain flag: Y
[005008] [MQTT] Keepalive time: 300 (s)
[005011] [MQTT] Will topic: h801-test/status
[005039] [MQTT] Subscribing to h801-test/light_json/set (PID 1)
[005040] [MQTT] Subscribing to h801-test/action/set (PID 2)
[005040] [MQTT] Subscribing to h801-test/led/+/set (PID 3)
[005045] [MQTT] Subscribing to h801-test/relay/+/set (PID 4)
[005051] [MQTT] Subscribing to h801-test/pulse/+/set (PID 5)
[005058] [MQTT] Subscribing to h801-test/brightness/set (PID 6)
[005062] [MQTT] Subscribing to h801-test/rgb/set (PID 7)
[005067] [MQTT] Subscribing to h801-test/hex/set (PID 8)
[005072] [MQTT] Subscribing to h801-test/hsv/set (PID 9)
[005077] [MQTT] Subscribing to h801-test/mired/set (PID 10)
[005083] [MQTT] Subscribing to h801-test/kelvin/set (PID 11)
[005089] [MQTT] Subscribing to h801-test/transition/set (PID 12)
[005094] [MQTT] Subscribing to h801-test/channel/+/set (PID 13)
[005100] [MQTT] Connected!
[007186] [NTP] Server     : 192.168.0.1
[007187] [NTP] Sync Time  : 2021-05-17 17:29:08 (UTC)
[007187] [NTP] UTC Time   : 2021-05-17 17:29:08
[007188] [NTP] Local Time : 2021-05-17 19:29:08 (CET-1CEST,M3.5.0,M10.5.0/3)
[008133] [MQTT] Sending h801-test/status => 1 (PID 1)
[008134] [MQTT] Sending h801-test/app => ESPURNA (PID 1)
[008134] [MQTT] Sending h801-test/version => 1.15.0-dev.git88921220 (PID 1)
[008140] [MQTT] Sending h801-test/board => HUACANXING_H801 (PID 1)
[008146] [MQTT] Sending h801-test/host => h801-test (PID 1)
[008152] [MQTT] Sending h801-test/desc => RGB Controller Dachstuhl oben (PID 1)
[008158] [MQTT] Sending h801-test/ssid => onklan (PID 1)
[008164] [MQTT] Sending h801-test/ip => 192.168.0.43 (PID 1)
[008169] [MQTT] Sending h801-test/mac => 60:01:94:42:24:40 (PID 1)
[008175] [MQTT] Sending h801-test/rssi => -37 (PID 1)
[008180] [MQTT] Sending h801-test/uptime => 8 (PID 1)
[008185] [MQTT] Sending h801-test/datetime => 2021-05-17 19:29:08 (PID 1)
[008192] [MQTT] Sending h801-test/freeheap => 18552 (PID 1)
[008197] [MQTT] Sending h801-test/loadavg => 0 (PID 1)
[008203] [MQTT] Sending h801-test/vcc => 3523 (PID 1)
[008207] [MQTT] Sending h801-test/light_json => {"state":"OFF"} (PID 1)
[008214] [MQTT] Sending h801-test/relay/0 => 0 (PID 1)
[008219] [MQTT] Sending h801-test/hex => #000000 (PID 1)
[008224] [MQTT] Sending h801-test/rgb => 0,0,0 (PID 1)
[008229] [MQTT] Sending h801-test/hsv => 0,0,0 (PID 1)
[008234] [MQTT] Sending h801-test/mired => 326 (PID 1)
[008239] [MQTT] Sending h801-test/channel/0 => 0 (PID 1)
[008244] [MQTT] Sending h801-test/channel/1 => 0 (PID 1)
[008249] [MQTT] Sending h801-test/channel/2 => 0 (PID 1)
[008255] [MQTT] Sending h801-test/channel/3 => 0 (PID 1)
[008260] [MQTT] Sending h801-test/channel/4 => 0 (PID 1)
[008265] [MQTT] Sending h801-test/brightness => 232 (PID 1)
mcspr commented 3 years ago

My guess is that there is a problem, when a color transition is triggered while there is still one in progress

Will need to look at this. My guess as well is something changing the object while it is used. There are some conditions that panic() when that sort of thing happens, but I kind of expected for those to produce a trace pointing at the culprit.

afaik HASS UI only generates an MQTT message when dragging stops? Our color widget does not do this, and sends all updates as they happen

mcspr commented 3 years ago

I think this should solve it? Locking seems out-of-place right now, so is the manual panic(). I only briefly tested this, so please check it out with the current dev build