vintlabs / fauxmoESP

Add voice control of your ESP32 and ESP8266 devices using Amazon Alexa
MIT License
383 stars 69 forks source link

Crash when controlling mutiple devices at same time from Alexa #115

Closed pvint closed 3 years ago

pvint commented 3 years ago

Original report by Paul Vint (Bitbucket: pvint, GitHub: pvint).


I’ve been having occasional crashes for months, and I had thought it was taken care of when I updated AsyncTCP, but it has come back, but today I was lucky to have a consistent way to reproduce it and got some info.

Right now, if I tell Alexa “Turn on White Lights”, it sends commands to turn on fauxmo devices 0,1 and 2 (which actually works), however when fauxmo is closing connections and cleaning up, it is trying to call _tcpClients[0]->free(); an extra time for device 0 (zero). (Tested with 2nd gen and 3rd gen Echo Dot with same results)

Here is my console output when it occurs (I added a couple printf statements in fauxmoESP.cpp and AsyncTCP.cpp for more info), along with a backtrace:

[FAUXMO] Client #0 connected
[FAUXMO] Handling state request
I (12337) starfish: fauxmo device_id = 1    state = 1   val = 255   v = 4080

[FAUXMO] Client #1 connected
[FAUXMO] Client #2 connected
[FAUXMO] Handling state request
I (12347) starfish: fauxmo device_id = 2    state = 1   val = 255   v = 4080

[FAUXMO] Handling state request
I (12347) starfish: fauxmo device_id = 3    state = 1   val = 255   v = 4080

fauxmoesp.cpp +343: about to run _tcpClients[0]->free();
Line 1002 AsyncTCP.cpp AsyncClient::free()
[FAUXMO] Client #0 disconnected
fauxmoesp.cpp +343: about to run _tcpClients[2]->free();
Line 1002 AsyncTCP.cpp AsyncClient::free()
[FAUXMO] Client #2 disconnected
[FAUXMO] Client #0 connected
[FAUXMO] Handling list request
fauxmoesp.cpp +343: about to run _tcpClients[1]->free();
Line 1002 AsyncTCP.cpp AsyncClient::free()
[FAUXMO] Client #1 disconnected
[FAUXMO] Client #0 connected
[FAUXMO] Client #1 connected
[FAUXMO] Handling list request
[FAUXMO] Handling list request
fauxmoesp.cpp +343: about to run _tcpClients[0]->free();
Line 1002 AsyncTCP.cpp AsyncClient::free()
[FAUXMO] Client #0 disconnected
fauxmoesp.cpp +343: about to run _tcpClients[1]->free();
Line 1002 AsyncTCP.cpp AsyncClient::free()
[FAUXMO] Client #1 disconnected
fauxmoesp.cpp +343: about to run _tcpClients[0]->free();
_tcpClients[i] is NULL!!!!
Line 1002 AsyncTCP.cpp AsyncClient::free()
this is NULL!!!
Guru Meditation Error: Core  1 panic'ed (LoadProhibited). Exception was unhandled.
Core 1 register dump:
PC      : 0x40101812  PS      : 0x00060b30  A0      : 0x80100171  A1      : 0x3ffeac80  
0x40101812: AsyncClient::free() at /usr/local/src/Starfish-idf/main/AsyncTCP.cpp:660

A2      : 0x00000000  A3      : 0x3ffeae78  A4      : 0x00000001  A5      : 0x00000001  
A6      : 0x0000000a  A7      : 0x3ffe11b0  A8      : 0x80101812  A9      : 0x3ffeac60  
A10     : 0x0000000a  A11     : 0x3ffb65f0  A12     : 0x8008f716  A13     : 0x3ffeab90  
A14     : 0x00000003  A15     : 0x00060023  SAR     : 0x0000000a  EXCCAUSE: 0x0000001c  
EXCVADDR: 0x00000000  LBEG    : 0x400014fd  LEND    : 0x4000150d  LCOUNT  : 0xfffffffb  

Backtrace: 0x40101812:0x3ffeac80 0x4010016e:0x3ffeaca0 0x40101b11:0x3ffeacc0 0x40101c96:0x3ffeacf0 0x40101cac:0x3ffead10 0x401020a3:0x3ffead30 0x40102161:0x3ffead50 0x4008f50a:0x3ffead80
0x40101812: AsyncClient::free() at /usr/local/src/Starfish-idf/main/AsyncTCP.cpp:660

0x4010016e: std::_Function_handler<void (void*, AsyncClient*), fauxmoESP::_onTCPClient(AsyncClient*)::{lambda(void*, AsyncClient*)#3}>::_M_invoke(std::_Any_data const&, void*&&, AsyncClient*&&) at /usr/local/src/Starfish-idf/main/fauxmoESP.cpp:459
 (inlined by) _M_invoke at /usr/local/src/xtensa-esp32-elf/xtensa-esp32-elf/include/c++/5.2.0/functional:1871

0x40101b11: std::function<void (void*, AsyncClient*)>::operator()(void*, AsyncClient*) const at /usr/local/src/Starfish-idf/main/AsyncTCP.cpp:660

0x40101c96: AsyncClient::_fin(tcp_pcb*, signed char) at /usr/local/src/Starfish-idf/main/AsyncTCP.cpp:660

0x40101cac: AsyncClient::_s_fin(void*, tcp_pcb*, signed char) at /usr/local/src/Starfish-idf/main/AsyncTCP.cpp:660

0x401020a3: _handle_async_event(lwip_event_packet_t*) at /usr/local/src/Starfish-idf/main/AsyncTCP.cpp:660

0x40102161: _async_service_task(void*) at /usr/local/src/Starfish-idf/main/AsyncTCP.cpp:660

0x4008f50a: vPortTaskWrapper at /home/pvint/ESP32/esp-idf/components/freertos/port.c:403

Entering gdb stub now.
$T0b#e6GNU gdb (crosstool-NG crosstool-ng-1.22.0-80-g6c4433a) 7.10
Copyright (C) 2015 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law.  Type "show copying"
and "show warranty" for details.
This GDB was configured as "--host=x86_64-build_pc-linux-gnu --target=xtensa-esp32-elf".
Type "show configuration" for configuration details.
For bug reporting instructions, please see:
<http://www.gnu.org/software/gdb/bugs/>.
Find the GDB manual and other documentation resources online at:
<http://www.gnu.org/software/gdb/documentation/>.
For help, type "help".
Type "apropos word" to search for commands related to "word"...
Reading symbols from /usr/local/src/Starfish-idf/build/starfish-idf.elf...done.
Remote debugging using /dev/ttyUSB0
AsyncClient::free (this=0x0) at /usr/local/src/Starfish-idf/main/AsyncTCP.cpp:1005
1005        if(!_pcb) {
(gdb) bt
#0  AsyncClient::free (this=0x0) at /usr/local/src/Starfish-idf/main/AsyncTCP.cpp:1005
#1  0x40100171 in fauxmoESP::<lambda(void*, AsyncClient*)>::operator() (c=0x3ffbb4e4, s=<optimized out>, __closure=0x3ffbb500) at /usr/local/src/Starfish-idf/main/fauxmoESP.cpp:347
#2  std::_Function_handler<void(void*, AsyncClient*), fauxmoESP::_onTCPClient(AsyncClient*)::<lambda(void*, AsyncClient*)> >::_M_invoke(const std::_Any_data &, <unknown type in /usr/local/src/Starfish-idf/build/starfish-idf.elf, CU 0x57c1c, DIE 0x64b90>, <unknown type in /usr/local/src/Starfish-idf/build/starfish-idf.elf, CU 0x57c1c, DIE 0x64b95>) (__functor=..., __args#0=<optimized out>, 
    __args#1=<unknown type in /usr/local/src/Starfish-idf/build/starfish-idf.elf, CU 0x57c1c, DIE 0x64b95>) at /usr/local/src/xtensa-esp32-elf/xtensa-esp32-elf/include/c++/5.2.0/functional:1871
#3  0x40101b14 in std::function<void (void*, AsyncClient*)>::operator()(void*, AsyncClient*) const (this=0x3ffbb500, __args#0=0x0, __args#1=0x3ffbb4e4)
    at /usr/local/src/xtensa-esp32-elf/xtensa-esp32-elf/include/c++/5.2.0/functional:2271
#4  0x40101c99 in AsyncClient::_fin (this=0x3ffbb4e4, pcb=0x3fff1500, err=0 '\000') at /usr/local/src/Starfish-idf/main/AsyncTCP.cpp:907
#5  0x40101caf in AsyncClient::_s_fin (arg=0x3ffbb4e4, pcb=0x3fff1500, err=0 '\000') at /usr/local/src/Starfish-idf/main/AsyncTCP.cpp:1217
#6  0x401020a6 in _handle_async_event (e=0x3ffbaf98) at /usr/local/src/Starfish-idf/main/AsyncTCP.cpp:165
#7  0x40102164 in _async_service_task (pvParameters=0x0) at /usr/local/src/Starfish-idf/main/AsyncTCP.cpp:197
#8  0x4008f50d in vPortTaskWrapper (pxCode=0x40102110 <_async_service_task(void*)>, pvParameters=0x0) at /home/pvint/ESP32/esp-idf/components/freertos/port.c:143
(gdb)

(The I (12337) starfish: fauxmo device_id = 1 state = 1 val = 255 v = 4080 lines are from my software showing where it receives info from fauxmoESP)

The critical part seems to be:

fauxmoesp.cpp +343: about to run _tcpClients[0]->free();
Line 1002 AsyncTCP.cpp AsyncClient::free()
[FAUXMO] Client #0 disconnected
fauxmoesp.cpp +343: about to run _tcpClients[2]->free();
Line 1002 AsyncTCP.cpp AsyncClient::free()
[FAUXMO] Client #2 disconnected
[FAUXMO] Client #0 connected
[FAUXMO] Handling list request
fauxmoesp.cpp +343: about to run _tcpClients[1]->free();
Line 1002 AsyncTCP.cpp AsyncClient::free()
[FAUXMO] Client #1 disconnected
[FAUXMO] Client #0 connected
[FAUXMO] Client #1 connected
[FAUXMO] Handling list request
[FAUXMO] Handling list request
fauxmoesp.cpp +343: about to run _tcpClients[0]->free();
Line 1002 AsyncTCP.cpp AsyncClient::free()
[FAUXMO] Client #0 disconnected
fauxmoesp.cpp +343: about to run _tcpClients[1]->free();
Line 1002 AsyncTCP.cpp AsyncClient::free()
[FAUXMO] Client #1 disconnected
fauxmoesp.cpp +343: about to run _tcpClients[0]->free();
_tcpClients[i] is NULL!!!!
Line 1002 AsyncTCP.cpp AsyncClient::free()
this is NULL!!!
Guru Meditation Error: Core  1 panic'ed (LoadProhibited). Exception was unhandled.

Note that near the end, it frees client 0, then client 1, and then tries to free client 0 again.

Debugging statements I added around line 343 in fauxmoESP.cpp:

printf("fauxmoesp.cpp +343: about to run _tcpClients[%d]->free();\n", i);
if(!_tcpClients[i])
printf("_tcpClients[i] is NULL!!!!\n");
                        _tcpClients[i]->free();
                        _tcpClients[i] = NULL;

I’ll keep digging and update as I have more info.

Thanks

pvint commented 3 years ago

Original comment by Paul Vint (Bitbucket: pvint, GitHub: pvint).


I’m having trouble tracing back to see why it’s trying to remove it twice, so for now I’ve done this:

340a341
> 
342,348c343,344
<           if(_tcpClients[i] != NULL) {
<                       _tcpClients[i]->free();
<                       _tcpClients[i] = NULL;
<                   }
<           else {
<                       DEBUG_MSG_FAUXMO("[FAUXMO] Client %d already disconnected\n", i);
<                   }
---
>                   _tcpClients[i]->free();
>                   _tcpClients[i] = NULL;

This seems to be functioning fine.

For reference, I’m using this in an esp-idf project, specifically: https://github.com/pvint/Starfish-idf/blob/master/main/starfish_main.cpp and it’s been controlling the lighting on my boat for a couple years. This is really a great project, and thanks!

Paul

Tejas-MD commented 3 years ago

Hi, I have recently been facing a new issue: Devices don't discover . And I think it might be slightly related to this issue.

Here's the Faxmo Debug Output:

During addDevice :

[FAUXMO] UDP server started
[FAUXMO] Device 'matrix 1' added as #0
[FAUXMO] Device 'matrix 2' added as #1
[FAUXMO] Device 'matrix 3' added as #2
[FAUXMO] Device 'matrix 4' added as #3
[FAUXMO] Device 'matrix 5' added as #4

When Alexa tries to discover devices :

[FAUXMO] Client #0 connected
[FAUXMO] Handling list request
[FAUXMO] Sending device info for "matrix 1", uniqueID = "e19e23ea6249"
[FAUXMO] Sending device info for "matrix 2", uniqueID = "73e1eff10d85"
[FAUXMO] Sending device info for "matrix 3", uniqueID = "2204d4759ed4"
[FAUXMO] Sending device info for "matrix 4", uniqueID = "53c083e13819"
[FAUXMO] Sending device info for "matrix 5", uniqueID = "8542c5f4db51"
[FAUXMO] Client #0 disconnected
[FAUXMO] Client #0 connected
[FAUXMO] Handling devicetype request
[FAUXMO] Client #0 disconnected
[FAUXMO] Client #0 connected
[FAUXMO] Handling list request
[FAUXMO] Sending device info for "matrix 1", uniqueID = "e19e23ea6249"
[FAUXMO] Sending device info for "matrix 2", uniqueID = "73e1eff10d85"
[FAUXMO] Sending device info for "matrix 3", uniqueID = "2204d4759ed4"
[FAUXMO] Sending device info for "matrix 4", uniqueID = "53c083e13819"
[FAUXMO] Sending device info for "matrix 5", uniqueID = "8542c5f4db51"
[FAUXMO] Client #0 disconnected
[FAUXMO] Client #0 connected
[FAUXMO] Handling devicetype request
[FAUXMO] Client #0 disconnected
[FAUXMO] Client #0 connected
[FAUXMO] Handling list request
[FAUXMO] Sending device info for "matrix 1", uniqueID = "e19e23ea6249"
[FAUXMO] Sending device info for "matrix 2", uniqueID = "73e1eff10d85"
[FAUXMO] Sending device info for "matrix 3", uniqueID = "2204d4759ed4"
[FAUXMO] Sending device info for "matrix 4", uniqueID = "53c083e13819"
[FAUXMO] Sending device info for "matrix 5", uniqueID = "8542c5f4db51"
[FAUXMO] Client #0 disconnected
[FAUXMO] Client #0 connected
[FAUXMO] Handling devicetype request
[FAUXMO] Client #0 disconnected
[FAUXMO] Client #0 connected
[FAUXMO] Handling list request
[FAUXMO] Sending device info for "matrix 1", uniqueID = "e19e23ea6249"
[FAUXMO] Sending device info for "matrix 2", uniqueID = "73e1eff10d85"
[FAUXMO] Sending device info for "matrix 3", uniqueID = "2204d4759ed4"
[FAUXMO] Sending device info for "matrix 4", uniqueID = "53c083e13819"
[FAUXMO] Sending device info for "matrix 5", uniqueID = "8542c5f4db51"
[FAUXMO] Client #0 disconnected

The code is fairly simple, Have used all necessary init stuff (setPort, .enable) and everything, I run fauxmo.handle() in the loop without fail.

Please help me fix this ASAP, not able to discover/ Turn devices on/off

pvint commented 3 years ago

@Tejas-MD
First thing I need to be sure of is that you're using version 3.1.2 or latest pull from master branch.

Failing that: ESP32 or ESP8266?

Can you test with a minimal sketch like the Basic example?

Tejas-MD commented 3 years ago

Hi, I ran a few more tests, and it was fixed!!!

Had to add this to the platform.ini:

board_build.f_flash = 80000000L
build_flags= -DPIO_FRAMEWORK_ARDUINO_LWIP_HIGHER_BANDWIDTH

Board: Esp8266

Tejas-MD commented 3 years ago

Also btw, since this relates to this issue fix: Thanks for giving the grouping and switch operation thing priority! I just saw it pair under "Lights" And has a cool UI for turning lights on and off on the alexa app itself!

I wanted to know: Does the library support the ON/OFF status on the alexa app? Cause my app says: Device does not support requested value and turns the switch(That button with a glowing white) off 5-6 seconds after the switch operation is successful, though it triggers the callback on my mcu!

pvint commented 3 years ago

Good news!

It's a bit "new" in the master branch (showing up as a proper light in Alexa App), so there's some quirks.

I'm testing that and more on the 'colour' branch - if you're feeling adventurous, try it out https://github.com/vintlabs/fauxmoESP/tree/colour