Bug 689986 - PS output of gnuplot, filtered through CUPS' pstops is rendered to 0 pages by Ghostscript
Summary: PS output of gnuplot, filtered through CUPS' pstops is rendered to 0 pages by...
Status: RESOLVED INVALID
Alias: None
Product: Ghostscript
Classification: Unclassified
Component: PS Interpreter (show other bugs)
Version: 8.61
Hardware: PC Linux
: P4 normal
Assignee: Alex Cherepanov
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2008-07-31 17:06 UTC by Carl Michal
Modified: 2010-08-12 23:10 UTC (History)
1 user (show)

See Also:
Customer:
Word Size: ---


Attachments
working postscript file (14.53 KB, application/postscript)
2008-07-31 17:07 UTC, Carl Michal
Details
postscript file that fails to print (21.36 KB, application/postscript)
2008-07-31 17:08 UTC, Carl Michal
Details
error log with debug loglevel (54.70 KB, text/plain)
2010-08-03 21:16 UTC, Carl Michal
Details
gnuplot-pstops.ps (22.31 KB, application/postscript)
2010-08-12 20:08 UTC, Till Kamppeter
Details

Note You need to log in before you can comment on or make changes to this bug.
Description Carl Michal 2008-07-31 17:06:44 UTC
Not sure if this is a ghostscript problem or a cups problem.  

Postscript plots produced with recent gnuplot disappear into a black hole when
sent to my printer.  I'll attach two postscript files of the same plot, one from
an old gnuplot, one from a recent gnuplot (4.2.3).  Both render fine in gs on
the screen.

When printed through cups to an HP laserjet 1012 using hpijs (from hplip 2.7.10
or 2.8.5), one of them prints fine, the other disappears.

The really weird thing though is that if I take the gs command line that cups is
using and run it from the command line, it appears to give usable output from
either file (if its output is dumped directed to the printer with cat, it works
for either file).

The cups log from the failure looks like this:
D [31/Jul/2008:16:51:32 -0700] [Job 836] Closing renderer
D [31/Jul/2008:16:51:32 -0700] [Job 836] Starting process 23193:
"foomatic-gswrapper -q -dBATCH -dPARANOIDSAFER -dQUIET -dNOPAUSE -sDEVICE=ijs
-sIjsServer=hpijs -sDev..."
D [31/Jul/2008:16:51:32 -0700] [Job 836] JCL: %-12345X@PJL
D [31/Jul/2008:16:51:32 -0700] [Job 836] @PJL SET MANUALFEED=OFF
D [31/Jul/2008:16:51:32 -0700] [Job 836] @PJL SET MEDIATYPE=NORMAL
D [31/Jul/2008:16:51:32 -0700] [Job 836] @PJL SET ECONOMODE=OFF
D [31/Jul/2008:16:51:32 -0700] [Job 836] @PJL SET COPIES=1
D [31/Jul/2008:16:51:32 -0700] [Job 836] @PJL SET RET=MEDIUM
D [31/Jul/2008:16:51:32 -0700] [Job 836] @PJL SET DENSITY=5
D [31/Jul/2008:16:51:32 -0700] [Job 836] @PJL SET PRINTQUALITY=NORMAL
D [31/Jul/2008:16:51:32 -0700] [Job 836] <job data> 
D [31/Jul/2008:16:51:32 -0700] [Job 836] %-12345X@PJL RESET
D [31/Jul/2008:16:51:32 -0700] [Job 836] 
D [31/Jul/2008:16:51:32 -0700] [Job 836] foomatic-gswrapper: gs
'-sstdout=%stderr' '-dBATCH' '-dPARANOIDSAFER' '-dQUIET' '-dNOPAUSE'
'-sDEVICE=ijs' '-sIjsServer=hpijs' '-sDeviceManufacturer=HEWLETT-PACKARD'
'-sDeviceModel=hp LaserJet 1012' '-dDEVICEWIDTHPOINTS=612'
'-dDEVICEHEIGHTPOINTS=792' '-dDuplex=false' '-r600'
'-sIjsParams=Quality:Quality=0,Quality:ColorMode=0,Quality:MediaType=0,Quality:PenSet=0,PS:MediaPosition=7'
'-dIjsUseOutputFD' '-sOutputFile=%stdout' '-_'
D [31/Jul/2008:16:51:32 -0700] [Job 836] Process 23193 ending:
"foomatic-gswrapper -q -dBATCH -dPARANOIDSAFER -dQUIET -dNOPAUSE -sDEVICE=ijs
-sIjsServer=hpijs -sDev..."
D [31/Jul/2008:16:51:32 -0700] [Job 836] tail process done writing data to STDOUT
D [31/Jul/2008:16:51:32 -0700] [Job 836] KID4 finished
D [31/Jul/2008:16:51:32 -0700] [Job 836] KID4 exited with status 0
D [31/Jul/2008:16:51:32 -0700] [Job 836] KID3 exited with status 0
D [31/Jul/2008:16:51:32 -0700] [Job 836] Renderer exit stat: 0
D [31/Jul/2008:16:51:32 -0700] [Job 836] KID3 finished
D [31/Jul/2008:16:51:32 -0700] [Job 836] Renderer process finished
D [31/Jul/2008:16:51:32 -0700] [Job 836] 
D [31/Jul/2008:16:51:32 -0700] [Job 836] Closing foomatic-rip.
D [31/Jul/2008:16:51:32 -0700] PID 23186 (/usr/libexec/cups/filter/foomatic-rip)
exited with no errors.
D [31/Jul/2008:16:51:32 -0700] [Job 836] Read 193 bytes of print data...
D [31/Jul/2008:16:51:32 -0700] Discarding unused printer-state-changed event...
D [31/Jul/2008:16:51:32 -0700] [Job 836] Wrote 193 bytes of print data...
D [31/Jul/2008:16:51:32 -0700] PID 23187 (/usr/libexec/cups/backend/usb) exited
with no errors.
D [31/Jul/2008:16:51:32 -0700] [Job 836] File 0 is complete.
I [31/Jul/2008:16:51:32 -0700] [Job 836] Completed successfully.


The cups log from the success :
D [31/Jul/2008:16:40:35 -0700] [Job 826] Closing renderer
D [31/Jul/2008:16:40:35 -0700] [Job 826] JCL: %-12345X@PJL
D [31/Jul/2008:16:40:35 -0700] [Job 826] @PJL SET MANUALFEED=OFF
D [31/Jul/2008:16:40:35 -0700] [Job 826] @PJL SET MEDIATYPE=NORMAL
D [31/Jul/2008:16:40:35 -0700] [Job 826] @PJL SET ECONOMODE=OFF
D [31/Jul/2008:16:40:35 -0700] [Job 826] @PJL SET COPIES=1
D [31/Jul/2008:16:40:35 -0700] [Job 826] @PJL SET RET=MEDIUM
D [31/Jul/2008:16:40:35 -0700] [Job 826] @PJL SET DENSITY=5
D [31/Jul/2008:16:40:35 -0700] [Job 826] @PJL SET PRINTQUALITY=NORMAL
D [31/Jul/2008:16:40:35 -0700] [Job 826] <job data> 
D [31/Jul/2008:16:40:35 -0700] [Job 826] %-12345X@PJL RESET
D [31/Jul/2008:16:40:35 -0700] [Job 826] 
D [31/Jul/2008:16:40:35 -0700] [Job 826] renderer PID kid4=20712
D [31/Jul/2008:16:40:35 -0700] [Job 826] renderer command: gs -q -dBATCH
-dPARANOIDSAFER -dQUIET -dNOPAUSE -sD
EVICE=ijs -sIjsServer=hpijs -sDeviceManufacturer="HEWLETT-PACKARD"
-sDeviceModel="hp LaserJet 1012" -dDEVICEWI
DTHPOINTS=612 -dDEVICEHEIGHTPOINTS=792 -dDuplex=false -r600
-sIjsParams=Quality:Quality=0,Quality:ColorMode=0,
Quality:MediaType=0,Quality:PenSet=0,PS:MediaPosition=7 -dIjsUseOutputFD
-sOutputFile=- -
D [31/Jul/2008:16:40:35 -0700] [Job 826] foomatic-gswrapper: gs '-dBATCH'
'-dPARANOIDSAFER' '-dQUIET' '-dNOPAU
SE' '-sDEVICE=ijs' '-sIjsServer=hpijs' '-sDeviceManufacturer=HEWLETT-PACKARD'
'-sDeviceModel=hp LaserJet 1012'
 '-dDEVICEWIDTHPOINTS=612' '-dDEVICEHEIGHTPOINTS=792' '-dDuplex=false' '-r600'
'-sIjsParams=Quality:Quality=0,
Quality:ColorMode=0,Quality:MediaType=0,Quality:PenSet=0,PS:MediaPosition=7'
'-dIjsUseOutputFD' '-sOutputFile=
/dev/fd/3' '/dev/fd/0' 3>&1 1>&2
D [31/Jul/2008:16:40:35 -0700] [Job 826] Read 287 bytes of print data...
D [31/Jul/2008:16:40:35 -0700] [Job 826] Wrote 287 bytes of print data...
D [31/Jul/2008:16:40:35 -0700] Discarding unused printer-state-changed event...
D [31/Jul/2008:16:40:35 -0700] [Job 826] Read 8192 bytes of print data...
D [31/Jul/2008:16:40:35 -0700] [Job 826] Wrote 8192 bytes of print data...
D [31/Jul/2008:16:40:35 -0700] [Job 826] Read 3506 bytes of print data...
D [31/Jul/2008:16:40:35 -0700] [Job 826] Wrote 3506 bytes of print data...
D [31/Jul/2008:16:40:35 -0700] [Job 826] Read 8192 bytes of print data...
D [31/Jul/2008:16:40:35 -0700] [Job 826] Wrote 8192 bytes of print data...
D [31/Jul/2008:16:40:35 -0700] [Job 826] Read 3746 bytes of print data...
D [31/Jul/2008:16:40:35 -0700] [Job 826] Wrote 3746 bytes of print data...
D [31/Jul/2008:16:40:35 -0700] [Job 826] Read 4622 bytes of print data...
D [31/Jul/2008:16:40:35 -0700] [Job 826] Wrote 4622 bytes of print data...
D [31/Jul/2008:16:40:35 -0700] [Job 826] Read 4308 bytes of print data...
D [31/Jul/2008:16:40:35 -0700] [Job 826] Wrote 4308 bytes of print data...
D [31/Jul/2008:16:40:35 -0700] [Job 826] Read 3576 bytes of print data...
D [31/Jul/2008:16:40:35 -0700] [Job 826] Wrote 3576 bytes of print data...
D [31/Jul/2008:16:40:35 -0700] [Job 826] Read 4108 bytes of print data...
D [31/Jul/2008:16:40:35 -0700] [Job 826] Wrote 4108 bytes of print data...
D [31/Jul/2008:16:40:35 -0700] [Job 826] Read 3667 bytes of print data...
D [31/Jul/2008:16:40:35 -0700] [Job 826] Wrote 3667 bytes of print data...
D [31/Jul/2008:16:40:35 -0700] [Job 826] Read 5050 bytes of print data...
D [31/Jul/2008:16:40:35 -0700] [Job 826] Wrote 5050 bytes of print data...
D [31/Jul/2008:16:40:35 -0700] [Job 826] Read 1900 bytes of print data...
D [31/Jul/2008:16:40:35 -0700] [Job 826] Wrote 1900 bytes of print data...
D [31/Jul/2008:16:40:35 -0700] [Job 826] Read 6240 bytes of print data...
D [31/Jul/2008:16:40:35 -0700] [Job 826] Wrote 6240 bytes of print data...
D [31/Jul/2008:16:40:36 -0700] [Job 826] Read 2714 bytes of print data...
D [31/Jul/2008:16:40:36 -0700] [Job 826] Wrote 2714 bytes of print data...
D [31/Jul/2008:16:40:36 -0700] [Job 826] KID3 exited with status 0
D [31/Jul/2008:16:40:36 -0700] [Job 826] tail process done writing data to STDOUT
D [31/Jul/2008:16:40:36 -0700] [Job 826] KID4 exited with status 0
D [31/Jul/2008:16:40:36 -0700] [Job 826] Renderer exit stat: 0
D [31/Jul/2008:16:40:36 -0700] [Job 826] KID4 finished
D [31/Jul/2008:16:40:36 -0700] [Job 826] KID3 finished
D [31/Jul/2008:16:40:36 -0700] [Job 826] Renderer process finished
D [31/Jul/2008:16:40:36 -0700] [Job 826] Read 9 bytes of print data...
D [31/Jul/2008:16:40:36 -0700] [Job 826] 
D [31/Jul/2008:16:40:36 -0700] [Job 826] Closing foomatic-rip.
D [31/Jul/2008:16:40:36 -0700] [Job 826] Wrote 9 bytes of print data...
D [31/Jul/2008:16:40:36 -0700] PID 20706 (/usr/libexec/cups/filter/foomatic-rip)
exited with no errors.
D [31/Jul/2008:16:40:36 -0700] PID 20707 (/usr/libexec/cups/backend/usb) exited
with no errors.
D [31/Jul/2008:16:40:36 -0700] [Job 826] File 0 is complete.
I [31/Jul/2008:16:40:36 -0700] [Job 826] Completed successfully.
Comment 1 Carl Michal 2008-07-31 17:07:52 UTC
Created attachment 4251 [details]
working postscript file
Comment 2 Carl Michal 2008-07-31 17:08:19 UTC
Created attachment 4252 [details]
postscript file that fails to print
Comment 3 Hin-Tak Leung 2010-07-05 04:42:08 UTC
re-assign two cups bugs, having no activity from Mike Sweet for a while.
Comment 4 Till Kamppeter 2010-07-05 12:28:09 UTC
This bug report is already 2 years old. Can you tell us whether the problem still persists with the current versions of CUPS, Ghostscript, Foomatic, HPIJS/HPLIP, and gnuplot? Thanks.
Comment 5 Carl Michal 2010-07-05 18:15:39 UTC
With:
gnuplot 4.2.6
hplip-3.9.12-r1
ghostscript-gpl-8.71
cups-1.3.11
foomatic not installed,

I still see a problem with the same general issue, though its maybe simpler now.

the entry in cups' error.log is: 

 [05/Jul/2010:11:14:13 -0700] [Job ???] Request file type is application/postscript.
I [05/Jul/2010:11:14:13 -0700] [Job 412] Adding start banner page "none".
I [05/Jul/2010:11:14:13 -0700] [Job 412] Adding end banner page "none".
I [05/Jul/2010:11:14:13 -0700] [Job 412] File of type application/postscript queued by "michal".
I [05/Jul/2010:11:14:13 -0700] [Job 412] Queued on "test-1012" by "michal".
I [05/Jul/2010:11:14:13 -0700] [Job 412] Started filter /usr/libexec/cups/filter/pstops (PID 10280)
I [05/Jul/2010:11:14:13 -0700] [Job 412] Started filter /usr/libexec/cups/filter/pstoraster (PID 10281)
I [05/Jul/2010:11:14:13 -0700] [Job 412] Started filter /usr/libexec/cups/filter/hpcups (PID 10282)
I [05/Jul/2010:11:14:13 -0700] [Job 412] Started backend /usr/libexec/cups/backend/hp (PID 10283)
E [05/Jul/2010:11:14:13 -0700] [Job 412] No %%Pages: comment in header!
E [05/Jul/2010:11:14:13 -0700] PID 10282 (/usr/libexec/cups/filter/hpcups) stopped with status 1!
I [05/Jul/2010:11:14:13 -0700] Hint: Try setting the LogLevel to "debug" to find out more.
E [05/Jul/2010:11:14:13 -0700] [Job 412] Job stopped due to filter errors.

it appears to be complaining about the lack of a %%Pages comment in the ps file.
Comment 6 Till Kamppeter 2010-07-31 23:43:07 UTC
Carl, can you set CUPS to debug logging, either with the command

cupsctl LogLevel=debug

or by putting a line "LogLevel debug" into /etc/cups/cupsd.conf and restarting CUPS (/etc/init.d/cups restart)?

After that do

cancel -a
cupsenable test-1012

then send a your problematic print job and after the job has disappeared from the print queue (or got into "stopped" state) attach your error_log here again.
Comment 7 Carl Michal 2010-08-03 21:16:32 UTC
Created attachment 6605 [details]
error log with debug loglevel

Done.  

I don't see anything obvious till the last 10 lines...
Comment 8 Till Kamppeter 2010-08-12 19:55:56 UTC
This is not a bug of the CUPS Raster output device, either it is a bug of CUPS' pstops filter or of the PostScript interpreter of Ghostscript.

Feeding the offending file directly into GhostScript

cat ../testfiles/gnuplot.ps | /usr/bin/gs -dQUIET -dPARANOIDSAFER -dNOPAUSE -dBATCH -dNOMEDIAATTRS -sDEVICE=cups -sstdout=%stderr -sOUTPUTFILE=%stdout -c  -f -_ > out.raster

cat ../testfiles/gnuplot.ps | /usr/bin/gs -dQUIET -dPARANOIDSAFER -dNOPAUSE -dBATCH -dNOMEDIAATTRS -sDEVICE=png16m -sstdout=%stderr -sOUTPUTFILE=%stdout -c  -f -_ > out.png

Gives correct output with both "cups" and "png16m" output devices, whereas passing the file through CUPS's pstops filter, as it usually happens when printing with CUPS, both "cups" and "png16m" produce empty output files (0 pages):

cat ../testfiles/gnuplot.ps | /usr/lib/cups/filter/pstops 1 1 1 1 'PageSize=A4' | /usr/bin/gs -dQUIET -dPARANOIDSAFER -dNOPAUSE -dBATCH -dNOMEDIAATTRS -sDEVICE=cups -sstdout=%stderr -sOUTPUTFILE=%stdout -c  -f -_ > out.raster

cat ../testfiles/gnuplot.ps | /usr/lib/cups/filter/pstops 1 1 1 1 'PageSize=A4' | /usr/bin/gs -dQUIET -dPARANOIDSAFER -dNOPAUSE -dBATCH -dNOMEDIAATTRS -sDEVICE=png16m -sstdout=%stderr -sOUTPUTFILE=%stdout -c  -f -_ > out.png

Strangely enough Ghostscript can display the output of pstops on the screen:

cat ../testfiles/gnuplot.ps | /usr/lib/cups/filter/pstops 1 1 1 1 'PageSize=A4' > gnuplot-pstops.ps
gs -sDEVICE=x11 gnuplot-pstops.ps

As the PNG output device shows the same problem as the CUPS Raster output device here, the problem cannot be in the CUPS Raster output device.
Comment 9 Till Kamppeter 2010-08-12 20:08:41 UTC
Created attachment 6654 [details]
gnuplot-pstops.ps

Attached is the offending PostScript file after being treated by CUPS' pstops filter:

cat ../testfiles/gnuplot.ps | /usr/lib/cups/filter/pstops 1 1 1 1 'PageSize=A4' > gnuplot-pstops.ps

The original file is not DSC-conforming and pstops makes it rather messy, especially appending the "%%BeginSetup ... %%EndSetup" section to the end of the file, after the code which draws tha page.
Comment 10 Alex Cherepanov 2010-08-12 20:22:43 UTC
The file from the comment 9 redefines --showpage-- as no-op.
Without --showpage-- Ghostscript doesn't show the page.
Everything works as designed.
Comment 11 Till Kamppeter 2010-08-12 20:30:08 UTC
Alex, but why is Ghostscript then able to display the page with the "x11" output device?
Comment 12 Till Kamppeter 2010-08-12 20:31:35 UTC
Michal, for me it looks like a problem of the pstops filter. Please report it on the bug tracker of CUPS:

http://www.cups.org/str.php
Comment 13 Till Kamppeter 2010-08-12 20:36:14 UTC
Alex, I have sent the file to a PostScript printer without any filtering now and the printer only wakes up from power-saving mode, it does not print any page. So it is not a Ghostscript bug.

Perhaps we can consider as a Ghostscript bug that the "x11" device displays the file.
Comment 14 Alex Cherepanov 2010-08-12 20:51:22 UTC
x11 device shows intermediate states of the output buffer
as a way to deliver some results faster and demonstrate the progress
to the user.
Comment 15 Till Kamppeter 2010-08-12 21:03:19 UTC
Alex, then this is really not a Ghostscript bug, so I will close it.

Michal, please report a bug against CUPS, see my comment #12.
Comment 16 Carl Michal 2010-08-12 23:10:14 UTC
ok, bug opened here:

http://www.cups.org/str.php?L3641+Qversion:1.3