Bug 14565 - INTERNAL ERROR: Signal 11 in pid XXX (4.12.7)
Summary: INTERNAL ERROR: Signal 11 in pid XXX (4.12.7)
Status: RESOLVED DUPLICATE of bug 14515
Alias: None
Product: Samba 4.1 and newer
Classification: Unclassified
Component: File services (show other bugs)
Version: 4.12.7
Hardware: x64 Linux
: P5 normal (vote)
Target Milestone: ---
Assignee: Samba QA Contact
QA Contact: Samba QA Contact
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2020-11-04 08:51 UTC by Aritz Brosa
Modified: 2020-11-09 11:20 UTC (History)
1 user (show)

See Also:

Attachments
Add an attachment (proposed patch, testcase, etc.)

Note You need to log in before you can comment on or make changes to this bug.
Description Aritz Brosa 2020-11-04 08:51:47 UTC 
2020-11-02T15:04:23.636539+01:00 samba-11 smbd[3549453]: ===============================================================
2020-11-02T15:04:23.636987+01:00 samba-11 smbd[3549453]: INTERNAL ERROR: Signal 11 in pid 3549453 (4.12.7)
2020-11-02T15:04:23.637080+01:00 samba-11 smbd[3549453]: ===============================================================
2020-11-02T15:04:23.637116+01:00 samba-11 smbd[3549453]: PANIC (pid 3549453): internal error
2020-11-02T15:04:23.637152+01:00 samba-11 smbd[3549453]: BACKTRACE:
2020-11-02T15:04:23.637588+01:00 samba-11 smbd[3549453]: #0 log_stack_trace + 0x3d [ip=0x7f445a1a141d] [sp=0x7ffcc4446b80]
2020-11-02T15:04:23.638229+01:00 samba-11 smbd[3549453]: #1 smb_panic_s3 + 0x29 [ip=0x7f4459bfb619] [sp=0x7ffcc44474c0]
2020-11-02T15:04:23.638795+01:00 samba-11 smbd[3549453]: #2 smb_panic + 0x31 [ip=0x7f445a1a1631] [sp=0x7ffcc44474e0]
2020-11-02T15:04:23.639342+01:00 samba-11 smbd[3549453]: #3 smb_panic + 0x291 [ip=0x7f445a1a1891] [sp=0x7ffcc44475f0]
2020-11-02T15:04:23.639812+01:00 samba-11 smbd[3549453]: #4 funlockfile + 0x50 [ip=0x7f4458d83dd0] [sp=0x7ffcc4447600]
2020-11-02T15:04:23.640361+01:00 samba-11 smbd[3549453]: #5 create_file_default + 0x72a [ip=0x7f4459e12f7a] [sp=0x7ffcc44482d0]
2020-11-02T15:04:23.640898+01:00 samba-11 smbd[3549453]: #6 close_file + 0xd0 [ip=0x7f4459e13940] [sp=0x7ffcc4448300]
2020-11-02T15:04:23.641430+01:00 samba-11 smbd[3549453]: #7 file_close_user + 0x3d [ip=0x7f4459dae8bd] [sp=0x7ffcc4448520]
2020-11-02T15:04:23.641975+01:00 samba-11 smbd[3549453]: #8 smbXsrv_session_logoff + 0x51 [ip=0x7f4459e5d211] [sp=0x7ffcc4448540]
2020-11-02T15:04:23.642530+01:00 samba-11 smbd[3549453]: #9 smbXsrv_session_logoff + 0x3fa [ip=0x7f4459e5d5ba] [sp=0x7ffcc4448590]
2020-11-02T15:04:23.642957+01:00 samba-11 smbd[3549453]: #10 dbwrap_unmarshall + 0x194 [ip=0x7f44578ff0a4] [sp=0x7ffcc44485b0]
2020-11-02T15:04:23.643430+01:00 samba-11 smbd[3549453]: #11 dbwrap_unmarshall + 0x3ce [ip=0x7f44578ff2de] [sp=0x7ffcc4448670]
2020-11-02T15:04:23.643869+01:00 samba-11 smbd[3549453]: #12 dbwrap_traverse + 0xb [ip=0x7f44578fd83b] [sp=0x7ffcc44486a0]
2020-11-02T15:04:23.644416+01:00 samba-11 smbd[3549453]: #13 smbXsrv_session_logoff_all + 0x5b [ip=0x7f4459e5d77b] [sp=0x7ffcc44486b0]
2020-11-02T15:04:23.644924+01:00 samba-11 smbd[3549453]: #14 smbXsrv_open_cleanup + 0x55e [ip=0x7f4459e62e8e] [sp=0x7ffcc44486f0]
2020-11-02T15:04:23.645455+01:00 samba-11 smbd[3549453]: #15 smbd_exit_server_cleanly + 0x14 [ip=0x7f4459e633f4] [sp=0x7ffcc4448740]
2020-11-02T15:04:23.646162+01:00 samba-11 smbd[3549453]: #16 exit_server_cleanly + 0x18 [ip=0x7f4459612a18] [sp=0x7ffcc4448750]
2020-11-02T15:04:23.646741+01:00 samba-11 smbd[3549453]: #17 smbd_server_connection_terminate_ex + 0x162 [ip=0x7f4459e3dd42] [sp=0x7ffcc44487
60]
2020-11-02T15:04:23.647302+01:00 samba-11 smbd[3549453]: #18 smbd_smb2_request_process_keepalive + 0x2fa [ip=0x7f4459e52d4a] [sp=0x7ffcc4448790]
2020-11-02T15:04:23.647809+01:00 samba-11 smbd[3549453]: #19 smbd_smb2_request_pending_queue + 0x15f [ip=0x7f4459e3ec1f] [sp=0x7ffcc44487f0]
2020-11-02T15:04:23.648331+01:00 samba-11 smbd[3549453]: #20 smbd_smb2_request_process_query_directory + 0x223 [ip=0x7f4459e548f3] [sp=0x7ffcc44488a0]
2020-11-02T15:04:23.648864+01:00 samba-11 smbd[3549453]: #21 smbd_smb2_request_dispatch + 0xe44 [ip=0x7f4459e40114] [sp=0x7ffcc4448910]
2020-11-02T15:04:23.649418+01:00 samba-11 smbd[3549453]: #22 smbd_smb2_request_dispatch_immediate + 0x50 [ip=0x7f4459e41830] [sp=0x7ffcc44489b0]
2020-11-02T15:04:23.649910+01:00 samba-11 smbd[3549453]: #23 tevent_common_invoke_immediate_handler + 0x139 [ip=0x7f4458f98879] [sp=0x7ffcc44489d0]
2020-11-02T15:04:23.650419+01:00 samba-11 smbd[3549453]: #24 tevent_common_loop_immediate + 0x27 [ip=0x7f4458f988a7] [sp=0x7ffcc4448a20]
2020-11-02T15:04:23.650897+01:00 samba-11 smbd[3549453]: #25 tevent_wakeup_recv + 0xfef [ip=0x7f4458f9e79f] [sp=0x7ffcc4448a40]
2020-11-02T15:04:23.651399+01:00 samba-11 smbd[3549453]: #26 tevent_cleanup_pending_signal_handlers + 0xcb [ip=0x7f4458f9c99b] [sp=0x7ffcc444
8aa0]
2020-11-02T15:04:23.651904+01:00 samba-11 smbd[3549453]: #27 _tevent_loop_once + 0x95 [ip=0x7f4458f97b15] [sp=0x7ffcc4448ac0]
2020-11-02T15:04:23.652385+01:00 samba-11 smbd[3549453]: #28 tevent_common_loop_wait + 0x1b [ip=0x7f4458f97dbb] [sp=0x7ffcc4448af0]
2020-11-02T15:04:23.652866+01:00 samba-11 smbd[3549453]: #29 tevent_cleanup_pending_signal_handlers + 0x5b [ip=0x7f4458f9c92b] [sp=0x7ffcc444
8b10]
2020-11-02T15:04:23.653397+01:00 samba-11 smbd[3549453]: #30 smbd_process + 0x7bf [ip=0x7f4459e3009f] [sp=0x7ffcc4448b30]
2020-11-02T15:04:23.653544+01:00 samba-11 smbd[3549453]: #31 smbd_accept_connection + 0x130 [ip=0x559323715d00] [sp=0x7ffcc4448bd0]
2020-11-02T15:04:23.654059+01:00 samba-11 smbd[3549453]: #32 tevent_common_invoke_fd_handler + 0x83 [ip=0x7f4458f98443] [sp=0x7ffcc4448ca0]
2020-11-02T15:04:23.654555+01:00 samba-11 smbd[3549453]: #33 tevent_wakeup_recv + 0x120f [ip=0x7f4458f9e9bf] [sp=0x7ffcc4448cd0]
2020-11-02T15:04:23.654997+01:00 samba-11 smbd[3549453]: #34 tevent_cleanup_pending_signal_handlers + 0xcb [ip=0x7f4458f9c99b] [sp=0x7ffcc444
8d30]
2020-11-02T15:04:23.655430+01:00 samba-11 smbd[3549453]: #35 _tevent_loop_once + 0x95 [ip=0x7f4458f97b15] [sp=0x7ffcc4448d50]
2020-11-02T15:04:23.655858+01:00 samba-11 smbd[3549453]: #36 tevent_common_loop_wait + 0x1b [ip=0x7f4458f97dbb] [sp=0x7ffcc4448d80]
2020-11-02T15:04:23.656286+01:00 samba-11 smbd[3549453]: #37 tevent_cleanup_pending_signal_handlers + 0x5b [ip=0x7f4458f9c92b] [sp=0x7ffcc444
8da0]
2020-11-02T15:04:23.656346+01:00 samba-11 smbd[3549453]: #38 main + 0x1bd2 [ip=0x5593237102a2] [sp=0x7ffcc4448dc0]
2020-11-02T15:04:23.656916+01:00 samba-11 smbd[3549453]: #39 __libc_start_main + 0xf3 [ip=0x7f44589d26a3] [sp=0x7ffcc4449180]
2020-11-02T15:04:23.657006+01:00 samba-11 smbd[3549453]: #40 _start + 0x2e [ip=0x55932371065e] [sp=0x7ffcc4449240]
2020-11-02T15:04:23.657038+01:00 samba-11 smbd[3549453]: coredump is handled by helper binary specified at /proc/sys/kernel/core_pattern
Comment 1 Jeremy Allison 2020-11-04 17:54:22 UTC 
What Samba are you running here ?

The call 'funlockfile()' doesn't exist in any Samba code.
Comment 2 Jeremy Allison 2020-11-04 17:58:54 UTC 
Are you using a custom VFS module ?
Comment 3 Ralph Böhme 2020-11-04 18:13:41 UTC 
(In reply to Jeremy Allison from comment #2)
THis is actually pretty common to have in a SBT. I guess it's coming from glibc or something like that. :)
Comment 4 Jeremy Allison 2020-11-04 18:16:24 UTC 
Oh, it's a pthread primitive from glibc. Sorry for the noise.
Comment 5 Jeremy Allison 2020-11-04 18:19:27 UTC 
Might be coming from a delete_on_close on a directory when (in close.c):

        if ((close_type == NORMAL_CLOSE || close_type == SHUTDOWN_CLOSE) &&
                                delete_dir) {

rmdir_internals() gets called.
Comment 6 Aritz Brosa 2020-11-06 10:52:55 UTC 
We are using 4.12.7.
Comment 7 Ralph Böhme 2020-11-06 11:13:12 UTC 
Can you install the Samba debug package so we get a SBT with more usable infos?
Comment 8 Aritz Brosa 2020-11-06 13:59:22 UTC 
Is installing the package enough, or should I also set the log level higher than 2 (our current value), or even raise the winbind log level?
It must be say that the issue only happened with a considerable load in terms of users accessing the service, so we may need some time to emulate the same situation in a test environment.
Comment 9 Ralph Böhme 2020-11-06 14:27:34 UTC 
(In reply to Aritz Brosa from comment #8)
Installing the package is enough.
Comment 10 Aritz Brosa 2020-11-09 11:13:36 UTC 
We have tried to analyze the issue with core dumps we have from the server's ABRT, and it seems that fsp->aio_requests[0] is freed before applying TALLOC_FREE, so that's the reason of the segmentation fault: [1]

We have available the full core dump, if that will make the investigation easier.

[1]
(gdb) up
#8  0x00007f28b87def7a in assert_no_pending_aio (close_type=SHUTDOWN_CLOSE, fsp=<optimized out>, fsp=<optimized out>) at ../../source3/smbd/close.c:669
669                TALLOC_FREE(fsp->aio_requests[0]);
(gdb) p fsp->aio_requests
value has been optimized out
(gdb) p fsp
$4 = <optimized out>
(gdb) up
#9  0x00007f28b87dfac0 in close_directory (close_type=SHUTDOWN_CLOSE, fsp=0x556e384dade0, req=0x0) at ../../source3/smbd/close.c:1140
1140        assert_no_pending_aio(fsp, close_type);
(gdb) p fsp
$5 = (files_struct *) 0x556e384dade0
(gdb) p *fsp
$6 = {next = 0x556e384db310, prev = 0x556e384db310, fnum = 3920950551, op = 0x556e384b50c0, conn = 0x556e38478520, fh = 0x556e384ce2c0,
  num_smb_operations = 0, file_id = {devid = 8215405831492424305, inode = 32206246, extid = 0}, initial_allocation_size = 0, file_pid = 65279,
  vuid = 879232126, open_time = {tv_sec = 1603814990, tv_usec = 31649}, access_mask = 1048705, kernel_share_modes_taken = false,
  update_write_time_triggered = false, update_write_time_event = 0x0, update_write_time_on_close = false, close_write_time = {tv_sec = 0,
    tv_nsec = 1073741822}, write_time_forced = false, oplock_type = 0, leases_db_seqnum = 0, lease_type = 0, lease = 0x0, sent_oplock_break = 0,
  oplock_timeout = 0x0, last_lock_failure = {context = {smblctx = 0, tid = 0, pid = {pid = 0, task_id = 0, vnn = 0, unique_id = 0}}, start = 0, size = 0,
    fnum = 0, lock_type = READ_LOCK, lock_flav = WINDOWS_LOCK}, current_lock_count = 0, can_lock = false, can_read = false, can_write = false,
  modified = false, is_directory = true, aio_write_behind = false, initial_delete_on_close = false, delete_on_close = false, posix_flags = 0,
  is_sparse = false, backup_intent = false, use_ofd_locks = true, fsp_name = 0x556e384c9f90, name_hash = 712496592, mid = 4, vfs_extension = 0x0,
  fake_file_handle = 0x0, notify = 0x0, base_fsp = 0x0, share_mode_flags_seqnum = 0, share_mode_flags = 0, brlock_seqnum = 0, brlock_rec = 0x0,
  dptr = 0x556e384cad60, print_file = 0x0, num_aio_requests = 0, aio_requests = 0x0, closing = false, blocked_smb1_lock_reqs = 0x0, lock_failure_seen = false,
  lock_failure_offset = 0, deferred_close = 0x0}
(gdb) p fsp->aio_requests
$7 = (struct tevent_req **) 0x0
Comment 11 Ralph Böhme 2020-11-09 11:20:08 UTC 
Oh, this looks like a duplicate of bug 14515 which has just been fixed.

The fix will ship with the next upcoming 4.12 and 4.13 releases and are also available as git-am patch files on the bugreport.

*** This bug has been marked as a duplicate of bug 14515 ***