Boron LTE regular cellular disconnects

Connectivity Cellular
1

Hi,

We’re having connectivity problems with the Boron LTE.

Problem:
-We have sporadic network disconnects. There is no consistent time interval between disconnects. The number of disconnects per day varies between a few and up to 300.

  • The problem persists when: we move the device to a location with a better reception; when we move the device location to connect to a different tower; when we test our firmware on other Boron LTE devices.

Hardware & Software description:
-Boron LTE OS 1.4.2 (not sure what the debug build uses but the same symptoms occur)
-3rd party sim, Telstra M2MOne Australia New South Wales

  • keepAlive = 45 seconds
  • Signal strength & quality are normally around 60%

Tests we’ve run to confirm the problem:
-Various Boron LTE devices
-Various versions of our firmware (taking parts out to see if the situation improves)
-Various different antennas
-Various different locations (connecting to different cellular towers)

Debug build logs:
When looking at the debug build logs it seems that the trigger for the disconnection is
“0324985398 [ncp.at] TRACE: < +CEREG: 0”.

After this the device goes through a disconnect routine and then attempts to reconnect to the cloud. This ususally takes 4-5 minutes.

Sometimes the reconnection times out initiating a hard reset of the modem.

Questions:

  1. Is our interpretation of the debug log correct? What else is happening in this log that may help with debugging?
  2. How should we go about fixing this connectivity problem?
  3. If the fault lies with the network operator, what conversation should we have with them / what questions should be asked?

Debug build log:

0324983876 [app] INFO: Tue Jan 28 07:27:56 2020
0324985241 [comm.coap] TRACE: sending message id=4c0f
0324985243 [hal] TRACE: Outputing 66 bytes
0324985244 [lwip] TRACE: pppos_netif_output[3]: proto=0x21, len = 61
0324985303 [lwip] TRACE: pppos_input[3]: got 25 bytes
0324985398 [ncp.at] TRACE: < +CEREG: 0
0324985399 [hal] TRACE: NCP connection state changed: 1
0324985400 [net.pppncp] TRACE: NCP event 2
0324985400 [net.pppncp] TRACE: State changed event: 1
0324985402 [hal] TRACE: PPP thread event LOWER_DOWN
0324985403 [hal] TRACE: State CONNECTED -> DISCONNECT
0324985404 [hal] TRACE: State DISCONNECT -> DISCONNECTING
0324985404 [lwip] TRACE: ppp_close[3]: carrier lost -> lcp_lowerdown
0324985405 [net.ppp.ipcp] TRACE: IPCP: lowerDown
0324985406 [net.ppp.ipcp] TRACE: IPCP: down
0324985407 [hal] TRACE: PPP netif -> 4
0324985408 [net.ifapi] INFO: Netif pp3 link DOWN
0324985409 [system.nm] TRACE: br_enabled=0
0324985410 [system.nm] INFO: State changed: IP_CONFIGURED -> IFACE_UP
0324985411 [lwip] TRACE: sifdown[3]: err_code=5
0324985412 [hal] TRACE: PPP netif -> b0
0324985412 [net.ifapi] TRACE: Netif pp3 ipv4 configuration changed
0324985413 [lwip] TRACE: ppp phase changed[3]: phase=9
0324985414 [hal] TRACE: PPP phase -> 9
0324985414 [net.ppp.ipcp] TRACE: ipcp:close
0324985415 [lwip] TRACE: ppp phase changed[3]: phase=6
0324985416 [hal] TRACE: PPP phase -> 6
0324985417 [lwip] TRACE: pppos_send_config[3]: out_accm=FF FF FF FF
0324985419 [lwip] TRACE: ppp_send_config[3]
0324985420 [lwip] TRACE: pppos_recv_config[3]: in_accm=0 0 0 0
0324985422 [lwip] TRACE: ppp_recv_config[3]
0324985423 [lwip] TRACE: ppp phase changed[3]: phase=12
0324985424 [hal] TRACE: PPP phase -> 12
0324985425 [lwip] TRACE: Connection terminated.
0324985426 [lwip] TRACE: ppp_link_terminated[3]
0324985427 [lwip] TRACE: ppp_link_end[3]
0324985428 [lwip] TRACE: ppp phase changed[3]: phase=0
0324985429 [hal] TRACE: PPP phase -> 0
0324985431 [hal] TRACE: PPP status -> 5
0324985432 [lwip] TRACE: ppp_link_terminated[3]: finished.
0324985433 [hal] TRACE: PPP thread event DOWN
0324985434 [hal] TRACE: State DISCONNECTING -> DISCONNECTED
0324985435 [hal] TRACE: State DISCONNECTED -> READY
0324985445 [system.nm] TRACE: br_enabled=0, br_permitted=0
0324989401 [ncp.at] TRACE: < +CEREG: 2
mbedtls/library/ssl_tls.c:3472: mbedtls_ssl_flush_output() returned -1 (-0x0001)
mbedtls/library/ssl_tls.c:8744: mbedtls_ssl_write_record() returned -1 (-0x0001)
0324989450 [comm.dtls] WARN: mbedtls_ssl_write returned ffffffff
0324989553 [comm.protocol] ERROR: Event loop error 3
0324989554 [system] WARN: Communication loop error, closing cloud socket
0324989556 [system] INFO: Cloud: disconnecting
0324989558 [system] INFO: Cloud: disconnected
0325000502 [ncp.at] TRACE: > AT+CEREG?
0325000554 [ncp.at] TRACE: < +CEREG: 2,2
0325000554 [ncp.at] TRACE: < OK
0325015655 [ncp.at] TRACE: > AT+CEREG?
0325015704 [ncp.at] TRACE: < +CEREG: 2,2
0325015704 [ncp.at] TRACE: < OK
0325030805 [ncp.at] TRACE: > AT+CEREG?
0325030854 [ncp.at] TRACE: < +CEREG: 2,2
0325030854 [ncp.at] TRACE: < OK
0325044876 [app] INFO: Tue Jan 28 07:28:57 2020
0325045955 [ncp.at] TRACE: > AT+CEREG?
0325046004 [ncp.at] TRACE: < +CEREG: 2,2
0325046004 [ncp.at] TRACE: < OK
0325061105 [ncp.at] TRACE: > AT+CEREG?
0325061154 [ncp.at] TRACE: < +CEREG: 2,2
0325061154 [ncp.at] TRACE: < OK
0325061254 [ncp.at] TRACE: < +CEREG: 0
0325076255 [ncp.at] TRACE: > AT+CEREG?
0325076304 [ncp.at] TRACE: < +CEREG: 2,0
0325076304 [ncp.at] TRACE: < OK
0325091405 [ncp.at] TRACE: > AT+CEREG?
0325091454 [ncp.at] TRACE: < +CEREG: 2,0
0325091454 [ncp.at] TRACE: < OK
0325105876 [app] INFO: Tue Jan 28 07:29:58 2020
0325106555 [ncp.at] TRACE: > AT+CEREG?
0325106604 [ncp.at] TRACE: < +CEREG: 2,0
0325106604 [ncp.at] TRACE: < OK
0325121615 [ncp.at] TRACE: > AT+CEREG?
0325121664 [ncp.at] TRACE: < +CEREG: 2,0
0325121665 [ncp.at] TRACE: < OK
0325136665 [ncp.at] TRACE: > AT+CEREG?
0325136714 [ncp.at] TRACE: < +CEREG: 2,0
0325136714 [ncp.at] TRACE: < OK
0325151715 [ncp.at] TRACE: > AT+CEREG?
0325151764 [ncp.at] TRACE: < +CEREG: 2,0
0325151765 [ncp.at] TRACE: < OK
0325166765 [ncp.at] TRACE: > AT+CEREG?
0325166814 [ncp.at] TRACE: < +CEREG: 2,0
0325166814 [ncp.at] TRACE: < OK
0325166887 [app] INFO: Tue Jan 28 07:30:59 2020
0325181815 [ncp.at] TRACE: > AT+CEREG?
0325181864 [ncp.at] TRACE: < +CEREG: 2,0
0325181864 [ncp.at] TRACE: < OK
0325196865 [ncp.at] TRACE: > AT+CEREG?
0325196914 [ncp.at] TRACE: < +CEREG: 2,0
0325196914 [ncp.at] TRACE: < OK
0325211915 [ncp.at] TRACE: > AT+CEREG?
0325211964 [ncp.at] TRACE: < +CEREG: 2,0
0325211965 [ncp.at] TRACE: < OK
0325226965 [ncp.at] TRACE: > AT+CEREG?
0325227014 [ncp.at] TRACE: < +CEREG: 2,0
0325227015 [ncp.at] TRACE: < OK
0325227887 [app] INFO: Tue Jan 28 07:32:00 2020
0325242015 [ncp.at] TRACE: > AT+CEREG?
0325242064 [ncp.at] TRACE: < +CEREG: 2,0
0325242064 [ncp.at] TRACE: < OK
0325257065 [ncp.at] TRACE: > AT+CEREG?
0325257114 [ncp.at] TRACE: < +CEREG: 2,0
0325257115 [ncp.at] TRACE: < OK
0325272115 [ncp.at] TRACE: > AT+CEREG?
0325272164 [ncp.at] TRACE: < +CEREG: 2,0
0325272165 [ncp.at] TRACE: < OK
0325287165 [ncp.at] TRACE: > AT+CEREG?
0325287214 [ncp.at] TRACE: < +CEREG: 2,0
0325287215 [ncp.at] TRACE: < OK
0325287216 [hal] WARN: Resetting the modem due to the network registration timeout
0325287217 [gsm0710muxer] INFO: Stopping GSM07.10 muxer
0325287219 [gsm0710muxer] INFO: Gracefully stopping GSM07.10 muxer
0325287220 [gsm0710muxer] INFO: Closing all muxed channels
0325287221 [gsm0710muxer] INFO: Closing mux channel 1
0325287222 [gsm0710muxer] INFO: Closing mux channel 2
0325287223 [gsm0710muxer] INFO: Muxed channel 3 already closed
0325287224 [gsm0710muxer] INFO: Muxed channel 4 already closed
0325287325 [gsm0710muxer] INFO: Sending CLD (multiplexer close down)
0325287375 [gsm0710muxer] INFO: Received response to CLD or timed out, exiting multiplexed mode
0325287375 [gsm0710muxer] INFO: GSM07.10 muxer thread exiting
0325287376 [gsm0710muxer] INFO: GSM07.10 muxer stopped
0325287377 [hal] TRACE: Hard resetting the modem
0325288887 [app] INFO: Tue Jan 28 07:33:01 2020
0325298378 [hal] TRACE: Powering on the modem after the hard reset
0325298378 [hal] TRACE: Powering modem on
0325298529 [hal] TRACE: Modem powered on
0325298529 [hal] TRACE: Setting UART voltage translator state 0
0325298530 [hal] TRACE: Powering modem off
0325298530 [hal] TRACE: Setting UART voltage translator state 0
0325310131 [hal] ERROR: Failed to power off modem
0325310131 [hal] TRACE: NCP state changed: 0
0325310132 [net.pppncp] TRACE: NCP event 1
0325310232 [hal] TRACE: Modem already on
0325310233 [hal] TRACE: Setting UART voltage translator state 1
0325311233 [ncp.at] TRACE: > AT
0325311239 [ncp.at] TRACE: < OK
0325312239 [hal] TRACE: NCP ready to accept AT commands
0325312239 [ncp.at] TRACE: > AT+UGPIOC?
0325312247 [ncp.at] TRACE: < +UGPIOC:
0325312248 [ncp.at] TRACE: < 7,255
0325312249 [ncp.at] TRACE: < 16,255
0325312249 [ncp.at] TRACE: < 19,255
0325312250 [ncp.at] TRACE: < 23,0
0325312251 [ncp.at] TRACE: < 24,255
0325312251 [ncp.at] TRACE: < 25,255
0325312252 [ncp.at] TRACE: < 42,255
0325312253 [ncp.at] TRACE: < OK
0325312253 [ncp.at] TRACE: > AT+UGPIOR=23
0325312260 [ncp.at] TRACE: < +UGPIOR: 23,0
0325312261 [ncp.at] TRACE: < OK
0325312261 [hal] INFO: Using external Nano SIM card
0325312262 [ncp.at] TRACE: > AT+CPIN?
0325312267 [ncp.at] TRACE: < +CPIN: READY
0325312268 [ncp.at] TRACE: < OK
0325312269 [ncp.at] TRACE: > AT+CCID
0325312276 [ncp.at] TRACE: < +CCID: 89610185002618873130
0325312277 [ncp.at] TRACE: < OK
0325312277 [ncp.at] TRACE: > AT+COPS=2,2
0325312290 [ncp.at] TRACE: < OK
0325312291 [ncp.at] TRACE: > AT+COPS=3,2
0325312295 [ncp.at] TRACE: < OK
0325312296 [ncp.at] TRACE: > ATI9
0325312301 [ncp.at] TRACE: < L0.0.00.00.05.08,A.02.04
0325312302 [ncp.at] TRACE: < OK
0325312302 [ncp.at] TRACE: > AT+UMNOPROF?
0325312308 [ncp.at] TRACE: < +UMNOPROF: 4
0325312309 [ncp.at] TRACE: < OK
0325312309 [ncp.at] TRACE: > AT+URAT?
0325312317 [ncp.at] TRACE: < +CME ERROR: Operation not supported
0325312317 [ncp.at] TRACE: > AT+CEDRXS?
0325312322 [ncp.at] TRACE: < +CEDRXS:
0325312323 [ncp.at] TRACE: < OK
0325312324 [ncp.at] TRACE: > AT+CPSMS=0
0325312329 [ncp.at] TRACE: < OK
0325312329 [ncp.at] TRACE: > AT+CMUX=0,0,,1509,,,,,
0325312336 [ncp.at] TRACE: < OK
0325312337 [gsm0710muxer] INFO: Starting GSM07.10 muxer
0325312338 [gsm0710muxer] INFO: Openning mux channel 0
0325312339 [gsm0710muxer] INFO: GSM07.10 muxer thread started
0325312390 [gsm0710muxer] INFO: Resuming channel 0
0325312391 [gsm0710muxer] INFO: Openning mux channel 1
0325312491 [gsm0710muxer] INFO: Resuming channel 1
0325312491 [gsm0710muxer] INFO: Resuming channel 1
0325312493 [ncp.at] TRACE: > AT
0325312543 [ncp.at] TRACE: < OK
0325312543 [hal] TRACE: NCP state changed: 1
0325312544 [net.pppncp] TRACE: NCP event 1
0325312545 [hal] TRACE: Muxer AT channel live
0325312546 [hal] TRACE: PPP thread event LOWER_DOWN
0325312546 [hal] TRACE: PPP thread event ADM_DOWN
0325312548 [hal] TRACE: State READY -> NONE
0325312548 [hal] TRACE: PPP thread event ADM_UP
0325312550 [hal] TRACE: State NONE -> READY
0325312551 [ncp.at] TRACE: > AT+CGDCONT=1,"IP","ipx1.m2mone"
0325312593 [ncp.at] TRACE: < OK
0325312594 [ncp.at] TRACE: > AT+CEREG=2
0325312643 [ncp.at] TRACE: < OK
0325312643 [hal] TRACE: NCP connection state changed: 1
0325312644 [net.pppncp] TRACE: NCP event 2
0325312644 [net.pppncp] TRACE: State changed event: 1
0325312645 [ncp.at] TRACE: > AT+COPS=0,2
0325312646 [hal] TRACE: PPP thread event LOWER_DOWN
0325312693 [ncp.at] TRACE: < OK
0325312694 [ncp.at] TRACE: > AT+CEREG?
0325312694 [ncp.at] TRACE: < +CEREG: 2
0325312743 [ncp.at] TRACE: < +CEREG: 2,2
0325312743 [ncp.at] TRACE: < OK
0325327744 [ncp.at] TRACE: > AT+CEREG?
0325327793 [ncp.at] TRACE: < +CEREG: 2,1,"2058","805CF0E",7
0325327794 [hal] TRACE: NCP connection state changed: 2
0325327795 [gsm0710muxer] INFO: Openning mux channel 2
0325327893 [gsm0710muxer] INFO: Resuming channel 2
0325327894 [net.pppncp] TRACE: NCP event 100
0325327894 [net.pppncp] TRACE: New auth info
0325327895 [net.pppncp] TRACE: NCP event 2
0325327896 [net.pppncp] TRACE: State changed event: 2
0325327898 [ncp.at] TRACE: < OK
0325327899 [hal] TRACE: PPP thread event LOWER_UP
0325327899 [hal] TRACE: State READY -> CONNECT
0325327900 [net.ppp.ipcp] TRACE: IPCP: init
0325327901 [net.ppp.ipcp] TRACE: IPCP: disable 1 0 0
0325327902 [net.ppp.ipcp] TRACE: IPCP: enable 0 0 0
0325327902 [hal] TRACE: Outputing 13 bytes
0325327903 [hal] TRACE: State CONNECT -> CONNECTING
0325327904 [lwip] TRACE: ppp_connect[3]: holdoff=1
0325327905 [lwip] TRACE: ppp phase changed[3]: phase=2
0325327906 [hal] TRACE: PPP phase -> 2
0325327945 [lwip] TRACE: pppos_input[3]: got 12 bytes
0325327945 [lwip] TRACE: pppos_input[3]: got 21 bytes
0325327999 [ncp.at] TRACE: < +CEREG: 1,"2058","805CF0E",7
0325328906 [lwip] TRACE: ppp phase changed[3]: phase=3
0325328906 [hal] TRACE: PPP phase -> 3
0325328907 [lwip] TRACE: pppos_connect: unit 3: connecting
0325328908 [lwip] TRACE: ppp_start[3]
0325328909 [lwip] TRACE: ppp phase changed[3]: phase=6
0325328909 [hal] TRACE: PPP phase -> 6
0325328910 [lwip] TRACE: pppos_send_config[3]: out_accm=FF FF FF FF
0325328911 [lwip] TRACE: ppp_send_config[3]
0325328912 [lwip] TRACE: pppos_recv_config[3]: in_accm=FF FF FF FF
0325328912 [lwip] TRACE: ppp_recv_config[3]
0325328913 [lwip] TRACE: ppp: auth protocols:
0325328914 [lwip] TRACE:  PAP=1
0325328915 [lwip] TRACE:  CHAP=1 CHAP_MD5=1
0325328916 [lwip] TRACE: 
0325328916 [hal] TRACE: Outputing 45 bytes
0325328917 [lwip] TRACE: pppos_write[3]: len=24
0325328918 [lwip] TRACE: ppp_start[3]: finished
0325329096 [lwip] TRACE: pppos_input[3]: got 53 bytes
0325329096 [hal] TRACE: Outputing 53 bytes
0325329097 [lwip] TRACE: pppos_write[3]: len=29
0325329098 [lwip] TRACE: pppos_input[3]: got 45 bytes
0325329099 [lwip] TRACE: netif_set_mtu[3]: mtu=1500
0325329099 [lwip] TRACE: pppos_send_config[3]: out_accm=0 0 0 0
0325329100 [lwip] TRACE: ppp_send_config[3]
0325329101 [lwip] TRACE: pppos_recv_config[3]: in_accm=0 0 0 0
0325329101 [lwip] TRACE: ppp_recv_config[3]
0325329102 [hal] TRACE: Outputing 15 bytes
0325329103 [lwip] TRACE: pppos_write[3]: len=12
0325329104 [net.ppp.ipcp] TRACE: IPCP: lowerUp
0325329104 [lwip] TRACE: ppp phase changed[3]: phase=7
0325329105 [hal] TRACE: PPP phase -> 7
0325329406 [lwip] TRACE: pppos_input[3]: got 21 bytes
0325329407 [lwip] TRACE: pppos_input[3]: got 41 bytes
0325329407 [lwip] TRACE: No CHAP secret found for authenticating us to UMTS_CHAP_SRVR
0325329408 [hal] TRACE: Outputing 29 bytes
0325329409 [lwip] TRACE: pppos_write[3]: len=25
0325329410 [lwip] TRACE: pppos_input[3]: got 26 bytes
0325329711 [lwip] TRACE: pppos_input[3]: got 10 bytes
0325329711 [lwip] TRACE: CHAP authentication succeeded
0325329712 [lwip] TRACE: CHAP authentication succeeded
0325329713 [lwip] TRACE: ppp phase changed[3]: phase=9
0325329713 [hal] TRACE: PPP phase -> 9
0325329713 [net.ppp.ipcp] TRACE: IPCP: open
0325329714 [net.ppp.ipcp] TRACE: IPCP: reset ci
0325329715 [net.ppp.ipcp] TRACE: IPCP: get ci length
0325329715 [net.ppp.ipcp] TRACE: IPCP: Our CI length: 24
0325329716 [hal] TRACE: Outputing 36 bytes
0325329717 [lwip] TRACE: pppos_write[3]: len=32
0325329718 [hal] TRACE: Outputing 21 bytes
0325329719 [lwip] TRACE: pppos_write[3]: len=18
0325330070 [lwip] TRACE: pppos_input[3]: got 10 bytes
0325330070 [net.ppp.ipcp] TRACE: IPCP: input 4
0325330071 [net.ppp.ipcp] TRACE: IPCP: request ci
0325330072 [hal] TRACE: Outputing 12 bytes
0325330073 [lwip] TRACE: pppos_write[3]: len=8
0325330074 [lwip] TRACE: pppos_input[3]: got 16 bytes
0325330075 [net.ppp.ipcp] TRACE: IPCP: input 10
0325330076 [net.ppp.ipcp] TRACE: IPCP: reject ci
0325330077 [net.ppp.ipcp] TRACE: IPCP: get ci length
0325330078 [net.ppp.ipcp] TRACE: IPCP: Our CI length: 18
0325330079 [hal] TRACE: Outputing 29 bytes
0325330080 [lwip] TRACE: pppos_write[3]: len=26
0325330381 [lwip] TRACE: pppos_input[3]: got 28 bytes
0325330381 [net.ppp.ipcp] TRACE: IPCP: input 22
0325330382 [net.ppp.ipcp] TRACE: IPCP: nak ci
0325330382 [net.ppp.ipcp] TRACE: IPCP: get ci length
0325330384 [net.ppp.ipcp] TRACE: IPCP: Our CI length: 18
0325330385 [hal] TRACE: Outputing 30 bytes
0325330386 [lwip] TRACE: pppos_write[3]: len=26
0325330687 [lwip] TRACE: pppos_input[3]: got 28 bytes
0325330687 [net.ppp.ipcp] TRACE: IPCP: input 22
0325330688 [net.ppp.ipcp] TRACE: IPCP: ack ci
0325330688 [net.ppp.ipcp] TRACE: IPCP: up
0325330689 [hal] TRACE: PPP netif -> 4
0325330689 [net.ifapi] INFO: Netif pp3 link UP
0325330690 [system.nm] INFO: State changed: IFACE_UP -> IFACE_LINK_UP
0325330691 [lwip] TRACE: sifup[3]: err_code=0
0325330691 [hal] TRACE: PPP status -> 0
0325330692 [hal] TRACE: PPP netif -> b0
0325330693 [hal] TRACE: PPP thread event UP
0325330693 [hal] TRACE: State CONNECTING -> CONNECTED
0325330694 [net.pppncp] TRACE: Negotiated MTU: 1500
0325330695 [net.pppncp] INFO: Updating MTU to: 1000
0325330694 [net.ifapi] TRACE: Netif pp3 ipv4 configuration changed
0325330697 [system.nm] TRACE: br_enabled=1
0325330697 [system.nm] INFO: State changed: IFACE_LINK_UP -> IP_CONFIGURED
0325330698 [hal] INFO: DNS server list changed
0325330699 [hal] INFO: DNS server list changed
0325330700 [lwip] TRACE: ppp phase changed[3]: phase=10
0325330701 [hal] TRACE: PPP phase -> 10
0325330740 [system.nm] TRACE: br_enabled=1, br_permitted=0
0325330740 [system.nm] INFO: Checking gateway status with the device cloud
0325330744 [system] INFO: Cloud: connecting
0325330744 [system] TRACE: Close Attempt
0325330746 [system] TRACE: sock_close()=success
0325330750 [system] INFO: Read Server Address = type:1,domain:$id.udp-mesh.particle.io
0325330752 [system] ERROR: Failed to load session data from persistent storage
0325330755 [system] INFO: Discarding session data
0325330758 [system] TRACE: Resolving e00fce680522926d12384a22.udp-mesh.particle.io#5684
0325330760 [hal] TRACE: Outputing 96 bytes
0325330762 [lwip] TRACE: pppos_netif_output[3]: proto=0x21, len = 91
0325331252 [lwip] TRACE: pppos_input[3]: got 241 bytes
0325331253 [lwip] TRACE: ppp_input[3]: ip in pbuf len=236
0325331254 [hal] TRACE: Outputing 96 bytes
0325331256 [lwip] TRACE: pppos_netif_output[3]: proto=0x21, len = 91
0325331604 [lwip] TRACE: pppos_input[3]: got 520 bytes
0325331605 [lwip] TRACE: ppp_input[3]: ip in pbuf len=515
0325331606 [system] TRACE: Address type: 3
0325331608 [system] TRACE: Cloud socket=0, family=2, type=2, protocol=17
0325331610 [system] INFO: Cloud socket=0, connecting to 3.229.54.1#5684
0325331610 [system] TRACE: Cloud socket=0, connected to 3.229.54.1#5684
0325331614 [system] TRACE: Updating cloud keepalive for AF_INET: 1380000 -> 1380000
0325331614 [system] TRACE: Applying new keepalive interval now
0325331616 [system] INFO: Cloud socket connected
0325331618 [system] INFO: Starting handshake: presense_announce=0
0325331620 [comm.protocol.handshake] INFO: Establish secure connection
0325332150 [ncp.at] TRACE: > AT+CCID
0325332206 [ncp.at] TRACE: < +CCID: 89610185002618873130
0325332207 [ncp.at] TRACE: < OK
0325332208 [ncp.at] TRACE: > AT+CGSN
0325332256 [ncp.at] TRACE: < 359215101723758
0325332256 [ncp.at] TRACE: < OK
0325332261 [comm.dtls] TRACE: restore size mismatch 1: 0/220
0325332261 [comm.dtls] INFO: (CMPL,RENEG,NO_SESS,ERR) restoreStatus=2
0325332269 [hal] TRACE: Outputing 144 bytes
0325332271 [lwip] TRACE: pppos_netif_output[3]: proto=0x21, len = 139
0325332806 [lwip] TRACE: pppos_input[3]: got 94 bytes
0325332807 [lwip] TRACE: ppp_input[3]: ip in pbuf len=88
0325332808 [hal] TRACE: Outputing 177 bytes
0325332810 [lwip] TRACE: pppos_netif_output[3]: proto=0x21, len = 171
0325333357 [lwip] TRACE: pppos_input[3]: got 153 bytes
0325333358 [lwip] TRACE: ppp_input[3]: ip in pbuf len=146
0325333409 [lwip] TRACE: pppos_input[3]: got 203 bytes
0325333410 [lwip] TRACE: ppp_input[3]: ip in pbuf len=197
0325333411 [lwip] TRACE: pppos_input[3]: got 66 bytes
0325333412 [lwip] TRACE: ppp_input[3]: ip in pbuf len=61
0325333413 [lwip] TRACE: pppos_input[3]: got 58 bytes
0325333415 [lwip] TRACE: ppp_input[3]: ip in pbuf len=53
0325333798 [hal] TRACE: Outputing 416 bytes
0325333800 [lwip] TRACE: pppos_netif_output[3]: proto=0x21, len = 405
0325334104 [hal] TRACE: Outputing 16 bytes
0325334104 [lwip] TRACE: pppos_write[3]: len=12
0325334267 [lwip] TRACE: pppos_input[3]: got 26 bytes
0325334268 [lwip] TRACE: pppos_input[3]: got 47 bytes
0325334269 [lwip] TRACE: ppp_input[3]: ip in pbuf len=42
0325334271 [lwip] TRACE: pppos_input[3]: got 86 bytes
0325334271 [lwip] TRACE: ppp_input[3]: ip in pbuf len=81
0325334276 [comm.protocol.handshake] INFO: Sending HELLO message
0325334278 [comm] TRACE: sending message id=4c10 synchronously
0325334280 [comm.coap] TRACE: sending message id=4c10
0325334282 [hal] TRACE: Outputing 91 bytes
0325334284 [lwip] TRACE: pppos_netif_output[3]: proto=0x21, len = 86
0325334772 [lwip] TRACE: pppos_input[3]: got 67 bytes
0325334773 [lwip] TRACE: ppp_input[3]: ip in pbuf len=61
0325334774 [lwip] TRACE: pppos_input[3]: got 71 bytes
0325334776 [lwip] TRACE: ppp_input[3]: ip in pbuf len=66
0325334778 [comm.coap] TRACE: recieved ACK for message id=4c10
0325334780 [comm.protocol.handshake] INFO: Handshake completed
0325334784 [system] INFO: Send spark/hardware/max_binary event
0325334786 [comm.coap] TRACE: sending message id=4c11
0325334789 [hal] TRACE: Outputing 104 bytes
0325334790 [lwip] TRACE: pppos_netif_output[3]: proto=0x21, len = 98
0325334792 [comm.coap] TRACE: sending message id=4c12
0325334794 [hal] TRACE: Outputing 105 bytes
0325334796 [lwip] TRACE: pppos_netif_output[3]: proto=0x21, len = 101
0325334798 [comm.coap] TRACE: sending message id=4c13
0325334802 [hal] TRACE: Outputing 105 bytes
0325334804 [lwip] TRACE: pppos_netif_output[3]: proto=0x21, len = 101
0325334806 [system] INFO: Send subscriptions
0325334808 [comm.coap] TRACE: sending message id=4c14
0325334810 [hal] TRACE: Outputing 75 bytes
0325334812 [lwip] TRACE: pppos_netif_output[3]: proto=0x21, len = 71
0325334814 [comm.coap] TRACE: sending message id=4c15
0325334816 [hal] TRACE: Outputing 78 bytes
0325334818 [lwip] TRACE: pppos_netif_output[3]: proto=0x21, len = 74
0325334822 [comm.dtls] INFO: session cmd (CLS,DIS,MOV,LOD,SAV): 4
0325334824 [comm.dtls] INFO: session cmd (CLS,DIS,MOV,LOD,SAV): 3
0325334826 [comm] INFO: Sending TIME request
0325334828 [comm.coap] TRACE: sending message id=4c16
0325334830 [hal] TRACE: Outputing 68 bytes
0325334832 [lwip] TRACE: pppos_netif_output[3]: proto=0x21, len = 64
0325334839 [ncp.at] TRACE: > AT+COPS=3,2
0325334876 [ncp.at] TRACE: < OK
0325334877 [ncp.at] TRACE: > AT+COPS?
0325334926 [ncp.at] TRACE: < +COPS: 0,2,"50501",7
0325334927 [ncp.at] TRACE: < OK
0325334928 [ncp.at] TRACE: > AT+CESQ
0325334976 [ncp.at] TRACE: < +CESQ: 99,99,255,255,24,56
0325334977 [ncp.at] TRACE: < OK
0325334981 [ncp.at] TRACE: > AT+COPS=3,2
0325335026 [ncp.at] TRACE: < OK
0325335028 [ncp.at] TRACE: > AT+COPS?
0325335076 [ncp.at] TRACE: < +COPS: 0,2,"50501",7
0325335078 [ncp.at] TRACE: < OK
0325335078 [comm.protocol] INFO: Posting 'M' describe message
0325335080 [comm.coap] TRACE: sending message id=8454
0325335084 [hal] TRACE: Outputing 214 bytes
0325335086 [lwip] TRACE: pppos_netif_output[3]: proto=0x21, len = 208
0325335086 [comm.protocol] INFO: rcv'd message type=1
0325335088 [system] TRACE: Waiting until all handshake messages are processed by the protocol layer
0325335290 [system.nm] TRACE: br_enabled=1, br_permitted=0
0325335290 [system.nm] INFO: Checking gateway status with the device cloud
0325335376 [lwip] TRACE: pppos_input[3]: got 66 bytes
0325335377 [lwip] TRACE: ppp_input[3]: ip in pbuf len=61
0325335379 [lwip] TRACE: pppos_input[3]: got 66 bytes
0325335381 [lwip] TRACE: ppp_input[3]: ip in pbuf len=61
0325335383 [lwip] TRACE: pppos_input[3]: got 66 bytes
0325335385 [lwip] TRACE: ppp_input[3]: ip in pbuf len=61
0325335387 [lwip] TRACE: pppos_input[3]: got 67 bytes
0325335389 [lwip] TRACE: ppp_input[3]: ip in pbuf len=61
0325335390 [lwip] TRACE: pppos_input[3]: got 66 bytes
0325335391 [lwip] TRACE: ppp_input[3]: ip in pbuf len=61
0325335393 [lwip] TRACE: pppos_input[3]: got 72 bytes
0325335394 [lwip] TRACE: ppp_input[3]: ip in pbuf len=67
0325335397 [comm.coap] TRACE: recieved ACK for message id=4c11
0325335401 [comm.protocol] TRACE: Reply recieved: type=2, code=0
0325335403 [comm.protocol] INFO: message id 19473 complete with code 0.00
0325335407 [comm.protocol] INFO: rcv'd message type=13
0325335509 [system.nm] TRACE: br_enabled=1, br_permitted=0
0325335509 [system.nm] INFO: Checking gateway status with the device cloud
0325335511 [comm.coap] TRACE: recieved ACK for message id=4c12
0325335513 [comm.protocol] TRACE: Reply recieved: type=2, code=0
0325335515 [comm.protocol] INFO: message id 19474 complete with code 0.00
0325335515 [comm.protocol] INFO: rcv'd message type=13
0325335617 [system.nm] TRACE: br_enabled=1, br_permitted=0
0325335617 [system.nm] INFO: Checking gateway status with the device cloud
0325335621 [comm.coap] TRACE: recieved ACK for message id=4c13
0325335621 [comm.protocol] TRACE: Reply recieved: type=2, code=0
0325335623 [comm.protocol] INFO: message id 19475 complete with code 0.00
0325335625 [comm.protocol] INFO: rcv'd message type=13
0325335720 [hal] TRACE: Outputing 22 bytes
0325335721 [lwip] TRACE: pppos_write[3]: len=18
0325335725 [comm.coap] TRACE: recieved ACK for message id=4c14
0325335726 [comm.protocol] TRACE: Reply recieved: type=2, code=0
0325335727 [comm.protocol] INFO: message id 19476 complete with code 0.00
0325335729 [comm.protocol] INFO: rcv'd message type=13
0325335831 [comm.coap] TRACE: recieved ACK for message id=4c15
0325335831 [comm.protocol] TRACE: Reply recieved: type=2, code=0
0325335833 [comm.protocol] INFO: message id 19477 complete with code 0.00
0325335835 [comm.protocol] INFO: rcv'd message type=13
0325335937 [comm.coap] TRACE: recieved ACK for message id=4c16
0325335939 [system] INFO: All handshake messages have been processed
0325335940 [comm.protocol] TRACE: Reply recieved: type=2, code=69
0325335941 [comm.protocol] INFO: message id 19478 complete with code 2.05
0325335943 [comm.protocol] INFO: Received TIME response: 1580171628
0325335945 [comm.protocol] INFO: rcv'd message type=12
0325336047 [system] INFO: Cloud connected
0325336345 [lwip] TRACE: pppos_input[3]: got 71 bytes
0325336345 [lwip] TRACE: ppp_input[3]: ip in pbuf len=66
0325336877 [ncp.at] TRACE: > AT+CCID
0325336896 [ncp.at] TRACE: < +CCID: 89610185002618873130
0325336897 [ncp.at] TRACE: < OK
0325336898 [ncp.at] TRACE: > AT+CGSN
0325336946 [ncp.at] TRACE: < 359215101723758
0325336946 [ncp.at] TRACE: < OK
0325336948 [comm.protocol] INFO: Posting 'S' describe message
0325336949 [comm.coap] TRACE: sending message id=8455
0325336955 [hal] TRACE: Outputing 343 bytes
0325336955 [lwip] TRACE: pppos_netif_output[3]: proto=0x21, len = 337
0325336957 [comm.dtls] INFO: session cmd (CLS,DIS,MOV,LOD,SAV): 4
0325337491 [ncp.at] TRACE: > AT+CCID
0325337496 [lwip] TRACE: pppos_input[3]: got 71 bytes
0325337497 [lwip] TRACE: ppp_input[3]: ip in pbuf len=66
0325337548 [ncp.at] TRACE: < +CCID: 89610185002618873130
0325337549 [ncp.at] TRACE: < OK
0325337550 [ncp.at] TRACE: > AT+CGSN
0325337598 [ncp.at] TRACE: < 359215101723758
0325337598 [ncp.at] TRACE: < OK
0325337599 [comm.dtls] INFO: session cmd (CLS,DIS,MOV,LOD,SAV): 3
0325337601 [comm.protocol] INFO: rcv'd message type=1
0325337703 [comm.protocol] INFO: Posting 'A' describe message
0325337705 [comm.coap] TRACE: sending message id=8456
0325337707 [hal] TRACE: Outputing 91 bytes
0325337709 [lwip] TRACE: pppos_netif_output[3]: proto=0x21, len = 86
0325337711 [comm.dtls] INFO: session cmd (CLS,DIS,MOV,LOD,SAV): 4
0325337711 [comm.dtls] INFO: session cmd (CLS,DIS,MOV,LOD,SAV): 3
0325337713 [comm.protocol] INFO: rcv'd message type=1
0325339105 [hal] TRACE: Outputing 16 bytes
0325339105 [lwip] TRACE: pppos_write[3]: len=12
0325339348 [lwip] TRACE: pppos_input[3]: got 25 bytes
0325341721 [hal] TRACE: Outputing 22 bytes
0325341721 [lwip] TRACE: pppos_write[3]: len=18
0325344106 [hal] TRACE: Outputing 16 bytes
0325344106 [lwip] TRACE: pppos_write[3]: len=12
0325344498 [lwip] TRACE: pppos_input[3]: got 25 bytes
0325347722 [hal] TRACE: Outputing 22 bytes
0325347722 [lwip] TRACE: pppos_write[3]: len=18
0325349107 [hal] TRACE: Outputing 16 bytes
0325349107 [lwip] TRACE: pppos_write[3]: len=12
0325349298 [lwip] TRACE: pppos_input[3]: got 26 bytes
0325349887 [app] INFO: Tue Jan 28 07:34:01 2020

Thank you in advance

2

Do these disconnects also happen with some test code that doesn’t do a lot more than attend to the cloud connection?
Are you using SYSTEM_THREAD(ENABLED)?
Can you try device OS v1.4.4?

3

Yes, the disconnects happen on devices which only maintain the cloud connection.

SYSTEM_THREAD(ENABLED) is used in all my code.

I’ve tested the connection with OS v1.4.4. The devices still disconnect sporadically. I’ll leave the devices running for a day to see if there’s any noticeable improvement.

Are there connectivity improvements in OS v1.4.4?

4

Hi @ScruffR

I’ve run OS v1.4.4.
The disconnect issue still persists and our debug device behaves the same.

We did run up another debug device that connected to a different telecom tower. And noticed that it didn’t take 5 min worth of attempts for it to register. It registered on the first attempt.

0001675580 [comm.protocol] ERROR: Event loop error 3
0001675581 [system] WARN: Communication loop error, closing cloud socket
0001675584 [system] INFO: Cloud: disconnecting
0001675585 [system] INFO: Cloud: disconnected
0001676502 [app] INFO: Fri Jan 31 13:06:13 2020
0001690393 [ncp.at] TRACE: > AT+CEREG?
0001690430 [ncp.at] TRACE: < +CEREG: 2,0
0001690431 [ncp.at] TRACE: < OK
0001701131 [ncp.at] TRACE: < +CEREG: 2
0001701231 [ncp.at] TRACE: < +CEREG: 1,"2058","805CF0E",8
0001701232 [hal] TRACE: NCP connection state changed: 2
0001701233 [gsm0710muxer] INFO: Mux channel 2 already opened
0001701234 [net.pppncp] TRACE: NCP event 100
0001701234 [net.pppncp] TRACE: New auth info
0001701235 [net.pppncp] TRACE: NCP event 2
0001701235 [net.pppncp] TRACE: State changed event: 2
0001701236 [hal] TRACE: PPP thread event LOWER_UP
0001701238 [hal] TRACE: State READY -> CONNECT

Any advice will be appreciated.

Thank you in advance

5

I cannot advise on LTE as I’m based in Europe where LTE Boron’s are not natively supported yet.
I don’t even own a Boron LTE.

6

I also am having disconnects. I was thinking it was a signal issue, but now that I’m digging deeper it’s looking like all of my devices are struggling with cloud disconnects. Latency seems to be playing a role, but I haven’t correlated that across my devices yet. My worst performing device has a ping around 1000ms, which is terrible, and has lost connection hundreds of times. I’ll be looking into this a little more carefully now, if you’ve learned anything new I’d be interested in hearing about it.

7

Hi @rickkas7,

It seems like you know a lot about the inner workings of LTE.
Do you have any advice or insight on this?

Kind regards

8

Hi @blacklabdon, have you made any progress on this front? Cloud/LTE disconnects seem to be an issue for some of us, and I’ve searched the forums high and low without finding satisfactory answers. I will be submitting some support tickets to Particle as well, but it would be great if you’ve learned anything. I will be sure to share if I find some resolution too, good luck!

9

Here's another thread where they were dealing with Event Loop Error 3...

Looks similar to what you're seeing. I've run cloud debug too, but only see the issues in the field and not here at our office.

10

@aklein24 I have some bad news for you…

I had the pleasure to have Ublox and Telstra Engineers assist in the fault finding and was lucky enough to be lent a Ublox Test evaluation kit. The conclusion even the test kit dropped off the Telstra network.

There is no think you can do that will stop the disconnects other then ensure your software can recover the dropouts. Cat-M1 is a lost cost solution and I do not see any improvements being made in the short term.

Devices that spend the majority of their time off line and only connected to transmit data and then drop back off will be fine and most likely wont see this issue.

The devices that require 24/7 connection will see this issue every day of the week.

1 Like
11

Well that’s a bit disheartening. How do you handle the disconnects? Reset?

12

Sorry missed your message, in short, if you reboot tge modem it wil connect back up and you won’t have tk wait the standard 5 minutes when it should automatically reboot. You can try and do checks to catch it early, but as far as I know, there is no fix.