Hi,
I'm printing stack maintainer of a distribution called Pardus. I don't know if the following problem is really caused by the new hplip or by a packaging issue between gs/hplip/cups.
Latest working version : 3.9.12
First broken version: 3.10.2
Other packages' versions:
CUPS: 1.3.11
Ghostscript: 8.71
Steps to reproduce:
1. Install hplip 3.10.2
2. Configure a local/remote queue for an HPLIP supported printer
3. Send a test page.
Expected results:
Test page is printed correctly (with colors if the device isn't monochrome)
Actual results:
Test page is printed out to 4 pages each one containing a quarter of the page (top-left, top-right, bottom-left, bottom-right). The output is black-white and each quarter of the test page is printed starting from the middle of the page vertically.
More details:
0. One of our users reproduces this with its DeskJet F4210 and I'm able to reproduce it with an OfficeJet J6410,
1. The problem isn't caused by a bug in the PPD file created by the hpcups backend because if you install hplip 3.9.12 and send a test page using the PPD generated using 3.10.2, everything works just fine.
2. My packages are generally based on Fedora, e.g. I'm carrying a lot of fedora patches for hplip/cups and ghostscript. But seen that there are no similar issues around, I doubt that I might be doing something wrong in one of these packages which has just been triggered with this new HPLIP,
3. My locale is tr_TR.UTF-8 which has the infamous collation bug, see:
http://www.mattryall.net/blog/2009/02/the-infamous-turkish-locale-bug
But I tried running CUPS and lp with LC_ALL=C to see if it changes something but nope,
Some outputs that may help:
# lpstat -t
scheduler is running
no system default destination
device for HP_OfficeJet_J6400_series_192.168.3.248: socket://192.168.3.248
HP_OfficeJet_J6400_series_192.168.3.248 accepting requests since Sal 30 Mar 2010 16:34:54 EEST
printer HP_OfficeJet_J6400_series_192.168.3.248 is idle. enabled since Sal 30 Mar 2010 16:34:54 EEST
4. It seems that there are no defects in the intermediate files e.g. the TIFF output from pstotiff is just fine.
5. The following is a sample error_log capture during a problematic printing:
I [30/Mar/2010:16:33:43 +0300] [Job 40] Adding start banner page "none".
I [30/Mar/2010:16:33:43 +0300] [Job 40] Adding end banner page "none".
I [30/Mar/2010:16:33:43 +0300] [Job 40] File of type application/postscript queued by "root".
D [30/Mar/2010:16:33:43 +0300] [Job 40] hold_until=0
I [30/Mar/2010:16:33:43 +0300] [Job 40] Queued on "HP_OfficeJet_J6400_series_192.168.3.248" by "root".
d [30/Mar/2010:16:33:43 +0300] cupsdCheckJobs: Job 40: state_value=3, loaded=yes
d [30/Mar/2010:16:33:43 +0300] [Job 40] start_job: file = 0/1
D [30/Mar/2010:16:33:43 +0300] [Job 40] job-sheets=none,none
D [30/Mar/2010:16:33:43 +0300] [Job 40] banner_page = 0
D [30/Mar/2010:16:33:43 +0300] [Job 40] argv[0]="HP_OfficeJet_J6400_series_192.168.3.248"
D [30/Mar/2010:16:33:43 +0300] [Job 40] argv[1]="40"
D [30/Mar/2010:16:33:43 +0300] [Job 40] argv[2]="root"
D [30/Mar/2010:16:33:43 +0300] [Job 40] argv[3]="testprint.ps"
D [30/Mar/2010:16:33:43 +0300] [Job 40] argv[4]="1"
D [30/Mar/2010:16:33:43 +0300] [Job 40] argv[5]="document-name=testprint.ps media=A4 sides=one-sided finishings=3 number-up=1 page-ranges=1 job-uuid=urn:uuid:d9b1fa08-8b55-3bc6-5e00-e0e51c972745"
D [30/Mar/2010:16:33:43 +0300] [Job 40] argv[6]="/var/spool/cups/d00040-001"
D [30/Mar/2010:16:33:43 +0300] [Job 40] envp[0]="CUPS_CACHEDIR=/var/cache/cups"
D [30/Mar/2010:16:33:43 +0300] [Job 40] envp[1]="CUPS_DATADIR=/usr/share/cups"
D [30/Mar/2010:16:33:43 +0300] [Job 40] envp[2]="CUPS_DOCROOT=/usr/share/cups/html"
D [30/Mar/2010:16:33:43 +0300] [Job 40] envp[3]="CUPS_FONTPATH=/usr/share/cups/fonts"
D [30/Mar/2010:16:33:43 +0300] [Job 40] envp[4]="CUPS_REQUESTROOT=/var/spool/cups"
D [30/Mar/2010:16:33:43 +0300] [Job 40] envp[5]="CUPS_SERVERBIN=/usr/lib/cups"
D [30/Mar/2010:16:33:43 +0300] [Job 40] envp[6]="CUPS_SERVERROOT=/etc/cups"
D [30/Mar/2010:16:33:43 +0300] [Job 40] envp[7]="CUPS_STATEDIR=/var/run/cups"
D [30/Mar/2010:16:33:43 +0300] [Job 40] envp[8]="PATH=/usr/lib/cups/filter:/usr/bin:/usr/sbin:/bin:/usr/bin"
D [30/Mar/2010:16:33:43 +0300] [Job 40] envp[9]="SERVER_ADMIN=root@2009"
D [30/Mar/2010:16:33:43 +0300] [Job 40] envp[10]="SOFTWARE=CUPS/1.3.11"
D [30/Mar/2010:16:33:43 +0300] [Job 40] envp[11]="TMPDIR=/var/spool/cups/tmp"
D [30/Mar/2010:16:33:43 +0300] [Job 40] envp[12]="USER=root"
D [30/Mar/2010:16:33:43 +0300] [Job 40] envp[13]="CUPS_SERVER=/var/run/cups/cups.sock"
D [30/Mar/2010:16:33:43 +0300] [Job 40] envp[14]="CUPS_ENCRYPTION=IfRequested"
D [30/Mar/2010:16:33:43 +0300] [Job 40] envp[15]="IPP_PORT=631"
D [30/Mar/2010:16:33:43 +0300] [Job 40] envp[16]="CHARSET=utf-8"
D [30/Mar/2010:16:33:43 +0300] [Job 40] envp[17]="LANG=en.UTF-8"
D [30/Mar/2010:16:33:43 +0300] [Job 40] envp[18]="PPD=/etc/cups/ppd/HP_OfficeJet_J6400_series_192.168.3.248.ppd"
D [30/Mar/2010:16:33:43 +0300] [Job 40] envp[19]="RIP_MAX_CACHE=8m"
D [30/Mar/2010:16:33:43 +0300] [Job 40] envp[20]="CONTENT_TYPE=application/postscript"
D [30/Mar/2010:16:33:43 +0300] [Job 40] envp[21]="DEVICE_URI=socket://192.168.3.248"
D [30/Mar/2010:16:33:43 +0300] [Job 40] envp[22]="PRINTER=HP_OfficeJet_J6400_series_192.168.3.248"
D [30/Mar/2010:16:33:43 +0300] [Job 40] envp[23]="FINAL_CONTENT_TYPE=printer/HP_OfficeJet_J6400_series_192.168.3.248"
d [30/Mar/2010:16:33:43 +0300] [Job 40] start_job: status_pipes = [ 19 20 ]
d [30/Mar/2010:16:33:43 +0300] [Job 40] start_job: filter="/usr/lib/cups/filter/pstotiff"
d [30/Mar/2010:16:33:43 +0300] [Job 40] start_job: filterfds[0]=[ 21 22 ]
d [30/Mar/2010:16:33:43 +0300] [Job 40] start_job: Closing filter pipes for slot 1 [ -1 -1 ]...
I [30/Mar/2010:16:33:43 +0300] [Job 40] Started filter /usr/lib/cups/filter/pstotiff (PID 2714)
d [30/Mar/2010:16:33:43 +0300] [Job 40] start_job: filter="/usr/lib/cups/filter/imagetoraster"
d [30/Mar/2010:16:33:43 +0300] [Job 40] start_job: filterfds[1]=[ 23 24 ]
d [30/Mar/2010:16:33:43 +0300] [Job 40] start_job: Closing filter pipes for slot 0 [ 21 22 ]...
I [30/Mar/2010:16:33:43 +0300] [Job 40] Started filter /usr/lib/cups/filter/imagetoraster (PID 2715)
d [30/Mar/2010:16:33:43 +0300] [Job 40] start_job: print_pipes = [ 21 22 ]
d [30/Mar/2010:16:33:43 +0300] [Job 40] start_job: filter="/usr/lib/cups/filter/hpcups"
d [30/Mar/2010:16:33:43 +0300] [Job 40] start_job: filterfds[0]=[ 21 22 ]
d [30/Mar/2010:16:33:43 +0300] [Job 40] start_job: Closing filter pipes for slot 1 [ 23 24 ]...
I [30/Mar/2010:16:33:43 +0300] [Job 40] Started filter /usr/lib/cups/filter/hpcups (PID 2716)
d [30/Mar/2010:16:33:43 +0300] [Job 40] start_job: backend="/usr/lib/cups/backend/socket"
d [30/Mar/2010:16:33:43 +0300] [Job 40] start_job: filterfds[1] = [ -1 -1 ]
I [30/Mar/2010:16:33:43 +0300] [Job 40] Started backend /usr/lib/cups/backend/socket (PID 2717)
d [30/Mar/2010:16:33:43 +0300] [Job 40] start_job: Closing print pipes [ 21 22 ]...
d [30/Mar/2010:16:33:43 +0300] [Job 40] start_job: Closing back pipes [ 15 16 ]...
d [30/Mar/2010:16:33:43 +0300] [Job 40] start_job: Closing side pipes [ 17 18 ]...
d [30/Mar/2010:16:33:43 +0300] [Job 40] start_job: Closing status output pipe 20...
d [30/Mar/2010:16:33:43 +0300] [Job 40] start_job: Closing filter pipes for slot 1 [ -1 -1 ]...
I [30/Mar/2010:16:33:43 +0300] [Job 40] Attempting to connect to host 192.168.3.248 on port 9100
d [30/Mar/2010:16:33:43 +0300] [Job 40] STATE: +connecting-to-device
d [30/Mar/2010:16:33:43 +0300] [Job 40] STATE: -connecting-to-device
I [30/Mar/2010:16:33:43 +0300] [Job 40] Connected to 192.168.3.248...
D [30/Mar/2010:16:33:43 +0300] [Job 40] Connected to 192.168.3.248:9100 (IPv4)...
D [30/Mar/2010:16:33:43 +0300] [Job 40] backendRunLoop(print_fd=0, device_fd=5, use_bc=1, side_cb=0xb7729eb0)
D [30/Mar/2010:16:33:43 +0300] [Job 40] imagetoraster - copying to temp print file "/var/spool/cups/tmp/4bb1fdb747b9d"
D [30/Mar/2010:16:33:43 +0300] [Job 40] GPL Ghostscript 8.71 (2010-02-10)
D [30/Mar/2010:16:33:43 +0300] [Job 40] Copyright (C) 2010 Artifex Software, Inc. All rights reserved.
D [30/Mar/2010:16:33:43 +0300] [Job 40] This software comes with NO WARRANTY: see the file PUBLIC for details.
D [30/Mar/2010:16:33:43 +0300] [Job 40] Loading NimbusSanL-Bold font from /usr/share/ghostscript/8.71/Resource/Font/NimbusSanL-Bold... 2349908 1001965 1503836 219359 1 done.
D [30/Mar/2010:16:33:43 +0300] [Job 40] Loading NimbusSanL-Regu font from /usr/share/ghostscript/8.71/Resource/Font/NimbusSanL-Regu... 2406764 1088465 1503836 220201 1 done.
D [30/Mar/2010:16:33:43 +0300] [Job 40] Loading NimbusRomNo9L-Regu font from /usr/share/ghostscript/8.71/Resource/Font/NimbusRomNo9L-Regu... 2564100 1238927 1503836 221365 1 done.
D [30/Mar/2010:16:33:43 +0300] [Job 40] Page = 595x842; 9,9 to 586,833
D [30/Mar/2010:16:33:43 +0300] [Job 40] Searching for profile "/Automatic"...
I [30/Mar/2010:16:33:43 +0300] [Job 40] Loading image file...
D [30/Mar/2010:16:33:43 +0300] [Job 40] TIFF resolution = 204.000000x196.000000, units=2
D [30/Mar/2010:16:33:43 +0300] [Job 40] Stored resolution = 204x196 PPI
D [30/Mar/2010:16:33:43 +0300] [Job 40] img->colorspace = 3
D [30/Mar/2010:16:33:43 +0300] [Job 40] orientation = top-left
D [30/Mar/2010:16:33:43 +0300] [Job 40] photometric = 0
D [30/Mar/2010:16:33:43 +0300] [Job 40] compression = 4
D [30/Mar/2010:16:33:44 +0300] [Job 40] Before scaling: xppi=204, yppi=196, zoom=0.00
D [30/Mar/2010:16:33:44 +0300] [Job 40] Before scaling: xprint=8.0, yprint=11.4
D [30/Mar/2010:16:33:44 +0300] [Job 40] Image size is 8.5 x 11.7 inches...
D [30/Mar/2010:16:33:44 +0300] [Job 40] Auto orientation...
D [30/Mar/2010:16:33:44 +0300] [Job 40] xpages = 2x4.24in, ypages = 2x5.85in
D [30/Mar/2010:16:33:44 +0300] [Job 40] PageSize = [595 841]
D [30/Mar/2010:16:33:44 +0300] [Job 40] cupsWidth = 4812
D [30/Mar/2010:16:33:44 +0300] [Job 40] cupsHeight = 6864
D [30/Mar/2010:16:33:44 +0300] [Job 40] cupsBitsPerColor = 8
D [30/Mar/2010:16:33:44 +0300] [Job 40] cupsBitsPerPixel = 32
D [30/Mar/2010:16:33:44 +0300] [Job 40] cupsBytesPerLine = 19248
D [30/Mar/2010:16:33:44 +0300] [Job 40] cupsColorOrder = 0
D [30/Mar/2010:16:33:44 +0300] [Job 40] cupsColorSpace = 17
D [30/Mar/2010:16:33:44 +0300] [Job 40] img->colorspace = 3
I [30/Mar/2010:16:33:44 +0300] [Job 40] Formatting page 1...
D [30/Mar/2010:16:33:44 +0300] [Job 40] Read 8192 bytes of print data...
d [30/Mar/2010:16:33:44 +0300] [Job 40] STATE: -media-empty-error
d [30/Mar/2010:16:33:44 +0300] [Job 40] STATE: -offline-error
I [30/Mar/2010:16:33:44 +0300] [Job 40] Printer is now on-line.
D [30/Mar/2010:16:33:44 +0300] [Job 40] Wrote 8192 bytes of print data...
D [30/Mar/2010:16:33:44 +0300] [Job 40] Read 1808 bytes of print data...
d [30/Mar/2010:16:33:44 +0300] [Job 40] PAGE: 1 1DEBUG: Writing 1678 leading blank lines...
D [30/Mar/2010:16:33:44 +0300] [Job 40] Wrote 1808 bytes of print data...
D [30/Mar/2010:16:33:44 +0300] [Job 40] Read 871 bytes of print data...
A lot of R/W without anything useful here...
I [30/Mar/2010:16:34:53 +0300] [Job 40] Print file sent, waiting for printer to finish...
d [30/Mar/2010:16:34:53 +0300] cupsdCheckJobs: Job 40: state_value=5, loaded=yes
I [30/Mar/2010:16:34:54 +0300] [Job 40] Ready to print.
D [30/Mar/2010:16:34:54 +0300] [Job 40] File 0 is complete.
d [30/Mar/2010:16:34:54 +0300] [Job 40] cupsdFinishJob: job->status is 0
d [30/Mar/2010:16:34:54 +0300] [Job 40] cupsdFinishJob: Closing status pipes [ 19 -1 ]...
I [30/Mar/2010:16:34:54 +0300] [Job 40] Completed successfully.
d [30/Mar/2010:16:34:54 +0300] [Job 40] cupsdStopJob: force = 0
d [30/Mar/2010:16:34:54 +0300] [Job 40] Closing print pipes [ -1 -1 ]...
d [30/Mar/2010:16:34:54 +0300] [Job 40] Closing back pipes [ -1 -1 ]...
d [30/Mar/2010:16:34:54 +0300] [Job 40] Closing side pipes [ -1 -1 ]...
D [30/Mar/2010:16:34:55 +0300] [Job 40] Unloading...