search

zauberzeug / lizard

Domain-specific language to specify behaviour of microcontroller managed hardware
MIT License
15 stars 5 forks source link

ESP Reboot on Sending Bluetooth Commands with Long Lizard Startup Script #23

Closed angelom93 closed 10 months ago

angelom93 commented 11 months ago

Issue Description: When initiating the Lizard system with a startup script that is longer than usual, the ESP module seems to reboot upon receiving Bluetooth commands (abort() function is called). This issue does not occur with shorter startup scripts or when no Bluetooth commands are sent.

Expected Behavior: The ESP module should remain stable and process Bluetooth commands regardless of the length of the Lizard startup script.

Troubleshooting Attempted:

angelom93 commented 10 months ago

Example Output of the abort function:

abort() was called at PC 0x400f7d0d on core 0

Backtrace:0x40081d12:0x3ffccba00x400916b5:0x3ffccbc0 0x40096bfa:0x3ffccbe0 0x400f7d0d:0x3ffccc50 0x400f7d5d:0x3ffccc70 0x400f8821:0x3ffccc90 0x400f94e3:0x3ffccd00 0x400fe68a:0x3ffccd60 0x400fe699:0x3ffccd90 0x400dd54c:0x3ffccdc0 0x40104566:0x3ffccea0 0x40115150:0x3ffccee0 0x4011516d:0x3ffccf00 0x4011511f:0x3ffccf30 0x40115137:0x3ffccf60 0x4011c00d:0x3ffccf80 0x4011c04a:0x3ffccfb0 0x4012132a:0x3ffccff0 0x40121ba7:0x3ffcd020 0x4012244d:0x3ffcd040 0x401170ad:0x3ffcd070 0x40116f62:0x3ffcd0a0 0x40116639:0x3ffcd0d0 0x4011664b:0x3ffcd0f0 0x4011e36a:0x3ffcd110 0x4011507b:0x3ffcd130 0x40115702:0x3ffcd150 0x4011573e:0x3ffcd170 0x40094345:0x3ffcd1a0

ELF file SHA256: 3d36f5b03fab0166

Rebooting...
I (12) boot: ESP-IDF v4.4 2nd stage bootloader
I (12) boot: compile time 14:25:54
I (12) boot: chip revision: 3
I (12) boot_comm: chip revision: 3, min. bootloader chip revision: 0
I (17) boot.esp32: SPI Speed      : 40MHz
I (21) boot.esp32: SPI Mode       : DIO
I (24) boot.esp32: SPI Flash Size : 16MB
I (28) boot: Enabling RNG early entropy source...
I (32) boot: Partition Table:
I (35) boot: ## Label            Usage          Type ST Offset   Length
I (41) boot:  0 nvs              WiFi data        01 02 00009000 00006000
I (48) boot:  1 phy_init         RF data          01 01 0000f000 00001000
I (54) boot:  2 factory          factory app      00 00 00010000 00177000
I (61) boot: End of partition table
I (64) boot_comm: chip revision: 3, min. application chip revision: 0
I (70) esp_image: segment 0: paddr=00010020 vaddr=3f400020 size=4958ch (300428) map
I (187) esp_image: segment 1: paddr=000595b4 vaddr=3ffbdb60 size=04774h ( 18292) load
I (194) esp_image: segment 2: paddr=0005dd30 vaddr=40080000 size=022e8h (  8936) load
I (198) esp_image: segment 3: paddr=00060020 vaddr=400d0020 size=a3914h (669972) map
I (440) esp_image: segment 4: paddr=0010393c vaddr=400822e8 size=164e0h ( 91360) load
I (478) esp_image: segment 5: paddr=00119e24 vaddr=50000000 size=00010h (    16) load
I (491) boot: Loaded app from partition at offset 0x10000
I (491) boot: Disabling RNG early entropy source...
I (500) cpu_start: Pro cpu up.
I (501) cpu_start: Starting app cpu, entry point is 0x4008140c
I (495) cpu_start: App cpu up.
I (514) cpu_start: Pro cpu start user code
I (514) cpu_start: cpu freq: 160000000
I (514) cpu_start: Application information:
I (516) cpu_start: Project name:     lizard
I (520) cpu_start: App version:      2023-11-08 14:41 v0.1.7-15-g52e
I (526) cpu_start: Compile time:     Nov  9 2023 14:25:36
I (531) cpu_start: ELF file SHA256:  3d36f5b03fab0166...
I (536) cpu_start: ESP-IDF:          v4.4
I (540) heap_init: Initializing. RAM available for dynamic allocation:
I (546) heap_init: At 3FFAFF10 len 000000F0 (0 KiB): DRAM
I (551) heap_init: At 3FFB6388 len 00001C78 (7 KiB): DRAM
I (556) heap_init: At 3FFB9A20 len 00004108 (16 KiB): DRAM
I (561) heap_init: At 3FFCF658 len 000109A8 (66 KiB): DRAM
I (567) heap_init: At 3FFE0440 len 00003AE0 (14 KiB): D/IRAM
I (572) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM
I (577) heap_init: At 400987C8 len 00007838 (30 KiB): IRAM
I (584) spi_flash: detected chip: generic
I (586) spi_
Ready.
I (700) gpio: GPIO[15]| InputEn: 0| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0
I (700) gpio: GPIO[12]| InputEn: 0| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0
I (710) BTDM_INIT: BT controller compile version [6a07b06]
I (710) system_api: Base MAC address is not set
I (720) system_api: read default base MAC address from EFUSE
I (730) phy_init: phy_version 4670,719f9f6,Feb 18 2021,17:07:07
I (1060) esp_zeug/FrtosUtil: Task [ble_host] executing on core [PRO]
I (1100) NimBLE: GAP procedure initiated: advertise;
I (1100) NimBLE: disc_mode=2
I (1100) NimBLE:  adv_channel_map=0 own_addr_type=0 adv_filter_policy=0 adv_itvl_min=0 adv_itvl_max=0
I (1110) NimBLE:

I (1130) gpio: GPIO[25]| InputEn: 0| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0
I (1130) gpio: GPIO[14]| InputEn: 0| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0
p0:
p0:
p0:
p0:
p0:
p0:
p0:
p0:
p0:
p0:
p0:
p0:
p0:
p0:
p0:
p0:
p0:
p0:
p0:
p0:
p0:
p0:
p0:
p0:
p0:
p0:
p0:
p0:
p0:
p0:
p0:
p0:
p0:
p0:
p0:
p0:
ERROR: CHECKSUM MISMATCH (65453 vs. 173 for "p0: !tornado_ref_motor.change=0;tornado_ref_motor.lev�I (12) boot: ESP-IDF v4.4 2nd stage bootloader")
p0: !tornado_ref_motor.change=0;tornado_ref_motor.lev�I (12) boot: ESP-IDF v4.4 2nd stage bootloader
p0: I (12) boot: compile time 10:14:42
p0: I (13) boot: chip revision: 3
p0: I (13) boot_comm: chip revision: 3, min. bootloader chip revision: 0
p0: I (17) boot.esp32: SPI Speed      : 40MHz
p0: I (21) boot.esp32: SPI Mode       : DIO
p0: I (25) boot.esp32: SPI Flash Size : 16MB
p0: I (28) boot: Enabling RNG early entropy source...
p0: I (33) boot: Partition Table:
p0: I (35) boot: ## Label            Usage          Type ST Offset   Length
p0: I (42) boot:  0 nvs              WiFi data        01 02 00009000 00006000
p0: I (48) boot:  1 phy_init         RF data          01 01 0000f000 00001000
p0: I (55) boot:  2 factory          factory app      00 00 00010000 00177000
p0: I (61) boot: End of partition table
p0: I (64) boot_comm: chip revision: 3, min. application chip revision: 0
p0: I (71) esp_image: segment 0: paddr=00010020 vaddr=3f400020 size=491e4h (299492) map
p0: I (186) esp_image: segment 1: paddr=0005920c vaddr=3ffbdb60 size=04774h ( 18292) load
p0: I (194) esp_image: segment 2: paddr=0005d988 vaddr=40080000 size=02690h (  9872) load
p0: I (198) esp_image: segment 3: paddr=00060020 vaddr=400d0020 size=a2538h (664888) map
p0: I (439) esp_image: segment 4: paddr=00102560 vaddr=40082690 size=16138h ( 90424) load
p0: I (476) esp_image: segment 5: paddr=001186a0 vaddr=50000000 size=00010h (    16) load
p0: I (489) boot: Loaded app from partition at offset 0x10000
p0: I (489) boot: Disabling RNG early entropy source...
p0: I (499) cpu_start: Pro cpu up.
p0: I (499) cpu_start: Starting app cpu, entry point is 0x4008140c
p0: I (0) cpu_start: App cpu up.
p0: I (512) cpu_start: Pro cpu start user code
p0: I (512) cpu_start: cpu freq: 160000000
p0: I (512) cpu_start: Application information:
p0: I (514) cpu_start: Project name:     lizard
p0: I (518) cpu_start: App version:      2023-10-27 16:10 v0.1.7-7-gaaac
p0: I (524) cpu_start: Compile time:     Nov  6 2023 10:14:28
p0: I (529) cpu_start: ELF file SHA256:  526f949d49dcdb5d...
p0: I (534) cpu_start: ESP-IDF:          v4.4
p0: I (538) heap_init: Initializing. RAM available for dynamic allocation:
p0: I (544) heap_init: At 3FFAFF10 len 000000F0 (0 KiB): DRAM
p0: I (549) heap_init: At 3FFB6388 len 00001C78 (7 KiB): DRAM
p0: I (554) heap_init: At 3FFB9A20 len 00004108 (16 KiB): DRAM
p0: I (559) heap_init: At 3FFCF558 len 00010AA8 (66 KiB): DRAM
p0: I (565) heap_init: At 3FFE0440 len 00003AE0 (14 KiB): D/IRAM
p0: I (570) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM
p0: I (575) heap_init: At 400987C8 len 00007838 (30 KiB): IRAM
p0: I (582) spi_flash: detected chip: generic
p0: I (584) spi_f
p0: Ready.
I (1840) gpio: GPIO[5]| InputEn: 0| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0
I (1850) gpio: GPIO[4]| InputEn: 0| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0
I (1860) gpio: GPIO[13]| InputEn: 0| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0
I (1900) gpio: GPIO[22]| InputEn: 0| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0
I (1910) gpio: GPIO[12]| InputEn: 0| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0
I (1910) gpio: GPIO[25]| InputEn: 0| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0
I (1920) gpio: GPIO[34]| InputEn: 0| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0
I (1930) gpio: GPIO[35]| InputEn: 0| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0
p0: I (695) gpio: GPIO[21]| InputEn: 0| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0
p0: I (695) gpio: GPIO[19]| InputEn: 0| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0
p0: I (705) gpio: GPIO[32]| InputEn: 0| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0
p0: I (715) gpio: GPIO[5]| InputEn: 0| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0
p0: I (725) gpio: GPIO[33]| InputEn: 0| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0
p0: I (725) gpio: GPIO[4]| InputEn: 0| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0
p0: I (735) gpio: GPIO[35]| InputEn: 0| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0
p0: I (745) gpio: GPIO[18]| InputEn: 0| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0
p0: I (755) gpio: GPIO[2]| InputEn: 0| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0
p0: I (775) gpio: GPIO[15]| InputEn: 0| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0
p0: I (775) gpio: GPIO[13]| InputEn: 0| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0
error in module "p0": checksum mismatch
falkoschindler commented 10 months ago

Thanks for the bug report, @angelom93!

Using the command

echo "0x40081d0e 0x40092071 0x4009756e 0x400f7fa5 0x400f7ff5 0x400f8ab9 0x400f977b 0x400fe922 0x400fe931 0x400dd7e4 0x4010480e 0x40115378 0x40115395 0x40115347 0x4011535f 0x4011c359 0x4011c396 0x40121666 0x40121ee3 0x40122789 0x40117415 0x401172ca 0x40116995 0x401169a7 0x4011e6a6 0x401152a3 0x4011592a 0x40115966 0x40094e09" | xargs -n1 arm-none-eabi-addr2line -e lizard.elf

we could extract the stacktrace

/Users/falko/esp/esp-idf_4.4/components/esp_system/panic.c:408
/Users/falko/esp/esp-idf_4.4/components/esp_system/esp_system.c:137
/Users/falko/esp/esp-idf_4.4/components/newlib/abort.c:46
/Users/falko/Projects/lizard/main/parser.h:361
/Users/falko/Projects/lizard/main/parser.h:1719
/Users/falko/Projects/lizard/main/parser.h:1981
/Users/falko/Projects/lizard/main/parser.h:4927
/Users/falko/Projects/lizard/main/parser.h:5036
/Users/falko/Projects/lizard/main/parser.h:5003
/Users/falko/Projects/lizard/main/main.cpp:298
/Users/falko/Projects/lizard/main/modules/bluetooth.cpp:9
/Users/falko/.espressif/tools/xtensa-esp32-elf/esp-2021r2-patch5-8.4.0/xtensa-esp32-elf/xtensa-esp32-elf/include/c++/8.4.0/bits/std_function.h:687
/Users/falko/Projects/lizard/components/esp32-ble-command/esp32-ble-command.cpp:183
/Users/falko/.espressif/tools/xtensa-esp32-elf/esp-2021r2-patch5-8.4.0/xtensa-esp32-elf/xtensa-esp32-elf/include/c++/8.4.0/bits/std_function.h:687
/Users/falko/Projects/lizard/components/esp32-zeug/include/esp_zeug/ble/gatts.h:70
/Users/falko/esp/esp-idf_4.4/components/bt/host/nimble/nimble/nimble/host/src/ble_gatts.c:395
/Users/falko/esp/esp-idf_4.4/components/bt/host/nimble/nimble/nimble/host/src/ble_gatts.c:421
/Users/falko/esp/esp-idf_4.4/components/bt/host/nimble/nimble/nimble/host/src/ble_att_svr.c:524
/Users/falko/esp/esp-idf_4.4/components/bt/host/nimble/nimble/nimble/host/src/ble_att_svr.c:555
/Users/falko/esp/esp-idf_4.4/components/bt/host/nimble/nimble/nimble/host/src/ble_att_svr.c:2001
/Users/falko/esp/esp-idf_4.4/components/bt/host/nimble/nimble/nimble/host/src/ble_att.c:503
/Users/falko/esp/esp-idf_4.4/components/bt/host/nimble/nimble/nimble/host/src/ble_hs_hci_evt.c:973
/Users/falko/esp/esp-idf_4.4/components/bt/host/nimble/nimble/nimble/host/src/ble_hs.c:238
/Users/falko/esp/esp-idf_4.4/components/bt/host/nimble/nimble/nimble/host/src/ble_hs.c:532
/Users/falko/esp/esp-idf_4.4/components/bt/host/nimble/nimble/porting/npl/freertos/include/nimble/nimble_npl_os.h:125
/Users/falko/Projects/lizard/components/esp32-ble-command/esp32-ble-command.cpp:167
/Users/falko/.espressif/tools/xtensa-esp32-elf/esp-2021r2-patch5-8.4.0/xtensa-esp32-elf/xtensa-esp32-elf/include/c++/8.4.0/bits/std_function.h:687
/Users/falko/Projects/lizard/components/esp32-zeug/include/esp_zeug/frtos-util.h:66 (discriminator 1)
/Users/falko/esp/esp-idf_4.4/components/freertos/port/xtensa/port.c:142

which basically leads to this line: https://github.com/ianh/owl/blob/75d6bffdff23c84555a781ff69eb66aa8f5819a4/src/1-parse.h#L305

It seems to be called when allocating more memory for the parse tree fails. And this linked to commit https://github.com/ianh/owl/commit/045af9d96fa881933a893c2549bc1a491a11b33b where a minimum size of 4096 bytes for the parse tree was introduced. In our use case it is more harm than good to always require a free chunk of 4K to parse a short line of Lizard code.

Anyway, we added a tiny string replacement in the get_parser.sh. It seems to work in our test. But maybe you can try it on your setup.

angelom93 commented 10 months ago

The suggested fix for the Lizard system issue resolved the ESP reboot problem on my setup. The system is now stable with both long startup scripts and Bluetooth commands.

Thank you @falkoschindler for your support.