Boost Log backends fail silently on Ubuntu

[lylemoffitt@…]

When compiled on Ubuntu, a test program using the global logger with custom sink backends fails to run properly. It produces no output to the console or to a file (it should do both). It does not produce any error messages or warnings during either the compilation, nor the run time. I believe this is caused by a failure on the part of the library to properly add new sinks. My believe is founded on the observation that: (1) the code works fine on another machine, (2) the dedicated thread for the asynchronous_sink can be observed, (3) when no new sinks are added the logger works fine (in default mode).

Includes: sample code, build scripts, and testing notes.

[lylemoffitt@…]

Zip'd files of sample code, with notes, and build scripts

[lylemoffitt@…]

Correction: Boost version on Linux is v1.54

[Andrey Semashev]

Could you please test it with the latest Boost version (from git develop or at least 1.60)?

[lylemoffitt@…]

Tried it with the instructions from here, but dead-ended in some 'undefined reference' errors.

/usr/local/include/boost/log/sinks/unbounded_fifo_queue.hpp:78: error: undefined reference to 'boost::log::v2_mt_posix::aux::futex_based_event::futex_based_event()'
/usr/local/include/boost/log/sinks/unbounded_fifo_queue.hpp:56: error: undefined reference to 'boost::log::v2_mt_posix::aux::futex_based_event::~futex_based_event()'
/usr/local/include/boost/log/sinks/unbounded_fifo_queue.hpp:129: error: undefined reference to 'boost::log::v2_mt_posix::aux::futex_based_event::set_signalled()'
/usr/local/include/boost/log/sinks/unbounded_fifo_queue.hpp:84: error: undefined reference to 'boost::log::v2_mt_posix::aux::futex_based_event::set_signalled()'
/usr/local/include/boost/log/sinks/unbounded_fifo_queue.hpp:117: error: undefined reference to 'boost::log::v2_mt_posix::aux::futex_based_event::wait()'
/usr/local/include/boost/log/sources/global_logger_storage.hpp:120: error: undefined reference to 'boost::log::v2_mt_posix::sources::aux::global_storage::get_or_init(boost::typeindex::stl_type_index, boost::shared_ptr<boost::log::v2_mt_posix::sources::aux::logger_holder_base> (*)())'
/usr/local/include/boost/log/sources/global_logger_storage.hpp:136: error: undefined reference to 'boost::log::v2_mt_posix::sources::aux::throw_odr_violation(boost::typeindex::stl_type_index, boost::typeindex::stl_type_index, boost::log::v2_mt_posix::sources::aux::logger_holder_base const&)'

It's possible I messed up the installation. Is there a dpkg repo I can try installing from?

Whatever the solution, it needs to work on Ubuntu 14.04 LTS, since that's the target platform for my codebase.

[anonymous]

Ok. Got it all sorted out. Had to reset the VM, uninstall all the old boost libs from dpkg, reinstall v1.60 *and* run ldconfig (forgot to do that before). Now it compiles and runs. Same result as before, bupkis.

And btw, this is all compiled with GCC. So there's no incompatibility introduced from there.

Here's confirmation from ldd that it was all linked correctly:

ldd ./log_test
        linux-vdso.so.1 =>  (0x00007ffd8ddc4000)
        libboost_log.so.1.60.0 => /usr/local/lib/libboost_log.so.1.60.0 (0x00007fbcc9a98000)
        libboost_thread.so.1.60.0 => /usr/local/lib/libboost_thread.so.1.60.0 (0x00007fbcc9876000)
        libboost_system.so.1.60.0 => /usr/local/lib/libboost_system.so.1.60.0 (0x00007fbcc9672000)
        libpthread.so.0 => /lib/x86_64-linux-gnu/libpthread.so.0 (0x00007fbcc9454000)
        libunwind.so.8 => /usr/lib/x86_64-linux-gnu/libunwind.so.8 (0x00007fbcc9239000)
        libstdc++.so.6 => /usr/lib/x86_64-linux-gnu/libstdc++.so.6 (0x00007fbcc8f35000)
        libc.so.6 => /lib/x86_64-linux-gnu/libc.so.6 (0x00007fbcc8b70000)
        libboost_filesystem.so.1.60.0 => /usr/local/lib/libboost_filesystem.so.1.60.0 (0x00007fbcc8957000)
        librt.so.1 => /lib/x86_64-linux-gnu/librt.so.1 (0x00007fbcc874f000)
        libgcc_s.so.1 => /lib/x86_64-linux-gnu/libgcc_s.so.1 (0x00007fbcc8539000)
        /lib64/ld-linux-x86-64.so.2 (0x00007fbcc9d44000)
        liblzma.so.5 => /lib/x86_64-linux-gnu/liblzma.so.5 (0x00007fbcc8317000)
        libm.so.6 => /lib/x86_64-linux-gnu/libm.so.6 (0x00007fbcc8011000)
        libdl.so.2 => /lib/x86_64-linux-gnu/libdl.so.2 (0x00007fbcc7e0d000)

[Andrey Semashev]

The attached test produces both console and file output on my system. I didn't dig into the test code too much, but I didn't find you calling flush() on the core or sink before exiting the process. Since you're using the asynchronous sink frontend, it is possible that some of the log records are left in the queue unprocessed when the test terminates. I suppose this may be the reason why you observe different results on different machines.

[Lyle Moffitt <lylemoffitt@…>]

1. What system are you testing on? Is is Ubuntu 14.04? This problem is likely specific to at the very least that distro.
2. I don't think you looked at the source code at all.. Both sinks are set to auto_flush=true.
3. If the problem were that "some of the log records are left in the queue unprocessed when the test terminates", then it would be easy to prove it so. Here are some ways you could do that:
   1. You could simply add alog_data::file_sink->flush() command before exiting main().
   2. You could remove the filter step to prevent the queue from being blocked.
   3. You could remove the async sink from the logger and just use the synchronous terminal sink, which would not be blocked.
4. Here are some reasons why I don't think your hypotheses is correct:
   1. The test_file_backend is setup to create a file and write a header to it before any logging is done.
   2. I tried calling flush() for both sinks before exiting main(). If the messages were stuck in the queue somehow, then this would have prevented the program from exiting at all, since both methods a defined to block until the queue is empty.
   3. I am in fact using 2 sinks (async'd file and sync'd terminal). Your explanation completely misses the latter.

TL;DR: Your explanation is just plain wrong.

---

I took a lot of time to make this as simple an example as possible while still retaining the essence of the problem. I took pains to document and format a bug report to help you out. The fact that you barely looked at the code and then gave me a half-assed answer is frankly insulting. If you aren't going to take this seriously, please pass this bug to someone who will.

[Andrey Semashev]

1. Kubuntu 15.10.
2. auto_flush has no effect on the sink frontend, where the queueing happens.
3. I'm not going to prove anything. You're the one who can reproduce the problem, so you're going to have to try the solution. Or not, and live on with the problem.
4. There's no test_file_backend. text_file_backend only creates the file on the first record it receives, so the file will not appear if no records reach the backend.

It's true I didn't notice that the console sink is synchronous. The output would have appeared at least on the console, so since you're not getting it the problem is elsewhere.

Upon further inspection I noticed you're using std::regex in your filter. If you're using gcc 4.8, the official one in 14.04, then it is broken and may be the reason why all records are filtered away (std::regex was actually implemented in ​4.9). Try switching to boost::regex.

If that doesn't help, debug your code. See if your filter works. See if records reach the sinks. See if any exceptions are thrown. Step through the processing of a log record in the debugger.

---

Suck up your emotions and deal with the problem. You're only one able to reproduce it, so it's highly likely the source is on your end. I'm not paid to read your whining and debug your code, and my time is limited. I suggested a possible solution; it may be wrong but that's why you are here - to try it out and provide more info. That's how solving the problem works. Also, I'm the only maintainer of Boost.Log, so you're unlikely to get help elsewhere.

[Lyle Moffitt <lylemoffitt@…>]

Thank you for taking the time to look at my code. Really. That alone made all the difference.

It turns out that you were spot on about std::regex being the the source of the problem. Simply commenting out the lines that use it is enough to produce the desired behavior. It works on both boost v1.54 and boost v1.60.

The remaining point of curiosity is why this doesn't work with clang 3.4 (and libc++), which supposedly have support for std::regex... (But that's not really important.)

Thanks for the suggestion on boost::regex; it was an easy, drop-in replacement.

---

Thank you for you time and help.