[cups] Text being garbled - Ricoh Pro 1156/1157 - Cups 1.5 and 1.7.2

Thu Apr 21 01:58:30 PDT 2016

> Am 21.04.2016 um 01:01 schrieb Chris Coleman <c at chriscoleman.com>:
> 
> Hi Helge,
> 
> Here is the requested output along with some pictures of the issues...
> 
> http://pasteboard.co/kUCon1M.jpg
> http://pasteboard.co/kUJ5Xqi.jpg
> http://pasteboard.co/kUK23DO.jpg
> http://pasteboard.co/kUM4Q6X.jpg
> 
> Thanks!
> Chris
> 
> I [20/Apr/2016:14:06:40 -0700] [Job 1186] Adding start banner page "none".
> I [20/Apr/2016:14:06:40 -0700] [Job 1186] Queued on "PrintStation1" by
> "lsprint1".
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Auto-typing file...
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Request file type is
> application/pdf.
> I [20/Apr/2016:14:06:40 -0700] [Job 1186] File of type application/pdf
> queued by "lsprint1".
> I [20/Apr/2016:14:06:40 -0700] [Job 1186] Adding end banner page "none".
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] job-sheets=none,none
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] argv[0]="PrintStation1"
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] argv[1]="1186"
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] argv[2]="lsprint1"
> D [20/Apr/2016:14:06:40 -0700] [Job 1186]
> argv[3]="903328_20160331_ft_9_bw_d_y_0_12068079_36681_n_SY.pdf"
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] argv[4]="1"
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] argv[5]="finishings=3 number-up=1
> sides=two-sided-long-edge StapleLocation=UpperLeft
> job-uuid=urn:uuid:f3bc4d05-a4d4-33b6-49fa-30298a1f075e
> job-originating-host-name=localhost time-at-creation=1461186400
> time-at-processing=1461186400 Duplex=DuplexNoTumble"
> D [20/Apr/2016:14:06:40 -0700] [Job 1186]
> argv[6]="/var/spool/cups/d01186-001"
> D [20/Apr/2016:14:06:40 -0700] [Job 1186]
> envp[0]="CUPS_CACHEDIR=/var/cache/cups"
> D [20/Apr/2016:14:06:40 -0700] [Job 1186]
> envp[1]="CUPS_DATADIR=/usr/share/cups"
> D [20/Apr/2016:14:06:40 -0700] [Job 1186]
> envp[2]="CUPS_DOCROOT=/usr/share/cups/doc-root"
> D [20/Apr/2016:14:06:40 -0700] [Job 1186]
> envp[3]="CUPS_FONTPATH=/usr/share/cups/fonts"
> D [20/Apr/2016:14:06:40 -0700] [Job 1186]
> envp[4]="CUPS_REQUESTROOT=/var/spool/cups"
> D [20/Apr/2016:14:06:40 -0700] [Job 1186]
> envp[5]="CUPS_SERVERBIN=/usr/lib/cups"
> D [20/Apr/2016:14:06:40 -0700] [Job 1186]
> envp[6]="CUPS_SERVERROOT=/etc/cups"
> D [20/Apr/2016:14:06:40 -0700] [Job 1186]
> envp[7]="CUPS_STATEDIR=/var/run/cups"
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] envp[8]="HOME=/var/spool/cups/tmp"
> D [20/Apr/2016:14:06:40 -0700] [Job 1186]
> envp[9]="PATH=/usr/lib/cups/filter:/usr/bin:/usr/sbin:/bin:/usr/bin"
> D [20/Apr/2016:14:06:40 -0700] [Job 1186]
> envp[10]="SERVER_ADMIN=root at lsprint1"
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] envp[11]="SOFTWARE=CUPS/1.5.3"
> D [20/Apr/2016:14:06:40 -0700] [Job 1186]
> envp[12]="TMPDIR=/var/spool/cups/tmp"
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] envp[13]="USER=root"
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] envp[14]="CUPS_SERVER=localhost"
> D [20/Apr/2016:14:06:40 -0700] [Job 1186]
> envp[15]="CUPS_ENCRYPTION=IfRequested"
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] envp[16]="IPP_PORT=631"
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] envp[17]="CHARSET=utf-8"
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] envp[18]="LANG=en_US.UTF-8"
> D [20/Apr/2016:14:06:40 -0700] [Job 1186]
> envp[19]="PPD=/etc/cups/ppd/PrintStation1.ppd"
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] envp[20]="RIP_MAX_CACHE=128m"
> D [20/Apr/2016:14:06:40 -0700] [Job 1186]
> envp[21]="CONTENT_TYPE=application/pdf"
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] envp[22]="DEVICE_URI=socket://
> 192.168.1.241"
> D [20/Apr/2016:14:06:40 -0700] [Job 1186]
> envp[23]="PRINTER_INFO=PrintStation1"
> D [20/Apr/2016:14:06:40 -0700] [Job 1186]
> envp[24]="PRINTER_LOCATION=192.168.1.241"
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] envp[25]="PRINTER=PrintStation1"
> D [20/Apr/2016:14:06:40 -0700] [Job 1186]
> envp[26]="PRINTER_STATE_REASONS=none"
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] envp[27]="CUPS_FILETYPE=document"
> D [20/Apr/2016:14:06:40 -0700] [Job 1186]
> envp[28]="FINAL_CONTENT_TYPE=printer/PrintStation1"
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] envp[29]="AUTH_I****"
> I [20/Apr/2016:14:06:40 -0700] [Job 1186] Started filter
> /usr/lib/cups/filter/pdftopdf (PID 23055)
> I [20/Apr/2016:14:06:40 -0700] [Job 1186] Started filter
> /usr/lib/cups/filter/foomatic-rip (PID 23056)
> I [20/Apr/2016:14:06:40 -0700] [Job 1186] Started backend
> /usr/lib/cups/backend/socket (PID 23057)
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] STATE: +connecting-to-device
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Looking up "192.168.1.241"...
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Getting input from file
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] foomatic-rip version 4.0.16.253
> running...
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Parsing PPD file ...
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Added option ColorSpace
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Added option LargeCapacityTray
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Added option Finisher
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Added option MultiFold
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Added option TrimmerUnit
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Added option Tray7
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Added option Stacker
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Added option MultiHolePunchUnit
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Added option OptionBind
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Added option BookletProcessor
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Added option ColorModel
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Added option GSCmdLine
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Added option Resolution
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Added option GSResolution
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Added option JCLResolution
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Added option PageSize
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Added option ImageableArea
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Added option PaperDimension
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Added option InputSlot
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Added option Duplex
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Added option GSDuplex
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Added option JCLDuplex
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Added option Collate
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Added option MediaType
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Added option OutputBin
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Added option RIZfold
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Added option StapleLocation
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Added option RIPunch
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Added option RIPrintMode
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Added option JobType
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Added option Password
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Added option UserCode
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Added option Font
> D [20/Apr/2016:14:06:40 -0700] [Job 1186]
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Parameter Summary
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] -----------------
> D [20/Apr/2016:14:06:40 -0700] [Job 1186]
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Spooler: cups
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Printer: PrintStation1
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Shell: /bin/bash
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] PPD file:
> /etc/cups/ppd/PrintStation1.ppd
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] ATTR file:
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Printer model: Ricoh Pro 1357EX
> PXL
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Job title:
> 903328_20160331_ft_9_bw_d_y_0_12068079_36681_n_SY.pdf
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] File(s) to be printed:
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] <STDIN>
> D [20/Apr/2016:14:06:40 -0700] [Job 1186]
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Ghostscript extra search path
> ('GS_LIB'): /usr/share/cups/fonts
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Printing system options:
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Pondering option 'finishings=3'
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Unknown option finishings=3.
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Pondering option 'number-up=1'
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Unknown option number-up=1.
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Pondering option
> 'sides=two-sided-long-edge'
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Pondering option
> 'job-uuid=urn:uuid:f3bc4d05-a4d4-33b6-49fa-30298a1f075e'
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Unknown option
> job-uuid=urn:uuid:f3bc4d05-a4d4-33b6-49fa-30298a1f075e.
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Pondering option
> 'job-originating-host-name=localhost'
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Unknown option
> job-originating-host-name=localhost.
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Pondering option
> 'time-at-creation=1461186400'
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Unknown option
> time-at-creation=1461186400.
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Pondering option
> 'time-at-processing=1461186400'
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Unknown option
> time-at-processing=1461186400.
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Options from the PPD file:
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Pondering option
> 'StapleLocation=UpperLeft'
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Pondering option
> 'Duplex=DuplexNoTumble'
> D [20/Apr/2016:14:06:40 -0700] [Job 1186]
> D [20/Apr/2016:14:06:40 -0700] [Job 1186]
> ================================================
> D [20/Apr/2016:14:06:40 -0700] [Job 1186]
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] File: <STDIN>
> D [20/Apr/2016:14:06:40 -0700] [Job 1186]
> D [20/Apr/2016:14:06:40 -0700] [Job 1186]
> ================================================
> D [20/Apr/2016:14:06:40 -0700] [Job 1186]
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Filetype: PDF
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Neither PDF renderer command line
> nor Ghostscript-based renderer command line found
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Driver does not understand PDF
> input, converting to PostScript
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Storing temporary files in
> /var/spool/cups/tmp
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] ATTR:
> marker-colors=#000000,#000000,#000000,#000000
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] ATTR: marker-names='"Toner
> Cartridge (Upper)"','"Toner Cartridge (Lower)"','"Waste Toner 1"','"Waste
> Toner 2"'
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] ATTR:
> marker-types=toner,toner,wasteToner,wasteToner
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] ATTR: marker-levels=-1,-1,-1,-1
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] new_supply_state=0,
> change_state=ffff
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] STATE: -developer-low-report
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] STATE: -developer-empty-warning
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] STATE: -marker-supply-low-report
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] STATE:
> -marker-supply-empty-warning
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] STATE: -opc-near-eol-report
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] STATE: -opc-life-over-warning
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] STATE: -toner-low-report
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] STATE: -toner-empty-warning
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] new_state=0, change_state=ffff
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] STATE: -media-low-report
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] STATE: -media-empty-warning
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] STATE: -door-open-report
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] STATE: -media-jam-warning
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] STATE: -input-tray-missing-warning
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] STATE:
> -output-tray-missing-warning
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] STATE:
> -marker-supply-missing-warning
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] STATE:
> -output-area-almost-full-report
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] STATE: -output-area-full-warning
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] backendWaitLoop(snmp_fd=5,
> addr=0x7f2a885369b8, side_cb=0x7f2a86e29180)
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Starting process "pdf-to-ps"
> (generation 1)
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Using image rendering resolution
> 300 dpi
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Started filter pdftops (PID 23059)
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Started filter pstops (PID 23060)
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Page = 612x792; 12,12 to 600,780
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] slow_collate=0, slow_duplex=0,
> slow_order=0
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Before copy_comments -
> %!PS-Adobe-3.0
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] %!PS-Adobe-3.0
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] %Produced by poppler pdftops
> version: 0.18.4 (http://poppler.freedesktop.org)
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] %%LanguageLevel: 2
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] %%DocumentSuppliedResources:
> (atend)
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] %%DocumentMedia: plain 612 792 0
> () ()
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] %%BoundingBox: 0 0 612 792
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] %%Pages: 18
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] %%EndComments
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Before copy_prolog -
> %%BeginDefaults
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Filetype: PostScript
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Before copy_setup - %%BeginSetup
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Reading PostScript input ...
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] --> This document is
> DSC-conforming!
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Found %RBINumCopies: 1
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Job claims to be DSC-conforming,
> but "%%BeginProlog" was missing before first line with
> another"%%BeginProlog" comment (is this a TeX/LaTeX/dvips-generated
> PostScript file?). Assuming start of "Prolog" here.
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Inserting option code into
> "Prolog" section.
> D [20/Apr/2016:14:06:40 -0700] [Job 1186]
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] -----------
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Found: %%BeginProlog
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Found: %%EndProlog
> D [20/Apr/2016:14:06:40 -0700] [Job 1186]
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] -----------
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Found: %%BeginSetup
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Found: %%BeginFeature:
> *BookletProcessor NotInstalled
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Option:
> BookletProcessor=NotInstalled
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] --> Option will be set by
> PostScript interpreter
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Found: %%BeginFeature: *Finisher
> NotInstalled
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Option: Finisher=NotInstalled
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] --> Option will be set by
> PostScript interpreter
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Found: %%BeginFeature:
> *LargeCapacityTray NotInstalled
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Option:
> LargeCapacityTray=NotInstalled
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] --> Option will be set by
> PostScript interpreter
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Found: %%BeginFeature: *MultiFold
> NotInstalled
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Option: MultiFold=NotInstalled
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] --> Option will be set by
> PostScript interpreter
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Found: %%BeginFeature:
> *MultiHolePunchUnit NotInstalled
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Option:
> MultiHolePunchUnit=NotInstalled
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] --> Option will be set by
> PostScript interpreter
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Found: %%BeginFeature:
> *OptionBind None
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Option: OptionBind=None
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] --> Option will be set by
> PostScript interpreter
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Found: %%BeginFeature: *Stacker
> NotInstalled
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Option: Stacker=NotInstalled
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] --> Option will be set by
> PostScript interpreter
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Found: %%BeginFeature: *Tray7
> NotInstalled
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Option: Tray7=NotInstalled
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] --> Option will be set by
> PostScript interpreter
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Found: %%BeginFeature:
> *TrimmerUnit NotInstalled
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Option: TrimmerUnit=NotInstalled
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] --> Option will be set by
> PostScript interpreter
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Found: %%BeginFeature:
> *ColorModel Grayscale
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Option: ColorModel=Grayscale
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Setting option
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Found: %%
> FoomaticRIPOptionSetting: ColorModel=Grayscale
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Option: ColorModel=Grayscale
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Setting option
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Found: %%BeginFeature:
> *Resolution 600dpi
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Option: Resolution=600dpi
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Setting option
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Found: %%
> FoomaticRIPOptionSetting: Resolution=600dpi
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Option: Resolution=600dpi
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Setting option
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Found: %%BeginFeature: *PageSize
> Letter
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Option: PageSize=Letter
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Setting option
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Found: %%
> FoomaticRIPOptionSetting: PageSize=Letter
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Option: PageSize=Letter
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Setting option
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Found: %%BeginFeature: *InputSlot
> Auto
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Option: InputSlot=Auto
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Setting option
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Found: %%
> FoomaticRIPOptionSetting: InputSlot=Auto
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Option: InputSlot=Auto
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Setting option
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Found: %%BeginFeature:
> *RIPrintMode 0rhit
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Option: RIPrintMode=0rhit
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Setting option
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Found: %%
> FoomaticRIPOptionSetting: RIPrintMode=0rhit
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Option: RIPrintMode=0rhit
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Setting option
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Found: %%BeginFeature: *Duplex
> DuplexNoTumble
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Option: Duplex=DuplexNoTumble
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Setting option
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Found: %%
> FoomaticRIPOptionSetting: Duplex=DuplexNoTumble
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Option: Duplex=DuplexNoTumble
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Setting option
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Found: %%BeginFeature: *Collate
> False
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Option: Collate=False
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Setting option
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Found: %%
> FoomaticRIPOptionSetting: Collate=False
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Option: Collate=False
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Setting option
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Found: %%BeginFeature: *MediaType
> Auto
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Option: MediaType=Auto
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Setting option
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Found: %%
> FoomaticRIPOptionSetting: MediaType=Auto
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Option: MediaType=Auto
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Setting option
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Found: %%BeginFeature: *OutputBin
> Default
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Option: OutputBin=Default
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Setting option
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Found: %%
> FoomaticRIPOptionSetting: OutputBin=Default
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Option: OutputBin=Default
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Setting option
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Found: %%BeginFeature:
> *StapleLocation UpperLeft
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Option: StapleLocation=UpperLeft
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Setting option
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Found: %%
> FoomaticRIPOptionSetting: StapleLocation=UpperLeft
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Option: StapleLocation=UpperLeft
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Setting option
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Found: %%BeginFeature: *RIZfold
> None
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Option: RIZfold=None
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Setting option
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Found: %%
> FoomaticRIPOptionSetting: RIZfold=None
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Option: RIZfold=None
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Setting option
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Found: %%BeginFeature: *RIPunch
> None
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Option: RIPunch=None
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Setting option
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Found: %%
> FoomaticRIPOptionSetting: RIPunch=None
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Option: RIPunch=None
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Setting option
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Found: %%BeginFeature: *JobType
> Normal
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Option: JobType=Normal
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Setting option
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Found: %%BeginFeature: *Password
> None
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Option: Password=None
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Setting option
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Found: %%BeginFeature: *UserCode
> None
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Option: UserCode=None
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Setting option
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Before page loop - %%Page: 1 1
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Copying page 1...
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] pagew = 588.0, pagel = 768.0
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] bboxx = 0, bboxy = 0, bboxw =
> 612, bboxl = 792
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] PageLeft = 12.0, PageRight = 600.0
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] PageTop = 780.0, PageBottom = 12.0
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] PageWidth = 612.0, PageLength =
> 792.0
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Found: %%EndSetup
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Inserting PostScript code for
> CUPS' page accounting
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Inserting option code into
> "Setup" section.
> D [20/Apr/2016:14:06:40 -0700] [Job 1186]
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] -----------
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] New page: %%Page: 1 1
> D [20/Apr/2016:14:06:40 -0700] [Job 1186]
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Found: %%BeginPageSetup
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Inserting option code into
> "PageSetup" section.
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Copying page 2...
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] pagew = 588.0, pagel = 768.0
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] bboxx = 0, bboxy = 0, bboxw =
> 612, bboxl = 792
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] PageLeft = 12.0, PageRight = 600.0
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] PageTop = 780.0, PageBottom = 12.0
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] PageWidth = 612.0, PageLength =
> 792.0
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Copying page 3...
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] New page found but previous not
> printed, print it now.
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Found: %%Page: 2 2
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] --> Output goes directly to the
> renderer now.
> D [20/Apr/2016:14:06:40 -0700] [Job 1186]
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] pagew = 588.0, pagel = 768.0
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] bboxx = 0, bboxy = 0, bboxw =
> 612, bboxl = 792
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] PageLeft = 12.0, PageRight = 600.0
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] PageTop = 780.0, PageBottom = 12.0
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] PageWidth = 612.0, PageLength =
> 792.0
> D [20/Apr/2016:14:06:40 -0700] [Job 1186]
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Starting renderer with command:
> "(printf '\033%%-12345X at PJL SET COPIES=1\n'|perl -p -e
> "s/\x26copies\x3b/1/");
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] (gs -q -dBATCH -dPARANOIDSAFER
> -dNOPAUSE -dNOINTERPOLATE  -sDEVICE=pxlmono -r600x600 -sPAPERSIZE=letter
> -sOutputFile=- -   | perl -p -e
> "s/\xf8\x26\xc0\x00\xf8\x34/\xf8\x26\xc0\x01\xf8\x35/g" | perl -p -e
> "s/^\x1b\x25-12345X//" | perl -p -e "s/\xc1\x01\x00\xf8\x31\x44/\x44/g");"
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Starting process "kid3"
> (generation 1)
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Starting process "kid4"
> (generation 2)
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Starting process "renderer"
> (generation 2)
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] JCL: ^[%-12345X at PJL
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] @PJL SET RESOLUTION=600
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] @PJL SET ECONOMODE=OFF
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] @PJL SET DUPLEX=ON
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] @PJL SET BINDING=LONGEDGE
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] @PJL SET MEDIATYPE=PLAINORRECYCLED
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] @PJL SET OUTBIN=SYSDEFAULT
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] @PJL SET STAPLE=LEFTTOP
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] @PJL SET PUNCH=OFF
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] @PJL SET FOLD=OFF
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] <job data> ^[%-12345X at PJL RESET
> D [20/Apr/2016:14:06:40 -0700] [Job 1186]
> D [20/Apr/2016:14:06:40 -0700] [Job 1186]
> D [20/Apr/2016:14:06:40 -0700] [Job 1186]
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] -----------
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] New page: %%Page: 2 2
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Found: %%Page: 2 2
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] --> Output goes to the FIFO
> buffer now.
> D [20/Apr/2016:14:06:40 -0700] [Job 1186]
> D [20/Apr/2016:14:06:40 -0700] [Job 1186]
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Found: %%BeginPageSetup
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Inserting option code into
> "PageSetup" section.
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] New page found but previous not
> printed, print it now.
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Found: %%Page: 3 3
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] --> Output goes directly to the
> renderer now.
> D [20/Apr/2016:14:06:40 -0700] [Job 1186]
> D [20/Apr/2016:14:06:40 -0700] [Job 1186]
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] -----------
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] New page: %%Page: 3 3
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Found: %%Page: 3 3
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] --> Output goes to the FIFO
> buffer now.
> D [20/Apr/2016:14:06:40 -0700] [Job 1186]
> D [20/Apr/2016:14:06:40 -0700] [Job 1186]
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Found: %%BeginPageSetup
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Inserting option code into
> "PageSetup" section.
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Copying page 4...
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] pagew = 588.0, pagel = 768.0
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] bboxx = 0, bboxy = 0, bboxw =
> 612, bboxl = 792
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] PageLeft = 12.0, PageRight = 600.0
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] PageTop = 780.0, PageBottom = 12.0
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] PageWidth = 612.0, PageLength =
> 792.0
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] New page found but previous not
> printed, print it now.
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Found: %%Page: 4 4
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] --> Output goes directly to the
> renderer now.
> D [20/Apr/2016:14:06:40 -0700] [Job 1186]
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Connecting to 192.168.1.241:9100
> I [20/Apr/2016:14:06:40 -0700] [Job 1186] Connecting to printer.
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Set job-printer-state-message to
> "Connecting to printer.", current level=INFO
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] STATE: -connecting-to-device
> I [20/Apr/2016:14:06:40 -0700] [Job 1186] Connected to printer.
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Set job-printer-state-message to
> "Connected to printer.", current level=INFO
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Connected to 192.168.1.241:9100...
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] PAGE: 1 1
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] PAGE: 2 1
> D [20/Apr/2016:14:06:40 -0700] [Job 1186]
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] -----------
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] New page: %%Page: 4 4
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Found: %%Page: 4 4
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] --> Output goes to the FIFO
> buffer now.
> D [20/Apr/2016:14:06:40 -0700] [Job 1186]
> D [20/Apr/2016:14:06:40 -0700] [Job 1186]
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Found: %%BeginPageSetup
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Inserting option code into
> "PageSetup" section.
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Copying page 5...
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] pagew = 588.0, pagel = 768.0
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] bboxx = 0, bboxy = 0, bboxw =
> 612, bboxl = 792
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] PageLeft = 12.0, PageRight = 600.0
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] PageTop = 780.0, PageBottom = 12.0
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] PageWidth = 612.0, PageLength =
> 792.0
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] New page found but previous not
> printed, print it now.
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Found: %%Page: 5 5
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] --> Output goes directly to the
> renderer now.
> D [20/Apr/2016:14:06:40 -0700] [Job 1186]
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] PAGE: 3 1
> D [20/Apr/2016:14:06:40 -0700] [Job 1186]
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] -----------
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] New page: %%Page: 5 5
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Found: %%Page: 5 5
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] --> Output goes to the FIFO
> buffer now.
> D [20/Apr/2016:14:06:40 -0700] [Job 1186]
> D [20/Apr/2016:14:06:40 -0700] [Job 1186]
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Found: %%BeginPageSetup
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Inserting option code into
> "PageSetup" section.
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] backendRunLoop(print_fd=0,
> device_fd=6, snmp_fd=5, addr=0x7f2a885369b8, use_bc=1,
> side_cb=0x7f2a86e29180)
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] Read 8192 bytes of print data...
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] ATTR: marker-levels=-1,-1,-1,-1
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] new_supply_state=0, change_state=0
> D [20/Apr/2016:14:06:40 -0700] [Job 1186] new_state=0, change_state=0
> 
> ...clipped
> 

Chris,

could you please tell how do you generate the PDFs in question – especially how you generate
the header text strings?
I suppose they are generated by some program that does font subsetting and uses its own 
encoding when doing that, using own character codes \x01, \x02, … .
On the other hand, the last filter used in cups’ filter chain, foomatic-rip, in combination with the
PPD used, calls Perl to do certain substitutions in the output generated by Ghostscript’s pxlmono device
to match e.g. the exact media size etc.
As these Perl snippets each consume the complete output data, it happens the substitutions catch
some of the header character strings.

Well, this is a first guess based on your log data – thanks for that! –, and my first suggestion is to
use Ricoh’s PostScript-PPD for this printer, if and only if the printer has the PostScript option built in
(I suppose that as you told your first experience with the 1.5.3 installation did print OK, but I may be wrong).
Otherwise we need to think more about the issue.

Helge