December 2019 - OvmsDev - Open Vehicles

ESP32 CAN controller hardware bug / interrupt issue
by Michael Balzer 02 Apr '21

02 Apr '21

Second finding & commit: TL;DR: * ESP32 CAN controller is broken, delivers trashed & duplicated RX frames * we need to optimize interrupt latency Users have been reporting occasional false BMS readings on the Twizy for more than a year. The error always trashed the reading of voltage #10 and/or temperature #8, so I initially thought that must be a variant of the SPIRAM/cache bug. But the SPIRAM fix didn't help, and the bug still occured with all BMS data in internal RAM. The issue correlated with high load situations and the SIMCOM UART issue. On testing the latest changes by Marko, my car module began showing that issue regularly, so I could take a closer look. It turned out the wrong data came from the CAN bus. Checking with a CAN logger didn't show any wrong data on the bus. So I scanned our CAN driver for potential issues, found & solved some (even a serious race condition) but that didn't fix it. I then added debug dumps of all frames read, dug into the SJA1000 spec sheet and found this: The SJA1000 RX FIFO has a capacity of 64 bytes. It's supposed to work as a ring buffer, with frames wrapping around as necessary. If no space is left in the FIFO for a new frame coming in, that frame should be discarded completely, not counted, just the overflow indicator should be set & the according interrupt be generated. Reality differs. The frame causing the overflow is added to the FIFO partially. It's also counted both in the RMC register and indicated by RBS as a valid frame when retrieving the FIFO contents. The read buffer delivers the partial frame + some trashed bytes up to the nominal frame length. In the BMS frame sequence it would normally trash bytes 7 & 8 on the sixth frame of length 8 in a sequence. A standard frame needs a 3 byte header + the data bytes in the FIFO, so 6 frames would add up to 66 bytes => 64 + 2 trash. The first trash byte normally is "08", the second "84" or "2a" or sometimes "ab", possibly some internal SJA1000 data. Better yet, if you rely on the indicators of the SJA1000 when reading the FIFO, the SJA1000 will repeat the first frame within the FIFO after the invalid frame. Mostly once or twice, and sometimes 7 times or more: inv_msg: framecnt=13, invindex=6 inv_msg: 55 01 00 00 07 98 50 54 54 20 00 6e | 4..?........U.....PTT .n inv_msg: 24 04 00 00 11 40 10 22 37 55 00 37 | 4..?........$....@."7U.7 inv_msg: 25 04 00 00 0a 1b 44 ff fe 4e 01 26 | 4..?........%.....D..N.& inv_msg: 54 05 00 00 37 37 37 37 37 37 37 00 | 4..?........T...7777777. inv_msg: 56 05 00 00 31 63 14 31 53 14 31 4a | 4..?........V...1c.1S.1J inv_msg: 57 05 00 00 31 43 14 31 53 15 *08 2a* | 4..?........W...1C.1S..* ^^^^^ trashed bytes … followed by 7 repetitions of the first frame: inv_msg: 55 01 00 00 07 98 50 54 54 20 00 6e | 4..?........U.....PTT .n inv_msg: 55 01 00 00 07 98 50 54 54 20 00 6e | 4..?........U.....PTT .n inv_msg: 55 01 00 00 07 98 50 54 54 20 00 6e | 4..?........U.....PTT .n inv_msg: 55 01 00 00 07 98 50 54 54 20 00 6e | 4..?........U.....PTT .n inv_msg: 55 01 00 00 07 98 50 54 54 20 00 6e | 4..?........U.....PTT .n inv_msg: 55 01 00 00 07 98 50 54 54 20 00 6e | 4..?........U.....PTT .n inv_msg: 55 01 00 00 07 98 50 54 54 20 00 6e | 4..?........U.....PTT .n If you had occasional strange false readings leading to strange effects, this may be the explanation. Note: the SJA1000 FIFO bug may need specific circumstance to occur in addition to the overflow, maybe the overflow happening on a specific byte position in the FIFO -- I haven't tried to determine that. I've tried clearing the overflow ASAP, looping on the IR indicator and looping on the RMC, the fault is always the same. The workaround I've now done is adding up the message lengths read during a FIFO run and discard all frames exceeding the 64 byte border. Not pretty, but functional. That keeps the trashed frames from being forwarded to the OVMS application level. As with the SIMCOM UART, these overflows wouldn't happen if the interrupt handler would react fast enough. It seems we've got a general interrupt latency issue. And just as with the SIMCOM I saw a reduction of overflows when allocating the CAN IRQ on core #0, another one with raising the IRQ level to 3, so that's also part of my commit. The esp-idf CAN driver apparently has the same issue even in the latest release, I'll contact the author about this or post another issue to Espressif. So our interrupt allocation is now: Task Run# Lvl ISR# Usage Source ---------------------------------------------------------------------------------------- - 0 1 0 RTC Core ETS_RTC_CORE_INTR_SOURCE esp_timer 0 1 0 RTOS esp_timer ETS_TIMER2_INTR_SOURCE ipc0 0 1 0 RTOS Scheduler Core0 ETS_FROM_CPU_INTR0_SOURCE ipc1 1 1 1 RTOS Scheduler Core1 ETS_FROM_CPU_INTR1_SOURCE main 0 1 0 RTOS Watchdog ETS_TG0_WDT_LEVEL_INTR_SOURCE OVMS Events 1 1 1 Peripherals (GPIO ISR) ETS_GPIO_INTR_SOURCE OVMS Events 1 1 1 MAX7317 (spi_nodma) ETS_SPI3_INTR_SOURCE *esp32can init 0 3 0 ESP32 CAN ETS_CAN_INTR_SOURCE** **OVMS SIMCOM 0 2 0 SIMCOM UART ETS_UART1_INTR_SOURCE* OVMS Events 1 1 1 USB console (UART) ETS_UART0_INTR_SOURCE OVMS Events 1 1 1 SD card ETS_SDIO_HOST_INTR_SOURCE ---------------------------------------------------------------------------------------- I think we need to find the source of the interrupt latency and/or find some better scheme to distribute the tasks & interrupts over the cores. I still don't know why core #1 already got an issue with just our 6 interrupts. This may be related to the SPIRAM fix adding overhead, but I've seen the FIFO overflows before applying the fix, and the CAN issue also has been present for over a year. My working hypothesis is some task/driver disabling interrupts for too often / too long, or non-IRAM ISRs getting delayed for too often / too long. And it seems this is an issue especially on core #1. Please verify & comment. Regards, Michael PS: a little side mystery: the netmanager task starts with priority 5, then gets raised to 22 (probably a mutex priority inheritance), but never gets lowered back to 5 afterwards. A FreeRTOS bug? -- Michael Balzer * Helkenberger Weg 9 * D-58256 Ennepetal Fon 02333 / 833 5735 * Handy 0176 / 206 989 26

2 11

File logging task
by Michael Balzer 04 Jul '20

04 Jul '20

Everyone, I've pushed the long due refactoring of the file logging into a dedicated task. This removes most of the delays involved in file logging, as the fsync() and log cycling now is done in the logging task and no longer blocks overall log message processing. I stumbled upon a bad thing (tm) though we need to resolve with logging: the esp-idf logging generally involves a semaphore wait of max 10 ms (!). I wasn't aware of this because I didn't look into the source before, there also is no warning about this in the esp-idf documentation (https://docs.espressif.com/projects/esp-idf/en/latest/api-reference/system/…) so I guess I'm not the only one being taken by surprise here. // Maximum time to wait for the mutex in a logging statement. #define *MAX_MUTEX_WAIT_MS 10* #define MAX_MUTEX_WAIT_TICKS ((MAX_MUTEX_WAIT_MS + portTICK_PERIOD_MS - 1) / portTICK_PERIOD_MS) … void IRAM_ATTR *esp_log_write*(esp_log_level_t level, const char* tag, const char* format, ...) { if (!s_log_mutex) { s_log_mutex = xSemaphoreCreateMutex(); } if (*xSemaphoreTake(s_log_mutex, MAX_MUTEX_WAIT_TICKS*) == pdFALSE) { return; } … That semaphore is needed to secure the log level tag cache against parallel access, so it also affects log messages of currently disabled tags and/or levels. This means we *must not* use the standard logging from timer callbacks, at no verbosity level. But we do, partially caused by my own code serving as a bad example I assume -- sorry. But I've not only found direct log calls in most vehicle timer callbacks, there also are some hidden ones from calling the framework, for example marking a notification as read can produce a log output from Cleanup() if tracing is enabled. We need to change this short to mid term. This may be the cause of those strange timer overflow issues we've seen occasionally. It also means every debug or verbose log output currently in the code involves potentially multiple semaphore waits, that's for example the case for all hex dumps logged by the SIMCOM module. Our primary option is to remove all log calls from all low level framework functions and timer callbacks. A simple & quick workaround could be to extend the ESP_LOGx macros to check if they are executed in the timer task context, if so suppress the message or call the ESP_EARLY log function instead. That will hide these log messages from the logging framework though, if using the _EARLY_ variant they only will be sent to the USB port. For a better solution I thought about adding a dedicated queue & task for the initial log submission as well. That will need quite some rework to the esp-idf (no changes for this in the current master) but would allow to continue logging as we do now. Cons: queue submission involves some overhead & RAM, printf format expansion needs to be done before the tag/level check, messages may need to be dropped if the task starves or RAM gets tight, log output to consoles will depend on a task as well. Opinions / better ideas? Regards, Michael -- Michael Balzer * Helkenberger Weg 9 * D-58256 Ennepetal Fon 02333 / 833 5735 * Handy 0176 / 206 989 26

2 5

WifiConsole V1.0
by Michael Balzer 04 Mar '20

04 Mar '20

FYI: I've just implemented an OVMS v3 style replacement for the SimpleConsole: https://github.com/dexterbg/WifiConsole V3 makes it pretty easy now to add stuff like this. It's using a script plugin to provide custom functions via the web API. Regards, Michael -- Michael Balzer * Helkenberger Weg 9 * D-58256 Ennepetal Fon 02333 / 833 5735 * Handy 0176 / 206 989 26

5 28

Cannot reset simcom stuck in PoweringOn state without removing module power
by Craig Leres 02 Feb '20

02 Feb '20

Maybe this has been discussed and I missed it but occasionally I'll get a module with the modem/simcom stuck in the PoweringOn state. Rebooting does not fix this. I thought I saw that you could reset the simcom with: power simcom off [wait a minute] power simcom on but that doesn't work. I turned up some logging: log monitor log level verbose simcom and I see this happen about every 30 seconds: I (2204129) simcom: State timeout, transition to 2 I (2204129) simcom: State: Enter PoweringOn state I (2204129) simcom: Power Cycle I thought this level of logging would let me see the results of command like: simcom muxtx 3 at+csq (signal quality) but I don't see anything after sending it. Is there a way to hardware reset the simcom? (Is there any reason this doesn't happen when the ovms module reboots?) Craig

4 23

Scripting - missing integrations
by Mark Webb-Johnson 10 Jan '20

10 Jan '20

Michael’s work has brought up an issue that we seem to be missing some javascript integrations. We have: OvmsCommand OvmsLocation OvmsMetrics OvmsVehicle PubSub (to ovms events) Obvious ones missing are: OvmsConfig OvmsWebServer I can do OvmsConfig, but one question: Do we allow scripts access to protected config values? I think not (as that would void the entire protection system with a ’script eval JSON.print(…)', but is a limitation). Comments? It would be interesting to see scripts extend the OvmsWebServer, so urls could be mapped to scripts - but not sure of the practical use of that vs plugins. Regards, Mark.

2 3

Scripting: Duktape update to version 2.5.0
by Craig Leres 03 Jan '20

03 Jan '20

Hum... I haven't tried to build for a week or so and am now getting a error from the new duktape: ice 840 % gmake Toolchain path: /home/ice/u0/leres/bin/xtensa-esp32-elf-gcc Toolchain version: crosstool-ng-1.22.0-80-g6c4433a5 Compiler version: 5.2.0 Python requirements from /home/ice/u0/leres/esp/openvehicles-xtensa-esp32-elf/requirements.txt are satisfied. App "ovms3" version: 3.2.008-34-gd1a0e982-dirty CC /home/ice/u0/leres/src/Open-Vehicle-Monitoring-System-3/vehicle/OVMS.V3/build/duktape/src/duktape.o duk_js_call.c: In function 'duk__handle_call_raw': duk_js_call.c:2268:32: error: 'func' may be used uninitialized in this function [-Werror=maybe-uninitialized] cc1: some warnings being treated as errors gmake[1]: *** [/home/ice/u0/leres/esp/openvehicles-xtensa-esp32-elf/make/component_wrapper.mk:290: src/duktape.o] Error 1 gmake: *** [/home/ice/u0/leres/esp/esp-idf/make/project.mk:552: component-duktape-build] Error 2 I looked at the code and don't see the problem: /* XXX: native funcptr could come out of call setup. */ if (func) { rc = ((duk_hnatfunc *) func)->func(thr); // 2268 } else { duk_tval *tv_func; My guess is my toolchain is too old? I'm using 1.22.0-80-g6c4433a5. Looking here: https://github.com/espressif/crosstool-NG Should I switch to the esp-1.23.x branch? Or am I just SOL because you're all using a binary release toolchain and espressif hasn't released the source to the crosstool-NG they're using to build it? Craig

2 7

Scripting HTTP API
by Michael Balzer 31 Dec '19

31 Dec '19

I've pushed a first implementation of a HTTP API for our scripting engine (only Duktape to be precise). https://docs.openvehicles.com/en/latest/userguide/scripting.html#http Regards, Michael -- Michael Balzer * Helkenberger Weg 9 * D-58256 Ennepetal Fon 02333 / 833 5735 * Handy 0176 / 206 989 26

2 2

Electrified Garage
by Mark Webb-Johnson 29 Dec '19

29 Dec '19

Nice video on the Electrified Garage, with a short mention of OVMS (that they are installing) at 14:07: https://youtu.be/DvlvNS9kQeU Regards, Mark

1 0

v3 EU hardware
by Shaun Jurrens 24 Dec '19

24 Dec '19

Hi, I thought I’d treat myself to a holiday gift since I seemed to have sufficient change available and my v2 hardware needs a new SIM and changes in customs rules will make the V3 even pricier here in .no after New Year’s, but alas, neither Fasttech nor the OpenEnergy site seem to have any OVMS EU v3 hardware. I try to follow along, but any idea when the next batch of hardware is scheduled? I’m certainly out of luck this holiday season, but barring financial misfortune, I’m probably ready to make the jump whenever things get rolling again. Yada, yada, S. (via the iPad thingamajigg)

3 5

Android App 3.15.0
by Michael Balzer 22 Dec '19

22 Dec '19

I've just released version 3.15.0 of the Android App to the Play Store. History: https://github.com/openvehicles/Open-Vehicle-Android/wiki/History#version-3… * Notifications: optional filtering by current vehicle selection * Fix application context dependency of ApiService * Add vehicle label to push notification title * Drop notifications for vehicles no longer registered with the App * Revert to dismissing "connection lost" dialog also on data update * Quick vehicle changing (slide image on info page) * Fix IllegalState exceptions from startService() calls on Android >= 8 * Battery charts: fix crash on invalid highlight set number * MPAndroidChart: upgrade to v3.1.0 * 12V history: chart X axis time based (= independent of update frequency) * 12V history: omit ambient temperature if unavailable * Support leaf_carlights.png * Move car specific data tweaks from CarFragment to CarData * Add initial leaf_carlights * Added new Leaf & Leaf 2 images by Daniel Öster to selector * Add 2nd Generation LEAF images * Compress overlay images without any quality loss * Add proper overlay and map image for env200 * Compress all car images * Add LEAF 'Planet Blue' * Remove fuzzy pixels and optimize filesize APK: https://github.com/openvehicles/Open-Vehicle-Android/raw/master/release/Ope… Regards, Michael -- Michael Balzer * Helkenberger Weg 9 * D-58256 Ennepetal Fon 02333 / 833 5735 * Handy 0176 / 206 989 26

2 2