boost::log, extending sources, race-condition

[Sorin Manolache <sorinm@…>]

Hello,

I'm using the example for extending boost::log sources found here: http://www.boost.org/doc/libs/1_56_0/libs/log/example/doc/extension_record_tagger.cpp

I've modified it in order to use the same logger in two threads. I've added a thread-main function:

static void
thr_main(my_logger<severity_level>& logger, unsigned int id, std::string const& msg, unsigned int iterations) {
	for (unsigned int i = 0; i < iterations; ++i)
		LOG_WITH_TAG(logger, normal, "GUI") << id << '\t' << msg;
}

I'm running the two threads from main:

int main(int, char*[])
{
	init();

	my_logger<severity_level> logger;

	boost::thread th1(boost::bind(&thr_main, boost::ref(logger), 0, "abc", 100000));
	boost::thread th2(boost::bind(&thr_main, boost::ref(logger), 1, "xyz", 100000));

	th1.join();
	th2.join();

	return 0;
}

I'm using Linux 3.14.1 on an x86_64 architecture, g++ 4.9.1, libc 2.19.

The compile/link command is:

g++ -DBOOST_LOG_DYN_LINK -Wall -std=c++11 -O0 -fno-inline -g -o example example.cc -lboost_log -lboost_log_setup -lboost_thread -lboost_system -pthread

I get segfaults every time.

gdb says:

Program terminated with signal SIGSEGV, Segmentation fault.
#0  0x00007f0f7f5efc3e in boost::log::v2_mt_posix::attribute_set::insert(boost::log::v2_mt_posix::attribute_name, boost::log::v2_mt_posix::attribute const&) () from /usr/lib/x86_64-linux-gnu/libboost_log.so.1.55.0

(gdb) thread apply all bt

Thread 2 (Thread 0x7f0f7d792700 (LWP 32726)):
#0  0x00007f0f7e042c75 in ?? () from /lib/x86_64-linux-gnu/libc.so.6
#1  0x00007f0f7e043821 in ?? () from /lib/x86_64-linux-gnu/libc.so.6
#2  0x00007f0f7f5f0740 in boost::log::v2_mt_posix::attribute_value_set::~attribute_value_set() () from /usr/lib/x86_64-linux-gnu/libboost_log.so.1.55.0
#3  0x00007f0f7f5f3419 in boost::log::v2_mt_posix::record_view::public_data::destroy(boost::log::v2_mt_posix::record_view::public_data const*) ()
   from /usr/lib/x86_64-linux-gnu/libboost_log.so.1.55.0
#4  0x00007f0f7f5f3e90 in boost::log::v2_mt_posix::core::push_record_move(boost::log::v2_mt_posix::record&) ()
   from /usr/lib/x86_64-linux-gnu/libboost_log.so.1.55.0
#5  0x000000000041bb8f in push_record (rec=<unknown type in /home/srn/cpp_tests/log/example, CU 0x0, DIE 0x3bd04>, this=0x127b2c0)
    at /usr/include/boost/log/core/core.hpp:308
#6  boost::log::v2_mt_posix::sources::basic_logger<char, my_logger<severity_level>, boost::log::v2_mt_posix::sources::single_thread_model>::push_record_unlocked(boost::log::v2_mt_posix::record&&) (this=0x7fff82b62cf0, rec=<unknown type in /home/srn/cpp_tests/log/example, CU 0x0, DIE 0x489a8>)
    at /usr/include/boost/log/sources/basic_logger.hpp:267
#7  0x000000000041928c in boost::log::v2_mt_posix::sources::basic_composite_logger<char, my_logger<severity_level>, boost::log::v2_mt_posix::sources::single_thread_model, boost::log::v2_mt_posix::sources::features<boost::log::v2_mt_posix::sources::severity<severity_level>, record_tagger> >::push_record(boost::log::v2_mt_posix::record&&) (this=0x7fff82b62cf0, rec=<unknown type in /home/srn/cpp_tests/log/example, CU 0x0, DIE 0x45930>)
    at /usr/include/boost/log/sources/basic_logger.hpp:581
#8  0x0000000000419308 in boost::log::v2_mt_posix::aux::record_pump<my_logger<severity_level> >::~record_pump (this=0x7f0f7d791dd0,
    __in_chrg=<optimized out>) at /usr/include/boost/log/sources/record_ostream.hpp:279
#9  0x0000000000413fd3 in thr_main (logger=..., id=0, msg="abc", iterations=100000) at example.cc:245


Thread 1 (Thread 0x7f0f7cf91700 (LWP 32727)):
#0  0x00007f0f7f5efc3e in boost::log::v2_mt_posix::attribute_set::insert(boost::log::v2_mt_posix::attribute_name, boost::log::v2_mt_posix::attribute const&) () from /usr/lib/x86_64-linux-gnu/libboost_log.so.1.55.0
#1  0x000000000041d6b2 in boost::log::v2_mt_posix::sources::basic_logger<char, my_logger<severity_level>, boost::log::v2_mt_posix::sources::single_thread_model>::add_attribute_unlocked (this=0x7fff82b62cf0, name=..., attr=...) at /usr/include/boost/log/sources/basic_logger.hpp:227
#2  0x000000000041d902 in record_tagger_feature<boost::log::v2_mt_posix::sources::basic_logger<char, my_logger<severity_level>, boost::log::v2_mt_posix::sources::single_thread_model> >::open_record_unlocked<boost::parameter::aux::arg_list<boost::parameter::aux::tagged_argument<boost::log::v2_mt_posix::keywords::tag::severity, severity_level const>, boost::parameter::aux::arg_list<boost::parameter::aux::tagged_argument<my_keywords::tag_ns::tag, char const [4]>, boost::parameter::aux::empty_arg_list> > > (this=0x7fff82b62cf0, args=...) at example.cc:127
#3  0x000000000041b850 in boost::log::v2_mt_posix::sources::basic_severity_logger<record_tagger_feature<boost::log::v2_mt_posix::sources::basic_logger<char, my_logger<severity_level>, boost::log::v2_mt_posix::sources::single_thread_model> >, severity_level>::open_record_unlocked<boost::parameter::aux::arg_list<boost::parameter::aux::tagged_argument<boost::log::v2_mt_posix::keywords::tag::severity, severity_level const>, boost::parameter::aux::arg_list<boost::parameter::aux::tagged_argument<my_keywords::tag_ns::tag, char const [4]>, boost::parameter::aux::empty_arg_list> > > (this=0x7fff82b62cf0, args=...)
    at /usr/include/boost/log/sources/severity_feature.hpp:253
#4  0x000000000041912d in boost::log::v2_mt_posix::sources::basic_composite_logger<char, my_logger<severity_level>, boost::log::v2_mt_posix::sources::single_thread_model, boost::log::v2_mt_posix::sources::features<boost::log::v2_mt_posix::sources::severity<severity_level>, record_tagger> >::open_record<boost::parameter::aux::arg_list<boost::parameter::aux::tagged_argument<boost::log::v2_mt_posix::keywords::tag::severity, severity_level const>, boost::parameter::aux::arg_list<boost::parameter::aux::tagged_argument<my_keywords::tag_ns::tag, char const [4]>, boost::parameter::aux::empty_arg_list> > > (
    this=0x7fff82b62cf0, args=...) at /usr/include/boost/log/sources/basic_logger.hpp:575
#5  0x0000000000413f68 in thr_main (logger=..., id=1, msg="xyz", iterations=100000) at example.cc:245

[Andrey Semashev]

You're using a non-thread-safe logger in multiple threads. There is a comment in the example on how to make the logger thread-safe.