Bug 1832229 - Regression: 0483:2016 STMicroelectronics Fingerprint Reader (UPEK) no longer works
Summary: Regression: 0483:2016 STMicroelectronics Fingerprint Reader (UPEK) no longer...
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: Fedora
Classification: Fedora
Component: libfprint
Version: 32
Hardware: x86_64
OS: Linux
unspecified
high
Target Milestone: ---
Assignee: Benjamin Berg
QA Contact: Fedora Extras Quality Assurance
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2020-05-06 11:12 UTC by Alex Smirnoff
Modified: 2020-08-01 06:21 UTC (History)
4 users (show)

Fixed In Version: libfprint-1.90.2-1.fc32
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed: 2020-06-22 08:10:02 UTC
Type: Bug


Attachments (Terms of Use)
fprintd debug log (23.17 KB, text/plain)
2020-05-07 16:34 UTC, Alex Smirnoff
no flags Details
more log from fc30 package (11.96 KB, text/plain)
2020-05-09 18:30 UTC, Alex Smirnoff
no flags Details
this one when it worked (34.70 KB, text/plain)
2020-05-09 18:31 UTC, Alex Smirnoff
no flags Details

Description Alex Smirnoff 2020-05-06 11:12:46 UTC
Description of problem:

After upgrade fc30 -> fc32, the fingerprint reader lost the enrolled fingerprint and is unable to enroll a new one.

Version-Release number of selected component (if applicable):

fprintd-1.90.1-1.fc32.x86_64

How reproducible:

Always

Steps to Reproduce:
1. fprintd-list `id -un`
2. fprintd-enroll

Actual results:

1.  ▲ ~ fprintd-list `id -un`                                                     
found 1 devices
Device at /net/reactivated/Fprint/Device/0
Using device /net/reactivated/Fprint/Device/0
User ark has no fingers enrolled for UPEK TouchStrip.

2.  
▲ ~ fprintd-enroll                                                            
Using device /net/reactivated/Fprint/Device/0
failed to claim device: Open failed with error: transfer timed out

▲ ~ sudo /usr/libexec/fprintd -t                                                                                                                          

(fprintd:343450): libfprint-upekts-CRITICAL **: 22:15:48.449: async msg read failed: transfer timed out

Expected results:

1. Pre-enrolled fingerprint should be visible in the list
2. A new fingerprint should be enrolled successfully.

Additional info:

also there is mate-about-me bug: https://bugzilla.redhat.com/show_bug.cgi?id=1831122

Comment 1 Benjamin Berg 2020-05-06 11:28:18 UTC
Probably a small regression in the driver port.

Please run with G_MESSAGES_DEBUG=all and paste the output.

Comment 2 Alex Smirnoff 2020-05-06 19:54:25 UTC
this happends when I do fprintd-list:

(fprintd:3926593): fprintd-DEBUG: 22:51:49.266: D-Bus service launched with name: net.reactivated.Fprint
(fprintd:3926593): fprintd-DEBUG: 22:51:49.266: entering main loop
(fprintd:3926593): fprintd-DEBUG: 22:52:09.989: file_storage_discover_prints() for user 'ark' in '/var/lib/fprint/ark/upekts/0'
(fprintd:3926593): fprintd-DEBUG: 22:52:09.989: scan_dev_storedir(): opendir("/var/lib/fprint/ark/upekts/0") failed: Error opening directory “/var/lib/fprint/ark/upekts/0”: No such file or directory

and this is for fprintd-enroll:

(fprintd:3926593): fprintd-DEBUG: 22:52:46.922: user 'ark' claiming the device: 0
(fprintd:3926593): libfprint-SSM-DEBUG: 22:52:46.922: [upekts] INITSM_NUM_STATES entering state 0
(fprintd:3926593): libfprint-SSM-DEBUG: 22:52:46.924: [upekts] INITSM_NUM_STATES entering state 1
(fprintd:3926593): libfprint-upekts-DEBUG: 22:52:46.925: A=03 B=00 len=5
(fprintd:3926593): libfprint-upekts-DEBUG: 22:52:46.925: cmd 3 from device to driver
(fprintd:3926593): libfprint-SSM-DEBUG: 22:52:46.925: [upekts] INITSM_NUM_STATES entering state 2
(fprintd:3926593): libfprint-upekts-DEBUG: 22:52:46.925: seq=14 subcmd=04 with 8 bytes of data
(fprintd:3926593): libfprint-SSM-DEBUG: 22:52:46.926: [upekts] INITSM_NUM_STATES entering state 3

(fprintd:3926593): libfprint-upekts-CRITICAL **: 22:52:51.928: async msg read failed: transfer timed out
(fprintd:3926593): libfprint-SSM-DEBUG: 22:52:51.928: [upekts] SSM INITSM_NUM_STATES failed in state 3 with error: transfer timed out
(fprintd:3926593): libfprint-SSM-DEBUG: 22:52:51.928: [upekts] INITSM_NUM_STATES completed with error: transfer timed out
(fprintd:3926593): libfprint-device-DEBUG: 22:52:51.928: Device reported open completion
(fprintd:3926593): libfprint-device-DEBUG: 22:52:51.928: Completing action 2 in idle!

Comment 3 Benjamin Berg 2020-05-07 08:08:36 UTC
OK, with that it was obvious. A rather simple regression after major internal APIs changes :)

I have two requests for you:

 1. Could you please try the scratch build: https://koji.fedoraproject.org/koji/taskinfo?taskID=44184507
 2. To prevent future problems, I would like to add upekts to the regression test suite. However, I don't have a device. Are you willing to record the USB traffic of an enroll+verify operation.

Request 2. means that the raw information from the device about the scanned print is captured and public. We don't know the format, but my suggestion is to not use your fingerprint as usual but some other skin (e.g. side of finger, palm, or even arm).

Point 2. should not be that complicated, but it would be helpful if your are more experienced overall :)

Comment 4 Alex Smirnoff 2020-05-07 16:34:45 UTC
Created attachment 1686238 [details]
fprintd debug log

Now I get another type of error!

△ ~ fprintd-enroll                                                            
Using device /net/reactivated/Fprint/Device/0
Enrolling right-index-finger finger.
Enroll result: enroll-stage-passed
Enroll result: enroll-unknown-error
ReleaseDevice failed: Release failed with error: transfer timed out

Comment 5 Benjamin Berg 2020-05-07 17:28:13 UTC
So, I did find a few more issues, but just in the error path after the enroll failure.

Just to make sure, did you try this only once or multiple times? I just want to make sure this is not an old rare failure that we might randomly hit depending on the user's interaction with the fingerprint reader.

Comment 6 Alex Smirnoff 2020-05-07 19:07:31 UTC
I tried several times and seems that it behaves even weirder than I thought! After a swipe I usually see "Enroll result: enroll-stage-passed" and the data continues to flow; on a subsequent swipe it crashes -- mostly like that time with the log, but occasionally the error could be different, like:

(fprintd:1620882): libfprint-upekts-DEBUG: 22:00:32.061: A=00 B=f0 len=20
(fprintd:1620882): libfprint-upekts-DEBUG: 22:00:32.061: device responds to subcmd 0 with 14 bytes
(fprintd:1620882): libfprint-upekts-DEBUG: 22:00:32.062: poll result = 00
(fprintd:1620882): libfprint-upekts-DEBUG: 22:00:32.062: seq=00 subcmd=00 with 2 bytes of data
(fprintd:1620882): libfprint-upekts-DEBUG: 22:00:32.958: didn't fit in buffer, need to extend by 92 bytes
(fprintd:1620882): libfprint-upekts-DEBUG: 22:00:32.960: A=00 B=00 len=147
(fprintd:1620882): libfprint-upekts-DEBUG: 22:00:32.960: device responds to subcmd 2 with 141 bytes
(fprintd:1620882): libfprint-SSM-DEBUG: 22:00:32.960: [upekts] DEINITSM_NUM_STATES entering state 0
(fprintd:1620882): libfprint-upekts-DEBUG: 22:00:32.960: seq=07 len=1
double free or corruption (!prev)

apparently I need to swipe three times, but if a swipe cannot be read, it crashes instead of retry.

another type of error:

(fprintd:1619448): libfprint-upekts-DEBUG: 21:59:54.929: device responds to subcmd 2 with 1 bytes

(fprintd:1619448): libfprint-upekts-CRITICAL **: 21:59:54.929: fingerprint data too short (1 bytes)

(fprintd:1619448): GLib-GObject-CRITICAL **: 21:59:54.929: g_object_ref: assertion 'G_IS_OBJECT (object)' failed
(fprintd:1619448): libfprint-SSM-DEBUG: 21:59:54.929: [upekts] DEINITSM_NUM_STATES entering state 0
(fprintd:1619448): libfprint-upekts-DEBUG: 21:59:54.929: seq=07 len=1
(fprintd:1619448): libfprint-SSM-DEBUG: 21:59:54.929: [upekts] DEINITSM_NUM_STATES entering state 1
(fprintd:1619448): libfprint-upekts-DEBUG: 21:59:54.930: A=01 B=00 len=0
(fprintd:1619448): libfprint-upekts-DEBUG: 21:59:54.930: cmd 1 from device to driver
(fprintd:1619448): libfprint-SSM-DEBUG: 21:59:54.930: [upekts] DEINITSM_NUM_STATES completed successfully
(fprintd:1619448): libfprint-device-DEBUG: 21:59:54.930: Device reported enroll completion
(fprintd:1619448): libfprint-device-DEBUG: 21:59:54.931: Completing action 4 in idle!
(fprintd:1619448): fprintd-DEBUG: 21:59:54.931: enroll_cb: result enroll-unknown-error

(fprintd:1619448): fprintd-WARNING **: 21:59:54.931: Device reported an error during enroll: (null)

sometimes I successfully get "swipe too short". but each time I try it behaves differently.

Comment 7 Alex Smirnoff 2020-05-07 19:20:26 UTC
And I cannot get a successful enrollment no matter how thoroughly I swipe :)

Comment 8 Benjamin Berg 2020-05-07 19:37:58 UTC
I am not really surprised about the different errors. There is a double free currently for the returned error (already have a patch see https://gitlab.freedesktop.org/libfprint/libfprint/-/merge_requests/143 on top of the earlier https://gitlab.freedesktop.org/libfprint/libfprint/-/merge_requests/142).

The funny thing is, I have compared the old/new code quite a bit, and the control flow appears identical. And it does work fine the first time it runs, which makes things even weirder.

The interesting this is that

(fprintd:1619448): libfprint-upekts-CRITICAL **: 21:59:54.929: fingerprint data too short (1 bytes)

means that the driver thought it was getting the final enrolled print (only happens at the end). But it happens too early and there is no print data attached.

Comment 9 Benjamin Berg 2020-05-08 08:18:05 UTC
OK, I am out of ideas.

I think we'll need a trace of a working enroll. Which hopefully does still work with the old packages from F31 or F30 (fprintd and libfprint).

Note, there are two things that you can do here:
 1. Run the exact same test with debug output. Luckily the driver prints quite a lot of information, so this might be enough to learn more.
 2. Run the test in umockdev-record to trace the USB transfers

For 2. you would need to install umockdev. Then wrap the fprintd binary with umockdev-record, something like:

  umockdev-record -i /dev/bus/usb/001/005=capture.ioctl -- fprintd

You can also build an old version of libfprint (the V_1_0 tag) from git and run the smaller enroll test in the repository. Replace 001/005 with the actual device path (these numbers match the bus and device number listed by lsusb).

Comment 10 Alex Smirnoff 2020-05-09 18:14:23 UTC
More strange things: fc31 version does remember my old fingerprints, but does not recognize the swipe or new enroll.

▲ ~ fprintd-enroll                                                            
Using device /net/reactivated/Fprint/Device/0
Enrolling right-index-finger finger.
Enroll result: enroll-disconnected

...

(fprintd:39576): libfprint-upekts-DEBUG: 21:12:09.926: device responds to subcmd 0 with 14 bytes
(fprintd:39576): libfprint-upekts-DEBUG: 21:12:09.926: poll result = 0c
(fprintd:39576): libfprint-upekts-DEBUG: 21:12:09.926: seq=00 subcmd=00 with 2 bytes of data
(fprintd:39576): libfprint-upekts-DEBUG: 21:12:10.053: A=00 B=00 len=7
(fprintd:39576): libfprint-upekts-DEBUG: 21:12:10.053: non-zero bytes in cmd response
(fprintd:39576): libfprint-upekts-DEBUG: 21:12:10.053: device responds to subcmd 2 with 1 bytes

(fprintd:39576): libfprint-upekts-WARNING **: 21:12:10.053: fingerprint data too short (1 bytes)
(fprintd:39576): libfprint-async-DEBUG: 21:12:10.053: result -71
(fprintd:39576): fprintd-DEBUG: 21:12:10.053: enroll_stage_cb: result -71
(fprintd:39576): libfprint-async-DEBUG: 21:12:10.114: 1011877334: ../libfprint/fpi-async.c:111

will now try fc30 version.

Comment 11 Alex Smirnoff 2020-05-09 18:30:09 UTC
Created attachment 1686850 [details]
more log from fc30 package

Even worse! Once it worked (not from the frist try), but the subsequent times it did not.


▲ ~ fprintd-enroll                                                            
Using device /net/reactivated/Fprint/Device/0
Enrolling right-index-finger finger.
Enroll result: enroll-stage-passed
Enroll result: enroll-finger-not-centered
Enroll result: enroll-stage-passed
Enroll result: enroll-finger-not-centered
Enroll result: enroll-finger-not-centered
Enroll result: enroll-finger-not-centered
Enroll result: enroll-completed

 ▲ ~ fprintd-enroll                                                            
Using device /net/reactivated/Fprint/Device/0
Enrolling right-index-finger finger.
Enroll result: enroll-disconnected

Comment 12 Alex Smirnoff 2020-05-09 18:31:00 UTC
Created attachment 1686851 [details]
this one when it worked

Comment 13 Alex Smirnoff 2020-05-09 19:55:37 UTC
Now I swiped my old fingerprint and it "just worked" as before. :-/

Comment 14 Benjamin Berg 2020-05-11 06:59:11 UTC
Yeah, the new libfprint is a rewrite in large parts and there are some incompatibilities (storage location and storage format). We never implemented a data migration, and usually it shouldn't be a big problem to simply enroll again …

From what you are writing, it looks like the old code already runs into the exact same problem. If that error is new, then I could image that your fingerprint reader itself is slowly dying. For example a dried up capacitor could make the power supply unstable, causing random processing errors.

I think the only thing one could try would be to simply ignore that bogus/unexpected packet and continue polling. But I am in doubt that will fix it, the "hardware slowly dying" hypothesis is too likely in my view. And even if we should be handling that data packet in some way, we don't know whether simply ignoring it is sufficient.

Comment 15 Benjamin Berg 2020-05-11 07:52:36 UTC
OK, building https://koji.fedoraproject.org/koji/taskinfo?taskID=44356544

This contains all the bugfixes that happened recently. It will not fix the "fingerprint data too short" problem. However, it does fix other issues in the error and retry code paths (i.e. you can continue after a retry is "not centered" needed). So while you might need multiple attempts, I suspect you'll be able to enroll your finger then.

Could you test the build?

Comment 16 Alex Smirnoff 2020-05-11 22:12:14 UTC
It works good and even picked up my old fingerprints! Regarding the faulty reader, it was like that for years :) I never ran it under any other OS so I do not know if it is supposed to work better.

Comment 17 Benjamin Berg 2020-05-12 06:42:27 UTC
Are you sure you updated correctly and restarted fprintd? The new build I did cannot open the old fingerprints. So it seems more likely that something went wrong during the upgrade and you were still using the F30 or F31 version of libfprint and fprintd.

Comment 18 Alex Smirnoff 2020-05-12 08:46:53 UTC
oops, apparently i had an old version hanging :( after the restart:

fprintd:361784): fprintd-DEBUG: 11:45:40.732: D-Bus service launched with name: net.reactivated.Fprint
(fprintd:361784): fprintd-DEBUG: 11:45:40.732: entering main loop
(fprintd:361784): fprintd-DEBUG: 11:45:44.366: user 'ark' claiming the device: 0
(fprintd:361784): libfprint-SSM-DEBUG: 11:45:44.366: [upekts] INITSM_NUM_STATES entering state 0
(fprintd:361784): libfprint-SSM-DEBUG: 11:45:44.370: [upekts] INITSM_NUM_STATES entering state 1
**
libfprint-upekts:ERROR:../libfprint/drivers/upekts.c:247:__handle_incoming_msg: assertion failed: (udata->buflen == len + 9)
Bail out! libfprint-upekts:ERROR:../libfprint/drivers/upekts.c:247:__handle_incoming_msg: assertion failed: (udata->buflen == len + 9)

Comment 19 Benjamin Berg 2020-05-12 09:16:41 UTC
Outch. I added that assert just to make an assumption in the code explicit. Looks like that assumption was wrong indeed and there is a 9 byte buffer overflow  in this driver. Ah, the code quality of these drivers …

Sorry, I fear you'll need to play guinea pig for me for a bit longer.

Please try this build:
  https://koji.fedoraproject.org/koji/taskinfo?taskID=44408087

That should fix the buffer overflow and result in the assertion to hold true.

Comment 20 Alex Smirnoff 2020-05-12 16:26:10 UTC
Nope, exactly the same error with different line number.

(fprintd:962696): fprintd-DEBUG: 19:23:51.675: D-Bus service launched with name: net.reactivated.Fprint
(fprintd:962696): fprintd-DEBUG: 19:23:51.675: entering main loop
(fprintd:962696): fprintd-DEBUG: 19:23:59.700: user 'ark' claiming the device: 0
(fprintd:962696): libfprint-SSM-DEBUG: 19:23:59.701: [upekts] INITSM_NUM_STATES entering state 0
(fprintd:962696): libfprint-SSM-DEBUG: 19:23:59.703: [upekts] INITSM_NUM_STATES entering state 1
**
libfprint-upekts:ERROR:../libfprint/drivers/upekts.c:246:__handle_incoming_msg: assertion failed: (udata->buflen == len + 9)
Bail out! libfprint-upekts:ERROR:../libfprint/drivers/upekts.c:246:__handle_incoming_msg: assertion failed: (udata->buflen == len + 9)

Comment 21 Benjamin Berg 2020-05-12 17:39:36 UTC
Hah, nice one. Obviously the assert itself was also wrong. :)

Another build
  https://koji.fedoraproject.org/koji/taskinfo?taskID=44422331
with the assert fixed up.

Comment 22 Alex Smirnoff 2020-05-13 06:02:49 UTC
What happens now:

fprintd-enroll works, but if it is unable to obtain swipe, it gives up immediately like that:

(fprintd:1961021): libfprint-upekts-DEBUG: 08:46:55.348: poll result = 0c
(fprintd:1961021): libfprint-upekts-DEBUG: 08:46:55.348: seq=20 subcmd=00 with 2 bytes of data
(fprintd:1961021): libfprint-upekts-DEBUG: 08:46:55.449: A=00 B=20 len=20
(fprintd:1961021): libfprint-upekts-DEBUG: 08:46:55.449: device responds to subcmd 0 with 14 bytes
(fprintd:1961021): libfprint-upekts-DEBUG: 08:46:55.449: poll result = 0c
(fprintd:1961021): libfprint-upekts-DEBUG: 08:46:55.449: seq=30 subcmd=00 with 2 bytes of data
(fprintd:1961021): libfprint-upekts-DEBUG: 08:46:55.704: A=00 B=30 len=7

(fprintd:1961021): libfprint-upekts-CRITICAL **: 08:46:55.704: fingerprint data too short (1 bytes)
(fprintd:1961021): libfprint-upekts-DEBUG: 08:46:55.704: non-zero bytes in cmd response
(fprintd:1961021): libfprint-upekts-DEBUG: 08:46:55.704: device responds to subcmd 2 with 1 bytes
(fprintd:1961021): libfprint-SSM-DEBUG: 08:46:55.704: [upekts] DEINITSM_NUM_STATES entering state 0
(fprintd:1961021): libfprint-upekts-DEBUG: 08:46:55.704: seq=07 len=1
(fprintd:1961021): libfprint-SSM-DEBUG: 08:46:55.705: [upekts] DEINITSM_NUM_STATES entering state 1
(fprintd:1961021): libfprint-upekts-DEBUG: 08:46:55.706: A=01 B=00 len=0
(fprintd:1961021): libfprint-upekts-DEBUG: 08:46:55.706: cmd 1 from device to driver
(fprintd:1961021): libfprint-SSM-DEBUG: 08:46:55.706: [upekts] DEINITSM_NUM_STATES completed successfully
(fprintd:1961021): libfprint-device-DEBUG: 08:46:55.706: Device reported enroll completion
(fprintd:1961021): libfprint-device-DEBUG: 08:46:55.706: Completing action 4 in idle!
(fprintd:1961021): fprintd-DEBUG: 08:46:55.706: enroll_cb: result enroll-disconnected

(fprintd:1961021): fprintd-WARNING **: 08:46:55.706: Device reported an error during enroll: fingerprint data too short
(fprintd:1961021): libfprint-device-DEBUG: 08:46:55.767: Device reported close completion
(fprintd:1961021): libfprint-device-DEBUG: 08:46:55.767: Completing action 3 in idle!
(fprintd:1961021): fprintd-DEBUG: 08:46:55.767: released device 0

However, if I delete fingerprints, mate-about-me is unable to enroll and crashes as before, however, I do not see anything wrong on the fprintd side, do you?

(fprintd:1961021): fprintd-DEBUG: 08:58:08.804: user 'ark' claiming the device: 0
(fprintd:1961021): libfprint-SSM-DEBUG: 08:58:08.804: [upekts] INITSM_NUM_STATES entering state 0
(fprintd:1961021): libfprint-SSM-DEBUG: 08:58:08.806: [upekts] INITSM_NUM_STATES entering state 1
(fprintd:1961021): libfprint-upekts-DEBUG: 08:58:08.807: A=03 B=00 len=5
(fprintd:1961021): libfprint-upekts-DEBUG: 08:58:08.807: cmd 3 from device to driver
(fprintd:1961021): libfprint-SSM-DEBUG: 08:58:08.807: [upekts] INITSM_NUM_STATES entering state 2
(fprintd:1961021): libfprint-upekts-DEBUG: 08:58:08.807: seq=04 len=8
(fprintd:1961021): libfprint-SSM-DEBUG: 08:58:08.810: [upekts] INITSM_NUM_STATES entering state 3
(fprintd:1961021): libfprint-upekts-DEBUG: 08:58:08.811: A=05 B=00 len=1
(fprintd:1961021): libfprint-upekts-DEBUG: 08:58:08.811: cmd 5 from device to driver
(fprintd:1961021): libfprint-SSM-DEBUG: 08:58:08.811: [upekts] INITSM_NUM_STATES entering state 4
(fprintd:1961021): libfprint-upekts-DEBUG: 08:58:08.811: seq=00 subcmd=06 with 1 bytes of data
(fprintd:1961021): libfprint-SSM-DEBUG: 08:58:08.812: [upekts] INITSM_NUM_STATES entering state 5
(fprintd:1961021): libfprint-upekts-DEBUG: 08:58:08.815: A=00 B=00 len=55
(fprintd:1961021): libfprint-upekts-DEBUG: 08:58:08.815: device responds to subcmd 6 with 49 bytes
(fprintd:1961021): libfprint-SSM-DEBUG: 08:58:08.815: [upekts] INITSM_NUM_STATES entering state 6
(fprintd:1961021): libfprint-upekts-DEBUG: 08:58:08.815: seq=10 subcmd=07 with 1 bytes of data
(fprintd:1961021): libfprint-SSM-DEBUG: 08:58:08.816: [upekts] INITSM_NUM_STATES entering state 7
(fprintd:1961021): libfprint-upekts-DEBUG: 08:58:08.817: A=00 B=10 len=15
(fprintd:1961021): libfprint-upekts-DEBUG: 08:58:08.817: device responds to subcmd 7 with 9 bytes
(fprintd:1961021): libfprint-SSM-DEBUG: 08:58:08.817: [upekts] INITSM_NUM_STATES entering state 8
(fprintd:1961021): libfprint-upekts-DEBUG: 08:58:08.817: seq=20 subcmd=08 with 25 bytes of data
(fprintd:1961021): libfprint-SSM-DEBUG: 08:58:08.819: [upekts] INITSM_NUM_STATES entering state 9
(fprintd:1961021): libfprint-upekts-DEBUG: 08:58:08.821: A=00 B=20 len=15
(fprintd:1961021): libfprint-upekts-DEBUG: 08:58:08.821: device responds to subcmd 8 with 9 bytes
(fprintd:1961021): libfprint-SSM-DEBUG: 08:58:08.821: [upekts] INITSM_NUM_STATES entering state 10
(fprintd:1961021): libfprint-upekts-DEBUG: 08:58:08.821: seq=30 subcmd=0c with 5 bytes of data
(fprintd:1961021): libfprint-SSM-DEBUG: 08:58:08.822: [upekts] INITSM_NUM_STATES entering state 11
(fprintd:1961021): libfprint-upekts-DEBUG: 08:58:08.823: didn't fit in buffer, need to extend by 52 bytes
(fprintd:1961021): libfprint-upekts-DEBUG: 08:58:08.824: A=00 B=30 len=107
(fprintd:1961021): libfprint-upekts-DEBUG: 08:58:08.824: device responds to subcmd c with 101 bytes
(fprintd:1961021): libfprint-SSM-DEBUG: 08:58:08.824: [upekts] INITSM_NUM_STATES entering state 12
(fprintd:1961021): libfprint-upekts-DEBUG: 08:58:08.824: seq=40 subcmd=0b with 105 bytes of data
(fprintd:1961021): libfprint-SSM-DEBUG: 08:58:08.825: [upekts] INITSM_NUM_STATES entering state 13
(fprintd:1961021): libfprint-upekts-DEBUG: 08:58:08.826: A=00 B=40 len=7
(fprintd:1961021): libfprint-upekts-DEBUG: 08:58:08.826: device responds to subcmd b with 1 bytes
(fprintd:1961021): libfprint-SSM-DEBUG: 08:58:08.826: [upekts] INITSM_NUM_STATES completed successfully
(fprintd:1961021): libfprint-device-DEBUG: 08:58:08.826: Device reported open completion
(fprintd:1961021): libfprint-device-DEBUG: 08:58:08.826: Completing action 2 in idle!
(fprintd:1961021): fprintd-DEBUG: 08:58:08.826: claimed device 0
(fprintd:1961021): libfprint-device-DEBUG: 08:58:12.712: Device reported close completion
(fprintd:1961021): libfprint-device-DEBUG: 08:58:12.712: Completing action 3 in idle!
(fprintd:1961021): fprintd-DEBUG: 08:58:12.712: released device 0

Well, not exactly the same way: it says the device is already in use first.

Comment 23 Benjamin Berg 2020-05-13 08:48:32 UTC
Alright! We still get

(fprintd:1961021): libfprint-upekts-CRITICAL **: 08:46:55.704: fingerprint data too short (1 bytes)

but that was expected and is not a regression.

As for mate-about-me, not sure. All that the log says is that the device is being opened and then closed again about 4 seconds later (claim/release in fprintd terms). Nothing suspicious from the libfprint/fprintd side there.

So, I'll close this bug once I have patches pulled into the Fedora libfprint package. I'll probably do an upstream release first.

Comment 24 Alex Smirnoff 2020-05-13 14:39:32 UTC
But the previous version did not crash mate-about-me on unsuccessful swipes.. Something still appears somewhat off.

Comment 25 Alex Smirnoff 2020-05-13 14:40:43 UTC
also, shouldn't fprintd-enroll prompt me for another try when it is unable to obtain a decent swipe instead of restarting the whole process?

Comment 26 Alex Smirnoff 2020-05-13 18:23:58 UTC
Also I see 3 distinct errors: swipe too short (handled correctly), swipe not centered (handled correctly) and "fingerprint data too short) -- not handled correctly.

Comment 27 Alex Smirnoff 2020-05-13 18:46:42 UTC
Also if I "successfully" enroll, it does not properly read it then!

(fprintd:2931208): libfprint-SSM-DEBUG: 21:45:13.391: [upekts] INITSM_NUM_STATES completed successfully
(fprintd:2931208): libfprint-device-DEBUG: 21:45:13.392: Device reported open completion
(fprintd:2931208): libfprint-device-DEBUG: 21:45:13.392: Completing action 2 in idle!
(fprintd:2931208): fprintd-DEBUG: 21:45:13.392: claimed device 0
(fprintd:2931208): fprintd-DEBUG: 21:45:13.396: file_storage_discover_prints() for user 'ark' in '/var/lib/fprint/ark/upekts/0'
(fprintd:2931208): fprintd-DEBUG: 21:45:13.396: start verification device 0 finger 7

(fprintd:2931208): libfprint-print-WARNING **: 21:45:13.396: Invalid print type: 0x0
Error deserializing data: Data could not be parsed(fprintd:2931208): fprintd-DEBUG: 21:45:13.396: file_storage_print_data_load(): loaded '/var/lib/fprint/ark/upekts/0/7' Unknown error -5

Comment 28 Benjamin Berg 2020-05-14 10:38:34 UTC
Ah, so one more issue …

New scratch build: https://koji.fedoraproject.org/koji/taskinfo?taskID=44482910

You'll need to delete the enrolled print. You may need to manually delete the file, i.e. /var/lib/fprint/ark/upekts/0/7.


Look, the "fingerprint data too short" is a *protocol* issue with the device. I agree it sucks, but I simply cannot support these drivers beyond fixing regressions and blatant issues like crashes. So what I am doing is resolving all the regressions. At this point we should be at the same level of support as F31 had (with a fixed buffer overflow!), so that is where my support stops.

For some of the newer device we have support from the manufacturer. That is obviously much better.

mate-about-me crashing is also a separate issue. I somewhat suspect (but really don't know) that this will already be fixed upstream. I doubt it is problem in fprintd (or libfprint) and will need dealing with on the mate side.


That said, I do have one more request for you. Could you do the following:
 * Download https://benjamin.sipsolutions.net/upekts.py
 * Install umockdev: sudo dnf install umockdev
 * Run lsusb to identify the USB port (the bus/device numbers in the "Bus X Device Y: ID ..." message)
 * Grab device information: umockdev-record /dev/bus/usb/X/Y >/tmp/device
 * Grab a log of USB packets: umockdev-record -i /dev/bus/usb/X/Y=/tmp/capture.ioctl -- python3 /path/to/upekts.py
 * Then enroll and verify the same finger; you may need to stop fprintd first.

Replace X, Y and "/path/to/upekts.py" with the correct information. Then please attach the two created files (/tmp/device and /tmp/capture.ioctl) to this bug. If I have that, I can create a unit test to prevent future regressions.

Comment 29 Benjamin Berg 2020-05-14 10:42:38 UTC
Ah, note that the bus/device numbers might change if you run into that annoying "fingerprint data too short error". In that case you probably need to restart the whole process.

Comment 30 Alex Smirnoff 2020-05-15 07:41:47 UTC
fprintd:1626233): libfprint-upekts-DEBUG: 10:40:10.386: didn't fit in buffer, need to extend by 52 bytes
(fprintd:1626233): libfprint-upekts-DEBUG: 10:40:10.387: A=00 B=30 len=107
(fprintd:1626233): libfprint-upekts-DEBUG: 10:40:10.388: device responds to subcmd c with 101 bytes
(fprintd:1626233): libfprint-SSM-DEBUG: 10:40:10.388: [upekts] INITSM_NUM_STATES entering state 12
(fprintd:1626233): libfprint-upekts-DEBUG: 10:40:10.388: seq=40 subcmd=0b with 105 bytes of data
(fprintd:1626233): libfprint-SSM-DEBUG: 10:40:10.388: [upekts] INITSM_NUM_STATES entering state 13
(fprintd:1626233): libfprint-upekts-DEBUG: 10:40:10.389: A=00 B=40 len=7
(fprintd:1626233): libfprint-upekts-DEBUG: 10:40:10.390: device responds to subcmd b with 1 bytes
(fprintd:1626233): libfprint-SSM-DEBUG: 10:40:10.390: [upekts] INITSM_NUM_STATES completed successfully
(fprintd:1626233): libfprint-SSM-DEBUG: 10:40:10.390: [upekts] VERIFY_NUM_STATES entering state 1

(fprintd:1626233): GLib-GObject-WARNING **: 10:40:10.390: g_object_get_is_valid_property: object class 'FpiDeviceUpekts' has no property named 'fpi-data'

(fprintd:1626233): GLib-CRITICAL **: 10:40:10.390: g_variant_get_type: assertion 'value != NULL' failed

(fprintd:1626233): GLib-CRITICAL **: 10:40:10.390: g_variant_type_is_subtype_of: assertion 'g_variant_type_check (type)' failed

(fprintd:1626233): GLib-CRITICAL **: 10:40:10.390: g_variant_get_fixed_array: assertion 'g_variant_is_of_type (value, G_VARIANT_TYPE_ARRAY)' failed

(fprintd:1626233): GLib-ERROR **: 10:40:10.390: ../glib/gmem.c:108: failed to allocate 94863762044169 bytes

Comment 31 Benjamin Berg 2020-05-15 16:32:45 UTC
At least we are at the point that enroll works …

https://koji.fedoraproject.org/koji/taskinfo?taskID=44538213

Comment 32 Alex Smirnoff 2020-05-15 21:33:33 UTC
Yes!

Comment 33 Alex Smirnoff 2020-05-17 20:21:12 UTC
With this build PAM module crashes immediately.

Swipe your right index finger across the fingerprint reader
An unknown error occurred
free(): double free detected in tcache 2
[1]    1131410 abort      sudo id


(fprintd:1116834): libfprint-SSM-DEBUG: 23:19:09.027: [upekts] INITSM_NUM_STATES completed successfully
(fprintd:1116834): libfprint-SSM-DEBUG: 23:19:09.027: [upekts] VERIFY_NUM_STATES entering state 1
(fprintd:1116834): libfprint-upekts-DEBUG: 23:19:09.028: seq=50 subcmd=03 with 164 bytes of data
(fprintd:1116834): libfprint-SSM-DEBUG: 23:19:09.028: [upekts] VERIFY_NUM_STATES completed successfully
(fprintd:1116834): libfprint-upekts-DEBUG: 23:19:09.029: A=00 B=50 len=7
(fprintd:1116834): libfprint-upekts-DEBUG: 23:19:09.029: non-zero bytes in cmd response
(fprintd:1116834): libfprint-upekts-DEBUG: 23:19:09.029: device responds to subcmd f0 with 1 bytes
(fprintd:1116834): libfprint-device-DEBUG: 23:19:09.029: Device reported verify result

(fprintd:1116834): libfprint-device-WARNING **: 23:19:09.029: Driver reported a verify error that was not in the retry domain, delaying report!
(fprintd:1116834): libfprint-SSM-DEBUG: 23:19:09.030: [upekts] DEINITSM_NUM_STATES entering state 0
(fprintd:1116834): libfprint-upekts-DEBUG: 23:19:09.030: seq=07 len=1
(fprintd:1116834): libfprint-SSM-DEBUG: 23:19:09.030: [upekts] DEINITSM_NUM_STATES entering state 1
(fprintd:1116834): libfprint-upekts-DEBUG: 23:19:09.031: A=01 B=00 len=0
(fprintd:1116834): libfprint-upekts-DEBUG: 23:19:09.031: cmd 1 from device to driver
(fprintd:1116834): libfprint-SSM-DEBUG: 23:19:09.031: [upekts] DEINITSM_NUM_STATES completed successfully
(fprintd:1116834): libfprint-device-DEBUG: 23:19:09.031: Device reported verify completion

(fprintd:1116834): GLib-CRITICAL **: 23:19:09.031: g_error_free: assertion 'error != NULL' failed
(fprintd:1116834): libfprint-device-DEBUG: 23:19:09.032: Completing action 5 in idle!
(fprintd:1116834): fprintd-DEBUG: 23:19:09.032: verify_cb: result verify-disconnect

(fprintd:1116834): fprintd-WARNING **: 23:19:09.032: Device reported an error during verify: Response had wrong subcommand type
(fprintd:1116834): libfprint-device-DEBUG: 23:19:09.040: Device reported close completion
(fprintd:1116834): libfprint-device-DEBUG: 23:19:09.042: Completing action 3 in idle!

Comment 34 Alex Smirnoff 2020-05-25 10:35:22 UTC
Anything else I could do?

Comment 35 Benjamin Berg 2020-05-25 12:15:30 UTC
Right, another memory management issue and a flaw in the error reporting logic.

https://koji.fedoraproject.org/koji/taskinfo?taskID=44951904

But even with that, well report a hard error and we'll give up fingprint auth in that situation.

Comment 36 Alex Smirnoff 2020-05-25 17:09:47 UTC
(fprintd:1046574): libfprint-SSM-DEBUG: 20:08:27.589: [upekts] INITSM_NUM_STATES entering state 11
(fprintd:1046574): libfprint-upekts-DEBUG: 20:08:27.590: didn't fit in buffer, need to extend by 52 bytes
(fprintd:1046574): libfprint-upekts-DEBUG: 20:08:27.591: A=00 B=30 len=107
(fprintd:1046574): libfprint-upekts-DEBUG: 20:08:27.591: device responds to subcmd c with 101 bytes
(fprintd:1046574): libfprint-SSM-DEBUG: 20:08:27.592: [upekts] INITSM_NUM_STATES entering state 12
(fprintd:1046574): libfprint-upekts-DEBUG: 20:08:27.592: seq=40 subcmd=0b with 105 bytes of data
(fprintd:1046574): libfprint-SSM-DEBUG: 20:08:27.592: [upekts] INITSM_NUM_STATES entering state 13
(fprintd:1046574): libfprint-upekts-DEBUG: 20:08:27.593: A=00 B=40 len=7
(fprintd:1046574): libfprint-upekts-DEBUG: 20:08:27.593: device responds to subcmd b with 1 bytes
(fprintd:1046574): libfprint-SSM-DEBUG: 20:08:27.594: [upekts] INITSM_NUM_STATES completed successfully
(fprintd:1046574): libfprint-SSM-DEBUG: 20:08:27.594: [upekts] VERIFY_NUM_STATES entering state 1
(fprintd:1046574): libfprint-upekts-DEBUG: 20:08:27.594: seq=50 subcmd=03 with 164 bytes of data
(fprintd:1046574): libfprint-SSM-DEBUG: 20:08:27.594: [upekts] VERIFY_NUM_STATES completed successfully
(fprintd:1046574): libfprint-upekts-DEBUG: 20:08:27.596: A=00 B=50 len=7
(fprintd:1046574): libfprint-upekts-DEBUG: 20:08:27.596: non-zero bytes in cmd response
(fprintd:1046574): libfprint-upekts-DEBUG: 20:08:27.596: device responds to subcmd f0 with 1 bytes
(fprintd:1046574): libfprint-SSM-DEBUG: 20:08:27.596: [upekts] DEINITSM_NUM_STATES entering state 0
(fprintd:1046574): libfprint-upekts-DEBUG: 20:08:27.596: seq=07 len=1
(fprintd:1046574): libfprint-SSM-DEBUG: 20:08:27.597: [upekts] DEINITSM_NUM_STATES entering state 1
(fprintd:1046574): libfprint-upekts-DEBUG: 20:08:27.598: A=01 B=00 len=0
(fprintd:1046574): libfprint-upekts-DEBUG: 20:08:27.598: cmd 1 from device to driver
(fprintd:1046574): libfprint-SSM-DEBUG: 20:08:27.599: [upekts] DEINITSM_NUM_STATES completed successfully
(fprintd:1046574): libfprint-device-DEBUG: 20:08:27.599: Device reported verify completion
(fprintd:1046574): libfprint-device-DEBUG: 20:08:27.599: Completing action 5 in idle!
(fprintd:1046574): fprintd-DEBUG: 20:08:27.599: verify_cb: result verify-disconnect

(fprintd:1046574): fprintd-WARNING **: 20:08:27.599: Device reported an error during verify: Response had wrong subcommand type
(fprintd:1046574): libfprint-device-DEBUG: 20:08:27.612: Device reported close completion
(fprintd:1046574): libfprint-device-DEBUG: 20:08:27.613: Completing action 3 in idle!

Comment 37 Benjamin Berg 2020-05-27 09:01:48 UTC
Alright, looking pretty good.

I have no idea what that error itself means. The device isn't doing what the driver expects, but I really don't think it is a regression. I do hope that it works fine most of the time though. The only thing I could offer is that we try simply ignoring that message and see what happens then. But again, I don't think that this is a regression.

Comment 38 Alex Smirnoff 2020-05-27 10:14:59 UTC
It crashes on the client side of PAM as well:

▲ ~ sudo id                                                                   
Swipe your right index finger across the fingerprint reader
An unknown error occurred
free(): double free detected in tcache 2
[1]    1047951 abort      sudo id

I do not think it is intended behavior, also it never happened with the old version

Comment 39 Alex Smirnoff 2020-05-27 10:16:09 UTC
Would recording debug session with the old version help?

Comment 40 Benjamin Berg 2020-05-27 12:22:55 UTC
Nah, pretty obvious what was going wrong:

  https://gitlab.freedesktop.org/libfprint/fprintd/-/merge_requests/64

Though the test case appears to be still failing, and I am not really sure why that is the case.

Comment 41 Alex Smirnoff 2020-05-28 07:13:40 UTC
ok waiting for the next build :)

Comment 42 Benjamin Berg 2020-05-29 15:53:46 UTC
https://koji.fedoraproject.org/koji/taskinfo?taskID=45145177

You'll need the fprintd-pam package at least.

Comment 43 Alex Smirnoff 2020-06-04 14:55:02 UTC
Sorry for the delay, the log is apprarently similar.

(fprintd:35181): fprintd-DEBUG: 17:52:41.283: claimed device 0
(fprintd:35181): fprintd-DEBUG: 17:52:41.287: file_storage_discover_prints() for user 'ark' in '/var/lib/fprint/ark/upekts/0'
(fprintd:35181): fprintd-DEBUG: 17:52:41.287: start verification device 0 finger 7
(fprintd:35181): fprintd-DEBUG: 17:52:41.287: file_storage_print_data_load(): loaded '/var/lib/fprint/ark/upekts/0/7' Success
(fprintd:35181): libfprint-SSM-DEBUG: 17:52:41.287: [upekts] VERIFY_NUM_STATES entering state 0
(fprintd:35181): libfprint-SSM-DEBUG: 17:52:41.287: [upekts] INITSM_NUM_STATES entering state 0
(fprintd:35181): libfprint-SSM-DEBUG: 17:52:41.288: [upekts] INITSM_NUM_STATES entering state 1
(fprintd:35181): libfprint-upekts-DEBUG: 17:52:41.289: A=03 B=00 len=5
(fprintd:35181): libfprint-upekts-DEBUG: 17:52:41.289: cmd 3 from device to driver
(fprintd:35181): libfprint-SSM-DEBUG: 17:52:41.289: [upekts] INITSM_NUM_STATES entering state 2
(fprintd:35181): libfprint-upekts-DEBUG: 17:52:41.289: seq=04 len=8
(fprintd:35181): libfprint-SSM-DEBUG: 17:52:41.290: [upekts] INITSM_NUM_STATES entering state 3
(fprintd:35181): libfprint-upekts-DEBUG: 17:52:41.291: A=05 B=00 len=1
(fprintd:35181): libfprint-upekts-DEBUG: 17:52:41.291: cmd 5 from device to driver
(fprintd:35181): libfprint-SSM-DEBUG: 17:52:41.291: [upekts] INITSM_NUM_STATES entering state 4
(fprintd:35181): libfprint-upekts-DEBUG: 17:52:41.291: seq=00 subcmd=06 with 1 bytes of data
(fprintd:35181): libfprint-SSM-DEBUG: 17:52:41.292: [upekts] INITSM_NUM_STATES entering state 5
(fprintd:35181): libfprint-upekts-DEBUG: 17:52:41.297: A=00 B=00 len=55
(fprintd:35181): libfprint-upekts-DEBUG: 17:52:41.297: device responds to subcmd 6 with 49 bytes
(fprintd:35181): libfprint-SSM-DEBUG: 17:52:41.297: [upekts] INITSM_NUM_STATES entering state 6
(fprintd:35181): libfprint-upekts-DEBUG: 17:52:41.297: seq=10 subcmd=07 with 1 bytes of data
(fprintd:35181): libfprint-SSM-DEBUG: 17:52:41.298: [upekts] INITSM_NUM_STATES entering state 7
(fprintd:35181): libfprint-upekts-DEBUG: 17:52:41.299: A=00 B=10 len=15
(fprintd:35181): libfprint-upekts-DEBUG: 17:52:41.299: device responds to subcmd 7 with 9 bytes
(fprintd:35181): libfprint-SSM-DEBUG: 17:52:41.299: [upekts] INITSM_NUM_STATES entering state 8
(fprintd:35181): libfprint-upekts-DEBUG: 17:52:41.299: seq=20 subcmd=08 with 25 bytes of data
(fprintd:35181): libfprint-SSM-DEBUG: 17:52:41.300: [upekts] INITSM_NUM_STATES entering state 9
(fprintd:35181): libfprint-upekts-DEBUG: 17:52:41.303: A=00 B=20 len=15
(fprintd:35181): libfprint-upekts-DEBUG: 17:52:41.303: device responds to subcmd 8 with 9 bytes
(fprintd:35181): libfprint-SSM-DEBUG: 17:52:41.303: [upekts] INITSM_NUM_STATES entering state 10
(fprintd:35181): libfprint-upekts-DEBUG: 17:52:41.303: seq=30 subcmd=0c with 5 bytes of data
(fprintd:35181): libfprint-SSM-DEBUG: 17:52:41.304: [upekts] INITSM_NUM_STATES entering state 11
(fprintd:35181): libfprint-upekts-DEBUG: 17:52:41.304: didn't fit in buffer, need to extend by 52 bytes
(fprintd:35181): libfprint-upekts-DEBUG: 17:52:41.305: A=00 B=30 len=107
(fprintd:35181): libfprint-upekts-DEBUG: 17:52:41.305: device responds to subcmd c with 101 bytes
(fprintd:35181): libfprint-SSM-DEBUG: 17:52:41.305: [upekts] INITSM_NUM_STATES entering state 12
(fprintd:35181): libfprint-upekts-DEBUG: 17:52:41.305: seq=40 subcmd=0b with 105 bytes of data
(fprintd:35181): libfprint-SSM-DEBUG: 17:52:41.306: [upekts] INITSM_NUM_STATES entering state 13
(fprintd:35181): libfprint-upekts-DEBUG: 17:52:41.307: A=00 B=40 len=7
(fprintd:35181): libfprint-upekts-DEBUG: 17:52:41.307: device responds to subcmd b with 1 bytes
(fprintd:35181): libfprint-SSM-DEBUG: 17:52:41.307: [upekts] INITSM_NUM_STATES completed successfully
(fprintd:35181): libfprint-SSM-DEBUG: 17:52:41.307: [upekts] VERIFY_NUM_STATES entering state 1
(fprintd:35181): libfprint-upekts-DEBUG: 17:52:41.307: seq=50 subcmd=03 with 164 bytes of data
(fprintd:35181): libfprint-SSM-DEBUG: 17:52:41.308: [upekts] VERIFY_NUM_STATES completed successfully
(fprintd:35181): libfprint-upekts-DEBUG: 17:52:41.309: A=00 B=50 len=7
(fprintd:35181): libfprint-upekts-DEBUG: 17:52:41.309: non-zero bytes in cmd response
(fprintd:35181): libfprint-upekts-DEBUG: 17:52:41.309: device responds to subcmd f0 with 1 bytes
(fprintd:35181): libfprint-SSM-DEBUG: 17:52:41.309: [upekts] DEINITSM_NUM_STATES entering state 0
(fprintd:35181): libfprint-upekts-DEBUG: 17:52:41.309: seq=07 len=1
(fprintd:35181): libfprint-SSM-DEBUG: 17:52:41.310: [upekts] DEINITSM_NUM_STATES entering state 1
(fprintd:35181): libfprint-upekts-DEBUG: 17:52:41.311: A=01 B=00 len=0
(fprintd:35181): libfprint-upekts-DEBUG: 17:52:41.311: cmd 1 from device to driver
(fprintd:35181): libfprint-SSM-DEBUG: 17:52:41.311: [upekts] DEINITSM_NUM_STATES completed successfully
(fprintd:35181): libfprint-device-DEBUG: 17:52:41.311: Device reported verify completion
(fprintd:35181): libfprint-device-DEBUG: 17:52:41.311: Completing action 5 in idle!
(fprintd:35181): fprintd-DEBUG: 17:52:41.311: verify_cb: result verify-disconnect

(fprintd:35181): fprintd-WARNING **: 17:52:41.311: Device reported an error during verify: Response had wrong subcommand type
(fprintd:35181): libfprint-device-DEBUG: 17:52:41.317: Device reported close completion
(fprintd:35181): libfprint-device-DEBUG: 17:52:41.317: Completing action 3 in idle!
(fprintd:35181): fprintd-DEBUG: 17:52:41.317: released device 0

Comment 44 Alex Smirnoff 2020-06-04 14:57:10 UTC
On the PAM side, it is still the same "unknown error" but without double free error, so it falls back to the next method gracefully.

Comment 45 Benjamin Berg 2020-06-04 15:02:26 UTC
Exactly, that was the point of the fix.

Comment 46 Alex Smirnoff 2020-06-04 21:49:50 UTC
aand, any chance I will get fprintd working? ;)

Comment 47 Fedora Update System 2020-06-08 12:42:51 UTC
FEDORA-2020-3e62b92f85 has been submitted as an update to Fedora 32. https://bodhi.fedoraproject.org/updates/FEDORA-2020-3e62b92f85

Comment 48 Alex Smirnoff 2020-06-09 09:18:15 UTC
There was a semi-working version of fprintd previously? This one fails instantly.

Comment 49 Benjamin Berg 2020-06-09 09:33:17 UTC
Well, the bugfix above is "just" the libfprint part. There was another (but entirely independent) problem in fprintd (i.e. pam_fprintd) for which I have not posted an update yet. Things *should* be OK if you use the new libfprint build together with the pam_fprintd package from https://koji.fedoraproject.org/koji/taskinfo?taskID=45145177

Comment 50 Benjamin Berg 2020-06-09 09:33:17 UTC
Well, the bugfix above is "just" the libfprint part. There was another (but entirely independent) problem in fprintd (i.e. pam_fprintd) for which I have not posted an update yet. Things *should* be OK if you use the new libfprint build together with the pam_fprintd package from https://koji.fedoraproject.org/koji/taskinfo?taskID=45145177

Comment 51 Alex Smirnoff 2020-06-11 11:21:57 UTC
No, it enrolls but it cannot verify; the verification fails with similar error messages even before I swipe.

Comment 52 Fedora Update System 2020-06-11 19:21:47 UTC
libfprint-1.90.2-1.fc32 has been pushed to the Fedora 32 testing repository. If problems still persist, please make note of it in this bug report.
See https://fedoraproject.org/wiki/QA:Updates_Testing for
instructions on how to install test updates.
You can provide feedback for this update here: https://bodhi.fedoraproject.org/updates/FEDORA-2020-3e62b92f85

Comment 53 Alex Smirnoff 2020-06-13 20:27:15 UTC
Yes, it does persist indeed. Can enroll, cannot verify.

Comment 54 Benjamin Berg 2020-06-19 09:25:35 UTC
Sorry, but just no …

AFAICT the regressions *are* fixed by the update. There seems to be some other issue, but I don't see anything that might be going wrong at this point.

Now, might there be another regression … yes, but this update *does* fix a lot of problems.

But, I am sorry, there is *nothing* I can do for you at this point. One might be able to figure this out with a lot of testing and comparing to the f30 version.

So:
 * IF the f30 version behaves better, then this would be a regression and a valid bug. But fixing that issue would need extensive debugging (e.g. tracing the USB transfers, finding differences, manually converting an enrolled print from f30 to the new version and test if that works …), which I cannot do as I don't have the device.
 * IF the f30 version beahves the same, then there is simply nothing I can do for you.

So yeah, I *will* close this bug as fixed … even if you are out of luck unfortunately.

Comment 55 Fedora Update System 2020-06-22 08:10:02 UTC
FEDORA-2020-3e62b92f85 has been pushed to the Fedora 32 stable repository.
If problem still persists, please make note of it in this bug report.

Comment 56 Alex Smirnoff 2020-06-22 09:15:38 UTC
Hey wait!

Ineed there *IS* a regression. Two of them: one on the fprintd side (cannot verify) and one on libfprint side (crash when cannot verify), Only the later one was fixed. fc30 version worked fine. As I said, I am willing to provide traces and whatever could help to fix it properly. Please reopen the bug.

Comment 57 Benjamin Berg 2020-06-22 09:36:28 UTC
Yes, there still is the fprintd regression for which I didn't bother to clone the bug (it'll be fixed with the next update, you can be certain of that).

There *is* something weird going on with that "f0" subcommand during verify, I agree. I don't know what the reason may be, it could be the way the driver works, it may be that the stored print data gets corrupted at some point. I simply don't know (and I *have* looked into it), and while I have some ideas of where I would start looking further (e.g. hacking together a stored libfprint 1.90.x print from the old version), I don't really have the time to do so.

It isn't that I don't want to help you. The problem is that it simply doesn't make sense for me to spend more time on supporting hardware that probably is not even sold anymore (I have not checked this). The cost/benefit falls flat if there is no big user base for the device.

It is an unfortunate regression … but I fear the "better" fix from my point of view would be to remove the driver upstream.

I do need to focus on other libfprint work unfortunately; support for new devices is simply more important.

Comment 58 Alex Smirnoff 2020-06-22 18:41:31 UTC
I understand. But it is the latest laptop you can get with 4x3 hires screen and decent keyboard, so some people like me are still stuck with it :)

Comment 59 Marc 2020-06-22 20:47:55 UTC
The problem continues, and it impacts the Lenovo KUF0452 Fingerprint external keyboard with this UPEK fingerprint reader. These are still widely used. 

The fingerprint will now register with the version that was in today's Fedora update (1.90.2-1.fc32). But commands like "sudo dnf update" will fail with: 

An unknown error occurred
free() double free detected in tcache 2
Aborted

This continues until you delete the stored fingerprint and fingerprint authentication is disabled. 

Marc

Comment 60 unknownbuckethead 2020-08-01 06:21:30 UTC
(In reply to Marc from comment #59)
> The problem continues, and it impacts the Lenovo KUF0452 Fingerprint
> external keyboard with this UPEK fingerprint reader. These are still widely
> used. 
> 
> The fingerprint will now register with the version that was in today's
> Fedora update (1.90.2-1.fc32). But commands like "sudo dnf update" will fail
> with: 
> 
> An unknown error occurred
> free() double free detected in tcache 2
> Aborted
> 
> This continues until you delete the stored fingerprint and fingerprint
> authentication is disabled. 
> 
> Marc

I can confirm this problem. When I prompted for scrolling fingers I got this error.


Note You need to log in before you can comment on or make changes to this bug.