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

Thu Feb 9 01:22:18 UTC 2012

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

> 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

SANE_DEBUG_SANEI_USB > 10 turns on the hexdump of the USB packet
payloads and therefore changes the timing of when things happen.
More precisely, it changes the speed with which events proceed.

> 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

OK, we've got a read failure here.

> 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

And a successful write here.

> 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

And another read failure here.

> 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

Both read failures are logged after three attempts to read a byte, each
30 seconds apart.  That's 1.5 minutes for the first read failure and
another 1.5 minutes for the next.  There you go, three minutes exactly.
Note that the USB timeout is hard-coded to 30 seconds and the sanei_usb
code (as used by iscan) is responsible for the three time repeat.

> 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 trudged through the interpreter code and found something interesting
there that is *probably* the cause of this.  I haven't done any testing
so far but it appear that the first read failure is not handled the way
it should (or no attempts are made to prevent it in the first place).

FTR, it looks like the interpreter is running at a faster speed than the
device can handle.

> I continue my tests...

Don't bother.  It's a bug in the interpreter (thanks BTW for reporting
it) and unless a fixed interpreter plugin is released there's nothing
you can do (that's non-free software for you!).  I'll file a bug report
(internally) here and see if something can be done about it.

> Bests,

Sorry this doesn't help.  For the time being, I'd suggest working around
by scanning with the USB debugging turned on at levels > 10 and diverted
to /dev/null.  Yuck!

> 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,
>

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