Sleep Initiating Cellular Power Down - when it is already off

chipmc · August 27, 2021, 1:28pm

I am noticing that is takes a long time for my Boron (deviceOS@2.1.0) to go to sleep. When I looked at the logs, it seems that the device is powering down the cellular modem each time it enters sleep. This is despite the fact that the device is off-line and the cellular modem had previously been powered down.

Here is what I am seeing from the serial logger:

Serial connection closed.  Attempting to reconnect...
Serial monitor opened successfully:
0000537654 [ncp.at] TRACE: > AT
0000537807 [app] INFO: From Idle to Napping
0000537807 [app.ab1805] INFO: setWDT 0
0000537808 [app.ab1805] TRACE: watchdog cleared bResult=1
0000537808 [system.sleep] TRACE: Entering system_sleep_ext()
0000537809 [system.nm] TRACE: Request to power off the interface
0000537810 [system.nm] TRACE: Interface 4 power state: 2
0000537811 [system.nm] INFO: State changed: IFACE_DOWN -> DISABLED
0000537811 [system.sleep] TRACE: Waiting interface 4 to be off...
0000538654 [ncp.at] TRACE: > AT
0000539654 [ncp.at] TRACE: > AT
0000540654 [ncp.at] TRACE: > AT
0000540696 [ncp.at] TRACE: < OK
0000540696 [ncp.client] TRACE: NCP ready to accept AT commands
0000540697 [ncp.at] TRACE: > ATI9
0000540699 [ncp.at] TRACE: < L0.0.00.00.05.08,A.02.04
0000540699 [ncp.at] TRACE: < OK
0000540700 [ncp.client] TRACE: App firmware: 204
0000540700 [ncp.at] TRACE: > AT+UGPIOC?
0000540702 [ncp.at] TRACE: < +UGPIOC:
0000540702 [ncp.at] TRACE: < 7,255
0000540703 [ncp.at] TRACE: < 16,255
0000540703 [ncp.at] TRACE: < 19,255
0000540704 [ncp.at] TRACE: < 23,0
0000540704 [ncp.at] TRACE: < 24,255
0000540705 [ncp.at] TRACE: < 25,255
0000540705 [ncp.at] TRACE: < 42,255
0000540706 [ncp.at] TRACE: < OK
0000540706 [ncp.at] TRACE: > AT+UGPIOR=23
0000540709 [ncp.at] TRACE: < +UGPIOR: 23,1
0000540709 [ncp.at] TRACE: < OK
0000540709 [ncp.client] INFO: Using internal SIM card
0000540710 [ncp.at] TRACE: > AT+CPIN?
0000540713 [ncp.at] TRACE: < +CME ERROR: SIM not inserted
0000541713 [ncp.at] TRACE: > AT+CPIN?
0000545518 [ncp.at] TRACE: < +CPIN: READY
0000545518 [ncp.at] TRACE: < OK
0000545518 [ncp.at] TRACE: > AT+CCID
0000545521 [ncp.at] TRACE: < +CCID: 89014103273166774681
0000545521 [ncp.at] TRACE: < OK
0000545522 [ncp.at] TRACE: > AT+CFUN=0,0
0000545735 [ncp.at] TRACE: < OK
0000545735 [ncp.at] TRACE: > AT+CFUN=1,0
0000545738 [ncp.at] TRACE: < OK
0000545738 [ncp.at] TRACE: > AT+CCID
0000545741 [ncp.at] TRACE: < +CCID: 89014103273166774681
0000545741 [ncp.at] TRACE: < OK
0000545742 [ncp.at] TRACE: > AT+CIMI
0000545744 [ncp.at] TRACE: < 310410316677468
0000545744 [ncp.at] TRACE: < OK
0000545745 [ncp.at] TRACE: > AT+UMNOPROF?
0000545750 [ncp.at] TRACE: < +UMNOPROF: 2
0000545751 [ncp.at] TRACE: < OK
0000545751 [ncp.at] TRACE: > AT+IFC=2,2
0000545754 [ncp.at] TRACE: < OK
0000545754 [ncp.at] TRACE: > AT
0000545756 [ncp.at] TRACE: < OK
0000545756 [ncp.at] TRACE: > AT+COPS=3,2
0000545759 [ncp.at] TRACE: < OK
0000545759 [ncp.at] TRACE: > AT+CGEREP=1,0
0000545762 [ncp.at] TRACE: < OK
0000545762 [ncp.at] TRACE: > AT+IPR=460800
0000545769 [ncp.at] TRACE: < OK
0000546769 [ncp.at] TRACE: > AT
0000546772 [ncp.at] TRACE: < OK
0000546772 [ncp.at] TRACE: > AT+URAT?
0000546774 [ncp.at] TRACE: < +CME ERROR: Operation not supported
0000546775 [ncp.at] TRACE: > AT+CEDRXS?
0000546777 [ncp.at] TRACE: < +CEDRXS:
0000546778 [ncp.at] TRACE: < OK
0000546778 [ncp.at] TRACE: > AT+CPSMS=0
0000546781 [ncp.at] TRACE: < OK
0000546781 [ncp.at] TRACE: > AT+CMUX=0,0,,1509,,,,,
0000546785 [ncp.at] TRACE: < OK
0000546785 [gsm0710muxer] INFO: Starting GSM07.10 muxer
0000546786 [gsm0710muxer] INFO: Openning mux channel 0
0000546786 [gsm0710muxer] INFO: GSM07.10 muxer thread started
0000546788 [gsm0710muxer] INFO: Openning mux channel 1
0000548058 [ncp.at] TRACE: > AT
0000548058 [ncp.at] TRACE: < +CGEV: ME DETACH
0000548061 [ncp.at] TRACE: < OK
0000548062 [ncp.client] TRACE: NCP state changed: 1
0000548062 [net.pppncp] TRACE: NCP event 1
0000548063 [ncp.at] TRACE: > AT+CIMI
0000548070 [ncp.at] TRACE: < 310410316677468
0000548070 [ncp.at] TRACE: < OK
0000548070 [net.pppncp] TRACE: PPP netif event from queue: 4
0000548071 [net.pppncp] TRACE: NCP event 3
0000548071 [net.pppncp] TRACE: NCP power state changed: IF_POWER_STATE_POWERING_DOWN
0000548072 [system.nm] TRACE: Interface 4 power state changed: 3
0000548073 [ncp.client] TRACE: Try powering modem off using AT command
0000548074 [ncp.at] TRACE: > AT+CPWROFF
0000548080 [ncp.at] TRACE: < OK
0000548081 [ncp.client] TRACE: Waiting the modem to be turned off...
0000548321 [net.pppncp] TRACE: NCP event 3
0000548321 [net.pppncp] TRACE: NCP power state changed: IF_POWER_STATE_DOWN
0000548322 [system.nm] TRACE: Interface 4 power state changed: 1
0000548322 [ncp.client] TRACE: It takes 241 ms to power off the modem.
0000548323 [gsm0710muxer] INFO: Stopping GSM07.10 muxer
0000548324 [gsm0710muxer] INFO: Gracefully stopping GSM07.10 muxer
0000548324 [gsm0710muxer] INFO: Closing all muxed channels
0000548324 [gsm0710muxer] INFO: Closing mux channel 1
0000548325 [gsm0710muxer] INFO: Muxed channel 2 already closed
0000548325 [gsm0710muxer] INFO: Muxed channel 3 already closed
0000548326 [gsm0710muxer] INFO: Muxed channel 4 already closed
0000548327 [gsm0710muxer] INFO: GSM07.10 muxer thread exiting
0000548327 [gsm0710muxer] INFO: GSM07.10 muxer stopped
0000548328 [ncp.client] TRACE: Setting UART voltage translator state 0
0000548329 [ncp.client] TRACE: Soft power off modem successfully
0000548329 [ncp.client] TRACE: Deinit modem serial.
0000548411 [system.sleep] TRACE: Interface 3 is off already


Serial connection closed.  Attempting to reconnect...

and here is what it is supposed to look like:

Serial monitor opened successfully:
0000244293 [app] INFO: Sleeping
0000244293 [app.ab1805] INFO: setWDT 0
0000244294 [app.ab1805] TRACE: watchdog cleared bResult=1
0000244294 [system.sleep] TRACE: Entering system_sleep_ext()
0000244295 [system.sleep] TRACE: Interface 4 is off already
0000244296 [system.sleep] TRACE: Interface 3 is off already


Serial connection closed.  Attempting to reconnect...
Serial monitor opened successfully:

In this sequence, the device is awoken by a hardware interrupt, services the interrupt and goes back to sleep. As my sketch is quite long, here are a few relevant snippets.

  case NAPPING_STATE: {  // This state puts the device in low power mode quickly
    if (state != oldState) publishStateTransition();
    if (sensorDetect || countSignalTimer.isActive()) break;           // Don't nap until we are done with event
    if (sysStatus.connectedStatus) disconnectFromParticle();          // If we are in connected mode we need to Disconnect from Particle
    stayAwake = 1000;                                                 // Once we come into this function, we need to reset stayAwake as it changes at the top of the hour
    ab1805.stopWDT();                                                 // If we are sleeping, we will miss petting the watchdog
    int wakeInSeconds = constrain(wakeBoundary - Time.now() % wakeBoundary, 1, wakeBoundary);
    config.mode(SystemSleepMode::ULTRA_LOW_POWER)
      .gpio(userSwitch,CHANGE)
      .gpio(intPin,RISING)
      .duration(wakeInSeconds * 1000);
    SystemSleepResult result = System.sleep(config);                   // Put the device to sleep
      ab1805.resumeWDT();                                              // Wakey Wakey - WDT can resume
      fuel.wakeup();                                                   // Make sure that the fuel gauge wakes quickly 
    fuel.quickStart();
    if (result.wakeupPin() == intPin) {                                // Executions starts here after sleep - time or sensor interrupt?
      stayAwakeTimeStamp = millis();
    }
    else if (result.wakeupPin() == userSwitch) setLowPowerMode("0");
    state = IDLE_STATE;                                                // Back to the IDLE_STATE after a nap - not enabling updates here as napping is typicallly disconnected
    } break;

So, my question is - why is the device powering off “interface 4” repeatedly?

Thanks,

Chip

chipmc · August 29, 2021, 7:08pm

To try to get to the Bottom of this issue, I tried to simplify the code to the minimum. I had stopped giving a specific instruction to power off the cellular modem once I updated to deviceOS@2.1.0.

Note that in this document is the statement - " Device OS branches 2.1.0+ and 3.0.0+ implement safety checks to ensure the graceful poweroff of the modem upon direction by standard Device OS API Commands ( Cellular.off() , System.Sleep() )."

I based on my experience here, I am not sure this is true as of deviceOS@2.1.0.

Here is my simplified code:

SYSTEM_MODE(MANUAL);
SYSTEM_THREAD(ENABLED);

#include "PublishQueuePosixRK.h"                    // Allows for queuing of messages - https://github.com/rickkas7/PublishQueuePosixRK
#include "AB1805_RK.h"                              // Watchdog and Real Time Clock - https://github.com/rickkas7/AB1805_RK

// For monitoring / debugging, you can uncomment the next line
SerialLogHandler logHandler(LOG_LEVEL_ALL);
SystemSleepConfiguration config;                                    // Initialize new Sleep 2.0 Api
AB1805 ab1805(Wire);                                                // Rickkas' RTC / Watchdog library

const int blueLED = D7;
const int userSwitch = D4;

inline void softDelay(uint32_t t) {
  for (uint32_t ms = millis(); millis() - ms < t; Particle.process());  //  safer than a delay()
}

void setup() {

  pinMode(userSwitch,INPUT);
  pinMode(blueLED,OUTPUT);
  digitalWrite(blueLED,HIGH);

  PublishQueuePosix::instance().setup();                            // Tend to the queue
  PublishQueuePosix::instance().withRamQueueSize(0);                // Writes to memory immediately
  PublishQueuePosix::instance().withFileQueueSize(4);               // This should last at least two days

  // Here is where we setup the Watchdog timer and Real Time Clock
  ab1805.withFOUT(D8).setup();                                      // The carrier board has D8 connected to FOUT for wake interrupts
  ab1805.setWDT(AB1805::WATCHDOG_MAX_SECONDS);                      // Enable watchdog

  config.mode(SystemSleepMode::ULTRA_LOW_POWER)
    .gpio(userSwitch,CHANGE)                                        // If we wake with userSwitch - then we connect
    .duration(10000);                                               // Sleep for 10 seconds
}

void loop() {
  softDelay(15000);                                                 // wait 15 seconds before Sleep.
  digitalWrite(blueLED,LOW);
  if (Particle.connected()) disconnectFromParticle();               // Fully disconnect and power off cellular modem
  Log.info("Sleeping");
  ab1805.stopWDT();                                                 // If we are sleeping, we will miss petting the watchdog
  SystemSleepResult result = System.sleep(config);  
  if (result.wakeupPin() == userSwitch) {                           // Executions starts here after sleep - time or sensor interrupt?
    Particle.connect();
    waitFor(Particle.connected, 660000);                            // Get connected before moving on
  }
  digitalWrite(blueLED,HIGH);
  ab1805.resumeWDT();                                               // Wakey Wakey - WDT can resume
  softDelay(1000);
  Log.info("Awake");
  PublishQueuePosix::instance().publish("Test", "Awake", PRIVATE, WITH_ACK);    // Pretend to publish something

  PublishQueuePosix::instance().loop();                             // Service the Queue
  ab1805.loop();                                                    // Keeps the RTC synchronized with the Boron's clock
}

bool disconnectFromParticle()                                     // Ensures we disconnect cleanly from Particle
                                                                  // Updated based onthis thread: https://community.particle.io/t/waitfor-particle-connected-timeout-does-not-time-out/59181
{
  Log.info("In the disconnect from Particle function");
  Particle.disconnect();
  waitForNot(Particle.connected, 15000);                          // make sure before turning off the cellular modem
  Cellular.disconnect();                                          // Disconnect from the cellular network
  Cellular.off();                                                 // Turn off the cellular modem

  // Commenting out this line causes the "Interface 4" shutdown issue.
  // waitFor(Cellular.isOff, 30000);                                 // As per TAN004: https://support.particle.io/hc/en-us/articles/1260802113569-TAN004-Power-off-Recommendations-for-SARA-R410M-Equipped-Devices
  return true;
}

From what I can tell, you need to make sure you don’t go to sleep too quickly after powering down the cellular modem. I thought that deviceOS@2.1.0 had protections against this but commenting out this line causes the issue of “Interface 4” needing to be be repeatedly shut down. So, I will go back to checking for Cellular.isOff even for Sleep.

Please let me know if I am missing anything.

Chip

jgskarda · August 29, 2021, 9:25pm

Hi Chip... Thanks for providing this info/observation:

I currently do not have this check but given your observation I'll likely add it back in. I did have a 2s softDelay() though after calling Cellular.Off() before initiating the ultra low power sleep. I'm probably better with a waitFor(Cellular.isOff, 30000) like you have as it can't hurt.

On a related note, have you tried the graceful disconnect and did that make a difference? I'm guessing it doesn't come into play as this is disconnecting from the Particle Cloud vs turning the Cellular Off but wasn't sure.

    //Disconnect and then turn off cellular. 
    Particle.disconnect(CloudDisconnectOptions().graceful(true).timeout(5s));

chipmc · August 29, 2021, 9:58pm

@jgskarda ,

I have opened a support ticket as this is not how things are supposed to work on deviceOS@2.1.0. Will keep you in the loop.

I use a global statement in setup():

  Particle.setDisconnectOptions(CloudDisconnectOptions().graceful(true).timeout(5s));  // Don't disconnect abruptly

This, unfortunately, does not seem to have an effect on this issue.

Long term, we need to get some clear guidance on best practices for connecting to Particle and disconnecting and preparing for sleep. My disconnectFromParticle() function is not grounded in anything more than my experience.

Thanks,

Chip

system · February 28, 2022, 9:58am

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

Topic		Replies	Views
Cellular Modem Poweroff Detection Firmware boron	1	389	October 3, 2020
Low power sleep on Boron LTE Troubleshooting	22	3919	September 2, 2021
Boron Sleep Method for Hourly Wake Firmware boron	4	675	March 5, 2022
Boron LTE Sleep Modes On 1.3.0-rc Troubleshooting	3	850	July 7, 2019
Boron LTE waking up from sleep mode Firmware boron	5	617	August 25, 2023

Sleep Initiating Cellular Power Down - when it is already off

Related topics