[Samba] Problem printing from one user only
Christ Schlacta
lists at aarcane.org
Mon May 23 13:59:56 MDT 2011
On 5/15/2011 18:12, Christ Schlacta wrote:
> I'm trying to figure out why I'm getting permission denied when trying
> to print from one user account only. all others work fine.
> the print server is configured as a domain controller backed by ldap.
> aarcane at density:/var/log$ sudo testparm -s
> Load smb config files from /etc/samba/smb.conf
> rlimit_max: rlimit_max (1024) below minimum Windows limit (16384)
> Processing section "[homes]"
> Processing section "[netlogon]"
> Processing section "[profiles]"
> Processing section "[printers]"
> Processing section "[print$]"
> Processing section "[downloads]"
> Processing section "[backups]"
> Processing section "[videos]"
> Processing section "[music]"
> Processing section "[ebooks]"
> Processing section "[games]"
> Processing section "[misc]"
> Processing section "[www]"
> Loaded services file OK.
> Server role: ROLE_DOMAIN_PDC
> [global]
> workgroup = TEMPEST
> server string = File/Print Services (%h)
> map to guest = Bad User
> obey pam restrictions = Yes
> passdb backend = ldapsam:ldap://density.aarcane.info/
> log level = 4
> syslog = 0
> log file = /var/log/samba.log
> max log size = 1000
> socket options = TCP_NODELAY IPTOS_LOWDELAY SO_KEEPALIVE
> SO_RCVBUF=8192 SO_SNDBUF=8192
> printcap name = cups
> add machine script = sudo /usr/sbin/smbldap-useradd -t 0 -w "%u"
> logon script = logon.cmd
> logon path = \\%N\profiles\%U
> logon drive = V:
> domain logons = Yes
> os level = 30
> preferred master = Yes
> domain master = Yes
> dns proxy = No
> ldap admin dn = cn=admin,dc=aarcane,dc=info
> ldap group suffix = ou=Groups
> ldap idmap suffix = ou=Idmap
> ldap machine suffix = ou=Machines
> ldap passwd sync = yes
> ldap suffix = dc=aarcane,dc=info
> ldap ssl = no
> ldap user suffix = ou=People
> usershare allow guests = Yes
> panic action = /usr/share/samba/panic-action %d
>
> [homes]
> comment = Home Directories
> valid users = %S
> read only = No
> create mask = 0750
> directory mask = 0750
> browseable = No
>
> [netlogon]
> comment = Network Logon Service
> path = /tank/samba/netlogon
> guest ok = Yes
> browseable = No
>
> [profiles]
> comment = Users profiles
> path = /tank/samba/profiles
> create mask = 01600
> directory mask = 01700
> guest ok = Yes
> browseable = No
>
> [printers]
> comment = All Printers
> path = /var/spool/samba
> guest ok = Yes
> printable = Yes
> browseable = No
>
> [print$]
> comment = Printer Drivers
> path = /var/lib/samba/printers
> write list = root, @PrintAdmin
>
> [misclenaeous shares omitted]
>
> the printer has permissions granted to group ml-2851-nd (which is the
> same model as the printer), "Print" checkbox is checked in permissions
> window in windows.
> getent shows: aarcane at density:/var/log$ getent group ml-2851-nd
> ml-2851-nd:*:10013:reesie,debra,aarcane
>
> reesie and debra can print fine, aarcane can't.
>
> another printer is titled f4440, same as above.
> aarcane at density:/var/log$ getent group f4440
> f4440:*:10012:reesie,aarcane
>
> reesie and aarcane can both print fine.
>
> aside from the one group difference, both printers have the following
> permissions:
> CREATOR OWNER: Manage Documents
> specific group: Print
> PrintAdmin: All 3
> Domain Admins: all 3
>
> if I add special user permissions to the printer ml-2851-nd
> "IZANAMI\aarcane" I can then print to the ml-2851-nd. it shouldn't be
> needed, but it is.
>
> The following is log output at level >= 3 of me trying to double-click
> the printer from windows 7 explorer (I typed in \\density and
> double-clicked the printer), which yields "Operation could not be
> completed (error 0x05). Access is denied."
> as you can see, there's no mention of the word "denied" in the
> following log, so I can't figure out where or why it's getting
> denied. I've checked all my permissions repeatedly, and can find no
> problems.
>
> [2011/05/15 14:41:13.466276, 3] smbd/process.c:1485(process_smb)
> Transaction 1818 of length 2196 (0 toread)
> [2011/05/15 14:41:13.466410, 3] smbd/process.c:1294(switch_message)
> switch message SMBtrans (pid 6487) conn 0xb8fd6490
> [2011/05/15 14:41:13.466457, 4] smbd/uid.c:257(change_to_user)
> change_to_user: Skipping user change - already user
> [2011/05/15 14:41:13.466518, 3] smbd/ipc.c:545(handle_trans)
> trans <\PIPE\> data=2108 params=0 setup=2
> [2011/05/15 14:41:13.466570, 3] smbd/ipc.c:496(named_pipe)
> named pipe command on <> name
> [2011/05/15 14:41:13.466617, 3] smbd/ipc.c:460(api_fd_reply)
> Got API command 0x26 on pipe "spoolss" (pnum 2f54)
> [2011/05/15 14:41:13.466686, 3]
> rpc_server/srv_pipe_hnd.c:344(free_pipe_context)
> free_pipe_context: destroying talloc pool of size 0
> [2011/05/15 14:41:13.466736, 4] rpc_server/srv_pipe.c:2403(api_rpcTNP)
> api_rpcTNP: \spoolss op 0x8 - api_rpcTNP: rpc command:
> SPOOLSS_GETPRINTER
> [2011/05/15 14:41:13.466804, 4]
> rpc_server/srv_lsa_hnd.c:219(find_policy_by_hnd_internal)
> Found policy hnd[0] [0000] 00 00 00 00 36 00 00 00 00 00 00 00 D0
> 4D 71 46 ....6... .....MqF
> [0010] 57 19 00 00 W...
> [2011/05/15 14:41:13.466942, 4]
> rpc_server/srv_lsa_hnd.c:219(find_policy_by_hnd_internal)
> Found policy hnd[0] [0000] 00 00 00 00 36 00 00 00 00 00 00 00 D0
> 4D 71 46 ....6... .....MqF
> [0010] 57 19 00 00 W...
> [2011/05/15 14:41:13.467088, 4]
> rpc_server/srv_spoolss_nt.c:379(get_printer_snum)
> short name:F4440
> [2011/05/15 14:41:13.467553, 3]
> rpc_server/srv_pipe_hnd.c:344(free_pipe_context)
> free_pipe_context: destroying talloc pool of size 26
> [2011/05/15 14:41:13.467760, 3] smbd/process.c:1485(process_smb)
> Transaction 1819 of length 2196 (0 toread)
> [2011/05/15 14:41:13.467804, 3] smbd/process.c:1294(switch_message)
> switch message SMBtrans (pid 6487) conn 0xb8fd6490
> [2011/05/15 14:41:13.467845, 4] smbd/uid.c:257(change_to_user)
> change_to_user: Skipping user change - already user
> [2011/05/15 14:41:13.467886, 3] smbd/ipc.c:545(handle_trans)
> trans <\PIPE\> data=2108 params=0 setup=2
> [2011/05/15 14:41:13.467923, 3] smbd/ipc.c:496(named_pipe)
> named pipe command on <> name
> [2011/05/15 14:41:13.467972, 3] smbd/ipc.c:460(api_fd_reply)
> Got API command 0x26 on pipe "spoolss" (pnum 2f5b)
> [2011/05/15 14:41:13.468023, 3]
> rpc_server/srv_pipe_hnd.c:344(free_pipe_context)
> free_pipe_context: destroying talloc pool of size 0
> [2011/05/15 14:41:13.468060, 4] rpc_server/srv_pipe.c:2403(api_rpcTNP)
> api_rpcTNP: \spoolss op 0x8 - api_rpcTNP: rpc command:
> SPOOLSS_GETPRINTER
> [2011/05/15 14:41:13.468111, 4]
> rpc_server/srv_lsa_hnd.c:219(find_policy_by_hnd_internal)
> Found policy hnd[0] [0000] 00 00 00 00 36 00 00 00 00 00 00 00 D0
> 4D 71 46 ....6... .....MqF
> [0010] 57 19 00 00 W...
> [2011/05/15 14:41:13.468216, 4]
> rpc_server/srv_lsa_hnd.c:219(find_policy_by_hnd_internal)
> Found policy hnd[0] [0000] 00 00 00 00 36 00 00 00 00 00 00 00 D0
> 4D 71 46 ....6... .....MqF
> [0010] 57 19 00 00 W...
> [2011/05/15 14:41:13.468322, 4]
> rpc_server/srv_spoolss_nt.c:379(get_printer_snum)
> short name:F4440
> [2011/05/15 14:41:13.468681, 3]
> rpc_server/srv_pipe_hnd.c:344(free_pipe_context)
> free_pipe_context: destroying talloc pool of size 26
> [2011/05/15 14:41:13.468828, 3] smbd/process.c:1485(process_smb)
> Transaction 1820 of length 176 (0 toread)
> [2011/05/15 14:41:13.468878, 3] smbd/process.c:1294(switch_message)
> switch message SMBtrans (pid 6487) conn 0xb8fd6490
> [2011/05/15 14:41:13.468915, 4] smbd/uid.c:257(change_to_user)
> change_to_user: Skipping user change - already user
> [2011/05/15 14:41:13.468953, 3] smbd/ipc.c:545(handle_trans)
> trans <\PIPE\> data=88 params=0 setup=2
> [2011/05/15 14:41:13.468999, 3] smbd/ipc.c:496(named_pipe)
> named pipe command on <> name
> [2011/05/15 14:41:13.469045, 3] smbd/ipc.c:460(api_fd_reply)
> Got API command 0x26 on pipe "spoolss" (pnum 2f54)
> [2011/05/15 14:41:13.469095, 3]
> rpc_server/srv_pipe_hnd.c:344(free_pipe_context)
> free_pipe_context: destroying talloc pool of size 0
> [2011/05/15 14:41:13.469156, 4] rpc_server/srv_pipe.c:2403(api_rpcTNP)
> api_rpcTNP: \spoolss op 0x1a - api_rpcTNP: rpc command:
> SPOOLSS_GETPRINTERDATA
> [2011/05/15 14:41:13.469208, 4]
> rpc_server/srv_lsa_hnd.c:219(find_policy_by_hnd_internal)
> Found policy hnd[0] [0000] 00 00 00 00 36 00 00 00 00 00 00 00 D0
> 4D 71 46 ....6... .....MqF
> [0010] 57 19 00 00 W...
> [2011/05/15 14:41:13.469331, 4]
> rpc_server/srv_spoolss_nt.c:8577(_spoolss_GetPrinterDataEx)
> _spoolss_GetPrinterDataEx
> [2011/05/15 14:41:13.469367, 4]
> rpc_server/srv_lsa_hnd.c:219(find_policy_by_hnd_internal)
> Found policy hnd[0] [0000] 00 00 00 00 36 00 00 00 00 00 00 00 D0
> 4D 71 46 ....6... .....MqF
> [0010] 57 19 00 00 W...
> [2011/05/15 14:41:13.469495, 4]
> rpc_server/srv_spoolss_nt.c:379(get_printer_snum)
> short name:F4440
> [2011/05/15 14:41:13.469784, 3]
> rpc_server/srv_pipe_hnd.c:344(free_pipe_context)
> free_pipe_context: destroying talloc pool of size 0
> [2011/05/15 14:41:13.469918, 3] smbd/process.c:1485(process_smb)
> Transaction 1821 of length 106 (0 toread)
> [2011/05/15 14:41:13.469967, 3] smbd/process.c:1294(switch_message)
> switch message SMBntcreateX (pid 6487) conn 0xb8fd6490
> [2011/05/15 14:41:13.470003, 4] smbd/uid.c:257(change_to_user)
> change_to_user: Skipping user change - already user
> [2011/05/15 14:41:13.470063, 4] smbd/nttrans.c:283(nt_open_pipe)
> nt_open_pipe: Opening pipe \spoolss.
> [2011/05/15 14:41:13.470121, 4]
> rpc_server/srv_pipe_hnd.c:99(make_internal_rpc_pipe_p)
> Create pipe requested \spoolss
> [2011/05/15 14:41:13.470193, 3] smbd/sec_ctx.c:210(push_sec_ctx)
> push_sec_ctx(10001, 513) : sec_ctx_stack_ndx = 1
> [2011/05/15 14:41:13.470242, 3] smbd/uid.c:429(push_conn_ctx)
> push_conn_ctx(101) : conn_ctx_stack_ndx = 0
> [2011/05/15 14:41:13.470279, 3] smbd/sec_ctx.c:310(set_sec_ctx)
> setting sec ctx (0, 0) - sec_ctx_stack_ndx = 1
> [2011/05/15 14:41:13.471146, 3] smbd/sec_ctx.c:418(pop_sec_ctx)
> pop_sec_ctx (10001, 513) - sec_ctx_stack_ndx = 0
> [2011/05/15 14:41:13.471290, 4] lib/substitute.c:504(automount_server)
> Home server: density
> [2011/05/15 14:41:13.471361, 3] smbd/sec_ctx.c:210(push_sec_ctx)
> push_sec_ctx(10001, 513) : sec_ctx_stack_ndx = 1
> [2011/05/15 14:41:13.471415, 3] smbd/uid.c:429(push_conn_ctx)
> push_conn_ctx(101) : conn_ctx_stack_ndx = 0
> [2011/05/15 14:41:13.471458, 3] smbd/sec_ctx.c:310(set_sec_ctx)
> setting sec ctx (0, 0) - sec_ctx_stack_ndx = 1
> [2011/05/15 14:41:13.471538, 3] smbd/sec_ctx.c:418(pop_sec_ctx)
> pop_sec_ctx (10001, 513) - sec_ctx_stack_ndx = 0
> [2011/05/15 14:41:13.471599, 4]
> rpc_server/srv_pipe_hnd.c:162(make_internal_rpc_pipe_p)
> Created internal pipe \spoolss (pipes_open=0)
> [2011/05/15 14:41:13.471712, 3] smbd/process.c:1485(process_smb)
> Transaction 1822 of length 2244 (0 toread)
> [2011/05/15 14:41:13.471761, 3] smbd/process.c:1294(switch_message)
> switch message SMBtrans (pid 6487) conn 0xb8fd6490
> [2011/05/15 14:41:13.471811, 4] smbd/uid.c:257(change_to_user)
> change_to_user: Skipping user change - already user
> [2011/05/15 14:41:13.471865, 3] smbd/ipc.c:545(handle_trans)
> trans <\PIPE\> data=2156 params=0 setup=2
> [2011/05/15 14:41:13.471913, 3] smbd/ipc.c:496(named_pipe)
> named pipe command on <> name
> [2011/05/15 14:41:13.471954, 3] smbd/ipc.c:460(api_fd_reply)
> Got API command 0x26 on pipe "spoolss" (pnum 2f54)
> [2011/05/15 14:41:13.472017, 3]
> rpc_server/srv_pipe_hnd.c:344(free_pipe_context)
> free_pipe_context: destroying talloc pool of size 0
> [2011/05/15 14:41:13.472063, 4] rpc_server/srv_pipe.c:2403(api_rpcTNP)
> api_rpcTNP: \spoolss op 0x35 - api_rpcTNP: rpc command:
> SPOOLSS_GETPRINTERDRIVER2
> [2011/05/15 14:41:13.472138, 4]
> rpc_server/srv_spoolss_nt.c:5126(_spoolss_GetPrinterDriver2)
> _spoolss_GetPrinterDriver2
> [2011/05/15 14:41:13.472183, 4]
> rpc_server/srv_lsa_hnd.c:219(find_policy_by_hnd_internal)
> Found policy hnd[0] [0000] 00 00 00 00 36 00 00 00 00 00 00 00 D0
> 4D 71 46 ....6... .....MqF
> [0010] 57 19 00 00 W...
> [2011/05/15 14:41:13.472304, 4]
> rpc_server/srv_lsa_hnd.c:219(find_policy_by_hnd_internal)
> Found policy hnd[0] [0000] 00 00 00 00 36 00 00 00 00 00 00 00 D0
> 4D 71 46 ....6... .....MqF
> [0010] 57 19 00 00 W...
> [2011/05/15 14:41:13.472422, 4]
> rpc_server/srv_spoolss_nt.c:379(get_printer_snum)
> short name:F4440
> [2011/05/15 14:41:13.472804, 3]
> rpc_server/srv_pipe_hnd.c:344(free_pipe_context)
> free_pipe_context: destroying talloc pool of size 0
> [2011/05/15 14:41:13.472928, 3] smbd/process.c:1485(process_smb)
> Transaction 1823 of length 106 (0 toread)
> [2011/05/15 14:41:13.472970, 3] smbd/process.c:1294(switch_message)
> switch message SMBntcreateX (pid 6487) conn 0xb8fd6490
> [2011/05/15 14:41:13.473004, 4] smbd/uid.c:257(change_to_user)
> change_to_user: Skipping user change - already user
> [2011/05/15 14:41:13.473041, 4] smbd/nttrans.c:283(nt_open_pipe)
> nt_open_pipe: Opening pipe \spoolss.
> [2011/05/15 14:41:13.473088, 4]
> rpc_server/srv_pipe_hnd.c:99(make_internal_rpc_pipe_p)
> Create pipe requested \spoolss
> [2011/05/15 14:41:13.473148, 3] smbd/sec_ctx.c:210(push_sec_ctx)
> push_sec_ctx(10001, 513) : sec_ctx_stack_ndx = 1
> [2011/05/15 14:41:13.473188, 3] smbd/uid.c:429(push_conn_ctx)
> push_conn_ctx(101) : conn_ctx_stack_ndx = 0
> [2011/05/15 14:41:13.473220, 3] smbd/sec_ctx.c:310(set_sec_ctx)
> setting sec ctx (0, 0) - sec_ctx_stack_ndx = 1
> [2011/05/15 14:41:13.473315, 3] smbd/sec_ctx.c:418(pop_sec_ctx)
> pop_sec_ctx (10001, 513) - sec_ctx_stack_ndx = 0
> [2011/05/15 14:41:13.473375, 4] lib/substitute.c:504(automount_server)
> Home server: density
> [2011/05/15 14:41:13.473429, 3] smbd/sec_ctx.c:210(push_sec_ctx)
> push_sec_ctx(10001, 513) : sec_ctx_stack_ndx = 1
> [2011/05/15 14:41:13.473469, 3] smbd/uid.c:429(push_conn_ctx)
> push_conn_ctx(101) : conn_ctx_stack_ndx = 0
> [2011/05/15 14:41:13.473502, 3] smbd/sec_ctx.c:310(set_sec_ctx)
> setting sec ctx (0, 0) - sec_ctx_stack_ndx = 1
> [2011/05/15 14:41:13.473570, 3] smbd/sec_ctx.c:418(pop_sec_ctx)
> pop_sec_ctx (10001, 513) - sec_ctx_stack_ndx = 0
> [2011/05/15 14:41:13.473615, 4]
> rpc_server/srv_pipe_hnd.c:162(make_internal_rpc_pipe_p)
> Created internal pipe \spoolss (pipes_open=0)
> [2011/05/15 14:41:13.473692, 3] smbd/process.c:1485(process_smb)
> Transaction 1824 of length 2196 (0 toread)
> [2011/05/15 14:41:13.473731, 3] smbd/process.c:1294(switch_message)
> switch message SMBtrans (pid 6487) conn 0xb8fd6490
> [2011/05/15 14:41:13.473764, 4] smbd/uid.c:257(change_to_user)
> change_to_user: Skipping user change - already user
> [2011/05/15 14:41:13.473802, 3] smbd/ipc.c:545(handle_trans)
> trans <\PIPE\> data=2108 params=0 setup=2
> [2011/05/15 14:41:13.473839, 3] smbd/ipc.c:496(named_pipe)
> named pipe command on <> name
> [2011/05/15 14:41:13.473871, 3] smbd/ipc.c:460(api_fd_reply)
> Got API command 0x26 on pipe "spoolss" (pnum 2f54)
> [2011/05/15 14:41:13.473917, 3]
> rpc_server/srv_pipe_hnd.c:344(free_pipe_context)
> free_pipe_context: destroying talloc pool of size 0
> [2011/05/15 14:41:13.473953, 4] rpc_server/srv_pipe.c:2403(api_rpcTNP)
> api_rpcTNP: \spoolss op 0x8 - api_rpcTNP: rpc command:
> SPOOLSS_GETPRINTER
> [2011/05/15 14:41:13.474007, 4]
> rpc_server/srv_lsa_hnd.c:219(find_policy_by_hnd_internal)
> Found policy hnd[0] [0000] 00 00 00 00 36 00 00 00 00 00 00 00 D0
> 4D 71 46 ....6... .....MqF
> [0010] 57 19 00 00 W...
> [2011/05/15 14:41:13.474112, 4]
> rpc_server/srv_lsa_hnd.c:219(find_policy_by_hnd_internal)
> Found policy hnd[0] [0000] 00 00 00 00 36 00 00 00 00 00 00 00 D0
> 4D 71 46 ....6... .....MqF
> [0010] 57 19 00 00 W...
> [2011/05/15 14:41:13.474212, 4]
> rpc_server/srv_spoolss_nt.c:379(get_printer_snum)
> short name:F4440
> [2011/05/15 14:41:13.475005, 3]
> rpc_server/srv_pipe_hnd.c:344(free_pipe_context)
> free_pipe_context: destroying talloc pool of size 1342
> [2011/05/15 14:41:13.475164, 3] smbd/process.c:1485(process_smb)
> Transaction 1825 of length 106 (0 toread)
> [2011/05/15 14:41:13.475209, 3] smbd/process.c:1294(switch_message)
> switch message SMBntcreateX (pid 6487) conn 0xb8fd6490
> [2011/05/15 14:41:13.475243, 4] smbd/uid.c:257(change_to_user)
> change_to_user: Skipping user change - already user
> [2011/05/15 14:41:13.475281, 4] smbd/nttrans.c:283(nt_open_pipe)
> nt_open_pipe: Opening pipe \spoolss.
> [2011/05/15 14:41:13.475327, 4]
> rpc_server/srv_pipe_hnd.c:99(make_internal_rpc_pipe_p)
> Create pipe requested \spoolss
> [2011/05/15 14:41:13.475386, 3] smbd/sec_ctx.c:210(push_sec_ctx)
> push_sec_ctx(10001, 513) : sec_ctx_stack_ndx = 1
> [2011/05/15 14:41:13.475427, 3] smbd/uid.c:429(push_conn_ctx)
> push_conn_ctx(101) : conn_ctx_stack_ndx = 0
> [2011/05/15 14:41:13.475460, 3] smbd/sec_ctx.c:310(set_sec_ctx)
> setting sec ctx (0, 0) - sec_ctx_stack_ndx = 1
> [2011/05/15 14:41:13.475536, 3] smbd/sec_ctx.c:418(pop_sec_ctx)
> pop_sec_ctx (10001, 513) - sec_ctx_stack_ndx = 0
> [2011/05/15 14:41:13.475596, 4] lib/substitute.c:504(automount_server)
> Home server: density
> [2011/05/15 14:41:13.475653, 3] smbd/sec_ctx.c:210(push_sec_ctx)
> push_sec_ctx(10001, 513) : sec_ctx_stack_ndx = 1
> [2011/05/15 14:41:13.475695, 3] smbd/uid.c:429(push_conn_ctx)
> push_conn_ctx(101) : conn_ctx_stack_ndx = 0
> [2011/05/15 14:41:13.475729, 3] smbd/sec_ctx.c:310(set_sec_ctx)
> setting sec ctx (0, 0) - sec_ctx_stack_ndx = 1
> [2011/05/15 14:41:13.475800, 3] smbd/sec_ctx.c:418(pop_sec_ctx)
> pop_sec_ctx (10001, 513) - sec_ctx_stack_ndx = 0
> [2011/05/15 14:41:13.475876, 4]
> rpc_server/srv_pipe_hnd.c:162(make_internal_rpc_pipe_p)
> Created internal pipe \spoolss (pipes_open=0)
> [2011/05/15 14:41:13.476725, 3] smbd/process.c:1485(process_smb)
> Transaction 1826 of length 228 (0 toread)
> [2011/05/15 14:41:13.476887, 3] smbd/process.c:1294(switch_message)
> switch message SMBwriteX (pid 6487) conn 0xb8fd6490
> [2011/05/15 14:41:13.476930, 4] smbd/uid.c:257(change_to_user)
> change_to_user: Skipping user change - already user
> [2011/05/15 14:41:13.477031, 3]
> rpc_server/srv_pipe.c:1667(api_pipe_bind_req)
> api_pipe_bind_req: \PIPE\spoolss -> \PIPE\spoolss
> [2011/05/15 14:41:13.477080, 3]
> rpc_server/srv_pipe.c:998(check_bind_req)
> check_bind_req for \spoolss
> [2011/05/15 14:41:13.477151, 3] smbd/pipes.c:352(pipe_write_andx_done)
> writeX-IPC nwritten=160
> [2011/05/15 14:41:13.477242, 3] smbd/process.c:1485(process_smb)
> Transaction 1827 of length 228 (0 toread)
> [2011/05/15 14:41:13.477290, 3] smbd/process.c:1294(switch_message)
> switch message SMBwriteX (pid 6487) conn 0xb8fd6490
> [2011/05/15 14:41:13.477342, 4] smbd/uid.c:257(change_to_user)
> change_to_user: Skipping user change - already user
> [2011/05/15 14:41:13.477399, 3]
> rpc_server/srv_pipe.c:1667(api_pipe_bind_req)
> api_pipe_bind_req: \PIPE\spoolss -> \PIPE\spoolss
> [2011/05/15 14:41:13.477441, 3]
> rpc_server/srv_pipe.c:998(check_bind_req)
> check_bind_req for \spoolss
> [2011/05/15 14:41:13.477519, 3] smbd/pipes.c:352(pipe_write_andx_done)
> writeX-IPC nwritten=160
> [2011/05/15 14:41:13.477597, 3] smbd/process.c:1485(process_smb)
> Transaction 1828 of length 228 (0 toread)
> [2011/05/15 14:41:13.477643, 3] smbd/process.c:1294(switch_message)
> switch message SMBwriteX (pid 6487) conn 0xb8fd6490
> [2011/05/15 14:41:13.477684, 4] smbd/uid.c:257(change_to_user)
> change_to_user: Skipping user change - already user
> [2011/05/15 14:41:13.477743, 3]
> rpc_server/srv_pipe.c:1667(api_pipe_bind_req)
> api_pipe_bind_req: \PIPE\spoolss -> \PIPE\spoolss
> [2011/05/15 14:41:13.477787, 3]
> rpc_server/srv_pipe.c:998(check_bind_req)
> check_bind_req for \spoolss
> [2011/05/15 14:41:13.477867, 3] smbd/pipes.c:352(pipe_write_andx_done)
> writeX-IPC nwritten=160
> [2011/05/15 14:41:13.477942, 3] smbd/process.c:1485(process_smb)
> Transaction 1829 of length 63 (0 toread)
> [2011/05/15 14:41:13.477989, 3] smbd/process.c:1294(switch_message)
> switch message SMBreadX (pid 6487) conn 0xb8fd6490
> [2011/05/15 14:41:13.478024, 4] smbd/uid.c:257(change_to_user)
> change_to_user: Skipping user change - already user
> [2011/05/15 14:41:13.478074, 3] smbd/pipes.c:462(pipe_read_andx_done)
> readX-IPC min=1024 max=1024 nread=68
> [2011/05/15 14:41:13.478161, 3] smbd/process.c:1485(process_smb)
> Transaction 1830 of length 63 (0 toread)
> [2011/05/15 14:41:13.478212, 3] smbd/process.c:1294(switch_message)
> switch message SMBreadX (pid 6487) conn 0xb8fd6490
> [2011/05/15 14:41:13.478247, 4] smbd/uid.c:257(change_to_user)
> change_to_user: Skipping user change - already user
> [2011/05/15 14:41:13.478295, 3] smbd/pipes.c:462(pipe_read_andx_done)
> readX-IPC min=1024 max=1024 nread=68
> [2011/05/15 14:41:13.478367, 3] smbd/process.c:1485(process_smb)
> Transaction 1831 of length 63 (0 toread)
> [2011/05/15 14:41:13.478426, 3] smbd/process.c:1294(switch_message)
> switch message SMBreadX (pid 6487) conn 0xb8fd6490
> [2011/05/15 14:41:13.478463, 4] smbd/uid.c:257(change_to_user)
> change_to_user: Skipping user change - already user
> [2011/05/15 14:41:13.478511, 3] smbd/pipes.c:462(pipe_read_andx_done)
> readX-IPC min=1024 max=1024 nread=68
> [2011/05/15 14:41:13.478596, 3] smbd/process.c:1485(process_smb)
> Transaction 1832 of length 288 (0 toread)
> [2011/05/15 14:41:13.478643, 3] smbd/process.c:1294(switch_message)
> switch message SMBtrans (pid 6487) conn 0xb8fd6490
> [2011/05/15 14:41:13.478679, 4] smbd/uid.c:257(change_to_user)
> change_to_user: Skipping user change - already user
> [2011/05/15 14:41:13.478721, 3] smbd/ipc.c:545(handle_trans)
> trans <\PIPE\> data=200 params=0 setup=2
> [2011/05/15 14:41:13.478768, 3] smbd/ipc.c:496(named_pipe)
> named pipe command on <> name
> [2011/05/15 14:41:13.478849, 3] smbd/ipc.c:460(api_fd_reply)
> Got API command 0x26 on pipe "spoolss" (pnum 2fb5)
> [2011/05/15 14:41:13.478908, 3]
> rpc_server/srv_pipe_hnd.c:344(free_pipe_context)
> free_pipe_context: destroying talloc pool of size 169
> [2011/05/15 14:41:13.478957, 4] rpc_server/srv_pipe.c:2403(api_rpcTNP)
> api_rpcTNP: \spoolss op 0x45 - api_rpcTNP: rpc command:
> SPOOLSS_OPENPRINTEREX
> checking name: \\Density\F4440
> [2011/05/15 14:41:13.479069, 4]
> rpc_server/srv_lsa_hnd.c:191(create_policy_hnd_internal)
> Opened policy hnd[3] [0000] 00 00 00 00 97 00 00 00 00 00 00 00 D0
> 4D 79 48 ........ .....MyH
> [0010] 57 19 00 00 W...
> [2011/05/15 14:41:13.479191, 3]
> rpc_server/srv_spoolss_nt.c:396(set_printer_hnd_printertype)
> Setting printer type=\\Density\F4440
> Printer is a printer
> [2011/05/15 14:41:13.479247, 4]
> rpc_server/srv_spoolss_nt.c:436(set_printer_hnd_name)
> Setting printer name=\\Density\F4440 (len=15)
> set_printer_hnd_name: Printer found: F4440 -> F4440
> [2011/05/15 14:41:13.479508, 4]
> rpc_server/srv_lsa_hnd.c:219(find_policy_by_hnd_internal)
> Found policy hnd[0] [0000] 00 00 00 00 97 00 00 00 00 00 00 00 D0
> 4D 79 48 ........ .....MyH
> [0010] 57 19 00 00 W...
> [2011/05/15 14:41:13.479677, 4]
> rpc_server/srv_lsa_hnd.c:219(find_policy_by_hnd_internal)
> Found policy hnd[0] [0000] 00 00 00 00 97 00 00 00 00 00 00 00 D0
> 4D 79 48 ........ .....MyH
> [0010] 57 19 00 00 W...
> [2011/05/15 14:41:13.479801, 4]
> rpc_server/srv_spoolss_nt.c:379(get_printer_snum)
> short name:F4440
> [2011/05/15 14:41:13.481016, 4]
> rpc_server/srv_spoolss_nt.c:1732(_spoolss_OpenPrinterEx)
> Setting printer access = PRINTER_ACCESS_USE
> [2011/05/15 14:41:13.481138, 3]
> rpc_server/srv_pipe_hnd.c:344(free_pipe_context)
> free_pipe_context: destroying talloc pool of size 0
> [2011/05/15 14:41:13.481291, 3] smbd/process.c:1485(process_smb)
> Transaction 1833 of length 300 (0 toread)
> [2011/05/15 14:41:13.481342, 3] smbd/process.c:1294(switch_message)
> switch message SMBtrans (pid 6487) conn 0xb8fd6490
> [2011/05/15 14:41:13.481381, 4] smbd/uid.c:257(change_to_user)
> change_to_user: Skipping user change - already user
> [2011/05/15 14:41:13.481433, 3] smbd/ipc.c:545(handle_trans)
> trans <\PIPE\> data=212 params=0 setup=2
> [2011/05/15 14:41:13.481481, 3] smbd/ipc.c:496(named_pipe)
> named pipe command on <> name
> [2011/05/15 14:41:13.481522, 3] smbd/ipc.c:460(api_fd_reply)
> Got API command 0x26 on pipe "spoolss" (pnum 2fb6)
> [2011/05/15 14:41:13.481578, 3]
> rpc_server/srv_pipe_hnd.c:344(free_pipe_context)
> free_pipe_context: destroying talloc pool of size 169
> [2011/05/15 14:41:13.481625, 4] rpc_server/srv_pipe.c:2403(api_rpcTNP)
> api_rpcTNP: \spoolss op 0x45 - api_rpcTNP: rpc command:
> SPOOLSS_OPENPRINTEREX
> checking name: \\Density\ML-2851-ND
> [2011/05/15 14:41:13.481719, 4]
> rpc_server/srv_lsa_hnd.c:191(create_policy_hnd_internal)
> Opened policy hnd[4] [0000] 00 00 00 00 98 00 00 00 00 00 00 00 D0
> 4D 79 48 ........ .....MyH
> [0010] 57 19 00 00 W...
> [2011/05/15 14:41:13.481847, 3]
> rpc_server/srv_spoolss_nt.c:396(set_printer_hnd_printertype)
> Setting printer type=\\Density\ML-2851-ND
> Printer is a printer
> [2011/05/15 14:41:13.481893, 4]
> rpc_server/srv_spoolss_nt.c:436(set_printer_hnd_name)
> Setting printer name=\\Density\ML-2851-ND (len=20)
> set_printer_hnd_name: Printer found: ML-2851-ND -> ML-2851-ND
> [2011/05/15 14:41:13.482066, 4]
> rpc_server/srv_lsa_hnd.c:219(find_policy_by_hnd_internal)
> Found policy hnd[0] [0000] 00 00 00 00 98 00 00 00 00 00 00 00 D0
> 4D 79 48 ........ .....MyH
> [0010] 57 19 00 00 W...
> [2011/05/15 14:41:13.482176, 4]
> rpc_server/srv_lsa_hnd.c:219(find_policy_by_hnd_internal)
> Found policy hnd[0] [0000] 00 00 00 00 98 00 00 00 00 00 00 00 D0
> 4D 79 48 ........ .....MyH
> [0010] 57 19 00 00 W...
> [2011/05/15 14:41:13.482300, 4]
> rpc_server/srv_spoolss_nt.c:379(get_printer_snum)
> short name:ML-2851-ND
> [2011/05/15 14:41:13.483541, 4]
> rpc_server/srv_spoolss_nt.c:1732(_spoolss_OpenPrinterEx)
> Setting printer access = PRINTER_ACCESS_USE
> [2011/05/15 14:41:13.483657, 3]
> rpc_server/srv_pipe_hnd.c:344(free_pipe_context)
> free_pipe_context: destroying talloc pool of size 0
> [2011/05/15 14:41:13.483795, 3] smbd/process.c:1485(process_smb)
> Transaction 1834 of length 288 (0 toread)
> [2011/05/15 14:41:13.483841, 3] smbd/process.c:1294(switch_message)
> switch message SMBtrans (pid 6487) conn 0xb8fd6490
> [2011/05/15 14:41:13.483879, 4] smbd/uid.c:257(change_to_user)
> change_to_user: Skipping user change - already user
> [2011/05/15 14:41:13.483923, 3] smbd/ipc.c:545(handle_trans)
> trans <\PIPE\> data=200 params=0 setup=2
> [2011/05/15 14:41:13.483965, 3] smbd/ipc.c:496(named_pipe)
> named pipe command on <> name
> [2011/05/15 14:41:13.484001, 3] smbd/ipc.c:460(api_fd_reply)
> Got API command 0x26 on pipe "spoolss" (pnum 2fb7)
> [2011/05/15 14:41:13.484051, 3]
> rpc_server/srv_pipe_hnd.c:344(free_pipe_context)
> free_pipe_context: destroying talloc pool of size 169
> [2011/05/15 14:41:13.484107, 4] rpc_server/srv_pipe.c:2403(api_rpcTNP)
> api_rpcTNP: \spoolss op 0x45 - api_rpcTNP: rpc command:
> SPOOLSS_OPENPRINTEREX
> checking name: \\Density\F4440
> [2011/05/15 14:41:13.484196, 4]
> rpc_server/srv_lsa_hnd.c:191(create_policy_hnd_internal)
> Opened policy hnd[5] [0000] 00 00 00 00 99 00 00 00 00 00 00 00 D0
> 4D 79 48 ........ .....MyH
> [0010] 57 19 00 00 W...
> [2011/05/15 14:41:13.484323, 3]
> rpc_server/srv_spoolss_nt.c:396(set_printer_hnd_printertype)
> Setting printer type=\\Density\F4440
> Printer is a printer
> [2011/05/15 14:41:13.484377, 4]
> rpc_server/srv_spoolss_nt.c:436(set_printer_hnd_name)
> Setting printer name=\\Density\F4440 (len=15)
> set_printer_hnd_name: Printer found: F4440 -> F4440
> [2011/05/15 14:41:13.484633, 4]
> rpc_server/srv_lsa_hnd.c:219(find_policy_by_hnd_internal)
> Found policy hnd[0] [0000] 00 00 00 00 99 00 00 00 00 00 00 00 D0
> 4D 79 48 ........ .....MyH
> [0010] 57 19 00 00 W...
> [2011/05/15 14:41:13.484740, 4]
> rpc_server/srv_lsa_hnd.c:219(find_policy_by_hnd_internal)
> Found policy hnd[0] [0000] 00 00 00 00 99 00 00 00 00 00 00 00 D0
> 4D 79 48 ........ .....MyH
> [0010] 57 19 00 00 W...
> [2011/05/15 14:41:13.484857, 4]
> rpc_server/srv_spoolss_nt.c:379(get_printer_snum)
> short name:F4440
> [2011/05/15 14:41:13.486039, 4]
> rpc_server/srv_spoolss_nt.c:1732(_spoolss_OpenPrinterEx)
> Setting printer access = PRINTER_ACCESS_USE
> [2011/05/15 14:41:13.486167, 3]
> rpc_server/srv_pipe_hnd.c:344(free_pipe_context)
> free_pipe_context: destroying talloc pool of size 0
> [2011/05/15 14:41:13.486313, 3] smbd/process.c:1485(process_smb)
> Transaction 1835 of length 132 (0 toread)
> [2011/05/15 14:41:13.486371, 3] smbd/process.c:1294(switch_message)
> switch message SMBtrans (pid 6487) conn 0xb8fd6490
> [2011/05/15 14:41:13.486409, 4] smbd/uid.c:257(change_to_user)
> change_to_user: Skipping user change - already user
> [2011/05/15 14:41:13.486455, 3] smbd/ipc.c:545(handle_trans)
> trans <\PIPE\> data=44 params=0 setup=2
> [2011/05/15 14:41:13.486502, 3] smbd/ipc.c:496(named_pipe)
> named pipe command on <> name
> [2011/05/15 14:41:13.486544, 3] smbd/ipc.c:460(api_fd_reply)
> Got API command 0x26 on pipe "spoolss" (pnum 2fb5)
> [2011/05/15 14:41:13.486598, 3]
> rpc_server/srv_pipe_hnd.c:344(free_pipe_context)
> free_pipe_context: destroying talloc pool of size 0
> [2011/05/15 14:41:13.486643, 4] rpc_server/srv_pipe.c:2403(api_rpcTNP)
> api_rpcTNP: \spoolss op 0x1d - api_rpcTNP: rpc command:
> SPOOLSS_CLOSEPRINTER
> [2011/05/15 14:41:13.486704, 4]
> rpc_server/srv_lsa_hnd.c:219(find_policy_by_hnd_internal)
> Found policy hnd[2] [0000] 00 00 00 00 97 00 00 00 00 00 00 00 D0
> 4D 79 48 ........ .....MyH
> [0010] 57 19 00 00 W...
> [2011/05/15 14:41:13.486831, 4]
> rpc_server/srv_lsa_hnd.c:219(find_policy_by_hnd_internal)
> Found policy hnd[2] [0000] 00 00 00 00 97 00 00 00 00 00 00 00 D0
> 4D 79 48 ........ .....MyH
> [0010] 57 19 00 00 W...
> [2011/05/15 14:41:13.487026, 4]
> rpc_server/srv_lsa_hnd.c:219(find_policy_by_hnd_internal)
> Found policy hnd[2] [0000] 00 00 00 00 97 00 00 00 00 00 00 00 D0
> 4D 79 48 ........ .....MyH
> [0010] 57 19 00 00 W...
> [2011/05/15 14:41:13.487149, 3]
> rpc_server/srv_lsa_hnd.c:258(close_policy_hnd)
> Closed policy
> [2011/05/15 14:41:13.487196, 3]
> rpc_server/srv_pipe_hnd.c:344(free_pipe_context)
> free_pipe_context: destroying talloc pool of size 0
> [2011/05/15 14:41:13.487305, 3] smbd/process.c:1485(process_smb)
> Transaction 1836 of length 106 (0 toread)
> [2011/05/15 14:41:13.487352, 3] smbd/process.c:1294(switch_message)
> switch message SMBntcreateX (pid 6487) conn 0xb8fd6490
> [2011/05/15 14:41:13.487393, 4] smbd/uid.c:257(change_to_user)
> change_to_user: Skipping user change - already user
> [2011/05/15 14:41:13.487440, 4] smbd/nttrans.c:283(nt_open_pipe)
> nt_open_pipe: Opening pipe \spoolss.
> [2011/05/15 14:41:13.487499, 4]
> rpc_server/srv_pipe_hnd.c:99(make_internal_rpc_pipe_p)
> Create pipe requested \spoolss
> [2011/05/15 14:41:13.487570, 3] smbd/sec_ctx.c:210(push_sec_ctx)
> push_sec_ctx(10001, 513) : sec_ctx_stack_ndx = 1
> [2011/05/15 14:41:13.487624, 3] smbd/uid.c:429(push_conn_ctx)
> push_conn_ctx(101) : conn_ctx_stack_ndx = 0
> [2011/05/15 14:41:13.487662, 3] smbd/sec_ctx.c:310(set_sec_ctx)
> setting sec ctx (0, 0) - sec_ctx_stack_ndx = 1
> [2011/05/15 14:41:13.487763, 3] smbd/sec_ctx.c:418(pop_sec_ctx)
> pop_sec_ctx (10001, 513) - sec_ctx_stack_ndx = 0
> [2011/05/15 14:41:13.487839, 4] lib/substitute.c:504(automount_server)
> Home server: density
> [2011/05/15 14:41:13.487899, 3] smbd/sec_ctx.c:210(push_sec_ctx)
> push_sec_ctx(10001, 513) : sec_ctx_stack_ndx = 1
> [2011/05/15 14:41:13.487946, 3] smbd/uid.c:429(push_conn_ctx)
> push_conn_ctx(101) : conn_ctx_stack_ndx = 0
> [2011/05/15 14:41:13.487987, 3] smbd/sec_ctx.c:310(set_sec_ctx)
> setting sec ctx (0, 0) - sec_ctx_stack_ndx = 1
> [2011/05/15 14:41:13.488063, 3] smbd/sec_ctx.c:418(pop_sec_ctx)
> pop_sec_ctx (10001, 513) - sec_ctx_stack_ndx = 0
> [2011/05/15 14:41:13.488121, 4]
> rpc_server/srv_pipe_hnd.c:162(make_internal_rpc_pipe_p)
> Created internal pipe \spoolss (pipes_open=0)
> [2011/05/15 14:41:13.488198, 3] smbd/process.c:1485(process_smb)
> Transaction 1837 of length 132 (0 toread)
> [2011/05/15 14:41:13.488244, 3] smbd/process.c:1294(switch_message)
> switch message SMBtrans (pid 6487) conn 0xb8fd6490
> [2011/05/15 14:41:13.488285, 4] smbd/uid.c:257(change_to_user)
> change_to_user: Skipping user change - already user
> [2011/05/15 14:41:13.488328, 3] smbd/ipc.c:545(handle_trans)
> trans <\PIPE\> data=44 params=0 setup=2
> [2011/05/15 14:41:13.488372, 3] smbd/ipc.c:496(named_pipe)
> named pipe command on <> name
> [2011/05/15 14:41:13.488412, 3] smbd/ipc.c:460(api_fd_reply)
> Got API command 0x26 on pipe "spoolss" (pnum 2fb6)
> [2011/05/15 14:41:13.488461, 3]
> rpc_server/srv_pipe_hnd.c:344(free_pipe_context)
> free_pipe_context: destroying talloc pool of size 0
> [2011/05/15 14:41:13.488499, 4] rpc_server/srv_pipe.c:2403(api_rpcTNP)
> api_rpcTNP: \spoolss op 0x1d - api_rpcTNP: rpc command:
> SPOOLSS_CLOSEPRINTER
> [2011/05/15 14:41:13.488548, 4]
> rpc_server/srv_lsa_hnd.c:219(find_policy_by_hnd_internal)
> Found policy hnd[1] [0000] 00 00 00 00 98 00 00 00 00 00 00 00 D0
> 4D 79 48 ........ .....MyH
> [0010] 57 19 00 00 W...
> [2011/05/15 14:41:13.488673, 4]
> rpc_server/srv_lsa_hnd.c:219(find_policy_by_hnd_internal)
> Found policy hnd[1] [0000] 00 00 00 00 98 00 00 00 00 00 00 00 D0
> 4D 79 48 ........ .....MyH
> [0010] 57 19 00 00 W...
> [2011/05/15 14:41:13.488801, 4]
> rpc_server/srv_lsa_hnd.c:219(find_policy_by_hnd_internal)
> Found policy hnd[1] [0000] 00 00 00 00 98 00 00 00 00 00 00 00 D0
> 4D 79 48 ........ .....MyH
> [0010] 57 19 00 00 W...
> [2011/05/15 14:41:13.488939, 3]
> rpc_server/srv_lsa_hnd.c:258(close_policy_hnd)
> Closed policy
> [2011/05/15 14:41:13.488979, 3]
> rpc_server/srv_pipe_hnd.c:344(free_pipe_context)
> free_pipe_context: destroying talloc pool of size 0
> [2011/05/15 14:41:13.489080, 3] smbd/process.c:1485(process_smb)
> Transaction 1838 of length 45 (0 toread)
> [2011/05/15 14:41:13.489127, 3] smbd/process.c:1294(switch_message)
> switch message SMBclose (pid 6487) conn 0xb8fd6490
> [2011/05/15 14:41:13.489167, 4] smbd/uid.c:257(change_to_user)
> change_to_user: Skipping user change - already user
> [2011/05/15 14:41:13.489208, 3] smbd/reply.c:4634(reply_close)
> close fd=-1 fnum=12213 (numopen=7)
> [2011/05/15 14:41:13.489299, 3] smbd/process.c:1485(process_smb)
> Transaction 1839 of length 2196 (0 toread)
> [2011/05/15 14:41:13.489345, 3] smbd/process.c:1294(switch_message)
> switch message SMBtrans (pid 6487) conn 0xb8fd6490
> [2011/05/15 14:41:13.489385, 4] smbd/uid.c:257(change_to_user)
> change_to_user: Skipping user change - already user
> [2011/05/15 14:41:13.489430, 3] smbd/ipc.c:545(handle_trans)
> trans <\PIPE\> data=2108 params=0 setup=2
> [2011/05/15 14:41:13.489474, 3] smbd/ipc.c:496(named_pipe)
> named pipe command on <> name
> [2011/05/15 14:41:13.489513, 3] smbd/ipc.c:460(api_fd_reply)
> Got API command 0x26 on pipe "spoolss" (pnum 2f54)
> [2011/05/15 14:41:13.489565, 3]
> rpc_server/srv_pipe_hnd.c:344(free_pipe_context)
> free_pipe_context: destroying talloc pool of size 0
> [2011/05/15 14:41:13.489609, 4] rpc_server/srv_pipe.c:2403(api_rpcTNP)
> api_rpcTNP: \spoolss op 0x8 - api_rpcTNP: rpc command:
> SPOOLSS_GETPRINTER
> [2011/05/15 14:41:13.489669, 4]
> rpc_server/srv_lsa_hnd.c:219(find_policy_by_hnd_internal)
> Found policy hnd[1] [0000] 00 00 00 00 36 00 00 00 00 00 00 00 D0
> 4D 71 46 ....6... .....MqF
> [0010] 57 19 00 00 W...
> [2011/05/15 14:41:13.489789, 4]
> rpc_server/srv_lsa_hnd.c:219(find_policy_by_hnd_internal)
> Found policy hnd[1] [0000] 00 00 00 00 36 00 00 00 00 00 00 00 D0
> 4D 71 46 ....6... .....MqF
> [0010] 57 19 00 00 W...
> [2011/05/15 14:41:13.489904, 4]
> rpc_server/srv_spoolss_nt.c:379(get_printer_snum)
> short name:F4440
> [2011/05/15 14:41:13.490324, 3]
> rpc_server/srv_pipe_hnd.c:344(free_pipe_context)
> free_pipe_context: destroying talloc pool of size 26
> [2011/05/15 14:41:13.490455, 3] smbd/process.c:1485(process_smb)
> Transaction 1840 of length 228 (0 toread)
> [2011/05/15 14:41:13.490504, 3] smbd/process.c:1294(switch_message)
> switch message SMBwriteX (pid 6487) conn 0xb8fd6490
> [2011/05/15 14:41:13.490544, 4] smbd/uid.c:257(change_to_user)
> change_to_user: Skipping user change - already user
> [2011/05/15 14:41:13.490608, 3]
> rpc_server/srv_pipe.c:1667(api_pipe_bind_req)
> api_pipe_bind_req: \PIPE\spoolss -> \PIPE\spoolss
> [2011/05/15 14:41:13.490650, 3]
> rpc_server/srv_pipe.c:998(check_bind_req)
> check_bind_req for \spoolss
> [2011/05/15 14:41:13.490707, 3] smbd/pipes.c:352(pipe_write_andx_done)
> writeX-IPC nwritten=160
> [2011/05/15 14:41:13.492242, 3] smbd/process.c:1485(process_smb)
> Transaction 1841 of length 63 (0 toread)
> [2011/05/15 14:41:13.492360, 3] smbd/process.c:1294(switch_message)
> switch message SMBreadX (pid 6487) conn 0xb8fd6490
> [2011/05/15 14:41:13.492400, 4] smbd/uid.c:257(change_to_user)
> change_to_user: Skipping user change - already user
> [2011/05/15 14:41:13.492474, 3] smbd/pipes.c:462(pipe_read_andx_done)
> readX-IPC min=1024 max=1024 nread=68
> [2011/05/15 14:41:13.493123, 3] smbd/process.c:1485(process_smb)
> Transaction 1842 of length 288 (0 toread)
> [2011/05/15 14:41:13.493237, 3] smbd/process.c:1294(switch_message)
> switch message SMBtrans (pid 6487) conn 0xb8fd6490
> [2011/05/15 14:41:13.493275, 4] smbd/uid.c:257(change_to_user)
> change_to_user: Skipping user change - already user
> [2011/05/15 14:41:13.493327, 3] smbd/ipc.c:545(handle_trans)
> trans <\PIPE\> data=200 params=0 setup=2
> [2011/05/15 14:41:13.493375, 3] smbd/ipc.c:496(named_pipe)
> named pipe command on <> name
> [2011/05/15 14:41:13.493438, 3] smbd/ipc.c:460(api_fd_reply)
> Got API command 0x26 on pipe "spoolss" (pnum 2fb8)
> [2011/05/15 14:41:13.493497, 3]
> rpc_server/srv_pipe_hnd.c:344(free_pipe_context)
> free_pipe_context: destroying talloc pool of size 169
> [2011/05/15 14:41:13.493546, 4] rpc_server/srv_pipe.c:2403(api_rpcTNP)
> api_rpcTNP: \spoolss op 0x45 - api_rpcTNP: rpc command:
> SPOOLSS_OPENPRINTEREX
> checking name: \\Density\F4440
> [2011/05/15 14:41:13.493644, 4]
> rpc_server/srv_lsa_hnd.c:191(create_policy_hnd_internal)
> Opened policy hnd[4] [0000] 00 00 00 00 9A 00 00 00 00 00 00 00 D0
> 4D 79 48 ........ .....MyH
> [0010] 57 19 00 00 W...
> [2011/05/15 14:41:13.493765, 3]
> rpc_server/srv_spoolss_nt.c:396(set_printer_hnd_printertype)
> Setting printer type=\\Density\F4440
> Printer is a printer
> [2011/05/15 14:41:13.493820, 4]
> rpc_server/srv_spoolss_nt.c:436(set_printer_hnd_name)
> Setting printer name=\\Density\F4440 (len=15)
> set_printer_hnd_name: Printer found: F4440 -> F4440
> [2011/05/15 14:41:13.494069, 4]
> rpc_server/srv_lsa_hnd.c:219(find_policy_by_hnd_internal)
> Found policy hnd[0] [0000] 00 00 00 00 9A 00 00 00 00 00 00 00 D0
> 4D 79 48 ........ .....MyH
> [0010] 57 19 00 00 W...
> [2011/05/15 14:41:13.494199, 4]
> rpc_server/srv_lsa_hnd.c:219(find_policy_by_hnd_internal)
> Found policy hnd[0] [0000] 00 00 00 00 9A 00 00 00 00 00 00 00 D0
> 4D 79 48 ........ .....MyH
> [0010] 57 19 00 00 W...
> [2011/05/15 14:41:13.494320, 4]
> rpc_server/srv_spoolss_nt.c:379(get_printer_snum)
> short name:F4440
> [2011/05/15 14:41:13.495569, 4]
> rpc_server/srv_spoolss_nt.c:1732(_spoolss_OpenPrinterEx)
> Setting printer access = PRINTER_ACCESS_USE
> [2011/05/15 14:41:13.495700, 3]
> rpc_server/srv_pipe_hnd.c:344(free_pipe_context)
> free_pipe_context: destroying talloc pool of size 0
> [2011/05/15 14:41:13.495850, 3] smbd/process.c:1485(process_smb)
> Transaction 1843 of length 45 (0 toread)
> [2011/05/15 14:41:13.495900, 3] smbd/process.c:1294(switch_message)
> switch message SMBclose (pid 6487) conn 0xb8fd6490
> [2011/05/15 14:41:13.495937, 4] smbd/uid.c:257(change_to_user)
> change_to_user: Skipping user change - already user
> [2011/05/15 14:41:13.495974, 3] smbd/reply.c:4634(reply_close)
> close fd=-1 fnum=12214 (numopen=6)
> [2011/05/15 14:41:13.496116, 3] smbd/process.c:1485(process_smb)
> Transaction 1844 of length 176 (0 toread)
> [2011/05/15 14:41:13.496162, 3] smbd/process.c:1294(switch_message)
> switch message SMBtrans (pid 6487) conn 0xb8fd6490
> [2011/05/15 14:41:13.496198, 4] smbd/uid.c:257(change_to_user)
> change_to_user: Skipping user change - already user
> [2011/05/15 14:41:13.496238, 3] smbd/ipc.c:545(handle_trans)
> trans <\PIPE\> data=88 params=0 setup=2
> [2011/05/15 14:41:13.496284, 3] smbd/ipc.c:496(named_pipe)
> named pipe command on <> name
> [2011/05/15 14:41:13.496326, 3] smbd/ipc.c:460(api_fd_reply)
> Got API command 0x26 on pipe "spoolss" (pnum 2f54)
> [2011/05/15 14:41:13.496381, 3]
> rpc_server/srv_pipe_hnd.c:344(free_pipe_context)
> free_pipe_context: destroying talloc pool of size 0
> [2011/05/15 14:41:13.496425, 4] rpc_server/srv_pipe.c:2403(api_rpcTNP)
> api_rpcTNP: \spoolss op 0x1a - api_rpcTNP: rpc command:
> SPOOLSS_GETPRINTERDATA
> [2011/05/15 14:41:13.496493, 4]
> rpc_server/srv_lsa_hnd.c:219(find_policy_by_hnd_internal)
> Found policy hnd[2] [0000] 00 00 00 00 36 00 00 00 00 00 00 00 D0
> 4D 71 46 ....6... .....MqF
> [0010] 57 19 00 00 W...
> [2011/05/15 14:41:13.496631, 4]
> rpc_server/srv_spoolss_nt.c:8577(_spoolss_GetPrinterDataEx)
> _spoolss_GetPrinterDataEx
> [2011/05/15 14:41:13.496668, 4]
> rpc_server/srv_lsa_hnd.c:219(find_policy_by_hnd_internal)
> Found policy hnd[2] [0000] 00 00 00 00 36 00 00 00 00 00 00 00 D0
> 4D 71 46 ....6... .....MqF
> [0010] 57 19 00 00 W...
> [2011/05/15 14:41:13.496791, 4]
> rpc_server/srv_spoolss_nt.c:379(get_printer_snum)
> short name:F4440
> [2011/05/15 14:41:13.497174, 3]
> rpc_server/srv_pipe_hnd.c:344(free_pipe_context)
> free_pipe_context: destroying talloc pool of size 0
> [2011/05/15 14:41:13.497295, 3] smbd/process.c:1485(process_smb)
> Transaction 1845 of length 132 (0 toread)
> [2011/05/15 14:41:13.497343, 3] smbd/process.c:1294(switch_message)
> switch message SMBtrans (pid 6487) conn 0xb8fd6490
> [2011/05/15 14:41:13.497379, 4] smbd/uid.c:257(change_to_user)
> change_to_user: Skipping user change - already user
> [2011/05/15 14:41:13.497419, 3] smbd/ipc.c:545(handle_trans)
> trans <\PIPE\> data=44 params=0 setup=2
> [2011/05/15 14:41:13.497464, 3] smbd/ipc.c:496(named_pipe)
> named pipe command on <> name
> [2011/05/15 14:41:13.497504, 3] smbd/ipc.c:460(api_fd_reply)
> Got API command 0x26 on pipe "spoolss" (pnum 2fb8)
> [2011/05/15 14:41:13.497553, 3]
> rpc_server/srv_pipe_hnd.c:344(free_pipe_context)
> free_pipe_context: destroying talloc pool of size 0
> [2011/05/15 14:41:13.497596, 4] rpc_server/srv_pipe.c:2403(api_rpcTNP)
> api_rpcTNP: \spoolss op 0x1d - api_rpcTNP: rpc command:
> SPOOLSS_CLOSEPRINTER
> [2011/05/15 14:41:13.497650, 4]
> rpc_server/srv_lsa_hnd.c:219(find_policy_by_hnd_internal)
> Found policy hnd[0] [0000] 00 00 00 00 9A 00 00 00 00 00 00 00 D0
> 4D 79 48 ........ .....MyH
> [0010] 57 19 00 00 W...
> [2011/05/15 14:41:13.497782, 4]
> rpc_server/srv_lsa_hnd.c:219(find_policy_by_hnd_internal)
> Found policy hnd[0] [0000] 00 00 00 00 9A 00 00 00 00 00 00 00 D0
> 4D 79 48 ........ .....MyH
> [0010] 57 19 00 00 W...
> [2011/05/15 14:41:13.497900, 4]
> rpc_server/srv_lsa_hnd.c:219(find_policy_by_hnd_internal)
> Found policy hnd[0] [0000] 00 00 00 00 9A 00 00 00 00 00 00 00 D0
> 4D 79 48 ........ .....MyH
> [0010] 57 19 00 00 W...
> [2011/05/15 14:41:13.498026, 3]
> rpc_server/srv_lsa_hnd.c:258(close_policy_hnd)
> Closed policy
> [2011/05/15 14:41:13.498067, 3]
> rpc_server/srv_pipe_hnd.c:344(free_pipe_context)
> free_pipe_context: destroying talloc pool of size 0
> [2011/05/15 14:41:13.498168, 3] smbd/process.c:1485(process_smb)
> Transaction 1846 of length 106 (0 toread)
> [2011/05/15 14:41:13.498214, 3] smbd/process.c:1294(switch_message)
> switch message SMBntcreateX (pid 6487) conn 0xb8fd6490
> [2011/05/15 14:41:13.498251, 4] smbd/uid.c:257(change_to_user)
> change_to_user: Skipping user change - already user
> [2011/05/15 14:41:13.498289, 4] smbd/nttrans.c:283(nt_open_pipe)
> nt_open_pipe: Opening pipe \spoolss.
> [2011/05/15 14:41:13.498346, 4]
> rpc_server/srv_pipe_hnd.c:99(make_internal_rpc_pipe_p)
> Create pipe requested \spoolss
> [2011/05/15 14:41:13.498414, 3] smbd/sec_ctx.c:210(push_sec_ctx)
> push_sec_ctx(10001, 513) : sec_ctx_stack_ndx = 1
> [2011/05/15 14:41:13.498462, 3] smbd/uid.c:429(push_conn_ctx)
> push_conn_ctx(101) : conn_ctx_stack_ndx = 0
> [2011/05/15 14:41:13.498503, 3] smbd/sec_ctx.c:310(set_sec_ctx)
> setting sec ctx (0, 0) - sec_ctx_stack_ndx = 1
> [2011/05/15 14:41:13.498597, 3] smbd/sec_ctx.c:418(pop_sec_ctx)
> pop_sec_ctx (10001, 513) - sec_ctx_stack_ndx = 0
> [2011/05/15 14:41:13.498665, 4] lib/substitute.c:504(automount_server)
> Home server: density
> [2011/05/15 14:41:13.498722, 3] smbd/sec_ctx.c:210(push_sec_ctx)
> push_sec_ctx(10001, 513) : sec_ctx_stack_ndx = 1
> [2011/05/15 14:41:13.498769, 3] smbd/uid.c:429(push_conn_ctx)
> push_conn_ctx(101) : conn_ctx_stack_ndx = 0
> [2011/05/15 14:41:13.498810, 3] smbd/sec_ctx.c:310(set_sec_ctx)
> setting sec ctx (0, 0) - sec_ctx_stack_ndx = 1
> [2011/05/15 14:41:13.498893, 3] smbd/sec_ctx.c:418(pop_sec_ctx)
> pop_sec_ctx (10001, 513) - sec_ctx_stack_ndx = 0
> [2011/05/15 14:41:13.498973, 4]
> rpc_server/srv_pipe_hnd.c:162(make_internal_rpc_pipe_p)
> Created internal pipe \spoolss (pipes_open=0)
> [2011/05/15 14:41:13.499050, 3] smbd/process.c:1485(process_smb)
> Transaction 1847 of length 2244 (0 toread)
> [2011/05/15 14:41:13.499096, 3] smbd/process.c:1294(switch_message)
> switch message SMBtrans (pid 6487) conn 0xb8fd6490
> [2011/05/15 14:41:13.499132, 4] smbd/uid.c:257(change_to_user)
> change_to_user: Skipping user change - already user
> [2011/05/15 14:41:13.499192, 3] smbd/ipc.c:545(handle_trans)
> trans <\PIPE\> data=2156 params=0 setup=2
> [2011/05/15 14:41:13.499239, 3] smbd/ipc.c:496(named_pipe)
> named pipe command on <> name
> [2011/05/15 14:41:13.499272, 3] smbd/ipc.c:460(api_fd_reply)
> Got API command 0x26 on pipe "spoolss" (pnum 2f54)
> [2011/05/15 14:41:13.499321, 3]
> rpc_server/srv_pipe_hnd.c:344(free_pipe_context)
> free_pipe_context: destroying talloc pool of size 0
> [2011/05/15 14:41:13.499367, 4] rpc_server/srv_pipe.c:2403(api_rpcTNP)
> api_rpcTNP: \spoolss op 0x35 - api_rpcTNP: rpc command:
> SPOOLSS_GETPRINTERDRIVER2
> [2011/05/15 14:41:13.499429, 4]
> rpc_server/srv_spoolss_nt.c:5126(_spoolss_GetPrinterDriver2)
> _spoolss_GetPrinterDriver2
> [2011/05/15 14:41:13.499470, 4]
> rpc_server/srv_lsa_hnd.c:219(find_policy_by_hnd_internal)
> Found policy hnd[1] [0000] 00 00 00 00 36 00 00 00 00 00 00 00 D0
> 4D 71 46 ....6... .....MqF
> [0010] 57 19 00 00 W...
> [2011/05/15 14:41:13.499588, 4]
> rpc_server/srv_lsa_hnd.c:219(find_policy_by_hnd_internal)
> Found policy hnd[1] [0000] 00 00 00 00 36 00 00 00 00 00 00 00 D0
> 4D 71 46 ....6... .....MqF
> [0010] 57 19 00 00 W...
> [2011/05/15 14:41:13.499704, 4]
> rpc_server/srv_spoolss_nt.c:379(get_printer_snum)
> short name:F4440
> [2011/05/15 14:41:13.500045, 3]
> rpc_server/srv_pipe_hnd.c:344(free_pipe_context)
> free_pipe_context: destroying talloc pool of size 0
> [2011/05/15 14:41:13.500161, 3] smbd/process.c:1485(process_smb)
> Transaction 1848 of length 45 (0 toread)
> [2011/05/15 14:41:13.500208, 3] smbd/process.c:1294(switch_message)
> switch message SMBclose (pid 6487) conn 0xb8fd6490
> [2011/05/15 14:41:13.500249, 4] smbd/uid.c:257(change_to_user)
> change_to_user: Skipping user change - already user
> [2011/05/15 14:41:13.500289, 3] smbd/reply.c:4634(reply_close)
> close fd=-1 fnum=12216 (numopen=6)
> [2011/05/15 14:41:13.501024, 3] smbd/process.c:1485(process_smb)
> Transaction 1849 of length 228 (0 toread)
> [2011/05/15 14:41:13.501136, 3] smbd/process.c:1294(switch_message)
> switch message SMBwriteX (pid 6487) conn 0xb8fd6490
> [2011/05/15 14:41:13.501176, 4] smbd/uid.c:257(change_to_user)
> change_to_user: Skipping user change - already user
> [2011/05/15 14:41:13.501255, 3]
> rpc_server/srv_pipe.c:1667(api_pipe_bind_req)
> api_pipe_bind_req: \PIPE\spoolss -> \PIPE\spoolss
> [2011/05/15 14:41:13.501301, 3]
> rpc_server/srv_pipe.c:998(check_bind_req)
> check_bind_req for \spoolss
> [2011/05/15 14:41:13.501359, 3] smbd/sec_ctx.c:310(set_sec_ctx)
> setting sec ctx (0, 0) - sec_ctx_stack_ndx = 0
>
still noone knows how to debug the printing process/access denied messages?
More information about the samba
mailing list