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

RPi4 reboot hangs with "kernel not found" blinks when running at 4kp60 #1763

Closed
HiassofT opened this issue Dec 6, 2022 · 22 comments
Closed

Comments

@HiassofT
Copy link

HiassofT commented Dec 6, 2022

Describe the bug
When rebooting my RPi4 4GB rev 1.1 connected to a 4K TV rebooting often hangs at the rainbow splash and UART reports that it could not read cmdline.txt and kernel.img from SD card.

The issue is a bit intermittent, sometimes they survive about 5 reboots but quite often the first reboot already fails.

I reproduced that with 2 rev 1.1 RPi4s and 3 different SD cards (two Sandisk Extreme 32G and one Sandisk Extreme Pro 32GB).

To reproduce
The key point seems to be that 4kp60 is enabled and the RPi is connected to a 4kp60 capable TV - or the edid of the 4k TV is used - I've used the latter to reproduce it without any peripherals except serial console connected.

I used this config.txt with the attached edid file lg-55c8.bin.zip

uart_2ndstage=1

dtoverlay=disable-bt

hdmi_enable_4kp60=1
hdmi_edid_filename:0=lg-55c8.bin
hdmi_edid_file=1

I dd a lot of reboots with and without 4kp60 enabled when connected to a 1920x1200 monitor and that worked fine (boot-looping for an hour).

Expected behaviour
RPi4 reboots fine without locking up in firmware.

Actual behaviour
On an unsuccessful reboot firmware reports that it couldn't load files from the SD card.

System

  • Which model of Raspberry Pi? e.g. Pi3B+, PiZeroW
    RPi4 4GB rev 1.1. cpuinfo:
Hardware	: BCM2711
Revision	: c03111
Serial		: 100000008eb25f41
Model		: Raspberry Pi 4 Model B Rev 1.1
  • Which OS and version (cat /etc/rpi-issue)?
    RPi OS Bullseye Lite, fully updated yesterday
Raspberry Pi reference 2022-01-28
Generated using pi-gen, https://github.com/RPi-Distro/pi-gen, f01430c9d8f67a4b9719cc00e74a2079d3834d5d, stage2
  • Which firmware version (vcgencmd version)?
Nov 11 2022 11:13:01 
Copyright (c) 2012 Broadcom
version 1a79bba5cc84ea52d15809fff557479fdf084529 (clean) (release) (start)
  • Which kernel version (uname -a)?
Linux raspberrypi 5.15.80-v7l+ #1602 SMP Tue Nov 29 14:45:31 GMT 2022 armv7l GNU/Linux

bootloader:

root@raspberrypi:~# rpi-eeprom-update 
BOOTLOADER: up to date
   CURRENT: Fri 25 Nov 2022 10:54:13 AM UTC (1669373653)
    LATEST: Fri 25 Nov 2022 10:54:13 AM UTC (1669373653)
   RELEASE: default (/lib/firmware/raspberrypi/bootloader/default)
            Use raspi-config to change the release.

  VL805_FW: Dedicated VL805 EEPROM
     VL805: up to date
   CURRENT: 000138a1
    LATEST: 000138a1
root@raspberrypi:~# rpi-eeprom-config 
[all]
BOOT_UART=1
WAKE_ON_GPIO=0
POWER_OFF_ON_HALT=1
BOOT_ORDER=0xf21
NET_INSTALL_ENABLED=0

Logs
Serial console log from an unsuccessful reboot:

[   29.005436] reboot: Restarting system

RPi: BOOTLOADER release VERSION:850fab5f DATE: 2022/11/25 TIME: 10:54:13
BOOTMODE: 0x06 partition 0 build-ts BUILD_TIMESTAMP=1669373653 serial 8eb25f41 boardrev c03111 stc 406430
PM_RSTS: 0x00001020
part 00000000 reset_info 00000000
uSD voltage 3.3V
Initialising SDRAM 'Micron' 16Gb x2 total-size: 32 Gbit 3200
DDR 3200 1 0 32 152

XHCI-STOP
xHC ver: 256 HCS: 05000420 fc000031 00e70004 HCC: 002841eb
USBSTS 1
xHC ver: 256 HCS: 05000420 fc000031 00e70004 HCC: 002841eb
xHC ports 5 slots 32 intrs 4
Reset USB port-power 1000 ms
xhci_set_port_power 1 0
xhci_set_port_power 2 0
xhci_set_port_power 3 0
xhci_set_port_power 4 0
xhci_set_port_power 5 0
xhci_set_port_power 1 1
xhci_set_port_power 2 1
xhci_set_port_power 3 1
xhci_set_port_power 4 1
xhci_set_port_power 5 1
XHCI-STOP
xHC ver: 256 HCS: 05000420 fc000031 00e70004 HCC: 002841eb
USBSTS 18
XHCI-STOP
xHC ver: 256 HCS: 05000420 fc000031 00e70004 HCC: 002841eb
USBSTS 19
xHC ver: 256 HCS: 05000420 fc000031 00e70004 HCC: 002841eb
xHC ports 5 slots 32 intrs 4
Boot mode: SD (01) order f2
SD HOST: 200000000 CTL0: 0x00800000 BUS: 400000 Hz actual: 390625 HZ div: 512 (256) status: 0x1fff0000 delay: 276
SD HOST: 200000000 CTL0: 0x00800f00 BUS: 400000 Hz actual: 390625 HZ div: 512 (256) status: 0x1fff0000 delay: 276
OCR c0ff8000 [14]
CID: 00035344534533324780bae4399a0122
CSD: 400e00325b590000edc87f800a404000
SD: bus-width: 4 spec: 2 SCR: 0x02358443 0x00000000
SD HOST: 200000000 CTL0: 0x00800f04 BUS: 50000000 Hz actual: 50000000 HZ div: 4 (2) status: 0x1fff0000 delay: 2
MBR: 0x00002000,  524288 type: 0x0c
MBR: 0x00082000,61801472 type: 0x83
MBR: 0x00000000,       0 type: 0x00
MBR: 0x00000000,       0 type: 0x00
Trying partition: 0
type: 32 lba: 8192 oem: 'mkfs.fat' volume: ' boot       '
rsc 32 fat-sectors 4033 c-count 516190 c-size 1
root dir cluster 2 sectors 0 entries 0
FAT32 clusters 516190
Trying partition: 0
type: 32 lba: 8192 oem: 'mkfs.fat' volume: ' boot       '
rsc 32 fat-sectors 4033 c-count 516190 c-size 1
root dir cluster 2 sectors 0 entries 0
FAT32 clusters 516190
Read config.txt bytes      109 hnd 0x1e
Read start4.elf bytes  2250688 hnd 0xcecb
Read fixup4.dat bytes     5398 hnd 0x15507
0x00c03111 0x00000000 0x00001fff
MEM GPU: 76 ARM: 948 TOTAL: 1024
Firmware: 1a79bba5cc84ea52d15809fff557479fdf084529 Nov 11 2022 11:13:01
Starting start4.elf @ 0xfec00200 partition 0
XHCI-STOP
xHC ver: 256 HCS: 05000420 fc000031 00e70004 HCC: 002841eb
USBSTS 8
+

MESS:00:00:04.048458:0: arasan: arasan_emmc_open
MESS:00:00:04.211226:0: brfs: File read: /mfs/sd/config.txt
MESS:00:00:04.213960:0: brfs: File read: 109 bytes
MESS:00:00:04.242379:0: brfs: File read: /mfs/sd/lg-55c8.bin
MESS:00:00:04.259045:0: HDMI1:EDID error reading EDID block 0 attempt 0
MESS:00:00:04.263552:0: HDMI1:EDID giving up on reading EDID block 0
MESS:00:00:04.268694:0: brfs: File read: 256 bytes
MESS:00:00:04.279807:0: brfs: File read: /mfs/sd/config.txt
MESS:00:00:04.730905:0: gpioman: gpioman_get_pin_num: pin DISPLAY_DSI_PORT not defined
MESS:00:00:04.738225:0: *** Restart logging
MESS:00:00:04.739629:0: brfs: File read: 109 bytes
MESS:00:00:04.762247:0: hdmi: HDMI1:EDID error reading EDID block 0 attempt 0
MESS:00:00:04.767268:0: hdmi: HDMI1:EDID giving up on reading EDID block 0
MESS:00:00:04.777887:0: hdmi: HDMI1:EDID error reading EDID block 0 attempt 0
MESS:00:00:04.782914:0: hdmi: HDMI1:EDID giving up on reading EDID block 0
MESS:00:00:04.788511:0: hdmi: HDMI:hdmi_get_state is deprecated, use hdmi_get_display_state instead
MESS:00:00:04.797276:0: HDMI0: hdmi_pixel_encoding: 600000000
MESS:00:00:04.802745:0: HDMI1: hdmi_pixel_encoding: 162000000
MESS:00:00:04.813009:0: dtb_file 'bcm2711-rpi-4-b.dtb'
MESS:00:00:04.823967:0: brfs: File read: /mfs/sd/bcm2711-rpi-4-b.dtb
MESS:00:00:04.827212:0: Loaded 'bcm2711-rpi-4-b.dtb' to 0x100 size 0xcc65
MESS:00:00:04.845644:0: brfs: File read: 52325 bytes
MESS:00:00:16.862060:0: gpioman: gpioman_get_pin_num: pin SDCARD_CONTROL_POWER not defined
MESS:00:00:16.867263:0: gpioman: gpioman_get_pin_num: pin SDCARD_CONTROL_POWER not defined
MESS:00:00:16.975202:0: gpioman: gpioman_get_pin_num: pin SDCARD_CONTROL_POWER not defined
MESS:00:00:17.022461:0: gpioman: gpioman_get_pin_num: pin SDCARD_CONTROL_WRITE_PROTECTED not defined
MESS:00:00:17.038422:0: dterror: fread failed
MESS:00:00:17.114515:0: Failed to open command line file 'cmdline.txt'
MESS:00:00:17.220042:0: kernel=
MESS:00:00:17.220254:0: No compatible kernel found
MESS:00:00:17.224582:0: Device tree loaded to 0x2eff2d00 (size 0xd2b4)

This is the log from the successful cold boot just before that

RPi: BOOTLOADER release VERSION:850fab5f DATE: 2022/11/25 TIME: 10:54:13
BOOTMODE: 0x06 partition 0 build-ts BUILD_TIMESTAMP=1669373653 serial 8eb25f41 boardrev c03111 stc 589821
PM_RSTS: 0x00001000
part 00000000 reset_info 00000000
uSD voltage 3.3V
Initialising SDRAM 'Micron' 16Gb x2 total-size: 32 Gbit 3200
DDR 3200 1 0 32 152

XHCI-STOP
xHC ver: 256 HCS: 05000420 fc000031 00e70004 HCC: 002841eb
USBSTS 11
xHC ver: 256 HCS: 05000420 fc000031 00e70004 HCC: 002841eb
xHC ports 5 slots 32 intrs 4
Reset USB port-power 1000 ms
xhci_set_port_power 1 0
xhci_set_port_power 2 0
xhci_set_port_power 3 0
xhci_set_port_power 4 0
xhci_set_port_power 5 0
xhci_set_port_power 1 1
xhci_set_port_power 2 1
xhci_set_port_power 3 1
xhci_set_port_power 4 1
xhci_set_port_power 5 1
XHCI-STOP
xHC ver: 256 HCS: 05000420 fc000031 00e70004 HCC: 002841eb
USBSTS 18
XHCI-STOP
xHC ver: 256 HCS: 05000420 fc000031 00e70004 HCC: 002841eb
USBSTS 19
xHC ver: 256 HCS: 05000420 fc000031 00e70004 HCC: 002841eb
xHC ports 5 slots 32 intrs 4
Boot mode: SD (01) order f2
SD HOST: 200000000 CTL0: 0x00800000 BUS: 400000 Hz actual: 390625 HZ div: 512 (256) status: 0x1fff0000 delay: 276
SD HOST: 200000000 CTL0: 0x00800f00 BUS: 400000 Hz actual: 390625 HZ div: 512 (256) status: 0x1fff0000 delay: 276
OCR c0ff8000 [15]
CID: 00035344534533324780bae4399a0122
CSD: 400e00325b590000edc87f800a404000
SD: bus-width: 4 spec: 2 SCR: 0x02358443 0x00000000
SD HOST: 200000000 CTL0: 0x00800f04 BUS: 50000000 Hz actual: 50000000 HZ div: 4 (2) status: 0x1fff0000 delay: 2
MBR: 0x00002000,  524288 type: 0x0c
MBR: 0x00082000,61801472 type: 0x83
MBR: 0x00000000,       0 type: 0x00
MBR: 0x00000000,       0 type: 0x00
Trying partition: 0
type: 32 lba: 8192 oem: 'mkfs.fat' volume: ' boot       '
rsc 32 fat-sectors 4033 c-count 516190 c-size 1
root dir cluster 2 sectors 0 entries 0
FAT32 clusters 516190
Trying partition: 0
type: 32 lba: 8192 oem: 'mkfs.fat' volume: ' boot       '
rsc 32 fat-sectors 4033 c-count 516190 c-size 1
root dir cluster 2 sectors 0 entries 0
FAT32 clusters 516190
Read config.txt bytes      109 hnd 0x1e
Read start4.elf bytes  2250688 hnd 0xcecb
Read fixup4.dat bytes     5398 hnd 0x15507
0x00c03111 0x00000000 0x00001fff
MEM GPU: 76 ARM: 948 TOTAL: 1024
Firmware: 1a79bba5cc84ea52d15809fff557479fdf084529 Nov 11 2022 11:13:01
Starting start4.elf @ 0xfec00200 partition 0
XHCI-STOP
xHC ver: 256 HCS: 05000420 fc000031 00e70004 HCC: 002841eb
USBSTS 8
+

MESS:00:00:04.232731:0: arasan: arasan_emmc_open
MESS:00:00:04.397884:0: brfs: File read: /mfs/sd/config.txt
MESS:00:00:04.400629:0: brfs: File read: 109 bytes
MESS:00:00:04.427131:0: brfs: File read: /mfs/sd/lg-55c8.bin
MESS:00:00:04.443797:0: HDMI1:EDID error reading EDID block 0 attempt 0
MESS:00:00:04.448304:0: HDMI1:EDID giving up on reading EDID block 0
MESS:00:00:04.453446:0: brfs: File read: 256 bytes
MESS:00:00:04.464279:0: brfs: File read: /mfs/sd/config.txt
MESS:00:00:04.948708:0: gpioman: gpioman_get_pin_num: pin DISPLAY_DSI_PORT not defined
MESS:00:00:04.956026:0: *** Restart logging
MESS:00:00:04.957432:0: brfs: File read: 109 bytes
MESS:00:00:04.979923:0: hdmi: HDMI1:EDID error reading EDID block 0 attempt 0
MESS:00:00:04.984944:0: hdmi: HDMI1:EDID giving up on reading EDID block 0
MESS:00:00:04.995564:0: hdmi: HDMI1:EDID error reading EDID block 0 attempt 0
MESS:00:00:05.003900:0: hdmi: HDMI1:EDID giving up on reading EDID block 0
MESS:00:00:05.007661:0: hdmi: HDMI:hdmi_get_state is deprecated, use hdmi_get_display_state instead
MESS:00:00:05.016424:0: HDMI0: hdmi_pixel_encoding: 600000000
MESS:00:00:05.021899:0: HDMI1: hdmi_pixel_encoding: 162000000
MESS:00:00:05.032179:0: dtb_file 'bcm2711-rpi-4-b.dtb'
MESS:00:00:05.042482:0: brfs: File read: /mfs/sd/bcm2711-rpi-4-b.dtb
MESS:00:00:05.045727:0: Loaded 'bcm2711-rpi-4-b.dtb' to 0x100 size 0xcc65
MESS:00:00:05.064504:0: brfs: File read: 52325 bytes
MESS:00:00:05.080142:0: brfs: File read: /mfs/sd/overlays/overlay_map.dtb
MESS:00:00:05.154028:0: brfs: File read: 2259 bytes
MESS:00:00:05.159312:0: brfs: File read: /mfs/sd/config.txt
MESS:00:00:05.162247:0: brfs: File read: 109 bytes
MESS:00:00:05.171563:0: brfs: File read: /mfs/sd/overlays/disable-bt.dtbo
MESS:00:00:05.189008:0: Loaded overlay 'disable-bt'
MESS:00:00:05.227266:0: brfs: File read: 1073 bytes
MESS:00:00:05.232526:0: brfs: File read: /mfs/sd/cmdline.txt
MESS:00:00:05.235091:0: Read command line from file 'cmdline.txt':
MESS:00:00:05.240970:0: 'console=serial0,115200 console=tty1 root=PARTUUID=819c33dd-02 rootfstype=ext4 fsck.repair=yes rootwait'
MESS:00:00:05.353141:0: kernel=
MESS:00:00:05.353182:0: brfs: File read: 103 bytes
MESS:00:00:05.919822:0: brfs: File read: /mfs/sd/kernel7l.img
MESS:00:00:05.922466:0: Loaded 'kernel7l.img' to 0x8000 size 0x6b8a48
MESS:00:00:05.928642:0: Device tree loaded to 0x2eff2d00 (size 0xd21e)
MESS:00:00:05.936568:0: uart: Set PL011 baud rate to 103448.300000 Hz
MESS:00:00:05.943947:0: uart: Baud rate change done...
MESS:00:00:05.945967:0: uart: Baud rate change done...
MESS:00:00:05.951107:0: gpioman: gpioman_get_pin_num: pin SDCARD_CONTROL_POWER not defined
[    0.000000] Booting Linux on physical CPU 0x0
[    0.000000] Linux version 5.15.80-v7l+ (dom@buildbot) (arm-linux-gnueabihf-gcc-8 (Ubuntu/Linaro 8.4.0-3ubuntu1) 8.4.0, GNU ld (GNU Binutils for Ubuntu) 2.34) #1602 SMP Tue Nov 29 14:45:31 GMT 2022
[    0.000000] CPU: ARMv7 Processor [410fd083] revision 3 (ARMv7), cr=30c5383d
[    0.000000] CPU: div instructions available: patching division code
[    0.000000] CPU: PIPT / VIPT nonaliasing data cache, PIPT instruction cache
[    0.000000] OF: fdt: Machine model: Raspberry Pi 4 Model B Rev 1.1
[    0.000000] random: crng init done
[    0.000000] Memory policy: Data cache writealloc
[    0.000000] Reserved memory: created CMA memory pool at 0x000000002ac00000, size 64 MiB
[    0.000000] OF: reserved mem: initialized node linux,cma, compatible id shared-dma-pool
[    0.000000] Zone ranges:
[    0.000000]   DMA      [mem 0x0000000000000000-0x000000002fffffff]
[    0.000000]   Normal   empty
[    0.000000]   HighMem  [mem 0x0000000030000000-0x00000000fbffffff]
[    0.000000] Movable zone start for each node
[    0.000000] Early memory node ranges
[    0.000000]   node   0: [mem 0x0000000000000000-0x000000003b3fffff]
[    0.000000]   node   0: [mem 0x0000000040000000-0x00000000fbffffff]
[    0.000000] Initmem setup node 0 [mem 0x0000000000000000-0x00000000fbffffff]
[    0.000000] percpu: Embedded 16 pages/cpu s35788 r8192 d21556 u65536
[    0.000000] Built 1 zonelists, mobility grouping on.  Total pages: 1011008
[    0.000000] Kernel command line: coherent_pool=1M 8250.nr_uarts=1 snd_bcm2835.enable_compat_alsa=0 snd_bcm2835.enable_hdmi=1 bcm2708_fb.fbwidth=3744 bcm2708_fb.fbheight=2064 bcm2708_fb.fbswap=1 smsc95xx.macaddr=DC:A6:32:3E:F4:78 vc_mem.mem_base=0x3ec00000 vc_mem.mem_size=0x40000000  console=ttyAMA0,115200 console=tty1 root=PARTUUID=819c33dd-02 rootfstype=ext4 fsck.repair=yes rootwait
[    0.000000] Dentry cache hash table entries: 131072 (order: 7, 524288 bytes, linear)
[    0.000000] Inode-cache hash table entries: 65536 (order: 6, 262144 bytes, linear)
[    0.000000] mem auto-init: stack:off, heap alloc:off, heap free:off
[    0.000000] software IO TLB: mapped [mem 0x0000000024890000-0x0000000028890000] (64MB)
[    0.000000] Memory: 3863984K/4050944K available (10240K kernel code, 1386K rwdata, 3308K rodata, 2048K init, 591K bss, 121424K reserved, 65536K cma-reserved, 3264512K highmem)
[    0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=4, Nodes=1
[    0.000000] ftrace: allocating 35511 entries in 105 pages
[    0.000000] ftrace: allocated 105 pages with 4 groups
[    0.000000] trace event string verifier disabled
[    0.000000] rcu: Hierarchical RCU implementation.
[    0.000000]  Rude variant of Tasks RCU enabled.
[    0.000000]  Tracing variant of Tasks RCU enabled.
[    0.000000] rcu: RCU calculated value of scheduler-enlistment delay is 10 jiffies.
[    0.000000] NR_IRQS: 16, nr_irqs: 16, preallocated irqs: 16
[    0.000000] GIC: Using split EOI/Deactivate mode
[    0.000000] arch_timer: cp15 timer(s) running at 54.00MHz (phys).
[    0.000000] clocksource: arch_sys_counter: mask: 0xffffffffffffff max_cycles: 0xc743ce346, max_idle_ns: 440795203123 ns
[    0.000000] sched_clock: 56 bits at 54MHz, resolution 18ns, wraps every 4398046511102ns
[    0.000022] Switching to timer-based delay loop, resolution 18ns
[    0.000372] Console: colour dummy device 80x30
[    0.001030] printk: console [tty1] enabled
[    0.001108] Calibrating delay loop (skipped), value calculated using timer frequency.. 108.00 BogoMIPS (lpj=540000)
[    0.001160] pid_max: default: 32768 minimum: 301
[    0.001312] LSM: Security Framework initializing
[    0.001522] Mount-cache hash table entries: 2048 (order: 1, 8192 bytes, linear)
[    0.001569] Mountpoint-cache hash table entries: 2048 (order: 1, 8192 bytes, linear)
[    0.003091] cgroup: Disabling memory control group subsystem
[    0.003337] CPU: Testing write buffer coherency: ok
[    0.003411] CPU0: Spectre BHB: enabling loop workaround for all CPUs
[    0.003850] CPU0: thread -1, cpu 0, socket 0, mpidr 80000000
[    0.005309] Setting up static identity map for 0x200000 - 0x20003c
[    0.005533] rcu: Hierarchical SRCU implementation.
[    0.006505] smp: Bringing up secondary CPUs ...
[    0.007633] CPU1: thread -1, cpu 1, socket 0, mpidr 80000001
[    0.008894] CPU2: thread -1, cpu 2, socket 0, mpidr 80000002
[    0.010172] CPU3: thread -1, cpu 3, socket 0, mpidr 80000003
[    0.010342] smp: Brought up 1 node, 4 CPUs
[    0.010421] SMP: Total of 4 processors activated (432.00 BogoMIPS).
[    0.010452] CPU: All CPU(s) started in HYP mode.
[    0.010478] CPU: Virtualization extensions available.
[    0.011221] devtmpfs: initialized
[    0.026258] VFP support v0.3: implementor 41 architecture 3 part 40 variant 8 rev 0
[    0.026501] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604462750000 ns
[    0.026556] futex hash table entries: 1024 (order: 4, 65536 bytes, linear)
[    0.028492] pinctrl core: initialized pinctrl subsystem
[    0.029753] NET: Registered PF_NETLINK/PF_ROUTE protocol family
[    0.033784] DMA: preallocated 1024 KiB pool for atomic coherent allocations
[    0.034592] audit: initializing netlink subsys (disabled)
[    0.034855] audit: type=2000 audit(0.030:1): state=initialized audit_enabled=0 res=1
[    0.035484] thermal_sys: Registered thermal governor 'step_wise'
[    0.036207] hw-breakpoint: found 5 (+1 reserved) breakpoint and 4 watchpoint registers.
[    0.036264] hw-breakpoint: maximum watchpoint size is 8 bytes.
[    0.036655] Serial: AMBA PL011 UART driver
[    0.047484] bcm2835-mbox fe00b880.mailbox: mailbox enabled
[    0.070011] raspberrypi-firmware soc:firmware: Attached to firmware from 2022-11-11T11:13:01, variant start
[    0.080022] raspberrypi-firmware soc:firmware: Firmware hash is 1a79bba5cc84ea52d15809fff557479fdf084529
[    0.138871] Kprobes globally optimized
[    0.144755] bcm2835-dma fe007000.dma: DMA legacy API manager, dmachans=0x1
[    0.149090] vgaarb: loaded
[    0.149553] SCSI subsystem initialized
[    0.149789] usbcore: registered new interface driver usbfs
[    0.149865] usbcore: registered new interface driver hub
[    0.149952] usbcore: registered new device driver usb
[    0.150791] usb_phy_generic phy: supply vcc not found, using dummy regulator
[    0.151000] usb_phy_generic phy: dummy supplies not allowed for exclusive requests
[    0.151352] pps_core: LinuxPPS API ver. 1 registered
[    0.151382] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti <giometti@linux.it>
[    0.151430] PTP clock support registered
[    0.152999] clocksource: Switched to clocksource arch_sys_counter
[    0.233737] VFS: Disk quotas dquot_6.6.0
[    0.233865] VFS: Dquot-cache hash table entries: 1024 (order 0, 4096 bytes)
[    0.234062] FS-Cache: Loaded
[    0.234271] CacheFiles: Loaded
[    0.244966] NET: Registered PF_INET protocol family
[    0.245209] IP idents hash table entries: 16384 (order: 5, 131072 bytes, linear)
[    0.246772] tcp_listen_portaddr_hash hash table entries: 512 (order: 0, 6144 bytes, linear)
[    0.246830] Table-perturb hash table entries: 65536 (order: 6, 262144 bytes, linear)
[    0.246875] TCP established hash table entries: 8192 (order: 3, 32768 bytes, linear)
[    0.246959] TCP bind hash table entries: 8192 (order: 4, 65536 bytes, linear)
[    0.247044] TCP: Hash tables configured (established 8192 bind 8192)
[    0.247199] UDP hash table entries: 512 (order: 2, 16384 bytes, linear)
[    0.247255] UDP-Lite hash table entries: 512 (order: 2, 16384 bytes, linear)
[    0.247524] NET: Registered PF_UNIX/PF_LOCAL protocol family
[    0.253897] RPC: Registered named UNIX socket transport module.
[    0.253930] RPC: Registered udp transport module.
[    0.253957] RPC: Registered tcp transport module.
[    0.253984] RPC: Registered tcp NFSv4.1 backchannel transport module.
[    0.254019] PCI: CLS 0 bytes, default 64
[    1.324488] hw perfevents: enabled with armv7_cortex_a7 PMU driver, 7 counters available
[    1.326854] Initialise system trusted keyrings
[    1.327160] workingset: timestamp_bits=14 max_order=20 bucket_order=6
[    1.336378] zbud: loaded
[    1.338224] FS-Cache: Netfs 'nfs' registered for caching
[    1.339067] NFS: Registering the id_resolver key type
[    1.339135] Key type id_resolver registered
[    1.339163] Key type id_legacy registered
[    1.339313] nfs4filelayout_init: NFSv4 File Layout Driver Registering...
[    1.339346] nfs4flexfilelayout_init: NFSv4 Flexfile Layout Driver Registering...
[    1.340525] Key type asymmetric registered
[    1.340557] Asymmetric key parser 'x509' registered
[    1.340797] bounce: pool size: 64 pages
[    1.340892] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 247)
[    1.341128] io scheduler mq-deadline registered
[    1.341159] io scheduler kyber registered
[    1.349442] brcm-pcie fd500000.pcie: host bridge /scb/pcie@7d500000 ranges:
[    1.349505] brcm-pcie fd500000.pcie:   No bus range found for /scb/pcie@7d500000, using [bus 00-ff]
[    1.349621] brcm-pcie fd500000.pcie:      MEM 0x0600000000..0x063fffffff -> 0x00c0000000
[    1.349735] brcm-pcie fd500000.pcie:   IB MEM 0x0000000000..0x00ffffffff -> 0x0400000000
[    1.405102] brcm-pcie fd500000.pcie: link up, 5.0 GT/s PCIe x1 (SSC)
[    1.405495] brcm-pcie fd500000.pcie: PCI host bridge to bus 0000:00
[    1.405531] pci_bus 0000:00: root bus resource [bus 00-ff]
[    1.405567] pci_bus 0000:00: root bus resource [mem 0x600000000-0x63fffffff] (bus address [0xc0000000-0xffffffff])
[    1.405676] pci 0000:00:00.0: [14e4:2711] type 01 class 0x060400
[    1.405934] pci 0000:00:00.0: PME# supported from D0 D3hot
[    1.409639] PCI: bus0: Fast back to back transfers disabled
[    1.409679] pci 0000:00:00.0: bridge configuration invalid ([bus 00-00]), reconfiguring
[    1.410071] pci 0000:01:00.0: [1106:3483] type 00 class 0x0c0330
[    1.410214] pci 0000:01:00.0: reg 0x10: [mem 0x00000000-0x00000fff 64bit]
[    1.410660] pci 0000:01:00.0: PME# supported from D0 D3cold
[    1.414362] PCI: bus1: Fast back to back transfers disabled
[    1.414399] pci_bus 0000:01: busn_res: [bus 01-ff] end is updated to 01
[    1.414455] pci 0000:00:00.0: BAR 8: assigned [mem 0x600000000-0x6000fffff]
[    1.414496] pci 0000:01:00.0: BAR 0: assigned [mem 0x600000000-0x600000fff 64bit]
[    1.414599] pci 0000:00:00.0: PCI bridge to [bus 01]
[    1.414638] pci 0000:00:00.0:   bridge window [mem 0x600000000-0x6000fffff]
[    1.415069] pcieport 0000:00:00.0: enabling device (0140 -> 0142)
[    1.415317] pcieport 0000:00:00.0: PME: Signaling with IRQ 57
[    1.416716] bcm2708_fb soc:fb: FB found 1 display(s)
[    1.577966] Console: switching to colour frame buffer device 468x129
[    1.615681] bcm2708_fb soc:fb: Registered framebuffer for display 0, size 3744x2064
[    1.622579] Serial: 8250/16550 driver, 1 ports, IRQ sharing enabled
[    1.625477] iproc-rng200 fe104000.rng: hwrng registered
[    1.625842] vc-mem: phys_addr:0x00000000 mem_base=0x3ec00000 mem_size:0x40000000(1024 MiB)
[    1.627340] gpiomem-bcm2835 fe200000.gpiomem: Initialised: Registers at 0xfe200000
[    1.640192] brd: module loaded
[    1.650638] loop: module loaded
[    1.651415] Loading iSCSI transport class v2.0-870.
[    1.656563] bcmgenet fd580000.ethernet: GENET 5.0 EPHY: 0x0000
[    1.753166] unimac-mdio unimac-mdio.-19: Broadcom UniMAC MDIO bus
[    1.754460] usbcore: registered new interface driver r8152
[    1.754593] usbcore: registered new interface driver lan78xx
[    1.754717] usbcore: registered new interface driver smsc95xx
[    1.756367] xhci_hcd 0000:01:00.0: enabling device (0140 -> 0142)
[    1.756592] xhci_hcd 0000:01:00.0: xHCI Host Controller
[    1.756681] xhci_hcd 0000:01:00.0: new USB bus registered, assigned bus number 1
[    1.761721] xhci_hcd 0000:01:00.0: hcc params 0x002841eb hci version 0x100 quirks 0x0000e40000000890
[    1.762904] xhci_hcd 0000:01:00.0: xHCI Host Controller
[    1.763027] xhci_hcd 0000:01:00.0: new USB bus registered, assigned bus number 2
[    1.763127] xhci_hcd 0000:01:00.0: Host supports USB 3.0 SuperSpeed
[    1.763615] usb usb1: New USB device found, idVendor=1d6b, idProduct=0002, bcdDevice= 5.15
[    1.763720] usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[    1.763810] usb usb1: Product: xHCI Host Controller
[    1.763877] usb usb1: Manufacturer: Linux 5.15.80-v7l+ xhci-hcd
[    1.763952] usb usb1: SerialNumber: 0000:01:00.0
[    1.764749] hub 1-0:1.0: USB hub found
[    1.764876] hub 1-0:1.0: 1 port detected
[    1.765976] usb usb2: New USB device found, idVendor=1d6b, idProduct=0003, bcdDevice= 5.15
[    1.766082] usb usb2: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[    1.766171] usb usb2: Product: xHCI Host Controller
[    1.766240] usb usb2: Manufacturer: Linux 5.15.80-v7l+ xhci-hcd
[    1.766315] usb usb2: SerialNumber: 0000:01:00.0
[    1.767102] hub 2-0:1.0: USB hub found
[    1.767232] hub 2-0:1.0: 4 ports detected
[    1.768942] dwc_otg: version 3.00a 10-AUG-2012 (platform bus)
[    1.769796] usbcore: registered new interface driver uas
[    1.769968] usbcore: registered new interface driver usb-storage
[    1.770280] mousedev: PS/2 mouse device common for all mice
[    1.775178] sdhci: Secure Digital Host Controller Interface driver
[    1.775267] sdhci: Copyright(c) Pierre Ossman
[    1.775898] sdhci-pltfm: SDHCI platform and OF driver helper
[    1.779464] ledtrig-cpu: registered to indicate activity on CPUs
[    1.779866] hid: raw HID events driver (C) Jiri Kosina
[    1.780118] usbcore: registered new interface driver usbhid
[    1.780192] usbhid: USB HID core driver
[    1.785668] Initializing XFRM netlink socket
[    1.785778] NET: Registered PF_PACKET protocol family
[    1.785945] Key type dns_resolver registered
[    1.786415] Registering SWP/SWPB emulation handler
[    1.787309] registered taskstats version 1
[    1.787393] Loading compiled-in X.509 certificates
[    1.788345] Key type .fscrypt registered
[    1.788412] Key type fscrypt-provisioning registered
[    1.800387] uart-pl011 fe201000.serial: there is not valid maps for state default
[    1.800756] uart-pl011 fe201000.serial: cts_event_workaround enabled
[    1.800968] fe201000.serial: ttyAMA0 at MMIO 0xfe201000 (irq = 32, base_baud = 0) is a PL011 rev2
[    2.133028] usb 1-1: new high-speed USB device number 2 using xhci_hcd
[    2.138784] printk: console [ttyAMA0] enabled
[    2.325717] usb 1-1: New USB device found, idVendor=2109, idProduct=3431, bcdDevice= 4.21
[    2.389796] bcm2835-wdt bcm2835-wdt: Broadcom BCM2835 watchdog timer
[    2.393233] usb 1-1: New USB device strings: Mfr=0, Product=1, SerialNumber=0
[    2.393252] usb 1-1: Product: USB2.0 Hub
[    2.397641] bcm2835-power bcm2835-power: Broadcom BCM2835 power domains driver
[    3.116404] mmc-bcm2835 fe300000.mmcnr: mmc_debug:0 mmc_debug2:0
[    3.116742] hub 1-1:1.0: USB hub found
[    3.122493] mmc-bcm2835 fe300000.mmcnr: DMA channel allocated
[    3.126561] hub 1-1:1.0: 4 ports detected
[    3.164114] of_cfs_init
[    3.167779] of_cfs_init: OK
[    3.209197] mmc0: SDHCI controller on fe340000.mmc [fe340000.mmc] using ADMA
[    3.216911] Waiting for root device PARTUUID=819c33dd-02...
[    3.280919] mmc1: new high speed SDIO card at address 0001
[    3.329598] mmc0: new ultra high speed DDR50 SDHC card at address aaaa
[    3.337117] mmcblk0: mmc0:aaaa SE32G 29.7 GiB
[    3.346715]  mmcblk0: p1 p2
[    3.350071] mmcblk0: mmc0:aaaa SE32G 29.7 GiB (quirks 0x00004000)
[    3.374834] EXT4-fs (mmcblk0p2): mounted filesystem with ordered data mode. Opts: (null). Quota mode: none.
[    3.384787] VFS: Mounted root (ext4 filesystem) readonly on device 179:2.
[    3.399905] devtmpfs: mounted
[    3.413911] Freeing unused kernel image (initmem) memory: 2048K
[    3.420210] Run /sbin/init as init process
[    3.802220] systemd[1]: System time before build time, advancing clock.
[    4.004753] NET: Registered PF_INET6 protocol family
[    4.011537] Segment Routing with IPv6
[    4.015321] In-situ OAM (IOAM) with IPv6
[    4.089168] systemd[1]: systemd 247.3-7+rpi1+deb11u1 running in system mode. (+PAM +AUDIT +SELINUX +IMA +APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 +ZSTD +SECCOMP +BLKID +ELFUTILS +KMOD +IDN2 -IDN +PCRE2 default-hierarchy=unified)
[    4.119750] systemd[1]: Detected architecture arm.
[    4.139982] systemd[1]: Set hostname to <raspberrypi>.
[    4.345877] uart-pl011 fe201000.serial: no DMA platform data
[    5.025358] systemd[1]: Queued start job for default target Graphical Interface.
[    5.039900] systemd[1]: Created slice system-getty.slice.
[    5.063804] systemd[1]: Created slice system-modprobe.slice.
[    5.087263] systemd[1]: Created slice system-serial\x2dgetty.slice.
[    5.111151] systemd[1]: Created slice system-systemd\x2dfsck.slice.
[    5.135063] systemd[1]: Created slice User and Session Slice.
[    5.157842] systemd[1]: Started Dispatch Password Requests to Console Directory Watch.
[    5.182851] systemd[1]: Started Forward Password Requests to Wall Directory Watch.
[    5.208208] systemd[1]: Set up automount Arbitrary Executable File Formats File System Automount Point.
[    5.234946] systemd[1]: Reached target Local Encrypted Volumes.
[    5.258062] systemd[1]: Reached target Paths.
[    5.279437] systemd[1]: Reached target Slices.
[    5.300921] systemd[1]: Reached target Swap.
[    5.323042] systemd[1]: Listening on Syslog Socket.
[    5.345594] systemd[1]: Listening on fsck to fsckd communication Socket.
[    5.369655] systemd[1]: Listening on initctl Compatibility Named Pipe.
[    5.394217] systemd[1]: Listening on Journal Audit Socket.
[    5.417536] systemd[1]: Listening on Journal Socket (/dev/log).
[    5.441293] systemd[1]: Listening on Journal Socket.
[    5.466808] systemd[1]: Listening on udev Control Socket.
[    5.490000] systemd[1]: Listening on udev Kernel Socket.
[    5.513223] systemd[1]: Condition check resulted in Huge Pages File System being skipped.
[    5.533706] systemd[1]: Mounting POSIX Message Queue File System...
[    5.563236] systemd[1]: Mounting RPC Pipe File System...
[    5.592070] systemd[1]: Mounting Kernel Debug File System...
[    5.621082] systemd[1]: Mounting Kernel Trace File System...
[    5.645004] systemd[1]: Condition check resulted in Kernel Module supporting RPCSEC_GSS being skipped.
[    5.669810] systemd[1]: Starting Restore / save the current clock...
[    5.700926] systemd[1]: Starting Set the console keyboard layout...
[    5.732363] systemd[1]: Starting Create list of static device nodes for the current kernel...
[    5.766527] systemd[1]: Starting Load Kernel Module configfs...
[    5.798202] systemd[1]: Starting Load Kernel Module drm...
[    5.828565] systemd[1]: Starting Load Kernel Module fuse...
[    5.856233] systemd[1]: Condition check resulted in Set Up Additional Binary Formats being skipped.
[    5.878545] systemd[1]: Starting File System Check on Root Device...
[    5.892472] fuse: init (API version 7.34)
[    5.926239] systemd[1]: Starting Journal Service...
[    5.967784] systemd[1]: Starting Load Kernel Modules...
[    6.029569] systemd[1]: Starting Coldplug All udev Devices...
[    6.081649] systemd[1]: Mounted POSIX Message Queue File System.
[    6.107640] systemd[1]: Mounted RPC Pipe File System.
[    6.132092] systemd[1]: Mounted Kernel Debug File System.
[    6.156205] systemd[1]: Mounted Kernel Trace File System.
[    6.181729] systemd[1]: Finished Restore / save the current clock.
[    6.216647] systemd[1]: Finished Create list of static device nodes for the current kernel.
[    6.245505] systemd[1]: Started Journal Service.

Raspbian GNU/Linux 11 raspberrypi ttyAMA0

raspberrypi login:

Additional context
I initially noticed the issue on LibreELEC master, running kernel 6.0 or 6.1, which showed the same behaviour

@popcornmix
Copy link
Contributor

Do you think this is a regression or has this issue always been present for you?
If a regression, any feel for whether it came with a bootloader or firmware update?

@timg236
Copy link

timg236 commented Dec 7, 2022

It looks like an issue with the 3.3V voltage switch on RPi 1.1 and earlier. Please could you give this a try.

rpi-eeprom-recovery.zip

@HiassofT
Copy link
Author

HiassofT commented Dec 7, 2022

I think it's a regression in the firmware but I can't tell when it occurred.

I've been running LE 9.2.8 (with ancient 2b76cfc firmware) and rather recent bootloaders on that RPi and didn't notice any reboot issues with that.

I had been using netboot to test LE10/11 on that RPi and just recently switched to running LE11 from SD card and noticed the issue.

I had been testing with SD cards and recent firmwares/bootloaders on other RPi4s in my office room but they were hooked up to non-4k monitors - and they were fine

@HiassofT
Copy link
Author

HiassofT commented Dec 7, 2022

@timg236 thanks a lot, I'll give it a try this evening after work!

@timg236
Copy link

timg236 commented Dec 7, 2022

I think the regression was introduced around April. I managed to find an RPi 1.0 and noticed that 3V3 was not being reset which appeared to cause the same symptoms that you reported. Failing to switch voltage isn't necessarily fatal on all cards, the 4Kp60 element isn't fully understood but system is in overclocked / voltage-boost state so there could be some subtle interaction there.

timg236 added a commit to timg236/rpi-eeprom that referenced this issue Dec 7, 2022
timg236 added a commit to timg236/rpi-eeprom that referenced this issue Dec 7, 2022
Fix issue where SD voltage was not reset by power cycling PMIC on reboot.

See raspberrypi/firmware#1763
@timg236
Copy link

timg236 commented Dec 7, 2022

The bootloader change seems good so I think we'll likely merge this since it's easy to verify it via 3V3.

There's possibly a secondary problem in start4.elf if there is no HDMI display connected and core_freq is boosted above 500MHz and force_turbo=1.

@HiassofT
Copy link
Author

HiassofT commented Dec 7, 2022

@timg236 thanks a lot, 2022-12-07 bootloader fixed the issue for me. I've found another bootloader bug though:

With 2022-04-26 and 2022-12-07 bootloader my scope confirmed that 3V3 is going low for about 50 ms on reboots and I saw the two bootloader init messages on console - 2022-05-20 and later didn't drop 3V3 and resulted in read errors.

However when doing a rpi-eeprom-update from 2022-04-26 to 2022-12-07 3V3 wasn't dropped and I was left with a similar non-boot situation:

BMD "vl805.bin" not found
SIG pieeprom.sig a61e9c976fb0d8aa7f900f33badd56af74bf66d047ccbb0ea50e1ff9c0f13d04 1670448824
Reading EEPROM: 524288
Writing EEPROM
+++++++++++.++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++***....+
Verify BOOT EEPROM
Reading EEPROM: 524288
BOOT-EEPROM: UPDATED
rename recovery.bin to RECOVERY.000
RESET

RPi: BOOTLOADER release VERSION:0fc8fc8e DATE: 2022/12/07 TIME: 14:24:15
BOOTMODE: 0x06 partition 0 build-ts BUILD_TIMESTAMP=1670423055 serial 8eb25f41 boardrev c03111 stc 405164
PM_RSTS: 0x00001020
part 00000000 reset_info 00000000
uSD voltage 3.3V
Initialising SDRAM 'Micron' 16Gb x2 total-size: 32 Gbit 3200
DDR 3200 1 0 32 152

XHCI-STOP
xHC ver: 256 HCS: 05000420 fc000031 00e70004 HCC: 002841eb
USBSTS 1
xHC ver: 256 HCS: 05000420 fc000031 00e70004 HCC: 002841eb
xHC ports 5 slots 32 intrs 4
Reset USB port-power 1000 ms
xhci_set_port_power 1 0
xhci_set_port_power 2 0
xhci_set_port_power 3 0
xhci_set_port_power 4 0
xhci_set_port_power 5 0
xhci_set_port_power 1 1
xhci_set_port_power 2 1
xhci_set_port_power 3 1
xhci_set_port_power 4 1
xhci_set_port_power 5 1
XHCI-STOP
xHC ver: 256 HCS: 05000420 fc000031 00e70004 HCC: 002841eb
USBSTS 18
XHCI-STOP
xHC ver: 256 HCS: 05000420 fc000031 00e70004 HCC: 002841eb
USBSTS 19
xHC ver: 256 HCS: 05000420 fc000031 00e70004 HCC: 002841eb
xHC ports 5 slots 32 intrs 4
Boot mode: SD (01) order f2
SD HOST: 200000000 CTL0: 0x00800000 BUS: 400000 Hz actual: 390625 HZ div: 512 (256) status: 0x1fff0000 delay: 276
SD HOST: 200000000 CTL0: 0x00800f00 BUS: 400000 Hz actual: 390625 HZ div: 512 (256) status: 0x1fff0000 delay: 276
OCR c0ff8000 [14]
CID: 00035344534533324780bae4399a0122
CSD: 400e00325b590000edc87f800a404000
SD: bus-width: 4 spec: 2 SCR: 0x02358443 0x00000000
SD HOST: 200000000 CTL0: 0x00800f04 BUS: 50000000 Hz actual: 50000000 HZ div: 4 (2) status: 0x1fff0000 delay: 2
MBR: 0x00002000,  524288 type: 0x0c
MBR: 0x00082000,61801472 type: 0x83
MBR: 0x00000000,       0 type: 0x00
MBR: 0x00000000,       0 type: 0x00
Trying partition: 0
type: 32 lba: 8192 oem: 'mkfs.fat' volume: ' boot       '
rsc 32 fat-sectors 4033 c-count 516190 c-size 1
root dir cluster 2 sectors 0 entries 0
FAT32 clusters 516190
Trying partition: 0
type: 32 lba: 8192 oem: 'mkfs.fat' volume: ' boot       '
rsc 32 fat-sectors 4033 c-count 516190 c-size 1
root dir cluster 2 sectors 0 entries 0
FAT32 clusters 516190
Read config.txt bytes      109 hnd 0x4c9
SIG pieeprom.sig a61e9c976fb0d8aa7f900f33badd56af74bf66d047ccbb0ea50e1ff9c0f13d04 1670448824
SELF-UPDATE timestamp current 1670448824 new 1670448824 skip
Read start4.elf bytes  2250688 hnd 0xcecb
Read fixup4.dat bytes     5398 hnd 0x15507
0x00c03111 0x00000000 0x00001fff
MEM GPU: 76 ARM: 948 TOTAL: 1024
Firmware: 1a79bba5cc84ea52d15809fff557479fdf084529 Nov 11 2022 11:13:01
Starting start4.elf @ 0xfec00200 partition 0
XHCI-STOP
xHC ver: 256 HCS: 05000420 fc000031 00e70004 HCC: 002841eb
USBSTS 8
+

MESS:00:00:04.151035:0: arasan: arasan_emmc_open
MESS:00:00:04.596765:0: brfs: File read: /mfs/sd/config.txt
MESS:00:00:04.599514:0: brfs: File read: 109 bytes
MESS:00:00:04.627759:0: brfs: File read: /mfs/sd/lg-55c8.bin
MESS:00:00:04.644432:0: HDMI1:EDID error reading EDID block 0 attempt 0
MESS:00:00:04.648939:0: HDMI1:EDID giving up on reading EDID block 0
MESS:00:00:04.654081:0: brfs: File read: 256 bytes
MESS:00:00:04.665074:0: brfs: File read: /mfs/sd/config.txt
MESS:00:00:05.116198:0: gpioman: gpioman_get_pin_num: pin DISPLAY_DSI_PORT not defined
MESS:00:00:05.123517:0: *** Restart logging
MESS:00:00:05.124922:0: brfs: File read: 109 bytes
MESS:00:00:05.147400:0: hdmi: HDMI1:EDID error reading EDID block 0 attempt 0
MESS:00:00:05.152422:0: hdmi: HDMI1:EDID giving up on reading EDID block 0
MESS:00:00:05.163041:0: hdmi: HDMI1:EDID error reading EDID block 0 attempt 0
MESS:00:00:05.168068:0: hdmi: HDMI1:EDID giving up on reading EDID block 0
MESS:00:00:05.173665:0: hdmi: HDMI:hdmi_get_state is deprecated, use hdmi_get_display_state instead
MESS:00:00:05.182430:0: HDMI0: hdmi_pixel_encoding: 600000000
MESS:00:00:05.187900:0: HDMI1: hdmi_pixel_encoding: 162000000
MESS:00:00:05.198179:0: dtb_file 'bcm2711-rpi-4-b.dtb'
MESS:00:00:17.209486:0: gpioman: gpioman_get_pin_num: pin SDCARD_CONTROL_POWER not defined
MESS:00:00:17.214696:0: gpioman: gpioman_get_pin_num: pin SDCARD_CONTROL_POWER not defined
MESS:00:00:17.322635:0: gpioman: gpioman_get_pin_num: pin SDCARD_CONTROL_POWER not defined
MESS:00:00:17.370238:0: gpioman: gpioman_get_pin_num: pin SDCARD_CONTROL_WRITE_PROTECTED not defined
MESS:00:00:17.390421:0: Loaded 'bcm2711-rpi-4-b.dtb' to 0x100 size 0x0
MESS:00:00:17.481460:0: Failed to read command line file 'cmdline.txt'
MESS:00:00:17.586922:0: kernel=
MESS:00:00:17.589254:0: Loaded 'kernel7l.img' to 0x8000 size 0x0
MESS:00:00:17.592687:0: Device tree loaded to 0x2eff2d00 (size 0xd29c)
MESS:00:00:17.600505:0: uart: Set PL011 baud rate to 103448.300000 Hz
MESS:00:00:17.608003:0: uart: Baud rate change done...
MESS:00:00:17.610021:0:

With 2022-12-07 bootloader I haven't noticed any issues with 4kp60 yet but it's still puzzling why rebooting eg with 2022-05-20 bootloader (or 2022-11-25 as in my initial report) seem to be working fine without 4kp60 and failing with 4kp60 enabled...

@HiassofT
Copy link
Author

HiassofT commented Dec 7, 2022

Just noticed updating from 2022-04-26 to 2022-12-07 wasn't a too good data point for testing 2022-12-07 bootloader but updating 2022-12-07 to 2022-12-07 resulted in the same issue - 3V3 not dropped, read errors.

root@raspberrypi:~# rpi-eeprom-update -f pieeprom-2022-12-07.bin 
*** INSTALLING pieeprom-2022-12-07.bin  ***

   CURRENT: Wed 07 Dec 2022 02:24:15 PM UTC (1670423055)
    UPDATE: Wed 07 Dec 2022 02:24:15 PM UTC (1670423055)
    BOOTFS: /boot
Using recovery.bin for EEPROM update

EEPROM updates pending. Please reboot to apply the update.
To cancel a pending update run "sudo rpi-eeprom-update -r".
root@raspberrypi:~# reboot
[  100.795449] reboot: Restarting system
BMD "vl805.bin" not found
SIG pieeprom.sig a61e9c976fb0d8aa7f900f33badd56af74bf66d047ccbb0ea50e1ff9c0f13d04 1670450713
Reading EEPROM: 524288
Writing EEPROM
...............................................................................................................................+
Verify BOOT EEPROM
Reading EEPROM: 524288
BOOT-EEPROM: UPDATED
rename recovery.bin to RECOVERY.000
RESET

RPi: BOOTLOADER release VERSION:0fc8fc8e DATE: 2022/12/07 TIME: 14:24:15
BOOTMODE: 0x06 partition 0 build-ts BUILD_TIMESTAMP=1670423055 serial 8eb25f41 boardrev c03111 stc 405202
PM_RSTS: 0x00000020
part 00000000 reset_info 00000000
uSD voltage 3.3V
Initialising SDRAM 'Micron' 16Gb x2 total-size: 32 Gbit 3200
DDR 3200 1 0 32 152

XHCI-STOP
xHC ver: 256 HCS: 05000420 fc000031 00e70004 HCC: 002841eb
USBSTS 1
xHC ver: 256 HCS: 05000420 fc000031 00e70004 HCC: 002841eb
xHC ports 5 slots 32 intrs 4
Reset USB port-power 1000 ms
xhci_set_port_power 1 0
xhci_set_port_power 2 0
xhci_set_port_power 3 0
xhci_set_port_power 4 0
xhci_set_port_power 5 0
xhci_set_port_power 1 1
xhci_set_port_power 2 1
xhci_set_port_power 3 1
xhci_set_port_power 4 1
xhci_set_port_power 5 1
XHCI-STOP
xHC ver: 256 HCS: 05000420 fc000031 00e70004 HCC: 002841eb
USBSTS 18
XHCI-STOP
xHC ver: 256 HCS: 05000420 fc000031 00e70004 HCC: 002841eb
USBSTS 19
xHC ver: 256 HCS: 05000420 fc000031 00e70004 HCC: 002841eb
xHC ports 5 slots 32 intrs 4
Boot mode: SD (01) order f2
SD HOST: 200000000 CTL0: 0x00800000 BUS: 400000 Hz actual: 390625 HZ div: 512 (256) status: 0x1fff0000 delay: 276
SD HOST: 200000000 CTL0: 0x00800f00 BUS: 400000 Hz actual: 390625 HZ div: 512 (256) status: 0x1fff0000 delay: 276
OCR c0ff8000 [14]
CID: 00035344534533324780bae4399a0122
CSD: 400e00325b590000edc87f800a404000
SD: bus-width: 4 spec: 2 SCR: 0x02358443 0x00000000
SD HOST: 200000000 CTL0: 0x00800f04 BUS: 50000000 Hz actual: 50000000 HZ div: 4 (2) status: 0x1fff0000 delay: 2
MBR: 0x00002000,  524288 type: 0x0c
MBR: 0x00082000,61801472 type: 0x83
MBR: 0x00000000,       0 type: 0x00
MBR: 0x00000000,       0 type: 0x00
Trying partition: 0
type: 32 lba: 8192 oem: 'mkfs.fat' volume: ' boot       '
rsc 32 fat-sectors 4033 c-count 516190 c-size 1
root dir cluster 2 sectors 0 entries 0
FAT32 clusters 516190
Trying partition: 0
type: 32 lba: 8192 oem: 'mkfs.fat' volume: ' boot       '
rsc 32 fat-sectors 4033 c-count 516190 c-size 1
root dir cluster 2 sectors 0 entries 0
FAT32 clusters 516190
Read config.txt bytes      109 hnd 0xe
SIG pieeprom.sig a61e9c976fb0d8aa7f900f33badd56af74bf66d047ccbb0ea50e1ff9c0f13d04 1670450713
SELF-UPDATE timestamp current 1670450713 new 1670450713 skip
Read start4.elf bytes  2250688 hnd 0xcecb
Read fixup4.dat bytes     5398 hnd 0x15507
0x00c03111 0x00000000 0x00001fff
MEM GPU: 76 ARM: 948 TOTAL: 1024
Firmware: 1a79bba5cc84ea52d15809fff557479fdf084529 Nov 11 2022 11:13:01
Starting start4.elf @ 0xfec00200 partition 0
XHCI-STOP
xHC ver: 256 HCS: 05000420 fc000031 00e70004 HCC: 002841eb
USBSTS 8
+

MESS:00:00:04.146219:0: arasan: arasan_emmc_open
MESS:00:00:04.592569:0: brfs: File read: /mfs/sd/config.txt
MESS:00:00:04.595304:0: brfs: File read: 109 bytes
MESS:00:00:04.623689:0: brfs: File read: /mfs/sd/lg-55c8.bin
MESS:00:00:04.640362:0: HDMI1:EDID error reading EDID block 0 attempt 0
MESS:00:00:04.644869:0: HDMI1:EDID giving up on reading EDID block 0
MESS:00:00:04.650011:0: brfs: File read: 256 bytes
MESS:00:00:04.661105:0: brfs: File read: /mfs/sd/config.txt
MESS:00:00:05.112523:0: gpioman: gpioman_get_pin_num: pin DISPLAY_DSI_PORT not defined
MESS:00:00:05.119842:0: *** Restart logging
MESS:00:00:05.121246:0: brfs: File read: 109 bytes
MESS:00:00:05.143828:0: hdmi: HDMI1:EDID error reading EDID block 0 attempt 0
MESS:00:00:05.148849:0: hdmi: HDMI1:EDID giving up on reading EDID block 0
MESS:00:00:05.159469:0: hdmi: HDMI1:EDID error reading EDID block 0 attempt 0
MESS:00:00:05.164496:0: hdmi: HDMI1:EDID giving up on reading EDID block 0
MESS:00:00:05.170094:0: hdmi: HDMI:hdmi_get_state is deprecated, use hdmi_get_display_state instead
MESS:00:00:05.178858:0: HDMI0: hdmi_pixel_encoding: 600000000
MESS:00:00:05.184328:0: HDMI1: hdmi_pixel_encoding: 162000000
MESS:00:00:05.194591:0: dtb_file 'bcm2711-rpi-4-b.dtb'
MESS:00:00:17.205680:0: gpioman: gpioman_get_pin_num: pin SDCARD_CONTROL_POWER not defined
MESS:00:00:17.210890:0: gpioman: gpioman_get_pin_num: pin SDCARD_CONTROL_POWER not defined
MESS:00:00:17.318829:0: gpioman: gpioman_get_pin_num: pin SDCARD_CONTROL_POWER not defined
MESS:00:00:17.367045:0: gpioman: gpioman_get_pin_num: pin SDCARD_CONTROL_WRITE_PROTECTED not defined
MESS:00:00:17.387231:0: Loaded 'bcm2711-rpi-4-b.dtb' to 0x100 size 0x0
MESS:00:00:17.478316:0: Failed to read command line file 'cmdline.txt'
MESS:00:00:17.583818:0: kernel=
MESS:00:00:17.586153:0: Loaded 'kernel7l.img' to 0x8000 size 0x0
MESS:00:00:17.589583:0: Device tree loaded to 0x2eff2d00 (size 0xd29c)
MESS:00:00:17.597402:0: uart: Set PL011 baud rate to 103448.300000 Hz
MESS:00:00:17.604900:0: uart: Baud rate change done...
MESS:00:00:17.606917:0:

@timg236
Copy link

timg236 commented Dec 7, 2022

Please could you check the version of recovery.bin installed to /boot before applying the update (strings /boot/recovery.bin | grep VERSION)
It should be 0fc8fc8e i.e. same as the EEPROM release since it will be recovery.bin and not the bootloader switching 3V3 during the update.

@timg236
Copy link

timg236 commented Dec 7, 2022

Btw I think the 4kp60 element is a separate issue which is exacerbated by losing the PMIC reset. Best guess is that the reboot causes the ROM to run with an unusual voltage which upsets MMC controller.
The EEPROM uses the modern controller which is better but start.elf still uses the old one which is now in a bad state.
Just a guess and the logging we looked at earlier is mostly just raising more questions. Very odd.

@HiassofT
Copy link
Author

HiassofT commented Dec 7, 2022

Ah, sorry, my fault. Of course I was using old recovery.bin (from apt update a few hours ago, 14.0-1).

apt just got me rpi-eeprom 15.0-1 with new recovery.bin and with that I see 3V3 is being dropped on eeprom update and updating 2022-12-07 to 2022-12-07 succeeded (I was lazy and just used rpi-eeprom-config -e).

I'll do a few more tests the next days but so far it's looing good here now.

The 4kp60 (probably core_freq?) thing is really puzzling.... You folks with access to firmware source might have a better chance than me finding out why it seems to have triggered the failure.

Anyways: though my initial issue seems to be solved now and I couldn't notice other issue I guess it might be good to keep this issue open for a week or so in case other people get hit by it (no one looks at closed issues...)

Feel free to close it any time in case I forget though - I'll reopen or create another issue if/when I have more info or an actual failure to report.

@timg236
Copy link

timg236 commented Dec 8, 2022

Thanks for confirming the recovery.bin thing. Let’s keep this issue open until we understand the clock issue.
Might take a few days to find the root cause!

@timg236
Copy link

timg236 commented Dec 8, 2022

I'm still investigating the root-cause but I've been testing a pending change to switch the firmware to the newer and more reliable SDHCI controller as used by Linux (and now the bootloader).

With this firmware I can no longer reproduces the 4kp60 issues (connected or not).

Originally, this change was added in order to see if it helped with boot time, since that wasn't the case it was parked because of the risk of regressions. However, the experience with the bootloader is convincing me that this is is actually more robust (soak testing on various board revisions will be required though!

Would you mind giving it a try? I can build the other start*elf variants if needed.

rpi-fw-new-sdhci.zip

@HiassofT
Copy link
Author

HiassofT commented Dec 8, 2022

@timg236 sure, I'll do some tests with it later.

Could you also build the 4x variant? That's the one we use in LE by default

@timg236
Copy link

timg236 commented Dec 8, 2022

No problem, here's the slightly more official releases from the CI system

rpi-fw-new-sdhci-all-variants.zip

@HiassofT
Copy link
Author

HiassofT commented Dec 8, 2022

Thanks a lot, initial testing with 32GB Sandisk Extreme and Extreme Pro cards looks good here so far.

II'll try to find my Samsung cards (I should have a couple of them, but where...) and do some more tests with them as well

@matulkov
Copy link

matulkov commented Dec 9, 2022

I had the same problem: after installing firmware version higher than 2022-04-26 and enabled hdmi_enable_4kp60=1, every reboot ends with rainbow screen.
I can confirm that after installing version 2022-12-07 rainbow screen is no more problem, rpi reboot is working as expected without any problems.
Many many thanks

@HiassofT
Copy link
Author

Testing with a 32GB Samsung Evo+ card and an 8GB rev 1.4 RPi4 looks fine here as well

popcornmix added a commit that referenced this issue Dec 12, 2022
firmware: power: Always read the uncached voltage for AIN and USB_PD
See: https://forums.raspberrypi.com/viewtopic.php?p=2059832#p2059832

firmware: Use new SDHCI controller instead of legacy arasan
See: #1763
popcornmix added a commit to raspberrypi/rpi-firmware that referenced this issue Dec 12, 2022
firmware: power: Always read the uncached voltage for AIN and USB_PD
See: https://forums.raspberrypi.com/viewtopic.php?p=2059832#p2059832

firmware: Use new SDHCI controller instead of legacy arasan
See: raspberrypi/firmware#1763
@timg236
Copy link

timg236 commented Dec 12, 2022

I left some boards in a reboot loop over the weekend and they were still running so this has been pushed to rpi-update master by @popcornmix. Not much else has changed but please shout if you encounter any issues in this area.

@HiassofT
Copy link
Author

Thanks a lot to everyone involved in fixing this issue!

Latest rpi-firmware works fine here so I'm closing this

@capiman
Copy link

capiman commented Dec 17, 2022

@timg236 Can you tell if this (SD card problem) also affects a compute module 4?

@timg236
Copy link

timg236 commented Dec 18, 2022

@capiman The 3V3 switch issue resolved by the bootloader update would not have affected CM4 because all CM4s have an SD power switch.

The firmware change for headless boot with 4kp60 enabled (or overclocked core freq) would be relevant for CM4 Lite + SD. I didn't see it fail with CM4 + EMMC though.

XECDesign pushed a commit to XECDesign/rpi-eeprom that referenced this issue Jan 6, 2023
Fix issue where SD voltage was not reset by power cycling PMIC on reboot.

See raspberrypi/firmware#1763
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