Cups Printing breaks with own backend script

Helge Blischke h.blischke at srz.de
Mon Jul 2 09:43:56 PDT 2007


Jesai langenbach wrote:
> Please Help,
> 
> we have our own backend script but it looks like that it never starts.
> 
> In the Log file I got some Error massages but I find nothing.
> 
> If i start the script manually with the same options cups should do and with the same Enviramant Variables, it works.
> 
> Cups starts correctly and there will also be 2 new files in /var/spool/cups. Our script normaly writes direcktly when its starts a log-file but it creates non, thats why I think that our backend script is not even started by cups.
> 
> 
> 
> printers.conf:
> 
> <Printer cold_printer>
> Info Druckt COLD-Daten
> DeviceURI dwcups:/COLD/
> State Stopped
> StateMessage /usr/lib/cups/backend/dwcups failed
> StateTime 1183391157
> Accepting Yes
> Shared Yes
> JobSheets none none
> QuotaPeriod 0
> PageLimit 0
> KLimit 0
> OpPolicy default
> ErrorPolicy stop-printer
> </Printer>
> 
> 
> cups error.log:
> 
> I [02/Jul/2007:18:09:22 +0200] Job 20 queued on "cold_printer" by "jlangenbach".
> D [02/Jul/2007:18:09:22 +0200] Job 20 hold_until = 0
> d [02/Jul/2007:18:09:22 +0200] cupsdCheckJobs: Job 20: state_value=3, loaded=yes
> D [02/Jul/2007:18:09:22 +0200] [Job 20] argv[0]="cold_printer"
> D [02/Jul/2007:18:09:22 +0200] [Job 20] argv[1]="20"
> D [02/Jul/2007:18:09:22 +0200] [Job 20] argv[2]="jlangenbach"
> D [02/Jul/2007:18:09:22 +0200] [Job 20] argv[3]="Testseite"
> D [02/Jul/2007:18:09:22 +0200] [Job 20] argv[4]="1"
> D [02/Jul/2007:18:09:22 +0200] [Job 20] argv[5]="job-uuid=urn:uuid:df785191-7331-351b-5f28-43eaa30aa51f"
> D [02/Jul/2007:18:09:22 +0200] [Job 20] argv[6]="/var/spool/cups/d00020-001"
> D [02/Jul/2007:18:09:22 +0200] [Job 20] envp[0]="CUPS_CACHEDIR=/var/cache/cups"
> D [02/Jul/2007:18:09:22 +0200] [Job 20] envp[1]="CUPS_DATADIR=/usr/share/cups"
> D [02/Jul/2007:18:09:22 +0200] [Job 20] envp[2]="CUPS_DOCROOT=/usr/share/cups/doc/"
> D [02/Jul/2007:18:09:22 +0200] [Job 20] envp[3]="CUPS_FONTPATH=/usr/share/cups/fonts"
> D [02/Jul/2007:18:09:22 +0200] [Job 20] envp[4]="CUPS_REQUESTROOT=/var/spool/cups"
> D [02/Jul/2007:18:09:22 +0200] [Job 20] envp[5]="CUPS_SERVERBIN=/usr/lib/cups"
> D [02/Jul/2007:18:09:22 +0200] [Job 20] envp[6]="CUPS_SERVERROOT=/etc/cups"
> D [02/Jul/2007:18:09:22 +0200] [Job 20] envp[7]="CUPS_STATEDIR=/var/run/cups"
> D [02/Jul/2007:18:09:22 +0200] [Job 20] envp[8]="PATH=/usr/lib/cups/filter:/usr/bin:/usr/sbin:/bin:/usr/bin"
> D [02/Jul/2007:18:09:22 +0200] [Job 20] envp[9]="SERVER_ADMIN=root at dw0000.vpn"
> D [02/Jul/2007:18:09:22 +0200] [Job 20] envp[10]="SOFTWARE=CUPS/1.2.7"
> D [02/Jul/2007:18:09:22 +0200] [Job 20] envp[11]="TMPDIR=/var/spool/cups/tmp"
> D [02/Jul/2007:18:09:22 +0200] [Job 20] envp[12]="USER=root"
> D [02/Jul/2007:18:09:22 +0200] [Job 20] envp[13]="CUPS_SERVER=localhost"
> D [02/Jul/2007:18:09:22 +0200] [Job 20] envp[14]="CUPS_ENCRYPTION=IfRequested"
> D [02/Jul/2007:18:09:22 +0200] [Job 20] envp[15]="IPP_PORT=631"
> D [02/Jul/2007:18:09:22 +0200] [Job 20] envp[16]="CHARSET=utf-8"
> D [02/Jul/2007:18:09:22 +0200] [Job 20] envp[17]="LANG=en_US"
> D [02/Jul/2007:18:09:22 +0200] [Job 20] envp[18]="PPD=/etc/cups/ppd/cold_printer.ppd"
> D [02/Jul/2007:18:09:22 +0200] [Job 20] envp[19]="RIP_MAX_CACHE=8m"
> D [02/Jul/2007:18:09:22 +0200] [Job 20] envp[20]="CONTENT_TYPE=application/postscript"
> D [02/Jul/2007:18:09:22 +0200] [Job 20] envp[21]="DEVICE_URI=dwcups:/COLD/"
> D [02/Jul/2007:18:09:22 +0200] [Job 20] envp[22]="PRINTER=cold_printer"
> D [02/Jul/2007:18:09:22 +0200] [Job 20] envp[23]="FINAL_CONTENT_TYPE=printer/cold_printer"
> D [02/Jul/2007:18:09:23 +0200] [Job 20] Page = 595x842; 24,48 to 571,818
> D [02/Jul/2007:18:09:23 +0200] [Job 20] slow_collate=0, slow_duplex=0, slow_order=0
> D [02/Jul/2007:18:09:23 +0200] [Job 20] Before copy_comments - %!PS-Adobe-3.0
> D [02/Jul/2007:18:09:23 +0200] [Job 20] %!PS-Adobe-3.0
> D [02/Jul/2007:18:09:23 +0200] [Job 20] %%Title: Testseite
> D [02/Jul/2007:18:09:23 +0200] [Job 20] %%Creator: PScript5.dll Version 5.2
> D [02/Jul/2007:18:09:23 +0200] [Job 20] %%CreationDate: 7/2/2007 18:7:50
> D [02/Jul/2007:18:09:23 +0200] [Job 20] %%For: jlangenbach
> D [02/Jul/2007:18:09:23 +0200] [Job 20] %%BoundingBox: (atend)
> D [02/Jul/2007:18:09:23 +0200] [Job 20] %%Pages: (atend)
> D [02/Jul/2007:18:09:23 +0200] [Job 20] %%Orientation: Portrait
> D [02/Jul/2007:18:09:23 +0200] [Job 20] %%PageOrder: Special
> D [02/Jul/2007:18:09:23 +0200] [Job 20] %%DocumentNeededResources: (atend)
> D [02/Jul/2007:18:09:23 +0200] [Job 20] %%DocumentSuppliedResources: (atend)
> D [02/Jul/2007:18:09:23 +0200] [Job 20] %%DocumentData: Clean7Bit
> D [02/Jul/2007:18:09:23 +0200] [Job 20] %%TargetDevice: (LaserWriter 12/640 PS) (2015.105) 1
> D [02/Jul/2007:18:09:23 +0200] [Job 20] %%LanguageLevel: 2
> D [02/Jul/2007:18:09:23 +0200] [Job 20] %%EndComments
> D [02/Jul/2007:18:09:23 +0200] [Job 20] Before copy_prolog -
> D [02/Jul/2007:18:09:23 +0200] [Job 20] Before copy_setup -
> D [02/Jul/2007:18:09:23 +0200] [Job 20] Before page loop - %%Page: 1 1
> D [02/Jul/2007:18:09:23 +0200] [Job 20] Copying page 1...
> D [02/Jul/2007:18:09:23 +0200] [Job 20] pagew = 547.0, pagel = 770.0
> D [02/Jul/2007:18:09:23 +0200] [Job 20] bboxw = 595, bboxl = 842
> D [02/Jul/2007:18:09:23 +0200] [Job 20] PageLeft = 24.0, PageRight = 571.0
> D [02/Jul/2007:18:09:23 +0200] [Job 20] PageTop = 818.0, PageBottom = 48.0
> D [02/Jul/2007:18:09:23 +0200] [Job 20] PageWidth = 595.0, PageLength = 842.0
> D [02/Jul/2007:18:09:23 +0200] [Job 20] Wrote 1 pages...
> d [02/Jul/2007:18:09:23 +0200] cupsdCheckJobs: Job 20: state_value=5, loaded=yes
> D [02/Jul/2007:18:09:23 +0200] [Job 20] Can`t open debug file at /usr/lib/cups/backend/dwcups line 95.
> D [02/Jul/2007:18:09:24 +0200] [Job 20] foomatic-rip version $Revision$ running...
> D [02/Jul/2007:18:09:24 +0200] [Job 20] Parsing PPD file ...
> D [02/Jul/2007:18:09:24 +0200] [Job 20] *cupsFilter: "application/vnd.cups-postscript 0 foomatic-rip"
> D [02/Jul/2007:18:09:24 +0200] [Job 20] Added option ColorSpace
> D [02/Jul/2007:18:09:24 +0200] [Job 20] Added option PageSize
> D [02/Jul/2007:18:09:24 +0200] [Job 20] Added option PageRegion
> D [02/Jul/2007:18:09:24 +0200] [Job 20] Added option ImageableArea
> D [02/Jul/2007:18:09:24 +0200] [Job 20] Added option PaperDimension
> D [02/Jul/2007:18:09:24 +0200] [Job 20] Added option Duplex
> D [02/Jul/2007:18:09:24 +0200] [Job 20] Added option Resolution
> D [02/Jul/2007:18:09:24 +0200] [Job 20] Added option PreFilter
> D [02/Jul/2007:18:09:24 +0200] [Job 20] Added option Font
> D [02/Jul/2007:18:09:24 +0200] [Job 20]
> D [02/Jul/2007:18:09:24 +0200] [Job 20] Parameter Summary
> D [02/Jul/2007:18:09:24 +0200] [Job 20] -----------------
> D [02/Jul/2007:18:09:24 +0200] [Job 20]
> D [02/Jul/2007:18:09:24 +0200] [Job 20] Spooler: cups
> D [02/Jul/2007:18:09:24 +0200] [Job 20] Printer: cold_printer
> D [02/Jul/2007:18:09:24 +0200] [Job 20] Shell: /bin/sh
> D [02/Jul/2007:18:09:24 +0200] [Job 20] PPD file: /etc/cups/ppd/cold_printer.ppd
> D [02/Jul/2007:18:09:24 +0200] [Job 20] ATTR file:
> D [02/Jul/2007:18:09:24 +0200] [Job 20] Printer model: Apple LaserWriter 16/600 Foomatic/Postscript (recommended)
> D [02/Jul/2007:18:09:24 +0200] [Job 20] Job title: Testseite
> D [02/Jul/2007:18:09:24 +0200] [Job 20] File(s) to be printed:
> D [02/Jul/2007:18:09:24 +0200] [Job 20] <STDIN>
> D [02/Jul/2007:18:09:24 +0200] [Job 20]
> D [02/Jul/2007:18:09:24 +0200] [Job 20] GhostScript extra search path ('GS_LIB'): /usr/share/cups/fonts
> D [02/Jul/2007:18:09:24 +0200] [Job 20] Pondering option 'job-uuid=urn:uuid:df785191-7331-351b-5f28-43eaa30aa51f'
> D [02/Jul/2007:18:09:24 +0200] [Job 20] Unknown option job-uuid=urn:uuid:df785191-7331-351b-5f28-43eaa30aa51f.
> D [02/Jul/2007:18:09:24 +0200] [Job 20]
> D [02/Jul/2007:18:09:24 +0200] [Job 20] ================================================
> D [02/Jul/2007:18:09:24 +0200] [Job 20]
> D [02/Jul/2007:18:09:24 +0200] [Job 20] File: <STDIN>
> D [02/Jul/2007:18:09:24 +0200] [Job 20]
> D [02/Jul/2007:18:09:24 +0200] [Job 20] ================================================
> D [02/Jul/2007:18:09:24 +0200] [Job 20]
> D [02/Jul/2007:18:09:24 +0200] [Job 20] Reading PostScript input ...
> D [02/Jul/2007:18:09:24 +0200] [Job 20] --> This document is DSC-conforming!
> D [02/Jul/2007:18:09:24 +0200] [Job 20] Job claims to be DSC-conforming, but "%%BeginProlog" was missing before first line wit
> h another "%%Begin..." comment (is this a TeX/LaTeX/dvips-generated PostScript file?). Assuming start of "Prolog" here.
> D [02/Jul/2007:18:09:24 +0200] [Job 20]
> D [02/Jul/2007:18:09:24 +0200] [Job 20] -----------
> D [02/Jul/2007:18:09:24 +0200] [Job 20] Found: %%BeginProlog
> D [02/Jul/2007:18:09:24 +0200] [Job 20] Found: %%EndProlog
> D [02/Jul/2007:18:09:24 +0200] [Job 20]
> D [02/Jul/2007:18:09:24 +0200] [Job 20] -----------
> D [02/Jul/2007:18:09:24 +0200] [Job 20] Found: %%BeginSetup
> D [02/Jul/2007:18:09:24 +0200] [Job 20] Found: %%BeginFeature: *PageSize A4
> D [02/Jul/2007:18:09:24 +0200] [Job 20] Option: PageSize=A4 --> Option will be set by PostScript interpreter
> D [02/Jul/2007:18:09:24 +0200] [Job 20] Found: %%BeginFeature: *PreFilter No
> D [02/Jul/2007:18:09:24 +0200] [Job 20] Option: PreFilter=No --> Setting option
> D [02/Jul/2007:18:09:24 +0200] [Job 20] Found: %% FoomaticRIPOptionSetting: PreFilter=No
> D [02/Jul/2007:18:09:24 +0200] [Job 20] Option: PreFilter=No --> Setting option
> D [02/Jul/2007:18:09:24 +0200] [Job 20] Found: %%BeginFeature: *Resolution default
> D [02/Jul/2007:18:09:24 +0200] [Job 20] Option: Resolution=default --> Setting option
> D [02/Jul/2007:18:09:24 +0200] [Job 20] Found: %% FoomaticRIPOptionSetting: Resolution=default
> D [02/Jul/2007:18:09:24 +0200] [Job 20] Option: Resolution=default --> Setting option
> D [02/Jul/2007:18:09:24 +0200] [Job 20] Found: %%BeginFeature: *Duplex Notcapable
> D [02/Jul/2007:18:09:24 +0200] [Job 20] Option: Duplex=Notcapable --> Setting option
> D [02/Jul/2007:18:09:24 +0200] [Job 20] Found: %% FoomaticRIPOptionSetting: Duplex=Notcapable
> D [02/Jul/2007:18:09:24 +0200] [Job 20] Option: Duplex=Notcapable --> Setting option
> D [02/Jul/2007:18:09:24 +0200] [Job 20] Found: %%BeginFeature: *Duplex None
> D [02/Jul/2007:18:09:24 +0200] [Job 20] Option: Duplex=None --> Setting option
> D [02/Jul/2007:18:09:24 +0200] [Job 20] Found: %%BeginFeature: *BitsPerPixel None
> D [02/Jul/2007:18:09:24 +0200] [Job 20] Unknown option BitsPerPixel=None found in the job
> D [02/Jul/2007:18:09:24 +0200] [Job 20] Found: %%BeginFeature: *Smoothing False
> D [02/Jul/2007:18:09:24 +0200] [Job 20] Unknown option Smoothing=False found in the job
> D [02/Jul/2007:18:09:24 +0200] [Job 20] Found: %%BeginFeature: *OutputOrder Normal
> D [02/Jul/2007:18:09:24 +0200] [Job 20] Unknown option OutputOrder=Normal found in the job
> D [02/Jul/2007:18:09:24 +0200] [Job 20] Found: %%BeginFeature: *TraySwitch False
> D [02/Jul/2007:18:09:24 +0200] [Job 20] Unknown option TraySwitch=False found in the job
> D [02/Jul/2007:18:09:24 +0200] [Job 20] Found: %%BeginFeature: *PageSize A4
> D [02/Jul/2007:18:09:24 +0200] [Job 20] Option: PageSize=A4 --> Option will be set by PostScript interpreter
> D [02/Jul/2007:18:09:24 +0200] [Job 20] Found: %%BeginFeature: *InstalledMemory 4Meg
> D [02/Jul/2007:18:09:24 +0200] [Job 20] Unknown option InstalledMemory=4Meg found in the job
> D [02/Jul/2007:18:09:24 +0200] [Job 20] Found: %%BeginFeature: *OptionalCassette1 False
> D [02/Jul/2007:18:09:24 +0200] [Job 20] Unknown option OptionalCassette1=False found in the job
> D [02/Jul/2007:18:09:24 +0200] [Job 20] Found: %%BeginFeature: *OptionalDuplexer False
> D [02/Jul/2007:18:09:24 +0200] [Job 20] Unknown option OptionalDuplexer=False found in the job
> D [02/Jul/2007:18:09:24 +0200] [Job 20] Found: %%BeginFeature: *Resolution 600dpi
> D [02/Jul/2007:18:09:24 +0200] [Job 20] Option: Resolution=600dpi --> Invalid option setting found in job
> D [02/Jul/2007:18:09:24 +0200] [Job 20] Found: %%EndSetup
> D [02/Jul/2007:18:09:24 +0200] [Job 20] Inserting PostScript code for CUPS' page accounting
> D [02/Jul/2007:18:09:24 +0200] [Job 20]
> D [02/Jul/2007:18:09:25 +0200] [Job 20] -----------
> D [02/Jul/2007:18:09:25 +0200] [Job 20] New page:  1 1
> D [02/Jul/2007:18:09:25 +0200] [Job 20] Inserting option code into "PageSetup" section.
> D [02/Jul/2007:18:09:25 +0200] [Job 20]
> D [02/Jul/2007:18:09:25 +0200] [Job 20] Found: %%BeginPageSetup
> D [02/Jul/2007:18:09:25 +0200] [Job 20] Found: %%EndPageSetup
> D [02/Jul/2007:18:09:25 +0200] [Job 20] End of page header
> D [02/Jul/2007:18:09:25 +0200] [Job 20]
> D [02/Jul/2007:18:09:25 +0200] [Job 20] Found: %%BeginPageSetup
> D [02/Jul/2007:18:09:25 +0200] [Job 20] Found: %%EndPageSetup
> D [02/Jul/2007:18:09:25 +0200] [Job 20] End of page header
> D [02/Jul/2007:18:09:25 +0200] [Job 20] Stopping search for page header options
> D [02/Jul/2007:18:09:25 +0200] [Job 20] Found:
> D [02/Jul/2007:18:09:25 +0200] [Job 20] O N 363 658 M 397 656 I 404 636 I 371 638 I 363 658 I C
> D [02/Jul/2007:18:09:25 +0200] [Job 20] --> Output goes directly to the renderer now.
> D [02/Jul/2007:18:09:25 +0200] [Job 20]
> D [02/Jul/2007:18:09:25 +0200] [Job 20]
> D [02/Jul/2007:18:09:25 +0200] [Job 20] Starting renderer
> D [02/Jul/2007:18:09:25 +0200] [Job 20]
> D [02/Jul/2007:18:09:25 +0200] [Job 20] Closing renderer
> D [02/Jul/2007:18:09:25 +0200] [Job 20] renderer PID kid4=7552
> D [02/Jul/2007:18:09:25 +0200] [Job 20] renderer command: level=0; printf "%%!\n%%%% %%%%\n<</Duplex false>>setpagedevice\n";
> if (( $level > 0 )); then if (( $level < 99 )); then level=" -dLanguageLevel=$level"; else level=""; fi; gs -q -dPARANOIDSAFER
>  -dNOPAUSE -dBATCH -sDEVICE=pswrite$level -sOutputFile=- -; else cat; fi
> D [02/Jul/2007:18:09:25 +0200] [Job 20] JCL: <job data>
> D [02/Jul/2007:18:09:25 +0200] [Job 20]
> D [02/Jul/2007:18:09:25 +0200] [Job 20] KID3 exited with status 0
> D [02/Jul/2007:18:09:25 +0200] [Job 20] KID4 exited with status 9
> D [02/Jul/2007:18:09:25 +0200] [Job 20] Renderer exit stat: 9
> D [02/Jul/2007:18:09:25 +0200] [Job 20] Process dying with "error closing *main::STDOUT", exit stat: 9
> D [02/Jul/2007:18:09:25 +0200] [Job 20] error: Broken pipe (32)
> D [02/Jul/2007:18:09:25 +0200] [Job 20] error closing *main::STDOUT
> D [02/Jul/2007:18:09:25 +0200] [Job 20] KID3 finished
> D [02/Jul/2007:18:09:25 +0200] [Job 20] Renderer process finished
> D [02/Jul/2007:18:09:25 +0200] [Job 20] Killing process 7551 (KID3)
> D [02/Jul/2007:18:09:25 +0200] [Job 20] Process dying with "Error closing renderer", exit stat: 9
> D [02/Jul/2007:18:09:25 +0200] [Job 20] error: Bad file descriptor (9)
> D [02/Jul/2007:18:09:25 +0200] [Job 20] Error closing renderer
> D [02/Jul/2007:18:09:27 +0200] [Job 20] File 0 is complete.
> I [02/Jul/2007:18:09:27 +0200] [Job 20] Backend returned status 13 (unknown)
> d [02/Jul/2007:18:09:27 +0200] cupsdCheckJobs: Job 20: state_value=6, loaded=yes
> d [02/Jul/2007:18:09:33 +0200] cupsdCheckJobs: Job 20: state_value=6, loaded=yes
> d [02/Jul/2007:18:09:43 +0200] cupsdCheckJobs: Job 20: state_value=6, loaded=yes
> d [02/Jul/2007:18:09:53 +0200] cupsdCheckJobs: Job 20: state_value=6, loaded=yes
> d [02/Jul/2007:18:10:03 +0200] cupsdCheckJobs: Job 20: state_value=6, loaded=yes
> d [02/Jul/2007:18:10:13 +0200] cupsdCheckJobs: Job 20: state_value=6, loaded=yes
> d [02/Jul/2007:18:10:23 +0200] cupsdCheckJobs: Job 20: state_value=6, loaded=yes
> d [02/Jul/2007:18:10:33 +0200] cupsdCheckJobs: Job 20: state_value=6, loaded=no
> d [02/Jul/2007:18:10:43 +0200] cupsdCheckJobs: Job 20: state_value=6, loaded=yes
> d [02/Jul/2007:18:10:53 +0200] cupsdCheckJobs: Job 20: state_value=6, loaded=yes
> d [02/Jul/2007:18:11:04 +0200] cupsdCheckJobs: Job 20: state_value=6, loaded=yes
> d [02/Jul/2007:18:11:14 +0200] cupsdCheckJobs: Job 20: state_value=6, loaded=yes
> d [02/Jul/2007:18:11:24 +0200] cupsdCheckJobs: Job 20: state_value=6, loaded=yes
> d [02/Jul/2007:18:11:34 +0200] cupsdCheckJobs: Job 20: state_value=6, loaded=no
> d [02/Jul/2007:18:11:45 +0200] cupsdCheckJobs: Job 20: state_value=6, loaded=yes
> d [02/Jul/2007:18:11:55 +0200] cupsdCheckJobs: Job 20: state_value=6, loaded=yes
> 
> 
> "strace -f  -e trace=file" (Only the process which breaks):
> 
> Process 7552 attached
> [pid  7552] --- SIGPIPE (Broken pipe) @ 0 (0) ---
> [pid  7552] --- SIGPIPE (Broken pipe) @ 0 (0) ---
> [pid  7552] --- SIGPIPE (Broken pipe) @ 0 (0) ---
> [pid  7552] --- SIGPIPE (Broken pipe) @ 0 (0) ---
> [pid  7552] --- SIGPIPE (Broken pipe) @ 0 (0) ---
> [pid  7552] --- SIGPIPE (Broken pipe) @ 0 (0) ---
> [pid  7552] --- SIGPIPE (Broken pipe) @ 0 (0) ---
> [pid  7552] --- SIGPIPE (Broken pipe) @ 0 (0) ---
> [pid  7552] --- SIGPIPE (Broken pipe) @ 0 (0) ---
> [pid  7552] --- SIGPIPE (Broken pipe) @ 0 (0) ---
> [pid  7552] --- SIGPIPE (Broken pipe) @ 0 (0) ---
> [pid  7552] --- SIGPIPE (Broken pipe) @ 0 (0) ---
> [pid  7552] --- SIGPIPE (Broken pipe) @ 0 (0) ---
> [pid  7552] --- SIGPIPE (Broken pipe) @ 0 (0) ---
> [pid  7552] --- SIGPIPE (Broken pipe) @ 0 (0) ---
> Process 7552 detached
> 
> strace -f  (Only the process which breaks):
> 
> [pid  7660] clone(Process 7661 attached
> child_stack=0, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0xb7e04708) = 7661
> [pid  7660] write(2, "renderer PID kid4=7661\n", 23 <unfinished ...>
> [pid  7022] read(11, "renderer PID kid4=7661\n", 1023) = 23
> [pid  7661] getppid( <unfinished ...>
> [pid  7661] <... getppid resumed> )     = 7660
> [pid  7661] close(8 <unfinished ...>
> [pid  7661] <... close resumed> )       = 0
> [pid  7661] close(6 <unfinished ...>
> [pid  7661] <... close resumed> )       = 0
> [pid  7661] write(2, "JCL: <job data> \n\n", 18 <unfinished ...>
> [pid  7661] <... write resumed> )       = 18
> [pid  7661] read(7,  <unfinished ...>
> [pid  7661] <... read resumed> "%!\n", 4096) = 3
> [pid  7661] write(1, "%!\n", 3 <unfinished ...>
> [pid  7661] <... write resumed> )       = -1 EPIPE (Broken pipe)
> [pid  7661] --- SIGPIPE (Broken pipe) @ 0 (0) ---
> [pid  7661] read(7,  <unfinished ...>
> [pid  7661] <... read resumed> "%% %%\n<</Duplex false>>setpagede"..., 4096) = 37
> [pid  7661] read(7,  <unfinished ...>
> [pid  7661] <... read resumed> "%!PS-Adobe-3.0\n%%Title: Testseit"..., 4096) = 4096
> [pid  7661] write(1, "%% %%\n<</Duplex false>>setpagede"..., 4096) = -1 EPIPE (Broken pipe)
> [pid  7661] --- SIGPIPE (Broken pipe) @ 0 (0) ---
> [pid  7661] read(7,  <unfinished ...>
> [pid  7661] <... read resumed> "f}bind def end version cvi 2016 "..., 4096) = 4096
> [pid  7661] read(7,  <unfinished ...>
> [pid  7661] <... read resumed> "endering{~ buildcrdname ~\r\n/Colo"..., 4096) = 4096
> [pid  7661] write(1, "rinter VM ]%%)= true FatalErrorI"..., 4096) = -1 EPIPE (Broken pipe)
> [pid  7661] --- SIGPIPE (Broken pipe) @ 0 (0) ---
> [pid  7661] write(1, "peat ! cvn 3 1 $ ! ! E}b/definec"..., 4096) = -1 EPIPE (Broken pipe)
> [pid  7661] --- SIGPIPE (Broken pipe) @ 0 (0) ---
> [pid  7661] read(7,  <unfinished ...>
> [pid  7661] <... read resumed> "igher\n\tcurrentglobal true setglo"..., 4096) = 4096
> [pid  7661] write(1, "evel2\n{\t\t\t\t\t% in case of level 2"..., 4096) = -1 EPIPE (Broken pipe)
> [pid  7661] --- SIGPIPE (Broken pipe) @ 0 (0) ---
> [pid  7661] read(7,  <unfinished ...>
> [pid  7661] <... read resumed> "zontal makehatch}b/h1{/h1/HS_Ver"..., 4096) = 4096
> [pid  7661] write(1, "tore ~ U ~ 2 ^ put}b/h0{/h0\r\n/HS"..., 4096) = -1 EPIPE (Broken pipe)
> [pid  7661] --- SIGPIPE (Broken pipe) @ 0 (0) ---
> [pid  7661] read(7,  <unfinished ...>
> [pid  7661] <... read resumed> " O N 606 864 M 604 859 I 602 858"..., 4096) = 4096
> [pid  7661] read(7,  <unfinished ...>
> [pid  7661] <... read resumed> "5 I 576 885 I 578 886 I 579 886 "..., 4096) = 4096
> [pid  7661] write(1, " I 525 850 I 524 850 I 522 849 I"..., 4096) = -1 EPIPE (Broken pipe)
> [pid  7661] --- SIGPIPE (Broken pipe) @ 0 (0) ---
> [pid  7661] read(7,  <unfinished ...>
> [pid  7661] <... read resumed> "832 I 354 833 I 353 833 I 352 83"..., 4096) = 4096
> [pid  7661] write(1, " 574 881 I 575 883 I 575 884 I 5"..., 4096) = -1 EPIPE (Broken pipe)
> [pid  7661] --- SIGPIPE (Broken pipe) @ 0 (0) ---
> [pid  7661] read(7,  <unfinished ...>
> [pid  7661] <... read resumed> "9 I 538 458 I 539 458 I C \r\n O N"..., 4096) = 4096
> [pid  7661] write(1, " I 359 830 I 356 830 I 356 831 I"..., 4096) = -1 EPIPE (Broken pipe)
> [pid  7661] --- SIGPIPE (Broken pipe) @ 0 (0) ---
> [pid  7661] read(7,  <unfinished ...>
> [pid  7661] <... read resumed> "43 I 327 543 I C \r\n O N 337 553 "..., 4096) = 4096
> [pid  7661] write(1, " 539 458 M 550 429 I 550 429 I 5"..., 4096) = -1 EPIPE (Broken pipe)
> [pid  7661] --- SIGPIPE (Broken pipe) @ 0 (0) ---
> [pid  7661] write(1, "M 342 542 I 342 541 I 342 541 I "..., 4096) = -1 EPIPE (Broken pipe)
> [pid  7661] --- SIGPIPE (Broken pipe) @ 0 (0) ---
> [pid  7661] read(7,  <unfinished ...>
> [pid  7661] <... read resumed> "th add dict `{1 ^/FID ne{d}{! !}"..., 4096) = 4096
> [pid  7661] write(1, "12557 1 0 0]d}if}b/copyfont{1 ^\r"..., 4096) = -1 EPIPE (Broken pipe)
> [pid  7661] --- SIGPIPE (Broken pipe) @ 0 (0) ---
> [pid  7661] read(7,  <unfinished ...>
> [pid  7661] <... read resumed> "acircumflex/atilde/adieresis/ari"..., 4096) = 4096
> [pid  7661] read(7,  <unfinished ...>
> [pid  7661] <... read resumed> "th flattenpath\r\npathbbox setcach"..., 4096) = 4096
> [pid  7661] write(1, "ute/Thorn/germandbls\r\n/agrave/aa"..., 4096) = -1 EPIPE (Broken pipe)
> [pid  7661] --- SIGPIPE (Broken pipe) @ 0 (0) ---
> [pid  7661] write(1, "h newpath 0 0 moveto Char true c"..., 4096) = -1 EPIPE (Broken pipe)
> [pid  7661] --- SIGPIPE (Broken pipe) @ 0 (0) ---
> [pid  7661] read(7,  <unfinished ...>
> [pid  7661] <... read resumed> "47 47 47 47 47 47 47 47 47 47 47"..., 4096) = 3434
> [pid  7661] read(7,  <unfinished ...>
> [pid  7660] waitpid(7661, Process 7660 suspended
> [pid  7661] <... read resumed> "", 4096) = 0
> [pid  7661] write(1, "0 PS)\n[47 47 47 47 47 47 47 47 4"..., 3471) = -1 EPIPE (Broken pipe)
> [pid  7661] --- SIGPIPE (Broken pipe) @ 0 (0) ---
> [pid  7661] close(1)                    = 0
> [pid  7661] close(7)                    = 0
> [pid  7661] close(4)                    = 0
> [pid  7661] write(5, "4 9\n", 4)        = 4
> [pid  7661] close(5)                    = 0
> [pid  7661] write(2, "Process dying with \"error closin"..., 88 <unfinished ...>
> [pid  7661] <... write resumed> )       = 88
> [pid  7661] write(2, "error closing *main::STDOUT\n", 28 <unfinished ...>
> [pid  7661] <... write resumed> )       = 28
> [pid  7661] _llseek(0, 34664, 0xbf8611a0, SEEK_SET) = -1 ESPIPE (Illegal seek)
> [pid  7661] _llseek(0, 34664, 0xbf861140, SEEK_SET) = -1 ESPIPE (Illegal seek)
> [pid  7661] exit_group(9)               = ?
> Process 7661 detached
> [pid  7660] <... waitpid resumed> [{WIFEXITED(s) && WEXITSTATUS(s) == 9}], 0) = 7661
> 
> 

You backend needs the permission to create the log file.
You did not specify in which directory your backend tries
to create the log file.

Either set the write permission for that directory so that your backend
can create a file there (I think in CUPS 1.2 the backend runs as user lp ?)
or make the backend script run as user root, or (as I think it is
a Perl script (deducing this estimate from the errror message),
change yourself temprarily to root to creat4e the log file.

Helge


-- 
Helge Blischke
Softwareentwicklung

H.Blischke at acm.org




More information about the cups mailing list