Discussion:
udev missing events?
Jim Paris
2012-04-22 04:36:55 UTC
Permalink
(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=add
DEVPATH=/devices/virtual/net/lo/queues/rx-0
SEQNUM=13589
SUBSYSTEM=queues
UDEV_LOG=3

KERNEL[537903.765683] add /devices/virtual/net/lo/queues/tx-0 (queues)
ACTION=add
DEVPATH=/devices/virtual/net/lo/queues/tx-0
SEQNUM=13590
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=13591
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=13592
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=add"
"DEVPATH=/devices/virtual/net/lo"
"SUBSYSTEM=net"
"INTERFACE=lo"
"IFINDEX=68"
"SEQNUM=13588"
-----
netlink_broadcast_filtered: 0x0
netlink_broadcast_filtered: -3 (ESRCH)
event was:
uevent_seqnum: 13589
"ACTION=add"
"DEVPATH=/devices/virtual/net/lo/queues/rx-0"
"SUBSYSTEM=queues"
"SEQNUM=13589"
-----
netlink_broadcast_filtered: 0x0
netlink_broadcast_filtered: -3 (ESRCH)
event was:
uevent_seqnum: 13590
"ACTION=add"
"DEVPATH=/devices/virtual/net/lo/queues/tx-0"
"SUBSYSTEM=queues"
"SEQNUM=13590"
-----
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=13591"
-----
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=13592"
-----
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"
"IFINDEX=68"
"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
--
To unsubscribe from this list: send the line "unsubscribe linux-hotplug" in
the body of a message to ***@vger.kernel.org
More majordomo info at http://vger.kernel.org/majordomo-info.html
Jim Paris
2012-04-22 14:11:06 UTC
Permalink
Post by 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
# 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
# udevadm monitor --kernel --property
KERNEL - the kernel uevent
KERNEL[537903.765581] add /devices/virtual/net/lo/queues/rx-0 (queues)
ACTION=add
DEVPATH=/devices/virtual/net/lo/queues/rx-0
SEQNUM=13589
SUBSYSTEM=queues
UDEV_LOG=3
KERNEL[537903.765683] add /devices/virtual/net/lo/queues/tx-0 (queues)
ACTION=add
DEVPATH=/devices/virtual/net/lo/queues/tx-0
SEQNUM=13590
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=13591
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=13592
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
$ sudo ./monitor.stp
begin
-----
netlink_broadcast_filtered: -3 (ESRCH)
netlink_broadcast_filtered: -3 (ESRCH)
uevent_seqnum: 13588
"ACTION=add"
"DEVPATH=/devices/virtual/net/lo"
"SUBSYSTEM=net"
"INTERFACE=lo"
"IFINDEX=68"
"SEQNUM=13588"
-----
netlink_broadcast_filtered: 0x0
netlink_broadcast_filtered: -3 (ESRCH)
uevent_seqnum: 13589
"ACTION=add"
"DEVPATH=/devices/virtual/net/lo/queues/rx-0"
"SUBSYSTEM=queues"
"SEQNUM=13589"
-----
netlink_broadcast_filtered: 0x0
netlink_broadcast_filtered: -3 (ESRCH)
uevent_seqnum: 13590
"ACTION=add"
"DEVPATH=/devices/virtual/net/lo/queues/tx-0"
"SUBSYSTEM=queues"
"SEQNUM=13590"
-----
netlink_broadcast_filtered: 0x0
netlink_broadcast_filtered: -3 (ESRCH)
uevent_seqnum: 13591
"ACTION=remove"
"DEVPATH=/devices/virtual/net/lo/queues/rx-0"
"SUBSYSTEM=queues"
"SEQNUM=13591"
-----
netlink_broadcast_filtered: 0x0
netlink_broadcast_filtered: -3 (ESRCH)
uevent_seqnum: 13592
"ACTION=remove"
"DEVPATH=/devices/virtual/net/lo/queues/tx-0"
"SUBSYSTEM=queues"
"SEQNUM=13592"
-----
netlink_broadcast_filtered: -3 (ESRCH)
netlink_broadcast_filtered: -3 (ESRCH)
uevent_seqnum: 13593
"ACTION=remove"
"DEVPATH=/devices/virtual/net/lo"
"SUBSYSTEM=net"
"INTERFACE=lo"
"IFINDEX=68"
"SEQNUM=13593"
-----
^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.
Post by Jim Paris
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
--
To unsubscribe from this list: send the line "unsubscribe linux-hotplug" in
the body of a message to ***@vger.kernel.org
More majordomo info at http://vger.kernel.org/majordomo-info.html
Eric W. Biederman
2012-04-22 16:07:11 UTC
Permalink
Post by Jim Paris
Post by 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
# 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
# udevadm monitor --kernel --property
KERNEL - the kernel uevent
KERNEL[537903.765581] add /devices/virtual/net/lo/queues/rx-0 (queues)
ACTION=add
DEVPATH=/devices/virtual/net/lo/queues/rx-0
SEQNUM=13589
SUBSYSTEM=queues
UDEV_LOG=3
KERNEL[537903.765683] add /devices/virtual/net/lo/queues/tx-0 (queues)
ACTION=add
DEVPATH=/devices/virtual/net/lo/queues/tx-0
SEQNUM=13590
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=13591
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=13592
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
$ sudo ./monitor.stp
begin
-----
netlink_broadcast_filtered: -3 (ESRCH)
netlink_broadcast_filtered: -3 (ESRCH)
uevent_seqnum: 13588
"ACTION=add"
"DEVPATH=/devices/virtual/net/lo"
"SUBSYSTEM=net"
"INTERFACE=lo"
"IFINDEX=68"
"SEQNUM=13588"
-----
netlink_broadcast_filtered: 0x0
netlink_broadcast_filtered: -3 (ESRCH)
uevent_seqnum: 13589
"ACTION=add"
"DEVPATH=/devices/virtual/net/lo/queues/rx-0"
"SUBSYSTEM=queues"
"SEQNUM=13589"
-----
netlink_broadcast_filtered: 0x0
netlink_broadcast_filtered: -3 (ESRCH)
uevent_seqnum: 13590
"ACTION=add"
"DEVPATH=/devices/virtual/net/lo/queues/tx-0"
"SUBSYSTEM=queues"
"SEQNUM=13590"
-----
netlink_broadcast_filtered: 0x0
netlink_broadcast_filtered: -3 (ESRCH)
uevent_seqnum: 13591
"ACTION=remove"
"DEVPATH=/devices/virtual/net/lo/queues/rx-0"
"SUBSYSTEM=queues"
"SEQNUM=13591"
-----
netlink_broadcast_filtered: 0x0
netlink_broadcast_filtered: -3 (ESRCH)
uevent_seqnum: 13592
"ACTION=remove"
"DEVPATH=/devices/virtual/net/lo/queues/tx-0"
"SUBSYSTEM=queues"
"SEQNUM=13592"
-----
netlink_broadcast_filtered: -3 (ESRCH)
netlink_broadcast_filtered: -3 (ESRCH)
uevent_seqnum: 13593
"ACTION=remove"
"DEVPATH=/devices/virtual/net/lo"
"SUBSYSTEM=net"
"INTERFACE=lo"
"IFINDEX=68"
"SEQNUM=13593"
-----
^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.
Post by Jim Paris
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"
#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
Jim Paris
2012-04-22 16:54:01 UTC
Permalink
Post by Eric W. Biederman
Post by Jim Paris
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"
#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.
Post by Eric W. Biederman
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.
Post by Eric W. Biederman
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
--
To unsubscribe from this list: send the line "unsubscribe linux-hotplug" in
the body of a message to ***@vger.kernel.org
More majordomo info at http://vger.kernel.org/majordomo-info.html
Frank Ch. Eigler
2012-04-27 13:59:49 UTC
Permalink
Post by Jim Paris
[...]
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
--
To unsubscribe from this list: send the line "unsubscribe linux-hotplug" in
the body of a message to ***@vger.kernel.org
More majordomo info at http://vger.kernel.org/majordomo-info.html
Loading...