gpsd-users
[Top][All Lists]
Advanced

[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index]

Re: Analysis of log files: Dire Wolf 1.7, libgps.so.29, gpsd 3.23.2~dev,


From: Don Rolph
Subject: Re: Analysis of log files: Dire Wolf 1.7, libgps.so.29, gpsd 3.23.2~dev, MT3333 gps
Date: Wed, 5 Jan 2022 14:38:20 -0500

email to gps users rejected because of size of log files.

Log files in zip format attached.

Change extension from zi_ to zip.

On Wed, Jan 5, 2022 at 12:11 PM Don Rolph <don.rolph@gmail.com> wrote:
Ok I have done a preliminary review of the log files at the time of the message storm in Dire Wolf.  log files dire3.log, gpsd3.log. and nmea3.log attached for independent review.

It is perhaps easiest to track the behavior by first reviewing the direwolf log file, dire3.log.  This was captured using the command:

direwolf -t 0 -d g > dire3.log

One can see the behavior of the packets around the time of gps fix:

gps_read: time=1641399042 fix=1 lat=-999999.000000 lon=-999999.000000 trk=-999999 spd=-999999.0 alt=-999999
gps_read: time=1641399044 fix=1 lat=-999999.000000 lon=-999999.000000 trk=-999999 spd=-999999.0 alt=-999999
gps_read: time=1641399046 fix=1 lat=-999999.000000 lon=-999999.000000 trk=-999999 spd=-999999.0 alt=-999999
GPSD: Location fix is now 3D.
gps_read: time=1641399048 fix=3 lat=42.147532 lon=-71.226743 trk=nan spd=nan alt=108
gps_read: time=1641399048 fix=3 lat=42.147532 lon=-71.226743 trk=nan spd=nan alt=108
gps_read: time=1641399048 fix=3 lat=42.147532 lon=-71.226743 trk=nan spd=nan alt=108
gps_read: time=1641399048 fix=3 lat=42.147532 lon=-71.226743 trk=nan spd=nan alt=108

One observes before gps fix, time is incrementing by 2 at each entry.  After gps fix, we have about 100 messages all with the same time stamp.

After about 100 messages in the log we see:

gps_read: time=1641399048 fix=3 lat=42.147532 lon=-71.226743 trk=nan spd=nan alt=108
gps_read: time=1641399048 fix=3 lat=42.147532 lon=-71.226743 trk=nan spd=nan alt=108
gps_read: time=1641399048 fix=3 lat=42.147532 lon=-71.226743 trk=nan spd=nan alt=108
gps_read: time=1641399048 fix=3 lat=42.147532 lon=-71.226743 trk=nan spd=nan alt=108
Transmit packet queue for channel 0 is too long.  Discarding packet.
Perhaps the channel is so busy there is no opportunity to send.
gps_read: time=1641399048 fix=3 lat=42.147532 lon=-71.226743 trk=nan spd=nan alt=108
Transmit packet queue for channel 0 is too long.  Discarding packet.
Perhaps the channel is so busy there is no opportunity to send.
gps_read: time=1641399048 fix=3 lat=42.147532 lon=-71.226743 trk=nan spd=nan alt=108
Transmit packet queue for channel 0 is too long.  Discarding packet.

It appears that the Dire Wolf internal message queue has filled and messages are discarded.  This appears to limit the aprs messages to on the order of 101 (although this can vary slightly).

Looking at the gpsd messages in gpsd3.log at the time of fix:

{"class":"TPV","device":"/dev/ttyUSB0","mode":1,"time":"2022-01-05T16:10:44.086Z","ept":0.005}
{"class":"GST","device":"/dev/ttyUSB0","time":"2022-01-05T16:10:44.086Z","rms":0.000,"major":99999.000,"minor":99999.000,"orient":0.000,"lat":99999.000,"lon":99999.000,"alt":99999.000}
{"class":"TPV","device":"/dev/ttyUSB0","mode":1,"time":"2022-01-05T16:10:45.086Z","ept":0.005}
{"class":"GST","device":"/dev/ttyUSB0","time":"2022-01-05T16:10:45.086Z","rms":0.000,"major":99999.000,"minor":99999.000,"orient":0.000,"lat":99999.000,"lon":99999.000,"alt":99999.000}
{"class":"TPV","device":"/dev/ttyUSB0","mode":1,"time":"2022-01-05T16:10:46.086Z","ept":0.005}
{"class":"GST","device":"/dev/ttyUSB0","time":"2022-01-05T16:10:46.086Z","rms":0.000,"major":99999.000,"minor":99999.000,"orient":0.000,"lat":99999.000,"lon":99999.000,"alt":99999.000}
{"class":"TPV","device":"/dev/ttyUSB0","mode":1,"time":"2022-01-05T16:10:47.086Z","ept":0.005}
{"class":"GST","device":"/dev/ttyUSB0","time":"2022-01-05T16:10:47.086Z","rms":0.000,"major":99999.000,"minor":99999.000,"orient":0.000,"lat":99999.000,"lon":99999.000,"alt":99999.000}
{"class":"TPV","device":"/dev/ttyUSB0","mode":3,"time":"2022-01-05T16:10:48.086Z","ept":0.005,"lat":42.147531667,"lon":-71.226743333,"altHAE":73.6000,"altMSL":107.5000,"alt":107.5000,"magvar":-14.4,"geoidSep":-33.900,"eph":32.110}
{"class":"GST","device":"/dev/ttyUSB0","time":"2022-01-05T16:10:48.086Z","rms":0.000,"major":35.000,"minor":21.000,"orient":23.700,"lat":33.000,"lon":24.000,"alt":142.000}
{"class":"TPV","device":"/dev/ttyUSB0","mode":3,"time":"2022-01-05T16:10:50.000Z","ept":0.005,"lat":42.147530000,"lon":-71.226735000,"altHAE":75.7000,"altMSL":109.6000,"alt":109.6000,"epv":21.850,"magvar":-14.4,"speed":0.373,"climb":1.097,"epc":22.83,"geoidSep":-33.900,"eph":109.250,"sep":36.860}
{"class":"TPV","device":"/dev/ttyUSB0","mode":3,"time":"2022-01-05T16:10:50.000Z","ept":0.005,"lat":42.147530000,"lon":-71.226735000,"altHAE":75.7000,"altMSL":109.6000,"alt":109.6000,"epv":21.850,"track":338.8800,"magtrack":324.5025,"magvar":-14.4,"speed":0.195,"climb":1.097,"epc":22.83,"geoidSep":-33.900,"eph":109.250,"sep":36.860}
{"class":"GST","device":"/dev/ttyUSB0","time":"2022-01-05T16:10:50.000Z","rms":1.500,"major":32.000,"minor":20.000,"orient":27.000,"lat":30.000,"lon":23.000,"alt":130.000}
{"class":"TPV","device":"/dev/ttyUSB0","mode":3,"time":"2022-01-05T16:10:51.000Z","ept":0.005,"lat":42.147528333,"lon":-71.226735000,"altHAE":74.2000,"altMSL":108.1000,"alt":108.1000,"epv":22.080,"magvar":-14.4,"speed":0.185,"climb":-1.500,"epc":43.93,"geoidSep":-33.900,"eph":109.250,"sep":110.770}
{"class":"SKY","device":"/dev/ttyUSB0","xdop":7.07,"ydop":1.03,"vdop":0.96,"tdop":5.50,"hdop":5.75,"gdop":9.68,"pdop":5.83,"nSat":15,"uSat":4,"satellites":[{"PRN":31,"el":72.0,"az":282.0,"ss":28.0,"used":false,"gnssid":0,"svid":31},{"PRN":32,"el":67.0,"az":93.0,"ss":29.0,"used":true,"gnssid":0,"svid":32},{"PRN":25,"el":45.0,"az":62.0,"ss":24.0,"used":true,"gnssid":0,"svid":25},{"PRN":26,"el":29.0,"az":193.0,"ss":0.0,"used":false,"gnssid":0,"svid":26},{"PRN":51,"el":29.0,"az":227.0,"ss":0.0,"used":false,"gnssid":1,"svid":138},{"PRN":3,"el":18.0,"az":319.0,"ss":0.0,"used":false,"gnssid":0,"svid":3},{"PRN":1,"el":10.0,"az":281.0,"ss":0.0,"used":false,"gnssid":0,"svid":1},{"PRN":29,"el":8.0,"az":105.0,"ss":0.0,"used":false,"gnssid":0,"svid":29},{"PRN":21,"el":4.0,"az":261.0,"ss":0.0,"used":false,"gnssid":0,"svid":21},{"PRN":70,"el":82.0,"az":345.0,"ss":0.0,"used":false,"gnssid":6,"svid":6},{"PRN":69,"el":31.0,"az":137.0,"ss":21.0,"used":true,"gnssid":6,"svid":5},{"PRN":79,"el":28.0,"az":36.0,"ss":27.0,"used":true,"gnssid":6,"svid":15},{"PRN":88,"el":1.0,"az":21.0,"ss":0.0,"used":false,"gnssid":6,"svid":24},{"PRN":76,"el":0.0,"az":0.0,"ss":0.0,"used":false,"gnssid":6,"svid":12},{"PRN":71,"el":0.0,"az":0.0,"ss":26.0,"used":false,"gnssid":6,"svid":7}]}
{"class":"TPV","device":"/dev/ttyUSB0","mode":3,"time":"2022-01-05T16:10:51.000Z","ept":0.005,"lat":42.147528333,"lon":-71.226735000,"altHAE":74.2000,"altMSL":108.1000,"alt":108.1000,"epx":106.062,"epy":15.379,"epv":22.080,"track":338.8800,"magtrack":324.5025,"magvar":-14.4,"speed":0.195,"climb":-1.500,"epc":43.93,"geoidSep":-33.900,"eph":109.250,"sep":110.770}
{"class":"GST","device":"/dev/ttyUSB0","time":"2022-01-05T16:10:51.000Z","rms":1.100,"major":29.000,"minor":20.000,"orient":27.600,"lat":27.000,"lon":22.000,"alt":105.000}
{"class":"TPV","device":"/dev/ttyUSB0","mode":3,"time":"2022-01-05T16:10:52.000Z","ept":0.005,"lat":42.147525000,"lon":-71.226733333,"altHAE":72.9000,"altMSL":106.8000,"alt":106.8000,"epx":106.062,"epy":15.379,"epv":22.080,"magvar":-14.4,"speed":0.395,"climb":-1.300,"eps":212.12,"epc":44.16,"geoidSep":-33.900,"eph":109.250,"sep":110.770}
{"class":"TPV","device":"/dev/ttyUSB0","mode":3,"time":"2022-01-05T16:10:52.000Z","ept":0.005,"lat":42.147525000,"lon":-71.226733333,"altHAE":72.9000,"altMSL":106.8000,"alt":106.8000,"epx":106.062,"epy":15.379,"epv":22.080,"track":338.8800,"magtrack":324.5025,"magvar":-14.4,"speed":0.195,"climb":-1.300,"eps":212.12,"epc":44.16,"geoidSep":-33.900,"eph":109.250,"sep":110.770}
{"class":"GST","device":"/dev/ttyUSB0","time":"2022-01-05T16:10:52.000Z","rms":1.100,"major":26.000,"minor":19.000,"orient":30.000,"lat":25.000,"lon":21.000,"alt":89.000}

It appears that speed is not provided in the gpspipe -w file which shows up as speed="NaN" in the Dire Wolf logs.

There are also some PRN records which I have not perused.

I have not reviewed the NMEA files, since that is a gpsd internal behavior.

So:

Dire Wolf 1.7 with libgps.so.23, libgps.so.28, or libgps.so.29 all show basically the same behavior when reading gpsd during time of GPS fix with the MT3333 gps  unit.

This works as expected with gpsd 3.17 but not in gpsd 3.23.2~dev (or gpsd 3.22-400).

This suggests that a change in the message format going from 3.17 to 3.22-400 is triggering a problem in the Dire Wolf gpsd code which worked as expected under gpsd 3.17.

I will now start perusing the code, BUT I am quickly outrunning my area of expertise.

My thanks to all for their help so far!

 

--

73,
AB1PH
Don Rolph


--

73,
AB1PH
Don Rolph

Attachment: new-logs.zi_
Description: Binary data


reply via email to

[Prev in Thread] Current Thread [Next in Thread]