November 2019 - OvmsDev - Open Vehicles

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

03 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 03 Feb '20

03 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 11 Jan '20

11 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

3.2.006 Release to Early Access Program
by Mark Webb-Johnson 09 Dec '19

09 Dec '19

https://www.openvehicles.com/node/2346 <https://www.openvehicles.com/node/2346> Today, we are pleased to release v3.2.006 to Early Access Program. A summary of the major changes is here: 2019-11-30 MWJ 3.2.006 OTA release - Web UI: Calibration and configuration aid for 12v monitor - Log monitoring via web shell - EGPIO/MAX7317: Port input monitoring, metrics, events, documentation - Powermgmt: New automatic power management module - Scripting: OvmsMetrics.AsJSON(), OvmsEvents, and OvmsNotify added - Logging: file logging moved to dedicated task (improved performance) - SWCAN: Support for add-on SWCAN module (see https://github.com/mjuhanne/OVMS-SWCAN) - Pushover: New Pushover notification framework support - SIMCOM: Allow user to set custom SIM PIN code - Metrics: 'metric list -s' shows metric age and staleness - Others: Factory reset from web/remote shell by "module factory reset -noconfirm" - Renault Zoe: Basic Metrics and charging status added, trip notify, web config for battery capacity - Volt/Ampera: Major update (including web config, SWCAN support, etc) - Twizy: Send custom OBD2 requests, output response as hex dump - Immediate tuning metrics updates (was delegated to ticker before) For full detail on all changes, check the GitHub revision history. The v3 modules can be updated over the air (wifi), via SD CARD, or over USB - all without requiring special hardware programmers like the PICKIT used for v2. The simplest way to update the module firmware is to connect it as a client to your wifi network (or phone hotspot), and then use the web interface Config / Firmware / Flash-from-Web; that will show you the version you are running, as well as the latest version available for update. One click on 'Flash now' and the update will be downloaded and installed. Alternatively, you can download the firmware update to a file named ovms3.bin in the root directory of a FAT formatted SD CARD and insert the card into the module's slot - the new firmware will be updated automatically and the file renamed ovms3.done to signify completion. This firmware also includes the feature to check for and automatically update to newly available firmware, every night (so long as the vehicle is connected to WiFi). After updating to 3.1.005 or later, you can enable this for future firmware releases with 'config ota auto yes'. You can choose the release level by setting 'config ota tag edge | eap | main', as one of: edge: Bleeding edge developer nightly-builds eap: Early Access Program (full releases, but with little public testing) main: Publicly tested full releases (the most stable) Thank you to all the open source developers who have contributed to this, and previous, releases, and thank you for your support of the project.

2 5

Time for 3.2.006?
by Michael Balzer 09 Dec '19

09 Dec '19

Looking at the git log and changes.txt I'd say it's time to head for the next main release. The current build with the latest changes and tiT on core 1 is working very smoothly here. No crashes, CAN RX overflows are down to 0.25 per mille and SIMCOM overflows around 0.3 per mille. Espressif have announced they're incorporating the PSRAM fix into the official toolchain now, but there is no schedule for the release. Are there any open issues that need to be fixed for 3.2.006? Regards, Michael -- Michael Balzer * Helkenberger Weg 9 * D-58256 Ennepetal Fon 02333 / 833 5735 * Handy 0176 / 206 989 26

2 4

Locations and scripts
by ovms 03 Dec '19

03 Dec '19

Hi I would like to run scripts based on location. The scripts work fine, but the location service stops working. I guess the location service requires CAN1 to be working? Since CAN1 stops receiving after a short period of time, the location service also stops. Is there a way to bypass this so the location service does not depend on CAN1 working? Kind regards, Stein Arne Sordal

7 61

OpenChargeMap API https
by Michael Balzer 02 Dec '19

02 Dec '19

Mark, the OpenChargeMap API has just changed to force redirecting to the https version -- basically a good idea. That broke the Android App OCM implementation: the standard Android InputStream class conveniently opens streams from URLs, but does not follow redirects. I've changed all API URLs to https, should have done so before when https became available for OCM. Maybe the iOS reader is smarter here, but maybe you should check that. Regards, Michael -- Michael Balzer * Helkenberger Weg 9 * D-58256 Ennepetal Fon 02333 / 833 5735 * Handy 0176 / 206 989 26

2 2

Help
by Tamás Kovács 30 Nov '19

30 Nov '19

Can anybody compile my fork and send it to me, the ovms3.bin? I would like to test, because this code works well if i compiled my old computer ( i sell it), but now always crash with the new one. My fork address: https://github.com/KommyKT/Open-Vehicle-Monitoring-System-3

1 0