MaxJobTime=0 results in jobs being cancelled immediately instead of never

Bug #1804576 reported by Trent Lloyd on 2018-11-22
12
This bug affects 1 person
Affects Status Importance Assigned to Milestone
CUPS
Fix Released
Unknown
cups (Debian)
Fix Released
Unknown
cups (Ubuntu)
Medium
Dan Streetman
Xenial
Medium
Dariusz Gadomski
Bionic
Medium
Dariusz Gadomski
Cosmic
Medium
Dariusz Gadomski
Disco
Medium
Dan Streetman

Bug Description

[Impact]

 Setting the cupsd option MaxJobTime to 0 should make the server wait indefinitely for the job to be ready for print. Instead, after updating job-cancel-after option with MaxJobTime=0 value it results in immediate cancelling.
This leads to problems with using filters that take some time to process - the user needs to set MaxJobTime to a ridiculously high value to ensure the job is not going to get cancelled instead of just disabling the cancelling timeout.

[Test Case]

 1. Add MaxJobTime 0 option to /etc/cups/cupsd.conf.
 2. Setup a filter that takes at least several seconds to process.
    (please find a sample imagetopdf wrapper introducing 5s delay)
 3. Submit a print job matching the filter, e.g.
    lp -d my-printer someimage.jpg # jpg uses the imagetopdf wrapper

Expected result:
The job is printed after the 5s delay.

Actual result:
The job is cancelled.

[Regression Potential]

 The scope of the change is limited to fixing the MaxJobTime handling
 in scheduler/job.c and scheduler/printers.c. There should be no
 difference in behavior except for the special value of MaxJobTime=0.

[Other Info]
Original bug description:

When using CUPS filters, these filters can take a few seconds to complete.

In this case no documents are allowed to be lost on printing failures, so we used to set "MaxJobTime 0" in cupsd.conf which worked on Ubuntu 14.04.

With cups on 18.04, you get the following message in /var/log/cups/error_log whenever the filter takes a little longer:
I [12/Nov/2018:14:43:26 +0100] [Job 18] Canceling stuck job after 0 seconds.

Then, the job is deleted and lost.

"MaxJobTime 0" is documented as "indefinite wait", but apparently cups treats is as "wait almost not at all".

This issue appears to have also been filed upstream: https://github.com/apple/cups/issues/5438

Temporary workaround is to set the MaxJobTime to a very large value instead (e.g. 3 years)

Trusty is not affected by this bug.

Trent Lloyd (lathiat) wrote :

I enabled "debug2" log level and tested again. I found the following entries in the log:
d [20/Nov/2018:08:22:25 +0100] cupsdCheckJobs: 1 active jobs, sleeping=0, ac-power=-1, reload=0, curtime=1542698545
d [20/Nov/2018:08:22:25 +0100] cupsdCheckJobs: Job 75 - dest="hvitcpdf", printer=(nil), state=3, cancel_time=0, hold_until=1542698845, kill_time=0, pending_cost=0, pending_timeout=0
[...]
d [20/Nov/2018:08:22:35 +0100] cupsdCheckJobs: 1 active jobs, sleeping=0, ac-power=-1, reload=0, curtime=1542698555
d [20/Nov/2018:08:22:35 +0100] cupsdCheckJobs: Job 75 - dest="hvitcpdf", printer=0x55faadd92e00, state=5, cancel_time=1542698545, hold_until=1542698845, kill_time=0, pending_cost=0, pending_timeout=0

In the first run of cupsdCheckJobs, the cancel_time of the job is zero, which means to wait indefinitely as expected. In the second run, the cancel_time has been updated to the time of the creation of the job which is wrong.

There is now an individual cancellation time for each job, which is initialized to MaxJobTime if it's not explicitely set. See printers.c around line 3450:
---
if (!cupsGetOption("job-cancel-after", p->num_options, p->options))
ippAddInteger(p->attrs, IPP_TAG_PRINTER, IPP_TAG_INTEGER,
"job-cancel-after-default", MaxJobTime);

---
So if MaxJobTime is set to 0 - which means never to kill the job - the default for job-cancel-after is set to 0 - which means to kill the job immediately. So I guess there is a missing check for the special value of 0.

Trent Lloyd (lathiat) on 2018-11-22
description: updated
Changed in cups (Ubuntu):
status: New → Confirmed
importance: Undecided → Medium
Changed in cups:
status: Unknown → New
Dariusz Gadomski (dgadomski) wrote :

SRU proposal for disco.

description: updated
tags: added: sts
Dariusz Gadomski (dgadomski) wrote :

SRU proposal for Cosmic.

Dariusz Gadomski (dgadomski) wrote :

SRU proposal for bionic.

Dariusz Gadomski (dgadomski) wrote :

SRU proposal for xenial.

Dariusz Gadomski (dgadomski) wrote :

imagetopdf filter wrapper I've used for the reproducer:
#!/usr/bin/env python

import sys
import time
import subprocess

def main():
    time.sleep(5)
    args = ["/usr/lib/cups/filter/imagetopdf.bkp"] + sys.argv[1:]
    subprocess.call(args, stdin=sys.stdin, stdout=sys.stdout, stderr=sys.stderr)

if __name__ == "__main__":
    main()

Dan Streetman (ddstreet) on 2018-12-06
Changed in cups (Ubuntu Disco):
assignee: nobody → Dariusz Gadomski (dgadomski)
Changed in cups (Ubuntu Cosmic):
assignee: nobody → Dariusz Gadomski (dgadomski)
Changed in cups (Ubuntu Bionic):
assignee: nobody → Dariusz Gadomski (dgadomski)
Changed in cups (Ubuntu Xenial):
assignee: nobody → Dariusz Gadomski (dgadomski)
Changed in cups (Ubuntu Cosmic):
importance: Undecided → Medium
Changed in cups (Ubuntu Bionic):
importance: Undecided → Medium
Changed in cups (Ubuntu Xenial):
importance: Undecided → Medium
Changed in cups (Ubuntu Cosmic):
status: New → In Progress
Changed in cups (Ubuntu Disco):
status: Confirmed → In Progress
Changed in cups (Ubuntu Bionic):
status: New → In Progress
Changed in cups (Ubuntu Xenial):
status: New → In Progress
Dan Streetman (ddstreet) on 2018-12-06
Changed in cups (Ubuntu Trusty):
status: New → Invalid
description: updated
Dariusz Gadomski (dgadomski) wrote :

SRU proposal for disco (fixed)

Dan Streetman (ddstreet) on 2018-12-06
tags: added: sts-sponsor sts-sponsor-ddstreet
Dan Streetman (ddstreet) on 2018-12-06
Changed in cups (Ubuntu Disco):
assignee: Dariusz Gadomski (dgadomski) → Dan Streetman (ddstreet)
Dan Streetman (ddstreet) wrote :
Changed in cups (Debian):
status: Unknown → New
Till Kamppeter (till-kamppeter) wrote :

Sponsored all the CUPS package uploads: disco, cosmic, bionic, xenial, and subscribed SRU team.

Dan Streetman (ddstreet) wrote :

> Sponsored all the CUPS package uploads: disco, cosmic, bionic, xenial,
> and subscribed SRU team.

hmm, cups is still in disco-proposed currently, so hopefully that proceeds to -updates without problems.

Thanks.

Jeremy Bicha (jbicha) wrote :

I am unsubscribing the Sponsors Team since there doesn't appear to be anything left to sponsor here. Please feel to resubscribe if you have anything else that needs to be sponsored.

Changed in cups (Debian):
status: New → Fix Released
Changed in cups:
status: New → Fix Released
Launchpad Janitor (janitor) wrote :

This bug was fixed in the package cups - 2.2.9-4

---------------
cups (2.2.9-4) unstable; urgency=medium

  * Cherry-pick from upstream:
    - Fix handling of MaxJobTime 0
      (Issue #5438, LP: #1804576, Closes: #915724)

 -- Didier Raboud <email address hidden> Thu, 06 Dec 2018 19:05:22 +0100

Changed in cups (Ubuntu Disco):
status: In Progress → Fix Released

An upload of cups to cosmic-proposed has been rejected from the upload queue for the following reason: "This SRU was shadowed by a security update of cups in cosmic. Please reupload these changes on top of that update.".

Brian Murray (brian-murray) wrote :

An upload of cups to bionic-proposed has been rejected from the upload queue for the following reason: "This SRU was shadowed by a security update of cups in cosmic. Please reupload these changes on top of that update.".

Brian Murray (brian-murray) wrote :

An upload of cups to xenial-proposed has been rejected from the upload queue for the following reason: "This SRU was shadowed by a security update of cups in xenial. Please reupload these changes on top of that update.".

Dariusz Gadomski (dgadomski) wrote :

Updated debdiff for cosmic.

Dariusz Gadomski (dgadomski) wrote :

Updated debdiff for bionic.

Dariusz Gadomski (dgadomski) wrote :

Updated debdiff for xenial.

Thank you for the new debdiffs. I have uploaded all these packages now.

Hello Trent, or anyone else affected,

Accepted cups into cosmic-proposed. The package will build now and be available at https://launchpad.net/ubuntu/+source/cups/2.2.8-5ubuntu1.2 in a few hours, and then in the -proposed repository.

Please help us by testing this new package. See https://wiki.ubuntu.com/Testing/EnableProposed for documentation on how to enable and use -proposed. Your feedback will aid us getting this update out to other Ubuntu users.

If this package fixes the bug for you, please add a comment to this bug, mentioning the version of the package you tested and change the tag from verification-needed-cosmic to verification-done-cosmic. If it does not fix the bug for you, please add a comment stating that, and change the tag to verification-failed-cosmic. In either case, without details of your testing we will not be able to proceed.

Further information regarding the verification process can be found at https://wiki.ubuntu.com/QATeam/PerformingSRUVerification . Thank you in advance for helping!

N.B. The updated package will be released to -updates after the bug(s) fixed by this package have been verified and the package has been in -proposed for a minimum of 7 days.

Changed in cups (Ubuntu Cosmic):
status: In Progress → Fix Committed
tags: added: verification-needed verification-needed-cosmic
Changed in cups (Ubuntu Bionic):
status: In Progress → Fix Committed
tags: added: verification-needed-bionic
Brian Murray (brian-murray) wrote :

Hello Trent, or anyone else affected,

Accepted cups into bionic-proposed. The package will build now and be available at https://launchpad.net/ubuntu/+source/cups/2.2.7-1ubuntu2.3 in a few hours, and then in the -proposed repository.

Please help us by testing this new package. See https://wiki.ubuntu.com/Testing/EnableProposed for documentation on how to enable and use -proposed. Your feedback will aid us getting this update out to other Ubuntu users.

If this package fixes the bug for you, please add a comment to this bug, mentioning the version of the package you tested and change the tag from verification-needed-bionic to verification-done-bionic. If it does not fix the bug for you, please add a comment stating that, and change the tag to verification-failed-bionic. In either case, without details of your testing we will not be able to proceed.

Further information regarding the verification process can be found at https://wiki.ubuntu.com/QATeam/PerformingSRUVerification . Thank you in advance for helping!

N.B. The updated package will be released to -updates after the bug(s) fixed by this package have been verified and the package has been in -proposed for a minimum of 7 days.

Changed in cups (Ubuntu Xenial):
status: In Progress → Fix Committed
tags: added: verification-needed-xenial
Brian Murray (brian-murray) wrote :

Hello Trent, or anyone else affected,

Accepted cups into xenial-proposed. The package will build now and be available at https://launchpad.net/ubuntu/+source/cups/2.1.3-4ubuntu0.7 in a few hours, and then in the -proposed repository.

Please help us by testing this new package. See https://wiki.ubuntu.com/Testing/EnableProposed for documentation on how to enable and use -proposed. Your feedback will aid us getting this update out to other Ubuntu users.

If this package fixes the bug for you, please add a comment to this bug, mentioning the version of the package you tested and change the tag from verification-needed-xenial to verification-done-xenial. If it does not fix the bug for you, please add a comment stating that, and change the tag to verification-failed-xenial. In either case, without details of your testing we will not be able to proceed.

Further information regarding the verification process can be found at https://wiki.ubuntu.com/QATeam/PerformingSRUVerification . Thank you in advance for helping!

N.B. The updated package will be released to -updates after the bug(s) fixed by this package have been verified and the package has been in -proposed for a minimum of 7 days.

Dariusz Gadomski (dgadomski) wrote :

I have just verified bionic with version 2.2.7-1ubuntu2.3.

My testing procedure:
1. Switch cups log level to info.
2. Restart cups.
3. Install printer-driver-cups-pdf to have a virtual printer.
4. Replace imagetopdf filter:
sudo mv /usr/lib/cups/filter/imagetopdf /usr/lib/cups/filter/imagetopdf.bkp
5. Install wrapper from comment #6 as replacement:
sudo install -m 755 ~/imagetopdf /usr/lib/cups/filter/imagetopdf
6. Print an image (so it gets picked by the filter wrapper):
lp -d PDF some_image.tiff

With 2.2.7-1ubuntu2.3 (Job 1):
$ grep -i cancel /var/log/cups/error_log
I [13/Dec/2018:08:49:02 +0100] [Job 1] Canceling stuck job after 0 seconds.

After upgrading to 2.2.7-1ubuntu2.3 (please look at Job 2)
$ grep -i -e cancel -e complete /var/log/cups/error_log
I [13/Dec/2018:08:49:02 +0100] [Job 1] Canceling stuck job after 0 seconds.
I [13/Dec/2018:08:50:09 +0100] Full reload complete.
I [13/Dec/2018:08:50:41 +0100] [Job 2] Job completed.

tags: added: verification-done-bionic
removed: verification-needed-bionic
Dariusz Gadomski (dgadomski) wrote :

Of course the above setup should include setting MaxJobTime to 0 in /etc/cups/cupsd.conf.

Dariusz Gadomski (dgadomski) wrote :

I have finished verification of cosmic.

With 2.2.8-5ubuntu1.1:
$ grep -i cancel /var/log/cups/error_log
I [13/Dec/2018:09:23:02 +0100] [Job 1] Canceling stuck job after 0 seconds.

After upgrading to 2.2.8-5ubuntu1.2:
$ grep -i -e cancel -e complete /var/log/cups/error_log
I [13/Dec/2018:09:25:00 +0100] Full reload complete.
I [13/Dec/2018:09:25:28 +0100] [Job 2] Job completed.

tags: added: verification-done-cosmic
removed: verification-needed-cosmic
Dariusz Gadomski (dgadomski) wrote :

Verification of xenial is positive as well:

2.1.3-4ubuntu0.6
$ grep -i cancel error_log
I [13/Dec/2018:09:28:50 +0100] [Job 1] Canceling stuck job after 0 seconds.

2.1.3-4ubuntu0.7
$ grep -i -e cancel -e completed error_log
I [13/Dec/2018:09:31:22 +0100] [Job 2] Job completed.

tags: added: verification-done verification-done-xenial
removed: verification-needed verification-needed-xenial
no longer affects: cups (Ubuntu Trusty)
Łukasz Zemczak (sil2100) wrote :

The SRUs have a few autopkgtest regressions reported against them in various series. The libreoffice ones seem generally flaky, not sure about openjdk-8 ones but what I'm worried about the epson-inkjet-printer-escpr ones. I re-ran the cosmic one against release and saw it passing, so I'd like someone to take a look and make sure there's no real regression here.

The epson-inkjet-printer-escpr seems to be some problem of the test script design that the test sometimes fails on slow processors due to being to time-consuming, because it works on most architectures and repeating it can make it pass. So I simply re-triggered it on Xenial i386 and Bionic i386 to see whether it passes now. Note that I did not look into the actual test script of this package. At least the output of the test script looks like some standard script also used by CUPS and other printer drivers. This script for sure does not set MaxJobTime=0 in CUPS and so results should not change by this fix.
I do not know about LibreOffice and OpenJDK tests.

Dan Streetman (ddstreet) wrote :

The libreoffice and openjdk tests appear to have been failing either consistently or intermittently for months or even over a year in some cases. It appears they should be ignored or marked flaky.

The epson-inkjet-printer-escpr failures have all passed now after my restarts.
There are still some libreoffice failures (1 arch on each Ubuntu release) which I have now re-triggered now. But do we really need libreoffice on s390x?
On Bionic on openjdk-8/8u191-b12-0ubuntu0.18.04.1 all architectures fail.Can this be a problem of openjdk and not of CUPS? Also the failures of openjdk-lts are all ignored, so should we also ignore openjdk-8?

Łukasz Zemczak (sil2100) wrote :

+1 on ignoring the remaining regressions. I'll try to hint them in whenever possible. Thanks!

Launchpad Janitor (janitor) wrote :

This bug was fixed in the package cups - 2.2.8-5ubuntu1.2

---------------
cups (2.2.8-5ubuntu1.2) cosmic; urgency=medium

  * fix-handling-of-MaxJobTime.patch: Fix handling of MaxJobTime 0
    (LP: #1804576)

 -- Dariusz Gadomski <email address hidden> Wed, 12 Dec 2018 08:27:17 +0100

Changed in cups (Ubuntu Cosmic):
status: Fix Committed → Fix Released

The verification of the Stable Release Update for cups has completed successfully and the package has now been released to -updates. Subsequently, the Ubuntu Stable Release Updates Team is being unsubscribed and will not receive messages about this bug report. In the event that you encounter a regression using the package from -updates please report a new bug using ubuntu-bug and tag the bug report regression-update so we can easily find any regressions.

Launchpad Janitor (janitor) wrote :

This bug was fixed in the package cups - 2.2.7-1ubuntu2.3

---------------
cups (2.2.7-1ubuntu2.3) bionic; urgency=medium

  * fix-handling-of-MaxJobTime.patch: Fix handling of MaxJobTime 0
    (LP: #1804576)

 -- Dariusz Gadomski <email address hidden> Wed, 12 Dec 2018 08:31:14 +0100

Changed in cups (Ubuntu Bionic):
status: Fix Committed → Fix Released
Launchpad Janitor (janitor) wrote :

This bug was fixed in the package cups - 2.1.3-4ubuntu0.7

---------------
cups (2.1.3-4ubuntu0.7) xenial; urgency=medium

  * fix-handling-of-MaxJobTime.patch: Fix handling of MaxJobTime 0
    (LP: #1804576)

 -- Dariusz Gadomski <email address hidden> Wed, 12 Dec 2018 08:34:26 +0100

Changed in cups (Ubuntu Xenial):
status: Fix Committed → Fix Released
Dan Streetman (ddstreet) on 2019-03-20
tags: removed: sts-sponsor sts-sponsor-ddstreet
To post a comment you must log in.
This report contains Public information  Edit
Everyone can see this information.

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.