Occasional crash in ntripClientUpdate

[PaulZC]

To replicate: release_candidate with pcUpdates (adds new RTCM1005/1006 ARP logging) on Postcard. Connected to WiFi. Corrections coming from PP (Flex NTRIP/RTCM).

I'm not yet sure if the new code I added to log the RTCM1005/1006 ARP is causing this. Logging it here just in case.

It is going bang in pbuf_free inside ntripClient->read inside ntripClientUpdate. Maybe a stack issue?

[PaulZC]

It looks like making rtcmData[] and rtcmCount static has fixed this: 6dd3503

I'll leave it running for a couple of hours to see if it goes bang again.

[PaulZC]

Spoke too soon... It's just gone bang in the same place:

Rover Accuracy (m): 0.006, SIV: 40 GNSS State: RTK Fix
FreeHeap: 40808 / HeapLowestPoint: 39720 / LargestBlock: 1966068 / Used PSRAM: 98620
FreeHeap: 40808 / HeapLowestPoint: 39720 / LargestBlock: 1966068 / Used PSRAM: 98620

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


Backtrace: 0x40083305:0x3ffd3f00 0x40098a15:0x3ffd3f20 0x4009e196:0x3ffd3f40 0x40175bf7:0x3ffd4070 0x40171786:0x3ffd4090 0x40172fad:0x3ffd40d0 0x40173076:0x3ffd4130 0x4011ed19:0x3ffd4150 0x4011ee7d:0x3ffd4180 0x4011f1d7:0x3ffd41a0 0x40102546:0x3ffd41f0 0x40117efc:0x3ffd4480 0x401181aa:0x3ffd44f0 0x4015d150:0x3ffd4510 0x4009b27a:0x3ffd4530




ELF file SHA256: 077df2ce2ee15add

Rebooting...
ets Jul 29 2019 12:21:46

rst:0xc (SW_CPU_RESET),boot:0x13 (SPI_FAST_FLASH_BOOT)
configsip: 271414342, SPIWP:0xee

[PaulZC]

Looks like it is my new code causing this... If I comment the sempParseNextBytes(rtcmParse, rtcmData, rtcmCount) in ntripClientUpdate, it doesn't crash. Investigating...

[PaulZC]

Looks like the root cause is the logFile->println(nmeaMessage); - even though it is protected by a semaphore. Investigating...

[PaulZC]

After much much much head-scratching, I now suspect this is linked to a network timeout.

It's difficult to prove conclusively because these crashes are rare (30 minutes to 1 hour typically), but I currently believe the following is true:

• These crashes only occur when I'm connected to the new PP RTCM NTRIP service
• They don't occur if I connect to my personal RTK2go caster
• They are not linked to SD writing, or semaphores, or the SEMP having a memory leak, or many other things...!

I haven't trapped one, but I do remember seeing messages on the console that suggested the PP connection had timed out. Maybe the default NetworkClient connection timeout of 3000ms is causing problems? If delivery of corrections from PP stalls for > 3 seconds, does that cause the ntripClient to perform a double-free? I.e. a second call of the packet-buffer free method (pbuf_free). Because that would cause the pbuf_free: p->ref > 0 assertion to fail...

Implementation is here: 248ba03

[PaulZC]

Humm... Why is the UDP Server running?

NTRIP Client received 910 RTCM bytes, pushed to GNSS
FreeHeap: 41712 / HeapLowestPoint: 40852 / LargestBlock: 1933300 / Used PSRAM: 101372
Rover Accuracy (m): 0.006, SIV: 39 GNSS State: RTK Fix
Log file: recording Antenna Reference Position 3666469.0281,-96662.9373,5200712.9555,0.0000
FreeHeap: 41712 / HeapLowestPoint: 40852 / LargestBlock: 1933300 / Used PSRAM: 101372
Ring buffer full: discarding 1863 bytes, UDP server is slow
Log file: recording Antenna Reference Position 3666469.0281,-96662.9373,5200712.9555,0.0000
FreeHeap: 41712 / HeapLowestPoint: 40852 / LargestBlock: 1933300 / Used PSRAM: 101372
Rover Accuracy (m): 0.006, SIV: 39 GNSS State: RTK Fix
Log file: recording Antenna Reference Position 3666469.0281,-96662.9373,5200712.9555,0.0000
FreeHeap: 41712 / HeapLowestPoint: 40852 / LargestBlock: 1933300 / Used PSRAM: 101372
Log file: recording Antenna Reference Position 3666469.0281,-96662.9373,5200712.9555,0.0000
FreeHeap: 41712 / HeapLowestPoint: 40852 / LargestBlock: 1933300 / Used PSRAM: 101372
Rover Accuracy (m): 0.006, SIV: 39 GNSS State: RTK Fix
Log file: recording Antenna Reference Position 3666469.0281,-96662.9373,5200712.9555,0.0000
Batt (96%): Voltage: 4.16V Charging: 2.70%/hr
Log file size: 3805877 - Generation rate: 3.4kB/s
NTRIP Client received 910 RTCM bytes, pushed to GNSS

[PaulZC]

With the improvements in pcUpdates, I was able to log LG290P GNSS data on Postcard at 2Hz with the ARP interleaved every 1s. Connected to my RTK2go caster, it logged for just under 12 hours until I stopped it manually. The 132MB single log file is completely clean:

Processing e:\SFE_Postcard_250718_192825.txt

NMEA $ found at byte 0


Processed 135433594 bytes
File size was 135433594
Longest valid UBX message was 0 bytes
Longest valid NMEA message was 89 characters
Message types and totals were:
Message type: GNTXT      Total: 41680
Message type: GNGGA      Total: 84499
Message type: GNRMC      Total: 84499
Message type: GNGLL      Total: 84499
Message type: GNVTG      Total: 84499
Message type: GNGST      Total: 84499
Message type: GNGSA      Total: 253494
Message type: GPGSV      Total: 301343
Message type: GLGSV      Total: 169686
Message type: GAGSV      Total: 328264
Message type: GBGSV      Total: 547676
Message type: GQGSV      Total: 126747
Message type: GIGSV      Total: 42249

The GNTXT messages contain the ARP.

Connected to PP RTCM NTRIP, it crashed out after just under 6 hours with the same (pbuf_free: p->ref > 0) assertion error:

Processing e:\SFE_Postcard_250719_080936.txt

NMEA $ found at byte 0


Processed 78643019 bytes
File size was 78643019
Longest valid UBX message was 0 bytes
Longest valid NMEA message was 89 characters
Message types and totals were:
Message type: GNTXT      Total: 22268
Message type: GNGGA      Total: 45142
Message type: GNRMC      Total: 45142
Message type: GNGLL      Total: 45142
Message type: GNVTG      Total: 45142
Message type: GNGST      Total: 45142
Message type: GNGSA      Total: 135426
Message type: GPGSV      Total: 166336
Message type: GLGSV      Total: 90672
Message type: GAGSV      Total: 210896
Message type: GBGSV      Total: 347332
Message type: GQGSV      Total: 67710
Message type: GIGSV      Total: 22570

I suspect there is an underlying NetworkClient 'timeout' issue which causes pbuf_free to be called twice. But I'm really not sure...

Note to my future self: to fully understand what's happening, we'd need to use the esp32-arduino-lib-builder to compile lwip with its LWIP_DBG debug messages routed through to log_.

[PaulZC]

Espressif have of course got the debug covered...

Using esp32-arduino-lib-builder

./build.sh -t esp32 -b menuconfig

Navigate to Component config LWIP Enable LWIP Debug. There are many debug options, including pbuf debug:

CONFIG_LWIP_DEBUG=y
CONFIG_LWIP_NETIF_DEBUG=y
CONFIG_LWIP_PBUF_DEBUG=y
CONFIG_LWIP_SOCKETS_DEBUG=y
CONFIG_LWIP_IP_DEBUG=y
CONFIG_LWIP_TCP_DEBUG=y

increases liblwip.a from 3776KB to 3961KB

[PaulZC]

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...

[PaulZC]

The tcp_recved: window got too big or tcpwnd_size_t overflow is almost certainly significant...?!

[PaulZC]

lwip_recvfrom(48): addr=54.216.128.133 port=2101 len=1436 : 1436 is the Maximum Segment Size (MSS)

The lwip_recv_tcp: buflen=0 recv_left=0 off=0 causes the assert failure

[PaulZC]

Just for giggles, I'm trying a test with CONFIG_LWIP_TCPIP_TASK_STACK_SIZE=6144

Edit: that didn't help. It still crashed in the same place.

[PaulZC]

CONFIG_LWIP_TCPIP_CORE_LOCKING and CONFIG_LWIP_CHECK_THREAD_SAFETY made no difference.

Trying again with CONFIG_LWIP_ESP_LWIP_ASSERT disabled - so the code ignores the assert

Edit: with CONFIG_LWIP_ESP_LWIP_ASSERT disabled the code continues past the assertion, but then crashes out during a subsequent memcpy in pbuf_copy_partial

[PaulZC]

I see the same warning on both my branch and with release 2.2:

Ring buffer full: discarding 3520 bytes, UDP server could be slow

I'm not convinced the UDP Server is actually to blame. I think it's just that UDP had the most recent buffer wrap-around event, causing usedSpace to be non-zero.

But, the 3520 bytes in the above message is deeply worrying. The buffer is only 4KB total. Why is 85% of it being discarded?

I suspect rbOffsetEntries could be to blame. But investigating that is a job for Future-Paul... ;-)