BenV's notes

Here we are today, trying to do a very simple thing. Print a stupid little PDF document so our customers can pay their bills.
Easy huh? Especially after the previous cups drama?

So we fire up xpdf on the document, hit the print icon, lpr, GO!
*time passes*
Mhm, what is it now?
*check http://localhost:631*
Nope, no document there, seems like it was handled by the printer.
*check cups error_log*
Heaps of garbage there.

Remember that we had this issue left in our previous cups story? Something about PDF printing causing issues?
Well, since then cups got upgraded to version 1.3.11 and some other stuff too, like ghostscript.
This time the error log showed something like this (only the relevant part here):

D [25/Aug/2009:14:19:49 +0200] [Job 652] backendRunLoop(print_fd=0, device_fd=5, use_bc=0, side_cb=0x804a23f)
D [25/Aug/2009:14:19:49 +0200] [Job 652] Wrote 1 pages...
D [25/Aug/2009:14:19:49 +0200] PID 26288 (/usr/lib/cups/filter/pstops) exited with no errors.
D [25/Aug/2009:14:19:50 +0200] [Job 652] Error: error occurred at print phase !!
E [25/Aug/2009:14:19:50 +0200] [Job 652] No pages found!
D [25/Aug/2009:14:19:50 +0200] Discarding unused printer-state-changed event...
D [25/Aug/2009:14:19:50 +0200] Discarding unused job-progress event...
D [25/Aug/2009:14:19:50 +0200] [Job 652] GPL Ghostscript 8.70: Unrecoverable error, exit code 1
D [25/Aug/2009:14:19:50 +0200] [Job 652] cat: write error: Broken pipe
D [25/Aug/2009:14:19:50 +0200] PID 26289 (/usr/lib/cups/filter/brlpdwrapperdcp135c) exited with no errors.
D [25/Aug/2009:14:19:50 +0200] PID 26299 (/usr/lib/cups/backend/usb) exited with no errors.
D [25/Aug/2009:14:19:50 +0200] [Job 652] File 0 is complete.
I [25/Aug/2009:14:19:50 +0200] [Job 652] Completed successfully.


Some weird definition of ‘successfully’ you have there, cups.
After a few hours of debugging through that error_log, fucking with filters in /usr/share/cups/filters (cursing at Brother for their half baked wrapper scripts), turning on and off debug and log options
I was getting more and more annoyed with it. Considering on how to pick up the Brother DCP-135C and smashing it through the 2nd story window onto the pavement, but then not being
sure if it really was the brother’s fault at all, I decided to make sure once and for all which one I had to throw through the window.

Time for a manual debug session with the filters again. If you are having trouble with stuff like this, I can commend it to you. The steps I took (after the usual turning on debug and log options etc):

1. Grab your input file, in my case some PDF document which I ran through xpdf.
2. Instead of sending it to the printer, print using the “save to file” option so we have the source that cups has to deal with to work with.
3. Manually run this file through the filters as cups does. I curse on cups for not being more specific — EVEN WITH THE LogLevel debug2 OPTION TURNED ON (it just becomes MORE unreadable, but without more information) — about how it runs these filters, but there are some shell scripts floating around that you can use. What I did was just use strace -qfve execve -p `pidof cupsd` -s 250 to figure out how my filters were called, but be ready to read tons of output on that one 😉
   Anyhow, to save you some trouble, the call syntax seems to be filterprogram PRINTER JobNum User title copies documentoptions [file] or a real example from my test case: /usr/lib/cups/filter/pstops "DCP135C" 666 benv jemoeder 1 "document-name=4a93e8d852a17 number-up=1 job-uuid=urn:uuid:873e2907-cf50-35e2-5626-741377b394be" "/var/spool/cups/d00666-001"
4. Find out which part fails. The pstops had some output that looked fine by me, as far as I can read postscript as it scrolls through my terminal.

Funny thing is…. it seemed to me like pstops worked fine, as did the brother cups wrapper….
However, there was still this soab left:

D [25/Aug/2009:15:48:21 +0200] [Job 667] GPL Ghostscript 8.70: Unrecoverable error, exit code 1

Execution of /usr/bin/gs showed up in strace as well btw, don’t worry 😉
So now the big question was: when did ghostscript become retarded?

I took my “print to file” postscript document, and tried opening it in ghostview.
It just looked at me like a cow looks at an oncoming train. Or in its own words:

Error: /undefined in ilQ2-amMq3gmMqGPL Ghostscript 8.70: Unrecoverable error, exit code 1

Execution stack:
%interp_exit .runexec2 --nostringval-- --nostringval-- --nostringval-- 2 %stopped_push --nostringval-- --nostringval-- --nostringval-- false 1 %stopped_push 1862 1 3 %oparray_pop 1861 1 3 %oparray_pop 1845 1 3 %oparray_pop 1739 1 3 %oparray_pop --nostringval-- %errorexec_pop .runexec2 --nostringval-- --nostringval-- --nostringval-- 2 %stopped_push --nostringval--
Dictionary stack:
--dict:1150/1684(ro)(G)-- --dict:0/20(G)-- --dict:71/200(L)-- --dict:65/75(L)-- --dict:18/25(L)--
Current allocation mode is local
Last OS error: 11


Ah-HA!

….

What?

Since I’m by no means an expert on postscript, I googled it. The search revealed that apparently this could be the result of an eps image conversion gone bad.
Postscript doesn’t like to deal with binary data, so it’s not supposed to be there.
This can mean only one thing!
xpdf failed!!!!!!

Some testing revealed that xpdf on the old slackware32 chroot environment still does work, and printing the exact same PDF file there works fine, while printing that document from the 64 bit
slackware envrionment fails with the above story. Fascinating. Seems like it isn’t a library issue though, unless it’s cleverly hidden in the X libraries. I hope they’ll fix this soon 🙂
Just for reference, this is the xpdf-3.02pl3-x86_64-1 package that fails.

Well, now that we all know the details we can go to bed.
And if you need to print that pdf document: simply use pdf2ps, it works. (and stay away from habbokrat reader)