ULTRA_LOW_POWER drawing 4 mA (>20x more than expected)

Firmware Device OS
1

I am testing the ULTRA_LOW_POWER sleep mode on the Boron LTE (BRN402). According to the doc ULP draws typically sub 200 uA without network. On mine they draw 3.8~4.3 mA @ 3.78 V or >20x more than claimed. I have gone through the relevant posts in this forum and none seems to have a satisfying resolution (either unresolved or due to users’ specific circuit issues). I am testing on DeviceOS 2.3.0 with no external circuit (just a Boron with a 18650 and a bench-top multimeter), tested with more than one Boron. Code follows with failed attempts in comments:

#include "particle.h"

SYSTEM_THREAD(ENABLED);
SYSTEM_MODE(SEMI_AUTOMATIC);

void setup() {

  // Leave enough time to unplug the USB cable after programming - still ~4 mA with or without.
  // https://community.particle.io/t/b523-deviceos-3-0-0-high-current-consumption-during-sleep/60736/5
  //delay(10s);

  // ~4.7 mA without this block, ~4 mA with this block. This is not it.
  RGB.control(true);
  RGB.color(0, 0, 0);
  RGB.brightness(0);

  // Floating GPIO in sleep? Nope. Same ~4 mA with or without.
  // https://community.particle.io/t/boron-lte-m-cat1-high-current-consumption-in-ultra-low-power-mode/61641
  /*pinMode(D2, INPUT_PULLDOWN);
  pinMode(D3, INPUT_PULLDOWN);
  pinMode(D4, INPUT_PULLDOWN);
  pinMode(D5, INPUT_PULLDOWN);
  pinMode(D6, INPUT_PULLDOWN);
  pinMode(D7, INPUT_PULLDOWN);
  pinMode(D8, INPUT_PULLDOWN);
  pinMode(D9, INPUT_PULLDOWN);
  pinMode(D10, INPUT_PULLDOWN);
  pinMode(D11, INPUT_PULLDOWN);
  pinMode(D12, INPUT_PULLDOWN);
  pinMode(D13, INPUT_PULLDOWN);*/

  // A "nicer" shut down maybe? Nope. Same ~4 mA draw with or without.
  // https://community.particle.io/t/boron-2g-3g-ultra-low-power-cant-get-170ua-720ua-instead/62176/8
  /*Particle.disconnect(CloudDisconnectOptions().graceful(true).timeout(5000));
  waitUntil(Particle.disconnected);
  Cellular.disconnect();
  waitUntilNot(Cellular.ready);
  Cellular.off();
  waitUntil(Cellular.isOff);*/

  SystemSleepConfiguration c;
  c.mode(SystemSleepMode::ULTRA_LOW_POWER);

  System.sleep(c);
}


void loop() {

}

Any idea?

2

That’s kind of an edge case. From cold boot, try connecting to the cloud first, then going sleep. That will likely work correctly.
If you actually need to power down the device from cold boot, it is possible to do so, but you basically need to turn the modem on first to shut to completely down.

1 Like
3

I noticed this problem in my actual program that does more than just ULP sleep, but I can’t post 2k+ lines of code here and expect someone to isolate the problem for me. This is the smallest example where the problem is reliably reproduced.

For battery powered systems deployed in the field where cellular connectivity is unreliable or even unavailable at times, “connecting to the cloud first” doesn’t work when I’m trying to save energy with sleep modes. But for the sake of debugging, this draws 3.5~4.4 mA just like before:

#include "particle.h"

SYSTEM_THREAD(ENABLED);
SYSTEM_MODE(SEMI_AUTOMATIC);

void setup() {

  Particle.connect();
  waitUntil(Particle.connected);

  // same ~3.5 mA with or without this block
  Particle.process();
  delay(1s);
  Particle.process();
  delay(1s);
  Particle.process();
  delay(1s);

  Particle.disconnect(CloudDisconnectOptions().graceful(true).timeout(5000));
  waitUntil(Particle.disconnected);
  Cellular.disconnect();
  waitUntilNot(Cellular.ready);
  Cellular.off();
  waitUntil(Cellular.isOff);

  RGB.control(true);
  RGB.color(0, 0, 0);
  RGB.brightness(0);

  SystemSleepConfiguration c;
  c.mode(SystemSleepMode::ULTRA_LOW_POWER);

  System.sleep(c);
}

void loop() {
}

(Somewhat unrelated: why is the RGB LED breathing white when the Boron is in ULP? I thought STOP/ULP modes stop the CPU entirely. So what hardware is generating that breathing pattern?)

4

@stanleylio ,

If the RGB LED is breathing white, it is not in ULP or sleeping at all. I find it is helpful to use the Serial logger and monitor the device in a terminal window. I suspect, that you will find that something is either preventing or delaying the device from going to sleep when you see the “breathing white” RGB LED.

Chip

5

Any idea what might be preventing the device from entering ULP? There is no external circuit (just a BRN402, a USB cable, an 18650, and a multimeter), and I have posted my test code in whole. USB cable is removed when taking current measurements. I did test with a 6.5-digit bench-top Rigol as well as a handheld Fluke.

Replacing ULTRA_LOW_POWER with HIBERNATE did get it down to ~95 uA as expected (and the RGB did turn off), but I need the wake on time feature of ULP, and I don’t want it to reset on wake like HIBERNATE. Not to mention I want to track down the cause since the doc did promise <200 uA draw.

I have tested this on my three Boron LTEs here, all running DeviceOS 2.3.0. DeviceOS along with the matching bootloader was flashed through USB with image downloaded from the release page. The Borons work fine otherwise (show up on Console with the correct OS version, can transmit and receive etc.).

I started with the Electrons since the 0.4.8 days and have 100+ of them out there actively in use so I’m confident it’s not an operator error like a botched OS upgrade or something.

With SerialLogHandler enabled, the last few lines of output:

0000034078 [ncp.client] TRACE: Try powering modem off using AT command
0000034079 [ncp.at] TRACE: > AT+CPWROFF
0000034086 [ncp.at] TRACE: < OK
0000034087 [ncp.client] TRACE: Waiting the modem to be turned off...
0000034131 [net.pppncp] TRACE: NCP event 3
0000034132 [net.pppncp] TRACE: NCP power state changed: IF_POWER_STATE_DOWN
0000034132 [system.nm] TRACE: Interface 4 power state changed: 1
0000034133 [ncp.client] TRACE: It takes 46 ms to power off the modem.
0000034133 [gsm0710muxer] INFO: Stopping GSM07.10 muxer
0000034134 [gsm0710muxer] INFO: Gracefully stopping GSM07.10 muxer
0000034134 [gsm0710muxer] INFO: Closing all muxed channels
0000034135 [gsm0710muxer] INFO: Closing mux channel 1
0000034135 [gsm0710muxer] INFO: Closing mux channel 2
0000034136 [gsm0710muxer] INFO: Muxed channel 3 already closed
0000034136 [gsm0710muxer] INFO: Muxed channel 4 already closed
0000034137 [gsm0710muxer] INFO: GSM07.10 muxer thread exiting
0000034137 [gsm0710muxer] INFO: GSM07.10 muxer stopped
0000034138 [ncp.client] TRACE: Setting UART voltage translator state 0
0000034138 [ncp.client] TRACE: Soft power off modem successfully
0000034139 [ncp.client] TRACE: Deinit modem serial.
0000034140 [system.sleep] TRACE: Entering system_sleep_ext()
0000034239 [ncp.client] TRACE: Modem already off
0000034240 [ncp.client] TRACE: Setting UART voltage translator state 0
0000034240 [ncp.client] TRACE: Soft power off modem successfully
0000034241 [ncp.client] TRACE: Deinit modem serial.
0000034242 [ncp.client] TRACE: NCP state changed: 0
0000034242 [net.pppncp] TRACE: NCP event 1

… doesn’t look like it’s the cell modem either.

6

That makes me think the MCU is hanging in Setup().
Do you ever notice a ~20 mA reading during the Boot Sequence ?

You might try a fresh flash with clean (basic) code.
Maybe call sleep in Loop() after a couple of minutes, or with a pin.
[However: I don't see any reason for your code to not be successful.]

I personally prefer Manual mode over Semi_Automatic for low power installs.
But a simple if (waitFor(Particle.connected, connectionFail)) instead of Particle.connect() might shed some light. Just throwing out guesses.

2 Likes
7

@stanleylio ,

Thank you for sharing the logs. When I put my Boron into ULP sleep it looks very similar:

0000122007 [ncp.client] TRACE: Waiting the modem to be turned off...
0000122037 [net.pppncp] TRACE: NCP event 3
0000122038 [net.pppncp] TRACE: NCP power state changed: IF_POWER_STATE_DOWN
0000122039 [system.nm] TRACE: Interface 4 power state changed: 1
0000122039 [ncp.client] TRACE: It takes 32 ms to power off the modem.
0000122040 [gsm0710muxer] INFO: Stopping GSM07.10 muxer
0000122040 [gsm0710muxer] INFO: Gracefully stopping GSM07.10 muxer
0000122041 [gsm0710muxer] INFO: Closing all muxed channels
0000122041 [gsm0710muxer] INFO: Closing mux channel 1
0000122042 [gsm0710muxer] INFO: Closing mux channel 2
0000122043 [gsm0710muxer] INFO: Muxed channel 3 already closed
0000122043 [gsm0710muxer] INFO: Muxed channel 4 already closed
0000122044 [gsm0710muxer] INFO: GSM07.10 muxer thread exiting
0000122045 [gsm0710muxer] INFO: GSM07.10 muxer stopped
0000122045 [ncp.client] TRACE: Setting UART voltage translator state 0
0000122046 [ncp.client] TRACE: Soft power off modem successfully
0000122046 [ncp.client] TRACE: Deinit modem serial.
0000122049 [system.sleep] TRACE: Entering system_sleep_ext()
0000122050 [system.sleep] TRACE: Interface 4 is off already
0000122050 [system.sleep] TRACE: Interface 3 is off already

The difference comes in the last few lines. Where the system sleep occurs. I know that this is not the solution but, I was thinking that perhaps showing what the sequence should look like would be helpful.

On my device, the NCP event 1 is associated with the beginning steps of a cellular connection:

0000011578 [gsm0710muxer] INFO: Starting GSM07.10 muxer
0000011579 [gsm0710muxer] INFO: Openning mux channel 0
0000011579 [gsm0710muxer] INFO: GSM07.10 muxer thread started
0000011583 [gsm0710muxer] INFO: Openning mux channel 1
0000011586 [ncp.at] TRACE: > AT
0000011590 [ncp.at] TRACE: < OK
0000011590 [ncp.client] TRACE: NCP state changed: 1
0000011591 [net.pppncp] TRACE: NCP event 1

So, it appears that, rather than going to sleep, your device is restarting the connection process. Perhaps there is a check in the sleep step that recognizes that the cellular modem is not off. I think that @Rftop 's suggestion is a good one - perhaps do a device restore which includes the soft modem.

Hope this helps,

Chip

8
  • Flashed SoftDevice, bootloader, and DeviceOS image through USB+CLI (still on v2.3.0);
  • Moved the sleep call from setup into loop (actually I tested both; it made no difference);
  • Replaced SerialLogHandler (USB) with Serial1LogHandler (USART) so I can see the log when USB is unplugged;
  • Added a few Log prints, including wakeupReason.

Code:

#include "particle.h"

SYSTEM_THREAD(ENABLED);
SYSTEM_MODE(SEMI_AUTOMATIC);

Serial1LogHandler logHandler2(115200,
  LOG_LEVEL_ALL, {
    { "app", LOG_LEVEL_ALL }
});

void setup() {

  Log.info("checkpoint 1");

  Particle.connect();
  waitUntil(Particle.connected);

  Log.info("checkpoint 2");

  Particle.process();
  delay(1s);
  Particle.process();
  delay(1s);
  Particle.process();
  delay(1s);

  Log.info("checkpoint 3");

  Particle.disconnect(CloudDisconnectOptions().graceful(true).timeout(5000));
  waitUntil(Particle.disconnected);
  Cellular.disconnect();
  waitUntilNot(Cellular.ready);
  Cellular.off();
  waitUntil(Cellular.isOff);

  Log.info("checkpoint 4");
}


void loop() {
  Log.info("entering sleep...");

  SystemSleepConfiguration c;
  c.mode(SystemSleepMode::ULTRA_LOW_POWER);
  SystemSleepResult result = System.sleep(c);

  Log.error("this ain't right (%u)", (uint16_t)result.wakeupReason());
  delay(1s);
}

Log:

0000000248 [system.nm] INFO: State changed: NONE -> DISABLED
0000000249 [system.nm] TRACE: Interface 4 power state: 2
0000000259 [app] INFO: checkpoint 1
0000000362 [system.nm] INFO: State changed: DISABLED -> IFACE_DOWN
0000000364 [system.nm] INFO: State changed: IFACE_DOWN -> IFACE_REQUEST_UP
0000000368 [net.pppncp] TRACE: PPP netif event from queue: 1
0000000371 [ncp.client] TRACE: Powering modem on, ncpId: 0x44
0000000380 [ncp.client] TRACE: Modem already on
0000000380 [ncp.client] TRACE: Setting UART voltage translator state 1
0000000393 [system.nm] INFO: State changed: IFACE_REQUEST_UP -> IFACE_UP
0000000492 [ncp.client] TRACE: Setting UART voltage translator state 0
0000000592 [ncp.client] TRACE: Setting UART voltage translator state 1
0000000592 [ncp.client] TRACE: Muxer is not currently running
0000000594 [ncp.client] TRACE: Initialized muxer @ 460800 baudrate
0000000599 [gsm0710muxer] INFO: Starting GSM07.10 muxer
0000000605 [gsm0710muxer] INFO: GSM07.10 muxer thread started
0000000904 [gsm0710muxer] INFO: Stopping GSM07.10 muxer
0000000904 [gsm0710muxer] INFO: Gracefully stopping GSM07.10 muxer
0000000905 [gsm0710muxer] INFO: Closing all muxed channels
0000000912 [gsm0710muxer] INFO: Muxed channel 1 already closed
0000000916 [gsm0710muxer] INFO: Muxed channel 2 already closed
0000000923 [gsm0710muxer] INFO: Muxed channel 3 already closed
0000000927 [gsm0710muxer] INFO: Muxed channel 4 already closed
0000001584 [gsm0710muxer] INFO: Sending CLD (multiplexer close down)
0000002485 [gsm0710muxer] INFO: Received response to CLD or timed out, exiting multiplexed mode
0000002535 [gsm0710muxer] INFO: GSM07.10 muxer thread exiting
0000002535 [gsm0710muxer] INFO: GSM07.10 muxer stopped
0000002536 [ncp.client] TRACE: Initialized muxer @ 115200 baudrate
0000002547 [gsm0710muxer] INFO: Starting GSM07.10 muxer
0000002548 [gsm0710muxer] INFO: GSM07.10 muxer thread started
0000002848 [gsm0710muxer] INFO: Stopping GSM07.10 muxer
0000002848 [gsm0710muxer] INFO: Gracefully stopping GSM07.10 muxer
0000002849 [gsm0710muxer] INFO: Closing all muxed channels
0000002858 [gsm0710muxer] INFO: Muxed channel 1 already closed
0000002860 [gsm0710muxer] INFO: Muxed channel 2 already closed
0000002870 [gsm0710muxer] INFO: Muxed channel 3 already closed
0000002872 [gsm0710muxer] INFO: Muxed channel 4 already closed
0000003531 [gsm0710muxer] INFO: Sending CLD (multiplexer close down)
0000004432 [gsm0710muxer] INFO: Received response to CLD or timed out, exiting multiplexed mode
0000004482 [gsm0710muxer] INFO: GSM07.10 muxer thread exiting
0000004482 [gsm0710muxer] INFO: GSM07.10 muxer stopped
0000004484 [ncp.at] TRACE: > AT
0000005495 [ncp.at] TRACE: > AT
0000006495 [ncp.client] TRACE: Modem is not responsive @ 460800 baudrate
0000006496 [ncp.at] TRACE: > AT
0000006501 [ncp.at] TRACE: < OK
0000006502 [ncp.client] TRACE: NCP ready to accept AT commands
0000006503 [ncp.at] TRACE: > AT
0000006507 [ncp.at] TRACE: < OK
0000006514 [ncp.at] TRACE: > ATI9
0000006522 [ncp.at] TRACE: < L0.0.00.00.05.06,A.02.00
0000006523 [ncp.at] TRACE: < OK
0000006523 [ncp.client] TRACE: App firmware: 200
0000006524 [ncp.at] TRACE: > AT+UGPIOC?
0000006535 [ncp.at] TRACE: < +UGPIOC:
0000006535 [ncp.at] TRACE: < 16,255
0000006535 [ncp.at] TRACE: < 19,255
0000006537 [ncp.at] TRACE: < 23,0
0000006546 [ncp.at] TRACE: < 24,255
0000006546 [ncp.at] TRACE: < 25,255
0000006548 [ncp.at] TRACE: < 42,255
0000006557 [ncp.at] TRACE: < OK
0000006557 [ncp.at] TRACE: > AT+UGPIOR=23
0000006566 [ncp.at] TRACE: < +UGPIOR: 23,1
0000006567 [ncp.at] TRACE: < OK
0000006567 [ncp.client] INFO: Using internal SIM card
0000006571 [ncp.at] TRACE: > AT+CPIN?
0000006578 [ncp.at] TRACE: < +CPIN: READY
0000006579 [ncp.at] TRACE: < OK
0000006579 [ncp.at] TRACE: > AT+CCID
0000006588 [ncp.at] TRACE: < +CCID: 89014103271226500732
0000006590 [ncp.at] TRACE: < OK
0000006590 [ncp.at] TRACE: > AT+IFC=2,2
0000006597 [ncp.at] TRACE: < OK
0000006601 [ncp.at] TRACE: > AT
0000006604 [ncp.at] TRACE: < OK
0000007604 [ncp.at] TRACE: > AT
0000007609 [ncp.at] TRACE: < OK
0000007610 [ncp.at] TRACE: > AT+CCID
0000007620 [ncp.at] TRACE: < +CCID: 89014103271226500732
0000007620 [ncp.at] TRACE: < OK
0000007621 [ncp.at] TRACE: > AT+CIMI
0000007628 [ncp.at] TRACE: < 310410122650073
0000007629 [ncp.at] TRACE: < OK
0000007631 [ncp.at] TRACE: > AT+UMNOPROF?
0000007641 [ncp.at] TRACE: < +UMNOPROF: 2
0000007642 [ncp.at] TRACE: < OK
0000007642 [ncp.at] TRACE: > AT+COPS=3,2
0000007647 [ncp.at] TRACE: < OK
0000007647 [ncp.at] TRACE: > AT+CGEREP=1,0
0000007657 [ncp.at] TRACE: < OK
0000007657 [ncp.at] TRACE: > AT+URAT?
0000007662 [ncp.at] TRACE: < +URAT: 7
0000007662 [ncp.at] TRACE: < OK
0000007665 [ncp.at] TRACE: > AT+CPSMS?
0000007676 [ncp.at] TRACE: < +CPSMS:0,,,"01100000","00000000"
0000007676 [ncp.at] TRACE: < OK
0000007676 [ncp.at] TRACE: > AT+CEDRXS?
0000007681 [ncp.at] TRACE: < +CEDRXS:
0000007682 [ncp.at] TRACE: < OK
0000007688 [ncp.at] TRACE: > AT+CMUX=0,0,,1509,,,,,
0000007697 [ncp.at] TRACE: < OK
0000007698 [gsm0710muxer] INFO: Starting GSM07.10 muxer
0000007699 [gsm0710muxer] INFO: Openning mux channel 0
0000007699 [gsm0710muxer] INFO: GSM07.10 muxer thread started
0000007713 [gsm0710muxer] INFO: Openning mux channel 1
0000007719 [ncp.at] TRACE: > AT
0000007729 [ncp.at] TRACE: < OK
0000007729 [ncp.client] TRACE: NCP state changed: 1
0000007730 [net.pppncp] TRACE: NCP event 1
0000007731 [net.ppp.client] TRACE: PPP thread event ADM_UP
0000007740 [net.ppp.client] TRACE: State NONE -> READY
0000007735 [ncp.at] TRACE: > AT+CFUN?
0000007751 [ncp.at] TRACE: < +CFUN: 1
0000007752 [ncp.at] TRACE: < OK
0000007753 [ncp.at] TRACE: > AT+CCID
0000007765 [ncp.at] TRACE: < +CCID: 89014103271226500732
0000007765 [ncp.at] TRACE: < OK
0000007766 [ncp.at] TRACE: > AT+CIMI
0000007777 [ncp.at] TRACE: < 310410122650073
0000007778 [ncp.at] TRACE: < OK
0000007778 [ncp.at] TRACE: > AT+CGDCONT?
0000007793 [ncp.at] TRACE: < +CGDCONT: 1,"IP","10569.mcs","10.207.191.71",0,0,0,0
0000007794 [ncp.at] TRACE: < OK
0000007795 [ncp.at] TRACE: > AT+CFUN?
0000007806 [ncp.at] TRACE: < +CFUN: 1
0000007806 [ncp.at] TRACE: < OK
0000007807 [ncp.at] TRACE: > AT+CEREG=2
0000007817 [ncp.at] TRACE: < OK
0000007817 [ncp.client] TRACE: NCP connection state changed: 1
0000007818 [net.pppncp] TRACE: NCP event 2
0000007823 [net.pppncp] TRACE: State changed event: 1
0000007829 [net.ppp.client] TRACE: PPP thread event LOWER_DOWN
0000007830 [ncp.at] TRACE: > AT+COPS?
0000007841 [ncp.at] TRACE: < +COPS: 0,2,"310410",8
0000007841 [ncp.at] TRACE: < OK
0000007842 [ncp.at] TRACE: > AT+CEREG?
0000007855 [ncp.at] TRACE: < +CEREG: 2,1,"8504","7A19B10",8
0000007856 [ncp.at] TRACE: < OK
0000007856 [ncp.client] TRACE: NCP connection state changed: 2
0000007863 [gsm0710muxer] INFO: Openning mux channel 2
0000009125 [net.pppncp] TRACE: NCP event 100
0000009125 [net.pppncp] TRACE: New auth info
0000009127 [net.pppncp] TRACE: NCP event 2
0000009127 [net.pppncp] TRACE: State changed event: 2
0000009137 [net.ppp.client] TRACE: PPP thread event LOWER_UP
0000009137 [net.ppp.client] TRACE: State READY -> CONNECT
0000009148 [net.ppp.client] TRACE: State CONNECT -> CONNECTING
0000009138 [ncp.at] TRACE: > AT+CIMI
0000009151 [ncp.at] TRACE: < 310410122650073
0000009159 [ncp.at] TRACE: < OK
0000009160 [ncp.at] TRACE: > AT
0000009168 [ncp.at] TRACE: < OK
0000010170 [ncp.at] TRACE: > AT
0000010179 [ncp.at] TRACE: < OK
0000010179 [ncp.at] TRACE: > ATD*99***1#
0000010193 [ncp.at] TRACE: < CONNECT 150000000
0000010193 [net.ppp.client] TRACE: PPP phase -> 3
0000010194 [net.ppp.client] TRACE: PPP phase -> 6
0000010224 [net.ppp.client] TRACE: PPP phase -> 7
0000010251 [net.ppp.client] TRACE: PPP phase -> 9
0000010281 [system.nm] INFO: State changed: IFACE_UP -> IFACE_LINK_UP
0000010283 [system.nm] INFO: State changed: IFACE_LINK_UP -> IP_CONFIGURED
0000010288 [net.ppp.client] TRACE: PPP phase -> 10
0000010283 [net.ppp.client] TRACE: PPP thread event UP
0000010299 [net.ppp.client] TRACE: State CONNECTING -> CONNECTED
0000010299 [net.pppncp] TRACE: Negotiated MTU: 1500
0000010310 [net.pppncp] TRACE: Updating MTU to: 990
0000010310 [system] INFO: Cloud: connecting
0000010317 [system] INFO: Cloud socket connected
0000010322 [comm.protocol.handshake] INFO: Establish secure connection
0000010701 [ncp.at] TRACE: > AT+CFUN?
0000010713 [ncp.at] TRACE: < +CFUN: 1
0000010713 [ncp.at] TRACE: < OK
0000010715 [ncp.at] TRACE: > AT+CCID
0000010727 [ncp.at] TRACE: < +CCID: 89014103271226500732
0000010727 [ncp.at] TRACE: < OK
0000010729 [ncp.at] TRACE: > AT+CGSN
0000010740 [ncp.at] TRACE: < 352753090294479
0000010741 [ncp.at] TRACE: < OK
0000010742 [ncp.at] TRACE: > ATI9
0000010754 [ncp.at] TRACE: < L0.0.00.00.05.06,A.02.00
0000010754 [ncp.at] TRACE: < OK
0000010755 [comm.protocol.handshake] INFO: Skipping HELLO message
0000010868 [comm.protocol] INFO: Checksum has not changed; not sending application DESCRIBE
0000010870 [comm.protocol] INFO: Checksum has not changed; not sending subscriptions
0000011390 [comm.protocol] TRACE: Reply recieved: type=2, code=0
0000011390 [comm.protocol] TRACE: message id 38 complete with code 0.00
0000011411 [comm.protocol] TRACE: rcv'd message type=13
0000011413 [comm.protocol] TRACE: Reply recieved: type=2, code=69
0000011413 [comm.protocol] TRACE: message id 41 complete with code 2.05
0000011424 [comm.protocol] INFO: Received TIME response: 1650593019
0000011425 [comm.protocol] TRACE: rcv'd message type=12
0000011535 [comm.protocol] TRACE: Reply recieved: type=2, code=0
0000011536 [comm.protocol] TRACE: message id 39 complete with code 0.00
0000011537 [comm.protocol] TRACE: rcv'd message type=13
0000011647 [comm.protocol] TRACE: Reply recieved: type=2, code=0
0000011648 [comm.protocol] TRACE: message id 40 complete with code 0.00
0000011649 [comm.protocol] TRACE: rcv'd message type=13
0000011761 [system] INFO: Cloud connected
0000011761 [app] INFO: checkpoint 2
0000012461 [comm.protocol] TRACE: rcv'd message type=8
0000014762 [app] INFO: checkpoint 3
0000014861 [system] INFO: Cloud: disconnecting
0000015068 [comm.protocol] TRACE: Reply recieved: type=2, code=0
0000015070 [comm.protocol] TRACE: message id 42 complete with code 0.00
0000015071 [comm.protocol] TRACE: rcv'd message type=13
0000015864 [system] INFO: Cloud: disconnected
0000015865 [net.pppncp] TRACE: PPP netif event from queue: 2
0000015866 [net.ppp.client] TRACE: PPP thread event LOWER_DOWN
0000015868 [net.ppp.client] TRACE: State CONNECTED -> DISCONNECT
0000015879 [net.ppp.client] TRACE: State DISCONNECT -> DISCONNECTING
0000015867 [ncp.at] TRACE: > AT+CFUN=0
0000015883 [system.nm] INFO: State changed: IP_CONFIGURED -> IFACE_UP
0000015891 [net.ppp.client] TRACE: PPP phase -> 9
0000015901 [net.ppp.client] TRACE: PPP phase -> 6
0000015902 [net.ppp.client] TRACE: PPP phase -> 12
0000015904 [net.ppp.client] TRACE: PPP phase -> 0
0000015913 [net.ppp.client] TRACE: PPP thread event ADM_DOWN
0000015913 [net.ppp.client] TRACE: PPP thread event DOWN
0000015924 [net.ppp.client] TRACE: State DISCONNECTING -> DISCONNECTED
0000015927 [net.ppp.client] TRACE: State DISCONNECTED -> NONE
0000015936 [system.nm] INFO: State changed: IFACE_UP -> IFACE_REQUEST_DOWN
0000015938 [system.nm] INFO: State changed: IFACE_REQUEST_DOWN -> IFACE_DOWN
0000015946 [system.nm] TRACE: Request to power off the interface
0000015950 [system.nm] TRACE: Interface 4 power state: 2
0000015959 [system.nm] INFO: State changed: IFACE_DOWN -> DISABLED
0000016019 [ncp.at] TRACE: < OK
0000016020 [ncp.client] TRACE: NCP connection state changed: 0
0000016020 [net.pppncp] TRACE: NCP event 2
0000016025 [net.pppncp] TRACE: State changed event: 0
0000016031 [ncp.at] TRACE: < +CEREG: 0
0000016032 [net.pppncp] TRACE: PPP netif event from queue: 4
0000016036 [net.pppncp] TRACE: NCP event 3
0000016042 [net.pppncp] TRACE: NCP power state changed: IF_POWER_STATE_POWERING_DOWN
0000016047 [system.nm] TRACE: Interface 4 power state changed: 3
0000016054 [ncp.client] TRACE: Try powering modem off using AT command
0000016032 [net.ppp.client] TRACE: PPP thread event LOWER_DOWN
0000016060 [ncp.at] TRACE: > AT+CPWROFF
0000016070 [ncp.at] TRACE: < OK
0000016070 [ncp.client] TRACE: Waiting the modem to be turned off...
0000016096 [net.pppncp] TRACE: NCP event 3
0000016096 [net.pppncp] TRACE: NCP power state changed: IF_POWER_STATE_DOWN
0000016097 [system.nm] TRACE: Interface 4 power state changed: 1
0000016108 [ncp.client] TRACE: It takes 37 ms to power off the modem.
0000016108 [gsm0710muxer] INFO: Stopping GSM07.10 muxer
0000016119 [gsm0710muxer] INFO: Gracefully stopping GSM07.10 muxer
0000016119 [gsm0710muxer] INFO: Closing all muxed channels
0000016130 [gsm0710muxer] INFO: Closing mux channel 1
0000016130 [gsm0710muxer] INFO: Closing mux channel 2
0000016141 [gsm0710muxer] INFO: Muxed channel 3 already closed
0000016141 [gsm0710muxer] INFO: Muxed channel 4 already closed
0000016152 [gsm0710muxer] INFO: GSM07.10 muxer thread exiting
0000016153 [gsm0710muxer] INFO: GSM07.10 muxer stopped
0000016163 [ncp.client] TRACE: Setting UART voltage translator state 0
0000016164 [ncp.client] TRACE: Soft power off modem successfully
0000016174 [ncp.client] TRACE: Deinit modem serial.
0000016175 [app] INFO: checkpoint 4
0000016176 [app] INFO: entering sleep...
0000016185 [system.sleep] TRACE: Entering system_sleep_ext()
0000016186 [app] ERROR: this ain't right (0)
0000016275 [ncp.client] TRACE: Modem already off
0000016275 [ncp.client] TRACE: Setting UART voltage translator state 0
0000016276 [ncp.client] TRACE: Soft power off modem successfully
0000016284 [ncp.client] TRACE: Deinit modem serial.
0000016287 [ncp.client] TRACE: NCP state changed: 0
0000016295 [net.pppncp] TRACE: NCP event 1
0000017196 [app] INFO: entering sleep...
0000017197 [system.sleep] TRACE: Entering system_sleep_ext()
0000017197 [app] ERROR: this ain't right (0)
0000018199 [app] INFO: entering sleep...
0000018199 [system.sleep] TRACE: Entering system_sleep_ext()
0000018200 [app] ERROR: this ain't right (0)
0000019209 [app] INFO: entering sleep...
0000019210 [system.sleep] TRACE: Entering system_sleep_ext()
0000019210 [app] ERROR: this ain't right (0)
0000020219 [app] INFO: entering sleep...
0000020219 [system.sleep] TRACE: Entering system_sleep_ext()
0000020220 [app] ERROR: this ain't right (0)
0000021226 [app] INFO: entering sleep...
0000021227 [system.sleep] TRACE: Entering system_sleep_ext()
0000021227 [app] ERROR: this ain't right (0)
0000022232 [app] INFO: entering sleep...
0000022232 [system.sleep] TRACE: Entering system_sleep_ext()
0000022233 [app] ERROR: this ain't right (0)
0000023236 [app] INFO: entering sleep...
0000023236 [system.sleep] TRACE: Entering system_sleep_ext()
0000023237 [app] ERROR: this ain't right (0)
0000024248 [app] INFO: entering sleep...
0000024248 [system.sleep] TRACE: Entering system_sleep_ext()

It just repeats the same thing from this point on; still drawing 4 mA. Wake up reason is 0, which from the definition of the struct it’s likely the first one, i.e. UNKNOWN.

9

@stanleylio ,

I can confirm that, when I run your sketch, I get the same result.

I think the issue here is that you have not given the sleep configuration any way to wake. If you add this line in setup()

  pinMode(D3,INPUT_PULLDOWN);

and change your sleep configuration to this:

  c.mode(SystemSleepMode::ULTRA_LOW_POWER)
    .gpio(D3,RISING);

I think you will see the expected result.

0000027262 [app] INFO: checkpoint 3
0000027361 [system] INFO: Cloud: disconnecting
0000027582 [comm.protocol] TRACE: Reply recieved: type=2, code=0
0000027582 [comm.protocol] TRACE: message id 121 complete with code 0.00
0000027584 [comm.protocol] TRACE: rcv'd message type=13
0000028364 [system] INFO: Cloud: disconnected
0000028364 [net.pppncp] TRACE: PPP netif event from queue: 2
0000028365 [net.ppp.client] TRACE: PPP thread event LOWER_DOWN
0000028366 [net.ppp.client] TRACE: State CONNECTED -> DISCONNECT
0000028366 [net.ppp.client] TRACE: State DISCONNECT -> DISCONNECTING
0000028366 [ncp.at] TRACE: > AT+CFUN=0
0000028368 [system.nm] INFO: State changed: IP_CONFIGURED -> IFACE_UP
0000028368 [net.ppp.client] TRACE: PPP phase -> 9
0000028369 [net.ppp.client] TRACE: PPP phase -> 6
0000028369 [net.ppp.client] TRACE: PPP phase -> 12
0000028370 [net.ppp.client] TRACE: PPP phase -> 0
0000028370 [net.ppp.client] TRACE: PPP thread event ADM_DOWN
0000028371 [net.ppp.client] TRACE: PPP thread event DOWN
0000028371 [net.ppp.client] TRACE: State DISCONNECTING -> DISCONNECTED
0000028372 [net.ppp.client] TRACE: State DISCONNECTED -> NONE
0000028374 [system.nm] INFO: State changed: IFACE_UP -> IFACE_REQUEST_DOWN
0000028380 [system.nm] INFO: State changed: IFACE_REQUEST_DOWN -> IFACE_DOWN
0000028381 [system.nm] TRACE: Request to power off the interface
0000028382 [system.nm] TRACE: Interface 4 power state: 2
0000028382 [system.nm] INFO: State changed: IFACE_DOWN -> DISABLED
0000028486 [ncp.at] TRACE: < OK
0000028487 [ncp.client] TRACE: NCP connection state changed: 0
0000028488 [net.pppncp] TRACE: NCP event 2
0000028488 [net.pppncp] TRACE: State changed event: 0
0000028488 [net.ppp.client] TRACE: PPP thread event LOWER_DOWN
0000028489 [ncp.at] TRACE: < +CEREG: 0
0000028489 [net.pppncp] TRACE: PPP netif event from queue: 4
0000028490 [net.pppncp] TRACE: NCP event 3
0000028490 [net.pppncp] TRACE: NCP power state changed: IF_POWER_STATE_POWERING_DOWN
0000028491 [system.nm] TRACE: Interface 4 power state changed: 3
0000028491 [ncp.client] TRACE: Try powering modem off using AT command
0000028493 [ncp.at] TRACE: > AT+CPWROFF
0000028501 [ncp.at] TRACE: < OK
0000028501 [ncp.client] TRACE: Waiting the modem to be turned off...
0000028540 [net.pppncp] TRACE: NCP event 3
0000028541 [net.pppncp] TRACE: NCP power state changed: IF_POWER_STATE_DOWN
0000028541 [system.nm] TRACE: Interface 4 power state changed: 1
0000028542 [ncp.client] TRACE: It takes 41 ms to power off the modem.
0000028543 [gsm0710muxer] INFO: Stopping GSM07.10 muxer
0000028543 [gsm0710muxer] INFO: Gracefully stopping GSM07.10 muxer
0000028544 [gsm0710muxer] INFO: Closing all muxed channels
0000028544 [gsm0710muxer] INFO: Closing mux channel 1
0000028545 [gsm0710muxer] INFO: Closing mux channel 2
0000028546 [gsm0710muxer] INFO: Muxed channel 3 already closed
0000028546 [gsm0710muxer] INFO: Muxed channel 4 already closed
0000028547 [gsm0710muxer] INFO: GSM07.10 muxer thread exiting
0000028547 [gsm0710muxer] INFO: GSM07.10 muxer stopped
0000028548 [ncp.client] TRACE: Setting UART voltage translator state 0
0000028548 [ncp.client] TRACE: Soft power off modem successfully
0000028549 [ncp.client] TRACE: Deinit modem serial.
0000028550 [app] INFO: checkpoint 4
0000028551 [app] INFO: entering sleep...
0000028551 [system.sleep] TRACE: Entering system_sleep_ext()
0000028552 [system.sleep] TRACE: Interface 4 is off already
0000028552 [system.sleep] TRACE: Interface 3 is off already

Chip

4 Likes
10

Chip is correct. You need to have at least one wake condition (duration, GPIO, etc.) or you won’t go to sleep.

1 Like
11

Good Catch @chipmc !

1 Like