Strange issue with open-fprintd-resume.service

[VorpalBlade]

After waking my laptop from suspend to RAM today the fingerprint reader failed to work. Normally open-fprintd-resume.service takes care of that. I connected with ssh from another computer and got the following log from journald:

okt 27 13:36:31 athena open-fprintd[2313]: DEBUG:root:Resume
okt 27 13:36:31 athena python3[1877]: DEBUG:root:In Resume
okt 27 13:36:31 athena python3[1877]: DEBUG:root:>cmd> 3e
okt 27 13:36:31 athena python3[1877]: DEBUG:root:<cmd< 0000ef00400000100100000101000500010407000010000000100000020102000020000000e00300050503000000040000800000060603000080040000800000040305000000050000000800
okt 27 13:36:31 athena python3[1877]: INFO:root:Flash has 5 partitions.
okt 27 13:36:31 athena python3[1877]: DEBUG:root:>cmd> 01
okt 27 13:36:31 athena python3[1877]: DEBUG:root:<cmd< 0000f0b05e54a40000000607013000010000beb78b6869dc0023000000000100000003d10007
okt 27 13:36:31 athena python3[1877]: DEBUG:root:>cmd> 19
okt 27 13:36:31 athena python3[1877]: DEBUG:root:<cmd< 0000000301020001000000000000000000000000d045e1990000000000000000000000000000000000000000000000000000000000000000000000000000000000000000
okt 27 13:36:31 athena python3[1877]: DEBUG:root:>cmd> 4302
okt 27 13:36:31 athena kernel: usb 1-9: usbfs: process 1877 (python3) did not claim interface 0 before use
okt 27 13:36:31 athena python3[1877]: DEBUG:root:<cmd< 0000010002000800e9832e5e0100344602000700e04200000100840801000700800600000200842803001200401000000200763601000c00000a00000100864700000100505a00000200237700000100c02f000002000037000001>
okt 27 13:36:31 athena python3[1877]: DEBUG:root:>cmd> 06020000014a231406e5542fc6dc3b1aedebe68f55596ad3ca13f6e019994c6f71672fff756fbde0511d09d45978b12ba415b3694a0e76348c8cfe9dbb9abf86813fc0c67c1005519a6f87360c2fb3e12bd0a9e012b06d9f5c9b44>
okt 27 13:36:31 athena python3[1877]: DEBUG:root:<cmd< 0000
okt 27 13:36:31 athena python3[1877]: DEBUG:root:>cmd> 40010100000000000000100000
okt 27 13:36:31 athena python3[1877]: DEBUG:root:<cmd< 0000001000000000000001006e340b9cffb37a989ca544e6bb780a2c78901d3fb33738768511a30617afa01d000400a100fb95b7f218dab8e6870443902769a602babb56d80988909014dc097d9602ee110299e4caa0ee071bfc6d>
okt 27 13:36:31 athena python3[1877]: DEBUG:root:>cmd> 44000000160303004501000041030399a87b7b54e87899c76b6a47dfe7510e063d89448ef05b482578f86261426adb07000000000000000006c005003d008d00000a000400020017000b00020100
okt 27 13:36:31 athena python3[1877]: DEBUG:root:<cmd< 160303003d0200002d0303000a82fd4568ec3489b898ee677381828302d7922981b1bae88b5a3a29dec71707544c534568ec34c005000d000004014000000e000000
okt 27 13:36:31 athena python3[1877]: DEBUG:root:>cmd> 4400000016030301530b0000c00000b80000b8ac1617000000200000003282fcf77645ed98e1fa9aef0e9d5e1ba67d7dc80fd559a646947fbe731c7e05000000000000000000000000000000000000000000000000000000000000>
okt 27 13:36:31 athena python3[1877]: DEBUG:root:<cmd< 1503030002022f
okt 27 13:36:32 athena resume.py[18671]: Traceback (most recent call last):
okt 27 13:36:32 athena resume.py[18671]:   File "/usr/lib/open-fprintd/resume.py", line 11, in <module>
okt 27 13:36:32 athena resume.py[18671]:     o.Resume()
okt 27 13:36:32 athena resume.py[18671]:   File "/usr/lib/python3/dist-packages/dbus/proxies.py", line 141, in __call__
okt 27 13:36:32 athena resume.py[18671]:     return self._connection.call_blocking(self._named_service,
okt 27 13:36:32 athena resume.py[18671]:   File "/usr/lib/python3/dist-packages/dbus/connection.py", line 652, in call_blocking
okt 27 13:36:32 athena resume.py[18671]:     reply_message = self.send_message_with_reply_and_block(
okt 27 13:36:32 athena resume.py[18671]: dbus.exceptions.DBusException: org.freedesktop.DBus.Python.Exception: Traceback (most recent call last):
okt 27 13:36:32 athena resume.py[18671]:   File "/usr/lib/python3/dist-packages/dbus/service.py", line 711, in _message_cb
okt 27 13:36:32 athena resume.py[18671]:     retval = candidate_method(self, *args, **keywords)
okt 27 13:36:32 athena resume.py[18671]:   File "/usr/lib/python-validity/dbus-service", line 73, in Resume
okt 27 13:36:32 athena resume.py[18671]:     init.open_common()
okt 27 13:36:32 athena resume.py[18671]:   File "/usr/lib/python3/dist-packages/validitysensor/init.py", line 32, in open_common
okt 27 13:36:32 athena resume.py[18671]:     tls.open()
okt 27 13:36:32 athena resume.py[18671]:   File "/usr/lib/python3/dist-packages/validitysensor/tls.py", line 144, in open
okt 27 13:36:32 athena resume.py[18671]:     self.parse_tls_response(rsp)
okt 27 13:36:32 athena resume.py[18671]:   File "/usr/lib/python3/dist-packages/validitysensor/tls.py", line 366, in parse_tls_response
okt 27 13:36:32 athena resume.py[18671]:     raise Exception('Dont know how to handle message type %02x' % t)
okt 27 13:36:32 athena resume.py[18671]: Exception: Dont know how to handle message type 15
okt 27 13:36:32 athena systemd[1]: open-fprintd-resume.service: Main process exited, code=exited, status=1/FAILURE
okt 27 13:36:32 athena systemd[1]: open-fprintd-resume.service: Failed with result 'exit-code'.
okt 27 13:36:32 athena systemd[1]: Failed to start Restart devices after resume.

Restarting this service on it's own did not help, I had to restart the main open-fprintd.service to get it to work.

I could not reproduce the issue by putting the laptop back to suspend and resuming it (the laptop hang and didn't want to resume at all). After a reboot I could not reproduce the issue at all. Thus, it seems like the system was in a "weird state" overall, and thus perhaps nothing to care about.

However, this issue completely blocked login. It would not fall back to a password prompt (either in gdm or in the VTs). If I had not been at home and had access to ssh login via another computer this would have forced me to reboot without the ability of saving my work first. Thus I believe it would be a good idea to fail gracefully in a situation like this, if the issue itself cannot be corrected.

Software and hardware

• Thinkpad T480
• Sensor: According to lsusb: Bus 001 Device 004: ID 06cb:009a Synaptics, Inc.
• Ubuntu 20.04

# apt show open-fprintd 
Package: open-fprintd
Version: 0.6~ppa1
Priority: optional
Section: admin
Maintainer: uunicorn <[email protected]>
Installed-Size: 58,4 kB
Depends: python3:any (>= 3.6~), python3-dbus, dbus
Conflicts: fprintd
Breaks: fprintd
Replaces: fprintd
Download-Size: 6 916 B
APT-Manual-Installed: yes
APT-Sources: http://ppa.launchpad.net/uunicorn/open-fprintd/ubuntu focal/main amd64 Packages
Description: Open fprintd DBus service.
 This package lets you integrate fingerprint driver backends with the rest of
 the system.
 .
 Warning: this is an experimental software. It lacks proper auth checks.
 Install and use at your own risk.

# apt show python3-validity 
Package: python3-validity
Version: 0.13~ppa1
Priority: optional
Section: misc
Source: python-validity
Maintainer: uunicorn <[email protected]>
Installed-Size: 452 kB
Depends: python3-cryptography, python3-usb, python3-yaml, python3:any (>= 3.6~), python3-dbus, dbus, open-fprintd (>= 0.6~), innoextract (>= 1.6~)
Download-Size: 74,3 kB
APT-Manual-Installed: yes
APT-Sources: http://ppa.launchpad.net/uunicorn/open-fprintd/ubuntu focal/main amd64 Packages
Description: Validity Fingerprint Sensor DBus Driver
 This package adds support to some Validity sensors.
 .
 Warning: this is an experimental software. It lacks proper auth checks.
 Install and use at your own risk.

[l4pa]

something isn't right with 06cb:009a, see
uunicorn/python-validity#106
#12

[VorpalBlade]

Interesting note: On Ubuntu 20.04 LTS it only happened occasionally. I have since switched to using Arch Linux on that laptop. It now happens every time.