udev initramfs hook ignores that udevadm is disabled, copies it anyway

[Steve Langasek]

Binary package hint: udev

I've just experienced a perfect storm of bugs during an upgrade, which I will relate here for its amusement value rather than for its relevance in fixing the bug that I am currently filing.

During an upgrade to the latest karmic - which somehow managed to find over 150 distinct packages in need of upgrading - the 'restart udev' command in the middle of the udev upgrade hung.

'sudo initctl log-priority debug' also hung - in the 'sudo' part, not the 'initctl' part. Trying to run 'sudo' anywhere else obviously also hangs.

Switching to VT 1 and trying to log in, the login is accepted... and then hangs right after pam_motd, without giving me a shell (this points to pam_ck_connector having problems).

So switching back and forth between X and VT1 and trying a few different things to get myself unwedged, something gets confused on the audio side, causing my speakers to repeat a single sample from the music I had playing. So I try to kill pulseaudio and get it to restart.

Killing pulseaudio alerts gnome-settings-daemon, which tries to reconnect, which hangs... thereby hanging metacity.

So now I can't type in any of my X terminals either.

So I use SysRq-E, which succeeds in killing the processes and respawning them... aside from the fact that X comes back without a keyboard or mouse.

And of course openssh isn't managed by upstart yet, so I can't log in remotely.

So I reboot, and that's when the fun starts... because among the packages that was upgraded before udev hung was the kernel. Which means that when the package was configured, a new initramfs was generated... while udev was in an unconfigured state. Which means that when /sbin/udevadm was copied into the new initramfs, it wasn't /sbin/udevadm.

Output I should never see from my initramfs at boot time:

  udevadm trigger is not permitted while udev is unconfigured.
  udevadm settle is not permitted while udev is unconfigured.

Fortunately, I had an earlier kernel installed so I could boot from it and recover - but the udev initramfs hook should *never* do this. Either it should explicitly grab /sbin/udevadm.upgrade if present and copy it in place of /sbin/udevadm, or it should detect /sbin/udevadm.upgrade and *abort* the initramfs generation.

What I can't figure out is how the linux package was configured at all under these circumstances: linux-image-2.6.31-14-generic depends on initramfs-tools, and initramfs-tools depends on udev. So there should have been no point at which update-initramfs would have been called while udev was unconfigured. So maybe this isn't a udev bug at all, but a bug in update-manager.

Here, though, are the relevant bits of /var/log/dpkg.log.

2009-10-16 17:37:32 upgrade linux-image-2.6.31-14-generic 2.6.31-14.46 2.6.31-14.48
2009-10-16 17:37:32 status half-configured linux-image-2.6.31-14-generic 2.6.31-14.46
2009-10-16 17:37:32 status unpacked linux-image-2.6.31-14-generic 2.6.31-14.46
2009-10-16 17:37:32 status half-installed linux-image-2.6.31-14-generic 2.6.31-14.46
2009-10-16 17:37:53 status half-installed linux-image-2.6.31-14-generic 2.6.31-14.46
2009-10-16 17:37:56 status unpacked linux-image-2.6.31-14-generic 2.6.31-14.48
2009-10-16 17:37:58 status unpacked linux-image-2.6.31-14-generic 2.6.31-14.48
2009-10-16 17:38:40 upgrade udev 147~-5 147~-6
2009-10-16 17:38:40 status half-configured udev 147~-5
2009-10-16 17:38:40 status unpacked udev 147~-5
2009-10-16 17:38:40 status half-installed udev 147~-5
2009-10-16 17:38:40 status half-installed udev 147~-5
2009-10-16 17:38:40 status half-installed udev 147~-5
2009-10-16 17:38:41 status half-installed udev 147~-5
2009-10-16 17:38:41 status unpacked udev 147~-6
2009-10-16 17:38:41 status unpacked udev 147~-6
2009-10-16 17:41:49 configure linux-image-2.6.31-14-generic 2.6.31-14.48 2.6.31-14.48
2009-10-16 17:41:49 status unpacked linux-image-2.6.31-14-generic 2.6.31-14.48
2009-10-16 17:41:49 status half-configured linux-image-2.6.31-14-generic 2.6.31-14.48
2009-10-16 17:42:12 status installed linux-image-2.6.31-14-generic 2.6.31-14.48
2009-10-16 17:42:55 configure udev 147~-6 147~-6
2009-10-16 17:42:55 status unpacked udev 147~-6
2009-10-16 17:42:55 status unpacked udev 147~-6
2009-10-16 17:42:55 status unpacked udev 147~-6
2009-10-16 17:42:55 status unpacked udev 147~-6
2009-10-16 17:42:56 status unpacked udev 147~-6
2009-10-16 17:42:56 status unpacked udev 147~-6
2009-10-16 17:42:56 status unpacked udev 147~-6
2009-10-16 17:42:56 status half-configured udev 147~-6
<crash>

ProblemType: Bug
Architecture: amd64
CustomUdevRuleFiles: 56-hpmud_support.rules 60-persistent-storage.rules.dpkg-old 60-persistent-storage.rules.dpkg-bak kino.rules
Date: Fri Oct 16 20:10:17 2009
DistroRelease: Ubuntu 9.10
MachineType: LENOVO 6371CTO
Package: udev 147~-6
PccardctlIdent:
 Socket 0:
   no product info available
PccardctlStatus:
 Socket 0:
   no card
ProcCmdLine: root=/dev/mapper/hostname-root ro quiet splash
ProcEnviron:
 PATH=(custom, user)
 LANG=en_US.UTF-8
 SHELL=/bin/bash
ProcVersionSignature: Ubuntu 2.6.31-14.48-generic
SourcePackage: udev
Uname: Linux 2.6.31-14-generic x86_64
dmi.bios.date: 12/27/2006
dmi.bios.vendor: LENOVO
dmi.bios.version: 7IET23WW (1.04 )
dmi.board.name: 6371CTO
dmi.board.vendor: LENOVO
dmi.board.version: Not Available
dmi.chassis.asset.tag: No Asset Information
dmi.chassis.type: 10
dmi.chassis.vendor: LENOVO
dmi.chassis.version: Not Available
dmi.modalias: dmi:bvnLENOVO:bvr7IET23WW(1.04):bd12/27/2006:svnLENOVO:pn6371CTO:pvrThinkPadT60:rvnLENOVO:rn6371CTO:rvrNotAvailable:cvnLENOVO:ct10:cvrNotAvailable:
dmi.product.name: 6371CTO
dmi.product.version: ThinkPad T60
dmi.sys.vendor: LENOVO

[Steve Langasek (vorlon)]

I still don't see any way this could be a udev bug, so reassigning to update-manager, which must have forced out-of-order configuration of the packages?

[Scott James Remnant (Canonical) (canonical-scott)]

Right, the entire reason that udev diverts udevadm out of the way was to *stop* serious bugs caused by mucking around with udev while it wasn't configured (due to the move of rules from /etc to /lib).

[bjaglin (bjaglin)]

I experienced the same problem on Karmic when my laptop turned off (low battery) in a middle of a major package upgrade.

[Michael Vogt (mvo)]

update-manager does not modify anything in the apt ordering. Here is what I got in a chroot:

# apt-get install linux-image udev -o Debug::pkgDpkgPM=true
/usr/bin/dpkg --status-fd 9 --unpack --auto-deconfigure /var/cache/apt/archives/libklibc_1.5.15-1ubuntu2_amd64.deb /var/cache/apt/archives/klibc-utils_1.5.15-1ubuntu2_amd64.deb /var/cache/apt/archives/busybox-initramfs_1%3a1.13.3-1ubuntu7_amd64.deb /var/cache/apt/archives/module-init-tools_3.10-3_amd64.deb /var/cache/apt/archives/libpcre3_7.8-3_amd64.deb /var/cache/apt/archives/libglib2.0-0_2.22.2-0ubuntu1_amd64.deb /var/cache/apt/archives/adduser_3.110ubuntu6_all.deb /var/cache/apt/archives/udev_147~-6_amd64.deb /var/cache/apt/archives/initramfs-tools_0.92bubuntu53_all.deb /var/cache/apt/archives/wireless-crda_1.10_amd64.deb /var/cache/apt/archives/linux-image-2.6.31-14-generic_2.6.31-14.48_amd64.deb /var/cache/apt/archives/linux-firmware_1.24_all.deb /var/cache/apt/archives/linux-image-generic_2.6.31.14.27_amd64.deb /var/cache/apt/archives/linux-image_2.6.31.14.27_amd64.deb
/usr/bin/dpkg --status-fd 11 --configure libklibc klibc-utils busybox-initramfs module-init-tools libpcre3 libglib2.0-0 adduser initramfs-tools udev wireless-crda linux-image-2.6.31-14-generic linux-firmware linux-image-generic linux-image

[Michael Vogt (mvo)]

On upgrade (jaunty->karmic I have):

/usr/bin/dpkg --status-fd 251 --unpack --auto-deconfigure /var/cache/apt/archives/bzip2_1.0.5-3_amd64.deb /var/cache/apt/archives/libbz2-1.0_1.0.5-3_amd64.deb /var/cache/apt/archives/openssl_0.9.8g-16ubuntu3_amd64.deb /var/cache/apt/archives/ca-certificates_20090814_all.deb /var/cache/apt/archives/libgpg-error0_1.6-1ubuntu1_amd64.deb /var/cache/apt/archives/libgcrypt11_1.4.4-2ubuntu2_amd64.deb /var/cache/apt/archives/libtasn1-3_2.2-1_amd64.deb /var/cache/apt/archives/libgnutls26_2.8.3-2_amd64.deb /var/cache/apt/archives/libkeyutils1_1.2-10_amd64.deb /var/cache/apt/archives/libkrb5support0_1.7dfsg~beta3-1_amd64.deb /var/cache/apt/archives/libk5crypto3_1.7dfsg~beta3-1_amd64.deb /var/cache/apt/archives/libkrb5-3_1.7dfsg~beta3-1_amd64.deb /var/cache/apt/archives/libgssapi-krb5-2_1.7dfsg~beta3-1_amd64.deb /var/cache/apt/archives/libidn11_1.15-1_amd64.deb /var/cache/apt/archives/libsasl2-2_2.1.23.dfsg1-1ubuntu3_amd64.deb /var/cache/apt/archives/libsasl2-modules_2.1.23.dfsg1-1ubuntu3_amd64.deb /var/cache/apt/archives/libldap-2.4-2_2.4.18-0ubuntu1_amd64.deb /var/cache/apt/archives/libcurl3-gnutls_7.19.5-1ubuntu2_amd64.deb /var/cache/apt/archives/readline-common_6.0-5_all.deb /var/cache/apt/archives/libreadline6_6.0-5_amd64.deb /var/cache/apt/archives/gpgv_1.4.9-4ubuntu7_amd64.deb /var/cache/apt/archives/gnupg_1.4.9-4ubuntu7_amd64.deb /var/cache/apt/archives/make_3.81-6_amd64.deb /var/cache/apt/archives/ubuntu-keyring_2009.08.28_all.deb /var/cache/apt/archives/locales_2.9+git20090617-3_all.deb /var/cache/apt/archives/libgmp3c2_2%3a4.3.1+dfsg-1ubuntu2_amd64.deb /var/cache/apt/archives/libmpfr1ldbl_2.4.1-1ubuntu1_amd64.deb /var/cache/apt/archives/cpp-4.4_4.4.1-4ubuntu8_amd64.deb /var/cache/apt/archives/cpp_4%3a4.4.1-1ubuntu2_amd64.deb /var/cache/apt/archives/binutils_2.20-0ubuntu1_amd64.deb /var/cache/apt/archives/dpkg-dev_1.15.4ubuntu2_all.deb /var/cache/apt/archives/libgomp1_4.4.1-4ubuntu8_amd64.deb /var/cache/apt/archives/gcc-4.4_4.4.1-4ubuntu8_amd64.deb /var/cache/apt/archives/gcc_4%3a4.4.1-1ubuntu2_amd64.deb /var/cache/apt/archives/libstdc++6-4.4-dev_4.4.1-4ubuntu8_amd64.deb /var/cache/apt/archives/g++-4.4_4.4.1-4ubuntu8_amd64.deb /var/cache/apt/archives/g++_4%3a4.4.1-1ubuntu2_amd64.deb /var/cache/apt/archives/libdb4.6_4.6.21-13ubuntu2_amd64.deb /var/cache/apt/archives/libreadline5_5.2-6_amd64.deb /var/cache/apt/archives/linux-firmware_1.24_all.deb /var/cache/apt/archives/linux-image_2.6.31.14.27_amd64.deb /var/cache/apt/archives/linux-image-generic_2.6.31.14.27_amd64.deb
/usr/bin/dpkg --status-fd 253 --configure libc-dev-bin linux-libc-dev libc6-dev perl perl-modules mawk module-init-tools libklibc klibc-utils busybox-initramfs cpio net-tools netbase ifupdown libglib2.0-0 procps adduser udev initramfs-tools wireless-crda linux-image-2.6.31-14-generic libxapian15 libept0 libncursesw5 libcwidget3 aptitude libbz2-1.0 bzip2 openssl ca-certificates libgpg-error0 libgcrypt11 libtasn1-3 libgnutls26 libkeyutils1 libkrb5support0 libk5crypto3 libkrb5-3 libgssapi-krb5-2 libidn11 libsasl2-modules libsasl2-2 libldap-2.4-2 libcurl3-gnutls readline-common libreadline6 gpgv gnupg make ubuntu-keyring locales libgmp3c2 libmpfr1...

[Steve Langasek (vorlon)]

term.log attached as requested.

Since the recovery was finished by hand using dpkg on the console, the relevant output ends with the lines:

Unpacking replacement grub-c
Log started: 2009-10-18 00:33:04

[Michael Vogt (mvo)]

I just created a chroot with just two packages upgradable:

# apt-get dist-upgrade -o Debug::pkgDpkgPm=true -y -o Debug::pkgOrderList=false -o Debug::pkgPackageManager=true
Reading package lists... Done
Building dependency tree
Reading state information... Done
Calculating upgrade... Done
The following packages will be upgraded:
  linux-image-2.6.31-14-generic udev
2 upgraded, 0 newly installed, 0 to remove and 0 not upgraded.
/usr/bin/dpkg --status-fd 9 --unpack --auto-deconfigure /var/cache/apt/archives/linux-image-2.6.31-14-generic_2.6.31-14.48_amd64.deb /var/cache/apt/archives/udev_147~-6_amd64.deb
/usr/bin/dpkg --status-fd 11 --configure linux-image-2.6.31-14-generic udev

So the ordering here is wrong. If I add initramfs-tools to the mix, it looks right again:
apt-get dist-upgrade -o Debug::pkgDpkgPm=true
Reading package lists... Done
Building dependency tree
Reading state information... Done
Calculating upgrade... Done
The following packages will be upgraded:
  initramfs-tools linux-image-2.6.31-14-generic udev
3 upgraded, 0 newly installed, 0 to remove and 0 not upgraded.
Need to get 0B/29.5MB of archives.
After this operation, 0B of additional disk space will be used.
Do you want to continue [Y/n]?
debconf: delaying package configuration, since apt-utils is not installed
/usr/bin/dpkg --status-fd 9 --unpack --auto-deconfigure /var/cache/apt/archives/udev_147~-6_amd64.deb /var/cache/apt/archives/initramfs-tools_0.92bubuntu53_all.deb /var/cache/apt/archives/linux-image-2.6.31-14-generic_2.6.31-14.48_amd64.deb
/usr/bin/dpkg --status-fd 11 --configure initramfs-tools udev linux-image-2.6.31-14-generic

Now the odd thing is that:
dpkg --unpack --auto-deconfigure /var/cache/apt/archives/linux-image-2.6.31-14-generic_2.6.31-14.48_amd64.deb /var/cache/apt/archives/udev_147~-6_amd64.deb
(Reading database ... 14430 files and directories currently installed.)
Preparing to replace linux-image-2.6.31-14-generic 2.6.31-14.47 (using .../linux-image-2.6.31-14-generic_2.6.31-14.48_amd64.deb) ...
Done.
Unpacking replacement linux-image-2.6.31-14-generic ...
Preparing to replace udev 147~-5 (using .../archives/udev_147~-6_amd64.deb) ...
Adding `local diversion of /sbin/udevadm to /sbin/udevadm.upgrade'
Unpacking replacement udev ...

# dpkg --configure -a
Setting up linux-image-2.6.31-14-generic (2.6.31-14.48) ...
Running depmod.
update-initramfs: Generating /boot/initrd.img-2.6.31-14-generic
Not updating initrd symbolic links since we are being updated/reinstalled
(2.6.31-14.47 was configured last, according to dpkg)
Not updating image symbolic links since we are being updated/reinstalled
(2.6.31-14.47 was configured last, according to dpkg)

Setting up udev (147~-6) ...
udev start/running, process 17756
Removing `local diversion of /sbin/udevadm to /sbin/udevadm.upgrade'
update-initramfs: deferring update (trigger activated)

Processing triggers for initramfs-tools ...
update-initramfs: Generating /boot/initrd.img-2.6.31-14-generic

So here dpkg will also order it this way (first l-i, then udev))

[Michael Vogt (mvo)]

I just checked with the jaunty version of dpkg:

# dpkg --unpack
# dpkg --configure -a

shows the same ordering as the karmic version.

[LimCore (limcore)]

It is said that this bug also is responsible also for Ubuntu not booting, giving following text in first 3 seconds after booting:

GRUB loading.
  udevadm trigger is not permitted while udev is unconfigured.
  udevadm settle is not permitted while udev is unconfigured.
  svgalib: cannot open /dev/mem

which makes computer fully un-bootable. See bug #515950 (now marked as duplicate of this one)

The work around is following (thanks to <slangasek>)
(re)Start computer
If you have grub2 installed, you need to hold down the shift key while booting. If you have grub1 installed, you need to hit escape.
Now you can select the older kernel version from the grub menu
The system will boot normally.
Now open a console and run root command:
sudo update-initramfs -u
that will regenerate the initramfs for the newest kernel,
and after reboot all will work in the newest kernel also.

[Dave Gilbert (ubuntu-treblig)]

I'm seeing this bug on Maverick; I've had it twice now between the earlier alpha's and today.

Today, it happened when I did an update (previous update was about a week ago).

Mounting / and running update-initramfs -k all -u fixed it.

[AZ (m-dev)]

I can confirm that this is still present on Maverick.

[Dave Gilbert (ubuntu-treblig)]

Is the same bug that has just been fixed in udev 162-2.2 - bug 672964 ?

Dave

[Julian Andres Klode (juliank)]

So how is this an APT bug?

[Julian Andres Klode (juliank)]

It seems this was an ordering issue. Ordering was changed a lot in 1.3 and newer (it interacts with dpkg much closer), so I assume that's fixed now.