Search code examples
c++boostboost-log

Boost log and severity / local attributes


I'm new to Boost log. I've got some simple stuff working but I'm stuck at getting a macro to make it easy to specify filename and line number. It's seeming so hard, I assume I've missed something.

I wrote this to initialize logging with a demo log at the end. Note that I'm logging to console and to a rotating file.

logging::add_console_log(std::clog, keywords::format = "%TimeStamp%: %_%",
                         keywords::auto_flush = true);
typedef sinks::synchronous_sink<sinks::text_file_backend> file_sink;
shared_ptr<file_sink> sink(new file_sink(
    keywords::file_name = "%Y%m%d_%H%M%S_%5N.log",
    keywords::rotation_size = 16384, keywords::auto_flush = true));

sink->locked_backend()->set_file_collector(sinks::file::make_collector(
    keywords::target = "logs",
    keywords::max_size = 16 * 1024 * 1024,
    keywords::min_free_space = 100 * 1024 * 1024));

sink->locked_backend()->scan_for_files();
sink->set_formatter(expr::stream
                    << expr::attr<boost::posix_time::ptime>("TimeStamp")
                    << " " << logging::trivial::severity << "["
                    << expr::attr<string>("FileName") << ":"
                    << expr::attr<unsigned int>("LineNumber") << "] "
                    << expr::smessage);
logging::core::get()->add_sink(sink);
logging::add_common_attributes();
logging::core::get()->add_global_attribute("TimeStamp",
                                           attrs::local_clock());

src::severity_logger<logging::trivial::severity_level> slg;
lg.add_attribute("LineNumber", attrs::constant<unsigned int>(__LINE__));
lg.add_attribute("FileName", attrs::constant<string>(__FILE__));
for (unsigned int i = 0; i < 5; ++i) {
    BOOST_LOG_SEV(slg, logging::trivial::info) << "Some log record";
}

Now I'd like to make a macro so that I can add file and line number and have it behave like an ostream. What I'd like to be able to do is say

LOG(info) << "Hello, world!";

I wrote the following, which doesn't work, but it expresses what I'm trying to do:

#define LOG(severity_level) LogMessage(__FILE__, __LINE__, severity_level)

// What's my return type?
auto LogMessage(const char* filename, const int line_number,
           const enum SeverityLevel) {
src::severity_logger slg;
slg.add_attribute("LineNumber", attrs::constant<unsigned int>(__LINE__));
slg.add_attribute("FileName", attrs::constant<string>(__FILE__));
return BOOST_LOG_SEV(slg, severity_level);    // NO
}

Solution

  • This answer owes quite a lot to these conversations and to the solution proposed by @guillermo-ruiz in particular. I chose to follow Guillermo's suggestions because it made the least use of the preprocessor. (Some use of the preprocessor is mandatory, of course, since I wanted __FILE__ and __LINE__.)

    In the interest of offering to those who follow somewhat broader help than just a strict answer, a couple remarks:

    • Yes, it's very strange that Boost log doesn't provide this out of the box.
    • Boost log doesn't do as much error checking as I'd like. In particular, if one has a mismatch between the name of an attribute at definition and the name at use, the result is a segfault without descriptive error, not a runtime error (followed by abort or not).
    • Boost log is remarkably sensitive to getting include statements correct. There's no single include to rule them all, and missing an include leads to error messages suggesting a programming error when, in fact, it's merely a missing definition.

    In the file log.cc, I wrote this:

    Log::Log() {
    try {
        // The first thing we have to do to get using the library is
        // to set up the logging sinks - i.e. where the logs will be written to.
        logging::add_console_log(std::clog,
                     keywords::format = "%TimeStamp%: %_%",
                     keywords::auto_flush = true);
    
        // Create a text file sink
        typedef sinks::synchronous_sink<sinks::text_file_backend> file_sink;
        shared_ptr<file_sink> sink(new file_sink(
        // File name pattern.
        keywords::file_name = "%Y%m%d_%H%M%S_%5N.log",
        // Rotation size, in characters
        keywords::rotation_size = 16384,
        // Rotate daily if not more often.  The time is arbitrary.
        keywords::time_based_rotation =
            sinks::file::rotation_at_time_point(4, 33, 17),
        // Flush after write.
        keywords::auto_flush = true));
    
        // Set up where the rotated files will be stored.
        sink->locked_backend()->set_file_collector(sinks::file::make_collector(
        // Where to store rotated files.
        keywords::target = "logs",
        // Maximum total size of the stored files, in bytes.
        keywords::max_size = 16 * 1024 * 1024,
        // Minimum free space on the drive, in bytes.
        keywords::min_free_space = 100 * 1024 * 1024));
    
        // Upon restart, scan the target directory for files matching the
        // file_name pattern.
        sink->locked_backend()->scan_for_files();
        boost::log::register_simple_formatter_factory<
        logging::trivial::severity_level, char>("Severity");
        sink->set_formatter(expr::stream
                << expr::attr<boost::posix_time::ptime>("TimeStamp")
                << " " << logging::trivial::severity << "["
                << expr::attr<string>("FileName") << ":"
                << expr::attr<unsigned int>("LineNumber") << "] "
                << expr::smessage);
        // Add it to the core
        logging::core::get()->add_sink(sink);
        // Add some attributes too
        logging::add_common_attributes();
        logging::core::get()->add_global_attribute("TimeStamp",
                               attrs::local_clock());
        logging::core::get()->add_global_attribute(
        "LineNumber", attrs::mutable_constant<unsigned int>(5));
        logging::core::get()->add_global_attribute(
        "FileName", attrs::mutable_constant<string>(""));
    
        src::severity_logger<logging::trivial::severity_level> slg;
        slg.add_attribute("LineNumber",
                  attrs::constant<unsigned int>(__LINE__));
        slg.add_attribute("FileName", attrs::constant<string>(__FILE__));
        for (unsigned int i = 0; i < 2; ++i) {
        BOOST_LOG_SEV(slg, logging::trivial::info) << "Testing log, #" << i;
        }
    } catch (std::exception& e) {
        std::cerr << "Failed to establish logging: " << e.what() << std::endl;
        throw LoggingInitException();
    }
    }
    
    Log::~Log() { boost::log::core::get()->remove_all_sinks(); }
    
    string PathToFilename(const string& path) {
    string sub_path = path.substr(path.find_last_of("/\\") + 1);
    return sub_path;
    }
    

    In the file log.h, I wrote this:

    // An exception if logging fails to initialize.
    class LoggingInitException : public std::exception {};
    
    /*
      Class to set up logging as we want it in all services.
    
      Instantiate a Log object near the beginning of main().
    */
    class Log {
       public:
        Log();
        ~Log();
    };
    
    // Logging macro that includes severity, filename, and line number.
    // Copied and modified from
    // https://stackoverflow.com/questions/24750218/boost-log-to-print-source-code-file-name-and-line-number
    // Set attribute and return the new value
    template <typename ValueType>
    ValueType SetGetAttrib(const char* name, ValueType value) {
        auto attr = boost::log::attribute_cast<
            boost::log::attributes::mutable_constant<ValueType>>(
            boost::log::core::get()->get_global_attributes()[name]);
        attr.set(value);
        return attr.get();
    }
    
    // Convert file path to only the filename
    std::string PathToFilename(const std::string& path);
    
    // Shortcut to declare a log source.  To insert in each function that will call
    // the LOG macro.
    #define LOGGABLE                                                              \
        boost::log::sources::severity_logger<boost::log::trivial::severity_level> \
            slg;
    
    #define LOG(sev)                                                 \
        BOOST_LOG_STREAM_WITH_PARAMS(                                \
            (slg),                                                   \
            (SetGetAttrib("FileName", PathToFilename(__FILE__)))(    \
                SetGetAttrib("LineNumber", (unsigned int)__LINE__))( \
                ::boost::log::keywords::severity = (boost::log::trivial::sev)))
    

    Then, to log from file foo.cc, I do this:

    void MyFunction() {
        LOGGABLE;
        LOG(debug) << "I made it to MyFunction().";
    }
    
    int main(int argc, char *argv[]) {
        Log log;
        LOGGABLE;
        LOG(info) << "Hey, I'm a message!";
        MyFunction();
        return 0;
    }
    

    A few quibbles remain, but they are out of scope for this SO question/answer:

    • To make this more usable, I should make logs go somewhere more specific than "logs", probably directed by invocation flags and the application name, whether I'm in production or not, etc.
    • I should check if stdout is connected to a terminal and if not, skip logging to stdout. Or I should provide a flag to disable it in data centers, at least.
    • Sometimes, mysteriously, I get a top level log file called (for example) 20160310_093628_00000.log instead of a file written to the logs/ directory. It took me a long time to realize that boost log writes there, then rotates to the logs/ directory. So if the program crashes, I end up with a log file at that level.