USB connection timeouts when attempting to attach a Canon SELPHY CP1200

[speachy]

An example of the failure. This repeats endlessly:

04-06-2021 21:29:35:   ===============================
04-06-2021 21:29:35: + Bus 003 Device 015: added SELPHY CP1200
04-06-2021 21:29:35:   Device info:
04-06-2021 21:29:35:     Ident:         04a9-32b1-ZT15120100000091-Canon-SELPHY-CP1200
04-06-2021 21:29:35:     Manufacturer:  Canon
04-06-2021 21:29:35:     Product:       SELPHY CP1200
04-06-2021 21:29:35:     SerialNumber:  ZT15120100000091
04-06-2021 21:29:35:     MfgAndProduct: Canon SELPHY CP1200
04-06-2021 21:29:35:
04-06-2021 21:29:35:   Device quirks:
04-06-2021 21:29:35:
04-06-2021 21:29:35:   USB stack parameters
04-06-2021 21:29:35:     authorized_default:          -1
04-06-2021 21:29:35:     autosuspend:                 2
04-06-2021 21:29:35:     blinkenlights:               N
04-06-2021 21:29:35:     initial_descriptor_timeout:  5000
04-06-2021 21:29:35:     nousb:                       N
04-06-2021 21:29:35:     old_scheme_first:            N
04-06-2021 21:29:35:     quirks:
04-06-2021 21:29:35:     usbfs_memory_mb:             16
04-06-2021 21:29:35:     usbfs_snoop:                 N
04-06-2021 21:29:35:     usbfs_snoop_max:             65536
04-06-2021 21:29:35:     use_both_schemes:            Y
04-06-2021 21:29:35:
04-06-2021 21:29:35:   USB interfaces:
04-06-2021 21:29:35:     Config Interface Alt Class SubClass Proto
04-06-2021 21:29:35:        1       0      0   7      1       2
04-06-2021 21:29:35: *      1       0      1   7      1       4
04-06-2021 21:29:35:        1       1      0   255    0       0
04-06-2021 21:29:35: *      1       1      1   7      1       4
04-06-2021 21:29:35:
04-06-2021 21:29:35:   USB[0]: open: Bus 003 Device 015 Interface 0 Alt 1
04-06-2021 21:29:35:   USB[1]: open: Bus 003 Device 015 Interface 1 Alt 1
04-06-2021 21:29:35: > IPP request:
04-06-2021 21:29:35: > {
04-06-2021 21:29:35: >     VERSION 2.0
04-06-2021 21:29:35: >     OPERATION Get-Printer-Attributes
04-06-2021 21:29:35: >
04-06-2021 21:29:35: >     GROUP operation-attributes-tag
04-06-2021 21:29:35: >     ATTR "attributes-charset" charset: utf-8
04-06-2021 21:29:35: >     ATTR "attributes-natural-language" naturalLanguage: en-US
04-06-2021 21:29:35: >     ATTR "printer-uri" uri: http://localhost:60000/ipp/print
04-06-2021 21:29:35: >     ATTR "requested-attributes" keyword: all
04-06-2021 21:29:35: > }
04-06-2021 21:29:35:
04-06-2021 21:29:35: > HTTP[038]: POST http://localhost:60000/ipp/print
04-06-2021 21:29:35: > HTTP[038]: request body: got 151 bytes; closed
04-06-2021 21:29:35: > HTTP[038]: body is small (151 bytes), prefetched before sending
04-06-2021 21:29:35: > HTTP[038]: HTTP request header:
04-06-2021 21:29:35: >   POST /ipp/print HTTP/1.1
04-06-2021 21:29:35: >   Host: localhost:60000
04-06-2021 21:29:35: >   User-Agent: ipp-usb
04-06-2021 21:29:35: >   Content-Length: 151
04-06-2021 21:29:35: >   Content-Type: application/ipp
04-06-2021 21:29:35: >
04-06-2021 21:29:35:   USB[0]: connection allocated, 1 in use: a-- ---
04-06-2021 21:29:35:   HTTP[038]: connection 0 allocated
04-06-2021 21:29:35: > USB[0]: write: wanted 275 sent 275 total 275
04-06-2021 21:29:40: < USB[0]: read: wanted 4096 got 0 total 0
04-06-2021 21:29:40: ! USB[0]: recv: libusb_bulk_transfer: Operation timed out
04-06-2021 21:29:40: ! HTTP[038]: libusb_bulk_transfer: Operation timed out
04-06-2021 21:29:40:   USB[0]: connection released, 0 in use: --- ---
04-06-2021 21:29:40: ! IPP: HTTP: Post "http://localhost:60000/ipp/print": libusb_bulk_transfer: Operation timed out
04-06-2021 21:29:40: - Bus 003 Device 015: resetting SELPHY CP1200
04-06-2021 21:29:40:   USB[0]: closed
04-06-2021 21:29:40:   USB[1]: closed
04-06-2021 21:29:40: - Bus 003 Device 015: removed SELPHY CP1200

I'm using ipp-usb 0.9.19, on a Fedora 34 box.

It appears the printer exports two interface/configurations that claim to support ipp-over-usb, but ipp-usb only ever attempts to bind to the first...

EDIT: I mean to say we never attempt to use USB[1], even when USB[0] is failing. That seems like an oversight!

[alexpevzner]

Hi Solomon,

actually, ipp-usb uses all available interfaces, but first request always sent to the first interface. At this case, first request fails, so ipp-usb runts reset/retry loop.

Are you able to build ipp-usb by youself? If so, could you please try the latest github version?

[speachy]

Hmm, building and running directly out of the git repo yields an endless loop of:

! PNP Bus 003 Device 017: libusb_get_device_descriptor: Pipe error
+ PNP Bus 003 Device 017: retry

[alexpevzner]

Please update and try again

[speachy]

Post-update:

! PNP Bus 003 Device 017: libusb_get_descriptor(0x21): Pipe error
+ PNP Bus 003 Device 017: retry

It seems that the commit (10450463) only changes a string, rather than making any logic changes?

EDIT: I'm compiing and running ' ./ipp-usb debug' -- that's the totality of the console logging message.

[speachy]

bisecting between the 0.9.19 and master shows "nothing but pipe errors" started with commit 971f06606b7fa8ee4725a41d7d

EDIT: pasted the wrong commit.

[speachy]

Ok, the current problem is that you're looking at the top-level interface descriptor type (which is 0x04, ie "DT_INTERFACE"), not the class-specific descriptor. This information is not directly exposed via libusb -- you'll have to manually decode it using the 'extra' and 'extra_length' fields in the interface descriptor.

Here's an example of how to do this -- see https://github.com/gregkh/usbutils/commit/657da96106d17ef64d9a17420e1b98bd828b7d35

[alexpevzner]

Yes, the previous patch only changed string in the log, to localize the problem (I onerously used the same string in two different places).

I'm actually trying to request class-specific descriptor from device, using libusb_get_descriptor and device refuses the requests. This is in usbio_libusb.go, line 528

Does usbutils correctly decode class-specific descriptor for your device?

[speachy]

Yes, ubutils works fine -- I originally wrote that patch for this very CP1200. :)

The problem is that you're asking for a device descriptor; whereas the class-specific stuff is tacked onto the end of interface descriptors -- ie 'alt' on line 243. with devhandle you can find out the current interface/altsetting, and walk the full config descriptor chain again to find the interface descriptor you need... or instead, run UsbIppBasicCaps() at the time you're probing things in libusbBuildUsbDeviceDesc() and stash the results?

[speachy]

Full lsusb -v output for the device:

Bus 003 Device 017: ID 04a9:32b1 Canon, Inc. SELPHY CP1200
Device Descriptor:
  bLength                18
  bDescriptorType         1
  bcdUSB               2.00
  bDeviceClass            0 
  bDeviceSubClass         0 
  bDeviceProtocol         0 
  bMaxPacketSize0        64
  idVendor           0x04a9 Canon, Inc.
  idProduct          0x32b1 SELPHY CP1200
  bcdDevice            0.01
  iManufacturer           1 Canon
  iProduct                2 SELPHY CP1200
  iSerial                 3 ZT15120100000091
  bNumConfigurations      1
  Configuration Descriptor:
    bLength                 9
    bDescriptorType         2
    wTotalLength       0x006b
    bNumInterfaces          2
    bConfigurationValue     1
    iConfiguration          0 
    bmAttributes         0xc0
      Self Powered
    MaxPower                2mA
    Interface Descriptor:
      bLength                 9
      bDescriptorType         4
      bInterfaceNumber        0
      bAlternateSetting       0
      bNumEndpoints           2
      bInterfaceClass         7 Printer
      bInterfaceSubClass      1 Printer
      bInterfaceProtocol      2 Bidirectional
      iInterface              0 
      Endpoint Descriptor:
        bLength                 7
        bDescriptorType         5
        bEndpointAddress     0x01  EP 1 OUT
        bmAttributes            2
          Transfer Type            Bulk
          Synch Type               None
          Usage Type               Data
        wMaxPacketSize     0x0200  1x 512 bytes
        bInterval               0
      Endpoint Descriptor:
        bLength                 7
        bDescriptorType         5
        bEndpointAddress     0x82  EP 2 IN
        bmAttributes            2
          Transfer Type            Bulk
          Synch Type               None
          Usage Type               Data
        wMaxPacketSize     0x0200  1x 512 bytes
        bInterval               0
    Interface Descriptor:
      bLength                 9
      bDescriptorType         4
      bInterfaceNumber        0
      bAlternateSetting       1
      bNumEndpoints           2
      bInterfaceClass         7 Printer
      bInterfaceSubClass      1 Printer
      bInterfaceProtocol      4 
      iInterface              0 
        IPP Printer Descriptor:
          bLength                10
          bDescriptorType        33
          bcdReleaseNumber        1
          bcdNumDescriptors       1
            iIPPVersionsSupported     0
            iIPPPrinterUUID           0 
            wBasicCapabilities   0x0011  Print HTTP-over-USB No-Auth
      Endpoint Descriptor:
        bLength                 7
        bDescriptorType         5
        bEndpointAddress     0x01  EP 1 OUT
        bmAttributes            2
          Transfer Type            Bulk
          Synch Type               None
          Usage Type               Data
        wMaxPacketSize     0x0200  1x 512 bytes
        bInterval               0
      Endpoint Descriptor:
        bLength                 7
        bDescriptorType         5
        bEndpointAddress     0x82  EP 2 IN
        bmAttributes            2
          Transfer Type            Bulk
          Synch Type               None
          Usage Type               Data
        wMaxPacketSize     0x0200  1x 512 bytes
        bInterval               0
    Interface Descriptor:
      bLength                 9
      bDescriptorType         4
      bInterfaceNumber        1
      bAlternateSetting       0
      bNumEndpoints           0
      bInterfaceClass       255 Vendor Specific Class
      bInterfaceSubClass      0 
      bInterfaceProtocol      0 
      iInterface              0 
    Interface Descriptor:
      bLength                 9
      bDescriptorType         4
      bInterfaceNumber        1
      bAlternateSetting       1
      bNumEndpoints           2
      bInterfaceClass         7 Printer
      bInterfaceSubClass      1 Printer
      bInterfaceProtocol      4 
      iInterface              0 
        IPP Printer Descriptor:
          bLength                10
          bDescriptorType        33
          bcdReleaseNumber        1
          bcdNumDescriptors       1
            iIPPVersionsSupported     0
            iIPPPrinterUUID           0 
            wBasicCapabilities   0x0011  Print HTTP-over-USB No-Auth
      Endpoint Descriptor:
        bLength                 7
        bDescriptorType         5
        bEndpointAddress     0x05  EP 5 OUT
        bmAttributes            2
          Transfer Type            Bulk
          Synch Type               None
          Usage Type               Data
        wMaxPacketSize     0x0200  1x 512 bytes
        bInterval               0
      Endpoint Descriptor:
        bLength                 7
        bDescriptorType         5
        bEndpointAddress     0x86  EP 6 IN
        bmAttributes            2
          Transfer Type            Bulk
          Synch Type               None
          Usage Type               Data
        wMaxPacketSize     0x0200  1x 512 bytes
        bInterval               0
Device Qualifier (for other device speed):
  bLength                10
  bDescriptorType         6
  bcdUSB               2.00
  bDeviceClass            0 
  bDeviceSubClass         0 
  bDeviceProtocol         0 
  bMaxPacketSize0        64
  bNumConfigurations      1
Device Status:     0x0001
  Self Powered

[alexpevzner]

I understand the idea and basically agree. The problem is that the next few days I will not have access to my printer, to test the changes.

For now, you can temporary hack the usbIppBasicCaps to always return UsbIppBasicCapsPrint | UsbIppBasicCapsScan | UsbIppBasicCapsFax | UsbIppBasicCapsAnyHTTP in caps and nil in error.

I want to understand, what is the reason of the timeout (the initial problem you came with). Latest official release requests all printer attributes, and it causes some HP devices to timeout; latest github version requests only attributes it really needs, which fixes initialization of these HP printers and may be will help with your printer too.

You may also try to play a little bit with the timeout duration, this is DevInitTimeout constant defined in the const.go file.

[alexpevzner]

ping

[speachy]

ok, short-circuiting usbIppBasicCaps to return that fixed value allows the device probe to succeed, however it's still timing out, even after I doubled DevInitTimeout to 10 seconds.

Interestingly, if I force it to use USB[1] instead of [0] it still times out.

sniff of USB handshake The interesting stuff is packets 289-310 (the IN URB is returned with -ENOENT)

It's worth stating that I have no idea if this printer actually works using IPP; under Windows (connecting via wifi) it uses Microsoft's WS-Print ("Web Services for Devices for Printing"), and via USB it uses a non-ipp proprietary protocol that I reverse-engineered several years ago. I'm still trying to get its builtin wifi working so I can see it it'll work via airprint and/or android print.

EDIT: I successfully printed directly via Android Print over wifi. But I don't have any way to determine if IPP-over-USB is expected to work on this thing.

[alexpevzner]

If it doesn't work with IPP-USB, it at least makes sense to blacklist it in the ipp-usb, so ipp-usb will not steal USB interfaces from legacy drivers. I've already seen a HP device which was announcing IPP-USB support, but responded 404 Not found to all HTTP requests sent to device,

But before doing so, it makes sense to play a little bit with the Connection: header in the HTTP requests. Please look to the /usr/share/ipp-usb/quirks/default.conf file:

http-connection = ""

Try to replace empty string with keep-alive or close

[speachy]

Okay... now it's suddently probing properly, with the hard-coded change to usbIppBasicCaps, the printer's now making it through the probe and advertising on the network. So once that descriptor parsing is fixed, this bug can probably be closed.

It seems that in order for the IPP-USB stuff to work, this printer has to be connected to WiFi. (wtf..)

I'm still not able to print (due to other issues) but I'll open other tickets.

[alexpevzner]

So http-connection setting is not required for your device, correct?

You probably can now return to the latest "official" release of the ipp-usb. The only advantage of the latest github release is that it requests less data from device during initialization, but seems it doesn't improve anything for your device. I'll notify you (and will ask to test), when I'll update the descriptor parsing.

Honestly, I've suspected that IPP-USB needs some configuration tweaks on your device, but the fact that it is bound to WiFi settings is really surprising. Looks that enabling WiFi actually enables all the HTTP stuff, including IPP-USB.

[speachy]

And it's back to not working again. Sigh. In the end it may make more sense to blacklist this thing, but in the mean time it's still useful as a particularly pathological test case.

[alexpevzner]

Have you tried to play with http-connection a little bit? For many devices it helps a lot.

[alexpevzner]

Hi!

Situation becomes more interesting. For my printer (Kyocera ECOSYS M2040dn), extra_length in the libusb_interface_descriptor is equal to 0, so lsusb with your patch doesn't print IPP capabilities, and ipp-usb also can't obtain it this way.

From another hand, obtaining class-specific Device Info Descriptor via libusb_get_descriptor, as it currently implemented in the ipp-usb, works well.

[alexpevzner]

Hi Solomon,

after some thinking/reading, I came to the following conclusion:

1. IPP-USB specification, section 4.3, cleanly states that class-specific device descriptor is the descriptor with type 0x21
2. Canon SELPHY CP1200 fails GET DESCRIPTOR command with type == 0x21, and returns the descriptor in unusual place
3. Other tested devices returns this descriptor, as expected.

So my solution is to query descriptor 0x21, but in a case of any error fall back to the reasonable default.

The only remaining question, should we try to fix IPP-USB instability of this device or simple blacklist it. Here I'm waiting for your feedback.

[speachy]

To be honest, I think the "correct" way to deal with this is to first look at the interface descriptor for the class-specific data, and if it is not detected (or invalid), fall back to a top-level descriptor query. It's all fine to quote the spec, but at the end of the day, we need to handle the printers encountered in the real world. If Canon did this for one model, they (and other manufacturers) likely did it for others.

Now it may come to pass that blacklisting the CP1200 is the a good idea, but I think there's still a lot of utility in using it as a (perhaps highly pathological) test case. I really want to see this thing print via IPP-USB.

(Oh, with respect to IPP-USB only working if a wifi connection is active; I suspect this is because the IPP functionality is implemented within the wifi module firmware...)

[alexpevzner]

Actually, query for class-specific descriptor was added as a workaroung for HP Color LaserJet Enterprise MFP M578, which returns unparseable HTTP response, when probing for /ipp/faxout, if fax unit is not installed. It's the first device to have this problem, in most cases legacy approach, which simply probes for printer/fax/scan, works well. So if ipp-usb ignores failed attempt to obtain class-specific descriptor, it will anyway work in most real world cases.

I still want you to play a little bit with the http-connection quirk, it may improve stability with the CP1200. If it helps, I will add the resulting quirk to the set of quirks that comes with the standard distribution.

[cjheppell]

Can confirm I'm seeing a similar problem trying to connect to the Canon SELPHY CP1300.

Error output below:

Error log

``` + Bus 001 Device 003: added SELPHY CP1300 Device info: Ident: 04a9-32db-B521031716242441-Canon-SELPHY-CP1300 Manufacturer: Canon Product: SELPHY CP1300 SerialNumber: B521031716242441 MfgAndProduct: Canon SELPHY CP1300 Device quirks: from [*] (/home/pi/cups/ipp-usb/ipp-usb-quirks/default.conf:3) blacklist = false usb-max-interfaces = 0 http-connection = "close" USB stack parameters authorized_default: -1 autosuspend: 2 blinkenlights: N initial_descriptor_timeout: 5000 nousb: N old_scheme_first: N quirks: 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 0 1 7 1 4 1 1 0 255 0 0 * 1 1 1 7 1 4 USB[0]: open: Bus 001 Device 003 Interface 0 Alt 1 USB[1]: open: Bus 001 Device 003 Interface 1 Alt 1 > HTTP[015]: POST http://localhost:60000/ipp/print > HTTP[015]: request body: got 151 bytes; closed > HTTP[015]: body is small (151 bytes), prefetched before sending USB[0]: connection allocated, 1 in use: a-- --- HTTP[015]: connection 0 allocated ! USB[0]: send: libusb_bulk_transfer: Operation timed out ! HTTP[015]: libusb_bulk_transfer: Operation timed out USB[0]: connection released, 0 in use: --- --- ! IPP: HTTP: Post "http://localhost:60000/ipp/print": libusb_bulk_transfer: Operation timed out - Bus 001 Device 003: resetting SELPHY CP1300 USB[0]: closed USB[1]: closed - Bus 001 Device 003: removed SELPHY CP1300 ! PNP Bus 001 Device 003: Device initialization timed out + PNP Bus 001 Device 003: retry ```

This is ipp-usb compiled from the 0.9.19 branch (the same also happens on master as of the time of this comment). I've tried setting the http-connection quirk to keep-alive and close and neither makes any difference for me.

I must admit, I know next to nothing about ipp but just sharing this in case it helps.

It'd be really nice to get this working, so I'm happy to run more tests if it can help get to the bottom of this.