Re: [gpsd-users] Communication loss with GR-701W

[Benoît Thébaudeau]

Hi Gary,

Le 18/05/2019 à 20:46, Gary E. Miller a écrit :
> On Sat, 18 May 2019 14:14:12 +0200 (CEST)
> Benoît Thébaudeau <address@hidden> wrote:
> 
>> I'm using a Navisys GR-701W (u-blox 7, USB PL2303 interface) with
>> gpsd 3.18, PPS, and ntp 4.2.8p13.
> 
> 3.18 had a bug, which is why 3.18.1 cam out shortly therafter.

I've upgraded to 3.18.1, but it does not help.

>> Most of the time, this setup works fine, but from time to time, after
>> hotplugging the GR-701W module, gpsd switches to the UBX protocol,
>> then gpsd no longer indicates any received packets, as if the module
>> became quiet.
> 
> I have a number of GR-601W running.  I've not seen that problem.
> 
> When you hotplug the GPS gets reset to stored configuration.  You
> should check how you have your GPS configured.  It is easy to 
> program the u-blox to ouput no data on startup, that can cause
> issues.

Actually, there is data at the very beginning. See the log below.

>> The PPS continues to work fine, though (and the LED of
>> the module blinks normally). When this happens, right before the
>> issue, gpsd reports a warning containing an error, apparently sent by
>> the module. I cannot post the exact log right now, but this warning
>> looks like this: gpsd:WARN: TXT: trk tick error[...]
> 
> The exact error would be nice.  Better yet the full log.

Here is the full log:
8><----------------------------------------------------
# gpsd -N -D 5 /dev/ttyUSB0 
gpsd:INFO: launching (Version 3.18.1)
gpsd:IO: opening IPv4 socket
gpsd:IO: opening IPv6 socket
gpsd:INFO: listening on port 2947
gpsd:PROG: NTP: shmat(0,0,0) succeeded, segment 0
gpsd:PROG: NTP: shmat(32769,0,0) succeeded, segment 1
gpsd:PROG: shmget(0x47505344, 14024, 0666) for SHM export succeeded
gpsd:PROG: shmat() for SHM export succeeded, segment 196610
gpsd:INFO: stashing device /dev/ttyUSB0 at slot 0
gpsd:PROG: no /etc/gpsd/device-hook present, skipped running ACTIVATE hook
gpsd:INFO: SER: opening GPS data source type 3 at '/dev/ttyUSB0'
gpsd:INFO: SER: speed 9600, 8N1
gpsd:PROG: no probe matched...
gpsd:INFO: gpsd_activate(2): activated GPS (fd 5)
gpsd:PROG: PPS:/dev/ttyUSB0 chrony socket /var/run/chrony.ttyUSB0.sock doesn't 
exist
gpsd:PROG: KPPS:/dev/ttyUSB0 checking /sys/devices/virtual/pps/pps0/path, 
/dev/ttyUSB0
gpsd:INFO: KPPS:/dev/ttyUSB0 RFC2783 path:/dev/pps0, fd is 6
gpsd:INFO: KPPS:/dev/ttyUSB0 pps_caps 0x1133
gpsd:INFO: KPPS:/dev/ttyUSB0 have PPS_CANWAIT
gpsd:INFO: KPPS:/dev/ttyUSB0 kernel PPS will be used
gpsd:PROG: PPS:/dev/ttyUSB0 thread launched
gpsd:INFO: PPS:/dev/ttyUSB0 ntpshm_link_activate: 1
gpsd:INFO: device /dev/ttyUSB0 activated
gpsd:INFO: running with effective group ID 0
gpsd:INFO: running with effective user ID 0
gpsd:INFO: startup at 2019-05-20T15:19:07.000Z (1558365547)
gpsd:INFO: KPPS:/dev/ttyUSB0 kernel PPS timeout Interrupted system call
gpsd:PROG: switching to match packet type 1: 
$GPGSV,2,2,08,20,40,119,37,21,52,059,37,26,58,164,39,27,53,290,20*7C\x0d\x0a
gpsd:PROG: switch_driver(NMEA0183) called...
gpsd:PROG: selecting NMEA0183 driver...
gpsd:INFO: /dev/ttyUSB0 identified as type NMEA0183, 0 sec @ 9600bps
gpsd:PROG: => Probing for Garmin NMEA
gpsd:IO: SER: => GPS: $PGRMCE*0E\x0d\x0a
gpsd:IO: <= GPS: 
$GPGSV,2,2,08,20,40,119,37,21,52,059,37,26,58,164,39,27,53,290,20*7C
gpsd:WARN: GPGSV field 3 value of 8 != actual count 4
gpsd:INFO: Sats used (0):
gpsd:IO: <= GPS: $GPGLL,4708.40693,N,00141.93532,W,151907.00,A,A*79
gpsd:WARN: can't use GLL time until after ZDA or RMC has supplied a year.
gpsd:PROG: GPGLL sentence timestamped 151907.00.
gpsd:PROG: GPGLL starts a reporting cycle.
gpsd:PROG: => Probing for FV-18
gpsd:IO: SER: => GPS: $PFEC,GPint*58\x0d\x0a
gpsd:IO: <= GPS: $GPTXT,01,01,01,PGRM inv format*34
gpsd:WARN: TXT: Warning: PGRM inv format
gpsd:PROG: => Probing for Trimble Copernicus
gpsd:IO: SER: => GPS: $PTNLSNM,0139,01*5C\x0d\x0a
gpsd:IO: <= GPS: $GPTXT,01,01,01,PFEC inv format*2C
gpsd:WARN: TXT: Warning: PFEC inv format
gpsd:IO: <= GPS: $GPTXT,01,01,01,PTNL inv format*3A
gpsd:WARN: TXT: Warning: PTNL inv format
gpsd:IO: <= GPS: 
$GPRMC,151908.00,A,4708.40835,N,00141.94000,W,0.349,,200519,,,A*6F
gpsd:PROG: GPRMC sentence timestamped 151908.00.
gpsd:PROG: GPRMC starts a reporting cycle.
gpsd:PROG: tagged GLL as a cycle ender.
gpsd:PROG: NTP: ntpshm_put(/dev/ttyUSB0,-20)  1558365548.000000000 @  
1558365548.126265661
gpsd:IO: <= GPS: $GPVTG,,T,,M,0.349,N,0.647,K,A*28
gpsd:WARN: unknown sentence: "$GPVTG,,T,,M,0.349,N,0.647,K,A*28\x0d\x0a"
gpsd:PROG: => Probing for UBX
gpsd:PROG: => GPS: UBX class: 06, id: 00, len: 0, crc: 0618
gpsd:IO: SER: => GPS: b562060000000618
gpsd:IO: <= GPS: 
$GPGGA,151908.00,4708.40835,N,00141.94000,W,1,04,5.17,13.4,M,48.2,M,,*7D
gpsd:PROG: GPGGA sentence timestamped 151908.00.
gpsd:IO: <= GPS: $GPGSA,A,3,26,21,20,10,,,,,,,,,8.35,5.17,6.55*0D
gpsd:PROG: xxGSA sets mode 3
gpsd:IO: <= GPS: 
$GPGSV,2,1,08,07,14,322,,08,19,279,,10,25,145,40,16,81,252,22*76
gpsd:PROG: Partial satellite data (1 of 2).
gpsd:IO: <= GPS: 
$GPGSV,2,2,08,20,40,119,37,21,52,059,36,26,58,164,39,27,53,290,19*77
gpsd:INFO: PRN= 10 az=145 el=25 (0.519837, -0.742404, 0.422618)
gpsd:INFO: PRN= 20 az=119 el=40 (0.669998, -0.371386, 0.642788)
gpsd:INFO: PRN= 21 az= 59 el=52 (0.527725, 0.317089, 0.788011)
gpsd:INFO: PRN= 26 az=164 el=58 (0.146066, -0.509391, 0.848048)
gpsd:INFO: Sats used (4):
gpsd:IO: <= GPS: $GPGLL,4708.40835,N,00141.94000,W,151908.00,A,A*77
gpsd:PROG: GPGLL sentence timestamped 151908.00.
gpsd:PROG: GPGLL ends a reporting cycle.
gpsd:IO: UBX: len 28
gpsd:PROG: switching to match packet type 11: 
b5620600140001000000c008000080250000070003000000000092b5
gpsd:PROG: switch_driver(u-blox) called...
gpsd:PROG: selecting u-blox driver...
gpsd:INFO: /dev/ttyUSB0 identified as type u-blox, 1 sec @ 9600bps
gpsd:PROG: => GPS: UBX class: 0a, id: 04, len: 0, crc: 0e34
gpsd:IO: SER: => GPS: b5620a0400000e34
gpsd:PROG: => GPS: UBX class: 06, id: 16, len: 8, crc: 31e5
gpsd:IO: SER: => GPS: b56206160800030703000000000031e5
gpsd:PROG: => GPS: UBX class: 06, id: 00, len: 20, crc: a0a9
gpsd:IO: SER: => GPS: b5620600140001000000d0080000802500000700010000000000a0a9
gpsd:PROG: => GPS: UBX class: 0a, id: 04, len: 0, crc: 0e34
gpsd:IO: SER: => GPS: b5620a0400000e34
gpsd:PROG: => GPS: UBX class: 06, id: 01, len: 3, crc: 104b
gpsd:IO: SER: => GPS: b56206010300010401104b
gpsd:PROG: => GPS: UBX class: 06, id: 01, len: 3, crc: 124f
gpsd:IO: SER: => GPS: b56206010300010601124f
gpsd:PROG: => GPS: UBX class: 06, id: 01, len: 3, crc: 2c83
gpsd:IO: SER: => GPS: b562060103000120012c83
gpsd:PROG: => GPS: UBX class: 06, id: 01, len: 3, crc: 45ac
gpsd:IO: SER: => GPS: b5620601030001300a45ac
gpsd:PROG: => GPS: UBX class: 06, id: 01, len: 3, crc: 47b0
gpsd:IO: SER: => GPS: b5620601030001320a47b0
gpsd:PROG: => GPS: UBX class: 06, id: 01, len: 3, crc: 0d45
gpsd:IO: SER: => GPS: b562060103000101010d45
gpsd:PROG: => GPS: UBX class: 06, id: 01, len: 3, crc: 1d65
gpsd:IO: SER: => GPS: b562060103000111011d65
gpsd:IO: UBX: len 10
gpsd:IO: UBX: len 108
gpsd:IO: UBX checksum 0x1b85 over length 108, expecting 0x3030 (type 0x0a04)
gpsd:IO: <= GPS: $GPTXT,01,01,00,trk tick 2 96000 dt 23881*3A
gpsd:WARN: TXT: Error: trk tick 2 96000 dt 23881
gpsd:IO: <= GPS: $GPTXT,01,01,00,trk tick 3 144000 dt 8694*36
gpsd:WARN: TXT: Error: trk tick 3 144000 dt 8694
gpsd:IO: <= GPS: $GPTXT,01,01,00,trk tick 5 240000 dt 5595*38
gpsd:WARN: TXT: Error: trk tick 5 240000 dt 5595
gpsd:IO: UBX: len 10
gpsd:INFO: KPPS:/dev/ttyUSB0 kernel PPS timeout Connection timed out
gpsd:INFO: KPPS:/dev/ttyUSB0 kernel PPS timeout Connection timed out
gpsd:INFO: KPPS:/dev/ttyUSB0 kernel PPS timeout Connection timed out
gpsd:INFO: KPPS:/dev/ttyUSB0 kernel PPS timeout Connection timed out
gpsd:INFO: KPPS:/dev/ttyUSB0 kernel PPS timeout Connection timed out
gpsd:PROG: KPPS:/dev/ttyUSB0 assert  0.000000000, sequence: 0, clear   
1558365563.999509701, sequence: 1 - using: clear
gpsd:PROG: KPPS:/dev/ttyUSB0 Clear cycle: 1558365563999509, duration: 
1558365563999509 @  1558365563.999509701
gpsd:PROG: PPS:/dev/ttyUSB0 Clear cycle: 1558365563999509, duration: 
1558365563999509 @  1558365563.999509701
gpsd:PROG: KPPS:/dev/ttyUSB0 assert  1558365564.099519991, sequence: 1, clear   
1558365563.999509701, sequence: 1 - using: assert
gpsd:PROG: KPPS:/dev/ttyUSB0 Assert cycle: 1558365564099519, duration:  100010 
@  1558365564.099519991
gpsd:PROG: PPS:/dev/ttyUSB0 Assert cycle: 1558365564099519, duration:  100010 @ 
 1558365564.099519991
gpsd:PROG: PPS:/dev/ttyUSB0 Assert ignored Too long for 0.5Hz
gpsd:PROG: KPPS:/dev/ttyUSB0 assert  1558365564.099519991, sequence: 1, clear   
1558365565.000435576, sequence: 2 - using: clear
gpsd:PROG: KPPS:/dev/ttyUSB0 Clear cycle: 1000925, duration:  900915 @  
1558365565.000435576
gpsd:PROG: PPS:/dev/ttyUSB0 Clear cycle: 1000925, duration:  900915 @  
1558365565.000435576
gpsd:PROG: PPS:/dev/ttyUSB0 Clear timestamp out of range @  
1558365565.000435576 offset -16.000435576
gpsd:PROG: KPPS:/dev/ttyUSB0 assert  1558365565.100428226, sequence: 2, clear   
1558365565.000435576, sequence: 2 - using: assert
gpsd:PROG: KPPS:/dev/ttyUSB0 Assert cycle: 1000908, duration:   99992 @  
1558365565.100428226
gpsd:PROG: PPS:/dev/ttyUSB0 Assert cycle: 1000908, duration:   99992 @  
1558365565.100428226
gpsd:PROG: PPS:/dev/ttyUSB0 Assert ignored 1Hz trailing edge
gpsd:PROG: KPPS:/dev/ttyUSB0 assert  1558365565.100428226, sequence: 2, clear   
1558365566.000343288, sequence: 3 - using: clear
gpsd:PROG: KPPS:/dev/ttyUSB0 Clear cycle:  999907, duration:  899915 @  
1558365566.000343288
gpsd:PROG: PPS:/dev/ttyUSB0 Clear cycle:  999907, duration:  899915 @  
1558365566.000343288
gpsd:PROG: PPS:/dev/ttyUSB0 Clear timestamp out of range @  
1558365566.000343288 offset -17.000343288
gpsd:PROG: KPPS:/dev/ttyUSB0 assert  1558365566.100323788, sequence: 3, clear   
1558365566.000343288, sequence: 3 - using: assert
gpsd:PROG: KPPS:/dev/ttyUSB0 Assert cycle:  999895, duration:   99980 @  
1558365566.100323788
gpsd:PROG: PPS:/dev/ttyUSB0 Assert cycle:  999895, duration:   99980 @  
1558365566.100323788
gpsd:PROG: PPS:/dev/ttyUSB0 Assert ignored 1Hz trailing edge
gpsd:PROG: KPPS:/dev/ttyUSB0 assert  1558365566.100323788, sequence: 3, clear   
1558365567.000241476, sequence: 4 - using: clear
gpsd:PROG: KPPS:/dev/ttyUSB0 Clear cycle:  999898, duration:  899917 @  
1558365567.000241476
gpsd:PROG: PPS:/dev/ttyUSB0 Clear cycle:  999898, duration:  899917 @  
1558365567.000241476
gpsd:PROG: PPS:/dev/ttyUSB0 Clear timestamp out of range @  
1558365567.000241476 offset -18.000241476
gpsd:PROG: KPPS:/dev/ttyUSB0 assert  1558365567.100274586, sequence: 4, clear   
1558365567.000241476, sequence: 4 - using: assert
gpsd:PROG: KPPS:/dev/ttyUSB0 Assert cycle:  999950, duration:  100033 @  
1558365567.100274586
gpsd:PROG: PPS:/dev/ttyUSB0 Assert cycle:  999950, duration:  100033 @  
1558365567.100274586
gpsd:PROG: PPS:/dev/ttyUSB0 Assert ignored 1Hz trailing edge
gpsd:PROG: KPPS:/dev/ttyUSB0 assert  1558365567.100274586, sequence: 4, clear   
1558365568.000137270, sequence: 5 - using: clear
gpsd:PROG: KPPS:/dev/ttyUSB0 Clear cycle:  999895, duration:  899862 @  
1558365568.000137270
gpsd:PROG: PPS:/dev/ttyUSB0 Clear cycle:  999895, duration:  899862 @  
1558365568.000137270
gpsd:PROG: PPS:/dev/ttyUSB0 Clear timestamp out of range @  
1558365568.000137270 offset -19.000137270
gpsd:PROG: KPPS:/dev/ttyUSB0 assert  1558365568.100126893, sequence: 5, clear   
1558365568.000137270, sequence: 5 - using: assert
gpsd:PROG: KPPS:/dev/ttyUSB0 Assert cycle:  999852, duration:   99989 @  
1558365568.100126893
gpsd:PROG: PPS:/dev/ttyUSB0 Assert cycle:  999852, duration:   99989 @  
1558365568.100126893
gpsd:PROG: PPS:/dev/ttyUSB0 Assert ignored 1Hz trailing edge
8><----------------------------------------------------

As you can see, after the trk tick error, the only thing still working is the 
PPS.

>> Restarting gpsd does not help. In this case, gpsd starts directly
>> with UBX, and the PPS still works, but that's all.
> 
> Have you tried ubxtool to reset the configuration?

Is it safe? I mean, I do not know the configuration the GR-701W ships with, nor 
if gpsd may change this configuration on its own, so I do not want to risk 
getting a malfunction because of this.

>> I have a few ideas to debug this using the gpsd debug log, gpsmon, a
>> USB sniffer, or ubxtool/u-center, but it won't be easy if it's
>> something going on inside the module. Perhaps sending a hot hardware
>> reset command to the module could be a good workaround.
> 
> Sending different types of reset is easy with ubxtool.

Sending a MON-HW2 poll (echo -ne '\xb5\x62\x0a\x0b\x00\x00\x15\x49' > 
/dev/ttyUSB0) results in:
00000000  b5 62 0a 0b 1c 00 fa 61  0f 5f 70 00 00 00 ff ff  |.b.....a._p.....|
00000010  ff ff ff ff ff ff ff ff  ff ff 00 00 00 00 00 00  |................|
00000020  00 00 5e 0f                                       |..^.|

So the module replies properly, which means that the baudrate is correct on 
both sides. But it does not talk more after having sent this command.

I still have to dump the whole internal state of the module to see if it 
reports anything abnormal.

Sending a CFG-RST/hotstart/HWreset (echo -ne 
'\xb5\x62\x06\x04\x04\x00\x00\x00\x00\x00\x0e\x64' > /dev/ttyUSB0) makes the 
module recover, but the issue can then still happen after replugging the module 
a few times.

I cannot succeed in duplicating the issue when stracing gpsd, which may 
indicate that it is timing-related.

> Also, since this happens on hotplug, how is your udevd setup?

I'm just using the SysV gpsd.hotplug and 25-gpsd.rules installed by gpsd 3.18.1.

Thanks

Best regards,
Benoît