CUPS: adding support for system journal

I’ve added a patch to CUPS in Fedora rawhide which uses the system journal for logging. I did this after watching Lennart’s devconf talk, which reminded me how awesome the systemd Journal is.

The changes are very simple at the moment: any log message relating to a particular job has a field “CUPS_JOB_ID” to say which one. Additionally, page log messages include the page number as “CUPS_PAGE_NUMBER”. This support is in rawhide, starting with cups-1.7.0-1.fc21.

To enable it, adjust /etc/cups/cups-files.conf and set “ErrorLog journal”. You can also set AccessLog and PageLog to “journal”.

Now you’ll be able to fetch the logs relating to a particular job by specifying the job ID, like this:

$ journalctl CUPS_JOB_ID=13

Not sure which job ID you want? You can use tab-completion to help, if you’ll recognise it when you see it. Just press <TAB> twice:

$ journalctl CUPS_JOB_ID=
10  11  12  13  14  15  16  2   3   4   6   7   8   9

Let’s look at job 13:

$ journalctl CUPS_JOB_ID=13 | fold
-- Logs begin at Tue 2013-10-08 14:21:33 BST, end at Fri 2013-10-25 15:31:49 BST
. --
Oct 24 16:53:20 rubik cupsd[13682]: DESKJET-990C twaugh 13 [24/Oct/2013:16:53:20
 +0100] 1 1 - localhost portrait-a4.pdf - -

This job completed normally, so with the default logging level (Info) there is nothing much to say except for the page log, wrapped to fit for this blog entry.

Jobs that fail get more log messages because the last few filter/backend messages are stored in the job history, and this history is replayed to the log on failure. Here’s an example of that, trimmed for brevity and again wrapped to fit:

$ journalctl CUPS_JOB_ID=16 | fold
-- Logs begin at Tue 2013-10-08 14:21:33 BST, end at Fri 2013-10-25 15:31:49 BST
. --
Oct 25 15:31:17 rubik cupsd[13682]: HP-Photosmart-5510-series twaugh 16 [25/Oct/
2013:15:31:17 +0100] 1 1 - localhost (stdin) - -
Oct 25 15:31:24 rubik cupsd[13682]: [Job 16] Job stopped due to filter errors; p
lease consult the error_log file for details.
Oct 25 15:31:24 rubik cupsd[13682]: [Job 16] The following messages were recorde
d from 15:31:17 to 15:31:24
Oct 25 15:31:24 rubik cupsd[13682]: [Job 16] Adding start banner page "none".
Oct 25 15:31:24 rubik cupsd[13682]: [Job 16] Queued on "HP-Photosmart-5510-serie
s" by "twaugh".
Oct 25 15:31:24 rubik cupsd[13682]: [Job 16] File of type application/postscript
 queued by "twaugh".
Oct 25 15:31:24 rubik cupsd[13682]: [Job 16] Adding end banner page "none".
Oct 25 15:31:24 rubik cupsd[13682]: [Job 16] time-at-processing=1382711477
Oct 25 15:31:24 rubik cupsd[13682]: [Job 16] 4 filters for job:
Oct 25 15:31:24 rubik cupsd[13682]: [Job 16] pstopdf (application/postscript to 
application/pdf, cost 0)
Oct 25 15:31:24 rubik cupsd[13682]: [Job 16] pdftopdf (application/pdf to applic
ation/vnd.cups-pdf, cost 66)
Oct 25 15:31:24 rubik cupsd[13682]: [Job 16] gstoraster (application/vnd.cups-pd
f to application/vnd.cups-raster, cost 99)
Oct 25 15:31:24 rubik cupsd[13682]: [Job 16] hpcups (application/vnd.cups-raster
 to printer/HP-Photosmart-5510-series, cost 0)
[...]
Oct 25 15:31:25 rubik cupsd[13682]: [Job 16] GPL Ghostscript 9.10: Unrecoverable
 error, exit code 1
Oct 25 15:31:25 rubik cupsd[13682]: [Job 16] PID 3423 (/usr/lib/cups/filter/psto
pdf) stopped with status 1.
Oct 25 15:31:25 rubik cupsd[13682]: [Job 16] Hint: Try setting the LogLevel to "
debug" to find out more.
[...]
Oct 25 15:31:25 rubik cupsd[13682]: [Job 16] End of messages
Oct 25 15:31:25 rubik cupsd[13682]: [Job 16] printer-state=3(idle)
Oct 25 15:31:25 rubik cupsd[13682]: [Job 16] printer-state-message="Waiting for 
printer to finish."
Oct 25 15:31:25 rubik cupsd[13682]: [Job 16] printer-state-reasons=none