On 9/18/21 8:28 AM, Michael Balzer wrote:
Craig,
Am 18.09.21 um 00:14 schrieb Craig Leres:
On 9/17/21 12:24 AM, Michael Balzer wrote:
Duktape still occasionally runs into the null/undefined issue with for…in: https://github.com/openvehicles/Open-Vehicle-Monitoring-System-3/issues/474#...
We need to test the revision 3 ESP32 on this.
What can I do to test this on my frankenstein v3 module?
Here's a simple test that reliably reproduces the effect on my modules:
1. Setup handler loop: script eval 'PubSub.subscribe("usr.testev", function(ev) { var ms=Number(ev.substr(11))||10; OvmsEvents.Raise("usr.testev."+ms, ms); })' 2. Start event loop with 10 ms interval: event raise usr.testev.10
The handler will keep raising the same event with the given interval. You can monitor the events by settingt log level debug on events or using the event tracing (event trace on/off), be aware 10 ms will flood your terminal/shell. Check the Duktape CPU usage to see if the loop is still running without enabling the event log.
The loop _should_ normally run indefinitely. To stop it manually, you would do: script eval 'PubSub.unsubscribe("usr.testev")'
In reality, it will abort after some random run time with a log entry like this:
E (1803740) ovms-duktape: [int/PubSub.js:1] TypeError: not object coercible| at [anon] (duk_api_stack.c:3661) internal| at hasKeys (int/PubSub.js:1) strict| at messageHasSubscribers (int/PubSub.js:1) strict| at publish (int/PubSub.js:1) strict| at [anon] (int/PubSub.js:1) strict preventsyield
…or (newly discovered today) with a heap corruption crash, which may have another cause though (investigating).
If it stops with the "TypeError", the loop should be restartable simply by repeating step 2. That proves the PubSub handler setup is still intact.
The time it needs to run into the TypeError varies widely and has some dependance on how many other handlers are registered. With no other javascript handlers registered, it normally takes 15-30 minutes on my modules to run into the error. With AuxBatMon, PwrMon & Edimax plugins enabled, it will normally happen within 5 minutes, sometimes within a few seconds.
The interval is basically irrelevant, the effect just comes faster with a short interval.
Regards, Michael
PS: btw, the effect occurs with Duktape running in the upper 2 MB as well. That doesn't prove it's not the SPIRAM bug though, it just may have other trigger conditions.
Running 3.2.016-394-ge7d9e1c1/ota_0/main, I ran your suggested script/event commands. Within ~30 seconds I tried "event trace on". But since I was on the serial console I next decided to type "event trace off" and try that on a ssh session but the module crashed with your heap crash before I could stop the output. Is it a problem if I cause the module to generate way more serial output than 115200 baud can handle? (Before I rebooted I saw that the module was again unhappy with the cell modem but I guess one problem at a time...) I ran your test commands a second time. After 3-4 minutes I tried ssh'ing in which seemed to cause another KCORRUPT HEAP crash. (I didn't collect any info from that crash. The third time I let it run for 3 hours. Then I turned trace on and back off to verify the test was still running. (Cellular registration stated up for 3 hours as well.) I will check again in the morning. Craig ======================================== [first crash] I (60262) events: Signal(usr.testev.10) I (60272) events: Signal(usr.testev.10) I (60282) events: SignCORRUPT HEAP: Bad head at 0x3f82d0c4. Expected 0xabba1234 got 0x3f82d148 abort() was called at PC 0x400844c3 on core 0 ELF file SHA256: 7c10178c2874419f Backtrace: 0x40089a2f:0x3ffcbc20 0x40089cc9:0x3ffcbc40 0x400844c3:0x3ffcbc60 0x400845dd:0x3ffcbca0 0x4011a4a3:0x3ffcbcc0 0x4010f439:0x3ffcbf80 0x4010ef89:0x3ffcbfd0 0x4008e903:0x3ffcc000 0x400840b1:0x3ffcc020 0x40084671:0x3ffcc040 0x4000bec7:0x3ffcc060 0x401b15ad:0x3ffcc080 0x400f7081:0x3ffcc0a0 0x4008d3af:0x3ffcc0c0 ======================================== ice 114 % ./backtrace.sh 0x40089a2f:0x3ffcbc20 0x40089cc9:0x3ffcbc40 0x400844c3:0x3ffcbc60 0x400845dd:0x3ffcbca0 0x4011a4a3:0x3ffcbcc0 0x4010f439:0x3ffcbf80 0x4010ef89:0x3ffcbfd0 0x4008e903:0x3ffcc000 0x400840b1:0x3ffcc020 0x40084671:0x3ffcc040 0x4000bec7:0x3ffcc060 0x401b15ad:0x3ffcc080 0x400f7081:0x3ffcc0a0 0x4008d3af:0x3ffcc0c0 + xtensa-esp32-elf-addr2line -e build/ovms3.elf 0x40089a2f:0x3ffcbc20 0x40089cc9:0x3ffcbc40 0x400844c3:0x3ffcbc60 0x400845dd:0x3ffcbca0 0x4011a4a3:0x3ffcbcc0 0x4010f439:0x3ffcbf80 0x4010ef89:0x3ffcbfd0 0x4008e903:0x3ffcc000 0x400840b1:0x3ffcc020 0x40084671:0x3ffcc040 0x4000bec7:0x3ffcc060 0x401b15ad:0x3ffcc080 0x400f7081:0x3ffcc0a0 0x4008d3af:0x3ffcc0c0 /home/ice/u0/leres/esp/openvehicles-xtensa-esp32-elf/components/esp32/panic.c:736 /home/ice/u0/leres/esp/openvehicles-xtensa-esp32-elf/components/esp32/panic.c:736 /home/ice/u0/leres/esp/openvehicles-xtensa-esp32-elf/components/newlib/locks.c:143 /home/ice/u0/leres/esp/openvehicles-xtensa-esp32-elf/components/newlib/locks.c:171 /Users/ivan/e/newlib_xtensa-2.2.0-bin/newlib_xtensa-2.2.0/xtensa-esp32-elf/newlib/libc/stdio/../../../.././newlib/libc/stdio/vfprintf.c:1699 (discriminator 8) /Users/ivan/e/newlib_xtensa-2.2.0-bin/newlib_xtensa-2.2.0/xtensa-esp32-elf/newlib/libc/stdlib/../../../.././newlib/libc/stdlib/strtod.c:428 /Users/ivan/e/newlib_xtensa-2.2.0-bin/newlib_xtensa-2.2.0/xtensa-esp32-elf/newlib/libc/string/../../../.././newlib/libc/string/strerror.c:591 /home/ice/u0/leres/esp/openvehicles-xtensa-esp32-elf/components/heap/multi_heap_poisoning.c:350 /home/ice/u0/leres/esp/openvehicles-xtensa-esp32-elf/components/heap/heap_caps.c:403 /home/ice/u0/leres/esp/openvehicles-xtensa-esp32-elf/components/newlib/syscalls.c:42 ??:0 /wrkdirs/usr/ports/devel/xtensa-esp32-elf/work/crosstool-NG-1.22.0-97-gc752ad5/.build/xtensa-esp32-elf/build/build-cc-gcc-final/xtensa-esp32-elf/libstdc++-v3/include/bits/locale_facets_nonio.tcc:1284 main/ovms_http.cpp:84 /home/ice/u0/leres/esp/openvehicles-xtensa-esp32-elf/components/freertos/timers.c:485 ======================================== ice 117 % diff sdkconfig support/sdkconfig.default.hw31 | fgrep -v CONFIG_OVMS_VEHICLE 209c209 < CONFIG_SPIRAM_CACHE_WORKAROUND= ---
CONFIG_SPIRAM_CACHE_WORKAROUND=y 665,680c665,681
683,686c684,687 ---