[2017/06/05 16:22:32.278698, 6, pid=2877, effective(0, 0), real(0, 0)] ../source3/param/loadparm.c:2229(lp_file_list_changed) lp_file_list_changed() file /etc/samba/smb.conf -> /etc/samba/smb.conf last mod_time: Mon Jun 5 14:14:33 2017 [2017/06/05 16:22:32.279394, 5, pid=2877, effective(0, 0), real(0, 0)] ../lib/dbwrap/dbwrap.c:159(dbwrap_check_lock_order) check lock order 1 for /var/lock/samba/smbXsrv_session_global.tdb [2017/06/05 16:22:32.279802, 10, pid=2877, effective(0, 0), real(0, 0)] ../lib/dbwrap/dbwrap.c:114(debug_lock_order) lock order: 1:/var/lock/samba/smbXsrv_session_global.tdb 2: 3: [2017/06/05 16:22:32.280148, 10, pid=2877, effective(0, 0), real(0, 0)] ../lib/dbwrap/dbwrap_tdb.c:59(db_tdb_log_key) Locking key 5A21384A [2017/06/05 16:22:32.280442, 10, pid=2877, effective(0, 0), real(0, 0)] ../lib/dbwrap/dbwrap_tdb.c:143(db_tdb_fetch_locked_internal) Allocated locked data 0x0x7f38ed3b0860 [2017/06/05 16:22:32.280858, 10, pid=2877, effective(0, 0), real(0, 0)] ../source3/smbd/smbXsrv_session.c:943(smbXsrv_session_global_store) [2017/06/05 16:22:32.281041, 10, pid=2877, effective(0, 0), real(0, 0)] ../source3/smbd/smbXsrv_session.c:945(smbXsrv_session_global_store) smbXsrv_session_global_store: key '5A21384A' stored [2017/06/05 16:22:32.281344, 1, pid=2877, effective(0, 0), real(0, 0)] ../librpc/ndr/ndr.c:413(ndr_print_debug) &global_blob: struct smbXsrv_session_globalB version : SMBXSRV_VERSION_0 (0) seqnum : 0x00000005 (5) info : union smbXsrv_session_globalU(case 0) info0 : * info0: struct smbXsrv_session_global0 db_rec : * session_global_id : 0x5a21384a (1512126538) session_wire_id : 0x000000005a21384a (1512126538) creation_time : Mon Jun 5 16:22:32 2017 IDT expiration_time : Thu Jan 1 02:00:00 1970 IST auth_time : Mon Jun 5 16:22:32 2017 IDT auth_session_info_seqnum : 0x00000001 (1) auth_session_info : * auth_session_info: struct auth_session_info security_token : * security_token: struct security_token num_sids : 0x00000009 (9) sids: ARRAY(9) sids : S-1-5-21-1893543895-1847372660-4172524467-501 sids : S-1-5-21-1893543895-1847372660-4172524467-514 sids : S-1-22-2-65534 sids : S-1-1-0 sids : S-1-5-2 sids : S-1-5-32-546 sids : S-1-22-1-65534 sids : S-1-22-2-1000003 sids : S-1-22-2-1000004 privilege_mask : 0x0000000000000000 (0) 0: SEC_PRIV_MACHINE_ACCOUNT_BIT 0: SEC_PRIV_PRINT_OPERATOR_BIT 0: SEC_PRIV_ADD_USERS_BIT 0: SEC_PRIV_DISK_OPERATOR_BIT 0: SEC_PRIV_REMOTE_SHUTDOWN_BIT 0: SEC_PRIV_BACKUP_BIT 0: SEC_PRIV_RESTORE_BIT 0: SEC_PRIV_TAKE_OWNERSHIP_BIT 0: SEC_PRIV_INCREASE_QUOTA_BIT 0: SEC_PRIV_SECURITY_BIT 0: SEC_PRIV_LOAD_DRIVER_BIT 0: SEC_PRIV_SYSTEM_PROFILE_BIT 0: SEC_PRIV_SYSTEMTIME_BIT 0: SEC_PRIV_PROFILE_SINGLE_PROCESS_BIT 0: SEC_PRIV_INCREASE_BASE_PRIORITY_BIT 0: SEC_PRIV_CREATE_PAGEFILE_BIT 0: SEC_PRIV_SHUTDOWN_BIT 0: SEC_PRIV_DEBUG_BIT 0: SEC_PRIV_SYSTEM_ENVIRONMENT_BIT 0: SEC_PRIV_CHANGE_NOTIFY_BIT 0: SEC_PRIV_UNDOCK_BIT 0: SEC_PRIV_ENABLE_DELEGATION_BIT 0: SEC_PRIV_MANAGE_VOLUME_BIT 0: SEC_PRIV_IMPERSONATE_BIT 0: SEC_PRIV_CREATE_GLOBAL_BIT rights_mask : 0x00000000 (0) 0: LSA_POLICY_MODE_INTERACTIVE 0: LSA_POLICY_MODE_NETWORK 0: LSA_POLICY_MODE_BATCH 0: LSA_POLICY_MODE_SERVICE 0: LSA_POLICY_MODE_PROXY 0: LSA_POLICY_MODE_DENY_INTERACTIVE 0: LSA_POLICY_MODE_DENY_NETWORK 0: LSA_POLICY_MODE_DENY_BATCH 0: LSA_POLICY_MODE_DENY_SERVICE 0: LSA_POLICY_MODE_REMOTE_INTERACTIVE 0: LSA_POLICY_MODE_DENY_REMOTE_INTERACTIVE 0x00: LSA_POLICY_MODE_ALL (0) 0x00: LSA_POLICY_MODE_ALL_NT4 (0) unix_token : * unix_token: struct security_unix_token uid : 0x000000000000fffe (65534) gid : 0x000000000000fffe (65534) ngroups : 0x00000003 (3) groups: ARRAY(3) groups : 0x000000000000fffe (65534) groups : 0x00000000000f4243 (1000003) groups : 0x00000000000f4244 (1000004) info : * info: struct auth_user_info account_name : * account_name : 'nobody' user_principal_name : NULL user_principal_constructed: 0x00 (0) domain_name : * domain_name : 'VSA-00000134' dns_domain_name : NULL full_name : NULL logon_script : NULL profile_path : NULL home_directory : NULL home_drive : NULL logon_server : NULL last_logon : NTTIME(0) last_logoff : NTTIME(0) acct_expiry : NTTIME(0) last_password_change : NTTIME(0) allow_password_change : NTTIME(0) force_password_change : NTTIME(0) logon_count : 0x0000 (0) bad_password_count : 0x0000 (0) acct_flags : 0x00000000 (0) authenticated : 0x00 (0) unix_info : * unix_info: struct auth_user_info_unix unix_name : * unix_name : 'nobody' sanitized_username : * sanitized_username : 'liran' torture : NULL credentials : NULL connection_dialect : 0x0300 (768) signing_flags : 0x04 (4) 0: SMBXSRV_SIGNING_REQUIRED 0: SMBXSRV_PROCESSED_SIGNED_PACKET 1: SMBXSRV_PROCESSED_UNSIGNED_PACKET encryption_flags : 0x08 (8) 0: SMBXSRV_ENCRYPTION_REQUIRED 0: SMBXSRV_ENCRYPTION_DESIRED 0: SMBXSRV_PROCESSED_ENCRYPTED_PACKET 1: SMBXSRV_PROCESSED_UNENCRYPTED_PACKET num_channels : 0x00000001 (1) channels: ARRAY(1) channels: struct smbXsrv_channel_global0 server_id: struct server_id pid : 0x0000000000000b3d (2877) task_id : 0x00000000 (0) vnn : 0xffffffff (4294967295) unique_id : 0x27330f1f08b45cf6 (2824618017255873782) local_address : 'ipv4:170.70.2.104:445' remote_address : 'ipv4:170.70.2.21:54923' remote_name : '170.70.2.21' auth_session_info_seqnum : 0x00000001 (1) connection : * encryption_cipher : 0x0001 (1) [2017/06/05 16:22:32.291874, 5, pid=2877, effective(0, 0), real(0, 0)] ../lib/dbwrap/dbwrap.c:127(dbwrap_lock_order_state_destructor) release lock order 1 for /var/lock/samba/smbXsrv_session_global.tdb [2017/06/05 16:22:32.291897, 10, pid=2877, effective(0, 0), real(0, 0)] ../lib/dbwrap/dbwrap.c:114(debug_lock_order) lock order: 1: 2: 3: [2017/06/05 16:22:32.291919, 10, pid=2877, effective(0, 0), real(0, 0)] ../lib/dbwrap/dbwrap_tdb.c:59(db_tdb_log_key) Unlocking key 5A21384A [2017/06/05 16:22:32.291942, 10, pid=2877, effective(0, 0), real(0, 0)] ../source3/smbd/smbXsrv_session.c:1405(smbXsrv_session_update) [2017/06/05 16:22:32.291954, 10, pid=2877, effective(0, 0), real(0, 0)] ../source3/smbd/smbXsrv_session.c:1413(smbXsrv_session_update) smbXsrv_session_update: global_id (0x5a21384a) stored [2017/06/05 16:22:32.291996, 1, pid=2877, effective(0, 0), real(0, 0)] ../librpc/ndr/ndr.c:413(ndr_print_debug) &session_blob: struct smbXsrv_sessionB version : SMBXSRV_VERSION_0 (0) reserved : 0x00000000 (0) info : union smbXsrv_sessionU(case 0) info0 : * info0: struct smbXsrv_session table : * db_rec : NULL client : * local_id : 0x5a21384a (1512126538) global : * global: struct smbXsrv_session_global0 db_rec : NULL session_global_id : 0x5a21384a (1512126538) session_wire_id : 0x000000005a21384a (1512126538) creation_time : Mon Jun 5 16:22:32 2017 IDT expiration_time : Thu Jan 1 02:00:00 1970 IST auth_time : Mon Jun 5 16:22:32 2017 IDT auth_session_info_seqnum : 0x00000001 (1) auth_session_info : * auth_session_info: struct auth_session_info security_token : * security_token: struct security_token num_sids : 0x00000009 (9) sids: ARRAY(9) sids : S-1-5-21-1893543895-1847372660-4172524467-501 sids : S-1-5-21-1893543895-1847372660-4172524467-514 sids : S-1-22-2-65534 sids : S-1-1-0 sids : S-1-5-2 sids : S-1-5-32-546 sids : S-1-22-1-65534 sids : S-1-22-2-1000003 sids : S-1-22-2-1000004 privilege_mask : 0x0000000000000000 (0) 0: SEC_PRIV_MACHINE_ACCOUNT_BIT 0: SEC_PRIV_PRINT_OPERATOR_BIT 0: SEC_PRIV_ADD_USERS_BIT 0: SEC_PRIV_DISK_OPERATOR_BIT 0: SEC_PRIV_REMOTE_SHUTDOWN_BIT 0: SEC_PRIV_BACKUP_BIT 0: SEC_PRIV_RESTORE_BIT 0: SEC_PRIV_TAKE_OWNERSHIP_BIT 0: SEC_PRIV_INCREASE_QUOTA_BIT 0: SEC_PRIV_SECURITY_BIT 0: SEC_PRIV_LOAD_DRIVER_BIT 0: SEC_PRIV_SYSTEM_PROFILE_BIT 0: SEC_PRIV_SYSTEMTIME_BIT 0: SEC_PRIV_PROFILE_SINGLE_PROCESS_BIT 0: SEC_PRIV_INCREASE_BASE_PRIORITY_BIT 0: SEC_PRIV_CREATE_PAGEFILE_BIT 0: SEC_PRIV_SHUTDOWN_BIT 0: SEC_PRIV_DEBUG_BIT 0: SEC_PRIV_SYSTEM_ENVIRONMENT_BIT 0: SEC_PRIV_CHANGE_NOTIFY_BIT 0: SEC_PRIV_UNDOCK_BIT 0: SEC_PRIV_ENABLE_DELEGATION_BIT 0: SEC_PRIV_MANAGE_VOLUME_BIT 0: SEC_PRIV_IMPERSONATE_BIT 0: SEC_PRIV_CREATE_GLOBAL_BIT rights_mask : 0x00000000 (0) 0: LSA_POLICY_MODE_INTERACTIVE 0: LSA_POLICY_MODE_NETWORK 0: LSA_POLICY_MODE_BATCH 0: LSA_POLICY_MODE_SERVICE 0: LSA_POLICY_MODE_PROXY 0: LSA_POLICY_MODE_DENY_INTERACTIVE 0: LSA_POLICY_MODE_DENY_NETWORK 0: LSA_POLICY_MODE_DENY_BATCH 0: LSA_POLICY_MODE_DENY_SERVICE 0: LSA_POLICY_MODE_REMOTE_INTERACTIVE 0: LSA_POLICY_MODE_DENY_REMOTE_INTERACTIVE 0x00: LSA_POLICY_MODE_ALL (0) 0x00: LSA_POLICY_MODE_ALL_NT4 (0) unix_token : * unix_token: struct security_unix_token uid : 0x000000000000fffe (65534) gid : 0x000000000000fffe (65534) ngroups : 0x00000003 (3) groups: ARRAY(3) groups : 0x000000000000fffe (65534) groups : 0x00000000000f4243 (1000003) groups : 0x00000000000f4244 (1000004) info : * info: struct auth_user_info account_name : * account_name : 'nobody' user_principal_name : NULL user_principal_constructed: 0x00 (0) domain_name : * domain_name : 'VSA-00000134' dns_domain_name : NULL full_name : NULL logon_script : NULL profile_path : NULL home_directory : NULL home_drive : NULL logon_server : NULL last_logon : NTTIME(0) last_logoff : NTTIME(0) acct_expiry : NTTIME(0) last_password_change : NTTIME(0) allow_password_change : NTTIME(0) force_password_change : NTTIME(0) logon_count : 0x0000 (0) bad_password_count : 0x0000 (0) acct_flags : 0x00000000 (0) authenticated : 0x00 (0) unix_info : * unix_info: struct auth_user_info_unix unix_name : * unix_name : 'nobody' sanitized_username : * sanitized_username : 'liran' torture : NULL credentials : NULL connection_dialect : 0x0300 (768) signing_flags : 0x04 (4) 0: SMBXSRV_SIGNING_REQUIRED 0: SMBXSRV_PROCESSED_SIGNED_PACKET 1: SMBXSRV_PROCESSED_UNSIGNED_PACKET encryption_flags : 0x08 (8) 0: SMBXSRV_ENCRYPTION_REQUIRED 0: SMBXSRV_ENCRYPTION_DESIRED 0: SMBXSRV_PROCESSED_ENCRYPTED_PACKET 1: SMBXSRV_PROCESSED_UNENCRYPTED_PACKET num_channels : 0x00000001 (1) channels: ARRAY(1) channels: struct smbXsrv_channel_global0 server_id: struct server_id pid : 0x0000000000000b3d (2877) task_id : 0x00000000 (0) vnn : 0xffffffff (4294967295) unique_id : 0x27330f1f08b45cf6 (2824618017255873782) local_address : 'ipv4:170.70.2.104:445' remote_address : 'ipv4:170.70.2.21:54923' remote_name : '170.70.2.21' auth_session_info_seqnum : 0x00000001 (1) connection : * encryption_cipher : 0x0001 (1) status : NT_STATUS_OK idle_time : Mon Jun 5 16:22:32 2017 IDT nonce_high_random : 0x5d8110aabdabd278 (6737684843035611768) nonce_high_max : 0x0000000000ffffff (16777215) nonce_high : 0x0000000000000000 (0) nonce_low : 0x0000000000000000 (0) compat : * tcon_table : * pending_auth : NULL [2017/06/05 16:22:32.293810, 10, pid=2877, effective(0, 0), real(0, 0)] ../source3/smbd/smb2_server.c:3014(smbd_smb2_request_done_ex) smbd_smb2_request_done_ex: idx[1] status[NT_STATUS_OK] body[8] dyn[yes:9] at ../source3/smbd/smb2_sesssetup.c:171 [2017/06/05 16:22:32.293866, 10, pid=2877, effective(0, 0), real(0, 0)] ../source3/smbd/smb2_server.c:925(smb2_set_operation_credit) smb2_set_operation_credit: requested 31, charge 1, granted 31, current possible/max 512/512, total granted/max/low/range 31/8192/4/31 [2017/06/05 16:22:32.294599, 10, pid=2877, effective(0, 0), real(0, 0)] ../source3/smbd/smb2_server.c:3912(smbd_smb2_io_handler) smbd_smb2_request idx[1] of 5 vectors [2017/06/05 16:22:32.294871, 10, pid=2877, effective(0, 0), real(0, 0)] ../source3/smbd/smb2_server.c:673(smb2_validate_sequence_number) smb2_validate_sequence_number: clearing id 4 (position 4) from bitmap [2017/06/05 16:22:32.295068, 10, pid=2877, effective(0, 0), real(0, 0)] ../source3/smbd/smb2_server.c:2272(smbd_smb2_request_dispatch) smbd_smb2_request_dispatch: opcode[SMB2_OP_TCON] mid = 4 [2017/06/05 16:22:32.295286, 0, pid=2877, effective(0, 0), real(0, 0)] ../source3/smbd/smb2_server.c:2145(smbd_smb2_request_dispatch_update_counts) smbd_smb2_request_dispatch_update_counts: compat_chain_fsp=(nil) [2017/06/05 16:22:32.295615, 4, pid=2877, effective(0, 0), real(0, 0)] ../source3/smbd/sec_ctx.c:320(set_sec_ctx_internal) setting sec ctx (0, 0) - sec_ctx_stack_ndx = 0 [2017/06/05 16:22:32.295852, 5, pid=2877, effective(0, 0), real(0, 0)] ../libcli/security/security_token.c:53(security_token_debug) Security token: (NULL) [2017/06/05 16:22:32.296064, 5, pid=2877, effective(0, 0), real(0, 0)] ../source3/auth/token_util.c:639(debug_unix_user_token) UNIX token of user 0 Primary group is 0 and contains 0 supplementary groups [2017/06/05 16:22:32.296298, 5, pid=2877, effective(0, 0), real(0, 0)] ../source3/smbd/uid.c:425(smbd_change_to_root_user) change_to_root_user: now uid=(0,0) gid=(0,0) [2017/06/05 16:22:32.296533, 10, pid=2877, effective(0, 0), real(0, 0)] ../source3/smbd/smb2_tcon.c:211(smbd_smb2_tree_connect) smbd_smb2_tree_connect: path[\\170.70.2.104\vol1] share[vol1] [2017/06/05 16:22:32.296754, 7, pid=2877, effective(0, 0), real(0, 0)] ../source3/param/loadparm.c:4102(lp_servicenumber) lp_servicenumber: couldn't find vol1 [2017/06/05 16:22:32.296955, 5, pid=2877, effective(0, 0), real(0, 0)] ../source3/lib/username.c:181(Get_Pwnam_alloc) Finding user vol1 [2017/06/05 16:22:32.297170, 5, pid=2877, effective(0, 0), real(0, 0)] ../source3/lib/username.c:120(Get_Pwnam_internals) Trying _Get_Pwnam(), username as lowercase is vol1 [2017/06/05 16:22:32.297773, 5, pid=2877, effective(0, 0), real(0, 0)] ../source3/lib/username.c:141(Get_Pwnam_internals) Trying _Get_Pwnam(), username as uppercase is VOL1 [2017/06/05 16:22:32.298134, 5, pid=2877, effective(0, 0), real(0, 0)] ../source3/lib/username.c:153(Get_Pwnam_internals) Checking combinations of 0 uppercase letters in vol1 [2017/06/05 16:22:32.298184, 5, pid=2877, effective(0, 0), real(0, 0)] ../source3/lib/username.c:159(Get_Pwnam_internals) Get_Pwnam_internals didn't find user [vol1]! [2017/06/05 16:22:32.298237, 3, pid=2877, effective(0, 0), real(0, 0)] ../source3/param/service.c:150(find_service) checking for home directory vol1 gave (NULL) [2017/06/05 16:22:32.298404, 7, pid=2877, effective(0, 0), real(0, 0)] ../source3/param/loadparm.c:4102(lp_servicenumber) lp_servicenumber: couldn't find printers [2017/06/05 16:22:32.298589, 5, pid=2877, effective(0, 0), real(0, 0)] ../source3/param/loadparm.c:2058(process_registry_service) process_registry_service: service name printers [2017/06/05 16:22:32.298641, 7, pid=2877, effective(0, 0), real(0, 0), class=registry] ../source3/registry/reg_api.c:143(regkey_open_onelevel) regkey_open_onelevel: name = [printers] [2017/06/05 16:22:32.298673, 10, pid=2877, effective(0, 0), real(0, 0), class=registry] ../source3/registry/reg_backend_db.c:857(regdb_open) regdb_open: incrementing refcount (2->3) [2017/06/05 16:22:32.298908, 10, pid=2877, effective(0, 0), real(0, 0), class=registry] ../source3/registry/reg_cachehook.c:125(reghook_cache_find) reghook_cache_find: Searching for keyname [\HKLM\SOFTWARE\Samba\smbconf\printers] [2017/06/05 16:22:32.298943, 10, pid=2877, effective(0, 0), real(0, 0)] ../source3/lib/adt_tree.c:367(pathtree_find) pathtree_find: Enter [\HKLM\SOFTWARE\Samba\smbconf\printers] [2017/06/05 16:22:32.299071, 10, pid=2877, effective(0, 0), real(0, 0)] ../source3/lib/adt_tree.c:440(pathtree_find) pathtree_find: Exit [2017/06/05 16:22:32.299116, 10, pid=2877, effective(0, 0), real(0, 0), class=registry] ../source3/registry/reg_cachehook.c:130(reghook_cache_find) reghook_cache_find: found ops 0x7f38e87c4580 for key [\HKLM\SOFTWARE\Samba\smbconf\printers] [2017/06/05 16:22:32.299169, 10, pid=2877, effective(0, 0), real(0, 0), class=registry] ../source3/registry/reg_backend_db.c:1739(regdb_fetch_keys_internal) key [HKLM\SOFTWARE\Samba\smbconf\printers] not found [2017/06/05 16:22:32.299336, 10, pid=2877, effective(0, 0), real(0, 0), class=registry] ../source3/registry/reg_backend_db.c:902(regdb_close) regdb_close: decrementing refcount (3->2) [2017/06/05 16:22:32.299376, 7, pid=2877, effective(0, 0), real(0, 0)] ../source3/param/loadparm.c:4102(lp_servicenumber) lp_servicenumber: couldn't find printers [2017/06/05 16:22:32.299408, 5, pid=2877, effective(0, 0), real(0, 0)] ../source3/param/loadparm.c:2058(process_registry_service) process_registry_service: service name vol1 [2017/06/05 16:22:32.299438, 7, pid=2877, effective(0, 0), real(0, 0), class=registry] ../source3/registry/reg_api.c:143(regkey_open_onelevel) regkey_open_onelevel: name = [vol1] [2017/06/05 16:22:32.299630, 10, pid=2877, effective(0, 0), real(0, 0), class=registry] ../source3/registry/reg_backend_db.c:857(regdb_open) regdb_open: incrementing refcount (2->3) [2017/06/05 16:22:32.299676, 10, pid=2877, effective(0, 0), real(0, 0), class=registry] ../source3/registry/reg_cachehook.c:125(reghook_cache_find) reghook_cache_find: Searching for keyname [\HKLM\SOFTWARE\Samba\smbconf\vol1] [2017/06/05 16:22:32.299876, 10, pid=2877, effective(0, 0), real(0, 0)] ../source3/lib/adt_tree.c:367(pathtree_find) pathtree_find: Enter [\HKLM\SOFTWARE\Samba\smbconf\vol1] [2017/06/05 16:22:32.299933, 10, pid=2877, effective(0, 0), real(0, 0)] ../source3/lib/adt_tree.c:440(pathtree_find) pathtree_find: Exit [2017/06/05 16:22:32.299963, 10, pid=2877, effective(0, 0), real(0, 0), class=registry] ../source3/registry/reg_cachehook.c:130(reghook_cache_find) reghook_cache_find: found ops 0x7f38e87c4580 for key [\HKLM\SOFTWARE\Samba\smbconf\vol1] [2017/06/05 16:22:32.300236, 10, pid=2877, effective(0, 0), real(0, 0), class=registry] ../source3/registry/reg_backend_db.c:902(regdb_close) regdb_close: decrementing refcount (3->2) [2017/06/05 16:22:32.300410, 7, pid=2877, effective(0, 0), real(0, 0), class=registry] ../source3/registry/reg_api.c:143(regkey_open_onelevel) regkey_open_onelevel: name = [vol1] [2017/06/05 16:22:32.300443, 10, pid=2877, effective(0, 0), real(0, 0), class=registry] ../source3/registry/reg_backend_db.c:857(regdb_open) regdb_open: incrementing refcount (2->3) [2017/06/05 16:22:32.300501, 10, pid=2877, effective(0, 0), real(0, 0), class=registry] ../source3/registry/reg_cachehook.c:125(reghook_cache_find) reghook_cache_find: Searching for keyname [\HKLM\SOFTWARE\Samba\smbconf\vol1] [2017/06/05 16:22:32.300669, 10, pid=2877, effective(0, 0), real(0, 0)] ../source3/lib/adt_tree.c:367(pathtree_find) pathtree_find: Enter [\HKLM\SOFTWARE\Samba\smbconf\vol1] [2017/06/05 16:22:32.300711, 10, pid=2877, effective(0, 0), real(0, 0)] ../source3/lib/adt_tree.c:440(pathtree_find) pathtree_find: Exit [2017/06/05 16:22:32.300911, 10, pid=2877, effective(0, 0), real(0, 0), class=registry] ../source3/registry/reg_cachehook.c:130(reghook_cache_find) reghook_cache_find: found ops 0x7f38e87c4580 for key [\HKLM\SOFTWARE\Samba\smbconf\vol1] [2017/06/05 16:22:32.301008, 10, pid=2877, effective(0, 0), real(0, 0), class=registry] ../source3/registry/reg_dispatcher.c:151(fetch_reg_values) fetch_reg_values called for key 'HKLM\SOFTWARE\Samba\smbconf\vol1' (ops 0x7f38e87c4580) [2017/06/05 16:22:32.301176, 10, pid=2877, effective(0, 0), real(0, 0), class=registry] ../source3/registry/reg_backend_db.c:1905(regdb_fetch_values_internal) regdb_fetch_values: Looking for values of key [HKLM\SOFTWARE\Samba\smbconf\vol1] [2017/06/05 16:22:32.301370, 10, pid=2877, effective(0, 0), real(0, 0), class=registry] ../source3/registry/reg_backend_db.c:1850(regdb_unpack_values) regdb_unpack_values: value[0]: name[path] len[26] [2017/06/05 16:22:32.301416, 10, pid=2877, effective(0, 0), real(0, 0), class=registry] ../source3/registry/reg_backend_db.c:1850(regdb_unpack_values) regdb_unpack_values: value[1]: name[read only] len[6] [2017/06/05 16:22:32.301588, 10, pid=2877, effective(0, 0), real(0, 0), class=registry] ../source3/registry/reg_backend_db.c:1850(regdb_unpack_values) regdb_unpack_values: value[2]: name[hosts deny] len[8] [2017/06/05 16:22:32.301829, 10, pid=2877, effective(0, 0), real(0, 0), class=registry] ../source3/registry/reg_backend_db.c:1850(regdb_unpack_values) regdb_unpack_values: value[3]: name[kernel oplocks] len[8] [2017/06/05 16:22:32.302050, 10, pid=2877, effective(0, 0), real(0, 0), class=registry] ../source3/registry/reg_backend_db.c:1850(regdb_unpack_values) regdb_unpack_values: value[4]: name[level2 oplocks] len[6] [2017/06/05 16:22:32.302241, 10, pid=2877, effective(0, 0), real(0, 0), class=registry] ../source3/registry/reg_backend_db.c:1850(regdb_unpack_values) regdb_unpack_values: value[5]: name[map archive] len[8] [2017/06/05 16:22:32.302415, 10, pid=2877, effective(0, 0), real(0, 0), class=registry] ../source3/registry/reg_backend_db.c:1850(regdb_unpack_values) regdb_unpack_values: value[6]: name[create mask] len[10] [2017/06/05 16:22:32.302578, 10, pid=2877, effective(0, 0), real(0, 0), class=registry] ../source3/registry/reg_backend_db.c:1850(regdb_unpack_values) regdb_unpack_values: value[7]: name[force create mode] len[10] [2017/06/05 16:22:32.302786, 10, pid=2877, effective(0, 0), real(0, 0), class=registry] ../source3/registry/reg_backend_db.c:1850(regdb_unpack_values) regdb_unpack_values: value[8]: name[directory mask] len[10] [2017/06/05 16:22:32.302833, 10, pid=2877, effective(0, 0), real(0, 0), class=registry] ../source3/registry/reg_backend_db.c:1850(regdb_unpack_values) regdb_unpack_values: value[9]: name[force directory mode] len[10] [2017/06/05 16:22:32.302869, 10, pid=2877, effective(0, 0), real(0, 0), class=registry] ../source3/registry/reg_backend_db.c:1850(regdb_unpack_values) regdb_unpack_values: value[10]: name[aio read size] len[4] [2017/06/05 16:22:32.302907, 10, pid=2877, effective(0, 0), real(0, 0), class=registry] ../source3/registry/reg_backend_db.c:1850(regdb_unpack_values) regdb_unpack_values: value[11]: name[aio write size] len[4] [2017/06/05 16:22:32.302944, 10, pid=2877, effective(0, 0), real(0, 0), class=registry] ../source3/registry/reg_backend_db.c:1850(regdb_unpack_values) regdb_unpack_values: value[12]: name[browseable] len[8] [2017/06/05 16:22:32.303196, 10, pid=2877, effective(0, 0), real(0, 0), class=registry] ../source3/registry/reg_backend_db.c:1850(regdb_unpack_values) regdb_unpack_values: value[13]: name[hide unreadable] len[6] [2017/06/05 16:22:32.303523, 10, pid=2877, effective(0, 0), real(0, 0), class=registry] ../source3/registry/reg_backend_db.c:1850(regdb_unpack_values) regdb_unpack_values: value[14]: name[hide unwriteable files] len[6] [2017/06/05 16:22:32.303871, 10, pid=2877, effective(0, 0), real(0, 0), class=registry] ../source3/registry/reg_backend_db.c:1850(regdb_unpack_values) regdb_unpack_values: value[15]: name[hide dot files] len[6] [2017/06/05 16:22:32.304237, 10, pid=2877, effective(0, 0), real(0, 0), class=registry] ../source3/registry/reg_backend_db.c:1850(regdb_unpack_values) regdb_unpack_values: value[16]: name[hosts allow] len[24] [2017/06/05 16:22:32.304566, 10, pid=2877, effective(0, 0), real(0, 0), class=registry] ../source3/registry/reg_backend_db.c:1850(regdb_unpack_values) regdb_unpack_values: value[17]: name[guest ok] len[8] [2017/06/05 16:22:32.304925, 10, pid=2877, effective(0, 0), real(0, 0), class=registry] ../source3/registry/reg_backend_db.c:1850(regdb_unpack_values) regdb_unpack_values: value[18]: name[hide files] len[12] [2017/06/05 16:22:32.305750, 10, pid=2877, effective(0, 0), real(0, 0), class=registry] ../source3/registry/reg_backend_db.c:902(regdb_close) regdb_close: decrementing refcount (3->2) [2017/06/05 16:22:32.305930, 2, pid=2877, effective(0, 0), real(0, 0)] ../source3/param/loadparm.c:2691(lp_do_section) Processing section "[vol1]" [2017/06/05 16:22:32.306185, 8, pid=2877, effective(0, 0), real(0, 0)] ../source3/param/loadparm.c:1434(add_a_service) add_a_service: Creating snum = 1 for vol1 [2017/06/05 16:22:32.306402, 10, pid=2877, effective(0, 0), real(0, 0)] ../source3/param/loadparm.c:1484(hash_a_service) hash_a_service: hashing index 1 for service name vol1 doing parameter path = /export/vol1 doing parameter read only = no doing parameter hosts deny = ALL doing parameter kernel oplocks = Yes doing parameter level2 oplocks = No doing parameter map archive = Yes doing parameter create mask = 0744 doing parameter force create mode = 0744 doing parameter directory mask = 0755 doing parameter force directory mode = 0755 doing parameter aio read size = 1 doing parameter aio write size = 1 doing parameter browseable = Yes doing parameter hide unreadable = No doing parameter hide unwriteable files = No doing parameter hide dot files = No doing parameter hosts allow = 170.70.2.21 doing parameter guest ok = Yes doing parameter hide files = file2 [2017/06/05 16:22:32.309234, 5, pid=2877, effective(0, 0), real(0, 0)] ../lib/dbwrap/dbwrap.c:159(dbwrap_check_lock_order) check lock order 1 for /var/lock/samba/smbXsrv_tcon_global.tdb [2017/06/05 16:22:32.309434, 10, pid=2877, effective(0, 0), real(0, 0)] ../lib/dbwrap/dbwrap.c:114(debug_lock_order) lock order: 1:/var/lock/samba/smbXsrv_tcon_global.tdb 2: 3: [2017/06/05 16:22:32.309612, 10, pid=2877, effective(0, 0), real(0, 0)] ../lib/dbwrap/dbwrap_tdb.c:59(db_tdb_log_key) Locking key E394D695 [2017/06/05 16:22:32.309844, 10, pid=2877, effective(0, 0), real(0, 0)] ../lib/dbwrap/dbwrap_tdb.c:143(db_tdb_fetch_locked_internal) Allocated locked data 0x0x7f38ed3a4c00 [2017/06/05 16:22:32.310145, 10, pid=2877, effective(0, 0), real(0, 0)] ../source3/smbd/smbXsrv_tcon.c:709(smbXsrv_tcon_global_store) [2017/06/05 16:22:32.310265, 10, pid=2877, effective(0, 0), real(0, 0)] ../source3/smbd/smbXsrv_tcon.c:711(smbXsrv_tcon_global_store) smbXsrv_tcon_global_store: key 'E394D695' stored [2017/06/05 16:22:32.310479, 1, pid=2877, effective(0, 0), real(0, 0)] ../librpc/ndr/ndr.c:413(ndr_print_debug) &global_blob: struct smbXsrv_tcon_globalB version : SMBXSRV_VERSION_0 (0) seqnum : 0x00000001 (1) info : union smbXsrv_tcon_globalU(case 0) info0 : * info0: struct smbXsrv_tcon_global0 db_rec : * tcon_global_id : 0xe394d695 (3818182293) tcon_wire_id : 0xe394d695 (3818182293) server_id: struct server_id pid : 0x0000000000000b3d (2877) task_id : 0x00000000 (0) vnn : 0xffffffff (4294967295) unique_id : 0x27330f1f08b45cf6 (2824618017255873782) creation_time : Mon Jun 5 16:22:32 2017 IDT share_name : NULL encryption_flags : 0x00 (0) 0: SMBXSRV_ENCRYPTION_REQUIRED 0: SMBXSRV_ENCRYPTION_DESIRED 0: SMBXSRV_PROCESSED_ENCRYPTED_PACKET 0: SMBXSRV_PROCESSED_UNENCRYPTED_PACKET session_global_id : 0x00000000 (0) signing_flags : 0x00 (0) 0: SMBXSRV_SIGNING_REQUIRED 0: SMBXSRV_PROCESSED_SIGNED_PACKET 0: SMBXSRV_PROCESSED_UNSIGNED_PACKET [2017/06/05 16:22:32.313251, 10, pid=2877, effective(0, 0), real(0, 0)] ../lib/dbwrap/dbwrap_tdb.c:59(db_tdb_log_key) Unlocking key E394D695 [2017/06/05 16:22:32.313432, 5, pid=2877, effective(0, 0), real(0, 0)] ../lib/dbwrap/dbwrap.c:127(dbwrap_lock_order_state_destructor) release lock order 1 for /var/lock/samba/smbXsrv_tcon_global.tdb [2017/06/05 16:22:32.313636, 10, pid=2877, effective(0, 0), real(0, 0)] ../lib/dbwrap/dbwrap.c:114(debug_lock_order) lock order: 1: 2: 3: [2017/06/05 16:22:32.313862, 10, pid=2877, effective(0, 0), real(0, 0)] ../source3/smbd/smbXsrv_tcon.c:831(smbXsrv_tcon_create) [2017/06/05 16:22:32.313998, 10, pid=2877, effective(0, 0), real(0, 0)] ../source3/smbd/smbXsrv_tcon.c:839(smbXsrv_tcon_create) smbXsrv_tcon_create: global_id (0xe394d695) stored [2017/06/05 16:22:32.314045, 1, pid=2877, effective(0, 0), real(0, 0)] ../librpc/ndr/ndr.c:413(ndr_print_debug) &tcon_blob: struct smbXsrv_tconB version : SMBXSRV_VERSION_0 (0) reserved : 0x00000000 (0) info : union smbXsrv_tconU(case 0) info0 : * info0: struct smbXsrv_tcon table : * db_rec : NULL local_id : 0xe394d695 (3818182293) global : * global: struct smbXsrv_tcon_global0 db_rec : NULL tcon_global_id : 0xe394d695 (3818182293) tcon_wire_id : 0xe394d695 (3818182293) server_id: struct server_id pid : 0x0000000000000b3d (2877) task_id : 0x00000000 (0) vnn : 0xffffffff (4294967295) unique_id : 0x27330f1f08b45cf6 (2824618017255873782) creation_time : Mon Jun 5 16:22:32 2017 IDT share_name : NULL encryption_flags : 0x00 (0) 0: SMBXSRV_ENCRYPTION_REQUIRED 0: SMBXSRV_ENCRYPTION_DESIRED 0: SMBXSRV_PROCESSED_ENCRYPTED_PACKET 0: SMBXSRV_PROCESSED_UNENCRYPTED_PACKET session_global_id : 0x00000000 (0) signing_flags : 0x00 (0) 0: SMBXSRV_SIGNING_REQUIRED 0: SMBXSRV_PROCESSED_SIGNED_PACKET 0: SMBXSRV_PROCESSED_UNSIGNED_PACKET status : NT_STATUS_INTERNAL_ERROR idle_time : Mon Jun 5 16:22:32 2017 IDT compat : NULL [2017/06/05 16:22:32.314464, 3, pid=2877, effective(0, 0), real(0, 0)] ../source3/lib/access.c:338(allow_access) Allowed connection from 170.70.2.21 (170.70.2.21) [2017/06/05 16:22:32.314563, 10, pid=2877, effective(0, 0), real(0, 0)] ../source3/smbd/service.c:72(set_conn_connectpath) set_conn_connectpath: service vol1, connectpath = /export/vol1 [2017/06/05 16:22:32.314590, 3, pid=2877, effective(0, 0), real(0, 0)] ../source3/smbd/service.c:581(make_connection_snum) Connect path is '/export/vol1' for service [vol1] [2017/06/05 16:22:32.314612, 10, pid=2877, effective(0, 0), real(0, 0)] ../source3/smbd/share_access.c:221(user_ok_token) user_ok_token: share vol1 is ok for unix user nobody [2017/06/05 16:22:32.314632, 10, pid=2877, effective(0, 0), real(0, 0)] ../source3/smbd/share_access.c:268(is_share_read_only_for_token) is_share_read_only_for_user: share vol1 is read-write for unix user nobody [2017/06/05 16:22:32.314682, 10, pid=2877, effective(0, 0), real(0, 0)] ../libcli/security/access_check.c:337(se_file_access_check) se_file_access_check: MAX desired = 0x2000000 mapped to 0x1f01ff [2017/06/05 16:22:32.314706, 3, pid=2877, effective(0, 0), real(0, 0), class=vfs] ../source3/smbd/vfs.c:113(vfs_init_default) Initialising default vfs hooks [2017/06/05 16:22:32.314756, 10, pid=2877, effective(0, 0), real(0, 0), class=vfs] ../source3/smbd/vfs.c:64(vfs_find_backend_entry) vfs_find_backend_entry called for /[Default VFS]/ [2017/06/05 16:22:32.314777, 5, pid=2877, effective(0, 0), real(0, 0), class=vfs] ../source3/smbd/vfs.c:103(smb_register_vfs) Successfully added vfs backend '/[Default VFS]/' [2017/06/05 16:22:32.314805, 10, pid=2877, effective(0, 0), real(0, 0), class=vfs] ../source3/smbd/vfs.c:64(vfs_find_backend_entry) vfs_find_backend_entry called for posixacl [2017/06/05 16:22:32.314822, 5, pid=2877, effective(0, 0), real(0, 0), class=vfs] ../source3/smbd/vfs.c:103(smb_register_vfs) Successfully added vfs backend 'posixacl' [2017/06/05 16:22:32.314838, 3, pid=2877, effective(0, 0), real(0, 0), class=vfs] ../source3/smbd/vfs.c:139(vfs_init_custom) Initialising custom vfs hooks from [/[Default VFS]/] [2017/06/05 16:22:32.314854, 10, pid=2877, effective(0, 0), real(0, 0), class=vfs] ../source3/smbd/vfs.c:64(vfs_find_backend_entry) vfs_find_backend_entry called for /[Default VFS]/ Successfully loaded vfs module [/[Default VFS]/] with the new modules system [2017/06/05 16:22:32.314919, 10, pid=2877, effective(0, 0), real(0, 0)] ../source3/smbd/notify_msg.c:80(notify_init) notify_init: notifyd=2602 [2017/06/05 16:22:32.314942, 5, pid=2877, effective(0, 0), real(0, 0)] ../source3/lib/messages.c:356(messaging_register) Registering messaging pointer for type 784 - private_data=0x7f38ed3b0ed0 [2017/06/05 16:22:32.314962, 5, pid=2877, effective(0, 0), real(0, 0)] ../source3/lib/messages.c:356(messaging_register) Registering messaging pointer for type 793 - private_data=0x7f38ed39da20 [2017/06/05 16:22:32.315025, 5, pid=2877, effective(0, 0), real(0, 0)] ../source3/lib/messages.c:356(messaging_register) Registering messaging pointer for type 799 - private_data=0x7f38ed39da20 [2017/06/05 16:22:32.315141, 3, pid=2877, effective(0, 0), real(0, 0), class=locking] ../source3/smbd/oplock_linux.c:260(linux_init_kernel_oplocks) Linux kernel oplocks enabled [2017/06/05 16:22:32.315203, 10, pid=2877, effective(0, 0), real(0, 0)] ../source3/smbd/service.c:72(set_conn_connectpath) set_conn_connectpath: service vol1, connectpath = /export/vol1 [2017/06/05 16:22:32.315290, 5, pid=2877, effective(0, 0), real(0, 0)] ../source3/smbd/service.c:686(make_connection_snum) cmd=/var/lib/zadara/scripts/vc/samba/zadara_smb_preexec.sh "nobody" "vol1" "vm21-win2012se" "170.70.2.21" [2017/06/05 16:22:32.321536, 10, pid=2877, effective(0, 0), real(0, 0)] ../source3/smbd/share_access.c:221(user_ok_token) user_ok_token: share vol1 is ok for unix user nobody [2017/06/05 16:22:32.321621, 10, pid=2877, effective(0, 0), real(0, 0)] ../source3/smbd/share_access.c:268(is_share_read_only_for_token) is_share_read_only_for_user: share vol1 is read-write for unix user nobody [2017/06/05 16:22:32.321706, 10, pid=2877, effective(0, 0), real(0, 0)] ../libcli/security/access_check.c:337(se_file_access_check) se_file_access_check: MAX desired = 0x2000000 mapped to 0x1f01ff [2017/06/05 16:22:32.321874, 4, pid=2877, effective(0, 0), real(0, 0)] ../source3/smbd/sec_ctx.c:320(set_sec_ctx_internal) setting sec ctx (65534, 65534) - sec_ctx_stack_ndx = 0 [2017/06/05 16:22:32.321928, 5, pid=2877, effective(0, 0), real(0, 0)] ../libcli/security/security_token.c:63(security_token_debug) Security token SIDs (9): SID[ 0]: S-1-5-21-1893543895-1847372660-4172524467-501 SID[ 1]: S-1-5-21-1893543895-1847372660-4172524467-514 SID[ 2]: S-1-22-2-65534 SID[ 3]: S-1-1-0 SID[ 4]: S-1-5-2 SID[ 5]: S-1-5-32-546 SID[ 6]: S-1-22-1-65534 SID[ 7]: S-1-22-2-1000003 SID[ 8]: S-1-22-2-1000004 Privileges (0x 0): Rights (0x 0): [2017/06/05 16:22:32.322147, 5, pid=2877, effective(0, 0), real(0, 0)] ../source3/auth/token_util.c:639(debug_unix_user_token) UNIX token of user 65534 Primary group is 65534 and contains 3 supplementary groups Group[ 0]: 65534 Group[ 1]: 1000003 Group[ 2]: 1000004 [2017/06/05 16:22:32.322248, 5, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/uid.c:363(change_to_user_internal) Impersonated user: uid=(65534,65534), gid=(0,65534) [2017/06/05 16:22:32.322299, 4, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/sec_ctx.c:320(set_sec_ctx_internal) setting sec ctx (0, 0) - sec_ctx_stack_ndx = 0 [2017/06/05 16:22:32.322338, 5, pid=2877, effective(65534, 65534), real(65534, 0)] ../libcli/security/security_token.c:53(security_token_debug) Security token: (NULL) [2017/06/05 16:22:32.322373, 5, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/auth/token_util.c:639(debug_unix_user_token) UNIX token of user 0 Primary group is 0 and contains 0 supplementary groups [2017/06/05 16:22:32.322432, 5, pid=2877, effective(0, 0), real(0, 0)] ../source3/smbd/uid.c:425(smbd_change_to_root_user) change_to_root_user: now uid=(0,0) gid=(0,0) [2017/06/05 16:22:32.322493, 10, pid=2877, effective(0, 0), real(0, 0)] ../source3/smbd/service.c:72(set_conn_connectpath) set_conn_connectpath: service vol1, connectpath = /export/vol1 [2017/06/05 16:22:32.322661, 1, pid=2877, effective(0, 0), real(0, 0)] ../source3/smbd/service.c:842(make_connection_snum) zsamba_stats_open(/export/vol1, 170.70.2.21), remote_hostname=170.70.2.21 [2017/06/05 16:22:32.322888, 10, pid=2877, effective(0, 0), real(0, 0), class=vfs] ../source3/modules/vfs_default.c:170(vfswrap_fs_capabilities) vfswrap_fs_capabilities: timestamp resolution of sec available on share vol1, directory /export/vol1 [2017/06/05 16:22:32.322947, 2, pid=2877, effective(0, 0), real(0, 0)] ../source3/smbd/service.c:868(make_connection_snum) vm21-win2012se (ipv4:170.70.2.21:54923) connect to service vol1 initially as user nobody (uid=65534, gid=65534) (pid 2877) [2017/06/05 16:22:32.323082, 5, pid=2877, effective(0, 0), real(0, 0)] ../lib/dbwrap/dbwrap.c:159(dbwrap_check_lock_order) check lock order 1 for /var/lock/samba/smbXsrv_tcon_global.tdb [2017/06/05 16:22:32.323131, 10, pid=2877, effective(0, 0), real(0, 0)] ../lib/dbwrap/dbwrap.c:114(debug_lock_order) lock order: 1:/var/lock/samba/smbXsrv_tcon_global.tdb 2: 3: [2017/06/05 16:22:32.323179, 10, pid=2877, effective(0, 0), real(0, 0)] ../lib/dbwrap/dbwrap_tdb.c:59(db_tdb_log_key) Locking key E394D695 [2017/06/05 16:22:32.323232, 10, pid=2877, effective(0, 0), real(0, 0)] ../lib/dbwrap/dbwrap_tdb.c:143(db_tdb_fetch_locked_internal) Allocated locked data 0x0x7f38ed3828d0 [2017/06/05 16:22:32.323297, 10, pid=2877, effective(0, 0), real(0, 0)] ../source3/smbd/smbXsrv_tcon.c:709(smbXsrv_tcon_global_store) [2017/06/05 16:22:32.323346, 10, pid=2877, effective(0, 0), real(0, 0)] ../source3/smbd/smbXsrv_tcon.c:711(smbXsrv_tcon_global_store) smbXsrv_tcon_global_store: key 'E394D695' stored [2017/06/05 16:22:32.323391, 1, pid=2877, effective(0, 0), real(0, 0)] ../librpc/ndr/ndr.c:413(ndr_print_debug) &global_blob: struct smbXsrv_tcon_globalB version : SMBXSRV_VERSION_0 (0) seqnum : 0x00000002 (2) info : union smbXsrv_tcon_globalU(case 0) info0 : * info0: struct smbXsrv_tcon_global0 db_rec : * tcon_global_id : 0xe394d695 (3818182293) tcon_wire_id : 0xe394d695 (3818182293) server_id: struct server_id pid : 0x0000000000000b3d (2877) task_id : 0x00000000 (0) vnn : 0xffffffff (4294967295) unique_id : 0x27330f1f08b45cf6 (2824618017255873782) creation_time : Mon Jun 5 16:22:32 2017 IDT share_name : 'vol1' encryption_flags : 0x00 (0) 0: SMBXSRV_ENCRYPTION_REQUIRED 0: SMBXSRV_ENCRYPTION_DESIRED 0: SMBXSRV_PROCESSED_ENCRYPTED_PACKET 0: SMBXSRV_PROCESSED_UNENCRYPTED_PACKET session_global_id : 0x5a21384a (1512126538) signing_flags : 0x00 (0) 0: SMBXSRV_SIGNING_REQUIRED 0: SMBXSRV_PROCESSED_SIGNED_PACKET 0: SMBXSRV_PROCESSED_UNSIGNED_PACKET [2017/06/05 16:22:32.323916, 10, pid=2877, effective(0, 0), real(0, 0)] ../lib/dbwrap/dbwrap_tdb.c:59(db_tdb_log_key) Unlocking key E394D695 [2017/06/05 16:22:32.323964, 5, pid=2877, effective(0, 0), real(0, 0)] ../lib/dbwrap/dbwrap.c:127(dbwrap_lock_order_state_destructor) release lock order 1 for /var/lock/samba/smbXsrv_tcon_global.tdb [2017/06/05 16:22:32.324052, 10, pid=2877, effective(0, 0), real(0, 0)] ../lib/dbwrap/dbwrap.c:114(debug_lock_order) lock order: 1: 2: 3: [2017/06/05 16:22:32.324094, 10, pid=2877, effective(0, 0), real(0, 0)] ../source3/smbd/smbXsrv_tcon.c:876(smbXsrv_tcon_update) [2017/06/05 16:22:32.324115, 10, pid=2877, effective(0, 0), real(0, 0)] ../source3/smbd/smbXsrv_tcon.c:884(smbXsrv_tcon_update) smbXsrv_tcon_update: global_id (0xe394d695) stored [2017/06/05 16:22:32.324152, 1, pid=2877, effective(0, 0), real(0, 0)] ../librpc/ndr/ndr.c:413(ndr_print_debug) &tcon_blob: struct smbXsrv_tconB version : SMBXSRV_VERSION_0 (0) reserved : 0x00000000 (0) info : union smbXsrv_tconU(case 0) info0 : * info0: struct smbXsrv_tcon table : * db_rec : NULL local_id : 0xe394d695 (3818182293) global : * global: struct smbXsrv_tcon_global0 db_rec : NULL tcon_global_id : 0xe394d695 (3818182293) tcon_wire_id : 0xe394d695 (3818182293) server_id: struct server_id pid : 0x0000000000000b3d (2877) task_id : 0x00000000 (0) vnn : 0xffffffff (4294967295) unique_id : 0x27330f1f08b45cf6 (2824618017255873782) creation_time : Mon Jun 5 16:22:32 2017 IDT share_name : 'vol1' encryption_flags : 0x00 (0) 0: SMBXSRV_ENCRYPTION_REQUIRED 0: SMBXSRV_ENCRYPTION_DESIRED 0: SMBXSRV_PROCESSED_ENCRYPTED_PACKET 0: SMBXSRV_PROCESSED_UNENCRYPTED_PACKET session_global_id : 0x5a21384a (1512126538) signing_flags : 0x00 (0) 0: SMBXSRV_SIGNING_REQUIRED 0: SMBXSRV_PROCESSED_SIGNED_PACKET 0: SMBXSRV_PROCESSED_UNSIGNED_PACKET status : NT_STATUS_OK idle_time : Mon Jun 5 16:22:32 2017 IDT compat : * [2017/06/05 16:22:32.324845, 10, pid=2877, effective(0, 0), real(0, 0)] ../source3/smbd/smb2_server.c:3014(smbd_smb2_request_done_ex) smbd_smb2_request_done_ex: idx[1] status[NT_STATUS_OK] body[16] dyn[no:0] at ../source3/smbd/smb2_tcon.c:170 [2017/06/05 16:22:32.324896, 10, pid=2877, effective(0, 0), real(0, 0)] ../source3/smbd/smb2_server.c:925(smb2_set_operation_credit) smb2_set_operation_credit: requested 1, charge 1, granted 1, current possible/max 482/512, total granted/max/low/range 31/8192/5/31 [2017/06/05 16:22:32.325632, 10, pid=2877, effective(0, 0), real(0, 0)] ../source3/smbd/smb2_server.c:3912(smbd_smb2_io_handler) smbd_smb2_request idx[1] of 5 vectors [2017/06/05 16:22:32.325688, 10, pid=2877, effective(0, 0), real(0, 0)] ../source3/smbd/smb2_server.c:673(smb2_validate_sequence_number) smb2_validate_sequence_number: clearing id 5 (position 5) from bitmap [2017/06/05 16:22:32.325765, 10, pid=2877, effective(0, 0), real(0, 0)] ../source3/smbd/smb2_server.c:2272(smbd_smb2_request_dispatch) smbd_smb2_request_dispatch: opcode[SMB2_OP_CREATE] mid = 5 [2017/06/05 16:22:32.325822, 4, pid=2877, effective(0, 0), real(0, 0)] ../source3/smbd/sec_ctx.c:320(set_sec_ctx_internal) setting sec ctx (65534, 65534) - sec_ctx_stack_ndx = 0 [2017/06/05 16:22:32.325869, 5, pid=2877, effective(0, 0), real(0, 0)] ../libcli/security/security_token.c:63(security_token_debug) Security token SIDs (9): SID[ 0]: S-1-5-21-1893543895-1847372660-4172524467-501 SID[ 1]: S-1-5-21-1893543895-1847372660-4172524467-514 SID[ 2]: S-1-22-2-65534 SID[ 3]: S-1-1-0 SID[ 4]: S-1-5-2 SID[ 5]: S-1-5-32-546 SID[ 6]: S-1-22-1-65534 SID[ 7]: S-1-22-2-1000003 SID[ 8]: S-1-22-2-1000004 Privileges (0x 0): Rights (0x 0): [2017/06/05 16:22:32.326109, 5, pid=2877, effective(0, 0), real(0, 0)] ../source3/auth/token_util.c:639(debug_unix_user_token) UNIX token of user 65534 Primary group is 65534 and contains 3 supplementary groups Group[ 0]: 65534 Group[ 1]: 1000003 Group[ 2]: 1000004 [2017/06/05 16:22:32.326197, 5, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/uid.c:363(change_to_user_internal) Impersonated user: uid=(65534,65534), gid=(0,65534) [2017/06/05 16:22:32.326242, 4, pid=2877, effective(65534, 65534), real(65534, 0), class=vfs] ../source3/smbd/vfs.c:874(vfs_ChDir) vfs_ChDir to /export/vol1 [2017/06/05 16:22:32.326313, 4, pid=2877, effective(65534, 65534), real(65534, 0), class=vfs] ../source3/smbd/vfs.c:885(vfs_ChDir) vfs_ChDir got /export/vol1 [2017/06/05 16:22:32.326360, 5, pid=2877, effective(65534, 65534), real(65534, 0)] ../lib/dbwrap/dbwrap.c:159(dbwrap_check_lock_order) check lock order 1 for /var/lock/samba/smbXsrv_tcon_global.tdb [2017/06/05 16:22:32.326402, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../lib/dbwrap/dbwrap.c:114(debug_lock_order) lock order: 1:/var/lock/samba/smbXsrv_tcon_global.tdb 2: 3: [2017/06/05 16:22:32.326447, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../lib/dbwrap/dbwrap_tdb.c:59(db_tdb_log_key) Locking key E394D695 [2017/06/05 16:22:32.326496, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../lib/dbwrap/dbwrap_tdb.c:143(db_tdb_fetch_locked_internal) Allocated locked data 0x0x7f38ed3828d0 [2017/06/05 16:22:32.326580, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/smbXsrv_tcon.c:709(smbXsrv_tcon_global_store) [2017/06/05 16:22:32.326613, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/smbXsrv_tcon.c:711(smbXsrv_tcon_global_store) smbXsrv_tcon_global_store: key 'E394D695' stored [2017/06/05 16:22:32.326658, 1, pid=2877, effective(65534, 65534), real(65534, 0)] ../librpc/ndr/ndr.c:413(ndr_print_debug) &global_blob: struct smbXsrv_tcon_globalB version : SMBXSRV_VERSION_0 (0) seqnum : 0x00000003 (3) info : union smbXsrv_tcon_globalU(case 0) info0 : * info0: struct smbXsrv_tcon_global0 db_rec : * tcon_global_id : 0xe394d695 (3818182293) tcon_wire_id : 0xe394d695 (3818182293) server_id: struct server_id pid : 0x0000000000000b3d (2877) task_id : 0x00000000 (0) vnn : 0xffffffff (4294967295) unique_id : 0x27330f1f08b45cf6 (2824618017255873782) creation_time : Mon Jun 5 16:22:32 2017 IDT share_name : 'vol1' encryption_flags : 0x08 (8) 0: SMBXSRV_ENCRYPTION_REQUIRED 0: SMBXSRV_ENCRYPTION_DESIRED 0: SMBXSRV_PROCESSED_ENCRYPTED_PACKET 1: SMBXSRV_PROCESSED_UNENCRYPTED_PACKET session_global_id : 0x5a21384a (1512126538) signing_flags : 0x04 (4) 0: SMBXSRV_SIGNING_REQUIRED 0: SMBXSRV_PROCESSED_SIGNED_PACKET 1: SMBXSRV_PROCESSED_UNSIGNED_PACKET [2017/06/05 16:22:32.327225, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../lib/dbwrap/dbwrap_tdb.c:59(db_tdb_log_key) Unlocking key E394D695 [2017/06/05 16:22:32.327274, 5, pid=2877, effective(65534, 65534), real(65534, 0)] ../lib/dbwrap/dbwrap.c:127(dbwrap_lock_order_state_destructor) release lock order 1 for /var/lock/samba/smbXsrv_tcon_global.tdb [2017/06/05 16:22:32.327314, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../lib/dbwrap/dbwrap.c:114(debug_lock_order) lock order: 1: 2: 3: [2017/06/05 16:22:32.327355, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/smbXsrv_tcon.c:876(smbXsrv_tcon_update) [2017/06/05 16:22:32.327383, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/smbXsrv_tcon.c:884(smbXsrv_tcon_update) smbXsrv_tcon_update: global_id (0xe394d695) stored [2017/06/05 16:22:32.327421, 1, pid=2877, effective(65534, 65534), real(65534, 0)] ../librpc/ndr/ndr.c:413(ndr_print_debug) &tcon_blob: struct smbXsrv_tconB version : SMBXSRV_VERSION_0 (0) reserved : 0x00000000 (0) info : union smbXsrv_tconU(case 0) info0 : * info0: struct smbXsrv_tcon table : * db_rec : NULL local_id : 0xe394d695 (3818182293) global : * global: struct smbXsrv_tcon_global0 db_rec : NULL tcon_global_id : 0xe394d695 (3818182293) tcon_wire_id : 0xe394d695 (3818182293) server_id: struct server_id pid : 0x0000000000000b3d (2877) task_id : 0x00000000 (0) vnn : 0xffffffff (4294967295) unique_id : 0x27330f1f08b45cf6 (2824618017255873782) creation_time : Mon Jun 5 16:22:32 2017 IDT share_name : 'vol1' encryption_flags : 0x08 (8) 0: SMBXSRV_ENCRYPTION_REQUIRED 0: SMBXSRV_ENCRYPTION_DESIRED 0: SMBXSRV_PROCESSED_ENCRYPTED_PACKET 1: SMBXSRV_PROCESSED_UNENCRYPTED_PACKET session_global_id : 0x5a21384a (1512126538) signing_flags : 0x04 (4) 0: SMBXSRV_SIGNING_REQUIRED 0: SMBXSRV_PROCESSED_SIGNED_PACKET 1: SMBXSRV_PROCESSED_UNSIGNED_PACKET status : NT_STATUS_OK idle_time : Mon Jun 5 16:22:32 2017 IDT compat : * [2017/06/05 16:22:32.328135, 0, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/smb2_server.c:2145(smbd_smb2_request_dispatch_update_counts) smbd_smb2_request_dispatch_update_counts: compat_chain_fsp=(nil) [2017/06/05 16:22:32.328339, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/smb2_create.c:503(smbd_smb2_create_send) smbd_smb2_create: name[] [2017/06/05 16:22:32.328393, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/smb2_create.c:997(smbd_smb2_create_send) smbd_smb2_create_send: open execution phase [2017/06/05 16:22:32.328458, 5, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/filename.c:443(unix_convert) unix_convert called on file "" [2017/06/05 16:22:32.328496, 5, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/filename.c:477(unix_convert) conversion finished "" -> . [2017/06/05 16:22:32.328527, 10, pid=2877, effective(65534, 65534), real(65534, 0), class=vfs] ../source3/smbd/vfs.c:1199(check_reduced_name) check_reduced_name: check_reduced_name [.] [/export/vol1] [2017/06/05 16:22:32.328564, 10, pid=2877, effective(65534, 65534), real(65534, 0), class=vfs] ../source3/smbd/vfs.c:1259(check_reduced_name) check_reduced_name realpath [.] -> [/export/vol1] [2017/06/05 16:22:32.328597, 5, pid=2877, effective(65534, 65534), real(65534, 0), class=vfs] ../source3/smbd/vfs.c:1370(check_reduced_name) check_reduced_name: . reduced to /export/vol1 [2017/06/05 16:22:32.328641, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/open.c:5515(create_file_default) create_file: access_mask = 0x100081 file_attributes = 0x0, share_access = 0x7, create_disposition = 0x1 create_options = 0x0 oplock_request = 0x2 private_flags = 0x0 root_dir_fid = 0x0, ea_list = 0x(nil), sd = 0x(nil), fname = . [2017/06/05 16:22:32.328777, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/open.c:4988(create_file_unixpath) create_file_unixpath: access_mask = 0x100081 file_attributes = 0x0, share_access = 0x7, create_disposition = 0x1 create_options = 0x0 oplock_request = 0x2 private_flags = 0x0 ea_list = 0x(nil), sd = 0x(nil), fname = . [2017/06/05 16:22:32.328829, 0, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/files.c:65(fsp_new) fsp_new: fsp=0x7f38ed3b32c0 [2017/06/05 16:22:32.329035, 5, pid=2877, effective(65534, 65534), real(65534, 0)] ../lib/dbwrap/dbwrap.c:159(dbwrap_check_lock_order) check lock order 1 for /var/lock/samba/smbXsrv_open_global.tdb [2017/06/05 16:22:32.329077, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../lib/dbwrap/dbwrap.c:114(debug_lock_order) lock order: 1:/var/lock/samba/smbXsrv_open_global.tdb 2: 3: [2017/06/05 16:22:32.329117, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../lib/dbwrap/dbwrap_tdb.c:59(db_tdb_log_key) Locking key 381F9B1E [2017/06/05 16:22:32.329171, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../lib/dbwrap/dbwrap_tdb.c:143(db_tdb_fetch_locked_internal) Allocated locked data 0x0x7f38ed39c3c0 [2017/06/05 16:22:32.329208, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/smbXsrv_open.c:624(smbXsrv_open_global_verify_record) smbXsrv_open_global_verify_record: empty value [2017/06/05 16:22:32.329312, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/smbXsrv_open.c:743(smbXsrv_open_global_store) smbXsrv_open_global_store: key '381F9B1E' stored [2017/06/05 16:22:32.329396, 1, pid=2877, effective(65534, 65534), real(65534, 0)] ../librpc/ndr/ndr.c:413(ndr_print_debug) &global_blob: struct smbXsrv_open_globalB version : SMBXSRV_VERSION_0 (0) seqnum : 0x00000001 (1) info : union smbXsrv_open_globalU(case 0) info0 : * info0: struct smbXsrv_open_global0 db_rec : * server_id: struct server_id pid : 0x0000000000000b3d (2877) task_id : 0x00000000 (0) vnn : 0xffffffff (4294967295) unique_id : 0x27330f1f08b45cf6 (2824618017255873782) open_global_id : 0x381f9b1e (941595422) open_persistent_id : 0x00000000381f9b1e (941595422) open_volatile_id : 0x00000000a53bedbd (2772168125) open_owner : S-1-5-21-1893543895-1847372660-4172524467-501 open_time : Mon Jun 5 16:22:32 2017 IDT create_guid : 00000000-0000-0000-0000-000000000000 client_guid : eb460979-4694-11e7-9429-005056ae0ecf app_instance_id : 00000000-0000-0000-0000-000000000000 disconnect_time : NTTIME(0) durable_timeout_msec : 0x00000000 (0) durable : 0x00 (0) backend_cookie : DATA_BLOB length=0 channel_sequence : 0x0000000000000000 (0) [2017/06/05 16:22:32.330015, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../lib/dbwrap/dbwrap_tdb.c:59(db_tdb_log_key) Unlocking key 381F9B1E [2017/06/05 16:22:32.330072, 5, pid=2877, effective(65534, 65534), real(65534, 0)] ../lib/dbwrap/dbwrap.c:127(dbwrap_lock_order_state_destructor) release lock order 1 for /var/lock/samba/smbXsrv_open_global.tdb [2017/06/05 16:22:32.330113, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../lib/dbwrap/dbwrap.c:114(debug_lock_order) lock order: 1: 2: 3: [2017/06/05 16:22:32.330155, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/smbXsrv_open.c:910(smbXsrv_open_create) smbXsrv_open_create: global_id (0x381f9b1e) stored [2017/06/05 16:22:32.330193, 1, pid=2877, effective(65534, 65534), real(65534, 0)] ../librpc/ndr/ndr.c:413(ndr_print_debug) &open_blob: struct smbXsrv_openB version : SMBXSRV_VERSION_0 (0) reserved : 0x00000000 (0) info : union smbXsrv_openU(case 0) info0 : * info0: struct smbXsrv_open table : * db_rec : NULL local_id : 0xa53bedbd (2772168125) global : * global: struct smbXsrv_open_global0 db_rec : NULL server_id: struct server_id pid : 0x0000000000000b3d (2877) task_id : 0x00000000 (0) vnn : 0xffffffff (4294967295) unique_id : 0x27330f1f08b45cf6 (2824618017255873782) open_global_id : 0x381f9b1e (941595422) open_persistent_id : 0x00000000381f9b1e (941595422) open_volatile_id : 0x00000000a53bedbd (2772168125) open_owner : S-1-5-21-1893543895-1847372660-4172524467-501 open_time : Mon Jun 5 16:22:32 2017 IDT create_guid : 00000000-0000-0000-0000-000000000000 client_guid : eb460979-4694-11e7-9429-005056ae0ecf app_instance_id : 00000000-0000-0000-0000-000000000000 disconnect_time : NTTIME(0) durable_timeout_msec : 0x00000000 (0) durable : 0x00 (0) backend_cookie : DATA_BLOB length=0 channel_sequence : 0x0000000000000000 (0) status : NT_STATUS_OK idle_time : Mon Jun 5 16:22:32 2017 IDT compat : NULL flags : 0x00 (0) 0: SMBXSRV_OPEN_NEED_REPLAY_CACHE 0: SMBXSRV_OPEN_HAVE_REPLAY_CACHE create_action : 0x00000000 (0) request_count : 0x0000000000000000 (0) pre_request_count : 0x0000000000000000 (0) [2017/06/05 16:22:32.330925, 5, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/files.c:130(file_new) allocated file structure fnum 2772168125 (1 used) [2017/06/05 16:22:32.330999, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/files.c:763(file_name_hash) file_name_hash: /export/vol1/. hash 0xd7088907 [2017/06/05 16:22:32.331058, 5, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/dosmode.c:206(unix_mode) unix_mode: unix_mode(.) returning 0744 [2017/06/05 16:22:32.331100, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/open.c:2972(open_file_ntcreate) open_file_ntcreate: fname=., dos_attrs=0x0 access_mask=0x100081 share_access=0x7 create_disposition = 0x1 create_options=0x0 unix mode=0744 oplock_request=2 private_flags = 0x0 [2017/06/05 16:22:32.331150, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/open.c:3142(open_file_ntcreate) open_file_ntcreate: fname=., after mapping access_mask=0x100081 [2017/06/05 16:22:32.331192, 4, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/open.c:3233(open_file_ntcreate) calling open_file with flags=0x0 flags2=0x800 mode=0744, access_mask = 0x100081, open_access_mask = 0x100081 [2017/06/05 16:22:32.331237, 10, pid=2877, effective(65534, 65534), real(65534, 0), class=acls] ../source3/smbd/posix_acls.c:3560(posix_get_nt_acl) posix_get_nt_acl: called for file . [2017/06/05 16:22:32.331402, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/passdb/lookup_sid.c:1251(uid_to_sid) uid 0 -> sid S-1-22-1-0 [2017/06/05 16:22:32.331486, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/passdb/lookup_sid.c:1300(gid_to_sid) gid 0 -> sid S-1-22-2-0 [2017/06/05 16:22:32.331541, 10, pid=2877, effective(65534, 65534), real(65534, 0), class=acls] ../source3/smbd/posix_acls.c:2724(canonicalise_acl) canonicalise_acl: Access ace entries before arrange : [2017/06/05 16:22:32.331583, 10, pid=2877, effective(65534, 65534), real(65534, 0), class=acls] ../source3/smbd/posix_acls.c:2737(canonicalise_acl) canon_ace index 0. Type = allow SID = S-1-1-0 other SMB_ACL_OTHER ace_flags = 0x0 perms rwx [2017/06/05 16:22:32.331632, 10, pid=2877, effective(65534, 65534), real(65534, 0), class=acls] ../source3/smbd/posix_acls.c:2737(canonicalise_acl) canon_ace index 1. Type = allow SID = S-1-22-2-0 gid 0 (root) SMB_ACL_GROUP_OBJ ace_flags = 0x0 perms rwx [2017/06/05 16:22:32.331828, 10, pid=2877, effective(65534, 65534), real(65534, 0), class=acls] ../source3/smbd/posix_acls.c:2737(canonicalise_acl) canon_ace index 2. Type = allow SID = S-1-22-1-0 uid 0 (root) SMB_ACL_USER_OBJ ace_flags = 0x0 perms rwx [2017/06/05 16:22:32.331935, 10, pid=2877, effective(65534, 65534), real(65534, 0), class=acls] ../source3/smbd/posix_acls.c:848(print_canon_ace_list) print_canon_ace_list: canonicalise_acl: ace entries after arrange canon_ace index 0. Type = allow SID = S-1-22-1-0 uid 0 (root) SMB_ACL_USER_OBJ ace_flags = 0x0 perms rwx canon_ace index 1. Type = allow SID = S-1-22-2-0 gid 0 (root) SMB_ACL_GROUP_OBJ ace_flags = 0x0 perms rwx canon_ace index 2. Type = allow SID = S-1-1-0 other SMB_ACL_OTHER ace_flags = 0x0 perms rwx [2017/06/05 16:22:32.332208, 10, pid=2877, effective(65534, 65534), real(65534, 0), class=acls] ../source3/smbd/posix_acls.c:1110(map_canon_ace_perms) map_canon_ace_perms: Mapped (UNIX) 1c0 to (NT) 1f01ff [2017/06/05 16:22:32.332253, 10, pid=2877, effective(65534, 65534), real(65534, 0), class=acls] ../source3/smbd/posix_acls.c:1110(map_canon_ace_perms) map_canon_ace_perms: Mapped (UNIX) 1c0 to (NT) 1f01ff [2017/06/05 16:22:32.332294, 10, pid=2877, effective(65534, 65534), real(65534, 0), class=acls] ../source3/smbd/posix_acls.c:1110(map_canon_ace_perms) map_canon_ace_perms: Mapped (UNIX) 1c0 to (NT) 1f01ff [2017/06/05 16:22:32.332354, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/open.c:181(smbd_check_access_rights) smbd_check_access_rights: file . requesting 0x100081 returning 0x100001 (NT_STATUS_OK) [2017/06/05 16:22:32.332426, 10, pid=2877, effective(65534, 65534), real(65534, 0), class=vfs] ../source3/smbd/vfs.c:1199(check_reduced_name) check_reduced_name: check_reduced_name [.] [/export/vol1] [2017/06/05 16:22:32.332475, 10, pid=2877, effective(65534, 65534), real(65534, 0), class=vfs] ../source3/smbd/vfs.c:1259(check_reduced_name) check_reduced_name realpath [.] -> [/export/vol1] [2017/06/05 16:22:32.332516, 5, pid=2877, effective(65534, 65534), real(65534, 0), class=vfs] ../source3/smbd/vfs.c:1370(check_reduced_name) check_reduced_name: . reduced to /export/vol1 [2017/06/05 16:22:32.332573, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/open.c:689(fd_open) fd_open: name ., flags = 04000 mode = 0744, fd = 35. [2017/06/05 16:22:32.332643, 10, pid=2877, effective(65534, 65534), real(65534, 0), class=locking] ../source3/locking/posix.c:498(delete_lock_ref_count) delete_lock_ref_count for file . [2017/06/05 16:22:32.332708, 5, pid=2877, effective(65534, 65534), real(65534, 0)] ../lib/dbwrap/dbwrap.c:159(dbwrap_check_lock_order) check lock order 1 for /var/lock/samba/smbXsrv_open_global.tdb [2017/06/05 16:22:32.332768, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../lib/dbwrap/dbwrap.c:114(debug_lock_order) lock order: 1:/var/lock/samba/smbXsrv_open_global.tdb 2: 3: [2017/06/05 16:22:32.332817, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../lib/dbwrap/dbwrap_tdb.c:59(db_tdb_log_key) Locking key 381F9B1E [2017/06/05 16:22:32.332866, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../lib/dbwrap/dbwrap_tdb.c:143(db_tdb_fetch_locked_internal) Allocated locked data 0x0x7f38ed382ca0 [2017/06/05 16:22:32.332931, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../lib/dbwrap/dbwrap_tdb.c:59(db_tdb_log_key) Unlocking key 381F9B1E [2017/06/05 16:22:32.333001, 5, pid=2877, effective(65534, 65534), real(65534, 0)] ../lib/dbwrap/dbwrap.c:127(dbwrap_lock_order_state_destructor) release lock order 1 for /var/lock/samba/smbXsrv_open_global.tdb [2017/06/05 16:22:32.333045, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../lib/dbwrap/dbwrap.c:114(debug_lock_order) lock order: 1: 2: 3: [2017/06/05 16:22:32.333099, 0, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/files.c:513(fsp_free) fsp_free(fsp=0x7f38ed3b32c0) [2017/06/05 16:22:32.333288, 5, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/files.c:570(file_free) freed files structure 2772168125 (0 used) [2017/06/05 16:22:32.333325, 5, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/open.c:3917(open_directory) open_directory: opening directory ., access_mask = 0x100081, share_access = 0x7 create_options = 0x0, create_disposition = 0x1, file_attributes = 0x10 [2017/06/05 16:22:32.333364, 10, pid=2877, effective(65534, 65534), real(65534, 0), class=acls] ../source3/smbd/posix_acls.c:3560(posix_get_nt_acl) posix_get_nt_acl: called for file . [2017/06/05 16:22:32.333432, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/passdb/lookup_sid.c:1251(uid_to_sid) uid 0 -> sid S-1-22-1-0 [2017/06/05 16:22:32.333483, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/passdb/lookup_sid.c:1300(gid_to_sid) gid 0 -> sid S-1-22-2-0 [2017/06/05 16:22:32.333522, 10, pid=2877, effective(65534, 65534), real(65534, 0), class=acls] ../source3/smbd/posix_acls.c:2724(canonicalise_acl) canonicalise_acl: Access ace entries before arrange : [2017/06/05 16:22:32.333549, 10, pid=2877, effective(65534, 65534), real(65534, 0), class=acls] ../source3/smbd/posix_acls.c:2737(canonicalise_acl) canon_ace index 0. Type = allow SID = S-1-1-0 other SMB_ACL_OTHER ace_flags = 0x0 perms rwx [2017/06/05 16:22:32.333586, 10, pid=2877, effective(65534, 65534), real(65534, 0), class=acls] ../source3/smbd/posix_acls.c:2737(canonicalise_acl) canon_ace index 1. Type = allow SID = S-1-22-2-0 gid 0 (root) SMB_ACL_GROUP_OBJ ace_flags = 0x0 perms rwx [2017/06/05 16:22:32.333680, 10, pid=2877, effective(65534, 65534), real(65534, 0), class=acls] ../source3/smbd/posix_acls.c:2737(canonicalise_acl) canon_ace index 2. Type = allow SID = S-1-22-1-0 uid 0 (root) SMB_ACL_USER_OBJ ace_flags = 0x0 perms rwx [2017/06/05 16:22:32.333819, 10, pid=2877, effective(65534, 65534), real(65534, 0), class=acls] ../source3/smbd/posix_acls.c:848(print_canon_ace_list) print_canon_ace_list: canonicalise_acl: ace entries after arrange canon_ace index 0. Type = allow SID = S-1-22-1-0 uid 0 (root) SMB_ACL_USER_OBJ ace_flags = 0x0 perms rwx canon_ace index 1. Type = allow SID = S-1-22-2-0 gid 0 (root) SMB_ACL_GROUP_OBJ ace_flags = 0x0 perms rwx canon_ace index 2. Type = allow SID = S-1-1-0 other SMB_ACL_OTHER ace_flags = 0x0 perms rwx [2017/06/05 16:22:32.334178, 10, pid=2877, effective(65534, 65534), real(65534, 0), class=acls] ../source3/smbd/posix_acls.c:1110(map_canon_ace_perms) map_canon_ace_perms: Mapped (UNIX) 1c0 to (NT) 1f01ff [2017/06/05 16:22:32.334225, 10, pid=2877, effective(65534, 65534), real(65534, 0), class=acls] ../source3/smbd/posix_acls.c:1110(map_canon_ace_perms) map_canon_ace_perms: Mapped (UNIX) 1c0 to (NT) 1f01ff [2017/06/05 16:22:32.334255, 10, pid=2877, effective(65534, 65534), real(65534, 0), class=acls] ../source3/smbd/posix_acls.c:1110(map_canon_ace_perms) map_canon_ace_perms: Mapped (UNIX) 1c0 to (NT) 1f01ff [2017/06/05 16:22:32.334314, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/open.c:181(smbd_check_access_rights) smbd_check_access_rights: file . requesting 0x100081 returning 0x100001 (NT_STATUS_OK) [2017/06/05 16:22:32.334365, 0, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/files.c:65(fsp_new) fsp_new: fsp=0x7f38ed3a4570 [2017/06/05 16:22:32.334551, 5, pid=2877, effective(65534, 65534), real(65534, 0)] ../lib/dbwrap/dbwrap.c:159(dbwrap_check_lock_order) check lock order 1 for /var/lock/samba/smbXsrv_open_global.tdb [2017/06/05 16:22:32.334590, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../lib/dbwrap/dbwrap.c:114(debug_lock_order) lock order: 1:/var/lock/samba/smbXsrv_open_global.tdb 2: 3: [2017/06/05 16:22:32.334626, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../lib/dbwrap/dbwrap_tdb.c:59(db_tdb_log_key) Locking key A4052486 [2017/06/05 16:22:32.334663, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../lib/dbwrap/dbwrap_tdb.c:143(db_tdb_fetch_locked_internal) Allocated locked data 0x0x7f38ed3bb7d0 [2017/06/05 16:22:32.334712, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/smbXsrv_open.c:624(smbXsrv_open_global_verify_record) smbXsrv_open_global_verify_record: empty value [2017/06/05 16:22:32.334845, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/smbXsrv_open.c:743(smbXsrv_open_global_store) smbXsrv_open_global_store: key 'A4052486' stored [2017/06/05 16:22:32.334897, 1, pid=2877, effective(65534, 65534), real(65534, 0)] ../librpc/ndr/ndr.c:413(ndr_print_debug) &global_blob: struct smbXsrv_open_globalB version : SMBXSRV_VERSION_0 (0) seqnum : 0x00000001 (1) info : union smbXsrv_open_globalU(case 0) info0 : * info0: struct smbXsrv_open_global0 db_rec : * server_id: struct server_id pid : 0x0000000000000b3d (2877) task_id : 0x00000000 (0) vnn : 0xffffffff (4294967295) unique_id : 0x27330f1f08b45cf6 (2824618017255873782) open_global_id : 0xa4052486 (2751800454) open_persistent_id : 0x00000000a4052486 (2751800454) open_volatile_id : 0x00000000c7c26114 (3351404820) open_owner : S-1-5-21-1893543895-1847372660-4172524467-501 open_time : Mon Jun 5 16:22:32 2017 IDT create_guid : 00000000-0000-0000-0000-000000000000 client_guid : eb460979-4694-11e7-9429-005056ae0ecf app_instance_id : 00000000-0000-0000-0000-000000000000 disconnect_time : NTTIME(0) durable_timeout_msec : 0x00000000 (0) durable : 0x00 (0) backend_cookie : DATA_BLOB length=0 channel_sequence : 0x0000000000000000 (0) [2017/06/05 16:22:32.335423, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../lib/dbwrap/dbwrap_tdb.c:59(db_tdb_log_key) Unlocking key A4052486 [2017/06/05 16:22:32.335473, 5, pid=2877, effective(65534, 65534), real(65534, 0)] ../lib/dbwrap/dbwrap.c:127(dbwrap_lock_order_state_destructor) release lock order 1 for /var/lock/samba/smbXsrv_open_global.tdb [2017/06/05 16:22:32.335514, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../lib/dbwrap/dbwrap.c:114(debug_lock_order) lock order: 1: 2: 3: [2017/06/05 16:22:32.335555, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/smbXsrv_open.c:910(smbXsrv_open_create) smbXsrv_open_create: global_id (0xa4052486) stored [2017/06/05 16:22:32.335583, 1, pid=2877, effective(65534, 65534), real(65534, 0)] ../librpc/ndr/ndr.c:413(ndr_print_debug) &open_blob: struct smbXsrv_openB version : SMBXSRV_VERSION_0 (0) reserved : 0x00000000 (0) info : union smbXsrv_openU(case 0) info0 : * info0: struct smbXsrv_open table : * db_rec : NULL local_id : 0xc7c26114 (3351404820) global : * global: struct smbXsrv_open_global0 db_rec : NULL server_id: struct server_id pid : 0x0000000000000b3d (2877) task_id : 0x00000000 (0) vnn : 0xffffffff (4294967295) unique_id : 0x27330f1f08b45cf6 (2824618017255873782) open_global_id : 0xa4052486 (2751800454) open_persistent_id : 0x00000000a4052486 (2751800454) open_volatile_id : 0x00000000c7c26114 (3351404820) open_owner : S-1-5-21-1893543895-1847372660-4172524467-501 open_time : Mon Jun 5 16:22:32 2017 IDT create_guid : 00000000-0000-0000-0000-000000000000 client_guid : eb460979-4694-11e7-9429-005056ae0ecf app_instance_id : 00000000-0000-0000-0000-000000000000 disconnect_time : NTTIME(0) durable_timeout_msec : 0x00000000 (0) durable : 0x00 (0) backend_cookie : DATA_BLOB length=0 channel_sequence : 0x0000000000000000 (0) status : NT_STATUS_OK idle_time : Mon Jun 5 16:22:32 2017 IDT compat : NULL flags : 0x00 (0) 0: SMBXSRV_OPEN_NEED_REPLAY_CACHE 0: SMBXSRV_OPEN_HAVE_REPLAY_CACHE create_action : 0x00000000 (0) request_count : 0x0000000000000000 (0) pre_request_count : 0x0000000000000000 (0) [2017/06/05 16:22:32.336357, 5, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/files.c:130(file_new) allocated file structure fnum 3351404820 (1 used) [2017/06/05 16:22:32.336411, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/files.c:763(file_name_hash) file_name_hash: /export/vol1/. hash 0xd7088907 [2017/06/05 16:22:32.336476, 10, pid=2877, effective(65534, 65534), real(65534, 0), class=vfs] ../source3/smbd/vfs.c:1199(check_reduced_name) check_reduced_name: check_reduced_name [.] [/export/vol1] [2017/06/05 16:22:32.336516, 10, pid=2877, effective(65534, 65534), real(65534, 0), class=vfs] ../source3/smbd/vfs.c:1259(check_reduced_name) check_reduced_name realpath [.] -> [/export/vol1] [2017/06/05 16:22:32.336547, 5, pid=2877, effective(65534, 65534), real(65534, 0), class=vfs] ../source3/smbd/vfs.c:1370(check_reduced_name) check_reduced_name: . reduced to /export/vol1 [2017/06/05 16:22:32.336602, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/open.c:689(fd_open) fd_open: name ., flags = 0200000 mode = 00, fd = 35. [2017/06/05 16:22:32.336650, 5, pid=2877, effective(65534, 65534), real(65534, 0)] ../lib/dbwrap/dbwrap.c:159(dbwrap_check_lock_order) check lock order 1 for /var/lock/samba/locking.tdb [2017/06/05 16:22:32.336694, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../lib/dbwrap/dbwrap.c:114(debug_lock_order) lock order: 1:/var/lock/samba/locking.tdb 2: 3: [2017/06/05 16:22:32.336795, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../lib/dbwrap/dbwrap_tdb.c:59(db_tdb_log_key) Locking key 1CFD0000000000008000 [2017/06/05 16:22:32.336882, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../lib/dbwrap/dbwrap_tdb.c:143(db_tdb_fetch_locked_internal) Allocated locked data 0x0x7f38ed3ae900 [2017/06/05 16:22:32.336934, 10, pid=2877, effective(65534, 65534), real(65534, 0), class=locking] ../source3/locking/share_mode_lock.c:366(unparse_share_modes) unparse_share_modes: [2017/06/05 16:22:32.337025, 1, pid=2877, effective(65534, 65534), real(65534, 0)] ../librpc/ndr/ndr.c:413(ndr_print_debug) d: struct share_mode_data sequence_number : 0xbb5d755ab6502ab2 (-4945667783316723022) servicepath : * servicepath : '/export/vol1' base_name : * base_name : '.' stream_name : NULL num_share_modes : 0x00000001 (1) share_modes: ARRAY(1) share_modes: struct share_mode_entry pid: struct server_id pid : 0x0000000000000b3d (2877) task_id : 0x00000000 (0) vnn : 0xffffffff (4294967295) unique_id : 0x27330f1f08b45cf6 (2824618017255873782) op_mid : 0x0000000000000005 (5) op_type : 0x0000 (0) lease_idx : 0xffffffff (4294967295) access_mask : 0x00100081 (1048705) share_access : 0x00000007 (7) private_options : 0x00000000 (0) time : Mon Jun 5 16:22:32 2017 IDT.334539 id: struct file_id devid : 0x000000000000fd1c (64796) inode : 0x0000000000000080 (128) extid : 0x0000000000000000 (0) share_file_id : 0x00000000397e3497 (964572311) uid : 0x0000fffe (65534) flags : 0x0000 (0) name_hash : 0xd7088907 (3607660807) stale : 0x00 (0) lease : NULL num_leases : 0x00000000 (0) leases: ARRAY(0) num_delete_tokens : 0x00000000 (0) delete_tokens: ARRAY(0) old_write_time : Thu Jan 1 02:00:00 1970 IST.0 changed_write_time : Thu Jan 1 02:00:00 1970 IST.0 fresh : 0x01 (1) modified : 0x01 (1) record : * id: struct file_id devid : 0x000000000000fd1c (64796) inode : 0x0000000000000080 (128) extid : 0x0000000000000000 (0) [2017/06/05 16:22:32.337835, 10, pid=2877, effective(65534, 65534), real(65534, 0), class=locking] ../source3/locking/share_mode_lock.c:155(share_mode_memcache_delete) deleting entry for file . seq 0x13501076290392828594 key fd1c:80:0 [2017/06/05 16:22:32.337936, 5, pid=2877, effective(65534, 65534), real(65534, 0)] ../lib/dbwrap/dbwrap.c:127(dbwrap_lock_order_state_destructor) release lock order 1 for /var/lock/samba/locking.tdb [2017/06/05 16:22:32.338000, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../lib/dbwrap/dbwrap.c:114(debug_lock_order) lock order: 1: 2: 3: [2017/06/05 16:22:32.338041, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../lib/dbwrap/dbwrap_tdb.c:59(db_tdb_log_key) Unlocking key 1CFD0000000000008000 [2017/06/05 16:22:32.338090, 10, pid=2877, effective(65534, 65534), real(65534, 0), class=locking] ../source3/locking/share_mode_lock.c:169(share_mode_memcache_store) stored entry for file . seq 0x13501076290392828595 key fd1c:80:0 [2017/06/05 16:22:32.338165, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/open.c:5322(create_file_unixpath) create_file_unixpath: info=1 [2017/06/05 16:22:32.338209, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/open.c:5603(create_file_default) create_file: info=1 [2017/06/05 16:22:32.338237, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/smb2_create.c:1188(smbd_smb2_create_send) smbd_smb2_create_send: response construction phase [2017/06/05 16:22:32.338276, 10, pid=2877, effective(65534, 65534), real(65534, 0), class=acls] ../source3/smbd/posix_acls.c:3560(posix_get_nt_acl) posix_get_nt_acl: called for file . [2017/06/05 16:22:32.338359, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/passdb/lookup_sid.c:1251(uid_to_sid) uid 0 -> sid S-1-22-1-0 [2017/06/05 16:22:32.338436, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/passdb/lookup_sid.c:1300(gid_to_sid) gid 0 -> sid S-1-22-2-0 [2017/06/05 16:22:32.338481, 10, pid=2877, effective(65534, 65534), real(65534, 0), class=acls] ../source3/smbd/posix_acls.c:2724(canonicalise_acl) canonicalise_acl: Access ace entries before arrange : [2017/06/05 16:22:32.338508, 10, pid=2877, effective(65534, 65534), real(65534, 0), class=acls] ../source3/smbd/posix_acls.c:2737(canonicalise_acl) canon_ace index 0. Type = allow SID = S-1-1-0 other SMB_ACL_OTHER ace_flags = 0x0 perms rwx [2017/06/05 16:22:32.338559, 10, pid=2877, effective(65534, 65534), real(65534, 0), class=acls] ../source3/smbd/posix_acls.c:2737(canonicalise_acl) canon_ace index 1. Type = allow SID = S-1-22-2-0 gid 0 (root) SMB_ACL_GROUP_OBJ ace_flags = 0x0 perms rwx [2017/06/05 16:22:32.338708, 10, pid=2877, effective(65534, 65534), real(65534, 0), class=acls] ../source3/smbd/posix_acls.c:2737(canonicalise_acl) canon_ace index 2. Type = allow SID = S-1-22-1-0 uid 0 (root) SMB_ACL_USER_OBJ ace_flags = 0x0 perms rwx [2017/06/05 16:22:32.338870, 10, pid=2877, effective(65534, 65534), real(65534, 0), class=acls] ../source3/smbd/posix_acls.c:848(print_canon_ace_list) print_canon_ace_list: canonicalise_acl: ace entries after arrange canon_ace index 0. Type = allow SID = S-1-22-1-0 uid 0 (root) SMB_ACL_USER_OBJ ace_flags = 0x0 perms rwx canon_ace index 1. Type = allow SID = S-1-22-2-0 gid 0 (root) SMB_ACL_GROUP_OBJ ace_flags = 0x0 perms rwx canon_ace index 2. Type = allow SID = S-1-1-0 other SMB_ACL_OTHER ace_flags = 0x0 perms rwx [2017/06/05 16:22:32.339130, 10, pid=2877, effective(65534, 65534), real(65534, 0), class=acls] ../source3/smbd/posix_acls.c:1110(map_canon_ace_perms) map_canon_ace_perms: Mapped (UNIX) 1c0 to (NT) 1f01ff [2017/06/05 16:22:32.339174, 10, pid=2877, effective(65534, 65534), real(65534, 0), class=acls] ../source3/smbd/posix_acls.c:1110(map_canon_ace_perms) map_canon_ace_perms: Mapped (UNIX) 1c0 to (NT) 1f01ff [2017/06/05 16:22:32.339214, 10, pid=2877, effective(65534, 65534), real(65534, 0), class=acls] ../source3/smbd/posix_acls.c:1110(map_canon_ace_perms) map_canon_ace_perms: Mapped (UNIX) 1c0 to (NT) 1f01ff [2017/06/05 16:22:32.339272, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../libcli/security/access_check.c:188(se_access_check) se_access_check: MAX desired = 0x2000000, granted = 0x1f01ff, remaining = 0x1f01ff [2017/06/05 16:22:32.339327, 5, pid=2877, effective(65534, 65534), real(65534, 0)] ../lib/dbwrap/dbwrap.c:159(dbwrap_check_lock_order) check lock order 1 for /var/lock/samba/smbXsrv_open_global.tdb [2017/06/05 16:22:32.339368, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../lib/dbwrap/dbwrap.c:114(debug_lock_order) lock order: 1:/var/lock/samba/smbXsrv_open_global.tdb 2: 3: [2017/06/05 16:22:32.339413, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../lib/dbwrap/dbwrap_tdb.c:59(db_tdb_log_key) Locking key A4052486 [2017/06/05 16:22:32.339454, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../lib/dbwrap/dbwrap_tdb.c:143(db_tdb_fetch_locked_internal) Allocated locked data 0x0x7f38ed3ba930 [2017/06/05 16:22:32.339520, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/smbXsrv_open.c:743(smbXsrv_open_global_store) smbXsrv_open_global_store: key 'A4052486' stored [2017/06/05 16:22:32.339569, 1, pid=2877, effective(65534, 65534), real(65534, 0)] ../librpc/ndr/ndr.c:413(ndr_print_debug) &global_blob: struct smbXsrv_open_globalB version : SMBXSRV_VERSION_0 (0) seqnum : 0x00000002 (2) info : union smbXsrv_open_globalU(case 0) info0 : * info0: struct smbXsrv_open_global0 db_rec : * server_id: struct server_id pid : 0x0000000000000b3d (2877) task_id : 0x00000000 (0) vnn : 0xffffffff (4294967295) unique_id : 0x27330f1f08b45cf6 (2824618017255873782) open_global_id : 0xa4052486 (2751800454) open_persistent_id : 0x00000000a4052486 (2751800454) open_volatile_id : 0x00000000c7c26114 (3351404820) open_owner : S-1-5-21-1893543895-1847372660-4172524467-501 open_time : Mon Jun 5 16:22:32 2017 IDT create_guid : eb46097a-4694-11e7-9429-005056ae0ecf client_guid : eb460979-4694-11e7-9429-005056ae0ecf app_instance_id : 00000000-0000-0000-0000-000000000000 disconnect_time : NTTIME(0) durable_timeout_msec : 0x00000000 (0) durable : 0x00 (0) backend_cookie : DATA_BLOB length=0 channel_sequence : 0x0000000000000000 (0) [2017/06/05 16:22:32.340145, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../lib/dbwrap/dbwrap_tdb.c:59(db_tdb_log_key) Unlocking key A4052486 [2017/06/05 16:22:32.340197, 5, pid=2877, effective(65534, 65534), real(65534, 0)] ../lib/dbwrap/dbwrap.c:127(dbwrap_lock_order_state_destructor) release lock order 1 for /var/lock/samba/smbXsrv_open_global.tdb [2017/06/05 16:22:32.340240, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../lib/dbwrap/dbwrap.c:114(debug_lock_order) lock order: 1: 2: 3: [2017/06/05 16:22:32.340292, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/smbXsrv_open.c:1055(smbXsrv_open_update) smbXsrv_open_update: global_id (0xa4052486) stored [2017/06/05 16:22:32.340333, 1, pid=2877, effective(65534, 65534), real(65534, 0)] ../librpc/ndr/ndr.c:413(ndr_print_debug) &open_blob: struct smbXsrv_openB version : SMBXSRV_VERSION_0 (0) reserved : 0x00000000 (0) info : union smbXsrv_openU(case 0) info0 : * info0: struct smbXsrv_open table : * db_rec : NULL local_id : 0xc7c26114 (3351404820) global : * global: struct smbXsrv_open_global0 db_rec : NULL server_id: struct server_id pid : 0x0000000000000b3d (2877) task_id : 0x00000000 (0) vnn : 0xffffffff (4294967295) unique_id : 0x27330f1f08b45cf6 (2824618017255873782) open_global_id : 0xa4052486 (2751800454) open_persistent_id : 0x00000000a4052486 (2751800454) open_volatile_id : 0x00000000c7c26114 (3351404820) open_owner : S-1-5-21-1893543895-1847372660-4172524467-501 open_time : Mon Jun 5 16:22:32 2017 IDT create_guid : eb46097a-4694-11e7-9429-005056ae0ecf client_guid : eb460979-4694-11e7-9429-005056ae0ecf app_instance_id : 00000000-0000-0000-0000-000000000000 disconnect_time : NTTIME(0) durable_timeout_msec : 0x00000000 (0) durable : 0x00 (0) backend_cookie : DATA_BLOB length=0 channel_sequence : 0x0000000000000000 (0) status : NT_STATUS_OK idle_time : Mon Jun 5 16:22:32 2017 IDT compat : * flags : 0x02 (2) 0: SMBXSRV_OPEN_NEED_REPLAY_CACHE 1: SMBXSRV_OPEN_HAVE_REPLAY_CACHE create_action : 0x00000000 (0) request_count : 0x0000000000000000 (0) pre_request_count : 0x0000000000000000 (0) [2017/06/05 16:22:32.341149, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/smb2_create.c:1248(smbd_smb2_create_send) smb2_create_send: smbXsrv_open_update returned NT_STATUS_OK [2017/06/05 16:22:32.341209, 0, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/smb2_create.c:1352(smbd_smb2_create_send) smbd_smb2_create_send: smb2req->compat_chain_fsp=0x7f38ed3a4570 [2017/06/05 16:22:32.341377, 8, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/dosmode.c:611(dos_mode) dos_mode: . [2017/06/05 16:22:32.341419, 5, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/dosmode.c:70(dos_mode_debug_print) dos_mode_debug_print: dos_mode_from_sbuf returning (0x10): "d" [2017/06/05 16:22:32.341463, 8, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/lib/util.c:1009(is_in_path) is_in_path: . [2017/06/05 16:22:32.341492, 8, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/lib/util.c:1033(is_in_path) is_in_path: match not found [2017/06/05 16:22:32.341518, 5, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/dosmode.c:70(dos_mode_debug_print) dos_mode_debug_print: dos_mode returning (0x10): "d" [2017/06/05 16:22:32.341549, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/smb2_create.c:1397(smbd_smb2_create_send) smbd_smb2_create_send: . - fnum 3351404820 [2017/06/05 16:22:32.341599, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/smb2_server.c:3014(smbd_smb2_request_done_ex) smbd_smb2_request_done_ex: idx[1] status[NT_STATUS_OK] body[88] dyn[yes:88] at ../source3/smbd/smb2_create.c:364 [2017/06/05 16:22:32.341640, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/smb2_server.c:925(smb2_set_operation_credit) smb2_set_operation_credit: requested 1, charge 1, granted 1, current possible/max 482/512, total granted/max/low/range 31/8192/6/31 [2017/06/05 16:22:32.342375, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/smb2_server.c:3912(smbd_smb2_io_handler) smbd_smb2_request idx[1] of 9 vectors [2017/06/05 16:22:32.342550, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/smb2_server.c:673(smb2_validate_sequence_number) smb2_validate_sequence_number: clearing id 6 (position 6) from bitmap [2017/06/05 16:22:32.342586, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/smb2_server.c:673(smb2_validate_sequence_number) smb2_validate_sequence_number: clearing id 7 (position 7) from bitmap [2017/06/05 16:22:32.342630, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/smb2_server.c:2272(smbd_smb2_request_dispatch) smbd_smb2_request_dispatch: opcode[SMB2_OP_QUERY_DIRECTORY] mid = 6 [2017/06/05 16:22:32.342668, 4, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/uid.c:384(change_to_user) Skipping user change - already user [2017/06/05 16:22:32.342751, 0, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/files.c:697(file_fsp_smb2) file_fsp_smb2: smb2req->compat_chain_fsp=(nil) [2017/06/05 16:22:32.342963, 0, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/smb2_server.c:2145(smbd_smb2_request_dispatch_update_counts) smbd_smb2_request_dispatch_update_counts: compat_chain_fsp=0x7f38ed3a4570 [2017/06/05 16:22:32.343160, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/smb2_query_directory.c:94(smbd_smb2_request_process_query_directory) smbd_smb2_request_find_done: in_output_buffer_length = 65536 [2017/06/05 16:22:32.343216, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/smb2_query_directory.c:242(smbd_smb2_query_directory_send) smbd_smb2_query_directory_send: . - fnum 3351404820 [2017/06/05 16:22:32.343252, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/smb2_server.c:1955(smbd_smb2_request_verify_creditcharge) mid 6, CreditCharge: 1, NeededCharge: 1 [2017/06/05 16:22:32.343282, 5, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/dir.c:474(dptr_create) dptr_create dir=. [2017/06/05 16:22:32.343330, 3, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/dir.c:656(dptr_create) creating new dirptr 0 for path ., expect_close = 0 [2017/06/05 16:22:32.343380, 8, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/smb2_query_directory.c:447(smbd_smb2_query_directory_send) smbd_smb2_query_directory_send: dirpath=<.> dontdescend=<>, in_output_buffer_length = 65528 [2017/06/05 16:22:32.343432, 6, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/dir.c:1136(smbd_dirptr_get_entry) smbd_dirptr_get_entry: dirptr 0x7f38ed3b2790 now at offset 0 [2017/06/05 16:22:32.343486, 8, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/dosmode.c:611(dos_mode) dos_mode: . [2017/06/05 16:22:32.343522, 5, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/dosmode.c:70(dos_mode_debug_print) dos_mode_debug_print: dos_mode_from_sbuf returning (0x10): "d" [2017/06/05 16:22:32.343591, 8, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/lib/util.c:1009(is_in_path) is_in_path: . [2017/06/05 16:22:32.343635, 8, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/lib/util.c:1033(is_in_path) is_in_path: match not found [2017/06/05 16:22:32.343662, 5, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/dosmode.c:70(dos_mode_debug_print) dos_mode_debug_print: dos_mode returning (0x10): "d" [2017/06/05 16:22:32.343711, 10, pid=2877, effective(65534, 65534), real(65534, 0), class=locking] ../source3/locking/share_mode_lock.c:283(share_mode_memcache_fetch) fetched entry for file . seq 0x13501076290392828595 key fd1c:80:0 [2017/06/05 16:22:32.343824, 3, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/dir.c:1227(smbd_dirptr_get_entry) smbd_dirptr_get_entry mask=[*] found . fname=. (.) [2017/06/05 16:22:32.343868, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/trans2.c:1821(smbd_marshall_dir_entry) smbd_marshall_dir_entry: space_remaining = 65528 [2017/06/05 16:22:32.343898, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/trans2.c:2226(smbd_marshall_dir_entry) smbd_marshall_dir_entry: SMB_FIND_ID_BOTH_DIRECTORY_INFO [2017/06/05 16:22:32.343937, 6, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/dir.c:1136(smbd_dirptr_get_entry) smbd_dirptr_get_entry: dirptr 0x7f38ed3b2790 now at offset 2147483648 [2017/06/05 16:22:32.344025, 8, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/dosmode.c:611(dos_mode) dos_mode: .. [2017/06/05 16:22:32.344067, 5, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/dosmode.c:70(dos_mode_debug_print) dos_mode_debug_print: dos_mode_from_sbuf returning (0x10): "d" [2017/06/05 16:22:32.344097, 8, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/lib/util.c:1009(is_in_path) is_in_path: .. [2017/06/05 16:22:32.344126, 8, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/lib/util.c:1033(is_in_path) is_in_path: match not found [2017/06/05 16:22:32.344163, 5, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/dosmode.c:70(dos_mode_debug_print) dos_mode_debug_print: dos_mode returning (0x10): "d" [2017/06/05 16:22:32.344208, 3, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/dir.c:1227(smbd_dirptr_get_entry) smbd_dirptr_get_entry mask=[*] found .. fname=.. (..) [2017/06/05 16:22:32.344303, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/trans2.c:1821(smbd_marshall_dir_entry) smbd_marshall_dir_entry: space_remaining = 65416 [2017/06/05 16:22:32.344338, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/trans2.c:2226(smbd_marshall_dir_entry) smbd_marshall_dir_entry: SMB_FIND_ID_BOTH_DIRECTORY_INFO [2017/06/05 16:22:32.344410, 6, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/dir.c:1136(smbd_dirptr_get_entry) smbd_dirptr_get_entry: dirptr 0x7f38ed3b2790 now at offset 512 [2017/06/05 16:22:32.344457, 8, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/dosmode.c:611(dos_mode) dos_mode: New Text Document.txt [2017/06/05 16:22:32.344492, 5, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/dosmode.c:70(dos_mode_debug_print) dos_mode_debug_print: dos_mode_from_sbuf returning (0x20): "a" [2017/06/05 16:22:32.344525, 8, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/lib/util.c:1009(is_in_path) is_in_path: New Text Document.txt [2017/06/05 16:22:32.344556, 8, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/lib/util.c:1033(is_in_path) is_in_path: match not found [2017/06/05 16:22:32.344584, 5, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/dosmode.c:70(dos_mode_debug_print) dos_mode_debug_print: dos_mode returning (0x20): "a" [2017/06/05 16:22:32.344630, 3, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/dir.c:1227(smbd_dirptr_get_entry) smbd_dirptr_get_entry mask=[*] found New Text Document.txt fname=New Text Document.txt (New Text Document.txt) [2017/06/05 16:22:32.344675, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/trans2.c:1821(smbd_marshall_dir_entry) smbd_marshall_dir_entry: space_remaining = 65304 [2017/06/05 16:22:32.344706, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/trans2.c:2226(smbd_marshall_dir_entry) smbd_marshall_dir_entry: SMB_FIND_ID_BOTH_DIRECTORY_INFO [2017/06/05 16:22:32.344802, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/mangle_hash2.c:791(hash2_name_to_8_3) hash2_name_to_8_3: New Text Document.txt -> 124541D5 -> N52HZ2~T.TXT (cache=1) [2017/06/05 16:22:32.344863, 6, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/dir.c:1136(smbd_dirptr_get_entry) smbd_dirptr_get_entry: dirptr 0x7f38ed3b2790 now at offset -1 [2017/06/05 16:22:32.344916, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/smb2_query_directory.c:184(smbd_smb2_request_find_done) smbd_smb2_request_find_done: out_output_buffer.length = 370 [2017/06/05 16:22:32.344957, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/smb2_server.c:3014(smbd_smb2_request_done_ex) smbd_smb2_request_done_ex: idx[1] status[NT_STATUS_OK] body[8] dyn[yes:370] at ../source3/smbd/smb2_query_directory.c:188 [2017/06/05 16:22:32.345029, 0, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/smb2_server.c:2717(smbd_smb2_request_reply_update_counts) smbd_smb2_request_reply_update_counts: compat_chain_fsp=0x7f38ed3a4570 [2017/06/05 16:22:32.345201, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/smb2_server.c:2982(smbd_smb2_request_dispatch_immediate) smbd_smb2_request_dispatch_immediate: idx[5] of 9 vectors req->in.vector[0].iov_len = 0 req->in.vector[1].iov_len = 0 req->in.vector[2].iov_len = 64 req->in.vector[3].iov_len = 32 req->in.vector[4].iov_len = 8 req->in.vector[5].iov_len = 0 req->in.vector[6].iov_len = 64 req->in.vector[7].iov_len = 32 req->in.vector[8].iov_len = 2 req->out.vector[0].iov_len = 4 req->out.vector[1].iov_len = 0 req->out.vector[2].iov_len = 64 req->out.vector[3].iov_len = 8 req->out.vector[4].iov_len = 376 req->out.vector[5].iov_len = 0 req->out.vector[6].iov_len = 64 req->out.vector[7].iov_len = 8 req->out.vector[8].iov_len = 0 [2017/06/05 16:22:32.345390, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/smb2_server.c:2272(smbd_smb2_request_dispatch) smbd_smb2_request_dispatch: opcode[SMB2_OP_QUERY_DIRECTORY] mid = 7 [2017/06/05 16:22:32.345442, 4, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/uid.c:384(change_to_user) Skipping user change - already user [2017/06/05 16:22:32.345478, 0, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/smb2_server.c:2145(smbd_smb2_request_dispatch_update_counts) smbd_smb2_request_dispatch_update_counts: compat_chain_fsp=0x7f38ed3a4570 [2017/06/05 16:22:32.345570, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/smb2_query_directory.c:94(smbd_smb2_request_process_query_directory) smbd_smb2_request_find_done: in_output_buffer_length = 128 [2017/06/05 16:22:32.345610, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/smb2_query_directory.c:242(smbd_smb2_query_directory_send) smbd_smb2_query_directory_send: . - fnum 3351404820 [2017/06/05 16:22:32.345681, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/smb2_server.c:1955(smbd_smb2_request_verify_creditcharge) mid 7, CreditCharge: 1, NeededCharge: 1 [2017/06/05 16:22:32.345717, 8, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/smb2_query_directory.c:447(smbd_smb2_query_directory_send) smbd_smb2_query_directory_send: dirpath=<.> dontdescend=<>, in_output_buffer_length = 120 [2017/06/05 16:22:32.345782, 6, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/dir.c:1136(smbd_dirptr_get_entry) smbd_dirptr_get_entry: dirptr 0x7f38ed3b2790 now at offset -1 [2017/06/05 16:22:32.345820, 3, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/smb2_server.c:3132(smbd_smb2_request_error_ex) smbd_smb2_request_error_ex: smbd_smb2_request_error_ex: idx[5] status[STATUS_NO_MORE_FILES] || at ../source3/smbd/smb2_query_directory.c:155 [2017/06/05 16:22:32.345855, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/smb2_server.c:3014(smbd_smb2_request_done_ex) smbd_smb2_request_done_ex: idx[5] status[STATUS_NO_MORE_FILES] body[8] dyn[yes:1] at ../source3/smbd/smb2_server.c:3189 [2017/06/05 16:22:32.345888, 0, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/smb2_server.c:2717(smbd_smb2_request_reply_update_counts) smbd_smb2_request_reply_update_counts: compat_chain_fsp=0x7f38ed3a4570 [2017/06/05 16:22:32.345966, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/smb2_server.c:925(smb2_set_operation_credit) smb2_set_operation_credit: requested 1, charge 1, granted 1, current possible/max 483/512, total granted/max/low/range 30/8192/8/30 [2017/06/05 16:22:32.346054, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/smb2_server.c:925(smb2_set_operation_credit) smb2_set_operation_credit: requested 1, charge 1, granted 1, current possible/max 482/512, total granted/max/low/range 31/8192/8/31 [2017/06/05 16:22:32.346679, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/smb2_server.c:3912(smbd_smb2_io_handler) smbd_smb2_request idx[1] of 9 vectors [2017/06/05 16:22:32.346831, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/smb2_server.c:673(smb2_validate_sequence_number) smb2_validate_sequence_number: clearing id 8 (position 8) from bitmap [2017/06/05 16:22:32.346886, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/smb2_server.c:673(smb2_validate_sequence_number) smb2_validate_sequence_number: clearing id 9 (position 9) from bitmap [2017/06/05 16:22:32.347021, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/smb2_server.c:2272(smbd_smb2_request_dispatch) smbd_smb2_request_dispatch: opcode[SMB2_OP_CREATE] mid = 8 [2017/06/05 16:22:32.347081, 4, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/uid.c:384(change_to_user) Skipping user change - already user [2017/06/05 16:22:32.347211, 0, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/smb2_server.c:2145(smbd_smb2_request_dispatch_update_counts) smbd_smb2_request_dispatch_update_counts: compat_chain_fsp=(nil) [2017/06/05 16:22:32.347321, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/smb2_create.c:503(smbd_smb2_create_send) smbd_smb2_create: name[] [2017/06/05 16:22:32.347360, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/smb2_create.c:997(smbd_smb2_create_send) smbd_smb2_create_send: open execution phase [2017/06/05 16:22:32.347393, 5, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/filename.c:443(unix_convert) unix_convert called on file "" [2017/06/05 16:22:32.347444, 5, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/filename.c:477(unix_convert) conversion finished "" -> . [2017/06/05 16:22:32.347471, 10, pid=2877, effective(65534, 65534), real(65534, 0), class=vfs] ../source3/smbd/vfs.c:1199(check_reduced_name) check_reduced_name: check_reduced_name [.] [/export/vol1] [2017/06/05 16:22:32.347502, 10, pid=2877, effective(65534, 65534), real(65534, 0), class=vfs] ../source3/smbd/vfs.c:1259(check_reduced_name) check_reduced_name realpath [.] -> [/export/vol1] [2017/06/05 16:22:32.347532, 5, pid=2877, effective(65534, 65534), real(65534, 0), class=vfs] ../source3/smbd/vfs.c:1370(check_reduced_name) check_reduced_name: . reduced to /export/vol1 [2017/06/05 16:22:32.347622, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/open.c:5515(create_file_default) create_file: access_mask = 0x100081 file_attributes = 0x0, share_access = 0x7, create_disposition = 0x1 create_options = 0x1 oplock_request = 0x0 private_flags = 0x0 root_dir_fid = 0x0, ea_list = 0x(nil), sd = 0x(nil), fname = . [2017/06/05 16:22:32.347665, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/open.c:4988(create_file_unixpath) create_file_unixpath: access_mask = 0x100081 file_attributes = 0x0, share_access = 0x7, create_disposition = 0x1 create_options = 0x1 oplock_request = 0x0 private_flags = 0x0 ea_list = 0x(nil), sd = 0x(nil), fname = . [2017/06/05 16:22:32.347701, 5, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/open.c:3917(open_directory) open_directory: opening directory ., access_mask = 0x100081, share_access = 0x7 create_options = 0x1, create_disposition = 0x1, file_attributes = 0x10 [2017/06/05 16:22:32.347847, 10, pid=2877, effective(65534, 65534), real(65534, 0), class=acls] ../source3/smbd/posix_acls.c:3560(posix_get_nt_acl) posix_get_nt_acl: called for file . [2017/06/05 16:22:32.347994, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/passdb/lookup_sid.c:1251(uid_to_sid) uid 0 -> sid S-1-22-1-0 [2017/06/05 16:22:32.348162, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/passdb/lookup_sid.c:1300(gid_to_sid) gid 0 -> sid S-1-22-2-0 [2017/06/05 16:22:32.348219, 10, pid=2877, effective(65534, 65534), real(65534, 0), class=acls] ../source3/smbd/posix_acls.c:2724(canonicalise_acl) canonicalise_acl: Access ace entries before arrange : [2017/06/05 16:22:32.348258, 10, pid=2877, effective(65534, 65534), real(65534, 0), class=acls] ../source3/smbd/posix_acls.c:2737(canonicalise_acl) canon_ace index 0. Type = allow SID = S-1-1-0 other SMB_ACL_OTHER ace_flags = 0x0 perms rwx [2017/06/05 16:22:32.348315, 10, pid=2877, effective(65534, 65534), real(65534, 0), class=acls] ../source3/smbd/posix_acls.c:2737(canonicalise_acl) canon_ace index 1. Type = allow SID = S-1-22-2-0 gid 0 (root) SMB_ACL_GROUP_OBJ ace_flags = 0x0 perms rwx [2017/06/05 16:22:32.348432, 10, pid=2877, effective(65534, 65534), real(65534, 0), class=acls] ../source3/smbd/posix_acls.c:2737(canonicalise_acl) canon_ace index 2. Type = allow SID = S-1-22-1-0 uid 0 (root) SMB_ACL_USER_OBJ ace_flags = 0x0 perms rwx [2017/06/05 16:22:32.348578, 10, pid=2877, effective(65534, 65534), real(65534, 0), class=acls] ../source3/smbd/posix_acls.c:848(print_canon_ace_list) print_canon_ace_list: canonicalise_acl: ace entries after arrange canon_ace index 0. Type = allow SID = S-1-22-1-0 uid 0 (root) SMB_ACL_USER_OBJ ace_flags = 0x0 perms rwx canon_ace index 1. Type = allow SID = S-1-22-2-0 gid 0 (root) SMB_ACL_GROUP_OBJ ace_flags = 0x0 perms rwx canon_ace index 2. Type = allow SID = S-1-1-0 other SMB_ACL_OTHER ace_flags = 0x0 perms rwx [2017/06/05 16:22:32.348928, 10, pid=2877, effective(65534, 65534), real(65534, 0), class=acls] ../source3/smbd/posix_acls.c:1110(map_canon_ace_perms) map_canon_ace_perms: Mapped (UNIX) 1c0 to (NT) 1f01ff [2017/06/05 16:22:32.348997, 10, pid=2877, effective(65534, 65534), real(65534, 0), class=acls] ../source3/smbd/posix_acls.c:1110(map_canon_ace_perms) map_canon_ace_perms: Mapped (UNIX) 1c0 to (NT) 1f01ff [2017/06/05 16:22:32.349044, 10, pid=2877, effective(65534, 65534), real(65534, 0), class=acls] ../source3/smbd/posix_acls.c:1110(map_canon_ace_perms) map_canon_ace_perms: Mapped (UNIX) 1c0 to (NT) 1f01ff [2017/06/05 16:22:32.349102, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/open.c:181(smbd_check_access_rights) smbd_check_access_rights: file . requesting 0x100081 returning 0x100001 (NT_STATUS_OK) [2017/06/05 16:22:32.349155, 0, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/files.c:65(fsp_new) fsp_new: fsp=0x7f38ed3ba6f0 [2017/06/05 16:22:32.349245, 5, pid=2877, effective(65534, 65534), real(65534, 0)] ../lib/dbwrap/dbwrap.c:159(dbwrap_check_lock_order) check lock order 1 for /var/lock/samba/smbXsrv_open_global.tdb [2017/06/05 16:22:32.349281, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../lib/dbwrap/dbwrap.c:114(debug_lock_order) lock order: 1:/var/lock/samba/smbXsrv_open_global.tdb 2: 3: [2017/06/05 16:22:32.349318, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../lib/dbwrap/dbwrap_tdb.c:59(db_tdb_log_key) Locking key C311E6B8 [2017/06/05 16:22:32.349355, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../lib/dbwrap/dbwrap_tdb.c:143(db_tdb_fetch_locked_internal) Allocated locked data 0x0x7f38ed3b2a70 [2017/06/05 16:22:32.349383, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/smbXsrv_open.c:624(smbXsrv_open_global_verify_record) smbXsrv_open_global_verify_record: empty value [2017/06/05 16:22:32.349453, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/smbXsrv_open.c:743(smbXsrv_open_global_store) smbXsrv_open_global_store: key 'C311E6B8' stored [2017/06/05 16:22:32.349552, 1, pid=2877, effective(65534, 65534), real(65534, 0)] ../librpc/ndr/ndr.c:413(ndr_print_debug) &global_blob: struct smbXsrv_open_globalB version : SMBXSRV_VERSION_0 (0) seqnum : 0x00000001 (1) info : union smbXsrv_open_globalU(case 0) info0 : * info0: struct smbXsrv_open_global0 db_rec : * server_id: struct server_id pid : 0x0000000000000b3d (2877) task_id : 0x00000000 (0) vnn : 0xffffffff (4294967295) unique_id : 0x27330f1f08b45cf6 (2824618017255873782) open_global_id : 0xc311e6b8 (3272730296) open_persistent_id : 0x00000000c311e6b8 (3272730296) open_volatile_id : 0x0000000006ab4715 (111888149) open_owner : S-1-5-21-1893543895-1847372660-4172524467-501 open_time : Mon Jun 5 16:22:32 2017 IDT create_guid : 00000000-0000-0000-0000-000000000000 client_guid : eb460979-4694-11e7-9429-005056ae0ecf app_instance_id : 00000000-0000-0000-0000-000000000000 disconnect_time : NTTIME(0) durable_timeout_msec : 0x00000000 (0) durable : 0x00 (0) backend_cookie : DATA_BLOB length=0 channel_sequence : 0x0000000000000000 (0) [2017/06/05 16:22:32.350354, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../lib/dbwrap/dbwrap_tdb.c:59(db_tdb_log_key) Unlocking key C311E6B8 [2017/06/05 16:22:32.350406, 5, pid=2877, effective(65534, 65534), real(65534, 0)] ../lib/dbwrap/dbwrap.c:127(dbwrap_lock_order_state_destructor) release lock order 1 for /var/lock/samba/smbXsrv_open_global.tdb [2017/06/05 16:22:32.350440, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../lib/dbwrap/dbwrap.c:114(debug_lock_order) lock order: 1: 2: 3: [2017/06/05 16:22:32.350534, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/smbXsrv_open.c:910(smbXsrv_open_create) smbXsrv_open_create: global_id (0xc311e6b8) stored [2017/06/05 16:22:32.350574, 1, pid=2877, effective(65534, 65534), real(65534, 0)] ../librpc/ndr/ndr.c:413(ndr_print_debug) &open_blob: struct smbXsrv_openB version : SMBXSRV_VERSION_0 (0) reserved : 0x00000000 (0) info : union smbXsrv_openU(case 0) info0 : * info0: struct smbXsrv_open table : * db_rec : NULL local_id : 0x06ab4715 (111888149) global : * global: struct smbXsrv_open_global0 db_rec : NULL server_id: struct server_id pid : 0x0000000000000b3d (2877) task_id : 0x00000000 (0) vnn : 0xffffffff (4294967295) unique_id : 0x27330f1f08b45cf6 (2824618017255873782) open_global_id : 0xc311e6b8 (3272730296) open_persistent_id : 0x00000000c311e6b8 (3272730296) open_volatile_id : 0x0000000006ab4715 (111888149) open_owner : S-1-5-21-1893543895-1847372660-4172524467-501 open_time : Mon Jun 5 16:22:32 2017 IDT create_guid : 00000000-0000-0000-0000-000000000000 client_guid : eb460979-4694-11e7-9429-005056ae0ecf app_instance_id : 00000000-0000-0000-0000-000000000000 disconnect_time : NTTIME(0) durable_timeout_msec : 0x00000000 (0) durable : 0x00 (0) backend_cookie : DATA_BLOB length=0 channel_sequence : 0x0000000000000000 (0) status : NT_STATUS_OK idle_time : Mon Jun 5 16:22:32 2017 IDT compat : NULL flags : 0x00 (0) 0: SMBXSRV_OPEN_NEED_REPLAY_CACHE 0: SMBXSRV_OPEN_HAVE_REPLAY_CACHE create_action : 0x00000000 (0) request_count : 0x0000000000000000 (0) pre_request_count : 0x0000000000000000 (0) [2017/06/05 16:22:32.351464, 5, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/files.c:130(file_new) allocated file structure fnum 111888149 (2 used) [2017/06/05 16:22:32.351517, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/files.c:763(file_name_hash) file_name_hash: /export/vol1/. hash 0xd7088907 [2017/06/05 16:22:32.351581, 10, pid=2877, effective(65534, 65534), real(65534, 0), class=vfs] ../source3/smbd/vfs.c:1199(check_reduced_name) check_reduced_name: check_reduced_name [.] [/export/vol1] [2017/06/05 16:22:32.351646, 10, pid=2877, effective(65534, 65534), real(65534, 0), class=vfs] ../source3/smbd/vfs.c:1259(check_reduced_name) check_reduced_name realpath [.] -> [/export/vol1] [2017/06/05 16:22:32.351689, 5, pid=2877, effective(65534, 65534), real(65534, 0), class=vfs] ../source3/smbd/vfs.c:1370(check_reduced_name) check_reduced_name: . reduced to /export/vol1 [2017/06/05 16:22:32.351759, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/open.c:689(fd_open) fd_open: name ., flags = 0200000 mode = 00, fd = 39. [2017/06/05 16:22:32.351800, 5, pid=2877, effective(65534, 65534), real(65534, 0)] ../lib/dbwrap/dbwrap.c:159(dbwrap_check_lock_order) check lock order 1 for /var/lock/samba/locking.tdb [2017/06/05 16:22:32.351891, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../lib/dbwrap/dbwrap.c:114(debug_lock_order) lock order: 1:/var/lock/samba/locking.tdb 2: 3: [2017/06/05 16:22:32.351943, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../lib/dbwrap/dbwrap_tdb.c:59(db_tdb_log_key) Locking key 1CFD0000000000008000 [2017/06/05 16:22:32.352014, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../lib/dbwrap/dbwrap_tdb.c:143(db_tdb_fetch_locked_internal) Allocated locked data 0x0x7f38ed3b9430 [2017/06/05 16:22:32.352061, 10, pid=2877, effective(65534, 65534), real(65534, 0), class=locking] ../source3/locking/share_mode_lock.c:233(share_mode_memcache_fetch) failed to find entry for key fd1c:80:0 [2017/06/05 16:22:32.352379, 10, pid=2877, effective(65534, 65534), real(65534, 0), class=locking] ../source3/locking/share_mode_lock.c:346(parse_share_modes) parse_share_modes: [2017/06/05 16:22:32.352574, 1, pid=2877, effective(65534, 65534), real(65534, 0)] ../librpc/ndr/ndr.c:413(ndr_print_debug) d: struct share_mode_data sequence_number : 0xbb5d755ab6502ab3 (-4945667783316723021) servicepath : * servicepath : '/export/vol1' base_name : * base_name : '.' stream_name : NULL num_share_modes : 0x00000001 (1) share_modes: ARRAY(1) share_modes: struct share_mode_entry pid: struct server_id pid : 0x0000000000000b3d (2877) task_id : 0x00000000 (0) vnn : 0xffffffff (4294967295) unique_id : 0x27330f1f08b45cf6 (2824618017255873782) op_mid : 0x0000000000000005 (5) op_type : 0x0000 (0) lease_idx : 0xffffffff (4294967295) access_mask : 0x00100081 (1048705) share_access : 0x00000007 (7) private_options : 0x00000000 (0) time : Mon Jun 5 16:22:32 2017 IDT.334539 id: struct file_id devid : 0x000000000000fd1c (64796) inode : 0x0000000000000080 (128) extid : 0x0000000000000000 (0) share_file_id : 0x00000000397e3497 (964572311) uid : 0x0000fffe (65534) flags : 0x0000 (0) name_hash : 0xd7088907 (3607660807) stale : 0x00 (0) lease : NULL num_leases : 0x00000000 (0) leases: ARRAY(0) num_delete_tokens : 0x00000000 (0) delete_tokens: ARRAY(0) old_write_time : Thu Jan 1 02:00:00 1970 IST.0 changed_write_time : Thu Jan 1 02:00:00 1970 IST.0 fresh : 0x00 (0) modified : 0x00 (0) record : NULL id: struct file_id devid : 0x000000000000fd1c (64796) inode : 0x0000000000000080 (128) extid : 0x0000000000000000 (0) [2017/06/05 16:22:32.353410, 10, pid=2877, effective(65534, 65534), real(65534, 0), class=locking] ../source3/locking/locking.c:1229(find_delete_on_close_token) find_delete_on_close_token: name_hash = 0xd7088907 [2017/06/05 16:22:32.353452, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/open.c:1342(share_conflict) share_conflict: entry->access_mask = 0x100081, entry->share_access = 0x7, entry->private_options = 0x0 [2017/06/05 16:22:32.353490, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/open.c:1353(share_conflict) share_conflict: access_mask = 0x100081, share_access = 0x7 [2017/06/05 16:22:32.353517, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/open.c:1402(share_conflict) share_conflict: [1] am (0x100081) & right (0x6) = 0x0 [2017/06/05 16:22:32.353550, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/open.c:1402(share_conflict) share_conflict: [1] sa (0x7) & share (0x2) = 0x2 [2017/06/05 16:22:32.353577, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/open.c:1404(share_conflict) share_conflict: [2] am (0x100081) & right (0x6) = 0x0 [2017/06/05 16:22:32.353611, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/open.c:1404(share_conflict) share_conflict: [2] sa (0x7) & share (0x2) = 0x2 [2017/06/05 16:22:32.353637, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/open.c:1407(share_conflict) share_conflict: [3] am (0x100081) & right (0x21) = 0x1 [2017/06/05 16:22:32.353670, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/open.c:1407(share_conflict) share_conflict: [3] sa (0x7) & share (0x1) = 0x1 [2017/06/05 16:22:32.353704, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/open.c:1409(share_conflict) share_conflict: [4] am (0x100081) & right (0x21) = 0x1 [2017/06/05 16:22:32.353808, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/open.c:1409(share_conflict) share_conflict: [4] sa (0x7) & share (0x1) = 0x1 [2017/06/05 16:22:32.353842, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/open.c:1412(share_conflict) share_conflict: [5] am (0x100081) & right (0x10000) = 0x0 [2017/06/05 16:22:32.353878, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/open.c:1412(share_conflict) share_conflict: [5] sa (0x7) & share (0x4) = 0x4 [2017/06/05 16:22:32.353912, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/open.c:1414(share_conflict) share_conflict: [6] am (0x100081) & right (0x10000) = 0x0 [2017/06/05 16:22:32.353937, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/open.c:1414(share_conflict) share_conflict: [6] sa (0x7) & share (0x4) = 0x4 [2017/06/05 16:22:32.353962, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/open.c:1416(share_conflict) share_conflict: No conflict. [2017/06/05 16:22:32.354039, 10, pid=2877, effective(65534, 65534), real(65534, 0), class=locking] ../source3/locking/share_mode_lock.c:366(unparse_share_modes) unparse_share_modes: [2017/06/05 16:22:32.354069, 1, pid=2877, effective(65534, 65534), real(65534, 0)] ../librpc/ndr/ndr.c:413(ndr_print_debug) d: struct share_mode_data sequence_number : 0xbb5d755ab6502ab3 (-4945667783316723021) servicepath : * servicepath : '/export/vol1' base_name : * base_name : '.' stream_name : NULL num_share_modes : 0x00000002 (2) share_modes: ARRAY(2) share_modes: struct share_mode_entry pid: struct server_id pid : 0x0000000000000b3d (2877) task_id : 0x00000000 (0) vnn : 0xffffffff (4294967295) unique_id : 0x27330f1f08b45cf6 (2824618017255873782) op_mid : 0x0000000000000005 (5) op_type : 0x0000 (0) lease_idx : 0xffffffff (4294967295) access_mask : 0x00100081 (1048705) share_access : 0x00000007 (7) private_options : 0x00000000 (0) time : Mon Jun 5 16:22:32 2017 IDT.334539 id: struct file_id devid : 0x000000000000fd1c (64796) inode : 0x0000000000000080 (128) extid : 0x0000000000000000 (0) share_file_id : 0x00000000397e3497 (964572311) uid : 0x0000fffe (65534) flags : 0x0000 (0) name_hash : 0xd7088907 (3607660807) stale : 0x00 (0) lease : NULL share_modes: struct share_mode_entry pid: struct server_id pid : 0x0000000000000b3d (2877) task_id : 0x00000000 (0) vnn : 0xffffffff (4294967295) unique_id : 0x27330f1f08b45cf6 (2824618017255873782) op_mid : 0x0000000000000008 (8) op_type : 0x0000 (0) lease_idx : 0xffffffff (4294967295) access_mask : 0x00100081 (1048705) share_access : 0x00000007 (7) private_options : 0x00000000 (0) time : Mon Jun 5 16:22:32 2017 IDT.349235 id: struct file_id devid : 0x000000000000fd1c (64796) inode : 0x0000000000000080 (128) extid : 0x0000000000000000 (0) share_file_id : 0x000000005b30c763 (1529923427) uid : 0x0000fffe (65534) flags : 0x0000 (0) name_hash : 0xd7088907 (3607660807) stale : 0x00 (0) lease : NULL num_leases : 0x00000000 (0) leases: ARRAY(0) num_delete_tokens : 0x00000000 (0) delete_tokens: ARRAY(0) old_write_time : Thu Jan 1 02:00:00 1970 IST.0 changed_write_time : Thu Jan 1 02:00:00 1970 IST.0 fresh : 0x00 (0) modified : 0x01 (1) record : * id: struct file_id devid : 0x000000000000fd1c (64796) inode : 0x0000000000000080 (128) extid : 0x0000000000000000 (0) [2017/06/05 16:22:32.355196, 10, pid=2877, effective(65534, 65534), real(65534, 0), class=locking] ../source3/locking/share_mode_lock.c:155(share_mode_memcache_delete) deleting entry for file . seq 0x13501076290392828595 key fd1c:80:0 [2017/06/05 16:22:32.355390, 5, pid=2877, effective(65534, 65534), real(65534, 0)] ../lib/dbwrap/dbwrap.c:127(dbwrap_lock_order_state_destructor) release lock order 1 for /var/lock/samba/locking.tdb [2017/06/05 16:22:32.355438, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../lib/dbwrap/dbwrap.c:114(debug_lock_order) lock order: 1: 2: 3: [2017/06/05 16:22:32.355558, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../lib/dbwrap/dbwrap_tdb.c:59(db_tdb_log_key) Unlocking key 1CFD0000000000008000 [2017/06/05 16:22:32.355608, 10, pid=2877, effective(65534, 65534), real(65534, 0), class=locking] ../source3/locking/share_mode_lock.c:169(share_mode_memcache_store) stored entry for file . seq 0x13501076290392828596 key fd1c:80:0 [2017/06/05 16:22:32.355695, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/open.c:5322(create_file_unixpath) create_file_unixpath: info=1 [2017/06/05 16:22:32.355804, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/open.c:5603(create_file_default) create_file: info=1 [2017/06/05 16:22:32.355840, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/smb2_create.c:1188(smbd_smb2_create_send) smbd_smb2_create_send: response construction phase [2017/06/05 16:22:32.355878, 10, pid=2877, effective(65534, 65534), real(65534, 0), class=acls] ../source3/smbd/posix_acls.c:3560(posix_get_nt_acl) posix_get_nt_acl: called for file . [2017/06/05 16:22:32.355953, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/passdb/lookup_sid.c:1251(uid_to_sid) uid 0 -> sid S-1-22-1-0 [2017/06/05 16:22:32.356034, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/passdb/lookup_sid.c:1300(gid_to_sid) gid 0 -> sid S-1-22-2-0 [2017/06/05 16:22:32.356127, 10, pid=2877, effective(65534, 65534), real(65534, 0), class=acls] ../source3/smbd/posix_acls.c:2724(canonicalise_acl) canonicalise_acl: Access ace entries before arrange : [2017/06/05 16:22:32.356167, 10, pid=2877, effective(65534, 65534), real(65534, 0), class=acls] ../source3/smbd/posix_acls.c:2737(canonicalise_acl) canon_ace index 0. Type = allow SID = S-1-1-0 other SMB_ACL_OTHER ace_flags = 0x0 perms rwx [2017/06/05 16:22:32.356271, 10, pid=2877, effective(65534, 65534), real(65534, 0), class=acls] ../source3/smbd/posix_acls.c:2737(canonicalise_acl) canon_ace index 1. Type = allow SID = S-1-22-2-0 gid 0 (root) SMB_ACL_GROUP_OBJ ace_flags = 0x0 perms rwx [2017/06/05 16:22:32.356423, 10, pid=2877, effective(65534, 65534), real(65534, 0), class=acls] ../source3/smbd/posix_acls.c:2737(canonicalise_acl) canon_ace index 2. Type = allow SID = S-1-22-1-0 uid 0 (root) SMB_ACL_USER_OBJ ace_flags = 0x0 perms rwx [2017/06/05 16:22:32.356569, 10, pid=2877, effective(65534, 65534), real(65534, 0), class=acls] ../source3/smbd/posix_acls.c:848(print_canon_ace_list) print_canon_ace_list: canonicalise_acl: ace entries after arrange canon_ace index 0. Type = allow SID = S-1-22-1-0 uid 0 (root) SMB_ACL_USER_OBJ ace_flags = 0x0 perms rwx canon_ace index 1. Type = allow SID = S-1-22-2-0 gid 0 (root) SMB_ACL_GROUP_OBJ ace_flags = 0x0 perms rwx canon_ace index 2. Type = allow SID = S-1-1-0 other SMB_ACL_OTHER ace_flags = 0x0 perms rwx [2017/06/05 16:22:32.356902, 10, pid=2877, effective(65534, 65534), real(65534, 0), class=acls] ../source3/smbd/posix_acls.c:1110(map_canon_ace_perms) map_canon_ace_perms: Mapped (UNIX) 1c0 to (NT) 1f01ff [2017/06/05 16:22:32.357003, 10, pid=2877, effective(65534, 65534), real(65534, 0), class=acls] ../source3/smbd/posix_acls.c:1110(map_canon_ace_perms) map_canon_ace_perms: Mapped (UNIX) 1c0 to (NT) 1f01ff [2017/06/05 16:22:32.357104, 10, pid=2877, effective(65534, 65534), real(65534, 0), class=acls] ../source3/smbd/posix_acls.c:1110(map_canon_ace_perms) map_canon_ace_perms: Mapped (UNIX) 1c0 to (NT) 1f01ff [2017/06/05 16:22:32.357200, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../libcli/security/access_check.c:188(se_access_check) se_access_check: MAX desired = 0x2000000, granted = 0x1f01ff, remaining = 0x1f01ff [2017/06/05 16:22:32.357253, 0, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/smb2_create.c:1352(smbd_smb2_create_send) smbd_smb2_create_send: smb2req->compat_chain_fsp=0x7f38ed3ba6f0 [2017/06/05 16:22:32.357520, 8, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/dosmode.c:611(dos_mode) dos_mode: . [2017/06/05 16:22:32.357570, 5, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/dosmode.c:70(dos_mode_debug_print) dos_mode_debug_print: dos_mode_from_sbuf returning (0x10): "d" [2017/06/05 16:22:32.357600, 8, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/lib/util.c:1009(is_in_path) is_in_path: . [2017/06/05 16:22:32.357625, 8, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/lib/util.c:1033(is_in_path) is_in_path: match not found [2017/06/05 16:22:32.357651, 5, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/dosmode.c:70(dos_mode_debug_print) dos_mode_debug_print: dos_mode returning (0x10): "d" [2017/06/05 16:22:32.357834, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/smb2_create.c:1397(smbd_smb2_create_send) smbd_smb2_create_send: . - fnum 111888149 [2017/06/05 16:22:32.357901, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/smb2_server.c:3014(smbd_smb2_request_done_ex) smbd_smb2_request_done_ex: idx[1] status[NT_STATUS_OK] body[88] dyn[yes:32] at ../source3/smbd/smb2_create.c:364 [2017/06/05 16:22:32.358024, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/smb2_server.c:2982(smbd_smb2_request_dispatch_immediate) smbd_smb2_request_dispatch_immediate: idx[5] of 9 vectors req->in.vector[0].iov_len = 0 req->in.vector[1].iov_len = 0 req->in.vector[2].iov_len = 64 req->in.vector[3].iov_len = 56 req->in.vector[4].iov_len = 32 req->in.vector[5].iov_len = 0 req->in.vector[6].iov_len = 64 req->in.vector[7].iov_len = 32 req->in.vector[8].iov_len = 0 req->out.vector[0].iov_len = 4 req->out.vector[1].iov_len = 0 req->out.vector[2].iov_len = 64 req->out.vector[3].iov_len = 88 req->out.vector[4].iov_len = 32 req->out.vector[5].iov_len = 0 req->out.vector[6].iov_len = 64 req->out.vector[7].iov_len = 8 req->out.vector[8].iov_len = 0 [2017/06/05 16:22:32.358315, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/smb2_server.c:2272(smbd_smb2_request_dispatch) smbd_smb2_request_dispatch: opcode[SMB2_OP_NOTIFY] mid = 9 [2017/06/05 16:22:32.358362, 4, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/uid.c:384(change_to_user) Skipping user change - already user [2017/06/05 16:22:32.358390, 0, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/smb2_server.c:2145(smbd_smb2_request_dispatch_update_counts) smbd_smb2_request_dispatch_update_counts: compat_chain_fsp=0x7f38ed3ba6f0 [2017/06/05 16:22:32.358540, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/smb2_server.c:1955(smbd_smb2_request_verify_creditcharge) mid 9, CreditCharge: 1, NeededCharge: 1 [2017/06/05 16:22:32.358577, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/smb2_notify.c:232(smbd_smb2_notify_send) smbd_smb2_notify_send: . - fnum 111888149 [2017/06/05 16:22:32.358616, 3, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/smb2_notify.c:252(smbd_smb2_notify_send) smbd_smb2_notify_send: notify change called on ., filter = FILE_NAME|DIR_NAME|ATTRIBUTES|LAST_WRITE, recursive = 0 [2017/06/05 16:22:32.358711, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/notify_msg.c:154(notify_add) notify_add: path=[/export/vol1], filter=23, subdir_filter=0, private_data=0x7f38ed3ba6f0 [2017/06/05 16:22:32.358813, 4, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/sec_ctx.c:216(push_sec_ctx) push_sec_ctx(65534, 65534) : sec_ctx_stack_ndx = 1 [2017/06/05 16:22:32.358929, 4, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/uid.c:491(push_conn_ctx) push_conn_ctx(1512126538) : conn_ctx_stack_ndx = 0 [2017/06/05 16:22:32.358956, 4, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/sec_ctx.c:320(set_sec_ctx_internal) setting sec ctx (0, 0) - sec_ctx_stack_ndx = 1 [2017/06/05 16:22:32.359027, 5, pid=2877, effective(65534, 65534), real(65534, 0)] ../libcli/security/security_token.c:53(security_token_debug) Security token: (NULL) [2017/06/05 16:22:32.359145, 5, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/auth/token_util.c:639(debug_unix_user_token) UNIX token of user 0 Primary group is 0 and contains 0 supplementary groups [2017/06/05 16:22:32.359202, 10, pid=2877, effective(0, 0), real(0, 0)] ../source3/lib/messages_dgm.c:323(messaging_dgm_send) messaging_dgm_send: Sending message to 2602 [2017/06/05 16:22:32.359338, 4, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/sec_ctx.c:438(pop_sec_ctx) pop_sec_ctx (65534, 65534) - sec_ctx_stack_ndx = 0 [2017/06/05 16:22:32.359384, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/notify.c:331(change_notify_add_request) change_notify_add_request: Adding request for .: max_param = 32 smbd_smb2_request_pending_queue: req->current_idx = 5 req->in.vector[0].iov_len = 0 req->in.vector[1].iov_len = 0 req->in.vector[2].iov_len = 64 req->in.vector[3].iov_len = 56 req->in.vector[4].iov_len = 32 req->in.vector[5].iov_len = 0 req->in.vector[6].iov_len = 64 req->in.vector[7].iov_len = 32 req->in.vector[8].iov_len = 0 req->out.vector[0].iov_len = 4 req->out.vector[1].iov_len = 0 req->out.vector[2].iov_len = 64 req->out.vector[3].iov_len = 88 req->out.vector[4].iov_len = 32 req->out.vector[5].iov_len = 0 req->out.vector[6].iov_len = 64 req->out.vector[7].iov_len = 8 req->out.vector[8].iov_len = 0 [2017/06/05 16:22:32.359614, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/smb2_server.c:925(smb2_set_operation_credit) smb2_set_operation_credit: requested 1, charge 1, granted 1, current possible/max 483/512, total granted/max/low/range 30/8192/10/30 smb2_send_async_interim_response: nreq->current_idx = 1 smb2_send_async_interim_response: returning 5 vectors req->out.vector[0].iov_len = 4 req->out.vector[1].iov_len = 0 req->out.vector[2].iov_len = 64 req->out.vector[3].iov_len = 88 req->out.vector[4].iov_len = 32 [2017/06/05 16:22:32.359839, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/smb2_server.c:3912(smbd_smb2_io_handler) smbd_smb2_request idx[1] of 5 vectors [2017/06/05 16:22:32.359889, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/smb2_server.c:673(smb2_validate_sequence_number) smb2_validate_sequence_number: clearing id 10 (position 10) from bitmap [2017/06/05 16:22:32.359920, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/smb2_server.c:2272(smbd_smb2_request_dispatch) smbd_smb2_request_dispatch: opcode[SMB2_OP_CLOSE] mid = 10 [2017/06/05 16:22:32.359951, 4, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/uid.c:384(change_to_user) Skipping user change - already user [2017/06/05 16:22:32.360008, 0, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/files.c:697(file_fsp_smb2) file_fsp_smb2: smb2req->compat_chain_fsp=(nil) [2017/06/05 16:22:32.360148, 0, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/smb2_server.c:2145(smbd_smb2_request_dispatch_update_counts) smbd_smb2_request_dispatch_update_counts: compat_chain_fsp=0x7f38ed3a4570 [2017/06/05 16:22:32.360304, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/smb2_close.c:227(smbd_smb2_close) smbd_smb2_close: . - fnum 3351404820 [2017/06/05 16:22:32.360347, 5, pid=2877, effective(65534, 65534), real(65534, 0)] ../lib/dbwrap/dbwrap.c:159(dbwrap_check_lock_order) check lock order 1 for /var/lock/samba/locking.tdb [2017/06/05 16:22:32.360375, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../lib/dbwrap/dbwrap.c:114(debug_lock_order) lock order: 1:/var/lock/samba/locking.tdb 2: 3: [2017/06/05 16:22:32.360459, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../lib/dbwrap/dbwrap_tdb.c:59(db_tdb_log_key) Locking key 1CFD0000000000008000 [2017/06/05 16:22:32.360496, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../lib/dbwrap/dbwrap_tdb.c:143(db_tdb_fetch_locked_internal) Allocated locked data 0x0x7f38ed3b7960 [2017/06/05 16:22:32.360598, 10, pid=2877, effective(65534, 65534), real(65534, 0), class=locking] ../source3/locking/share_mode_lock.c:283(share_mode_memcache_fetch) fetched entry for file . seq 0x13501076290392828596 key fd1c:80:0 [2017/06/05 16:22:32.360648, 10, pid=2877, effective(65534, 65534), real(65534, 0), class=locking] ../source3/locking/locking.c:1229(find_delete_on_close_token) find_delete_on_close_token: name_hash = 0xd7088907 [2017/06/05 16:22:32.360679, 10, pid=2877, effective(65534, 65534), real(65534, 0), class=locking] ../source3/locking/share_mode_lock.c:366(unparse_share_modes) unparse_share_modes: [2017/06/05 16:22:32.360707, 1, pid=2877, effective(65534, 65534), real(65534, 0)] ../librpc/ndr/ndr.c:413(ndr_print_debug) d: struct share_mode_data sequence_number : 0xbb5d755ab6502ab4 (-4945667783316723020) servicepath : * servicepath : '/export/vol1' base_name : * base_name : '.' stream_name : NULL num_share_modes : 0x00000001 (1) share_modes: ARRAY(1) share_modes: struct share_mode_entry pid: struct server_id pid : 0x0000000000000b3d (2877) task_id : 0x00000000 (0) vnn : 0xffffffff (4294967295) unique_id : 0x27330f1f08b45cf6 (2824618017255873782) op_mid : 0x0000000000000008 (8) op_type : 0x0000 (0) lease_idx : 0xffffffff (4294967295) access_mask : 0x00100081 (1048705) share_access : 0x00000007 (7) private_options : 0x00000000 (0) time : Mon Jun 5 16:22:32 2017 IDT.349235 id: struct file_id devid : 0x000000000000fd1c (64796) inode : 0x0000000000000080 (128) extid : 0x0000000000000000 (0) share_file_id : 0x000000005b30c763 (1529923427) uid : 0x0000fffe (65534) flags : 0x0000 (0) name_hash : 0xd7088907 (3607660807) stale : 0x00 (0) lease : NULL num_leases : 0x00000000 (0) leases: ARRAY(0) num_delete_tokens : 0x00000000 (0) delete_tokens: ARRAY(0) old_write_time : Thu Jan 1 02:00:00 1970 IST.0 changed_write_time : Thu Jan 1 02:00:00 1970 IST.0 fresh : 0x00 (0) modified : 0x01 (1) record : * id: struct file_id devid : 0x000000000000fd1c (64796) inode : 0x0000000000000080 (128) extid : 0x0000000000000000 (0) [2017/06/05 16:22:32.362274, 10, pid=2877, effective(65534, 65534), real(65534, 0), class=locking] ../source3/locking/share_mode_lock.c:155(share_mode_memcache_delete) deleting entry for file . seq 0x13501076290392828596 key fd1c:80:0 [2017/06/05 16:22:32.362499, 5, pid=2877, effective(65534, 65534), real(65534, 0)] ../lib/dbwrap/dbwrap.c:127(dbwrap_lock_order_state_destructor) release lock order 1 for /var/lock/samba/locking.tdb [2017/06/05 16:22:32.362547, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../lib/dbwrap/dbwrap.c:114(debug_lock_order) lock order: 1: 2: 3: [2017/06/05 16:22:32.362643, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../lib/dbwrap/dbwrap_tdb.c:59(db_tdb_log_key) Unlocking key 1CFD0000000000008000 [2017/06/05 16:22:32.362774, 10, pid=2877, effective(65534, 65534), real(65534, 0), class=locking] ../source3/locking/share_mode_lock.c:169(share_mode_memcache_store) stored entry for file . seq 0x13501076290392828597 key fd1c:80:0 [2017/06/05 16:22:32.362892, 4, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/dir.c:233(dptr_close_internal) closing dptr key 0 [2017/06/05 16:22:32.363055, 5, pid=2877, effective(65534, 65534), real(65534, 0)] ../lib/dbwrap/dbwrap.c:159(dbwrap_check_lock_order) check lock order 1 for /var/lock/samba/smbXsrv_open_global.tdb [2017/06/05 16:22:32.363089, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../lib/dbwrap/dbwrap.c:114(debug_lock_order) lock order: 1:/var/lock/samba/smbXsrv_open_global.tdb 2: 3: [2017/06/05 16:22:32.363166, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../lib/dbwrap/dbwrap_tdb.c:59(db_tdb_log_key) Locking key A4052486 [2017/06/05 16:22:32.363205, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../lib/dbwrap/dbwrap_tdb.c:143(db_tdb_fetch_locked_internal) Allocated locked data 0x0x7f38ed382ca0 [2017/06/05 16:22:32.363252, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../lib/dbwrap/dbwrap_tdb.c:59(db_tdb_log_key) Unlocking key A4052486 [2017/06/05 16:22:32.363296, 5, pid=2877, effective(65534, 65534), real(65534, 0)] ../lib/dbwrap/dbwrap.c:127(dbwrap_lock_order_state_destructor) release lock order 1 for /var/lock/samba/smbXsrv_open_global.tdb [2017/06/05 16:22:32.363405, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../lib/dbwrap/dbwrap.c:114(debug_lock_order) lock order: 1: 2: 3: [2017/06/05 16:22:32.363494, 0, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/files.c:513(fsp_free) fsp_free(fsp=0x7f38ed3a4570) [2017/06/05 16:22:32.363772, 5, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/files.c:570(file_free) freed files structure 3351404820 (1 used) [2017/06/05 16:22:32.363823, 8, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/dosmode.c:611(dos_mode) dos_mode: . [2017/06/05 16:22:32.363855, 5, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/dosmode.c:70(dos_mode_debug_print) dos_mode_debug_print: dos_mode_from_sbuf returning (0x10): "d" [2017/06/05 16:22:32.363895, 8, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/lib/util.c:1009(is_in_path) is_in_path: . [2017/06/05 16:22:32.364023, 8, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/lib/util.c:1033(is_in_path) is_in_path: match not found [2017/06/05 16:22:32.364057, 5, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/dosmode.c:70(dos_mode_debug_print) dos_mode_debug_print: dos_mode returning (0x10): "d" [2017/06/05 16:22:32.364095, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/smb2_server.c:3014(smbd_smb2_request_done_ex) smbd_smb2_request_done_ex: idx[1] status[NT_STATUS_OK] body[60] dyn[no:0] at ../source3/smbd/smb2_close.c:144 [2017/06/05 16:22:32.364219, 0, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/smb2_server.c:2717(smbd_smb2_request_reply_update_counts) smbd_smb2_request_reply_update_counts: compat_chain_fsp=(nil) [2017/06/05 16:22:32.364471, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/smb2_server.c:925(smb2_set_operation_credit) smb2_set_operation_credit: requested 1, charge 1, granted 1, current possible/max 483/512, total granted/max/low/range 30/8192/11/30 [2017/06/05 16:22:32.364550, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/smb2_server.c:1571(smbd_smb2_request_pending_timer) smbd_smb2_request_pending_queue: opcode[SMB2_OP_NOTIFY] mid 9 going async [2017/06/05 16:22:32.364704, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/smb2_server.c:925(smb2_set_operation_credit) smb2_set_operation_credit: requested 1, charge 1, granted 1, current possible/max 482/512, total granted/max/low/range 31/8192/11/31 [2017/06/05 16:22:32.364778, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/smb2_server.c:1669(smbd_smb2_request_pending_timer) state->vector[0/5].iov_len = 4 state->vector[1/5].iov_len = 0 state->vector[2/5].iov_len = 64 state->vector[3/5].iov_len = 8 state->vector[4/5].iov_len = 1 [2017/06/05 16:22:32.370834, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/smb2_server.c:3912(smbd_smb2_io_handler) smbd_smb2_request idx[1] of 9 vectors [2017/06/05 16:22:32.370883, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/smb2_server.c:673(smb2_validate_sequence_number) smb2_validate_sequence_number: clearing id 11 (position 11) from bitmap [2017/06/05 16:22:32.370913, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/smb2_server.c:673(smb2_validate_sequence_number) smb2_validate_sequence_number: clearing id 12 (position 12) from bitmap [2017/06/05 16:22:32.370944, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/smb2_server.c:2272(smbd_smb2_request_dispatch) smbd_smb2_request_dispatch: opcode[SMB2_OP_CREATE] mid = 11 [2017/06/05 16:22:32.371004, 4, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/uid.c:384(change_to_user) Skipping user change - already user [2017/06/05 16:22:32.371046, 0, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/smb2_server.c:2145(smbd_smb2_request_dispatch_update_counts) smbd_smb2_request_dispatch_update_counts: compat_chain_fsp=(nil) [2017/06/05 16:22:32.371263, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/smb2_create.c:503(smbd_smb2_create_send) smbd_smb2_create: name[] [2017/06/05 16:22:32.371302, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/smb2_create.c:997(smbd_smb2_create_send) smbd_smb2_create_send: open execution phase [2017/06/05 16:22:32.371387, 5, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/filename.c:443(unix_convert) unix_convert called on file "" [2017/06/05 16:22:32.371438, 5, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/filename.c:477(unix_convert) conversion finished "" -> . [2017/06/05 16:22:32.371466, 10, pid=2877, effective(65534, 65534), real(65534, 0), class=vfs] ../source3/smbd/vfs.c:1199(check_reduced_name) check_reduced_name: check_reduced_name [.] [/export/vol1] [2017/06/05 16:22:32.371507, 10, pid=2877, effective(65534, 65534), real(65534, 0), class=vfs] ../source3/smbd/vfs.c:1259(check_reduced_name) check_reduced_name realpath [.] -> [/export/vol1] [2017/06/05 16:22:32.371537, 5, pid=2877, effective(65534, 65534), real(65534, 0), class=vfs] ../source3/smbd/vfs.c:1370(check_reduced_name) check_reduced_name: . reduced to /export/vol1 [2017/06/05 16:22:32.371614, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/open.c:5515(create_file_default) create_file: access_mask = 0x100080 file_attributes = 0x0, share_access = 0x0, create_disposition = 0x1 create_options = 0x800001 oplock_request = 0x0 private_flags = 0x0 root_dir_fid = 0x0, ea_list = 0x(nil), sd = 0x(nil), fname = . [2017/06/05 16:22:32.371691, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/open.c:4988(create_file_unixpath) create_file_unixpath: access_mask = 0x100080 file_attributes = 0x0, share_access = 0x0, create_disposition = 0x1 create_options = 0x800001 oplock_request = 0x0 private_flags = 0x0 ea_list = 0x(nil), sd = 0x(nil), fname = . [2017/06/05 16:22:32.371808, 5, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/open.c:3917(open_directory) open_directory: opening directory ., access_mask = 0x100080, share_access = 0x0 create_options = 0x800001, create_disposition = 0x1, file_attributes = 0x10 [2017/06/05 16:22:32.371857, 10, pid=2877, effective(65534, 65534), real(65534, 0), class=acls] ../source3/smbd/posix_acls.c:3560(posix_get_nt_acl) posix_get_nt_acl: called for file . [2017/06/05 16:22:32.372060, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/passdb/lookup_sid.c:1251(uid_to_sid) uid 0 -> sid S-1-22-1-0 [2017/06/05 16:22:32.372345, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/passdb/lookup_sid.c:1300(gid_to_sid) gid 0 -> sid S-1-22-2-0 [2017/06/05 16:22:32.372406, 10, pid=2877, effective(65534, 65534), real(65534, 0), class=acls] ../source3/smbd/posix_acls.c:2724(canonicalise_acl) canonicalise_acl: Access ace entries before arrange : [2017/06/05 16:22:32.372504, 10, pid=2877, effective(65534, 65534), real(65534, 0), class=acls] ../source3/smbd/posix_acls.c:2737(canonicalise_acl) canon_ace index 0. Type = allow SID = S-1-1-0 other SMB_ACL_OTHER ace_flags = 0x0 perms rwx [2017/06/05 16:22:32.372607, 10, pid=2877, effective(65534, 65534), real(65534, 0), class=acls] ../source3/smbd/posix_acls.c:2737(canonicalise_acl) canon_ace index 1. Type = allow SID = S-1-22-2-0 gid 0 (root) SMB_ACL_GROUP_OBJ ace_flags = 0x0 perms rwx [2017/06/05 16:22:32.372788, 10, pid=2877, effective(65534, 65534), real(65534, 0), class=acls] ../source3/smbd/posix_acls.c:2737(canonicalise_acl) canon_ace index 2. Type = allow SID = S-1-22-1-0 uid 0 (root) SMB_ACL_USER_OBJ ace_flags = 0x0 perms rwx [2017/06/05 16:22:32.372933, 10, pid=2877, effective(65534, 65534), real(65534, 0), class=acls] ../source3/smbd/posix_acls.c:848(print_canon_ace_list) print_canon_ace_list: canonicalise_acl: ace entries after arrange canon_ace index 0. Type = allow SID = S-1-22-1-0 uid 0 (root) SMB_ACL_USER_OBJ ace_flags = 0x0 perms rwx canon_ace index 1. Type = allow SID = S-1-22-2-0 gid 0 (root) SMB_ACL_GROUP_OBJ ace_flags = 0x0 perms rwx canon_ace index 2. Type = allow SID = S-1-1-0 other SMB_ACL_OTHER ace_flags = 0x0 perms rwx [2017/06/05 16:22:32.373291, 10, pid=2877, effective(65534, 65534), real(65534, 0), class=acls] ../source3/smbd/posix_acls.c:1110(map_canon_ace_perms) map_canon_ace_perms: Mapped (UNIX) 1c0 to (NT) 1f01ff [2017/06/05 16:22:32.373368, 10, pid=2877, effective(65534, 65534), real(65534, 0), class=acls] ../source3/smbd/posix_acls.c:1110(map_canon_ace_perms) map_canon_ace_perms: Mapped (UNIX) 1c0 to (NT) 1f01ff [2017/06/05 16:22:32.373467, 10, pid=2877, effective(65534, 65534), real(65534, 0), class=acls] ../source3/smbd/posix_acls.c:1110(map_canon_ace_perms) map_canon_ace_perms: Mapped (UNIX) 1c0 to (NT) 1f01ff [2017/06/05 16:22:32.373565, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/open.c:181(smbd_check_access_rights) smbd_check_access_rights: file . requesting 0x100080 returning 0x100000 (NT_STATUS_OK) [2017/06/05 16:22:32.373614, 0, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/files.c:65(fsp_new) fsp_new: fsp=0x7f38ed3b9960 [2017/06/05 16:22:32.373892, 5, pid=2877, effective(65534, 65534), real(65534, 0)] ../lib/dbwrap/dbwrap.c:159(dbwrap_check_lock_order) check lock order 1 for /var/lock/samba/smbXsrv_open_global.tdb [2017/06/05 16:22:32.373928, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../lib/dbwrap/dbwrap.c:114(debug_lock_order) lock order: 1:/var/lock/samba/smbXsrv_open_global.tdb 2: 3: [2017/06/05 16:22:32.373964, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../lib/dbwrap/dbwrap_tdb.c:59(db_tdb_log_key) Locking key C86CD68C [2017/06/05 16:22:32.374104, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../lib/dbwrap/dbwrap_tdb.c:143(db_tdb_fetch_locked_internal) Allocated locked data 0x0x7f38ed3b2790 [2017/06/05 16:22:32.374151, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/smbXsrv_open.c:624(smbXsrv_open_global_verify_record) smbXsrv_open_global_verify_record: empty value [2017/06/05 16:22:32.374336, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/smbXsrv_open.c:743(smbXsrv_open_global_store) smbXsrv_open_global_store: key 'C86CD68C' stored [2017/06/05 16:22:32.374386, 1, pid=2877, effective(65534, 65534), real(65534, 0)] ../librpc/ndr/ndr.c:413(ndr_print_debug) &global_blob: struct smbXsrv_open_globalB version : SMBXSRV_VERSION_0 (0) seqnum : 0x00000001 (1) info : union smbXsrv_open_globalU(case 0) info0 : * info0: struct smbXsrv_open_global0 db_rec : * server_id: struct server_id pid : 0x0000000000000b3d (2877) task_id : 0x00000000 (0) vnn : 0xffffffff (4294967295) unique_id : 0x27330f1f08b45cf6 (2824618017255873782) open_global_id : 0xc86cd68c (3362576012) open_persistent_id : 0x00000000c86cd68c (3362576012) open_volatile_id : 0x00000000afd51f7d (2949980029) open_owner : S-1-5-21-1893543895-1847372660-4172524467-501 open_time : Mon Jun 5 16:22:32 2017 IDT create_guid : 00000000-0000-0000-0000-000000000000 client_guid : eb460979-4694-11e7-9429-005056ae0ecf app_instance_id : 00000000-0000-0000-0000-000000000000 disconnect_time : NTTIME(0) durable_timeout_msec : 0x00000000 (0) durable : 0x00 (0) backend_cookie : DATA_BLOB length=0 channel_sequence : 0x0000000000000000 (0) [2017/06/05 16:22:32.374908, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../lib/dbwrap/dbwrap_tdb.c:59(db_tdb_log_key) Unlocking key C86CD68C [2017/06/05 16:22:32.374954, 5, pid=2877, effective(65534, 65534), real(65534, 0)] ../lib/dbwrap/dbwrap.c:127(dbwrap_lock_order_state_destructor) release lock order 1 for /var/lock/samba/smbXsrv_open_global.tdb [2017/06/05 16:22:32.375033, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../lib/dbwrap/dbwrap.c:114(debug_lock_order) lock order: 1: 2: 3: [2017/06/05 16:22:32.375076, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/smbXsrv_open.c:910(smbXsrv_open_create) smbXsrv_open_create: global_id (0xc86cd68c) stored [2017/06/05 16:22:32.375112, 1, pid=2877, effective(65534, 65534), real(65534, 0)] ../librpc/ndr/ndr.c:413(ndr_print_debug) &open_blob: struct smbXsrv_openB version : SMBXSRV_VERSION_0 (0) reserved : 0x00000000 (0) info : union smbXsrv_openU(case 0) info0 : * info0: struct smbXsrv_open table : * db_rec : NULL local_id : 0xafd51f7d (2949980029) global : * global: struct smbXsrv_open_global0 db_rec : NULL server_id: struct server_id pid : 0x0000000000000b3d (2877) task_id : 0x00000000 (0) vnn : 0xffffffff (4294967295) unique_id : 0x27330f1f08b45cf6 (2824618017255873782) open_global_id : 0xc86cd68c (3362576012) open_persistent_id : 0x00000000c86cd68c (3362576012) open_volatile_id : 0x00000000afd51f7d (2949980029) open_owner : S-1-5-21-1893543895-1847372660-4172524467-501 open_time : Mon Jun 5 16:22:32 2017 IDT create_guid : 00000000-0000-0000-0000-000000000000 client_guid : eb460979-4694-11e7-9429-005056ae0ecf app_instance_id : 00000000-0000-0000-0000-000000000000 disconnect_time : NTTIME(0) durable_timeout_msec : 0x00000000 (0) durable : 0x00 (0) backend_cookie : DATA_BLOB length=0 channel_sequence : 0x0000000000000000 (0) status : NT_STATUS_OK idle_time : Mon Jun 5 16:22:32 2017 IDT compat : NULL flags : 0x00 (0) 0: SMBXSRV_OPEN_NEED_REPLAY_CACHE 0: SMBXSRV_OPEN_HAVE_REPLAY_CACHE create_action : 0x00000000 (0) request_count : 0x0000000000000000 (0) pre_request_count : 0x0000000000000000 (0) [2017/06/05 16:22:32.375838, 5, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/files.c:130(file_new) allocated file structure fnum 2949980029 (2 used) [2017/06/05 16:22:32.375879, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/files.c:763(file_name_hash) file_name_hash: /export/vol1/. hash 0xd7088907 [2017/06/05 16:22:32.375918, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/open.c:4125(open_directory) Not opening Directory . [2017/06/05 16:22:32.375953, 5, pid=2877, effective(65534, 65534), real(65534, 0)] ../lib/dbwrap/dbwrap.c:159(dbwrap_check_lock_order) check lock order 1 for /var/lock/samba/locking.tdb [2017/06/05 16:22:32.376099, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../lib/dbwrap/dbwrap.c:114(debug_lock_order) lock order: 1:/var/lock/samba/locking.tdb 2: 3: [2017/06/05 16:22:32.376157, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../lib/dbwrap/dbwrap_tdb.c:59(db_tdb_log_key) Locking key 1CFD0000000000008000 [2017/06/05 16:22:32.376269, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../lib/dbwrap/dbwrap_tdb.c:143(db_tdb_fetch_locked_internal) Allocated locked data 0x0x7f38ed3bada0 [2017/06/05 16:22:32.376366, 10, pid=2877, effective(65534, 65534), real(65534, 0), class=locking] ../source3/locking/share_mode_lock.c:283(share_mode_memcache_fetch) fetched entry for file . seq 0x13501076290392828597 key fd1c:80:0 [2017/06/05 16:22:32.376417, 10, pid=2877, effective(65534, 65534), real(65534, 0), class=locking] ../source3/locking/locking.c:1229(find_delete_on_close_token) find_delete_on_close_token: name_hash = 0xd7088907 [2017/06/05 16:22:32.376459, 10, pid=2877, effective(65534, 65534), real(65534, 0), class=locking] ../source3/locking/share_mode_lock.c:366(unparse_share_modes) unparse_share_modes: [2017/06/05 16:22:32.376498, 1, pid=2877, effective(65534, 65534), real(65534, 0)] ../librpc/ndr/ndr.c:413(ndr_print_debug) d: struct share_mode_data sequence_number : 0xbb5d755ab6502ab5 (-4945667783316723019) servicepath : * servicepath : '/export/vol1' base_name : * base_name : '.' stream_name : NULL num_share_modes : 0x00000002 (2) share_modes: ARRAY(2) share_modes: struct share_mode_entry pid: struct server_id pid : 0x0000000000000b3d (2877) task_id : 0x00000000 (0) vnn : 0xffffffff (4294967295) unique_id : 0x27330f1f08b45cf6 (2824618017255873782) op_mid : 0x0000000000000008 (8) op_type : 0x0000 (0) lease_idx : 0xffffffff (4294967295) access_mask : 0x00100081 (1048705) share_access : 0x00000007 (7) private_options : 0x00000000 (0) time : Mon Jun 5 16:22:32 2017 IDT.349235 id: struct file_id devid : 0x000000000000fd1c (64796) inode : 0x0000000000000080 (128) extid : 0x0000000000000000 (0) share_file_id : 0x000000005b30c763 (1529923427) uid : 0x0000fffe (65534) flags : 0x0000 (0) name_hash : 0xd7088907 (3607660807) stale : 0x00 (0) lease : NULL share_modes: struct share_mode_entry pid: struct server_id pid : 0x0000000000000b3d (2877) task_id : 0x00000000 (0) vnn : 0xffffffff (4294967295) unique_id : 0x27330f1f08b45cf6 (2824618017255873782) op_mid : 0x000000000000000b (11) op_type : 0x0000 (0) lease_idx : 0xffffffff (4294967295) access_mask : 0x00100080 (1048704) share_access : 0x00000000 (0) private_options : 0x00000000 (0) time : Mon Jun 5 16:22:32 2017 IDT.373882 id: struct file_id devid : 0x000000000000fd1c (64796) inode : 0x0000000000000080 (128) extid : 0x0000000000000000 (0) share_file_id : 0x0000000068f82785 (1761093509) uid : 0x0000fffe (65534) flags : 0x0000 (0) name_hash : 0xd7088907 (3607660807) stale : 0x00 (0) lease : NULL num_leases : 0x00000000 (0) leases: ARRAY(0) num_delete_tokens : 0x00000000 (0) delete_tokens: ARRAY(0) old_write_time : Thu Jan 1 02:00:00 1970 IST.0 changed_write_time : Thu Jan 1 02:00:00 1970 IST.0 fresh : 0x00 (0) modified : 0x01 (1) record : * id: struct file_id devid : 0x000000000000fd1c (64796) inode : 0x0000000000000080 (128) extid : 0x0000000000000000 (0) [2017/06/05 16:22:32.377707, 10, pid=2877, effective(65534, 65534), real(65534, 0), class=locking] ../source3/locking/share_mode_lock.c:155(share_mode_memcache_delete) deleting entry for file . seq 0x13501076290392828597 key fd1c:80:0 [2017/06/05 16:22:32.377856, 5, pid=2877, effective(65534, 65534), real(65534, 0)] ../lib/dbwrap/dbwrap.c:127(dbwrap_lock_order_state_destructor) release lock order 1 for /var/lock/samba/locking.tdb [2017/06/05 16:22:32.377902, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../lib/dbwrap/dbwrap.c:114(debug_lock_order) lock order: 1: 2: 3: [2017/06/05 16:22:32.378033, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../lib/dbwrap/dbwrap_tdb.c:59(db_tdb_log_key) Unlocking key 1CFD0000000000008000 [2017/06/05 16:22:32.378172, 10, pid=2877, effective(65534, 65534), real(65534, 0), class=locking] ../source3/locking/share_mode_lock.c:169(share_mode_memcache_store) stored entry for file . seq 0x13501076290392828598 key fd1c:80:0 [2017/06/05 16:22:32.378224, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/open.c:5322(create_file_unixpath) create_file_unixpath: info=1 [2017/06/05 16:22:32.378261, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/open.c:5603(create_file_default) create_file: info=1 [2017/06/05 16:22:32.378309, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/smb2_create.c:1188(smbd_smb2_create_send) smbd_smb2_create_send: response construction phase [2017/06/05 16:22:32.378341, 10, pid=2877, effective(65534, 65534), real(65534, 0), class=acls] ../source3/smbd/posix_acls.c:3560(posix_get_nt_acl) posix_get_nt_acl: called for file . [2017/06/05 16:22:32.378464, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/passdb/lookup_sid.c:1251(uid_to_sid) uid 0 -> sid S-1-22-1-0 [2017/06/05 16:22:32.378524, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/passdb/lookup_sid.c:1300(gid_to_sid) gid 0 -> sid S-1-22-2-0 [2017/06/05 16:22:32.378657, 10, pid=2877, effective(65534, 65534), real(65534, 0), class=acls] ../source3/smbd/posix_acls.c:2724(canonicalise_acl) canonicalise_acl: Access ace entries before arrange : [2017/06/05 16:22:32.378797, 10, pid=2877, effective(65534, 65534), real(65534, 0), class=acls] ../source3/smbd/posix_acls.c:2737(canonicalise_acl) canon_ace index 0. Type = allow SID = S-1-1-0 other SMB_ACL_OTHER ace_flags = 0x0 perms rwx [2017/06/05 16:22:32.378851, 10, pid=2877, effective(65534, 65534), real(65534, 0), class=acls] ../source3/smbd/posix_acls.c:2737(canonicalise_acl) canon_ace index 1. Type = allow SID = S-1-22-2-0 gid 0 (root) SMB_ACL_GROUP_OBJ ace_flags = 0x0 perms rwx [2017/06/05 16:22:32.379083, 10, pid=2877, effective(65534, 65534), real(65534, 0), class=acls] ../source3/smbd/posix_acls.c:2737(canonicalise_acl) canon_ace index 2. Type = allow SID = S-1-22-1-0 uid 0 (root) SMB_ACL_USER_OBJ ace_flags = 0x0 perms rwx [2017/06/05 16:22:32.379184, 10, pid=2877, effective(65534, 65534), real(65534, 0), class=acls] ../source3/smbd/posix_acls.c:848(print_canon_ace_list) print_canon_ace_list: canonicalise_acl: ace entries after arrange canon_ace index 0. Type = allow SID = S-1-22-1-0 uid 0 (root) SMB_ACL_USER_OBJ ace_flags = 0x0 perms rwx canon_ace index 1. Type = allow SID = S-1-22-2-0 gid 0 (root) SMB_ACL_GROUP_OBJ ace_flags = 0x0 perms rwx canon_ace index 2. Type = allow SID = S-1-1-0 other SMB_ACL_OTHER ace_flags = 0x0 perms rwx [2017/06/05 16:22:32.379428, 10, pid=2877, effective(65534, 65534), real(65534, 0), class=acls] ../source3/smbd/posix_acls.c:1110(map_canon_ace_perms) map_canon_ace_perms: Mapped (UNIX) 1c0 to (NT) 1f01ff [2017/06/05 16:22:32.379472, 10, pid=2877, effective(65534, 65534), real(65534, 0), class=acls] ../source3/smbd/posix_acls.c:1110(map_canon_ace_perms) map_canon_ace_perms: Mapped (UNIX) 1c0 to (NT) 1f01ff [2017/06/05 16:22:32.379502, 10, pid=2877, effective(65534, 65534), real(65534, 0), class=acls] ../source3/smbd/posix_acls.c:1110(map_canon_ace_perms) map_canon_ace_perms: Mapped (UNIX) 1c0 to (NT) 1f01ff [2017/06/05 16:22:32.379622, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../libcli/security/access_check.c:188(se_access_check) se_access_check: MAX desired = 0x2000000, granted = 0x1f01ff, remaining = 0x1f01ff [2017/06/05 16:22:32.379717, 0, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/smb2_create.c:1352(smbd_smb2_create_send) smbd_smb2_create_send: smb2req->compat_chain_fsp=0x7f38ed3b9960 [2017/06/05 16:22:32.379930, 8, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/dosmode.c:611(dos_mode) dos_mode: . [2017/06/05 16:22:32.379966, 5, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/dosmode.c:70(dos_mode_debug_print) dos_mode_debug_print: dos_mode_from_sbuf returning (0x10): "d" [2017/06/05 16:22:32.380024, 8, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/lib/util.c:1009(is_in_path) is_in_path: . [2017/06/05 16:22:32.380060, 8, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/lib/util.c:1033(is_in_path) is_in_path: match not found [2017/06/05 16:22:32.380084, 5, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/dosmode.c:70(dos_mode_debug_print) dos_mode_debug_print: dos_mode returning (0x10): "d" [2017/06/05 16:22:32.380124, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/smb2_create.c:1397(smbd_smb2_create_send) smbd_smb2_create_send: . - fnum 2949980029 [2017/06/05 16:22:32.380210, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/smb2_server.c:3014(smbd_smb2_request_done_ex) smbd_smb2_request_done_ex: idx[1] status[NT_STATUS_OK] body[88] dyn[yes:32] at ../source3/smbd/smb2_create.c:364 [2017/06/05 16:22:32.380278, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/smb2_server.c:2982(smbd_smb2_request_dispatch_immediate) smbd_smb2_request_dispatch_immediate: idx[5] of 9 vectors req->in.vector[0].iov_len = 0 req->in.vector[1].iov_len = 0 req->in.vector[2].iov_len = 64 req->in.vector[3].iov_len = 56 req->in.vector[4].iov_len = 32 req->in.vector[5].iov_len = 0 req->in.vector[6].iov_len = 64 req->in.vector[7].iov_len = 40 req->in.vector[8].iov_len = 0 req->out.vector[0].iov_len = 4 req->out.vector[1].iov_len = 0 req->out.vector[2].iov_len = 64 req->out.vector[3].iov_len = 88 req->out.vector[4].iov_len = 32 req->out.vector[5].iov_len = 0 req->out.vector[6].iov_len = 64 req->out.vector[7].iov_len = 8 req->out.vector[8].iov_len = 0 [2017/06/05 16:22:32.380633, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/smb2_server.c:2272(smbd_smb2_request_dispatch) smbd_smb2_request_dispatch: opcode[SMB2_OP_GETINFO] mid = 12 [2017/06/05 16:22:32.380680, 4, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/uid.c:384(change_to_user) Skipping user change - already user [2017/06/05 16:22:32.380732, 0, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/smb2_server.c:2145(smbd_smb2_request_dispatch_update_counts) smbd_smb2_request_dispatch_update_counts: compat_chain_fsp=0x7f38ed3b9960 [2017/06/05 16:22:32.380901, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/smb2_server.c:1955(smbd_smb2_request_verify_creditcharge) mid 12, CreditCharge: 1, NeededCharge: 1 [2017/06/05 16:22:32.380939, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/smb2_getinfo.c:272(smbd_smb2_getinfo_send) smbd_smb2_getinfo_send: . - fnum 2949980029 [2017/06/05 16:22:32.381018, 3, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/trans2.c:3422(smbd_do_qfsinfo) smbd_do_qfsinfo: level = 1007 [2017/06/05 16:22:32.381545, 10, pid=2877, effective(65534, 65534), real(65534, 0), class=quota] ../source3/lib/sysquotas.c:466(sys_get_quota) sys_get_quota() uid(65534, 65534), fs(xfs) [2017/06/05 16:22:32.381596, 10, pid=2877, effective(65534, 65534), real(65534, 0), class=quota] ../source3/lib/sysquotas_xfs.c:121(sys_get_xfs_quota) sys_get_xfs_quota: path[/export/vol1] bdev[/dev/dm-28] SMB_USER_FS_QUOTA_TYPE (uid[4294967295]) [2017/06/05 16:22:32.381636, 10, pid=2877, effective(65534, 65534), real(65534, 0), class=quota] ../source3/lib/sysquotas.c:476(sys_get_quota) sys_get_xfs_quota() called for mntpath[/export/vol1] bdev[/dev/dm-28] qtype[1] id[-1]. [2017/06/05 16:22:32.381910, 10, pid=2877, effective(65534, 65534), real(65534, 0), class=quota] ../source3/lib/sysquotas.c:466(sys_get_quota) sys_get_quota() uid(65534, 65534), fs(xfs) [2017/06/05 16:22:32.381957, 10, pid=2877, effective(65534, 65534), real(65534, 0), class=quota] ../source3/lib/sysquotas_xfs.c:138(sys_get_xfs_quota) sys_get_xfs_quota: path[/export/vol1] bdev[/dev/dm-28] SMB_GROUP_FS_QUOTA_TYPE (gid[4294967295]) [2017/06/05 16:22:32.382043, 10, pid=2877, effective(65534, 65534), real(65534, 0), class=quota] ../source3/lib/sysquotas.c:476(sys_get_quota) sys_get_xfs_quota() called for mntpath[/export/vol1] bdev[/dev/dm-28] qtype[3] id[-1]. [2017/06/05 16:22:32.382083, 5, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/trans2.c:3661(smbd_do_qfsinfo) smbd_do_qfsinfo : SMB_QUERY_FS_FULL_SIZE_INFO bsize=1024, cSectorUnit=2, cBytesSector=512, cUnitTotal=10475520, cUnitAvail=10442592 [2017/06/05 16:22:32.382183, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/smb2_server.c:3014(smbd_smb2_request_done_ex) smbd_smb2_request_done_ex: idx[5] status[NT_STATUS_OK] body[8] dyn[yes:32] at ../source3/smbd/smb2_getinfo.c:201 [2017/06/05 16:22:32.382223, 0, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/smb2_server.c:2717(smbd_smb2_request_reply_update_counts) smbd_smb2_request_reply_update_counts: compat_chain_fsp=0x7f38ed3b9960 [2017/06/05 16:22:32.382388, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/smb2_server.c:925(smb2_set_operation_credit) smb2_set_operation_credit: requested 1, charge 1, granted 1, current possible/max 483/512, total granted/max/low/range 30/8192/13/30 [2017/06/05 16:22:32.382425, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/smb2_server.c:925(smb2_set_operation_credit) smb2_set_operation_credit: requested 1, charge 1, granted 1, current possible/max 482/512, total granted/max/low/range 31/8192/13/31 [2017/06/05 16:22:32.400406, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/smb2_server.c:3912(smbd_smb2_io_handler) smbd_smb2_request idx[1] of 5 vectors [2017/06/05 16:22:32.400456, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/smb2_server.c:673(smb2_validate_sequence_number) smb2_validate_sequence_number: clearing id 13 (position 13) from bitmap [2017/06/05 16:22:32.400488, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/smb2_server.c:2272(smbd_smb2_request_dispatch) smbd_smb2_request_dispatch: opcode[SMB2_OP_GETINFO] mid = 13 [2017/06/05 16:22:32.400522, 4, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/uid.c:384(change_to_user) Skipping user change - already user [2017/06/05 16:22:32.400564, 0, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/files.c:697(file_fsp_smb2) file_fsp_smb2: smb2req->compat_chain_fsp=(nil) [2017/06/05 16:22:32.400826, 0, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/smb2_server.c:2145(smbd_smb2_request_dispatch_update_counts) smbd_smb2_request_dispatch_update_counts: compat_chain_fsp=0x7f38ed3b9960 [2017/06/05 16:22:32.401060, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/smb2_server.c:1955(smbd_smb2_request_verify_creditcharge) mid 13, CreditCharge: 1, NeededCharge: 1 [2017/06/05 16:22:32.401099, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/smb2_getinfo.c:272(smbd_smb2_getinfo_send) smbd_smb2_getinfo_send: . - fnum 2949980029 [2017/06/05 16:22:32.401140, 3, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/trans2.c:3422(smbd_do_qfsinfo) smbd_do_qfsinfo: level = 1007 [2017/06/05 16:22:32.401770, 10, pid=2877, effective(65534, 65534), real(65534, 0), class=quota] ../source3/lib/sysquotas.c:466(sys_get_quota) sys_get_quota() uid(65534, 65534), fs(xfs) [2017/06/05 16:22:32.401847, 10, pid=2877, effective(65534, 65534), real(65534, 0), class=quota] ../source3/lib/sysquotas_xfs.c:121(sys_get_xfs_quota) sys_get_xfs_quota: path[/export/vol1] bdev[/dev/dm-28] SMB_USER_FS_QUOTA_TYPE (uid[4294967295]) [2017/06/05 16:22:32.401884, 10, pid=2877, effective(65534, 65534), real(65534, 0), class=quota] ../source3/lib/sysquotas.c:476(sys_get_quota) sys_get_xfs_quota() called for mntpath[/export/vol1] bdev[/dev/dm-28] qtype[1] id[-1]. [2017/06/05 16:22:32.402198, 10, pid=2877, effective(65534, 65534), real(65534, 0), class=quota] ../source3/lib/sysquotas.c:466(sys_get_quota) sys_get_quota() uid(65534, 65534), fs(xfs) [2017/06/05 16:22:32.402251, 10, pid=2877, effective(65534, 65534), real(65534, 0), class=quota] ../source3/lib/sysquotas_xfs.c:138(sys_get_xfs_quota) sys_get_xfs_quota: path[/export/vol1] bdev[/dev/dm-28] SMB_GROUP_FS_QUOTA_TYPE (gid[4294967295]) [2017/06/05 16:22:32.402286, 10, pid=2877, effective(65534, 65534), real(65534, 0), class=quota] ../source3/lib/sysquotas.c:476(sys_get_quota) sys_get_xfs_quota() called for mntpath[/export/vol1] bdev[/dev/dm-28] qtype[3] id[-1]. [2017/06/05 16:22:32.402369, 5, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/trans2.c:3661(smbd_do_qfsinfo) smbd_do_qfsinfo : SMB_QUERY_FS_FULL_SIZE_INFO bsize=1024, cSectorUnit=2, cBytesSector=512, cUnitTotal=10475520, cUnitAvail=10442592 [2017/06/05 16:22:32.402413, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/smb2_server.c:3014(smbd_smb2_request_done_ex) smbd_smb2_request_done_ex: idx[1] status[NT_STATUS_OK] body[8] dyn[yes:32] at ../source3/smbd/smb2_getinfo.c:201 [2017/06/05 16:22:32.402452, 0, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/smb2_server.c:2717(smbd_smb2_request_reply_update_counts) smbd_smb2_request_reply_update_counts: compat_chain_fsp=0x7f38ed3b9960 [2017/06/05 16:22:32.402626, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/smb2_server.c:925(smb2_set_operation_credit) smb2_set_operation_credit: requested 1, charge 1, granted 1, current possible/max 482/512, total granted/max/low/range 31/8192/14/31 [2017/06/05 16:22:42.005403, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/lib/messages.c:152(messaging_recv_cb) messaging_recv_cb: Received message 0x302 len 5 (num_fds:0) from 3162 [2017/06/05 16:22:42.005483, 1, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/conn_idle.c:120(conn_force_tdis) conn_force_tdis: Forcing close of share 'vol1' (wire_id=0xe394d695) [2017/06/05 16:22:42.005520, 5, pid=2877, effective(65534, 65534), real(65534, 0)] ../lib/dbwrap/dbwrap.c:159(dbwrap_check_lock_order) check lock order 1 for /var/lock/samba/smbXsrv_tcon_global.tdb [2017/06/05 16:22:42.005601, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../lib/dbwrap/dbwrap.c:114(debug_lock_order) lock order: 1:/var/lock/samba/smbXsrv_tcon_global.tdb 2: 3: [2017/06/05 16:22:42.005648, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../lib/dbwrap/dbwrap_tdb.c:59(db_tdb_log_key) Locking key E394D695 [2017/06/05 16:22:42.005687, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../lib/dbwrap/dbwrap_tdb.c:143(db_tdb_fetch_locked_internal) Allocated locked data 0x0x7f38ed3bb540 [2017/06/05 16:22:42.005734, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../lib/dbwrap/dbwrap_tdb.c:59(db_tdb_log_key) Unlocking key E394D695 [2017/06/05 16:22:42.005781, 5, pid=2877, effective(65534, 65534), real(65534, 0)] ../lib/dbwrap/dbwrap.c:127(dbwrap_lock_order_state_destructor) release lock order 1 for /var/lock/samba/smbXsrv_tcon_global.tdb [2017/06/05 16:22:42.005812, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../lib/dbwrap/dbwrap.c:114(debug_lock_order) lock order: 1: 2: 3: [2017/06/05 16:22:42.005859, 5, pid=2877, effective(65534, 65534), real(65534, 0)] ../lib/dbwrap/dbwrap.c:159(dbwrap_check_lock_order) check lock order 1 for /var/lock/samba/locking.tdb [2017/06/05 16:22:42.005902, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../lib/dbwrap/dbwrap.c:114(debug_lock_order) lock order: 1:/var/lock/samba/locking.tdb 2: 3: [2017/06/05 16:22:42.005940, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../lib/dbwrap/dbwrap_tdb.c:59(db_tdb_log_key) Locking key 1CFD0000000000008000 [2017/06/05 16:22:42.006003, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../lib/dbwrap/dbwrap_tdb.c:143(db_tdb_fetch_locked_internal) Allocated locked data 0x0x7f38ed3c1d40 [2017/06/05 16:22:42.006051, 10, pid=2877, effective(65534, 65534), real(65534, 0), class=locking] ../source3/locking/share_mode_lock.c:283(share_mode_memcache_fetch) fetched entry for file . seq 0x13501076290392828598 key fd1c:80:0 [2017/06/05 16:22:42.006089, 10, pid=2877, effective(65534, 65534), real(65534, 0), class=locking] ../source3/locking/locking.c:1229(find_delete_on_close_token) find_delete_on_close_token: name_hash = 0xd7088907 [2017/06/05 16:22:42.006120, 10, pid=2877, effective(65534, 65534), real(65534, 0), class=locking] ../source3/locking/share_mode_lock.c:366(unparse_share_modes) unparse_share_modes: [2017/06/05 16:22:42.006163, 1, pid=2877, effective(65534, 65534), real(65534, 0)] ../librpc/ndr/ndr.c:413(ndr_print_debug) d: struct share_mode_data sequence_number : 0xbb5d755ab6502ab6 (-4945667783316723018) servicepath : * servicepath : '/export/vol1' base_name : * base_name : '.' stream_name : NULL num_share_modes : 0x00000001 (1) share_modes: ARRAY(1) share_modes: struct share_mode_entry pid: struct server_id pid : 0x0000000000000b3d (2877) task_id : 0x00000000 (0) vnn : 0xffffffff (4294967295) unique_id : 0x27330f1f08b45cf6 (2824618017255873782) op_mid : 0x0000000000000008 (8) op_type : 0x0000 (0) lease_idx : 0xffffffff (4294967295) access_mask : 0x00100081 (1048705) share_access : 0x00000007 (7) private_options : 0x00000000 (0) time : Mon Jun 5 16:22:32 2017 IDT.349235 id: struct file_id devid : 0x000000000000fd1c (64796) inode : 0x0000000000000080 (128) extid : 0x0000000000000000 (0) share_file_id : 0x000000005b30c763 (1529923427) uid : 0x0000fffe (65534) flags : 0x0000 (0) name_hash : 0xd7088907 (3607660807) stale : 0x00 (0) lease : NULL num_leases : 0x00000000 (0) leases: ARRAY(0) num_delete_tokens : 0x00000000 (0) delete_tokens: ARRAY(0) old_write_time : Thu Jan 1 02:00:00 1970 IST.0 changed_write_time : Thu Jan 1 02:00:00 1970 IST.0 fresh : 0x00 (0) modified : 0x01 (1) record : * id: struct file_id devid : 0x000000000000fd1c (64796) inode : 0x0000000000000080 (128) extid : 0x0000000000000000 (0) [2017/06/05 16:22:42.006960, 10, pid=2877, effective(65534, 65534), real(65534, 0), class=locking] ../source3/locking/share_mode_lock.c:155(share_mode_memcache_delete) deleting entry for file . seq 0x13501076290392828598 key fd1c:80:0 [2017/06/05 16:22:42.007070, 5, pid=2877, effective(65534, 65534), real(65534, 0)] ../lib/dbwrap/dbwrap.c:127(dbwrap_lock_order_state_destructor) release lock order 1 for /var/lock/samba/locking.tdb [2017/06/05 16:22:42.007143, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../lib/dbwrap/dbwrap.c:114(debug_lock_order) lock order: 1: 2: 3: [2017/06/05 16:22:42.007185, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../lib/dbwrap/dbwrap_tdb.c:59(db_tdb_log_key) Unlocking key 1CFD0000000000008000 [2017/06/05 16:22:42.007227, 10, pid=2877, effective(65534, 65534), real(65534, 0), class=locking] ../source3/locking/share_mode_lock.c:169(share_mode_memcache_store) stored entry for file . seq 0x13501076290392828599 key fd1c:80:0 [2017/06/05 16:22:42.007271, 5, pid=2877, effective(65534, 65534), real(65534, 0)] ../lib/dbwrap/dbwrap.c:159(dbwrap_check_lock_order) check lock order 1 for /var/lock/samba/smbXsrv_open_global.tdb [2017/06/05 16:22:42.007299, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../lib/dbwrap/dbwrap.c:114(debug_lock_order) lock order: 1:/var/lock/samba/smbXsrv_open_global.tdb 2: 3: [2017/06/05 16:22:42.007342, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../lib/dbwrap/dbwrap_tdb.c:59(db_tdb_log_key) Locking key C86CD68C [2017/06/05 16:22:42.007376, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../lib/dbwrap/dbwrap_tdb.c:143(db_tdb_fetch_locked_internal) Allocated locked data 0x0x7f38ed382ca0 [2017/06/05 16:22:42.007418, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../lib/dbwrap/dbwrap_tdb.c:59(db_tdb_log_key) Unlocking key C86CD68C [2017/06/05 16:22:42.007447, 5, pid=2877, effective(65534, 65534), real(65534, 0)] ../lib/dbwrap/dbwrap.c:127(dbwrap_lock_order_state_destructor) release lock order 1 for /var/lock/samba/smbXsrv_open_global.tdb [2017/06/05 16:22:42.007476, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../lib/dbwrap/dbwrap.c:114(debug_lock_order) lock order: 1: 2: 3: [2017/06/05 16:22:42.007518, 0, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/files.c:513(fsp_free) fsp_free(fsp=0x7f38ed3b9960) [2017/06/05 16:22:42.008446, 5, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/files.c:570(file_free) freed files structure 2949980029 (1 used) [2017/06/05 16:22:42.008503, 5, pid=2877, effective(65534, 65534), real(65534, 0)] ../lib/dbwrap/dbwrap.c:159(dbwrap_check_lock_order) check lock order 1 for /var/lock/samba/locking.tdb [2017/06/05 16:22:42.008535, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../lib/dbwrap/dbwrap.c:114(debug_lock_order) lock order: 1:/var/lock/samba/locking.tdb 2: 3: [2017/06/05 16:22:42.008602, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../lib/dbwrap/dbwrap_tdb.c:59(db_tdb_log_key) Locking key 1CFD0000000000008000 [2017/06/05 16:22:42.008766, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../lib/dbwrap/dbwrap_tdb.c:143(db_tdb_fetch_locked_internal) Allocated locked data 0x0x7f38ed3c23e0 [2017/06/05 16:22:42.008822, 10, pid=2877, effective(65534, 65534), real(65534, 0), class=locking] ../source3/locking/share_mode_lock.c:283(share_mode_memcache_fetch) fetched entry for file . seq 0x13501076290392828599 key fd1c:80:0 [2017/06/05 16:22:42.008934, 10, pid=2877, effective(65534, 65534), real(65534, 0), class=locking] ../source3/locking/locking.c:1229(find_delete_on_close_token) find_delete_on_close_token: name_hash = 0xd7088907 [2017/06/05 16:22:42.009012, 10, pid=2877, effective(65534, 65534), real(65534, 0), class=locking] ../source3/locking/share_mode_lock.c:366(unparse_share_modes) unparse_share_modes: [2017/06/05 16:22:42.009055, 1, pid=2877, effective(65534, 65534), real(65534, 0)] ../librpc/ndr/ndr.c:413(ndr_print_debug) d: struct share_mode_data sequence_number : 0xbb5d755ab6502ab7 (-4945667783316723017) servicepath : * servicepath : '/export/vol1' base_name : * base_name : '.' stream_name : NULL num_share_modes : 0x00000000 (0) share_modes: ARRAY(0) num_leases : 0x00000000 (0) leases: ARRAY(0) num_delete_tokens : 0x00000000 (0) delete_tokens: ARRAY(0) old_write_time : Thu Jan 1 02:00:00 1970 IST.0 changed_write_time : Thu Jan 1 02:00:00 1970 IST.0 fresh : 0x00 (0) modified : 0x01 (1) record : * id: struct file_id devid : 0x000000000000fd1c (64796) inode : 0x0000000000000080 (128) extid : 0x0000000000000000 (0) [2017/06/05 16:22:42.009402, 10, pid=2877, effective(65534, 65534), real(65534, 0), class=locking] ../source3/locking/share_mode_lock.c:155(share_mode_memcache_delete) deleting entry for file . seq 0x13501076290392828599 key fd1c:80:0 [2017/06/05 16:22:42.009463, 10, pid=2877, effective(65534, 65534), real(65534, 0), class=locking] ../source3/locking/share_mode_lock.c:378(unparse_share_modes) No used share mode found [2017/06/05 16:22:42.009511, 5, pid=2877, effective(65534, 65534), real(65534, 0)] ../lib/dbwrap/dbwrap.c:127(dbwrap_lock_order_state_destructor) release lock order 1 for /var/lock/samba/locking.tdb [2017/06/05 16:22:42.009595, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../lib/dbwrap/dbwrap.c:114(debug_lock_order) lock order: 1: 2: 3: [2017/06/05 16:22:42.009646, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../lib/dbwrap/dbwrap_tdb.c:59(db_tdb_log_key) Unlocking key 1CFD0000000000008000 [2017/06/05 16:22:42.009715, 10, pid=2877, effective(65534, 65534), real(65534, 0), class=locking] ../source3/locking/posix.c:498(delete_lock_ref_count) delete_lock_ref_count for file . [2017/06/05 16:22:42.009777, 4, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/sec_ctx.c:216(push_sec_ctx) push_sec_ctx(65534, 65534) : sec_ctx_stack_ndx = 1 [2017/06/05 16:22:42.009824, 4, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/uid.c:491(push_conn_ctx) push_conn_ctx(1512126538) : conn_ctx_stack_ndx = 0 [2017/06/05 16:22:42.009855, 4, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/sec_ctx.c:320(set_sec_ctx_internal) setting sec ctx (0, 0) - sec_ctx_stack_ndx = 1 [2017/06/05 16:22:42.009893, 5, pid=2877, effective(65534, 65534), real(65534, 0)] ../libcli/security/security_token.c:53(security_token_debug) Security token: (NULL) [2017/06/05 16:22:42.009932, 5, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/auth/token_util.c:639(debug_unix_user_token) UNIX token of user 0 Primary group is 0 and contains 0 supplementary groups [2017/06/05 16:22:42.010023, 10, pid=2877, effective(0, 0), real(0, 0)] ../source3/lib/messages_dgm.c:323(messaging_dgm_send) messaging_dgm_send: Sending message to 2602 [2017/06/05 16:22:42.010744, 4, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/sec_ctx.c:438(pop_sec_ctx) pop_sec_ctx (65534, 65534) - sec_ctx_stack_ndx = 0 [2017/06/05 16:22:42.010794, 5, pid=2877, effective(65534, 65534), real(65534, 0)] ../lib/dbwrap/dbwrap.c:159(dbwrap_check_lock_order) check lock order 1 for /var/lock/samba/smbXsrv_open_global.tdb [2017/06/05 16:22:42.010826, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../lib/dbwrap/dbwrap.c:114(debug_lock_order) lock order: 1:/var/lock/samba/smbXsrv_open_global.tdb 2: 3: [2017/06/05 16:22:42.010873, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../lib/dbwrap/dbwrap_tdb.c:59(db_tdb_log_key) Locking key C311E6B8 [2017/06/05 16:22:42.010914, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../lib/dbwrap/dbwrap_tdb.c:143(db_tdb_fetch_locked_internal) Allocated locked data 0x0x7f38ed382ca0 [2017/06/05 16:22:42.010998, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../lib/dbwrap/dbwrap_tdb.c:59(db_tdb_log_key) Unlocking key C311E6B8 [2017/06/05 16:22:42.011049, 5, pid=2877, effective(65534, 65534), real(65534, 0)] ../lib/dbwrap/dbwrap.c:127(dbwrap_lock_order_state_destructor) release lock order 1 for /var/lock/samba/smbXsrv_open_global.tdb [2017/06/05 16:22:42.011091, 10, pid=2877, effective(65534, 65534), real(65534, 0)] ../lib/dbwrap/dbwrap.c:114(debug_lock_order) lock order: 1: 2: 3: [2017/06/05 16:22:42.011140, 0, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/files.c:513(fsp_free) fsp_free(fsp=0x7f38ed3ba6f0) [2017/06/05 16:22:42.011626, 5, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/files.c:570(file_free) freed files structure 111888149 (0 used) [2017/06/05 16:22:42.011680, 4, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/smbd/sec_ctx.c:320(set_sec_ctx_internal) setting sec ctx (0, 0) - sec_ctx_stack_ndx = 0 [2017/06/05 16:22:42.011795, 5, pid=2877, effective(65534, 65534), real(65534, 0)] ../libcli/security/security_token.c:53(security_token_debug) Security token: (NULL) [2017/06/05 16:22:42.011851, 5, pid=2877, effective(65534, 65534), real(65534, 0)] ../source3/auth/token_util.c:639(debug_unix_user_token) UNIX token of user 0 Primary group is 0 and contains 0 supplementary groups [2017/06/05 16:22:42.011917, 5, pid=2877, effective(0, 0), real(0, 0)] ../source3/smbd/uid.c:425(smbd_change_to_root_user) change_to_root_user: now uid=(0,0) gid=(0,0) [2017/06/05 16:22:42.011961, 2, pid=2877, effective(0, 0), real(0, 0)] ../source3/smbd/service.c:1144(close_cnum) vm21-win2012se (ipv4:170.70.2.21:54923) closed connection to service vol1 [2017/06/05 16:22:42.012054, 4, pid=2877, effective(0, 0), real(0, 0), class=vfs] ../source3/smbd/vfs.c:874(vfs_ChDir) vfs_ChDir to / [2017/06/05 16:22:42.012116, 4, pid=2877, effective(0, 0), real(0, 0), class=vfs] ../source3/smbd/vfs.c:885(vfs_ChDir) vfs_ChDir got / [2017/06/05 16:22:42.012166, 4, pid=2877, effective(0, 0), real(0, 0)] ../source3/smbd/sec_ctx.c:320(set_sec_ctx_internal) setting sec ctx (0, 0) - sec_ctx_stack_ndx = 0 [2017/06/05 16:22:42.012197, 5, pid=2877, effective(0, 0), real(0, 0)] ../libcli/security/security_token.c:53(security_token_debug) Security token: (NULL) [2017/06/05 16:22:42.012282, 5, pid=2877, effective(0, 0), real(0, 0)] ../source3/auth/token_util.c:639(debug_unix_user_token) UNIX token of user 0 Primary group is 0 and contains 0 supplementary groups [2017/06/05 16:22:42.012335, 5, pid=2877, effective(0, 0), real(0, 0)] ../source3/smbd/uid.c:425(smbd_change_to_root_user) change_to_root_user: now uid=(0,0) gid=(0,0) [2017/06/05 16:22:42.018515, 4, pid=2877, effective(0, 0), real(0, 0)] ../source3/smbd/sec_ctx.c:320(set_sec_ctx_internal) setting sec ctx (0, 0) - sec_ctx_stack_ndx = 0 [2017/06/05 16:22:42.018586, 5, pid=2877, effective(0, 0), real(0, 0)] ../libcli/security/security_token.c:53(security_token_debug) Security token: (NULL) [2017/06/05 16:22:42.018615, 5, pid=2877, effective(0, 0), real(0, 0)] ../source3/auth/token_util.c:639(debug_unix_user_token) UNIX token of user 0 Primary group is 0 and contains 0 supplementary groups [2017/06/05 16:22:42.018681, 5, pid=2877, effective(0, 0), real(0, 0)] ../source3/smbd/uid.c:425(smbd_change_to_root_user) change_to_root_user: now uid=(0,0) gid=(0,0) [2017/06/05 16:22:42.018771, 6, pid=2877, effective(0, 0), real(0, 0)] ../source3/param/loadparm.c:2229(lp_file_list_changed) lp_file_list_changed() file /etc/samba/smb.conf -> /etc/samba/smb.conf last mod_time: Mon Jun 5 14:14:33 2017 [2017/06/05 16:22:42.018911, 0, pid=2877, effective(0, 0), real(0, 0)] ../source3/smbd/smb2_notify.c:118(smbd_smb2_request_notify_done) smbd_smb2_request_notify_done: req->compat_chain_fsp=0x7f38ed3ba6f0 [2017/06/05 16:22:42.019636, 3, pid=2877, effective(0, 0), real(0, 0)] ../source3/smbd/smb2_server.c:3132(smbd_smb2_request_error_ex) smbd_smb2_request_error_ex: smbd_smb2_request_error_ex: idx[1] status[STATUS_NOTIFY_CLEANUP] || at ../source3/smbd/smb2_notify.c:125 [2017/06/05 16:22:42.019732, 10, pid=2877, effective(0, 0), real(0, 0)] ../source3/smbd/smb2_server.c:3014(smbd_smb2_request_done_ex) smbd_smb2_request_done_ex: idx[1] status[STATUS_NOTIFY_CLEANUP] body[8] dyn[yes:1] at ../source3/smbd/smb2_server.c:3189 [2017/06/05 16:22:42.019811, 0, pid=2877, effective(0, 0), real(0, 0)] ../source3/smbd/smb2_server.c:2717(smbd_smb2_request_reply_update_counts) smbd_smb2_request_reply_update_counts: compat_chain_fsp=0x7f38ed3ba6f0 [2017/06/05 16:22:42.020173, 0, pid=2877, effective(0, 0), real(0, 0)] ../lib/util/fault.c:78(fault_report) =============================================================== [2017/06/05 16:22:42.020853, 0, pid=2877, effective(0, 0), real(0, 0)] ../lib/util/fault.c:79(fault_report) INTERNAL ERROR: Signal 11 in pid 2877 (4.5.10) Please read the Trouble-Shooting section of the Samba HOWTO [2017/06/05 16:22:42.021481, 0, pid=2877, effective(0, 0), real(0, 0)] ../lib/util/fault.c:81(fault_report) =============================================================== [2017/06/05 16:22:42.021992, 0, pid=2877, effective(0, 0), real(0, 0)] ../source3/lib/util.c:791(smb_panic_s3) PANIC (pid 2877): internal error [2017/06/05 16:22:42.023094, 0, pid=2877, effective(0, 0), real(0, 0)] ../source3/lib/util.c:910(log_stack_trace) BACKTRACE: 34 stack frames: #0 /usr/lib/libsmbconf.so.0(log_stack_trace+0x1f) [0x7f38e855f4b9] #1 /usr/lib/libsmbconf.so.0(smb_panic_s3+0x70) [0x7f38e855f2ef] #2 /usr/lib/libsamba-util.so.0(smb_panic+0x28) [0x7f38eb04814d] #3 /usr/lib/libsamba-util.so.0(+0x21e25) [0x7f38eb047e25] #4 /usr/lib/libsamba-util.so.0(+0x21e3a) [0x7f38eb047e3a] #5 /lib/x86_64-linux-gnu/libpthread.so.0(+0x10330) [0x7f38eb2b4330] #6 /usr/lib/samba/libsmbd-base-samba4.so(+0x1a6bf1) [0x7f38eabb7bf1] #7 /usr/lib/samba/libsmbd-base-samba4.so(+0x1a6e50) [0x7f38eabb7e50] #8 /usr/lib/samba/libsmbd-base-samba4.so(smbd_smb2_request_done_ex+0x622) [0x7f38eabb9638] #9 /usr/lib/samba/libsmbd-base-samba4.so(smbd_smb2_request_error_ex+0x2f4) [0x7f38eabb993a] #10 /usr/lib/samba/libsmbd-base-samba4.so(+0x1c9205) [0x7f38eabda205] #11 /usr/lib/samba/libtevent.so.0(_tevent_req_notify_callback+0x6a) [0x7f38e9ff0367] #12 /usr/lib/samba/libtevent.so.0(+0x643a) [0x7f38e9ff043a] #13 /usr/lib/samba/libtevent.so.0(+0x655f) [0x7f38e9ff055f] #14 /usr/lib/samba/libtevent.so.0(tevent_common_loop_immediate+0x1f5) [0x7f38e9fef77c] #15 /usr/lib/samba/libtevent.so.0(+0xe19a) [0x7f38e9ff819a] #16 /usr/lib/samba/libtevent.so.0(+0xb11e) [0x7f38e9ff511e] #17 /usr/lib/samba/libtevent.so.0(_tevent_loop_once+0xf4) [0x7f38e9fee8c3] #18 /usr/lib/samba/libtevent.so.0(tevent_common_loop_wait+0x25) [0x7f38e9feeb0d] #19 /usr/lib/samba/libtevent.so.0(+0xb1c0) [0x7f38e9ff51c0] #20 /usr/lib/samba/libtevent.so.0(_tevent_loop_wait+0x2b) [0x7f38e9feebd8] #21 /usr/lib/samba/libsmbd-base-samba4.so(smbd_process+0xc3b) [0x7f38eab99f34] #22 smbd(+0xdd16) [0x7f38eb906d16] #23 /usr/lib/samba/libtevent.so.0(+0xdc16) [0x7f38e9ff7c16] #24 /usr/lib/samba/libtevent.so.0(+0xe234) [0x7f38e9ff8234] #25 /usr/lib/samba/libtevent.so.0(+0xb11e) [0x7f38e9ff511e] #26 /usr/lib/samba/libtevent.so.0(_tevent_loop_once+0xf4) [0x7f38e9fee8c3] #27 /usr/lib/samba/libtevent.so.0(tevent_common_loop_wait+0x25) [0x7f38e9feeb0d] #28 /usr/lib/samba/libtevent.so.0(+0xb1c0) [0x7f38e9ff51c0] #29 /usr/lib/samba/libtevent.so.0(_tevent_loop_wait+0x2b) [0x7f38e9feebd8] #30 smbd(+0xeb26) [0x7f38eb907b26] #31 smbd(main+0x189c) [0x7f38eb909579] #32 /lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0xf5) [0x7f38e6e44f45] #33 smbd(+0x68b9) [0x7f38eb8ff8b9]