Sleep, serial, and interrupts misbehaving

cmod · September 1, 2022, 9:24pm

I have an application where I have a RAK4630 receiving UART data from an external device, and sleep.all() behaves strangely.

What should happen:
The module should wake up from an interrupt, wait some delay to allow bytes to fill the buffer, parse those bytes, and then go back to sleep again.

What actually happens:
Before T=30 seconds the module does not seem to handle interrupts as it should, after T=30 seconds, interrupts seem to trigger when they are supposed to, but Serial data I should be parsing doesn’t make it through. The sleep timer is also wrong after T=30s as well, for long delays it can be almost double what is intended.

Here’s my code:

unsigned long ts = 0;

void setup() {
  Serial0.begin(9600, RAK_CUSTOM_MODE);
  Serial.begin(115200, RAK_CUSTOM_MODE);
  api.system.sleep.setup(RUI_WAKEUP_FALLING_EDGE, P0_15);

}



void loop() {

  if (Serial0.available() == 0) {
    Serial.print("sleeping...");
    ts = millis();
    api.system.sleep.all(200);
    Serial.print("awake after "); Serial.print(millis() - ts); Serial.print("ms! millis():");Serial.println(millis());
    delay(5); //wait for data to hit the buffer
  }
  else {
    delay(10); //wait for rest of data
    for (int i = 0; i < Serial0.available(); i++) {
      digitalWrite(P1_04, HIGH);
      Serial.print("Serial0: "); Serial.println(Serial0.read(), HEX);
      digitalWrite(P1_04, LOW);
    }
  }

}

Serial log:

awake after 200ms! millis():7355
sleeping…awake after 200ms! millis():7560
sleeping…awake after 200ms! millis():7765
sleeping…awake after 200ms! millis():7970
sleeping…awake after 200ms! millis():8175
sleeping…awake after 200ms! millis():8380
sleeping…awake after 200ms! millis():8585
sleeping…awake after 200ms! millis():8790
sleeping…awake after 200ms! millis():8995
sleeping…awake after 200ms! millis():9200
sleeping…awake after 200ms! millis():9405
Serial0: 1
Serial0: 6
Serial0: 90
sleeping…awake after 200ms! millis():9630
sleeping…awake after 200ms! millis():9835
Serial0: 9
Serial0: 6
Serial0: 10
sleeping…awake after 200ms! millis():10060
sleeping…awake after 200ms! millis():10265
sleeping…awake after 200ms! millis():10470
sleeping…awake after 200ms! millis():10675
sleeping…awake after 200ms! millis():10880
sleeping…awake after 200ms! millis():11085
sleeping…awake after 200ms! millis():11290
Serial0: 0
Serial0: 6
Serial0: A0
sleeping…awake after 200ms! millis():11515
sleeping…awake after 200ms! millis():11720
sleeping…awake after 200ms! millis():11925
sleeping…awake after 200ms! millis():12130
sleeping…awake after 200ms! millis():12335
sleeping…awake after 200ms! millis():12540
sleeping…awake after 200ms! millis():12745
sleeping…awake after 200ms! millis():12950
Serial0: 1
Serial0: 6
Serial0: 90
sleeping…awake after 200ms! millis():13175
sleeping…awake after 200ms! millis():13380
Serial0: 9
Serial0: 6
Serial0: 10
sleeping…awake after 200ms! millis():13605
sleeping…awake after 200ms! millis():13810
Serial0: 1
Serial0: 6
Serial0: 90
sleeping…awake after 200ms! millis():14035
sleeping…awake after 200ms! millis():14240
sleeping…awake after 200ms! millis():14445
sleeping…awake after 200ms! millis():14650
sleeping…awake after 200ms! millis():14855
sleeping…awake after 200ms! millis():15060
sleeping…awake after 200ms! millis():15265
sleeping…awake after 200ms! millis():15470
Serial0: 0
Serial0: 6
Serial0: A0
sleeping…awake after 200ms! millis():15695
sleeping…awake after 200ms! millis():15900
sleeping…awake after 200ms! millis():16105
sleeping…awake after 200ms! millis():16310
sleeping…awake after 200ms! millis():16515
sleeping…awake after 200ms! millis():16720
sleeping…awake after 200ms! millis():16926
sleeping…awake after 200ms! millis():17131
Serial0: 1
Serial0: 6
Serial0: 90
sleeping…awake after 200ms! millis():17356
sleeping…awake after 200ms! millis():17561
Serial0: 9
Serial0: 6
Serial0: 10
sleeping…awake after 200ms! millis():17786
sleeping…awake after 200ms! millis():17991
Serial0: 1
Serial0: 6
Serial0: 90
sleeping…awake after 200ms! millis():18216
sleeping…awake after 200ms! millis():18421
sleeping…awake after 200ms! millis():18626
sleeping…awake after 200ms! millis():18831
sleeping…awake after 200ms! millis():19037
sleeping…awake after 200ms! millis():19242
sleeping…awake after 200ms! millis():19447
sleeping…awake after 200ms! millis():19652
sleeping…awake after 200ms! millis():19857
sleeping…awake after 200ms! millis():20062
Serial0: 0
Serial0: 6
Serial0: A0
sleeping…awake after 200ms! millis():20289
sleeping…awake after 200ms! millis():20494
sleeping…awake after 200ms! millis():20699
sleeping…awake after 200ms! millis():20904
sleeping…awake after 200ms! millis():21109
sleeping…awake after 200ms! millis():21314
sleeping…awake after 200ms! millis():21519
sleeping…awake after 200ms! millis():21725
sleeping…awake after 200ms! millis():21930
sleeping…awake after 200ms! millis():22135
sleeping…awake after 200ms! millis():22340
sleeping…awake after 200ms! millis():22545
sleeping…awake after 200ms! millis():22750
sleeping…awake after 200ms! millis():22955
sleeping…awake after 200ms! millis():23160
sleeping…awake after 200ms! millis():23365
sleeping…awake after 200ms! millis():23570
sleeping…awake after 200ms! millis():23775
sleeping…awake after 200ms! millis():23980
sleeping…awake after 200ms! millis():24185
sleeping…awake after 200ms! millis():24390
sleeping…awake after 200ms! millis():24595
sleeping…awake after 200ms! millis():24800
sleeping…awake after 200ms! millis():25005
sleeping…awake after 200ms! millis():25210
sleeping…awake after 200ms! millis():25415
sleeping…awake after 200ms! millis():25620
sleeping…awake after 200ms! millis():25825
sleeping…awake after 200ms! millis():26030
sleeping…awake after 200ms! millis():26235
sleeping…awake after 200ms! millis():26440
sleeping…awake after 200ms! millis():26645
sleeping…awake after 200ms! millis():26850
sleeping…awake after 200ms! millis():27055
sleeping…awake after 200ms! millis():27260
sleeping…awake after 200ms! millis():27465
sleeping…awake after 200ms! millis():27670
sleeping…awake after 200ms! millis():27875
sleeping…awake after 200ms! millis():28080
sleeping…awake after 200ms! millis():28285
sleeping…awake after 200ms! millis():28490
sleeping…awake after 200ms! millis():28695
sleeping…awake after 200ms! millis():28900
sleeping…awake after 200ms! millis():29105
sleeping…awake after 200ms! millis():29310
sleeping…awake after 200ms! millis():29515
sleeping…awake after 200ms! millis():29720
sleeping…awake after 200ms! millis():29925
sleeping…awake after 200ms! millis():30130
sleeping…awake after 200ms! millis():30335
sleeping…awake after 232ms! millis():30572
sleeping…awake after 218ms! millis():30795
sleeping…awake after 218ms! millis():31018
sleeping…awake after 218ms! millis():31241
sleeping…awake after 218ms! millis():31464
sleeping…awake after 217ms! millis():31686
sleeping…awake after 9ms! millis():31700
Serial0: 9
Serial0: 6
Serial0: 10
sleeping…awake after 117ms! millis():31843
Serial0: 1
Serial0: 6
Serial0: 90
sleeping…awake after 117ms! millis():31985
Serial0: 0
Serial0: 6
Serial0: A0
sleeping…awake after 218ms! millis():32228
sleeping…awake after 218ms! millis():32451
sleeping…awake after 218ms! millis():32674
sleeping…awake after 218ms! millis():32897
sleeping…awake after 218ms! millis():33120
sleeping…awake after 109ms! millis():33234
sleeping…awake after 217ms! millis():33456
sleeping…awake after 9ms! millis():33470
Serial0: 9
Serial0: 6
Serial0: 10
sleeping…awake after 117ms! millis():33613
Serial0: 1
Serial0: 6
Serial0: 90
sleeping…awake after 118ms! millis():33757
sleeping…awake after 217ms! millis():33979
sleeping…awake after 218ms! millis():34202
sleeping…awake after 218ms! millis():34425
sleeping…awake after 218ms! millis():34648
sleeping…awake after 218ms! millis():34871
sleeping…awake after 218ms! millis():35095
sleeping…awake after 218ms! millis():35319
sleeping…awake after 218ms! millis():35542
sleeping…awake after 218ms! millis():35766
sleeping…awake after 218ms! millis():35989
sleeping…awake after 218ms! millis():36212

Could this be related to BLE advertising somehow? Seems about the time that BLE stops advertising after startup. @beegee any chance you know of a workaround? This is from staging, by the way.

cmod · September 1, 2022, 9:30pm

To make things even stranger, upping the sleep duration to 1000 has the following effect, it starts missing bytes despite the interrupt, sometimes waiting until the 1000ms duration is hit to actually print anything.

Other times, after 30s, the serial output doesn’t print out at all, and time timer is way off despite the controller clearly waking up at the appropriate times with what you can see of the shorter sleep durations (bolded).

awake after 1000ms! millis():7624
sleeping…awake after 1000ms! millis():8629
sleeping…awake after 1000ms! millis():9634
sleeping…awake after 1000ms! millis():10639
Serial0: 9
Serial0: 6
Serial0: 10
Serial0: 1
Serial0: 6
Serial0: 90
sleeping…awake after 1000ms! millis():11676
Serial0: 0
Serial0: 6
Serial0: A0
sleeping…awake after 1000ms! millis():12701
sleeping…awake after 1000ms! millis():13706
sleeping…awake after 1000ms! millis():14711
sleeping…awake after 1000ms! millis():15716
Serial0: 1
Serial0: 6
Serial0: 90
Serial0: 9
Serial0: 6
Serial0: 10
sleeping…awake after 1000ms! millis():16752
Serial0: 1
Serial0: 6
Serial0: 90
sleeping…awake after 1000ms! millis():17778
Serial0: 0
Serial0: 6
Serial0: A0
sleeping…awake after 1000ms! millis():18803
sleeping…awake after 1000ms! millis():19808
sleeping…awake after 1000ms! millis():20813
sleeping…awake after 1000ms! millis():21818
sleeping…awake after 1000ms! millis():22823
sleeping…awake after 1000ms! millis():23828
sleeping…awake after 1000ms! millis():24833
sleeping…awake after 1000ms! millis():25838
sleeping…awake after 1000ms! millis():26843
sleeping…awake after 1000ms! millis():27848
sleeping…awake after 1000ms! millis():28853
sleeping…awake after 1000ms! millis():29858
sleeping…awake after 1539ms! millis():31402
sleeping…awake after 1818ms! millis():33225
sleeping…awake after 1818ms! millis():35048
sleeping…awake after 609ms! millis():35662
sleeping…awake after 408ms! millis():36075
sleeping…awake after 308ms! millis():36388
sleeping…awake after 208ms! millis():36601
sleeping…awake after 1817ms! millis():38424
sleeping…awake after 1818ms! millis():40247
sleeping…awake after 1818ms! millis():42071
sleeping…awake after 109ms! millis():42185
sleeping…awake after 408ms! millis():42598
sleeping…awake after 308ms! millis():42911
sleeping…awake after 208ms! millis():43124

cmod · September 1, 2022, 9:33pm

Further context: the UART data I’m sending to the module arrives in chunks of 3 bytes, and there are usually 4 chunks of 3 bytes clustered next to each other.

I’m actually using the UART RX line (Serial1) as the interrupt source, and then another chip (MSP430) acts as a UART repeater with a delay to mirror that incoming data on Serial0. Otherwise, if I just use the RAK4630 I always misread the first byte after the interrupt, byte 0 gets corrupted, and bytes 2 and 3 come in fine, I think because the nRF52840 can’t wake up in time, even at 9600 baud.

Of course without calling sleep.all() I receive the bytes perfectly fine on Serial0 each and every time, something behind the scenes seems to be misbehaving.

cmod · September 1, 2022, 9:50pm

By sheer luck I found a band-aid: by increasing the delay after the wakeup from 5ms to 20ms the data started parsing as it should.

Relevant line is delay(20);

if (Serial0.available() == 0) {
    Serial.print("sleeping...");
    ts = millis();
    api.system.sleep.all(1000);
    Serial.print("awake after "); Serial.print(millis() - ts); Serial.print("ms! millis():");Serial.println(millis());
    delay(20); //wait for data to hit the buffer
  }
  else {
    delay(10); //wait for rest of data
    for (int i = 0; i < Serial0.available(); i++) {
      digitalWrite(P1_04, HIGH);
      Serial.print("Serial0: "); Serial.println(Serial0.read(), HEX);
      digitalWrite(P1_04, LOW);
    }
  }

Successful log:

sleeping…awake after 1818ms! millis():201304
sleeping…awake after 1618ms! millis():202942
Serial0: 1
Serial0: 6
Serial0: 90
sleeping…awake after 308ms! millis():203290
Serial0: 9
Serial0: 6
Serial0: 10
sleeping…awake after 309ms! millis():203640
Serial0: 1
Serial0: 6
Serial0: 90
sleeping…awake after 1017ms! millis():204697
Serial0: 0
Serial0: 6
Serial0: A0
sleeping…awake after 1817ms! millis():206554
sleeping…awake after 1818ms! millis():208392
sleeping…awake after 1818ms! millis():210230
sleeping…awake after 1818ms! millis():212068
sleeping…awake after 1818ms! millis():213906
sleeping…awake after 1818ms! millis():215744

My guess is something weird is happening in those 18 extra ms, that my delay manages to overcome.

cmod · September 1, 2022, 9:55pm

@beegee is there a way to disable the 30s advertising period at the start, unless I explicitly start BLE somehow? I think that is the other half of this bandaid for now.

beegee · September 2, 2022, 1:29am

I didn’t try it, but there is an API call api.ble.advertise.stop();

cmod · September 2, 2022, 1:29pm

So there isn’t anything I can change so BLE doesn’t start up at all at boot?

cmod · September 2, 2022, 3:20pm

@beegee I tested your stop advertising line in my void setup() before calling sleep and it seems doing that causes something to go awry, the chip never sleeps as it should staying in the 3mA range instead.

beegee · September 3, 2022, 4:43am

Still learning about RUI3.

Can you try api.ble.stop(); in your setup().

It stops advertising immediately and my test app was working just fine after that.
Didn’t have the time to make current measurements yet.

cmod · September 6, 2022, 1:03pm

I can certainly try it and let you know, but is there also a way to prevent BLE from starting at all after boot?

beegee · September 8, 2022, 2:56am

Hi @cmod
There is no option to complete disable BLE on startup.

cmod · September 8, 2022, 1:15pm

I see, thank you for confirming.

system · October 8, 2022, 1:15pm

This topic was automatically closed 30 days after the last reply. New replies are no longer allowed.