OpenPrinting / ipp-usb

ipp-usb -- HTTP reverse proxy, backed by IPP-over-USB connection to device
BSD 2-Clause "Simplified" License
129 stars 11 forks source link

Unable to add printer Ricoh with IPP-over-USB #59

Closed bfg01 closed 1 year ago

bfg01 commented 1 year ago

Printer is Ricoh SP 377SFNwx. Using openSUSE Leap 15.4, installed from scratch (no upgrade).

As network printer, with URI ipp:// and driver "everywhere", seemingly no problems until now.

Wanted to try with IPP-over-USB. So connected printer via USB, and tried "lpinfo -v". There was this found URI "direct usb://UNKNOWN/Printer[...]". Did internet search and found that an additional daemon was needed: https://github.com/OpenPrinting/ipp-usb So manually downloaded the RPM package and installed. Now shown URI was "direct usb://RICOH/SP[...]" (cannot remember it exactly)

So tried adding it, and got:

# lpadmin -p <a_name> -Ev usb://RICOH/SP[...] -m everywhere; echo $?
lpadmin: Unable to connect to "RICOH:0": Name or service not known
1

Tried several things: ---Double-checking that firewalld was -temporarily- disabled (otherwise "lpinfo -v" wouldn't even have worked) ---Trying URI ipp://RICOH/SP[...] instead ---Trying the "lsusb" advice here https://wiki.debian.org/CUPSDriverlessPrinting#IPP-over-USB:_The_Basics ; and I did get the right output like there says, so printer does have support for this

Could someone help please? Thanks for your attention.

michaelrsweet commented 1 year ago

"usb://..." URIs are not IPP-USB, but the old/legacy USB printer class interface. You can't actually use IPP Everywhere with it over legacy USB.

Some network MFPs do not support IPP-USB since the USB port is treated as a "maintenance" port. But if the printer does support IPP-USB then "lpinfo -v" should show it with an "ipp:" or "dnssd:" URI.

bfg01 commented 1 year ago

Thanks very much sir.

Well, "lpinfo -v" does show the printer with "ipp://..." and "dnssd://...", but as far as I have understood in the CUPS docs, these are purely network protocols; i.e., only usable through network connection (ethernet or wifi). In fact, as mentioned in the OP, I already added it as a network printer, using its IP address.

The only other URIs shown by "lpinfo -v" are "socket://..." and "usb://..." itself.

I'm not at office right now, but I thought about a weird idea: trying to isolate both PC and printer, connect with USB, and use "ipp://..." URI to see if it's detected. But AFAIK, the only IPP URIs shown by "lpinfo -v" even when USB connected were "ipp://" and "ipp://"... Am I just completely wrong regarding IPP-USB? Is there still a way to test IPP-USB with this printer?

Thanks again for your help.

michaelrsweet commented 1 year ago

So IPP-USB shows up as a network protocol because the ipp-usb daemon provides a gateway from localhost (127.0.0.1 or ::1) to the IPP-USB endpoints provided by the printer.

zdohnal commented 1 year ago

@bfg01 it is as @michaelrsweet says - the ipp-over-usb device works via network ipp backend, because they're shared on localhost by ipp-usb daemon as an IPP printer. However, you can always deduct whether the device is actually USB by checking the mDNS record ipp-usb shares, f.e. avahi-browse -avrt output:

=     lo IPv4 Canon MF440 Series (USB 1)                    _ipp._tcp            local
                                                       ^^^^^
   hostname = [fedora.local]
   address = [127.0.0.1]
   port = [60000]
   txt = ["air=none" "mopria-certified=1.3" "rp=ipp/print" "priority=50" "kind=document,envelope,postcard" "PaperMax=legal-A4" "URF=CP255,DM1,PQ4,RS300,W8-16,FN3,IS1-4,OB10-40,V1.4" "UUID=6d4ff0ce-6b11-11d8-8020-00bbc1796a37" "Color=F" "Duplex=T" "note=" "qtotal=1" "usb_MDL=MF440 Series UFR II" "usb_MFG=Canon" "usb_CMD=LIPSLX,CPCA" "ty=CNMF440 Series" "product=(CNMF440 Series)" "pdl=application/octet-stream,image/urf,image/pwg-raster,image/jpeg,application/pdf" "txtvers=1" "adminurl=http://localhost:60000/airprint.html" "Fax=F" "Scan=T"]

Ad testing:

First it would be great if you found out whether the device really supports ipp-over-usb protocol. There is an easy way how to find out via lsusb -v - you look for your device entry and the following lines:

My device entry:

Bus 001 Device 005: ID 04a9:2823 Canon, Inc. MF440 Series
Device Descriptor:
  bLength                18
  bDescriptorType         1
  bcdUSB               2.10
...

and further down in the entry I can see it has an interface 7/1/4, which is ipp-over-usb interface:

...
    Interface Descriptor:
      bLength                 9
      bDescriptorType         4
      bInterfaceNumber        0
      bAlternateSetting       1
      bNumEndpoints           2
      bInterfaceClass         7 Printer
      bInterfaceSubClass      1 Printer
      bInterfaceProtocol      4 
      iInterface              0
...

If your device does not have the similar lsusb -v output, the device doesn't support ipp-over-usb.

If you verified the device really is ipp-over-usb, then you can test the device in two ways:

A) via temporary queue - this requires the OS which is capable of using mDNS (having nss-mdns or systemd-resolved and set up installed for mDNS resolving, running avahi-daemon) and the application capable of using the current (6 years old) CUPS API - AFAIK this works in Fedora and Ubuntu (Ubuntu achieves this by running cups-browsed natively), I'm not sure about OpenSUSE. Applications capable of using CUPS API are at least Firefox, Libreoffice and any GTK3 based application. Temporary queues will be one of the ways how to use printers in the future CUPS, so I strongly recommend trying this one.

B) via a permanent queue - you can add the queue permanently by using this command:

$ lpadmin -p <name> -v ipp://localhost:60000/ipp/print -m everywhere -E

This way will no longer be available for common printing in the future CUPS - it will be used only for sharing the queue on the CUPS sharing server - but today you can try this way to figure out whether your device works via ipp-usb as well.

======================

Note: there is driverless backend from cups-filters, which can show your ipp-usb device in lpinfo -v like this:

ipp://Canon%20MF440%20Series%20(USB%201)._ipp._tcp.local/

but there is an issue which results this discovery is not reliable - the uri is shown sometimes, but then it is not... so that's why, if you have to try a permanent queue, I recommend using localhost:60000/ipp/print in uri instead.

zdohnal commented 1 year ago

And ipp-usb has its own logs - consult with its man pages how to enable debug logging and where to find the logs.

Closing the issue for now, do let me know the result and we can find out whether there is a problem we can solve in CUPS.

bfg01 commented 1 year ago

Isolated both printer and PC from any network, started IPP USB daemon with "ipp-usb debug", then connected each other via USB cable.

I already did the "lsusb -v" test, as mentioned in the OP with "the Debian link", and I still get the output.

Tried the temporary queue, both with LibreOffice and "lpstat -l -e". No URIs found at all...

Tried adding permanent queue; result: "lpadmin: Error [...]: Operation now in progress". And I did temporarily disable firewalld

Both "driverless [list]" and "lpinfo -v" show no URIs, except the legacy "usb://..."

Output from ipp-usb debugging:

  USB interfaces:
    Config Interface Alt Class SubClass Proto
       1       0      0   7      1       2
       1       1      0   255    255     255
*      1       3      0   7      1       4
*      1       4      0   7      1       4
*      1       5      0   7      1       4
*      1       6      0   7      1       4

  USB[0]: open: Bus 001 Device 007 Interface 2 Alt 0
! USB[0]: libusb_claim_interface: Invalid parameter
! PNP Bus 001 Device 007: libusb_claim_interface: Invalid parameter
+ PNP Bus 001 Device 007: retry

WTH is happening here? Now nothing of all of this makes sense...

zdohnal commented 1 year ago

@bfg01 I've passed the issue to ipp-usb project for further investigation.

bfg01 commented 1 year ago

Thanks.

I'm sorry, I made a mistake: command "driverless [list]" shows no URIs at all, and instead fails with exit status 1.

bfg01 commented 1 year ago

By chance, any findings?

BTW, legacy "usb://..." with model's PPD from OpenPrinting website doesn't work neither... "lpadmin" does succeed in adding the queue with no errors, but when trying to print anything either with any GUI app or "lp" command, the print job stays hung infinitely, with no activity from printer nor any console output. I always have to use the "cancel" command to remove the print job.

Also I tried everything in this thread on another printer of exact same model, which is known for having no issues, and a brand new USB cable. Exact same results in everything. So I discard the possibility of a faulty printer.

zdohnal commented 1 year ago

@bfg01 regarding the legacy usb:// please file a new issue back to OpenPrinting/CUPS - let's leave this issue for ipp-usb only.

Ad this issue - please take /var/log/ipp-usb/main.log, rename it to have .txt suffix and attach it here as an attachment.

Ad legacy usb issue - it would be great if you enabled CUPS debug logging via cupsctl LogLevel=debug2, tried to print, get /var/log/cups/error_log, added .txt suffix to it and attached the file to the new OpenPrinting/CUPS issue.

bfg01 commented 1 year ago

Regarding ipp-usb here, since log was composed mostly by just repeated lines, I shortened it and I think it was not necessary to post it as attachment. Log:

21-10-2022 18:09:47:   ===============================
21-10-2022 18:09:47:   ipp-usb started in "udev" mode, pid=11057
21-10-2022 18:09:47:   ctrlsock: listening at "/var/ipp-usb/ctrl"
21-10-2022 18:09:47: + PNP Bus 001 Device 013: added
21-10-2022 18:09:47: ! PNP Bus 001 Device 013: libusb_claim_interface: Invalid parameter
21-10-2022 18:09:49: + PNP Bus 001 Device 013: retry
21-10-2022 18:09:49: ! PNP Bus 001 Device 013: libusb_claim_interface: Invalid parameter
21-10-2022 18:09:52: + PNP Bus 001 Device 013: retry
21-10-2022 18:09:52: ! PNP Bus 001 Device 013: libusb_claim_interface: Invalid parameter
21-10-2022 18:09:55: + PNP Bus 001 Device 013: retry
[...]
21-10-2022 18:20:07: ! PNP Bus 001 Device 013: libusb_claim_interface: Invalid parameter
21-10-2022 18:20:09: - HOTPLUG: removed Bus 001 Device 013
21-10-2022 18:20:09: - PNP Bus 001 Device 013: removed
21-10-2022 18:20:09:   No IPP-over-USB devices present, exiting
21-10-2022 18:20:09:   ctrlsock: shutdown
21-10-2022 18:20:09:   ipp-usb finished
24-10-2022 09:50:01:   ===============================
24-10-2022 09:50:01:   ipp-usb started in "udev" mode, pid=4294
24-10-2022 09:50:01:   ctrlsock: listening at "/var/ipp-usb/ctrl"
24-10-2022 09:50:01: + PNP Bus 001 Device 006: added
24-10-2022 09:50:01: ! PNP Bus 001 Device 006: libusb_claim_interface: Invalid parameter
24-10-2022 09:50:03: + PNP Bus 001 Device 006: retry
24-10-2022 09:50:04: ! PNP Bus 001 Device 006: libusb_claim_interface: Invalid parameter
24-10-2022 09:50:06: + PNP Bus 001 Device 006: retry
[...]
24-10-2022 10:31:29: ! PNP Bus 001 Device 007: libusb_open: No such device (it may have been disconnected)
24-10-2022 10:31:29: - HOTPLUG: removed Bus 001 Device 007
24-10-2022 10:31:29: - PNP Bus 001 Device 007: removed
24-10-2022 10:31:36:   interrupt signal received, exiting
24-10-2022 10:31:36:   ctrlsock: shutdown
24-10-2022 10:31:36:   ipp-usb finished
24-10-2022 10:31:41:   ===============================
24-10-2022 10:31:41:   ipp-usb started in "udev" mode, pid=4251
24-10-2022 10:31:41:   ctrlsock: listening at "/var/ipp-usb/ctrl"
24-10-2022 10:31:41: + PNP Bus 001 Device 008: added
24-10-2022 10:31:41: ! PNP Bus 001 Device 008: libusb_claim_interface: Invalid parameter
24-10-2022 10:31:43: + PNP Bus 001 Device 008: retry
24-10-2022 10:31:44: ! PNP Bus 001 Device 008: libusb_claim_interface: Invalid parameter
24-10-2022 10:31:46: + PNP Bus 001 Device 008: retry
[...]
25-10-2022 12:31:06: ! PNP Bus 001 Device 007: libusb_claim_interface: Invalid parameter
25-10-2022 12:31:07: - HOTPLUG: removed Bus 001 Device 007
25-10-2022 12:31:07: - PNP Bus 001 Device 007: removed
25-10-2022 12:31:07:   No IPP-over-USB devices present, exiting
25-10-2022 12:31:07:   ctrlsock: shutdown
25-10-2022 12:31:07:   ipp-usb finished

Does it say something?

Regarding legacy usb://... , already posted in the CUPS issues.

Thanks again.

bfg01 commented 1 year ago

Also tried on Debian 11.

Same results, except that /var/log/ipp-usb/main.log was never generated at all...

alexpevzner commented 1 year ago

Hi @bfg01,

sorry for delay. May I ask you to show me output of the lsusb -v command for this device?

bfg01 commented 1 year ago

@alexpevzner , Just attached here.

Brief offtopic: How does the '@' pinging work here? I've been "pinged" like this before, however no notification at all has ever appeared anywhere in the Github web interface...

lsusbOut.txt

alexpevzner commented 1 year ago

Thanks, @bfg01,

Regarding "pinging", I will receive notifications from this topic in any case, because I'm the member of this discussion (and project owner), so I receive notifications in any case.

alexpevzner commented 1 year ago

Hi @bfg01,

I hope I've fixed this bug, but cant't test by myself due to a lack of the appropriate device.

Can you build ipp-usb and test it by yourself?

bfg01 commented 1 year ago

@alexpevzner , Sorry sir, still exact same errors...

Posting all logs, using Debian 11: When building:

$ make; echo $?
gotags -R . > tags
/bin/sh: 1: gotags: not found
make: [Makefile:12: all] Error 127 (ignored)
go build -ldflags "-s -w" -tags nethttpomithttp2
go: downloading github.com/OpenPrinting/goipp v1.0.0
0
$

Ipp-usb log:

$ sudo Downloads/ipp-usb/ipp-usb; echo $?
  ===============================
  ipp-usb started in "debug" mode, pid=26356
  ctrlsock: listening at "/var/ipp-usb/ctrl"
+ HOTPLUG: added Bus 001 Device 020
+ PNP Bus 001 Device 020: added

  ===============================
+ Bus 001 Device 020: added RICOH SP 377SFNwX
  Device info:
    Ident:         05ca-0459-RH11117C-RICOH-SP-377SFNwX
    Manufacturer:  RICOH
    Product:       RICOH SP 377SFNwX
    SerialNumber:  RH11117C
    MfgAndProduct: RICOH SP 377SFNwX
    BasicCaps:     print,scan,fax,http

  Device quirks:
    from [*] (/home/user/Downloads/ipp-usb/ipp-usb-quirks/default.conf:3)
      blacklist = false
      usb-max-interfaces = 0
      disable-fax = false
      init-delay = 0s
      request-delay = 0s
      http-connection = ""

  USB stack parameters
    authorized_default:          -1
    autosuspend:                 2
    blinkenlights:               N
    initial_descriptor_timeout:  5000
    nousb:                       N
    old_scheme_first:            N
    usbfs_memory_mb:             16
    usbfs_snoop:                 N
    usbfs_snoop_max:             65536
    use_both_schemes:            Y

  USB interfaces:
    Config Interface Alt Class SubClass Proto
       1       0      0   7      1       2
       1       1      0   255    255     255
*      1       3      0   7      1       4
*      1       4      0   7      1       4
*      1       5      0   7      1       4
*      1       6      0   7      1       4

  USB[0]: open: Bus 001 Device 020 Interface 3 Alt 0
  USB[1]: open: Bus 001 Device 020 Interface 4 Alt 0
  USB[2]: open: Bus 001 Device 020 Interface 5 Alt 0
  USB[3]: open: Bus 001 Device 020 Interface 6 Alt 0
> HTTP[000]: POST http://localhost:60000/ipp/print
> HTTP[000]: request body: got 462 bytes; closed
> HTTP[000]: body is small (462 bytes), prefetched before sending
  USB[0]: connection allocated, 1 in use: a-- --- --- ---
  HTTP[000]: connection 0 allocated
< HTTP[000]: POST http://localhost:60000/ipp/print - 200 OK
< HTTP[000]: response body: got 1236 bytes; EOF
  USB[0]: connection released, 0 in use: --- --- --- ---
> HTTP[001]: POST http://localhost:60000/ipp/faxout
> HTTP[001]: request body: got 463 bytes; closed
> HTTP[001]: body is small (463 bytes), prefetched before sending
  USB[1]: connection allocated, 1 in use: --- a-- --- ---
  HTTP[001]: connection 1 allocated
< HTTP[001]: POST http://localhost:60000/ipp/faxout - 200 OK
< HTTP[001]: response body: got 1236 bytes; EOF
  USB[1]: connection released, 0 in use: --- --- --- ---
  IPP FaxOut service detected
> HTTP[002]: GET http://localhost:60000/eSCL/ScannerCapabilities
  USB[2]: connection allocated, 1 in use: --- --- a-- ---
  HTTP[002]: connection 2 allocated
< HTTP[002]: GET http://localhost:60000/eSCL/ScannerCapabilities - 200 OK
< HTTP[002]: response body: got 6854 bytes; EOF
  USB[2]: connection released, 0 in use: --- --- --- ---
> RICOH SP 377SFNwX (d01913): _printer._tcp TXT record:
> RICOH SP 377SFNwX (d01913): _ipp._tcp TXT record:
    air=none
    mopria-certified=1.3
    rp=ipp/print
    priority=50
    kind=document
    PaperMax=legal-A4
    URF=V1.4,W8,DM3,IS1,CP99,PQ3,OB10,RS600,RS200
    UUID=6861d9b0-a100-11e0-8264-002673d01913
    Color=F
    Duplex=T
    note=
    qtotal=1
    usb_MDL=SP 377SFNwX
    usb_MFG=RICOH
    usb_CMD=:JBGRD,URF
    ty=RICOH SP 377SFNwX
    product=(RICOH SP 377SFNwX)
    pdl=image/urf,image/pwg-raster,application/octet-stream
    txtvers=1
    adminurl=http://localhost:60000/index.html
    Fax=T
    rfo=ipp/faxout
    Scan=T
> RICOH SP 377SFNwX (d01913): _uscan._tcp TXT record:
    duplex=T
    is=platen,adf
    cs=binary,color,grayscale
    UUID=6861d9b0-a100-11e0-8264-002673d01913
    adminurl=http://377SFNwX-D01913.local:80/index.html
    representation=http://377SFNwX-D01913.local:80/RemyMF2_128.png
    pdl=application/pdf,image/jpeg
    ty=RICOH SP 377SFNwX
    rs=eSCL
    vers=2.62
    txtvers=1
> RICOH SP 377SFNwX (d01913): _http._tcp TXT record:
> RICOH SP 377SFNwX (d01913): _ipp-usb._tcp TXT record:
  DNS-SD: RICOH SP 377SFNwX (d01913) (USB): trying
  DNS-SD: FQDN: "host1.local"
  DNS-SD: FQDN: "host1.local"->"localhost"
  DNS-SD: +subtype: "_universal._sub._ipp._tcp"
+ DNS-SD: RICOH SP 377SFNwX (d01913) (USB): publishing requested
  DNS-SD: RICOH SP 377SFNwX (d01913) (USB): AVAHI_ENTRY_GROUP_REGISTERING
  DNS-SD: RICOH SP 377SFNwX (d01913) (USB): AVAHI_ENTRY_GROUP_ESTABLISHED
  DNS-SD: RICOH SP 377SFNwX (d01913) (USB): published
- HOTPLUG: removed Bus 001 Device 020
- PNP Bus 001 Device 020: removed
- DNS-SD: RICOH SP 377SFNwX (d01913) (USB): removed
  USB[0]: closed
  USB[1]: closed
  USB[2]: closed
  USB[3]: closed
- Bus 001 Device 020: removed RICOH SP 377SFNwX
^C  interrupt signal received, exiting
  ctrlsock: shutdown
  ipp-usb finished
0
$

CUPS version here is 2.3.3. Here I had to manually start avahi-daemon. Not sure if this matters...

Thanks again.

alexpevzner commented 1 year ago

@bfg01,

I see no errors in this log. The log looks just perfect. What actually doesn't work at this step?

alexpevzner commented 1 year ago

While ipp-usb is running, please show me output of the following 3 commands:

avahi-browse -rt _ipp._tcp
avahi-browse -rt _uscan._tcp
scanimage -L
bfg01 commented 1 year ago

@alexpevzner Command "driverless [list]" just exits with status '1', and "lpinfo -v" show no URIs, except the legacy "usb://..."

EDIT: Ok, will try those ones in a moment...

alexpevzner commented 1 year ago

avahi-daemon must be running for this stuff to work...

bfg01 commented 1 year ago

@alexpevzner , Apologies sir, it turns that it was actually a broken USB port, which most of the time no longer makes contact... Tried again, and this time it worked and was finally able to print, at least the CUPS test page.

Just one last -a bit fool- doubt, couldn't this fix affect printers using continuous USB interface listing?

Thanks very much for all your help.

alexpevzner commented 1 year ago

@bfg01,

regardless of your broken USB port, there was a real bug that was fixed, thanks to your report.

Just one last -a bit fool- doubt, couldn't this fix affect printers using continuous USB interface listing?

libusb returns me, roughly speaking, an array of interface descriptors. Each structure in this array contains, among other things, interface index within a device, used to open the interface. Usually these indices correspond 1:1 to the structure position in the array, but it is not guaranteed. By mistake, I've used structure position in the array instead of the interface index contained within each structure of that array. This mistake was not noticed before your report, so thanks for that!

alexpevzner commented 1 year ago

Hi @zdohnal,

JFYI, I've just released the 0.9.23 version which includes this fix...

zdohnal commented 1 year ago

Hi @alexpevzner ,

thank you for the ping! I'll update the package in Fedora today.

I'm glad you are okay with all things going on in the world,

Zdenek

alexpevzner commented 1 year ago

Hi @zdohnal,

Glad to hear from you.

I'm more or less fine these hard days. Found a full time job in a big enterprise (or, to be precise, that job has found me). Believe or not, this is my first time in the such a big enterprise, quite interesting experience. The only drawback, I have almost no spare time for working on my open source projects.