[2018/07/11 20:03:14.707487, 10, pid=6945, effective(0, 0), real(0, 0), class=smb2] ../source3/smbd/smb2_server.c:3934(smbd_smb2_io_handler) smbd_smb2_request idx[1] of 5 vectors [2018/07/11 20:03:14.707825, 10, pid=6945, effective(0, 0), real(0, 0), class=smb2_credits] ../source3/smbd/smb2_server.c:678(smb2_validate_sequence_number) smb2_validate_sequence_number: smb2_validate_sequence_number: clearing id 241 (position 241) from bitmap [2018/07/11 20:03:14.707972, 10, pid=6945, effective(0, 0), real(0, 0), class=smb2] ../source3/smbd/smb2_server.c:2327(smbd_smb2_request_dispatch) smbd_smb2_request_dispatch: opcode[SMB2_OP_CREATE] mid = 241 [2018/07/11 20:03:14.708126, 4, pid=6945, effective(0, 0), real(0, 0)] ../source3/smbd/sec_ctx.c:320(set_sec_ctx_internal) setting sec ctx (1000, 1000) - sec_ctx_stack_ndx = 0 [2018/07/11 20:03:14.708260, 5, pid=6945, effective(0, 0), real(0, 0)] ../libcli/security/security_token.c:63(security_token_debug) Security token SIDs (18): SID[ 0]: S-1-5-21-974925914-423971577-4012352237-1000 SID[ 1]: S-1-5-21-974925914-423971577-4012352237-513 SID[ 2]: S-1-22-2-1000 SID[ 3]: S-1-22-2-4 SID[ 4]: S-1-22-2-20 SID[ 5]: S-1-22-2-24 SID[ 6]: S-1-22-2-25 SID[ 7]: S-1-22-2-27 SID[ 8]: S-1-22-2-29 SID[ 9]: S-1-22-2-30 SID[ 10]: S-1-22-2-44 SID[ 11]: S-1-22-2-46 SID[ 12]: S-1-22-2-108 SID[ 13]: S-1-22-2-114 SID[ 14]: S-1-1-0 SID[ 15]: S-1-5-2 SID[ 16]: S-1-5-11 SID[ 17]: S-1-22-1-1000 Privileges (0x 0): Rights (0x 0): [2018/07/11 20:03:14.708903, 5, pid=6945, effective(0, 0), real(0, 0)] ../source3/auth/token_util.c:810(debug_unix_user_token) UNIX token of user 1000 Primary group is 1000 and contains 12 supplementary groups Group[ 0]: 1000 Group[ 1]: 4 Group[ 2]: 20 Group[ 3]: 24 Group[ 4]: 25 Group[ 5]: 27 Group[ 6]: 29 Group[ 7]: 30 Group[ 8]: 44 Group[ 9]: 46 Group[ 10]: 108 Group[ 11]: 114 [2018/07/11 20:03:14.709297, 5, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/smbd/uid.c:363(change_to_user_internal) Impersonated user: uid=(1000,1000), gid=(0,1000) [2018/07/11 20:03:14.709386, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=smb2] ../source3/smbd/smb2_create.c:652(smbd_smb2_create_send) smbd_smb2_create_send: name [] [2018/07/11 20:03:14.709461, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=smb2] ../source3/smbd/smb2_create.c:750(smbd_smb2_create_send) smbd_smb2_create_send: open execution phase [2018/07/11 20:03:14.709530, 5, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/smbd/filename.c:461(unix_convert) unix_convert called on file "" [2018/07/11 20:03:14.709687, 5, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/smbd/filename.c:495(unix_convert) conversion finished "" -> . [2018/07/11 20:03:14.709769, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=vfs] ../source3/smbd/vfs.c:1283(check_reduced_name) check_reduced_name: check_reduced_name [.] [/storage] [2018/07/11 20:03:14.709853, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=vfs] ../source3/smbd/vfs.c:1347(check_reduced_name) check_reduced_name realpath [.] -> [/storage] [2018/07/11 20:03:14.709926, 5, pid=6945, effective(1000, 1000), real(1000, 0), class=vfs] ../source3/smbd/vfs.c:1458(check_reduced_name) check_reduced_name: . reduced to /storage [2018/07/11 20:03:14.710000, 10, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:5554(create_file_default) create_file: access_mask = 0x81 file_attributes = 0x10, share_access = 0x3, create_disposition = 0x1 create_options = 0x1 oplock_request = 0x0 private_flags = 0x0 root_dir_fid = 0x0, ea_list = 0x(nil), sd = 0x(nil), fname = . [2018/07/11 20:03:14.710080, 10, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:5017(create_file_unixpath) create_file_unixpath: access_mask = 0x81 file_attributes = 0x10, share_access = 0x3, create_disposition = 0x1 create_options = 0x1 oplock_request = 0x0 private_flags = 0x0 ea_list = 0x(nil), sd = 0x(nil), fname = . [2018/07/11 20:03:14.710156, 5, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:3945(open_directory) open_directory: opening directory ., access_mask = 0x81, share_access = 0x3 create_options = 0x1, create_disposition = 0x1, file_attributes = 0x10 [2018/07/11 20:03:14.710234, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=acls] ../source3/smbd/posix_acls.c:3483(posix_get_nt_acl) posix_get_nt_acl: called for file . [2018/07/11 20:03:14.710380, 10, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/passdb/lookup_sid.c:1286(uid_to_sid) uid 1000 -> sid S-1-5-21-974925914-423971577-4012352237-1000 [2018/07/11 20:03:14.710471, 10, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/passdb/lookup_sid.c:1335(gid_to_sid) gid 1000 -> sid S-1-22-2-1000 [2018/07/11 20:03:14.710549, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=acls] ../source3/smbd/posix_acls.c:2726(canonicalise_acl) canonicalise_acl: Access ace entries before arrange : [2018/07/11 20:03:14.710619, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=acls] ../source3/smbd/posix_acls.c:2739(canonicalise_acl) canon_ace index 0. Type = allow SID = S-1-1-0 other SMB_ACL_OTHER ace_flags = 0x0 perms r-x [2018/07/11 20:03:14.710697, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=acls] ../source3/smbd/posix_acls.c:2739(canonicalise_acl) canon_ace index 1. Type = allow SID = S-1-22-2-1000 gid 1000 SMB_ACL_GROUP_OBJ ace_flags = 0x0 perms r-x [2018/07/11 20:03:14.710772, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=acls] ../source3/smbd/posix_acls.c:2739(canonicalise_acl) canon_ace index 2. Type = allow SID = S-1-5-21-974925914-423971577-4012352237-1000 uid 1000 SMB_ACL_USER_OBJ ace_flags = 0x0 perms rwx [2018/07/11 20:03:14.710850, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=acls] ../source3/smbd/posix_acls.c:847(print_canon_ace_list) print_canon_ace_list: canonicalise_acl: ace entries after arrange canon_ace index 0. Type = allow SID = S-1-5-21-974925914-423971577-4012352237-1000 uid 1000 SMB_ACL_USER_OBJ ace_flags = 0x0 perms rwx canon_ace index 1. Type = allow SID = S-1-22-2-1000 gid 1000 SMB_ACL_GROUP_OBJ ace_flags = 0x0 perms r-x canon_ace index 2. Type = allow SID = S-1-1-0 other SMB_ACL_OTHER ace_flags = 0x0 perms r-x [2018/07/11 20:03:14.711007, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=acls] ../source3/smbd/posix_acls.c:1111(map_canon_ace_perms) map_canon_ace_perms: Mapped (UNIX) 1c0 to (NT) 1f01ff [2018/07/11 20:03:14.711079, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=acls] ../source3/smbd/posix_acls.c:1111(map_canon_ace_perms) map_canon_ace_perms: Mapped (UNIX) 140 to (NT) 1200a9 [2018/07/11 20:03:14.711150, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=acls] ../source3/smbd/posix_acls.c:1111(map_canon_ace_perms) map_canon_ace_perms: Mapped (UNIX) 140 to (NT) 1200a9 [2018/07/11 20:03:14.711234, 10, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:183(smbd_check_access_rights) smbd_check_access_rights: file . requesting 0x81 returning 0x1 (NT_STATUS_OK) [2018/07/11 20:03:14.711322, 5, pid=6945, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap.c:130(dbwrap_lock_order_lock) dbwrap_lock_order_lock: check lock order 1 for /var/run/samba/smbXsrv_open_global.tdb [2018/07/11 20:03:14.711343, 10, pid=6945, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap.c:116(debug_lock_order) lock order: 1:/var/run/samba/smbXsrv_open_global.tdb 2: 3: [2018/07/11 20:03:14.711364, 10, pid=6945, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap_tdb.c:61(db_tdb_log_key) Locking key 0886D56E [2018/07/11 20:03:14.711385, 10, pid=6945, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap_tdb.c:145(db_tdb_fetch_locked_internal) Allocated locked data 0x0x564278559d70 [2018/07/11 20:03:14.711405, 10, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/smbd/smbXsrv_open.c:625(smbXsrv_open_global_verify_record) smbXsrv_open_global_verify_record: empty value [2018/07/11 20:03:14.711438, 10, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/smbd/smbXsrv_open.c:744(smbXsrv_open_global_store) smbXsrv_open_global_store: key '0886D56E' stored [2018/07/11 20:03:14.711459, 1, pid=6945, effective(1000, 1000), real(1000, 0), class=rpc_parse] ../librpc/ndr/ndr.c:422(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 : 0x0000000000001b21 (6945) task_id : 0x00000000 (0) vnn : 0xffffffff (4294967295) unique_id : 0xce186dd40ec2e45f (-3596003544907193249) open_global_id : 0x0886d56e (143054190) open_persistent_id : 0x000000000886d56e (143054190) open_volatile_id : 0x00000000c53829ca (3308792266) open_owner : S-1-5-21-974925914-423971577-4012352237-1000 open_time : Wed Jul 11 20:03:15 2018 UTC create_guid : 00000000-0000-0000-0000-000000000000 client_guid : 841545fa-46c0-4b53-94ae-f78a9288a6fe 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 : 0x0000 (0) channel_generation : 0x0000000000000000 (0) [2018/07/11 20:03:14.711668, 10, pid=6945, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap_tdb.c:61(db_tdb_log_key) Unlocking key 0886D56E [2018/07/11 20:03:14.711688, 5, pid=6945, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap.c:159(dbwrap_lock_order_unlock) dbwrap_lock_order_unlock: release lock order 1 for /var/run/samba/smbXsrv_open_global.tdb [2018/07/11 20:03:14.711708, 10, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/smbd/smbXsrv_open.c:911(smbXsrv_open_create) smbXsrv_open_create: global_id (0x0886d56e) stored [2018/07/11 20:03:14.711728, 1, pid=6945, effective(1000, 1000), real(1000, 0), class=rpc_parse] ../librpc/ndr/ndr.c:422(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 : 0xc53829ca (3308792266) global : * global: struct smbXsrv_open_global0 db_rec : NULL server_id: struct server_id pid : 0x0000000000001b21 (6945) task_id : 0x00000000 (0) vnn : 0xffffffff (4294967295) unique_id : 0xce186dd40ec2e45f (-3596003544907193249) open_global_id : 0x0886d56e (143054190) open_persistent_id : 0x000000000886d56e (143054190) open_volatile_id : 0x00000000c53829ca (3308792266) open_owner : S-1-5-21-974925914-423971577-4012352237-1000 open_time : Wed Jul 11 20:03:15 2018 UTC create_guid : 00000000-0000-0000-0000-000000000000 client_guid : 841545fa-46c0-4b53-94ae-f78a9288a6fe 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 : 0x0000 (0) channel_generation : 0x0000000000000000 (0) status : NT_STATUS_OK idle_time : Wed Jul 11 20:03:15 2018 UTC 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) [2018/07/11 20:03:14.712026, 5, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/smbd/files.c:128(file_new) allocated file structure fnum 3308792266 (1 used) [2018/07/11 20:03:14.712051, 10, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/smbd/files.c:754(file_name_hash) file_name_hash: /storage/. hash 0x83de38f3 [2018/07/11 20:03:14.712078, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=vfs] ../source3/smbd/vfs.c:1283(check_reduced_name) check_reduced_name: check_reduced_name [.] [/storage] [2018/07/11 20:03:14.712102, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=vfs] ../source3/smbd/vfs.c:1347(check_reduced_name) check_reduced_name realpath [.] -> [/storage] [2018/07/11 20:03:14.712122, 5, pid=6945, effective(1000, 1000), real(1000, 0), class=vfs] ../source3/smbd/vfs.c:1458(check_reduced_name) check_reduced_name: . reduced to /storage [2018/07/11 20:03:14.712147, 10, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:767(fd_open) fd_open: name ., flags = 0200000 mode = 00, fd = 32. [2018/07/11 20:03:14.712171, 5, pid=6945, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap.c:130(dbwrap_lock_order_lock) dbwrap_lock_order_lock: check lock order 1 for /var/run/samba/locking.tdb [2018/07/11 20:03:14.712191, 10, pid=6945, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap.c:116(debug_lock_order) lock order: 1:/var/run/samba/locking.tdb 2: 3: [2018/07/11 20:03:14.712212, 10, pid=6945, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap_tdb.c:61(db_tdb_log_key) Locking key 7000000000000000A3A7 [2018/07/11 20:03:14.712232, 10, pid=6945, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap_tdb.c:145(db_tdb_fetch_locked_internal) Allocated locked data 0x0x564278539430 [2018/07/11 20:03:14.712255, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=locking] ../source3/locking/share_mode_lock.c:368(unparse_share_modes) unparse_share_modes: [2018/07/11 20:03:14.712275, 1, pid=6945, effective(1000, 1000), real(1000, 0), class=rpc_parse] ../librpc/ndr/ndr.c:422(ndr_print_debug) d: struct share_mode_data sequence_number : 0xc62a61f1220a0920 (-4167410816891877088) servicepath : * servicepath : '/storage' 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 : 0x0000000000001b21 (6945) task_id : 0x00000000 (0) vnn : 0xffffffff (4294967295) unique_id : 0xce186dd40ec2e45f (-3596003544907193249) op_mid : 0x00000000000000f1 (241) op_type : 0x0000 (0) lease_idx : 0xffffffff (4294967295) access_mask : 0x00000081 (129) share_access : 0x00000003 (3) private_options : 0x00000000 (0) time : Wed Jul 11 20:03:14 2018 UTC.711317 id: struct file_id devid : 0x0000000000000070 (112) inode : 0x000000000000a7a3 (42915) extid : 0x0000000000000000 (0) share_file_id : 0x0000000075021510 (1963070736) uid : 0x000003e8 (1000) flags : 0x0000 (0) name_hash : 0x83de38f3 (2212378867) 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 00:00:00 1970 UTC.0 changed_write_time : Thu Jan 1 00:00:00 1970 UTC.0 fresh : 0x01 (1) modified : 0x01 (1) record : * id: struct file_id devid : 0x0000000000000070 (112) inode : 0x000000000000a7a3 (42915) extid : 0x0000000000000000 (0) [2018/07/11 20:03:14.712606, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=locking] ../source3/locking/share_mode_lock.c:157(share_mode_memcache_delete) deleting entry for file . seq 0x14279333256817674528 key 70:a7a3:0 [2018/07/11 20:03:14.712635, 5, pid=6945, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap.c:159(dbwrap_lock_order_unlock) dbwrap_lock_order_unlock: release lock order 1 for /var/run/samba/locking.tdb [2018/07/11 20:03:14.712657, 10, pid=6945, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap_tdb.c:61(db_tdb_log_key) Unlocking key 7000000000000000A3A7 [2018/07/11 20:03:14.712677, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=locking] ../source3/locking/share_mode_lock.c:171(share_mode_memcache_store) stored entry for file . seq 0x14279333256817674529 key 70:a7a3:0 [2018/07/11 20:03:14.712698, 10, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:5363(create_file_unixpath) create_file_unixpath: info=1 [2018/07/11 20:03:14.712717, 10, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:5642(create_file_default) create_file: info=1 [2018/07/11 20:03:14.712737, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=smb2] ../source3/smbd/smb2_create.c:1281(smbd_smb2_create_after_exec) smbd_smb2_create_send: response construction phase [2018/07/11 20:03:14.712757, 8, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/smbd/dosmode.c:667(dos_mode) dos_mode: . [2018/07/11 20:03:14.712778, 5, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/smbd/dosmode.c:70(dos_mode_debug_print) dos_mode_debug_print: dos_mode_from_sbuf returning (0x10): "d" [2018/07/11 20:03:14.712799, 5, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/smbd/dosmode.c:70(dos_mode_debug_print) dos_mode_debug_print: dos_mode returning (0x10): "d" [2018/07/11 20:03:14.712819, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=smb2] ../source3/smbd/smb2_create.c:1507(smbd_smb2_create_finish) smbd_smb2_create_finish: . - fnum 3308792266 [2018/07/11 20:03:14.712842, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=smb2] ../source3/smbd/smb2_server.c:3062(smbd_smb2_request_done_ex) smbd_smb2_request_done_ex: idx[1] status[NT_STATUS_OK] body[88] dyn[yes:0] at ../source3/smbd/smb2_create.c:367 [2018/07/11 20:03:14.712864, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=smb2_credits] ../source3/smbd/smb2_server.c:936(smb2_set_operation_credit) smb2_set_operation_credit: smb2_set_operation_credit: requested 7681, charge 1, granted 1, current possible/max 1/512, total granted/max/low/range 512/8192/242/512 [2018/07/11 20:03:14.713001, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=smb2] ../source3/smbd/smb2_server.c:3934(smbd_smb2_io_handler) smbd_smb2_request idx[1] of 5 vectors [2018/07/11 20:03:14.713028, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=smb2_credits] ../source3/smbd/smb2_server.c:678(smb2_validate_sequence_number) smb2_validate_sequence_number: smb2_validate_sequence_number: clearing id 242 (position 242) from bitmap [2018/07/11 20:03:14.713048, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=smb2] ../source3/smbd/smb2_server.c:2327(smbd_smb2_request_dispatch) smbd_smb2_request_dispatch: opcode[SMB2_OP_QUERY_DIRECTORY] mid = 242 [2018/07/11 20:03:14.713069, 4, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/smbd/uid.c:384(change_to_user) Skipping user change - already user [2018/07/11 20:03:14.713089, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=smb2] ../source3/smbd/smb2_query_directory.c:97(smbd_smb2_request_process_query_directory) smbd_smb2_request_find_done: in_output_buffer_length = 65535 [2018/07/11 20:03:14.713111, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=smb2] ../source3/smbd/smb2_query_directory.c:263(smbd_smb2_query_directory_send) smbd_smb2_query_directory_send: . - fnum 3308792266 [2018/07/11 20:03:14.713132, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=smb2_credits] ../source3/smbd/smb2_server.c:1997(smbd_smb2_request_verify_creditcharge) smbd_smb2_request_verify_creditcharge: mid 242, CreditCharge: 1, NeededCharge: 1 [2018/07/11 20:03:14.713154, 5, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/smbd/filename.c:461(unix_convert) unix_convert called on file "apt-cdrom" [2018/07/11 20:03:14.713175, 10, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/smbd/statcache.c:245(stat_cache_lookup) stat_cache_lookup: lookup failed for name [APT-CDROM] [2018/07/11 20:03:14.713196, 5, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/smbd/filename.c:662(unix_convert) unix_convert begin: name = apt-cdrom, dirpath = , start = apt-cdrom [2018/07/11 20:03:14.713221, 5, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/smbd/statcache.c:144(stat_cache_add) stat_cache_add: Added entry (56427852c940:size 9) APT-CDROM -> apt-cdrom [2018/07/11 20:03:14.713241, 5, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/smbd/filename.c:685(unix_convert) conversion of base_name finished apt-cdrom -> apt-cdrom [2018/07/11 20:03:14.713261, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=vfs] ../source3/smbd/vfs.c:1283(check_reduced_name) check_reduced_name: check_reduced_name [apt-cdrom] [/storage] [2018/07/11 20:03:14.713285, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=vfs] ../source3/smbd/vfs.c:1347(check_reduced_name) check_reduced_name realpath [apt-cdrom] -> [/storage/apt-cdrom] [2018/07/11 20:03:14.713305, 5, pid=6945, effective(1000, 1000), real(1000, 0), class=vfs] ../source3/smbd/vfs.c:1458(check_reduced_name) check_reduced_name: apt-cdrom reduced to /storage/apt-cdrom [2018/07/11 20:03:14.713325, 5, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/smbd/dir.c:475(dptr_create) dptr_create dir=. [2018/07/11 20:03:14.713350, 3, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/smbd/dir.c:657(dptr_create) creating new dirptr 0 for path ., expect_close = 0 [2018/07/11 20:03:14.713382, 8, pid=6945, effective(1000, 1000), real(1000, 0), class=smb2] ../source3/smbd/smb2_query_directory.c:470(smbd_smb2_query_directory_send) smbd_smb2_query_directory_send: dirpath=<.> dontdescend=<>, in_output_buffer_length = 65527 [2018/07/11 20:03:14.713414, 6, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/smbd/dir.c:1129(smbd_dirptr_get_entry) smbd_dirptr_get_entry: dirptr 0x56427855d480 now at offset -1 [2018/07/11 20:03:14.713436, 8, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/smbd/dosmode.c:667(dos_mode) dos_mode: apt-cdrom [2018/07/11 20:03:14.713458, 5, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/smbd/dosmode.c:70(dos_mode_debug_print) dos_mode_debug_print: dos_mode_from_sbuf returning (0x20): "a" [2018/07/11 20:03:14.713478, 5, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/smbd/dosmode.c:70(dos_mode_debug_print) dos_mode_debug_print: dos_mode returning (0x20): "a" [2018/07/11 20:03:14.713500, 3, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/smbd/dir.c:1220(smbd_dirptr_get_entry) smbd_dirptr_get_entry mask=[apt-cdrom] found apt-cdrom fname=apt-cdrom (apt-cdrom) [2018/07/11 20:03:14.713522, 10, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/smbd/trans2.c:1842(smbd_marshall_dir_entry) smbd_marshall_dir_entry: space_remaining = 65527 [2018/07/11 20:03:14.713543, 10, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/smbd/trans2.c:2247(smbd_marshall_dir_entry) smbd_marshall_dir_entry: SMB_FIND_ID_BOTH_DIRECTORY_INFO [2018/07/11 20:03:14.713573, 10, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/smbd/mangle_hash2.c:791(hash2_name_to_8_3) hash2_name_to_8_3: apt-cdrom -> 659FA53C -> AS738L~8 (cache=1) [2018/07/11 20:03:14.713597, 6, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/smbd/dir.c:1129(smbd_dirptr_get_entry) smbd_dirptr_get_entry: dirptr 0x56427855d480 now at offset -1 [2018/07/11 20:03:14.713619, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=smb2] ../source3/smbd/smb2_query_directory.c:187(smbd_smb2_request_find_done) smbd_smb2_request_find_done: out_output_buffer.length = 122 [2018/07/11 20:03:14.713639, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=smb2] ../source3/smbd/smb2_server.c:3062(smbd_smb2_request_done_ex) smbd_smb2_request_done_ex: idx[1] status[NT_STATUS_OK] body[8] dyn[yes:122] at ../source3/smbd/smb2_query_directory.c:191 [2018/07/11 20:03:14.713660, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=smb2_credits] ../source3/smbd/smb2_server.c:936(smb2_set_operation_credit) smb2_set_operation_credit: smb2_set_operation_credit: requested 7681, charge 1, granted 1, current possible/max 1/512, total granted/max/low/range 512/8192/243/512 [2018/07/11 20:03:14.713788, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=smb2] ../source3/smbd/smb2_server.c:3934(smbd_smb2_io_handler) smbd_smb2_request idx[1] of 5 vectors [2018/07/11 20:03:14.713813, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=smb2_credits] ../source3/smbd/smb2_server.c:678(smb2_validate_sequence_number) smb2_validate_sequence_number: smb2_validate_sequence_number: clearing id 243 (position 243) from bitmap [2018/07/11 20:03:14.713834, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=smb2] ../source3/smbd/smb2_server.c:2327(smbd_smb2_request_dispatch) smbd_smb2_request_dispatch: opcode[SMB2_OP_CREATE] mid = 243 [2018/07/11 20:03:14.713854, 4, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/smbd/uid.c:384(change_to_user) Skipping user change - already user [2018/07/11 20:03:14.713876, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=smb2] ../source3/smbd/smb2_create.c:652(smbd_smb2_create_send) smbd_smb2_create_send: name [apt-cdrom] [2018/07/11 20:03:14.713897, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=smb2] ../source3/smbd/smb2_create.c:750(smbd_smb2_create_send) smbd_smb2_create_send: open execution phase [2018/07/11 20:03:14.713918, 5, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/smbd/filename.c:461(unix_convert) unix_convert called on file "apt-cdrom" [2018/07/11 20:03:14.713938, 10, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/smbd/statcache.c:284(stat_cache_lookup) stat_cache_lookup: lookup succeeded for name [APT-CDROM] -> [apt-cdrom] [2018/07/11 20:03:14.713960, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=vfs] ../source3/smbd/vfs.c:1283(check_reduced_name) check_reduced_name: check_reduced_name [apt-cdrom] [/storage] [2018/07/11 20:03:14.713984, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=vfs] ../source3/smbd/vfs.c:1347(check_reduced_name) check_reduced_name realpath [apt-cdrom] -> [/storage/apt-cdrom] [2018/07/11 20:03:14.714004, 5, pid=6945, effective(1000, 1000), real(1000, 0), class=vfs] ../source3/smbd/vfs.c:1458(check_reduced_name) check_reduced_name: apt-cdrom reduced to /storage/apt-cdrom [2018/07/11 20:03:14.714023, 10, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:5554(create_file_default) create_file: access_mask = 0x10000 file_attributes = 0x80, share_access = 0x7, create_disposition = 0x1 create_options = 0x1000 oplock_request = 0x0 private_flags = 0x0 root_dir_fid = 0x0, ea_list = 0x(nil), sd = 0x(nil), fname = apt-cdrom [2018/07/11 20:03:14.714045, 10, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:5017(create_file_unixpath) create_file_unixpath: access_mask = 0x10000 file_attributes = 0x80, share_access = 0x7, create_disposition = 0x1 create_options = 0x1000 oplock_request = 0x0 private_flags = 0x0 ea_list = 0x(nil), sd = 0x(nil), fname = apt-cdrom [2018/07/11 20:03:14.714068, 5, pid=6945, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap.c:130(dbwrap_lock_order_lock) dbwrap_lock_order_lock: check lock order 1 for /var/run/samba/smbXsrv_open_global.tdb [2018/07/11 20:03:14.714088, 10, pid=6945, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap.c:116(debug_lock_order) lock order: 1:/var/run/samba/smbXsrv_open_global.tdb 2: 3: [2018/07/11 20:03:14.714109, 10, pid=6945, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap_tdb.c:61(db_tdb_log_key) Locking key C7B9C9E0 [2018/07/11 20:03:14.714130, 10, pid=6945, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap_tdb.c:145(db_tdb_fetch_locked_internal) Allocated locked data 0x0x56427855f360 [2018/07/11 20:03:14.714149, 10, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/smbd/smbXsrv_open.c:625(smbXsrv_open_global_verify_record) smbXsrv_open_global_verify_record: empty value [2018/07/11 20:03:14.714175, 10, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/smbd/smbXsrv_open.c:744(smbXsrv_open_global_store) smbXsrv_open_global_store: key 'C7B9C9E0' stored [2018/07/11 20:03:14.714197, 1, pid=6945, effective(1000, 1000), real(1000, 0), class=rpc_parse] ../librpc/ndr/ndr.c:422(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 : 0x0000000000001b21 (6945) task_id : 0x00000000 (0) vnn : 0xffffffff (4294967295) unique_id : 0xce186dd40ec2e45f (-3596003544907193249) open_global_id : 0xc7b9c9e0 (3350841824) open_persistent_id : 0x00000000c7b9c9e0 (3350841824) open_volatile_id : 0x00000000faef7f17 (4209999639) open_owner : S-1-5-21-974925914-423971577-4012352237-1000 open_time : Wed Jul 11 20:03:15 2018 UTC create_guid : 00000000-0000-0000-0000-000000000000 client_guid : 841545fa-46c0-4b53-94ae-f78a9288a6fe 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 : 0x0000 (0) channel_generation : 0x0000000000000000 (0) [2018/07/11 20:03:14.714400, 10, pid=6945, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap_tdb.c:61(db_tdb_log_key) Unlocking key C7B9C9E0 [2018/07/11 20:03:14.714420, 5, pid=6945, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap.c:159(dbwrap_lock_order_unlock) dbwrap_lock_order_unlock: release lock order 1 for /var/run/samba/smbXsrv_open_global.tdb [2018/07/11 20:03:14.714440, 10, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/smbd/smbXsrv_open.c:911(smbXsrv_open_create) smbXsrv_open_create: global_id (0xc7b9c9e0) stored [2018/07/11 20:03:14.714459, 1, pid=6945, effective(1000, 1000), real(1000, 0), class=rpc_parse] ../librpc/ndr/ndr.c:422(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 : 0xfaef7f17 (4209999639) global : * global: struct smbXsrv_open_global0 db_rec : NULL server_id: struct server_id pid : 0x0000000000001b21 (6945) task_id : 0x00000000 (0) vnn : 0xffffffff (4294967295) unique_id : 0xce186dd40ec2e45f (-3596003544907193249) open_global_id : 0xc7b9c9e0 (3350841824) open_persistent_id : 0x00000000c7b9c9e0 (3350841824) open_volatile_id : 0x00000000faef7f17 (4209999639) open_owner : S-1-5-21-974925914-423971577-4012352237-1000 open_time : Wed Jul 11 20:03:15 2018 UTC create_guid : 00000000-0000-0000-0000-000000000000 client_guid : 841545fa-46c0-4b53-94ae-f78a9288a6fe 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 : 0x0000 (0) channel_generation : 0x0000000000000000 (0) status : NT_STATUS_OK idle_time : Wed Jul 11 20:03:15 2018 UTC 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) [2018/07/11 20:03:14.714754, 5, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/smbd/files.c:128(file_new) allocated file structure fnum 4209999639 (2 used) [2018/07/11 20:03:14.714776, 10, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/smbd/files.c:754(file_name_hash) file_name_hash: /storage/apt-cdrom hash 0x421ed6b5 [2018/07/11 20:03:14.714797, 5, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/smbd/dosmode.c:206(unix_mode) unix_mode: unix_mode(apt-cdrom) returning 0744 [2018/07/11 20:03:14.714817, 10, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:2994(open_file_ntcreate) open_file_ntcreate: fname=apt-cdrom, dos_attrs=0x80 access_mask=0x10000 share_access=0x7 create_disposition = 0x1 create_options=0x1000 unix mode=0744 oplock_request=0 private_flags = 0x0 [2018/07/11 20:03:14.714839, 10, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:3164(open_file_ntcreate) open_file_ntcreate: fname=apt-cdrom, after mapping access_mask=0x10000 [2018/07/11 20:03:14.714860, 4, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:3253(open_file_ntcreate) calling open_file with flags=0x0 flags2=0x0 mode=0744, access_mask = 0x10000, open_access_mask = 0x10000 [2018/07/11 20:03:14.714881, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=acls] ../source3/smbd/posix_acls.c:3483(posix_get_nt_acl) posix_get_nt_acl: called for file apt-cdrom [2018/07/11 20:03:14.714914, 10, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/passdb/lookup_sid.c:1286(uid_to_sid) uid 0 -> sid S-1-22-1-0 [2018/07/11 20:03:14.714939, 10, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/passdb/lookup_sid.c:1335(gid_to_sid) gid 0 -> sid S-1-22-2-0 [2018/07/11 20:03:14.714961, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=acls] ../source3/smbd/posix_acls.c:2726(canonicalise_acl) canonicalise_acl: Access ace entries before arrange : [2018/07/11 20:03:14.714980, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=acls] ../source3/smbd/posix_acls.c:2739(canonicalise_acl) canon_ace index 0. Type = allow SID = S-1-1-0 other SMB_ACL_OTHER ace_flags = 0x0 perms r-x [2018/07/11 20:03:14.715002, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=acls] ../source3/smbd/posix_acls.c:2739(canonicalise_acl) canon_ace index 1. Type = allow SID = S-1-22-2-0 gid 0 SMB_ACL_GROUP_OBJ ace_flags = 0x0 perms r-x [2018/07/11 20:03:14.715023, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=acls] ../source3/smbd/posix_acls.c:2739(canonicalise_acl) canon_ace index 2. Type = allow SID = S-1-22-1-0 uid 0 SMB_ACL_USER_OBJ ace_flags = 0x0 perms rwx [2018/07/11 20:03:14.715044, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=acls] ../source3/smbd/posix_acls.c:847(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 SMB_ACL_USER_OBJ ace_flags = 0x0 perms rwx canon_ace index 1. Type = allow SID = S-1-22-2-0 gid 0 SMB_ACL_GROUP_OBJ ace_flags = 0x0 perms r-x canon_ace index 2. Type = allow SID = S-1-1-0 other SMB_ACL_OTHER ace_flags = 0x0 perms r-x [2018/07/11 20:03:14.715086, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=acls] ../source3/smbd/posix_acls.c:1111(map_canon_ace_perms) map_canon_ace_perms: Mapped (UNIX) 1c0 to (NT) 1e01ff [2018/07/11 20:03:14.715106, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=acls] ../source3/smbd/posix_acls.c:1111(map_canon_ace_perms) map_canon_ace_perms: Mapped (UNIX) 140 to (NT) 1200a9 [2018/07/11 20:03:14.715125, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=acls] ../source3/smbd/posix_acls.c:1111(map_canon_ace_perms) map_canon_ace_perms: Mapped (UNIX) 140 to (NT) 1200a9 [2018/07/11 20:03:14.715147, 10, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:183(smbd_check_access_rights) smbd_check_access_rights: file apt-cdrom requesting 0x10000 returning 0x10000 (NT_STATUS_ACCESS_DENIED) [2018/07/11 20:03:14.715169, 10, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:188(smbd_check_access_rights) smbd_check_access_rights: acl for apt-cdrom is: [2018/07/11 20:03:14.715188, 1, pid=6945, effective(1000, 1000), real(1000, 0), class=rpc_parse] ../librpc/ndr/ndr.c:422(ndr_print_debug) sd: struct security_descriptor revision : SECURITY_DESCRIPTOR_REVISION_1 (1) type : 0x9004 (36868) 0: SEC_DESC_OWNER_DEFAULTED 0: SEC_DESC_GROUP_DEFAULTED 1: SEC_DESC_DACL_PRESENT 0: SEC_DESC_DACL_DEFAULTED 0: SEC_DESC_SACL_PRESENT 0: SEC_DESC_SACL_DEFAULTED 0: SEC_DESC_DACL_TRUSTED 0: SEC_DESC_SERVER_SECURITY 0: SEC_DESC_DACL_AUTO_INHERIT_REQ 0: SEC_DESC_SACL_AUTO_INHERIT_REQ 0: SEC_DESC_DACL_AUTO_INHERITED 0: SEC_DESC_SACL_AUTO_INHERITED 1: SEC_DESC_DACL_PROTECTED 0: SEC_DESC_SACL_PROTECTED 0: SEC_DESC_RM_CONTROL_VALID 1: SEC_DESC_SELF_RELATIVE owner_sid : * owner_sid : S-1-22-1-0 group_sid : * group_sid : S-1-22-2-0 sacl : NULL dacl : * dacl: struct security_acl revision : SECURITY_ACL_REVISION_NT4 (2) size : 0x004c (76) num_aces : 0x00000003 (3) aces: ARRAY(3) aces: struct security_ace type : SEC_ACE_TYPE_ACCESS_ALLOWED (0) flags : 0x00 (0) 0: SEC_ACE_FLAG_OBJECT_INHERIT 0: SEC_ACE_FLAG_CONTAINER_INHERIT 0: SEC_ACE_FLAG_NO_PROPAGATE_INHERIT 0: SEC_ACE_FLAG_INHERIT_ONLY 0: SEC_ACE_FLAG_INHERITED_ACE 0x00: SEC_ACE_FLAG_VALID_INHERIT (0) 0: SEC_ACE_FLAG_SUCCESSFUL_ACCESS 0: SEC_ACE_FLAG_FAILED_ACCESS size : 0x0018 (24) access_mask : 0x001e01ff (1966591) object : union security_ace_object_ctr(case 0) trustee : S-1-22-1-0 aces: struct security_ace type : SEC_ACE_TYPE_ACCESS_ALLOWED (0) flags : 0x00 (0) 0: SEC_ACE_FLAG_OBJECT_INHERIT 0: SEC_ACE_FLAG_CONTAINER_INHERIT 0: SEC_ACE_FLAG_NO_PROPAGATE_INHERIT 0: SEC_ACE_FLAG_INHERIT_ONLY 0: SEC_ACE_FLAG_INHERITED_ACE 0x00: SEC_ACE_FLAG_VALID_INHERIT (0) 0: SEC_ACE_FLAG_SUCCESSFUL_ACCESS 0: SEC_ACE_FLAG_FAILED_ACCESS size : 0x0018 (24) access_mask : 0x001200a9 (1179817) object : union security_ace_object_ctr(case 0) trustee : S-1-22-2-0 aces: struct security_ace type : SEC_ACE_TYPE_ACCESS_ALLOWED (0) flags : 0x00 (0) 0: SEC_ACE_FLAG_OBJECT_INHERIT 0: SEC_ACE_FLAG_CONTAINER_INHERIT 0: SEC_ACE_FLAG_NO_PROPAGATE_INHERIT 0: SEC_ACE_FLAG_INHERIT_ONLY 0: SEC_ACE_FLAG_INHERITED_ACE 0x00: SEC_ACE_FLAG_VALID_INHERIT (0) 0: SEC_ACE_FLAG_SUCCESSFUL_ACCESS 0: SEC_ACE_FLAG_FAILED_ACCESS size : 0x0014 (20) access_mask : 0x001200a9 (1179817) object : union security_ace_object_ctr(case 0) trustee : S-1-1-0 [2018/07/11 20:03:14.715711, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=acls] ../source3/smbd/posix_acls.c:3483(posix_get_nt_acl) posix_get_nt_acl: called for file . [2018/07/11 20:03:14.715743, 10, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/passdb/lookup_sid.c:1286(uid_to_sid) uid 1000 -> sid S-1-5-21-974925914-423971577-4012352237-1000 [2018/07/11 20:03:14.715766, 10, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/passdb/lookup_sid.c:1335(gid_to_sid) gid 1000 -> sid S-1-22-2-1000 [2018/07/11 20:03:14.715788, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=acls] ../source3/smbd/posix_acls.c:2726(canonicalise_acl) canonicalise_acl: Access ace entries before arrange : [2018/07/11 20:03:14.715807, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=acls] ../source3/smbd/posix_acls.c:2739(canonicalise_acl) canon_ace index 0. Type = allow SID = S-1-1-0 other SMB_ACL_OTHER ace_flags = 0x0 perms r-x [2018/07/11 20:03:14.715828, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=acls] ../source3/smbd/posix_acls.c:2739(canonicalise_acl) canon_ace index 1. Type = allow SID = S-1-22-2-1000 gid 1000 SMB_ACL_GROUP_OBJ ace_flags = 0x0 perms r-x [2018/07/11 20:03:14.715849, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=acls] ../source3/smbd/posix_acls.c:2739(canonicalise_acl) canon_ace index 2. Type = allow SID = S-1-5-21-974925914-423971577-4012352237-1000 uid 1000 SMB_ACL_USER_OBJ ace_flags = 0x0 perms rwx [2018/07/11 20:03:14.715871, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=acls] ../source3/smbd/posix_acls.c:847(print_canon_ace_list) print_canon_ace_list: canonicalise_acl: ace entries after arrange canon_ace index 0. Type = allow SID = S-1-5-21-974925914-423971577-4012352237-1000 uid 1000 SMB_ACL_USER_OBJ ace_flags = 0x0 perms rwx canon_ace index 1. Type = allow SID = S-1-22-2-1000 gid 1000 SMB_ACL_GROUP_OBJ ace_flags = 0x0 perms r-x canon_ace index 2. Type = allow SID = S-1-1-0 other SMB_ACL_OTHER ace_flags = 0x0 perms r-x [2018/07/11 20:03:14.715913, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=acls] ../source3/smbd/posix_acls.c:1111(map_canon_ace_perms) map_canon_ace_perms: Mapped (UNIX) 1c0 to (NT) 1f01ff [2018/07/11 20:03:14.715933, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=acls] ../source3/smbd/posix_acls.c:1111(map_canon_ace_perms) map_canon_ace_perms: Mapped (UNIX) 140 to (NT) 1200a9 [2018/07/11 20:03:14.715952, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=acls] ../source3/smbd/posix_acls.c:1111(map_canon_ace_perms) map_canon_ace_perms: Mapped (UNIX) 140 to (NT) 1200a9 [2018/07/11 20:03:14.715973, 10, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:183(smbd_check_access_rights) smbd_check_access_rights: file . requesting 0x40 returning 0x40 (NT_STATUS_OK) [2018/07/11 20:03:14.715994, 10, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:238(smbd_check_access_rights) smbd_check_access_rights: overrode DELETE_ACCESS on file apt-cdrom [2018/07/11 20:03:14.716015, 2, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:1404(open_file) ubuntu opened file apt-cdrom read=No write=No (numopen=2) [2018/07/11 20:03:14.716036, 5, pid=6945, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap.c:130(dbwrap_lock_order_lock) dbwrap_lock_order_lock: check lock order 1 for /var/run/samba/locking.tdb [2018/07/11 20:03:14.716055, 10, pid=6945, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap.c:116(debug_lock_order) lock order: 1:/var/run/samba/locking.tdb 2: 3: [2018/07/11 20:03:14.716077, 10, pid=6945, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap_tdb.c:61(db_tdb_log_key) Locking key 700000000000000073AA [2018/07/11 20:03:14.716097, 10, pid=6945, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap_tdb.c:145(db_tdb_fetch_locked_internal) Allocated locked data 0x0x564278578d90 [2018/07/11 20:03:14.716120, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=locking] ../source3/locking/brlock.c:2050(brl_get_locks_readonly) seqnum=0, fsp->brlock_seqnum=0 [2018/07/11 20:03:14.716143, 5, pid=6945, effective(1000, 1000), real(1000, 0), class=locking] ../source3/smbd/oplock.c:89(set_file_oplock) set_file_oplock: granted oplock on file apt-cdrom, 70:aa73:0/1803758515, tv_sec = 5b466282, tv_usec = ae552 [2018/07/11 20:03:14.716165, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=locking] ../source3/locking/brlock.c:2050(brl_get_locks_readonly) seqnum=0, fsp->brlock_seqnum=0 [2018/07/11 20:03:14.716184, 10, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:2273(grant_fsp_oplock_type) grant_fsp_oplock_type: oplock type 0x0 on file apt-cdrom [2018/07/11 20:03:14.716204, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=locking] ../source3/locking/share_mode_lock.c:368(unparse_share_modes) unparse_share_modes: [2018/07/11 20:03:14.716224, 1, pid=6945, effective(1000, 1000), real(1000, 0), class=rpc_parse] ../librpc/ndr/ndr.c:422(ndr_print_debug) d: struct share_mode_data sequence_number : 0xf2e47d581406c681 (-944492204594379135) servicepath : * servicepath : '/storage' base_name : * base_name : 'apt-cdrom' stream_name : NULL num_share_modes : 0x00000001 (1) share_modes: ARRAY(1) share_modes: struct share_mode_entry pid: struct server_id pid : 0x0000000000001b21 (6945) task_id : 0x00000000 (0) vnn : 0xffffffff (4294967295) unique_id : 0xce186dd40ec2e45f (-3596003544907193249) op_mid : 0x00000000000000f3 (243) op_type : 0x0000 (0) lease_idx : 0xffffffff (4294967295) access_mask : 0x00010000 (65536) share_access : 0x00000007 (7) private_options : 0x00000000 (0) time : Wed Jul 11 20:03:14 2018 UTC.714066 id: struct file_id devid : 0x0000000000000070 (112) inode : 0x000000000000aa73 (43635) extid : 0x0000000000000000 (0) share_file_id : 0x000000006b832bb3 (1803758515) uid : 0x000003e8 (1000) flags : 0x0000 (0) name_hash : 0x421ed6b5 (1109317301) stale : 0x00 (0) lease : NULL num_leases : 0x00000000 (0) leases: ARRAY(0) num_delete_tokens : 0x00000000 (0) delete_tokens: ARRAY(0) old_write_time : Wed Jul 11 19:46:34 2018 UTC.432775009 changed_write_time : Thu Jan 1 00:00:00 1970 UTC.0 fresh : 0x01 (1) modified : 0x01 (1) record : * id: struct file_id devid : 0x0000000000000070 (112) inode : 0x000000000000aa73 (43635) extid : 0x0000000000000000 (0) [2018/07/11 20:03:14.716556, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=locking] ../source3/locking/share_mode_lock.c:157(share_mode_memcache_delete) deleting entry for file apt-cdrom seq 0x17502251869115172481 key 70:aa73:0 [2018/07/11 20:03:14.716586, 5, pid=6945, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap.c:159(dbwrap_lock_order_unlock) dbwrap_lock_order_unlock: release lock order 1 for /var/run/samba/locking.tdb [2018/07/11 20:03:14.716608, 10, pid=6945, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap_tdb.c:61(db_tdb_log_key) Unlocking key 700000000000000073AA [2018/07/11 20:03:14.716627, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=locking] ../source3/locking/share_mode_lock.c:171(share_mode_memcache_store) stored entry for file apt-cdrom seq 0x17502251869115172482 key 70:aa73:0 [2018/07/11 20:03:14.716648, 10, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:5363(create_file_unixpath) create_file_unixpath: info=1 [2018/07/11 20:03:14.716666, 10, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:5642(create_file_default) create_file: info=1 [2018/07/11 20:03:14.716685, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=smb2] ../source3/smbd/smb2_create.c:1281(smbd_smb2_create_after_exec) smbd_smb2_create_send: response construction phase [2018/07/11 20:03:14.716703, 8, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/smbd/dosmode.c:667(dos_mode) dos_mode: apt-cdrom [2018/07/11 20:03:14.716723, 5, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/smbd/dosmode.c:70(dos_mode_debug_print) dos_mode_debug_print: dos_mode_from_sbuf returning (0x20): "a" [2018/07/11 20:03:14.716742, 5, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/smbd/dosmode.c:70(dos_mode_debug_print) dos_mode_debug_print: dos_mode returning (0x20): "a" [2018/07/11 20:03:14.716761, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=smb2] ../source3/smbd/smb2_create.c:1507(smbd_smb2_create_finish) smbd_smb2_create_finish: apt-cdrom - fnum 4209999639 [2018/07/11 20:03:14.716782, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=smb2] ../source3/smbd/smb2_server.c:3062(smbd_smb2_request_done_ex) smbd_smb2_request_done_ex: idx[1] status[NT_STATUS_OK] body[88] dyn[yes:0] at ../source3/smbd/smb2_create.c:367 [2018/07/11 20:03:14.716803, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=smb2_credits] ../source3/smbd/smb2_server.c:936(smb2_set_operation_credit) smb2_set_operation_credit: smb2_set_operation_credit: requested 7681, charge 1, granted 1, current possible/max 1/512, total granted/max/low/range 512/8192/244/512 [2018/07/11 20:03:14.716915, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=smb2] ../source3/smbd/smb2_server.c:3934(smbd_smb2_io_handler) smbd_smb2_request idx[1] of 5 vectors [2018/07/11 20:03:14.716939, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=smb2_credits] ../source3/smbd/smb2_server.c:678(smb2_validate_sequence_number) smb2_validate_sequence_number: smb2_validate_sequence_number: clearing id 244 (position 244) from bitmap [2018/07/11 20:03:14.716959, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=smb2] ../source3/smbd/smb2_server.c:2327(smbd_smb2_request_dispatch) smbd_smb2_request_dispatch: opcode[SMB2_OP_CLOSE] mid = 244 [2018/07/11 20:03:14.716978, 4, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/smbd/uid.c:384(change_to_user) Skipping user change - already user [2018/07/11 20:03:14.716999, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=smb2] ../source3/smbd/smb2_close.c:230(smbd_smb2_close) smbd_smb2_close: apt-cdrom - fnum 4209999639 [2018/07/11 20:03:14.717020, 5, pid=6945, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap.c:130(dbwrap_lock_order_lock) dbwrap_lock_order_lock: check lock order 1 for /var/run/samba/locking.tdb [2018/07/11 20:03:14.717039, 10, pid=6945, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap.c:116(debug_lock_order) lock order: 1:/var/run/samba/locking.tdb 2: 3: [2018/07/11 20:03:14.717060, 10, pid=6945, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap_tdb.c:61(db_tdb_log_key) Locking key 700000000000000073AA [2018/07/11 20:03:14.717080, 10, pid=6945, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap_tdb.c:145(db_tdb_fetch_locked_internal) Allocated locked data 0x0x564278575130 [2018/07/11 20:03:14.717101, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=locking] ../source3/locking/share_mode_lock.c:285(share_mode_memcache_fetch) fetched entry for file apt-cdrom seq 0x17502251869115172482 key 70:aa73:0 [2018/07/11 20:03:14.717121, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=locking] ../source3/locking/locking.c:1226(find_delete_on_close_token) find_delete_on_close_token: name_hash = 0x421ed6b5 [2018/07/11 20:03:14.717145, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=locking] ../source3/locking/locking.c:1226(find_delete_on_close_token) find_delete_on_close_token: name_hash = 0x421ed6b5 [2018/07/11 20:03:14.717164, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=locking] ../source3/locking/locking.c:1232(find_delete_on_close_token) find__delete_on_close_token: dt->name_hash = 0x421ed6b5 [2018/07/11 20:03:14.717183, 5, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/smbd/close.c:373(close_remove_share_mode) close_remove_share_mode: file apt-cdrom. Delete on close was set - deleting file. [2018/07/11 20:03:14.717202, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=locking] ../source3/locking/locking.c:1226(find_delete_on_close_token) find_delete_on_close_token: name_hash = 0x421ed6b5 [2018/07/11 20:03:14.717220, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=locking] ../source3/locking/locking.c:1232(find_delete_on_close_token) find__delete_on_close_token: dt->name_hash = 0x421ed6b5 [2018/07/11 20:03:14.717244, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=recycle] ../source3/modules/vfs_recycle.c:47(recycle_repository) recycle: repository = .recycle [2018/07/11 20:03:14.717269, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=recycle] ../source3/modules/vfs_recycle.c:136(recycle_maxsize) recycle: maxsize = 0 [2018/07/11 20:03:14.717289, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=recycle] ../source3/modules/vfs_recycle.c:148(recycle_minsize) recycle: minsize = 0 [2018/07/11 20:03:14.717308, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=recycle] ../source3/modules/vfs_recycle.c:547(recycle_unlink) recycle: fname = apt-cdrom [2018/07/11 20:03:14.717326, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=recycle] ../source3/modules/vfs_recycle.c:549(recycle_unlink) recycle: fpath = / [2018/07/11 20:03:14.717344, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=recycle] ../source3/modules/vfs_recycle.c:551(recycle_unlink) recycle: base = apt-cdrom [2018/07/11 20:03:14.717363, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=recycle] ../source3/modules/vfs_recycle.c:102(recycle_exclude) recycle: exclude = ... [2018/07/11 20:03:14.717382, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=recycle] ../source3/modules/vfs_recycle.c:113(recycle_exclude_dir) recycle: exclude_dir = ... [2018/07/11 20:03:14.717400, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=recycle] ../source3/modules/vfs_recycle.c:58(recycle_keep_dir_tree) recycle_bin: keeptree = False [2018/07/11 20:03:14.717422, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=recycle] ../source3/modules/vfs_recycle.c:576(recycle_unlink) recycle: Directory already exists [2018/07/11 20:03:14.717441, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=recycle] ../source3/modules/vfs_recycle.c:605(recycle_unlink) recycle: recycled file name: .recycle/apt-cdrom [2018/07/11 20:03:14.717473, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=recycle] ../source3/modules/vfs_recycle.c:636(recycle_unlink) recycle: Moving apt-cdrom to .recycle/apt-cdrom [2018/07/11 20:03:14.717540, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=recycle] ../source3/modules/vfs_recycle.c:80(recycle_touch) recycle: touch = False [2018/07/11 20:03:14.717571, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=recycle] ../source3/modules/vfs_recycle.c:91(recycle_touch_mtime) recycle: touch_mtime = False [2018/07/11 20:03:14.717596, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=locking] ../source3/locking/share_mode_lock.c:368(unparse_share_modes) unparse_share_modes: [2018/07/11 20:03:14.717615, 1, pid=6945, effective(1000, 1000), real(1000, 0), class=rpc_parse] ../librpc/ndr/ndr.c:422(ndr_print_debug) d: struct share_mode_data sequence_number : 0xf2e47d581406c682 (-944492204594379134) servicepath : * servicepath : '/storage' base_name : * base_name : 'apt-cdrom' 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 : Wed Jul 11 19:46:34 2018 UTC.432775009 changed_write_time : Thu Jan 1 00:00:00 1970 UTC.0 fresh : 0x00 (0) modified : 0x01 (1) record : * id: struct file_id devid : 0x0000000000000070 (112) inode : 0x000000000000aa73 (43635) extid : 0x0000000000000000 (0) [2018/07/11 20:03:14.717799, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=locking] ../source3/locking/share_mode_lock.c:157(share_mode_memcache_delete) deleting entry for file apt-cdrom seq 0x17502251869115172482 key 70:aa73:0 [2018/07/11 20:03:14.717829, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=locking] ../source3/locking/share_mode_lock.c:380(unparse_share_modes) No used share mode found [2018/07/11 20:03:14.717854, 5, pid=6945, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap.c:159(dbwrap_lock_order_unlock) dbwrap_lock_order_unlock: release lock order 1 for /var/run/samba/locking.tdb [2018/07/11 20:03:14.717876, 10, pid=6945, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap_tdb.c:61(db_tdb_log_key) Unlocking key 700000000000000073AA [2018/07/11 20:03:14.717896, 10, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/smbd/notify_msg.c:218(notify_trigger) notify_trigger called action=0x2, filter=0x1, dir=/storage, name=apt-cdrom [2018/07/11 20:03:14.717938, 4, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/smbd/sec_ctx.c:216(push_sec_ctx) push_sec_ctx(1000, 1000) : sec_ctx_stack_ndx = 1 [2018/07/11 20:03:14.717963, 4, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/smbd/uid.c:491(push_conn_ctx) push_conn_ctx(1220382092) : conn_ctx_stack_ndx = 0 [2018/07/11 20:03:14.717983, 4, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/smbd/sec_ctx.c:320(set_sec_ctx_internal) setting sec ctx (0, 0) - sec_ctx_stack_ndx = 1 [2018/07/11 20:03:14.718002, 5, pid=6945, effective(1000, 1000), real(1000, 0)] ../libcli/security/security_token.c:53(security_token_debug) Security token: (NULL) [2018/07/11 20:03:14.718020, 5, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/auth/token_util.c:810(debug_unix_user_token) UNIX token of user 0 Primary group is 0 and contains 0 supplementary groups [2018/07/11 20:03:14.718067, 10, pid=6945, effective(0, 0), real(0, 0)] ../source3/lib/messages_dgm.c:1430(messaging_dgm_send) messaging_dgm_send: Sending message to 6848 [2018/07/11 20:03:14.718115, 4, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/smbd/sec_ctx.c:438(pop_sec_ctx) pop_sec_ctx (1000, 1000) - sec_ctx_stack_ndx = 0 [2018/07/11 20:03:14.718148, 2, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/smbd/close.c:805(close_normal_file) ubuntu closed file apt-cdrom (numopen=1) NT_STATUS_OK [2018/07/11 20:03:14.718177, 5, pid=6945, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap.c:130(dbwrap_lock_order_lock) dbwrap_lock_order_lock: check lock order 1 for /var/run/samba/smbXsrv_open_global.tdb [2018/07/11 20:03:14.718206, 10, pid=6945, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap.c:116(debug_lock_order) lock order: 1:/var/run/samba/smbXsrv_open_global.tdb 2: 3: [2018/07/11 20:03:14.718235, 10, pid=6945, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap_tdb.c:61(db_tdb_log_key) Locking key C7B9C9E0 [2018/07/11 20:03:14.718276, 10, pid=6945, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap_tdb.c:145(db_tdb_fetch_locked_internal) Allocated locked data 0x0x564278574060 [2018/07/11 20:03:14.718308, 10, pid=6945, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap_tdb.c:61(db_tdb_log_key) Unlocking key C7B9C9E0 [2018/07/11 20:03:14.718328, 5, pid=6945, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap.c:159(dbwrap_lock_order_unlock) dbwrap_lock_order_unlock: release lock order 1 for /var/run/samba/smbXsrv_open_global.tdb [2018/07/11 20:03:14.718348, 5, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/smbd/files.c:563(file_free) freed files structure 4209999639 (1 used) [2018/07/11 20:03:14.718370, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=smb2] ../source3/smbd/smb2_server.c:3062(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:147 [2018/07/11 20:03:14.718391, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=smb2_credits] ../source3/smbd/smb2_server.c:936(smb2_set_operation_credit) smb2_set_operation_credit: smb2_set_operation_credit: requested 7681, charge 1, granted 1, current possible/max 1/512, total granted/max/low/range 512/8192/245/512 [2018/07/11 20:03:14.718489, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=smb2] ../source3/smbd/smb2_server.c:3934(smbd_smb2_io_handler) smbd_smb2_request idx[1] of 5 vectors [2018/07/11 20:03:14.718517, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=smb2_credits] ../source3/smbd/smb2_server.c:678(smb2_validate_sequence_number) smb2_validate_sequence_number: smb2_validate_sequence_number: clearing id 245 (position 245) from bitmap [2018/07/11 20:03:14.718537, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=smb2] ../source3/smbd/smb2_server.c:2327(smbd_smb2_request_dispatch) smbd_smb2_request_dispatch: opcode[SMB2_OP_CLOSE] mid = 245 [2018/07/11 20:03:14.718556, 4, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/smbd/uid.c:384(change_to_user) Skipping user change - already user [2018/07/11 20:03:14.718580, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=smb2] ../source3/smbd/smb2_close.c:230(smbd_smb2_close) smbd_smb2_close: . - fnum 3308792266 [2018/07/11 20:03:14.718611, 5, pid=6945, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap.c:130(dbwrap_lock_order_lock) dbwrap_lock_order_lock: check lock order 1 for /var/run/samba/locking.tdb [2018/07/11 20:03:14.718644, 10, pid=6945, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap.c:116(debug_lock_order) lock order: 1:/var/run/samba/locking.tdb 2: 3: [2018/07/11 20:03:14.718682, 10, pid=6945, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap_tdb.c:61(db_tdb_log_key) Locking key 7000000000000000A3A7 [2018/07/11 20:03:14.718728, 10, pid=6945, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap_tdb.c:145(db_tdb_fetch_locked_internal) Allocated locked data 0x0x564278565610 [2018/07/11 20:03:14.718793, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=locking] ../source3/locking/share_mode_lock.c:285(share_mode_memcache_fetch) fetched entry for file . seq 0x14279333256817674529 key 70:a7a3:0 [2018/07/11 20:03:14.718850, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=locking] ../source3/locking/locking.c:1226(find_delete_on_close_token) find_delete_on_close_token: name_hash = 0x83de38f3 [2018/07/11 20:03:14.718905, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=locking] ../source3/locking/share_mode_lock.c:368(unparse_share_modes) unparse_share_modes: [2018/07/11 20:03:14.718951, 1, pid=6945, effective(1000, 1000), real(1000, 0), class=rpc_parse] ../librpc/ndr/ndr.c:422(ndr_print_debug) d: struct share_mode_data sequence_number : 0xc62a61f1220a0921 (-4167410816891877087) servicepath : * servicepath : '/storage' 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 00:00:00 1970 UTC.0 changed_write_time : Thu Jan 1 00:00:00 1970 UTC.0 fresh : 0x00 (0) modified : 0x01 (1) record : * id: struct file_id devid : 0x0000000000000070 (112) inode : 0x000000000000a7a3 (42915) extid : 0x0000000000000000 (0) [2018/07/11 20:03:14.719446, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=locking] ../source3/locking/share_mode_lock.c:157(share_mode_memcache_delete) deleting entry for file . seq 0x14279333256817674529 key 70:a7a3:0 [2018/07/11 20:03:14.719481, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=locking] ../source3/locking/share_mode_lock.c:380(unparse_share_modes) No used share mode found [2018/07/11 20:03:14.719508, 5, pid=6945, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap.c:159(dbwrap_lock_order_unlock) dbwrap_lock_order_unlock: release lock order 1 for /var/run/samba/locking.tdb [2018/07/11 20:03:14.719533, 10, pid=6945, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap_tdb.c:61(db_tdb_log_key) Unlocking key 7000000000000000A3A7 [2018/07/11 20:03:14.719555, 4, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/smbd/dir.c:233(dptr_close_internal) closing dptr key 0 [2018/07/11 20:03:14.719606, 5, pid=6945, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap.c:130(dbwrap_lock_order_lock) dbwrap_lock_order_lock: check lock order 1 for /var/run/samba/smbXsrv_open_global.tdb [2018/07/11 20:03:14.719631, 10, pid=6945, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap.c:116(debug_lock_order) lock order: 1:/var/run/samba/smbXsrv_open_global.tdb 2: 3: [2018/07/11 20:03:14.719651, 10, pid=6945, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap_tdb.c:61(db_tdb_log_key) Locking key 0886D56E [2018/07/11 20:03:14.719671, 10, pid=6945, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap_tdb.c:145(db_tdb_fetch_locked_internal) Allocated locked data 0x0x564278574060 [2018/07/11 20:03:14.719696, 10, pid=6945, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap_tdb.c:61(db_tdb_log_key) Unlocking key 0886D56E [2018/07/11 20:03:14.719715, 5, pid=6945, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap.c:159(dbwrap_lock_order_unlock) dbwrap_lock_order_unlock: release lock order 1 for /var/run/samba/smbXsrv_open_global.tdb [2018/07/11 20:03:14.719736, 5, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/smbd/files.c:563(file_free) freed files structure 3308792266 (0 used) [2018/07/11 20:03:14.719761, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=smb2] ../source3/smbd/smb2_server.c:3062(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:147 [2018/07/11 20:03:14.719785, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=smb2_credits] ../source3/smbd/smb2_server.c:936(smb2_set_operation_credit) smb2_set_operation_credit: smb2_set_operation_credit: requested 7681, charge 1, granted 1, current possible/max 1/512, total granted/max/low/range 512/8192/246/512 [2018/07/11 20:03:15.321807, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=smb2] ../source3/smbd/smb2_server.c:3934(smbd_smb2_io_handler) smbd_smb2_request idx[1] of 5 vectors [2018/07/11 20:03:15.321983, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=smb2_credits] ../source3/smbd/smb2_server.c:678(smb2_validate_sequence_number) smb2_validate_sequence_number: smb2_validate_sequence_number: clearing id 246 (position 246) from bitmap [2018/07/11 20:03:15.322061, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=smb2] ../source3/smbd/smb2_server.c:2327(smbd_smb2_request_dispatch) smbd_smb2_request_dispatch: opcode[SMB2_OP_KEEPALIVE] mid = 246 [2018/07/11 20:03:15.322133, 4, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/smbd/sec_ctx.c:320(set_sec_ctx_internal) setting sec ctx (0, 0) - sec_ctx_stack_ndx = 0 [2018/07/11 20:03:15.322198, 5, pid=6945, effective(1000, 1000), real(1000, 0)] ../libcli/security/security_token.c:53(security_token_debug) Security token: (NULL) [2018/07/11 20:03:15.322261, 5, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/auth/token_util.c:810(debug_unix_user_token) UNIX token of user 0 Primary group is 0 and contains 0 supplementary groups [2018/07/11 20:03:15.322384, 5, pid=6945, 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) [2018/07/11 20:03:15.322465, 10, pid=6945, effective(0, 0), real(0, 0), class=smb2] ../source3/smbd/smb2_server.c:3062(smbd_smb2_request_done_ex) smbd_smb2_request_done_ex: idx[1] status[NT_STATUS_OK] body[4] dyn[no:0] at ../source3/smbd/smb2_keepalive.c:49 [2018/07/11 20:03:15.322533, 10, pid=6945, effective(0, 0), real(0, 0), class=smb2_credits] ../source3/smbd/smb2_server.c:936(smb2_set_operation_credit) smb2_set_operation_credit: smb2_set_operation_credit: requested 7681, charge 1, granted 1, current possible/max 1/512, total granted/max/low/range 512/8192/247/512 [2018/07/11 20:03:15.883570, 10, pid=6945, effective(0, 0), real(0, 0)] ../source3/lib/util_event.c:42(smbd_idle_event_handler) smbd_idle_event_handler: idle_evt(deadtime) (nil) called [2018/07/11 20:03:15.883828, 10, pid=6945, effective(0, 0), real(0, 0)] ../source3/lib/util_event.c:53(smbd_idle_event_handler) smbd_idle_event_handler: idle_evt(deadtime) (nil) rescheduled [2018/07/11 20:03:15.883935, 10, pid=6945, effective(0, 0), real(0, 0)] ../source3/lib/util_event.c:42(smbd_idle_event_handler) smbd_idle_event_handler: idle_evt(housekeeping) (nil) called [2018/07/11 20:03:15.884017, 5, pid=6945, effective(0, 0), real(0, 0)] ../source3/smbd/process.c:2898(housekeeping_fn) housekeeping [2018/07/11 20:03:15.884094, 4, pid=6945, 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 [2018/07/11 20:03:15.884167, 5, pid=6945, effective(0, 0), real(0, 0)] ../libcli/security/security_token.c:53(security_token_debug) Security token: (NULL) [2018/07/11 20:03:15.884238, 5, pid=6945, effective(0, 0), real(0, 0)] ../source3/auth/token_util.c:810(debug_unix_user_token) UNIX token of user 0 Primary group is 0 and contains 0 supplementary groups [2018/07/11 20:03:15.884361, 5, pid=6945, 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) [2018/07/11 20:03:15.884458, 10, pid=6945, effective(0, 0), real(0, 0)] ../source3/lib/util_event.c:53(smbd_idle_event_handler) smbd_idle_event_handler: idle_evt(housekeeping) (nil) rescheduled