[cups.general] PDF backend questions... Really long.. :-/

Tue May 11 11:23:48 PDT 2004

Hi guys.. 

I have Dax from GuruLabs' pdf script for running as a PDF Printer service on CUPS v1.1.20.0 running on FreeBSD 4.7....

I put 'sh -x' right after the shebang in the pdf script, and turned on "debug" level for the logs...

When I start the printer, it won't stay 'running'... :-/ At first I got:

D [11/May/2004:14:11:04 -0400] [Job 3] + OUTPUTFILENAME=
D [11/May/2004:14:11:04 -0400] [Job 3] /usr/local/libexec/cups/backend/pdf: 68: Syntax error: Bad substitution

So line 68 reads:

        OUTPUTFILENAME="$PDFDIR/$2-$PRINTTIME-${3//[^[:alnum:]]/_}.pdf"

So I ditched the ${3//... Bit and kept it $2-PRINTTIME.pdf just to make it simple. That got _that_ error to go away.

So then I get an error on line 80:

D [11/May/2004:14:16:11 -0400] [Job 3] /usr/local/libexec/cups/backend/pdf: 80:
Syntax error: Bad fd number

Line 80 is just "fi" but is at the end of this block of code:

# run ghostscript
if [ $# -eq 6 ]; then
        $PDFBIN $6 "$OUTPUTFILENAME"
#>& /dev/null
else
        $PDFBIN - "$OUTPUTFILENAME" >& /dev/null
fi

($PDFBIN is set to /usr/local/bin/ps2pdf, which is where it lives on FreeBSD)

So I go and restart cupsd, and try to print a test page... Here's the log:

D [11/May/2004:14:20:51 -0400] AcceptClient() 5 from lucy.corp.lumeta.com:631.
D [11/May/2004:14:20:51 -0400] ReadClient() 5 POST / HTTP/1.1
D [11/May/2004:14:20:51 -0400] ProcessIPPRequest: 5 status_code=0
D [11/May/2004:14:20:51 -0400] ReadClient() 5 POST / HTTP/1.1
D [11/May/2004:14:20:51 -0400] ProcessIPPRequest: 5 status_code=0
D [11/May/2004:14:20:51 -0400] CloseClient() 5
D [11/May/2004:14:20:53 -0400] AcceptClient() 5 from lucy.corp.lumeta.com:631.
D [11/May/2004:14:20:53 -0400] ReadClient() 5 POST /printers/pdfprinter HTTP/1.1
D [11/May/2004:14:20:54 -0400] print_job: auto-typing file...
D [11/May/2004:14:20:54 -0400] print_job: request file type is application/postscript.
D [11/May/2004:14:20:54 -0400] check_quotas: requesting-user-name = 'ges'
D [11/May/2004:14:20:54 -0400] print_job: requesting-user-name = 'ges'
D [11/May/2004:14:20:54 -0400] Adding default job-sheets values "none,none"...
I [11/May/2004:14:20:54 -0400] Adding start banner page "none" to job 4.
I [11/May/2004:14:20:54 -0400] Adding end banner page "none" to job 4.
I [11/May/2004:14:20:54 -0400] Job 4 queued on 'pdfprinter' by 'ges'.
D [11/May/2004:14:20:54 -0400] Job 4 hold_until = 0
D [11/May/2004:14:20:54 -0400] ProcessIPPRequest: 5 status_code=0
D [11/May/2004:14:20:54 -0400] CloseClient() 5

Ok--the printer is stopped--so let me go start it...

D [11/May/2004:14:21:45 -0400] AcceptClient() 5 from 65.246.246.82:631.
D [11/May/2004:14:21:45 -0400] ReadClient() 5 GET /admin/?op=start-printer&printer_name=pdfprinter HTTP/1.1
D [11/May/2004:14:21:45 -0400] CGI /usr/local/libexec/cups/cgi-bin/admin.cgi started - PID = 24224
I [11/May/2004:14:21:45 -0400] Started "/usr/local/libexec/cups/cgi-bin/admin.cgi" (pid=24224)
D [11/May/2004:14:21:45 -0400] SendCommand() 5 file=8
D [11/May/2004:14:21:45 -0400] AcceptClient() 7 from localhost:631.
D [11/May/2004:14:21:45 -0400] ReadClient() 7 POST /admin/ HTTP/1.1
D [11/May/2004:14:21:45 -0400] SendError() 7 code=401 (Unauthorized)
D [11/May/2004:14:21:45 -0400] AcceptClient() 9 from localhost:631.
D [11/May/2004:14:21:45 -0400] ReadClient() 9 POST /admin/ HTTP/1.1
I [11/May/2004:14:21:45 -0400] Saving printers.conf...
I [11/May/2004:14:21:45 -0400] Printer 'pdfprinter' started by 'root'.
D [11/May/2004:14:21:45 -0400] StartJob(3, 0x8096000)
D [11/May/2004:14:21:45 -0400] StartJob() id = 3, file = 0/1
D [11/May/2004:14:21:45 -0400] job-sheets=none,none
D [11/May/2004:14:21:45 -0400] banner_page = 0
D [11/May/2004:14:21:45 -0400] StartJob: argv = "pdfprinter","3","ges","Test Page","1","","/var/spool/cups/d00003-001"
D [11/May/2004:14:21:45 -0400] StartJob: envp[0]="PATH=/usr/local/libexec/cups/filter:/bin:/usr/bin"
D [11/May/2004:14:21:45 -0400] StartJob: envp[1]="SOFTWARE=CUPS/1.1"
D [11/May/2004:14:21:45 -0400] StartJob: envp[2]="USER=root"
D [11/May/2004:14:21:45 -0400] StartJob: envp[3]="CHARSET=iso-8859-1"
D [11/May/2004:14:21:45 -0400] StartJob: envp[4]="LANG=en"
D [11/May/2004:14:21:45 -0400] StartJob: envp[5]="PPD=/usr/local/etc/cups/ppd/pdfprinter.ppd"
D [11/May/2004:14:21:45 -0400] StartJob: envp[6]="CUPS_SERVERROOT=/usr/local/etc/cups"
D [11/May/2004:14:21:45 -0400] StartJob: envp[7]="RIP_MAX_CACHE=8m"
D [11/May/2004:14:21:45 -0400] StartJob: envp[8]="TMPDIR=/var/spool/cups/tmp"
D [11/May/2004:14:21:45 -0400] StartJob: envp[9]="CONTENT_TYPE=application/postscript"
D [11/May/2004:14:21:45 -0400] StartJob: envp[10]="DEVICE_URI=pdf:/home/pdfdropbox"
D [11/May/2004:14:21:45 -0400] StartJob: envp[11]="PRINTER=pdfprinter"
D [11/May/2004:14:21:45 -0400] StartJob: envp[12]="CUPS_DATADIR=/usr/local/share/cups"
D [11/May/2004:14:21:45 -0400] StartJob: envp[13]="CUPS_FONTPATH=/usr/local/share/cups/fonts"
D [11/May/2004:14:21:45 -0400] StartJob: envp[14]="CUPS_SERVER=localhost"
D [11/May/2004:14:21:45 -0400] StartJob: envp[15]="IPP_PORT=631"
D [11/May/2004:14:21:45 -0400] StartJob: statusfds = [ 10 11 ]
D [11/May/2004:14:21:45 -0400] StartJob: filterfds[1] = [ 12 -1 ]
D [11/May/2004:14:21:45 -0400] StartJob: filter = "/usr/local/libexec/cups/filter/pstops"
D [11/May/2004:14:21:45 -0400] StartJob: filterfds[0] = [ 13 14 ]
D [11/May/2004:14:21:45 -0400] start_process("/usr/local/libexec/cups/filter/pstops", 0xbfbf0fb0, 0xbfbf0320, 12, 14, 11)
I [11/May/2004:14:21:45 -0400] Started filter /usr/local/libexec/cups/filter/pstops (PID 24225) for job 3.
D [11/May/2004:14:21:45 -0400] StartJob: backend = "/usr/local/libexec/cups/backend/pdf"
D [11/May/2004:14:21:45 -0400] StartJob: filterfds[1] = [ -1 12 ]
D [11/May/2004:14:21:45 -0400] start_process("/usr/local/libexec/cups/backend/pdf", 0xbfbf0fb0, 0xbfbf0320, 13, 12, 11)
I [11/May/2004:14:21:45 -0400] Started backend /usr/local/libexec/cups/backend/pdf (PID 24226) for job 3.
D [11/May/2004:14:21:45 -0400] ProcessIPPRequest: 9 status_code=0
D [11/May/2004:14:21:45 -0400] AcceptClient() 11 from 65.246.246.82:631.
D [11/May/2004:14:21:45 -0400] ReadClient() 11 GET /cups.css HTTP/1.1
D [11/May/2004:14:21:45 -0400] SendFile() 11 file=12
D [11/May/2004:14:21:45 -0400] CloseClient() 9
D [11/May/2004:14:21:45 -0400] [Job 3] Page = 612x792; 0,0 to 612,792
D [11/May/2004:14:21:45 -0400] [Job 3] /usr/local/libexec/cups/backend/pdf: 80: Syntax error: Bad fd number
E [11/May/2004:14:21:45 -0400] PID 24226 stopped with status 2!
D [11/May/2004:14:21:45 -0400] [Job 3] Skipping PJL header...
D [11/May/2004:14:21:45 -0400] [Job 3] slowcollate=0, slowduplex=0, sloworder=0
D [11/May/2004:14:21:45 -0400] [Job 3] 0 %%Title: Test Page
D [11/May/2004:14:21:45 -0400] [Job 3] 0 %%Creator: PScript5.dll Version 5.2
D [11/May/2004:14:21:45 -0400] [Job 3] 0 %%CreationDate: 5/11/2004 13:19:39
D [11/May/2004:14:21:45 -0400] [Job 3] 0 %%For: ges
D [11/May/2004:14:21:45 -0400] [Job 3] 0 %%BoundingBox: (atend)
D [11/May/2004:14:21:45 -0400] [Job 3] 0 %%DocumentNeededResources: (atend)
D [11/May/2004:14:21:45 -0400] [Job 3] 0 %%DocumentSuppliedResources: (atend)
D [11/May/2004:14:21:45 -0400] [Job 3] 0 %%DocumentData: Clean7Bit
D [11/May/2004:14:21:45 -0400] [Job 3] 0 %%TargetDevice: (HP Color LaserJet 4550 ) (3010.107) 0
D [11/May/2004:14:21:45 -0400] [Job 3] 0 %%LanguageLevel: 3
D [11/May/2004:14:21:45 -0400] [Job 3] 0 %%EndComments
D [11/May/2004:14:21:45 -0400] [Job 3] 0 %%BeginDefaults
D [11/May/2004:14:21:45 -0400] [Job 3] 0 %%ViewingOrientation: 1 0 0 1
D [11/May/2004:14:21:45 -0400] [Job 3] 0 %%EndDefaults
D [11/May/2004:14:21:45 -0400] [Job 3] 0 %%BeginProlog
D [11/May/2004:14:21:45 -0400] [Job 3] 0 %%BeginResource: file Pscript_WinNT_ErrorHandler 5.0 0
D [11/May/2004:14:21:45 -0400] [Job 3] 0 %%EndResource
D [11/May/2004:14:21:45 -0400] [Job 3] 0 %%BeginResource: file Pscript_FatalError 5.0 0
D [11/May/2004:14:21:45 -0400] [Job 3] 0 %%EndResource
D [11/May/2004:14:21:45 -0400] [Job 3] 0 %%BeginResource: file Pscript_Win_Basic 5.0 0
D [11/May/2004:14:21:45 -0400] [Job 3] 0 %%EndResource
D [11/May/2004:14:21:45 -0400] [Job 3] 0 %%BeginResource: file Pscript_Win_Utils_L2 5.0 0
D [11/May/2004:14:21:45 -0400] [Job 3] 0 %%EndResource
D [11/May/2004:14:21:45 -0400] [Job 3] 0 %%EndProlog
D [11/May/2004:14:21:45 -0400] [Job 3] 0 %%BeginSetup
D [11/May/2004:14:21:45 -0400] [Job 3] 0 %%BeginNonPPDFeature: JobTimeout 0
D [11/May/2004:14:21:45 -0400] [Job 3] 0 %%EndNonPPDFeature
D [11/May/2004:14:21:45 -0400] [Job 3] 0 %%BeginNonPPDFeature: WaitTimeout 300
D [11/May/2004:14:21:45 -0400] [Job 3] 0 %%EndNonPPDFeature
D [11/May/2004:14:21:45 -0400] [Job 3] 0 %%BeginFeature: *HPPaperPolicy PromptUser
D [11/May/2004:14:21:45 -0400] [Job 3] 0 %%EndFeature
D [11/May/2004:14:21:45 -0400] [Job 3] 0 %%BeginFeature: *Collate False
D [11/May/2004:14:21:45 -0400] [Job 3] 0 %%EndFeature
D [11/May/2004:14:21:45 -0400] [Job 3] 0 %%BeginFeature: *SpotTag True
D [11/May/2004:14:21:45 -0400] [Job 3] 0 %%EndFeature
D [11/May/2004:14:21:45 -0400] [Job 3] 0 %%BeginFeature: *HPColorasGray False
D [11/May/2004:14:21:45 -0400] [Job 3] 0 %%EndFeature
D [11/May/2004:14:21:45 -0400] [Job 3] 0 %%BeginFeature: *PageSize Letter
D [11/May/2004:14:21:45 -0400] [Job 3] 0 %%EndFeature
D [11/May/2004:14:21:45 -0400] [Job 3] 0 %%BeginFeature: *PrintFinish Matte
D [11/May/2004:14:21:45 -0400] [Job 3] 0 %%EndFeature
D [11/May/2004:14:21:45 -0400] [Job 3] 0 %%BeginFeature: *MediaType None
D [11/May/2004:14:21:45 -0400] [Job 3] 0 %%EndFeature
D [11/May/2004:14:21:45 -0400] [Job 3] 0 %%BeginFeature: *Duplex None
D [11/May/2004:14:21:45 -0400] [Job 3] 0 %%EndFeature
D [11/May/2004:14:21:45 -0400] [Job 3] 0 %%BeginFeature: *ColorSmart Automatic
D [11/May/2004:14:21:45 -0400] [Job 3] 0 %%EndFeature
D [11/May/2004:14:21:45 -0400] [Job 3] 0 %%BeginFeature: *CSText MatchDetail
D [11/May/2004:14:21:45 -0400] [Job 3] 0 %%EndFeature
D [11/May/2004:14:21:45 -0400] [Job 3] 0 %%BeginFeature: *CSGraphics MatchSmooth
D [11/May/2004:14:21:45 -0400] [Job 3] 0 %%EndFeature
D [11/May/2004:14:21:45 -0400] [Job 3] 0 %%BeginFeature: *CSImage MatchSmooth
D [11/May/2004:14:21:45 -0400] [Job 3] 0 %%EndFeature
D [11/May/2004:14:21:45 -0400] [Job 3] 0 %%BeginFeature: *CMYKInks FAST
D [11/May/2004:14:21:45 -0400] [Job 3] 0 %%EndFeature
D [11/May/2004:14:21:45 -0400] [Job 3] 0 %%BeginFeature: *HPPrinterModelName HP_Color_LaserJet_4550_PS
D [11/May/2004:14:21:45 -0400] [Job 3] 0 %%EndFeature
D [11/May/2004:14:21:45 -0400] [Job 3] 0 %%BeginFeature: *JRConstraints JRCHDFull
D [11/May/2004:14:21:45 -0400] [Job 3] 0 %%EndFeature
D [11/May/2004:14:21:45 -0400] [Job 3] 0 %%BeginFeature: *Resolution 600dpi
D [11/May/2004:14:21:45 -0400] [Job 3] 0 %%EndFeature
D [11/May/2004:14:21:45 -0400] [Job 3] 0 %%BeginFeature: *Tray3 False
D [11/May/2004:14:21:45 -0400] [Job 3] 0 %%EndFeature
D [11/May/2004:14:21:45 -0400] [Job 3] 0 %%BeginFeature: *InstalledMemory 64-127MB
D [11/May/2004:14:21:45 -0400] [Job 3] 0 %%EndFeature
D [11/May/2004:14:21:45 -0400] [Job 3] 0 %%BeginFeature: *Duplexer False
D [11/May/2004:14:21:45 -0400] [Job 3] 0 %%EndFeature
D [11/May/2004:14:21:45 -0400] [Job 3] 0 %%BeginFeature: *PrinterHardDisk False
D [11/May/2004:14:21:45 -0400] [Job 3] 0 %%EndFeature
D [11/May/2004:14:21:45 -0400] [Job 3] 0 %%BeginFeature: *JobRetention False
D [11/May/2004:14:21:45 -0400] [Job 3] 0 %%EndFeature
D [11/May/2004:14:21:45 -0400] [Job 3] 0 %%EndSetup
D [11/May/2004:14:21:45 -0400] [Job 3] 0 %%EndPageComments
D [11/May/2004:14:21:45 -0400] [Job 3] 0 %%BeginPageSetup
D [11/May/2004:14:21:45 -0400] [Job 3] 0 %%EndPageSetup
D [11/May/2004:14:21:45 -0400] [Job 3] 0 %%BeginResource: file Pscript_Win_GdiObject 5.0 0
D [11/May/2004:14:21:45 -0400] [Job 3] 0 %%EndResource
D [11/May/2004:14:21:45 -0400] [Job 3] 0 %%BeginResource: file Pscript_Win_GdiObject_L3 5.0 0
D [11/May/2004:14:21:45 -0400] [Job 3] 0 %%EndResource
D [11/May/2004:14:21:45 -0400] [Job 3] 0 %%BeginResource: file Pscript_Text 5.0 0
D [11/May/2004:14:21:45 -0400] [Job 3] 0 %%EndResource
D [11/May/2004:14:21:45 -0400] [Job 3] 0 %%BeginResource: file Pscript_Encoding256 5.0 0
D [11/May/2004:14:21:45 -0400] [Job 3] 0 %%EndResource
D [11/May/2004:14:21:45 -0400] [Job 3] 0 %%IncludeResource: font Times-Roman
D [11/May/2004:14:21:45 -0400] [Job 3] 0 %%BeginResource: file Pscript_Win_Euro_L2 5.0 0
D [11/May/2004:14:21:45 -0400] [Job 3] 0 %%EndResource
D [11/May/2004:14:21:45 -0400] [Job 3] 0 %%BeginResource: file Pscript_T42Hdr 5.0 0
D [11/May/2004:14:21:45 -0400] [Job 3] 0 %%EndResource
D [11/May/2004:14:21:45 -0400] [Job 3] 0 %%PageTrailer
D [11/May/2004:14:21:45 -0400] [Job 3] 0 %%Trailer
D [11/May/2004:14:21:45 -0400] [Job 3] 0 %%DocumentNeededResources:
D [11/May/2004:14:21:45 -0400] [Job 3] 0 %%+ font Times-Roman
D [11/May/2004:14:21:45 -0400] [Job 3] 0 %%DocumentSuppliedResources:
D [11/May/2004:14:21:45 -0400] [Job 3] 0 %%+ procset Pscript_WinNT_ErrorHandler 5.0 0
D [11/May/2004:14:21:45 -0400] [Job 3] 0 %%+ procset Pscript_FatalError 5.0 0
D [11/May/2004:14:21:45 -0400] [Job 3] 0 %%+ procset Pscript_Win_Basic 5.0 0
D [11/May/2004:14:21:45 -0400] [Job 3] 0 %%+ procset Pscript_Win_Utils_L2 5.0 0
D [11/May/2004:14:21:45 -0400] [Job 3] 0 %%+ procset Pscript_Win_GdiObject 5.0 0
D [11/May/2004:14:21:45 -0400] [Job 3] 0 %%+ procset Pscript_Win_GdiObject_L3 5.0 0
D [11/May/2004:14:21:45 -0400] [Job 3] 0 %%+ procset Pscript_Text 5.0 0
D [11/May/2004:14:21:45 -0400] [Job 3] 0 %%+ procset Pscript_Encoding256 5.0 0
D [11/May/2004:14:21:45 -0400] [Job 3] 0 %%+ procset Pscript_Win_Euro_L2 5.0 0
D [11/May/2004:14:21:45 -0400] [Job 3] 0 %%+ procset Pscript_T42Hdr 5.0 0
D [11/May/2004:14:21:45 -0400] [Job 3] 0 %%EOF
D [11/May/2004:14:21:45 -0400] UpdateJob: job 3, file 0 is complete.
D [11/May/2004:14:21:45 -0400] StopJob: id = 3, force = 0
I [11/May/2004:14:21:45 -0400] Saving printers.conf...
D [11/May/2004:14:21:45 -0400] StopJob: printer state is 5
D [11/May/2004:14:21:45 -0400] ReadClient() 11 GET /favicon.ico HTTP/1.1
D [11/May/2004:14:21:45 -0400] SendError() 11 code=404 (Not Found)
D [11/May/2004:14:21:45 -0400] CloseClient() 11

I've googled, on this error 2! condition, to no avail... :-/ Can anyone help me figure out what's going on?

Thank you in advance!
Glenn
-- 
Glenn E. Sieb
System Administrator
Lumeta Corporation
+1 732 357-3514 (V)
+1 732 564-0731 (Fax) 