[Solved] Mongoose Timers Overwrite each other

bblanke · September 23, 2019, 1:09am

If you are asking a question, please follow this template:

My goal is: Make it so that timers won’t overwrite already executing timers.
My actions are: I’ve reproduced the behavior in a repository located here:
https://github.com/bblanke/mongoose_timer_test
The result I see is: When setting/clearing timers consecutively, a new timer will be calloc’d (through the mongoose os sdk)–overwriting an existing timer.
My expectation & question is:

Here’s an output from my log file:

[Sep 22 20:24:41.838] Timer.cpp:5             Intializing timer
[Sep 22 20:24:41.838] Timer.cpp:5             Intializing timer
[Sep 22 20:24:41.844] Timer.cpp:5             Intializing timer
[Sep 22 20:24:41.850] Timer.cpp:5             Intializing timer
[Sep 22 20:24:41.850] Timer.cpp:5             Intializing timer
[Sep 22 20:24:41.855] Timer.cpp:5             Intializing timer
[Sep 22 20:24:41.861] Timer.cpp:5             Intializing timer
[Sep 22 20:24:41.861] Timer.cpp:5             Intializing timer
[Sep 22 20:24:41.867] Timer.cpp:5             Intializing timer
[Sep 22 20:24:41.873] Timer.cpp:5             Intializing timer
[Sep 22 20:24:41.873] Timer.cpp:5             Intializing timer
[Sep 22 20:24:41.879] Timer.cpp:5             Intializing timer
[Sep 22 20:24:41.885] Timer.cpp:5             Intializing timer
[Sep 22 20:24:41.885] Timer.cpp:5             Intializing timer
[Sep 22 20:24:41.890] Timer.cpp:5             Intializing timer
[Sep 22 20:24:41.896] Timer.cpp:5             Intializing timer
[Sep 22 20:24:41.896] MongooseTimerID.hpp:16  Changing timer id from 0 to 1073615372
[Sep 22 20:24:41.902] MongooseTimer.cpp:36    ALLOC: 1073615372
[Sep 22 20:24:41.908] mgos_init.c:36          Init done, RAM: 232696 total, 126432 free, 126404 min free
[Sep 22 20:24:41.914] mgos_ota_core.c:1308    UID: 0f6f29f2e63e2670, license: none
[Sep 22 20:24:41.924] esp32_bt_gap.c:100      BT device name esp32_37D9A8, addr 84:0d:8e:37:d9:aa,1
[Sep 22 20:24:41.935] esp32_bt_gap.c:280      BLE advertising started
[Sep 22 20:24:41.941] esp32_bt_gatts.c:394    Starting BT service 5f6d4f53-5f44-4247-5f53-56435f49445f
[Sep 22 20:24:41.947] esp32_bt_gatts.c:394    Starting BT service 5f6d4f53-5f52-5043-5f53-56435f49445f
[Sep 22 20:24:41.953] mgos_mongoose.c:66      New heap free LWM: 125400
[Sep 22 20:24:47.956] mgos_mongoose.c:66      New heap free LWM: 124576
[Sep 22 20:24:51.902] MongooseTimer.cpp:9     Firing callback for timer with id: 1073615372
[Sep 22 20:24:51.917] main.cpp:37             Testing:
[Sep 22 20:24:52.012] MongooseTimerID.hpp:16  Changing timer id from 0 to 1073555712
[Sep 22 20:24:52.027] MongooseTimer.cpp:36    ALLOC: 1073555712
[Sep 22 20:24:52.122] MongooseTimerID.hpp:16  Changing timer id from 0 to 1073465872
[Sep 22 20:24:52.138] MongooseTimer.cpp:36    ALLOC: 1073465872
[Sep 22 20:24:52.232] MongooseTimerID.hpp:16  Changing timer id from 0 to 1073555796
[Sep 22 20:24:52.246] MongooseTimer.cpp:36    ALLOC: 1073555796
[Sep 22 20:24:52.341] MongooseTimerID.hpp:16  Changing timer id from 0 to 1073613804
[Sep 22 20:24:52.357] MongooseTimer.cpp:36    ALLOC: 1073613804
[Sep 22 20:24:52.451] MongooseTimerID.hpp:16  Changing timer id from 0 to 1073615664
[Sep 22 20:24:52.467] MongooseTimer.cpp:36    ALLOC: 1073615664
[Sep 22 20:24:52.561] MongooseTimerID.hpp:16  Changing timer id from 0 to 1073615700
[Sep 22 20:24:52.577] MongooseTimer.cpp:36    ALLOC: 1073615700
[Sep 22 20:24:52.671] MongooseTimerID.hpp:16  Changing timer id from 0 to 1073615408
[Sep 22 20:24:52.687] MongooseTimer.cpp:36    ALLOC: 1073615408
[Sep 22 20:24:52.781] MongooseTimerID.hpp:16  Changing timer id from 0 to 1073615444
[Sep 22 20:24:52.797] MongooseTimer.cpp:36    ALLOC: 1073615444
[Sep 22 20:24:52.891] MongooseTimerID.hpp:16  Changing timer id from 0 to 1073615872
[Sep 22 20:24:52.907] MongooseTimer.cpp:36    ALLOC: 1073615872
[Sep 22 20:24:53.001] MongooseTimerID.hpp:16  Changing timer id from 0 to 1073615908
[Sep 22 20:24:53.017] MongooseTimer.cpp:36    ALLOC: 1073615908
[Sep 22 20:24:53.111] MongooseTimerID.hpp:16  Changing timer id from 0 to 1073615944
[Sep 22 20:24:53.127] MongooseTimer.cpp:36    ALLOC: 1073615944
[Sep 22 20:24:53.221] MongooseTimerID.hpp:16  Changing timer id from 0 to 1073615980
[Sep 22 20:24:53.236] MongooseTimer.cpp:36    ALLOC: 1073615980
[Sep 22 20:24:53.331] MongooseTimerID.hpp:16  Changing timer id from 0 to 1073616016
[Sep 22 20:24:53.346] MongooseTimer.cpp:36    ALLOC: 1073616016
[Sep 22 20:24:53.441] MongooseTimerID.hpp:16  Changing timer id from 0 to 1073616052
[Sep 22 20:24:53.456] MongooseTimer.cpp:36    ALLOC: 1073616052
[Sep 22 20:24:53.551] MongooseTimerID.hpp:16  Changing timer id from 0 to 1073616088
[Sep 22 20:24:53.557] MongooseTimer.cpp:36    ALLOC: 1073616088
[Sep 22 20:24:53.557] MongooseTimer.cpp:9     Firing callback for timer with id: 1073555712
[Sep 22 20:24:53.563] MongooseTimer.cpp:9     Firing callback for timer with id: 1073465872
[Sep 22 20:24:53.569] MongooseTimer.cpp:9     Firing callback for timer with id: 1073555796
[Sep 22 20:24:53.580] MongooseTimer.cpp:9     Firing callback for timer with id: 1073613804
[Sep 22 20:24:53.586] MongooseTimer.cpp:9     Firing callback for timer with id: 1073615664
[Sep 22 20:24:53.592] MongooseTimer.cpp:9     Firing callback for timer with id: 1073615700
[Sep 22 20:24:53.671] MongooseTimer.cpp:9     Firing callback for timer with id: 1073615408
[Sep 22 20:24:53.781] MongooseTimer.cpp:9     Firing callback for timer with id: 1073615444
[Sep 22 20:24:53.891] MongooseTimer.cpp:9     Firing callback for timer with id: 1073615872
[Sep 22 20:24:54.001] MongooseTimer.cpp:9     Firing callback for timer with id: 1073615908
[Sep 22 20:24:54.111] MongooseTimer.cpp:9     Firing callback for timer with id: 1073615944
[Sep 22 20:24:54.221] MongooseTimer.cpp:9     Firing callback for timer with id: 1073615980
[Sep 22 20:24:54.331] MongooseTimer.cpp:9     Firing callback for timer with id: 1073616016
[Sep 22 20:24:54.427] mgos_mongoose.c:66      New heap free LWM: 123916
[Sep 22 20:24:54.439] MongooseTimer.cpp:9     Firing callback for timer with id: 1073616052
[Sep 22 20:24:54.535] mgos_mongoose.c:66      New heap free LWM: 123632
[Sep 22 20:24:54.547] MongooseTimer.cpp:9     Firing callback for timer with id: 1073616088
[Sep 22 20:25:01.902] MongooseTimer.cpp:9     Firing callback for timer with id: 1073615372
[Sep 22 20:25:01.918] main.cpp:37             Testing:
[Sep 22 20:25:02.012] MongooseTimer.cpp:42    Stopping timer with id: 1073555712
[Sep 22 20:25:02.012] MongooseTimer.cpp:46    FREED: 1073555712
[Sep 22 20:25:02.018] MongooseTimerID.hpp:16  Changing timer id from 1073555712 to 0
[Sep 22 20:25:02.023] MongooseTimerID.hpp:16  Changing timer id from 0 to 1073465872
[Sep 22 20:25:02.029] MongooseTimer.cpp:36    ALLOC: 1073465872
[Sep 22 20:25:02.137] MongooseTimer.cpp:42    Stopping timer with id: 1073465872
[Sep 22 20:25:02.137] MongooseTimer.cpp:46    FREED: 1073465872
[Sep 22 20:25:02.143] MongooseTimerID.hpp:16  Changing timer id from 1073465872 to 0
[Sep 22 20:25:02.149] MongooseTimerID.hpp:16  Changing timer id from 0 to 1073465872
[Sep 22 20:25:02.154] MongooseTimer.cpp:36    ALLOC: 1073465872
[Sep 22 20:25:02.262] MongooseTimer.cpp:42    Stopping timer with id: 1073555796
[Sep 22 20:25:02.262] MongooseTimer.cpp:46    FREED: 1073555796
[Sep 22 20:25:02.268] MongooseTimerID.hpp:16  Changing timer id from 1073555796 to 0
[Sep 22 20:25:02.274] MongooseTimerID.hpp:16  Changing timer id from 0 to 1073555780
[Sep 22 20:25:02.279] MongooseTimer.cpp:36    ALLOC: 1073555780
[Sep 22 20:25:02.387] MongooseTimer.cpp:42    Stopping timer with id: 1073613804
[Sep 22 20:25:02.387] MongooseTimer.cpp:46    FREED: 1073613804
[Sep 22 20:25:02.393] MongooseTimerID.hpp:16  Changing timer id from 1073613804 to 0
[Sep 22 20:25:02.399] MongooseTimerID.hpp:16  Changing timer id from 0 to 1073613804
[Sep 22 20:25:02.404] MongooseTimer.cpp:36    ALLOC: 1073613804
[Sep 22 20:25:02.513] MongooseTimer.cpp:42    Stopping timer with id: 1073615664
[Sep 22 20:25:02.513] MongooseTimer.cpp:46    FREED: 1073615664
[Sep 22 20:25:02.518] MongooseTimerID.hpp:16  Changing timer id from 1073615664 to 0
[Sep 22 20:25:02.524] MongooseTimerID.hpp:16  Changing timer id from 0 to 1073615664
[Sep 22 20:25:02.530] MongooseTimer.cpp:36    ALLOC: 1073615664
[Sep 22 20:25:02.638] MongooseTimer.cpp:42    Stopping timer with id: 1073615700
[Sep 22 20:25:02.638] MongooseTimer.cpp:46    FREED: 1073615700
[Sep 22 20:25:02.643] MongooseTimerID.hpp:16  Changing timer id from 1073615700 to 0
[Sep 22 20:25:02.649] MongooseTimerID.hpp:16  Changing timer id from 0 to 1073615700
[Sep 22 20:25:02.654] MongooseTimer.cpp:36    ALLOC: 1073615700
[Sep 22 20:25:02.763] MongooseTimer.cpp:42    Stopping timer with id: 1073615408
[Sep 22 20:25:02.763] MongooseTimer.cpp:46    FREED: 1073615408
[Sep 22 20:25:02.768] MongooseTimerID.hpp:16  Changing timer id from 1073615408 to 0
[Sep 22 20:25:02.774] MongooseTimerID.hpp:16  Changing timer id from 0 to 1073615408
[Sep 22 20:25:02.780] MongooseTimer.cpp:36    ALLOC: 1073615408
[Sep 22 20:25:02.888] MongooseTimer.cpp:42    Stopping timer with id: 1073615444
[Sep 22 20:25:02.888] MongooseTimer.cpp:46    FREED: 1073615444
[Sep 22 20:25:02.894] MongooseTimerID.hpp:16  Changing timer id from 1073615444 to 0
[Sep 22 20:25:02.899] MongooseTimerID.hpp:16  Changing timer id from 0 to 1073615444
[Sep 22 20:25:02.905] MongooseTimer.cpp:36    ALLOC: 1073615444
[Sep 22 20:25:03.013] MongooseTimer.cpp:42    Stopping timer with id: 1073615872
[Sep 22 20:25:03.013] MongooseTimer.cpp:46    FREED: 1073615872
[Sep 22 20:25:03.019] MongooseTimerID.hpp:16  Changing timer id from 1073615872 to 0
[Sep 22 20:25:03.024] MongooseTimerID.hpp:16  Changing timer id from 0 to 1073615872
[Sep 22 20:25:03.030] MongooseTimer.cpp:36    ALLOC: 1073615872
[Sep 22 20:25:03.138] MongooseTimer.cpp:42    Stopping timer with id: 1073615908
[Sep 22 20:25:03.138] MongooseTimer.cpp:46    FREED: 1073615908
[Sep 22 20:25:03.144] MongooseTimerID.hpp:16  Changing timer id from 1073615908 to 0
[Sep 22 20:25:03.150] MongooseTimerID.hpp:16  Changing timer id from 0 to 1073615908
[Sep 22 20:25:03.155] MongooseTimer.cpp:36    ALLOC: 1073615908
[Sep 22 20:25:03.263] MongooseTimer.cpp:42    Stopping timer with id: 1073615944
[Sep 22 20:25:03.263] MongooseTimer.cpp:46    FREED: 1073615944
[Sep 22 20:25:03.269] MongooseTimerID.hpp:16  Changing timer id from 1073615944 to 0
[Sep 22 20:25:03.275] MongooseTimerID.hpp:16  Changing timer id from 0 to 1073615944
[Sep 22 20:25:03.280] MongooseTimer.cpp:36    ALLOC: 1073615944
[Sep 22 20:25:03.388] MongooseTimer.cpp:42    Stopping timer with id: 1073615980
[Sep 22 20:25:03.389] MongooseTimer.cpp:46    FREED: 1073615980
[Sep 22 20:25:03.394] MongooseTimerID.hpp:16  Changing timer id from 1073615980 to 0
[Sep 22 20:25:03.400] MongooseTimerID.hpp:16  Changing timer id from 0 to 1073615980
[Sep 22 20:25:03.406] MongooseTimer.cpp:36    ALLOC: 1073615980
[Sep 22 20:25:03.513] MongooseTimer.cpp:42    Stopping timer with id: 1073616016
[Sep 22 20:25:03.514] MongooseTimer.cpp:46    FREED: 1073616016
[Sep 22 20:25:03.519] MongooseTimerID.hpp:16  Changing timer id from 1073616016 to 0
[Sep 22 20:25:03.525] MongooseTimerID.hpp:16  Changing timer id from 0 to 1073616016
[Sep 22 20:25:03.531] MongooseTimer.cpp:36    ALLOC: 1073616016
[Sep 22 20:25:03.639] MongooseTimer.cpp:42    Stopping timer with id: 1073616052
[Sep 22 20:25:03.639] MongooseTimer.cpp:46    FREED: 1073616052
[Sep 22 20:25:03.644] MongooseTimerID.hpp:16  Changing timer id from 1073616052 to 0
[Sep 22 20:25:03.650] MongooseTimerID.hpp:16  Changing timer id from 0 to 1073616052
[Sep 22 20:25:03.656] MongooseTimer.cpp:36    ALLOC: 1073616052
[Sep 22 20:25:03.764] MongooseTimer.cpp:42    Stopping timer with id: 1073616088
[Sep 22 20:25:03.764] MongooseTimer.cpp:46    FREED: 1073616088
[Sep 22 20:25:03.769] MongooseTimerID.hpp:16  Changing timer id from 1073616088 to 0
[Sep 22 20:25:03.775] MongooseTimerID.hpp:16  Changing timer id from 0 to 1073616088
[Sep 22 20:25:03.781] MongooseTimer.cpp:36    ALLOC: 1073616088
[Sep 22 20:25:03.786] MongooseTimer.cpp:9     Firing callback for timer with id: 1073465872
[Sep 22 20:25:03.792] MongooseTimer.cpp:9     Firing callback for timer with id: 1073555780
[Sep 22 20:25:03.798] MongooseTimer.cpp:9     Firing callback for timer with id: 1073613804
[Sep 22 20:25:03.804] MongooseTimer.cpp:9     Firing callback for timer with id: 1073615664
[Sep 22 20:25:03.810] MongooseTimer.cpp:9     Firing callback for timer with id: 1073615700
[Sep 22 20:25:03.816] MongooseTimer.cpp:9     Firing callback for timer with id: 1073615408
[Sep 22 20:25:03.901] MongooseTimer.cpp:9     Firing callback for timer with id: 1073615444
[Sep 22 20:25:04.028] MongooseTimer.cpp:9     Firing callback for timer with id: 1073615872
[Sep 22 20:25:04.153] MongooseTimer.cpp:9     Firing callback for timer with id: 1073615908
[Sep 22 20:25:04.278] MongooseTimer.cpp:9     Firing callback for timer with id: 1073615944
[Sep 22 20:25:04.403] MongooseTimer.cpp:9     Firing callback for timer with id: 1073615980
[Sep 22 20:25:04.529] MongooseTimer.cpp:9     Firing callback for timer with id: 1073616016
[Sep 22 20:25:04.654] MongooseTimer.cpp:9     Firing callback for timer with id: 1073616052
[Sep 22 20:25:04.779] MongooseTimer.cpp:9     Firing callback for timer with id: 1073616088
[Sep 22 20:25:11.902] MongooseTimer.cpp:9     Firing callback for timer with id: 1073615372
[Sep 22 20:25:11.908] main.cpp:37             Testing:
[Sep 22 20:25:11.908] main.cpp:26             DID NOT FIRE ALL TIMERS LAST ROUND; 1 missing.

In this example, I’ve statically allocated 15 MongooseTimer objects (a wrapper around mgos_timer sdk).
I set these timers one after another. When one sets a timer in mongoose, they get back a mgos_timer_id, which is just a pointer to where the timer was allocated. I save this variable every time I set a timer (in the MongooseTimer class). Here’s the snippet where the error is apparent:

[Sep 22 20:25:02.012] MongooseTimer.cpp:46    FREED: 1073555712
[Sep 22 20:25:02.018] MongooseTimerID.hpp:16  Changing timer id from 1073555712 to 0
[Sep 22 20:25:02.023] MongooseTimerID.hpp:16  Changing timer id from 0 to 1073465872
[Sep 22 20:25:02.029] MongooseTimer.cpp:36    ALLOC: 1073465872
[Sep 22 20:25:02.137] MongooseTimer.cpp:42    Stopping timer with id: 1073465872
[Sep 22 20:25:02.137] MongooseTimer.cpp:46    FREED: 1073465872
[Sep 22 20:25:02.143] MongooseTimerID.hpp:16  Changing timer id from 1073465872 to 0
[Sep 22 20:25:02.149] MongooseTimerID.hpp:16  Changing timer id from 0 to 1073465872
[Sep 22 20:25:02.154] MongooseTimer.cpp:36    ALLOC: 1073465872

If my MongooseTimer class detects that it already has a running timer attached to it, it will stop the timer associated with it (tracked through its internal timer_id variable).

Notice that a timer with ID 1073555712 is stopped, then a timer with ID 1073465872 is set. This is a problem; 1073465872 is already set (see the messages above it where 1073465872 is ALLOC’d but not FREE’d beforehand), so this timer is overwritten.

I’d appreciate all help and thoughts! If this is a problem with my wrapper code, I sincerely apologize. I believe that I’ve done my due dilligence in narrowing down this problem, and I’d appreciate any thoughts anyone has!

nliviu · September 23, 2019, 4:30am

The memory allocated by a one shot timer is freed here

bblanke · September 24, 2019, 4:39am

Thank you so much; I totally missed this. Ended up solving my problem.

needlerp · July 1, 2020, 3:06pm

I’d be interested to know how you solved the problem - I’m not sure whether it’s linked but I quite regularly find that one-shot timers set in mjs fail to execute properly.