CUPS is too chatty about "Removing document files." in debug mode

[akorobkin]

CUPS 2.2.11 on Linux reports "Removing document files" for every job many times per second for every job for many days since the job was printed. It seems to correlate with the period of time that control file is still sitting in /var/spool/cups. The data file is no longer there because PreserveJobFiles is set to Off.

$ grep -c "Removing document files" /var/log/cups/error_log
2278857

/var/log/cups/error_log.O:D [14/Jun/2019:12:05:35 +0000] [Job 7019] Removing document files.
/var/log/cups/error_log.O:D [14/Jun/2019:12:05:35 +0000] [Job 7019] Removing document files.
/var/log/cups/error_log.O:D [14/Jun/2019:12:05:35 +0000] [Job 7019] Removing document files.
/var/log/cups/error_log.O:D [14/Jun/2019:12:05:35 +0000] [Job 7019] Removing document files.
/var/log/cups/error_log.O:D [14/Jun/2019:12:05:36 +0000] [Job 7019] Removing document files.
/var/log/cups/error_log.O:D [14/Jun/2019:12:05:39 +0000] [Job 7019] Removing document files.
/var/log/cups/error_log.O:D [14/Jun/2019:12:05:39 +0000] [Job 7019] Removing document files.
/var/log/cups/error_log.O:D [14/Jun/2019:12:05:39 +0000] [Job 7019] Removing document files.
/var/log/cups/error_log.O:D [14/Jun/2019:12:05:39 +0000] [Job 7019] Removing document files.
/var/log/cups/error_log.O:D [14/Jun/2019:12:05:39 +0000] [Job 7019] Removing document files.
/var/log/cups/error_log.O:D [14/Jun/2019:12:05:40 +0000] [Job 7019] Removing document files.
/var/log/cups/error_log.O:D [14/Jun/2019:12:05:43 +0000] [Job 7019] Removing document files.
/var/log/cups/error_log.O:D [14/Jun/2019:12:05:43 +0000] [Job 7019] Removing document files.
/var/log/cups/error_log.O:D [14/Jun/2019:12:05:44 +0000] [Job 7019] Removing document files.
/var/log/cups/error_log.O:D [14/Jun/2019:12:05:44 +0000] [Job 7019] Removing document files.
/var/log/cups/error_log.O:D [14/Jun/2019:12:05:45 +0000] [Job 7019] Removing document files.
/var/log/cups/error_log.O:D [14/Jun/2019:12:05:45 +0000] [Job 7019] Removing document files.
/var/log/cups/error_log.O:D [14/Jun/2019:12:05:45 +0000] [Job 7019] Removing document files.
/var/log/cups/error_log.O:D [14/Jun/2019:12:05:45 +0000] [Job 7019] Removing document files.
/var/log/cups/error_log.O:D [14/Jun/2019:12:05:45 +0000] [Job 7019] Removing document files.
/var/log/cups/error_log.O:D [14/Jun/2019:12:05:45 +0000] [Job 7019] Removing document files.
/var/log/cups/error_log.O:D [14/Jun/2019:12:05:45 +0000] [Job 7019] Removing document files.
/var/log/cups/error_log.O:D [14/Jun/2019:12:05:46 +0000] [Job 7019] Removing document files.
/var/log/cups/error_log.O:D [14/Jun/2019:12:05:46 +0000] [Job 7019] Removing document files.
/var/log/cups/error_log.O:D [14/Jun/2019:12:05:47 +0000] [Job 7019] Removing document files.
/var/log/cups/error_log.O:D [14/Jun/2019:12:05:47 +0000] [Job 7019] Removing document files.
/var/log/cups/error_log.O:D [14/Jun/2019:12:05:47 +0000] [Job 7019] Removing document files.
/var/log/cups/error_log.O:D [14/Jun/2019:12:05:47 +0000] [Job 7019] Removing document files.
/var/log/cups/error_log.O:D [14/Jun/2019:12:05:47 +0000] [Job 7019] Removing document files.
/var/log/cups/error_log.O:D [14/Jun/2019:12:05:47 +0000] [Job 7019] Removing document files.
/var/log/cups/error_log.O:D [14/Jun/2019:12:05:48 +0000] [Job 7019] Removing document files.
/var/log/cups/error_log.O:D [14/Jun/2019:12:05:49 +0000] [Job 7019] Removing document files.
/var/log/cups/error_log.O:D [14/Jun/2019:12:05:49 +0000] [Job 7019] Removing document files.
/var/log/cups/error_log.O:D [14/Jun/2019:12:05:49 +0000] [Job 7019] Removing document files.
/var/log/cups/error_log.O:D [14/Jun/2019:12:05:49 +0000] [Job 7019] Removing document files.
/var/log/cups/error_log.O:D [14/Jun/2019:12:05:49 +0000] [Job 7019] Removing document files.
/var/log/cups/error_log.O:D [14/Jun/2019:12:05:50 +0000] [Job 7019] Removing document files.
/var/log/cups/error_log.O:D [14/Jun/2019:12:05:50 +0000] [Job 7019] Removing document files.
/var/log/cups/error_log.O:D [14/Jun/2019:12:05:51 +0000] [Job 7019] Removing document files.
/var/log/cups/error_log.O:D [14/Jun/2019:12:05:53 +0000] [Job 7019] Removing document files.
/var/log/cups/error_log.O:D [14/Jun/2019:12:05:53 +0000] [Job 7019] Removing document files.
/var/log/cups/error_log.O:D [14/Jun/2019:12:05:54 +0000] [Job 7019] Removing document files.
/var/log/cups/error_log.O:D [14/Jun/2019:12:05:54 +0000] [Job 7019] Removing document files.
/var/log/cups/error_log.O:D [14/Jun/2019:12:05:55 +0000] [Job 7019] Removing document files.
/var/log/cups/error_log.O:D [14/Jun/2019:12:05:55 +0000] [Job 7019] Removing document files.
/var/log/cups/error_log.O:D [14/Jun/2019:12:05:55 +0000] [Job 7019] Removing document files.
/var/log/cups/error_log.O:D [14/Jun/2019:12:05:55 +0000] [Job 7019] Removing document files.
/var/log/cups/error_log.O:D [14/Jun/2019:12:05:55 +0000] [Job 7019] Removing document files.
/var/log/cups/error_log.O:D [14/Jun/2019:12:05:55 +0000] [Job 7019] Removing document files.
/var/log/cups/error_log.O:D [14/Jun/2019:12:05:56 +0000] [Job 7019] Removing document files.
/var/log/cups/error_log.O:D [14/Jun/2019:12:05:56 +0000] [Job 7019] Removing document files.
/var/log/cups/error_log.O:D [14/Jun/2019:12:05:56 +0000] [Job 7019] Removing document files.
/var/log/cups/error_log.O:D [14/Jun/2019:12:05:57 +0000] [Job 7019] Removing document files.
/var/log/cups/error_log.O:D [14/Jun/2019:12:05:57 +0000] [Job 7019] Removing document files.
/var/log/cups/error_log.O:D [14/Jun/2019:12:05:58 +0000] [Job 7019] Removing document files.
/var/log/cups/error_log.O:D [14/Jun/2019:12:05:58 +0000] [Job 7019] Removing document files.
/var/log/cups/error_log.O:D [14/Jun/2019:12:05:58 +0000] [Job 7019] Removing document files.
/var/log/cups/error_log.O:D [14/Jun/2019:12:05:58 +0000] [Job 7019] Removing document files.
/var/log/cups/error_log.O:D [14/Jun/2019:12:05:58 +0000] [Job 7019] Removing document files.
/var/log/cups/error_log.O:D [14/Jun/2019:12:05:58 +0000] [Job 7019] Removing document files.
/var/log/cups/error_log.O:D [14/Jun/2019:12:05:58 +0000] [Job 7019] Removing document files.
/var/log/cups/error_log.O:D [14/Jun/2019:12:05:58 +0000] [Job 7019] Removing document files.
/var/log/cups/error_log.O:D [14/Jun/2019:12:05:59 +0000] [Job 7019] Removing document files.
/var/log/cups/error_log.O:D [14/Jun/2019:12:05:59 +0000] [Job 7019] Removing document files.
/var/log/cups/error_log.O:D [14/Jun/2019:12:05:59 +0000] [Job 7019] Removing document files.
/var/log/cups/error_log.O:D [14/Jun/2019:12:05:59 +0000] [Job 7019] Removing document files.
/var/log/cups/error_log.O:D [14/Jun/2019:12:05:59 +0000] [Job 7019] Removing document files.
/var/log/cups/error_log.O:D [14/Jun/2019:12:05:59 +0000] [Job 7019] Removing document files.
/var/log/cups/error_log.O:D [14/Jun/2019:12:05:59 +0000] [Job 7019] Removing document files.
/var/log/cups/error_log.O:D [14/Jun/2019:12:05:59 +0000] [Job 7019] Removing document files.
/var/log/cups/error_log.O:D [14/Jun/2019:12:05:59 +0000] [Job 7019] Removing document files.
/var/log/cups/error_log.O:D [14/Jun/2019:12:05:59 +0000] [Job 7019] Removing document files.
/var/log/cups/error_log.O:D [14/Jun/2019:12:05:59 +0000] [Job 7019] Removing document files.
/var/log/cups/error_log.O:D [14/Jun/2019:12:05:59 +0000] [Job 7019] Removing document files.
/var/log/cups/error_log.O:D [14/Jun/2019:12:05:59 +0000] [Job 7019] Removing document files.
/var/log/cups/error_log.O:D [14/Jun/2019:12:05:59 +0000] [Job 7019] Removing document files.
/var/log/cups/error_log.O:D [14/Jun/2019:12:06:00 +0000] [Job 7019] Removing document files.

[michaelrsweet]

@akorobkin Hmm, not sure what is going on there, but will investigate. Is this with stock CUPS or with patches?

[akorobkin]

This is with standard patches from a Debian installation, https://packages.debian.org/sid/cups

[michaelrsweet]

OK, I don't see how this would happen (remove_job_files clears job->file_time, so it should not be called again), so I've updated the code to also look at the "num_files" member.

[master 6647894] Fix potential excess logging from the scheduler when removing job files (Issue #5597)

(not bothering to backport this to 2.2.x, but the fix is trivial and you can feel free to do so under the old CUPS license...)

[akorobkin]

Worked like a charm:

$ zgrep -c "Removing document files" /var/log/cups/error_log* 
/var/log/cups/error_log:0
/var/log/cups/error_log.1.gz:0
/var/log/cups/error_log.2.gz:0
/var/log/cups/error_log.3.gz:9
/var/log/cups/error_log.4.gz:39141
/var/log/cups/error_log.5.gz:2955997
/var/log/cups/error_log.6.gz:234134
/var/log/cups/error_log.7.gz:640167
/var/log/cups/error_log.8.gz:1236456
/var/log/cups/error_log.9.gz:2870020
/var/log/cups/error_log.10.gz:2282992

[chri50]

Hi, just to notice - same behaviour on SLES12.
As far as i have investigated, the job->file_time will be set again from cupsdLoadJob with timestamp of job completed if for e.g. Cups Website is reloaded.

cupsd:2.2.13 ( mentioned bugfix not backported )

MaxJobs 0
MaxJobTime 0
MaxHoldTime 60
PreserveJobFiles No
PreserveJobHistory 60

d [29/Nov/2019:11:13:27.884235 +0100] cupsdCleanJobs: Job 121, state=7, printer=0x562bc5bf0f10, history_time=1575022467, file_time=0
d [29/Nov/2019:11:13:58.628391 +0100] [Job 121] cupsdLoadJob: job->file_time=1575022407, time-at-completed=1575022407, JobFiles=0
d [29/Nov/2019:11:13:58.628737 +0100] cupsdCleanJobs: Job 121, state=7, printer=(nil), history_time=1575022467, file_time=1575022407