udev missing events?

udev missing events?

[Jim Paris]

(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
  
  KERNEL[537903.765581] add      /devices/virtual/net/lo/queues/rx-0 (queues)
  ACTION­d
  DEVPATH=/devices/virtual/net/lo/queues/rx-0
  SEQNUM\x13589
  SUBSYSTEM=queues
  UDEV_LOG=3
  
  KERNEL[537903.765683] add      /devices/virtual/net/lo/queues/tx-0 (queues)
  ACTION­d
  DEVPATH=/devices/virtual/net/lo/queues/tx-0
  SEQNUM\x13590
  SUBSYSTEM=queues
  UDEV_LOG=3
  
  KERNEL[537903.844154] remove   /devices/virtual/net/lo/queues/rx-0 (queues)
  ACTION=remove
  DEVPATH=/devices/virtual/net/lo/queues/rx-0
  SEQNUM\x13591
  SUBSYSTEM=queues
  UDEV_LOG=3
  
  KERNEL[537903.844192] remove   /devices/virtual/net/lo/queues/tx-0 (queues)
  ACTION=remove
  DEVPATH=/devices/virtual/net/lo/queues/tx-0
  SEQNUM\x13592
  SUBSYSTEM=queues
  UDEV_LOG=3

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 
  begin
  -----
  netlink_broadcast_filtered: -3 (ESRCH)
  netlink_broadcast_filtered: -3 (ESRCH)
  event was:
    uevent_seqnum: 13588
    "ACTION­d"
    "DEVPATH=/devices/virtual/net/lo"
    "SUBSYSTEM=net"
    "INTERFACE=lo"
    "IFINDEXh"
    "SEQNUM\x13588"
  -----
  netlink_broadcast_filtered: 0x0
  netlink_broadcast_filtered: -3 (ESRCH)
  event was:
    uevent_seqnum: 13589
    "ACTION­d"
    "DEVPATH=/devices/virtual/net/lo/queues/rx-0"
    "SUBSYSTEM=queues"
    "SEQNUM\x13589"
  -----
  netlink_broadcast_filtered: 0x0
  netlink_broadcast_filtered: -3 (ESRCH)
  event was:
    uevent_seqnum: 13590
    "ACTION­d"
    "DEVPATH=/devices/virtual/net/lo/queues/tx-0"
    "SUBSYSTEM=queues"
    "SEQNUM\x13590"
  -----
  netlink_broadcast_filtered: 0x0
  netlink_broadcast_filtered: -3 (ESRCH)
  event was:
    uevent_seqnum: 13591
    "ACTION=remove"
    "DEVPATH=/devices/virtual/net/lo/queues/rx-0"
    "SUBSYSTEM=queues"
    "SEQNUM\x13591"
  -----
  netlink_broadcast_filtered: 0x0
  netlink_broadcast_filtered: -3 (ESRCH)
  event was:
    uevent_seqnum: 13592
    "ACTION=remove"
    "DEVPATH=/devices/virtual/net/lo/queues/tx-0"
    "SUBSYSTEM=queues"
    "SEQNUM\x13592"
  -----
  netlink_broadcast_filtered: -3 (ESRCH)
  netlink_broadcast_filtered: -3 (ESRCH)
  event was:
    uevent_seqnum: 13593
    "ACTION=remove"
    "DEVPATH=/devices/virtual/net/lo"
    "SUBSYSTEM=net"
    "INTERFACE=lo"
    "IFINDEXh"
    "SEQNUM\x13593"
  -----
  ^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

Re: udev missing events?

[Jim Paris]

Eric W. Biederman wrote:
> Jim Paris <jim@jtan.com> wrote:
> 
> >(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
> >  
> >KERNEL[537903.765581] add      /devices/virtual/net/lo/queues/rx-0
> >(queues)
> >  ACTION­d
> >  DEVPATH=/devices/virtual/net/lo/queues/rx-0
> >  SEQNUM\x13589
> >  SUBSYSTEM=queues
> >  UDEV_LOG=3
> >  
> >KERNEL[537903.765683] add      /devices/virtual/net/lo/queues/tx-0
> >(queues)
> >  ACTION­d
> >  DEVPATH=/devices/virtual/net/lo/queues/tx-0
> >  SEQNUM\x13590
> >  SUBSYSTEM=queues
> >  UDEV_LOG=3
> >  
> >KERNEL[537903.844154] remove   /devices/virtual/net/lo/queues/rx-0
> >(queues)
> >  ACTION=remove
> >  DEVPATH=/devices/virtual/net/lo/queues/rx-0
> >  SEQNUM\x13591
> >  SUBSYSTEM=queues
> >  UDEV_LOG=3
> >  
> >KERNEL[537903.844192] remove   /devices/virtual/net/lo/queues/tx-0
> >(queues)
> >  ACTION=remove
> >  DEVPATH=/devices/virtual/net/lo/queues/tx-0
> >  SEQNUM\x13592
> >  SUBSYSTEM=queues
> >  UDEV_LOG=3
> >
> >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 
> >  begin
> >  -----
> >  netlink_broadcast_filtered: -3 (ESRCH)
> >  netlink_broadcast_filtered: -3 (ESRCH)
> >  event was:
> >    uevent_seqnum: 13588
> >    "ACTION­d"
> >    "DEVPATH=/devices/virtual/net/lo"
> >    "SUBSYSTEM=net"
> >    "INTERFACE=lo"
> >    "IFINDEXh"
> >    "SEQNUM\x13588"
> >  -----
> >  netlink_broadcast_filtered: 0x0
> >  netlink_broadcast_filtered: -3 (ESRCH)
> >  event was:
> >    uevent_seqnum: 13589
> >    "ACTION­d"
> >    "DEVPATH=/devices/virtual/net/lo/queues/rx-0"
> >    "SUBSYSTEM=queues"
> >    "SEQNUM\x13589"
> >  -----
> >  netlink_broadcast_filtered: 0x0
> >  netlink_broadcast_filtered: -3 (ESRCH)
> >  event was:
> >    uevent_seqnum: 13590
> >    "ACTION­d"
> >    "DEVPATH=/devices/virtual/net/lo/queues/tx-0"
> >    "SUBSYSTEM=queues"
> >    "SEQNUM\x13590"
> >  -----
> >  netlink_broadcast_filtered: 0x0
> >  netlink_broadcast_filtered: -3 (ESRCH)
> >  event was:
> >    uevent_seqnum: 13591
> >    "ACTION=remove"
> >    "DEVPATH=/devices/virtual/net/lo/queues/rx-0"
> >    "SUBSYSTEM=queues"
> >    "SEQNUM\x13591"
> >  -----
> >  netlink_broadcast_filtered: 0x0
> >  netlink_broadcast_filtered: -3 (ESRCH)
> >  event was:
> >    uevent_seqnum: 13592
> >    "ACTION=remove"
> >    "DEVPATH=/devices/virtual/net/lo/queues/tx-0"
> >    "SUBSYSTEM=queues"
> >    "SEQNUM\x13592"
> >  -----
> >  netlink_broadcast_filtered: -3 (ESRCH)
> >  netlink_broadcast_filtered: -3 (ESRCH)
> >  event was:
> >    uevent_seqnum: 13593
> >    "ACTION=remove"
> >    "DEVPATH=/devices/virtual/net/lo"
> >    "SUBSYSTEM=net"
> >    "INTERFACE=lo"
> >    "IFINDEXh"
> >    "SEQNUM\x13593"
> >  -----
> >  ^Cend
> >
> >
> >Is it expected that those events would not be sent like that?
> 
> Roughly. Events for network devices are only delivered to sockets in the same netwoerk namespace.
> 
> So you really shouldn't see much of an event for the creationof a network namespace.
> 
> >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?
> 
> I don't think so.  Udev for the host should not see events for things that happen inside a container.
>
> I am a little mystified that you see as much of the add of lo as you do in the udem monitor command.
> 
> I am infering what is going on with libvirt and your machine and assuming containers are involved because of the additions and removals of lo.

I'm not using them on purpose, but it's caused by a probing clone() in
libvirt's lxcContainerAavilable, followed by a "ip link set lo netns -1"
in lxcCheckNetNsSupport.  It can be recreated with just:

  #include <unistd.h>
  #include <sched.h>
  static int dummy(void *argv) { _exit(0); }
  main() {
          char stack[4096];
          clone(dummy, stack+4096, CLONE_NEWNET, NULL);
          wait();
          system("ip link set lo netns -1");
  }

Running that program causes "udevadm settle" to stop working due to
the filtered events.

-jim

Re: udev missing events?

[Eric W. Biederman]

Jim Paris <jim@jtan.com> writes:

> Eric W. Biederman wrote:
>> Jim Paris <jim@jtan.com> wrote:
>> 
>> >(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
>> >  
>> >KERNEL[537903.765581] add      /devices/virtual/net/lo/queues/rx-0
>> >(queues)
>> >  ACTION­d
>> >  DEVPATH=/devices/virtual/net/lo/queues/rx-0
>> >  SEQNUM\x13589
>> >  SUBSYSTEM=queues
>> >  UDEV_LOG=3
>> >  
>> >KERNEL[537903.765683] add      /devices/virtual/net/lo/queues/tx-0
>> >(queues)
>> >  ACTION­d
>> >  DEVPATH=/devices/virtual/net/lo/queues/tx-0
>> >  SEQNUM\x13590
>> >  SUBSYSTEM=queues
>> >  UDEV_LOG=3
>> >  
>> >KERNEL[537903.844154] remove   /devices/virtual/net/lo/queues/rx-0
>> >(queues)
>> >  ACTION=remove
>> >  DEVPATH=/devices/virtual/net/lo/queues/rx-0
>> >  SEQNUM\x13591
>> >  SUBSYSTEM=queues
>> >  UDEV_LOG=3
>> >  
>> >KERNEL[537903.844192] remove   /devices/virtual/net/lo/queues/tx-0
>> >(queues)
>> >  ACTION=remove
>> >  DEVPATH=/devices/virtual/net/lo/queues/tx-0
>> >  SEQNUM\x13592
>> >  SUBSYSTEM=queues
>> >  UDEV_LOG=3
>> >
>> >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 
>> >  begin
>> >  -----
>> >  netlink_broadcast_filtered: -3 (ESRCH)
>> >  netlink_broadcast_filtered: -3 (ESRCH)
>> >  event was:
>> >    uevent_seqnum: 13588
>> >    "ACTION­d"
>> >    "DEVPATH=/devices/virtual/net/lo"
>> >    "SUBSYSTEM=net"
>> >    "INTERFACE=lo"
>> >    "IFINDEXh"
>> >    "SEQNUM\x13588"
>> >  -----
>> >  netlink_broadcast_filtered: 0x0
>> >  netlink_broadcast_filtered: -3 (ESRCH)
>> >  event was:
>> >    uevent_seqnum: 13589
>> >    "ACTION­d"
>> >    "DEVPATH=/devices/virtual/net/lo/queues/rx-0"
>> >    "SUBSYSTEM=queues"
>> >    "SEQNUM\x13589"
>> >  -----
>> >  netlink_broadcast_filtered: 0x0
>> >  netlink_broadcast_filtered: -3 (ESRCH)
>> >  event was:
>> >    uevent_seqnum: 13590
>> >    "ACTION­d"
>> >    "DEVPATH=/devices/virtual/net/lo/queues/tx-0"
>> >    "SUBSYSTEM=queues"
>> >    "SEQNUM\x13590"
>> >  -----
>> >  netlink_broadcast_filtered: 0x0
>> >  netlink_broadcast_filtered: -3 (ESRCH)
>> >  event was:
>> >    uevent_seqnum: 13591
>> >    "ACTION=remove"
>> >    "DEVPATH=/devices/virtual/net/lo/queues/rx-0"
>> >    "SUBSYSTEM=queues"
>> >    "SEQNUM\x13591"
>> >  -----
>> >  netlink_broadcast_filtered: 0x0
>> >  netlink_broadcast_filtered: -3 (ESRCH)
>> >  event was:
>> >    uevent_seqnum: 13592
>> >    "ACTION=remove"
>> >    "DEVPATH=/devices/virtual/net/lo/queues/tx-0"
>> >    "SUBSYSTEM=queues"
>> >    "SEQNUM\x13592"
>> >  -----
>> >  netlink_broadcast_filtered: -3 (ESRCH)
>> >  netlink_broadcast_filtered: -3 (ESRCH)
>> >  event was:
>> >    uevent_seqnum: 13593
>> >    "ACTION=remove"
>> >    "DEVPATH=/devices/virtual/net/lo"
>> >    "SUBSYSTEM=net"
>> >    "INTERFACE=lo"
>> >    "IFINDEXh"
>> >    "SEQNUM\x13593"
>> >  -----
>> >  ^Cend
>> >
>> >
>> >Is it expected that those events would not be sent like that?
>> 
>> Roughly. Events for network devices are only delivered to sockets in the same netwoerk namespace.
>> 
>> So you really shouldn't see much of an event for the creationof a network namespace.
>> 
>> >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?
>> 
>> I don't think so.  Udev for the host should not see events for things that happen inside a container.
>>
>> I am a little mystified that you see as much of the add of lo as you do in the udem monitor command.
>> 
>> I am infering what is going on with libvirt and your machine and assuming containers are involved because of the additions and removals of lo.
>
> I'm not using them on purpose, but it's caused by a probing clone() in
> libvirt's lxcContainerAavilable, followed by a "ip link set lo netns -1"
> in lxcCheckNetNsSupport.  It can be recreated with just:
>
>   #include <unistd.h>
>   #include <sched.h>
>   static int dummy(void *argv) { _exit(0); }
>   main() {
>           char stack[4096];
>           clone(dummy, stack+4096, CLONE_NEWNET, NULL);
>           wait();
>           system("ip link set lo netns -1");
>   }
>
> Running that program causes "udevadm settle" to stop working due to
> the filtered events.

By stop working you mean "udevadm settle" waits because it thinks there
are unprocessed events but those events are never found, and eventually
"udevadm settle" times out?

I'm sorry I don't see the problem.

I think the most we could do would be to have a per network namespace
sequence number, but I don't get see the problem with skipping a sequence
number or two.  Does that cause udev to explode or something?  It
doesn't sound like udev has problems.

It does look like we aren't filtering all of the events for the new
loopback device properly.  We should be filtering the events for
/sys/devices/virtual/net/lo/queues/rx-0 and friends.  But fixing that
problem looks like it will only make the gap in sequence numbers
larger, and if anything make the "udevadm settle" problem worse.

What precisely is the problem you are seeing?

Of course in this instance I can't see how the version of libvirt you
are playing with would ever have worked.  It is relying on features to
act in a way the simply don't act.

Eric

Re: udev missing events?

[Jim Paris]

Eric W. Biederman wrote:
> > I'm not using them on purpose, but it's caused by a probing clone() in
> > libvirt's lxcContainerAavilable, followed by a "ip link set lo netns -1"
> > in lxcCheckNetNsSupport.  It can be recreated with just:
> >
> >   #include <unistd.h>
> >   #include <sched.h>
> >   static int dummy(void *argv) { _exit(0); }
> >   main() {
> >           char stack[4096];
> >           clone(dummy, stack+4096, CLONE_NEWNET, NULL);
> >           wait();
> >           system("ip link set lo netns -1");
> >   }
> >
> > Running that program causes "udevadm settle" to stop working due to
> > the filtered events.
> 
> By stop working you mean "udevadm settle" waits because it thinks there
> are unprocessed events but those events are never found, and eventually
> "udevadm settle" times out?

Yeah.

> I'm sorry I don't see the problem.
> 
> I think the most we could do would be to have a per network namespace
> sequence number, but I don't get see the problem with skipping a sequence
> number or two.  Does that cause udev to explode or something?  It
> doesn't sound like udev has problems.
> 
> It does look like we aren't filtering all of the events for the new
> loopback device properly.  We should be filtering the events for
> /sys/devices/virtual/net/lo/queues/rx-0 and friends.  But fixing that
> problem looks like it will only make the gap in sequence numbers
> larger, and if anything make the "udevadm settle" problem worse.
> 
> What precisely is the problem you are seeing?

The specific problem is that virt-manager loses its connection to
libvirt.  Libvirt triggers this situation, and then later executes
"udevadm settle" after some of virt-manager's storage requests.  I
think that happens in one thread, while another libvirt thread then
kills the virt-manager connection for stalling for so long.

I can certainly ask the libvirt guys to add a shorter --timeout
parameter, at the very least, if this isn't considered a bug from the
udev point of view.  But libvirt isn't the only thing that calls
"udevadm settle" -- having to wait 2-3 minutes for each settle call
during an initramfs build or similar would also be annoying.

> Of course in this instance I can't see how the version of libvirt you
> are playing with would ever have worked.  It is relying on features to
> act in a way the simply don't act.

I upgraded libvirt and the kernel lately, so either some of this lxc
probing code in libvirt is new, or maybe my kernel didn't support net
namespaces before.  Libvirt has called udevadm settle for a while,
though.

Thanks,
-jim

Re: udev missing events?

[Frank Ch. Eigler]

Jim Paris <jim@jtan.com> writes:

> [...]
> 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 [...]

By the way, your monitor.stp contains this bit:

   /* I don't know how to do this better, indexing envp
   if ($env->envp_idx > 0) printf("  %s\n", $env->envp[0]$)
   if ($env->envp_idx > 1) printf("  %s\n", $env->envp[1]$)
   [...]
   if ($env->envp_idx > 9) printf("  %s\n", $env->envp[9]$)
   if ($env->envp_idx > 10) printf("..... more\n")

More idiomatic would be as follows (stap version 0.9.9+):

   for (i=0; i<$env->envp_idx; i++) {
       printf("  %s\n", $env->envp[i]$)
   }

- FChE