Negative timer numbers in logs + Feather M0 not waking from sleep using RTCZero

[pomplesiegel]

Issue

Adafruit Feather M0 now consistently fails to wake from sleep after many transmits (a day or two of transmits + sleeps every ~10 seconds). Previously this was not an issue, and may be due to an interaction between LMIC + RTCZero's sleep (standbyMode) functionality.

NOTE: This one is a bit complicated, as it involves interaction between various libraries, but represents a common use case, and I'm hoping folks can help.

Strange observation: Seconds before this occurs, negative timestamps can be seen in the logs. See log file below (note that our program prints dots every second for logging purposes):

Woke up!
Time to take some sensor readings
Now measuring ambient temperature...
<skipping unimportant logs>....
Total measurement duration millis: 2534
-2146438103
: 
EV_TXSTART
.
.
.
-2146294889
: 
EV_TXCOMPLETE (includes waiting for RX windows)
Transmit successful!
About to go to sleep
Duration we've been awake since last sleep (ms): 5829
Actually going to sleep for 9s...
-------

Are these negative values a clue of something which could be going on, or are they just red herrings?

This exact code used to run fine indefinitely, and the failure (with my test method) often takes more than a day to reproduce, so I'm having a hard time narrowing down the exact culprit.

Thank you for your help!!

Environment

• Version of RTCZero: 1.6
• Version of LMIC being used: v3.2
• BSP version: 1.5.14
• Version of Arduino IDE being used: 1.8.12
• Network provider: TTN
• Region: US915
• Board: Adafruit Feather M0
• Radio: HopeRF

[salvagione]

https://arduino.stackexchange.com/questions/12587/how-can-i-handle-the-millis-rollover

[pomplesiegel]

@salvagione, totally, I understand. But in this case I am not doing any manipulation of millis, nor am I using it to set any timers or interrupts in my code.

Perhaps that is being done by one of the previously stated libraries?

Using RTCZero, I am sleeping using the code

    rtc.begin(true); // Initialize RTC
    rtc.setEpoch(0); // Use RTC as a second timer instead of calendar
    rtc.setAlarmEpoch(rtc.getEpoch() + numSecondsToSleepFor );
    rtc.enableAlarm(rtc.MATCH_YYMMDDHHMMSS);
    rtc.attachInterrupt(alarmMatch); //just an empty function, to satisfy compiler 
    rtc.standbyMode(); //going to sleep with this command

The sleep time is based on epoch (at least the API)

[terrillmoore]

@pomplesiegel, the LMIC assumes that micros() and millis() increment and match real time. The Adafruit BSP doesn't give you a way to do this, and the RTC lib doesn't do it either. So... this is not going to work well for you. The primary reason for MCCI having our own BSP for the M0 was to add the required API.

If you wait until the LMIC says it's ok to delay for numSecondsToSleepFor, you might be OK. but there are timers for channel access, etc., that run off real time difference of millis(), and so this really is not likely to work very well. os_getTime() is assumed to be a function of elapsed time, not elapsed-time-while-not-sleeping. millis(), in the M0 BSPs, is generally "elapsed-time-while-not-sleeping".

The hack would be to change os_getTime() to add an offset to millis(); you'd adjust this based on the result, so you could influence it. Or search for all uses of millis() in the lmic, and replace with your own os_Millis() and then hack it. It would be reasonable to add this to the list of things to do in the standard library, but I don't think this is something I want to do without more thought and testing.

[cyberman54]

I ran into the same problem with deep sleep MCCI LMIC on ESP32, using arduino-esp32 framework.
In this framework millis() is hardwired to esp_timer_get_time(), which does not persist it's value during deep sleep, while gettimeofday() does, and so it is possible to calculate exact sleep time in microsecond precision using gettimeofday().

But I'm wondering how i could solve the problem to add this offset to millis() for LMIC, after wake up from deep sleep. Any suggestions?

[salvagione]

Hmm, have a look at this line and the type/size of the variables that hold the values.

rtc.setAlarmEpoch(rtc.getEpoch() + numSecondsToSleepFor );

Does it overflow in about 2 days?

[pomplesiegel]

@salvagione, Thank you for your response.

Epoch is set to 0 in the line above, in order to avoid this issue. The actual epoch time is not relevant, and we only expect to sleep for at most a few hours.

    rtc.setEpoch(0); // Use RTC as a second timer instead of calendar

[pomplesiegel]

@terrillmoore, thank you for the reply! Some (much) of this is a bit over my head :)

Our strategy for the last two years (worked well until recently) has been to take this approach:

Sleep when we know the transmit has been successful, at the end of onEvent(), case EV_TXCOMPLETE, then wake up and schedule the next transmission for immediately

os_setTimedCallback(&sendjob, os_getTime() + sec2osticks(1), do_send);

Is this strategy no longer functional? Or is the answer already in your response and I'm too thick to figure it out? :)

Thank you,
Michael

[pomplesiegel]

To clarify, is millis overflow the underlying problem? Also, I searched for millis() and millis in LMIC, but couldn't find its underlying call to redierct

[terrillmoore]

Sorry, the earlier comment about millis() overflow got me off track.

The LMIC uses micros() to get the time (in hal_ticks()). But micros() in turn is based on millis() * 1000 plus an offset (from tick to tick). This is not necessarily so, but is is in fact the way it works in the M0 BSP, last I looked.

Since you are using code from two years ago, it's almost certain that you are being bit by things that have changed.

1. The LMIC now (as of 3.2) really is compliant with LoRaWAN, and reliably receives and processes downlink MAC frames. (Before, the downlinks were largely ignored, or not handled compliantly)

2. The networks (as of a year or two ago) are trying to manage device transmit power, and so they send downlinks a lot more than before. These downlinks require responses.

3. TXDONE never meant that the LMIC was idle; it only meant that the work for transmitting user data is complete (including the RX downlinks)

4. If the network sends you a downlink, the LMIC is not idle; it's already sending its uplink response.

5. if you go to sleep while the LMIC is not idle, when you wake up, thing are not going to be right in the LMIC.

6. the transmit APIs now return errors rather than silently failing (or silently blowing up) if you try to send while the LMIC is busy handling network traffic. This can break older apps, or at least cause them to function differently. Most older apps didn't check for errors because the sample apps don't. (Yes, the sample apps are a problem to be fixed.)

There are probably two issues.

1. you must arrange for the LMIC to continue to generate times that are approximately correct with respect to passage of time (not just time-while-awake). This can be done by adjusting the value of millis() when you wake up, by adding how long you were asleep -- this will indirectly fix the value of micros(); or it can be done by hacking hal_ticks() so you can add an offset (cumulative sleep time in microseconds modulo 2^32, or cumulative sleep time in ostime_t ticks). This has always been true for reliability, but it's even more true now. That will probably fix your problem with sleep.

2. you must not sleep while the LMIC has an event scheduled. You can find out if a given sleep interval is safe by calling the LMIC api os_queryTimeCriticalJobs(). You pass it how long you would like to sleep, in ostime_t ticks; it returns non-zero if there are time-critical jobs in the interval, and zero otherwise. This might also fix your problem with sleep, if what's really happening is you're calling the LMIC when it's busy.

And maybe:

3. you should check for errors when you try to transmit, and recover. You won't get a completion (EV_TXDONE) if your transmit didn't launch.

[pomplesiegel]

@terrillmoore, got it, thank you!

In a way, this issue is actually about two separate things:

1. Time values that make no sense (as a result of user not complying with needs of LMIC, by not keeping time while sleeping)
2. (the main issue I was battling): Device stops waking up after a random amount of sleeps (about a day into testing, using the procedure above)

As I mentioned earlier, this was a sudden and recent occurrence.

In fact, it seems the problem is totally irradiated (crossing fingers) by downgrading RTCZero library from 1.6 to 1.5.2. The time values are now also staying positive, and the device continues to wake up from every sleep.

I'm planning to post an issue on RTC, but FYI, downgrading RTCZero solved this particular problem on this particular board.

[pomplesiegel]

@terrillmoore, FYI for good measure I am implementing what you mentioned here. Thank you!

I've added this to hal.cpp:

static uint32_t addition_in_seconds = 0; //state for our offset
void AddOffsetInSecondsToMicros(uint32_t offsetInSeconds) {
    addition_in_seconds = (addition_in_seconds + offsetInSeconds) % UINT_MAX; 
}

uint32_t ModifiedMicros(){
    return (micros() + addition_in_seconds * 1000000) % UINT_MAX; 
}

and have changed the usage of micros() to ModifiedMicros():

    uint32_t scaled = ModifiedMicros() >> US_PER_OSTICK_EXPONENT;

In my code, after each sleep I call

    AddOffsetInSecondsToMicros( localCopyOfPersistentData.getTransmitInterval() ); //Advance the clock for LMIC

Think that should do the trick? Thanks again for your help

[terrillmoore]

@pomplesiegel it looks right to me...