boost log crash during thread termination

[Marco Strohner <marco.strohner@…>]

I'm using boost 1.64 on iOS and Android. Adding trivial log causes a crash during thread termination.

Removing more and more code produces the follwing example code for reproducing the issue. In the default settings in XCode it randomly crashed.

Enabling all memory related helper in the Scheme (memory guards, ...) helps because it crashes more reproducible and procudes better callstacks.

My result of debugging is:

1. the first executed log line -> creates a thread local storage object with the severity - this severity is stored in severity_level_holder which creates a thread local storage with an automatic deleter (boost::this_thread::at_thread_exit(boost::bind(checked_deleter< uintmax_t >(), p));) - saw this in severity_level.cpp
2. normal Code -> logging works
3. thread terminates
4. the destructor of the TestClass is called and adds a result to the internal promise -> logging works
5. the automatic deleter is called and frees the memory block for the severity.
6. the TestClass of the internal promise is destroyed -> logging crashes because it tries to read the destroyed severity memory block.

#include <memory>

#ifndef BOOST_THREAD_PROVIDES_FUTURE
#define BOOST_THREAD_PROVIDES_FUTURE
#endif

#ifndef BOOST_THREAD_PROVIDES_FUTURE_CONTINUATION
#define BOOST_THREAD_PROVIDES_FUTURE_CONTINUATION
#endif

#include <boost/thread/thread.hpp>
#include <boost/thread/future.hpp>
#include <boost/log/trivial.hpp>



class TestClass {
public:
  TestClass(bool shouldSet) : shouldSet_(shouldSet) {}

  virtual ~TestClass() {
    if (shouldSet_) {
      BOOST_LOG_TRIVIAL(warning) << "crashes here";
      promise_.set_value(std::unique_ptr<TestClass>(new TestClass(false)));
    }
  }

  bool shouldSet_;
  boost::promise<std::unique_ptr<TestClass>> promise_;
};


int main(int, char **) {
#define N 1

  auto wait_future = boost::async([](){
    auto task = []() {
      for (int i=0;i<1000;i++) {
        BOOST_LOG_TRIVIAL(warning) << "Create event #" << i;
        std::shared_ptr<TestClass> event = std::shared_ptr<TestClass>(new TestClass(false));
        boost::future<std::unique_ptr<TestClass>>  future = event->promise_.get_future();
        future.then([i](boost::future<std::unique_ptr<TestClass>>){BOOST_LOG_TRIVIAL(warning) << "event handled #" << i; });
        boost::async([event, i](){
          event->promise_.set_value(std::unique_ptr<TestClass>(new TestClass(true)));
          BOOST_LOG_TRIVIAL(warning) << "Destroy event #" << i;
        }).wait();
      }
    };
    boost::future<void> f[N];

    for(int j=0; j<N; j++){
      f[j] = boost::async(task);
    }
    for(int j=0; j<N; j++){
      f[j].wait();
    }

  });

  wait_future.wait_for(boost::chrono::seconds(10));
  return 0;
}

[Marco Strohner]

I've tested it again with boost 1.66.0 and the behaviour is the same. I also tried to compile boost with BOOST_LOG_USE_COMPILER_TLS but the behaviour is still the same.

My results after more debugging:

1. the logging core creates a thread_data object for the first log that is executed in a thread (core.cpp:open_record). This is triggered by the line BOOST_LOG_TRIVIAL(warning) << "Destroy event #" << i;
2. This created thread_data object ist added to the tss_node map for automatic cleanup after thread execution is finished.
3. After the thread execution is finished the tls_destructor is called (thread.cpp:thread_proxy). This tls_destructor destroys the in step 1 created thread_data object
4. When the method thread_proxy is finished the reference counter of the lambda parameter event is decreased and the destructor is called.
5. The destructor tries to log one line (BOOST_LOG_TRIVIAL(warning) << "crashes here";). But the method get_thread_data still returns the already destroyed pointer to the thread_data object.

[Andrey Semashev]

So the problem seems to be that the code attempts to write a log record after the thread-local data has been destroyed, am I correct? If so, I'm sorry, but this use case is not going to be supported. Like with global destructors on program termination, there's generally no way to make sure that a thread-local object is still alive while the thread terminates and attempting to log at this point will always be unreliable. My advice is to avoid this practice and finish logging before the thread terminates.