[2015/02/18 05:54:45.573577, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/smb2_server.c:3432(smbd_smb2_io_handler) smbd_smb2_request idx[1] of 9 vectors [2015/02/18 05:54:45.573752, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/smb2_server.c:647(smb2_validate_sequence_number) smb2_validate_sequence_number: clearing id 58 (position 58) from bitmap [2015/02/18 05:54:45.573792, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/smb2_server.c:647(smb2_validate_sequence_number) smb2_validate_sequence_number: clearing id 59 (position 59) from bitmap [2015/02/18 05:54:45.573821, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/smb2_server.c:1957(smbd_smb2_request_dispatch) smbd_smb2_request_dispatch: opcode[SMB2_OP_GETINFO] mid = 58 [2015/02/18 05:54:45.573857, 4, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/uid.c:384(change_to_user) Skipping user change - already user [2015/02/18 05:54:45.573897, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/smb2_server.c:1848(smbd_smb2_request_verify_creditcharge) mid 58, CreditCharge: 1, NeededCharge: 1 [2015/02/18 05:54:45.573924, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/smb2_getinfo.c:272(smbd_smb2_getinfo_send) smbd_smb2_getinfo_send: . - fnum 3482229120 [2015/02/18 05:54:45.573986, 3, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/trans2.c:3234(smbd_do_qfsinfo) smbd_do_qfsinfo: level = 1001 [2015/02/18 05:54:45.574056, 5, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/trans2.c:3404(smbd_do_qfsinfo) smbd_do_qfsinfo : SMB_QUERY_FS_VOLUME_INFO namelen = 6, vol=normal serv=normal [2015/02/18 05:54:45.574101, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/smb2_server.c:2564(smbd_smb2_request_done_ex) smbd_smb2_request_done_ex: idx[1] status[NT_STATUS_OK] body[8] dyn[yes:30] at ../source3/smbd/smb2_getinfo.c:201 [2015/02/18 05:54:45.574142, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/smb2_server.c:2532(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 = 40 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 = 40 req->in.vector[8].iov_len = 1 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 = 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 [2015/02/18 05:54:45.574240, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/smb2_server.c:1957(smbd_smb2_request_dispatch) smbd_smb2_request_dispatch: opcode[SMB2_OP_GETINFO] mid = 59 [2015/02/18 05:54:45.574266, 4, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/uid.c:384(change_to_user) Skipping user change - already user [2015/02/18 05:54:45.574318, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/smb2_server.c:1848(smbd_smb2_request_verify_creditcharge) mid 59, CreditCharge: 1, NeededCharge: 1 [2015/02/18 05:54:45.574646, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/smb2_getinfo.c:272(smbd_smb2_getinfo_send) smbd_smb2_getinfo_send: . - fnum 3482229120 [2015/02/18 05:54:45.574681, 3, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/trans2.c:3234(smbd_do_qfsinfo) smbd_do_qfsinfo: level = 1005 [2015/02/18 05:54:45.574741, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/smb2_server.c:2564(smbd_smb2_request_done_ex) smbd_smb2_request_done_ex: idx[5] status[NT_STATUS_OK] body[8] dyn[yes:20] at ../source3/smbd/smb2_getinfo.c:201 [2015/02/18 05:54:45.574777, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/smb2_server.c:899(smb2_set_operation_credit) smb2_set_operation_credit: requested 1, charge 1, granted 1, current possible/max 387/512, total granted/max/low/range 126/8192/60/126 [2015/02/18 05:54:45.574802, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/smb2_server.c:899(smb2_set_operation_credit) smb2_set_operation_credit: requested 1, charge 1, granted 1, current possible/max 386/512, total granted/max/low/range 127/8192/60/127 [2015/02/18 05:54:45.578876, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/smb2_server.c:3432(smbd_smb2_io_handler) smbd_smb2_request idx[1] of 5 vectors [2015/02/18 05:54:45.579042, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/smb2_server.c:647(smb2_validate_sequence_number) smb2_validate_sequence_number: clearing id 60 (position 60) from bitmap [2015/02/18 05:54:45.579075, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/smb2_server.c:1957(smbd_smb2_request_dispatch) smbd_smb2_request_dispatch: opcode[SMB2_OP_CREATE] mid = 60 [2015/02/18 05:54:45.579110, 4, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/uid.c:384(change_to_user) Skipping user change - already user [2015/02/18 05:54:45.579162, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/smb2_create.c:501(smbd_smb2_create_send) smbd_smb2_create: name[README] [2015/02/18 05:54:45.579199, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/smb2_create.c:889(smbd_smb2_create_send) Got lease request size 52 [2015/02/18 05:54:45.579234, 1, pid=12720, effective(1000, 1000), real(1000, 0)] ../librpc/ndr/ndr.c:402(ndr_print_debug) lease_ptr: struct smb2_lease lease_key: struct smb2_lease_key data: ARRAY(2) data : 0x00000000cfb12998 (3484494232) data : 0x0000000000000140 (320) lease_state : 0x00000007 (7) 1: SMB2_LEASE_READ 1: SMB2_LEASE_HANDLE 1: SMB2_LEASE_WRITE lease_flags : 0x00000000 (0) lease_duration : 0x0000000000000000 (0) parent_lease_key: struct smb2_lease_key data: ARRAY(2) data : 0x0000000000000000 (0) data : 0x0000000000000000 (0) lease_version : 0x0002 (2) lease_epoch : 0x0000 (0) [2015/02/18 05:54:45.579600, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/smb2_create.c:911(smbd_smb2_create_send) smbd_smb2_create_send: open execution phase [2015/02/18 05:54:45.579693, 5, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/filename.c:258(unix_convert) unix_convert called on file "README" [2015/02/18 05:54:45.579730, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/statcache.c:283(stat_cache_lookup) stat_cache_lookup: lookup succeeded for name [README] -> [README] [2015/02/18 05:54:45.579861, 3, pid=12720, effective(1000, 1000), real(1000, 0), class=vfs] ../source3/smbd/vfs.c:1143(check_reduced_name) check_reduced_name [README] [/Volumes/normal] [2015/02/18 05:54:45.580352, 10, pid=12720, effective(1000, 1000), real(1000, 0), class=vfs] ../source3/smbd/vfs.c:1203(check_reduced_name) check_reduced_name realpath [README] -> [/Volumes/normal/README] [2015/02/18 05:54:45.581268, 3, pid=12720, effective(1000, 1000), real(1000, 0), class=vfs] ../source3/smbd/vfs.c:1273(check_reduced_name) check_reduced_name: README reduced to /Volumes/normal/README [2015/02/18 05:54:45.581315, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:4949(create_file_default) create_file: access_mask = 0x120089 file_attributes = 0x80, share_access = 0x1, create_disposition = 0x1 create_options = 0x40 oplock_request = 0x100 private_flags = 0x0 root_dir_fid = 0x0, ea_list = 0x(nil), sd = 0x(nil), fname = README [2015/02/18 05:54:45.581538, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:4422(create_file_unixpath) create_file_unixpath: access_mask = 0x120089 file_attributes = 0x80, share_access = 0x1, create_disposition = 0x1 create_options = 0x40 oplock_request = 0x100 private_flags = 0x0 ea_list = 0x(nil), sd = 0x(nil), fname = README [2015/02/18 05:54:45.581573, 10, pid=12720, effective(1000, 1000), real(1000, 0), class=locking] ../source3/locking/leases_db.c:75(leases_db_key) leases_db_key: [2015/02/18 05:54:45.581660, 1, pid=12720, effective(1000, 1000), real(1000, 0)] ../librpc/ndr/ndr.c:402(ndr_print_debug) &db_key: struct leases_db_key client_guid : 807779ee-b1c8-11e4-a338-0800275b519b lease_key: struct smb2_lease_key data: ARRAY(2) data : 0x00000000cfb12998 (3484494232) data : 0x0000000000000140 (320) [2015/02/18 05:54:45.581845, 5, pid=12720, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap.c:178(dbwrap_check_lock_order) check lock order 1 for /opt/samba/var/lock/smbXsrv_open_global.tdb [2015/02/18 05:54:45.581939, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap.c:133(debug_lock_order) lock order: 1:/opt/samba/var/lock/smbXsrv_open_global.tdb 2: 3: [2015/02/18 05:54:45.581971, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap_tdb.c:60(db_tdb_log_key) Locking key 1330144F [2015/02/18 05:54:45.582062, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap_tdb.c:144(db_tdb_fetch_locked_internal) Allocated locked data 0x0x7fb80e1173b0 [2015/02/18 05:54:45.582104, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/smbXsrv_open.c:588(smbXsrv_open_global_verify_record) smbXsrv_open_global_verify_record: empty value [2015/02/18 05:54:45.583128, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/smbXsrv_open.c:706(smbXsrv_open_global_store) smbXsrv_open_global_store: key '1330144F' stored [2015/02/18 05:54:45.583328, 1, pid=12720, effective(1000, 1000), real(1000, 0)] ../librpc/ndr/ndr.c:402(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 : 0x00000000000031b0 (12720) task_id : 0x00000000 (0) vnn : 0xffffffff (4294967295) unique_id : 0xfb17366705686992 (-353754229625034350) open_global_id : 0x1330144f (321918031) open_persistent_id : 0x000000001330144f (321918031) open_volatile_id : 0x000000005ef23051 (1592930385) open_owner : S-1-5-21-1849679311-379505231-1387054432-1000 open_time : Wed Feb 18 05:54:46 AM 2015 CET create_guid : 00000000-0000-0000-0000-000000000000 client_guid : 807779ee-b1c8-11e4-a338-0800275b519b 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 [2015/02/18 05:54:45.583963, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap_tdb.c:60(db_tdb_log_key) Unlocking key 1330144F [2015/02/18 05:54:45.584056, 5, pid=12720, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap.c:146(dbwrap_lock_order_state_destructor) release lock order 1 for /opt/samba/var/lock/smbXsrv_open_global.tdb [2015/02/18 05:54:45.584124, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap.c:133(debug_lock_order) lock order: 1: 2: 3: [2015/02/18 05:54:45.584154, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/smbXsrv_open.c:880(smbXsrv_open_create) smbXsrv_open_create: global_id (0x1330144f) stored [2015/02/18 05:54:45.584207, 1, pid=12720, effective(1000, 1000), real(1000, 0)] ../librpc/ndr/ndr.c:402(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 : 0x5ef23051 (1592930385) global : * global: struct smbXsrv_open_global0 db_rec : NULL server_id: struct server_id pid : 0x00000000000031b0 (12720) task_id : 0x00000000 (0) vnn : 0xffffffff (4294967295) unique_id : 0xfb17366705686992 (-353754229625034350) open_global_id : 0x1330144f (321918031) open_persistent_id : 0x000000001330144f (321918031) open_volatile_id : 0x000000005ef23051 (1592930385) open_owner : S-1-5-21-1849679311-379505231-1387054432-1000 open_time : Wed Feb 18 05:54:46 AM 2015 CET create_guid : 00000000-0000-0000-0000-000000000000 client_guid : 807779ee-b1c8-11e4-a338-0800275b519b 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 status : NT_STATUS_OK idle_time : Wed Feb 18 05:54:46 AM 2015 CET compat : NULL [2015/02/18 05:54:45.584743, 5, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/files.c:129(file_new) allocated file structure fnum 1592930385 (3 used) [2015/02/18 05:54:45.584786, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/files.c:743(file_name_hash) file_name_hash: /Volumes/normal/README hash 0x7d551025 [2015/02/18 05:54:45.585941, 3, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/dosmode.c:196(unix_mode) unix_mode(README) returning 0744 [2015/02/18 05:54:45.586067, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:2478(open_file_ntcreate) open_file_ntcreate: fname=README, dos_attrs=0x80 access_mask=0x120089 share_access=0x1 create_disposition = 0x1 create_options=0x40 unix mode=0744 oplock_request=256 private_flags = 0x0 [2015/02/18 05:54:45.586106, 8, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/dosmode.c:600(dos_mode) dos_mode: README [2015/02/18 05:54:45.586150, 8, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/dosmode.c:242(dos_mode_from_sbuf) dos_mode_from_sbuf returning [2015/02/18 05:54:45.586188, 8, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/dosmode.c:36(dos_mode_debug_print) dos_mode returning [2015/02/18 05:54:45.586277, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:2636(open_file_ntcreate) open_file_ntcreate: fname=README, after mapping access_mask=0x120089 [2015/02/18 05:54:45.586309, 4, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:2726(open_file_ntcreate) calling open_file with flags=0x0 flags2=0x0 mode=0744, access_mask = 0x120089, open_access_mask = 0x120089 [2015/02/18 05:54:45.586355, 10, pid=12720, effective(1000, 1000), real(1000, 0), class=acls] ../source3/smbd/posix_acls.c:3521(posix_get_nt_acl) posix_get_nt_acl: called for file README [2015/02/18 05:54:45.586614, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/passdb/lookup_sid.c:1198(uid_to_sid) uid 1000 -> sid S-1-5-21-1849679311-379505231-1387054432-1000 [2015/02/18 05:54:45.586731, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/passdb/lookup_sid.c:1247(gid_to_sid) gid 0 -> sid S-1-22-2-0 [2015/02/18 05:54:45.587900, 10, pid=12720, effective(1000, 1000), real(1000, 0), class=acls] ../source3/smbd/posix_acls.c:2724(canonicalise_acl) canonicalise_acl: Access ace entries before arrange : [2015/02/18 05:54:45.587942, 10, pid=12720, effective(1000, 1000), real(1000, 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 r-- [2015/02/18 05:54:45.588037, 10, pid=12720, effective(1000, 1000), real(1000, 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 r-- [2015/02/18 05:54:45.588794, 10, pid=12720, effective(1000, 1000), real(1000, 0), class=acls] ../source3/smbd/posix_acls.c:2737(canonicalise_acl) canon_ace index 2. Type = allow SID = S-1-5-21-1849679311-379505231-1387054432-1000 uid 1000 (ralph) SMB_ACL_USER_OBJ ace_flags = 0x0 perms rw- [2015/02/18 05:54:45.589008, 10, pid=12720, effective(1000, 1000), real(1000, 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-5-21-1849679311-379505231-1387054432-1000 uid 1000 (ralph) SMB_ACL_USER_OBJ ace_flags = 0x0 perms rw- canon_ace index 1. Type = allow SID = S-1-22-2-0 gid 0 (root) SMB_ACL_GROUP_OBJ ace_flags = 0x0 perms r-- canon_ace index 2. Type = allow SID = S-1-1-0 other SMB_ACL_OTHER ace_flags = 0x0 perms r-- [2015/02/18 05:54:45.590318, 10, pid=12720, effective(1000, 1000), real(1000, 0), class=acls] ../source3/smbd/posix_acls.c:1110(map_canon_ace_perms) map_canon_ace_perms: Mapped (UNIX) 180 to (NT) 12019f [2015/02/18 05:54:45.590359, 10, pid=12720, effective(1000, 1000), real(1000, 0), class=acls] ../source3/smbd/posix_acls.c:1110(map_canon_ace_perms) map_canon_ace_perms: Mapped (UNIX) 100 to (NT) 120089 [2015/02/18 05:54:45.590621, 10, pid=12720, effective(1000, 1000), real(1000, 0), class=acls] ../source3/smbd/posix_acls.c:1110(map_canon_ace_perms) map_canon_ace_perms: Mapped (UNIX) 100 to (NT) 120089 [2015/02/18 05:54:45.590823, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:174(smbd_check_access_rights) smbd_check_access_rights: file README requesting 0x120089 returning 0x120009 (NT_STATUS_OK) [2015/02/18 05:54:45.590885, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:408(fd_open) fd_open: name README, flags = 00 mode = 0744, fd = 40. [2015/02/18 05:54:45.591596, 2, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:1005(open_file) ralph opened file README read=Yes write=No (numopen=3) [2015/02/18 05:54:45.591990, 5, pid=12720, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap.c:178(dbwrap_check_lock_order) check lock order 1 for /opt/samba/var/lock/locking.tdb [2015/02/18 05:54:45.592849, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap.c:133(debug_lock_order) lock order: 1:/opt/samba/var/lock/locking.tdb 2: 3: [2015/02/18 05:54:45.593887, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap_tdb.c:60(db_tdb_log_key) Locking key 01FD000000000000810A [2015/02/18 05:54:45.594219, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap_tdb.c:144(db_tdb_fetch_locked_internal) Allocated locked data 0x0x7fb80e10e030 [2015/02/18 05:54:45.594342, 10, pid=12720, effective(1000, 1000), real(1000, 0), class=locking] ../source3/locking/brlock.c:2032(brl_get_locks_readonly) seqnum=6, fsp->brlock_seqnum=0 [2015/02/18 05:54:45.594533, 10, pid=12720, effective(1000, 1000), real(1000, 0), class=locking] ../source3/locking/leases_db.c:75(leases_db_key) leases_db_key: [2015/02/18 05:54:45.594581, 1, pid=12720, effective(1000, 1000), real(1000, 0)] ../librpc/ndr/ndr.c:402(ndr_print_debug) &db_key: struct leases_db_key client_guid : 807779ee-b1c8-11e4-a338-0800275b519b lease_key: struct smb2_lease_key data: ARRAY(2) data : 0x00000000cfb12998 (3484494232) data : 0x0000000000000140 (320) [2015/02/18 05:54:45.594661, 5, pid=12720, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap.c:178(dbwrap_check_lock_order) check lock order 2 for /opt/samba/var/lock/leases.tdb [2015/02/18 05:54:45.594689, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap.c:133(debug_lock_order) lock order: 1:/opt/samba/var/lock/locking.tdb 2:/opt/samba/var/lock/leases.tdb 3: [2015/02/18 05:54:45.594826, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap_tdb.c:60(db_tdb_log_key) Locking key EE797780C8B1E411A338 [2015/02/18 05:54:45.595547, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap_tdb.c:144(db_tdb_fetch_locked_internal) Allocated locked data 0x0x7fb80e1187e0 [2015/02/18 05:54:45.596191, 10, pid=12720, effective(1000, 1000), real(1000, 0), class=locking] ../source3/locking/leases_db.c:172(leases_db_add) leases_db_add: new record [2015/02/18 05:54:45.596246, 10, pid=12720, effective(1000, 1000), real(1000, 0), class=locking] ../source3/locking/leases_db.c:199(leases_db_add) leases_db_add: [2015/02/18 05:54:45.596336, 1, pid=12720, effective(1000, 1000), real(1000, 0)] ../librpc/ndr/ndr.c:402(ndr_print_debug) value: struct leases_db_value num_files : 0x00000001 (1) files: ARRAY(1) files: struct leases_db_file id: struct file_id devid : 0x000000000000fd01 (64769) inode : 0x0000000000080a81 (526977) extid : 0x0000000000000000 (0) servicepath : * servicepath : '/Volumes/normal' base_name : * base_name : 'README' stream_name : NULL [2015/02/18 05:54:45.597952, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap_tdb.c:60(db_tdb_log_key) Unlocking key EE797780C8B1E411A338 [2015/02/18 05:54:45.598088, 5, pid=12720, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap.c:146(dbwrap_lock_order_state_destructor) release lock order 2 for /opt/samba/var/lock/leases.tdb [2015/02/18 05:54:45.598117, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap.c:133(debug_lock_order) lock order: 1:/opt/samba/var/lock/locking.tdb 2: 3: [2015/02/18 05:54:45.598144, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:1827(grant_fsp_oplock_type) lease_state=7 [2015/02/18 05:54:45.598256, 10, pid=12720, effective(1000, 1000), real(1000, 0), class=locking] ../source3/locking/brlock.c:2032(brl_get_locks_readonly) seqnum=6, fsp->brlock_seqnum=6 [2015/02/18 05:54:45.598289, 5, pid=12720, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap.c:178(dbwrap_check_lock_order) check lock order 2 for /opt/samba/var/lock/brlock.tdb [2015/02/18 05:54:45.598313, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap.c:133(debug_lock_order) lock order: 1:/opt/samba/var/lock/locking.tdb 2:/opt/samba/var/lock/brlock.tdb 3: [2015/02/18 05:54:45.598535, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap_tdb.c:60(db_tdb_log_key) Locking key 01FD000000000000810A [2015/02/18 05:54:45.598582, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap_tdb.c:144(db_tdb_fetch_locked_internal) Allocated locked data 0x0x7fb80e118cc0 [2015/02/18 05:54:45.598608, 10, pid=12720, effective(1000, 1000), real(1000, 0), class=locking] ../source3/locking/brlock.c:1990(brl_get_locks) brl_get_locks_internal: 0 current locks on file_id fd01:80a81:0 [2015/02/18 05:54:45.598660, 10, pid=12720, effective(1000, 1000), real(1000, 0), class=locking] ../source3/locking/brlock.c:94(brl_set_num_read_oplocks) Setting num_read_oplocks to 1 [2015/02/18 05:54:45.598708, 10, pid=12720, effective(1000, 1000), real(1000, 0), class=locking] ../source3/locking/brlock.c:1908(byte_range_lock_flush) seqnum=7 [2015/02/18 05:54:45.598818, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap_tdb.c:60(db_tdb_log_key) Unlocking key 01FD000000000000810A [2015/02/18 05:54:45.598853, 5, pid=12720, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap.c:146(dbwrap_lock_order_state_destructor) release lock order 2 for /opt/samba/var/lock/brlock.tdb [2015/02/18 05:54:45.598889, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap.c:133(debug_lock_order) lock order: 1:/opt/samba/var/lock/locking.tdb 2: 3: [2015/02/18 05:54:45.598998, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:1873(grant_fsp_oplock_type) grant_fsp_oplock_type: oplock type 0x100 on file README [2015/02/18 05:54:45.599033, 10, pid=12720, effective(1000, 1000), real(1000, 0), class=locking] ../source3/locking/share_mode_lock.c:194(unparse_share_modes) unparse_share_modes: [2015/02/18 05:54:45.599070, 1, pid=12720, effective(1000, 1000), real(1000, 0)] ../librpc/ndr/ndr.c:402(ndr_print_debug) d: struct share_mode_data servicepath : * servicepath : '/Volumes/normal' base_name : * base_name : 'README' stream_name : NULL num_share_modes : 0x00000001 (1) share_modes: ARRAY(1) share_modes: struct share_mode_entry pid: struct server_id pid : 0x00000000000031b0 (12720) task_id : 0x00000000 (0) vnn : 0xffffffff (4294967295) unique_id : 0xfb17366705686992 (-353754229625034350) op_mid : 0x000000000000003c (60) op_type : 0x0100 (256) lease_idx : 0x00000000 (0) access_mask : 0x00120089 (1179785) share_access : 0x00000001 (1) private_options : 0x00000000 (0) time : Wed Feb 18 05:54:45 AM 2015 CET.581827 id: struct file_id devid : 0x000000000000fd01 (64769) inode : 0x0000000000080a81 (526977) extid : 0x0000000000000000 (0) share_file_id : 0x000000003357c520 (861390112) uid : 0x000003e8 (1000) flags : 0x0000 (0) name_hash : 0x7d551025 (2102726693) stale : 0x00 (0) lease : * lease: struct share_mode_lease client_guid : 807779ee-b1c8-11e4-a338-0800275b519b lease_key: struct smb2_lease_key data: ARRAY(2) data : 0x00000000cfb12998 (3484494232) data : 0x0000000000000140 (320) current_state : 0x00000007 (7) 1: SMB2_LEASE_READ 1: SMB2_LEASE_HANDLE 1: SMB2_LEASE_WRITE breaking : 0x00 (0) breaking_to_requested : 0x00000000 (0) 0: SMB2_LEASE_READ 0: SMB2_LEASE_HANDLE 0: SMB2_LEASE_WRITE breaking_to_required : 0x00000000 (0) 0: SMB2_LEASE_READ 0: SMB2_LEASE_HANDLE 0: SMB2_LEASE_WRITE lease_version : 0x0002 (2) epoch : 0x0001 (1) num_leases : 0x00000001 (1) leases: ARRAY(1) leases: struct share_mode_lease client_guid : 807779ee-b1c8-11e4-a338-0800275b519b lease_key: struct smb2_lease_key data: ARRAY(2) data : 0x00000000cfb12998 (3484494232) data : 0x0000000000000140 (320) current_state : 0x00000007 (7) 1: SMB2_LEASE_READ 1: SMB2_LEASE_HANDLE 1: SMB2_LEASE_WRITE breaking : 0x00 (0) breaking_to_requested : 0x00000000 (0) 0: SMB2_LEASE_READ 0: SMB2_LEASE_HANDLE 0: SMB2_LEASE_WRITE breaking_to_required : 0x00000000 (0) 0: SMB2_LEASE_READ 0: SMB2_LEASE_HANDLE 0: SMB2_LEASE_WRITE lease_version : 0x0002 (2) epoch : 0x0001 (1) num_delete_tokens : 0x00000000 (0) delete_tokens: ARRAY(0) old_write_time : Thu Aug 7 11:02:08 AM 2014 CEST.0 changed_write_time : Thu Jan 1 01:00:00 AM 1970 CET.0 fresh : 0x01 (1) modified : 0x01 (1) record : * [2015/02/18 05:54:45.602170, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap_tdb.c:60(db_tdb_log_key) Unlocking key 01FD000000000000810A [2015/02/18 05:54:45.602212, 5, pid=12720, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap.c:146(dbwrap_lock_order_state_destructor) release lock order 1 for /opt/samba/var/lock/locking.tdb [2015/02/18 05:54:45.602237, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap.c:133(debug_lock_order) lock order: 1: 2: 3: [2015/02/18 05:54:45.602263, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:4758(create_file_unixpath) create_file_unixpath: info=1 [2015/02/18 05:54:45.602286, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:5037(create_file_default) create_file: info=1 [2015/02/18 05:54:45.602309, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/smb2_create.c:1093(smbd_smb2_create_send) smbd_smb2_create_send: response construction phase [2015/02/18 05:54:45.602347, 10, pid=12720, effective(1000, 1000), real(1000, 0), class=acls] ../source3/smbd/posix_acls.c:3521(posix_get_nt_acl) posix_get_nt_acl: called for file README [2015/02/18 05:54:45.602593, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/passdb/lookup_sid.c:1198(uid_to_sid) uid 1000 -> sid S-1-5-21-1849679311-379505231-1387054432-1000 [2015/02/18 05:54:45.602638, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/passdb/lookup_sid.c:1247(gid_to_sid) gid 0 -> sid S-1-22-2-0 [2015/02/18 05:54:45.602669, 10, pid=12720, effective(1000, 1000), real(1000, 0), class=acls] ../source3/smbd/posix_acls.c:2724(canonicalise_acl) canonicalise_acl: Access ace entries before arrange : [2015/02/18 05:54:45.602693, 10, pid=12720, effective(1000, 1000), real(1000, 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 r-- [2015/02/18 05:54:45.602720, 10, pid=12720, effective(1000, 1000), real(1000, 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 r-- [2015/02/18 05:54:45.602887, 10, pid=12720, effective(1000, 1000), real(1000, 0), class=acls] ../source3/smbd/posix_acls.c:2737(canonicalise_acl) canon_ace index 2. Type = allow SID = S-1-5-21-1849679311-379505231-1387054432-1000 uid 1000 (ralph) SMB_ACL_USER_OBJ ace_flags = 0x0 perms rw- [2015/02/18 05:54:45.602962, 10, pid=12720, effective(1000, 1000), real(1000, 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-5-21-1849679311-379505231-1387054432-1000 uid 1000 (ralph) SMB_ACL_USER_OBJ ace_flags = 0x0 perms rw- canon_ace index 1. Type = allow SID = S-1-22-2-0 gid 0 (root) SMB_ACL_GROUP_OBJ ace_flags = 0x0 perms r-- canon_ace index 2. Type = allow SID = S-1-1-0 other SMB_ACL_OTHER ace_flags = 0x0 perms r-- [2015/02/18 05:54:45.603067, 10, pid=12720, effective(1000, 1000), real(1000, 0), class=acls] ../source3/smbd/posix_acls.c:1110(map_canon_ace_perms) map_canon_ace_perms: Mapped (UNIX) 180 to (NT) 12019f [2015/02/18 05:54:45.603093, 10, pid=12720, effective(1000, 1000), real(1000, 0), class=acls] ../source3/smbd/posix_acls.c:1110(map_canon_ace_perms) map_canon_ace_perms: Mapped (UNIX) 100 to (NT) 120089 [2015/02/18 05:54:45.603117, 10, pid=12720, effective(1000, 1000), real(1000, 0), class=acls] ../source3/smbd/posix_acls.c:1110(map_canon_ace_perms) map_canon_ace_perms: Mapped (UNIX) 100 to (NT) 120089 [2015/02/18 05:54:45.603158, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../libcli/security/access_check.c:188(se_access_check) se_access_check: MAX desired = 0x2000000, granted = 0x16019f, remaining = 0x16019f [2015/02/18 05:54:45.603210, 10, pid=12720, effective(1000, 1000), real(1000, 0), class=acls] ../source3/smbd/posix_acls.c:3521(posix_get_nt_acl) posix_get_nt_acl: called for file . [2015/02/18 05:54:45.603262, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/passdb/lookup_sid.c:1198(uid_to_sid) uid 0 -> sid S-1-5-21-1849679311-379505231-1387054432-1001 [2015/02/18 05:54:45.603301, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/passdb/lookup_sid.c:1247(gid_to_sid) gid 0 -> sid S-1-22-2-0 [2015/02/18 05:54:45.603329, 10, pid=12720, effective(1000, 1000), real(1000, 0), class=acls] ../source3/smbd/posix_acls.c:2724(canonicalise_acl) canonicalise_acl: Access ace entries before arrange : [2015/02/18 05:54:45.603352, 10, pid=12720, effective(1000, 1000), real(1000, 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 [2015/02/18 05:54:45.603379, 10, pid=12720, effective(1000, 1000), real(1000, 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 [2015/02/18 05:54:45.603534, 10, pid=12720, effective(1000, 1000), real(1000, 0), class=acls] ../source3/smbd/posix_acls.c:2737(canonicalise_acl) canon_ace index 2. Type = allow SID = S-1-5-21-1849679311-379505231-1387054432-1001 uid 0 (root) SMB_ACL_USER_OBJ ace_flags = 0x0 perms rwx [2015/02/18 05:54:45.603679, 10, pid=12720, effective(1000, 1000), real(1000, 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-5-21-1849679311-379505231-1387054432-1001 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 [2015/02/18 05:54:45.603778, 10, pid=12720, effective(1000, 1000), real(1000, 0), class=acls] ../source3/smbd/posix_acls.c:1110(map_canon_ace_perms) map_canon_ace_perms: Mapped (UNIX) 1c0 to (NT) 1f01ff [2015/02/18 05:54:45.603804, 10, pid=12720, effective(1000, 1000), real(1000, 0), class=acls] ../source3/smbd/posix_acls.c:1110(map_canon_ace_perms) map_canon_ace_perms: Mapped (UNIX) 1c0 to (NT) 1f01ff [2015/02/18 05:54:45.603828, 10, pid=12720, effective(1000, 1000), real(1000, 0), class=acls] ../source3/smbd/posix_acls.c:1110(map_canon_ace_perms) map_canon_ace_perms: Mapped (UNIX) 1c0 to (NT) 1f01ff [2015/02/18 05:54:45.603866, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:174(smbd_check_access_rights) smbd_check_access_rights: file . requesting 0x40 returning 0x40 (NT_STATUS_OK) [2015/02/18 05:54:45.603901, 5, pid=12720, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap.c:178(dbwrap_check_lock_order) check lock order 1 for /opt/samba/var/lock/smbXsrv_open_global.tdb [2015/02/18 05:54:45.603926, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap.c:133(debug_lock_order) lock order: 1:/opt/samba/var/lock/smbXsrv_open_global.tdb 2: 3: [2015/02/18 05:54:45.603952, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap_tdb.c:60(db_tdb_log_key) Locking key 1330144F [2015/02/18 05:54:45.603983, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap_tdb.c:144(db_tdb_fetch_locked_internal) Allocated locked data 0x0x7fb80e10cab0 [2015/02/18 05:54:45.604023, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/smbXsrv_open.c:706(smbXsrv_open_global_store) smbXsrv_open_global_store: key '1330144F' stored [2015/02/18 05:54:45.604050, 1, pid=12720, effective(1000, 1000), real(1000, 0)] ../librpc/ndr/ndr.c:402(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 : 0x00000000000031b0 (12720) task_id : 0x00000000 (0) vnn : 0xffffffff (4294967295) unique_id : 0xfb17366705686992 (-353754229625034350) open_global_id : 0x1330144f (321918031) open_persistent_id : 0x000000001330144f (321918031) open_volatile_id : 0x000000005ef23051 (1592930385) open_owner : S-1-5-21-1849679311-379505231-1387054432-1000 open_time : Wed Feb 18 05:54:46 AM 2015 CET create_guid : 80778864-b1c8-11e4-a338-0800275b519b client_guid : 807779ee-b1c8-11e4-a338-0800275b519b 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 [2015/02/18 05:54:45.604227, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap_tdb.c:60(db_tdb_log_key) Unlocking key 1330144F [2015/02/18 05:54:45.604254, 5, pid=12720, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap.c:146(dbwrap_lock_order_state_destructor) release lock order 1 for /opt/samba/var/lock/smbXsrv_open_global.tdb [2015/02/18 05:54:45.604278, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap.c:133(debug_lock_order) lock order: 1: 2: 3: [2015/02/18 05:54:45.604302, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/smbXsrv_open.c:951(smbXsrv_open_update) smbXsrv_open_update: global_id (0x1330144f) stored [2015/02/18 05:54:45.604325, 1, pid=12720, effective(1000, 1000), real(1000, 0)] ../librpc/ndr/ndr.c:402(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 : 0x5ef23051 (1592930385) global : * global: struct smbXsrv_open_global0 db_rec : NULL server_id: struct server_id pid : 0x00000000000031b0 (12720) task_id : 0x00000000 (0) vnn : 0xffffffff (4294967295) unique_id : 0xfb17366705686992 (-353754229625034350) open_global_id : 0x1330144f (321918031) open_persistent_id : 0x000000001330144f (321918031) open_volatile_id : 0x000000005ef23051 (1592930385) open_owner : S-1-5-21-1849679311-379505231-1387054432-1000 open_time : Wed Feb 18 05:54:46 AM 2015 CET create_guid : 80778864-b1c8-11e4-a338-0800275b519b client_guid : 807779ee-b1c8-11e4-a338-0800275b519b 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 status : NT_STATUS_OK idle_time : Wed Feb 18 05:54:46 AM 2015 CET compat : * [2015/02/18 05:54:45.604662, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/smb2_create.c:1149(smbd_smb2_create_send) smb2_create_send: smbXsrv_open_update returned NT_STATUS_OK [2015/02/18 05:54:45.604772, 8, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/dosmode.c:600(dos_mode) dos_mode: README [2015/02/18 05:54:45.604845, 8, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/dosmode.c:242(dos_mode_from_sbuf) dos_mode_from_sbuf returning [2015/02/18 05:54:45.604875, 8, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/dosmode.c:36(dos_mode_debug_print) dos_mode returning [2015/02/18 05:54:45.604912, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/smb2_create.c:1274(smbd_smb2_create_send) smbd_smb2_create_send: README - fnum 1592930385 [2015/02/18 05:54:45.604950, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/smb2_server.c:2564(smbd_smb2_request_done_ex) smbd_smb2_request_done_ex: idx[1] status[NT_STATUS_OK] body[88] dyn[yes:164] at ../source3/smbd/smb2_create.c:364 [2015/02/18 05:54:45.604987, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/smb2_server.c:899(smb2_set_operation_credit) smb2_set_operation_credit: requested 1, charge 1, granted 1, current possible/max 386/512, total granted/max/low/range 127/8192/61/127 [2015/02/18 05:54:45.607315, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/smb2_server.c:3432(smbd_smb2_io_handler) smbd_smb2_request idx[1] of 5 vectors [2015/02/18 05:54:45.607814, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/smb2_server.c:647(smb2_validate_sequence_number) smb2_validate_sequence_number: clearing id 61 (position 61) from bitmap [2015/02/18 05:54:45.607864, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/smb2_server.c:1957(smbd_smb2_request_dispatch) smbd_smb2_request_dispatch: opcode[SMB2_OP_READ] mid = 61 [2015/02/18 05:54:45.607904, 4, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/uid.c:384(change_to_user) Skipping user change - already user [2015/02/18 05:54:45.607995, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/smb2_server.c:1848(smbd_smb2_request_verify_creditcharge) mid 61, CreditCharge: 1, NeededCharge: 1 [2015/02/18 05:54:45.608051, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/smb2_read.c:452(smbd_smb2_read_send) smbd_smb2_read: README - fnum 1592930385 [2015/02/18 05:54:45.608142, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/aio.c:705(schedule_smb2_aio_read) smb2: read size (3967) too small for minimum aio_read of 0 [2015/02/18 05:54:45.608221, 10, pid=12720, effective(1000, 1000), real(1000, 0), class=locking] ../source3/locking/brlock.c:2032(brl_get_locks_readonly) seqnum=7, fsp->brlock_seqnum=6 [2015/02/18 05:54:45.608329, 10, pid=12720, effective(1000, 1000), real(1000, 0), class=locking] ../source3/locking/posix.c:305(is_posix_locked) is_posix_locked: File README, offset = 0, count = 3967, type = READ [2015/02/18 05:54:45.608381, 10, pid=12720, effective(1000, 1000), real(1000, 0), class=locking] ../source3/locking/posix.c:169(posix_lock_in_range) posix_lock_in_range: offset_out = 0, count_out = 3967 [2015/02/18 05:54:45.608621, 8, pid=12720, effective(1000, 1000), real(1000, 0), class=locking] ../source3/locking/posix.c:252(posix_fcntl_getlock) posix_fcntl_getlock 40 0 3967 0 [2015/02/18 05:54:45.608696, 8, pid=12720, effective(1000, 1000), real(1000, 0), class=locking] ../source3/lib/util.c:1158(fcntl_getlock) fcntl_getlock fd=40 offset=0 count=3967 type=0 [2015/02/18 05:54:45.608754, 3, pid=12720, effective(1000, 1000), real(1000, 0), class=locking] ../source3/lib/util.c:1182(fcntl_getlock) fcntl_getlock: fd 40 is returned info 2 pid 0 [2015/02/18 05:54:45.608875, 8, pid=12720, effective(1000, 1000), real(1000, 0), class=locking] ../source3/locking/posix.c:284(posix_fcntl_getlock) posix_fcntl_getlock: Lock query call successful [2015/02/18 05:54:45.608943, 10, pid=12720, effective(1000, 1000), real(1000, 0), class=locking] ../source3/locking/brlock.c:1422(brl_locktest) brl_locktest: posix start=0 len=3967 unlocked for fnum 1592930385 file README [2015/02/18 05:54:45.608987, 10, pid=12720, effective(1000, 1000), real(1000, 0), class=locking] ../source3/locking/locking.c:156(strict_lock_default) strict_lock_default: flavour = WINDOWS_LOCK brl start=0 len=3967 unlocked for fnum 1592930385 file README [2015/02/18 05:54:45.609104, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/fileio.c:98(read_file) read_file (README): pos = 0, size = 3967, returned 3967 [2015/02/18 05:54:45.609155, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/smb2_read.c:570(smbd_smb2_read_send) smbd_smb2_read: file README, fnum 1592930385, offset=0 len=3967 returned 3967 [2015/02/18 05:54:45.609202, 3, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/smb2_read.c:404(smb2_read_complete) smbd_smb2_read: fnum 1592930385, file README, length=3967 offset=0 read=3967 [2015/02/18 05:54:45.609272, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/smb2_server.c:2564(smbd_smb2_request_done_ex) smbd_smb2_request_done_ex: idx[1] status[NT_STATUS_OK] body[16] dyn[yes:3967] at ../source3/smbd/smb2_read.c:156 [2015/02/18 05:54:45.609311, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/smb2_server.c:899(smb2_set_operation_credit) smb2_set_operation_credit: requested 1, charge 1, granted 1, current possible/max 386/512, total granted/max/low/range 127/8192/62/127 [2015/02/18 05:54:45.612019, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/smb2_server.c:3432(smbd_smb2_io_handler) smbd_smb2_request idx[1] of 5 vectors [2015/02/18 05:54:45.612263, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/smb2_server.c:647(smb2_validate_sequence_number) smb2_validate_sequence_number: clearing id 62 (position 62) from bitmap [2015/02/18 05:54:45.612295, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/smb2_server.c:1957(smbd_smb2_request_dispatch) smbd_smb2_request_dispatch: opcode[SMB2_OP_CREATE] mid = 62 [2015/02/18 05:54:45.612330, 4, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/uid.c:384(change_to_user) Skipping user change - already user [2015/02/18 05:54:45.613862, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/smb2_create.c:501(smbd_smb2_create_send) smbd_smb2_create: name[README] [2015/02/18 05:54:45.614130, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/smb2_create.c:889(smbd_smb2_create_send) Got lease request size 52 [2015/02/18 05:54:45.615126, 1, pid=12720, effective(1000, 1000), real(1000, 0)] ../librpc/ndr/ndr.c:402(ndr_print_debug) lease_ptr: struct smb2_lease lease_key: struct smb2_lease_key data: ARRAY(2) data : 0x00000000cfb12998 (3484494232) data : 0x0000000000000140 (320) lease_state : 0x00000007 (7) 1: SMB2_LEASE_READ 1: SMB2_LEASE_HANDLE 1: SMB2_LEASE_WRITE lease_flags : 0x00000000 (0) lease_duration : 0x0000000000000000 (0) parent_lease_key: struct smb2_lease_key data: ARRAY(2) data : 0x0000000000000000 (0) data : 0x0000000000000000 (0) lease_version : 0x0002 (2) lease_epoch : 0x0001 (1) [2015/02/18 05:54:45.615917, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/smb2_create.c:911(smbd_smb2_create_send) smbd_smb2_create_send: open execution phase [2015/02/18 05:54:45.616003, 5, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/filename.c:258(unix_convert) unix_convert called on file "README" [2015/02/18 05:54:45.616089, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/statcache.c:283(stat_cache_lookup) stat_cache_lookup: lookup succeeded for name [README] -> [README] [2015/02/18 05:54:45.616164, 3, pid=12720, effective(1000, 1000), real(1000, 0), class=vfs] ../source3/smbd/vfs.c:1143(check_reduced_name) check_reduced_name [README] [/Volumes/normal] [2015/02/18 05:54:45.616235, 10, pid=12720, effective(1000, 1000), real(1000, 0), class=vfs] ../source3/smbd/vfs.c:1203(check_reduced_name) check_reduced_name realpath [README] -> [/Volumes/normal/README] [2015/02/18 05:54:45.616274, 3, pid=12720, effective(1000, 1000), real(1000, 0), class=vfs] ../source3/smbd/vfs.c:1273(check_reduced_name) check_reduced_name: README reduced to /Volumes/normal/README [2015/02/18 05:54:45.616316, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:4949(create_file_default) create_file: access_mask = 0x120089 file_attributes = 0x80, share_access = 0x3, create_disposition = 0x1 create_options = 0x40 oplock_request = 0x100 private_flags = 0x0 root_dir_fid = 0x0, ea_list = 0x(nil), sd = 0x(nil), fname = README [2015/02/18 05:54:45.616362, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:4422(create_file_unixpath) create_file_unixpath: access_mask = 0x120089 file_attributes = 0x80, share_access = 0x3, create_disposition = 0x1 create_options = 0x40 oplock_request = 0x100 private_flags = 0x0 ea_list = 0x(nil), sd = 0x(nil), fname = README [2015/02/18 05:54:45.616549, 10, pid=12720, effective(1000, 1000), real(1000, 0), class=locking] ../source3/locking/leases_db.c:75(leases_db_key) leases_db_key: [2015/02/18 05:54:45.616596, 1, pid=12720, effective(1000, 1000), real(1000, 0)] ../librpc/ndr/ndr.c:402(ndr_print_debug) &db_key: struct leases_db_key client_guid : 807779ee-b1c8-11e4-a338-0800275b519b lease_key: struct smb2_lease_key data: ARRAY(2) data : 0x00000000cfb12998 (3484494232) data : 0x0000000000000140 (320) [2015/02/18 05:54:45.616775, 10, pid=12720, effective(1000, 1000), real(1000, 0), class=locking] ../source3/locking/leases_db.c:356(leases_db_parser) leases_db_parser: [2015/02/18 05:54:45.616835, 1, pid=12720, effective(1000, 1000), real(1000, 0)] ../librpc/ndr/ndr.c:402(ndr_print_debug) value: struct leases_db_value num_files : 0x00000001 (1) files: ARRAY(1) files: struct leases_db_file id: struct file_id devid : 0x000000000000fd01 (64769) inode : 0x0000000000080a81 (526977) extid : 0x0000000000000000 (0) servicepath : * servicepath : '/Volumes/normal' base_name : * base_name : 'README' stream_name : NULL [2015/02/18 05:54:45.617065, 5, pid=12720, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap.c:178(dbwrap_check_lock_order) check lock order 1 for /opt/samba/var/lock/smbXsrv_open_global.tdb [2015/02/18 05:54:45.617138, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap.c:133(debug_lock_order) lock order: 1:/opt/samba/var/lock/smbXsrv_open_global.tdb 2: 3: [2015/02/18 05:54:45.617190, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap_tdb.c:60(db_tdb_log_key) Locking key 6A86B967 [2015/02/18 05:54:45.617254, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap_tdb.c:144(db_tdb_fetch_locked_internal) Allocated locked data 0x0x7fb80e109510 [2015/02/18 05:54:45.617300, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/smbXsrv_open.c:588(smbXsrv_open_global_verify_record) smbXsrv_open_global_verify_record: empty value [2015/02/18 05:54:45.620102, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/smbXsrv_open.c:706(smbXsrv_open_global_store) smbXsrv_open_global_store: key '6A86B967' stored [2015/02/18 05:54:45.620200, 1, pid=12720, effective(1000, 1000), real(1000, 0)] ../librpc/ndr/ndr.c:402(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 : 0x00000000000031b0 (12720) task_id : 0x00000000 (0) vnn : 0xffffffff (4294967295) unique_id : 0xfb17366705686992 (-353754229625034350) open_global_id : 0x6a86b967 (1787214183) open_persistent_id : 0x000000006a86b967 (1787214183) open_volatile_id : 0x000000004d957c3e (1301642302) open_owner : S-1-5-21-1849679311-379505231-1387054432-1000 open_time : Wed Feb 18 05:54:46 AM 2015 CET create_guid : 00000000-0000-0000-0000-000000000000 client_guid : 807779ee-b1c8-11e4-a338-0800275b519b 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 [2015/02/18 05:54:45.620902, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap_tdb.c:60(db_tdb_log_key) Unlocking key 6A86B967 [2015/02/18 05:54:45.620995, 5, pid=12720, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap.c:146(dbwrap_lock_order_state_destructor) release lock order 1 for /opt/samba/var/lock/smbXsrv_open_global.tdb [2015/02/18 05:54:45.621044, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap.c:133(debug_lock_order) lock order: 1: 2: 3: [2015/02/18 05:54:45.621094, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/smbXsrv_open.c:880(smbXsrv_open_create) smbXsrv_open_create: global_id (0x6a86b967) stored [2015/02/18 05:54:45.621138, 1, pid=12720, effective(1000, 1000), real(1000, 0)] ../librpc/ndr/ndr.c:402(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 : 0x4d957c3e (1301642302) global : * global: struct smbXsrv_open_global0 db_rec : NULL server_id: struct server_id pid : 0x00000000000031b0 (12720) task_id : 0x00000000 (0) vnn : 0xffffffff (4294967295) unique_id : 0xfb17366705686992 (-353754229625034350) open_global_id : 0x6a86b967 (1787214183) open_persistent_id : 0x000000006a86b967 (1787214183) open_volatile_id : 0x000000004d957c3e (1301642302) open_owner : S-1-5-21-1849679311-379505231-1387054432-1000 open_time : Wed Feb 18 05:54:46 AM 2015 CET create_guid : 00000000-0000-0000-0000-000000000000 client_guid : 807779ee-b1c8-11e4-a338-0800275b519b 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 status : NT_STATUS_OK idle_time : Wed Feb 18 05:54:46 AM 2015 CET compat : NULL [2015/02/18 05:54:45.623317, 5, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/files.c:129(file_new) allocated file structure fnum 1301642302 (4 used) [2015/02/18 05:54:45.623376, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/files.c:743(file_name_hash) file_name_hash: /Volumes/normal/README hash 0x7d551025 [2015/02/18 05:54:45.623556, 3, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/dosmode.c:196(unix_mode) unix_mode(README) returning 0744 [2015/02/18 05:54:45.623613, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:2478(open_file_ntcreate) open_file_ntcreate: fname=README, dos_attrs=0x80 access_mask=0x120089 share_access=0x3 create_disposition = 0x1 create_options=0x40 unix mode=0744 oplock_request=256 private_flags = 0x0 [2015/02/18 05:54:45.623655, 8, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/dosmode.c:600(dos_mode) dos_mode: README [2015/02/18 05:54:45.623714, 8, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/dosmode.c:242(dos_mode_from_sbuf) dos_mode_from_sbuf returning [2015/02/18 05:54:45.623757, 8, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/dosmode.c:36(dos_mode_debug_print) dos_mode returning [2015/02/18 05:54:45.623806, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:2636(open_file_ntcreate) open_file_ntcreate: fname=README, after mapping access_mask=0x120089 [2015/02/18 05:54:45.623849, 4, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:2726(open_file_ntcreate) calling open_file with flags=0x0 flags2=0x0 mode=0744, access_mask = 0x120089, open_access_mask = 0x120089 [2015/02/18 05:54:45.623903, 10, pid=12720, effective(1000, 1000), real(1000, 0), class=acls] ../source3/smbd/posix_acls.c:3521(posix_get_nt_acl) posix_get_nt_acl: called for file README [2015/02/18 05:54:45.623999, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/passdb/lookup_sid.c:1198(uid_to_sid) uid 1000 -> sid S-1-5-21-1849679311-379505231-1387054432-1000 [2015/02/18 05:54:45.624052, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/passdb/lookup_sid.c:1247(gid_to_sid) gid 0 -> sid S-1-22-2-0 [2015/02/18 05:54:45.624098, 10, pid=12720, effective(1000, 1000), real(1000, 0), class=acls] ../source3/smbd/posix_acls.c:2724(canonicalise_acl) canonicalise_acl: Access ace entries before arrange : [2015/02/18 05:54:45.624135, 10, pid=12720, effective(1000, 1000), real(1000, 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 r-- [2015/02/18 05:54:45.624151, 10, pid=12720, effective(1000, 1000), real(1000, 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 r-- [2015/02/18 05:54:45.624591, 10, pid=12720, effective(1000, 1000), real(1000, 0), class=acls] ../source3/smbd/posix_acls.c:2737(canonicalise_acl) canon_ace index 2. Type = allow SID = S-1-5-21-1849679311-379505231-1387054432-1000 uid 1000 (ralph) SMB_ACL_USER_OBJ ace_flags = 0x0 perms rw- [2015/02/18 05:54:45.624773, 10, pid=12720, effective(1000, 1000), real(1000, 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-5-21-1849679311-379505231-1387054432-1000 uid 1000 (ralph) SMB_ACL_USER_OBJ ace_flags = 0x0 perms rw- canon_ace index 1. Type = allow SID = S-1-22-2-0 gid 0 (root) SMB_ACL_GROUP_OBJ ace_flags = 0x0 perms r-- canon_ace index 2. Type = allow SID = S-1-1-0 other SMB_ACL_OTHER ace_flags = 0x0 perms r-- [2015/02/18 05:54:45.624945, 10, pid=12720, effective(1000, 1000), real(1000, 0), class=acls] ../source3/smbd/posix_acls.c:1110(map_canon_ace_perms) map_canon_ace_perms: Mapped (UNIX) 180 to (NT) 12019f [2015/02/18 05:54:45.624988, 10, pid=12720, effective(1000, 1000), real(1000, 0), class=acls] ../source3/smbd/posix_acls.c:1110(map_canon_ace_perms) map_canon_ace_perms: Mapped (UNIX) 100 to (NT) 120089 [2015/02/18 05:54:45.625028, 10, pid=12720, effective(1000, 1000), real(1000, 0), class=acls] ../source3/smbd/posix_acls.c:1110(map_canon_ace_perms) map_canon_ace_perms: Mapped (UNIX) 100 to (NT) 120089 [2015/02/18 05:54:45.625093, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:174(smbd_check_access_rights) smbd_check_access_rights: file README requesting 0x120089 returning 0x120009 (NT_STATUS_OK) [2015/02/18 05:54:45.625166, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:408(fd_open) fd_open: name README, flags = 00 mode = 0744, fd = 43. [2015/02/18 05:54:45.625228, 2, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:1005(open_file) ralph opened file README read=Yes write=No (numopen=4) [2015/02/18 05:54:45.625234, 5, pid=12720, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap.c:178(dbwrap_check_lock_order) check lock order 1 for /opt/samba/var/lock/locking.tdb [2015/02/18 05:54:45.625315, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap.c:133(debug_lock_order) lock order: 1:/opt/samba/var/lock/locking.tdb 2: 3: [2015/02/18 05:54:45.625423, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap_tdb.c:60(db_tdb_log_key) Locking key 01FD000000000000810A [2015/02/18 05:54:45.625587, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap_tdb.c:144(db_tdb_fetch_locked_internal) Allocated locked data 0x0x7fb80e120030 [2015/02/18 05:54:45.625674, 10, pid=12720, effective(1000, 1000), real(1000, 0), class=locking] ../source3/locking/share_mode_lock.c:174(parse_share_modes) parse_share_modes: [2015/02/18 05:54:45.632095, 1, pid=12720, effective(1000, 1000), real(1000, 0)] ../librpc/ndr/ndr.c:402(ndr_print_debug) d: struct share_mode_data servicepath : * servicepath : '/Volumes/normal' base_name : * base_name : 'README' stream_name : NULL num_share_modes : 0x00000001 (1) share_modes: ARRAY(1) share_modes: struct share_mode_entry pid: struct server_id pid : 0x00000000000031b0 (12720) task_id : 0x00000000 (0) vnn : 0xffffffff (4294967295) unique_id : 0xfb17366705686992 (-353754229625034350) op_mid : 0x000000000000003c (60) op_type : 0x0100 (256) lease_idx : 0x00000000 (0) access_mask : 0x00120089 (1179785) share_access : 0x00000001 (1) private_options : 0x00000000 (0) time : Wed Feb 18 05:54:45 AM 2015 CET.581827 id: struct file_id devid : 0x000000000000fd01 (64769) inode : 0x0000000000080a81 (526977) extid : 0x0000000000000000 (0) share_file_id : 0x000000003357c520 (861390112) uid : 0x000003e8 (1000) flags : 0x0000 (0) name_hash : 0x7d551025 (2102726693) stale : 0x00 (0) lease : * lease: struct share_mode_lease client_guid : 807779ee-b1c8-11e4-a338-0800275b519b lease_key: struct smb2_lease_key data: ARRAY(2) data : 0x00000000cfb12998 (3484494232) data : 0x0000000000000140 (320) current_state : 0x00000007 (7) 1: SMB2_LEASE_READ 1: SMB2_LEASE_HANDLE 1: SMB2_LEASE_WRITE breaking : 0x00 (0) breaking_to_requested : 0x00000000 (0) 0: SMB2_LEASE_READ 0: SMB2_LEASE_HANDLE 0: SMB2_LEASE_WRITE breaking_to_required : 0x00000000 (0) 0: SMB2_LEASE_READ 0: SMB2_LEASE_HANDLE 0: SMB2_LEASE_WRITE lease_version : 0x0002 (2) epoch : 0x0001 (1) num_leases : 0x00000001 (1) leases: ARRAY(1) leases: struct share_mode_lease client_guid : 807779ee-b1c8-11e4-a338-0800275b519b lease_key: struct smb2_lease_key data: ARRAY(2) data : 0x00000000cfb12998 (3484494232) data : 0x0000000000000140 (320) current_state : 0x00000007 (7) 1: SMB2_LEASE_READ 1: SMB2_LEASE_HANDLE 1: SMB2_LEASE_WRITE breaking : 0x00 (0) breaking_to_requested : 0x00000000 (0) 0: SMB2_LEASE_READ 0: SMB2_LEASE_HANDLE 0: SMB2_LEASE_WRITE breaking_to_required : 0x00000000 (0) 0: SMB2_LEASE_READ 0: SMB2_LEASE_HANDLE 0: SMB2_LEASE_WRITE lease_version : 0x0002 (2) epoch : 0x0001 (1) num_delete_tokens : 0x00000000 (0) delete_tokens: ARRAY(0) old_write_time : Thu Aug 7 11:02:08 AM 2014 CEST.0 changed_write_time : Thu Jan 1 01:00:00 AM 1970 CET.0 fresh : 0x00 (0) modified : 0x00 (0) record : NULL [2015/02/18 05:54:45.633379, 10, pid=12720, effective(1000, 1000), real(1000, 0), class=locking] ../source3/locking/locking.c:1192(find_delete_on_close_token) find_delete_on_close_token: name_hash = 0x7d551025 [2015/02/18 05:54:45.633569, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:1025(share_conflict) share_conflict: entry->access_mask = 0x120089, entry->share_access = 0x1, entry->private_options = 0x0 [2015/02/18 05:54:45.633624, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:1036(share_conflict) share_conflict: access_mask = 0x120089, share_access = 0x3 [2015/02/18 05:54:45.633680, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:1085(share_conflict) share_conflict: [1] am (0x120089) & right (0x6) = 0x0 [2015/02/18 05:54:45.633721, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:1085(share_conflict) share_conflict: [1] sa (0x3) & share (0x2) = 0x2 [2015/02/18 05:54:45.633759, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:1087(share_conflict) share_conflict: [2] am (0x120089) & right (0x6) = 0x0 [2015/02/18 05:54:45.633796, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:1087(share_conflict) share_conflict: [2] sa (0x1) & share (0x2) = 0x0 [2015/02/18 05:54:45.633836, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:1090(share_conflict) share_conflict: [3] am (0x120089) & right (0x21) = 0x1 [2015/02/18 05:54:45.633873, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:1090(share_conflict) share_conflict: [3] sa (0x3) & share (0x1) = 0x1 [2015/02/18 05:54:45.633899, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:1092(share_conflict) share_conflict: [4] am (0x120089) & right (0x21) = 0x1 [2015/02/18 05:54:45.633962, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:1092(share_conflict) share_conflict: [4] sa (0x1) & share (0x1) = 0x1 [2015/02/18 05:54:45.634000, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:1095(share_conflict) share_conflict: [5] am (0x120089) & right (0x10000) = 0x0 [2015/02/18 05:54:45.634038, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:1095(share_conflict) share_conflict: [5] sa (0x3) & share (0x4) = 0x0 [2015/02/18 05:54:45.634076, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:1097(share_conflict) share_conflict: [6] am (0x120089) & right (0x10000) = 0x0 [2015/02/18 05:54:45.634114, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:1097(share_conflict) share_conflict: [6] sa (0x1) & share (0x4) = 0x0 [2015/02/18 05:54:45.634152, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:1099(share_conflict) share_conflict: No conflict. [2015/02/18 05:54:45.634188, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:1442(delay_for_oplock) entry 0: e_lease_type 7, will_overwrite: 0 [2015/02/18 05:54:45.634254, 10, pid=12720, effective(1000, 1000), real(1000, 0), class=locking] ../source3/locking/brlock.c:2032(brl_get_locks_readonly) seqnum=7, fsp->brlock_seqnum=0 [2015/02/18 05:54:45.634326, 10, pid=12720, effective(1000, 1000), real(1000, 0), class=locking] ../source3/locking/locking.c:748(share_mode_stale_pid) PID 12720 (index 0 out of 1) still exists [2015/02/18 05:54:45.634373, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:1634(grant_fsp_lease) existing=7, requested=7, granted=7, do_upgrade=0 [2015/02/18 05:54:45.634592, 10, pid=12720, effective(1000, 1000), real(1000, 0), class=locking] ../source3/smbd/oplock.c:389(fsp_lease_update) fsp_lease_update: refresh lease state [2015/02/18 05:54:45.634645, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:1827(grant_fsp_oplock_type) lease_state=7 [2015/02/18 05:54:45.634688, 10, pid=12720, effective(1000, 1000), real(1000, 0), class=locking] ../source3/locking/brlock.c:2032(brl_get_locks_readonly) seqnum=7, fsp->brlock_seqnum=7 [2015/02/18 05:54:45.634732, 5, pid=12720, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap.c:178(dbwrap_check_lock_order) check lock order 2 for /opt/samba/var/lock/brlock.tdb [2015/02/18 05:54:45.634807, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap.c:133(debug_lock_order) lock order: 1:/opt/samba/var/lock/locking.tdb 2:/opt/samba/var/lock/brlock.tdb 3: [2015/02/18 05:54:45.634870, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap_tdb.c:60(db_tdb_log_key) Locking key 01FD000000000000810A [2015/02/18 05:54:45.634920, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap_tdb.c:144(db_tdb_fetch_locked_internal) Allocated locked data 0x0x7fb80e122470 [2015/02/18 05:54:45.634961, 10, pid=12720, effective(1000, 1000), real(1000, 0), class=locking] ../source3/locking/brlock.c:1990(brl_get_locks) brl_get_locks_internal: 0 current locks on file_id fd01:80a81:0 [2015/02/18 05:54:45.634994, 10, pid=12720, effective(1000, 1000), real(1000, 0), class=locking] ../source3/locking/brlock.c:94(brl_set_num_read_oplocks) Setting num_read_oplocks to 2 [2015/02/18 05:54:45.635072, 10, pid=12720, effective(1000, 1000), real(1000, 0), class=locking] ../source3/locking/brlock.c:1908(byte_range_lock_flush) seqnum=8 [2015/02/18 05:54:45.635118, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap_tdb.c:60(db_tdb_log_key) Unlocking key 01FD000000000000810A [2015/02/18 05:54:45.635161, 5, pid=12720, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap.c:146(dbwrap_lock_order_state_destructor) release lock order 2 for /opt/samba/var/lock/brlock.tdb [2015/02/18 05:54:45.635199, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap.c:133(debug_lock_order) lock order: 1:/opt/samba/var/lock/locking.tdb 2: 3: [2015/02/18 05:54:45.635239, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:1873(grant_fsp_oplock_type) grant_fsp_oplock_type: oplock type 0x100 on file README [2015/02/18 05:54:45.635282, 10, pid=12720, effective(1000, 1000), real(1000, 0), class=locking] ../source3/locking/share_mode_lock.c:194(unparse_share_modes) unparse_share_modes: [2015/02/18 05:54:45.635322, 1, pid=12720, effective(1000, 1000), real(1000, 0)] ../librpc/ndr/ndr.c:402(ndr_print_debug) d: struct share_mode_data servicepath : * servicepath : '/Volumes/normal' base_name : * base_name : 'README' stream_name : NULL num_share_modes : 0x00000002 (2) share_modes: ARRAY(2) share_modes: struct share_mode_entry pid: struct server_id pid : 0x00000000000031b0 (12720) task_id : 0x00000000 (0) vnn : 0xffffffff (4294967295) unique_id : 0xfb17366705686992 (-353754229625034350) op_mid : 0x000000000000003c (60) op_type : 0x0100 (256) lease_idx : 0x00000000 (0) access_mask : 0x00120089 (1179785) share_access : 0x00000001 (1) private_options : 0x00000000 (0) time : Wed Feb 18 05:54:45 AM 2015 CET.581827 id: struct file_id devid : 0x000000000000fd01 (64769) inode : 0x0000000000080a81 (526977) extid : 0x0000000000000000 (0) share_file_id : 0x000000003357c520 (861390112) uid : 0x000003e8 (1000) flags : 0x0000 (0) name_hash : 0x7d551025 (2102726693) stale : 0x00 (0) lease : * lease: struct share_mode_lease client_guid : 807779ee-b1c8-11e4-a338-0800275b519b lease_key: struct smb2_lease_key data: ARRAY(2) data : 0x00000000cfb12998 (3484494232) data : 0x0000000000000140 (320) current_state : 0x00000007 (7) 1: SMB2_LEASE_READ 1: SMB2_LEASE_HANDLE 1: SMB2_LEASE_WRITE breaking : 0x00 (0) breaking_to_requested : 0x00000000 (0) 0: SMB2_LEASE_READ 0: SMB2_LEASE_HANDLE 0: SMB2_LEASE_WRITE breaking_to_required : 0x00000000 (0) 0: SMB2_LEASE_READ 0: SMB2_LEASE_HANDLE 0: SMB2_LEASE_WRITE lease_version : 0x0002 (2) epoch : 0x0001 (1) share_modes: struct share_mode_entry pid: struct server_id pid : 0x00000000000031b0 (12720) task_id : 0x00000000 (0) vnn : 0xffffffff (4294967295) unique_id : 0xfb17366705686992 (-353754229625034350) op_mid : 0x000000000000003e (62) op_type : 0x0100 (256) lease_idx : 0x00000000 (0) access_mask : 0x00120089 (1179785) share_access : 0x00000003 (3) private_options : 0x00000000 (0) time : Wed Feb 18 05:54:45 AM 2015 CET.617039 id: struct file_id devid : 0x000000000000fd01 (64769) inode : 0x0000000000080a81 (526977) extid : 0x0000000000000000 (0) share_file_id : 0x00000000db0ae006 (3674923014) uid : 0x000003e8 (1000) flags : 0x0000 (0) name_hash : 0x7d551025 (2102726693) stale : 0x00 (0) lease : * lease: struct share_mode_lease client_guid : 807779ee-b1c8-11e4-a338-0800275b519b lease_key: struct smb2_lease_key data: ARRAY(2) data : 0x00000000cfb12998 (3484494232) data : 0x0000000000000140 (320) current_state : 0x00000007 (7) 1: SMB2_LEASE_READ 1: SMB2_LEASE_HANDLE 1: SMB2_LEASE_WRITE breaking : 0x00 (0) breaking_to_requested : 0x00000000 (0) 0: SMB2_LEASE_READ 0: SMB2_LEASE_HANDLE 0: SMB2_LEASE_WRITE breaking_to_required : 0x00000000 (0) 0: SMB2_LEASE_READ 0: SMB2_LEASE_HANDLE 0: SMB2_LEASE_WRITE lease_version : 0x0002 (2) epoch : 0x0001 (1) num_leases : 0x00000001 (1) leases: ARRAY(1) leases: struct share_mode_lease client_guid : 807779ee-b1c8-11e4-a338-0800275b519b lease_key: struct smb2_lease_key data: ARRAY(2) data : 0x00000000cfb12998 (3484494232) data : 0x0000000000000140 (320) current_state : 0x00000007 (7) 1: SMB2_LEASE_READ 1: SMB2_LEASE_HANDLE 1: SMB2_LEASE_WRITE breaking : 0x00 (0) breaking_to_requested : 0x00000000 (0) 0: SMB2_LEASE_READ 0: SMB2_LEASE_HANDLE 0: SMB2_LEASE_WRITE breaking_to_required : 0x00000000 (0) 0: SMB2_LEASE_READ 0: SMB2_LEASE_HANDLE 0: SMB2_LEASE_WRITE lease_version : 0x0002 (2) epoch : 0x0001 (1) num_delete_tokens : 0x00000000 (0) delete_tokens: ARRAY(0) old_write_time : Thu Aug 7 11:02:08 AM 2014 CEST.0 changed_write_time : Thu Jan 1 01:00:00 AM 1970 CET.0 fresh : 0x00 (0) modified : 0x01 (1) record : * [2015/02/18 05:54:45.637162, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap_tdb.c:60(db_tdb_log_key) Unlocking key 01FD000000000000810A [2015/02/18 05:54:45.637257, 5, pid=12720, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap.c:146(dbwrap_lock_order_state_destructor) release lock order 1 for /opt/samba/var/lock/locking.tdb [2015/02/18 05:54:45.637306, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap.c:133(debug_lock_order) lock order: 1: 2: 3: [2015/02/18 05:54:45.637357, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:4758(create_file_unixpath) create_file_unixpath: info=1 [2015/02/18 05:54:45.637402, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:5037(create_file_default) create_file: info=1 [2015/02/18 05:54:45.638199, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/smb2_create.c:1093(smbd_smb2_create_send) smbd_smb2_create_send: response construction phase [2015/02/18 05:54:45.638301, 10, pid=12720, effective(1000, 1000), real(1000, 0), class=acls] ../source3/smbd/posix_acls.c:3521(posix_get_nt_acl) posix_get_nt_acl: called for file README [2015/02/18 05:54:45.638428, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/passdb/lookup_sid.c:1198(uid_to_sid) uid 1000 -> sid S-1-5-21-1849679311-379505231-1387054432-1000 [2015/02/18 05:54:45.638561, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/passdb/lookup_sid.c:1247(gid_to_sid) gid 0 -> sid S-1-22-2-0 [2015/02/18 05:54:45.638624, 10, pid=12720, effective(1000, 1000), real(1000, 0), class=acls] ../source3/smbd/posix_acls.c:2724(canonicalise_acl) canonicalise_acl: Access ace entries before arrange : [2015/02/18 05:54:45.639357, 10, pid=12720, effective(1000, 1000), real(1000, 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 r-- [2015/02/18 05:54:45.639578, 10, pid=12720, effective(1000, 1000), real(1000, 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 r-- [2015/02/18 05:54:45.639742, 10, pid=12720, effective(1000, 1000), real(1000, 0), class=acls] ../source3/smbd/posix_acls.c:2737(canonicalise_acl) canon_ace index 2. Type = allow SID = S-1-5-21-1849679311-379505231-1387054432-1000 uid 1000 (ralph) SMB_ACL_USER_OBJ ace_flags = 0x0 perms rw- [2015/02/18 05:54:45.639885, 10, pid=12720, effective(1000, 1000), real(1000, 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-5-21-1849679311-379505231-1387054432-1000 uid 1000 (ralph) SMB_ACL_USER_OBJ ace_flags = 0x0 perms rw- canon_ace index 1. Type = allow SID = S-1-22-2-0 gid 0 (root) SMB_ACL_GROUP_OBJ ace_flags = 0x0 perms r-- canon_ace index 2. Type = allow SID = S-1-1-0 other SMB_ACL_OTHER ace_flags = 0x0 perms r-- [2015/02/18 05:54:45.640052, 10, pid=12720, effective(1000, 1000), real(1000, 0), class=acls] ../source3/smbd/posix_acls.c:1110(map_canon_ace_perms) map_canon_ace_perms: Mapped (UNIX) 180 to (NT) 12019f [2015/02/18 05:54:45.640081, 10, pid=12720, effective(1000, 1000), real(1000, 0), class=acls] ../source3/smbd/posix_acls.c:1110(map_canon_ace_perms) map_canon_ace_perms: Mapped (UNIX) 100 to (NT) 120089 [2015/02/18 05:54:45.640106, 10, pid=12720, effective(1000, 1000), real(1000, 0), class=acls] ../source3/smbd/posix_acls.c:1110(map_canon_ace_perms) map_canon_ace_perms: Mapped (UNIX) 100 to (NT) 120089 [2015/02/18 05:54:45.640154, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../libcli/security/access_check.c:188(se_access_check) se_access_check: MAX desired = 0x2000000, granted = 0x16019f, remaining = 0x16019f [2015/02/18 05:54:45.640211, 10, pid=12720, effective(1000, 1000), real(1000, 0), class=acls] ../source3/smbd/posix_acls.c:3521(posix_get_nt_acl) posix_get_nt_acl: called for file . [2015/02/18 05:54:45.640282, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/passdb/lookup_sid.c:1198(uid_to_sid) uid 0 -> sid S-1-5-21-1849679311-379505231-1387054432-1001 [2015/02/18 05:54:45.640314, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/passdb/lookup_sid.c:1247(gid_to_sid) gid 0 -> sid S-1-22-2-0 [2015/02/18 05:54:45.640344, 10, pid=12720, effective(1000, 1000), real(1000, 0), class=acls] ../source3/smbd/posix_acls.c:2724(canonicalise_acl) canonicalise_acl: Access ace entries before arrange : [2015/02/18 05:54:45.640368, 10, pid=12720, effective(1000, 1000), real(1000, 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 [2015/02/18 05:54:45.640545, 10, pid=12720, effective(1000, 1000), real(1000, 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 [2015/02/18 05:54:45.640618, 10, pid=12720, effective(1000, 1000), real(1000, 0), class=acls] ../source3/smbd/posix_acls.c:2737(canonicalise_acl) canon_ace index 2. Type = allow SID = S-1-5-21-1849679311-379505231-1387054432-1001 uid 0 (root) SMB_ACL_USER_OBJ ace_flags = 0x0 perms rwx [2015/02/18 05:54:45.640701, 10, pid=12720, effective(1000, 1000), real(1000, 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-5-21-1849679311-379505231-1387054432-1001 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 [2015/02/18 05:54:45.640886, 10, pid=12720, effective(1000, 1000), real(1000, 0), class=acls] ../source3/smbd/posix_acls.c:1110(map_canon_ace_perms) map_canon_ace_perms: Mapped (UNIX) 1c0 to (NT) 1f01ff [2015/02/18 05:54:45.640933, 10, pid=12720, effective(1000, 1000), real(1000, 0), class=acls] ../source3/smbd/posix_acls.c:1110(map_canon_ace_perms) map_canon_ace_perms: Mapped (UNIX) 1c0 to (NT) 1f01ff [2015/02/18 05:54:45.640982, 10, pid=12720, effective(1000, 1000), real(1000, 0), class=acls] ../source3/smbd/posix_acls.c:1110(map_canon_ace_perms) map_canon_ace_perms: Mapped (UNIX) 1c0 to (NT) 1f01ff [2015/02/18 05:54:45.641063, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:174(smbd_check_access_rights) smbd_check_access_rights: file . requesting 0x40 returning 0x40 (NT_STATUS_OK) [2015/02/18 05:54:45.641123, 5, pid=12720, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap.c:178(dbwrap_check_lock_order) check lock order 1 for /opt/samba/var/lock/smbXsrv_open_global.tdb [2015/02/18 05:54:45.641166, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap.c:133(debug_lock_order) lock order: 1:/opt/samba/var/lock/smbXsrv_open_global.tdb 2: 3: [2015/02/18 05:54:45.641215, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap_tdb.c:60(db_tdb_log_key) Locking key 6A86B967 [2015/02/18 05:54:45.641278, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap_tdb.c:144(db_tdb_fetch_locked_internal) Allocated locked data 0x0x7fb80e1094a0 [2015/02/18 05:54:45.641345, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/smbXsrv_open.c:706(smbXsrv_open_global_store) smbXsrv_open_global_store: key '6A86B967' stored [2015/02/18 05:54:45.641375, 1, pid=12720, effective(1000, 1000), real(1000, 0)] ../librpc/ndr/ndr.c:402(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 : 0x00000000000031b0 (12720) task_id : 0x00000000 (0) vnn : 0xffffffff (4294967295) unique_id : 0xfb17366705686992 (-353754229625034350) open_global_id : 0x6a86b967 (1787214183) open_persistent_id : 0x000000006a86b967 (1787214183) open_volatile_id : 0x000000004d957c3e (1301642302) open_owner : S-1-5-21-1849679311-379505231-1387054432-1000 open_time : Wed Feb 18 05:54:46 AM 2015 CET create_guid : 80778865-b1c8-11e4-a338-0800275b519b client_guid : 807779ee-b1c8-11e4-a338-0800275b519b 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 [2015/02/18 05:54:45.641777, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap_tdb.c:60(db_tdb_log_key) Unlocking key 6A86B967 [2015/02/18 05:54:45.641831, 5, pid=12720, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap.c:146(dbwrap_lock_order_state_destructor) release lock order 1 for /opt/samba/var/lock/smbXsrv_open_global.tdb [2015/02/18 05:54:45.641911, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap.c:133(debug_lock_order) lock order: 1: 2: 3: [2015/02/18 05:54:45.641960, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/smbXsrv_open.c:951(smbXsrv_open_update) smbXsrv_open_update: global_id (0x6a86b967) stored [2015/02/18 05:54:45.642002, 1, pid=12720, effective(1000, 1000), real(1000, 0)] ../librpc/ndr/ndr.c:402(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 : 0x4d957c3e (1301642302) global : * global: struct smbXsrv_open_global0 db_rec : NULL server_id: struct server_id pid : 0x00000000000031b0 (12720) task_id : 0x00000000 (0) vnn : 0xffffffff (4294967295) unique_id : 0xfb17366705686992 (-353754229625034350) open_global_id : 0x6a86b967 (1787214183) open_persistent_id : 0x000000006a86b967 (1787214183) open_volatile_id : 0x000000004d957c3e (1301642302) open_owner : S-1-5-21-1849679311-379505231-1387054432-1000 open_time : Wed Feb 18 05:54:46 AM 2015 CET create_guid : 80778865-b1c8-11e4-a338-0800275b519b client_guid : 807779ee-b1c8-11e4-a338-0800275b519b 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 status : NT_STATUS_OK idle_time : Wed Feb 18 05:54:46 AM 2015 CET compat : * [2015/02/18 05:54:45.642975, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/smb2_create.c:1149(smbd_smb2_create_send) smb2_create_send: smbXsrv_open_update returned NT_STATUS_OK [2015/02/18 05:54:45.643011, 8, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/dosmode.c:600(dos_mode) dos_mode: README [2015/02/18 05:54:45.643053, 8, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/dosmode.c:242(dos_mode_from_sbuf) dos_mode_from_sbuf returning [2015/02/18 05:54:45.643080, 8, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/dosmode.c:36(dos_mode_debug_print) dos_mode returning [2015/02/18 05:54:45.643119, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/smb2_create.c:1274(smbd_smb2_create_send) smbd_smb2_create_send: README - fnum 1301642302 [2015/02/18 05:54:45.643159, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/smb2_server.c:2564(smbd_smb2_request_done_ex) smbd_smb2_request_done_ex: idx[1] status[NT_STATUS_OK] body[88] dyn[yes:108] at ../source3/smbd/smb2_create.c:364 [2015/02/18 05:54:45.643196, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/smb2_server.c:899(smb2_set_operation_credit) smb2_set_operation_credit: requested 1, charge 1, granted 1, current possible/max 386/512, total granted/max/low/range 127/8192/63/127 [2015/02/18 05:54:45.650618, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/smb2_server.c:3432(smbd_smb2_io_handler) smbd_smb2_request idx[1] of 5 vectors [2015/02/18 05:54:45.650721, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/smb2_server.c:647(smb2_validate_sequence_number) smb2_validate_sequence_number: clearing id 63 (position 63) from bitmap [2015/02/18 05:54:45.650772, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/smb2_server.c:1957(smbd_smb2_request_dispatch) smbd_smb2_request_dispatch: opcode[SMB2_OP_CREATE] mid = 63 [2015/02/18 05:54:45.650824, 4, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/uid.c:384(change_to_user) Skipping user change - already user [2015/02/18 05:54:45.650904, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/smb2_create.c:501(smbd_smb2_create_send) smbd_smb2_create: name[README] [2015/02/18 05:54:45.650989, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/smb2_create.c:889(smbd_smb2_create_send) Got lease request size 52 [2015/02/18 05:54:45.651035, 1, pid=12720, effective(1000, 1000), real(1000, 0)] ../librpc/ndr/ndr.c:402(ndr_print_debug) lease_ptr: struct smb2_lease lease_key: struct smb2_lease_key data: ARRAY(2) data : 0x00000000cfb12998 (3484494232) data : 0x0000000000000140 (320) lease_state : 0x00000007 (7) 1: SMB2_LEASE_READ 1: SMB2_LEASE_HANDLE 1: SMB2_LEASE_WRITE lease_flags : 0x00000000 (0) lease_duration : 0x0000000000000000 (0) parent_lease_key: struct smb2_lease_key data: ARRAY(2) data : 0x0000000000000000 (0) data : 0x0000000000000000 (0) lease_version : 0x0002 (2) lease_epoch : 0x0001 (1) [2015/02/18 05:54:45.651238, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/smb2_create.c:911(smbd_smb2_create_send) smbd_smb2_create_send: open execution phase [2015/02/18 05:54:45.651319, 5, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/filename.c:258(unix_convert) unix_convert called on file "README" [2015/02/18 05:54:45.651372, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/statcache.c:283(stat_cache_lookup) stat_cache_lookup: lookup succeeded for name [README] -> [README] [2015/02/18 05:54:45.651607, 3, pid=12720, effective(1000, 1000), real(1000, 0), class=vfs] ../source3/smbd/vfs.c:1143(check_reduced_name) check_reduced_name [README] [/Volumes/normal] [2015/02/18 05:54:45.651700, 10, pid=12720, effective(1000, 1000), real(1000, 0), class=vfs] ../source3/smbd/vfs.c:1203(check_reduced_name) check_reduced_name realpath [README] -> [/Volumes/normal/README] [2015/02/18 05:54:45.651744, 3, pid=12720, effective(1000, 1000), real(1000, 0), class=vfs] ../source3/smbd/vfs.c:1273(check_reduced_name) check_reduced_name: README reduced to /Volumes/normal/README [2015/02/18 05:54:45.651820, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:4949(create_file_default) create_file: access_mask = 0x120089 file_attributes = 0x80, share_access = 0x5, create_disposition = 0x1 create_options = 0x40 oplock_request = 0x100 private_flags = 0x0 root_dir_fid = 0x0, ea_list = 0x(nil), sd = 0x(nil), fname = README [2015/02/18 05:54:45.651876, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:4422(create_file_unixpath) create_file_unixpath: access_mask = 0x120089 file_attributes = 0x80, share_access = 0x5, create_disposition = 0x1 create_options = 0x40 oplock_request = 0x100 private_flags = 0x0 ea_list = 0x(nil), sd = 0x(nil), fname = README [2015/02/18 05:54:45.651930, 10, pid=12720, effective(1000, 1000), real(1000, 0), class=locking] ../source3/locking/leases_db.c:75(leases_db_key) leases_db_key: [2015/02/18 05:54:45.651977, 1, pid=12720, effective(1000, 1000), real(1000, 0)] ../librpc/ndr/ndr.c:402(ndr_print_debug) &db_key: struct leases_db_key client_guid : 807779ee-b1c8-11e4-a338-0800275b519b lease_key: struct smb2_lease_key data: ARRAY(2) data : 0x00000000cfb12998 (3484494232) data : 0x0000000000000140 (320) [2015/02/18 05:54:45.652132, 10, pid=12720, effective(1000, 1000), real(1000, 0), class=locking] ../source3/locking/leases_db.c:356(leases_db_parser) leases_db_parser: [2015/02/18 05:54:45.652182, 1, pid=12720, effective(1000, 1000), real(1000, 0)] ../librpc/ndr/ndr.c:402(ndr_print_debug) value: struct leases_db_value num_files : 0x00000001 (1) files: ARRAY(1) files: struct leases_db_file id: struct file_id devid : 0x000000000000fd01 (64769) inode : 0x0000000000080a81 (526977) extid : 0x0000000000000000 (0) servicepath : * servicepath : '/Volumes/normal' base_name : * base_name : 'README' stream_name : NULL [2015/02/18 05:54:45.652663, 5, pid=12720, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap.c:178(dbwrap_check_lock_order) check lock order 1 for /opt/samba/var/lock/smbXsrv_open_global.tdb [2015/02/18 05:54:45.652715, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap.c:133(debug_lock_order) lock order: 1:/opt/samba/var/lock/smbXsrv_open_global.tdb 2: 3: [2015/02/18 05:54:45.652763, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap_tdb.c:60(db_tdb_log_key) Locking key D78F0AF7 [2015/02/18 05:54:45.652813, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap_tdb.c:144(db_tdb_fetch_locked_internal) Allocated locked data 0x0x7fb80e10ea90 [2015/02/18 05:54:45.652856, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/smbXsrv_open.c:588(smbXsrv_open_global_verify_record) smbXsrv_open_global_verify_record: empty value [2015/02/18 05:54:45.654345, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/smbXsrv_open.c:706(smbXsrv_open_global_store) smbXsrv_open_global_store: key 'D78F0AF7' stored [2015/02/18 05:54:45.657293, 1, pid=12720, effective(1000, 1000), real(1000, 0)] ../librpc/ndr/ndr.c:402(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 : 0x00000000000031b0 (12720) task_id : 0x00000000 (0) vnn : 0xffffffff (4294967295) unique_id : 0xfb17366705686992 (-353754229625034350) open_global_id : 0xd78f0af7 (3616475895) open_persistent_id : 0x00000000d78f0af7 (3616475895) open_volatile_id : 0x00000000b2c9debc (2999574204) open_owner : S-1-5-21-1849679311-379505231-1387054432-1000 open_time : Wed Feb 18 05:54:46 AM 2015 CET create_guid : 00000000-0000-0000-0000-000000000000 client_guid : 807779ee-b1c8-11e4-a338-0800275b519b 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 [2015/02/18 05:54:45.657690, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap_tdb.c:60(db_tdb_log_key) Unlocking key D78F0AF7 [2015/02/18 05:54:45.657940, 5, pid=12720, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap.c:146(dbwrap_lock_order_state_destructor) release lock order 1 for /opt/samba/var/lock/smbXsrv_open_global.tdb [2015/02/18 05:54:45.657987, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap.c:133(debug_lock_order) lock order: 1: 2: 3: [2015/02/18 05:54:45.658031, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/smbXsrv_open.c:880(smbXsrv_open_create) smbXsrv_open_create: global_id (0xd78f0af7) stored [2015/02/18 05:54:45.658093, 1, pid=12720, effective(1000, 1000), real(1000, 0)] ../librpc/ndr/ndr.c:402(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 : 0xb2c9debc (2999574204) global : * global: struct smbXsrv_open_global0 db_rec : NULL server_id: struct server_id pid : 0x00000000000031b0 (12720) task_id : 0x00000000 (0) vnn : 0xffffffff (4294967295) unique_id : 0xfb17366705686992 (-353754229625034350) open_global_id : 0xd78f0af7 (3616475895) open_persistent_id : 0x00000000d78f0af7 (3616475895) open_volatile_id : 0x00000000b2c9debc (2999574204) open_owner : S-1-5-21-1849679311-379505231-1387054432-1000 open_time : Wed Feb 18 05:54:46 AM 2015 CET create_guid : 00000000-0000-0000-0000-000000000000 client_guid : 807779ee-b1c8-11e4-a338-0800275b519b 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 status : NT_STATUS_OK idle_time : Wed Feb 18 05:54:46 AM 2015 CET compat : NULL [2015/02/18 05:54:45.658512, 5, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/files.c:129(file_new) allocated file structure fnum 2999574204 (5 used) [2015/02/18 05:54:45.658658, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/files.c:743(file_name_hash) file_name_hash: /Volumes/normal/README hash 0x7d551025 [2015/02/18 05:54:45.658691, 3, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/dosmode.c:196(unix_mode) unix_mode(README) returning 0744 [2015/02/18 05:54:45.658716, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:2478(open_file_ntcreate) open_file_ntcreate: fname=README, dos_attrs=0x80 access_mask=0x120089 share_access=0x5 create_disposition = 0x1 create_options=0x40 unix mode=0744 oplock_request=256 private_flags = 0x0 [2015/02/18 05:54:45.658744, 8, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/dosmode.c:600(dos_mode) dos_mode: README [2015/02/18 05:54:45.658781, 8, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/dosmode.c:242(dos_mode_from_sbuf) dos_mode_from_sbuf returning [2015/02/18 05:54:45.658808, 8, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/dosmode.c:36(dos_mode_debug_print) dos_mode returning [2015/02/18 05:54:45.658838, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:2636(open_file_ntcreate) open_file_ntcreate: fname=README, after mapping access_mask=0x120089 [2015/02/18 05:54:45.658889, 4, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:2726(open_file_ntcreate) calling open_file with flags=0x0 flags2=0x0 mode=0744, access_mask = 0x120089, open_access_mask = 0x120089 [2015/02/18 05:54:45.658926, 10, pid=12720, effective(1000, 1000), real(1000, 0), class=acls] ../source3/smbd/posix_acls.c:3521(posix_get_nt_acl) posix_get_nt_acl: called for file README [2015/02/18 05:54:45.659006, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/passdb/lookup_sid.c:1198(uid_to_sid) uid 1000 -> sid S-1-5-21-1849679311-379505231-1387054432-1000 [2015/02/18 05:54:45.659039, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/passdb/lookup_sid.c:1247(gid_to_sid) gid 0 -> sid S-1-22-2-0 [2015/02/18 05:54:45.659069, 10, pid=12720, effective(1000, 1000), real(1000, 0), class=acls] ../source3/smbd/posix_acls.c:2724(canonicalise_acl) canonicalise_acl: Access ace entries before arrange : [2015/02/18 05:54:45.659093, 10, pid=12720, effective(1000, 1000), real(1000, 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 r-- [2015/02/18 05:54:45.659121, 10, pid=12720, effective(1000, 1000), real(1000, 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 r-- [2015/02/18 05:54:45.659276, 10, pid=12720, effective(1000, 1000), real(1000, 0), class=acls] ../source3/smbd/posix_acls.c:2737(canonicalise_acl) canon_ace index 2. Type = allow SID = S-1-5-21-1849679311-379505231-1387054432-1000 uid 1000 (ralph) SMB_ACL_USER_OBJ ace_flags = 0x0 perms rw- [2015/02/18 05:54:45.659372, 10, pid=12720, effective(1000, 1000), real(1000, 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-5-21-1849679311-379505231-1387054432-1000 uid 1000 (ralph) SMB_ACL_USER_OBJ ace_flags = 0x0 perms rw- canon_ace index 1. Type = allow SID = S-1-22-2-0 gid 0 (root) SMB_ACL_GROUP_OBJ ace_flags = 0x0 perms r-- canon_ace index 2. Type = allow SID = S-1-1-0 other SMB_ACL_OTHER ace_flags = 0x0 perms r-- [2015/02/18 05:54:45.659580, 10, pid=12720, effective(1000, 1000), real(1000, 0), class=acls] ../source3/smbd/posix_acls.c:1110(map_canon_ace_perms) map_canon_ace_perms: Mapped (UNIX) 180 to (NT) 12019f [2015/02/18 05:54:45.659617, 10, pid=12720, effective(1000, 1000), real(1000, 0), class=acls] ../source3/smbd/posix_acls.c:1110(map_canon_ace_perms) map_canon_ace_perms: Mapped (UNIX) 100 to (NT) 120089 [2015/02/18 05:54:45.659641, 10, pid=12720, effective(1000, 1000), real(1000, 0), class=acls] ../source3/smbd/posix_acls.c:1110(map_canon_ace_perms) map_canon_ace_perms: Mapped (UNIX) 100 to (NT) 120089 [2015/02/18 05:54:45.659683, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:174(smbd_check_access_rights) smbd_check_access_rights: file README requesting 0x120089 returning 0x120009 (NT_STATUS_OK) [2015/02/18 05:54:45.659728, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:408(fd_open) fd_open: name README, flags = 00 mode = 0744, fd = 44. [2015/02/18 05:54:45.659766, 2, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:1005(open_file) ralph opened file README read=Yes write=No (numopen=5) [2015/02/18 05:54:45.659794, 5, pid=12720, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap.c:178(dbwrap_check_lock_order) check lock order 1 for /opt/samba/var/lock/locking.tdb [2015/02/18 05:54:45.659818, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap.c:133(debug_lock_order) lock order: 1:/opt/samba/var/lock/locking.tdb 2: 3: [2015/02/18 05:54:45.659846, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap_tdb.c:60(db_tdb_log_key) Locking key 01FD000000000000810A [2015/02/18 05:54:45.659880, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap_tdb.c:144(db_tdb_fetch_locked_internal) Allocated locked data 0x0x7fb80e121770 [2015/02/18 05:54:45.659923, 10, pid=12720, effective(1000, 1000), real(1000, 0), class=locking] ../source3/locking/share_mode_lock.c:174(parse_share_modes) parse_share_modes: [2015/02/18 05:54:45.659983, 1, pid=12720, effective(1000, 1000), real(1000, 0)] ../librpc/ndr/ndr.c:402(ndr_print_debug) d: struct share_mode_data servicepath : * servicepath : '/Volumes/normal' base_name : * base_name : 'README' stream_name : NULL num_share_modes : 0x00000002 (2) share_modes: ARRAY(2) share_modes: struct share_mode_entry pid: struct server_id pid : 0x00000000000031b0 (12720) task_id : 0x00000000 (0) vnn : 0xffffffff (4294967295) unique_id : 0xfb17366705686992 (-353754229625034350) op_mid : 0x000000000000003c (60) op_type : 0x0100 (256) lease_idx : 0x00000000 (0) access_mask : 0x00120089 (1179785) share_access : 0x00000001 (1) private_options : 0x00000000 (0) time : Wed Feb 18 05:54:45 AM 2015 CET.581827 id: struct file_id devid : 0x000000000000fd01 (64769) inode : 0x0000000000080a81 (526977) extid : 0x0000000000000000 (0) share_file_id : 0x000000003357c520 (861390112) uid : 0x000003e8 (1000) flags : 0x0000 (0) name_hash : 0x7d551025 (2102726693) stale : 0x00 (0) lease : * lease: struct share_mode_lease client_guid : 807779ee-b1c8-11e4-a338-0800275b519b lease_key: struct smb2_lease_key data: ARRAY(2) data : 0x00000000cfb12998 (3484494232) data : 0x0000000000000140 (320) current_state : 0x00000007 (7) 1: SMB2_LEASE_READ 1: SMB2_LEASE_HANDLE 1: SMB2_LEASE_WRITE breaking : 0x00 (0) breaking_to_requested : 0x00000000 (0) 0: SMB2_LEASE_READ 0: SMB2_LEASE_HANDLE 0: SMB2_LEASE_WRITE breaking_to_required : 0x00000000 (0) 0: SMB2_LEASE_READ 0: SMB2_LEASE_HANDLE 0: SMB2_LEASE_WRITE lease_version : 0x0002 (2) epoch : 0x0001 (1) share_modes: struct share_mode_entry pid: struct server_id pid : 0x00000000000031b0 (12720) task_id : 0x00000000 (0) vnn : 0xffffffff (4294967295) unique_id : 0xfb17366705686992 (-353754229625034350) op_mid : 0x000000000000003e (62) op_type : 0x0100 (256) lease_idx : 0x00000000 (0) access_mask : 0x00120089 (1179785) share_access : 0x00000003 (3) private_options : 0x00000000 (0) time : Wed Feb 18 05:54:45 AM 2015 CET.617039 id: struct file_id devid : 0x000000000000fd01 (64769) inode : 0x0000000000080a81 (526977) extid : 0x0000000000000000 (0) share_file_id : 0x00000000db0ae006 (3674923014) uid : 0x000003e8 (1000) flags : 0x0000 (0) name_hash : 0x7d551025 (2102726693) stale : 0x00 (0) lease : * lease: struct share_mode_lease client_guid : 807779ee-b1c8-11e4-a338-0800275b519b lease_key: struct smb2_lease_key data: ARRAY(2) data : 0x00000000cfb12998 (3484494232) data : 0x0000000000000140 (320) current_state : 0x00000007 (7) 1: SMB2_LEASE_READ 1: SMB2_LEASE_HANDLE 1: SMB2_LEASE_WRITE breaking : 0x00 (0) breaking_to_requested : 0x00000000 (0) 0: SMB2_LEASE_READ 0: SMB2_LEASE_HANDLE 0: SMB2_LEASE_WRITE breaking_to_required : 0x00000000 (0) 0: SMB2_LEASE_READ 0: SMB2_LEASE_HANDLE 0: SMB2_LEASE_WRITE lease_version : 0x0002 (2) epoch : 0x0001 (1) num_leases : 0x00000001 (1) leases: ARRAY(1) leases: struct share_mode_lease client_guid : 807779ee-b1c8-11e4-a338-0800275b519b lease_key: struct smb2_lease_key data: ARRAY(2) data : 0x00000000cfb12998 (3484494232) data : 0x0000000000000140 (320) current_state : 0x00000007 (7) 1: SMB2_LEASE_READ 1: SMB2_LEASE_HANDLE 1: SMB2_LEASE_WRITE breaking : 0x00 (0) breaking_to_requested : 0x00000000 (0) 0: SMB2_LEASE_READ 0: SMB2_LEASE_HANDLE 0: SMB2_LEASE_WRITE breaking_to_required : 0x00000000 (0) 0: SMB2_LEASE_READ 0: SMB2_LEASE_HANDLE 0: SMB2_LEASE_WRITE lease_version : 0x0002 (2) epoch : 0x0001 (1) num_delete_tokens : 0x00000000 (0) delete_tokens: ARRAY(0) old_write_time : Thu Aug 7 11:02:08 AM 2014 CEST.0 changed_write_time : Thu Jan 1 01:00:00 AM 1970 CET.0 fresh : 0x00 (0) modified : 0x00 (0) record : NULL [2015/02/18 05:54:45.661017, 10, pid=12720, effective(1000, 1000), real(1000, 0), class=locking] ../source3/locking/locking.c:1192(find_delete_on_close_token) find_delete_on_close_token: name_hash = 0x7d551025 [2015/02/18 05:54:45.661072, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:1025(share_conflict) share_conflict: entry->access_mask = 0x120089, entry->share_access = 0x1, entry->private_options = 0x0 [2015/02/18 05:54:45.661131, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:1036(share_conflict) share_conflict: access_mask = 0x120089, share_access = 0x5 [2015/02/18 05:54:45.661156, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:1085(share_conflict) share_conflict: [1] am (0x120089) & right (0x6) = 0x0 [2015/02/18 05:54:45.661179, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:1085(share_conflict) share_conflict: [1] sa (0x5) & share (0x2) = 0x0 [2015/02/18 05:54:45.661202, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:1087(share_conflict) share_conflict: [2] am (0x120089) & right (0x6) = 0x0 [2015/02/18 05:54:45.661224, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:1087(share_conflict) share_conflict: [2] sa (0x1) & share (0x2) = 0x0 [2015/02/18 05:54:45.661247, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:1090(share_conflict) share_conflict: [3] am (0x120089) & right (0x21) = 0x1 [2015/02/18 05:54:45.661269, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:1090(share_conflict) share_conflict: [3] sa (0x5) & share (0x1) = 0x1 [2015/02/18 05:54:45.661292, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:1092(share_conflict) share_conflict: [4] am (0x120089) & right (0x21) = 0x1 [2015/02/18 05:54:45.661315, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:1092(share_conflict) share_conflict: [4] sa (0x1) & share (0x1) = 0x1 [2015/02/18 05:54:45.661337, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:1095(share_conflict) share_conflict: [5] am (0x120089) & right (0x10000) = 0x0 [2015/02/18 05:54:45.661360, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:1095(share_conflict) share_conflict: [5] sa (0x5) & share (0x4) = 0x4 [2015/02/18 05:54:45.661382, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:1097(share_conflict) share_conflict: [6] am (0x120089) & right (0x10000) = 0x0 [2015/02/18 05:54:45.661409, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:1097(share_conflict) share_conflict: [6] sa (0x1) & share (0x4) = 0x0 [2015/02/18 05:54:45.661413, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:1099(share_conflict) share_conflict: No conflict. [2015/02/18 05:54:45.661582, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:1025(share_conflict) share_conflict: entry->access_mask = 0x120089, entry->share_access = 0x3, entry->private_options = 0x0 [2015/02/18 05:54:45.661655, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:1036(share_conflict) share_conflict: access_mask = 0x120089, share_access = 0x5 [2015/02/18 05:54:45.661697, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:1085(share_conflict) share_conflict: [1] am (0x120089) & right (0x6) = 0x0 [2015/02/18 05:54:45.661737, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:1085(share_conflict) share_conflict: [1] sa (0x5) & share (0x2) = 0x0 [2015/02/18 05:54:45.661776, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:1087(share_conflict) share_conflict: [2] am (0x120089) & right (0x6) = 0x0 [2015/02/18 05:54:45.661816, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:1087(share_conflict) share_conflict: [2] sa (0x3) & share (0x2) = 0x2 [2015/02/18 05:54:45.661853, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:1090(share_conflict) share_conflict: [3] am (0x120089) & right (0x21) = 0x1 [2015/02/18 05:54:45.661884, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:1090(share_conflict) share_conflict: [3] sa (0x5) & share (0x1) = 0x1 [2015/02/18 05:54:45.661967, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:1092(share_conflict) share_conflict: [4] am (0x120089) & right (0x21) = 0x1 [2015/02/18 05:54:45.662005, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:1092(share_conflict) share_conflict: [4] sa (0x3) & share (0x1) = 0x1 [2015/02/18 05:54:45.662043, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:1095(share_conflict) share_conflict: [5] am (0x120089) & right (0x10000) = 0x0 [2015/02/18 05:54:45.662082, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:1095(share_conflict) share_conflict: [5] sa (0x5) & share (0x4) = 0x4 [2015/02/18 05:54:45.662119, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:1097(share_conflict) share_conflict: [6] am (0x120089) & right (0x10000) = 0x0 [2015/02/18 05:54:45.662158, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:1097(share_conflict) share_conflict: [6] sa (0x3) & share (0x4) = 0x0 [2015/02/18 05:54:45.662196, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:1099(share_conflict) share_conflict: No conflict. [2015/02/18 05:54:45.662236, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:1442(delay_for_oplock) entry 0: e_lease_type 7, will_overwrite: 0 [2015/02/18 05:54:45.662280, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:1442(delay_for_oplock) entry 1: e_lease_type 7, will_overwrite: 0 [2015/02/18 05:54:45.662342, 10, pid=12720, effective(1000, 1000), real(1000, 0), class=locking] ../source3/locking/brlock.c:2032(brl_get_locks_readonly) seqnum=8, fsp->brlock_seqnum=0 [2015/02/18 05:54:45.662412, 10, pid=12720, effective(1000, 1000), real(1000, 0), class=locking] ../source3/locking/locking.c:748(share_mode_stale_pid) PID 12720 (index 0 out of 2) still exists [2015/02/18 05:54:45.662599, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:1634(grant_fsp_lease) existing=7, requested=7, granted=7, do_upgrade=0 [2015/02/18 05:54:45.662691, 10, pid=12720, effective(1000, 1000), real(1000, 0), class=locking] ../source3/smbd/oplock.c:389(fsp_lease_update) fsp_lease_update: refresh lease state [2015/02/18 05:54:45.662735, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:1827(grant_fsp_oplock_type) lease_state=7 [2015/02/18 05:54:45.662778, 10, pid=12720, effective(1000, 1000), real(1000, 0), class=locking] ../source3/locking/brlock.c:2032(brl_get_locks_readonly) seqnum=8, fsp->brlock_seqnum=8 [2015/02/18 05:54:45.662823, 5, pid=12720, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap.c:178(dbwrap_check_lock_order) check lock order 2 for /opt/samba/var/lock/brlock.tdb [2015/02/18 05:54:45.662864, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap.c:133(debug_lock_order) lock order: 1:/opt/samba/var/lock/locking.tdb 2:/opt/samba/var/lock/brlock.tdb 3: [2015/02/18 05:54:45.662911, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap_tdb.c:60(db_tdb_log_key) Locking key 01FD000000000000810A [2015/02/18 05:54:45.664312, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap_tdb.c:144(db_tdb_fetch_locked_internal) Allocated locked data 0x0x7fb80e121d80 [2015/02/18 05:54:45.664644, 10, pid=12720, effective(1000, 1000), real(1000, 0), class=locking] ../source3/locking/brlock.c:1990(brl_get_locks) brl_get_locks_internal: 0 current locks on file_id fd01:80a81:0 [2015/02/18 05:54:45.664718, 10, pid=12720, effective(1000, 1000), real(1000, 0), class=locking] ../source3/locking/brlock.c:94(brl_set_num_read_oplocks) Setting num_read_oplocks to 3 [2015/02/18 05:54:45.664779, 10, pid=12720, effective(1000, 1000), real(1000, 0), class=locking] ../source3/locking/brlock.c:1908(byte_range_lock_flush) seqnum=9 [2015/02/18 05:54:45.664830, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap_tdb.c:60(db_tdb_log_key) Unlocking key 01FD000000000000810A [2015/02/18 05:54:45.664900, 5, pid=12720, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap.c:146(dbwrap_lock_order_state_destructor) release lock order 2 for /opt/samba/var/lock/brlock.tdb [2015/02/18 05:54:45.664942, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap.c:133(debug_lock_order) lock order: 1:/opt/samba/var/lock/locking.tdb 2: 3: [2015/02/18 05:54:45.664988, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:1873(grant_fsp_oplock_type) grant_fsp_oplock_type: oplock type 0x100 on file README [2015/02/18 05:54:45.665037, 10, pid=12720, effective(1000, 1000), real(1000, 0), class=locking] ../source3/locking/share_mode_lock.c:194(unparse_share_modes) unparse_share_modes: [2015/02/18 05:54:45.666643, 1, pid=12720, effective(1000, 1000), real(1000, 0)] ../librpc/ndr/ndr.c:402(ndr_print_debug) d: struct share_mode_data servicepath : * servicepath : '/Volumes/normal' base_name : * base_name : 'README' stream_name : NULL num_share_modes : 0x00000003 (3) share_modes: ARRAY(3) share_modes: struct share_mode_entry pid: struct server_id pid : 0x00000000000031b0 (12720) task_id : 0x00000000 (0) vnn : 0xffffffff (4294967295) unique_id : 0xfb17366705686992 (-353754229625034350) op_mid : 0x000000000000003c (60) op_type : 0x0100 (256) lease_idx : 0x00000000 (0) access_mask : 0x00120089 (1179785) share_access : 0x00000001 (1) private_options : 0x00000000 (0) time : Wed Feb 18 05:54:45 AM 2015 CET.581827 id: struct file_id devid : 0x000000000000fd01 (64769) inode : 0x0000000000080a81 (526977) extid : 0x0000000000000000 (0) share_file_id : 0x000000003357c520 (861390112) uid : 0x000003e8 (1000) flags : 0x0000 (0) name_hash : 0x7d551025 (2102726693) stale : 0x00 (0) lease : * lease: struct share_mode_lease client_guid : 807779ee-b1c8-11e4-a338-0800275b519b lease_key: struct smb2_lease_key data: ARRAY(2) data : 0x00000000cfb12998 (3484494232) data : 0x0000000000000140 (320) current_state : 0x00000007 (7) 1: SMB2_LEASE_READ 1: SMB2_LEASE_HANDLE 1: SMB2_LEASE_WRITE breaking : 0x00 (0) breaking_to_requested : 0x00000000 (0) 0: SMB2_LEASE_READ 0: SMB2_LEASE_HANDLE 0: SMB2_LEASE_WRITE breaking_to_required : 0x00000000 (0) 0: SMB2_LEASE_READ 0: SMB2_LEASE_HANDLE 0: SMB2_LEASE_WRITE lease_version : 0x0002 (2) epoch : 0x0001 (1) share_modes: struct share_mode_entry pid: struct server_id pid : 0x00000000000031b0 (12720) task_id : 0x00000000 (0) vnn : 0xffffffff (4294967295) unique_id : 0xfb17366705686992 (-353754229625034350) op_mid : 0x000000000000003e (62) op_type : 0x0100 (256) lease_idx : 0x00000000 (0) access_mask : 0x00120089 (1179785) share_access : 0x00000003 (3) private_options : 0x00000000 (0) time : Wed Feb 18 05:54:45 AM 2015 CET.617039 id: struct file_id devid : 0x000000000000fd01 (64769) inode : 0x0000000000080a81 (526977) extid : 0x0000000000000000 (0) share_file_id : 0x00000000db0ae006 (3674923014) uid : 0x000003e8 (1000) flags : 0x0000 (0) name_hash : 0x7d551025 (2102726693) stale : 0x00 (0) lease : * lease: struct share_mode_lease client_guid : 807779ee-b1c8-11e4-a338-0800275b519b lease_key: struct smb2_lease_key data: ARRAY(2) data : 0x00000000cfb12998 (3484494232) data : 0x0000000000000140 (320) current_state : 0x00000007 (7) 1: SMB2_LEASE_READ 1: SMB2_LEASE_HANDLE 1: SMB2_LEASE_WRITE breaking : 0x00 (0) breaking_to_requested : 0x00000000 (0) 0: SMB2_LEASE_READ 0: SMB2_LEASE_HANDLE 0: SMB2_LEASE_WRITE breaking_to_required : 0x00000000 (0) 0: SMB2_LEASE_READ 0: SMB2_LEASE_HANDLE 0: SMB2_LEASE_WRITE lease_version : 0x0002 (2) epoch : 0x0001 (1) share_modes: struct share_mode_entry pid: struct server_id pid : 0x00000000000031b0 (12720) task_id : 0x00000000 (0) vnn : 0xffffffff (4294967295) unique_id : 0xfb17366705686992 (-353754229625034350) op_mid : 0x000000000000003f (63) op_type : 0x0100 (256) lease_idx : 0x00000000 (0) access_mask : 0x00120089 (1179785) share_access : 0x00000005 (5) private_options : 0x00000000 (0) time : Wed Feb 18 05:54:45 AM 2015 CET.652645 id: struct file_id devid : 0x000000000000fd01 (64769) inode : 0x0000000000080a81 (526977) extid : 0x0000000000000000 (0) share_file_id : 0x000000003987c697 (965199511) uid : 0x000003e8 (1000) flags : 0x0000 (0) name_hash : 0x7d551025 (2102726693) stale : 0x00 (0) lease : * lease: struct share_mode_lease client_guid : 807779ee-b1c8-11e4-a338-0800275b519b lease_key: struct smb2_lease_key data: ARRAY(2) data : 0x00000000cfb12998 (3484494232) data : 0x0000000000000140 (320) current_state : 0x00000007 (7) 1: SMB2_LEASE_READ 1: SMB2_LEASE_HANDLE 1: SMB2_LEASE_WRITE breaking : 0x00 (0) breaking_to_requested : 0x00000000 (0) 0: SMB2_LEASE_READ 0: SMB2_LEASE_HANDLE 0: SMB2_LEASE_WRITE breaking_to_required : 0x00000000 (0) 0: SMB2_LEASE_READ 0: SMB2_LEASE_HANDLE 0: SMB2_LEASE_WRITE lease_version : 0x0002 (2) epoch : 0x0001 (1) num_leases : 0x00000001 (1) leases: ARRAY(1) leases: struct share_mode_lease client_guid : 807779ee-b1c8-11e4-a338-0800275b519b lease_key: struct smb2_lease_key data: ARRAY(2) data : 0x00000000cfb12998 (3484494232) data : 0x0000000000000140 (320) current_state : 0x00000007 (7) 1: SMB2_LEASE_READ 1: SMB2_LEASE_HANDLE 1: SMB2_LEASE_WRITE breaking : 0x00 (0) breaking_to_requested : 0x00000000 (0) 0: SMB2_LEASE_READ 0: SMB2_LEASE_HANDLE 0: SMB2_LEASE_WRITE breaking_to_required : 0x00000000 (0) 0: SMB2_LEASE_READ 0: SMB2_LEASE_HANDLE 0: SMB2_LEASE_WRITE lease_version : 0x0002 (2) epoch : 0x0001 (1) num_delete_tokens : 0x00000000 (0) delete_tokens: ARRAY(0) old_write_time : Thu Aug 7 11:02:08 AM 2014 CEST.0 changed_write_time : Thu Jan 1 01:00:00 AM 1970 CET.0 fresh : 0x00 (0) modified : 0x01 (1) record : * [2015/02/18 05:54:45.671763, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap_tdb.c:60(db_tdb_log_key) Unlocking key 01FD000000000000810A [2015/02/18 05:54:45.672008, 5, pid=12720, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap.c:146(dbwrap_lock_order_state_destructor) release lock order 1 for /opt/samba/var/lock/locking.tdb [2015/02/18 05:54:45.672053, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap.c:133(debug_lock_order) lock order: 1: 2: 3: [2015/02/18 05:54:45.672104, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:4758(create_file_unixpath) create_file_unixpath: info=1 [2015/02/18 05:54:45.672184, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:5037(create_file_default) create_file: info=1 [2015/02/18 05:54:45.672246, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/smb2_create.c:1093(smbd_smb2_create_send) smbd_smb2_create_send: response construction phase [2015/02/18 05:54:45.672317, 10, pid=12720, effective(1000, 1000), real(1000, 0), class=acls] ../source3/smbd/posix_acls.c:3521(posix_get_nt_acl) posix_get_nt_acl: called for file README [2015/02/18 05:54:45.672769, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/passdb/lookup_sid.c:1198(uid_to_sid) uid 1000 -> sid S-1-5-21-1849679311-379505231-1387054432-1000 [2015/02/18 05:54:45.672837, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/passdb/lookup_sid.c:1247(gid_to_sid) gid 0 -> sid S-1-22-2-0 [2015/02/18 05:54:45.672870, 10, pid=12720, effective(1000, 1000), real(1000, 0), class=acls] ../source3/smbd/posix_acls.c:2724(canonicalise_acl) canonicalise_acl: Access ace entries before arrange : [2015/02/18 05:54:45.672896, 10, pid=12720, effective(1000, 1000), real(1000, 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 r-- [2015/02/18 05:54:45.672925, 10, pid=12720, effective(1000, 1000), real(1000, 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 r-- [2015/02/18 05:54:45.673106, 10, pid=12720, effective(1000, 1000), real(1000, 0), class=acls] ../source3/smbd/posix_acls.c:2737(canonicalise_acl) canon_ace index 2. Type = allow SID = S-1-5-21-1849679311-379505231-1387054432-1000 uid 1000 (ralph) SMB_ACL_USER_OBJ ace_flags = 0x0 perms rw- [2015/02/18 05:54:45.673185, 10, pid=12720, effective(1000, 1000), real(1000, 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-5-21-1849679311-379505231-1387054432-1000 uid 1000 (ralph) SMB_ACL_USER_OBJ ace_flags = 0x0 perms rw- canon_ace index 1. Type = allow SID = S-1-22-2-0 gid 0 (root) SMB_ACL_GROUP_OBJ ace_flags = 0x0 perms r-- canon_ace index 2. Type = allow SID = S-1-1-0 other SMB_ACL_OTHER ace_flags = 0x0 perms r-- [2015/02/18 05:54:45.673297, 10, pid=12720, effective(1000, 1000), real(1000, 0), class=acls] ../source3/smbd/posix_acls.c:1110(map_canon_ace_perms) map_canon_ace_perms: Mapped (UNIX) 180 to (NT) 12019f [2015/02/18 05:54:45.673325, 10, pid=12720, effective(1000, 1000), real(1000, 0), class=acls] ../source3/smbd/posix_acls.c:1110(map_canon_ace_perms) map_canon_ace_perms: Mapped (UNIX) 100 to (NT) 120089 [2015/02/18 05:54:45.673349, 10, pid=12720, effective(1000, 1000), real(1000, 0), class=acls] ../source3/smbd/posix_acls.c:1110(map_canon_ace_perms) map_canon_ace_perms: Mapped (UNIX) 100 to (NT) 120089 [2015/02/18 05:54:45.673394, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../libcli/security/access_check.c:188(se_access_check) se_access_check: MAX desired = 0x2000000, granted = 0x16019f, remaining = 0x16019f [2015/02/18 05:54:45.673449, 10, pid=12720, effective(1000, 1000), real(1000, 0), class=acls] ../source3/smbd/posix_acls.c:3521(posix_get_nt_acl) posix_get_nt_acl: called for file . [2015/02/18 05:54:45.673507, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/passdb/lookup_sid.c:1198(uid_to_sid) uid 0 -> sid S-1-5-21-1849679311-379505231-1387054432-1001 [2015/02/18 05:54:45.673539, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/passdb/lookup_sid.c:1247(gid_to_sid) gid 0 -> sid S-1-22-2-0 [2015/02/18 05:54:45.673567, 10, pid=12720, effective(1000, 1000), real(1000, 0), class=acls] ../source3/smbd/posix_acls.c:2724(canonicalise_acl) canonicalise_acl: Access ace entries before arrange : [2015/02/18 05:54:45.673710, 10, pid=12720, effective(1000, 1000), real(1000, 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 [2015/02/18 05:54:45.673765, 10, pid=12720, effective(1000, 1000), real(1000, 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 [2015/02/18 05:54:45.673819, 10, pid=12720, effective(1000, 1000), real(1000, 0), class=acls] ../source3/smbd/posix_acls.c:2737(canonicalise_acl) canon_ace index 2. Type = allow SID = S-1-5-21-1849679311-379505231-1387054432-1001 uid 0 (root) SMB_ACL_USER_OBJ ace_flags = 0x0 perms rwx [2015/02/18 05:54:45.673906, 10, pid=12720, effective(1000, 1000), real(1000, 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-5-21-1849679311-379505231-1387054432-1001 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 [2015/02/18 05:54:45.674007, 10, pid=12720, effective(1000, 1000), real(1000, 0), class=acls] ../source3/smbd/posix_acls.c:1110(map_canon_ace_perms) map_canon_ace_perms: Mapped (UNIX) 1c0 to (NT) 1f01ff [2015/02/18 05:54:45.674035, 10, pid=12720, effective(1000, 1000), real(1000, 0), class=acls] ../source3/smbd/posix_acls.c:1110(map_canon_ace_perms) map_canon_ace_perms: Mapped (UNIX) 1c0 to (NT) 1f01ff [2015/02/18 05:54:45.674059, 10, pid=12720, effective(1000, 1000), real(1000, 0), class=acls] ../source3/smbd/posix_acls.c:1110(map_canon_ace_perms) map_canon_ace_perms: Mapped (UNIX) 1c0 to (NT) 1f01ff [2015/02/18 05:54:45.674099, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:174(smbd_check_access_rights) smbd_check_access_rights: file . requesting 0x40 returning 0x40 (NT_STATUS_OK) [2015/02/18 05:54:45.674135, 5, pid=12720, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap.c:178(dbwrap_check_lock_order) check lock order 1 for /opt/samba/var/lock/smbXsrv_open_global.tdb [2015/02/18 05:54:45.674161, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap.c:133(debug_lock_order) lock order: 1:/opt/samba/var/lock/smbXsrv_open_global.tdb 2: 3: [2015/02/18 05:54:45.674189, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap_tdb.c:60(db_tdb_log_key) Locking key D78F0AF7 [2015/02/18 05:54:45.674224, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap_tdb.c:144(db_tdb_fetch_locked_internal) Allocated locked data 0x0x7fb80e11fe60 [2015/02/18 05:54:45.674270, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/smbXsrv_open.c:706(smbXsrv_open_global_store) smbXsrv_open_global_store: key 'D78F0AF7' stored [2015/02/18 05:54:45.674299, 1, pid=12720, effective(1000, 1000), real(1000, 0)] ../librpc/ndr/ndr.c:402(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 : 0x00000000000031b0 (12720) task_id : 0x00000000 (0) vnn : 0xffffffff (4294967295) unique_id : 0xfb17366705686992 (-353754229625034350) open_global_id : 0xd78f0af7 (3616475895) open_persistent_id : 0x00000000d78f0af7 (3616475895) open_volatile_id : 0x00000000b2c9debc (2999574204) open_owner : S-1-5-21-1849679311-379505231-1387054432-1000 open_time : Wed Feb 18 05:54:46 AM 2015 CET create_guid : 80778866-b1c8-11e4-a338-0800275b519b client_guid : 807779ee-b1c8-11e4-a338-0800275b519b 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 [2015/02/18 05:54:45.674709, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap_tdb.c:60(db_tdb_log_key) Unlocking key D78F0AF7 [2015/02/18 05:54:45.674763, 5, pid=12720, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap.c:146(dbwrap_lock_order_state_destructor) release lock order 1 for /opt/samba/var/lock/smbXsrv_open_global.tdb [2015/02/18 05:54:45.674806, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap.c:133(debug_lock_order) lock order: 1: 2: 3: [2015/02/18 05:54:45.674855, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/smbXsrv_open.c:951(smbXsrv_open_update) smbXsrv_open_update: global_id (0xd78f0af7) stored [2015/02/18 05:54:45.674864, 1, pid=12720, effective(1000, 1000), real(1000, 0)] ../librpc/ndr/ndr.c:402(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 : 0xb2c9debc (2999574204) global : * global: struct smbXsrv_open_global0 db_rec : NULL server_id: struct server_id pid : 0x00000000000031b0 (12720) task_id : 0x00000000 (0) vnn : 0xffffffff (4294967295) unique_id : 0xfb17366705686992 (-353754229625034350) open_global_id : 0xd78f0af7 (3616475895) open_persistent_id : 0x00000000d78f0af7 (3616475895) open_volatile_id : 0x00000000b2c9debc (2999574204) open_owner : S-1-5-21-1849679311-379505231-1387054432-1000 open_time : Wed Feb 18 05:54:46 AM 2015 CET create_guid : 80778866-b1c8-11e4-a338-0800275b519b client_guid : 807779ee-b1c8-11e4-a338-0800275b519b 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 status : NT_STATUS_OK idle_time : Wed Feb 18 05:54:46 AM 2015 CET compat : * [2015/02/18 05:54:45.678280, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/smb2_create.c:1149(smbd_smb2_create_send) smb2_create_send: smbXsrv_open_update returned NT_STATUS_OK [2015/02/18 05:54:45.680701, 8, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/dosmode.c:600(dos_mode) dos_mode: README [2015/02/18 05:54:45.682185, 8, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/dosmode.c:242(dos_mode_from_sbuf) dos_mode_from_sbuf returning [2015/02/18 05:54:45.682314, 8, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/dosmode.c:36(dos_mode_debug_print) dos_mode returning [2015/02/18 05:54:45.682383, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/smb2_create.c:1274(smbd_smb2_create_send) smbd_smb2_create_send: README - fnum 2999574204 [2015/02/18 05:54:45.682654, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/smb2_server.c:2564(smbd_smb2_request_done_ex) smbd_smb2_request_done_ex: idx[1] status[NT_STATUS_OK] body[88] dyn[yes:108] at ../source3/smbd/smb2_create.c:364 [2015/02/18 05:54:45.682718, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/smb2_server.c:899(smb2_set_operation_credit) smb2_set_operation_credit: requested 1, charge 1, granted 1, current possible/max 386/512, total granted/max/low/range 127/8192/64/127 [2015/02/18 05:54:45.702482, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/smb2_server.c:3432(smbd_smb2_io_handler) smbd_smb2_request idx[1] of 5 vectors [2015/02/18 05:54:45.702655, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/smb2_server.c:647(smb2_validate_sequence_number) smb2_validate_sequence_number: clearing id 64 (position 64) from bitmap [2015/02/18 05:54:45.702688, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/smb2_server.c:1957(smbd_smb2_request_dispatch) smbd_smb2_request_dispatch: opcode[SMB2_OP_CREATE] mid = 64 [2015/02/18 05:54:45.702724, 4, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/uid.c:384(change_to_user) Skipping user change - already user [2015/02/18 05:54:45.702777, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/smb2_create.c:501(smbd_smb2_create_send) smbd_smb2_create: name[README] [2015/02/18 05:54:45.702814, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/smb2_create.c:889(smbd_smb2_create_send) Got lease request size 52 [2015/02/18 05:54:45.702839, 1, pid=12720, effective(1000, 1000), real(1000, 0)] ../librpc/ndr/ndr.c:402(ndr_print_debug) lease_ptr: struct smb2_lease lease_key: struct smb2_lease_key data: ARRAY(2) data : 0x00000000cfb12998 (3484494232) data : 0x0000000000000140 (320) lease_state : 0x00000000 (0) 0: SMB2_LEASE_READ 0: SMB2_LEASE_HANDLE 0: SMB2_LEASE_WRITE lease_flags : 0x00000000 (0) lease_duration : 0x0000000000000000 (0) parent_lease_key: struct smb2_lease_key data: ARRAY(2) data : 0x0000000000000000 (0) data : 0x0000000000000000 (0) lease_version : 0x0002 (2) lease_epoch : 0x0001 (1) [2015/02/18 05:54:45.702975, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/smb2_create.c:911(smbd_smb2_create_send) smbd_smb2_create_send: open execution phase [2015/02/18 05:54:45.703006, 5, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/filename.c:258(unix_convert) unix_convert called on file "README" [2015/02/18 05:54:45.703019, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/statcache.c:283(stat_cache_lookup) stat_cache_lookup: lookup succeeded for name [README] -> [README] [2015/02/18 05:54:45.703088, 3, pid=12720, effective(1000, 1000), real(1000, 0), class=vfs] ../source3/smbd/vfs.c:1143(check_reduced_name) check_reduced_name [README] [/Volumes/normal] [2015/02/18 05:54:45.703135, 10, pid=12720, effective(1000, 1000), real(1000, 0), class=vfs] ../source3/smbd/vfs.c:1203(check_reduced_name) check_reduced_name realpath [README] -> [/Volumes/normal/README] [2015/02/18 05:54:45.703613, 3, pid=12720, effective(1000, 1000), real(1000, 0), class=vfs] ../source3/smbd/vfs.c:1273(check_reduced_name) check_reduced_name: README reduced to /Volumes/normal/README [2015/02/18 05:54:45.703675, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:4949(create_file_default) create_file: access_mask = 0x10e0080 file_attributes = 0x0, share_access = 0x3, create_disposition = 0x1 create_options = 0x0 oplock_request = 0x100 private_flags = 0x0 root_dir_fid = 0x0, ea_list = 0x(nil), sd = 0x(nil), fname = README [2015/02/18 05:54:45.703853, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:4422(create_file_unixpath) create_file_unixpath: access_mask = 0x10e0080 file_attributes = 0x0, share_access = 0x3, create_disposition = 0x1 create_options = 0x0 oplock_request = 0x100 private_flags = 0x0 ea_list = 0x(nil), sd = 0x(nil), fname = README [2015/02/18 05:54:45.704102, 10, pid=12720, effective(1000, 1000), real(1000, 0), class=locking] ../source3/locking/leases_db.c:75(leases_db_key) leases_db_key: [2015/02/18 05:54:45.704921, 1, pid=12720, effective(1000, 1000), real(1000, 0)] ../librpc/ndr/ndr.c:402(ndr_print_debug) &db_key: struct leases_db_key client_guid : 807779ee-b1c8-11e4-a338-0800275b519b lease_key: struct smb2_lease_key data: ARRAY(2) data : 0x00000000cfb12998 (3484494232) data : 0x0000000000000140 (320) [2015/02/18 05:54:45.705781, 10, pid=12720, effective(1000, 1000), real(1000, 0), class=locking] ../source3/locking/leases_db.c:356(leases_db_parser) leases_db_parser: [2015/02/18 05:54:45.706128, 1, pid=12720, effective(1000, 1000), real(1000, 0)] ../librpc/ndr/ndr.c:402(ndr_print_debug) value: struct leases_db_value num_files : 0x00000001 (1) files: ARRAY(1) files: struct leases_db_file id: struct file_id devid : 0x000000000000fd01 (64769) inode : 0x0000000000080a81 (526977) extid : 0x0000000000000000 (0) servicepath : * servicepath : '/Volumes/normal' base_name : * base_name : 'README' stream_name : NULL [2015/02/18 05:54:45.706889, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:4477(create_file_unixpath) create_file_unixpath: open on README failed - SEC_FLAG_SYSTEM_SECURITY denied. [2015/02/18 05:54:45.707563, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:4770(create_file_unixpath) create_file_unixpath: NT_STATUS_PRIVILEGE_NOT_HELD [2015/02/18 05:54:45.707976, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:5046(create_file_default) create_file: NT_STATUS_PRIVILEGE_NOT_HELD [2015/02/18 05:54:45.708160, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/smb2_server.c:2665(smbd_smb2_request_error_ex) smbd_smb2_request_error_ex: idx[1] status[NT_STATUS_PRIVILEGE_NOT_HELD] || at ../source3/smbd/smb2_create.c:293 [2015/02/18 05:54:45.708255, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/smb2_server.c:2564(smbd_smb2_request_done_ex) smbd_smb2_request_done_ex: idx[1] status[NT_STATUS_PRIVILEGE_NOT_HELD] body[8] dyn[yes:1] at ../source3/smbd/smb2_server.c:2713 [2015/02/18 05:54:45.708329, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/smb2_server.c:899(smb2_set_operation_credit) smb2_set_operation_credit: requested 1, charge 1, granted 1, current possible/max 386/512, total granted/max/low/range 127/8192/65/127 [2015/02/18 05:54:45.710717, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/smb2_server.c:3432(smbd_smb2_io_handler) smbd_smb2_request idx[1] of 5 vectors [2015/02/18 05:54:45.710889, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/smb2_server.c:647(smb2_validate_sequence_number) smb2_validate_sequence_number: clearing id 65 (position 65) from bitmap [2015/02/18 05:54:45.710942, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/smb2_server.c:1957(smbd_smb2_request_dispatch) smbd_smb2_request_dispatch: opcode[SMB2_OP_CREATE] mid = 65 [2015/02/18 05:54:45.710979, 4, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/uid.c:384(change_to_user) Skipping user change - already user [2015/02/18 05:54:45.711033, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/smb2_create.c:501(smbd_smb2_create_send) smbd_smb2_create: name[README] [2015/02/18 05:54:45.711071, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/smb2_create.c:889(smbd_smb2_create_send) Got lease request size 52 [2015/02/18 05:54:45.711095, 1, pid=12720, effective(1000, 1000), real(1000, 0)] ../librpc/ndr/ndr.c:402(ndr_print_debug) lease_ptr: struct smb2_lease lease_key: struct smb2_lease_key data: ARRAY(2) data : 0x00000000cfb12998 (3484494232) data : 0x0000000000000140 (320) lease_state : 0x00000000 (0) 0: SMB2_LEASE_READ 0: SMB2_LEASE_HANDLE 0: SMB2_LEASE_WRITE lease_flags : 0x00000000 (0) lease_duration : 0x0000000000000000 (0) parent_lease_key: struct smb2_lease_key data: ARRAY(2) data : 0x0000000000000000 (0) data : 0x0000000000000000 (0) lease_version : 0x0002 (2) lease_epoch : 0x0001 (1) [2015/02/18 05:54:45.711212, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/smb2_create.c:911(smbd_smb2_create_send) smbd_smb2_create_send: open execution phase [2015/02/18 05:54:45.711235, 5, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/filename.c:258(unix_convert) unix_convert called on file "README" [2015/02/18 05:54:45.711290, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/statcache.c:283(stat_cache_lookup) stat_cache_lookup: lookup succeeded for name [README] -> [README] [2015/02/18 05:54:45.711338, 3, pid=12720, effective(1000, 1000), real(1000, 0), class=vfs] ../source3/smbd/vfs.c:1143(check_reduced_name) check_reduced_name [README] [/Volumes/normal] [2015/02/18 05:54:45.711388, 10, pid=12720, effective(1000, 1000), real(1000, 0), class=vfs] ../source3/smbd/vfs.c:1203(check_reduced_name) check_reduced_name realpath [README] -> [/Volumes/normal/README] [2015/02/18 05:54:45.711410, 3, pid=12720, effective(1000, 1000), real(1000, 0), class=vfs] ../source3/smbd/vfs.c:1273(check_reduced_name) check_reduced_name: README reduced to /Volumes/normal/README [2015/02/18 05:54:45.711435, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:4949(create_file_default) create_file: access_mask = 0x20080 file_attributes = 0x0, share_access = 0x3, create_disposition = 0x1 create_options = 0x0 oplock_request = 0x100 private_flags = 0x0 root_dir_fid = 0x0, ea_list = 0x(nil), sd = 0x(nil), fname = README [2015/02/18 05:54:45.711470, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:4422(create_file_unixpath) create_file_unixpath: access_mask = 0x20080 file_attributes = 0x0, share_access = 0x3, create_disposition = 0x1 create_options = 0x0 oplock_request = 0x100 private_flags = 0x0 ea_list = 0x(nil), sd = 0x(nil), fname = README [2015/02/18 05:54:45.711597, 10, pid=12720, effective(1000, 1000), real(1000, 0), class=locking] ../source3/locking/leases_db.c:75(leases_db_key) leases_db_key: [2015/02/18 05:54:45.711745, 1, pid=12720, effective(1000, 1000), real(1000, 0)] ../librpc/ndr/ndr.c:402(ndr_print_debug) &db_key: struct leases_db_key client_guid : 807779ee-b1c8-11e4-a338-0800275b519b lease_key: struct smb2_lease_key data: ARRAY(2) data : 0x00000000cfb12998 (3484494232) data : 0x0000000000000140 (320) [2015/02/18 05:54:45.711842, 10, pid=12720, effective(1000, 1000), real(1000, 0), class=locking] ../source3/locking/leases_db.c:356(leases_db_parser) leases_db_parser: [2015/02/18 05:54:45.711869, 1, pid=12720, effective(1000, 1000), real(1000, 0)] ../librpc/ndr/ndr.c:402(ndr_print_debug) value: struct leases_db_value num_files : 0x00000001 (1) files: ARRAY(1) files: struct leases_db_file id: struct file_id devid : 0x000000000000fd01 (64769) inode : 0x0000000000080a81 (526977) extid : 0x0000000000000000 (0) servicepath : * servicepath : '/Volumes/normal' base_name : * base_name : 'README' stream_name : NULL [2015/02/18 05:54:45.711978, 5, pid=12720, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap.c:178(dbwrap_check_lock_order) check lock order 1 for /opt/samba/var/lock/smbXsrv_open_global.tdb [2015/02/18 05:54:45.712004, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap.c:133(debug_lock_order) lock order: 1:/opt/samba/var/lock/smbXsrv_open_global.tdb 2: 3: [2015/02/18 05:54:45.712031, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap_tdb.c:60(db_tdb_log_key) Locking key A835263C [2015/02/18 05:54:45.712061, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap_tdb.c:144(db_tdb_fetch_locked_internal) Allocated locked data 0x0x7fb80e10e2f0 [2015/02/18 05:54:45.712085, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/smbXsrv_open.c:588(smbXsrv_open_global_verify_record) smbXsrv_open_global_verify_record: empty value [2015/02/18 05:54:45.712138, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/smbXsrv_open.c:706(smbXsrv_open_global_store) smbXsrv_open_global_store: key 'A835263C' stored [2015/02/18 05:54:45.712165, 1, pid=12720, effective(1000, 1000), real(1000, 0)] ../librpc/ndr/ndr.c:402(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 : 0x00000000000031b0 (12720) task_id : 0x00000000 (0) vnn : 0xffffffff (4294967295) unique_id : 0xfb17366705686992 (-353754229625034350) open_global_id : 0xa835263c (2822055484) open_persistent_id : 0x00000000a835263c (2822055484) open_volatile_id : 0x00000000910d3994 (2433563028) open_owner : S-1-5-21-1849679311-379505231-1387054432-1000 open_time : Wed Feb 18 05:54:46 AM 2015 CET create_guid : 00000000-0000-0000-0000-000000000000 client_guid : 807779ee-b1c8-11e4-a338-0800275b519b 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 [2015/02/18 05:54:45.712333, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap_tdb.c:60(db_tdb_log_key) Unlocking key A835263C [2015/02/18 05:54:45.712368, 5, pid=12720, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap.c:146(dbwrap_lock_order_state_destructor) release lock order 1 for /opt/samba/var/lock/smbXsrv_open_global.tdb [2015/02/18 05:54:45.712392, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap.c:133(debug_lock_order) lock order: 1: 2: 3: [2015/02/18 05:54:45.712808, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/smbXsrv_open.c:880(smbXsrv_open_create) smbXsrv_open_create: global_id (0xa835263c) stored [2015/02/18 05:54:45.712915, 1, pid=12720, effective(1000, 1000), real(1000, 0)] ../librpc/ndr/ndr.c:402(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 : 0x910d3994 (2433563028) global : * global: struct smbXsrv_open_global0 db_rec : NULL server_id: struct server_id pid : 0x00000000000031b0 (12720) task_id : 0x00000000 (0) vnn : 0xffffffff (4294967295) unique_id : 0xfb17366705686992 (-353754229625034350) open_global_id : 0xa835263c (2822055484) open_persistent_id : 0x00000000a835263c (2822055484) open_volatile_id : 0x00000000910d3994 (2433563028) open_owner : S-1-5-21-1849679311-379505231-1387054432-1000 open_time : Wed Feb 18 05:54:46 AM 2015 CET create_guid : 00000000-0000-0000-0000-000000000000 client_guid : 807779ee-b1c8-11e4-a338-0800275b519b 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 status : NT_STATUS_OK idle_time : Wed Feb 18 05:54:46 AM 2015 CET compat : NULL [2015/02/18 05:54:45.713285, 5, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/files.c:129(file_new) allocated file structure fnum 2433563028 (6 used) [2015/02/18 05:54:45.713318, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/files.c:743(file_name_hash) file_name_hash: /Volumes/normal/README hash 0x7d551025 [2015/02/18 05:54:45.713348, 3, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/dosmode.c:196(unix_mode) unix_mode(README) returning 0744 [2015/02/18 05:54:45.713373, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:2478(open_file_ntcreate) open_file_ntcreate: fname=README, dos_attrs=0x0 access_mask=0x20080 share_access=0x3 create_disposition = 0x1 create_options=0x0 unix mode=0744 oplock_request=256 private_flags = 0x0 [2015/02/18 05:54:45.713396, 8, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/dosmode.c:600(dos_mode) dos_mode: README [2015/02/18 05:54:45.713433, 8, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/dosmode.c:242(dos_mode_from_sbuf) dos_mode_from_sbuf returning [2015/02/18 05:54:45.713470, 8, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/dosmode.c:36(dos_mode_debug_print) dos_mode returning [2015/02/18 05:54:45.713497, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:2636(open_file_ntcreate) open_file_ntcreate: fname=README, after mapping access_mask=0x20080 [2015/02/18 05:54:45.713522, 4, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:2726(open_file_ntcreate) calling open_file with flags=0x0 flags2=0x0 mode=0744, access_mask = 0x20080, open_access_mask = 0x20080 [2015/02/18 05:54:45.713650, 10, pid=12720, effective(1000, 1000), real(1000, 0), class=acls] ../source3/smbd/posix_acls.c:3521(posix_get_nt_acl) posix_get_nt_acl: called for file README [2015/02/18 05:54:45.713733, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/passdb/lookup_sid.c:1198(uid_to_sid) uid 1000 -> sid S-1-5-21-1849679311-379505231-1387054432-1000 [2015/02/18 05:54:45.713765, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/passdb/lookup_sid.c:1247(gid_to_sid) gid 0 -> sid S-1-22-2-0 [2015/02/18 05:54:45.713794, 10, pid=12720, effective(1000, 1000), real(1000, 0), class=acls] ../source3/smbd/posix_acls.c:2724(canonicalise_acl) canonicalise_acl: Access ace entries before arrange : [2015/02/18 05:54:45.713818, 10, pid=12720, effective(1000, 1000), real(1000, 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 r-- [2015/02/18 05:54:45.713845, 10, pid=12720, effective(1000, 1000), real(1000, 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 r-- [2015/02/18 05:54:45.714089, 10, pid=12720, effective(1000, 1000), real(1000, 0), class=acls] ../source3/smbd/posix_acls.c:2737(canonicalise_acl) canon_ace index 2. Type = allow SID = S-1-5-21-1849679311-379505231-1387054432-1000 uid 1000 (ralph) SMB_ACL_USER_OBJ ace_flags = 0x0 perms rw- [2015/02/18 05:54:45.714163, 10, pid=12720, effective(1000, 1000), real(1000, 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-5-21-1849679311-379505231-1387054432-1000 uid 1000 (ralph) SMB_ACL_USER_OBJ ace_flags = 0x0 perms rw- canon_ace index 1. Type = allow SID = S-1-22-2-0 gid 0 (root) SMB_ACL_GROUP_OBJ ace_flags = 0x0 perms r-- canon_ace index 2. Type = allow SID = S-1-1-0 other SMB_ACL_OTHER ace_flags = 0x0 perms r-- [2015/02/18 05:54:45.714267, 10, pid=12720, effective(1000, 1000), real(1000, 0), class=acls] ../source3/smbd/posix_acls.c:1110(map_canon_ace_perms) map_canon_ace_perms: Mapped (UNIX) 180 to (NT) 12019f [2015/02/18 05:54:45.714293, 10, pid=12720, effective(1000, 1000), real(1000, 0), class=acls] ../source3/smbd/posix_acls.c:1110(map_canon_ace_perms) map_canon_ace_perms: Mapped (UNIX) 100 to (NT) 120089 [2015/02/18 05:54:45.714316, 10, pid=12720, effective(1000, 1000), real(1000, 0), class=acls] ../source3/smbd/posix_acls.c:1110(map_canon_ace_perms) map_canon_ace_perms: Mapped (UNIX) 100 to (NT) 120089 [2015/02/18 05:54:45.714357, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:174(smbd_check_access_rights) smbd_check_access_rights: file README requesting 0x20080 returning 0x20000 (NT_STATUS_OK) [2015/02/18 05:54:45.714386, 2, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:1005(open_file) ralph opened file README read=No write=No (numopen=6) [2015/02/18 05:54:45.714413, 5, pid=12720, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap.c:178(dbwrap_check_lock_order) check lock order 1 for /opt/samba/var/lock/locking.tdb [2015/02/18 05:54:45.714521, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap.c:133(debug_lock_order) lock order: 1:/opt/samba/var/lock/locking.tdb 2: 3: [2015/02/18 05:54:45.714563, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap_tdb.c:60(db_tdb_log_key) Locking key 01FD000000000000810A [2015/02/18 05:54:45.714608, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap_tdb.c:144(db_tdb_fetch_locked_internal) Allocated locked data 0x0x7fb80e11fd80 [2015/02/18 05:54:45.714658, 10, pid=12720, effective(1000, 1000), real(1000, 0), class=locking] ../source3/locking/share_mode_lock.c:174(parse_share_modes) parse_share_modes: [2015/02/18 05:54:45.714684, 1, pid=12720, effective(1000, 1000), real(1000, 0)] ../librpc/ndr/ndr.c:402(ndr_print_debug) d: struct share_mode_data servicepath : * servicepath : '/Volumes/normal' base_name : * base_name : 'README' stream_name : NULL num_share_modes : 0x00000003 (3) share_modes: ARRAY(3) share_modes: struct share_mode_entry pid: struct server_id pid : 0x00000000000031b0 (12720) task_id : 0x00000000 (0) vnn : 0xffffffff (4294967295) unique_id : 0xfb17366705686992 (-353754229625034350) op_mid : 0x000000000000003c (60) op_type : 0x0100 (256) lease_idx : 0x00000000 (0) access_mask : 0x00120089 (1179785) share_access : 0x00000001 (1) private_options : 0x00000000 (0) time : Wed Feb 18 05:54:45 AM 2015 CET.581827 id: struct file_id devid : 0x000000000000fd01 (64769) inode : 0x0000000000080a81 (526977) extid : 0x0000000000000000 (0) share_file_id : 0x000000003357c520 (861390112) uid : 0x000003e8 (1000) flags : 0x0000 (0) name_hash : 0x7d551025 (2102726693) stale : 0x00 (0) lease : * lease: struct share_mode_lease client_guid : 807779ee-b1c8-11e4-a338-0800275b519b lease_key: struct smb2_lease_key data: ARRAY(2) data : 0x00000000cfb12998 (3484494232) data : 0x0000000000000140 (320) current_state : 0x00000007 (7) 1: SMB2_LEASE_READ 1: SMB2_LEASE_HANDLE 1: SMB2_LEASE_WRITE breaking : 0x00 (0) breaking_to_requested : 0x00000000 (0) 0: SMB2_LEASE_READ 0: SMB2_LEASE_HANDLE 0: SMB2_LEASE_WRITE breaking_to_required : 0x00000000 (0) 0: SMB2_LEASE_READ 0: SMB2_LEASE_HANDLE 0: SMB2_LEASE_WRITE lease_version : 0x0002 (2) epoch : 0x0001 (1) share_modes: struct share_mode_entry pid: struct server_id pid : 0x00000000000031b0 (12720) task_id : 0x00000000 (0) vnn : 0xffffffff (4294967295) unique_id : 0xfb17366705686992 (-353754229625034350) op_mid : 0x000000000000003e (62) op_type : 0x0100 (256) lease_idx : 0x00000000 (0) access_mask : 0x00120089 (1179785) share_access : 0x00000003 (3) private_options : 0x00000000 (0) time : Wed Feb 18 05:54:45 AM 2015 CET.617039 id: struct file_id devid : 0x000000000000fd01 (64769) inode : 0x0000000000080a81 (526977) extid : 0x0000000000000000 (0) share_file_id : 0x00000000db0ae006 (3674923014) uid : 0x000003e8 (1000) flags : 0x0000 (0) name_hash : 0x7d551025 (2102726693) stale : 0x00 (0) lease : * lease: struct share_mode_lease client_guid : 807779ee-b1c8-11e4-a338-0800275b519b lease_key: struct smb2_lease_key data: ARRAY(2) data : 0x00000000cfb12998 (3484494232) data : 0x0000000000000140 (320) current_state : 0x00000007 (7) 1: SMB2_LEASE_READ 1: SMB2_LEASE_HANDLE 1: SMB2_LEASE_WRITE breaking : 0x00 (0) breaking_to_requested : 0x00000000 (0) 0: SMB2_LEASE_READ 0: SMB2_LEASE_HANDLE 0: SMB2_LEASE_WRITE breaking_to_required : 0x00000000 (0) 0: SMB2_LEASE_READ 0: SMB2_LEASE_HANDLE 0: SMB2_LEASE_WRITE lease_version : 0x0002 (2) epoch : 0x0001 (1) share_modes: struct share_mode_entry pid: struct server_id pid : 0x00000000000031b0 (12720) task_id : 0x00000000 (0) vnn : 0xffffffff (4294967295) unique_id : 0xfb17366705686992 (-353754229625034350) op_mid : 0x000000000000003f (63) op_type : 0x0100 (256) lease_idx : 0x00000000 (0) access_mask : 0x00120089 (1179785) share_access : 0x00000005 (5) private_options : 0x00000000 (0) time : Wed Feb 18 05:54:45 AM 2015 CET.652645 id: struct file_id devid : 0x000000000000fd01 (64769) inode : 0x0000000000080a81 (526977) extid : 0x0000000000000000 (0) share_file_id : 0x000000003987c697 (965199511) uid : 0x000003e8 (1000) flags : 0x0000 (0) name_hash : 0x7d551025 (2102726693) stale : 0x00 (0) lease : * lease: struct share_mode_lease client_guid : 807779ee-b1c8-11e4-a338-0800275b519b lease_key: struct smb2_lease_key data: ARRAY(2) data : 0x00000000cfb12998 (3484494232) data : 0x0000000000000140 (320) current_state : 0x00000007 (7) 1: SMB2_LEASE_READ 1: SMB2_LEASE_HANDLE 1: SMB2_LEASE_WRITE breaking : 0x00 (0) breaking_to_requested : 0x00000000 (0) 0: SMB2_LEASE_READ 0: SMB2_LEASE_HANDLE 0: SMB2_LEASE_WRITE breaking_to_required : 0x00000000 (0) 0: SMB2_LEASE_READ 0: SMB2_LEASE_HANDLE 0: SMB2_LEASE_WRITE lease_version : 0x0002 (2) epoch : 0x0001 (1) num_leases : 0x00000001 (1) leases: ARRAY(1) leases: struct share_mode_lease client_guid : 807779ee-b1c8-11e4-a338-0800275b519b lease_key: struct smb2_lease_key data: ARRAY(2) data : 0x00000000cfb12998 (3484494232) data : 0x0000000000000140 (320) current_state : 0x00000007 (7) 1: SMB2_LEASE_READ 1: SMB2_LEASE_HANDLE 1: SMB2_LEASE_WRITE breaking : 0x00 (0) breaking_to_requested : 0x00000000 (0) 0: SMB2_LEASE_READ 0: SMB2_LEASE_HANDLE 0: SMB2_LEASE_WRITE breaking_to_required : 0x00000000 (0) 0: SMB2_LEASE_READ 0: SMB2_LEASE_HANDLE 0: SMB2_LEASE_WRITE lease_version : 0x0002 (2) epoch : 0x0001 (1) num_delete_tokens : 0x00000000 (0) delete_tokens: ARRAY(0) old_write_time : Thu Aug 7 11:02:08 AM 2014 CEST.0 changed_write_time : Thu Jan 1 01:00:00 AM 1970 CET.0 fresh : 0x00 (0) modified : 0x00 (0) record : NULL [2015/02/18 05:54:45.717295, 10, pid=12720, effective(1000, 1000), real(1000, 0), class=locking] ../source3/locking/locking.c:1192(find_delete_on_close_token) find_delete_on_close_token: name_hash = 0x7d551025 [2015/02/18 05:54:45.718174, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:1025(share_conflict) share_conflict: entry->access_mask = 0x120089, entry->share_access = 0x1, entry->private_options = 0x0 [2015/02/18 05:54:45.719423, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:1036(share_conflict) share_conflict: access_mask = 0x20080, share_access = 0x3 [2015/02/18 05:54:45.719634, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:1056(share_conflict) share_conflict: No conflict due to access_mask = 0x20080 [2015/02/18 05:54:45.719685, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:1025(share_conflict) share_conflict: entry->access_mask = 0x120089, entry->share_access = 0x3, entry->private_options = 0x0 [2015/02/18 05:54:45.719785, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:1036(share_conflict) share_conflict: access_mask = 0x20080, share_access = 0x3 [2015/02/18 05:54:45.719852, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:1056(share_conflict) share_conflict: No conflict due to access_mask = 0x20080 [2015/02/18 05:54:45.720029, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:1025(share_conflict) share_conflict: entry->access_mask = 0x120089, entry->share_access = 0x5, entry->private_options = 0x0 [2015/02/18 05:54:45.720313, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:1036(share_conflict) share_conflict: access_mask = 0x20080, share_access = 0x3 [2015/02/18 05:54:45.720807, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:1056(share_conflict) share_conflict: No conflict due to access_mask = 0x20080 [2015/02/18 05:54:45.720873, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:1442(delay_for_oplock) entry 0: e_lease_type 7, will_overwrite: 0 [2015/02/18 05:54:45.720913, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:1442(delay_for_oplock) entry 1: e_lease_type 7, will_overwrite: 0 [2015/02/18 05:54:45.721185, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:1442(delay_for_oplock) entry 2: e_lease_type 7, will_overwrite: 0 [2015/02/18 05:54:45.721237, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:1755(grant_fsp_oplock_type) No read or write lease requested [2015/02/18 05:54:45.721281, 10, pid=12720, effective(1000, 1000), real(1000, 0), class=locking] ../source3/locking/brlock.c:2032(brl_get_locks_readonly) seqnum=9, fsp->brlock_seqnum=0 [2015/02/18 05:54:45.721727, 10, pid=12720, effective(1000, 1000), real(1000, 0), class=locking] ../source3/locking/locking.c:748(share_mode_stale_pid) PID 12720 (index 0 out of 3) still exists [2015/02/18 05:54:45.721803, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:1634(grant_fsp_lease) existing=7, requested=0, granted=0, do_upgrade=0 [2015/02/18 05:54:45.721846, 10, pid=12720, effective(1000, 1000), real(1000, 0), class=locking] ../source3/smbd/oplock.c:389(fsp_lease_update) fsp_lease_update: refresh lease state [2015/02/18 05:54:45.721885, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:1827(grant_fsp_oplock_type) lease_state=7 [2015/02/18 05:54:45.721927, 10, pid=12720, effective(1000, 1000), real(1000, 0), class=locking] ../source3/locking/brlock.c:2032(brl_get_locks_readonly) seqnum=9, fsp->brlock_seqnum=9 [2015/02/18 05:54:45.721973, 5, pid=12720, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap.c:178(dbwrap_check_lock_order) check lock order 2 for /opt/samba/var/lock/brlock.tdb [2015/02/18 05:54:45.722012, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap.c:133(debug_lock_order) lock order: 1:/opt/samba/var/lock/locking.tdb 2:/opt/samba/var/lock/brlock.tdb 3: [2015/02/18 05:54:45.722059, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap_tdb.c:60(db_tdb_log_key) Locking key 01FD000000000000810A [2015/02/18 05:54:45.722120, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap_tdb.c:144(db_tdb_fetch_locked_internal) Allocated locked data 0x0x7fb80e120380 [2015/02/18 05:54:45.722176, 10, pid=12720, effective(1000, 1000), real(1000, 0), class=locking] ../source3/locking/brlock.c:1990(brl_get_locks) brl_get_locks_internal: 0 current locks on file_id fd01:80a81:0 [2015/02/18 05:54:45.723204, 10, pid=12720, effective(1000, 1000), real(1000, 0), class=locking] ../source3/locking/brlock.c:94(brl_set_num_read_oplocks) Setting num_read_oplocks to 4 [2015/02/18 05:54:45.723404, 10, pid=12720, effective(1000, 1000), real(1000, 0), class=locking] ../source3/locking/brlock.c:1908(byte_range_lock_flush) seqnum=10 [2015/02/18 05:54:45.723793, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap_tdb.c:60(db_tdb_log_key) Unlocking key 01FD000000000000810A [2015/02/18 05:54:45.724227, 5, pid=12720, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap.c:146(dbwrap_lock_order_state_destructor) release lock order 2 for /opt/samba/var/lock/brlock.tdb [2015/02/18 05:54:45.724411, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap.c:133(debug_lock_order) lock order: 1:/opt/samba/var/lock/locking.tdb 2: 3: [2015/02/18 05:54:45.724665, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:1873(grant_fsp_oplock_type) grant_fsp_oplock_type: oplock type 0x100 on file README [2015/02/18 05:54:45.724689, 10, pid=12720, effective(1000, 1000), real(1000, 0), class=locking] ../source3/locking/share_mode_lock.c:194(unparse_share_modes) unparse_share_modes: [2015/02/18 05:54:45.724860, 1, pid=12720, effective(1000, 1000), real(1000, 0)] ../librpc/ndr/ndr.c:402(ndr_print_debug) d: struct share_mode_data servicepath : * servicepath : '/Volumes/normal' base_name : * base_name : 'README' stream_name : NULL num_share_modes : 0x00000004 (4) share_modes: ARRAY(4) share_modes: struct share_mode_entry pid: struct server_id pid : 0x00000000000031b0 (12720) task_id : 0x00000000 (0) vnn : 0xffffffff (4294967295) unique_id : 0xfb17366705686992 (-353754229625034350) op_mid : 0x000000000000003c (60) op_type : 0x0100 (256) lease_idx : 0x00000000 (0) access_mask : 0x00120089 (1179785) share_access : 0x00000001 (1) private_options : 0x00000000 (0) time : Wed Feb 18 05:54:45 AM 2015 CET.581827 id: struct file_id devid : 0x000000000000fd01 (64769) inode : 0x0000000000080a81 (526977) extid : 0x0000000000000000 (0) share_file_id : 0x000000003357c520 (861390112) uid : 0x000003e8 (1000) flags : 0x0000 (0) name_hash : 0x7d551025 (2102726693) stale : 0x00 (0) lease : * lease: struct share_mode_lease client_guid : 807779ee-b1c8-11e4-a338-0800275b519b lease_key: struct smb2_lease_key data: ARRAY(2) data : 0x00000000cfb12998 (3484494232) data : 0x0000000000000140 (320) current_state : 0x00000007 (7) 1: SMB2_LEASE_READ 1: SMB2_LEASE_HANDLE 1: SMB2_LEASE_WRITE breaking : 0x00 (0) breaking_to_requested : 0x00000000 (0) 0: SMB2_LEASE_READ 0: SMB2_LEASE_HANDLE 0: SMB2_LEASE_WRITE breaking_to_required : 0x00000000 (0) 0: SMB2_LEASE_READ 0: SMB2_LEASE_HANDLE 0: SMB2_LEASE_WRITE lease_version : 0x0002 (2) epoch : 0x0001 (1) share_modes: struct share_mode_entry pid: struct server_id pid : 0x00000000000031b0 (12720) task_id : 0x00000000 (0) vnn : 0xffffffff (4294967295) unique_id : 0xfb17366705686992 (-353754229625034350) op_mid : 0x000000000000003e (62) op_type : 0x0100 (256) lease_idx : 0x00000000 (0) access_mask : 0x00120089 (1179785) share_access : 0x00000003 (3) private_options : 0x00000000 (0) time : Wed Feb 18 05:54:45 AM 2015 CET.617039 id: struct file_id devid : 0x000000000000fd01 (64769) inode : 0x0000000000080a81 (526977) extid : 0x0000000000000000 (0) share_file_id : 0x00000000db0ae006 (3674923014) uid : 0x000003e8 (1000) flags : 0x0000 (0) name_hash : 0x7d551025 (2102726693) stale : 0x00 (0) lease : * lease: struct share_mode_lease client_guid : 807779ee-b1c8-11e4-a338-0800275b519b lease_key: struct smb2_lease_key data: ARRAY(2) data : 0x00000000cfb12998 (3484494232) data : 0x0000000000000140 (320) current_state : 0x00000007 (7) 1: SMB2_LEASE_READ 1: SMB2_LEASE_HANDLE 1: SMB2_LEASE_WRITE breaking : 0x00 (0) breaking_to_requested : 0x00000000 (0) 0: SMB2_LEASE_READ 0: SMB2_LEASE_HANDLE 0: SMB2_LEASE_WRITE breaking_to_required : 0x00000000 (0) 0: SMB2_LEASE_READ 0: SMB2_LEASE_HANDLE 0: SMB2_LEASE_WRITE lease_version : 0x0002 (2) epoch : 0x0001 (1) share_modes: struct share_mode_entry pid: struct server_id pid : 0x00000000000031b0 (12720) task_id : 0x00000000 (0) vnn : 0xffffffff (4294967295) unique_id : 0xfb17366705686992 (-353754229625034350) op_mid : 0x000000000000003f (63) op_type : 0x0100 (256) lease_idx : 0x00000000 (0) access_mask : 0x00120089 (1179785) share_access : 0x00000005 (5) private_options : 0x00000000 (0) time : Wed Feb 18 05:54:45 AM 2015 CET.652645 id: struct file_id devid : 0x000000000000fd01 (64769) inode : 0x0000000000080a81 (526977) extid : 0x0000000000000000 (0) share_file_id : 0x000000003987c697 (965199511) uid : 0x000003e8 (1000) flags : 0x0000 (0) name_hash : 0x7d551025 (2102726693) stale : 0x00 (0) lease : * lease: struct share_mode_lease client_guid : 807779ee-b1c8-11e4-a338-0800275b519b lease_key: struct smb2_lease_key data: ARRAY(2) data : 0x00000000cfb12998 (3484494232) data : 0x0000000000000140 (320) current_state : 0x00000007 (7) 1: SMB2_LEASE_READ 1: SMB2_LEASE_HANDLE 1: SMB2_LEASE_WRITE breaking : 0x00 (0) breaking_to_requested : 0x00000000 (0) 0: SMB2_LEASE_READ 0: SMB2_LEASE_HANDLE 0: SMB2_LEASE_WRITE breaking_to_required : 0x00000000 (0) 0: SMB2_LEASE_READ 0: SMB2_LEASE_HANDLE 0: SMB2_LEASE_WRITE lease_version : 0x0002 (2) epoch : 0x0001 (1) share_modes: struct share_mode_entry pid: struct server_id pid : 0x00000000000031b0 (12720) task_id : 0x00000000 (0) vnn : 0xffffffff (4294967295) unique_id : 0xfb17366705686992 (-353754229625034350) op_mid : 0x0000000000000041 (65) op_type : 0x0100 (256) lease_idx : 0x00000000 (0) access_mask : 0x00020080 (131200) share_access : 0x00000003 (3) private_options : 0x00000000 (0) time : Wed Feb 18 05:54:45 AM 2015 CET.711964 id: struct file_id devid : 0x000000000000fd01 (64769) inode : 0x0000000000080a81 (526977) extid : 0x0000000000000000 (0) share_file_id : 0x00000000d69f1b7b (3600751483) uid : 0x000003e8 (1000) flags : 0x0000 (0) name_hash : 0x7d551025 (2102726693) stale : 0x00 (0) lease : * lease: struct share_mode_lease client_guid : 807779ee-b1c8-11e4-a338-0800275b519b lease_key: struct smb2_lease_key data: ARRAY(2) data : 0x00000000cfb12998 (3484494232) data : 0x0000000000000140 (320) current_state : 0x00000007 (7) 1: SMB2_LEASE_READ 1: SMB2_LEASE_HANDLE 1: SMB2_LEASE_WRITE breaking : 0x00 (0) breaking_to_requested : 0x00000000 (0) 0: SMB2_LEASE_READ 0: SMB2_LEASE_HANDLE 0: SMB2_LEASE_WRITE breaking_to_required : 0x00000000 (0) 0: SMB2_LEASE_READ 0: SMB2_LEASE_HANDLE 0: SMB2_LEASE_WRITE lease_version : 0x0002 (2) epoch : 0x0001 (1) num_leases : 0x00000001 (1) leases: ARRAY(1) leases: struct share_mode_lease client_guid : 807779ee-b1c8-11e4-a338-0800275b519b lease_key: struct smb2_lease_key data: ARRAY(2) data : 0x00000000cfb12998 (3484494232) data : 0x0000000000000140 (320) current_state : 0x00000007 (7) 1: SMB2_LEASE_READ 1: SMB2_LEASE_HANDLE 1: SMB2_LEASE_WRITE breaking : 0x00 (0) breaking_to_requested : 0x00000000 (0) 0: SMB2_LEASE_READ 0: SMB2_LEASE_HANDLE 0: SMB2_LEASE_WRITE breaking_to_required : 0x00000000 (0) 0: SMB2_LEASE_READ 0: SMB2_LEASE_HANDLE 0: SMB2_LEASE_WRITE lease_version : 0x0002 (2) epoch : 0x0001 (1) num_delete_tokens : 0x00000000 (0) delete_tokens: ARRAY(0) old_write_time : Thu Aug 7 11:02:08 AM 2014 CEST.0 changed_write_time : Thu Jan 1 01:00:00 AM 1970 CET.0 fresh : 0x00 (0) modified : 0x01 (1) record : * [2015/02/18 05:54:45.728033, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap_tdb.c:60(db_tdb_log_key) Unlocking key 01FD000000000000810A [2015/02/18 05:54:45.728069, 5, pid=12720, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap.c:146(dbwrap_lock_order_state_destructor) release lock order 1 for /opt/samba/var/lock/locking.tdb [2015/02/18 05:54:45.728095, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap.c:133(debug_lock_order) lock order: 1: 2: 3: [2015/02/18 05:54:45.728122, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:4758(create_file_unixpath) create_file_unixpath: info=1 [2015/02/18 05:54:45.728148, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:5037(create_file_default) create_file: info=1 [2015/02/18 05:54:45.728173, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/smb2_create.c:1093(smbd_smb2_create_send) smbd_smb2_create_send: response construction phase [2015/02/18 05:54:45.728211, 10, pid=12720, effective(1000, 1000), real(1000, 0), class=acls] ../source3/smbd/posix_acls.c:3521(posix_get_nt_acl) posix_get_nt_acl: called for file README [2015/02/18 05:54:45.728287, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/passdb/lookup_sid.c:1198(uid_to_sid) uid 1000 -> sid S-1-5-21-1849679311-379505231-1387054432-1000 [2015/02/18 05:54:45.728552, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/passdb/lookup_sid.c:1247(gid_to_sid) gid 0 -> sid S-1-22-2-0 [2015/02/18 05:54:45.728597, 10, pid=12720, effective(1000, 1000), real(1000, 0), class=acls] ../source3/smbd/posix_acls.c:2724(canonicalise_acl) canonicalise_acl: Access ace entries before arrange : [2015/02/18 05:54:45.728623, 10, pid=12720, effective(1000, 1000), real(1000, 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 r-- [2015/02/18 05:54:45.728678, 10, pid=12720, effective(1000, 1000), real(1000, 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 r-- [2015/02/18 05:54:45.729648, 10, pid=12720, effective(1000, 1000), real(1000, 0), class=acls] ../source3/smbd/posix_acls.c:2737(canonicalise_acl) canon_ace index 2. Type = allow SID = S-1-5-21-1849679311-379505231-1387054432-1000 uid 1000 (ralph) SMB_ACL_USER_OBJ ace_flags = 0x0 perms rw- [2015/02/18 05:54:45.729802, 10, pid=12720, effective(1000, 1000), real(1000, 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-5-21-1849679311-379505231-1387054432-1000 uid 1000 (ralph) SMB_ACL_USER_OBJ ace_flags = 0x0 perms rw- canon_ace index 1. Type = allow SID = S-1-22-2-0 gid 0 (root) SMB_ACL_GROUP_OBJ ace_flags = 0x0 perms r-- canon_ace index 2. Type = allow SID = S-1-1-0 other SMB_ACL_OTHER ace_flags = 0x0 perms r-- [2015/02/18 05:54:45.730557, 10, pid=12720, effective(1000, 1000), real(1000, 0), class=acls] ../source3/smbd/posix_acls.c:1110(map_canon_ace_perms) map_canon_ace_perms: Mapped (UNIX) 180 to (NT) 12019f [2015/02/18 05:54:45.730923, 10, pid=12720, effective(1000, 1000), real(1000, 0), class=acls] ../source3/smbd/posix_acls.c:1110(map_canon_ace_perms) map_canon_ace_perms: Mapped (UNIX) 100 to (NT) 120089 [2015/02/18 05:54:45.731213, 10, pid=12720, effective(1000, 1000), real(1000, 0), class=acls] ../source3/smbd/posix_acls.c:1110(map_canon_ace_perms) map_canon_ace_perms: Mapped (UNIX) 100 to (NT) 120089 [2015/02/18 05:54:45.731722, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../libcli/security/access_check.c:188(se_access_check) se_access_check: MAX desired = 0x2000000, granted = 0x16019f, remaining = 0x16019f [2015/02/18 05:54:45.731956, 10, pid=12720, effective(1000, 1000), real(1000, 0), class=acls] ../source3/smbd/posix_acls.c:3521(posix_get_nt_acl) posix_get_nt_acl: called for file . [2015/02/18 05:54:45.732195, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/passdb/lookup_sid.c:1198(uid_to_sid) uid 0 -> sid S-1-5-21-1849679311-379505231-1387054432-1001 [2015/02/18 05:54:45.732262, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/passdb/lookup_sid.c:1247(gid_to_sid) gid 0 -> sid S-1-22-2-0 [2015/02/18 05:54:45.732979, 10, pid=12720, effective(1000, 1000), real(1000, 0), class=acls] ../source3/smbd/posix_acls.c:2724(canonicalise_acl) canonicalise_acl: Access ace entries before arrange : [2015/02/18 05:54:45.733048, 10, pid=12720, effective(1000, 1000), real(1000, 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 [2015/02/18 05:54:45.733103, 10, pid=12720, effective(1000, 1000), real(1000, 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 [2015/02/18 05:54:45.734348, 10, pid=12720, effective(1000, 1000), real(1000, 0), class=acls] ../source3/smbd/posix_acls.c:2737(canonicalise_acl) canon_ace index 2. Type = allow SID = S-1-5-21-1849679311-379505231-1387054432-1001 uid 0 (root) SMB_ACL_USER_OBJ ace_flags = 0x0 perms rwx [2015/02/18 05:54:45.734890, 10, pid=12720, effective(1000, 1000), real(1000, 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-5-21-1849679311-379505231-1387054432-1001 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 [2015/02/18 05:54:45.735063, 10, pid=12720, effective(1000, 1000), real(1000, 0), class=acls] ../source3/smbd/posix_acls.c:1110(map_canon_ace_perms) map_canon_ace_perms: Mapped (UNIX) 1c0 to (NT) 1f01ff [2015/02/18 05:54:45.735384, 10, pid=12720, effective(1000, 1000), real(1000, 0), class=acls] ../source3/smbd/posix_acls.c:1110(map_canon_ace_perms) map_canon_ace_perms: Mapped (UNIX) 1c0 to (NT) 1f01ff [2015/02/18 05:54:45.735655, 10, pid=12720, effective(1000, 1000), real(1000, 0), class=acls] ../source3/smbd/posix_acls.c:1110(map_canon_ace_perms) map_canon_ace_perms: Mapped (UNIX) 1c0 to (NT) 1f01ff [2015/02/18 05:54:45.736008, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:174(smbd_check_access_rights) smbd_check_access_rights: file . requesting 0x40 returning 0x40 (NT_STATUS_OK) [2015/02/18 05:54:45.736076, 5, pid=12720, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap.c:178(dbwrap_check_lock_order) check lock order 1 for /opt/samba/var/lock/smbXsrv_open_global.tdb [2015/02/18 05:54:45.736152, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap.c:133(debug_lock_order) lock order: 1:/opt/samba/var/lock/smbXsrv_open_global.tdb 2: 3: [2015/02/18 05:54:45.736202, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap_tdb.c:60(db_tdb_log_key) Locking key A835263C [2015/02/18 05:54:45.736259, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap_tdb.c:144(db_tdb_fetch_locked_internal) Allocated locked data 0x0x7fb80e10e280 [2015/02/18 05:54:45.736328, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/smbXsrv_open.c:706(smbXsrv_open_global_store) smbXsrv_open_global_store: key 'A835263C' stored [2015/02/18 05:54:45.736373, 1, pid=12720, effective(1000, 1000), real(1000, 0)] ../librpc/ndr/ndr.c:402(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 : 0x00000000000031b0 (12720) task_id : 0x00000000 (0) vnn : 0xffffffff (4294967295) unique_id : 0xfb17366705686992 (-353754229625034350) open_global_id : 0xa835263c (2822055484) open_persistent_id : 0x00000000a835263c (2822055484) open_volatile_id : 0x00000000910d3994 (2433563028) open_owner : S-1-5-21-1849679311-379505231-1387054432-1000 open_time : Wed Feb 18 05:54:46 AM 2015 CET create_guid : 8077886a-b1c8-11e4-a338-0800275b519b client_guid : 807779ee-b1c8-11e4-a338-0800275b519b 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 [2015/02/18 05:54:45.736834, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap_tdb.c:60(db_tdb_log_key) Unlocking key A835263C [2015/02/18 05:54:45.736883, 5, pid=12720, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap.c:146(dbwrap_lock_order_state_destructor) release lock order 1 for /opt/samba/var/lock/smbXsrv_open_global.tdb [2015/02/18 05:54:45.736924, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap.c:133(debug_lock_order) lock order: 1: 2: 3: [2015/02/18 05:54:45.736967, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/smbXsrv_open.c:951(smbXsrv_open_update) smbXsrv_open_update: global_id (0xa835263c) stored [2015/02/18 05:54:45.737021, 1, pid=12720, effective(1000, 1000), real(1000, 0)] ../librpc/ndr/ndr.c:402(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 : 0x910d3994 (2433563028) global : * global: struct smbXsrv_open_global0 db_rec : NULL server_id: struct server_id pid : 0x00000000000031b0 (12720) task_id : 0x00000000 (0) vnn : 0xffffffff (4294967295) unique_id : 0xfb17366705686992 (-353754229625034350) open_global_id : 0xa835263c (2822055484) open_persistent_id : 0x00000000a835263c (2822055484) open_volatile_id : 0x00000000910d3994 (2433563028) open_owner : S-1-5-21-1849679311-379505231-1387054432-1000 open_time : Wed Feb 18 05:54:46 AM 2015 CET create_guid : 8077886a-b1c8-11e4-a338-0800275b519b client_guid : 807779ee-b1c8-11e4-a338-0800275b519b 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 status : NT_STATUS_OK idle_time : Wed Feb 18 05:54:46 AM 2015 CET compat : * [2015/02/18 05:54:45.739255, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/smb2_create.c:1149(smbd_smb2_create_send) smb2_create_send: smbXsrv_open_update returned NT_STATUS_OK [2015/02/18 05:54:45.739313, 8, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/dosmode.c:600(dos_mode) dos_mode: README [2015/02/18 05:54:45.739380, 8, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/dosmode.c:242(dos_mode_from_sbuf) dos_mode_from_sbuf returning [2015/02/18 05:54:45.739570, 8, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/dosmode.c:36(dos_mode_debug_print) dos_mode returning [2015/02/18 05:54:45.739645, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/smb2_create.c:1274(smbd_smb2_create_send) smbd_smb2_create_send: README - fnum 2433563028 [2015/02/18 05:54:45.739707, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/smb2_server.c:2564(smbd_smb2_request_done_ex) smbd_smb2_request_done_ex: idx[1] status[NT_STATUS_OK] body[88] dyn[yes:108] at ../source3/smbd/smb2_create.c:364 [2015/02/18 05:54:45.739766, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/smb2_server.c:899(smb2_set_operation_credit) smb2_set_operation_credit: requested 1, charge 1, granted 1, current possible/max 386/512, total granted/max/low/range 127/8192/66/127 [2015/02/18 05:54:45.745523, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/smb2_server.c:3432(smbd_smb2_io_handler) smbd_smb2_request idx[1] of 5 vectors [2015/02/18 05:54:45.745645, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/smb2_server.c:647(smb2_validate_sequence_number) smb2_validate_sequence_number: clearing id 66 (position 66) from bitmap [2015/02/18 05:54:45.745712, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/smb2_server.c:1957(smbd_smb2_request_dispatch) smbd_smb2_request_dispatch: opcode[SMB2_OP_CREATE] mid = 66 [2015/02/18 05:54:45.745765, 4, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/uid.c:384(change_to_user) Skipping user change - already user [2015/02/18 05:54:45.745843, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/smb2_create.c:501(smbd_smb2_create_send) smbd_smb2_create: name[README] [2015/02/18 05:54:45.745898, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/smb2_create.c:889(smbd_smb2_create_send) Got lease request size 52 [2015/02/18 05:54:45.745937, 1, pid=12720, effective(1000, 1000), real(1000, 0)] ../librpc/ndr/ndr.c:402(ndr_print_debug) lease_ptr: struct smb2_lease lease_key: struct smb2_lease_key data: ARRAY(2) data : 0x00000000cfb12998 (3484494232) data : 0x0000000000000140 (320) lease_state : 0x00000000 (0) 0: SMB2_LEASE_READ 0: SMB2_LEASE_HANDLE 0: SMB2_LEASE_WRITE lease_flags : 0x00000000 (0) lease_duration : 0x0000000000000000 (0) parent_lease_key: struct smb2_lease_key data: ARRAY(2) data : 0x0000000000000000 (0) data : 0x0000000000000000 (0) lease_version : 0x0002 (2) lease_epoch : 0x0001 (1) [2015/02/18 05:54:45.746228, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/smb2_create.c:911(smbd_smb2_create_send) smbd_smb2_create_send: open execution phase [2015/02/18 05:54:45.746284, 5, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/filename.c:258(unix_convert) unix_convert called on file "README" [2015/02/18 05:54:45.746574, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/statcache.c:283(stat_cache_lookup) stat_cache_lookup: lookup succeeded for name [README] -> [README] [2015/02/18 05:54:45.746669, 3, pid=12720, effective(1000, 1000), real(1000, 0), class=vfs] ../source3/smbd/vfs.c:1143(check_reduced_name) check_reduced_name [README] [/Volumes/normal] [2015/02/18 05:54:45.746789, 10, pid=12720, effective(1000, 1000), real(1000, 0), class=vfs] ../source3/smbd/vfs.c:1203(check_reduced_name) check_reduced_name realpath [README] -> [/Volumes/normal/README] [2015/02/18 05:54:45.746836, 3, pid=12720, effective(1000, 1000), real(1000, 0), class=vfs] ../source3/smbd/vfs.c:1273(check_reduced_name) check_reduced_name: README reduced to /Volumes/normal/README [2015/02/18 05:54:45.746891, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:4949(create_file_default) create_file: access_mask = 0x40080 file_attributes = 0x0, share_access = 0x3, create_disposition = 0x1 create_options = 0x0 oplock_request = 0x100 private_flags = 0x0 root_dir_fid = 0x0, ea_list = 0x(nil), sd = 0x(nil), fname = README [2015/02/18 05:54:45.746947, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:4422(create_file_unixpath) create_file_unixpath: access_mask = 0x40080 file_attributes = 0x0, share_access = 0x3, create_disposition = 0x1 create_options = 0x0 oplock_request = 0x100 private_flags = 0x0 ea_list = 0x(nil), sd = 0x(nil), fname = README [2015/02/18 05:54:45.747001, 10, pid=12720, effective(1000, 1000), real(1000, 0), class=locking] ../source3/locking/leases_db.c:75(leases_db_key) leases_db_key: [2015/02/18 05:54:45.747046, 1, pid=12720, effective(1000, 1000), real(1000, 0)] ../librpc/ndr/ndr.c:402(ndr_print_debug) &db_key: struct leases_db_key client_guid : 807779ee-b1c8-11e4-a338-0800275b519b lease_key: struct smb2_lease_key data: ARRAY(2) data : 0x00000000cfb12998 (3484494232) data : 0x0000000000000140 (320) [2015/02/18 05:54:45.747264, 10, pid=12720, effective(1000, 1000), real(1000, 0), class=locking] ../source3/locking/leases_db.c:356(leases_db_parser) leases_db_parser: [2015/02/18 05:54:45.747959, 1, pid=12720, effective(1000, 1000), real(1000, 0)] ../librpc/ndr/ndr.c:402(ndr_print_debug) value: struct leases_db_value num_files : 0x00000001 (1) files: ARRAY(1) files: struct leases_db_file id: struct file_id devid : 0x000000000000fd01 (64769) inode : 0x0000000000080a81 (526977) extid : 0x0000000000000000 (0) servicepath : * servicepath : '/Volumes/normal' base_name : * base_name : 'README' stream_name : NULL [2015/02/18 05:54:45.748260, 5, pid=12720, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap.c:178(dbwrap_check_lock_order) check lock order 1 for /opt/samba/var/lock/smbXsrv_open_global.tdb [2015/02/18 05:54:45.748691, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap.c:133(debug_lock_order) lock order: 1:/opt/samba/var/lock/smbXsrv_open_global.tdb 2: 3: [2015/02/18 05:54:45.748727, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap_tdb.c:60(db_tdb_log_key) Locking key DB5552B7 [2015/02/18 05:54:45.748761, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap_tdb.c:144(db_tdb_fetch_locked_internal) Allocated locked data 0x0x7fb80e118f10 [2015/02/18 05:54:45.748871, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/smbXsrv_open.c:588(smbXsrv_open_global_verify_record) smbXsrv_open_global_verify_record: empty value [2015/02/18 05:54:45.748959, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/smbXsrv_open.c:706(smbXsrv_open_global_store) smbXsrv_open_global_store: key 'DB5552B7' stored [2015/02/18 05:54:45.749124, 1, pid=12720, effective(1000, 1000), real(1000, 0)] ../librpc/ndr/ndr.c:402(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 : 0x00000000000031b0 (12720) task_id : 0x00000000 (0) vnn : 0xffffffff (4294967295) unique_id : 0xfb17366705686992 (-353754229625034350) open_global_id : 0xdb5552b7 (3679802039) open_persistent_id : 0x00000000db5552b7 (3679802039) open_volatile_id : 0x00000000c98499bc (3380910524) open_owner : S-1-5-21-1849679311-379505231-1387054432-1000 open_time : Wed Feb 18 05:54:46 AM 2015 CET create_guid : 00000000-0000-0000-0000-000000000000 client_guid : 807779ee-b1c8-11e4-a338-0800275b519b 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 [2015/02/18 05:54:45.750106, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap_tdb.c:60(db_tdb_log_key) Unlocking key DB5552B7 [2015/02/18 05:54:45.750286, 5, pid=12720, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap.c:146(dbwrap_lock_order_state_destructor) release lock order 1 for /opt/samba/var/lock/smbXsrv_open_global.tdb [2015/02/18 05:54:45.750340, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap.c:133(debug_lock_order) lock order: 1: 2: 3: [2015/02/18 05:54:45.750391, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/smbXsrv_open.c:880(smbXsrv_open_create) smbXsrv_open_create: global_id (0xdb5552b7) stored [2015/02/18 05:54:45.750414, 1, pid=12720, effective(1000, 1000), real(1000, 0)] ../librpc/ndr/ndr.c:402(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 : 0xc98499bc (3380910524) global : * global: struct smbXsrv_open_global0 db_rec : NULL server_id: struct server_id pid : 0x00000000000031b0 (12720) task_id : 0x00000000 (0) vnn : 0xffffffff (4294967295) unique_id : 0xfb17366705686992 (-353754229625034350) open_global_id : 0xdb5552b7 (3679802039) open_persistent_id : 0x00000000db5552b7 (3679802039) open_volatile_id : 0x00000000c98499bc (3380910524) open_owner : S-1-5-21-1849679311-379505231-1387054432-1000 open_time : Wed Feb 18 05:54:46 AM 2015 CET create_guid : 00000000-0000-0000-0000-000000000000 client_guid : 807779ee-b1c8-11e4-a338-0800275b519b 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 status : NT_STATUS_OK idle_time : Wed Feb 18 05:54:46 AM 2015 CET compat : NULL [2015/02/18 05:54:45.751067, 5, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/files.c:129(file_new) allocated file structure fnum 3380910524 (7 used) [2015/02/18 05:54:45.751154, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/files.c:743(file_name_hash) file_name_hash: /Volumes/normal/README hash 0x7d551025 [2015/02/18 05:54:45.751207, 3, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/dosmode.c:196(unix_mode) unix_mode(README) returning 0744 [2015/02/18 05:54:45.751253, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:2478(open_file_ntcreate) open_file_ntcreate: fname=README, dos_attrs=0x0 access_mask=0x40080 share_access=0x3 create_disposition = 0x1 create_options=0x0 unix mode=0744 oplock_request=256 private_flags = 0x0 [2015/02/18 05:54:45.751308, 8, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/dosmode.c:600(dos_mode) dos_mode: README [2015/02/18 05:54:45.751372, 8, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/dosmode.c:242(dos_mode_from_sbuf) dos_mode_from_sbuf returning [2015/02/18 05:54:45.751418, 8, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/dosmode.c:36(dos_mode_debug_print) dos_mode returning [2015/02/18 05:54:45.751642, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:2636(open_file_ntcreate) open_file_ntcreate: fname=README, after mapping access_mask=0x40080 [2015/02/18 05:54:45.751707, 4, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:2726(open_file_ntcreate) calling open_file with flags=0x0 flags2=0x0 mode=0744, access_mask = 0x40080, open_access_mask = 0x40080 [2015/02/18 05:54:45.751789, 10, pid=12720, effective(1000, 1000), real(1000, 0), class=acls] ../source3/smbd/posix_acls.c:3521(posix_get_nt_acl) posix_get_nt_acl: called for file README [2015/02/18 05:54:45.751903, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/passdb/lookup_sid.c:1198(uid_to_sid) uid 1000 -> sid S-1-5-21-1849679311-379505231-1387054432-1000 [2015/02/18 05:54:45.751957, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/passdb/lookup_sid.c:1247(gid_to_sid) gid 0 -> sid S-1-22-2-0 [2015/02/18 05:54:45.752012, 10, pid=12720, effective(1000, 1000), real(1000, 0), class=acls] ../source3/smbd/posix_acls.c:2724(canonicalise_acl) canonicalise_acl: Access ace entries before arrange : [2015/02/18 05:54:45.752058, 10, pid=12720, effective(1000, 1000), real(1000, 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 r-- [2015/02/18 05:54:45.752107, 10, pid=12720, effective(1000, 1000), real(1000, 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 r-- [2015/02/18 05:54:45.752245, 10, pid=12720, effective(1000, 1000), real(1000, 0), class=acls] ../source3/smbd/posix_acls.c:2737(canonicalise_acl) canon_ace index 2. Type = allow SID = S-1-5-21-1849679311-379505231-1387054432-1000 uid 1000 (ralph) SMB_ACL_USER_OBJ ace_flags = 0x0 perms rw- [2015/02/18 05:54:45.752357, 10, pid=12720, effective(1000, 1000), real(1000, 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-5-21-1849679311-379505231-1387054432-1000 uid 1000 (ralph) SMB_ACL_USER_OBJ ace_flags = 0x0 perms rw- canon_ace index 1. Type = allow SID = S-1-22-2-0 gid 0 (root) SMB_ACL_GROUP_OBJ ace_flags = 0x0 perms r-- canon_ace index 2. Type = allow SID = S-1-1-0 other SMB_ACL_OTHER ace_flags = 0x0 perms r-- [2015/02/18 05:54:45.752711, 10, pid=12720, effective(1000, 1000), real(1000, 0), class=acls] ../source3/smbd/posix_acls.c:1110(map_canon_ace_perms) map_canon_ace_perms: Mapped (UNIX) 180 to (NT) 12019f [2015/02/18 05:54:45.752772, 10, pid=12720, effective(1000, 1000), real(1000, 0), class=acls] ../source3/smbd/posix_acls.c:1110(map_canon_ace_perms) map_canon_ace_perms: Mapped (UNIX) 100 to (NT) 120089 [2015/02/18 05:54:45.752865, 10, pid=12720, effective(1000, 1000), real(1000, 0), class=acls] ../source3/smbd/posix_acls.c:1110(map_canon_ace_perms) map_canon_ace_perms: Mapped (UNIX) 100 to (NT) 120089 [2015/02/18 05:54:45.752968, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:174(smbd_check_access_rights) smbd_check_access_rights: file README requesting 0x40080 returning 0x40000 (NT_STATUS_OK) [2015/02/18 05:54:45.753017, 2, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:1005(open_file) ralph opened file README read=No write=No (numopen=7) [2015/02/18 05:54:45.753066, 5, pid=12720, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap.c:178(dbwrap_check_lock_order) check lock order 1 for /opt/samba/var/lock/locking.tdb [2015/02/18 05:54:45.753110, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap.c:133(debug_lock_order) lock order: 1:/opt/samba/var/lock/locking.tdb 2: 3: [2015/02/18 05:54:45.753162, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap_tdb.c:60(db_tdb_log_key) Locking key 01FD000000000000810A [2015/02/18 05:54:45.753234, 10, pid=12720, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap_tdb.c:144(db_tdb_fetch_locked_internal) Allocated locked data 0x0x7fb80e123b40 [2015/02/18 05:54:45.753311, 10, pid=12720, effective(1000, 1000), real(1000, 0), class=locking] ../source3/locking/share_mode_lock.c:174(parse_share_modes) parse_share_modes: [2015/02/18 05:54:45.753357, 1, pid=12720, effective(1000, 1000), real(1000, 0)] ../librpc/ndr/ndr.c:402(ndr_print_debug) d: struct share_mode_data servicepath : * servicepath : '/Volumes/normal' base_name : * base_name : 'README' stream_name : NULL num_share_modes : 0x00000004 (4) share_modes: ARRAY(4) share_modes: struct share_mode_entry pid: struct server_id pid : 0x00000000000031b0 (12720) task_id : 0x00000000 (0) vnn : 0xffffffff (4294967295) unique_id : 0xfb17366705686992 (-353754229625034350) op_mid : 0x000000000000003c (60) op_type : 0x0100 (256) lease_idx : 0x00000000 (0) access_mask : 0x00120089 (1179785) share_access : 0x00000001 (1) private_options : 0x00000000 (0) time : Wed Feb 18 05:54:45 AM 2015 CET.581827 id: struct file_id devid : 0x000000000000fd01 (64769) inode : 0x0000000000080a81 (526977) extid : 0x0000000000000000 (0) share_file_id : 0x000000003357c520 (861390112) uid : 0x000003e8 (1000) flags : 0x0000 (0) name_hash : 0x7d551025 (2102726693) stale : 0x00 (0) lease : * lease: struct share_mode_lease client_guid : 807779ee-b1c8-11e4-a338-0800275b519b lease_key: struct smb2_lease_key data: ARRAY(2) data : 0x00000000cfb12998 (3484494232) data : 0x0000000000000140 (320) current_state : 0x00000007 (7) 1: SMB2_LEASE_READ 1: SMB2_LEASE_HANDLE 1: SMB2_LEASE_WRITE breaking : 0x00 (0) breaking_to_requested : 0x00000000 (0) 0: SMB2_LEASE_READ 0: SMB2_LEASE_HANDLE 0: SMB2_LEASE_WRITE breaking_to_required : 0x00000000 (0) 0: SMB2_LEASE_READ 0: SMB2_LEASE_HANDLE 0: SMB2_LEASE_WRITE lease_version : 0x0002 (2) epoch : 0x0001 (1) share_modes: struct share_mode_entry pid: struct server_id pid : 0x00000000000031b0 (12720) task_id : 0x00000000 (0) vnn : 0xffffffff (4294967295) unique_id : 0xfb17366705686992 (-353754229625034350) op_mid : 0x000000000000003e (62) op_type : 0x0100 (256) lease_idx : 0x00000000 (0) access_mask : 0x00120089 (1179785) share_access : 0x00000003 (3) private_options : 0x00000000 (0) time : Wed Feb 18 05:54:45 AM 2015 CET.617039 id: struct file_id devid : 0x000000000000fd01 (64769) inode : 0x0000000000080a81 (526977) extid : 0x0000000000000000 (0) share_file_id : 0x00000000db0ae006 (3674923014) uid : 0x000003e8 (1000) flags : 0x0000 (0) name_hash : 0x7d551025 (2102726693) stale : 0x00 (0) lease : * lease: struct share_mode_lease client_guid : 807779ee-b1c8-11e4-a338-0800275b519b lease_key: struct smb2_lease_key data: ARRAY(2) data : 0x00000000cfb12998 (3484494232) data : 0x0000000000000140 (320) current_state : 0x00000007 (7) 1: SMB2_LEASE_READ 1: SMB2_LEASE_HANDLE 1: SMB2_LEASE_WRITE breaking : 0x00 (0) breaking_to_requested : 0x00000000 (0) 0: SMB2_LEASE_READ 0: SMB2_LEASE_HANDLE 0: SMB2_LEASE_WRITE breaking_to_required : 0x00000000 (0) 0: SMB2_LEASE_READ 0: SMB2_LEASE_HANDLE 0: SMB2_LEASE_WRITE lease_version : 0x0002 (2) epoch : 0x0001 (1) share_modes: struct share_mode_entry pid: struct server_id pid : 0x00000000000031b0 (12720) task_id : 0x00000000 (0) vnn : 0xffffffff (4294967295) unique_id : 0xfb17366705686992 (-353754229625034350) op_mid : 0x000000000000003f (63) op_type : 0x0100 (256) lease_idx : 0x00000000 (0) access_mask : 0x00120089 (1179785) share_access : 0x00000005 (5) private_options : 0x00000000 (0) time : Wed Feb 18 05:54:45 AM 2015 CET.652645 id: struct file_id devid : 0x000000000000fd01 (64769) inode : 0x0000000000080a81 (526977) extid : 0x0000000000000000 (0) share_file_id : 0x000000003987c697 (965199511) uid : 0x000003e8 (1000) flags : 0x0000 (0) name_hash : 0x7d551025 (2102726693) stale : 0x00 (0) lease : * lease: struct share_mode_lease client_guid : 807779ee-b1c8-11e4-a338-0800275b519b lease_key: struct smb2_lease_key data: ARRAY(2) data : 0x00000000cfb12998 (3484494232) data : 0x0000000000000140 (320) current_state : 0x00000007 (7) 1: SMB2_LEASE_READ 1: SMB2_LEASE_HANDLE 1: SMB2_LEASE_WRITE breaking : 0x00 (0) breaking_to_requested : 0x00000000 (0) 0: SMB2_LEASE_READ 0: SMB2_LEASE_HANDLE 0: SMB2_LEASE_WRITE breaking_to_required : 0x00000000 (0) 0: SMB2_LEASE_READ 0: SMB2_LEASE_HANDLE 0: SMB2_LEASE_WRITE lease_version : 0x0002 (2) epoch : 0x0001 (1) share_modes: struct share_mode_entry pid: struct server_id pid : 0x00000000000031b0 (12720) task_id : 0x00000000 (0) vnn : 0xffffffff (4294967295) unique_id : 0xfb17366705686992 (-353754229625034350) op_mid : 0x0000000000000041 (65) op_type : 0x0100 (256) lease_idx : 0x00000000 (0) access_mask : 0x00020080 (131200) share_access : 0x00000003 (3) private_options : 0x00000000 (0) time : Wed Feb 18 05:54:45 AM 2015 CET.711964 id: struct file_id devid : 0x000000000000fd01 (64769) inode : 0x0000000000080a81 (526977) extid : 0x0000000000000000 (0) share_file_id : 0x00000000d69f1b7b (3600751483) uid : 0x000003e8 (1000) flags : 0x0000 (0) name_hash : 0x7d551025 (2102726693) stale : 0x00 (0) lease : * lease: struct share_mode_lease client_guid : 807779ee-b1c8-11e4-a338-0800275b519b lease_key: struct smb2_lease_key data: ARRAY(2) data : 0x00000000cfb12998 (3484494232) data : 0x0000000000000140 (320) current_state : 0x00000007 (7) 1: SMB2_LEASE_READ 1: SMB2_LEASE_HANDLE 1: SMB2_LEASE_WRITE breaking : 0x00 (0) breaking_to_requested : 0x00000000 (0) 0: SMB2_LEASE_READ 0: SMB2_LEASE_HANDLE 0: SMB2_LEASE_WRITE breaking_to_required : 0x00000000 (0) 0: SMB2_LEASE_READ 0: SMB2_LEASE_HANDLE 0: SMB2_LEASE_WRITE lease_version : 0x0002 (2) epoch : 0x0001 (1) num_leases : 0x00000001 (1) leases: ARRAY(1) leases: struct share_mode_lease client_guid : 807779ee-b1c8-11e4-a338-0800275b519b lease_key: struct smb2_lease_key data: ARRAY(2) data : 0x00000000cfb12998 (3484494232) data : 0x0000000000000140 (320) current_state : 0x00000007 (7) 1: SMB2_LEASE_READ 1: SMB2_LEASE_HANDLE 1: SMB2_LEASE_WRITE breaking : 0x00 (0) breaking_to_requested : 0x00000000 (0) 0: SMB2_LEASE_READ 0: SMB2_LEASE_HANDLE 0: SMB2_LEASE_WRITE breaking_to_required : 0x00000000 (0) 0: SMB2_LEASE_READ 0: SMB2_LEASE_HANDLE 0: SMB2_LEASE_WRITE lease_version : 0x0002 (2) epoch : 0x0001 (1) num_delete_tokens : 0x00000000 (0) delete_tokens: ARRAY(0) old_write_time : Thu Aug 7 11:02:08 AM 2014 CEST.0 changed_write_time : Thu Jan 1 01:00:00 AM 1970 CET.0 fresh : 0x00 (0) modified : 0x00 (0) record : NULL [2015/02/18 05:54:45.756320, 10, pid=12720, effective(1000, 1000), real(1000, 0), class=locking] ../source3/locking/locking.c:1192(find_delete_on_close_token) find_delete_on_close_token: name_hash = 0x7d551025 [2015/02/18 05:54:45.756355, 0, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/smbd/files.c:332(file_find_dif) file_find_dif: file README file_id = fd01:80a81:0, gen = 3600751483 oplock_type = 256 is a stat open with oplock type ! [2015/02/18 05:54:45.759027, 0, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/lib/util.c:790(smb_panic_s3) PANIC (pid 12720): file_find_dif [2015/02/18 05:54:45.771230, 0, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/lib/util.c:901(log_stack_trace) BACKTRACE: 32 stack frames: #0 /home/ralph/samba/test/bin/shared/libsmbconf.so.0(log_stack_trace+0x1f) [0x7fb80bc691d5] #1 /home/ralph/samba/test/bin/shared/libsmbconf.so.0(smb_panic_s3+0x6f) [0x7fb80bc69020] #2 /home/ralph/samba/test/bin/shared/libsamba-util.so.0(smb_panic+0x28) [0x7fb80c898fc7] #3 /home/ralph/samba/test/bin/shared/private/libsmbd-base-samba4.so(file_find_dif+0x2a4) [0x7fb80c187759] #4 /home/ralph/samba/test/bin/shared/private/libsmbd-base-samba4.so(+0x151580) [0x7fb80c206580] #5 /home/ralph/samba/test/bin/shared/private/libsmbd-base-samba4.so(+0x151840) [0x7fb80c206840] #6 /home/ralph/samba/test/bin/shared/private/libsmbd-base-samba4.so(+0x155935) [0x7fb80c20a935] #7 /home/ralph/samba/test/bin/shared/private/libsmbd-base-samba4.so(+0x1599f4) [0x7fb80c20e9f4] #8 /home/ralph/samba/test/bin/shared/private/libsmbd-base-samba4.so(create_file_default+0x2ec) [0x7fb80c20f5d0] #9 /home/ralph/samba/test/bin/shared/private/libsmbd-base-samba4.so(+0x27fde5) [0x7fb80c334de5] #10 /home/ralph/samba/test/bin/shared/private/libsmbd-base-samba4.so(smb_vfs_call_create_file+0xe6) [0x7fb80c21b35f] #11 /home/ralph/samba/test/bin/shared/private/libsmbd-base-samba4.so(+0x1a9d02) [0x7fb80c25ed02] #12 /home/ralph/samba/test/bin/shared/private/libsmbd-base-samba4.so(smbd_smb2_request_process_create+0x795) [0x7fb80c25bd14] #13 /home/ralph/samba/test/bin/shared/private/libsmbd-base-samba4.so(smbd_smb2_request_dispatch+0x167d) [0x7fb80c2515a4] #14 /home/ralph/samba/test/bin/shared/private/libsmbd-base-samba4.so(+0x1a10b1) [0x7fb80c2560b1] #15 /home/ralph/samba/test/bin/shared/private/libsmbd-base-samba4.so(+0x1a11b8) [0x7fb80c2561b8] #16 /home/ralph/samba/test/bin/shared/libsmbconf.so.0(run_events_poll+0x54f) [0x7fb80bc84182] #17 /home/ralph/samba/test/bin/shared/libsmbconf.so.0(+0x3c40e) [0x7fb80bc8440e] #18 /home/ralph/samba/test/bin/shared/private/libtevent.so.0(_tevent_loop_once+0xf4) [0x7fb80c855626] #19 /home/ralph/samba/test/bin/shared/private/libtevent.so.0(tevent_common_loop_wait+0x25) [0x7fb80c855870] #20 /home/ralph/samba/test/bin/shared/private/libtevent.so.0(_tevent_loop_wait+0x2b) [0x7fb80c85593b] #21 /home/ralph/samba/test/bin/shared/private/libsmbd-base-samba4.so(smbd_process+0xb24) [0x7fb80c23853d] #22 ./bin/smbd(+0xaa82) [0x7fb80c8d0a82] #23 /home/ralph/samba/test/bin/shared/libsmbconf.so.0(run_events_poll+0x54f) [0x7fb80bc84182] #24 /home/ralph/samba/test/bin/shared/libsmbconf.so.0(+0x3c40e) [0x7fb80bc8440e] #25 /home/ralph/samba/test/bin/shared/private/libtevent.so.0(_tevent_loop_once+0xf4) [0x7fb80c855626] #26 /home/ralph/samba/test/bin/shared/private/libtevent.so.0(tevent_common_loop_wait+0x25) [0x7fb80c855870] #27 /home/ralph/samba/test/bin/shared/private/libtevent.so.0(_tevent_loop_wait+0x2b) [0x7fb80c85593b] #28 ./bin/smbd(+0xb8cb) [0x7fb80c8d18cb] #29 ./bin/smbd(main+0x1776) [0x7fb80c8d31f8] #30 /lib64/libc.so.6(__libc_start_main+0xf5) [0x7fb80af34d65] #31 ./bin/smbd(+0x5f29) [0x7fb80c8cbf29] [2015/02/18 05:54:45.794288, 0, pid=12720, effective(1000, 1000), real(1000, 0)] ../source3/lib/util.c:802(smb_panic_s3) smb_panic(): calling panic action [/bin/sleep 999999999] ^C [ralph@fedora20 test]$