Segfault freeing cursor after request ends due to max_execution_time

XMLWordPrintableJSON

    • Type: Bug
    • Resolution: Cannot Reproduce
    • Priority: Major - P3
    • None
    • Affects Version/s: 1.4.1
    • Component/s: None
    • None
    • Environment:
      MongoDB 3.4.10
      PHP 7.2.3
    • None
    • None
    • None
    • None
    • None
    • None
    • None

      While investigating mongodb/mongo-php-library#343 and attempting to use max_execution_timeout to trigger an "Invalid response_to for query" error I discovered a fairly reproducible segfault.

      I had a standalone mongod instance running (e.g. mongod --dbpath /tmp/db). The following script was served with php -S localhost:8080 and repeatedly hit with curl localhost:8080:

      <?php

ini_set('max_execution_time', 1);

function ublock($usec)
{
    $start = getrusage()['ru_utime.tv_usec'];
    while (getrusage()['ru_utime.tv_usec'] < $start + $usec);
}

MongoDB\Driver\Monitoring\addSubscriber(new class implements MongoDB\Driver\Monitoring\CommandSubscriber {
    public function commandStarted(MongoDB\Driver\Monitoring\CommandStartedEvent $event)
    {
        ublock(100000);
        echo '.';
    }

    public function commandSucceeded(MongoDB\Driver\Monitoring\CommandSucceededEvent $event)
    {
        ublock(100000);
        echo '#';
    }

    public function commandFailed(MongoDB\Driver\Monitoring\CommandFailedEvent $event)
    {
        ublock(100000);
        echo '!';
    }
});

$manager = new MongoDB\Driver\Manager('mongodb://localhost:27017/');
$query = new MongoDB\Driver\Query([], ['batchSize' => 2]);
while (1) $manager->executeQuery('test.test', $query)->toArray();

      My ublock() function above is similar to usleep(), but it spins PHP instead of issuing a system call to sleep so that its time counts against max_execution_time().

      After a series of initial requests reporting "Maximum execution time of 1 second exceeded" we eventually encounter a segfault with the following backtrace:

      (gdb) bt full
#0  0x00007f389121d428 in __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:54
        resultvar = 0
        pid = 10008
        selftid = 10008
#1  0x00007f389121f02a in __GI_abort () at abort.c:89
        save_stage = 2
        act = {__sigaction_handler = {sa_handler = 0x2d30303039353932, sa_sigaction = 0x2d30303039353932}, sa_mask = {__val = {3835151779020105271, 3276212736508309601, 3474581195552989296, 
              3544396919740575792, 3545235847113814304, 2314885530818453536, 2314885530818453536, 7091318037929795616, 3257288213055174703, 7955377262162766188, 8315178054010548085, 
              3689061837815835759, 4049692876520518446, 3472328506765554233, 4121419522540713773, 8606977229197435701}}, sa_flags = 807432237, sa_restorer = 0x4c}
        sigs = {__val = {32, 0 <repeats 15 times>}}
#2  0x00007f389125f7ea in __libc_message (do_abort=do_abort@entry=2, fmt=fmt@entry=0x7f3891378ed8 "*** Error in `%s': %s: 0x%s ***\n") at ../sysdeps/posix/libc_fatal.c:175
        ap = <error reading variable ap (Attempt to dereference a generic pointer.)>
        fd = 6
        on_2 = <optimized out>
        list = <optimized out>
        nlist = <optimized out>
        cp = <optimized out>
        written = <optimized out>
#3  0x00007f389126837a in malloc_printerr (ar_ptr=<optimized out>, ptr=<optimized out>, str=0x7f3891378fc8 "double free or corruption (top)", action=3) at malloc.c:5006
        buf = "000000000373c7e0"
        cp = <optimized out>
        ar_ptr = <optimized out>
        str = 0x7f3891378fc8 "double free or corruption (top)"
        action = 3
#4  _int_free (av=<optimized out>, p=<optimized out>, have_lock=0) at malloc.c:3867
        size = <optimized out>
        fb = <optimized out>
        nextchunk = <optimized out>
        nextsize = <optimized out>
        nextinuse = <optimized out>
        prevsize = <optimized out>
        bck = <optimized out>
        fwd = <optimized out>
        errstr = <optimized out>
        locked = <optimized out>
#5  0x00007f389126c53c in __GI___libc_free (mem=<optimized out>) at malloc.c:2968
        ar_ptr = <optimized out>
        p = <optimized out>
        hook = <optimized out>
#6  0x00007f388e2b4461 in php_phongo_free (mem=0x373c7e0) at /home/jmikola/workspace/mongodb/phpc/php_phongo.c:2498
No locals.
#7  0x00007f388e23e594 in bson_free (mem=0x373c7e0) at /home/jmikola/workspace/mongodb/phpc/src/libbson/src/bson/bson-memory.c:218
No locals.
#8  0x00007f388e22c1ce in bson_destroy (bson=0x373aab0) at /home/jmikola/workspace/mongodb/phpc/src/libbson/src/bson/bson.c:2285
        __func__ = "bson_destroy"
#9  0x00007f388e270a07 in _mongoc_cursor_cursorid_destroy (cursor=0x373acb0) at /home/jmikola/workspace/mongodb/phpc/src/libmongoc/src/mongoc/mongoc-cursor-cursorid.c:58
        cid = 0x373aab0
        __func__ = "_mongoc_cursor_cursorid_destroy"
#10 0x00007f388e26aa9c in mongoc_cursor_destroy (cursor=0x373acb0) at /home/jmikola/workspace/mongodb/phpc/src/libmongoc/src/mongoc/mongoc-cursor.c:520
        __func__ = "mongoc_cursor_destroy"
#11 0x00007f388e2cab6c in php_phongo_cursor_free_object (object=0x7f388e8020b8) at /home/jmikola/workspace/mongodb/phpc/src/MongoDB/Cursor.c:372
        intern = 0x7f388e802000
#12 0x0000000000a0ccde in zend_objects_store_free_object_storage (objects=0x15d1cf8 <executor_globals+824>, fast_shutdown=0 '\000')
    at /tmp/build_php-7.2.3.wuE/php-7.2.3/Zend/zend_objects_API.c:120
        obj_ptr = 0x7f388e861030
        end = 0x7f388e861008
        obj = 0x7f388e8020b8
#13 0x000000000099cdad in shutdown_executor () at /tmp/build_php-7.2.3.wuE/php-7.2.3/Zend/zend_execute_API.c:265
        key = 0x371aab0
        zv = 0x3652ff0
        fast_shutdown = 0 '\000'
#14 0x00000000009b850e in zend_deactivate () at /tmp/build_php-7.2.3.wuE/php-7.2.3/Zend/zend.c:1036
No locals.
#15 0x000000000091c372 in php_request_shutdown (dummy=0x0) at /tmp/build_php-7.2.3.wuE/php-7.2.3/main/main.c:1904
        report_memleaks = 1 '\001'
#16 0x0000000000ab6381 in php_cli_server_request_shutdown (server=0x15cd460 <server>, client=0x37311e0) at /tmp/build_php-7.2.3.wuE/php-7.2.3/sapi/cli/php_cli_server.c:2085
No locals.
#17 0x0000000000ab6787 in php_cli_server_dispatch (server=0x15cd460 <server>, client=0x37311e0) at /tmp/build_php-7.2.3.wuE/php-7.2.3/sapi/cli/php_cli_server.c:2166
        is_static_file = 0
#18 0x0000000000ab6ff0 in php_cli_server_recv_event_read_request (server=0x15cd460 <server>, client=0x37311e0) at /tmp/build_php-7.2.3.wuE/php-7.2.3/sapi/cli/php_cli_server.c:2377
        errstr = 0x0
        status = 1
#19 0x0000000000ab7362 in php_cli_server_do_event_for_each_fd_callback (_params=0x7ffd49285900, fd=3, event=1) at /tmp/build_php-7.2.3.wuE/php-7.2.3/sapi/cli/php_cli_server.c:2455
        client = 0x37311e0
        client_sock = 4
        socklen = 16
        sa = 0x3731410
        params = 0x7ffd49285900
        server = 0x15cd460 <server>
#20 0x0000000000ab309b in php_cli_server_poller_iter_on_active (poller=0x15cd468 <server+8>, opaque=0x7ffd49285900, callback=0xab717f <php_cli_server_do_event_for_each_fd_callback>)
    at /tmp/build_php-7.2.3.wuE/php-7.2.3/sapi/cli/php_cli_server.c:846
        retval = 0
        fd = 3
        max_fd = 3
#21 0x0000000000ab7442 in php_cli_server_do_event_for_each_fd (server=0x15cd460 <server>, rhandler=0xab6ea2 <php_cli_server_recv_event_read_request>, 
    whandler=0xab702b <php_cli_server_send_event>) at /tmp/build_php-7.2.3.wuE/php-7.2.3/sapi/cli/php_cli_server.c:2478
        params = {server = 0x15cd460 <server>, rhandler = 0xab6ea2 <php_cli_server_recv_event_read_request>, whandler = 0xab702b <php_cli_server_send_event>}
#22 0x0000000000ab74ca in php_cli_server_do_event_loop (server=0x15cd460 <server>) at /tmp/build_php-7.2.3.wuE/php-7.2.3/sapi/cli/php_cli_server.c:2488
        tv = {tv_sec = 0, tv_usec = 567061}
        n = 1
        retval = 0
#23 0x0000000000ab7891 in do_cli_server (argc=3, argv=0x359c540) at /tmp/build_php-7.2.3.wuE/php-7.2.3/sapi/cli/php_cli_server.c:2610
        php_optarg = 0x359c5b0 "localhost:8080"
        php_optind = 3
        c = -1
        server_bind_address = 0x359c5b0 "localhost:8080"
        document_root = 0x7ffd49285aa0 "/home/jmikola/workspace/mongodb/phplib"
        router = 0x0
        document_root_buf = "/home/jmikola/workspace/mongodb/phplib\000\000 `a\003\003\000\000\000\003", '\000' <repeats 143 times>, "@`(I\375\177\000\000"...
#24 0x0000000000aadc78 in main (argc=3, argv=0x359c540) at /tmp/build_php-7.2.3.wuE/php-7.2.3/sapi/cli/php_cli.c:1407
        __orig_bailout = 0x0
        __bailout = {{__jmpbuf = {0, -1569833063077060401, 4378704, 140725830839520, 0, 0, -1569833063269998385, 1570707473818247375}, __mask_was_saved = 0, __saved_mask = {__val = {0, 0, 0, 
                0, 0, 0, 18374686479671623680, 0, 0, 1, 11240061, 0, 0, 11239984, 4378704, 140725830839520}}}}
        c = -1
        exit_status = 0
        module_started = 1
        sapi_started = 1
        php_optarg = 0x359c5b0 "localhost:8080"
        php_optind = 3
        use_extended_info = 0
        ini_path_override = 0x0
        ini_entries = 0x0
        ini_entries_len = 0
        ini_ignore = 0
        sapi_module = 0x15b6200 <cli_server_sapi_module>

      Note that when running php -S localhost:8080 with USE_ZEND_ALLOC=0, we still see a segfault although the message "double free or corruption (top)" is slightly changed (IIRC, it reports "(!link)" as a suffix).

            Assignee:
            Jeremy Mikola
            Reporter:
            Jeremy Mikola
            Votes:
            0 Vote for this issue
            Watchers:
            2 Start watching this issue

              Created:
              Updated:
              Resolved: