[Samba] printing problems and permissions

Frank Fürst ffrank at rz.uni-potsdam.de
Tue Feb 26 10:53:03 GMT 2002


I've got Samba 2.2.3 running as a PDC for some Win9x and WinNT
clients. Everything seems to be fine except that occasionally (but
rather often, at least every second day) printing from one of the
NT-clients is impossible. In the log file it says (word wrap here in the
editor):

[2002/02/26 18:04:21, 0] printing/printing.c:print_job_start(952)
  print_job_start: insufficient permissions to open spool file \
                         /var/spool/samba/print/smbprn.002806.CObq8v.
[2002/02/26 18:04:21, 3] printing/printing.c:print_job_start(985)
  print_job_start: returning fail. Error = Permission denied

However, the permissions of this directory are correct, I think.

ls -al /var/spool/samba/print/
total 2
drwxrwsr-x    2 samba    samba        1024 Feb 26 19:07 .
drwxrwsrwx    3 root     root         1024 Jul 30  2000 ..

and all the Samba-Users have group samba as primary group. How can I
debug this problem?

The system is: Debian/GNU Linux potato (stable), Linux 2.2.20, Samba
2.2.3 (compiled from the Debian source package in unstable). At the end
of the posting, I add all the entries in the respective logfile at debug
level 3 that have the same time stamp (and one before and after), as
well as the global and printers section of smb.conf.

One more thing: With a linux client mounting shares with smbmount, I
once got a similar strange permission problem when trying to overwrite
files with xemacs - but that migth be completely unrelated.

TIA, Frank
--
Frank Fürst, physikalische Biochemie, Universität Potsdam, Germany
Tel.: +49-331-977-5062		Fax: +49-331-977-5062

[2002/02/26 18:04:20, 3] rpc_server/srv_pipe_hnd.c:free_pipe_context(440)
  free_pipe_context: destroying talloc pool of size 6556
[2002/02/26 18:04:21, 3] smbd/process.c:process_smb(860)
  Transaction 563 of length 256
[2002/02/26 18:04:21, 3] smbd/process.c:switch_message(667)
  switch message SMBtrans (pid 32149)
[2002/02/26 18:04:21, 3] smbd/ipc.c:reply_trans(480)
  trans <\PIPE\> data=176 params=0 setup=2
[2002/02/26 18:04:21, 3] smbd/ipc.c:named_pipe(334)
  named pipe command on <> name
[2002/02/26 18:04:21, 3] smbd/ipc.c:api_fd_reply(296)
  Got API command 0x26 on pipe "spoolss" (pnum 746c)free_pipe_context: destroying talloc pool of size 0
[2002/02/26 18:04:21, 3] rpc_server/srv_pipe.c:api_pipe_request(1148)
  Doing \PIPE\spoolss
[2002/02/26 18:04:21, 3] rpc_server/srv_pipe.c:api_rpcTNP(1180)
  api_rpcTNP: pipe 29804 rpc command: SPOOLSS_OPENPRINTEREX
  checking name: \\SUGAR\hplj6
[2002/02/26 18:04:21, 3] rpc_server/srv_spoolss_nt.c:set_printer_hnd_printertype(378)
  Setting printer type=\\SUGAR\hplj6
[2002/02/26 18:04:21, 3] lib/util_seaccess.c:se_access_check(244)
  se_access_check: user sid is S-1-5-21-710766589-56582740-2239126349-132068
[2002/02/26 18:04:21, 3] lib/util_seaccess.c:se_access_check(248)
  se_access_check: also S-1-5-21-710766589-56582740-2239126349-132069
[2002/02/26 18:04:21, 3] lib/util_seaccess.c:se_access_check(248)
  se_access_check: also S-1-1-0
[2002/02/26 18:04:21, 3] lib/util_seaccess.c:se_access_check(248)
  se_access_check: also S-1-5-2
[2002/02/26 18:04:21, 3] lib/util_seaccess.c:se_access_check(248)
  se_access_check: also S-1-5-32-546
[2002/02/26 18:04:21, 3] rpc_server/srv_pipe_hnd.c:free_pipe_context(440)
  free_pipe_context: destroying talloc pool of size 928
[2002/02/26 18:04:21, 3] smbd/process.c:process_smb(860)
  Transaction 564 of length 4236
[2002/02/26 18:04:21, 3] smbd/process.c:switch_message(667)
  switch message SMBtrans (pid 32149)
[2002/02/26 18:04:21, 3] smbd/ipc.c:reply_trans(480)
  trans <\PIPE\> data=4156 params=0 setup=2
[2002/02/26 18:04:21, 3] smbd/ipc.c:named_pipe(334)
  named pipe command on <> name
[2002/02/26 18:04:21, 3] smbd/ipc.c:api_fd_reply(296)
  Got API command 0x26 on pipe "spoolss" (pnum 746c)free_pipe_context: destroying talloc pool of size 0
[2002/02/26 18:04:21, 3] rpc_server/srv_pipe.c:api_pipe_request(1148)
  Doing \PIPE\spoolss
[2002/02/26 18:04:21, 3] rpc_server/srv_pipe.c:api_rpcTNP(1180)
  api_rpcTNP: pipe 29804 rpc command: SPOOLSS_GETPRINTER
[2002/02/26 18:04:21, 3] rpc_server/srv_pipe_hnd.c:free_pipe_context(440)
  free_pipe_context: destroying talloc pool of size 6556
[2002/02/26 18:04:21, 3] smbd/process.c:process_smb(860)
  Transaction 565 of length 64
[2002/02/26 18:04:21, 3] smbd/process.c:switch_message(667)
  switch message SMBreadX (pid 32149)
[2002/02/26 18:04:21, 3] smbd/pipes.c:reply_pipe_read_and_X(239)
  readX-IPC pnum=746c min=3112 max=3112 nread=3112
[2002/02/26 18:04:21, 3] smbd/process.c:process_smb(860)
  Transaction 566 of length 4236
[2002/02/26 18:04:21, 3] smbd/process.c:switch_message(667)
  switch message SMBtrans (pid 32149)
[2002/02/26 18:04:21, 3] smbd/ipc.c:reply_trans(480)
  trans <\PIPE\> data=4156 params=0 setup=2
[2002/02/26 18:04:21, 3] smbd/ipc.c:named_pipe(334)
  named pipe command on <> name
[2002/02/26 18:04:21, 3] smbd/ipc.c:api_fd_reply(296)
  Got API command 0x26 on pipe "spoolss" (pnum 746c)free_pipe_context: destroying talloc pool of size 0
[2002/02/26 18:04:21, 3] rpc_server/srv_pipe.c:api_pipe_request(1148)
  Doing \PIPE\spoolss
[2002/02/26 18:04:21, 3] rpc_server/srv_pipe.c:api_rpcTNP(1180)
  api_rpcTNP: pipe 29804 rpc command: SPOOLSS_GETPRINTER
[2002/02/26 18:04:21, 3] rpc_server/srv_pipe_hnd.c:free_pipe_context(440)
  free_pipe_context: destroying talloc pool of size 6556
[2002/02/26 18:04:21, 3] smbd/process.c:process_smb(860)
  Transaction 567 of length 680
[2002/02/26 18:04:21, 3] smbd/process.c:switch_message(667)
  switch message SMBtrans (pid 32149)
[2002/02/26 18:04:21, 3] smbd/ipc.c:reply_trans(480)
  trans <\PIPE\> data=600 params=0 setup=2
[2002/02/26 18:04:21, 3] smbd/ipc.c:named_pipe(334)
  named pipe command on <> name
[2002/02/26 18:04:21, 3] smbd/ipc.c:api_fd_reply(296)
  Got API command 0x26 on pipe "spoolss" (pnum 746c)free_pipe_context: destroying talloc pool of size 0
[2002/02/26 18:04:21, 3] rpc_server/srv_pipe.c:api_pipe_request(1148)
  Doing \PIPE\spoolss
[2002/02/26 18:04:21, 3] rpc_server/srv_pipe.c:api_rpcTNP(1180)
  api_rpcTNP: pipe 29804 rpc command: SPOOLSS_OPENPRINTEREX
  checking name: \\SUGAR\hplj6
[2002/02/26 18:04:21, 3] rpc_server/srv_spoolss_nt.c:set_printer_hnd_printertype(378)
  Setting printer type=\\SUGAR\hplj6
[2002/02/26 18:04:21, 3] lib/util_seaccess.c:se_access_check(244)
  se_access_check: user sid is S-1-5-21-710766589-56582740-2239126349-132068
[2002/02/26 18:04:21, 3] lib/util_seaccess.c:se_access_check(248)
  se_access_check: also S-1-5-21-710766589-56582740-2239126349-132069
[2002/02/26 18:04:21, 3] lib/util_seaccess.c:se_access_check(248)
  se_access_check: also S-1-1-0
[2002/02/26 18:04:21, 3] lib/util_seaccess.c:se_access_check(248)
  se_access_check: also S-1-5-2
[2002/02/26 18:04:21, 3] lib/util_seaccess.c:se_access_check(248)
  se_access_check: also S-1-5-32-546
[2002/02/26 18:04:21, 3] rpc_server/srv_pipe_hnd.c:free_pipe_context(440)
  free_pipe_context: destroying talloc pool of size 1352
[2002/02/26 18:04:21, 3] smbd/process.c:process_smb(860)
  Transaction 568 of length 4236
[2002/02/26 18:04:21, 3] smbd/process.c:switch_message(667)
  switch message SMBtrans (pid 32149)
[2002/02/26 18:04:21, 3] smbd/ipc.c:reply_trans(480)
  trans <\PIPE\> data=4156 params=0 setup=2
[2002/02/26 18:04:21, 3] smbd/ipc.c:named_pipe(334)
  named pipe command on <> name
[2002/02/26 18:04:21, 3] smbd/ipc.c:api_fd_reply(296)
  Got API command 0x26 on pipe "spoolss" (pnum 746c)free_pipe_context: destroying talloc pool of size 0
[2002/02/26 18:04:21, 3] rpc_server/srv_pipe.c:api_pipe_request(1148)
  Doing \PIPE\spoolss
[2002/02/26 18:04:21, 3] rpc_server/srv_pipe.c:api_rpcTNP(1180)
  api_rpcTNP: pipe 29804 rpc command: SPOOLSS_GETPRINTER
[2002/02/26 18:04:21, 3] rpc_server/srv_pipe_hnd.c:free_pipe_context(440)
  free_pipe_context: destroying talloc pool of size 6556
[2002/02/26 18:04:21, 3] smbd/process.c:process_smb(860)
  Transaction 569 of length 64
[2002/02/26 18:04:21, 3] smbd/process.c:switch_message(667)
  switch message SMBreadX (pid 32149)
[2002/02/26 18:04:21, 3] smbd/pipes.c:reply_pipe_read_and_X(239)
  readX-IPC pnum=746c min=3112 max=3112 nread=3112
[2002/02/26 18:04:21, 3] smbd/process.c:process_smb(860)
  Transaction 570 of length 180
[2002/02/26 18:04:21, 3] smbd/process.c:switch_message(667)
  switch message SMBtrans (pid 32149)
[2002/02/26 18:04:21, 3] smbd/ipc.c:reply_trans(480)
  trans <\PIPE\> data=100 params=0 setup=2
[2002/02/26 18:04:21, 3] smbd/ipc.c:named_pipe(334)
  named pipe command on <> name
[2002/02/26 18:04:21, 3] smbd/ipc.c:api_fd_reply(296)
  Got API command 0x26 on pipe "spoolss" (pnum 746c)free_pipe_context: destroying talloc pool of size 0
[2002/02/26 18:04:21, 3] rpc_server/srv_pipe.c:api_pipe_request(1148)
  Doing \PIPE\spoolss
[2002/02/26 18:04:21, 3] rpc_server/srv_pipe.c:api_rpcTNP(1180)
  api_rpcTNP: pipe 29804 rpc command: SPOOLSS_STARTDOCPRINTER
[2002/02/26 18:04:21, 3] lib/util_seaccess.c:se_access_check(244)
  se_access_check: user sid is S-1-5-21-710766589-56582740-2239126349-132068
[2002/02/26 18:04:21, 3] lib/util_seaccess.c:se_access_check(248)
  se_access_check: also S-1-5-21-710766589-56582740-2239126349-132069
[2002/02/26 18:04:21, 3] lib/util_seaccess.c:se_access_check(248)
  se_access_check: also S-1-1-0
[2002/02/26 18:04:21, 3] lib/util_seaccess.c:se_access_check(248)
  se_access_check: also S-1-5-2
[2002/02/26 18:04:21, 3] lib/util_seaccess.c:se_access_check(248)
  se_access_check: also S-1-5-32-546
[2002/02/26 18:04:21, 0] printing/printing.c:print_job_start(952)
  print_job_start: insufficient permissions to open spool file /var/spool/samba/print/smbprn.002806.CObq8v.
[2002/02/26 18:04:21, 3] printing/printing.c:print_job_start(985)
  print_job_start: returning fail. Error = Permission denied
[2002/02/26 18:04:21, 3] rpc_server/srv_pipe_hnd.c:free_pipe_context(440)
  free_pipe_context: destroying talloc pool of size 456
[2002/02/26 18:04:21, 3] smbd/process.c:process_smb(860)
  Transaction 571 of length 124
[2002/02/26 18:04:21, 3] smbd/process.c:switch_message(667)
  switch message SMBtrans (pid 32149)
[2002/02/26 18:04:21, 3] smbd/ipc.c:reply_trans(480)
  trans <\PIPE\> data=44 params=0 setup=2
[2002/02/26 18:04:21, 3] smbd/ipc.c:named_pipe(334)
  named pipe command on <> name
[2002/02/26 18:04:21, 3] smbd/ipc.c:api_fd_reply(296)
  Got API command 0x26 on pipe "spoolss" (pnum 746c)free_pipe_context: destroying talloc pool of size 0
[2002/02/26 18:04:21, 3] rpc_server/srv_pipe.c:api_pipe_request(1148)
  Doing \PIPE\spoolss
[2002/02/26 18:04:21, 3] rpc_server/srv_pipe.c:api_rpcTNP(1180)
  api_rpcTNP: pipe 29804 rpc command: SPOOLSS_CLOSEPRINTER
[2002/02/26 18:04:21, 3] rpc_server/srv_lsa_hnd.c:close_policy_hnd(186)
  Closed policy
[2002/02/26 18:04:21, 3] rpc_server/srv_pipe_hnd.c:free_pipe_context(440)
  free_pipe_context: destroying talloc pool of size 0
[2002/02/26 18:04:21, 3] smbd/process.c:process_smb(860)
  Transaction 572 of length 124
[2002/02/26 18:04:21, 3] smbd/process.c:switch_message(667)
  switch message SMBtrans (pid 32149)
[2002/02/26 18:04:21, 3] smbd/ipc.c:reply_trans(480)
  trans <\PIPE\> data=44 params=0 setup=2
[2002/02/26 18:04:21, 3] smbd/ipc.c:named_pipe(334)
  named pipe command on <> name
[2002/02/26 18:04:21, 3] smbd/ipc.c:api_fd_reply(296)
  Got API command 0x26 on pipe "spoolss" (pnum 746c)free_pipe_context: destroying talloc pool of size 0
[2002/02/26 18:04:21, 3] rpc_server/srv_pipe.c:api_pipe_request(1148)
  Doing \PIPE\spoolss
[2002/02/26 18:04:21, 3] rpc_server/srv_pipe.c:api_rpcTNP(1180)
  api_rpcTNP: pipe 29804 rpc command: SPOOLSS_CLOSEPRINTER
[2002/02/26 18:04:21, 3] rpc_server/srv_lsa_hnd.c:close_policy_hnd(186)
  Closed policy
[2002/02/26 18:04:21, 3] rpc_server/srv_pipe_hnd.c:free_pipe_context(440)
  free_pipe_context: destroying talloc pool of size 0
[2002/02/26 18:04:25, 3] smbd/process.c:process_smb(860)
  Transaction 573 of length 124
[2002/02/26 18:04:25, 3] smbd/process.c:switch_message(667)
  switch message SMBtrans (pid 32149)
[2002/02/26 18:04:25, 3] smbd/ipc.c:reply_trans(480)
  trans <\PIPE\> data=44 params=0 setup=2
[2002/02/26 18:04:25, 3] smbd/ipc.c:named_pipe(334)
  named pipe command on <> name
[2002/02/26 18:04:25, 3] smbd/ipc.c:api_fd_reply(296)
  Got API command 0x26 on pipe "spoolss" (pnum 746c)free_pipe_context: destroying talloc pool of size 0
[2002/02/26 18:04:25, 3] rpc_server/srv_pipe.c:api_pipe_request(1148)
  Doing \PIPE\spoolss
[2002/02/26 18:04:25, 3] rpc_server/srv_pipe.c:api_rpcTNP(1180)
  api_rpcTNP: pipe 29804 rpc command: SPOOLSS_CLOSEPRINTER
[2002/02/26 18:04:25, 3] rpc_server/srv_lsa_hnd.c:close_policy_hnd(186)
[2002/02/26 18:04:21, 3] rpc_server/srv_lsa_hnd.c:close_policy_hnd(186)
  Closed policy
[2002/02/26 18:04:21, 3] rpc_server/srv_pipe_hnd.c:free_pipe_context(440)
  free_pipe_context: destroying talloc pool of size 0
[2002/02/26 18:04:25, 3] smbd/process.c:process_smb(860)
  Transaction 573 of length 124

smb.conf:, manual word wrap:
[global]
workgroup = seckler
domain logons = yes
server string = sugar
logon home = 
logon path =
logon script = %U.bat
domain admin group = @wsadmin root
printer admin = @wsadmin

add user script = /usr/sbin/adduser --conf \
        /etc/adduser.smbmachine.conf --home /dev/null --no-create-home \
        --gecos "Machine Trust Account" --disabled-password \
        --force-badname %u

#printing
printing=LPRNG
printcap name = /etc/printcap
load printers = yes

# security
security = user
guest account = nobody
encrypt passwords = yes
include = /etc/samba/hosts_allow

# browsing
os level = 64
local master = yes
preferred master = yes
domain master = yes
remote announce = 141.89.201.255

# wins-support: 
wins support = yes
name resolve order = wins lmhosts hosts bcast

debug level = 3
log file = /var/log/samba/%m.log
max log size = 1000
syslog = 0

# compatibility
client code page = 850
character set = ISO8859-1

[netlogon]
path = /var/export/smblogon
guest ok = no
writeable = no

[printers]
printable = yes
browseable = yes
path = /var/spool/samba/print
guest ok = no
writeable = no
create mode = 0700
lppause command = lpc hold %p %j
lpresume command = lpc release %p %j
queuepause command = lpc -P%p stop
queueresume command = lpc -P%p start
use client driver = yes





More information about the samba mailing list