FS#78957 - [linux] usbguard Locks fingerprint reader after kernel update
Attached to Project:
Arch Linux
Opened by Ilario Gelmetti (ilario) - Monday, 03 July 2023, 10:56 GMT
Last edited by Toolybird (Toolybird) - Monday, 14 August 2023, 21:17 GMT
Opened by Ilario Gelmetti (ilario) - Monday, 03 July 2023, 10:56 GMT
Last edited by Toolybird (Toolybird) - Monday, 14 August 2023, 21:17 GMT
|
Details
Description:
After kernel upgrades, usbguard locks the fingerprint reader of a Lenovo ThinkPad X1 Carbon 2nd gen. as if it was a new device. In this case I have to reboot, as for some other unidentified bug (PAM or fprintd) I cannot unlock the Gnome screen lock with password. ``` $ lsusb -d 138a:0017 Bus 002 Device 002: ID 138a:0017 Validity Sensors, Inc. VFS 5011 fingerprint sensor ``` ``` # grep 138a:0017 /etc/usbguard/rules.conf [12:51:33] allow id 138a:0017 serial "9585d92de732" name "" hash "I42u56Qym91l9WYPg8wt7+lqHyWekuV0oMt0Urt15FA=" parent-hash "jEP/6WzviqdJ5VSeTUY8PatCNBKeaREvo2OqdplND/o=" with-interface ff:00:00 with-connect-type "not used" ``` Here some lines from journalctl: ``` $ journalctl --since "2023-07-03" | grep -i "usb\|fingerprint" Jul 03 08:40:48 iglaptop kernel: usb 2-6: new full-speed USB device number 2 using xhci_hcd Jul 03 08:40:48 iglaptop kernel: usb 2-6: New USB device found, idVendor=138a, idProduct=0017, bcdDevice= 0.78 Jul 03 08:40:48 iglaptop kernel: usb 2-6: New USB device strings: Mfr=0, Product=0, SerialNumber=1 Jul 03 08:40:48 iglaptop kernel: usb 2-6: SerialNumber: 9585d92de732 [...] Jul 03 08:40:50 iglaptop systemd[1]: Starting USBGuard D-Bus Service... Jul 03 08:40:50 iglaptop systemd[1]: Starting USBGuard daemon... [...] Jul 03 08:40:50 iglaptop usbguard-daemon[369]: uid=0 pid=359 result='SUCCESS' device.rule='allow id 138a:0017 serial "9585d92de732" name "" hash "I42u56Qym91l9WYPg8wt7+lqHyWekuV0oMt0Urt15FA=" parent-hash "jEP/6WzviqdJ5VSeTUY8PatCNBKeaREvo2OqdplND/o=" via-port "2-6" with-interface ff:00:00 with-connect-type "not used"' device.system_name='/devices/pci0000:00/0000:00:14.0/usb2/2-6' type='Device.Present' Jul 03 08:40:50 iglaptop usbguard-daemon[369]: uid=0 pid=359 result='SUCCESS' device.system_name='/devices/pci0000:00/0000:00:14.0/usb2/2-6' target.new='allow' device.rule='allow id 138a:0017 serial "9585d92de732" name "" hash "I42u56Qym91l9WYPg8wt7+lqHyWekuV0oMt0Urt15FA=" parent-hash "jEP/6WzviqdJ5VSeTUY8PatCNBKeaREvo2OqdplND/o=" via-port "2-6" with-interface ff:00:00 with-connect-type "not used"' target.old='allow' type='Policy.Device.Update' [...] Jul 03 08:40:50 iglaptop systemd[1]: Started USBGuard daemon. Jul 03 08:40:50 iglaptop systemd[1]: Started USBGuard D-Bus Service. Jul 03 08:40:54 iglaptop systemd[1]: Starting Fingerprint Authentication Daemon... Jul 03 08:40:54 iglaptop systemd[1]: Started Fingerprint Authentication Daemon. Jul 03 08:41:03 iglaptop kernel: usb 2-6: USB disconnect, device number 2 Jul 03 08:41:03 iglaptop usbguard-daemon[369]: uid=0 pid=359 result='SUCCESS' device.rule='allow id 138a:0017 serial "9585d92de732" name "" hash "I42u56Qym91l9WYPg8wt7+lqHyWekuV0oMt0Urt15FA=" parent-hash "jEP/6WzviqdJ5VSeTUY8PatCNBKeaREvo2OqdplND/o=" via-port "2-6" with-interface ff:00:00 with-connect-type "not used"' device.system_name='/devices/pci0000:00/0000:00:14.0/usb2/2-6' type='Device.Remove' Jul 03 08:41:04 iglaptop kernel: usb 2-6: new full-speed USB device number 4 using xhci_hcd Jul 03 08:41:04 iglaptop usbguard-daemon[369]: uid=0 pid=359 result='SUCCESS' device.rule='block id 138a:0017 serial "9585d92de732" name "" hash "I42u56Qym91l9WYPg8wt7+lqHyWekuV0oMt0Urt15FA=" parent-hash "jEP/6WzviqdJ5VSeTUY8PatCNBKeaREvo2OqdplND/o=" via-port "2-6" with-interface ff:00:00 with-connect-type "not used"' device.system_name='/devices/pci0000:00/0000:00:14.0/usb2/2-6' type='Device.Insert' Jul 03 08:41:04 iglaptop kernel: usb 2-6: New USB device found, idVendor=138a, idProduct=0017, bcdDevice= 0.78 Jul 03 08:41:04 iglaptop kernel: usb 2-6: New USB device strings: Mfr=0, Product=0, SerialNumber=1 Jul 03 08:41:04 iglaptop kernel: usb 2-6: SerialNumber: 9585d92de732 Jul 03 08:41:04 iglaptop kernel: usb 2-6: Device is not authorized for usage Jul 03 08:41:04 iglaptop kernel: usb 2-6: authorized to connect Jul 03 08:41:04 iglaptop usbguard-daemon[369]: uid=0 pid=359 result='SUCCESS' device.system_name='/devices/pci0000:00/0000:00:14.0/usb2/2-6' target.new='allow' device.rule='block id 138a:0017 serial "9585d92de732" name "" hash "I42u56Qym91l9WYPg8wt7+lqHyWekuV0oMt0Urt15FA=" parent-hash "jEP/6WzviqdJ5VSeTUY8PatCNBKeaREvo2OqdplND/o=" via-port "2-6" with-interface ff:00:00 with-connect-type "not used"' target.old='block' type='Policy.Device.Update' Jul 03 08:41:04 iglaptop usbguard-daemon[369]: Ignoring unknown UEvent action: sysfs_devpath=/devices/pci0000:00/0000:00:14.0/usb2/2-6 action=change Jul 03 08:41:04 iglaptop mtp-probe[933]: checking bus 2, device 4: "/sys/devices/pci0000:00/0000:00:14.0/usb2/2-6" Jul 03 08:41:04 iglaptop mtp-probe[934]: checking bus 2, device 4: "/sys/devices/pci0000:00/0000:00:14.0/usb2/2-6" Jul 03 08:41:04 iglaptop fprintd[790]: libusb: error [udev_hotplug_event] ignoring udev action change Jul 03 08:41:08 iglaptop systemd[905]: Starting GNOME USB protection service... Jul 03 08:41:08 iglaptop systemd[905]: Started GNOME USB protection service. Jul 03 08:41:08 iglaptop systemd[905]: Reached target GNOME USB protection target. Jul 03 08:41:08 iglaptop dbus-daemon[927]: [session uid=1000 pid=927] Activating service name='org.gnome.ScreenSaver' requested by ':1.50' (uid=1000 pid=1279 comm="/usr/lib/gsd-usb-protection") [[[HERE I LOCKED THE SCREEN AND UNLOCKED IT USING THE FINGERPRINT]]] Jul 03 10:02:27 iglaptop systemd[1]: Starting Fingerprint Authentication Daemon... Jul 03 10:02:27 iglaptop systemd[1]: Started Fingerprint Authentication Daemon. [[[HERE I START THE SYSTEM UPGRADE WHICH INCLUDED A KERNEL UPGRADE]]] Jul 03 10:10:10 iglaptop systemd[1]: Starting Fingerprint Authentication Daemon... Jul 03 10:10:10 iglaptop systemd[1]: Started Fingerprint Authentication Daemon. [[[THE FINGERPRINT READER WORKED FOR SUDO]]] Jul 03 10:12:45 iglaptop systemd[1]: Starting Fingerprint Authentication Daemon... Jul 03 10:12:45 iglaptop systemd[1]: Started Fingerprint Authentication Daemon. Jul 03 10:17:22 iglaptop usbguard-daemon[369]: Ignoring unknown UEvent action: sysfs_devpath=/devices/pci0000:00/0000:00:14.0/usb2 action=change Jul 03 10:17:22 iglaptop usbguard-daemon[369]: Ignoring unknown UEvent action: sysfs_devpath=/devices/pci0000:00/0000:00:14.0/usb2/2-0:1.0 action=change Jul 03 10:17:22 iglaptop usbguard-daemon[369]: Ignoring unknown UEvent action: sysfs_devpath=/devices/pci0000:00/0000:00:14.0/usb2/2-6 action=change Jul 03 10:17:22 iglaptop usbguard-daemon[369]: Ignoring unknown UEvent action: sysfs_devpath=/devices/pci0000:00/0000:00:14.0/usb2/2-6/2-6:1.0 action=change Jul 03 10:17:22 iglaptop usbguard-daemon[369]: Ignoring unknown UEvent action: sysfs_devpath=/devices/pci0000:00/0000:00:14.0/usb3 action=change Jul 03 10:17:22 iglaptop usbguard-daemon[369]: Ignoring unknown UEvent action: sysfs_devpath=/devices/pci0000:00/0000:00:14.0/usb3/3-0:1.0 action=change Jul 03 10:17:22 iglaptop usbguard-daemon[369]: Ignoring unknown UEvent action: sysfs_devpath=/devices/pci0000:00/0000:00:1d.0/usb1 action=change Jul 03 10:17:22 iglaptop usbguard-daemon[369]: Ignoring unknown UEvent action: sysfs_devpath=/devices/pci0000:00/0000:00:1d.0/usb1/1-0:1.0 action=change Jul 03 10:17:22 iglaptop usbguard-daemon[369]: Ignoring unknown UEvent action: sysfs_devpath=/devices/pci0000:00/0000:00:1d.0/usb1/1-1 action=change Jul 03 10:17:22 iglaptop usbguard-daemon[369]: Ignoring unknown UEvent action: sysfs_devpath=/devices/pci0000:00/0000:00:1d.0/usb1/1-1/1-1.8 action=change Jul 03 10:17:22 iglaptop usbguard-daemon[369]: Ignoring unknown UEvent action: sysfs_devpath=/devices/pci0000:00/0000:00:1d.0/usb1/1-1/1-1.8/1-1.8:1.0 action=change Jul 03 10:17:22 iglaptop usbguard-daemon[369]: Ignoring unknown UEvent action: sysfs_devpath=/devices/pci0000:00/0000:00:1d.0/usb1/1-1/1-1.8/1-1.8:1.1 action=change Jul 03 10:17:22 iglaptop usbguard-daemon[369]: Ignoring unknown UEvent action: sysfs_devpath=/devices/pci0000:00/0000:00:1d.0/usb1/1-1/1-1:1.0 action=change [[[HERE I LOCK THE SCREEN USING THE GNOME SCREEN LOCKER]]] Jul 03 11:16:04 iglaptop systemd[1]: Starting Fingerprint Authentication Daemon... Jul 03 11:16:04 iglaptop systemd[1]: Started Fingerprint Authentication Daemon. Jul 03 11:16:06 iglaptop kernel: usb 2-6: USB disconnect, device number 4 Jul 03 11:16:06 iglaptop usbguard-daemon[369]: uid=0 pid=359 result='SUCCESS' device.rule='allow id 138a:0017 serial "9585d92de732" name "" hash "I42u56Qym91l9WYPg8wt7+lqHyWekuV0oMt0Urt15FA=" parent-hash "jEP/6WzviqdJ5VSeTUY8PatCNBKeaREvo2OqdplND/o=" via-port "2-6" with-interface ff:00:00 with-connect-type "not used"' device.system_name='/devices/pci0000:00/0000:00:14.0/usb2/2-6' type='Device.Remove' Jul 03 11:16:07 iglaptop kernel: usb 2-6: new full-speed USB device number 5 using xhci_hcd Jul 03 11:16:07 iglaptop usbguard-daemon[369]: uid=0 pid=359 result='SUCCESS' device.rule='block id 138a:0017 serial "9585d92de732" name "" hash "I42u56Qym91l9WYPg8wt7+lqHyWekuV0oMt0Urt15FA=" parent-hash "jEP/6WzviqdJ5VSeTUY8PatCNBKeaREvo2OqdplND/o=" via-port "2-6" with-interface ff:00:00 with-connect-type "not used"' device.system_name='/devices/pci0000:00/0000:00:14.0/usb2/2-6' type='Device.Insert' Jul 03 11:16:07 iglaptop usbguard-daemon[369]: uid=0 pid=359 result='SUCCESS' device.system_name='/devices/pci0000:00/0000:00:14.0/usb2/2-6' target.new='block' device.rule='block id 138a:0017 serial "9585d92de732" name "" hash "I42u56Qym91l9WYPg8wt7+lqHyWekuV0oMt0Urt15FA=" parent-hash "jEP/6WzviqdJ5VSeTUY8PatCNBKeaREvo2OqdplND/o=" via-port "2-6" with-interface ff:00:00 with-connect-type "not used"' target.old='block' type='Policy.Device.Update' Jul 03 11:16:07 iglaptop kernel: usb 2-6: New USB device found, idVendor=138a, idProduct=0017, bcdDevice= 0.78 Jul 03 11:16:07 iglaptop kernel: usb 2-6: New USB device strings: Mfr=0, Product=0, SerialNumber=1 Jul 03 11:16:07 iglaptop kernel: usb 2-6: SerialNumber: 9585d92de732 Jul 03 11:16:07 iglaptop kernel: usb 2-6: Device is not authorized for usage Jul 03 11:16:07 iglaptop mtp-probe[19880]: checking bus 2, device 5: "/sys/devices/pci0000:00/0000:00:14.0/usb2/2-6" Jul 03 11:16:07 iglaptop mtp-probe[19881]: checking bus 2, device 5: "/sys/devices/pci0000:00/0000:00:14.0/usb2/2-6" Jul 03 11:16:51 iglaptop systemd[1]: Starting Fingerprint Authentication Daemon... Jul 03 11:16:51 iglaptop systemd[1]: Started Fingerprint Authentication Daemon. [[[AS THE FINGERPRINT READER GOT BLOCKED BY USBGUARD, 3 CONSECUTIVE LOGIN FAILURES ARE DETECTED]]] Jul 03 11:16:51 iglaptop gdm-fingerprint][19923]: pam_faillock(gdm-fingerprint:auth): Consecutive login failures for user ilario account temporarily locked ``` Additional info: * usbguard 1.1.2-1 from Extra repository * kernel 6.4.1.arch1-1 Steps to reproduce: Update the kernel using pacman, lock the screen, try to unlock using the fingerprint reader. |
This task depends upon
Closed by Toolybird (Toolybird)
Monday, 14 August 2023, 21:17 GMT
Reason for closing: Not a bug
Additional comments about closing: See comments
Monday, 14 August 2023, 21:17 GMT
Reason for closing: Not a bug
Additional comments about closing: See comments
Which strongly indicates it's a kernel regression. General advice for debugging kernel regressions [1]. You'll have better luck reporting this upstream to the kernel folks...maybe also talk to the usbguard folks. Please let us know what you find out.
[1] https://wiki.archlinux.org/title/Kernel#Debugging_regressions
It is not a kernel regression as once rebooted USBguard worked perfectly again (or at least didn't block my fingerprint reader when locking the screen).
As soon as a new kernel update arrives, I will try to reproduce and post here. To prove that the problem is the limbo status that happens after an update (e.g. new modules cannot be loaded because the current kernel do not find them where expected, as they got deleted and replaced by the ones from the new kernel, or something like that, just throwing (unrelated) hypotheses).
So the title should be updated.
I have no idea anymore about what triggers this.
Some logs:
```
$ journalctl --since "2023-07-07" | grep -i "usb\|fingerprint"
[...]
Jul 07 12:11:36 iglaptop systemd[1]: Starting Fingerprint Authentication Daemon...
Jul 07 12:11:36 iglaptop systemd[1]: Started Fingerprint Authentication Daemon.
Jul 07 12:11:40 iglaptop gdm-fingerprint][28998]: pam_faillock(gdm-fingerprint:auth): Consecutive login failures for user ilario account temporarily locked
Jul 07 12:12:54 iglaptop kernel: usb 2-6: USB disconnect, device number 2
Jul 07 12:12:54 iglaptop usbguard-daemon[372]: uid=0 pid=357 result='SUCCESS' device.rule='allow id 138a:0017 serial "9585d92de732" name "" hash "I42u56Qym91l9WYPg8wt7+lqHyWekuV0oMt0Urt15FA=" parent-hash "jEP/6WzviqdJ5VSeTUY8PatCNBKeaREvo2OqdplND/o=" via-port "2-6" with-interface ff:00:00 with-connect-type "not used"' device.system_name='/devices/pci0000:00/0000:00:14.0/usb2/2-6' type='Device.Remove'
Jul 07 12:12:54 iglaptop kernel: usb 2-6: new full-speed USB device number 4 using xhci_hcd
Jul 07 12:12:54 iglaptop kernel: usb 2-6: New USB device found, idVendor=138a, idProduct=0017, bcdDevice= 0.78
Jul 07 12:12:54 iglaptop kernel: usb 2-6: New USB device strings: Mfr=0, Product=0, SerialNumber=1
Jul 07 12:12:54 iglaptop kernel: usb 2-6: SerialNumber: 9585d92de732
Jul 07 12:12:54 iglaptop kernel: usb 2-6: Device is not authorized for usage
Jul 07 12:12:54 iglaptop usbguard-daemon[372]: uid=0 pid=357 result='SUCCESS' device.rule='block id 138a:0017 serial "9585d92de732" name "" hash "I42u56Qym91l9WYPg8wt7+lqHyWekuV0oMt0Urt15FA=" parent-hash "jEP/6WzviqdJ5VSeTUY8PatCNBKeaREvo2OqdplND/o=" via-port "2-6" with-interface ff:00:00 with-connect-type "not used"' device.system_name='/devices/pci0000:00/0000:00:14.0/usb2/2-6' type='Device.Insert'
Jul 07 12:12:54 iglaptop usbguard-daemon[372]: uid=0 pid=357 result='SUCCESS' device.system_name='/devices/pci0000:00/0000:00:14.0/usb2/2-6' target.new='block' device.rule='block id 138a:0017 serial "9585d92de732" name "" hash "I42u56Qym91l9WYPg8wt7+lqHyWekuV0oMt0Urt15FA=" parent-hash "jEP/6WzviqdJ5VSeTUY8PatCNBKeaREvo2OqdplND/o=" via-port "2-6" with-interface ff:00:00 with-connect-type "not used"' target.old='block' type='Policy.Device.Update'
```
> the limbo status that happens after an update (e.g. new modules cannot be loaded because the current kernel do not find them where expected, as they got deleted and replaced by the ones from the new kernel
If that is indeed what is happening then unfortunately it cannot be fixed. The general Arch advice is *always* reboot after installing a new kernel. It's simply asking for trouble if you don't. Either that, or hold back installation of the new kernel until you're ready to reboot e.g.
$ sudo pacman -Syu --ignore linux
I observed this many other times when I did not update the kernel nor did any update at all.
So I would edit the title of the bug but seems that I cannot.
The bug seems to happen at random times.
Looks like the USB fingerprint reader gets "disconnected and reconnected" (virtually, as it is integrated in the case of the Lenovo X1 Carbon 2nd gen) when it does not work properly, and this triggers usb-guard.
I attach here some more logs where you can see the "kernel: usb 2-6: USB disconnect, device number 2" at 10:46:58:
```
Aug 14 10:46:54 iglaptop dbus-daemon[388]: [system] Activating via systemd: service name='net.reactivated.Fprint' unit='fprintd.service' requested by ':1.53' (uid=1000 pid=1285 comm="/usr/bin/gnome-shell")
Aug 14 10:46:54 iglaptop systemd[1]: Starting Fingerprint Authentication Daemon...
Aug 14 10:46:54 iglaptop dbus-daemon[388]: [system] Successfully activated service 'net.reactivated.Fprint'
Aug 14 10:46:54 iglaptop systemd[1]: Started Fingerprint Authentication Daemon.
Aug 14 10:46:56 iglaptop fprintd[8292]: Authorization denied to :1.125 to call method 'Claim' for device 'Validity VFS5011': Device was already claimed
Aug 14 10:46:58 iglaptop fprintd[8292]: Authorization denied to :1.129 to call method 'Claim' for device 'Validity VFS5011': Device was already claimed
Aug 14 10:46:58 iglaptop gdm-fingerprint][8343]: pam_faillock(gdm-fingerprint:auth): Consecutive login failures for user ilario account temporarily locked
Aug 14 10:46:58 iglaptop dbus-daemon[388]: [system] Activating via systemd: service name='org.freedesktop.home1' unit='dbus-org.freedesktop.home1.service' requested by ':1.130' (uid=0 pid=8342 comm="gdm-session-worker [pam/gdm-password]")
Aug 14 10:46:58 iglaptop dbus-daemon[388]: [system] Activation via systemd failed for unit 'dbus-org.freedesktop.home1.service': Unit dbus-org.freedesktop.home1.service not found.
Aug 14 10:46:58 iglaptop kernel: usb 2-6: USB disconnect, device number 2
Aug 14 10:46:58 iglaptop usbguard-daemon[432]: uid=0 pid=397 result='SUCCESS' device.rule='allow id 138a:0017 serial "9585d92de732" name "" hash "I42u56Qym91l9WYPg8wt7+lqHyWekuV0oMt0Urt15FA=" parent-hash "jEP/6WzviqdJ5VSeTUY8PatCNBKeaREvo2OqdplND/o=" via-port "2-6" with-interface ff:00:00 with-connect-type "not used"' device.system_name='/devices/pci0000:00/0000:00:14.0/usb2/2-6' type='Device.Remove'
Aug 14 10:46:58 iglaptop kernel: usb 2-6: new full-speed USB device number 6 using xhci_hcd
Aug 14 10:46:58 iglaptop usbguard-daemon[432]: uid=0 pid=397 result='SUCCESS' device.rule='block id 138a:0017 serial "9585d92de732" name "" hash "I42u56Qym91l9WYPg8wt7+lqHyWekuV0oMt0Urt15FA=" parent-hash "jEP/6WzviqdJ5VSeTUY8PatCNBKeaREvo2OqdplND/o=" via-port "2-6" with-interface ff:00:00 with-connect-type "not used"' device.system_name='/devices/pci0000:00/0000:00:14.0/usb2/2-6' type='Device.Insert'
Aug 14 10:46:58 iglaptop usbguard-daemon[432]: uid=0 pid=397 result='SUCCESS' device.system_name='/devices/pci0000:00/0000:00:14.0/usb2/2-6' target.new='block' device.rule='block id 138a:0017 serial "9585d92de732" name "" hash "I42u56Qym91l9WYPg8wt7+lqHyWekuV0oMt0Urt15FA=" parent-hash "jEP/6WzviqdJ5VSeTUY8PatCNBKeaREvo2OqdplND/o=" via-port "2-6" with-interface ff:00:00 with-connect-type "not used"' target.old='block' type='Policy.Device.Update'
Aug 14 10:46:58 iglaptop kernel: usb 2-6: New USB device found, idVendor=138a, idProduct=0017, bcdDevice= 0.78
Aug 14 10:46:58 iglaptop kernel: usb 2-6: New USB device strings: Mfr=0, Product=0, SerialNumber=1
Aug 14 10:46:58 iglaptop kernel: usb 2-6: SerialNumber: 9585d92de732
Aug 14 10:46:58 iglaptop kernel: usb 2-6: Device is not authorized for usage
```
Yeah, that seems like the root cause. Maybe it's a power saving related buglet in the kernel drivers? Or maybe even a hardware issue? Either way, this doesn't appear to be an Arch packaging issue. I recommend you take this to the proper Arch support channels (Forum/IRC/Mailing Lists/Rediit/etc) to see if anyone can assist with troubleshooting. If it turns out to be a kernel issue then of course it will need to be reported upstream.