CUPS prints files out of order

Solution Unverified - Updated -

Environment

  • Red Hat Enterprise Linux (RHEL)
  • Common Unix Printing System (CUPS)

Issue

  • Out-of-sequence print output. Example: Order of the printing is job #2, then job #3, then comes a delay of about 10 minutes and then job #1 is printed. Then there's another delay lasting about 2 minutes and then job #4 is printed. Another delay of about 5 minutes and then job #5 is printed. Another 5 minute delay and then job #6, job #8, and job #9 are printed. Finally, another 7 minute delay and job #7 is printed.

  • Packing slip report sheets are printed not in order. I mean that the order of the printing was 413086 and 413087, then comes a delay about 10 minute, then printed the 413085 another delay about 2 minute then printed the 413988, another delay about 5 minute then printed the 413089 another five minute delay then printed the 413090, 413092, 413093 and another 7 minute delay and printed the 413091 sheet.

Resolution

Absent any errors in the print jobs themselves, CUPS will always print jobs submitted to a single print queue in the order in which they were received (first-in-first-out). However, there are two conditions under which out-of-order printouts may occur:

  • A print job error causes CUPS to hold the print job with the error while other jobs continue printing.

  • Jobs are received by CUPS scheduler in the incorrect order.

The following section describes each of these cases in more detail.

Out-of-order Printing Caused by Print Job Errors

To resolve/minimize the effect of print job errors that can cause this out-of-order printing, please consider the following:

  • Eliminate printing errors as described in the following Knowledgebase Solution:

    Poor printing performance printing to LPD printers in Red Hat Enterprise Linux

  • Print multiple files in the same print job.

  • In RHEL 6 and later versions, set the Error Policy for the print queue to retry-current-job. This setting should cause CUPS to retry failed jobs immediately on the same queue, instead of holding the failed job and allowing other jobs to print. More information on setting printer Error Policy can be found in the following Knowledgebase Solution:

    How to keep RHEL printers from being permanently disabled due to printing errors

  • In RHEL 5 and earlier versions, it may be possible to reduce out-of-order printing by adding or changing the following line in /etc/cups/cupsd.conf:

    JobRetryInterval 0

    This will not stop the delays in printing, but it may fix out-of-order printing by configuring CUPS to immediately retry a failed print job instead of holding it for 30 seconds. Additional information on the CUPS JobRetryInterval can be found in the following Knowledgebase Solution:

    How to adjust the CUPS retry interval for printing in RHEL

Jobs Received Out-of-order

If the order of documents is critical, make sure that your application sends them in the correct order and does not interleave print job submission through multi-threaded or multi-process mechanisms (or that there are proper synchronization methods in place to ensure that jobs are submitted in the correct order). CUPS creates jobs in the order that the IPP Create-Job operation is received, not in the order that the client connections are made or in the order that the documents are sent via the IPP Send-Document operation. For example, consider the following sequence of events.

  1. Connection "a" is created to CUPS to print Document A.
  2. Connection "b" is created to CUPS to print Document B.
  3. Connection "b" is used to create a print job. This will be Job #1.
  4. Connection "a" is used to create a print job. This will be Job #2.
  5. Connection "a" is used to send Document A to Print Job #2
  6. Connection "b" is used to send Document A to Print Job #1
  7. Connection "a" is closed
  8. Connection "b" is closed

This sequence can also be represented as follows:

Connection "a" Connection "b"
Connect to CUPS
Connect to CUPS
Create-Job (Job 1)
Create-Job (Job 2)
Send-Document A
Send-Document B

In the scenario described above, Document B will be printed first because it has the lower-numbered Job ID. Document B has the lower-numbered Job ID because Connection "b" was the first to issue the Create-Job request, even though Connection "b" was made after Connection "a".

Root Cause

Jobs sent to the same print queue will be sent to the printer in the order in which they were accepted by CUPS. You can tell the order by the Job ID. When there are multiple print jobs in a print queue, the lowered-numbered job will always be printed first.

The only exception to this is wen files are submitted as separate print jobs, errors can cause the print jobs to be printed out of order. If the ErrorPolicy for a printer (defined in /etc/cups/printers.conf) is set to retry-job, then the job is re-queued to print at a later time. When CUPS sees a failure in a backend process, it holds the job for a period of time specified by the JobRetryInterval option in /etc/cups/cupsd.conf. By default, JobRetryInterval is set to 30 seconds. While the job is being held, other jobs can be printed on the same printer, leading to jobs being printed in a different order than they were added to the print queue.

However, when files are submitted as part of the same print job, all the files are treated as a single group. The lp and lpr commands submit multi-file print jobs to the local CUPS server as a single job with multiple files. The files will be printed in the same order as specified on the command line. If those files are relayed to a remote CUPS server, they will again be treated as a single, atomic, print job, and again, the order in which the files are printed will be the same as specified on the command line.

It is possible to configure two separate CUPS servers to send jobs to the same physical printer. If that printer accepts multiple connections (which some HP and Canon printers will do), then it is the responsibility of the printer to treat a single connection as a single job and not interleave multiple connections/jobs. Check with the printer manufacturer to see how the printer handles connections from multiple print servers.

Diagnostic Steps

Look for warnings like the following in /var/log/cups/error_log that indicate errors during printing:

W [23/Mar/2010:02:29:37 -0500] [Job 8104] Remote host did not respond with command status byte after 300 seconds!
I [23/Mar/2010:02:29:37 -0500] [Job 8104] Backend returned status 1 (failed)

To determine the order of print job submission, analyze the CUPS Error Log for sequences like the following:

  1. A client (Client 18) connects:

    D [03/Jul/2019:15:16:27 +0200] cupsdAcceptClient: 18 from localhost (Domain)

  2. A second client (Client 19) connects and complete the create-job/send-document/disconnect process before the previous client:

    D [03/Jul/2019:15:16:27 +0200] cupsdAcceptClient: 19 from localhost (Domain)
D [03/Jul/2019:15:16:27 +0200] cupsdReadClient: 19 1.1 Create-Job 1
D [03/Jul/2019:15:16:27 +0200] cupsdReadClient: 19 1.1 Send-Document 1
D [03/Jul/2019:15:16:27 +0200] cupsdReadClient: 19 WAITING Closing on EOF

  3. A third client (Client 20) connects and does the same thing:

    D [03/Jul/2019:15:16:27 +0200] cupsdAcceptClient: 20 from localhost (Domain)
D [03/Jul/2019:15:16:27 +0200] cupsdReadClient: 20 1.1 Create-Job 1
D [03/Jul/2019:15:16:27 +0200] cupsdReadClient: 20 1.1 Send-Document 1
D [03/Jul/2019:15:16:27 +0200] cupsdReadClient: 20 WAITING Closing on EOF

  4. Finally, Client 18 does the create-job/send-document/disconnect:

    D [03/Jul/2019:15:16:27 +0200] cupsdReadClient: 18 1.1 Create-Job 1
D [03/Jul/2019:15:16:27 +0200] cupsdReadClient: 18 1.1 Send-Document 1
D [03/Jul/2019:15:16:27 +0200] cupsdReadClient: 18 WAITING Closing on EOF

In the case above the print job from Client 19 and Client 20 would be processed before the job from Client 18. Even though Client 18 connected first, it created the print job and send the document to be printed after Clients 19 and 20 did the same.

Another example of out-or-order job submission can be found in the following log entries:

  1. Three connections (Client 21, 23, and 24) connect to CUPS:

    D [20/Jul/2021:10:43:49 -0500] [Client 21] Accepted from localhost (Domain)
D [20/Jul/2021:10:43:49 -0500] [Client 23] Accepted from localhost (Domain)
D [20/Jul/2021:10:43:49 -0500] [Client 24] Accepted from localhost (Domain)

  2. Client 23 is the first to create a job:

    D [20/Jul/2021:10:43:49 -0500] [Client 23] 1.1 Create-Job 2
D [20/Jul/2021:10:43:49 -0500] Create-Job ipp://localhost:631/printers/printer
I [20/Jul/2021:10:43:49 -0500] [Job 70027] Queued on "printer" by "user".

  3. Client 24 then creates a job:

    D [20/Jul/2021:10:43:49 -0500] [Client 24] 1.1 Create-Job 2
D [20/Jul/2021:10:43:49 -0500] Create-Job ipp://localhost:631/printers/printer
I [20/Jul/2021:10:43:49 -0500] [Job 70028] Queued on "printer" by "user".

  4. Followed by Client 21:

    D [20/Jul/2021:10:43:49 -0500] [Client 21] 1.1 Create-Job 2
D [20/Jul/2021:10:43:49 -0500] Create-Job ipp://localhost:631/printers/printer
I [20/Jul/2021:10:43:49 -0500] [Job 70029] Queued on "printer" by "user".

When the jobs are processed, they are processed in the order of Job ID, not in the order that the client connections were received:

D [20/Jul/2021:10:49:57 -0500] [Job 70027] time-at-processing=1626796197
D [20/Jul/2021:10:49:57 -0500] [Job 70027] argv[3]="Document B"
D [20/Jul/2021:10:49:58 -0500] [Job 70027] time-at-completed=1626796198

D [20/Jul/2021:10:49:58 -0500] [Job 70028] time-at-processing=1626796198
D [20/Jul/2021:10:49:58 -0500] [Job 70028] argv[3]="Document C"
D [20/Jul/2021:10:49:59 -0500] [Job 70028] time-at-completed=1626796199

D [20/Jul/2021:10:49:59 -0500] [Job 70029] time-at-processing=1626796199
D [20/Jul/2021:10:49:59 -0500] [Job 70029] argv[3]="Document A"
D [20/Jul/2021:10:50:00 -0500] [Job 70029] time-at-completed=1626796200

Because Client 21 was the last client to create a print job, it is the last job to print, even though the connection was made to the CUPS scheduler before Clients 23 and 24.

This solution is part of Red Hat’s fast-track publication program, providing a huge library of solutions that Red Hat engineers have created while supporting our customers. To give you the knowledge you need the instant it becomes available, these articles may be presented in a raw and unedited form.

Comments