January 2020 - 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

Double updates - Normal?
by Greg D. 31 Jan '20

31 Jan '20

Hi folks, I moved my car's OVMSv3 to the Edge firmware a bit ago, and notice that every update seems to be doubled. Besides being a bit annoying, it ends up without a previous version to fall back to since both partitions end up being the same. Is this behavior normal? Can it be prevented? I'm only on Edge because of the bug in obd2ecu, and will probably move to EAP after we get an EAP build with the fix in it. Is the behavior the same there? I used to be on Main, and all seemed fine there. Thanks, Greg

5 14

Stock
by Mark Webb-Johnson 21 Jan '20

21 Jan '20

FYI: Kits and Cables are back in stock. It was tight, but the factory came through and got these done before the Chinese New Year holiday shut everything down. Fasttech have them already, and managed to fulfil outstanding orders over the weekend. They are now closed for the Chinese New Year holidays, and will resume shipping around 31st January. Shipment to OpenEnergyMonitor is on the way. They should have the stock thursday/friday this week. Regards, Mark.

1 0

xTimerCreate <10ms
by Mark Webb-Johnson 21 Jan '20

21 Jan '20

I’ve received a bug report that the Tesla Roadster vehicle module is crashing when the digital speedo option is used (with latest 3.2.008 firmware): #324 Tesla Roadster digital speedo crashing on latest firmware <https://github.com/openvehicles/Open-Vehicle-Monitoring-System-3/issues/324> Backtrace is: 0x4008b72f is in invoke_abort (esp-idf/components/esp32/panic.c:156). 0x4008b9c9 is in abort (esp-idf/components/esp32/panic.c:171). 0x40097765 is in xTimerCreate (esp-idf/components/freertos/timers.c:385). 0x4018ccaa is in OvmsVehicleTeslaRoadster::IncomingFrameCan1(CAN_frame_t*) (components/vehicle_teslaroadster/src/vehicle_teslaroadster.cpp:375). 0x4015ba95 is in OvmsVehicle::RxTask() (components/vehicle/vehicle.cpp:1138). 0x4027fee2 is in OvmsVehicleRxTask(void*) (components/vehicle/vehicle.cpp:940). and the abort is called by an assert: configASSERT( ( xTimerPeriodInTicks > 0 ) ); In our default sdkconfig configurations, we have: CONFIG_FREERTOS_HZ=100 so I think that means there are 0.1 ticks per millisecond, and setting any timer <10ms will trigger the assertion crash. I have no idea why it wasn’t a problem when this was written (a few years ago), but the crash is definitely caused by this. Maybe at some time ago we disabled abort on assertions? Anyway, reviewing the code there are a few places we use xTimerCreate and this can happen. Most are hard-coded times greater than 10ms. The remaining ones are: ovms_events.cpp in the SignalRaise function vehicle_teslaroadster.cpp in two places I changed both of these to avoid the issue (enforce ticks to be >= 1). Just beware that we can’t have timers less than 10ms with our current configuration. Regards, Mark.

1 0

Fasttech kit status "discontinued"
by Michael Balzer 15 Jan '20

15 Jan '20

Mark, Fasttech now have tagged both kits as "discontinued", and tell users this: https://www.openvehicles.com/comment/6167#comment-6167 /> "We are really sorry to write here that the item 9642829 had been discontinued and we can't find the other supplier, so it may not be in our stock again. Sorry for the inconvenience."/ Do you have any info on this? Regards, Michael -- Michael Balzer * Helkenberger Weg 9 * D-58256 Ennepetal Fon 02333 / 833 5735 * Handy 0176 / 206 989 26

2 1

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

iOS App v1.8.2
by Mark Webb-Johnson 07 Jan '20

07 Jan '20

iOS App v1.8.2 has now been approved by Apple for TestFlight beta testing. Public link is here: https://testflight.apple.com/join/05tfPlqR <https://testflight.apple.com/join/05tfPlqR> This addresses the compatibility issue with iOS 13 and APNS push notification registration. Regards, Mark.

2 4