[systemd-bugs] [Bug 79576] New: udevd flock() failure on disk partitions due to fsck holding WRITE FLOCK

Tue Jun 3 00:59:09 PDT 2014

https://bugs.freedesktop.org/show_bug.cgi?id=79576

          Priority: medium
            Bug ID: 79576
          Assignee: systemd-bugs at lists.freedesktop.org
           Summary: udevd flock() failure on disk partitions due to fsck
                    holding WRITE FLOCK
        QA Contact: systemd-bugs at lists.freedesktop.org
          Severity: critical
    Classification: Unclassified
                OS: Linux (All)
          Reporter: jpsinthemix at verizon.net
          Hardware: x86 (IA32)
            Status: NEW
           Version: unspecified
         Component: general
           Product: systemd

Created attachment 100341
  --> https://bugs.freedesktop.org/attachment.cgi?id=100341&action=edit
uded.c:worker_new() flock() attempts debug

Hi,

On upgrading from systemd-212 to systemd-213, my development system once again
(see BR#75512) no longer is able to reliably mount non-root disk partitions
listed in /etc/fstab at boot time. I say 'reliably' here as it is able to do
sometimes, but mosty not.

On this system, I'm using MBR (not GPT) disk partitions, and not using lvm.

My grub2 boot kernel line is:
  linux   /boot/vmlinuz-3.14.5 root=/dev/sda7 ro raid=noautodetect quiet

At boot, I get the messages like
systemd-fsck[62]: /sbin/fsck.xfs: XFS file system.
[ * ] (1 of 4) A start job is running for dev-sda10.device. (1min 26s / 1min
30s)

The root partition is fine, but no other sdaX partitions appear.

In appearence, this issue results in the same behavior as described in
BR#75512, however, note that the kernel has been built with CONFIG_FHANDLE=y
here.

I have traced this to systemd-213/src/udev/udevd.c:worker_new(), where among
other things, the following code is new w.r.t sytemd-212,

 285                         /*
 286                          * Take a "read lock" on the device node; this
establishes
 287                          * a concept of device "ownership" to serialize
device
 288                          * access. External processes holding a "write
lock" will
 289                          * cause udev to skip the event handling; in the
case udev
 290                          * acquired the lock, the external process will
block until
 291                          * udev has finished its event handling.
 292                          */
 293                         if (streq_ptr("block",
udev_device_get_subsystem(dev))) {
 294                                 struct udev_device *d = dev;
 295
 296                                 if (streq_ptr("partition",
udev_device_get_devtype(d)))
 297                                         d = udev_device_get_parent(d);
 298
 299                                 if (d) {
 300                                         fd_lock =
open(udev_device_get_devnode(d), O_RDONLY|O_CLOEXEC|O_NOFOLLOW|O_NONBLOCK);
 301                                         if (fd_lock >= 0 && flock(fd_lock,
LOCK_SH|LOCK_NB) < 0) {
 302                                                 log_debug("Unable to
flock(%s), skipping event handling: %m", udev_device_get_de     vnode(d));
 303                                                 err = -EWOULDBLOCK;
 304                                                 goto skip;
 305                                         }
 306                                 }
 307                         }
 308

On reaching line 293 in worker_new(), for all incoming /dev/sda{,X} devices an
attempt to flock()  device /dev/sda is made (lines 296-7 => the lock is always
attempted on /dev/sda in these cases).

What is happenning is that an fsck process (see attachment) has already placed
a WRITE FLOCK on  /dev/sda, and so udev processing is skipped. When the problem
occurs, the result is that no udev processing is done for /dev/sda or any
/dev/sdaX partitions.

I've attached a log of events with occur when the flock()'s fail (generated by
simply adding some debug code between lines 302 and 303 (I simply print
/proc/locks and from that get and print the pid/command(s) which hold FLOCKs).
>From this log it appears that fsck is holding a WRITE FLOCK before the first
entry into worker_new(). Apparently, this WRITE FLOCK is held long enough so
that
udevd skips all /dev/sda{.X} processing (and I speculate that fsck is then
unable to complete its work as well). Looks like a file lock deadlock between
fsck and udevd ?

As noted above, the problem doesn't always occur; it occurs much more
frequently on a simple sparsely populated system (9/10 times), than on a full
desktop system (1/10 times).

Also, if I add 
     systemd.log_level=debug systemd.log_target=kmsg log_buf_len=1M
to the grub boot commandline, it rarely occurs, and even the addition of
debugging code dramatically alters the frequency of occurrence.

In passing also note that it appears that the file close of fd_lock is not done
if the 'goto skip' path is taken in the udevd.c code above.

As a temporary work-around, I'm now using sytemd-213 without issue, with lines
285-308 (plus several other associated lines) removed (thes lines are, of
course, absent in sytemd-212).

I do not know enough about systemd and the kernel to move much further on this,
so any help would be greatly appreciated.

thanks much,
John

-- 
You are receiving this mail because:
You are the QA Contact for the bug.
You are the assignee for the bug.
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.freedesktop.org/archives/systemd-bugs/attachments/20140603/503339db/attachment-0001.html>