Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

[CM4] No longer boots after updating to 1739293213 ("Tue 11 Feb 17:00:13 UTC 2025") #668

Open
srcshelton opened this issue Feb 17, 2025 · 14 comments

Comments

@srcshelton
Copy link

srcshelton commented Feb 17, 2025

Describe the bug

After updating to firmware 1739293213 ("Tue 11 Feb 17:00:13 UTC 2025"), one of my CM4 units is no longer booting (from eMMC). It can still be restarted in MSD mode and its filesystems appear to be intact.

I've held-off from updating the other three identical CM4 units in the cluster for fear of them also being affected, but do have these additional nodes which could be used to test a solution if necessary...

Steps to reproduce the behaviour

  1. Reboot successfully
  2. Install firmware 1739293213
  3. Reboot (and subsequently power-cycle) and the boot process appears to never complete:
TIMESTAMP=1739293213 serial f80ba322 boardrev d03140 stc 530933
  0.40 PM_RSTS 00001000
  0.42 POWER_OFF_ON_HALT: 0 WAIT_FOR_PWER_BUTTON 0 power-on-reset 1
  0.64 part 00000000 reset_info 00000000
  0.65 uSD voltage 3.3V
  0.90 Initialising SDRAM rank 2 total-size: 64 Gbit 3200 (0x14 0x00)
  0.94 DDR 3200 1 0 64 152 BL:3
  2.38 OTP boardrev d03140 bootrom 48b0 48b0
  2.39 Customer key hash 000000000000000000000000000000000000000000000000000000000000000
  2.47 VC-JTAG unlocked


  2.24 RPi: BOOTLOADER release VERSION:75c1e570 DATE: 2025/02/11 TIME: 17:00:13
  2.29 BOOTMODE: 0x06 partition 0 build-ts BULD_TIMESTAMP=1739293213 serial f80ba322 boardrev d03140 stc 2529023
  2.64 Boot mode: SD (01) order f64
  2.79 SD HOST: 200000000 CTL0: 0x00800000 BUS: 400000 Hz actual: 390625 HZ div: 512 (256) status: 0x1fff0000 delay: 276
  2.89SD HOST: 200000000 CTL0: 0x00800f00 BUS: 400000 Hz actual: 390625 HZ div: 512 (256) status: 0x1fff0000 delay: 276
  2.98 EMMC
  2.98 SD retry 1 oc 0
  2.23 SD HOST: 200000000 CTL0: 0x00800000 BUS: 400000 Hz actual: 390625 HZ div: 512 (256) status: 0x1fff0000 delay: 276
  2.34 OCR c0ff8080 [0]
CID: 00150100424a5444345203708e4e9788
  2.54 SD HOST: 200000000 CTL0: 0x00800f04 BUS: 25000000 Hz actual: 25000000 HZ div: 8 (4) status: 0x1fff0000 delay: 4
  2.64 S HOST: 200000000 CTL0: 0x00800f04 BUS: 50000000 Hz actual: 50000000 HZ div: 4 (2) status: 0x1fff0000 delay: 2
  2.73 MBR: 0x0000001,    2047 type: 0xee
  2.76 MBR: 0x00000800,    4096 type: 0x04
  2.79 MBR: 0x00201800,  131072 type: 0x0b
  2.83 MBR: 0x1f1f800,  131072 type: 0x0b
  2.87 Trying partition: 0
  2.90 GPT e60773e0a240de478c1d95d7d0aa35a3 000000001 003a3dfff num-paritions 128 entry-size 128 pentry 2 first 0
  2.00 GPT partition: 0 b921b045-1df0-41c3-af44-4c6f280d3fae 000001800..0002017ff
 2.07 GPT partition: 1 ebd0a0a2-b9e5-4433-87c0-68b6b72699c7 000201800..0002217ff
  2.14 Matched GUID bootable-part-idx 0 want patition 0
  2.19 type: 32 lba: 2103296 'BSD  4.4' ' BOOT_0     ' clusters 129024 (1)
  2.26 rsc 32 fat-sectors 1008 root dir clster 2 sectors 0 entries 0
  2.32 FAT32 clusters 129024
  2.40 [sdcard] autoboot.txt not found
  2.41 Select partition rsts 0 C(boot_partition) 0 EEPROM config 0 result 1
  2.48 Tryig partition: 1
  2.50 GPT e60773e0a240de478c1d95d7d0aa35a3 000000001 003a3dfff num-partitions 128 entry-size 128 pentry 2 first0
  2.60 GPT partition: 0 b921b045-1df0-41c3-af44-4c6f280d3fae 000001800..0002017ff
  2.67 GPT partition: 1 ebd0a0a2-b9e5-4433-87c0-68b6b72699c7 000201800..0002217ff
  2.74 Matched GUID bootable-part-idx 0 want partition 0
  2.80 type: 32 lba: 2103296 'SD  4.4' ' BOOT_0     ' clusters 129024 (1)
  2.86 rsc 32 fat-sectors 1008 root dir cluster 2 sectors 0 entries 0
  2.93 FAT32clusters 129024
  2.99 Read config.txt bytes     7379 hnd 0x12e9d
  3.04 Read overclock.txt bytes     2296 hnd 0x1d839
  3.10 Read legacy.txt bytes     3563 hnd 0x1d832
  3.12 pieeprom.sig
  3.13 hash: 45e09714d5379b2479ddf6f7e8d7a5f59756fac5e5174ac548421adaaeef9fc
  3.20 ts: 1739790528
  3.08 SELF-UPDATE timestamp current 1739790528 new 1739790528 skip
  3.14 [sdcard] recover4.elf not found
  3.17 [sdcard] recvery.elf not found
  3.45 Read start4.elf bytes  2262304 hnd 0x1f220
  3.48 Read fixup4.dat bytes     5459 hnd 0x1ef58
  3.51 0x00d03140 0x00000000 0x00001fff
  3.55 MEM GPU: 76 ARM: 948 TOTAL: 1024
  3.24 Firmware: 03554ca336a03ace164f36755144e0d8c060062d Dec  5 2024 11:45:37
  3.57 Starting start4.elf @ 0xfec00200 partition 1
  3.59 PCI0 reset
  3.70 +

MESS:00:00:03.472509:0: arasan: arasan_emmc_open
MESS:00:00:03.474171:0: arasan: arasan_emmc_set_clock C0: 0x00800000 C1: 0x0000047 emmc: 200000000 actual: 390625 div: 0x00000100 target: 400000 min: 400000 max: 400000 delay: 5
MESS:00:00:03.594404:0: arasan: arasan_emmc_set_clock C0: 0x00800000 C1: 0x000e0047 emmc: 200000000 actual: 390625 div: 0x0000010 target: 400000 min: 400000 max: 400000 delay: 5
MESS:00:00:03.607276:0: arasan: arasan_emmc_set_clock C0: 0x00800f00 C1: 0x000e0047 emmc: 200000000 actual: 390625 div: 0x00000100 target: 400000 min: 390000 max: 400000 delay: 5
MESS:00:00:03.658220:0: arasan: arasan_emmc_set_clock C0: 0x00800f02 C1: 0x000e0407 emmc: 200000000 actual: 25000000 div: 0x0000004 target: 25000000 min: 0 max: 25000000 delay: 1
MESS:00:00:03.775678:0: arasan: arasan_emmc_set_clock C0: 0x00800000 C1: 0x000e0047 emmc: 200000000 actual: 390625 div: 0x0000010 target: 400000 min: 400000 max: 400000 delay: 5
MESS:00:00:03.788559:0: arasan: arasan_emmc_set_clock C0: 0x00800f00 C1: 0x00e0047 emmc: 200000000 actual: 390625 div: 0x00000100 target: 400000 min: 390000 max: 400000 delay: 5
MESS:00:00:12.021846:0: gpioman: gpioman_get_pin_num: attempting to get pin number for SDCARD_CONTROL_POWER before we're ready
ESS:00:00:12.030195:0: gpioman: gpioman_get_pin_num: attempting to get pin number for SDCARD_CONTROL_POWER before we're ready
MESS:00:00:12.141251:0: gpioman: gpioman_get_pin_num: attempting to get pin number for SDCARD_CONTROL_POWER before we're ready
MESS:00:00:12.153691:0: arasan: arasan_emmc_set_clock C0: 0x00800000 C1: 0x000e0047 emmc: 200000000 actual: 390625 div: 0x0000010 target: 400000 min: 400000 max: 400000 delay: 5
MESS:00:00:12.166573:0: arasan: arasan_emmc_set_clock C0: 0x00800f00 C1: 0x00e0047 emmc: 200000000 actual: 389863 div: 0x00000100 target: 400000 min: 390000 max: 400000 delay: 5
MESS:00:00:16.399623:0: gpioman: gpioman_get_pin_num: attempting to get pin number for SDCARD_CONTROL_POWER before we're ready
MESS:00:00:16.428911:0: HDMI0:EDID error reading EDID block 0 attempt 0
MESS:00:00:16.433421:0: HDMI0:EDID giving up on readingEDID block 0
MESS:00:00:16.450428:0: HDMI1:EDID error reading EDID block 0 attempt 0
MESS:00:00:16.454929:0: HDMI1:EDID giving up on readingEDID block 0
MESS:00:00:16.460164:0: gpioman: gpioman_get_pin_num: pin SDCARD_CONTROL_POWER not defined
MESS:00:00:16.567995:0: gpioman: gpioman_get_pin_num: pin SDCARD_CONTROL_POWER not defined
MESS:00:00:16.577306:0: arasan: arasan_emmc_set_clock C0: 0x00800000 C1: 0x000e0047 emmc: 200000000 actual: 390625 div: 0x00000100 target: 400000 min: 400000 max: 40
400000 delay: 5
MESS:00:00:16.590187:0: arasan: arasan_emmc_set_clock C0: 0x00800f00 C1: 0x00e0047 emmc: 200000000 actual: 389863 div: 0x00000100 target: 400000 min: 390000 max: 400000 delay: 5
MESS:00:00:24.823463:0: gpioman: gpioman_get_pin_num: pin SDCARD_CONTROL_POWER not defined
MESS:00:00:24.828680:0: gpioman: gpiman_get_pin_num: pin SDCARD_CONTROL_POWER not defined
MESS:00:00:24.936610:0: gpioman: gpioman_get_pin_num: pin SDCARD_CONTROL_POWER not defined
MESS:00:00:24.945921:0: arasan: arasan_emmc_set_clock C0: 0x00800000 C1: 0x000e0047 emmc: 200000000 actual: 390625 div: 0x0000010 target: 400000 min: 400000 max: 400000 delay: 5
MESS:00:00:24.958803:0: arasan: arasan_emmc_set_clock C0: 0x00800f00 C1: 0x00e0147 emmc: 200000000 actual: 389105 div: 0x00000101 target: 400000 min: 390000 max: 400000 delay: 5
MESS:00:00:29.191948:0: gpioman: gpioman_get_pin_num: pin SDCARD_CONTROL_POWEman_get_pin_num: pin DISPLAY_SDA not defined
MESS:00:00:29.672955:0: gpioman: gpioman_get_pin_num: pin LEDS_PWR_OK not defined
MESS:00:00:29.678600:0: *** Restart logging
ESS:00:00:29.681333:0: gpioman: gpioman_get_pin_num: pin SDCARD_CONTROL_POWER not defined
MESS:00:00:29.789233:0: gpioman: gpioman_get_pin_num: pin SDCARD_CONTROL_POWER not defined
MESS:00:00:29.798561:0: arasan: arasan_emmc_set_clock C0: 0x00800000 C1: 0x000e8007 emmc: 100000000 actual: 390625 div: 0x0000000 target: 400000 min: 400000 max: 400000 delay: 5
MESS:00:00:29.811451:0: arasan: arasan_emmc_set_clock C0: 0x00800f00 C1: 0x000e8107 emmc: 100000000 actual: 387596 div: 0x00000081 target: 400000 min: 390000 max: 400000 delay: 5
MESS:00:00:34.049399:0: hdmi: HDMI0:EDID error reading EDID block 0 attempt 0
MESS:00:00:34.054431:0: hdmi: HDMI0:EDID giving u on reading EDID block 0
MESS:00:00:34.065054:0: hdmi: HDMI0:EDID error reading EDID block 0 attempt 0
MESS:00:00:34.070076:0: hdmi: HDMI0:EDID giving u on reading EDID block 0
MESS:00:00:34.075675:0: hdmi: HDMI:hdmi_get_state is deprecated, use hdmi_get_display_state instead
MESS:00:00:34.089467:0: hdmi: HDMI1:EDID error reading EDID block 0 attempt 0
MESS:00:00:34.094492:0: hdmi: HDMI1:EDID giving u on reading EDID block 0
MESS:00:00:34.105114:0: hdmi: HDMI1:EDID error reading EDID block 0 attempt 0
MESS:00:00:34.110144:0: hdmi: HDMI1:EDID giving u on reading EDID block 0
MESS:00:00:34.115741:0: hdmi: HDMI:hdmi_get_state is deprecated, use hdmi_get_display_state instead
MSS:00:00:34.124506:0: HDMI0: hdmi_pixel_encoding: 300000000
MESS:00:00:34.129982:0: HDMI1: hdmi_pixel_encoding: 300000000
MESS:00:00:38.135913:0: gpioman: gpioman_get_pin_num: pin SDCARD_CONTROL_POWER not defined
MESS:00:00:38.141139:0: gpioman: gpiman_get_pin_num: pin SDCARD_CONTROL_POWER not defined
MESS:00:00:38.249062:0: gpioman: gpioman_get_pin_num: pin SDCARD_CONTROL_POWER not defined
MESS:00:00:38.258387:0: arasan: arasan_emmc_set_clock C0: 0x00800000 C1: 0x000e8007 emmc: 100000000 actual: 390625 div: 0x0000000 target: 400000 min: 400000 max: 400000 delay: 5
MESS:00:00:38.271277:0: arasan: arasan_emmc_set_clock C0: 0x00800f00 C1: 0x00e8107 emmc: 100000000 actual: 386100 div: 0x00000081 target: 400000 min: 390000 max: 400000 delay: 5
MESS:00:00:42.504387:0: gpioman: gpioman_get_pin_num: pin SDCARD_CONTROL_POWER not defined
MESS:00:00:42.509627:0: gpioman: gpiman_get_pin_num: pin SDCARD_CONTROL_POWER not defined
MESS:00:00:42.617535:0: gpioman: gpioman_get_pin_num: pin SDCARD_CONTROL_POWER not defined
MESS:00:00:42.626860:0: arasan: arasan_emmc_set_clock C0: 0x00800000 C1: 0x000e8007 emmc: 100000000 actual: 390625 div: 0x00000080 target: 400000 min: 400000 max: 400000 delay: 5
MESS:00:00:42.639748:0: arasan: arasan_emmc_set_clock C0: 0x00800f00 C1: 0x00e8107 emmc: 100000000 actual: 386100 div: 0x00000081 target: 400000 min: 390000 max: 400000 delay: 5
MESS:00:00:50.872902:0: gpioman: gpioman_get_pin_num: pin SDCARD_CONTROL_POWER not defined
MESS:00:00:50.878126:0: gpioman: gpiman_get_pin_num: pin SDCARD_CONTROL_POWER not defined
MESS:00:00:50.986049:0: gpioman: gpioman_get_pin_num: pin SDCARD_CONTROL_POWER not defined
MESS:00:00:50.995375:0: arasan: arasan_emmc_set_clock C0: 0x00800000 C1: 0x000e8007 emmc: 100000000 actual: 390625 div: 0x0000000 target: 400000 min: 400000 max: 400000 delay: 5
MESS:00:00:51.008265:0: arasan: arasan_emmc_set_clock C0: 0x00800f00 C1: 0x00e8207 emmc: 100000000 actual: 384615 div: 0x00000082 target: 400000 min: 390000 max: 400000 delay: 5
MESS:00:00:55.241406:0: gpioman: gpioman_get_pin_num: pin SDCARD_CONTROL_POWER not defined
MESS:00:00:55.246644:0: gpioman: gpiman_get_pin_num: pin SDCARD_CONTROL_POWER not defined
MESS:00:00:55.354553:0: gpioman: gpioman_get_pin_num: pin SDCARD_CONTROL_POWER not defined
MESS:00:00:55.363879:0: arasan: arasan_emmc_set_clock C0: 0x00800000 C1: 0x000e8007 emmc: 100000000 actual: 390625 div: 0x0000000 target: 400000 min: 400000 max: 400000 delay: 5
MESS:00:00:55.376769:0: arasan: arasan_emmc_set_clock C0: 0x00800f00 C1: 0x00e8207 emmc: 100000000 actual: 384615 div: 0x00000082 target: 400000 min: 390000 max: 400000 delay: 5
MESS:00:01:03.609908:0: gpioman: gpioman_get_pin_num: pin SDCARD_CONTROL_POWER not defined
MESS:00:01:03.615132:0: gpioman: gpiman_get_pin_num: pin SDCARD_CONTROL_POWER not defined
MESS:00:01:03.723055:0: gpioman: gpioman_get_pin_num: pin SDCARD_CONTROL_POWER not defined
MESS:00:01:03.732382:0: arasan: arasan_emmc_set_clock C0: 0x00800000 C1: 0x000e8007 emmc: 100000000 actual: 390625 div: 0x0000000 target: 400000 min: 400000 max: 400000 delay: 5
MESS:00:01:03.745273:0: arasan: arasan_emmc_set_clock C0: 0x00800f00 C1: 0x00e8207 emmc: 100000000 actual: 383141 div: 0x00000082 target: 400000 min: 390000 max: 400000 delay: 5
MESS:00:01:07.978398:0: gpioman: gpioman_get_pin_num: pin SDCARD_CONTROL_POWER not defined
MESS:00:01:07.983637:0: gpioman: gpiman_get_pin_num: pin SDCARD_CONTROL_POWER not defined
MESS:00:01:08.091546:0: gpioman: gpioman_get_pin_num: pin SDCARD_CONTROL_POWER not defined
MESS:00:01:08.100873:0: arasan: arasan_emmc_set_clock C0: 0x00800000 C1: 0x000e8007 emmc: 100000000 actual: 390625 div: 0x0000000 target: 400000 min: 400000 max: 400000 delay: 5
MESS:00:01:08.113762:0: arasan: arasan_emmc_set_clock C0: 0x00800f00 C1: 0x00e8207 emmc: 100000000 actual: 383141 div: 0x00000082 target: 400000 min: 390000 max: 400000 delay: 5
MESS:00:01:16.346929:0: gpioman: gpioman_get_pin_num: pin SDCARD_CONTROL_POWER not defined
MESS:00:01:16.352153:0: gpioman: gpiman_get_pin_num: pin SDCARD_CONTROL_POWER not defined
MESS:00:01:16.460076:0: gpioman: gpioman_get_pin_num: pin SDCARD_CONTROL_POWER not defined
MESS:00:01:16.469402:0: arasan: arasan_emmc_set_clock C0: 0x00800000 C1: 0x000e8007 emmc: 100000000 actual: 390625 div: 0x0000000 target: 400000 min: 400000 max: 400000 delay: 5
MESS:00:01:16.482293:0: arasan: arasan_emmc_set_clock C0: 0x00800f00 C1: 0x00e8307 emmc: 100000000 actual: 381679 div: 0x00000083 target: 400000 min: 390000 max: 400000 delay: 5
MESS:00:01:20.715419:0: gpioman: gpioman_get_pin_num: pin SDCARD_CONTROL_POWER not defined
MESS:00:01:20.720657:0: gpioman: gpiman_get_pin_num: pin SDCARD_CONTROL_POWER not defined
MESS:00:01:20.828566:0: gpioman: gpioman_get_pin_num: pin SDCARD_CONTROL_POWER not defined
MESS:00:01:20.837892:0: arasan: arasan_emmc_set_clock C0: 0x00800000 C1: 0x000e8007 emmc: 100000000 actual: 390625 div: 0x0000000 target: 400000 min: 400000 max: 400000 delay: 5
MESS:00:01:20.850782:0: arasan: arasan_emmc_set_clock C0: 0x00800f00 C1: 0x00e8307 emmc: 100000000 actual: 381679 div: 0x00000083 target: 400000 min: 390000 max: 400000 delay: 5
MESS:00:01:29.083951:0: gpioman: gpioman_get_pin_num: pin SDCARD_CONTROL_POWER not defined
MESS:00:01:29.089175:0: gpioman: gpiman_get_pin_num: pin SDCARD_CONTROL_POWER not defined
MESS:00:01:29.197098:0: gpioman: gpioman_get_pin_num: pin SDCARD_CONTROL_POWER not defined
MESS:00:01:29.206425:0: arasan: arasan_emmc_set_clock C0: 0x00800000 C1: 0x000e8007 emmc: 100000000 actual: 390625 div: 0x0000000 target: 400000 min: 400000 max: 400000 delay: 5
MESS:00:01:29.219316:0: arasan: arasan_emmc_set_clock C0: 0x00800f00 C1: 0x00e8307 emmc: 100000000 actual: 380228 div: 0x00000083 target: 400000 min: 390000 max: 400000 delay: 5
MESS:00:01:33.452440:0: gpioman: gpioman_get_pin_num: pin SDCARD_CONTROL_POWER not defined
MESS:00:01:33.457679:0: gpioman: gpiman_get_pin_num: pin SDCARD_CONTROL_POWER not defined
MESS:00:01:33.565587:0: gpioman: gpioman_get_pin_num: pin SDCARD_CONTROL_POWER not defined
MESS:00:01:33.574914:0: arasan: arasan_emmc_set_clock C0: 0x00800000 C1: 0x000e8007 emmc: 100000000 actual: 390625 div: 0x0000000 target: 400000 min: 400000 max: 400000 delay: 5
MESS:00:01:33.587805:0: arasan: arasan_emmc_set_clock C0: 0x00800f00 C1: 0x00e8307 emmc: 100000000 actual: 380228 div: 0x00000083 target: 400000 min: 390000 max: 400000 delay: 5
MESS:00:01:37.830267:0: dtb_file 'bcm2711-rpi-cm4.dtb'
MESS:00:01:41.832458:0: gpioman: gpioman_get_pin_num: pin SDCARD_CONTROL_POWER not defined
MESS:00:01:41.837683:0: gpioman: gpiman_get_pin_num: pin SDCARD_CONTROL_POWER not defined
MESS:00:01:41.945605:0: gpioman: gpioman_get_pin_num: pin SDCARD_CONTROL_POWER not defined
MESS:00:01:41.954931:0: arasan: arasan_emmc_set_clock C0: 0x00800000 C1: 0x000e8007 emmc: 100000000 actual: 390625 div: 0x0000000 target: 400000 min: 400000 max: 400000 delay: 5
MESS:00:01:41.967821:0: arasan: arasan_emmc_set_clock C0: 0x00800f00 C1: 0x00e8407 emmc: 100000000 actual: 378787 div: 0x00000084 target: 400000 min: 390000 max: 400000 delay: 5
MESS:00:01:46.200909:0: gpioman: gpioman_get_pin_num: pin SDCARD_CONTROL_POWER not defined
MESS:00:01:46.206069:0: dtb_file 'bc2711-rpi-4-b.dtb'
MESS:00:01:46.211005:0: gpioman: gpioman_get_pin_num: pin SDCARD_CONTROL_POWER not defined
MESS:00:01:46.318917:0: gpioman: gpioman_get_pin_num: pin SDCARD_CONTROL_POWER not defined
MESS:00:01:46.328242:0: arasan: arasan_emmc_set_clock C0: 0x00800000 C1: 0x000e8007 emmc: 100000000 actual: 390625 div: 0x0000000 target: 400000 min: 400000 max: 400000 delay: 5
MESS:00:01:46.341131:0: arasan: arasan_emmc_set_clock C0: 0x00800f00 C1: 0x000e8407 emmc: 100000000 actual: 378787 div: 0x00000084 target: 400000 min: 390000 max: 400000 delay: 5
MESS:00:01:50.574187:0: dtb_file 'bcm2711-rpi-cm4-io.dtb'
MESS:00:01:54.576615:0: gpioman: gpioman_get_pin_num: pin SDCARD_CONTROL_POWER not defined
MESS:00:01:54.581833:0: gpioman: gpiman_get_pin_num: pin SDCARD_CONTROL_POWER not defined
MESS:00:01:54.689756:0: gpioman: gpioman_get_pin_num: pin SDCARD_CONTROL_POWER not defined
MESS:00:01:54.699076:0: arasan: arasan_emmc_set_clock C0: 0x00800000 C1: 0x000e8007 emmc: 100000000 actual: 390625 div: 0x0000000 target: 400000 min: 400000 max: 400000 delay: 5
MESS:00:01:54.711947:0: arasan: arasan_emmc_set_clock C0: 0x00800f00 C1: 0x00e8407 emmc: 100000000 actual: 377358 div: 0x00000084 target: 400000 min: 390000 max: 400000 delay: 5
MESS:00:01:58.945054:0: gpioman: gpioman_get_pin_num: pin SDCARD_CONTROL_POWER not defined
MESS:00:01:58.950207:0: dterror: Faied to load Device Tree file '?'
MESS:00:01:58.956364:0: gpioman: gpioman_get_pin_num: pin SDCARD_CONTROL_POWER not defined
MESS:00:01:59.064269:0: gpioman: gpioman_get_pin_num: pin SDCARD_CONTROL_POWER not defined
MESS:00:01:59.073585:0: arasan: arasan_emmc_set_clock C0: 0x00800000 C1: 0x000e8007 emmc: 100000000 actual: 390625 div: 0x0000000 target: 400000 min: 400000 max: 400000 delay: 5
MESS:00:01:59.086464:0: arasan: arasan_emmc_set_clock C0: 0x00800f00 C1: 0x00e8407 emmc: 100000000 actual: 377358 div: 0x00000084 target: 400000 min: 390000 max: 400000 delay: 5
MESS:00:02:03.319520:0: Failed to open command line file 'cmdline.txt'
MESS:00:02:07.323309:0: gpioman: gpioman_get_pin_num: pin SDCARD_CONTROL_POWER not defined
MESS:00:02:07.328525:0: gpioman: gpiman_get_pin_num: pin SDCARD_CONTROL_POWER not defined
MESS:00:02:07.436448:0: gpioman: gpioman_get_pin_num: pin SDCARD_CONTROL_POWER not defined
MESS:00:02:07.445766:0: arasan: arasan_emmc_set_clock C0: 0x00800000 C1: 0x000e8007 emmc: 100000000 actual: 390625 div: 0x0000000 target: 400000 min: 400000 max: 400000 delay: 5
MESS:00:02:07.458645:0: arasan: arasan_emmc_set_clock C0: 0x00800f00 C1: 0x00e8507 emmc: 100000000 actual: 375939 div: 0x00000085 target: 400000 min: 390000 max: 400000 delay: 5
MESS:00:02:11.691784:0: gpioman: gpioman_get_pin_num: pin SDCARD_CONTROL_POWER not defined
MESS:00:02:11.696944:0: No compatibl kernel found
MESS:00:02:11.701464:0: gpioman: gpioman_get_pin_num: pin LEDS_PWR_OK not defined
(last message repeated every ~4 seconds)

Nit-pick: e missing from compatibl(e).

N.B. This cluster has 4x CM4 units with identical configuration - the remainder are still on firmware 1733575168 ("Sat 7 Dec 12:39:28 UTC 2024") but work as expected with the same configuration, and I've confirmed by booting the failing node in MSD mode that the md5sums of the kernel images are identical across all four nodes.

Device (s)

Raspberry Pi CM4

Bootloader configuration.

[all]
BOOT_UART=1
[pi4]
SDRAM_BANKLOW=3

System

n/a - system won't boot

Kernel is (/dev/mmcblk0p2)/6.6.74_p20250127/kernel8.img (9337714 bytes, md5sum df21701e93d074637bfa25fe00c88298) with config.txt:

[all]
disable_overscan=1
[pi4]
arm_boost=1
[cm4]
camera_auto_detect=0
display_auto_detect=0
dtparam=noant=on,hdmi=off,sd_poll_once=on,spi=on
dtoverlay=audremap
dtoverlay=disable-bt
dtoverlay=disable-wifi
dtoverlay=ramoops-pi4,console-size=16384
dtoverlay=spi-gpio40-45
max_framebuffers=0
[all]
arm_64bit=1
boot_delay=0
disable_poe_fan=1
disable_splash=1
enable_uart=1
force_eeprom_read=0
os_prefix=6.6.74_p20250127/
[cm4]
otg_mode=1
[all]
uart_2ndstage=1
include overclock.txt
include legacy.txt

Where all directives in overclock.txt and legacy.txt are commented.

Bootloader logs

(See above)

USB boot

n/a

NVMe boot

n/a

Network (TFTP boot)

n/a

@pelwell
Copy link
Collaborator

pelwell commented Feb 17, 2025

Nit-pick: e missing from compatibl(e).

Nit-pick: "l" missing from "Faied to load Device Tree file".

Both are present in the source - you are losing characters somewhere.

@timg236
Copy link
Collaborator

timg236 commented Feb 17, 2025

Re: Nit-pick: e missing from compatibl(e).
It looks like characters are being lost on your UART :"e.g. recvery.elf not found"

It looks like the bootloader successfully loaded start.elf from partition1 but start.elf cannot read from the disk. It's GPT partition layout which isn't well supported.

What's the partition layout?

@timg236
Copy link
Collaborator

timg236 commented Feb 17, 2025

Re partition layout. This is possible the same as this issue - there's a pre-release start4.elf attached to that Issue
#654

@srcshelton
Copy link
Author

Both are present in the source - you are losing characters somewhere.

Fair - the BMC UART implementation has always been a bit dodgy (to say the least…)

@srcshelton
Copy link
Author

srcshelton commented Feb 17, 2025

What's the partition layout?

$ fdisk -l /dev/sdb
Disk /dev/sdb: 29.12 GiB, 31268536320 bytes, 61071360 sectors
Disk model: 0001            
Units: sectors of 1 * 512 = 512 bytes
Sector size (logical/physical): 512 bytes / 512 bytes
I/O size (minimum/optimal): 512 bytes / 512 bytes
Disklabel type: gpt
Disk identifier: xxxx

Device         Start      End  Sectors  Size Type
/dev/sdb1       6144  2103295  2097152    1G Linux root (ARM-64)
/dev/sdb2    2103296  2234367   131072   64M Microsoft basic data
/dev/sdb3    2234368 14817279 12582912    6G Linux variable data
/dev/sdb4   14817280 23205887  8388608    4G Linux /usr (ARM-64)
/dev/sdb5   23205888 27400191  4194304    2G Linux home
/dev/sdb6   27400192 29497343  2097152    1G Linux filesystem
/dev/sdb7   29497344 30537727  1040384  508M Linux swap
/dev/sdb64  30537728 32634879  2097152    1G Linux root (ARM-64)
/dev/sdb65  32634880 32765951   131072   64M Microsoft basic data
/dev/sdb66  32765952 45348863 12582912    6G Linux variable data
/dev/sdb67  45348864 53737471  8388608    4G Linux /usr (ARM-64)
/dev/sdb68  53737472 57931775  4194304    2G Linux home
/dev/sdb69  57931776 60028927  2097152    1G Linux filesystem
/dev/sdb70  60028928 61069311  1040384  508M Linux swap
/dev/sdb128     2048     6143     4096    2M Microsoft basic data

Partition table entries are not in disk order.

This has always worked to date, and with firmware releases up to and including 1733575168 (the three other nodes and several other RPi devices have a similar setup, differing only in partition size w.r.t total device capacity).

@srcshelton
Copy link
Author

srcshelton commented Feb 17, 2025

Re partition layout. This is possible the same as this issue - there's a pre-release start4.elf attached to that Issue #654

Yup, that's fixed it!

That's a pretty severe regression between 1733575168 and 1739293213 :(

Are all platforms affected - I've got a remote (and hard to access) RPi5 with a very similar partition-scheme which I luckily held off from updating? 😯

@ragazenta
Copy link

I also got this problem on Pi 4B. I use GPT partition via systemd-repart.

I see that content of rpi-eeprom, bootloader-2711/default was updated recently, I thought it will be frozen at 2024-04-15, which worked well. In the mean time I think it's safe to downgrade to 2024-04-15 for Pi 4B.

Bootloader Version Firmware Version Works
1739293213 (2025/02/11 17:00:13) b25f3428a3370a5685ee026a7d0d6557438f078d (Jan 16 2025 15:54:38 ) (pre-release) Yes ✅
1739293213 (2025/02/11 17:00:13) 2ae30f53898ae2f1ba77ff570a92991bedfb0398 (Nov 26 2024 12:52:28) No ❌
1713186734 (2024/04/15 14:12:14) 2ae30f53898ae2f1ba77ff570a92991bedfb0398 (Nov 26 2024 12:52:28) Yes ✅

@timg236
Copy link
Collaborator

timg236 commented Feb 18, 2025

I believe the issue is that the bootloader now correctly passes the partition number (resolves 0 to actual number) and passes it to start.elf. Start.elf has never previously correctly handled non-default partition numbers with GPT partitions.

N.B. In any A/B boot-system I would recommend putting all the FAT/EFI partitions together at the start of the GPT or in the MBR world put A/B boot in the first primary partitions and put rootfs as the last or in extended.

@timg236
Copy link
Collaborator

timg236 commented Feb 18, 2025

The start.elf updates should now be in rpi-update
raspberrypi/firmware@9995946

@srcshelton
Copy link
Author

I see the recent update's ChangeLog states:

Walk the partition table if the requested partition is not bootable and PARTITION_WALK is set in the bootloader config

… would PARTITION_WALK need to be set to resolve this issue, or should things just-work?

@timg236
Copy link
Collaborator

timg236 commented Feb 18, 2025

PARTITION_WALK shouldn't have any effect - it's specific to the bootloader (not start.elf) and is to handle the case where autoboot.txt is missing e.g. on PARTITION 1 - where the real boot partitions are 2 and 3

@timg236
Copy link
Collaborator

timg236 commented Feb 18, 2025

Does the updated start.elf resolve the problem for you? Otherwise, it would be useful to see the logs for a good boot from before.

The relevant lines would be

2.74 Matched GUID bootable-part-idx 0 want partition 0
2.80 type: 32 lba: 2103296 'SD 4.4' ' BOOT_0 ' clusters 129024 (1)
...
3.57 Starting start4.elf @ 0xfec00200 partition 1
...

i.e. was a different boot partition matched the bootloader and what was the partition number that was passed to start.elf. Zero means default and in the case of GPT 1 means the first EFI/FAT part in the GPT table.

@stapelberg
Copy link

I also ran into this issue with https://gokrazy.org/: Updating my Raspberry Pi 4’s EEPROM to bad328a resulted in a no-longer booting system.

Updating the firmware to raspberrypi/firmware@9995946 does indeed fix the issue for me.

Just in case it helps further narrow down/confirm the problem, my partition layout is:

% sudo fdisk -l /dev/mmcblk0
Disk /dev/mmcblk0: 14,84 GiB, 15931539456 bytes, 31116288 sectors
Units: sectors of 1 * 512 = 512 bytes
Sector size (logical/physical): 512 bytes / 512 bytes
I/O size (minimum/optimal): 512 bytes / 512 bytes
Disklabel type: gpt
Disk identifier: 60C24CC1-F3F9-427A-8199-73B10A8B0000

Device           Start      End  Sectors  Size Type
/dev/mmcblk0p1    8192   212991   204800  100M EFI System
/dev/mmcblk0p2  212992  1236991  1024000  500M Linux root (ARM-64)
/dev/mmcblk0p3 1236992  2260991  1024000  500M Linux filesystem
/dev/mmcblk0p4 2260992 31116253 28855262 13,8G Linux filesystem

(The code which generates the MBR+GPT partition table is at https://github.com/gokrazy/tools/blob/8bcde52fb89a27075b0262fe617a96b5d8a90636/packer/packer.go#L433)

@timg236
Copy link
Collaborator

timg236 commented Feb 21, 2025

To know for sure I would need to see the UART log from the old bootloader but it does appear that the answer it is to update the RPi 4 firmware first before updating the bootloader. Hopefully, the start4.elf firmware will be in an APT release before too long.
The issues is that older start4.elf does not properly handle the partition number parameter with GPT partitions.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

5 participants