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 [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
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 [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
Created attachment 1686851 [details] 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.
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.
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
Yes!
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 :)
https://koji.fedoraproject.org/koji/taskinfo?taskID=45145177 You'll need the fprintd-pam package at least.
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
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
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
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.
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
(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.