fprintd-enroll fails on fresh install of xubuntu 20.04 with an USB UPEK reader

Bug #1881380 reported by Jesús Diéguez Fernández on 2020-05-30
18
This bug affects 3 people
Affects Status Importance Assigned to Milestone
libfprint
Fix Released
High
libfprint (Ubuntu)
High
Marco Trevisan (Treviño)
Focal
High
Marco Trevisan (Treviño)

Bug Description

[ Impact ]

The fingerprint reader is an UPEK TCRE3C usb fingerprint reader. It was working fine with ubuntu 16.04 and 18.04.

[ Test case ]

With an UPEK fingerprint reader run:
 - fprintd-enroll

Enrollment should work properly

[ Regression potential ]

Fingers are not enrolled (not that now they are :))

----

lsusb shows:

0483:2016 STMicroelectronics Fingerprint Reader

user@xubuntu:~$ fprintd-enroll
Using device /net/reactivated/Fprint/Device/0
failed to claim device: Open failed with error: transfer timed out

user@xubuntu:~$ fprintd-list user
found 1 devices
Device at /net/reactivated/Fprint/Device/0
Using device /net/reactivated/Fprint/Device/0
User user has no fingers enrolled for UPEK TouchStrip.

This bug is probably the same as:

https://bugzilla.redhat.com/show_bug.cgi?id=1832229

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

Probably a small regression in the driver port.

Please run with G_MESSAGES_DEBUG=all and paste the output.

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!

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 :)

Created attachment 1686238
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

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.

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.

And I cannot get a successful enrollment no matter how thoroughly I swipe :)

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.

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).

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.

Created attachment 1686850
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

Created attachment 1686851
this one when it worked

Now I swiped my old fingerprint and it "just worked" as before. :-/

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.

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?

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.

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.

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)

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.

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)

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.

Download full text (6.1 KiB)

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-DE...

Read more...

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.

But the previous version did not crash mate-about-me on unsuccessful swipes.. Something still appears somewhat off.

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?

Also I see 3 distinct errors: swipe too short (handled correctly), swipe not centered (handled correctly) and "fingerprint data too short) -- not handled correctly.

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

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.

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.

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

At least we are at the point that enroll works …

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

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!

Anything else I could do?

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.

(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!

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.

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

Would recording debug session with the old version help?

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.

ok waiting for the next build :)

Launchpad Janitor (janitor) wrote :

Status changed to 'Confirmed' because the bug affects multiple users.

Changed in fprintd (Ubuntu):
status: New → Confirmed
Download full text (5.3 KiB)

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 respo...

Read more...

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.

Exactly, that was the point of the fix.

aand, any chance I will get fprintd working? ;)

FEDORA-2020-3e62b92f85 has been submitted as an update to Fedora 32. https://bodhi.fedoraproject.org/updates/FEDORA-2020-3e62b92f85

Changed in fprintd:
importance: Unknown → High
status: Unknown → Fix Committed
Sebastien Bacher (seb128) wrote :

Marco, sounds like Benjamin has a fix for that, probably worth including in the next upload?

Changed in fprintd (Ubuntu):
importance: Undecided → High
status: Confirmed → In Progress
assignee: nobody → Marco Trevisan (Treviño) (3v1n0)

There was a semi-working version of fprintd previously? This one fails instantly.

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

tags: added: fixed-upstream
affects: fprintd (Ubuntu) → libfprint (Ubuntu)
affects: fprintd → libfprint

No, it enrolls but it cannot verify; the verification fails with similar error messages even before I swipe.

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

Yes, it does persist indeed. Can enroll, cannot verify.

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.

description: updated
Changed in libfprint (Ubuntu Focal):
status: New → Fix Committed
Changed in libfprint (Ubuntu):
status: In Progress → Fix Committed
Changed in libfprint (Ubuntu Focal):
importance: Undecided → High
assignee: nobody → Marco Trevisan (Treviño) (3v1n0)
Launchpad Janitor (janitor) wrote :

This bug was fixed in the package libfprint - 1:1.90.2+tod1-0ubuntu1

---------------
libfprint (1:1.90.2+tod1-0ubuntu1) groovy; urgency=medium

  * New upstream release
    - Fixed crash in VFS0050 (LP: #1876502)
    - Enrollment fails with UPEK reader (LP: #1881380)
    - Lots of various drivers fixes
    - As per a patch for nbis required for some sensors that was accidentally
      dropped in an earlier release. Users of sensors/drivers aes1610, aes2501,
      aes2550, aes1660, aes2660, elan, upektc_img) need to re-enroll
  * d/p/git_reading_pointer.patch:
    - Dopped (applied upstream)
  * debian/control: Add missing libfprint-2-tod-dev dependencies (LP: #1884267)
  * debian/rules: Be strictier about symbol changes
  * libfprint-2-tod1.symbols: Add new TOD symbols

 -- Marco Trevisan (Treviño) <email address hidden> Fri, 19 Jun 2020 17:38:55 +0200

Changed in libfprint (Ubuntu):
status: Fix Committed → Fix Released

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.

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.

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.

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 :)

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

An upload of libfprint to focal-proposed has been rejected from the upload queue for the following reason: "No bug references and/or SRU information for "New upstream release" and "Lots of various driver fixes"; incomplete discussion of regression potential in all bugs that are referenced. Please see https://wiki.ubuntu.com/StableReleaseUpdates for the required information and procedure.".

Hello Jesús, or anyone else affected,

Accepted libfprint into focal-proposed. The package will build now and be available at https://launchpad.net/ubuntu/+source/libfprint/1:1.90.2+tod1-0ubuntu1~20.04.1 in a few hours, and then in the -proposed repository.

Please help us by testing this new package. See https://wiki.ubuntu.com/Testing/EnableProposed for documentation on how to enable and use -proposed. Your feedback will aid us getting this update out to other Ubuntu users.

If this package fixes the bug for you, please add a comment to this bug, mentioning the version of the package you tested, what testing has been performed on the package and change the tag from verification-needed-focal to verification-done-focal. If it does not fix the bug for you, please add a comment stating that, and change the tag to verification-failed-focal. In either case, without details of your testing we will not be able to proceed.

Further information regarding the verification process can be found at https://wiki.ubuntu.com/QATeam/PerformingSRUVerification . Thank you in advance for helping!

N.B. The updated package will be released to -updates after the bug(s) fixed by this package have been verified and the package has been in -proposed for a minimum of 7 days.

tags: added: verification-needed verification-needed-focal

Hi,
I enabled proposed updates and updated my packages to:

libfprint-2-2:amd64 (1:1.90.2+tod1-0ubuntu1~20.04.1)
libfprint-2-tod1:amd64 (1:1.90.2+tod1-0ubuntu1~20.04.1)

And I can confirm that enrollment of fingerprints now succeeds:

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

However, trying to use su or sudo after this returns another error:

$ LANG=C sudo ls
Swipe your right index finger across the fingerprint reader
free(): double free detected in tcache 2
Abortado

$ LANG=C su
Swipe your right index finger across the fingerprint reader
free(): double free detected in tcache 2
Abortado

Should this be addressed in another bugtrack or can it be solved on this one?

Thank you.

It appears that in the RedHat bugtracker people are stuck at the same spot.
I'm changing the tag to verification-failed since registration of fingerprints works but validation fails.

tags: added: verification-failed-focal
removed: verification-needed-focal

Please report a new bug for that, as they're effectively two different issues.

We will fix it in a next iteration while the enroll issue is effectively fixed as you said, so marking it as verified, but please open a new bug for the verification side of things.

tags: added: verification-done verification-done-focal
removed: verification-failed-focal verification-needed

Ok, I've actually opened. So moving to bug #1888495.

(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.

Changed in libfprint:
status: Fix Committed → Fix Released
To post a comment you must log in.
This report contains Public information  Edit
Everyone can see this information.

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.