Current Consumption and Sleep modes Boron


#21

I wonder what changed?

Is it connected to a different cell tower? Did it switch to transmitting at a higher power level?

I think @rickkas7 has some cellular debug code you can load that will spit out what it’s actually doing every min now.


#22

Yes, I would run the Boron cloud debug code to see what the device is doing every minute:

I used a Boron LTE running 0.8.0-rc.26 and Tinker. This is a graph of the current over about 25 minutes. I’m only seeing the 23 minute spikes in current usage.

22%20PM


#23

I have no idea. I’m thoroughly confused.
Boron LTE & Test Rig haven’t moved, but I can’t confirm that’s it’s not connected to a different Cell Tower. Not sure why that would cause the Boron to perform Cloud Tasks “behind the scenes” every Minute now, when it hasn’t been doing that ? The peak current is still ~100 mA @ 4.00V, but the Boron does it every minute now instead of every 23 minutes.

My uneducated guess is something could have changed with the Particle Cloud Backend yesterday?

I would love to figure out what’s happening, because we’re headed in the wrong direction with a 40% increase for a “low-powered” device.


#24

Ricks cellular test code above should highlight exactly what is causing the 1 min spikes.


#25
Boron Cloud Debug Output

0000001941 [hal] TRACE: Modem powered off
0000001941 [hal] TRACE: Powering modem on
0000002091 [hal] TRACE: Modem powered on
0000002092 [hal] TRACE: Setting UART voltage translator state 1
0000003092 [ncp.at] TRACE: > AT
0000004092 [ncp.at] TRACE: > AT
0000005092 [ncp.at] TRACE: > AT
0000006092 [ncp.at] TRACE: > AT
0000006161 [ncp.at] TRACE: < AT
0000006161 [ncp.at] TRACE: < OK
0000007161 [hal] TRACE: NCP ready to accept AT commands
0000007161 [ncp.at] TRACE: > AT+UGPIOC?
0000007165 [ncp.at] TRACE: < AT+UGPIOC?
0000007166 [ncp.at] TRACE: < +UGPIOC:
0000007166 [ncp.at] TRACE: < 16,255
0000007167 [ncp.at] TRACE: < 19,255
0000007168 [ncp.at] TRACE: < 23,0
0000007168 [ncp.at] TRACE: < 24,255
0000007169 [ncp.at] TRACE: < 25,255
0000007170 [ncp.at] TRACE: < 42,255
0000007170 [ncp.at] TRACE: < OK
0000007170 [ncp.at] TRACE: > AT+UGPIOR=23
0000007175 [ncp.at] TRACE: < AT+UGPIOR=23
0000007176 [ncp.at] TRACE: < +UGPIOR: 23,1
0000007177 [ncp.at] TRACE: < OK
0000007177 [hal] INFO: Using internal SIM card
0000007177 [ncp.at] TRACE: > AT+CPIN?
0000007180 [ncp.at] TRACE: < AT+CPIN?
0000007182 [ncp.at] TRACE: < +CPIN: READY
0000007182 [ncp.at] TRACE: < OK
0000007182 [ncp.at] TRACE: > AT+CCID
0000007185 [ncp.at] TRACE: < AT+CCID
0000007188 [ncp.at] TRACE: < +CCID: 89014103259631200022
0000007188 [ncp.at] TRACE: < OK
0000007188 [ncp.at] TRACE: > AT+COPS=2
0000007192 [ncp.at] TRACE: < AT+COPS=2
0000007199 [ncp.at] TRACE: < OK
0000007199 [ncp.at] TRACE: > AT+CEDRXS=0
0000007203 [ncp.at] TRACE: < AT+CEDRXS=0
0000007203 [ncp.at] TRACE: < OK
0000007203 [ncp.at] TRACE: > AT+CPSMS=0
0000007208 [ncp.at] TRACE: < AT+CPSMS=0
0000007208 [ncp.at] TRACE: < OK
0000007208 [ncp.at] TRACE: > AT+CEDRXS?
0000007212 [ncp.at] TRACE: < AT+CEDRXS?
0000007213 [ncp.at] TRACE: < +CEDRXS: 2,"1001"
0000007215 [ncp.at] TRACE: < +CEDRXS: 5,"1001"
0000007216 [ncp.at] TRACE: < OK
0000007216 [ncp.at] TRACE: > AT+CPSMS?
0000007219 [ncp.at] TRACE: < AT+CPSMS?
0000007223 [ncp.at] TRACE: < +CPSMS:0,“01100000”,"00000000"
0000007223 [ncp.at] TRACE: < OK
0000007223 [ncp.at] TRACE: > AT+CMUX=0,0,1509,
0000007230 [ncp.at] TRACE: < AT+CMUX=0,0,1509,
0000007230 [ncp.at] TRACE: < OK
0000007231 [gsm0710muxer] INFO: Starting GSM07.10 muxer
0000007232 [gsm0710muxer] INFO: GSM07.10 muxer thread started
0000007231 [gsm0710muxer] INFO: Openning mux channel 0
0000007332 [gsm0710muxer] INFO: Resuming channel 0
0000007332 [gsm0710muxer] INFO: Openning mux channel 1
0000007382 [gsm0710muxer] INFO: Resuming channel 1
0000007382 [gsm0710muxer] INFO: Resuming channel 1
0000007383 [ncp.at] TRACE: > AT
0000007433 [ncp.at] TRACE: < AT
0000007433 [ncp.at] TRACE: < OK
0000007433 [hal] TRACE: NCP state changed: 1
0000007434 [net.pppncp] TRACE: NCP event 1
0000007434 [hal] TRACE: Muxer AT channel live
0000007435 [hal] TRACE: PPP thread event LOWER_DOWN
0000007435 [hal] TRACE: PPP thread event ADM_DOWN
0000007435 [hal] TRACE: PPP thread event ADM_UP
0000007437 [hal] TRACE: State NONE -> READY
0000007438 [ncp.at] TRACE: > AT+CIMI
0000007483 [ncp.at] TRACE: < AT+CIMI
0000007483 [ncp.at] TRACE: < 310410963120002
0000007483 [ncp.at] TRACE: < OK
0000007484 [ncp.at] TRACE: > AT+CGDCONT=1,“IP”,"10569.mcs"
0000007533 [ncp.at] TRACE: < AT+CGDCONT=1,“IP”,"10569.mcs"
0000007533 [ncp.at] TRACE: < OK
0000007533 [ncp.at] TRACE: > AT+CEREG=2
0000007583 [ncp.at] TRACE: < AT+CEREG=2
0000007583 [ncp.at] TRACE: < OK
0000007583 [hal] TRACE: NCP connection state changed: 1
0000007584 [net.pppncp] TRACE: NCP event 2
0000007584 [net.pppncp] TRACE: State changed event: 1
0000007584 [ncp.at] TRACE: > AT+COPS=0
0000007585 [hal] TRACE: PPP thread event LOWER_DOWN
0000007633 [ncp.at] TRACE: < AT+COPS=0
0000007633 [ncp.at] TRACE: < OK
0000007633 [ncp.at] TRACE: > AT+CEREG?
0000007634 [ncp.at] TRACE: < +CEREG: 2
0000007683 [ncp.at] TRACE: < AT+CEREG?
0000007683 [ncp.at] TRACE: < +CEREG: 2,2
0000007683 [ncp.at] TRACE: < OK
0000008884 [ncp.at] TRACE: < +CEREG: 1,“3B21”,“312C910”,8
0000008884 [hal] TRACE: NCP connection state changed: 2
0000008884 [gsm0710muxer] INFO: Openning mux channel 2
0000008983 [gsm0710muxer] INFO: Resuming channel 2
0000008983 [net.pppncp] TRACE: NCP event 100
0000008983 [net.pppncp] TRACE: New auth info
0000008984 [net.pppncp] TRACE: NCP event 2
0000008984 [net.pppncp] TRACE: State changed event: 2
0000008984 [hal] TRACE: PPP thread event LOWER_UP
0000008985 [hal] TRACE: State READY -> CONNECT
0000008985 [net.ppp.ipcp] TRACE: IPCP: init
0000008986 [net.ppp.ipcp] TRACE: IPCP: disable 0 0 0
0000008986 [net.ppp.ipcp] TRACE: IPCP: enable 0 0 0
0000008986 [hal] TRACE: Outputing 13 bytes
0000008987 [hal] TRACE: State CONNECT -> CONNECTING
0000008987 [lwip] TRACE: ppp_connect[3]: holdoff=1
0000008987 [lwip] TRACE: ppp phase changed[3]: phase=2
0000008988 [hal] TRACE: PPP phase -> 2
0000009034 [lwip] TRACE: pppos_input[3]: got 12 bytes
0000009034 [lwip] TRACE: pppos_input[3]: got 21 bytes
0000009988 [lwip] TRACE: ppp phase changed[3]: phase=3
0000009988 [hal] TRACE: PPP phase -> 3
0000009988 [lwip] TRACE: pppos_connect: unit 3: connecting
0000009989 [lwip] TRACE: ppp_start[3]
0000009989 [lwip] TRACE: ppp phase changed[3]: phase=6
0000009989 [hal] TRACE: PPP phase -> 6
0000009990 [lwip] TRACE: pppos_send_config[3]: out_accm=FF FF FF FF
0000009990 [lwip] TRACE: ppp_send_config[3]
0000009991 [lwip] TRACE: pppos_recv_config[3]: in_accm=FF FF FF FF
0000009991 [lwip] TRACE: ppp_recv_config[3]
0000009992 [lwip] TRACE: ppp: auth protocols:
0000009992 [lwip] TRACE: PAP=1
0000009992 [lwip] TRACE: CHAP=1 CHAP_MD5=1
0000009992 [lwip] TRACE:
0000009993 [hal] TRACE: Outputing 48 bytes
0000009993 [lwip] TRACE: pppos_write[3]: len=24
0000009994 [lwip] TRACE: ppp_start[3]: finished
0000010035 [lwip] TRACE: pppos_input[3]: got 55 bytes
0000010035 [hal] TRACE: Outputing 55 bytes
0000010036 [lwip] TRACE: pppos_write[3]: len=29
0000010036 [lwip] TRACE: pppos_input[3]: got 46 bytes
0000010037 [lwip] TRACE: netif_set_mtu[3]: mtu=1500
0000010037 [lwip] TRACE: pppos_send_config[3]: out_accm=0 0 0 0
0000010038 [lwip] TRACE: ppp_send_config[3]
0000010038 [lwip] TRACE: pppos_recv_config[3]: in_accm=0 0 0 0
0000010038 [lwip] TRACE: ppp_recv_config[3]
0000010039 [hal] TRACE: Outputing 15 bytes
0000010039 [lwip] TRACE: pppos_write[3]: len=12
0000010040 [net.ppp.ipcp] TRACE: IPCP: lowerUp
0000010040 [lwip] TRACE: ppp phase changed[3]: phase=7
0000010040 [hal] TRACE: PPP phase -> 7
0000010091 [lwip] TRACE: pppos_input[3]: got 23 bytes
0000010091 [lwip] TRACE: pppos_input[3]: got 41 bytes
0000010092 [lwip] TRACE: No CHAP secret found for authenticating us to UMTS_CHAP_SRVR
0000010092 [hal] TRACE: Outputing 28 bytes
0000010093 [lwip] TRACE: pppos_write[3]: len=25
0000010093 [lwip] TRACE: pppos_input[3]: got 28 bytes
0000010144 [lwip] TRACE: pppos_input[3]: got 10 bytes
0000010144 [lwip] TRACE: CHAP authentication succeeded
0000010144 [lwip] TRACE: CHAP authentication succeeded
0000010145 [lwip] TRACE: ppp phase changed[3]: phase=9
0000010145 [hal] TRACE: PPP phase -> 9
0000010145 [net.ppp.ipcp] TRACE: IPCP: open
0000010145 [net.ppp.ipcp] TRACE: IPCP: reset ci
0000010146 [net.ppp.ipcp] TRACE: IPCP: get ci length
0000010147 [net.ppp.ipcp] TRACE: IPCP: Our CI length: 24
0000010147 [hal] TRACE: Outputing 35 bytes
0000010148 [lwip] TRACE: pppos_write[3]: len=32
0000010148 [hal] TRACE: Outputing 21 bytes
0000010148 [lwip] TRACE: pppos_write[3]: len=18
0000010199 [lwip] TRACE: pppos_input[3]: got 10 bytes
0000010199 [net.ppp.ipcp] TRACE: IPCP: input 4
0000010199 [net.ppp.ipcp] TRACE: IPCP: request ci
0000010200 [hal] TRACE: Outputing 11 bytes
0000010200 [lwip] TRACE: pppos_write[3]: len=8
0000010200 [lwip] TRACE: pppos_input[3]: got 16 bytes
0000010201 [net.ppp.ipcp] TRACE: IPCP: input 10
0000010201 [net.ppp.ipcp] TRACE: IPCP: reject ci
0000010202 [net.ppp.ipcp] TRACE: IPCP: get ci length
0000010202 [net.ppp.ipcp] TRACE: IPCP: Our CI length: 18
0000010202 [hal] TRACE: Outputing 29 bytes
0000010203 [lwip] TRACE: pppos_write[3]: len=26
0000010253 [lwip] TRACE: pppos_input[3]: got 28 bytes
0000010253 [net.ppp.ipcp] TRACE: IPCP: input 22
0000010253 [net.ppp.ipcp] TRACE: IPCP: nak ci
0000010254 [net.ppp.ipcp] TRACE: IPCP: get ci length
0000010254 [net.ppp.ipcp] TRACE: IPCP: Our CI length: 18
0000010254 [hal] TRACE: Outputing 29 bytes
0000010255 [lwip] TRACE: pppos_write[3]: len=26
0000010305 [lwip] TRACE: pppos_input[3]: got 28 bytes
0000010305 [net.ppp.ipcp] TRACE: IPCP: input 22
0000010305 [net.ppp.ipcp] TRACE: IPCP: ack ci
0000010306 [net.ppp.ipcp] TRACE: IPCP: up
0000010306 [hal] TRACE: PPP netif -> 4
0000010306 [net.ifapi] INFO: Netif pp3 link UP
0000010306 [system.nm] INFO: State changed: IFACE_UP -> IFACE_LINK_UP
0000010308 [lwip] TRACE: sifup[3]: err_code=0
0000010308 [hal] TRACE: PPP status -> 0
0000010308 [hal] TRACE: PPP netif -> b0
0000010309 [net.ifapi] TRACE: Netif pp3 ipv4 configuration changed
0000010309 [hal] TRACE: PPP thread event UP
0000010310 [hal] TRACE: State CONNECTING -> CONNECTED
0000010310 [hal] INFO: DNS server list changed
0000010311 [system.nm] TRACE: br_enabled=1
0000010311 [system.nm] INFO: State changed: IFACE_LINK_UP -> IP_CONFIGURED
0000010312 [hal] INFO: DNS server list changed
0000010312 [lwip] TRACE: ppp phase changed[3]: phase=10
0000010313 [hal] TRACE: PPP phase -> 10
0000010313 [system.nm] TRACE: br_enabled=1, br_permitted=0
0000010314 [system.nm] INFO: Checking gateway status with the device cloud
0000010314 [system] INFO: Cloud: connecting
0000010316 [system] INFO: Read Server Address = type:1,domain:$id.udp-mesh.particle.io
0000010316 [system] INFO: Loaded cloud server address and port from session data
0000010317 [system] TRACE: Address type: 1
0000010317 [system] TRACE: Cloud socket=0, family=2, type=2, protocol=17
0000010318 [system] INFO: Cloud socket=0, connecting to 54.227.171.171#5684
0000010319 [system] TRACE: Cloud socket=0, connected to 54.227.171.171#5684
0000010319 [system] TRACE: Updating cloud keepalive for AF_INET: 1380000 -> 1380000
0000010319 [system] TRACE: Applying new keepalive interval now
0000010320 [system] INFO: Cloud socket connected
0000010320 [system] INFO: Starting handshake: presense_announce=0
0000010320 [comm.protocol.handshake] INFO: Establish secure connection
0000010560 [ncp.at] TRACE: > AT+CCID
0000010613 [ncp.at] TRACE: < AT+CCID
0000010613 [ncp.at] TRACE: < +CCID: 89014103259631200022
0000010613 [ncp.at] TRACE: < OK
0000010614 [ncp.at] TRACE: > AT+CGSN
0000010663 [ncp.at] TRACE: < AT+CGSN
0000010663 [ncp.at] TRACE: < 352753091102150
0000010663 [ncp.at] TRACE: < OK
0000010671 [comm.dtls] INFO: (CMPL,RENEG,NO_SESS,ERR) restoreStatus=0
0000010671 [comm.dtls] INFO: out_ctr 0,1,0,0,0,0,0,15, next_coap_id=5
0000010672 [comm.dtls] INFO: app state crc: cached: b59e785d, actual: ba65b316
0000010672 [comm.dtls] INFO: restored session from persisted session data. next_msg_id=5
0000010673 [comm.dtls] INFO: session cmd (CLS,DIS,MOV,LOD,SAV): 2
0000010674 [comm.protocol.handshake] INFO: Sending HELLO message
0000010674 [comm.coap] TRACE: sending message id=6 synchronously
0000010674 [comm.coap] TRACE: sending message id=6
0000010675 [hal] TRACE: Outputing 105 bytes
0000010676 [lwip] TRACE: pppos_netif_output[3]: proto=0x21, len = 99
0000010963 [lwip] TRACE: pppos_input[3]: got 66 bytes
0000010963 [lwip] TRACE: ppp_input[3]: ip in pbuf len=61
0000010964 [lwip] TRACE: pppos_input[3]: got 71 bytes
0000010964 [lwip] TRACE: ppp_input[3]: ip in pbuf len=66
0000010965 [comm.coap] TRACE: recieved ACK for message id=6
0000010966 [comm.protocol.handshake] INFO: Handshake completed
0000010967 [system] INFO: Send spark/hardware/max_binary event
0000010967 [comm.coap] TRACE: sending message id=7
0000010968 [hal] TRACE: Outputing 103 bytes
0000010969 [lwip] TRACE: pppos_netif_output[3]: proto=0x21, len = 98
0000010970 [system] INFO: Send subscriptions
0000010971 [comm.coap] TRACE: sending message id=8
0000010971 [hal] TRACE: Outputing 73 bytes
0000010972 [lwip] TRACE: pppos_netif_output[3]: proto=0x21, len = 69
0000010972 [comm.dtls] INFO: session cmd (CLS,DIS,MOV,LOD,SAV): 4
0000010973 [comm.dtls] INFO: session cmd (CLS,DIS,MOV,LOD,SAV): 3
0000010973 [comm] INFO: Sending TIME request
0000010973 [comm.coap] TRACE: sending message id=9
0000010974 [hal] TRACE: Outputing 68 bytes
0000010975 [lwip] TRACE: pppos_netif_output[3]: proto=0x21, len = 64
0000010976 [comm.protocol] INFO: Sending ‘M’ describe message
0000010976 [comm.coap] TRACE: sending message id=9f65
0000010977 [hal] TRACE: Outputing 153 bytes
0000010978 [lwip] TRACE: pppos_netif_output[3]: proto=0x21, len = 148
0000010978 [comm.protocol] INFO: rcv’d message type=1
0000010979 [system] INFO: Cloud connected
0000010979 [comm] INFO: Forcing a cloud ping
0000010979 [comm.coap] TRACE: sending message id=a
0000010980 [hal] TRACE: Outputing 65 bytes
0000010981 [lwip] TRACE: pppos_netif_output[3]: proto=0x21, len = 61
0000010981 [system.nm] TRACE: br_enabled=1, br_permitted=0
0000010982 [system.nm] INFO: Checking gateway status with the device cloud
0000010982 [system.nm] TRACE: br_enabled=1, br_permitted=0
0000010983 [system.nm] INFO: Checking gateway status with the device cloud
0000010984 [system.nm] TRACE: br_enabled=1, br_permitted=0
0000010984 [system.nm] INFO: Checking gateway status with the device cloud
0000011265 [lwip] TRACE: pppos_input[3]: got 66 bytes
0000011265 [lwip] TRACE: ppp_input[3]: ip in pbuf len=61
0000011266 [lwip] TRACE: pppos_input[3]: got 66 bytes
0000011266 [lwip] TRACE: ppp_input[3]: ip in pbuf len=61
0000011267 [lwip] TRACE: pppos_input[3]: got 73 bytes
0000011268 [lwip] TRACE: ppp_input[3]: ip in pbuf len=67
0000011268 [comm.coap] TRACE: recieved ACK for message id=7
0000011269 [comm.protocol] TRACE: Reply recieved: type=2, code=0
0000011269 [comm.protocol] INFO: message id 7 complete with code 0.00
0000011269 [comm.protocol] INFO: rcv’d message type=13
0000011270 [comm.coap] TRACE: recieved ACK for message id=8
0000011271 [comm.protocol] TRACE: Reply recieved: type=2, code=0
0000011271 [comm.protocol] INFO: message id 8 complete with code 0.00
0000011271 [comm.protocol] INFO: rcv’d message type=13
0000011272 [comm.coap] TRACE: recieved ACK for message id=9
0000011273 [comm.protocol] TRACE: Reply recieved: type=2, code=69
0000011273 [comm.protocol] INFO: message id 9 complete with code 2.05
0000011273 [comm.protocol] INFO: Received TIME response: 1545244952
0000011274 [comm.protocol] INFO: rcv’d message type=12
0000011318 [lwip] TRACE: pppos_input[3]: got 66 bytes
0000011318 [lwip] TRACE: ppp_input[3]: ip in pbuf len=61
0000011319 [comm.coap] TRACE: recieved ACK for message id=a
0000011319 [comm.protocol] TRACE: Reply recieved: type=2, code=0
0000011320 [comm.protocol] INFO: message id 10 complete with code 0.00
0000011320 [comm.protocol] INFO: rcv’d message type=13
0000012219 [lwip] TRACE: pppos_input[3]: got 72 bytes
0000012219 [lwip] TRACE: ppp_input[3]: ip in pbuf len=66
0000012457 [ncp.at] TRACE: > AT+CCID
0000012470 [ncp.at] TRACE: < AT+CCID
0000012470 [ncp.at] TRACE: < +CCID: 89014103259631200022
0000012470 [ncp.at] TRACE: < OK
0000012471 [ncp.at] TRACE: > AT+CGSN
0000012520 [ncp.at] TRACE: < AT+CGSN
0000012520 [ncp.at] TRACE: < 352753091102150
0000012520 [ncp.at] TRACE: < OK
0000012521 [comm.protocol] INFO: Sending ‘S’ describe message
0000012521 [comm.coap] TRACE: sending message id=9f66
0000012523 [hal] TRACE: Outputing 275 bytes
0000012524 [lwip] TRACE: pppos_netif_output[3]: proto=0x21, len = 268
0000012524 [comm.dtls] INFO: session cmd (CLS,DIS,MOV,LOD,SAV): 4
0000012763 [ncp.at] TRACE: > AT+CCID
0000012770 [lwip] TRACE: pppos_input[3]: got 71 bytes
0000012770 [lwip] TRACE: ppp_input[3]: ip in pbuf len=66
0000012821 [ncp.at] TRACE: < AT+CCID
0000012871 [ncp.at] TRACE: < +CCID: 89014103259631200022
0000012871 [ncp.at] TRACE: < OK
0000012872 [ncp.at] TRACE: > AT+CGSN
0000012921 [ncp.at] TRACE: < AT+CGSN
0000012921 [ncp.at] TRACE: < 352753091102150
0000012921 [ncp.at] TRACE: < OK
0000012922 [comm.dtls] INFO: session cmd (CLS,DIS,MOV,LOD,SAV): 3
0000012922 [comm.protocol] INFO: rcv’d message type=1
0000012923 [comm.protocol] INFO: Sending ‘A’ describe message
0000012924 [comm.coap] TRACE: sending message id=9f67
0000012925 [hal] TRACE: Outputing 138 bytes
0000012925 [lwip] TRACE: pppos_netif_output[3]: proto=0x21, len = 133
0000012926 [comm.dtls] INFO: session cmd (CLS,DIS,MOV,LOD,SAV): 4
0000012926 [comm.dtls] INFO: session cmd (CLS,DIS,MOV,LOD,SAV): 3
0000012927 [comm.protocol] INFO: rcv’d message type=1
0000015040 [hal] TRACE: Outputing 16 bytes
0000015040 [lwip] TRACE: pppos_write[3]: len=12
0000015071 [lwip] TRACE: pppos_input[3]: got 28 bytes
0000016149 [hal] TRACE: Outputing 22 bytes
0000016149 [lwip] TRACE: pppos_write[3]: len=18
0000020040 [hal] TRACE: Outputing 16 bytes
0000020040 [lwip] TRACE: pppos_write[3]: len=12
0000020071 [lwip] TRACE: pppos_input[3]: got 29 bytes
0000022149 [hal] TRACE: Outputing 22 bytes
0000022149 [lwip] TRACE: pppos_write[3]: len=18
0000025040 [hal] TRACE: Outputing 16 bytes
0000025040 [lwip] TRACE: pppos_write[3]: len=12
0000025071 [lwip] TRACE: pppos_input[3]: got 28 bytes
0000028149 [hal] TRACE: Outputing 22 bytes
0000028149 [lwip] TRACE: pppos_write[3]: len=18
0000030040 [hal] TRACE: Outputing 16 bytes
0000030040 [lwip] TRACE: pppos_write[3]: len=12
0000030071 [lwip] TRACE: pppos_input[3]: got 28 bytes
0000034149 [hal] TRACE: Outputing 22 bytes
0000034149 [lwip] TRACE: pppos_write[3]: len=18
0000035040 [hal] TRACE: Outputing 16 bytes
0000035040 [lwip] TRACE: pppos_write[3]: len=12
0000035071 [lwip] TRACE: pppos_input[3]: got 28 bytes
0000040040 [hal] TRACE: Outputing 16 bytes
0000040040 [lwip] TRACE: pppos_write[3]: len=12
0000040071 [lwip] TRACE: pppos_input[3]: got 28 bytes
0000040149 [hal] TRACE: Outputing 22 bytes
0000040149 [lwip] TRACE: pppos_write[3]: len=18
0000045040 [hal] TRACE: Outputing 16 bytes
0000045040 [lwip] TRACE: pppos_write[3]: len=12
0000045071 [lwip] TRACE: pppos_input[3]: got 28 bytes
0000046149 [hal] TRACE: Outputing 22 bytes
0000046149 [lwip] TRACE: pppos_write[3]: len=18
0000050040 [hal] TRACE: Outputing 16 bytes
0000050040 [lwip] TRACE: pppos_write[3]: len=12
0000050071 [lwip] TRACE: pppos_input[3]: got 28 bytes
0000052149 [hal] TRACE: Outputing 22 bytes
0000052149 [lwip] TRACE: pppos_write[3]: len=18
0000055040 [hal] TRACE: Outputing 16 bytes
0000055040 [lwip] TRACE: pppos_write[3]: len=12
0000055071 [lwip] TRACE: pppos_input[3]: got 29 bytes
0000058149 [hal] TRACE: Outputing 22 bytes
0000058149 [lwip] TRACE: pppos_write[3]: len=18
0000060040 [hal] TRACE: Outputing 16 bytes
0000060040 [lwip] TRACE: pppos_write[3]: len=12
0000060071 [lwip] TRACE: pppos_input[3]: got 28 bytes
0000060414 [sys.power] TRACE: re-enabling charging
0000060463 [sys.power] TRACE: Battery state DISCONNECTED -> CHARGED
0000060867 [sys.power] TRACE: Battery state CHARGED -> DISCONNECTED
0000064149 [hal] TRACE: Outputing 22 bytes
0000064149 [lwip] TRACE: pppos_write[3]: len=18
0000065040 [hal] TRACE: Outputing 16 bytes
0000065040 [lwip] TRACE: pppos_write[3]: len=12
0000065071 [lwip] TRACE: pppos_input[3]: got 28 bytes
0000070040 [hal] TRACE: Outputing 16 bytes
0000070040 [lwip] TRACE: pppos_write[3]: len=12
0000070071 [lwip] TRACE: pppos_input[3]: got 28 bytes
0000070149 [lwip] TRACE: IPV6CP: timeout sending Config-Requests
0000075040 [hal] TRACE: Outputing 16 bytes
0000075040 [lwip] TRACE: pppos_write[3]: len=12
0000075071 [lwip] TRACE: pppos_input[3]: got 28 bytes
0000080040 [hal] TRACE: Outputing 16 bytes
0000080040 [lwip] TRACE: pppos_write[3]: len=12
0000080071 [lwip] TRACE: pppos_input[3]: got 28 bytes
0000085040 [hal] TRACE: Outputing 16 bytes
0000085040 [lwip] TRACE: pppos_write[3]: len=12
0000085071 [lwip] TRACE: pppos_input[3]: got 28 bytes
0000090040 [hal] TRACE: Outputing 16 bytes
0000090040 [lwip] TRACE: pppos_write[3]: len=12
0000090071 [lwip] TRACE: pppos_input[3]: got 28 bytes
0000095040 [hal] TRACE: Outputing 16 bytes
0000095040 [lwip] TRACE: pppos_write[3]: len=12
0000095071 [lwip] TRACE: pppos_input[3]: got 28 bytes
0000100040 [hal] TRACE: Outputing 16 bytes
0000100040 [lwip] TRACE: pppos_write[3]: len=12
0000100071 [lwip] TRACE: pppos_input[3]: got 29 bytes
0000105040 [hal] TRACE: Outputing 16 bytes
0000105040 [lwip] TRACE: pppos_write[3]: len=12
0000105071 [lwip] TRACE: pppos_input[3]: got 28 bytes
0000110040 [hal] TRACE: Outputing 16 bytes
0000110040 [lwip] TRACE: pppos_write[3]: len=12
0000110071 [lwip] TRACE: pppos_input[3]: got 28 bytes
0000115040 [hal] TRACE: Outputing 16 bytes
0000115040 [lwip] TRACE: pppos_write[3]: len=12
0000115071 [lwip] TRACE: pppos_input[3]: got 28 bytes
0000119721 [lwip] TRACE: pppos_input[3]: got 67 bytes
0000119721 [lwip] TRACE: ppp_input[3]: ip in pbuf len=61
0000119722 [lwip] TRACE: pppos_input[3]: got 66 bytes
0000119722 [lwip] TRACE: ppp_input[3]: ip in pbuf len=61
0000119723 [comm.coap] TRACE: sending message id=9f68
0000119724 [hal] TRACE: Outputing 66 bytes
0000119724 [lwip] TRACE: pppos_netif_output[3]: proto=0x21, len = 61
0000119725 [comm.protocol] INFO: rcv’d message type=14
0000119725 [comm.coap] TRACE: sending message id=9f69
0000119726 [hal] TRACE: Outputing 65 bytes
0000119727 [lwip] TRACE: pppos_netif_output[3]: proto=0x21, len = 61
0000119727 [comm.protocol] INFO: rcv’d message type=14
0000120040 [hal] TRACE: Outputing 16 bytes
0000120040 [lwip] TRACE: pppos_write[3]: len=12
0000120073 [lwip] TRACE: pppos_input[3]: got 29 bytes
0000120868 [sys.power] TRACE: re-enabling charging
0000120914 [sys.power] TRACE: Battery state DISCONNECTED -> CHARGED
0000121079 [sys.power] TRACE: Battery state CHARGED -> CHARGING
0000121114 [sys.power] TRACE: Battery state CHARGING -> CHARGED
0000121318 [sys.power] TRACE: Battery state CHARGED -> DISCONNECTED
0000125040 [hal] TRACE: Outputing 16 bytes
0000125040 [lwip] TRACE: pppos_write[3]: len=12
0000125073 [lwip] TRACE: pppos_input[3]: got 29 bytes
0000130040 [hal] TRACE: Outputing 16 bytes
0000130040 [lwip] TRACE: pppos_write[3]: len=12
0000130073 [lwip] TRACE: pppos_input[3]: got 29 bytes
0000135040 [hal] TRACE: Outputing 16 bytes
0000135040 [lwip] TRACE: pppos_write[3]: len=12
0000135073 [lwip] TRACE: pppos_input[3]: got 28 bytes
0000140040 [hal] TRACE: Outputing 16 bytes
0000140040 [lwip] TRACE: pppos_write[3]: len=12
0000140073 [lwip] TRACE: pppos_input[3]: got 28 bytes
0000145040 [hal] TRACE: Outputing 16 bytes
0000145040 [lwip] TRACE: pppos_write[3]: len=12
0000145073 [lwip] TRACE: pppos_input[3]: got 28 bytes
0000150040 [hal] TRACE: Outputing 16 bytes
0000150040 [lwip] TRACE: pppos_write[3]: len=12
0000150073 [lwip] TRACE: pppos_input[3]: got 28 bytes
0000155040 [hal] TRACE: Outputing 16 bytes
0000155040 [lwip] TRACE: pppos_write[3]: len=12
0000155073 [lwip] TRACE: pppos_input[3]: got 30 bytes
0000160040 [hal] TRACE: Outputing 16 bytes
0000160040 [lwip] TRACE: pppos_write[3]: len=12
0000160073 [lwip] TRACE: pppos_input[3]: got 28 bytes
0000165040 [hal] TRACE: Outputing 16 bytes
0000165040 [lwip] TRACE: pppos_write[3]: len=12
0000165073 [lwip] TRACE: pppos_input[3]: got 28 bytes
0000170040 [hal] TRACE: Outputing 16 bytes
0000170040 [lwip] TRACE: pppos_write[3]: len=12
0000170073 [lwip] TRACE: pppos_input[3]: got 27 bytes
0000175040 [hal] TRACE: Outputing 16 bytes
0000175040 [lwip] TRACE: pppos_write[3]: len=12
0000175073 [lwip] TRACE: pppos_input[3]: got 27 bytes
0000180040 [hal] TRACE: Outputing 16 bytes
0000180040 [lwip] TRACE: pppos_write[3]: len=12
0000180073 [lwip] TRACE: pppos_input[3]: got 27 bytes
0000181319 [sys.power] TRACE: re-enabling charging
0000181378 [sys.power] TRACE: Battery state DISCONNECTED -> CHARGED
0000181497 [sys.power] TRACE: Battery state CHARGED -> CHARGING
0000181526 [sys.power] TRACE: Battery state CHARGING -> CHARGED
0000181782 [sys.power] TRACE: Battery state CHARGED -> DISCONNECTED
0000185040 [hal] TRACE: Outputing 16 bytes
0000185040 [lwip] TRACE: pppos_write[3]: len=12
0000185082 [lwip] TRACE: pppos_input[3]: got 28 bytes
0000190040 [hal] TRACE: Outputing 16 bytes
0000190040 [lwip] TRACE: pppos_write[3]: len=12
0000190082 [lwip] TRACE: pppos_input[3]: got 27 bytes
0000195040 [hal] TRACE: Outputing 17 bytes
0000195040 [lwip] TRACE: pppos_write[3]: len=12
0000195082 [lwip] TRACE: pppos_input[3]: got 27 bytes
0000197782 [lwip] TRACE: pppos_input[3]: got 66 bytes
0000197782 [lwip] TRACE: ppp_input[3]: ip in pbuf len=61
0000197783 [comm.coap] TRACE: sending message id=9f6a
0000197784 [hal] TRACE: Outputing 67 bytes
0000197784 [lwip] TRACE: pppos_netif_output[3]: proto=0x21, len = 61
0000197785 [comm.protocol] INFO: rcv’d message type=14
0000197833 [lwip] TRACE: pppos_input[3]: got 66 bytes
0000197833 [lwip] TRACE: ppp_input[3]: ip in pbuf len=61
0000197834 [comm.coap] TRACE: sending message id=9f6b
0000197835 [hal] TRACE: Outputing 65 bytes
0000197835 [lwip] TRACE: pppos_netif_output[3]: proto=0x21, len = 61
0000197836 [comm.protocol] INFO: rcv’d message type=14
0000200040 [hal] TRACE: Outputing 16 bytes
0000200040 [lwip] TRACE: pppos_write[3]: len=12
0000200084 [lwip] TRACE: pppos_input[3]: got 27 bytes
0000205040 [hal] TRACE: Outputing 16 bytes
0000205040 [lwip] TRACE: pppos_write[3]: len=12
0000205084 [lwip] TRACE: pppos_input[3]: got 27 bytes
0000210040 [hal] TRACE: Outputing 16 bytes
0000210040 [lwip] TRACE: pppos_write[3]: len=12
0000210084 [lwip] TRACE: pppos_input[3]: got 28 bytes
0000215040 [hal] TRACE: Outputing 16 bytes
0000215040 [lwip] TRACE: pppos_write[3]: len=12
0000215084 [lwip] TRACE: pppos_input[3]: got 27 bytes
0000220040 [hal] TRACE: Outputing 16 bytes
0000220040 [lwip] TRACE: pppos_write[3]: len=12
0000220084 [lwip] TRACE: pppos_input[3]: got 27 bytes
0000225040 [hal] TRACE: Outputing 16 bytes
0000225040 [lwip] TRACE: pppos_write[3]: len=12
0000225134 [lwip] TRACE: pppos_input[3]: got 27 bytes
0000230040 [hal] TRACE: Outputing 16 bytes
0000230040 [lwip] TRACE: pppos_write[3]: len=12
0000230084 [lwip] TRACE: pppos_input[3]: got 27 bytes
0000235040 [hal] TRACE: Outputing 16 bytes
0000235040 [lwip] TRACE: pppos_write[3]: len=12
0000235084 [lwip] TRACE: pppos_input[3]: got 27 bytes
0000240040 [hal] TRACE: Outputing 16 bytes
0000240040 [lwip] TRACE: pppos_write[3]: len=12
0000240084 [lwip] TRACE: pppos_input[3]: got 27 bytes
0000241782 [sys.power] TRACE: re-enabling charging
0000241842 [sys.power] TRACE: Battery state DISCONNECTED -> CHARGED
0000241973 [sys.power] TRACE: Battery state CHARGED -> CHARGING
0000241990 [sys.power] TRACE: Battery state CHARGING -> CHARGED
0000242246 [sys.power] TRACE: Battery state CHARGED -> DISCONNECTED
0000245040 [hal] TRACE: Outputing 16 bytes
0000245040 [lwip] TRACE: pppos_write[3]: len=12
0000245096 [lwip] TRACE: pppos_input[3]: got 27 bytes
0000250040 [hal] TRACE: Outputing 16 bytes
0000250040 [lwip] TRACE: pppos_write[3]: len=12
0000250096 [lwip] TRACE: pppos_input[3]: got 27 bytes


#26

This is happening every 1 minute… wonder what that’s about?


#27

Hmmm… The boron is still on my Test Rig for Current Measurements. There is a connector in the Li-PO slot, but no Voltage there at the moment (since I’m connected to USB for the logging). I’ll remove that and start over.

{Edit} Still does the Battery Dance every minute. Nothing in the Li-Po connector.


#28

I updated to 0.8.0-rc.26, Blank Sketch, same results.


#29

Oh, wait, you’re powering by VUSB, not Li-Po? Try inserting a PMIC.disableCharging() in setup() and see if it makes a difference.

I was powering by the Li-Po only when I ran my test.


#30

No Sir, VUSB was only during the Boron Cloud Debug that was suggested.
My current tests are performed with 4.00V on the Li-Po connector, no other pins or USB are touched during Current Testing.


#31

Try dropping the power supply voltage closer to the resting nominal voltage of a LiPo cell like 3.7-3.8v and see if that makes any difference.


#32

For Confirmation, I just opened up another Boron LTE, fresh out of the Box.
Setup with IPhone, selected NO MESH during Setup.
Flashed OTA from WebIDE (0.8.0-rc.26) the following Code

void setup() {
    Mesh.off();   // Same Results with or without this line
}
void loop() {
}  

5 minute log:

@rickkas7, my test results were very similar to yours (every 23 minutes) until late Tuesday.
With no changes to my Rig or Boron, it increased to slightly more than 1 minute (see Post #20).

Can you (or anybody else) run a current test today ?


#33

Did you try lowering the owner supply voltage to see if the battery message that also was popping up in the debug goes away. Considering it is happening every min it could have something to do with the TX burst frequency.

Still doesn’t explain why it didn’t happen before since you were feeding it 4v then also but worth a try to knock the LiPo voltage down.


#34

Dropped to 3.80V supply. Resulted in No change, except obviously the mA has to increase. It still ramps up every minute.
image


#35

And you completely power cycled the system after changing the voltage?


#36

Yes, I have to in order to start a new test. Shouldn’t matter anyway, a Li-Po voltage changes :rofl:


#37

Cool, just wasn’t sure if the PMIC had gotten into a state or loop that could have caused the 1 min charging to discharging message.

The PMIC is a fairly complex chip with tons of different settings and features so it’s hard telling if holding the battery voltage at 4v for long periods of time could have triggered something or not.


#38

Hey, It was worth a try… I still don’t know that it’s not being caused by the PMIC. It’s hard to think of a reason why this suddenly started yesterday, and reproduced with a brand new Boron.


#39

Don’t these logs mean that there is cellular activity? If so, I see them happening about every 78 seconds, which could mean that this is originally what you thought (cloud activity).

0000119723 [comm.coap] TRACE: sending message id=9f68
0000119724 [hal] TRACE: Outputing 66 bytes
0000119724 [lwip] TRACE: pppos_netif_output[3]: proto=0x21, len = 61
0000119725 [comm.protocol] INFO: rcv’d message type=14
0000119725 [comm.coap] TRACE: sending message id=9f69
0000119726 [hal] TRACE: Outputing 65 bytes
0000119727 [lwip] TRACE: pppos_netif_output[3]: proto=0x21, len = 61
0000119727 [comm.protocol] INFO: rcv’d message type=14

#40

Thanks! I didn’t know what to look for in the Cloud Debug Logs.

Drilling down into the my Current Measurement Logs, The current is spiking at 77 to 78 seconds (1min 17 secs).