search

SimulPiscator / AirSane

Publish SANE scanners to MacOS, Android, and Windows via Apple AirScan.
GNU General Public License v3.0
243 stars 26 forks source link

Scanning from feeder is bugged with HP LaserJet 3380 #109

Closed ilya-fedin closed 10 months ago

ilya-fedin commented 10 months ago

It scans only 1.5 page and then hangs

Sep 27 10:24:13 rpi4 airsaned[105150]: io/hpmud/musb.c 428: Found interface conf=0, iface=0, altset=1, index=1
Sep 27 10:24:13 rpi4 airsaned[105150]: io/hpmud/musb.c 390: Active kernel driver on interface=0 ret=1
Sep 27 10:24:13 rpi4 airsaned[105150]: io/hpmud/musb.c 394: Detaching kernel driver on interface=0 ret=0
Sep 27 10:24:13 rpi4 airsaned[105150]: io/hpmud/musb.c 536: claimed 7/1/2 interface
Sep 27 10:24:13 rpi4 airsaned[105150]: io/hpmud/musb.c 781: read actual device_id successfully fd=1 len=157
Sep 27 10:24:13 rpi4 airsaned[105150]: io/hpmud/musb.c 562: released 7/1/2 interface
Sep 27 10:24:13 rpi4 airsaned[105150]: io/hpmud/musb.c 428: Found interface conf=0, iface=0, altset=1, index=1
Sep 27 10:24:13 rpi4 airsaned[105150]: io/hpmud/musb.c 390: Active kernel driver on interface=0 ret=0
Sep 27 10:24:13 rpi4 airsaned[105150]: io/hpmud/musb.c 536: claimed 7/1/2 interface
Sep 27 10:24:13 rpi4 airsaned[105150]: io/hpmud/musb.c 781: read actual device_id successfully fd=1 len=157
Sep 27 10:24:13 rpi4 airsaned[105150]: io/hpmud/musb.c 562: released 7/1/2 interface
Sep 27 10:24:13 rpi4 airsaned[105150]: io/hpmud/musb.c 961: new HP-MESSAGE channel=1 clientCnt=1 channelCnt=1
Sep 27 10:24:13 rpi4 airsaned[105150]: io/hpmud/musb.c 428: Found interface conf=0, iface=0, altset=0, index=2
Sep 27 10:24:13 rpi4 airsaned[105150]: io/hpmud/musb.c 390: Active kernel driver on interface=0 ret=0
Sep 27 10:24:13 rpi4 airsaned[105150]: io/hpmud/musb.c 536: claimed 7/1/3 interface
Sep 27 10:24:14 rpi4 airsaned[105150]: io/hpmud/musb.c 562: released 7/1/3 interface
Sep 27 10:24:15 rpi4 airsaned[105150]: io/hpmud/musb.c 976: removed HP-MESSAGE channel=1 clientCnt=0 channelCnt=0
Sep 27 10:26:15 rpi4 airsaned[105150]: io/hpmud/musb.c 428: Found interface conf=0, iface=0, altset=1, index=1
Sep 27 10:26:15 rpi4 airsaned[105150]: io/hpmud/musb.c 390: Active kernel driver on interface=0 ret=0
Sep 27 10:26:15 rpi4 airsaned[105150]: io/hpmud/musb.c 536: claimed 7/1/2 interface
Sep 27 10:26:15 rpi4 airsaned[105150]: io/hpmud/musb.c 781: read actual device_id successfully fd=1 len=157
Sep 27 10:26:15 rpi4 airsaned[105150]: io/hpmud/musb.c 562: released 7/1/2 interface
Sep 27 10:26:15 rpi4 airsaned[105150]: io/hpmud/musb.c 428: Found interface conf=0, iface=0, altset=1, index=1
Sep 27 10:26:15 rpi4 airsaned[105150]: io/hpmud/musb.c 390: Active kernel driver on interface=0 ret=0
Sep 27 10:26:15 rpi4 airsaned[105150]: io/hpmud/musb.c 536: claimed 7/1/2 interface
Sep 27 10:26:15 rpi4 airsaned[105150]: io/hpmud/musb.c 781: read actual device_id successfully fd=1 len=157
Sep 27 10:26:15 rpi4 airsaned[105150]: io/hpmud/musb.c 562: released 7/1/2 interface
Sep 27 10:26:15 rpi4 airsaned[105150]: io/hpmud/musb.c 961: new HP-MESSAGE channel=1 clientCnt=1 channelCnt=1
Sep 27 10:26:15 rpi4 airsaned[105150]: io/hpmud/musb.c 428: Found interface conf=0, iface=0, altset=0, index=2
Sep 27 10:26:15 rpi4 airsaned[105150]: io/hpmud/musb.c 390: Active kernel driver on interface=0 ret=0
Sep 27 10:26:15 rpi4 airsaned[105150]: io/hpmud/musb.c 536: claimed 7/1/3 interface
Sep 27 10:26:15 rpi4 airsaned[105150]: io/hpmud/musb.c 562: released 7/1/3 interface
Sep 27 10:26:16 rpi4 airsaned[105150]: io/hpmud/musb.c 976: removed HP-MESSAGE channel=1 clientCnt=0 channelCnt=0
Sep 27 10:26:16 rpi4 airsaned[105150]: io/hpmud/musb.c 961: new HP-MESSAGE channel=1 clientCnt=1 channelCnt=1
Sep 27 10:26:16 rpi4 airsaned[105150]: io/hpmud/musb.c 428: Found interface conf=0, iface=0, altset=0, index=2
Sep 27 10:26:16 rpi4 airsaned[105150]: io/hpmud/musb.c 390: Active kernel driver on interface=0 ret=0
Sep 27 10:26:16 rpi4 airsaned[105150]: io/hpmud/musb.c 536: claimed 7/1/3 interface
Sep 27 10:26:16 rpi4 airsaned[105150]: io/hpmud/musb.c 961: new HP-SCAN channel=4 clientCnt=1 channelCnt=2
Sep 27 10:26:33 rpi4 airsaned[105150]: io/hpmud/musb.c 976: removed HP-SCAN channel=4 clientCnt=0 channelCnt=1
Sep 27 10:26:33 rpi4 airsaned[105150]: io/hpmud/musb.c 562: released 7/1/3 interface
Sep 27 10:26:34 rpi4 airsaned[105150]: io/hpmud/musb.c 976: removed HP-MESSAGE channel=1 clientCnt=0 channelCnt=0
Sep 27 10:26:34 rpi4 airsaned[105150]: sane_hpaio_cancel: already cancelled!
Sep 27 10:26:34 rpi4 airsaned[105150]: io/hpmud/hpmud.c 721: invalid channel_write state
Sep 27 10:26:34 rpi4 airsaned[105150]: io/hpmud/pml.c 374: SetPml channel_write failed ret=31
Sep 27 10:26:35 rpi4 airsaned[105150]: io/hpmud/musb.c 428: Found interface conf=0, iface=0, altset=1, index=1
Sep 27 10:26:35 rpi4 airsaned[105150]: io/hpmud/musb.c 390: Active kernel driver on interface=0 ret=0
Sep 27 10:26:35 rpi4 airsaned[105150]: io/hpmud/musb.c 536: claimed 7/1/2 interface
Sep 27 10:26:35 rpi4 airsaned[105150]: io/hpmud/musb.c 781: read actual device_id successfully fd=1 len=157
Sep 27 10:26:35 rpi4 airsaned[105150]: io/hpmud/musb.c 562: released 7/1/2 interface
Sep 27 10:26:35 rpi4 airsaned[105150]: io/hpmud/musb.c 428: Found interface conf=0, iface=0, altset=1, index=1
Sep 27 10:26:35 rpi4 airsaned[105150]: io/hpmud/musb.c 390: Active kernel driver on interface=0 ret=0
Sep 27 10:26:35 rpi4 airsaned[105150]: io/hpmud/musb.c 536: claimed 7/1/2 interface
Sep 27 10:26:35 rpi4 airsaned[105150]: io/hpmud/musb.c 781: read actual device_id successfully fd=1 len=157
Sep 27 10:26:35 rpi4 airsaned[105150]: io/hpmud/musb.c 562: released 7/1/2 interface
Sep 27 10:26:35 rpi4 airsaned[105150]: io/hpmud/musb.c 961: new HP-MESSAGE channel=1 clientCnt=1 channelCnt=1
Sep 27 10:26:35 rpi4 airsaned[105150]: io/hpmud/musb.c 428: Found interface conf=0, iface=0, altset=0, index=2
Sep 27 10:26:35 rpi4 airsaned[105150]: io/hpmud/musb.c 390: Active kernel driver on interface=0 ret=0
Sep 27 10:26:35 rpi4 airsaned[105150]: io/hpmud/musb.c 536: claimed 7/1/3 interface
Sep 27 10:26:35 rpi4 airsaned[105150]: io/hpmud/musb.c 562: released 7/1/3 interface
Sep 27 10:26:36 rpi4 airsaned[105150]: io/hpmud/musb.c 976: removed HP-MESSAGE channel=1 clientCnt=0 channelCnt=0
Sep 27 10:26:36 rpi4 airsaned[105150]: io/hpmud/musb.c 961: new HP-MESSAGE channel=1 clientCnt=1 channelCnt=1
Sep 27 10:26:36 rpi4 airsaned[105150]: io/hpmud/musb.c 428: Found interface conf=0, iface=0, altset=0, index=2
Sep 27 10:26:36 rpi4 airsaned[105150]: io/hpmud/musb.c 390: Active kernel driver on interface=0 ret=0
Sep 27 10:26:36 rpi4 airsaned[105150]: io/hpmud/musb.c 536: claimed 7/1/3 interface
Sep 27 10:26:36 rpi4 airsaned[105150]: io/hpmud/musb.c 961: new HP-SCAN channel=4 clientCnt=1 channelCnt=2
Sep 27 10:26:46 rpi4 airsaned[105150]: hpaio: hpaioScannerToSaneError: pmlError=0.
Sep 27 10:26:46 rpi4 airsaned[105150]: io/hpmud/musb.c 976: removed HP-SCAN channel=4 clientCnt=0 channelCnt=1
Sep 27 10:26:46 rpi4 airsaned[105150]: io/hpmud/musb.c 562: released 7/1/3 interface
Sep 27 10:26:47 rpi4 airsaned[105150]: io/hpmud/musb.c 976: removed HP-MESSAGE channel=1 clientCnt=0 channelCnt=0
Sep 27 10:26:47 rpi4 airsaned[105150]: sane_hpaio_cancel: already cancelled!
Sep 27 10:26:47 rpi4 airsaned[105150]: io/hpmud/hpmud.c 721: invalid channel_write state
Sep 27 10:26:47 rpi4 airsaned[105150]: io/hpmud/pml.c 374: SetPml channel_write failed ret=31

Scanning with feeder via the net plugin works just fine

SimulPiscator commented 10 months ago

Hi, could you help me understand this:

Scanning with feeder via the net plugin works just fine What is the "net plugin"? Which application (SANE frontend) are you using when it works?

Also, could you try scanimage in batch mode and see whether that works?

Thank you!

ilya-fedin commented 10 months ago

I used gnome-scan. The net plugin is the sane's native protocol for network scanning. I also noticed that with the net plugin I get the preview on the fly while with airsane it hangs for multiple seconds after a page is scanned and displays the preview only then.

ilya-fedin commented 10 months ago 
   /sane  scanimage -d "airscan:e0:Hewlett-Packard hp_LaserJet_3380" -b
Output format is not set, using pnm as a default.
Scanning infinity pages, incrementing by 1, numbering from 1
Scanning page 1
Scanned page 1. (scanner status = 5)
Scanning page 2
scanimage: sane_read: Error during device I/O
Scanned page 2. (scanner status = 9)
Batch terminated, 2 pages scanned

Lines in airsaned output after the client error:

Sep 27 15:22:18 rpi4 airsaned[105150]: hpaio: hpaioScannerToSaneError: pmlError=0.
Sep 27 15:22:19 rpi4 airsaned[105150]: io/hpmud/musb.c 976: removed HP-SCAN channel=4 clientCnt=0 channelCnt=1
Sep 27 15:22:19 rpi4 airsaned[105150]: io/hpmud/musb.c 562: released 7/1/3 interface
Sep 27 15:22:20 rpi4 airsaned[105150]: io/hpmud/musb.c 976: removed HP-MESSAGE channel=1 clientCnt=0 channelCnt=0
Sep 27 15:22:20 rpi4 airsaned[105150]: sane_hpaio_cancel: already cancelled!
Sep 27 15:22:20 rpi4 airsaned[105150]: io/hpmud/hpmud.c 721: invalid channel_write state
Sep 27 15:22:20 rpi4 airsaned[105150]: io/hpmud/pml.c 374: SetPml channel_write failed ret=31
ilya-fedin commented 10 months ago

I also noticed it scans way slower than with the net plugin and hangs when a half of the first page is printed. It finishes scanning the first page though, starts scanning the second one, hangs and errors out.

With the net plugin, it works fast and scans as it should.

ilya-fedin commented 10 months ago

https://wiki.archlinux.org/title/SANE#Sharing_your_scanner_over_a_network

SimulPiscator commented 10 months ago

OK, so you have a machine on the network which is physically attached to the scanner, and that machine is running both saned and airsaned. You try scanning from a second machine using gnome-scan, once through the saned protocol, and once through the eSCL/AirScan protocol. With the saned protocol, it works fine, with eSCL it does not. Is that correct?

ilya-fedin commented 10 months ago

Yes, absolutely correct.

SimulPiscator commented 10 months ago

When I asked for the scanimage output, I was referring to the machine the scanner is attached to, not the network. Sorry if I was unclear.

SimulPiscator commented 10 months ago

The log from airsaned contains information from the SANE hpaio driver, not from airsaned itself. If you want output from airsaned, run it with --debug=true as an argument.

ilya-fedin commented 10 months ago

Here it is:

 ilya@rpi4  /sane  scanimage -d "hpaio:/usb/hp_LaserJet_3380?serial=00CNBN115268" -b
Output format is not set, using pnm as a default.
Scanning infinity pages, incrementing by 1, numbering from 1
Scanning page 1
Scanned page 1. (scanner status = 5)
Scanning page 2
Scanned page 2. (scanner status = 5)
Scanning page 3
scanimage: sane_start: Error during device I/O
Batch terminated, 2 pages scanned

(for whatever reason it thought there's a third page but there were only two so it expectedly failed when attempting to scan the third one)

ilya-fedin commented 10 months ago 
Sep 27 15:42:55 rpi4 airsaned[121557]: hpaio: hpaioScannerToSaneError: pmlError=0.
Sep 27 15:42:55 rpi4 airsaned[121557]: sane_cancel(0x7f74048b70)
Sep 27 15:42:55 rpi4 airsaned[121557]: io/hpmud/musb.c 976: removed HP-SCAN channel=4 clientCnt=0 channelCnt=1
Sep 27 15:42:55 rpi4 airsaned[121557]: io/hpmud/musb.c 562: released 7/1/3 interface
Sep 27 15:42:56 rpi4 airsaned[121557]: io/hpmud/musb.c 976: removed HP-MESSAGE channel=1 clientCnt=0 channelCnt=0
Sep 27 15:42:56 rpi4 airsaned[121557]: sane_cancel(0x7f74048b70)
Sep 27 15:42:56 rpi4 airsaned[121557]: sane_close(0x7f74048b70)
Sep 27 15:42:56 rpi4 airsaned[121557]: sane_hpaio_cancel: already cancelled!
Sep 27 15:42:56 rpi4 airsaned[121557]: sane_exit()
Sep 27 15:42:56 rpi4 airsaned[121557]: io/hpmud/hpmud.c 721: invalid channel_write state
Sep 27 15:42:56 rpi4 airsaned[121557]: io/hpmud/pml.c 374: SetPml channel_write failed ret=31

I see the scanner prints "Device is busy. Try again later." on its display when airsaned fails.

SimulPiscator commented 10 months ago

Another test I ask you to perform: If you go to <ip-of-scanserver>:8090, follow the link to your scanner, and choose "Feeder" and "PDF" as data format, will you be able to scan multiple pages without error? Thank you!

ilya-fedin commented 10 months ago

Seem to work just fine!

SimulPiscator commented 10 months ago

This log entry is strange: hpaio: hpaioScannerToSaneError: pmlError=0. It basically says "there is no error" but still results in aborting the scan (as viewed from hpaio's side, whereas the scanner itself seems to be fine).

Which version of HPLIP do you have installed? The current one (3.23.8) is relatively new, and may be downloaded from SourceForge (https://sourceforge.net/projects/hplip/files/hplip/) if you want to give it a try.

ilya-fedin commented 10 months ago

3.23.5

ilya-fedin commented 10 months ago

I have this problem since I started using airsaned (2 years)

SimulPiscator commented 10 months ago

Do you have a macOS or Windows 10/11 machine or VM around to test? That AirSane's web interface works suggests the issue might not be on the server side but on the client side, so trying a different client might lead to some insight.

ilya-fedin commented 10 months ago

I have a Mopria on smartphone. Would that work for the test?

SimulPiscator commented 10 months ago

I think so, yes. If you start a scan from the feeder, will it behave well?

ilya-fedin commented 10 months ago

Mopria Scan has the same problem with the same log

Sep 27 18:35:12 rpi4 airsaned[121557]: hpaio: hpaioScannerToSaneError: pmlError=0.
Sep 27 18:35:12 rpi4 airsaned[121557]: sane_cancel(0x7f74044fb0)
Sep 27 18:35:12 rpi4 airsaned[121557]: io/hpmud/musb.c 976: removed HP-SCAN channel=4 clientCnt=0 channelCnt=1
Sep 27 18:35:12 rpi4 airsaned[121557]: io/hpmud/musb.c 562: released 7/1/3 interface
Sep 27 18:35:13 rpi4 airsaned[121557]: io/hpmud/musb.c 976: removed HP-MESSAGE channel=1 clientCnt=0 channelCnt=0
Sep 27 18:35:13 rpi4 airsaned[121557]: sane_cancel(0x7f74044fb0)
Sep 27 18:35:13 rpi4 airsaned[121557]: sane_close(0x7f74044fb0)
Sep 27 18:35:13 rpi4 airsaned[121557]: sane_hpaio_cancel: already cancelled!
Sep 27 18:35:13 rpi4 airsaned[121557]: sane_exit()
Sep 27 18:35:13 rpi4 airsaned[121557]: io/hpmud/hpmud.c 721: invalid channel_write state
Sep 27 18:35:13 rpi4 airsaned[121557]: io/hpmud/pml.c 374: SetPml channel_write failed ret=31
SimulPiscator commented 10 months ago

Thanks for the log. Maybe I can fix the issue.

markosjal commented 10 months ago

As my problem is similar with a Brother MFP7360N scanner , I did a scan from the web GUI and it worked for me too. There seems to be no issue for the GUI .

What I am noticing however is that on feeder scans over escl protocol to AirSane files start to transfer before the scanning is complete. After having worked a lot with this escl protocol on my own projects, it seems to me that the files should not begin to transfer until all pages have been scanned.

SimulPiscator commented 10 months ago

I have modified AirSane to improve behavior with ADFs. Please give it a try.

ilya-fedin commented 10 months ago

It says that the scanning has ended due to ADF error but otherwise works fine now, scans all the pages. Not sure whose fault it is, the ADF state is not really good and I have to help it to avoid paper jam.