Bug 1275879

Could you please run 'journalctl _COMM=cupsd --since=2015-10-27' and attach the output? Thanks.

Created attachment 1087344 [details]
output from journalctl _COMM=cupsd --since=2015-10-27

three events of interest - where printer was re-enabled at timestamps
18:05:24, 18.05:29 and 22:01:38

Job 23, started Oct 27 17:54:55, failed here:

Oct 27 17:55:00 drdoom cupsd[1200]: Rendering completed
Oct 27 17:55:00 drdoom cupsd[1200]: Connecting to printer.
Oct 27 17:55:00 drdoom cupsd[1200]: Connected to printer.
Oct 27 17:55:00 drdoom cupsd[1200]: Hint: Try setting the LogLevel to "debug" to find out more.
Oct 27 17:55:00 drdoom cupsd[1200]: Backend returned status 1 (failed)
Oct 27 17:55:00 drdoom cupsd[1200]: Printer stopped due to backend errors; please consult the error_log file for details.

The next INFO-level log line we would expect would be "Control file sent successfully." and so the three points at which it might have failed are:

fstat() on the input file [unlikely]
Sending the receive-print-job LPD command
Sending the receive-control-file LPD command

To find out which, please run 'cupsctl LogLevel=debug2' to enable extra debugging and see if you can cause the error to happen again.

Could it be that the printer is being used by more than one queue at a time, and is failing LPD requests rather than delaying connection attempts?

Created attachment 1088787 [details]
output after sudo cupsctl LogLevel=debug2

I ran cupsctl LogLevel=debug2
which resulted in
cupsctl |grep '^_debug_logging'
_debug_logging=1

It looked like the queue didn't disable until the 1st job finished printing.
as 
lpr file
lpq
didn't show printer as disabled. but when 1st job finished it was.

Also, There are two print queues on this machine, one restricting output to black,
the other normal.  THere was no overt acvtivity on the other queue.
There was no other network activity to the printer while testing.

Thanks.

Could you please try capturing the communication between the computer and the printer?

This will print the TCP header and 4 data bytes from each packet:

tcpdump -w lpd.pcap -U -s 70 host 192.168.1.10 port 515

We only need to see the first few packets of a failed connection to know what's wrong. If you can set that tcpdump command running, and only stop it once a job fails, you can extra the packets we're interested in by running:

tcpdump -r lpd.pcap -X

and correlating the timestamps with the output of this:

journalctl -e MESSAGE='Backend returned status 1 (failed)'

Once you've found the packets, please add them into a comment here so I can figure out what's going on. The start of the connection will be indicated by '[S]' in the flags, and the final three packets of the connection will have flags [F.], [F.], and [.].

I'm expecting to see a packet sent to the printer where the last four bytes of the printed output are 0x2 followed by 'Bla' (the start of the name of the printer) -- that's the command to receive a job.

The printer should reply to that with either 0x0 (ok) or some other byte indicating error.

If it responded with 0x0, we should be sending a control file, so the next packet we send should have printed output that ends with 0x2 followed by numeric digits (the start of the length of the control file).

If we get this far, the printer will respond with some other byte that 0x0, as we know this step did not succeed.

Created attachment 1091166 [details]
Output from tcpdump -r lpd-pcap -X

Most of what you said I should see in the tcpdump doesn't agree with what I
see.
I added the 'and' to the tcpdump command
tcpdump -w lpd.pcap -U -s 70 host 192.168.1.10 and  port 515
tcpdump: listening on enp4s0, link-type EN10MB (Ethernet), capture size 70
bytes
C2390 packets captured
2390 packets received by filter
0 packets dropped by kernel

browsing to http:192.168.1.10 printer status page
    thinks its name is "Canon MP495 series" not Black-MP495
Output from journalctl -e MESSAGE='Backend returned status 1 (failed)'
Nov 07 16:13:53 drdoom cupsd[10645]: Backend returned status 1 (failed)

Only a few packets at 16:13:53, but since data didn't match what you described, 
I attached the whole dump (it was under 1 Mb)

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

This message is a reminder that Fedora 23 is nearing its end of life.
Approximately 4 (four) weeks from now Fedora will stop maintaining
and issuing updates for Fedora 23. It is Fedora's policy to close all
bug reports from releases that are no longer maintained. At that time
this bug will be closed as EOL if it remains open with a Fedora  'version'
of '23'.

Package Maintainer: If you wish for this bug to remain open because you
plan to fix it in a currently maintained version, simply change the 'version' 
to a later Fedora version.

Thank you for reporting this issue and we are sorry that we were not 
able to fix it before Fedora 23 is end of life. If you would still like 
to see this bug fixed and are able to reproduce it against a later version 
of Fedora, you are encouraged  change the 'version' to a later Fedora 
version prior this bug is closed as described in the policy above.

Although we aim to fix as many bugs as possible during every release's 
lifetime, sometimes those efforts are overtaken by events. Often a 
more recent Fedora release includes newer upstream software that fixes 
bugs or makes them obsolete.

Fedora 23 changed to end-of-life (EOL) status on 2016-12-20. Fedora 23 is
no longer maintained, which means that it will not receive any further
security or bug fix updates. As a result we are closing this bug.

If you can reproduce this bug against a currently maintained version of
Fedora please feel free to reopen this bug against that version. If you
are unable to reopen this bug, please file a new report against the
current release. If you experience problems, please add a comment to this
bug.

Thank you for reporting this bug and we are sorry it could not be fixed.