Since a couple weeks ago I've been seeing an increased amount of events on all my borons consoles. I'm afraid that some of them may be having connectivity issues since some are skipping reports (they should be reporting once every 15minutes and some of them may be reporting just 3 or 2 times an hour) and also some others are just impossible to update through OTA if it is not declared as an automated FW update through Particle Product declaration. This is weird because I thought that it may be related to my own FW but I uploaded the Tinker app as it is and this is what is shown on one of the Boron's Console.
Is this happening to someone else? Is it a known issue?
That log could be seen with poor cellular connectivity. Either use the web device doctor or add this to your firmware (or a new empty project):
SerialLogHandler logHandler(LOG_LEVEL_TRACE);
and monitor the USB serial debug. Get several minutes of logs, at least a few minutes after breathing cyan, a few cycles if it switches back to blinking green, and at least 11 minutes if it stays blinking green (presumably not what you are seeing, just general advice).
Hello Rick,
Thank you for your response, here are the logs from one of the affected devices, I captured the logs with timestamps and also here is a capture of what this device is showing on the console.
I had already noted during my tests in the previous days that each of the console message is showing following one "[mux] Error ... " message on the log this device also showed one disconnect event from the particle cloud at abou the xx:08 timestamp that is also following an "[mux] ERROR: The other end has not replied to keep alives (TESTs) 5 times, considering muxed connection dead" message on the log. Feel free to see both the picture and the log document, if you need more information I can share any.
I can also note that this test was taken flashing this FW using usb cable. Particle OS version is 6.2.1 on the device. And this behavior is consistent on Borons deployed to Latam (Chile) and Europe (Spain).
Best regards and thanks in advance for any help.
MRM
#include "Particle.h"
SYSTEM_MODE(AUTOMATIC);
SYSTEM_THREAD(ENABLED);
SerialLogHandler logHandler(LOG_LEVEL_ALL);
void setup() {
}
void loop() {
}
I have the full .txt of exported logs but it does not let me share the file here so I'm copying only a bit where I think it may have some useful info
20:04:19:928 -> 0000140059 [ncp.at] TRACE: < OK
20:04:19:928 -> 0000140060 [ncp.at] TRACE: > AT+IFC?
20:04:19:932 -> 0000140063 [ncp.at] TRACE: < +IFC: 2,2
20:04:19:933 -> 0000140064 [ncp.at] TRACE: < OK
20:04:19:933 -> 0000140064 [ncp.at] TRACE: > AT+IFC=2,2
20:04:19:936 -> 0000140068 [ncp.at] TRACE: < OK
20:04:19:937 -> 0000140068 [ncp.at] TRACE: > AT
20:04:20:916 -> 0000141045 [ncp.at] TRACE: < +UMWI: 0,1
20:04:20:916 -> 0000141046 [ncp.at] TRACE: < +UMWI: 0,2
20:04:20:925 -> 0000141047 [ncp.at] TRACE: < +UMWI: 0,3
20:04:20:925 -> 0000141049 [ncp.at] TRACE: < +UMWI: 0,4
20:04:20:938 -> 0000141069 [ncp.at] TRACE: > AT
20:04:20:940 -> 0000141071 [ncp.at] TRACE: < OK
20:04:20:940 -> 0000141071 [ncp.at] TRACE: > AT+IPR=921600
20:04:20:944 -> 0000141075 [ncp.at] TRACE: < OK
20:04:20:946 -> 0000141077 [ncp.at] TRACE: > AT
20:04:20:947 -> 0000141078 [ncp.at] TRACE: <
20:04:20:948 -> 0000141079 [ncp.at] TRACE: < OK
20:04:21:950 -> 0000142079 [ncp.at] TRACE: > AT
20:04:21:950 -> 0000142080 [ncp.at] TRACE: < OK
20:04:21:950 -> 0000142081 [ncp.at] TRACE: > AT+COPS=3,2
20:04:21:953 -> 0000142083 [ncp.at] TRACE: < OK
20:04:21:953 -> 0000142084 [ncp.at] TRACE: > AT+CGEREP=1,0
20:04:21:955 -> 0000142086 [ncp.at] TRACE: < OK
20:04:21:955 -> 0000142086 [ncp.at] TRACE: > AT+UPSV?
20:04:21:958 -> 0000142089 [ncp.at] TRACE: < +UPSV: 0
20:04:21:958 -> 0000142089 [ncp.at] TRACE: < OK
20:04:21:958 -> 0000142089 [ncp.at] TRACE: > AT+CMUX=0,0,,1509,,,,,
20:04:22:087 -> 0000142219 [ncp.at] TRACE: < OK
20:04:22:088 -> 0000142219 [mux] INFO: Starting GSM07.10 muxer
20:04:22:089 -> 0000142220 [mux] INFO: Opening mux channel 0
20:04:22:089 -> 0000142221 [mux] INFO: GSM07.10 muxer thread started
20:04:22:091 -> 0000142223 [mux] INFO: Opening mux channel 1
20:04:22:095 -> 0000142226 [ncp.at] TRACE: > AT
20:04:22:098 -> 0000142229 [ncp.at] TRACE: < OK
20:04:22:098 -> 0000142230 [ncp.client] TRACE: NCP state changed: 1
20:04:22:099 -> 0000142230 [net.pppncp] TRACE: NCP event 1
20:04:22:099 -> 0000142231 [net.ppp.client] TRACE: PPP thread event ADM_UP data=0
20:04:22:103 -> 0000142234 [ncp.at] TRACE: > AT
20:04:22:105 -> 0000142236 [ncp.at] TRACE: < OK
20:04:22:106 -> 0000142237 [ncp.at] TRACE: > AT+CFUN?
20:04:22:109 -> 0000142240 [ncp.at] TRACE: < +CFUN: 1,0
20:04:22:109 -> 0000142241 [ncp.at] TRACE: < OK
20:04:22:110 -> 0000142242 [ncp.at] TRACE: > AT+CCID
20:04:22:181 -> 0000142312 [ncp.at] TRACE: < +CCID: 89883070000006616682
20:04:22:181 -> 0000142313 [ncp.at] TRACE: < OK
20:04:22:182 -> 0000142314 [ncp.at] TRACE: > AT+CGDCONT?
20:04:22:186 -> 0000142317 [ncp.at] TRACE: < +CGDCONT: 1,"IP","super","0.0.0.0",0,0
20:04:22:186 -> 0000142318 [ncp.at] TRACE: < OK
20:04:22:187 -> 0000142319 [ncp.at] TRACE: > AT+CFUN?
20:04:22:190 -> 0000142321 [ncp.at] TRACE: < +CFUN: 1,0
20:04:22:191 -> 0000142322 [ncp.at] TRACE: < OK
20:04:22:191 -> 0000142323 [ncp.at] TRACE: > AT+CREG=2
20:04:22:194 -> 0000142325 [ncp.at] TRACE: < OK
20:04:22:195 -> 0000142326 [ncp.at] TRACE: > AT+CGREG=2
20:04:22:198 -> 0000142329 [ncp.at] TRACE: < OK
20:04:22:198 -> 0000142330 [ncp.client] TRACE: NCP connection state changed: 1
20:04:22:199 -> 0000142330 [net.pppncp] TRACE: NCP event 2
20:04:22:199 -> 0000142331 [net.pppncp] TRACE: State changed event: 1
20:04:22:200 -> 0000142332 [ncp.at] TRACE: > AT+COPS?
20:04:22:201 -> 0000142332 [net.ppp.client] TRACE: PPP thread event LOWER_DOWN data=0
20:04:22:203 -> 0000142334 [ncp.at] TRACE: < +COPS: 0
20:04:22:203 -> 0000142335 [ncp.at] TRACE: < OK
20:04:22:204 -> 0000142336 [ncp.at] TRACE: > AT+CREG?
20:04:22:207 -> 0000142339 [ncp.at] TRACE: < +CREG: 2,0
20:04:22:208 -> 0000142339 [ncp.at] TRACE: < OK
20:04:22:209 -> 0000142340 [ncp.at] TRACE: > AT+CGREG?
20:04:22:212 -> 0000142343 [ncp.at] TRACE: < +CGREG: 2,0
20:04:22:212 -> 0000142343 [ncp.at] TRACE: < OK
20:04:23:514 -> 0000143643 [ncp.at] TRACE: < +CREG: 5,"0484","8EA8D6B",6
20:04:23:514 -> 0000143644 [ncp.at] TRACE: > AT+CIMI
20:04:23:518 -> 0000143646 [ncp.at] TRACE: < 732123200686677
20:04:23:518 -> 0000143647 [ncp.at] TRACE: < OK
20:04:23:817 -> 0000143947 [ncp.at] TRACE: < +CGREG: 5,"0484","8EA8D6B",6,"83"
20:04:23:817 -> 0000143947 [ncp.client] TRACE: NCP connection state changed: 2
20:04:23:817 -> 0000143948 [mux] INFO: Opening mux channel 2
20:04:25:020 -> 0000145150 [net.pppncp] TRACE: NCP event 100
20:04:25:020 -> 0000145151 [net.pppncp] TRACE: New auth info
20:04:25:023 -> 0000145153 [net.pppncp] TRACE: NCP event 2
20:04:25:023 -> 0000145153 [net.pppncp] TRACE: State changed event: 2
20:04:25:023 -> 0000145154 [net.ppp.client] TRACE: PPP thread event LOWER_UP data=0
20:04:25:023 -> 0000145154 [net.ppp.client] TRACE: State READY -> CONNECT
20:04:25:025 -> 0000145155 [ncp.at] TRACE: > AT+CIMI
20:04:25:027 -> 0000145158 [ncp.at] TRACE: < 732123200686677
20:04:25:027 -> 0000145157 [net.ppp.client] TRACE: State CONNECT -> CONNECTING
20:04:25:028 -> 0000145159 [ncp.at] TRACE: < OK
20:04:25:030 -> 0000145161 [ncp.at] TRACE: > AT+CGATT?
20:04:25:032 -> 0000145164 [ncp.at] TRACE: < +CGATT: 1
20:04:25:035 -> 0000145164 [ncp.at] TRACE: < OK
20:04:26:035 -> 0000146165 [ncp.at] TRACE: > AT
20:04:26:036 -> 0000146167 [ncp.at] TRACE: < OK
20:04:26:036 -> 0000146167 [ncp.at] TRACE: > ATH
20:04:26:038 -> 0000146169 [ncp.at] TRACE: < OK
20:04:26:039 -> 0000146170 [ncp.at] TRACE: > ATD*99***1#
20:04:26:042 -> 0000146173 [ncp.at] TRACE: < CONNECT
20:04:26:042 -> 0000146174 [net.ppp.client] TRACE: PPP phase -> Initialize
20:04:26:043 -> 0000146174 [net.ppp.client] TRACE: PPP phase -> Establish
20:04:26:043 -> 0000146175 [lwip.ppp] TRACE: sent [LCP ConfReq id=0x3 <asyncmap 0x0> <magic 0x4bc7dd45> <pcomp> <accomp>]
20:04:26:049 -> 0000146180 [lwip.ppp] TRACE: rcvd [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0xd4fb98a1> <pcomp> <accomp>]
20:04:26:050 -> 0000146181 [lwip.ppp] TRACE: sent [LCP ConfAck id=0x1 <asyncmap 0x0> <magic 0xd4fb98a1> <pcomp> <accomp>]
20:04:26:052 -> 0000146183 [lwip.ppp] TRACE: rcvd [LCP ConfAck id=0x3 <asyncmap 0x0> <magic 0x4bc7dd45> <pcomp> <accomp>]
20:04:26:052 -> 0000146184 [lwip.ppp] TRACE: sent [LCP EchoReq id=0x0 magic=0x4bc7dd45]
20:04:26:053 -> 0000146185 [net.ppp.client] TRACE: PPP phase -> Authenticate
20:04:26:054 -> 0000146185 [net.ppp.client] TRACE: PPP phase -> Network
20:04:26:055 -> 0000146186 [lwip.ppp] TRACE: sent [IPCP ConfReq id=0x1 <addr 0.0.0.0> <msdns1 8.8.8.8> <msdns2 8.8.4.4>]
20:04:26:059 -> 0000146189 [lwip.ppp] TRACE: rcvd [LCP EchoRep id=0x0 magic=0xd4fb98a1]
20:04:31:054 -> 0000151185 [lwip.ppp] TRACE: sent [LCP EchoReq id=0x1 magic=0x4bc7dd45]
20:04:31:057 -> 0000151188 [lwip.ppp] TRACE: rcvd [LCP EchoRep id=0x1 magic=0xd4fb98a1]
20:04:32:057 -> 0000152188 [lwip.ppp] TRACE: sent [IPCP ConfReq id=0x1 <addr 0.0.0.0> <msdns1 8.8.8.8> <msdns2 8.8.4.4>]
20:04:32:060 -> 0000152192 [lwip.ppp] TRACE: rcvd [IPCP ConfReq id=0x1]
20:04:32:061 -> 0000152192 [lwip.ppp] TRACE: sent [IPCP ConfAck id=0x1]
20:04:32:064 -> 0000152195 [lwip.ppp] TRACE: rcvd [IPCP ConfNak id=0x1 <addr 100.65.108.99> <msdns1 8.8.4.4> <msdns2 8.8.8.8>]
20:04:32:064 -> 0000152196 [lwip.ppp] TRACE: sent [IPCP ConfReq id=0x2 <addr 100.65.108.99> <msdns1 8.8.4.4> <msdns2 8.8.8.8>]
20:04:32:069 -> 0000152200 [lwip.ppp] TRACE: rcvd [IPCP ConfAck id=0x2 <addr 100.65.108.99> <msdns1 8.8.4.4> <msdns2 8.8.8.8>]
20:04:32:072 -> 0000152203 [system.nm] INFO: State changed: IFACE_UP -> IFACE_LINK_UP
20:04:32:073 -> 0000152205 [net.ppp.client] TRACE: PPP thread event UP data=0
20:04:32:074 -> 0000152205 [net.ppp.client] TRACE: State CONNECTING -> CONNECTED
20:04:32:075 -> 0000152206 [system.nm] INFO: State changed: IFACE_LINK_UP -> IP_CONFIGURED
20:04:32:077 -> 0000152208 [net.ppp.client] TRACE: PPP phase -> Running
20:04:32:078 -> 0000152209 [net.pppncp] TRACE: Negotiated MTU: 1500
20:04:32:086 -> 0000152216 [comm.coap] TRACE: Sending CoAP message
20:04:32:086 -> 0000152216 [comm.coap] TRACE: CON 0.00 size=4 token= id=62
20:04:36:487 -> 0000156618 [comm.coap] TRACE: Retransmitting CoAP message; ID: 62; attempt 1 of 3
20:04:36:491 -> 0000156618 [comm.coap] TRACE: Sending CoAP message
20:04:36:491 -> 0000156620 [comm.coap] TRACE: CON 0.00 size=4 token= id=62
20:04:37:613 -> 0000157743 [comm.coap] TRACE: Received CoAP message
20:04:37:615 -> 0000157745 [comm.coap] TRACE: ACK 0.00 size=4 token= id=62
20:06:10:194 -> 0000250323 [mux] ERROR: The other end has not replied to keep alives (TESTs) 5 times, considering muxed connection dead
20:06:10:194 -> 0000250324 [ncp.client] TRACE: NCP connection state changed: 1
20:06:10:194 -> 0000250324 [net.pppncp] TRACE: NCP event 2
20:06:10:197 -> 0000250324 [net.pppncp] TRACE: State changed event: 1
20:06:10:197 -> 0000250325 [mux] INFO: GSM07.10 muxer thread exiting
20:06:10:197 -> 0000250325 [net.ppp.client] TRACE: PPP thread event LOWER_DOWN data=0
20:06:10:197 -> 0000250326 [net.ppp.client] TRACE: State CONNECTED -> DISCONNECT
20:06:10:197 -> 0000250328 [net.ppp.client] TRACE: State DISCONNECT -> DISCONNECTING
20:06:10:200 -> 0000250330 [system.nm] INFO: State changed: IP_CONFIGURED -> IFACE_LINK_UP
20:06:10:200 -> 0000250331 [system.nm] INFO: State changed: IFACE_LINK_UP -> IFACE_UP
20:06:10:201 -> 0000250332 [net.ppp.client] TRACE: PPP phase -> Network
20:06:10:202 -> 0000250332 [net.ppp.client] TRACE: PPP phase -> Establish
20:06:10:202 -> 0000250333 [net.ppp.client] TRACE: PPP phase -> Disconnect
20:06:10:202 -> 0000250333 [net.ppp.client] TRACE: PPP phase -> Dead
20:06:10:203 -> 0000250334 [net.ppp.client] TRACE: PPP thread event ERROR data=5
20:06:10:203 -> 0000250334 [net.pppncp] ERROR: PPP error event data=5
20:06:10:204 -> 0000250335 [net.ppp.client] TRACE: PPP thread event DOWN data=0
20:06:10:204 -> 0000250335 [net.ppp.client] TRACE: State DISCONNECTING -> DISCONNECTED
20:06:10:207 -> 0000250337 [net.ppp.client] TRACE: State DISCONNECTED -> READY
20:06:10:247 -> 0000250378 [net.pppncp] TRACE: NCP event 3
20:06:10:247 -> 0000250378 [net.pppncp] TRACE: NCP power state changed: IF_POWER_STATE_POWERING_DOWN
20:06:10:248 -> 0000250379 [system.nm] TRACE: Interface 4 power state changed: POWERING_DOWN
20:06:10:248 -> 0000250379 [ncp.client] TRACE: Powering off using AT command
20:06:10:249 -> 0000250380 [mux] INFO: Stopping GSM07.10 muxer
20:06:10:249 -> 0000250380 [mux] INFO: GSM07.10 muxer stopped
20:06:10:250 -> 0000250381 [ncp.client] TRACE: Powering off using hardware control
20:06:13:136 -> 0000253266 [net.pppncp] TRACE: NCP event 3
20:06:13:136 -> 0000253266 [net.pppncp] TRACE: NCP power state changed: IF_POWER_STATE_DOWN
20:06:13:137 -> 0000253267 [system.nm] TRACE: Interface 4 power state changed: DOWN
20:06:13:137 -> 0000253267 [ncp.client] TRACE: Powered off
20:06:13:137 -> 0000253268 [ncp.client] TRACE: Deinit UART
20:06:13:137 -> 0000253268 [ncp.client] TRACE: NCP connection state changed: 0
20:06:13:140 -> 0000253269 [net.pppncp] TRACE: NCP event 2
20:06:13:140 -> 0000253269 [net.pppncp] TRACE: State changed event: 0
20:06:13:140 -> 0000253269 [ncp.client] TRACE: NCP state changed: 0
20:06:13:140 -> 0000253270 [net.pppncp] TRACE: NCP event 1
20:06:13:140 -> 0000253270 [ncp.client] TRACE: Powering on, ncpId: 0x42
20:06:13:140 -> 0000253271 [net.pppncp] TRACE: NCP event 3
20:06:13:140 -> 0000253271 [net.pppncp] TRACE: NCP power state changed: IF_POWER_STATE_POWERING_UP
20:06:13:141 -> 0000253272 [system.nm] TRACE: Interface 4 power state changed: POWERING_UP
20:06:13:142 -> 0000253270 [net.ppp.client] TRACE: PPP thread event LOWER_DOWN data=0
20:06:13:152 -> 0000253283 [net.pppncp] TRACE: NCP event 3
20:06:13:152 -> 0000253283 [net.pppncp] TRACE: NCP power state changed: IF_POWER_STATE_UP
20:06:13:153 -> 0000253284 [system.nm] TRACE: Interface 4 power state changed: UP
20:06:13:153 -> 0000253284 [ncp.client] TRACE: Powered on
20:06:14:354 -> 0000254484 [ncp.at] TRACE: > AT
20:06:15:354 -> 0000255484 [ncp.at] TRACE: > AT
20:06:16:354 -> 0000256484 [ncp.at] TRACE: > AT
20:06:17:354 -> 0000257484 [ncp.at] TRACE: > AT
20:06:17:355 -> 0000257486 [ncp.at] TRACE: < OK
20:06:17:357 -> 0000257486 [ncp.client] TRACE: NCP ready to accept AT commands
20:06:17:357 -> 0000257487 [ncp.at] TRACE: > AT
20:06:17:359 -> 0000257489 [ncp.at] TRACE: < OK
20:06:17:359 -> 0000257489 [ncp.at] TRACE: > ATI9
20:06:17:375 -> 0000257506 [ncp.at] TRACE: < 23.60,A01.01
20:06:17:375 -> 0000257506 [ncp.at] TRACE: < OK
20:06:17:376 -> 0000257507 [ncp.client] TRACE: App firmware: 101
20:06:17:376 -> 0000257507 [ncp.at] TRACE: > AT+UGPIOC?
20:06:17:381 -> 0000257511 [ncp.at] TRACE: < +UGPIOC:
20:06:17:381 -> 0000257512 [ncp.at] TRACE: < 16,255
20:06:17:382 -> 0000257513 [ncp.at] TRACE: < 23,255
20:06:17:382 -> 0000257513 [ncp.at] TRACE: < 24,4
20:06:17:383 -> 0000257514 [ncp.at] TRACE: < 25,5
20:06:17:383 -> 0000257514 [ncp.at] TRACE: < 34,12
20:06:17:384 -> 0000257515 [ncp.at] TRACE: < 35,12
20:06:17:385 -> 0000257516 [ncp.at] TRACE: < 36,12
20:06:17:385 -> 0000257516 [ncp.at] TRACE: < 37,12
20:06:17:386 -> 0000257517 [ncp.at] TRACE: < 42,7
20:06:17:387 -> 0000257517 [ncp.at] TRACE: < OK
20:06:17:387 -> 0000257518 [ncp.client] INFO: Using internal SIM card
20:06:17:387 -> 0000257518 [ncp.at] TRACE: > AT+CPIN?
20:06:17:391 -> 0000257522 [ncp.at] TRACE: < ERROR
20:06:18:393 -> 0000258522 [ncp.at] TRACE: > AT+CPIN?
20:06:18:397 -> 0000258526 [ncp.at] TRACE: < +CPIN: READY
20:06:18:397 -> 0000258527 [ncp.at] TRACE: < OK
20:06:18:397 -> 0000258528 [ncp.at] TRACE: > AT+CCID
20:06:18:555 -> 0000258685 [ncp.at] TRACE: < +CCID: 89883070000006616682
20:06:18:555 -> 0000258686 [ncp.at] TRACE: < OK
20:06:18:556 -> 0000258687 [ncp.at] TRACE: > AT+IFC?
20:06:18:560 -> 0000258690 [ncp.at] TRACE: < +IFC: 2,2
20:06:18:560 -> 0000258691 [ncp.at] TRACE: < OK
20:06:18:561 -> 0000258691 [ncp.at] TRACE: > AT+IFC=2,2
20:06:18:564 -> 0000258695 [ncp.at] TRACE: < OK
20:06:18:564 -> 0000258695 [ncp.at] TRACE: > AT
20:06:19:571 -> 0000259696 [ncp.at] TRACE: > AT
20:06:19:571 -> 0000259699 [ncp.at] TRACE: < OK
20:06:19:571 -> 0000259699 [ncp.at] TRACE: > AT+IPR=921600
20:06:19:572 -> 0000259703 [ncp.at] TRACE: < OK
20:06:19:574 -> 0000259705 [ncp.at] TRACE: > AT
20:06:19:575 -> 0000259706 [ncp.at] TRACE: <
20:06:19:575 -> 0000259706 [ncp.at] TRACE: < OK
20:06:19:647 -> 0000259778 [ncp.at] TRACE: < +UMWI: 0,1
20:06:19:647 -> 0000259778 [ncp.at] TRACE: < +UMWI: 0,2
20:06:19:648 -> 0000259779 [ncp.at] TRACE: < +UMWI: 0,3
20:06:19:648 -> 0000259779 [ncp.at] TRACE: < +UMWI: 0,4
20:06:20:576 -> 0000260706 [ncp.at] TRACE: > AT
20:06:20:579 -> 0000260707 [ncp.at] TRACE: < OK
20:06:20:579 -> 0000260708 [ncp.at] TRACE: > AT+COPS=3,2
20:06:20:579 -> 0000260710 [ncp.at] TRACE: < OK
20:06:20:580 -> 0000260711 [ncp.at] TRACE: > AT+CGEREP=1,0
20:06:20:582 -> 0000260713 [ncp.at] TRACE: < OK
20:06:20:582 -> 0000260713 [ncp.at] TRACE: > AT+UPSV?
20:06:20:585 -> 0000260716 [ncp.at] TRACE: < +UPSV: 0
20:06:20:585 -> 0000260716 [ncp.at] TRACE: < OK
20:06:20:585 -> 0000260716 [ncp.at] TRACE: > AT+CMUX=0,0,,1509,,,,,
20:06:20:714 -> 0000260845 [ncp.at] TRACE: < OK
20:06:20:715 -> 0000260846 [mux] INFO: Starting GSM07.10 muxer
20:06:20:716 -> 0000260847 [mux] INFO: Opening mux channel 0
20:06:20:716 -> 0000260847 [mux] INFO: GSM07.10 muxer thread started
20:06:20:718 -> 0000260849 [mux] INFO: Opening mux channel 1
20:06:20:722 -> 0000260853 [ncp.at] TRACE: > AT
20:06:20:725 -> 0000260856 [ncp.at] TRACE: < OK
20:06:20:725 -> 0000260856 [ncp.client] TRACE: NCP state changed: 1
20:06:20:725 -> 0000260856 [net.pppncp] TRACE: NCP event 1
20:06:20:727 -> 0000260858 [net.ppp.client] TRACE: PPP thread event ADM_UP data=0
20:06:20:730 -> 0000260861 [ncp.at] TRACE: > AT
20:06:20:732 -> 0000260863 [ncp.at] TRACE: < OK
20:06:20:733 -> 0000260863 [ncp.at] TRACE: > AT+CFUN?
20:06:20:736 -> 0000260866 [ncp.at] TRACE: < +CFUN: 1,0
20:06:20:736 -> 0000260867 [ncp.at] TRACE: < OK
20:06:20:737 -> 0000260868 [ncp.at] TRACE: > AT+CCID
20:06:20:805 -> 0000260936 [ncp.at] TRACE: < +CCID: 89883070000006616682
20:06:20:805 -> 0000260936 [ncp.at] TRACE: < OK
20:06:20:806 -> 0000260937 [ncp.at] TRACE: > AT+CGDCONT?
20:06:20:810 -> 0000260941 [ncp.at] TRACE: < +CGDCONT: 1,"IP","super","0.0.0.0",0,0
20:06:20:811 -> 0000260941 [ncp.at] TRACE: < OK
20:06:20:811 -> 0000260942 [ncp.at] TRACE: > AT+CFUN?
20:06:20:814 -> 0000260945 [ncp.at] TRACE: < +CFUN: 1,0
20:06:20:815 -> 0000260946 [ncp.at] TRACE: < OK
20:06:20:816 -> 0000260946 [ncp.at] TRACE: > AT+CREG=2
20:06:20:827 -> 0000260957 [ncp.at] TRACE: < OK
20:06:20:827 -> 0000260958 [ncp.at] TRACE: > AT+CGREG=2
20:06:20:830 -> 0000260961 [ncp.at] TRACE: < OK
20:06:20:830 -> 0000260961 [ncp.client] TRACE: NCP connection state changed: 1
20:06:20:831 -> 0000260962 [net.pppncp] TRACE: NCP event 2
20:06:20:831 -> 0000260962 [net.pppncp] TRACE: State changed event: 1
20:06:20:832 -> 0000260963 [net.ppp.client] TRACE: PPP thread event LOWER_DOWN data=0
20:06:20:833 -> 0000260964 [ncp.at] TRACE: > AT+COPS?
20:06:20:835 -> 0000260966 [ncp.at] TRACE: < +COPS: 0
20:06:20:835 -> 0000260966 [ncp.at] TRACE: < OK
20:06:20:836 -> 0000260967 [ncp.at] TRACE: > AT+CREG?
20:06:20:838 -> 0000260969 [ncp.at] TRACE: < +CREG: 2,0
20:06:20:838 -> 0000260969 [ncp.at] TRACE: < OK
20:06:20:839 -> 0000260970 [ncp.at] TRACE: > AT+CGREG?
20:06:20:842 -> 0000260973 [ncp.at] TRACE: < +CGREG: 2,0
20:06:20:843 -> 0000260974 [ncp.at] TRACE: < OK
20:06:22:544 -> 0000262674 [ncp.at] TRACE: < +CREG: 5,"0484","8EA8D6B",6
20:06:22:544 -> 0000262675 [ncp.at] TRACE: > AT+CIMI
20:06:22:547 -> 0000262677 [ncp.at] TRACE: < 732123200686677
20:06:22:547 -> 0000262678 [ncp.at] TRACE: < OK
20:06:23:148 -> 0000263278 [ncp.at] TRACE: < +CGREG: 5,"0484","8EA8D6B",6,"83"
20:06:23:148 -> 0000263279 [ncp.client] TRACE: NCP connection state changed: 2
20:06:23:148 -> 0000263279 [mux] INFO: Opening mux channel 2
20:06:24:405 -> 0000264534 [net.pppncp] TRACE: NCP event 100
20:06:24:405 -> 0000264534 [net.pppncp] TRACE: New auth info
20:06:24:406 -> 0000264537 [net.pppncp] TRACE: NCP event 2
20:06:24:406 -> 0000264537 [net.pppncp] TRACE: State changed event: 2
20:06:24:408 -> 0000264538 [ncp.at] TRACE: > AT+CIMI
20:06:24:408 -> 0000264539 [net.ppp.client] TRACE: PPP thread event LOWER_UP data=0
20:06:24:409 -> 0000264540 [net.ppp.client] TRACE: State READY -> CONNECT
20:06:24:412 -> 0000264542 [net.ppp.client] TRACE: State CONNECT -> CONNECTING
20:06:24:413 -> 0000264543 [ncp.at] TRACE: < 732123200686677
20:06:24:413 -> 0000264544 [ncp.at] TRACE: < OK
20:06:24:415 -> 0000264546 [ncp.at] TRACE: > AT+CGATT?
20:06:24:417 -> 0000264548 [ncp.at] TRACE: < +CGATT: 1
20:06:24:418 -> 0000264548 [ncp.at] TRACE: < OK
20:06:25:419 -> 0000265549 [ncp.at] TRACE: > AT
20:06:25:420 -> 0000265551 [ncp.at] TRACE: < OK
20:06:25:422 -> 0000265552 [ncp.at] TRACE: > ATH
20:06:25:422 -> 0000265553 [ncp.at] TRACE: < OK
20:06:25:423 -> 0000265554 [ncp.at] TRACE: > ATD*99***1#
20:06:25:426 -> 0000265557 [ncp.at] TRACE: < CONNECT
20:06:25:427 -> 0000265557 [net.ppp.client] TRACE: PPP phase -> Initialize
20:06:25:427 -> 0000265558 [net.ppp.client] TRACE: PPP phase -> Establish
20:06:25:428 -> 0000265559 [lwip.ppp] TRACE: sent [LCP ConfReq id=0x4 <asyncmap 0x0> <magic 0x4749e3a5> <pcomp> <accomp>]
20:06:25:432 -> 0000265563 [lwip.ppp] TRACE: rcvd [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0xd4fb98a1> <pcomp> <accomp>]
20:06:25:434 -> 0000265565 [lwip.ppp] TRACE: sent [LCP ConfAck id=0x1 <asyncmap 0x0> <magic 0xd4fb98a1> <pcomp> <accomp>]
20:06:25:436 -> 0000265567 [lwip.ppp] TRACE: rcvd [LCP ConfAck id=0x4 <asyncmap 0x0> <magic 0x4749e3a5> <pcomp> <accomp>]
20:06:25:437 -> 0000265568 [lwip.ppp] TRACE: sent [LCP EchoReq id=0x0 magic=0x4749e3a5]
20:06:25:438 -> 0000265568 [net.ppp.client] TRACE: PPP phase -> Authenticate
20:06:25:438 -> 0000265569 [net.ppp.client] TRACE: PPP phase -> Network
20:06:25:439 -> 0000265570 [lwip.ppp] TRACE: sent [IPCP ConfReq id=0x1 <addr 0.0.0.0> <msdns1 8.8.8.8> <msdns2 8.8.4.4>]
20:06:25:442 -> 0000265573 [lwip.ppp] TRACE: rcvd [LCP EchoRep id=0x0 magic=0xd4fb98a1]
20:06:30:438 -> 0000270568 [lwip.ppp] TRACE: sent [LCP EchoReq id=0x1 magic=0x4749e3a5]
20:06:30:443 -> 0000270571 [lwip.ppp] TRACE: rcvd [LCP EchoRep id=0x1 magic=0xd4fb98a1]
20:06:31:443 -> 0000271572 [lwip.ppp] TRACE: sent [IPCP ConfReq id=0x1 <addr 0.0.0.0> <msdns1 8.8.8.8> <msdns2 8.8.4.4>]
20:06:31:447 -> 0000271577 [lwip.ppp] TRACE: rcvd [IPCP ConfReq id=0x1]
20:06:31:447 -> 0000271577 [lwip.ppp] TRACE: sent [IPCP ConfAck id=0x1]
20:06:31:448 -> 0000271579 [lwip.ppp] TRACE: rcvd [IPCP ConfNak id=0x1 <addr 100.65.69.13> <msdns1 8.8.4.4> <msdns2 8.8.8.8>]
20:06:31:449 -> 0000271580 [lwip.ppp] TRACE: sent [IPCP ConfReq id=0x2 <addr 100.65.69.13> <msdns1 8.8.4.4> <msdns2 8.8.8.8>]
20:06:31:454 -> 0000271584 [lwip.ppp] TRACE: rcvd [IPCP ConfAck id=0x2 <addr 100.65.69.13> <msdns1 8.8.4.4> <msdns2 8.8.8.8>]
20:06:31:457 -> 0000271588 [system.nm] INFO: State changed: IFACE_UP -> IFACE_LINK_UP
20:06:31:458 -> 0000271589 [net.ppp.client] TRACE: PPP thread event UP data=0
20:06:31:458 -> 0000271589 [net.ppp.client] TRACE: State CONNECTING -> CONNECTED
20:06:31:460 -> 0000271590 [system.nm] INFO: State changed: IFACE_LINK_UP -> IP_CONFIGURED
20:06:31:462 -> 0000271592 [net.ppp.client] TRACE: PPP phase -> Running
20:06:31:464 -> 0000271593 [net.pppncp] TRACE: Negotiated MTU: 1500
20:06:31:516 -> 0000271647 [comm.coap] TRACE: Sending CoAP message
20:06:31:516 -> 0000271647 [comm.coap] TRACE: CON 0.00 size=4 token= id=63
20:06:35:619 -> 0000275749 [comm.coap] TRACE: Retransmitting CoAP message; ID: 63; attempt 1 of 3
20:06:35:619 -> 0000275749 [comm.coap] TRACE: Sending CoAP message
20:06:35:620 -> 0000275751 [comm.coap] TRACE: CON 0.00 size=4 token= id=63
20:06:44:723 -> 0000284853 [comm.coap] TRACE: Retransmitting CoAP message; ID: 63; attempt 2 of 3
20:06:44:723 -> 0000284853 [comm.coap] TRACE: Sending CoAP message
20:06:44:724 -> 0000284855 [comm.coap] TRACE: CON 0.00 size=4 token= id=63
20:07:01:527 -> 0000301657 [comm.protocol] ERROR: Event loop error 1
20:07:01:527 -> 0000301657 [system] WARN: Communication loop error, closing cloud socket
20:07:01:529 -> 0000301659 [system] INFO: Cloud: disconnecting
20:07:01:529 -> 0000301659 [system] INFO: Cloud: disconnected
20:07:01:531 -> 0000301661 [system] INFO: Cloud: connecting
20:07:01:535 -> 0000301665 [system] INFO: Cloud socket connected
20:07:01:535 -> 0000301665 [comm.protocol.handshake] INFO: Establish secure connection
20:07:01:543 -> 0000301673 [comm.dtls] INFO: session has 0 uses
20:07:01:561 -> 0000301691 [comm.dtls] INFO: (CMPL,RENEG,NO_SESS,ERR) restoreStatus=0
20:07:01:562 -> 0000301693 [comm.dtls] INFO: out_ctr 0,1,0,0,0,0,0,27, next_coap_id=3f
20:07:01:563 -> 0000301693 [comm.dtls] INFO: restored session from persisted session data. next_msg_id=63
20:07:01:565 -> 0000301695 [comm.dtls] INFO: session cmd (CLS,DIS,MOV,LOD,SAV): 2
20:07:01:950 -> 0000302080 [ncp.at] TRACE: > AT+CFUN?
20:07:28:819 -> 0000328949 [mux] ERROR: The other end has not replied to keep alives (TESTs) 5 times, considering muxed connection dead
20:07:28:819 -> 0000328949 [ncp.client] TRACE: NCP connection state changed: 1
20:07:28:821 -> 0000328950 [net.pppncp] TRACE: NCP event 2
20:07:28:821 -> 0000328950 [net.pppncp] TRACE: State changed event: 1
20:07:28:821 -> 0000328951 [mux] INFO: GSM07.10 muxer thread exiting
20:07:28:821 -> 0000328951 [net.ppp.client] TRACE: PPP thread event LOWER_DOWN data=0
20:07:28:823 -> 0000328952 [net.ppp.client] TRACE: State CONNECTED -> DISCONNECT
20:07:28:823 -> 0000328952 [net.pppncp] TRACE: NCP event 3
20:07:28:823 -> 0000328953 [net.pppncp] TRACE: NCP power state changed: IF_POWER_STATE_POWERING_DOWN
20:07:28:825 -> 0000328954 [system.nm] TRACE: Interface 4 power state changed: POWERING_DOWN
20:07:28:825 -> 0000328955 [ncp.client] TRACE: Powering off using AT command
20:07:28:825 -> 0000328955 [mux] INFO: Stopping GSM07.10 muxer
20:07:28:827 -> 0000328957 [mux] INFO: GSM07.10 muxer stopped
20:07:28:827 -> 0000328957 [ncp.client] TRACE: Powering off using hardware control
20:07:28:827 -> 0000328956 [net.ppp.client] TRACE: State DISCONNECT -> DISCONNECTING
20:07:28:830 -> 0000328960 [system.nm] INFO: State changed: IP_CONFIGURED -> IFACE_LINK_UP
20:07:28:831 -> 0000328961 [system.nm] INFO: State changed: IFACE_LINK_UP -> IFACE_UP
20:07:28:831 -> 0000328961 [net.ppp.client] TRACE: PPP phase -> Network
20:07:28:832 -> 0000328962 [net.ppp.client] TRACE: PPP phase -> Establish
20:07:28:832 -> 0000328962 [net.ppp.client] TRACE: PPP phase -> Disconnect
20:07:28:833 -> 0000328963 [net.ppp.client] TRACE: PPP phase -> Dead
20:07:28:833 -> 0000328963 [net.ppp.client] TRACE: PPP thread event ERROR data=5
20:07:28:834 -> 0000328964 [net.pppncp] ERROR: PPP error event data=5
20:07:28:834 -> 0000328964 [net.ppp.client] TRACE: PPP thread event DOWN data=0
20:07:28:835 -> 0000328965 [net.ppp.client] TRACE: State DISCONNECTING -> DISCONNECTED
20:07:28:837 -> 0000328967 [net.ppp.client] TRACE: State DISCONNECTED -> READY
20:07:28:839 -> 0000328969 [comm.protocol.handshake] INFO: Skipping HELLO message
20:07:28:839 -> 0000328969 [comm.coap] TRACE: Sending CoAP message
20:07:28:841 -> 0000328971 [comm.coap] TRACE: CON 0.00 size=4 token= id=64
20:07:28:843 -> 0000328973 [system] ERROR: sock_send returned -1 118
20:07:28:843 -> 0000328973 [comm.dtls] ERROR: mbedtls_ssl_write() failed: -0x4e
20:07:28:849 -> 0000328979 [system] ERROR: Failed to determine server address
20:07:28:849 -> 0000328979 [system] WARN: Internet test failed: -170 DNS
20:07:28:851 -> 0000328981 [system] WARN: Cloud handshake failed, code=-220
20:07:29:101 -> 0000329231 [system] INFO: Cloud: disconnecting
20:07:29:101 -> 0000329231 [system] INFO: Cloud: disconnected
20:07:30:993 -> 0000331122 [net.pppncp] TRACE: NCP event 3
20:07:30:993 -> 0000331122 [net.pppncp] TRACE: NCP power state changed: IF_POWER_STATE_DOWN
20:07:30:993 -> 0000331122 [system.nm] TRACE: Interface 4 power state changed: DOWN
20:07:30:997 -> 0000331123 [ncp.client] TRACE: Powered off
20:07:30:997 -> 0000331123 [ncp.client] TRACE: Deinit UART
20:07:30:997 -> 0000331124 [ncp.client] TRACE: NCP connection state changed: 0
20:07:30:997 -> 0000331124 [net.pppncp] TRACE: NCP event 2
20:07:30:997 -> 0000331125 [net.pppncp] TRACE: State changed event: 0
20:07:30:997 -> 0000331125 [ncp.client] TRACE: NCP state changed: 0
20:07:30:997 -> 0000331126 [net.pppncp] TRACE: NCP event 1
20:07:30:997 -> 0000331126 [ncp.client] TRACE: Powering on, ncpId: 0x42
20:07:30:997 -> 0000331127 [net.pppncp] TRACE: NCP event 3
20:07:30:997 -> 0000331127 [net.pppncp] TRACE: NCP power state changed: IF_POWER_STATE_POWERING_UP
20:07:30:998 -> 0000331128 [system.nm] TRACE: Interface 4 power state changed: POWERING_UP
20:07:30:998 -> 0000331126 [net.ppp.client] TRACE: PPP thread event LOWER_DOWN data=0
20:07:31:008 -> 0000331138 [net.pppncp] TRACE: NCP event 3
20:07:31:008 -> 0000331138 [net.pppncp] TRACE: NCP power state changed: IF_POWER_STATE_UP
20:07:31:008 -> 0000331138 [system.nm] TRACE: Interface 4 power state changed: UP
20:07:31:009 -> 0000331139 [ncp.client] TRACE: Powered on
20:07:32:210 -> 0000332339 [ncp.at] TRACE: > AT
20:07:33:209 -> 0000333339 [ncp.at] TRACE: > AT
20:07:34:209 -> 0000334339 [ncp.at] TRACE: > AT
20:07:35:209 -> 0000335339 [ncp.at] TRACE: > AT
20:07:35:211 -> 0000335341 [ncp.at] TRACE: < OK
20:07:35:212 -> 0000335342 [ncp.client] TRACE: NCP ready to accept AT commands
20:07:35:212 -> 0000335342 [ncp.at] TRACE: > AT
20:07:35:214 -> 0000335344 [ncp.at] TRACE: < OK
20:07:35:215 -> 0000335345 [ncp.at] TRACE: > ATI9
20:07:35:229 -> 0000335359 [ncp.at] TRACE: < 23.60,A01.01
20:07:35:230 -> 0000335360 [ncp.at] TRACE: < OK
20:07:35:230 -> 0000335360 [ncp.client] TRACE: App firmware: 101
20:07:35:231 -> 0000335361 [ncp.at] TRACE: > AT+UGPIOC?
20:07:35:235 -> 0000335365 [ncp.at] TRACE: < +UGPIOC:
20:07:35:236 -> 0000335366 [ncp.at] TRACE: < 16,255
20:07:35:237 -> 0000335367 [ncp.at] TRACE: < 23,255
20:07:35:237 -> 0000335367 [ncp.at] TRACE: < 24,4
20:07:35:238 -> 0000335368 [ncp.at] TRACE: < 25,5
20:07:35:238 -> 0000335368 [ncp.at] TRACE: < 34,12
20:07:35:239 -> 0000335369 [ncp.at] TRACE: < 35,12
20:07:35:240 -> 0000335370 [ncp.at] TRACE: < 36,12
20:07:35:240 -> 0000335370 [ncp.at] TRACE: < 37,12
20:07:35:241 -> 0000335371 [ncp.at] TRACE: < 42,7
20:07:35:242 -> 0000335372 [ncp.at] TRACE: < OK
20:07:35:242 -> 0000335372 [ncp.client] INFO: Using internal SIM card
20:07:35:242 -> 0000335372 [ncp.at] TRACE: > AT+CPIN?
20:07:35:246 -> 0000335376 [ncp.at] TRACE: < ERROR
20:07:36:246 -> 0000336376 [ncp.at] TRACE: > AT+CPIN?
20:07:36:251 -> 0000336381 [ncp.at] TRACE: < +CPIN: READY
20:07:36:252 -> 0000336382 [ncp.at] TRACE: < OK
20:07:36:252 -> 0000336382 [ncp.at] TRACE: > AT+CCID
20:07:36:431 -> 0000336561 [ncp.at] TRACE: < +CCID: 89883070000006616682
20:07:36:432 -> 0000336562 [ncp.at] TRACE: < OK
20:07:36:432 -> 0000336562 [ncp.at] TRACE: > AT+IFC?
20:07:36:436 -> 0000336566 [ncp.at] TRACE: < +IFC: 2,2
20:07:36:437 -> 0000336567 [ncp.at] TRACE: < OK
20:07:36:437 -> 0000336567 [ncp.at] TRACE: > AT+IFC=2,2
20:07:36:440 -> 0000336570 [ncp.at] TRACE: < OK
20:07:36:441 -> 0000336571 [ncp.at] TRACE: > AT
20:07:37:441 -> 0000337571 [ncp.at] TRACE: > AT
20:07:37:445 -> 0000337573 [ncp.at] TRACE: < OK
20:07:37:445 -> 0000337573 [ncp.at] TRACE: > AT+IPR=921600
20:07:37:447 -> 0000337577 [ncp.at] TRACE: < OK
20:07:37:449 -> 0000337579 [ncp.at] TRACE: > AT
20:07:37:450 -> 0000337580 [ncp.at] TRACE: <
20:07:37:450 -> 0000337580 [ncp.at] TRACE: < OK
If you need the full txt log to find more information or catch any trace I can share the full exported log taken from the 30min that the test lasted.
Best regards and thanks in advance.
Trying to keep this post alive since it is getting almost impossible to flash devices using OTA and they do not show any sign of irregular cellular signal and they have been reporting good in almost all different devices.
The SIM is definitely reconnecting very frequently, but it's not clear why to me.
I'm experiencing several devices with connectivity issues that are not able to receive Particle.functions calls and are degrading normal operation from client's point of view. I guess they are halting when they also try to call Particle.publish. Also, almost all of the devices are showing increased cellular data usage as of 6MB as of just 3 days from billing date (normally is just 3MB for the whole month)
Both of those behaviors would be expected if the device is losing its cellular connection. There may be a period of time before the device realizes it's no longer connected, and also a period of time for it to reconnect, that it would no longer respond to the cloud.
When the device reconnects, it will consume cellular data, so frequent reconnection will cause increased data operation.
I can see tha it is happening due to those reasons, but what I find intriguing is that I have not changed anything on FW or HW and most of my deployments are showing this decreased service across all of my console.
Is it possible that it is related to the SIM on the modules rather than something that I can take control due to FW? @rickkas7