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://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://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)