[SOLVED] LWIP ASSERT (pbuf_free: p->ref > 0) during NetworkClient read

[PaulZC]

Hi Everyone,

I am using Arduino 3.0.7 NetworkClient on ESP32 Pico Mini 02 N8R2 to receive GNSS RTCM corrections from a NTRIP Caster / Server via TCP over WiFi.

I see occasional crashes due to an assert in LWIP pbuf_free. These happen rarely, every few hours.

I would like to understand if they are caused by a network timeout of some kind, or if a delay caused by my writing the RTCM to the GNSS and SD card (using SdFat) could be the cause.

The assert failure happens during a NetworkClient read:

Exception_decoder.png (93.56 KiB) Viewed 481 times

I have tried using readBytes instead of read. That seems to make the crashes less frequent, but does not prevent them.

I recompiled lwip and enabled a bunch of debug messages. Here is the activity leading up to the crash:

Code: Select all

IP header:
+-------------------------------+
| 4 | 5 |  0x00 |        40     | (v, hl, tos, len)
+-------------------------------+
pbuf_free(0x3ffeb8c0)
|      360      |000|       0   | (id, flags, offset)
+-------------------------------+
|   64  |    6  |    0x0093     | (ttl, proto, chksum)
+-------------------------------+
|  192  |  168  |    0  |  208  | (src)
+-------------------------------+
|   54  |  216  |  128  |  133  | (dest)
+-------------------------------+
pbuf_free: deallocating 0x3ffeb8c0
ip4_output_if: call netif->output()
lwip_recv_tcp: buflen=889 recv_left=0 off=0
pbuf_add_header: old 0x3f818108 new 0x3f8180fa (14)
lwip_recv_tcp: top while sock->lastdata=0x0
lwip_recv_tcp: buflen=889 recv_left=547 off=889
pbuf_free(0x3f8180d4)
pbuf_free: 0x3f8180d4 has ref 1, ending here.
lwip_recv_tcp: lastdata now pbuf=0x3ffeb8c0
pbuf_free(0x3f8180d4)
pbuf_remove_header: old 0x3f817d3a new 0x3f817f5d (547)
lwip_recv_tcp: lastdata now pbuf=0x3ffeb8c0
pbuf_free: deallocating 0x3f8180d4
lwip_recvfrom(48):  addr=54.216.128.133 port=2101 len=0
tcp_recved: window got too big or tcpwnd_size_t overflow
lwip_select(49, 0x0, 0x3ffe8f98, 0x0, tvsec=0 tvusec=1000000)
pbuf_alloc(length=20)
lwip_selscan: fd=48 ready for writing
pbuf_alloc(length=20) == 0x3f817cf0
lwip_select: nready=1
pbuf_add_header: old 0x3f817d38 new 0x3f817d24 (20)
lwip_send(48, data=0x3f811c34, size=93, flags=0x8)
ip4_output_if: st1
IP header:
+-------------------------------+
| 4 | 5 |  0x00 |        40     | (v, hl, tos, len)
+-------------------------------+
|      361      |000|       0   | (id, flags, offset)
+-------------------------------+
|   64  |    6  |    0x0092     | (ttl, proto, chksum)
+-------------------------------+
|  192  |  168  |    0  |  208  | (src)
+-------------------------------+
|   54  |  216  |  128  |  133  | (dest)
+-------------------------------+
ip4_output_if: call netif->output()
pbuf_add_header: old 0x3f817d24 new 0x3f817d16 (14)
pbuf_free(0x3f817cf0)
pbuf_free: 0x3f817cf0 has ref 1, ending here.
pbuf_free(0x3f817cf0)
pbuf_free: deallocating 0x3f817cf0
tcp_recved: received 1436 bytes, wnd 5760 (0).
pbuf_alloc(length=1436)
pbuf_alloc(length=1436) == 0x3f817c70
pbuf_add_header: old 0x3f817ccc new 0x3f817cb8 (20)
pbuf_add_header: old 0x3f817cb8 new 0x3f817ca4 (20)
ip4_output_if: st1
IP header:
+-------------------------------+
| 4 | 5 |  0x00 |       133     | (v, hl, tos, len)
+-------------------------------+
|      362      |000|       0   | (id, flags, offset)
+-------------------------------+
|   64  |    6  |    0x0034     | (ttl, proto, chksum)
+-------------------------------+
|  192  |  168  |    0  |  208  | (src)
+-------------------------------+
|   54  |  216  |  128  |  133  | (dest)
+-------------------------------+
ip4_output_if: call netif->output()
pbuf_add_header: old 0x3f817ca4 new 0x3f817c96 (14)
pbuf_free(0x3f817c70)
pbuf_free: 0x3f817c70 has ref 1, ending here.
lwip_send(48) err=0 written=93
lwip_recvfrom(48):  addr=54.216.128.133 port=2101 len=1436
FreeHeap: 42528 / HeapLowestPoint: 41592 / LargestBlock: 1966068 / Used PSRAM: 100068
lwip_recvfrom(48, 0x3ffd33ff, 0, 0x8, ..)
lwip_recv_tcp: top while sock->lastdata=0x3ffeb8c0
lwip_recv_tcp: buflen=0 recv_left=0 off=0
lwip_recv_tcp: deleting pbuf=0x3ffeb8c0
tcp_slowtmr: processing active pcb
pbuf_free(0x3ffeb8c0)

assert failed: pbuf_free /IDF/components/lwip/lwip/src/core/pbuf.c:753 (pbuf_free: p->ref > 0)


Backtrace: 0x40083305:0x3ffd3160 0x40098ad9:0x3ffd3180 0x4009e25a:0x3ffd31a0 0x40177518:0x3ffd32d0 0x40172501:0x3ffd32f0 0x40174335:0x3ffd3330 0x401744ea:0x3ffd33b0 0x4011f08e:0x3ffd33d0 0x401027d6:0x3ffd3420 0x4011856c:0x3ffd3cb0 0x4011881a:0x3ffd3d20 0x4015dda8:0x3ffd3d40 0x4009b33e:0x3ffd3d60




ELF file SHA256: 895e3dde40850abf

Rebooting...

The

Code: Select all

tcp_recved: window got too big or tcpwnd_size_t overflow

is critical. I would like to understand what could cause that.

The

Code: Select all

lwip_recvfrom(48):  addr=54.216.128.133 port=2101 len=0

followed by

Code: Select all

lwip_recvfrom(48):  addr=54.216.128.133 port=2101 len=1436

is puzzling too. 1436 is the Maximum Segment Size (MSS).

I'd be grateful for your thoughts on this. Am I chasing a network packet-delivery issue - or something else?

Best wishes,
Paul

[PaulZC]

Thanks for reading...

I'm now 99% sure this is a simple case of PEBCAK, although it has had me scratching my head for several days.

The root cause was calling NetworkClient print (write) from a periodic task, with NetworkClient read being performed by the loop. The LWIP ASSERT (pbuf_free: p->ref > 0) was caused by the task trying to write midway through a read...