EPS file printing failure

[Bill Gribble]

I have a form-filling library that I use to merge scanned or SVG form templates (paper forms such as invoices) with database data for print.  Internally it uses Pyx to poke text and images onto the background and spits out an EPS file with the combined image.

This has worked great for me, printing with CUPS, until about 2 weeks ago. I'm not sure exactly what happened, but now my CUPS print jobs die with a Postscript-related error.  Probably some component got upgraded (I'm on debian unstable) and is stricter about something than it used to be.

Only the EPS files that I generate with my program fail, AFAICT... other PS content works fine.  And if I turn my EPS file into a PDF file with pstopdf it prints OK.  I can look at the EPS file with gv and it's fine.

Here's the relevant section from my cups error_log.  The only thing that looks abnormal to me before the GS error is the stuff about DSC compliance.

Any thoughts?  I can send the offending EPS file to anybody interested.  Contact me directly.

cups-1.2.1
gs-esp 8.15.1.dfsg.1-2
everything else from debian unstable

Thanks,
Bill Gribble

----------- error_log excerpt -------------

I [08/Jun/2006:19:26:29 -0500] Adding start banner page "none" to job 305.
D [08/Jun/2006:19:26:29 -0500] Discarding unused job-created event...
I [08/Jun/2006:19:26:29 -0500] Adding end banner page "none" to job 305.
I [08/Jun/2006:19:26:29 -0500] Job 305 queued on "Deskjet5440" by "grib".
D [08/Jun/2006:19:26:29 -0500] Job 305 hold_until = 0
D [08/Jun/2006:19:26:29 -0500] Discarding unused printer-state-changed event...
D [08/Jun/2006:19:26:29 -0500] job-sheets=none,none
D [08/Jun/2006:19:26:29 -0500] banner_page = 0
D [08/Jun/2006:19:26:29 -0500] [Job 305] argv[0]="Deskjet5440"
D [08/Jun/2006:19:26:29 -0500] [Job 305] argv[1]="305"
D [08/Jun/2006:19:26:29 -0500] [Job 305] argv[2]="grib"
D [08/Jun/2006:19:26:29 -0500] [Job 305] argv[3]="1N4AL11D75C147317.eps"
D [08/Jun/2006:19:26:29 -0500] [Job 305] argv[4]="1"
D [08/Jun/2006:19:26:29 -0500] [Job 305] argv[5]="printer-state-change-time=1149805155 printer-state-reasons=none printer-type=167964 PageRegion=Letter PrintoutMode=Normal Quality=FromPrintoutMode job-uuid=urn:uuid:a8d1cbdc-1288-3f28-715e-5f66762db5cb"
D [08/Jun/2006:19:26:29 -0500] [Job 305] argv[6]="/var/spool/cups/d00305-001"
D [08/Jun/2006:19:26:29 -0500] [Job 305] envp[0]="CUPS_CACHEDIR=/var/cache/cups"
D [08/Jun/2006:19:26:29 -0500] [Job 305] envp[1]="CUPS_DATADIR=/usr/share/cups"
D [08/Jun/2006:19:26:29 -0500] [Job 305] envp[2]="CUPS_DOCROOT=/usr/share/cups/doc-root"
D [08/Jun/2006:19:26:29 -0500] [Job 305] envp[3]="CUPS_FONTPATH=/usr/share/cups/fonts"
D [08/Jun/2006:19:26:29 -0500] [Job 305] envp[4]="CUPS_REQUESTROOT=/var/spool/cups"
D [08/Jun/2006:19:26:29 -0500] [Job 305] envp[5]="CUPS_SERVERBIN=/usr/lib/cups"
D [08/Jun/2006:19:26:29 -0500] [Job 305] envp[6]="CUPS_SERVERROOT=/etc/cups"
D [08/Jun/2006:19:26:29 -0500] [Job 305] envp[7]="CUPS_STATEDIR=/var/run/cups"
D [08/Jun/2006:19:26:29 -0500] [Job 305] envp[8]="PATH=/usr/lib/cups/filter:/usr/bin:/usr/sbin:/bin:/usr/bin"
D [08/Jun/2006:19:26:29 -0500] [Job 305] envp[9]="SERVER_ADMIN=root at localhost"
D [08/Jun/2006:19:26:29 -0500] [Job 305] envp[10]="SOFTWARE=CUPS/1.2.1"
D [08/Jun/2006:19:26:29 -0500] [Job 305] envp[11]="TMPDIR=/var/spool/cups/tmp"
D [08/Jun/2006:19:26:29 -0500] [Job 305] envp[12]="TZ=US/Central"
D [08/Jun/2006:19:26:29 -0500] [Job 305] envp[13]="USER=root"
D [08/Jun/2006:19:26:29 -0500] [Job 305] envp[14]="CUPS_SERVER=localhost"
D [08/Jun/2006:19:26:29 -0500] [Job 305] envp[15]="CUPS_ENCRYPTION=IfRequested"
D [08/Jun/2006:19:26:29 -0500] [Job 305] envp[16]="IPP_PORT=631"
D [08/Jun/2006:19:26:29 -0500] [Job 305] envp[17]="CHARSET=utf-8"
D [08/Jun/2006:19:26:29 -0500] [Job 305] envp[18]="LANG=en_US"
D [08/Jun/2006:19:26:29 -0500] [Job 305] envp[19]="PPD=/etc/cups/ppd/Deskjet5440.ppd"
D [08/Jun/2006:19:26:29 -0500] [Job 305] envp[20]="RIP_MAX_CACHE=8m"
D [08/Jun/2006:19:26:29 -0500] [Job 305] envp[21]="CONTENT_TYPE=application/postscript"
D [08/Jun/2006:19:26:29 -0500] [Job 305] envp[22]="DEVICE_URI=hp:/usb/Deskjet_5400_series?serial=TH62R142Q004K8"
D [08/Jun/2006:19:26:29 -0500] [Job 305] envp[23]="PRINTER=Deskjet5440"
D [08/Jun/2006:19:26:29 -0500] [Job 305] envp[24]="FINAL_CONTENT_TYPE=printer/Deskjet5440"
I [08/Jun/2006:19:26:29 -0500] Started filter /usr/lib/cups/filter/pstops (PID 13948) for job 305.
I [08/Jun/2006:19:26:30 -0500] Started filter /usr/lib/cups/filter/foomatic-rip (PID 13949) for job 305.
I [08/Jun/2006:19:26:30 -0500] Started backend /usr/lib/cups/backend/hp (PID 13950) for job 305.
D [08/Jun/2006:19:26:30 -0500] Discarding unused job-state event...
D [08/Jun/2006:19:26:30 -0500] cupsdProcessIPPRequest: 7 status_code=0 (successful-ok)
D [08/Jun/2006:19:26:30 -0500] [Job 305] Page = 612x792; 18,36 to 594,783
D [08/Jun/2006:19:26:30 -0500] [Job 305] slow_collate=0, slow_duplex=0, slow_order=0
D [08/Jun/2006:19:26:30 -0500] [Job 305] Before copy_comments - %!PS-Adobe-3.0 EPSF-3.0
D [08/Jun/2006:19:26:30 -0500] [Job 305] %!PS-Adobe-3.0 EPSF-3.0
D [08/Jun/2006:19:26:30 -0500] [Job 305] %%BoundingBox: -1 -1 613 793
D [08/Jun/2006:19:26:30 -0500] [Job 305] %%HiResBoundingBox: -1 -1 613 793
D [08/Jun/2006:19:26:30 -0500] [Job 305] %%Creator: PyX 0.8.1
D [08/Jun/2006:19:26:30 -0500] [Job 305] %%Title: /tmp/1N4AL11D75C147317.eps
D [08/Jun/2006:19:26:30 -0500] [Job 305] %%CreationDate: Thu Jun  8 15:05:22 2006
D [08/Jun/2006:19:26:30 -0500] [Job 305] %%EndComments
E [08/Jun/2006:19:26:30 -0500] [Job 305] No %%Pages: comment in header!
D [08/Jun/2006:19:26:30 -0500] [Job 305] Before copy_prolog - %%BeginProlog
D [08/Jun/2006:19:26:30 -0500] [Job 305] Before copy_setup - 0.566929 setlinewidth
D [08/Jun/2006:19:26:30 -0500] [Job 305] Before page loop - %%Page: 1 1
D [08/Jun/2006:19:26:30 -0500] [Job 305] Copying page 1...
D [08/Jun/2006:19:26:30 -0500] [Job 305] pagew = 576.0, pagel = 747.0
D [08/Jun/2006:19:26:30 -0500] [Job 305] bboxw = 612, bboxl = 792
D [08/Jun/2006:19:26:30 -0500] [Job 305] PageLeft = 18.0, PageRight = 594.0
D [08/Jun/2006:19:26:30 -0500] [Job 305] PageTop = 783.0, PageBottom = 36.0
D [08/Jun/2006:19:26:30 -0500] [Job 305] PageWidth = 612.0, PageLength = 792.0
D [08/Jun/2006:19:26:30 -0500] cupsdAcceptClient: 5 from localhost:631 (IPv4)
D [08/Jun/2006:19:26:30 -0500] cupsdReadClient: 5 POST / HTTP/1.1
D [08/Jun/2006:19:26:30 -0500] cupsdAuthorize: No authentication data provided.
D [08/Jun/2006:19:26:30 -0500] Get-Jobs ipp://localhost/jobs
D [08/Jun/2006:19:26:30 -0500] cupsdProcessIPPRequest: 5 status_code=0 (successful-ok)
D [08/Jun/2006:19:26:30 -0500] cupsdReadClient: 5 POST / HTTP/1.1
D [08/Jun/2006:19:26:30 -0500] cupsdAuthorize: No authentication data provided.
D [08/Jun/2006:19:26:30 -0500] Get-Jobs ipp://localhost/jobs
D [08/Jun/2006:19:26:30 -0500] Loading attributes for job 284...
D [08/Jun/2006:19:26:30 -0500] Loading attributes for job 286...
D [08/Jun/2006:19:26:30 -0500] Loading attributes for job 288...
D [08/Jun/2006:19:26:30 -0500] Loading attributes for job 289...
D [08/Jun/2006:19:26:30 -0500] Loading attributes for job 290...
D [08/Jun/2006:19:26:30 -0500] Loading attributes for job 291...
D [08/Jun/2006:19:26:30 -0500] Loading attributes for job 292...
D [08/Jun/2006:19:26:30 -0500] Loading attributes for job 293...
D [08/Jun/2006:19:26:30 -0500] Loading attributes for job 294...
D [08/Jun/2006:19:26:30 -0500] Loading attributes for job 295...
D [08/Jun/2006:19:26:30 -0500] Loading attributes for job 296...
D [08/Jun/2006:19:26:30 -0500] Loading attributes for job 297...
D [08/Jun/2006:19:26:30 -0500] Loading attributes for job 298...
D [08/Jun/2006:19:26:30 -0500] Loading attributes for job 299...
D [08/Jun/2006:19:26:30 -0500] Loading attributes for job 300...
D [08/Jun/2006:19:26:30 -0500] Loading attributes for job 301...
D [08/Jun/2006:19:26:30 -0500] Loading attributes for job 302...
D [08/Jun/2006:19:26:30 -0500] Loading attributes for job 303...
D [08/Jun/2006:19:26:30 -0500] Loading attributes for job 304...
D [08/Jun/2006:19:26:30 -0500] cupsdProcessIPPRequest: 5 status_code=0 (successful-ok)
D [08/Jun/2006:19:26:30 -0500] cupsdCloseClient: 7
D [08/Jun/2006:19:26:30 -0500] [Job 305] foomatic-rip version $Revision: 3.43.2.16 $ running...
D [08/Jun/2006:19:26:30 -0500] [Job 305] Parsing PPD file ...
D [08/Jun/2006:19:26:30 -0500] [Job 305] *cupsFilter: "application/vnd.cups-postscript 0 foomatic-rip"
D [08/Jun/2006:19:26:30 -0500] [Job 305] Added option ColorSpace
D [08/Jun/2006:19:26:30 -0500] [Job 305] Added option Resolution
D [08/Jun/2006:19:26:30 -0500] [Job 305] Added option PageSize
D [08/Jun/2006:19:26:30 -0500] [Job 305] Added option PageRegion
D [08/Jun/2006:19:26:30 -0500] [Job 305] Added option Model
D [08/Jun/2006:19:26:30 -0500] [Job 305] Added option PrintoutMode
D [08/Jun/2006:19:26:30 -0500] [Job 305] Added option ImageableArea
D [08/Jun/2006:19:26:30 -0500] [Job 305] Added option PaperDimension
D [08/Jun/2006:19:26:30 -0500] [Job 305] Added option InputSlot
D [08/Jun/2006:19:26:30 -0500] [Job 305] Added option Duplex
D [08/Jun/2006:19:26:30 -0500] [Job 305] Added option Quality
D [08/Jun/2006:19:26:30 -0500] [Job 305] Added option Font
D [08/Jun/2006:19:26:30 -0500] [Job 305]
D [08/Jun/2006:19:26:30 -0500] [Job 305] Parameter Summary
D [08/Jun/2006:19:26:30 -0500] [Job 305] -----------------
D [08/Jun/2006:19:26:30 -0500] [Job 305]
D [08/Jun/2006:19:26:30 -0500] [Job 305] Spooler: cups
D [08/Jun/2006:19:26:30 -0500] [Job 305] Printer: Deskjet5440
D [08/Jun/2006:19:26:30 -0500] [Job 305] PPD file: /etc/cups/ppd/Deskjet5440.ppd
D [08/Jun/2006:19:26:30 -0500] [Job 305] ATTR file:
D [08/Jun/2006:19:26:30 -0500] [Job 305] Printer model: HP DeskJet 5440 Foomatic/hpijs (recommended) - HPLIP 0.9.11
D [08/Jun/2006:19:26:30 -0500] [Job 305] Job title: 1N4AL11D75C147317.eps
D [08/Jun/2006:19:26:30 -0500] [Job 305] File(s) to be printed:
D [08/Jun/2006:19:26:30 -0500] [Job 305] <STDIN>
D [08/Jun/2006:19:26:30 -0500] [Job 305]
D [08/Jun/2006:19:26:30 -0500] [Job 305] GhostScript extra search path ('GS_LIB'): /usr/share/cups/fonts
D [08/Jun/2006:19:26:30 -0500] [Job 305] Pondering option 'printer-state-change-time=1149805155'
D [08/Jun/2006:19:26:30 -0500] [Job 305] Unknown option printer-state-change-time=1149805155.
D [08/Jun/2006:19:26:30 -0500] [Job 305] Pondering option 'printer-state-reasons=none'
D [08/Jun/2006:19:26:30 -0500] [Job 305] Unknown option printer-state-reasons=none.
D [08/Jun/2006:19:26:30 -0500] [Job 305] Pondering option 'printer-type=167964'
D [08/Jun/2006:19:26:30 -0500] [Job 305] Unknown option printer-type=167964.
D [08/Jun/2006:19:26:30 -0500] [Job 305] Pondering option 'PageRegion=Letter'
D [08/Jun/2006:19:26:30 -0500] [Job 305] Pondering option 'PrintoutMode=Normal'
D [08/Jun/2006:19:26:30 -0500] [Job 305] Pondering option 'Quality=FromPrintoutMode'
D [08/Jun/2006:19:26:30 -0500] [Job 305] Pondering option 'job-uuid=urn:uuid:a8d1cbdc-1288-3f28-715e-5f66762db5cb'
D [08/Jun/2006:19:26:30 -0500] [Job 305] Unknown option job-uuid=urn:uuid:a8d1cbdc-1288-3f28-715e-5f66762db5cb.
D [08/Jun/2006:19:26:30 -0500] [Job 305]
D [08/Jun/2006:19:26:30 -0500] [Job 305] ================================================
D [08/Jun/2006:19:26:30 -0500] [Job 305]
D [08/Jun/2006:19:26:30 -0500] [Job 305] File: <STDIN>
D [08/Jun/2006:19:26:30 -0500] [Job 305]
D [08/Jun/2006:19:26:30 -0500] [Job 305] ================================================
D [08/Jun/2006:19:26:30 -0500] [Job 305]
D [08/Jun/2006:19:26:30 -0500] [Job 305] Reading PostScript input ...
D [08/Jun/2006:19:26:30 -0500] [Job 305] --> This document is DSC-conforming!
D [08/Jun/2006:19:26:30 -0500] [Job 305]
D [08/Jun/2006:19:26:30 -0500] [Job 305] -----------
D [08/Jun/2006:19:26:30 -0500] [Job 305] Found: %%BeginProlog
D [08/Jun/2006:19:26:30 -0500] [Job 305] Found: %%EndProlog
D [08/Jun/2006:19:26:30 -0500] [Job 305] Embedded document, nesting level now: 1
D [08/Jun/2006:19:26:30 -0500] [Job 305] This job seems not to be DSC-conforming, DSC-comment for next section not found, stopping to parse the rest, passing it directly to the renderer.
D [08/Jun/2006:19:26:30 -0500] [Job 305] "Setup" section is missing, inserting it.
D [08/Jun/2006:19:26:30 -0500] [Job 305] Inserting PostScript code for CUPS' page accounting
D [08/Jun/2006:19:26:30 -0500] [Job 305] "PageSetup" section is missing, inserting it.
D [08/Jun/2006:19:26:30 -0500] [Job 305] Inserting option code into "PageSetup" section.
D [08/Jun/2006:19:26:30 -0500] [Job 305] Stopped parsing the PostScript data, sending rest directly to renderer.
D [08/Jun/2006:19:26:30 -0500] [Job 305]
D [08/Jun/2006:19:26:30 -0500] [Job 305] Starting renderer
D [08/Jun/2006:19:26:30 -0500] [Job 305] JCL: <job data>
D [08/Jun/2006:19:26:30 -0500] [Job 305]
D [08/Jun/2006:19:26:30 -0500] [Job 305] renderer PID kid4=13955
D [08/Jun/2006:19:26:30 -0500] [Job 305] renderer command: gs -q -dBATCH -dPARANOIDSAFER -dQUIET -dNOPAUSE -sDEVICE=ijs -sIjsServer=hpijs -sDeviceManufacturer="HEWLETT-PACKARD" -sDeviceModel="deskjet 5600" -dDEVICEWIDTHPOINTS=612 -dDEVICEHEIGHTPOINTS=792 -dDuplex=false -r300 -sIjsParams=Quality:Quality=0,Quality:ColorMode=2,Quality:MediaType=0,Quality:PenSet=2,PS:MediaPosition=7 -dIjsUseOutputFD -sOutputFile=- -
D [08/Jun/2006:19:26:30 -0500] [Job 305] foomatic-gswrapper: gs '-dBATCH' '-dPARANOIDSAFER' '-dQUIET' '-dNOPAUSE' '-sDEVICE=ijs' '-sIjsServer=hpijs' '-sDeviceManufacturer=HEWLETT-PACKARD' '-sDeviceModel=deskjet 5600' '-dDEVICEWIDTHPOINTS=612' '-dDEVICEHEIGHTPOINTS=792' '-dDuplex=false' '-r300' '-sIjsParams=Quality:Quality=0,Quality:ColorMode=2,Quality:MediaType=0,Quality:PenSet=2,PS:MediaPosition=7' '-dIjsUseOutputFD' '-sOutputFile=/dev/fd/3' '/dev/fd/0' 3>&1 1>&2
D [08/Jun/2006:19:26:30 -0500] [Job 305] Wrote 1 pages...
D [08/Jun/2006:19:26:30 -0500] PID 13948 (/usr/lib/cups/filter/pstops) exited with no errors.
D [08/Jun/2006:19:26:30 -0500] [Job 305]
D [08/Jun/2006:19:26:30 -0500] [Job 305] Closing renderer
D [08/Jun/2006:19:26:30 -0500] [Job 305] Error: /undefined in ESPwl
D [08/Jun/2006:19:26:30 -0500] [Job 305] Operand stack:
D [08/Jun/2006:19:26:30 -0500] [Job 305]
D [08/Jun/2006:19:26:30 -0500] [Job 305] Execution stack:
D [08/Jun/2006:19:26:30 -0500] [Job 305] %interp_exit   .runexec2   --nostringval--   --nostringval--   --nostringval--   2   %stopped_push   --nostringval--   --nostringval--   --nostringval--   false   1   %stopped_push   1   3   %oparray_pop   1   3   %oparray_pop   1   3   %oparray_pop   1   3   %oparray_pop   .runexec2   --nostringval--   --nostringval--   --nostringval--   2   %stopped_push   --nostringval--
D [08/Jun/2006:19:26:30 -0500] [Job 305] Dictionary stack:
D [08/Jun/2006:19:26:30 -0500] [Job 305] --dict:1129/1686(ro)(G)--   --dict:1/20(G)--   --dict:90/200(L)--
D [08/Jun/2006:19:26:30 -0500] [Job 305] Current allocation mode is local
D [08/Jun/2006:19:26:30 -0500] [Job 305] Last OS error: 2
D [08/Jun/2006:19:26:30 -0500] [Job 305] ESP Ghostscript 815.01: Unrecoverable error, exit code 1
D [08/Jun/2006:19:26:30 -0500] [Job 305] renderer return value: 1
D [08/Jun/2006:19:26:30 -0500] [Job 305] renderer received signal: 1
D [08/Jun/2006:19:26:30 -0500] [Job 305] Process dying with "Possible error on renderer command line or PostScript error. Check options.", exit stat: 3
D [08/Jun/2006:19:26:30 -0500] [Job 305] error: Illegal seek (29)
D [08/Jun/2006:19:26:30 -0500] [Job 305] Possible error on renderer command line or PostScript error. Check options.
D [08/Jun/2006:19:26:30 -0500] [Job 305] KID3 exited with status 3
D [08/Jun/2006:19:26:30 -0500] [Job 305] Renderer exit stat: 3
D [08/Jun/2006:19:26:30 -0500] [Job 305] Renderer process finished
D [08/Jun/2006:19:26:30 -0500] [Job 305] Killing process 13954 (KID3)
D [08/Jun/2006:19:26:30 -0500] [Job 305] Process dying with "Error closing renderer", exit stat: 3
D [08/Jun/2006:19:26:30 -0500] [Job 305] error: Bad file descriptor (9)
D [08/Jun/2006:19:26:30 -0500] [Job 305] Error closing renderer
D [08/Jun/2006:19:26:30 -0500] [Job 305] tail process done writing data to STDOUT
D [08/Jun/2006:19:26:30 -0500] [Job 305] KID4 finished
E [08/Jun/2006:19:26:30 -0500] PID 13949 (/usr/lib/cups/filter/foomatic-rip) stopped with status 3!
D [08/Jun/2006:19:26:32 -0500] PID 13950 (/usr/lib/cups/backend/hp) exited with no errors.
D [08/Jun/2006:19:26:32 -0500] [Job 305] File 0 is complete.