FreeNAS and Veeam 9.5

Status
Not open for further replies.

LaserAllan

Dabbler
Joined
Mar 25, 2017
Messages
34
Hi there folks!

So the last couple of days I have been trying to get Veeam backup & replication 9.5 software to play nice with a CIFS share that I have added as a backup repository. However getting that to play nicely seems to be much harder than expected. After a lot of troubleshooting this is what I have found so far:

/var/log/samba4/log.smbd
Code:
[2018/02/12 00:41:44.047613,  0, pid=45136, effective(1003, 65534), real(0, 0)] ../lib/dbwrap/dbwrap.c:166(dbwrap_check_lock_order)
  Lock order violation: Trying /var/db/samba4/file_ntacls.tdb at 1 while /var/lock/locking.tdb at 1 is locked
[2018/02/12 00:41:44.047693,  0, pid=45136, effective(1003, 65534), real(0, 0)] ../lib/dbwrap/dbwrap.c:115(debug_lock_order)
  lock order:  1:/var/lock/locking.tdb 2:<none> 3:<none>
[2018/02/12 00:41:44.047787,  0, pid=45136, effective(1003, 65534), real(0, 0)] ../source3/lib/util.c:804(smb_panic_s3)
  PANIC (pid 45136): invalid lock_order
[2018/02/12 00:41:44.051424,  0, pid=45136, effective(1003, 65534), real(0, 0)] ../source3/lib/util.c:915(log_stack_trace)
  BACKTRACE: 34 stack frames:
   #0 0x80326f2fe <log_stack_trace+0x1e> at /usr/local/lib/libsmbconf.so.0
   #1 0x80326f0f8 <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 0x8075d63af <dbwrap_name+0x27f> at /usr/local/lib/samba/libdbwrap-samba4.so
   #4 0x8075d5162 <dbwrap_fetch_locked+0x82> at /usr/local/lib/samba/libdbwrap-samba4.so
   #5 0x8075d5114 <dbwrap_fetch_locked+0x34> at /usr/local/lib/samba/libdbwrap-samba4.so
   #6 0x81b87e291 <samba_init_module+0x2921> at /usr/local/lib/shared-modules/vfs/acl_tdb.so
   #7 0x81b87db38 <samba_init_module+0x21c8> at /usr/local/lib/shared-modules/vfs/acl_tdb.so
   #8 0x81b87c482 <samba_init_module+0xb12> at /usr/local/lib/shared-modules/vfs/acl_tdb.so
   #9 0x801232a7f <smb_vfs_call_unlink+0x4f> at /usr/local/lib/samba/libsmbd-base-samba4.so
   #10 0x8012267e0 <msg_close_file+0x1b50> at /usr/local/lib/samba/libsmbd-base-samba4.so
   #11 0x801224a7f <close_file+0x11df> at /usr/local/lib/samba/libsmbd-base-samba4.so
   #12 0x80122392e <close_file+0x8e> at /usr/local/lib/samba/libsmbd-base-samba4.so
   #13 0x80128935f <smbd_smb2_request_process_close+0x12df> at /usr/local/lib/samba/libsmbd-base-samba4.so
   #14 0x8012884c5 <smbd_smb2_request_process_close+0x445> at /usr/local/lib/samba/libsmbd-base-samba4.so
   #15 0x80128827f <smbd_smb2_request_process_close+0x1ff> at /usr/local/lib/samba/libsmbd-base-samba4.so
   #16 0x80126eb5f <smbd_smb2_request_dispatch+0x136f> at /usr/local/lib/samba/libsmbd-base-samba4.so
   #17 0x801276bd2 <smbd_smb2_process_negprot+0x4002> at /usr/local/lib/samba/libsmbd-base-samba4.so
   #18 0x801276296 <smbd_smb2_process_negprot+0x36c6> at /usr/local/lib/samba/libsmbd-base-samba4.so
   #19 0x804c2124c <tevent_req_set_cleanup_fn+0x15cc> at /usr/local/lib/libtevent.so.0
   #20 0x804c20696 <tevent_req_set_cleanup_fn+0xa16> at /usr/local/lib/libtevent.so.0
   #21 0x804c1cc18 <_tevent_loop_once+0x118> at /usr/local/lib/libtevent.so.0
   #22 0x804c20738 <tevent_req_set_cleanup_fn+0xab8> at /usr/local/lib/libtevent.so.0
   #23 0x804c1d0d0 <_tevent_loop_wait+0x30> at /usr/local/lib/libtevent.so.0
   #24 0x8012503ad <smbd_process+0xe9d> at /usr/local/lib/samba/libsmbd-base-samba4.so
   #25 0x41305e <main+0x7a7e> at /usr/local/sbin/smbd
   #26 0x804c2124c <tevent_req_set_cleanup_fn+0x15cc> at /usr/local/lib/libtevent.so.0
   #27 0x804c20696 <tevent_req_set_cleanup_fn+0xa16> at /usr/local/lib/libtevent.so.0
   #28 0x804c1cc18 <_tevent_loop_once+0x118> at /usr/local/lib/libtevent.so.0
   #29 0x804c20738 <tevent_req_set_cleanup_fn+0xab8> at /usr/local/lib/libtevent.so.0
   #30 0x804c1d0d0 <_tevent_loop_wait+0x30> at /usr/local/lib/libtevent.so.0
   #31 0x40fcd8 <main+0x46f8> at /usr/local/sbin/smbd
   #32 0x40d77f <main+0x219f> at /usr/local/sbin/smbd
   #33 0x40703f <_start+0x17f> at /usr/local/sbin/smbd
[2018/02/12 00:41:44.053031,  0, pid=45136, effective(1003, 65534), real(0, 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: cannot create /var/log/samba4/samba.backtraces: Permission denied
/usr/local/libexec/samba/samba-backtrace: /usr/local/bin/gdb7111: not found
/usr/local/libexec/samba/samba-backtrace: cannot create /var/log/samba4/samba.backtraces: Permission denied
/usr/local/libexec/samba/samba-backtrace: cannot create /var/log/samba4/samba.backtraces: Permission denied
/usr/local/libexec/samba/samba-backtrace: /usr/local/bin/gdb7111: not found
/usr/local/libexec/samba/samba-backtrace: cannot create /var/log/samba4/samba.backtraces: Permission denied
/usr/local/libexec/samba/samba-backtrace: cannot create /var/log/samba4/samba.backtraces: Permission denied
/usr/local/libexec/samba/samba-backtrace: /usr/local/bin/gdb7111: not found
/usr/local/libexec/samba/samba-backtrace: cannot create /var/log/samba4/samba.backtraces: Permission denied
[2018/02/12 00:41:44.076218,  0, pid=45136, effective(1003, 65534), real(0, 0)] ../source3/lib/util.c:824(smb_panic_s3)
  smb_panic(): action returned status 2
[2018/02/12 00:41:44.076348,  4, pid=45136, effective(1003, 65534), real(0, 0)] ../source3/smbd/sec_ctx.c:216(push_sec_ctx)
  push_sec_ctx(1003, 65534) : sec_ctx_stack_ndx = 1
[2018/02/12 00:41:44.076454,  4, pid=45136, effective(1003, 65534), real(0, 0)] ../source3/smbd/uid.c:491(push_conn_ctx)
  push_conn_ctx(3758314062) : conn_ctx_stack_ndx = 0
[2018/02/12 00:41:44.076524,  4, pid=45136, effective(1003, 65534), real(0, 0)] ../source3/smbd/sec_ctx.c:320(set_sec_ctx_internal)
  setting sec ctx (0, 0) - sec_ctx_stack_ndx = 1
[2018/02/12 00:41:44.076617,  5, pid=45136, effective(1003, 65534), real(0, 0)] ../libcli/security/security_token.c:53(security_token_debug)
  Security token: (NULL)
[2018/02/12 00:41:44.076716,  5, pid=45136, effective(1003, 65534), real(0, 0)] ../source3/auth/token_util.c:651(debug_unix_user_token)
  UNIX token of user 0
  Primary group is 0 and contains 0 supplementary groups
[2018/02/12 00:41:44.076919,  0, pid=45136, effective(0, 0), real(0, 0)] ../source3/lib/dumpcore.c:315(dump_core)
  dumping core in /var/db/system/cores
[2018/02/12 00:41:44.806594, 10, pid=44741, effective(0, 0), real(0, 0)] ../source3/lib/messages_dgm.c:1344(messaging_dgm_send)
  messaging_dgm_send: Sending message to 44769
[2018/02/12 00:41:44.807077,  3, pid=44741, effective(0, 0), real(0, 0)] ../source3/smbd/server.c:868(remove_child_pid)
  ../source3/smbd/server.c:867 Unclean shutdown of pid 45136
[2018/02/12 00:41:44.807130, 10, pid=44769, effective(0, 0), real(0, 0)] ../source3/lib/messages.c:203(messaging_recv_cb)
  messaging_recv_cb: Received message 0x314 len 0 (num_fds:0) from 44741
[2018/02/12 00:41:44.807482, 10, pid=44769, effective(0, 0), real(0, 0)] ../source3/lib/messages_dgm.c:1469(messaging_dgm_cleanup)
  messaging_dgm_cleanup: Cleaning up : No error: 0
[2018/02/12 00:41:44.807810,  5, pid=44769, effective(0, 0), real(0, 0)] ../lib/dbwrap/dbwrap.c:160(dbwrap_check_lock_order)
  check lock order 2 for /var/lock/serverid.tdb
[2018/02/12 00:41:44.807932, 10, pid=44769, effective(0, 0), real(0, 0)] ../lib/dbwrap/dbwrap.c:115(debug_lock_order)
  lock order:  1:<none> 2:/var/lock/serverid.tdb 3:<none>
[2018/02/12 00:41:44.808078, 10, pid=44769, effective(0, 0), real(0, 0)] ../lib/dbwrap/dbwrap_tdb.c:59(db_tdb_log_key)
  Locking key 50B0000000000000FFFF
[2018/02/12 00:41:44.808260, 10, pid=44769, effective(0, 0), real(0, 0)] ../lib/dbwrap/dbwrap_tdb.c:143(db_tdb_fetch_locked_internal)
  Allocated locked data 0x0x81284d960
[2018/02/12 00:41:44.808428, 10, pid=44769, effective(0, 0), real(0, 0)] ../lib/dbwrap/dbwrap_tdb.c:59(db_tdb_log_key)
  Unlocking key 50B0000000000000FFFF
[2018/02/12 00:41:44.808500,  5, pid=44769, effective(0, 0), real(0, 0)] ../lib/dbwrap/dbwrap.c:128(dbwrap_lock_order_state_destructor)
  release lock order 2 for /var/lock/serverid.tdb
[2018/02/12 00:41:44.808568, 10, pid=44769, effective(0, 0), real(0, 0)] ../lib/dbwrap/dbwrap.c:115(debug_lock_order)
  lock order:  1:<none> 2:<none> 3:<none>
[2018/02/12 00:41:44.808635, 10, pid=44769, effective(0, 0), real(0, 0)] ../source3/smbd/smbd_cleanupd.c:210(smbd_cleanupd_process_exited)
  smbd_cleanupd_process_exited: cleaned up pid 45136
[2018/02/12 00:41:44.811634, 10, pid=45147, effective(0, 0), real(0, 0)] ../source3/lib/messages_dgm_ref.c:157(msg_dgm_ref_destructor)
  msg_dgm_ref_destructor: refs=0x0
[2018/02/12 00:41:44.812399, 10, pid=45147, effective(0, 0), real(0, 0)] ../source3/lib/messages_dgm_ref.c:79(messaging_dgm_ref)
  messaging_dgm_ref: messaging_dgm_init returned No error: 0
[2018/02/12 00:41:44.812510, 10, pid=45147, effective(0, 0), real(0, 0)] ../source3/lib/messages_dgm_ref.c:108(messaging_dgm_ref)
  messaging_dgm_ref: unique = 13072513250355267000
[2018/02/12 00:41:44.814980, 10, pid=45147, effective(0, 0), real(0, 0)] ../source3/smbd/smbXsrv_client.c:534(smbXsrv_client_create)
[2018/02/12 00:41:44.815064, 10, pid=45147, effective(0, 0), real(0, 0)] ../source3/smbd/smbXsrv_client.c:542(smbXsrv_client_create)
  smbXsrv_client_create: client_guid[00000000-0000-0000-0000-000000000000] stored


Dmesg
Code:
pid 1756 (syslog-ng), uid 0: exited on signal 6 (core dumped)
pid 12705 (smbd), uid 0: exited on signal 6 (core dumped)
pid 12716 (smbd), uid 0: exited on signal 6 (core dumped)
pid 12727 (smbd), uid 0: exited on signal 6 (core dumped)
pid 12908 (smbd), uid 0: exited on signal 6 (core dumped)
pid 12929 (smbd), uid 0: exited on signal 6 (core dumped)
pid 13016 (smbd), uid 0: exited on signal 6 (core dumped)
pid 13119 (smbd), uid 0: exited on signal 6 (core dumped)
pid 13175 (smbd), uid 0: exited on signal 6 (core dumped)
pid 13851 (smbd), uid 0: exited on signal 6 (core dumped)
pid 14269 (smbd), uid 0: exited on signal 6 (core dumped)
pid 14383 (smbd), uid 0: exited on signal 6 (core dumped)
pid 14394 (smbd), uid 0: exited on signal 6 (core dumped)
pid 44890 (smbd), uid 0: exited on signal 6 (core dumped)
pid 44902 (smbd), uid 0: exited on signal 6 (core dumped)
pid 44913 (smbd), uid 0: exited on signal 6 (core dumped)
pid 44924 (smbd), uid 0: exited on signal 6 (core dumped)
pid 44935 (smbd), uid 0: exited on signal 6 (core dumped)
pid 45029 (smbd), uid 0: exited on signal 6 (core dumped)
pid 45125 (smbd), uid 0: exited on signal 6 (core dumped)
pid 45136 (smbd), uid 0: exited on signal 6 (core dumped)
pid 46829 (smbd), uid 0: exited on signal 6 (core dumped)
pid 47134 (smbd), uid 0: exited on signal 6 (core dumped)
pid 47399 (smbd), uid 0: exited on signal 6 (core dumped)
pid 47410 (smbd), uid 0: exited on signal 6 (core dumped)


The auxillary paramters I have set in SMB is the following:
Code:
socket options = TCP_NODELAY SO_RCVBUF=1048576 SO_SNDBUF=1048576 IPTOS_LOWDELAY IPTOS_THROUGHPUT
use sendfile = no
min receivefile size = 131072
aio read size = 1
aio write size = 1
aio write behind = true
read raw = yes
local master = yes
os level = 255
preferred master = yes
posix locking = no
server max protocol = SMB2_10


I am kinda lost what to try at this point. I have tried NFS with similar results.
Build FreeNAS-11.1-U1
Motherboard: ASRock C2758D4
CPU: Intel Atom C2758
32 gig ECC RAM
Boot devices are dual USB sticks Sandisk Ultrafit
 
Last edited by a moderator:

LaserAllan

Dabbler
Joined
Mar 25, 2017
Messages
34
Can you post your full smb4.conf file? /usr/local/etc/smb4.conf
Are you able to reproduce that crash on demand?

I am able to reproduce it on-demand yes. It happens when Veeam is going to send data over smb to FreeNAS.

Code:
[global]
	interfaces = 127.0.0.1 10.10.10.100 10.27.70.2
	bind interfaces only = yes
	encrypt passwords = yes
	dns proxy = no
	strict locking = no
	oplocks = yes
	deadtime = 15
	max log size = 51200
	max open files = 941825
	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
	hostname lookups = yes
	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 = VAULDERIE
	workgroup = WORKGROUP
	security = user
	create mask = 0666
	directory mask = 0777
	client ntlmv2 auth = yes
	dos charset = CP437
	unix charset = UTF-8
	log level = 10
	socket options = TCP_NODELAY SO_RCVBUF=1048576 SO_SNDBUF=1048576 IPTOS_LOWDELAY IPTOS_THROUGHPUT
	use sendfile = no
	min receivefile size = 131072
	aio read size = 1
	aio write size = 1
	aio write behind = true
	read raw = yes
	local master = yes
	os level = 255
	preferred master = yes
	posix locking = no
	server max protocol = SMB2_10
	smb2 leases = no


[Data2]
	path = "/mnt/Storage2"
	printable = no
	veto files = /.snapshot/.windows/.mac/.zfs/
	writeable = yes
	browseable = yes
	access based share enum = no
	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


[data]
	path = "/mnt/Storage1/data"
	printable = no
	veto files = /.snapshot/.windows/.mac/.zfs/
	writeable = yes
	browseable = yes
	access based share enum = no
	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


[homes]
	valid users = %U
	path = "/mnt/Storage1/user/%U"
	comment = Home Directories
	printable = no
	veto files = /.snapshot/.windows/.mac/.zfs/
	writeable = yes
	browseable = yes
	access based share enum = no
	vfs objects = zfs_space zfsacl streams_xattr aio_pthread
	hide dot files = yes
	hosts allow = 10.27.70.3
	guest ok = no
	nfs4:mode = special
	nfs4:acedup = merge
	nfs4:chown = true
	zfsacl:acesort = dontcare


So far I have gone around it by creating a CentOS 7 VM and mount NFS from freenas inside there and then using that as a backup repository for veeam. But CIFS would be better to not rely on a vm for that whole thing.
 

bigphil

Patron
Joined
Jan 30, 2014
Messages
486
Do you have update3 installed for Veeam Backup & Replication 9.5?
 

anodos

Sambassador
iXsystems
Joined
Mar 6, 2014
Messages
9,554
The stacktrace you posted indicated that the acl_tdb VFS object was enabled (which it shouldn't be). Try removing all of your auxiliary parameters
 

LaserAllan

Dabbler
Joined
Mar 25, 2017
Messages
34
The stacktrace you posted indicated that the acl_tdb VFS object was enabled (which it shouldn't be). Try removing all of your auxiliary parameters
Ok so I recreated the share without any vfs_objects at all other than the standard ones. Now I am only getting about 400 Mbits though. More as with the Centos machien running NFS i get saturated gigabit right away. Is there anything i can do to improve the speed because at this stage i am farily sure smb can be tweaked to give me better speeds.

Thanks for good ansers anyway. At this stage I am probably gonna run with the centos vm if i cannot get SMB to perform gigabit speeds. For some reason Centos and NFS gives me gigabit which CIFS also should be able to give me :)

Code:
socket options = TCP_NODELAY SO_RCVBUF=1048576 SO_SNDBUF=1048576 IPTOS_LOWDELAY IPTOS_THROUGHPUT
use sendfile = no
min receivefile size = 131072
aio read size = 1
aio write size = 1
aio write behind = true
read raw = yes
local master = yes
os level = 255
preferred master = yes
posix locking = no
server max protocol = SMB2_10
 

bigphil

Patron
Joined
Jan 30, 2014
Messages
486
Something looks off in your global config. I was comparing it to mine, albeit I'm on 9.10.2, and it seems to have some odd values and ones that don't even appear to have acceptable settings ("aio write behind" seems in the wrong format). If doing what @anodos said doesnt work, you might try taking a backup of you smb4.conf file, stopping the SMB service, and then either rename/move/delete the smb4.conf, reboot and then start the SMB service again to create a fresh smb4.conf file. Then setup your shares and permissions again and see if it works.
 

LaserAllan

Dabbler
Joined
Mar 25, 2017
Messages
34
Something looks off in your global config. I was comparing it to mine, albeit I'm on 9.10.2, and it seems to have some odd values and ones that don't even appear to have acceptable settings ("aio write behind" seems in the wrong format). If doing what @anodos said doesnt work, you might try taking a backup of you smb4.conf file, stopping the SMB service, and then either rename/move/delete the smb4.conf, reboot and then start the SMB service again to create a fresh smb4.conf file. Then setup your shares and permissions again and see if it works.


I managed to get CIFS working but with far less speed than SSH bakcups. I will try deleting all parameters and readding one by one to see what is the culprit. Will post the update as soon as I find out.
 
Status
Not open for further replies.
Top