Bug#928125: losetup causes Dead systemd-udevd processes, blocks forever
Michael Biebl
biebl at debian.org
Sun Apr 28 18:41:47 BST 2019
Am 28.04.19 um 18:00 schrieb Brad Barnett:
>
> Package: udev
> Version: 232-25+deb9u11
>
> After today's upgrade to debian 9.9, I attempted to create a disk image.
>
> I have a script, it does the following:
>
> ###
> dd if=/dev/zero of=/tmp/ff1.raw bs=1G seek=8 count=0
> sync
> sleep 1
> parted /tmp/ff1.raw mklabel msdos
> parted -s /tmp/ff1.raw mkpart primary linux-swap 1 100
> parted -s -- /tmp/ff1.raw mkpart primary ext2 101 -1
> parted -s -- /tmp/ff1.raw set 2 boot on
> sleep 5
> losetup -Pf /tmp/ff1.raw --show
> ###
>
> The above has been run several times per month, for years.
>
> After today's upgrade I rebooted, ran the above, and it locked on losetup.
>
> I see this:
>
> # ps auxwwf
>
> root 346 0.0 0.1 45656 3420 ? Ss 11:30 0:00 /lib/systemd/systemd-udevd --daemon
> root 2596 0.0 0.0 45564 2120 ? S 11:31 0:00 \_ /lib/systemd/systemd-udevd --daemon
> root 2597 0.0 0.0 45564 2184 ? D 11:31 0:00 \_ /lib/systemd/systemd-udevd --daemon
> root 2599 0.0 0.1 45644 3096 ? S 11:31 0:00 \_ /lib/systemd/systemd-udevd --daemon
> root 2602 0.0 0.0 45564 2120 ? D 11:31 0:00 \_ /lib/systemd/systemd-udevd --daemon
> root 2603 0.0 0.0 45656 1936 ? D 11:31 0:00 \_ /lib/systemd/systemd-udevd --daemon
> root 2607 0.0 0.0 45656 1936 ? D 11:31 0:00 \_ /lib/systemd/systemd-udevd --daemon
> root 2609 0.0 0.0 45564 2120 ? D 11:31 0:00 \_ /lib/systemd/systemd-udevd --daemon
> root 2610 0.0 0.0 45656 1936 ? D 11:31 0:00 \_ /lib/systemd/systemd-udevd --daemon
> root 2612 0.0 0.0 45656 1936 ? D 11:31 0:00 \_ /lib/systemd/systemd-udevd --daemon
>
> And
>
> root 2591 0.0 0.0 8064 780 pts/2 D 11:31 0:00 /sbin/losetup -Pf /tmp/ff1.raw --show
>
> I also see this (last 3 'blocks' pasted):
>
> Apr 28 11:34:17 buildvm kernel: [ 242.831744] INFO: task systemd-udevd:2612 blocked for more than 120 seconds.
> Apr 28 11:34:17 buildvm kernel: [ 242.831807] Not tainted 4.9.0-9-amd64 #1 Debian 4.9.168-1
> Apr 28 11:34:17 buildvm kernel: [ 242.831859] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> Apr 28 11:34:17 buildvm kernel: [ 242.831927] systemd-udevd D 0 2612 346 0x00000004
> Apr 28 11:34:17 buildvm kernel: [ 242.831932] ffff8a2dbb10c400 0000000000000000 ffff8a2dbacc5240 ffff8a2dbfa18980
> Apr 28 11:34:17 buildvm kernel: [ 242.831939] ffffffffaf411500 ffffaf84409e7b58 ffffffffaee15a99 1e580f2a959617cf
> Apr 28 11:34:17 buildvm kernel: [ 242.831946] 00000000000402c0
> ffff8a2dbfa18980 0000000000000000 ffff8a2dbacc5240
>
> Apr 28 11:34:17 buildvm kernel: [ 242.831952] Call Trace:
> Apr 28 11:34:17 buildvm kernel: [ 242.831960] [<ffffffffaee15a99>] ? __schedule+0x239/0x6f0
> Apr 28 11:34:17 buildvm kernel: [ 242.831967] [<ffffffffaee15f82>] ? schedule+0x32/0x80
> Apr 28 11:34:17 buildvm kernel: [ 242.831973] [<ffffffffaee1623a>] ? schedule_preempt_disabled+0xa/0x10
> Apr 28 11:34:17 buildvm kernel: [ 242.831977] [<ffffffffaee17c94>] ? __mutex_lock_slowpath+0xb4/0x130
> Apr 28 11:34:17 buildvm kernel: [ 242.831982] [<ffffffffaee17d2b>] ? mutex_lock+0x1b/0x30
> Apr 28 11:34:17 buildvm kernel: [ 242.831988] [<ffffffffc03e11c5>] ? lo_open+0x15/0x50 [loop]
> Apr 28 11:34:17 buildvm kernel: [ 242.831994] [<ffffffffaea48ce3>] ? __blkdev_get+0xd3/0x470
> Apr 28 11:34:17 buildvm kernel: [ 242.832001] [<ffffffffaea492e6>] ? blkdev_get+0x126/0x330
> Apr 28 11:34:17 buildvm kernel: [ 242.832008] [<ffffffffaea27e04>] ? unlock_new_inode+0x44/0x70
> Apr 28 11:34:17 buildvm kernel: [ 242.832014] [<ffffffffaea47e3a>] ? bdget+0xfa/0x110
> Apr 28 11:34:17 buildvm kernel: [ 242.832020] [<ffffffffaea49530>] ? blkdev_get_by_dev+0x40/0x40
> Apr 28 11:34:17 buildvm kernel: [ 242.832026] [<ffffffffaea08e74>] ? do_dentry_open+0x234/0x340
> Apr 28 11:34:17 buildvm kernel: [ 242.832030] [<ffffffffaea1ada7>] ? path_openat+0x777/0x15b0
> Apr 28 11:34:17 buildvm kernel: [ 242.832037] [<ffffffffae9c8211>] ? page_add_file_rmap+0x11/0x110
> Apr 28 11:34:17 buildvm kernel: [ 242.832042] [<ffffffffaea1cea1>] ? do_filp_open+0x91/0x100
> Apr 28 11:34:17 buildvm kernel: [ 242.832047] [<ffffffffae9bb263>] ? handle_mm_fault+0xcc3/0x1350
> Apr 28 11:34:17 buildvm kernel: [ 242.832052] [<ffffffffaea07b3a>] ? __check_object_size+0xfa/0x1d8
> Apr 28 11:34:17 buildvm kernel: [ 242.832058] [<ffffffffaea0a3ae>] ? do_sys_open+0x12e/0x210
> Apr 28 11:34:17 buildvm kernel: [ 242.832064] [<ffffffffae803b7d>] ? do_syscall_64+0x8d/0xf0
> Apr 28 11:34:17 buildvm kernel: [ 242.832069] [<ffffffffaee1a84e>] ? entry_SYSCALL_64_after_swapgs+0x58/0xc6
> Apr 28 11:36:18 buildvm kernel: [ 363.661408] INFO: task losetup:2591 blocked for more than 120 seconds.
> Apr 28 11:36:18 buildvm kernel: [ 363.661487] Not tainted 4.9.0-9-amd64 #1 Debian 4.9.168-1
> Apr 28 11:36:18 buildvm kernel: [ 363.661541] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> Apr 28 11:36:18 buildvm kernel: [ 363.661610] losetup D 0 2591 1 0x00000004
> Apr 28 11:36:18 buildvm kernel: [ 363.661620] ffff8a2db7926c00 0000000000000000 ffff8a2db7956ec0 ffff8a2dbfa18980
> Apr 28 11:36:18 buildvm kernel: [ 363.661628] ffffffffaf411500 ffffaf8440a7fbd8 ffffffffaee15a99 ffffffffaee1a964
> Apr 28 11:36:18 buildvm kernel: [ 363.661635] 00ff8a2db7957a00 ffff8a2dbfa18980 ffff8a2dbacc5240 ffff8a2db7956ec0
> Apr 28 11:36:18 buildvm kernel: [ 363.661642] Call Trace:
> Apr 28 11:36:18 buildvm kernel: [ 363.661656] [<ffffffffaee15a99>] ? __schedule+0x239/0x6f0
> Apr 28 11:36:18 buildvm kernel: [ 363.661663] [<ffffffffaee1a964>] ? __switch_to_asm+0x34/0x70
> Apr 28 11:36:18 buildvm kernel: [ 363.661670] [<ffffffffaee15f82>] ? schedule+0x32/0x80
> Apr 28 11:36:18 buildvm kernel: [ 363.661677] [<ffffffffaee1623a>] ? schedule_preempt_disabled+0xa/0x10
> Apr 28 11:36:18 buildvm kernel: [ 363.661682] [<ffffffffaee17c94>] ? __mutex_lock_slowpath+0xb4/0x130
> Apr 28 11:36:18 buildvm kernel: [ 363.661689] [<ffffffffaee17d2b>] ? mutex_lock+0x1b/0x30
> Apr 28 11:36:18 buildvm kernel: [ 363.661697] [<ffffffffaeb15e46>] ? blkdev_reread_part+0x16/0x30
> Apr 28 11:36:18 buildvm kernel: [ 363.661705] [<ffffffffc03e1803>] ? loop_reread_partitions+0x23/0x50 [loop]
> Apr 28 11:36:18 buildvm kernel: [ 363.661712] [<ffffffffc03e1b3b>] ? loop_set_status+0x30b/0x3a0 [loop]
> Apr 28 11:36:18 buildvm kernel: [ 363.661719] [<ffffffffc03e1e88>] ? loop_set_status64+0x48/0x70 [loop]
> Apr 28 11:36:18 buildvm kernel: [ 363.661726] [<ffffffffc03e3138>] ? lo_ioctl+0xe8/0x6f0 [loop]
> Apr 28 11:36:18 buildvm kernel: [ 363.661734] [<ffffffffaeb16645>] ? blkdev_ioctl+0x265/0x970
> Apr 28 11:36:18 buildvm kernel: [ 363.661740] [<ffffffffae9bb37f>] ? handle_mm_fault+0xddf/0x1350
> Apr 28 11:36:18 buildvm kernel: [ 363.661748] [<ffffffffaea481a9>] ? block_ioctl+0x39/0x40
> Apr 28 11:36:18 buildvm kernel: [ 363.661753] [<ffffffffaea201b2>] ? do_vfs_ioctl+0xa2/0x620
> Apr 28 11:36:18 buildvm kernel: [ 363.661759] [<ffffffffaea207a4>] ? SyS_ioctl+0x74/0x80
> Apr 28 11:36:18 buildvm kernel: [ 363.661765] [<ffffffffae803b7d>] ? do_syscall_64+0x8d/0xf0
> Apr 28 11:36:18 buildvm kernel: [ 363.661771] [<ffffffffaee1a84e>] ? entry_SYSCALL_64_after_swapgs+0x58/0xc6
> Apr 28 11:36:18 buildvm kernel: [ 363.661776] INFO: task systemd-udevd:2597 blocked for more than 120 seconds.
> Apr 28 11:36:18 buildvm kernel: [ 363.661841] Not tainted 4.9.0-9-amd64 #1 Debian 4.9.168-1
> Apr 28 11:36:18 buildvm kernel: [ 363.661894] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> Apr 28 11:36:18 buildvm kernel: [ 363.661962] systemd-udevd D 0 2597 346 0x00000004
> Apr 28 11:36:18 buildvm kernel: [ 363.661969] ffff8a2db7924400 0000000000000000 ffff8a2db79ff180 ffff8a2dbfb18980
> Apr 28 11:36:18 buildvm kernel: [ 363.661976] ffff8a2dbb91cec0 ffffaf844086bd88 ffffffffaee15a99 3959c0b6fb0308ab
> Apr 28 11:36:18 buildvm kernel: [ 363.661983] 00ffaf844086bd70 ffff8a2dbfb18980 ffff8a2dbb219498 ffff8a2db79ff180
> Apr 28 11:36:18 buildvm kernel: [ 363.661990] Call Trace:
> Apr 28 11:36:18 buildvm kernel: [ 363.661998] [<ffffffffaee15a99>] ? __schedule+0x239/0x6f0
> Apr 28 11:36:18 buildvm kernel: [ 363.662006] [<ffffffffaee15f82>] ? schedule+0x32/0x80
> Apr 28 11:36:18 buildvm kernel: [ 363.662013] [<ffffffffaee1623a>] ? schedule_preempt_disabled+0xa/0x10
> Apr 28 11:36:18 buildvm kernel: [ 363.662017] [<ffffffffaee17c94>] ? __mutex_lock_slowpath+0xb4/0x130
> Apr 28 11:36:18 buildvm kernel: [ 363.662022] [<ffffffffaee17d2b>] ? mutex_lock+0x1b/0x30
> Apr 28 11:36:18 buildvm kernel: [ 363.662029] [<ffffffffc03e2ff4>] ? lo_release+0x44/0xa0 [loop]
> Apr 28 11:36:18 buildvm kernel: [ 363.662036] [<ffffffffaea48b2d>] ? __blkdev_put+0x1ed/0x2d0
> Apr 28 11:36:18 buildvm kernel: [ 363.662043] [<ffffffffaea491b1>] ? blkdev_close+0x21/0x30
> Apr 28 11:36:18 buildvm kernel: [ 363.662048] [<ffffffffaea0dc48>] ? __fput+0xd8/0x220
> Apr 28 11:36:18 buildvm kernel: [ 363.662055] [<ffffffffae898d5f>] ? task_work_run+0x7f/0xa0
> Apr 28 11:36:18 buildvm kernel: [ 363.662061] [<ffffffffae803754>] ? exit_to_usermode_loop+0xa4/0xb0
> Apr 28 11:36:18 buildvm kernel: [ 363.662067] [<ffffffffae803bcd>] ? do_syscall_64+0xdd/0xf0
> Apr 28 11:36:18 buildvm kernel: [ 363.662073] [<ffffffffaee1a84e>] ? entry_SYSCALL_64_after_swapgs+0x58/0xc6
>
> The above repeats for all D systemd-udev tasks, and losetup, EG:
>
> Apr 28 11:34:17 buildvm kernel: [ 242.829350] INFO: task losetup:2591 blocked for more than 120 seconds.
> Apr 28 11:34:17 buildvm kernel: [ 242.829715] INFO: task systemd-udevd:2597 blocked for more than 120 seconds.
> Apr 28 11:34:17 buildvm kernel: [ 242.830018] INFO: task systemd-udevd:2602 blocked for more than 120 seconds.
> Apr 28 11:34:17 buildvm kernel: [ 242.830342] INFO: task systemd-udevd:2603 blocked for more than 120 seconds.
> Apr 28 11:34:17 buildvm kernel: [ 242.830679] INFO: task systemd-udevd:2607 blocked for more than 120 seconds.
> Apr 28 11:34:17 buildvm kernel: [ 242.831086] INFO: task systemd-udevd:2609 blocked for more than 120 seconds.
> Apr 28 11:34:17 buildvm kernel: [ 242.831413] INFO: task systemd-udevd:2610 blocked for more than 120 seconds.
> Apr 28 11:34:17 buildvm kernel: [ 242.831744] INFO: task systemd-udevd:2612 blocked for more than 120 seconds.
> Apr 28 11:36:18 buildvm kernel: [ 363.661408] INFO: task losetup:2591 blocked for more than 120 seconds.
> Apr 28 11:36:18 buildvm kernel: [ 363.661776] INFO: task systemd-udevd:2597 blocked for more than 120 seconds.
>
> I tried to strace this, but if I do? It works fine. Further, once I've
> done an strace, further losetups work fine -- without blocking.
>
> Not really sure what's causing this, but without strace and losetup D
> forever, it's annoying to debug. Suggestions welcome.
>
> Note that after the above INFO/hangs, the above systemd-udev and losetup
> tasks sit D forever. It's been 20+ minutes, no activity in kern.log,
> just dead.
>
This looks like a kernel regression.
Do you use a Debian kernel? From which version did you upgrade?
If you downgrade to the previous kernel version, does the problem go away.
--
Why is it that all of the instruments seeking intelligent life in the
universe are pointed away from Earth?
-------------- next part --------------
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 833 bytes
Desc: OpenPGP digital signature
URL: <http://alioth-lists.debian.net/pipermail/pkg-systemd-maintainers/attachments/20190428/5326baf4/attachment-0001.sig>
More information about the Pkg-systemd-maintainers
mailing list