Bug 14036 - coredump halfway TimeMachine backup from OSX
Summary: coredump halfway TimeMachine backup from OSX
Status: NEW
Alias: None
Product: Samba 4.1 and newer
Classification: Unclassified
Component: Other (show other bugs)
Version: 4.10.6
Hardware: x86 Linux
: P5 normal (vote)
Target Milestone: ---
Assignee: Samba QA Contact
QA Contact: Samba QA Contact
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2019-07-11 09:21 UTC by leo
Modified: 2020-02-13 06:54 UTC (History)
4 users (show)

See Also:


Attachments
smb.conf (11.70 KB, text/plain)
2019-07-11 10:01 UTC, leo
no flags Details
SMB log for crash during time machine backup (400.20 KB, text/plain)
2019-08-28 18:37 UTC, juha.kuikka
no flags Details
Patch to potentially keep locking.tdb smaller (2.12 KB, text/plain)
2019-12-10 19:56 UTC, Volker Lendecke
no flags Details

Note You need to log in before you can comment on or make changes to this bug.
Description leo 2019-07-11 09:21:48 UTC
Machine runs Ubuntu 18.04.2. I installed samba 4.10.6 (latest available) from source following the guide at
https://kirb.me/2018/03/24/using-samba-as-a-time-machine-network-server.html

with the only difference that I disabled spotlight support because that did not configure well. 

After some initial hickups I got Samba to work and created a share that could be recognized by the Apple TimeMachine backup program:

```
[timemachine]
comment = MacOS TimeMachine backups 500 Gb
path = /media/timemachine
browseable = yes
writable = yes
guest ok = no
guest only = no
valid users = @timemachine
create mask = 0600
directory mask = 0700
vfs objects = catia fruit streams_xattr
fruit:aapl = yes
fruit:time machine = yes
```

I could succesfully add this share as a backup disk in TimeMachine and the first backup got about half way (49 Gb out of approx. 120 Gb) when I ran into a crash with coredump.
Comment 1 leo 2019-07-11 09:28:46 UTC
Created attachment 15301 [details]
crash report

Ubuntu crash report including core dump
Comment 2 leo 2019-07-11 10:01:00 UTC
Created attachment 15302 [details]
smb.conf
Comment 3 Ralph Böhme 2019-07-11 10:03:32 UTC
The crash report has the core file, but that doesn't help us.

Can you get us a stack-backtrace with debug symbols? One step would be installing samba-debug or similar.
Comment 4 leo 2019-07-11 10:27:18 UTC
OK I will reconfigure using --enable-debug and report back to you.
Comment 6 juha.kuikka 2019-08-26 15:49:42 UTC
I saw the same bug on 4.10.7 when doing an initial time machine backup from a mac. It got to about 47GB before the smb process crashed.

This seems to be reproducible since this is the 2nd time I see this.

Trace:

[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1".
Core was generated by `/usr/sbin/smbd --foreground --no-process-group'.
Program terminated with signal SIGABRT, Aborted.
#0  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:51
51	../sysdeps/unix/sysv/linux/raise.c: No such file or directory.
[Current thread is 1 (Thread 0x7f0501152e40 (LWP 15374))]
(gdb) where
#0  0x00007f04fc87ee97 in __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:51
#1  0x00007f04fc880801 in __GI_abort () at abort.c:79
#2  0x00007f04ff27e35e in VALGRIND_PRINTF () at /usr/lib/x86_64-linux-gnu/libsmbconf.so.0
#3  0x00007f04ff2427c5 in readdirname () at /usr/lib/x86_64-linux-gnu/libsmbconf.so.0
#4  0x00007f0500d5361b in smb_panic () at /usr/lib/x86_64-linux-gnu/libsamba-util.so.0
#5  0x00007f050091eb5c in share_mode_data_destructor (d=0x559b983fc7f0) at ../../source3/locking/share_mode_lock.c:423
#6  0x00007f04ff8aaa96 in _tc_free_internal (tc=0x559b983fc790, location=0x7f0500a3c2b0 "../../source3/smbd/open.c:3845") at ../../lib/talloc/talloc.c:1137
#7  0x00007f04ff8abd2b in _tc_free_children_internal (tc=0x559b9860e2c0, ptr=0x559b9860e320, location=0x7f0500a3c2b0 "../../source3/smbd/open.c:3845")
    at ../../lib/talloc/talloc.c:1646
#8  0x00007f04ff8aac51 in _tc_free_internal (tc=0x559b9860e2c0, location=0x7f0500a3c2b0 "../../source3/smbd/open.c:3845") at ../../lib/talloc/talloc.c:1163
#9  0x00007f04ff8abd2b in _tc_free_children_internal (tc=0x559b983b63a0, ptr=0x559b983b6400, location=0x7f0500a3c2b0 "../../source3/smbd/open.c:3845")
    at ../../lib/talloc/talloc.c:1646
#10 0x00007f04ff8aac51 in _tc_free_internal (tc=0x559b983b63a0, location=0x7f0500a3c2b0 "../../source3/smbd/open.c:3845") at ../../lib/talloc/talloc.c:1163
#11 0x00007f04ff8aae12 in _talloc_free_internal (ptr=0x559b983b6400, location=0x7f0500a3c2b0 "../../source3/smbd/open.c:3845") at ../../lib/talloc/talloc.c:1227
#12 0x00007f04ff8ac178 in _talloc_free (ptr=0x559b983b6400, location=0x7f0500a3c2b0 "../../source3/smbd/open.c:3845") at ../../lib/talloc/talloc.c:1769
#13 0x00007f050084c30a in open_file_ntcreate (conn=0x559b98297cb0, req=0x559b982e6480, access_mask=131207, share_access=0, create_disposition=3, create_options=0, new_dos_attributes=32, oplock_request=0, lease=0x0, private_flags=0, pinfo=0x7ffe1a56a4b8, fsp=0x559b98362510) at ../../source3/smbd/open.c:3845
#14 0x00007f050084f8d2 in create_file_unixpath (conn=0x559b98297cb0, req=0x559b982e6480, smb_fname=0x559b985265e0, access_mask=131207, share_access=0, create_disposition=3, create_options=0, file_attributes=160, oplock_request=0, lease=0x0, allocation_size=0, private_flags=0, sd=0x0, ea_list=0x0, result=0x7ffe1a56a5d8, pinfo=0x7ffe1a56a5c8)
    at ../../source3/smbd/open.c:5292
#15 0x00007f0500850598 in create_file_default (conn=0x559b98297cb0, req=0x559b982e6480, root_dir_fid=0, smb_fname=0x559b985265e0, access_mask=131207, share_access=0, create_disposition=3, create_options=0, file_attributes=160, oplock_request=0, lease=0x0, allocation_size=0, private_flags=0, sd=
    0x0, ea_list=0x0, result=0x559b98423948, pinfo=0x559b9842395c, in_context_blobs=0x7ffe1a56aa78, out_context_blobs=0x559b986fdec0) at ../../source3/smbd/open.c:5700
#16 0x00007f05009c3353 in vfswrap_create_file (handle=0x559b982c94d0, req=0x559b982e6480, root_dir_fid=0, smb_fname=0x559b985265e0, access_mask=131207, share_access=0, create_disposition=3, create_options=0, file_attributes=160, oplock_request=0, lease=0x0, allocation_size=0, private_flags=0, sd=
    0x0, ea_list=0x0, result=0x559b98423948, pinfo=0x559b9842395c, in_context_blobs=0x7ffe1a56aa78, out_context_blobs=0x559b986fdec0) at ../../source3/modules/vfs_default.c:582
#17 0x00007f050085cd0a in smb_vfs_call_create_file (handle=0x559b982c94d0, req=0x559b982e6480, root_dir_fid=0, smb_fname=0x559b985265e0, access_mask=131207, share_access=0, create_disposition=3, create_options=0, file_attributes=160, oplock_request=0, lease=0x0, allocation_size=0, private_flags=0, sd=
    0x0, ea_list=0x0, result=0x559b98423948, pinfo=0x559b9842395c, in_context_blobs=0x7ffe1a56aa78, out_context_blobs=0x559b986fdec0) at ../../source3/smbd/vfs.c:1627
#18 0x00007f04e4884152 in fruit_create_file () at /usr/lib/x86_64-linux-gnu/samba/vfs/fruit.so
#19 0x00007f050085cd0a in smb_vfs_call_create_file (handle=0x559b982d9990, req=0x559b982e6480, root_dir_fid=0, smb_fname=0x559b985265e0, access_mask=131207, share_access=0, create_disposition=3, create_options=0, file_attributes=160, oplock_request=0, lease=0x0, allocation_size=0, private_flags=0, sd=
    0x0, ea_list=0x0, result=0x559b98423948, pinfo=0x559b9842395c, in_context_blobs=0x7ffe1a56aa78, out_context_blobs=0x559b986fdec0) at ../../source3/smbd/vfs.c:1627
#20 0x00007f05008a6fca in smbd_smb2_create_send (mem_ctx=0x559b985eb740, ev=0x559b9829af00, smb2req=0x559b985eb740, in_oplock_level=0 '\000', in_impersonation_level=2, in_desired_access=131207, in_file_attributes=160, in_share_access=0, in_create_disposition=3, in_create_options=0, in_name=0x559b9858b600 "Juha’s MacBook Pro.sparsebundle\\bands\\18c0", in_context_blobs=...) at ../../source3/smbd/smb2_create.c:938
#21 0x00007f05008a4aeb in smbd_smb2_request_process_create (smb2req=0x559b985eb740) at ../../source3/smbd/smb2_create.c:230
#22 0x00007f0500897ab7 in smbd_smb2_request_dispatch (req=0x559b985eb740) at ../../source3/smbd/smb2_server.c:2687
#23 0x00007f050089bb2f in smbd_smb2_io_handler (xconn=0x559b982ceeb0, fde_flags=1) at ../../source3/smbd/smb2_server.c:3991
#24 0x00007f050089bc49 in smbd_smb2_connection_handler (ev=0x559b9829af00, fde=0x559b982cb000, flags=1, private_data=0x559b982ceeb0) at ../../source3/smbd/smb2_server.c:4029
#25 0x00007f04ffec3f24 in tevent_common_invoke_fd_handler (fde=0x559b982cb000, flags=1, removed=0x0) at ../../lib/tevent/tevent_fd.c:138
#26 0x00007f04ffece80f in epoll_event_loop (epoll_ev=0x559b982c2170, tvalp=0x7ffe1a56adb0) at ../../lib/tevent/tevent_epoll.c:736
#27 0x00007f04ffeceee3 in epoll_event_loop_once (ev=0x559b9829af00, location=0x7f0500a4b858 "../../source3/smbd/process.c:4120") at ../../lib/tevent/tevent_epoll.c:937
#28 0x00007f04ffecb6db in std_event_loop_once (ev=0x559b9829af00, location=0x7f0500a4b858 "../../source3/smbd/process.c:4120") at ../../lib/tevent/tevent_standard.c:110
#29 0x00007f04ffec314f in _tevent_loop_once (ev=0x559b9829af00, location=0x7f0500a4b858 "../../source3/smbd/process.c:4120") at ../../lib/tevent/tevent.c:772
#30 0x00007f04ffec34a1 in tevent_common_loop_wait (ev=0x559b9829af00, location=0x7f0500a4b858 "../../source3/smbd/process.c:4120") at ../../lib/tevent/tevent.c:895
#31 0x00007f04ffecb77d in std_event_loop_wait (ev=0x559b9829af00, location=0x7f0500a4b858 "../../source3/smbd/process.c:4120") at ../../lib/tevent/tevent_standard.c:141
#32 0x00007f04ffec3544 in _tevent_loop_wait (ev=0x559b9829af00, location=0x7f0500a4b858 "../../source3/smbd/process.c:4120") at ../../lib/tevent/tevent.c:914
#33 0x00007f050087c2bd in smbd_process (ev_ctx=0x559b9829af00, msg_ctx=0x559b982ae7f0, sock_fd=38, interactive=false) at ../../source3/smbd/process.c:4120
#34 0x0000559b977b840a in  ()
(gdb) frame 5
#5  0x00007f050091eb5c in share_mode_data_destructor (d=0x559b983fc7f0) at ../../source3/locking/share_mode_lock.c:423
423			smb_panic(errmsg);
(gdb) info locals
errmsg = 0x559b98391660 "could not store share mode entry: NT_STATUS_UNSUCCESSFUL"
status = {v = 3221225473}
data = {dptr = 0x559b98611060 "\331ͫAA\037R\203", dsize = 332}
__FUNCTION__ = "share_mode_data_destructor"
(gdb) frame 6
#6  0x00007f04ff8aaa96 in _tc_free_internal (tc=0x559b983fc790, location=0x7f0500a3c2b0 "../../source3/smbd/open.c:3845") at ../../lib/talloc/talloc.c:1137
1137			if (d(ptr) == -1) {
(gdb) info locals
d = 0x7f050091e95f <share_mode_data_destructor>
ptr_to_free = 0x0
ptr = 0x559b983fc7f0
(gdb) frame 7
#7  0x00007f04ff8abd2b in _tc_free_children_internal (tc=0x559b9860e2c0, ptr=0x559b9860e320, location=0x7f0500a3c2b0 "../../source3/smbd/open.c:3845")
    at ../../lib/talloc/talloc.c:1646
1646			if (unlikely(_tc_free_internal(tc->child, location) == -1)) {
(gdb) info locals
child = 0x559b983fc7f0
new_parent = 0x559b98294550
Comment 7 Ralph Böhme 2019-08-27 09:44:48 UTC
(In reply to juha.kuikka from comment #6)
The crash is triggered by an explicit call to smb_panic() in an error code path. Here dbwrap_record_store() failed to store the open file information in locking.tdb for some reason.

The codepath has an DBG_ERR message that would log the error code:

  DEBUG(0, ("store returned %s\n", nt_errstr(status)));

Can you check your logs please and post the line? Thanks!
Comment 8 juha.kuikka 2019-08-28 18:35:06 UTC
(In reply to Ralph Böhme from comment #7)

Is this the pertinent part, I can also attach the full log if needed.

[2019/08/26 22:15:58.018347,  0] ../../source3/lib/dumpcore.c:318(dump_core)
  coredump is handled by helper binary specified at /proc/sys/kernel/core_pattern[2019/08/26 22:15:58.159897,  0] ../../source3/locking/share_mode_lock.c:417(share_mode_data_destructor)
  store returned NT_STATUS_UNSUCCESSFUL
[2019/08/26 22:15:58.159942,  0] ../../source3/lib/util.c:824(smb_panic_s3)
  PANIC (pid 20462): could not store share mode entry: NT_STATUS_UNSUCCESSFUL
[2019/08/26 22:15:58.160430,  0] ../../lib/util/fault.c:261(log_stack_trace)
  BACKTRACE: 43 stack frames:
   #0 /usr/lib/x86_64-linux-gnu/libsamba-util.so.0(log_stack_trace+0x2e) [0x7f0500d5365f]
   #1 /usr/lib/x86_64-linux-gnu/libsmbconf.so.0(smb_panic_s3+0x6b) [0x7f04ff242647]
   #2 /usr/lib/x86_64-linux-gnu/libsamba-util.so.0(smb_panic+0x28) [0x7f0500d5361b]
   #3 /usr/lib//samba/libsmbd-base-samba4.so(+0x241b5c) [0x7f050091eb5c]
   #4 /usr/lib//samba/libtalloc.so.2(+0x3a96) [0x7f04ff8aaa96]
   #5 /usr/lib//samba/libtalloc.so.2(+0x4d2b) [0x7f04ff8abd2b]
   #6 /usr/lib//samba/libtalloc.so.2(+0x3c51) [0x7f04ff8aac51]
   #7 /usr/lib//samba/libtalloc.so.2(+0x4d2b) [0x7f04ff8abd2b]
   #8 /usr/lib//samba/libtalloc.so.2(+0x3c51) [0x7f04ff8aac51]
   #9 /usr/lib//samba/libtalloc.so.2(+0x3e12) [0x7f04ff8aae12]
   #10 /usr/lib//samba/libtalloc.so.2(_talloc_free+0x105) [0x7f04ff8ac178]
   #11 /usr/lib//samba/libsmbd-base-samba4.so(+0x16f30a) [0x7f050084c30a]
   #12 /usr/lib//samba/libsmbd-base-samba4.so(+0x1728d2) [0x7f050084f8d2]
   #13 /usr/lib//samba/libsmbd-base-samba4.so(create_file_default+0x32d) [0x7f0500850598]
   #14 /usr/lib//samba/libsmbd-base-samba4.so(+0x2e6353) [0x7f05009c3353]
   #15 /usr/lib//samba/libsmbd-base-samba4.so(smb_vfs_call_create_file+0xa9) [0x7f050085cd0a]
   #16 /usr/lib//samba/libsmbd-base-samba4.so(+0x1c9fca) [0x7f05008a6fca]
   #17 /usr/lib//samba/libsmbd-base-samba4.so(smbd_smb2_request_process_create+0x765) [0x7f05008a4aeb]
   #18 /usr/lib//samba/libsmbd-base-samba4.so(smbd_smb2_request_dispatch+0x128c) [0x7f0500897ab7]
   #19 /usr/lib//samba/libsmbd-base-samba4.so(+0x1beb2f) [0x7f050089bb2f]
   #20 /usr/lib//samba/libsmbd-base-samba4.so(+0x1bec49) [0x7f050089bc49]
   #21 /usr/lib//samba/libtevent.so.0(tevent_common_invoke_fd_handler+0x101) [0x7f04ffec3f24]
   #22 /usr/lib//samba/libtevent.so.0(+0x1180f) [0x7f04ffece80f]
   #23 /usr/lib//samba/libtevent.so.0(+0x11ee3) [0x7f04ffeceee3]
   #24 /usr/lib//samba/libtevent.so.0(+0xe6db) [0x7f04ffecb6db]
   #25 /usr/lib//samba/libtevent.so.0(_tevent_loop_once+0x11e) [0x7f04ffec314f]
   #26 /usr/lib//samba/libtevent.so.0(tevent_common_loop_wait+0x25) [0x7f04ffec34a1]
   #27 /usr/lib//samba/libtevent.so.0(+0xe77d) [0x7f04ffecb77d]
   #28 /usr/lib//samba/libtevent.so.0(_tevent_loop_wait+0x2b) [0x7f04ffec3544]
   #29 /usr/lib//samba/libsmbd-base-samba4.so(smbd_process+0xba4) [0x7f050087c2bd]
   #30 /usr/sbin/smbd(+0xe40a) [0x559b977b840a]
   #31 /usr/lib//samba/libtevent.so.0(tevent_common_invoke_fd_handler+0x101) [0x7f04ffec3f24]
   #32 /usr/lib//samba/libtevent.so.0(+0x1180f) [0x7f04ffece80f]
   #33 /usr/lib//samba/libtevent.so.0(+0x11ee3) [0x7f04ffeceee3]
   #34 /usr/lib//samba/libtevent.so.0(+0xe6db) [0x7f04ffecb6db]
   #35 /usr/lib//samba/libtevent.so.0(_tevent_loop_once+0x11e) [0x7f04ffec314f]
   #36 /usr/lib//samba/libtevent.so.0(tevent_common_loop_wait+0x25) [0x7f04ffec34a1]
   #37 /usr/lib//samba/libtevent.so.0(+0xe77d) [0x7f04ffecb77d]
   #38 /usr/lib//samba/libtevent.so.0(_tevent_loop_wait+0x2b) [0x7f04ffec3544]
   #39 /usr/sbin/smbd(+0xf1a1) [0x559b977b91a1]
   #40 /usr/sbin/smbd(main+0x1921) [0x559b977bb419]
   #41 /lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0xe7) [0x7f04fc861b97]
   #42 /usr/sbin/smbd(_start+0x2a) [0x559b977b094a]
Comment 9 juha.kuikka 2019-08-28 18:37:30 UTC
Created attachment 15445 [details]
SMB log for crash during time machine backup
Comment 10 Kevin Stallard 2019-11-03 19:27:53 UTC
This is also happening to me, even running Samaba 4.11 (the latest).

Below is the log information from syslog (stack trace).  

I did a fair amount of digging, I found one reference that suggested it might be running out of temporary space for some of the memory resident data files that it creates:

https://lists.samba.org/archive/samba/2018-October/218975.html

This seems to make because talloc is involved and mention of share_mode_data_store is mentioned.
 
At the point that the server crashed df reported that /run/lock was at 89%.  So while it wasn't full, I am still testing with a much bigger allocation for /run/lock than should be needed to see how it does.

I will follow up with results this testing.  Hopefully it is just a configuration issue.


Nov  3 11:34:32 macbackup smbd[3460]: [2019/11/03 11:34:32.956084,  0, pid=3460, effective(0, 10006), real(0, 0), class=locking] ../../source3/locking/share_mode_lock.c:653(share_mode_lock_destructor)
Nov  3 11:34:32 macbackup smbd[3460]:   share_mode_lock_destructor: share_mode_data_store failed: NT_STATUS_UNSUCCESSFUL
Nov  3 11:34:32 macbackup smbd[3460]: [2019/11/03 11:34:32.957186,  0, pid=3460, effective(0, 10006), real(0, 0)] ../../source3/lib/util.c:824(smb_panic_s3)
Nov  3 11:34:32 macbackup smbd[3460]:   PANIC (pid 3460): Could not store share mode data
Nov  3 11:34:32 macbackup smbd[3460]: 
Nov  3 11:34:32 macbackup smbd[3460]: [2019/11/03 11:34:32.959989,  0, pid=3460, effective(0, 10006), real(0, 0)] ../../lib/util/fault.c:265(log_stack_trace)
Nov  3 11:34:32 macbackup smbd[3460]:   BACKTRACE: 41 stack frames:
Nov  3 11:34:32 macbackup smbd[3460]:    #0 /usr/lib/x86_64-linux-gnu/libsamba-util.so.0(log_stack_trace+0x2e) [0x7f48890c2f7e]
Nov  3 11:34:32 macbackup smbd[3460]:    #1 /usr/lib/x86_64-linux-gnu/libsmbconf.so.0(smb_panic_s3+0x6b) [0x7f48875f27a0]
Nov  3 11:34:32 macbackup smbd[3460]:    #2 /usr/lib/x86_64-linux-gnu/libsamba-util.so.0(smb_panic+0x28) [0x7f48890c2f3a]
Nov  3 11:34:32 macbackup smbd[3460]:    #3 /usr/lib/x86_64-linux-gnu/samba/libsmbd-base-samba4.so(+0x2247f5) [0x7f4888ca27f5]
Nov  3 11:34:32 macbackup smbd[3460]:    #4 /usr/lib/x86_64-linux-gnu/samba/libtalloc.so.2(+0x378f) [0x7f4887c4b78f]
Nov  3 11:34:32 macbackup smbd[3460]:    #5 /usr/lib/x86_64-linux-gnu/samba/libtalloc.so.2(+0x3b0b) [0x7f4887c4bb0b]
Nov  3 11:34:32 macbackup smbd[3460]:    #6 /usr/lib/x86_64-linux-gnu/samba/libtalloc.so.2(_talloc_free+0x105) [0x7f4887c4ce71]
Nov  3 11:34:32 macbackup smbd[3460]:    #7 /usr/lib/x86_64-linux-gnu/samba/libsmbd-base-samba4.so(+0x16003f) [0x7f4888bde03f]
Nov  3 11:34:32 macbackup smbd[3460]:    #8 /usr/lib/x86_64-linux-gnu/samba/libsmbd-base-samba4.so(+0x163a90) [0x7f4888be1a90]
Nov  3 11:34:32 macbackup smbd[3460]:    #9 /usr/lib/x86_64-linux-gnu/samba/libsmbd-base-samba4.so(create_file_default+0x333) [0x7f4888be26e7]
Nov  3 11:34:32 macbackup smbd[3460]:    #10 /usr/lib/x86_64-linux-gnu/samba/libsmbd-base-samba4.so(+0x2c090a) [0x7f4888d3e90a]
Nov  3 11:34:32 macbackup smbd[3460]:    #11 /usr/lib/x86_64-linux-gnu/samba/libsmbd-base-samba4.so(smb_vfs_call_create_file+0xa9) [0x7f4888bed620]
Nov  3 11:34:32 macbackup smbd[3460]:    #12 /usr/lib/x86_64-linux-gnu/samba/vfs/fruit.so(+0x16667) [0x7f486f345667]
Nov  3 11:34:32 macbackup smbd[3460]:    #13 /usr/lib/x86_64-linux-gnu/samba/libsmbd-base-samba4.so(smb_vfs_call_create_file+0xa9) [0x7f4888bed620]
Nov  3 11:34:32 macbackup smbd[3460]:    #14 /usr/lib/x86_64-linux-gnu/samba/libsmbd-base-samba4.so(+0x1b60cb) [0x7f4888c340cb]
Nov  3 11:34:32 macbackup smbd[3460]:    #15 /usr/lib/x86_64-linux-gnu/samba/libsmbd-base-samba4.so(smbd_smb2_request_process_create+0x7ab) [0x7f4888c31bc8]
Nov  3 11:34:32 macbackup smbd[3460]:    #16 /usr/lib/x86_64-linux-gnu/samba/libsmbd-base-samba4.so(smbd_smb2_request_dispatch+0x12a2) [0x7f4888c24a0c]
Nov  3 11:34:32 macbackup smbd[3460]:    #17 /usr/lib/x86_64-linux-gnu/samba/libsmbd-base-samba4.so(+0x1aaca8) [0x7f4888c28ca8]
Nov  3 11:34:32 macbackup smbd[3460]:    #18 /usr/lib/x86_64-linux-gnu/samba/libsmbd-base-samba4.so(+0x1aadc2) [0x7f4888c28dc2]
Nov  3 11:34:32 macbackup smbd[3460]:    #19 /usr/lib/x86_64-linux-gnu/samba/libtevent.so.0(tevent_common_invoke_fd_handler+0x101) [0x7f4888264d47]
Nov  3 11:34:32 macbackup smbd[3460]:    #20 /usr/lib/x86_64-linux-gnu/samba/libtevent.so.0(+0x11795) [0x7f488826f795]
Nov  3 11:34:32 macbackup smbd[3460]:    #21 /usr/lib/x86_64-linux-gnu/samba/libtevent.so.0(+0x11e78) [0x7f488826fe78]
Nov  3 11:34:32 macbackup smbd[3460]:    #22 /usr/lib/x86_64-linux-gnu/samba/libtevent.so.0(+0xe5e3) [0x7f488826c5e3]
Nov  3 11:34:32 macbackup smbd[3460]:    #23 /usr/lib/x86_64-linux-gnu/samba/libtevent.so.0(_tevent_loop_once+0x11e) [0x7f4888263f6a]
Nov  3 11:34:32 macbackup smbd[3460]:    #24 /usr/lib/x86_64-linux-gnu/samba/libtevent.so.0(tevent_common_loop_wait+0x25) [0x7f48882642b8]
Nov  3 11:34:32 macbackup smbd[3460]:    #25 /usr/lib/x86_64-linux-gnu/samba/libtevent.so.0(+0xe685) [0x7f488826c685]
Nov  3 11:34:32 macbackup smbd[3460]:    #26 /usr/lib/x86_64-linux-gnu/samba/libtevent.so.0(_tevent_loop_wait+0x2b) [0x7f488826435b]
Nov  3 11:34:32 macbackup smbd[3460]:    #27 /usr/lib/x86_64-linux-gnu/samba/libsmbd-base-samba4.so(smbd_process+0xbaf) [0x7f4888c0c26f]
Nov  3 11:34:32 macbackup smbd[3460]:    #28 /usr/sbin/smbd(+0xd961) [0x55a8f7f07961]
Nov  3 11:34:32 macbackup smbd[3460]:    #29 /usr/lib/x86_64-linux-gnu/samba/libtevent.so.0(tevent_common_invoke_fd_handler+0x101) [0x7f4888264d47]
Nov  3 11:34:32 macbackup smbd[3460]:    #30 /usr/lib/x86_64-linux-gnu/samba/libtevent.so.0(+0x11795) [0x7f488826f795]
Nov  3 11:34:32 macbackup smbd[3460]:    #31 /usr/lib/x86_64-linux-gnu/samba/libtevent.so.0(+0x11e78) [0x7f488826fe78]
Nov  3 11:34:32 macbackup smbd[3460]:    #32 /usr/lib/x86_64-linux-gnu/samba/libtevent.so.0(+0xe5e3) [0x7f488826c5e3]
Nov  3 11:34:32 macbackup smbd[3460]:    #33 /usr/lib/x86_64-linux-gnu/samba/libtevent.so.0(_tevent_loop_once+0x11e) [0x7f4888263f6a]
Nov  3 11:34:32 macbackup smbd[3460]:    #34 /usr/lib/x86_64-linux-gnu/samba/libtevent.so.0(tevent_common_loop_wait+0x25) [0x7f48882642b8]
Nov  3 11:34:32 macbackup smbd[3460]:    #35 /usr/lib/x86_64-linux-gnu/samba/libtevent.so.0(+0xe685) [0x7f488826c685]
Nov  3 11:34:32 macbackup smbd[3460]:    #36 /usr/lib/x86_64-linux-gnu/samba/libtevent.so.0(_tevent_loop_wait+0x2b) [0x7f488826435b]
Nov  3 11:34:32 macbackup smbd[3460]:    #37 /usr/sbin/smbd(+0xe663) [0x55a8f7f08663]
Nov  3 11:34:32 macbackup smbd[3460]:    #38 /usr/sbin/smbd(main+0x1913) [0x55a8f7f0a942]
Nov  3 11:34:32 macbackup smbd[3460]:    #39 /lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0xf0) [0x7f4884c45830]
Nov  3 11:34:32 macbackup smbd[3460]:    #40 /usr/sbin/smbd(_start+0x29) [0x55a8f7f00039]
Nov  3 11:34:32 macbackup smbd[3460]: [2019/11/03 11:34:32.969232,  0, pid=3460, effective(0, 10006), real(0, 0)] ../../source3/lib/dumpcore.c:315(dump_core)
Nov  3 11:34:32 macbackup smbd[3460]:   dumping core in /var/log/samba/cores/smbd
Nov  3 11:34:32 macbackup smbd[3460]: 
Nov  3 11:56:03 macbackup smbd[1147]: [2019/11/03 11:56:03.849731,  0, pid=1147, effective(0, 0), real(0, 0)] ../../lib/util/become_daemon.c:136(daemon_ready)
Nov  3 11:56:03 macbackup smbd[1147]:   daemon_ready: daemon 'smbd' finished starting up and ready to serve connections
Comment 11 Kevin Stallard 2019-11-04 03:17:58 UTC
This was most certainly the issue.  Increasing the amount of RAM for /run/lock fixed the problem.  When m very large backup completed, /run/lock/samba/locking.tbd is over 5 Megs.  /run/lock is consuming over 6 megs currently. 5 MB was the previous default max size for /run/lock.  

When samba core dumped, it was 89% full.  It was unable to allocate the necessary memory to add data to locking.tdb.

Either that is normal behavior or there is a resource leak with respect to locking.tdb.

Considering the original information posted, and comparing it to my results, it seems leo@vankampenhout.net and I had the same issue.

If this remains open it should only be because samba needs to release/recycle entries in locking.tdb (if that is the appropriate thing to do).

Thanks,
Kevin
Comment 12 Kevin Stallard 2019-11-04 12:44:15 UTC
I started another complete Time Machine backup (renamed the old sparse bundle so that a new one was created).  It was a 400GB backup.  I did not restart Samba. /run/var/samba/locking.tdb has continued to grow from 5.1MB to 8MB thus far.  Around 200GB (about half) has completed.

It isn't much, but from what I can see (I don't yet have an understanding of how locking.tdb is supposed to behave) there is a resource leak here. It appears that Samba is unable to run continuosley as eventually locking.tdb will use up all available space.

Thanks,
Kevin
Comment 13 Ralph Böhme 2019-11-04 12:56:49 UTC
(In reply to Kevin Stallard from comment #12)
locking.tdb store state associated with file handles. You can use smbstatus to list file handles.

If this list keeps growing there may be a file handle leak in the client or the server. It could be by design (in the client), but I doubt.
Comment 14 Kevin Stallard 2019-11-04 13:14:48 UTC
(In reply to Ralph Böhme from comment #13)

Thank you Ralph,

I did an smbstatus (locking.tdb still around 8MB).  It does not appear that the client is holding onto excess file handles.  Here is the output of smbstatus. The number of open file handles is limited.

Samba version 4.11.2
PID     Username     Group        Machine                                   Protocol Version  Encryption           Signing              
----------------------------------------------------------------------------------------------------------------------------------------
2684    leah         domain users 10.100.50.71 (ipv4:10.100.50.71:49718)    SMB3_02           -                    AES-128-CMAC         
2390    leah         domain users 10.100.50.71 (ipv4:10.100.50.71:49691)    SMB3_02           -                    AES-128-CMAC         

Service      pid     Machine       Connected at                     Encryption   Signing     
---------------------------------------------------------------------------------------------
leahsTimemachine 2684    10.100.50.71  Sun Nov  3 10:42:44 PM 2019 MST  -            AES-128-CMAC
leahsTimemachine 2390    10.100.50.71  Sun Nov  3 09:52:23 PM 2019 MST  -            AES-128-CMAC

Locked files:
Pid          User(ID)   DenyMode   Access      R/W        Oplock           SharePath   Name   Time
--------------------------------------------------------------------------------------------------
2390         0          DENY_ALL   0x20007     RDWR       LEASE(RH)        /data/backup/leahsTimemachine   LeahsMacbook.sparsebundle/bands/7446   Mon Nov  4 06:07:21 2019
2390         0          DENY_ALL   0x20007     RDWR       LEASE(RH)        /data/backup/leahsTimemachine   LeahsMacbook.sparsebundle/bands/7449   Mon Nov  4 06:07:25 2019
2390         0          DENY_ALL   0x20007     RDWR       LEASE(RH)        /data/backup/leahsTimemachine   LeahsMacbook.sparsebundle/bands/7443   Mon Nov  4 06:07:18 2019
2390         0          DENY_ALL   0x20007     RDWR       LEASE(RH)        /data/backup/leahsTimemachine   LeahsMacbook.sparsebundle/bands/7444   Mon Nov  4 06:07:19 2019
2684         0          DENY_NONE  0x100081    RDONLY     NONE             /data/backup/leahsTimemachine   .   Sun Nov  3 22:42:44 2019
2390         0          DENY_ALL   0x20007     RDWR       LEASE(RH)        /data/backup/leahsTimemachine   LeahsMacbook.sparsebundle/token   Sun Nov  3 21:53:21 2019
2390         0          DENY_ALL   0x20007     RDWR       LEASE(RH)        /data/backup/leahsTimemachine   LeahsMacbook.sparsebundle/bands/7448   Mon Nov  4 06:07:24 2019
2390         0          DENY_ALL   0x20007     RDWR       LEASE(RH)        /data/backup/leahsTimemachine   LeahsMacbook.sparsebundle/bands/7447   Mon Nov  4 06:07:23 2019
2390         0          DENY_ALL   0x20007     RDWR       LEASE(RH)        /data/backup/leahsTimemachine   LeahsMacbook.sparsebundle/bands/73fb   Mon Nov  4 06:07:16 2019
2390         0          DENY_ALL   0x20007     RDWR       LEASE(RH)        /data/backup/leahsTimemachine   LeahsMacbook.sparsebundle/bands/73ad   Mon Nov  4 06:07:17 2019
2390         0          DENY_ALL   0x20007     RDWR       LEASE(RH)        /data/backup/leahsTimemachine   LeahsMacbook.sparsebundle/bands/4f79   Mon Nov  4 06:07:16 2019
2390         0          DENY_ALL   0x20007     RDWR       LEASE(RH)        /data/backup/leahsTimemachine   LeahsMacbook.sparsebundle/bands/729f   Mon Nov  4 06:07:16 2019
2390         0          DENY_ALL   0x20007     RDWR       LEASE(RH)        /data/backup/leahsTimemachine   LeahsMacbook.sparsebundle/bands/7441   Mon Nov  4 06:07:09 2019
2390         0          DENY_ALL   0x20007     RDWR       LEASE(RH)        /data/backup/leahsTimemachine   LeahsMacbook.sparsebundle/bands/53b9   Mon Nov  4 06:07:16 2019
2390         0          DENY_ALL   0x20007     RDWR       LEASE(RH)        /data/backup/leahsTimemachine   LeahsMacbook.sparsebundle/bands/23   Mon Nov  4 06:07:09 2019
2390         0          DENY_ALL   0x20007     RDWR       LEASE(RH)        /data/backup/leahsTimemachine   LeahsMacbook.sparsebundle/bands/273   Mon Nov  4 06:07:16 2019
2390         0          DENY_ALL   0x20007     RDWR       LEASE(RH)        /data/backup/leahsTimemachine   LeahsMacbook.sparsebundle/bands/7445   Mon Nov  4 06:07:20 2019
2390         0          DENY_ALL   0x20007     RDWR       LEASE(RH)        /data/backup/leahsTimemachine   LeahsMacbook.sparsebundle/bands/5b   Mon Nov  4 06:07:17 2019
2390         0          DENY_ALL   0x20007     RDWR       LEASE(RH)        /data/backup/leahsTimemachine   LeahsMacbook.sparsebundle/bands/7442   Mon Nov  4 06:07:17 2019
2390         0          DENY_ALL   0x20007     RDWR       LEASE(RH)        /data/backup/leahsTimemachine   LeahsMacbook.sparsebundle/bands/19   Mon Nov  4 06:07:16 2019
2390         0          DENY_ALL   0x20007     RDWR       LEASE(RH)        /data/backup/leahsTimemachine   LeahsMacbook.sparsebundle/bands/4f   Mon Nov  4 06:07:15 2019
Comment 15 Ralph Böhme 2019-11-04 13:17:37 UTC
(In reply to Kevin Stallard from comment #14)
Oh, good! That means what you're seeing is just on-disk free space fragmentation. Just ensure there's enough space for the TDBs.
Comment 16 Kevin Stallard 2019-11-04 13:22:17 UTC
(In reply to Ralph Böhme from comment #15)

I don't understand, locking.tdb continues to grow unabated, and does not shrink. I have run two separate backups, and Samba does not appear to reclaim/remove entries in locking.tdb.  It causes a core dump and failure of Samba when this happens.
Comment 17 Kevin Stallard 2019-11-04 13:23:27 UTC
(In reply to Kevin Stallard from comment #16)

...when it runs out of space...
Comment 18 Ralph Böhme 2019-11-04 13:29:37 UTC
(In reply to Kevin Stallard from comment #17)
The only numbers you posted were "8 MB" which is reasonable. Do you actually see it growing larger then that?
Comment 19 Kevin Stallard 2019-11-04 13:37:17 UTC
(In reply to Ralph Böhme from comment #18)

I apologize, I was not as clear as I would have liked.  

1st 400GB backup yielded a 5.1MB Locking.tdb file.
2nd 400GB backup (still in progress) has thus far increased locking.tdb to 8MB.

The backup has yet to complete, but as of now, I have only seen locking.tdb continue to increase.

I will wait for this to finish before I claim that there is no reclamation occurring, but as of this point, it continues to grow.
Comment 20 Kevin Stallard 2019-11-04 17:13:17 UTC
(In reply to Kevin Stallard from comment #19)

Hi Ralph,

The usage capped out at 8MB.  Never increased beyond that.  Thank you for working with me on this.  I think this bug report can be closed.

Kevin
Comment 21 leo 2019-12-10 08:41:35 UTC
(In reply to Kevin Stallard from comment #20)
Hi Kevin, thanks for your analysis on this issue! Could you summarize how you increased the amount of RAM for /run/lock ? 

And: doesn't this need a pull request to be fixed in the code?
Comment 22 leo 2019-12-10 08:44:04 UTC
(In reply to leo from comment #21)
Or, if it can't be fixed on Samba's side, there should at least be a warning message or something, instead of a core dump.
Comment 23 Kevin Stallard 2019-12-10 14:51:10 UTC
(In reply to leo from comment #22)

Hi Leo,

I added/changed the following in /etc/fstab

tmpfs  /run/lock   tmpfs  nodev,noexec,nosuid,size=15M  0 0


I agree, a change to samba to at least put in a log entry before it dies when it runs out of lock space would be great along with a hint.  I am not familiar with samba code and thought it might make more sense for someone more familiar with it to make this change.

If no one does anything with it, I might take a stab at it and see if it is accepted....

But in the mean time, hopefully Google has picked up on this thread and other poor souls trying to make Time Machine work with Samba can easily find this.

Thanks,
Kevin
Comment 24 juha.kuikka 2019-12-10 18:19:22 UTC
One more anecdote: for my mac with several TBs of TM data, I had to increase the size to 64M to avoid this issue.

I don't know if the size is related to amount of files, size of backup or something completely different but I just wanted to point out that 16MB is not sufficient for all cases.

And I agree, if a crash cannot be avoided, smbd should at least provide a helpful log message in this case.
Comment 25 Volker Lendecke 2019-12-10 19:56:56 UTC
Created attachment 15675 [details]
Patch to potentially keep locking.tdb smaller

Can someone on this bug try the attached patch? It's intended to keep locking.tdb smaller for lightly loaded systems