nRF badge skips time

[OrenLederman]

Badge time jumped to the future. This does not seem to be an hardware issue (battery level was within reason)

Data file, date skipped from 2016-03-10 to 2016-04-28 2016-03-10 22:20:34,2.56891489029,250,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,2,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1 2016-04-28 03:59:43,2.60410547256,250,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,2,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1

server log, did not send a new date in between 2016-03-10 22:21:37,858 - INFO - [D1:61:D8:00:57:61] Talking with D1:61:D8:00:57:61 2016-03-10 22:21:39,416 - INFO - [D1:61:D8:00:57:61] Connected 2016-03-10 22:21:39,543 - INFO - [D1:61:D8:00:57:61] Got status 2016-03-10 22:21:39,557 - INFO - [D1:61:D8:00:57:61] Already synced 2016-03-10 22:21:39,560 - INFO - [D1:61:D8:00:57:61] Requesting data... 2016-03-10 22:21:40,837 - INFO - [D1:61:D8:00:57:61] Waiting for more data... 2016-03-10 22:21:41,843 - INFO - [D1:61:D8:00:57:61] Waiting for more data... 2016-03-10 22:21:42,847 - INFO - [D1:61:D8:00:57:61] Waiting for more data... 2016-03-10 22:21:42,851 - INFO - [D1:61:D8:00:57:61] finished reading data 2016-03-10 22:21:42,869 - INFO - [D1:61:D8:00:57:61] disconnected 2016-03-10 22:21:42,872 - INFO - [D1:61:D8:00:57:61] Chunks received: 1 2016-03-10 22:21:42,876 - INFO - [D1:61:D8:00:57:61] saving chunks to file 2016-03-10 22:21:42,879 - INFO - [D1:61:D8:00:57:61] Chunk timestamp: 2016-03-10 22:20:34, Voltage: 2.56891489029, Samples in chunk: 116 2016-03-10 22:21:42,888 - INFO - [D1:61:D8:00:57:61] done writing 2016-03-10 22:21:44,899 - INFO - [None] Reading whitelist: 2016-03-10 22:21:44,904 - INFO - [None] D1:61:D8:00:57:61 2016-03-10 22:21:44,907 - INFO - [None] EC:21:82:A8:0B:59 2016-03-10 22:21:44,911 - INFO - [None] Scanning for devices... 2016-03-10 22:21:49,924 - DEBUG - [None] Found EC:21:82:A8:0B:59, added 2016-03-10 22:21:49,928 - DEBUG - [None] Found D1:61:D8:00:57:61, added 2016-03-10 22:21:49,931 - INFO - [None] Found: 2 devices 2016-03-10 22:21:51,935 - INFO - [None] Communicating with synced devices... ... 2016-03-10 22:21:59,312 - INFO - [D1:61:D8:00:57:61] Talking with D1:61:D8:00:57:61 2016-03-10 22:22:00,825 - INFO - [D1:61:D8:00:57:61] Connected 2016-03-10 22:22:00,963 - INFO - [D1:61:D8:00:57:61] Got status 2016-03-10 22:22:00,967 - INFO - [D1:61:D8:00:57:61] Already synced 2016-03-10 22:22:00,979 - INFO - [D1:61:D8:00:57:61] disconnected 2016-03-10 22:22:00,982 - INFO - [D1:61:D8:00:57:61] No data ready 2016-03-10 22:22:02,988 - INFO - [None] Reading whitelist: 2016-03-10 22:22:03,002 - INFO - [None] D1:61:D8:00:57:61 2016-03-10 22:22:03,016 - INFO - [None] EC:21:82:A8:0B:59 2016-03-10 22:22:03,019 - INFO - [None] Scanning for devices... 2016-03-10 22:22:08,064 - DEBUG - [None] Found EC:21:82:A8:0B:59, added 2016-03-10 22:22:08,078 - DEBUG - [None] Found D1:61:D8:00:57:61, added 2016-03-10 22:22:08,088 - INFO - [None] Found: 2 devices 2016-03-10 22:22:10,093 - INFO - [None] Communicating with synced devices... ... 2016-03-10 22:22:13,499 - INFO - [D1:61:D8:00:57:61] Talking with D1:61:D8:00:57:61 2016-03-10 22:22:15,666 - INFO - [D1:61:D8:00:57:61] Connected 2016-03-10 22:22:15,803 - INFO - [D1:61:D8:00:57:61] Got status 2016-03-10 22:22:15,807 - INFO - [D1:61:D8:00:57:61] Already synced 2016-03-10 22:22:15,810 - INFO - [D1:61:D8:00:57:61] Requesting data... 2016-03-10 22:22:17,088 - INFO - [D1:61:D8:00:57:61] Waiting for more data... 2016-03-10 22:22:18,092 - INFO - [D1:61:D8:00:57:61] Waiting for more data... 2016-03-10 22:22:19,097 - INFO - [D1:61:D8:00:57:61] Waiting for more data... 2016-03-10 22:22:19,101 - INFO - [D1:61:D8:00:57:61] finished reading data 2016-03-10 22:22:19,138 - INFO - [D1:61:D8:00:57:61] disconnected 2016-03-10 22:22:19,142 - INFO - [D1:61:D8:00:57:61] Chunks received: 1 2016-03-10 22:22:19,155 - INFO - [D1:61:D8:00:57:61] saving chunks to file 2016-03-10 22:22:19,159 - INFO - [D1:61:D8:00:57:61] Chunk timestamp: 2016-04-28 03:59:43, Voltage: 2.60410547256, Samples in chunk: 116 2016-03-10 22:22:19,174 - INFO - [D1:61:D8:00:57:61] done writing

[OrenLederman]

for reference, here's the first line from the log (so you'll know how long it was up): 2016-03-09 09:56:51,3.12492656708,250,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,4,2,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,2,1,2,1,2,2,9,1,1,1,1,1,1,1,1,1,1,1,1,1,1

[OrenLederman]

The problem appeared in a second badge as well. With the second badge, the RasPI crashed in the middle of the test (after 1.5 days). The logs before the scan shows the correct date, the logs right after the crash shows the faulty date.

I find it hard to believe that the crashed caused it, or that these two problems happened at the same time. I think that something in timekeeping of the badge changed. Perhaps we manipulate the date before sending it out to the server, and the stored data is actually correct?

[OrenLederman]

another example 2016-03-12 10:52:12,2.95249271393,250,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,2,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1 ... 2016-03-14 00:17:51,2.68504405022,250,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1 2016-05-01 04:57:00,2.67800593376,250,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1

[anguslocke]

For the two bug instances above:

-Seconds elapsed between first chunk and chunk just before time jump: 131,023; 134,739 ^^^ Accounting for DST (3600s), within ~2mins. i.e. the error probably happened the same elapsed time from power-on (one badge just got synced 2mins later). Maybe 2^17 = 131,072?

-Length of time jump, in seconds: 4,163,949; 4,167,549 ^^^ Accounting for DST (3600s), the jumps are exactly the same length. related to 2^22 = 4,194,304?

[OrenLederman]

FYI - if the server re-sends the datetime to the badge it uses the new date. Not sure if this information helps.