262 second offset occured with NAP ext event.

[denniszollo]

NAP counts rollover on 262 second boundaries. There must be some kind of bug in how the rollover is handled at this line. https://github.com/swift-nav/piksi_firmware/blob/master/src/ext_events.c#L77

Excerpt from SBP log is below. The TOW from a observation message was 257025600, and the external event message just after shows a TOW of 257288092. These are 262 seconds apart.

{"timestamp": 1445988208, "data": {"sender": 0, "msg_type": 67, "header": {"n_obs": 32, "t": {"wn": 1868, "tow": 257025600}}, "obs": [{"lock": 60663, "sid": 3, "L": {"i": 5 254360, "f": 219}, "cn0": 156, "P": 2579631556}, {"lock": 63282, "sid": 7, "L": {"i": 2517732, "f": 153}, "cn0": 192, "P": 2481446324}, {"lock": 36714, "sid": 10, "L": {"i" : 1077349, "f": 181}, "cn0": 172, "P": 2720787236}, {"lock": 49201, "sid": 13, "L": {"i": 2832033, "f": 25}, "cn0": 204, "P": 2300947201}, {"lock": 24986, "sid": 17, "L": { "i": -1906912, "f": 211}, "cn0": 202, "P": 2456336233}, {"lock": 19442, "sid": 20, "L": {"i": -2775210, "f": 94}, "cn0": 176, "P": 2522436919}], "crc": 5185, "length": 103, "preamble": 85, "payload": "QOZRD0wHIMQNwpnYLFAA25z37AMAAAC03eeT5GomAJnAMvcHAAAAJOsromVwEAC1rGqPCgAAAAGrJYmhNisAGcwxwA0AAABpt2iSIOfi/9PKmmERAAAAN1VZllan1f9esPJLFAAAAA=="}, "delta": 18642}
{"timestamp": 1445988208, "data": {"sender": 22754, "msg_type": 257, "wn": 1868, "tow": 257288092, "crc": 58161, "length": 12, "flags": 2, "pin": 0, "ns": 428682, "preamble ": 85, "payload": "TAec51UPiooGAAIA"}, "delta": 18690}

cc @henryhallam @fnoble @gsmcmullin @rai-swiftnav

[denniszollo]

Entire file is here for context.
practicehackathonlog2.txt

[denniszollo]

This seems to be a problem in the NAP external event stuff. See below how I am printing out the results of calling nap_rw_ext_event() (https://github.com/swift-nav/piksi_firmware/blob/master/src/board/nap/nap_common.c#L259) during an external event callback. You'll see here between subsequent calls this function goes from
Event nap time is 1910736386.
to
Event nap time is 1927513602.
then back to
Event nap time is 1913492602.
The exterior event code assumes that the event nap_timing_count is always increasing except during rollover.

/cc @soulcmdc @wltr @henryhallam @cbeighley

Any idea why the external event communication from the NAP would give a bogus number?

[denniszollo]

Here is another problem. We have 2 exterior events 10 seconds apart according to the hosts clocks (see timestamps in LH column), but the TOW given back by the NAP is identical.

[ljbade]

hmm that is wierd, where does it grab the current time from in the code?

[denniszollo]

It gets it from the NAPs external event register via SPI.

[ljbade]

Keep open until @denniszollo confirms it is fixed by #626

[jacobmcnamee]

The NAP latches the timing count every time a rising / falling (whatever is configured) edge occurs on the external event pin, sampled at 16MHz. It appears that the value output over SPI has no additional buffering and may change if a second edge occurs while the SPI transaction is in progress.

I'd say it is fairly likely that there is some amount of bounce on the external event input, causing the latched timing count to change while being read out over SPI.

[jacobmcnamee]

What we should be doing is latching the event time and level once and keeping them until the SPI transaction completes. Or if we want to get really sophisticated, push them to a FIFO.