Activity log for bug #1431650

Date Who What changed Old value New value Message
2015-03-13 00:54:58 Mauricio Faria de Oliveira bug added bug
2015-03-16 16:34:54 Breno Leitão bug added subscriber Breno Leitão
2015-03-16 16:49:48 bugproxy tags architecture-ppc64le bugnameltc-122821 severity-critical targetmilestone-inin1504
2015-03-17 18:17:19 Mathieu Trudel-Lapierre multipath-tools (Ubuntu): status New In Progress
2015-03-17 18:17:21 Mathieu Trudel-Lapierre multipath-tools (Ubuntu): importance Undecided Medium
2015-03-17 18:17:24 Mathieu Trudel-Lapierre multipath-tools (Ubuntu): assignee Mathieu Trudel-Lapierre (mathieu-tl)
2015-03-17 18:17:25 Mathieu Trudel-Lapierre multipath-tools (Ubuntu): importance Medium High
2015-03-20 14:44:12 Mauricio Faria de Oliveira attachment added multipath-tools_shared-lock.debdiff https://bugs.launchpad.net/ubuntu/+source/multipath-tools/+bug/1431650/+attachment/4350707/+files/multipath-tools_shared-lock.debdiff
2015-03-20 16:17:51 Ubuntu Foundations Team Bug Bot tags architecture-ppc64le bugnameltc-122821 severity-critical targetmilestone-inin1504 architecture-ppc64le bugnameltc-122821 patch severity-critical targetmilestone-inin1504
2015-03-20 16:18:01 Ubuntu Foundations Team Bug Bot bug added subscriber Ubuntu Sponsors Team
2015-03-23 19:19:30 Launchpad Janitor branch linked lp:ubuntu/vivid-proposed/multipath-tools
2015-03-24 05:10:42 Launchpad Janitor multipath-tools (Ubuntu): status In Progress Fix Released
2015-05-30 17:27:06 Alexandre Anoutchine bug added subscriber Alexandre Anoutchine
2015-07-14 15:36:56 Mathieu Trudel-Lapierre nominated for series Ubuntu Vivid
2015-07-14 15:36:56 Mathieu Trudel-Lapierre bug task added multipath-tools (Ubuntu Vivid)
2015-07-14 15:36:56 Mathieu Trudel-Lapierre nominated for series Ubuntu Trusty
2015-07-14 15:36:56 Mathieu Trudel-Lapierre bug task added multipath-tools (Ubuntu Trusty)
2015-07-14 15:37:05 Mathieu Trudel-Lapierre multipath-tools (Ubuntu Trusty): status New In Progress
2015-07-14 15:37:08 Mathieu Trudel-Lapierre multipath-tools (Ubuntu Vivid): status New In Progress
2015-07-14 15:37:10 Mathieu Trudel-Lapierre multipath-tools (Ubuntu Trusty): assignee Mathieu Trudel-Lapierre (mathieu-tl)
2015-07-14 15:37:11 Mathieu Trudel-Lapierre multipath-tools (Ubuntu Vivid): assignee Mathieu Trudel-Lapierre (mathieu-tl)
2015-07-14 15:37:17 Mathieu Trudel-Lapierre multipath-tools (Ubuntu Trusty): importance Undecided High
2015-07-14 15:37:18 Mathieu Trudel-Lapierre multipath-tools (Ubuntu Vivid): importance Undecided High
2015-07-14 15:43:20 Mathieu Trudel-Lapierre description Problem: during initramfs, multipath devices takes long to initialize (~30 seconds?) Symptom: <...> Loading, please wait... <...> [ 4.492303] device-mapper: multipath: version 1.7.0 loaded [ 4.643053] random: nonblocking pool is initialized worker [116] /devices/vio/71000002/host0/target0:0:0/0:0:0:0/block/sda is taking a long time worker [117] /devices/vio/71000002/host0/target0:0:2/0:0:2:0/block/sdc is taking a long time worker [121] /devices/vio/71000002/host0/target0:0:1/0:0:1:0/block/sdb is taking a long time worker [123] /devices/vio/71000002/host0/target0:0:3/0:0:3:0/block/sdd is taking a long time <... here's the delay ...> timeout '/sbin/multipath -v0 /dev/sda' slow: '/sbin/multipath -v0 /dev/sda' [181] timeout '/sbin/multipath -v0 /dev/sdb' slow: '/sbin/multipath -v0 /dev/sdb' [178] timeout '/sbin/multipath -v0 /dev/sdc' slow: '/sbin/multipath -v0 /dev/sdc' [180] timeout '/sbin/multipath -v0 /dev/sdd' slow: '/sbin/multipath -v0 /dev/sdd' [182] worker [116] /devices/vio/71000002/host0/target0:0:0/0:0:0:0/block/sda timeout; kill it seq 1059 '/devices/vio/71000002/host0/target0:0:0/0:0:0:0/block/sda' killed worker [117] /devices/vio/71000002/host0/target0:0:2/0:0:2:0/block/sdc timeout; kill it seq 1079 '/devices/vio/71000002/host0/target0:0:2/0:0:2:0/block/sdc' killed worker [121] /devices/vio/71000002/host0/target0:0:1/0:0:1:0/block/sdb timeout; kill it seq 1069 '/devices/vio/71000002/host0/target0:0:1/0:0:1:0/block/sdb' killed worker [123] /devices/vio/71000002/host0/target0:0:3/0:0:3:0/block/sdd timeout; kill it seq 1089 '/devices/vio/71000002/host0/target0:0:3/0:0:3:0/block/sdd' killed worker [116] terminated by signal 9 (Killed) worker [117] terminated by signal 9 (Killed) worker [121] terminated by signal 9 (Killed) worker [123] terminated by signal 9 (Killed) <...> <login prompt> Reason: When udev starts to handle the block device, it acquires a lock on it, then processes the rules. Therefore, by the time 'multipath' runs (called in udev rules), the block device is already locked. For 'multipath' to finish, it must acquire a *exclusive* lock on the block device. Thus it fails (exclusive mode doesn't succeed with another lock in place). So it loops, trying again until the lock is acquired. (messages: "failed to create map (in use)" / "restart multipath configuration process"). Sure enough, it will keep looping.. until killed by time-out (message: "timeout '/sbin/multipath -v0 /dev/sda'"). Only then (after rule-processing) udev releases the lock. The next call to the 'multipath' command succeeds (out of udev rules, in /scripts/local-top/multipath). This happens because, by that time, udev has finished handling all devices (i.e., 'udev settle' in /scripts/init-bottom/udev, which is run earlier), so there's no more the udev worker lock to the underlying block device(s). Steps to reproduce: Do a multipath install (disk-detect/multipath/enable=true), and boot. Solution: left as an exercise for the reader :) I guess the udev 95-multipath.rules shouldn't be in the initramfs. (i.e., add_udev_rules() in /usr/share/initramfs-tools/hooks from multipath-tools-boot) Booting on multipath devices would still be possible because there's another call to 'multipath' on initramfs/scripts/local-top/multipath, before mounting root. Not sure about the behavior during system operation; e.g., hotplug a new disk.. the multipath command would be called from the udev rule in the root filesystem now (i.e., /lib/udev/rules.d/ from rootfs, not initramfs). I'm now sure of how multipathd is related to that now. Analysis: Checking out why '/sbin/multipath -v0 /dev/sda' is timing out. Boot with: break=top,pre-multipath,post-multipath <...> Spawning shell within the initramfs <...> (initramfs) Increase verbosity on multipath and udevd, and show udevd And, to save time/output, reduce the udev timeout, and restrict that command to only a single disk (e.g., sda). udevd: (initramfs) grep udevd /scripts/init-top/udev /lib/systemd/systemd-udevd --daemon --resolve-names=never (initramfs) sed '/systemd-udevd/ { s:--daemon:--debug --event-timeout=5: ; s:$: 2>\&1 \&: }' -i /scripts/init-top/udev (initramfs) grep udevd /scripts/init-top/udev /lib/systemd/systemd-udevd --debug --event-timeout=5 --resolve-names=never 2>&1 & multipath: (initramfs) grep -F 'multipath -v' /lib/udev/rules.d/95-multipath.rules ACTION=="add|change", SUBSYSTEM=="block", RUN+="/sbin/multipath -v0 /dev/$name" (initramfs) sed '/multipath -v/ { s:-v0:-v3: ; s:^:KERNEL=="sda", : }' -i /lib/udev/rules.d/95-multipath.rules (initramfs) grep -F 'multipath -v' /lib/udev/rules.d/95-multipath.rules KERNEL=="sda", ACTION=="add|change", SUBSYSTEM=="block", RUN+="/sbin/multipath -v3 /dev/$name" Let initramfs continue: (initramfs) exit The udevd output rolls out. The output of the multipath command is looping. Looking closer, it's always restarting the multipath configuration process. At the end of each iteration (it's looping..), there is this block: '/sbin/multipath -v3 /dev/sda'(out) 'Mar 12 13:44:48 | mpath0: set ACT_CREATE (map does not exist)' '/sbin/multipath -v3 /dev/sda'(out) 'Mar 12 13:44:48 | mpath0: failed to create map (in use)' '/sbin/multipath -v3 /dev/sda'(out) 'Mar 12 13:44:48 | mpath0: domap (4294967295) failure for create/reload map' '/sbin/multipath -v3 /dev/sda'(out) 'Mar 12 13:44:48 | restart multipath configuration process' Searching multipath-tools source package for what causes that error message "failed to create map (in use)". # apt-get source multipath-tools # cd multipath-tools-* # grep -r 'failed to create map (in use)' . ./libmultipath/configure.c: condlog(3, "%s: failed to create map (in use)", And there it is, in domap() (also mentioned in the error): extern int domap (struct multipath * mpp) { ... case ACT_CREATE: if (lock_multipath(mpp, 1)) { condlog(3, "%s: failed to create map (in use)", mpp->alias); return DOMAP_RETRY; } The error thus comes from lock_multipath(), in the same file: static int lock_multipath (struct multipath * mpp, int lock) { ... if (lock && flock(pp->fd, LOCK_EX | LOCK_NB) && errno == EWOULDBLOCK) return 1; So, basically, it's trying to lock a file w/ exclusive access flock(fd, LOCK_EX). To check what file is that, on another system, which is booted already, let's use strace: # strace -f strace.multipath multipath -v0 /dev/sda <...> 26362 open("/dev/sda", O_RDONLY) = 5 <...> 26362 flock(5, LOCK_EX|LOCK_NB) = 0 <...> OK; it tries to lock the same device that is passed as argument. In order to discover the owner of the lock in the initramfs... hm.. there's no lsof or something. Let's use a script to check every process's open files (if a file is locked, it must be open; e.g., flock operates on an open file descriptor). Reboot to that point again, in the initramfs (i.e., break=..., sed ...; NOT exit). break=top,pre-multipath,post-multipath (initramfs) sed '/systemd-udevd/ { s:--daemon:--debug --event-timeout=5: ; s:$: 2>\&1 \&: }' -i /scripts/init-top/udev (initramfs) sed '/multipath -v/ { s:-v0:-v3: ; s:^:KERNEL=="sda", : }' -i /lib/udev/rules.d/95-multipath.rules But now *REPLACE* the multipath command to a script which searches for an open fd for the device specified (expect sda, per the restriction inserted), and list some details of the owning process. note: we replace (not append) just to avoid the flock from multipath, for not to confuse us. (initramfs) sed 's:/sbin/multipath -v. /dev/:/find.sh :' -i /lib/udev/rules.d/95-multipath.rules (initramfs) grep -F 'find.sh' /lib/udev/rules.d/95-multipath.rules KERNEL=="sda", ACTION=="add|change", SUBSYSTEM=="block", RUN+="/find.sh $name" (initramfs) cat <<EOF >/find.sh #!/bin/sh #set -x for dir in /proc/* do [ -d "\$dir/fd" ] || continue ls -l \$dir/fd | grep -q \$1 || continue echo "FD FOUND" echo "process: \$dir" ls -l \$dir/exe echo "cmdline: \$(cat \$dir/cmdline | tr '\0' ' ')" echo "file descriptors:" ls -l \$dir/fd done EOF OK; let's go for udev. (initramfs) exit Lots of udev output.. Searching back for the scripts' output (find.sh).. Tip: use 'screen'. Got it. The lock is from udevd. See fd 6. <...> '/find.sh sda'(out) 'FD FOUND' '/find.sh sda'(out) 'process: /proc/369' '/find.sh sda'(out) 'lrwxrwxrwx 1 0 /proc/369/exe -> /lib/systemd/systemd-udevd' '/find.sh sda'(out) 'cmdline: /lib/systemd/systemd-udevd --debug --event-timeout=5 --resolve-names=never ' '/find.sh sda'(out) 'file descriptors:' '/find.sh sda'(out) 'lr-x------ 1 64 11 -> pipe:[8569]' '/find.sh sda'(out) 'lrwx------ 1 64 10 -> socket:[8352]' '/find.sh sda'(out) 'lrwx------ 1 64 9 -> anon_inode:[eventpoll]' '/find.sh sda'(out) 'lrwx------ 1 64 8 -> socket:[8351]' '/find.sh sda'(out) 'lr-x------ 1 64 7 -> pipe:[8568]' '/find.sh sda'(out) 'lr-x------ 1 64 6 -> /dev/sda' '/find.sh sda'(out) 'lr-x------ 1 64 5 -> anon_inode:inotify' '/find.sh sda'(out) 'lrwx------ 1 64 4 -> anon_inode:[eventpoll]' '/find.sh sda'(out) 'lrwx------ 1 64 3 -> anon_inode:[signalfd]' '/find.sh sda'(out) 'lrwx------ 1 64 2 -> /dev/console' '/find.sh sda'(out) 'lrwx------ 1 64 1 -> /dev/console' '/find.sh sda'(out) 'lr-x------ 1 64 0 -> /dev/null' '/find.sh sda' [422] exit with return code 0 And if you search backwards for that PID, it reaches the fork of a udev worker: seq 873 forked new worker [369] Looking at udevd code for a worker: # apt-get source systemd # cd systemd-* # grep -r worker . hmm.. udevd.c.. ah, "worker_new".. looking. static void worker_new(struct event *event) { <...> fd_lock = open(udev_device_get_devnode(d), O_RDONLY|O_CLOEXEC|O_NOFOLLOW|O_NONBLOCK); if (fd_lock >= 0 && flock(fd_lock, LOCK_SH|LOCK_NB) < 0) { <...> /* apply rules, create node, symlinks */ udev_event_execute_rules(udev_event, <...> safe_close(fd_lock); } And there's a very meaningful comment above it: /* * Take a shared lock on the device node; this establishes * a concept of device "ownership" to serialize device * access. External processes holding an exclusive lock will * cause udev to skip the event handling; in the case udev * acquired the lock, the external process can block until * udev has finished its event handling. */ Specially: in the case udev * acquired the lock, the external process can block until * udev has finished its event handling. AH. So, that explains it all. See: 1) udevd/worker acquires a lock of the block device (shared access), 2) process the udev rules (e.g., 95-multipath.rules) 3) *afterwards*, release the lock. So, the 'multipath' command that is run inside the udev rule that handles the add event of a block device (e.g., sda), will never finish (will keep looping until killed by timeout), because it requires an exclusive lock of that device.. however, that device already has a lock in place (locked by udev worker before rule processing), which will only be released after the rule processing (after multipath ends.) [Impact] Impacts any user of multipath, regardless of release. Users who do not currently see issues may see them on upgrade to a newer version of systemd/udev. [Test case] See below. Test case can be summarized as "boot on a multipath system". [Regression potential] This changes the behavior on locking devices for multipath, to avoid a deadlock with udev. Since this changes the locking behavior of multipath this may also affect other scripts or applications depending on multipath doing an exclusive lock, so scripts or applications could fail because they acquired a lock on the devices prematurely, before multipath was finished. In most cases this shouldn't happen, as it should be limited to an isolated multipath step in the boot process (in initramfs). --- Problem: during initramfs, multipath devices takes long to initialize (~30 seconds?) Symptom:  <...>  Loading, please wait...  <...>  [ 4.492303] device-mapper: multipath: version 1.7.0 loaded  [ 4.643053] random: nonblocking pool is initialized  worker [116] /devices/vio/71000002/host0/target0:0:0/0:0:0:0/block/sda is taking a long time  worker [117] /devices/vio/71000002/host0/target0:0:2/0:0:2:0/block/sdc is taking a long time  worker [121] /devices/vio/71000002/host0/target0:0:1/0:0:1:0/block/sdb is taking a long time  worker [123] /devices/vio/71000002/host0/target0:0:3/0:0:3:0/block/sdd is taking a long time  <... here's the delay ...>  timeout '/sbin/multipath -v0 /dev/sda'  slow: '/sbin/multipath -v0 /dev/sda' [181]  timeout '/sbin/multipath -v0 /dev/sdb'  slow: '/sbin/multipath -v0 /dev/sdb' [178]  timeout '/sbin/multipath -v0 /dev/sdc'  slow: '/sbin/multipath -v0 /dev/sdc' [180]  timeout '/sbin/multipath -v0 /dev/sdd'  slow: '/sbin/multipath -v0 /dev/sdd' [182]  worker [116] /devices/vio/71000002/host0/target0:0:0/0:0:0:0/block/sda timeout; kill it  seq 1059 '/devices/vio/71000002/host0/target0:0:0/0:0:0:0/block/sda' killed  worker [117] /devices/vio/71000002/host0/target0:0:2/0:0:2:0/block/sdc timeout; kill it  seq 1079 '/devices/vio/71000002/host0/target0:0:2/0:0:2:0/block/sdc' killed  worker [121] /devices/vio/71000002/host0/target0:0:1/0:0:1:0/block/sdb timeout; kill it  seq 1069 '/devices/vio/71000002/host0/target0:0:1/0:0:1:0/block/sdb' killed  worker [123] /devices/vio/71000002/host0/target0:0:3/0:0:3:0/block/sdd timeout; kill it  seq 1089 '/devices/vio/71000002/host0/target0:0:3/0:0:3:0/block/sdd' killed  worker [116] terminated by signal 9 (Killed)  worker [117] terminated by signal 9 (Killed)  worker [121] terminated by signal 9 (Killed)  worker [123] terminated by signal 9 (Killed)  <...>  <login prompt> Reason:  When udev starts to handle the block device, it acquires a lock on it, then processes the rules.  Therefore, by the time 'multipath' runs (called in udev rules), the block device is already locked.  For 'multipath' to finish, it must acquire a *exclusive* lock on the block device.  Thus it fails (exclusive mode doesn't succeed with another lock in place).  So it loops, trying again until the lock is acquired.  (messages: "failed to create map (in use)" / "restart multipath configuration process").  Sure enough, it will keep looping.. until killed by time-out (message: "timeout '/sbin/multipath -v0 /dev/sda'").  Only then (after rule-processing) udev releases the lock.  The next call to the 'multipath' command succeeds (out of udev rules, in /scripts/local-top/multipath).  This happens because, by that time, udev has finished handling all devices (i.e., 'udev settle' in /scripts/init-bottom/udev, which is run earlier),  so there's no more the udev worker lock to the underlying block device(s). Steps to reproduce:  Do a multipath install (disk-detect/multipath/enable=true), and boot. Solution:  left as an exercise for the reader :)  I guess the udev 95-multipath.rules shouldn't be in the initramfs.  (i.e., add_udev_rules() in /usr/share/initramfs-tools/hooks from   multipath-tools-boot)  Booting on multipath devices would still be possible because there's  another call to 'multipath' on initramfs/scripts/local-top/multipath,  before mounting root.  Not sure about the behavior during system operation; e.g., hotplug  a new disk.. the multipath command would be called from the udev rule  in the root filesystem now (i.e., /lib/udev/rules.d/ from rootfs, not  initramfs). I'm now sure of how multipathd is related to that now. Analysis:  Checking out why '/sbin/multipath -v0 /dev/sda' is timing out.  Boot with:   break=top,pre-multipath,post-multipath   <...>   Spawning shell within the initramfs   <...>   (initramfs)  Increase verbosity on multipath and udevd, and show udevd  And, to save time/output, reduce the udev timeout, and restrict that command  to only a single disk (e.g., sda).   udevd:   (initramfs) grep udevd /scripts/init-top/udev   /lib/systemd/systemd-udevd --daemon --resolve-names=never   (initramfs) sed '/systemd-udevd/ { s:--daemon:--debug --event-timeout=5: ; s:$: 2>\&1 \&: }' -i /scripts/init-top/udev   (initramfs) grep udevd /scripts/init-top/udev   /lib/systemd/systemd-udevd --debug --event-timeout=5 --resolve-names=never 2>&1 &   multipath:   (initramfs) grep -F 'multipath -v' /lib/udev/rules.d/95-multipath.rules   ACTION=="add|change", SUBSYSTEM=="block", RUN+="/sbin/multipath -v0 /dev/$name"   (initramfs) sed '/multipath -v/ { s:-v0:-v3: ; s:^:KERNEL=="sda", : }' -i /lib/udev/rules.d/95-multipath.rules   (initramfs) grep -F 'multipath -v' /lib/udev/rules.d/95-multipath.rules   KERNEL=="sda", ACTION=="add|change", SUBSYSTEM=="block", RUN+="/sbin/multipath -v3 /dev/$name"  Let initramfs continue:   (initramfs) exit  The udevd output rolls out.  The output of the multipath command is looping. Looking closer, it's always  restarting the multipath configuration process. At the end of each iteration  (it's looping..), there is this block:   '/sbin/multipath -v3 /dev/sda'(out) 'Mar 12 13:44:48 | mpath0: set ACT_CREATE (map does not exist)'   '/sbin/multipath -v3 /dev/sda'(out) 'Mar 12 13:44:48 | mpath0: failed to create map (in use)'   '/sbin/multipath -v3 /dev/sda'(out) 'Mar 12 13:44:48 | mpath0: domap (4294967295) failure for create/reload map'   '/sbin/multipath -v3 /dev/sda'(out) 'Mar 12 13:44:48 | restart multipath configuration process'  Searching multipath-tools source package for what causes that error message "failed to create map (in use)".   # apt-get source multipath-tools   # cd multipath-tools-*   # grep -r 'failed to create map (in use)' .   ./libmultipath/configure.c: condlog(3, "%s: failed to create map (in use)",  And there it is, in domap() (also mentioned in the error):   extern int   domap (struct multipath * mpp)   {   ...    case ACT_CREATE:     if (lock_multipath(mpp, 1)) {             condlog(3, "%s: failed to create map (in use)",                     mpp->alias);             return DOMAP_RETRY;     }  The error thus comes from lock_multipath(), in the same file:   static int   lock_multipath (struct multipath * mpp, int lock)   {   ...             if (lock && flock(pp->fd, LOCK_EX | LOCK_NB) &&                 errno == EWOULDBLOCK)                     return 1;  So, basically, it's trying to lock a file w/ exclusive access flock(fd, LOCK_EX).  To check what file is that, on another system, which is booted already, let's use strace:   # strace -f strace.multipath multipath -v0 /dev/sda   <...>   26362 open("/dev/sda", O_RDONLY) = 5   <...>   26362 flock(5, LOCK_EX|LOCK_NB) = 0   <...>  OK; it tries to lock the same device that is passed as argument.  In order to discover the owner of the lock in the initramfs... hm..  there's no lsof or something.  Let's use a script to check every process's open files  (if a file is locked, it must be open; e.g., flock operates on an open file descriptor).  Reboot to that point again, in the initramfs (i.e., break=..., sed ...; NOT exit).   break=top,pre-multipath,post-multipath   (initramfs) sed '/systemd-udevd/ { s:--daemon:--debug --event-timeout=5: ; s:$: 2>\&1 \&: }' -i /scripts/init-top/udev   (initramfs) sed '/multipath -v/ { s:-v0:-v3: ; s:^:KERNEL=="sda", : }' -i /lib/udev/rules.d/95-multipath.rules  But now *REPLACE* the multipath command to a script which searches for an  open fd for the device specified (expect sda, per the restriction inserted),  and list some details of the owning process.  note: we replace (not append) just to avoid the flock from multipath,        for not to confuse us.   (initramfs) sed 's:/sbin/multipath -v. /dev/:/find.sh :' -i /lib/udev/rules.d/95-multipath.rules   (initramfs) grep -F 'find.sh' /lib/udev/rules.d/95-multipath.rules   KERNEL=="sda", ACTION=="add|change", SUBSYSTEM=="block", RUN+="/find.sh $name"   (initramfs) cat <<EOF >/find.sh   #!/bin/sh   #set -x   for dir in /proc/*   do       [ -d "\$dir/fd" ] || continue       ls -l \$dir/fd | grep -q \$1 || continue       echo "FD FOUND"       echo "process: \$dir"       ls -l \$dir/exe       echo "cmdline: \$(cat \$dir/cmdline | tr '\0' ' ')"       echo "file descriptors:"       ls -l \$dir/fd   done   EOF  OK; let's go for udev.  (initramfs) exit  Lots of udev output..  Searching back for the scripts' output (find.sh).. Tip: use 'screen'.  Got it.  The lock is from udevd.  See fd 6.   <...>   '/find.sh sda'(out) 'FD FOUND'   '/find.sh sda'(out) 'process: /proc/369'   '/find.sh sda'(out) 'lrwxrwxrwx 1 0 /proc/369/exe -> /lib/systemd/systemd-udevd'   '/find.sh sda'(out) 'cmdline: /lib/systemd/systemd-udevd --debug --event-timeout=5 --resolve-names=never '   '/find.sh sda'(out) 'file descriptors:'   '/find.sh sda'(out) 'lr-x------ 1 64 11 -> pipe:[8569]'   '/find.sh sda'(out) 'lrwx------ 1 64 10 -> socket:[8352]'   '/find.sh sda'(out) 'lrwx------ 1 64 9 -> anon_inode:[eventpoll]'   '/find.sh sda'(out) 'lrwx------ 1 64 8 -> socket:[8351]'   '/find.sh sda'(out) 'lr-x------ 1 64 7 -> pipe:[8568]'   '/find.sh sda'(out) 'lr-x------ 1 64 6 -> /dev/sda'   '/find.sh sda'(out) 'lr-x------ 1 64 5 -> anon_inode:inotify'   '/find.sh sda'(out) 'lrwx------ 1 64 4 -> anon_inode:[eventpoll]'   '/find.sh sda'(out) 'lrwx------ 1 64 3 -> anon_inode:[signalfd]'   '/find.sh sda'(out) 'lrwx------ 1 64 2 -> /dev/console'   '/find.sh sda'(out) 'lrwx------ 1 64 1 -> /dev/console'   '/find.sh sda'(out) 'lr-x------ 1 64 0 -> /dev/null'   '/find.sh sda' [422] exit with return code 0  And if you search backwards for that PID, it reaches the fork of a udev worker:   seq 873 forked new worker [369]  Looking at udevd code for a worker:   # apt-get source systemd   # cd systemd-*   # grep -r worker .     hmm.. udevd.c.. ah, "worker_new".. looking.   static void worker_new(struct event *event) {    <...>     fd_lock = open(udev_device_get_devnode(d), O_RDONLY|O_CLOEXEC|O_NOFOLLOW|O_NONBLOCK);     if (fd_lock >= 0 && flock(fd_lock, LOCK_SH|LOCK_NB) < 0) {    <...>            /* apply rules, create node, symlinks */            udev_event_execute_rules(udev_event,    <...>            safe_close(fd_lock);   }  And there's a very meaningful comment above it:                 /*                  * Take a shared lock on the device node; this establishes                  * a concept of device "ownership" to serialize device                  * access. External processes holding an exclusive lock will                  * cause udev to skip the event handling; in the case udev                  * acquired the lock, the external process can block until                  * udev has finished its event handling.                  */  Specially:   in the case udev                  * acquired the lock, the external process can block until                  * udev has finished its event handling.  AH.  So, that explains it all.  See:  1) udevd/worker acquires a lock of the block device (shared access),  2) process the udev rules (e.g., 95-multipath.rules)  3) *afterwards*, release the lock.  So, the 'multipath' command that is run inside the udev rule  that handles the add event of a block device (e.g., sda),  will never finish (will keep looping until killed by timeout),  because it requires an exclusive lock of that device..  however, that device already has a lock in place (locked by  udev worker before rule processing), which will only be  released after the rule processing (after multipath ends.)
2015-07-14 15:46:18 Mathieu Trudel-Lapierre bug task deleted multipath-tools (Ubuntu Vivid)
2015-07-15 19:28:13 Chris J Arges multipath-tools (Ubuntu Trusty): status In Progress Fix Committed
2015-07-15 19:28:14 Chris J Arges bug added subscriber Ubuntu Stable Release Updates Team
2015-07-15 19:28:16 Chris J Arges bug added subscriber SRU Verification
2015-07-15 19:28:23 Chris J Arges tags architecture-ppc64le bugnameltc-122821 patch severity-critical targetmilestone-inin1504 architecture-ppc64le bugnameltc-122821 patch severity-critical targetmilestone-inin1504 verification-needed
2015-07-24 20:28:21 Launchpad Janitor branch linked lp:~mathieu-tl/ubuntu/trusty/multipath-tools/usb+local
2015-07-27 18:05:46 Adam Conrad removed subscriber Ubuntu Sponsors Team
2015-07-27 21:30:30 Mauricio Faria de Oliveira tags architecture-ppc64le bugnameltc-122821 patch severity-critical targetmilestone-inin1504 verification-needed architecture-ppc64le bugnameltc-122821 patch severity-critical targetmilestone-inin1504 verification-done
2015-07-28 17:41:40 Launchpad Janitor multipath-tools (Ubuntu Trusty): status Fix Committed Fix Released
2015-07-28 17:41:51 Steve Langasek removed subscriber Ubuntu Stable Release Updates Team