Hey,
While using this library on a Muon, DeviceOS6.3.0, I am observing a certain timeout or something that impacts the cloud connection around the 70-80 seconds mark.
The cloud connection eventually reconnects, but this behaviour is intriguing.
I see it happening when the location fix takes longer than 70 seconds:
- the connection to the cloud is deemed down
- the connection is then restarted
Logs of the "issue"
0000073608 [loc] TRACE: glocCallback: (120000) +CME ERROR: 516
0000074652 [loc] TRACE: glocCallback: (120000) +CME ERROR: 516
0000075695 [loc] TRACE: glocCallback: (120000) +CME ERROR: 516
0000075842 [net.pppncp] ERROR: PPP error event data=9
0000075846 [net.pppncp] ERROR: PPP error event data=5
0000086454 [ncp.client] ERROR: Failed to enter data mode
0000086455 [net.ppp.client] ERROR: Failed to dial
0000087373 [mux] INFO: Stopping GSM07.10 muxer
0000087374 [mux] INFO: GSM07.10 muxer thread exiting
0000087376 [mux] INFO: GSM07.10 muxer stopped
0000087377 [net.pppncp] ERROR: Failed to initialize cellular NCP client: -210
0000090259 [comm.coap] ERROR: CoAP message timeout; ID: 10
0000090290 [comm.dtls] INFO: session cmd (CLS,DIS,MOV,LOD,SAV): 0
0000090324 [comm.protocol] ERROR: Event loop error 3
0000090351 [system] WARN: Communication loop error, closing cloud socket
0000090388 [system] INFO: Cloud: disconnecting
0000090412 [system] INFO: Cloud: disconnected
0000092888 [ncp.client] ERROR: Failed to enter data mode
0000092889 [net.ppp.client] ERROR: Failed to dial
0000092893 [net.pppncp] ERROR: PPP error event data=5
0000097102 [mux] INFO: Starting GSM07.10 muxer
0000097104 [mux] INFO: Opening mux channel 0
0000097104 [mux] INFO: GSM07.10 muxer thread started
0000097207 [mux] INFO: Opening mux channel 1
0000097287 [loc] TRACE: Sending asynchronous completion
Is this expected? Why would a location fix impact the cloud connection?
Thanks!
Full logs:
0000002312 [comm] INFO: channel inited
0000002429 [system.nm] INFO: State changed: DISABLED -> IFACE_DOWN
0000002448 [system.nm] INFO: State changed: IFACE_DOWN -> IFACE_REQUEST_UP
0000002469 [net.ifapi] INFO: Netif pp3 state UP
0000002473 [system.nm] INFO: State changed: IFACE_REQUEST_UP -> IFACE_UP
0000002578 [mux] INFO: Starting GSM07.10 muxer
0000002579 [mux] INFO: Opening mux channel 0
0000002579 [mux] INFO: GSM07.10 muxer thread started
0000002582 [mux] INFO: Opening mux channel 1
0000002636 [mux] INFO: Mux channel 1 already opened
0000002664 [mux] INFO: Opening mux channel 2
0000003840 [net.ifapi] INFO: Netif pp3 link UP, profile=NONE
0000003843 [system.nm] INFO: State changed: IFACE_UP -> IFACE_LINK_UP
0000003845 [hal] INFO: DNS server list changed
0000003847 [system.nm] INFO: State changed: IFACE_LINK_UP -> IP_CONFIGURED
0000003849 [hal] INFO: DNS server list changed
0000003883 [system] INFO: Cloud: connecting
0000003896 [system] INFO: Read Server Address = type:1,domain:$id.udp.particle.io
0000003917 [system] WARN: Failed to load session data from persistent storage
0000003938 [system] INFO: Discarding session data
0000005031 [system] INFO: Cloud socket=0, connecting to 34.231.252.59#5684 using if 4
0000005053 [system] INFO: Bound cloud socket to lwip if 4 ("pp3")
0000005071 [system] INFO: Cloud socket connected
0000005084 [system] INFO: Starting handshake: presense_announce=0
0000005101 [comm.protocol.handshake] INFO: Establish secure connection
0000005120 [comm.dtls] INFO: (CMPL,RENEG,NO_SESS,ERR) restoreStatus=2
0000006875 [comm.protocol.handshake] INFO: Sending HELLO message
0000007049 [comm.protocol.handshake] INFO: Handshake completed
0000007066 [comm.dtls] INFO: session cmd (CLS,DIS,MOV,LOD,SAV): 4
0000007083 [comm.dtls] INFO: session cmd (CLS,DIS,MOV,LOD,SAV): 3
0000007595 [comm] INFO: Sending TIME request
0000007608 [system] INFO: Send spark/device/last_reset event
0000007753 [comm.dtls] INFO: session cmd (CLS,DIS,MOV,LOD,SAV): 4
0000008282 [comm.dtls] INFO: session cmd (CLS,DIS,MOV,LOD,SAV): 3
0000008301 [comm.protocol] INFO: Received TIME response: 1743691983
0000008320 [system] INFO: All handshake messages have been processed
0000008438 [system] INFO: Cloud connected
0000008450 [system.ledger] INFO: Subscribing to ledger updates
0000008469 [comm] INFO: Forcing a cloud ping
0000009012 [system.ledger] INFO: Subscribed to ledger updates
0000009051 [comm.protocol] INFO: Received DESCRIBE request; flags: 0x04
0000009329 [loc] INFO: Beginning location library
0000009343 [loc] INFO: Detecting modem type
0000009361 [loc] TRACE: Modem ID is 19
0000009372 [loc] TRACE: BG95-M5 detected
0000009385 [loc] TRACE: Starting asynchronous aquisition
0000009386 [system] INFO: Sending application DESCRIBE
0000009401 [loc] TRACE: Started aquisition
0000009400 [app] INFO: GNSS acquisition started
0000009417 [system] INFO: Sending subscriptions
0000009442 [comm.protocol] INFO: Sending subscriptions
0000009483 [loc] TRACE: glocCallback: (120000) +CME ERROR: 516
0000010526 [loc] TRACE: glocCallback: (120000) +CME ERROR: 516
0000011555 [loc] TRACE: glocCallback: (120000) +CME ERROR: 516
0000012600 [loc] TRACE: glocCallback: (120000) +CME ERROR: 516
0000013644 [loc] TRACE: glocCallback: (120000) +CME ERROR: 516
0000014657 [loc] TRACE: glocCallback: (120000) +CME ERROR: 516
0000015701 [loc] TRACE: glocCallback: (120000) +CME ERROR: 516
0000016743 [loc] TRACE: glocCallback: (120000) +CME ERROR: 516
0000017761 [loc] TRACE: glocCallback: (120000) +CME ERROR: 516
0000018804 [loc] TRACE: glocCallback: (120000) +CME ERROR: 516
0000019846 [loc] TRACE: glocCallback: (120000) +CME ERROR: 516
0000020863 [loc] TRACE: glocCallback: (120000) +CME ERROR: 516
0000021908 [loc] TRACE: glocCallback: (120000) +CME ERROR: 516
0000022952 [loc] TRACE: glocCallback: (120000) +CME ERROR: 516
0000023967 [loc] TRACE: glocCallback: (120000) +CME ERROR: 516
0000025012 [loc] TRACE: glocCallback: (120000) +CME ERROR: 516
0000026056 [loc] TRACE: glocCallback: (120000) +CME ERROR: 516
0000027072 [loc] TRACE: glocCallback: (120000) +CME ERROR: 516
0000028117 [loc] TRACE: glocCallback: (120000) +CME ERROR: 516
0000029160 [loc] TRACE: glocCallback: (120000) +CME ERROR: 516
0000030174 [loc] TRACE: glocCallback: (120000) +CME ERROR: 516
0000031217 [loc] TRACE: glocCallback: (120000) +CME ERROR: 516
0000032260 [loc] TRACE: glocCallback: (120000) +CME ERROR: 516
0000033276 [loc] TRACE: glocCallback: (120000) +CME ERROR: 516
0000034319 [loc] TRACE: glocCallback: (120000) +CME ERROR: 516
0000035362 [loc] TRACE: glocCallback: (120000) +CME ERROR: 516
0000036379 [loc] TRACE: glocCallback: (120000) +CME ERROR: 516
0000037422 [loc] TRACE: glocCallback: (120000) +CME ERROR: 516
0000038466 [loc] TRACE: glocCallback: (120000) +CME ERROR: 516
0000039480 [loc] TRACE: glocCallback: (120000) +CME ERROR: 516
0000040522 [loc] TRACE: glocCallback: (120000) +CME ERROR: 516
0000041566 [loc] TRACE: glocCallback: (120000) +CME ERROR: 516
0000042583 [loc] TRACE: glocCallback: (120000) +CME ERROR: 516
0000043627 [loc] TRACE: glocCallback: (120000) +CME ERROR: 516
0000044670 [loc] TRACE: glocCallback: (120000) +CME ERROR: 516
0000045684 [loc] TRACE: glocCallback: (120000) +CME ERROR: 516
0000046727 [loc] TRACE: glocCallback: (120000) +CME ERROR: 516
0000047770 [loc] TRACE: glocCallback: (120000) +CME ERROR: 516
0000048787 [loc] TRACE: glocCallback: (120000) +CME ERROR: 516
0000049830 [loc] TRACE: glocCallback: (120000) +CME ERROR: 516
0000050873 [loc] TRACE: glocCallback: (120000) +CME ERROR: 516
0000051890 [loc] TRACE: glocCallback: (120000) +CME ERROR: 516
0000052935 [loc] TRACE: glocCallback: (120000) +CME ERROR: 516
0000053979 [loc] TRACE: glocCallback: (120000) +CME ERROR: 516
0000054994 [loc] TRACE: glocCallback: (120000) +CME ERROR: 516
0000056038 [loc] TRACE: glocCallback: (120000) +CME ERROR: 516
0000057083 [loc] TRACE: glocCallback: (120000) +CME ERROR: 516
0000058097 [loc] TRACE: glocCallback: (120000) +CME ERROR: 516
0000059141 [loc] TRACE: glocCallback: (120000) +CME ERROR: 516
0000060183 [loc] TRACE: glocCallback: (120000) +CME ERROR: 516
0000061198 [loc] TRACE: glocCallback: (120000) +CME ERROR: 516
0000062241 [loc] TRACE: glocCallback: (120000) +CME ERROR: 516
0000063283 [loc] TRACE: glocCallback: (120000) +CME ERROR: 516
0000063833 [net.ifapi] INFO: Netif pp3 link DOWN, profile=NONE
0000063834 [hal] INFO: DNS server list changed
0000063835 [system.nm] INFO: State changed: IP_CONFIGURED -> IFACE_LINK_UP
0000063837 [hal] INFO: DNS server list changed
0000063839 [system.nm] INFO: State changed: IFACE_LINK_UP -> IFACE_UP
0000064303 [loc] TRACE: glocCallback: (120000) +CME ERROR: 516
0000065346 [loc] TRACE: glocCallback: (120000) +CME ERROR: 516
0000066388 [loc] TRACE: glocCallback: (120000) +CME ERROR: 516
0000067404 [loc] TRACE: glocCallback: (120000) +CME ERROR: 516
0000068447 [loc] TRACE: glocCallback: (120000) +CME ERROR: 516
0000069491 [loc] TRACE: glocCallback: (120000) +CME ERROR: 516
0000070506 [loc] TRACE: glocCallback: (120000) +CME ERROR: 516
0000071548 [loc] TRACE: glocCallback: (120000) +CME ERROR: 516
0000072592 [loc] TRACE: glocCallback: (120000) +CME ERROR: 516
0000073608 [loc] TRACE: glocCallback: (120000) +CME ERROR: 516
0000074652 [loc] TRACE: glocCallback: (120000) +CME ERROR: 516
0000075695 [loc] TRACE: glocCallback: (120000) +CME ERROR: 516
0000075842 [net.pppncp] ERROR: PPP error event data=9
0000075846 [net.pppncp] ERROR: PPP error event data=5
0000086454 [ncp.client] ERROR: Failed to enter data mode
0000086455 [net.ppp.client] ERROR: Failed to dial
0000087373 [mux] INFO: Stopping GSM07.10 muxer
0000087374 [mux] INFO: GSM07.10 muxer thread exiting
0000087376 [mux] INFO: GSM07.10 muxer stopped
0000087377 [net.pppncp] ERROR: Failed to initialize cellular NCP client: -210
0000090259 [comm.coap] ERROR: CoAP message timeout; ID: 10
0000090290 [comm.dtls] INFO: session cmd (CLS,DIS,MOV,LOD,SAV): 0
0000090324 [comm.protocol] ERROR: Event loop error 3
0000090351 [system] WARN: Communication loop error, closing cloud socket
0000090388 [system] INFO: Cloud: disconnecting
0000090412 [system] INFO: Cloud: disconnected
0000092888 [ncp.client] ERROR: Failed to enter data mode
0000092889 [net.ppp.client] ERROR: Failed to dial
0000092893 [net.pppncp] ERROR: PPP error event data=5
0000097102 [mux] INFO: Starting GSM07.10 muxer
0000097104 [mux] INFO: Opening mux channel 0
0000097104 [mux] INFO: GSM07.10 muxer thread started
0000097207 [mux] INFO: Opening mux channel 1
0000097287 [loc] TRACE: Sending asynchronous completion
0000097316 [app] INFO: async callback returned 0
0000097341 [app] INFO: Position fixed!
0000097352 [app] INFO: Lat 0.00000, lon 0.00000
0000097364 [app] INFO: Alt 0.0 m, speed 0.0 m/s, heading 0.0 deg
0000097685 [mux] INFO: Opening mux channel 2
0000104845 [net.ifapi] INFO: Netif pp3 link UP, profile=NONE
0000104848 [system.nm] INFO: State changed: IFACE_UP -> IFACE_LINK_UP
0000104850 [hal] INFO: DNS server list changed
0000104851 [system.nm] INFO: State changed: IFACE_LINK_UP -> IP_CONFIGURED
0000104853 [hal] INFO: DNS server list changed
0000104938 [system] INFO: Cloud: connecting
0000104962 [system] INFO: Read Server Address = type:1,domain:$id.udp.particle.io
0000105004 [system] WARN: Failed to load session data from persistent storage
0000105044 [system] INFO: Discarding session data
0000105592 [system] INFO: Cloud socket=0, connecting to 34.231.252.59#5684 using if 4
0000105636 [system] INFO: Bound cloud socket to lwip if 4 ("pp3")
0000105670 [system] INFO: Cloud socket connected
0000105695 [system] INFO: Starting handshake: presense_announce=0
0000105728 [comm.protocol.handshake] INFO: Establish secure connection
0000105766 [comm.dtls] INFO: (CMPL,RENEG,NO_SESS,ERR) restoreStatus=2
0000109036 [comm.protocol.handshake] INFO: Sending HELLO message
0000109198 [comm.protocol.handshake] INFO: Handshake completed
0000109231 [comm.dtls] INFO: session cmd (CLS,DIS,MOV,LOD,SAV): 4
0000109263 [comm.dtls] INFO: session cmd (CLS,DIS,MOV,LOD,SAV): 3
0000110297 [comm] INFO: Sending TIME request
0000110326 [system] INFO: Sending application DESCRIBE
0000110356 [system] INFO: Sending subscriptions
0000110380 [comm.protocol] INFO: Sending subscriptions
0000110480 [comm.protocol] INFO: Received TIME response: 1743692086
0000110515 [comm.dtls] INFO: session cmd (CLS,DIS,MOV,LOD,SAV): 4
0000110545 [comm.dtls] INFO: session cmd (CLS,DIS,MOV,LOD,SAV): 3
0000110574 [comm.dtls] INFO: session cmd (CLS,DIS,MOV,LOD,SAV): 4
0000111632 [comm.dtls] INFO: session cmd (CLS,DIS,MOV,LOD,SAV): 3
0000111660 [system] INFO: All handshake messages have been processed
0000111689 [comm.dtls] INFO: session cmd (CLS,DIS,MOV,LOD,SAV): 4
0000111714 [comm.dtls] INFO: session cmd (CLS,DIS,MOV,LOD,SAV): 3
0000111740 [comm.protocol] INFO: Received DESCRIBE request; flags: 0x04
0000111797 [system] INFO: Cloud connected
0000111819 [system.ledger] INFO: Subscribing to ledger updates
0000111847 [comm] INFO: Forcing a cloud ping
0000112134 [system.ledger] INFO: Subscribed to ledger updates
0000127381 [app] INFO: retrying acquisition
0000127392 [loc] TRACE: Starting asynchronous aquisition
0000127407 [app] INFO: GNSS acquisition started
0000127408 [loc] TRACE: Started aquisition
0000127466 [loc] TRACE: glocCallback: (120000) +CME ERROR: 516
0000128511 [loc] TRACE: glocCallback: (120000) +CME ERROR: 516
0000129544 [loc] TRACE: glocCallback: (120000) +CME ERROR: 516
0000130586 [loc] TRACE: glocCallback: (120000) +CME ERROR: 516
0000131628 [loc] TRACE: glocCallback: (120000) +CME ERROR: 516
0000132646 [loc] TRACE: glocCallback: (120000) +CME ERROR: 516
0000133689 [loc] TRACE: glocCallback: (120000) +CME ERROR: 516
0000134733 [loc] TRACE: glocCallback: (120000) +CME ERROR: 516