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

Tue Feb 7 12:50:12 UTC 2012

OK.

After further investigations, here is what I found so far:

SANE_DEBUG_SANEI_USB=11 scanimage -v -v -v --format=tiff> test.tiff 2> 
usb-verbose-11.log

gives no delay at all but I can hear the carriage hangs/stops few times 
(each time being a millisecond or so) during the scan.

[SANE_DEBBUG_SANEI_USB=11]
2012-02-07 12:25:06 scanimage: read 26780688 bytes in total
2012-02-07 12:25:06 Closing device
2012-02-07 12:25:06 [sanei_usb] sanei_usb_write_bulk: trying to write 2 
bytes
2012-02-07 12:25:06 [sanei_usb] 0000: 1E 93               ................
2012-02-07 12:25:06 [sanei_usb] sanei_usb_write_bulk: wanted 2 bytes, 
wrote 2 bytes
2012-02-07 12:25:06 [sanei_usb] sanei_usb_read_bulk: trying to read 1 bytes
2012-02-07 12:25:06 [sanei_usb] 0000: 06               ................
2012-02-07 12:25:06 [sanei_usb] sanei_usb_read_bulk: wanted 1 bytes, got 
1 bytes
2012-02-07 12:25:06 [sanei_usb] sanei_usb_write_bulk: trying to write 1 
bytes
2012-02-07 12:25:06 [sanei_usb] 0000: 00               ................
2012-02-07 12:25:06 [sanei_usb] sanei_usb_write_bulk: wanted 1 bytes, 
wrote 1 bytes
2012-02-07 12:25:06 [sanei_usb] sanei_usb_read_bulk: trying to read 1 bytes
2012-02-07 12:25:06 [sanei_usb] 0000: 06               ................
2012-02-07 12:25:06 [sanei_usb] sanei_usb_read_bulk: wanted 1 bytes, got 
1 bytes
2012-02-07 12:25:06 [sanei_usb] sanei_usb_close: closing device 0
2012-02-07 12:25:06 Calling sane_exit
2012-02-07 12:25:06 scanimage: finished

SANE_DEBUG_SANEI_USB=10 scanimage -v -v -v --format=tiff> test.tiff 2> 
usb-verbose-10.log

gives the bothering 3 minutes delay but the carriage movement during the 
scanning is perfectly smooth.

[SANE_DEBUG_SANEI_USB=10]
2012-02-07 12:29:48 scanimage: read 26780688 bytes in total
2012-02-07 12:29:48 Closing device
2012-02-07 12:29:48 [sanei_usb] sanei_usb_write_bulk: trying to write 2 
bytes
2012-02-07 12:29:48 [sanei_usb] sanei_usb_write_bulk: wanted 2 bytes, 
wrote 2 bytes
2012-02-07 12:29:48 [sanei_usb] sanei_usb_read_bulk: trying to read 1 bytes
2012-02-07 12:30:18 [sanei_usb] sanei_usb_read_bulk: trying to read 1 bytes
2012-02-07 12:30:48 [sanei_usb] sanei_usb_read_bulk: trying to read 1 bytes
2012-02-07 12:31:18 [sanei_usb] sanei_usb_read_bulk: read failed: 
Resource temporarily unavailable
2012-02-07 12:31:18 [sanei_usb] sanei_usb_write_bulk: trying to write 1 
bytes
2012-02-07 12:31:18 [sanei_usb] sanei_usb_write_bulk: wanted 1 bytes, 
wrote 1 bytes
2012-02-07 12:31:18 [sanei_usb] sanei_usb_read_bulk: trying to read 1 bytes
2012-02-07 12:31:48 [sanei_usb] sanei_usb_read_bulk: trying to read 1 bytes
2012-02-07 12:32:18 [sanei_usb] sanei_usb_read_bulk: trying to read 1 bytes
2012-02-07 12:32:48 [sanei_usb] sanei_usb_read_bulk: read failed: 
Resource temporarily unavailable
2012-02-07 12:32:48 [sanei_usb] sanei_usb_close: closing device 0
2012-02-07 12:32:48 Calling sane_exit
2012-02-07 12:32:48 scanimage: finished

I also noted that after a "3 minutes delay", I can't turn off the 
scanner (have to unplug it) so it seems something really bother it. As 
soon as I re-do a scan without the "3 minutes delay" (ie using 
SANE_DEBUG_SANEI_USB=11), then I can turn it off straight away without 
any problem.

I continue my tests...

Bests,

Emmanuel

Le 07/02/2012 00:55, Olaf Meeuwissen a écrit :
> "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,