Bug 90051

Created attachment 115115 [details]
Shell script to reproduce the problem

Hi,

I'm having a hard time following this report.

Let summarize how things are meant to work:

Events received by udev (due to trigger) are either 'queued' or 'running' at any point in time. When you call 'exit', all the 'queued' events are dropped and the 'running' events are finished before we exit (up to a timeout of 30s). That means that even if one event is 'running' until the timeout, no new events are moved from 'queued' to running state.

What you should see is that once you call exit, udev exits "almost immediately". If it does not, that should mean that an event is stuck in "running" state for a long time (this should not happen, but could happen due to kernel issues or other external factors). You can verify that by seeing if udevd has any child processes after you call exit.

If udevd has no child processes, but still does not exit after you call exit, that is an udev bug. I was not able to reproduce that with your script though, so would be great if you could check that out.

Lastly, if if you want to make sure that udevd only exits after all the events caused by trigger have been processed, that is precisely what settle is for. It waits for udevd to receive the triggered events and then it waits for udevd to finish procssing them all (new events may appear at any time, but we make no guarantees about those).

(In reply to Tom Gundersen from comment #2)
> What you should see is that once you call exit, udev exits "almost
> immediately".
This is true for `udevadm control --exit`, but if udevd is started and stopped as a service, this is generally false. Here is an example, which you can see that it waits for exactly 30s:

[tom@localhost ~]$ systemctl status -l systemd-udevd
● systemd-udevd.service - udev Kernel Device Manager
   Loaded: loaded (/usr/lib/systemd/system/systemd-udevd.service; static; vendor preset: disabled)
   Active: active (running) since Fri 2015-04-24 19:36:02 HKT; 46s ago
     Docs: man:systemd-udevd.service(8)
           man:udev(7)
 Main PID: 194 (systemd-udevd)
   CGroup: /system.slice/systemd-udevd.service
           └─194 /usr/lib/systemd/systemd-udevd

Apr 24 19:36:02 localhost systemd-udevd[194]: starting version 219
[tom@localhost ~]$ systemctl status -l systemd-udevd
● systemd-udevd.service - udev Kernel Device Manager
   Loaded: loaded (/usr/lib/systemd/system/systemd-udevd.service; static; vendor preset: disabled)
   Active: inactive (dead) since Fri 2015-04-24 19:37:26 HKT; 2s ago
     Docs: man:systemd-udevd.service(8)
           man:udev(7)
  Process: 659 ExecStart=/usr/lib/systemd/systemd-udevd (code=exited, status=0/SUCCESS)
 Main PID: 659 (code=exited, status=0/SUCCESS)

Apr 24 19:36:55 localhost systemd-udevd[659]: starting version 219
Apr 24 19:36:55 localhost systemd[1]: Started udev Kernel Device Manager.
Apr 24 19:36:55 localhost systemd[1]: Stopping udev Kernel Device Manager...
Apr 24 19:36:55 localhost systemd-udevd[659]: worker [668] did not accept message -1 (Connection refused), kill it
Apr 24 19:36:55 localhost systemd-udevd[659]: worker [672] did not accept message -1 (Connection refused), kill it
Apr 24 19:36:55 localhost systemd-udevd[659]: worker [677] did not accept message -1 (Connection refused), kill it
Apr 24 19:36:55 localhost systemd-udevd[659]: worker [682] did not accept message -1 (Connection refused), kill it
Apr 24 19:36:55 localhost systemd-udevd[659]: worker [682] terminated by signal 9 (Killed)
Apr 24 19:37:25 localhost systemd-udevd[659]: timeout, giving up waiting for workers to finish
Apr 24 19:37:26 localhost systemd[1]: Stopped udev Kernel Device Manager.

But during the wait, I only see the main pid with `watch -n 0.1 pgrep udev`. (Well most of the wait, like 29.x seconds out of 30)

> Lastly, if if you want to make sure that udevd only exits after all the
> events caused by trigger have been processed, that is precisely what settle
> is for. It waits for udevd to receive the triggered events and then it waits
> for udevd to finish procssing them all (new events may appear at any time,
> but we make no guarantees about those).

It doesn't seem to work in the way you said. For example in this script:
https://projects.archlinux.org/svntogit/packages.git/tree/trunk/initcpio-hook-udev?h=packages/systemd
I assume that `udevadm settle` should make sure that events triggered by the two commands before it should be finished? But from what I am experiencing it does not.

For example, a number of kernel modules is included in the initramfs. Suppose given enough time (with `sleep` command), 26 of them would be loaded in early user space, but if only `udevadm settle` is used, the number could be random.

Hmm, does adding KillMode=mixed to the systemd-udevd.service unit file fix your issue?

(In reply to Lennart Poettering from comment #4)
> Hmm, does adding KillMode=mixed to the systemd-udevd.service unit file fix
> your issue?

Yes it does avoid the seemingly useless timeout. So now remains the settle issue.

I have set KillMode=mixed in the unit file now in git.

(In reply to Tom Yan from comment #3)
> It doesn't seem to work in the way you said. For example in this script:
> https://projects.archlinux.org/svntogit/packages.git/tree/trunk/initcpio-
> hook-udev?h=packages/systemd
> I assume that `udevadm settle` should make sure that events triggered by the
> two commands before it should be finished? But from what I am experiencing
> it does not.

A quick test seems to work fine here.

# cat /etc/udev/rules.d/10-local.rules
KERNEL=="null", RUN+="/usr/bin/sleep 3"

# echo $(date +%s) trigger; udevadm trigger; \
  echo $(date +%s) settling; udevadm settle; \
  echo $(date +%s) exiting; udevadm control --exit; \
  echo $(date +%s) done
1429886202 trigger
1429886202 settling
1429886205 exiting
1429886205 done

(In reply to Kay Sievers from comment #7)
> (In reply to Tom Yan from comment #3)
> > It doesn't seem to work in the way you said. For example in this script:
> > https://projects.archlinux.org/svntogit/packages.git/tree/trunk/initcpio-
> > hook-udev?h=packages/systemd
> > I assume that `udevadm settle` should make sure that events triggered by the
> > two commands before it should be finished? But from what I am experiencing
> > it does not.
> 
> A quick test seems to work fine here.
> 
> # cat /etc/udev/rules.d/10-local.rules
> KERNEL=="null", RUN+="/usr/bin/sleep 3"
> 
> # echo $(date +%s) trigger; udevadm trigger; \
>   echo $(date +%s) settling; udevadm settle; \
>   echo $(date +%s) exiting; udevadm control --exit; \
>   echo $(date +%s) done
> 1429886202 trigger
> 1429886202 settling
> 1429886205 exiting
> 1429886205 done

I am aware of that. This problem can't be easily reproduced in a script because the time needed to make a difference could varies depending on the job and could be really short.

Not sure how to give you very nice proof. But maybe I can upload some pics to let you see the difference.

Created attachment 115307 [details]
modified "hook" script for reproducing issue

So i add `lsmod` and `lsmod | wc -l` after the "early" udevd is exited to see the (number of) modules get loaded, and by toggling `sleep 1` you can see they change despite the `udevadm settle` command.

Four screenshots from two test cases will follow. The two cases aim to show that it's not a module-specific problem. The difference of the two cases is the port being used by my two usb hid receivers: In case 1 Receiver A use Port 13 and Receiver B use Port 14; In case 2 Receiver A use port 14 and Receiver B use Port 13.

Created attachment 115308 [details]
Case 1 -- without `sleep 1`

Created attachment 115309 [details]
Case 1 -- with `sleep 1`

Created attachment 115310 [details]
Case 2 -- without `sleep 1`

Created attachment 115311 [details]
Case 2 -- with `sleep 1`

same as "Case 1 -- `with sleep 1`", except the order

Created attachment 115312 [details]
control hook script

I tried to put `sleep 1` after `udevadm control --exit` as well. The results are the same as in the "case*_without_sleep" screenshots. Kind of confirm the time is needed for udevd but not something else.

Also tried to have only one receiver plugged into Port 14. The issue would disappear, probably because the time needed is reduced. Hence not a hardware problem (except for being a bit slow?).

(In reply to Tom Yan from comment #14)
> Also tried to have only one receiver plugged into Port 14. The issue would
> disappear, probably because the time needed is reduced. Hence not a hardware
> problem (except for being a bit slow?).

Sorry I should have explained it a bit.

The reason I test Port 14 alone is because in the previous two test cases, the driver module(s) of receiver plugged into Port 14 are not loaded, which are:

Case 1 -- without `sleep 1`: hid_generic
Case 2 -- without `sleep 1`: hid_logitech_hidpp, hid_logitech_dj

so I did extra tests by plugging in receiver into Port 14 only each time to confirm the port itself is fine

Thanks for all the info.

I'm still puzzled by the 30 second timeout. It appears we are losing track of worker processes, but I can't see how, and I can't reproduce it. Could you try to reproduce again (without Lennart's fix) using current git HEAD (you can just do "./autogen.sh c && make systemd-udevd"). I added quite a bit of extra logging now.

As to the settle issue, I'm not sure what's going on. There was a fix in this area not too long ago, so could you also confirm that this is still a problem with current git?

Created attachment 115314 [details]
5 trials of reproducing timeout issue

(In reply to Tom Gundersen from comment #16)
> As to the settle issue, I'm not sure what's going on. There was a fix in
> this area not too long ago, so could you also confirm that this is still a
> problem with current git?

Yes it is still a problem as of commit b66f29a.

Thanks for checking. The output of systemctl is truncated, so could you possibly instead attach the relevant output of "journalctl -u systemd-udevd"?

Also, could you check if this patch fixes the 30 second timeout: http://paste.fedoraproject.org/215475/99796611/ ?

Created attachment 115329 [details]
journalctl -b -u systemd-udevd (after patch)

journalctl output looks the same to me, so I assume you mean udev_log="debug"?

Created attachment 115330 [details]
journalctl -b -u systemd-udevd (before patch)

The patch doesn't help. Another 5 trials before the patch.