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

Thu Feb 9 09:13:48 UTC 2012

Thanks a lot for your investigations Olaf ! At least, having an 
explanation/confirmation is a step towards a solution. Now eagerly 
waiting for a fix ;-)

In the meantime I'll return to scanbd as I'm about to succeed having all 
the 4 buttons working now :-)

Bests,

Emmanuel

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