IPP printer gets paused after MaxJobTime even though the policy is retry-job

[akorobkin]

I found that when a job is sent to a printer over IPP, and the printer reports back any kind of an issue (cover open, no toner, jam, etc). the job is held in the queue for the MaxJobTime.

However, after MaxJobTime not only the job gets cancelled, but the printer itself gets paused as well and never unpaused. It's surprising because server-wide policy is retry-job and printer's own policy is retry-job.

Here is the printer setup:

<Printer blip-color>
UUID urn:uuid:c2ed813e-507b-30b4-7bc6-698a9226378e
AuthInfoRequired none
Info blip-color
MakeModel Ricoh Aficio MP C3004 PS
DeviceURI ipp://blip-color:631/printer
State Idle
StateTime 1550157235
ConfigTime 1549568815
Type 8434172
Accepting Yes
Shared Yes
JobSheets none none
QuotaPeriod 0
PageLimit 0
KLimit 0
OpPolicy default
ErrorPolicy retry-job
</Printer>

Attached is a debug log for a Job 72, that was sent on 20:55, got cancelled on 21:55 (because printer cover was open), and the printer itself had become paused. (error_log_Job_72.txt)
Also attached cupsd.conf, cups-files.conf, and whole error_log from 20:55 to 21:55.

Could this please be looked at? It seems to be an unexpected behaviour of IPP backend for such a setup.

Relevant feature request: please add a line to the log showing when the printer was paused and why. It exists for manual cupsenable/cupsdisable (Printer "blip-color" started by "admin"), but doesn't seem to exist for internal events like this one.

[michaelrsweet]

Investigating; as for logging, such logging already exists when debug logging is enabled and for job errors...

[akorobkin]

Thank you.

If have a moment, could you please point out how the logging message looks in the referenced error_log? The printer had got paused around 21:55, but I couldn't find a relevant line in the debug log that would clearly tell me that it happened.

I forgot to attach cupsd.conf. Here it is.

#
# See "man cupsd.conf" for a complete description of this file.
#

ServerName printserver-unstable1
ServerAlias *
ServerAdmin cups-team

# Include /etc/cups/cups-files.conf

MaxLogSize 1000000000

# Log general information in error_log - change "info" to "debug" for
# troubleshooting...
LogLevel debug

# Only listen for connections from the local machine.
Port 631
SSLPort 443

Listen /var/run/cups/cups.sock
ListenBacklog 1024

# MaxClients is limited to 1/3 (109225) of the file descriptor limit
# Make sure this ulimit is increased to 3x MaxClients
MaxClients 20000
MaxClientsPerHost 1000

# Max jobs per server, and per printer, and max waiting time before purging
MaxJobs 500
MaxJobsPerPrinter 50
MaxJobTime 3600

# Don't store job files
PreserveJobFiles Off

# Run filters at lower priority to avoid starving out smbd/cupsd
FilterNice 5

# Browsing configuration varies per host; include it as a separate file
Browsing off

# Default authentication type, when authentication is required...
DefaultAuthType Basic

# Do not pause printers on communication errors
ErrorPolicy retry-job

# Use papersize from PPD, don't enforce it
DefaultPaperSize none

<Location />
  Encryption Required
</Location>

# Restrict access to the admin pages...
<Location /admin>
  Encryption Required
  Require user @SYSTEM @support-admin-printers 
</Location>

# Restrict access to configuration files...
<Location /admin/conf>
  Encryption Required
  Require user @SYSTEM @support-admin-printers 
</Location>

# Set the default printer/job policies...
<Policy default>
  # Hide job names in the log (new in CUPS 1.5.x, but breaks 1.4)
  JobPrivateAccess @OWNER @SYSTEM @support-admin-printers 
  JobPrivateValues job-name

  # Job-related operations must be done by the owner or an adminstrator...
  <Limit Send-Document Send-URI Set-Job-Attributes CUPS-Move-Job CUPS-Get-Document>
    Require user @OWNER @SYSTEM
  </Limit>

  # Job-related operations must be done by the owner or an printer support...
  <Limit Hold-Job Release-Job Restart-Job Purge-Jobs Reprocess-Job Cancel-Current-Job Suspend-Current-Job Resume-Job>
    Require user @OWNER @SYSTEM @support-admin-printers 
  </Limit>

  # All administration operations require an adminstrator to authenticate...
  <Limit Pause-Printer Resume-Printer Set-Printer-Attributes Enable-Printer Disable-Printer Pause-Printer-After-Current-Job Hold-New-Jobs Release-Held-New-Jobs Deactivate-Printer Activate-Printer Restart-Printer Shutdown-Printer Startup-Printer Promote-Job Schedule-Job-After CUPS-Delete-Printer CUPS-Delete-Class CUPS-Accept-Jobs CUPS-Reject-Jobs>
    Require user @SYSTEM @support-admin-printers 
  </Limit>

  # Only allow system and role accounts to create new print queues.
  <Limit CUPS-Add-Modify-Printer CUPS-Add-Class CUPS-Set-Default Create-Job-Subscription Create-Printer-Subscription Renew-Subscription Cancel-Subscription Get-Notifications>
    Require user @SYSTEM 
  </Limit>

  # Only the owner or an administrator can cancel or authenticate a job...
  <Limit Cancel-Job CUPS-Authenticate-Job>
    Require user @OWNER @SYSTEM @support-admin-printers 
  </Limit>

  <Limit All>
    Order deny,allow
  </Limit>
</Policy>

[michaelrsweet]

The log snippet you sent contains the following at the end:

D [13/Feb/2019:21:56:40 +0000] [Job 72] PID 56831 (/usr/lib/cups/backend/ipp) stopped with status 4.
I [13/Feb/2019:21:56:40 +0000] [Job 72] Backend returned status 4 (stop printer)

Tracing things back it looks like it is returning status 4 because the Create-Job request was interrupted:

D [13/Feb/2019:21:56:39 +0000] [Job 72] Create-Job: server-error-internal-error (Interrupted system call)

which tells me this printer doesn't implement IPP properly (Create-Job MUST NOT hang like this, Send-Document and Print-Job might but at that point we are able to track the progress of the remote job...)

Seems like a) cupsd should ignore the exit status when a job has been canceled and b) the IPP backend should return OK when it gets SIGTERM.

[michaelrsweet]

[master 45cae1b] Don't stop a printer after a job is canceled/aborted (Issue #5517)

[branch-2.2 3a66aed] Don't stop a printer after a job is canceled/aborted (Issue #5517)

[akorobkin]

Thank you so much.
Would be so helpful if there was an additional info line: "Printer blip-color was stopped by IPP backend." or something. "Backend returned status 4 (stop printer)" isn't apparent enough that it was the cause that stopped the printer.

i understand this one is fixed, it's just for any future situations where a backend stops the printer for any other reason.

[akorobkin]

I added this patch to my 2.2.8 server and confirmed that it works. Thanks again!

[UliWehner]

The log snippet you sent contains the following at the end:

D [13/Feb/2019:21:56:40 +0000] [Job 72] PID 56831 (/usr/lib/cups/backend/ipp) stopped with status 4.
I [13/Feb/2019:21:56:40 +0000] [Job 72] Backend returned status 4 (stop printer)

Tracing things back it looks like it is returning status 4 because the Create-Job request was interrupted:

D [13/Feb/2019:21:56:39 +0000] [Job 72] Create-Job: server-error-internal-error (Interrupted system call)

which tells me this printer doesn't implement IPP properly (Create-Job MUST NOT hang like this, Send-Document and Print-Job might but at that point we are able to track the progress of the remote job...)

Seems like a) cupsd should ignore the exit status when a job has been canceled and b) the IPP backend should return OK when it gets SIGTERM.

Mike,

what exactly should happen on the printer side? Cover open can easily be rectified by a user, at which point the job would continue to print. Should it time out?
Should it return a particular status?

I asked Alex to send me a capture that i can share with the developers, but if you have a particular solution in mind, please share it.

regards

Uli

[michaelrsweet]

@UliWehner The printer should accept the Create-Job request or reject it with server-error-service-unavailable or server-error-busy so that the client retries at a later time. The only time you have the printer pause the data transfer during a print is with the Print-Job and Send-Document requests.

Otherwise, it looks like the printer is correctly returning the cover-open printer-state-reason, so the issue is just that the IPP backend is hung waiting for the printer to respond to the Create-Job request.