[cups] Print job inverts colours halfway

Tue Aug 11 05:56:46 PDT 2015

On 8/10/15, Helge Blischke <helgeblischke at web.de> wrote:
> Please do the following:
> –	cupsctl —debug-logging
> –	print a test job exhibiting the issue
> –	grep 'Job xxx‘ /var/log/cups/error_log > an_arbitrary_temporary_file
> 	where xxx is the Job ID
> –	post the contents of the temporary file.
>
> This information will probably give some first hints on where the cause of
> the issue is.

Thanks for the help, grepped content as below, nothing appears out of
ordinary to my untrained eye though since it seems to be full of
"exited without errors"

====================================
I [11/Aug/2015:20:45:50 +0800] [Job 8] Adding start banner page "none".
I [11/Aug/2015:20:45:50 +0800] [Job 8] Adding end banner page "none".
I [11/Aug/2015:20:45:50 +0800] [Job 8] File of type
application/vnd.cups-pdf-banner queued by "c7admin".
D [11/Aug/2015:20:45:50 +0800] [Job 8] hold_until=0
I [11/Aug/2015:20:45:50 +0800] [Job 8] Queued on "Canon-MF4700-OCB1"
by "c7admin".
D [11/Aug/2015:20:45:50 +0800] [Job 8] time-at-processing=1439297150
D [11/Aug/2015:20:45:50 +0800] [Job 8] 4 filters for job:
D [11/Aug/2015:20:45:50 +0800] [Job 8] bannertopdf
(application/vnd.cups-pdf-banner to application/pdf, cost 32)
D [11/Aug/2015:20:45:50 +0800] [Job 8] pdftopdf (application/pdf to
application/vnd.cups-pdf, cost 66)
D [11/Aug/2015:20:45:50 +0800] [Job 8] pdftops
(application/vnd.cups-pdf to application/vnd.cups-postscript, cost
100)
D [11/Aug/2015:20:45:50 +0800] [Job 8] pstoufr2cpca
(application/vnd.cups-postscript to printer/Canon-MF4700-OCB1, cost 0)
D [11/Aug/2015:20:45:50 +0800] [Job 8] job-sheets=none,none
D [11/Aug/2015:20:45:50 +0800] [Job 8] argv[0]="Canon-MF4700-OCB1"
D [11/Aug/2015:20:45:50 +0800] [Job 8] argv[1]="8"
D [11/Aug/2015:20:45:50 +0800] [Job 8] argv[2]="c7admin"
D [11/Aug/2015:20:45:50 +0800] [Job 8] argv[3]="Test page"
D [11/Aug/2015:20:45:50 +0800] [Job 8] argv[4]="1"
D [11/Aug/2015:20:45:50 +0800] [Job 8]
argv[5]="job-uuid=urn:uuid:2acf125f-c65d-3b1d-56c6-f5233d4cf6fd
job-originating-host-name=localhost time-at-creation=1439297150
time-at-processing=1439297150"
D [11/Aug/2015:20:45:50 +0800] [Job 8] argv[6]="/var/spool/cups/d00008-001"
D [11/Aug/2015:20:45:50 +0800] [Job 8] envp[0]="CUPS_CACHEDIR=/var/cache/cups"
D [11/Aug/2015:20:45:50 +0800] [Job 8] envp[1]="CUPS_DATADIR=/usr/share/cups"
D [11/Aug/2015:20:45:50 +0800] [Job 8]
envp[2]="CUPS_DOCROOT=/usr/share/cups/www"
D [11/Aug/2015:20:45:50 +0800] [Job 8]
envp[3]="CUPS_FONTPATH=/usr/share/cups/fonts"
D [11/Aug/2015:20:45:50 +0800] [Job 8]
envp[4]="CUPS_REQUESTROOT=/var/spool/cups"
D [11/Aug/2015:20:45:50 +0800] [Job 8] envp[5]="CUPS_SERVERBIN=/usr/lib/cups"
D [11/Aug/2015:20:45:50 +0800] [Job 8] envp[6]="CUPS_SERVERROOT=/etc/cups"
D [11/Aug/2015:20:45:50 +0800] [Job 8] envp[7]="CUPS_STATEDIR=/var/run/cups"
D [11/Aug/2015:20:45:50 +0800] [Job 8] envp[8]="HOME=/var/spool/cups/tmp"
D [11/Aug/2015:20:45:50 +0800] [Job 8]
envp[9]="PATH=/usr/lib/cups/filter:/usr/lib64/cups/filter:/usr/bin:/usr/sbin:/bin:/usr/bin"
D [11/Aug/2015:20:45:50 +0800] [Job 8]
envp[10]="SERVER_ADMIN=root at localhost.localdomain"
D [11/Aug/2015:20:45:50 +0800] [Job 8] envp[11]="SOFTWARE=CUPS/1.6.3"
D [11/Aug/2015:20:45:50 +0800] [Job 8] envp[12]="TMPDIR=/var/spool/cups/tmp"
D [11/Aug/2015:20:45:50 +0800] [Job 8] envp[13]="USER=root"
D [11/Aug/2015:20:45:50 +0800] [Job 8] envp[14]="CUPS_MAX_MESSAGE=2047"
D [11/Aug/2015:20:45:50 +0800] [Job 8]
envp[15]="CUPS_SERVER=/var/run/cups/cups.sock"
D [11/Aug/2015:20:45:50 +0800] [Job 8] envp[16]="CUPS_ENCRYPTION=IfRequested"
D [11/Aug/2015:20:45:50 +0800] [Job 8] envp[17]="IPP_PORT=631"
D [11/Aug/2015:20:45:50 +0800] [Job 8] envp[18]="CHARSET=utf-8"
D [11/Aug/2015:20:45:50 +0800] [Job 8] envp[19]="LANG=en_US.UTF-8"
D [11/Aug/2015:20:45:50 +0800] [Job 8]
envp[20]="PPD=/etc/cups/ppd/Canon-MF4700-OCB1.ppd"
D [11/Aug/2015:20:45:50 +0800] [Job 8] envp[21]="RIP_MAX_CACHE=128m"
D [11/Aug/2015:20:45:50 +0800] [Job 8]
envp[22]="CONTENT_TYPE=application/vnd.cups-pdf-banner"
D [11/Aug/2015:20:45:50 +0800] [Job 8] envp[23]="DEVICE_URI=socket://10.0.0.201"
D [11/Aug/2015:20:45:50 +0800] [Job 8] envp[24]="PRINTER_INFO=Canon
MF4700 Series"
D [11/Aug/2015:20:45:50 +0800] [Job 8] envp[25]="PRINTER_LOCATION="
D [11/Aug/2015:20:45:50 +0800] [Job 8] envp[26]="PRINTER=Canon-MF4700-OCB1"
D [11/Aug/2015:20:45:50 +0800] [Job 8] envp[27]="PRINTER_STATE_REASONS=none"
D [11/Aug/2015:20:45:50 +0800] [Job 8] envp[28]="CUPS_FILETYPE=document"
D [11/Aug/2015:20:45:50 +0800] [Job 8]
envp[29]="FINAL_CONTENT_TYPE=application/vnd.cups-postscript"
D [11/Aug/2015:20:45:50 +0800] [Job 8] envp[30]="AUTH_I****"
I [11/Aug/2015:20:45:50 +0800] [Job 8] Started filter
/usr/lib/cups/filter/bannertopdf (PID 13685)
I [11/Aug/2015:20:45:50 +0800] [Job 8] Started filter
/usr/lib/cups/filter/pdftopdf (PID 13686)
I [11/Aug/2015:20:45:50 +0800] [Job 8] Started filter
/usr/lib/cups/filter/pdftops (PID 13687)
I [11/Aug/2015:20:45:50 +0800] [Job 8] Started filter
/usr/lib/cups/filter/pstoufr2cpca (PID 13688)
I [11/Aug/2015:20:45:50 +0800] [Job 8] Started backend
/usr/lib/cups/backend/socket (PID 13689)
D [11/Aug/2015:20:45:50 +0800] [Job 8] STATE: +connecting-to-device
D [11/Aug/2015:20:45:50 +0800] [Job 8] Looking up "10.0.0.201"...
D [11/Aug/2015:20:45:50 +0800] [Job 8] pdftops - copying to temp print
file "/var/spool/cups/tmp/cupsGgTsEO"
D [11/Aug/2015:20:45:50 +0800] [Job 8] pstoufr2cpca start.
D [11/Aug/2015:20:45:50 +0800] [Job 8] PID 13685
(/usr/lib/cups/filter/bannertopdf) exited with no errors.
D [11/Aug/2015:20:45:50 +0800] [Job 8] PID 13686
(/usr/lib/cups/filter/pdftopdf) exited with no errors.
D [11/Aug/2015:20:45:50 +0800] [Job 8] Using image rendering resolution 600 dpi
D [11/Aug/2015:20:45:50 +0800] [Job 8] Started filter pdftops (PID 13690)
D [11/Aug/2015:20:45:50 +0800] [Job 8] Started filter pstops (PID 13691)
D [11/Aug/2015:20:45:50 +0800] [Job 8] Page = 595x842; 14,14 to 581,828
D [11/Aug/2015:20:45:50 +0800] [Job 8] slow_collate=0, slow_duplex=0,
slow_order=0
D [11/Aug/2015:20:45:50 +0800] [Job 8] Before copy_comments - %!PS-Adobe-3.0
D [11/Aug/2015:20:45:50 +0800] [Job 8] %!PS-Adobe-3.0
D [11/Aug/2015:20:45:50 +0800] [Job 8] %Produced by poppler pdftops
version: 0.22.5 (http://poppler.freedesktop.org)
D [11/Aug/2015:20:45:50 +0800] [Job 8] %%Creator: cairo 1.10.2
(http://cairographics.org)
D [11/Aug/2015:20:45:50 +0800] [Job 8] %%LanguageLevel: 3
D [11/Aug/2015:20:45:50 +0800] [Job 8] %%DocumentSuppliedResources: (atend)
D [11/Aug/2015:20:45:50 +0800] [Job 8] %%DocumentMedia: 595x842 595 842 0 () ()
D [11/Aug/2015:20:45:50 +0800] [Job 8] %%BoundingBox: 0 0 595 842
D [11/Aug/2015:20:45:50 +0800] [Job 8] %%Pages: 1
D [11/Aug/2015:20:45:50 +0800] [Job 8] %%EndComments
D [11/Aug/2015:20:45:50 +0800] [Job 8] Before copy_prolog - %%BeginProlog
D [11/Aug/2015:20:45:50 +0800] [Job 8] Before copy_setup - %%BeginSetup
D [11/Aug/2015:20:45:50 +0800] [Job 8] prtGeneralCurrentLocalization
type is 5, expected 2!
D [11/Aug/2015:20:45:50 +0800] [Job 8] backendWaitLoop(snmp_fd=6,
addr=0x7fd06dec6298, side_cb=0x7fd06c5e8360)
D [11/Aug/2015:20:45:50 +0800] [Job 8] Before page loop - %%Page: 1 1
D [11/Aug/2015:20:45:50 +0800] [Job 8] Copying page 1...
D [11/Aug/2015:20:45:50 +0800] [Job 8] pagew = 566.9, pagel = 813.5
D [11/Aug/2015:20:45:50 +0800] [Job 8] bboxx = 0, bboxy = 0, bboxw =
595, bboxl = 842
D [11/Aug/2015:20:45:50 +0800] [Job 8] PageLeft = 14.2, PageRight = 581.1
D [11/Aug/2015:20:45:50 +0800] [Job 8] PageTop = 827.8, PageBottom = 14.3
D [11/Aug/2015:20:45:50 +0800] [Job 8] PageWidth = 595.0, PageLength = 842.0
D [11/Aug/2015:20:45:50 +0800] [Job 8] opvpOpenPrinter(463)
D [11/Aug/2015:20:45:50 +0800] [Job 8] CStubOpenPrinter(397)
D [11/Aug/2015:20:45:50 +0800] [Job 8] opvpOpenPrinter(463)
D [11/Aug/2015:20:45:50 +0800] [Job 8] CStubOpenPrinter(397)
D [11/Aug/2015:20:45:50 +0800] [Job 8] Connecting to 10.0.0.201:9100
I [11/Aug/2015:20:45:50 +0800] [Job 8] Connecting to printer.
D [11/Aug/2015:20:45:50 +0800] [Job 8] Set job-printer-state-message
to "Connecting to printer.", current level=INFO
D [11/Aug/2015:20:45:50 +0800] [Job 8] STATE: -connecting-to-device
I [11/Aug/2015:20:45:50 +0800] [Job 8] Connected to printer.
D [11/Aug/2015:20:45:50 +0800] [Job 8] Set job-printer-state-message
to "Connected to printer.", current level=INFO
D [11/Aug/2015:20:45:50 +0800] [Job 8] Connected to 10.0.0.201:9100...
D [11/Aug/2015:20:45:50 +0800] [Job 8] backendRunLoop(print_fd=0,
device_fd=7, snmp_fd=6, addr=0x7fd06dec6298, use_bc=1,
side_cb=0x7fd06c5e8360)
D [11/Aug/2015:20:45:50 +0800] [Job 8] Read 81 bytes of print data...
D [11/Aug/2015:20:45:50 +0800] [Job 8] Wrote 81 bytes of print data...
D [11/Aug/2015:20:45:52 +0800] [Job 8] PID 13690 (pdftops) exited with
no errors.
D [11/Aug/2015:20:45:52 +0800] [Job 8] Wrote 1 pages...
D [11/Aug/2015:20:45:52 +0800] [Job 8] PID 13691 (pstops) exited with no errors.
D [11/Aug/2015:20:45:52 +0800] [Job 8] PID 13687
(/usr/lib/cups/filter/pdftops) exited with no errors.
D [11/Aug/2015:20:45:52 +0800] [Job 8] Read 97 bytes of print data...
D [11/Aug/2015:20:45:52 +0800] [Job 8] Wrote 97 bytes of print data...
D [11/Aug/2015:20:45:52 +0800] [Job 8] Read 8192 bytes of print data...
D [11/Aug/2015:20:45:52 +0800] [Job 8] Wrote 8192 bytes of print data...
D [11/Aug/2015:20:45:52 +0800] [Job 8] Read 8192 bytes of print data...
D [11/Aug/2015:20:45:52 +0800] [Job 8] Wrote 8192 bytes of print data...
D [11/Aug/2015:20:45:52 +0800] [Job 8] Read 8192 bytes of print data...
D [11/Aug/2015:20:45:53 +0800] [Job 8] Wrote 8192 bytes of print data...
D [11/Aug/2015:20:45:53 +0800] [Job 8] Read 8192 bytes of print data...
D [11/Aug/2015:20:45:53 +0800] [Job 8] Wrote 8192 bytes of print data...
D [11/Aug/2015:20:45:53 +0800] [Job 8] Read 8192 bytes of print data...
D [11/Aug/2015:20:45:53 +0800] [Job 8] Wrote 8192 bytes of print data...
D [11/Aug/2015:20:45:53 +0800] [Job 8] Read 8192 bytes of print data...
D [11/Aug/2015:20:45:53 +0800] [Job 8] Wrote 8192 bytes of print data...
D [11/Aug/2015:20:45:53 +0800] [Job 8] Read 8192 bytes of print data...
D [11/Aug/2015:20:45:53 +0800] [Job 8] Wrote 8192 bytes of print data...
D [11/Aug/2015:20:45:53 +0800] [Job 8] Read 8192 bytes of print data...
D [11/Aug/2015:20:45:53 +0800] [Job 8] Wrote 8192 bytes of print data...
D [11/Aug/2015:20:45:53 +0800] [Job 8] Read 8192 bytes of print data...
D [11/Aug/2015:20:45:53 +0800] [Job 8] Wrote 8192 bytes of print data...
D [11/Aug/2015:20:45:53 +0800] [Job 8] Read 8192 bytes of print data...
D [11/Aug/2015:20:45:53 +0800] [Job 8] Wrote 8192 bytes of print data...
D [11/Aug/2015:20:45:53 +0800] [Job 8] Read 8192 bytes of print data...
D [11/Aug/2015:20:45:53 +0800] [Job 8] Wrote 8192 bytes of print data...
D [11/Aug/2015:20:45:53 +0800] [Job 8] Read 8192 bytes of print data...
D [11/Aug/2015:20:45:53 +0800] [Job 8] Wrote 8192 bytes of print data...
D [11/Aug/2015:20:45:53 +0800] [Job 8] Read 8192 bytes of print data...
D [11/Aug/2015:20:45:53 +0800] [Job 8] Wrote 8192 bytes of print data...
D [11/Aug/2015:20:45:53 +0800] [Job 8] Read 8192 bytes of print data...
D [11/Aug/2015:20:45:53 +0800] [Job 8] Wrote 8192 bytes of print data...
D [11/Aug/2015:20:45:53 +0800] [Job 8] Read 8192 bytes of print data...
D [11/Aug/2015:20:45:53 +0800] [Job 8] Wrote 8192 bytes of print data...
D [11/Aug/2015:20:45:53 +0800] [Job 8] Read 8192 bytes of print data...
D [11/Aug/2015:20:45:53 +0800] [Job 8] Wrote 8192 bytes of print data...
D [11/Aug/2015:20:45:53 +0800] [Job 8] Read 8192 bytes of print data...
D [11/Aug/2015:20:45:53 +0800] [Job 8] Wrote 8192 bytes of print data...
D [11/Aug/2015:20:45:53 +0800] [Job 8] Read 8192 bytes of print data...
D [11/Aug/2015:20:45:53 +0800] [Job 8] Wrote 8192 bytes of print data...
D [11/Aug/2015:20:45:53 +0800] [Job 8] Read 8192 bytes of print data...
D [11/Aug/2015:20:45:53 +0800] [Job 8] Wrote 8192 bytes of print data...
D [11/Aug/2015:20:45:53 +0800] [Job 8] Read 8192 bytes of print data...
D [11/Aug/2015:20:45:53 +0800] [Job 8] Wrote 8192 bytes of print data...
D [11/Aug/2015:20:45:53 +0800] [Job 8] Read 8192 bytes of print data...
D [11/Aug/2015:20:45:53 +0800] [Job 8] Wrote 8192 bytes of print data...
D [11/Aug/2015:20:45:53 +0800] [Job 8] Read 8192 bytes of print data...
D [11/Aug/2015:20:45:53 +0800] [Job 8] PID 13688
(/usr/lib/cups/filter/pstoufr2cpca) exited with no errors.
D [11/Aug/2015:20:45:53 +0800] [Job 8] Wrote 8192 bytes of print data...
D [11/Aug/2015:20:45:53 +0800] [Job 8] Read 8192 bytes of print data...
D [11/Aug/2015:20:45:53 +0800] [Job 8] Wrote 8192 bytes of print data...
D [11/Aug/2015:20:45:53 +0800] [Job 8] Read 8192 bytes of print data...
D [11/Aug/2015:20:45:53 +0800] [Job 8] Wrote 8192 bytes of print data...
D [11/Aug/2015:20:45:53 +0800] [Job 8] Read 8192 bytes of print data...
D [11/Aug/2015:20:45:53 +0800] [Job 8] Wrote 8192 bytes of print data...
D [11/Aug/2015:20:45:53 +0800] [Job 8] Read 8192 bytes of print data...
D [11/Aug/2015:20:45:53 +0800] [Job 8] Wrote 8192 bytes of print data...
D [11/Aug/2015:20:45:53 +0800] [Job 8] Read 8192 bytes of print data...
D [11/Aug/2015:20:45:53 +0800] [Job 8] Wrote 8192 bytes of print data...
D [11/Aug/2015:20:45:53 +0800] [Job 8] Read 4040 bytes of print data...
D [11/Aug/2015:20:45:53 +0800] [Job 8] Wrote 4040 bytes of print data...
I [11/Aug/2015:20:45:53 +0800] [Job 8] Waiting for printer to finish.
D [11/Aug/2015:20:45:53 +0800] [Job 8] Set job-printer-state-message
to "Waiting for printer to finish.", current level=INFO
D [11/Aug/2015:20:45:53 +0800] [Job 8] PID 13689
(/usr/lib/cups/backend/socket) exited with no errors.
D [11/Aug/2015:20:45:53 +0800] [Job 8] time-at-completed=1439297153
I [11/Aug/2015:20:45:53 +0800] [Job 8] Job completed.
D [11/Aug/2015:20:48:11 +0800] [Job 8] Unloading...
D [11/Aug/2015:20:48:11 +0800] [Job 8] Loading from cache...