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

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

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?