Blocking system functions and graceful power off

Firmware
1

Hi,

I’m writing firmware for a boron that is only allowed to stay powered for 15 minutes. This boron has to connect, then send messages, and then turn off the cellular modem gracefully (TAN004) before turning off.

While reading the documentation, I found some functions that may block or prevent me from gracefully turning off the cellular in time.

  • Particle.connect(): After you call Particle.connect(), your loop will not be called again until the device finishes connecting to the Cloud. Typically, you can expect a delay of approximately one second.
    Does that mean that loop will not be called anymore if the device fails to connect?

  • System functions: Synchronous system functions always block the caller until the system has performed the requested operation. These are the synchronous system functions: [...] Particle.subscribe(), Particle.publish()
    Again, does it block in case of failure?

  • Particle.timeSyncedLast(): It is possible that the call will block for an indeterminate amount of time, possibly for as long as 10 minutes. This can occur if the system thread is busy trying to reconnect to cellular and is unable to do so. Doing operations that access the cellular modem or require access to the system thread (as is the case for Particle.timeSyncedLast()) from a separate worker thread is a good workaround.
    How come this function wasn’t in the list of the “synchronous system functions” above?

So my plan right now is to make separate worker threads as advised above. However I’m concerned that it won’t allow me to gracefully turn off the cellular. For example: if one of my worker threads is blocked waiting for the system thread to finish reconnecting to cellular, then how can I be sure that Particle.disconnect() or Cellular.off() won’t also be blocked waiting for the system thread to finish its current operation?

Below is a simplified version of my code. Let me know if you have any tips to make sure that the cellular turns off gracefully every time. Boron is turned off automatically after 15 minutes no matter what.
Thank you in advance.

SYSTEM_MODE(SEMI_AUTOMATIC);
SYSTEM_THREAD(ENABLED);

int state = 0;

void setup() {
}

void loop() {
    if (state == 0) {
        // Connect and sync time
        Particle.connect();
        waitFor(Particle.connected, 13*60*1000);
        if (Particle.connected()) {
            Particle.syncTime();
            waitFor(Particle.syncTimeDone, 10*1000);
            // Here I do use Particle.timeSyncedLast()
        }
        state = 1;
    }
    if (state == 1) {
        // Publish if necessary and there's enough time left
        if (millis() < 14*60*1000 && needsToSend()) {
            Particle.process();
            if (Particle.connected()) {
                Particle.publish(...);
            } else {
                state = 2;
            }
        } else {
            state = 2;
        }
    }
    if (state == 2) {
        // Disconnect gracefully
        Particle.disconnect(CloudDisconnectOptions().graceful(true).timeout(5000));
        waitFor(Particle.disconnected, 5000);
        Cellular.off();
        waitFor(Cellular.isOff, 30000);
        state = 3;
    }
}
2

The note for Particle.connect() only applies in non-threaded mode. It should not block in the threaded mode, which is why you need to call Particle.connected() to find out if it has connected. You don’t generally have to worry about connect blocking.

The list of synchronous functions is not complete. There are also two difference classes of blocking functions: those that do not return until the operation completes in non-threaded mode (that list) and functions that run on the system thread in threaded mode (timeSyncedLast). If the system thread is blocked, that will cause functions like timeSyncedLast to block.

Incidentally, you should not sync time after connecting to the cloud. It’s already done on every cloud connection so doing it again isn’t useful.

You can solve for almost every case with the following:

  • Don’t sync time. Time.isValid() is safe to use.
  • Do Particle.publish() and Cellular.RSSI() only from a worker thread
  • Before publishing, also check for Particle.connected() and skip if not connected
  • To see how to do the publish from a background thread see this library
  • Subscribe from setup() before connecting to the cloud; it won’t block in this case.

If you do these things you will mostly avoid the dreaded 10 minute blocking until the cellular modem resets situation.

3

Thanks a lot! I’ll follow these guidelines. The reason I’m syncing time again is because I need time to be a little more accurate than up to the second.

And just to be sure, what will happen if for example my worker thread #1 calls Particle.publish(), it blocks because of bad cellular, then some seconds later my worker thread #2 calls Particle.disconnect() followed by Cellular.off() ?

I’m worried that my worker thread #2 won’t turn off the cellular as fast as I’d like it to if the system thread is blocked for whatever reason.

4

The RTC on the Boron only has one second resolution, and even then it's not particularly stable. It's really just a counter that's clocked off the MCU 32 kHz crystal oscillator which is not a precise time reference. Also the Particle cloud time sync does not take into account network latency, so it will always be slightly off. If you need really accurate time you should use GNSS (GPS) or an external high-accuracy RTC and NTP.

And just to be sure, what will happen if for example my worker thread #1 calls Particle.publish(), it blocks because of bad cellular, then some seconds later my worker thread #2 calls Particle.disconnect() followed by Cellular.off() ?

If you check for Particle.connected() before the publish, it could block, but should only block for a maximum of 20 seconds.

5

Hi again,

I investigated more and found issues with Cellular.off().

I use a simple code to check how long it takes to turn off the modem:

SYSTEM_MODE(SEMI_AUTOMATIC);
SYSTEM_THREAD(ENABLED);

SerialLogHandler logHandler(LOG_LEVEL_ALL);

uint8_t state = 0;
uint32_t disconnectMillis;

void setup() {
    delay(1000);
}

void loop() {
    if (state == 0) {
        Log.info("Particle.connect()");
        Particle.connect();
        disconnectMillis = 5000 + random(60000);
        state = 2;
    }
    
    if (state == 2 && millis() >= disconnectMillis) {
        Log.info("Particle.disconnect()");
        Particle.disconnect(CloudDisconnectOptions().graceful(true).timeout(5000));
        waitFor(Particle.disconnected, 5000);
        Log.info("Cellular.off()");
        Cellular.off();
        waitFor(Cellular.isOff, 180000);
        Log.info("Cellular.isOff() = %u", Cellular.isOff());
        state = 3;
    }
    
}

My boron is powered with a good battery and plugged via usb so I can read logs. We also decreased significantly the signal’s quality. After the modem is turned off, I turn the boron off, then try again. In case you’re wondering, I delay the disconnection by a random amount in case the issue is time sensitive.

5% of the time it takes more than 20 seconds to turn off the modem.
1% of the time it takes more than 50 seconds to turn off the modem.

We’ve been having major issues with our modems dying randomly, this abnormal delay might explain why. It seems that waitFor(Cellular.isOff, 30000); as advised on TAN004 isn’t sufficient.

Here are the logs obtained from the code above:

64 seconds to turn off the modem (60038 ms → 124770 ms) 
0000001399 [app] INFO: Particle.connect()
0000001402 [system.nm] INFO: State changed: DISABLED -> IFACE_DOWN
0000001403 [system.nm] INFO: State changed: IFACE_DOWN -> IFACE_REQUEST_UP
0000001404 [ncp.client] TRACE: Powering modem on, ncpId: 0x44
0000001404 [net.pppncp] TRACE: NCP event 3
0000001405 [net.pppncp] TRACE: NCP power state changed: IF_POWER_STATE_POWERING_UP
0000001405 [system.nm] INFO: State changed: IFACE_REQUEST_UP -> IFACE_UP
0000001406 [system.nm] TRACE: Interface 4 power state changed: 4
0000001555 [net.pppncp] TRACE: NCP event 3
0000001556 [net.pppncp] TRACE: NCP power state changed: IF_POWER_STATE_UP
0000001556 [system.nm] TRACE: Interface 4 power state changed: 2
0000001556 [ncp.client] TRACE: Modem powered on
0000001557 [ncp.client] TRACE: Setting UART voltage translator state 1
0000001656 [ncp.client] TRACE: Setting UART voltage translator state 0
0000001756 [ncp.client] TRACE: Setting UART voltage translator state 1
0000002757 [ncp.at] TRACE: > AT
0000003758 [ncp.at] TRACE: > AT
0000004759 [ncp.at] TRACE: > AT
0000005760 [ncp.at] TRACE: > AT
0000006761 [ncp.at] TRACE: > AT
0000007269 [ncp.at] TRACE: < OK
0000007270 [ncp.client] TRACE: NCP ready to accept AT commands
0000007270 [ncp.at] TRACE: > AT
0000007271 [ncp.at] TRACE: < OK
0000007271 [ncp.at] TRACE: > ATI9
0000007273 [ncp.at] TRACE: < L0.0.00.00.05.12,A.02.19
0000007273 [ncp.at] TRACE: < OK
0000007274 [ncp.client] TRACE: App firmware: 219
0000007274 [ncp.at] TRACE: > AT+UGPIOC?
0000007275 [ncp.at] TRACE: < +UGPIOC:
0000007276 [ncp.at] TRACE: < 7,255
0000007276 [ncp.at] TRACE: < 16,255
0000007276 [ncp.at] TRACE: < 19,255
0000007277 [ncp.at] TRACE: < 23,0
0000007277 [ncp.at] TRACE: < 24,255
0000007277 [ncp.at] TRACE: < 25,255
0000007278 [ncp.at] TRACE: < 42,255
0000007278 [ncp.at] TRACE: < OK
0000007278 [ncp.at] TRACE: > AT+UGPIOR=23
0000007283 [ncp.at] TRACE: < +UGPIOR: 23,1
0000007283 [ncp.at] TRACE: < OK
0000007283 [ncp.client] INFO: Using internal SIM card
0000007284 [ncp.at] TRACE: > AT+CPIN?
0000007286 [ncp.at] TRACE: < +CME ERROR: SIM not inserted
0000008286 [ncp.at] TRACE: > AT+CPIN?
0000008287 [ncp.at] TRACE: < +PACSP0
0000008290 [ncp.at] TRACE: < +CPIN: READY
0000008290 [ncp.at] TRACE: < OK
0000008290 [ncp.at] TRACE: > AT+CCID
0000008294 [ncp.at] TRACE: < +CCID: 89014103273525938548
0000008294 [ncp.at] TRACE: < OK
0000008295 [ncp.at] TRACE: > AT+IFC?
0000008297 [ncp.at] TRACE: < +IFC: 2,2
0000008297 [ncp.at] TRACE: < OK
0000008297 [ncp.at] TRACE: > AT+CFUN=0,0
0000008397 [ncp.at] TRACE: < OK
0000008397 [ncp.at] TRACE: > AT+CFUN=1,0
0000008401 [ncp.at] TRACE: < OK
0000008401 [ncp.at] TRACE: > AT+CPIN?
0000008403 [ncp.at] TRACE: < +CPIN: READY
0000008404 [ncp.at] TRACE: < OK
0000008404 [ncp.at] TRACE: > AT+CCID
0000008407 [ncp.at] TRACE: < +CCID: 89014103273525938548
0000008407 [ncp.at] TRACE: < OK
0000008407 [ncp.at] TRACE: > AT+IFC?
0000008409 [ncp.at] TRACE: < +IFC: 2,2
0000008409 [ncp.at] TRACE: < OK
0000008410 [ncp.at] TRACE: > AT+IFC=2,2
0000008412 [ncp.at] TRACE: < OK
0000008413 [ncp.at] TRACE: > AT
0000008414 [ncp.at] TRACE: < OK
0000008414 [ncp.at] TRACE: > AT+IPR=460800
0000008424 [ncp.at] TRACE: < OK
0000009424 [ncp.at] TRACE: > AT
0000009427 [ncp.at] TRACE: < OK
0000009427 [ncp.at] TRACE: > AT+CCID
0000009430 [ncp.at] TRACE: < +CCID: 89014103273525938548
0000009431 [ncp.at] TRACE: < OK
0000009431 [ncp.at] TRACE: > AT+CIMI
0000009433 [ncp.at] TRACE: < 310410352593854
0000009434 [ncp.at] TRACE: < OK
0000009434 [ncp.at] TRACE: > AT+UMNOPROF?
0000009438 [ncp.at] TRACE: < +UMNOPROF: 2
0000009439 [ncp.at] TRACE: < OK
0000009439 [ncp.at] TRACE: > AT+COPS=3,2
0000009442 [ncp.at] TRACE: < OK
0000009442 [ncp.at] TRACE: > AT+CGEREP=1,0
0000009444 [ncp.at] TRACE: < OK
0000009445 [ncp.at] TRACE: > AT+URAT?
0000009447 [ncp.at] TRACE: < +CME ERROR: Operation not supported
0000009448 [ncp.at] TRACE: > AT+CPSMS?
0000009452 [ncp.at] TRACE: < +CPSMS:0,,,"01100000","00000000"
0000009453 [ncp.at] TRACE: < OK
0000009453 [ncp.at] TRACE: > AT+CEDRXS?
0000009455 [ncp.at] TRACE: < +CEDRXS:
0000009455 [ncp.at] TRACE: < OK
0000009456 [ncp.at] TRACE: > AT+CMUX=0,0,,1509,,,,,
0000009460 [ncp.at] TRACE: < OK
0000009460 [mux] INFO: Starting GSM07.10 muxer
0000009461 [mux] INFO: Openning mux channel 0
0000009461 [mux] INFO: GSM07.10 muxer thread started
0000009465 [mux] INFO: Openning mux channel 1
0000009467 [ncp.at] TRACE: > AT
0000009472 [ncp.at] TRACE: < OK
0000009472 [ncp.client] TRACE: NCP state changed: 1
0000009473 [net.pppncp] TRACE: NCP event 1
0000009473 [net.ppp.client] TRACE: PPP thread event ADM_UP data=0
0000009474 [net.ppp.client] TRACE: State NONE -> READY
0000009477 [ncp.at] TRACE: > AT
0000009482 [ncp.at] TRACE: < OK
0000009483 [ncp.at] TRACE: > AT+CFUN?
0000009486 [ncp.at] TRACE: < +CFUN: 1
0000009486 [ncp.at] TRACE: < OK
0000009487 [ncp.at] TRACE: > AT+CCID
0000009492 [ncp.at] TRACE: < +CCID: 89014103273525938548
0000009492 [ncp.at] TRACE: < OK
0000009493 [ncp.at] TRACE: > AT+CIMI
0000009498 [ncp.at] TRACE: < 310410352593854
0000009498 [ncp.at] TRACE: < OK
0000009499 [ncp.at] TRACE: > AT+CGDCONT?
0000009509 [ncp.at] TRACE: < +CGDCONT: 1,"IP","10569.mcs","0.0.0.0",0,0,0,0,0,0
0000009509 [ncp.at] TRACE: < +CGDCONT: 2,"IPV4V6","attm2mglobal","0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0",0,0,0,0,0,0
0000009510 [ncp.at] TRACE: < OK
0000009510 [ncp.at] TRACE: > AT+CFUN?
0000009515 [ncp.at] TRACE: < +CFUN: 1
0000009516 [ncp.at] TRACE: < OK
0000009516 [ncp.at] TRACE: > AT+CEREG=2
0000009521 [ncp.at] TRACE: < OK
0000009521 [ncp.client] TRACE: NCP connection state changed: 1
0000009521 [net.pppncp] TRACE: NCP event 2
0000009522 [net.pppncp] TRACE: State changed event: 1
0000009522 [net.ppp.client] TRACE: PPP thread event LOWER_DOWN data=0
0000009523 [ncp.at] TRACE: > AT+COPS?
0000009527 [ncp.at] TRACE: < +COPS: 0
0000009528 [ncp.at] TRACE: < OK
0000009528 [ncp.at] TRACE: > AT+CEREG?
0000009533 [ncp.at] TRACE: < +CEREG: 2,0
0000009534 [ncp.at] TRACE: < OK
0000024634 [ncp.at] TRACE: > AT+CEREG?
0000024641 [ncp.at] TRACE: < +CEREG: 2,1,"41C","104DF23",7
0000024643 [ncp.at] TRACE: < OK
0000024644 [ncp.at] TRACE: > AT+UCGED=5
0000024644 [ncp.at] TRACE: < +CEREG: 2
0000024644 [ncp.at] TRACE: < +CEREG: 1,"41C","104DF23",7
0000024649 [ncp.at] TRACE: < OK
0000024649 [ncp.at] TRACE: > AT+UCGED?
0000024655 [ncp.at] TRACE: < +RSRP: 355,700,"-134.50",
0000024655 [ncp.at] TRACE: < +RSRQ: 355,700,"-20.00",
0000024656 [ncp.at] TRACE: < OK
0000024755 [ncp.client] TRACE: NCP connection state changed: 2
0000024756 [mux] INFO: Openning mux channel 2
0000025922 [net.pppncp] TRACE: NCP event 100
0000025922 [net.pppncp] TRACE: New auth info
0000025925 [net.pppncp] TRACE: NCP event 2
0000025925 [net.pppncp] TRACE: State changed event: 2
0000025926 [ncp.at] TRACE: > AT+CIMI
0000025926 [net.ppp.client] TRACE: PPP thread event LOWER_UP data=0
0000025927 [net.ppp.client] TRACE: State READY -> CONNECT
0000025927 [net.ppp.client] TRACE: State CONNECT -> CONNECTING
0000025931 [ncp.at] TRACE: < 310410352593854
0000025932 [ncp.at] TRACE: < OK
0000025932 [ncp.at] TRACE: > AT
0000025936 [ncp.at] TRACE: < OK
0000025937 [ncp.at] TRACE: > AT+CGATT?
0000025945 [ncp.at] TRACE: < +CGATT: 1
0000025945 [ncp.at] TRACE: < OK
0000026946 [ncp.at] TRACE: > AT
0000026953 [ncp.at] TRACE: < OK
0000026954 [ncp.at] TRACE: > ATD*99***1#
0000026965 [ncp.at] TRACE: < CONNECT 150000000
0000026966 [net.ppp.client] TRACE: PPP phase -> Initialize
0000026966 [net.ppp.client] TRACE: PPP phase -> Establish
0000026967 [lwip.ppp] TRACE: sent [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0x58525ccc> <pcomp> <accomp>]
0000027120 [lwip.ppp] TRACE: rcvd [LCP ConfReq id=0x0 <asyncmap 0x0> <auth chap MD5> <magic 0xe33d823> <pcomp> <accomp>]
0000027121 [lwip.ppp] TRACE: sent [LCP ConfAck id=0x0 <asyncmap 0x0> <auth chap MD5> <magic 0xe33d823> <pcomp> <accomp>]
0000027124 [lwip.ppp] TRACE: rcvd [LCP ConfAck id=0x1 <asyncmap 0x0> <magic 0x58525ccc> <pcomp> <accomp>]
0000027125 [lwip.ppp] TRACE: sent [LCP EchoReq id=0x0 magic=0x58525ccc]
0000027125 [net.ppp.client] TRACE: PPP phase -> Authenticate
0000027273 [lwip.ppp] TRACE: rcvd [LCP DiscReq id=0x1 magic=0xe33d823]
0000027276 [lwip.ppp] TRACE: rcvd [CHAP Challenge id=0x1 <0556600eed281016850bb271e9c8ea53>, name = "UMTS_CHAP_SRVR"]
0000027277 [lwip.ppp] TRACE: sent [CHAP Response id=0x1 <5cf2783c44205004308ce08e4a598173>, name = ""]
0000027279 [lwip.ppp] TRACE: rcvd [LCP EchoRep id=0x0 magic=0xe33d823 58 52 5c cc]
0000027427 [lwip.ppp] TRACE: rcvd [CHAP Success id=0x1 ""]
0000027427 [net.ppp.client] TRACE: PPP phase -> Network
0000027427 [lwip.ppp] TRACE: sent [IPCP ConfReq id=0x1 <addr 0.0.0.0> <msdns1 8.8.8.8> <msdns2 8.8.4.4>]
0000027579 [lwip.ppp] TRACE: rcvd [IPCP ConfReq id=0x0]
0000027580 [lwip.ppp] TRACE: sent [IPCP ConfAck id=0x0]
0000027582 [lwip.ppp] TRACE: rcvd [IPCP ConfNak id=0x1 <addr 10.210.205.248> <msdns1 174.47.40.106> <msdns2 174.47.20.106>]
0000027583 [lwip.ppp] TRACE: sent [IPCP ConfReq id=0x2 <addr 10.210.205.248> <msdns1 174.47.40.106> <msdns2 174.47.20.106>]
0000027730 [lwip.ppp] TRACE: rcvd [IPCP ConfAck id=0x2 <addr 10.210.205.248> <msdns1 174.47.40.106> <msdns2 174.47.20.106>]
0000027731 [system.nm] INFO: State changed: IFACE_UP -> IFACE_LINK_UP
0000027732 [net.ppp.client] TRACE: PPP thread event UP data=0
0000027733 [net.ppp.client] TRACE: State CONNECTING -> CONNECTED
0000027733 [net.pppncp] TRACE: Negotiated MTU: 1500
0000027733 [system.nm] INFO: State changed: IFACE_LINK_UP -> IP_CONFIGURED
0000027734 [net.ppp.client] TRACE: PPP phase -> Running
0000027735 [system] INFO: Cloud: connecting
0000027739 [system] WARN: Failed to load session data from persistent storage
0000040192 [system] ERROR: Failed to determine server address
0000040193 [system] WARN: Cloud socket connection failed: -230
0000048237 [system] WARN: Internet available, cloud not reachable
0000048237 [system] WARN: Handling cloud error: 3
0000048338 [system] INFO: Cloud: connecting
0000048341 [system] WARN: Failed to load session data from persistent storage
0000054293 [system] INFO: Cloud socket connected
0000054294 [comm.protocol.handshake] INFO: Establish secure connection
0000054299 [comm.dtls] INFO: (CMPL,RENEG,NO_SESS,ERR) restoreStatus=2
0000060038 [app] INFO: Particle.disconnect()
0000060038 [app] INFO: Cellular.off()
0000123144 [comm.dtls] ERROR: handshake failed -6800
0000123144 [comm.dtls] ERROR: Invalid handshake state
0000123148 [comm.protocol.handshake] ERROR: Handshake failed: 17
0000124349 [system] WARN: Internet available, cloud not reachable
0000124350 [system] WARN: Cloud handshake failed, code=-220
0000124601 [system] INFO: Cloud: disconnecting
0000124605 [system] INFO: Cloud: disconnected
0000124606 [ncp.at] TRACE: > AT+CFUN=0,0
0000124606 [net.ppp.client] TRACE: PPP thread event LOWER_DOWN data=0
0000124607 [net.ppp.client] TRACE: State CONNECTED -> DISCONNECT
0000124607 [net.ppp.client] TRACE: State DISCONNECT -> DISCONNECTING
0000124608 [system.nm] INFO: State changed: IP_CONFIGURED -> IFACE_UP
0000124609 [net.ppp.client] TRACE: PPP phase -> Network
0000124609 [net.ppp.client] TRACE: PPP phase -> Establish
0000124609 [net.ppp.client] TRACE: PPP phase -> Disconnect
0000124610 [net.ppp.client] TRACE: PPP phase -> Dead
0000124611 [net.ppp.client] TRACE: PPP thread event ADM_DOWN data=0
0000124612 [net.ppp.client] TRACE: PPP thread event ERROR data=5
0000124613 [net.pppncp] ERROR: PPP error event data=5
0000124614 [net.ppp.client] TRACE: PPP thread event DOWN data=0
0000124615 [net.ppp.client] TRACE: State DISCONNECTING -> DISCONNECTED
0000124616 [net.ppp.client] TRACE: State DISCONNECTED -> NONE
0000124618 [system.nm] INFO: State changed: IFACE_UP -> IFACE_REQUEST_DOWN
0000124619 [system.nm] INFO: State changed: IFACE_REQUEST_DOWN -> IFACE_DOWN
0000124620 [system.nm] TRACE: Request to power off the interface
0000124621 [system.nm] TRACE: Interface 4 power state: 2
0000124623 [system.nm] INFO: State changed: IFACE_DOWN -> DISABLED
0000124711 [ncp.at] TRACE: < OK
0000124711 [ncp.client] TRACE: NCP connection state changed: 0
0000124711 [net.pppncp] TRACE: NCP event 2
0000124712 [net.pppncp] TRACE: State changed event: 0
0000124712 [net.pppncp] TRACE: NCP event 3
0000124712 [net.pppncp] TRACE: NCP power state changed: IF_POWER_STATE_POWERING_DOWN
0000124713 [system.nm] TRACE: Interface 4 power state changed: 3
0000124714 [ncp.client] TRACE: Try powering modem off using AT command
0000124712 [net.ppp.client] TRACE: PPP thread event LOWER_DOWN data=0
0000124715 [ncp.at] TRACE: > AT+CPWROFF
0000124716 [ncp.at] TRACE: < +CEREG: 0
0000124719 [ncp.at] TRACE: < OK
0000124719 [ncp.client] TRACE: Waiting the modem to be turned off...
0000124754 [net.pppncp] TRACE: NCP event 3
0000124755 [net.pppncp] TRACE: NCP power state changed: IF_POWER_STATE_DOWN
0000124755 [system.nm] TRACE: Interface 4 power state changed: 1
0000124755 [ncp.client] TRACE: It takes 36 ms to power off the modem.
0000124756 [mux] INFO: Stopping GSM07.10 muxer
0000124756 [mux] INFO: Gracefully stopping GSM07.10 muxer
0000124756 [mux] INFO: Closing all muxed channels
0000124757 [mux] INFO: Closing mux channel 1
0000124758 [mux] INFO: Closing mux channel 2
0000124758 [mux] INFO: Muxed channel 3 already closed
0000124759 [mux] INFO: Muxed channel 4 already closed
0000124760 [mux] INFO: GSM07.10 muxer thread exiting
0000124761 [mux] INFO: GSM07.10 muxer stopped
0000124762 [ncp.client] TRACE: Setting UART voltage translator state 0
0000124763 [ncp.client] TRACE: Soft power off modem successfully
0000124764 [ncp.client] TRACE: Deinit modem serial.
0000124765 [ncp.client] TRACE: Modem already off
0000124765 [ncp.client] TRACE: Setting UART voltage translator state 0
0000124767 [ncp.client] TRACE: Soft power off modem successfully
0000124768 [ncp.client] TRACE: Deinit modem serial.
0000124768 [ncp.client] TRACE: NCP state changed: 0
0000124769 [net.pppncp] TRACE: NCP event 1
0000124770 [app] INFO: Cellular.isOff() = 1
57 seconds to turn off the modem (62520 ms → 119966 ms) 
0000001404 [app] INFO: Particle.connect()
0000001507 [system.nm] INFO: State changed: DISABLED -> IFACE_DOWN
0000001509 [system.nm] INFO: State changed: IFACE_DOWN -> IFACE_REQUEST_UP
0000001509 [ncp.client] TRACE: Powering modem on, ncpId: 0x44
0000001509 [net.pppncp] TRACE: NCP event 3
0000001510 [net.pppncp] TRACE: NCP power state changed: IF_POWER_STATE_POWERING_UP
0000001510 [system.nm] INFO: State changed: IFACE_REQUEST_UP -> IFACE_UP
0000001511 [system.nm] TRACE: Interface 4 power state changed: 4
0000001660 [net.pppncp] TRACE: NCP event 3
0000001661 [net.pppncp] TRACE: NCP power state changed: IF_POWER_STATE_UP
0000001661 [system.nm] TRACE: Interface 4 power state changed: 2
0000001661 [ncp.client] TRACE: Modem powered on
0000001662 [ncp.client] TRACE: Setting UART voltage translator state 1
0000001761 [ncp.client] TRACE: Setting UART voltage translator state 0
0000001861 [ncp.client] TRACE: Setting UART voltage translator state 1
0000002863 [ncp.at] TRACE: > AT
0000003864 [ncp.at] TRACE: > AT
0000004865 [ncp.at] TRACE: > AT
0000005866 [ncp.at] TRACE: > AT
0000006867 [ncp.at] TRACE: > AT
0000007411 [ncp.at] TRACE: < OK
0000007411 [ncp.client] TRACE: NCP ready to accept AT commands
0000007411 [ncp.at] TRACE: > AT
0000007413 [ncp.at] TRACE: < OK
0000007413 [ncp.at] TRACE: > ATI9
0000007413 [ncp.at] TRACE: < AT
0000007413 [ncp.at] TRACE: < OK
0000007414 [ncp.at] TRACE: < L0.0.00.00.05.12,
0000007415 [ncp.at] TRACE: > AT+UGPIOC?
0000007415 [ncp.at] TRACE: < OK
0000007417 [ncp.at] TRACE: < +UGPIOC:
0000007417 [ncp.at] TRACE: < 7,255
0000007417 [ncp.at] TRACE: < 16,255
0000007418 [ncp.at] TRACE: < 19,255
0000007418 [ncp.at] TRACE: < 23,0
0000007418 [ncp.at] TRACE: < 24,255
0000007419 [ncp.at] TRACE: < 25,255
0000007419 [ncp.at] TRACE: < 42,255
0000007419 [ncp.at] TRACE: < OK
0000007420 [ncp.at] TRACE: > AT+UGPIOR=23
0000007422 [ncp.at] TRACE: < +UGPIOR: 23,1
0000007423 [ncp.at] TRACE: < OK
0000007423 [ncp.client] INFO: Using internal SIM card
0000007423 [ncp.at] TRACE: > AT+CPIN?
0000007426 [ncp.at] TRACE: < +CME ERROR: SIM not inserted
0000008425 [ncp.at] TRACE: > AT+CPIN?
0000008426 [ncp.at] TRACE: < +PACSP0
0000008429 [ncp.at] TRACE: < +CPIN: READY
0000008429 [ncp.at] TRACE: < OK
0000008430 [ncp.at] TRACE: > AT+CCID
0000008433 [ncp.at] TRACE: < +CCID: 89014103273525938548
0000008434 [ncp.at] TRACE: < OK
0000008434 [ncp.at] TRACE: > AT+IFC?
0000008436 [ncp.at] TRACE: < +IFC: 2,2
0000008436 [ncp.at] TRACE: < OK
0000008437 [ncp.at] TRACE: > AT+CFUN=0,0
0000008475 [ncp.at] TRACE: < OK
0000008475 [ncp.at] TRACE: > AT+CFUN=1,0
0000008478 [ncp.at] TRACE: < OK
0000008478 [ncp.at] TRACE: > AT+CPIN?
0000008480 [ncp.at] TRACE: < +CPIN: READY
0000008480 [ncp.at] TRACE: < OK
0000008481 [ncp.at] TRACE: > AT+CCID
0000008484 [ncp.at] TRACE: < +CCID: 89014103273525938548
0000008485 [ncp.at] TRACE: < OK
0000008485 [ncp.at] TRACE: > AT+IFC?
0000008487 [ncp.at] TRACE: < +IFC: 2,2
0000008487 [ncp.at] TRACE: < OK
0000008487 [ncp.at] TRACE: > AT+IFC=2,2
0000008489 [ncp.at] TRACE: < OK
0000008490 [ncp.at] TRACE: > AT
0000008491 [ncp.at] TRACE: < OK
0000008491 [ncp.at] TRACE: > AT+IPR=460800
0000008500 [ncp.at] TRACE: < OK
0000009501 [ncp.at] TRACE: > AT
0000009504 [ncp.at] TRACE: < OK
0000009504 [ncp.at] TRACE: > AT+CCID
0000009507 [ncp.at] TRACE: < +CCID: 89014103273525938548
0000009508 [ncp.at] TRACE: < OK
0000009508 [ncp.at] TRACE: > AT+CIMI
0000009511 [ncp.at] TRACE: < 310410352593854
0000009511 [ncp.at] TRACE: < OK
0000009512 [ncp.at] TRACE: > AT+UMNOPROF?
0000009516 [ncp.at] TRACE: < +UMNOPROF: 2
0000009517 [ncp.at] TRACE: < OK
0000009517 [ncp.at] TRACE: > AT+COPS=3,2
0000009520 [ncp.at] TRACE: < OK
0000009520 [ncp.at] TRACE: > AT+CGEREP=1,0
0000009522 [ncp.at] TRACE: < OK
0000009523 [ncp.at] TRACE: > AT+URAT?
0000009525 [ncp.at] TRACE: < +CME ERROR: Operation not supported
0000009526 [ncp.at] TRACE: > AT+CPSMS?
0000009530 [ncp.at] TRACE: < +CPSMS:0,,,"01100000","00000000"
0000009531 [ncp.at] TRACE: < OK
0000009531 [ncp.at] TRACE: > AT+CEDRXS?
0000009533 [ncp.at] TRACE: < +CEDRXS:
0000009533 [ncp.at] TRACE: < OK
0000009534 [ncp.at] TRACE: > AT+CMUX=0,0,,1509,,,,,
0000009539 [ncp.at] TRACE: < OK
0000009539 [mux] INFO: Starting GSM07.10 muxer
0000009540 [mux] INFO: Openning mux channel 0
0000009540 [mux] INFO: GSM07.10 muxer thread started
0000009543 [mux] INFO: Openning mux channel 1
0000009546 [ncp.at] TRACE: > AT
0000009551 [ncp.at] TRACE: < OK
0000009551 [ncp.client] TRACE: NCP state changed: 1
0000009551 [net.pppncp] TRACE: NCP event 1
0000009552 [net.ppp.client] TRACE: PPP thread event ADM_UP data=0
0000009553 [net.ppp.client] TRACE: State NONE -> READY
0000009556 [ncp.at] TRACE: > AT
0000009560 [ncp.at] TRACE: < OK
0000009561 [ncp.at] TRACE: > AT+CFUN?
0000009565 [ncp.at] TRACE: < +CFUN: 1
0000009565 [ncp.at] TRACE: < OK
0000009566 [ncp.at] TRACE: > AT+CCID
0000009571 [ncp.at] TRACE: < +CCID: 89014103273525938548
0000009571 [ncp.at] TRACE: < OK
0000009572 [ncp.at] TRACE: > AT+CIMI
0000009576 [ncp.at] TRACE: < 310410352593854
0000009577 [ncp.at] TRACE: < OK
0000009577 [ncp.at] TRACE: > AT+CGDCONT?
0000009587 [ncp.at] TRACE: < +CGDCONT: 1,"IP","10569.mcs","0.0.0.0",0,0,0,0,0,0
0000009588 [ncp.at] TRACE: < +CGDCONT: 2,"IPV4V6","attm2mglobal","0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0",0,0,0,0,0,0
0000009588 [ncp.at] TRACE: < OK
0000009589 [ncp.at] TRACE: > AT+CFUN?
0000009594 [ncp.at] TRACE: < +CFUN: 1
0000009594 [ncp.at] TRACE: < OK
0000009595 [ncp.at] TRACE: > AT+CEREG=2
0000009599 [ncp.at] TRACE: < OK
0000009600 [ncp.client] TRACE: NCP connection state changed: 1
0000009600 [net.pppncp] TRACE: NCP event 2
0000009600 [net.pppncp] TRACE: State changed event: 1
0000009601 [ncp.at] TRACE: > AT+COPS?
0000009601 [net.ppp.client] TRACE: PPP thread event LOWER_DOWN data=0
0000009606 [ncp.at] TRACE: < +COPS: 0
0000009606 [ncp.at] TRACE: < OK
0000009607 [ncp.at] TRACE: > AT+CEREG?
0000009612 [ncp.at] TRACE: < +CEREG: 2,0
0000009612 [ncp.at] TRACE: < OK
0000024613 [ncp.at] TRACE: > AT+CEREG?
0000024623 [ncp.at] TRACE: < +CEREG: 2,1,"41C","104DF23",7
0000024623 [ncp.at] TRACE: < OK
0000024624 [ncp.at] TRACE: > AT+UCGED=5
0000024624 [ncp.at] TRACE: < +CEREG: 2
0000024625 [ncp.at] TRACE: < +CEREG: 1,"41C","104DF23",7
0000024634 [ncp.at] TRACE: < OK
0000024634 [ncp.at] TRACE: > AT+UCGED?
0000024640 [ncp.at] TRACE: < +RSRP: 355,700,"-135.20",
0000024640 [ncp.at] TRACE: < +RSRQ: 355,700,"-20.00",
0000024640 [ncp.at] TRACE: < OK
0000024740 [ncp.client] TRACE: NCP connection state changed: 2
0000024741 [mux] INFO: Openning mux channel 2
0000025907 [net.pppncp] TRACE: NCP event 100
0000025908 [net.pppncp] TRACE: New auth info
0000025910 [net.pppncp] TRACE: NCP event 2
0000025911 [net.pppncp] TRACE: State changed event: 2
0000025911 [net.ppp.client] TRACE: PPP thread event LOWER_UP data=0
0000025912 [net.ppp.client] TRACE: State READY -> CONNECT
0000025912 [net.ppp.client] TRACE: State CONNECT -> CONNECTING
0000025912 [ncp.at] TRACE: > AT+CIMI
0000025916 [ncp.at] TRACE: < 310410352593854
0000025917 [ncp.at] TRACE: < OK
0000025917 [ncp.at] TRACE: > AT
0000025925 [ncp.at] TRACE: < OK
0000025925 [ncp.at] TRACE: > AT+CGATT?
0000025933 [ncp.at] TRACE: < +CGATT: 1
0000025933 [ncp.at] TRACE: < OK
0000026935 [ncp.at] TRACE: > AT
0000026942 [ncp.at] TRACE: < OK
0000026943 [ncp.at] TRACE: > ATD*99***1#
0000026955 [ncp.at] TRACE: < CONNECT 150000000
0000026955 [net.ppp.client] TRACE: PPP phase -> Initialize
0000026956 [net.ppp.client] TRACE: PPP phase -> Establish
0000026956 [lwip.ppp] TRACE: sent [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0x58525cbc> <pcomp> <accomp>]
0000027109 [lwip.ppp] TRACE: rcvd [LCP ConfReq id=0x0 <asyncmap 0x0> <auth chap MD5> <magic 0xe6503fd> <pcomp> <accomp>]
0000027110 [lwip.ppp] TRACE: sent [LCP ConfAck id=0x0 <asyncmap 0x0> <auth chap MD5> <magic 0xe6503fd> <pcomp> <accomp>]
0000027112 [lwip.ppp] TRACE: rcvd [LCP ConfAck id=0x1 <asyncmap 0x0> <magic 0x58525cbc> <pcomp> <accomp>]
0000027113 [lwip.ppp] TRACE: sent [LCP EchoReq id=0x0 magic=0x58525cbc]
0000027114 [net.ppp.client] TRACE: PPP phase -> Authenticate
0000027262 [lwip.ppp] TRACE: rcvd [LCP DiscReq id=0x1 magic=0xe6503fd]
0000027264 [lwip.ppp] TRACE: rcvd [CHAP Challenge id=0x1 <2d2d22ee1d140df96b28a73b1b96dcbc>, name = "UMTS_CHAP_SRVR"]
0000027266 [lwip.ppp] TRACE: sent [CHAP Response id=0x1 <79934e310d08df6e2eaae711efa913e1>, name = ""]
0000027267 [lwip.ppp] TRACE: rcvd [LCP EchoRep id=0x0 magic=0xe6503fd 58 52 5c bc]
0000027415 [lwip.ppp] TRACE: rcvd [CHAP Success id=0x1 ""]
0000027415 [net.ppp.client] TRACE: PPP phase -> Network
0000027416 [lwip.ppp] TRACE: sent [IPCP ConfReq id=0x1 <addr 0.0.0.0> <msdns1 8.8.8.8> <msdns2 8.8.4.4>]
0000027569 [lwip.ppp] TRACE: rcvd [IPCP ConfReq id=0x0]
0000027569 [lwip.ppp] TRACE: sent [IPCP ConfAck id=0x0]
0000027571 [lwip.ppp] TRACE: rcvd [IPCP ConfNak id=0x1 <addr 10.210.205.248> <msdns1 174.47.40.106> <msdns2 174.47.20.106>]
0000027572 [lwip.ppp] TRACE: sent [IPCP ConfReq id=0x2 <addr 10.210.205.248> <msdns1 174.47.40.106> <msdns2 174.47.20.106>]
0000027719 [lwip.ppp] TRACE: rcvd [IPCP ConfAck id=0x2 <addr 10.210.205.248> <msdns1 174.47.40.106> <msdns2 174.47.20.106>]
0000027720 [system.nm] INFO: State changed: IFACE_UP -> IFACE_LINK_UP
0000027721 [net.ppp.client] TRACE: PPP thread event UP data=0
0000027722 [net.ppp.client] TRACE: State CONNECTING -> CONNECTED
0000027722 [net.pppncp] TRACE: Negotiated MTU: 1500
0000027722 [system.nm] INFO: State changed: IFACE_LINK_UP -> IP_CONFIGURED
0000027723 [net.ppp.client] TRACE: PPP phase -> Running
0000027724 [system] INFO: Cloud: connecting
0000027728 [system] WARN: Failed to load session data from persistent storage
0000043198 [system] ERROR: Failed to determine server address
0000043198 [system] WARN: Cloud socket connection failed: -230
0000051198 [system] WARN: Internet test failed: DNS
0000051198 [system] WARN: Handling cloud error: 2
0000051298 [system] INFO: Cloud: connecting
0000051300 [system] WARN: Failed to load session data from persistent storage
0000062520 [app] INFO: Particle.disconnect()
0000062520 [app] INFO: Cellular.off()
0000064837 [system] INFO: Cloud socket connected
0000064837 [comm.protocol.handshake] INFO: Establish secure connection
0000064843 [comm.dtls] INFO: (CMPL,RENEG,NO_SESS,ERR) restoreStatus=2
0000111786 [comm.dtls] ERROR: handshake failed -6800
0000111787 [comm.dtls] ERROR: Invalid handshake state
0000111791 [comm.protocol.handshake] ERROR: Handshake failed: 17
0000119198 [system] WARN: Internet test failed: DNS
0000119198 [system] WARN: Cloud handshake failed, code=-220
0000119448 [system] INFO: Cloud: disconnecting
0000119448 [system] INFO: Cloud: disconnected
0000119449 [net.ppp.client] TRACE: PPP thread event LOWER_DOWN data=0
0000119450 [net.ppp.client] TRACE: State CONNECTED -> DISCONNECT
0000119450 [net.ppp.client] TRACE: State DISCONNECT -> DISCONNECTING
0000119450 [ncp.at] TRACE: > AT+CFUN=0,0
0000119451 [system.nm] INFO: State changed: IP_CONFIGURED -> IFACE_UP
0000119452 [net.ppp.client] TRACE: PPP phase -> Network
0000119452 [net.ppp.client] TRACE: PPP phase -> Establish
0000119452 [net.ppp.client] TRACE: PPP phase -> Disconnect
0000119453 [net.ppp.client] TRACE: PPP phase -> Dead
0000119453 [net.ppp.client] TRACE: PPP thread event ADM_DOWN data=0
0000119454 [net.ppp.client] TRACE: PPP thread event ERROR data=5
0000119455 [net.pppncp] ERROR: PPP error event data=5
0000119456 [net.ppp.client] TRACE: PPP thread event DOWN data=0
0000119457 [net.ppp.client] TRACE: State DISCONNECTING -> DISCONNECTED
0000119458 [net.ppp.client] TRACE: State DISCONNECTED -> NONE
0000119460 [system.nm] INFO: State changed: IFACE_UP -> IFACE_REQUEST_DOWN
0000119464 [system.nm] INFO: State changed: IFACE_REQUEST_DOWN -> IFACE_DOWN
0000119464 [system.nm] TRACE: Request to power off the interface
0000119464 [system.nm] TRACE: Interface 4 power state: 2
0000119465 [system.nm] INFO: State changed: IFACE_DOWN -> DISABLED
0000119907 [ncp.at] TRACE: < OK
0000119907 [ncp.client] TRACE: NCP connection state changed: 0
0000119907 [net.pppncp] TRACE: NCP event 2
0000119908 [net.pppncp] TRACE: State changed event: 0
0000119908 [net.pppncp] TRACE: NCP event 3
0000119908 [net.pppncp] TRACE: NCP power state changed: IF_POWER_STATE_POWERING_DOWN
0000119909 [system.nm] TRACE: Interface 4 power state changed: 3
0000119910 [ncp.client] TRACE: Try powering modem off using AT command
0000119908 [net.ppp.client] TRACE: PPP thread event LOWER_DOWN data=0
0000119911 [ncp.at] TRACE: > AT+CPWROFF
0000119911 [ncp.at] TRACE: < +CEREG: 0
0000119915 [ncp.at] TRACE: < OK
0000119915 [ncp.client] TRACE: Waiting the modem to be turned off...
0000119950 [net.pppncp] TRACE: NCP event 3
0000119951 [net.pppncp] TRACE: NCP power state changed: IF_POWER_STATE_DOWN
0000119951 [system.nm] TRACE: Interface 4 power state changed: 1
0000119952 [ncp.client] TRACE: It takes 37 ms to power off the modem.
0000119952 [mux] INFO: Stopping GSM07.10 muxer
0000119952 [mux] INFO: Gracefully stopping GSM07.10 muxer
0000119952 [mux] INFO: Closing all muxed channels
0000119953 [mux] INFO: Closing mux channel 1
0000119953 [mux] INFO: Closing mux channel 2
0000119954 [mux] INFO: Muxed channel 3 already closed
0000119955 [mux] INFO: Muxed channel 4 already closed
0000119955 [mux] INFO: GSM07.10 muxer thread exiting
0000119956 [mux] INFO: GSM07.10 muxer stopped
0000119957 [ncp.client] TRACE: Setting UART voltage translator state 0
0000119958 [ncp.client] TRACE: Soft power off modem successfully
0000119959 [ncp.client] TRACE: Deinit modem serial.
0000119960 [ncp.client] TRACE: Modem already off
0000119961 [ncp.client] TRACE: Setting UART voltage translator state 0
0000119962 [ncp.client] TRACE: Soft power off modem successfully
0000119963 [ncp.client] TRACE: Deinit modem serial.
0000119964 [ncp.client] TRACE: NCP state changed: 0
0000119964 [net.pppncp] TRACE: NCP event 1
0000119966 [app] INFO: Cellular.isOff() = 1

I believe that for this issue, there is nothing I can do except increase the amount of time that we wait for the modem to turn off? How about calling Cellular.command("AT+CPWROFF"); myself?

6

In the two cases where it took a long time to turn off cellular, you disconnected from the cloud before it finished connecting. I’m not completely sure which will be the best method, but a few things that might work:

  • Wait for connection to succeed or fail on its own is the best if you can.
  • If not Particle.connected(), disconnect with graceful false. Not positive this will make a difference but it might.
  • If not Particle.connected() jump directly to Cellular.off, not disconnecting from the cloud at all.
7

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