One faulty core message on startup

[pascalzauberzeug]

I noticed that the ESP sends its first core message when it is not finished with its startup yet.
That is problematic because most of the values like estops, bumpers and the imu are wrong

Wrong (06:07:33.850):

core 6310 0.000 0.000 true true 0 false false false true true 0 false false false false false 0 true true true 0 0.0000 0.0000 0.0000 0.0000 0 0 54144@19

Correct, one tick later (06:07:34.053):

core 6488 0.000 0.000 false false 0 false false false false false 0 false false false false false 1 false false false 0 0.6993 -0.7147 0.0182 0.0000 0 0 54144@53

Full reset log:

06:07:24.674 core 27525 0.000 0.000 false false 0 false false false false false 0 false false false false false 1 false false false 0 0.7018 -0.7121 0.0196 -0.0007 0 0 54076@42
06:07:26.812 I (13) boot: ESP-IDF v5.3.1 2nd stage bootloader
06:07:26.822 I (13) boot: compile time May 16 2025 14:38:57
06:07:26.832 I (13) boot: Multicore bootloader
06:07:26.842 I (13) boot: chip revision: v3.1
06:07:26.852 I (16) boot.esp32: SPI Speed      : 40MHz
06:07:26.862 I (20) boot.esp32: SPI Mode       : DIO
06:07:26.873 I (23) boot.esp32: SPI Flash Size : 8MB
06:07:26.884 I (27) boot: Enabling RNG early entropy source...
06:07:26.896 I (32) boot: Partition Table:
06:07:26.909 I (34) boot: ## Label            Usage          Type ST Offset   Length
06:07:26.919 I (40) boot:  0 nvs              WiFi data        01 02 00009000 00006000
06:07:26.930 I (47) boot:  1 otadata          OTA data         01 00 0000f000 00002000
06:07:26.940 I (54) boot:  2 phy_init         RF data          01 01 00011000 00001000
06:07:26.950 I (60) boot:  3 ota_0            OTA app          00 10 00020000 001f0000
06:07:26.961 I (67) boot:  4 ota_1            OTA app          00 11 00210000 001f0000
06:07:26.971 I (73) boot:  5 coredump         Unknown data     01 03 00400000 00020000
06:07:26.982 I (80) boot: End of partition table
06:07:26.993 I (83) esp_image: segment 0: paddr=00020020 vaddr=3f400020 size=73450h (472144) map
06:07:27.010 I (252) esp_image: segment 1: paddr=00093478 vaddr=3ff80000 size=00004h (     4) load
06:07:27.021 I (252) esp_image: segment 2: paddr=00093484 vaddr=3ffbdb60 size=06264h ( 25188) load
06:07:27.031 I (265) esp_image: segment 3: paddr=000996f0 vaddr=40080000 size=06928h ( 26920) load
06:07:27.041 I (276) esp_image: segment 4: paddr=000a0020 vaddr=400d0020 size=1146d8h (1132248) map
06:07:27.384 I (664) esp_image: segment 5: paddr=001b4700 vaddr=40086928 size=17194h ( 94612) load
06:07:27.448 I (717) boot: Loaded app from partition at offset 0x20000
06:07:27.465 I (717) boot: Disabling RNG early entropy source...
06:07:27.476 I (727) cpu_start: Multicore app
06:07:27.584 I (735) cpu_start: Pro cpu start user code
06:07:27.593 I (735) cpu_start: cpu freq: 160000000 Hz
06:07:27.604 I (735) app_init: Application information:
06:07:27.614 I (735) app_init: Project name:     lizard
06:07:27.624 I (739) app_init: App version:      v0.7.2
06:07:27.635 I (743) app_init: Compile time:     May 16 2025 14:38:51
06:07:27.647 I (748) app_init: ELF file SHA256:  1d4290b8f...
06:07:27.674 I (752) app_init: ESP-IDF:          v5.3.1
06:07:27.684 I (756) efuse_init: Min chip rev:     v0.0
06:07:27.694 I (760) efuse_init: Max chip rev:     v3.99 
06:07:27.705 I (764) efuse_init: Chip rev:         v3.1
06:07:27.716 I (768) heap_init: Initializing. RAM available for dynamic allocation:
06:07:27.726 I (774) heap_init: At 3FFAFF10 len 000000F0 (0 KiB): DRAM
06:07:27.738 I (779) heap_init: At 3FFB6388 len 00001C78 (7 KiB): DRAM
06:07:27.778 I (784) heap_init: At 3FFB9A20 len 00004108 (16 KiB): DRAM
06:07:27.791 I (790) heap_init: At 3FFD5888 len 0000A778 (41 KiB): DRAM
06:07:27.801 I (795) heap_init: At 3FFE0440 len 00003AE0 (14 KiB): D/IRAM
06:07:27.811 I (800) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM
06:07:27.822 I (806) heap_init: At 4009DABC len 00002544 (9 KiB): IRAM
06:07:27.832 I (813) spi_flash: detected chip: gd
06:07:27.843 I (814) spi_flash: flash io: dio
06:07:27.853 W (817) spi_flash: Detected size(16384k) larger than the size in the binary image header(8192k). Using the size in the binary image header.
06:07:27.875 W (830) pcnt(legacy): legacy driver is deprecated, please migrate to `driver/pulse_cnt.h`
06:07:27.893 W (837) i2c: This driver is an old driver, please migrate your application code to adapt `driver/i2c_master.h`
06:07:27.904 I (850) esp_core_dump_flash: Init core dump to flash
06:07:27.914 I (853) esp_core_dump_flash: Found partition 'coredump' @ 400000 131072 bytes
06:07:27.925 E (879) esp_core_dump_flash: Core dump data check failed:
06:07:27.936 Calculated checksum='2ea508bf'
06:07:27.946 Image checksum='ffffffff'
06:07:27.956 I (880) coexist: coex firmware version: 4482466
06:07:27.967 I (884) main_task: Started on CPU0
06:07:27.978 I (894) main_task: Calling app_main()
06:07:29.178 I (2424) gpio: GPIO[15]| InputEn: 0| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0 
06:07:29.197 I (2424) gpio: GPIO[12]| InputEn: 0| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0 
06:07:29.207 I (2434) BTDM_INIT: BT controller compile version [b022216]
06:07:29.217 I (2434) BTDM_INIT: Bluetooth MAC: b0:a7:32:31:bc:c2
06:07:29.228 I (2444) phy_init: phy_version 4830,54550f7,Jun 20 2024,14:22:08
06:07:29.481 I (2754) esp_zeug/FrtosUtil: Task [ble_host] executing on core [PRO]
06:07:29.549 I (2794) gpio: GPIO[32]| InputEn: 1| OutputEn: 0| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:0 
06:07:29.559 I (2794) gpio: GPIO[33]| InputEn: 0| OutputEn: 1| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:0 
06:07:29.570 I (2804) NimBLE: Failed to restore IRKs from store; status=8
06:07:29.580 
06:07:29.590 I (2814) NimBLE: GAP procedure initiated: advertise; 
06:07:29.600 I (2814) NimBLE: disc_mode=2
06:07:29.611 I (2814) NimBLE:  adv_channel_map=0 own_addr_type=0 adv_filter_policy=0 adv_itvl_min=0 adv_itvl_max=0
06:07:29.626 I (2824) NimBLE: 
06:07:29.636 
06:07:29.647 I (2854) gpio: GPIO[25]| InputEn: 0| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0 
06:07:29.658 I (2854) gpio: GPIO[14]| InputEn: 0| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0 
06:07:29.809 p0: I (13) boot: ESP-IDF v5.3.1 2nd stage bootloader@26
06:07:29.809 p0: I (13) boot: compile time May 16 2025 14:38:57@03
06:07:29.809 p0: I (13) boot: Multicore bootloader@69
06:07:29.810 p0: I (13) boot: chip revision: v3.1@7d
06:07:29.810 p0: I (16) boot.esp32: SPI Speed      : 40MHz@1c
06:07:29.810 p0: I (20) boot.esp32: SPI Mode       : DIO@64
06:07:29.810 p0: I (24) boot.esp32: SPI Flash Size : 8MB@63
06:07:29.810 p0: I (27) boot: Enabling RNG early entropy source...@5f
06:07:29.810 p0: I (32) boot: Partition Table:@19
06:07:29.811 p0: I (34) boot: ## Label            Usage          Type ST Offset   Length@34
06:07:29.811 p0: I (41) boot:  0 nvs              WiFi data        01 02 00009000 00006000@4d
06:07:29.811 p0: I (47) boot:  1 otadata          OTA data         01 00 0000f000 00002000@79
06:07:29.811 p0: I (54) boot:  2 phy_init         RF data          01 01 00011000 00001000@2c
06:07:29.812 p0: I (60) boot:  3 ota_0            OTA app          00 10 00020000 001f0000@51
06:07:29.813 p0: I (67) boot:  4 ota_1            OTA app          00 11 00210000 001f0000@50
06:07:29.813 p0: I (73) boot:  5 coredump         Unknown data     01 03 00400000 00020000@64
06:07:29.813 p0: I (80) boot: End of partition table@6c
06:07:29.813 p0: I (83) esp_image: segment 0: paddr=00020020 vaddr=3f400020 size=73450h (472144) map@79
06:07:29.999 p0: I (252) esp_image: segment 1: paddr=00093478 vaddr=3ff80000 size=00004h (     4) load@70
06:07:29.999 p0: I (252) esp_image: segment 2: paddr=00093484 vaddr=3ffbdb60 size=06264h ( 25188) load@2a
06:07:30.000 p0: I (265) esp_image: segment 3: paddr=000996f0 vaddr=40080000 size=06928h ( 26920) load@2a
06:07:30.000 p0: I (276) esp_image: segment 4: paddr=000a0020 vaddr=400d0020 size=1146d8h (1132248) map@43
06:07:30.388 p0: I (664) esp_image: segment 5: paddr=001b4700 vaddr=40086928 size=17194h ( 94612) load@24
06:07:30.420 p0: I (717) boot: Loaded app from partition at offset 0x20000@7f
06:07:30.420 p0: I (717) boot: Disabling RNG early entropy source...@1e
06:07:30.609 p0: I (727) cpu_start: Multicore app@70
06:07:30.609 p0: I (735) cpu_start: Pro cpu start user code@37
06:07:30.609 p0: I (735) cpu_start: cpu freq: 160000000 Hz@19
06:07:30.610 p0: I (735) app_init: Application information:@31
06:07:30.610 p0: I (736) app_init: Project name:     lizard@7e
06:07:30.610 p0: I (739) app_init: App version:      v0.7.2@73
06:07:30.610 p0: I (743) app_init: Compile time:     May 16 2025 14:38:51@1f
06:07:30.610 p0: I (748) app_init: ELF file SHA256:  1d4290b8f...@47
06:07:30.610 p0: I (753) app_init: ESP-IDF:          v5.3.1@46
06:07:30.611 p0: I (756) efuse_init: Min chip rev:     v0.0@62
06:07:30.611 p0: I (760) efuse_init: Max chip rev:     v3.99@4a
06:07:30.611 p0: I (764) efuse_init: Chip rev:         v3.1@2b
06:07:30.611 p0: I (768) heap_init: Initializing. RAM available for dynamic allocation:@48
06:07:30.611 p0: I (774) heap_init: At 3FFAFF10 len 000000F0 (0 KiB): DRAM@43
06:07:30.611 p0: I (779) heap_init: At 3FFB6388 len 00001C78 (7 KiB): DRAM@45
06:07:30.612 p0: I (784) heap_init: At 3FFB9A20 len 00004108 (16 KiB): DRAM@78
06:07:30.612 p0: I (790) heap_init: At 3FFD5888 len 0000A778 (41 KiB): DRAM@7a
06:07:30.612 p0: I (795) heap_init: At 3FFE0440 len 00003AE0 (14 KiB): D/IRAM@6b
06:07:30.612 p0: I (800) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM@2b
06:07:30.612 p0: I (806) heap_init: At 4009DABC len 00002544 (9 KiB): IRAM@46
06:07:30.613 p0: I (813) spi_flash: detected chip: gd@5a
06:07:30.613 p0: I (814) spi_flash: flash io: dio@5e
06:07:30.613 p0: W (817) spi_flash: Detected size(16384k) larger than the size in the binary image header(8192k). Using the size in the binary image header.@2e
06:07:30.613 p0: W (830) pcnt(legacy): legacy driver is deprecated, please migrate to `driver/pulse_cnt.h`@66
06:07:30.613 p0: W (837) i2c: This driver is an old driver, please migrate your application code to adapt `driver/i2c_master.h`@34
06:07:30.613 p0: I (850) esp_core_dump_flash: Init core dump to flash@2d
06:07:30.613 p0: I (853) esp_core_dump_flash: Found partition 'coredump' @ 400000 131072 bytes@70
06:07:30.614 p0: I (859) coexist: coex firmware version: 4482466@1d
06:07:30.614 p0: I (865) main_task: Started on CPU0@5c
06:07:30.614 p0: I (875) main_task: Calling app_main()@3d
06:07:32.098 p0: @5a
06:07:32.099 p0: Ready.@3f
06:07:32.099 p0: Booting process completed successfully@23
06:07:32.165 I (5434) gpio: GPIO[5]| InputEn: 0| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0 
06:07:32.175 I (5434) gpio: GPIO[4]| InputEn: 0| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0 
06:07:32.186 I (5454) gpio: GPIO[34]| InputEn: 0| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0 
06:07:32.198 I (5454) gpio: GPIO[35]| InputEn: 0| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0 
06:07:33.617 I (6884) gpio: GPIO[39]| InputEn: 0| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0 
06:07:33.628 
06:07:33.638 Ready.
06:07:33.684 p0: I (2465) gpio: GPIO[25]| InputEn: 0| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0@16
06:07:33.684 p0: I (2475) gpio: GPIO[12]| InputEn: 0| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0@13
06:07:33.685 p0: I (2475) gpio: GPIO[22]| InputEn: 0| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0@10
06:07:33.685 p0: I (2485) gpio: GPIO[23]| InputEn: 0| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0@1e
06:07:33.737 p0: I (2535) gpio: GPIO[15]| InputEn: 0| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0@11
06:07:33.738 p0: I (2545) gpio: GPIO[13]| InputEn: 0| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0@10
06:07:33.738 p0: I (2545) gpio: GPIO[35]| InputEn: 0| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0@14
06:07:33.738 p0: I (2555) gpio: GPIO[18]| InputEn: 0| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0@1a
06:07:33.738 p0: I (2565) gpio: GPIO[21]| InputEn: 0| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0@13
06:07:33.850 error in module "p0": checksum mismatch@36
06:07:33.850 core 6310 0.000 0.000 true true 0 false false false true true 0 false false false false false 0 true true true 0 0.0000 0.0000 0.0000 0.0000 0 0 54144@19
06:07:33.888 p0: I (3955) gpio: GPIO[39]| InputEn: 0| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0@14
06:07:33.958 bluetooth.send("POST /notification ESP connected")@66
06:07:33.958 core.version()@4e
06:07:33.959 p0.version()@15
06:07:34.053 error in module "p0": checksum mismatch@36
06:07:34.053 core 6488 0.000 0.000 false false 0 false false false false false 0 false false false false false 1 false false false 0 0.6993 -0.7147 0.0182 0.0000 0 0 54144@53

[JensOgorek]

These are the default values, since the p0 did not have the time to update its properties

[falkoschindler]

We think that, after creating a new proxy and calling .broadcast(), the expander should wait until receiving the first broadcast message for this module. This can be done with a small loop listening for the serial port and passing messages to the message_handler.

To reduce the waiting time, the remote module should broadcast immediately when receiving a broadcast() call.

Note that some modules don't have any properties and might not send any broadcast messages at all. We need to think about how to handle this case.

Last but not least, we can think about removing the "default property" pattern. Once we await the first broadcast messages, there is no need to initialize all properties via the get_defaults() method.