Saturday, October 13, 2007

The Case of the First Page Only Printer

Chapter 1: I'm hit

In the past week or so I've been hit with a strange printing problem: my hp officejet 5510 all-in-one only prints the first page of multi-page print jobs. There are no error indications, it just stops after the first page.

It all started when I tried printing a PDF document from within Acrobat Reader. My initial guess was that there was something wrong with the document (I downloaded it from some website, so it seemed plausible).

Chapter 2: I Test therefore I Am

I tried printing another document, that I've printed before, and I got the same result - just the first page.

I tried printing to a virtual PDF printer, and this time I got all pages printed.

I tried printing to file from Acrobat Reader (with the officejet as the target printer) - the PostScript file looked just fine - all pages were there. Weird.

I tried printing the PostScript file at the console with lpr - and was a bit surprised when I got the first page only.

At this point I was pissed. But also worried - I rarely use the printer, but my wife prints a lot, as part of her work. She prints from her Windows laptop, and I had to make sure that it still worked. So I copied the PDF file to her machine and tried printing it from Acrobat Reader. It printed OK - all pages came out.

Eeek!

I can print from a remote Windows machine but not directly from my own Debian box? this was an insult!

Chapter 3: From Insult to Workaround

The officejet is accessed from my wife's PC via IPP (Internet Printing Protocol) - so I came up with an idea: I'll setup an IPP printer in CUPS, that prints to the URL of the direct printer. This can be easily accomplished from the CUPS web interface at http://localhost:631:
  1. select the "Printers" tab
  2. copy the link to the directly connected printer
  3. select the "Administration" tab
  4. click "Add Printer"
  5. fill in the printer's name, location and description, press "Continue"
  6. select the device "Internet Printing Protocol (http)"
  7. paste the link copied at step 2, press "Continue"
  8. fill in printer make/model, press "Add Printer"
  9. print a test page
Except for step 2, this is the way to add a network connected printer to CUPS.

OK, so now I tried printing to this new printer - it's really funny, since GNOME shows two printer icons in the tray area! Oh, and guess what? it printed all pages!

This was very puzzling. I could've let it go at this point, since I found a workaround, but I just couldn't. It worked before and it broke down - I wanted a fix. I had no idea what went wrong. The system guys at work were also puzzled - not a good sign - I was alone with this problem.

Chapter 4: Debugging CUPS

But now I had a way to compare a working print job against a non-working print job:
  1. set LogLevel to debug in /etc/cups/cupsd.conf
  2. restart CUPS:
    /etc/init.d/cupsys restart
  3. print the same file twice: once to the directly connected printer, and once to the IPP printer
  4. compare the diagnostic messages in the CUPS error log file /var/log/cups/error_log, that are emitted while printing each job
I sifted out the relevant debug messages from the log file, by searching for messages that contain the string "Job nnn" (where nnn is the job number of the relevant print job), and removing the time stamp and job number (by removing first few characters in each line):

grep "Job 399" /var/log/cups/error_log | cut -c 42- > direct-log.txt
grep "Job 400" /var/log/cups/error_log | cut -c 42- > ipp-log.txt

I then compared the files in emacs (ediff-buffers). There were differences alright, too many of them actually. I finally decided that the interesting part was where direct-log.txt showed

Skipping page 2...
Skipping page 3...
Wrote 1 pages...

and ipp-log.txt showed bits of PostScript ending with the message

Wrote 3 pages...

Chapter 5: The Fix

So CUPS was telling me that it is skipping pages for the directly connected printer. But why does it do that? there's only one explanation (unless I stumbled upon a bug, which didn't seem likely) - because it's told to do that! Somewhere there was an option set to print just the first page. But where?

I started reading the CUPS manual at http://localhost:631/help and found the manual page for lpoptions which pointed me to the file ~/.cups/lpoptions which holds user default printing options. And sure enough, one of the options set for my printer in this file was "page-ranges=1" - print just the first page...

I removed that option and got the printer working again. Bliss.

Epilogue: The Culprit

At this point I recalled that the page ranges option did indeed show up in the debug log messages, just for the directly connected printer. There were other unique options there like "wrap=true" - which pointed me to the culprit: gtklp.

I played around with gtklp while trying to print a certain plain text document, with wrapping of long lines enabled. After a bit of testing I realized that gtklp saves printing options into ~/.cups/lpoptions which affects printing from any other application.

It turns out I'm not the only one ever hit by this bit of odd behavior - see Debian bug #386592.

Anyway, the only appropriate action at this point seemed to be this:

apt-get remove --purge gtklp

4 comments:

  1. You could have disabled this saving of preferences by clearing a checkbox or two in the last tab of gtklp.

    Gtklp is a very useful tool for exposing all the features of a printer when an application does not.

    ReplyDelete
  2. True. I even submitted a patch to the Debian BTS, that disables this option by default. But the package maintainer seems to be MIA.

    I did find gtklp useful, and I installed it because I was in fact clueless about printing under Linux. Which is exactly the reason I was so angry when I realized that it actually caused my problems.

    The fact that saving printing options in gtklp affects printing from any other application is not advertised - I found this out the hard way.

    The solution IMO is for gtklp to use printer instances to save printing options.

    I'm not clueless anymore, but I wish I still was.

    ReplyDelete
  3. thanks for your article.
    I have to same symptom of 'prints only the 1st page'.
    But on these Debian Squeeze, there is no gtklp installed.
    And I don't have ~/.cups/lpoptions

    I'll try to set debug on cups.conf and look at the error.

    ReplyDelete
  4. Thanks for the tips. This f** problem was driving me mad.

    ReplyDelete