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

[Trent Lloyd]

[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)]

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.

[Dariusz Gadomski (dgadomski)]

SRU proposal for disco.

[Dariusz Gadomski (dgadomski)]

SRU proposal for Cosmic.

[Dariusz Gadomski (dgadomski)]

SRU proposal for bionic.

[Dariusz Gadomski (dgadomski)]

SRU proposal for xenial.

[Dariusz Gadomski (dgadomski)]

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()

[Dariusz Gadomski (dgadomski)]

SRU proposal for disco (fixed)

[Till Kamppeter (till-kamppeter)]

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

[Dan Streetman (ddstreet)]

> 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 Bícha (jbicha)]

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.

[Launchpad Janitor (janitor)]

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

[Brian Murray (brian-murray)]

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)]

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)]

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)]

Updated debdiff for cosmic.

[Dariusz Gadomski (dgadomski)]

Updated debdiff for bionic.

[Dariusz Gadomski (dgadomski)]

Updated debdiff for xenial.

[Till Kamppeter (till-kamppeter)]

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

[Brian Murray (brian-murray)]

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.

[Brian Murray (brian-murray)]

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.

[Brian Murray (brian-murray)]

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)]

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.

[Dariusz Gadomski (dgadomski)]

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

[Dariusz Gadomski (dgadomski)]

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.

[Dariusz Gadomski (dgadomski)]

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.

[Łukasz Zemczak (sil2100)]

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.

[Till Kamppeter (till-kamppeter)]

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)]

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.

[Till Kamppeter (till-kamppeter)]

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)]

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

[Launchpad Janitor (janitor)]

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

[Łukasz Zemczak (sil2100)]

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)]

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

[Launchpad Janitor (janitor)]

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