[sane-devel] saned/Epson problems - second try

[Henning Meier-Geinitz]

Hi,

On Fri, Jan 03, 2003 at 09:41:17PM -0300, John Coppens wrote:
> A problem I reported last year. In short: I run saned from inetd, with the
> EPSON backend. Xsane seems to run erratically, and produces 'Invalid
> argument' error windows. Henning proposed a few tests which I could just
> now realize. Below are the comments and some log extracts:

> > Do you get the same problems with other frontends (xscanimage,
> > quiteinsane, scanimage)? No? -> xsane problem (unlikely)
> 
> I've tried: xscanimage (same error), scanimage (with several options
> such as --mode Color, --mode Gray, --mode Binary (!NO ERRORS HERE! no
> errors in any mode) Didn't have QuiteInsane... Am compiling Qt now to
> install it. Machine is slow, and won't be able to test today.

There are two main differences between scanimage and xsane/xscanimage:

1) scanimage only scans one image and closes the connection after that.
   No change in mode can be done, so if your problem only occurs when
   changing options repeatedly, this error jsut can't happen with
   scanimage.
2) scanimage can't do non-blocking IO. However, this only applies to
   actual scanning, it shouldn't cause any changes in setting options.

And maybe the timing is a bit different, that may also cause bugs to
(not) be visible.

> > Does it happen with other backends? If you don't have other scan
> > hardware, try the "test" backend. It does also happen? --> bug in
> > saned or net. I think that's unlikely, too, but I'm biased. We had
> > bugs in saned/net before but they resulted in crashes.

Any news from using the test backend? Try xsane net:hostname:test

> > You can try if it happens in debug mode, too. Comment out saned in
> > inetd.conf, restart inetd, and run saned in daemon mode from the
> > This will also enable debug messages. If the problem occurs in this
> > mode, too, you can also set epson debugging:
> 
> running saned -d128... 
> 
> 1) xscanimage runs without problems now?

That may be an indication of timing issues. However, I don't know if
these issues are in saned/net or in the actual backend.

> 2) starting xsane stops saned! This appears on screen:

You must restart saned -d after each session. It doesn't restart
itsself.

> [saned] process_request: got request 6
> [saned] process_request: waiting for request
> [saned] process_request: got request 3
> [saned] process_request: waiting for request
> [saned] process_request: got request 10
> [saned] quit: exiting

That's just a normal output (6 = get_parameters, 3 = close, 10 = exit).

> Restarted saned -d128, then xsane, runs fine but the problems changing
> the mode (Gray/Color/etc) reappear on screen (with the 'Invalid argument'
> messages). No indication (error) from the -d128.

> > SANE_DEBUG_EPSON=128 saned -d128
> 
> The error (invalid argument) appears when running xsane. No diagnotics on
> the screen. Just the normal comm:
> 
> [saned] process_request: got request 5
> [saned] process_request: waiting for request
> [saned] process_request: got request 5
> [saned] process_request: waiting for request


Then something went wrong. You should at least get the following
output (this is for scanimage -L, I don't have an epson scanner):

[saned] main: starting debug mode (level 128)
[saned] main: trying to get port for service sane' (getservbyname)
[saned] main: port is 6566
[saned] main: socket ()
[saned] main: setsockopt ()
[saned] main: bind ()
[saned] main: listen ()
[saned] main: waiting for control connection

now saned is waiting for a connection

[saned] check_host: access by remote host: 127.0.0.1
[saned] check_host: remote host is IN_LOOPBACK: access accepted
[saned] init: access by hmg@127.0.0.1 accepted
[saned] process_request: waiting for request
[saned] process_request: got request 1
[sanei_debug] Setting debug level of epson to 255.
[epson] sane_init: sane-backends 1.0.9-cvs
[epson] sane_init, ># epson.conf<

lots of more epson debugging removed

[epson] sane_get_devices()
[saned] process_request: waiting for request
[saned] process_request: got request 10
[saned] quit: exiting

So if you don't get the epson debugging messages, you either didn't
call saned correctly or something went wrong when insatlling
sane-backends.

> No weird messages on /var/log/debug either:
> 
> Jan  3 20:27:58 susan saned[10667]: init: access by saned-user@127.0.0.1
> accepte d
> Jan  3 20:28:02 susan saned[10667]: [epson] Requesting extended status
> Jan  3 20:28:02 susan saned[10667]: [epson] No error
> Jan  3 20:28:02 susan saned[10667]: [epson] Checking for ADF: (00)
> Jan  3 20:28:02 susan saned[10667]: [epson] Checking for TPU: (00)
> Jan  3 20:28:02 susan saned[10667]: [epson] Device name = GT-5000M

Huh? These are the epson debug messages. They shouldn't go to syslog
if you use saned -d128. They go to syslog when you use saned -s128.

I have the impression that you are not using saned from SANE 1.0.9 but
from 1.0.6 or before. This saned did print to syslog when started with
option "-d".

And in fact, these old saned versions had race conditions that may
cause bugs like yours.

Please double-check the version of saned you use. Maybe you have
installed in /usr/local, but there is an older saned in /usr/sbin.

If you don't get these messages when starting "saned -d128":

[saned] main: starting debug mode (level 128)
[saned] main: trying to get port for service sane' (getservbyname)
[saned] main: port is 6566
[saned] main: socket ()
[saned] main: setsockopt ()
[saned] main: bind ()
[saned] main: listen ()
[saned] main: waiting for control connection

Then you use an ancient version of saned. I think I'll add a version
number to the code when debugging is active so it's easier to find out.

> (On changing the scan mode I get the following)
> [net] sane_get_option_descriptor: option 2
> [net] sane_get_option_descripter: getting option descriptors
> [net] fetch_options: 0x80eb450
> [net] fetch_options: 47 option descriptors cached... freeing
> [net] fetch_options: get_option_descriptors
> [net] fetch_options: copying 47 option descriptors
> [net] fetch_options: 47 options fetched

The net backend is from 1.0.9 (at least it's rather current).

> [net] sane_control_option: option 2, action 1
> [net] sane_control_option: remote control option
> [net] sane_control_option: done (Invalid argument)

For me it really looks like the old race condition bug in saned.

Bye,
  Henning