FreeNAS-11.0-U1 (aa82cc58d) SMBD exited on signal 6

Nicholas M · Jul 20, 2017

We had the SMBD crash signal 6 issue in FreeNAS-9.10.2-U4, updated to U5 and still occurred. Updated to current stable FreeNAS-11.0-U1 and its has occurred once again. Up until U3 the system had been rock solid.

Wondering if anyone else has the SMBD issue on FN11.0-U1 before raising it as a bug?

Code:

Jul 20 12:22:35 abney kernel: Failed to fully fault in a core file segment at VA 0x800f64000 with size 0x3000 to be written at offset 0x2a1000 for process smbd
Jul 20 12:22:35 abney kernel: Failed to fully fault in a core file segment at VA 0x800f64000 with size 0x3000 to be written at offset 0x2a1000 for process smbd
Jul 20 12:22:35 abney kernel: pid 96668 (smbd), uid 0: exited on signal 6 (core dumped)

/var/log/samba4/log.smbd:

Code:

[2017/07/20 12:22:20.121488,  0] ../source3/smbd/close.c:1092(close_directory)
  close_directory: Could not get share mode lock for CVDATA_14/CV_MAGNETIC/V_989185/CHUNK_44642977
[2017/07/20 12:22:31.259035,  0] ../lib/util/fault.c:78(fault_report)
  ===============================================================
[2017/07/20 12:22:31.259106,  0] ../lib/util/fault.c:79(fault_report)
  INTERNAL ERROR: Signal 11 in pid 96668 (4.6.4-GIT-5fe3bc2)
  Please read the Trouble-Shooting section of the Samba HOWTO
[2017/07/20 12:22:31.259137,  0] ../lib/util/fault.c:81(fault_report)
  ===============================================================
[2017/07/20 12:22:31.259157,  0] ../source3/lib/util.c:791(smb_panic_s3)
  PANIC (pid 96668): internal error
[2017/07/20 12:22:31.261946,  0] ../source3/lib/util.c:902(log_stack_trace)
  BACKTRACE: 7 stack frames:
   #0 0x803262d1e <log_stack_trace+0x1e> at /usr/local/lib/libsmbconf.so.0
   #1 0x803262b18 <smb_panic_s3+0x98> at /usr/local/lib/libsmbconf.so.0
   #2 0x800c9a597 <smb_panic+0x27> at /usr/local/lib/libsamba-util.so.0
   #3 0x800c9ab40 <string_sub_once> at /usr/local/lib/libsamba-util.so.0
   #4 0x800c9a563 <fault_setup+0x73> at /usr/local/lib/libsamba-util.so.0
   #5 0x8008488b6 <pthread_sigmask+0x4f6> at /lib/libthr.so.3
   #6 0x800847e9f <pthread_getspecific+0xe5f> at /lib/libthr.so.3
[2017/07/20 12:22:31.262054,  0] ../source3/lib/util.c:803(smb_panic_s3)
  smb_panic(): calling panic action [/usr/local/libexec/samba/samba-backtrace]
ptrace: Device busy.
ptrace: Device busy.
ptrace: Device busy.
[2017/07/20 12:22:35.359438,  0] ../source3/lib/util.c:811(smb_panic_s3)
  smb_panic(): action returned status 0
[2017/07/20 12:22:35.359759,  0] ../source3/lib/dumpcore.c:315(dump_core)
  dumping core in /var/db/system/cores

anodos · Jul 20, 2017

Nicholas M said:

We had the SMBD crash signal 6 issue in FreeNAS-9.10.2-U4, updated to U5 and still occurred. Updated to current stable FreeNAS-11.0-U1 and its has occurred once again. Up until U3 the system had been rock solid.

Wondering if anyone else has the SMBD issue on FN11.0-U1 before raising it as a bug?

Code:

Jul 20 12:22:35 abney kernel: Failed to fully fault in a core file segment at VA 0x800f64000 with size 0x3000 to be written at offset 0x2a1000 for process smbd
Jul 20 12:22:35 abney kernel: Failed to fully fault in a core file segment at VA 0x800f64000 with size 0x3000 to be written at offset 0x2a1000 for process smbd
Jul 20 12:22:35 abney kernel: pid 96668 (smbd), uid 0: exited on signal 6 (core dumped)

/var/log/samba4/log.smbd:

Code:

[2017/07/20 12:22:20.121488,  0] ../source3/smbd/close.c:1092(close_directory)
  close_directory: Could not get share mode lock for CVDATA_14/CV_MAGNETIC/V_989185/CHUNK_44642977
[2017/07/20 12:22:31.259035,  0] ../lib/util/fault.c:78(fault_report)
  ===============================================================
[2017/07/20 12:22:31.259106,  0] ../lib/util/fault.c:79(fault_report)
  INTERNAL ERROR: Signal 11 in pid 96668 (4.6.4-GIT-5fe3bc2)
  Please read the Trouble-Shooting section of the Samba HOWTO
[2017/07/20 12:22:31.259137,  0] ../lib/util/fault.c:81(fault_report)
  ===============================================================
[2017/07/20 12:22:31.259157,  0] ../source3/lib/util.c:791(smb_panic_s3)
  PANIC (pid 96668): internal error
[2017/07/20 12:22:31.261946,  0] ../source3/lib/util.c:902(log_stack_trace)
  BACKTRACE: 7 stack frames:
   #0 0x803262d1e <log_stack_trace+0x1e> at /usr/local/lib/libsmbconf.so.0
   #1 0x803262b18 <smb_panic_s3+0x98> at /usr/local/lib/libsmbconf.so.0
   #2 0x800c9a597 <smb_panic+0x27> at /usr/local/lib/libsamba-util.so.0
   #3 0x800c9ab40 <string_sub_once> at /usr/local/lib/libsamba-util.so.0
   #4 0x800c9a563 <fault_setup+0x73> at /usr/local/lib/libsamba-util.so.0
   #5 0x8008488b6 <pthread_sigmask+0x4f6> at /lib/libthr.so.3
   #6 0x800847e9f <pthread_getspecific+0xe5f> at /lib/libthr.so.3
[2017/07/20 12:22:31.262054,  0] ../source3/lib/util.c:803(smb_panic_s3)
  smb_panic(): calling panic action [/usr/local/libexec/samba/samba-backtrace]
ptrace: Device busy.
ptrace: Device busy.
ptrace: Device busy.
[2017/07/20 12:22:35.359438,  0] ../source3/lib/util.c:811(smb_panic_s3)
  smb_panic(): action returned status 0
[2017/07/20 12:22:35.359759,  0] ../source3/lib/dumpcore.c:315(dump_core)
  dumping core in /var/db/system/cores

Interesting. Can you increase logging verbosity under Services->SMB to "Full", then make it crash again?

Also post the contents of /usr/local/etc/smb4.conf. Feel free to redact personal information.

Nicholas M · Jul 20, 2017

Here is the smb4.conf:

Code:

[global]
	server min protocol = SMB2
	server max protocol = SMB3_02
	interfaces = 127.0.0.1 10.150.0.15 10.150.1.1
	bind interfaces only = yes
	encrypt passwords = yes
	dns proxy = no
	strict locking = no
	oplocks = yes
	deadtime = 15
	max log size = 51200
	max open files = 7545386
	logging = file
	load printers = no
	printing = bsd
	printcap name = /dev/null
	disable spoolss = yes
	getwd cache = yes
	guest account = nobody
	map to guest = Bad User
	obey pam restrictions = yes
	ntlm auth = no
	directory name cache size = 0
	kernel change notify = no
	panic action = /usr/local/libexec/samba/samba-backtrace
	nsupdate command = /usr/local/bin/samba-nsupdate -g
	server string = FreeNAS Server
	ea support = yes
	store dos attributes = yes
	lm announce = yes
	acl allow execute always = true
	dos filemode = yes
	multicast dns register = no
	domain logons = no
	local master = yes
	idmap config *: backend = tdb
	idmap config *: range = 90000001-100000000
	server role = standalone
	netbios name = ABNEY
	workgroup = COMMVAULT
	security = user
	pid directory = /var/run/samba
	create mask = 0666
	directory mask = 0777
	client ntlmv2 auth = yes
	dos charset = CP437
	unix charset = UTF-8
	log level = 3


[POOL_09_CIFS]
	path = "/mnt/POOL_09/POOL_09_CIFS"
	printable = no
	veto files = /.snapshot/.windows/.mac/.zfs/
	writeable = yes
	browseable = yes
	vfs objects = zfs_space zfsacl streams_xattr aio_pthread
	hide dot files = yes
	guest ok = no
	nfs4:mode = special
	nfs4:acedup = merge
	nfs4:chown = true
	zfsacl:acesort = dontcare


[POOL_10_CIFS]
	path = "/mnt/POOL_10/POOL_10_CIFS"
	printable = no
	veto files = /.snapshot/.windows/.mac/.zfs/
	writeable = yes
	browseable = yes
	vfs objects = zfs_space zfsacl streams_xattr aio_pthread
	hide dot files = yes
	guest ok = no
	nfs4:mode = special
	nfs4:acedup = merge
	nfs4:chown = true
	zfsacl:acesort = dontcare


[POOL_11_CIFS]
	path = "/mnt/POOL_11/POOL_11_CIFS"
	printable = no
	veto files = /.snapshot/.windows/.mac/.zfs/
	writeable = yes
	browseable = yes
	vfs objects = zfs_space zfsacl streams_xattr aio_pthread
	hide dot files = yes
	guest ok = no
	nfs4:mode = special
	nfs4:acedup = merge
	nfs4:chown = true
	zfsacl:acesort = dontcare


[POOL_12_CIFS]
	path = "/mnt/POOL_12/POOL_12_CIFS"
	printable = no
	veto files = /.snapshot/.windows/.mac/.zfs/
	writeable = yes
	browseable = yes
	vfs objects = zfs_space zfsacl streams_xattr aio_pthread
	hide dot files = yes
	guest ok = no
	nfs4:mode = special
	nfs4:acedup = merge
	nfs4:chown = true
	zfsacl:acesort = dontcare


[POOL_13_CIFS]
	path = "/mnt/POOL_13/POOL_13_CIFS"
	printable = no
	veto files = /.snapshot/.windows/.mac/.zfs/
	writeable = yes
	browseable = yes
	vfs objects = zfs_space zfsacl streams_xattr aio_pthread
	hide dot files = yes
	guest ok = no
	nfs4:mode = special
	nfs4:acedup = merge
	nfs4:chown = true
	zfsacl:acesort = dontcare


[POOL_14_CIFS]
	path = "/mnt/POOL_14/POOL_14_CIFS"
	printable = no
	veto files = /.snapshot/.windows/.mac/.zfs/
	writeable = yes
	browseable = yes
	vfs objects = zfs_space zfsacl streams_xattr aio_pthread
	hide dot files = yes
	guest ok = no
	nfs4:mode = special
	nfs4:acedup = merge
	nfs4:chown = true
	zfsacl:acesort = dontcare


[c$]
	path = "/mnt/POOL_09/c"
	printable = no
	veto files = /.snapshot/.windows/.mac/.zfs/
	writeable = yes
	browseable = yes
	vfs objects = zfs_space zfsacl streams_xattr aio_pthread
	hide dot files = yes
	guest ok = no
	nfs4:mode = special
	nfs4:acedup = merge
	nfs4:chown = true
	zfsacl:acesort = dontcare


[cv_utils]
	path = "/mnt/FLASH_POOL_01/Commvault"
	printable = no
	veto files = /.snapshot/.windows/.mac/.zfs/
	writeable = yes
	browseable = yes
	vfs objects = zfs_space zfsacl streams_xattr aio_pthread
	hide dot files = yes
	guest ok = no
	nfs4:mode = special
	nfs4:acedup = merge
	nfs4:chown = true
	zfsacl:acesort = dontcare


[monitoring-share]
	path = "/mnt/monitoring/share"
	printable = no
	veto files = /.snapshot/.windows/.mac/.zfs/
	writeable = yes
	browseable = yes
	vfs objects = zfs_space zfsacl streams_xattr aio_pthread
	hide dot files = yes
	guest ok = no
	nfs4:mode = special
	nfs4:acedup = merge
	nfs4:chown = true
	zfsacl:acesort = dontcare

Note: Ive increased the logging to 'Full' and disabled 'Hostnames lookups' as it was flooding the log (has been for months, can re-enable if required).

I can't really 'make' it crash - but if i were to put money on it, its likely to crash all by itself within a week ;)

Brentnall · Jul 28, 2017

I also experienced a similar error on 19th but did not report it till now as I assumed it was just an unlucky one time event.

Code:

Jul 19 20:24:08 roflnas kernel: Failed to fully fault in a core file segment at VA 0x800f7e000 with size 0x3000 to be written at offset 0x2bd000 for process smbd
Jul 19 20:24:08 roflnas kernel: Failed to fully fault in a core file segment at VA 0x800f7e000 with size 0x3000 to be written at offset 0x2bd000 for process smbd
Jul 19 20:24:09 roflnas kernel: pid 81311 (smbd), uid 0: exited on signal 6 (core dumped)

As would be expected this resulted in all my SMB shares becoming unavailable and required a service restart to resolve.
Will upgrade to FN11.0-U2, up the SMB verbosity as suggested, and post here with requested details if the issue reoccurs.

anodos · Jul 28, 2017

Brentnall said:
I also experienced a similar error on 19th but did not report it till now as I assumed it was just an unlucky one time event.

Code:
Jul 19 20:24:08 roflnas kernel: Failed to fully fault in a core file segment at VA 0x800f7e000 with size 0x3000 to be written at offset 0x2bd000 for process smbd Jul 19 20:24:08 roflnas kernel: Failed to fully fault in a core file segment at VA 0x800f7e000 with size 0x3000 to be written at offset 0x2bd000 for process smbd Jul 19 20:24:09 roflnas kernel: pid 81311 (smbd), uid 0: exited on signal 6 (core dumped)

As would be expected this resulted in all my SMB shares becoming unavailable and required a service restart to resolve.
Will upgrade to FN11.0-U2, up the SMB verbosity as suggested, and post here with requested details if the issue reoccurs.

Thanks! That would be great. One of my servers has a similar entry in its logs but functionality wasn't affected. Unfortunately, it's very hard to reproduce and I didn't have logging turned up. :(

Tsaukpaetra · Aug 25, 2017

Probably unrelated and anecdotal, but I got "failed to fully fault" message when one of the disks I was using would stop responding to commands (ie it would freeze up, but not actually disconnect). If it got stuck while trying to page against that disk, the operation would timeout and the message would appear.

PhilipS · Sep 7, 2017

I may be having (or had) a similar issue with samba crashing with Signal 6 - it only happens on one of my servers after I upgraded to FreeNAS 11.0 (from 9.10). I didn't have time to troubleshoot this, so I rolled back to 9.10.2 u5 on that one server. Today I updated it to 11.0 u3 and the issue occurs again.

I could reproduce it by creating a text document from the right click menu from a windows client. It would only crash the session, not all of smb. I turned on full debug and here is a smbd.log

Code:

[2017/09/07 18:40:34.000030,  3] ../source3/smbd/trans2.c:3427(smbd_do_qfsinfo)
  smbd_do_qfsinfo: level = 1007
[2017/09/07 18:40:34.000239,  3] ../source3/lib/sysquotas.c:488(sys_get_quota)
  sys_get_vfs_quota() failed for mntpath[Company] bdev[(null)] qtype[1] id[-1]: Operation not supported
[2017/09/07 18:40:34.000317,  3] ../source3/lib/sysquotas.c:488(sys_get_quota)
  sys_get_vfs_quota() failed for mntpath[Company] bdev[(null)] qtype[3] id[-1]: Operation not supported
[2017/09/07 18:40:34.004357,  3] ../source3/smbd/smb2_server.c:3097(smbd_smb2_request_error_ex)
  smbd_smb2_request_error_ex: smbd_smb2_request_error_ex: idx[1] status[NT_STATUS_OBJECT_NAME_NOT_FOUND] || at ../source3/smbd/smb2_create.c:293
[2017/09/07 18:40:34.006275,  2] ../source3/smbd/open.c:1322(open_file)
  WEATHERITE\philip opened file Company/New Text Document.txt read=Yes write=Yes (numopen=1)
Assertion failed: (_entry_brand(a) == ACL_BRAND_POSIX), function _posix1e_acl_entry_compare, file /freenas-11-releng/freenas/_BE/os/lib/libc/posix1e/acl_support.c, line 96.
[2017/09/07 18:40:34.006917,  0] ../lib/util/fault.c:78(fault_report)
  ===============================================================
[2017/09/07 18:40:34.006975,  0] ../lib/util/fault.c:79(fault_report)
  INTERNAL ERROR: Signal 6 in pid 12891 (4.6.4-GIT-d1d80f3)
  Please read the Trouble-Shooting section of the Samba HOWTO
[2017/09/07 18:40:34.007054,  0] ../lib/util/fault.c:81(fault_report)
  ===============================================================
[2017/09/07 18:40:34.007108,  0] ../source3/lib/util.c:791(smb_panic_s3)
  PANIC (pid 12891): internal error
[2017/09/07 18:40:34.009024,  0] ../source3/lib/util.c:902(log_stack_trace)
  BACKTRACE: 7 stack frames:
   #0 0x803262d1e <log_stack_trace+0x1e> at /usr/local/lib/libsmbconf.so.0
   #1 0x803262b18 <smb_panic_s3+0x98> at /usr/local/lib/libsmbconf.so.0
   #2 0x800c9a597 <smb_panic+0x27> at /usr/local/lib/libsamba-util.so.0
   #3 0x800c9ab40 <string_sub_once> at /usr/local/lib/libsamba-util.so.0
   #4 0x800c9a563 <fault_setup+0x73> at /usr/local/lib/libsamba-util.so.0
   #5 0x8008488b6 <pthread_sigmask+0x4f6> at /lib/libthr.so.3
   #6 0x800847e9f <pthread_getspecific+0xe5f> at /lib/libthr.so.3
[2017/09/07 18:40:34.009320,  0] ../source3/lib/util.c:803(smb_panic_s3)
  smb_panic(): calling panic action [/usr/local/libexec/samba/samba-backtrace]
mv: rename /var/log/samba4/samba.backtraces to /var/log/samba4/samba.backtraces.20170907184034: Permission denied
ptrace: Operation not permitted.
/mnt/tank/DFS/12819: No such file or directory.
ptrace: Operation not permitted.
/mnt/tank/DFS/12823: No such file or directory.
ptrace: Operation not permitted.
/mnt/tank/DFS/12830: No such file or directory.
[2017/09/07 18:40:35.777470,  0] ../source3/lib/util.c:811(smb_panic_s3)
  smb_panic(): action returned status 0
[2017/09/07 18:40:35.777686,  0] ../source3/lib/dumpcore.c:315(dump_core)
  dumping core in /var/db/system/cores
[2017/09/07 18:40:35.810077,  3] ../source3/smbd/server.c:859(remove_child_pid)
  ../source3/smbd/server.c:858 Unclean shutdown of pid 12891
[2017/09/07 18:40:35.810192,  1] ../source3/smbd/server.c:868(remove_child_pid)
  Scheduled cleanup of brl and lock database after unclean shutdown
[2017/09/07 18:40:35.816143,  3] ../lib/util/access.c:361(allow_access)
  Allowed connection from 192.168.10.18 (192.168.10.18)
[2017/09/07 18:40:35.816397,  3] ../source3/smbd/oplock.c:1301(init_oplocks)
  init_oplocks: initializing messages.
[2017/09/07 18:40:35.862518,  3] ../source3/smbd/process.c:1957(process_smb)
  Transaction 0 of length 106 (0 toread)
[2017/09/07 18:40:35.862919,  3] ../source3/smbd/smb2_negprot.c:290(smbd_smb2_request_process_negprot)
  Selected protocol SMB2_02
[2017/09/07 18:40:35.864768,  3] ../auth/gensec/gensec_start.c:918(gensec_register)
  GENSEC backend 'gssapi_spnego' registered
[2017/09/07 18:40:35.864865,  3] ../auth/gensec/gensec_start.c:918(gensec_register)
  GENSEC backend 'gssapi_krb5' registered
[2017/09/07 18:40:35.864924,  3] ../auth/gensec/gensec_start.c:918(gensec_register)
  GENSEC backend 'gssapi_krb5_sasl' registered
[2017/09/07 18:40:35.864982,  3] ../auth/gensec/gensec_start.c:918(gensec_register)
  GENSEC backend 'spnego' registered
[2017/09/07 18:40:35.865039,  3] ../auth/gensec/gensec_start.c:918(gensec_register)
  GENSEC backend 'schannel' registered
[2017/09/07 18:40:35.865097,  3] ../auth/gensec/gensec_start.c:918(gensec_register)
  GENSEC backend 'naclrpc_as_system' registered
[2017/09/07 18:40:35.865155,  3] ../auth/gensec/gensec_start.c:918(gensec_register)
  GENSEC backend 'sasl-EXTERNAL' registered
[2017/09/07 18:40:35.865213,  3] ../auth/gensec/gensec_start.c:918(gensec_register)
  GENSEC backend 'ntlmssp' registered
[2017/09/07 18:40:35.865272,  3] ../auth/gensec/gensec_start.c:918(gensec_register)
  GENSEC backend 'ntlmssp_resume_ccache' registered
[2017/09/07 18:40:35.865330,  3] ../auth/gensec/gensec_start.c:918(gensec_register)
  GENSEC backend 'http_basic' registered
[2017/09/07 18:40:35.865388,  3] ../auth/gensec/gensec_start.c:918(gensec_register)
  GENSEC backend 'http_ntlm' registered
[2017/09/07 18:40:35.865450,  3] ../auth/gensec/gensec_start.c:918(gensec_register)
  GENSEC backend 'krb5' registered
[2017/09/07 18:40:35.865508,  3] ../auth/gensec/gensec_start.c:918(gensec_register)
  GENSEC backend 'fake_gssapi_krb5' registered
[2017/09/07 18:40:39.868990,  3] ../auth/kerberos/kerberos_pac.c:409(kerberos_decode_pac)
  Found account name from PAC: philip [Philip Spigelmire]
[2017/09/07 18:40:39.869136,  3] ../source3/auth/user_krb5.c:51(get_user_from_kerberos_info)
  Kerberos ticket principal name is [philip@WEATHERITE.INFO]
[2017/09/07 18:40:39.884019,  3] ../source3/param/loadparm.c:3825(lp_load_ex)
  lp_load_ex: refreshing parameters
[2017/09/07 18:40:39.884262,  3] ../source3/param/loadparm.c:542(init_globals)
  Initialising global parameters
[2017/09/07 18:40:39.884606,  3] ../source3/param/loadparm.c:2754(lp_do_section)
  Processing section "[global]"
[2017/09/07 18:40:39.887424,  2] ../source3/param/loadparm.c:2771(lp_do_section)
  Processing section "[DFS]"
[2017/09/07 18:40:39.888512,  2] ../source3/param/loadparm.c:2771(lp_do_section)
  Processing section "[Special]"
[2017/09/07 18:40:39.889581,  3] ../source3/param/loadparm.c:1587(lp_add_ipc)
  adding IPC service
[2017/09/07 18:40:39.892693,  2] ../source3/smbd/smbXsrv_session.c:876(smbXsrv_session_global_verify_record)
  smbXsrv_session_global_verify_record: key 'BBE2D2C0' server_id 12891 does not exist.
[2017/09/07 18:40:39.892832,  2] ../source3/smbd/smbXsrv_session.c:877(smbXsrv_session_global_verify_record)
[2017/09/07 18:40:39.892862,  1] ../librpc/ndr/ndr.c:413(ndr_print_debug)
	   &global_blob: struct smbXsrv_session_globalB
		  version				  : SMBXSRV_VERSION_0 (0)
		  seqnum				   : 0x00000004 (4)
		  info					 : union smbXsrv_session_globalU(case 0)
		  info0					: *
			  info0: struct smbXsrv_session_global0
				  db_rec				   : NULL
				  session_global_id		: 0xbbe2d2c0 (3152204480)
				  session_wire_id		  : 0x00000000bbe2d2c0 (3152204480)
				  creation_time			: Thu Sep  7 18:40:16 2017 PDT
				  expiration_time		  : Thu Sep  7 20:30:31 2017 PDT
				  auth_time				: Thu Sep  7 18:40:16 2017 PDT
				  auth_session_info_seqnum : 0x00000001 (1)
				  auth_session_info		: *
					  auth_session_info: struct auth_session_info
						  security_token		   : *
							  security_token: struct security_token
								  num_sids				 : 0x00000023 (35)
								  sids: ARRAY(35)
									  sids					 : S-1-5-21-1909809274-676993417-9522986-1008
									  sids					 : S-1-5-21-1909809274-676993417-9522986-513
									  sids					 : S-1-5-21-1909809274-676993417-9522986-1166
									  sids					 : S-1-5-21-1909809274-676993417-9522986-1162
									  sids					 : S-1-5-21-1909809274-676993417-9522986-1100
									  sids					 : S-1-5-21-1909809274-676993417-9522986-1168
									  sids					 : S-1-5-21-1909809274-676993417-9522986-3346
									  sids					 : S-1-5-21-1909809274-676993417-9522986-512
									  sids					 : S-1-5-21-1909809274-676993417-9522986-2954
									  sids					 : S-1-5-21-1909809274-676993417-9522986-2955
									  sids					 : S-1-5-21-1909809274-676993417-9522986-1183
									  sids					 : S-1-5-21-1909809274-676993417-9522986-572
									  sids					 : S-1-1-0
									  sids					 : S-1-5-2
									  sids					 : S-1-5-11
									  sids					 : S-1-5-32-545
									  sids					 : S-1-5-32-544
									  sids					 : S-1-22-1-11008
									  sids					 : S-1-22-2-11008
									  sids					 : S-1-22-2-10513
									  sids					 : S-1-22-2-11166
									  sids					 : S-1-22-2-11162
									  sids					 : S-1-22-2-11100
									  sids					 : S-1-22-2-11168
									  sids					 : S-1-22-2-13346
									  sids					 : S-1-22-2-10512
									  sids					 : S-1-22-2-12954
									  sids					 : S-1-22-2-12955
									  sids					 : S-1-22-2-11183
									  sids					 : S-1-22-2-10572
									  sids					 : S-1-22-2-90000003
									  sids					 : S-1-22-2-90000004
									  sids					 : S-1-22-2-90000005
									  sids					 : S-1-22-2-90000002
									  sids					 : S-1-22-2-90000001
								  privilege_mask		   : 0x000000001ffffff0 (536870896)
										 1: SEC_PRIV_MACHINE_ACCOUNT_BIT
										 1: SEC_PRIV_PRINT_OPERATOR_BIT
										 1: SEC_PRIV_ADD_USERS_BIT
										 1: SEC_PRIV_DISK_OPERATOR_BIT
										 1: SEC_PRIV_REMOTE_SHUTDOWN_BIT
										 1: SEC_PRIV_BACKUP_BIT
										 1: SEC_PRIV_RESTORE_BIT
										 1: SEC_PRIV_TAKE_OWNERSHIP_BIT
										 1: SEC_PRIV_INCREASE_QUOTA_BIT
										 1: SEC_PRIV_SECURITY_BIT
										 1: SEC_PRIV_LOAD_DRIVER_BIT
										 1: SEC_PRIV_SYSTEM_PROFILE_BIT
										 1: SEC_PRIV_SYSTEMTIME_BIT
										 1: SEC_PRIV_PROFILE_SINGLE_PROCESS_BIT
										 1: SEC_PRIV_INCREASE_BASE_PRIORITY_BIT
										 1: SEC_PRIV_CREATE_PAGEFILE_BIT
										 1: SEC_PRIV_SHUTDOWN_BIT
										 1: SEC_PRIV_DEBUG_BIT
										 1: SEC_PRIV_SYSTEM_ENVIRONMENT_BIT
										 1: SEC_PRIV_CHANGE_NOTIFY_BIT
										 1: SEC_PRIV_UNDOCK_BIT
										 1: SEC_PRIV_ENABLE_DELEGATION_BIT
										 1: SEC_PRIV_MANAGE_VOLUME_BIT
										 1: SEC_PRIV_IMPERSONATE_BIT
										 1: SEC_PRIV_CREATE_GLOBAL_BIT
								  rights_mask			  : 0x00000000 (0)
										 0: LSA_POLICY_MODE_INTERACTIVE
										 0: LSA_POLICY_MODE_NETWORK
										 0: LSA_POLICY_MODE_BATCH
										 0: LSA_POLICY_MODE_SERVICE
										 0: LSA_POLICY_MODE_PROXY
										 0: LSA_POLICY_MODE_DENY_INTERACTIVE
										 0: LSA_POLICY_MODE_DENY_NETWORK
										 0: LSA_POLICY_MODE_DENY_BATCH
										 0: LSA_POLICY_MODE_DENY_SERVICE
										 0: LSA_POLICY_MODE_REMOTE_INTERACTIVE
										 0: LSA_POLICY_MODE_DENY_REMOTE_INTERACTIVE
									  0x00: LSA_POLICY_MODE_ALL	   (0)
									  0x00: LSA_POLICY_MODE_ALL_NT4   (0)
						  unix_token			   : *
							  unix_token: struct security_unix_token
								  uid					  : 0x0000000000002b00 (11008)
								  gid					  : 0x0000000000002911 (10513)
								  ngroups				  : 0x00000011 (17)
								  groups: ARRAY(17)
									  groups				   : 0x0000000000002b00 (11008)
									  groups				   : 0x0000000000002911 (10513)
									  groups				   : 0x0000000000002b9e (11166)
									  groups				   : 0x0000000000002b9a (11162)
									  groups				   : 0x0000000000002b5c (11100)
									  groups				   : 0x0000000000002ba0 (11168)
									  groups				   : 0x0000000000003422 (13346)
									  groups				   : 0x0000000000002910 (10512)
									  groups				   : 0x000000000000329a (12954)
									  groups				   : 0x000000000000329b (12955)
									  groups				   : 0x0000000000002baf (11183)
									  groups				   : 0x000000000000294c (10572)
									  groups				   : 0x00000000055d4a83 (90000003)
									  groups				   : 0x00000000055d4a84 (90000004)
									  groups				   : 0x00000000055d4a85 (90000005)
									  groups				   : 0x00000000055d4a82 (90000002)
									  groups				   : 0x00000000055d4a81 (90000001)
						  info					 : *
							  info: struct auth_user_info
								  account_name			 : *
									  account_name			 : 'philip'
								  user_principal_name	  : NULL
								  user_principal_constructed: 0x00 (0)
								  domain_name			  : *
									  domain_name			  : 'WEATHERITE'
								  dns_domain_name		  : NULL
								  full_name				: *
									  full_name				: 'Philip Spigelmire'
								  logon_script			 : *
									  logon_script			 : ''
								  profile_path			 : *
									  profile_path			 : ''
								  home_directory		   : *
									  home_directory		   : 'D:\Users Shared Folders\philip'
								  home_drive			   : *
									  home_drive			   : ''
								  logon_server			 : *
									  logon_server			 : 'BREEZE'
								  last_logon			   : Thu Sep  7 10:30:26 2017 PDT
								  last_logoff			  : Mon Jan 18 19:14:07 2038 PST
								  acct_expiry			  : Mon Jan 18 19:14:07 2038 PST
								  last_password_change	 : Wed Apr  9 18:29:53 2014 PDT
								  allow_password_change	: Wed Apr  9 18:29:53 2014 PDT
								  force_password_change	: Mon Jan 18 19:14:07 2038 PST
								  logon_count			  : 0x1e6f (7791)
								  bad_password_count	   : 0x0000 (0)
								  acct_flags			   : 0x00000010 (16)
								  authenticated			: 0x01 (1)
						  unix_info				: *
							  unix_info: struct auth_user_info_unix
								  unix_name				: *
									  unix_name				: 'WEATHERITE\philip'
								  sanitized_username	   : *
									  sanitized_username	   : 'philip'
						  torture				  : NULL
						  credentials			  : NULL
				  connection_dialect	   : 0x0202 (514)
				  signing_flags			: 0x04 (4)
						 0: SMBXSRV_SIGNING_REQUIRED
						 0: SMBXSRV_PROCESSED_SIGNED_PACKET
						 1: SMBXSRV_PROCESSED_UNSIGNED_PACKET
				  encryption_flags		 : 0x08 (8)
						 0: SMBXSRV_ENCRYPTION_REQUIRED
						 0: SMBXSRV_ENCRYPTION_DESIRED
						 0: SMBXSRV_PROCESSED_ENCRYPTED_PACKET
						 1: SMBXSRV_PROCESSED_UNENCRYPTED_PACKET
				  num_channels			 : 0x00000001 (1)
				  channels: ARRAY(1)
					  channels: struct smbXsrv_channel_global0
						  server_id: struct server_id
							  pid					  : 0x000000000000325b (12891)
							  task_id				  : 0x00000000 (0)
							  vnn					  : 0xffffffff (4294967295)
							  unique_id				: 0x05997161dd283775 (403478306762536821)
						  local_address			: 'ipv4:192.168.10.27:445'
						  remote_address		   : 'ipv4:192.168.10.18:56906'
						  remote_name			  : '192.168.10.18'
						  auth_session_info_seqnum : 0x00000001 (1)
						  connection			   : NULL
						  encryption_cipher		: 0x0000 (0)
[2017/09/07 18:40:39.899425,  3] ../source3/smbd/password.c:144(register_homes_share)
  Adding homes service for user 'WEATHERITE\philip' using home directory: '/home/WEATHERITE/philip'
[2017/09/07 18:40:39.910833,  3] ../lib/util/access.c:361(allow_access)
  Allowed connection from 192.168.10.18 (192.168.10.18)
[2017/09/07 18:40:39.911066,  3] ../source3/smbd/service.c:576(make_connection_snum)
  Connect path is '/mnt/tank/DFS' for service [DFS]
[2017/09/07 18:40:39.911186,  3] ../source3/smbd/vfs.c:113(vfs_init_default)
  Initialising default vfs hooks
[2017/09/07 18:40:39.911246,  3] ../source3/smbd/vfs.c:139(vfs_init_custom)
  Initialising custom vfs hooks from [/[Default VFS]/]
[2017/09/07 18:40:39.911305,  3] ../source3/smbd/vfs.c:139(vfs_init_custom)
  Initialising custom vfs hooks from [aio_pthread]
[2017/09/07 18:40:39.911691,  2] ../lib/util/modules.c:196(do_smb_load_module)
  Module 'aio_pthread' loaded
[2017/09/07 18:40:39.911762,  3] ../source3/smbd/vfs.c:139(vfs_init_custom)
  Initialising custom vfs hooks from [streams_xattr]
[2017/09/07 18:40:39.912247,  2] ../lib/util/modules.c:196(do_smb_load_module)
  Module 'streams_xattr' loaded
[2017/09/07 18:40:39.912317,  3] ../source3/smbd/vfs.c:139(vfs_init_custom)
  Initialising custom vfs hooks from [shadow_copy2]
[2017/09/07 18:40:39.912874,  2] ../lib/util/modules.c:196(do_smb_load_module)
  Module 'shadow_copy2' loaded
[2017/09/07 18:40:39.913702,  2] ../source3/smbd/service.c:822(make_connection_snum)
  192.168.10.18 (ipv4:192.168.10.18:56907) connect to service DFS initially as user WEATHERITE\philip (uid=11008, gid=10513) (pid 12923)
[2017/09/07 18:40:39.914869,  3] ../source3/smbd/smb2_server.c:3097(smbd_smb2_request_error_ex)
  smbd_smb2_request_error_ex: smbd_smb2_request_error_ex: idx[1] status[NT_STATUS_OBJECT_NAME_COLLISION] || at ../source3/smbd/smb2_create.c:293
[2017/09/07 18:40:39.916171,  2] ../source3/smbd/open.c:1322(open_file)
  WEATHERITE\philip opened file Company/New Text Document.txt read=No write=No (numopen=1)
[2017/09/07 18:40:39.917022,  2] ../source3/smbd/close.c:798(close_normal_file)
  WEATHERITE\philip closed file Company/New Text Document.txt (numopen=0) NT_STATUS_OK
[2017/09/07 18:40:39.919579,  3] ../source3/smbd/dir.c:656(dptr_create)
  creating new dirptr 0 for path Company, expect_close = 0
[2017/09/07 18:40:39.919785,  3] ../source3/smbd/dir.c:1227(smbd_dirptr_get_entry)
  smbd_dirptr_get_entry mask=[New Text Document.txt] found Company/New Text Document.txt fname=New Text Document.txt (New Text Document.txt)
[2017/09/07 18:40:39.922219,  3] ../source3/smbd/dir.c:656(dptr_create)
  creating new dirptr 0 for path Company, expect_close = 0
[2017/09/07 18:40:39.922385,  3] ../source3/smbd/dir.c:1227(smbd_dirptr_get_entry)
  smbd_dirptr_get_entry mask=[New Text Document.txt] found Company/New Text Document.txt fname=New Text Document.txt (New Text Document.txt)

And here is the smbd.conf

Code:

[global]
	server max protocol = SMB3_11
	encrypt passwords = yes
	dns proxy = no
	strict locking = no
	oplocks = yes
	deadtime = 15
	max log size = 51200
	max open files = 470504
	logging = file
	load printers = no
	printing = bsd
	printcap name = /dev/null
	disable spoolss = yes
	getwd cache = yes
	guest account = nobody
	map to guest = Bad User
	obey pam restrictions = yes
	ntlm auth = no
	directory name cache size = 0
	kernel change notify = no
	panic action = /usr/local/libexec/samba/samba-backtrace
	nsupdate command = /usr/local/bin/samba-nsupdate -g
	server string = FreeNAS Server
	ea support = yes
	store dos attributes = yes
	lm announce = yes
	unix extensions = no
	acl allow execute always = true
	dos filemode = yes
	multicast dns register = no
	domain logons = no
	idmap config *: backend = tdb
	idmap config *: range = 90000001-100000000
	server role = member server
	workgroup = WEATHERITE
	realm = WEATHERITE.INFO
	security = ADS
	client use spnego = yes
	local master = no
	domain master = no
	preferred master = no
	ads dns update = yes
	winbind cache time = 7200
	winbind offline logon = yes
	winbind enum users = yes
	winbind enum groups = yes
	winbind nested groups = yes
	winbind use default domain = no
	winbind refresh tickets = yes
	idmap config WEATHERITE: backend = rid
	idmap config WEATHERITE: range = 10000-90000000
	allow trusted domains = no
	client ldap sasl wrapping = plain
	template shell = /bin/sh
	template homedir = /home/%D/%U
	netbios name = FREENASLA1
	pid directory = /var/run/samba
	create mask = 0660
	directory mask = 0770
	client ntlmv2 auth = yes
	dos charset = CP437
	unix charset = UTF-8
	log level = 3
	ea support = no
	store dos attributes = no
	map archive = no
	map hidden = no
	map readonly = no
	map system = no


[DFS]
	path = "/mnt/tank/DFS"
	printable = no
	veto files = /.snapshot/.windows/.mac/.zfs/
	writeable = yes
	browseable = yes
	shadow:snapdir = .zfs/snapshot
	shadow:sort = desc
	shadow:localtime = yes
	shadow:format = auto-%Y%m%d.%H%M-1y
	shadow:snapdirseverywhere = yes
	vfs objects = shadow_copy2 streams_xattr aio_pthread
	hide dot files = yes
	guest ok = no
	nfs4:mode = special
	nfs4:acedup = merge
	nfs4:chown = true
	zfsacl:acesort = dontcare
	veto files = /*$RECYCLE.BIN/
	delete veto files = yes


[Special]
	path = "/mnt/tank/Special"
	printable = no
	veto files = /.snapshot/.windows/.mac/.zfs/
	writeable = yes
	browseable = no
	shadow:snapdir = .zfs/snapshot
	shadow:sort = desc
	shadow:localtime = yes
	shadow:format = auto-%Y%m%d.%H%M-1w
	shadow:snapdirseverywhere = yes
	vfs objects = shadow_copy2 streams_xattr aio_pthread
	hide dot files = yes
	guest ok = no
	nfs4:mode = special
	nfs4:acedup = merge
	nfs4:chown = true
	zfsacl:acesort = dontcare

I didn't have zfs_space or zfsacl vfs objects in my share config. My other servers had these and I see that Nicholas has them, but since that is the only thing I found different from my working servers, I added them to this server (I removed the DFS share and recreated it).

So far, it hasn't crashed again. I removed the zfs_space or zfsacl and it still doesn't crash. So I think recreating the share must of fixed a config somewhere. I don't see any differences in the smbd.conf before and after though.

This particular server is about a year older than the others and started on an earlier FreeNAS version, so it's configuration has gone through more upgrades.

I will keep an eye on it and report back if it crashes again.

napalmd · Sep 22, 2017

I also just got this problem on a new server I installed. It was running fine for a week or so and then samba service stopped with "signal 6 core dumped", and before that was the "failed to fully fault in a core file segment" error.
Latest version of freenas installed 11.0 U3
I've increased samba log level and will see if it crashes again...

aionica · Sep 23, 2017

I have the same problem. Since upgrading to FreeNAS-11.0-U3 (c5dcf4416) from 9.10 I can't write to samba shares. I get a crash each time a try to copy a file and on the server side I see a 0 bytes file created.
As I client I have MacOS 10.12.6 . If I use a Windows 10 Home edition client then it first gets the same 0 bytes file but then it offers to overwrite it and indeed it succeeds (same behaviour doesn't happen or work on MacOS).

Because after upgrading I had some isssues with incorrect SIDs and I had to muck around with them my first thought was that its related so I proceeded to:
- stop samba
- backup /var/db/system/samba4
- run find /var/db/system/samba4 -type f -name '*\.tdb' | xargs rm
- started samba
- run smbpasswd and add back my users
This didn't provide any change so I stopped samba , restored backup of /var/db/system/samba4 and started back samba

Then I adjusted various stuff (like removed the socket options I pass, removed force users from shares, etc) but no difference was made so I reverted my changes back.

Logfile looks like:

Code:

[2017/09/24 13:08:22.581166, 10, pid=66479, effective(1001, 1001), real(0, 0)] ../lib/dbwrap/dbwrap_tdb.c:143(db_tdb_fetch_locked_internal)
  Allocated locked data 0x0x8120cd0a0
[2017/09/24 13:08:22.581279, 10, pid=66479, effective(1001, 1001), real(0, 0), class=locking] ../source3/locking/brlock.c:2049(brl_get_locks_readonly)
  seqnum=18, fsp->brlock_seqnum=0
[2017/09/24 13:08:22.581377,  5, pid=66479, effective(1001, 1001), real(0, 0), class=locking] ../source3/smbd/oplock.c:86(set_file_oplock)
  set_file_oplock: granted oplock on file alex/access_point.txt, 3163aa9d:5073:0/3459081168, tv_sec = 59c721a6, tv_usec = 8b814
[2017/09/24 13:08:22.581480, 10, pid=66479, effective(1001, 1001), real(0, 0), class=locking] ../source3/locking/brlock.c:2049(brl_get_locks_readonly)
  seqnum=18, fsp->brlock_seqnum=18
[2017/09/24 13:08:22.581556, 10, pid=66479, effective(1001, 1001), real(0, 0)] ../source3/smbd/open.c:2208(grant_fsp_oplock_type)
  grant_fsp_oplock_type: oplock type 0x0 on file alex/access_point.txt
[2017/09/24 13:08:22.581631, 10, pid=66479, effective(1001, 1001), real(0, 0)] ../source3/smbd/dosmode.c:678(file_set_dosmode)
  file_set_dosmode: setting dos mode 0x20 on file alex/access_point.txt
[2017/09/24 13:08:22.581770, 10, pid=66479, effective(1001, 1001), real(0, 0)] ../source3/smbd/dosmode.c:406(set_ea_dos_attribute)
  set_ea_dos_attributes: set attribute 0x20, btime = Sun Sep 24 13:08:23 2017
   on file alex/access_point.txt
[2017/09/24 13:08:22.583097, 10, pid=66479, effective(1001, 1001), real(0, 0)] ../source3/modules/vfs_shadow_copy2.c:609(shadow_copy2_strip_snapshot_internal)
  ../source3/modules/vfs_shadow_copy2.c:609: enter path 'alex/access_point.txt'
[2017/09/24 13:08:22.583237, 10, pid=66479, effective(1001, 1001), real(0, 0)] ../source3/modules/vfs_shadow_copy2.c:618(shadow_copy2_strip_snapshot_internal)
  ../source3/modules/vfs_shadow_copy2.c:618: abs path '/mnt/storage/storage1/alex/access_point.txt'
[2017/09/24 13:08:22.583614, 10, pid=66479, effective(1001, 1001), real(0, 0)] ../source3/smbd/dosmode.c:476(set_ea_dos_attribute)
  set_ea_dos_attribute: set EA 0x20 on file alex/access_point.txt
Assertion failed: (_entry_brand(a) == ACL_BRAND_POSIX), function _posix1e_acl_entry_compare, file /freenas-11-releng/freenas/_BE/os/lib/libc/posix1e/acl_support.c, line 96.
[2017/09/24 13:08:22.584256,  0, pid=66479, effective(1001, 1001), real(0, 0)] ../lib/util/fault.c:78(fault_report)
  ===============================================================
[2017/09/24 13:08:22.584334,  0, pid=66479, effective(1001, 1001), real(0, 0)] ../lib/util/fault.c:79(fault_report)
  INTERNAL ERROR: Signal 6 in pid 66479 (4.6.4-GIT-d1d80f3)
  Please read the Trouble-Shooting section of the Samba HOWTO
[2017/09/24 13:08:22.584442,  0, pid=66479, effective(1001, 1001), real(0, 0)] ../lib/util/fault.c:81(fault_report)
  ===============================================================
[2017/09/24 13:08:22.584510,  0, pid=66479, effective(1001, 1001), real(0, 0)] ../source3/lib/util.c:791(smb_panic_s3)
  PANIC (pid 66479): internal error
[2017/09/24 13:08:22.586487,  0, pid=66479, effective(1001, 1001), real(0, 0)] ../source3/lib/util.c:902(log_stack_trace)
  BACKTRACE: 7 stack frames:
   #0 0x803262d1e <log_stack_trace+0x1e> at /usr/local/lib/libsmbconf.so.0
   #1 0x803262b18 <smb_panic_s3+0x98> at /usr/local/lib/libsmbconf.so.0
   #2 0x800c9a597 <smb_panic+0x27> at /usr/local/lib/libsamba-util.so.0
   #3 0x800c9ab40 <string_sub_once> at /usr/local/lib/libsamba-util.so.0
   #4 0x800c9a563 <fault_setup+0x73> at /usr/local/lib/libsamba-util.so.0
   #5 0x8008488b6 <pthread_sigmask+0x4f6> at /lib/libthr.so.3
   #6 0x800847e9f <pthread_getspecific+0xe5f> at /lib/libthr.so.3
[2017/09/24 13:08:22.586848,  0, pid=66479, effective(1001, 1001), real(0, 0)] ../source3/lib/util.c:803(smb_panic_s3)
  smb_panic(): calling panic action [/usr/local/libexec/samba/samba-backtrace]
mv: rename /var/log/samba4/samba.backtraces to /var/log/samba4/samba.backtraces.20170924130822: Permission denied

Config file (some shares were removed from output for privacy reasons, but they were different than the one I'm testing on)

Code:

[global]
	server max protocol = SMB3_11
	interfaces = 127.0.0.1 A_REDACTED_LAN_IP_ADDRESS
	bind interfaces only = yes
	encrypt passwords = yes
	dns proxy = no
	strict locking = no
	oplocks = yes
	deadtime = 15
	max log size = 51200
	max open files = 226928
	logging = file
	load printers = no
	printing = bsd
	printcap name = /dev/null
	disable spoolss = yes
	getwd cache = yes
	guest account = nobody
	map to guest = Bad User
	obey pam restrictions = yes
	ntlm auth = no
	directory name cache size = 0
	kernel change notify = no
	panic action = /usr/local/libexec/samba/samba-backtrace
	nsupdate command = /usr/local/bin/samba-nsupdate -g
	server string = FreeNAS Server
	ea support = yes
	store dos attributes = yes
	lm announce = yes
	unix extensions = no
	time server = yes
	acl allow execute always = true
	dos filemode = yes
	multicast dns register = yes
	domain logons = no
	local master = yes
	idmap config *: backend = tdb
	idmap config *: range = 90000001-100000000
	server role = standalone
	netbios name = FREENAS
	workgroup = BG.ORG
	security = user
	pid directory = /var/run/samba
	create mask = 0666
	directory mask = 0777
	client ntlmv2 auth = yes
	dos charset = CP437
	unix charset = UTF-8
	log level = 1
	socket options = TCP_NODELAY IPTOS_LOWDELAY SO_RCVBUF=131072 SO_SNDBUF=131072
	min receivefile size = 131072
	write cache size = 131072


[storage]
	path = "/mnt/storage/storage1"
	printable = no
	veto files = /.snapshot/.windows/.mac/.zfs/
	writeable = yes
	browseable = yes
	shadow:snapdir = .zfs/snapshot
	shadow:sort = desc
	shadow:localtime = yes
	shadow:format = auto-%Y%m%d.%H%M-1m
	shadow:snapdirseverywhere = yes
	vfs objects = shadow_copy2
	hide dot files = no
	guest ok = no
	nfs4:mode = special
	nfs4:acedup = merge
	nfs4:chown = true
	zfsacl:acesort = dontcare
	force user = some_redacted_username
	force group = some_redacted_username
	valid users = @some_redacted_groupname some_redacted_username

The error (from above) seems to be:

Code:

Assertion failed: (_entry_brand(a) == ACL_BRAND_POSIX), function _posix1e_acl_entry_compare, file /freenas-11-releng/freenas/_BE/os/lib/libc/posix1e/acl_support.c, line 96.

aionica · Sep 27, 2017

I've just upgraded to FreeNAS-11.0-U4 (54848d13b) . The situation remains unchanged

Code:

Assertion failed: (_entry_brand(a) == ACL_BRAND_POSIX), function _posix1e_acl_entry_compare, file /freenas-11-releng/freenas/_BE/os/lib/libc/posix1e/acl_support.c, line 96.
[2017/09/27 20:43:17.338328,  0] ../lib/util/fault.c:78(fault_report)
  ===============================================================
[2017/09/27 20:43:17.338421,  0] ../lib/util/fault.c:79(fault_report)
  INTERNAL ERROR: Signal 6 in pid 6964 (4.6.8-GIT-7a91926)
  Please read the Trouble-Shooting section of the Samba HOWTO
[2017/09/27 20:43:17.338515,  0] ../lib/util/fault.c:81(fault_report)
  ===============================================================
[2017/09/27 20:43:17.338592,  0] ../source3/lib/util.c:791(smb_panic_s3)
  PANIC (pid 6964): internal error
[2017/09/27 20:43:17.340957,  0] ../source3/lib/util.c:902(log_stack_trace)
  BACKTRACE: 7 stack frames:
   #0 0x803262d1e <log_stack_trace+0x1e> at /usr/local/lib/libsmbconf.so.0
   #1 0x803262b18 <smb_panic_s3+0x98> at /usr/local/lib/libsmbconf.so.0
   #2 0x800c9a597 <smb_panic+0x27> at /usr/local/lib/libsamba-util.so.0
   #3 0x800c9ab40 <string_sub_once> at /usr/local/lib/libsamba-util.so.0
   #4 0x800c9a563 <fault_setup+0x73> at /usr/local/lib/libsamba-util.so.0
   #5 0x8008488b6 <pthread_sigmask+0x4f6> at /lib/libthr.so.3
   #6 0x800847e9f <pthread_getspecific+0xe5f> at /lib/libthr.so.3
[2017/09/27 20:43:17.341331,  0] ../source3/lib/util.c:803(smb_panic_s3)
  smb_panic(): calling panic action [/usr/local/libexec/samba/samba-backtrace]
mv: rename /var/log/samba4/samba.backtraces to /var/log/samba4/samba.backtraces.20170927204317: Permission denied
ptrace: Operation not permitted.

aionica · Sep 27, 2017

I've found the problem (at least in my case). I've started truss and attached to the smbd pid corresponding to my session and then proceeded to cause a crash. The last lines of output are:

Code:

open("/usr/lib/i18n",O_RDONLY|O_NONBLOCK|O_DIRECTORY|O_CLOEXEC,040100200) = 42 (0x2a)
fstatfs(42,{ fstypename=zfs,mntonname=/,mntfromname=freenas-boot/ROOT/11.0-U4,fsid= }) = 0 (0x0)
getdirentries(0x2a,0x81208c000,0x1000,0x81201d868) = 1144 (0x478)
getdirentries(0x2a,0x81208c000,0x1000,0x81201d868) = 0 (0x0)
close(42)					 = 0 (0x0)
open("/usr/share/i18n/csmapper/charset.alias.db",O_RDONLY|O_CLOEXEC,037777706430) ERR#2 'No such file or directory'
open("/usr/share/i18n/csmapper/charset.alias",O_RDONLY|O_CLOEXEC,0507263030) ERR#2 'No such file or directory'
open("/usr/share/i18n/csmapper/charset.alias.db",O_RDONLY|O_CLOEXEC,037777706430) ERR#2 'No such file or directory'
open("/usr/share/i18n/csmapper/charset.alias",O_RDONLY|O_CLOEXEC,0507263030) ERR#2 'No such file or directory'
open("/usr/share/i18n/csmapper/mapper.dir",O_RDONLY|O_CLOEXEC,037777704450) = 42 (0x2a)
fstat(42,{ mode=-r--r--r-- ,inode=125265,size=45300,blksize=45568 }) = 0 (0x0)
mmap(0x0,45300,PROT_READ,MAP_PRIVATE,42,0x0)	 = 34392981504 (0x801fb4000)
close(42)					 = 0 (0x0)
munmap(0x801fb4000,45300)			 = 0 (0x0)
open("/usr/lib/i18n",O_RDONLY|O_NONBLOCK|O_DIRECTORY|O_CLOEXEC,020040100200) = 42 (0x2a)
fstatfs(42,{ fstypename=zfs,mntonname=/,mntfromname=freenas-boot/ROOT/11.0-U4,fsid= }) = 0 (0x0)
getdirentries(0x2a,0x81208c000,0x1000,0x81201d868) = 1144 (0x478)
getdirentries(0x2a,0x81208c000,0x1000,0x81201d868) = 0 (0x0)
close(42)					 = 0 (0x0)
open("/usr/share/i18n/csmapper/CP/UCS%CP437.mps",O_RDONLY|O_CLOEXEC,037777702170) = 42 (0x2a)
fstat(42,{ mode=-r--r--r-- ,inode=124795,size=262288,blksize=131072 }) = 0 (0x0)
mmap(0x0,262288,PROT_READ,MAP_PRIVATE,42,0x0)	 = 34421895168 (0x803b47000)
close(42)					 = 0 (0x0)
extattr_set_file(0x8120ed300,0x1,0x801379cac,0x812017460,0x38) = 56 (0x38)
fpathconf(0x27,0x40)				 = 1 (0x1)
__acl_get_fd(0x27,0x4,0x8121e4000)		 = 0 (0x0)
write(2,"Assertion failed: (_entry_brand("...,173) = 173 (0xad)
sigprocmask(SIG_SETMASK,{ SIGHUP|SIGINT|SIGQUIT|SIGILL|SIGTRAP|SIGEMT|SIGFPE|SIGKILL|SIGBUS|SIGSEGV|SIGSYS|SIGPIPE|SIGALRM|SIGTERM|SIGURG|SIGSTOP|SIGTSTP|SIGCONT|SIGCHLD|SIGTTIN|SIGTTOU|SIGIO|SIGXCPU|SIGXFSZ|SIGVTALRM|SIGPROF|SIGWINCH|SIGINFO|SIGUSR1|SIGUSR2 },0x0) = 0 (0x0)
thr_self(0x7fffffffc300)			 = 0 (0x0)
thr_kill(102035,SIGABRT)			 = 0 (0x0)

Just before the Assertion Failed message I can see:

Code:

__acl_get_fd(0x27,0x4,0x8121e4000)		= 0 (0x0)

Digging up through output I didn't paste here, it turns out that file handle 0x27 corresponds to the file I was trying to write to the share.

This lead me to believe there is something going wrong related to Unix extended ACLs. After a bit of digging I realised there are several Samba VFS modules related to ACLs and further for that for some reason this particular share did not have them while others did.
So before:

Code:

vfs objects = shadow_copy2

and after adding vfs objects available for other shares:

Code:

vfs objects = shadow_copy2 zfs_space zfsacl streams_xattr aio_pthread

Restarted samba and things work normally now.
I have no idea how I ended up in this situation but I suspect it's something regarding the upgrade to FreeNas 11 . I am sure I didn't poke around with such settings ever.

Ericloewe · Sep 27, 2017

Could you update the bug ticket with your findings? It might help the devs figure out what's going on.

Nicholas M · Sep 27, 2017

Well it took longer than expected, but it crashed 5 mins ago.

At the same time, it looks like a drive has dropped from the vdev. (timeout errors in messages.log). Still running FN11 U1.

messages.log

Code:

Sep 25 04:50:00 abney (da18:mpr0:0:65:0):
Sep 25 04:50:00 abney (da18:mpr0:0:65:0): Field Replaceable Unit: 0
Sep 25 04:50:00 abney (da18:mpr0:0:65:0): Command Specific Info: 0
Sep 25 04:50:00 abney (da18:mpr0:0:65:0): Actual Retry Count: 125
Sep 25 04:50:00 abney (da18:mpr0:0:65:0): Descriptor 0x80: f7 2d
Sep 25 04:50:00 abney (da18:mpr0:0:65:0): Descriptor 0x81: 01 38 d9 0c 0(da18:mpr0:0:65:0): Error 5, Unretryable error
Sep 25 06:33:38 abney (da108:mpr1:0:65:0): READ(16). CDB: 88 00 00 00 00 01 2e 09 78 20 00 00 01 00 00 00
Sep 25 06:33:38 abney (da108:mpr1:0:65:0): CAM status: SCSI Status Error
Sep 25 06:33:38 abney (da108:mpr1:0:65:0): SCSI status: Check Condition
Sep 25 06:33:38 abney (da108:mpr1:0:65:0): SCSI sense: MEDIUM ERROR asc:11,0 (Unrecovered read error)
Sep 25 06:33:38 abney (da108:mpr1:0:65:0):
Sep 25 06:33:38 abney (da108:mpr1:0:65:0): Field Replaceable Unit: 0
Sep 25 06:33:38 abney (da108:mpr1:0:65:0): Command Specific Info: 0
Sep 25 06:33:38 abney (da108:mpr1:0:65:0): Actual Retry Count: 1405
Sep 25 06:33:38 abney (da108:mpr1:0:65:0): Descriptor 0x80: f7 2d
Sep 25 06:33:38 abney (da108:mpr1:0:65:0): Descriptor 0x81: 01(da108:mpr1:0:65:0): Error 5, Unretryable error
Sep 25 06:33:38 abney GEOM_MULTIPATH: Error 5, da108 in 18_6GTV_3_6 marked FAIL
Sep 25 06:33:38 abney GEOM_MULTIPATH: all paths in 18_6GTV_3_6 were marked FAIL, restore da18
Sep 25 06:33:41 abney (da18:mpr0:0:65:0): READ(16). CDB: 88 00 00 00 00 01 2e 09 78 20 00 00 01 00 00 00
Sep 25 06:33:41 abney (da18:mpr0:0:65:0): CAM status: SCSI Status Error
Sep 25 06:33:41 abney (da18:mpr0:0:65:0): SCSI status: Check Condition
Sep 25 06:33:41 abney (da18:mpr0:0:65:0): SCSI sense: MEDIUM ERROR asc:11,0 (Unrecovered read error)
Sep 25 06:33:41 abney (da18:mpr0:0:65:0):
Sep 25 06:33:41 abney (da18:mpr0:0:65:0): Field Replaceable Unit: 0
Sep 25 06:33:41 abney (da18:mpr0:0:65:0): Command Specific Info: 0
Sep 25 06:33:41 abney (da18:mpr0:0:65:0): Actual Retry Count: 1405
Sep 25 06:33:41 abney (da18:mpr0:0:65:0): Descriptor 0x80: f7 2d
Sep 25 06:33:41 abney (da18:mpr0:0:65:0): Descriptor 0x81: 01 68 76 0c (da18:mpr0:0:65:0): Error 5, Unretryable error
Sep 25 06:33:41 abney GEOM_MULTIPATH: Error 5, da18 in 18_6GTV_3_6 marked FAIL
Sep 25 06:33:41 abney GEOM_MULTIPATH: all paths in 18_6GTV_3_6 were marked FAIL, restore da108
Sep 25 06:33:42 abney ZFS: vdev state changed, pool_guid=8953964995138066495 vdev_guid=2658964524373063210
Sep 26 00:00:00 abney syslog-ng[2360]: Configuration reload request received, reloading configuration;
Sep 26 06:22:29 abney collectd[6753]: aggregation plugin: Unable to read the current rate of "abney/cpu-3/cpu-user".
Sep 26 06:22:29 abney collectd[6753]: utils_vl_lookup: The user object callback failed with status 2.
Sep 26 13:06:09 abney collectd[6753]: aggregation plugin: Unable to read the current rate of "abney/cpu-3/cpu-user".
Sep 26 13:06:09 abney collectd[6753]: aggregation plugin: Unable to read the current rate of "abney/cpu-4/cpu-user".
Sep 26 13:06:09 abney collectd[6753]: utils_vl_lookup: The user object callback failed with status 2.
Sep 26 13:06:09 abney collectd[6753]: aggregation plugin: Unable to read the current rate of "abney/cpu-0/cpu-user".
Sep 26 13:06:09 abney collectd[6753]: utils_vl_lookup: The user object callback failed with status 2.
Sep 26 13:06:09 abney collectd[6753]: utils_vl_lookup: The user object callback failed with status 2.
Sep 26 23:30:39 abney collectd[6753]: aggregation plugin: Unable to read the current rate of "abney/cpu-0/cpu-user".
Sep 26 23:30:39 abney collectd[6753]: utils_vl_lookup: The user object callback failed with status 2.
Sep 27 00:00:00 abney syslog-ng[2360]: Configuration reload request received, reloading configuration;
Sep 27 13:30:29 abney collectd[6753]: aggregation plugin: Unable to read the current rate of "abney/cpu-2/cpu-user".
Sep 27 13:30:29 abney collectd[6753]: utils_vl_lookup: The user object callback failed with status 2.
Sep 27 13:46:50 abney kernel: Failed to fully fault in a core file segment at VA 0x800f64000 with size 0x3000 to be written at offset 0x2a1000 for process smbd
Sep 27 13:46:50 abney kernel: Failed to fully fault in a core file segment at VA 0x800f64000 with size 0x3000 to be written at offset 0x2a1000 for process smbd
Sep 27 13:46:51 abney kernel: pid 83446 (smbd), uid 0: exited on signal 6 (core dumped)

Last few lines from smbd.log

Code:


[2017/09/27 13:46:48.812107,  3] ../source3/smbd/trans2.c:8398(smbd_do_setfilepathinfo)
  smbd_do_setfilepathinfo: CVDATA_09/CV_MAGNETIC/V_946536/CHUNK_42813275/SFILE_CONTAINER_245 (fnum 1343151921) info_level=1013 totdata=1
[2017/09/27 13:46:48.812168,  3] ../source3/smbd/smb2_server.c:3097(smbd_smb2_request_error_ex)
  smbd_smb2_request_error_ex: smbd_smb2_request_error_ex: idx[1] status[NT_STATUS_OBJECT_NAME_NOT_FOUND] || at ../source3/smbd/smb2_create.c:293
[2017/09/27 13:46:48.812572,  3] ../source3/smbd/smb2_server.c:3097(smbd_smb2_request_error_ex)
  smbd_smb2_request_error_ex: smbd_smb2_request_error_ex: idx[1] status[NT_STATUS_OBJECT_NAME_NOT_FOUND] || at ../source3/smbd/smb2_create.c:293
[2017/09/27 13:46:48.812737,  2] ../source3/smbd/close.c:798(close_normal_file)
  cvsmb closed file CVDATA_09/CV_MAGNETIC/V_946536/CHUNK_42813275/SFILE_CONTAINER_245 (numopen=2) NT_STATUS_OK
[2017/09/27 13:46:48.813102,  2] ../source3/smbd/open.c:1322(open_file)
  cvsmb opened file CVDATA_09/CV_MAGNETIC/V_946538/CHUNK_42813277/SFILE_CONTAINER_235 read=No write=No (numopen=3)
[2017/09/27 13:46:48.813276,  2] ../source3/smbd/open.c:1322(open_file)
  cvsmb opened file CVDATA_09/CV_MAGNETIC/V_946536/CHUNK_42813275/SFILE_CONTAINER_246 read=No write=No (numopen=3)
[2017/09/27 13:46:48.813398,  3] ../source3/smbd/trans2.c:8398(smbd_do_setfilepathinfo)
  smbd_do_setfilepathinfo: CVDATA_09/CV_MAGNETIC/V_946538/CHUNK_42813277/SFILE_CONTAINER_235 (fnum 3305407138) info_level=1013 totdata=1
[2017/09/27 13:46:48.813553,  2] ../source3/smbd/close.c:798(close_normal_file)
  cvsmb closed file CVDATA_09/CV_MAGNETIC/V_946536/CHUNK_42813275/SFILE_CONTAINER_246 (numopen=2) NT_STATUS_OK
[2017/09/27 13:46:48.814148,  3] ../source3/smbd/smb2_server.c:3097(smbd_smb2_request_error_ex)
  smbd_smb2_request_error_ex: smbd_smb2_request_error_ex: idx[1] status[NT_STATUS_OBJECT_NAME_NOT_FOUND] || at ../source3/smbd/smb2_create.c:293
[2017/09/27 13:46:48.814177,  2] ../source3/smbd/close.c:798(close_normal_file)
  cvsmb closed file CVDATA_09/CV_MAGNETIC/V_946538/CHUNK_42813277/SFILE_CONTAINER_235 (numopen=2) NT_STATUS_OK
[2017/09/27 13:46:48.814609,  3] ../source3/smbd/smb2_server.c:3097(smbd_smb2_request_error_ex)
  smbd_smb2_request_error_ex: smbd_smb2_request_error_ex: idx[1] status[NT_STATUS_OBJECT_NAME_NOT_FOUND] || at ../source3/smbd/smb2_create.c:293
[2017/09/27 13:46:48.814775,  2] ../source3/smbd/open.c:1322(open_file)
  cvsmb opened file CVDATA_09/CV_MAGNETIC/V_946538/CHUNK_42813277/SFILE_CONTAINER_236 read=No write=No (numopen=3)
ptrace: Device busy.
[2017/09/27 13:46:48.815041,  2] ../source3/smbd/close.c:798(close_normal_file)
  cvsmb closed file CVDATA_09/CV_MAGNETIC/V_946538/CHUNK_42813277/SFILE_CONTAINER_236 (numopen=2) NT_STATUS_OK
[2017/09/27 13:46:48.815149,  2] ../source3/smbd/open.c:1322(open_file)
  cvsmb opened file CVDATA_09/CV_MAGNETIC/V_946536/CHUNK_42813275/SFILE_CONTAINER_246 read=No write=No (numopen=3)
[2017/09/27 13:46:48.815479,  3] ../source3/smbd/trans2.c:8398(smbd_do_setfilepathinfo)
  smbd_do_setfilepathinfo: CVDATA_09/CV_MAGNETIC/V_946536/CHUNK_42813275/SFILE_CONTAINER_246 (fnum 1984553841) info_level=1013 totdata=1
[2017/09/27 13:46:48.815536,  3] ../source3/smbd/smb2_server.c:3097(smbd_smb2_request_error_ex)
  smbd_smb2_request_error_ex: smbd_smb2_request_error_ex: idx[1] status[NT_STATUS_OBJECT_NAME_NOT_FOUND] || at ../source3/smbd/smb2_create.c:293
[2017/09/27 13:46:48.815943,  3] ../source3/smbd/smb2_server.c:3097(smbd_smb2_request_error_ex)
  smbd_smb2_request_error_ex: smbd_smb2_request_error_ex: idx[1] status[NT_STATUS_OBJECT_NAME_NOT_FOUND] || at ../source3/smbd/smb2_create.c:293
[2017/09/27 13:46:48.816461,  2] ../source3/smbd/open.c:1322(open_file)
  cvsmb opened file CVDATA_09/CV_MAGNETIC/V_946538/CHUNK_42813277/SFILE_CONTAINER_236 read=No write=No (numopen=3)
[2017/09/27 13:46:48.816748,  3] ../source3/smbd/trans2.c:8398(smbd_do_setfilepathinfo)
  smbd_do_setfilepathinfo: CVDATA_09/CV_MAGNETIC/V_946538/CHUNK_42813277/SFILE_CONTAINER_236 (fnum 2935666002) info_level=1013 totdata=1
[2017/09/27 13:46:48.823838,  2] ../source3/smbd/close.c:798(close_normal_file)
  cvsmb closed file CVDATA_09/CV_MAGNETIC/V_946538/CHUNK_42813277/SFILE_CONTAINER_236 (numopen=2) NT_STATUS_OK
[2017/09/27 13:46:48.824031,  2] ../source3/smbd/close.c:798(close_normal_file)
  cvsmb closed file CVDATA_09/CV_MAGNETIC/V_946538/CHUNK_42813277/.compactlock (numopen=1) NT_STATUS_OK
[2017/09/27 13:46:48.824128,  2] ../source3/smbd/close.c:798(close_normal_file)
  cvsmb closed file CVDATA_09/CV_MAGNETIC/V_946538/CHUNK_42813277/SFILE_CONTAINER.idx (numopen=0) NT_STATUS_OK
[2017/09/27 13:46:48.824187,  2] ../source3/smbd/service.c:1098(close_cnum)
  jackson (ipv4:10.150.1.9:59792) closed connection to service POOL_09_CIFS
[2017/09/27 13:46:48.825867,  2] ../source3/smbd/close.c:798(close_normal_file)
  cvsmb closed file CVDATA_09/CV_MAGNETIC/V_946536/CHUNK_42813275/SFILE_CONTAINER_246 (numopen=2) NT_STATUS_OK
[2017/09/27 13:46:48.826058,  2] ../source3/smbd/close.c:798(close_normal_file)
  cvsmb closed file CVDATA_09/CV_MAGNETIC/V_946536/CHUNK_42813275/.compactlock (numopen=1) NT_STATUS_OK
[2017/09/27 13:46:48.826217,  2] ../source3/smbd/close.c:798(close_normal_file)
  cvsmb closed file CVDATA_09/CV_MAGNETIC/V_946536/CHUNK_42813275/SFILE_CONTAINER.idx (numopen=0) NT_STATUS_OK
[2017/09/27 13:46:48.826279,  2] ../source3/smbd/service.c:1098(close_cnum)
  stagg (ipv4:10.150.1.10:55263) closed connection to service POOL_09_CIFS
[2017/09/27 13:46:48.828659,  3] ../source3/smbd/server_exit.c:246(exit_server_common)
  Server exit (termination signal)
[2017/09/27 13:46:48.830327,  3] ../source3/smbd/server_exit.c:246(exit_server_common)
  Server exit (termination signal)
ptrace: Device busy.
[2017/09/27 13:46:50.107487,  0] ../source3/lib/util.c:811(smb_panic_s3)
  smb_panic(): action returned status 0
[2017/09/27 13:46:50.107785,  0] ../source3/lib/dumpcore.c:315(dump_core)
  dumping core in /var/db/system/cores

PhilipS · Oct 4, 2017

Nicholas M said:
Well it took longer than expected, but it crashed 5 mins ago.

At the same time, it looks like a drive has dropped from the vdev. (timeout errors in messages.log). Still running FN11 U1.

Your issue looks like you have a hardware issue. I would check the smart status and run a scrub to see what happens. These things should be done regularly.

PhilipS · Oct 4, 2017

aionica said:
and after adding vfs objects available for other shares:

Code:
vfs objects = shadow_copy2 zfs_space zfsacl streams_xattr aio_pthread

Curiously, if you remove these added vfs objects, will it crash again? I added zfs_space and zfsacl as they were found missing on mine which seemed to fix the issue. I then removed them and tested again and it still didn't crash. I'm a bit perplexed at this. I didn't leave them removed though, as I didn't want the problem to re-occur.

Scampicfx · Nov 24, 2017

Hey guys,
I just encountered the same error using FreeNAS-11.0-U4.

Code:

Nov 24 03:13:06 SERVER kernel: Failed to fully fault in a core file segment at VA 0x800f89000 with size 0x3000 to be written at offset 0x2d7000 for process smbd
Nov 24 03:13:06 SERVER kernel: Failed to fully fault in a core file segment at VA 0x800f89000 with size 0x3000 to be written at offset 0x2d7000 for process smbd
Nov 24 03:13:06 SERVER kernel: pid 60266 (smbd), uid 0: exited on signal 6 (core dumped)

What I found interesting: The server itself was running stable for weeks now.
The only thing I touched a few hours before this error happened was trying hardly to change permissions with chmod and so on.
Since I learned that this is not a bug but a feature when dealing with windows SMB shares (;)), I decided to redo all permissions for this particular dataset from scratch.

Storage -> Volumes
I selected the dataset. I clicked on "Change Permissions" (although at this moment, for this dataset a SMB share was configured!)

I applied following values:

Code:

apply owner (user): checkmark
owner (user): admin
apply owner (group): checkmark
owner (group): systems
apply mode: checkmark
mode: greyed out
permission type: windows
set permission recursively: no (because there are no sub-datasets).

Afterwards I connected via admin to this windows-smb-share and reconfigured the permissions. Everything was fine so far. However, a few hours later, this error occured.

I'm quite sure, that it has something to do with this reconfiguration!

Wouter · Jan 2, 2018

Nicholas M said:
Wondering if anyone else has the SMBD issue on FN11.0-U1 before raising it as a bug?

I had the same yesterday, after a successful upgrade from 9.10 to 11.1 and running stable for a few days:

Code:

Failed to fully fault in a core file segment at VA 0x819f39000 with size 0xd000 to be written at offset 0x858a000 for process smbd
pid 74692 (smbd), uid 0: exited on signal 6 (core dumped)

Just before this error, I see the following in my (remote) syslog:

Code:

Jan  2 09:09:50 s smbd[74692]: [2018/01/02 09:09:50.388800,  0] ../source3/lib/util.c:804(smb_panic_s3)
Jan  2 09:09:50 s smbd[74692]:   PANIC (pid 74692): internal error
Jan  2 09:09:50 s smbd[74692]: [2018/01/02 09:09:50.393219,  0] ../source3/lib/util.c:915(log_stack_trace)
Jan  2 09:09:50 s smbd[74692]:   BACKTRACE: 7 stack frames:
Jan  2 09:09:50 s smbd[74692]:	#0 0x80326f31e <log_stack_trace+0x1e> at /usr/local/lib/libsmbconf.so.0
Jan  2 09:09:50 s smbd[74692]:	#1 0x80326f118 <smb_panic_s3+0x98> at /usr/local/lib/libsmbconf.so.0
Jan  2 09:09:50 s smbd[74692]:	#2 0x800c9e597 <smb_panic+0x27> at /usr/local/lib/libsamba-util.so.0
Jan  2 09:09:50 s smbd[74692]:	#3 0x800c9eb40 <string_sub_once> at /usr/local/lib/libsamba-util.so.0
Jan  2 09:09:50 s smbd[74692]:	#4 0x800c9e563 <fault_setup+0x73> at /usr/local/lib/libsamba-util.so.0
Jan  2 09:09:50 s smbd[74692]:	#5 0x80084a8f6 <pthread_sigmask+0x536> at /lib/libthr.so.3
Jan  2 09:09:50 s smbd[74692]:	#6 0x800849e9f <pthread_getspecific+0xe2f> at /lib/libthr.so.3
Jan  2 09:09:50 s smbd[74692]: [2018/01/02 09:09:50.393278,  0] ../source3/lib/util.c:816(smb_panic_s3)
Jan  2 09:09:50 s smbd[74692]:   smb_panic(): calling panic action [/usr/local/libexec/samba/samba-backtrace]
Jan  2 09:09:50 s smbd[74692]: [2018/01/02 09:09:50.398408,  0] ../source3/lib/util.c:824(smb_panic_s3)
Jan  2 09:09:50 s smbd[74692]:   smb_panic(): action returned status 0
Jan  2 09:09:50 s smbd[74692]: [2018/01/02 09:09:50.398488,  0] ../source3/lib/dumpcore.c:315(dump_core)
Jan  2 09:09:50 s smbd[74692]:   dumping core in /var/db/system/cores

All six WD drives tell me:

Code:

root@s:~ # smartctl -a /dev/ada* | grep -A1 "START OF READ SMART DATA SECTION"
=== START OF READ SMART DATA SECTION ===
SMART overall-health self-assessment test result: PASSED

and

Code:

root@s:~ # smartctl -a /dev/ada* | grep -A1 "SMART Error Log Version"
SMART Error Log Version: 1
No Errors Logged

ekzodian · Jan 5, 2018

I was having the same problem. Working for days after the 11.1 update, and then errors began happening. But after hours of digging through logs, I think I found the culprit.

It was DNS. (it's always DNS, isn't it?)

First of all, here is an example of the logs I was getting, just so you can see if your problem is similar to mine:

File: messages

Code:

Jan  5 10:45:23 SRV-NAS1 kernel: Failed to fully fault in a core file segment at VA 0x804bc7000 with size 0x23000 to be written at offset 0x80e000 for process winbindd
Jan  5 10:45:23 SRV-NAS1 kernel: Failed to fully fault in a core file segment at VA 0x804bc7000 with size 0x23000 to be written at offset 0x80e000 for process winbindd
Jan  5 10:45:23 SRV-NAS1 kernel: pid 76765 (winbindd), uid 0: exited on signal 6 (core dumped)

File: log.smbd

Code:

[2018/01/04 11:23:41.935417,  0] ../lib/util/fault.c:78(fault_report)
  ===============================================================
[2018/01/04 11:23:41.935485,  0] ../lib/util/fault.c:79(fault_report)
  INTERNAL ERROR: Signal 11 in pid 35125 (4.7.0)
  Please read the Trouble-Shooting section of the Samba HOWTO
[2018/01/04 11:23:41.935522,  0] ../lib/util/fault.c:81(fault_report)
  ===============================================================
[2018/01/04 11:23:41.935547,  0] ../source3/lib/util.c:804(smb_panic_s3)
  PANIC (pid 35125): internal error
[2018/01/04 11:23:41.936232,  0] ../source3/lib/util.c:915(log_stack_trace)
  BACKTRACE: 7 stack frames:
   #0 0x80326f31e <log_stack_trace+0x1e> at /usr/local/lib/libsmbconf.so.0
   #1 0x80326f118 <smb_panic_s3+0x98> at /usr/local/lib/libsmbconf.so.0
   #2 0x800c9e597 <smb_panic+0x27> at /usr/local/lib/libsamba-util.so.0
   #3 0x800c9eb40 <string_sub_once> at /usr/local/lib/libsamba-util.so.0
   #4 0x800c9e563 <fault_setup+0x73> at /usr/local/lib/libsamba-util.so.0
   #5 0x80084a8f6 <pthread_sigmask+0x536> at /lib/libthr.so.3
   #6 0x800849e9f <pthread_getspecific+0xe2f> at /lib/libthr.so.3
[2018/01/04 11:23:41.936351,  0] ../source3/lib/util.c:816(smb_panic_s3)
  smb_panic(): calling panic action [/usr/local/libexec/samba/samba-backtrace]
/usr/local/libexec/samba/samba-backtrace: /usr/local/bin/gdb7111: not found
/usr/local/libexec/samba/samba-backtrace: /usr/local/bin/gdb7111: not found
/usr/local/libexec/samba/samba-backtrace: /usr/local/bin/gdb7111: not found
[2018/01/04 11:23:41.945593,  0] ../source3/lib/util.c:824(smb_panic_s3)
  smb_panic(): action returned status 0
[2018/01/04 11:23:41.945651,  0] ../source3/lib/dumpcore.c:315(dump_core)
  dumping core in /var/db/system/cores
[2018/01/04 11:23:42.270834,  1] ../source3/smbd/server.c:877(remove_child_pid)
  Scheduled cleanup of brl and lock database after unclean shutdown
[2018/01/04 11:23:42.291455,  0] ../lib/util/fault.c:78(fault_report)

But the one that made me realize what the problem was, was the middlewared.log file. (Domain name was replaced by 'DOMAIN_FQDN'):

Code:

[2018/01/05 13:48:47] (DEBUG) ServiceMonitorService.tryConnect():101 - [ServiceMonitorThread] Cannot connect: DOMAIN_FQDN:389 with error: timed out
[2018/01/05 13:50:02] (DEBUG) ServiceMonitorService.tryConnect():101 - [ServiceMonitorThread] Cannot connect: DOMAIN_FQDN:389 with error: timed out
[2018/01/05 13:52:28] (DEBUG) ServiceMonitorService.tryConnect():101 - [ServiceMonitorThread] Cannot connect: DOMAIN_FQDN:389 with error: timed out
[2018/01/05 13:53:36] (DEBUG) ServiceService._simplecmd():255 - Calling: restart(activedirectory)
[2018/01/05 13:53:37] (DEBUG) ServiceService._simplecmd():255 - Calling: stop(cifs)

So I tried pinging our domain FQDN and doing a nslookup to it, and found out that it was returning 5 different IPs, 2 of which are inactive for years. So I supposed that every time that FreeNAS got unlucky and received an offline IP from its DNS request, it tried restarting AD and stopping CIFS.

Hopefully this helps someone else! I suggest reading all the logs and trying to find some error that happens a little bit before smbd panics, it may be another error that crashes the AD connection or something else entirely.

EDIT: I cleaned up our old DNS records, a it has been a few days without errors!

paradoxiom · Jan 14, 2018

ekzodian said:
EDIT: I cleaned up our old DNS records, a it has been a few days without errors!

Could you explain exactly how you did this? My SMB keeps crashing with this and I think it's the same 'problem' (a simple restart of samba fixes it)

Code:

Jan 14 20:36:34 OrbitalHub /middlewared[214]: dnssd_clientstub DNSServiceProcessResult called with invalid DNSServiceRef 0x82021a8a0 FFFFFFFF DDDDDDDD
Jan 14 23:52:16 OrbitalHub kernel: Failed to fully fault in a core file segment at VA 0x8008ff000 with size 0x3000 to be written at offset 0x2cc000 for process winbindd
Jan 14 23:52:16 OrbitalHub kernel: Failed to fully fault in a core file segment at VA 0x8008ff000 with size 0x3000 to be written at offset 0x2cc000 for process winbindd
Jan 14 23:52:16 OrbitalHub kernel: Failed to fully fault in a core file segment at VA 0x800902000 with size 0xd000 to be written at offset 0x2cf000 for process winbindd
Jan 14 23:52:16 OrbitalHub kernel: Failed to fully fault in a core file segment at VA 0x800902000 with size 0xd000 to be written at offset 0x2cf000 for process winbindd
Jan 14 23:52:16 OrbitalHub kernel: pid 19087 (winbindd), uid 0: exited on signal 6 (core dumped)

ekzodian · Jan 15, 2018

paradoxiom said:
Could you explain exactly how you did this? My SMB keeps crashing with this and I think it's the same 'problem' (a simple restart of samba fixes it)

I opened up dnsmgmt.msc on one of our DNS servers and removed all mentions of unavailable DNS server names/IPs from our forward lookup zones. I cleaned every subfolder from every lookup zone. Don't forget to remove entries from unavailable server IPs with the name "same as parent folder". After that, run nslookup and query for your domain name to see if it still returns invalid IPs.

As a temporary workaround, or just to verify if this is really your problem, you can force a valid DNS server IP on /etc/hosts of your FreeNAS. That's what I did before figuring out how to clean our DNS entries.

Important Announcement for the TrueNAS Community.

FreeNAS-11.0-U1 (aa82cc58d) SMBD exited on signal 6

Dabbler

Sambassador

Dabbler

Dabbler

Sambassador

Patron

Contributor

Dabbler

Cadet

Cadet

Cadet

Server Wrangler

Dabbler

Contributor

Contributor

Contributor

Dabbler

Cadet

Patron

Cadet

Similar threads