udevd hangs on vgscan trying to replicate start-up

[Bevis King]

[ 405.990023] sd 4:0:0:1: [sdf] Spinning up disk........
[ 455.102162] type=1400 audit(1322168668.036:18): apparmor="STATUS" operation="profile_replace" name="/usr/lib/cups/backend/cups-pdf" pid=2034 comm="apparmor_parser"
[ 455.103001] type=1400 audit(1322168668.036:19): apparmor="STATUS" operation="profile_replace" name="/usr/sbin/cupsd" pid=2034 comm="apparmor_parser"
[ 458.150009] ...
[ 480.480028] INFO: task udisks-lvm-pv-e:606 blocked for more than 120 seconds.
[ 480.480032] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 480.480036] udisks-lvm-pv-e D 0000000000000000 0 606 1 0x00000000
[ 480.480042] ffff880123463b48 0000000000000082 ffff880123463fd8 ffff880123462000
[ 480.480047] 0000000000013d00 ffff88012313c858 ffff880123463fd8 0000000000013d00
[ 480.480052] ffffffff81a0b020 ffff88012313c4a0 0000000000800050 ffff880125c38020
[ 480.480058] Call Trace:
[ 480.480067] [<ffffffff815c1fa7>] __mutex_lock_slowpath+0xf7/0x180
[ 480.480072] [<ffffffff815c19fb>] mutex_lock+0x2b/0x50
[ 480.480077] [<ffffffff81199720>] __blkdev_get+0x50/0x3e0
[ 480.480081] [<ffffffff81199b11>] blkdev_get+0x61/0x2c0
[ 480.480085] [<ffffffff815c326e>] ? _raw_spin_lock+0xe/0x20
[ 480.480089] [<ffffffff81199d70>] ? blkdev_open+0x0/0x80
[ 480.480093] [<ffffffff81199dd5>] blkdev_open+0x65/0x80
[ 480.480098] [<ffffffff81162d2e>] __dentry_open+0xce/0x2f0
[ 480.480107] [<ffffffff8116ef73>] ? generic_permission+0x23/0xc0
[ 480.480110] [<ffffffff81164221>] nameidata_to_filp+0x71/0x80
[ 480.480113] [<ffffffff81173428>] finish_open+0xc8/0x1b0
[ 480.480116] [<ffffffff81172617>] ? do_path_lookup+0x87/0x160
[ 480.480119] [<ffffffff81173be8>] do_filp_open+0x2c8/0x7c0
[ 480.480122] [<ffffffff81172962>] ? user_path_at+0x62/0xa0
[ 480.480127] [<ffffffff812e6e37>] ? __strncpy_from_user+0x27/0x60
[ 480.480130] [<ffffffff81180f17>] ? alloc_fd+0xf7/0x150
[ 480.480133] [<ffffffff8116429a>] do_sys_open+0x6a/0x150
[ 480.480136] [<ffffffff811643a0>] sys_open+0x20/0x30
[ 480.480140] [<ffffffff8100c002>] system_call_fastpath+0x16/0x1b
[ 480.480156] INFO: task hdparm:1365 blocked for more than 120 seconds.
[ 480.480158] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 480.480160] hdparm D 0000000000000001 0 1365 1336 0x00000000
[ 480.480164] ffff880116e4bb48 0000000000000082 ffff880116e4bfd8 ffff880116e4a000
[ 480.480168] 0000000000013d00 ffff880116ea4858 ffff880116e4bfd8 0000000000013d00
[ 480.480171] ffff880127718000 ffff880116ea44a0 0000000000800050 ffff880125c38020
[ 480.480175] Call Trace:
[ 480.480179] [<ffffffff815c1fa7>] __mutex_lock_slowpath+0xf7/0x180
[ 480.480182] [<ffffffff815c19fb>] mutex_lock+0x2b/0x50
[ 480.480185] [<ffffffff81199720>] __blkdev_get+0x50/0x3e0
[ 480.480188] [<ffffffff81199b11>] blkdev_get+0x61/0x2c0
[ 480.480191] [<ffffffff815c326e>] ? _raw_spin_lock+0xe/0x20
[ 480.480194] [<ffffffff81199d70>] ? blkdev_open+0x0/0x80
[ 480.480196] [<ffffffff81199dd5>] blkdev_open+0x65/0x80
[ 480.480199] [<ffffffff81162d2e>] __dentry_open+0xce/0x2f0
[ 480.480202] [<ffffffff8116ef73>] ? generic_permission+0x23/0xc0
[ 480.480205] [<ffffffff81164221>] nameidata_to_filp+0x71/0x80
[ 480.480208] [<ffffffff81173428>] finish_open+0xc8/0x1b0
[ 480.480211] [<ffffffff81172617>] ? do_path_lookup+0x87/0x160
[ 480.480214] [<ffffffff81173be8>] do_filp_open+0x2c8/0x7c0
[ 480.480217] [<ffffffff812e6e37>] ? __strncpy_from_user+0x27/0x60
[ 480.480221] [<ffffffff81180f17>] ? alloc_fd+0xf7/0x150
[ 480.480224] [<ffffffff8116429a>] do_sys_open+0x6a/0x150
[ 480.480226] [<ffffffff811643a0>] sys_open+0x20/0x30
[ 480.480229] [<ffffffff8100c002>] system_call_fastpath+0x16/0x1b
[ 480.480235] INFO: task udisks-daemon:1786 blocked for more than 120 seconds.
[ 480.480237] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 480.480239] udisks-daemon D 0000000000000001 0 1786 1 0x00000000
[ 480.480242] ffff8801240b1b48 0000000000000086 ffff8801240b1fd8 ffff8801240b0000
[ 480.480246] 0000000000013d00 ffff88012772b178 ffff8801240b1fd8 0000000000013d00
[ 480.480250] ffff880127718000 ffff88012772adc0 0000000000800050 ffff880125c38020
[ 480.480254] Call Trace:
[ 480.480257] [<ffffffff815c1fa7>] __mutex_lock_slowpath+0xf7/0x180
[ 480.480260] [<ffffffff815c19fb>] mutex_lock+0x2b/0x50
[ 480.480263] [<ffffffff81199720>] __blkdev_get+0x50/0x3e0
[ 480.480266] [<ffffffff81199b11>] blkdev_get+0x61/0x2c0
[ 480.480269] [<ffffffff815c326e>] ? _raw_spin_lock+0xe/0x20
[ 480.480272] [<ffffffff81199d70>] ? blkdev_open+0x0/0x80
[ 480.480275] [<ffffffff81199dd5>] blkdev_open+0x65/0x80
[ 480.480278] [<ffffffff81162d2e>] __dentry_open+0xce/0x2f0
[ 480.480280] [<ffffffff8116ef73>] ? generic_permission+0x23/0xc0
[ 480.480283] [<ffffffff81164221>] nameidata_to_filp+0x71/0x80
[ 480.480286] [<ffffffff81173428>] finish_open+0xc8/0x1b0
[ 480.480289] [<ffffffff81172617>] ? do_path_lookup+0x87/0x160
[ 480.480292] [<ffffffff81173be8>] do_filp_open+0x2c8/0x7c0
[ 480.480296] [<ffffffff812e6e37>] ? __strncpy_from_user+0x27/0x60
[ 480.480299] [<ffffffff81180f17>] ? alloc_fd+0xf7/0x150
[ 480.480302] [<ffffffff8116429a>] do_sys_open+0x6a/0x150
[ 480.480305] [<ffffffff81162c30>] ? filp_close+0x60/0x90
[ 480.480307] [<ffffffff811643a0>] sys_open+0x20/0x30
[ 480.480310] [<ffffffff8100c002>] system_call_fastpath+0x16/0x1b
[ 488.840008] ...not responding...

[Bevis King (brwk)]

This is a result of running:

# cd /etc/udev/rules.d/
root@cyane:/etc/udev/rules.d# more 85-lvm2.rules
# This file causes block devices with LVM signatures to be automatically
# added to their volume group.
# See udev(8) for syntax
# MODIFIED per https://bugs.launchpad.net/ubuntu/+source/udev/+bug/789930

SUBSYSTEM=="block", ACTION=="add|change", ENV{ID_FS_TYPE}=="lvm*|LVM*", \
 RUN+="watershed sh -c '/sbin/lvm vgscan; /sbin/lvm vgchange --noudevsync
 -a y'"
root@cyane:/etc/udev/rules.d# vgscan
  Reading all physical volumes. This may take a while...

[Bevis King (brwk)]

root@cyane:/lib/modules/2.6.38-12-generic# cat /proc/cmdline
BOOT_IMAGE=/boot/vmlinuz-2.6.38-12-generic root=UUID=0aaee49b-84b7-45a1-88a7-b21577635021 ro quiet splash clocksource=jiffies nolapic_timers vt.handoff=7
root@cyane:/lib/modules/2.6.38-12-generic#

root@cyane:/lib/modules/2.6.38-12-generic# lsb_release -a
No LSB modules are available.
Distributor ID: Ubuntu
Description: Ubuntu 11.04
Release: 11.04
Codename: natty
root@cyane:/lib/modules/2.6.38-12-generic#

[Bevis King (brwk)]

System configuration is an Intel G41 motherboard with 4 300GB SATA drives, each with a small boot section and a much larger partition devoted to being part of a RAID5 array.

Thus /dev/md0 is built from the sd[abcd]2 partition each of which is approx 250GB. The resulting /dev/md0 device is an LVM2 physical device. Sometime around the 2.6.35 kernel this configuration became unstable with the boot being extremely slow and a udevd: worker exited unexpectedly error.

Once finally booted, the system has been working normally.

Both update-grub and update-initramfs -c -k all have been run since the last update/configuration change.

[Bevis King (brwk)]

As far as I can tell the errant sdf drive it's complaining about was most recently assigned to the SD card reader connected by USB to the system.

[Bevis King (brwk)]

Disconnecting the motherboard USB -> Card reader connection brings back an instant successful response.