Bug 13002 - smbd abort writing from macOS 10.12.3 with strict sync and vfs_aio_linux
Summary: smbd abort writing from macOS 10.12.3 with strict sync and vfs_aio_linux
Status: RESOLVED INVALID
Alias: None
Product: Samba 4.1 and newer
Classification: Unclassified
Component: File services (show other bugs)
Version: 4.7.0rc5
Hardware: All All
: P5 normal (vote)
Target Milestone: ---
Assignee: Samba QA Contact
QA Contact: Samba QA Contact
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2017-08-30 23:27 UTC by Justin Maggard
Modified: 2017-08-31 03:39 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 Justin Maggard 2017-08-30 23:27:23 UTC 
I'm consistently getting an abort() from smbd when writing a file from a macOS Sierra (10.12.3) client.  The issue seems to disappear if I disable either "strict sync" or the aio_linux vfs module.  It also works fine if I use aio_pthread instead of aio_linux.

Kernel: 4.4.84
Platform: x86_64
C library: Debian GLIBC 2.19-18+deb8u10
Compiler: gcc version 4.9.2 (Debian 4.9.2-10)

Backtrace:
(gdb) bt full
#0  0x00007fe1b15b7b3c in __libc_waitpid (pid=8826, stat_loc=stat_loc@entry=0x7ffd0ebdf950, options=options@entry=0) at ../sysdeps/unix/sysv/linux/waitpid.c:31
        resultvar = 18446744073709551104
        oldtype = -1316334368
#1  0x00007fe1b153f12b in do_system (line=<optimized out>) at ../sysdeps/posix/system.c:148
        __result = <optimized out>
        _buffer = {__routine = 0x7fe1b153f3d0 <cancel_handler>, __arg = 0x7ffd0ebdf92c, __canceltype = 0, __prev = 0x0}
        _avail = 1
        status = 247331200
        save = <optimized out>
        pid = 8826
        sa = {__sigaction_handler = {sa_handler = 0x1, sa_sigaction = 0x1}, sa_mask = {__val = {65536, 0 <repeats 15 times>}}, sa_flags = 0, sa_restorer = 0x55ffea8ec1d0}
        omask = 
            {__val = {6304, 0, 140607319200576, 140607393155560, 140724850784728, 140607346160040, 244835068409, 0, 140724850784928, 140607375769937, 140607369410468, 140607346160040, 72152151670757845, 206158430224, 140724850784944, 140607391010944}}
#2  0x00007fe1b2e829a8 in smb_panic_s3 (why=0x7fe1b535a865 "internal error") at ../source3/lib/util.c:817
        cmd = 0x55ffea8ec1d0 "/bin/sleep 999999999"
        result = 32765
        __FUNCTION__ = "smb_panic_s3"
#3  0x00007fe1b5311b62 in smb_panic (why=0x7fe1b535a865 "internal error") at ../lib/util/fault.c:166
#4  0x00007fe1b531183a in fault_report (sig=6) at ../lib/util/fault.c:83
        counter = 1
        __FUNCTION__ = "fault_report"
#5  0x00007fe1b531184f in sig_fault (sig=6) at ../lib/util/fault.c:94
#6  0x00007fe1b5778890 in <signal handler called> () at /lib/x86_64-linux-gnu/libpthread.so.0
#7  0x00007fe1b1533067 in __GI_raise (sig=sig@entry=6) at ../nptl/sysdeps/unix/sysv/linux/raise.c:56
        resultvar = 0
        pid = 8823
        selftid = 8823
#8  0x00007fe1b1534448 in __GI_abort () at abort.c:89
        save_stage = 2
        act = 
          {__sigaction_handler = {sa_handler = 0x55ffea8d36d0, sa_sigaction = 0x55ffea8d36d0}, sa_mask = {__val = {140607380117523, 1504134469, 226492, 94557640144592, 94557639964272, 140724850787088, 140607380117142, 140607381435896, 140607381435856, 3727937460, 2151418625344, 0, 94557640144592, 24, 94557640144592, 4295426048}}, sa_flags = 247333672, sa_restorer = 0x7ffd0ebe0324}
        sigs = {__val = {32, 0 <repeats 15 times>}}
#9  0x00007fe1b42d9195 in tevent_req_is_nterror (req=0x55ffea8d3a70, status=0x7ffd0ebe0350) at ../lib/util/tevent_ntstatus.c:66
        state = TEVENT_REQ_USER_ERROR
        err = 22
#10 0x00007fe1b4f33cec in smbd_smb2_flush_recv (req=0x55ffea8d3a70) at ../source3/smbd/smb2_flush.c:211
        status = {v = 3934890864}
#11 0x00007fe1b4f33768 in smbd_smb2_request_flush_done (subreq=0x55ffea8d3a70) at ../source3/smbd/smb2_flush.c:75
        req = 0x55ffea8d36d0
        outbody = {data = 0x7ffd0ebe0410 "p\253\211\352\003", length = 94557640176032}
        status = {v = 247333840}
        error = {v = 0}
#12 0x00007fe1b44e2285 in _tevent_req_notify_callback (req=0x55ffea8d3a70, location=0x7fe1b5064310 "../source3/smbd/smb2_flush.c:201") at ../lib/tevent/tevent_req.c:125
#13 0x00007fe1b44e2358 in tevent_req_finish (req=0x55ffea8d3a70, state=TEVENT_REQ_USER_ERROR, location=0x7fe1b5064310 "../source3/smbd/smb2_flush.c:201") at ../lib/tevent/tevent_req.c:162
#14 0x00007fe1b44e23c4 in _tevent_req_error (req=0x55ffea8d3a70, error=22, location=0x7fe1b5064310 "../source3/smbd/smb2_flush.c:201") at ../lib/tevent/tevent_req.c:180
#15 0x00007fe1b4f33cb6 in smbd_smb2_flush_done (subreq=0x0) at ../source3/smbd/smb2_flush.c:201
        req = 0x55ffea8d3a70
        ret = -1
        vfs_aio_state = {error = 22, duration = 94557640153792}
#16 0x00007fe1b44e2285 in _tevent_req_notify_callback (req=0x55ffea8db1a0, location=0x7fe1b5052ce4 "../source3/smbd/vfs.c:1921") at ../lib/tevent/tevent_req.c:125
#17 0x00007fe1b44e2358 in tevent_req_finish (req=0x55ffea8db1a0, state=TEVENT_REQ_USER_ERROR, location=0x7fe1b5052ce4 "../source3/smbd/vfs.c:1921") at ../lib/tevent/tevent_req.c:162
#18 0x00007fe1b44e23c4 in _tevent_req_error (req=0x55ffea8db1a0, error=22, location=0x7fe1b5052ce4 "../source3/smbd/vfs.c:1921") at ../lib/tevent/tevent_req.c:180
#19 0x00007fe1b4eedc00 in smb_vfs_call_fsync_done (subreq=0x0) at ../source3/smbd/vfs.c:1921
        req = 0x55ffea8db1a0
        state = 0x55ffea8db330
#20 0x00007fe1b44e2285 in _tevent_req_notify_callback (req=0x55ffea8d5ac0, location=0x7fe1a0e3e230 "../source3/modules/vfs_aio_linux.c:247") at ../lib/tevent/tevent_req.c:125
#21 0x00007fe1b44e2358 in tevent_req_finish (req=0x55ffea8d5ac0, state=TEVENT_REQ_USER_ERROR, location=0x7fe1a0e3e230 "../source3/modules/vfs_aio_linux.c:247") at ../lib/tevent/tevent_req.c:162
#22 0x00007fe1b44e247d in tevent_req_trigger (ev=0x55ffea8a7670, im=0x55ffea8d5ba0, private_data=0x55ffea8d5ac0) at ../lib/tevent/tevent_req.c:219
        req = 0x55ffea8d5ac0
#23 0x00007fe1b44e1677 in tevent_common_loop_immediate (ev=0x55ffea8a7670) at ../lib/tevent/tevent_immediate.c:135
        im = 0x55ffea8d5ba0
        handler = 0x7fe1b44e242e <tevent_req_trigger>
        private_data = 0x55ffea8d5ac0
#24 0x00007fe1b44ea95f in epoll_event_loop_once (ev=0x55ffea8a7670, location=0x7fe1b5059f30 "../source3/smbd/process.c:4126") at ../lib/tevent/tevent_epoll.c:911
        epoll_ev = 0x55ffea8ae030
        tval = {tv_sec = 94557639912304, tv_usec = 140724850787984}
        panic_triggered = false
#25 0x00007fe1b44e7702 in std_event_loop_once (ev=0x55ffea8a7670, location=0x7fe1b5059f30 "../source3/smbd/process.c:4126") at ../lib/tevent/tevent_standard.c:114
        glue_ptr = 0x55ffea8a9020
        glue = 0x55ffea8a9020
        ret = 32737
#26 0x00007fe1b44e0515 in _tevent_loop_once (ev=0x55ffea8a7670, location=0x7fe1b5059f30 "../source3/smbd/process.c:4126") at ../lib/tevent/tevent.c:726
        ret = 0
        nesting_stack_ptr = 0x0
#27 0x00007fe1b44e0825 in tevent_common_loop_wait (ev=0x55ffea8a7670, location=0x7fe1b5059f30 "../source3/smbd/process.c:4126") at ../lib/tevent/tevent.c:849
        ret = 0
#28 0x00007fe1b44e77a4 in std_event_loop_wait (ev=0x55ffea8a7670, location=0x7fe1b5059f30 "../source3/smbd/process.c:4126") at ../lib/tevent/tevent_standard.c:145
        glue_ptr = 0x55ffea8a9020
        glue = 0x55ffea8a9020
        ret = 22015
#29 0x00007fe1b44e08c8 in _tevent_loop_wait (ev=0x55ffea8a7670, location=0x7fe1b5059f30 "../source3/smbd/process.c:4126") at ../lib/tevent/tevent.c:868
#30 0x00007fe1b4f0943f in smbd_process (ev_ctx=0x55ffea8a7670, msg_ctx=0x55ffea8a9320, sock_fd=36, interactive=false) at ../source3/smbd/process.c:4126
        trace_state = {ev = 0x55ffea8a7670, frame = 0x55ffea8ec170}
        client = 0x55ffea8c0100
        sconn = 0x55ffea8af070
        xconn = 0x55ffea8afd40
        locaddr = 0x55ffea8c0d00 "\300\060\214\352\377U"
        remaddr = 0x55ffea8c0d80 "10.20.0.146"
        ret = 22015
        status = {v = 0}
        tv = {tv_sec = 1504134452, tv_usec = 401917}
        now = 131486080524019170
        chroot_dir = 0x55ffea8ae3f0 "s3fs"
        rc = -360017120
        __func__ = "smbd_process"
        __FUNCTION__ = "smbd_process"
#31 0x000055ffea1d8c0d in smbd_accept_connection (ev=0x55ffea8a7670, fde=0x55ffea8c1ca0, flags=1, private_data=0x55ffea8c1ba0) at ../source3/smbd/server.c:1026
        status = {v = 0}
        s = 0x0
        msg_ctx = 0x55ffea8a9320
        addr = 
          {ss_family = 2, __ss_align = 0, __ss_padding = "\360\273N\264\341\177\000\000pv\212\352\377U\000\000\340/\214\352\377U\000\000 6\212\261\341\177\000\000`\000\000\000\000\000\000\000 \t\276\016\375\177\000\000SÜ¿\016\375\177\000\000\063\231\035\352\377U\000\000 \v\276\016\375\177\000\000\200\t\276\016\001\000\000\000@\t\276\016\375\177\000\000 \v\276\016\375\177\000\000@\t\276\016\375\177\000\000\363\fN\264\341\177\000"}
        in_addrlen = 16
        fd = 36
        pid = 0
        __FUNCTION__ = "smbd_accept_connection"
#32 0x00007fe1b44ea3c3 in epoll_event_loop (epoll_ev=0x55ffea8ae660, tvalp=0x7ffd0ebe09d0) at ../lib/tevent/tevent_epoll.c:728
        fde = 0x55ffea8c1ca0
        flags = 1
        mpx_fde = 0x0
        ret = 1
        i = 0
        events = {{events = 1, data = {ptr = 0x55ffea8c1ca0, fd = -359916384, u32 = 3935050912, u64 = 94557640072352}}}
        timeout = 147
        wait_errno = 0
#33 0x00007fe1b44ea9f9 in epoll_event_loop_once (ev=0x55ffea8a7670, location=0x55ffea1dfe54 "../source3/smbd/server.c:1393") at ../lib/tevent/tevent_epoll.c:930
        epoll_ev = 0x55ffea8ae660
        tval = {tv_sec = 0, tv_usec = 146977}
        panic_triggered = false
#34 0x00007fe1b44e7702 in std_event_loop_once (ev=0x55ffea8a7670, location=0x55ffea1dfe54 "../source3/smbd/server.c:1393") at ../lib/tevent/tevent_standard.c:114
        glue_ptr = 0x55ffea8a9020
        glue = 0x55ffea8a9020
        ret = 32737
#35 0x00007fe1b44e0515 in _tevent_loop_once (ev=0x55ffea8a7670, location=0x55ffea1dfe54 "../source3/smbd/server.c:1393") at ../lib/tevent/tevent.c:726
        ret = 0
        nesting_stack_ptr = 0x0
#36 0x00007fe1b44e0825 in tevent_common_loop_wait (ev=0x55ffea8a7670, location=0x55ffea1dfe54 "../source3/smbd/server.c:1393") at ../lib/tevent/tevent.c:849
---Type <return> to continue, or q <return> to quit---
        ret = 0
#37 0x00007fe1b44e77a4 in std_event_loop_wait (ev=0x55ffea8a7670, location=0x55ffea1dfe54 "../source3/smbd/server.c:1393") at ../lib/tevent/tevent_standard.c:145
        glue_ptr = 0x55ffea8a9020
        glue = 0x55ffea8a9020
        ret = 32765
#38 0x00007fe1b44e08c8 in _tevent_loop_wait (ev=0x55ffea8a7670, location=0x55ffea1dfe54 "../source3/smbd/server.c:1393") at ../lib/tevent/tevent.c:868
#39 0x000055ffea1d99d5 in smbd_parent_loop (ev_ctx=0x55ffea8a7670, parent=0x55ffea8af070) at ../source3/smbd/server.c:1393
        trace_state = {frame = 0x55ffea899040}
        ret = 0
        __FUNCTION__ = "smbd_parent_loop"
#40 0x000055ffea1dbbf3 in main (argc=1, argv=0x7ffd0ebe0fc8) at ../source3/smbd/server.c:2160
        is_daemon = true
        interactive = false
        Fork = true
        no_process_group = false
        log_stdout = false
        ports = 0x0
        profile_level = 0x0
        opt = -1
        pc = 0x55ffea898a70
        print_build_options = false
        main_server_id = {pid = 8816, task_id = 0, vnn = 4294967295, unique_id = 18038852320227628384}
        long_options = 
            {{longName = 0x0, shortName = 0 '\000', argInfo = 4, arg = 0x7fe1b1cca480 <poptHelpOptions>, val = 0, descrip = 0x55ffea1e020b "Help options:", argDescrip = 0x0}, {longName = 0x55ffea1e0219 "daemon", shortName = 68 'D', argInfo = 0, arg = 0x0, val = 1000, descrip = 0x55ffea1e0220 "Become a daemon (default)", argDescrip = 0x0}, {longName = 0x55ffea1e023a "interactive", shortName = 105 'i', argInfo = 0, arg = 0x0, val = 1001, descrip = 0x55ffea1e0248 "Run interactive (not a daemon)", argDescrip = 0x0}, {longName = 0x55ffea1e0267 "foreground", shortName = 70 'F', argInfo = 0, arg = 0x0, val = 1002, descrip = 0x55ffea1e0278 "Run daemon in foreground (for daemontools, etc.)", argDescrip = 0x0}, {longName = 0x55ffea1e02a9 "no-process-group", shortName = 0 '\000', argInfo = 0, arg = 0x0, val = 1003, descrip = 0x55ffea1e02c0 "Don't create a new process group", argDescrip = 0x0}, {longName = 0x55ffea1e02e1 "log-stdout", shortName = 83 'S', argInfo = 0, arg = 0x0, val = 1004, descrip = 0x55ffea1e02ec "Log to stdout", argDescrip = 0x0}, {longName = 0x55ffea1e02fa "build-options", shortName = 98 'b', argInfo = 0, arg = 0x0, val = 98, descrip = 0x55ffea1e0308 "Print build options", argDescrip = 0x0}, {longName = 0x55ffea1e031c "port", shortName = 112 'p', argInfo = 1, arg = 0x7ffd0ebe0b90, val = 0, descrip = 0x55ffea1e0321 "Listen on the specified ports", argDescrip = 0x0}, {longName = 0x55ffea1e033f "profiling-level", shortName = 80 'P', argInfo = 1, arg = 0x7ffd0ebe0b98, val = 0, descrip = 0x55ffea1e034f "Set profiling level", argDescrip = 0x55ffea1e0363 "PROFILE_LEVEL"}, {longName = 0x0, shortName = 0 '\000', argInfo = 4, arg = 0x7fe1b5768180 <popt_common_samba>, val = 0, descrip = 0x55ffea1e0371 "Common samba options:", argDescrip = 0x0}, {longName = 0x0, shortName = 0 '\000', argInfo = 0, arg = 0x0, val = 0, descrip = 0x0, argDescrip = 0x0}}
        parent = 0x55ffea8af070
        frame = 0x55ffea8963d0
        status = {v = 0}
        ev_ctx = 0x55ffea8a7670
        msg_ctx = 0x55ffea8a9320
        server_id = {pid = 8818, task_id = 0, vnn = 4294967295, unique_id = 3325470261833262687}
        se = 0x55ffea8aff80
        profiling_level = 0
        np_dir = 0x55ffea8b99b0 ""
        smbd_shim_fns = 
          {cancel_pending_lock_requests_by_fid = 0x7fe1b4ee6e01 <smbd_cancel_pending_lock_requests_by_fid>, send_stat_cache_delete_message = 0x7fe1b4ef10fd <smbd_send_stat_cache_delete_message>, change_to_root_user = 0x7fe1b4ed1138 <smbd_change_to_root_user>, become_authenticated_pipe_user = 0x7fe1b4ed11ee <smbd_become_authenticated_pipe_user>, unbecome_authenticated_pipe_user = 0x7fe1b4ed12e0 <smbd_unbecome_authenticated_pipe_user>, contend_level2_oplocks_begin = 0x7fe1b4f61d1b <smbd_contend_level2_oplocks_begin>, contend_level2_oplocks_end = 0x7fe1b4f61d8e <smbd_contend_level2_oplocks_end>, become_root = 0x7fe1b4ed1500 <smbd_become_root>, unbecome_root = 0x7fe1b4ed1528 <smbd_unbecome_root>, exit_server = 0x7fe1b4f564d4 <smbd_exit_server>, exit_server_cleanly = 0x7fe1b4f564f1 <smbd_exit_server_cleanly>}
        __FUNCTION__ = "main"
        __func__ = "main"
Comment 1 Jeremy Allison 2017-08-30 23:34:39 UTC 
Ah, sorry to waste your time Jason.

aio_linux vfs module is *unsupported* and does not work. It was an early experiment in trying to use native Linux kernel aio calls. After I wrote it I discovered these calls have to be page aligned (which ours are not).

That code should be deleted from the tree, I had no idea anyone was using it :-(.

You don't need aio_pthread to get asyncio anymore - it's built-in. You would only use it to get async create.

Sorry for the trouble.

Jeremy.
Comment 2 Jeremy Allison 2017-08-30 23:35:15 UTC 
Justin, sorry - brain wrote Jason as I was composing an email to another Jason at the time, sorry :-).