You are not logged in.
I just realized that since 2019-11-02 my cups error logs have become huge. This is cups 2.3.0-4.
The culprit seems to be cupsdCleanJobs, as in the following line:
d [27/Nov/2019:11:01:16 -0500] cupsdCleanJobs: Job 471, state=9, printer=(nil), history_time=2147483647, file_time=1574542398
In this particular log file, 3063273 lines out of 3236574 contain "cupsdCleanJobs".
If I open the printing dialog in Thunderbird, tail tells me that the error log immediately starts printing lines similar to the above several times per second, between 27/Nov/2019:10:57:17 and 27/Nov/2019:11:01:16. It "cupsdCleanJobs" on jobs 55 to 472 repeatedly (in fact, more than 7K times in this log).
From localhost:631 I can see that no jobs are pending (I don't print often). However the jobs 55 to 472 correspond to the content of /var/cache/cups/job.cache. These jobs relate to two different printers plugged through an ethernet cable in my cable router.
Please note that printing works fine, I can print to both connected printers without any problem.
This might be related to the pacman update of cups and libcups on 2019-10-27: the job cache file does start on 2019-10-27 at 11:01 whereas the pacman -Syu update completed on 2019-10-27 at 10:54.
# Job cache file for CUPS v2.3.0
# Written by cupsd on 2019-11-27 11:01
NextJobId 473
<Job 55>
[...]This is a sample output between 2 series of cupsdCleanJobs messages:
d [27/Nov/2019:10:58:53 -0500] cupsdCleanJobs: Job 471, state=9, printer=(nil), history_time=2147483647, file_time=1574542398
d [27/Nov/2019:10:58:53 -0500] cupsdCleanJobs: JobHistoryUpdate=1479258757
d [27/Nov/2019:10:58:53 -0500] select_timeout: JobHistoryUpdate=1479258757
d [27/Nov/2019:10:58:53 -0500] [Client 1553] cupsdReadClient: error=0, used=0, state=HTTP_STATE_WAITING, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=0, request=(nil)(), file=-1
D [27/Nov/2019:10:58:53 -0500] [Client 1553] HTTP_STATE_WAITING Closing for error 32 (Broken pipe)
D [27/Nov/2019:10:58:53 -0500] [Client 1553] Closing connection.
D [27/Nov/2019:10:58:53 -0500] cupsdSetBusyState: newbusy="Not busy", busy="Not busy"
d [27/Nov/2019:10:58:53 -0500] cupsdRemoveSelect(fd=14)
d [27/Nov/2019:10:58:53 -0500] cupsdRemoveSelect(fd=-1)
d [27/Nov/2019:10:58:53 -0500] cupsdCleanJobs: MaxJobs=500, JobHistory=2147483647, JobFiles=86400
d [27/Nov/2019:10:58:53 -0500] cupsdCleanJobs: curtime=1574870333
d [27/Nov/2019:10:58:53 -0500] cupsdCleanJobs: Job 55, state=9, printer=(nil), history_time=2147483647, file_time=1479258757Note that the "broken pipe" error is not always present between series, this is another example:
d [27/Nov/2019:10:58:53 -0500] cupsdCleanJobs: Job 471, state=9, printer=(nil), history_time=2147483647, file_time=1574542398
d [27/Nov/2019:10:58:53 -0500] cupsdCleanJobs: JobHistoryUpdate=1479258757
d [27/Nov/2019:10:58:53 -0500] select_timeout: JobHistoryUpdate=1479258757
D [27/Nov/2019:10:58:53 -0500] [Client 1553] con->http=0x558761972bb0
D [27/Nov/2019:10:58:53 -0500] [Client 1553] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=1835, response=0x558761884020(IPP_STATE_DATA), pipe_pid=0, file=-1
D [27/Nov/2019:10:58:53 -0500] [Client 1553] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [27/Nov/2019:10:58:53 -0500] [Client 1553] bytes=0, http_state=0, data_remaining=1835
D [27/Nov/2019:10:58:53 -0500] [Client 1553] Flushing write buffer.
D [27/Nov/2019:10:58:53 -0500] [Client 1553] New state is HTTP_STATE_WAITING
d [27/Nov/2019:10:58:53 -0500] cupsdAddSelect(fd=14, read_cb=0x558761643140, write_cb=(nil), data=0x5587618ce790)
D [27/Nov/2019:10:58:53 -0500] [Client 1553] Waiting for request.
D [27/Nov/2019:10:58:53 -0500] cupsdSetBusyState: newbusy="Not busy", busy="Active clients"
d [27/Nov/2019:10:58:53 -0500] cupsdCleanJobs: MaxJobs=500, JobHistory=2147483647, JobFiles=86400
d [27/Nov/2019:10:58:53 -0500] cupsdCleanJobs: curtime=1574870333
d [27/Nov/2019:10:58:53 -0500] cupsdCleanJobs: Job 55, state=9, printer=(nil), history_time=2147483647, file_time=1479258757These are the messages after the last series:
d [27/Nov/2019:11:01:16 -0500] cupsdCleanJobs: Job 470, state=9, printer=(nil), history_time=2147483647, file_time=1574541877
d [27/Nov/2019:11:01:16 -0500] cupsdCleanJobs: Job 471, state=9, printer=(nil), history_time=2147483647, file_time=1574542398
d [27/Nov/2019:11:01:16 -0500] cupsdCleanJobs: Job 472, state=9, printer=(nil), history_time=2147483647, file_time=1574956845
d [27/Nov/2019:11:01:16 -0500] cupsdCleanJobs: JobHistoryUpdate=1479258757
d [27/Nov/2019:11:01:16 -0500] cupsdCheckJobs: 0 active jobs, sleeping=0, ac-power=-1, reload=0, curtime=1574870476
d [27/Nov/2019:11:01:16 -0500] select_timeout: JobHistoryUpdate=1479258757
d [27/Nov/2019:11:01:16 -0500] select_timeout(0): 662 seconds to timeout a client connectionI've found this bug report which might be related:
https://bugs.debian.org/cgi-bin/bugrepo … bug=826543
Any clues or suggestions?
Last edited by nfortier (2019-11-27 17:12:08)
Offline
Ok, I'm embarassed: the log problem is probably due to the fact I overlooked the appearance of /etc/cups/cupsd.conf.pacnew in the Oct 25 upgrade. The new version seems to modify logging:
# Disable cups internal logging - use logrotate instead
MaxLogSize 0
# Log general information in error_log - change "warn" to "debug"
# for troubleshooting...
LogLevel warnMore to the point, for some reason my old /etc/cups/cupsd.conf had debug2 as log level, which explains the large logs.
However, the processing of cached jobs thousands of times still does not seem normal. Anyone has a clue as to whether this is ok?
Offline