2

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
}
jma
  • 3,580
  • 6
  • 40
  • 60

2 Answers2

8

A similar question was answered here, I'll just rehash my recommendations.

  1. The simplest solution is to define your own logging macro, that will prepend the message with the location in the source file. For example:
#define LOG(lg, sev)\
    BOOST_LOG_SEV(lg, sev) << "[" << __FILE__ << ":" << __LINE__ << "]: "

Now you can use this macro everywhere in your code instead of BOOST_LOG_SEV. The downside of this solution is that you can't use the file and line as attributes and as such the log format is fixed.

  1. Use stream manipulators to attach the file name and line number as attributes. Again, it is easier to do that in a macro:
BOOST_LOG_ATTRIBUTE_KEYWORD(a_file, "File", std::string)
BOOST_LOG_ATTRIBUTE_KEYWORD(a_line, "Line", unsigned int)

#define LOG(lg, sev)\
    BOOST_LOG_SEV(lg, sev) << logging::add_value(a_file, __FILE__) << logging::add_value(a_line, __LINE__)

(See here about keywords.) After doing that you can use these attributes in formatters:

sink->set_formatter(
    expr::stream << "[" << a_file << ":" << a_line << "]: " << expr::message);

The attributes added this way cannot be used in filters though, and if that's a problem you can...

  1. Use scoped attributes. Again, you can define a macro to automate the process:
#define LOG(lg, sev, strm)\
    do {\
        BOOST_LOG_SCOPED_LOGGER_ATTR(lg, a_file.get_name(), attrs::constant< tag::a_file::value_type >(__FILE__));\
        BOOST_LOG_SCOPED_LOGGER_ATTR(lg, a_line.get_name(), attrs::constant< tag::a_line::value_type >(__LINE__));\
        BOOST_LOG_SEV(lg, sev) strm;\
    } while (false)

Note that in this case the streaming expression is passed as an argument to the macro as we need to inject it in the middle of the scope. Note also that this solution has probably inferior performance to the other two.

There really isn't a solution not involving a macro at some point as __FILE__ and __LINE__ are macros that gets unfolded at the point of use. I believe, this was one of the problems with your code, where you used the macros in the LogMessage function.

It is because of the necessity to define macros anyway, which are supposed to be user-specific, Boost.Log does not provide this feature out of the box.

Andrey Semashev
  • 10,046
  • 1
  • 17
  • 27
2

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.
jma
  • 3,580
  • 6
  • 40
  • 60
  • 1
    Btw, `attrs` is `namespace attrs = boost::log::attributes;`. I have seen multiple stack overflow answers using that. I have seen official boost documentations make use of that without even telling what is it. Hopefully, it saves someone's time. – mradul dubey Jun 20 '23 at 14:34