Tracker device restarts without obvious reasons after system request to power off interface

Firmware Device OS
1

Hello.

Once in while without an obvious reason we get this in the serial monitor in our T524MKIT:

0000207211 [system.nm] TRACE: Request to power off the interface
0000207212 [ncp.esp32.mux] INFO: Stopping GSM07.10 muxer
0000207212 [ncp.esp32.mux] INFO: Gracefully stopping GSM07.10 muxer
0000207212 [ncp.esp32.mux] INFO: Closing all muxed channels
0000207213 [ncp.esp32.mux] INFO: Closing mux channel 1
0000207213 [ncp.esp32.mux] INFO: Muxed channel 2 already closed
0000207214 [ncp.esp32.mux] INFO: Muxed channel 3 already closed
0000207214 [ncp.esp32.mux] INFO: Muxed channel 4 already closed

Serial connection closed. Attempting to reconnect...

after which the device restarts. LiPo is activated, power comes from USB too. Cloud settings asset tracker sleep is disabled. Asset Tracker Firmware is v16, at 3.1.0. This repeats each 2-3 minutes.

Edit: additional dump - looks like it's connected with publishing somehow:

0000265263 [app] TRACE: evaluatePublish maxNetwork
0000265264 [app] TRACE: evaluatePublish max
0000265264 [app] TRACE: publishing from max interval
0000265264 [app] INFO: publishing now...
0000265301 [system.nm] TRACE: Request to power on the interface
0000265621 [hal] ERROR: Not found response
0000265641 [hal] ERROR: CMD0 response error, expect 0x1, response 0
0000265642 [hal] ERROR: Please restart slave and test again,error code:264
0000267704 [ncp.esp32.at] TRACE: > AT
0000267707 [ncp.esp32.at] TRACE: < OK
0000268707 [ncp.esp32.client] TRACE: NCP ready to accept AT commands
0000268709 [ncp.esp32.at] TRACE: > AT+MVER
0000268711 [ncp.esp32.at] TRACE: < 7
0000268712 [ncp.esp32.at] TRACE: < OK
0000268713 [ncp.esp32.at] TRACE: > AT+GETMAC=0
0000268715 [ncp.esp32.at] TRACE: < +GETMAC: "30:ae:a4:ac:37:d0"
0000268716 [ncp.esp32.at] TRACE: < OK
0000268718 [ncp.esp32.at] TRACE: > AT+CMUX=0
0000268721 [ncp.esp32.at] TRACE: < OK
0000268722 [ncp.esp32.mux] INFO: Starting GSM07.10 muxer
0000268722 [ncp.esp32.mux] INFO: Openning mux channel 0
0000268723 [ncp.esp32.mux] INFO: GSM07.10 muxer thread started
0000268729 [ncp.esp32.mux] INFO: Openning mux channel 1
0000268742 [ncp.esp32.at] TRACE: > AT
0000268751 [ncp.esp32.at] TRACE: < OK
0000268758 [ncp.esp32.at] TRACE: > AT+CWDHCP=0,3
0000268765 [ncp.esp32.at] TRACE: < OK
0000268765 [ncp.esp32.client] TRACE: NCP state changed: 1
0000268766 [system.nm] TRACE: Interface 5 power state changed: 2
0000268772 [ncp.esp32.at] TRACE: > AT+CWLAP
0000270881 [ncp.esp32.at] TRACE: < +CWLAP:(4,"TP-Link_988F",-43,"1c:3b:f3:8e:98:8f",7)
0000270882 [ncp.esp32.at] TRACE: < +CWLAP:(3,"",-44,"22:3b:f3:8e:98:8f",7)
0000270884 [ncp.esp32.at] TRACE: < +CWLAP:(3,":signal_strength::closed_lock_with_key:Asus​:globe_with_meridians:-:lithuania:",-66,"4c:ed:fb:a6:dd:40",1)
0000270885 [ncp.esp32.at] TRACE: < +CWLAP:(3,"TP-LINK_F6E2",-69,"18:a6:f7:c0:f6:e2",11)
0000270886 [ncp.esp32.at] TRACE: < +CWLAP:(3,"SavoNet_2G",-80,"d4:5d:64:df:7f:88",1)
0000270890 [ncp.esp32.at] TRACE: < +CWLAP:(3,"SGL",-82,"c0:25:2f:6f:12:83",9)
0000270891 [ncp.esp32.at] TRACE: < +CWLAP:(4,"30-2.4",-83,"d8:0d:17:a4:36:34",5)
0000270893 [ncp.esp32.at] TRACE: < +CWLAP:(4,"TP-Link_1040",-83,"00:31:92:ce:10:40",8)
0000270894 [ncp.esp32.at] TRACE: < +CWLAP:(3,"",-84,"06:31:92:ce:10:40",8)
0000270895 [ncp.esp32.at] TRACE: < +CWLAP:(3,"Telia-549723-Greitas",-87,"a4:91:b1:54:97:23",1)
0000270896 [ncp.esp32.at] TRACE: < +CWLAP:(4,"TEO-187439",-90,"00:8c:54:57:87:a4",1)
0000270899 [ncp.esp32.at] TRACE: < +CWLAP:(3,"ZyXELD79278",-90,"b8:ec:a3:d7:92:78",11)
0000270900 [ncp.esp32.at] TRACE: < +CWLAP:(4,"GIGLICH",-92,"4c:5e:0c:27:39:1c",5)
0000270901 [ncp.esp32.at] TRACE: < OK
0000271905 [app] INFO: {"cmd":"loc","time":1642153778,"loc":{"lck":1,"time":1642153779,"lat":54.73353958,"lon":25.25127983,"alt":205.441,"hd":90.19,"spd":0.00,"h_acc":10.000,"hdop":~
0000271907 [app] INFO: cloud sent: {"cmd":"loc","time":1642153778,"loc":{"lck":1,"time":1642153779,"lat":54.73353958,"lon":25.25127983,"alt":205.441,"hd":90.19,"spd":0.00,"h_acc":10~
0000271911 [system.nm] TRACE: Request to power off the interface
0000271911 [ncp.esp32.mux] INFO: Stopping GSM07.10 muxer
0000271912 [ncp.esp32.mux] INFO: Gracefully stopping GSM07.10 muxer
0000271912 [ncp.esp32.mux] INFO: Closing all muxed channels
0000271913 [ncp.esp32.mux] INFO: Closing mux channel 1
0000271913 [ncp.esp32.mux] INFO: Muxed channel 2 already closed
0000271914 [ncp.esp32.mux] INFO: Muxed channel 3 already closed
0000271914 [ncp.esp32.mux] INFO: Muxed channel 4 already closed

Serial connection closed. Attempting to reconnect...
Serial monitor opened successfully:
0000000849 [app] INFO: loading config location: {"version":1,"hash":"BA8257A1CBB4B83F2F9D163EF06E921C","location":{"radius":0,"interval_min":180,"interval_max":180,"min_publish":fal~
0000000854 [app] INFO: loading config imu_trig: {"version":1,"hash":"5E5488D40858A17D5C214BA3319647FD","imu_trig":{"motion":"disable","high_g":"disable"}}
0000000869 [app] INFO: loading config rgb: {"version":1,"hash":"2B1CD6509BBD4801D3AF1DE32E1A9D23","rgb":{"type":"particle","direct":{"brightness":255,"red":0,"green":0,"blue":255}}}
0000000872 [app] INFO: Starting modem
0000000880 [system.nm] INFO: State changed: DISABLED -> IFACE_DOWN
0000000885 [system.nm] INFO: State changed: IFACE_DOWN -> IFACE_REQUEST_UP
0000000890 [ncp.client] TRACE: Modem already on
0000000927 [system.nm] INFO: State changed: IFACE_REQUEST_UP -> IFACE_UP
0000000955 [mux] INFO: Starting GSM07.10 muxer
0000000955 [mux] INFO: GSM07.10 muxer thread started
0000000956 [mux] INFO: Openning mux channel 0
0000001006 [mux] INFO: Openning mux channel 1
0000001060 [ncp.client] TRACE: NCP ready to accept AT commands
0000001063 [mux] INFO: Mux channel 1 already opened
0000001066 [ncp.client] TRACE: NCP state changed: 1
0000001066 [net.pppncp] TRACE: NCP event 1
0000001090 [ncp.client] TRACE: NCP connection state changed: 1
0000001090 [net.pppncp] TRACE: NCP event 2
0000001091 [net.pppncp] TRACE: State changed event: 1
0000001104 [ncp.client] TRACE: NCP connection state changed: 2
0000001105 [mux] INFO: Openning mux channel 2
0000001154 [net.pppncp] TRACE: NCP event 100
0000001155 [net.pppncp] TRACE: New auth info
0000001156 [net.pppncp] TRACE: NCP event 2
0000001157 [net.pppncp] TRACE: State changed event: 2
0000003226 [app.gps.ubx] INFO: enable PUBX-POSITION
0000003233 [app.gps.ubx] INFO: enable PUBX-SVSTATUS
0000003235 [app.gps.ubx] INFO: enable PUBX-TIME
0000003258 [app.gps.ubx] INFO: enable GPS
0000003259 [app.gps.ubx] INFO: enable QZSS
0000003259 [app.gps.ubx] INFO: enable SBAS
0000003259 [app.gps.ubx] INFO: enable Galileo
0000003260 [app.gps.ubx] INFO: enable BeiDou
0000003260 [app.gps.ubx] INFO: enable GLONASS
0000003263 [app.gps.ubx] INFO: set to power management mode 0
0000003266 [app.gps.ubx] INFO: set dynamic platform model to 0
0000003270 [app] TRACE: evaluatePublish first
0000003271 [app] TRACE: waiting for stable GNSS lock for triggers
0000004079 [system.nm] INFO: State changed: IFACE_UP -> IFACE_LINK_UP
0000004080 [net.pppncp] TRACE: Negotiated MTU: 1500
0000004081 [system.nm] INFO: State changed: IFACE_LINK_UP -> IP_CONFIGURED
0000004083 [system] INFO: Cloud: connecting
0000004085 [system] INFO: Cloud socket connected
0000004085 [comm.protocol.handshake] INFO: Establish secure connection
0000004087 [comm.dtls] INFO: session has 0 uses
0000004096 [comm.dtls] INFO: (CMPL,RENEG,NO_SESS,ERR) restoreStatus=0
0000004096 [comm.dtls] INFO: out_ctr 0,1,0,0,0,0,0,132, next_coap_id=60
0000004096 [comm.dtls] INFO: restored session from persisted session data. next_msg_id=96
0000004097 [comm.dtls] INFO: session cmd (CLS,DIS,MOV,LOD,SAV): 2
0000004113 [hal] TRACE: Cached ESP32 NCP firmware version: 7
0000004310 [hal] TRACE: Cached ESP32 NCP firmware version: 7
0000004324 [comm.protocol.handshake] INFO: Skipping HELLO message
0000004327 [comm.protocol] INFO: Checksum has not changed; not sending application DESCRIBE
0000004327 [comm.protocol] INFO: Checksum has not changed; not sending subscriptions
0000004940 [comm.dtls] INFO: session cmd (CLS,DIS,MOV,LOD,SAV): 4
0000004940 [comm.protocol] TRACE: Reply recieved: type=2, code=0
0000004941 [comm.protocol] TRACE: message id 97 complete with code 0.00
0000004942 [comm.protocol] TRACE: rcv'd message type=13
0000004952 [comm.protocol] TRACE: Reply recieved: type=2, code=0
0000004952 [comm.protocol] TRACE: message id 98 complete with code 0.00
0000004952 [comm.protocol] TRACE: rcv'd message type=13
0000005053 [comm.protocol] TRACE: Reply recieved: type=2, code=0
0000005053 [comm.protocol] TRACE: message id 99 complete with code 0.00
0000005053 [comm.protocol] TRACE: rcv'd message type=13
0000005153 [system] INFO: Cloud connected
0000005983 [comm.protocol] TRACE: rcv'd message type=8
0000008226 [app] INFO: cloud sent: {"cmd":"sync","time":1642153793,"hash":"E5317663D70B292BADE1504E0D0CD685"}
0000008228 [app] TRACE: evaluatePublish first
0000008229 [app] TRACE: waiting for stable GNSS lock for triggers
0000008461 [comm.protocol] TRACE: Reply recieved: type=2, code=0
0000008461 [comm.protocol] TRACE: message id 100 complete with code 0.00
0000008462 [comm.protocol] TRACE: rcv'd message type=13
0000013184 [app] TRACE: evaluatePublish first
0000013185 [app] TRACE: publishing from triggers
0000013185 [app] INFO: publishing now...
0000013187 [app] TRACE: extending execution
0000013217 [system.nm] TRACE: Request to power on the interface
0000013536 [hal] ERROR: Not found response
0000013556 [hal] ERROR: CMD0 response error, expect 0x1, response 0
0000013557 [hal] ERROR: Please restart slave and test again,error code:264
0000015619 [ncp.esp32.at] TRACE: > AT
0000015621 [ncp.esp32.at] TRACE: < OK
0000016622 [ncp.esp32.client] TRACE: NCP ready to accept AT commands
0000016624 [ncp.esp32.at] TRACE: > AT+MVER
0000016626 [ncp.esp32.at] TRACE: < 7
0000016626 [ncp.esp32.at] TRACE: < OK
0000016628 [ncp.esp32.at] TRACE: > AT+GETMAC=0
0000016630 [ncp.esp32.at] TRACE: < +GETMAC: "30:ae:a4:ac:37:d0"
0000016631 [ncp.esp32.at] TRACE: < OK
0000016634 [ncp.esp32.at] TRACE: > AT+CMUX=0
0000016636 [ncp.esp32.at] TRACE: < OK
0000016636 [ncp.esp32.mux] INFO: Starting GSM07.10 muxer
0000016637 [ncp.esp32.mux] INFO: Openning mux channel 0
0000016637 [ncp.esp32.mux] INFO: GSM07.10 muxer thread started
0000016644 [ncp.esp32.mux] INFO: Openning mux channel 1
0000016657 [ncp.esp32.at] TRACE: > AT
0000016664 [ncp.esp32.at] TRACE: < OK
0000016668 [ncp.esp32.at] TRACE: > AT+CWDHCP=0,3
0000016675 [ncp.esp32.at] TRACE: < OK
0000016675 [ncp.esp32.client] TRACE: NCP state changed: 1
0000016676 [system.nm] TRACE: Interface 5 power state changed: 2
0000016684 [ncp.esp32.at] TRACE: > AT+CWLAP
0000018793 [ncp.esp32.at] TRACE: < +CWLAP:(4,"TP-Link_988F",-43,"1c:3b:f3:8e:98:8f",7)
0000018794 [ncp.esp32.at] TRACE: < +CWLAP:(3,"",-44,"22:3b:f3:8e:98:8f",7)
0000018796 [ncp.esp32.at] TRACE: < +CWLAP:(3,":signal_strength::closed_lock_with_key:Asus​:globe_with_meridians:-:lithuania:",-64,"4c:ed:fb:a6:dd:40",1)
0000018797 [ncp.esp32.at] TRACE: < +CWLAP:(3,"TP-LINK_F6E2",-72,"18:a6:f7:c0:f6:e2",11)
0000018798 [ncp.esp32.at] TRACE: < +CWLAP:(3,"SavoNet_2G",-81,"d4:5d:64:df:7f:88",1)
0000018809 [ncp.esp32.at] TRACE: < +CWLAP:(4,"30-2.4",-82,"d8:0d:17:a4:36:34",5)
0000018810 [ncp.esp32.at] TRACE: < +CWLAP:(3,"SGL",-82,"c0:25:2f:6f:12:83",9)
0000018812 [ncp.esp32.at] TRACE: < +CWLAP:(3,"",-83,"06:31:92:ce:10:40",8)
0000018813 [ncp.esp32.at] TRACE: < +CWLAP:(4,"TP-Link_1040",-84,"00:31:92:ce:10:40",8)
0000018814 [ncp.esp32.at] TRACE: < +CWLAP:(3,"Telia-549723-Greitas",-86,"a4:91:b1:54:97:23",1)
0000018816 [ncp.esp32.at] TRACE: < +CWLAP:(3,"Extension",-90,"00:1d:73:9f:2f:70",5)
0000018817 [ncp.esp32.at] TRACE: < +CWLAP:(4,"TP-Link_07AD",-90,"cc:32:e5:b3:07:ad",5)
0000018820 [ncp.esp32.at] TRACE: < +CWLAP:(4,"GIGLICH",-91,"4c:5e:0c:27:39:1c",5)
0000018821 [ncp.esp32.at] TRACE: < +CWLAP:(4,"TEO-187439",-92,"00:8c:54:57:87:a4",1)
0000018823 [ncp.esp32.at] TRACE: < +CWLAP:(3,"ZyXELD79278",-92,"b8:ec:a3:d7:92:78",11)
0000018824 [ncp.esp32.at] TRACE: < OK
0000019828 [app] INFO: {"cmd":"loc","time":1642153798,"loc":{"lck":1,"time":1584835210,"lat":54.73353958,"lon":25.25128365,"alt":205.573,"hd":90.19,"spd":0.00,"h_acc":11.000,"hdop":~
0000019830 [app] INFO: cloud sent: {"cmd":"loc","time":1642153798,"loc":{"lck":1,"time":1584835210,"lat":54.73353958,"lon":25.25128365,"alt":205.573,"hd":90.19,"spd":0.00,"h_acc":11~
0000019834 [system.nm] TRACE: Request to power off the interface
0000019834 [ncp.esp32.mux] INFO: Stopping GSM07.10 muxer
0000019835 [ncp.esp32.mux] INFO: Gracefully stopping GSM07.10 muxer
0000019835 [ncp.esp32.mux] INFO: Closing all muxed channels
0000019836 [ncp.esp32.mux] INFO: Closing mux channel 1
0000019836 [ncp.esp32.mux] INFO: Muxed channel 2 already closed
0000019836 [ncp.esp32.mux] INFO: Muxed channel 3 already closed
0000019837 [ncp.esp32.mux] INFO: Muxed channel 4 already closed

Serial connection closed. Attempting to reconnect...
Serial monitor opened successfully:
0000008238 [app] TRACE: evaluatePublish first
0000008239 [app] TRACE: waiting for stable GNSS lock for triggers
0000013193 [app] TRACE: evaluatePublish first
0000013193 [app] TRACE: waiting for stable GNSS lock for triggers
0000014566 [net.pppncp] TRACE: NCP event 3
0000014567 [net.pppncp] TRACE: NCP power state changed: IF_POWER_STATE_DOWN
0000014567 [system.nm] TRACE: Interface 4 power state changed: 1
0000014567 [ncp.client] TRACE: It takes 8977 ms to power off the modem.
0000014568 [mux] INFO: Stopping GSM07.10 muxer
0000014568 [mux] INFO: Gracefully stopping GSM07.10 muxer
0000014569 [mux] INFO: Closing all muxed channels
0000014569 [mux] INFO: Closing mux channel 1
0000014569 [mux] INFO: Closing mux channel 2
0000014570 [mux] INFO: Muxed channel 3 already closed
0000014570 [mux] INFO: Muxed channel 4 already closed
0000014571 [mux] INFO: GSM07.10 muxer thread exiting
0000014571 [ncp.client] TRACE: NCP connection state changed: 1
0000014572 [net.pppncp] TRACE: NCP event 2
0000014572 [net.pppncp] TRACE: State changed event: 1
0000014572 [mux] INFO: GSM07.10 muxer stopped
0000014573 [ncp.client] TRACE: Soft power off modem successfully
0000014573 [ncp.client] TRACE: Deinit modem serial.
0000018148 [app] TRACE: evaluatePublish first

1 Like
2

Hi Vadim- sorry for the delayed response. It could be configured to sleep. Can you DM me the device id so I can check the console?

3 
0000513218 [app] TRACE: TrackerLocation: last=21, interval=28800, wake=28701
0000513219 [app] INFO: Stoping modem
0000513268 [system] INFO: Cloud: disconnecting
0000513269 [app.pubq] TRACE: reset or disconnect event, save files to queue
0000513684 [comm.protocol] TRACE: Reply recieved: type=2, code=0
0000513684 [comm.protocol] TRACE: message id 23 complete with code 0.00
0000513685 [comm.protocol] TRACE: rcv'd message type=13
0000514271 [system] INFO: Cloud: disconnected
0000514274 [app] INFO: sleeping until 3753218 milliseconds
0000514275 [system.sleep] TRACE: Entering system_sleep_ext()
0000514281 [system.nm] INFO: State changed: IP_CONFIGURED -> IFACE_UP
0000514285 [system.nm] INFO: State changed: IFACE_UP -> IFACE_REQUEST_DOWN
0000514286 [system.nm] INFO: State changed: IFACE_REQUEST_DOWN -> IFACE_DOWN
0000514290 [system.nm] TRACE: Request to power off the interface
0000514293 [system.nm] TRACE: Interface 4 power state: 2
0000514293 [system.nm] INFO: State changed: IFACE_DOWN -> DISABLED
0000514294 [system.sleep] TRACE: Waiting interface 4 to be off...
0000514643 [ncp.client] TRACE: NCP connection state changed: 0
0000514643 [net.pppncp] TRACE: NCP event 2
0000514643 [net.pppncp] TRACE: State changed event: 0
0000514644 [net.pppncp] TRACE: NCP event 3
0000514645 [net.pppncp] TRACE: NCP power state changed: IF_POWER_STATE_POWERING_DOWN
0000514645 [system.nm] TRACE: Interface 4 power state changed: 3
0000514646 [ncp.client] TRACE: Try powering modem off using AT command
0000514721 [ncp.client] TRACE: Waiting the modem to be turned off...
0000523296 [net.pppncp] TRACE: NCP event 3
0000523297 [net.pppncp] TRACE: NCP power state changed: IF_POWER_STATE_DOWN
0000523297 [system.nm] TRACE: Interface 4 power state changed: 1
0000523297 [ncp.client] TRACE: It takes 8576 ms to power off the modem.
0000523298 [mux] INFO: Stopping GSM07.10 muxer
0000523298 [mux] INFO: Gracefully stopping GSM07.10 muxer
0000523299 [mux] INFO: Closing all muxed channels
0000523299 [mux] INFO: Closing mux channel 1
0000523299 [mux] INFO: Closing mux channel 2
0000523300 [mux] INFO: Muxed channel 3 already closed
0000523300 [mux] INFO: Muxed channel 4 already closed
0000523301 [mux] INFO: GSM07.10 muxer thread exiting
0000523301 [mux] INFO: GSM07.10 muxer stopped
0000523301 [ncp.client] TRACE: Soft power off modem successfully
0000523302 [ncp.client] TRACE: Deinit modem serial.
0000523303 [ncp.client] TRACE: Modem already off
0000523303 [ncp.client] TRACE: Soft power off modem successfully
0000523303 [ncp.client] TRACE: Deinit modem serial.
0000523304 [ncp.client] TRACE: NCP state changed: 0
0000523304 [net.pppncp] TRACE: NCP event 1



Serial connection closed.  Attempting to reconnect...

Now this is how it goes to sleep gracefully. That aforementioned variant was something else.

4

I believe I might have an issue related to this (or identical) on DeviceOS 3.2.0 - I have a safeguard to catch any hard fault resets using the following logic:

void Namespace::enableSafeModeRecovery()
{
   // Enable Reset Info from DeviceOS
   System.enableFeature(FEATURE_RESET_INFO);

   // Check whether we've run into an SOS
   if (System.resetReason() == RESET_REASON_PANIC)
   {
      // If hardfault, boot into always-connected safemode for remote diagnostics.
      System.enterSafeMode();
   }
}

But I’ve been lucky to catch it happen on a development device with the following logs:

<When sleep works correctly>
0109454009 [system.sleep] TRACE: Entering system_sleep_ext()
0109454009 [system.sleep] TRACE: Interface 4 is off already
0109454010 [system.sleep] TRACE: Interface 3 is off already

<Next sleep iteration, where sleep fails (I believe)>
0109574100 [system.sleep] TRACE: Entering system_sleep_ext()
<Hard fault I believe>
<boots into safe mode>