[SOLVED] "scanimage: sane_start: Invalid argument" with a Canon LiDE 220 scanner

YuGiOhJCJ · 03-03-2021, 06:29 AM

Hello,

I own a Canon LiDE 220 scanner.
This scanner is working perfectly fine on Windows 8.1 (64-bit) so I suppose that it is not broken.

Here is what happens when I try to use it with SANE on Slackware 14.2 (64-bit):

Code:

$ scanimage --version
scanimage (sane-backends) 1.0.32; backend version 1.0.32
$ scanimage -L
device `genesys:libusb:001:004' is a Canon LiDE 220 flatbed scanner
$ scanimage >image.pnm
Output format is not set, using pnm as a default.
scanimage: sane_start: Invalid argument

Do you know how to fix that please?

Thank you.
Best regards.

hazel · 03-03-2021, 07:15 AM

You can often get more information on scanner problems by using sane's built-in debug options. Start by reading the sane man page. This will tell you (if you don't already know) what driver your scanner uses. Then look at the sane man page for that driver. All these drivers provide an environmental variable which you can set to a high number to get verbose error messages. For example, my Canoscan LIDE 25 scanner uses the plustek driver so I looked at sane-plustek. In sane-plustek the variable is called SANE_DEBUG_PLUSTEK and the other drivers probably use a similar nomenclature. So:

Code:

export SANE_DEBUG_PLUSTEK=255

Then run scanimage again.

You can also check if the error is due to a usb problem by setting the appropriate debug variable given on the SANE-USB man page. With any luck, the error messages will allow you to home in on where the problem is.

YuGiOhJCJ · 03-05-2021, 04:05 AM

OK I read the "sane" man:

Code:

$ man sane
[...]
genesys
         Supports several scanners based on the Genesys Logic GL646, GL841, GL843, GL847 and GL124 chips like the Medion 6471 and Hewlett-Packard 2300c.
          See sane-genesys(5) for details.
[...]

I already know that the driver is "genesys" because it is written here: http://sane-project.org/sane-mfgs.html#Z-CANON

Then I read the "sane-genesys" man:

Code:

$ man sane-genesys
[...]
      SANE_DEBUG_GENESYS
              If  the  library  was  compiled with debug support enabled, this
              environment variable controls the debug level for this  backend.
              Higher debug levels increase the verbosity of the output. If the
              debug level is set to 1 or higher,  some  debug  options  become
              available  that are normally hidden. Handle them with care. This
              will print messages related to core genesys functions.

[...]

Then I set the "SANE_DEBUG_GENESYS" environment variable to "255":

Code:

$ export SANE_DEBUG_GENESYS=255

Then I ran "scanimage -L":

Code:

$ scanimage -L
[10:43:55.508965] [sanei_debug] Setting debug level of genesys to 255.
[10:43:55.509092] [genesys] void genesys::sane_init_impl(SANE_Int*, SANE_Auth_Callback): start
[10:43:55.509109] [genesys] void genesys::sane_init_impl(SANE_Int*, SANE_Auth_Callback): [10:43:55.509121] [genesys] authorize != null[10:43:55.509131] [genesys] 
[10:43:55.509141] [genesys] SANE Genesys backend from sane-backends 1.0.32
[10:43:55.509168] [genesys] SANE Genesys backend built with libusb-1.0
[10:43:55.511595] [genesys] sane_init_impl: little endian machine
[10:43:55.511641] [genesys] void genesys::probe_genesys_devices(): start
[10:43:55.511757] [genesys] SANE_Status genesys::attach_one_device(SANE_String_Const): start
[10:43:55.511796] [genesys] genesys::Genesys_Device* genesys::attach_device_by_name(SANE_String_Const, bool): start
[10:43:55.511817] [genesys] genesys::Genesys_Device* genesys::attach_device_by_name(SANE_String_Const, bool): [10:43:55.511830] [genesys]  devname: libusb:001:005, may_wait = 0[10:43:55.511845] [genesys] 
[10:43:55.511859] [genesys] attach_device_by_name: trying to open device `libusb:001:005'
[10:43:55.511882] [genesys] virtual void genesys::UsbDevice::open(const char*): start
[10:43:55.512128] [genesys] virtual void genesys::UsbDevice::open(const char*): completed
[10:43:55.512152] [genesys] attach_device_by_name: device `libusb:001:005' successfully opened
[10:43:55.512169] [genesys] virtual uint16_t genesys::UsbDevice::get_vendor_id(): start
[10:43:55.512188] [genesys] virtual uint16_t genesys::UsbDevice::get_vendor_id(): completed
[10:43:55.512211] [genesys] virtual uint16_t genesys::UsbDevice::get_product_id(): start
[10:43:55.512231] [genesys] virtual uint16_t genesys::UsbDevice::get_product_id(): completed
[10:43:55.512254] [genesys] virtual void genesys::UsbDevice::close(): start
[10:43:55.512342] [genesys] virtual void genesys::UsbDevice::close(): completed
[10:43:55.512392] [genesys] attach_device_by_name: found 1193 flatbed scanner 6415 at libusb:001:005
[10:43:55.512443] [genesys] genesys::Genesys_Device* genesys::attach_device_by_name(SANE_String_Const, bool): completed
[10:43:55.512463] [genesys] SANE_Status genesys::attach_one_device(SANE_String_Const): completed
[10:43:55.512580] [genesys] probe_genesys_devices: 1 devices currently attached
[10:43:55.512608] [genesys] void genesys::probe_genesys_devices(): completed
[10:43:55.512625] [genesys] void genesys::sane_init_impl(SANE_Int*, SANE_Auth_Callback): completed
[10:43:55.512653] [genesys] void genesys::sane_get_devices_impl(const SANE_Device***, SANE_Bool): start
[10:43:55.512677] [genesys] void genesys::sane_get_devices_impl(const SANE_Device***, SANE_Bool): [10:43:55.512697] [genesys] local_only = false[10:43:55.512712] [genesys] 
[10:43:55.512881] [genesys] void genesys::probe_genesys_devices(): start
[10:43:55.512998] [genesys] SANE_Status genesys::attach_one_device(SANE_String_Const): start
[10:43:55.513019] [genesys] genesys::Genesys_Device* genesys::attach_device_by_name(SANE_String_Const, bool): start
[10:43:55.513031] [genesys] genesys::Genesys_Device* genesys::attach_device_by_name(SANE_String_Const, bool): [10:43:55.513041] [genesys]  devname: libusb:001:005, may_wait = 0[10:43:55.513055] [genesys] 
[10:43:55.513096] [genesys] attach_device_by_name: device `libusb:001:005' was already in device list
[10:43:55.513114] [genesys] genesys::Genesys_Device* genesys::attach_device_by_name(SANE_String_Const, bool): completed
[10:43:55.513134] [genesys] SANE_Status genesys::attach_one_device(SANE_String_Const): completed
[10:43:55.513248] [genesys] probe_genesys_devices: 1 devices currently attached
[10:43:55.513268] [genesys] void genesys::probe_genesys_devices(): completed
[10:43:55.513293] [genesys] SANE_Status genesys::check_present(SANE_String_Const): start
[10:43:55.513309] [genesys] SANE_Status genesys::check_present(SANE_String_Const): [10:43:55.513329] [genesys] libusb:001:005 detected.[10:43:55.513346] [genesys] 
[10:43:55.513359] [genesys] SANE_Status genesys::check_present(SANE_String_Const): completed
[10:43:55.513393] [genesys] void genesys::sane_get_devices_impl(const SANE_Device***, SANE_Bool): completed
device `genesys:libusb:001:005' is a Canon LiDE 220 flatbed scanner
[10:43:56.849937] [genesys] void genesys::sane_exit_impl(): start
[10:43:56.850200] [genesys] void genesys::sane_exit_impl(): completed

Then I ran "scanimage":

Code:

$ scanimage >image.pnm
Output format is not set, using pnm as a default.
[10:45:29.029165] [sanei_debug] Setting debug level of genesys to 255.
[10:45:29.029290] [genesys] void genesys::sane_init_impl(SANE_Int*, SANE_Auth_Callback): start
[10:45:29.029317] [genesys] void genesys::sane_init_impl(SANE_Int*, SANE_Auth_Callback): [10:45:29.029333] [genesys] authorize != null[10:45:29.029343] [genesys] 
[10:45:29.029352] [genesys] SANE Genesys backend from sane-backends 1.0.32
[10:45:29.029376] [genesys] SANE Genesys backend built with libusb-1.0
[10:45:29.031305] [genesys] sane_init_impl: little endian machine
[10:45:29.031336] [genesys] void genesys::probe_genesys_devices(): start
[...]
[10:45:34.092471] [genesys] virtual uint8_t genesys::ScannerInterfaceUsb::read_register(uint16_t): completed
[10:45:34.092473] [genesys] virtual uint8_t genesys::ScannerInterfaceUsb::read_register(uint16_t): start
[10:45:34.092474] [genesys] virtual void genesys::UsbDevice::control_msg(int, int, int, int, int, uint8_t*): start
[10:45:34.093003] [genesys] virtual void genesys::UsbDevice::control_msg(int, int, int, int, int, uint8_t*): failed
[10:45:34.093016] [genesys] virtual uint8_t genesys::ScannerInterfaceUsb::read_register(uint16_t): failed
[10:45:34.093020] [genesys] void genesys::sanei_genesys_read_valid_words(genesys::Genesys_Device*, unsigned int*): failed
[10:45:34.093025] [genesys] void genesys::sanei_genesys_read_data_from_scanner(genesys::Genesys_Device*, uint8_t*, size_t): failed
[10:45:34.093029] [genesys] genesys::Image genesys::read_unshuffled_image_from_scanner(genesys::Genesys_Device*, const genesys::ScanSession&, std::size_t): failed
[10:45:34.093035] [genesys] genesys::SensorExposure genesys::scanner_led_calibration(genesys::Genesys_Device&, const genesys::Genesys_Sensor&, genesys::Genesys_Register_Set&): failed
[10:45:34.093040] [genesys] void genesys::genesys_flatbed_calibration(genesys::Genesys_Device*, genesys::Genesys_Sensor&): failed
[10:45:34.093044] [genesys] void genesys::genesys_scanner_calibration(genesys::Genesys_Device*, genesys::Genesys_Sensor&): failed
[10:45:34.093050] [genesys] void genesys::genesys_start_scan(genesys::Genesys_Device*, bool): failed
[10:45:34.093052] [genesys] void genesys::sane_start_impl(SANE_Handle): failed
[10:45:34.093059] [genesys] sane_genesys_start: got error: Invalid argument
scanimage: sane_start: Invalid argument
[10:45:34.093090] [genesys] void genesys::sane_cancel_impl(SANE_Handle): start
[...]

I don't know what to do with this output.

Then I read the "sane-usb" man:
---
$ man sane-usb
[...]
SANE_DEBUG_SANEI_USB
If the library was compiled with debug support enabled, this
environment variable controls the debug level for the USB I/O
subsystem. E.g., a value of 128 requests all debug output to be
printed. Smaller levels reduce verbosity. Values greater than 4
enable libusb debugging (if available). Example: export
SANE_DEBUG_SANEI_USB=4.
[...]
---

And if I set "SANE_DEBUG_SANEI_USB" to "5", I am able to scan!

That's what is said here: https://gitlab.com/sane-project/back...note_513207464
I confirm, it works!

However, I don't understand how a debug variable can fix the problem.
Problem fixed with this workaround.

Thank you.
Best regards.

hazel · 03-05-2021, 04:24 AM

I'm glad you were able to find a solution yourself. That shows initiative!

Obviously the problem lies with the interface between the sane driver and libusb, which is why your debug run on the driver itself didn't yield anything of note.

As to how setting a debug variable can affect the behaviour (because obviously it ought not to), the thread you found includes a tentative explanation here:

Quote:

That's often indicative of a timing issue, assuming that at 5 or higher more log messages are output, leading to changed timing in code execution.
.....
My alternative guess was that some other system process (udev or some other similar tool) does some interval probing and if scanimage hits between the intervals, it succeeds, and if the probing is running, scanimage fails.

That's definitely buggy behaviour.