Bug 989303 - Per-backend device blacklist for GroupPhysicalDevices
Per-backend device blacklist for GroupPhysicalDevices
Status: ASSIGNED
Product: Fedora
Classification: Fedora
Component: system-config-printer (Show other bugs)
rawhide
Unspecified Unspecified
unspecified Severity unspecified
: ---
: ---
Assigned To: Zdenek Dohnal
Fedora Extras Quality Assurance
: FutureFeature, Reopened
Depends On:
Blocks:
  Show dependency treegraph
 
Reported: 2013-07-28 23:25 EDT by Jonathan Kamens
Modified: 2016-06-24 06:40 EDT (History)
4 users (show)

See Also:
Fixed In Version:
Doc Type: Enhancement
Doc Text:
Story Points: ---
Clone Of:
Environment:
Last Closed: 2013-08-05 07:25:54 EDT
Type: Bug
Regression: ---
Mount Type: ---
Documentation: ---
CRM:
Verified Versions:
Category: ---
oVirt Team: ---
RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: ---


Attachments (Terms of Use)
debug2 Log of printing a job to LaserJet M551dn through ipp (1021.36 KB, text/plain)
2013-07-29 10:57 EDT, Jonathan Kamens
no flags Details
debug2 error log (2.89 MB, text/plain)
2013-07-31 14:36 EDT, Robert Buchholz
no flags Details

  None (edit)
Description Jonathan Kamens 2013-07-28 23:25:05 EDT
I have an HP LaserJet 500 Color M551dn printer on my network.

The driver that gets automatically selected when I add this printer is HP LaserJet 500 color M551. It uses dnssd protocol by default. It can also be configured manually to use ipp instead of dnssd.

In either case, the driver is pretty much unusable, by which I mean that perhaps it would print properly if it were actually able to talk to the printer, but most of the time it simply hangs when you try to print.

Right now, for example, I've just tried to print a test page immediately after adding the printer, and lpstat -t says "Connected to printer", but the printer itself shows no sign of thinking that anything is connected to it, and nothing is printing.

Restarting cups with "systemctl restart cups" doesn't help.

Here are the four cups processes that are running right now while the print job is hung:

lp       19045  0.0  0.0  65712  2468 ?        S    23:12   0:00 HP-LaserJet-500-color-M551 8053 jik Test page 1 job-uuid=urn:uuid:939a7b85-d938-35ff-6560-4511eb9546aa media=na-letter job-originating-host-name=localhost time-at-creation=1375067393 time-at-processing=1375067579 PageSize=Letter
lp       19046  0.1  0.1 254480 13224 ?        S    23:12   0:00 python /usr/lib/cups/filter/hpps 8053 jik Test page 1 job-uuid=urn:uuid:939a7b85-d938-35ff-6560-4511eb9546aa media=na-letter job-originating-host-name=localhost time-at-creation=1375067393 time-at-processing=1375067579 PageSize=Letter
lp       19048  0.5  0.5 105736 70724 ?        S    23:12   0:00 pdftops -level2 -origpagesizes -r 600 /var/spool/cups/tmp/cupsvCWqPE -
lp       19049  0.0  0.0 162420  2448 ?        S    23:12   0:00 HP-LaserJet-500-color-M551 8053 jik Test page 1 job-uuid=urn:uuid:939a7b85-d938-35ff-6560-4511eb9546aa media=na-letter job-originating-host-name=localhost time-at-creation=1375067393 time-at-processing=1375067579 PageSize=Letter

Process 19045 is hung in wait4. Process 19046 is hung writing to stdout (though I don't know what its stdout is connected to; lsof just says "pipe"). Process 19048 is also hung writing to stdout (ditto). And process 19049 is _also_ hung writing to stdout (ditto). If you're scratching you're head and saying, "Hmm, that's odd, how can a bunch of processes in a pipe all be hung writing to stdout, when nothing appears to be trying to _read_?" then you're wondering the same thing I am.

When I remove the hung print job with lprm, lpstat -t subsequently reports "Unable to cancel print job."

I've tried changing the log level to debug in cupsd.conf, but that doesn't seem to shed and useful light on what is going wrong.

Because these problems are not knew, i.e., they were equally present in earlier Fedora releases, I had in the past used the Generic PCL 6/PCL XL Printer driver, but that has a new problem in Fedora 19 which I will submit a separate bug about.

If anyone has any ideas for how I might be able to debug this further, I'm all ears.
Comment 1 Jonathan Kamens 2013-07-28 23:43:51 EDT
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.
Comment 2 Jonathan Kamens 2013-07-29 01:02:04 EDT
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?
Comment 3 Tim Waugh 2013-07-29 10:46:49 EDT
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.)
Comment 4 Jonathan Kamens 2013-07-29 10:57:08 EDT
Created attachment 779973 [details]
debug2 Log of printing a job to LaserJet M551dn through ipp
Comment 5 Robert Buchholz 2013-07-31 14:36:14 EDT
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.
Comment 6 Tim Waugh 2013-08-01 11:37:34 EDT
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?
Comment 7 Jonathan Kamens 2013-08-01 11:38:55 EDT
(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.
Comment 8 Tim Waugh 2013-08-05 07:25:54 EDT
OK, I think the answer is just that some printers don't have reliable IPP implementations. :-(
Comment 9 Jonathan Kamens 2013-08-11 07:22:34 EDT
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.
Comment 10 Tim Waugh 2013-08-12 06:13:00 EDT
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.
Comment 11 Jonathan Kamens 2013-08-12 07:36:17 EDT
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
Comment 12 Tim Waugh 2013-08-28 10:07:54 EDT
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.
Comment 13 Frank Büttner 2014-04-18 13:35:06 EDT
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.
Comment 14 Fedora Admin XMLRPC Client 2016-06-24 06:40:55 EDT
This package has changed ownership in the Fedora Package Database.  Reassigning to the new owner of this component.

Note You need to log in before you can comment on or make changes to this bug.