cupsd can't execute installed filter

Chris nobody at noway.non
Thu Oct 5 19:18:50 PDT 2006 

I've just tried to do printing with gentoo, and am a little baffled by
what I see. I can't seem to print postscript files.  Here is a little run-down:

  - I have an old hp deskjet 842C. 
  - As of right now, I am using HP DeskJet 842C - CUPS+Gimp-Print
    v4.2.7.
  - I can print the test page from the web interface, but not the same
    page from the command line. 
  - I can also print files generated by Gimp, when using their DeskJet
    842c printer setting. 
  - Looking at the error log, I find that some of the filters are
    puking, saying that they can't be executed, but permissions are
    fine on the filters.
  - The ppd _IS_ in the right place, although the logs say it can't be
    loaded

argv is showing different parameters for the same file, so there must
be something being called when the document is submitted from the web
that isn't when I submit a file from OpenOffice or the command line. I
have a feeling that I am missing something obvious, so if anyone has a
more rested mind than mine, and could point out what I am missing, I
would greatly appreciate it.

I'm including two sections of the error log.  The first section is after
it fails printing with the command line, and the second section is
after printing fine through the web based
interface. 

/usr/share/cups/data/testprint.ps

D [05/Oct/2006:21:49:46 -0400] print_job: auto-typing file...
D [05/Oct/2006:21:49:46 -0400] print_job: request file type is application/postscript.
D [05/Oct/2006:21:49:46 -0400] check_quotas: requesting-user-name = 'root'
D [05/Oct/2006:21:49:46 -0400] print_job: requesting-user-name = 'root'
I [05/Oct/2006:21:49:46 -0400] Adding start banner page "none" to job 43.
I [05/Oct/2006:21:49:46 -0400] Adding end banner page "none" to job 43.
I [05/Oct/2006:21:49:46 -0400] Job 43 queued on 'DeskJet_840C' by 'root'.
D [05/Oct/2006:21:49:46 -0400] Job 43 hold_until = 0
D [05/Oct/2006:21:49:46 -0400] StartJob(43, 0x8096150)
D [05/Oct/2006:21:49:46 -0400] StartJob() id = 43, file = 0/1
D [05/Oct/2006:21:49:46 -0400] job-sheets=none,none
D [05/Oct/2006:21:49:46 -0400] banner_page = 0
D [05/Oct/2006:21:49:46 -0400] StartJob: argv = "DeskJet_840C","43","root","testprint.ps","1","PrintoutMode=Draft.Gray","/var/spool/cups/d00043-001"
D [05/Oct/2006:21:49:46 -0400] StartJob: envp[0]="PATH=/usr/lib/cups/filter:/bin:/usr/bin"
D [05/Oct/2006:21:49:46 -0400] StartJob: envp[1]="SOFTWARE=CUPS/1.1"
D [05/Oct/2006:21:49:46 -0400] StartJob: envp[2]="USER=root"
D [05/Oct/2006:21:49:46 -0400] StartJob: envp[3]="CHARSET=utf-8"
D [05/Oct/2006:21:49:46 -0400] StartJob: envp[4]="LANG=en_US"
D [05/Oct/2006:21:49:46 -0400] StartJob: envp[5]="PPD=/etc/cups/ppd/DeskJet_840C.ppd"
D [05/Oct/2006:21:49:46 -0400] StartJob: envp[6]="CUPS_SERVERROOT=/etc/cups"
D [05/Oct/2006:21:49:46 -0400] StartJob: envp[7]="RIP_MAX_CACHE=8m"
D [05/Oct/2006:21:49:46 -0400] StartJob: envp[8]="TMPDIR=/var/spool/cups/tmp"
D [05/Oct/2006:21:49:46 -0400] StartJob: envp[9]="CONTENT_TYPE=application/postscript"
D [05/Oct/2006:21:49:46 -0400] StartJob: envp[10]="DEVICE_URI=usb://HP/DeskJet%20840C?serial=CN04L1N1TFLB"
D [05/Oct/2006:21:49:46 -0400] StartJob: envp[11]="PRINTER=DeskJet_840C"
D [05/Oct/2006:21:49:46 -0400] StartJob: envp[12]="CUPS_DATADIR=/usr/share/cups"
D [05/Oct/2006:21:49:46 -0400] StartJob: envp[13]="CUPS_FONTPATH=/usr/share/cups/fonts"
D [05/Oct/2006:21:49:46 -0400] StartJob: envp[14]="CUPS_SERVER=localhost"
D [05/Oct/2006:21:49:46 -0400] StartJob: envp[15]="IPP_PORT=631"
D [05/Oct/2006:21:49:46 -0400] StartJob: statusfds = [ 5 10 ]
D [05/Oct/2006:21:49:46 -0400] StartJob: filterfds[1] = [ 11 -1 ]
D [05/Oct/2006:21:49:46 -0400] StartJob: filter = "/usr/lib/cups/filter/pstops"
D [05/Oct/2006:21:49:46 -0400] StartJob: filterfds[0] = [ 12 13 ]
D [05/Oct/2006:21:49:46 -0400] start_process("/usr/lib/cups/filter/pstops", 0xbfbfae30, 0xbfbfa1a0, 11, 13, 10)
I [05/Oct/2006:21:49:46 -0400] Started filter /usr/lib/cups/filter/pstops (PID 9484) for job 43.
D [05/Oct/2006:21:49:46 -0400] StartJob: filter = "/usr/lib/cups/filter/pstoraster"
D [05/Oct/2006:21:49:46 -0400] StartJob: filterfds[1] = [ 11 14 ]
D [05/Oct/2006:21:49:46 -0400] start_process("/usr/lib/cups/filter/pstoraster", 0xbfbfae30, 0xbfbfa1a0, 12, 14, 10)
I [05/Oct/2006:21:49:46 -0400] Started filter /usr/lib/cups/filter/pstoraster (PID 9485) for job 43.
D [05/Oct/2006:21:49:46 -0400] StartJob: filter = "/usr/lib/cups/filter/rastertoprinter"
D [05/Oct/2006:21:49:46 -0400] StartJob: filterfds[0] = [ 12 13 ]
D [05/Oct/2006:21:49:46 -0400] start_process("/usr/lib/cups/filter/rastertoprinter", 0xbfbfae30, 0xbfbfa1a0, 11, 13, 10)
I [05/Oct/2006:21:49:46 -0400] Started filter /usr/lib/cups/filter/rastertoprinter (PID 9486) for job 43.
D [05/Oct/2006:21:49:46 -0400] StartJob: backend = "/usr/lib/cups/backend/usb"
D [05/Oct/2006:21:49:46 -0400] StartJob: filterfds[1] = [ -1 11 ]
D [05/Oct/2006:21:49:46 -0400] start_process("/usr/lib/cups/backend/usb", 0xbfbfae30, 0xbfbfa1a0, 12, 11, 10)
I [05/Oct/2006:21:49:46 -0400] Started backend /usr/lib/cups/backend/usb (PID 9487) for job 43.
D [05/Oct/2006:21:49:46 -0400] ProcessIPPRequest: 7 status_code=0
E [05/Oct/2006:21:49:46 -0400] PID 9485 stopped with status 126!
D [05/Oct/2006:21:49:46 -0400] [Job 43] /usr/lib/cups/filter/pstoraster: /usr/lib/cups/filter/pstoraster: cannot execute binary file
D [05/Oct/2006:21:49:46 -0400] [Job 43] slowcollate=0, slowduplex=0, sloworder=0
D [05/Oct/2006:21:49:46 -0400] [Job 43] 0 %%BoundingBox: 0 0 612 792
D [05/Oct/2006:21:49:46 -0400] [Job 43] 0 %%Pages: 1
D [05/Oct/2006:21:49:46 -0400] [Job 43] 0 %%LanguageLevel: 1
D [05/Oct/2006:21:49:46 -0400] [Job 43] 0 %%DocumentData: Clean7Bit
D [05/Oct/2006:21:49:46 -0400] [Job 43] 0 %%DocumentSuppliedResources: procset testprint/1.1
D [05/Oct/2006:21:49:46 -0400] [Job 43] 0 %%DocumentNeededResources: font Helvetica Helvetica-Bold Times-Roman
D [05/Oct/2006:21:49:46 -0400] [Job 43] 0 %%Creator: Michael Sweet, Easy Software Products
D [05/Oct/2006:21:49:46 -0400] [Job 43] 0 %%CreationDate: May 11, 1999
D [05/Oct/2006:21:49:46 -0400] [Job 43] 0 %%Title: Test Page
D [05/Oct/2006:21:49:46 -0400] [Job 43] 0 %%EndComments
D [05/Oct/2006:21:49:46 -0400] [Job 43] 0 %%BeginProlog
D [05/Oct/2006:21:49:46 -0400] [Job 43] 0 %%BeginResource procset testprint 1.1 0
D [05/Oct/2006:21:49:46 -0400] [Job 43] 0 %%EndResource
D [05/Oct/2006:21:49:46 -0400] [Job 43] 0 %%EndProlog
D [05/Oct/2006:21:49:46 -0400] [Job 43] 0 %%Page: 1 1
D [05/Oct/2006:21:49:46 -0400] [Job 43] 0 %%Page: 1 1
D [05/Oct/2006:21:49:46 -0400] [Job 43] pw = 576.0, pl = 720.0
D [05/Oct/2006:21:49:46 -0400] [Job 43] PageLeft = 18.0, PageRight = 594.0
D [05/Oct/2006:21:49:46 -0400] [Job 43] PageTop = 756.0, PageBottom = 36.0
D [05/Oct/2006:21:49:46 -0400] [Job 43] PageWidth = 612.0, PageLength = 792.0
D [05/Oct/2006:21:49:46 -0400] [Job 43] 0 %%EOF
D [05/Oct/2006:21:49:46 -0400] [Job 43] Saw EOF!
D [05/Oct/2006:21:49:46 -0400] CloseClient: 7
E [05/Oct/2006:21:49:46 -0400] [Job 43] Fatal error: Unable to load PPD file "/etc/cups/ppd/DeskJet_840C.ppd"!
E [05/Oct/2006:21:49:46 -0400] PID 9486 stopped with status 1!
D [05/Oct/2006:21:49:46 -0400] [Job 43] Printer using device file "/dev/usb/lp0"...
D [05/Oct/2006:21:49:46 -0400] [Job 43] LPGETSTATUS returned a port status of 18...
D [05/Oct/2006:21:49:46 -0400] UpdateJob: job 43, file 0 is complete.
D [05/Oct/2006:21:49:46 -0400] CancelJob: id = 43
D [05/Oct/2006:21:49:46 -0400] StopJob: id = 43, force = 0
D [05/Oct/2006:21:49:46 -0400] StopJob: printer state is 3






--------------------------------------------------------------------------------------------------------------
Here is the file passing through without a problem from the web interface.  
It is cut short, since it spans several pages in the log.


D [05/Oct/2006:17:20:43 -0400] StartJob() id = 41, file = 0/1 
D [05/Oct/2006:17:20:43 -0400] job-sheets=none,none 
D [05/Oct/2006:17:20:43 -0400] banner_page = 0 
D [05/Oct/2006:17:20:43 -0400] StartJob: argv = "DeskJet_840C","41","","Test Page","1","","/var/spool/cups/d00041-001" 
D [05/Oct/2006:17:20:43 -0400] StartJob: envp[0]="PATH=/usr/lib/cups/filter:/bin:/usr/bin" 
D [05/Oct/2006:17:20:43 -0400] StartJob: envp[1]="SOFTWARE=CUPS/1.1" 
D [05/Oct/2006:17:20:43 -0400] StartJob: envp[2]="USER=root" 
D [05/Oct/2006:17:20:43 -0400] StartJob: envp[3]="CHARSET=utf-8" 
D [05/Oct/2006:17:20:43 -0400] StartJob: envp[4]="LANG=en" 
D [05/Oct/2006:17:20:43 -0400] StartJob: envp[5]="PPD=/etc/cups/ppd/DeskJet_840C.ppd" 
D [05/Oct/2006:17:20:43 -0400] StartJob: envp[6]="CUPS_SERVERROOT=/etc/cups" 
D [05/Oct/2006:17:20:43 -0400] StartJob: envp[7]="RIP_MAX_CACHE=8m" 
D [05/Oct/2006:17:20:43 -0400] StartJob: envp[8]="TMPDIR=/var/spool/cups/tmp" 
D [05/Oct/2006:17:20:43 -0400] StartJob: envp[9]="CONTENT_TYPE=application/postscript" 
D [05/Oct/2006:17:20:43 -0400] StartJob: envp[10]="DEVICE_URI=usb://HP/DeskJet%20840C?serial=CN04L1N1TFLB" 
D [05/Oct/2006:17:20:43 -0400] StartJob: envp[11]="PRINTER=DeskJet_840C" 
D [05/Oct/2006:17:20:43 -0400] StartJob: envp[12]="CUPS_DATADIR=/usr/share/cups" 
D [05/Oct/2006:17:20:43 -0400] StartJob: envp[13]="CUPS_FONTPATH=/usr/share/cups/fonts" 
D [05/Oct/2006:17:20:43 -0400] StartJob: envp[14]="CUPS_SERVER=localhost" 
D [05/Oct/2006:17:20:43 -0400] StartJob: envp[15]="IPP_PORT=631" 
D [05/Oct/2006:17:20:43 -0400] StartJob: statusfds = [ 11 12 ] 
D [05/Oct/2006:17:20:43 -0400] StartJob: filterfds[1] = [ 13 -1 ] 
D [05/Oct/2006:17:20:43 -0400] StartJob: filter = "/usr/lib/cups/filter/pstops" 
D [05/Oct/2006:17:20:43 -0400] StartJob: filterfds[0] = [ 14 15 ] 
D [05/Oct/2006:17:20:43 -0400] start_process("/usr/lib/cups/filter/pstops", 0xbfbfae30, 0xbfbfa1a0, 13, 15, 12) 
I [05/Oct/2006:17:20:43 -0400] Started filter /usr/lib/cups/filter/pstops (PID 8481) for job 41. 
D [05/Oct/2006:17:20:43 -0400] StartJob: filter = "/usr/lib/cups/filter/pstoraster" 
D [05/Oct/2006:17:20:43 -0400] StartJob: filterfds[1] = [ 13 16 ] 
D [05/Oct/2006:17:20:43 -0400] start_process("/usr/lib/cups/filter/pstoraster", 0xbfbfae30, 0xbfbfa1a0, 14, 16, 12) 
I [05/Oct/2006:17:20:43 -0400] Started filter /usr/lib/cups/filter/pstoraster (PID 8482) for job 41. 
D [05/Oct/2006:17:20:43 -0400] StartJob: filter = "/usr/lib/cups/filter/rastertoprinter" 
D [05/Oct/2006:17:20:43 -0400] StartJob: filterfds[0] = [ 14 15 ] 
D [05/Oct/2006:17:20:43 -0400] start_process("/usr/lib/cups/filter/rastertoprinter", 0xbfbfae30, 0xbfbfa1a0, 13, 15, 12) 
I [05/Oct/2006:17:20:43 -0400] Started filter /usr/lib/cups/filter/rastertoprinter (PID 8483) for job 41. 
D [05/Oct/2006:17:20:43 -0400] StartJob: backend = "/usr/lib/cups/backend/usb" 
D [05/Oct/2006:17:20:43 -0400] StartJob: filterfds[1] = [ -1 13 ] 
D [05/Oct/2006:17:20:43 -0400] start_process("/usr/lib/cups/backend/usb", 0xbfbfae30, 0xbfbfa1a0, 14, 13, 12) 
I [05/Oct/2006:17:20:43 -0400] Started backend /usr/lib/cups/backend/usb (PID 8484) for job 41. 
D [05/Oct/2006:17:20:43 -0400] ProcessIPPRequest: 9 status_code=0 
D [05/Oct/2006:17:20:43 -0400] [Job 41] Running /usr/bin/gs -dQUIET -dDEBUG -dPARANOIDSAFER -dNOPAUSE -dBATCH -dNOMEDIAATTRS -sDEVICE=cups -sstdout=%stderr -sOUTPUTFILE=%stdout -c - 
D [05/Oct/2006:17:20:43 -0400] CloseClient: 9 
D [05/Oct/2006:17:20:43 -0400] [Job 41] Printer using device file "/dev/usb/lp0"... 
D [05/Oct/2006:17:20:43 -0400] [Job 41] LPGETSTATUS returned a port status of 18... 
D [05/Oct/2006:17:20:44 -0400] [Job 41] Page = 612x792; 18,33 to 594,792 
D [05/Oct/2006:17:20:44 -0400] [Job 41] slowcollate=0, slowduplex=0, sloworder=0 
D [05/Oct/2006:17:20:44 -0400] [Job 41] 0 %%BoundingBox: 0 0 612 792 
D [05/Oct/2006:17:20:44 -0400] [Job 41] 0 %%Pages: 1 
D [05/Oct/2006:17:20:44 -0400] [Job 41] 0 %%LanguageLevel: 1 
D [05/Oct/2006:17:20:44 -0400] [Job 41] 0 %%DocumentData: Clean7Bit 
D [05/Oct/2006:17:20:44 -0400] [Job 41] 0 %%DocumentSuppliedResources: procset testprint/1.1 
D [05/Oct/2006:17:20:44 -0400] [Job 41] 0 %%DocumentNeededResources: font Helvetica Helvetica-Bold Times-Roman 
D [05/Oct/2006:17:20:44 -0400] [Job 41] 0 %%Creator: Michael Sweet, Easy Software Products 
D [05/Oct/2006:17:20:44 -0400] [Job 41] 0 %%CreationDate: May 11, 1999 
D [05/Oct/2006:17:20:44 -0400] [Job 41] 0 %%Title: Test Page 
D [05/Oct/2006:17:20:44 -0400] [Job 41] 0 %%EndComments 
D [05/Oct/2006:17:20:44 -0400] [Job 41] 0 %%BeginProlog 
D [05/Oct/2006:17:20:44 -0400] [Job 41] 0 %%BeginResource procset testprint 1.1 0 
D [05/Oct/2006:17:20:44 -0400] [Job 41] 0 %%EndResource 
D [05/Oct/2006:17:20:44 -0400] [Job 41] 0 %%EndProlog 
D [05/Oct/2006:17:20:44 -0400] [Job 41] 0 %%Page: 1 1 
D [05/Oct/2006:17:20:44 -0400] [Job 41] 0 %%Page: 1 1 
D [05/Oct/2006:17:20:44 -0400] [Job 41] pw = 576.0, pl = 759.0 
D [05/Oct/2006:17:20:44 -0400] [Job 41] PageLeft = 18.0, PageRight = 594.0 
D [05/Oct/2006:17:20:44 -0400] [Job 41] PageTop = 792.0, PageBottom = 33.0 
D [05/Oct/2006:17:20:44 -0400] [Job 41] PageWidth = 612.0, PageLength = 792.0 
D [05/Oct/2006:17:20:44 -0400] [Job 41] 0 %%EOF 
D [05/Oct/2006:17:20:44 -0400] [Job 41] Saw EOF! 
D [05/Oct/2006:17:20:44 -0400] [Job 41] START 0 1397176 113535 1300844 11688 true 510 3 <0> 
D [05/Oct/2006:17:20:44 -0400] [Job 41] END PROCS 3 1417272 130705 1300844 13056 true 630 3 <0> 
D [05/Oct/2006:17:20:44 -0400] [Job 41] gs_std_e.ps 21 1437368 140658 1300844 14432 true 639 3 <0> 
D [05/Oct/2006:17:20:44 -0400] [Job 41] gs_il1_e.ps 29 1457464 146710 1300844 14432 true 640 3 <0> 
D [05/Oct/2006:17:20:44 -0400] [Job 41] END FONTDIR/ENCS 29 1457464 146862 1300844 14432 true 642 3 <0> 
D [05/Oct/2006:17:20:44 -0400] [Job 41] END DEVS 133 1461168 167383 1300844 14432 true 646 3 <0> 
D [05/Oct/2006:17:20:44 -0400] [Job 41] END STATD 138 1481264 178507 1300844 16044 true 651 3 <0> 
D [05/Oct/2006:17:20:44 -0400] [Job 41] END GS_FONTS 146 1521456 216238 1300844 16044 true 699 3 <0> 
D [05/Oct/2006:17:20:44 -0400] [Job 41] END BASIC COLOR 151 1521456 224097 1300844 16044 true 714 3 <0> 
D [05/Oct/2006:17:20:44 -0400] [Job 41] END LEVEL 1 COLOR 153 1541552 229212 1300844 16044 true 715 3 <0> 
D [05/Oct/2006:17:20:44 -0400] [Job 41] END IMAGE 158 1541552 232960 1300844 16044 true 720 3 <0> 
D [05/Oct/2006:17:20:44 -0400] [Job 41] gs_btokn.ps 166 1541552 237088 1300844 16044 true 723 3 <0> 
D [05/Oct/2006:17:20:44 -0400] [Job 41] gs_dps1.ps 173 1541552 238846 1300844 16044 true 725 3 <0> 
D [05/Oct/2006:17:20:44 -0400] [Job 41] gs_dps2.ps 174 1541552 241304 1300844 16044 true 726 3 <0> 
D [05/Oct/2006:17:20:44 -0400] [Job 41] gs_type1.ps 184 1541552 246246 1300844 16044 true 733 3 <0> 
D [05/Oct/2006:17:20:44 -0400] [Job 41] gs_lev2.ps 227 1561648 266297 1396944 112540 true 739 3 <0>

More information about the cups mailing list