Bug 1084944 - Events based on WATCH udev rule cause the udev db to be out of sync with real state if inotify events are coalesced
Summary: Events based on WATCH udev rule cause the udev db to be out of sync with real...
Keywords:
Status: CLOSED WORKSFORME
Alias: None
Product: Fedora
Classification: Fedora
Component: systemd
Version: 20
Hardware: Unspecified
OS: Unspecified
unspecified
unspecified
Target Milestone: ---
Assignee: systemd-maint
QA Contact: Fedora Extras Quality Assurance
URL:
Whiteboard:
: 1066525 (view as bug list)
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2014-04-07 11:04 UTC by Marius Vollmer
Modified: 2014-06-23 08:54 UTC (History)
20 users (show)

Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Clone Of:
Environment:
Last Closed: 2014-06-23 08:54:42 UTC
Type: Bug
Embargoed:


Attachments (Terms of Use)

Description Marius Vollmer 2014-04-07 11:04:32 UTC
Description of problem:

After wipe/pvscan/vgcreate, udevadm info reports wrong things.

Version-Release number of selected component (if applicable):

lvm2-2.02.103-5.fc20.x86_64

How reproducible:

every time.

Steps to Reproduce:
# wipefs -a /dev/vdb
/dev/vdb: 8 bytes were erased at offset 0x00000218 (LVM2_member): 4c 56 4d 32 20 30 30 31
# pvscan --cache /dev/vdb
  No PV label found on /dev/vdb.
# vgcreate demo /dev/vdb
  No physical volume found in lvmetad cache for /dev/vdb
  Physical volume /dev/vdb not found
  Physical volume "/dev/vdb" successfully created
  Volume group "demo" successfully created
# udevadm info /dev/vdb

Actual results:

P: /devices/pci0000:00/0000:00:0f.0/virtio5/block/vdb
N: vdb
E: DEVNAME=/dev/vdb
E: DEVPATH=/devices/pci0000:00/0000:00:0f.0/virtio5/block/vdb
E: DEVTYPE=disk
E: MAJOR=252
E: MINOR=16
E: SUBSYSTEM=block
E: TAGS=:systemd:
E: USEC_INITIALIZED=1745830

Expected results:

P: /devices/pci0000:00/0000:00:0f.0/virtio5/block/vdb
N: vdb
E: DEVNAME=/dev/vdb
E: DEVPATH=/devices/pci0000:00/0000:00:0f.0/virtio5/block/vdb
E: DEVTYPE=disk
E: ID_FS_TYPE=LVM2_member
E: ID_FS_USAGE=raid
E: ID_FS_UUID=9N5dcZ-yBy9-A4n3-Fs6R-PE8y-31jh-0D4zYK
E: ID_FS_UUID_ENC=9N5dcZ-yBy9-A4n3-Fs6R-PE8y-31jh-0D4zYK
E: ID_FS_VERSION=LVM2 001
E: MAJOR=252
E: MINOR=16
E: SUBSYSTEM=block
E: TAGS=:systemd:
E: USEC_INITIALIZED=1745830

Additional info:

Executing "udevadm trigger" results in correct udev attributes, so the label on the device is correct.

The vgcreate command above results in exactly these events:

# udevadm monitor --property
monitor will print the received events for:
UDEV - the event which udev sends out after rule processing
KERNEL - the kernel uevent

KERNEL[2148.788075] change   /devices/pci0000:00/0000:00:10.0/virtio5/block/vdb (block)
ACTION=change
DEVNAME=/dev/vdb
DEVPATH=/devices/pci0000:00/0000:00:10.0/virtio5/block/vdb
DEVTYPE=disk
MAJOR=252
MINOR=16
SEQNUM=2332
SUBSYSTEM=block

UDEV  [2148.795023] change   /devices/pci0000:00/0000:00:10.0/virtio5/block/vdb (block)
ACTION=change
DEVNAME=/dev/vdb
DEVPATH=/devices/pci0000:00/0000:00:10.0/virtio5/block/vdb
DEVTYPE=disk
MAJOR=252
MINOR=16
SEQNUM=2332
SUBSYSTEM=block
TAGS=:systemd:
USEC_INITIALIZED=503100

Comment 1 Peter Rajnoha 2014-04-07 12:06:01 UTC
When running the vgcreate step-by-step in debugger, there are actually 4 events generated. When running it on cmd line as usual, there's only 1 event seen which is the result of udev coalescing these events if they happen too close each other in time. Unfortunately, the state in udev db does not reflect the final state.

So this is actually a dup of bug #1066525 (rawhide). I'll keep this one open for F20. Changing to systemd/udev component.

Comment 2 Marius Vollmer 2014-04-07 12:34:09 UTC
(In reply to Peter Rajnoha from comment #1)
> When running the vgcreate step-by-step in debugger, there are actually 4
> events generated. When running it on cmd line as usual, there's only 1 event
> seen which is the result of udev coalescing these events if they happen too
> close each other in time. Unfortunately, the state in udev db does not
> reflect the final state.

*groan*

So udev ignores some events that happen shortly after another event?  That would mean that the obvious workaround of artificially triggering an event after vgcreate doesn't work.

Comment 3 Peter Rajnoha 2014-04-07 13:31:42 UTC
(In reply to Marius Vollmer from comment #2)
> (In reply to Peter Rajnoha from comment #1)
> > When running the vgcreate step-by-step in debugger, there are actually 4
> > events generated. When running it on cmd line as usual, there's only 1 event
> > seen which is the result of udev coalescing these events if they happen too
> > close each other in time. Unfortunately, the state in udev db does not
> > reflect the final state.
> 
> *groan*
> 
> So udev ignores some events that happen shortly after another event?  That
> would mean that the obvious workaround of artificially triggering an event
> after vgcreate doesn't work.

This might be only related to the way how inotify events (the "WATCH" rule) are processedd so probably the trigger is not affected here. There's a note in "man 7 inotify":

  "If successive output inotify events produced on the inotify file descriptor  are  identical  (same  wd,  mask, cookie,  and  name)  then they are coalesced into a single event if the older event has not yet been read (but see BUGS).

BUGS
       In kernels before 2.6.16, the IN_ONESHOT mask flag does not work.

       Before kernel 2.6.25, the kernel code that was intended to coalesce successive identical events (i.e., the two
       most recent events could potentially be coalesced if the older had not yet been read) instead checked  if  the
       most recent event could be coalesced with the oldest unread event."

So someone from udev team should check this and then probably redirect it to kernel if it appears to be a kernel bug. I can't evaluate this properly since I don't see into udev code much...

Comment 4 Lennart Poettering 2014-06-17 00:52:09 UTC
*** Bug 1066525 has been marked as a duplicate of this bug. ***

Comment 5 Kay Sievers 2014-06-20 13:00:27 UTC
I cannot reproduce this, it works just fine on a real disk.

I have no idea about the virtio stuff. Please try if this also
fails for you with other devices than virtio.

$ udevadm monitor -u &

$ vgcreate demo /dev/sdd
UDEV  [2371.079259] change   [...]/block/sdd (block)
  Physical volume "/dev/sdd" successfully created
  Volume group "demo" successfully created

$ udevadm info /dev/sdd
[...]
E: ID_FS_USAGE=raid
E: ID_FS_UUID=9QRiym-RB2e-RNDt-9qUc-9cGP-fqOH-kkWb5O
E: ID_FS_UUID_ENC=9QRiym-RB2e-RNDt-9qUc-9cGP-fqOH-kkWb5O
E: ID_FS_VERSION=LVM2 001
[...]

Comment 6 Marius Vollmer 2014-06-23 08:54:42 UTC
(In reply to Kay Sievers from comment #5)
> I cannot reproduce this, it works just fine on a real disk.

I can't reproduce it anymore either.  Time heals all wounds. :-) Thanks for checking!


Note You need to log in before you can comment on or make changes to this bug.