Elan 0903 fingerprint bug

[Teetoow]

Hi,

First of all, thank you for your work on developing a driver for these Elan hardware. I followed your discussion on launchpad and I understand it was a hard job

I just tried the last version of fprint and tried to use my Elan device. img_capture works well and enroll works for some time. However after 2-4 times of scanning my fingerprint a bug occurs and the device seems to not respond. Here is the output of enroll when it crashs:

Scan your finger now. sync:debug [fp_enroll_finger_img] sync:debug [fp_enroll_finger_img] elan will handle enroll stage 4/4 poll:debug [get_next_timeout_expiry] first timeout already expired poll:debug [handle_timeout] elan:debug [elan_capture] elan:debug [elan_dev_reset] drv:debug [ssm_call_handler] 0x55ed7034b010 entering state 0 elan:debug [elan_run_cmd] 4031 elan:debug [elan_cmd_cb] elan:debug [elan_cmd_read] elan:debug [elan_cmd_read] skipping read, not expecting anything elan:debug [elan_cmd_done] drv:debug [ssm_call_handler] 0x55ed7034b010 entering state 1 elan:debug [elan_run_cmd] 403f elan:debug [elan_cmd_cb] elan:debug [elan_cmd_read] elan:debug [elan_cmd_cb] elan:debug [elan_cmd_done] drv:debug [__ssm_call_handler] 0x55ed7034b010 entering state 2 fp:debug [fpi_imgdev_report_finger_status] finger on sensor elan:debug [elan_run_cmd] 0009 elan:debug [elan_cmd_cb] elan:debug [elan_cmd_cb] transfer timed out drv:debug [fpi_ssm_mark_aborted] error -110 from state 2 drv:debug [fpi_ssm_mark_completed] 0x55ed7034b010 completed with status -110 elan:debug [capture_complete] fp:debug [fpi_imgdev_session_error] error 0 fp:error [fpi_imgdev_session_error] BUG at imgdev.c:313 async:debug [fpi_drvcb_enroll_stage_completed] result 0 sync:debug [sync_enroll_cb] result 0 poll:debug [fpi_timeout_add] in 10ms poll:debug [get_next_timeout_expiry] next timeout in 0.009980s sync:error [fp_enroll_finger_img] unrecognised return code 0 sync:debug [fp_enroll_finger_img] ending enrollment async:debug [fp_async_enroll_stop] elan:debug [dev_deactivate] elan:debug [elan_deactivate] elan:debug [elan_dev_reset] drv:debug [ssm_call_handler] 0x55ed7034b010 entering state 0 elan:debug [deactivate_run_state] elan:debug [elan_run_cmd] 000b poll:debug [get_next_timeout_expiry] next timeout in 0.009680s poll:debug [get_next_timeout_expiry] first timeout already expired poll:debug [handle_timeout] elan:debug [elan_capture] elan:debug [elan_dev_reset] elan:error [elan_dev_reset] BUG at drivers/elan.c:101 drv:debug [ssm_call_handler] 0x55ed703ee460 entering state 0 elan:debug [elan_run_cmd] 4031 elan:debug [elan_cmd_cb] elan:debug [elan_cmd_cb] transfer timed out drv:debug [fpi_ssm_mark_aborted] error -110 from state 0 drv:debug [fpi_ssm_mark_completed] 0x55ed7034b010 completed with status -110 elan:debug [deactivate_complete] fp:debug [fpi_imgdev_deactivate_complete] async:debug [fpi_drvcb_enroll_stopped] sync:debug [enroll_stop_cb] Enroll failed with error -22 sync:debug [fp_dev_close] elan:debug [dev_deinit] elan:debug [elan_dev_reset] async:debug [fpi_drvcb_close_complete] libusb: error [do_close] Device handle closed while transfer was still being processed, but the device is still connected as far as we know libusb: error [do_close] A cancellation hasn't even been scheduled on the transfer for which the device is closing sync:debug [sync_close_cb] fp:debug [fp_exit]

Please tell me if you need more information. Thank you again for your job!!

[Teetoow]

I forgot to specify that the device does not respond anymore after that. I need to suspend / resume the laptop to get it working again for some time...

[iafilatov]

Sorry for the late response. For some reason your device didn't return the image in time and the driver didn't handle it well.

Scan your finger now.
sync:debug [fp_enroll_finger_img]
sync:debug [fp_enroll_finger_img] elan will handle enroll stage 4/4
<...17 lines...>
fp:debug [fpi_imgdev_report_finger_status] finger on sensor
elan:debug [elan_run_cmd] 0009
elan:debug [elan_cmd_cb]
elan:debug [elan_cmd_cb] transfer timed out                <---- image read timeout
drv:debug [fpi_ssm_mark_aborted] error -110 from state 2
drv:debug [fpi_ssm_mark_completed] 0x55ed7034b010 completed with status -110
elan:debug [capture_complete]
fp:debug [fpi_imgdev_session_error] error 0                <---- 0 is a bug...
fp:error [fpi_imgdev_session_error] BUG at imgdev.c:313

I've fixed this, please try the latest version.

Well actually, the fix will only handle the timeout properly and the driver will exit where it should... I don't know why your reader stopped responding right after the "get image" command, to be honest. I've never seen this happen in any report so far.

[stefanocirici]

Same problem. My log here.

[mumrau]

Hello.

I've faced the same issue but now I cannot get my fingerprint sensor to work either on Linux or even on Windows. It seems the unlikely event of breaking the device actually happened. Anyone could possibly help with a way of unlocking it (I get "Device cannot start" under windows, and on linux it just seems to stop responding).

Thanks in advance.

[iafilatov]

Hi, Did you try to power-cycle the sensor? Usually a reboot or a cold boot helps. I don't know how you're switching from LInux to Win but if you're just sending the USB device to VM and back it won't help.

[mumrau]

I finally fixed it. Looks like even after a reboot and switching in grub (I got dual-boot, no VMs here), the sensor didn't truly power-cycle and remained in an unstable (and thus failing) state. I forced a power shutdown (a complete one) by going through BIOS, reinstalled driver and it looks back alive on Windows. Seems like with all the power saving options, reboots are no longer proper reboots !

It is kinda reassuring for the others though, the device still is robust even after a linux failure (04f3:0903), I'll stop the adventure here, because by the way, the pgm files were absolutely messy and not rendering properly at all, so even uner working conditions, it sill wasn't able to cycle 4-5 times for the enrolling.

Thanks folks !

[iafilatov]

@Mumrau If you don't mind, could you please send me a couple of "messy" examples? I'm wondering if it's because of bad frame quality or problems with assembling the final image. If you're ok, you can find my email here.

[mumrau]

I panicked and (stupidly) delete my libfrprint folder. I'm redoing the process quickly.

[iafilatov]

No rush. A couple of examples/img_capture pgm's would be enough. You reader shouldn't lock from that.

[mumrau]

I had a decent image once, so I couldn't resist trying the enrolling... Which lead me here, my sensor "locked" on the third input with these logs :

sync:debug [fp_enroll_finger_img] enroll should retry
fp:debug [fp_img_save_to_file] written to 'enrolled.pgm'
Wrote scanned image to enrolled.pgm
Didn't quite catch that. Please try again.

I sent you the email.

[iafilatov]

I've changed the order of commands a bit and it may fix the 0903 lock-up issue. It's still a shot in the dark though. If anyone is willing to test (run enroll a few times in a row to see) I'd appreciate it. Thanks! https://github.com/iafilatov/libfprint/tree/elan-try-fix-0903

[mumrau]

I get into a "swipe too short loop" right after the first scan, without even touching the sensor.

Scan your finger now.
sync:debug [fp_enroll_finger_img] 
sync:debug [fp_enroll_finger_img] elan will handle enroll stage 0/4
poll:debug [get_next_timeout_expiry] first timeout already expired
poll:debug [handle_timeout] 
elan:debug [elan_change_state] changing to 1
elan:debug [elan_capture] 
elan:debug [elan_dev_reset] 
drv:debug [__ssm_call_handler] 0x5628dc51b500 entering state 0
elan:debug [elan_run_cmd] 4031
poll:debug [get_next_timeout_expiry] first timeout already expired
poll:debug [handle_timeout] 
elan:debug [elan_change_state] already in 1
elan:debug [elan_cmd_cb] 
elan:debug [elan_cmd_read] 
elan:debug [elan_cmd_read] skipping read, not expecting anything
elan:debug [elan_cmd_done] 
drv:debug [__ssm_call_handler] 0x5628dc51b500 entering state 1
elan:debug [elan_run_cmd] 403f
elan:debug [elan_cmd_cb] 
elan:debug [elan_cmd_read] 
elan:debug [elan_cmd_cb] 55
elan:debug [elan_cmd_done] 
drv:debug [__ssm_call_handler] 0x5628dc51b500 entering state 2
fp:debug [fpi_imgdev_report_finger_status] finger on sensor
elan:debug [dev_change_state] 2
elan:debug [elan_run_cmd] 0009
elan:debug [elan_cmd_cb] 
elan:debug [elan_cmd_read] 
elan:debug [elan_cmd_cb] ffff... (18432 bytes)
elan:debug [elan_cmd_done] 
drv:debug [__ssm_call_handler] 0x5628dc51b500 entering state 3
elan:debug [elan_save_img_frame] 
elan:debug [elan_save_frame] 
drv:debug [__ssm_call_handler] 0x5628dc51b500 entering state 1
elan:debug [elan_run_cmd] 403f
elan:debug [elan_cmd_cb] 
elan:debug [elan_cmd_read] 
elan:debug [elan_cmd_cb] transfer timed out
drv:debug [fpi_ssm_mark_aborted] error -110 from state 1
drv:debug [fpi_ssm_mark_completed] 0x5628dc51b500 completed with status -110
elan:debug [capture_complete] 
elan:debug [capture_complete] swipe too short: want >= 7 frames, got 1
elan:debug [dev_change_state] 3
poll:debug [fpi_timeout_add] in 10ms
poll:debug [get_next_timeout_expiry] next timeout in 0.009986s
poll:debug [get_next_timeout_expiry] next timeout in 0.009960s
poll:debug [get_next_timeout_expiry] first timeout already expired
poll:debug [handle_timeout] 
elan:debug [elan_change_state] changing to 3
elan:debug [elan_stop_capture] 
elan:debug [elan_dev_reset] 
drv:debug [__ssm_call_handler] 0x5628dc51b500 entering state 0
elan:debug [stop_capture_run_state] 
elan:debug [elan_run_cmd] 000b
elan:debug [elan_cmd_cb] 
elan:debug [elan_cmd_read] 
elan:debug [elan_cmd_read] skipping read, not expecting anything
elan:debug [elan_cmd_done] 
drv:debug [fpi_ssm_mark_completed] 0x5628dc51b500 completed with status 0
elan:debug [stop_capture_complete] 
fp:debug [fpi_imgdev_report_finger_status] finger removed
fp:debug [fpi_imgdev_report_finger_status] reporting enroll result
async:debug [fpi_drvcb_enroll_stage_completed] result 101
sync:debug [sync_enroll_cb] result 101
elan:debug [dev_change_state] 1
poll:debug [fpi_timeout_add] in 10ms
elan:debug [dev_change_state] 1
poll:debug [fpi_timeout_add] in 10ms
poll:debug [get_next_timeout_expiry] next timeout in 0.009965s
sync:debug [fp_enroll_finger_img] swipe was too short, enroll should retry
Your swipe was too short, please try again.

And that happens pretty much forever.

Nonetheless, the sensor never ever ended up in a "locked" state.

[iafilatov]

@Mumrau Could you please post or send me the entire enroll log?

[andyclegg]

Using elan-try-fix-0903, I get 'Scan your finger now' very quickly followed by the 'Your swipe was too short, please try again.' message, in a loop. It seems like this only happens the second time onwards, so perhaps its not clearing an error code properly? If I react very quickly after the 'scan your finger now', I can often get a successful enrolment.

On Tue, 17 Jul 2018 at 11:38 Igor Filatov notifications@github.com wrote:

@Mumrau https://github.com/Mumrau Could you please post or send me the entire enroll log?

— You are receiving this because you are subscribed to this thread. Reply to this email directly, view it on GitHub https://github.com/iafilatov/libfprint/issues/5#issuecomment-405538639, or mute the thread https://github.com/notifications/unsubscribe-auth/AAjEHmTreeb0BNCH6kDeXIayIfjtpQsmks5uHb6sgaJpZM4SBSwW .

[iafilatov]

I pushed something else, please try again.

[andyclegg]

With that latest commit (4bc99b), the fast loop has gone and enrolment seems to work successfully.

On Tue, 17 Jul 2018 at 16:17 Igor Filatov notifications@github.com wrote:

I pushed something else, please try again.

— You are receiving this because you commented.

Reply to this email directly, view it on GitHub https://github.com/iafilatov/libfprint/issues/5#issuecomment-405620124, or mute the thread https://github.com/notifications/unsubscribe-auth/AAjEHhLHnTjNnAs50NJTCcXdayEIwvutks5uHgAZgaJpZM4SBSwW .

[mumrau]

It seems working here too, no loop, enrolling successful. It looks like I cannot get a single successful verification, but the bug itself looks fixed.