MSOM Connecting to Cloud Blocking Reprogramming

radek · March 11, 2025, 12:43pm

I noticed that I cannot reprogram my device when it is rapidly flashing cyan (connecting to the cloud). Normally this isn't an issue because the connection is pretty quick, but its been flashing for several minutes now. I can reprogram it if I put it into DFU mode using buttons.

The specific error I get is a Request Timeout during flash. It looks like my application thread still runs.

The device will respond to particle usb list, but it takes >10 seconds.

status.particle.io shows All systems operational, but my coworker is also having trouble getting his unit to connect.

I am running a simple firmware with device os 6.3.0.

#include "Particle.h"

SYSTEM_MODE(AUTOMATIC);
SYSTEM_THREAD(ENABLED);

SerialLogHandler logHandler(LOG_LEVEL_INFO);
uint32_t loopTime;

void setup() {
    Serial.begin();
    loopTime = millis();
}

void loop() {
    if(millis() - loopTime > 5000) {
        loopTime = millis();
        Log.info("loop");
    }
}

rickkas7 · March 11, 2025, 1:22pm

Is the M-SoM connecting by cellular or Wi-Fi? In general, fast blinking cyan is the point after the device has its IP address and is doing the DNS lookup and sending packets to the cloud. If there's a problem doing these things, for example because of an internet outage, then you could be stuck there longer.

During certain parts of connecting the system thread will be blocked, and this can prevent USB control requests from being processed, which is why you can't go into DFU from USB request.

radek · March 11, 2025, 1:35pm

I am connecting by cellular.

Side note, I see my bsom devices are connecting, but my msoms are not, even in the same area. Is it possible for one product to be down but not another? I have the above firmware on both at my desk.

rickkas7 · March 11, 2025, 1:40pm

That's weird that the B-SoM would connect but not the M-SoM. They share the same set of cloud servers, and have the same SIM (unless it's a B402 or B523).

The cellular modem is different, but that shouldn't affect the cyan part of the connection.

When a device connects after being unconnected it picks a cloud server by DNS, which rotates. Once it picks one it will continue to use that until it's disconnected by either side, by a network disruption, or the 3-day session timeout.

radek · March 11, 2025, 1:53pm

I have B402s and B404x that are connecting.

I collected some logs from the m404. Here's part 1

[Connected]
0000002369 [hal] INFO: WiFi on
0000002766 [hal.ble] TRACE: Going to stop the stack...
0000003089 [hal] INFO: WiFi off
0000003274 [system.nm] INFO: State changed: NONE -> DISABLED
0000003289 [system.nm] TRACE: Interface 5 power state: DOWN
0000003304 [system.nm] TRACE: Interface 4 power state: UP
0000004578 [comm] INFO: channel inited
0000007183 [system.nm] INFO: State changed: DISABLED -> IFACE_DOWN
0000007587 [system.nm] INFO: State changed: IFACE_DOWN -> IFACE_REQUEST_UP
0000007975 [net.ifapi] INFO: Netif pp3 state UP
0000007991 [system.nm] INFO: State changed: IFACE_REQUEST_UP -> IFACE_UP
0000008248 [ncp.client] TRACE: Powering modem on, ncpId: 0x6a
0000008249 [ncp.client] TRACE: Modem already on
0000008342 [mux] INFO: Starting GSM07.10 muxer
0000008344 [mux] INFO: Opening mux channel 0
0000008344 [mux] INFO: GSM07.10 muxer thread started
0000008348 [mux] INFO: Opening mux channel 1
0000008400 [ncp.at] TRACE: > AT
0000008402 [ncp.at] TRACE: < OK
0000008402 [ncp.client] TRACE: NCP ready to accept AT commands
0000008404 [ncp.at] TRACE: > AT+CFUN?
0000008405 [ncp.at] TRACE: < +CFUN: 1
0000008406 [ncp.at] TRACE: < OK
0000008407 [mux] INFO: Mux channel 1 already opened
0000008409 [ncp.at] TRACE: > AT
0000008410 [ncp.at] TRACE: < OK
0000008411 [ncp.client] TRACE: NCP state changed: 1
0000008412 [net.pppncp] TRACE: NCP event 1
0000008414 [ncp.at] TRACE: > AT+QCFG="cmux/urcport",1
0000008416 [ncp.at] TRACE: < OK
0000008417 [ncp.at] TRACE: > AT+CGEREP=1,0
0000008418 [ncp.at] TRACE: < OK
0000008423 [net.ppp.client] TRACE: PPP thread event ADM_UP data=0
0000008677 [net.ppp.client] TRACE: State NONE -> READY
0000008676 [ncp.at] TRACE: > AT+CFUN=1,0
0000008861 [ncp.at] TRACE: < OK
0000008862 [ncp.at] TRACE: > AT+CCID
0000008863 [ncp.at] TRACE: < +CCID: 89883070000039913841
0000008864 [ncp.at] TRACE: < OK
0000008865 [ncp.at] TRACE: > AT+CGDCONT=1,"IP","super"
0000008867 [ncp.at] TRACE: < OK
0000008869 [ncp.at] TRACE: > AT+CFUN=1,0
0000008870 [ncp.at] TRACE: < OK
0000008871 [ncp.at] TRACE: > AT+CREG=2
0000008873 [ncp.at] TRACE: < OK
0000008874 [ncp.at] TRACE: > AT+CGREG=2
0000008876 [ncp.at] TRACE: < OK
0000008877 [ncp.at] TRACE: > AT+CEREG=2
0000008878 [ncp.at] TRACE: < OK
0000008879 [ncp.client] TRACE: NCP connection state changed: 1
0000008881 [net.pppncp] TRACE: NCP event 2
0000008882 [net.pppncp] TRACE: State changed event: 1
0000008883 [net.ppp.client] TRACE: PPP thread event LOWER_DOWN data=0
0000008885 [ncp.at] TRACE: > AT+COPS?
0000008886 [ncp.at] TRACE: < +COPS: 0,0,"Verizon Wireless",8
0000008888 [ncp.at] TRACE: < OK
0000008889 [ncp.at] TRACE: > AT+QCFG="nwscanmode"
0000008891 [ncp.at] TRACE: < +QCFG: "nwscanmode",3
0000008893 [ncp.at] TRACE: < OK
0000008894 [ncp.at] TRACE: > AT+QCFG="nwscanseq"
0000008895 [ncp.at] TRACE: < +QCFG: "nwscanseq",020103
0000008898 [ncp.at] TRACE: < OK
0000008899 [ncp.at] TRACE: > AT+QCFG="iotopmode"
0000008901 [ncp.at] TRACE: < +QCFG: "iotopmode",0
0000008902 [ncp.at] TRACE: < OK
0000008903 [ncp.at] TRACE: > AT+CEREG?
0000008904 [ncp.at] TRACE: < +CEREG: 2,5,"9D03","266F903",8
0000008907 [ncp.at] TRACE: < OK
0000008908 [ncp.at] TRACE: > AT+CREG?
0000008909 [ncp.at] TRACE: < +CREG: 2,5,"9D03","266F903",8
0000008910 [ncp.at] TRACE: < OK
0000008911 [ncp.at] TRACE: > AT+CGREG?
0000008914 [ncp.at] TRACE: < +CGREG: 2,4
0000008915 [ncp.at] TRACE: < OK
0000008915 [ncp.client] TRACE: NCP connection state changed: 2
0000008917 [mux] INFO: Opening mux channel 2
0000008962 [net.pppncp] TRACE: NCP event 100
0000008964 [net.pppncp] TRACE: New auth info
0000009123 [net.pppncp] TRACE: NCP event 2
0000009124 [net.pppncp] TRACE: State changed event: 2
0000009125 [net.ppp.client] TRACE: PPP thread event LOWER_UP data=0
0000009129 [net.ppp.client] TRACE: State READY -> CONNECT
0000009127 [ncp.at] TRACE: > AT+CIMI
0000009139 [ncp.at] TRACE: < 234104869682393
0000009144 [ncp.at] TRACE: < OK
0000009296 [net.ppp.client] TRACE: State CONNECT -> CONNECTING
0000009473 [net.ppp.ipcp] TRACE: init
0000009475 [net.ppp.ipcp] TRACE: disable 0 0 0
0000009476 [net.ppp.ipcp] TRACE: enable 0 0 0
0000010579 [ncp.at] TRACE: > AT
0000010581 [ncp.at] TRACE: < OK
0000010582 [ncp.at] TRACE: > ATO
0000010583 [ncp.at] TRACE: < CONNECT 150000000
0000010585 [net.ppp.client] TRACE: PPP phase -> Initialize
0000010586 [net.ppp.client] TRACE: PPP phase -> Establish
0000010925 [net.ppp.ipcp] TRACE: lowerUp
0000010926 [net.ppp.client] TRACE: PPP phase -> Authenticate
0000011450 [net.ppp.client] TRACE: PPP phase -> Network
0000011451 [net.ppp.ipcp] TRACE: open
0000011452 [net.ppp.ipcp] TRACE: resetting CI
0000011453 [net.ppp.ipcp] TRACE: iur CI length: 18
0000011625 [net.ppp.ipcp] TRACE: input 4
0000011798 [net.ppp.ipcp] TRACE: input 22
0000011799 [net.ppp.ipcp] TRACE: iur CI length: 18
0000011973 [net.ppp.ipcp] TRACE: input 22
0000011974 [net.ppp.ipcp] TRACE: up
0000011975 [net.ifapi] INFO: Netif pp3 link UP, profile=NONE
0000012218 [system.nm] INFO: State changed: IFACE_UP -> IFACE_LINK_UP
0000012220 [net.ifapi] TRACE: Netif pp3 ipv4 configuration changed
0000012221 [hal] INFO: DNS server list changed
0000012223 [system.nm] INFO: State changed: IFACE_LINK_UP -> IP_CONFIGURED
0000012225 [hal] INFO: DNS server list changed
0000012227 [net.ppp.client] TRACE: PPP phase -> Running
0000012224 [net.ppp.client] TRACE: PPP thread event UP data=0
0000012230 [net.ppp.client] TRACE: State CONNECTING -> CONNECTED
0000012398 [net.pppncp] TRACE: Negotiated MTU: 1500
0000012400 [system] INFO: Cloud: connecting
0000012701 [system] INFO: Read Server Address = type:1,domain:$id.udp.particle.io
0000012742 [system] WARN: Failed to load session data from persistent storage
0000012782 [system] INFO: Discarding session data
0000012837 [system] TRACE: Resolving 0a10aced202194944a051d48.v6.udp.particle.io#5684
0000013629 [system] TRACE: Address type: 3
0000013652 [system] TRACE: Cloud socket=0, family=2, type=2, protocol=17
0000013689 [system.cm] TRACE: Using best network: Cellular
0000013719 [system] INFO: Cloud socket=0, connecting to 52.45.184.198#5684 using if 4
0000013763 [system] INFO: Bound cloud socket to lwip if 4 ("pp3")
0000013970 [system] TRACE: Cloud socket=0, connected to 52.45.184.198#5684
0000014008 [system] TRACE: Updating cloud keepalive for AF_INET: 1380000 -> 1380000
0000014051 [system] TRACE: Applying new keepalive interval now
0000014083 [system] INFO: Cloud socket connected
0000014108 [system] INFO: Starting handshake: presense_announce=0
0000014141 [comm.protocol.handshake] INFO: Establish secure connection
0000014179 [comm.dtls] INFO: (CMPL,RENEG,NO_SESS,ERR) restoreStatus=2
0000017501 [comm.protocol.handshake] INFO: Sending HELLO message
0000017535 [comm.coap] TRACE: Sending CoAP message
0000017561 [comm.coap] TRACE: CON POST /h size=39 token= id=1
0000017974 [comm.coap] TRACE: Received CoAP message
0000018000 [comm.coap] TRACE: ACK 0.00  size=4 token= id=1
0000018030 [comm.protocol.handshake] INFO: Handshake completed
0000018062 [comm.protocol.handshake] TRACE: Updating cached session parameters
0000018102 [comm.dtls] INFO: session cmd (CLS,DIS,MOV,LOD,SAV): 4
0000018136 [comm.dtls] INFO: session cmd (CLS,DIS,MOV,LOD,SAV): 3

radek · March 11, 2025, 1:53pm

Part 2

0000225737 [ncp.at] TRACE: > AT+CFUN?
0000225757 [ncp.at] TRACE: < +CFUN: 1
0000225776 [ncp.at] TRACE: < OK
0000225797 [ncp.at] TRACE: > AT+CCID
0000225805 [ncp.at] TRACE: < +CCID: 89883070000039913841
0000225807 [ncp.at] TRACE: < OK
0000225809 [ncp.at] TRACE: > AT+CGSN
0000225812 [ncp.at] TRACE: < 862044067623368
0000225814 [ncp.at] TRACE: < OK
0000225816 [ncp.at] TRACE: > AT+CGMR
0000225819 [ncp.at] TRACE: < BG95M5LAR02A03
0000225822 [ncp.at] TRACE: < OK
0000225879 [comm.coap] TRACE: Sending CoAP message
0000225905 [comm.coap] TRACE: CON POST /d?\x01 size=253 token=84 id=2
0000226322 [comm] INFO: Sending TIME request
0000226345 [comm.coap] TRACE: Sending CoAP message
0000226371 [comm.coap] TRACE: CON GET /t size=7 token=85 id=3
0000226404 [system] INFO: Send spark/device/last_reset event
0000226435 [comm.coap] TRACE: Sending CoAP message
0000226461 [comm.coap] TRACE: CON POST /E/spark/device/last_reset size=38 token= id=4
0000226843 [comm.coap] TRACE: Sending CoAP message
0000226869 [comm.coap] TRACE: CON POST /E/particle/device/updates/enabled size=44 token= id=5
0000226918 [comm.coap] TRACE: Sending CoAP message
0000226944 [comm.coap] TRACE: CON POST /E/particle/device/updates/forced size=44 token= id=6
0000226993 [system] INFO: Sending application DESCRIBE
0000227548 [comm.coap] TRACE: Sending CoAP message
0000227574 [comm.coap] TRACE: CON POST /d?\x02 size=25 token=86 id=7
0000227612 [system] INFO: Sending subscriptions
0000227805 [comm.protocol] INFO: Sending subscriptions
0000228000 [comm.coap] TRACE: Sending CoAP message
0000228026 [comm.coap] TRACE: CON GET /e/particle size=15 token= id=8
0000228063 [comm.coap] TRACE: Sending CoAP message
0000228089 [comm.coap] TRACE: CON GET /e/spark size=12 token= id=9
0000228124 [system] TRACE: Waiting until all handshake messages are processed by the protocol layer
0000228175 [comm.coap] TRACE: Received CoAP message
0000228202 [comm.coap] TRACE: CON GET /d?\x04 size=9 token=01 id=8017
0000228237 [comm.protocol] INFO: Received DESCRIBE request; flags: 0x04
0000228274 [comm.coap] TRACE: Sending CoAP message
0000228300 [comm.coap] TRACE: ACK 0.00  size=4 token= id=8017
0000228333 [ncp.at] TRACE: > AT+COPS=3,2
0000228341 [ncp.at] TRACE: < OK
0000228343 [ncp.at] TRACE: > AT+COPS?
0000228346 [ncp.at] TRACE: < +COPS: 0,2,"311480",8
0000228348 [ncp.at] TRACE: < OK
0000228350 [ncp.at] TRACE: > AT+QCSQ
0000228353 [ncp.at] TRACE: < +QCSQ: "eMTC",-67,-91,153,-11
0000228356 [ncp.at] TRACE: < OK
0000228360 [ncp.at] TRACE: > AT+COPS=3,2
0000228381 [ncp.at] TRACE: < OK
0000228400 [ncp.at] TRACE: > AT+COPS?
0000228421 [ncp.at] TRACE: < +COPS: 0,2,"311480",8
0000228447 [ncp.at] TRACE: < OK
0000228458 [ncp.at] TRACE: > AT+CEREG?
0000228461 [ncp.at] TRACE: < +CEREG: 2,5,"9D03","266F903",8
0000228463 [ncp.at] TRACE: < OK
0000228465 [ncp.at] TRACE: > AT+CGREG?
0000228468 [ncp.at] TRACE: < +CGREG: 2,4
0000228469 [ncp.at] TRACE: < OK
0000228473 [ncp.at] TRACE: > AT+CREG?
0000228475 [ncp.at] TRACE: < +CREG: 2,5,"9D03","266F903",8
0000228478 [ncp.at] TRACE: < OK
0000228480 [comm.coap] TRACE: Sending CoAP message
0000228506 [comm.coap] TRACE: CON 2.05  size=235 token=01 id=10
0000228545 [comm.coap] TRACE: Received CoAP message
0000228908 [comm.coap] TRACE: CON GET /d?\x01 size=9 token=02 id=8018
0000228944 [comm.protocol] INFO: Received DESCRIBE request; flags: 0x01
0000228980 [comm.coap] TRACE: Sending CoAP message
0000229006 [comm.coap] TRACE: ACK 0.00  size=4 token= id=8018
0000280951 [net.ppp.client] TRACE: PPP phase -> Terminate
0000280953 [net.ppp.ipcp] TRACE: lowerDown
0000280954 [net.ppp.ipcp] TRACE: down
0000280955 [net.ifapi] INFO: Netif pp3 link DOWN, profile=NONE
0000280956 [hal] INFO: DNS server list changed
0000280957 [system.nm] INFO: State changed: IP_CONFIGURED -> IFACE_LINK_UP
0000280968 [hal] INFO: DNS server list changed
0000281218 [system.nm] INFO: State changed: IFACE_LINK_UP -> IFACE_UP
0000281220 [net.ifapi] TRACE: Netif pp3 ipv4 configuration changed
0000281222 [net.ppp.client] TRACE: PPP phase -> Network
0000281223 [net.ppp.ipcp] TRACE: close
0000281225 [net.ppp.client] TRACE: PPP phase -> Establish
0000293227 [net.ppp.client] TRACE: PPP phase -> Disconnect
0000293229 [net.ppp.client] TRACE: PPP phase -> Dead
0000293230 [net.ppp.client] TRACE: PPP thread event ERROR data=9
0000293231 [net.pppncp] ERROR: PPP error event data=9
0000293233 [net.ppp.client] TRACE: PPP thread event DOWN data=0
0000293239 [net.ppp.client] TRACE: State CONNECTED -> DISCONNECT
0000293424 [net.ppp.client] TRACE: State DISCONNECT -> DISCONNECTING
0000293602 [net.ppp.client] TRACE: PPP thread event ERROR data=5
0000293603 [net.pppncp] ERROR: PPP error event data=5
0000293609 [net.ppp.client] TRACE: PPP thread event DOWN data=0
0000293610 [net.ppp.client] TRACE: State DISCONNECTING -> DISCONNECTED
0000293817 [net.ppp.client] TRACE: State DISCONNECTED -> CONNECT
0000294098 [net.ppp.client] TRACE: State CONNECT -> CONNECTING
0000294304 [net.ppp.ipcp] TRACE: init
0000294304 [net.ppp.ipcp] TRACE: disable 1 0 0
0000294305 [net.ppp.ipcp] TRACE: enable 0 0 0
0000295414 [ncp.at] TRACE: > AT
0000295917 [ncp.at] TRACE: > AT
0000297525 [ncp.at] TRACE: > AT
0000298028 [ncp.at] TRACE: > AT
0000299636 [ncp.at] TRACE: > AT
0000300138 [ncp.at] TRACE: > AT
0000301746 [ncp.at] TRACE: > AT
0000302247 [ncp.at] TRACE: > AT
0000303855 [ncp.at] TRACE: > AT
0000304356 [ncp.at] TRACE: > AT
0000304857 [ncp.client] ERROR: Failed to enter data mode
0000304858 [net.ppp.client] ERROR: Failed to dial
0000304859 [net.ppp.client] TRACE: State CONNECTING -> CONNECT
0000304859 [net.pppncp] TRACE: NCP event 3
0000304866 [net.pppncp] TRACE: NCP power state changed: IF_POWER_STATE_POWERING_DOWN
0000305074 [system.nm] TRACE: Interface 4 power state changed: POWERING_DOWN
0000305075 [ncp.client] TRACE: Try powering modem off using AT command
0000305077 [ncp.at] TRACE: > AT+QPOWD
0000305079 [ncp.at] TRACE: < OK
0000305080 [ncp.client] TRACE: Waiting the modem to be turned off...
0000305171 [net.ppp.client] TRACE: State CONNECT -> CONNECTING
0000305369 [net.ppp.ipcp] TRACE: init
0000305370 [net.ppp.ipcp] TRACE: disable 1 0 0
0000305371 [net.ppp.ipcp] TRACE: enable 0 0 0
0000305513 [net.pppncp] TRACE: NCP event 3
0000305514 [net.pppncp] TRACE: NCP power state changed: IF_POWER_STATE_DOWN
0000305516 [system.nm] TRACE: Interface 4 power state changed: DOWN
0000305517 [ncp.client] TRACE: It takes 437 ms to power off the modem.
0000305524 [mux] INFO: Stopping GSM07.10 muxer
0000305524 [mux] INFO: GSM07.10 muxer thread exiting
0000305531 [ncp.client] TRACE: NCP connection state changed: 1
0000305532 [net.pppncp] TRACE: NCP event 2
0000305537 [net.pppncp] TRACE: State changed event: 1
0000305539 [mux] INFO: GSM07.10 muxer stopped
0000305539 [ncp.client] TRACE: Soft power off modem success
0000305541 [ncp.client] TRACE: Deinit modem serial.
0000305547 [net.pppncp] ERROR: Failed to initialize cellular NCP client: -210
0000311079 [ncp.client] ERROR: Failed to enter data mode
0000311080 [net.ppp.client] ERROR: Failed to dial
0000311081 [net.ppp.client] TRACE: State CONNECTING -> CONNECT
0000311183 [ncp.client] TRACE: Modem already off
0000311192 [ncp.client] TRACE: Soft power off modem success
0000311265 [ncp.client] TRACE: Deinit modem serial.
0000311267 [ncp.client] TRACE: NCP connection state changed: 0
0000311268 [net.pppncp] TRACE: NCP event 2
0000311269 [net.pppncp] TRACE: State changed event: 0
0000311271 [ncp.client] TRACE: NCP state changed: 0
0000311272 [net.pppncp] TRACE: NCP event 1
0000311273 [ncp.client] TRACE: Powering modem on, ncpId: 0x6a
0000311274 [net.pppncp] TRACE: NCP event 3
0000311275 [net.pppncp] TRACE: NCP power state changed: IF_POWER_STATE_POWERING_UP
0000311282 [system.nm] TRACE: Interface 4 power state changed: POWERING_UP
0000311264 [net.ppp.client] TRACE: PPP thread event LOWER_DOWN data=0
0000311285 [net.ppp.client] TRACE: State CONNECT -> DISCONNECT
0000311473 [net.ppp.client] TRACE: State DISCONNECT -> DISCONNECTING
0000311647 [net.ppp.client] TRACE: PPP thread event LOWER_DOWN data=0
0000311648 [net.ppp.client] TRACE: PPP thread event ERROR data=5
0000311650 [net.pppncp] ERROR: PPP error event data=5
0000311651 [net.ppp.client] TRACE: PPP thread event DOWN data=0
0000311653 [net.ppp.client] TRACE: State DISCONNECTING -> DISCONNECTED
0000311821 [net.ppp.client] TRACE: State DISCONNECTED -> READY
0000313169 [net.pppncp] TRACE: NCP event 3
0000313170 [net.pppncp] TRACE: NCP power state changed: IF_POWER_STATE_UP
0000313171 [system.nm] TRACE: Interface 4 power state changed: UP
0000313172 [ncp.client] TRACE: Modem powered on
0000314176 [ncp.at] TRACE: > AT
0000314178 [ncp.at] TRACE: < OK
0000314178 [ncp.client] TRACE: NCP ready to accept AT commands
0000314180 [ncp.at] TRACE: > AT+CFUN?
0000314183 [ncp.at] TRACE: < +CFUN: 1
0000314184 [ncp.at] TRACE: < OK
0000314184 [ncp.at] TRACE: > AT+IFC=2,2
0000314187 [ncp.at] TRACE: < OK
0000314188 [ncp.at] TRACE: > AT
0000314190 [ncp.at] TRACE: < OK
0000314191 [ncp.at] TRACE: > AT+IPR=921600
0000314197 [ncp.at] TRACE: < OK
0000315200 [ncp.at] TRACE: > AT
0000315201 [ncp.at] TRACE: < OK
0000315377 [ncp.at] TRACE: > AT+CPIN?
0000315378 [ncp.at] TRACE: < +CPIN: READY
0000315379 [ncp.at] TRACE: < OK
0000315379 [ncp.at] TRACE: > AT+CCID
0000315380 [ncp.at] TRACE: < +CCID: 89883070000039913841
0000315382 [ncp.at] TRACE: < OK
0000315383 [ncp.at] TRACE: > AT+CEDRXS=0
0000315384 [ncp.at] TRACE: < OK
0000315385 [ncp.at] TRACE: > AT+CPSMS=0
0000315386 [ncp.at] TRACE: < OK
0000315387 [ncp.at] TRACE: > AT+CMUX=0,0,8,1509,,,,,
0000315388 [ncp.at] TRACE: < OK
0000315389 [mux] INFO: Starting GSM07.10 muxer
0000315390 [mux] INFO: Opening mux channel 0
0000315390 [mux] INFO: GSM07.10 muxer thread started
0000315498 [mux] INFO: Opening mux channel 1
0000315549 [ncp.at] TRACE: > AT
0000315551 [ncp.at] TRACE: < +CREG: 0
0000315551 [ncp.at] TRACE: < +CEREG: 0
0000315552 [ncp.at] TRACE: < +CGEV: ME DETACH
0000315553 [ncp.at] TRACE: < OK
0000315554 [ncp.client] TRACE: NCP state changed: 1
0000315555 [net.pppncp] TRACE: NCP event 1
0000315561 [ncp.at] TRACE: > AT+QCFG="cmux/urcport",1
0000315563 [ncp.at] TRACE: < OK
0000315564 [ncp.at] TRACE: > AT+CGEREP=1,0
0000315566 [ncp.at] TRACE: < OK
0000315571 [net.ppp.client] TRACE: PPP thread event ADM_UP data=0
0000315820 [ncp.at] TRACE: > AT+CFUN=1,0
0000315822 [ncp.at] TRACE: < OK
0000315824 [ncp.at] TRACE: > AT+CCID
0000315826 [ncp.at] TRACE: < +CCID: 89883070000039913841
0000315827 [ncp.at] TRACE: < OK
0000315828 [ncp.at] TRACE: > AT+CGDCONT=1,"IP","super"
0000315830 [ncp.at] TRACE: < OK
0000315831 [ncp.at] TRACE: > AT+CFUN=1,0
0000315833 [ncp.at] TRACE: < OK
0000315835 [ncp.at] TRACE: > AT+CREG=2
0000315836 [ncp.at] TRACE: < OK
0000315837 [ncp.at] TRACE: > AT+CGREG=2
0000315838 [ncp.at] TRACE: < OK
0000315839 [ncp.at] TRACE: > AT+CEREG=2
0000315840 [ncp.at] TRACE: < OK
0000315842 [ncp.client] TRACE: NCP connection state changed: 1
0000315844 [net.pppncp] TRACE: NCP event 2
0000315844 [net.pppncp] TRACE: State changed event: 1
0000315845 [net.ppp.client] TRACE: PPP thread event LOWER_DOWN data=0
0000315847 [ncp.at] TRACE: > AT+COPS?
0000315850 [ncp.at] TRACE: < +COPS: 0
0000315851 [ncp.at] TRACE: < OK
0000315852 [ncp.at] TRACE: > AT+QCFG="nwscanmode"
0000315854 [ncp.at] TRACE: < +QCFG: "nwscanmode",3
0000315855 [ncp.at] TRACE: < OK
0000315856 [ncp.at] TRACE: > AT+QCFG="nwscanseq"
0000315858 [ncp.at] TRACE: < +QCFG: "nwscanseq",020103
0000315860 [ncp.at] TRACE: < OK
0000315861 [ncp.at] TRACE: > AT+QCFG="iotopmode"
0000315863 [ncp.at] TRACE: < +QCFG: "iotopmode",0
0000315864 [ncp.at] TRACE: < OK
0000315866 [ncp.at] TRACE: > AT+CEREG?
0000315867 [ncp.at] TRACE: < +CEREG: 2,2
0000315868 [ncp.at] TRACE: < OK
0000315869 [ncp.at] TRACE: > AT+CREG?
0000315870 [ncp.at] TRACE: < +CREG: 2,2
0000315871 [ncp.at] TRACE: < OK
0000315872 [ncp.at] TRACE: > AT+CGREG?
0000315874 [ncp.at] TRACE: < +CGREG: 2,4
0000315875 [ncp.at] TRACE: < OK
0000317077 [ncp.at] TRACE: < APP RDY
0000318479 [ncp.at] TRACE: < +CREG: 5,"9D03","266F903",8
0000318481 [ncp.at] TRACE: > AT+CIMI
0000318482 [ncp.at] TRACE: < +CEREG: 5,"9D03","266F903",8
0000318484 [ncp.at] TRACE: < 234104869682393
0000318485 [ncp.at] TRACE: < OK
0000318585 [ncp.client] TRACE: NCP connection state changed: 2
0000318586 [mux] INFO: Opening mux channel 2
0000318633 [net.pppncp] TRACE: NCP event 100
0000318634 [net.pppncp] TRACE: New auth info
0000318799 [net.pppncp] TRACE: NCP event 2
0000318800 [net.pppncp] TRACE: State changed event: 2
0000318801 [net.ppp.client] TRACE: PPP thread event LOWER_UP data=0
0000318804 [net.ppp.client] TRACE: State READY -> CONNECT
0000318802 [ncp.at] TRACE: > AT+CIMI
0000318815 [ncp.at] TRACE: < 234104869682393
0000318820 [ncp.at] TRACE: < OK
0000318975 [net.ppp.client] TRACE: State CONNECT -> CONNECTING
0000319152 [net.ppp.ipcp] TRACE: init
0000319153 [net.ppp.ipcp] TRACE: disable 1 0 0
0000319154 [net.ppp.ipcp] TRACE: enable 0 0 0
0000320263 [ncp.at] TRACE: > AT
0000320264 [ncp.at] TRACE: < OK
0000320265 [ncp.at] TRACE: > ATO
0000320266 [ncp.at] TRACE: < NO CARRIER
0000320267 [ncp.at] TRACE: > ATD*99***1#
0000320269 [ncp.at] TRACE: < CONNECT 150000000
0000320270 [net.ppp.client] TRACE: PPP phase -> Initialize
0000320276 [net.ppp.client] TRACE: PPP phase -> Establish
0000386289 [net.ppp.client] TRACE: PPP phase -> Disconnect
0000386291 [net.ppp.client] TRACE: PPP phase -> Dead
0000386292 [net.ppp.client] TRACE: PPP thread event ERROR data=5
0000386293 [net.pppncp] ERROR: PPP error event data=5
0000386294 [net.ppp.client] TRACE: PPP thread event DOWN data=0
0000386301 [net.ppp.client] TRACE: State CONNECTING -> DISCONNECT
0000386503 [net.ppp.client] TRACE: State DISCONNECT -> DISCONNECTING
0000386671 [net.ppp.client] TRACE: PPP thread event ERROR data=5
0000386678 [net.pppncp] ERROR: PPP error event data=5
0000386679 [net.ppp.client] TRACE: PPP thread event DOWN data=0
0000386680 [net.ppp.client] TRACE: State DISCONNECTING -> DISCONNECTED
0000386874 [net.ppp.client] TRACE: State DISCONNECTED -> CONNECT
0000387148 [net.ppp.client] TRACE: State CONNECT -> CONNECTING
0000387325 [net.ppp.ipcp] TRACE: init
0000387326 [net.ppp.ipcp] TRACE: disable 1 0 0
0000387327 [net.ppp.ipcp] TRACE: enable 0 0 0
0000388435 [ncp.at] TRACE: > AT
0000388937 [ncp.at] TRACE: > AT
0000390545 [ncp.at] TRACE: > AT
0000391047 [ncp.at] TRACE: > AT
0000392654 [ncp.at] TRACE: > AT
0000393156 [ncp.at] TRACE: > AT
0000394764 [ncp.at] TRACE: > AT
0000395265 [ncp.at] TRACE: > AT
0000396872 [ncp.at] TRACE: > AT
0000397374 [ncp.at] TRACE: > AT
0000397876 [ncp.client] ERROR: Failed to enter data mode
0000397877 [net.ppp.client] ERROR: Failed to dial
0000397879 [net.ppp.client] TRACE: State CONNECTING -> CONNECT
0000397878 [net.pppncp] TRACE: NCP event 3
0000397885 [net.pppncp] TRACE: NCP power state changed: IF_POWER_STATE_POWERING_DOWN
0000398097 [system.nm] TRACE: Interface 4 power state changed: POWERING_DOWN
0000398098 [ncp.client] TRACE: Try powering modem off using AT command
0000398101 [ncp.at] TRACE: > AT+QPOWD
0000398102 [ncp.at] TRACE: < OK
0000398103 [ncp.client] TRACE: Waiting the modem to be turned off...
0000398195 [net.ppp.client] TRACE: State CONNECT -> CONNECTING
0000398372 [net.ppp.ipcp] TRACE: init
0000398373 [net.ppp.ipcp] TRACE: disable 1 0 0
0000398374 [net.ppp.ipcp] TRACE: enable 0 0 0
0000398833 [net.pppncp] TRACE: NCP event 3
0000398834 [net.pppncp] TRACE: NCP power state changed: IF_POWER_STATE_DOWN
0000398836 [system.nm] TRACE: Interface 4 power state changed: DOWN
0000398837 [ncp.client] TRACE: It takes 734 ms to power off the modem.
0000398839 [mux] INFO: Stopping GSM07.10 muxer
0000398840 [mux] INFO: GSM07.10 muxer thread exiting
0000398846 [ncp.client] TRACE: NCP connection state changed: 1
0000398852 [net.pppncp] TRACE: NCP event 2
0000398853 [net.pppncp] TRACE: State changed event: 1
0000398854 [mux] INFO: GSM07.10 muxer stopped
0000398859 [ncp.client] TRACE: Soft power off modem success
0000398865 [ncp.client] TRACE: Deinit modem serial.
0000398867 [net.pppncp] ERROR: Failed to initialize cellular NCP client: -210
0000404395 [ncp.client] ERROR: Failed to enter data mode
0000404396 [net.ppp.client] ERROR: Failed to dial
0000404397 [net.ppp.client] TRACE: State CONNECTING -> CONNECT
0000404498 [ncp.client] TRACE: Modem already off
0000404504 [ncp.client] TRACE: Soft power off modem success
0000404589 [ncp.client] TRACE: Deinit modem serial.
0000404591 [ncp.client] TRACE: NCP connection state changed: 0
0000404592 [net.pppncp] TRACE: NCP event 2
0000404593 [net.pppncp] TRACE: State changed event: 0
0000404595 [ncp.client] TRACE: NCP state changed: 0
0000404596 [net.pppncp] TRACE: NCP event 1
0000404597 [ncp.client] TRACE: Powering modem on, ncpId: 0x6a
0000404599 [net.pppncp] TRACE: NCP event 3
0000404600 [net.pppncp] TRACE: NCP power state changed: IF_POWER_STATE_POWERING_UP
0000404602 [system.nm] TRACE: Interface 4 power state changed: POWERING_UP
0000404588 [net.ppp.client] TRACE: PPP thread event LOWER_DOWN data=0
0000404605 [net.ppp.client] TRACE: State CONNECT -> DISCONNECT
0000404774 [net.ppp.client] TRACE: State DISCONNECT -> DISCONNECTING
0000404947 [net.ppp.client] TRACE: PPP thread event LOWER_DOWN data=0
0000404948 [net.ppp.client] TRACE: PPP thread event ERROR data=5
0000404950 [net.pppncp] ERROR: PPP error event data=5
0000404951 [net.ppp.client] TRACE: PPP thread event DOWN data=0
0000404953 [net.ppp.client] TRACE: State DISCONNECTING -> DISCONNECTED
0000405121 [net.ppp.client] TRACE: State DISCONNECTED -> READY
0000406440 [net.pppncp] TRACE: NCP event 3
0000406441 [net.pppncp] TRACE: NCP power state changed: IF_POWER_STATE_UP
0000406442 [system.nm] TRACE: Interface 4 power state changed: UP
0000406443 [ncp.client] TRACE: Modem powered on
0000407446 [ncp.at] TRACE: > AT
0000407448 [ncp.at] TRACE: < OK
0000407448 [ncp.client] TRACE: NCP ready to accept AT commands
0000407450 [ncp.at] TRACE: > AT+CFUN?
0000407457 [ncp.at] TRACE: < +CFUN: 1
0000407458 [ncp.at] TRACE: < OK
0000407459 [ncp.at] TRACE: > AT+IFC=2,2
0000407461 [ncp.at] TRACE: < OK
0000407462 [ncp.at] TRACE: > AT
0000407464 [ncp.at] TRACE: < OK
0000407465 [ncp.at] TRACE: > AT+IPR=921600
0000407470 [ncp.at] TRACE: < OK
0000408473 [ncp.at] TRACE: > AT
0000408474 [ncp.at] TRACE: < OK
0000408646 [ncp.at] TRACE: > AT+CPIN?
0000408647 [ncp.at] TRACE: < +CPIN: READY
0000408648 [ncp.at] TRACE: < OK
0000408648 [ncp.at] TRACE: > AT+CCID
0000408649 [ncp.at] TRACE: < +CCID: 89883070000039913841
0000408651 [ncp.at] TRACE: < OK
0000408652 [ncp.at] TRACE: > AT+CEDRXS=0
0000408654 [ncp.at] TRACE: < OK
0000408655 [ncp.at] TRACE: > AT+CPSMS=0
0000408656 [ncp.at] TRACE: < OK
0000408657 [ncp.at] TRACE: > AT+CMUX=0,0,8,1509,,,,,
0000408658 [ncp.at] TRACE: < OK
0000408658 [mux] INFO: Starting GSM07.10 muxer
0000408659 [mux] INFO: Opening mux channel 0
0000408660 [mux] INFO: GSM07.10 muxer thread started
0000408763 [mux] INFO: Opening mux channel 1
0000408817 [ncp.at] TRACE: > AT
0000408818 [ncp.at] TRACE: < +CREG: 0
0000408819 [ncp.at] TRACE: < +CEREG: 0
0000408819 [ncp.at] TRACE: < +CGEV: ME DETACH
0000408820 [ncp.at] TRACE: < OK
0000408821 [ncp.client] TRACE: NCP state changed: 1
0000408822 [net.pppncp] TRACE: NCP event 1
0000408828 [ncp.at] TRACE: > AT+QCFG="cmux/urcport",1
0000408830 [ncp.at] TRACE: < OK
0000408831 [ncp.at] TRACE: > AT+CGEREP=1,0
0000408833 [ncp.at] TRACE: < OK
0000408834 [net.ppp.client] TRACE: PPP thread event ADM_UP data=0
0000409099 [ncp.at] TRACE: > AT+CFUN=1,0
0000409101 [ncp.at] TRACE: < OK
0000409102 [ncp.at] TRACE: > AT+CCID
0000409103 [ncp.at] TRACE: < +CCID: 89883070000039913841
0000409106 [ncp.at] TRACE: < OK
0000409107 [ncp.at] TRACE: > AT+CGDCONT=1,"IP","super"
0000409108 [ncp.at] TRACE: < OK
0000409110 [ncp.at] TRACE: > AT+CFUN=1,0
0000409111 [ncp.at] TRACE: < OK
0000409112 [ncp.at] TRACE: > AT+CREG=2
0000409114 [ncp.at] TRACE: < OK
0000409115 [ncp.at] TRACE: > AT+CGREG=2
0000409116 [ncp.at] TRACE: < OK
0000409118 [ncp.at] TRACE: > AT+CEREG=2
0000409119 [ncp.at] TRACE: < OK
0000409120 [ncp.client] TRACE: NCP connection state changed: 1
0000409121 [net.pppncp] TRACE: NCP event 2
0000409122 [net.pppncp] TRACE: State changed event: 1
0000409124 [net.ppp.client] TRACE: PPP thread event LOWER_DOWN data=0
0000409126 [ncp.at] TRACE: > AT+COPS?
0000409127 [ncp.at] TRACE: < +COPS: 0
0000409128 [ncp.at] TRACE: < OK
0000409130 [ncp.at] TRACE: > AT+QCFG="nwscanmode"
0000409132 [ncp.at] TRACE: < +QCFG: "nwscanmode",3
0000409133 [ncp.at] TRACE: < OK
0000409134 [ncp.at] TRACE: > AT+QCFG="nwscanseq"
0000409136 [ncp.at] TRACE: < +QCFG: "nwscanseq",020103
0000409137 [ncp.at] TRACE: < OK
0000409139 [ncp.at] TRACE: > AT+QCFG="iotopmode"
0000409140 [ncp.at] TRACE: < +QCFG: "iotopmode",0
0000409142 [ncp.at] TRACE: < OK
0000409143 [ncp.at] TRACE: > AT+CEREG?
0000409145 [ncp.at] TRACE: < +CEREG: 2,2
0000409146 [ncp.at] TRACE: < OK
0000409147 [ncp.at] TRACE: > AT+CREG?
0000409148 [ncp.at] TRACE: < +CREG: 2,2
0000409149 [ncp.at] TRACE: < OK
0000409151 [ncp.at] TRACE: > AT+CGREG?
0000409152 [ncp.at] TRACE: < +CGREG: 2,4
0000409153 [ncp.at] TRACE: < OK
0000409963 [ncp.at] TRACE: < APP RDY
0000411764 [ncp.at] TRACE: < +CREG: 5,"9D03","266F903",8
0000411766 [ncp.at] TRACE: > AT+CIMI
0000411767 [ncp.at] TRACE: < +CEREG: 5,"9D03","266F903",8
0000411769 [ncp.at] TRACE: < 234104869682393
0000411769 [ncp.at] TRACE: < OK
0000411870 [ncp.client] TRACE: NCP connection state changed: 2
0000411871 [mux] INFO: Opening mux channel 2
0000411919 [net.pppncp] TRACE: NCP event 100
0000411920 [net.pppncp] TRACE: New auth info
0000412121 [net.pppncp] TRACE: NCP event 2
0000412122 [net.pppncp] TRACE: State changed event: 2
0000412123 [net.ppp.client] TRACE: PPP thread event LOWER_UP data=0
0000412127 [net.ppp.client] TRACE: State READY -> CONNECT
0000412125 [ncp.at] TRACE: > AT+CIMI
0000412137 [ncp.at] TRACE: < 234104869682393
0000412143 [ncp.at] TRACE: < OK
0000412297 [net.ppp.client] TRACE: State CONNECT -> CONNECTING
0000412474 [net.ppp.ipcp] TRACE: init
0000412475 [net.ppp.ipcp] TRACE: disable 1 0 0
0000412477 [net.ppp.ipcp] TRACE: enable 0 0 0
0000413585 [ncp.at] TRACE: > AT
0000413586 [ncp.at] TRACE: < OK
0000413587 [ncp.at] TRACE: > ATO
0000413588 [ncp.at] TRACE: < NO CARRIER
0000413589 [ncp.at] TRACE: > ATD*99***1#
0000413591 [ncp.at] TRACE: < CONNECT 150000000
0000413593 [net.ppp.client] TRACE: PPP phase -> Initialize
0000413598 [net.ppp.client] TRACE: PPP phase -> Establish
0000436999 [ncp.at] TRACE: > AT+CFUN?
0000437019 [ncp.at] TRACE: < +CFUN: 1
0000437023 [ncp.at] TRACE: < OK
0000437025 [ncp.at] TRACE: > AT+CCID
0000437027 [ncp.at] TRACE: < +CCID: 89883070000039913841
0000437029 [ncp.at] TRACE: < OK
0000437031 [ncp.at] TRACE: > AT+CGSN
0000437034 [ncp.at] TRACE: < 862044067623368
0000437037 [ncp.at] TRACE: < OK
0000437039 [ncp.at] TRACE: > AT+CGMR
0000437041 [ncp.at] TRACE: < BG95M5LAR02A03
0000437043 [ncp.at] TRACE: < OK
0000437101 [comm.coap] TRACE: Sending CoAP message
0000437127 [comm.coap] TRACE: CON 2.05  size=249 token=02 id=11
0000437164 [system] ERROR: sock_send returned -1 118
0000437191 [comm.dtls] ERROR: mbedtls_ssl_write() failed: -0x4e
0000437223 [comm.protocol] ERROR: Event loop error 33
0000437251 [system] ERROR: sock_send returned -1 118
0000437278 [comm.dtls] ERROR: mbedtls_ssl_read() failed: -0x4e
0000437310 [comm.coap] TRACE: Retransmitting CoAP message; ID: 10; attempt 1 of 3
0000437352 [comm.coap] TRACE: Sending CoAP message
0000437378 [comm.coap] TRACE: CON 2.05  size=235 token=01 id=10
0000437410 [system] ERROR: sock_send returned -1 118
0000437437 [comm.dtls] ERROR: mbedtls_ssl_write() failed: -0x4e
0000437470 [comm.coap] TRACE: Retransmitting CoAP message; ID: 9; attempt 1 of 3
0000437511 [comm.coap] TRACE: Sending CoAP message
0000437537 [comm.coap] TRACE: CON GET /e/spark size=12 token= id=9
0000437571 [system] ERROR: sock_send returned -1 118
0000437598 [comm.dtls] ERROR: mbedtls_ssl_write() failed: -0x4e
0000437631 [comm.coap] TRACE: Retransmitting CoAP message; ID: 8; attempt 1 of 3
0000437672 [comm.coap] TRACE: Sending CoAP message
0000437698 [comm.coap] TRACE: CON GET /e/particle size=15 token= id=8
0000437734 [system] ERROR: sock_send returned -1 118
0000437761 [comm.dtls] ERROR: mbedtls_ssl_write() failed: -0x4e
0000437793 [comm.coap] TRACE: Retransmitting CoAP message; ID: 7; attempt 1 of 3
0000437834 [comm.coap] TRACE: Sending CoAP message
0000437860 [comm.coap] TRACE: CON POST /d?\x02 size=25 token=86 id=7
0000437895 [system] ERROR: sock_send returned -1 118
0000437922 [comm.dtls] ERROR: mbedtls_ssl_write() failed: -0x4e
0000437955 [comm.coap] TRACE: Retransmitting CoAP message; ID: 6; attempt 1 of 3
0000437996 [comm.coap] TRACE: Sending CoAP message
0000438022 [comm.coap] TRACE: CON POST /E/particle/device/updates/forced size=44 token= id=6
0000438069 [system] ERROR: sock_send returned -1 118
0000438096 [comm.dtls] ERROR: mbedtls_ssl_write() failed: -0x4e
0000438129 [comm.coap] TRACE: Retransmitting CoAP message; ID: 5; attempt 1 of 3
0000438170 [comm.coap] TRACE: Sending CoAP message
0000438196 [comm.coap] TRACE: CON POST /E/particle/device/updates/enabled size=44 token= id=5
0000438244 [system] ERROR: sock_send returned -1 118
0000438271 [comm.dtls] ERROR: mbedtls_ssl_write() failed: -0x4e
0000438303 [comm.coap] TRACE: Retransmitting CoAP message; ID: 4; attempt 1 of 3
0000438344 [comm.coap] TRACE: Sending CoAP message
0000438370 [comm.coap] TRACE: CON POST /E/spark/device/last_reset size=38 token= id=4
0000438414 [system] ERROR: sock_send returned -1 118
0000438441 [comm.dtls] ERROR: mbedtls_ssl_write() failed: -0x4e
0000438473 [comm.coap] TRACE: Retransmitting CoAP message; ID: 3; attempt 1 of 3
0000438514 [comm.coap] TRACE: Sending CoAP message
0000438540 [comm.coap] TRACE: CON GET /t size=7 token=85 id=3
0000438572 [system] ERROR: sock_send returned -1 118
0000438599 [comm.dtls] ERROR: mbedtls_ssl_write() failed: -0x4e
0000438631 [comm.coap] TRACE: Retransmitting CoAP message; ID: 2; attempt 1 of 3
0000438672 [comm.coap] TRACE: Sending CoAP message
0000438698 [comm.coap] TRACE: CON POST /d?\x01 size=253 token=84 id=2
0000438734 [system] ERROR: sock_send returned -1 118
0000438761 [comm.dtls] ERROR: mbedtls_ssl_write() failed: -0x4e
0000438793 [comm.protocol] ERROR: Event loop error 34
0000439157 [system] TRACE: Resolving 0a10aced202194944a051d48.v6.udp.particle.io#5684
0000439201 [system] ERROR: Failed to determine server address
0000439233 [system] WARN: Internet test failed: -170 DNS
0000439262 [system] WARN: Cloud handshake failed, code=10
0000439541 [system] INFO: Cloud: disconnecting
0000439729 [system] INFO: Cloud: disconnected
0000479609 [net.ppp.client] TRACE: PPP phase -> Disconnect
0000479611 [net.ppp.client] TRACE: PPP phase -> Dead
0000479612 [net.ppp.client] TRACE: PPP thread event ERROR data=5
0000479613 [net.pppncp] ERROR: PPP error event data=5
0000479614 [net.ppp.client] TRACE: PPP thread event DOWN data=0
0000479617 [net.ppp.client] TRACE: State CONNECTING -> DISCONNECT
0000479805 [net.ppp.client] TRACE: State DISCONNECT -> DISCONNECTING
0000479974 [net.ppp.client] TRACE: PPP thread event ERROR data=5
0000479975 [net.pppncp] ERROR: PPP error event data=5
0000479977 [net.ppp.client] TRACE: PPP thread event DOWN data=0
0000479979 [net.ppp.client] TRACE: State DISCONNECTING -> DISCONNECTED
0000480147 [net.ppp.client] TRACE: State DISCONNECTED -> CONNECT
0000480421 [net.ppp.client] TRACE: State CONNECT -> CONNECTING
0000480602 [net.ppp.ipcp] TRACE: init
0000480603 [net.ppp.ipcp] TRACE: disable 1 0 0
0000480604 [net.ppp.ipcp] TRACE: enable 0 0 0
0000481708 [ncp.at] TRACE: > AT
0000481709 [ncp.at] TRACE: < OK
0000481710 [ncp.at] TRACE: > ATO
0000481711 [ncp.at] TRACE: < NO CARRIER
0000481712 [ncp.at] TRACE: > ATD*99***1#
0000481714 [ncp.at] TRACE: < CONNECT 150000000
0000481715 [net.ppp.client] TRACE: PPP phase -> Initialize
0000481718 [net.ppp.client] TRACE: PPP phase -> Establish
0000482248 [net.ppp.ipcp] TRACE: lowerUp
0000482249 [net.ppp.client] TRACE: PPP phase -> Authenticate
0000482774 [net.ppp.client] TRACE: PPP phase -> Network
0000482776 [net.ppp.ipcp] TRACE: open
0000482777 [net.ppp.ipcp] TRACE: resetting CI
0000482778 [net.ppp.ipcp] TRACE: iur CI length: 18
0000482948 [net.ppp.ipcp] TRACE: input 4
0000483121 [net.ppp.ipcp] TRACE: input 22
0000483122 [net.ppp.ipcp] TRACE: iur CI length: 18
0000483297 [net.ppp.ipcp] TRACE: input 22
0000483298 [net.ppp.ipcp] TRACE: up
0000483299 [net.ifapi] INFO: Netif pp3 link UP, profile=NONE
0000483537 [system.nm] INFO: State changed: IFACE_UP -> IFACE_LINK_UP
0000483539 [net.ifapi] TRACE: Netif pp3 ipv4 configuration changed
0000483542 [hal] INFO: DNS server list changed
0000483543 [system.nm] INFO: State changed: IFACE_LINK_UP -> IP_CONFIGURED
0000483545 [hal] INFO: DNS server list changed
0000483546 [net.ppp.client] TRACE: PPP phase -> Running
0000483539 [net.ppp.client] TRACE: PPP thread event UP data=0
0000483550 [net.ppp.client] TRACE: State CONNECTING -> CONNECTED
0000483728 [net.pppncp] TRACE: Negotiated MTU: 1500
0000483730 [system] INFO: Cloud: connecting
0000484034 [system] INFO: Read Server Address = type:1,domain:$id.udp.particle.io
0000484075 [system] INFO: Loaded cloud server address and port from session data
0000484116 [system] TRACE: Address type: 1
0000484138 [system] TRACE: Cloud socket=0, family=2, type=2, protocol=17
0000484175 [system.cm] TRACE: Using best network: Cellular
0000484205 [system] INFO: Cloud socket=0, connecting to 52.45.184.198#5684 using if 4
0000484249 [system] INFO: Bound cloud socket to lwip if 4 ("pp3")
0000484282 [system] TRACE: Cloud socket=0, connected to 52.45.184.198#5684
0000484320 [system] TRACE: Updating cloud keepalive for AF_INET: 1380000 -> 1380000
0000484363 [system] TRACE: Applying new keepalive interval now
0000484395 [system] INFO: Cloud socket connected
0000484420 [system] INFO: Starting handshake: presense_announce=0
0000484453 [comm.protocol.handshake] INFO: Establish secure connection
0000484491 [comm.dtls] INFO: session has 0 uses
0000484520 [comm.dtls] INFO: (CMPL,RENEG,NO_SESS,ERR) restoreStatus=0
0000484557 [comm.dtls] INFO: out_ctr 0,1,0,0,0,0,0,13, next_coap_id=a
0000484592 [comm.dtls] INFO: restored session from persisted session data. next_msg_id=10
0000484638 [comm.dtls] INFO: session cmd (CLS,DIS,MOV,LOD,SAV): 2

rickkas7 · March 11, 2025, 2:08pm

The logs are unusual. In log 1, the connection proceeds normally. It actually connects at the beginning of log 2, then 51 seconds later the connection is terminated for unknown reasons.

0000229006 [comm.coap] TRACE: ACK 0.00  size=4 token= id=8018
0000280951 [net.ppp.client] TRACE: PPP phase -> Terminate

After that, the Device OS has trouble reinitializing the modem. The modem finally starts working properly around here (133 second later), but not really because it can't receive any packets (that's what the retransmission messages are):

0000413598 [net.ppp.client] TRACE: PPP phase -> Establish

It's not clear to me what's wrong. Sometimes the modem could behave that way because of power issues. However, it could also be a mobile network issue. The M-SoM is connecting to Verizon, which the B402 would not, so that's another difference.

radek · March 11, 2025, 6:32pm

Its connecting again

radek · March 21, 2025, 5:03pm

Following up, this happening on my msom again, on a blank firmware, but only on 6.3.0. The device connects immediately on 6.2.0.

I can currently switch back and forth between the 2 device os and cause the issue on 6.3.0. There is some network component to this, as I was running a blank firmware just fine on 6.3.0 earlier today.

radek · March 24, 2025, 12:18pm

I got a firmware to connect to LTE on 6.3.0 and found the line causing these issues. Actually, the issue can be traced back to 6.2.1.

The led will rapidly blink cyan forever if I do not call detachInterrupt(A6). In the Particle's system power manager, this pin is used as the default interrupt pin from the fuel gauge alert and bq24195 interrupt signal. While we have a bq24195 and MAX17048 built into our design, the interrupt pins aren't hooked up. Prior to 6.2.1, this would have been fine.

#include "Particle.h"

SYSTEM_MODE(AUTOMATIC);
SYSTEM_THREAD(ENABLED);

SerialLogHandler logHandler(LOG_LEVEL_INFO);

void setup() {
    Serial.begin();

    SystemPowerConfiguration conf;
    conf.feature(SystemPowerFeature::PMIC_DETECTION);
    // conf.interruptPin(A6);
    int res = System.setPowerConfiguration(conf);
    Log.info("res=%d", res);

    // bool success = detachInterrupt(A6);
    // Log.info("detach=%d", success);
}

void loop() {}

So I can call detachInterrupt(A6), but I was looking thru the device os and saw that A5 (LOW_BAT_DEPRECATED might sometimes be used instead of A6 (LOW_BAT_IC). So should I call conf.interruptPin(A6); to force A6 as the interrupt pin first? It doesn't look like its possible to say I don't have an interrupt pin connected, since if you call this with PIN_INVALID, it will use the default pin.

// ~/.particle/toolchains/deviceOS/6.2.1/system/src/system_power_manager.cpp 
hal_pin_t PowerManager::getIntPin() const {
  hal_pin_t pin = LOW_BAT_UC;
#if PLATFORM_ID == PLATFORM_MSOM
  uint32_t revision = 0xFFFFFFFF;
  hal_get_device_hw_version(&revision, nullptr);
  if (revision == 1) {
    pin = LOW_BAT_DEPRECATED;
  }
#endif
  if (config_.version >= HAL_POWER_CONFIG_VERSION_1 && config_.int_pin != PIN_INVALID) {
    pin = config_.int_pin;
  }
  return pin;
}

rickkas7 · March 24, 2025, 1:01pm

Only EVT (engineering validation test) M-SoM use A5.

All DVT (design validation) and production modules use A6 and will have the version set in the hw_version field and will use A6.

You should never encounter an EVT module. It won't have a serial number sticker, so if your module has a sticker, it's definitely not an EVT.

Not having the interrupt connected to the PMIC will probably break battery detection. Battery detection works because the PMIC rapidly goes between charging and not charging, many times per second. This is why the charge LED flickers while in DFU mode. Detection of this requires the interrupt to work properly.

Topic		Replies	Views
Boron LTE OS 0.9 breathing cyan but not connected to particle cloud Firmware boron	10	917	April 17, 2019
Cloud Connectivity Issues Cloud	3	375	October 31, 2020
Boron stuck in rapid cyan blink Connectivity boron	2	750	December 4, 2020
Connection Issues Cellular boron	1	826	February 25, 2021
[SOLVED]Breathing Green Troubleshooting	2	1080	May 17, 2016

MSOM Connecting to Cloud Blocking Reprogramming

Related topics