Mongodb: run mongoc_cleanup() only when connection is established…

[mitzkia]

with mongodb

Mongodb crashes after some reload in free() when there is no established connection

Reproduction:

• start syslog-ng with the following config:

@version: 3.12
@include 'scl.conf'

source s_file {file("/dev/stdin");};
destination d_mongodb {mongodb();};
log {source(s_file); destination(d_mongodb);};

• send some SIGHUP to syslog-ng
• syslog-ng will crashes after some SIGHUP

Backtrace (SIGABRT):

*** Error in `/home/micek/micek_work/git_projects/github_mitzkia/syslog-ng/install/sbin/syslog-ng': munmap_chunk(): invalid pointer: 0x00005555557b2250 ***
2017/11/17 20:23:24.0666: [20065]:    DEBUG:       mongoc: No transition entry to 4 for 1

Thread 1 "syslog-ng" received signal SIGABRT, Aborted.
__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.
(gdb) bt
#0  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:51
#1  0x00007ffff720cf5d in __GI_abort () at abort.c:90
#2  0x00007ffff725528d in __libc_message (action=action@entry=do_abort, fmt=fmt@entry=0x7ffff737c4e8 "*** Error in `%s': %s: 0x%s ***\n")
    at ../sysdeps/posix/libc_fatal.c:181
#3  0x00007ffff7263600 in malloc_printerr (ar_ptr=0x0, ptr=<optimized out>, str=0x7ffff737c800 "munmap_chunk(): invalid pointer", 
    action=<optimized out>) at malloc.c:5425
#4  munmap_chunk (p=<optimized out>) at malloc.c:2877
#5  __GI___libc_free (mem=<optimized out>) at malloc.c:3137
#6  0x00007ffff780bc84 in ?? () from /lib/x86_64-linux-gnu/libglib-2.0.so.0
#7  0x00007ffff780cbd8 in g_hash_table_remove_all () from /lib/x86_64-linux-gnu/libglib-2.0.so.0
#8  0x00007ffff780cc1e in g_hash_table_destroy () from /lib/x86_64-linux-gnu/libglib-2.0.so.0
#9  0x00007ffff7b194a7 in cfg_args_unref (self=0x555555784710) at ../lib/cfg-args.c:118
#10 0x00007ffff7b19806 in cfg_block_free_instance (s=0x5555557b2300) at ../lib/cfg-block.c:119
#11 0x00007ffff7b1995d in cfg_block_generator_free (self=0x5555557b2300) at ../lib/cfg-block-generator.c:51
#12 0x00007ffff7b1b2c5 in _generator_plugin_free (s=0x5555557b2340) at ../lib/cfg-lexer.c:681
#13 0x00007ffff7b39eb0 in _free_plugin (plugin=0x5555557b2340, user_data=0x0) at ../lib/plugin.c:590
#14 0x00007ffff781a11d in g_list_foreach () from /lib/x86_64-linux-gnu/libglib-2.0.so.0
#15 0x00007ffff7b39eda in plugin_free_plugins (context=0x5555557966a0) at ../lib/plugin.c:596
#16 0x00007ffff7b39f88 in plugin_context_deinit_instance (context=0x5555557966a0) at ../lib/plugin.c:618
#17 0x00007ffff7b18e2e in cfg_free (self=0x555555796690) at ../lib/cfg.c:578
#18 0x00007ffff7b33189 in main_loop_reload_config_apply (user_data=0x7ffff7dd3d00 <main_loop>) at ../lib/mainloop.c:232
#19 0x00007ffff7b3481f in _consume_action (action=0x5555557acae0, dummy=0x0) at ../lib/mainloop-worker.c:240
#20 0x00007ffff782e3fc in g_queue_foreach () from /lib/x86_64-linux-gnu/libglib-2.0.so.0
#21 0x00007ffff7b34850 in _invoke_sync_call_actions () at ../lib/mainloop-worker.c:247
#22 0x00007ffff7b348a2 in main_loop_worker_job_complete () at ../lib/mainloop-worker.c:296
#23 0x00007ffff7b34024 in main_loop_call_handler (user_data=0x0) at ../lib/mainloop-call.c:113
#24 0x00007ffff7b840a6 in __iv_event_run_pending_events (_st=0x5555557620e0) at ../../../../lib/ivykis/src/iv_event.c:56
#25 0x00007ffff7b841b7 in iv_event_run_pending_events () at ../../../../lib/ivykis/src/iv_event.c:88
#26 0x00007ffff7b8ac56 in iv_fd_epoll_timerfd_poll (st=0x5555557620e0, active=0x7fffffffdef0, abs=0x0)
    at ../../../../lib/ivykis/src/iv_fd_epoll.c:484
#27 0x00007ffff7b86d1a in iv_fd_poll_and_run (st=0x5555557620e0, abs=0x7ffff7dd4500 <stats_timer>)
    at ../../../../lib/ivykis/src/iv_fd.c:202
#28 0x00007ffff7b881a2 in iv_main () at ../../../../lib/ivykis/src/iv_main_posix.c:112
#29 0x00007ffff7b33c06 in main_loop_run (self=0x7ffff7dd3d00 <main_loop>) at ../lib/mainloop.c:561
#30 0x0000555555556178 in main (argc=1, argv=0x7fffffffe0b8) at ../syslog-ng/main.c:304

Backtrace (SIGSEGV):

#0  0x00007f36a7f995bd in iv_list_del_init (ilh=0x560b400ed121) at ../../../../lib/ivykis/src/include/iv_list.h:75
No locals.
#1  0x00007f36a7f99972 in iv_task_unregister (_t=0x560b400ed111) at ../../../../lib/ivykis/src/iv_task.c:86
        st = 0x7f369c0008c0
        t = 0x560b400ed111
#2  0x00007f36a7f42f3a in log_threaded_dest_driver_stop_watches (self=0x560b400ecec1) at ../lib/logthrdestdrv.c:81
No locals.
#3  0x00007f36a7f4340c in log_threaded_dest_driver_do_work (data=0x560b400ecec1) at ../lib/logthrdestdrv.c:228
        self = 0x560b400ecec1
        timeout_msec = 0
#4  0x00007f36a7f997cf in iv_run_tasks (st=0x7f369c0008c0) at ../../../../lib/ivykis/src/iv_task.c:48
        t = 0x560b400ed110
        tasks = {next = 0x7f36a83ebba0, prev = 0x7f36a83ebba0}
        epoch = 1
#5  0x00007f36a7f9d140 in iv_main () at ../../../../lib/ivykis/src/iv_main_posix.c:99
        _abs = {tv_sec = 139872727645200, tv_nsec = 94606319341248}
        abs = 0x7f36a83ebc10
        st = 0x7f369c0008c0
        run_timers = 1
#6  0x00007f36a7f436f4 in log_threaded_dest_driver_worker_thread_main (arg=0x560b400ecec0) at ../lib/logthrdestdrv.c:298
        self = 0x560b400ecec0
#7  0x00007f36a7f499a3 in _worker_thread_func (st=0x560b400d74c0) at ../lib/mainloop-worker.c:339
        p = 0x560b400d74c0
        __func__ = "_worker_thread_func"
#8  0x00007f36a7c5a645 in ?? () from /lib/x86_64-linux-gnu/libglib-2.0.so.0
No symbol table info available.
#9  0x00007f36a79d07fc in start_thread (arg=0x7f36a83ee700) at pthread_create.c:465
        pd = 0x7f36a83ee700
        now = <optimized out>
        unwind_buf = {cancel_jmp_buf = {{jmp_buf = {139872727656192, -3828499964287243820, 140720765454846, 140720765454847, 
                139872727656192, 16, 3797449195513719252, 3797414830043834836}, mask_was_saved = 0}}, priv = {pad = {0x0, 0x0, 0x0, 0x0}, 
            data = {prev = 0x0, cleanup = 0x0, canceltype = 0}}}
        not_first_call = <optimized out>
        pagesize_m1 = <optimized out>
        sp = <optimized out>
        freesize = <optimized out>
        __PRETTY_FUNCTION__ = "start_thread"
#10 0x00007f36a76fdb0f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
No locals.

Valgrind log:

• starter command: valgrind --run-libc-freeres=no --leak-check=full -v --tool=memcheck --track-origins=yes --keep-stacktraces=alloc-and-free --error-limit=no --num-callers=40 sbin/syslog-ng -Fedv -f syslog_ng_mongodb_double_free.conf

==20285== 84 errors in context 13 of 18:
==20285== Invalid read of size 8
==20285==    at 0x7A17D8D: mongoc_counter_streams_ingress_add (mongoc-counters.defs:49)
==20285==    by 0x7A18B04: mongoc_socket_recv (mongoc-socket.c:824)
==20285==    by 0x7A1B1DE: _mongoc_stream_socket_readv (mongoc-stream-socket.c:153)
==20285==    by 0x7A19E4C: mongoc_stream_readv (mongoc-stream.c:234)
==20285==    by 0x7A19FA0: mongoc_stream_read (mongoc-stream.c:278)
==20285==    by 0x7A2F17B: _mongoc_buffer_try_append_from_stream (mongoc-buffer.c:317)
==20285==    by 0x7A2E0BC: _mongoc_async_cmd_phase_recv_len (mongoc-async-cmd.c:306)
==20285==    by 0x7A2D5F4: mongoc_async_cmd_run (mongoc-async-cmd.c:103)
==20285==    by 0x7A2D426: mongoc_async_run (mongoc-async.c:143)
==20285==    by 0x7A1F50A: mongoc_topology_scanner_work (mongoc-topology-scanner.c:577)
==20285==    by 0x7A1BE91: _mongoc_topology_run_scanner (mongoc-topology.c:303)
==20285==    by 0x7A1BF02: _mongoc_topology_do_blocking_scan (mongoc-topology.c:329)
==20285==    by 0x7A1C166: mongoc_topology_select (mongoc-topology.c:430)
==20285==    by 0x79FFECB: mongoc_cluster_select_by_optype (mongoc-cluster.c:1610)
==20285==    by 0x7A08404: _mongoc_cursor_query (mongoc-cursor.c:610)
==20285==    by 0x7A08ED4: _mongoc_cursor_next (mongoc-cursor.c:948)
==20285==    by 0x7A08CC4: mongoc_cursor_next (mongoc-cursor.c:876)
==20285==    by 0x79FBC79: _mongoc_client_command_simple_with_hint (mongoc-client.c:1187)
==20285==    by 0x79FBAFE: mongoc_client_command_simple (mongoc-client.c:1161)
==20285==    by 0x79FC576: mongoc_client_get_server_status (mongoc-client.c:1387)
==20285==    by 0x79DCEFF: _connect (afmongodb.c:187)
==20285==    by 0x79DDBE3: _worker_thread_init (afmongodb.c:483)
==20285==    by 0x4E836EE: log_threaded_dest_driver_worker_thread_main (logthrdestdrv.c:296)
==20285==    by 0x4E899A2: _worker_thread_func (mainloop-worker.c:339)
==20285==    by 0x519C644: ??? (in /lib/x86_64-linux-gnu/libglib-2.0.so.0.5400.1)
==20285==    by 0x54457FB: start_thread (pthread_create.c:465)
==20285==    by 0x5771B0E: clone (clone.S:95)
==20285==  Address 0x70e7188 is 5,384 bytes inside a block of size 5,696 free'd
==20285==    at 0x4C30D3B: free (in /usr/lib/valgrind/vgpreload_memcheck-amd64-linux.so)
==20285==    by 0x79F3D26: bson_free (bson-memory.c:216)
==20285==    by 0x7A05FD6: _mongoc_counters_cleanup (mongoc-counters.c:132)
==20285==    by 0x7A0CF32: _mongoc_do_cleanup (mongoc-init.c:141)
==20285==    by 0x544E138: __pthread_once_slow (pthread_once.c:116)
==20285==    by 0x7A0CF4C: mongoc_cleanup (mongoc-init.c:150)
==20285==    by 0x79DDE44: _free (afmongodb.c:561)
==20285==    by 0x4E7D78D: _free (logpipe.c:85)
==20285==    by 0x4E7D816: log_pipe_unref (logpipe.c:97)
==20285==    by 0x4E72C66: log_expr_node_free (cfg-tree.c:267)
==20285==    by 0x4E72C28: log_expr_node_free (cfg-tree.c:264)
==20285==    by 0x4E72C28: log_expr_node_free (cfg-tree.c:264)
==20285==    by 0x5162C91: ??? (in /lib/x86_64-linux-gnu/libglib-2.0.so.0.5400.1)
==20285==    by 0x5163BD7: g_hash_table_remove_all (in /lib/x86_64-linux-gnu/libglib-2.0.so.0.5400.1)
==20285==    by 0x5163C1D: g_hash_table_destroy (in /lib/x86_64-linux-gnu/libglib-2.0.so.0.5400.1)
==20285==    by 0x4E7480E: cfg_tree_free_instance (cfg-tree.c:1174)
==20285==    by 0x4E6DE3F: cfg_free (cfg.c:579)
==20285==    by 0x4E88188: main_loop_reload_config_apply (mainloop.c:232)
==20285==    by 0x4E8981E: _consume_action (mainloop-worker.c:240)
==20285==    by 0x51853FB: g_queue_foreach (in /lib/x86_64-linux-gnu/libglib-2.0.so.0.5400.1)
==20285==    by 0x4E8984F: _invoke_sync_call_actions (mainloop-worker.c:247)
==20285==    by 0x4E898A1: main_loop_worker_job_complete (mainloop-worker.c:296)
==20285==    by 0x4E89023: main_loop_call_handler (mainloop-call.c:113)
==20285==    by 0x4ED90A5: __iv_event_run_pending_events (iv_event.c:56)
==20285==    by 0x4ED91B6: iv_event_run_pending_events (iv_event.c:88)
==20285==    by 0x4EDFC55: iv_fd_epoll_timerfd_poll (iv_fd_epoll.c:484)
==20285==    by 0x4EDBD19: iv_fd_poll_and_run (iv_fd.c:202)
==20285==    by 0x4EDD1A1: iv_main (iv_main_posix.c:112)
==20285==    by 0x4E88C05: main_loop_run (mainloop.c:561)
==20285==    by 0x10A177: main (main.c:304)
==20285==  Block was alloc'd at
==20285==    at 0x4C31B25: calloc (in /usr/lib/valgrind/vgpreload_memcheck-amd64-linux.so)
==20285==    by 0x79F3C55: bson_malloc0 (bson-memory.c:103)
==20285==    by 0x7A05FFC: mongoc_counters_alloc (mongoc-counters.c:204)
==20285==    by 0x7A0624E: _mongoc_counters_init (mongoc-counters.c:286)
==20285==    by 0x7A0CF07: _mongoc_do_init (mongoc-init.c:94)
==20285==    by 0x544E138: __pthread_once_slow (pthread_once.c:116)
==20285==    by 0x7A0CF21: mongoc_init (mongoc-init.c:119)
==20285==    by 0x7A0CF58: _mongoc_init_ctor (mongoc-init.c:162)
==20285==    by 0x4010A69: call_init.part.0 (dl-init.c:72)
==20285==    by 0x4010B7A: call_init (dl-init.c:30)
==20285==    by 0x4010B7A: _dl_init (dl-init.c:120)
==20285==    by 0x4015B85: dl_open_worker (dl-open.c:575)
==20285==    by 0x57B5D63: _dl_catch_error (dl-error-skeleton.c:198)
==20285==    by 0x40150D8: _dl_open (dl-open.c:660)
==20285==    by 0x6B6CFF5: dlopen_doit (dlopen.c:66)
==20285==    by 0x57B5D63: _dl_catch_error (dl-error-skeleton.c:198)
==20285==    by 0x6B6D758: _dlerror_run (dlerror.c:163)
==20285==    by 0x6B6D091: dlopen@@GLIBC_2.2.5 (dlopen.c:87)
==20285==    by 0x5C466D1: g_module_open (in /usr/lib/x86_64-linux-gnu/libgmodule-2.0.so.0.5400.1)
==20285==    by 0x4E8E187: plugin_dlopen_module_as_filename (plugin.c:250)
==20285==    by 0x4E8E413: plugin_dlopen_module_on_path (plugin.c:332)
==20285==    by 0x4E8E4BF: plugin_load_module (plugin.c:359)
==20285==    by 0x4E8DF7A: plugin_find (plugin.c:196)
==20285==    by 0x4E6CF48: cfg_find_plugin (cfg.c:204)
==20285==    by 0x4EA3320: main_parse (cfg-grammar.y:685)
==20285==    by 0x4E723F5: cfg_parser_parse (cfg-parser.c:302)
==20285==    by 0x4E6DA50: cfg_run_parser (cfg.c:475)
==20285==    by 0x4E6DC2C: cfg_read_config (cfg.c:534)
==20285==    by 0x4E88A6A: main_loop_read_and_init_config (mainloop.c:505)
==20285==    by 0x10A105: main (main.c:275)

Signed-off-by: Andras Mitzki andras.mitzki@balabit.com

[kira-syslogng]

Build SUCCESS, the tests were executed on test branch: master and test suite: functions

[algernon]

Nice catch, and a straightforward fix! (Not sure why the Clang build on Travis is failing, will attempt a retry)

[algernon]

There we go. Restarting the clang job did the trick.

[mitzkia]

Thank you.