Bug 11063 - Panic on FreeBSD with directory with more than 10K files
Panic on FreeBSD with directory with more than 10K files
Status: ASSIGNED
Product: Samba 4.1 and newer
Classification: Unclassified
Component: File services
4.1.16
x64 FreeBSD
: P5 critical
: ---
Assigned To: Ralph Böhme
Samba QA Contact
:
Depends on:
Blocks:
  Show dependency treegraph
 
Reported: 2015-01-20 19:22 UTC by Mike Carlson
Modified: 2015-08-31 00:19 UTC (History)
3 users (show)

See Also:


Attachments
smbd open fds in directory with 50k files (4.58 MB, text/plain)
2015-01-21 01:20 UTC, Mike Carlson
no flags Details
smbd open fds in directory with 100k files (399.18 KB, application/gzip)
2015-01-21 01:27 UTC, Mike Carlson
no flags Details
level 10 log files for successful smbclient connection (62.17 KB, application/gzip)
2015-01-23 01:41 UTC, Mike Carlson
no flags Details
level 10 log files for failed smbclient connection (65.65 KB, application/gzip)
2015-01-23 01:43 UTC, Mike Carlson
no flags Details
level 10 log files for failed windows client connection (4.66 MB, application/gzip)
2015-01-29 20:43 UTC, Mike Carlson
no flags Details
level 10 log files for successful smbclient connection (186.31 KB, application/gzip)
2015-01-29 20:44 UTC, Mike Carlson
no flags Details

Note You need to log in before you can comment on or make changes to this bug.
Description Mike Carlson 2015-01-20 19:22:25 UTC
System Details:

OS:
FreeBSD working-2.discdrive.bayphoto.com 10.0-RELEASE-p3 FreeBSD 10.0-RELEASE-p3 #0: Tue May 13 18:31:10 UTC 2014     root@amd64-builder.daemonology.net:/usr/obj/usr/src/sys/GENERIC  amd64

Samba Package info:
samba41-4.1.16
Name           : samba41
Version        : 4.1.16
Installed on   : Tue Jan 20 10:21:58 PST 2015
Origin         : net/samba41
Architecture   : freebsd:10:x86:64
Prefix         : /usr/local
Categories     : net
Licenses       : GPLv3
Maintainer     : timur@FreeBSD.org
WWW            : http://www.samba.org/
Comment        : Free SMB/CIFS and AD/DC server and client for Unix
Options        :
        ACL_SUPPORT    : on
        ADS            : on
        AD_DC          : on
        AIO_SUPPORT    : on
        AVAHI          : on
        BIND910        : off
        BIND99         : off
        CUPS           : on
        DEBUG          : on
        DEVELOPER      : off
        DNSUPDATE      : on
        DOCS           : on
        EXP_MODULES    : on
        FAM            : on
        LDAP           : on
        MANPAGES       : off
        MDNSRESPONDER  : off
        NSUPDATE       : on
        PAM_SMBPASS    : on
        PTHREADPOOL    : on
        QUOTAS         : on
        SYSLOG         : on
        UTMP           : on
Shared Libs required:
        libtevent.so.0
        libtdb.so.1
        libtalloc.so.2
        libsunacl.so.1
        libsasl2.so.3
        libpython2.7.so.1
        libpytalloc-util.so.2
        libpyldb-util.so.1
        libpopt.so.0
        libntdb.so.1
        libldb.so.1
        libldap-2.4.so.2
        liblber-2.4.so.2
        libinotify.so.0
        libiconv.so.2
        libgnutls.so.28
        libgcrypt.so.20
        libfam.so.0
        libcups.so.2
        libavahi-common.so.3
        libavahi-client.so.3
Shared Libs provided:
        libxattr_tdb.so
        libwind-samba4.so.0
        libwinbind-client.so
        libwbclient.so.0
        libutil_tdb.so
        libutil_setid.so
        libutil_reg.so
        libutil_ntdb.so
        libutil_cmdline.so
        libtrusts_util.so
        libtorture.so.0
        libtevent-util.so.0
        libtdb_compat.so
        libtdb-wrap.so
        libsubunit.so
        libsmbsharemodes.so.0
        libsmbregistry.so
        libsmbpasswdparser.so
        libsmbldaphelper.so
        libsmbldap.so.0
        libsmbd_shim.so
        libsmbd_conn.so
        libsmbd_base.so
        libsmbconf.so.0
        libsmbclient-raw.so.0
        libsmb_transport.so
        libshares.so
        libservice.so
        libserver-role.so
        libsecrets3.so
        libsamdb.so.0
        libsamdb-common.so
        libsamba_python.so
        libsamba3-util.so
        libsamba-util.so.0
        libsamba-sockets.so
        libsamba-security.so
        libsamba-policy.so.0
        libsamba-net.so
        libsamba-modules.so
        libsamba-hostconfig.so.0
        libsamba-credentials.so.0
        libroken-samba4.so.19
        libreplace.so
        libregistry.so.0
        libprocess_model.so
        libprinting_migrate.so
        libposix_eadb.so
        libpopt_samba3.so
        libpdb.so.0
        libpac.so
        libntvfs.so
        libnss_info.so
        libnpa_tstream.so
        libnon_posix_acls.so
        libnetif.so
        libnetapi.so.0
        libnet_keytab.so
        libndr.so.0
        libndr-standard.so.0
        libndr-samba4.so
        libndr-samba.so
        libndr-nbt.so.0
        libndr-krb5pac.so.0
        libmsrpc3.so
        liblibsmb.so
        liblibcli_netlogon3.so
        liblibcli_lsa3.so
        libldbsamba.so
        libkrb5samba.so
        libkrb5-samba4.so.26
        libkdc-samba4.so.2
        libinterfaces.so
        libiniparser.so
        libidmap.so
        libhx509-samba4.so.5
        libheimntlm-samba4.so.1
        libheimbase-samba4.so.1
        libhdb-samba4.so.11
        libhcrypto-samba4.so.5
        libgssapi-samba4.so.2
        libgse.so
        libgpo.so
        libgensec.so.0
        libflag_mapping.so
        libevents.so
        liberrors.so
        libdsdb-module.so
        libdnsserver_common.so
        libdlz_bind9_for_torture.so
        libdfs_server_ad.so
        libdcerpc.so.0
        libdcerpc-server.so.0
        libdcerpc-samr.so.0
        libdcerpc-samba4.so
        libdcerpc-samba.so
        libdcerpc-binding.so.0
        libdcerpc-atsvc.so.0
        libdbwrap.so
        libdb-glue.so
        libcom_err-samba4.so.0
        libcmdline-credentials.so
        libcluster.so
        libcliauth.so
        libcli_spoolss.so
        libcli_smb_common.so
        libcli_cldap.so
        libcli-nbt.so
        libcli-ldap.so
        libcli-ldap-common.so
        libccan.so
        libauthkrb5.so
        libauth_unix_token.so
        libauth_sam_reply.so
        libauth4.so
        libauth.so
        libasn1util.so
        libasn1-samba4.so.8
        libads.so
        libaddns.so
        libMESSAGING.so
        libLIBWBCLIENT_OLD.so
        libHDB_SAMBA4.so
        libCHARSET3.so
Annotations    :
        cpe            : cpe:2.3:a:samba:samba:4.1.16:::::freebsd10:x64
        repo_type      : binary
        repository     : pkgng
Flat size      : 103MiB
Description    :
Samba4 is an attempt to implement an Active Directory compatible Domain
Controller.

In short, you can join a WinNT, Win2000, WinXP or Win2003 member server
to a Samba4 domain, and it will behave much as it does in AD, including
Kerberos domain logins where applicable.

WWW: http://www.samba.org/

Issue:

We have a large production environment, a single directory may contain over 50K files/folders

We were running Samba 3.6, and there has never been a problem, but when we upgraded to Samba 4.1.16, we started to receive the error of:

Jan 18 12:28:10 working-1 smbd_audit:   Too many open files, unable to open more!  smbd's max open files = 32768

The OS related sysctl values are set (automatically) to:

kern.maxfiles: 256000
kern.maxfilesperproc: 32768
kern.openfiles: 32411

I increased the 'maxfilesperproc' to 65000, and then adjusted the smb.conf parameter:

max open files = 240000

But, that did not have any effect:

Jan 18 12:48:59 working-1 smbd_audit:   Too many open files, unable to open more!  smbd's max open files = 240000



I've had to downgrade back to samba 3.6, which has been pretty stable for us, but we need to move to samba 4.1 due to an active directory upgrade that is pending


I have been able to reproduce this issue on a virtual machine, I created a few test directories inside of a share:


root@samba-qa-1:~ # ls /data/smb_qa/
100k_file_test          10k_file_test           200k_file_test          50k_file_test           test_file_version.txt   testing_from_mikec      root@samba-qa-1:~ #


When a few users attempt to connect to the 10k_files_test dir, they can view all 10,000 files. When they connect to the 50, 100, and 250k test dirs, smbd crashes with:

Jan 20 11:01:31 samba-qa-1 smbd[1135]:   ===============================================================
Jan 20 11:01:31 samba-qa-1 smbd[1135]: [2015/01/20 11:01:31.154353,  0] ../source3/lib/util.c:785(smb_panic_s3)
Jan 20 11:01:31 samba-qa-1 smbd[1135]:   PANIC (pid 1135): internal error
Jan 20 11:01:31 samba-qa-1 smbd[1135]: [2015/01/20 11:01:31.155738,  0] ../source3/lib/util.c:896(log_stack_trace)
Jan 20 11:01:31 samba-qa-1 smbd[1135]:   BACKTRACE: 7 stack frames:
Jan 20 11:01:31 samba-qa-1 smbd[1135]:    #0 0x802d99b71 <log_stack_trace+0x21> at /usr/local/lib/libsmbconf.so.0
Jan 20 11:01:31 samba-qa-1 smbd[1135]:    #1 0x802d99958 <smb_panic_s3+0x98> at /usr/local/lib/libsmbconf.so.0
Jan 20 11:01:31 samba-qa-1 smbd[1135]:    #2 0x801470725 <smb_panic+0x35> at /usr/local/lib/libsamba-util.so.0
Jan 20 11:01:31 samba-qa-1 smbd[1135]:    #3 0x801470d0a <smb_panic+0x61a> at /usr/local/lib/libsamba-util.so.0
Jan 20 11:01:31 samba-qa-1 smbd[1135]:    #4 0x8014706e3 <fault_setup+0x73> at /usr/local/lib/libsamba-util.so.0
Jan 20 11:01:31 samba-qa-1 smbd[1135]:    #5 0x80472b40b <_swapcontext+0x15b> at /lib/libthr.so.3
Jan 20 11:01:31 samba-qa-1 smbd[1135]:    #6 0x80472aff3 <sigaction+0x343> at /lib/libthr.so.3
Jan 20 11:01:31 samba-qa-1 smbd[1135]: [2015/01/20 11:01:31.155952,  0] ../source3/lib/dumpcore.c:312(dump_core)
Jan 20 11:01:31 samba-qa-1 smbd[1135]:   unable to change to %N.core
Jan 20 11:01:31 samba-qa-1 smbd[1135]:   refusing to dump core
Jan 20 11:01:31 samba-qa-1 smbd[1136]:   STATUS=daemon 'smbd' finished starting up and ready to serve connections===============================================================
Jan 20 11:01:31 samba-qa-1 smbd[1136]: [2015/01/20 11:01:31.446076,  0] ../lib/util/fault.c:73(fault_report)
Jan 20 11:01:31 samba-qa-1 smbd[1136]:   INTERNAL ERROR: Signal 11 in pid 1136 (4.1.16)
Jan 20 11:01:31 samba-qa-1 smbd[1136]:   Please read the Trouble-Shooting section of the Samba HOWTO
Jan 20 11:01:31 samba-qa-1 smbd[1136]: [2015/01/20 11:01:31.446121,  0] ../lib/util/fault.c:75(fault_report)
Jan 20 11:01:31 samba-qa-1 smbd[1136]:   ===============================================================


Here is that VM's smb.conf:

root@samba-qa-1:~ # testparm
Load smb config files from /usr/local/etc/smb4.conf
Processing section "[smb_qa]"
Loaded services file OK.
Server role: ROLE_DOMAIN_MEMBER
Press enter to see a dump of your service definitions

[global]
        workgroup = DISCDRIVE
        realm = DISCDRIVE.BAYPHOTO.COM
        server string = samba-qa-1
        security = ADS
        obey pam restrictions = Yes
        kerberos method = secrets and keytab
        log file = /var/log/samba4/log.%m
        max log size = 50
        server min protocol = NT1
        client max protocol = SMB3
        client min protocol = NT1
        local master = No
        domain master = No
        dns proxy = No
        wins server = dc-01.discdrive.bayphoto.com
        template shell = /bin/zsh
        winbind enum users = Yes
        winbind enum groups = Yes
        winbind use default domain = Yes
        winbind nss info = rfc2307
        idmap config BAYPHOTO : base_rid = 0
        idmap config BAYPHOTO: backend = rid
        idmap config BAYPHOTO: range = 10000-20000
        idmap config DISCDRIVE : base_rid = 0
        idmap config DISCDRIVE: backend = rid
        idmap config DISCDRIVE: range = 20001-30000
        idmap config *:range = 10001-30000
        idmap config * : backend = tdb
        admin users = "@DISCDRIVE\Domain Admins"
        write list = "@DISCDRIVE\Domain Users"
        hosts allow = 10.250., 10.5.68., 10.29., 10.26., 10.30., 10.7.1., 127.0.0.1

[smb_qa]
        path = /data/smb_qa
        admin users = "@domain admins"
        read only = No
        create mask = 0775
        directory mask = 0775
        inherit permissions = Yes
        inherit acls = Yes
        inherit owner = Yes
        guest ok = Yes
        map acl inherit = Yes
        map archive = No
        map readonly = no
        store dos attributes = Yes
        csc policy = disable
        strict locking = No
        vfs objects = zfsacl, shadow_copy2
        nfs4:mode = special
        nfs4:acedup = merge
        nfs4:chown = yes
        shadow: snapdir = .zfs/snapshot
        shadow: sort = desc
        shadow: format = %Y-%m-%d_%H.%M.%S--5d
Comment 1 Jeremy Allison 2015-01-21 00:27:12 UTC
Can you get os-level info on the how many file descriptors are open by which smbd's. It's possible you've found an fd leak but we're not currently aware of any.
Comment 2 Mike Carlson 2015-01-21 01:20:08 UTC
Created attachment 10640 [details]
smbd open fds in directory with 50k files

procstat output of smbd while I enter a directory with 50K files (worked for one user)
Comment 3 Mike Carlson 2015-01-21 01:27:06 UTC
Created attachment 10641 [details]
smbd open fds in directory with 100k files

procstat of my smbd process while I entered a share with 100K files in it

This was not successful, resulted in the samba error message:

Jan 20 17:17:47 samba-qa-1 smbd[2419]: [2015/01/20 17:17:47.550923,  0] ../source3/smbd/open.c:396(fd_open)
Jan 20 17:17:47 samba-qa-1 smbd[2419]:   Too many open files, unable to open more!  smbd's max open files = 58329


If I increase smb.conf's parameter max open files = 110000, and, adjust kern.maxfilesperproc, one user can access the directory with 100k files. Nothing higher (200k files in one directory)
Comment 4 Mike Carlson 2015-01-21 01:46:57 UTC
I did the same procstat check on one of the servers running 3.6, and it looks totally different

4.1 looks like it allocates a new FD for each file, whereas 3.6 has one FD with a growing offsite size:

root@zfs-3:/root # ls -al /data/ROES_ORDERS | wc -l
   69738

procstat -f 74381
  PID COMM               FD T V FLAGS     REF  OFFSET PRO NAME        
74381 smbd             text v r r--------   -       - -   /usr/local/sbin/smbd
74381 smbd              cwd v d r--------   -       - -   /data/ROES_ORDERS 
74381 smbd             root v d r--------   -       - -   /                 
74381 smbd                0 v c rw-------   1       0 -   /dev/null         
74381 smbd                1 v c rw-------   1       0 -   /dev/null         
74381 smbd                2 v r -wa------   2       0 -   /var/log/samba/log.smbd
74381 smbd                3 v r rw-------  30     168 -   /var/db/samba/messages.tdb
74381 smbd                4 v c r--------  30   73279 -   /dev/random       
74381 smbd                5 v r rw-------  30     168 -   /usr/local/etc/samba/secrets.tdb
74381 smbd                6 p - rw---n---   1       0 -   -                 
74381 smbd                7 p - rw---n---   1       0 -   -                 
74381 smbd                8 s - rw-------   1       0 TCP 10.5.68.210:445 10.5.68.46:58654
74381 smbd                9 v r -w---n---  30       5 -   -                 
74381 smbd               10 v r rw-------  30     168 -   /var/db/samba/sessionid.tdb
74381 smbd               11 v r rw-------  30     168 -   /var/db/samba/connections.tdb
74381 smbd               12 v r rw-------  30     168 -   /var/db/samba/brlock.tdb
74381 smbd               13 v r rw-------  30     168 -   /var/db/samba/locking.tdb
74381 smbd               14 v r rw-------  30     168 -   /var/db/samba/notify.tdb
74381 smbd               15 v r rw-------  30     168 -   /var/db/samba/notify_onelevel.tdb
74381 smbd               16 v r rw-------  30     168 -   /var/db/samba/serverid.tdb
74381 smbd               17 v r rw-------  30     168 -   /var/db/samba/printer_list.tdb
74381 smbd               18 v r rw-------  30     168 -   /var/db/samba/share_info.tdb
74381 smbd               19 v r rw-------  30     168 -   /usr/local/etc/samba/passdb.tdb
74381 smbd               20 v r rw-------  30     168 -   /var/db/samba/group_mapping.tdb
74381 smbd               21 v r rw-------  30     696 -   /var/db/samba/gencache.tdb
74381 smbd               22 v r rw-------  30     168 -   /var/db/samba/gencache_notrans.tdb
74381 smbd               23 v r rw-------  30     168 -   /var/db/samba/account_policy.tdb
74381 smbd               24 s - rw-------  29       0 UDD /var/run/logpriv
74381 smbd               25 p - rw-------  29       0 -   -                 
74381 smbd               26 p - rw---n---  30       0 -   -                 
74381 smbd               27 p - rw---n---  30       0 -   -                 
74381 smbd               29 p - rw---n---   1       0 -   -                 
74381 smbd               30 p - rw---n---   1       0 -   -                 
74381 smbd               31 v r rw-------   1     168 -   /var/db/samba/netsamlogon_cache.tdb
74381 smbd               32 s - rw---n---   1       0 UDS /var/db/samba/winbindd_privileged/pipe
74381 smbd               33 v d r--------   1       0 -   /data/ROES_ORDERS 
74381 smbd               34 s - rw---n---   1       0 UDS /var/db/samba/winbindd_privileged/pipe
74381 smbd               35 v r -wa------   2       0 -   /var/log/samba/log.smbd
74381 smbd               36 v d r--------   1       0 -   /data/ROES_ORDERS 
74381 smbd               37 v d r----n---   1 302959089 -   /data/ROES_ORDERS
Comment 5 Jeremy Allison 2015-01-21 01:52:29 UTC
That's the symptom of an fd leak. We shouldn't keep files open when listing the directory. Any chance you can run this repeatably with an smbclient driver and set some breakpoints on fd_open()/fd_close ?
Comment 6 Mike Carlson 2015-01-21 02:01:59 UTC
I would love too, however, I don't know to do that :)

Are there steps documented to perform that task? Do you need ssh access?
Comment 7 Volker Lendecke 2015-01-21 07:10:26 UTC
(In reply to Mike Carlson from comment #6)

Maybe truss output also helps already.

truss -p <smbd-pid> -o /tmp/smbd.out

while it's going mad might reveal something.
Comment 8 Mike Carlson 2015-01-21 17:59:55 UTC
Truss did not seem to provide any useful information:

cat /tmp/smbd.out
readv(0x23,0x813448148,0x1,0x813448138,0x8019df8ba,0xaaa9176e) = 4 (0x4)
readv(0x23,0x813448148,0x1,0x813448138,0x8019df8ba,0xaaa9176e) = 121 (0x79)
gettimeofday({1421862561.544477 },0x0)           = 0 (0x0)
geteuid()                                        = 0 (0x0)
getegid()                                        = 0 (0x0)
__sysctl(0x7fffffffca60,0x2,0x7fffffffca5c,0x7fffffffca68,0x0,0x0) = 0 (0x0)
Comment 9 Mike Carlson 2015-01-21 18:36:44 UTC
I used the smbclient (4.1.16) to connect to the samba-qa-1 server, and I had no issues listing the directories with 100K, and 200k files
Comment 10 Jeremy Allison 2015-01-21 18:44:11 UTC
Oh that's interesting. Did you use smbclient -mSMB3 to ensure it's using the most modern protocol ?
Comment 11 Mike Carlson 2015-01-21 19:06:27 UTC
(In reply to Jeremy Allison from comment #10)
using -mSMB3 (and SMB2) works as well
Comment 12 Jeremy Allison 2015-01-22 01:00:45 UTC
Ok, that's interesting. smbclient won't attempt any shadow copy lookups.

Can you test Windows clients after removing the shadow_copy2 entry from the vfs objects = line in your smb.conf and see if you have the same problem ?

If Windows clients work without shadow_copy2, at least we know where to look.
Comment 13 Mike Carlson 2015-01-22 01:07:50 UTC
(In reply to Jeremy Allison from comment #12)

I removed the shadow copy entries, restarted samba, but I had the same issue in Windows Explorer. FD's still leaked.

Also, our production servers have never used the shadow_copy2 module, we were testing it out on that samba-qa-1 server as a potential user storage enhancement.
Comment 14 Jeremy Allison 2015-01-22 19:32:15 UTC
Ok, if without shadow_copy Windows clients leak fd's, but smbclient clients using -mSMB2 do not, then we have a comparison to make.

As it's happening just listing directories (I'm assuming), it should happen when listing small directories as well as long ones.

So create a small directory (10 files), set the debug log level to 10, list it with smbclient -mSMB2. Check system level fd usage to ensure it doesn't go up. Save off that log file, then clean it up. Restart smbd and to exactly the same with a Windows client. Check system level fd usage before and after to ensure it *does* go up. Then attach both 'success-noleak' and 'fail-leak' log files to this bug report.

Make sure you get *all* the log data, from initial login to end of directory listing.
Comment 15 Mike Carlson 2015-01-23 01:41:57 UTC
Created attachment 10650 [details]
level 10 log files for successful smbclient connection

Steps used:

Server:
winbindd -d 10 -s /usr/local/etc/smb4.conf
smbd -d 10 -s /usr/local/etc/smb4.conf

client:

kinit mikec
smbclient -d 3 -k -mSMB2 //samba-qa-1/smb_qa
lp_load_ex: refreshing parameters
Initialising global parameters
params.c:pm_process() - Processing configuration file "/usr/local/etc/smb4.conf"
Processing section "[global]"
WARNING: The "idmap uid" option is deprecated
WARNING: The "idmap gid" option is deprecated
WARNING: The "idmap backend" option is deprecated
params.c:pm_process() - Processing configuration file "/usr/local/etc/smb.conf.local"
added interface em0 ip=10.250.12.63 bcast=10.250.13.255 netmask=255.255.254.0
Client started (version 4.1.11).
tdb(/var/db/samba4/gencache.tdb): tdb_open_ex: could not open file /var/db/samba4/gencache.tdb: Permission denied
resolve_lmhosts: Attempting lmhosts lookup for name samba-qa-1<0x20>
resolve_lmhosts: Attempting lmhosts lookup for name samba-qa-1<0x20>
resolve_wins: using WINS server 10.5.68.12 and tag '*'
resolve_hosts: Attempting host lookup for name samba-qa-1<0x20>
Connecting to 10.5.68.127 at port 445
Doing spnego session setup (blob length=96)
got OID=1.2.840.48018.1.2.2
got OID=1.2.840.113554.1.2.2
got OID=1.3.6.1.4.1.311.2.2.10
got principal=not_defined_in_RFC4178@please_ignore
cli_session_setup_spnego: using target hostname not SPNEGO principal
cli_session_setup_spnego: guessed server principal=cifs/samba-qa-1@DISCDRIVE.BAYPHOTO.COM
Doing kerberos session setup
ads_cleanup_expired_creds: Ticket in ccache[FILE:/tmp/krb5cc_21208] expiration Fri, 23 Jan 2015 03:30:27 PST
smb: \> ls
  .                                   D        0  Thu Jan 22 14:37:10 2015
  ..                                  D        0  Thu Nov 13 13:56:01 2014
  10k_file_test                       D        0  Tue Jan 20 10:28:31 2015
  50k_file_test                       D        0  Tue Jan 20 10:29:16 2015
  20_files_test                       D        0  Thu Jan 22 14:39:38 2015
  test_file_version.txt               A       19  Mon Dec  8 15:03:18 2014
  100k_file_test                      D        0  Tue Jan 20 10:30:00 2015
  200k_file_test                      D        0  Tue Jan 20 10:38:30 2015
  testing_from_svmike                 D        0  Thu Nov 13 13:57:30 2014
  testing_from_mikec                  D        0  Thu Nov 13 13:57:02 2014

		20108749 blocks of size 1024. 19856914 blocks available
Total bytes listed: 19
smb: \> cd 20_files_test\
dos_clean_name [\20_files_test\]
unix_clean_name [\20_files_test\]
smb: \20_files_test\> ls
  .                                   D        0  Thu Jan 22 14:39:38 2015
  ..                                  D        0  Thu Jan 22 14:37:10 2015
  xaaaaaaaaai                         N        1  Thu Jan 22 14:39:03 2015
  xaaaaaaaaac                         N        1  Thu Jan 22 14:38:54 2015
  xaaaaaaaaan                         N        1  Thu Jan 22 14:39:14 2015
  xaaaaaaaaad                         N        1  Thu Jan 22 14:38:55 2015
  xaaaaaaaaap                         N        1  Thu Jan 22 14:39:32 2015
  xaaaaaaaaaj                         N        1  Thu Jan 22 14:39:06 2015
  xaaaaaaaaat                         N        1  Thu Jan 22 14:39:38 2015
  xaaaaaaaaas                         N        1  Thu Jan 22 14:39:37 2015
  xaaaaaaaaag                         N        1  Thu Jan 22 14:39:00 2015
  xaaaaaaaaam                         N        1  Thu Jan 22 14:39:11 2015
  xaaaaaaaaae                         N        1  Thu Jan 22 14:38:57 2015
  xaaaaaaaaao                         N        1  Thu Jan 22 14:39:17 2015
  xaaaaaaaaaq                         N        1  Thu Jan 22 14:39:34 2015
  xaaaaaaaaab                         N        1  Thu Jan 22 14:38:52 2015
  xaaaaaaaaah                         N        1  Thu Jan 22 14:39:02 2015
  xaaaaaaaaar                         N        1  Thu Jan 22 14:39:36 2015
  xaaaaaaaaal                         N        1  Thu Jan 22 14:39:10 2015
  xaaaaaaaaaf                         N        1  Thu Jan 22 14:38:58 2015
  xaaaaaaaaak                         N        1  Thu Jan 22 14:39:08 2015
  xaaaaaaaaaa                         N        1  Thu Jan 22 14:38:47 2015

		20108749 blocks of size 1024. 19856914 blocks available
Total bytes listed: 20
smb: \20_files_test\> SMBecho failed (NT_STATUS_CONNECTION_DISCONNECTED). The connection is disconnected now
Comment 16 Mike Carlson 2015-01-23 01:43:29 UTC
Created attachment 10651 [details]
level 10 log files for failed smbclient connection

Log level 10

Steps used:

Server:
winbindd -d 10 -s /usr/local/etc/smb4.conf
smbd -d 10 -s /usr/local/etc/smb4.conf


Client (Windows)
Opened up UNC path to:

\\samba-qa-1\smb_qa

Entered directory \20_files_test\
Comment 17 Volker Lendecke 2015-01-25 10:36:51 UTC
(In reply to Mike Carlson from comment #16)

max log size = 50

rotates logfiles too quickly. Please for your test set that to 0.

Also, have you been able to do the truss?

Thanks,

Volker
Comment 18 Mike Carlson 2015-01-29 20:39:55 UTC
(In reply to Volker Lendecke from comment #17)
here is the truss output, I also set log level to 0

truss output for a windows client accessing \\samba-qa-1\smb_qa:

readv(0x24,0x813491ec8,0x1,0x813491eb8,0x8019df8ba,0xaaa9176e) = 4 (0x4)
readv(0x24,0x813491ec8,0x1,0x813491eb8,0x8019df8ba,0xaaa9176e) = 68 (0x44)
gettimeofday({1422563525.012462 },0x0)		 = 0 (0x0)
getpid()					 = 68676 (0x10c44)
geteuid()					 = 0 (0x0)
getegid()					 = 0 (0x0)
getuid()					 = 0 (0x0)
getgid()					 = 0 (0x0)
gettimeofday({1422563525.012975 },0x0)		 = 0 (0x0)
geteuid()					 = 0 (0x0)
write(32,"[2015/01/29 12:32:05.012975, 10,"...,130) = 130 (0x82)
geteuid()					 = 0 (0x0)
write(32,"  smbd_smb2_request idx[1] of 5 "...,40) = 40 (0x28)
getpid()					 = 68676 (0x10c44)
geteuid()					 = 0 (0x0)
getegid()					 = 0 (0x0)
getuid()					 = 0 (0x0)
getgid()					 = 0 (0x0)
gettimeofday({1422563525.013976 },0x0)		 = 0 (0x0)
geteuid()					 = 0 (0x0)
write(32,"[2015/01/29 12:32:05.013976, 10,"...,136) = 136 (0x88)
geteuid()					 = 0 (0x0)
write(32,"  smbd_smb2_request_dispatch: op"...,61) = 61 (0x3d)
getpid()					 = 68676 (0x10c44)
geteuid()					 = 0 (0x0)
getegid()					 = 0 (0x0)
getuid()					 = 0 (0x0)
getgid()					 = 0 (0x0)
gettimeofday({1422563525.014800 },0x0)		 = 0 (0x0)
geteuid()					 = 0 (0x0)
write(32,"[2015/01/29 12:32:05.014800,  4,"...,116) = 116 (0x74)
geteuid()					 = 0 (0x0)
write(32,"  setting sec ctx (0, 0) - sec_c"...,49) = 49 (0x31)
getpid()					 = 68676 (0x10c44)
geteuid()					 = 0 (0x0)
getegid()					 = 0 (0x0)
getuid()					 = 0 (0x0)
getgid()					 = 0 (0x0)
gettimeofday({1422563525.015509 },0x0)		 = 0 (0x0)
geteuid()					 = 0 (0x0)
write(32,"[2015/01/29 12:32:05.015509,  5,"...,134) = 134 (0x86)
geteuid()					 = 0 (0x0)
write(32,"  Security token: (NULL)\n",25)	 = 25 (0x19)
getpid()					 = 68676 (0x10c44)
geteuid()					 = 0 (0x0)
getegid()					 = 0 (0x0)
getuid()					 = 0 (0x0)
getgid()					 = 0 (0x0)
gettimeofday({1422563525.016220 },0x0)		 = 0 (0x0)
geteuid()					 = 0 (0x0)
write(32,"[2015/01/29 12:32:05.016220,  5,"...,129) = 129 (0x81)
geteuid()					 = 0 (0x0)
write(32,"  UNIX token of user 0\n",23)		 = 23 (0x17)
geteuid()					 = 0 (0x0)
write(32,"  Primary group is 0 and contain"...,57) = 57 (0x39)
geteuid()					 = 0 (0x0)
getegid()					 = 0 (0x0)
__sysctl(0x7fffffffc940,0x2,0x7fffffffc93c,0x7fffffffc948,0x0,0x0) = 0 (0x0)
SIGNAL 15 (SIGTERM)
sigprocmask(SIG_SETMASK,SIGFPE|SIGPIPE|SIGTERM|SIGUSR2,0x0) = 0 (0x0)
setgroups(0x1,0x7fffffffc9e8,0x7fffffffc93c,0x7fffffffc948,0x0,0x0) = 1 (0x1)
write(7,"\0",1)					 = 1 (0x1)
sigreturn(0x7fffffbfd500,0x7fffffbfd500,0x300,0x0,0xfffffffffffffbc0,0x0) ERR#4 'Interrupted system call'
getpid()					 = 68676 (0x10c44)
geteuid()					 = 0 (0x0)
getegid()					 = 0 (0x0)
getuid()					 = 0 (0x0)
getgid()					 = 0 (0x0)
gettimeofday({1422563584.526627 },0x0)		 = 0 (0x0)
geteuid()					 = 0 (0x0)
write(32,"[2015/01/29 12:33:04.526627,  4,"...,116) = 116 (0x74)
geteuid()					 = 0 (0x0)
write(32,"  setting sec ctx (0, 0) - sec_c"...,49) = 49 (0x31)
getpid()					 = 68676 (0x10c44)
geteuid()					 = 0 (0x0)
getegid()					 = 0 (0x0)
getuid()					 = 0 (0x0)
getgid()					 = 0 (0x0)
gettimeofday({1422563584.527048 },0x0)		 = 0 (0x0)
geteuid()					 = 0 (0x0)
write(32,"[2015/01/29 12:33:04.527048,  5,"...,134) = 134 (0x86)
geteuid()					 = 0 (0x0)
write(32,"  Security token: (NULL)\n",25)	 = 25 (0x19)
getpid()					 = 68676 (0x10c44)
geteuid()					 = 0 (0x0)
getegid()					 = 0 (0x0)
getuid()					 = 0 (0x0)
getgid()					 = 0 (0x0)
gettimeofday({1422563584.527469 },0x0)		 = 0 (0x0)
geteuid()					 = 0 (0x0)
write(32,"[2015/01/29 12:33:04.527469,  5,"...,129) = 129 (0x81)
geteuid()					 = 0 (0x0)
write(32,"  UNIX token of user 0\n",23)		 = 23 (0x17)
geteuid()					 = 0 (0x0)
write(32,"  Primary group is 0 and contain"...,57) = 57 (0x39)
geteuid()					 = 0 (0x0)
getegid()					 = 0 (0x0)
__sysctl(0x7fffffffca50,0x2,0x7fffffffca4c,0x7fffffffca58,0x0,0x0) = 0 (0x0)
SIGNAL 15 (SIGTERM)
sigprocmask(SIG_SETMASK,SIGFPE|SIGPIPE|SIGTERM|SIGUSR2,0x0) = 0 (0x0)
write(7,"\0",1)					 = 1 (0x1)
sigreturn(0x7fffffbfd500,0x7fffffbfd500,0x300,0x0,0xfffffffffffffbc0,0x0) ERR#4 'Interrupted system call'
close(33)					 = 0 (0x0)
read(11,0x81353f000,32768)			 = 0 (0x0)
close(11)					 = 0 (0x0)
open("/etc/pam.d/other",O_RDONLY,0666)		 = 11 (0xb)
geteuid()					 = 0 (0x0)
fstat(11,{ mode=-rw-r--r-- ,inode=323950,size=671,blksize=32768 }) = 0 (0x0)
fstat(11,{ mode=-rw-r--r-- ,inode=323950,size=671,blksize=32768 }) = 0 (0x0)
read(11,"#\n# $FreeBSD: release/10.0.0/et"...,32768) = 671 (0x29f)
open("/usr/lib/pam_nologin.so.5",O_RDONLY,00)	 = 33 (0x21)
geteuid()					 = 0 (0x0)
fstat(33,{ mode=-r--r--r-- ,inode=480921,size=6096,blksize=32768 }) = 0 (0x0)
fcntl(33,0x11,0x0)				 = 39 (0x27)
fstat(39,{ mode=-r--r--r-- ,inode=480921,size=6096,blksize=32768 }) = 0 (0x0)
mmap(0x0,4096,PROT_READ,MAP_PRIVATE|MAP_PREFAULT_READ,39,0x0) = 34380173312 (0x80137d000)
mmap(0x0,2101248,PROT_NONE,MAP_PRIVATE|MAP_ANON|MAP_NOCORE,-1,0x0) = 34737336320 (0x81681b000)
mmap(0x81681b000,4096,PROT_READ|PROT_EXEC,MAP_PRIVATE|MAP_FIXED|MAP_NOCORE|MAP_PREFAULT_READ,39,0x0) = 34737336320 (0x81681b000)
mmap(0x816a1b000,4096,PROT_READ|PROT_WRITE,MAP_PRIVATE|MAP_FIXED|MAP_PREFAULT_READ,39,0x0) = 34739433472 (0x816a1b000)
munmap(0x80137d000,4096)			 = 0 (0x0)
close(39)					 = 0 (0x0)
close(33)					 = 0 (0x0)
open("/usr/lib/pam_login_access.so.5",O_RDONLY,00) = 33 (0x21)
geteuid()					 = 0 (0x0)
fstat(33,{ mode=-r--r--r-- ,inode=480920,size=9296,blksize=32768 }) = 0 (0x0)
fcntl(33,0x11,0x0)				 = 39 (0x27)
fstat(39,{ mode=-r--r--r-- ,inode=480920,size=9296,blksize=32768 }) = 0 (0x0)
mmap(0x0,4096,PROT_READ,MAP_PRIVATE|MAP_PREFAULT_READ,39,0x0) = 34380173312 (0x80137d000)
mmap(0x0,2105344,PROT_NONE,MAP_PRIVATE|MAP_ANON|MAP_NOCORE,-1,0x0) = 34739437568 (0x816a1c000)
mmap(0x816a1c000,8192,PROT_READ|PROT_EXEC,MAP_PRIVATE|MAP_FIXED|MAP_NOCORE|MAP_PREFAULT_READ,39,0x0) = 34739437568 (0x816a1c000)
mmap(0x816c1d000,4096,PROT_READ|PROT_WRITE,MAP_PRIVATE|MAP_FIXED|MAP_PREFAULT_READ,39,0x1000) = 34741538816 (0x816c1d000)
munmap(0x80137d000,4096)			 = 0 (0x0)
close(39)					 = 0 (0x0)
close(33)					 = 0 (0x0)
open("/usr/lib/pam_unix.so.5",O_RDONLY,00)	 = 33 (0x21)
geteuid()					 = 0 (0x0)
fstat(33,{ mode=-r--r--r-- ,inode=480938,size=12528,blksize=32768 }) = 0 (0x0)
fcntl(33,0x11,0x0)				 = 39 (0x27)
fstat(39,{ mode=-r--r--r-- ,inode=480938,size=12528,blksize=32768 }) = 0 (0x0)
mmap(0x0,4096,PROT_READ,MAP_PRIVATE|MAP_PREFAULT_READ,39,0x0) = 34380173312 (0x80137d000)
mmap(0x0,2109440,PROT_NONE,MAP_PRIVATE|MAP_ANON|MAP_NOCORE,-1,0x0) = 34741542912 (0x816c1e000)
mmap(0x816c1e000,12288,PROT_READ|PROT_EXEC,MAP_PRIVATE|MAP_FIXED|MAP_NOCORE|MAP_PREFAULT_READ,39,0x0) = 34741542912 (0x816c1e000)
mmap(0x816e20000,4096,PROT_READ|PROT_WRITE,MAP_PRIVATE|MAP_FIXED|MAP_PREFAULT_READ,39,0x2000) = 34743648256 (0x816e20000)
munmap(0x80137d000,4096)			 = 0 (0x0)
close(39)					 = 0 (0x0)
mmap(0x0,36864,PROT_READ|PROT_WRITE,MAP_PRIVATE|MAP_ANON,-1,0x0) = 34380173312 (0x80137d000)
close(33)					 = 0 (0x0)
read(11,0x81353f000,32768)			 = 0 (0x0)
close(11)					 = 0 (0x0)
open("/etc/pam.d/other",O_RDONLY,0666)		 = 11 (0xb)
geteuid()					 = 0 (0x0)
fstat(11,{ mode=-rw-r--r-- ,inode=323950,size=671,blksize=32768 }) = 0 (0x0)
fstat(11,{ mode=-rw-r--r-- ,inode=323950,size=671,blksize=32768 }) = 0 (0x0)
read(11,"#\n# $FreeBSD: release/10.0.0/et"...,32768) = 671 (0x29f)
open("/usr/lib/pam_permit.so.5",O_RDONLY,00)	 = 33 (0x21)
geteuid()					 = 0 (0x0)
fstat(33,{ mode=-r--r--r-- ,inode=480930,size=4576,blksize=32768 }) = 0 (0x0)
fcntl(33,0x11,0x0)				 = 39 (0x27)
fstat(39,{ mode=-r--r--r-- ,inode=480930,size=4576,blksize=32768 }) = 0 (0x0)
mmap(0x0,4096,PROT_READ,MAP_PRIVATE|MAP_PREFAULT_READ,39,0x0) = 34380210176 (0x801386000)
mmap(0x0,2101248,PROT_NONE,MAP_PRIVATE|MAP_ANON|MAP_NOCORE,-1,0x0) = 34743652352 (0x816e21000)
mmap(0x816e21000,4096,PROT_READ|PROT_EXEC,MAP_PRIVATE|MAP_FIXED|MAP_NOCORE|MAP_PREFAULT_READ,39,0x0) = 34743652352 (0x816e21000)
mmap(0x817021000,4096,PROT_READ|PROT_WRITE,MAP_PRIVATE|MAP_FIXED|MAP_PREFAULT_READ,39,0x0) = 34745749504 (0x817021000)
munmap(0x801386000,4096)			 = 0 (0x0)
close(39)					 = 0 (0x0)
close(33)					 = 0 (0x0)
read(11,0x81353f000,32768)			 = 0 (0x0)
close(11)					 = 0 (0x0)
open("/etc/pam.d/other",O_RDONLY,0666)		 = 11 (0xb)
geteuid()					 = 0 (0x0)
fstat(11,{ mode=-rw-r--r-- ,inode=323950,size=671,blksize=32768 }) = 0 (0x0)
fstat(11,{ mode=-rw-r--r-- ,inode=323950,size=671,blksize=32768 }) = 0 (0x0)
read(11,"#\n# $FreeBSD: release/10.0.0/et"...,32768) = 671 (0x29f)
open("/usr/lib/pam_permit.so.5",O_RDONLY,00)	 = 33 (0x21)
geteuid()					 = 0 (0x0)
fstat(33,{ mode=-r--r--r-- ,inode=480930,size=4576,blksize=32768 }) = 0 (0x0)
fcntl(33,0x11,0x0)				 = 39 (0x27)
fstat(39,{ mode=-r--r--r-- ,inode=480930,size=4576,blksize=32768 }) = 0 (0x0)
mmap(0x0,4096,PROT_READ,MAP_PRIVATE|MAP_PREFAULT_READ,39,0x0) = 34380210176 (0x801386000)
mmap(0x0,2101248,PROT_NONE,MAP_PRIVATE|MAP_ANON|MAP_NOCORE,-1,0x0) = 34745753600 (0x817022000)
mmap(0x817022000,4096,PROT_READ|PROT_EXEC,MAP_PRIVATE|MAP_FIXED|MAP_NOCORE|MAP_PREFAULT_READ,39,0x0) = 34745753600 (0x817022000)
mmap(0x817222000,4096,PROT_READ|PROT_WRITE,MAP_PRIVATE|MAP_FIXED|MAP_PREFAULT_READ,39,0x0) = 34747850752 (0x817222000)
munmap(0x801386000,4096)			 = 0 (0x0)
close(39)					 = 0 (0x0)
close(33)					 = 0 (0x0)
read(11,0x81353f000,32768)			 = 0 (0x0)
close(11)					 = 0 (0x0)
getpid()					 = 68676 (0x10c44)
geteuid()					 = 0 (0x0)
getegid()					 = 0 (0x0)
getuid()					 = 0 (0x0)
getgid()					 = 0 (0x0)
gettimeofday({1422563584.544240 },0x0)		 = 0 (0x0)
geteuid()					 = 0 (0x0)
write(32,"[2015/01/29 12:33:04.544240,  4,"...,130) = 130 (0x82)
geteuid()					 = 0 (0x0)
write(32,"  smb_pam_start: PAM: setting rh"...,51) = 51 (0x33)
getpid()					 = 68676 (0x10c44)
geteuid()					 = 0 (0x0)
getegid()					 = 0 (0x0)
getuid()					 = 0 (0x0)
getgid()					 = 0 (0x0)
gettimeofday({1422563584.544651 },0x0)		 = 0 (0x0)
geteuid()					 = 0 (0x0)
write(32,"[2015/01/29 12:33:04.544651,  4,"...,130) = 130 (0x82)
geteuid()					 = 0 (0x0)
write(32,"  smb_pam_start: PAM: setting tt"...,34) = 34 (0x22)
getpid()					 = 68676 (0x10c44)
geteuid()					 = 0 (0x0)
getegid()					 = 0 (0x0)
getuid()					 = 0 (0x0)
getgid()					 = 0 (0x0)
gettimeofday({1422563584.545070 },0x0)		 = 0 (0x0)
geteuid()					 = 0 (0x0)
write(32,"[2015/01/29 12:33:04.545070,  4,"...,130) = 130 (0x82)
geteuid()					 = 0 (0x0)
write(32,"  smb_pam_start: PAM: Init passe"...,60) = 60 (0x3c)
getpid()					 = 68676 (0x10c44)
geteuid()					 = 0 (0x0)
getegid()					 = 0 (0x0)
getuid()					 = 0 (0x0)
getgid()					 = 0 (0x0)
gettimeofday({1422563584.545496 },0x0)		 = 0 (0x0)
geteuid()					 = 0 (0x0)
write(32,"[2015/01/29 12:33:04.545496,  4,"...,141) = 141 (0x8d)
geteuid()					 = 0 (0x0)
write(32,"  smb_internal_pam_session: PAM:"...,60) = 60 (0x3c)
munmap(0x816201000,2109440)			 = 0 (0x0)
munmap(0x816000000,2101248)			 = 0 (0x0)
munmap(0x815425000,2105344)			 = 0 (0x0)
munmap(0x816616000,2117632)			 = 0 (0x0)
munmap(0x816c1e000,2109440)			 = 0 (0x0)
munmap(0x816a1c000,2105344)			 = 0 (0x0)
munmap(0x816404000,2170880)			 = 0 (0x0)
munmap(0x81681b000,2101248)			 = 0 (0x0)
munmap(0x816e21000,2101248)			 = 0 (0x0)
munmap(0x817022000,2101248)			 = 0 (0x0)
getpid()					 = 68676 (0x10c44)
geteuid()					 = 0 (0x0)
getegid()					 = 0 (0x0)
getuid()					 = 0 (0x0)
getgid()					 = 0 (0x0)
gettimeofday({1422563584.546517 },0x0)		 = 0 (0x0)
geteuid()					 = 0 (0x0)
write(32,"[2015/01/29 12:33:04.546517,  4,"...,128) = 128 (0x80)
geteuid()					 = 0 (0x0)
write(32,"  smb_pam_end: PAM: PAM_END OK."...,32) = 32 (0x20)
getpid()					 = 68676 (0x10c44)
geteuid()					 = 0 (0x0)
getegid()					 = 0 (0x0)
getuid()					 = 0 (0x0)
getgid()					 = 0 (0x0)
gettimeofday({1422563584.546940 },0x0)		 = 0 (0x0)
geteuid()					 = 0 (0x0)
write(32,"[2015/01/29 12:33:04.546940,  4,"...,116) = 116 (0x74)
geteuid()					 = 0 (0x0)
write(32,"  setting sec ctx (0, 0) - sec_c"...,49) = 49 (0x31)
getpid()					 = 68676 (0x10c44)
geteuid()					 = 0 (0x0)
getegid()					 = 0 (0x0)
getuid()					 = 0 (0x0)
getgid()					 = 0 (0x0)
gettimeofday({1422563584.547339 },0x0)		 = 0 (0x0)
geteuid()					 = 0 (0x0)
write(32,"[2015/01/29 12:33:04.547339,  5,"...,134) = 134 (0x86)
geteuid()					 = 0 (0x0)
write(32,"  Security token: (NULL)\n",25)	 = 25 (0x19)
getpid()					 = 68676 (0x10c44)
geteuid()					 = 0 (0x0)
getegid()					 = 0 (0x0)
getuid()					 = 0 (0x0)
getgid()					 = 0 (0x0)
gettimeofday({1422563584.547751 },0x0)		 = 0 (0x0)
geteuid()					 = 0 (0x0)
write(32,"[2015/01/29 12:33:04.547751,  5,"...,129) = 129 (0x81)
geteuid()					 = 0 (0x0)
write(32,"  UNIX token of user 0\n",23)		 = 23 (0x17)
geteuid()					 = 0 (0x0)
write(32,"  Primary group is 0 and contain"...,57) = 57 (0x39)
geteuid()					 = 0 (0x0)
getegid()					 = 0 (0x0)
__sysctl(0x7fffffffca50,0x2,0x7fffffffca4c,0x7fffffffca58,0x0,0x0) = 0 (0x0)
process exit, rval = 0





Here is the truss output of using smbclient on a freebsd client, with no FD leaks:

gettimeofday({1422563741.702207 },0x0)		 = 0 (0x0)
gettimeofday({1422563741.702365 },0x0)		 = 0 (0x0)
gettimeofday({1422563741.702459 },0x0)		 = 0 (0x0)
poll({6/POLLIN|POLLHUP 10/POLLIN|POLLHUP 36/POLLIN|POLLHUP},3,36112) = 1 (0x1)
readv(0x24,0x813491ec8,0x1,0x813491eb8,0x8019df8ba,0x804edbb10) = 4 (0x4)
readv(0x24,0x813491ec8,0x1,0x813491eb8,0x8019df8ba,0x804edbb10) = 68 (0x44)
gettimeofday({1422563743.345012 },0x0)		 = 0 (0x0)
getpid()					 = 68733 (0x10c7d)
geteuid()					 = 0 (0x0)
getegid()					 = 0 (0x0)
getuid()					 = 0 (0x0)
getgid()					 = 0 (0x0)
gettimeofday({1422563743.345524 },0x0)		 = 0 (0x0)
geteuid()					 = 0 (0x0)
write(32,"[2015/01/29 12:35:43.345524, 10,"...,130) = 130 (0x82)
geteuid()					 = 0 (0x0)
write(32,"  smbd_smb2_request idx[1] of 5 "...,40) = 40 (0x28)
getpid()					 = 68733 (0x10c7d)
geteuid()					 = 0 (0x0)
getegid()					 = 0 (0x0)
getuid()					 = 0 (0x0)
getgid()					 = 0 (0x0)
gettimeofday({1422563743.346442 },0x0)		 = 0 (0x0)
geteuid()					 = 0 (0x0)
write(32,"[2015/01/29 12:35:43.346442, 10,"...,138) = 138 (0x8a)
geteuid()					 = 0 (0x0)
write(32,"  smb2_validate_sequence_number:"...,74) = 74 (0x4a)
getpid()					 = 68733 (0x10c7d)
geteuid()					 = 0 (0x0)
getegid()					 = 0 (0x0)
getuid()					 = 0 (0x0)
getgid()					 = 0 (0x0)
gettimeofday({1422563743.347160 },0x0)		 = 0 (0x0)
geteuid()					 = 0 (0x0)
write(32,"[2015/01/29 12:35:43.347160, 10,"...,136) = 136 (0x88)
geteuid()					 = 0 (0x0)
write(32,"  smbd_smb2_request_dispatch: op"...,65) = 65 (0x41)
getpid()					 = 68733 (0x10c7d)
geteuid()					 = 0 (0x0)
getegid()					 = 0 (0x0)
getuid()					 = 0 (0x0)
getgid()					 = 0 (0x0)
gettimeofday({1422563743.347863 },0x0)		 = 0 (0x0)
geteuid()					 = 0 (0x0)
write(32,"[2015/01/29 12:35:43.347863,  4,"...,116) = 116 (0x74)
geteuid()					 = 0 (0x0)
write(32,"  setting sec ctx (0, 0) - sec_c"...,49) = 49 (0x31)
getpid()					 = 68733 (0x10c7d)
geteuid()					 = 0 (0x0)
getegid()					 = 0 (0x0)
getuid()					 = 0 (0x0)
getgid()					 = 0 (0x0)
gettimeofday({1422563743.348587 },0x0)		 = 0 (0x0)
geteuid()					 = 0 (0x0)
write(32,"[2015/01/29 12:35:43.348587,  5,"...,134) = 134 (0x86)
geteuid()					 = 0 (0x0)
write(32,"  Security token: (NULL)\n",25)	 = 25 (0x19)
getpid()					 = 68733 (0x10c7d)
geteuid()					 = 0 (0x0)
getegid()					 = 0 (0x0)
getuid()					 = 0 (0x0)
getgid()					 = 0 (0x0)
gettimeofday({1422563743.349323 },0x0)		 = 0 (0x0)
geteuid()					 = 0 (0x0)
write(32,"[2015/01/29 12:35:43.349323,  5,"...,129) = 129 (0x81)
geteuid()					 = 0 (0x0)
write(32,"  UNIX token of user 0\n",23)		 = 23 (0x17)
geteuid()					 = 0 (0x0)
write(32,"  Primary group is 0 and contain"...,57) = 57 (0x39)
geteuid()					 = 0 (0x0)
getegid()					 = 0 (0x0)
__sysctl(0x7fffffffc940,0x2,0x7fffffffc93c,0x7fffffffc948,0x0,0x0) = 0 (0x0)
SIGNAL 30 (SIGUSR1)
sigprocmask(SIG_SETMASK,SIGFPE|SIGPIPE|SIGUSR1|SIGUSR2,0x0) = 0 (0x0)
write(7,"\0",1)					 = 1 (0x1)
sigreturn(0x7fffffffc480,0x7fffffffc480,0x301,0x1,0xfffffffffffffbc0,0xaaa9176e) ERR#4 'Interrupted system call'
getpid()					 = 68733 (0x10c7d)
geteuid()					 = 0 (0x0)
getegid()					 = 0 (0x0)
getuid()					 = 0 (0x0)
getgid()					 = 0 (0x0)
gettimeofday({1422563758.220704 },0x0)		 = 0 (0x0)
geteuid()					 = 0 (0x0)
write(32,"[2015/01/29 12:35:58.220704, 10,"...,138) = 138 (0x8a)
geteuid()					 = 0 (0x0)
write(32,"  messaging_tdb_signal_handler: "...,57) = 57 (0x39)
getpid()					 = 68733 (0x10c7d)
geteuid()					 = 0 (0x0)
getegid()					 = 0 (0x0)
getuid()					 = 0 (0x0)
getgid()					 = 0 (0x0)
gettimeofday({1422563758.221182 },0x0)		 = 0 (0x0)
geteuid()					 = 0 (0x0)
write(32,"[2015/01/29 12:35:58.221182, 10,"...,127) = 127 (0x7f)
geteuid()					 = 0 (0x0)
write(32,"  message_dispatch: received_mes"...,42) = 42 (0x2a)
fcntl(3,F_SETLKW,0x7fffffffcbd8)		 = 0 (0x0)
getpid()					 = 68733 (0x10c7d)
geteuid()					 = 0 (0x0)
getegid()					 = 0 (0x0)
getuid()					 = 0 (0x0)
getgid()					 = 0 (0x0)
gettimeofday({1422563758.222022 },0x0)		 = 0 (0x0)
geteuid()					 = 0 (0x0)
write(32,"[2015/01/29 12:35:58.222022, 10,"...,130) = 130 (0x82)
geteuid()					 = 0 (0x0)
write(32,"  messaging_tdb_fetch:\n",23)		 = 23 (0x17)
getpid()					 = 68733 (0x10c7d)
geteuid()					 = 0 (0x0)
getegid()					 = 0 (0x0)
getuid()					 = 0 (0x0)
getgid()					 = 0 (0x0)
gettimeofday({1422563758.222779 },0x0)		 = 0 (0x0)
geteuid()					 = 0 (0x0)
write(32,"[2015/01/29 12:35:58.222779,  1,"...,114) = 114 (0x72)
geteuid()					 = 0 (0x0)
write(32,"       result: struct messaging_"...,38) = 38 (0x26)
geteuid()					 = 0 (0x0)
write(32,"          num_messages          "...,52) = 52 (0x34)
geteuid()					 = 0 (0x0)
write(32,"          messages: ARRAY(1)\n",29)	 = 29 (0x1d)
geteuid()					 = 0 (0x0)
write(32,"              messages: struct m"...,45) = 45 (0x2d)
geteuid()					 = 0 (0x0)
write(32,"                  msg_version   "...,60) = 60 (0x3c)
geteuid()					 = 0 (0x0)
write(32,"                  msg_type      "...,68) = 68 (0x44)
geteuid()					 = 0 (0x0)
write(32,"                  dest: struct s"...,41) = 41 (0x29)
geteuid()					 = 0 (0x0)
write(32,"                      pid       "...,76) = 76 (0x4c)
geteuid()					 = 0 (0x0)
write(32,"                      task_id   "...,64) = 64 (0x40)
geteuid()					 = 0 (0x0)
write(32,"                      vnn       "...,73) = 73 (0x49)
geteuid()					 = 0 (0x0)
write(32,"                      unique_id "...,91) = 91 (0x5b)
geteuid()					 = 0 (0x0)
write(32,"                  src: struct se"...,40) = 40 (0x28)
geteuid()					 = 0 (0x0)
write(32,"                      pid       "...,76) = 76 (0x4c)
geteuid()					 = 0 (0x0)
write(32,"                      task_id   "...,64) = 64 (0x40)
geteuid()					 = 0 (0x0)
write(32,"                      vnn       "...,73) = 73 (0x49)
geteuid()					 = 0 (0x0)
write(32,"                      unique_id "...,90) = 90 (0x5a)
geteuid()					 = 0 (0x0)
write(32,"                  buf           "...,64) = 64 (0x40)
fcntl(3,F_SETLKW,0x7fffffffcc48)		 = 0 (0x0)
getpid()					 = 68733 (0x10c7d)
geteuid()					 = 0 (0x0)
getegid()					 = 0 (0x0)
getuid()					 = 0 (0x0)
getgid()					 = 0 (0x0)
gettimeofday({1422563758.225668 },0x0)		 = 0 (0x0)
geteuid()					 = 0 (0x0)
write(32,"[2015/01/29 12:35:58.225668, 10,"...,138) = 138 (0x8a)
geteuid()					 = 0 (0x0)
write(32,"  messaging_tdb_signal_handler: "...,57) = 57 (0x39)
getpid()					 = 68733 (0x10c7d)
geteuid()					 = 0 (0x0)
getegid()					 = 0 (0x0)
getuid()					 = 0 (0x0)
getgid()					 = 0 (0x0)
gettimeofday({1422563758.226097 },0x0)		 = 0 (0x0)
geteuid()					 = 0 (0x0)
write(32,"[2015/01/29 12:35:58.226097, 10,"...,127) = 127 (0x7f)
geteuid()					 = 0 (0x0)
write(32,"  message_dispatch: received_mes"...,42) = 42 (0x2a)
fcntl(3,F_SETLKW,0x7fffffffcbd8)		 = 0 (0x0)
fcntl(3,F_SETLKW,0x7fffffffcc48)		 = 0 (0x0)
gettimeofday({1422563758.226487 },0x0)		 = 0 (0x0)
gettimeofday({1422563758.226540 },0x0)		 = 0 (0x0)
poll({6/POLLIN|POLLHUP 10/POLLIN|POLLHUP 36/POLLIN|POLLHUP},3,19588) = 1 (0x1)
read(6,"\0",16)					 = 1 (0x1)
gettimeofday({1422563758.226718 },0x0)		 = 0 (0x0)
gettimeofday({1422563758.226773 },0x0)		 = 0 (0x0)
poll({10/POLLIN|POLLHUP 36/POLLIN|POLLHUP 6/POLLIN|POLLHUP},3,19588) = 1 (0x1)
readv(0x24,0x813491ec8,0x1,0x813491eb8,0x8019df8ba,0x804edbb10) = 4 (0x4)
readv(0x24,0x813491ec8,0x1,0x813491eb8,0x8019df8ba,0x804edbb10) = 68 (0x44)
gettimeofday({1422563758.423445 },0x0)		 = 0 (0x0)
getpid()					 = 68733 (0x10c7d)
geteuid()					 = 0 (0x0)
getegid()					 = 0 (0x0)
getuid()					 = 0 (0x0)
getgid()					 = 0 (0x0)
gettimeofday({1422563758.423900 },0x0)		 = 0 (0x0)
geteuid()					 = 0 (0x0)
write(32,"[2015/01/29 12:35:58.423900, 10,"...,130) = 130 (0x82)
geteuid()					 = 0 (0x0)
write(32,"  smbd_smb2_request idx[1] of 5 "...,40) = 40 (0x28)
getpid()					 = 68733 (0x10c7d)
geteuid()					 = 0 (0x0)
getegid()					 = 0 (0x0)
getuid()					 = 0 (0x0)
getgid()					 = 0 (0x0)
gettimeofday({1422563758.424740 },0x0)		 = 0 (0x0)
geteuid()					 = 0 (0x0)
write(32,"[2015/01/29 12:35:58.424740, 10,"...,138) = 138 (0x8a)
geteuid()					 = 0 (0x0)
write(32,"  smb2_validate_sequence_number:"...,74) = 74 (0x4a)
getpid()					 = 68733 (0x10c7d)
geteuid()					 = 0 (0x0)
getegid()					 = 0 (0x0)
getuid()					 = 0 (0x0)
getgid()					 = 0 (0x0)
gettimeofday({1422563758.425435 },0x0)		 = 0 (0x0)
geteuid()					 = 0 (0x0)
write(32,"[2015/01/29 12:35:58.425435, 10,"...,136) = 136 (0x88)
geteuid()					 = 0 (0x0)
write(32,"  smbd_smb2_request_dispatch: op"...,65) = 65 (0x41)
getpid()					 = 68733 (0x10c7d)
geteuid()					 = 0 (0x0)
getegid()					 = 0 (0x0)
getuid()					 = 0 (0x0)
getgid()					 = 0 (0x0)
gettimeofday({1422563758.426183 },0x0)		 = 0 (0x0)
geteuid()					 = 0 (0x0)
write(32,"[2015/01/29 12:35:58.426183,  4,"...,116) = 116 (0x74)
geteuid()					 = 0 (0x0)
write(32,"  setting sec ctx (0, 0) - sec_c"...,49) = 49 (0x31)
getpid()					 = 68733 (0x10c7d)
geteuid()					 = 0 (0x0)
getegid()					 = 0 (0x0)
getuid()					 = 0 (0x0)
getgid()					 = 0 (0x0)
gettimeofday({1422563758.426992 },0x0)		 = 0 (0x0)
geteuid()					 = 0 (0x0)
write(32,"[2015/01/29 12:35:58.426992,  5,"...,134) = 134 (0x86)
geteuid()					 = 0 (0x0)
write(32,"  Security token: (NULL)\n",25)	 = 25 (0x19)
getpid()					 = 68733 (0x10c7d)
geteuid()					 = 0 (0x0)
getegid()					 = 0 (0x0)
getuid()					 = 0 (0x0)
getgid()					 = 0 (0x0)
gettimeofday({1422563758.427714 },0x0)		 = 0 (0x0)
geteuid()					 = 0 (0x0)
write(32,"[2015/01/29 12:35:58.427714,  5,"...,129) = 129 (0x81)
geteuid()					 = 0 (0x0)
write(32,"  UNIX token of user 0\n",23)		 = 23 (0x17)
geteuid()					 = 0 (0x0)
write(32,"  Primary group is 0 and contain"...,57) = 57 (0x39)
geteuid()					 = 0 (0x0)
getegid()					 = 0 (0x0)
__sysctl(0x7fffffffc940,0x2,0x7fffffffc93c,0x7fffffffc948,0x0,0x0) = 0 (0x0)
SIGNAL 15 (SIGTERM)
sigprocmask(SIG_SETMASK,SIGFPE|SIGPIPE|SIGTERM|SIGUSR2,0x0) = 0 (0x0)
write(7,"\0",1)					 = 1 (0x1)
sigreturn(0x7fffffffc480,0x7fffffffc480,0x301,0x1,0xfffffffffffffbc0,0xaaa9176e) ERR#4 'Interrupted system call'
getpid()					 = 68733 (0x10c7d)
geteuid()					 = 0 (0x0)
getegid()					 = 0 (0x0)
getuid()					 = 0 (0x0)
getgid()					 = 0 (0x0)
gettimeofday({1422563759.480944 },0x0)		 = 0 (0x0)
geteuid()					 = 0 (0x0)
write(32,"[2015/01/29 12:35:59.480944,  4,"...,116) = 116 (0x74)
geteuid()					 = 0 (0x0)
write(32,"  setting sec ctx (0, 0) - sec_c"...,49) = 49 (0x31)
getpid()					 = 68733 (0x10c7d)
geteuid()					 = 0 (0x0)
getegid()					 = 0 (0x0)
getuid()					 = 0 (0x0)
getgid()					 = 0 (0x0)
gettimeofday({1422563759.481578 },0x0)		 = 0 (0x0)
geteuid()					 = 0 (0x0)
write(32,"[2015/01/29 12:35:59.481578,  5,"...,134) = 134 (0x86)
geteuid()					 = 0 (0x0)
write(32,"  Security token: (NULL)\n",25)	 = 25 (0x19)
getpid()					 = 68733 (0x10c7d)
geteuid()					 = 0 (0x0)
getegid()					 = 0 (0x0)
getuid()					 = 0 (0x0)
getgid()					 = 0 (0x0)
gettimeofday({1422563759.482190 },0x0)		 = 0 (0x0)
geteuid()					 = 0 (0x0)
write(32,"[2015/01/29 12:35:59.482190,  5,"...,129) = 129 (0x81)
geteuid()					 = 0 (0x0)
write(32,"  UNIX token of user 0\n",23)		 = 23 (0x17)
geteuid()					 = 0 (0x0)
write(32,"  Primary group is 0 and contain"...,57) = 57 (0x39)
geteuid()					 = 0 (0x0)
getegid()					 = 0 (0x0)
__sysctl(0x7fffffffca50,0x2,0x7fffffffca4c,0x7fffffffca58,0x0,0x0) = 0 (0x0)
SIGNAL 15 (SIGTERM)
sigreturn(0x7fffffffa440,0xe,0x804725d60,0x8013f9a20,0x101010101010101,0x8080808080808080) ERR#34379126784 'Unknown error: 19388416'
getcontext(0x7fffffffa6f0,0x80471e65b,0x40000000,0x3c0,0xfffffffffffab250,0x8080808080808080) = 0 (0x0)
sysarch(0x84,0x7fffffffa6c8,0x40000000,0x7fffffffaa60,0xfffffffffffab250,0x8080808080808080) = 0 (0x0)
sigprocmask(SIG_SETMASK,SIGFPE|SIGPIPE|SIGTERM|SIGUSR2,0x0) = 0 (0x0)
write(7,"\0",1)					 = 1 (0x1)
sigreturn(0x7fffffffa340,0x7fffffffa340,0x301,0x1,0xfffffffffffffc50,0x8080808080808080) = 0 (0x0)
close(33)					 = 0 (0x0)
read(11,0x813514000,32768)			 = 0 (0x0)
close(11)					 = 0 (0x0)
open("/etc/pam.d/other",O_RDONLY,0666)		 = 11 (0xb)
geteuid()					 = 0 (0x0)
fstat(11,{ mode=-rw-r--r-- ,inode=323950,size=671,blksize=32768 }) = 0 (0x0)
fstat(11,{ mode=-rw-r--r-- ,inode=323950,size=671,blksize=32768 }) = 0 (0x0)
read(11,"#\n# $FreeBSD: release/10.0.0/et"...,32768) = 671 (0x29f)
open("/usr/lib/pam_nologin.so.5",O_RDONLY,00)	 = 33 (0x21)
geteuid()					 = 0 (0x0)
fstat(33,{ mode=-r--r--r-- ,inode=480921,size=6096,blksize=32768 }) = 0 (0x0)
fcntl(33,0x11,0x0)				 = 34 (0x22)
fstat(34,{ mode=-r--r--r-- ,inode=480921,size=6096,blksize=32768 }) = 0 (0x0)
mmap(0x0,4096,PROT_READ,MAP_PRIVATE|MAP_PREFAULT_READ,34,0x0) = 34380128256 (0x801372000)
mmap(0x0,2101248,PROT_NONE,MAP_PRIVATE|MAP_ANON|MAP_NOCORE,-1,0x0) = 34726481920 (0x815dc1000)
mmap(0x815dc1000,4096,PROT_READ|PROT_EXEC,MAP_PRIVATE|MAP_FIXED|MAP_NOCORE|MAP_PREFAULT_READ,34,0x0) = 34726481920 (0x815dc1000)
mmap(0x815fc1000,4096,PROT_READ|PROT_WRITE,MAP_PRIVATE|MAP_FIXED|MAP_PREFAULT_READ,34,0x0) = 34728579072 (0x815fc1000)
munmap(0x801372000,4096)			 = 0 (0x0)
close(34)					 = 0 (0x0)
close(33)					 = 0 (0x0)
open("/usr/lib/pam_login_access.so.5",O_RDONLY,00) = 33 (0x21)
geteuid()					 = 0 (0x0)
fstat(33,{ mode=-r--r--r-- ,inode=480920,size=9296,blksize=32768 }) = 0 (0x0)
fcntl(33,0x11,0x0)				 = 34 (0x22)
fstat(34,{ mode=-r--r--r-- ,inode=480920,size=9296,blksize=32768 }) = 0 (0x0)
mmap(0x0,4096,PROT_READ,MAP_PRIVATE|MAP_PREFAULT_READ,34,0x0) = 34380128256 (0x801372000)
mmap(0x0,2105344,PROT_NONE,MAP_PRIVATE|MAP_ANON|MAP_NOCORE,-1,0x0) = 34728583168 (0x815fc2000)
mmap(0x815fc2000,8192,PROT_READ|PROT_EXEC,MAP_PRIVATE|MAP_FIXED|MAP_NOCORE|MAP_PREFAULT_READ,34,0x0) = 34728583168 (0x815fc2000)
mmap(0x8161c3000,4096,PROT_READ|PROT_WRITE,MAP_PRIVATE|MAP_FIXED|MAP_PREFAULT_READ,34,0x1000) = 34730684416 (0x8161c3000)
munmap(0x801372000,4096)			 = 0 (0x0)
close(34)					 = 0 (0x0)
close(33)					 = 0 (0x0)
open("/usr/lib/pam_unix.so.5",O_RDONLY,00)	 = 33 (0x21)
geteuid()					 = 0 (0x0)
fstat(33,{ mode=-r--r--r-- ,inode=480938,size=12528,blksize=32768 }) = 0 (0x0)
fcntl(33,0x11,0x0)				 = 34 (0x22)
fstat(34,{ mode=-r--r--r-- ,inode=480938,size=12528,blksize=32768 }) = 0 (0x0)
mmap(0x0,4096,PROT_READ,MAP_PRIVATE|MAP_PREFAULT_READ,34,0x0) = 34380128256 (0x801372000)
mmap(0x0,2109440,PROT_NONE,MAP_PRIVATE|MAP_ANON|MAP_NOCORE,-1,0x0) = 34730688512 (0x8161c4000)
mmap(0x8161c4000,12288,PROT_READ|PROT_EXEC,MAP_PRIVATE|MAP_FIXED|MAP_NOCORE|MAP_PREFAULT_READ,34,0x0) = 34730688512 (0x8161c4000)
mmap(0x8163c6000,4096,PROT_READ|PROT_WRITE,MAP_PRIVATE|MAP_FIXED|MAP_PREFAULT_READ,34,0x2000) = 34732793856 (0x8163c6000)
munmap(0x801372000,4096)			 = 0 (0x0)
close(34)					 = 0 (0x0)
mmap(0x0,36864,PROT_READ|PROT_WRITE,MAP_PRIVATE|MAP_ANON,-1,0x0) = 34380173312 (0x80137d000)
close(33)					 = 0 (0x0)
read(11,0x813514000,32768)			 = 0 (0x0)
close(11)					 = 0 (0x0)
open("/etc/pam.d/other",O_RDONLY,0666)		 = 11 (0xb)
geteuid()					 = 0 (0x0)
fstat(11,{ mode=-rw-r--r-- ,inode=323950,size=671,blksize=32768 }) = 0 (0x0)
fstat(11,{ mode=-rw-r--r-- ,inode=323950,size=671,blksize=32768 }) = 0 (0x0)
read(11,"#\n# $FreeBSD: release/10.0.0/et"...,32768) = 671 (0x29f)
open("/usr/lib/pam_permit.so.5",O_RDONLY,00)	 = 33 (0x21)
geteuid()					 = 0 (0x0)
fstat(33,{ mode=-r--r--r-- ,inode=480930,size=4576,blksize=32768 }) = 0 (0x0)
fcntl(33,0x11,0x0)				 = 34 (0x22)
fstat(34,{ mode=-r--r--r-- ,inode=480930,size=4576,blksize=32768 }) = 0 (0x0)
mmap(0x0,4096,PROT_READ,MAP_PRIVATE|MAP_PREFAULT_READ,34,0x0) = 34380128256 (0x801372000)
mmap(0x0,2101248,PROT_NONE,MAP_PRIVATE|MAP_ANON|MAP_NOCORE,-1,0x0) = 34732797952 (0x8163c7000)
mmap(0x8163c7000,4096,PROT_READ|PROT_EXEC,MAP_PRIVATE|MAP_FIXED|MAP_NOCORE|MAP_PREFAULT_READ,34,0x0) = 34732797952 (0x8163c7000)
mmap(0x8165c7000,4096,PROT_READ|PROT_WRITE,MAP_PRIVATE|MAP_FIXED|MAP_PREFAULT_READ,34,0x0) = 34734895104 (0x8165c7000)
munmap(0x801372000,4096)			 = 0 (0x0)
close(34)					 = 0 (0x0)
close(33)					 = 0 (0x0)
read(11,0x813514000,32768)			 = 0 (0x0)
close(11)					 = 0 (0x0)
open("/etc/pam.d/other",O_RDONLY,0666)		 = 11 (0xb)
geteuid()					 = 0 (0x0)
fstat(11,{ mode=-rw-r--r-- ,inode=323950,size=671,blksize=32768 }) = 0 (0x0)
fstat(11,{ mode=-rw-r--r-- ,inode=323950,size=671,blksize=32768 }) = 0 (0x0)
read(11,"#\n# $FreeBSD: release/10.0.0/et"...,32768) = 671 (0x29f)
open("/usr/lib/pam_permit.so.5",O_RDONLY,00)	 = 33 (0x21)
geteuid()					 = 0 (0x0)
fstat(33,{ mode=-r--r--r-- ,inode=480930,size=4576,blksize=32768 }) = 0 (0x0)
fcntl(33,0x11,0x0)				 = 34 (0x22)
fstat(34,{ mode=-r--r--r-- ,inode=480930,size=4576,blksize=32768 }) = 0 (0x0)
mmap(0x0,4096,PROT_READ,MAP_PRIVATE|MAP_PREFAULT_READ,34,0x0) = 34380128256 (0x801372000)
mmap(0x0,2101248,PROT_NONE,MAP_PRIVATE|MAP_ANON|MAP_NOCORE,-1,0x0) = 34734899200 (0x8165c8000)
mmap(0x8165c8000,4096,PROT_READ|PROT_EXEC,MAP_PRIVATE|MAP_FIXED|MAP_NOCORE|MAP_PREFAULT_READ,34,0x0) = 34734899200 (0x8165c8000)
mmap(0x8167c8000,4096,PROT_READ|PROT_WRITE,MAP_PRIVATE|MAP_FIXED|MAP_PREFAULT_READ,34,0x0) = 34736996352 (0x8167c8000)
munmap(0x801372000,4096)			 = 0 (0x0)
close(34)					 = 0 (0x0)
close(33)					 = 0 (0x0)
read(11,0x813514000,32768)			 = 0 (0x0)
close(11)					 = 0 (0x0)
getpid()					 = 68733 (0x10c7d)
geteuid()					 = 0 (0x0)
getegid()					 = 0 (0x0)
getuid()					 = 0 (0x0)
getgid()					 = 0 (0x0)
gettimeofday({1422563759.496673 },0x0)		 = 0 (0x0)
geteuid()					 = 0 (0x0)
write(32,"[2015/01/29 12:35:59.496673,  4,"...,130) = 130 (0x82)
geteuid()					 = 0 (0x0)
write(32,"  smb_pam_start: PAM: setting rh"...,53) = 53 (0x35)
getpid()					 = 68733 (0x10c7d)
geteuid()					 = 0 (0x0)
getegid()					 = 0 (0x0)
getuid()					 = 0 (0x0)
getgid()					 = 0 (0x0)
gettimeofday({1422563759.497113 },0x0)		 = 0 (0x0)
geteuid()					 = 0 (0x0)
write(32,"[2015/01/29 12:35:59.497113,  4,"...,130) = 130 (0x82)
geteuid()					 = 0 (0x0)
write(32,"  smb_pam_start: PAM: setting tt"...,34) = 34 (0x22)
getpid()					 = 68733 (0x10c7d)
geteuid()					 = 0 (0x0)
getegid()					 = 0 (0x0)
getuid()					 = 0 (0x0)
getgid()					 = 0 (0x0)
gettimeofday({1422563759.497539 },0x0)		 = 0 (0x0)
geteuid()					 = 0 (0x0)
write(32,"[2015/01/29 12:35:59.497539,  4,"...,130) = 130 (0x82)
geteuid()					 = 0 (0x0)
write(32,"  smb_pam_start: PAM: Init passe"...,60) = 60 (0x3c)
getpid()					 = 68733 (0x10c7d)
geteuid()					 = 0 (0x0)
getegid()					 = 0 (0x0)
getuid()					 = 0 (0x0)
getgid()					 = 0 (0x0)
gettimeofday({1422563759.497980 },0x0)		 = 0 (0x0)
geteuid()					 = 0 (0x0)
write(32,"[2015/01/29 12:35:59.497980,  4,"...,141) = 141 (0x8d)
geteuid()					 = 0 (0x0)
write(32,"  smb_internal_pam_session: PAM:"...,60) = 60 (0x3c)
munmap(0x8157a7000,2109440)			 = 0 (0x0)
munmap(0x8155a6000,2101248)			 = 0 (0x0)
munmap(0x8153a4000,2105344)			 = 0 (0x0)
munmap(0x815bbc000,2117632)			 = 0 (0x0)
munmap(0x8161c4000,2109440)			 = 0 (0x0)
munmap(0x815fc2000,2105344)			 = 0 (0x0)
munmap(0x8159aa000,2170880)			 = 0 (0x0)
munmap(0x815dc1000,2101248)			 = 0 (0x0)
munmap(0x8163c7000,2101248)			 = 0 (0x0)
munmap(0x8165c8000,2101248)			 = 0 (0x0)
getpid()					 = 68733 (0x10c7d)
geteuid()					 = 0 (0x0)
getegid()					 = 0 (0x0)
getuid()					 = 0 (0x0)
getgid()					 = 0 (0x0)
gettimeofday({1422563759.499043 },0x0)		 = 0 (0x0)
geteuid()					 = 0 (0x0)
write(32,"[2015/01/29 12:35:59.499043,  4,"...,128) = 128 (0x80)
geteuid()					 = 0 (0x0)
write(32,"  smb_pam_end: PAM: PAM_END OK."...,32) = 32 (0x20)
getpid()					 = 68733 (0x10c7d)
geteuid()					 = 0 (0x0)
getegid()					 = 0 (0x0)
getuid()					 = 0 (0x0)
getgid()					 = 0 (0x0)
gettimeofday({1422563759.499499 },0x0)		 = 0 (0x0)
geteuid()					 = 0 (0x0)
write(32,"[2015/01/29 12:35:59.499499,  4,"...,116) = 116 (0x74)
geteuid()					 = 0 (0x0)
write(32,"  setting sec ctx (0, 0) - sec_c"...,49) = 49 (0x31)
getpid()					 = 68733 (0x10c7d)
geteuid()					 = 0 (0x0)
getegid()					 = 0 (0x0)
getuid()					 = 0 (0x0)
getgid()					 = 0 (0x0)
gettimeofday({1422563759.499912 },0x0)		 = 0 (0x0)
geteuid()					 = 0 (0x0)
write(32,"[2015/01/29 12:35:59.499912,  5,"...,134) = 134 (0x86)
geteuid()					 = 0 (0x0)
write(32,"  Security token: (NULL)\n",25)	 = 25 (0x19)
getpid()					 = 68733 (0x10c7d)
geteuid()					 = 0 (0x0)
getegid()					 = 0 (0x0)
getuid()					 = 0 (0x0)
getgid()					 = 0 (0x0)
gettimeofday({1422563759.500329 },0x0)		 = 0 (0x0)
geteuid()					 = 0 (0x0)
write(32,"[2015/01/29 12:35:59.500329,  5,"...,129) = 129 (0x81)
geteuid()					 = 0 (0x0)
write(32,"  UNIX token of user 0\n",23)		 = 23 (0x17)
geteuid()					 = 0 (0x0)
write(32,"  Primary group is 0 and contain"...,57) = 57 (0x39)
geteuid()					 = 0 (0x0)
getegid()					 = 0 (0x0)
__sysctl(0x7fffffffca50,0x2,0x7fffffffca4c,0x7fffffffca58,0x0,0x0) = 0 (0x0)
process exit, rval = 0
Comment 19 Mike Carlson 2015-01-29 20:43:00 UTC
Created attachment 10700 [details]
level 10 log files for failed windows client  connection

level 10 log files for failed windows client connection

Log level 10

Steps used:

Server:
winbindd -d 10 -s /usr/local/etc/smb4.conf
smbd -d 10 -s /usr/local/etc/smb4.conf


Client (Windows)
Opened up UNC path to:

\\samba-qa-1\smb_qa

Entered directory \20_files_test\
Comment 20 Mike Carlson 2015-01-29 20:44:07 UTC
Created attachment 10701 [details]
level 10 log files for successful smbclient connection

level 10 log files for successful smbclient connection

Steps used:

Server:
winbindd -d 10 -s /usr/local/etc/smb4.conf
smbd -d 10 -s /usr/local/etc/smb4.conf

client:

kinit mikec
smbclient -d 3 -k -mSMB2 //samba-qa-1/smb_qa
Comment 21 Ralph Böhme 2015-02-16 13:05:42 UTC
Is this possibly a freebsd/libinotify issue? From rushing through this PR, the web, APIs and the libinotify code, it seems when adding a inotify watch for a directory libibnotify adds watches for every file in the directory which means an open fd per file...

Can you test with

  kernel change notify = no

Thanks!
Comment 22 Mike Carlson 2015-02-16 20:07:03 UTC
(In reply to Ralph Böhme from comment #21)
This seems to fix the FD leak:


root@samba-qa-1:~ # procstat -f 99634
  PID COMM               FD T V FLAGS     REF  OFFSET PRO NAME
99634 smbd              text v r r-------  -       - -   /usr/local/sbin/smbd
99634 smbd               cwd v d r-------  -       - -   /data/smb_qa
99634 smbd              root v d r-------  -       - -   /
99634 smbd                 0 v c rw------  3       0 -   /dev/null
99634 smbd                 1 v c rw------  3       0 -   /dev/null
99634 smbd                 2 v r -wa-----  2       0 -   /var/log/samba4/log.10.5.68.20
99634 smbd                 3 v r rw------  3     168 -   /var/db/samba4/messages.tdb
99634 smbd                 4 v c r-------  3     113 -   /dev/random
99634 smbd                 5 v r rw------  3     168 -   /var/db/samba4/private/secrets.tdb
99634 smbd                 6 p - rw---n--  1       0 -   -
99634 smbd                 7 p - rw---n--  1       0 -   -
99634 smbd                 8 v r rw------  1     168 -   /var/db/samba4/dbwrap_watchers.tdb
99634 smbd                 9 v r -w---n--  3       6 -   -
99634 smbd                10 p - rw------  3       0 -   -
99634 smbd                11 v d r-------  1       0 -   /data/smb_qa/100k_file_test
99634 smbd                12 v r rw------  3     168 -   /var/db/samba4/smbXsrv_version_global.tdb
99634 smbd                13 v r rw------  3     168 -   /var/db/samba4/smbXsrv_session_global.tdb
99634 smbd                14 v r rw------  3     168 -   /var/db/samba4/smbXsrv_tcon_global.tdb
99634 smbd                15 v r rw------  3     168 -   /var/db/samba4/brlock.tdb
99634 smbd                16 v r rw------  3     168 -   /var/db/samba4/locking.tdb
99634 smbd                17 v r rw------  3     168 -   /var/db/samba4/notify.tdb
99634 smbd                18 v r rw------  3     168 -   /var/db/samba4/notify_index.tdb
99634 smbd                19 v r rw------  3     168 -   /var/db/samba4/serverid.tdb
99634 smbd                20 v r rw------  3     168 -   /var/db/samba4/share_info.tdb
99634 smbd                21 v r rw------  3     168 -   /var/db/samba4/private/passdb.tdb
99634 smbd                22 v r rw------  3     168 -   /var/db/samba4/group_mapping.tdb
99634 smbd                23 v r rw------  3     168 -   /var/db/samba4/gencache.tdb
99634 smbd                24 v r rw------  3     168 -   /var/db/samba4/gencache_notrans.tdb
99634 smbd                25 v r rw------  3     168 -   /var/db/samba4/account_policy.tdb
99634 smbd                26 v r rw------  1     168 -   /var/db/samba4/netsamlogon_cache.tdb
99634 smbd                27 v r rw------  3     168 -   /var/db/samba4/smbXsrv_open_global.tdb
99634 smbd                28 v r rw------  3     168 -   /var/db/samba4/printer_list.tdb
99634 smbd                29 p - rw------  2       0 -   -
99634 smbd                30 p - rw------  3       0 -   -
99634 smbd                31 s - rw---n--  1       0 UDS /var/db/samba4/winbindd_privileged/pipe
99634 smbd                32 v r -wa-----  2       0 -   /var/log/samba4/log.10.5.68.20
99634 smbd                34 v d r-------  1 485992734 -   /data/smb_qa
99634 smbd                35 v r rw------  2     168 -   /var/db/samba4/registry.tdb
99634 smbd                36 s - rw---n--  1       0 TCP 10.5.68.127:445 10.5.68.20:6636
99634 smbd                37 v d r----n--  1 380145208 -   /data/smb_qa/100k_file_test
99634 smbd                38 v d r-------  1 379608559 -   /data/smb_qa/100k_file_test
99634 smbd                39 v d r-------  1       0 -   /data/smb_qa

I was able to browse the directory with 100K files in it!

What are the drawbacks to this? Is this a issue with FreeBSD that should be filed, or, is it fine to operate this this config option?

Thanks!
Mike C
Comment 23 Ralph Böhme 2015-02-17 11:42:19 UTC
It's an issue with FreeBSD's kqueue not providing sufficient events when watching a directory. Only file rename or delete within a directory trigger notifications, but not file modifications. Therefor libinotify, which provides the inotify compatible API on FreeBSD and which uses the kernel kqueue facility, additionally adds monitors to every file in a monitored directory.

As an alternative to inotify API based libinotify, you could check whether Samba can be built with FAM/gamin support on FreeBSD instead. Possibly gamin does this differently then libinotify. If not, either gamin or libinotify could be tweaked to provide some sort of inotify API extension that request only FILE_CREATED, FILE_DELETED, FILE_RENAMED events when monitoring a directory.

By setting "kernel change notify = no" Samba will still distribute file events done by smbd processes, but you won't get notification for local changes, NFS or other protocols.
Comment 24 Mike Carlson 2015-02-17 17:57:41 UTC
(In reply to Ralph Böhme from comment #23)
Thank you for the information Ralph.

We do have Samba41 built with FAM, I can investigate that later on.

These servers primarily export their data through CIFS/Samba, there are a few instances where the data is also exported via NFS. 

Will this lead to data corruption?
Comment 25 Ralph Böhme 2015-02-17 18:06:52 UTC
(In reply to Mike Carlson from comment #24)
No.