CUPS error log should include timeout's in default state.

[fhcarter]

It should be easier to diagnose time outs from spooling application to CUPS.

Ran Adobe Lightroom to produce a large print. Due to machine's age, etc., job took a long time (5.5 minutes). CUPS Timeout setting at default is 300 seconds. CUPS error log says

E [17/Apr/2019:21:50:17 -0700] [Job 3] Aborting job because it has no files.
E [17/Apr/2019:21:50:40 -0700] [Client 44] Returning IPP client-error-not-possible for Set-Job-Attributes (ipp:https://localhost/jobs/3) from localhost.
E [17/Apr/2019:21:57:10 -0700] [Job 4] Aborting job because it has no files.
E [17/Apr/2019:21:57:41 -0700] [Client 59] Returning IPP client-error-not-possible for Set-Job-Attributes (ipp:https://localhost/jobs/4) from localhost.

which gives no hint that there was a timeout.

Doing this on MacOS, I could use cupsctl to set Loglevel to debug, and then I saw the timeout. Changed Timeout to better value & things work as expected. As a user, I shouldn't have to go that deep to diagnose things. Log level for timeout message should be changed.

[jsmeix]

I think the basic root cause in this issue here is same as in
#5559

In both cases by default CUPS does not provide sufficient information
to the user that something "unusual" happened or is still going on.

[michaelrsweet]

@jsmeix This issue is different - the application submitting the print job is taking too long to prepare the PDF file for submission, and the timeout isn't getting logged.

[michaelrsweet]

[master d6395c6] Increase the MultipleOperationTimeOut default to 15 minutes, log an error if the job submission times out (Issue #5570)

[branch-2.2 c1b1337] Increase the MultipleOperationTimeOut default to 15 minutes, log an error if the job submission times out (Issue #5570)

[fhcarter]

For what it's worth, the case in question was NOT a multiple file job, I don't believe. It was a single page (ergo single PDF) that had 25 little images on it (as in a photographer's contact sheet). That's why it took so long to produce.

The "fix" (from my side) was to increase the Timeout parameter, not the MultipleOperationTimeOut parameter. You all probably understand more than I about CUPS (I hope so), but I just want to ensure that the right thing is happening.

[michaelrsweet]

@fhcarter There are two timeouts at play here - one between the Create-Job and Send-Document requests, and one during the Send-Document request. I'll double-check that the timeout has been increased for both, but the intent is to log an error whenever a timeout occurs...

[fhcarter]

@michaelrsweet Thanks. Just wanted to make the situation clear. The code changes looked like it changed only MultipleOperationTimeOut. It specifically didn't change DEFAULT_TIMEOUT, instead changing the initializer from DEFAULT_TIMEOUT to 900.

[michaelrsweet]

@fhcarter Right, DEFAULT_TIMEOUT is used in a bunch of places for the normal networking timeout value, but in this case MultipleOperationTimeOut is king because it applies to the submission process (how long it takes the document(s) for the job to be submitted) and not to how long cupsd waits for a client to send something over the network.

After reviewing the code in scheduler/job.c, it looks like I needed to move things around a bit for the logging to only happen for a timed out job (vs. the hold on the job expiring normally).

[michaelrsweet]

[master 6dac113] Update the hold expiration logging - one case is an error, the other is normal.

[branch-2.2 a2eba04] Update the hold expiration logging - one case is an error, the other is normal (Issue #5570)

[fhcarter]

@michaelrsweet OK, thanks. At home tonight, I'll try updating my CUPS config, changing MultipleOperationTimeOut instead of Timeout (setting Timeout back to its default) and see if that (also) solves the issue. It's easy enough to test -- just not from here at work.

[fhcarter]

@michaelrsweet I tried making the changes you appeared to make via cupsctl -- specifically setting Timeout back to 300 and setting MultipleOperationTimeout to 900. This put me back to the job being canceled due to no files:

[01/May/2019:20:25:56 -0700] Scheduler shutting down due to program error.
E [01/May/2019:20:31:16 -0700] [Job 18] Aborting job because it has no files.
E [01/May/2019:20:32:40 -0700] [Client 16] Returning IPP client-error-not-possible for Set-Job-Attributes (ipp:https://localhost/jobs/18) from localhost.
E [01/May/2019:20:33:05 -0700] Scheduler shutting down due to program error.
E [01/May/2019:20:40:20 -0700] [Job 19] Aborting job because it has no files.
E [01/May/2019:20:40:51 -0700] Scheduler shutting down due to program error.
E [01/May/2019:20:47:35 -0700] [Job 20] Aborting job because it has no files.
E [01/May/2019:20:48:18 -0700] Scheduler shutting down due to program error.

(I tried 3 times.) However, setting Timeout to 900 (and returning MultiOperationTimeout back to its default) works fine.

Mojave 10.14.4, CUPS 2.2.9

Attached copy of error log from running in this configuration

cupsd.conf:

_debug_logging=1
_remote_admin=0
_remote_any=0
_share_printers=0
_user_cancel_any=0
BrowseLocalProtocols=dnssd
DefaultAuthType=Basic
JobPrivateAccess=default
JobPrivateValues=default
MultipleOperationTimeOut=900
PageLogFormat=
SubscriptionPrivateAccess=default
SubscriptionPrivateValues=default
Timeout=300
WebInterface=true

cups.log

Hopefully, this helps with diagnostics

[michaelrsweet]

The simplest change here is to just bump the default Timeout value to 900 seconds; the new logging code will still let you know why the timeout occurred for the job, and the increased timeout value will hopefully make these issues non-existent.

I looked at tying the in-process IPP request to MultipleOperationTimeout and all other HTTP requests to Timeout, but that seemed too likely to be abused...

[master f49af67] Bump the default Timeout to 15 minutes as well (Issue #5570)

[branch-2.2 9d6f1bb] Bump the default Timeout to 15 minutes as well (Issue #5570)

[jsmeix]

@fhcarter
for the fun of it a side note reagding your
#5570 (comment)

a single page ... that had 25 little images on it

I guess each of that little images was perhaps several megabytes big
(e.g. just what one gets from a modern smartphone camera ;-)

[fhcarter]

@jsmeix -- Indeed. Approximately half were iPhone 7's, the other half either Sony NEX-7 (24MP) or Sony a7r iii (40+MP) :-). It takes a while.

@michaelrsweet Thanks -- that seems like a reasonable fix. With the error message, it will be (more) possible to find the cause and deal with it.