I have a networked printer at IP 192.168.0.250 that I am trying to print to from my Fedora host at 192.168.0.210. It appears that the jobs are succeeding from the CUPS side, but nothing is being printed on the printer. Printer is brand new (I got a new one yesterday after I was seeing similar problems on my old USB one), and has paper, ink, etc.
I put log level on CUPS to "debug" and so it is rather long. But here is the pertinent section:
D [20/Aug/2010:10:21:31 -0600] [Job 8] Before copy_prolog - %%BeginProlog
D [20/Aug/2010:10:21:31 -0600] [Job 8] Resolution: 600
D [20/Aug/2010:10:21:31 -0600] [Job 8] Page size: Letter
D [20/Aug/2010:10:21:31 -0600] [Job 8] Width: 612, height: 792
D [20/Aug/2010:10:21:31 -0600] [Job 8] Absolute margins: 12, 12, 600, 780
D [20/Aug/2010:10:21:31 -0600] [Job 8] Relative margins: 12, 12, 12, 12
D [20/Aug/2010:10:21:31 -0600] [Job 8] Resolved as "socket://192.168.0.250:9100"...
D [20/Aug/2010:10:21:31 -0600] [Job 8] STATE: -connecting-to-device
D [20/Aug/2010:10:21:31 -0600] [Job 8] Executing backend "/usr/lib/cups/backend/socket"...
D [20/Aug/2010:10:21:31 -0600] Discarding unused printer-state-changed event...
D [20/Aug/2010:10:21:31 -0600] [Job 8] STATE: +connecting-to-device
D [20/Aug/2010:10:21:31 -0600] Discarding unused printer-state-changed event...
D [20/Aug/2010:10:21:31 -0600] [Job 8] Looking up "192.168.0.250"...
D [20/Aug/2010:10:21:31 -0600] [Job 8] Connecting to 192.168.0.250:9100
I [20/Aug/2010:10:21:31 -0600] [Job 8] Connecting to printer...
D [20/Aug/2010:10:21:31 -0600] Discarding unused job-progress event...
D [20/Aug/2010:10:21:31 -0600] [Job 8] STATE: -connecting-to-device
D [20/Aug/2010:10:21:31 -0600] Discarding unused printer-state-changed event...
I [20/Aug/2010:10:21:31 -0600] [Job 8] Connected to printer...
D [20/Aug/2010:10:21:31 -0600] [Job 8] Connected to 192.168.0.250:9100 (IPv4)...
D [20/Aug/2010:10:21:31 -0600] Discarding unused job-progress event...
D [20/Aug/2010:10:21:31 -0600] [Job 8] InputSlot: Default
D [20/Aug/2010:10:21:31 -0600] [Job 8] Value for MediaPosition: 0
D [20/Aug/2010:10:21:31 -0600] [Job 8] ColorModel: RGB
D [20/Aug/2010:10:21:31 -0600] [Job 8] Value for BitsPerPixel: 24
D [20/Aug/2010:10:21:31 -0600] [Job 8] Duplex: None
D [20/Aug/2010:10:21:31 -0600] [Job 8] Value for Duplex: false; Value for Tumble:
D [20/Aug/2010:10:21:31 -0600] [Job 8] PPD options: -r600 -dDEVICEWIDTHPOINTS=612 -dDEVICEHEIGHTPOINTS=792 -dMediaPosition=0 -dBitsPerPixel=24 -dDuplex=false
D [20/Aug/2010:10:21:31 -0600] [Job 8] PostScript code from options: <</.HWMargins[12 12 12 12] /Margins[0 0]>>setpagedevice
D [20/Aug/2010:10:21:31 -0600] [Job 8] Before copy_setup - %%Page: 1 1
D [20/Aug/2010:10:21:31 -0600] [Job 8] Before page loop - %%Page: 1 1
D [20/Aug/2010:10:21:31 -0600] [Job 8] Copying page 1...
D [20/Aug/2010:10:21:31 -0600] [Job 8] pagew = 588.0, pagel = 768.0
D [20/Aug/2010:10:21:31 -0600] [Job 8] bboxx = 0, bboxy = 0, bboxw = 612, bboxl = 792
D [20/Aug/2010:10:21:31 -0600] [Job 8] PageLeft = 12.0, PageRight = 600.0
D [20/Aug/2010:10:21:31 -0600] [Job 8] PageTop = 780.0, PageBottom = 12.0
D [20/Aug/2010:10:21:31 -0600] [Job 8] PageWidth = 612.0, PageLength = 792.0
D [20/Aug/2010:10:21:31 -0600] [Job 8] Copying page 2...
D [20/Aug/2010:10:21:31 -0600] [Job 8] pagew = 588.0, pagel = 768.0
D [20/Aug/2010:10:21:31 -0600] [Job 8] bboxx = 0, bboxy = 0, bboxw = 612, bboxl = 792
D [20/Aug/2010:10:21:31 -0600] [Job 8] PageLeft = 12.0, PageRight = 600.0
D [20/Aug/2010:10:21:31 -0600] [Job 8] PageTop = 780.0, PageBottom = 12.0
D [20/Aug/2010:10:21:31 -0600] [Job 8] PageWidth = 612.0, PageLength = 792.0
D [20/Aug/2010:10:21:31 -0600] [Job 8] Wrote 2 pages...
D [20/Aug/2010:10:21:31 -0600] PID 14374 (/usr/lib/cups/filter/pstops) exited with no errors.
D [20/Aug/2010:10:21:31 -0600] PID 14373 (/usr/lib/cups/filter/texttops) exited with no errors.
D [20/Aug/2010:10:21:31 -0600] [Job 8] ATTR: marker-colors=none,none,none,none
D [20/Aug/2010:10:21:31 -0600] cupsdMarkDirty(P-----)
D [20/Aug/2010:10:21:31 -0600] [Job 8] ATTR: marker-names="black ink","yellow ink","cyan ink","magenta ink"
D [20/Aug/2010:10:21:31 -0600] cupsdMarkDirty(P-----)
D [20/Aug/2010:10:21:31 -0600] [Job 8] ATTR: marker-types=ink,ink,ink,ink
D [20/Aug/2010:10:21:31 -0600] cupsdMarkDirty(P-----)
D [20/Aug/2010:10:21:31 -0600] [Job 8] ATTR: marker-levels=88,243,277,285
D [20/Aug/2010:10:21:31 -0600] cupsdMarkDirty(P-----)
D [20/Aug/2010:10:21:31 -0600] Discarding unused printer-state-changed event...
D [20/Aug/2010:10:21:31 -0600] [Job 8] STATE: -media-low-report
D [20/Aug/2010:10:21:31 -0600] [Job 8] STATE: -media-empty-warning
D [20/Aug/2010:10:21:31 -0600] [Job 8] STATE: -toner-low-report
D [20/Aug/2010:10:21:31 -0600] [Job 8] STATE: -toner-empty-warning
D [20/Aug/2010:10:21:31 -0600] [Job 8] STATE: -door-open-report
D [20/Aug/2010:10:21:31 -0600] [Job 8] STATE: -media-jam-warning
D [20/Aug/2010:10:21:31 -0600] [Job 8] STATE: -input-tray-missing-warning
D [20/Aug/2010:10:21:31 -0600] [Job 8] STATE: -output-tray-missing-warning
D [20/Aug/2010:10:21:31 -0600] [Job 8] STATE: -marker-supply-missing-warning
D [20/Aug/2010:10:21:31 -0600] [Job 8] STATE: -output-area-almost-full-report
D [20/Aug/2010:10:21:31 -0600] [Job 8] STATE: -output-area-full-warning
D [20/Aug/2010:10:21:31 -0600] [Job 8] backendRunLoop(print_fd=0, device_fd=5, snmp_fd=6, addr=0x22790cc, use_bc=1, side_cb=0xeca380)
I [20/Aug/2010:10:21:31 -0600] [Job 8] Starting GPL Ghostscript 8.71...
D [20/Aug/2010:10:21:31 -0600] [Job 8] Running /usr/bin/gs -dQUIET -dPARANOIDSAFER -dNOPAUSE -dBATCH -sDEVICE=pxlcolor -sstdout=%stderr -r600 -dDEVICEWIDTHPOINTS=612 -dDEVICEHEIGHTPOINTS=792 -dMediaPosition=0 -dBitsPerPixel=24 -dDuplex=false -sOUTPUTFILE=%stdout -c <</.HWMargins[12 12 12 12] /Margins[0 0]>>setpagedevice -f /var/spool/cups/tmp/pstopxl.Bl80Tp
D [20/Aug/2010:10:21:31 -0600] Discarding unused job-progress event...
D [20/Aug/2010:10:21:31 -0600] [Job 8] Read 4096 bytes of print data...
D [20/Aug/2010:10:21:31 -0600] [Job 8] ATTR: marker-levels=88,243,277,285
D [20/Aug/2010:10:21:31 -0600] cupsdMarkDirty(P-----)
D [20/Aug/2010:10:21:31 -0600] Discarding unused printer-state-changed event...
D [20/Aug/2010:10:21:31 -0600] [Job 8] Wrote 4096 bytes of print data...
D [20/Aug/2010:10:21:31 -0600] [Job 8] Read 4096 bytes of print data...
D [20/Aug/2010:10:21:31 -0600] [Job 8] Wrote 4096 bytes of print data...
D [20/Aug/2010:10:21:31 -0600] [Job 8] Read 4096 bytes of print data...
.......
.......
.......
D [20/Aug/2010:10:21:31 -0600] [Job 8] Read 11 bytes of print data...
D [20/Aug/2010:10:21:31 -0600] [Job 8] Wrote 11 bytes of print data...
I [20/Aug/2010:10:21:31 -0600] [Job 8] Print file sent, waiting for printer to finish...
D [20/Aug/2010:10:21:31 -0600] Discarding unused job-progress event...
D [20/Aug/2010:10:21:31 -0600] PID 14375 (/usr/lib/cups/filter/pstopxl) exited with no errors.
D [20/Aug/2010:10:21:32 -0600] [Job 8] ATTR: marker-levels=88,243,277,285
D [20/Aug/2010:10:21:32 -0600] cupsdMarkDirty(P-----)
D [20/Aug/2010:10:21:32 -0600] Discarding unused printer-state-changed event...
I [20/Aug/2010:10:21:32 -0600] [Job 8] Ready to print.
D [20/Aug/2010:10:21:32 -0600] Discarding unused job-progress event...
D [20/Aug/2010:10:21:32 -0600] PID 14376 (/usr/lib/cups/backend/dnssd) exited with no errors.
D [20/Aug/2010:10:21:32 -0600] Discarding unused job-completed event...
I [20/Aug/2010:10:21:32 -0600] [Job 8] Job completed.
D [20/Aug/2010:10:21:32 -0600] cupsdMarkDirty(----J-)
D [20/Aug/2010:10:21:32 -0600] Discarding unused printer-state-changed event...
D [20/Aug/2010:10:21:33 -0600] [Job 8] Unloading...
D [20/Aug/2010:10:21:43 -0600] cupsdNetIFUpdate: "lo" = localhost:631
D [20/Aug/2010:10:21:43 -0600] cupsdNetIFUpdate: "eth0" = pdc0.cospringsit.com:631
D [20/Aug/2010:10:21:43 -0600] cupsdNetIFUpdate: "lo" = localhost:631
D [20/Aug/2010:10:21:43 -0600] cupsdNetIFUpdate: "eth0" = fe80::203:47ff:fefc:7c19%eth0:631
D [20/Aug/2010:10:21:43 -0600] Report: clients=0
D [20/Aug/2010:10:21:43 -0600] Report: jobs=8
D [20/Aug/2010:10:21:43 -0600] Report: jobs-active=0
D [20/Aug/2010:10:21:43 -0600] Report: printers=2
D [20/Aug/2010:10:21:43 -0600] Report: printers-implicit=0
D [20/Aug/2010:10:21:43 -0600] Report: stringpool-string-count=3293
D [20/Aug/2010:10:21:43 -0600] Report: stringpool-alloc-bytes=8040
D [20/Aug/2010:10:21:43 -0600] Report: stringpool-total-bytes=62400
I [20/Aug/2010:10:22:02 -0600] Saving printers.conf...
I [20/Aug/2010:10:22:02 -0600] Saving job cache file "/var/cache/cups/job.cache"...
D [20/Aug/2010:10:22:02 -0600] cupsdSetBusyState: Not busy
Does anybody have any ideas on how to even begin debugging this problem?
Thanks in advance for any replies...
Further update for anyone that runs into this issue:
The problem resolved itself when I installed the "hplic" drivers. This has a whole bunch of dependencies, and so ended up installing a lot, but the setup now seems to work with the drivers provided by "hp-setp" binary that gets installed with the hplic package.
Further note of caution:
I was using both a network (hp) printer as well as a USB one (both Deskjet series I believe), and whereas hplic provided the correct drivers for the network printer, but the issues with the USB printer still remain (although hp-setup was able to find that printer and reported successful completion).