search

me-no-dev / ESPAsyncTCP

Async TCP Library for ESP8266
GNU Lesser General Public License v3.0
758 stars 396 forks source link

got Exception 29 when have bad internet #79

Closed tarzan115 closed 5 years ago

tarzan115 commented 6 years ago

thank you for your libraries. I got a problem with Arduino core 2.4 when I have internet and then I shut down internet (wifi still present), after 10 senconds I turn on internet I got an error with this log

Exception 29: StoreProhibited: A store referenced a page mapped with an attribute that does not permit stores
Decoding 21 results
0x40225952: memset at /Users/igrokhotkov/e/newlib-xtensa/xtensa-lx106-elf/newlib/libc/machine/xtensa/../../../../.././newlib/libc/machine/xtensa/memset.S line 133
0x401007d9: umm_calloc at C:\Program Files (x86)\Arduino\hardware\esp8266com\esp8266\cores\esp8266\umm_malloc/umm_malloc.c line 1688
0x4020229d: calloc at C:\Program Files (x86)\Arduino\hardware\esp8266com\esp8266\cores\esp8266/heap.c line 82
0x402330f1: ssl_new at ssl/tls1.c line 2007
0x40234dbc: ssl_client_new at ssl/tls1_clnt.c line 69
0x4020229d: calloc at C:\Program Files (x86)\Arduino\hardware\esp8266com\esp8266\cores\esp8266/heap.c line 82
0x402011c7: tcp_ssl_new_client at D:\Documents\Arduino\libraries\ESPAsyncTCP-master\src/tcp_axtls.c line 477
0x40213857: AsyncClient::_connected(void*, long) at D:\Documents\Arduino\libraries\ESPAsyncTCP-master\src/ESPAsyncTCP.cpp line 659
0x402138bc: AsyncClient::_s_connected(void*, void*, long) at D:\Documents\Arduino\libraries\ESPAsyncTCP-master\src/ESPAsyncTCP.cpp line 659
0x4022d306: tcp_process at /home/david/dev/esp8266/origin/tools/sdk/lwip2/builder/lwip2-src/src/core/tcp_in.c line 821
:  (inlined by) tcp_input at /home/david/dev/esp8266/origin/tools/sdk/lwip2/builder/lwip2-src/src/core/tcp_in.c line 372
0x401007ac: umm_malloc at C:\Program Files (x86)\Arduino\hardware\esp8266com\esp8266\cores\esp8266\umm_malloc/umm_malloc.c line 1668
0x40240000: crypto_mod_exp at ?? line ?
0x40231679: ip4_input at /home/david/dev/esp8266/origin/tools/sdk/lwip2/builder/lwip2-src/src/core/ipv4/ip4.c line 685
0x4022ab79: ethernet_input_LWIP2 at /home/david/dev/esp8266/origin/tools/sdk/lwip2/builder/lwip2-src/src/netif/ethernet.c line 182
0x401048ec: esp2glue_ethernet_input at /home/david/dev/esp8266/origin/tools/sdk/lwip2/builder/glue-lwip/lwip-git.c line 406
0x4025cb5a: ethernet_input at /home/david/dev/esp8266/origin/tools/sdk/lwip2/builder/glue-esp/lwip-esp.c line 356
0x4025cb88: ethernet_input at /home/david/dev/esp8266/origin/tools/sdk/lwip2/builder/glue-esp/lwip-esp.c line 364
0x40257a8f: ppPeocessRxPktHdr at ?? line ?
0x4025ec0b: ets_snprintf at ?? line ?
tarzan115 commented 6 years ago

I used option LwIP v2 prebuild (MSS=1460) and I got that problem. but when I used option LwIP 1.4 prebuild it works perfectly.

Adam5Wu commented 6 years ago

Maybe related to #83 / #84 A double free would likely occur at connection closure with LwIP2. Before #84 is finalized, the best workaround is to use LwIP1 instead.

tarzan115 commented 6 years ago

Hi @Adam5Wu. thanks for your comment. I have tried your PR but that error still valid with this log:

0x40232d43: send_client_hello at ssl/tls1_clnt.c line 202
:  (inlined by) do_client_connect at ssl/tls1_clnt.c line 167
0x40232d3f: send_client_hello at ssl/tls1_clnt.c line 202
:  (inlined by) do_client_connect at ssl/tls1_clnt.c line 167
0x401004d8: malloc at D:\Documents\Arduino\hardware\esp8266com\esp8266\cores\esp8266\umm_malloc/umm_malloc.c line 1668
0x4010453c: esp2glue_ethernet_input at /local/users/gauchard/arduino/arduino_esp8266/origin/tools/sdk/lwip2/builder/glue-lwip/lwip-git.c line 407
0x40232f82: ssl_client_new at ssl/tls1_clnt.c line 89
0x401004d8: malloc at D:\Documents\Arduino\hardware\esp8266com\esp8266\cores\esp8266\umm_malloc/umm_malloc.c line 1668
0x402011c3: tcp_ssl_new_client at D:\Documents\Arduino\libraries\ESPAsyncTCP\src/tcp_axtls.c line 479
0x40214b93: AsyncClient::_connected(void*, long) at D:\Documents\Arduino\libraries\ESPAsyncTCP\src/ESPAsyncTCP.cpp line 670
0x40214bf8: AsyncClient::_s_connected(void*, void*, long) at D:\Documents\Arduino\libraries\ESPAsyncTCP\src/ESPAsyncTCP.cpp line 670
0x4022b472: tcp_process at /local/users/gauchard/arduino/arduino_esp8266/origin/tools/sdk/lwip2/builder/lwip2-src/src/core/tcp_in.c line 821
:  (inlined by) tcp_input at /local/users/gauchard/arduino/arduino_esp8266/origin/tools/sdk/lwip2/builder/lwip2-src/src/core/tcp_in.c line 372
0x4022f7e5: ip4_input at /local/users/gauchard/arduino/arduino_esp8266/origin/tools/sdk/lwip2/builder/lwip2-src/src/core/ipv4/ip4.c line 685
0x40228ce5: ethernet_input_LWIP2 at /local/users/gauchard/arduino/arduino_esp8266/origin/tools/sdk/lwip2/builder/lwip2-src/src/netif/ethernet.c line 182
0x4010453c: esp2glue_ethernet_input at /local/users/gauchard/arduino/arduino_esp8266/origin/tools/sdk/lwip2/builder/glue-lwip/lwip-git.c line 407
0x40252174: ethernet_input at /local/users/gauchard/arduino/arduino_esp8266/origin/tools/sdk/lwip2/builder/glue-esp/lwip-esp.c line 356
0x40252186: ethernet_input at /local/users/gauchard/arduino/arduino_esp8266/origin/tools/sdk/lwip2/builder/glue-esp/lwip-esp.c line 364
0x4024cf52: ppPeocessRxPktHdr at ?? line ?
0x402540df: ets_snprintf at ?? line

I disconnect Internet and WiFi still available. and after 2 minutes I plug in cable internet and got that issue.

tarzan115 commented 6 years ago

I enable debug and I saw client with log below. if _connected() once it run perfectly but it _connected() 3 times without free. @Adam5Wu can you help me solve this problem. please!

TCP disconnected
reconnect MQTT
_connected()
address pcb: 0x3fff781c
tcp_ssl_new: 1
_connected() end
_connected()
address pcb: 0x3fff742c
tcp_ssl_new: 2
_connected() end
_connected()
address pcb: 0x3fff3fac
tcp_ssl_new: 3
Fatal exception 29(StoreProhibitedCause):
epc1=0x40232f9b, epc2=0x00000000, epc3=0x00000000, excvaddr=0x00000006, depc=0x00000000

Exception (29):
epc1=0x40232f9b epc2=0x00000000 epc3=0x00000000 excvaddr=0x00000006 depc=0x00000000

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

>>>stack>>>
3ffffe50:  00000003 00000314 3fffab44 40232f97  
3ffffe60:  00000003 3fff4244 3fffab44 401004d8  
3ffffe70:  3ffffe90 3fff4244 3fffab44 00000000  
3ffffe80:  00000000 3fff4244 3fffab44 402331da  
3ffffe90:  00000000 00000003 00000000 00000003  
3ffffea0:  00000012 3fff3450 3fff4244 3fff4244  
3ffffeb0:  00000000 3fff3fac 3fff4274 40201221  
3ffffec0:  3ffe9e64 3fff3fac 00000000 3fff2658  
3ffffed0:  3fff3fac 3fff3fac 3fff08f0 40214dc8  
3ffffee0:  3fff3fac 3fff263c 3fff263d 40214e38  
3ffffef0:  3fff3fac 3fff263c 3fff263d 4022b6ca  
3fffff00:  3089a8c0 00000012 00000002 00000000  
3fffff10:  00000000 0000003a 3fffff80 3fff78e2  
3fffff20:  3fff27c0 3fff78c4 3fff28a8 4022fa3d  
3fffff30:  00000014 00000228 00000228 3fff27c0  
3fffff40:  3fffdc80 3fff2ec4 3fff3b64 3fff2f34  
3fffff50:  00000008 3fff27c0 3fff78c4 40228f3d  
3fffff60:  3fffdc80 3fff2ec4 3fff3b64 4010453c  
3fffff70:  402523cc 3fff2ec4 3fff3b64 402523de  
3fffff80:  3fff78d4 3fff78c4 3fffdab0 00000000  
3fffff90:  4024d1aa 00000000 3fff3b64 40254337  
3fffffa0:  40000f49 3fffdab0 3fffdab0 40000f49  
<<<stack<<<

decode stack:

Exception 29: StoreProhibited: A store referenced a page mapped with an attribute that does not permit stores
Decoding 18 results
0x40232f9b: send_client_hello at ssl/tls1_clnt.c line 202
:  (inlined by) do_client_connect at ssl/tls1_clnt.c line 167
0x40232f9b: send_client_hello at ssl/tls1_clnt.c line 202
:  (inlined by) do_client_connect at ssl/tls1_clnt.c line 167
0x40232f97: send_client_hello at ssl/tls1_clnt.c line 202
:  (inlined by) do_client_connect at ssl/tls1_clnt.c line 167
0x401004d8: malloc at D:\Documents\Arduino\hardware\esp8266com\esp8266\cores\esp8266\umm_malloc/umm_malloc.c line 1674
0x402331da: ssl_client_new at ssl/tls1_clnt.c line 89
0x40201221: tcp_ssl_new_client at D:\Documents\Arduino\libraries\ESPAsyncTCP\src/tcp_axtls.c line 479
0x40214dc8: AsyncClient::_connected(void*, long) at D:\Documents\Arduino\libraries\ESPAsyncTCP\src/ESPAsyncTCP.cpp line 674
0x40214e38: AsyncClient::_s_connected(void*, void*, long) at D:\Documents\Arduino\libraries\ESPAsyncTCP\src/ESPAsyncTCP.cpp line 674
0x4022b6ca: tcp_process at /local/users/gauchard/arduino/arduino_esp8266/origin/tools/sdk/lwip2/builder/lwip2-src/src/core/tcp_in.c line 821
:  (inlined by) tcp_input at /local/users/gauchard/arduino/arduino_esp8266/origin/tools/sdk/lwip2/builder/lwip2-src/src/core/tcp_in.c line 372
0x4022fa3d: ip4_input at /local/users/gauchard/arduino/arduino_esp8266/origin/tools/sdk/lwip2/builder/lwip2-src/src/core/ipv4/ip4.c line 685
0x40228f3d: ethernet_input_LWIP2 at /local/users/gauchard/arduino/arduino_esp8266/origin/tools/sdk/lwip2/builder/lwip2-src/src/netif/ethernet.c line 182
0x4010453c: esp2glue_ethernet_input at /local/users/gauchard/arduino/arduino_esp8266/origin/tools/sdk/lwip2/builder/glue-lwip/lwip-git.c line 407
0x402523cc: ethernet_input at /local/users/gauchard/arduino/arduino_esp8266/origin/tools/sdk/lwip2/builder/glue-esp/lwip-esp.c line 356
0x402523de: ethernet_input at /local/users/gauchard/arduino/arduino_esp8266/origin/tools/sdk/lwip2/builder/glue-esp/lwip-esp.c line 364
0x4024d1aa: ppPeocessRxPktHdr at ?? line ?
0x40254337: ets_snprintf at ?? line ?
Adam5Wu commented 6 years ago

Have you enabled ASYNC_TCP_DEBUG and TCP_SSL_DEBUG in async_config? If not please do so, it can help to give more context of what is going on. :D

tarzan115 commented 6 years ago

I did enable. and this is log: to produce that problem, I connected my laptop to WiFi A, and create a hotspot name B in my laptop. I connected my ESP8266 to WiFi B that I created. after my ESP8266 connected to Server successfully. I disconnect my laptop to WiFi A (hostpot B still valid) and waiting about 20 seconds and reconnect my laptop to WiFi A. my ESP8266 will reconnect to server and I got that problem. if I waiting about 5 seconds, the device run perfectly.

_close
tcp_ssl_free: 0
reconnect MQTT
reconnect MQTT
reconnect MQTT
reconnect MQTT
_error()
Disconnected from MQTT. Because: TCP disconnected
reconnect MQTT
reconnect MQTT
_error()
Disconnected from MQTT. Because: TCP disconnected
reconnect MQTT
reconnect MQTT
_error()
Disconnected from MQTT. Because: TCP disconnected
reconnect MQTT
reconnect MQTT
_error()
Disconnected from MQTT. Because: TCP disconnected
reconnect MQTT
reconnect MQTT
_error()
Disconnected from MQTT. Because: TCP disconnected
reconnect MQTT
_error()
Disconnected from MQTT. Because: TCP disconnected
...

and so on with same log in about 20 seconds and then I reconnect to WiFi A and hotspot B will have Internet.

...
Disconnected from MQTT. Because: TCP disconnected
reconnect MQTT
_connected()
pcb address: 0x3fff6bbc
tcp_ssl_new: 1
_connected() end
_connected()
pcb address: 0x3fff404c
tcp_ssl_new: 2
_connected() end
_connected()
pcb address: 0x3fff6a84
tcp_ssl_new: 3
Fatal exception 29(StoreProhibitedCause):
epc1=0x40232f77, epc2=0x00000000, epc3=0x00000000, excvaddr=0x00000006, depc=0x00000000

Exception (29):
epc1=0x40232f77 epc2=0x00000000 epc3=0x00000000 excvaddr=0x00000006 depc=0x00000000

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

>>>stack>>>
3ffffe50:  00000003 00000314 3fffbd94 40232f73  
3ffffe60:  00000003 3fff6b2c 3fffbd94 401004d8  
3ffffe70:  3ffffe90 3fff6b2c 3fffbd94 00000000  
3ffffe80:  00000000 3fff6b2c 3fffbd94 402331b6  
3ffffe90:  00000000 00000003 00000000 00000008  
3ffffea0:  0000002f 3fff2a20 3fff6b2c 3fff6b2c  
3ffffeb0:  00000000 3fff6a84 3fff6b5c 40201221  
3ffffec0:  3ffe9e64 3fff6a84 00000000 3fff2658  
3ffffed0:  3fff6a84 3fff6a84 3fff08f0 40214da0  
3ffffee0:  3fff6a84 3fff263c 3fff263d 40214e10  
3ffffef0:  3fff6a84 3fff263c 3fff263d 4022b6a6  
3fffff00:  0289a8c0 00000012 00000002 00000000  
3fffff10:  00000000 0000003a 3fffff80 3fff690a  
3fffff20:  3fff27c0 3fff68ec 3fff28a8 4022fa19  
3fffff30:  00000014 00000906 00000906 3fff27c0  
3fffff40:  3fffdc80 3fff2ec4 3fff7254 3fff2f3c  
3fffff50:  00000008 3fff27c0 3fff68ec 40228f19  
3fffff60:  3fffdc80 3fff2ec4 3fff7254 4010453c  
3fffff70:  402523a8 3fff2ec4 3fff7254 402523ba  
3fffff80:  3fff68fc 3fff68ec 00000000 3fffdcc0  
3fffff90:  4024d186 00000000 3fff7254 40254313  
3fffffa0:  40000f49 3fffdab0 3fffdab0 40000f49  
<<<stack<<<

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

decode stack

Exception 29: StoreProhibited: A store referenced a page mapped with an attribute that does not permit stores
Decoding 17 results
0x40232f77: send_client_hello at ssl/tls1_clnt.c line 202
:  (inlined by) do_client_connect at ssl/tls1_clnt.c line 167
0x40232f73: send_client_hello at ssl/tls1_clnt.c line 202
:  (inlined by) do_client_connect at ssl/tls1_clnt.c line 167
0x401004d8: malloc at D:\Documents\Arduino\hardware\esp8266com\esp8266\cores\esp8266\umm_malloc/umm_malloc.c line 1674
0x402331b6: ssl_client_new at ssl/tls1_clnt.c line 89
0x40201221: tcp_ssl_new_client at D:\Documents\Arduino\libraries\ESPAsyncTCP\src/tcp_axtls.c line 479
0x40214da0: AsyncClient::_connected(void*, long) at D:\Documents\Arduino\libraries\ESPAsyncTCP\src/ESPAsyncTCP.cpp line 674
0x40214e10: AsyncClient::_s_connected(void*, void*, long) at D:\Documents\Arduino\libraries\ESPAsyncTCP\src/ESPAsyncTCP.cpp line 674
0x4022b6a6: tcp_process at /local/users/gauchard/arduino/arduino_esp8266/origin/tools/sdk/lwip2/builder/lwip2-src/src/core/tcp_in.c line 821
:  (inlined by) tcp_input at /local/users/gauchard/arduino/arduino_esp8266/origin/tools/sdk/lwip2/builder/lwip2-src/src/core/tcp_in.c line 372
0x4022fa19: ip4_input at /local/users/gauchard/arduino/arduino_esp8266/origin/tools/sdk/lwip2/builder/lwip2-src/src/core/ipv4/ip4.c line 685
0x40228f19: ethernet_input_LWIP2 at /local/users/gauchard/arduino/arduino_esp8266/origin/tools/sdk/lwip2/builder/lwip2-src/src/netif/ethernet.c line 182
0x4010453c: esp2glue_ethernet_input at /local/users/gauchard/arduino/arduino_esp8266/origin/tools/sdk/lwip2/builder/glue-lwip/lwip-git.c line 407
0x402523a8: ethernet_input at /local/users/gauchard/arduino/arduino_esp8266/origin/tools/sdk/lwip2/builder/glue-esp/lwip-esp.c line 356
0x402523ba: ethernet_input at /local/users/gauchard/arduino/arduino_esp8266/origin/tools/sdk/lwip2/builder/glue-esp/lwip-esp.c line 364
0x4024d186: ppPeocessRxPktHdr at ?? line ?
0x40254313: ets_snprintf at ?? line ?

thank you for your consider.

Adam5Wu commented 6 years ago

The information you provided is too little to understand the situation.

My wild guess: your reconnect routine did not wait for previous attempt to conclude before making a new connection, this causes multiple pending connection requests. When Internet is restored, all three pending connection succeeded at the same time, and this used up all heap space. I remember seeing somewhere that axTLS internally did not gracefully handle all malloc failure everywhere, and this leads to access violation exception (excvaddr=0x00000006 hinted the cause).

If you can share your code maybe I can better help.

tarzan115 commented 6 years ago

thank you so so much. In your comment, I realize that I reconnect too much in a short time. so I reduce that and problem is gone. but I found another error is: when we lost Internet (Access point still valid) the event Disconnect not fire. I tried example https://github.com/marvinroger/async-mqtt-client/tree/master/examples/FullyFeaturedSSL

anyway, thank you so much. have a good day :D

marciopamplona commented 6 years ago

Questions: 1) do you disable the SDK autoreconnect and create yourself an autoreconnect routine ? The SDK documentation mention an issue in the correct status information when the autoreconnect is disabled. 2) How do you know when the pending connection conclude or fail to reattempt a new connection ?

tarzan115 commented 6 years ago
  1. No, I didn't. autoReconnect is for Wi-Fi. And my case Wi-Fi is still available but MQTT was disconnected.
  2. I got that problem when I make a functioning auto reconnect MQTT every 10 seconds. And I fix it by making a new connection at a time and waiting for disconnect event to free last connection and make a new one.
marciopamplona commented 6 years ago

Thanks for the answer. I have the exact same problem (loadstore exception) with the WIFI SDK autoconnect routine, especially when i use the WPA2 enterprise. I'm going nuts with this thing...

stale[bot] commented 5 years ago

[STALE_SET] This issue has been automatically marked as stale because it has not had recent activity. It will be closed in 14 days if no further activity occurs. Thank you for your contributions.

stale[bot] commented 5 years ago

[STALE_DEL] This stale issue has been automatically closed. Thank you for your contributions.