Keyboard not available immediately in X11 / display manager after the boot on some machine #24026
Description
systemd version the issue has been seen with
251
Used distribution
Debian/unstable
Linux kernel version used
5.17.0-2-amd64 / 5.18.0-2-amd64
CPU architectures issue was seen on
x86_64
Component
systemd-logind
Expected behaviour you didn't see
The keyboard should be available immediately after the boot in the display manager.
Unexpected behaviour you saw
After the boot, when I start typing my password, the first keys are not taken into account. The journalctl and Xorg logs show an unexpected delay concerning the keyboard (about systemd-logind and udev respectively), which could explain the issue, while the keyboard is visible almost immediately by the kernel (according to journalctl). See details later.
This happens with my desktop machine at my lab, but I have no such issue with my laptop.
Steps to reproduce the problem
On the machine in question:
- Boot (or reboot) the machine.
- In the grub screen, select the kernel (or wait for a few seconds for the default).
- In the display manager (I've tried with both lightdm and xdm), start typing with the keyboard: nothing happens, and after a few seconds, keys are starting to be taken into account.
Note: This issue is visible only when systemd-udev-trigger.service contains
ExecStart=-udevadm trigger --type=all --action=add --prioritized-subsystem=block,tpmrm
which is new in systemd 251 (I didn't have this issue with systemd 250 and before). However, without that, there is a reproducible 6-second freeze that makes the display manager start later, thus actually hiding the issue.
Additional information
With systemd 250.4-1, journalctl shows:
May 24 14:12:15 cventin kernel: microcode: microcode updated early to revision 0x49, date = 2021-08-11
May 24 14:12:15 cventin kernel: Linux version 5.17.0-2-amd64 ([email protected]) (gcc-11 (Debian 11.3.0-1) 11.3.0, GNU ld (GNU Binutils for Debian) 2.38) #1 SMP PREEMPT Debian 5.17.6-1 (2022-05-11)
[...]
May 24 14:12:16 cventin systemd[1]: Started Network Time Synchronization.
May 24 14:12:16 cventin systemd[1]: Reached target System Time Set.
May 24 14:12:22 cventin kernel: sr 2:0:0:0: Attached scsi generic sg0 type 5
May 24 14:12:22 cventin kernel: sr 3:0:0:0: Attached scsi generic sg1 type 5
May 24 14:12:22 cventin kernel: sd 6:0:0:0: Attached scsi generic sg2 type 0
[...]
May 24 14:12:23 cventin systemd[1]: Starting User Login Management...
May 24 14:12:23 cventin systemd[1]: Starting Disk Manager...
May 24 14:12:23 cventin udisksd[662]: udisks daemon version 2.9.4 starting
May 24 14:12:23 cventin systemd-logind[661]: New seat seat0.
[...]
May 24 14:12:23 cventin systemd[1]: Started User Login Management.
[...]
May 24 14:12:23 cventin systemd-logind[661]: Watching system buttons on /dev/input/event0 (Power Button)
May 24 14:12:23 cventin systemd-logind[661]: Watching system buttons on /dev/input/event1 (Power Button)
[...]
May 24 14:12:23 cventin systemd-logind[661]: Watching system buttons on /dev/input/event2 (DELL Dell USB Entry Keyboard)
[...]
May 24 14:12:27 cventin systemd[1]: Started Session c1 of User lightdm.
and everything was fine (but note the 6-second delay from 14:12:16 to 14:12:22, the above lines being consecutive in the logs, and I get exactly the same behavior with systemd 251 and the old systemd-udev-trigger.service file put under /etc/systemd/system).
With systemd 251-2, journalctl shows:
May 24 14:17:47 cventin kernel: microcode: microcode updated early to revision 0x49, date = 2021-08-11
May 24 14:17:47 cventin kernel: Linux version 5.17.0-2-amd64 ([email protected]) (gcc-11 (Debian 11.3.0-1) 11.3.0, GNU ld (GNU Binutils for Debian) 2.38) #1 SMP PREEMPT Debian 5.17.6-1 (2022-05-11)
[...]
May 24 14:17:47 cventin kernel: sr 2:0:0:0: Attached scsi generic sg0 type 5
May 24 14:17:47 cventin kernel: sr 3:0:0:0: Attached scsi generic sg1 type 5
May 24 14:17:47 cventin kernel: sd 6:0:0:0: Attached scsi generic sg2 type 0
[...]
May 24 14:17:47 cventin systemd[1]: Starting Network Time Synchronization...
May 24 14:17:47 cventin systemd[1]: Starting Record System Boot/Shutdown in UTMP...
May 24 14:17:47 cventin systemd[1]: Finished Record System Boot/Shutdown in UTMP.
May 24 14:17:47 cventin systemd[1]: Started Network Time Synchronization.
May 24 14:17:47 cventin systemd[1]: Reached target System Initialization.
May 24 14:17:47 cventin systemd[1]: Started CUPS Scheduler.
May 24 14:17:47 cventin systemd[1]: Started Daily Cleanup of Temporary Directories.
May 24 14:17:47 cventin systemd[1]: Reached target Path Units.
May 24 14:17:47 cventin systemd[1]: Reached target System Time Set.
May 24 14:17:47 cventin systemd[1]: Started Trigger anacron every hour.
[...]
May 24 14:17:48 cventin systemd[1]: Starting User Login Management...
May 24 14:17:48 cventin systemd[1]: Starting Disk Manager...
May 24 14:17:48 cventin udisksd[604]: udisks daemon version 2.9.4 starting
May 24 14:17:48 cventin systemd[1]: Started D-Bus System Message Bus.
May 24 14:17:48 cventin systemd-logind[603]: New seat seat0.
[...]
May 24 14:17:48 cventin systemd[1]: Started User Login Management.
[...]
May 24 14:17:52 cventin systemd[1]: Started Session c1 of User lightdm.
[...]
May 24 14:17:57 cventin systemd-logind[603]: Watching system buttons on /dev/input/event0 (Power Button)
May 24 14:17:57 cventin systemd-logind[603]: Watching system buttons on /dev/input/event1 (Power Button)
May 24 14:17:57 cventin systemd[1]: Listening on Load/Save RF Kill Switch Status /dev/rfkill Watch.
May 24 14:17:57 cventin systemd-logind[603]: Watching system buttons on /dev/input/event2 (DELL Dell USB Entry Keyboard)
and this time, the "Watching system buttons" lines appear 5 seconds after "Started Session c1 of User lightdm", and I suppose that this is related to the fact that the keyboard is useless during the first few seconds.
On the Xorg side, I could also notice an important delay after the switch to systemd 251.
2 tests with systemd 250:
[ 14.784]
X.Org X Server 1.21.1.3
[...]
[ 16.597] (II) config/udev: Adding input device DELL Dell USB Entry Keyboard (/dev/input/event2)
and
[ 15.005]
X.Org X Server 1.21.1.3
[...]
[ 16.818] (II) config/udev: Adding input device DELL Dell USB Entry Keyboard (/dev/input/event2)
(i.e. less than 2 seconds, which was fine).
2 tests with systemd 251:
[ 11.999]
X.Org X Server 1.21.1.3
[...]
[ 15.909] (II) config/udev: Adding input device DELL Dell USB Entry Keyboard (/dev/input/event2)
and
[ 7.688]
X.Org X Server 1.21.1.3
[ 14.644] (II) config/udev: Adding input device DELL Dell USB Entry Keyboard (/dev/input/event2)
(i.e. that's 4 to 7 seconds, which is too much in practice, but note that Xorg started earlier, presumably because the display manager started earlier, as mentioned above).
With a test I did on June 24 with systemd 251, journalctl shows:
Jun 24 17:21:16 cventin kernel: microcode: microcode updated early to revision 0x49, date = 2021-08-11
Jun 24 17:21:16 cventin kernel: Linux version 5.18.0-2-amd64 ([email protected]) (gcc-11 (Debian 11.3.0-3) 11.3.0, GNU ld (GNU Binutils for Debian) 2.38.50.20220615) #1 SMP PREEMPT_DYNAMIC Debian 5.18.5-1 (2022-06-16)
[...]
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: hid: raw HID events driver (C) Jiri Kosina
Jun 24 17:21:16 cventin kernel: usbcore: registered new interface driver usbhid
Jun 24 17:21:16 cventin kernel: usbhid: USB HID core driver
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: usb 2-8.1: new low-speed USB device number 4 using xhci_hcd
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
[...]
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[1]: Created slice User Slice of UID 118.
Jun 24 17:21:21 cventin systemd[1]: Starting User Runtime Directory /run/user/118...
Jun 24 17:21:21 cventin systemd-logind[606]: New session c1 of user lightdm.
Jun 24 17:21:21 cventin systemd[1]: Finished User Runtime Directory /run/user/118.
Jun 24 17:21:21 cventin systemd[1]: Starting User Manager for UID 118...
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-logind[606]: New session c1 of user lightdm.
[...]
Jun 24 17:21:21 cventin systemd[1]: Started Session c1 of User lightdm.
[...]
Jun 24 17:21:26 cventin systemd-logind[606]: Watching system buttons on /dev/input/event1 (Power Button)
Jun 24 17:21:26 cventin systemd-logind[606]: Watching system buttons on /dev/input/event0 (Power Button)
Jun 24 17:21:26 cventin systemd[1]: Listening on Load/Save RF Kill Switch Status /dev/rfkill Watch.
Jun 24 17:21:26 cventin systemd-logind[606]: Watching system buttons on /dev/input/event2 (DELL Dell USB Entry Keyboard)
(showing that the keyboard was detected by the kernel a fraction of second after the boot, but the systemd-logind lines "Watching system buttons on" appear only 10 seconds later).
I think that the real issue is related to the fact that the systemd-logind lines "Watching system buttons on" and udev's line "Adding input device DELL Dell USB Entry Keyboard" appear too late after the boot, whether I use systemd 250 or 251 (or 251 with an older systemd-udev-trigger.service file).
And I'm not sure about the component since the logs show a delay with both systemd-logind (in the journalctl output) and udev (in the Xorg logs).
FYI, the bug I had reported in the Debian BTS on May 24:
https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=1011523
Additional program output to the terminal or log subsystem illustrating the issue
No response