NRF52832: time stops after 35 minutes (or am I going mad again?)

[RobMeades]

Description

On the NRF52832 platform time(NULL) produces the correct answer for 35 minutes and, afterwards, returns zero or, if set_time() has been called, the time it was set to, forever and never moves again. Here's a simple test program:

#include "mbed.h"

int main()
{
    int wakeUpCount = 0;
    time_t waitStartTime = time(NULL);
    time_t now;
    int x;

    printf("Starting up.\n");
    //set_time(1);
    //waitStartTime = time(NULL);
    
    while (1) {
        now = time(NULL);
        x = now - waitStartTime;

        wakeUpCount++;
        printf("%d: started wait at %d, time now %d, difference %d.\n",
               wakeUpCount, waitStartTime, now, x);
        waitStartTime = time(NULL);
        wait_ms(10000);
    }
}

mbed compile it and run it on an NRF52832 platform (I'm using a UBLOX_EVK_NINA_B1 module) and you'll see that time(NULL) reports 0 forever after the 215th iteration:

212: started wait at 2112, time now 2122, difference 10.
213: started wait at 2122, time now 2132, difference 10.
214: started wait at 2132, time now 2142, difference 10.
215: started wait at 2142, time now 0, difference -2142.
216: started wait at 0, time now 0, difference 0.
217: started wait at 0, time now 0, difference 0.
218: started wait at 0, time now 0, difference 0.

Uncomment the two commented lines and you'll see that time(NULL) reports 1 forever after the 215th iteration instead:

212: started wait at 2113, time now 2123, difference 10.
213: started wait at 2123, time now 2133, difference 10.
214: started wait at 2133, time now 2143, difference 10.
215: started wait at 2143, time now 1, difference -2142.
216: started wait at 1, time now 1, difference 0.
217: started wait at 1, time now 1, difference 0.
218: started wait at 1, time now 1, difference 0.

FYI, 35 minutes is suspiciously close to going half way around a 32-bit microsecond timer. C'mon guys, this is not on, I've just wasted several days looking for a bug in my code; time() has to work, it is a complete show-stopper for me if it doesn't, I need a fix/workaround quickly please!!!

• Target: NRF52832 (in a UBLOX_EVK_NINA_B1 module)
• Toolchain: ARM
• mbed-os SHA 40e9f41b4 "Merge pull request Add license files for MTS bootloaders #7821 from klaas019/master" plus the fix to set_time() in Low power timer needs to be reset when setting time #7849

Issue request type

[ ] Question
[ ] Enhancement
[x] Serious Bug
[ ] I'm going mad

[0xc0170]

@mprse @c1728p9 Can you review please?

[ciarmcom]

ARM Internal Ref: MBOTRIAGE-1671

[mprse]

I'm looking into it.

[mprse]

C'mon guys, this is not on, I've just wasted several days looking for a bug in my code; time() has to work, it is a complete show-stopper for me if it doesn't, I need a fix/workaround quickly please!!!

As far as I remember MCU_NRF52832 has RTC feature disabled since it is not able to keep RTC counter alive when reset is performed. In such case time() function is based on LowPowerTimer.
It looks like the problem is with types returned by Timer member functions (they operate on signed integers). This limits time tracing to ~35 min. As you can see in manual:

Note: Timers are based on 32-bit int microsecond counters, so they can only time up to a maximum of 2^31-1 microseconds (30 minutes). They are designed for times between microseconds and seconds. For longer times, use the time() real time clock.

In our case (no RTC support) time() function calls Timer::read().

mbed-os/platform/mbed_rtc_time.cpp

Lines 51 to 54 in 3da606e

	static time_t _rtc_lpticker_read(void)
	{
	return (uint64_t)_rtc_lp_timer->read() + _rtc_lp_base;
	}

Timer::read() returns number of seconds as float, but calculated from int (Timer::read_us() returns int):

mbed-os/drivers/Timer.cpp

Lines 80 to 83 in 3da606e

	float Timer::read()
	{
	return (float)read_us() / 1000000.0f;
	}

mbed-os/drivers/Timer.cpp

Lines 75 to 78 in 3da606e

	int Timer::read_us()
	{
	return read_high_resolution_us();
	}

_rtc_lpticker_read() should be implemented as follows to operate on unsigned 64 bit value:

static time_t _rtc_lpticker_read(void)
{
    return _rtc_lp_timer->read_high_resolution_us() / 1000000 + _rtc_lp_base;
}

I was able to reproduce you issue on NRF52_DK. I can confirm that issue does not exist with the above fix.

208: started wait at 2085, time now 2095, difference 10.
209: started wait at 2095, time now 2105, difference 10.
210: started wait at 2106, time now 2116, difference 10.
211: started wait at 2116, time now 2126, difference 10.
212: started wait at 2126, time now 2136, difference 10.
213: started wait at 2136, time now 2146, difference 10.
214: started wait at 2146, time now 2156, difference 10.
215: started wait at 2156, time now 2166, difference 10.
216: started wait at 2166, time now 2176, difference 10.
217: started wait at 2176, time now 2186, difference 10.
218: started wait at 2187, time now 2197, difference 10.
219: started wait at 2197, time now 2207, difference 10.
220: started wait at 2207, time now 2217, difference 10.
221: started wait at 2217, time now 2227, difference 10.

Patch is on the way.

[mprse]

Patch can be found here: PR #8165.

[RobMeades]

Many thanks for the very swift investigation and fix, checking it myself now, will comment on the PR in ~35 minutes :-).

[RobMeades]

Confirmed that #8165 fixes this, thanks guys!