[sane-devel] Suggestion to enhance log file output.

[G.W. Haywood]

Hi there,

We have a HP M1522n all-in-one printer which has been in continual use
for both printing and scanning for about the past fifteen years.  It's
connected (only) to our LAN with a static IP in the 192.168.x.x range.

All the workstations on our network are Linux boxes.  Most of the time
we use the simple-scan front end, but occasionally I'll use scanimage
at the command line.

Years ago when I first set up networking for the HP I did it manually.
I lied about the gateway - gave it a nonexistent IP - so it can't talk
to the Internet even if it tries.  It's been that way ever since.
Originally I used the HP-supplied software for Linux.  Life was good.

After I upgraded to Debian Buster the scanner stopped responding.
Printing continued to work just fine.  After much ado I installed
'airprint', and it started responding to scan requests once more.
Never did find out why hpaio: stopped working.

This time I upgraded to Bullseye.  Printing was still OK but the
scanner wasn't found by scanimage -L.  The scanning system resisted
several weeks of intermittent attempts to kick it into life.

Finally I tracked down the problem to an apparently damaged shared
library.  No idea what caused the damage.  It was simple to rectify by
a reinstall (and curiously enough hpaio: started working again, but I
guess that's down to something in the Bullseye upgrade).  But it was
almost by accident that I found the problem, and it took a long time.

I'm not really satisfied with that.

The debug file output is below at [***].  The docs at

http://www.sane-project.org/html/doc012.html

seem to deny that what it contains is possible.  Specfically, section
4.3.4 (sane_open) claims that the possible returned values are:

SANE_STATUS_DEVICE_BUSY
SANE_STATUS_INVAL
SANE_STATUS_IO_ERROR
SANE_STATUS_NO_MEM
SANE_STATUS_ACCESS_DENIED

but the returned value that I saw in the debug output from the command

8<----------------------------------------------------------------------8<----------------------------------------------------------------------
$ /usr/bin/simple-scan hpaio:/net/HP_LaserJet_M1522n_MFP?ip=192.168.44.169
8<----------------------------------------------------------------------8<----------------------------------------------------------------------

(output written into the file ~/.cache/simple-scan/simple-scan.log) is

SANE_STATUS_UNSUPPORTED

at +8.12s in the output.

[***] The entire log file output: [***]
8<----------------------------------------------------------------------8<----------------------------------------------------------------------
[+0.05s] DEBUG: simple-scan.vala:2012: Starting /usr/bin/simple-scan 3.38.1, PID=2919927
[+0.06s] DEBUG: unsetenv() is not thread-safe and should not be used after threads are created
[+0.08s] DEBUG: _g_io_module_get_default: Found default implementation gvfs (GDaemonVfs) for ‘gio-vfs’
[+0.18s] DEBUG: _g_io_module_get_default: Found default implementation dconf (DConfSettingsBackend) for ‘gsettings-backend’
[+0.29s] DEBUG: app-window.vala:1990: Loading state from /home/ged/.cache/simple-scan/state
[+0.30s] DEBUG: app-window.vala:1969: Restoring window to 1590x844 pixels
[+0.46s] DEBUG: scanner.vala:1548: sane_init () -> SANE_STATUS_GOOD
[+0.46s] DEBUG: scanner.vala:1554: SANE version 1.0.31
[+0.46s] DEBUG: scanner.vala:1615: Requesting redetection of scan devices
[+0.46s] DEBUG: scanner.vala:828: Processing request
[+0.55s] DEBUG: app-window.vala:2065: Saving state to /home/ged/.cache/simple-scan/state
[+0.75s] DEBUG: app-window.vala:2065: Saving state to /home/ged/.cache/simple-scan/state
[+6.72s] DEBUG: app-window.vala:2065: Saving state to /home/ged/.cache/simple-scan/state
[+7.08s] DEBUG: simple-scan.vala:1817: Requesting scan at 300 dpi from device 'hpaio:/net/HP_LaserJet_M1522n_MFP?ip=192.168.44.169'
[+7.08s] DEBUG: scanner.vala:1683: Scanner.scan ("hpaio:/net/HP_LaserJet_M1522n_MFP?ip=192.168.44.169", dpi=300, scan_mode=ScanMode.GRAY, depth=2, type=single, paper_width=0, paper_height=0, brightness=0, contrast=48, delay=3000ms)
[+7.41s] DEBUG: app-window.vala:2065: Saving state to /home/ged/.cache/simple-scan/state
[+7.91s] DEBUG: app-window.vala:2065: Saving state to /home/ged/.cache/simple-scan/state
[+8.12s] DEBUG: scanner.vala:341: sane_get_devices () -> SANE_STATUS_GOOD
[+8.12s] DEBUG: scanner.vala:828: Processing request
[+8.12s] DEBUG: scanner.vala:889: sane_open ("hpaio:/net/HP_LaserJet_M1522n_MFP?ip=192.168.44.169") -> SANE_STATUS_UNSUPPORTED
[+8.12s] WARNING: scanner.vala:893: Unable to open device: Operation not supported
[+8.28s] DEBUG: app-window.vala:2065: Saving state to /home/ged/.cache/simple-scan/state
[+8.50s] DEBUG: app-window.vala:2065: Saving state to /home/ged/.cache/simple-scan/state
[+11.75s] DEBUG: autosave-manager.vala:201: Deleting autosave records
[+11.76s] DEBUG: scanner.vala:1711: Stopping scan thread
[+11.76s] DEBUG: scanner.vala:828: Processing request
[+11.86s] DEBUG: scanner.vala:1722: sane_exit ()
8<----------------------------------------------------------------------8<----------------------------------------------------------------------

It wasn't until I came across a post on some forum which suggested
setting the environment variable SANE_DEBUG_DLL to 255 that I found
this output on the *terminal*, not in the file:

8<----------------------------------------------------------------------8<----------------------------------------------------------------------
zeroconf: ZEROCONF_MDNS_HINT: initial scan finished
zeroconf: device_list wait: OK
zeroconf: zeroconf_device_list_get: building list of devices
zeroconf: zeroconf_device_list_get: resulting list:
API: sane_get_devices(): done
[16:36:47.074438] [dll] load: searching backend `hpaio' in `/usr/lib/aarch64-linux-gnu/sane:/usr/lib/sane:/usr/lib64/sane'
[16:36:47.074509] [dll] load: trying to load `/usr/lib/aarch64-linux-gnu/sane/libsane-hpaio.so.1'
[16:36:47.074582] [dll] load: dlopen()ing `/usr/lib/aarch64-linux-gnu/sane/libsane-hpaio.so.1'
[16:36:47.075651] [dll] load: dlopen() failed (/lib/aarch64-linux-gnu/libhpip.so.0: invalid ELF header)
[16:36:47.075723] [dll] sane_get_devices: found 0 devices
[16:36:47.075903] [dll] sane_open: trying to open `hpaio://net/HP_LaserJet_M1522n_MFP?ip=192.168.44.169'
[16:36:47.075988] [dll] init: initializing backend `hpaio'
[16:36:47.076016] [dll] op_unsupported: call to unsupported backend operation
WSDD: 2001:470:6976:44:96bb:293b:bae0:63b9: done discovery
WSDD: 192.168.44.15: done discovery
WSDD: fe80::722b:79fb:927e:f503: done discovery
zeroconf: ZEROCONF_WSD: initial scan finished
[16:36:50.017799] [dll] sane_exit: exiting
8<----------------------------------------------------------------------8<----------------------------------------------------------------------

It seems to me that the log file content could have been a bit more
forthcoming.  The notion of "operation unsupported" is to me very
different from that of "broken shared object".

Did I miss something obvious?

Could the error message in the log file conveniently be improved?  It
would have saved me a *lot* of effort if it had mentioned the broken
shared object file.

-- 

73,
Ged.