4G wrong time in Svalbard

[jdavid]

We have this in the log files from Svalbard:

2019-04-10 22:00:30.726000 DEBUG 2 frame(s) sent in 918 ms
2019-04-11 22:00:32.102000 INFO Loop done in 31683 ms
[...]
2019-04-12 00:01:49.792000 DEBUG 2 frame(s) sent in 940 ms
2019-04-11 00:01:51.104000 INFO Loop done in 110748 ms

At midnight (local time) the clock jumps 1 day to the future, and 2 hours later the clock is back to the right time.

The 4G networks was scheduled to run once every 2 hours.

[jdavid]

After quite some tests I'm pretty sure the code is correct. The value we're reading from the 4G module is bad, but we don't know which value it's because it's not logged.

And I've not reproduced the issue locally.

So it looks like the bug is in the 4G network in Svalbard, like the 4G operator is sending bad time data.

[jdavid]

The main changes from the commit pushed:

Workaround. Don't update the time at midnight local time. This way when deployed this issue should be fixed. But this should be considered a temporary fix.

Also, now we log the raw line we read from the 4G module. So when deployed and the SD card retrieved we will know exactly the bad data.

[jdavid]

Open questions:

• Do I fix the data in the server?
• Do we contact the 4G operator to report on the issue?

[jdavid]

Done today:

• Fixed data in the server with new command fix_sw002
• New command to analyse data from one mote, wsn_frames_analyze
• Added code to fix new data from sw-002 (to be verified)

TODO:

• Verify the new data is good
• Test the new code in Oslo, check the raw value read from the 4G module
• Contact the 4G operator, Telenor
• When the problem is fixed at the source, remove the online fix in the server

[johnhulth]

Could this be a time convention problem? One system is using 00:00:00-23:59:59 and the other uses 00:00:01-24:00:00.

2009:12:31:24:00:00 is the same time as 2010:01:01:00:00:00

[jdavid]

Please post the mote's log file, the exact value sent by the 4G network should be there, so we can know exactly what it is sending.

https://github.com/spectraphilic/wasp_sketches/blob/master/libraries/WaspUIO/network_4g.cpp#L193

[jdavid]

This is what we can see in the log files:

$ grep "4G time" test_4g_2/LOG.TXT
[...]
1565646403.695 DEBUG 4G time: 19/08/12,23:46:45+08"
1565647302.878 DEBUG 4G time: 19/08/14,00:01:43+08"
1565648203.100 DEBUG 4G time: 19/08/14,00:16:44+08"
1565649103.089 DEBUG 4G time: 19/08/14,00:31:44+08"
1565650002.249 DEBUG 4G time: 19/08/14,00:46:42+08"
1565650902.043 DEBUG 4G time: 19/08/14,01:01:42+08"
1565738202.542 DEBUG 4G time: 19/08/14,01:16:44+08"
1565739101.456 DEBUG 4G time: 19/08/14,01:31:42+08"
1565740002.530 DEBUG 4G time: 19/08/14,01:46:43+08"
1565740902.249 DEBUG 4G time: 19/08/13,02:01:44+08"
[...]

Fixed the workaround in commit 122f5a8 so we skip 2 hours instead of 1.

[jdavid]

To be clear this cannot be a code bug, ours or libelium's, as we're just sending the AT+CCLK? command to the LE9100 module and reading the raw value from the buffer.

So this can only be a bug in the LE9100 module or in the 4G network.

Actually I tested this in Spain in April and it worked, so this can only come from the 4G network in Norway (is it Telenor?):

(venv36) wsn@latice-vm:~/wsn_server$ python manage.py shell
[...]
In [1]: from wsn.models import Frame
In [2]: frames = Frame.objects.filter(metadata__name='v15@CS')
In [3]: frames = list(frames)
In [4]: frames = sorted(frames, key=lamda x: x.pk)
In [5]: for frame in frames:
    ...:     if 'remote_addr' in frame.data:
    ...:         time = datetime.datetime.utcfromtimestamp(frame.time)
    ...:         print(f'{time} pk={frame.pk} seq={frame.frame} bat={frame.bat}')
[...]
2019-04-12 18:09:54 pk=25511647 seq=0 bat=None
2019-04-12 18:10:00 pk=25511648 seq=1 bat=90
2019-04-12 18:20:00 pk=25511649 seq=2 bat=91
[...]
2019-04-12 23:40:00 pk=25523242 seq=34 bat=91
2019-04-12 23:50:00 pk=25523243 seq=35 bat=91
2019-04-13 00:00:00 pk=25523244 seq=36 bat=91
2019-04-13 00:10:00 pk=25529033 seq=37 bat=90
2019-04-13 00:20:00 pk=25529035 seq=38 bat=91
2019-04-13 00:30:00 pk=25529037 seq=39 bat=91
2019-04-13 00:40:00 pk=25529038 seq=40 bat=91
2019-04-13 00:50:00 pk=25529043 seq=41 bat=91
2019-04-13 01:00:00 pk=25529044 seq=42 bat=91
2019-04-13 01:10:00 pk=25529045 seq=43 bat=91
[...]
2019-04-13 10:40:00 pk=25705433 seq=100 bat=90
2019-04-13 10:50:00 pk=25705434 seq=101 bat=90
2019-04-13 11:00:00 pk=25705435 seq=102 bat=90
2019-04-13 11:10:00 pk=25705436 seq=103 bat=90
[...]