Tracker Edge wakeFor network issue

peergum · April 11, 2022, 2:36pm

So, I wanted to put the tracker-edge firmware (on v16 currently) to sleep for extended periods of time, but with the ability of waking up on network function calls. Previously device was going to sleep and I had to wait for either a movement or a customizable period of time had passed for it to wake up. When using wakeFor(NETWORK_INTERFACE_CELLULAR) device goes to sleep, but wakes up 3s later, without any particular (obvious) network request. Am I missing something, or is network standby sleep mode not really working with tracker-edge firmware? Our client wants to be able to wake the device on demand, so we’re a bit in a pickle here and I’d rather not have the device awake all the time, for battery saving reasons.

Note that we had to use pauseSleep and resumeSleep (and the sleep callbacks) to interfere with sleep, due to polling bluetooth tags while awake, but I don’t think that would interfere here when going to sleep.

Any help/hints appreciated.

Cheers,
Phil

Note: Our device is based on the Tracker SoM.

Update: I just checked and we in fact rebased our code on v16 end of last year.

peergum · April 11, 2022, 5:38pm

I just rebased our code on tracker-edge v17 and problem is still present:

0000370477 [app] TRACE: EXECUTE time expired and transitioning to SLEEP
0000370478 [app] TRACE: TrackerLocation: last=2115, interval=1800, wake=3825
0000370478 [app] INFO: Prepare to sleep 
0000370479 [app] INFO: Stopping modem
0000370577 [system] INFO: Cloud: disconnecting
0000371580 [system] INFO: Cloud: disconnected
0000371590 [system.nm] INFO: State changed: IP_CONFIGURED -> IFACE_UP
0000371595 [system.nm] INFO: State changed: IFACE_UP -> IFACE_REQUEST_DOWN
0000371595 [system.nm] INFO: State changed: IFACE_REQUEST_DOWN -> IFACE_DOWN
0000371683 [app] INFO: sleeping until 3825000 milliseconds


Serial connection closed.  Attempting to reconnect...
Serial monitor opened successfully:
0000375420 [app] INFO: UUID: 50765CB7-D9EA-4E21-99A4-FA879613A492, Add: 10:5B:AD:A5:BF:D2, M/m: 42462/38685, str: -67dB/-50dB
0000375422 [app] INFO: UUID: 01020304-0506-0708-090A-0B0C0D0E0FF5, Add: FA:27:29:42:26:4D, M/m: 523/266, str: -56dB/-56dB
0000377388 [mux] INFO: Mux channel 2 already opened
0000378427 [system.nm] INFO: State changed: IFACE_UP -> IFACE_LINK_UP
0000378429 [system.nm] INFO: State changed: IFACE_LINK_UP -> IP_CONFIGURED
0000378431 [system] INFO: Cloud: connecting
0000378433 [system] INFO: Cloud socket connected
0000378433 [comm.protocol.handshake] INFO: Establish secure connection
0000378436 [comm.dtls] INFO: session has 0 uses
0000378444 [comm.dtls] INFO: (CMPL,RENEG,NO_SESS,ERR) restoreStatus=0
0000378445 [comm.dtls] INFO: out_ctr 0,1,0,0,0,0,3,218, next_coap_id=3b8

note the time when going to sleep (371683) and when waking up again (375420)

Update: removed comment about time getting out of sync (my bad: I misread some value)

rickkas7 · April 11, 2022, 7:26pm

That should work. Unfortunately it will be a little tricky to troubleshoot. Do you have the TX pin broken out somewhere where you can access it? The log messages that specify exactly what is causing the wake to occur would be really useful, but they occur right at wake, and the USB serial takes several seconds to restart so you lose those messages. The UART messages work immediately upon wake.

A FT232 3.3V serial board, a Particle debugger, Otii power meter, another Particle device could be rigged up to handle the serial. You’ll probably eventually want one for debugging sleep because it’s really tricky to do so with USB debugging.

peergum · April 11, 2022, 7:45pm

I’m using the tracker Som dev board for my tests, so I assume I should be able to do that, since it’s probably one of the TX pins (MCU?) on the connector. I also have the particle debugger.

rickkas7 · April 11, 2022, 7:46pm

Yes, that should work.

peergum · April 11, 2022, 7:50pm

Can you point me to a “manual” or anything to do that? I’ve honestly never gone into debugging my code a proper way, it’s a first! (despite the thousands of line of code written for particle devices, I know… lame [or lucky…])

update: found Device Debugging Lab | Community | Particle I’ll try to figure things from here. Any hint on what I should look for in particular? (TrackerSleep properties…? anything related to CPU state?)

rickkas7 · April 11, 2022, 8:03pm

Connect the TX pin of the Tracker to the USB to serial converter, or the RX signal on the header pins on the debugger (not the 5x2 micro debugging connector).

Open the debugger serial port with a serial terminal program Particle serial monitor.

Add this to your firmware:

Serial1LogHandler uartLogHandler(115200, LOG_LEVEL_TRACE);

You can leave your SerialLogHandler in place and use both, or comment the other one out. Change 115200 to whatever baud rate you’ve set your converter to. The default is usually 9600 but that’s kind of slow.

There should be messages generated automatically in the serial log.

You don’t need do the actual full debugger thing, you’ll just be using it as a serial adapter.

peergum · April 11, 2022, 8:29pm

I’m getting garbage on the port… could it be a GND issue?

peergum · April 11, 2022, 8:36pm

nvm, used minicom it works now

peergum · April 11, 2022, 8:56pm

Any reason why I get only the system.nm messages on the serial1 logHandler, even when I add other sources? If I keep my serialLogHandler on the USB, I get the other messages there… Is there any hard-coded filter for serial1LogHandler?

peergum · April 11, 2022, 9:01pm

okay, I just found out I was disabling Serial1 a bit further, because we use it the pins for a load switch on our actual device. Nvm, I don’t have to disable it on the dev board…

peergum · April 11, 2022, 9:07pm

dump from the moment device tries to go into sleep:

0000145878 [app] INFO: Prepare to sleep 
0000145882 [app] INFO: Stopping modem
0000145913 [system] INFO: Cloud: disconnecting
0000146365 [comm.protocol] TRACE: Reply recieved: type=2, code=0
0000146367 [comm.protocol] TRACE: message id 2113 complete with code 0.00
0000146373 [comm.protocol] TRACE: rcv'd message type=13
0000146423 [app.gps.ubx] TRACE: RX: 
        0109140000af8700c8260200000000000000000000000000
0000146439 [app.gps.nmea] TRACE: RX: $PUBX,00,000221.00,0000.00000,N,00000.00000,E,0.000,NF,5303303,3750001,0.000,0.00,0.000,,99.99,99.99,99.99,0,0,0*28
0000146453 [app.gps.ubx] TRACE: RX: 
        10102800c826020002200200000000000000000685040a008d040a008e040a0090040a0091040a0092040a00
0000146515 [ncp.at] TRACE: > AT+COPS=3,2
0000146517 [ncp.at] TRACE: < OK
0000146520 [ncp.at] TRACE: > AT+COPS?
0000146523 [ncp.at] TRACE: < +COPS: 0,2,"302720",8
0000146526 [ncp.at] TRACE: < OK
0000146532 [ncp.at] TRACE: > AT+QCSQ
0000146536 [ncp.at] TRACE: < +QCSQ: "CAT-M1",-73,-101,128,-12
0000146542 [ncp.at] TRACE: < OK
0000146917 [system] INFO: Cloud: disconnected
0000146921 [net.ppp.client] TRACE: PPP thread event LOWER_DOWN
0000146922 [net.ppp.client] TRACE: State CONNECTED -> DISCONNECT
0000146928 [net.ppp.client] TRACE: State DISCONNECT -> DISCONNECTING
0000146921 [ncp.at] TRACE: > AT+CFUN=0,0
0000146938 [system.nm] INFO: State changed: IP_CONFIGURED -> IFACE_UP
0000146944 [net.ppp.client] TRACE: PPP phase -> 9
0000146949 [net.ppp.client] TRACE: PPP phase -> 6
0000146954 [net.ppp.client] TRACE: PPP phase -> 12
0000146960 [net.ppp.client] TRACE: PPP phase -> 0
0000146961 [net.ppp.client] TRACE: PPP thread event ADM_DOWN
0000146967 [net.ppp.client] TRACE: PPP thread event DOWN
0000146972 [net.ppp.client] TRACE: State DISCONNECTING -> DISCONNECTED
0000146978 [net.ppp.client] TRACE: State DISCONNECTED -> NONE
0000146986 [system.nm] INFO: State changed: IFACE_UP -> IFACE_REQUEST_DOWN
0000146994 [system.nm] INFO: State changed: IFACE_REQUEST_DOWN -> IFACE_DOWN
0000147020 [app] INFO: sleeping until 7203000 milliseconds
0000147022 [system.sleep] TRACE: Entering system_sleep_ext()
0000147028 [system.sleep] TRACE: Interface 5 is off already
0000147033 [system.sleep] TRACE: Interface 3 is off already
0000147356 [ncp.at] TRACE: < OK
0000147356 [ncp.client] TRACE: NCP connection state changed: 0
0000147362 [net.pppncp] TRACE: NCP event 2
0000147363 [net.pppncp] TRACE: State changed event: 0
0000147369 [ncp.at] TRACE: < +CREG: 0
0000147369 [net.ppp.client] TRACE: PPP thread event LOWER_DOWN
0000147473 [ncp.at] TRACE: < +CEREG: 0
0000147734 [app] TRACE: extending execution
0000147735 [app] INFO: Woke up
0000147736 [app] TRACE: woke and executing without connection
0000147742 [app] TRACE: evaluatePublish pending_immediate
0000147747 [app] TRACE: publishing from immediate
0000147753 [app] TRACE: full wakeup requested, connecting
0000147758 [app] INFO: Starting modem
0000147842 [system.nm] INFO: State changed: IFACE_DOWN -> IFACE_REQUEST_UP
0000147848 [net.ppp.client] TRACE: PPP thread event ADM_UP
0000147849 [net.ppp.client] TRACE: State NONE -> READY
0000147853 [ncp.at] TRACE: > AT+CFUN=1,0
0000147859 [system.nm] INFO: State changed: IFACE_REQUEST_UP -> IFACE_UP
0000148111 [ncp.at] TRACE: < OK
0000148112 [ncp.at] TRACE: > AT+CCID
0000148114 [ncp.at] TRACE: < +CCID: 89014103271407732385
0000148118 [ncp.at] TRACE: < OK
0000148129 [ncp.at] TRACE: > AT+CIMI
0000148131 [ncp.at] TRACE: < ERROR
0000148234 [ncp.at] TRACE: > AT+CIMI
0000148236 [ncp.at] TRACE: < ERROR
0000148436 [ncp.at] TRACE: > AT+CIMI
0000148438 [ncp.at] TRACE: < 310410140773238
0000148440 [ncp.at] TRACE: < OK
0000148445 [ncp.at] TRACE: > AT+CGDCONT=1,"IP","10569.mcs"
0000148467 [ncp.at] TRACE: < OK
0000148467 [ncp.at] TRACE: > AT+CFUN=1,0
0000148472 [ncp.at] TRACE: < OK
0000148472 [ncp.at] TRACE: > AT+CREG=2
0000148478 [ncp.at] TRACE: < OK
0000148478 [ncp.at] TRACE: > AT+CGREG=2
0000148483 [ncp.at] TRACE: < OK
0000148486 [ncp.at] TRACE: > AT+CEREG=2
0000148489 [ncp.at] TRACE: < OK
0000148491 [ncp.client] TRACE: NCP connection state changed: 1
0000148496 [net.pppncp] TRACE: NCP event 2
0000148500 [net.pppncp] TRACE: State changed event: 1
0000148506 [net.ppp.client] TRACE: PPP thread event LOWER_DOWN
0000148506 [ncp.at] TRACE: > AT+COPS?
0000148517 [ncp.at] TRACE: < +COPS: 2
0000148519 [ncp.at] TRACE: < OK
0000148523 [ncp.at] TRACE: > AT+COPS=0,2
0000148525 [ncp.at] TRACE: < +CME ERROR: 13
0000148528 [ncp.at] TRACE: > AT+QCFG="nwscanmode"
0000148534 [ncp.at] TRACE: < +QCFG: "nwscanmode",3
0000148539 [ncp.at] TRACE: < OK
0000148541 [ncp.at] TRACE: > AT+QCFG="iotopmode"
0000148545 [ncp.at] TRACE: < +QCFG: "iotopmode",0
0000148550 [ncp.at] TRACE: < OK
0000148553 [ncp.at] TRACE: > AT+CREG?
0000148556 [ncp.at] TRACE: < +CREG: 2,0
0000148561 [ncp.at] TRACE: < OK
0000148562 [ncp.at] TRACE: > AT+CGREG?
0000148567 [ncp.at] TRACE: < +CGREG: 2,0
0000148569 [ncp.at] TRACE: < OK
0000148573 [ncp.at] TRACE: > AT+CEREG?
0000148575 [ncp.at] TRACE: < +CEREG: 2,0
0000148578 [ncp.at] TRACE: < OK
0000148683 [ncp.at] TRACE: < +CPIN: READY
0000148683 [ncp.at] TRACE: < +QUSIM: 1
0000148686 [ncp.at] TRACE: > AT+CIMI
0000148690 [ncp.at] TRACE: < +CREG: 2
0000148696 [ncp.at] TRACE: < +CEREG: 2
0000148696 [ncp.at] TRACE: < +PACSP0
0000148701 [ncp.at] TRACE: < 310410140773238
0000148703 [ncp.at] TRACE: < OK
0000149007 [ncp.at] TRACE: < +QIND: SMS DONE
0000149707 [ncp.at] TRACE: < +CREG: 5,"73A0","9B5979",8
0000149708 [ncp.at] TRACE: > AT+CIMI
0000149712 [ncp.at] TRACE: < +CEREG: 5,"73A0","9B5979",8
0000149718 [ncp.at] TRACE: < 310410140773238
0000149720 [ncp.at] TRACE: < OK
0000149823 [ncp.client] TRACE: NCP connection state changed: 2
0000149824 [mux] INFO: Mux channel 2 already opened
0000149829 [net.pppncp] TRACE: NCP event 100
0000149835 [net.pppncp] TRACE: New auth info
0000149841 [net.pppncp] TRACE: NCP event 2
0000149842 [net.pppncp] TRACE: State changed event: 2
0000149847 [net.ppp.client] TRACE: PPP thread event LOWER_UP
0000149852 [net.ppp.client] TRACE: State READY -> CONNECT
0000149858 [net.ppp.client] TRACE: State CONNECT -> CONNECTING
0000149848 [ncp.at] TRACE: > AT+CIMI
0000149865 [ncp.at] TRACE: < 310410140773238
0000149869 [ncp.at] TRACE: < OK
0000149948 [app] INFO: UUID: 50765CB7-D9EA-4E21-99A4-FA879613A492, Add: 10:5B:AD:A5:BF:D2, M/m: 42462/38685, str: -66dB/-50dB
0000149956 [app] INFO: UUID: 01020304-0506-0708-090A-0B0C0D0E0FF5, Add: FA:27:29:42:26:4D, M/m: 523/266, str: -61dB/-56dB
0000150876 [ncp.at] TRACE: > AT
0000150879 [ncp.at] TRACE: < NO CARRIER
0000150977 [app.gps.nmea] TRACE: RX: $GNTXT,01,01,02,u-blox AG - www.u-blox.com*4E
0000150981 [app.gps.nmea] TRACE: RX: $GNTXT,01,01,02,HW UBX-M8030 00080000*60
0000150987 [app.gps.nmea] TRACE: RX: $GNTXT,01,01,02,EXT CORE 3.01 (1ec93f)*67
0000150997 [app.gps.nmea] TRACE: RX: $GNTXT,01,01,02,ROM BASE 2.01 (75331)*19
0000151003 [app.gps.nmea] TRACE: RX: $GNTXT,01,01,02,FWVER=UDR 1.21*41
0000151008 [app.gps.nmea] TRACE: RX: $GNTXT,01,01,02,PROTVER=19.20*12
0000151014 [app.gps.nmea] TRACE: RX: $GNTXT,01,01,02,MOD=NEO-M8U-0*7C
0000151020 [app.gps.nmea] TRACE: RX: $GNTXT,01,01,02,FIS=0xEF4015 (200056)*59
0000151029 [app.gps.nmea] TRACE: RX: $GNTXT,01,01,02,GPS;GLO;GAL;BDS*77
0000151035 [app.gps.nmea] TRACE: RX: $GNTXT,01,01,02,SBAS;IMES;QZSS*49
0000151040 [app.gps.nmea] TRACE: RX: $GNTXT,01,01,02,GNSS OTP=GPS;GLO*37
0000151047 [app.gps.nmea] TRACE: RX: $GNTXT,01,01,02,LLC=FFFFFFFF-FFFFFFFF-FFFFFFFF-5FFFFBFE-FFFFFF49*54
0000151057 [app.gps.nmea] TRACE: RX: $GNTXT,01,01,02,ANTSUPERV=AC *00
0000151063 [app.gps.nmea] TRACE: RX: $GNTXT,01,01,02,ANTSTATUS=DONTKNOW*2D
0000151068 [app.gps.nmea] TRACE: RX: $GNTXT,01,01,02,PF=3BF*4F
0000151074 [app.gps.nmea] TRACE: RX: $GNRMC,,V,,,,,,,,,,N*4D
0000151079 [app.gps.nmea] TRACE: RX: $GNVTG,,,,,,,,,N*2E
0000151085 [app.gps.nmea] TRACE: RX: $GNGGA,,,,,,0,00,99.99,,,,,,*56
0000151091 [app.gps.nmea] TRACE: RX: $GNGSA,A,1,,,,,,,,,,,,,99.99,99.99,99.99*2E
0000151100 [app.gps.nmea] TRACE: RX: $GNGSA,A,1,,,,,,,,,,,,,99.99,99.99,99.99*2E
0000151104 [app.gps.nmea] TRACE: RX: $GPGSV,1,1,00*79
0000151109 [app.gps.nmea] TRACE: RX: $GLGSV,1,1,00*65
0000151115 [app.gps.nmea] TRACE: RX: $GNGLL,,,,,,V,N*7A
0000151119 [app.gps.ubx] TRACE: TX:

Looks like it wakes up pretty much immediately

peergum · April 11, 2022, 9:20pm

OK… not sure what changed… it went to sleep eventually, then I sent a cmd from the console and it woke up…

peergum · April 12, 2022, 3:47pm

OK, I don’t think my problem is solved, it worked above once, but then it hasn’t… I’ll continue investigating.

Note, my device went to sleep and woke up fine from the network function call, but that was after I had updated the json configuration for the device with the default for v17 (handling geofencing), then I realized sleep option was disabled. I reenabled it (why would it go to sleep if option is disabled?) and then it didn’t work anymore. Starting to wonder if it was such a good idea to base my FW on the tracker-edge that eventually works differently from ours, esp. regarding sleep…

peergum · April 18, 2022, 5:56pm

Found the cause: there is a stopModem() call line 325 of tracker_sleep.cpp that just kills the modem, independently of the network sleep mode… Just got rid of it, and device goes to sleep nicely, and I can wake it up with a console function.

eberseth · April 19, 2022, 1:43am

Hi @peergum, I’ll get this scheduled for a fix in Tracker Edge.

system · May 19, 2022, 11:44am

This topic was automatically closed 30 days after the last reply. New replies are no longer allowed.

Topic		Replies	Views
Sleep with modem connected Edge Systems	1	581	December 16, 2020
How to put the Tracker one to sleep immediately? and what is the right way to handle wakeup properly? Edge Systems	4	687	January 20, 2024
Tracker Edge version 10 with sleep has been released! Edge Systems tracker	2	773	December 16, 2020
Tracker - Wake for CAN interrupt ignored Edge Systems tracker , tracker-som , tracker-edge	1	212	January 4, 2024
Initiate Sleep for Tracker SoM Edge Systems tracker	1	593	May 14, 2021

Tracker Edge wakeFor network issue

Related topics