Re: [gpsd-dev] Major progress!

[Eric S. Raymond]

Greg Troxel <address@hidden>:
> bisect fingers
> 
> commit 156c381715e13466682af32d284ee1c684b0de96
> Author: Eric S. Raymond <address@hidden>
> Date:   Mon Feb 9 06:13:31 2015 -0500
> 
> which doesn't make a lot of sense.

Actually, that's a pretty good clue to what's going on.  There used to be
two ways a test could terminate:

(1) gpsd recognizes a final "# EOF\n" comment packet injected by gpsfake.
    It shuts down the device pty.

(2) gpsd waits on select.  The test code notices it has run out of data.  After
    a timeout of CLOSE_DELAY it removes the device.  This is the code path that
    produced flaky errors.

You've fingered the commit where method 2 was removed.
 
> Your commit message said "all regression tests pass", but of course that
> isn't true :-)   What platforms did you actually test on (and it would
> be good to note that in the commit message)?

My main development machine of course, under Linux.  If I check out
that commit and run 

gpsfake -D 10 -p -1 test/daemon/bu303-stillfix.log

here's what the tail of the log looks like (wuth comments interspersed, led
with ;;):


gpsd:UNK: 00004848: character '.' [b3], SIRF_TRAILER_1 -> SIRF_RECOGNIZED
gpsd:UNK: Packet type 4 accepted 99 = 
a0a2005b2900000000012e17ba3d050000000000000000000000001bb710440482b37c00021f5200020c8c00000000000000000000000000010a000001e500000000000000000000000000000000000000000000000000000000000000004f0693b0b3

;; Lexer went to strate SIRF_RECOGNIZED, meaning it sees a complete SiRF 
;; binary packet.  That is accepted and placed in the lexer's output buffer

gpsd:UNK: Packet discard of 99, chars remaining is 6 = # EOF\x0a
gpsd:RAW: /dev/pts/9 is known to be SiRF
gpsd:RAW: window average of received byte count is 70.250000
gpsd:UNK: /dev/pts/9 sent 99 new characters
gpsd:RAW: packet sniff on /dev/pts/9 finds type 4
gpsd:RAW: raw packet of type 4, 
99:a0a2005b2900000000012e17ba3d050000000000000000000000001bb710440482b37c00021f5200020c8c00000000000000000000000000010a000001e500000000000000000000000000000000000000000000000000000000000000004f0693b0b3
gpsd:RAW: SiRF: Raw packet type 0x29
gpsd:PROG: SiRF: unused GND 0x29
gpsd:DATA: packet type 4 from /dev/pts/9 with {ONLINE|PACKET}
gpsd:UNK: Read 0 chars to buffer offset 6 (total 6): # EOF\x0a

;; The SiRF packet is a GND and is ignored. "# EOF\n" remains in the input
;; buffer - that is the stop packet injected by gpsfake.

gpsd:SPIN: packet_get() fd 10 -> 0 (0)
gpsd:UNK: 00004848: character '#' [23]  pushed back, state set to GROUND_STATE
gpsd:UNK: 00004848: character '#' [23], GROUND_STATE -> COMMENT_BODY
gpsd:UNK: 00004849: character ' ' [20], COMMENT_BODY -> COMMENT_BODY
gpsd:UNK: 00004850: character 'E' [45], COMMENT_BODY -> COMMENT_BODY
gpsd:UNK: 00004851: character 'O' [4f], COMMENT_BODY -> COMMENT_BODY
gpsd:UNK: 00004852: character 'F' [46], COMMENT_BODY -> COMMENT_BODY
gpsd:UNK: 00004853: character '.' [0a], COMMENT_BODY -> COMMENT_RECOGNIZED
gpsd:UNK: Packet type 0 accepted 6 = # EOF\x0a

;; The lexer sees # in state SIRF_RECOGNIZED, pushes it back, and drops to
;; GROUND_STATE.  This is where it is ready to recognize any kind of packet
;; start.

gpsd:UNK: Packet discard of 6, chars remaining is 0 = # EOF\x0a
gpsd:RAW: /dev/pts/9 is known to be SiRF
gpsd:RAW: window average of received byte count is 6.000000
gpsd:UNK: /dev/pts/9 sent 6 new characters
gpsd:RAW: packet sniff on /dev/pts/9 finds type 0
gpsd:PROG: synthetic EOF
gpsd:WARN: device signed off /dev/pts/9

;; gpsd recognizes a synthetic EOF

gpsd:CLIENT: => client(0): 
{"class":"DEVICE","path":"/dev/pts/9","activated":0}\x0d\x0a
gpsd:INFO: closing GPS=/dev/pts/9 (10)
{"class":"DEVICE","path":"/dev/pts/9","activated":0}
gpsd:SPIN: close(10) in gpsd_close(/dev/pts/9)

;; It ships a device-close notification to all watchers, then closes
;; the device.

gpsd:PROG: no /etc/gpsd/device-hook present, skipped running DEACTIVATE hook
gpsd:UNK: select waits
gpsd:SPIN: select() {6 7 8 9} -> { 6 } at 1423504701.449384 (errno 0)
gpsd:INFO: control socket connect on fd 10
gpsd:CLIENT: <= control(10): -/dev/pts/9\x0d\x0a
gpsd:INFO: <= control(10): removing /dev/pts/9
gpsd:CLIENT: => client(0): 
{"class":"DEVICE","path":"/dev/pts/9","activated":0}\x0d\x0a
gpsd:SPIN: close(10) of control socket
gpsd:UNK: select waits
{"class":"DEVICE","path":"/dev/pts/9","activated":0}

;; gpsfake receives the device-closed notification...

gpsd:WARN: received terminating signal 15.

;; ...because no active devices remain, it signals the slave gpsd,

gpsd:WARN: exiting.
gpsd:SPIN: close(9) in detach_client()
gpsd:INFO: detaching 127.0.0.1 (sub 0, fd 9) in detach_client

;; Which then exits.

What we need to figure out is where in this shutdown sequence things are
going awry.  You should run 

gpsfake -D 10 -p -1 test/daemon/bu303-stillfix.log

and compare the tail of the log with this. 
-- 
                <a href="http://www.catb.org/~esr/";>Eric S. Raymond</a>

signature.asc
Description: Digital signature