Boost log mutex lock failure

[anonymous]

I'm using add_console_log(), passing it std::clog. When I build in release with optimizations, everything works fine. When building in debug without optimizations though, when my program exits there's a core dump as a result of the assertion on destruction of the mutex lock failing (pthread_mutex_destroy() is returning 16, which iic is EBUSY). I started digging through add_console_log(), and if I switch to an asynchronous sink there's no issues (I suppose it doesn't need the mutex lock anymore and that's why) My compiler's 4.8.3 on FC 20. I've tried with 1.55 and 1.56.

The code that results in the core dump:

typedef boost::log::sources::severity_logger<severity_level> lgr_type;
BOOST_LOG_GLOBAL_LOGGER(logger, lgr_type);
...
BOOST_LOG_GLOBAL_LOGGER_INIT(logger, src::severity_logger_mt)
{
  // setup the console sink
  typedef boost::log::sinks::synchronous_sink<boost::log::sinks::text_ostream_backend> text_sink;
  boost::shared_ptr<text_sink> consoleSink = boost::log::add_console_log(std::clog;

  lgr_type lgr;
  return lgr;
}
...
BOOST_LOG_SEV(logger::get(), SEV_LVL_TRACE) << "a message";

Thread [1] 29960 [core: 6] (Suspended : Signal : SIGABRT:Aborted)	
	raise() at 0x3215035c39	
	abort() at 0x3215037348	
	__assert_fail_base() at 0x321502eb96	
	__assert_fail() at 0x321502ec42	
	boost::mutex::~mutex() at mutex.hpp:108 0x7ffff7b5fb8b	
	boost::log::v2_mt_posix::sinks::synchronous_sink<boost::log::v2_mt_posix::sinks::basic_text_ostream_backend<char> >::~synchronous_sink() at sync_frontend.hpp:61 0x7ffff7b6c7af	
	boost::detail::sp_ms_deleter<boost::log::v2_mt_posix::sinks::synchronous_sink<boost::log::v2_mt_posix::sinks::basic_text_ostream_backend<char> > >::destroy() at make_shared_object.hpp:57 0x7ffff7b6c890	
	boost::detail::sp_ms_deleter<boost::log::v2_mt_posix::sinks::synchronous_sink<boost::log::v2_mt_posix::sinks::basic_text_ostream_backend<char> > >::operator() at make_shared_object.hpp:87 0x7ffff7b79dca	
	boost::detail::sp_counted_impl_pd<boost::log::v2_mt_posix::sinks::synchronous_sink<boost::log::v2_mt_posix::sinks::basic_text_ostream_backend<char> >*, boost::detail::sp_ms_deleter<boost::log::v2_mt_posix::sinks::synchronous_sink<boost::log::v2_mt_posix::sinks::basic_text_ostream_backend<char> > > >::dispose() at sp_counted_impl.hpp:153 0x7ffff7b78f6d	
	boost::log::v2_mt_posix::core::~core() at 0x7ffff7459100	
	<...more frames...>	

[Andrey Semashev]

I cannot reproduce it with the code from the description. Could you provide the compilable code sample that demonstrates the problem?

Also, if your application is multithreaded, make sure you join all threads before the application terminates.

[mirous]

I'm having the same problem. My environment is debian testing, x86_64, gcc 4.9.1, libboost 1.55.

I stripped down the code to this minimum, main.cpp:

#include <boost/log/trivial.hpp>
#include <boost/log/utility/setup/console.hpp>
#include <boost/log/utility/setup/common_attributes.hpp>

namespace logging = boost::log;

int main(int argc, char *argv[])
{
    logging::add_console_log();
    logging::add_common_attributes();

    BOOST_LOG_TRIVIAL(info) << "Application starting..";
}

Compiled with

gcc -Wall -O2 -g -std=c++11 -DBOOST_LOG_DYN_LINK -o main main.cpp -lstdc++ -lboost_log -lpthread -lboost_thread -lboost_system

[Andrey Semashev]

I don't have gcc 4.9 locally but it doesn't crash for me with gcc 4.8.2. Tried with Boost 1.55 and recent develop branch. Note that you missed -lboost_filesystem in the command line.

Does it crash every time or is it not stable? Could you attach a backtrace of the crash (e.g. run the test from gdb and then execute 'thread apply all bt')?

[mirous]

It crashes every time. I tried it with gcc 4.8 & 4.7 on the same system and it crashes as well.

The backtrace:

#0  0x00007ffff6a16077 in __GI_raise (sig=sig@entry=6) at ../nptl/sysdeps/unix/sysv/linux/raise.c:56
#1  0x00007ffff6a17458 in __GI_abort () at abort.c:89
#2  0x00007ffff6a0f196 in __assert_fail_base (fmt=0x7ffff6b458c8 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", 
    assertion=assertion@entry=0x4120d0 "!posix::pthread_mutex_destroy(&m)", 
    file=file@entry=0x4120a0 "/usr/include/boost/thread/pthread/mutex.hpp", line=line@entry=108, 
    function=function@entry=0x412960 <boost::mutex::~mutex()::__PRETTY_FUNCTION__> "boost::mutex::~mutex()") at assert.c:92
#3  0x00007ffff6a0f242 in __GI___assert_fail (assertion=0x4120d0 "!posix::pthread_mutex_destroy(&m)", 
    file=0x4120a0 "/usr/include/boost/thread/pthread/mutex.hpp", line=108, 
    function=0x412960 <boost::mutex::~mutex()::__PRETTY_FUNCTION__> "boost::mutex::~mutex()") at assert.c:101
#4  0x000000000040cda4 in ~mutex (this=0x61a850, __in_chrg=<optimized out>) at /usr/include/boost/thread/pthread/mutex.hpp:108
#5  boost::log::v2_mt_posix::sinks::synchronous_sink<boost::log::v2_mt_posix::sinks::basic_text_ostream_backend<char> >::~synchronous_sink (this=0x61a7c0, __in_chrg=<optimized out>) at /usr/include/boost/log/sinks/sync_frontend.hpp:61
#6  0x000000000040b58e in destroy (this=0x61a7b8) at /usr/include/boost/smart_ptr/make_shared_object.hpp:57
#7  operator() (this=0x61a7b8) at /usr/include/boost/smart_ptr/make_shared_object.hpp:87
#8  boost::detail::sp_counted_impl_pd<boost::log::v2_mt_posix::sinks::synchronous_sink<boost::log::v2_mt_posix::sinks::basic_text_ostream_backend<char> >*, boost::detail::sp_ms_deleter<boost::log::v2_mt_posix::sinks::synchronous_sink<boost::log::v2_mt_posix::sinks::basic_text_ostream_backend<char> > > >::dispose (this=0x61a7a0) at /usr/include/boost/smart_ptr/detail/sp_counted_impl.hpp:153
#9  0x00007ffff7853ab8 in boost::log::v2_mt_posix::core::~core() () from /usr/lib/x86_64-linux-gnu/libboost_log.so.1.55.0
#10 0x00007ffff7856262 in boost::detail::sp_counted_impl_p<boost::log::v2_mt_posix::core>::dispose() ()
   from /usr/lib/x86_64-linux-gnu/libboost_log.so.1.55.0
#11 0x00007ffff7855eb9 in boost::shared_ptr<boost::log::v2_mt_posix::core>::~shared_ptr() ()
   from /usr/lib/x86_64-linux-gnu/libboost_log.so.1.55.0
#12 0x00007ffff6a18b39 in __run_exit_handlers (status=0, listp=0x7ffff6d835a8 <__exit_funcs>, 
    run_list_atexit=run_list_atexit@entry=true) at exit.c:82
#13 0x00007ffff6a18b85 in __GI_exit (status=<optimized out>) at exit.c:104
#14 0x00007ffff6a02b4c in __libc_start_main (main=0x40a630 <main(int, char**)>, argc=1, argv=0x7fffffffe398, init=<optimized out>, 
    fini=<optimized out>, rtld_fini=<optimized out>, stack_end=0x7fffffffe388) at libc-start.c:321
#15 0x000000000040ab34 in _start ()

[Andrey Semashev]

I cannot reproduce this. If it still happens, please attach a self-contained reproducing code sample.