search

meshtastic / firmware

Meshtastic device firmware
https://meshtastic.org
GNU General Public License v3.0
3.35k stars 816 forks source link

[Bug]: Odd behavior of GPS #4067

Closed GPSFan closed 3 months ago

GPSFan commented 3 months ago

Category

Other

Hardware

Other

Firmware Version

Latest master

Description

With the GPS Update interval set to 10, it appears as though the GPS is cycled every second. This commit is responsible: https://github.com/meshtastic/firmware/commit/da5bca31edcd091b33d1e6b9b35ea6f807850eb0 Reverting it results in "normal" GPS behavior, i.e. the GPS is cycled every 10 seconds.

Attached serial logs shows the effect. I have only noticed this recently on my Chatter 2 device (ESP32 with 1262 Lora and M8N GPS. Each of the attached serial logs are with the same Position Settings in Radio Configuration.

Relevant log output

******************************
Current master:
******************************

INFO  | 02:57:14 14 From Radio onread
DEBUG | 02:57:15 15 [GPS] WANT GPS=0
DEBUG | 02:57:15 15 [GPS] GPS Lock took 15, average 11
DEBUG | 02:57:15 15 [GPS] publishing pos@66666b8c:2, hasVal=1, Sats=8, GPSlock=1
DEBUG | 02:57:15 15 [GPS] New GPS pos@66666b8c:3 lat=38.898273, lon=-107.574069, alt=1915, pdop=1.52, trac8
DEBUG | 02:57:15 15 [GPS] onGPSChanged() pos@66666b8c, time=1717988235, lat=388982728, lon=-1075740688, al5
INFO  | 02:57:15 15 [GPS] updatePosition LOCAL pos@66666b8c, time=1717988235, latI=388982728, lonI=-1075745
DEBUG | 02:57:15 15 [GPS] Setting local position: latitude=388982728, longitude=-1075740688, time=171798826
DEBUG | 02:57:15 15 [GPS] Node status update: 2 online, 4 total
DEBUG | 02:57:15 15 [GPS] WANT GPS=0
DEBUG | 02:57:15 15 [GPS] GPS Lock took 15, average 12
DEBUG | 02:57:15 15 [GPS] publishing pos@66666b8c:2, hasVal=1, Sats=8, GPSlock=1
ERROR | 02:57:15 15 [GPS] BUG: Positional timestamp unchanged from prev solution
DEBUG | 02:57:15 15 [GPS] New GPS pos@66666b8c:3 lat=38.898273, lon=-107.574069, alt=1917, pdop=1.52, trac8
DEBUG | 02:57:15 15 [GPS] onGPSChanged() pos@66666b8c, time=1717988235, lat=388982728, lon=-1075740688, al7
INFO  | 02:57:15 15 [GPS] updatePosition LOCAL pos@66666b8c, time=1717988235, latI=388982728, lonI=-1075747
DEBUG | 02:57:15 15 [GPS] Setting local position: latitude=388982728, longitude=-1075740688, time=171798826
DEBUG | 02:57:15 15 [GPS] Node status update: 2 online, 4 total
DEBUG | 02:57:16 16 [GPS] WANT GPS=0
DEBUG | 02:57:16 16 [GPS] GPS Lock took 16, average 12
DEBUG | 02:57:16 16 [GPS] publishing pos@66666b8d:2, hasVal=1, Sats=9, GPSlock=1
DEBUG | 02:57:16 16 [GPS] New GPS pos@66666b8d:3 lat=38.898270, lon=-107.574074, alt=1916, pdop=1.29, trac9
DEBUG | 02:57:16 16 [GPS] onGPSChanged() pos@66666b8d, time=1717988236, lat=388982698, lon=-1075740736, al6
INFO  | 02:57:16 16 [GPS] updatePosition LOCAL pos@66666b8d, time=1717988236, latI=388982698, lonI=-1075746
DEBUG | 02:57:16 16 [GPS] Setting local position: latitude=388982698, longitude=-1075740736, time=171798827
DEBUG | 02:57:16 16 [GPS] Node status update: 2 online, 4 total
DEBUG | 02:57:17 17 [GPS] WANT GPS=0
DEBUG | 02:57:17 17 [GPS] GPS Lock took 17, average 12
DEBUG | 02:57:17 17 [GPS] publishing pos@66666b8e:2, hasVal=1, Sats=9, GPSlock=1
DEBUG | 02:57:17 17 [GPS] New GPS pos@66666b8e:3 lat=38.898270, lon=-107.574079, alt=1916, pdop=1.29, trac9
DEBUG | 02:57:17 17 [GPS] onGPSChanged() pos@66666b8e, time=1717988237, lat=388982703, lon=-1075740790, al6
INFO  | 02:57:17 17 [GPS] updatePosition LOCAL pos@66666b8e, time=1717988237, latI=388982703, lonI=-1075746
DEBUG | 02:57:17 17 [GPS] Setting local position: latitude=388982703, longitude=-1075740790, time=171798828
DEBUG | 02:57:17 17 [GPS] Node status update: 2 online, 4 total

*************************************
Commit reverted:
*************************************

INFO  | 12:33:41 634 [GPS] updatePosition LOCAL pos@6666f2a6, time=1718022821, latI=388982206, lonI=-1075740540, alt=1909
DEBUG | 12:33:41 634 [GPS] Setting local position: latitude=388982206, longitude=-1075740540, time=1718022821, timestamp=17182
DEBUG | 12:33:41 634 [GPS] Node status update: 1 online, 4 total
DEBUG | 12:33:50 643 [Power] Battery: usbPower=1, isCharging=1, batMv=5083, batPct=100
DEBUG | 12:33:51 644 [GPS] WANT GPS=1
INFO  | 12:33:51 644 [GPS] Setting GPS power=1
DEBUG | 12:33:52 645 [GPS] WANT GPS=0
DEBUG | 12:33:52 645 [GPS] GPS Lock took 0, average 0
DEBUG | 12:33:52 645 [GPS] publishing pos@6666f2b1:2, hasVal=1, Sats=12, GPSlock=1
DEBUG | 12:33:52 645 [GPS] New GPS pos@6666f2b1:3 lat=38.898205, lon=-107.574055, alt=1907, pdop=1.21, track=290.38, speed=0.2
DEBUG | 12:33:52 645 [GPS] onGPSChanged() pos@6666f2b1, time=1718022832, lat=388982050, lon=-1075740546, alt=1907
INFO  | 12:33:52 645 [GPS] updatePosition LOCAL pos@6666f2b1, time=1718022832, latI=388982050, lonI=-1075740546, alt=1907
DEBUG | 12:33:52 645 [GPS] Setting local position: latitude=388982050, longitude=-1075740546, time=1718022832, timestamp=17183
DEBUG | 12:33:52 645 [GPS] Node status update: 1 online, 4 total
INFO  | 12:33:54 647 [DeviceTelemetryModule] (Sending): air_util_tx=0.000000, channel_utilization=0.000000, battery_level=1017
DEBUG | 12:33:54 647 [DeviceTelemetryModule] updateTelemetry LOCAL
DEBUG | 12:33:54 647 [DeviceTelemetryModule] Node status update: 1 online, 4 total
INFO  | 12:33:54 647 [DeviceTelemetryModule] Sending packet to phone
INFO  | 12:33:54 647 Telling client we have new packets 27
INFO  | 12:33:54 647 BLE notify fromNum
INFO  | 12:33:54 647 From Radio onread
INFO  | 12:33:54 647 getFromRadio=STATE_SEND_PACKETS
DEBUG | 12:33:54 647 phone downloaded packet (id=0x79deac9d fr=0x48 to=0xff, WantAck=0, HopLim=3 Ch=0x0 Portnum=67 rxtime=171)
DEBUG | 12:33:54 647 encoding toPhone packet to phone variant=2, 49 bytes
INFO  | 12:33:54 647 From Radio onread
DEBUG | 12:34:02 655 [GPS] WANT GPS=1
INFO  | 12:34:02 655 [GPS] Setting GPS power=1
DEBUG | 12:34:03 656 [GPS] WANT GPS=0
DEBUG | 12:34:03 656 [GPS] GPS Lock took 0, average 0
DEBUG | 12:34:03 656 [GPS] publishing pos@6666f2bc:2, hasVal=1, Sats=12, GPSlock=1
DEBUG | 12:34:03 656 [GPS] New GPS pos@6666f2bc:3 lat=38.898193, lon=-107.574085, alt=1910, pdop=1.21, track=290.38, speed=0.2
DEBUG | 12:34:03 656 [GPS] onGPSChanged() pos@6666f2bc, time=1718022843, lat=388981930, lon=-1075740853, alt=1910
INFO  | 12:34:03 656 [GPS] updatePosition LOCAL pos@6666f2bc, time=1718022843, latI=388981930, lonI=-1075740853, alt=1910
DEBUG | 12:34:03 656 [GPS] Setting local position: latitude=388981930, longitude=-1075740853, time=1718022843, timestamp=17184
DEBUG | 12:34:03 656 [GPS] Node status update: 1 online, 4 total
DEBUG | 12:34:10 663 [Power] Battery: usbPower=1, isCharging=1, batMv=5089, batPct=100
DEBUG | 12:34:13 666 [GPS] WANT GPS=1
INFO  | 12:34:13 666 [GPS] Setting GPS power=1
DEBUG | 12:34:14 667 [GPS] WANT GPS=0
DEBUG | 12:34:14 667 [GPS] GPS Lock took 0, average 0
DEBUG | 12:34:14 667 [GPS] publishing pos@6666f2c7:2, hasVal=1, Sats=12, GPSlock=1
DEBUG | 12:34:14 667 [GPS] New GPS pos@6666f2c7:3 lat=38.898205, lon=-107.574084, alt=1910, pdop=1.02, track=290.38, speed=0.2
DEBUG | 12:34:14 667 [GPS] onGPSChanged() pos@6666f2c7, time=1718022854, lat=388982053, lon=-1075740843, alt=1910
INFO  | 12:34:14 667 [GPS] updatePosition LOCAL pos@6666f2c7, time=1718022854, latI=388982053, lonI=-1075740843, alt=1910
DEBUG | 12:34:14 667 [GPS] Setting local position: latitude=388982053, longitude=-1075740843, time=1718022854, timestamp=17185
DEBUG | 12:34:14 667 [GPS] Node status update: 1 online, 4 total
INFO  | 12:34:20 673 [PositionModule] Sending pos@6666f2c7:6 to mesh (wantReplies=0)
DEBUG | 12:34:20 673 [PositionModule] cancelSending id=0x79deac9c, removed=0
DEBUG | 12:34:20 673 [PositionModule] Sending location with precision 32
INFO  | 12:34:20 673 [PositionModule] Providing time to mesh 1718022860
INFO  | 12:34:20 673 [PositionModule] Position reply: time=1718022860, latI=388982053, lonI=-1075740843
DEBUG | 12:34:20 673 [PositionModule] Update DB node 0xb2a56448, rx_time=1718022860
DEBUG | 12:34:20 673 [PositionModule] handleReceived(LOCAL) (id=0x79deac9e fr=0x48 to=0xff, WantAck=0, HopLim=3 Ch=0x0 Portnu)
DEBUG | 12:34:20 673 [PositionModule] No modules interested in portnum=3, src=LOCAL
DEBUG | 12:34:20 673 [PositionModule] localSend to channel 0
DEBUG | 12:34:20 673 [PositionModule] Add packet record (id=0x79deac9e fr=0x48 to=0xff, WantAck=0, HopLim=3 Ch=0x0 Portnum=3 )
DEBUG | 12:34:20 673 [PositionModule] Expanding short PSK #1
DEBUG | 12:34:20 673 [PositionModule] Using AES128 key!
DEBUG | 12:34:20 673 [PositionModule] ESP32 crypt fr=b2a56448, num=79deac9e, numBytes=36!
WARN  | 12:34:20 673 [PositionModule] send - lora tx disable because RegionCode_Unset
INFO  | 12:34:20 673 Telling client we have new packets 28
INFO  | 12:34:20 673 BLE notify fromNum
INFO  | 12:34:20 673 From Radio onread
INFO  | 12:34:20 673 getFromRadio=STATE_SEND_PACKETS
DEBUG | 12:34:20 673 encoding toPhone packet to phone variant=11, 14 bytes
INFO  | 12:34:20 673 From Radio onread
DEBUG | 12:34:24 677 [GPS] WANT GPS=1
INFO  | 12:34:24 677 [GPS] Setting GPS power=1
DEBUG | 12:34:25 678 [GPS] WANT GPS=0
DEBUG | 12:34:25 678 [GPS] GPS Lock took 0, average 0
DEBUG | 12:34:25 678 [GPS] publishing pos@6666f2d2:2, hasVal=1, Sats=12, GPSlock=1
DEBUG | 12:34:25 678 [GPS] New GPS pos@6666f2d2:3 lat=38.898180, lon=-107.574094, alt=1910, pdop=1.02, track=290.38, speed=0.2
DEBUG | 12:34:25 678 [GPS] onGPSChanged() pos@6666f2d2, time=1718022865, lat=388981801, lon=-1075740940, alt=1910
INFO  | 12:34:25 678 [GPS] updatePosition LOCAL pos@6666f2d2, time=1718022865, latI=388981801, lonI=-1075740940, alt=1910
DEBUG | 12:34:25 678 [GPS] Setting local position: latitude=388981801, longitude=-1075740940, time=1718022865, timestamp=17186
DEBUG | 12:34:25 678 [GPS] Node status update: 1 online, 4 total
DEBUG | 12:34:30 683 [Power] Battery: usbPower=1, isCharging=1, batMv=5092, batPct=100
todd-herbert commented 3 months ago

I think I did see this come up the other day on my T-Beam V1.2. I wasn't sure what to make of it, but I erased the flash and it seemed to go away. I didn't think anything more of it at the time..

I'll go see if I can reproduce this with the 10 second update interval