firmware
firmware copied to clipboard
raspberrypi
Regression post 1.20220331: blk_update_request: I/O error, dev sr0
Reading Audio CD seems to fail with recent kernel and post 1.20220331 firmware (on PiZeroW) (Note: by firmware here I just mean bootcode.bin, *.dat, *.elf files)
All this started with failing cdda2wav on a new system install (Alpine 3.17-based): https://pastebin.com/EF9rsQ24
Note last line: Driver and/or firmware bug detected! Drive cannot play the very last sector (248604)!
On the very same hardware (same PiZeroW, CD-ROM drive, AudioCD, SD card, Power Supply,....), I installed several base Alpine system (no bells & whistles) and looked at dmesg
Working combo: Alpine 3.16 (kernel 5.15.78, firmware 1.20220331): https://pastebin.com/JDUHDJTy
Failing combo: Alpine 3.17 (kernel 5.15.79, firmware 6cbf00359959cf7381f4e3773037c7d5573d94b2): https://pastebin.com/B8HqN0Pv
I then copied Alpine 3.17 firmware onto initially working 3.16 and got it failing too: https://pastebin.com/U606fAqx
Finally the opposite test (Alpine 3.17 with firmware 1.20220331), which seems OK: https://pastebin.com/srsYgPEX
With that, it very much seems like some recent firmware changes (bootcode.bin, *.dat, *.elf) post 1.20220331 are colliding with CD driver. Thoughts?
Lucky cdda2wav gives more clues than cdparanoia or mpd which just get blocked by struggling IO.
@popcornmix any hint by chance?
It seem unlikely that start.elf firmware could cause an issue like this in the kernel driver (but it's conceivable that some prior setup has had an effect).
Best way to confirm this for sure is to manually bisect the firmware.
I think you have said this firmware:
[ 0.130639] raspberrypi-firmware soc:firmware: Attached to firmware from 2022-03-24T13:20:54, variant start
is good, and this is bad:
[ 0.130616] raspberrypi-firmware soc:firmware: Attached to firmware from 2022-11-11T11:14:37, variant start
If you look here you can see ~25 firmwares between these two points. Bisecting them should take about 5 steps.
For each commit you'll want to download start.elf and fixup.dat and replace the ones on your sdcard.
The download addresses will look like:
https://github.com/raspberrypi/firmware/raw/ea4c803c57697aad951a27fcd64c01ef16f9fe7f/boot/start.elf
https://github.com/raspberrypi/firmware/raw/ea4c803c57697aad951a27fcd64c01ef16f9fe7f/boot/fixup.dat
This url is for the March 24 firmware (which should work), but replace the hash (ea4c803c57697aad951a27fcd64c01ef16f9fe7f/) with each of the bisect points. You are expecting March 24 firmware to work, and Nov 11 firmware to fail. Report the first version that has the failure.
Thanks for feedback. I have indeed started bisecting and it failed in the first few changes following 1.20220331. I'll report exactly which, as soon as I'm in reach with that setup again.
I can confirm things start to fail after 22/04/13 commit https://github.com/raspberrypi/firmware/commit/afc7631bc9a58f94a157503955881ab27a6287d0 (firmware: arm_loader: Support longer file paths)
It's actually first firmware files change following 1.20220331 if I'm correct.
Would that ring a bell? (seems quite unrelated at first sight...)
dmesg is not happy (below) and cdda2wav complains as reported earlier (cdparanoia also fails)
[ 21.083740] sr 0:0:0:0: Power-on or device reset occurred
[ 21.086307] sr 0:0:0:0: [sr0] scsi3-mmc drive: 24x/24x writer cd/rw xa/form2 cdda tray
[ 21.086346] cdrom: Uniform CD-ROM driver Revision: 3.20
[ 21.621214] sr 0:0:0:0: Attached scsi CD-ROM sr0
[ 22.278091] cfg80211: Loading compiled-in X.509 certificates for regulatory database
[ 22.281678] sr 0:0:0:0: [sr0] tag#0 UNKNOWN(0x2003) Result: hostbyte=0x00 driverbyte=DRIVER_OK cmd_age=0s
[ 22.281722] sr 0:0:0:0: [sr0] tag#0 Sense Key : 0x5 [current]
[ 22.281741] sr 0:0:0:0: [sr0] tag#0 ASC=0x64 ASCQ=0x0
[ 22.281765] sr 0:0:0:0: [sr0] tag#0 CDB: opcode=0x28 28 00 00 03 ca e0 00 00 02 00
[ 22.281781] blk_update_request: I/O error, dev sr0, sector 994176 op 0x0:(READ) flags 0x80700 phys_seg 1 prio class 0
Note: kernel (and related dtbs, overlays & al) remain 5.15.79 in this test, just rolling back .elf/.dat). Happy to provide more detailed info if needed.
That commit seems surprising. Are you sure that is the first firmware update that has the issue? i.e. the previous firmware "firmware: arm_loader_dvfs: Make arm only see its own boosts" is good?
Looking at commit messages it's the first with commit message referring to firmware change, following 1.20220331 which is "known-good". The one you are referring to ea4c803c57697aad951a27fcd64c01ef16f9fe7f on March 24th seems to predates 1.20220331, right? (EDIT: indeed I just checked .bin/.dat/.elf have same sha512sum)
That commit seems surprising. Are you sure that is the first firmware update that has the issue?
Yes I double-checked: issue does come-up with afc7631bc9a58f94a157503955881ab27a6287d0
dmesg warning are here earlier (maybe normal as Audio CD won't mount per say), but cdda2wav/cdparanoia issues do start with that firmware.
Thanks for any tip.
It looks as if DTBs are not selected the same way after that https://github.com/raspberrypi/firmware/commit/afc7631bc9a58f94a157503955881ab27a6287d0 change.
Indeed by defaults /mmcblk0p1 contains both downstream bcm27*.dtb and upstream bcm28*.dtb
When using firmware from https://github.com/raspberrypi/firmware/commit/afc7631bc9a58f94a157503955881ab27a6287d0 and on, if I remove/move away bcm28*.dtb then the issue is fixed!...
So after that change it seems upstream DTBs are selected if available (and BTW those may have a problem): it was seemingly not the case before.
How can I check which DTB file is selected on a running system?
For records, defauls Alpine config.txt is as follows, with all DTBs in /mmcblk0p1:
[pi0]
kernel=boot/vmlinuz-rpi
initramfs boot/initramfs-rpi
[pi0w]
kernel=boot/vmlinuz-rpi
initramfs boot/initramfs-rpi
[pi1]
kernel=boot/vmlinuz-rpi
initramfs boot/initramfs-rpi
[pi02]
kernel=boot/vmlinuz-rpi2
initramfs boot/initramfs-rpi2
[pi2]
kernel=boot/vmlinuz-rpi2
initramfs boot/initramfs-rpi2
[pi3]
kernel=boot/vmlinuz-rpi2
initramfs boot/initramfs-rpi2
[pi3+]
kernel=boot/vmlinuz-rpi2
initramfs boot/initramfs-rpi2
[all]
include usercfg.txt
@pelwell any thought as it seemingly relates to https://github.com/raspberrypi/firmware/issues/1720 ?
How can I check which DTB file is selected on a running system?
sudo vcdbg log msg
should include the dtb files loaded.
hum, unfortunately it does not seem to be built on Alpine, while vcgencmd is.
I'll need to find-out how to build it then...
You can use the vclog utility instead: https://github.com/raspberrypi/utils/tree/master/vclog
Do you have an os_prefix set in config.txt? The older, smaller filename limit was sufficient for the known DTB files unless they had been moved into a subdirectory. And what about upstream_kernel?
You can use the vclog utility instead: https://github.com/raspberrypi/utils/tree/master/vclog
Not available either. Package is built with -DCMAKE_BUILD_TYPE=MinSizeRel. Any hint on proper option to get all the missing binaries?
Do you have an os_prefix set in config.txt? The older, smaller filename limit was sufficient for the known DTB files unless they had been moved into a subdirectory. And what about upstream_kernel?
No, none are set, as shown in copied config.txt (DTBs are in root of SD aside firmware files and overlays directory, not in boot/ that has initramfs and vmlinuz)
ls /media/mmcblk0p1/
bcm2710-rpi-zero-2.dtb bcm2837-rpi-3-a-plus.dtb
bcm2708-rpi-b-plus.dtb bcm2711-rpi-4-b.dtb bcm2837-rpi-3-b-plus.dtb
bcm2708-rpi-b-rev1.dtb bcm2711-rpi-400.dtb bcm2837-rpi-3-b.dtb
bcm2708-rpi-b.dtb bcm2711-rpi-cm4.dtb bcm2837-rpi-cm3-io3.dtb
bcm2708-rpi-cm.dtb bcm2711-rpi-cm4s.dtb boot
bcm2708-rpi-zero-w.dtb bcm2835-rpi-a-plus.dtb bootcode.bin
bcm2708-rpi-zero.dtb bcm2835-rpi-a.dtb
bcm2709-rpi-2-b.dtb bcm2835-rpi-b-plus.dtb cmdline.txt
bcm2709-rpi-cm2.dtb bcm2835-rpi-b-rev2.dtb config.txt
bcm2710-rpi-2-b.dtb bcm2835-rpi-b.dtb fixup.dat
bcm2710-rpi-3-b-plus.dtb bcm2835-rpi-cm1-io1.dtb
bcm2710-rpi-3-b.dtb bcm2835-rpi-zero-w.dtb overlays
bcm2710-rpi-cm3.dtb bcm2835-rpi-zero.dtb start.elf
bcm2710-rpi-zero-2-w.dtb bcm2836-rpi-2-b.dtb
Just clone the git repo and follow build instructions in README. It only takes a minute to build and has minimal dependencies.
Thanks @popcornmix will try to do so. Meanwhile, the tests & results so far show that:
- when
bcm2708-rpi-zero-w.dtbis the only relevant DTB available, AudioCD programs work as expected with firmware after https://github.com/raspberrypi/firmware/commit/afc7631bc9a58f94a157503955881ab27a6287d0 - if upstream
bcm2835-rpi-zero-w.dtbfile is also available then AudioCD programs fail with those later firmware, while they worked with earlier firmware. config.txthas noupstream_kernel/os_prefixstatement, so only downstream DTBs in root FAT filesystem should be selected (even if there are upstream files next to them).
Can't we conclude https://github.com/raspberrypi/firmware/commit/afc7631bc9a58f94a157503955881ab27a6287d0 change somehow broke default downstream DTBs selection in root FAT filesystem, with no further tests?
Let me know if/which further info is needed to help for a fix.
Can't we conclude https://github.com/raspberrypi/firmware/commit/afc7631bc9a58f94a157503955881ab27a6287d0 change somehow broke default downstream DTBs selection in root FAT filesystem, with no further tests?
Based on the evidence you've provided that sounds likely. The commit mentioned ("Support longer file paths") doesn't look blatantly wrong, but it perhaps has caused some unintended change in behaviour.
I'm sure once we've reproduced this, the fix will be straightforward. But most of us supporting here are away with family for the holiday period, so we can ask questions to narrow down the issue, but actually stepping through the code with a debugger is unlikely to happen before the office opens next week.
It's possible the output of vclog will make it clear how it's failing.
Of course, no hurry: enjoy a great & refreshing family break ! Let's recap next week.
For records, few pending issues compiling vclog as described there: https://github.com/raspberrypi/utils/issues/14 , https://github.com/raspberrypi/utils/pull/15
vclog output in the failing condition is below. Looks-like my assumption was incorrect then, as log says downstream DTB is indeed loaded... Log is same in working condition (with earlier firmware). Would you have any other clue?
# vclog --msg
001558.028: brfs: File read: /mfs/sd/config.txt
001558.589: brfs: File read: 628 bytes
001571.921: Failed to open include file 'usercfg.txt'
001571.940: brfs: File read: /mfs/sd/usercfg.txt
001619.447: HDMI0:EDID error reading EDID block 0 attempt 0
001620.713: HDMI0:EDID error reading EDID block 0 attempt 1
001621.978: HDMI0:EDID error reading EDID block 0 attempt 2
001623.242: HDMI0:EDID error reading EDID block 0 attempt 3
001624.507: HDMI0:EDID error reading EDID block 0 attempt 4
001625.770: HDMI0:EDID error reading EDID block 0 attempt 5
001627.037: HDMI0:EDID error reading EDID block 0 attempt 6
001628.301: HDMI0:EDID error reading EDID block 0 attempt 7
001629.566: HDMI0:EDID error reading EDID block 0 attempt 8
001630.831: HDMI0:EDID error reading EDID block 0 attempt 9
001631.855: HDMI0:EDID giving up on reading EDID block 0
001651.781: brfs: File read: /mfs/sd/config.txt
001652.116: brfs: File read: 628 bytes
001665.442: Failed to open include file 'usercfg.txt'
001665.461: brfs: File read: /mfs/sd/usercfg.txt
001665.698: gpioman: gpioman_get_pin_num: pin LEDS_PWR_OK not defined
001851.704: gpioman: gpioman_get_pin_num: pin LEDS_PWR_OK not defined
001851.759: *** Restart logging
001867.735: hdmi: HDMI0:EDID error reading EDID block 0 attempt 0
001869.005: hdmi: HDMI0:EDID error reading EDID block 0 attempt 1
001870.273: hdmi: HDMI0:EDID error reading EDID block 0 attempt 2
001871.543: hdmi: HDMI0:EDID error reading EDID block 0 attempt 3
001872.811: hdmi: HDMI0:EDID error reading EDID block 0 attempt 4
001874.081: hdmi: HDMI0:EDID error reading EDID block 0 attempt 5
001875.348: hdmi: HDMI0:EDID error reading EDID block 0 attempt 6
001876.617: hdmi: HDMI0:EDID error reading EDID block 0 attempt 7
001877.885: hdmi: HDMI0:EDID error reading EDID block 0 attempt 8
001879.156: hdmi: HDMI0:EDID error reading EDID block 0 attempt 9
001880.181: hdmi: HDMI0:EDID giving up on reading EDID block 0
001880.516: hdmi: HDMI0:EDID error reading EDID block 0 attempt 0
001881.785: hdmi: HDMI0:EDID error reading EDID block 0 attempt 1
001883.052: hdmi: HDMI0:EDID error reading EDID block 0 attempt 2
001884.321: hdmi: HDMI0:EDID error reading EDID block 0 attempt 3
001885.589: hdmi: HDMI0:EDID error reading EDID block 0 attempt 4
001886.859: hdmi: HDMI0:EDID error reading EDID block 0 attempt 5
001888.126: hdmi: HDMI0:EDID error reading EDID block 0 attempt 6
001889.397: hdmi: HDMI0:EDID error reading EDID block 0 attempt 7
001890.665: hdmi: HDMI0:EDID error reading EDID block 0 attempt 8
001891.935: hdmi: HDMI0:EDID error reading EDID block 0 attempt 9
001892.960: hdmi: HDMI0:EDID giving up on reading EDID block 0
001893.005: hdmi: HDMI:hdmi_get_state is deprecated, use hdmi_get_display_state instead
001893.028: HDMI0: hdmi_pixel_encoding: 162000000
001893.295: vec: vec_middleware_power_on: vec_base: 0x7e806000 rev-id 0x00002708 @ vec: 0x7e806100 @ 0x00000420 enc: 0x7e806060 @ 0x00000220 cgmsae: 0x7e80605c @ 0x00000000
002350.981: brfs: File read: /mfs/sd/boot/initramfs-rpi
002351.007: Loaded 'boot/initramfs-rpi' to 0x0 size 0x4e8e19
002356.883: initramfs loaded to 0x1bb07000 (size 0x4e8e19)
002361.324: dtb_file 'bcm2708-rpi-zero-w.dtb'
002361.353: brfs: File read: 5148185 bytes
002371.962: brfs: File read: /mfs/sd/bcm2708-rpi-zero-w.dtb
002371.986: Loaded 'bcm2708-rpi-zero-w.dtb' to 0x100 size 0x7253
002385.509: brfs: File read: 29267 bytes
002410.617: brfs: File read: /mfs/sd/overlays/overlay_map.dtb
002495.555: brfs: File read: 2259 bytes
002500.552: brfs: File read: /mfs/sd/config.txt
002500.813: brfs: File read: 628 bytes
002520.857: Failed to open include file 'usercfg.txt'
002520.876: brfs: File read: /mfs/sd/usercfg.txt
002533.331: brfs: File read: /mfs/sd/cmdline.txt
002533.359: Read command line from file 'cmdline.txt':
002533.372: 'modules=loop,squashfs,sd-mod,usb-storage quiet console=tty1'
002812.558: gpioman: gpioman_get_pin_num: pin EMMC_ENABLE not defined
002838.020: kernel=boot/vmlinuz-rpi
002838.044: brfs: File read: 60 bytes
003397.014: brfs: File read: /mfs/sd/boot/vmlinuz-rpi
003397.038: Loaded 'boot/vmlinuz-rpi' to 0x8000 size 0x5db9e0
003397.077: Device tree loaded to 0x1baff800 (size 0x7770)
003414.016: gpioman: gpioman_get_pin_num: pin SDCARD_CONTROL_POWER not defined
007918.276: vchiq_core: vchiq_init_state: slot_zero = 0x97980000, is_master = 1
Tried again (twice) after a cold reboot (poweroff + unplugging for 15mn+) with "working" firmware (1.20220331):
# vclog --msg
Could not read from Device Tree log starts and log size
Does vclog require later firmware ?
vclog requires a recent APT (or rpi update stable) release of the firmware in order to discover the location of the log buffer via device tree
uart_2ndstage=1 in config.txt will also emit all of the dt loading message up till the kernel is started via the uart
hum... so I won't be able to compare the situation at 1.20220331 stable) and following https://github.com/raspberrypi/firmware/commit/afc7631bc9a58f94a157503955881ab27a6287d0 with vclog then, and I don't think I'm equipped to hook-up uart.
Are we stuck, or can I provide any other meaningful info to figure-out what happens since https://github.com/raspberrypi/firmware/commit/afc7631bc9a58f94a157503955881ab27a6287d0 ?
You may be able to use a static build of vcdbg. See https://github.com/raspberrypi/Raspberry-Pi-OS-64bit/issues/67#issuecomment-653209729
Thanks. Here is the output below: seems pretty much same: anything of interest?
Tests to isolate failing conditions are quite tricky and do not seem as clear-cut as the other day... I even have some successes with https://github.com/raspberrypi/firmware/commit/afc7631bc9a58f94a157503955881ab27a6287d0 (though it fails frequently). I'm wondering init condition (cold boot with unplug rest time) has an effet vs poweroff (but keep PSU plugged) vs just reboot...
A bit lost ATM...
Maybe working from the other-end of the foodchain from cdda2wav errors would make sense, maybe debunking driver-side issue (blk_update_request: I/O error). No clue what to seek for though...
index scan: 9...Errno: 5 (I/O error), play sectors scsi sendcmd: no error
CDB: 47 00 00 37 10 36 37 10 37 00
status: 0x2 (CHECK CONDITION)
Sense Bytes: 70 00 02 00 00 00 00 0A 00 00 00 00 04 01 00 00
Sense Key: 0x2 Not Ready, Segment 0
Sense Code: 0x04 Qual 0x01 (logical unit is in process of becoming ready) Fru 0x0
Sense flags: Blk 0 (not valid)
cmd finished after 0.002s timeout 60s
Driver and/or firmware bug detected! Drive cannot play the very last sector (248604)!
# ./vcdbg log msg
001502.875: brfs: File read: /mfs/sd/config.txt
001503.434: brfs: File read: 628 bytes
001516.738: Failed to open include file 'usercfg.txt'
001516.758: brfs: File read: /mfs/sd/usercfg.txt
001564.319: HDMI0:EDID error reading EDID block 0 attempt 0
001565.585: HDMI0:EDID error reading EDID block 0 attempt 1
001566.850: HDMI0:EDID error reading EDID block 0 attempt 2
001568.114: HDMI0:EDID error reading EDID block 0 attempt 3
001569.380: HDMI0:EDID error reading EDID block 0 attempt 4
001570.645: HDMI0:EDID error reading EDID block 0 attempt 5
001571.910: HDMI0:EDID error reading EDID block 0 attempt 6
001573.174: HDMI0:EDID error reading EDID block 0 attempt 7
001574.439: HDMI0:EDID error reading EDID block 0 attempt 8
001575.704: HDMI0:EDID error reading EDID block 0 attempt 9
001576.728: HDMI0:EDID giving up on reading EDID block 0
001596.730: brfs: File read: /mfs/sd/config.txt
001597.064: brfs: File read: 628 bytes
001610.397: Failed to open include file 'usercfg.txt'
001610.416: brfs: File read: /mfs/sd/usercfg.txt
001610.654: gpioman: gpioman_get_pin_num: pin LEDS_PWR_OK not defined
001796.669: gpioman: gpioman_get_pin_num: pin LEDS_PWR_OK not defined
001796.723: *** Restart logging
001812.860: hdmi: HDMI0:EDID error reading EDID block 0 attempt 0
001814.131: hdmi: HDMI0:EDID error reading EDID block 0 attempt 1
001815.399: hdmi: HDMI0:EDID error reading EDID block 0 attempt 2
001816.669: hdmi: HDMI0:EDID error reading EDID block 0 attempt 3
001817.937: hdmi: HDMI0:EDID error reading EDID block 0 attempt 4
001819.207: hdmi: HDMI0:EDID error reading EDID block 0 attempt 5
001820.475: hdmi: HDMI0:EDID error reading EDID block 0 attempt 6
001821.745: hdmi: HDMI0:EDID error reading EDID block 0 attempt 7
001823.014: hdmi: HDMI0:EDID error reading EDID block 0 attempt 8
001824.288: hdmi: HDMI0:EDID error reading EDID block 0 attempt 9
001825.313: hdmi: HDMI0:EDID giving up on reading EDID block 0
001825.648: hdmi: HDMI0:EDID error reading EDID block 0 attempt 0
001826.918: hdmi: HDMI0:EDID error reading EDID block 0 attempt 1
001828.185: hdmi: HDMI0:EDID error reading EDID block 0 attempt 2
001829.455: hdmi: HDMI0:EDID error reading EDID block 0 attempt 3
001830.723: hdmi: HDMI0:EDID error reading EDID block 0 attempt 4
001831.992: hdmi: HDMI0:EDID error reading EDID block 0 attempt 5
001833.260: hdmi: HDMI0:EDID error reading EDID block 0 attempt 6
001834.529: hdmi: HDMI0:EDID error reading EDID block 0 attempt 7
001835.797: hdmi: HDMI0:EDID error reading EDID block 0 attempt 8
001837.066: hdmi: HDMI0:EDID error reading EDID block 0 attempt 9
001838.091: hdmi: HDMI0:EDID giving up on reading EDID block 0
001838.136: hdmi: HDMI:hdmi_get_state is deprecated, use hdmi_get_display_state instead
001838.159: HDMI0: hdmi_pixel_encoding: 162000000
001838.426: vec: vec_middleware_power_on: vec_base: 0x7e806000 rev-id 0x00002708 @ vec: 0x7e806100 @ 0x00000420 enc: 0x7e806060 @ 0x00000220 cgmsae: 0x7e80605c @ 0x00000000
002296.175: brfs: File read: /mfs/sd/boot/initramfs-rpi
002296.200: Loaded 'boot/initramfs-rpi' to 0x0 size 0x4e8e19
002302.076: initramfs loaded to 0x1bb07000 (size 0x4e8e19)
002306.518: dtb_file 'bcm2708-rpi-zero-w.dtb'
002306.547: brfs: File read: 5148185 bytes
002317.159: brfs: File read: /mfs/sd/bcm2708-rpi-zero-w.dtb
002317.184: Loaded 'bcm2708-rpi-zero-w.dtb' to 0x100 size 0x7253
002330.651: brfs: File read: 29267 bytes
002355.920: brfs: File read: /mfs/sd/overlays/overlay_map.dtb
002441.223: brfs: File read: 2259 bytes
002446.271: brfs: File read: /mfs/sd/config.txt
002446.532: brfs: File read: 628 bytes
002466.472: Failed to open include file 'usercfg.txt'
002466.491: brfs: File read: /mfs/sd/usercfg.txt
002478.945: brfs: File read: /mfs/sd/cmdline.txt
002478.973: Read command line from file 'cmdline.txt':
002478.986: 'modules=loop,squashfs,sd-mod,usb-storage quiet console=tty1'
002763.234: gpioman: gpioman_get_pin_num: pin EMMC_ENABLE not defined
002788.611: kernel=boot/vmlinuz-rpi
002788.635: brfs: File read: 60 bytes
003347.268: brfs: File read: /mfs/sd/boot/vmlinuz-rpi
003347.292: Loaded 'boot/vmlinuz-rpi' to 0x8000 size 0x5db9e0
003347.331: Device tree loaded to 0x1baff800 (size 0x7770)
003364.424: gpioman: gpioman_get_pin_num: pin SDCARD_CONTROL_POWER not defined
007868.967: vchiq_core: vchiq_init_state: slot_zero = 0x97980000, is_master = 1
The two vcdbg logs are identical (ignoring the timestamps).
I even have some successes with https://github.com/raspberrypi/firmware/commit/afc7631bc9a58f94a157503955881ab27a6287d0 (though it fails frequently).
Are you sure the preceding commit is 100% working? When failures are intermittent, it's easy to think a version is good, when you get a few lucky successes.
I could produce some additional firmware builds in between the two versions released just to be sure it is the (internal tree) commit we are assuming, but that only works if you can reliably say whether a build has the issue or not.
It seems system do not always properly recover from eventual:
sr 0:0:0:0: Power-on or device reset occurred
This often occur after CD totally spins down, and cdda2wav or cdparanoia are then called.
CD spins-up (may draw too much current initially?) and then reads may be affected (apps become very slow to respond but may go through).
Subsequent CD app launch are very slow and it seems it would stay so until a cold reboot...
It may eventually go doggy with cdparanoia blocking IO ops to death for example.
[ 1825.802613] Indeed it is in host mode hprt0 = 00001101
[ 1826.012513] usb 1-1: reset high-speed USB device number 2 using dwc_otg
If those apps are called with CD already spinning (and no previous lockup), then they operate fine...
Could root cause be some power limitation (though vcgencmd get_throttled reports throttled=0x0) somehow altering CD USB interface/driver/firmware food-chain, it not being able to recover/flush the situation in some cases?...
Any known command that would just spin-up CD (without reading) I could call prior testing access with cdda2wav or cdparanoia (or reset drivers chain)?
Further refined testing pattern trying to be more immune to transient effects.
- swapped PSU to similarly rated 2.4A and known to be very stable & low noise
- unplug & let setup rest for about 20mn between each test suite where firmware files are changed (let caps discharge & try avoid memory effects).
- run
cdda2wav -D /dev/cdrom --info-onlycommand several time, either with CD spinning or letting it spin down for a couple of minutes
With that, apparently no more sr 0:0:0:0: Power-on or device reset occurred in dmesg (apart initial one at about 20sec during system init), and no more cdda2wav errors.
Tested with 1.20220331 stable, https://github.com/raspberrypi/firmware/commit/afc7631bc9a58f94a157503955881ab27a6287d0 and https://github.com/raspberrypi/firmware/commit/6cbf00359959cf7381f4e3773037c7d5573d94b2
So, I'd pretend some transient power instabilities may affect CD interface board, and/or USB communication with Pi device under some circumstances, while Pi device itself does not seem affected (throttled=0x0) by such power instabilities (USB port wiring is indeed in parallel in my PiZeroWed-Mac Mini).
Now, whether or not firmware changes may marginally influence such power sensitivity on USB port/built-in hub, I don't know...
I'll keep monitoring this and eventually close it if all shame is to be put on PSU (though was happy with the original 2.4A so far...).
I could produce some additional firmware builds
Thanks for the kind offer, but I'm reluctant to consume more of your time on this, unless you think some of the firmware changes may adversely affect USB communication. Thanks again for your great support.
interface details for records (bulk)
# lsusb -v
Bus 001 Device 002: ID 14cd:6600 Super Top USB 2.0 IDE DEVICE
Device Descriptor:
bLength 18
bDescriptorType 1
bcdUSB 2.00
bDeviceClass 0
bDeviceSubClass 0
bDeviceProtocol 0
bMaxPacketSize0 64
idVendor 0x14cd
idProduct 0x6600
bcdDevice 2.01
iManufacturer 1 Super Top
iProduct 3 USB 2.0 IDE DEVICE
iSerial 2 ††††††††††
bNumConfigurations 1
Configuration Descriptor:
bLength 9
bDescriptorType 2
wTotalLength 0x0020
bNumInterfaces 1
bConfigurationValue 1
iConfiguration 0
bmAttributes 0xc0
Self Powered
MaxPower 2mA
Interface Descriptor:
bLength 9
bDescriptorType 4
bInterfaceNumber 0
bAlternateSetting 0
bNumEndpoints 2
bInterfaceClass 8
bInterfaceSubClass 6
bInterfaceProtocol 80
iInterface 0
Endpoint Descriptor:
bLength 7
bDescriptorType 5
bEndpointAddress 0x81 EP 1 IN
bmAttributes 2
Transfer Type Bulk
Synch Type None
Usage Type Data
wMaxPacketSize 0x0200 1x 512 bytes
bInterval 0
Endpoint Descriptor:
bLength 7
bDescriptorType 5
bEndpointAddress 0x02 EP 2 OUT
bmAttributes 2
Transfer Type Bulk
Synch Type None
Usage Type Data
wMaxPacketSize 0x0200 1x 512 bytes
bInterval 0
Device Qualifier (for other device speed):
bLength 10
bDescriptorType 6
bcdUSB 2.00
bDeviceClass 0
bDeviceSubClass 0
bDeviceProtocol 0
bMaxPacketSize0 64
bNumConfigurations 1
Device Status: 0x0001
Self Powered
Bus 001 Device 001: ID 1d6b:0002 Linux 5.15.79-0-rpi dwc_otg_hcd DWC OTG Controller
Device Descriptor:
bLength 18
bDescriptorType 1
bcdUSB 2.00
bDeviceClass 9
bDeviceSubClass 0
bDeviceProtocol 1
bMaxPacketSize0 64
idVendor 0x1d6b
idProduct 0x0002
bcdDevice 5.15
iManufacturer 3 Linux 5.15.79-0-rpi dwc_otg_hcd
iProduct 2 DWC OTG Controller
iSerial 1 20980000.usb
bNumConfigurations 1
Configuration Descriptor:
bLength 9
bDescriptorType 2
wTotalLength 0x0019
bNumInterfaces 1
bConfigurationValue 1
iConfiguration 0
bmAttributes 0xe0
Self Powered
Remote Wakeup
MaxPower 0mA
Interface Descriptor:
bLength 9
bDescriptorType 4
bInterfaceNumber 0
bAlternateSetting 0
bNumEndpoints 1
bInterfaceClass 9
bInterfaceSubClass 0
bInterfaceProtocol 0
iInterface 0
Endpoint Descriptor:
bLength 7
bDescriptorType 5
bEndpointAddress 0x81 EP 1 IN
bmAttributes 3
Transfer Type Interrupt
Synch Type None
Usage Type Data
wMaxPacketSize 0x0004 1x 4 bytes
bInterval 12
Hub Descriptor:
bLength 9
bDescriptorType 41
nNbrPorts 1
wHubCharacteristic 0x0008
Ganged power switching
Per-port overcurrent protection
TT think time 8 FS bits
bPwrOn2PwrGood 1 * 2 milli seconds
bHubContrCurrent 0 milli Ampere
DeviceRemovable 0x00
PortPwrCtrlMask 0xff
Hub Port Status:
Port 1: 0000.0503 highspeed power enable connect
Device Status: 0x0001
Self Powered