permission denied on spool file with cups 1.1.22
Robert Sander
robert.sander at epigenomics.com
Fri Dec 3 09:02:11 PST 2004
Hi!
I get the following log file entries when trying to print a test page
with a freshly installed cups 1.1.22:
d [03/Dec/2004:17:51:10 +0100] ReadClient: 4, used=0, file=-1
D [03/Dec/2004:17:51:10 +0100] ReadClient: 4 GET /printers/hm205?op=print-test-page HTTP/1.1
d [03/Dec/2004:17:51:10 +0100] decode_auth(0x403be008): Authorization string = ""
d [03/Dec/2004:17:51:10 +0100] decode_auth: 4 username=""
d [03/Dec/2004:17:51:10 +0100] IsAuthorized: con->uri = "/printers/hm205?op=print-test-page"
d [03/Dec/2004:17:51:10 +0100] FindBest: uri = "/printers/hm205?op=print-test-page"...
d [03/Dec/2004:17:51:10 +0100] FindBest: Location / Limit 7f
d [03/Dec/2004:17:51:10 +0100] FindBest: Location /admin Limit 7f
d [03/Dec/2004:17:51:10 +0100] FindBest: best = "/"
d [03/Dec/2004:17:51:10 +0100] IsAuthorized: auth = 0, satisfy=0...
d [03/Dec/2004:17:51:10 +0100] pipe_command: command="/usr/local/cupsys/lib/cups/cgi-bin/printers.cgi", options="hm205?op=print-test-page"
d [03/Dec/2004:17:51:10 +0100] pipe_command: argv[0] = "hm205"
d [03/Dec/2004:17:51:10 +0100] pipe_command: argv[1] = "op=print-test-page"
d [03/Dec/2004:17:51:10 +0100] pipe_command: envp[0] = "PATH=/bin:/usr/bin"
d [03/Dec/2004:17:51:10 +0100] pipe_command: envp[1] = "SERVER_SOFTWARE=CUPS/1.1"
d [03/Dec/2004:17:51:10 +0100] pipe_command: envp[2] = "GATEWAY_INTERFACE=CGI/1.1"
d [03/Dec/2004:17:51:10 +0100] pipe_command: envp[3] = "SERVER_PROTOCOL=HTTP/1.1"
d [03/Dec/2004:17:51:10 +0100] pipe_command: envp[4] = "REDIRECT_STATUS=1"
d [03/Dec/2004:17:51:10 +0100] pipe_command: envp[5] = "CUPS_SERVER=localhost"
d [03/Dec/2004:17:51:10 +0100] pipe_command: envp[6] = "IPP_PORT=631"
d [03/Dec/2004:17:51:10 +0100] pipe_command: envp[7] = "SERVER_NAME=perl.epigenomics.epi"
d [03/Dec/2004:17:51:10 +0100] pipe_command: envp[8] = "SERVER_PORT=631"
d [03/Dec/2004:17:51:10 +0100] pipe_command: envp[9] = "REMOTE_ADDR=192.168.51.249"
d [03/Dec/2004:17:51:10 +0100] pipe_command: envp[10] = "REMOTE_HOST=snell.epigenomics.epi"
d [03/Dec/2004:17:51:10 +0100] pipe_command: envp[11] = "REMOTE_USER="
d [03/Dec/2004:17:51:10 +0100] pipe_command: envp[12] = "LANG=de.UTF-8"
d [03/Dec/2004:17:51:10 +0100] pipe_command: envp[13] = ""
d [03/Dec/2004:17:51:10 +0100] pipe_command: envp[14] = "TMPDIR=/usr/local/cupsys/var/spool/cups/tmp"
d [03/Dec/2004:17:51:10 +0100] pipe_command: envp[15] = "CUPS_DATADIR=/usr/local/cupsys/share/cups"
d [03/Dec/2004:17:51:10 +0100] pipe_command: envp[16] = "CUPS_SERVERROOT=/usr/local/cupsys/etc/cups"
d [03/Dec/2004:17:51:10 +0100] pipe_command: envp[17] = "HTTP_USER_AGENT=Mozilla/5.0 (X11; U; Linux i686; de-AT; rv:1.7.2) Gecko/20040803 Mnenhy/0.6.0.104"
d [03/Dec/2004:17:51:10 +0100] pipe_command: envp[18] = "SCRIPT_NAME=/printers/hm205"
d [03/Dec/2004:17:51:10 +0100] pipe_command: envp[19] = "REQUEST_METHOD=GET"
d [03/Dec/2004:17:51:10 +0100] pipe_command: envp[20] = "QUERY_STRING=op=print-test-page"
d [03/Dec/2004:17:51:10 +0100] pipe_command: envp[21] = "CUPS_ENCRYPTION=IfRequested"
d [03/Dec/2004:17:51:10 +0100] AddCert: adding certificate for pid 9945
D [03/Dec/2004:17:51:10 +0100] CGI /usr/local/cupsys/lib/cups/cgi-bin/printers.cgi started - PID = 9945
I [03/Dec/2004:17:51:10 +0100] Started "/usr/local/cupsys/lib/cups/cgi-bin/printers.cgi" (pid=9945)
D [03/Dec/2004:17:51:10 +0100] SendCommand: 4 file=7
d [03/Dec/2004:17:51:10 +0100] SendCommand: Adding fd 7 to InputSet...
d [03/Dec/2004:17:51:10 +0100] SendCommand: Adding fd 4 to OutputSet...
d [03/Dec/2004:17:51:10 +0100] AcceptClient(lis=0x808a008) 0 NumClients = 1
D [03/Dec/2004:17:51:10 +0100] AcceptClient: 6 from localhost:631.
d [03/Dec/2004:17:51:10 +0100] AcceptClient: Adding fd 6 to InputSet...
d [03/Dec/2004:17:51:10 +0100] WriteClient: 4 Content-Type: text/html;charset=utf-8
d [03/Dec/2004:17:51:10 +0100] WriteClient: 4
d [03/Dec/2004:17:51:10 +0100] WriteClient: 4 1181 bytes
d [03/Dec/2004:17:51:10 +0100] ReadClient: 6, used=0, file=-1
D [03/Dec/2004:17:51:10 +0100] ReadClient: 6 POST /printers/hm205 HTTP/1.1
d [03/Dec/2004:17:51:10 +0100] decode_auth(0x403c0c3c): Authorization string = ""
d [03/Dec/2004:17:51:10 +0100] decode_auth: 6 username=""
d [03/Dec/2004:17:51:10 +0100] IsAuthorized: con->uri = "/printers/hm205"
d [03/Dec/2004:17:51:10 +0100] FindBest: uri = "/printers/hm205"...
d [03/Dec/2004:17:51:10 +0100] FindBest: Location / Limit 7f
d [03/Dec/2004:17:51:10 +0100] FindBest: Location /admin Limit 7f
d [03/Dec/2004:17:51:10 +0100] FindBest: best = "/"
d [03/Dec/2004:17:51:10 +0100] IsAuthorized: auth = 0, satisfy=0...
d [03/Dec/2004:17:51:10 +0100] POST /printers/hm205
d [03/Dec/2004:17:51:10 +0100] CONTENT_TYPE = application/ipp
d [03/Dec/2004:17:51:10 +0100] ReadClient: 6 con->data_encoding = length, con->data_remaining = 14761, con->file = -1
d [03/Dec/2004:17:51:10 +0100] ReadClient: 6, used=200, file=-1
d [03/Dec/2004:17:51:10 +0100] ReadClient: 6 con->data_encoding = length, con->data_remaining = 14753, con->file = -1
d [03/Dec/2004:17:51:10 +0100] ReadClient: 6 REQUEST /usr/local/cupsys/var/spool/cups/00000005=8
d [03/Dec/2004:17:51:10 +0100] ReadClient: 6 writing 14553 bytes to 8
d [03/Dec/2004:17:51:10 +0100] ReadClient: 6 Closing data file 8, size = 14553.
d [03/Dec/2004:17:51:10 +0100] ProcessIPPRequest(0x403c0c3c[6]): operation_id = 0002
d [03/Dec/2004:17:51:10 +0100] ProcessIPPRequest: URI="ipp://localhost/printers/hm205"
d [03/Dec/2004:17:51:10 +0100] print_job(0x403c0c3c[6], ipp://localhost/printers/hm205)
D [03/Dec/2004:17:51:10 +0100] print_job: request file type is application/postscript.
d [03/Dec/2004:17:51:10 +0100] check_quotas(0x403c0c3c[6], 0x80cb3e0[hm205])
D [03/Dec/2004:17:51:10 +0100] check_quotas: requesting-user-name = ''
D [03/Dec/2004:17:51:10 +0100] print_job: requesting-user-name = ''
D [03/Dec/2004:17:51:10 +0100] Adding default job-sheets values "none,none"...
I [03/Dec/2004:17:51:10 +0100] Adding start banner page "none" to job 13.
d [03/Dec/2004:17:51:10 +0100] copy_banner(0x403c0c3c[6], 0x80a9190[13], none)
d [03/Dec/2004:17:51:10 +0100] add_file(con=0x403c0c3c[6], job=13, filetype=application/postscript, compression=0)
I [03/Dec/2004:17:51:10 +0100] Adding end banner page "none" to job 13.
d [03/Dec/2004:17:51:10 +0100] copy_banner(0x403c0c3c[6], 0x80a9190[13], none)
I [03/Dec/2004:17:51:10 +0100] Job 13 queued on 'hm205' by ''.
D [03/Dec/2004:17:51:10 +0100] Job 13 hold_until = 0
d [03/Dec/2004:17:51:10 +0100] SaveJob: Closing file 8...
D [03/Dec/2004:17:51:10 +0100] StartJob(13, 0x80cb3e0)
D [03/Dec/2004:17:51:10 +0100] StartJob() id = 13, file = 0/1
D [03/Dec/2004:17:51:10 +0100] job-sheets=none,none
D [03/Dec/2004:17:51:10 +0100] banner_page = 0
D [03/Dec/2004:17:51:10 +0100] StartJob: argv = "hm205","13","","Test Page","1","","/usr/local/cupsys/var/spool/cups/d00013-001"
D [03/Dec/2004:17:51:10 +0100] StartJob: envp[0]="PATH=/usr/local/cupsys/lib/cups/filter:/bin:/usr/bin"
D [03/Dec/2004:17:51:10 +0100] StartJob: envp[1]="SOFTWARE=CUPS/1.1"
D [03/Dec/2004:17:51:10 +0100] StartJob: envp[2]="USER=root"
D [03/Dec/2004:17:51:10 +0100] StartJob: envp[3]="CHARSET=utf-8"
D [03/Dec/2004:17:51:10 +0100] StartJob: envp[4]="LANG=de"
D [03/Dec/2004:17:51:10 +0100] StartJob: envp[5]="PPD=/usr/local/cupsys/etc/cups/ppd/hm205.ppd"
D [03/Dec/2004:17:51:10 +0100] StartJob: envp[6]="CUPS_SERVERROOT=/usr/local/cupsys/etc/cups"
D [03/Dec/2004:17:51:10 +0100] StartJob: envp[7]="RIP_MAX_CACHE=8m"
D [03/Dec/2004:17:51:10 +0100] StartJob: envp[8]="TMPDIR=/usr/local/cupsys/var/spool/cups/tmp"
D [03/Dec/2004:17:51:10 +0100] StartJob: envp[9]="CONTENT_TYPE=application/postscript"
D [03/Dec/2004:17:51:10 +0100] StartJob: envp[10]="DEVICE_URI=socket://hm205:9100/"
D [03/Dec/2004:17:51:10 +0100] StartJob: envp[11]="PRINTER=hm205"
D [03/Dec/2004:17:51:10 +0100] StartJob: envp[12]="CUPS_DATADIR=/usr/local/cupsys/share/cups"
D [03/Dec/2004:17:51:10 +0100] StartJob: envp[13]="CUPS_FONTPATH=/usr/local/cupsys/share/cups/fonts"
D [03/Dec/2004:17:51:10 +0100] StartJob: envp[14]="CUPS_SERVER=localhost"
D [03/Dec/2004:17:51:10 +0100] StartJob: envp[15]="IPP_PORT=631"
d [03/Dec/2004:17:51:10 +0100] StartJob: Allocating status buffer...
D [03/Dec/2004:17:51:10 +0100] StartJob: statusfds = [ 8 9 ]
D [03/Dec/2004:17:51:10 +0100] StartJob: filterfds[1] = [ 10 -1 ]
D [03/Dec/2004:17:51:10 +0100] StartJob: filter = "/usr/local/cupsys/lib/cups/filter/pstops"
D [03/Dec/2004:17:51:10 +0100] StartJob: filterfds[0] = [ 11 12 ]
D [03/Dec/2004:17:51:10 +0100] start_process("/usr/local/cupsys/lib/cups/filter/pstops", 0xbffefdd0, 0xbffef140, 10, 12, 9)
I [03/Dec/2004:17:51:10 +0100] Started filter /usr/local/cupsys/lib/cups/filter/pstops (PID 9946) for job 13.
D [03/Dec/2004:17:51:10 +0100] StartJob: backend = "/usr/local/cupsys/lib/cups/backend/socket"
D [03/Dec/2004:17:51:10 +0100] StartJob: filterfds[1] = [ -1 10 ]
D [03/Dec/2004:17:51:10 +0100] start_process("/usr/local/cupsys/lib/cups/backend/socket", 0xbffefdd0, 0xbffef140, 11, 10, 9)
I [03/Dec/2004:17:51:10 +0100] Started backend /usr/local/cupsys/lib/cups/backend/socket (PID 9947) for job 13.
d [03/Dec/2004:17:51:10 +0100] StartJob: Adding fd 8 to InputSet...
d [03/Dec/2004:17:51:10 +0100] add_job_state_reasons(0x403c0c3c[6], 13)
D [03/Dec/2004:17:51:10 +0100] ProcessIPPRequest: 6 status_code=0
d [03/Dec/2004:17:51:10 +0100] ProcessIPPRequest: Adding fd 6 to OutputSet...
d [03/Dec/2004:17:51:10 +0100] WriteClient: Removing fd 6 from OutputSet...
d [03/Dec/2004:17:51:10 +0100] ReadClient: 6, used=0, file=-1
d [03/Dec/2004:17:51:10 +0100] ReadClient: httpGets returned EOF...
D [03/Dec/2004:17:51:10 +0100] CloseClient: 6
d [03/Dec/2004:17:51:10 +0100] CloseClient: Removing fd 6 from InputSet and OutputSet...
d [03/Dec/2004:17:51:10 +0100] WriteClient: Removing fd 4 from OutputSet...
d [03/Dec/2004:17:51:10 +0100] WriteClient: Removing fd 7 from InputSet...
d [03/Dec/2004:17:51:10 +0100] WriteClient: 4 Closing data file 7.
d [03/Dec/2004:17:51:10 +0100] PID 9945 exited with no errors.
d [03/Dec/2004:17:51:10 +0100] DeleteCert: removing certificate for pid 9945
E [03/Dec/2004:17:51:10 +0100] [Job 13] unable to open print file "/usr/local/cupsys/var/spool/cups/d00013-001" - Permission denied
E [03/Dec/2004:17:51:10 +0100] PID 9946 stopped with status 1!
I [03/Dec/2004:17:51:10 +0100] [Job 13] Attempting to connect to host hm205 on port 9100
I [03/Dec/2004:17:51:10 +0100] [Job 13] Connected to host, sending print job...
I [03/Dec/2004:17:51:10 +0100] [Job 13] Print file sent, waiting for printer to finish...
d [03/Dec/2004:17:51:10 +0100] PID 9947 exited with no errors.
D [03/Dec/2004:17:51:10 +0100] UpdateJob: job 13, file 0 is complete.
d [03/Dec/2004:17:51:10 +0100] UpdateJob: Removing fd 8 from InputSet...
D [03/Dec/2004:17:51:10 +0100] CancelJob: id = 13
D [03/Dec/2004:17:51:10 +0100] StopJob: id = 13, force = 0
D [03/Dec/2004:17:51:10 +0100] StopJob: printer state is 3
d [03/Dec/2004:17:51:10 +0100] StopJob: Freeing status buffer...
d [03/Dec/2004:17:51:10 +0100] SaveJob: Closing file 6...
d [03/Dec/2004:17:51:10 +0100] SaveJob: Closing file 6...
Permissions on the spool dirs are:
drwx--x--- 3 root lpadmin 4096 Dec 3 17:56 ./
drwx--s--- 3 root staff 4096 Dec 3 14:35 ../
drwxrwx--T 2 root lpadmin 4096 Dec 3 17:50 tmp/
What can be done to solve this problem?
When the printer is stopped but accepts jobs the job data file is
submitted to the spool directory. When I start the printer again
the error message appears and the job data file gets deleted.
The printer (hm205) does not receive anything.
We have CUPS running since more than three years now. I wanted to
upgrade from the Debian included 1.1.20 using the self-compiled
1.1.22 because of the newer cupsaddsmb.
Greetings
--
Robert Sander Senior Manager Information Systems
Epigenomics AG Kleine Praesidentenstr. 1 10178 Berlin, Germany
phone:+49-30-24345-330 fax:+49-30-24345-555
http://www.epigenomics.com robert.sander at epigenomics.com
More information about the cups-devel
mailing list