[fprint] uru4000, number of enroll stages

Tue Jun 24 13:01:24 PDT 2014

On Tue, 2014-06-24 at 22:46 +0300, Timo Teras wrote:
> On Tue, 24 Jun 2014 21:19:25 +0200
> Martin Hejnfelt <martin at duffman.dk> wrote:
> 
> > If it gives any clues, I can see that after the first stage, then the
> > imaging run state machine (imaging_run_state) is just blazing through
> > its states, 
> > IMAGING_CAPTURE -> IMAGING_SEND_INDEX -> IMAGING_DECODE ->
> > IMAGING_REPORT_IMAGE -> IMAGING_CAPTURE -> ...
> > in an endless loop...
> 
> Sounds like something mismatching wrt. to finger on/off detection and
> the capture loop. Could you send the debug traces including the first
> capture, and the one or two first looped ones after that. I think
> something goes wrong at the end of the first capture.

Here's the output, this is just the examples/enroll.c which does the
same as my own app (which is using async calls).
I've inserted the "* * * <state>" output via fp_dbg just to make it a
bit easier (for myself) to see whats going on...

Found device claimed by Digital Persona U.are.U 4000/4000B/4500 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 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
fp:debug [generic_acquire_start] action 1
drv:debug [__ssm_call_handler] 0x1bc40c0 entering state 0
uru4000:debug [sm_read_regs] read 1 regs at 7
sync:debug [fp_enroll_finger_img] uru4000 will handle enroll stage 0/4
uru4000:debug [sm_read_reg_cb] reg value 1
drv:debug [__ssm_call_handler] 0x1bc40c0 entering state 1
drv:debug [__ssm_call_handler] 0x1bc40c0 entering state 3
uru4000:debug [sm_set_hwstat] set 81
drv:debug [__ssm_call_handler] 0x1bc40c0 entering state 4
drv:debug [__ssm_call_handler] 0x1bc41c0 entering state 0
drv:debug [__ssm_call_handler] 0x1bc41c0 entering state 1
uru4000:debug [sm_set_hwstat] set 01
uru4000:debug [irq_handler] recv irq type 56aa
uru4000:debug [init_scanpwr_irq_cb] early scanpwr interrupt
drv:debug [__ssm_call_handler] 0x1bc41c0 entering state 2
uru4000:debug [sm_read_regs] read 1 regs at 7
uru4000:debug [sm_read_reg_cb] reg value 0
drv:debug [__ssm_call_handler] 0x1bc41c0 entering state 3
drv:debug [fpi_ssm_mark_completed] 0x1bc41c0 completed with status 0
drv:debug [__ssm_call_handler] 0x1bc40c0 entering state 5
drv:debug [__ssm_call_handler] 0x1bc40c0 entering state 6
drv:debug [__ssm_call_handler] 0x1bc40c0 entering state 7
uru4000:debug [sm_read_regs] read 16 regs at f0
uru4000:debug [sm_read_reg_cb] reg value 1a
drv:debug [__ssm_call_handler] 0x1bc40c0 entering state 8
uru4000:info [init_run_state] Versions 0010 and 0115
drv:debug [fpi_ssm_mark_completed] 0x1bc40c0 completed with status 0
uru4000:debug [execute_state_change] wait finger on
fp:debug [fpi_imgdev_activate_complete] status 0
async:debug [fpi_drvcb_enroll_started] status 0
uru4000:debug [execute_state_change] wait finger on
uru4000:debug [irq_handler] recv irq type 56aa
uru4000:warning [finger_presence_irq_cb] ignoring unexpected interrupt
56aa
uru4000:debug [irq_handler] recv irq type 0101
fp:debug [fpi_imgdev_report_finger_status] finger on sensor
uru4000:debug [execute_state_change] starting capture
drv:debug [__ssm_call_handler] 0x1ba9a40 entering state 0
uru4000:debug [imaging_run_state] * * * IMAGING_CAPTURE
drv:debug [__ssm_call_handler] 0x1ba9a40 entering state 1
uru4000:debug [imaging_run_state] * * * IMAGING_SEND_INDEX
uru4000:debug [imaging_run_state] hw header lines 289
drv:debug [__ssm_call_handler] 0x1ba9a40 entering state 2
uru4000:debug [imaging_run_state] * * * IMAGING_READ_KEY
uru4000:debug [sm_read_regs] read 4 regs at 34
uru4000:debug [sm_read_reg_cb] reg value fc
drv:debug [__ssm_call_handler] 0x1ba9a40 entering state 3
uru4000:debug [imaging_run_state] * * * IMAGING_DECODE
uru4000:debug [imaging_run_state] encryption id e0 -> key 678cb59b
uru4000:debug [imaging_run_state] 0 02 77
uru4000:debug [imaging_run_state] decoding 77 lines
uru4000:debug [imaging_run_state] 1 00 1
uru4000:debug [imaging_run_state] skipping 1 lines
uru4000:debug [imaging_run_state] 2 02 49
uru4000:debug [imaging_run_state] decoding 49 lines
uru4000:debug [imaging_run_state] 3 01 1
uru4000:debug [imaging_run_state] skipping 1 lines
uru4000:debug [imaging_run_state] 4 00 1
uru4000:debug [imaging_run_state] skipping 1 lines
uru4000:debug [imaging_run_state] 5 02 49
uru4000:debug [imaging_run_state] decoding 49 lines
uru4000:debug [imaging_run_state] 6 00 1
uru4000:debug [imaging_run_state] skipping 1 lines
uru4000:debug [imaging_run_state] 7 02 111
uru4000:debug [imaging_run_state] decoding 111 lines
drv:debug [__ssm_call_handler] 0x1ba9a40 entering state 4
uru4000:debug [imaging_run_state] * * * IMAGING_REPORT_IMAGE
fp:debug [fpi_img_new] length=111360
fp:debug [fpi_imgdev_image_captured] 
fp:debug [fpi_img_detect_minutiae] minutiae scan completed in 0.038548
secs
fp:debug [fpi_img_detect_minutiae] detected 29 minutiae
fp:debug [print_data_new] driver=02 devtype=0000
fp:debug [print_data_new] driver=02 devtype=0000
drv:debug [fpi_ssm_mark_completed] 0x1ba9a40 completed with status 0
uru4000:debug [execute_state_change] await finger off
uru4000:debug [irq_handler] recv irq type 0200
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 3
sync:debug [sync_enroll_cb] result 3
uru4000:debug [execute_state_change] starting capture
drv:debug [__ssm_call_handler] 0x1ba9a40 entering state 0
uru4000:debug [imaging_run_state] * * * IMAGING_CAPTURE
sync:debug [fp_enroll_finger_img] enroll stage passed
fp:debug [fp_img_save_to_file] written to 'enrolled.pgm'
Wrote scanned image to enrolled.pgm
Enroll stage passed. Yay!

Scan your finger now.
sync:debug [fp_enroll_finger_img] 
sync:debug [fp_enroll_finger_img] uru4000 will handle enroll stage 1/4
drv:debug [__ssm_call_handler] 0x1ba9a40 entering state 1
uru4000:debug [imaging_run_state] * * * IMAGING_SEND_INDEX
uru4000:debug [imaging_run_state] hw header lines 289
drv:debug [__ssm_call_handler] 0x1ba9a40 entering state 2
uru4000:debug [imaging_run_state] * * * IMAGING_READ_KEY
uru4000:debug [sm_read_regs] read 4 regs at 34
uru4000:debug [sm_read_reg_cb] reg value 8b
drv:debug [__ssm_call_handler] 0x1ba9a40 entering state 3
uru4000:debug [imaging_run_state] * * * IMAGING_DECODE
uru4000:debug [imaging_run_state] encryption id e1 -> key 6c067d4d
uru4000:debug [imaging_run_state] 0 02 77
uru4000:debug [imaging_run_state] decoding 77 lines
uru4000:debug [imaging_run_state] 1 00 1
uru4000:debug [imaging_run_state] skipping 1 lines
uru4000:debug [imaging_run_state] 2 02 49
uru4000:debug [imaging_run_state] decoding 49 lines
uru4000:debug [imaging_run_state] 3 01 1
uru4000:debug [imaging_run_state] skipping 1 lines
uru4000:debug [imaging_run_state] 4 00 1
uru4000:debug [imaging_run_state] skipping 1 lines
uru4000:debug [imaging_run_state] 5 02 49
uru4000:debug [imaging_run_state] decoding 49 lines
uru4000:debug [imaging_run_state] 6 00 1
uru4000:debug [imaging_run_state] skipping 1 lines
uru4000:debug [imaging_run_state] 7 02 111
uru4000:debug [imaging_run_state] decoding 111 lines
drv:debug [__ssm_call_handler] 0x1ba9a40 entering state 4
uru4000:debug [imaging_run_state] * * * IMAGING_REPORT_IMAGE
fp:debug [fpi_img_new] length=111360
fp:debug [fpi_imgdev_image_captured] 
fp:debug [fpi_imgdev_image_captured] ignoring due to current state 2
drv:debug [__ssm_call_handler] 0x1ba9a40 entering state 0
uru4000:debug [imaging_run_state] * * * IMAGING_CAPTURE
drv:debug [__ssm_call_handler] 0x1ba9a40 entering state 1
uru4000:debug [imaging_run_state] * * * IMAGING_SEND_INDEX
uru4000:debug [imaging_run_state] hw header lines 289
drv:debug [__ssm_call_handler] 0x1ba9a40 entering state 2
uru4000:debug [imaging_run_state] * * * IMAGING_READ_KEY
uru4000:debug [sm_read_regs] read 4 regs at 34
uru4000:debug [sm_read_reg_cb] reg value 3e
drv:debug [__ssm_call_handler] 0x1ba9a40 entering state 3
uru4000:debug [imaging_run_state] * * * IMAGING_DECODE
uru4000:debug [imaging_run_state] encryption id e2 -> key 63b77ff8
uru4000:debug [imaging_run_state] 0 02 77
uru4000:debug [imaging_run_state] decoding 77 lines
uru4000:debug [imaging_run_state] 1 00 1
uru4000:debug [imaging_run_state] skipping 1 lines
uru4000:debug [imaging_run_state] 2 02 49
uru4000:debug [imaging_run_state] decoding 49 lines
uru4000:debug [imaging_run_state] 3 01 1
uru4000:debug [imaging_run_state] skipping 1 lines
uru4000:debug [imaging_run_state] 4 00 1
uru4000:debug [imaging_run_state] skipping 1 lines
uru4000:debug [imaging_run_state] 5 02 49
uru4000:debug [imaging_run_state] decoding 49 lines
uru4000:debug [imaging_run_state] 6 00 1
uru4000:debug [imaging_run_state] skipping 1 lines
uru4000:debug [imaging_run_state] 7 02 111
uru4000:debug [imaging_run_state] decoding 111 lines
drv:debug [__ssm_call_handler] 0x1ba9a40 entering state 4
uru4000:debug [imaging_run_state] * * * IMAGING_REPORT_IMAGE
fp:debug [fpi_img_new] length=111360
fp:debug [fpi_imgdev_image_captured] 
fp:debug [fpi_imgdev_image_captured] ignoring due to current state 2
drv:debug [__ssm_call_handler] 0x1ba9a40 entering state 0
uru4000:debug [imaging_run_state] * * * IMAGING_CAPTURE
drv:debug [__ssm_call_handler] 0x1ba9a40 entering state 1
uru4000:debug [imaging_run_state] * * * IMAGING_SEND_INDEX
uru4000:debug [imaging_run_state] hw header lines 289
drv:debug [__ssm_call_handler] 0x1ba9a40 entering state 2
uru4000:debug [imaging_run_state] * * * IMAGING_READ_KEY
uru4000:debug [sm_read_regs] read 4 regs at 34
uru4000:debug [sm_read_reg_cb] reg value 9c
drv:debug [__ssm_call_handler] 0x1ba9a40 entering state 3
uru4000:debug [imaging_run_state] * * * IMAGING_DECODE
uru4000:debug [imaging_run_state] encryption id e3 -> key 94d35c5a

Hope it helps, and thanks :)

Martin