search

raspberrypi / bookworm-feedback

13 stars 1 forks source link

[regression]: "cannot get freq (v2/v3): err -110", "cannot set freq 44100 (v2/v3): err -110", "uac_clock_source_is_valid(): cannot get clock validity for id 9" after latest apt upgrade with new firmware #288

Open qrp73 opened 3 months ago

qrp73 commented 3 months ago

Hardware: Raspberry Pi 4 4GB rev 1.5

$ uname -a
Linux raspi 6.6.32-v8+ #1 SMP PREEMPT Fri Jun  7 16:39:58 UTC 2024 aarch64 GNU/Linux

$ cat /etc/rpi-issue
Raspberry Pi reference 2023-09-22
Generated using pi-gen, https://github.com/RPi-Distro/pi-gen, 40f37458ae7cadea1aec913ae10b5e7008ebce0a, stage4

$ vcgencmd version
May 24 2024 15:30:04 
Copyright (c) 2012 Broadcom
version 4942b7633c0ff1af1ee95a51a33b56a9dae47529 (clean) (release) (start)

today I executed apt upgrade, it completed ok. But I notice, that now sound periodically disappears with the following errors in the dmesg log:

[59082.276833] usb 1-1.4.4: 1:3: cannot get freq (v2/v3): err -110
[59087.397083] usb 1-1.4.4: 1:3: cannot set freq 44100 (v2/v3): err -110
[59092.516999] usb 1-1.4.4: uac_clock_source_is_valid(): cannot get clock validity for id 9
[59092.517028] usb 1-1.4.4: clock source 9 is not valid, cannot use
[59097.637106] usb 1-1.4.4: 1:3: cannot get freq (v2/v3): err -110
[59102.757202] usb 1-1.4.4: 1:3: cannot set freq 44100 (v2/v3): err -110
[59107.877231] usb 1-1.4.4: uac_clock_source_is_valid(): cannot get clock validity for id 9
[59107.877247] usb 1-1.4.4: clock source 9 is not valid, cannot use
[59112.997365] usb 1-1.4.4: 1:3: cannot get freq (v2/v3): err -110
[59117.457953] usb 1-1.4.4: 1:3: cannot set freq 44100 (v2/v3): err -71
[59117.462239] usb 1-1.4.4: uac_clock_source_is_valid(): cannot get clock validity for id 9
[59117.462257] usb 1-1.4.4: clock source 9 is not valid, cannot use
[59117.462617] usb 1-1.4.4: 1:3: cannot get freq (v2/v3): err -71
[59117.462988] usb 1-1.4.4: 1:3: cannot set freq 44100 (v2/v3): err -71

// here I notice sound issue and manually reconnected USB sound DAC.

[59117.549356] usb 1-1.4.4: USB disconnect, device number 8
[59120.837190] usb 1-1.4.4: new high-speed USB device number 9 using xhci_hcd
[59120.958535] usb 1-1.4.4: New USB device found, idVendor=3302, idProduct=3352, bcdDevice= 0.01
[59120.958551] usb 1-1.4.4: New USB device strings: Mfr=1, Product=2, SerialNumber=0
[59120.958555] usb 1-1.4.4: Product: CX31993 384Khz HIFI AUDIO
[59120.958558] usb 1-1.4.4: Manufacturer: Synaptics
[59120.986902] input: Synaptics CX31993 384Khz HIFI AUDIO Consumer Control as /devices/platform/scb/fd500000.pcie/pci0000:00/0000:00:00.0/0000:01:00.0/usb1/1-1/1-1.4/1-1.4.4/1-1.4.4:1.3/0003:3302:3352.0006/input/input10
[59121.045560] hid-generic 0003:3302:3352.0006: input,hidraw3: USB HID v1.11 Device [Synaptics CX31993 384Khz HIFI AUDIO] on usb-0000:01:00.0-1.4.4/input3

When I disconnect sound DAC from USB and connect again, the sound works again.

This issue is regression in apt upgrade, because before latest apt upgrade the USB sound DAC worked ok.

I'm using CX31993 sound DAC dongle: https://www.aliexpress.com/item/1005005719157767.html

The issue happens about once per 10-20 minutes. It happens when I playing music in Firefox or when playing music in VLC.

Additional info: If it matters I'm using system with modified this line in /usr/share/pipewire/pipewire.conf after installation:

default.clock.allowed-rates = [ 44100, 48000, 96000, 192000, 384000 ]

I added all sample rates supported by sound DAC, because when I use my applications I need to use specific sample rate with no resampling. With this line sample rate is automatically selected according to requested sample rate from application.

The sound DAC is connected through this USB hub: https://www.aliexpress.com/item/1005005802405660.html

$ lsusb
Bus 002 Device 001: ID 1d6b:0003 Linux Foundation 3.0 root hub
Bus 001 Device 009: ID 3302:3352 Synaptics CX31993 384Khz HIFI AUDIO
Bus 001 Device 006: ID 046d:c051 Logitech, Inc. G3 (MX518) Optical Mouse
Bus 001 Device 005: ID 1c4f:0026 SiGma Micro Keyboard
Bus 001 Device 004: ID 214b:7250 Huasheng Electronics USB2.0 HUB
Bus 001 Device 003: ID 0bda:2838 Realtek Semiconductor Corp. RTL2838 DVB-T
Bus 001 Device 002: ID 2109:3431 VIA Labs, Inc. Hub
Bus 001 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub

RTL2838 connected directly to USB2 port. The hub is connected to the second USB2 port. Keyboard, Mouse and USB DAC connected to the hub.

I also notice that when I use this USB DAC on Raspi Zero 2W with latest Bookworm aarch64, it has sound issues (broken sound). There is definitely some bug in Raspberry Pi USB firmware, because this dongle works ok on PC with Linux Arch and Linux Mint. Also it worked ok on Raspi 4 before latest apt upgrade.

I notice that the latest apt upgrade includes firmware update for Raspberry Pi hardware. And it seems that it leads to this bug.

qrp73 commented 3 months ago

If it helps, the google shows similar issue here: https://guillaumeplayground.net/teac-ud-503-ud-501-snd-usb-audio-patch/ Maybe it is related, because it says that the issue happens when playback format is changed.

I notice that in my case the issue happens when application starts playing music or when player switch between different audio file, such events may lead to change sound playback sample rate.

ghollingworth commented 2 months ago

Might be useful to look in /var/log/apt/history* to see what packages were updated, to see if you can identify which package caused the change

qrp73 commented 2 months ago

I hadn't encountered this error for a long time, and I was almost sure that it had been fixed with some update. But no, it's still there...

Yesterday, I encountered it again. However, I'm not sure what condition causes it. It seems to happen when a new app tries to play a sound, but there might be some additional condition that triggers it. I'm not sure what that trigger is. It probably occurs when the app tries to play sound at a 44100 Hz sample rate, but I'm not certain. More testing is needed...

corus87 commented 1 month ago

I've come across the same issue with my new Respeaker Lite on a raspberry pi zero 2. I first thought about an problem with the Respeaker firmware but after finding this issue, I would assume an PI problem too.

I bought the Respeaker a couple of weeks ago, so I have no clue if this issue started with packages updates.

I've described my issue on the Seeed forum.

qrp73 commented 1 month ago

I suspect this issue is related to memory management. It typically occurs when an application starts consuming a significant amount of memory. I've observed this behavior frequently with Octave, as well as Audacity and other applications. It tends to happen during operations that rapidly require large amounts of memory.

In this case it happens when I started Octave script which consume about 2 GB memory:

[44897.727131] bcm2835-codec bcm2835-codec: bcm2835_codec_flush_buffers: Timeout waiting for buffers to be returned - 0 outstanding
[106409.261811] usb 1-1.4.4: 1:3: cannot get freq (v2/v3): err -110
[106414.382049] usb 1-1.4.4: 1:3: cannot set freq 44100 (v2/v3): err -110
[106419.502225] usb 1-1.4.4: uac_clock_source_is_valid(): cannot get clock validity for id 9
[106419.502239] usb 1-1.4.4: clock source 9 is not valid, cannot use
[106424.622432] usb 1-1.4.4: 1:3: cannot get freq (v2/v3): err -110
[106429.742664] usb 1-1.4.4: 1:3: cannot set freq 44100 (v2/v3): err -110
[106438.450735] usb 1-1.4.4: uac_clock_source_is_valid(): cannot get clock validity for id 9
[106438.450753] usb 1-1.4.4: clock source 9 is not valid, cannot use
[106443.567342] usb 1-1.4.4: 1:3: cannot get freq (v2/v3): err -110
[106448.687485] usb 1-1.4.4: 1:3: cannot set freq 44100 (v2/v3): err -110
[106453.807671] usb 1-1.4.4: uac_clock_source_is_valid(): cannot get clock validity for id 9
[106453.807687] usb 1-1.4.4: clock source 9 is not valid, cannot use
[106458.927975] usb 1-1.4.4: 1:3: cannot get freq (v2/v3): err -110
[106464.048123] usb 1-1.4.4: 1:3: cannot set freq 44100 (v2/v3): err -110
[106469.168334] usb 1-1.4.4: uac_clock_source_is_valid(): cannot get clock validity for id 9
[106469.168350] usb 1-1.4.4: clock source 9 is not valid, cannot use
[106474.288439] usb 1-1.4.4: 1:3: cannot get freq (v2/v3): err -110
[106479.408644] usb 1-1.4.4: 1:3: cannot set freq 44100 (v2/v3): err -110
[106489.649135] usb 1-1.4.4: uac_clock_source_is_valid(): cannot get clock validity for id 9
[106489.649150] usb 1-1.4.4: clock source 9 is not valid, cannot use
[106494.769270] usb 1-1.4.4: 1:3: cannot get freq (v2/v3): err -110
[106499.889634] usb 1-1.4.4: 1:3: cannot set freq 44100 (v2/v3): err -110
[106555.187639] usb 1-1.4.4: uac_clock_source_is_valid(): cannot get clock validity for id 9
[106555.187656] usb 1-1.4.4: clock source 9 is not valid, cannot use
[106560.308249] usb 1-1.4.4: 1:3: cannot get freq (v2/v3): err -110
[106565.429164] usb 1-1.4.4: 1:3: cannot set freq 44100 (v2/v3): err -110
[106570.548398] usb 1-1.4.4: uac_clock_source_is_valid(): cannot get clock validity for id 9
[106570.548414] usb 1-1.4.4: clock source 9 is not valid, cannot use
[106575.672558] usb 1-1.4.4: 1:3: cannot get freq (v2/v3): err -110
[106580.788689] usb 1-1.4.4: 1:3: cannot set freq 44100 (v2/v3): err -110
[106585.908860] usb 1-1.4.4: uac_clock_source_is_valid(): cannot get clock validity for id 9
[106585.908875] usb 1-1.4.4: clock source 9 is not valid, cannot use
[106591.029048] usb 1-1.4.4: 1:3: cannot get freq (v2/v3): err -110
[106596.149323] usb 1-1.4.4: 1:3: cannot set freq 44100 (v2/v3): err -110
[106606.389585] usb 1-1.4.4: uac_clock_source_is_valid(): cannot get clock validity for id 9
[106606.389600] usb 1-1.4.4: clock source 9 is not valid, cannot use
[106611.509741] usb 1-1.4.4: 1:3: cannot get freq (v2/v3): err -110
[106616.630123] usb 1-1.4.4: 1:3: cannot set freq 44100 (v2/v3): err -110
[113653.930661] usb 1-1.4.4: uac_clock_source_is_valid(): cannot get clock validity for id 9
[113653.930680] usb 1-1.4.4: clock source 9 is not valid, cannot use
[113659.049818] usb 1-1.4.4: 1:3: cannot get freq (v2/v3): err -110
[113664.169820] usb 1-1.4.4: 1:3: cannot set freq 44100 (v2/v3): err -110
[113669.290504] usb 1-1.4.4: uac_clock_source_is_valid(): cannot get clock validity for id 9
[113669.290525] usb 1-1.4.4: clock source 9 is not valid, cannot use
[113674.409947] usb 1-1.4.4: 1:3: cannot get freq (v2/v3): err -110
[113679.533671] usb 1-1.4.4: 1:3: cannot set freq 44100 (v2/v3): err -110
[113684.650312] usb 1-1.4.4: uac_clock_source_is_valid(): cannot get clock validity for id 9
[113684.650343] usb 1-1.4.4: clock source 9 is not valid, cannot use
[113689.770198] usb 1-1.4.4: 1:3: cannot get freq (v2/v3): err -110
[113694.890343] usb 1-1.4.4: 1:3: cannot set freq 44100 (v2/v3): err -110
[113705.130441] usb 1-1.4.4: uac_clock_source_is_valid(): cannot get clock validity for id 9
[113705.130458] usb 1-1.4.4: clock source 9 is not valid, cannot use
[113710.250563] usb 1-1.4.4: 1:3: cannot get freq (v2/v3): err -110
[113715.370795] usb 1-1.4.4: 1:3: cannot set freq 44100 (v2/v3): err -110
[115173.807282] usb 1-1.4.4: uac_clock_source_is_valid(): cannot get clock validity for id 9
[115173.807303] usb 1-1.4.4: clock source 9 is not valid, cannot use
[115178.927416] usb 1-1.4.4: 1:3: cannot get freq (v2/v3): err -110
[115184.047765] usb 1-1.4.4: 1:3: cannot set freq 44100 (v2/v3): err -110
[115189.167713] usb 1-1.4.4: uac_clock_source_is_valid(): cannot get clock validity for id 9
[115189.167777] usb 1-1.4.4: clock source 9 is not valid, cannot use
[115194.287568] usb 1-1.4.4: 1:3: cannot get freq (v2/v3): err -110
[115199.407605] usb 1-1.4.4: 1:3: cannot set freq 44100 (v2/v3): err -110
[115204.531749] usb 1-1.4.4: uac_clock_source_is_valid(): cannot get clock validity for id 9
[115204.531773] usb 1-1.4.4: clock source 9 is not valid, cannot use
[115209.647668] usb 1-1.4.4: 1:3: cannot get freq (v2/v3): err -110
[115214.767666] usb 1-1.4.4: 1:3: cannot set freq 44100 (v2/v3): err -110
[115225.007792] usb 1-1.4.4: uac_clock_source_is_valid(): cannot get clock validity for id 9
[115225.007808] usb 1-1.4.4: clock source 9 is not valid, cannot use
[115230.127715] usb 1-1.4.4: 1:3: cannot get freq (v2/v3): err -110
[115235.247881] usb 1-1.4.4: 1:3: cannot set freq 44100 (v2/v3): err -110
[115278.004330] usb 1-1.4.4: uac_clock_source_is_valid(): cannot get clock validity for id 9
[115278.004365] usb 1-1.4.4: clock source 9 is not valid, cannot use
[115283.120203] usb 1-1.4.4: 1:3: cannot get freq (v2/v3): err -110
[115288.241693] usb 1-1.4.4: 1:3: cannot set freq 44100 (v2/v3): err -110
[115293.360357] usb 1-1.4.4: uac_clock_source_is_valid(): cannot get clock validity for id 9
[115293.360372] usb 1-1.4.4: clock source 9 is not valid, cannot use
[115298.482942] usb 1-1.4.4: 1:3: cannot get freq (v2/v3): err -110
[115303.600605] usb 1-1.4.4: 1:3: cannot set freq 44100 (v2/v3): err -110
[115308.724491] usb 1-1.4.4: uac_clock_source_is_valid(): cannot get clock validity for id 9
[115308.724508] usb 1-1.4.4: clock source 9 is not valid, cannot use
[115313.840534] usb 1-1.4.4: 1:3: cannot get freq (v2/v3): err -110
[115318.960661] usb 1-1.4.4: 1:3: cannot set freq 44100 (v2/v3): err -110
[115329.200704] usb 1-1.4.4: uac_clock_source_is_valid(): cannot get clock validity for id 9
[115329.200720] usb 1-1.4.4: clock source 9 is not valid, cannot use
[115334.323647] usb 1-1.4.4: 1:3: cannot get freq (v2/v3): err -110
[115339.440794] usb 1-1.4.4: 1:3: cannot set freq 44100 (v2/v3): err -110
[116146.366281] usb 1-1.4.4: uac_clock_source_is_valid(): cannot get clock validity for id 9
[116146.366332] usb 1-1.4.4: clock source 9 is not valid, cannot use
[116151.490166] usb 1-1.4.4: 1:3: cannot get freq (v2/v3): err -110
[116156.607411] usb 1-1.4.4: 1:3: cannot set freq 44100 (v2/v3): err -110
[116161.731620] usb 1-1.4.4: uac_clock_source_is_valid(): cannot get clock validity for id 9
[116161.731639] usb 1-1.4.4: clock source 9 is not valid, cannot use
[116166.848303] usb 1-1.4.4: 1:3: cannot get freq (v2/v3): err -110
[116171.969110] usb 1-1.4.4: 1:3: cannot set freq 44100 (v2/v3): err -110
[116177.093267] usb 1-1.4.4: uac_clock_source_is_valid(): cannot get clock validity for id 9
[116177.093290] usb 1-1.4.4: clock source 9 is not valid, cannot use
[116182.210338] usb 1-1.4.4: 1:3: cannot get freq (v2/v3): err -110
[116187.331110] usb 1-1.4.4: 1:3: cannot set freq 44100 (v2/v3): err -110
[116197.572240] usb 1-1.4.4: uac_clock_source_is_valid(): cannot get clock validity for id 9
[116197.572290] usb 1-1.4.4: clock source 9 is not valid, cannot use
[116202.694086] usb 1-1.4.4: 1:3: cannot get freq (v2/v3): err -110
[116207.816555] usb 1-1.4.4: 1:3: cannot set freq 44100 (v2/v3): err -110
[116212.933706] usb 1-1.4.4: uac_clock_source_is_valid(): cannot get clock validity for id 9
[116212.933727] usb 1-1.4.4: clock source 9 is not valid, cannot use
[116218.054253] usb 1-1.4.4: 1:3: cannot get freq (v2/v3): err -110
[116223.175060] usb 1-1.4.4: 1:3: cannot set freq 44100 (v2/v3): err -110
[116228.295421] usb 1-1.4.4: uac_clock_source_is_valid(): cannot get clock validity for id 9
[116228.295439] usb 1-1.4.4: clock source 9 is not valid, cannot use
[116231.444781] vc4-drm gpu: swiotlb buffer is full (sz: 425984 bytes), total 32768 (slots), used 182 (slots)
[116231.451548] vc4-drm gpu: swiotlb buffer is full (sz: 425984 bytes), total 32768 (slots), used 182 (slots)
[116233.415970] usb 1-1.4.4: 1:3: cannot get freq (v2/v3): err -110
[116238.536498] usb 1-1.4.4: 1:3: cannot set freq 44100 (v2/v3): err -110
[116238.965338] vc4-drm gpu: swiotlb buffer is full (sz: 393216 bytes), total 32768 (slots), used 90 (slots)
[116238.968648] vc4-drm gpu: swiotlb buffer is full (sz: 393216 bytes), total 32768 (slots), used 90 (slots)
[116257.482672] usb 1-1.4.4: uac_clock_source_is_valid(): cannot get clock validity for id 9
[116257.482695] usb 1-1.4.4: clock source 9 is not valid, cannot use
[116262.603264] usb 1-1.4.4: 1:3: cannot get freq (v2/v3): err -110
[116265.937536] usb 1-1.4.4: 1:3: cannot set freq 44100 (v2/v3): err -71
[116265.975087] usb 1-1.4.4: uac_clock_source_is_valid(): cannot get clock validity for id 9
[116265.975107] usb 1-1.4.4: clock source 9 is not valid, cannot use
[116265.975414] usb 1-1.4.4: 1:3: cannot get freq (v2/v3): err -71
[116265.975725] usb 1-1.4.4: 1:3: cannot set freq 44100 (v2/v3): err -71
[116266.081516] usb 1-1.4.4: USB disconnect, device number 7
[116268.607990] usb 1-1.4.4: new high-speed USB device number 8 using xhci_hcd
[116268.727703] usb 1-1.4.4: New USB device found, idVendor=3302, idProduct=3352, bcdDevice= 0.01
[116268.727886] usb 1-1.4.4: New USB device strings: Mfr=1, Product=2, SerialNumber=0
[116268.727891] usb 1-1.4.4: Product: CX31993 384Khz HIFI AUDIO
[116268.727897] usb 1-1.4.4: Manufacturer: Synaptics
[116268.759483] input: Synaptics CX31993 384Khz HIFI AUDIO Consumer Control as /devices/platform/scb/fd500000.pcie/pci0000:00/0000:00:00.0/0000:01:00.0/usb1/1-1/1-1.4/1-1.4.4/1-1.4.4:1.3/0003:3302:3352.0005/input/input9
[116268.820075] hid-generic 0003:3302:3352.0005: input,hidraw3: USB HID v1.11 Device [Synaptics CX31993 384Khz HIFI AUDIO] on usb-0000:01:00.0-1.4.4/input3
[116269.668846] usb 1-1.4.4: USB disconnect, device number 8
[116271.936269] usb 1-1.4.4: new high-speed USB device number 9 using xhci_hcd
[116272.056178] usb 1-1.4.4: New USB device found, idVendor=3302, idProduct=3352, bcdDevice= 0.01
[116272.056224] usb 1-1.4.4: New USB device strings: Mfr=1, Product=2, SerialNumber=0
[116272.056231] usb 1-1.4.4: Product: CX31993 384Khz HIFI AUDIO
[116272.056234] usb 1-1.4.4: Manufacturer: Synaptics
[116272.083977] input: Synaptics CX31993 384Khz HIFI AUDIO Consumer Control as /devices/platform/scb/fd500000.pcie/pci0000:00/0000:00:00.0/0000:01:00.0/usb1/1-1/1-1.4/1-1.4.4/1-1.4.4:1.3/0003:3302:3352.0006/input/input10
[116272.144434] hid-generic 0003:3302:3352.0006: input,hidraw3: USB HID v1.11 Device [Synaptics CX31993 384Khz HIFI AUDIO] on usb-0000:01:00.0-1.4.4/input3

After reconnecting USB sound card it starts to work again.