Skip to content

Regression post 1.20220331: blk_update_request: I/O error, dev sr0 #1765

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

Open
macmpi opened this issue Dec 16, 2022 · 31 comments
Open

Regression post 1.20220331: blk_update_request: I/O error, dev sr0 #1765

macmpi opened this issue Dec 16, 2022 · 31 comments

Comments

@macmpi
Copy link

macmpi commented Dec 16, 2022

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 6cbf003):
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?

@macmpi
Copy link
Author

macmpi commented Dec 21, 2022

Lucky cdda2wav gives more clues than cdparanoia or mpd which just get blocked by struggling IO.
@popcornmix any hint by chance?

@popcornmix
Copy link
Contributor

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 (ea4c803/) 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.

@macmpi
Copy link
Author

macmpi commented Dec 21, 2022

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.

@macmpi
Copy link
Author

macmpi commented Dec 26, 2022

I can confirm things start to fail after 22/04/13 commit afc7631 (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.

@popcornmix
Copy link
Contributor

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?

@macmpi
Copy link
Author

macmpi commented Dec 26, 2022

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 ea4c803 on March 24th seems to predates 1.20220331, right? (EDIT: indeed I just checked .bin/.dat/.elf have same sha512sum)

@macmpi
Copy link
Author

macmpi commented Dec 28, 2022

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 afc7631
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.

@macmpi
Copy link
Author

macmpi commented Dec 30, 2022

It looks as if DTBs are not selected the same way after that afc7631 change.

Indeed by defaults /mmcblk0p1 contains both downstream bcm27*.dtb and upstream bcm28*.dtb
When using firmware from afc7631 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

@macmpi
Copy link
Author

macmpi commented Dec 30, 2022

@pelwell any thought as it seemingly relates to #1720 ?

@popcornmix
Copy link
Contributor

How can I check which DTB file is selected on a running system?

sudo vcdbg log msg

should include the dtb files loaded.

@macmpi
Copy link
Author

macmpi commented Dec 30, 2022

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...

@pelwell
Copy link
Contributor

pelwell commented Dec 30, 2022

You can use the vclog utility instead: https://github.com/raspberrypi/utils/tree/master/vclog

@pelwell
Copy link
Contributor

pelwell commented Dec 30, 2022

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?

@macmpi
Copy link
Author

macmpi commented Dec 30, 2022

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

@popcornmix
Copy link
Contributor

Just clone the git repo and follow build instructions in README. It only takes a minute to build and has minimal dependencies.

@macmpi
Copy link
Author

macmpi commented Dec 31, 2022

Thanks @popcornmix will try to do so.
Meanwhile, the tests & results so far show that:

  • when bcm2708-rpi-zero-w.dtb is the only relevant DTB available, AudioCD programs work as expected with firmware after afc7631
  • if upstream bcm2835-rpi-zero-w.dtb file is also available then AudioCD programs fail with those later firmware, while they worked with earlier firmware.
  • config.txt has no upstream_kernel / os_prefix statement, so only downstream DTBs in root FAT filesystem should be selected (even if there are upstream files next to them).

Can't we conclude afc7631 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.

@popcornmix
Copy link
Contributor

Can't we conclude afc7631 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.

@macmpi
Copy link
Author

macmpi commented Dec 31, 2022

Of course, no hurry: enjoy a great & refreshing family break !
Let's recap next week.

@macmpi
Copy link
Author

macmpi commented Jan 4, 2023

For records, few pending issues compiling vclog as described there: raspberrypi/utils#14 , raspberrypi/utils#15

@macmpi
Copy link
Author

macmpi commented Jan 4, 2023

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

@macmpi
Copy link
Author

macmpi commented Jan 4, 2023

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 ?

@timg236
Copy link

timg236 commented Jan 4, 2023

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

@timg236
Copy link

timg236 commented Jan 4, 2023

uart_2ndstage=1 in config.txt will also emit all of the dt loading message up till the kernel is started via the uart

@macmpi
Copy link
Author

macmpi commented Jan 4, 2023

hum... so I won't be able to compare the situation at 1.20220331 stable) and following afc7631 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 afc7631 ?

@popcornmix
Copy link
Contributor

You may be able to use a static build of vcdbg. See raspberrypi/Raspberry-Pi-OS-64bit#67 (comment)

@macmpi
Copy link
Author

macmpi commented Jan 5, 2023

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 afc7631 (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

@popcornmix
Copy link
Contributor

The two vcdbg logs are identical (ignoring the timestamps).

I even have some successes with afc7631 (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.

@macmpi
Copy link
Author

macmpi commented Jan 5, 2023

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)?

@macmpi
Copy link
Author

macmpi commented Jan 6, 2023

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-only command 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, afc7631 and 6cbf003

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.

@macmpi
Copy link
Author

macmpi commented Jan 6, 2023

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

@macmpi
Copy link
Author

macmpi commented Jan 6, 2023

is PiZeroW QC3.0 compatible on its OTG port (when host)?
i.e would it be able to reclaim 5v/3A from a QC3.0 charger for instance?

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

4 participants