[cups.general] "unable to open print file..."

Mac Mason mac at cs.hmc.edu
Fri Jun 25 13:16:10 PDT 2004 

Ack! I'm getting more and more confused...

:-)

So, after re-installing CUPS in /usr/local, turning off RunAsUser (so
the web interface works) and trying to print a test page, I still get
the error below ("unable to open print file
"/usr/local/var/spool/cups/d00008-001" - Permission denied"). 
doing a 

# chmod -R a+rwx /usr/local/var/spool/cups

didn't fix it, either.

This error has been so persistant that I'm not entirely sure this is
really the problem any more; to illustrate, take a look at the output of
error_log:

D [25/Jun/2004:13:12:26 +0800] LoadAllJobs: Scanning /usr/local/var/spool/cups...
D [25/Jun/2004:13:12:26 +0800] LoadAllJobs: Loading attributes for job 6...
D [25/Jun/2004:13:12:26 +0800] LoadAllJobs: Loading attributes for job 7...
D [25/Jun/2004:13:12:26 +0800] LoadAllJobs: Loading attributes for job 8...
D [25/Jun/2004:13:12:26 +0800] LoadAllJobs: Loading attributes for job 9...
D [25/Jun/2004:13:12:26 +0800] LoadAllJobs: Loading attributes for job 10...
D [25/Jun/2004:13:12:26 +0800] LoadAllJobs: Loading attributes for job 11...
I [25/Jun/2004:13:12:26 +0800] Full reload complete.
D [25/Jun/2004:13:12:26 +0800] StartListening: NumListeners=1
D [25/Jun/2004:13:12:26 +0800] StartListening: address=00000000 port=631
D [25/Jun/2004:13:12:26 +0800] ResumeListening: setting input bits...
D [25/Jun/2004:13:12:33 +0800] AcceptClient() 6 from 134.173.42.99:631.
D [25/Jun/2004:13:12:33 +0800] ReadClient() 6 GET /printers/gute HTTP/1.1
D [25/Jun/2004:13:12:33 +0800] CGI /usr/local/lib/cups/cgi-bin/printers.cgi started - PID = 16135
I [25/Jun/2004:13:12:33 +0800] Started "/usr/local/lib/cups/cgi-bin/printers.cgi" (pid=16135)
D [25/Jun/2004:13:12:33 +0800] SendCommand() 6 file=8
D [25/Jun/2004:13:12:33 +0800] AcceptClient() 9 from localhost:631.
D [25/Jun/2004:13:12:33 +0800] ReadClient() 9 POST / HTTP/1.1
D [25/Jun/2004:13:12:33 +0800] ProcessIPPRequest: 9 status_code=0
D [25/Jun/2004:13:12:33 +0800] ReadClient() 9 POST / HTTP/1.1
D [25/Jun/2004:13:12:33 +0800] ProcessIPPRequest: 9 status_code=1
D [25/Jun/2004:13:12:33 +0800] ReadClient() 9 POST / HTTP/1.1
D [25/Jun/2004:13:12:33 +0800] ProcessIPPRequest: 9 status_code=1
D [25/Jun/2004:13:12:33 +0800] CloseClient() 9
D [25/Jun/2004:13:12:35 +0800] ReadClient() 6 GET /printers/gute?op=print-test-page HTTP/1.1
D [25/Jun/2004:13:12:35 +0800] CGI /usr/local/lib/cups/cgi-bin/printers.cgi started - PID = 16136
I [25/Jun/2004:13:12:35 +0800] Started "/usr/local/lib/cups/cgi-bin/printers.cgi" (pid=16136)
D [25/Jun/2004:13:12:35 +0800] SendCommand() 6 file=9
D [25/Jun/2004:13:12:35 +0800] AcceptClient() 8 from localhost:631.
D [25/Jun/2004:13:12:35 +0800] ReadClient() 8 POST /printers/gute HTTP/1.1
D [25/Jun/2004:13:12:35 +0800] print_job: request file type is application/postscript.
D [25/Jun/2004:13:12:35 +0800] check_quotas: requesting-user-name = 'root'
D [25/Jun/2004:13:12:35 +0800] print_job: requesting-user-name = 'root'
D [25/Jun/2004:13:12:35 +0800] Adding default job-sheets values "none,none"...
I [25/Jun/2004:13:12:35 +0800] Adding start banner page "none" to job 12.
I [25/Jun/2004:13:12:35 +0800] Adding end banner page "none" to job 12.
I [25/Jun/2004:13:12:35 +0800] Job 12 queued on 'gute' by 'root'.
D [25/Jun/2004:13:12:35 +0800] Job 12 hold_until = 0
D [25/Jun/2004:13:12:35 +0800] StartJob(12, 199e50)
D [25/Jun/2004:13:12:35 +0800] StartJob() id = 12, file = 0/1
D [25/Jun/2004:13:12:35 +0800] job-sheets=none,none
D [25/Jun/2004:13:12:35 +0800] banner_page = 0
D [25/Jun/2004:13:12:35 +0800] StartJob: argv = "gute","12","root","Test Page","1","","/usr/local/var/spool/cups/d00012-001"
D [25/Jun/2004:13:12:35 +0800] StartJob: envp[0]="PATH=/usr/local/lib/cups/filter:/bin:/usr/bin"
D [25/Jun/2004:13:12:35 +0800] StartJob: envp[1]="SOFTWARE=CUPS/1.1"
D [25/Jun/2004:13:12:35 +0800] StartJob: envp[2]="USER=root"
D [25/Jun/2004:13:12:35 +0800] StartJob: envp[3]="CHARSET=utf-8"
D [25/Jun/2004:13:12:35 +0800] StartJob: envp[4]="LANG=en_US"
D [25/Jun/2004:13:12:35 +0800] StartJob: envp[5]="TZ=US/Pacific"
D [25/Jun/2004:13:12:35 +0800] StartJob: envp[6]="PPD=/usr/local/etc/cups/ppd/gute.ppd"
D [25/Jun/2004:13:12:35 +0800] StartJob: envp[7]="CUPS_SERVERROOT=/usr/local/etc/cups"
D [25/Jun/2004:13:12:35 +0800] StartJob: envp[8]="RIP_MAX_CACHE=8m"
D [25/Jun/2004:13:12:35 +0800] StartJob: envp[9]="TMPDIR=/usr/local/var/spool/cups/tmp"
D [25/Jun/2004:13:12:35 +0800] StartJob: envp[10]="CONTENT_TYPE=application/postscript"
D [25/Jun/2004:13:12:35 +0800] StartJob: envp[11]="DEVICE_URI=socket://gute.cs.hmc.edu:9100"
D [25/Jun/2004:13:12:35 +0800] StartJob: envp[12]="PRINTER=gute"
D [25/Jun/2004:13:12:35 +0800] StartJob: envp[13]="CUPS_DATADIR=/usr/local/share/cups"
D [25/Jun/2004:13:12:35 +0800] StartJob: envp[14]="CUPS_FONTPATH=/usr/local/share/cups/fonts"
D [25/Jun/2004:13:12:35 +0800] StartJob: envp[15]="CUPS_SERVER=localhost"
D [25/Jun/2004:13:12:35 +0800] StartJob: envp[16]="IPP_PORT=631"
D [25/Jun/2004:13:12:35 +0800] StartJob: statusfds = [ 10 11 ]
D [25/Jun/2004:13:12:35 +0800] StartJob: filterfds[1] = [ 12 -1 ]
D [25/Jun/2004:13:12:35 +0800] StartJob: filter = "/usr/local/lib/cups/filter/pstops"
D [25/Jun/2004:13:12:35 +0800] StartJob: filterfds[0] = [ 13 14 ]
D [25/Jun/2004:13:12:35 +0800] start_process("/usr/local/lib/cups/filter/pstops", ffbf01f0, ffbef560, 12, 14, 11)
I [25/Jun/2004:13:12:35 +0800] Started filter /usr/local/lib/cups/filter/pstops (PID 16137) for job 12.
D [25/Jun/2004:13:12:35 +0800] StartJob: backend = "/usr/local/lib/cups/backend/socket"
D [25/Jun/2004:13:12:35 +0800] StartJob: filterfds[1] = [ -1 12 ]
D [25/Jun/2004:13:12:35 +0800] start_process("/usr/local/lib/cups/backend/socket", ffbf01f0, ffbef560, 13, 12, 11)
I [25/Jun/2004:13:12:35 +0800] Started backend /usr/local/lib/cups/backend/socket (PID 16138) for job 12.
D [25/Jun/2004:13:12:35 +0800] ProcessIPPRequest: 8 status_code=0
E [25/Jun/2004:13:12:35 +0800] PID 16137 stopped with status 1!
D [25/Jun/2004:13:12:35 +0800] CloseClient() 8
E [25/Jun/2004:13:12:35 +0800] [Job 12] unable to open print file "/usr/local/var/spool/cups/d00012-001" - Permission denied
D [25/Jun/2004:13:12:35 +0800] UpdateJob: job 12, file 0 is complete.
D [25/Jun/2004:13:12:35 +0800] CancelJob: id = 12
D [25/Jun/2004:13:12:35 +0800] StopJob: id = 12, force = 0
D [25/Jun/2004:13:12:35 +0800] StopJob: printer state is 3
D [25/Jun/2004:13:12:36 +0800] ReadClient() 6 GET /printers/gute HTTP/1.1
D [25/Jun/2004:13:12:36 +0800] CGI /usr/local/lib/cups/cgi-bin/printers.cgi started - PID = 16139
I [25/Jun/2004:13:12:36 +0800] Started "/usr/local/lib/cups/cgi-bin/printers.cgi" (pid=16139)
D [25/Jun/2004:13:12:36 +0800] SendCommand() 6 file=9
D [25/Jun/2004:13:12:36 +0800] AcceptClient() 8 from localhost:631.
D [25/Jun/2004:13:12:36 +0800] ReadClient() 8 POST / HTTP/1.1
D [25/Jun/2004:13:12:36 +0800] ProcessIPPRequest: 8 status_code=0
D [25/Jun/2004:13:12:36 +0800] ReadClient() 8 POST / HTTP/1.1
D [25/Jun/2004:13:12:36 +0800] ProcessIPPRequest: 8 status_code=1
D [25/Jun/2004:13:12:36 +0800] ReadClient() 8 POST / HTTP/1.1
D [25/Jun/2004:13:12:36 +0800] ProcessIPPRequest: 8 status_code=1
D [25/Jun/2004:13:12:36 +0800] CloseClient() 8

(Sorry for the flood...)

Observe that it looks like the backend is crashing partway through and
then everything is sort of bailing out. 

Anybody got any ideas?

Thanks!

    --Mac

On Wed, Jun 23, 2004 at 07:58:48PM -0400, Michael Sweet wrote:
> Mac Mason wrote:
> >Trying to print a test page on my new install (self-compiled on Solaris
> >9, using a Xerox Phaser 5400, with a Xerox-provided PPD), gives the
> >following in both /var/log/cups/error_log and the web interface:
> >
> >"unable to open print file "/cups-local/var/spool/cups/d00004-001" -
> >Permission denied" 
> >
> >Given that cupsd is running as root, and root owns (and can write to)
> >that directory, this doesn't make much sense.
> 
> Actually, unless you've changed the default configuration the
> filters run as user "lp" group "sys", so verify that /cups-local
> and the remaining directories allow read and search (execute)
> access.
> 
> >A possibility: the contents of that directory are called 'c00003' and
> >'c00004'; nothing starting with 'd's.
> >
> >Could the 'permission denied' actually be a 'no such file'?
> 
> Nope, the "d" files are normally removed after the job finishes
> (successfully or not).
> 
> -- 
> ______________________________________________________________________
> Michael Sweet, Easy Software Products           mike at easysw dot com
> Printing Software for UNIX                       http://www.easysw.com
> _______________________________________________
> cups mailing list
> cups at easysw.com
> http://lists.easysw.com/mailman/listinfo/cups
> 

-- 
Julian "Mac" Mason                            mac at cs.hmc.edu
Computer Science '06                          (909)-607-3129
Harvey Mudd College
-------------- next part --------------
A non-text attachment was scrubbed...
Name: not available
Type: application/pgp-signature
Size: 185 bytes
Desc: not available
URL: <https://lists.cups.org/pipermail/cups/attachments/20040625/ec4dd1cf/attachment.bin>

More information about the cups mailing list