Bug 1971387

Summary: Upgrade to alsa-utils-1.2.5-2.fc34.x86_64 causes multi-minute delays at bootup
Product: [Fedora] Fedora Reporter: larsh
Component: alsa-libAssignee: Jaroslav Kysela <jkysela>
Status: CLOSED ERRATA QA Contact: Fedora Extras Quality Assurance <extras-qa>
Severity: medium Docs Contact:
Priority: unspecified    
Version: 34CC: fmhstar, jkysela, larsh
Target Milestone: ---   
Target Release: ---   
Hardware: x86_64   
OS: Linux   
Whiteboard:
Fixed In Version: alsa-lib-1.2.5.1-1.fc34 Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2021-06-17 01:18:45 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:

Description larsh 2021-06-14 00:27:50 UTC
Description of problem:
After I upgraded to alsa-utils-1.2.5-2.fc34.x86_64 the machine hangs at bootup for 2-3 minutes

Downgrading to alsa-utils-1.2.4-2.fc34.x86_64 restores the old (fast) behavior.

Version-Release number of selected component (if applicable):
alsa-utils-1.2.5-2.fc34.x86_64

How reproducible:
Every time.
Verified on two different Thinkpads: X1 extreme gen2, and an old T440P.

Steps to Reproduce:
1. Upgrade to alsa-utils-1.2.5-2.fc34.x86_64
2. Reboot. Observe long waittime at reboot.

Actual results:
Long delay at bootup.

Expected results:
Normal bootup time without delay.

Additional info:
Relevant parts from the logs (reverse order):

Jun 12 13:22:18 think systemd-udevd[768]: controlC0: Failed to execute '/sbin/alsactl -E ALSA_CONFIG_PATH=/etc/alsa/alsactl.conf --initfile=/lib/alsa/init/00main nrestore /dev/snd/controlC0', ignoring: Input/o>
Jun 12 13:22:18 think systemd-udevd[768]: controlC0: Failed to wait for spawned command '/sbin/alsactl -E ALSA_CONFIG_PATH=/etc/alsa/alsactl.conf --initfile=/lib/alsa/init/00main nrestore /dev/snd/controlC0': >
Jun 12 13:22:18 think systemd-udevd[768]: controlC0: Process '/sbin/alsactl -E ALSA_CONFIG_PATH=/etc/alsa/alsactl.conf --initfile=/lib/alsa/init/00main nrestore /dev/snd/controlC0' terminated by signal ABRT.
Jun 12 13:22:18 think systemd-udevd[874]: controlC1: Failed to execute '/sbin/alsactl -E ALSA_CONFIG_PATH=/etc/alsa/alsactl.conf --initfile=/lib/alsa/init/00main nrestore /dev/snd/controlC1', ignoring: Input/o>
Jun 12 13:22:18 think systemd-udevd[874]: controlC1: Failed to wait for spawned command '/sbin/alsactl -E ALSA_CONFIG_PATH=/etc/alsa/alsactl.conf --initfile=/lib/alsa/init/00main nrestore /dev/snd/controlC1': >
Jun 12 13:22:18 think systemd-udevd[874]: controlC1: Process '/sbin/alsactl -E ALSA_CONFIG_PATH=/etc/alsa/alsactl.conf --initfile=/lib/alsa/init/00main nrestore /dev/snd/controlC1' terminated by signal ABRT.
Jun 12 13:22:18 think audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 subj=kernel msg='unit=systemd-coredump@1-2589-0 comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=>
Jun 12 13:22:18 think audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 subj=kernel msg='unit=systemd-coredump@0-2256-0 comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=>
Jun 12 13:22:18 think audit[2698]: SYSTEM_BOOT pid=2698 uid=0 auid=4294967295 ses=4294967295 subj=kernel msg=' comm="systemd-update-utmp" exe="/usr/lib/systemd/systemd-update-utmp" hostname=? addr=? terminal=?>
Jun 12 13:22:18 think systemd-coredump[2676]: [🡕] Process 2584 (alsactl) of user 0 dumped core.

Stack trace of thread 2584:
#0  0x00007f2f19cad2a2 raise (libc.so.6 + 0x3d2a2)
#1  0x00007f2f19c968a4 abort (libc.so.6 + 0x268a4)
#2  0x00007f2f19c96789 __assert_fail_base.cold (libc.so.6 + 0x26789)
#3  0x00007f2f19ca5a16 __assert_fail (libc.so.6 + 0x35a16)
#4  0x00007f2f19eb5d3a snd_config_delete (libasound.so.2 + 0x55d3a)
#5  0x0000558a669f7ada main (alsactl + 0x8ada)
#6  0x00007f2f19c97b75 __libc_start_main (libc.so.6 + 0x27b75)
#7  0x0000558a669f859e _start (alsactl + 0x959e)
Jun 12 13:22:18 think systemd-coredump[2675]: [🡕] Process 2255 (alsactl) of user 0 dumped core.

Stack trace of thread 2255:
#0  0x00007f9e88def2a2 raise (libc.so.6 + 0x3d2a2)
#1  0x00007f9e88dd88a4 abort (libc.so.6 + 0x268a4)
#2  0x00007f9e88dd8789 __assert_fail_base.cold (libc.so.6 + 0x26789)
#3  0x00007f9e88de7a16 __assert_fail (libc.so.6 + 0x35a16)
#4  0x00007f9e88ff7d3a snd_config_delete (libasound.so.2 + 0x55d3a)
#5  0x00005637bf4ddada main (alsactl + 0x8ada)
#6  0x00007f9e88dd9b75 __libc_start_main (libc.so.6 + 0x27b75)
#7  0x00005637bf4de59e _start (alsactl + 0x959e)

...

Jun 12 13:22:17 think systemd[1]: Failed to start Wait for udev To Complete Device Initialization.
Jun 12 13:22:17 think systemd[1]: systemd-udev-settle.service: Failed with result 'exit-code'.
Jun 12 13:22:17 think systemd[1]: systemd-udev-settle.service: Main process exited, code=exited, status=1/FAILURE
Jun 12 13:21:21 think systemd-udevd[768]: controlC0: Spawned process '/sbin/alsactl -E ALSA_CONFIG_PATH=/etc/alsa/alsactl.conf --initfile=/lib/alsa/init/00main nrestore /dev/snd/controlC0' [2584] is taking lon>
Jun 12 13:21:21 think systemd-udevd[714]: controlC0: Worker [768] processing SEQNUM=3871 is taking a long time
Jun 12 13:21:19 think systemd-udevd[874]: controlC1: Spawned process '/sbin/alsactl -E ALSA_CONFIG_PATH=/etc/alsa/alsactl.conf --initfile=/lib/alsa/init/00main nrestore /dev/snd/controlC1' [2255] is taking lon>
Jun 12 13:21:19 think systemd-udevd[714]: controlC1: Worker [874] processing SEQNUM=3704 is taking a long time

...

Jun 12 13:20:20 think kernel: audit: type=1701 audit(1623529220.569:112): auid=4294967295 uid=0 gid=0 ses=4294967295 subj=kernel pid=2584 comm="alsactl" exe="/usr/sbin/alsactl" sig=6 res=1
Jun 12 13:20:20 think audit[2584]: ANOM_ABEND auid=4294967295 uid=0 gid=0 ses=4294967295 subj=kernel pid=2584 comm="alsactl" exe="/usr/sbin/alsactl" sig=6 res=1
Jun 12 13:20:20 think kernel: input: HDA Intel PCH Headphone as /devices/pci0000:00/0000:00:1f.3/sound/card0/input20
Jun 12 13:20:20 think kernel: input: HDA Intel PCH Mic as /devices/pci0000:00/0000:00:1f.3/sound/card0/input19
Jun 12 13:20:20 think kernel: snd_hda_codec_conexant hdaudioC0D0:      Mic=0x19
Jun 12 13:20:20 think kernel: snd_hda_codec_conexant hdaudioC0D0:      Internal Mic=0x1a
Jun 12 13:20:20 think kernel: snd_hda_codec_conexant hdaudioC0D0:    inputs:
Jun 12 13:20:20 think kernel: snd_hda_codec_conexant hdaudioC0D0:    mono: mono_out=0x0
Jun 12 13:20:20 think kernel: snd_hda_codec_conexant hdaudioC0D0:    hp_outs=1 (0x16/0x0/0x0/0x0/0x0)
Jun 12 13:20:20 think kernel: snd_hda_codec_conexant hdaudioC0D0:    speaker_outs=0 (0x0/0x0/0x0/0x0/0x0)
Jun 12 13:20:20 think kernel: snd_hda_codec_conexant hdaudioC0D0: autoconfig for CX8070: line_outs=1 (0x17/0x0/0x0/0x0/0x0) type:speaker
Jun 12 13:20:20 think kernel: snd_hda_codec_conexant hdaudioC0D0: CX8070: BIOS auto-probing.

Comment 1 Jaroslav Kysela 2021-06-14 07:49:05 UTC
It's already fixed in upstream: https://github.com/alsa-project/alsa-utils/commit/6018c2014ac24877b2aa58c2c57f2fd901e6c7b1 . I'll update Fedora packages ASAP.

Comment 2 Jaroslav Kysela 2021-06-14 12:01:35 UTC
*** Bug 1971559 has been marked as a duplicate of this bug. ***

Comment 3 Fedora Update System 2021-06-14 13:24:55 UTC
FEDORA-2021-3149b1b25c has been submitted as an update to Fedora 34. https://bodhi.fedoraproject.org/updates/FEDORA-2021-3149b1b25c

Comment 4 larsh 2021-06-14 16:14:29 UTC
Awesome. Thank you. (Didn't think to check upstream - my apologies.)

Comment 5 Fedora Update System 2021-06-15 01:08:34 UTC
FEDORA-2021-3149b1b25c has been pushed to the Fedora 34 testing repository.
Soon you'll be able to install the update with the following command:
`sudo dnf upgrade --enablerepo=updates-testing --advisory=FEDORA-2021-3149b1b25c`
You can provide feedback for this update here: https://bodhi.fedoraproject.org/updates/FEDORA-2021-3149b1b25c

See also https://fedoraproject.org/wiki/QA:Updates_Testing for more information on how to test updates.

Comment 6 larsh 2021-06-15 19:46:48 UTC
I can confirm that there is no hanging upon restart. All good now. Thanks.

Comment 7 Fedora Update System 2021-06-17 01:18:45 UTC
FEDORA-2021-3149b1b25c has been pushed to the Fedora 34 stable repository.
If problem still persists, please make note of it in this bug report.