SNTP originate timestamp mismatch when RRC state change

[Moustapha DIENG]

Hello,

I am currently using NCS version 1.6.1 with my modem's firmware version being 1.3.0.
I have encountered an issue while utilizing Zephyr's SNTP library to retrieve time from time.google.com.

Periodically, I am experiencing the following error:

net_sntp: Mismatch originate timestamp: -2085978480, expect: -2085978479

This error appears to originate from the parse_response(...) function in sntp.c.

Upon further investigation, I have observed that this error consistently occurs whenever there is a change in the
RRC state during the SNTP request. In over 20 instances of the error, the RRC state has indeed changed.

[00:01:44.449,462] <inf> app: SNTP request on time.google.com
[00:01:46.197,601] <inf> app: RRC mode: Idle
[00:01:46.333,679] <inf> app: RRC mode: Connected
[00:01:46.452,087] <err>app: Request failed with error -22 (the timestamp mismatch error)

I am reaching out to seek clarification on this phenomenon.
Could you provide insights into why the RRC state change might be causing a timestamp mismatch in the SNTP response?
Is this behavior normal? How could I avoid this error?
It seems to be related to timing, and I suspect that an RRC state change in the midst of the query might be disrupting the timing.

Your assistance in resolving this matter would be greatly appreciated.

Best regards.

[Didrik Rokhaug]

Hi,

Are you able to capture a modem trace where this happens?

Are you using PSM and/or eDRX in your application?

When are you doing the SNTP request? Has the device just woken up from sleep and is in RRC Idle and the SNTP request is the first data traffic, or is the device already active, and in an RRC connection?

Could you try to upgrade the modem FW to version 1.3.5 to see if the same happens there?

Best regards,

Didrik

[Moustapha DIENG]

Hello, thank you for your reply.

I've checked, we haven't activated the PSM and eDRX options. 

The SNTP request is made immediately after connection to the network (after receiving the registered status from CEREG).

And yes, SNTP is the first data traffic in our product.

Between each cycle, the nrf9160 on our product is completely switched off, and is switched back on a few hours later.

For the moment, we've decided not to upgrade the modem version, as we're using SDK 1.6.1, and according to Nordic documentation, the maximum modem version compatible with this SDK is 1.3.2.
On this basis, it will not be possible for us to upgrade the modem version to 1.3.5 without changing the SDK.

Regarding modem traces, is it possible to receive them in my application logs and output them with my other logs? 

Best regards.

[Didrik Rokhaug]

Moustapha DIENG said:

Regarding modem traces, is it possible to receive them in my application logs and output them with my other logs? 

No. The modem traces come over UART1 by default, and it needs to be the only user of UART1 (or SPI1 or TWI1, as they share the same physical peripheral).

It is possible to change it to use other UARTs instead, but you then have to manually edit the source files, there are no config option for it.

[Moustapha DIENG]

Hello,

I have made modifications to the SDK source files to change the UART configuration (as UART1 was inaccessible on our board).

Enclosed, please find the modem traces along with timestamped traces from my application.

I have identified a recurring pattern when encountering the issue with the SNTP request
(Maybe it can be useful in elucidating the root cause of the problem).

In my application logs, the error is occurring on the lines: 'app: Request failed with error -22.' This error originates from a 'Mismatch originate timestamp' error generated by the 'parse_response(...)' function in 'sntp.c'.

trace-2023-12-19T13-11-06.223Z.mtrace

Fullscreen sntp-test-logs.txt Download

[00:00:00.158,508] <inf> app: my app booting ....
[00:00:05.662,811] <inf> app: doing some stuff here ... not related to the modem
[00:00:07.423,461] <inf> app: Connecting to LTE network. This may take minutes.
[00:00:08.497,406] <inf> app: LTE_LC_NW_REG status = 2
[00:00:08.497,436] <inf> app: LTE cell changed: Cell ID: 20345350, Tracking area: 25640
[00:00:09.039,520] <inf> app: RRC mode: Connected
[00:00:10.456,420] <inf> app: LTE_LC_NW_REG status = 1
[00:00:10.456,451] <inf> app: LTE cell changed: Cell ID: 20345350, Tracking area: 25640
[00:00:10.456,451] <inf> app: PSM parameter update: TAU: -1, Active time: -1
[00:00:10.556,030] <inf> app: Modem registered to network
[00:00:16.889,312] <inf> app: RRC mode: Idle
[00:00:16.900,604] <inf> app: Starting neighbor cells scan ...
[00:00:17.629,058] <inf> app: Neighbor cells scan result received
[00:00:17.629,058] <inf> app: Current serving cell info
[00:00:17.629,089] <inf> app:   E-UTRAN cell ID: 20345350
[00:00:17.629,089] <inf> app:   Physical cell ID: 86
[00:00:17.629,089] <inf> app:   MCC: 208
[00:00:17.629,089] <inf> app:   MNC: 1
[00:00:17.629,089] <inf> app:   TAC: 25640
[00:00:17.629,089] <inf> app:   EARFCN: 6400
[00:00:17.629,119] <inf> app:   RSRP: 43
[00:00:17.629,119] <inf> app:   RSRQ: 14
[00:00:17.629,150] <inf> app: Neighbor cell 1
[00:00:17.629,150] <inf> app:   EARFCN: 1300
[00:00:17.629,150] <inf> app:   Time difference: 24
[00:00:17.629,150] <inf> app:   Physical cell ID: 278
[00:00:17.629,150] <inf> app:   RSRP: 33
[00:00:17.629,180] <inf> app:   RSRQ: 14
[00:00:17.629,180] <inf> app: Neighbor cell 2
[00:00:17.629,180] <inf> app:   EARFCN: 524
[00:00:17.629,180] <inf> app:   Time difference: 32
[00:00:17.629,180] <inf> app:   Physical cell ID: 428
[00:00:17.629,211] <inf> app:   RSRP: 29
[00:00:17.629,211] <inf> app:   RSRQ: 20
[00:00:17.706,451] <inf> app: SNTP request on time.google.com
[00:00:17.820,098] <inf> app: RRC mode: Connected
[00:00:18.140,289] <inf> app: Clock drift is 36981779517 s
[00:00:23.140,380] <inf> app: SNTP request on time.google.com
[00:00:23.342,163] <inf> app: Clock drift is 34359738368 s
[00:00:28.345,672] <inf> app: SNTP request on time.google.com
[00:00:28.454,345] <inf> app: Clock drift is 34359738368 s
[00:00:33.455,535] <inf> app: SNTP request on time.google.com
[00:00:33.577,575] <inf> app: Clock drift is 34359738368 s
[00:00:38.577,667] <inf> app: SNTP request on time.google.com
[00:00:38.694,519] <inf> app: Clock drift is 34359738369 s
[00:00:43.695,800] <inf> app: SNTP request on time.google.com
[00:00:43.815,948] <inf> app: Clock drift is 34359738369 s
[00:00:48.816,009] <inf> app: SNTP request on time.google.com
[00:00:48.937,072] <inf> app: Clock drift is 34359738369 s
[00:00:53.937,133] <inf> app: SNTP request on time.google.com
[00:00:54.054,870] <err> app: Request failed with error -22
[00:00:54.054,901] <inf> app: SNTP request on time1.google.com
[00:00:55.250,000] <inf> app: Clock drift is 34359738368 s
[00:01:00.250,091] <inf> app: SNTP request on time.google.com
[00:01:01.646,545] <inf> app: RRC mode: Idle
[00:01:02.071,136] <inf> app: RRC mode: Connected
[00:01:02.202,606] <err> app: Request failed with error -22
[00:01:02.202,606] <inf> app: SNTP request on time1.google.com
[00:01:02.292,510] <inf> app: Clock drift is 34359738368 s
[00:01:07.292,572] <inf> app: SNTP request on time.google.com
[00:01:08.964,508] <inf> app: RRC mode: Idle
[00:01:08.964,813] <inf> app: RRC mode: Connected
[00:01:09.074,951] <err> app: Request failed with error -22
[00:01:09.074,981] <inf> app: SNTP request on time1.google.com
[00:01:09.308,380] <inf> app: Clock drift is 34359738368 s
[00:01:14.308,441] <inf> app: SNTP request on time.google.com
[00:01:14.463,867] <inf> app: Clock drift is 34359738368 s
[00:01:19.463,958] <inf> app: SNTP request on time.google.com
[00:01:21.052,764] <inf> app: RRC mode: Idle
[00:01:21.194,366] <inf> app: RRC mode: Connected
[00:01:21.241,088] <err> app: Request failed with error -22
[00:01:21.241,088] <inf> app: SNTP request on time1.google.com
[00:01:21.385,498] <inf> app: Clock drift is 34359738368 s
[00:01:26.385,589] <inf> app: SNTP request on time.google.com
[00:01:26.532,348] <inf> app: Clock drift is 34359738368 s
[00:01:31.532,440] <inf> app: SNTP request on time.google.com
[00:01:31.662,445] <inf> app: Clock drift is 34359738369 s
[00:01:36.662,536] <inf> app: SNTP request on time.google.com
[00:01:36.772,277] <inf> app: Clock drift is 34359738369 s
[00:01:41.772,338] <inf> app: SNTP request on time.google.com
[00:01:43.129,669] <inf> app: RRC mode: Idle
[00:01:43.592,437] <inf> app: RRC mode: Connected
[00:01:43.725,494] <err> app: Request failed with error -22
[00:01:43.725,524] <inf> app: SNTP request on time1.google.com
[00:01:43.817,779] <inf> app: Clock drift is 34359738369 s
[00:01:48.817,871] <inf> app: SNTP request on time.google.com
[00:01:48.936,920] <inf> app: Clock drift is 34359738369 s
[00:01:53.936,981] <inf> app: SNTP request on time.google.com
[00:01:54.054,748] <err> app: Request failed with error -22
[00:01:54.054,748] <inf> app: SNTP request on time1.google.com
[00:01:54.178,405] <inf> app: Clock drift is 34359738368 s
[00:01:59.178,497] <inf> app: SNTP request on time.google.com
[00:01:59.381,835] <inf> app: Clock drift is 34359738368 s
[00:02:04.381,927] <inf> app: SNTP request on time.google.com
[00:02:04.545,410] <inf> app: Clock drift is 34359738368 s
[00:02:09.545,501] <inf> app: SNTP request on time.google.com
[00:02:09.740,295] <inf> app: Clock drift is 34359738369 s
[00:02:14.740,386] <inf> app: SNTP request on time.google.com
[00:02:14.859,649] <inf> app: Clock drift is 34359738369 s
[00:02:19.859,741] <inf> app: SNTP request on time.google.com
[00:02:20.011,749] <inf> app: Clock drift is 34359738369 s
[00:02:25.011,810] <inf> app: SNTP request on time.google.com
[00:02:25.101,776] <inf> app: Clock drift is 34359738369 s
[00:02:30.101,837] <inf> app: SNTP request on time.google.com
[00:02:30.226,226] <inf> app: Clock drift is 34359738368 s
[00:02:35.226,287] <inf> app: SNTP request on time.google.com
[00:02:35.353,393] <inf> app: Clock drift is 34359738368 s
[00:02:40.353,454] <inf> app: SNTP request on time.google.com
[00:02:40.462,432] <inf> app: Clock drift is 34359738368 s
[00:02:45.462,524] <inf> app: SNTP request on time.google.com
[00:02:45.573,425] <inf> app: Clock drift is 34359738368 s
[00:02:50.573,486] <inf> app: SNTP request on time.google.com
[00:02:50.713,867] <inf> app: Clock drift is 34359738369 s
[00:02:55.713,928] <inf> app: SNTP request on time.google.com
[00:02:55.833,190] <inf> app: Clock drift is 34359738369 s
[00:03:00.833,282] <inf> app: SNTP request on time.google.com
[00:03:02.414,611] <inf> app: RRC mode: Idle
[00:03:02.580,596] <inf> app: LTE cell changed: Cell ID: 20169734, Tracking area: 25640
[00:03:02.738,067] <inf> app: RRC mode: Connected
[00:03:03.209,442] <err> app: Request failed with error -22
[00:03:03.209,442] <inf> app: SNTP request on time1.google.com
[00:03:03.380,035] <inf> app: Clock drift is 34359738368 s
[00:03:08.380,096] <inf> app: SNTP request on time.google.com
[00:03:08.537,658] <inf> app: Clock drift is 34359738368 s
[00:03:13.540,496] <inf> app: SNTP request on time.google.com
[00:03:13.709,228] <inf> app: Clock drift is 34359738369 s
[00:03:18.709,320] <inf> app: SNTP request on time.google.com
[00:03:18.868,408] <inf> app: Clock drift is 34359738369 s
[00:03:23.868,469] <inf> app: SNTP request on time.google.com
[00:03:24.059,082] <err> app: Request failed with error -22
[00:03:24.059,082] <inf> app: SNTP request on time1.google.com
[00:03:24.156,250] <inf> app: Clock drift is 34359738368 s
[00:03:29.156,341] <inf> app: SNTP request on time.google.com
[00:03:29.345,764] <inf> app: Clock drift is 34359738368 s

Thanks in advance for your help.

[Didrik Rokhaug]

Thanks for the trace.

When the RRC connection is released, the SNTP library doesn't get a response from the server fast enough, so it re-sends the request (with new timestamps). However, when the RRC connection is re-established, it receives the servers response to the first request. As this response doesn't match the last request sent by the library, you get the error.

I have asked our modem team to look at the trace to see if they can figure out why the RRC connection is released so shortly after a data transfer. However, due to Christmas vacations, it might take a bit longer to get a reply from them than usual. We apologize for the inconvenience.

Merry Christmas and a happy new year.

[Moustapha DIENG]

Hello Didrik,
Happy new year!

Thanks for your analysis.

Were you able to get any new information from your colleagues?

Best regards.

[Didrik Rokhaug]

Hello, and happy new year to you to.

Unfortunately, the analysis has been delayed due to Christmas vacations, so they are still working their way through the various protocol layers.

However, they haven't found anything suspicious yet.

I think the analysis will complete soon, and I'll update you once I have the conclusions.

Best regards,

Didrik

[Moustapha DIENG]

Hi Didrik,

I wanted to follow up regarding the analysis that your team was scheduled to conduct based on the modem traces I previously shared. Could you please provide any updates or information on the progress?

This matter is currently posing a significant challenge for us, and any assistance from your end would be greatly appreciated.

Upon reviewing the release notes for modem firmware versions higher than ours (1.3.0), specifically version 1.3.4, I came across the following entry:

-- Fixed an issue with AS-RAI where the modem reported BSR 0 too early, causing the network to release RRC connection before responding to the last data UL packet.

This description closely resembles the problem we encountered. I would appreciate it if your team could delve into this further and tell me if it's the same issue or not. 

Thank you for your attention to this matter.

Best regards,

[Didrik Rokhaug]

The team has looked into the modem trace, and it looks like you are just unlucky with the timing.

While the packet has been queued to be sent, it hasn't actually been sent on air, so the network releases the RRC connection after 5 seconds of inactivity.

I've asked if they have any suggestions on how to improve the situation, and if the line from the mfw 1.3.4 release notes are related to this issue.

[Didrik Rokhaug]

Hi, and sorry for the long wait.

Moustapha DIENG said:

-- Fixed an issue with AS-RAI where the modem reported BSR 0 too early, causing the network to release RRC connection before responding to the last data UL packet.

According to the trace, you are not using Release Assistance Indication (RAI), so that fix is not relevant.

The RRC release timer is network dependent, and there isn't really anything the device can do to affect it, other than sending more frequently (so that the timer is restarted).

Best regards,

Didrik