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

Tue May 11 14:52:55 PDT 2004

Glenn E. Sieb wrote:

> 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

Maybe it wont help you but I have few remarks on PDF backend.
- I had to change shell from sh to bash. My sh wasnt able to handle 
substitutions (like ${3//[^[:alnum:]]/_} ). I am not 
shell-scripting-guru so I dont know if this is normal or it is some bug 
in sh in freebsd ( even recompiling sh doesnt help ). Bash is working so 
I dont bother about that anymore :-).

- I had to add /usr/local/bin to PATH variable (ps2pdf is script too so 
it needs to know path to other executables and/or scripts)