[Bug]: GPS Buffer full

[cracky22]

Category

Hardware Compatibility, Other

Hardware

Seeed Card Tracker T1000-E

Firmware Version

2.5.18

Description

WARN | 10:26:13 342 [GPS] GPS Buffer full with 1023 bytes waiting. Flush to avoid corruption

Relevant log output

WARN | 10:26:13 342 [GPS] GPS Buffer full with 1023 bytes waiting. Flush to avoid corruption

[cracky22]

DEBUG | 10:29:59 568 [Router] Module 'routing' considered

INFO | 10:29:59 568 [GPS] GPS power state move from IDLE to ACTIVE

WARN | 10:29:59 568 [Position] Ch. util >25%. Skip send

DEBUG | 10:29:59 568 [RadioIf] Lora RX (id=0x49311782 fr=0xda63587c to=0xffffffff, WantAck=0, HopLim=3 Ch=0x1e encrypted len=49 rxSNR=10 rxRSSI=-34 via MQTT hopStart=7)

DEBUG | 10:29:59 568 [RadioIf] Packet RX: 600ms

DEBUG | 10:29:59 568 [RadioIf] rx_snr found. hop_limit:5 rx_snr:9.750000

DEBUG | 10:29:59 568 [RadioIf] rx_snr found in packet. Setting tx delay:5467

DEBUG | 10:29:59 568 [Router] Add packet record (id=0x49311782 fr=0xda63587c to=0xffffffff, WantAck=0, HopLim=3 Ch=0x1e encrypted len=49 rxSNR=10 rxRSSI=-34 via MQTT hopStart=7)

DEBUG | 10:29:59 568 [Router] Use channel 1 (hash 0x1e)

DEBUG | 10:29:59 568 [Router] Use AES128 key!

DEBUG | 10:29:59 568 [Router] decoded message (id=0x49311782 fr=0xda63587c to=0xffffffff, WantAck=0, HopLim=3 Ch=0x1 Portnum=3 rxtime=1736155799 rxSNR=10 rxRSSI=-34 via MQTT hopStart=7)

DEBUG | 10:29:59 568 [Router] handleReceived(REMOTE) (id=0x49311782 fr=0xda63587c to=0xffffffff, WantAck=0, HopLim=3 Ch=0x1 Portnum=3 rxtime=1736155799 rxSNR=10 rxRSSI=-34 via MQTT hopStar

DEBUG | 10:29:59 568 [Router] Module 'position' wantsPacket=1

INFO | 10:29:59 568 [Router] Received position from=0xda63587c, id=0x49311782, portnum=3, payloadlen=27

DEBUG | 10:29:59 568 [Router] POSITION node=da63587c l=27 lat=482770944 lon=115572736 msl=0 hae=0 geo=0 pdop=0 hdop=0 vdop=0 siv=0 fxq=0 fxt=0 pts=0 time=1736155782

INFO | 10:30:00 568 [Router] updatePosition REMOTE node=0xda63587c time=1736155782 lat=482770944 lon=115572736

DEBUG | 10:30:00 568 [Router] Node status update: 49 online, 76 total

DEBUG | 10:30:00 568 [Router] Module 'position' considered

DEBUG | 10:30:00 568 [Router] Module 'routing' wantsPacket=1

INFO | 10:30:00 568 [Router] Received routing from=0xda63587c, id=0x49311782, portnum=3, payloadlen=27

DEBUG | 10:30:00 568 [Router] Routing sniffing (id=0x49311782 fr=0xda63587c to=0xffffffff, WantAck=0, HopLim=3 Ch=0x1 Portnum=3 rxtime=1736155799 rxSNR=10 rxRSSI=-34 via MQTT hopStart=7)

INFO | 10:30:00 569 [Router] Rebroadcast received floodmsg

DEBUG | 10:30:00 569 [Router] Use AES128 key!

DEBUG | 10:30:00 569 [Router] enqueue for send (id=0x49311782 fr=0xda63587c to=0xffffffff, WantAck=0, HopLim=2 Ch=0x1e encrypted len=49 rxtime=1736155799 rxSNR=10 rxRSSI=-34 via MQTT hopSt

DEBUG | 10:30:00 569 [Router] txGood=24,txRelay=20,rxGood=38,rxBad=0

DEBUG | 10:30:00 569 [Router] rx_snr found. hop_limit:5 rx_snr:9.750000

DEBUG | 10:30:00 569 [Router] rx_snr found in packet. Setting tx delay:1694

DEBUG | 10:30:00 569 [Router] Delivering rx packet (id=0x49311782 fr=0xda63587c to=0xffffffff, WantAck=0, HopLim=3 Ch=0x1 Portnum=3 rxtime=1736155799 rxSNR=10 rxRSSI=-34 via MQTT hopStart=

DEBUG | 10:30:00 569 [Router] Update DB node 0xda63587c, rx_time=1736155799

DEBUG | 10:30:00 569 [Router] Forwarding to phone (id=0x49311782 fr=0xda63587c to=0xffffffff, WantAck=0, HopLim=3 Ch=0x1 Portnum=3 rxtime=1736155799 rxSNR=10 rxRSSI=-34 via MQTT hopStart=7

DEBUG | 10:30:00 569 [Router] Module 'routing' considered

INFO | 10:30:00 569 Tell client we have new packets 42

INFO | 10:30:00 569 BLE notify fromNum

DEBUG | 10:30:00 569 FromRadio=STATE_SEND_PACKETS

DEBUG | 10:30:00 569 phone downloaded packet (id=0x49311782 fr=0xda63587c to=0xffffffff, WantAck=0, HopLim=3 Ch=0x1 Portnum=3 rxtime=1736155799 rxSNR=10 rxRSSI=-34 via MQTT hopSta

DEBUG | 10:30:16 585 [Power] Battery: usbPower=1, isCharging=1, batMv=4192, batPct=100

WARN | 10:30:16 585 [GPS] GPS Buffer full with 1023 bytes waiting. Flush to avoid corruption

INFO | 10:30:16 585 [EnvironmentTelemetry] Send: barometric_pressure=0.000000, current=0.000000, gas_resistance=0.000000, relative_humidity=0.000000, temperature=26.416958

INFO | 10:30:16 585 [EnvironmentTelemetry] Send: voltage=0.000000, IAQ=0, distance=0.000000, lux=0.000000

INFO | 10:30:16 585 [EnvironmentTelemetry] Send: wind speed=0.000000m/s, direction=0 degrees, weight=0.000000kg

INFO | 10:30:16 585 [EnvironmentTelemetry] Send: radiation=0.000000##R/h

DEBUG | 10:30:16 585 [EnvironmentTelemetry] Partially randomized packet id 2028851658

INFO | 10:30:16 585 [EnvironmentTelemetry] Send packet to phone

WARN | 10:30:16 585 [RadioIf] Can not send yet, busyRx

DEBUG | 10:30:16 585 [RadioIf] rx_snr found. hop_limit:5 rx_snr:9.750000

DEBUG | 10:30:16 585 [RadioIf] rx_snr found in packet. Setting tx delay:5159

INFO | 10:30:16 585 Tell client we have new packets 43

INFO | 10:30:16 585 BLE notify fromNum

[fifieldt]

Thanks @cracky22 . Do you have the ability to build your own firmware? If so logs from one with #define GPS_DEBUG 1 in variant.h . Otherwise let me know and I'll make one for you.

[cracky22]

in variants/tracker-t1000e/variant.h ?

[cracky22]

DEBUG | 09:57:18 50 Radio wait to sleep, txEmpty=0

DEBUG | 09:57:18 50 Radio wait to sleep, txEmpty=0

DEBUG | 09:57:18 50 Radio wait to sleep, txEmpty=0

DEBUG | 09:57:18 50 Radio wait to sleep, txEmpty=0

DEBUG | 09:57:18 50 Radio wait to sleep, txEmpty=0

DEBUG | 09:57:18 50 Radio wait to sleep, txEmpty=0

DEBUG | 09:57:19 50 Radio wait to sleep, txEmpty=0

DEBUG | 09:57:19 50 Radio wait to sleep, txEmpty=0

DEBUG | 09:57:19 51 Radio wait to sleep, txEmpty=0

DEBUG | 09:57:19 51 Radio wait to sleep, txEmpty=0

[cracky22]

ERROR | 09:57:40 72 NOTE! Record critical error 2 at src/sleep.cpp:176

ERROR | 09:57:40 72 assert failed src/sleep.cpp: 177, vo

[fifieldt]

OK, interesting. I wonder if our GPS configuration is being lost while asleep. Then it starts back up with every NMEA sequence enabled. Something like #5088

[cracky22]

wait i have some logs for you:
WARN | 10:35:20 2123 [GPS] GPS Buffer full with 1023 bytes waiting. Flush to avoid corruption
meshtastic-log-2025-01-11T09-57-08.007Z.log

[fifieldt]

Thanks for the logs @cracky22 .

So, the NMEA sequences are correct: GGA and RMC

Though, there are a few lines in there like the GPS just started up again (when it starts it announces its version info), like this:

DEBUG | 10:26:33 1597 [GPS] ..F1: 0000 0000..V0: 0000 0000 [0001]..00: 0000 0000..U0: 0000 0001 [0000]..T0: 0000 00B7..Leaving the BROM........8....~.....$PAIR001,002,1*38..$PAIR001,021,
DEBUG | 10:26:33 1597 [GPS] AGE: LOC=86851 FIX=0 DATE=86851 TIME=86851
DEBUG | 10:26:33 1597 [GPS] $PAIR011,001*27..$PAIR010,1,-1*16..$PAIR010,2,-1*15..$PAIR001,002,0*39..$PAIR001,021,0*38..$PAIR021,AG3335M_V2.6.0.AG3335_20221230,S,I,cfced9e,2212300120,,,,,
DEBUG | 10:26:34 1598 [GPS] $GNGGA,092634.784,,,,,0,0,,,M,,M,,*57..$GNRMC,092634.784,V,,,,,,,110125,,,N,V*2E..
DEBUG | 10:26:35 1598 [RadioIf] Started Tx (id=0x54894424 fr=0x1d698c30 to=0xffffffff, WantAck=0, HopLim=0 Ch=0x8 encrypted len=50 rxtime=1736586913 rxSNR=10.5 rxRSSI=-45 hopStart=3 priority
DEBUG | 10:26:35 1598 [RadioIf] Packet TX: 608ms
DEBUG | 10:26:35 1599 [GPS] $GNGGA,092635.784,,,,,0,0,,,M,,M,,*56..$GNRMC,092635.784,V,,,,,,,110125,,,N,V*2F..
DEBUG | 10:26:35 1599 [RadioIf] Completed sending (id=0x54894424 fr=0x1d698c30 to=0xffffffff, WantAck=0, HopLim=0 Ch=0x8 encrypted len=50 rxtime=1736586913 rxSNR=10.5 rxRSSI=-45 hopStart=3 p
DEBUG | 10:26:35 1599 [RadioIf] rx_snr found. hop_limit:6 rx_snr:11.000000
DEBUG | 10:26:35 1599 [RadioIf] rx_snr found in packet. Setting tx delay:1309
DEBUG | 10:26:36 1600 [GPS] $GNGGA,092636.752,,,,,0,0,,,M,,M,,*5E..$GNRMC,092636.752,V,,,,,,,110125,,,N,V*27..
DEBUG | 10:26:37 1600 [RadioIf] Started Tx (id=0xc12a0b5f fr=0xda547a28 to=0xffffffff, WantAck=0, HopLim=6 Ch=0x8 encrypted len=91 rxtime=1736586930 rxSNR=11 rxRSSI=-38 hopStart=7 priority=6
DEBUG | 10:26:37 1600 [RadioIf] Packet TX: 911ms
DEBUG | 10:26:37 1601 [GPS] $PAIR001,021,0*38..$PAIR021,AG3335M_V2.6.0.AG3335_20221230,S,I,cfced9e,2212300120,a2b7,0,,,735e4e5a,2212300107,e951622,2212300116,,,,,-15.48,-15.48,-14.02,-15
DEBUG | 10:26:37 1601 [RadioIf] Completed sending (id=0xc12a0b5f fr=0xda547a28 to=0xffffffff, WantAck=0, HopLim=6 Ch=0x8 encrypted len=91 rxtime=1736586930 rxSNR=11 rxRSSI=-38 hopStart=7 pri
DEBUG | 10:26:37 1601 [RadioIf] rx_snr found. hop_limit:5 rx_snr:8.750000
DEBUG | 10:26:37 1601 [RadioIf] rx_snr found in packet. Setting tx delay:5467
WARN  | 10:26:38 1601 [Position] Ch. util >25%. Skip send
DEBUG | 10:26:38 1602 [GPS] $PAIR010,0,0,2348,552415*34..
DEBUG | 10:26:38 1602 [GPS] $GNGGA,092638.758,4810.1629,N,01149.1463,E,1,8,1.11,518.3,M,47.4,M,,*43..$GNRMC,092638.758,A,4810.1629,N,01149.1463,E,0.44,0.00,110125,,,A,V*0C..
INFO  | 10:27:10 1634 [GPS] toRadioWriteCb data 0x20014b9a, len 2

[fifieldt]

OK,so I read the logs from 10:00 to 10:10 and it all looks good. Then out of the blue, we get our buffer error. There aren't too many messages going on, so it looks like the buffer is not getting cleared properly. We probably need to clear it before sleep or something like that.

Next step: reading the code.