USB connections sometimes stuck with HP LaserJet MFP M28

[alexpevzner]

HTTP request sent to USB sometimes stuck forever, which causes USB connection to be locked. This is especially visible on web console

Moved here from #3

[alexpevzner]

Hi @scubajeff

I'm trying to investigate this issue.

may I ask you to start freshly build ipp-usb manually with the following command:

LIBUSB_DEBUG=1000 ipp-usb debug 2>libusb.log

try to reproduce web console hangup and send me collected logs

[alexpevzner]

Hi @scubajeff,

it actually looks like hardware/firmware bug of the printer. Sometimes, but not always, GET /hp/device/defaultnew.css or GET /hp/device/jquery.js request to the printer stuck after receiving exactly 3K bytes of response (when it is not happen, defaultnew.css returns 27969 bytes and jquery.js returns 120894 bytes).

I already had a similar problem with HP OfficeJet Pro 8730, and for that device the problem was fixed by disabling HTTP connection keep-alive in the HTTP requests going to device. Although for IPP-over-USB HTTP keep-alive is meaningless, this action had a side effect of fixing the problem. It took a lot of time and testing attempts to figure out this solution :-)

I'm not giving up, but I need to think, may be several days, before I'll get any idea where to move next

[scubajeff]

I will try to upgrade to the latest firmware here. HP's firmware tools only support Windows. Got to play with qemu first.

[scubajeff]

Updated the printer to the latest firmware. Things get worse. I can't access the Web console anymore, the page kept on loading and a lot of zero-size read errors in ipp-usb log. And the worst thing is after the web console hang, printing function stopped and could only be resumed by recycle power.

[alexpevzner]

Please, send me ipp-usb logs after firmware update.

[alexpevzner]

Hi @scubajeff,

after many thinking, I've tweaked code a bit. Please, retest.

[alexpevzner]

Make a next iteration, please.

And send me, please, all log fines from the /var/log/ipp-usb/. They rotate, and sometimes something get lost.

[scubajeff]

Don't worry about the time gap in log. We usually switched off the printer after the printing finished.

[alexpevzner]

Seems it's not the very latest version of the ipp-usb. Please, fetch the latest changes and retest

[alexpevzner]

May I ask you to do two small code modifications by yourself? I don't want to put it to github before tested.

1. File usbtransport.go, line 254, comment out the following 2 lines:

   outreq.Header.Set("Connection", "close") outreq.Close = true

2. File usbio_libusb.go, line 578:

   const MAX_BULK_READ = 16384

Set constant to 512 instead of 16384

[scubajeff]

The key is connection keep-alive setting. With this on, the web console is smooth as silk. I have also try two MAX_BULK_READ setting, both worked. I can definitely feel that the response is faster when the setting is 16384. So, maybe the problem is with HP OfficeJet Pro 8730's firmware.

[alexpevzner]

Thank a lot for your investigations!

Actually, both keep-alive settings should be OK. USB connection cannot be closed from the printer side, so this setting, in theory, should have absolutely no effect. But we see, sometimes practice != theory :-)

So bug actually in both firmwares, and to make life less easy, they require different keep-alive setting as workaround.

Looks like for 8730 "closing" the connection has a side-effect of flushing remaining buffered data to the USB stack, while M28 drops this data when connection is being "closed". And in both cases there is a race between data generation and transferring it via USB, because both devices stuck with some probability, not always. Even after your firmware upgrade, many HTTP requests are served before all USB connections finally get blocked. The difference between two versions of M28 firmware seems to be in redesigned web interface, which requires more successful request to be performed to render a page.

I've added this workaround to ipp-usb, so please retest, and if everything is OK, I'll close the bug and will create a next "official" release

[scubajeff]

I believe you can close this bug now!

[alexpevzner]

Closed - resolved. Created release 0.9.7

Thank you for your help and feedback!

[scubajeff]

It is a nice piece of software, every distro should include this.

[alexpevzner]

Thank a lot for your kind words!

Distro maintainers show some resistance to inclusion of programs written in Go. Most often pronounced reason: executable size a too large. My personal opinion: when even low-end SSD size starts from tens of gigabytes, executable size doesn't matter at all.

Rewriting this program in C, that will preserve all its features, will take half a year, I guess.

[alexpevzner]

Hi @scubajeff,

Recently I've discovered yet another device that requires specific Connection: setting, and after some investigations found that it works perfectly well if Connection: header is completely removed from the HTTP request. I've newer tried your device in this mode.

I'm trying to find most generic solution that works with as many devices as possible, so I want to try your device without Connection: header.

May I ask you to perform the following experiment. Please, fetch the latest github release and in the usbtransport.go, function makeQuirks, comment out the lines 390-391:

case "HP LaserJet MFP M28-M31":
        transport.quirks = [][2]string{{"Connection", "keep-alive"}}

and then retest with your device.

Thank in advance!

[scubajeff]

Alex,

With that line commented out: Web console: fine Printing from Ubuntu: job pending forever Scanning from Ubuntu: fine Printing from Android's Office app: fine Scanning from Android using Mopria Scan app: fine

With that line still in, everything works. Do you need the log?

[alexpevzner]

Thank a lot for your response!

If it is possible, please send or attach a log,

[kayrus]

@alexpevzner I'm having the same issue with the 0.9.23 version. For some reason requests to curl -v http://192.168.1.34:60000/ipp/print stuck for 6 seconds. At the very rare situations they're fast.

Here are logs for most of the "bad" responses:

18:54: > HTTP[041]: GET http://192.168.1.34:60000/ipp/print
18:54: > HTTP[041]: HTTP request header:
18:54: >   GET /ipp/print HTTP/1.1
18:54: >   Host: 192.168.1.34:60000
18:54: >   User-Agent: curl/8.5.0
18:54: >   Accept: */*
18:54: >   Connection: keep-alive
18:54: >
18:54:   USB[0]: connection allocated, 1 in use: a-- --- ---
18:54:   HTTP[041]: connection 0 allocated
18:54: > HTTP[041]: request body: got 0 bytes; EOF
18:54: > USB[0]: write: wanted 116 sent 116 total 116
18:54: < USB[0]: read: wanted 4096 got 0 total 0
18:54: ! USB[0]: zero-size read
18:54: < USB[0]: read: wanted 4096 got 0 total 0
18:54: ! USB[0]: zero-size read
18:54: < USB[0]: read: wanted 4096 got 0 total 0
18:54: ! USB[0]: zero-size read
18:55: < USB[0]: read: wanted 4096 got 0 total 0
18:55: ! USB[0]: zero-size read
18:55: < USB[0]: read: wanted 4096 got 0 total 0
18:55: ! USB[0]: zero-size read
18:56: < USB[0]: read: wanted 4096 got 0 total 0
18:56: ! USB[0]: zero-size read
18:57: < USB[0]: read: wanted 4096 got 0 total 0
18:57: ! USB[0]: zero-size read
18:58: < USB[0]: read: wanted 4096 got 0 total 0
18:58: ! USB[0]: zero-size read
18:59: < USB[0]: read: wanted 4096 got 0 total 0
18:59: ! USB[0]: zero-size read
19:00: < USB[0]: read: wanted 4096 got 142 total 142
19:00: < HTTP[041]: GET http://192.168.1.34:60000/ipp/print - 200 OK
19:00: < HTTP[041]: HTTP response header:
19:00: <   HTTP/1.1 200 OK
19:00: <   Content-Length: 72
19:00: <   Content-Type: application/ipp
19:00: <
19:00: < HTTP[041]: response body: got 72 bytes; EOF
19:00:   USB[0]: connection released, 0 in use: --- --- ---

here are "good" rapid responses:

18:34: > HTTP[040]: GET http://192.168.1.34:60000/ipp/print
18:34: > HTTP[040]: HTTP request header:
18:34: >   GET /ipp/print HTTP/1.1
18:34: >   Host: 192.168.1.34:60000
18:34: >   User-Agent: curl/8.5.0
18:34: >   Accept: */*
18:34: >   Connection: keep-alive
18:34: >
18:34:   USB[2]: connection allocated, 1 in use: --- --- a--
18:34:   HTTP[040]: connection 2 allocated
18:34: > HTTP[040]: request body: got 0 bytes; EOF
18:34: > USB[2]: write: wanted 116 sent 116 total 116
18:34: < USB[2]: read: wanted 4096 got 142 total 142
18:34: < HTTP[040]: GET http://192.168.1.34:60000/ipp/print - 200 OK
18:34: < HTTP[040]: HTTP response header:
18:34: <   HTTP/1.1 200 OK
18:34: <   Content-Length: 72
18:34: <   Content-Type: application/ipp
18:34: <
18:34: < HTTP[040]: response body: got 72 bytes; EOF
18:34:   USB[2]: connection released, 0 in use: --- --- ---

Do I need to open a new issue?

P.S. I'm using ARM based board with https://dietpi.com image.

[alexpevzner]

Hi @kayrus,

what is the purpose of doing GET request from the IPP interface? Normally IPP uses POST requests...

[kayrus]

@alexpevzner GET is the simplest request possible.

Anyway, via printer web UI I discovered that USB was set to the "full" speed instead of the "high". After switching it to the "high" and rebooting the printer, the hiccup issue somehow disappeared. Another thing that might helped, I added the printer explicitly in my Android phone using IP:PORT. Before the mDNS discovery worked only for a couple of seconds after toggling the WiFi, but then the printer disappeared after a 3-5 secs. According to the wireshark packet capture it could happen due to slow printer responses, but I'm not 100% sure.

Anyway, now the problem is more or less solved. The only thing that remains, if I remove the printer from Android phone and rely only to mDNS, the printer still disappears after a couple of seconds.