Rapid calls to tcp_output cause Guru Meditation failure at random

[philbowles]

Hardware:

Version 1.0.6
IDE name Arduino IDE 1.8.15
PSRAM enabled no
Computer OS Windows 10

Description:

Further to my previous issue #5520 (closed by me) I have narrowed down the bug. It seems to be a timing error when managing the LwIP send Q. I believe the problem in the previous sketch that it was failing to check the error return from tcp_write which returns the (very unhelpful) ERR_MEM when the internal Q is exceeded even though there is tons of free memory and the total data sent are well within the TCP_WND value. Why LwIP has no ERR_Q is beyond me, however...That code runs 100% as expected on ESP8266 (with changed libs and wdt of course).

I therefore assumed that LwIP had internal code for handling "out of Q" conditions and doing a non-blocking wait until the Q had space. On ESP32 this is either a) not the case or b) broken. On discovering this, I rewrote the MVCE to the one shown here, to highlight the obvious problem with ESP32 + LwIP send Q.

It sometimes works, sometimes doesn't: there is no obvious pattern to when it fails. When it does fail it reboots and will often then work. When it works, I manually RST the device for the next test

Sketch:

#include<WiFi.h>
#include "esp_task_wdt.h"

extern "C" {
    #include "lwip/tcp.h"
};

#define BURST_SIZE 10
#define MSG_SIZE 500

struct tcp_pcb* pcb;
bool cnx=false;

uint8_t msg[MSG_SIZE];

err_t _tcp_connected(void* arg, void* tpcb, err_t err){
  Serial.printf("Connected to echoserver\n");
  cnx=true;
  tcp_nagle_enable(pcb);
}

void sendData(const uint8_t* data,size_t len){
    auto Tstart=millis(); 
    size_t  bytesSent=0;
    size_t  bytesRemaining=len;
    while(bytesRemaining){
        size_t available=tcp_sndbuf(pcb);
        if(available && (tcp_sndqueuelen(pcb) < TCP_SND_QUEUELEN )){ // if there is any space at all (and space in Q!), use it
            auto chunk=std::min(bytesRemaining,available); // send as much as will fit
            auto err=tcp_write(pcb,data+bytesSent,chunk,TCP_WRITE_FLAG_COPY);
            // error handling deliberately omitted
            Serial.printf("(e=%d) AVAILABLE=%d SENT=%d REMAINING=%d QL=%d\n",err,available,bytesSent,bytesRemaining,tcp_sndqueuelen(pcb));
            err=tcp_output(pcb);
            if(err) Serial.printf("ERROR! tcp_output returns %d\n",err);
            else {
              bytesSent+=chunk;
              bytesRemaining-=chunk;
            }
        } 
        else { // spin while LwIP clears buffers
          esp_task_wdt_reset();  
          yield(); // allow LwIP to clear buffers  
        }
    }
    Serial.printf("%u bytes sent in %u mS\n",bytesSent,millis()-Tstart);
}

void setup(){
  Serial.begin(115200);
  WiFi.mode(WIFI_STA);
  WiFi.begin("XXXXXXXX", "XXXXXXXX");
  while (WiFi.status() != WL_CONNECTED) {
    Serial.print(".");
    delay(1000);
  }
  Serial.printf("\nIP: %s\n",WiFi.localIP().toString().c_str());
  pcb=tcp_new();
  Serial.printf("MSS=%d SND_BUF=%d WND=%d SND_QUEUELEN=%d\n",TCP_MSS,TCP_SND_BUF,TCP_WND,TCP_SND_QUEUELEN);

  IPAddress ip(192,168,1,20); // 192.168.1.20:8080 is an "echo server"
  ip_addr_t ipt;
  ip_addr_set_ip4_u32(&ipt, ip);
  err_t err = tcp_connect(pcb, &ipt, 8080,(tcp_connected_fn)&_tcp_connected);
}

void loop(){
  static int N=0;
  if(cnx && !(N++)) for(int i=0;i<BURST_SIZE;i++) sendData(msg,MSG_SIZE); // 1x only has to be on main loop
}

NOTES

1. I am aware that the TCP_WRITE_FLAG_COPY is redundant since the data sent are static.

Debug Messages: ESP32 Dev Module

//
// Test 1: Works perfectly
//
17:58:22.416 -> ets Jun  8 2016 00:22:57
17:58:22.416 -> 
17:58:22.416 -> rst:0x1 (POWERON_RESET),boot:0x13 (SPI_FAST_FLASH_BOOT)
17:58:22.463 -> configsip: 0, SPIWP:0xee
17:58:22.463 -> clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00
17:58:22.463 -> mode:DIO, clock div:1
17:58:22.463 -> load:0x3fff0018,len:4
17:58:22.463 -> load:0x3fff001c,len:1216
17:58:22.463 -> ho 0 tail 12 room 4
17:58:22.463 -> load:0x40078000,len:10944
17:58:22.463 -> load:0x40080400,len:6388
17:58:22.463 -> entry 0x400806b4
17:58:22.792 -> ...
17:58:25.797 -> IP: 192.168.1.200
17:58:25.797 -> MSS=1436 SND_BUF=5744 WND=5744 SND_QUEUELEN=16
17:58:25.797 -> Connected to echoserver
17:58:25.797 -> (e=0) AVAILABLE=5744 SENT=0 REMAINING=500 QL=1
17:58:25.844 -> 500 bytes sent in 1 mS
17:58:25.844 -> (e=0) AVAILABLE=5244 SENT=0 REMAINING=500 QL=2
17:58:25.844 -> 500 bytes sent in 0 mS
17:58:25.844 -> (e=0) AVAILABLE=4744 SENT=0 REMAINING=500 QL=2
17:58:25.844 -> 500 bytes sent in 4 mS
17:58:25.844 -> (e=0) AVAILABLE=4744 SENT=0 REMAINING=500 QL=2
17:58:25.844 -> 500 bytes sent in 5 mS
17:58:25.844 -> (e=0) AVAILABLE=5244 SENT=0 REMAINING=500 QL=2
17:58:25.844 -> 500 bytes sent in 4 mS
17:58:25.844 -> (e=0) AVAILABLE=4744 SENT=0 REMAINING=500 QL=3
17:58:25.844 -> 500 bytes sent in 4 mS
17:58:25.844 -> (e=0) AVAILABLE=4244 SENT=0 REMAINING=500 QL=3
17:58:25.844 -> 500 bytes sent in 4 mS
17:58:25.844 -> (e=0) AVAILABLE=3744 SENT=0 REMAINING=500 QL=4
17:58:25.844 -> 500 bytes sent in 4 mS
17:58:25.892 -> (e=0) AVAILABLE=3244 SENT=0 REMAINING=500 QL=4
17:58:25.892 -> 500 bytes sent in 4 mS
17:58:25.892 -> (e=0) AVAILABLE=2744 SENT=0 REMAINING=500 QL=4
17:58:25.892 -> 500 bytes sent in 4 mS
//
// (MANUAL RST)
// Test 2: Fails after 2x sends
//
17:58:28.231 -> ets Jun  8 2016 00:22:57
17:58:28.231 -> 
17:58:28.231 -> rst:0x1 (POWERON_RESET),boot:0x13 (SPI_FAST_FLASH_BOOT)
17:58:28.231 -> configsip: 0, SPIWP:0xee
17:58:28.231 -> clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00
17:58:28.231 -> mode:DIO, clock div:1
17:58:28.231 -> load:0x3fff0018,len:4
17:58:28.231 -> load:0x3fff001c,len:1216
17:58:28.231 -> ho 0 tail 12 room 4
17:58:28.231 -> load:0x40078000,len:10944
17:58:28.231 -> load:0x40080400,len:6388
17:58:28.231 -> entry 0x400806b4
17:58:28.609 -> ...
17:58:31.570 -> IP: 192.168.1.200
17:58:31.570 -> MSS=1436 SND_BUF=5744 WND=5744 SND_QUEUELEN=16
17:58:31.618 -> Connected to echoserver
17:58:31.618 -> (e=0) AVAILABLE=5744 SENT=0 REMAINING=500 QL=1
17:58:31.618 -> 500 bytes sent in 0 mS
17:58:31.618 -> (e=0) AVAILABLE=5244 SENT=0 REMAINING=500 QL=2
17:58:31.618 -> 500 bytes sent in 1 mS
17:58:31.618 -> (e=0) AVAILABLE=4744 SENT=0 REMAINING=500 QL=2
17:58:31.618 -> 50Guru Meditation Error: Core  0 panic'ed (LoadProhibited). Exception was unhandled.
17:58:31.618 -> Core 0 register dump:
17:58:31.618 -> PC      : 0x40116905  PS      : 0x00060a30  A0      : 0x80113fdc  A1      : 0x3ffb3e00  
17:58:31.618 -> A2      : 0x3ffcb454  A3      : 0x3ffbbd60  A4      : 0x38a7d853  A5      : 0x00000000  
17:58:31.665 -> A6      : 0x3ffcb160  A7      : 0x0000a738  A8      : 0x80116902  A9      : 0x3ffb3de0  
17:58:31.665 -> A10     : 0x38a7d853  A11     : 0x3ffcb454  A12     : 0x3ffcb160  A13     : 0x00000000  
17:58:31.665 -> A14     : 0x3ffcc190  A15     : 0x00000000  SAR     : 0x00000010  EXCCAUSE: 0x0000001c  
17:58:31.665 -> EXCVADDR: 0x00000010  LBEG    : 0x4000c2e0  LEND    : 0x4000c2f6  LCOUNT  : 0xffffffff  
17:58:31.665 -> 
17:58:31.665 -> ELF file SHA256: 0000000000000000
17:58:31.665 -> 
17:58:31.665 -> Backtrace: 0x40116905:0x3ffb3e00 0x40113fd9:0x3ffb3e30 0x40119993:0x3ffb3e50 0x4011e0da:0x3ffb3e80 0x4011f867:0x3ffb3ea0 0x40089792:0x3ffb3ed0
17:58:31.712 -> 
17:58:31.712 -> Rebooting...
//
// Test 3: Fails after 2x sends
//
17:58:31.712 -> ets Jun  8 2016 00:22:57
17:58:31.712 -> 
17:58:31.712 -> rst:0xc (SW_CPU_RESET),boot:0x13 (SPI_FAST_FLASH_BOOT)
17:58:31.712 -> configsip: 0, SPIWP:0xee
17:58:31.712 -> clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00
17:58:31.712 -> mode:DIO, clock div:1
17:58:31.712 -> load:0x3fff0018,len:4
17:58:31.712 -> load:0x3fff001c,len:1216
17:58:31.712 -> ho 0 tail 12 room 4
17:58:31.712 -> load:0x40078000,len:10944
17:58:31.712 -> load:0x40080400,len:6388
17:58:31.712 -> entry 0x400806b4
17:58:32.088 -> ...
17:58:35.095 -> IP: 192.168.1.200
17:58:35.095 -> MSS=1436 SND_BUF=5744 WND=5744 SND_QUEUELEN=16
17:58:35.140 -> Connected to echoserver
17:58:35.140 -> (e=0) AVAILABLE=5744 SENT=0 REMAINING=500 QL=1
17:58:35.140 -> 500 bytes sent in 0 mS
17:58:35.140 -> (e=0) AVAILABLE=5244 SENT=0 REMAINING=500 QL=2
17:58:35.140 -> 500 bytes sent in 1 mS
17:58:35.140 -> (e=0) AVAILABLE=4744 SENT=0 REMAINING=500 QL=2
17:58:35.140 -> Guru Meditation Error: Core  1 panic'ed (LoadProhibited). Exception was unhandled.
17:58:35.188 -> Core 1 register dump:
17:58:35.188 -> PC      : 0x40116905  PS      : 0x00060e30  A0      : 0x800d0515  A1      : 0x3ffb1f20  
17:58:35.188 -> A2      : 0x3ffcb438  A3      : 0x3ffbd86c  A4      : 0x3cfb49b5  A5      : 0x00000000  
17:58:35.188 -> A6      : 0x3ffcb160  A7      : 0x0000fb3c  A8      : 0x80116902  A9      : 0x3ffb1f00  
17:58:35.188 -> A10     : 0x3cfb49b5  A11     : 0x3ffcb438  A12     : 0x3ffcb160  A13     : 0x00000000  
17:58:35.188 -> A14     : 0x3ffcc174  A15     : 0x00000008  SAR     : 0x00000010  EXCCAUSE: 0x0000001c  
17:58:35.188 -> EXCVADDR: 0x00000010  LBEG    : 0x4000c349  LEND    : 0x4000c36b  LCOUNT  : 0x00000000  
17:58:35.234 -> 
17:58:35.234 -> ELF file SHA256: 0000000000000000
17:58:35.234 -> 
17:58:35.234 -> Backtrace: 0x40116905:0x3ffb1f20 0x400d0512:0x3ffb1f50 0x400d0690:0x3ffb1f90 0x400d19f9:0x3ffb1fb0 0x40089792:0x3ffb1fd0
17:58:35.234 -> 
17:58:35.234 -> Rebooting...
//
// Test 4: Works perfectly
//
17:58:35.234 -> ets Jun  8 2016 00:22:57
17:58:35.234 -> 
17:58:35.234 -> rst:0xc (SW_CPU_RESET),boot:0x13 (SPI_FAST_FLASH_BOOT)
17:58:35.234 -> configsip: 0, SPIWP:0xee
17:58:35.234 -> clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00
17:58:35.234 -> mode:DIO, clock div:1
17:58:35.234 -> load:0x3fff0018,len:4
17:58:35.234 -> load:0x3fff001c,len:1216
17:58:35.234 -> ho 0 tail 12 room 4
17:58:35.234 -> load:0x40078000,len:10944
17:58:35.281 -> load:0x40080400,len:6388
17:58:35.281 -> entry 0x400806b4
17:58:35.613 -> ...
17:58:38.612 -> IP: 192.168.1.200
17:58:38.612 -> MSS=1436 SND_BUF=5744 WND=5744 SND_QUEUELEN=16
17:58:38.612 -> Connected to echoserver
17:58:38.612 -> (e=0) AVAILABLE=5744 SENT=0 REMAINING=500 QL=1
17:58:38.612 -> 500 bytes sent in 1 mS
17:58:38.612 -> (e=0) AVAILABLE=5244 SENT=0 REMAINING=500 QL=2
17:58:38.612 -> 500 bytes sent in 0 mS
17:58:38.612 -> (e=0) AVAILABLE=4744 SENT=0 REMAINING=500 QL=2
17:58:38.659 -> 500 bytes sent in 5 mS
17:58:38.659 -> (e=0) AVAILABLE=4744 SENT=0 REMAINING=500 QL=2
17:58:38.659 -> 500 bytes sent in 4 mS
17:58:38.659 -> (e=0) AVAILABLE=5244 SENT=0 REMAINING=500 QL=2
17:58:38.659 -> 500 bytes sent in 4 mS
17:58:38.659 -> (e=0) AVAILABLE=4744 SENT=0 REMAINING=500 QL=3
17:58:38.659 -> 500 bytes sent in 4 mS
17:58:38.659 -> (e=0) AVAILABLE=4244 SENT=0 REMAINING=500 QL=3
17:58:38.659 -> 500 bytes sent in 4 mS
17:58:38.659 -> (e=0) AVAILABLE=3744 SENT=0 REMAINING=500 QL=4
17:58:38.659 -> 500 bytes sent in 4 mS
17:58:38.659 -> (e=0) AVAILABLE=3244 SENT=0 REMAINING=500 QL=4
17:58:38.659 -> 500 bytes sent in 4 mS
17:58:38.659 -> (e=0) AVAILABLE=2744 SENT=0 REMAINING=500 QL=4
17:58:38.659 -> 500 bytes sent in 4 mS
//
// (MANUAL RST)
// Test 5: Fails after 9x sends
//
17:58:48.748 -> ets Jun  8 2016 00:22:57
17:58:48.748 -> 
17:58:48.748 -> rst:0x1 (POWERON_RESET),boot:0x13 (SPI_FAST_FLASH_BOOT)
17:58:48.748 -> configsip: 0, SPIWP:0xee
17:58:48.748 -> clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00
17:58:48.748 -> mode:DIO, clock div:1
17:58:48.748 -> load:0x3fff0018,len:4
17:58:48.748 -> load:0x3fff001c,len:1216
17:58:48.748 -> ho 0 tail 12 room 4
17:58:48.748 -> load:0x40078000,len:10944
17:58:48.748 -> load:0x40080400,len:6388
17:58:48.748 -> entry 0x400806b4
17:58:49.077 -> ...
17:58:52.081 -> IP: 192.168.1.200
17:58:52.081 -> MSS=1436 SND_BUF=5744 WND=5744 SND_QUEUELEN=16
17:58:52.128 -> Connected to echoserver
17:58:52.128 -> (e=0) AVAILABLE=5744 SENT=0 REMAINING=500 QL=1
17:58:52.128 -> 500 bytes sent in 1 mS
17:58:52.128 -> (e=0) AVAILABLE=5244 SENT=0 REMAINING=500 QL=2
17:58:52.128 -> 500 bytes sent in 1 mS
17:58:52.128 -> (e=0) AVAILABLE=4744 SENT=0 REMAINING=500 QL=2
17:58:52.128 -> 500 bytes sent in 4 mS
17:58:52.128 -> (e=0) AVAILABLE=4244 SENT=0 REMAINING=500 QL=3
17:58:52.128 -> 500 bytes sent in 4 mS
17:58:52.128 -> (e=0) AVAILABLE=3744 SENT=0 REMAINING=500 QL=3
17:58:52.128 -> 500 bytes sent in 4 mS
17:58:52.128 -> (e=0) AVAILABLE=3244 SENT=0 REMAINING=500 QL=3
17:58:52.128 -> 500 bytes sent in 4 mS
17:58:52.175 -> (e=0) AVAILABLE=4680 SENT=0 REMAINING=500 QL=2
17:58:52.175 -> 500 bytes sent in 4 mS
17:58:52.175 -> (e=0) AVAILABLE=5244 SENT=0 REMAINING=500 QL=2
17:58:52.175 -> 500 bytes sent in 4 mS
17:58:52.175 -> (e=0) AVAILABLE=5244 SENT=0 REMAINING=500 QL=2
17:58:52.175 -> 500 bytes sent in 4 mS
17:58:52.175 -> (e=0) AVAILABLE=5244 SENT=0 REMAINING=500 QL=2
17:58:52.175 -> 500 Guru Meditation Error: Core  0 panic'ed (LoadProhibited). Exception was unhandled.
17:58:52.175 -> Core 0 register dump:
17:58:52.175 -> PC      : 0x40116905  PS      : 0x00060c30  A0      : 0x80113fdc  A1      : 0x3ffb3e00  
17:58:52.175 -> A2      : 0x3ffcb540  A3      : 0x3ffbbdc0  A4      : 0xbfad78b2  A5      : 0x00000000  
17:58:52.222 -> A6      : 0x3ffcb1f8  A7      : 0x0000adbf  A8      : 0x80116902  A9      : 0x3ffb3de0  
17:58:52.222 -> A10     : 0xbfad78b2  A11     : 0x3ffcb540  A12     : 0x3ffcb1f8  A13     : 0x00000000  
17:58:52.222 -> A14     : 0x3ffcbd74  A15     : 0x00000000  SAR     : 0x00000010  EXCCAUSE: 0x0000001c  
17:58:52.222 -> EXCVADDR: 0x00000010  LBEG    : 0x4000c2e0  LEND    : 0x4000c2f6  LCOUNT  : 0xffffffff  
17:58:52.222 -> 
17:58:52.222 -> ELF file SHA256: 0000000000000000
17:58:52.222 -> 
17:58:52.222 -> Backtrace: 0x40116905:0x3ffb3e00 0x40113fd9:0x3ffb3e30 0x40119993:0x3ffb3e50 0x4011e0da:0x3ffb3e80 0x4011f867:0x3ffb3ea0 0x40089792:0x3ffb3ed0
17:58:52.269 -> 
17:58:52.269 -> Rebooting...
//
// Test 6: Works perfectly
//
17:58:52.269 -> ets Jun  8 2016 00:22:57
17:58:52.269 -> 
17:58:52.269 -> rst:0xc (SW_CPU_RESET),boot:0x13 (SPI_FAST_FLASH_BOOT)
17:58:52.269 -> configsip: 0, SPIWP:0xee
17:58:52.269 -> clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00
17:58:52.269 -> mode:DIO, clock div:1
17:58:52.269 -> load:0x3fff0018,len:4
17:58:52.269 -> load:0x3fff001c,len:1216
17:58:52.269 -> ho 0 tail 12 room 4
17:58:52.269 -> load:0x40078000,len:10944
17:58:52.269 -> load:0x40080400,len:6388
17:58:52.269 -> entry 0x400806b4
17:58:52.643 -> ...
17:58:55.651 -> IP: 192.168.1.200
17:58:55.651 -> MSS=1436 SND_BUF=5744 WND=5744 SND_QUEUELEN=16
17:58:55.651 -> Connected to echoserver
17:58:55.651 -> (e=0) AVAILABLE=5744 SENT=0 REMAINING=500 QL=1
17:58:55.651 -> 500 bytes sent in 0 mS
17:58:55.651 -> (e=0) AVAILABLE=5244 SENT=0 REMAINING=500 QL=2
17:58:55.698 -> 500 bytes sent in 1 mS
17:58:55.698 -> (e=0) AVAILABLE=4744 SENT=0 REMAINING=500 QL=2
17:58:55.698 -> 500 bytes sent in 4 mS
17:58:55.698 -> (e=0) AVAILABLE=4744 SENT=0 REMAINING=500 QL=2
17:58:55.698 -> 500 bytes sent in 4 mS
17:58:55.698 -> (e=0) AVAILABLE=4244 SENT=0 REMAINING=500 QL=2
17:58:55.698 -> 500 bytes sent in 4 mS
17:58:55.698 -> (e=0) AVAILABLE=4744 SENT=0 REMAINING=500 QL=2
17:58:55.698 -> 500 bytes sent in 4 mS
17:58:55.698 -> (e=0) AVAILABLE=5244 SENT=0 REMAINING=500 QL=2
17:58:55.698 -> 500 bytes sent in 4 mS
17:58:55.698 -> (e=0) AVAILABLE=5244 SENT=0 REMAINING=500 QL=2
17:58:55.698 -> 500 bytes sent in 4 mS
17:58:55.698 -> (e=0) AVAILABLE=5244 SENT=0 REMAINING=500 QL=2
17:58:55.698 -> 500 bytes sent in 4 mS
17:58:55.745 -> (e=0) AVAILABLE=4744 SENT=0 REMAINING=500 QL=2
17:58:55.745 -> 500 bytes sent in 4 mS

Decoded Stack Trace

PC: 0x40116905: tcp_output at /home/runner/work/esp32-arduino-lib-builder/esp32-arduino-lib-builder/esp-idf/components/lwip/lwip/src/core/tcp_out.c line 1153
EXCVADDR: 0x00000010

Decoding stack results
0x40116905: tcp_output at /home/runner/work/esp32-arduino-lib-builder/esp32-arduino-lib-builder/esp-idf/components/lwip/lwip/src/core/tcp_out.c line 1153
0x40113fd9: tcp_input at /home/runner/work/esp32-arduino-lib-builder/esp32-arduino-lib-builder/esp-idf/components/lwip/lwip/src/core/tcp_in.c line 487
0x40119993: ip4_input at /home/runner/work/esp32-arduino-lib-builder/esp32-arduino-lib-builder/esp-idf/components/lwip/lwip/src/core/ipv4/ip4.c line 750
0x4011e0da: ethernet_input at /home/runner/work/esp32-arduino-lib-builder/esp32-arduino-lib-builder/esp-idf/components/lwip/lwip/src/netif/ethernet.c line 184
0x4011f867: tcpip_thread at /home/runner/work/esp32-arduino-lib-builder/esp32-arduino-lib-builder/esp-idf/components/lwip/lwip/src/api/tcpip.c line 135
0x40089792: vPortTaskWrapper at /home/runner/work/esp32-arduino-lib-builder/esp32-arduino-lib-builder/esp-idf/components/freertos/port.c line 143

Additional information

1. The remote target 192.168.1.20:8080 is a python "echo server" running within VSCode (see below) which simply replies with whatever has been sent.

Echo server code (run from within VSCode)

import asyncore
import socket

ANSWER = 'HTTP/1.0 200 OK\r\n' + \
    'Content-Type: text/html; charset=utf-8\r\n' + \
    'Content-Length: 0\r\n' + \
    'Connection: close\r\n\r\n'

class EchoHandler(asyncore.dispatcher_with_send):

    def handle_read(self):
        data = self.recv(16384)
        print("RX ",len(data))
        print(data)

        if(data):
            self.send(data)

class EchoServer(asyncore.dispatcher):

    def __init__(self, host, port):
        asyncore.dispatcher.__init__(self)
        self.create_socket(socket.AF_INET, socket.SOCK_STREAM)
        self.set_reuse_addr()
        self.bind((host, port))
        self.listen(5)

    def handle_accept(self):
        pair = self.accept()
        if pair is not None:
            sock, addr = pair
            print ('Incoming connection from %s' % repr(addr))
            handler = EchoHandler(sock)

server = EchoServer('0.0.0.0', 8080)
asyncore.loop()

[philbowles]

Further research shows this is very similar to:
https://github.com/ambrop72/badvpn/issues/85
and
https://lists.gnu.org/archive/html/lwip-users/2015-01/msg00000.html

While these are not ESP32, they are both caused by the same problem, and it seems the ESP32 implementation may be breaking the same rules... The above issues are due to an incorrect thread / context switch leading to two separate threads concurrently accessing LwIP which - from what I understand - is not thread-safe and must run all code from one context.

In the second of those links, one reply explains:

Summary:

• Do NOT call anything in interrupt context, nothing, never, never,
  use your OS semaphore signaling to an Ethernet/serial/… RX thread
• memp_* functions are thread-safe if SYS_LIGHTWEIGHT_PROT is
  set, and again, thread safe does not mean it is interrupt safe, especially
  if your hardware does nested interrupts
• Do NOT call any function from the RAW API outside lwIP thread

It seems like the ESP32 is stepping outside those boundaries, since (obviouslly) all of the sketch code is called on the main thread and I believe that "under the hood" LwIP on the ESP32 runs in its own task...so my money is on a badly-timed switch between the two. Given that the same code runs perfectly on ESP8266 where threads / contexts are not an issue, this tends to support that theory. I readily admit I'm "in over my head" at that point, so I fully accept it may be something else.

I have also introduced a delay(N) into the burst to put a time-gap between each successive call to try to find the "break point". Early indications are that if the timing is such that the Q rarely (if ever) exceeds 1 then the crash disappears. Once the Q goes above 1, the potential for the "random" crash reappears., irrespective of actual timing values. So while it is a "timing issue" it is only so because the timing affects the Q growth and the real problem is faulty Q handling.

FWIW, my conclusion is that there is a missing / incorrect / unsynchronised access to the tcp send queue by the "ack" process, i.e. that items are being both added to the Q from the main loop code of the sketch and simultaneously removed - without proper locking / synchronisation - by the ack process.

[igrr]

@philbowles It looks like you are calling LwIP "Raw" API functions in your sketch, outside of LwIP thread. Could that be the reason? In ESP-IDF, LwIP "Raw" APIs shouldn't be called outside the LwIP thread, so are effectively off limits to the applications. There is a note about that in the docs, but I suppose it's not made clear enough.

It is recommended to use BSD socket APIs instead.

[philbowles]

@igrr Thanks for the reply. When I have put code inside lwip raw callbacks the tiny 6388 stack breaks almost any time I try to do anything "sensible" is there any easy way to increase that?

Are you saying that tcp_* calls simply cannot ever be used from main loop code on the ESP32?, ie that my whole strategy is doomed to failure?

Is the result of all this that it's impossible to write source code using LwIP raw API calls that is portable between ESP32 and ESP8266 ?

[philbowles]

I hear you. It's quite clear - although it's what I'd call "pretty well buried" :) Thanks again for you help.

If your answers to my two previous questions are "Yes", "Yes" then obviously I will close the issue.

[igrr]

Are you saying that tcp_* calls simply cannot ever be used from main loop code on the ESP32?, ie that my whole strategy is doomed to failure?
Is the result of all this that it's impossible to write source code using LwIP raw API calls that is portable between ESP32 and ESP8266 ?

The answer is "Yes", "Yes", unfortunately.

ESP-IDF itself does use raw API in one place currently, but the concurrency issue is mitigated by doing every raw API function call inside lwIP task via some LwIP internal APIs. I definitely would not recommend doing this in your code — it tooks us a long time to weed out all the issues from this IPC approach, and we are considering replacing that code with a BSD socket based implementation which may be fractionally slower but a lot less fragile. However if your goal is to run the same code on the ESP8266 (non-OS SDK, arduino-esp8266) and ESP32 (ESP-IDF, arduino-esp32) then this approach also won't be of much use as tcpip_api_call isn't present in the ESP8266 (non-OS SDK, arduino-esp8266) version of LwIP.

[philbowles]

@igrr. Thank you. It explains everything (even though its very depressing! :) ) I have already decided to go down a 2x separate code base path since my ESP8266 implemenation is very stable. Ironically so is the ESP32 compile until the stress testing runs!.

I now know why it's called "stress" testing.

Thanks again for your thorough, clear and helpful explanation and advice.