Using FreeBSD + ZFS, on SOME shares, a simple rename of any file in the root of the share will cause the SMBD process to crash. Renames of files in subdirectories do not cause this problem. Reproducable with smbclient $ smbclient \\\\ecfile1\\erick --user=erick Enter erick's password: Domain=[NEXUS] OS=[Windows 6.1] Server=[Samba 4.3.3] smb: \> dir ? . D 0 Sat Jan 2 18:20:31 2016 .. D 0 Tue Dec 22 15:00:08 2015 7 A 119745 Fri Dec 4 09:25:56 2015 9 15003 Fri Dec 4 09:18:31 2015 e D 0 Tue Aug 26 11:36:52 2014 65535 blocks of size 33553920. 65535 blocks available smb: \> ren 7 8 smb: \> dir 8 NT_STATUS_ACCESS_DENIED listing \8 smb: \> dir NT_STATUS_ACCESS_DENIED listing \* smb: \> The smb session is then unusable until the server process dies and is replaced with a new process. This bug does not happen with all ZFS mounts, but we cannot figure out what makes some mounts work fine, and others fail. Calling mv from a login csh does not produce the problem. It has been present on Samab going back to 3.6 and possibly earlier. I can't find anything in the logs, with logging turned up to max. [global] workgroup = NEXUS realm = NEXUS.UWATERLOO.CA server string = Engineering File Server security = ADS restrict anonymous = 2 log file = /var/log/smb.log client signing = if_required deadtime = 15 socket options = TCP_NODELAY IPTOS_LOWDELAY SO_KEEPALIVE load printers = No preferred master = No local master = No domain master = No dns proxy = No host msdfs = No winbind separator = / winbind use default domain = Yes winbind trusted domains only = Yes idmap config * : backend = tdb aio read size = 1 aio write size = 1 csc policy = disable include = /usr/local/etc/samba/debug. dont descend = /bin, /cdrom, /dev, /etc, /mnt, /proc, /usr, /var [homes] comment = Home Directories path = %p read only = No map readonly = no store dos attributes = Yes browseable = No dfree cache time = 2400 include = /usr/local/etc/samba/local.shares vfs objects = zfsacl nfs4:chown = yes nfs4:acedup = merge nfs4:mode = special erick account: /u4/erick fails as shown above erick2 account: /home/erick2 works perfectly file permissions and directory permissions are identical on both. /home/erick2 mounted on: ecserv30/ROOT/default on / (zfs, local, noatime, nfsv4acls) but fails on all accounts mounted on following: u1 on /u1 (zfs, NFS exported, local, noatime, nfsv4acls) u2 on /u2 (zfs, NFS exported, local, noatime, nfsv4acls) u3_u4/u3 on /u3 (zfs, NFS exported, local, noatime, nfsv4acls) u3_u4/u4 on /u4 (zfs, NFS exported, local, noatime, nfsv4acls)
sorry, meant x64, not IA64.
Also fails for subdirectory names $ smbclient \\\\ecfile1\\erick --user=erick Enter erick's password: Domain=[NEXUS] OS=[Windows 6.1] Server=[Samba 4.3.3] smb: \> mkdir temptemp smb: \> ren temptemp temp2 smb: \> dir temp2 NT_STATUS_ACCESS_DENIED listing \temp2 smb: \> dir NT_STATUS_ACCESS_DENIED listing \* smb: \> but only in the root directory of the share. Note, in all cases, the rename works on the fileserver, something is goofing up on the code after the rename. Erick
could strrchr_m in the rename function return Null if there is no leading \, if so, the calculations on the pointers would be nonsense. This would match the behaviour of sometimes failing in the root of the share.
[2016/01/03 11:52:12.443754, 5, pid=73700, effective(0, 0), real(0, 0)] ../libcli/security/security_token.c:63(security_token_debug) Security token SIDs (12): SID[ 0]: S-1-5-21-3402271078-1959448159-1473268157-1000 SID[ 1]: S-1-5-21-3402271078-1959448159-1473268157-513 SID[ 2]: S-1-22-2-0 SID[ 3]: S-1-22-2-79 SID[ 4]: S-1-22-2-10009 SID[ 5]: S-1-22-2-15925 SID[ 6]: S-1-22-2-15926 SID[ 7]: S-1-22-2-28778 SID[ 8]: S-1-1-0 SID[ 9]: S-1-5-2 SID[ 10]: S-1-5-11 SID[ 11]: S-1-22-1-17420 Privileges (0x 0): Rights (0x 0): [2016/01/03 11:52:12.444021, 5, pid=73700, effective(0, 0), real(0, 0)] ../source3/auth/token_util.c:639(debug_unix_user_token) UNIX token of user 17420 Primary group is 0 and contains 6 supplementary groups Group[ 0]: 0 Group[ 1]: 79 Group[ 2]: 10009 Group[ 3]: 15925 Group[ 4]: 15926 Group[ 5]: 28778 [2016/01/03 11:52:12.444196, 5, pid=73700, effective(17420, 0), real(0, 0)] ../source3/smbd/uid.c:363(change_to_user_internal) Impersonated user: uid=(0,17420), gid=(0,0) [2016/01/03 11:52:12.444242, 4, pid=73700, effective(17420, 0), real(0, 0), class=vfs] ../source3/smbd/vfs.c:844(vfs_ChDir) vfs_ChDir to /u4/erick [2016/01/03 11:52:12.444443, 4, pid=73700, effective(17420, 0), real(0, 0), class=vfs] ../source3/smbd/vfs.c:855(vfs_ChDir) vfs_ChDir got /u4/erick [2016/01/03 11:52:12.444531, 5, pid=73700, effective(17420, 0), real(0, 0)] ../source3/smbd/filename.c:257(unix_convert) unix_convert called on file "4" [2016/01/03 11:52:12.444576, 10, pid=73700, effective(17420, 0), real(0, 0)] ../source3/smbd/statcache.c:244(stat_cache_lookup) stat_cache_lookup: lookup failed for name [4] [2016/01/03 11:52:12.444613, 5, pid=73700, effective(17420, 0), real(0, 0)] ../source3/smbd/filename.c:449(unix_convert) unix_convert begin: name = 4, dirpath = , start = 4 [2016/01/03 11:52:12.444665, 5, pid=73700, effective(17420, 0), real(0, 0)] ../source3/smbd/statcache.c:143(stat_cache_add) stat_cache_add: Added entry (81311f500:size 1) 4 -> 4 [2016/01/03 11:52:12.444704, 5, pid=73700, effective(17420, 0), real(0, 0)] ../source3/smbd/filename.c:472(unix_convert) conversion of base_name finished 4 -> 4 [2016/01/03 11:52:12.444741, 10, pid=73700, effective(17420, 0), real(0, 0), class=vfs] ../source3/smbd/vfs.c:1147(check_reduced_name) check_reduced_name [4] [/u4/erick] [2016/01/03 11:52:12.444800, 10, pid=73700, effective(17420, 0), real(0, 0), class=vfs] ../source3/smbd/vfs.c:1207(check_reduced_name) check_reduced_name realpath [4] -> [/u4/erick/4] [2016/01/03 11:52:12.444840, 5, pid=73700, effective(17420, 0), real(0, 0), class=vfs] ../source3/smbd/vfs.c:1279(check_reduced_name) 4 reduced to /u4/erick/4 [2016/01/03 11:52:12.444875, 5, pid=73700, effective(17420, 0), real(0, 0)] ../source3/smbd/filename.c:257(unix_convert) unix_convert called on file "3" [2016/01/03 11:52:12.444913, 10, pid=73700, effective(17420, 0), real(0, 0)] ../source3/smbd/statcache.c:244(stat_cache_lookup) stat_cache_lookup: lookup failed for name [3] [2016/01/03 11:52:12.444949, 5, pid=73700, effective(17420, 0), real(0, 0)] ../source3/smbd/filename.c:449(unix_convert) unix_convert begin: name = 3, dirpath = , start = 3 [2016/01/03 11:52:12.445018, 10, pid=73700, effective(17420, 0), real(0, 0)] ../source3/smbd/mangle_hash2.c:418(is_mangled) is_mangled 3 ? [2016/01/03 11:52:12.445059, 10, pid=73700, effective(17420, 0), real(0, 0)] ../source3/smbd/mangle_hash2.c:357(is_mangled_component) is_mangled_component 3 (len 1) ? [2016/01/03 11:52:12.445099, 10, pid=73700, effective(17420, 0), real(0, 0)] ../source3/smbd/mangle_hash2.c:418(is_mangled) is_mangled 3 ? [2016/01/03 11:52:12.445132, 10, pid=73700, effective(17420, 0), real(0, 0)] ../source3/smbd/mangle_hash2.c:357(is_mangled_component) is_mangled_component 3 (len 1) ? [2016/01/03 11:52:12.446306, 10, pid=73700, effective(17420, 0), real(0, 0)] ../source3/smbd/mangle_hash2.c:418(is_mangled) is_mangled 3 ? [2016/01/03 11:52:12.446350, 10, pid=73700, effective(17420, 0), real(0, 0)] ../source3/smbd/mangle_hash2.c:357(is_mangled_component) is_mangled_component 3 (len 1) ? [2016/01/03 11:52:12.446384, 5, pid=73700, effective(17420, 0), real(0, 0)] ../source3/smbd/filename.c:844(unix_convert) New file 3 [2016/01/03 11:52:12.446418, 10, pid=73700, effective(17420, 0), real(0, 0), class=vfs] ../source3/smbd/vfs.c:1147(check_reduced_name) check_reduced_name [3] [/u4/erick] [2016/01/03 11:52:12.446471, 10, pid=73700, effective(17420, 0), real(0, 0), class=vfs] ../source3/smbd/vfs.c:1207(check_reduced_name) check_reduced_name realpath [3] -> [/u4/erick/3] [2016/01/03 11:52:12.446508, 5, pid=73700, effective(17420, 0), real(0, 0), class=vfs] ../source3/smbd/vfs.c:1279(check_reduced_name) 3 reduced to /u4/erick/3 [2016/01/03 11:52:12.446542, 3, pid=73700, effective(17420, 0), real(0, 0)] ../source3/smbd/reply.c:7147(reply_mv) reply_mv : 4 -> 3 [2016/01/03 11:52:12.446581, 3, pid=73700, effective(17420, 0), real(0, 0)] ../source3/smbd/reply.c:6788(rename_internals) rename_internals: case_sensitive = 0, case_preserve = 1, short case preserve = 1, directory = 4, newname = 3, last_component_dest = 3 [2016/01/03 11:52:12.446637, 10, pid=73700, effective(17420, 0), real(0, 0)] ../source3/smbd/open.c:4975(create_file_default) create_file: access_mask = 0x10000 file_attributes = 0x0, share_access = 0x3, create_disposition = 0x1 create_options = 0x0 oplock_request = 0x0 private_flags = 0x0 root_dir_fid = 0x0, ea_list = 0x0x0, sd = 0x0x0, fname = 4 [2016/01/03 11:52:12.446681, 10, pid=73700, effective(17420, 0), real(0, 0)] ../source3/smbd/open.c:4448(create_file_unixpath) create_file_unixpath: access_mask = 0x10000 file_attributes = 0x0, share_access = 0x3, create_disposition = 0x1 create_options = 0x0 oplock_request = 0x0 private_flags = 0x0 ea_list = 0x0x0, sd = 0x0x0, fname = 4 [2016/01/03 11:52:12.446734, 5, pid=73700, effective(17420, 0), real(0, 0)] ../lib/dbwrap/dbwrap.c:178(dbwrap_check_lock_order) check lock order 1 for /usr/local/samba/var/lock/smbXsrv_open_global.tdb [2016/01/03 11:52:12.446771, 10, pid=73700, effective(17420, 0), real(0, 0)] ../lib/dbwrap/dbwrap.c:133(debug_lock_order) lock order: 1:/usr/local/samba/var/lock/smbXsrv_open_global.tdb 2:<none> 3:<none> [2016/01/03 11:52:12.446809, 10, pid=73700, effective(17420, 0), real(0, 0)] ../lib/dbwrap/dbwrap_tdb.c:59(db_tdb_log_key) Locking key F7A275C6 [2016/01/03 11:52:12.446860, 10, pid=73700, effective(17420, 0), real(0, 0)] ../lib/dbwrap/dbwrap_tdb.c:143(db_tdb_fetch_locked_internal) Allocated locked data 0x0x81316b620 [2016/01/03 11:52:12.446897, 10, pid=73700, effective(17420, 0), real(0, 0)] ../source3/smbd/smbXsrv_open.c:587(smbXsrv_open_global_verify_record) smbXsrv_open_global_verify_record: empty value [2016/01/03 11:52:12.447018, 10, pid=73700, effective(17420, 0), real(0, 0)] ../source3/smbd/smbXsrv_open.c:706(smbXsrv_open_global_store) smbXsrv_open_global_store: key 'F7A275C6' stored [2016/01/03 11:52:12.447067, 1, pid=73700, effective(17420, 0), real(0, 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 : 0x0000000000011fe4 (73700) task_id : 0x00000000 (0) vnn : 0xffffffff (4294967295) unique_id : 0x1671bfce06a2a858 (1617284632798210136) open_global_id : 0xf7a275c6 (4154619334) open_persistent_id : 0x00000000f7a275c6 (4154619334) open_volatile_id : 0x000000000000298c (10636) open_owner : S-1-5-21-3402271078-1959448159-1473268157-1000 open_time : Sun Jan 3 11:52:12 2016 EST create_guid : 00000000-0000-0000-0000-000000000000 client_guid : 00000000-0000-0000-0000-000000000000 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 [2016/01/03 11:52:12.447518, 10, pid=73700, effective(17420, 0), real(0, 0)] ../lib/dbwrap/dbwrap_tdb.c:59(db_tdb_log_key) Unlocking key F7A275C6 [2016/01/03 11:52:12.447557, 5, pid=73700, effective(17420, 0), real(0, 0)] ../lib/dbwrap/dbwrap.c:146(dbwrap_lock_order_state_destructor) release lock order 1 for /usr/local/samba/var/lock/smbXsrv_open_global.tdb [2016/01/03 11:52:12.447593, 10, pid=73700, effective(17420, 0), real(0, 0)] ../lib/dbwrap/dbwrap.c:133(debug_lock_order) lock order: 1:<none> 2:<none> 3:<none> [2016/01/03 11:52:12.447630, 10, pid=73700, effective(17420, 0), real(0, 0)] ../source3/smbd/smbXsrv_open.c:880(smbXsrv_open_create) smbXsrv_open_create: global_id (0xf7a275c6) stored [2016/01/03 11:52:12.447664, 1, pid=73700, effective(17420, 0), real(0, 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 : 0x0000298c (10636) global : * global: struct smbXsrv_open_global0 db_rec : NULL server_id: struct server_id pid : 0x0000000000011fe4 (73700) task_id : 0x00000000 (0) vnn : 0xffffffff (4294967295) unique_id : 0x1671bfce06a2a858 (1617284632798210136) open_global_id : 0xf7a275c6 (4154619334) open_persistent_id : 0x00000000f7a275c6 (4154619334) open_volatile_id : 0x000000000000298c (10636) open_owner : S-1-5-21-3402271078-1959448159-1473268157-1000 open_time : Sun Jan 3 11:52:12 2016 EST create_guid : 00000000-0000-0000-0000-000000000000 client_guid : 00000000-0000-0000-0000-000000000000 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 : Sun Jan 3 11:52:12 2016 EST compat : NULL [2016/01/03 11:52:12.448243, 5, pid=73700, effective(17420, 0), real(0, 0)] ../source3/smbd/files.c:128(file_new) allocated file structure fnum 10636 (1 used) [2016/01/03 11:52:12.448284, 10, pid=73700, effective(17420, 0), real(0, 0)] ../source3/smbd/files.c:745(file_name_hash) file_name_hash: /u4/erick/4 hash 0x9d3cc599 [2016/01/03 11:52:12.448329, 2, pid=73700, effective(17420, 0), real(0, 0)] ../source3/smbd/dosmode.c:129(unix_mode) unix_mode(4) inheriting from . [2016/01/03 11:52:12.448373, 2, pid=73700, effective(17420, 0), real(0, 0)] ../source3/smbd/dosmode.c:151(unix_mode) unix_mode(4) inherit mode 40733 [2016/01/03 11:52:12.448412, 5, pid=73700, effective(17420, 0), real(0, 0)] ../source3/smbd/dosmode.c:196(unix_mode) unix_mode(4) returning 0722 [2016/01/03 11:52:12.448446, 10, pid=73700, effective(17420, 0), real(0, 0)] ../source3/smbd/open.c:2479(open_file_ntcreate) open_file_ntcreate: fname=4, dos_attrs=0x0 access_mask=0x10000 share_access=0x3 create_disposition = 0x1 create_options=0x0 unix mode=0722 oplock_request=0 private_flags = 0x0 [2016/01/03 11:52:12.448486, 8, pid=73700, effective(17420, 0), real(0, 0)] ../source3/smbd/dosmode.c:601(dos_mode) dos_mode: 4 [2016/01/03 11:52:12.448522, 8, pid=73700, effective(17420, 0), real(0, 0)] ../source3/smbd/dosmode.c:243(dos_mode_from_sbuf) dos_mode_from_sbuf returning [2016/01/03 11:52:12.448559, 8, pid=73700, effective(17420, 0), real(0, 0)] ../source3/smbd/dosmode.c:36(dos_mode_debug_print) dos_mode returning [2016/01/03 11:52:12.448597, 10, pid=73700, effective(17420, 0), real(0, 0)] ../source3/smbd/open.c:2637(open_file_ntcreate) open_file_ntcreate: fname=4, after mapping access_mask=0x10000 [2016/01/03 11:52:12.448634, 4, pid=73700, effective(17420, 0), real(0, 0)] ../source3/smbd/open.c:2727(open_file_ntcreate) calling open_file with flags=0x0 flags2=0x0 mode=0722, access_mask = 0x10000, open_access_mask = 0x10000 [2016/01/03 11:52:12.448682, 10, pid=73700, effective(17420, 0), real(0, 0), class=acls] ../source3/smbd/posix_acls.c:3521(posix_get_nt_acl) posix_get_nt_acl: called for file 4 [2016/01/03 11:52:12.448847, 10, pid=73700, effective(17420, 0), real(0, 0)] ../source3/passdb/lookup_sid.c:1251(uid_to_sid) uid 0 -> sid S-1-22-1-0 [2016/01/03 11:52:12.448899, 10, pid=73700, effective(17420, 0), real(0, 0)] ../source3/passdb/lookup_sid.c:1300(gid_to_sid) gid 0 -> sid S-1-22-2-0 [2016/01/03 11:52:12.448940, 10, pid=73700, effective(17420, 0), real(0, 0), class=acls] ../source3/smbd/posix_acls.c:2724(canonicalise_acl) canonicalise_acl: Access ace entries before arrange : [2016/01/03 11:52:12.448982, 10, pid=73700, effective(17420, 0), real(0, 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-- [2016/01/03 11:52:12.449023, 10, pid=73700, effective(17420, 0), real(0, 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 (wheel) SMB_ACL_GROUP_OBJ ace_flags = 0x0 perms r-- [2016/01/03 11:52:12.449156, 10, pid=73700, effective(17420, 0), real(0, 0), class=acls] ../source3/smbd/posix_acls.c:2737(canonicalise_acl) canon_ace index 2. Type = allow SID = S-1-22-1-0 uid 0 (root) SMB_ACL_USER_OBJ ace_flags = 0x0 perms rw- [2016/01/03 11:52:12.449317, 10, pid=73700, effective(17420, 0), real(0, 0), class=acls] ../source3/smbd/posix_acls.c:848(print_canon_ace_list) print_canon_ace_list: canonicalise_acl: ace entries after arrange canon_ace index 0. Type = allow SID = S-1-22-1-0 uid 0 (root) SMB_ACL_USER_OBJ ace_flags = 0x0 perms rw- canon_ace index 1. Type = allow SID = S-1-22-2-0 gid 0 (wheel) 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-- [2016/01/03 11:52:12.449533, 10, pid=73700, effective(17420, 0), real(0, 0), class=acls] ../source3/smbd/posix_acls.c:1110(map_canon_ace_perms) map_canon_ace_perms: Mapped (UNIX) 180 to (NT) 12019f [2016/01/03 11:52:12.449570, 10, pid=73700, effective(17420, 0), real(0, 0), class=acls] ../source3/smbd/posix_acls.c:1110(map_canon_ace_perms) map_canon_ace_perms: Mapped (UNIX) 100 to (NT) 120089 [2016/01/03 11:52:12.449604, 10, pid=73700, effective(17420, 0), real(0, 0), class=acls] ../source3/smbd/posix_acls.c:1110(map_canon_ace_perms) map_canon_ace_perms: Mapped (UNIX) 100 to (NT) 120089 [2016/01/03 11:52:12.449653, 10, pid=73700, effective(17420, 0), real(0, 0)] ../source3/smbd/open.c:174(smbd_check_access_rights) smbd_check_access_rights: file 4 requesting 0x10000 returning 0x10000 (NT_STATUS_ACCESS_DENIED) [2016/01/03 11:52:12.449693, 10, pid=73700, effective(17420, 0), real(0, 0)] ../source3/smbd/open.c:179(smbd_check_access_rights) smbd_check_access_rights: acl for 4 is: [2016/01/03 11:52:12.449726, 1, pid=73700, effective(17420, 0), real(0, 0)] ../librpc/ndr/ndr.c:402(ndr_print_debug) sd: struct security_descriptor revision : SECURITY_DESCRIPTOR_REVISION_1 (1) type : 0x9004 (36868) 0: SEC_DESC_OWNER_DEFAULTED 0: SEC_DESC_GROUP_DEFAULTED 1: SEC_DESC_DACL_PRESENT 0: SEC_DESC_DACL_DEFAULTED 0: SEC_DESC_SACL_PRESENT 0: SEC_DESC_SACL_DEFAULTED 0: SEC_DESC_DACL_TRUSTED 0: SEC_DESC_SERVER_SECURITY 0: SEC_DESC_DACL_AUTO_INHERIT_REQ 0: SEC_DESC_SACL_AUTO_INHERIT_REQ 0: SEC_DESC_DACL_AUTO_INHERITED 0: SEC_DESC_SACL_AUTO_INHERITED 1: SEC_DESC_DACL_PROTECTED 0: SEC_DESC_SACL_PROTECTED 0: SEC_DESC_RM_CONTROL_VALID 1: SEC_DESC_SELF_RELATIVE owner_sid : * owner_sid : S-1-22-1-0 group_sid : * group_sid : S-1-22-2-0 sacl : NULL dacl : * dacl: struct security_acl revision : SECURITY_ACL_REVISION_NT4 (2) size : 0x004c (76) num_aces : 0x00000003 (3) aces: ARRAY(3) aces: struct security_ace type : SEC_ACE_TYPE_ACCESS_ALLOWED (0) flags : 0x00 (0) 0: SEC_ACE_FLAG_OBJECT_INHERIT 0: SEC_ACE_FLAG_CONTAINER_INHERIT 0: SEC_ACE_FLAG_NO_PROPAGATE_INHERIT 0: SEC_ACE_FLAG_INHERIT_ONLY 0: SEC_ACE_FLAG_INHERITED_ACE 0x00: SEC_ACE_FLAG_VALID_INHERIT (0) 0: SEC_ACE_FLAG_SUCCESSFUL_ACCESS 0: SEC_ACE_FLAG_FAILED_ACCESS size : 0x0018 (24) access_mask : 0x0012019f (1180063) object : union security_ace_object_ctr(case 0) trustee : S-1-22-1-0 aces: struct security_ace type : SEC_ACE_TYPE_ACCESS_ALLOWED (0) flags : 0x00 (0) 0: SEC_ACE_FLAG_OBJECT_INHERIT 0: SEC_ACE_FLAG_CONTAINER_INHERIT 0: SEC_ACE_FLAG_NO_PROPAGATE_INHERIT 0: SEC_ACE_FLAG_INHERIT_ONLY 0: SEC_ACE_FLAG_INHERITED_ACE 0x00: SEC_ACE_FLAG_VALID_INHERIT (0) 0: SEC_ACE_FLAG_SUCCESSFUL_ACCESS 0: SEC_ACE_FLAG_FAILED_ACCESS size : 0x0018 (24) access_mask : 0x00120089 (1179785) object : union security_ace_object_ctr(case 0) trustee : S-1-22-2-0 aces: struct security_ace type : SEC_ACE_TYPE_ACCESS_ALLOWED (0) flags : 0x00 (0) 0: SEC_ACE_FLAG_OBJECT_INHERIT 0: SEC_ACE_FLAG_CONTAINER_INHERIT 0: SEC_ACE_FLAG_NO_PROPAGATE_INHERIT 0: SEC_ACE_FLAG_INHERIT_ONLY 0: SEC_ACE_FLAG_INHERITED_ACE 0x00: SEC_ACE_FLAG_VALID_INHERIT (0) 0: SEC_ACE_FLAG_SUCCESSFUL_ACCESS 0: SEC_ACE_FLAG_FAILED_ACCESS size : 0x0014 (20) access_mask : 0x00120089 (1179785) object : union security_ace_object_ctr(case 0) trustee : S-1-1-0 [2016/01/03 11:52:12.451006, 10, pid=73700, effective(17420, 0), real(0, 0), class=acls] ../source3/smbd/posix_acls.c:3521(posix_get_nt_acl) posix_get_nt_acl: called for file . [2016/01/03 11:52:12.451088, 10, pid=73700, effective(17420, 0), real(0, 0)] ../source3/passdb/lookup_sid.c:1251(uid_to_sid) uid 17420 -> sid S-1-5-21-3402271078-1959448159-1473268157-1000 [2016/01/03 11:52:12.451138, 10, pid=73700, effective(17420, 0), real(0, 0)] ../source3/passdb/lookup_sid.c:1300(gid_to_sid) gid 0 -> sid S-1-22-2-0 [2016/01/03 11:52:12.451177, 10, pid=73700, effective(17420, 0), real(0, 0), class=acls] ../source3/smbd/posix_acls.c:2724(canonicalise_acl) canonicalise_acl: Access ace entries before arrange : [2016/01/03 11:52:12.451211, 10, pid=73700, effective(17420, 0), real(0, 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 -wx [2016/01/03 11:52:12.451252, 10, pid=73700, effective(17420, 0), real(0, 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 (wheel) SMB_ACL_GROUP_OBJ ace_flags = 0x0 perms -wx [2016/01/03 11:52:12.451334, 10, pid=73700, effective(17420, 0), real(0, 0), class=acls] ../source3/smbd/posix_acls.c:2737(canonicalise_acl) canon_ace index 2. Type = allow SID = S-1-5-21-3402271078-1959448159-1473268157-1000 uid 17420 (erick) SMB_ACL_USER_OBJ ace_flags = 0x0 perms rwx [2016/01/03 11:52:12.451452, 10, pid=73700, effective(17420, 0), real(0, 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-3402271078-1959448159-1473268157-1000 uid 17420 (erick) SMB_ACL_USER_OBJ ace_flags = 0x0 perms rwx canon_ace index 1. Type = allow SID = S-1-22-2-0 gid 0 (wheel) SMB_ACL_GROUP_OBJ ace_flags = 0x0 perms -wx canon_ace index 2. Type = allow SID = S-1-1-0 other SMB_ACL_OTHER ace_flags = 0x0 perms -wx [2016/01/03 11:52:12.451664, 10, pid=73700, effective(17420, 0), real(0, 0), class=acls] ../source3/smbd/posix_acls.c:1110(map_canon_ace_perms) map_canon_ace_perms: Mapped (UNIX) 1c0 to (NT) 1f01ff [2016/01/03 11:52:12.451700, 10, pid=73700, effective(17420, 0), real(0, 0), class=acls] ../source3/smbd/posix_acls.c:1110(map_canon_ace_perms) map_canon_ace_perms: Mapped (UNIX) c0 to (NT) 1201f6 [2016/01/03 11:52:12.451735, 10, pid=73700, effective(17420, 0), real(0, 0), class=acls] ../source3/smbd/posix_acls.c:1110(map_canon_ace_perms) map_canon_ace_perms: Mapped (UNIX) c0 to (NT) 1201f6 [2016/01/03 11:52:12.451776, 10, pid=73700, effective(17420, 0), real(0, 0)] ../source3/smbd/open.c:174(smbd_check_access_rights) smbd_check_access_rights: file . requesting 0x40 returning 0x40 (NT_STATUS_OK) [2016/01/03 11:52:12.451815, 10, pid=73700, effective(17420, 0), real(0, 0)] ../source3/smbd/open.c:229(smbd_check_access_rights) smbd_check_access_rights: overrode DELETE_ACCESS on file 4 [2016/01/03 11:52:12.451851, 2, pid=73700, effective(17420, 0), real(0, 0)] ../source3/smbd/open.c:1005(open_file) erick opened file 4 read=No write=No (numopen=1) [2016/01/03 11:52:12.451890, 5, pid=73700, effective(17420, 0), real(0, 0)] ../lib/dbwrap/dbwrap.c:178(dbwrap_check_lock_order) check lock order 1 for /usr/local/samba/var/lock/locking.tdb [2016/01/03 11:52:12.451924, 10, pid=73700, effective(17420, 0), real(0, 0)] ../lib/dbwrap/dbwrap.c:133(debug_lock_order) lock order: 1:/usr/local/samba/var/lock/locking.tdb 2:<none> 3:<none> [2016/01/03 11:52:12.451963, 10, pid=73700, effective(17420, 0), real(0, 0)] ../lib/dbwrap/dbwrap_tdb.c:59(db_tdb_log_key) Locking key BE1A84D7000000000593 [2016/01/03 11:52:12.452026, 10, pid=73700, effective(17420, 0), real(0, 0)] ../lib/dbwrap/dbwrap_tdb.c:143(db_tdb_fetch_locked_internal) Allocated locked data 0x0x81316b620 [2016/01/03 11:52:12.452103, 10, pid=73700, effective(17420, 0), real(0, 0), class=locking] ../source3/locking/brlock.c:2048(brl_get_locks_readonly) seqnum=0, fsp->brlock_seqnum=0 [2016/01/03 11:52:12.452154, 5, pid=73700, effective(17420, 0), real(0, 0), class=locking] ../source3/smbd/oplock.c:86(set_file_oplock) set_file_oplock: granted oplock on file 4, d7841abe:2339305:0/3743681904, tv_sec = 568951bc, tv_usec = 6d104 [2016/01/03 11:52:12.452198, 10, pid=73700, effective(17420, 0), real(0, 0), class=locking] ../source3/locking/brlock.c:2048(brl_get_locks_readonly) seqnum=0, fsp->brlock_seqnum=0 [2016/01/03 11:52:12.452234, 10, pid=73700, effective(17420, 0), real(0, 0)] ../source3/smbd/open.c:1874(grant_fsp_oplock_type) grant_fsp_oplock_type: oplock type 0x0 on file 4 [2016/01/03 11:52:12.452271, 10, pid=73700, effective(17420, 0), real(0, 0), class=locking] ../source3/locking/share_mode_lock.c:358(unparse_share_modes) unparse_share_modes: [2016/01/03 11:52:12.452304, 1, pid=73700, effective(17420, 0), real(0, 0)] ../librpc/ndr/ndr.c:402(ndr_print_debug) d: struct share_mode_data sequence_number : 0x159752e8d94e6dbe (1555803356311481790) servicepath : * servicepath : '/u4/erick' base_name : * base_name : '4' stream_name : NULL num_share_modes : 0x00000001 (1) share_modes: ARRAY(1) share_modes: struct share_mode_entry pid: struct server_id pid : 0x0000000000011fe4 (73700) task_id : 0x00000000 (0) vnn : 0xffffffff (4294967295) unique_id : 0x1671bfce06a2a858 (1617284632798210136) op_mid : 0x0000000000000005 (5) op_type : 0x0000 (0) lease_idx : 0xffffffff (4294967295) access_mask : 0x00010080 (65664) share_access : 0x00000003 (3) private_options : 0x00000000 (0) time : Sun Jan 3 11:52:12 2016 EST.446724 id: struct file_id devid : 0x00000000d7841abe (3615759038) inode : 0x0000000002339305 (36934405) extid : 0x0000000000000000 (0) share_file_id : 0x00000000df240d70 (3743681904) uid : 0x0000440c (17420) flags : 0x0000 (0) name_hash : 0x9d3cc599 (2638005657) stale : 0x00 (0) lease : NULL num_leases : 0x00000000 (0) leases: ARRAY(0) num_delete_tokens : 0x00000000 (0) delete_tokens: ARRAY(0) old_write_time : Fri Dec 4 09:18:31 2015 EST.631060402 changed_write_time : Wed Dec 31 19:00:00 1969 EST.0 fresh : 0x01 (1) modified : 0x01 (1) record : * id: struct file_id devid : 0x00000000d7841abe (3615759038) inode : 0x0000000002339305 (36934405) extid : 0x0000000000000000 (0) [2016/01/03 11:52:12.453096, 10, pid=73700, effective(17420, 0), real(0, 0), class=locking] ../source3/locking/share_mode_lock.c:147(share_mode_memcache_delete) deleting entry for file 4 seq 0x1555803356311481790 key d7841abe:2339305:0 [2016/01/03 11:52:12.453196, 10, pid=73700, effective(17420, 0), real(0, 0)] ../lib/dbwrap/dbwrap_tdb.c:59(db_tdb_log_key) Unlocking key BE1A84D7000000000593 [2016/01/03 11:52:12.453241, 5, pid=73700, effective(17420, 0), real(0, 0)] ../lib/dbwrap/dbwrap.c:146(dbwrap_lock_order_state_destructor) release lock order 1 for /usr/local/samba/var/lock/locking.tdb [2016/01/03 11:52:12.453276, 10, pid=73700, effective(17420, 0), real(0, 0)] ../lib/dbwrap/dbwrap.c:133(debug_lock_order) lock order: 1:<none> 2:<none> 3:<none> [2016/01/03 11:52:12.453312, 10, pid=73700, effective(17420, 0), real(0, 0), class=locking] ../source3/locking/share_mode_lock.c:161(share_mode_memcache_store) stored entry for file 4 seq 0x1555803356311481791 key d7841abe:2339305:0 [2016/01/03 11:52:12.453352, 10, pid=73700, effective(17420, 0), real(0, 0)] ../source3/smbd/open.c:4784(create_file_unixpath) create_file_unixpath: info=1 [2016/01/03 11:52:12.453388, 10, pid=73700, effective(17420, 0), real(0, 0)] ../source3/smbd/open.c:5063(create_file_default) create_file: info=1 [2016/01/03 11:52:12.453423, 10, pid=73700, effective(17420, 0), real(0, 0), class=vfs] ../source3/smbd/vfs.c:1147(check_reduced_name) check_reduced_name [3] [/u4/erick] [2016/01/03 11:52:12.453485, 10, pid=73700, effective(17420, 0), real(0, 0), class=vfs] ../source3/smbd/vfs.c:1207(check_reduced_name) check_reduced_name realpath [3] -> [/u4/erick/3] [2016/01/03 11:52:12.453524, 5, pid=73700, effective(17420, 0), real(0, 0), class=vfs] ../source3/smbd/vfs.c:1279(check_reduced_name) 3 reduced to /u4/erick/3 [2016/01/03 11:52:12.453588, 5, pid=73700, effective(17420, 0), real(0, 0)] ../lib/dbwrap/dbwrap.c:178(dbwrap_check_lock_order) check lock order 1 for /usr/local/samba/var/lock/locking.tdb [2016/01/03 11:52:12.453628, 10, pid=73700, effective(17420, 0), real(0, 0)] ../lib/dbwrap/dbwrap.c:133(debug_lock_order) lock order: 1:/usr/local/samba/var/lock/locking.tdb 2:<none> 3:<none> [2016/01/03 11:52:12.453668, 10, pid=73700, effective(17420, 0), real(0, 0)] ../lib/dbwrap/dbwrap_tdb.c:59(db_tdb_log_key) Locking key BE1A84D7000000000593 [2016/01/03 11:52:12.453709, 10, pid=73700, effective(17420, 0), real(0, 0)] ../lib/dbwrap/dbwrap_tdb.c:143(db_tdb_fetch_locked_internal) Allocated locked data 0x0x813160860 [2016/01/03 11:52:12.453751, 10, pid=73700, effective(17420, 0), real(0, 0), class=locking] ../source3/locking/share_mode_lock.c:275(share_mode_memcache_fetch) fetched entry for file 4 seq 0x1555803356311481791 key d7841abe:2339305:0 [2016/01/03 11:52:12.453917, 3, pid=73700, effective(17420, 0), real(0, 0)] ../source3/smbd/reply.c:6625(rename_internals_fsp) rename_internals_fsp: succeeded doing rename on 4 -> 3 [2016/01/03 11:52:12.453975, 8, pid=73700, effective(17420, 0), real(0, 0)] ../source3/smbd/dosmode.c:601(dos_mode) dos_mode: 3 [2016/01/03 11:52:12.454015, 8, pid=73700, effective(17420, 0), real(0, 0)] ../source3/smbd/dosmode.c:243(dos_mode_from_sbuf) dos_mode_from_sbuf returning [2016/01/03 11:52:12.454055, 8, pid=73700, effective(17420, 0), real(0, 0)] ../source3/smbd/dosmode.c:36(dos_mode_debug_print) dos_mode returning [2016/01/03 11:52:12.454089, 10, pid=73700, effective(17420, 0), real(0, 0)] ../source3/smbd/dosmode.c:690(file_set_dosmode) file_set_dosmode: setting dos mode 0x20 on file 3 [2016/01/03 11:52:12.454134, 8, pid=73700, effective(17420, 0), real(0, 0)] ../source3/smbd/dosmode.c:601(dos_mode) dos_mode: 3 [2016/01/03 11:52:12.454171, 8, pid=73700, effective(17420, 0), real(0, 0)] ../source3/smbd/dosmode.c:243(dos_mode_from_sbuf) dos_mode_from_sbuf returning [2016/01/03 11:52:12.454204, 8, pid=73700, effective(17420, 0), real(0, 0)] ../source3/smbd/dosmode.c:36(dos_mode_debug_print) dos_mode returning [2016/01/03 11:52:12.454239, 5, pid=73700, effective(17420, 0), real(0, 0)] ../source3/smbd/dosmode.c:196(unix_mode) unix_mode(3) returning 0744 [2016/01/03 11:52:12.454294, 10, pid=73700, effective(17420, 0), real(0, 0)] ../source3/smbd/notify_msg.c:227(notify_trigger) notify_trigger called action=0x4, filter=0x1, dir=/u4/erick, name=4 [2016/01/03 11:52:12.454339, 4, pid=73700, effective(17420, 0), real(0, 0)] ../source3/smbd/sec_ctx.c:217(push_sec_ctx) push_sec_ctx(17420, 0) : sec_ctx_stack_ndx = 1 [2016/01/03 11:52:12.454377, 4, pid=73700, effective(17420, 0), real(0, 0)] ../source3/smbd/uid.c:491(push_conn_ctx) push_conn_ctx(24476) : conn_ctx_stack_ndx = 0 [2016/01/03 11:52:12.454412, 4, pid=73700, effective(17420, 0), real(0, 0)] ../source3/smbd/sec_ctx.c:321(set_sec_ctx_internal) setting sec ctx (0, 0) - sec_ctx_stack_ndx = 1 [2016/01/03 11:52:12.454445, 5, pid=73700, effective(17420, 0), real(0, 0)] ../libcli/security/security_token.c:53(security_token_debug) Security token: (NULL) [2016/01/03 11:52:12.454478, 5, pid=73700, effective(17420, 0), real(0, 0)] ../source3/auth/token_util.c:639(debug_unix_user_token) UNIX token of user 0 Primary group is 0 and contains 0 supplementary groups [2016/01/03 11:52:12.454545, 10, pid=73700, effective(0, 0), real(0, 0)] ../source3/lib/messages_dgm.c:284(messaging_dgm_send) messaging_dgm_send: Sending message to 73655 [2016/01/03 11:52:12.454656, 4, pid=73700, effective(17420, 0), real(0, 0)] ../source3/smbd/sec_ctx.c:439(pop_sec_ctx) pop_sec_ctx (17420, 0) - sec_ctx_stack_ndx = 0 [2016/01/03 11:52:12.454676, 10, pid=73655, effective(0, 0), real(0, 0)] ../source3/lib/messages.c:254(messaging_recv_cb) [2016/01/03 11:52:12.454699, 10, pid=73700, effective(17420, 0), real(0, 0)] ../source3/smbd/notify_msg.c:227(notify_trigger) messaging_recv_cb: Received message 0x31b len 36 (num_fds:0) from 73700 notify_trigger called action=0x5, filter=0x1, dir=/u4/erick, name=3 [2016/01/03 11:52:12.454814, 4, pid=73700, effective(17420, 0), real(0, 0)] ../source3/smbd/sec_ctx.c:217(push_sec_ctx) [2016/01/03 11:52:12.454821, 10, pid=73655, effective(0, 0), real(0, 0)] ../source3/smbd/notifyd/notifyd.c:651(notifyd_trigger) push_sec_ctx(17420, 0) : sec_ctx_stack_ndx = 1 notifyd_trigger: Got trigger_msg action=4, filter=1, path=/u4/erick/4 [2016/01/03 11:52:12.454888, 4, pid=73700, effective(17420, 0), real(0, 0)] ../source3/smbd/uid.c:491(push_conn_ctx) [2016/01/03 11:52:12.454913, 10, pid=73655, effective(0, 0), real(0, 0)] ../source3/smbd/notifyd/notifyd.c:668(notifyd_trigger) push_conn_ctx(24476) : conn_ctx_stack_ndx = 0 notifyd_trigger: Trying path /u4 [2016/01/03 11:52:12.454977, 4, pid=73700, effective(17420, 0), real(0, 0)] ../source3/smbd/sec_ctx.c:321(set_sec_ctx_internal) [2016/01/03 11:52:12.455007, 10, pid=73655, effective(0, 0), real(0, 0)] ../source3/smbd/notifyd/notifyd.c:668(notifyd_trigger) setting sec ctx (0, 0) - sec_ctx_stack_ndx = 1 notifyd_trigger: Trying path /u4/erick [2016/01/03 11:52:12.455073, 5, pid=73700, effective(17420, 0), real(0, 0)] ../libcli/security/security_token.c:53(security_token_debug) Security token: (NULL) [2016/01/03 11:52:12.455121, 5, pid=73700, effective(17420, 0), real(0, 0)] ../source3/auth/token_util.c:639(debug_unix_user_token) UNIX token of user 0 Primary group is 0 and contains 0 supplementary groups [2016/01/03 11:52:12.455183, 10, pid=73700, effective(0, 0), real(0, 0)] ../source3/lib/messages_dgm.c:284(messaging_dgm_send) messaging_dgm_send: Sending message to 73655 [2016/01/03 11:52:12.455254, 4, pid=73700, effective(17420, 0), real(0, 0)] ../source3/smbd/sec_ctx.c:439(pop_sec_ctx) [2016/01/03 11:52:12.455255, 10, pid=73655, effective(0, 0), real(0, 0)] ../source3/lib/messages.c:254(messaging_recv_cb) pop_sec_ctx (17420, 0) - sec_ctx_stack_ndx = 0 messaging_recv_cb: Received message 0x31b len 36 (num_fds:0) from 73700 [2016/01/03 11:52:12.455338, 10, pid=73700, effective(17420, 0), real(0, 0)] ../source3/smbd/notify_msg.c:227(notify_trigger) notify_trigger called action=0x3, filter=0x44, dir=/u4/erick, name=3 [2016/01/03 11:52:12.455374, 10, pid=73655, effective(0, 0), real(0, 0)] ../source3/smbd/notifyd/notifyd.c:651(notifyd_trigger) [2016/01/03 11:52:12.455403, 4, pid=73700, effective(17420, 0), real(0, 0)] ../source3/smbd/sec_ctx.c:217(push_sec_ctx) notifyd_trigger: Got trigger_msg action=5, filter=1, path=/u4/erick/3 push_sec_ctx(17420, 0) : sec_ctx_stack_ndx = 1 [2016/01/03 11:52:12.455478, 10, pid=73655, effective(0, 0), real(0, 0)] ../source3/smbd/notifyd/notifyd.c:668(notifyd_trigger) [2016/01/03 11:52:12.455507, 4, pid=73700, effective(17420, 0), real(0, 0)] ../source3/smbd/uid.c:491(push_conn_ctx) notifyd_trigger: Trying path /u4 push_conn_ctx(24476) : conn_ctx_stack_ndx = 0 [2016/01/03 11:52:12.455569, 10, pid=73655, effective(0, 0), real(0, 0)] ../source3/smbd/notifyd/notifyd.c:668(notifyd_trigger) [2016/01/03 11:52:12.455594, 4, pid=73700, effective(17420, 0), real(0, 0)] ../source3/smbd/sec_ctx.c:321(set_sec_ctx_internal) notifyd_trigger: Trying path /u4/erick setting sec ctx (0, 0) - sec_ctx_stack_ndx = 1 [2016/01/03 11:52:12.455692, 5, pid=73700, effective(17420, 0), real(0, 0)] ../libcli/security/security_token.c:53(security_token_debug) Security token: (NULL) [2016/01/03 11:52:12.455735, 5, pid=73700, effective(17420, 0), real(0, 0)] ../source3/auth/token_util.c:639(debug_unix_user_token) UNIX token of user 0 Primary group is 0 and contains 0 supplementary groups [2016/01/03 11:52:12.455804, 10, pid=73700, effective(0, 0), real(0, 0)] ../source3/lib/messages_dgm.c:284(messaging_dgm_send) messaging_dgm_send: Sending message to 73655 [2016/01/03 11:52:12.455876, 4, pid=73700, effective(17420, 0), real(0, 0)] ../source3/smbd/sec_ctx.c:439(pop_sec_ctx) pop_sec_ctx (17420, 0) - sec_ctx_stack_ndx = 0 [2016/01/03 11:52:12.455875, 10, pid=73655, effective(0, 0), real(0, 0)] ../source3/lib/messages.c:254(messaging_recv_cb) [2016/01/03 11:52:12.455924, 10, pid=73700, effective(17420, 0), real(0, 0)] ../source3/smbd/reply.c:6273(rename_open_files) messaging_recv_cb: Received message 0x31b len 36 (num_fds:0) from 73700 rename_open_files: renaming file fnum 10636 (file_id d7841abe:2339305:0) from 4 -> 3 [2016/01/03 11:52:12.456005, 10, pid=73655, effective(0, 0), real(0, 0)] ../source3/smbd/notifyd/notifyd.c:651(notifyd_trigger) [2016/01/03 11:52:12.456021, 10, pid=73700, effective(17420, 0), real(0, 0)] ../source3/smbd/files.c:745(file_name_hash) notifyd_trigger: Got trigger_msg action=3, filter=68, path=/u4/erick/3 file_name_hash: /u4/erick/3 hash 0xff10138b [2016/01/03 11:52:12.456088, 10, pid=73655, effective(0, 0), real(0, 0)] ../source3/smbd/notifyd/notifyd.c:668(notifyd_trigger) [2016/01/03 11:52:12.456113, 10, pid=73700, effective(17420, 0), real(0, 0), class=locking] ../source3/locking/locking.c:483(rename_share_filename) notifyd_trigger: Trying path /u4 rename_share_filename: servicepath /u4/erick newname 3 [2016/01/03 11:52:12.456187, 10, pid=73655, effective(0, 0), real(0, 0)] ../source3/smbd/notifyd/notifyd.c:668(notifyd_trigger) [2016/01/03 11:52:12.456217, 10, pid=73700, effective(17420, 0), real(0, 0), class=locking] ../source3/locking/locking.c:523(rename_share_filename) notifyd_trigger: Trying path /u4/erick rename_share_filename: msg_len = 37 [2016/01/03 11:52:12.456306, 10, pid=73700, effective(17420, 0), real(0, 0), class=locking] ../source3/locking/share_mode_lock.c:358(unparse_share_modes) unparse_share_modes: [2016/01/03 11:52:12.456351, 1, pid=73700, effective(17420, 0), real(0, 0)] ../librpc/ndr/ndr.c:402(ndr_print_debug) d: struct share_mode_data sequence_number : 0x159752e8d94e6dbf (1555803356311481791) servicepath : * servicepath : '/u4/erick' base_name : * base_name : '3' stream_name : NULL num_share_modes : 0x00000001 (1) share_modes: ARRAY(1) share_modes: struct share_mode_entry pid: struct server_id pid : 0x0000000000011fe4 (73700) task_id : 0x00000000 (0) vnn : 0xffffffff (4294967295) unique_id : 0x1671bfce06a2a858 (1617284632798210136) op_mid : 0x0000000000000005 (5) op_type : 0x0000 (0) lease_idx : 0xffffffff (4294967295) access_mask : 0x00010080 (65664) share_access : 0x00000003 (3) private_options : 0x00000000 (0) time : Sun Jan 3 11:52:12 2016 EST.446724 id: struct file_id devid : 0x00000000d7841abe (3615759038) inode : 0x0000000002339305 (36934405) extid : 0x0000000000000000 (0) share_file_id : 0x00000000df240d70 (3743681904) uid : 0x0000440c (17420) flags : 0x0000 (0) name_hash : 0xff10138b (4279243659) stale : 0x00 (0) lease : NULL num_leases : 0x00000000 (0) leases: ARRAY(0) num_delete_tokens : 0x00000000 (0) delete_tokens: ARRAY(0) old_write_time : Fri Dec 4 09:18:31 2015 EST.631060402 changed_write_time : Wed Dec 31 19:00:00 1969 EST.0 fresh : 0x00 (0) modified : 0x01 (1) record : * id: struct file_id devid : 0x00000000d7841abe (3615759038) inode : 0x0000000002339305 (36934405) extid : 0x0000000000000000 (0) [2016/01/03 11:52:12.457113, 10, pid=73700, effective(17420, 0), real(0, 0), class=locking] ../source3/locking/share_mode_lock.c:147(share_mode_memcache_delete) deleting entry for file 3 seq 0x1555803356311481791 key d7841abe:2339305:0 [2016/01/03 11:52:12.457180, 10, pid=73700, effective(17420, 0), real(0, 0)] ../lib/dbwrap/dbwrap_tdb.c:59(db_tdb_log_key) Unlocking key BE1A84D7000000000593 [2016/01/03 11:52:12.457222, 5, pid=73700, effective(17420, 0), real(0, 0)] ../lib/dbwrap/dbwrap.c:146(dbwrap_lock_order_state_destructor) release lock order 1 for /usr/local/samba/var/lock/locking.tdb [2016/01/03 11:52:12.457256, 10, pid=73700, effective(17420, 0), real(0, 0)] ../lib/dbwrap/dbwrap.c:133(debug_lock_order) lock order: 1:<none> 2:<none> 3:<none> [2016/01/03 11:52:12.457292, 10, pid=73700, effective(17420, 0), real(0, 0), class=locking] ../source3/locking/share_mode_lock.c:161(share_mode_memcache_store) stored entry for file 3 seq 0x1555803356311481792 key d7841abe:2339305:0 [2016/01/03 11:52:12.457335, 5, pid=73700, effective(17420, 0), real(0, 0)] ../lib/dbwrap/dbwrap.c:178(dbwrap_check_lock_order) check lock order 1 for /usr/local/samba/var/lock/locking.tdb [2016/01/03 11:52:12.457370, 10, pid=73700, effective(17420, 0), real(0, 0)] ../lib/dbwrap/dbwrap.c:133(debug_lock_order) lock order: 1:/usr/local/samba/var/lock/locking.tdb 2:<none> 3:<none> [2016/01/03 11:52:12.457409, 10, pid=73700, effective(17420, 0), real(0, 0)] ../lib/dbwrap/dbwrap_tdb.c:59(db_tdb_log_key) Locking key BE1A84D7000000000593 [2016/01/03 11:52:12.457448, 10, pid=73700, effective(17420, 0), real(0, 0)] ../lib/dbwrap/dbwrap_tdb.c:143(db_tdb_fetch_locked_internal) Allocated locked data 0x0x813160860 [2016/01/03 11:52:12.457486, 10, pid=73700, effective(17420, 0), real(0, 0), class=locking] ../source3/locking/share_mode_lock.c:275(share_mode_memcache_fetch) fetched entry for file 3 seq 0x1555803356311481792 key d7841abe:2339305:0 [2016/01/03 11:52:12.457525, 10, pid=73700, effective(17420, 0), real(0, 0), class=locking] ../source3/locking/locking.c:1224(find_delete_on_close_token) find_delete_on_close_token: name_hash = 0xff10138b [2016/01/03 11:52:12.457561, 10, pid=73700, effective(17420, 0), real(0, 0), class=locking] ../source3/locking/share_mode_lock.c:358(unparse_share_modes) unparse_share_modes: [2016/01/03 11:52:12.457594, 1, pid=73700, effective(17420, 0), real(0, 0)] ../librpc/ndr/ndr.c:402(ndr_print_debug) d: struct share_mode_data sequence_number : 0x159752e8d94e6dc0 (1555803356311481792) servicepath : * servicepath : '/u4/erick' base_name : * base_name : '3' stream_name : NULL num_share_modes : 0x00000000 (0) share_modes: ARRAY(0) num_leases : 0x00000000 (0) leases: ARRAY(0) num_delete_tokens : 0x00000000 (0) delete_tokens: ARRAY(0) old_write_time : Fri Dec 4 09:18:31 2015 EST.631060402 changed_write_time : Wed Dec 31 19:00:00 1969 EST.0 fresh : 0x00 (0) modified : 0x01 (1) record : * id: struct file_id devid : 0x00000000d7841abe (3615759038) inode : 0x0000000002339305 (36934405) extid : 0x0000000000000000 (0) [2016/01/03 11:52:12.457961, 10, pid=73700, effective(17420, 0), real(0, 0), class=locking] ../source3/locking/share_mode_lock.c:147(share_mode_memcache_delete) deleting entry for file 3 seq 0x1555803356311481792 key d7841abe:2339305:0 [2016/01/03 11:52:12.457997, 10, pid=73700, effective(17420, 0), real(0, 0), class=locking] ../source3/locking/share_mode_lock.c:370(unparse_share_modes) No used share mode found [2016/01/03 11:52:12.458042, 10, pid=73700, effective(17420, 0), real(0, 0)] ../lib/dbwrap/dbwrap_tdb.c:59(db_tdb_log_key) Unlocking key BE1A84D7000000000593 [2016/01/03 11:52:12.458084, 5, pid=73700, effective(17420, 0), real(0, 0)] ../lib/dbwrap/dbwrap.c:146(dbwrap_lock_order_state_destructor) release lock order 1 for /usr/local/samba/var/lock/locking.tdb [2016/01/03 11:52:12.458119, 10, pid=73700, effective(17420, 0), real(0, 0)] ../lib/dbwrap/dbwrap.c:133(debug_lock_order) lock order: 1:<none> 2:<none> 3:<none> [2016/01/03 11:52:12.458161, 2, pid=73700, effective(17420, 0), real(0, 0)] ../source3/smbd/close.c:780(close_normal_file) erick closed file 3 (numopen=0) NT_STATUS_OK [2016/01/03 11:52:12.458199, 5, pid=73700, effective(17420, 0), real(0, 0)] ../lib/dbwrap/dbwrap.c:178(dbwrap_check_lock_order) check lock order 1 for /usr/local/samba/var/lock/smbXsrv_open_global.tdb [2016/01/03 11:52:12.458233, 10, pid=73700, effective(17420, 0), real(0, 0)] ../lib/dbwrap/dbwrap.c:133(debug_lock_order) lock order: 1:/usr/local/samba/var/lock/smbXsrv_open_global.tdb 2:<none> 3:<none> [2016/01/03 11:52:12.458270, 10, pid=73700, effective(17420, 0), real(0, 0)] ../lib/dbwrap/dbwrap_tdb.c:59(db_tdb_log_key) Locking key F7A275C6 [2016/01/03 11:52:12.458308, 10, pid=73700, effective(17420, 0), real(0, 0)] ../lib/dbwrap/dbwrap_tdb.c:143(db_tdb_fetch_locked_internal) Allocated locked data 0x0x8130e1ae0 [2016/01/03 11:52:12.458353, 10, pid=73700, effective(17420, 0), real(0, 0)] ../lib/dbwrap/dbwrap_tdb.c:59(db_tdb_log_key) Unlocking key F7A275C6 [2016/01/03 11:52:12.458391, 5, pid=73700, effective(17420, 0), real(0, 0)] ../lib/dbwrap/dbwrap.c:146(dbwrap_lock_order_state_destructor) release lock order 1 for /usr/local/samba/var/lock/smbXsrv_open_global.tdb [2016/01/03 11:52:12.458426, 10, pid=73700, effective(17420, 0), real(0, 0)] ../lib/dbwrap/dbwrap.c:133(debug_lock_order) lock order: 1:<none> 2:<none> 3:<none> [2016/01/03 11:52:12.458467, 5, pid=73700, effective(17420, 0), real(0, 0)] ../source3/smbd/files.c:554(file_free) freed files structure 10636 (0 used) [2016/01/03 11:52:12.458502, 3, pid=73700, effective(17420, 0), real(0, 0)] ../source3/smbd/reply.c:6858(rename_internals) rename_internals: Error NT_STATUS_OK rename 4 -> 3 [2016/01/03 11:52:12.458542, 5, pid=73700, effective(17420, 0), real(0, 0)] ../source3/lib/util.c:169(show_msg) [2016/01/03 11:52:12.458562, 5, pid=73700, effective(17420, 0), real(0, 0)] ../source3/lib/util.c:179(show_msg) size=35 smb_com=0x7 smb_rcls=0 smb_reh=0 smb_err=0 smb_flg=136 smb_flg2=51203 smb_tid=53180 smb_pid=9289 smb_uid=24476 smb_mid=5 smt_wct=0 smb_bcc=0 [2016/01/03 11:52:12.458748, 10, pid=73700, effective(17420, 0), real(0, 0)] ../lib/util/util.c:559(dump_data) [2016/01/03 11:52:15.192251, 10, pid=73700, effective(17420, 0), real(0, 0)] ../source3/lib/util_sock.c:248(read_smb_length_return_keepalive) got smb length of 88 [2016/01/03 11:52:15.192316, 6, pid=73700, effective(17420, 0), real(0, 0)] ../source3/smbd/process.c:1878(process_smb) got message type 0x0 of len 0x58 [2016/01/03 11:52:15.192352, 3, pid=73700, effective(17420, 0), real(0, 0)] ../source3/smbd/process.c:1880(process_smb) Transaction 5 of length 92 (0 toread) [2016/01/03 11:52:15.192388, 5, pid=73700, effective(17420, 0), real(0, 0)] ../source3/lib/util.c:169(show_msg) [2016/01/03 11:52:15.192407, 5, pid=73700, effective(17420, 0), real(0, 0)] ../source3/lib/util.c:179(show_msg) size=88 smb_com=0x32 smb_rcls=0 smb_reh=0 smb_err=0 smb_flg=8 smb_flg2=51201 smb_tid=53180 smb_pid=9289 smb_uid=24476 smb_mid=6 smt_wct=15 smb_vwv[ 0]= 18 (0x12) smb_vwv[ 1]= 0 (0x0) smb_vwv[ 2]= 10 (0xA) smb_vwv[ 3]=16644 (0x4104) smb_vwv[ 4]= 0 (0x0) smb_vwv[ 5]= 0 (0x0) smb_vwv[ 6]= 0 (0x0) smb_vwv[ 7]= 0 (0x0) smb_vwv[ 8]= 0 (0x0) smb_vwv[ 9]= 18 (0x12) smb_vwv[10]= 68 (0x44) smb_vwv[11]= 0 (0x0) smb_vwv[12]= 88 (0x58) smb_vwv[13]= 1 (0x1) smb_vwv[14]= 1 (0x1) smb_bcc=23 [2016/01/03 11:52:15.192811, 10, pid=73700, effective(17420, 0), real(0, 0)] ../lib/util/util.c:559(dump_data) [0000] 00 44 20 16 00 56 05 06 00 04 01 00 00 00 00 5C .D ..V.. .......\ [0010] 00 33 00 00 00 00 00 .3..... [2016/01/03 11:52:15.192894, 3, pid=73700, effective(17420, 0), real(0, 0)] ../source3/smbd/process.c:1490(switch_message) switch message SMBtrans2 (pid 73700) conn 0x8130e1960 [2016/01/03 11:52:15.192934, 4, pid=73700, effective(17420, 0), real(0, 0)] ../source3/smbd/uid.c:384(change_to_user) Skipping user change - already user [2016/01/03 11:52:15.192996, 3, pid=73700, effective(17420, 0), real(0, 0)] ../source3/smbd/trans2.c:2500(call_trans2findfirst) call_trans2findfirst: dirtype = 16, maxentries = 1366, close_after_first=0, close_if_end = 1 requires_resume_key = 1 backup_priv = 0 level = 0x104, max_data_bytes = 16644 [2016/01/03 11:52:15.193050, 5, pid=73700, effective(17420, 0), real(0, 0)] ../source3/smbd/filename.c:257(unix_convert) unix_convert called on file "3" [2016/01/03 11:52:15.193091, 10, pid=73700, effective(17420, 0), real(0, 0)] ../source3/smbd/statcache.c:244(stat_cache_lookup) stat_cache_lookup: lookup failed for name [3] [2016/01/03 11:52:15.193126, 5, pid=73700, effective(17420, 0), real(0, 0)] ../source3/smbd/filename.c:449(unix_convert) unix_convert begin: name = 3, dirpath = , start = 3 [2016/01/03 11:52:15.193176, 5, pid=73700, effective(17420, 0), real(0, 0)] ../source3/smbd/statcache.c:143(stat_cache_add) stat_cache_add: Added entry (81311f430:size 1) 3 -> 3 [2016/01/03 11:52:15.193214, 5, pid=73700, effective(17420, 0), real(0, 0)] ../source3/smbd/filename.c:472(unix_convert) conversion of base_name finished 3 -> 3 [2016/01/03 11:52:15.193248, 10, pid=73700, effective(17420, 0), real(0, 0), class=vfs] ../source3/smbd/vfs.c:1147(check_reduced_name) check_reduced_name [3] [/u4/erick] [2016/01/03 11:52:15.193372, 3, pid=73700, effective(17420, 0), real(0, 0), class=vfs] ../source3/smbd/vfs.c:1201(check_reduced_name) check_reduced_name: couldn't get realpath for 3 [2016/01/03 11:52:15.193414, 5, pid=73700, effective(17420, 0), real(0, 0)] ../source3/smbd/filename.c:1078(check_name) check_name: name 3 failed with NT_STATUS_ACCESS_DENIED [2016/01/03 11:52:15.193448, 3, pid=73700, effective(17420, 0), real(0, 0)] ../source3/smbd/filename.c:1431(filename_convert_internal) filename_convert_internal: check_name failed for name 3 with NT_STATUS_ACCESS_DENIED [2016/01/03 11:52:15.193486, 3, pid=73700, effective(17420, 0), real(0, 0)] ../source3/smbd/error.c:82(error_packet_set) NT error packet at ../source3/smbd/trans2.c(2566) cmd=50 (SMBtrans2) NT_STATUS_ACCESS_DENIED [2016/01/03 11:52:15.193524, 5, pid=73700, effective(17420, 0), real(0, 0)] ../source3/lib/util.c:169(show_msg) [2016/01/03 11:52:15.193543, 5, pid=73700, effective(17420, 0), real(0, 0)] ../source3/lib/util.c:179(show_msg) size=35 smb_com=0x32 smb_rcls=34 smb_reh=0 smb_err=49152 smb_flg=136 smb_flg2=51203 smb_tid=53180 smb_pid=9289 smb_uid=24476 smb_mid=6 smt_wct=0 smb_bcc=0 [2016/01/03 11:52:15.193726, 10, pid=73700, effective(17420, 0), real(0, 0)] ../lib/util/util.c:559(dump_data) [2016/01/03 11:53:01.276077, 10, pid=73656, effective(0, 0), real(0, 0)] ../source3/lib/events.c:426(smbd_idle_event_handler) smbd_idle_event_handler: idle_evt(print_queue_housekeeping) 0x0 called [2016/01/03 11:53:01.276197, 5, pid=73656, effective(0, 0), real(0, 0)] ../source3/printing/queue_process.c:163(print_queue_housekeeping) print queue housekeeping [2016/01/03 11:53:01.276246, 10, pid=73656, effective(0, 0), real(0, 0)] ../source3/lib/events.c:437(smbd_idle_event_handler) smbd_idle_event_handler: idle_evt(print_queue_housekeeping) 0x0 rescheduled [2016/01/03 11:53:07.796086, 10, pid=73700, effective(17420, 0), real(0, 0)] ../source3/lib/events.c:426(smbd_idle_event_handler) smbd_idle_event_handler: idle_evt(deadtime) 0x0 called [2016/01/03 11:53:07.796204, 10, pid=73700, effective(17420, 0), real(0, 0)] ../source3/lib/events.c:437(smbd_idle_event_handler) smbd_idle_event_handler: idle_evt(deadtime) 0x0 rescheduled [2016/01/03 11:53:07.796263, 10, pid=73700, effective(17420, 0), real(0, 0)] ../source3/lib/events.c:426(smbd_idle_event_handler) smbd_idle_event_handler: idle_evt(housekeeping) 0x0 called [2016/01/03 11:53:07.796312, 5, pid=73700, effective(17420, 0), real(0, 0)] ../source3/smbd/process.c:2812(housekeeping_fn) housekeeping [2016/01/03 11:53:07.796361, 4, pid=73700, effective(17420, 0), real(0, 0)] ../source3/smbd/sec_ctx.c:321(set_sec_ctx_internal) setting sec ctx (0, 0) - sec_ctx_stack_ndx = 0 [2016/01/03 11:53:07.796410, 5, pid=73700, effective(17420, 0), real(0, 0)] ../libcli/security/security_token.c:53(security_token_debug) Security token: (NULL) [2016/01/03 11:53:07.796456, 5, pid=73700, effective(17420, 0), real(0, 0)] ../source3/auth/token_util.c:639(debug_unix_user_token) UNIX token of user 0 Primary group is 0 and contains 0 supplementary groups [2016/01/03 11:53:07.796555, 5, pid=73700, effective(0, 0), real(0, 0)] ../source3/smbd/uid.c:425(smbd_change_to_root_user) change_to_root_user: now uid=(0,0) gid=(0,0) [2016/01/03 11:53:07.796628, 10, pid=73700, effective(0, 0), real(0, 0)] ../source3/lib/events.c:437(smbd_idle_event_handler) smbd_idle_event_handler: idle_evt(housekeeping) 0x0 rescheduled
If smbd is crashing - you should be able to get a good backtrace using panic action = /bin/sleep 999999 causing the crash, attaching to the crashed process using gdb and then typing "bt" to get a backtrace.
Hi Erick asked me to start dealing with this issue. I'm running the newest FreeBSD and samba4.3.9. The disconnected behavior appears to be independent of the OS version and samba version. The problem is strange since it depends upon the number of files and directories in the zpool so I've moved my account from one pool to the other and rerun the same commands including the backtrace. I've attached the script output, smb4.conf, and log file which are also available at https://www.eng.uwaterloo.ca/~ray/samba/typescript.ecserv30.server etc. I ran the date command periodically to help with keeping the commands and output in sync. Please get back to me if you need anything else. Thanks Ray.
Created attachment 12276 [details] backtrace etc.
Created attachment 12277 [details] Rays smb.log
Created attachment 12278 [details] smb4.conf
Created attachment 12279 [details] client view and commands entered
There are no symbols in this backtrace, making it useless I'm afraid. Please rebuild Samba with debug symbols and recreate the crash. Thanks ! Jeremy.
Hi Jeremy, I did build it with debug support, I assumed it was working since the first gdb listing returned what I thought was correct. Ray
In your attachment called "backtrace etc." the backtrace is: ----------------------------------------------------- gdb /usr/local/sbin/smdb[K[Kbd 8463 GNU gdb 6.1.1 [FreeBSD] Copyright 2004 Free Software Foundation, Inc. GDB is free software, covered by the GNU General Public License, and you are welcome to change it and/or distribute copies of it under certain conditions. Type "show copying" to see the conditions. There is absolutely no warranty for GDB. Type "show warranty" for details. This GDB was configured as "amd64-marcel-freebsd"... Attaching to program: /usr/local/sbin/smbd, process 8463 0x0000000805911eea in ?? () (gdb) where bt #0 0x0000000805911eea in ?? () #1 0x0000000801461536 in ?? () #2 0x0000000801461500 in ?? () #3 0x000000081266f300 in ?? () #4 0x00007fffffffe9b8 in ?? () #5 0x0000000001031fa3 in ?? () #6 0x0000000801d8498a in ?? () #7 0x0000000801d8498a in ?? () #8 0x00007fffffffdfb0 in ?? () #9 0x0000000803c8591b in ?? () #10 0x0000000000002000 in .dynsym () Error accessing memory address 0xb40: Bad address. (gdb) wh bt list Error accessing memory address 0x7f20: Bad address. (gdb) where #0 0x0000000805911eea in ?? () #1 0x0000000801461536 in ?? () #2 0x0000000801461500 in ?? () #3 0x000000081266f300 in ?? () #4 0x00007fffffffe9b8 in ?? () #5 0x0000000001031fa3 in ?? () #6 0x0000000801d8498a in ?? () #7 0x0000000801d8498a in ?? () #8 0x00007fffffffdfb0 in ?? () #9 0x0000000803c8591b in ?? () #10 0x0000000000002000 in .dynsym () (gdb) quit The program is running. Quit anyway (and detach it)? (y or n) y Detaching from program: /usr/local/sbin/smbd, process 8463 ----------------------------------------------------- That really isn't useful and doesn't tell me anything I can use to debug.
Erick, Ray: does this still happen with modern FreeBSD and Samba releases? I'm closing this bug for now but let us know about the current status please and feel free to reopen the bug report if you still see the issue with modern versions.