Soft WDT reset in tcp_write with WiFiClientSecure

[liquidfalcon]

Basic Infos

Hardware

Hardware: ESP-12F
Core Version: Git

Description

After I believe the second WiFiClient rewrite (Although, I may be wrong here), I started noticing occasional WDT resets when using WiFiClientSeccure and large payloads. They consistently fail in the same area, namely tcp_write in LWIP.

The setup is simple:

Connect to a TLS 1.1 server with a 2K certificate. My code has approximately 30500 bytes free of heap space before I start this connection. Then, send a 1600+ byte (dynamically allocated in my case, exact size being 1696 bytes sent) payload at once via client.write(...). This will then trigger a soft WDT reset approximately 5 seconds later with the below trace. Sending my smaller payload (1200 bytes and below) over and over again generally does not cause an issue, but does occasionally crash with the same reset once or twice an hour.

Settings in IDE

Module: Generic ESP8266 Module
Flash Size: 4MB/1MB
CPU Frequency: 80Mhz
Flash Mode: qio
Flash Frequency: 40Mhz
Upload Using: SERIAL
Reset Method: N/A

Debug Messages

Raw Output:

Soft WDT reset

ctx: cont 
sp: 3fff2684 end: 3fff2c94 offset: 01b0

>>>stack>>>
3fff2834:  271af377 856ba915 00000000 00000000  
3fff2844:  4024df9e 3fff43fc 00000000 4024df74  
3fff2854:  00000000 000006e5 00000000 3fffa4fc  
3fff2864:  000005b4 00000000 00000001 3fff9b2c  
3fff2874:  000005b4 00000000 00000000 40220668  
3fff2884:  0000000a 00000009 3fff4c68 00000000  
3fff2894:  3fffa4fc 000006e5 3fff42f4 402171b4  
3fff28a4:  3fff4bb8 3fff4bc8 3fff4d98 00000000  
3fff28b4:  3fffa4fc 000006e5 3fff42f4 40217f08  
3fff28c4:  00000000 3fff455c 000006e5 40240a8d  
3fff28d4:  06030317 74736fa0 306d203a 61656d2e  
3fff28e4:  000006a0 00000017 00000010 006e6574  
3fff28f4:  3fff2934 3fff2904 00000008 00000000  
3fff2904:  3fff455c 3fff93d4 000006a0 40240b17  
3fff2914:  000006a0 ff000000 00000008 4020e3cd  
3fff2924:  3ffe9212 000006b5 3fff2904 3fff2964  
3fff2934:  3fff2aac 3fff2a64 3fff2aac 40217988  
3fff2944:  00000653 3fff2a64 3fff93d4 40213aac  
3fff2954:  656e696c 3130307a 33333132 40210039  
3fff2964:  39313631 00000000 00000000 00000000  
3fff2974:  00000000 00000000 00000000 3fff0000  
3fff2984:  2d434354 31373631 00393532 00000000  
3fff2994:  00000000 00000000 00000000 40250000  
3fff29a4:  005e0001 3ffffb00 3fff3be4 fffffffc  
3fff29b4:  000000ac 00023e90 000001ac 40253110  
3fff29c4:  40001f46 0000001a 00000195 40225aec  
3fff29d4:  3fff42e4 3fff2a28 00000001 00000002  
3fff29e4:  00000000 00000494 3fff3be4 40221d5c  
3fff29f4:  3fff0000 00000016 3fff1934 00000000  
3fff2a04:  3fff42f4 3fff42dc 3fff4364 40252702  
3fff2a14:  3fff3a74 3fff2a24 00000004 3fff3a74  
3fff2a24:  3fff190c 000001c3 000001c3 4010020c  
3fff2a34:  3fff166c 00000000 3fff2a94 4010068c  
3fff2a44:  3fff166c 3fff43dc 3fff2a84 40220668  
3fff2a54:  3fff166c 00000000 3fff4374 40218843  
3fff2a64:  00000000 00000000 00000000 40222c80  
3fff2a74:  3fff166c 00000000 3fff4374 40218f1d  
3fff2a84:  00000102 0000000b 0000003a 00000012  
3fff2a94:  0000001d 00000007 00000074 00000001  
3fff2aa4:  000000f1 0000014e 3ffe9768 00000000  
3fff2ab4:  00001388 00000000 00000000 3fff42f4  
3fff2ac4:  3fff44cc 3fff8dfc 3fff2a64 00000000  
3fff2ad4:  3fff1608 3ffe8f00 3fff166c 3fff8bc4  
3fff2ae4:  00001000 6d2e306d 75736165 6e2e7a72  
3fff2af4:  3f007465 3fff7040 3fff2ac8 00000001  
3fff2b04:  0068d7a3 00000013 3fff1934 4021f0a0  
3fff2b14:  3fff10ec 3fff10e4 3fff1934 4021f0c4  
3fff2b24:  00000754 3fff29a4 3fff52cc 3fff7040  
3fff2b34:  3fff4b18 3fff5258 3fff6fb4 00000002  
3fff2b44:  3fff5250 3fff5288 00000000 3fff2964  
3fff2b54:  3fff2954 3fff4808 3734313a 40107aa9  
3fff2b64:  4023ce8e 3fff10f4 40359999 3fffdad0  
3fff2b74:  a0000000 00000001 3fff2bd4 4021fbab  
3fff2b84:  3fff36b4 402166f4 3fff1764 3fff2ba4  
3fff2b94:  3fff0fe5 3fff119d 3fff10f4 402151e0  
3fff2ba4:  3ffe9077 3fff10f8 3fff2bd4 4010068c  
3fff2bb4:  40201312 000003e8 000003e8 4021fb00  
3fff2bc4:  3fff10f4 3fff10f8 3fff13c0 4020c498  
3fff2bd4:  00000000 00000000 00000000 4020df84  
3fff2be4:  3fff10f4 3fff10f8 3fff10e4 40211cfc  
3fff2bf4:  0000000b 0000003a 00000012 0000001d  
3fff2c04:  00000007 00000074 00000001 000000f1  
3fff2c14:  0000014e feefeffe feefeffe feefeffe  
3fff2c24:  0000000b 0000003a 00000012 0000001d  
3fff2c34:  00000007 00000074 00000001 000000f1  
3fff2c44:  0000014e feefeffe feefeffe feefeffe  
3fff2c54:  feefeffe feefeffe feefeffe feefeffe  
3fff2c64:  feefeffe feefeffe feefeffe 3fff1a70  
3fff2c74:  3fffdad0 00000000 3fff1a69 40220788  
3fff2c84:  feefeffe feefeffe 3fff1a80 40100720  
<<<stack<<<

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


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

wdt reset

Decoded:

Decoding 38 results
0x4024df9e: tcp_write at /home/danielm/arduino-esp8266/hardware/esp8266com/esp8266/tools/sdk/lwip/src/core/tcp_out.c:575
0x4024df74: tcp_pbuf_prealloc at /home/danielm/arduino-esp8266/hardware/esp8266com/esp8266/tools/sdk/lwip/src/core/tcp_out.c:257
 (inlined by) tcp_write at /home/danielm/arduino-esp8266/hardware/esp8266com/esp8266/tools/sdk/lwip/src/core/tcp_out.c:535
0x40220668: operator delete(void*) at /home/danielm/arduino-esp8266/hardware/esp8266com/esp8266/cores/esp8266/abi.cpp:57
0x402171b4: ClientContext::_write_some() at /home/danielm/arduino-esp8266/hardware/esp8266com/esp8266/libraries/ESP8266WiFi/src/WiFiServer.cpp:91
0x40217f08: ClientContext::_write_from_source(DataSource*) at /home/danielm/arduino-esp8266/hardware/esp8266com/esp8266/libraries/ESP8266WiFi/src/WiFiClientSecure.cpp:587
 (inlined by) ClientContext::write(unsigned char const*, unsigned int) at /home/danielm/arduino-esp8266/hardware/esp8266com/esp8266/libraries/ESP8266WiFi/src/include/ClientContext.h:291
 (inlined by) __ax_port_write at /home/danielm/arduino-esp8266/hardware/esp8266com/esp8266/libraries/ESP8266WiFi/src/WiFiClientSecure.cpp:616
0x40240a8d: send_raw_packet at /Users/ficeto/Desktop/ESP8266/axtls-8266/ssl/tls1.c:1072
 (inlined by) send_packet at /Users/ficeto/Desktop/ESP8266/axtls-8266/ssl/tls1.c:1209
0x40240b17: ssl_write at /Users/ficeto/Desktop/ESP8266/axtls-8266/ssl/tls1.c:312
0x4020e3cd: ArduinoJson::Internals::JsonPrintable<ArduinoJson::JsonObject>::printTo(char*, unsigned int) const at /home/danielm/Arduino/core/core.ino:857
0x40217988: WiFiClientSecure::write(unsigned char const*, unsigned int) at /home/danielm/arduino-esp8266/hardware/esp8266com/esp8266/libraries/ESP8266WiFi/src/WiFiClientSecure.cpp:587
0x40213aac: measurz_send(bool) at /home/danielm/Arduino/core/measurz.ino:526
0x40210039: onWebSocketEvent(unsigned char, WStype_t, unsigned char*, unsigned int) at /home/danielm/Arduino/core/core.ino:857
0x40250000: espconn_tcp_memp_free at /home/danielm/arduino-esp8266/hardware/esp8266com/esp8266/tools/sdk/lwip/src/app/espconn_tcp.c:235 (discriminator 1)
0x40253110: ip_output_if_opt at /home/danielm/arduino-esp8266/hardware/esp8266com/esp8266/tools/sdk/lwip/src/core/ipv4/ip.c:780
0x40001f46: ?? ??:0
0x40225aec: pvPortMalloc at /home/danielm/arduino-esp8266/hardware/esp8266com/esp8266/cores/esp8266/heap.c:13
0x40221d5c: SPIFFSImpl::end() at /home/danielm/arduino-esp8266/hardware/esp8266com/esp8266/cores/esp8266/spiffs_api.h:169
0x40252702: igmp_send at /home/danielm/arduino-esp8266/hardware/esp8266com/esp8266/tools/sdk/lwip/src/core/ipv4/igmp.c:830
0x4010020c: _umm_free at /home/danielm/arduino-esp8266/hardware/esp8266com/esp8266/cores/esp8266/umm_malloc/umm_malloc.c:1287
0x4010068c: free at /home/danielm/arduino-esp8266/hardware/esp8266com/esp8266/cores/esp8266/umm_malloc/umm_malloc.c:1734
0x40220668: operator delete(void*) at /home/danielm/arduino-esp8266/hardware/esp8266com/esp8266/cores/esp8266/abi.cpp:57
0x40218843: std::_Function_base::_Base_manager<std::_Bind<std::_Mem_fn<void (MDNSResponder::*)()> (MDNSResponder*)> >::_M_manager(std::_Any_data&, std::_Any_data const&, std::_Manager_operation) at /home/danielm/arduino-esp8266/hardware/esp8266com/esp8266/libraries/ESP8266mDNS/ESP8266mDNS.cpp:401
0x40222c80: std::_Function_base::~_Function_base() at /home/danielm/arduino-esp8266/hardware/esp8266com/esp8266/tools/xtensa-lx106-elf/xtensa-lx106-elf/include/c++/4.8.2/functional:2031
0x40218f1d: MDNSResponder::_listen() at /home/danielm/arduino-esp8266/hardware/esp8266com/esp8266/libraries/ESP8266mDNS/ESP8266mDNS.cpp:401
0x4021f0a0: Print::println() at /home/danielm/arduino-esp8266/hardware/esp8266com/esp8266/cores/esp8266/Print.cpp:87
0x4021f0c4: Print::println(__FlashStringHelper const*) at /home/danielm/arduino-esp8266/hardware/esp8266com/esp8266/cores/esp8266/Print.cpp:87
0x40107aa9: __digitalWrite at /home/danielm/arduino-esp8266/hardware/esp8266com/esp8266/cores/esp8266/core_esp8266_wiring_digital.c:84
0x4023ce8e: wifi_get_opmode at ??:?
0x4021fbab: String::reserve(unsigned int) at /home/danielm/arduino-esp8266/hardware/esp8266com/esp8266/cores/esp8266/WString.cpp:519
0x402166f4: ESP8266WiFiSTAClass::status() at /home/danielm/arduino-esp8266/hardware/esp8266com/esp8266/libraries/ESP8266WiFi/src/ESP8266WiFiSTA.cpp:510
0x402151e0: loop at /home/danielm/Arduino/core/core.ino:1052
0x4010068c: free at /home/danielm/arduino-esp8266/hardware/esp8266com/esp8266/cores/esp8266/umm_malloc/umm_malloc.c:1734
0x40201312: delay at /home/danielm/arduino-esp8266/hardware/esp8266com/esp8266/cores/esp8266/core_esp8266_wiring.c:53
0x4021fb00: String::~String() at /home/danielm/arduino-esp8266/hardware/esp8266com/esp8266/cores/esp8266/WString.cpp:519
0x4020c498: PowerSensor::writeCalibrationSettings() at /tmp/build90d29aedfc73faf1bed5fd3965104930.tmp/sketch/PowerSensor.cpp:377
0x4020df84: unmountStorage() at /home/danielm/Arduino/core/core.ino:857
0x40211cfc: setup at /home/danielm/Arduino/core/core.ino:857
0x40220788: loop_wrapper at /home/danielm/arduino-esp8266/hardware/esp8266com/esp8266/cores/esp8266/core_esp8266_main.cpp:56
0x40100720: cont_norm at /home/danielm/arduino-esp8266/hardware/esp8266com/esp8266/cores/esp8266/cont.S:109

[c-mysec]

I have similar behavior but for me it is very rare. Finally it happend in development environment where I could catch the stacktrace.
I am sending only around 200 caracters.
ESP seems to hang for some seconds and then reset.

I don't know if it is really time-out waiting for network a bug in my program (some problem with my buffer).

There has to be a work around to this. I can't loose all execution context if something wrong happend with network a connection.
I am work on a system that notifies me about some event by sending an e-mail, publishing to a webapp, sending an SMS and making a call because I can't miss the event. But if the chip halts when trying to send the e-mail, I will receive nothing.
I can think only of 2 solutions to me:
1- using static ram, so ESP restart and recover previous state.
2- multi-processing with 2 ESP8266 or Arduino+ESP8266, One processor to control and the other to execute time consuming tasks.

But I want to avoid increase hardware complexity. TCP needs to time out before WDT.

Is there a workaround to this?

Soft WDT reset

ctx: cont
sp: 3fff34c0 end: 3fff3880 offset: 01b0

stack>>>
3fff3670: 3fff4bd4 00000000 00000000 4024828c
3fff3680: 3fff63a4 00000000 3fffb8cc 00000000
3fff3690: 3fff4bd4 c0eecc3d 73fd0f47 0000000b
3fff36a0: 3fffa6bc 3fff63a4 00000000 40249664
3fff36b0: 00000000 00000045 00000002 3fff67c4
3fff36c0: 0000003a 00000000 00000000 3fff38d0
3fff36d0: 0000003a 00000045 0000000b 3fff2860
3fff36e0: 40201972 00001388 00001388 00000045
3fff36f0: 00000045 00000000 3fff645c 40217ee0
3fff3700: 00000045 c7ed656f 7de8b510 00000000
3fff3710: 00000000 3fff64fc 00000045 4023a2ec
3fff3720: 00020317 3fff371a 00000000 4010053d
3fff3730: 0000001a 00000017 00000010 401005a6
3fff3740: 00000014 000063a0 00000c74 00000000
3fff3750: 3fff64fc 3fffa70c 0000001a 4023a373
3fff3760: 0000001a 3fff37c0 3fff37c0 4021d104
3fff3770: 0000001a 00000001 3fff37c0 3fff1a18
3fff3780: 3fff66bc 00000001 3fff66bc 40217ac8
3fff3790: 3fff66bc 00000001 3fff66bc 4021f0ad
3fff37a0: 3fff66bc 00000001 3fff37c0 4021c799
3fff37b0: 3fffdad0 00000001 3fff19b4 402154a7
3fff37c0: 3fffa70c 0000001f 0000001a 3fffa664
3fff37d0: 0000001f 00000014 3fff6354 0000000f
3fff37e0: 00000006 00000000 3fff1c88 4021983d
3fff37f0: 3fff4454 40216ddc 000003e8 4020c9b8
3fff3800: 00000000 00000000 3fff19ec 3fff1a18
3fff3810: 3fffdad0 00000000 3fff19ec 40203c0b
3fff3820: 00000000 00000000 00000000 00000000
3fff3830: 00000000 00000000 00000000 00000000
3fff3840: ffffffe2 feefeffe feefeffe feefeffe
3fff3850: 00000000 00000000 00000001 3fff2858
3fff3860: 3fffdad0 00000000 3fff2852 4021dea4
3fff3870: feefeffe feefeffe 3fff2860 40100718
<<<stack<<<

0x4024828c: pbuf_alloc at /Users/igrokhotkov/espressif/arduino/tools/sdk/lwip/src/core/pbuf.c:366
0x40249664: tcp_pbuf_prealloc at /Users/igrokhotkov/espressif/arduino/tools/sdk/lwip/src/core/tcp_out.c:257
(inlined by) tcp_write at /Users/igrokhotkov/espressif/arduino/tools/sdk/lwip/src/core/tcp_out.c:535
0x40201972: delay at D:\iot\ESP8266\sloeber\arduinoPlugin\packages\esp8266\hardware\esp8266\2.3.0\cores\esp8266/core_esp8266_wiring.c:53
0x40217ee0: ClientContext::write(char const*, unsigned int) at D:\iot\ESP8266\sloeber\arduinoPlugin\packages\esp8266\hardware\esp8266\2.3.0\libraries\ESP8266WiFi\src\include/ClientContext.h:232
(inlined by) ax_port_write at D:\iot\ESP8266\sloeber\arduinoPlugin\packages\esp8266\hardware\esp8266\2.3.0\libraries\ESP8266WiFi\src/WiFiClientSecure.cpp:560
0x4023a2ec: send_raw_packet at /Users/igrokhotkov/e/axtls/e1/ssl/tls1.c:986
(inlined by) send_packet at /Users/igrokhotkov/e/axtls/e1/ssl/tls1.c:1121
0x4010053d: _umm_realloc at D:\iot\ESP8266\sloeber\arduinoPlugin\packages\esp8266\hardware\esp8266\2.3.0\cores\esp8266\umm_malloc/umm_malloc.c:1491
(inlined by) realloc at D:\iot\ESP8266\sloeber\arduinoPlugin\packages\esp8266\hardware\esp8266\2.3.0\cores\esp8266\umm_malloc/umm_malloc.c:1709
0x401005a6: _umm_realloc at D:\iot\ESP8266\sloeber\arduinoPlugin\packages\esp8266\hardware\esp8266\2.3.0\cores\esp8266\umm_malloc/umm_malloc.c:1568
(inlined by) realloc at D:\iot\ESP8266\sloeber\arduinoPlugin\packages\esp8266\hardware\esp8266\2.3.0\cores\esp8266\umm_malloc/umm_malloc.c:1709
0x4023a373: ssl_write at /Users/igrokhotkov/e/axtls/e1/ssl/tls1.c:306
0x4021d104: String::changeBuffer(unsigned int) at D:\iot\ESP8266\sloeber\arduinoPlugin\packages\esp8266\hardware\esp8266\2.3.0\cores\esp8266/WString.cpp:712
0x40217ac8: WiFiClientSecure::write(unsigned char const*, unsigned int) at D:\iot\ESP8266\sloeber\arduinoPlugin\packages\esp8266\hardware\esp8266\2.3.0\libraries\ESP8266WiFi\src/WiFiClientSecure.cpp:517
0x4021f0ad: Print::print(String const&) at D:\iot\ESP8266\sloeber\arduinoPlugin\packages\esp8266\hardware\esp8266\2.3.0\cores\esp8266/Print.cpp:100
0x4021c799: Print::println(String const&) at D:\iot\ESP8266\sloeber\arduinoPlugin\packages\esp8266\hardware\esp8266\2.3.0\cores\esp8266/Print.cpp:184
0x402154a7: SmtpSend::loop() at C:\Users\inetsoftware\Documents\Arduino\libraries\InetCommons\src/SmtpSend.cpp:136
0x4021983d: ESP8266WebServer::handleClient() at D:\iot\ESP8266\sloeber\arduinoPlugin\packages\esp8266\hardware\esp8266\2.3.0\libraries\ESP8266WebServer\src\detail/RequestHandlersImpl.h:53
0x40216ddc: ESP8266WiFiSTAClass::status() at D:\iot\ESP8266\sloeber\arduinoPlugin\packages\esp8266\hardware\esp8266\2.3.0\libraries\ESP8266WiFi\src/ESP8266WiFiSTA.cpp:453
0x4020c9b8: Sirene::fire() at D:\iot\ESP8266\sloeber\workspace\wifialarm\Release/../Sirene.cpp:19
0x40203c0b: loop at D:\iot\ESP8266\sloeber\workspace\wifialarm\Release/../wifialarm.ino:293
0x4021dea4: loop_wrapper at D:\iot\ESP8266\sloeber\arduinoPlugin\packages\esp8266\hardware\esp8266\2.3.0\cores\esp8266/core_esp8266_main.cpp:56
0x40100718: cont_norm at D:\iot\ESP8266\sloeber\arduinoPlugin\packages\esp8266\hardware\esp8266\2.3.0\cores\esp8266/cont.S:109
0x4010f000: ?? ??:0

[liquidfalcon]

The unfortunate workaround right now is keeping free heap space above ~33-34K. That seems to be the sweet spot in my programs. As soon as you go under that, these stack traces return. I'm almost certain it's because a malloc/realloc fails somewhere when the heap decreases, and due to the incredibly poor memory discipline in axTLS, it's not caught, and bad stuff happens shortly afterwards such as this fault.

I have had many production devices connecting, and sending to a 2048-bit cert HTTPS server every second running for over a month now without a single reset. However, this was only after spending an inordinate amount of time freeing up heap space for SSL.

[c-mysec]

This is not a solution for me.
My device needs to monitor activity on some GPIOs and I can't free much memory while sending e-mail. SMTP is a very time consuming protocol (many requests and responses). Maybe my only solution is to use one Esp8266 for network/TLS tasks and an arduino or other ESP8266 for the rest of work.

[devyte]

@liquidfalcon has mem requirement improved with latest git? Does it improve or get worse with

• PR Update to SDK 2.1.0 #3215
• PR lwip2: lighter implementation #3362
  ?

[devyte]

BearSSL is merged in #4273 , with alternate BearSSL::WiFi* classes. Although axtls-based classes are still available and even the default, they are planned for deprecation and then retirement, hence won't be fixed. Any issues with BearSSL-based classes should be reported in new issues.
Closing.