Bug#1011523: systemd-logind: lightdm ignores keyboard input for the first 3 seconds

[Vincent Lefevre]

On 2022-06-27 13:27:23 +0200, Michael Biebl wrote:
> What I can see here is that "Before" the Xorg server was apparently ready
> after 16.597/16.818 and "After" it is after 15.909/14.644. So it is actually
> quicker?

Yes, the X server is started earlier (because the display manager is
started earlier, I assume).

> So is this maybe just a perceived slowness?

But this does not explain why the keyboard isn't available immediately
by the X server like on my laptop. The systemd-logind logs show the
same kind of delay.

For instance, on my laptop, a fraction of second after the boot:

Jun 23 04:29:32 zira kernel: usb 2-6.2: New USB device found, idVendor=05ac, idProduct=0221, bcdDevice= 0.69
Jun 23 04:29:32 zira kernel: usb 2-6.2: New USB device strings: Mfr=1, Product=2, SerialNumber=0
Jun 23 04:29:32 zira kernel: usb 2-6.2: Product: Apple Keyboard
Jun 23 04:29:32 zira kernel: usb 2-6.2: Manufacturer: Apple, Inc
Jun 23 04:29:32 zira kernel: input: Apple, Inc Apple Keyboard as /devices/pci0000:00/0000:00:14.0/usb2/2-6/2-6.2/2-6.2:1.0/0003:05AC:0221.0001/input/input9
Jun 23 04:29:32 zira kernel: apple 0003:05AC:0221.0001: input,hidraw0: USB HID v1.11 Keyboard [Apple, Inc Apple Keyboard] on usb-0000:00:14.0-6.2/input0
Jun 23 04:29:32 zira kernel: apple 0003:05AC:0221.0002: Fn key not found (Apple Wireless Keyboard clone?), disabling Fn key handling
Jun 23 04:29:32 zira kernel: input: Apple, Inc Apple Keyboard as /devices/pci0000:00/0000:00:14.0/usb2/2-6/2-6.2/2-6.2:1.1/0003:05AC:0221.0002/input/input10
Jun 23 04:29:32 zira kernel: apple 0003:05AC:0221.0002: input,hidraw1: USB HID v1.11 Device [Apple, Inc Apple Keyboard] on usb-0000:00:14.0-6.2/input1

5 seconds later, about the display manager:

Jun 23 04:29:37 zira lightdm[3347]: pam_unix(lightdm-greeter:session): session opened for user lightdm(uid=116) by (uid=0)
Jun 23 04:29:37 zira systemd-logind[846]: New session c1 of user lightdm.
Jun 23 04:29:37 zira systemd[3381]: pam_unix(systemd-user:session): session opened for user lightdm(uid=116) by (uid=0)
Jun 23 04:29:37 zira systemd[1]: Started Session c1 of User lightdm.

but systemd-logind logged about the keyboard just 1 second after the
boot (thus before lightdm):

Jun 23 04:29:33 zira systemd-logind[846]: Watching system buttons on /dev/input/event3 (Apple, Inc Apple Keyboard)

So everything is fine there.

But on my desktop machine, a fraction of second after the boot:

Jun 24 17:21:16 cventin kernel: usb 2-14: New USB device found, idVendor=413c, idProduct=2107, bcdDevice= 1.04
Jun 24 17:21:16 cventin kernel: usb 2-14: New USB device strings: Mfr=1, Product=2, SerialNumber=0
Jun 24 17:21:16 cventin kernel: usb 2-14: Product: Dell USB Entry Keyboard
Jun 24 17:21:16 cventin kernel: usb 2-14: Manufacturer: DELL
Jun 24 17:21:16 cventin kernel: input: DELL Dell USB Entry Keyboard as /devices/pci0000:00/0000:00:14.0/usb2/2-14/2-14:1.0/0003:413C:2107.0001/input/input2
Jun 24 17:21:16 cventin kernel: hid-generic 0003:413C:2107.0001: input,hidraw0: USB HID v1.11 Keyboard [DELL Dell USB Entry Keyboard] on usb-0000:00:14.0-14/input0

5 seconds later, about the display manager:

Jun 24 17:21:21 cventin lightdm[827]: pam_unix(lightdm-greeter:session): session opened for user lightdm(uid=118) by (uid=0)
Jun 24 17:21:21 cventin systemd[831]: pam_unix(systemd-user:session): session opened for user lightdm(uid=118) by (uid=0)
Jun 24 17:21:21 cventin systemd[1]: Started Session c1 of User lightdm.

but systemd-logind logged about the keyboard 10 seconds after the
boot, thus 5 seconds *after* the display manager was started:

Jun 24 17:21:26 cventin systemd-logind[606]: Watching system buttons on /dev/input/event2 (DELL Dell USB Entry Keyboard)

So, what happens with systemd-logind there?

Perhaps that's actually the real issue (which didn't exist in
early 2019 and gradually became more and more apparent with the
maximum reached in November 2019). And the change in systemd 251
just revealed it.

But there might also be something wrong in the dependencies of
the services.

> That said, as neither Yves-Alexis nor me is able to reproduce any issues
> here, your best bet, if you think this is related to systemd, is to run a
> git bisect to find the commit which changed the behaviour.

I'm wondering whether it could be related to this change:

        Changes in udev:
[...]
        * udevadm trigger gained a new --prioritized-subsystem= option to
          process certain subsystems (and all their parent devices) earlier.

          systemd-udev-trigger.service now uses this new option to trigger
          block and TPM devices first, hopefully making the boot a bit faster.

Also, I have plymouth installed on this machine. I should probably
try without it to see if this makes a difference.

-- 
Vincent Lefèvre <vincent at vinc17.net> - Web: <https://www.vinc17.net/>
100% accessible validated (X)HTML - Blog: <https://www.vinc17.net/blog/>
Work: CR INRIA - computer arithmetic / AriC project (LIP, ENS-Lyon)