scan failed, unpack requires a bytes object fo length 4

[teto]

Using current masters of paperwork(-backend), I can scan only once: the program starts with an exception, can scan once, then subsequent scans fails with gui popup: scan failed, unpack requires a bytes object fo length 4 I use python3.5

Here is the full log

(paperwork:7729): Gtk-WARNING **: Allocating size to GtkRevealer 0x55adf32ef300 without calling gtk_widget_get_preferred_width/height(). How does the code know the size to allocate?
INFO   paperwork.frontend.util.actions Action: [Scan a single page]
INFO   paperwork.frontend.util.config Will scan using genesys:libusb:003:009
WARNING paperwork.frontend.util.config Exception while configuring scanner: <class 'pyinsane2.sane.rawapi.SaneException'>: <class 'pyinsane2.sane.rawapi.SaneStatus'> : Data is invalid (4)
ERROR  paperwork.frontend.util.config <class 'pyinsane2.sane.rawapi.SaneStatus'> : Data is invalid (4)
Traceback (most recent call last):
  File "/home/teto/paperwork/paperwork/frontend/util/config.py", line 357, in get_scanner
    return _get_scanner(config, devid, preferred_sources)
  File "/home/teto/paperwork/paperwork/frontend/util/config.py", line 314, in _get_scanner
    if 'source' not in dev.options:
  File "/home/teto/.local/lib/python3.5/site-packages/pyinsane2/sane/abstract_proc.py", line 249, in _get_options
    options = remote_do("get_options", self.name)
  File "/home/teto/.local/lib/python3.5/site-packages/pyinsane2/sane/abstract_proc.py", line 74, in remote_do
    raise exc_class(*result['exception_args'])
pyinsane2.sane.rawapi.SaneException: <class 'pyinsane2.sane.rawapi.SaneStatus'> : Data is invalid (4)
INFO   paperwork.frontend.util.config Will try another scanner id: genesys:libusb:003:004
INFO   paperwork.frontend.util.config Will scan using genesys:libusb:003:004
ERROR  pyinsane2                      Unable to set scanner option [source]: Option is not active
INFO   paperwork.frontend.util.config Will scan at a resolution of 300
INFO   pyinsane2                      [resolution] set to [300]
INFO   pyinsane2                      [mode] set to [Color]
WARNING paperwork.frontend.mainwindow  Error while scanning: unpack requires a bytes object of length 4
ERROR  paperwork.frontend.diag        === UNCATCHED EXCEPTION ===
Traceback (most recent call last):
  File "/home/teto/paperwork/paperwork/frontend/util/actions.py", line 67, in on_button_clicked_cb
    return self.__do()
  File "/home/teto/paperwork/paperwork/frontend/util/actions.py", line 64, in __do
    return self.do(**kwargs)
  File "/home/teto/paperwork/paperwork/frontend/mainwindow/__init__.py", line 1412, in do
    scan_session = dev.scan(multiple=False)
  File "/home/teto/.local/lib/python3.5/site-packages/pyinsane2/sane/abstract_proc.py", line 258, in scan
    return ScanSession(self, multiple)
  File "/home/teto/.local/lib/python3.5/site-packages/pyinsane2/sane/abstract_proc.py", line 198, in __init__
    self._remote_session = remote_do('scan', scanner.name, multiple)
  File "/home/teto/.local/lib/python3.5/site-packages/pyinsane2/sane/abstract_proc.py", line 68, in remote_do
    length = struct.unpack("i", length)[0]
struct.error: unpack requires a bytes object of length 4

[teto]

hum there seems to be an old paperwork installed, I am gonna double check

[teto]

confirmed with latest source

[teto]

fixed via installing latest pyinsane2

[teto]

sorry for the noise, it seems to be intermittent (maybe after hibernation only) and now have it with master.

[jflesch]

It seems to be a bug in Pyinsane2, or maybe in your scanner drivers. Main problem here is that there is a workaround to prevent faulty drivers from crashing Paperwork. And this workaround hides the real stacktrace. However this workaround can be easily disabled:

cd /tmp
git clone https://github.com/jflesch/pyinsane.git
cd pyinsane

patch -p1 << EOF
diff --git a/src/pyinsane2/__init__.py b/src/pyinsane2/__init__.py
index bd3a6e7..b596ed2 100644
--- a/src/pyinsane2/__init__.py
+++ b/src/pyinsane2/__init__.py
@@ -25,7 +25,7 @@ elif sys.platform == "darwin":
     # The dedicated process appear to crash on MacOSX. Don't know why.
     from .sane.abstract import *
 else:
-    from .sane.abstract_proc import *
+    from .sane.abstract import *
 
 
 def __normalize_value(value):
EOF

python3 ./setup.py install

[jflesch]

Have you had time to test with the patch yet ?

[teto]

Seems like I have 2 different failures. The patch does not change anything. I tracked down one problem but I need to fix it. Was trying the testsuite of pyinsane but the first tests fail, are you able to make all of them work with your scanner ?

$ python3 setup.py test -v
running test
running egg_info
writing pyinsane2.egg-info/PKG-INFO
writing requirements to pyinsane2.egg-info/requires.txt
writing top-level names to pyinsane2.egg-info/top_level.txt
writing dependency_links to pyinsane2.egg-info/dependency_links.txt
reading manifest file 'pyinsane2.egg-info/SOURCES.txt'
reading manifest template 'MANIFEST.in'
warning: no files found matching '*.py' under directory 'src'
warning: no files found matching '*.glade' under directory 'src'
warning: no files found matching '*.xml' under directory 'src'
warning: no files found matching '*.css' under directory 'src'
warning: no files found matching '*.cpp' under directory 'src'
warning: no files found matching '*.h' under directory 'src'
warning: no files found matching 'example-paperwork.conf'
warning: no files found matching 'COPYING'
writing manifest file 'pyinsane2.egg-info/SOURCES.txt'
running build_ext
abstract (unittest.loader._FailedTest) ... ERROR
rawapi (unittest.loader._FailedTest) ... ERROR
abstract (unittest.loader._FailedTest) ... ERROR
rawapi (unittest.loader._FailedTest) ... ERROR
test_get_devices (tests.tests_abstract.TestSaneGetDevices) ... ok
test_get_option (tests.tests_abstract.TestSaneOptions) ... ^Cinterrupted

[jflesch]

The intend behind the patch is just to get the exact and detailed exception :-). Behavior should be the same.

[teto]

I found out the bug a long time ago but I didn't have a proper patch. Btw I tried with your patch and I find it harder to see the error xD

WARNING paperwork.frontend.util.config Exception while configuring scanner: <class 'pyinsane2.sane.rawapi.SaneException'>: <class 'pyinsane2.sane.rawapi.SaneStatus'> : Data is invalid (4)
ERROR  paperwork.frontend.util.config <class 'pyinsane2.sane.rawapi.SaneStatus'> : Data is invalid (4)
Traceback (most recent call last):
  File "/home/teto/paperwork/src/paperwork/frontend/util/config.py", line 379, in get_scanner
    return _get_scanner(config, devid, preferred_sources)
  File "/home/teto/paperwork/src/paperwork/frontend/util/config.py", line 336, in _get_scanner
    if 'source' not in dev.options:
  File "/home/teto/pyinsane/pyinsane2/sane/abstract.py", line 439, in _get_options
    self.__load_options()
  File "/home/teto/pyinsane/pyinsane2/sane/abstract.py", line 410, in __load_options
    self._open()
  File "/home/teto/pyinsane/pyinsane2/sane/abstract.py", line 395, in _open
    handle = rawapi.sane_open(self.name)
  File "/home/teto/pyinsane/pyinsane2/sane/rawapi.py", line 591, in sane_open
    raise SaneException(SaneStatus(status))
pyinsane2.sane.rawapi.SaneException: <class 'pyinsane2.sane.rawapi.SaneStatus'> : Data is invalid (4)

The problem is at some point pyinsane tried to unpack (now unpickle) data whereas 0 bytes were read: https://github.com/teto/pyinsane/commit/716734be9e549f7068666d835920f75c2fd72244#diff-25d5a2d88acd8bf8ea6f83bf72231b8fR71

[jflesch]

sane_open():

SANE_STATUS_INVAL:
    The device name is not valid. 

[jflesch]

The unpacking issue fails when the forked process of Pyinsane crashes (SIGSEGV). It doesn't tell us anything more than that. However, the exception here shouldn't have caused a crash ... Anyway, the source problem seems to be the sane_open() calls that fails.

[jflesch]

As previously stated, Pyinsane implements a workaround for crappy sane drivers. With this workaround (abstract_proc.py), when starting, Pyinsane forks. All the scan operations happen in another process.

The packing/unpacking is related to the communication with this other process. You shouldn't focus on the unpacking exception. It just hides the real problem.

The patch I provided disable this other process.

[teto]

Right I see your point. So I should fork libsane and see what's wrong ?

[jflesch]

Before that, it would be interesting to just see what Pyinsane gives to sane_open(). With the previous patch, you can just add a print() in sane_open() to see the exact value of dev_name.

[teto]

I'll add some logging in pyinsane2.

It tries to open "genesys:libusb:003:004".

INFO   pyinsane2.sane.rawapi          Opening device b'genesys:libusb:003:004'
WARNING paperwork.frontend.util.config Exception while configuring scanner: <class 'pyinsane2.sane.rawapi.SaneException'>: <class 'pyinsane2.sane.rawapi.SaneStatus'> : Data is invalid (4)
ERROR  paperwork.frontend.util.config <class 'pyinsane2.sane.rawapi.SaneStatus'> : Data is invalid (4)
Traceback (most recent call last):
  File "/home/teto/paperwork/src/paperwork/frontend/util/config.py", line 379, in get_scanner
    return _get_scanner(config, devid, preferred_sources)
  File "/home/teto/paperwork/src/paperwork/frontend/util/config.py", line 336, in _get_scanner
    if 'source' not in dev.options:
  File "/home/teto/pyinsane/pyinsane2/sane/abstract.py", line 439, in _get_options
    self.__load_options()
  File "/home/teto/pyinsane/pyinsane2/sane/abstract.py", line 410, in __load_options
    self._open()
  File "/home/teto/pyinsane/pyinsane2/sane/abstract.py", line 395, in _open
    handle = rawapi.sane_open(self.name)
  File "/home/teto/pyinsane/pyinsane2/sane/rawapi.py", line 595, in sane_open
    raise SaneException(SaneStatus(status))

Then I have

ERROR  pyinsane2                      Unable to set scanner option [source]: Option is not active
zsh: segmentation fault  paperwork

[jflesch]

When it happens (segfault), would it be possible to have the full output please ?

[jaesivsm]

I've also affected by this issue. I applied your patch and paperwork segfault when trying to scan a second document (it never fails when it's the first document that I scan).

Here's the complete traceback before crashing :

INFO   paperwork.frontend.util.canvas Animators: 1
INFO   paperwork.frontend.util.canvas Animators: 2
INFO   paperwork.frontend.util.canvas Animators: 1
INFO   paperwork.frontend.util.canvas Animators: 2
INFO   paperwork.frontend.util.canvas Animators: 1
INFO   paperwork.frontend.util.actions Action: [Scan a single page]
INFO   paperwork.frontend.util.config Will scan using genesys:libusb:001:004
WARNING paperwork.frontend.util.config Exception while configuring scanner: <class 'pyinsane2.sane.rawapi.SaneException'>: <class 'pyinsane2.sane.rawapi.SaneStatus'> : Data is invalid (4)
ERROR  paperwork.frontend.util.config <class 'pyinsane2.sane.rawapi.SaneStatus'> : Data is invalid (4)
Traceback (most recent call last):
  File "/home/jaes/.local/share/virtualenvs/paper/lib/python3.5/site-packages/paperwork/frontend/util/config.py", line 352, in get_scanner
    return _get_scanner(config, devid, preferred_sources)
  File "/home/jaes/.local/share/virtualenvs/paper/lib/python3.5/site-packages/paperwork/frontend/util/config.py", line 309, in _get_scanner
    if 'source' not in dev.options:
  File "/home/jaes/.local/share/virtualenvs/paper/lib/python3.5/site-packages/pyinsane2/sane/abstract.py", line 439, in _get_options
    self.__load_options()
  File "/home/jaes/.local/share/virtualenvs/paper/lib/python3.5/site-packages/pyinsane2/sane/abstract.py", line 410, in __load_options
    self._open()
  File "/home/jaes/.local/share/virtualenvs/paper/lib/python3.5/site-packages/pyinsane2/sane/abstract.py", line 395, in _open
    handle = rawapi.sane_open(self.name)
  File "/home/jaes/.local/share/virtualenvs/paper/lib/python3.5/site-packages/pyinsane2/sane/rawapi.py", line 591, in sane_open
    raise SaneException(SaneStatus(status))
pyinsane2.sane.rawapi.SaneException: <class 'pyinsane2.sane.rawapi.SaneStatus'> : Data is invalid (4)
INFO   paperwork.frontend.util.config Will try another scanner id: genesys:libusb:001:002
INFO   paperwork.frontend.util.config Will scan using genesys:libusb:001:002
ERROR  pyinsane2                      Unable to set scanner option [source]: Option is not active
INFO   paperwork.frontend.util.config Will scan at a resolution of 300
INFO   pyinsane2                      [resolution] set to [300]
INFO   pyinsane2                      [mode] set to [Color]
Segmentation fault (core dumped)