boost logging channel filtering in shared libraries not working as expected on linux

I have an executable for both Linux and Windows with three dlls/shared libraries, and I’m using boost.log for logging. I wish to have a separate, file log for each module. My approach was to create a severity_channel_logger_mt for each module, constructed in a singleton for each module with the channel name.

class LogSingleton final
{
  src::severity_channel_logger_mt<logging::trivial::severity_level, std::string> slg_;
...
protected:
  LogSingleton() : slg_(boost::log::keywords::channel = "ModuleOne") {}
public:
  src::severity_channel_logger_mt<logging::trivial::severity_level, std::string>& logger() { return slg_; }
...
};

Each module then creates its own file sink on initialisation, and sets a channel filter so that only that module’s log messages should reach this sink.

logging::add_file_log(logging::keywords::file_name = "module_one.log",
  logging::keywords::open_mode = std::ios::app,
  ->set_filter(logging::trivial::severity >= level 
    && expr::attr< std::string >("Channel") == "ModuleOne");

I have then created my own module specific macro for logging, which passes to the right logger.

#define BLOG(lvl)  BOOST_LOG_STREAM_WITH_PARAMS((LogSingleton::instance()->logger()), (::boost::log::keywords::severity = ::boost::log::trivial::lvl))

which is used like this:

BLOG(info) << "Hello world";

Whilst on Windows logging works as expected, on Linux the log files for ModuleOne (initialised first) and ModuleThree (initialised third) do not receive any log messages. ModuleTwo logs correctly. The logging code for all three modules is identical apart from the log sink filename, channel names, and the class name of the singleton.

I wonder if the problem is with my macro but any ideas welcome, together with comments on the approach.

Update

I have reduced this problem to a minimal example, all in one executable. The shared library issue was a misdirection. The issue appears to be that if I create the severity_channel_logger in a singleton, logging fails. If I use a local logger, logging works. Even if I create a logger in the singleton and don’t use it, it prevents the local logger from functioning. Despite tracing through the code, I can’t see why this is happening. (platform = Fedora 21, gcc 4.9.2, boost 1.58)

#include <boost/config.hpp> 
#include <boost/filesystem.hpp>
#include <boost/log/core.hpp>
#include <boost/log/trivial.hpp>
#include <boost/log/sources/severity_feature.hpp>
#include <boost/log/sources/severity_channel_logger.hpp>
#include <boost/log/expressions.hpp>
#include <boost/log/expressions/formatters/date_time.hpp>
#include <boost/log/support/date_time.hpp>
#include <boost/log/attributes/current_thread_id.hpp>
#include <boost/log/utility/setup/file.hpp>
#include <boost/log/utility/setup/console.hpp>
#include <boost/log/utility/setup/common_attributes.hpp>

namespace logging = boost::log;
namespace expr = boost::log::expressions;
namespace src = boost::log::sources;
namespace fs = boost::filesystem;

class LogSingleton
{
    src::severity_channel_logger<logging::trivial::severity_level, std::string> slg_;
    static LogSingleton* instance_;

    LogSingleton(const LogSingleton&);
    LogSingleton& operator=(const LogSingleton&);

protected:
    LogSingleton() : slg_(boost::log::keywords::channel = "Core") {}
public:
    src::severity_channel_logger<logging::trivial::severity_level, std::string>&  logger()
    {
        return slg_;
    }

    static LogSingleton* instance()
    {
        if (!instance_)
        {
            instance_ = new LogSingleton;
        }
        return instance_;
    }
};

LogSingleton* LogSingleton::instance_ = nullptr;

// 1. doesn't work
//#define BLOG(lvl)  BOOST_LOG_STREAM_WITH_PARAMS((LogSingleton::instance()->logger()), (::boost::log::keywords::severity = ::boost::log::trivial::lvl))

// access to logger via reference. Works if it is passed a ref to logger declared in main. Doesn't work if it is ref to logger in singleton
#define BLOG(lvl)  BOOST_LOG_STREAM_WITH_PARAMS((rlogger), (::boost::log::keywords::severity = ::boost::log::trivial::lvl))

int main(int argc, char **argv)
{
    logging::add_common_attributes();
    logging::trivial::severity_level level = logging::trivial::trace;
        auto formatter = expr::stream
        << "[" << expr::format_date_time<boost::posix_time::ptime>("TimeStamp", "%Y-%m-%dT%H:%M:%S.%f")
        << "] (" << logging::trivial::severity
        << "): " << expr::message;

    fs::path plog = fs::system_complete(fs::path(".."));
    if (!fs::exists(plog) || !fs::is_directory(plog))
        throw std::invalid_argument("Log directory doesn't exist, or path isn't a directory");
    plog /= "core.log";

    logging::add_file_log(logging::keywords::file_name = plog.string(),
        logging::keywords::open_mode = std::ios::app,
        logging::keywords::format = formatter)
        ->set_filter(logging::trivial::severity >= level &&    expr::attr< std::string >("Channel") == "Core");

    // this works with rlogger macro variant
    src::severity_channel_logger<logging::trivial::severity_level, std::string> logger(boost::log::keywords::channel = "Core");
    auto& rlogger = logger;

    // 2. this doesn't work, with same macro
    //auto& rlogger = LogSingleton::instance()->logger();

    // 3. just creating the singleton, before or after the creation of the local logger, stops logging from working
    //LogSingleton::instance();

    BLOG(info) << "Hello world";

    return 0;
}

As currently written, this example works with the local logger. Comment labelled 1 – this is the variant of the macro that uses singleton logger direct (fails). Also commenting out the local logger and enabling the reference to the singleton will demonstrate the issue. (comment 2). Comment labelled 3 shows that just creating a singleton logger causes logging to fail via the local logger.

Answer

The problem is caused by the leak of LogSingleton in your code. The singleton contains a logger, which keeps the logging core and sinks from being destroyed. The log record you make is correctly processed and written to the file stream but not flushed (i.e. it ends up in the file stream buffers). Normally, stream buffers are flushed when the stream is destroyed (in case of Boost.Log this happens when sinks are destroyed, at program termination) or after every log record, if you enable auto-flush (pass the keywords::auto_flush = true argument to the add_file_log function call).

You can fix it if you change LogSingleton::instance_ to be a std::unique_ptr.

Advertisement

Answer