From mboxrd@z Thu Jan  1 00:00:00 1970
From: Jim Paris <jim@jtan.com>
Date: Sun, 22 Apr 2012 04:36:55 +0000
Subject: udev missing events?
Message-Id: <20120422043655.GA27861@psychosis.jim.sh>
List-Id: <linux-hotplug.vger.kernel.org>
MIME-Version: 1.0
Content-Type: text/plain; charset="iso-8859-1"
Content-Transfer-Encoding: quoted-printable
To: linux-hotplug@vger.kernel.org, linux-kernel@vger.kernel.org
Cc: "Eric W. Biederman" <ebiederm@xmission.com>, Milan Broz <mbroz@redhat.com>

(cc'd Eric and Milan because 5f71a296 and ebf4127c might be related)

I'm trying to track down a problem that started with virt-manager not
being able to connect to libvirtd.  Long story short, the problem is
that "udevadm settle" is timing out, with no events in the udev queue.

(I know it's bad for libvirt to rely on "udevadm settle", but it seems
that this is exposing some other problem).

This is with 3.2.14 from Debian.

I can trigger the problem easily by just starting libvirtd and killing
it.  Then, the counters are stuck here:

  # cat /sys/kernel/uevent_seqnum
  13593
  # od -t d2 /dev/.udev/queue.bin | head -1
  0000000  13592

During the libvirtd startup, I ran "udevadm monitor", which seems to
indicate that 13593 never made it to udev:

 # udevadm monitor --kernel --property
  monitor will print the received events for:
  KERNEL - the kernel uevent
 =20
  KERNEL[537903.765581] add      /devices/virtual/net/lo/queues/rx-0 (queue=
s)
  ACTION=ADd
  DEVPATH=3D/devices/virtual/net/lo/queues/rx-0
  SEQNUM=13589
  SUBSYSTEM=3Dqueues
  UDEV_LOG=3D3
 =20
  KERNEL[537903.765683] add      /devices/virtual/net/lo/queues/tx-0 (queue=
s)
  ACTION=ADd
  DEVPATH=3D/devices/virtual/net/lo/queues/tx-0
  SEQNUM=13590
  SUBSYSTEM=3Dqueues
  UDEV_LOG=3D3
 =20
  KERNEL[537903.844154] remove   /devices/virtual/net/lo/queues/rx-0 (queue=
s)
  ACTION=3Dremove
  DEVPATH=3D/devices/virtual/net/lo/queues/rx-0
  SEQNUM=13591
  SUBSYSTEM=3Dqueues
  UDEV_LOG=3D3
 =20
  KERNEL[537903.844192] remove   /devices/virtual/net/lo/queues/tx-0 (queue=
s)
  ACTION=3Dremove
  DEVPATH=3D/devices/virtual/net/lo/queues/tx-0
  SEQNUM=13592
  SUBSYSTEM=3Dqueues
  UDEV_LOG=3D3

To try to track it further, I wrote a systemtap script (available at
http://jim.sh/~jim/tmp/monitor.stp).  It dumps the result of
netlink_broadcast_filtered at lib/kobject_uevent.c:248, and then dumps
the uevent_seqnum and environment at the end of the same function.
It seems to show that netlink_broadcast_filter is failing to send out
the event, with -ESRCH:

  $ sudo ./monitor.stp=20
  begin
  -----
  netlink_broadcast_filtered: -3 (ESRCH)
  netlink_broadcast_filtered: -3 (ESRCH)
  event was:
    uevent_seqnum: 13588
    "ACTION=ADd"
    "DEVPATH=3D/devices/virtual/net/lo"
    "SUBSYSTEM=3Dnet"
    "INTERFACE=3Dlo"
    "IFINDEXh"
    "SEQNUM=13588"
  -----
  netlink_broadcast_filtered: 0x0
  netlink_broadcast_filtered: -3 (ESRCH)
  event was:
    uevent_seqnum: 13589
    "ACTION=ADd"
    "DEVPATH=3D/devices/virtual/net/lo/queues/rx-0"
    "SUBSYSTEM=3Dqueues"
    "SEQNUM=13589"
  -----
  netlink_broadcast_filtered: 0x0
  netlink_broadcast_filtered: -3 (ESRCH)
  event was:
    uevent_seqnum: 13590
    "ACTION=ADd"
    "DEVPATH=3D/devices/virtual/net/lo/queues/tx-0"
    "SUBSYSTEM=3Dqueues"
    "SEQNUM=13590"
  -----
  netlink_broadcast_filtered: 0x0
  netlink_broadcast_filtered: -3 (ESRCH)
  event was:
    uevent_seqnum: 13591
    "ACTION=3Dremove"
    "DEVPATH=3D/devices/virtual/net/lo/queues/rx-0"
    "SUBSYSTEM=3Dqueues"
    "SEQNUM=13591"
  -----
  netlink_broadcast_filtered: 0x0
  netlink_broadcast_filtered: -3 (ESRCH)
  event was:
    uevent_seqnum: 13592
    "ACTION=3Dremove"
    "DEVPATH=3D/devices/virtual/net/lo/queues/tx-0"
    "SUBSYSTEM=3Dqueues"
    "SEQNUM=13592"
  -----
  netlink_broadcast_filtered: -3 (ESRCH)
  netlink_broadcast_filtered: -3 (ESRCH)
  event was:
    uevent_seqnum: 13593
    "ACTION=3Dremove"
    "DEVPATH=3D/devices/virtual/net/lo"
    "SUBSYSTEM=3Dnet"
    "INTERFACE=3Dlo"
    "IFINDEXh"
    "SEQNUM=13593"
  -----
  ^Cend


Is it expected that those events would not be sent like that?
If not, is there something else I can do to track this further?

Or, if that's expected behavior, is there anything "udevadm settle"
can do to avoid the timeout?

-jim