[ncp.client] ERROR: AT+QPOWD command is not responding

Firmware
1

For some reason, I keep getting this error when trying to sleep (standard ULTRA_LOW_POWER sleep with no network standby for approx. 1 minutes). The device has disconnected and turned cellular off prior to this (with a waitUntil).

0001043221 [my.app] INFO: MEAS FSM -> SLEEP
0001043221 [my.app] INFO: MEAS FSM: SLEEP (dur=60 s)
0001043222 [my.app] INFO: Going to sleep...
0001049123 [ncp.client] ERROR: AT+QPOWD command is not responding

Problem is that it offsets my sleep calculations and synchronisations with 6-9 seconds, which is 'unhandled', because it happens after the program intends to sleep. It happens with both 6.3.3 and 6.3.4 it seems.

My disconnect function:

// Disconnect from Particle Cloud and cellular network
void MyCloud::disconnect()
{
   // Disconnect from cloud if connected
   if (Particle.connected())
   {
      Particle.disconnect();
      // Wait for Particle disconnect
      waitFor(Particle.disconnected, DeviceConfigurationConstants::DISCONNECT_TIMEOUT);
   }
   else
   {
      networkLogger.info("Cloud already disconnected; skipping disconnect.");
   }

   // Turn cellular module off when not using network standby
   if (!myClass::instance().getNetworkStandby())
   {
      if (Cellular.isOn())
      {
         Cellular.off();
         waitFor(Cellular.isOff, DeviceConfigurationConstants::DISCONNECT_TIMEOUT);
      }
      else
      {
         networkLogger.info("Modem already off; skipping power-down.");
      }
   }

   // Log final disconnect state before returning
   bool particleDisconnected = !Particle.connected();
   bool modemOn = Cellular.isOn();
   networkLogger.info("Disconnect state -> Particle.disconnected=%s, Cellular.isOn=%s",
                      particleDisconnected ? "true" : "false",
                      modemOn ? "true" : "false");
}
2

You really should not sleep for less than 10 minutes with cellular off. There is a high likelihood that your SIM card will be banned from the cellular network for frequent connection attempts.

There is no way to precisely control the amount of time it takes to actually go to sleep, and the duration is always added to that.

What are the log messages prior to the not responding error? My guess is that the modem was in the in-between state between being on and off when you invoked sleep, and then when it actually went to sleep, the modem had actually turned off.

3

Maybe I need to add some details here, it only sleeps for 2 minutes, wakes up, measures and goes back to sleep again. It never turns the cellular modem on again, well after 6 hours it does. But when measuring in a 2 minute interval, it only does so with cellular off and disconnected.

The logs messages before are more of the same, with the FSM (finite state machine state changes being logged)

4

In that case, you may need to set up Serial1 debugging using a USB to 3.3V serial adapter (FT232 or compatible) to debug. The cellular modem should not be turning on when waking up from sleep with it off before sleep, so it should not need to be turned off again. You'll need to see all of the log messages before it went to sleep, and immediately upon waking.

The problem is that USB serial takes too long to reconnect after sleep, and you'll lose all of the messages upon wake. The external adapter stays awake during sleep so the USB connection does not disconnect.

1 Like
5

I finally got some more logs about the process which happens after i call the Sleep-functon:

0000168285 [my.app] INFO: Going to sleep...
0000168285 [system.sleep] TRACE: Entering system_sleep_ext()
0000168287 [system.nm] INFO: State changed: IFACE_UP -> IFACE_REQUEST_DOWN
0000168288 [system.nm] INFO: State changed: IFACE_REQUEST_DOWN -> IFACE_DOWN
0000168288 [system.nm] TRACE: Request to power off interface 4
0000168289 [system.nm] TRACE: Interface 4 power state: POWERING_UP
0000168290 [system.nm] INFO: State changed: IFACE_DOWN -> DISABLED
0000168290 [system.sleep] TRACE: Waiting interface 4 to be off...
0000173160 [net.pppncp] TRACE: NCP event 3
0000173160 [net.pppncp] TRACE: NCP power state changed: IF_POWER_STATE_UP
0000173161 [system.nm] TRACE: Interface 4 power state changed: UP
0000173161 [ncp.client] TRACE: Modem powered on
0000173226 [ncp.at] TRACE: > AT
0000173226 [ncp.at] TRACE: < RDY
0000173295 [ncp.at] TRACE: < OK
0000173296 [ncp.client] TRACE: NCP ready to accept AT commands
0000173296 [ncp.at] TRACE: > AT+CFUN?
0000173347 [ncp.at] TRACE: < +CFUN: 1
0000173347 [ncp.at] TRACE: < OK
0000173348 [ncp.at] TRACE: > AT+QGMR
0000173376 [ncp.at] TRACE: < EG91EFBR06A07M4G_01.007.01.007
0000173376 [ncp.at] TRACE: < OK
0000173377 [ncp.at] TRACE: > AT+IFC=2,2
0000173385 [ncp.at] TRACE: < OK
0000173385 [ncp.at] TRACE: > AT
0000173387 [ncp.at] TRACE: < OK
0000173387 [ncp.at] TRACE: > AT+IPR=921600
0000173390 [ncp.at] TRACE: < OK
0000174391 [ncp.at] TRACE: > AT
0000174393 [ncp.at] TRACE: < OK
0000174395 [ncp.at] TRACE: > AT+CPIN?
0000174397 [ncp.at] TRACE: < +CPIN: READY
0000174397 [ncp.at] TRACE: < OK
0000174397 [ncp.at] TRACE: > AT+CCID
0000174398 [ncp.at] TRACE: < +CCID: 89883070000021697394
0000174399 [ncp.at] TRACE: < OK
0000174399 [ncp.at] TRACE: > AT+QDSIM=0
0000174400 [ncp.at] TRACE: < OK
0000174400 [ncp.at] TRACE: > AT+CMUX=0,0,8,1509,,,,,
0000174402 [ncp.at] TRACE: < OK
0000174402 [mux] INFO: Starting GSM07.10 muxer
0000174403 [mux] INFO: Opening mux channel 0
0000174403 [mux] INFO: GSM07.10 muxer thread started
0000174505 [mux] INFO: Opening mux channel 1
0000174507 [ncp.at] TRACE: > AT
0000174507 [ncp.at] TRACE: < POWERED DOWN
0000174509 [ncp.at] TRACE: < OK
0000174509 [ncp.client] TRACE: NCP state changed: 1
0000174510 [net.pppncp] TRACE: NCP event 1
0000174511 [ncp.at] TRACE: > AT+QCFG="cmux/urcport",1
0000174513 [ncp.at] TRACE: < OK
0000174514 [ncp.at] TRACE: > AT+CGEREP=1,0
0000174515 [ncp.at] TRACE: < OK
0000174516 [net.pppncp] TRACE: NCP event 3
0000174516 [net.pppncp] TRACE: NCP power state changed: IF_POWER_STATE_POWERING_DOWN
0000174517 [system.nm] TRACE: Interface 4 power state changed: POWERING_DOWN
0000174517 [ncp.client] TRACE: Try powering modem off using AT command
0000174518 [ncp.at] TRACE: > AT+QPOWD
0000174520 [ncp.at] TRACE: < ERROR
0000175019 [ncp.at] TRACE: > AT+QPOWD
0000175023 [ncp.at] TRACE: < ERROR
0000175523 [ncp.at] TRACE: > AT+QPOWD
0000175525 [ncp.at] TRACE: < ERROR
0000176024 [ncp.at] TRACE: > AT+QPOWD
0000176026 [ncp.at] TRACE: < ERROR
0000176525 [ncp.at] TRACE: > AT+QPOWD
0000176527 [ncp.at] TRACE: < ERROR
0000177027 [ncp.at] TRACE: > AT+QPOWD
0000177029 [ncp.at] TRACE: < ERROR
0000177529 [ncp.client] ERROR: AT+QPOWD command is not responding
0000177529 [mux] INFO: Stopping GSM07.10 muxer
0000177530 [mux] INFO: Gracefully stopping GSM07.10 muxer
0000177530 [mux] INFO: Closing all muxed channels
0000177531 [mux] INFO: Closing mux channel 1
0000177531 [mux] INFO: Muxed channel 2 already closed
0000177532 [mux] INFO: Muxed channel 3 already closed
0000177532 [mux] INFO: Muxed channel 4 already closed
0000177533 [mux] INFO: GSM07.10 muxer thread exiting
0000177533 [mux] INFO: GSM07.10 muxer stopped
0000177534 [ncp.client] TRACE: Powering modem off
0000199639 [net.pppncp] TRACE: NCP event 3
0000199639 [net.pppncp] TRACE: NCP power state changed: IF_POWER_STATE_DOWN
0000199640 [system.nm] TRACE: Interface 4 power state changed: DOWN
0000199640 [ncp.client] TRACE: Modem powered off
0000199641 [ncp.client] TRACE: Deinit modem serial.
0000199641 [ncp.client] TRACE: Modem already off
0000199642 [ncp.client] TRACE: Soft power off modem success
0000199642 [ncp.client] TRACE: Deinit modem serial.
0000199643 [ncp.client] TRACE: NCP state changed: 0
0000199643 [net.pppncp] TRACE: NCP event 1
0000199691 [system.sleep] TRACE: Interface 3 is off already

It looks like a race condition, where it tries to power it off, but then suddenly power state is POWERING_UP. I'm trying to investigate what is trying to turn the modem on again.

When we start up, we send data more often with network on standby, in that case, it closes down quickly, i.e.

0000423427 [my.app] INFO: Going to sleep...
0000423428 [system.sleep] TRACE: Entering system_sleep_ext()
0000423428 [system] INFO: Cloud: disconnecting
0000423429 [system] INFO: Cloud: disconnected
0000423429 [system.sleep] TRACE: Interface 3 is off already

But when we return to the normal measurement cycle with transmission every 6 hours, then we set network standby to off, that's when it starts to go wrong on entering sleep - at least sometimes it goes wrong (and then it goes wrong on each wakeup/sleep sequence). Sometimes it does not, and then it doesn't happen in subsequent cycles.

6

So it goes like this, when the device turns on:

Burst stage (measurement transmitted every 1 minute with network standby) for 15 minutes, after it disconnects and turns off the modem. Network standby is set to false.

Normal measurement stage (measurement every 1 minute, but put into a queue with modem turned off from before. After 30-180 measurement packages, it turns modem on, connects and transmits the payloads, disconnects, turns modem off and goes to sleep again, cycle continues.

After burst stage, the problem with the race condition/issue with powering off from above happens during the normal measurement stage. However, it seems as if after the normal measurement stage is transmitted and a new normal measurement sequence has started, the problem disappears - at least for now in my testing on a lab unit.

E.g. what should happen is this:

0003859756 [my.bluetooth] INFO: Beacon not found within 2000 ms, extending scan by 4000 ms
0003860233 [my.bluetooth] INFO: scan: start=3857619ms end=3860233ms dur=2614ms
0003860234 [my.bluetooth] TRACE: Beacon scan time [scanStart=3857619ms estBeacon=2898671ms scanEnd=3860233ms]
0003860236 [my.bluetooth] INFO: DB:58:1A:42:2C:BE measured following - distance: 1349, ampltitude: 750, battery: 3, temperature: 22, signalStrength: -52 
0003860237 [my.onboard] INFO: Measuring D01XX using onboard interface
0003860345 [my.app] INFO: MEAS FSM -> SLEEP
0003860345 [my.app] INFO: MEAS FSM: SLEEP (dur=60 s)
0003860346 [my.app] TRACE: Sleeping for 57271 ms...
0003860346 [my.app] INFO: Going to sleep...
0003860347 [system.sleep] TRACE: Entering system_sleep_ext()
0003860347 [system.sleep] TRACE: Interface 4 is off already
0003860348 [system.sleep] TRACE: Interface 3 is off already

The last four lines is key.

7

Upon waking up, these are the logs lines (I'll see if I can catch the ones prior to these as well):

Serial monitor opened successfully:
0002383174 [system.nm] INFO: State changed: DISABLED -> IFACE_DOWN
0002383175 [system.nm] INFO: State changed: IFACE_DOWN -> IFACE_REQUEST_UP
0002388175 [system.nm] INFO: State changed: IFACE_REQUEST_UP -> IFACE_UP

In this case, it should not be up, it should be powered down. I think that I may not be giving it enough time to disconnect in my

   Particle.disconnect();
   // Wait for Particle disconnect
   waitFor(Particle.disconnected, DeviceConfigurationConstants::DISCONNECT_TIMEOUT);

Where the timeout is 5000 ms

8

Writing if anybody has the same problem as I - I've done everything as written in the docs, but I still get cases where the Cellular modem is not turned off - after calling Particle.disconnect, waiting for 30 sec, then calling Cellular.off() and waiting for 60 seconds. Not sure why/how the device cannot turn off the modem within that timeperiod and with the consequence of the modem being brought on again next time the device goes out of sleep.

I suspose my next experiment is to send force power-down commands, such as AT+QPOWD=0 instead of using the DeviceOS commands.

9

@rickkas7 just wanted to hear your thoughts/experience on this - what's the best/most robust way to handle a cellular modem of a B524 not powering down? Retry? Give it more time? Or use AT commands and try to force it down myself?

It's the only Issue I have left in my current firmware, but I have yet to find a reliable way of prevent it or fixing it when it happens.

10

I would get trace logs during the shutdown process to see where it's getting stuck. It's highly unlikely that you would be able to issue a command manually that would be any more effective than what Device OS is doing, but knowing exactly which part of shut down is not working would narrow down the problem.

1 Like
11

What other trace logs can I access on top of these:

0000168285 [my.app] INFO: Going to sleep...
0000168285 [system.sleep] TRACE: Entering system_sleep_ext()
0000168287 [system.nm] INFO: State changed: IFACE_UP -> IFACE_REQUEST_DOWN
0000168288 [system.nm] INFO: State changed: IFACE_REQUEST_DOWN -> IFACE_DOWN
0000168288 [system.nm] TRACE: Request to power off interface 4
0000168289 [system.nm] TRACE: Interface 4 power state: POWERING_UP
0000168290 [system.nm] INFO: State changed: IFACE_DOWN -> DISABLED
0000168290 [system.sleep] TRACE: Waiting interface 4 to be off...
0000173160 [net.pppncp] TRACE: NCP event 3
0000173160 [net.pppncp] TRACE: NCP power state changed: IF_POWER_STATE_UP
0000173161 [system.nm] TRACE: Interface 4 power state changed: UP
0000173161 [ncp.client] TRACE: Modem powered on
0000173226 [ncp.at] TRACE: > AT
0000173226 [ncp.at] TRACE: < RDY
0000173295 [ncp.at] TRACE: < OK
0000173296 [ncp.client] TRACE: NCP ready to accept AT commands
0000173296 [ncp.at] TRACE: > AT+CFUN?
0000173347 [ncp.at] TRACE: < +CFUN: 1
0000173347 [ncp.at] TRACE: < OK
0000173348 [ncp.at] TRACE: > AT+QGMR
0000173376 [ncp.at] TRACE: < EG91EFBR06A07M4G_01.007.01.007
0000173376 [ncp.at] TRACE: < OK
0000173377 [ncp.at] TRACE: > AT+IFC=2,2
0000173385 [ncp.at] TRACE: < OK
0000173385 [ncp.at] TRACE: > AT
0000173387 [ncp.at] TRACE: < OK
0000173387 [ncp.at] TRACE: > AT+IPR=921600
0000173390 [ncp.at] TRACE: < OK
0000174391 [ncp.at] TRACE: > AT
0000174393 [ncp.at] TRACE: < OK
0000174395 [ncp.at] TRACE: > AT+CPIN?
0000174397 [ncp.at] TRACE: < +CPIN: READY
0000174397 [ncp.at] TRACE: < OK
0000174397 [ncp.at] TRACE: > AT+CCID
0000174398 [ncp.at] TRACE: < +CCID: 89883070000021697394
0000174399 [ncp.at] TRACE: < OK
0000174399 [ncp.at] TRACE: > AT+QDSIM=0
0000174400 [ncp.at] TRACE: < OK
0000174400 [ncp.at] TRACE: > AT+CMUX=0,0,8,1509,,,,,
0000174402 [ncp.at] TRACE: < OK
0000174402 [mux] INFO: Starting GSM07.10 muxer
0000174403 [mux] INFO: Opening mux channel 0
0000174403 [mux] INFO: GSM07.10 muxer thread started
0000174505 [mux] INFO: Opening mux channel 1
0000174507 [ncp.at] TRACE: > AT
0000174507 [ncp.at] TRACE: < POWERED DOWN
0000174509 [ncp.at] TRACE: < OK
0000174509 [ncp.client] TRACE: NCP state changed: 1
0000174510 [net.pppncp] TRACE: NCP event 1
0000174511 [ncp.at] TRACE: > AT+QCFG="cmux/urcport",1
0000174513 [ncp.at] TRACE: < OK
0000174514 [ncp.at] TRACE: > AT+CGEREP=1,0
0000174515 [ncp.at] TRACE: < OK
0000174516 [net.pppncp] TRACE: NCP event 3
0000174516 [net.pppncp] TRACE: NCP power state changed: IF_POWER_STATE_POWERING_DOWN
0000174517 [system.nm] TRACE: Interface 4 power state changed: POWERING_DOWN
0000174517 [ncp.client] TRACE: Try powering modem off using AT command
0000174518 [ncp.at] TRACE: > AT+QPOWD
0000174520 [ncp.at] TRACE: < ERROR
0000175019 [ncp.at] TRACE: > AT+QPOWD
0000175023 [ncp.at] TRACE: < ERROR
0000175523 [ncp.at] TRACE: > AT+QPOWD
0000175525 [ncp.at] TRACE: < ERROR
0000176024 [ncp.at] TRACE: > AT+QPOWD
0000176026 [ncp.at] TRACE: < ERROR
0000176525 [ncp.at] TRACE: > AT+QPOWD
0000176527 [ncp.at] TRACE: < ERROR
0000177027 [ncp.at] TRACE: > AT+QPOWD
0000177029 [ncp.at] TRACE: < ERROR
0000177529 [ncp.client] ERROR: AT+QPOWD command is not responding
0000177529 [mux] INFO: Stopping GSM07.10 muxer
0000177530 [mux] INFO: Gracefully stopping GSM07.10 muxer
0000177530 [mux] INFO: Closing all muxed channels
0000177531 [mux] INFO: Closing mux channel 1
0000177531 [mux] INFO: Muxed channel 2 already closed
0000177532 [mux] INFO: Muxed channel 3 already closed
0000177532 [mux] INFO: Muxed channel 4 already closed
0000177533 [mux] INFO: GSM07.10 muxer thread exiting
0000177533 [mux] INFO: GSM07.10 muxer stopped
0000177534 [ncp.client] TRACE: Powering modem off
0000199639 [net.pppncp] TRACE: NCP event 3
0000199639 [net.pppncp] TRACE: NCP power state changed: IF_POWER_STATE_DOWN
0000199640 [system.nm] TRACE: Interface 4 power state changed: DOWN
0000199640 [ncp.client] TRACE: Modem powered off
0000199641 [ncp.client] TRACE: Deinit modem serial.
0000199641 [ncp.client] TRACE: Modem already off
0000199642 [ncp.client] TRACE: Soft power off modem success
0000199642 [ncp.client] TRACE: Deinit modem serial.
0000199643 [ncp.client] TRACE: NCP state changed: 0
0000199643 [net.pppncp] TRACE: NCP event 1
0000199691 [system.sleep] TRACE: Interface 3 is off already
12

This is my understanding of what is happening, do note that I've called cellular.off before it goes to sleep:

0000445710 [system.sleep] TRACE: Entering system_sleep_ext()

Sleep requested while modem is still considered active

0000445711 [system.nm] INFO: State changed: IFACE_UP -> IFACE_REQUEST_DOWN    
0000445712 [system.nm] INFO: State changed: IFACE_REQUEST_DOWN -> IFACE_DOWN
0000445712 [system.nm] TRACE: Request to power off interface 4

Network manager requests modem power-off

0000445713 [system.nm] TRACE: Interface 4 power state: POWERING_UP
Conflict? modem is mistakenly marked as powering up instead of down

0000445714 [system.nm] INFO: State changed: IFACE_DOWN -> DISABLED
0000445714 [system.sleep] TRACE: Waiting interface 4 to be off...

Sleep waits for modem shutdown to complete

0000455662 [net.pppncp] TRACE: NCP event 3                                    
0000455663 [net.pppncp] TRACE: NCP power state changed: IF_POWER_STATE_UP
0000455663 [system.nm] TRACE: Interface 4 power state changed: UP
0000455664 [ncp.client] TRACE: Modem powered on

Modem is powered on again, opposite of intended shutdown

0000455695 [ncp.at] TRACE: > AT                                               
0000455695 [ncp.at] TRACE: < RDY
0000455701 [ncp.at] TRACE: < OK
0000455701 [ncp.client] TRACE: NCP ready to accept AT commands

DeviceOS begins modem boot/configure sequence again, as seen below:

0000455701 [ncp.at] TRACE: > AT+CFUN?
0000455812 [ncp.at] TRACE: < +CFUN: 0
0000455813 [ncp.at] TRACE: < OK
0000455813 [ncp.at] TRACE: > AT+CFUN=1,0
0000455859 [ncp.at] TRACE: < OK
0000455860 [ncp.at] TRACE: > AT+QGMR
0000455869 [ncp.at] TRACE: < EG91EFBR06A07M4G_01.007.01.007
0000455870 [ncp.at] TRACE: < OK

... (normal modem initialization continues)

0000456998 [ncp.at] TRACE: > AT
0000456998 [ncp.at] TRACE: < POWERED DOWN

Modem completes the original shutdown request here

0000457010 [ncp.at] TRACE: < OK
0000457011 [ncp.client] TRACE: NCP state changed: 1                            
0000457011 [net.pppncp] TRACE: NCP event 1

0000457012 [ncp.at] TRACE: > AT+QCFG="cmux/urcport",1

DeviceOS is still sending configuration commands to an off modem

0000457017 [ncp.at] TRACE: < OK
0000457018 [ncp.at] TRACE: > AT+CGEREP=1,0
0000457020 [ncp.at] TRACE: < OK

0000457020 [net.pppncp] TRACE: NCP event 3
0000457020 [net.pppncp] TRACE: NCP power state changed: IF_POWER_STATE_POWERING_DOWN
0000457021 [system.nm] TRACE: Interface 4 power state changed: POWERING_DOWN
0000457021 [ncp.client] TRACE: Try powering modem off using AT command

DeviceOS incorrectly attempts shutdown again using AT command

0000457022 [ncp.at] TRACE: > AT+QPOWD
0000457024 [ncp.at] TRACE: < ERROR

Tries to turn off the modem again, but

0000457524 [ncp.at] TRACE: > AT+QPOWD
0000457525 [ncp.at] TRACE: < +QIND: SMS DONE
0000457526 [ncp.at] TRACE: < ERROR

... (repeated QPOWD failures because modem is doing something else?)

0000460030 [ncp.client] ERROR: AT+QPOWD command is not responding
OS gives up on AT shutdown

0000460031 [mux] INFO: Stopping GSM07.10 muxer
... (mux shutdown)

0000460035 [ncp.client] TRACE: Powering modem off        
0000481929 [net.pppncp] TRACE: NCP event 3
0000481930 [net.pppncp] TRACE: NCP power state changed: IF_POWER_STATE_DOWN
0000481930 [system.nm] TRACE: Interface 4 power state changed: DOWN
0000481931 [ncp.client] TRACE: Modem powered off

Not sure here, because it seems to be confirmed that modem is powered off, but through AT commands earlier it seems like it might not be? or is it confirmed?

0000481931 [ncp.client] TRACE: Deinit modem serial.
0000481932 [ncp.client] TRACE: Modem already off
0000481932 [ncp.client] TRACE: Soft power off modem success
0000481933 [ncp.client] TRACE: Deinit modem serial.
0000482015 [system.sleep] TRACE: Interface 3 is off already

Now it seems to be safe to sleep? But not always the case, and unsure why it seems to be doing the opposite of what is being requested. There's no tricky sequence of connects and disconnects. It simply disconnects from Particle, runs Cellular.off and waits for isOff to return true for 60 seconds. Then proceeds to sleep.