assert failed + reboot on Remote command

[t-huyeng]

I am running Paxcounter on a heltecv2 .
Starting paxcounter_14a60add v3.3.2 (runmode=2 / restarts=4) with espressif32@5.1.0 because espressif32@5.2.0 did not build.

If I send a Remote command to deactivate the Wifi Scanner following error occurs:

09:10:36.652 > [ 66505][I][lorawan.cpp:408] myRxCallback(): [src/lorawan.cpp] Received 2 byte(s) of payload on port 2
09:10:36.662 > [ 66505][I][rcommand.cpp:273] set_wifiscan(): [src/rcommand.cpp] Remote command: set WIFI scanner to off
09:10:36.671 >
09:10:36.672 > assert failed: xTimerGenericCommand timers.c:404 (xTimer)
09:10:36.677 >
09:10:36.677 >
09:10:36.677 > Backtrace:0x40084095:0x3ffe98f00x400968cd:0x3ffe9910 0x4009c925:0x3ffe9930 0x40099e99:0x3ffe9a60 0x400da669:0x3ffe9a90 0x400d8a36:0x3ffe9ab0 0x400d92bd:0x3ffe9b00 0x400d93e3:0x3ffe9b60 
09:10:36.693 >
09:10:36.693 >
09:10:36.694 >
09:10:36.694 >
09:10:36.694 > ELF file SHA256: 0000000000000000
09:10:36.697 >
09:10:36.697 > Rebooting...
09:10:37.231 > [    20][I][configmanager.cpp:96] loadConfig(): [src/configmanager.cpp] Loading device configuration from NVRAM...

Same happens with remote command to deactivate Bluetooth.
I was not really able to find the timers.c (only in some other folders for ESP8266) maybe this is the problem?

Overview:
Working paxcounter.conf https://gist.github.com/t-huyeng/027474c50836c37f1ebbfa4ba941418f .
Scanner BLE und WIFI 1

Not working paxcounter.conf which leads to error (see above) https://gist.github.com/t-huyeng/16fe2cd9bb217844f62e8c1e08137e52
Scanner BLE und WIFI 0

[cyberman54]

The #define BLECOUNTER / WIFICOUNTER statements in paxcounter.conf control wether the code blocks for wifi/ble are to be processed during build. They don't control the runtime default settings which can be altered by rcommands. If you change these #defines remember to clear the default settings from NVRAM from previous build, before flashing the new build:

pio run -t erase

[t-huyeng]

Yes, I am flashing the ESP but with platformio.exe run --target erase --environment usb, which should do the same. At least there is nothing running on the ESP afterwards.

Still weird to me that I can not run with BLECOUNTER / WIFICOUNTER (installation) disabled and the SLEEPCYCLE enabled. And also it is not possible to disable the COUNTERS during runtime with remote commands (error from above occurs).

[t-huyeng]

I was able to kind of get in running by disable the WIFICOUNTER before I enable a sleepcyle.

If I want to disable the WIFICOUNTER with an active sleepcyle it will through the same error.

10:52:35.301 > [ 91340][I][lorawan.cpp:408] myRxCallback(): [src/lorawan.cpp] Received 3 byte(s) of payload on port 2
10:52:35.310 > [ 91341][I][rcommand.cpp:273] set_wifiscan(): [src/rcommand.cpp] Remote command: set WIFI scanner to off
10:52:35.319 > [ 91352][I][blescan.cpp:277] stop_BLE_scan(): [bluetooth] Shutting down bluetooth scanner ...
10:52:35.327 > [ 91359][I][blescan.cpp:286] stop_BLE_scan(): [bluetooth] Bluetooth scanner stopped
10:52:35.335 > [ 91363][I][blescan.cpp:203] start_BLE_scan(): [bluetooth] Initializing bluetooth scanner ...

Maybe it has something to do with restarting the Bluetooth scanner, after setting the WIFI Scanner to off.

I am also not able to activate WiFI Scanning again if a sleep cycle on.

[t-huyeng]

Sadly it looks like I can not reproduce this every time.

[t-huyeng]

If the BLE Scanner is not activated and no sleep cycle is set the logs look like that:

09:50:20.276 > [691341][I][rcommand.cpp:273] set_wifiscan(): [src/rcommand.cpp] Remote command: set WIFI scanner to off
09:50:20.284 > [691351][I][rcommand.cpp:407] set_saveconfig(): [src/rcommand.cpp] Remote command: save config to NVRAM
09:50:20.293 > [691356][I][configmanager.cpp:69] saveConfig(): [src/configmanager.cpp] Storing settings to NVRAM...
09:50:20.302 > [691372][I][configmanager.cpp:85] saveConfig(): [src/configmanager.cpp] Device settings saved

I think there is something with the timer wrong and I will try to find more information about: assert failed: xTimerGenericCommand timers.c:404 (xTimer)

[cyberman54]

The high level logic for triggering a sleep is as follows:

• check if a sleep cycle is configured happenes after each senddata cycle (purpose is the device goes to sleep after data of a cycle is sent, not before)
• senddata is triggered either by libpax lib callback (if wifi and/or ble count is active) OR by xTimer, if libpax lib is not active (devices without wifi/ble count).

[cyberman54]

because espressif32@5.2.0 did not build.

What's the problem here, can you provide error log?

[t-huyeng]

Yes:

*** [.pio\build\usb\src\i2c.cpp.o] Error 1
In file included from ..x/.platformio/packages/framework-arduinoespressif32/cores/esp32/esp32-hal.h:79,
                 from  ..x/.platformio/packages/framework-arduinoespressif32/cores/esp32/Arduino.h:36,
                 from include/globals.h:5,
                 from include/irqhandler.h:15,
                 from src/irqhandler.cpp:1:
 ..x/.platformio/packages/framework-arduinoespressif32/cores/esp32/esp32-hal-gpio.h:29:10: fatal error: pins_arduino.h: No such file or directory

**********************************************************************
* Looking for pins_arduino.h dependency? Check our library registry!

Is the framework not really up to date on my machine?

This error occurs a few times in different files. I guess pins_arduino.h is not found. Short google did not bring up an easy solution, so I switched back to espressif32@5.1.0 which worked fine.

[t-huyeng]

@cyberman54 I tried the current master with your recent changes. But the error still exist for me with espressif32@5.2.0.

I assume espressif32@5.2.0 is working for you or am I wrong?

[t-huyeng]

I was able to build the project with espressif32@5.2.0 after I uninstalled Espressif 32 within the platformio Platforms UI (using VSCode with platformio).

I also added a workflow to test the build process see #900

[t-huyeng]

The issue still exist for me even with the new release (3.4.3).
BLECOUNTER and WIFICOUNTER are installed (in paxcounter.conf- set to 1)

The logs are here.

Board heltecv21.h

Steps:

• deleted flash on board
• uploaded new firmware
• set sleep cycle to 30 seconds with 19000321
• deactivate wifi scanner with 170021 -> error occurs

Workaround (logs):

• set sleep cycle to 0 with 19000021
• deactivate wifi scanner with 170021 -> now it works
• activate sleepcycle to 30 seconds again with 19000321

This also happens if I want to deactivate the BLE Scanner (when a sleep cycle is set)

15:38:45.797 > [ 36477][I][lorawan.cpp:408] myRxCallback(): [src/lorawan.cpp] Received 3 byte(s) of payload on port 2
15:38:45.807 > [ 36477][I][rcommand.cpp:259] set_blescan(): [src/rcommand.cpp] Remote command: set BLE scanner to off
15:38:45.815 >
15:38:45.815 > assert failed: xTimerGenericCommand timers.c:404 (xTimer)
15:38:45.820 >
15:38:45.820 >
15:38:45.820 > Backtrace:0x4008406d:0x3ffd62900x4009612d:0x3ffd62b0 0x4009c18d:0x3ffd62d0 0x40099701:0x3ffd6400 0x400d8665:0x3ffd6430 0x400d6c4a:0x3ffd6450 0x400d747d:0x3ffd64a0 0x400d75a2:0x3ffd6500 
15:38:45.836 >
15:38:45.837 >
15:38:45.837 >
15:38:45.837 >
15:38:45.837 > ELF file SHA256: 0000000000000000

Can anyone confirm this issue? I have tried multiple Heltec Boards.

[t-huyeng]

okay, thanks for trying. I will try a complete clean new set up and report back if this changes something.

[cyberman54]

One more thing, maybe it is hardware related. I saw reports on arduino timer function issues, related to older (1st) silicium versions of ESP32 chip. Maybe...

[t-huyeng]

Okay, clean set up does not seem to help. Deactivation of libpax_counter_stop(); here . Works kind of: the direct error does not occur, but I guess the logic behind everything is not working anymore and some other timer errors occur during longer runtime.

[cyberman54]

libpax lib has a unit test, which switches wifi and ble scanning on and off. Can you run this test on the Heltec board?

[t-huyeng]

Tests are working: logs & verbose logs

Really weird libpax_counter_stop() gets called during the test and works...
I will try to test the currently used fork https://github.com/cyberman54/libpax as well.

[cyberman54]

I got this. It's an RTOS timer in libpax lib which is stopped, while it does not exist. This results to a crash.

The root cause is a mix of sleep flow control in paxcounter, and behavior of libpax function libpax_counter_stop(), and, thus, can be fixed on two ways: Either in libpax code, or in paxcounter code.

The issue occurs, when remote commands arrive while the device is already in going to sleep flow control. At this time libpax_counter_stop() was already called by enter_deepsleep(), to stop libpax enqueuing payload which would lead to an endless waiting loop in enter_deepsleep(). So far not a problem. But when at this time a remote command arrives, which also calls libpax_counter_stop(), libpax crashes, because libpax_counter_stop() is not thread safe - can only be called once.

A quick fix is to make libpax_counter_stop() thread safe, by applying this easy patch in libpax_api.cpp (make a fork of libpax to try this without PR):

int libpax_counter_stop() {
  if (PaxReportTimer == NULL) {
    return -1;
  }
  wifi_sniffer_stop();
  stop_BLE_scan();
  xTimerStop(PaxReportTimer, 0);
  PaxReportTimer = NULL;
  return 0;
}

A probably more straight forward way would be to rework the flow control of enter_deepsleep(). This way also would solve the behaviour of "one more sendcycle round before going to sleep" after a sleep cycle command was send to the device.

I openend issue and PR in libpax repo.
dbinfrago/libpax#21

[t-huyeng]

Awesome! Thanks so much!
Quick test looks like it is working with this change t-huyeng/libpax@aa7b282

[cyberman54]

I applied the above libpax patch to my fork of this lib, which is currently referenced by platformio.ini (until official libpax was repaired). This should give a quick fix for all paxcounter users.

[t-huyeng]

Thank you again!