D [04/Oct/2005:00:15:05 +0000] StartJob: argv = "Pixma4000","4","","Test Page","1","","/var/spool/cups/d00004-001"
D [04/Oct/2005:00:15:05 +0000] StartJob: envp[0]="PATH=/usr/local/libexec/cups/filter:/bin:/usr/bin"
D [04/Oct/2005:00:15:05 +0000] StartJob: envp[1]="SOFTWARE=CUPS/1.1"
D [04/Oct/2005:00:15:05 +0000] StartJob: envp[2]="USER=root"
D [04/Oct/2005:00:15:05 +0000] StartJob: envp[3]="CHARSET=utf-8"
D [04/Oct/2005:00:15:05 +0000] StartJob: envp[4]="LANG=en_US"
D [04/Oct/2005:00:15:05 +0000] StartJob: envp[5]="PPD=/usr/local/etc/cups/ppd/Pixma4000.ppd"
D [04/Oct/2005:00:15:05 +0000] StartJob: envp[6]="CUPS_SERVERROOT=/usr/local/etc/cups"
D [04/Oct/2005:00:15:05 +0000] StartJob: envp[7]="RIP_MAX_CACHE=8m"
D [04/Oct/2005:00:15:05 +0000] StartJob: envp[8]="TMPDIR=/var/spool/cups/tmp"
D [04/Oct/2005:00:15:05 +0000] StartJob: envp[9]="CONTENT_TYPE=application/postscript"
D [04/Oct/2005:00:15:05 +0000] StartJob: envp[10]="DEVICE_URI=usb:/dev/ulpt0"
D [04/Oct/2005:00:15:05 +0000] StartJob: envp[11]="PRINTER=Pixma4000"
D [04/Oct/2005:00:15:05 +0000] StartJob: envp[12]="CUPS_DATADIR=/usr/local/share/cups"
D [04/Oct/2005:00:15:05 +0000] StartJob: envp[13]="CUPS_FONTPATH=/usr/local/share/cups/fonts"
D [04/Oct/2005:00:15:05 +0000] StartJob: envp[14]="CUPS_SERVER=localhost"
D [04/Oct/2005:00:15:05 +0000] StartJob: envp[15]="IPP_PORT=631"
d [04/Oct/2005:00:15:05 +0000] StartJob: Allocating status buffer...
D [04/Oct/2005:00:15:05 +0000] StartJob: statusfds = [ 9 10 ]
D [04/Oct/2005:00:15:05 +0000] StartJob: filterfds[1] = [ 11 -1 ]
D [04/Oct/2005:00:15:05 +0000] StartJob: filter = "/usr/local/libexec/cups/filter/pstops"
D [04/Oct/2005:00:15:05 +0000] StartJob: filterfds[0] = [ 12 13 ]
D [04/Oct/2005:00:15:05 +0000] start_process("/usr/local/libexec/cups/filter/pstops", 0xbfbef180, 0xbfbee4f0, 11, 13, 10)
I [04/Oct/2005:00:15:05 +0000] Started filter /usr/local/libexec/cups/filter/pstops (PID 5839) for job 4.
D [04/Oct/2005:00:15:05 +0000] StartJob: filter = "/usr/local/libexec/cups/filter/foomatic-rip"
D [04/Oct/2005:00:15:05 +0000] StartJob: filterfds[1] = [ 11 14 ]
D [04/Oct/2005:00:15:05 +0000] start_process("/usr/local/libexec/cups/filter/foomatic-rip", 0xbfbef180, 0xbfbee4f0, 12, 14, 10)
I [04/Oct/2005:00:15:05 +0000] Started filter /usr/local/libexec/cups/filter/foomatic-rip (PID 5840) for job 4.
D [04/Oct/2005:00:15:05 +0000] StartJob: backend = "/usr/local/libexec/cups/backend/usb"
D [04/Oct/2005:00:15:05 +0000] StartJob: filterfds[0] = [ -1 12 ]
D [04/Oct/2005:00:15:05 +0000] start_process("/usr/local/libexec/cups/backend/usb", 0xbfbef180, 0xbfbee4f0, 11, 12, 10)
I [04/Oct/2005:00:15:05 +0000] Started backend /usr/local/libexec/cups/backend/usb (PID 5841) for job 4.
d [04/Oct/2005:00:15:05 +0000] StartJob: Adding fd 9 to InputSet...
d [04/Oct/2005:00:15:05 +0000] add_job_state_reasons(0x8093c34[7], 4)
D [04/Oct/2005:00:15:05 +0000] ProcessIPPRequest: 7 status_code=0
d [04/Oct/2005:00:15:05 +0000] ProcessIPPRequest: Adding fd 7 to OutputSet...
d [04/Oct/2005:00:15:05 +0000] PID 5839 exited with no errors.
D [04/Oct/2005:00:15:05 +0000] [Job 4] Page = 612x792; 0,0 to 612,792
D [04/Oct/2005:00:15:05 +0000] [Job 4] slowcollate=0, slowduplex=0, sloworder=0
D [04/Oct/2005:00:15:05 +0000] [Job 4] 0 %%BoundingBox: 0 0 612 792
D [04/Oct/2005:00:15:05 +0000] [Job 4] 0 %%Pages: 1
D [04/Oct/2005:00:15:05 +0000] [Job 4] 0 %%LanguageLevel: 1
D [04/Oct/2005:00:15:05 +0000] [Job 4] 0 %%DocumentData: Clean7Bit
D [04/Oct/2005:00:15:05 +0000] [Job 4] 0 %%DocumentSuppliedResources: procset testprint/1.1
D [04/Oct/2005:00:15:05 +0000] [Job 4] 0 %%DocumentNeededResources: font Helvetica Helvetica-Bold Times-Roman
D [04/Oct/2005:00:15:05 +0000] [Job 4] 0 %%Creator: Michael Sweet, Easy Software Products
D [04/Oct/2005:00:15:05 +0000] [Job 4] 0 %%CreationDate: May 11, 1999
D [04/Oct/2005:00:15:05 +0000] [Job 4] 0 %%Title: Test Page
D [04/Oct/2005:00:15:05 +0000] [Job 4] 0 %%EndComments
D [04/Oct/2005:00:15:05 +0000] [Job 4] 0 %%BeginProlog
D [04/Oct/2005:00:15:05 +0000] [Job 4] 0 %%BeginResource procset testprint 1.1 0D [04/Oct/2005:00:15:05 +0000] [Job 4] 0 %%EndResource
D [04/Oct/2005:00:15:05 +0000] [Job 4] 0 %%EndProlog
D [04/Oct/2005:00:15:05 +0000] [Job 4] 0 %%Page: 1 1
D [04/Oct/2005:00:15:05 +0000] [Job 4] 0 %%Page: 1 1
D [04/Oct/2005:00:15:05 +0000] [Job 4] pw = 612.0, pl = 792.0
D [04/Oct/2005:00:15:05 +0000] [Job 4] PageLeft = 0.0, PageRight = 612.0
D [04/Oct/2005:00:15:05 +0000] [Job 4] PageTop = 792.0, PageBottom = 0.0
D [04/Oct/2005:00:15:05 +0000] [Job 4] PageWidth = 612.0, PageLength = 792.0
D [04/Oct/2005:00:15:05 +0000] [Job 4] 0 %%EOF
D [04/Oct/2005:00:15:05 +0000] [Job 4] Saw EOF!
D [04/Oct/2005:00:15:05 +0000] [Job 4] perl: warning: Setting locale failed.
D [04/Oct/2005:00:15:05 +0000] [Job 4] perl: warning: Please check that your locale settings:
D [04/Oct/2005:00:15:05 +0000] [Job 4] LC_ALL = (unset),
D [04/Oct/2005:00:15:05 +0000] [Job 4] LANG = "en_US"
D [04/Oct/2005:00:15:05 +0000] [Job 4] are supported and installed on your system.
D [04/Oct/2005:00:15:05 +0000] [Job 4] perl: warning: Falling back to the standard locale ("C").
d [04/Oct/2005:00:15:05 +0000] WriteClient: Removing fd 7 from OutputSet...
d [04/Oct/2005:00:15:05 +0000] ReadClient: 7, used=0, file=-1
d [04/Oct/2005:00:15:05 +0000] ReadClient: httpGets returned EOF...
D [04/Oct/2005:00:15:05 +0000] CloseClient: 7
d [04/Oct/2005:00:15:05 +0000] CloseClient: Removing fd 7 from InputSet and OutputSet...
d [04/Oct/2005:00:15:05 +0000] PID 5838 exited with no errors.
d [04/Oct/2005:00:15:05 +0000] DeleteCert: removing certificate for pid 5838
d [04/Oct/2005:00:15:05 +0000] WriteClient: Removing fd 5 from OutputSet...
d [04/Oct/2005:00:15:05 +0000] WriteClient: Removing fd 8 from InputSet...
d [04/Oct/2005:00:15:05 +0000] WriteClient: 5 Closing data file 8.
d [04/Oct/2005:00:15:05 +0000] ReadClient: 5, used=0, file=-1
D [04/Oct/2005:00:15:05 +0000] ReadClient: 5 GET /favicon.ico HTTP/1.1
d [04/Oct/2005:00:15:05 +0000] decode_auth(0x8091000): Authorization string = ""d [04/Oct/2005:00:15:05 +0000] decode_auth: 5 username=""
d [04/Oct/2005:00:15:05 +0000] IsAuthorized: con->uri = "/favicon.ico"
d [04/Oct/2005:00:15:05 +0000] FindBest: uri = "/favicon.ico"...
d [04/Oct/2005:00:15:05 +0000] FindBest: Location / Limit 7f
d [04/Oct/2005:00:15:05 +0000] FindBest: Location /admin Limit 7f
d [04/Oct/2005:00:15:05 +0000] FindBest: best = "/"
d [04/Oct/2005:00:15:05 +0000] IsAuthorized: auth = 0, satisfy=0...
d [04/Oct/2005:00:15:05 +0000] get_file: 5 filename=/usr/local/share/doc/cups/favicon.ico size=-1
D [04/Oct/2005:00:15:05 +0000] SendError: 5 code=404 (Not Found)
D [04/Oct/2005:00:15:05 +0000] CloseClient: 5
d [04/Oct/2005:00:15:05 +0000] CloseClient: Removing fd 5 from InputSet and OutputSet...
D [04/Oct/2005:00:15:05 +0000] [Job 4] foomatic-rip version $Revision: 3.43.2.15 $ running...
D [04/Oct/2005:00:15:05 +0000] [Job 4] Parsing PPD file ...
D [04/Oct/2005:00:15:05 +0000] [Job 4] *cupsFilter: "application/vnd.cups-postscript 0 foomatic-rip"
D [04/Oct/2005:00:15:05 +0000] [Job 4] Added option ColorSpace
D [04/Oct/2005:00:15:05 +0000] [Job 4] Added option PageSize
D [04/Oct/2005:00:15:05 +0000] [Job 4] Added option PageRegion
D [04/Oct/2005:00:15:05 +0000] [Job 4] Added option ImageableArea
D [04/Oct/2005:00:15:05 +0000] [Job 4] Added option PaperDimension
D [04/Oct/2005:00:15:05 +0000] [Job 4] Added option Manual
D [04/Oct/2005:00:15:05 +0000] [Job 4] Added option MediaType
D [04/Oct/2005:00:15:05 +0000] [Job 4] Added option MediaWeight
D [04/Oct/2005:00:15:05 +0000] [Job 4] Added option Resolution
D [04/Oct/2005:00:15:05 +0000] [Job 4] Added option PrintQuality
D [04/Oct/2005:00:15:05 +0000] [Job 4] Added option BitsPerPixel
D [04/Oct/2005:00:15:05 +0000] [Job 4] Added option ProcessColorModel
D [04/Oct/2005:00:15:05 +0000] [Job 4] Added option PrintColors
D [04/Oct/2005:00:15:05 +0000] [Job 4] Added option Font
D [04/Oct/2005:00:15:05 +0000] [Job 4]
D [04/Oct/2005:00:15:05 +0000] [Job 4] Parameter Summary
D [04/Oct/2005:00:15:05 +0000] [Job 4] -----------------
D [04/Oct/2005:00:15:05 +0000] [Job 4]
D [04/Oct/2005:00:15:05 +0000] [Job 4] Spooler: cups
D [04/Oct/2005:00:15:05 +0000] [Job 4] Printer: Pixma4000
D [04/Oct/2005:00:15:05 +0000] [Job 4] PPD file: /usr/local/etc/cups/ppd/Pixma4000.ppd
D [04/Oct/2005:00:15:05 +0000] [Job 4] Printer model: Canon BJC-7004 Foomatic/bjc800 (recommended)
D [04/Oct/2005:00:15:05 +0000] [Job 4] Job title: Test Page
D [04/Oct/2005:00:15:05 +0000] [Job 4] File(s) to be printed:
D [04/Oct/2005:00:15:05 +0000] [Job 4] <STDIN>
D [04/Oct/2005:00:15:05 +0000] [Job 4]
D [04/Oct/2005:00:15:05 +0000] [Job 4] GhostScript extra search path ('GS_LIB'): /usr/local/share/cups/fonts
D [04/Oct/2005:00:15:05 +0000] [Job 4]
D [04/Oct/2005:00:15:05 +0000] [Job 4] ================================================
D [04/Oct/2005:00:15:05 +0000] [Job 4]
D [04/Oct/2005:00:15:05 +0000] [Job 4] File: <STDIN>
D [04/Oct/2005:00:15:05 +0000] [Job 4]
D [04/Oct/2005:00:15:05 +0000] [Job 4] ================================================
D [04/Oct/2005:00:15:05 +0000] [Job 4]
D [04/Oct/2005:00:15:05 +0000] [Job 4] Reading PostScript input ...
D [04/Oct/2005:00:15:05 +0000] [Job 4] --> This document is DSC-conforming!
D [04/Oct/2005:00:15:05 +0000] [Job 4]
D [04/Oct/2005:00:15:05 +0000] [Job 4] -----------
D [04/Oct/2005:00:15:05 +0000] [Job 4] Found: %%BeginProlog
D [04/Oct/2005:00:15:05 +0000] [Job 4] Found: %%EndProlog
D [04/Oct/2005:00:15:05 +0000] [Job 4]
D [04/Oct/2005:00:15:05 +0000] [Job 4] -----------
D [04/Oct/2005:00:15:05 +0000] [Job 4] Found: %%BeginSetup
D [04/Oct/2005:00:15:05 +0000] [Job 4] Found: %%BeginFeature: *PrintColors CMYK
D [04/Oct/2005:00:15:05 +0000] [Job 4] Option: PrintColors=CMYK --> Option will be set by PostScript interpreter
D [04/Oct/2005:00:15:05 +0000] [Job 4] Found: %%BeginFeature: *BitsPerPixel 24
D [04/Oct/2005:00:15:05 +0000] [Job 4] Option: BitsPerPixel=24 --> Setting option
D [04/Oct/2005:00:15:05 +0000] [Job 4] Found: %% FoomaticRIPOptionSetting: BitsPerPixel=24
D [04/Oct/2005:00:15:05 +0000] [Job 4] Option: BitsPerPixel=24 --> Setting option
D [04/Oct/2005:00:15:05 +0000] [Job 4] Found: %%BeginFeature: *MediaType plain
D [04/Oct/2005:00:15:05 +0000] [Job 4] Option: MediaType=plain --> Option will be set by PostScript interpreter
D [04/Oct/2005:00:15:05 +0000] [Job 4] Found: %%BeginFeature: *MediaWeight Normal
D [04/Oct/2005:00:15:05 +0000] [Job 4] Option: MediaWeight=Normal --> Option will be set by PostScript interpreter
D [04/Oct/2005:00:15:05 +0000] [Job 4] Found: %%BeginFeature: *PageSize Letter
D [04/Oct/2005:00:15:05 +0000] [Job 4] Option: PageSize=Letter --> Option will be set by PostScript interpreter
D [04/Oct/2005:00:15:05 +0000] [Job 4] Found: %%BeginFeature: *PrintQuality Normal
D [04/Oct/2005:00:15:05 +0000] [Job 4] Option: PrintQuality=Normal --> Option will be set by PostScript interpreter
D [04/Oct/2005:00:15:05 +0000] [Job 4] Found: %%BeginFeature: *ProcessColorModel CMYK
D [04/Oct/2005:00:15:05 +0000] [Job 4] Option: ProcessColorModel=CMYK --> Setting option
D [04/Oct/2005:00:15:05 +0000] [Job 4] Found: %% FoomaticRIPOptionSetting: ProcessColorModel=CMYK
D [04/Oct/2005:00:15:05 +0000] [Job 4] Option: ProcessColorModel=CMYK --> Setting option
D [04/Oct/2005:00:15:05 +0000] [Job 4] Found: %%BeginFeature: *Manual False
D [04/Oct/2005:00:15:05 +0000] [Job 4] Option: Manual=False --> Correcting numerical/string option to Manual=0 (Command line argument)
D [04/Oct/2005:00:15:05 +0000] [Job 4] Found: %%BeginFeature: *Resolution 300x300dpi
D [04/Oct/2005:00:15:05 +0000] [Job 4] Option: Resolution=300x300dpi --> Option will be set by PostScript interpreter
D [04/Oct/2005:00:15:05 +0000] [Job 4] Found: %%EndSetup
D [04/Oct/2005:00:15:05 +0000] [Job 4] Inserting PostScript code for CUPS' page accounting
D [04/Oct/2005:00:15:05 +0000] [Job 4]
D [04/Oct/2005:00:15:05 +0000] [Job 4] -----------
D [04/Oct/2005:00:15:05 +0000] [Job 4] New page: 1 1
D [04/Oct/2005:00:15:05 +0000] [Job 4] Inserting option code into "PageSetup" section.
D [04/Oct/2005:00:15:05 +0000] [Job 4] No page header or page header not DSC-conforming
D [04/Oct/2005:00:15:05 +0000] [Job 4] Stopping search for page header options
D [04/Oct/2005:00:15:05 +0000] [Job 4] Found:
D [04/Oct/2005:00:15:05 +0000] [Job 4] pageHeight sub % Move down...
D [04/Oct/2005:00:15:05 +0000] [Job 4] --> Output goes directly to the renderer now.
D [04/Oct/2005:00:15:05 +0000] [Job 4]
D [04/Oct/2005:00:15:05 +0000] [Job 4]
D [04/Oct/2005:00:15:05 +0000] [Job 4] Starting renderer
D [04/Oct/2005:00:15:05 +0000] [Job 4]
D [04/Oct/2005:00:15:05 +0000] [Job 4] Closing renderer
D [04/Oct/2005:00:15:05 +0000] [Job 4] renderer PID kid4=5844
D [04/Oct/2005:00:15:05 +0000] [Job 4] JCL: <job data>
D [04/Oct/2005:00:15:05 +0000] [Job 4]
D [04/Oct/2005:00:15:05 +0000] [Job 4] renderer command: gs -q -dBATCH -dPARANOIDSAFER -dQUIET -dNOPAUSE -sDEVICE=bjc800 -dBitsPerPixel=24 -dProcessColorModel=/DeviceCMYK -sOutputFile=- -
D [04/Oct/2005:00:15:05 +0000] [Job 4] perl: warning: Setting locale failed.
D [04/Oct/2005:00:15:05 +0000] [Job 4] perl: warning: Please check that your locale settings:
D [04/Oct/2005:00:15:05 +0000] [Job 4] LC_ALL = (unset),
D [04/Oct/2005:00:15:05 +0000] [Job 4] LANG = "en_US"
D [04/Oct/2005:00:15:05 +0000] [Job 4] are supported and installed on your system.
D [04/Oct/2005:00:15:05 +0000] [Job 4] perl: warning: Falling back to the standard locale ("C").
D [04/Oct/2005:00:15:05 +0000] [Job 4] foomatic-gswrapper: gs '-dBATCH' '-dPARANOIDSAFER' '-dQUIET' '-dNOPAUSE' '-sDEVICE=bjc800' '-dBitsPerPixel=24' '-dProcessColorModel=/DeviceCMYK' '-sOutputFile=/dev/fd/3' '/dev/fd/0' 3>&1 1>&2
D [04/Oct/2005:00:15:05 +0000] [Job 4] Error: /invalidfileaccess in --.outputpage--
D [04/Oct/2005:00:15:05 +0000] [Job 4] Operand stack:
D [04/Oct/2005:00:15:05 +0000] [Job 4] 391.347 296.987 287.52 721.253 287.52 53.0333 47.92 1 true
D [04/Oct/2005:00:15:05 +0000] [Job 4] Execution stack:
D [04/Oct/2005:00:15:05 +0000] [Job 4] %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-- 7 3 %oparray_pop --nostringval-- --nostringval-- --nostringval-- --nostringval--
D [04/Oct/2005:00:15:05 +0000] [Job 4] Dictionary stack:
D [04/Oct/2005:00:15:05 +0000] [Job 4] --dict:1063/1123(ro)(G)-- --dict:1/20(G)-- --dict:100/200(L)--
D [04/Oct/2005:00:15:05 +0000] [Job 4] Current allocation mode is local
D [04/Oct/2005:00:15:05 +0000] [Job 4] Last OS error: 45
D [04/Oct/2005:00:15:05 +0000] [Job 4] GNU Ghostscript 7.07: Unrecoverable error, exit code 1
D [04/Oct/2005:00:15:05 +0000] [Job 4] renderer return value: 1
D [04/Oct/2005:00:15:05 +0000] [Job 4] renderer received signal: 1
D [04/Oct/2005:00:15:05 +0000] [Job 4] KID3 exited with status 3
D [04/Oct/2005:00:15:05 +0000] [Job 4] tail process done writing data to STDOUT
D [04/Oct/2005:00:15:05 +0000] [Job 4] KID4 finished
D [04/Oct/2005:00:15:05 +0000] [Job 4] Process dying with "Possible error on renderer command line or PostScript error. Check options.", exit stat: 3
D [04/Oct/2005:00:15:05 +0000] [Job 4] error: No such file or directory (2)
D [04/Oct/2005:00:15:05 +0000] [Job 4] Possible error on renderer command line or PostScript error. Check options.
D [04/Oct/2005:00:15:05 +0000] [Job 4] Renderer exit stat: 3
D [04/Oct/2005:00:15:05 +0000] [Job 4] Renderer process finished
D [04/Oct/2005:00:15:05 +0000] [Job 4] Killing process 5843 (KID3)
D [04/Oct/2005:00:15:05 +0000] [Job 4] Process dying with "Error closing renderer", exit stat: 3
D [04/Oct/2005:00:15:05 +0000] [Job 4] error: No such file or directory (2)
D [04/Oct/2005:00:15:05 +0000] [Job 4] Error closing renderer
E [04/Oct/2005:00:15:05 +0000] PID 5840 stopped with status 3!
d [04/Oct/2005:00:15:05 +0000] PID 5841 exited with no errors.
D [04/Oct/2005:00:15:05 +0000] UpdateJob: job 4, file 0 is complete.
d [04/Oct/2005:00:15:05 +0000] UpdateJob: Removing fd 9 from InputSet...
D [04/Oct/2005:00:15:05 +0000] CancelJob: id = 4
D [04/Oct/2005:00:15:05 +0000] StopJob: id = 4, force = 0
D [04/Oct/2005:00:15:05 +0000] StopJob: printer state is 3
d [04/Oct/2005:00:15:05 +0000] StopJob: Freeing status buffer...
d [04/Oct/2005:00:15:05 +0000] SaveJob: Closing file 7...
d [04/Oct/2005:00:15:05 +0000] SaveJob: Closing file 7...
d [04/Oct/2005:00:15:06 +0000] select_timeout: 31 seconds to send browse update
I [04/Oct/2005:00:15:09 +0000] Scheduler shutting down normally.
D [04/Oct/2005:00:15:09 +0000] StopListening: closing all listen sockets.
D [04/Oct/2005:00:15:09 +0000] PauseListening: clearing input bits...
d [04/Oct/2005:00:15:09 +0000] PauseListening: Removing fd 0 from InputSet...
d [04/Oct/2005:00:15:09 +0000] StopBrowsing: Removing fd 2 from InputSet...
d [04/Oct/2005:00:15:09 +0000] StopServer: Removing fd 3 from InputSet...