[Samba] vfs_shadow_copy2 woes / WITH logs

Matthias Leopold matthias.leopold at meduniwien.ac.at
Wed Feb 21 13:45:29 UTC 2018


Hi,

finally everything is working fine on my Samba 4.6 AD Domain member 
server after _exactly_ following 
https://wiki.samba.org/index.php/Setting_up_a_Share_Using_Windows_ACLs 
(no more fiddling with acl_xattr:ignore system acls = yes, thanks 
Rowland Penny).

Next thing i wanted to try is vfs_shadow_copy2 (with LVM snapshots: 
https://wiki.samba.org/index.php/Rotating_LVM_snapshots_for_shadow_copy). 
But as soon as i enable "vfs objects = shadow_copy2" for a share i can't 
administer file permissions ("Security") via Windows (as "Domain Admin") 
anymore. This happens even without any snapshots (it's the same when 
there are snapshots).
Why?

I tried disabling SELinux, no avail. I'm attaching some "log level = 9" 
logs and hope someone can enlighten me.

Thanks
Matthias
-------------- next part --------------
[2018/02/21 14:26:38.414299,  5] ../lib/dbwrap/dbwrap.c:159(dbwrap_check_lock_order)
  check lock order 2 for /var/lib/samba/lock/serverid.tdb
[2018/02/21 14:26:38.414404,  5] ../lib/dbwrap/dbwrap.c:127(dbwrap_lock_order_state_destructor)
  release lock order 2 for /var/lib/samba/lock/serverid.tdb
[2018/02/21 14:26:38.414444,  5] ../lib/util/util_net.c:1057(print_socket_options)
  Socket options:
  	SO_KEEPALIVE = 1
  	SO_REUSEADDR = 1
  	SO_BROADCAST = 0
  	TCP_NODELAY = 1
  	TCP_KEEPCNT = 9
  	TCP_KEEPIDLE = 7200
  	TCP_KEEPINTVL = 75
  	IPTOS_LOWDELAY = 0
  	IPTOS_THROUGHPUT = 0
  	SO_REUSEPORT = 1
  	SO_SNDBUF = 87040
  	SO_RCVBUF = 369280
  	SO_SNDLOWAT = 1
  	SO_RCVLOWAT = 1
  	SO_SNDTIMEO = 0
  	SO_RCVTIMEO = 0
  	TCP_QUICKACK = 1
  	TCP_DEFER_ACCEPT = 0
[2018/02/21 14:26:38.414562,  5] ../lib/util/util_net.c:1057(print_socket_options)
  Socket options:
  	SO_KEEPALIVE = 1
  	SO_REUSEADDR = 1
  	SO_BROADCAST = 0
  	TCP_NODELAY = 1
  	TCP_KEEPCNT = 9
  	TCP_KEEPIDLE = 7200
  	TCP_KEEPINTVL = 75
  	IPTOS_LOWDELAY = 0
  	IPTOS_THROUGHPUT = 0
  	SO_REUSEPORT = 1
  	SO_SNDBUF = 87040
  	SO_RCVBUF = 369280
  	SO_SNDLOWAT = 1
  	SO_RCVLOWAT = 1
  	SO_SNDTIMEO = 0
  	SO_RCVTIMEO = 0
  	TCP_QUICKACK = 1
  	TCP_DEFER_ACCEPT = 0
[2018/02/21 14:26:38.414757,  3] ../lib/util/access.c:361(allow_access)
  Allowed connection from 111.222.333.444 (111.222.333.444)
[2018/02/21 14:26:38.414840,  6] ../source3/param/loadparm.c:2307(lp_file_list_changed)
  lp_file_list_changed()
  file /etc/samba/smb.conf -> /etc/samba/smb.conf  last mod_time: Wed Feb 21 14:25:01 2018
  
[2018/02/21 14:26:38.414894,  3] ../source3/smbd/oplock.c:1322(init_oplocks)
  init_oplocks: initializing messages.
[2018/02/21 14:26:38.414910,  5] ../source3/lib/messages.c:448(messaging_register)
  Registering messaging pointer for type 774 - private_data=0x556d3e67ebc0
[2018/02/21 14:26:38.414927,  5] ../source3/lib/messages.c:448(messaging_register)
  Registering messaging pointer for type 778 - private_data=0x556d3e67ebc0
[2018/02/21 14:26:38.414940,  5] ../source3/lib/messages.c:448(messaging_register)
  Registering messaging pointer for type 770 - private_data=0x556d3e67ebc0
[2018/02/21 14:26:38.414953,  5] ../source3/lib/messages.c:448(messaging_register)
  Registering messaging pointer for type 787 - private_data=0x556d3e67ebc0
[2018/02/21 14:26:38.414965,  5] ../source3/lib/messages.c:448(messaging_register)
  Registering messaging pointer for type 779 - private_data=0x556d3e67ebc0
[2018/02/21 14:26:38.414978,  5] ../source3/lib/messages.c:448(messaging_register)
  Registering messaging pointer for type 15 - private_data=(nil)
[2018/02/21 14:26:38.414991,  5] ../source3/lib/messages.c:463(messaging_register)
  Overriding messaging pointer for type 15 - private_data=(nil)
[2018/02/21 14:26:38.415004,  5] ../source3/lib/messages.c:495(messaging_deregister)
  Deregistering messaging pointer for type 16 - private_data=(nil)
[2018/02/21 14:26:38.415022,  5] ../source3/lib/messages.c:448(messaging_register)
  Registering messaging pointer for type 16 - private_data=0x556d3e67ebc0
[2018/02/21 14:26:38.415036,  5] ../source3/lib/messages.c:495(messaging_deregister)
  Deregistering messaging pointer for type 33 - private_data=0x556d3e677540
[2018/02/21 14:26:38.415049,  5] ../source3/lib/messages.c:448(messaging_register)
  Registering messaging pointer for type 33 - private_data=0x556d3e67ebc0
[2018/02/21 14:26:38.415062,  5] ../source3/lib/messages.c:495(messaging_deregister)
  Deregistering messaging pointer for type 790 - private_data=(nil)
[2018/02/21 14:26:38.415074,  5] ../source3/lib/messages.c:448(messaging_register)
  Registering messaging pointer for type 790 - private_data=0x556d3e67ebc0
[2018/02/21 14:26:38.415087,  5] ../source3/lib/messages.c:495(messaging_deregister)
  Deregistering messaging pointer for type 791 - private_data=(nil)
[2018/02/21 14:26:38.415100,  5] ../source3/lib/messages.c:495(messaging_deregister)
  Deregistering messaging pointer for type 1 - private_data=(nil)
[2018/02/21 14:26:38.415113,  5] ../source3/lib/messages.c:448(messaging_register)
  Registering messaging pointer for type 1 - private_data=(nil)
[2018/02/21 14:26:38.415262,  6] ../source3/smbd/process.c:1956(process_smb)
  got message type 0x0 of len 0x9b
[2018/02/21 14:26:38.415286,  3] ../source3/smbd/process.c:1958(process_smb)
  Transaction 0 of length 159 (0 toread)
[2018/02/21 14:26:38.415302,  5] ../source3/lib/util.c:171(show_msg)
[2018/02/21 14:26:38.415313,  5] ../source3/lib/util.c:181(show_msg)
  size=155
  smb_com=0x72
  smb_rcls=0
  smb_reh=0
  smb_err=0
  smb_flg=24
  smb_flg2=51283
  smb_tid=65535
  smb_pid=65279
  smb_uid=0
  smb_mid=0
  smt_wct=0
  smb_bcc=120
[2018/02/21 14:26:38.415388,  3] ../source3/smbd/process.c:1538(switch_message)
  switch message SMBnegprot (pid 4002) conn 0x0
[2018/02/21 14:26:38.415412,  4] ../source3/smbd/sec_ctx.c:321(set_sec_ctx_internal)
  setting sec ctx (0, 0) - sec_ctx_stack_ndx = 0
[2018/02/21 14:26:38.415433,  5] ../libcli/security/security_token.c:53(security_token_debug)
  Security token: (NULL)
[2018/02/21 14:26:38.415457,  5] ../source3/auth/token_util.c:640(debug_unix_user_token)
  UNIX token of user 0
  Primary group is 0 and contains 0 supplementary groups
[2018/02/21 14:26:38.415497,  5] ../source3/smbd/uid.c:425(smbd_change_to_root_user)
  change_to_root_user: now uid=(0,0) gid=(0,0)
[2018/02/21 14:26:38.416355,  3] ../source3/smbd/negprot.c:603(reply_negprot)
  Requested protocol [PC NETWORK PROGRAM 1.0]
[2018/02/21 14:26:38.416379,  3] ../source3/smbd/negprot.c:603(reply_negprot)
  Requested protocol [LANMAN1.0]
[2018/02/21 14:26:38.416393,  3] ../source3/smbd/negprot.c:603(reply_negprot)
  Requested protocol [Windows for Workgroups 3.1a]
[2018/02/21 14:26:38.416406,  3] ../source3/smbd/negprot.c:603(reply_negprot)
  Requested protocol [LM1.2X002]
[2018/02/21 14:26:38.416419,  3] ../source3/smbd/negprot.c:603(reply_negprot)
  Requested protocol [LANMAN2.1]
[2018/02/21 14:26:38.416432,  3] ../source3/smbd/negprot.c:603(reply_negprot)
  Requested protocol [NT LM 0.12]
[2018/02/21 14:26:38.416445,  3] ../source3/smbd/negprot.c:603(reply_negprot)
  Requested protocol [SMB 2.002]
[2018/02/21 14:26:38.416458,  3] ../source3/smbd/negprot.c:603(reply_negprot)
  Requested protocol [SMB 2.???]
[2018/02/21 14:26:38.416495,  6] ../source3/param/loadparm.c:2307(lp_file_list_changed)
  lp_file_list_changed()
  file /etc/samba/smb.conf -> /etc/samba/smb.conf  last mod_time: Wed Feb 21 14:25:01 2018
  
[2018/02/21 14:26:38.416527,  5] ../lib/dbwrap/dbwrap.c:159(dbwrap_check_lock_order)
  check lock order 2 for /var/lib/samba/lock/serverid.tdb
[2018/02/21 14:26:38.416551,  5] ../lib/dbwrap/dbwrap.c:127(dbwrap_lock_order_state_destructor)
  release lock order 2 for /var/lib/samba/lock/serverid.tdb
[2018/02/21 14:26:38.416581,  6] ../source3/param/loadparm.c:2307(lp_file_list_changed)
  lp_file_list_changed()
  file /etc/samba/smb.conf -> /etc/samba/smb.conf  last mod_time: Wed Feb 21 14:25:01 2018
  
[2018/02/21 14:26:38.416647,  4] ../source3/smbd/sec_ctx.c:321(set_sec_ctx_internal)
  setting sec ctx (0, 0) - sec_ctx_stack_ndx = 0
[2018/02/21 14:26:38.416680,  5] ../libcli/security/security_token.c:53(security_token_debug)
  Security token: (NULL)
[2018/02/21 14:26:38.416693,  5] ../source3/auth/token_util.c:640(debug_unix_user_token)
  UNIX token of user 0
  Primary group is 0 and contains 0 supplementary groups
[2018/02/21 14:26:38.416720,  5] ../source3/smbd/uid.c:425(smbd_change_to_root_user)
  change_to_root_user: now uid=(0,0) gid=(0,0)
[2018/02/21 14:26:38.416836,  6] ../source3/param/loadparm.c:2307(lp_file_list_changed)
  lp_file_list_changed()
  file /etc/samba/smb.conf -> /etc/samba/smb.conf  last mod_time: Wed Feb 21 14:25:01 2018
  
[2018/02/21 14:26:38.416873,  3] ../source3/smbd/smb2_negprot.c:290(smbd_smb2_request_process_negprot)
  Selected protocol SMB2_FF
[2018/02/21 14:26:38.416900,  5] ../source3/auth/auth.c:477(make_auth_context_subsystem)
  Making default auth method list for server role = 'domain member'
[2018/02/21 14:26:38.416920,  5] ../source3/auth/auth.c:48(smb_register_auth)
  Attempting to register auth backend trustdomain
[2018/02/21 14:26:38.416959,  5] ../source3/auth/auth.c:60(smb_register_auth)
  Successfully added auth method 'trustdomain'
[2018/02/21 14:26:38.416975,  5] ../source3/auth/auth.c:48(smb_register_auth)
  Attempting to register auth backend ntdomain
[2018/02/21 14:26:38.416990,  5] ../source3/auth/auth.c:60(smb_register_auth)
  Successfully added auth method 'ntdomain'
[2018/02/21 14:26:38.417024,  5] ../source3/auth/auth.c:48(smb_register_auth)
  Attempting to register auth backend guest
[2018/02/21 14:26:38.417039,  5] ../source3/auth/auth.c:60(smb_register_auth)
  Successfully added auth method 'guest'
[2018/02/21 14:26:38.417055,  5] ../source3/auth/auth.c:48(smb_register_auth)
  Attempting to register auth backend sam
[2018/02/21 14:26:38.417069,  5] ../source3/auth/auth.c:60(smb_register_auth)
  Successfully added auth method 'sam'
[2018/02/21 14:26:38.417101,  5] ../source3/auth/auth.c:48(smb_register_auth)
  Attempting to register auth backend sam_ignoredomain
[2018/02/21 14:26:38.417151,  5] ../source3/auth/auth.c:60(smb_register_auth)
  Successfully added auth method 'sam_ignoredomain'
[2018/02/21 14:26:38.417174,  5] ../source3/auth/auth.c:48(smb_register_auth)
  Attempting to register auth backend winbind
[2018/02/21 14:26:38.417192,  5] ../source3/auth/auth.c:60(smb_register_auth)
  Successfully added auth method 'winbind'
[2018/02/21 14:26:38.417207,  5] ../source3/auth/auth.c:378(load_auth_module)
  load_auth_module: Attempting to find an auth method to match guest
[2018/02/21 14:26:38.417223,  5] ../source3/auth/auth.c:403(load_auth_module)
  load_auth_module: auth method guest has a valid init
[2018/02/21 14:26:38.417255,  5] ../source3/auth/auth.c:378(load_auth_module)
  load_auth_module: Attempting to find an auth method to match sam
[2018/02/21 14:26:38.417270,  5] ../source3/auth/auth.c:403(load_auth_module)
  load_auth_module: auth method sam has a valid init
[2018/02/21 14:26:38.417285,  5] ../source3/auth/auth.c:378(load_auth_module)
  load_auth_module: Attempting to find an auth method to match winbind:ntdomain
[2018/02/21 14:26:38.417317,  5] ../source3/auth/auth.c:378(load_auth_module)
  load_auth_module: Attempting to find an auth method to match ntdomain
[2018/02/21 14:26:38.417345,  5] ../source3/auth/auth.c:403(load_auth_module)
  load_auth_module: auth method ntdomain has a valid init
[2018/02/21 14:26:38.417358,  5] ../source3/auth/auth.c:403(load_auth_module)
  load_auth_module: auth method winbind has a valid init
[2018/02/21 14:26:38.418733,  5] ../auth/gensec/gensec_start.c:681(gensec_start_mech)
  Starting GENSEC mechanism spnego
[2018/02/21 14:26:38.418788,  5] ../auth/gensec/gensec_start.c:681(gensec_start_mech)
  Starting GENSEC submechanism gse_krb5
[2018/02/21 14:26:38.632881,  3] ../source3/smbd/negprot.c:730(reply_negprot)
  Selected protocol SMB 2.???
[2018/02/21 14:26:38.632907,  5] ../source3/smbd/negprot.c:737(reply_negprot)
  negprot index=7
[2018/02/21 14:26:38.633397,  4] ../source3/smbd/sec_ctx.c:321(set_sec_ctx_internal)
  setting sec ctx (0, 0) - sec_ctx_stack_ndx = 0
[2018/02/21 14:26:38.633422,  5] ../libcli/security/security_token.c:53(security_token_debug)
  Security token: (NULL)
[2018/02/21 14:26:38.633437,  5] ../source3/auth/token_util.c:640(debug_unix_user_token)
  UNIX token of user 0
  Primary group is 0 and contains 0 supplementary groups
[2018/02/21 14:26:38.633479,  5] ../source3/smbd/uid.c:425(smbd_change_to_root_user)
  change_to_root_user: now uid=(0,0) gid=(0,0)
[2018/02/21 14:26:38.633506,  4] ../source3/smbd/sec_ctx.c:217(push_sec_ctx)
  push_sec_ctx(0, 0) : sec_ctx_stack_ndx = 1
[2018/02/21 14:26:38.633526,  4] ../source3/smbd/uid.c:491(push_conn_ctx)
  push_conn_ctx(0) : conn_ctx_stack_ndx = 0
[2018/02/21 14:26:38.633542,  4] ../source3/smbd/sec_ctx.c:321(set_sec_ctx_internal)
  setting sec ctx (0, 0) - sec_ctx_stack_ndx = 1
[2018/02/21 14:26:38.633556,  5] ../libcli/security/security_token.c:53(security_token_debug)
  Security token: (NULL)
[2018/02/21 14:26:38.633569,  5] ../source3/auth/token_util.c:640(debug_unix_user_token)
  UNIX token of user 0
  Primary group is 0 and contains 0 supplementary groups
[2018/02/21 14:26:38.633681,  4] ../source3/smbd/sec_ctx.c:439(pop_sec_ctx)
  pop_sec_ctx (0, 0) - sec_ctx_stack_ndx = 0
[2018/02/21 14:26:38.633721,  6] ../source3/param/loadparm.c:2307(lp_file_list_changed)
  lp_file_list_changed()
  file /etc/samba/smb.conf -> /etc/samba/smb.conf  last mod_time: Wed Feb 21 14:25:01 2018
  
[2018/02/21 14:26:38.633755,  3] ../source3/smbd/smb2_negprot.c:290(smbd_smb2_request_process_negprot)
  Selected protocol SMB3_02
[2018/02/21 14:26:38.633771,  5] ../source3/auth/auth.c:477(make_auth_context_subsystem)
  Making default auth method list for server role = 'domain member'
[2018/02/21 14:26:38.633786,  5] ../source3/auth/auth.c:378(load_auth_module)
  load_auth_module: Attempting to find an auth method to match guest
[2018/02/21 14:26:38.633801,  5] ../source3/auth/auth.c:403(load_auth_module)
  load_auth_module: auth method guest has a valid init
[2018/02/21 14:26:38.633819,  5] ../source3/auth/auth.c:378(load_auth_module)
  load_auth_module: Attempting to find an auth method to match sam
[2018/02/21 14:26:38.633833,  5] ../source3/auth/auth.c:403(load_auth_module)
  load_auth_module: auth method sam has a valid init
[2018/02/21 14:26:38.633847,  5] ../source3/auth/auth.c:378(load_auth_module)
  load_auth_module: Attempting to find an auth method to match winbind:ntdomain
[2018/02/21 14:26:38.633861,  5] ../source3/auth/auth.c:378(load_auth_module)
  load_auth_module: Attempting to find an auth method to match ntdomain
[2018/02/21 14:26:38.633875,  5] ../source3/auth/auth.c:403(load_auth_module)
  load_auth_module: auth method ntdomain has a valid init
[2018/02/21 14:26:38.633889,  5] ../source3/auth/auth.c:403(load_auth_module)
  load_auth_module: auth method winbind has a valid init
[2018/02/21 14:26:38.633935,  5] ../auth/gensec/gensec_start.c:681(gensec_start_mech)
  Starting GENSEC mechanism spnego
[2018/02/21 14:26:38.633977,  5] ../auth/gensec/gensec_start.c:681(gensec_start_mech)
  Starting GENSEC submechanism gse_krb5
[2018/02/21 14:26:38.845168,  4] ../source3/smbd/sec_ctx.c:321(set_sec_ctx_internal)
  setting sec ctx (0, 0) - sec_ctx_stack_ndx = 0
[2018/02/21 14:26:38.845196,  5] ../libcli/security/security_token.c:53(security_token_debug)
  Security token: (NULL)
[2018/02/21 14:26:38.845211,  5] ../source3/auth/token_util.c:640(debug_unix_user_token)
  UNIX token of user 0
  Primary group is 0 and contains 0 supplementary groups
[2018/02/21 14:26:38.845239,  5] ../source3/smbd/uid.c:425(smbd_change_to_root_user)
  change_to_root_user: now uid=(0,0) gid=(0,0)
[2018/02/21 14:26:38.845268,  5] ../lib/dbwrap/dbwrap.c:159(dbwrap_check_lock_order)
  check lock order 1 for /var/lib/samba/lock/smbXsrv_session_global.tdb
[2018/02/21 14:26:38.845375,  5] ../lib/dbwrap/dbwrap.c:127(dbwrap_lock_order_state_destructor)
  release lock order 1 for /var/lib/samba/lock/smbXsrv_session_global.tdb
[2018/02/21 14:26:38.845415,  5] ../source3/auth/auth.c:477(make_auth_context_subsystem)
  Making default auth method list for server role = 'domain member'
[2018/02/21 14:26:38.845431,  5] ../source3/auth/auth.c:378(load_auth_module)
  load_auth_module: Attempting to find an auth method to match guest
[2018/02/21 14:26:38.845445,  5] ../source3/auth/auth.c:403(load_auth_module)
  load_auth_module: auth method guest has a valid init
[2018/02/21 14:26:38.845458,  5] ../source3/auth/auth.c:378(load_auth_module)
  load_auth_module: Attempting to find an auth method to match sam
[2018/02/21 14:26:38.845471,  5] ../source3/auth/auth.c:403(load_auth_module)
  load_auth_module: auth method sam has a valid init
[2018/02/21 14:26:38.845484,  5] ../source3/auth/auth.c:378(load_auth_module)
  load_auth_module: Attempting to find an auth method to match winbind:ntdomain
[2018/02/21 14:26:38.845497,  5] ../source3/auth/auth.c:378(load_auth_module)
  load_auth_module: Attempting to find an auth method to match ntdomain
[2018/02/21 14:26:38.845510,  5] ../source3/auth/auth.c:403(load_auth_module)
  load_auth_module: auth method ntdomain has a valid init
[2018/02/21 14:26:38.845523,  5] ../source3/auth/auth.c:403(load_auth_module)
  load_auth_module: auth method winbind has a valid init
[2018/02/21 14:26:38.845550,  5] ../auth/gensec/gensec_start.c:681(gensec_start_mech)
  Starting GENSEC mechanism spnego
[2018/02/21 14:26:38.845566,  5] ../lib/dbwrap/dbwrap.c:159(dbwrap_check_lock_order)
  check lock order 1 for /var/lib/samba/lock/smbXsrv_session_global.tdb
[2018/02/21 14:26:38.845589,  5] ../lib/dbwrap/dbwrap.c:127(dbwrap_lock_order_state_destructor)
  release lock order 1 for /var/lib/samba/lock/smbXsrv_session_global.tdb
[2018/02/21 14:26:38.845608,  4] ../source3/smbd/sec_ctx.c:217(push_sec_ctx)
  push_sec_ctx(0, 0) : sec_ctx_stack_ndx = 1
[2018/02/21 14:26:38.845624,  4] ../source3/smbd/uid.c:491(push_conn_ctx)
  push_conn_ctx(0) : conn_ctx_stack_ndx = 0
[2018/02/21 14:26:38.845637,  4] ../source3/smbd/sec_ctx.c:321(set_sec_ctx_internal)
  setting sec ctx (0, 0) - sec_ctx_stack_ndx = 1
[2018/02/21 14:26:38.845680,  5] ../libcli/security/security_token.c:53(security_token_debug)
  Security token: (NULL)
[2018/02/21 14:26:38.845695,  5] ../source3/auth/token_util.c:640(debug_unix_user_token)
  UNIX token of user 0
  Primary group is 0 and contains 0 supplementary groups
[2018/02/21 14:26:38.845734,  4] ../source3/smbd/sec_ctx.c:439(pop_sec_ctx)
  pop_sec_ctx (0, 0) - sec_ctx_stack_ndx = 0
[2018/02/21 14:26:38.845782,  5] ../auth/gensec/gensec_start.c:681(gensec_start_mech)
  Starting GENSEC submechanism ntlmssp
[2018/02/21 14:26:38.845819,  3] ../auth/ntlmssp/ntlmssp_util.c:69(debug_ntlmssp_flags)
  Got NTLMSSP neg_flags=0xe2088297
    NTLMSSP_NEGOTIATE_UNICODE
    NTLMSSP_NEGOTIATE_OEM
    NTLMSSP_REQUEST_TARGET
    NTLMSSP_NEGOTIATE_SIGN
    NTLMSSP_NEGOTIATE_LM_KEY
    NTLMSSP_NEGOTIATE_NTLM
    NTLMSSP_NEGOTIATE_ALWAYS_SIGN
    NTLMSSP_NEGOTIATE_EXTENDED_SESSIONSECURITY
    NTLMSSP_NEGOTIATE_VERSION
    NTLMSSP_NEGOTIATE_128
    NTLMSSP_NEGOTIATE_KEY_EXCH
    NTLMSSP_NEGOTIATE_56
[2018/02/21 14:26:38.845956,  4] ../source3/smbd/sec_ctx.c:217(push_sec_ctx)
  push_sec_ctx(0, 0) : sec_ctx_stack_ndx = 1
[2018/02/21 14:26:38.845988,  4] ../source3/smbd/uid.c:491(push_conn_ctx)
  push_conn_ctx(0) : conn_ctx_stack_ndx = 0
[2018/02/21 14:26:38.846001,  4] ../source3/smbd/sec_ctx.c:321(set_sec_ctx_internal)
  setting sec ctx (0, 0) - sec_ctx_stack_ndx = 1
[2018/02/21 14:26:38.846014,  5] ../libcli/security/security_token.c:53(security_token_debug)
  Security token: (NULL)
[2018/02/21 14:26:38.846028,  5] ../source3/auth/token_util.c:640(debug_unix_user_token)
  UNIX token of user 0
  Primary group is 0 and contains 0 supplementary groups
[2018/02/21 14:26:38.846064,  4] ../source3/smbd/sec_ctx.c:439(pop_sec_ctx)
  pop_sec_ctx (0, 0) - sec_ctx_stack_ndx = 0
[2018/02/21 14:26:38.846654,  5] ../lib/dbwrap/dbwrap.c:159(dbwrap_check_lock_order)
  check lock order 1 for /var/lib/samba/lock/smbXsrv_session_global.tdb
[2018/02/21 14:26:38.846709,  5] ../lib/dbwrap/dbwrap.c:127(dbwrap_lock_order_state_destructor)
  release lock order 1 for /var/lib/samba/lock/smbXsrv_session_global.tdb
[2018/02/21 14:26:38.846729,  4] ../source3/smbd/sec_ctx.c:321(set_sec_ctx_internal)
  setting sec ctx (0, 0) - sec_ctx_stack_ndx = 0
[2018/02/21 14:26:38.846744,  5] ../libcli/security/security_token.c:53(security_token_debug)
  Security token: (NULL)
[2018/02/21 14:26:38.846758,  5] ../source3/auth/token_util.c:640(debug_unix_user_token)
  UNIX token of user 0
  Primary group is 0 and contains 0 supplementary groups
[2018/02/21 14:26:38.846802,  5] ../source3/smbd/uid.c:425(smbd_change_to_root_user)
  change_to_root_user: now uid=(0,0) gid=(0,0)
[2018/02/21 14:26:38.846823,  5] ../lib/dbwrap/dbwrap.c:159(dbwrap_check_lock_order)
  check lock order 1 for /var/lib/samba/lock/smbXsrv_session_global.tdb
[2018/02/21 14:26:38.846844,  5] ../lib/dbwrap/dbwrap.c:127(dbwrap_lock_order_state_destructor)
  release lock order 1 for /var/lib/samba/lock/smbXsrv_session_global.tdb
[2018/02/21 14:26:38.846864,  4] ../source3/smbd/sec_ctx.c:217(push_sec_ctx)
  push_sec_ctx(0, 0) : sec_ctx_stack_ndx = 1
[2018/02/21 14:26:38.846879,  4] ../source3/smbd/uid.c:491(push_conn_ctx)
  push_conn_ctx(0) : conn_ctx_stack_ndx = 0
[2018/02/21 14:26:38.846893,  4] ../source3/smbd/sec_ctx.c:321(set_sec_ctx_internal)
  setting sec ctx (0, 0) - sec_ctx_stack_ndx = 1
[2018/02/21 14:26:38.846922,  5] ../libcli/security/security_token.c:53(security_token_debug)
  Security token: (NULL)
[2018/02/21 14:26:38.846935,  5] ../source3/auth/token_util.c:640(debug_unix_user_token)
  UNIX token of user 0
  Primary group is 0 and contains 0 supplementary groups
[2018/02/21 14:26:38.846971,  4] ../source3/smbd/sec_ctx.c:439(pop_sec_ctx)
  pop_sec_ctx (0, 0) - sec_ctx_stack_ndx = 0
[2018/02/21 14:26:38.847002,  3] ../auth/ntlmssp/ntlmssp_server.c:452(ntlmssp_server_preauth)
  Got user=[matthias] domain=[MYDOMAIN] workstation=[SRVDS2] len1=24 len2=380
[2018/02/21 14:26:38.847066,  3] ../source3/param/loadparm.c:3823(lp_load_ex)
  lp_load_ex: refreshing parameters
[2018/02/21 14:26:38.847084,  5] ../source3/param/loadparm.c:1319(free_param_opts)
  Freeing parametrics:
[2018/02/21 14:26:38.847154,  3] ../source3/param/loadparm.c:542(init_globals)
  Initialising global parameters
[2018/02/21 14:26:38.847245,  3] ../source3/param/loadparm.c:2752(lp_do_section)
  Processing section "[global]"
  doing parameter workgroup = MYDOMAIN
  doing parameter realm = MYDOMAIN.TLD
  doing parameter security = ADS
  doing parameter passdb backend = tdbsam
  doing parameter load printers = no
  doing parameter idmap config * : backend = tdb
  doing parameter idmap config * : range = 3000-7999
  doing parameter idmap config MYDOMAIN : backend = rid
  doing parameter idmap config MYDOMAIN : range = 10000-999999
  doing parameter vfs objects = acl_xattr
  doing parameter map acl inherit = yes
  doing parameter store dos attributes = yes
  doing parameter acl_xattr:ignore system acls = no
  doing parameter acl_xattr:default acl style = posix
  doing parameter map archive = no
  doing parameter map hidden = no
  doing parameter map read only = no
  doing parameter map system = no
  doing parameter unix extensions = no
  doing parameter log level = 9
[2018/02/21 14:26:38.847442,  5] ../lib/util/debug.c:643(debug_dump_status)
  INFO: Current debug levels:
    all: 9
    tdb: 9
    printdrivers: 9
    lanman: 9
    smb: 9
    rpc_parse: 9
    rpc_srv: 9
    rpc_cli: 9
    passdb: 9
    sam: 9
    auth: 9
    winbind: 9
    vfs: 9
    idmap: 9
    quota: 9
    acls: 9
    locking: 9
    msdfs: 9
    dmapi: 9
    registry: 9
    scavenger: 9
    dns: 9
    ldb: 9
    tevent: 9
[2018/02/21 14:26:38.847549,  2] ../source3/param/loadparm.c:2769(lp_do_section)
  Processing section "[share01]"
[2018/02/21 14:26:38.847564,  5] ../source3/param/loadparm.c:1319(free_param_opts)
  Freeing parametrics:
  doing parameter path = /data/share01
  doing parameter read only = no
  doing parameter vfs objects = shadow_copy2
  doing parameter shadow:mountpoint = /data
  doing parameter shadow:snapdir = /data
[2018/02/21 14:26:38.847628,  2] ../source3/param/loadparm.c:2769(lp_do_section)
  Processing section "[share02]"
[2018/02/21 14:26:38.847642,  5] ../source3/param/loadparm.c:1319(free_param_opts)
  Freeing parametrics:
  doing parameter path = /data/share02
  doing parameter read only = no
  doing parameter vfs objects = shadow_copy2
  doing parameter shadow:mountpoint = /data
  doing parameter shadow:snapdir = /data
[2018/02/21 14:26:38.847732,  2] ../source3/param/loadparm.c:2769(lp_do_section)
  Processing section "[share04]"
[2018/02/21 14:26:38.847747,  5] ../source3/param/loadparm.c:1319(free_param_opts)
  Freeing parametrics:
  doing parameter path = /data/subdir/share04
  doing parameter read only = no
  doing parameter vfs objects = shadow_copy2
  doing parameter shadow:mountpoint = /data
  doing parameter shadow:snapdir = /data
[2018/02/21 14:26:38.847824,  4] ../source3/param/loadparm.c:3864(lp_load_ex)
  pm_process() returned Yes
[2018/02/21 14:26:38.847847,  7] ../source3/param/loadparm.c:4183(lp_servicenumber)
  lp_servicenumber: couldn't find homes
[2018/02/21 14:26:38.847868,  3] ../source3/param/loadparm.c:1592(lp_add_ipc)
  adding IPC service
[2018/02/21 14:26:38.847908,  5] ../source3/auth/auth_util.c:123(make_user_info_map)
  Mapping user [MYDOMAIN]\[matthias] from workstation [SRVDS2]
[2018/02/21 14:26:38.848873,  5] ../source3/auth/user_info.c:62(make_user_info)
  attempting to make a user_info for matthias (matthias)
[2018/02/21 14:26:38.848916,  5] ../source3/auth/user_info.c:70(make_user_info)
  making strings for matthias's user_info struct
[2018/02/21 14:26:38.848931,  5] ../source3/auth/user_info.c:108(make_user_info)
  making blobs for matthias's user_info struct
[2018/02/21 14:26:38.848945,  3] ../source3/auth/auth.c:178(auth_check_ntlm_password)
  check_ntlm_password:  Checking password for unmapped user [MYDOMAIN]\[matthias]@[SRVDS2] with the new password interface
[2018/02/21 14:26:38.848959,  3] ../source3/auth/auth.c:181(auth_check_ntlm_password)
  check_ntlm_password:  mapped user is: [MYDOMAIN]\[matthias]@[SRVDS2]
[2018/02/21 14:26:38.848976,  5] ../lib/util/util.c:555(dump_data)
  [0000] A5 31 E1 EA 4D EC E3 6E                             .1..M..n 
[2018/02/21 14:26:38.849001,  8] ../source3/lib/util.c:1239(is_myname)
  is_myname("MYDOMAIN") returns 0
[2018/02/21 14:26:38.849016,  6] ../source3/auth/auth_sam.c:88(auth_samstrict_auth)
  check_samstrict_security: MYDOMAIN is not one of my local names (ROLE_DOMAIN_MEMBER)
[2018/02/21 14:26:38.849033,  4] ../source3/smbd/sec_ctx.c:217(push_sec_ctx)
  push_sec_ctx(0, 0) : sec_ctx_stack_ndx = 1
[2018/02/21 14:26:38.849048,  4] ../source3/smbd/uid.c:491(push_conn_ctx)
  push_conn_ctx(0) : conn_ctx_stack_ndx = 0
[2018/02/21 14:26:38.849061,  4] ../source3/smbd/sec_ctx.c:321(set_sec_ctx_internal)
  setting sec ctx (0, 0) - sec_ctx_stack_ndx = 1
[2018/02/21 14:26:38.849074,  5] ../libcli/security/security_token.c:53(security_token_debug)
  Security token: (NULL)
[2018/02/21 14:26:38.849087,  5] ../source3/auth/token_util.c:640(debug_unix_user_token)
  UNIX token of user 0
  Primary group is 0 and contains 0 supplementary groups
[2018/02/21 14:26:38.851291,  4] ../source3/smbd/sec_ctx.c:439(pop_sec_ctx)
  pop_sec_ctx (0, 0) - sec_ctx_stack_ndx = 0
[2018/02/21 14:26:38.851335,  5] ../source3/lib/username.c:181(Get_Pwnam_alloc)
  Finding user MYDOMAIN\matthias
[2018/02/21 14:26:38.851352,  5] ../source3/lib/username.c:120(Get_Pwnam_internals)
  Trying _Get_Pwnam(), username as lowercase is zmp\matthias
[2018/02/21 14:26:38.851971,  5] ../source3/lib/username.c:159(Get_Pwnam_internals)
  Get_Pwnam_internals did find user [MYDOMAIN\matthias]!
[2018/02/21 14:26:38.852005,  3] ../source3/auth/auth.c:249(auth_check_ntlm_password)
  check_ntlm_password: winbind authentication for user [matthias] succeeded
[2018/02/21 14:26:38.852026,  4] ../source3/smbd/sec_ctx.c:217(push_sec_ctx)
  push_sec_ctx(0, 0) : sec_ctx_stack_ndx = 1
[2018/02/21 14:26:38.852042,  4] ../source3/smbd/uid.c:491(push_conn_ctx)
  push_conn_ctx(0) : conn_ctx_stack_ndx = 0
[2018/02/21 14:26:38.852056,  4] ../source3/smbd/sec_ctx.c:321(set_sec_ctx_internal)
  setting sec ctx (0, 0) - sec_ctx_stack_ndx = 1
[2018/02/21 14:26:38.852070,  5] ../libcli/security/security_token.c:53(security_token_debug)
  Security token: (NULL)
[2018/02/21 14:26:38.852083,  5] ../source3/auth/token_util.c:640(debug_unix_user_token)
  UNIX token of user 0
  Primary group is 0 and contains 0 supplementary groups
[2018/02/21 14:26:38.852152,  4] ../source3/smbd/sec_ctx.c:439(pop_sec_ctx)
  pop_sec_ctx (0, 0) - sec_ctx_stack_ndx = 0
[2018/02/21 14:26:38.852173,  5] ../source3/auth/auth.c:292(auth_check_ntlm_password)
  check_ntlm_password:  PAM Account for user [MYDOMAIN\matthias] succeeded
[2018/02/21 14:26:38.852186,  2] ../source3/auth/auth.c:305(auth_check_ntlm_password)
  check_ntlm_password:  authentication for user [matthias] -> [matthias] -> [MYDOMAIN\matthias] succeeded
[2018/02/21 14:26:38.852214,  3] ../auth/ntlmssp/ntlmssp_sign.c:509(ntlmssp_sign_reset)
  NTLMSSP Sign/Seal - Initialising with flags:
[2018/02/21 14:26:38.852228,  3] ../auth/ntlmssp/ntlmssp_util.c:69(debug_ntlmssp_flags)
  Got NTLMSSP neg_flags=0xe2088215
    NTLMSSP_NEGOTIATE_UNICODE
    NTLMSSP_REQUEST_TARGET
    NTLMSSP_NEGOTIATE_SIGN
    NTLMSSP_NEGOTIATE_NTLM
    NTLMSSP_NEGOTIATE_ALWAYS_SIGN
    NTLMSSP_NEGOTIATE_EXTENDED_SESSIONSECURITY
    NTLMSSP_NEGOTIATE_VERSION
    NTLMSSP_NEGOTIATE_128
    NTLMSSP_NEGOTIATE_KEY_EXCH
    NTLMSSP_NEGOTIATE_56
[2018/02/21 14:26:38.852292,  3] ../auth/ntlmssp/ntlmssp_sign.c:509(ntlmssp_sign_reset)
  NTLMSSP Sign/Seal - Initialising with flags:
[2018/02/21 14:26:38.852305,  3] ../auth/ntlmssp/ntlmssp_util.c:69(debug_ntlmssp_flags)
  Got NTLMSSP neg_flags=0xe2088215
    NTLMSSP_NEGOTIATE_UNICODE
    NTLMSSP_REQUEST_TARGET
    NTLMSSP_NEGOTIATE_SIGN
    NTLMSSP_NEGOTIATE_NTLM
    NTLMSSP_NEGOTIATE_ALWAYS_SIGN
    NTLMSSP_NEGOTIATE_EXTENDED_SESSIONSECURITY
    NTLMSSP_NEGOTIATE_VERSION
    NTLMSSP_NEGOTIATE_128
    NTLMSSP_NEGOTIATE_KEY_EXCH
    NTLMSSP_NEGOTIATE_56
[2018/02/21 14:26:38.852378,  4] ../source3/smbd/sec_ctx.c:217(push_sec_ctx)
  push_sec_ctx(0, 0) : sec_ctx_stack_ndx = 1
[2018/02/21 14:26:38.852398,  4] ../source3/smbd/uid.c:491(push_conn_ctx)
  push_conn_ctx(0) : conn_ctx_stack_ndx = 0
[2018/02/21 14:26:38.852412,  4] ../source3/smbd/sec_ctx.c:321(set_sec_ctx_internal)
  setting sec ctx (0, 0) - sec_ctx_stack_ndx = 1
[2018/02/21 14:26:38.852425,  5] ../libcli/security/security_token.c:53(security_token_debug)
  Security token: (NULL)
[2018/02/21 14:26:38.852437,  5] ../source3/auth/token_util.c:640(debug_unix_user_token)
  UNIX token of user 0
  Primary group is 0 and contains 0 supplementary groups
[2018/02/21 14:26:38.852473,  4] ../source3/smbd/sec_ctx.c:439(pop_sec_ctx)
  pop_sec_ctx (0, 0) - sec_ctx_stack_ndx = 0
[2018/02/21 14:26:38.853609,  4] ../source3/smbd/sec_ctx.c:217(push_sec_ctx)
  push_sec_ctx(0, 0) : sec_ctx_stack_ndx = 1
[2018/02/21 14:26:38.853658,  4] ../source3/smbd/uid.c:491(push_conn_ctx)
  push_conn_ctx(0) : conn_ctx_stack_ndx = 0
[2018/02/21 14:26:38.853673,  4] ../source3/smbd/sec_ctx.c:321(set_sec_ctx_internal)
  setting sec ctx (0, 0) - sec_ctx_stack_ndx = 1
[2018/02/21 14:26:38.853687,  5] ../libcli/security/security_token.c:53(security_token_debug)
  Security token: (NULL)
[2018/02/21 14:26:38.853700,  5] ../source3/auth/token_util.c:640(debug_unix_user_token)
  UNIX token of user 0
  Primary group is 0 and contains 0 supplementary groups
[2018/02/21 14:26:38.853810,  4] ../source3/smbd/sec_ctx.c:439(pop_sec_ctx)
  pop_sec_ctx (0, 0) - sec_ctx_stack_ndx = 0
[2018/02/21 14:26:38.853839,  4] ../source3/lib/privileges.c:98(get_privileges)
  get_privileges: No privileges assigned to SID [S-1-5-21-822149324-2706365316-2594636336-3627]
[2018/02/21 14:26:38.853860,  4] ../source3/lib/privileges.c:98(get_privileges)
  get_privileges: No privileges assigned to SID [S-1-5-21-822149324-2706365316-2594636336-513]
[2018/02/21 14:26:38.853878,  4] ../source3/lib/privileges.c:98(get_privileges)
  get_privileges: No privileges assigned to SID [S-1-5-21-822149324-2706365316-2594636336-512]
[2018/02/21 14:26:38.853897,  4] ../source3/lib/privileges.c:98(get_privileges)
  get_privileges: No privileges assigned to SID [S-1-5-21-822149324-2706365316-2594636336-572]
[2018/02/21 14:26:38.853917,  5] ../source3/lib/privileges.c:176(get_privileges_for_sids)
  get_privileges_for_sids: sid = S-1-1-0
  Privilege set: 0x0
[2018/02/21 14:26:38.853938,  4] ../source3/lib/privileges.c:98(get_privileges)
  get_privileges: No privileges assigned to SID [S-1-5-2]
[2018/02/21 14:26:38.853956,  4] ../source3/lib/privileges.c:98(get_privileges)
  get_privileges: No privileges assigned to SID [S-1-5-11]
[2018/02/21 14:26:38.853974,  4] ../source3/lib/privileges.c:98(get_privileges)
  get_privileges: No privileges assigned to SID [S-1-5-32-545]
[2018/02/21 14:26:38.853992,  5] ../source3/lib/privileges.c:176(get_privileges_for_sids)
  get_privileges_for_sids: sid = S-1-5-32-544
  Privilege set: 0x1ffffff0
[2018/02/21 14:26:38.854097,  7] ../source3/param/loadparm.c:4183(lp_servicenumber)
  lp_servicenumber: couldn't find MYDOMAIN\matthias
[2018/02/21 14:26:38.854113,  5] ../source3/lib/username.c:181(Get_Pwnam_alloc)
  Finding user MYDOMAIN\matthias
[2018/02/21 14:26:38.854126,  5] ../source3/lib/username.c:120(Get_Pwnam_internals)
  Trying _Get_Pwnam(), username as lowercase is zmp\matthias
[2018/02/21 14:26:38.854164,  5] ../source3/lib/username.c:159(Get_Pwnam_internals)
  Get_Pwnam_internals did find user [MYDOMAIN\matthias]!
[2018/02/21 14:26:38.854179,  3] ../source3/smbd/password.c:144(register_homes_share)
  Adding homes service for user 'MYDOMAIN\matthias' using home directory: '/home/MYDOMAIN/matthias'
[2018/02/21 14:26:38.854200,  7] ../source3/param/loadparm.c:4183(lp_servicenumber)
  lp_servicenumber: couldn't find homes
[2018/02/21 14:26:38.854233,  6] ../source3/param/loadparm.c:2307(lp_file_list_changed)
  lp_file_list_changed()
  file /etc/samba/smb.conf -> /etc/samba/smb.conf  last mod_time: Wed Feb 21 14:25:01 2018
  
[2018/02/21 14:26:38.854274,  5] ../lib/dbwrap/dbwrap.c:159(dbwrap_check_lock_order)
  check lock order 1 for /var/lib/samba/lock/smbXsrv_session_global.tdb
[2018/02/21 14:26:38.854334,  5] ../lib/dbwrap/dbwrap.c:127(dbwrap_lock_order_state_destructor)
  release lock order 1 for /var/lib/samba/lock/smbXsrv_session_global.tdb
[2018/02/21 14:26:38.854369,  5] ../libcli/smb/smb2_signing.c:93(smb2_signing_sign_pdu)
  signed SMB2 message
[2018/02/21 14:26:38.855089,  4] ../source3/smbd/sec_ctx.c:321(set_sec_ctx_internal)
  setting sec ctx (0, 0) - sec_ctx_stack_ndx = 0
[2018/02/21 14:26:38.855165,  5] ../libcli/security/security_token.c:53(security_token_debug)
  Security token: (NULL)
[2018/02/21 14:26:38.855180,  5] ../source3/auth/token_util.c:640(debug_unix_user_token)
  UNIX token of user 0
  Primary group is 0 and contains 0 supplementary groups
[2018/02/21 14:26:38.855206,  5] ../source3/smbd/uid.c:425(smbd_change_to_root_user)
  change_to_root_user: now uid=(0,0) gid=(0,0)
[2018/02/21 14:26:38.855245,  5] ../lib/dbwrap/dbwrap.c:159(dbwrap_check_lock_order)
  check lock order 1 for /var/lib/samba/lock/smbXsrv_tcon_global.tdb
[2018/02/21 14:26:38.855307,  5] ../lib/dbwrap/dbwrap.c:127(dbwrap_lock_order_state_destructor)
  release lock order 1 for /var/lib/samba/lock/smbXsrv_tcon_global.tdb
[2018/02/21 14:26:38.855334,  3] ../lib/util/access.c:361(allow_access)
  Allowed connection from 111.222.333.444 (111.222.333.444)
[2018/02/21 14:26:38.855388,  3] ../source3/smbd/service.c:576(make_connection_snum)
  Connect path is '/data/share01' for service [share01]
[2018/02/21 14:26:38.855434,  3] ../source3/smbd/vfs.c:113(vfs_init_default)
  Initialising default vfs hooks
[2018/02/21 14:26:38.855457,  5] ../source3/smbd/vfs.c:103(smb_register_vfs)
  Successfully added vfs backend '/[Default VFS]/'
[2018/02/21 14:26:38.855477,  5] ../source3/smbd/vfs.c:103(smb_register_vfs)
  Successfully added vfs backend 'posixacl'
[2018/02/21 14:26:38.855490,  3] ../source3/smbd/vfs.c:139(vfs_init_custom)
  Initialising custom vfs hooks from [/[Default VFS]/]
  Successfully loaded vfs module [/[Default VFS]/] with the new modules system
[2018/02/21 14:26:38.855508,  3] ../source3/smbd/vfs.c:139(vfs_init_custom)
  Initialising custom vfs hooks from [shadow_copy2]
[2018/02/21 14:26:38.855521,  5] ../source3/smbd/vfs.c:179(vfs_init_custom)
  vfs module [shadow_copy2] not loaded - trying to load...
[2018/02/21 14:26:38.855537,  5] ../lib/util/modules.c:171(do_smb_load_module)
  Loading module 'shadow_copy2'
[2018/02/21 14:26:38.855551,  5] ../lib/util/modules.c:185(do_smb_load_module)
  Loading module 'shadow_copy2': Trying to load from /usr/lib64/samba/vfs/shadow_copy2.so
[2018/02/21 14:26:38.857099,  2] ../lib/util/modules.c:196(do_smb_load_module)
  Module 'shadow_copy2' loaded
[2018/02/21 14:26:38.857127,  5] ../source3/smbd/vfs.c:103(smb_register_vfs)
  Successfully added vfs backend 'shadow_copy2'
  Successfully loaded vfs module [shadow_copy2] with the new modules system
[2018/02/21 14:26:38.857202,  5] ../source3/lib/messages.c:448(messaging_register)
  Registering messaging pointer for type 784 - private_data=0x556d3e67b440
[2018/02/21 14:26:38.857219,  5] ../source3/lib/messages.c:448(messaging_register)
  Registering messaging pointer for type 793 - private_data=0x556d3e67ebc0
[2018/02/21 14:26:38.857232,  5] ../source3/lib/messages.c:448(messaging_register)
  Registering messaging pointer for type 799 - private_data=0x556d3e67ebc0
[2018/02/21 14:26:38.857302,  4] ../source3/smbd/sec_ctx.c:321(set_sec_ctx_internal)
  setting sec ctx (13627, 10513) - sec_ctx_stack_ndx = 0
[2018/02/21 14:26:38.857320,  5] ../libcli/security/security_token.c:63(security_token_debug)
  Security token SIDs (19):
    SID[  0]: S-1-5-21-822149324-2706365316-2594636336-3627
    SID[  1]: S-1-5-21-822149324-2706365316-2594636336-513
    SID[  2]: S-1-5-21-822149324-2706365316-2594636336-512
    SID[  3]: S-1-5-21-822149324-2706365316-2594636336-572
    SID[  4]: S-1-1-0
    SID[  5]: S-1-5-2
    SID[  6]: S-1-5-11
    SID[  7]: S-1-5-32-545
    SID[  8]: S-1-5-32-544
    SID[  9]: S-1-22-1-13627
    SID[ 10]: S-1-22-2-13627
    SID[ 11]: S-1-22-2-10513
    SID[ 12]: S-1-22-2-10512
    SID[ 13]: S-1-22-2-10572
    SID[ 14]: S-1-22-2-3002
    SID[ 15]: S-1-22-2-3003
    SID[ 16]: S-1-22-2-3004
    SID[ 17]: S-1-22-2-3001
    SID[ 18]: S-1-22-2-3000
   Privileges (0x        1FFFFFF0):
    Privilege[  0]: SeMachineAccountPrivilege
    Privilege[  1]: SeTakeOwnershipPrivilege
    Privilege[  2]: SeBackupPrivilege
    Privilege[  3]: SeRestorePrivilege
    Privilege[  4]: SeRemoteShutdownPrivilege
    Privilege[  5]: SePrintOperatorPrivilege
    Privilege[  6]: SeAddUsersPrivilege
    Privilege[  7]: SeDiskOperatorPrivilege
    Privilege[  8]: SeSecurityPrivilege
    Privilege[  9]: SeSystemtimePrivilege
    Privilege[ 10]: SeShutdownPrivilege
    Privilege[ 11]: SeDebugPrivilege
    Privilege[ 12]: SeSystemEnvironmentPrivilege
    Privilege[ 13]: SeSystemProfilePrivilege
    Privilege[ 14]: SeProfileSingleProcessPrivilege
    Privilege[ 15]: SeIncreaseBasePriorityPrivilege
    Privilege[ 16]: SeLoadDriverPrivilege
    Privilege[ 17]: SeCreatePagefilePrivilege
    Privilege[ 18]: SeIncreaseQuotaPrivilege
    Privilege[ 19]: SeChangeNotifyPrivilege
    Privilege[ 20]: SeUndockPrivilege
    Privilege[ 21]: SeManageVolumePrivilege
    Privilege[ 22]: SeImpersonatePrivilege
    Privilege[ 23]: SeCreateGlobalPrivilege
    Privilege[ 24]: SeEnableDelegationPrivilege
   Rights (0x               0):
[2018/02/21 14:26:38.857526,  5] ../source3/auth/token_util.c:640(debug_unix_user_token)
  UNIX token of user 13627
  Primary group is 10513 and contains 9 supplementary groups
  Group[  0]: 13627
  Group[  1]: 10513
  Group[  2]: 10512
  Group[  3]: 10572
  Group[  4]: 3002
  Group[  5]: 3003
  Group[  6]: 3004
  Group[  7]: 3001
  Group[  8]: 3000
[2018/02/21 14:26:38.857591,  5] ../source3/smbd/uid.c:363(change_to_user_internal)
  Impersonated user: uid=(13627,13627), gid=(0,10513)
[2018/02/21 14:26:38.857613,  4] ../source3/smbd/sec_ctx.c:321(set_sec_ctx_internal)
  setting sec ctx (0, 0) - sec_ctx_stack_ndx = 0
[2018/02/21 14:26:38.857627,  5] ../libcli/security/security_token.c:53(security_token_debug)
  Security token: (NULL)
[2018/02/21 14:26:38.857640,  5] ../source3/auth/token_util.c:640(debug_unix_user_token)
  UNIX token of user 0
  Primary group is 0 and contains 0 supplementary groups
[2018/02/21 14:26:38.857699,  5] ../source3/smbd/uid.c:425(smbd_change_to_root_user)
  change_to_root_user: now uid=(0,0) gid=(0,0)
[2018/02/21 14:26:38.857808,  2] ../source3/smbd/service.c:822(make_connection_snum)
  dc-server (ipv4:111.222.333.444:50586) connect to service share01 initially as user MYDOMAIN\matthias (uid=13627, gid=10513) (pid 4002)
[2018/02/21 14:26:38.857835,  5] ../lib/dbwrap/dbwrap.c:159(dbwrap_check_lock_order)
  check lock order 1 for /var/lib/samba/lock/smbXsrv_tcon_global.tdb
[2018/02/21 14:26:38.857863,  5] ../lib/dbwrap/dbwrap.c:127(dbwrap_lock_order_state_destructor)
  release lock order 1 for /var/lib/samba/lock/smbXsrv_tcon_global.tdb
[2018/02/21 14:26:38.858474,  4] ../source3/smbd/sec_ctx.c:321(set_sec_ctx_internal)
  setting sec ctx (13627, 10513) - sec_ctx_stack_ndx = 0
[2018/02/21 14:26:38.858501,  5] ../libcli/security/security_token.c:63(security_token_debug)
  Security token SIDs (19):
    SID[  0]: S-1-5-21-822149324-2706365316-2594636336-3627
    SID[  1]: S-1-5-21-822149324-2706365316-2594636336-513
    SID[  2]: S-1-5-21-822149324-2706365316-2594636336-512
    SID[  3]: S-1-5-21-822149324-2706365316-2594636336-572
    SID[  4]: S-1-1-0
    SID[  5]: S-1-5-2
    SID[  6]: S-1-5-11
    SID[  7]: S-1-5-32-545
    SID[  8]: S-1-5-32-544
    SID[  9]: S-1-22-1-13627
    SID[ 10]: S-1-22-2-13627
    SID[ 11]: S-1-22-2-10513
    SID[ 12]: S-1-22-2-10512
    SID[ 13]: S-1-22-2-10572
    SID[ 14]: S-1-22-2-3002
    SID[ 15]: S-1-22-2-3003
    SID[ 16]: S-1-22-2-3004
    SID[ 17]: S-1-22-2-3001
    SID[ 18]: S-1-22-2-3000
   Privileges (0x        1FFFFFF0):
    Privilege[  0]: SeMachineAccountPrivilege
    Privilege[  1]: SeTakeOwnershipPrivilege
    Privilege[  2]: SeBackupPrivilege
    Privilege[  3]: SeRestorePrivilege
    Privilege[  4]: SeRemoteShutdownPrivilege
    Privilege[  5]: SePrintOperatorPrivilege
    Privilege[  6]: SeAddUsersPrivilege
    Privilege[  7]: SeDiskOperatorPrivilege
    Privilege[  8]: SeSecurityPrivilege
    Privilege[  9]: SeSystemtimePrivilege
    Privilege[ 10]: SeShutdownPrivilege
    Privilege[ 11]: SeDebugPrivilege
    Privilege[ 12]: SeSystemEnvironmentPrivilege
    Privilege[ 13]: SeSystemProfilePrivilege
    Privilege[ 14]: SeProfileSingleProcessPrivilege
    Privilege[ 15]: SeIncreaseBasePriorityPrivilege
    Privilege[ 16]: SeLoadDriverPrivilege
    Privilege[ 17]: SeCreatePagefilePrivilege
    Privilege[ 18]: SeIncreaseQuotaPrivilege
    Privilege[ 19]: SeChangeNotifyPrivilege
    Privilege[ 20]: SeUndockPrivilege
    Privilege[ 21]: SeManageVolumePrivilege
    Privilege[ 22]: SeImpersonatePrivilege
    Privilege[ 23]: SeCreateGlobalPrivilege
    Privilege[ 24]: SeEnableDelegationPrivilege
   Rights (0x               0):
[2018/02/21 14:26:38.858762,  5] ../source3/auth/token_util.c:640(debug_unix_user_token)
  UNIX token of user 13627
  Primary group is 10513 and contains 9 supplementary groups
  Group[  0]: 13627
  Group[  1]: 10513
  Group[  2]: 10512
  Group[  3]: 10572
  Group[  4]: 3002
  Group[  5]: 3003
  Group[  6]: 3004
  Group[  7]: 3001
  Group[  8]: 3000
[2018/02/21 14:26:38.858833,  5] ../source3/smbd/uid.c:363(change_to_user_internal)
  Impersonated user: uid=(13627,13627), gid=(0,10513)
[2018/02/21 14:26:38.858854,  4] ../source3/smbd/vfs.c:874(vfs_ChDir)
  vfs_ChDir to /data/share01
[2018/02/21 14:26:38.858895,  4] ../source3/smbd/vfs.c:885(vfs_ChDir)
  vfs_ChDir got /data/share01
[2018/02/21 14:26:38.858929,  5] ../lib/dbwrap/dbwrap.c:159(dbwrap_check_lock_order)
  check lock order 1 for /var/lib/samba/lock/smbXsrv_session_global.tdb
[2018/02/21 14:26:38.858979,  5] ../lib/dbwrap/dbwrap.c:127(dbwrap_lock_order_state_destructor)
  release lock order 1 for /var/lib/samba/lock/smbXsrv_session_global.tdb
[2018/02/21 14:26:38.858998,  5] ../lib/dbwrap/dbwrap.c:159(dbwrap_check_lock_order)
  check lock order 1 for /var/lib/samba/lock/smbXsrv_tcon_global.tdb
[2018/02/21 14:26:38.859019,  5] ../lib/dbwrap/dbwrap.c:127(dbwrap_lock_order_state_destructor)
  release lock order 1 for /var/lib/samba/lock/smbXsrv_tcon_global.tdb
[2018/02/21 14:26:38.859053,  5] ../libcli/smb/smb2_signing.c:93(smb2_signing_sign_pdu)
  signed SMB2 message
[2018/02/21 14:26:38.859564,  4] ../source3/smbd/uid.c:384(change_to_user)
  Skipping user change - already user
[2018/02/21 14:26:38.859592,  5] ../lib/dbwrap/dbwrap.c:159(dbwrap_check_lock_order)
  check lock order 1 for /var/lib/samba/lock/smbXsrv_tcon_global.tdb
[2018/02/21 14:26:38.859620,  5] ../lib/dbwrap/dbwrap.c:127(dbwrap_lock_order_state_destructor)
  release lock order 1 for /var/lib/samba/lock/smbXsrv_tcon_global.tdb
[2018/02/21 14:26:38.859697,  5] ../source3/smbd/filename.c:443(unix_convert)
  unix_convert called on file ""
[2018/02/21 14:26:38.859723,  5] ../source3/smbd/filename.c:477(unix_convert)
  conversion finished "" -> .
[2018/02/21 14:26:38.859749,  5] ../source3/smbd/vfs.c:1370(check_reduced_name)
  check_reduced_name: . reduced to /data/share01
[2018/02/21 14:26:38.859794,  5] ../lib/dbwrap/dbwrap.c:159(dbwrap_check_lock_order)
  check lock order 1 for /var/lib/samba/lock/smbXsrv_open_global.tdb
[2018/02/21 14:26:38.859864,  5] ../lib/dbwrap/dbwrap.c:127(dbwrap_lock_order_state_destructor)
  release lock order 1 for /var/lib/samba/lock/smbXsrv_open_global.tdb
[2018/02/21 14:26:38.859884,  5] ../source3/smbd/files.c:128(file_new)
  allocated file structure fnum 1383817672 (1 used)
[2018/02/21 14:26:38.859929,  5] ../source3/smbd/dosmode.c:206(unix_mode)
  unix_mode: unix_mode(.) returning 0644
[2018/02/21 14:26:38.859995,  5] ../source3/smbd/dosmode.c:287(get_ea_dos_attribute)
  get_ea_dos_attribute: Cannot get attribute from EA on file .: Error = No data available
[2018/02/21 14:26:38.860033,  4] ../source3/smbd/open.c:3056(open_file_ntcreate)
  calling open_file with flags=0x0 flags2=0x0 mode=0644, access_mask = 0x60080, open_access_mask = 0x60080
[2018/02/21 14:26:38.860206,  5] ../lib/dbwrap/dbwrap.c:159(dbwrap_check_lock_order)
  check lock order 1 for /var/lib/samba/lock/smbXsrv_open_global.tdb
[2018/02/21 14:26:38.860242,  5] ../lib/dbwrap/dbwrap.c:127(dbwrap_lock_order_state_destructor)
  release lock order 1 for /var/lib/samba/lock/smbXsrv_open_global.tdb
[2018/02/21 14:26:38.860259,  5] ../source3/smbd/files.c:565(file_free)
  freed files structure 1383817672 (0 used)
[2018/02/21 14:26:38.860274,  5] ../source3/smbd/open.c:3738(open_directory)
  open_directory: opening directory ., access_mask = 0x60080, share_access = 0x7 create_options = 0x200000, create_disposition = 0x1, file_attributes = 0x10
[2018/02/21 14:26:38.860346,  5] ../lib/dbwrap/dbwrap.c:159(dbwrap_check_lock_order)
  check lock order 1 for /var/lib/samba/lock/smbXsrv_open_global.tdb
[2018/02/21 14:26:38.860380,  5] ../lib/dbwrap/dbwrap.c:127(dbwrap_lock_order_state_destructor)
  release lock order 1 for /var/lib/samba/lock/smbXsrv_open_global.tdb
[2018/02/21 14:26:38.860396,  5] ../source3/smbd/files.c:128(file_new)
  allocated file structure fnum 1593000861 (1 used)
[2018/02/21 14:26:38.860418,  5] ../lib/dbwrap/dbwrap.c:159(dbwrap_check_lock_order)
  check lock order 1 for /var/lib/samba/lock/locking.tdb
[2018/02/21 14:26:38.860500,  5] ../lib/dbwrap/dbwrap.c:127(dbwrap_lock_order_state_destructor)
  release lock order 1 for /var/lib/samba/lock/locking.tdb
[2018/02/21 14:26:38.860572,  5] ../lib/dbwrap/dbwrap.c:159(dbwrap_check_lock_order)
  check lock order 1 for /var/lib/samba/lock/smbXsrv_open_global.tdb
[2018/02/21 14:26:38.860599,  5] ../lib/dbwrap/dbwrap.c:127(dbwrap_lock_order_state_destructor)
  release lock order 1 for /var/lib/samba/lock/smbXsrv_open_global.tdb
[2018/02/21 14:26:38.860620,  8] ../source3/smbd/dosmode.c:616(dos_mode)
  dos_mode: .
[2018/02/21 14:26:38.860641,  5] ../source3/smbd/dosmode.c:287(get_ea_dos_attribute)
  get_ea_dos_attribute: Cannot get attribute from EA on file .: Error = No data available
[2018/02/21 14:26:38.860688,  5] ../source3/smbd/dosmode.c:70(dos_mode_debug_print)
  dos_mode_debug_print: dos_mode_from_sbuf returning (0x10): "d"
[2018/02/21 14:26:38.860705,  5] ../source3/smbd/dosmode.c:70(dos_mode_debug_print)
  dos_mode_debug_print: dos_mode returning (0x10): "d"
[2018/02/21 14:26:38.861188,  4] ../source3/smbd/uid.c:384(change_to_user)
  Skipping user change - already user
[2018/02/21 14:26:38.861287,  3] ../source3/smbd/nttrans.c:2034(smbd_do_query_security_desc)
  smbd_do_query_security_desc: sd_size = 264.
[2018/02/21 14:26:38.861746,  4] ../source3/smbd/uid.c:384(change_to_user)
  Skipping user change - already user
[2018/02/21 14:26:38.861823,  3] ../source3/smbd/nttrans.c:2034(smbd_do_query_security_desc)
  smbd_do_query_security_desc: sd_size = 64.
[2018/02/21 14:26:38.862406,  4] ../source3/smbd/uid.c:384(change_to_user)
  Skipping user change - already user
[2018/02/21 14:26:38.862436,  5] ../source3/smbd/filename.c:443(unix_convert)
  unix_convert called on file ""
[2018/02/21 14:26:38.862457,  5] ../source3/smbd/filename.c:477(unix_convert)
  conversion finished "" -> .
[2018/02/21 14:26:38.862475,  5] ../source3/smbd/vfs.c:1370(check_reduced_name)
  check_reduced_name: . reduced to /data/share01
[2018/02/21 14:26:38.862491,  5] ../source3/smbd/open.c:3738(open_directory)
  open_directory: opening directory ., access_mask = 0x100081, share_access = 0x3 create_options = 0x200001, create_disposition = 0x1, file_attributes = 0x10
[2018/02/21 14:26:38.862546,  5] ../lib/dbwrap/dbwrap.c:159(dbwrap_check_lock_order)
  check lock order 1 for /var/lib/samba/lock/smbXsrv_open_global.tdb
[2018/02/21 14:26:38.862582,  5] ../lib/dbwrap/dbwrap.c:127(dbwrap_lock_order_state_destructor)
  release lock order 1 for /var/lib/samba/lock/smbXsrv_open_global.tdb
[2018/02/21 14:26:38.862598,  5] ../source3/smbd/files.c:128(file_new)
  allocated file structure fnum 1983524724 (2 used)
[2018/02/21 14:26:38.862642,  5] ../source3/smbd/vfs.c:1370(check_reduced_name)
  check_reduced_name: . reduced to /data/share01
[2018/02/21 14:26:38.862722,  5] ../lib/dbwrap/dbwrap.c:159(dbwrap_check_lock_order)
  check lock order 1 for /var/lib/samba/lock/locking.tdb
[2018/02/21 14:26:38.862761,  5] ../lib/dbwrap/dbwrap.c:127(dbwrap_lock_order_state_destructor)
  release lock order 1 for /var/lib/samba/lock/locking.tdb
[2018/02/21 14:26:38.862834,  8] ../source3/smbd/dosmode.c:616(dos_mode)
  dos_mode: .
[2018/02/21 14:26:38.862860,  5] ../source3/smbd/dosmode.c:287(get_ea_dos_attribute)
  get_ea_dos_attribute: Cannot get attribute from EA on file .: Error = No data available
[2018/02/21 14:26:38.862881,  5] ../source3/smbd/dosmode.c:70(dos_mode_debug_print)
  dos_mode_debug_print: dos_mode_from_sbuf returning (0x10): "d"
[2018/02/21 14:26:38.862898,  5] ../source3/smbd/dosmode.c:70(dos_mode_debug_print)
  dos_mode_debug_print: dos_mode returning (0x10): "d"
[2018/02/21 14:26:38.862923,  4] ../source3/smbd/uid.c:384(change_to_user)
  Skipping user change - already user
[2018/02/21 14:26:38.862985,  5] ../source3/smbd/dir.c:474(dptr_create)
  dptr_create dir=.
[2018/02/21 14:26:38.863045,  3] ../source3/smbd/dir.c:656(dptr_create)
  creating new dirptr 0 for path ., expect_close = 0
[2018/02/21 14:26:38.863066,  8] ../source3/smbd/smb2_query_directory.c:447(smbd_smb2_query_directory_send)
  smbd_smb2_query_directory_send: dirpath=<.> dontdescend=<>, in_output_buffer_length = 65528
[2018/02/21 14:26:38.863090,  6] ../source3/smbd/dir.c:1136(smbd_dirptr_get_entry)
  smbd_dirptr_get_entry: dirptr 0x556d3e679ce0 now at offset 0
[2018/02/21 14:26:38.863124,  8] ../source3/smbd/dosmode.c:616(dos_mode)
  dos_mode: .
[2018/02/21 14:26:38.863157,  5] ../source3/smbd/dosmode.c:287(get_ea_dos_attribute)
  get_ea_dos_attribute: Cannot get attribute from EA on file .: Error = No data available
[2018/02/21 14:26:38.863175,  5] ../source3/smbd/dosmode.c:70(dos_mode_debug_print)
  dos_mode_debug_print: dos_mode_from_sbuf returning (0x10): "d"
[2018/02/21 14:26:38.863189,  5] ../source3/smbd/dosmode.c:70(dos_mode_debug_print)
  dos_mode_debug_print: dos_mode returning (0x10): "d"
[2018/02/21 14:26:38.863213,  3] ../source3/smbd/dir.c:1227(smbd_dirptr_get_entry)
  smbd_dirptr_get_entry mask=[*] found . fname=. (.)
[2018/02/21 14:26:38.863240,  6] ../source3/smbd/dir.c:1136(smbd_dirptr_get_entry)
  smbd_dirptr_get_entry: dirptr 0x556d3e679ce0 now at offset 2147483648
[2018/02/21 14:26:38.863260,  8] ../source3/smbd/dosmode.c:616(dos_mode)
  dos_mode: ..
[2018/02/21 14:26:38.863278,  5] ../source3/smbd/dosmode.c:287(get_ea_dos_attribute)
  get_ea_dos_attribute: Cannot get attribute from EA on file ..: Error = No data available
[2018/02/21 14:26:38.863293,  5] ../source3/smbd/dosmode.c:70(dos_mode_debug_print)
  dos_mode_debug_print: dos_mode_from_sbuf returning (0x10): "d"
[2018/02/21 14:26:38.863308,  5] ../source3/smbd/dosmode.c:70(dos_mode_debug_print)
  dos_mode_debug_print: dos_mode returning (0x10): "d"
[2018/02/21 14:26:38.863329,  3] ../source3/smbd/dir.c:1227(smbd_dirptr_get_entry)
  smbd_dirptr_get_entry mask=[*] found .. fname=.. (..)
[2018/02/21 14:26:38.863360,  6] ../source3/smbd/dir.c:1136(smbd_dirptr_get_entry)
  smbd_dirptr_get_entry: dirptr 0x556d3e679ce0 now at offset -1
[2018/02/21 14:26:38.863380,  4] ../source3/smbd/uid.c:384(change_to_user)
  Skipping user change - already user
[2018/02/21 14:26:38.863397,  8] ../source3/smbd/smb2_query_directory.c:447(smbd_smb2_query_directory_send)
  smbd_smb2_query_directory_send: dirpath=<.> dontdescend=<>, in_output_buffer_length = 120
[2018/02/21 14:26:38.863414,  6] ../source3/smbd/dir.c:1136(smbd_dirptr_get_entry)
  smbd_dirptr_get_entry: dirptr 0x556d3e679ce0 now at offset -1
[2018/02/21 14:26:38.863429,  3] ../source3/smbd/smb2_server.c:3097(smbd_smb2_request_error_ex)
  smbd_smb2_request_error_ex: smbd_smb2_request_error_ex: idx[9] status[STATUS_NO_MORE_FILES] || at ../source3/smbd/smb2_query_directory.c:155
[2018/02/21 14:26:38.863992,  4] ../source3/smbd/uid.c:384(change_to_user)
  Skipping user change - already user
[2018/02/21 14:26:38.864041,  5] ../source3/smbd/posix_acls.c:1179(unpack_nt_owners)
  unpack_nt_owners: validating owner_sids.
[2018/02/21 14:26:38.864059,  5] ../source3/smbd/posix_acls.c:1224(unpack_nt_owners)
  unpack_nt_owners: owner_sids validated.
[2018/02/21 14:26:38.864126,  2] ../source3/smbd/posix_acls.c:3004(set_canon_ace_list)
  set_canon_ace_list: sys_acl_set_file type file failed for file . (Operation not permitted).
[2018/02/21 14:26:38.864200,  3] ../source3/smbd/posix_acls.c:3888(set_nt_acl)
  set_nt_acl: failed to set file acl on file . (Operation not permitted).
[2018/02/21 14:26:38.864220,  3] ../source3/smbd/smb2_server.c:3097(smbd_smb2_request_error_ex)
  smbd_smb2_request_error_ex: smbd_smb2_request_error_ex: idx[1] status[NT_STATUS_ACCESS_DENIED] || at ../source3/smbd/smb2_setinfo.c:132



More information about the samba mailing list