Updating Communication Code

[DavieV]

Changes to USB

The first commit is a simple change which has the USB library claim all of the available ipp-over-usb interfaces at the time of startup and only release them once the USB connection has been closed. The reason for this is that some printers will behave in strange ways if one interface is released while another interface is in the process of communicating.

Changes to ippusbxd

The second larger change is a redesign of how ippusbxd processes communication between the socket and the printer. The current implementation only supports transferring data from one end to the other, and relies on parsing the contents of the HTTP headers in the messages in order to determine when one end is done transferring data. Unfortunately due to the fact that many printers have implemented their HTTP servers in a variety of ways, the assumptions that the current implementation have made about when the printer has finished sending data do not hold up.

The proposed implementation uses a pair of threads which are responsible for reading strictly from one end of the communication. One thread reads from the socket and sends data to the printer, the other thread reads from the printer and sends data to the socket. This allows ippusbxd to serve as a simple pass-through of information without having to keep any internal state or parse the contents of the messages which it handles.

Since parsing the contents of the HTTP messages is no longer necessary, most of the existing HTTP code has been deleted.

[tillkamppeter]

Thank you very much for this major change. I have done my first test and here are my first impressions (with HP OfficeJet Pro 8730):

• In debug mode there is too much output, the console output causes high CPU load and breaks the timing when using the web admin interface localhost:60000
• Do not output binary data to the console in the debug output, use the hexdump() function of src/logging.c.
• If not in debug mode avoid all console output, not even errors, perhaps offer more than one debug mode (different verbosity levels), also syslog and/or logfile output could make sense.
• When not in debug mode the web admin interface works perfectly in Firefox (I can even scan through the web admin interface, so I have some kind of driverless scanning) and in Chromium it works more or less (much improved against my version where it did not work at all in Chromium).
• I can print multi-page jobs correctly, at least if the paper does not run out mid-job. In the end the interfaces getavailable again and the job gets removed from the print queue. If the paper runs out and I refill paper the printing of the job gets completed but ippusbxd (or the CUPS IPP backend) get into some timeout and the job stays in the print queue and the interfaces of the printer get blocked (I cannot use the web admin interface or print another job). I get error messages like

  <564537088>Error: Timed out waiting for a free USB interface
  <564537088>Error: Thread #321: Failed to acquire usb interface
  <41928448>Error: Timed out waiting for a free USB interface
  <41928448>Error: Thread #329: Failed to acquire usb interface
  <553948928>Error: Timed out waiting for a free USB interface
  <553948928>Error: Thread #323: Failed to acquire usb interface
  <67106560>Error: Timed out waiting for a free USB interface
  <67106560>Error: Thread #325: Failed to acquire usb interface
  <33535744>Error: Timed out waiting for a free USB interface
  <33535744>Error: Thread #331: Failed to acquire usb interface

  If I unplug the printer in this state ippusbxd does not terminate by itself. I have to "kill -9" ippusbxd. After plugging in the printer again and restarting ippusbxd the already printed job gets printed again.

• During all operations, especially also all succeeding operations, I get tons of error messages:

  <1932904192>Error: recv failed with err 11:Resource temporarily unavailable
  <1924511488>Error: recv failed with err 11:Resource temporarily unavailable
  <1958082304>Error: Thread #120: The transfer timed out before it could be completed: Received 0 bytes
  <1941296896>Error: recv failed with err 11:Resource temporarily unavailable
  <1924511488>Error: recv failed with err 11:Resource temporarily unavailable
  <1932904192>Error: recv failed with err 11:Resource temporarily unavailable
  <1958082304>Error: Thread #126: The transfer timed out before it could be completed: Received 0 bytes

  Please tell me if you need any additional information or testing.

[DavieV]

I think I fixed the bug that was causing that weird state to occur when you unplugged the printer. Please let me know if you still encounter anything strange.

Regarding the logging, is there anything in particular that you would like me to remove? The logs that seem to take up the most space are the ones which record the messages which have been passed through, but those were already in the code. I also see no logs when I run without debug mode on, which errors are you seeing specifically?

Also, can you point out where it is that I'm outputting binary data without using the hexdump function?

I'll make a change which trims down on the logging and add it to this pull request once I get a better idea of what needs to be changed.

[tillkamppeter]

First, about the logging problems:

1. The binary data in the log come from the hexdump() function when it is asked to output a zero-length hex dump. The function needs to get corrected to output an empty string or a newline then (simply "if (length <= 0) {...}" in the beginning).
2. The busy debug logging is caused by the high frequency of zero-length packages being transferred. Can these transfers be suppressed? Or is this what the printer/the system are actually doing? At least one could abbreviate the logging for a zero packet not logging "==========".

What has exactly changed? Why do we have that many zero-length packets now?

[tillkamppeter]

When doing a web scan, using the web admin interface http://localhost:60000/ via Firefox, I can select the scanning options and send the command to the printer, the printer then initiates the scanning and one hears the scan head moving and also slower when one chooses a higher resolution. But the PDF file does not correctly get created. The PDF viewer is opened in a new tab but nothing gets displayed. On the console where I have started ippusbxd, without --debug, I get several

<1564292864>Error: recv failed with err 11:Resource temporarily unavailable

messages. Seems that there is a timing problem with the large amount of data returned by the printer.

[tillkamppeter]

The standard version of ippusbxd, last release, as shipped with Ubuntu 18.04, has no problem with scanning via Firefox at all. I can choose the highest resolution (600 dpi) and the highest quality (100, Maximum) and I get a correct scan in the browser's PDF viewer.

[DavieV]

I have made some changes which reduce the amount of unnecessary logging, and fix the issue you were seeing where hexump() was being called on a 0 length message.

I have also made some changes which appear to fix scanning via the web interface. Using the web interface for my HP Envy 4520 printer I am able to scan a large photo using the highest DPI setting (600) as well as the the highest quality setting (100).

Please let me know if the scanning works for you now, or if you encounter any other errors.

[tillkamppeter]

Thank you very much for the fix. Hi-DPI web scanning works now. Also the items on the front page get reliably loaded (was not the case before). Independent whether one is doing something or not, sometimes appears a message like

<2133137152>Error: recv failed with err 11:Resource temporarily unavailable

When going around in the web interface or when scanning, messages like

<1610610432>Error: Timed out waiting for a free USB interface
<1610610432>Error: Thread #19: Failed to acquire usb interface
<1602217728>Error: Timed out waiting for a free USB interface
<1602217728>Error: Thread #21: Failed to acquire usb interface
<1593825024>Error: Timed out waiting for a free USB interface
<1593825024>Error: Thread #23: Failed to acquire usb interface
<1585432320>Error: Timed out waiting for a free USB interface
<1585432320>Error: Thread #25: Failed to acquire usb interface
<-2145044736>Error: Thread #18: The transfer timed out before it could be completed: Received 0 bytes
<-2145044736>Error: Thread #18: The transfer timed out before it could be completed: Received 0 bytes

They usually occur once per operation, not repeating during scan data tranfer and not appearing when doing nothing.

[tillkamppeter]

Both navigating in the web interface and hi-DPI scanning works also with ippusbxd running in debug mode now.

[tillkamppeter]

With Chromium I can now open the front page of the web admin interface and all the items show, but when I click on "Scan", the browser tries to switch to secure (https:) mode which does not work (do not know whether it is the printer or ippusbxd not supporting secure mode).

[tillkamppeter]

Can you also fix the compiler warnings? Especially there are some comparisons of signed with unsigned integers.

[tillkamppeter]

Thank you very much. The compiler warnings are actually eliminated. Using Firefox the web interface works, including high-res high-quality scanning, but it is slow and on the terminal where I have started ippusbxd I get messages like this (no --debug);

<-25180416>Error: Timed out waiting for a free USB interface
<-25180416>Error: Thread #7: Failed to acquire usb interface
<-25180416>Error: Timed out waiting for a free USB interface
<-25180416>Error: Thread #9: Failed to acquire usb interface
<-33573120>Error: Timed out waiting for a free USB interface
<-33573120>Error: Thread #11: Failed to acquire usb interface
<-41965824>Error: Timed out waiting for a free USB interface
<-41965824>Error: Thread #13: Failed to acquire usb interface
<-50358528>Error: Timed out waiting for a free USB interface
<-50358528>Error: Thread #15: Failed to acquire usb interface
<382240512>Error: Thread #6: The transfer timed out before it could be completed: Received 0 bytes
<382240512>Error: Thread #6: The transfer timed out before it could be completed: Received 0 bytes

so the message

recv failed with err 11:Resource temporarily unavailable

is not there any more, but the other messages talked about earlier are still there.

[DavieV]

Is the web interface in this version slower than the current upstream version?

I think the reason for the slowness is due to the fact that the web browser attempts to retrieve many different elements on the page using separate tcp connections. There are more connection requests than available ippusb interfaces, which results in a few of the connection threads timing out before being able to acquire an interface (and slowing down the page load).

I think this is also connected to these USB timeout errors: <-50358528>Error: Timed out waiting for a free USB interface

I'll look into a way to remedy these errors, but I should point out that they also occur in the current upstream version (1.32).

As for these USB errors: <382240512>Error: Thread #6: The transfer timed out before it could be completed: Received 0 bytes

They are caused by a similar issue to the recv errors that I just removed, I'll add another commit to fix these as well.

[tillkamppeter]

Yes, the upstream ippusbxd is as slow and produces similar errors:

till@till-x1yoga:~/printing/openprinting/ippusbxd/new/ippusbxd$ ippusbxd
60000|18900|till@till-x1yoga:~/printing/openprinting/ippusbxd/new/ippusbxd$ 
till@till-x1yoga:~/printing/openprinting/ippusbxd/new/ippusbxd$ 
till@till-x1yoga:~/printing/openprinting/ippusbxd/new/ippusbxd$ <-1909459200>Error: recv failed with err 11:Resource temporarily unavailable
<2013263616>Error: Timed out waiting for a free USB interface
<2013263616>Error: Thread #5: M 0x7f666c000b20: Failed to acquire usb interface
<2004870912>Error: Timed out waiting for a free USB interface
<2004870912>Error: Thread #6: M 0x7f6664000b20: Failed to acquire usb interface
<-1917851904>Error: recv failed with err 11:Resource temporarily unavailable
<2004870912>Error: Timed out waiting for a free USB interface
<2004870912>Error: Thread #8: M 0x7f6664000b20: Failed to acquire usb interface
<-1934637312>Error: recv failed with err 11:Resource temporarily unavailable
<2004870912>Error: Interface #0 (4) already in use!
<2004870912>Error: Thread #10: M 0x7f6664000b20: Failed to acquire usb interface
<2013263616>Error: Timed out waiting for a free USB interface
<2013263616>Error: Thread #11: M 0x7f666c000b20: Failed to acquire usb interface
<2004870912>Error: Timed out waiting for a free USB interface
<2004870912>Error: Thread #12: M 0x7f6664000b20: Failed to acquire usb interface
<-1909459200>Error: Timed out waiting for a free USB interface
<-1909459200>Error: Thread #13: M 0x7f6680000b20: Failed to acquire usb interface
<-1934637312>Error: recv failed with err 11:Resource temporarily unavailable
<-1926244608>Error: recv failed with err 11:Resource temporarily unavailable
<-1917851904>Error: recv failed with err 11:Resource temporarily unavailable

till@till-x1yoga:~/printing/openprinting/ippusbxd/new/ippusbxd$ <-1917851904>Error: recv failed with err 11:Resource temporarily unavailable

till@till-x1yoga:~/printing/openprinting/ippusbxd/new/ippusbxd$ 

[DavieV]

I've created a simple patch to remove the "Transfer timed out before it could be completed errors"

In a future patch I'll look into addressing the overall slowness and the fact that some connections are dropped before they are able to access a USB interface.

[tillkamppeter]

Thanks for the patch. Now I only get

<1870653184>Error: Timed out waiting for a free USB interface
<1870653184>Error: Thread #11: Failed to acquire usb interface

5 times for the front page of the web interface, 3 times for the "Scan" page and no occurance for the scan itself (scanned on highest resolution and quality).

[DavieV]

Right, so these are already errors that are seen in the current version ippusbxd.

With this pull request, there should be support for more Canon devices that would previously fail when using ippusbxd. Also, since this version no longer requires reading the contents of the messages it transfers, it should now be possible to add support for ipps.

In a future pull request I can try to address to overall slowness found in the web interface due to the browser flooding the printer with more requests than it can handle.

If there's anything else that you would like me to address before pulling this in let me know.

[tillkamppeter]

Thank you very much for this change. As this is a great improvements and also not showing any regressions any more I have merged this pull request. I especially appreciate your testing on another printer brand than HP, in this case Canon, and also eliminating the need of parsing the stream content. I am looking forward for further contributions, especially

• ipps support
• Fix overall slowness found in the web interface