The watchdog timer is kicking in our code base and I am having trouble tracking down the cause. In a bit to try and debug the issue I disabled the WDT and now I am getting a NRF_FAULT_ID_SD_ASSERT with the PC at 0xA62.
At this point I'm stuck as to how to keep debugging the issue, are there some common tricks to use to get more info? I see a few posts with the same fault but no reference I can check for this value.
We are using the nRF5 SDK, 17.1.0 and softdevice S140 7.2.0
So after some more testing.
Our watchdog is actually feed by repeated app timer handler function (that's something that needs looking at after this issue).
What is happening is that when the buttons are pressed, we move into another state where we start another app timer based timer (idle timer). At this point the feed function isn't being called often enough - WDT timeout is 2000ms, we call the feed function every 50ms. After the idle timer is started the feed function timer isn't called again for a little over 5 seconds. For this testing I've disabled to WDT so that I can dig more into the cause.
We have checks for NRF_ERROR_NO_MEM when calling start timer, and check for != 0.
While writing this I realised that the feed function timer handler isn't be called for the length of time that the idle timer is set for.
That seems about right that the WDT got triggered and the WDT ISR handler in the MBR (Master Boot Record) is stuck looping. Have you implemented the WDT ISR on the app side?
That seems about right that the WDT got triggered and the WDT ISR handler in the MBR (Master Boot Record) is stuck looping. Have you implemented the WDT ISR on the app side?
I have, yes. I only saw the assert when I #defined out the init and enable WDT functions.
So the WDT was doing its job, what I need to fix now is the repeated timer waiting(?) until the new timer has run. I receive a success back when starting the new timer but it causes the existing repeated timer to not fire until the new timer expires. I'm not sure how to start debugging this issue.
For clarity, when I disable the WDT for debugging purposes:
Repeated 50ms app timer started
50ms timer firing away
specific button sequence
starts idle timer for n seconds
50ms timer now does not fire (this is where the WDT kicks in if enabled)
idle time expires
50ms timer starts firing again
TomDavies said:50ms timer now does not fire (this is where the WDT kicks in if enabled)
I think this is the key area of debugging you need to focus now. When it reaches to this state in your application, then pause the debugger and look into the timer registers and see if everything is configured right and if the interrupts are enabled. Other thing to see if this interrupt is being enabled in NVIC using NVIC_GetEnableIRQ and see if this is masked in ARM NVIC level. If there is anything that does not look normal/disabled/masked then you need to find out where exactly that happened. This will be tedious debugging session unfortunately.
Thanks Susheel, I'm going to start digging into that now.
Given this is an app timer, rather than hardware (I need to read up more to get a better understanding) given this is based on the RTC, I don't think what you've described is applicable, that would be if it were a hardware based timer? Please correct me if I'm wrong.
If based on the RTC, where/what can go wrong with the app based timers?
TomDavies said:given this is based on the RTC, I don't think what you've described is applicable
Hmm, Not sure what you mean. You can still read the RTC registers in the debugger and read NVIC register values from the memory read viewer or nrfjprog. The app_timer is based on RTC1 in nRF5SDK. So if your timer callbacks are not being called, we first try to make sure that the source of the interrupts are configured correctly and the interrupts are being fired. If the ISR is being called, then the issue might be something in the callback mechanism. But to reach to that point you need to have some low level checks to see if something else might have not masked the interrupts. If you think that we do not need to dive this deep and you first want to check if the issue is with the callback mechanism, then that is your debugging direction which is one way to do it.
Sorry, I got the wrong end of the stick - when I read timer registers I thought you were talking about the hardware timers.
I did capture some logs yesterday, after enabling logging for app_timer2.c. I haven't had a chance to properly digest them yet but this is what I'm seeing:
00> [00:14:45.088,562] <info> sc_code: $ 00> [00:14:45.088,684] <debug> app_timer: Activating timer (CC:81610312/04DD4648). 00> [00:14:45.088,684] <debug> app_timer: Setting CC to 0x00DD4648 (err: 0) 00> [00:14:45.098,144] <debug> app_timer: Compare EVT 00> [00:14:45.098,144] <debug> app_timer: Timer expired (context: 0) 00> [00:14:45.098,205] <debug> app_timer: Start request (expiring at 81610640/0x04DD4790). 00> [00:14:45.098,266] <debug> app_timer: Activating timer (CC:81610640/04DD4790). 00> [00:14:45.098,266] <debug> app_timer: Setting CC to 0x00DD4790 (err: 0) 00> [00:14:45.118,164] <debug> app_timer: Compare EVT 00> [00:14:45.118,164] <debug> app_timer: Timer expired (context: 0) 00> [00:14:45.118,225] <debug> app_timer: Start request (expiring at 81610968/0x04DD48D8). 00> [00:14:45.118,286] <debug> app_timer: Activating timer (CC:81610968/04DD48D8). 00> [00:14:45.118,286] <debug> app_timer: Setting CC to 0x00DD48D8 (err: 0) 00> [00:14:45.138,183] <debug> app_timer: Compare EVT 00> [00:14:45.138,183] <debug> app_timer: Timer expired (context: 0) 00> [00:14:45.138,244] <debug> app_timer: Start request (expiring at 81611296/0x04DD4A20). 00> [00:14:45.138,305] <debug> app_timer: Activating timer (CC:81610974/04DD48DE). 00> [00:14:45.138,305] <debug> app_timer: Setting CC to 0x00DD48DE (err: 0) 00> [00:14:45.138,549] <debug> app_timer: Compare EVT 00> [00:14:45.138,549] <debug> app_timer: Timer expired (context: 0) 00> [00:14:45.138,549] <info> sc_code: $ 00> [00:14:45.138,671] <debug> app_timer: Activating timer (CC:81611296/04DD4A20). 00> [00:14:45.138,671] <debug> app_timer: Setting CC to 0x00DD4A20 (err: 0) 00> [00:14:45.139,221] <info> rpm: CC 0 00> [00:14:45.158,203] <debug> app_timer: Compare EVT 00> [00:14:45.158,203] <debug> app_timer: Timer expired (context: 0) 00> [00:14:45.158,264] <debug> app_timer: Start request (expiring at 81611624/0x04DD4B68). 00> [00:14:45.158,325] <debug> app_timer: Activating timer (CC:81611624/04DD4B68). 00> [00:14:45.158,325] <debug> app_timer: Setting CC to 0x00DD4B68 (err: 0) 00> [00:14:45.178,222] <debug> app_timer: Compare EVT 00> [00:14:45.178,222] <debug> app_timer: Timer expired (context: 0) 00> [00:14:45.178,283] <debug> app_timer: Start request (expiring at 81611952/0x04DD4CB0). 00> [00:14:45.178,344] <debug> app_timer: Activating timer (CC:81611793/04DD4C11). 00> [00:14:45.178,344] <debug> app_timer: Setting CC to 0x00DD4C11 (err: 0) 00> [00:14:45.188,537] <debug> app_timer: Compare EVT 00> [00:14:45.188,537] <debug> app_timer: Timer expired (context: 0) 00> [00:14:45.188,537] <info> sc_code: $ 00> [00:14:45.188,659] <debug> app_timer: Activating timer (CC:81611952/04DD4CB0). 00> [00:14:45.188,659] <debug> app_timer: Setting CC to 0x00DD4CB0 (err: 0) 00> [00:14:45.198,242] <debug> app_timer: Compare EVT 00> [00:14:45.198,242] <debug> app_timer: Timer expired (context: 0) 00> [00:14:45.198,303] <debug> app_timer: Start request (expiring at 81612280/0x04DD4DF8). 00> [00:14:45.198,364] <debug> app_timer: Activating timer (CC:81612107/04DD4D4B). 00> [00:14:45.198,364] <debug> app_timer: Setting CC to 0x00DD4D4B (err: 0) 00> [00:14:45.207,702] <debug> app_timer: Compare EVT 00> [00:14:45.207,702] <debug> app_timer: Timer expired (context: 0) 00> [00:14:45.207,763] <debug> app_timer: Activating timer (CC:81612280/04DD4DF8). 00> [00:14:45.207,763] <debug> app_timer: Setting CC to 0x00DD4DF8 (err: 0) 00> [00:14:45.218,261] <debug> app_timer: Compare EVT 00> [00:14:45.218,261] <debug> app_timer: Timer expired (context: 0) 00> [00:14:45.218,322] <debug> app_timer: Start request (expiring at 81612608/0x04DD4F40). 00> [00:14:45.218,383] <debug> app_timer: Activating timer (CC:81612599/04DD4F37). 00> [00:14:45.218,383] <debug> app_timer: Setting CC to 0x00DD4F37 (err: 0) 00> [00:14:45.237,731] <debug> app_timer: Compare EVT 00> [00:14:45.237,731] <debug> app_timer: Timer expired (context: 0) 00> [00:14:45.237,792] <debug> app_timer: Activating timer (CC:81612608/04DD4F40). 00> [00:14:45.237,792] <debug> app_timer: Setting CC to 0x00DD4F40 (err: 0) 00> [00:14:45.238,281] <debug> app_timer: Compare EVT 00> [00:14:45.238,281] <debug> app_timer: Timer expired (context: 0) 00> [00:14:45.238,342] <debug> app_timer: Start request (expiring at 81612936/0x04DD5088). 00> [00:14:45.238,403] <debug> app_timer: Activating timer (CC:81612612/04DD4F44). 00> [00:14:45.238,403] <debug> app_timer: Setting CC to 0x00DD4F44 (err: 0) 00> [00:14:45.238,525] <debug> app_timer: Compare EVT 00> [00:14:45.238,525] <debug> app_timer: Timer expired (context: 0) 00> [00:14:45.238,525] <info> sc_code: $ 00> [00:14:45.238,647] <debug> app_timer: Activating timer (CC:81612936/04DD5088). 00> [00:14:45.238,647] <debug> app_timer: Setting CC to 0x00DD5088 (err: 0) 00> [00:14:45.239,257] <info> rpm: CC 0 00> [00:14:45.258,300] <debug> app_timer: Compare EVT 00> [00:14:45.258,300] <debug> app_timer: Timer expired (context: 0) 00> [00:14:45.258,361] <debug> app_timer: Start request (expiring at 81613264/0x04DD51D0). 00> [00:14:45.258,422] <debug> app_timer: Activating timer (CC:81613264/04DD51D0). 00> [00:14:45.258,422] <debug> app_timer: Setting CC to 0x00DD51D0 (err: 0) 00> [00:14:45.278,320] <debug> app_timer: Compare EVT 00> [00:14:45.278,320] <debug> app_timer: Timer expired (context: 0) 00> [00:14:45.278,381] <debug> app_timer: Start request (expiring at 81613592/0x04DD5318). 00> [00:14:45.278,442] <debug> app_timer: Activating timer (CC:81613431/04DD5277). 00> [00:14:45.278,442] <debug> app_timer: Setting CC to 0x00DD5277 (err: 0) 00> [00:14:45.288,513] <debug> app_timer: Compare EVT 00> [00:14:45.288,513] <debug> app_timer: Timer expired (context: 0) 00> [00:14:45.288,513] <info> sc_code: $ 00> [00:14:45.289,184] <debug> app_timer: Activating timer (CC:81613592/04DD5318). 00> [00:14:45.289,184] <debug> app_timer: Setting CC to 0x00DD5318 (err: 0) 00> [00:14:45.298,339] <debug> app_timer: Compare EVT 00> [00:14:45.298,339] <debug> app_timer: Timer expired (context: 0) 00> [00:14:45.298,400] <debug> app_timer: Start request (expiring at 81613920/0x04DD5460). 00> [00:14:45.298,461] <debug> app_timer: Activating timer (CC:81613920/04DD5460). 00> [00:14:45.298,461] <debug> app_timer: Setting CC to 0x00DD5460 (err: 0) 00> [00:14:45.318,359] <debug> app_timer: Compare EVT 00> [00:14:45.318,359] <debug> app_timer: Timer expired (context: 0) 00> [00:14:45.318,420] <debug> app_timer: Start request (expiring at 81614248/0x04DD55A8). 00> [00:14:45.318,481] <debug> app_timer: Activating timer (CC:81614248/04DD55A8). 00> [00:14:45.318,481] <debug> app_timer: Setting CC to 0x00DD55A8 (err: 0) 00> [00:14:45.338,378] <debug> app_timer: Compare EVT 00> [00:14:45.338,378] <debug> app_timer: Timer expired (context: 0) 00> [00:14:45.338,439] <debug> app_timer: Start request (expiring at 81614576/0x04DD56F0). 00> [00:14:45.338,500] <debug> app_timer: Activating timer (CC:81614250/04DD55AA). 00> [00:14:45.338,500] <debug> app_timer: Timer expired (context: 0) 00> [00:14:45.338,500] <info> sc_code: $ 00> [00:14:45.338,562] <debug> app_timer: Timer expired before scheduled to RTC. 00> [00:14:45.338,562] <debug> app_timer: Activating timer (CC:81614576/04DD56F0). 00> [00:14:45.338,623] <debug> app_timer: Setting CC to 0x00DD56F0 (err: 0) 00> [00:14:45.339,233] <info> rpm: CC 0 00> [00:14:45.358,398] <debug> app_timer: Compare EVT 00> [00:14:45.358,398] <debug> app_timer: Timer expired (context: 0) 00> [00:14:45.358,459] <debug> app_timer: Start request (expiring at 81614904/0x04DD5838). 00> [00:14:45.358,520] <debug> app_timer: Activating timer (CC:81614904/04DD5838). 00> [00:14:45.358,520] <debug> app_timer: Setting CC to 0x00DD5838 (err: 0) 00> [00:14:45.378,417] <debug> app_timer: Compare EVT 00> [00:14:45.378,417] <debug> app_timer: Timer expired (context: 0) 00> [00:14:45.378,479] <debug> app_timer: Start request (expiring at 81615232/0x04DD5980). 00> [00:14:45.378,540] <debug> app_timer: Activating timer (CC:81615069/04DD58DD). 00> [00:14:45.378,540] <debug> app_timer: Setting CC to 0x00DD58DD (err: 0) 00> [00:14:45.388,488] <debug> app_timer: Compare EVT 00> [00:14:45.388,488] <debug> app_timer: Timer expired (context: 0) 00> [00:14:45.388,488] <info> sc_code: $ 00> [00:14:45.388,610] <debug> app_timer: Activating timer (CC:81615232/04DD5980). 00> [00:14:45.388,610] <debug> app_timer: Setting CC to 0x00DD5980 (err: 0) 00> [00:14:45.398,437] <debug> app_timer: Compare EVT 00> [00:14:45.398,437] <debug> app_timer: Timer expired (context: 0) 00> [00:14:45.398,498] <debug> app_timer: Start request (expiring at 81615560/0x04DD5AC8). 00> [00:14:45.398,559] <debug> app_timer: Activating timer (CC:81615560/04DD5AC8). 00> [00:14:45.398,559] <debug> app_timer: Setting CC to 0x00DD5AC8 (err: 0) 00> [00:14:45.418,457] <debug> app_timer: Compare EVT 00> [00:14:45.418,457] <debug> app_timer: Timer expired (context: 0) 00> [00:14:45.418,518] <debug> app_timer: Start request (expiring at 81615888/0x04DD5C10). 00> [00:14:45.418,579] <debug> app_timer: Activating timer (CC:81615888/04DD5C10). 00> [00:14:45.418,579] <debug> app_timer: Setting CC to 0x00DD5C10 (err: 0) 00> [00:14:45.438,476] <debug> app_timer: Compare EVT 00> [00:14:45.438,476] <debug> app_timer: Timer expired (context: 0) 00> [00:14:45.438,476] <info> sc_code: $ 00> [00:14:45.438,598] <debug> app_timer: Activating timer (CC:81615888/04DD5C10). 00> [00:14:45.438,598] <debug> app_timer: Timer expired (context: 0) 00> [00:14:45.438,659] <debug> app_timer: Timer expired before scheduled to RTC. 00> [00:14:45.438,659] <debug> app_timer: Activating timer (CC:81616707/04DD5F43). 00> [00:14:45.438,720] <debug> app_timer: Setting CC to 0x00DD5F43 (err: 0) 00> [00:14:45.438,720] <debug> app_timer: Start request (expiring at 81616217/0x04DD5D59). 00> [00:14:45.438,720] <debug> app_timer: Timer preempted. 00> [00:14:45.438,781] <debug> app_timer: Activating timer (CC:81616217/04DD5D59). 00> [00:14:45.438,781] <debug> app_timer: Setting CC to 0x00DD5D59 (err: 0) 00> [00:14:45.439,208] <info> rpm: CC 0 00> [00:14:45.458,557] <debug> app_timer: Compare EVT 00> [00:14:45.458,557] <debug> app_timer: Timer expired (context: 0) 00> [00:14:45.458,618] <debug> app_timer: Start request (expiring at 81616545/0x04DD5EA1). 00> [00:14:45.458,679] <debug> app_timer: Activating timer (CC:81616545/04DD5EA1). 00> [00:14:45.458,679] <debug> app_timer: Setting CC to 0x00DD5EA1 (err: 0) 00> [00:14:45.478,576] <debug> app_timer: Compare EVT 00> [00:14:45.478,576] <debug> app_timer: Timer expired (context: 0) 00> [00:14:45.478,637] <debug> app_timer: Start request (expiring at 81616873/0x04DD5FE9). 00> [00:14:45.478,698] <debug> app_timer: Activating timer (CC:81616707/04DD5F43). 00> [00:14:45.478,698] <debug> app_timer: Setting CC to 0x00DD5F43 (err: 0) 00> [00:14:45.488,464] <debug> app_timer: Compare EVT 00> [00:14:45.488,464] <debug> app_timer: Timer expired (context: 0) 00> [00:14:45.488,464] <info> sc_code: $ 00> [00:14:45.488,586] <debug> app_timer: Activating timer (CC:81616873/04DD5FE9). 00> [00:14:45.488,586] <debug> app_timer: Setting CC to 0x00DD5FE9 (err: 0) 00> [00:14:45.498,596] <debug> app_timer: Compare EVT 00> [00:14:45.498,596] <debug> app_timer: Timer expired (context: 0) 00> [00:14:45.498,657] <debug> app_timer: Start request (expiring at 81617201/0x04DD6131). 00> [00:14:45.498,718] <debug> app_timer: Activating timer (CC:81617201/04DD6131). 00> [00:14:45.498,718] <debug> app_timer: Setting CC to 0x00DD6131 (err: 0) 00> [00:14:45.518,615] <debug> app_timer: Compare EVT 00> [00:14:45.518,615] <debug> app_timer: Timer expired (context: 0) 00> [00:14:45.518,676] <debug> app_timer: Start request (expiring at 81617529/0x04DD6279). 00> [00:14:45.518,737] <debug> app_timer: Activating timer (CC:81617526/04DD6276). 00> [00:14:45.518,737] <debug> app_timer: Setting CC to 0x00DD6276 (err: 0) 00> [00:14:45.538,452] <debug> app_timer: Compare EVT 00> [00:14:45.538,452] <debug> app_timer: Timer expired (context: 0) 00> [00:14:45.538,452] <info> sc_code: $ 00> [00:14:45.538,574] <debug> app_timer: Activating timer (CC:81617529/04DD6279). 00> [00:14:45.538,574] <debug> app_timer: Setting CC to 0x00DD6279 (err: 0) 00> [00:14:45.538,696] <debug> app_timer: Compare EVT 00> [00:14:45.538,696] <debug> app_timer: Timer expired (context: 0) 00> [00:14:45.538,757] <debug> app_timer: Start request (expiring at 81617858/0x04DD63C2). 00> [00:14:45.538,818] <debug> app_timer: Activating timer (CC:81617841/04DD63B1). 00> [00:14:45.538,818] <debug> app_timer: Setting CC to 0x00DD63B1 (err: 0) 00> [00:14:45.539,184] <info> rpm: CC 0 00> [00:14:45.557,678] <debug> app_timer: Compare EVT 00> [00:14:45.557,678] <debug> app_timer: Timer expired (context: 0) 00> [00:14:45.557,739] <debug> app_timer: Activating timer (CC:81617858/04DD63C2). 00> [00:14:45.557,739] <debug> app_timer: Setting CC to 0x00DD63C2 (err: 0) 00> [00:14:45.558,715] <debug> app_timer: Compare EVT 00> [00:14:45.558,715] <debug> app_timer: Timer expired (context: 0) 00> [00:14:45.558,776] <debug> app_timer: Start request (expiring at 81618186/0x04DD650A). 00> [00:14:45.558,837] <debug> app_timer: Activating timer (CC:81618186/04DD650A). 00> [00:14:45.558,837] <debug> app_timer: Setting CC to 0x00DD650A (err: 0) 00> [00:14:45.578,735] <debug> app_timer: Compare EVT 00> [00:14:45.578,735] <debug> app_timer: Timer expired (context: 0) 00> [00:14:45.578,796] <debug> app_timer: Start request (expiring at 81618514/0x04DD6652). 00> [00:14:45.578,857] <debug> app_timer: Activating timer (CC:81618345/04DD65A9). 00> [00:14:45.578,857] <debug> app_timer: Setting CC to 0x00DD65A9 (err: 0) 00> [00:14:45.588,439] <debug> app_timer: Compare EVT 00> [00:14:45.588,439] <debug> app_timer: Timer expired (context: 0) 00> [00:14:45.588,439] <info> sc_code: $ 00> [00:14:45.588,562] <debug> app_timer: Activating timer (CC:81618514/04DD6652). 00> [00:14:45.588,562] <debug> app_timer: Setting CC to 0x00DD6652 (err: 0) 00> [00:14:45.598,754] <debug> app_timer: Compare EVT 00> [00:14:45.598,754] <debug> app_timer: Timer expired (context: 0) 00> [00:14:45.598,815] <debug> app_timer: Start request (expiring at 81618842/0x04DD679A). 00> [00:14:45.598,876] <debug> app_timer: Activating timer (CC:81618842/04DD679A). 00> [00:14:45.598,876] <debug> app_timer: Setting CC to 0x00DD679A (err: 0) 00> [00:14:45.618,774] <debug> app_timer: Compare EVT 00> [00:14:45.618,774] <debug> app_timer: Timer expired (context: 0) 00> [00:14:45.618,835] <debug> app_timer: Start request (expiring at 81619170/0x04DD68E2). 00> [00:14:45.618,896] <debug> app_timer: Activating timer (CC:81619164/04DD68DC). 00> [00:14:45.618,896] <debug> app_timer: Setting CC to 0x00DD68DC (err: 0) 00> [00:14:45.638,427] <debug> app_timer: Compare EVT 00> [00:14:45.638,427] <debug> app_timer: Timer expired (context: 0) 00> [00:14:45.638,427] <info> sc_code: $ 00> [00:14:45.638,549] <debug> app_timer: Activating timer (CC:81619170/04DD68E2). 00> [00:14:45.638,549] <debug> app_timer: Setting CC to 0x00DD68E2 (err: 0) 00> [00:14:45.638,793] <debug> app_timer: Compare EVT 00> [00:14:45.638,793] <debug> app_timer: Timer expired (context: 0) 00> [00:14:45.638,854] <debug> app_timer: Start request (expiring at 81619498/0x04DD6A2A). 00> [00:14:45.638,916] <debug> app_timer: Activating timer (CC:81619498/04DD6A2A). 00> [00:14:45.638,916] <debug> app_timer: Setting CC to 0x00DD6A2A (err: 0) 00> [00:14:45.639,221] <info> rpm: CC 0 00> [00:14:45.658,813] <debug> app_timer: Compare EVT 00> [00:14:45.658,813] <debug> app_timer: Timer expired (context: 0) 00> [00:14:45.658,874] <debug> app_timer: Start request (expiring at 81619826/0x04DD6B72). 00> [00:14:45.658,935] <debug> app_timer: Activating timer (CC:81619826/04DD6B72). 00> [00:14:45.658,935] <debug> app_timer: Setting CC to 0x00DD6B72 (err: 0) 00> [00:14:45.678,833] <debug> app_timer: Compare EVT 00> [00:14:45.678,833] <debug> app_timer: Timer expired (context: 0) 00> [00:14:45.678,894] <debug> app_timer: Start request (expiring at 81620154/0x04DD6CBA). 00> [00:14:45.678,955] <debug> app_timer: Activating timer (CC:81619983/04DD6C0F). 00> [00:14:45.678,955] <debug> app_timer: Setting CC to 0x00DD6C0F (err: 0) 00> [00:14:45.688,415] <debug> app_timer: Compare EVT 00> [00:14:45.688,415] <debug> app_timer: Timer expired (context: 0) 00> [00:14:45.688,415] <info> sc_code: $ 00> [00:14:45.688,537] <debug> app_timer: Activating timer (CC:81620154/04DD6CBA). 00> [00:14:45.688,537] <debug> app_timer: Setting CC to 0x00DD6CBA (err: 0) 00> [00:14:45.698,852] <debug> app_timer: Compare EVT 00> [00:14:45.698,852] <debug> app_timer: Timer expired (context: 0) 00> [00:14:45.698,913] <debug> app_timer: Start request (expiring at 81620482/0x04DD6E02). 00> [00:14:45.698,974] <debug> app_timer: Activating timer (CC:81620482/04DD6E02). 00> [00:14:45.698,974] <debug> app_timer: Setting CC to 0x00DD6E02 (err: 0) 00> [00:14:45.718,872] <debug> app_timer: Compare EVT 00> [00:14:45.718,872] <debug> app_timer: Timer expired (context: 0) 00> [00:14:45.722,595] <info> buttons: Button 32 pressed 00> [00:14:45.722,595] <info> buttons: Converted to button 14 00> [00:14:45.722,656] <info> sc_code: stop_all_sm_timers 00> [00:14:45.722,656] <info> sc_code: All state timers stopped 00> [00:14:45.722,656] <info> sc_code: start_idle_timer 00> [00:14:45.722,717] <info> sc_code: Idle Timer started: 5000 ms 00> [00:14:45.722,717] <info> motor: turn_motor_off 00> [00:14:45.722,717] <info> motor: Turning motor off 00> [00:14:45.722,778] <info> motor_track: motor_track_off 00> [00:14:45.722,778] <info> valve: Turning valve off 00> [00:14:45.722,839] <info> sc_code: Idle 00> [00:14:45.722,839] <debug> app_timer: Start request (expiring at 81702465/0x04DEAE41). 00> [00:14:45.722,900] <debug> app_timer: Stop request. 00> [00:14:45.722,900] <debug> app_timer: Start request (expiring at 81620874/0x04DD6F8A). 00> [00:14:45.722,900] <debug> app_timer: Activating timer (CC:81620874/04DD6F8A). 00> [00:14:45.722,961] <debug> app_timer: Setting CC to 0x00DD6F8A (err: 0) 00> [00:14:45.742,797] <debug> app_timer: Compare EVT 00> [00:14:45.742,797] <debug> app_timer: Timer expired (context: 0) 00> [00:14:45.742,858] <debug> app_timer: Start request (expiring at 81621202/0x04DD70D2). 00> [00:14:45.742,919] <debug> app_timer: Activating timer (CC:81621202/04DD70D2). 00> [00:14:45.742,919] <debug> app_timer: Setting CC to 0x00DD70D2 (err: 0) 00> [00:14:45.762,817] <debug> app_timer: Compare EVT 00> [00:14:45.762,817] <debug> app_timer: Timer expired (context: 0) 00> [00:14:45.762,878] <debug> app_timer: Start request (expiring at 81621530/0x04DD721A). 00> [00:14:45.762,939] <debug> app_timer: Activating timer (CC:81621530/04DD721A). 00> [00:14:45.762,939] <debug> app_timer: Setting CC to 0x00DD721A (err: 0) 00> [00:14:45.782,836] <debug> app_timer: Compare EVT 00> [00:14:45.782,836] <debug> app_timer: Timer expired (context: 0) 00> [00:14:45.782,897] <debug> app_timer: Start request (expiring at 81621858/0x04DD7362). 00> [00:14:45.782,958] <debug> app_timer: Activating timer (CC:81621858/04DD7362). 00> [00:14:45.782,958] <debug> app_timer: Setting CC to 0x00DD7362 (err: 0) 00> [00:14:45.802,856] <debug> app_timer: Compare EVT 00> [00:14:45.802,856] <debug> app_timer: Timer expired (context: 0) 00> [00:14:45.802,917] <debug> app_timer: Start request (expiring at 81622186/0x04DD74AA). 00> [00:14:45.802,978] <debug> app_timer: Activating timer (CC:81622186/04DD74AA). 00> [00:14:45.802,978] <debug> app_timer: Setting CC to 0x00DD74AA (err: 0) 00> [00:14:45.822,875] <debug> app_timer: Compare EVT 00> [00:14:45.822,875] <debug> app_timer: Timer expired (context: 0) 00> [00:14:45.822,937] <debug> app_timer: Start request (expiring at 81622514/0x04DD75F2). 00> [00:14:45.822,998] <debug> app_timer: Activating timer (CC:81622514/04DD75F2). 00> [00:14:45.822,998] <debug> app_timer: Setting CC to 0x00DD75F2 (err: 0) 00> [00:14:45.842,895] <debug> app_timer: Compare EVT 00> [00:14:45.842,895] <debug> app_timer: Timer expired (context: 0) 00> [00:14:45.842,956] <debug> app_timer: Start request (expiring at 81622842/0x04DD773A). 00> [00:14:45.843,017] <debug> app_timer: Activating timer (CC:81622842/04DD773A). 00> [00:14:45.843,017] <debug> app_timer: Setting CC to 0x00DD773A (err: 0) 00> [00:14:45.862,915] <debug> app_timer: Compare EVT 00> [00:14:45.862,915] <debug> app_timer: Timer expired (context: 0) 00> [00:14:45.862,976] <debug> app_timer: Start request (expiring at 81623170/0x04DD7882). 00> [00:14:45.863,037] <debug> app_timer: Activating timer (CC:81623170/04DD7882). 00> [00:14:45.863,037] <debug> app_timer: Setting CC to 0x00DD7882 (err: 0) 00> [00:14:45.882,934] <debug> app_timer: Compare EVT 00> [00:14:45.882,934] <debug> app_timer: Timer expired (context: 0) 00> [00:14:45.882,995] <debug> app_timer: Start request (expiring at 81623498/0x04DD79CA). 00> [00:14:45.883,056] <debug> app_timer: Activating timer (CC:81623498/04DD79CA). 00> [00:14:45.883,056] <debug> app_timer: Setting CC to 0x00DD79CA (err: 0) 00> [00:14:45.902,954] <debug> app_timer: Compare EVT 00> [00:14:45.902,954] <debug> app_timer: Timer expired (context: 0) 00> [00:14:45.903,015] <debug> app_timer: Start request (expiring at 81623826/0x04DD7B12). 00> [00:14:45.903,076] <debug> app_timer: Activating timer (CC:81623826/04DD7B12). 00> [00:14:45.903,076] <debug> app_timer: Setting CC to 0x00DD7B12 (err: 0) 00> [00:14:45.922,973] <debug> app_timer: Compare EVT 00> [00:14:45.922,973] <debug> app_timer: Timer expired (context: 0) 00> [00:14:45.923,034] <debug> app_timer: Start request (expiring at 81624154/0x04DD7C5A). 00> [00:14:45.923,095] <debug> app_timer: Activating timer (CC:81624154/04DD7C5A). 00> [00:14:45.923,095] <debug> app_timer: Setting CC to 0x00DD7C5A (err: 0) 00> [00:14:45.942,993] <debug> app_timer: Compare EVT 00> [00:14:45.942,993] <debug> app_timer: Timer expired (context: 0) 00> [00:14:45.943,054] <debug> app_timer: Start request (expiring at 81624482/0x04DD7DA2). 00> [00:14:45.943,115] <debug> app_timer: Activating timer (CC:81624482/04DD7DA2). 00> [00:14:45.943,115] <debug> app_timer: Setting CC to 0x00DD7DA2 (err: 0) 00> [00:14:45.963,012] <debug> app_timer: Compare EVT 00> [00:14:45.963,012] <debug> app_timer: Timer expired (context: 0) 00> [00:14:45.963,073] <debug> app_timer: Start request (expiring at 81624810/0x04DD7EEA). 00> [00:14:45.963,134] <debug> app_timer: Activating timer (CC:81624810/04DD7EEA). 00> [00:14:45.963,134] <debug> app_timer: Setting CC to 0x00DD7EEA (err: 0) 00> [00:14:45.983,032] <debug> app_timer: Compare EVT 00> [00:14:45.983,032] <debug> app_timer: Timer expired (context: 0) 00> [00:14:45.983,093] <debug> app_timer: Start request (expiring at 81625138/0x04DD8032). 00> [00:14:45.983,154] <debug> app_timer: Activating timer (CC:81625138/04DD8032). 00> [00:14:45.983,154] <debug> app_timer: Setting CC to 0x00DD8032 (err: 0) 00> [00:14:46.003,051] <debug> app_timer: Compare EVT 00> [00:14:46.003,051] <debug> app_timer: Timer expired (context: 0) 00> [00:14:46.003,112] <debug> app_timer: Start request (expiring at 81625466/0x04DD817A). 00> [00:14:46.003,173] <debug> app_timer: Activating timer (CC:81625466/04DD817A). 00> [00:14:46.003,173] <debug> app_timer: Setting CC to 0x00DD817A (err: 0) 00> [00:14:46.023,071] <debug> app_timer: Compare EVT 00> [00:14:46.023,071] <debug> app_timer: Timer expired (context: 0) 00> [00:14:46.023,132] <debug> app_timer: Start request (expiring at 81625794/0x04DD82C2). 00> [00:14:46.023,193] <debug> app_timer: Activating timer (CC:81625794/04DD82C2). 00> [00:14:46.023,193] <debug> app_timer: Setting CC to 0x00DD82C2 (err: 0) 00> [00:14:46.043,090] <debug> app_timer: Compare EVT 00> [00:14:46.043,090] <debug> app_timer: Timer expired (context: 0) 00> [00:14:46.043,151] <debug> app_timer: Start request (expiring at 81626122/0x04DD840A). 00> [00:14:46.043,212] <debug> app_timer: Activating timer (CC:81626122/04DD840A). 00> [00:14:46.043,212] <debug> app_timer: Setting CC to 0x00DD840A (err: 0) 00> [00:14:46.063,110] <debug> app_timer: Compare EVT 00> [00:14:46.063,110] <debug> app_timer: Timer expired (context: 0) 00> [00:14:46.063,171] <debug> app_timer: Start request (expiring at 81626450/0x04DD8552). 00> [00:14:46.063,232] <debug> app_timer: Activating timer (CC:81626450/04DD8552). 00> [00:14:46.063,232] <debug> app_timer: Setting CC to 0x00DD8552 (err: 0) 00> [00:14:46.083,129] <debug> app_timer: Compare EVT 00> [00:14:46.083,129] <debug> app_timer: Timer expired (context: 0) 00> [00:14:46.083,190] <debug> app_timer: Start request (expiring at 81626778/0x04DD869A). 00> [00:14:46.083,251] <debug> app_timer: Activating timer (CC:81626778/04DD869A). 00> [00:14:46.083,251] <debug> app_timer: Setting CC to 0x00DD869A (err: 0) 00> [00:14:46.103,149] <debug> app_timer: Compare EVT 00> [00:14:46.103,149] <debug> app_timer: Timer expired (context: 0) 00> [00:14:46.103,210] <debug> app_timer: Start request (expiring at 81627106/0x04DD87E2). 00> [00:14:46.103,271] <debug> app_timer: Activating timer (CC:81627106/04DD87E2). 00> [00:14:46.103,271] <debug> app_timer: Setting CC to 0x00DD87E2 (err: 0) 00> [00:14:46.123,168] <debug> app_timer: Compare EVT 00> [00:14:46.123,168] <debug> app_timer: Timer expired (context: 0) 00> [00:14:46.123,229] <debug> app_timer: Start request (expiring at 81627434/0x04DD892A). 00> [00:14:46.123,291] <debug> app_timer: Activating timer (CC:81627434/04DD892A). 00> [00:14:46.123,291] <debug> app_timer: Setting CC to 0x00DD892A (err: 0) 00> [00:14:46.143,188] <debug> app_timer: Compare EVT 00> [00:14:46.143,188] <debug> app_timer: Timer expired (context: 0) 00> [00:14:46.143,249] <debug> app_timer: Start request (expiring at 81627762/0x04DD8A72). 00> [00:14:46.143,310] <debug> app_timer: Activating timer (CC:81627762/04DD8A72). 00> [00:14:46.143,310] <debug> app_timer: Setting CC to 0x00DD8A72 (err: 0) 00> [00:14:46.163,208] <debug> app_timer: Compare EVT 00> [00:14:46.163,208] <debug> app_timer: Timer expired (context: 0) 00> [00:14:46.163,269] <debug> app_timer: Start request (expiring at 81628090/0x04DD8BBA). 00> [00:14:46.163,330] <debug> app_timer: Activating timer (CC:81628090/04DD8BBA). 00> [00:14:46.163,330] <debug> app_timer: Setting CC to 0x00DD8BBA (err: 0) 00> [00:14:46.183,227] <debug> app_timer: Compare EVT 00> [00:14:46.183,227] <debug> app_timer: Timer expired (context: 0) 00> [00:14:46.183,288] <debug> app_timer: Start request (expiring at 81628418/0x04DD8D02). 00> [00:14:46.183,349] <debug> app_timer: Activating timer (CC:81628418/04DD8D02). 00> [00:14:46.183,349] <debug> app_timer: Setting CC to 0x00DD8D02 (err: 0) 00> [00:14:46.203,247] <debug> app_timer: Compare EVT 00> [00:14:46.203,247] <debug> app_timer: Timer expired (context: 0) 00> [00:14:46.203,308] <debug> app_timer: Start request (expiring at 81628746/0x04DD8E4A). 00> [00:14:46.203,369] <debug> app_timer: Activating timer (CC:81628746/04DD8E4A). 00> [00:14:46.203,369] <debug> app_timer: Setting CC to 0x00DD8E4A (err: 0) 00> [00:14:46.223,266] <debug> app_timer: Compare EVT 00> [00:14:46.223,266] <debug> app_timer: Timer expired (context: 0) 00> [00:14:46.223,327] <debug> app_timer: Start request (expiring at 81629074/0x04DD8F92). 00> [00:14:46.223,388] <debug> app_timer: Activating timer (CC:81629074/04DD8F92). 00> [00:14:46.223,388] <debug> app_timer: Setting CC to 0x00DD8F92 (err: 0) 00> [00:14:46.243,286] <debug> app_timer: Compare EVT 00> [00:14:46.243,286] <debug> app_timer: Timer expired (context: 0) 00> [00:14:46.243,347] <debug> app_timer: Start request (expiring at 81629402/0x04DD90DA). 00> [00:14:46.243,408] <debug> app_timer: Activating timer (CC:81629402/04DD90DA). 00> [00:14:46.243,408] <debug> app_timer: Setting CC to 0x00DD90DA (err: 0) 00> [00:14:46.263,305] <debug> app_timer: Compare EVT 00> [00:14:46.263,305] <debug> app_timer: Timer expired (context: 0) 00> [00:14:46.263,366] <debug> app_timer: Start request (expiring at 81629730/0x04DD9222). 00> [00:14:46.263,427] <debug> app_timer: Activating timer (CC:81629730/04DD9222). 00> [00:14:46.263,427] <debug> app_timer: Setting CC to 0x00DD9222 (err: 0) 00> [00:14:46.283,325] <debug> app_timer: Compare EVT 00> [00:14:46.283,325] <debug> app_timer: Timer expired (context: 0) 00> [00:14:46.283,386] <debug> app_timer: Start request (expiring at 81630058/0x04DD936A). 00> [00:14:46.283,447] <debug> app_timer: Activating timer (CC:81630058/04DD936A). 00> [00:14:46.283,447] <debug> app_timer: Setting CC to 0x00DD936A (err: 0) 00> [00:14:46.303,344] <debug> app_timer: Compare EVT 00> [00:14:46.303,344] <debug> app_timer: Timer expired (context: 0) 00> [00:14:46.303,405] <debug> app_timer: Start request (expiring at 81630386/0x04DD94B2). 00> [00:14:46.303,466] <debug> app_timer: Activating timer (CC:81630386/04DD94B2). 00> [00:14:46.303,466] <debug> app_timer: Setting CC to 0x00DD94B2 (err: 0) 00> [00:14:46.323,364] <debug> app_timer: Compare EVT 00> [00:14:46.323,364] <debug> app_timer: Timer expired (context: 0) 00> [00:14:46.323,425] <debug> app_timer: Start request (expiring at 81630714/0x04DD95FA). 00> [00:14:46.323,486] <debug> app_timer: Activating timer (CC:81630714/04DD95FA). 00> [00:14:46.323,486] <debug> app_timer: Setting CC to 0x00DD95FA (err: 0) 00> [00:14:46.343,383] <debug> app_timer: Compare EVT 00> [00:14:46.343,383] <debug> app_timer: Timer expired (context: 0) 00> [00:14:46.343,444] <debug> app_timer: Start request (expiring at 81631042/0x04DD9742). 00> [00:14:46.343,505] <debug> app_timer: Activating timer (CC:81631042/04DD9742). 00> [00:14:46.343,505] <debug> app_timer: Setting CC to 0x00DD9742 (err: 0) 00> [00:14:46.363,403] <debug> app_timer: Compare EVT 00> [00:14:46.363,403] <debug> app_timer: Timer expired (context: 0) 00> [00:14:46.363,464] <debug> app_timer: Start request (expiring at 81631370/0x04DD988A). 00> [00:14:46.363,525] <debug> app_timer: Activating timer (CC:81631370/04DD988A). 00> [00:14:46.363,525] <debug> app_timer: Setting CC to 0x00DD988A (err: 0) 00> [00:14:46.383,422] <debug> app_timer: Compare EVT 00> [00:14:46.383,422] <debug> app_timer: Timer expired (context: 0) 00> [00:14:46.383,483] <debug> app_timer: Start request (expiring at 81631698/0x04DD99D2). 00> [00:14:46.383,544] <debug> app_timer: Activating timer (CC:81631698/04DD99D2). 00> [00:14:46.383,544] <debug> app_timer: Setting CC to 0x00DD99D2 (err: 0) 00> [00:14:46.403,442] <debug> app_timer: Compare EVT 00> [00:14:46.403,442] <debug> app_timer: Timer expired (context: 0) 00> [00:14:46.403,503] <debug> app_timer: Start request (expiring at 81632026/0x04DD9B1A). 00> [00:14:46.403,564] <debug> app_timer: Activating timer (CC:81632026/04DD9B1A). 00> [00:14:46.403,564] <debug> app_timer: Setting CC to 0x00DD9B1A (err: 0) 00> [00:14:46.423,461] <debug> app_timer: Compare EVT 00> [00:14:46.423,461] <debug> app_timer: Timer expired (context: 0) 00> [00:14:46.423,522] <debug> app_timer: Start request (expiring at 81632354/0x04DD9C62). 00> [00:14:46.423,583] <debug> app_timer: Activating timer (CC:81632354/04DD9C62). 00> [00:14:46.423,583] <debug> app_timer: Setting CC to 0x00DD9C62 (err: 0) 00> [00:14:46.443,481] <debug> app_timer: Compare EVT 00> [00:14:46.443,481] <debug> app_timer: Timer expired (context: 0) 00> [00:14:46.443,542] <debug> app_timer: Start request (expiring at 81632682/0x04DD9DAA). 00> [00:14:46.443,603] <debug> app_timer: Activating timer (CC:81632682/04DD9DAA). 00> [00:14:46.443,603] <debug> app_timer: Setting CC to 0x00DD9DAA (err: 0) 00> [00:14:46.463,500] <debug> app_timer: Compare EVT 00> [00:14:46.463,500] <debug> app_timer: Timer expired (context: 0) 00> [00:14:46.463,562] <debug> app_timer: Start request (expiring at 81633010/0x04DD9EF2). 00> [00:14:46.463,623] <debug> app_timer: Activating timer (CC:81633010/04DD9EF2). 00> [00:14:46.463,623] <debug> app_timer: Setting CC to 0x00DD9EF2 (err: 0) 00> [00:14:46.483,520] <debug> app_timer: Compare EVT 00> [00:14:46.483,520] <debug> app_timer: Timer expired (context: 0) 00> [00:14:46.483,581] <debug> app_timer: Start request (expiring at 81633338/0x04DDA03A). 00> [00:14:46.483,642] <debug> app_timer: Activating timer (CC:81633338/04DDA03A). 00> [00:14:46.483,642] <debug> app_timer: Setting CC to 0x00DDA03A (err: 0) 00> [00:14:46.503,540] <debug> app_timer: Compare EVT 00> [00:14:46.503,540] <debug> app_timer: Timer expired (context: 0) 00> [00:14:46.503,601] <debug> app_timer: Start request (expiring at 81633666/0x04DDA182). 00> [00:14:46.503,662] <debug> app_timer: Activating timer (CC:81633666/04DDA182). 00> [00:14:46.503,662] <debug> app_timer: Setting CC to 0x00DDA182 (err: 0) 00> [00:14:46.523,559] <debug> app_timer: Compare EVT 00> [00:14:46.523,559] <debug> app_timer: Timer expired (context: 0) 00> [00:14:46.523,620] <debug> app_timer: Start request (expiring at 81633994/0x04DDA2CA). 00> [00:14:46.523,681] <debug> app_timer: Activating timer (CC:81633994/04DDA2CA). 00> [00:14:46.523,681] <debug> app_timer: Setting CC to 0x00DDA2CA (err: 0) 00> [00:14:46.543,579] <debug> app_timer: Compare EVT 00> [00:14:46.543,579] <debug> app_timer: Timer expired (context: 0) 00> [00:14:46.543,640] <debug> app_timer: Start request (expiring at 81634322/0x04DDA412). 00> [00:14:46.543,701] <debug> app_timer: Activating timer (CC:81634322/04DDA412). 00> [00:14:46.543,701] <debug> app_timer: Setting CC to 0x00DDA412 (err: 0) 00> [00:14:46.563,598] <debug> app_timer: Compare EVT 00> [00:14:46.563,598] <debug> app_timer: Timer expired (context: 0) 00> [00:14:46.563,659] <debug> app_timer: Start request (expiring at 81634650/0x04DDA55A). 00> [00:14:46.563,720] <debug> app_timer: Activating timer (CC:81634650/04DDA55A). 00> [00:14:46.563,720] <debug> app_timer: Setting CC to 0x00DDA55A (err: 0) 00> [00:14:46.583,618] <debug> app_timer: Compare EVT 00> [00:14:46.583,618] <debug> app_timer: Timer expired (context: 0) 00> [00:14:46.583,679] <debug> app_timer: Start request (expiring at 81634978/0x04DDA6A2). 00> [00:14:46.583,740] <debug> app_timer: Activating timer (CC:81634978/04DDA6A2). 00> [00:14:46.583,740] <debug> app_timer: Setting CC to 0x00DDA6A2 (err: 0) 00> [00:14:46.603,637] <debug> app_timer: Compare EVT 00> [00:14:46.603,637] <debug> app_timer: Timer expired (context: 0) 00> [00:14:46.603,698] <debug> app_timer: Start request (expiring at 81635306/0x04DDA7EA). 00> [00:14:46.603,759] <debug> app_timer: Activating timer (CC:81635306/04DDA7EA). 00> [00:14:46.603,759] <debug> app_timer: Setting CC to 0x00DDA7EA (err: 0) 00> [00:14:46.623,657] <debug> app_timer: Compare EVT 00> [00:14:46.623,657] <debug> app_timer: Timer expired (context: 0) 00> [00:14:46.623,718] <debug> app_timer: Start request (expiring at 81635634/0x04DDA932). 00> [00:14:46.623,779] <debug> app_timer: Activating timer (CC:81635634/04DDA932). 00> [00:14:46.623,779] <debug> app_timer: Setting CC to 0x00DDA932 (err: 0) 00> [00:14:46.643,676] <debug> app_timer: Compare EVT 00> [00:14:46.643,676] <debug> app_timer: Timer expired (context: 0) 00> [00:14:46.643,737] <debug> app_timer: Start request (expiring at 81635962/0x04DDAA7A). 00> [00:14:46.643,798] <debug> app_timer: Activating timer (CC:81635962/04DDAA7A). 00> [00:14:46.643,798] <debug> app_timer: Setting CC to 0x00DDAA7A (err: 0) 00> [00:14:46.663,696] <debug> app_timer: Compare EVT 00> [00:14:46.663,696] <debug> app_timer: Timer expired (context: 0) 00> [00:14:46.663,757] <debug> app_timer: Start request (expiring at 81636290/0x04DDABC2). 00> [00:14:46.663,818] <debug> app_timer: Activating timer (CC:81636290/04DDABC2). 00> [00:14:46.663,818] <debug> app_timer: Setting CC to 0x00DDABC2 (err: 0) 00> [00:14:46.683,715] <debug> app_timer: Compare EVT 00> [00:14:46.683,715] <debug> app_timer: Timer expired (context: 0) 00> [00:14:46.683,776] <debug> app_timer: Start request (expiring at 81636618/0x04DDAD0A). 00> [00:14:46.683,837] <debug> app_timer: Activating timer (CC:81636618/04DDAD0A). 00> [00:14:46.683,837] <debug> app_timer: Setting CC to 0x00DDAD0A (err: 0) 00> [00:14:46.703,735] <debug> app_timer: Compare EVT 00> [00:14:46.703,735] <debug> app_timer: Timer expired (context: 0) 00> [00:14:46.707,580] <info> buttons: Button 36 released 00> [00:14:46.707,580] <info> buttons: Converted to button 1 00> [00:14:46.712,646] <info> buttons: Button 32 released 00> [00:14:46.712,646] <info> buttons: Converted to button 0 00> [00:14:46.712,707] <debug> app_timer: Activating timer (CC:81702465/04DEAE41). 00> [00:14:46.712,707] <debug> app_timer: Setting CC to 0x00DEAE41 (err: 0) 00> Logs dropped (1) 00> [00:14:50.742,248] <debug> app_timer: Timer expired (context: 0) 00> Logs dropped (13) 00> [00:14:50.742,248] <info> sc_code: $ 00> [00:14:50.742,309] <debug> app_timer: Timer expired before scheduled to RTC. 00> Logs dropped (11) 00> [00:14:50.742,309] <debug> app_timer: Activating timer (CC:81692055/04DE8597). 00> Logs dropped (1) 00> [00:14:50.742,370] <debug> app_timer: Timer expired (context: 0) 00> Logs dropped (13) 00> [00:14:50.742,370] <info> sc_code: $ 00> [00:14:50.742,431] <debug> app_timer: Timer expired before scheduled to RTC. 00> Logs dropped (11) 00> [00:14:50.742,492] <debug> app_timer: Activating timer (CC:81692383/04DE86DF). 00> Logs dropped (1) 00> [00:14:50.742,492] <debug> app_timer: Timer expired (context: 0) 00> Logs dropped (12) 00> [00:14:50.742,553] <debug> app_timer: Timer expired before scheduled to RTC. 00> Logs dropped (2) 00> [00:14:50.742,553] <debug> app_timer: Activating timer (CC:81692874/04DE88CA). 00> Logs dropped (9) 00> [00:14:50.742,614] <debug> app_timer: Timer expired (context: 0) 00> Logs dropped (5) 00> [00:14:50.742,614] <info> sc_code: $ 00> [00:14:50.742,675] <debug> app_timer: Timer expired before scheduled to RTC. 00> Logs dropped (16) 00> [00:14:50.742,736] <debug> app_timer: Activating timer (CC:81693693/04DE8BFD). 00> Logs dropped (1) 00> [00:14:50.742,736] <debug> app_timer: Timer expired (context: 0) 00> Logs dropped (11) 00> [00:14:50.742,797] <info> sc_code: $ 00> [00:14:50.742,858] <debug> app_timer: Timer expired before scheduled to RTC. 00> Logs dropped (12) 00> [00:14:50.742,858] <debug> app_timer: Activating timer (CC:81694512/04DE8F30). 00> Logs dropped (1) 00> [00:14:50.742,919] <debug> app_timer: Timer expired (context: 0) 00> Logs dropped (6) 00> [00:14:50.742,919] <info> sc_code: $ 00> [00:14:50.742,980] <debug> app_timer: Timer expired before scheduled to RTC. 00> Logs dropped (14) 00> [00:14:50.743,041] <debug> app_timer: Activating timer (CC:81695331/04DE9263). 00> Logs dropped (1) 00> [00:14:50.743,041] <debug> app_timer: Timer expired (context: 0) 00> Logs dropped (10) 00> [00:14:50.743,103] <info> sc_code: $ 00> [00:14:50.743,713] <debug> app_timer: Timer expired before scheduled to RTC. 00> Logs dropped (13) 00> [00:14:50.743,774] <debug> app_timer: Activating timer (CC:81696150/04DE9596). 00> Logs dropped (1) 00> [00:14:50.743,774] <debug> app_timer: Timer expired (context: 0) 00> Logs dropped (10) 00> [00:14:50.743,835] <info> sc_code: $ 00> [00:14:50.743,896] <debug> app_timer: Timer expired before scheduled to RTC. 00> Logs dropped (13) 00> [00:14:50.743,896] <debug> app_timer: Activating timer (CC:81696969/04DE98C9). 00> Logs dropped (1) 00> [00:14:50.743,957] <debug> app_timer: Timer expired (context: 0) 00> Logs dropped (10) 00> [00:14:50.743,957] <info> sc_code: $ 00> [00:14:50.744,018] <debug> app_timer: Timer expired before scheduled to RTC. 00> Logs dropped (13) 00> [00:14:50.744,079] <debug> app_timer: Activating timer (CC:81697788/04DE9BFC). 00> Logs dropped (1) 00> [00:14:50.744,079] <debug> app_timer: Timer expired (context: 0) 00> Logs dropped (10) 00> [00:14:50.744,140] <info> sc_code: $ 00> [00:14:50.744,201] <debug> app_timer: Timer expired before scheduled to RTC. 00> Logs dropped (12) 00> [00:14:50.744,201] <debug> app_timer: Activating timer (CC:81698117/04DE9D45). 00> Logs dropped (1) 00> [00:14:50.744,262] <debug> app_timer: Timer expired (context: 0) 00> Logs dropped (11) 00> [00:14:50.744,262] <debug> app_timer: Timer expired before scheduled to RTC. 00> Logs dropped (9) 00> [00:14:50.744,323] <debug> app_timer: Activating timer (CC:81698607/04DE9F2F). 00> Logs dropped (1) 00> [00:14:50.744,323] <debug> app_timer: Timer expired (context: 0) 00> Logs dropped (12) 00> [00:14:50.744,384] <info> sc_code: $ 00> [00:14:50.744,445] <debug> app_timer: Timer expired before scheduled to RTC. 00> Logs dropped (11) 00> [00:14:50.744,445] <debug> app_timer: Activating timer (CC:81699426/04DEA262). 00> Logs dropped (1) 00> [00:14:50.744,506] <debug> app_timer: Timer expired (context: 0) 00> Logs dropped (12) 00> [00:14:50.744,506] <info> sc_code: $ 00> [00:14:50.744,567] <debug> app_timer: Timer expired before scheduled to RTC. 00> Logs dropped (5) 00> [00:14:50.744,628] <debug> app_timer: Activating timer (CC:81700245/04DEA595). 00> Logs dropped (7) 00> [00:14:50.744,628] <debug> app_timer: Timer expired (context: 0) 00> Logs dropped (7) 00> [00:14:50.744,689] <info> sc_code: $ 00> [00:14:50.744,750] <debug> app_timer: Timer expired before scheduled to RTC. 00> Logs dropped (12) 00> [00:14:50.744,750] <debug> app_timer: Activating timer (CC:81701064/04DEA8C8). 00> Logs dropped (3) 00> [00:14:50.744,812] <debug> app_timer: Timer expired (context: 0) 00> Logs dropped (10) 00> [00:14:50.744,812] <info> sc_code: $ 00> [00:14:50.744,873] <debug> app_timer: Timer expired before scheduled to RTC. 00> Logs dropped (11) 00> [00:14:50.744,934] <debug> app_timer: Activating timer (CC:81701883/04DEABFB). 00> Logs dropped (3) 00> [00:14:50.744,934] <debug> app_timer: Timer expired (context: 0) 00> Logs dropped (10) 00> [00:14:50.744,995] <info> sc_code: $ 00> [00:14:50.745,056] <debug> app_timer: Timer expired before scheduled to RTC. 00> Logs dropped (10) 00> [00:14:50.745,056] <debug> app_timer: Activating timer (CC:81702702/04DEAF2E). 00> Logs dropped (3) 00> [00:14:50.745,117] <debug> app_timer: Timer expired (context: 0) 00> Logs dropped (9) 00> [00:14:50.745,117] <info> sc_code: $ 00> [00:14:50.745,178] <debug> app_timer: Timer expired before scheduled to RTC. 00> Logs dropped (12) 00> [00:14:50.745,239] <debug> app_timer: Activating timer (CC:81703521/04DEB261). 00> Logs dropped (11) 00> [00:14:50.745,239] <debug> app_timer: Setting CC to 0x00DEB261 (err: 0) 00> [00:14:50.787,170] <debug> app_timer: Compare EVT 00> [00:14:50.787,170] <debug> app_timer: Timer expired (context: 0) 00> [00:14:50.787,170] <info> sc_code: $ 00> [00:14:50.787,841] <debug> app_timer: Activating timer (CC:81703851/04DEB3AB). 00> [00:14:50.787,902] <debug> app_timer: Setting CC to 0x00DEB3AB (err: 0) 00> [00:14:50.807,312] <debug> app_timer: Compare EVT 00> [00:14:50.807,312] <debug> app_timer: Timer expired (context: 0) 00> [00:14:50.807,373] <debug> app_timer: Activating timer (CC:81704340/04DEB594). 00> [00:14:50.807,373] <debug> app_timer: Setting CC to 0x00DEB594 (err: 0) 00> [00:14:50.837,158] <debug> app_timer: Compare EVT 00> [00:14:50.837,158] <debug> app_timer: Timer expired (context: 0) 00> [00:14:50.837,158] <info> sc_code: $ 00> [00:14:50.837,280] <debug> app_timer: Activating timer (CC:81705159/04DEB8C7). 00> [00:14:50.837,280] <debug> app_timer: Setting CC to 0x00DEB8C7 (err: 0) 00> [00:14:50.887,145] <debug> app_timer: Compare EVT 00> [00:14:50.887,145] <debug> app_timer: Timer expired (context: 0) 00> [00:14:50.887,145] <info> sc_code: $ 00> [00:14:50.887,268] <debug> app_timer: Activating timer (CC:81705978/04DEBBFA). 00> [00:14:50.887,268] <debug> app_timer: Setting CC to 0x00DEBBFA (err: 0) 00> [00:14:50.937,133] <debug> app_timer: Compare EVT 00> [00:14:50.937,133] <debug> app_timer: Timer expired (context: 0) 00> [00:14:50.937,133] <info> sc_code: $ 00> [00:14:50.937,255] <debug> app_timer: Activating timer (CC:81706797/04DEBF2D). 00> [00:14:50.937,255] <debug> app_timer: Setting CC to 0x00DEBF2D (err: 0) 00> [00:14:50.987,121] <debug> app_timer: Compare EVT 00> [00:14:50.987,121] <debug> app_timer: Timer expired (context: 0) 00> [00:14:50.987,121] <info> sc_code: $ 00> [00:14:50.987,243] <debug> app_timer: Activating timer (CC:81707008/04DEC000). 00> [00:14:50.987,243] <debug> app_timer: Setting CC to 0x00DEC000 (err: 0) 00> [00:14:51.000,000] <debug> app_timer: Compare EVT 00> [00:14:51.000,000] <debug> app_timer: Timer expired (context: 0) 00> [00:14:51.000,061] <debug> app_timer: Activating timer (CC:81707616/04DEC260). 00> [00:14:51.000,061] <debug> app_timer: Setting CC to 0x00DEC260 (err: 0) 00> [00:14:51.037,109] <debug> app_timer: Compare EVT 00> [00:14:51.037,109] <debug> app_timer: Timer expired (context: 0) 00> [00:14:51.037,109] <info> sc_code: $
In the log, I am printing $ in the 50ms timer handler, this was added so I can link the log to what I'm seeing on the board - there is also an LED toggled in the handler so I can see when it isn't being called.
In the log you see it regularly until the last regular firing on line 230, timestamp 00:14:45.688,415
The button sequence is at line 240, 00:14:45.722,595 and the idle timer started at line 251, 00:14:45.722,839
There is, on line 242, 00:14:45.722,656, a call to stop all sm timers, this stops the idle, as well as a couple of other timers, but does not stop the 50ms timer. From the logs it appears as though the timer is still firing, first one after the idle transistion is a little delayed, but the callback isn't being called.
It's not until the last line of the log, 658, 00:14:51.037,109, 5 seconds later (the period for the idle timer), that the handler is called again.
