[sane-devel] scanimage freezes for 3 minutes with Epson Perfection V200 [epkowa]

Mon Feb 6 23:55:55 UTC 2012

"emmanuel.michel at wanadoo.fr" <emmanuel.michel at wanadoo.fr> writes:

> Thanks Olaf for taking the time to help.
>
> OK, now it's even more obscure for me now...
>
> Tonight, I still have the same 3 minutes delay if I do for example:
>
> SANE_DEBUG_DLL=255 scanimage -v -v -v > test.pnm 2> dll-verbose.log
>
> or simply
>
> scanimage > test.pnm
>
> But, if I do:
>
> SANE_DEBUG_SANEI_USB=255 scanimage -v -v -v > test.pnm 2> usb-verbose.log
>
> I have absolutely no delay!

Weird indeed.  Anyone have any idea why this might happen?

FYI, the epkowa backend uses sanei_usb_*_bulk() API to read and write
througout.  The interpreter gets two callbacks that wrap this API.  Do
note though that the backend uses a copy of sanei_usb.c from way back
(sane-backends 1.0.12, but we're updating as I write ;-).

> [SANEI_USB]
> 2012-02-06 22:34:34 scanimage: read 26780688 bytes in total

Looks like you did acquire an image so the backend is going through its
usual hoops.  For a moment, I considered that scanimage might have just
exited rightaway without doing anything.

> 2012-02-06 22:34:34 Closing device
> 2012-02-06 22:34:34 [sanei_usb] sanei_usb_write_bulk: trying to write
> 2 bytes
> 2012-02-06 22:34:34 [sanei_usb] 0000: 1E 93
> ................
> 2012-02-06 22:34:34 [sanei_usb] sanei_usb_write_bulk: wanted 2 bytes,
> wrote 2 bytes
> 2012-02-06 22:34:34 [sanei_usb] sanei_usb_read_bulk: trying to read 1 bytes
> 2012-02-06 22:34:34 [sanei_usb] 0000: 06             ................
> 2012-02-06 22:34:34 [sanei_usb] sanei_usb_read_bulk: wanted 1 bytes,
> got 1 bytes
> 2012-02-06 22:34:34 [sanei_usb] sanei_usb_write_bulk: trying to write
> 1 bytes
> 2012-02-06 22:34:34 [sanei_usb] 0000: 00             ................
> 2012-02-06 22:34:34 [sanei_usb] sanei_usb_write_bulk: wanted 1 bytes,
> wrote 1 bytes
> 2012-02-06 22:34:34 [sanei_usb] sanei_usb_read_bulk: trying to read 1 bytes
> 2012-02-06 22:34:34 [sanei_usb] 0000: 06             ........$
> 2012-02-06 22:34:34 [sanei_usb] sanei_usb_read_bulk: wanted 1 bytes,
> got 1 bytes
> 2012-02-06 22:34:34 [sanei_usb] sanei_usb_close: closing device 0
> 2012-02-06 22:34:34 Calling sane_exit
> 2012-02-06 22:34:34 scanimage: finished
>
> Regarding your SANEI_USB_KEEP_USBLP suggestion, I see no difference in
> the log. Can you please confirm the use of this variable ? I presume
> you want me to use the following command:
>
> SANE_DEBUG_SANEI_USB=255 SANEI_USB_KEEP_USBLP=no scanimage -v -v -v >
> test.pnm 2> usb-verbose.log

Yes, that usage is fine.  The reason you see no difference is probably
because the usblp kernel module is blacklisted (by CUPS, IIRC).  When
that's the case, the epkowa backend doesn't have to do anything special
to begin with.

The backend detaches the usblp module before scanning and re-attaches
it when done.  This is an ugly hack to get a number of all-in-ones to
behave again with 2.6.13 kernels or later.  I thought that maybe that
re-attaching was causing the 3 minute wait.  Guess not.

> Le 06/02/2012 04:53, Olaf Meeuwissen a écrit :
>> "emmanuel.michel at wanadoo.fr"<emmanuel.michel at wanadoo.fr>  writes:
>>
>>> The setup:
>>> Scanner EPSON Prefection V200
>>> OS Ubuntu Server 64 bits 10.04.3
>>>
>>> libsane 1.0.20-13ubuntu2
>>> sane-utils 1.0.20-13ubuntu2
>>> iscan 2.28.1-3.ltdl7
>>> iscan-data 1.14.0-1
>>> iscan-plugin-gt-f670 2.1.2-1
>>>
>>> The problem:
>>> Everytime I scan a document with scanimage I have to wait _exactly_ 3
>>> minutes before it returns to the command line. Below are the end of
>>> the debug logs from dll and epkowa:
>>>
>>> [DLL]
>>> 2012-02-05 20:48:31 scanimage: read 26780688 bytes in total
>>> 2012-02-05 20:48:31 [dll] sane_cancel(handle=0x1088da0)
>>> 2012-02-05 20:48:31 Closing device
>>> 2012-02-05 20:48:31 [dll] sane_close(handle=0x1088da0)
>>> 2012-02-05 20:51:31 Calling sane_exit
>>> 2012-02-05 20:51:31 [dll] sane_exit: exiting
>>> 2012-02-05 20:51:31 [dll] sane_exit: calling backend `epkowa's exit function
>>> 2012-02-05 20:51:31 [dll] sane_exit: finished
>>> 2012-02-05 20:51:31 scanimage: finished
>>>
>>> [EPKOWA]
>>> 2012-02-05 20:58:42 scanimage: read 26780688 bytes in total
>>> 2012-02-05 20:58:42 epkowa.c:5955: [epkowa]{C} sane_epkowa_cancel
>>> 2012-02-05 20:58:42 device.c:536: [epkowa]{C} dev_unlock
>>> 2012-02-05 20:58:42 Closing device
>>> 2012-02-05 20:58:42 epkowa.c:2554: [epkowa]{C} sane_epkowa_close
>>> 2012-02-05 20:58:42 device.c:242: [epkowa]{C} dev_close (fd = 0)
>>> 2012-02-05 21:01:42 Calling sane_exit
>>> 2012-02-05 21:01:42 backend.c:251: [epkowa]{C} sane_epkowa_exit ()
>>> 2012-02-05 21:01:42 dip-obj.c:152: [epkowa]{C} dip_exit (0x1fe46b0)
>>> 2012-02-05 21:01:42 cfg-obj.c:468: [epkowa]{C} cfg_has (0x1fdf630, 4)
>>> 2012-02-05 21:01:42 cfg-obj.c:468: [epkowa]{C} cfg_has (0x1fdf630, 3)
>>> 2012-02-05 21:01:42 cfg-obj.c:468: [epkowa]{C} cfg_has (0x1fdf630, 2)
>>> 2012-02-05 21:01:42 cfg-obj.c:468: [epkowa]{C} cfg_has (0x1fdf630, 1)
>>> 2012-02-05 21:01:42 cfg-obj.c:411: [epkowa]{C} cfg_exit (0x1fdf630)
>>> 2012-02-05 21:01:42 model-info.c:209: [epkowa]{C} model_info_cache_exit (0x1fdf$
>>> 2012-02-05 21:01:42 scanimage: finished
>>>
>>> As you can see, I always have this 3 minutes delay just after
>>> sane_close. I would be glad if someone could help me to understand
>>> what this temporal hole is about. Thanks in advance.
>>
>> This is caused by one or more of:
>>   - the interpreter taking its time to clean up and leave the device in a
>>     consistent state
>>   - the SANE USB layer taking its time to reattach the usblp module
>>
>> To identify the culprit could you please provide the relevant part of
>> the SANEI_USB log, with and without the SANEI_USB_KEEP_USBLP variable
>> set?  This environment variable can be set to completely disable the
>> (iscan specific) usblp module tweaks in the backend.

Sorry that this doesn't help,
-- 
Olaf Meeuwissen, LPIC-2           FLOSS Engineer -- AVASYS CORPORATION
FSF Associate Member #1962               Help support software freedom
                 http://www.fsf.org/jf?referrer=1962