large data copy crashes samba4 file sharing

[spiral]

Since 2.3 beta, and currently in final 3.0, in 2 different hardware setups, when I rsync from linux or robocopy from windows a large amount of data >20gig, samba chokes, and must be restarted to allow access to the file shares.  I will analyze the samba.log and maybe syslog for clues, but has anybody else experienced similar behavior.

Thanks.

[spiral]

seems after it errors out I get this in the samba.log: 

[2012/09/14 16:53:58.909004,  3] ../source3/smbd/trans2.c:5227(call_trans2qfilepathinfo)
  call_trans2qfilepathinfo: TRANSACT2_QPATHINFO: level = 1004
[2012/09/14 16:53:58.909695,  3] ../source3/smbd/vfs.c:1110(check_reduced_name)
  check_reduced_name [1709141719/120914_1_data/transaction/00000000000/header] [/home/samba/shares/NetShare]
[2012/09/14 16:53:58.909901,  3] ../source3/smbd/vfs.c:1240(check_reduced_name)
  check_reduced_name: 1709141719/120914_1_data/transaction/00000000000/header reduced to /home/samba/shares/NetShare/1709141719/120914_1_data/transaction/00000000000/header
[2012/09/14 16:53:58.910108,  3] ../source3/smbd/trans2.c:5346(call_trans2qfilepathinfo)
  call_trans2qfilepathinfo: SMB_VFS_STAT of 1709141719/120914_1_data/transaction/00000000000/header failed (No such file or directory)
[2012/09/14 16:53:58.910481,  3] ../source3/smbd/error.c:82(error_packet_set)
  NT error packet at ../source3/smbd/trans2.c(5348) cmd=50 (SMBtrans2) NT_STATUS_OBJECT_NAME_NOT_FOUND
[2012/09/14 16:53:58.913965,  3] ../source3/smbd/process.c:1789(process_smb)
  Transaction 17 of length 69 (0 toread)
[2012/09/14 16:53:58.914193,  3] ../source3/smbd/process.c:1392(switch_message)
  switch message SMBwriteX (pid 8018) conn 0x99e0ae8
[2012/09/14 16:53:58.914399,  3] ../source3/smbd/error.c:82(error_packet_set)
  NT error packet at ../source3/smbd/reply.c(343) cmd=47 (SMBwriteX) NT_STATUS_INVALID_HANDLE
[2012/09/14 16:53:58.941706,  3] ../source3/smbd/process.c:1789(process_smb)
  Transaction 18 of length 69 (0 toread)
[2012/09/14 16:53:58.942065,  3] ../source3/smbd/process.c:1392(switch_message)
  switch message SMBwriteX (pid 8018) conn 0x99e0ae8
[2012/09/14 16:53:58.942318,  3] ../source3/smbd/error.c:82(error_packet_set)
  NT error packet at ../source3/smbd/reply.c(343) cmd=47 (SMBwriteX) NT_STATUS_INVALID_HANDLE
[2012/09/14 16:53:58.943273,  3] ../source3/smbd/process.c:1789(process_smb)
  Transaction 19 of length 76 (0 toread)
[2012/09/14 16:53:58.943481,  3] ../source3/smbd/process.c:1392(switch_message)
  switch message SMBtrans2 (pid 8018) conn 0x99e0ae8
[2012/09/14 16:53:58.943714,  3] ../source3/smbd/trans2.c:5142(call_trans2qfilepathinfo)
  call_trans2qfilepathinfo: TRANSACT2_QFILEINFO: level = 1005
[2012/09/14 16:53:58.943915,  3] ../source3/smbd/error.c:82(error_packet_set)
  NT error packet at ../source3/smbd/reply.c(343) cmd=50 (SMBtrans2) NT_STATUS_INVALID_HANDLE
[2012/09/14 16:53:58.944657,  3] ../source3/smbd/process.c:1789(process_smb)
  Transaction 20 of length 76 (0 toread)
[2012/09/14 16:53:58.944863,  3] ../source3/smbd/process.c:1392(switch_message)
  switch message SMBtrans2 (pid 8018) conn 0x99e0ae8

.......................then

[2012/09/14 16:54:18.344372,  1] ../source3/smbd/server.c:407(cleanup_timeout_fn)
  Cleaning up brl and lock database after unclean shutdown
[2012/09/14 16:54:56.552333,  2] ../source3/smbd/server.c:435(remove_child_pid)
  Could not find child 8037 -- ignoring
[2012/09/14 16:55:56.638684,  2] ../source3/smbd/server.c:435(remove_child_pid)
  Could not find child 8048 -- ignoring
[2012/09/14 16:56:15.449564,  3] ../source3/smbd/process.c:1789(process_smb)
  Transaction 41 of length 80 (0 toread)
[2012/09/14 16:56:15.450119,  3] ../source3/smbd/process.c:1392(switch_message)
  switch message SMBtrans2 (pid 8018) conn 0x99e0ae8
[2012/09/14 16:56:15.450686,  3] ../source3/smbd/trans2.c:5227(call_trans2qfilepathinfo)
  call_trans2qfilepathinfo: TRANSACT2_QPATHINFO: level = 1004
[2012/09/14 16:56:15.450992,  3] ../source3/smbd/vfs.c:1110(check_reduced_name)
  check_reduced_name [.] [/home/samba/shares/NetShare]
[2012/09/14 16:56:15.451223,  3] ../source3/smbd/vfs.c:1240(check_reduced_name)
  check_reduced_name: . reduced to /home/samba/shares/NetShare
[2012/09/14 16:56:15.451646,  3] ../source3/locking/share_mode_lock.c:408(fetch_share_mode_unlocked)
  Could not fetch share entry
[2012/09/14 16:56:15.451798,  3] ../source3/smbd/trans2.c:5372(call_trans2qfilepathinfo)
  call_trans2qfilepathinfo . (fnum [fsp is NULL]) level=1004 call=5 total_data=0
[2012/09/14 16:56:15.452728,  3] ../source3/smbd/process.c:1789(process_smb)
  Transaction 42 of length 80 (0 toread)
[2012/09/14 16:56:15.452949,  3] ../source3/smbd/process.c:1392(switch_message)
  switch message SMBtrans2 (pid 8018) conn 0x99e0ae8
[2012/09/14 16:56:15.453161,  3] ../source3/smbd/trans2.c:5227(call_trans2qfilepathinfo)
  call_trans2qfilepathinfo: TRANSACT2_QPATHINFO: level = 1034
[2012/09/14 16:56:15.453367,  3] ../source3/smbd/vfs.c:1110(check_reduced_name)
  check_reduced_name [.] [/home/samba/shares/NetShare]
[2012/09/14 16:56:15.453604,  3] ../source3/smbd/vfs.c:1240(check_reduced_name)
  check_reduced_name: . reduced to /home/samba/shares/NetShare
[2012/09/14 16:56:15.453816,  3] ../source3/locking/share_mode_lock.c:408(fetch_share_mode_unlocked)
  Could not fetch share entry
[2012/09/14 16:56:15.454015,  3] ../source3/smbd/trans2.c:5372(call_trans2qfilepathinfo)
  call_trans2qfilepathinfo . (fnum [fsp is NULL]) level=1034 call=5 total_data=0
[2012/09/14 16:56:15.454924,  3] ../source3/smbd/process.c:1789(process_smb)
  Transaction 43 of length 102 (0 toread)
[2012/09/14 16:56:15.455159,  3] ../source3/smbd/process.c:1392(switch_message)
  switch message SMBtrans2 (pid 8018) conn 0x99e0ae8

[spiral]

syslog has an interesting entry:

Sep 14 16:59:33 zentyal smbd_audit: [2012/09/14 16:59:33.604366,  0] ../lib/tdb_wrap/tdb_wrap.c:64(tdb_wrap_log)
Sep 14 16:59:33 zentyal smbd_audit:   tdb(/var/lock/samba/notify.tdb): expand_file write of 8192 bytes failed (No space left on device)

Appears that it is acting as if the drive is full, when in-fact it shouldn't be.

[c4rdinal]

Try to make the folder permission as administrator only and see if that makes a diff.

Hth

[spiral]

Thanks, I tried with admin file share permissions, and by making user a domain admin, but same issue.

I am trying to isolate the cause...

Seems it is caused by a lot of read/write activity, especially using a backup application like Areca backup, which creates a lot of overhead, especially when merging archives.

[spiral]

The error is here:

[2012/09/17 10:59:59.575594,  2] ../lib/tdb_wrap/tdb_wrap.c:64(tdb_wrap_log)
  tdb(/var/lock/samba/smbXsrv_session_global.tdb): tdb_mmap failed for size -349720576 (Cannot allocate memory)
[2012/09/17 10:59:59.575628,  0] ../lib/tdb_wrap/tdb_wrap.c:64(tdb_wrap_log)
  tdb(/var/lock/samba/smbXsrv_session_global.tdb): expand_file write of 8192 bytes failed (No space left on device)
[2012/09/17 10:59:59.575674,  1] ../source3/smbd/smbXsrv_session.c:848(smbXsrv_session_global_store)
  smbXsrv_session_global_store: key '1351C95C' store - NT_STATUS_UNSUCCESSFUL
[2012/09/17 10:59:59.575704,  0] ../source3/smbd/smbXsrv_session.c:1265(smbXsrv_session_update)
  smbXsrv_session_update: global_id (0x1351c95c) store failed - NT_STATUS_UNSUCCESSFUL
[2012/09/17 10:59:59.575746,  0] ../source3/smbd/sesssetup.c:373(reply_sesssetup_and_X_spnego)
  smb1: Failed to update session for vuid=49366 - NT_STATUS_UNSUCCESSFUL
[2012/09/17 10:59:59.575795,  0] ../source3/smbd/smbXsrv_session.c:1336(smbXsrv_session_logoff)
  smbXsrv_session_logoff(0x1351c95c): failed to delete global key '1351C95C': NT_STATUS_NOT_FOUND
[2012/09/17 10:59:59.575853,  0] ../source3/smbd/smbXsrv_session.c:1070(smbXsrv_session_destructor)
  smbXsrv_session_destructor: smbXsrv_session_logoff() failed: NT_STATUS_NOT_FOUND
[2012/09/17 10:59:59.575989,  3] ../source3/smbd/error.c:82(error_packet_set)
  NT error packet at ../source3/smbd/sesssetup.c(376) cmd=115 (SMBsesssetupX) NT_STATUS_LOGON_FAILURE
[2012/09/17 11:00:07.625490,  1] ../source3/smbd/server.c:407(cleanup_timeout_fn)
  Cleaning up brl and lock database after unclean shutdown
[2012/09/17 11:00:27.730025,  2] ../source3/smbd/server.c:435(remove_child_pid)
  Could not find child 17512 -- ignoring
[2012/09/17 11:00:50.229132,  2] ../source3/smbd/process.c:2602(deadtime_fn)
  Closing idle connection
[2012/09/17 11:00:50.229345,  3] ../source3/smbd/server.c:157(msg_exit_server)
  got a SHUTDOWN message

Odd that it seems nobody else is getting this error. 

[kmmorgan20]

I am also seeing something similar when a large number of files are being accessed with many repeats for each file being accessed:

[2012/09/17 18:28:16.644112,  0] ../lib/tdb_wrap/tdb_wrap.c:64(tdb_wrap_log)
  tdb(/var/lock/samba/smbXsrv_open_global.tdb): expand_file write of 8192 bytes failed (No space left on device)
[2012/09/17 18:28:16.644264,  1] ../source3/smbd/smbXsrv_open.c:686(smbXsrv_open_global_store)
  smbXsrv_open_global_store: key 'E505A649' store - NT_STATUS_UNSUCCESSFUL
[2012/09/17 18:28:16.644351,  0] ../source3/smbd/smbXsrv_open.c:805(smbXsrv_open_create)
  smbXsrv_open_create: global_id (0xe505a649) store failed - NT_STATUS_UNSUCCESSFUL
[2012/09/17 18:28:16.644501,  0] ../source3/smbd/smbXsrv_open.c:945(smbXsrv_open_close)
  smbXsrv_open_close(0xe505a649): failed to delete global key 'E505A649': NT_STATUS_NOT_FOUND
[2012/09/17 18:28:16.644655,  0] ../source3/smbd/smbXsrv_open.c:710(smbXsrv_open_destructor)
  smbXsrv_open_destructor: smbXsrv_open_close() failed - NT_STATUS_NOT_FOUND

[spiral]

OK, so I am not the only one seeing this issue.

I am going to head on over to some Samba forums and see if I can find anything out...

[spiral]

In-case anybody else is experiencing this...  I think I have narrowed the error down in syslog to:

tdb(/var/lock/samba/locking.tdb): expand_file write of 8192 bytes failed (No space left on device)


((There is plenty of room on the drive where the file share is (160 gig share and trying to backup 5 gig of small files to share then verify backup), but maybe this has something to do with log size or cache size of samba and/or mount size of the var dir  ))

directly after this Samba crashes...

[2012/09/19 21:26:58.347712,  0] ../source3/locking/share_mode_lock.c:224(share_mode_data_destructor)
store returned NT_STATUS_UNSUCCESSFUL
[2012/09/19 21:26:58.347780,  0] ../source3/lib/util.c:810(smb_panic_s3)
PANIC (pid 5017): could not store share mode entry: NT_STATUS_UNSUCCESSFUL
[2012/09/19 21:26:58.348492,  0] ../source3/lib/util.c:921(log_stack_trace)
BACKTRACE: 27 stack frames:
#0 /usr/lib/i386-linux-gnu/libsmbconf.so.0(log_stack_trace+0x29) [0xb7220729]
#1 /usr/lib/i386-linux-gnu/libsmbconf.so.0(smb_panic_s3+0x31) [0xb7220831]
#2 /usr/lib/i386-linux-gnu/libsamba-util.so.0(smb_panic+0x3a) [0xb772531a]
#3 /usr/lib/i386-linux-gnu/samba/libsmbd_base.so(+0x185007) [0xb7592007]
#4 /usr/lib/i386-linux-gnu/libtalloc.so.2(+0x6aa3) [0xb6e19aa3]
#5 /usr/lib/i386-linux-gnu/libtalloc.so.2(+0x6777) [0xb6e19777]
#6 /usr/lib/i386-linux-gnu/libtalloc.so.2(_talloc_free+0x12f) [0xb6e15fef]
#7 /usr/lib/i386-linux-gnu/samba/libsmbd_base.so(set_delete_on_close+0x118) [0xb758a018]
#8 /usr/lib/i386-linux-gnu/samba/libsmbd_base.so(+0xbea1f) [0xb74cba1f]
#9 /usr/lib/i386-linux-gnu/samba/libsmbd_base.so(smbd_do_setfilepathinfo+0x5e4) [0xb74d8554]
#10 /usr/lib/i386-linux-gnu/samba/libsmbd_base.so(+0xce94f) [0xb74db94f]
#11 /usr/lib/i386-linux-gnu/samba/libsmbd_base.so(+0xcfc79) [0xb74dcc79]
#12 /usr/lib/i386-linux-gnu/samba/libsmbd_base.so(reply_trans2+0x575) [0xb74dff55]
#13 /usr/lib/i386-linux-gnu/samba/libsmbd_base.so(+0x100082) [0xb750d082]
#14 /usr/lib/i386-linux-gnu/samba/libsmbd_base.so(+0x101220) [0xb750e220]
#15 /usr/lib/i386-linux-gnu/samba/libsmbd_base.so(+0x101787) [0xb750e787]
#16 /usr/lib/i386-linux-gnu/libsmbconf.so.0(run_events_poll+0x366) [0xb723b7d6]
#17 /usr/lib/i386-linux-gnu/libsmbconf.so.0(+0x3498b) [0xb723b98b]
#18 /usr/lib/i386-linux-gnu/libtevent.so.0(_tevent_loop_once+0xa8) [0xb6e08e28]
#19 /usr/lib/i386-linux-gnu/samba/libsmbd_base.so(smbd_process+0xc83) [0xb750fe83]
#20 /usr/sbin/smbd() [0x8050f49]
#21 /usr/lib/i386-linux-gnu/libsmbconf.so.0(run_events_poll+0x366) [0xb723b7d6]
#22 /usr/lib/i386-linux-gnu/libsmbconf.so.0(+0x3498b) [0xb723b98b]
#23 /usr/lib/i386-linux-gnu/libtevent.so.0(_tevent_loop_once+0xa8) [0xb6e08e28]
#24 /usr/sbin/smbd(main+0x199b) [0x804d51b]
#25 /lib/i386-linux-gnu/libc.so.6(__libc_start_main+0xf3) [0xb6c7a4d3]
#26 /usr/sbin/smbd() [0x804d8bd]
[2012/09/19 21:26:58.349255,  0] ../source3/lib/dumpcore.c:317(dump_core)
dumping core in /var/log/samba/cores/smbd

[christian]

I didn't on my side but did you look already at Samba related forums or Google to see whenever such problem exists elsewhere, I mean out of Zentyal.

[spiral]

Not sure exactly what the problem is, but it appears to be solved if I only install the File Sharing and Domain Services, and related services instead of installing the Office package.

As far as reproducing this issue, I have reliably reproduced this issue using two different hardware installations, and numerous virtual machine installs.  The trick is to generate a lot of read/write activity on the samba share to crash it. (A user profile file backup with a verify option will do the trick)

I was searching through the samba forums, and they have pointed me towards many some log that is filling memory and crashing samba...

[J. A. Calvo]

This should be already fixed on a fresh install of zentyal-samba 3.0.2. If you installed previous versions, you should be able to fix your system with:

echo -e "none\t/run/lock\ttmpfs\trw,noexec,nosuid,nodev,size=52428800" >> /etc/fstab

[J. A. Calvo]

After that, to apply the new wize for the /run/lock filesystem you will need to reboot your system or simply execute:

mount -o remount /run/lock

[spiral]

what was the tracker # for this, just curious, since I was into it, just wondering the details on what it was?

[spiral]

After a weekend of testing, the original issue with samba crashing does appear to be solved.  Although, I have noticed new problems, for example, samba not starting when server is rebooted, but that is another post...