Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

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

Closed
akorobkin opened this issue Jun 14, 2019 · 5 comments
Closed

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

akorobkin opened this issue Jun 14, 2019 · 5 comments
Assignees
@michaelrsweet
Labels
investigating Investigating the issue priority-low
Milestone
CUPS 2.3.x

Comments

@akorobkin
Copy link

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
Copy link
Collaborator

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

@michaelrsweet michaelrsweet self-assigned this Jun 14, 2019
@michaelrsweet michaelrsweet added the investigating Investigating the issue label Jun 14, 2019
@akorobkin
Copy link
Author

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

@michaelrsweet michaelrsweet added this to the CUPS 2.3.x milestone Jul 16, 2019
michaelrsweet added a commit that referenced this issue Jul 16, 2019
@michaelrsweet
Fix potential excess logging from the scheduler when removing job files
6647894 
(Issue #5597)

(may be Debian-specific, as I was unable to duplicate - the extra check is in
place in case file_time is reset)
@michaelrsweet
Copy link
Collaborator

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
Copy link
Author

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
Copy link

chri50 commented Nov 29, 2019

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

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@michaelrsweet michaelrsweet

Labels
investigating Investigating the issue priority-low
Projects
None yet
Milestone
CUPS 2.3.x
Development

No branches or pull requests
3 participants
@michaelrsweet @akorobkin @chri50