Basic Infos
Platform
- Hardware: ESP-12 (NodeMCU v2 style board)
- Core Version: 3.1.2 (framework-arduinoespressif8266 3.30102.0), NONOS SDK 2.2.2-dev(38a443e)
- Development Env: Platformio
- Operating System: Windows
Settings in IDE
- Module: Nodemcu (nodemcuv2)
- Flash Mode: dio
- Flash Size: 4MB (eagle.flash.4m2m.ld)
- lwip Variant: v2 Lower Memory (PlatformIO default)
- Reset Method: nodemcu
- Flash Frequency: 40Mhz
- CPU Frequency: 80Mhz
- Upload Using: OTA
Problem Description
tools/sdk/lwip2/builder/patches/time-wait.patch adds TCP_TW_LIMIT(MEMP_NUM_TCP_PCB_TIME_WAIT) straight after TCP_REG(&tcp_tw_pcbs, pcb) in tcp_process() (FIN_WAIT_1, FIN_WAIT_2 and CLOSING cases). When the TIME_WAIT list grows past the limit (MEMP_NUM_TCP_PCB_TIME_WAIT, 5 by default), the macro calls tcp_kill_timewait(), which tcp_abort()s the pcb with the largest tcp_ticks - pcb->tmr.
That pcb can be the one tcp_process() has just moved to TIME_WAIT. Once the application has closed a connection, TF_RXCLOSED is set and tcp_process() stops refreshing pcb->tmr:
// tcp_in.c (lwIP 2.1.3), start of tcp_process()
if ((pcb->flags & TF_RXCLOSED) == 0) {
/* Update the PCB (in)activity timer unless rx is closed (see tcp_shutdown) */
pcb->tmr = tcp_ticks;
}
So a pcb that sat in FIN_WAIT_2 waiting for the peer's FIN keeps the timestamp from when we closed it, and it is usually the "oldest" entry in the TIME_WAIT list by the time the FIN arrives.
tcp_kill_timewait() frees it, but tcp_process() doesn't return ERR_ABRT, so tcp_input() carries on using the freed pcb. If the segment carried data (for example a browser re-using a keep-alive connection that the server has already closed), tcp_input() goes down the "received data although already closed" branch and calls tcp_abort(pcb) a second time:
// tcp_in.c (lwIP 2.1.3) ~line 494, line 497 after the patch
if (pcb->flags & TF_RXCLOSED) {
/* received data although already closed -> abort (send RST) ... */
pbuf_free(recv_data);
tcp_abort(pcb);
goto aborted;
}
The result is a double free of the tcp_pcb. Before the second free the block has often been handed out again, so the second tcp_abort() corrupts the new owner. That surfaces much later as unrelated exceptions: wild pointers in wDev_ProcessFiq, umm_assimilate_up LoadStoreError, illegal instructions. We had about a dozen of these over four months on a device running ESP8266WebServer + PubSubClient + HTTPClient before tracking this down.
Conditions: a TIME_WAIT list already at the limit (many short HTTP connections closed by the ESP side), plus a peer that sends data + FIN on a connection the ESP has already closed. Two browsers/pollers on an ESP8266WebServer at the same time reproduced it in 38 minutes.
How it was caught
-Wl,--wrap=free -Wl,--wrap=vPortFree, with a wrapper that checks the umm block header's free bit (UMM_FREELIST_MASK) before each free. It keeps a small history of recent frees with a stack scan and abort()s on a double free. Decoded with the matching ELF:
Double free of 0x3fff75a4 (tcp_pcb), first freed 78 us before the second
1st free:
0x4023f780: mem_free at lwip2-src/src/core/mem.c:237
0x4023f80d: memp_free at lwip2-src/src/core/memp.c:447
0x40240374: tcp_free at lwip2-src/src/core/tcp.c:217
0x40240964: tcp_abandon at lwip2-src/src/core/tcp.c:583
0x40240a68: tcp_abort at lwip2-src/src/core/tcp.c:641
0x40240b2d: tcp_kill_timewait at lwip2-src/src/core/tcp.c:1809
0x40242bab: tcp_process at lwip2-src/src/core/tcp_in.c:1020 <- TCP_TW_LIMIT, FIN_WAIT_2 -> TIME_WAIT
(inlined by) tcp_input at lwip2-src/src/core/tcp_in.c:438
2nd free:
0x4023f780: mem_free at lwip2-src/src/core/mem.c:237
0x4023f80d: memp_free at lwip2-src/src/core/memp.c:447
0x40240374: tcp_free at lwip2-src/src/core/tcp.c:217
0x402409ff: tcp_abandon at lwip2-src/src/core/tcp.c:622
0x40240a68: tcp_abort at lwip2-src/src/core/tcp.c:641
0x40242cd7: tcp_input at lwip2-src/src/core/tcp_in.c:497 <- "received data although already closed"
0x40247d59: ip4_input at lwip2-src/src/core/ipv4/ip4.c:1467
0x4023ee21: ethernet_input_LWIP2 at lwip2-src/src/netif/ethernet.c:188
0x4026788b: ethernet_input at glue-esp/lwip-esp.c:373
Without the tracer, the same bug crashed later inside the allocator, e.g. umm_assimilate_up <- umm_free_core <- umm_free <- mem_free <- memp_free <- ... tcp_free, with EXCVADDR computed from a free-list index that already had UMM_FREELIST_MASK set.
Suggested fix
Apply the limit before the pcb joins the TIME_WAIT list, so tcp_kill_timewait() can never choose it:
TCP_RMV_ACTIVE(pcb);
pcb->state = TIME_WAIT;
- TCP_REG(&tcp_tw_pcbs, pcb);
- TCP_TW_LIMIT(MEMP_NUM_TCP_PCB_TIME_WAIT);
+ TCP_TW_LIMIT(MEMP_NUM_TCP_PCB_TIME_WAIT - 1);
+ TCP_REG(&tcp_tw_pcbs, pcb);
(in all three places). An alternative is a tcp_kill_timewait() variant that skips a given pcb.
Workaround for sketches
Remove all TIME_WAIT pcbs from loop(), so the list never grows past the limit and the patch never has to choose (this is d-a-v's tcpCleanup() from #4213):
#include <lwip/tcp.h>
#include <lwip/priv/tcp_priv.h>
void loop() {
server.handleClient();
while (tcp_tw_pcbs) tcp_abort(tcp_tw_pcbs); // TIME_WAIT pcbs: just unlinked + freed
...
}
With this in place (and the tracer still active), the same two-client test ran for 90 minutes with no double free and no crash: 3,204 HTTP requests, and the workaround removed 2,448 TIME_WAIT pcbs (250-300 every 10 minutes). Without it, the same test hit the double free after 38 minutes. It only narrows the window: 6+ connections entering TIME_WAIT inside a single loop() pass could still hit the bug.
MCVE Sketch
Not yet reduced to a minimal sketch. It was reproduced on a full application (ESP8266WebServer with ~40 JSON routes, PubSubClient, SoftwareSerial). The trigger is two HTTP clients at once: one polling 4 URLs in parallel every 10 s over keep-alive connections, and one loading a page plus 10 API calls (6 in parallel) every 30 s. From the analysis above, a minimal repro should be:
ESP8266WebServer answering GET / (it closes after each response).
- A client making 6+ short connections to fill TIME_WAIT.
- Another client that keeps a connection open after the server's FIN, then sends a request plus FIN on it.
Debug Messages
Not captured on serial; the decode above is from a crash record written by custom_crash_callback.
Basic Infos
tools/sdk/lwip2/builderon master points at esp82xx-nonos-linklayer 4087efd, whosepatches/time-wait.patchis byte-identical to the one in 3.1.2.)Platform
Settings in IDE
Problem Description
tools/sdk/lwip2/builder/patches/time-wait.patchaddsTCP_TW_LIMIT(MEMP_NUM_TCP_PCB_TIME_WAIT)straight afterTCP_REG(&tcp_tw_pcbs, pcb)intcp_process()(FIN_WAIT_1, FIN_WAIT_2 and CLOSING cases). When the TIME_WAIT list grows past the limit (MEMP_NUM_TCP_PCB_TIME_WAIT, 5 by default), the macro callstcp_kill_timewait(), whichtcp_abort()s the pcb with the largesttcp_ticks - pcb->tmr.That pcb can be the one
tcp_process()has just moved to TIME_WAIT. Once the application has closed a connection,TF_RXCLOSEDis set andtcp_process()stops refreshingpcb->tmr:So a pcb that sat in FIN_WAIT_2 waiting for the peer's FIN keeps the timestamp from when we closed it, and it is usually the "oldest" entry in the TIME_WAIT list by the time the FIN arrives.
tcp_kill_timewait()frees it, buttcp_process()doesn't returnERR_ABRT, sotcp_input()carries on using the freed pcb. If the segment carried data (for example a browser re-using a keep-alive connection that the server has already closed),tcp_input()goes down the "received data although already closed" branch and callstcp_abort(pcb)a second time:The result is a double free of the tcp_pcb. Before the second free the block has often been handed out again, so the second
tcp_abort()corrupts the new owner. That surfaces much later as unrelated exceptions: wild pointers inwDev_ProcessFiq,umm_assimilate_upLoadStoreError, illegal instructions. We had about a dozen of these over four months on a device runningESP8266WebServer+PubSubClient+HTTPClientbefore tracking this down.Conditions: a TIME_WAIT list already at the limit (many short HTTP connections closed by the ESP side), plus a peer that sends data + FIN on a connection the ESP has already closed. Two browsers/pollers on an
ESP8266WebServerat the same time reproduced it in 38 minutes.How it was caught
-Wl,--wrap=free -Wl,--wrap=vPortFree, with a wrapper that checks the umm block header's free bit (UMM_FREELIST_MASK) before each free. It keeps a small history of recent frees with a stack scan andabort()s on a double free. Decoded with the matching ELF:Without the tracer, the same bug crashed later inside the allocator, e.g.
umm_assimilate_up <- umm_free_core <- umm_free <- mem_free <- memp_free <- ... tcp_free, with EXCVADDR computed from a free-list index that already hadUMM_FREELIST_MASKset.Suggested fix
Apply the limit before the pcb joins the TIME_WAIT list, so
tcp_kill_timewait()can never choose it:TCP_RMV_ACTIVE(pcb); pcb->state = TIME_WAIT; - TCP_REG(&tcp_tw_pcbs, pcb); - TCP_TW_LIMIT(MEMP_NUM_TCP_PCB_TIME_WAIT); + TCP_TW_LIMIT(MEMP_NUM_TCP_PCB_TIME_WAIT - 1); + TCP_REG(&tcp_tw_pcbs, pcb);(in all three places). An alternative is a
tcp_kill_timewait()variant that skips a given pcb.Workaround for sketches
Remove all TIME_WAIT pcbs from
loop(), so the list never grows past the limit and the patch never has to choose (this is d-a-v'stcpCleanup()from #4213):With this in place (and the tracer still active), the same two-client test ran for 90 minutes with no double free and no crash: 3,204 HTTP requests, and the workaround removed 2,448 TIME_WAIT pcbs (250-300 every 10 minutes). Without it, the same test hit the double free after 38 minutes. It only narrows the window: 6+ connections entering TIME_WAIT inside a single
loop()pass could still hit the bug.MCVE Sketch
Not yet reduced to a minimal sketch. It was reproduced on a full application (
ESP8266WebServerwith ~40 JSON routes, PubSubClient, SoftwareSerial). The trigger is two HTTP clients at once: one polling 4 URLs in parallel every 10 s over keep-alive connections, and one loading a page plus 10 API calls (6 in parallel) every 30 s. From the analysis above, a minimal repro should be:ESP8266WebServeransweringGET /(it closes after each response).Debug Messages
Not captured on serial; the decode above is from a crash record written by
custom_crash_callback.