[fprint] upek fingerprint sensor: pam_fprint_enroll exits after 5 enrolls with error -22

Ulf Dambacher ulf.dambacher at web.de
Thu Jan 5 07:48:14 PST 2012 

Hi there

I have  a problem with my fingerprint reader on thinkpad w520.
pam_enroll scans 5 prints with comment "yep" and then gives error -22
I activated debugging during libfprint compile, debug output is attached.

I tried to read the code for the debug messages and wondered about the
"sync:error [fp_enroll_finger_img] exceeding number of enroll stages for device
claimed by driver upeke2 (5 stages)"
Maybe the driver does not stop enrolling?"

Who can help?

#lsusb -s 1:3 -v

Bus 001 Device 003: ID 147e:2016 Upek Biometric Touchchip/Touchstrip Fingerprint
Sensor
Device Descriptor:
  bLength                18
  bDescriptorType         1
  bcdUSB               1.01
  bDeviceClass            0 (Defined at Interface level)
  bDeviceSubClass         0
  bDeviceProtocol         0
  bMaxPacketSize0         8
  idVendor           0x147e Upek
  idProduct          0x2016 Biometric Touchchip/Touchstrip Fingerprint Sensor
  bcdDevice            0.02
  iManufacturer           1 UPEK
  iProduct                2 Biometric Coprocessor
  iSerial                 0
  bNumConfigurations      1
  Configuration Descriptor:


---------------8<------

#equery list *fprint*
 * Searching for *fprint* ...
[IP-] [  ] sys-auth/fprint_demo-0.4:0
[IP-] [  ] sys-auth/fprintd-0.2.0-r1:0
[IP-] [  ] sys-auth/libfprint-0.4.0:0
[IP-] [  ] sys-auth/pam_fprint-0.2-r1:0

-----------8<-----------

#pam_fprint_enroll 
This program will enroll your finger, unconditionally overwriting any selected
print that was enrolled previously. If you want to continue, press enter,
otherwise hit Ctrl+C

fp:debug [fp_init]
fp:debug [register_driver] registered driver upekts
fp:debug [register_driver] registered driver upeke2
fp:debug [register_driver] registered driver aes4000
fp:debug [register_driver] registered driver aes2501
fp:debug [register_driver] registered driver uru4000
fp:debug [register_driver] registered driver vcom5s
fp:debug [register_driver] registered driver upeksonly
fp:debug [register_driver] registered driver aes1610
fp:debug [register_driver] registered driver vfs101
fp:debug [find_supporting_driver] driver upeke2 supports USB device 147e:2016
fp:debug [find_supporting_driver] selected driver upeke2 supports USB device
147e:2016
Found device claimed by UPEK Eikon 2 driver
sync:debug [fp_dev_open]
async:debug [fp_async_dev_open]
async:debug [fpi_drvcb_open_complete] status 0
sync:debug [sync_open_cb] status 0
Opened device. It's now time to enroll your finger.

You will need to successfully scan your Right Index Finger 5 times to complete
the process.

Scan your finger now.
sync:debug [fp_enroll_finger_img]
async:debug [fp_async_enroll_start] starting enrollment
drv:debug [__ssm_call_handler] 0xc3f6f0 entering state 0
drv:debug [__ssm_call_handler] 0xc3f730 entering state 0
sync:debug [fp_enroll_finger_img] upeke2 will handle enroll stage 0/4
drv:debug [__ssm_call_handler] 0xc3f730 entering state 1
upeke2:debug [__handle_incoming_msg] A=03 B=00 len=5
upeke2:debug [__handle_incoming_msg] cmd 3 from device to driver
drv:debug [__ssm_call_handler] 0xc3f730 entering state 2
upeke2:debug [alloc_send_cmdresponse_transfer] seq=04 len=8
upeke2:debug [initsm_send_msg_cb] state 2 completed
drv:debug [__ssm_call_handler] 0xc3f730 entering state 3
upeke2:debug [__handle_incoming_msg] A=05 B=00 len=1
upeke2:debug [__handle_incoming_msg] cmd 5 from device to driver
drv:debug [__ssm_call_handler] 0xc3f730 entering state 4
upeke2:debug [alloc_send_cmd28_transfer] seq=00 subcmd=06 with 1 bytes of data
upeke2:debug [initsm_send_msg_cb] state 4 completed
drv:debug [__ssm_call_handler] 0xc3f730 entering state 5
upeke2:debug [__handle_incoming_msg] A=00 B=00 len=55
upeke2:debug [__handle_incoming_msg] device responds to subcmd 6 with 49 bytes
upeke2:debug [initsm_read_msg_response_cb] state 5 completed
drv:debug [__ssm_call_handler] 0xc3f730 entering state 6
upeke2:debug [alloc_send_cmd28_transfer] seq=10 subcmd=51 with 5 bytes of data
upeke2:debug [initsm_send_msg_cb] state 6 completed
drv:debug [__ssm_call_handler] 0xc3f730 entering state 7
upeke2:debug [__handle_incoming_msg] A=00 B=10 len=27
upeke2:debug [__handle_incoming_msg] device responds to subcmd 51 with 21 bytes
upeke2:debug [initsm_read_msg_response_cb] state 7 completed
drv:debug [__ssm_call_handler] 0xc3f730 entering state 8
upeke2:debug [alloc_send_cmd28_transfer] seq=20 subcmd=07 with 5 bytes of data
upeke2:debug [initsm_send_msg_cb] state 8 completed
drv:debug [__ssm_call_handler] 0xc3f730 entering state 9
upeke2:debug [__handle_incoming_msg] A=00 B=20 len=39
upeke2:debug [__handle_incoming_msg] device responds to subcmd 7 with 33 bytes
upeke2:debug [initsm_read_msg_response_cb] state 9 completed
drv:debug [__ssm_call_handler] 0xc3f730 entering state 10
upeke2:debug [alloc_send_cmd28_transfer] seq=30 subcmd=08 with 99 bytes of data
upeke2:debug [initsm_send_msg_cb] state 10 completed
drv:debug [__ssm_call_handler] 0xc3f730 entering state 11
upeke2:debug [__handle_incoming_msg] A=00 B=30 len=7
upeke2:debug [__handle_incoming_msg] non-zero bytes in cmd response
upeke2:debug [__handle_incoming_msg] device responds to subcmd 8 with 1 bytes
upeke2:debug [initsm_read_msg_response_cb] state 11 completed
drv:debug [fpi_ssm_mark_completed] 0xc3f730 completed with status 0
drv:debug [__ssm_call_handler] 0xc3f6f0 entering state 1
upeke2:debug [alloc_send_cmd28_transfer] seq=40 subcmd=02 with 8 bytes of data
drv:debug [__ssm_call_handler] 0xc3f6f0 entering state 2
upeke2:debug [__handle_incoming_msg] A=00 B=40 len=20
upeke2:debug [__handle_incoming_msg] device responds to subcmd 0 with 14 bytes
drv:debug [fpi_ssm_mark_completed] 0xc3f6f0 completed with status 0
async:debug [fpi_drvcb_enroll_started] status 0
upeke2:debug [alloc_send_cmd28_transfer] seq=50 subcmd=00 with 2 bytes of data
upeke2:debug [__handle_incoming_msg] A=00 B=50 len=20
upeke2:debug [__handle_incoming_msg] device responds to subcmd 0 with 14 bytes
upeke2:debug [e_handle_resp00] poll result = 0c
upeke2:debug [alloc_send_cmd28_transfer] seq=60 subcmd=00 with 2 bytes of data
upeke2:debug [__handle_incoming_msg] A=00 B=60 len=20
upeke2:debug [__handle_incoming_msg] device responds to subcmd 0 with 14 bytes
upeke2:debug [e_handle_resp00] poll result = 0c
upeke2:debug [alloc_send_cmd28_transfer] seq=70 subcmd=00 with 2 bytes of data
upeke2:debug [__handle_incoming_msg] A=00 B=70 len=20
upeke2:debug [__handle_incoming_msg] device responds to subcmd 0 with 14 bytes
upeke2:debug [e_handle_resp00] poll result = 20
upeke2:debug [alloc_send_cmd28_transfer] seq=80 subcmd=00 with 2 bytes of data
upeke2:debug [__handle_incoming_msg] A=00 B=80 len=20
upeke2:debug [__handle_incoming_msg] device responds to subcmd 0 with 14 bytes
upeke2:debug [e_handle_resp00] poll result = 2e
async:debug [fpi_drvcb_enroll_stage_completed] result 3
sync:debug [sync_enroll_cb] result 3
upeke2:debug [alloc_send_cmd28_transfer] seq=90 subcmd=00 with 2 bytes of data
sync:debug [fp_enroll_finger_img] enroll stage passed
Enroll stage passed. Yay!

Scan your finger now.
sync:debug [fp_enroll_finger_img]
sync:debug [fp_enroll_finger_img] upeke2 will handle enroll stage 1/4
upeke2:debug [__handle_incoming_msg] A=00 B=90 len=20
upeke2:debug [__handle_incoming_msg] device responds to subcmd 0 with 14 bytes
upeke2:debug [e_handle_resp00] poll result = 0c
upeke2:debug [alloc_send_cmd28_transfer] seq=a0 subcmd=00 with 2 bytes of data
upeke2:debug [__handle_incoming_msg] A=00 B=a0 len=20
upeke2:debug [__handle_incoming_msg] device responds to subcmd 0 with 14 bytes
upeke2:debug [e_handle_resp00] poll result = 0c
upeke2:debug [alloc_send_cmd28_transfer] seq=b0 subcmd=00 with 2 bytes of data
upeke2:debug [__handle_incoming_msg] A=00 B=b0 len=20
upeke2:debug [__handle_incoming_msg] device responds to subcmd 0 with 14 bytes
upeke2:debug [e_handle_resp00] poll result = 0c
upeke2:debug [alloc_send_cmd28_transfer] seq=c0 subcmd=00 with 2 bytes of data
upeke2:debug [__handle_incoming_msg] A=00 B=c0 len=20
upeke2:debug [__handle_incoming_msg] device responds to subcmd 0 with 14 bytes
upeke2:debug [e_handle_resp00] poll result = 0c
upeke2:debug [alloc_send_cmd28_transfer] seq=d0 subcmd=00 with 2 bytes of data
upeke2:debug [__handle_incoming_msg] A=00 B=d0 len=20
upeke2:debug [__handle_incoming_msg] device responds to subcmd 0 with 14 bytes
upeke2:debug [e_handle_resp00] poll result = 0c
upeke2:debug [alloc_send_cmd28_transfer] seq=e0 subcmd=00 with 2 bytes of data
upeke2:debug [__handle_incoming_msg] A=00 B=e0 len=20
upeke2:debug [__handle_incoming_msg] device responds to subcmd 0 with 14 bytes
upeke2:debug [e_handle_resp00] poll result = 0c
upeke2:debug [alloc_send_cmd28_transfer] seq=f0 subcmd=00 with 2 bytes of data
upeke2:debug [__handle_incoming_msg] A=00 B=f0 len=20
upeke2:debug [__handle_incoming_msg] device responds to subcmd 0 with 14 bytes
upeke2:debug [e_handle_resp00] poll result = 0c
upeke2:debug [alloc_send_cmd28_transfer] seq=00 subcmd=00 with 2 bytes of data
upeke2:debug [__handle_incoming_msg] A=00 B=00 len=20
upeke2:debug [__handle_incoming_msg] device responds to subcmd 0 with 14 bytes
upeke2:debug [e_handle_resp00] poll result = 0c
upeke2:debug [alloc_send_cmd28_transfer] seq=10 subcmd=00 with 2 bytes of data
upeke2:debug [__handle_incoming_msg] A=00 B=10 len=20
upeke2:debug [__handle_incoming_msg] device responds to subcmd 0 with 14 bytes
upeke2:debug [e_handle_resp00] poll result = 0c
upeke2:debug [alloc_send_cmd28_transfer] seq=20 subcmd=00 with 2 bytes of data
upeke2:debug [__handle_incoming_msg] A=00 B=20 len=20
upeke2:debug [__handle_incoming_msg] device responds to subcmd 0 with 14 bytes
upeke2:debug [e_handle_resp00] poll result = 0c
upeke2:debug [alloc_send_cmd28_transfer] seq=30 subcmd=00 with 2 bytes of data
upeke2:debug [__handle_incoming_msg] A=00 B=30 len=20
upeke2:debug [__handle_incoming_msg] device responds to subcmd 0 with 14 bytes
upeke2:debug [e_handle_resp00] poll result = 0c
upeke2:debug [alloc_send_cmd28_transfer] seq=40 subcmd=00 with 2 bytes of data
upeke2:debug [__handle_incoming_msg] A=00 B=40 len=20
upeke2:debug [__handle_incoming_msg] device responds to subcmd 0 with 14 bytes
upeke2:debug [e_handle_resp00] poll result = 20
upeke2:debug [alloc_send_cmd28_transfer] seq=50 subcmd=00 with 2 bytes of data
upeke2:debug [__handle_incoming_msg] A=00 B=50 len=20
upeke2:debug [__handle_incoming_msg] device responds to subcmd 0 with 14 bytes
upeke2:debug [e_handle_resp00] poll result = 2e
async:debug [fpi_drvcb_enroll_stage_completed] result 3
sync:debug [sync_enroll_cb] result 3
upeke2:debug [alloc_send_cmd28_transfer] seq=60 subcmd=00 with 2 bytes of data
sync:debug [fp_enroll_finger_img] enroll stage passed
Enroll stage passed. Yay!

Scan your finger now.
sync:debug [fp_enroll_finger_img]
sync:debug [fp_enroll_finger_img] upeke2 will handle enroll stage 2/4
upeke2:debug [__handle_incoming_msg] A=00 B=60 len=20
upeke2:debug [__handle_incoming_msg] device responds to subcmd 0 with 14 bytes
upeke2:debug [e_handle_resp00] poll result = 0c
upeke2:debug [alloc_send_cmd28_transfer] seq=70 subcmd=00 with 2 bytes of data
upeke2:debug [__handle_incoming_msg] A=00 B=70 len=20
upeke2:debug [__handle_incoming_msg] device responds to subcmd 0 with 14 bytes
upeke2:debug [e_handle_resp00] poll result = 0c
upeke2:debug [alloc_send_cmd28_transfer] seq=80 subcmd=00 with 2 bytes of data
upeke2:debug [__handle_incoming_msg] A=00 B=80 len=20
upeke2:debug [__handle_incoming_msg] device responds to subcmd 0 with 14 bytes
upeke2:debug [e_handle_resp00] poll result = 0c
upeke2:debug [alloc_send_cmd28_transfer] seq=90 subcmd=00 with 2 bytes of data
upeke2:debug [__handle_incoming_msg] A=00 B=90 len=20
upeke2:debug [__handle_incoming_msg] device responds to subcmd 0 with 14 bytes
upeke2:debug [e_handle_resp00] poll result = 0c
upeke2:debug [alloc_send_cmd28_transfer] seq=a0 subcmd=00 with 2 bytes of data
upeke2:debug [__handle_incoming_msg] A=08 B=00 len=0
upeke2:debug [__handle_incoming_msg] cmd 8 from device to driver
upeke2:debug [__handle_incoming_msg] device busy, send busy-ack
upeke2:debug [alloc_send_cmdresponse_transfer] seq=09 len=0
upeke2:debug [__handle_incoming_msg] A=00 B=a0 len=20
upeke2:debug [__handle_incoming_msg] device responds to subcmd 0 with 14 bytes
upeke2:debug [e_handle_resp00] poll result = 20
upeke2:debug [alloc_send_cmd28_transfer] seq=b0 subcmd=00 with 2 bytes of data
upeke2:debug [__handle_incoming_msg] A=00 B=b0 len=20
upeke2:debug [__handle_incoming_msg] device responds to subcmd 0 with 14 bytes
upeke2:debug [e_handle_resp00] poll result = 2e
async:debug [fpi_drvcb_enroll_stage_completed] result 3
sync:debug [sync_enroll_cb] result 3
upeke2:debug [alloc_send_cmd28_transfer] seq=c0 subcmd=00 with 2 bytes of data
sync:debug [fp_enroll_finger_img] enroll stage passed
Enroll stage passed. Yay!

Scan your finger now.
sync:debug [fp_enroll_finger_img]
sync:debug [fp_enroll_finger_img] upeke2 will handle enroll stage 3/4
upeke2:debug [__handle_incoming_msg] A=00 B=c0 len=20
upeke2:debug [__handle_incoming_msg] device responds to subcmd 0 with 14 bytes
upeke2:debug [e_handle_resp00] poll result = 0c
upeke2:debug [alloc_send_cmd28_transfer] seq=d0 subcmd=00 with 2 bytes of data
upeke2:debug [__handle_incoming_msg] A=00 B=d0 len=20
upeke2:debug [__handle_incoming_msg] device responds to subcmd 0 with 14 bytes
upeke2:debug [e_handle_resp00] poll result = 0c
upeke2:debug [alloc_send_cmd28_transfer] seq=e0 subcmd=00 with 2 bytes of data
upeke2:debug [__handle_incoming_msg] A=00 B=e0 len=20
upeke2:debug [__handle_incoming_msg] device responds to subcmd 0 with 14 bytes
upeke2:debug [e_handle_resp00] poll result = 0c
upeke2:debug [alloc_send_cmd28_transfer] seq=f0 subcmd=00 with 2 bytes of data
upeke2:debug [__handle_incoming_msg] A=00 B=f0 len=20
upeke2:debug [__handle_incoming_msg] device responds to subcmd 0 with 14 bytes
upeke2:debug [e_handle_resp00] poll result = 0c
upeke2:debug [alloc_send_cmd28_transfer] seq=00 subcmd=00 with 2 bytes of data
upeke2:debug [__handle_incoming_msg] A=08 B=00 len=0
upeke2:debug [__handle_incoming_msg] cmd 8 from device to driver
upeke2:debug [__handle_incoming_msg] device busy, send busy-ack
upeke2:debug [alloc_send_cmdresponse_transfer] seq=09 len=0
upeke2:debug [__handle_incoming_msg] A=00 B=00 len=20
upeke2:debug [__handle_incoming_msg] device responds to subcmd 0 with 14 bytes
upeke2:debug [e_handle_resp00] poll result = 20
upeke2:debug [alloc_send_cmd28_transfer] seq=10 subcmd=00 with 2 bytes of data
upeke2:debug [__handle_incoming_msg] A=00 B=10 len=20
upeke2:debug [__handle_incoming_msg] device responds to subcmd 0 with 14 bytes
upeke2:debug [e_handle_resp00] poll result = 2e
async:debug [fpi_drvcb_enroll_stage_completed] result 3
sync:debug [sync_enroll_cb] result 3
upeke2:debug [alloc_send_cmd28_transfer] seq=20 subcmd=00 with 2 bytes of data
sync:debug [fp_enroll_finger_img] enroll stage passed
Enroll stage passed. Yay!

Scan your finger now.
sync:debug [fp_enroll_finger_img]
sync:debug [fp_enroll_finger_img] upeke2 will handle enroll stage 4/4
upeke2:debug [__handle_incoming_msg] A=00 B=20 len=20
upeke2:debug [__handle_incoming_msg] device responds to subcmd 0 with 14 bytes
upeke2:debug [e_handle_resp00] poll result = 0c
upeke2:debug [alloc_send_cmd28_transfer] seq=30 subcmd=00 with 2 bytes of data
upeke2:debug [__handle_incoming_msg] A=00 B=30 len=20
upeke2:debug [__handle_incoming_msg] device responds to subcmd 0 with 14 bytes
upeke2:debug [e_handle_resp00] poll result = 0c
upeke2:debug [alloc_send_cmd28_transfer] seq=40 subcmd=00 with 2 bytes of data
upeke2:debug [__handle_incoming_msg] A=00 B=40 len=20
upeke2:debug [__handle_incoming_msg] device responds to subcmd 0 with 14 bytes
upeke2:debug [e_handle_resp00] poll result = 0c
upeke2:debug [alloc_send_cmd28_transfer] seq=50 subcmd=00 with 2 bytes of data
upeke2:debug [__handle_incoming_msg] A=00 B=50 len=20
upeke2:debug [__handle_incoming_msg] device responds to subcmd 0 with 14 bytes
upeke2:debug [e_handle_resp00] poll result = 0c
upeke2:debug [alloc_send_cmd28_transfer] seq=60 subcmd=00 with 2 bytes of data
upeke2:debug [__handle_incoming_msg] A=00 B=60 len=20
upeke2:debug [__handle_incoming_msg] device responds to subcmd 0 with 14 bytes
upeke2:debug [e_handle_resp00] poll result = 0c
upeke2:debug [alloc_send_cmd28_transfer] seq=70 subcmd=00 with 2 bytes of data
upeke2:debug [__handle_incoming_msg] A=00 B=70 len=20
upeke2:debug [__handle_incoming_msg] device responds to subcmd 0 with 14 bytes
upeke2:debug [e_handle_resp00] poll result = 0c
upeke2:debug [alloc_send_cmd28_transfer] seq=80 subcmd=00 with 2 bytes of data
upeke2:debug [__handle_incoming_msg] A=00 B=80 len=20
upeke2:debug [__handle_incoming_msg] device responds to subcmd 0 with 14 bytes
upeke2:debug [e_handle_resp00] poll result = 0c
upeke2:debug [alloc_send_cmd28_transfer] seq=90 subcmd=00 with 2 bytes of data
upeke2:debug [__handle_incoming_msg] A=00 B=90 len=20
upeke2:debug [__handle_incoming_msg] device responds to subcmd 0 with 14 bytes
upeke2:debug [e_handle_resp00] poll result = 0c
upeke2:debug [alloc_send_cmd28_transfer] seq=a0 subcmd=00 with 2 bytes of data
upeke2:debug [__handle_incoming_msg] A=08 B=00 len=0
upeke2:debug [__handle_incoming_msg] cmd 8 from device to driver
upeke2:debug [__handle_incoming_msg] device busy, send busy-ack
upeke2:debug [alloc_send_cmdresponse_transfer] seq=09 len=0
upeke2:debug [__handle_incoming_msg] A=00 B=a0 len=20
upeke2:debug [__handle_incoming_msg] device responds to subcmd 0 with 14 bytes
upeke2:debug [e_handle_resp00] poll result = 20
upeke2:debug [alloc_send_cmd28_transfer] seq=b0 subcmd=00 with 2 bytes of data
upeke2:debug [__handle_incoming_msg] A=00 B=b0 len=20
upeke2:debug [__handle_incoming_msg] device responds to subcmd 0 with 14 bytes
upeke2:debug [e_handle_resp00] poll result = 2e
async:debug [fpi_drvcb_enroll_stage_completed] result 3
sync:debug [sync_enroll_cb] result 3
upeke2:debug [alloc_send_cmd28_transfer] seq=c0 subcmd=00 with 2 bytes of data
sync:debug [fp_enroll_finger_img] enroll stage passed
Enroll stage passed. Yay!

Scan your finger now.
sync:debug [fp_enroll_finger_img]
sync:error [fp_enroll_finger_img] exceeding number of enroll stages for device
claimed by driver upeke2 (5 stages)
sync:debug [fp_enroll_finger_img] ending enrollment
async:debug [fp_async_enroll_stop]
drv:debug [__ssm_call_handler] 0xc3f6f0 entering state 0
upeke2:debug [alloc_send_cmdresponse_transfer] seq=07 len=1
upeke2:debug [__handle_incoming_msg] A=00 B=c0 len=20
upeke2:debug [__handle_incoming_msg] device responds to subcmd 0 with 14 bytes
upeke2:debug [e_handle_resp00] poll result = 24
async:error [fpi_drvcb_enroll_stage_completed] BUG at async.c:161
async:debug [fpi_drvcb_enroll_stage_completed] result 102
async:debug [fpi_drvcb_enroll_stage_completed] ignoring enroll result as no
callback is subscribed
upeke2:debug [alloc_send_cmd28_transfer] seq=d0 subcmd=00 with 2 bytes of data
drv:debug [__ssm_call_handler] 0xc3f6f0 entering state 1
upeke2:error [read_msg_cb] async msg read failed, code 2
drv:debug [fpi_ssm_mark_aborted] error -1 from state 1
drv:debug [fpi_ssm_mark_completed] 0xc3f6f0 completed with status -1
async:debug [fpi_drvcb_enroll_stopped]
sync:debug [enroll_stop_cb]
Enroll failed with error -22
sync:debug [fp_dev_close]
async:debug [fpi_drvcb_close_complete]
sync:debug [sync_close_cb]
fp:debug [fp_exit]

-- 
---------------------------------------
Ulf Dambacher
ulf.dambacher at web.de
---------------------------------------

More information about the fprint mailing list