esp-idf: [Bug][v4.4.1][Websockets] "httpd_accept_conn: error in accept (23)" despite lru_purge_enable = true (IDFGH-7868)

ESP32-S3 w/ 2MB PSRAM ESP-IDF v4.4.1

Problem: When using websockets, eventually I hit “httpd_accept_conn: error in accept (23)”, and all future connections are rejected.

Rough Steps:

client connected to “/logs/websocket”
client sends small pkt to “/logs/websocket” every second, and server responds with small pkt.
client makes some more http GET calls to other unrelated endpoints, while socket is still open.
client refreshes page which tries to reestablish “/logs/websocket”
After a few (roughly ~3) iterations of steps 1-4, eventually I hit “httpd_accept_conn: error in accept (23)” and wifi refuses to make further connections.

I am already setting (httpd_config_t) lru_purge_enable = true,

I’ve enabled Socket debugging and collected the following:

lwip error list: https://github.com/espressif/esp-lwip/blob/master/src/include/lwip/err.h

Relevant errors I’m sometimes hitting: lwip_recv_tcp: netconn_recv err=-7, pbuf=0x0 (ERR_WOULDBLOCK) lwip_recv_tcp: netconn_recv err=-15, pbuf=0x0 (ERR_CLSD)

lwip_recv_tcp: netconn_recv err=-15, pbuf=0x0 (ERR_CLSD) ^ This error seems to be preceding error in accept (23)

I’m also occasionally seeing these errors before seeing the above errors: lwip_recv_tcp: netconn_recv err=-14, pbuf=0x1 (ECONNRESET) lwip_recv_tcp: p == NULL, error is “Connection reset.”! lwip_recvfrom(62): addr=0.150.206.63 port=65535 len=-1 W (781495) httpd_txrx: httpd_sock_err: error in recv : 104

Relevant ERR_WOULDBLOCK Code From LWIP (determined by adding additional logs) which seems to correspond to then hitting ‘httpd_txrx: httpd_sock_err: error in send : 104:’

  /* If we are closed, we indicate that we no longer wish to use the socket */
  if (buf == NULL) {
    if (apiflags & NETCONN_NOFIN) {
      /* received a FIN but the caller cannot handle it right now:
         re-enqueue it and return "no data" */
      netconn_set_flags(conn, NETCONN_FIN_RX_PENDING);
      return ERR_WOULDBLOCK;
    }

I also occasionally hit this ERR_WOULDBLOCK code from LWIP, but it also does not appear to cause any problems:

#if !ESP_LWIP_LOCK
  NETCONN_MBOX_WAITING_INC(conn);
#endif /* !ESP_LWIP_LOCK */  
  if (netconn_is_nonblocking(conn) || (apiflags & NETCONN_DONTBLOCK) ||
      (conn->flags & NETCONN_FLAG_MBOXCLOSED) || (conn->pending_err != ERR_OK)) {
    if (sys_arch_mbox_tryfetch(&conn->recvmbox, &buf) == SYS_ARCH_TIMEOUT) {
      err_t err;
      NETCONN_MBOX_WAITING_DEC(conn);
      err = netconn_err(conn);
      if (err != ERR_OK) {
        /* return pending error */
        return err;
      }
      if (conn->flags & NETCONN_FLAG_MBOXCLOSED) {
        return ERR_CONN;
      }
      return ERR_WOULDBLOCK;
    }
  }

Logs:

I (288009) pd http api: GET /api/logs/websocket called
I (288009) pd http api: GET /api/logs/websocket called
I (288019) pd http api: new client fd 62 Websocket
I (288029) keep alive: Added client: 62
lwip_send(62, data=0x3fce9442, size=2, flags=0x0)
lwip_send(62) err=0 written=2
lwip_send(62, data=0x3fca8230, size=51, flags=0x0)
lwip_send(62) err=0 written=51
lwip_select(63, 0x3fce9884, 0x0, 0x0, tvsec=-1 tvusec=-1)
lwip_selscan: fd=62 ready for reading
lwip_select: nready=1
lwip_recvfrom(62, 0x3fce96eb, 1, 0x0, ..)
lwip_recv_tcp: top while sock->lastdata=0x0
lwip_recv_tcp: netconn_recv err=0, pbuf=0x3fcc39a0
lwip_recv_tcp: buflen=23 recv_left=1 off=0
lwip_recv_tcp: lastdata now pbuf=0x3fcc39a0
lwip_recvfrom(62):  addr=192.168.0.2 port=56722 len=1

// removed some websocket revc packet for brevity 

I (288079) pd http api: ws: /api/logs/websocket recv pkt
lwip_send(62, data=0x3fce95a2, size=2, flags=0x0)
lwip_send(62) err=0 written=2
lwip_send(62, data=0x3fca8230, size=50, flags=0x0)
lwip_send(62) err=0 written=50
lwip_recvfrom(62, 0x3fce9703, 1, 0x0, ..)
lwip_recv_tcp: top while sock->lastdata=0x3fcc39a0
lwip_recv_tcp: buflen=22 recv_left=1 off=0
lwip_recv_tcp: lastdata now pbuf=0x3fcc39a0
lwip_recvfrom(62):  addr=192.168.0.2 port=56722 len=1
lwip_recvfrom(62, 0x3de5529d, 4, 0x0, ..)
lwip_recv_tcp: top while sock->lastdata=0x3fcc39a0
lwip_recv_tcp: buflen=21 recv_left=4 off=0
lwip_recv_tcp: lastdata now pbuf=0x3fcc39a0
lwip_recvfrom(62):  addr=192.168.0.2 port=56722 len=4
lwip_recvfrom(62, 0x3fcc3710, 17, 0x0, ..)
lwip_recv_tcp: top while sock->lastdata=0x3fcc39a0
lwip_recv_tcp: buflen=17 recv_left=17 off=0
lwip_recv_tcp: deleting pbuf=0x3fcc39a0
lwip_recvfrom(62):  addr=192.168.0.2 port=56722 len=17
lwip_select(63, 0x3fce9884, 0x0, 0x0, tvsec=-1 tvusec=-1)
lwip_sendto(56, data=0x3fcf2d30, short_size=12, flags=0x0 to=127.0.0.1 port=32768
lwip_selscan: fd=55 ready for reading
lwip_select: nready=1
lwip_recvfrom(55, 0x3fce9830, 12, 0x0, ..)
lwip_recvfrom_udp_raw[UDP/RAW]: top sock->lastdata=0x0
lwip_recvfrom_udp_raw[UDP/RAW]: netconn_recv err=0, netbuf=0x3fcc39a0
lwip_recvfrom_udp_raw: buflen=12
lwip_recvfrom_udp_raw(55):  addr=127.0.0.1 port=55494 len=12
lwip_send(62, data=0x3fce9792, size=2, flags=0x0)
lwip_send(62) err=0 written=2
lwip_send(62, data=0x3c10c294, size=5, flags=0x0)
lwip_send(62) err=0 written=5
lwip_select(63, 0x3fce9884, 0x0, 0x0, tvsec=-1 tvusec=-1)
lwip_selscan: fd=62 ready for reading
lwip_select: nready=1
lwip_recvfrom(62, 0x3fce96eb, 1, 0x0, ..)
lwip_recv_tcp: top while sock->lastdata=0x0
lwip_recv_tcp: netconn_recv err=0, pbuf=0x3fcc34dc
lwip_recv_tcp: buflen=10 recv_left=1 off=0
lwip_recv_tcp: lastdata now pbuf=0x3fcc34dc
lwip_recvfrom(62):  addr=192.168.0.2 port=56722 len=1

lwip_select(63, 0x3fce9884, 0x0, 0x0, tvsec=-1 tvusec=-1)
lwip_selscan: fd=61 ready for reading
lwip_select: nready=1
lwip_recvfrom(61, 0x3de54a54, 128, 0x0, ..)
lwip_recv_tcp: top while sock->lastdata=0x0
lwip_recv_tcp: netconn_recv err=0, pbuf=0x3fcc34dc
lwip_recv_tcp: buflen=372 recv_left=128 off=0
lwip_recv_tcp: lastdata now pbuf=0x3fcc34dc
lwip_recvfrom(61):  addr=192.168.0.2 port=56721 len=128
lwip_recvfrom(61, 0x3de54abc, 128, 0x0, ..)
lwip_recv_tcp: top while sock->lastdata=0x3fcc34dc
lwip_recv_tcp: buflen=244 recv_left=128 off=0
lwip_recv_tcp: lastdata now pbuf=0x3fcc34dc
lwip_recvfrom(61):  addr=192.168.0.2 port=56721 len=128
lwip_recvfrom(61, 0x3de54b3c, 128, 0x0, ..)
lwip_recv_tcp: top while sock->lastdata=0x3fcc34dc
lwip_recv_tcp: buflen=116 recv_left=128 off=0
lwip_recv_tcp: deleting pbuf=0x3fcc34dc
lwip_recv_tcp: top while sock->lastdata=0x0
lwip_recv_tcp: netconn_recv err=-7, pbuf=0x0
lwip_recvfrom(61):  addr=192.168.0.2 port=56721 len=116

I (292399) pd http api: GET /internal called
lwip_send(62, data=0x3fce94d2, size=2, flags=0x0)
lwip_send(62) err=0 written=2
..
..
..
lwip_send(61, data=0x3c101260, size=2, flags=0x0)
lwip_send(61) err=0 written=2
lwip_select(63, 0x3fce9884, 0x0, 0x0, tvsec=-1 tvusec=-1)
lwip_selscan: fd=55 ready for reading
lwip_select: nready=1
lwip_recvfrom(55, 0x3fce9830, 12, 0x0, ..)
lwip_recvfrom_udp_raw[UDP/RAW]: top sock->lastdata=0x0
lwip_recvfrom_udp_raw[UDP/RAW]: netconn_recv err=0, netbuf=0x3fcc39a0
lwip_recvfrom_udp_raw: buflen=12
lwip_recvfrom_udp_raw(55):  addr=127.0.0.1 port=55494 len=12
lwip_send(62, data=0x3fce9792, size=2, flags=0x0)
lwip_send(62) err=0 written=2
lwip_send(62, data=0x3c10c294, size=5, flags=0x0)
lwip_send(62) err=0 written=5
lwip_select(63, 0x3fce9884, 0x0, 0x0, tvsec=-1 tvusec=-1)
lwip_selscan: fd=62 ready for reading
lwip_select: nready=1
lwip_recvfrom(62, 0x3fce96eb, 1, 0x0, ..)
lwip_recv_tcp: top while sock->lastdata=0x0
lwip_recv_tcp: netconn_recv err=0, pbuf=0x3fcc3494
lwip_recv_tcp: buflen=10 recv_left=1 off=0
lwip_recv_tcp: lastdata now pbuf=0x3fcc3494
lwip_recvfrom(62):  addr=192.168.0.2 port=56722 len=1

I (312739) pd http api: ws: /api/logs/websocket recv pkt
lwip_send(62, data=0x3fce95a2, size=2, flags=0x0)
lwip_send(62) err=0 written=2
lwip_send(62, data=0x3fca8230, size=50, flags=0x0)
lwip_send(62) err=0 written=50
lwip_recvfrom(62, 0x3fce9703, 1, 0x0, ..)
lwip_recv_tcp: top while sock->lastdata=0x3fcc371c
lwip_recv_tcp: buflen=9 recv_left=1 off=0
lwip_recv_tcp: lastdata now pbuf=0x3fcc371c
lwip_recvfrom(62):  addr=192.168.0.2 port=56722 len=1
lwip_recvfrom(62, 0x3de5529d, 4, 0x0, ..)
lwip_recv_tcp: top while sock->lastdata=0x3fcc371c
lwip_recv_tcp: buflen=8 recv_left=4 off=0
lwip_recv_tcp: lastdata now pbuf=0x3fcc371c
lwip_recvfrom(62):  addr=192.168.0.2 port=56722 len=4
lwip_recvfrom(62, 0x3fcc34a4, 4, 0x0, ..)
lwip_recv_tcp: top while sock->lastdata=0x3fcc371c
lwip_recv_tcp: buflen=4 recv_left=4 off=0
lwip_recv_tcp: deleting pbuf=0x3fcc371c
lwip_recvfrom(62):  addr=192.168.0.2 port=56722 len=4
lwip_select(63, 0x3fce9884, 0x0, 0x0, tvsec=-1 tvusec=-1)
lwip_selscan: fd=61 ready for reading
lwip_select: nready=1
lwip_recvfrom(61, 0x3de54a54, 128, 0x0, ..)
lwip_recv_tcp: top while sock->lastdata=0x0
lwip_recv_tcp: netconn_recv err=0, pbuf=0x3fcc3494
lwip_recv_tcp: buflen=427 recv_left=128 off=0
lwip_recv_tcp: lastdata now pbuf=0x3fcc3494
lwip_recvfrom(61):  addr=192.168.0.2 port=56721 len=128
lwip_recvfrom(61, 0x3de54aaf, 128, 0x0, ..)
lwip_recv_tcp: top while sock->lastdata=0x3fcc3494
lwip_recv_tcp: buflen=299 recv_left=128 off=0
lwip_recv_tcp: lastdata now pbuf=0x3fcc3494
lwip_recvfrom(61):  addr=192.168.0.2 port=56721 len=128
lwip_recvfrom(61, 0x3de54b2f, 128, 0x0, ..)
lwip_recv_tcp: top while sock->lastdata=0x3fcc3494
lwip_recv_tcp: buflen=171 recv_left=128 off=0
lwip_recv_tcp: lastdata now pbuf=0x3fcc3494
lwip_recvfrom(61):  addr=192.168.0.2 port=56721 len=128
lwip_recvfrom(61, 0x3de54baf, 128, 0x0, ..)
lwip_recv_tcp: top while sock->lastdata=0x3fcc3494
lwip_recv_tcp: buflen=43 recv_left=128 off=0
lwip_recv_tcp: deleting pbuf=0x3fcc3494
lwip_recv_tcp: top while sock->lastdata=0x0
lwip_recv_tcp: netconn_recv err=-7, pbuf=0x0
lwip_recvfrom(61):  addr=192.168.0.2 port=56721 len=43

I (315099) pd http api: GET /api/system/heap-usage called
lwip_send(62, data=0x3fce94e2, size=2, flags=0x0)
lwip_send(62) err=0 written=2
lwip_send(62, data=0x3fca8230, size=69, flags=0x0)
lwip_send(62) err=0 written=69
lwip_send(61, data=0x3de54a54, size=70, flags=0x0)
lwip_send(61) err=0 written=70
lwip_send(61, data=0x3c101260, size=2, flags=0x0)
lwip_send(61) err=0 written=2
lwip_send(61, data=0x3de59cf8, size=969, flags=0x0)
lwip_send(61) err=0 written=969
lwip_select(63, 0x3fce9884, 0x0, 0x0, tvsec=-1 tvusec=-1)
lwip_sendto(56, data=0x3fcf2d30, short_size=12, flags=0x0 to=127.0.0.1 port=32768
lwip_selscan: fd=55 ready for reading
lwip_select: nready=1
lwip_recvfrom(55, 0x3fce9830, 12, 0x0, ..)
lwip_recvfrom_udp_raw[UDP/RAW]: top sock->lastdata=0x0
lwip_recvfrom_udp_raw[UDP/RAW]: netconn_recv err=0, netbuf=0x3fcc39a0
lwip_recvfrom_udp_raw: buflen=12
lwip_recvfrom_udp_raw(55):  addr=127.0.0.1 port=55494 len=12
lwip_send(62, data=0x3fce9792, size=2, flags=0x0)
lwip_send(62) err=0 written=2
lwip_send(62, data=0x3c10c294, size=5, flags=0x0)
lwip_send(62) err=0 written=5
lwip_select(63, 0x3fce9884, 0x0, 0x0, tvsec=-1 tvusec=-1)
lwip_selscan: fd=62 ready for reading
lwip_select: nready=1
lwip_recvfrom(62, 0x3fce96eb, 1, 0x0, ..)
lwip_recv_tcp: top while sock->lastdata=0x0
lwip_recv_tcp: netconn_recv err=0, pbuf=0x3fcc3494
lwip_recv_tcp: buflen=10 recv_left=1 off=0
lwip_recv_tcp: lastdata now pbuf=0x3fcc3494
lwip_recvfrom(62):  addr=192.168.0.2 port=56722 len=1

I (315769) pd http api: ws: /api/logs/websocket recv pkt
lwip_send(62, data=0x3fce95a2, size=2, flags=0x0)
lwip_send(62) err=0 written=2
lwip_send(62, data=0x3fca8230, size=50, flags=0x0)
lwip_send(62) err=0 written=50
lwip_recvfrom(62, 0x3fce9703, 1, 0x0, ..)
lwip_recv_tcp: top while sock->lastdata=0x3fcc3494
lwip_recv_tcp: buflen=9 recv_left=1 off=0
lwip_recv_tcp: lastdata now pbuf=0x3fcc3494
lwip_recvfrom(62):  addr=192.168.0.2 port=56722 len=1
lwip_recvfrom(62, 0x3de5529d, 4, 0x0, ..)
lwip_recv_tcp: top while sock->lastdata=0x3fcc3494
lwip_recv_tcp: buflen=8 recv_left=4 off=0
lwip_recv_tcp: lastdata now pbuf=0x3fcc3494
lwip_recvfrom(62):  addr=192.168.0.2 port=56722 len=4
lwip_recvfrom(62, 0x3fcc34ec, 4, 0x0, ..)
lwip_recv_tcp: top while sock->lastdata=0x3fcc3494
lwip_recv_tcp: buflen=4 recv_left=4 off=0
lwip_recv_tcp: deleting pbuf=0x3fcc3494
lwip_recvfrom(62):  addr=192.168.0.2 port=56722 len=4
lwip_select(63, 0x3fce9884, 0x0, 0x0, tvsec=-1 tvusec=-1)
lwip_selscan: fd=61 ready for reading
lwip_select: nready=1
lwip_recvfrom(61, 0x3de54a54, 128, 0x0, ..)
lwip_recv_tcp: top while sock->lastdata=0x0
lwip_recv_tcp: netconn_recv err=0, pbuf=0x3fcc3494
lwip_recv_tcp: buflen=364 recv_left=128 off=0
lwip_recv_tcp: lastdata now pbuf=0x3fcc3494
lwip_recvfrom(61):  addr=192.168.0.2 port=56721 len=128
lwip_recvfrom(61, 0x3de54ac4, 128, 0x0, ..)
lwip_recv_tcp: top while sock->lastdata=0x3fcc3494
lwip_recv_tcp: buflen=236 recv_left=128 off=0
lwip_recv_tcp: lastdata now pbuf=0x3fcc3494
lwip_recvfrom(61):  addr=192.168.0.2 port=56721 len=128
lwip_recvfrom(61, 0x3de54b44, 128, 0x0, ..)
lwip_recv_tcp: top while sock->lastdata=0x3fcc3494
lwip_recv_tcp: buflen=108 recv_left=128 off=0
lwip_recv_tcp: deleting pbuf=0x3fcc3494
lwip_recv_tcp: top while sock->lastdata=0x0
lwip_recv_tcp: netconn_recv err=-7, pbuf=0x0
lwip_recvfrom(61):  addr=192.168.0.2 port=56721 len=108

// ... More "Delete" events...

I (318079) pd http api: GET / called
lwip_send(62, data=0x3fce94d2, size=2, flags=0x0)
lwip_send(62) err=0 written=2
lwip_send(62, data=0x3fca8230, size=48, flags=0x0)
lwip_send(62) err=0 written=48
lwip_send(61, data=0x3de54a54, size=64, flags=0x0)
lwip_send(61) err=0 written=64
lwip_send(61, data=0x3c101260, size=2, flags=0x0)
lwip_send(61) err=0 written=2
lwip_send(61, data=0x3c112e07, size=4311, flags=0x0)
lwip_send(61) err=0 written=4311
lwip_select(63, 0x3fce9884, 0x0, 0x0, tvsec=-1 tvusec=-1)
lwip_sendto(56, data=0x3fcf2d30, short_size=12, flags=0x0 to=127.0.0.1 port=32768
lwip_selscan: fd=55 ready for reading
lwip_select: nready=1
lwip_recvfrom(55, 0x3fce9830, 12, 0x0, ..)
lwip_recvfrom_udp_raw[UDP/RAW]: top sock->lastdata=0x0
lwip_recvfrom_udp_raw[UDP/RAW]: netconn_recv err=0, netbuf=0x3fcc3790
lwip_recvfrom_udp_raw: buflen=12
lwip_recvfrom_udp_raw(55):  addr=127.0.0.1 port=55494 len=12
lwip_send(62, data=0x3fce9792, size=2, flags=0x0)
lwip_send(62) err=0 written=2
lwip_send(62, data=0x3c10c294, size=5, flags=0x0)
lwip_send(62) err=0 written=5
lwip_select(63, 0x3fce9884, 0x0, 0x0, tvsec=-1 tvusec=-1)
lwip_selscan: fd=62 ready for reading
lwip_select: nready=1
lwip_recvfrom(62, 0x3fce96eb, 1, 0x0, ..)
lwip_recv_tcp: top while sock->lastdata=0x0
lwip_recv_tcp: netconn_recv err=0, pbuf=0x3fcc34dc
lwip_recv_tcp: buflen=10 recv_left=1 off=0
lwip_recv_tcp: lastdata now pbuf=0x3fcc34dc
lwip_recvfrom(62):  addr=192.168.0.2 port=56722 len=1

// ... More "Delete" events...

I (351769) pd http api: ws: /api/logs/websocket recv pkt
lwip_send(62, data=0x3fce95a2, size=2, flags=0x0)
lwip_send(62) err=0 written=2
lwip_send(62, data=0x3fca8230, size=50, flags=0x0)
lwip_send(62) err=0 written=50
lwip_recvfrom(62, 0x3fce9703, 1, 0x0, ..)
lwip_recv_tcp: top while sock->lastdata=0x3fcc3494
lwip_recv_tcp: buflen=9 recv_left=1 off=0
lwip_recv_tcp: lastdata now pbuf=0x3fcc3494
lwip_recvfrom(62):  addr=192.168.0.2 port=56722 len=1
lwip_recvfrom(62, 0x3de5529d, 4, 0x0, ..)
lwip_recv_tcp: top while sock->lastdata=0x3fcc3494
lwip_recv_tcp: buflen=8 recv_left=4 off=0
lwip_recv_tcp: lastdata now pbuf=0x3fcc3494
lwip_recvfrom(62):  addr=192.168.0.2 port=56722 len=4
lwip_recvfrom(62, 0x3fcc372c, 4, 0x0, ..)
lwip_recv_tcp: top while sock->lastdata=0x3fcc3494
lwip_recv_tcp: buflen=4 recv_left=4 off=0
lwip_recv_tcp: deleting pbuf=0x3fcc3494
lwip_recvfrom(62):  addr=192.168.0.2 port=56722 len=4
lwip_select(63, 0x3fce9884, 0x0, 0x0, tvsec=-1 tvusec=-1)
lwip_selscan: fd=54 ready for reading
lwip_select: nready=1
lwip_accept(54)...
lwip_accept(54) returning new sock=63 addr=192.168.0.2 port=56723

I (353319) pd http api: Client connected 63
lwip_send(62, data=0x3fce9612, size=2, flags=0x0)
lwip_send(62) err=0 written=2
lwip_send(62, data=0x3fca8230, size=55, flags=0x0)
lwip_send(62) err=0 written=55
lwip_select(64, 0x3fce9884, 0x0, 0x0, tvsec=-1 tvusec=-1)
lwip_selscan: fd=63 ready for reading
lwip_select: nready=1
lwip_recvfrom(63, 0x3de54a54, 128, 0x0, ..)
lwip_recv_tcp: top while sock->lastdata=0x0
lwip_recv_tcp: netconn_recv err=0, pbuf=0x3fcc3c08
lwip_recv_tcp: buflen=368 recv_left=128 off=0
lwip_recv_tcp: lastdata now pbuf=0x3fcc3c08
lwip_recvfrom(63):  addr=192.168.0.2 port=56723 len=128
lwip_recvfrom(63, 0x3de54ac0, 128, 0x0, ..)
lwip_recv_tcp: top while sock->lastdata=0x3fcc3c08
lwip_recv_tcp: buflen=240 recv_left=128 off=0
lwip_recv_tcp: lastdata now pbuf=0x3fcc3c08
lwip_recvfrom(63):  addr=192.168.0.2 port=56723 len=128
lwip_recvfrom(63, 0x3de54b40, 128, 0x0, ..)
lwip_recv_tcp: top while sock->lastdata=0x3fcc3c08
lwip_recv_tcp: buflen=112 recv_left=128 off=0
lwip_recv_tcp: deleting pbuf=0x3fcc3c08
lwip_recv_tcp: top while sock->lastdata=0x0
lwip_recv_tcp: netconn_recv err=-7, pbuf=0x0
lwip_recvfrom(63):  addr=192.168.0.2 port=56723 len=112

I (353429) pd http api: GET /logs called
lwip_send(62, data=0x3fce94d2, size=2, flags=0x0)
lwip_send(62) err=0 written=2
lwip_send(62, data=0x3fca8230, size=52, flags=0x0)
lwip_send(62) err=0 written=52
lwip_send(63, data=0x3de54a54, size=64, flags=0x0)
lwip_send(63) err=0 written=64
lwip_send(63, data=0x3c101260, size=2, flags=0x0)
lwip_send(63) err=0 written=2
lwip_send(63, data=0x3c111d85, size=4222, flags=0x0)
lwip_send(63) err=0 written=4222
lwip_select(64, 0x3fce9884, 0x0, 0x0, tvsec=-1 tvusec=-1)
lwip_selscan: fd=62 ready for reading
lwip_select: nready=1
lwip_recvfrom(62, 0x3fce96eb, 1, 0x0, ..)
lwip_recv_tcp: top while sock->lastdata=0x0
lwip_recv_tcp: netconn_recv err=0, pbuf=0x3fcc3c98
lwip_recv_tcp: buflen=8 recv_left=1 off=0
lwip_recv_tcp: lastdata now pbuf=0x3fcc3c98
lwip_recvfrom(62):  addr=192.168.0.2 port=56722 len=1
lwip_recvfrom(62, 0x3fce96b3, 1, 0x0, ..)
lwip_recv_tcp: top while sock->lastdata=0x3fcc3c98
lwip_recv_tcp: buflen=7 recv_left=1 off=0
lwip_recv_tcp: lastdata now pbuf=0x3fcc3c98
lwip_recvfrom(62):  addr=192.168.0.2 port=56722 len=1
lwip_recvfrom(62, 0x3de5529d, 4, 0x0, ..)
lwip_recv_tcp: top while sock->lastdata=0x3fcc3c98
lwip_recv_tcp: buflen=6 recv_left=4 off=0
lwip_recv_tcp: lastdata now pbuf=0x3fcc3c98
lwip_recvfrom(62):  addr=192.168.0.2 port=56722 len=4
lwip_recvfrom(62, 0x3fce96fc, 2, 0x0, ..)
lwip_recv_tcp: top while sock->lastdata=0x3fcc3c98
lwip_recv_tcp: buflen=2 recv_left=2 off=0
lwip_recv_tcp: deleting pbuf=0x3fcc3c98
lwip_recvfrom(62):  addr=192.168.0.2 port=56722 len=2
lwip_send(62, data=0x3fce9682, size=2, flags=0x0)
lwip_send(62) err=0 written=2
lwip_sendto(56, data=0x3fce96c0, short_size=12, flags=0x0 to=127.0.0.1 port=32768
lwip_select(64, 0x3fce9884, 0x0, 0x0, tvsec=-1 tvusec=-1)
lwip_selscan: fd=55 ready for reading
lwip_selscan: fd=62 ready for reading
lwip_select: nready=2
lwip_recvfrom(55, 0x3fce9830, 12, 0x0, ..)
lwip_recvfrom_udp_raw[UDP/RAW]: top sock->lastdata=0x0
lwip_recvfrom_udp_raw[UDP/RAW]: netconn_recv err=0, netbuf=0x3fcc3d84
lwip_recvfrom_udp_raw: buflen=12
lwip_recvfrom_udp_raw(55):  addr=127.0.0.1 port=55494 len=12

I (353619) pd http api: Client disconnected 62
I (353629) keep alive: Removed client: 62
lwip_select(64, 0x3fce9884, 0x0, 0x0, tvsec=-1 tvusec=-1)
lwip_selscan: fd=63 ready for reading
lwip_select: nready=1
lwip_recvfrom(63, 0x3de54a54, 128, 0x0, ..)
lwip_recv_tcp: top while sock->lastdata=0x0
lwip_recv_tcp: netconn_recv err=0, pbuf=0x3fcc371c
lwip_recv_tcp: buflen=332 recv_left=128 off=0
lwip_recv_tcp: lastdata now pbuf=0x3fcc371c
lwip_recvfrom(63):  addr=192.168.0.2 port=56723 len=128
lwip_recvfrom(63, 0x3de54ab0, 128, 0x0, ..)
lwip_recv_tcp: top while sock->lastdata=0x3fcc371c
lwip_recv_tcp: buflen=204 recv_left=128 off=0
lwip_recv_tcp: lastdata now pbuf=0x3fcc371c
lwip_recvfrom(63):  addr=192.168.0.2 port=56723 len=128
lwip_recvfrom(63, 0x3de54b30, 128, 0x0, ..)
lwip_recv_tcp: top while sock->lastdata=0x3fcc371c
lwip_recv_tcp: buflen=76 recv_left=128 off=0
lwip_recv_tcp: deleting pbuf=0x3fcc371c
lwip_recv_tcp: top while sock->lastdata=0x0
lwip_recv_tcp: netconn_recv err=-7, pbuf=0x0
lwip_recvfrom(63):  addr=192.168.0.2 port=56723 len=76

I (354069) pd http api: GET /api/logs/recent-logs called
lwip_send(63, data=0x3de54a54, size=71, flags=0x0)
lwip_send(63) err=0 written=71
lwip_send(63, data=0x3c101260, size=2, flags=0x0)
lwip_send(63) err=0 written=2
lwip_send(63, data=0x3fce95b2, size=6, flags=0x0)
lwip_send(63) err=0 written=6
lwip_send(63, data=0x3de01248, size=14334, flags=0x0)
lwip_send(63) err=0 written=14334
lwip_send(63, data=0x3c101260, size=2, flags=0x0)
lwip_send(63) err=0 written=2
lwip_send(63, data=0x3fce95b2, size=3, flags=0x0)
lwip_send(63) err=0 written=3
lwip_send(63, data=0x3c101260, size=2, flags=0x0)
lwip_send(63) err=0 written=2
lwip_send(63, data=0x3fce95b2, size=3, flags=0x0)
lwip_send(63) err=0 written=3
lwip_send(63, data=0x3c101260, size=2, flags=0x0)
lwip_send(63) err=0 written=2
lwip_select(64, 0x3fce9884, 0x0, 0x0, tvsec=-1 tvusec=-1)
lwip_selscan: fd=63 ready for reading
lwip_select: nready=1
lwip_recvfrom(63, 0x3de54a54, 128, 0x0, ..)
lwip_recv_tcp: top while sock->lastdata=0x0
lwip_recv_tcp: netconn_recv err=-15, pbuf=0x0
lwip_recv_tcp: p == NULL, error is "Connection closed."!
lwip_recvfrom(63):  addr=192.168.0.2 port=56723 len=0

I (354209) pd http api: Client disconnected 63
lwip_select(56, 0x3fce9884, 0x0, 0x0, tvsec=-1 tvusec=-1)
lwip_selscan: fd=54 ready for reading
lwip_select: nready=1
lwip_accept(54)...
W (354299) httpd: httpd_accept_conn: error in accept (23)
W (354299) httpd: httpd_server: error accepting new connection
lwip_select(56, 0x3fce9884, 0x0, 0x0, tvsec=-1 tvusec=-1)
lwip_selscan: fd=54 ready for reading
lwip_select: nready=1
lwip_accept(54)...
W (354399) httpd: httpd_accept_conn: error in accept (23)
W (354399) httpd: httpd_server: error accepting new connection
lwip_select(56, 0x3fce9884, 0x0, 0x0, tvsec=-1 tvusec=-1)
lwip_selscan: fd=54 ready for reading
lwip_select: nready=1
lwip_accept(54)...
W (354499) httpd: httpd_accept_conn: error in accept (23)
W (354499) httpd: httpd_server: error accepting new connection
lwip_select(56, 0x3fce9884, 0x0, 0x0, tvsec=-1 tvusec=-1)
I (475719) pd wifi: Wifi Event: AP Mode - Client Disconnected
I (475729) pd wifi: Client disconnected: f8:4d:89:7c:19:f0 leave, AID=1

(the errors happen near the end)

About this issue

Original URL
State: closed
Created 2 years ago
Comments: 15 (10 by maintainers)

Most upvoted comments

@chipweinberger Sorry for late reply. 109 means ENOPROTOOPT, protocol not available. You need check whether you enable CONFIG_LWIP_SO_LINGER in menuconfig.

ESP-YJM on Sep 28, 2022

That fixes it !!! 🥳 🥳 🥳

Wow thank you. It’s night and day how much more reliable my server is now.

2 Questions:

Would it make more sense to call this code in open_fd_cb? That way, it is set as soon as the socket is established?
Shouldn’t SO_LINGER = 0 be the default when setting lru_page_enable = true?

Small note, I called lwip_setsockopt instead of setsocketopt since #include <sys/socket.h> does not seem to include that one.

chipweinberger on Jul 28, 2022

@chipweinberger 23 means allocate socket number failed. Maybe the closed sockets are in TIME-WAIT state and not free the socket number. I think you can use SO_LINGER socket option in httpd.close_fn callback function. Like this :

void close_fd_cb(httpd_handle_t hd, int sockfd)
{
   struct linger so_linger;
   so_linger.l_onoff = true;
   so_linger.l_linger = 0;
   setsocketopt(sockfd, SOL_SOCKET, SO_LINGER, &so_linger, sizeof(so_linger));
   close(sockfd);
}

ESP-YJM on Jul 28, 2022