Bug 989303

OK, I did a bit more digging into this.

The reason why I couldn't figure out what's reading the data is because it's running as root, not as lp, so I didn't see it. It's a process like this one:

root     20104  0.0  0.0 136944  3324 ?        Sl   23:33   0:00 ipp://192.168.0.14:631/ipp/port1 8056 jik Test page 1 job-uuid=urn:uuid:c7d3b46b-0f44-3613-41c1-77242013c980 media=na-letter job-originating-host-name=localhost time-at-creation=1375068796 time-at-processing=1375068796 PageSize=Letter

Now, I ran strace -f -F on the cupsd process before my most recent attempt to print a test page, and here's what it shows at the end for the ipp process:

20104 sendto(7, "emotleft/guilsinglleft/guilsingl"..., 16384, 0, NULL, 0 <unfinished ...>
20104 <... sendto resumed> )            = 6776
20104 poll([{fd=7, events=POLLOUT}], 1, 30000 <unfinished ...>
20104 <... poll resumed> )              = 0 (Timeout)
20104 poll([{fd=7, events=POLLOUT}], 1, 30000 <unfinished ...>
20104 <... poll resumed> )              = 0 (Timeout)
20104 poll([{fd=7, events=POLLOUT}], 1, 30000 <unfinished ...>
20104 <... poll resumed> )              = 0 (Timeout)
20104 poll([{fd=7, events=POLLOUT}], 1, 30000 <unfinished ...>
20104 <... poll resumed> )              = 0 (Timeout)
20104 poll([{fd=7, events=POLLOUT}], 1, 30000 <unfinished ...>
20104 <... poll resumed> )              = 0 (Timeout)
20104 poll([{fd=7, events=POLLOUT}], 1, 30000 <unfinished ...>
20104 <... poll resumed> )              = 0 (Timeout)
20104 poll([{fd=7, events=POLLOUT}], 1, 30000 <unfinished ...>
20104 <... poll resumed> )              = 0 (Timeout)
20104 poll([{fd=7, events=POLLOUT}], 1, 30000 <unfinished ...>
20104 <... poll resumed> )              = 0 (Timeout)
20104 poll([{fd=7, events=POLLOUT}], 1, 30000 <unfinished ...>
20104 <... poll resumed> )              = 0 (Timeout)
20104 poll([{fd=7, events=POLLOUT}], 1, 30000 <unfinished ...>
20104 <... poll resumed> )              = 0 (Timeout)
20104 poll([{fd=7, events=POLLOUT}], 1, 30000 <unfinished ...>

When I run netstat and look for connections to the printer, it says that the send q for the established connection has 11,584 bytes in it, so it would appear that the ipp process is correct to be blocked -- for some reason the data it's sending isn't getting to the printer.

I am not sure how things get into this state. I'm continuing to investigate.

I upgraded the firmware on my printer, and now I'm seeing slightly different behavior... If I wait long enough, the ipp job eventually does exit and the next print job eventually does get printed properly. The delay is much longer than it seems like it should be.... After the entire print job finishes coming out and the printer says "Ready" on its LCD, it takes something like 30 seconds for the ipp process to exist and for cupsd to conclude that the job has finished printing.

I have to admit that I'm not 100% certain if upgrading the printer firmware actually made a difference, or if things were working this way even before I upgraded the firmware, but I wasn't waiting long enough for the ipp process to exit.

I'm therefore going to close this with WORKSFORME; however, there is one additional important fact that I want to point out.

If I add the printer using system-config-printer instead of the settings control panel, and explicitly specify that I want the printer to use JetDirect (port 9100) instead of dnssd or ipp, then the long, unnecessary delay after each print job described above completely goes away and everything seems to work much better.

Given this, is it perhaps a bug that the apps that add printers default to IPP for HP LaserJet printers, when defaulting to JetDirect would make the printer perform better?

Re-opening for: it takes 30 seconds for cupsd to conclude that the job has finished printing.

Could you please enable debugging with 'cupsctl LogLevel=debug2' and then try the job again? Then attach /var/log/cups/error_log.

I want to see what might be causing the delay. (It's actually just the "[Job {N}]" lines I'm after.)

Created attachment 779973 [details]
debug2 Log of printing a job to LaserJet M551dn through ipp

Created attachment 781299 [details]
debug2 error log

I am seeing a similar issue (?) on my Lexmark X544, connected via dnssd://Lexmark%20X544._ipp._tcp.local/

It takes about five minutes per page to print, while cups is looping happily in "connected to printer". Have not had this in Fedora 18.

Jonathan, here's what I got from your error_log:

10:52:39 job accepted by printer
10:52:40 printer says job-state=processing
10:52:45 printer says job-state=processing
10:52:53 printer says job-state=processing
10:52:55 printer says job-state=processing
10:52:56 printer says job-state=processing
10:52:58 printer says job-state=processing
10:53:02 printer says job-state=processing
10:53:07 printer says job-state=processing
10:53:16 printer says job-state=processing
10:53:17 printer says job-state=processing
10:53:18 printer says job-state=processing
10:53:21 printer says job-state=processing
10:53:24 printer says job-state=processing
10:53:29 printer says job-state=processing
10:53:38 printer says job-state=processing
10:53:21 printer says job-state=canceled

Did you cancel it at the printer?

(In reply to Tim Waugh from comment #6)
> Did you cancel it at the printer?

No, I did not cancel it, and as far as I can tell the printer thinks that it printed the job successfully.

OK, I think the answer is just that some printers don't have reliable IPP implementations. :-(

Can't we make JetDirect the default, instead of dnssd or ipp, on printers that support it and have unreliable IPP implementations?

Frankly it stands to reason that the drivers should use JetDirect by default on printers that have it, since (at least for now) HP considers JetDirect the preferred method for submitting jobs to its printers, so it's going to support it better than IPP.

No: printers that are capable of IPP are capable of firmware updates, and should be fixed by the manufacturers.

IPP offers a number of benefits over JetDirect, including proper error reporting.

Hi Tim,

As a developer who hates when the hardware misbehaves and needs to be worked around, I am certainly sympathetic to that argument. However, I think there's a strong argument to be made on the other side.

Linux is rife with examples of workarounds for hardware issues that could and should have been fixed by the hardware manufacturers. The kernel and the X server in particular are chock full of server workarounds. Some of those are not fixable with a firmware update, so you could argue that the workarounds are necessary to support legacy hardware, but others could be fixed with updates, and some of the ones that can't have survived through many many generations of hardware, at any point during which the vendors could have fixed the problems but didn't. Heck, there are tons of workarounds for hardware issues in CUPS itself. So there is ample precedent for working around idiosyncrasies in the hardware to improve the user experience.

Proper error reporting is a good thing, but errors are the exceptional case, not the normal case, and software should be optimized to deal with the normal cases at the expense (when necessary) of sub-optimal exception handling, rather than the reverse. Furthermore, it's not like users are not going to see these errors if they aren't reported by CUPS... Any printer which is capable of supporting IPP and CUPS has more than enough lights, displays and buttons on the front of it to tell the user when something is wrong, not to mention many of them can be configured to send email when there's a problem. So I don't think slowing down the normal print cycle significantly for the sake of displaying "Low toner" to the user is the best choice.

I believe HP still has the largest market share in the enterprise printer space, which is where this problem is going to occur most obviously (though not exclusively), which means it affects a lot of people. It seems a shame to make all those people suffer for the sake of software purity.

HP's Mac OS and Windows drivers do not have this problem. Leaving this problem extant in Linux gives the Linux haters another reason (they already have many) to claim that Linux in general and Fedora in particular are not good enough to be considered a desktop platform on par with Windows and Mac OS. I don't think this is good for Linux in particular or OSS in general.

Finally, HP can't fix the problem if they don't know about it. I would think that Red Hat has a little more sway to contact HP about a problem like this than an individual user like me. Can you or someone else at Red Hat bring this issue to HP's attention, so that perhaps there is a chance they will fix it in a future release?

Thanks,

  jik

There aren't a great deal of workarounds for hardware issues in CUPS, but yes, there are indeed a few.

You raise good points. One of the main issues is that IPP bugs in printer firmware are pretty common at the moment. I guess system-config-printer could keep a per-backend blacklist of devices and the D-Bus GroupPhysicalDevices method could filter out blacklisted URIs.

I have the same printer, but no problems with printing via ipp.
My device have the firmware: 2302243_421979 and I have enable level of HP FutureSmart.
My printing URL is: ipp://DNSnameOfPrinter/ipp
I hope this will help.

This package has changed ownership in the Fedora Package Database.  Reassigning to the new owner of this component.

I don't plan to implement new features into system-config-printer - in case there is a volunteer who would like to implement the functionality, I can give him collaborator's rights at https://github.com/OpenPrinting/system-config-printer/ .