[systemd-bugs] [Bug 90041] New: udevd affected by instance in early user space / does not apply udev rules as expected/logged

[bugzilla-daemon at freedesktop.org]

https://bugs.freedesktop.org/show_bug.cgi?id=90041

            Bug ID: 90041
           Summary: udevd affected by instance in early user space / does
                    not apply udev rules as expected/logged
           Product: systemd
           Version: unspecified
          Hardware: Other
                OS: All
            Status: NEW
          Severity: normal
          Priority: medium
         Component: general
          Assignee: systemd-bugs at lists.freedesktop.org
          Reporter: tom.ty89 at gmail.com
        QA Contact: systemd-bugs at lists.freedesktop.org

Created attachment 115090
  --> https://bugs.freedesktop.org/attachment.cgi?id=115090&action=edit
modified trigger service to capture test cases

So I have these two USB receivers, let's name them:
Device-13: logitech-djreceiver 0003:046D:C52B.0003: hiddev0,hidraw0: USB HID
v1.11 Device [Logitech USB Receiver] on usb-0000:00:14.0-13/input2
Device-14: hid-generic 0003:046D:C52E.0005: input,hidraw2: USB HID v1.11
Keyboard [Logitech USB Receiver] on usb-0000:00:14.0-14/input0

I am quite certain the bug is NOT hardware-specific, but I still list them here
for reference, and more importantly for some reason they have different default
value for attributes {power/wakeup}:
Device-13: disabled
Device-14: enabled
I don't know if this is determined by the kernel or udev, but this is the
default when there's no udev rules written to set attributes for them.

But my desired values is exactly the opposite, which are:
Device-13: enabled
Device-14: disabled

So I have the following udev rules written:
ATTR{devpath}=="13", ATTR{power/wakeup}="enabled"
ATTR{devpath}=="14", ATTR{power/wakeup}="disabled"

This reverse thing might make you a bit dizzy, so I'm gonna tell you, the bug
is gonna show up on Device-14, because it has a default value of "enabled",
while Device-13 makes a perfect control. So this is what happened after a fresh
reboot.

[tom at localhost ~]$ sudo journalctl -b | grep wakeup
...
Apr 15 16:54:03 localhost systemd-udevd[205]: Reading rules file:
/etc/udev/rules.d/wakeup.rules
Apr 15 16:54:04 localhost systemd-udevd[214]: ATTR
'/sys/devices/pci0000:00/0000:00:14.0/usb3/3-13/power/wakeup' writing 'enabled'
/etc/udev/rules.d/wakeup.rules:1
Apr 15 16:54:04 localhost systemd-udevd[215]: ATTR
'/sys/devices/pci0000:00/0000:00:14.0/usb3/3-14/power/wakeup' writing
'disabled' /etc/udev/rules.d/wakeup.rules:2
[tom at localhost ~]$ cat /sys/bus/usb/devices/3-13/power/wakeup
enabled
[tom at localhost ~]$ cat /sys/bus/usb/devices/3-14/power/wakeup
enabled

So the result is different from what is logged, but it only happens on
Device-14, why? You might suggest that I probably have some quirky power
management tools or scripts. But the answer is no, and I'm gonna to prove it.
(Note 1: in order to get the "ATTR" lines logged, I have to make sure that the
command `udevadm trigger` for type "devices" runs before the one for type
"subsystems", so I reverse them in the service file, not sure if it's another
bug)

After many different tests and experiments, I found that the cause of this
weird results is because of the systemd-udevd that has to be started in early
user space of the initramfs is exited before it has finished all of its job.
(Note 2: here actually shows another possible bug: there is no way to make sure
udevd exit only after finishing its job, despites all possible timeout
parameters. I would probably file another bug report for that)
This is the initcpio "hook" in Arch Linux for starting the udevd and triggering
events:
https://projects.archlinux.org/svntogit/packages.git/tree/trunk/initcpio-hook-udev?h=packages/systemd
(Note 3: `udevadm settle` is basically a no-op to this issue, not sure if it's
another bug.)
In order to confirm my proposed theory, I "toggle" `sleep 1` between the
trigger command and the exit command, and use the attached modified
systemd-udev-trigger.service to capture what happen before and after the
"later" trigger command, and to prove that giving the "early" udevd extra time
to finish its job would have impact on the final results.

So if I boot with `sleep 1` in the hook, the captured results are:
Pre-trigger:
Device-13: disabled
Device-14: enabled
(same as what should be without the udev rules written above)
Post-trigger:
Device-13: enabled
Device-14: disabled
(same as what should be with the udev rules written above)

But if I boot with the original hook, which is without `sleep 1` and cause
troubles, what captured are:
Pre-trigger:
Device-13: disabled
Device-14: disabled
Post-trigger:
Device-13: enabled
Device-14: enabled

I'll interpret the results as followed:
>From what I captured, it seems that the "raw default" of {power/wakeup} for all
devices are "disabled", and they gain their "own default" after the trigger
command. Since the udev rules written above is not included in the initcpio so
it does not exist in early user space, so you can see that: if the "early"
udevd have time to finish its job (with `sleep 1`), Device-14 gets its "own
default" which is "enabled", if not, Device-14 remains "disabled"; while for
Device-13, because the two values are the same before and after anyway, so the
time doesn't matter to it.

But the question is, why does this affect the final results of the "later"
udevd to a degree that what happen is different from what is clearly logged?

-- 
You are receiving this mail because:
You are the QA Contact for the bug.
You are the assignee for the bug.
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.freedesktop.org/archives/systemd-bugs/attachments/20150415/5710342f/attachment.html>