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

[Wilhelm]

Am 09.02.2012 10:13, schrieb emmanuel.michel at wanadoo.fr:
> 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 :-)

Are there any issues regarding scanbd?

Regards,

Wilhelm

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


-- 
Wilhelm