thr3ads.net - samba - [Samba] Problem printing from one user only [May 2011]

If this information is useful, please help other people find it:
Share via:

Christ Schlacta

2011-May-16 01:12 UTC

[Samba] Problem printing from one user only

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

Christ Schlacta

2011-May-23 19:59 UTC

head link

[Samba] Problem printing from one user only

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?

Apparently Analagous Threads

Search for more reasonably related threads

samba - May 2011 - Problem printing from one user only

[Samba] Problem printing from one user only

[Samba] Problem printing from one user only

Apparently Analagous Threads