Bug 90041

Created attachment 115090 [details]
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@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@localhost ~]$ cat /sys/bus/usb/devices/3-13/power/wakeup
enabled
[tom@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?