Created attachment 864599 [details]
reproducer

There's a problem with processing the events based on WATCH udev rule. A simple sequence can make the udev db records out of sync when compared to real state. This is probably a consequence of inotify events coalescence if there are more inotify events at once in a short time for the same element being watched.

This is reproducible with following sequence (check the ID_FS_TYPE variable):
  echo 1 > /dev/sda
  mkswap /dev/sda




The initial state of /dev/sda is:

[0] raw/~ # dd if=/dev/zero of=/dev/sda bs=1M
dd: error writing '/dev/sda': No space left on device
129+0 records in
128+0 records out
134217728 bytes (134 MB) copied, 0.50778 s, 264 MB/s

[0] raw/~ # udevadm info --name=/dev/sda
P: /devices/pci0000:00/0000:00:08.0/host2/target2:0:0/2:0:0:0/block/sda
N: sda
S: disk/by-id/scsi-0QEMU_QEMU_HARDDISK_drive-scsi1-0-0
S: disk/by-path/pci-0000:00:08.0-scsi-0:0:0:0
E: DEVLINKS=/dev/disk/by-id/scsi-0QEMU_QEMU_HARDDISK_drive-scsi1-0-0 /dev/disk/by-path/pci-0000:00:08.0-scsi-0:0:0:0
E: DEVNAME=/dev/sda
E: DEVPATH=/devices/pci0000:00/0000:00:08.0/host2/target2:0:0/2:0:0:0/block/sda
E: DEVTYPE=disk
E: ID_BUS=scsi
E: ID_MODEL=QEMU_HARDDISK
E: ID_MODEL_ENC=QEMU\x20HARDDISK\x20\x20\x20
E: ID_PATH=pci-0000:00:08.0-scsi-0:0:0:0
E: ID_PATH_TAG=pci-0000_00_08_0-scsi-0_0_0_0
E: ID_REVISION=1.6.
E: ID_SCSI=1
E: ID_SERIAL=0QEMU_QEMU_HARDDISK_drive-scsi1-0-0
E: ID_SERIAL_SHORT=drive-scsi1-0-0
E: ID_TYPE=disk
E: ID_VENDOR=QEMU
E: ID_VENDOR_ENC=QEMU\x20\x20\x20\x20
E: MAJOR=8
E: MINOR=0
E: MPATH_SBIN_PATH=/sbin
E: SUBSYSTEM=block
E: TAGS=:systemd:
E: UDISKS_PRESENTATION_NOPOLICY=0
E: USEC_INITIALIZED=31620

[0] raw/~ # blkid -c /dev/null -o udev /dev/sda
  (blank)



When we run the command echo and mkswap command sequence with a delay in between the commands (...e.g. by running this manually on command line with a delay in between), we end up with these events generated (based on the WATCH udev rule - both echo and mkswap command write to the /dev/sda, hence opening it in RW mode and closing it which fires the inotify event - the WATCH rule):

[0] raw/~ # udevadm monitor --udev --property
monitor will print the received events for:
UDEV - the event which udev sends out after rule processing

UDEV  [1826.395270] change   /devices/pci0000:00/0000:00:08.0/host2/target2:0:0/2:0:0:0/block/sda (block)
ACTION=change
DEVLINKS=/dev/disk/by-id/scsi-0QEMU_QEMU_HARDDISK_drive-scsi1-0-0 /dev/disk/by-path/pci-0000:00:08.0-scsi-0:0:0:0
DEVNAME=/dev/sda
DEVPATH=/devices/pci0000:00/0000:00:08.0/host2/target2:0:0/2:0:0:0/block/sda
DEVTYPE=disk
ID_BUS=scsi
ID_MODEL=QEMU_HARDDISK
ID_MODEL_ENC=QEMU\x20HARDDISK\x20\x20\x20
ID_PATH=pci-0000:00:08.0-scsi-0:0:0:0
ID_PATH_TAG=pci-0000_00_08_0-scsi-0_0_0_0
ID_REVISION=1.6.
ID_SCSI=1
ID_SERIAL=0QEMU_QEMU_HARDDISK_drive-scsi1-0-0
ID_SERIAL_SHORT=drive-scsi1-0-0
ID_TYPE=disk
ID_VENDOR=QEMU
ID_VENDOR_ENC=QEMU\x20\x20\x20\x20
MAJOR=8
MINOR=0
MPATH_SBIN_PATH=/sbin
SEQNUM=2013
SUBSYSTEM=block
TAGS=:systemd:
UDISKS_PRESENTATION_NOPOLICY=0
USEC_INITIALIZED=620

UDEV  [1830.287914] change   /devices/pci0000:00/0000:00:08.0/host2/target2:0:0/2:0:0:0/block/sda (block)
ACTION=change
DEVLINKS=/dev/disk/by-id/scsi-0QEMU_QEMU_HARDDISK_drive-scsi1-0-0 /dev/disk/by-path/pci-0000:00:08.0-scsi-0:0:0:0 /dev/disk/by-uuid/3d3bd5bb-aa4f-46ca-9615-437f12718e7a
DEVNAME=/dev/sda
DEVPATH=/devices/pci0000:00/0000:00:08.0/host2/target2:0:0/2:0:0:0/block/sda
DEVTYPE=disk
ID_BUS=scsi
ID_FS_TYPE=swap
ID_FS_USAGE=other
ID_FS_UUID=3d3bd5bb-aa4f-46ca-9615-437f12718e7a
ID_FS_UUID_ENC=3d3bd5bb-aa4f-46ca-9615-437f12718e7a
ID_FS_VERSION=1
ID_MODEL=QEMU_HARDDISK
ID_MODEL_ENC=QEMU\x20HARDDISK\x20\x20\x20
ID_PATH=pci-0000:00:08.0-scsi-0:0:0:0
ID_PATH_TAG=pci-0000_00_08_0-scsi-0_0_0_0
ID_REVISION=1.6.
ID_SCSI=1
ID_SERIAL=0QEMU_QEMU_HARDDISK_drive-scsi1-0-0
ID_SERIAL_SHORT=drive-scsi1-0-0
ID_TYPE=disk
ID_VENDOR=QEMU
ID_VENDOR_ENC=QEMU\x20\x20\x20\x20
MAJOR=8
MINOR=0
MPATH_SBIN_PATH=/sbin
SEQNUM=2014
SUBSYSTEM=block
TAGS=:systemd:
UDISKS_PRESENTATION_NOPOLICY=0
USEC_INITIALIZED=620

[0] raw/~ # udevadm info --name=/dev/sda
P: /devices/pci0000:00/0000:00:08.0/host2/target2:0:0/2:0:0:0/block/sda
N: sda
S: disk/by-id/scsi-0QEMU_QEMU_HARDDISK_drive-scsi1-0-0
S: disk/by-path/pci-0000:00:08.0-scsi-0:0:0:0
S: disk/by-uuid/3d3bd5bb-aa4f-46ca-9615-437f12718e7a
E: DEVLINKS=/dev/disk/by-id/scsi-0QEMU_QEMU_HARDDISK_drive-scsi1-0-0 /dev/disk/by-path/pci-0000:00:08.0-scsi-0:0:0:0 /dev/disk/by-uuid/3d3bd5bb-aa4f-46ca-9615-437f12718e7a
E: DEVNAME=/dev/sda
E: DEVPATH=/devices/pci0000:00/0000:00:08.0/host2/target2:0:0/2:0:0:0/block/sda
E: DEVTYPE=disk
E: ID_BUS=scsi
E: ID_FS_TYPE=swap
E: ID_FS_USAGE=other
E: ID_FS_UUID=3d3bd5bb-aa4f-46ca-9615-437f12718e7a
E: ID_FS_UUID_ENC=3d3bd5bb-aa4f-46ca-9615-437f12718e7a
E: ID_FS_VERSION=1
E: ID_MODEL=QEMU_HARDDISK
E: ID_MODEL_ENC=QEMU\x20HARDDISK\x20\x20\x20
E: ID_PATH=pci-0000:00:08.0-scsi-0:0:0:0
E: ID_PATH_TAG=pci-0000_00_08_0-scsi-0_0_0_0
E: ID_REVISION=1.6.
E: ID_SCSI=1
E: ID_SERIAL=0QEMU_QEMU_HARDDISK_drive-scsi1-0-0
E: ID_SERIAL_SHORT=drive-scsi1-0-0
E: ID_TYPE=disk
E: ID_VENDOR=QEMU
E: ID_VENDOR_ENC=QEMU\x20\x20\x20\x20
E: MAJOR=8
E: MINOR=0
E: MPATH_SBIN_PATH=/sbin
E: SUBSYSTEM=block
E: TAGS=:systemd:
E: UDISKS_PRESENTATION_NOPOLICY=0
E: USEC_INITIALIZED=31620

[0] raw/~ # blkid -c /dev/null -o udev /dev/sda
ID_FS_UUID=3d3bd5bb-aa4f-46ca-9615-437f12718e7a
ID_FS_UUID_ENC=3d3bd5bb-aa4f-46ca-9615-437f12718e7a
ID_FS_TYPE=swap

So we end up with ID_FS_TYPE=swap in both udev db and in real.



(INITIALIZE THE DEV AGAIN - e.g. dd if=/dev/zero of=/dev/sda so we have a raw disk again without anything written in it)



Now the same sequence, but running from the script so the delay in between the echo and mkswap commands is minimal:

[1] raw/~ # ./test.sh 
Setting up swapspace version 1, size = 131068 KiB
no label, UUID=047fa81c-9821-4687-8ef7-f143d0065b46

[0] raw/~ # udevadm monitor --udev --property
monitor will print the received events for:
UDEV - the event which udev sends out after rule processing

UDEV  [2135.612564] change   /devices/pci0000:00/0000:00:08.0/host2/target2:0:0/2:0:0:0/block/sda (block)
ACTION=change
DEVLINKS=/dev/disk/by-id/scsi-0QEMU_QEMU_HARDDISK_drive-scsi1-0-0 /dev/disk/by-path/pci-0000:00:08.0-scsi-0:0:0:0
DEVNAME=/dev/sda
DEVPATH=/devices/pci0000:00/0000:00:08.0/host2/target2:0:0/2:0:0:0/block/sda
DEVTYPE=disk
ID_BUS=scsi
ID_MODEL=QEMU_HARDDISK
ID_MODEL_ENC=QEMU\x20HARDDISK\x20\x20\x20
ID_PATH=pci-0000:00:08.0-scsi-0:0:0:0
ID_PATH_TAG=pci-0000_00_08_0-scsi-0_0_0_0
ID_REVISION=1.6.
ID_SCSI=1
ID_SERIAL=0QEMU_QEMU_HARDDISK_drive-scsi1-0-0
ID_SERIAL_SHORT=drive-scsi1-0-0
ID_TYPE=disk
ID_VENDOR=QEMU
ID_VENDOR_ENC=QEMU\x20\x20\x20\x20
MAJOR=8
MINOR=0
MPATH_SBIN_PATH=/sbin
SEQNUM=2016
SUBSYSTEM=block
TAGS=:systemd:
UDISKS_PRESENTATION_NOPOLICY=0
USEC_INITIALIZED=620

There's only one event that is probably a consequence of inotify event coalescence. But see that the ID_FS_TYPE=swap is missing - the swap signature has not been detected yet! (...as it has not yet been written by mkswap)

And we end up with the udev db out of sync when compared to real state:

[0] raw/~ # udevadm info --name=/dev/sda
P: /devices/pci0000:00/0000:00:08.0/host2/target2:0:0/2:0:0:0/block/sda
N: sda
S: disk/by-id/scsi-0QEMU_QEMU_HARDDISK_drive-scsi1-0-0
S: disk/by-path/pci-0000:00:08.0-scsi-0:0:0:0
E: DEVLINKS=/dev/disk/by-id/scsi-0QEMU_QEMU_HARDDISK_drive-scsi1-0-0 /dev/disk/by-path/pci-0000:00:08.0-scsi-0:0:0:0
E: DEVNAME=/dev/sda
E: DEVPATH=/devices/pci0000:00/0000:00:08.0/host2/target2:0:0/2:0:0:0/block/sda
E: DEVTYPE=disk
E: ID_BUS=scsi
E: ID_MODEL=QEMU_HARDDISK
E: ID_MODEL_ENC=QEMU\x20HARDDISK\x20\x20\x20
E: ID_PATH=pci-0000:00:08.0-scsi-0:0:0:0
E: ID_PATH_TAG=pci-0000_00_08_0-scsi-0_0_0_0
E: ID_REVISION=1.6.
E: ID_SCSI=1
E: ID_SERIAL=0QEMU_QEMU_HARDDISK_drive-scsi1-0-0
E: ID_SERIAL_SHORT=drive-scsi1-0-0
E: ID_TYPE=disk
E: ID_VENDOR=QEMU
E: ID_VENDOR_ENC=QEMU\x20\x20\x20\x20
E: MAJOR=8
E: MINOR=0
E: MPATH_SBIN_PATH=/sbin
E: SUBSYSTEM=block
E: TAGS=:systemd:
E: UDISKS_PRESENTATION_NOPOLICY=0
E: USEC_INITIALIZED=31620

[0] raw/~ # blkid -c /dev/null -o udev /dev/sda
ID_FS_UUID=047fa81c-9821-4687-8ef7-f143d0065b46
ID_FS_UUID_ENC=047fa81c-9821-4687-8ef7-f143d0065b46
ID_FS_TYPE=swap


It seems we're losing events!

[0] raw/~ # rpm -q kernel
kernel-3.14.0-0.rc2.git4.1.fc21.x86_64

[0] raw/~ # rpm -q systemd
systemd-208-12.fc21.x86_64