Bug 1750899 - CANOSCAN N650U scanner device not correctly detected via USB
Summary: CANOSCAN N650U scanner device not correctly detected via USB
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: Fedora
Classification: Fedora
Component: sane-backends
Version: 32
Hardware: x86_64
OS: Linux
unspecified
high
Target Milestone: ---
Assignee: Nils Philippsen
QA Contact: Fedora Extras Quality Assurance
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2019-09-10 17:12 UTC by Peter Gückel
Modified: 2020-10-23 22:08 UTC (History)
5 users (show)

Fixed In Version: sane-backends-1.0.31-3.fc32 sane-backends-1.0.31-3.fc31 sane-backends-1.0.31-3.fc33
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed: 2020-10-12 14:41:54 UTC
Type: Bug
Embargoed:


Attachments (Terms of Use)
lusb (489 bytes, text/plain)
2019-09-11 17:34 UTC, Peter Gückel
no flags Details
scanimage (74.71 KB, text/plain)
2019-09-11 17:35 UTC, Peter Gückel
no flags Details
lsusb #2 (489 bytes, text/plain)
2019-09-12 18:07 UTC, Peter Gückel
no flags Details
scanimage #2 (215.43 KB, text/plain)
2019-09-12 18:08 UTC, Peter Gückel
no flags Details
debug.log (308.61 KB, text/plain)
2020-10-06 04:26 UTC, Peter Gückel
no flags Details
scan-debug.log (6.26 MB, text/plain)
2020-10-06 04:47 UTC, Peter Gückel
no flags Details
debug.log with latest rpms (301.44 KB, text/plain)
2020-10-07 23:34 UTC, Peter Gückel
no flags Details
scan-debug.log with latest rpms (840.88 KB, text/plain)
2020-10-07 23:35 UTC, Peter Gückel
no flags Details

Description Peter Gückel 2019-09-10 17:12:06 UTC
Description of problem:
Since smartphones, a simple photo suffices, but sometimes a 1:1 copy, unaffected by light, camera angle etc is desired. Wanting a good copy, I tried to make scan yesterday, using my trusted CANOSCAN N650U. This scanner has worked on Fedora for more than 10 years without problem—literally plug and play.

I plugged in the USB cable and launched XSane, clicked scan and it responded with some error message about an incorrect command or something. I noticed in the frame of the application window that it said camera video0. I am pretty sure that this is the built-in webcam on my laptop, not the /dev/ for the scanner. I searched through the program settings and also the files in ~/.sane, but I could find nowhere to change this. Also, I searched /dev, but I did not see any device that links to a /dev/scanner; I have no idea what the correct device would be. When I looked in KDE's InfoCentre, it showed my CanoScan as a device, but did not give me a clue what the /dev is supposed to be.

Frustrated, I launched Simple Scan and it searched ages for a scanner and finally showed a CanoScan N650U, but refused to scan. Frustrated, I installed SkanLite and nothing ever appeared on the screen: it must have crashed as soon as it was executed. For some reason, it seems that the correct device is no longer being detected for my scanner, that has worked on Fedora forever.

Version-Release number of selected component (if applicable):
xsane-0.999-33.fc30.x86_64

How reproducible:


Steps to Reproduce:
1.
2.
3.

Actual results:


Expected results:


Additional info:

Comment 1 Zdenek Dohnal 2019-09-11 08:03:24 UTC
Hi Peter,

thank you for reporting the issue!

Would you mind trying following commands, gather the logs into files and attach the files to the bugzilla?

1) $ lsusb &> lsusb_output

2) $ SANE_DEBUG_DLL=255 SANE_DEBUG_SANEI_USB=255 SANE_DEBUG_PLUSTEK=255 scanimage -L &> scanimage_L_log

Comment 2 Peter Gückel 2019-09-11 17:00:57 UTC
Thanks for respnding! I will get back to you tonight, in about 12 hours ;-)

Comment 3 Peter Gückel 2019-09-11 17:34:36 UTC
Created attachment 1614175 [details]
lusb

Comment 4 Peter Gückel 2019-09-11 17:35:26 UTC
Created attachment 1614176 [details]
scanimage

Comment 5 Peter Gückel 2019-09-11 17:37:03 UTC
I guess I still had a moment ;-)

Remind me what it means to have a command prompt starting with $ is it root or user? To be safe, I su sudoed.

The scanimage command did not finish and I had to ^c.

Comment 6 Zdenek Dohnal 2019-09-12 07:06:24 UTC
(In reply to Peter Gückel from comment #5)
> Remind me what it means to have a command prompt starting with $ is it root
> or user? To be safe, I su sudoed.

'$' is for user prompt, '#' is for root prompt. You do not know, uncle you-know-who knows ;)

> 
> The scanimage command did not finish and I had to ^c.

Thank you for the data!

The scanner is correctly recognized by 'lsusb'.

I can see following messages in scanimage log:

[sanei_usb] sanei_usb_write_bulk: trying to write 4 bytes
[sanei_usb] 000 01 07 00 01                                     ....            
[sanei_usb] sanei_usb_write_bulk: write failed: Input/output error
libusb: error [op_clear_halt] clear_halt failed error -1 errno 71

The issue happens during writing to the device.

There is a known issue about how linux kernels handle differently USB and xHCI, which causes problems for some scanners. Upstream advises to try setting SANE_USB_WORKAROUND environment variable to 1 in such cases.

Peter, would you mind trying following command in your terminal?

$ export SANE_USB_WORKAROUND=1

and try to scan?

Comment 7 Peter Gückel 2019-09-12 18:06:56 UTC
I put the command in the terminal and then I opened another tab in the terminal to dispay the value of the variable and it was unset (even though I had just set it). Instead, then, I put the command into .profile, sourced the file, and still no luck: the variable was unset inthe temrinal. Finally, I rebooted and tested the value of the variable in a terminal window and it responded with: 1.

I opened xsane. A very small window appeared, displaying xsane 0.999 in the frame, but there was nothing inside the window, just white. After over a minute, finally a selector appeared with 2 lines: one for the webcam and another for the scanner. I selected scanner and I tried to scan a preview in xsane. Immediately, an error message appeared: Failed to start scanner. Error during device I/O. I decided to rerun the 2 commands you gave me at the start and have included them here.

Next, I opened Simple Scan. It appeared immediately and in the window shows: Ready to Scan. Noname USB Camera: USB Camera. I tried to scan anyway and a window appeared with the fuzzy webcam display.

Finally, I opened SkanLite and, like a day ago, absoutely nothing happened: no window appeared on the desktop; no visible response. Crashed?

In over 10 years, might I remind you, I have had no problems using this scanner with Fedora. Some kind of error has crept in somewhere. I don't scan a lot, perhaps only a few times a year, at best, but when I need a scan, only a scan will do.

Comment 8 Peter Gückel 2019-09-12 18:07:27 UTC
Created attachment 1614617 [details]
lsusb #2

Comment 9 Peter Gückel 2019-09-12 18:08:05 UTC
Created attachment 1614618 [details]
scanimage #2

Comment 10 Zdenek Dohnal 2019-09-13 05:46:16 UTC
Reported upstream https://gitlab.com/sane-project/backends/issues/137

Comment 11 Peter Gückel 2019-09-14 01:46:19 UTC
Is there any action I need to take?

Comment 12 Zdenek Dohnal 2019-09-16 08:01:45 UTC
Hi Peter,

you can follow the upstream issue and if they want more info, you can provide it and minimize the delay between I send it to them from this bugzilla tracker.

Comment 13 Peter Gückel 2019-10-22 18:20:00 UTC
I (clean-)installed Fedora 31 on Saturday night (3 days before release) and have upgraded to the latest packages on updates-testing and all other repos. I had noticed that there were a number of updates to sane* while I was still on F30, but I never got around to testing. I am presuming that these new versions are the ones in F31, so...

I just tried the scanner. Nothing happened. XSane reported, in the top of the window, that it was using the USB Camera (dev/video0). Out of curiosity, I clicked acquire preview and it reported failed to start scanner: invalid argument.

Then, I uncommented the export SANE_USB_WORKAROUND=1 line in .profile and sourced it. I ran XSane again, with the same result: USB Camera and failed to start scanner. It does not work in F31.

Comment 14 Zdenek Dohnal 2020-09-15 13:00:56 UTC
I was able to trace down the possible source of error based on log, sane-backends and libusbx source code.

I used logs without SANE_USB_WORKAROUND=1 - it seems the code execution got further without it.

The first error comes when plustek backend is trying to set register 0x59:

sanei_lm983x_write_byte( dev->fd, 0x59, regs[0x59] );

libusb_bulk_transfer() from libusbx is called under this function. Then IO error comes from submit_bulk_transfer() - specifically from ioctl call - errno is set (right now to unknown value) and LIBUSB_ERROR_IO is returned afterwards.

But plustek backend goes further and calls libusb_clear_halt(), which, thankfully, shows the possible real errno (since the command is called on the same file descriptor, so maybe the errno is still the same). We can see that on the line:

libusb: error [op_clear_halt] clear_halt failed error -1 errno 71

Errno 71 is EPROTO - which is 'Protocol error', but I don't know what it can mean right know.

Hans, would you mind helping me here? What can cause EPROTO during op_clear_halt? Probably the same errno is hit in libusb_bulk_transfer too...

Comment 15 Hans de Goede 2020-09-15 13:09:51 UTC
EPROTO means that there was a low-level USB transaction error. Typical causes of this are a bad cable, or bad and/or dirty connectors. I guess it is possible to also get this when causing the scanner to crash by sending it bad data, but that is unlikely.

Looking at the lsusb output, atm the scanner is connected to a PC which has a single XHCI controller.

What might be worth trying is connecting it to an older PC which still has USB-2 only ports which are connected to an EHCI controller. This could be an incompatibility between the XHCI controller and the scanner and/or Linux's XHCI driver and the scanner.

Comment 16 Zdenek Dohnal 2020-09-16 06:26:50 UTC
(In reply to Hans de Goede from comment #15)
> What might be worth trying is connecting it to an older PC which still has
> USB-2 only ports which are connected to an EHCI controller. This could be an
> incompatibility between the XHCI controller and the scanner and/or Linux's
> XHCI driver and the scanner.

If that have been the case, wouldn't it show at the beginning of communication? Here the device and the backend is capable of communication for some time (capable to transfer few bulks), but it went sour after trying to write into specific register.

However, sane-backends is capable to workaround XHCI driver problems with SANE_USB_WORKAROUND environment variable in a way - it uses libusb_set_interface_alt_setting() when closing the device (before calling libusb_release_interface()) and before using libusb_clear_halt() (when issuing clear_halt command).

The user already tried setting the env variable - the device discovery ended even sooner than without env variable. It ended on the first libusb_bulk_transfer() on the first register. The workaround, as I wrote above, cannot influence this IMO. It can influence clear_halt op which comes after:

libusb: error [op_clear_halt] clear_halt failed error -1 errno 71
[plustek]  * could not read version register!
[sanei_usb] sanei_usb_close: evaluating environment variable SANE_USB_WORKAROUND
[sanei_usb] sanei_usb_close: workaround: 1
[sanei_usb] sanei_usb_close: closing device 0
[sanei_usb] sanei_usb_set_altinterface: alternate = 0
libusb: error [op_set_interface] setintf failed error -1 errno 71
[sanei_usb] sanei_usb_set_altinterface: libusb complained: Other error

but still fails even with the workaround, with EPROTO errno.

Is it possible that device registers are damaged or worn out after the years and now writing to them fails randomly?

Comment 17 Hans de Goede 2020-09-16 06:47:25 UTC
(In reply to Zdenek Dohnal from comment #16)
> (In reply to Hans de Goede from comment #15)
> > What might be worth trying is connecting it to an older PC which still has
> > USB-2 only ports which are connected to an EHCI controller. This could be an
> > incompatibility between the XHCI controller and the scanner and/or Linux's
> > XHCI driver and the scanner.
> 
> If that have been the case, wouldn't it show at the beginning of
> communication?

Maybe.

> Here the device and the backend is capable of communication
> for some time (capable to transfer few bulks), but it went sour after trying
> to write into specific register.

Yes that does sound like the issue is the sane-backend tickling the scanner in a way is does not like.

> However, sane-backends is capable to workaround XHCI driver problems with
> SANE_USB_WORKAROUND environment variable in a way - it uses
> libusb_set_interface_alt_setting() when closing the device (before calling
> libusb_release_interface()) and before using libusb_clear_halt() (when
> issuing clear_halt command).
> 
> The user already tried setting the env variable - the device discovery ended
> even sooner than without env variable.

That is not really surprising, I find that a weird workaround, esp. the calling of libusb_set_interface_alt_setting() before calling libusb_clear_halt() sounds weird.

One thing which is a known issue with XHCI controllers which this workaround does not seem to address is timing. EHCI controllers schedule new usb-transfers using a 1 ms clock. So when the bulk transfer ends and the register write is then done, the EHCI controller will wait for the next 1 ms timer-tick before executing the register write, where as XHCI will execute it immediately. So you could try building a version of sane with a usleep(1000) added before the offending register write.

> Is it possible that device registers are damaged or worn out after the years and now writing to them fails randomly?

Sure the device could be defective, but I would expect the defect to be in the power-supply (capacitors gone bad) it is possible that the register write's intention is to trigger the scan-head to move (e.g. reset it to its home position) mand then as soon as the scanner tries to power up the motor this causes interference on the power-supply lines.

Again if possible it would be good to try the scanner with an EHCI USB controller, if it does not work there either then the scanner might indeed be defective.

Comment 18 Zdenek Dohnal 2020-09-16 08:45:32 UTC
(In reply to Hans de Goede from comment #15)
> Looking at the lsusb output, atm the scanner is connected to a PC which has
> a single XHCI controller.
> 

Do I understand correctly 'Linux Foundation 3.0 root hub' entry means XHCI controller is used? Is it always like this way?

Because if I check my PC I have:

Bus 002 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub

but when I check it via 'lsusb -t' I see:

/:  Bus 02.Port 1: Dev 1, Class=root_hub, Driver=xhci_hcd/11p, 480M

So USB 2.0 hub can be XHCI, but USB 3.0 hub cannot be EHCI?

I'm sorry for such questions, but I'm not experienced in USB stuff.

(In reply to Hans de Goede from comment #17)
> That is not really surprising, I find that a weird workaround, esp. the
> calling of libusb_set_interface_alt_setting() before calling
> libusb_clear_halt() sounds weird.
> 
> One thing which is a known issue with XHCI controllers which this workaround
> does not seem to address is timing. EHCI controllers schedule new
> usb-transfers using a 1 ms clock. So when the bulk transfer ends and the
> register write is then done, the EHCI controller will wait for the next 1 ms
> timer-tick before executing the register write, where as XHCI will execute
> it immediately. So you could try building a version of sane with a
> usleep(1000) added before the offending register write.

Is there a best practice how to deal with such issues in the code which supposes to work for EHCI and XHCI? Or only by implementing sleeps between bulk transfers?

Comment 19 Zdenek Dohnal 2020-09-16 08:48:36 UTC
Hi Peter,

are you capable of trying the scanner on PC which has only USB 2.0 ports with EHCI controllers?

You can check it by `lsusb -t`, there shouldn't be (IIUC) any 'xhci_hcd'.

Comment 20 Peter Gückel 2020-09-18 05:21:30 UTC
(In reply to Zdenek Dohnal from comment #19)
> Hi Peter,
> 
> are you capable of trying the scanner on PC which has only USB 2.0 ports
> with EHCI controllers?
> 
> You can check it by `lsusb -t`, there shouldn't be (IIUC) any 'xhci_hcd'.

The command returns:

/:  Bus 02.Port 1: Dev 1, Class=root_hub, Driver=xhci_hcd/4p, 5000M
/:  Bus 01.Port 1: Dev 1, Class=root_hub, Driver=xhci_hcd/11p, 480M
    |__ Port 1: Dev 9, If 0, Class=Vendor Specific Class, Driver=, 12M
    |__ Port 3: Dev 3, If 2, Class=Human Interface Device, Driver=, 12M
    |__ Port 3: Dev 3, If 0, Class=Human Interface Device, Driver=usbhid, 12M
    |__ Port 3: Dev 3, If 1, Class=Human Interface Device, Driver=usbhid, 12M
    |__ Port 5: Dev 4, If 0, Class=Video, Driver=uvcvideo, 480M
    |__ Port 5: Dev 4, If 1, Class=Video, Driver=uvcvideo, 480M
    |__ Port 6: Dev 5, If 0, Class=Wireless, Driver=btusb, 12M
    |__ Port 6: Dev 5, If 1, Class=Wireless, Driver=btusb, 12M
    |__ Port 8: Dev 6, If 0, Class=Vendor Specific Class, Driver=rtsx_usb, 480M

Comment 21 Peter Gückel 2020-09-18 05:24:57 UTC
I only have this laptop and no access to another computer.

Comment 22 Peter Gückel 2020-09-18 05:37:31 UTC
It's insane. I tried it with the SANE_USB_WORKAROUND variable both unset and set and nothing happened. The scanner does not show any sign of life. XSane was unable to find any scanning device and gnome's (?) Document Scanner only found the laptop's built-in camera.

Perhaps it's just too old, even though it would surprise me to find that it truly is broken, to bother with any longer?

Comment 23 Zdenek Dohnal 2020-09-21 07:39:52 UTC
We can try what Hans suggests - put 1ms sleep before every bulk transfer when SANE_XHCI_WORKAROUND is used (I created a new env variable for this purpose...).

Please install rpms from this build:


And try (without SANE_USB_WORKAROUND active):

SANE_DEBUG_SANEI_USB=255 SANE_DEBUG_DLL=255 SANE_DEBUG_PLUSTEK=255 SANE_XHCI_WORKAROUND=1 scanimage -L &> debug.log

if it works and upload the debug.log file.

Comment 24 Zdenek Dohnal 2020-09-21 07:48:29 UTC
Sorry, didn't copy the link:

https://koji.fedoraproject.org/koji/taskinfo?taskID=51937896

Comment 25 Hans de Goede 2020-09-21 07:57:42 UTC
(In reply to Zdenek Dohnal from comment #18)
> Do I understand correctly 'Linux Foundation 3.0 root hub' entry means XHCI
> controller is used? Is it always like this way?

If there is a "3.0 root hub" then yes there must be a XHCI controller, because EHCI only does USB 2.0 and 1.x . An XHCI controller will always show up as 2 buses a 3.x (5000M or 10000M) bus and a 2.0 (480M) bus.

But earlier machines with USB 3.0 machine often had both a XHCI controller with a few ports and an EHCI controller with a whole bunch of 2.0 ports. So there in lsusb -t you will see 3 busses, 1 3.x bus and 1 2.0 bus both with xhci_hcd as driver and another 2.0 bus with ehci_hcd as driver,

> Because if I check my PC I have:
> 
> Bus 002 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub
> 
> but when I check it via 'lsusb -t' I see:
> 
> /:  Bus 02.Port 1: Dev 1, Class=root_hub, Driver=xhci_hcd/11p, 480M
> 
> So USB 2.0 hub can be XHCI, but USB 3.0 hub cannot be EHCI?

Correct, see above.

> Is there a best practice how to deal with such issues in the code which
> supposes to work for EHCI and XHCI? Or only by implementing sleeps between
> bulk transfers?

If this is the issue, then the issue really is a bug inside the scanner, where it cannot handle requests if they come to quickly behind each other. But this bug has always been covered up by the EHCI controller's scheduling behavior. So yes if the 1 ms sleep help, then the only way to fix this is to add them inside the driver for that specific scanner. Also ideally only where necessary (e.g. before and/or after the troublesome register write) and not everywhere.

Comment 26 Hans de Goede 2020-09-21 07:57:54 UTC
(In reply to Zdenek Dohnal from comment #23)
> We can try what Hans suggests - put 1ms sleep before every bulk transfer
> when SANE_XHCI_WORKAROUND is used (I created a new env variable for this
> purpose...).

Note it is not just bulk transfers which need a sleep before them, also control transfers. You said it was a register write which was failing, I would expect that to be a control transfer. But I guess the scanner might use bulk transfers for those?

Comment 27 Zdenek Dohnal 2020-09-21 09:03:09 UTC
(In reply to Hans de Goede from comment #26)
> (In reply to Zdenek Dohnal from comment #23)
> > We can try what Hans suggests - put 1ms sleep before every bulk transfer
> > when SANE_XHCI_WORKAROUND is used (I created a new env variable for this
> > purpose...).
> 
> Note it is not just bulk transfers which need a sleep before them, also
> control transfers. You said it was a register write which was failing, I
> would expect that to be a control transfer. But I guess the scanner might
> use bulk transfers for those?

Yes, it uses libusb_bulk_transfer() for writing to the register.

I will see if the proposed patch helps (now the code waits 1ms before every libusb_bulk_transfer if SANE_XHCI_WORKAROUND is set) and then narrow the calls.

Thank you for the info!

Comment 28 Peter Gückel 2020-09-22 16:54:16 UTC
I went to the link you sent, but there are no rpms there to be installed.

Comment 29 Hans de Goede 2020-09-23 07:40:52 UTC
(In reply to Peter Gückel from comment #28)
> I went to the link you sent, but there are no rpms there to be installed.

You need to clock on the buildarch(x86_64) link, that will take you here:

https://koji.fedoraproject.org/koji/taskinfo?taskID=51937898

And that is were the RPMS are.

Comment 30 Peter Gückel 2020-09-24 16:25:40 UTC
OK, I located the rpms. I only updated the 4 that were already installed (by default) on my system:

sane-backends
sane-backends-libs
sane-backends-drivers-cameras
sane-backends-drivers-scanners

I put the 4 environment variables into .profile and ran source .profile. I checked one of them and it's value was correct, but the value for SANE_XHCI_WORKAROUND only shows 1 and not the last part with sanimage -L etc.

I plugged in the scanner and clicked on XSANE in the launcher. It took a while, but it did eventually locate both Canoscan and the laptop's built-in camera. I selected Canoscan and tried to scan. Nothing happened. I checked whether debug.log exists. It does and it contains only one line:

bash: export: `-L': not a valid identifier

Comment 31 Zdenek Dohnal 2020-09-29 06:05:50 UTC
Hi Peter,

please follow the instructions in comment 23 - it will do the trick for testing purposes, so please remove any lines you put into your .profile file - a binary is capable to read env variable without being in .profile, if you provide env variable at the command line during executing the binary (not convenient for everyday usage, but does the trick for testing).

Then simply run the command:

$ SANE_DEBUG_SANEI_USB=255 SANE_DEBUG_DLL=255 SANE_DEBUG_PLUSTEK=255 SANE_XHCI_WORKAROUND=1 scanimage -L &> debug.log

and attach debug.log as an attachment here.

The command should only look for your scanner and the patch is designed only for making discovery work, so don't expect scanning to work - it will be the next step, but I need to be sure that the current fix works for discovery.



================ Only after the previous testing is successful ===================

If the discovery works, then you can find a device uri of your scanner in debug.log. It will start with 'plustek:/'. Then please use the uri in following command:

$ SANE_DEBUG_SANEI_USB=255 SANE_DEBUG_DLL=255 SANE_DEBUG_PLUSTEK=255 SANE_XHCI_WORKAROUND=1 scanimage -d <your device uri> > out.pnm 2> scan-debug.log


And please upload scan-debug.log too (only when the first testing was fine).

This testing will check where scanning process itself ends.

Comment 32 Peter Gückel 2020-10-06 04:26:10 UTC
Created attachment 1719212 [details]
debug.log

I ran the command as you indicated. I heard a click, as if the scanner were about to start scanning, but there was no further activity. Nevertheless, debug.log is not filled with a massive amount of information for you to examine. Note that I did not install the debug packages, only the undated ones that are installed by default on the system. I hope this is still enough information for you. If you want me to install the debug packages, I will, but you would have to tell me which ones you need.

Comment 33 Peter Gückel 2020-10-06 04:28:45 UTC
sorry, spelling mistakes above:

debug.log is NOW filled...

only the UPDATED ones are installed...

Now what I wrote should make sense.

Comment 34 Peter Gückel 2020-10-06 04:47:42 UTC
Created attachment 1719213 [details]
scan-debug.log

I searched debug.log and, after dozens upon dozens of instances of plustek, the final line in the file was the uri for the scanner ;-) It doesn't have plustek:/, though, so I wasn't certain, since the / is missing. Anyway, I ran the command and my scanner immediately came to life (I always knew it wasn't broken, since it had been working just fine right up until the problem occurred after an update, when I first reported it). A whole slew of *.raw and *.dat files were produced, as well as scan-debug.log. I hope this helps... and sorry that I took so long to provide this.

Comment 35 Zdenek Dohnal 2020-10-06 05:29:45 UTC
(In reply to Peter Gückel from comment #32)
> Created attachment 1719212 [details]
> debug.log
> 
> I ran the command as you indicated. I heard a click, as if the scanner were
> about to start scanning, but there was no further activity.

That's expected - the command does only a device discovery :).


(In reply to Peter Gückel from comment #34)
> Created attachment 1719213 [details]
> scan-debug.log
> 
> I searched debug.log and, after dozens upon dozens of instances of plustek,
> the final line in the file was the uri for the scanner ;-) It doesn't have
> plustek:/, though, so I wasn't certain, since the / is missing.

A professional deformation, sorry - I work with printers too and their uris have a structure '<backend>:/<IP/hostname>:<port>', and several SANE backends have it that way too, so I thought plustek has it too (I debug it for the first time and I don't have any machine which is supported by it) - it seems it doesn't. I would really appreciate some conformance for uris in SANE, so I wouldn't look as a fool too many times...

> Anyway, I
> ran the command and my scanner immediately came to life (I always knew it
> wasn't broken, since it had been working just fine right up until the
> problem occurred after an update, when I first reported it). A whole slew of
> *.raw and *.dat files were produced, as well as scan-debug.log. I hope this
> helps... and sorry that I took so long to provide this.

No problem, thank you for the data!

It seems like the process went well in the log, would you mind trying to scan with:

SANE_XHCI_WORKAROUND=1 xsane &

?

Comment 36 Peter Gückel 2020-10-06 14:43:26 UTC
Zdenek,

Es hat geklappt! I pasted the command into konsole and, to my amazement, 5-6 windows of Xsane opened up. I thought something was supposed to happen, when I realized that I had to tell it to scan ;-) It worked perfectly. I had never seen the view window before! Is that new? It sure is handy, as, previously, I always had to search through my drive to find the location where the scan was placed. It was saved as a ppm that not many programs can view, so I opened it in Gimp and it was there in full colour. That is how I usually used the scanner—with the scan into Gimp rpm, so that I could crop and edit before saving. Wonderful!

So, if you're satisfied, let'ß get this fix into the regular rpm packages ;-)

Peter

Comment 37 Zdenek Dohnal 2020-10-07 06:44:55 UTC
Ok, thanks for letting me know and good to hear it helps!

The fact the scanner works now confirms the fix concept is correct. Now I would like to try to narrow the fix, because the current fix contains the 1ms sleep hack before every usb bulk transfer, which can slow the scanning process more than necessary.

This new build:

https://koji.fedoraproject.org/koji/taskinfo?taskID=52915563

applies the workaround only before register 0x59, which caused harm previously. Please note the scanning can malfunction again with this build.

Because the build has the same NVR, you need to take those rpms and issue a dnf transaction with 'reinstall', f.e.:

$ sudo dnf reinstall <1.rpm> <2.rpm> ... <N.rpm>

then please issue following commands:

This will try to find a scanner:

$ SANE_DEBUG_SANEI_USB=255 SANE_DEBUG_DLL=255 SANE_DEBUG_PLUSTEK=255 SANE_PLUSTEK_USB_WORKAROUND=1 scanimage -L &> debug.log

If it fails to find the CanoScan scanner, please upload debug.log and tell me.

If it finds the CanoScan scanner, please try scanning itself with following command:

$ SANE_DEBUG_SANEI_USB=255 SANE_DEBUG_DLL=255 SANE_DEBUG_PLUSTEK=255 SANE_PLUSTEK_USB_WORKAROUND=1 xsane &> scan-debug.log

If the scanning fails, please upload scan-debug.log and tell me.

If all went well, please tell me too :) .

Comment 38 Peter Gückel 2020-10-07 16:47:44 UTC
I ran the first command and the final 2 lines show the 2 devices: built-in camera and the plustek (actually Canon) scanner. Next, I ran the second program and the scanning went perfectly. I did both a preview and an actual scan.

Do you want to see the debug.log and scan-debug.log files?

Comment 39 Peter Gückel 2020-10-07 23:34:20 UTC
Created attachment 1719859 [details]
debug.log with latest rpms

in case you want to see; quicker than asking for it and waiting until tomorrow morning

Comment 40 Peter Gückel 2020-10-07 23:35:27 UTC
Created attachment 1719860 [details]
scan-debug.log with latest rpms

in case you want to have a look; quicker than waiting for me to upload tomorrow morning

Comment 41 Zdenek Dohnal 2020-10-08 06:17:20 UTC
Thanks! :) It looks good, I'll present the current patch upstream.

Comment 42 Zdenek Dohnal 2020-10-08 06:48:51 UTC
(In reply to Peter Gückel from comment #34)
> Anyway, I ran the command and my scanner immediately came to life (I always knew it
> wasn't broken, since it had been working just fine right up until the
> problem occurred after an update, when I first reported it).

Just a nitpick - the device is actually broken :( - it can't handle a quick bulk transfers for the affected device register. The current 'fix' is a workaround for the issue in the device.

Comment 43 Hans de Goede 2020-10-08 07:42:53 UTC
(In reply to Zdenek Dohnal from comment #42)
> Just a nitpick - the device is actually broken :( - it can't handle a quick
> bulk transfers for the affected device register. The current 'fix' is a
> workaround for the issue in the device.

Small nitpick on the nitpick, the device is not broken, that suggests (to me at least) that it is a problem with the specific scanner which Peter has. The entire series/model of this scanner does indeed seem to be buggy, but to be fair to the manufacturer, likely only USB-2 existed when this was designed, so the bug never showed up in testing since USB-2 controllers never packed the bulk transfers close enough together (in time) for the bug to trigger.

USB-3 controllers are special in that they can make things go faster even while running at USB-2 speeds; and this scanner model is not the first device-model to have issues with this.

Comment 44 Zdenek Dohnal 2020-10-08 07:58:13 UTC
Yeah, 'broken' is a strong word for it and don't cover the points which Hans mentioned. I apologize for that. Then I would say the device is incompatible with modern environment in certain ways, due its bugs and being designed for older technologies, which aren't common nowadays.

Comment 45 Zdenek Dohnal 2020-10-08 11:12:20 UTC
The fix is sent upstream as https://gitlab.com/sane-project/backends/-/merge_requests/535 .

I will build an official rpms after upstream accepts the patch.

Comment 46 Peter Gückel 2020-10-08 16:58:32 UTC
Whether broken or not, it now does exactly what it did very well since the day I got it. Öhh... bulk transfers? It is a flatbed scanner that does only one sheet at a time and one has to open the lid to swap documents. I don't know what a bulk transfer is supposed to be.

I am glad there is a 'fix' for it, though. I only scan a document every blue moon, so purchasing a new scanner would not be worth it for me. It is handy to have one, though, instead of having to take the documents to a shop to be scanned.

Will I be notified here when rpms incorporating the fix are available? As you recall, working with the folks upstream at github resulted in a wait of 13 months until you came along, Zdenek.

Comment 47 Hans de Goede 2020-10-08 19:34:03 UTC
FWIW I believe that it is fine to carry a patch downstream for this, even if it has not been merged upstream yet.

Especially if you adjust the patch to make the sleep unconditionally as discussed in the upstream merge-req, then the remaining change will be a one liner, which should be fine as downstream patch for now.

Comment 48 Zdenek Dohnal 2020-10-09 06:54:34 UTC
(In reply to Peter Gückel from comment #46)
> Öhh... bulk transfers? It is a flatbed scanner that does only
> one sheet at a time and one has to open the lid to swap documents. I don't
> know what a bulk transfer is supposed to be.

It's the way how your PC communicates with your scanner if it is connected via USB cable. The driver (plustek backend here) uses functions from USB library to send data to the device. Those data are sent together in bulks (bigger amount of data together) and they are transferred to the device, then device sends data back in bulks too. So that's where bulk transfer goes from.

> 
> I am glad there is a 'fix' for it, though. I only scan a document every blue
> moon, so purchasing a new scanner would not be worth it for me. It is handy
> to have one, though, instead of having to take the documents to a shop to be
> scanned.

Glad to hear it works!

> 
> Will I be notified here when rpms incorporating the fix are available?

Yep, I'll attach this bug ticket number to bodhi update, which will contain the build with the fix.

> As you recall, working with the folks upstream at github resulted in a wait of
> 13 months until you came along, Zdenek.

You're right, I will do a downstream fix for now, as Hans suggested. The build will come in a hour or so.

Comment 49 Fedora Update System 2020-10-09 08:01:18 UTC
FEDORA-2020-3d18500371 has been submitted as an update to Fedora 33. https://bodhi.fedoraproject.org/updates/FEDORA-2020-3d18500371

Comment 50 Fedora Update System 2020-10-09 08:19:40 UTC
FEDORA-2020-cad4f03bfb has been submitted as an update to Fedora 32. https://bodhi.fedoraproject.org/updates/FEDORA-2020-cad4f03bfb

Comment 51 Fedora Update System 2020-10-09 08:39:14 UTC
FEDORA-2020-1d4412c037 has been submitted as an update to Fedora 31. https://bodhi.fedoraproject.org/updates/FEDORA-2020-1d4412c037

Comment 52 Fedora Update System 2020-10-09 16:37:58 UTC
FEDORA-2020-cad4f03bfb has been pushed to the Fedora 32 testing repository.
In short time you'll be able to install the update with the following command:
`sudo dnf upgrade --enablerepo=updates-testing --advisory=FEDORA-2020-cad4f03bfb`
You can provide feedback for this update here: https://bodhi.fedoraproject.org/updates/FEDORA-2020-cad4f03bfb

See also https://fedoraproject.org/wiki/QA:Updates_Testing for more information on how to test updates.

Comment 53 Fedora Update System 2020-10-09 16:52:51 UTC
FEDORA-2020-1d4412c037 has been pushed to the Fedora 31 testing repository.
In short time you'll be able to install the update with the following command:
`sudo dnf upgrade --enablerepo=updates-testing --advisory=FEDORA-2020-1d4412c037`
You can provide feedback for this update here: https://bodhi.fedoraproject.org/updates/FEDORA-2020-1d4412c037

See also https://fedoraproject.org/wiki/QA:Updates_Testing for more information on how to test updates.

Comment 54 Fedora Update System 2020-10-09 18:15:47 UTC
FEDORA-2020-3d18500371 has been pushed to the Fedora 33 testing repository.
In short time you'll be able to install the update with the following command:
`sudo dnf upgrade --enablerepo=updates-testing --advisory=FEDORA-2020-3d18500371`
You can provide feedback for this update here: https://bodhi.fedoraproject.org/updates/FEDORA-2020-3d18500371

See also https://fedoraproject.org/wiki/QA:Updates_Testing for more information on how to test updates.

Comment 55 Fedora Update System 2020-10-12 14:41:54 UTC
FEDORA-2020-cad4f03bfb has been pushed to the Fedora 32 stable repository.
If problem still persists, please make note of it in this bug report.

Comment 56 Fedora Update System 2020-10-17 14:24:14 UTC
FEDORA-2020-1d4412c037 has been pushed to the Fedora 31 stable repository.
If problem still persists, please make note of it in this bug report.

Comment 57 Fedora Update System 2020-10-23 22:08:28 UTC
FEDORA-2020-3d18500371 has been pushed to the Fedora 33 stable repository.
If problem still persists, please make note of it in this bug report.


Note You need to log in before you can comment on or make changes to this bug.