boost log to print source code file name and line number

Question

I'm using Boost(1.55.0) Logging in my C++ application. I have been able to generate log of this format

[2014-Jul-15 10:47:26.137959]: <debug>  A regular message

I want to be able to add source file name and line number where the log is generated.

[2014-Jul-15 10:47:26.137959]: <debug> [filename:line_no] A regular message

example:

[2014-Jul-15 10:47:26.137959]: <debug> [helloworld.cpp : 12] A regular message

Source Code:

#include <boost/log/core.hpp>
#include <boost/log/trivial.hpp>
#include <boost/log/expressions.hpp>
#include <boost/log/sinks/text_file_backend.hpp>
#include <boost/log/utility/setup/file.hpp>
#include <boost/log/utility/setup/common_attributes.hpp>
#include <boost/log/sources/severity_logger.hpp>
#include <boost/log/sources/record_ostream.hpp>
#include <boost/log/expressions.hpp>
#include <boost/log/support/date_time.hpp>
#include <boost/log/attributes/attribute.hpp>
#include <boost/log/attributes/attribute_cast.hpp>
#include <boost/log/attributes/attribute_value.hpp>
#include <boost/make_shared.hpp>
#include <boost/property_tree/ptree.hpp>

namespace logging = boost::log;
namespace src = boost::log::sources;
namespace sinks = boost::log::sinks;
namespace keywords = boost::log::keywords;

void init()
{
    logging::add_file_log
    (
        keywords::file_name = "sample_%N.log",                                        /*< file name pattern >*/
        keywords::rotation_size = 10*1024*1204,                                 /*< rotate files every 10 MiB... >*/
        keywords::time_based_rotation = sinks::file::rotation_at_time_point(0, 0, 0), /*< ...or at midnight >*/
        keywords::format =
        (
            boost::log::expressions::stream
                << boost::log::expressions::format_date_time< boost::posix_time::ptime >("TimeStamp", "%Y-%m-%d_%H:%M:%S.%f")
                << ": <" << boost::log::trivial::severity << "> "
                << boost::log::expressions::smessage
        )
    );
}

int main(int, char*[])
{
    init();
    logging::add_common_attributes();

    using namespace logging::trivial;
    src::severity_logger< severity_level > lg;

    BOOST_LOG_SEV(lg, debug) << "A regular message";
    return 0;
}

Solution 1

I would suggest to use the boost::log::add_value() function.

Define:

#define LOG_LOCATION(LEVEL, MSG)      \
  BOOST_LOG_SEV(logger::get(), LEVEL)     \
    << boost::log::add_value("Line", __LINE__)          \
    << boost::log::add_value("File", __FILE__)          \
    << boost::log::add_value("Function", __FUNCTION__) << MSG

And then you can format it as follows:

boost::log::add_common_attributes();

boost::log::register_simple_filter_factory<boost::log::trivial::severity_level, char>("Severity");
boost::log::register_simple_formatter_factory<boost::log::trivial::severity_level, char>("Severity");

auto syslog_format(
    boost::log::expressions::stream <<
        "["   << boost::log::expressions::format_date_time< boost::posix_time::ptime >("TimeStamp", "%Y-%m-%d %H:%M:%S") <<
        "] [" << boost::log::expressions::attr<boost::log::attributes::current_thread_id::value_type>("ThreadID") << 
        "] [" << std::left << std::setw(7) << std::setfill(' ') << boost::log::trivial::severity <<
        "] "  << boost::log::expressions::smessage <<
        " ("  << boost::log::expressions::attr<std::string>("Filename") <<
        ":"   << boost::log::expressions::attr<int>("Line") <<
        ":"   << boost::log::expressions::attr<std::string>("Function") <<
        ")"
);

boost::log::add_file_log(
    boost::log::keywords::file_name  = "sys_%d_%m_%Y.%N.log",
    boost::log::keywords::format = syslog_format
);

No need to add global attributes, and you can format it easily as seen above. I find this is a good compromise between other's solutions and the raw __FILE__ __LINE__ approach.

Full example here.

Solution 2

As Horus pointed out, you can use attributes to log file and line numbers. However it is best to avoid using multi-statements macros to avoid problems with expressions like this:

if (something)
   LOG_FILE_LINE(debug) << "It's true"; // Only the first statement is conditional!

You can do better creating a macro that leverages the underlying behavior of the Boost Log library. For example, BOOST_LOG_SEV is:

#define BOOST_LOG_SEV(logger, lvl) BOOST_LOG_STREAM_SEV(logger, lvl)
#define BOOST_LOG_STREAM_SEV(logger, lvl)\
    BOOST_LOG_STREAM_WITH_PARAMS((logger), (::boost::log::keywords::severity = (lvl)))

Using BOOST_LOG_STREAM_WITH_PARAMS you can set and get more attributes, like this:

// New macro that includes severity, filename and line number
#define CUSTOM_LOG(logger, sev) \
   BOOST_LOG_STREAM_WITH_PARAMS( \
      (logger), \
         (set_get_attrib("File", path_to_filename(__FILE__))) \
         (set_get_attrib("Line", __LINE__)) \
         (::boost::log::keywords::severity = (boost::log::trivial::sev)) \
   )

// Set attribute and return the new value
template<typename ValueType>
ValueType set_get_attrib(const char* name, ValueType value) {
   auto attr = logging::attribute_cast<attrs::mutable_constant<ValueType>>(logging::core::get()->get_thread_attributes()[name]);
   attr.set(value);
   return attr.get();
}

// Convert file path to only the filename
std::string path_to_filename(std::string path) {
   return path.substr(path.find_last_of("/\\")+1);
}

The complete source code is:

#include <boost/log/trivial.hpp>
#include <boost/log/sources/severity_logger.hpp>
#include <boost/log/utility/setup/file.hpp>
#include <boost/log/utility/setup/console.hpp>
#include <boost/log/expressions.hpp>
#include <boost/log/utility/setup/common_attributes.hpp>
#include <boost/log/attributes/mutable_constant.hpp>
#include <boost/date_time/posix_time/posix_time_types.hpp>
#include <boost/log/support/date_time.hpp>
#include <boost/log/attributes/mutable_constant.hpp>

namespace logging  = boost::log;
namespace attrs    = boost::log::attributes;
namespace expr     = boost::log::expressions;
namespace src      = boost::log::sources;
namespace keywords = boost::log::keywords;

// New macro that includes severity, filename and line number
#define CUSTOM_LOG(logger, sev) \
   BOOST_LOG_STREAM_WITH_PARAMS( \
      (logger), \
         (set_get_attrib("File", path_to_filename(__FILE__))) \
         (set_get_attrib("Line", __LINE__)) \
         (::boost::log::keywords::severity = (boost::log::trivial::sev)) \
   )

// Set attribute and return the new value
template<typename ValueType>
ValueType set_get_attrib(const char* name, ValueType value) {
   auto attr = logging::attribute_cast<attrs::mutable_constant<ValueType>>(logging::core::get()->get_thread_attributes()[name]);
   attr.set(value);
   return attr.get();
}

// Convert file path to only the filename
std::string path_to_filename(std::string path) {
   return path.substr(path.find_last_of("/\\")+1);
}

void init() {
   // New attributes that hold filename and line number
   logging::core::get()->add_thread_attribute("File", attrs::mutable_constant<std::string>(""));
   logging::core::get()->add_thread_attribute("Line", attrs::mutable_constant<int>(0));

   logging::add_file_log (
    keywords::file_name = "sample.log",
    keywords::format = (
     expr::stream
      << expr::format_date_time<boost::posix_time::ptime>("TimeStamp", "%Y-%m-%d_%H:%M:%S.%f")
      << ": <" << boost::log::trivial::severity << "> "
      << '['   << expr::attr<std::string>("File")
               << ':' << expr::attr<int>("Line") << "] "
      << expr::smessage
    )
   );
   logging::add_common_attributes();
}

int main(int argc, char* argv[]) {
   init();
   src::severity_logger<logging::trivial::severity_level> lg;

   CUSTOM_LOG(lg, debug) << "A regular message";
   return 0;
}

This generate a log like this:

2015-10-15_15:25:12.743153: <debug> [main.cpp:61] A regular message

Solution 3

As user2943014 pointed out, using scopes prints the line number where you opened that scope, not the line number where you emitted a log message using BOOST_LOG_SEV.

You can use attributes to log the line numbers etc at the place you actually logged.

Register global attributes in your logging initialization function:

using namespace boost::log;
core::get()->add_global_attribute("Line", attributes::mutable_constant<int>(5));
core::get()->add_global_attribute("File", attributes::mutable_constant<std::string>(""));
core::get()->add_global_attribute("Function", attributes::mutable_constant<std::string>(""));

Setting these attributes in your logging macro:

#define logInfo(methodname, message)                          \
  LOG_LOCATION;                                               \
  BOOST_LOG_SEV(_log, boost::log::trivial::severity_level::trace) << message

#define LOG_LOCATION                            \
  boost::log::attribute_cast<boost::log::attributes::mutable_constant<int>>(boost::log::core::get()->get_global_attributes()["Line"]).set(__LINE__); \
  boost::log::attribute_cast<boost::log::attributes::mutable_constant<std::string>>(boost::log::core::get()->get_global_attributes()["File"]).set(__FILE__); \
  boost::log::attribute_cast<boost::log::attributes::mutable_constant<std::string>>(boost::log::core::get()->get_global_attributes()["Function"]).set(__func__);

Not exactly beautiful, but it works and it was a long way for me. It's a pity boost doesn't offer this feature out of the box.

Solution 4

Define

namespace attrs = boost::logging::attributes;
namespace expr = boost::logging::expressions;

Add

<< expr::format_named_scope("Scope", keywords::format = "[%f:%l]")

to your keywords::format = (...) in init.

Then add

logging::core::get()->add_global_attribute("Scope", attrs::named_scope());

after add_common_attributes() in main.

Then just before the BOOST_LOG_SEV line add BOOST_LOG_NAMED_SCOPE("whatever").

BOOST_LOG_NAMED_SCOPE("whatever") creates a "scope" named "whatever". The scope is implemented by a unused variable that contains the scope name and the file and the line where the scope was defined.

The format_named_scope line specifies how a scope should be formatted in the log line. %f is the file, %l is the line and %n is the scope name.

Note that the file line that appears in the log record is the line where the macro BOOST_LOG_NAMED_SCOPE appears and not the line of the BOOST_LOG_SEV macro.

I am not aware of simple method to record the file and line without using the BOOST_LOG_NAMED_SCOPE.

View more solutions

Comments

[graywolf]

Possible duplicate of Boost.Log: Support file name and line number

[Jason Harrison]

See also stackoverflow.com/questions/22095667/…

[Pritesh Acharya]

Looks nice to me. Will try this somtime

[bobah]

+1. Looking at how it's implemented - it should work faster if you define attribute type as mutable_constant<boost::log::string_literal> and assign it with boost::log::string_literal(__FILE__) etc., as it will stop allocating / copying strings on each log line.

[Guillermo Ruiz]

Good point. However, __LINE__ is an integer constant and __FILE__ is used to get a substring in this sample. boost::log::string_literal constructs from an array constant like char value[N].

[Guillermo Ruiz]

@Nature.Li has indicated that the code was not thread safe. I changed the global attributes for thread attributes in the code, but I have not tested with several threads.

[unnamed]

@GuillermoRuiz Hi. Could you share the thread safe code? I've also some issues with threads.

[Pranav]

Does it work in multi-threaded code? I'm getting inconsistent line numbers with this solution

[jean]

The thread issue is no relate to add_thread_attribute or add_global_attribute due to this action is an init action, so it generally called in main thread. call add_thread_attribute in init is problematic, that means this attribute only available for main thread. If you want to make this work concurrently, manual add lock to protect "logging::core::get()->get_global_attributes()", it return attribute_set object which belong to logging core which can not be shared by multi thread without an lock

[graywolf]

stackoverflow.com/a/31160870/781743 provides nicer and imho thread-safe solution

[bevis]

I know this is an old thread, but for those coming here from a search, I found (like others) that Guillermo Ruiz solution was not thread safe, but this one does seem to be (using logger_mt etc) , and seems to be much more straightforward.