How to reverse-engineer a CUPS printer/print job?

Question

I have quality issue with PDF printing local (CUPS) vs. Google Cloud Printing. (GCP is better, with CUPS I get wrong size, wrong characters, wrong fonts. So I want to know what CUPS does!)

The printer can handle a couple of formats natively: application/pdf (≥ 1.0, ≤ 1.7), image/jpeg, image/tiff, image/pwg-raster

I have added the printer to CUPS in different ways over the months, I also used it „driverless”, where CUPS detects the printer in the local network itself.

In all cases it prints PDF with errors; not entirely, but rendering the print useless to me. What happens: page is zoomed in by ~30%, starting from page 2 or 3 the fonts get mixed up, characters turn into symbols, paragraphs printed in bold, etc...

The same PDFs turn out great if printed via Google Cloud Print on the same printer. Directly feeding the printer a USB-stick with the PDF is equally great. – I want to have the same good results with printing from my computer!

My questions are:

I want to know what pipeline each CUPS printer takes on my machine before it is sent to the real printer. Does it detect the format? How? Will it reconvert to PDF again? Which PPD will it use? What other decisions is the pipeline taking and what conversions?
From a passed print job I want to know: What did CUPS detect? What conversions did it do? Where can I fetch the intermediate outputs generated?

I found no good entry point for CUPS debugging/reverse-engineering so far (with my questions in mind)...

I have had scaling issues when printing PDFs (Debian 9.6) via evince and okular. However, using libreoffice and lpr worked fine. So, in my case, cups isn’t the culprit. It seems that evince and okular fail. — hermannk, Dec 07 '18 at 21:57

score 4 · Answer 1 · answered Dec 17 '18 at 23:58

I'm answering a part of your questions only, because you seem to employ a sharp mind who only needs to be shown some hidden hooks to climb up the wall:

"Which PPD will it use?"

If a printqueue printername is locally installed (and if it is not a 'raw' queue), it will use the PPD /etc/cups/ppd/printername.ppd.
"Does it detect the format? How?"

Yes, it does. When you have debug logging enabled (line LogLevel debug in /etc/cups/cupsd.conf), you will see a line in the error_log reading "Auto-typing file...". (There will be no auto-typing, if the job already states a mime type, like in lp -d printername -o document-format=application/pdf my.pdf.)

The rules for classifying various MIME types are defined in /usr/share/cups/mime.types and in all other files which may be in the same directory with the suffix *.types. (You could put your own rules there too, to define your own custom MIME types which should be processed by your own custom filters...)
"What other decisions is the pipeline taking and what conversions?"
1. If the PPD doesn't have any line starting with one of the *cupsFilter: or cupsFilter2: keywords, then it assumes the final print device to be a PostScript printer. Hence it converts everything to PostScript, which does not get submitted as PostScript.
2. If there is one or more lines starting with the keyword *cupsFilter: or *cupsFilter2: it will read from these lines which MIME type the print device can consume and it will employ an appropriate filter chain to generate the respective MIME type.
3. The filters which can process certain MIME types are listed in /usr/share/cups/mime.convs and in all other files which may be in the same directory with the suffix *.convs. (You could put your own custom filters there for any MIME type you want to be processed by these filters...)
4. The *.convs files name the input as well as the output MIME types the respective filter can consume and produce, and what virtual "cost" (just an integer number) such a conversion will cause. When faced with different possible filtering chains which CUPS could construct to go from application/alpha to application/zeta it picks the one with the lowest total cost.
"Will it reconvert to PDF again?"

Most likely no. Unless you asked for a print option to be used for the original PDF that requires it: to print only a range of pages; to print 2 or more pages on one sheet of paper; to scale it; to reshuffle pages for booklet printing, etc. Then a pdftopdf filter may be applied, that converts application/pdf to application/vnd.cups-pdf.
"What did CUPS detect?"

See above: search for the string "Auto-typing file" in /var/log/error_log:
```
sudo grep -A 2 "Auto-typing file" /var/log/error_log
```
"What conversions did it do?"

See in error_log again and search for lines containing Started filter:
```
sudo grep "Started filter" /var/log/error_log
```
"Where can I fetch the intermediate outputs generated?"

You cannot do this directly. You'd have to manipulate each and every filter of CUPS to write out the intermediary format. (I can do it, I have a ready-made recipe for this, but you'd have to pay me to apply it.)

So fetching intermediate outputs might be out-of-scope for you, you can do something different: simulate the filtering chain CUPS would employ for any job.

You can discover how to do this by reading the man page of cupsfilter. You can also just list the filters CUPS would employ for any of the print queues:
```
cupsfilter           \
    --list-filters    \
    -d <printername>   \
    -i <inputmime/type> \
    -m <outputmime/type> \
    -o "number-up=4 page-ranges=3-5,7,11" \
     <filename>
```

hermannk · Answer 2 · 2018-12-11T22:04:46.633

Your question does not specify the OS you are working with. My answer is for Debian 9.6 and for a network-connected Kyocera FS-1350DN which is specified to handle “PDF Direct print”. There should be no necessity for cups to tamper with PDF-files.

To find out, you have to enable cups-debugging. Unfortunately, cupsctl --debug-logging (as root) failed with the error message cupsctl: Forbidden. After setting LogLevel debug in the file /etc/cups/cupsd.conf and restarting cupsd, I sent a print job with lpr scale.pdf. The file contained line graphics from a CAD program (no grayscale) and printed with 100% scale.

The relevant lines (300 totally for the job) in /var/log/cups/error_log read:

⋮
D [11/Dec/2018:17:50:02 +0100] [Job 319] Request file type is application/pdf.
⋮
D [11/Dec/2018:17:50:02 +0100] [Job 319] 3 filters for job:
D [11/Dec/2018:17:50:02 +0100] [Job 319] pdftopdf (application/pdf to application/vnd.cups-pdf, cost 66)
D [11/Dec/2018:17:50:02 +0100] [Job 319] pdftops (application/vnd.cups-pdf to application/vnd.cups-postscript, cost 100)
D [11/Dec/2018:17:50:02 +0100] [Job 319] - (application/vnd.cups-postscript to printer/fs1350, cost 0)
⋮
I [11/Dec/2018:17:50:02 +0100] [Job 319] Started filter /usr/lib/cups/filter/pdftopdf (PID 16570)
I [11/Dec/2018:17:50:02 +0100] [Job 319] Started filter /usr/lib/cups/filter/pdftops (PID 16571)
I [11/Dec/2018:17:50:02 +0100] [Job 319] Started backend /usr/lib/cups/backend/socket (PID 16572)
⋮
D [11/Dec/2018:17:50:02 +0100] [Job 319] pdftops - copying to temp print file \"/tmp/040bb5c158ce7\"
⋮
D [11/Dec/2018:17:50:02 +0100] [Job 319] PID 16570 (/usr/lib/cups/filter/pdftopdf) exited with no errors.
⋮
D [11/Dec/2018:17:50:02 +0100] [Job 319] 319 h scale.pdf 1 \'finishings=3 job-uuid=urn:uuid:045216b6-e2e0-34ee-50af-36c3bdbdc04f job-originating-host-name=192.168.0.2 date-time-at-creation= date-time-at-processing= time-at-creation=1544547002 time-at-processing=1544547002 document-name-supplied=scale.pdf\'
⋮
D [11/Dec/2018:17:50:02 +0100] [Job 319] Running command line for gs: gs -q -dNOPAUSE -dBATCH -dSAFER -dNOMEDIAATTRS -sDEVICE=ps2write -sOUTPUTFILE=%stdout -dLanguageLevel=3 -r1200 -dCompressPages=false -dCompressFonts=false -dNoT3CCITT -dNOINTERPOLATE -c \'save pop\' -f /tmp/040bb5c158ce7
D [11/Dec/2018:17:50:02 +0100] [Job 319] Started filter gs (PID 16577)
D [11/Dec/2018:17:50:02 +0100] [Job 319] Started post-processing (PID 16578)
⋮
D [11/Dec/2018:17:50:02 +0100] [Job 319] Started filter pstops (PID 16579)
⋮
D [11/Dec/2018:17:50:02 +0100] [Job 319] %!PS-Adobe-3.0
D [11/Dec/2018:17:50:02 +0100] [Job 319] %%BoundingBox: 0 0 595 842
D [11/Dec/2018:17:50:02 +0100] [Job 319] %%HiResBoundingBox: 0 0 595.00 842.00
D [11/Dec/2018:17:50:02 +0100] [Job 319] %%Creator: GPL Ghostscript 920 (ps2write)
D [11/Dec/2018:17:50:02 +0100] [Job 319] %%LanguageLevel: 2
D [11/Dec/2018:17:50:02 +0100] [Job 319] %%CreationDate: D:20181211175002+01\'00\'
D [11/Dec/2018:17:50:02 +0100] [Job 319] %%Pages: 1
D [11/Dec/2018:17:50:02 +0100] [Job 319] %%EndComments
⋮
D [11/Dec/2018:17:50:02 +0100] [Job 319] PID 16577 (gs) exited with no errors.
⋮
D [11/Dec/2018:17:50:02 +0100] [Job 319] PID 16578 (Post-processing) exited with no errors.
⋮
D [11/Dec/2018:17:50:02 +0100] [Job 319] PID 16579 (pstops) exited with no errors.
⋮
D [11/Dec/2018:17:50:02 +0100] [Job 319] PID 16571 (/usr/lib/cups/filter/pdftops) exited with no errors.
⋮

The line containing - (application/vnd.cups-postscript to printer/fs1350, cost 0) tells you that cups is using the post-processor (aka printer driver) /etc/cups/ppd/fs1350.ppd. Another view of the same process can be obtained with the ps-command. An excerpt of the output of

while true ; do date +'%N'>> log; ps axSfu | fgrep -v grep | egrep '^lp[[:space:]]|/usr/sbin/cupsd' >> log ; done

which is

⋮
root     15796  0.1  0.1 171440  8536 ?        Ssl  17:49   0:00 /usr/sbin/cupsd -l
lp       16571  0.0  0.0  77632  5728 ?        S    17:50   0:00  \_ fs1350 319 h scale.pdf 1 finishings=3 number-up=1 job-uuid=urn:uuid:045216b6-e2e0-34ee-50af-36c3bdbdc04f job-originating-host-name=192.168.0.2 date-time-at-creation= date-time-at-processing= time-at-creation=1544547002 time-at-processing=1544547002 document-name-supplied=scale.pdf
lp       16577  0.0  0.2 129760 20836 ?        R    17:50   0:00  |   \_ gs -q -dNOPAUSE -dBATCH -dSAFER -dNOMEDIAATTRS -sDEVICE=ps2write -sOUTPUTFILE=%stdout -dLanguageLevel=3 -r1200 -dCompressPages=false -dCompressFonts=false -dNoT3CCITT -dNOINTERPOLATE -c save pop -f /tmp/040bb5c158ce7
lp       16578  0.0  0.0  77632   924 ?        S    17:50   0:00  |   \_ fs1350 319 h scale.pdf 1 finishings=3 number-up=1 job-uuid=urn:uuid:045216b6-e2e0-34ee-50af-36c3bdbdc04f job-originating-host-name=192.168.0.2 date-time-at-creation= date-time-at-processing= time-at-creation=1544547002 time-at-processing=1544547002 document-name-supplied=scale.pdf
lp       16579  0.0  0.0  75424  5288 ?        S    17:50   0:00  |   \_ fs1350 319 h scale.pdf 1 finishings=3 job-uuid=urn:uuid:045216b6-e2e0-34ee-50af-36c3bdbdc04f job-originating-host-name=192.168.0.2 date-time-at-creation= date-time-at-processing= time-at-creation=1544547002 time-at-processing=1544547002 document-name-supplied=scale.pdf
lp       16572  0.0  0.0  79792  5900 ?        S    17:50   0:00  \_ socket://fs1350.xxxx.xxxx.xxx 319 h scale.pdf 1 finishings=3 number-up=1 job-uuid=urn:uuid:045216b6-e2e0-34ee-50af-36c3bdbdc04f job-originating-host-name=192.168.0.2 date-time-at-creation= date-time-at-processing= time-at-creation=1544547002 time-at-processing=1544547002 document-name-supplied=scale.pdf
⋮

tells us that cups invokes the prefilter (pdftops, PID 16571, named fs1350 here) and the backend (PID 16572, named socket://fs1350.xxxx.xxxx.xxx here). The prefilter invokes gs. Because the whole processing takes less than 0.2 s it makes sense to collect the output into a file. The date +'%N' is only there to get an idea of the timing.

The unwanted scaling by evince (that I wrote about in my comment) was because evince→Print→Print Setup→Scale→100% was silently overwritten by evince→Print→Page Handling→Fit to Printable Area. So check your print clients with great care.

Alas, this is not the whole story. To bypass cups and use the “PDF Direct print” feature of the printer, I sent the file directly: nc fs1350.xxxx.xxxx.xxx 9100 < scale.pdf. After more than 10 minutes of processing time the printer shipped out the paper.

Raw print using netcat, the digits reflect the size in mm.

Printout using lpr→cups

Bitmap image of the file (1200 dpi)

Regardless of the printer setting “Override A4/LT” the scaling of the raw print is 97.7% whereas the scaling of the lpr→cups print is okay. There is a small dot gain for the raw print whereas the lpr→cups print comes a bit meager.

Shrinking the page size of the drawing before raw printing enlarged the scale.

score 0 · Answer 3 · answered Apr 02 '22 at 01:23

Let me chip in here... I'm running Gentoo Linux with CUPS 2.3.3op2, sending jobs to a Xerox VersaLink C405 via IPP Everywhere. That printer natively supports PostScript (genuine Adobe PostScript 3, not an emulation), as well as PDF, PCL6, PCL5e, and XPS.

From looking at debugging information in the log, CUPS is sending PostScript to the machine regardless of input format. This is what I'm seeing when I pipe PDF data to lp (dates stripped for readability):

[Job 61] 3 filters for job:
[Job 61] pdftopdf (application/pdf to application/vnd.cups-pdf, cost 66)
[Job 61] pdftops (application/vnd.cups-pdf to application/vnd.cups-postscript, cost 100)
[Job 61] - (application/vnd.cups-postscript to printer/vlc405, cost 0)

If you want to send a PDF directly to the printer, you can bypass CUPS altogether and use netcat to send the data directly to port 9100 on the printer (assuming that's enabled):

nc 192.0.2.0 9100 < file.pdf

(Replace the IP address with that of your printer.)

This won't apply if your machine doesn't directly support PostScript or PDF. Genuine Adobe PostScript 3 support is generally limited to high-end laser printers for office use. Consumer-grade printers will probably use PWG Raster, or possibly PDF, for IPP Everywhere. Some have emulated PostScript 3, which may be less reliable. (Emulations are often used because the Adobe reference implementation is expensive to license.)

How to reverse-engineer a CUPS printer/print job?

3 Answers3