Discussion:
scanimage freezes for 3 minutes with Epson Perfection V200 [epkowa]
(too old to reply)
e***@wanadoo.fr
2012-02-05 21:06:45 UTC
Permalink
Hello,

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.

Bests,

Emmanuel MICHEL
Olaf Meeuwissen
2012-02-06 03:53:08 UTC
Permalink
Post by e***@wanadoo.fr
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
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
[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.

Hope this helps,
--
Olaf Meeuwissen, LPIC-2 FLOSS Engineer -- AVASYS CORPORATION
FSF Associate Member #1962 Help support software freedom
http://www.fsf.org/jf?referrer=1962
e***@wanadoo.fr
2012-02-06 22:27:57 UTC
Permalink
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!

[SANEI_USB]
2012-02-06 22:34:34 scanimage: read 26780688 bytes in total
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

Thanks.

Emmanuel
Post by Olaf Meeuwissen
Post by e***@wanadoo.fr
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
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
[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.
- 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.
Hope this helps,
Olaf Meeuwissen
2012-02-06 23:55:55 UTC
Permalink
Post by e***@wanadoo.fr
Thanks Olaf for taking the time to help.
OK, now it's even more obscure for me now...
SANE_DEBUG_DLL=255 scanimage -v -v -v > test.pnm 2> dll-verbose.log
or simply
scanimage > test.pnm
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 ;-).
Post by e***@wanadoo.fr
[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.
Post by e***@wanadoo.fr
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
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.
Post by e***@wanadoo.fr
Post by Olaf Meeuwissen
Post by e***@wanadoo.fr
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
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
[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.
- 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
e***@wanadoo.fr
2012-02-07 12:50:12 UTC
Permalink
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
Post by Olaf Meeuwissen
Post by e***@wanadoo.fr
Thanks Olaf for taking the time to help.
OK, now it's even more obscure for me now...
SANE_DEBUG_DLL=255 scanimage -v -v -v> test.pnm 2> dll-verbose.log
or simply
scanimage> test.pnm
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 ;-).
Post by e***@wanadoo.fr
[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.
Post by e***@wanadoo.fr
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
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.
Post by e***@wanadoo.fr
Post by Olaf Meeuwissen
Post by e***@wanadoo.fr
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
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
[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.
- 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
2012-02-09 01:22:18 UTC
Permalink
Post by e***@wanadoo.fr
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.
Post by e***@wanadoo.fr
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
Resource temporarily unavailable
OK, we've got a read failure here.
Post by e***@wanadoo.fr
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.
Post by e***@wanadoo.fr
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
Resource temporarily unavailable
And another read failure here.
Post by e***@wanadoo.fr
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.
Post by e***@wanadoo.fr
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.
Post by e***@wanadoo.fr
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.
Post by e***@wanadoo.fr
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!
Post by e***@wanadoo.fr
Emmanuel
Post by Olaf Meeuwissen
Post by e***@wanadoo.fr
Thanks Olaf for taking the time to help.
OK, now it's even more obscure for me now...
SANE_DEBUG_DLL=255 scanimage -v -v -v> test.pnm 2> dll-verbose.log
or simply
scanimage> test.pnm
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 ;-).
Post by e***@wanadoo.fr
[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.
Post by e***@wanadoo.fr
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
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.
Post by e***@wanadoo.fr
Post by Olaf Meeuwissen
Post by e***@wanadoo.fr
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
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
[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.
- 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
e***@wanadoo.fr
2012-02-09 09:13:48 UTC
Permalink
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
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
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
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
Post by Olaf Meeuwissen
Post by e***@wanadoo.fr
Thanks Olaf for taking the time to help.
OK, now it's even more obscure for me now...
SANE_DEBUG_DLL=255 scanimage -v -v -v> test.pnm 2> dll-verbose.log
or simply
scanimage> test.pnm
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 ;-).
Post by e***@wanadoo.fr
[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.
Post by e***@wanadoo.fr
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
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.
Post by e***@wanadoo.fr
Post by Olaf Meeuwissen
Post by e***@wanadoo.fr
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
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
[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.
- 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
2012-02-09 11:33:58 UTC
Permalink
Post by e***@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
Post by e***@wanadoo.fr
Bests,
Emmanuel
Post by e***@wanadoo.fr
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.
Post by e***@wanadoo.fr
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
Resource temporarily unavailable
OK, we've got a read failure here.
Post by e***@wanadoo.fr
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.
Post by e***@wanadoo.fr
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
Resource temporarily unavailable
And another read failure here.
Post by e***@wanadoo.fr
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.
Post by e***@wanadoo.fr
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.
Post by e***@wanadoo.fr
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.
Post by e***@wanadoo.fr
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!
Post by e***@wanadoo.fr
Emmanuel
Post by e***@wanadoo.fr
Thanks Olaf for taking the time to help.
OK, now it's even more obscure for me now...
SANE_DEBUG_DLL=255 scanimage -v -v -v> test.pnm 2> dll-verbose.log
or simply
scanimage> test.pnm
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 ;-).
Post by e***@wanadoo.fr
[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.
Post by e***@wanadoo.fr
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
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.
Post by e***@wanadoo.fr
Post by Olaf Meeuwissen
Post by e***@wanadoo.fr
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
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
[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.
- 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
e***@wanadoo.fr
2012-02-09 16:31:57 UTC
Permalink
Wilhelm

I promise I'll post to confirm when it'll work. Problem is I'm a Linux
newbie so I'm slow as I discover a lot of things :-). scanbd is the
first program I compile (stop laughing please). For now I can confirm I
patched scanbd to add a scanbuttond backend specific to the Espon v200
(because as far as I know epkowa backend won't allow me to manage the
buttons of this scanner), I run it using xinetd, the 4 functions are
discovered so I'll make my scripts. After that, I'll try to make sure
saned is ok and better understand some parts of your doc to be sure
everything is OK. Such as for example the part "If scanbd is running on
a desktop machine..." which is obscure to me ;-)

I'm glad to have scanbd as it seems it will end the fight between saned
and scanbuttond. Thanks for it !

Bests,

Emmanuel
Post by Wilhelm
Post by e***@wanadoo.fr
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
e***@wanadoo.fr
2012-04-01 21:47:49 UTC
Permalink
Hi Wilhelm, Hi everyone,

As promised, this is my post to confirm I completed the install of
scanbd on Ubuntu with full support of all four buttons of an "EPSON
Perfection V200 Photo" scanner.

To share my findings, I posted the whole procedure (2 posts) here:

http://thehomeserverhandbook.com/2012/03/03/scanbd_part1/

which explains how to patch scanbd with an "EPSON V200" specific
backend, compile and install it.


http://thehomeserverhandbook.com/2012/03/18/scanbd_part2/

which explains scanbd configuration including a nice script offering the
following functions:
- Single page scan to JPEG
- Instant copy (scan to printer)
- Email creation with JPEG or multi-page PDF attachment
- Multi-page PDF creation
All this using only the scanner front buttons!

Also included is a special udev rule allowing to start xinetd/scanbd
when the scanner is turned on and stop them when the scanner is turned off.

Enjoy!

Emmanuel

(PS: As Ubuntu seems to have replaced inetd/xinetd with upstart now, I
would be glad to start scanbd using upstart. Thanks in advance to those
who will help me.)
Post by Wilhelm
Wilhelm
I promise I'll post to confirm when it'll work. Problem is I'm a Linux
newbie so I'm slow as I discover a lot of things :-). scanbd is the
first program I compile (stop laughing please). For now I can confirm I
patched scanbd to add a scanbuttond backend specific to the Espon v200
(because as far as I know epkowa backend won't allow me to manage the
buttons of this scanner), I run it using xinetd, the 4 functions are
discovered so I'll make my scripts. After that, I'll try to make sure
saned is ok and better understand some parts of your doc to be sure
everything is OK. Such as for example the part "If scanbd is running on
a desktop machine..." which is obscure to me ;-)
I'm glad to have scanbd as it seems it will end the fight between saned
and scanbuttond. Thanks for it !
Bests,
Emmanuel
Post by Wilhelm
Post by e***@wanadoo.fr
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
Wilhelm
2012-04-04 06:54:34 UTC
Permalink
Post by e***@wanadoo.fr
Hi Wilhelm, Hi everyone,
As promised, this is my post to confirm I completed the install of
scanbd on Ubuntu with full support of all four buttons of an "EPSON
Perfection V200 Photo" scanner.
http://thehomeserverhandbook.com/2012/03/03/scanbd_part1/
which explains how to patch scanbd with an "EPSON V200" specific
backend, compile and install it.
many thanks to Emmanuel!

I just added the Epson V200 backend to scanbd/trunk. So the procedure
should be a little bit easier ...
Post by e***@wanadoo.fr
http://thehomeserverhandbook.com/2012/03/18/scanbd_part2/
which explains scanbd configuration including a nice script offering the
- Single page scan to JPEG
- Instant copy (scan to printer)
- Email creation with JPEG or multi-page PDF attachment
- Multi-page PDF creation
All this using only the scanner front buttons!
Also included is a special udev rule allowing to start xinetd/scanbd
when the scanner is turned on and stop them when the scanner is turned off.
Enjoy!
Emmanuel
(PS: As Ubuntu seems to have replaced inetd/xinetd with upstart now, I
would be glad to start scanbd using upstart. Thanks in advance to those
who will help me.)
Post by Wilhelm
Wilhelm
I promise I'll post to confirm when it'll work. Problem is I'm a Linux
newbie so I'm slow as I discover a lot of things :-). scanbd is the
first program I compile (stop laughing please). For now I can confirm I
patched scanbd to add a scanbuttond backend specific to the Espon v200
(because as far as I know epkowa backend won't allow me to manage the
buttons of this scanner), I run it using xinetd, the 4 functions are
discovered so I'll make my scripts. After that, I'll try to make sure
saned is ok and better understand some parts of your doc to be sure
everything is OK. Such as for example the part "If scanbd is running on
a desktop machine..." which is obscure to me ;-)
I'm glad to have scanbd as it seems it will end the fight between saned
and scanbuttond. Thanks for it !
Bests,
Emmanuel
Post by Wilhelm
Post by e***@wanadoo.fr
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
--
Wilhelm
Loading...