[Ovmsdev] Branch for-v3.3 network issues

[Craig Leres]

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#issuecomment-744005044 
>>>
>>> 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
---