Bug 11657 - attempt to rename a file in the user's root of a share on a ZFS partition causes server process to crash
attempt to rename a file in the user's root of a share on a ZFS partition ca...
Status: NEEDINFO
Product: Samba 4.1 and newer
Classification: Unclassified
Component: File services
4.3.3
x64 FreeBSD
: P5 major
: ---
Assigned To: Samba QA Contact
Samba QA Contact
:
Depends on:
Blocks:
  Show dependency treegraph
 
Reported: 2016-01-03 00:22 UTC by Erick Engelke
Modified: 2016-07-19 21:45 UTC (History)
1 user (show)

See Also:


Attachments
backtrace etc. (8.20 KB, text/plain)
2016-07-19 21:19 UTC, Ray
no flags Details
Rays smb.log (2.17 MB, text/x-log)
2016-07-19 21:20 UTC, Ray
no flags Details
smb4.conf (1.44 KB, text/plain)
2016-07-19 21:21 UTC, Ray
no flags Details
client view and commands entered (2.38 KB, text/plain)
2016-07-19 21:22 UTC, Ray
no flags Details

Note You need to log in before you can comment on or make changes to this bug.
Description Erick Engelke 2016-01-03 00:22:39 UTC
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)
Comment 1 Erick Engelke 2016-01-03 00:23:46 UTC
sorry, meant x64, not IA64.
Comment 2 Erick Engelke 2016-01-03 14:31:55 UTC
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
Comment 3 Erick Engelke 2016-01-03 15:25:14 UTC
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.
Comment 4 Erick Engelke 2016-01-03 17:01:45 UTC


[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
Comment 5 Jeremy Allison 2016-01-04 19:38:18 UTC
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.
Comment 6 Ray 2016-07-19 21:19:10 UTC
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.
Comment 7 Ray 2016-07-19 21:19:41 UTC
Created attachment 12276 [details]
backtrace etc.
Comment 8 Ray 2016-07-19 21:20:42 UTC
Created attachment 12277 [details]
Rays smb.log
Comment 9 Ray 2016-07-19 21:21:30 UTC
Created attachment 12278 [details]
smb4.conf
Comment 10 Ray 2016-07-19 21:22:00 UTC
Created attachment 12279 [details]
client view and commands entered
Comment 11 Jeremy Allison 2016-07-19 21:27:10 UTC
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.
Comment 12 Ray 2016-07-19 21:32:28 UTC
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
Comment 13 Jeremy Allison 2016-07-19 21:45:27 UTC
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.