Formater Factory for __LINE__ and __FILE__

[Anonymous]

Using post #11 of http://sourceforge.net/projects/boost-log/forums/forum/710022/topic/3604044 as my guide, I thought I would go about adding __LINE__ and __FILE__ to my logs (A useful feature indeed). I had already been using named scopes with the severity logger to give us a better view at critical log entries. As such I added a new attribute (FileAndLine) identical to my previous Scope Attribute.

While it compiles and runs, it seems to skip the custom formatter completely, and instead I end up with two copies of the scope attribute. I compared my code to http://boost-log.sourceforge.net/libs/log/doc/html/log/extension/settings.html#log.extension.settings.adding_support_for_user_defined_types_to_the_formatter_parser but I cannot seem to find the missing piece. Given the amount of time I have spent going nowhere, I am willing to bet that I am merely overlooking something simple and need an outside voice. Thank you for your help in advance.

The code is in a header-only file to make it easier for me to use in multiple projects. I have included what I believe to be the relevant parts here:

namespace fmt       = boost::log::formatters;
namespace flt       = boost::log::filters;
namespace sinks     = boost::log::sinks;
namespace attrs     = boost::log::attributes;
namespace keywords  = boost::log::keywords;
namespace logging {
//Helper type for member functions (Less Typing)
typedef boost::log::formatter_types< char > types;
//Formatting Logic for Scope (Filename and Line number)
struct FileAndLineFormatter
{
  typedef void result_type;
  typedef boost::log::attributes::basic_named_scope< char >::scope_stack scope_stack;
  explicit FileAndLineFormatter(std::string const& name) : name_(name) {}
  void operator() (std::ostream& strm, boost::log::record const& rec) const {
    boost::log::extract< scope_stack >(name_, rec.attribute_values(), bind(&FileAndLineFormatter::format, boost::ref(strm), _1));
  }
private:
  static void format(std::ostream& strm, scope_stack const& scopes) {
    scope_stack::const_iterator it = scopes.begin(), end = scopes.end();
    for (; it != end; ++it) {
      strm << "[" << it->file_name << ":" << it->line << "]";
    }
  }
private:
  std::string name_;
};
//Formatter Factory
inline types::formatter_type scope_formatter_factory(types::string_type const& a_attr_name, types::formatter_factory_args const& a_args) {
  BOOST_LOG_NO_UNUSED_WARNINGS(a_args);
  return types::formatter_type(logging::FileAndLineFormatter(a_attr_name));
}
//Function which gets called by main
inline void initLog(std::string a_logfile,int a_logLevel) {
  //Add attributes
  boost::log::core::get()->add_global_attribute("ProcessID", boost::make_shared< attrs::current_process_id >());
  boost::log::core::get()->add_global_attribute("ThreadID", boost::make_shared< attrs::current_thread_id >());
  boost::log::core::get()->add_global_attribute("Scope", boost::make_shared< attrs::named_scope >());
  boost::log::core::get()->add_global_attribute("FileAndLine", boost::make_shared< attrs::named_scope >());
  boost::log::add_common_attributes();
  boost::log::register_formatter_factory("FileAndLine", &logging::scope_formatter_factory);
  boost::log::init_log_to_file  (
    keywords::auto_flush = true,
    keywords::file_name = a_logfile,
    keywords::filter = \
      flt::attr< severity_level_enum >("Severity", std::nothrow) >= a_logLevel,
    keywords::format = (fmt::stream
      << "["
      << fmt::attr< severity_level_enum >(
           "Severity",
           keywords::format = "%-13x"
         )
      << "]"
      << fmt::date_time("TimeStamp", std::nothrow) << "|"
      << fmt::named_scope("FileAndLine") << "|"
      << fmt::if_ (
          flt::attr< severity_level_enum >("Severity", std::nothrow) >= error
         ) [
            fmt::named_scope("Scope", keywords::iteration = fmt::forward)
         ]
      << ": "
      << fmt::message()
      )
  );
}
} // namespace logging {

[Anonymous]

As an additional note, I thought perhaps I ought to replace

fmt::named_scope("FileAndLine")

with

logging::FileAndLineFormatter("FileAndLine")

But that leaves me with the following compile-time error:

boost/log/formatters/wrappers.hpp:74: error: no match for 'operator<<' in 'strm << ((const boost::log_mt_posix::formatters::fmt_wrapper<char, logging::FileAndLineFormatter>*)this)->boost::log_mt_posix::formatters::fmt_wrapper<char, logging::FileAndLineFormatter>::m_T'

[Andrey Semashev]

In the first code snippet, you didn't use FileAndLineFormatter in the formatting expression. The  register_formatter_factory function call registers the factory to be used when formatter is parsed from a string (like when loading from a settings file) and this is not the case. That's why FileAndLineFormatter is not used.

When you use FileAndLineFormatter in the formatter expression the compilation fails because it doesn't derive from basic_formatter class template. The library interprets it as an object to be output when formatting a record and it doesn't have operator<<.

[Anonymous]

Ah, of course. That makes sense.  When I first set the logger up, I was using configuration files and only recently switched. Thank you for pointing that out.

For those who read this thread in the future and want an explicit answer, the updated (and now working) code is included below:

namespace fmt       = boost::log::formatters;
namespace flt       = boost::log::filters;
namespace sinks     = boost::log::sinks;
namespace attrs     = boost::log::attributes;
namespace keywords  = boost::log::keywords;
namespace logging {
//Helper type for member functions (Less Typing)
typedef boost::log::formatter_types< char > types;
//Formatting Logic for Scope (Filename and Line number)
//template<typename CharT, typename DerivedT>
struct FileAndLineFormatter :
    public boost::log::formatters::basic_formatter<std::string, std::string> {
  typedef void result_type;
  typedef boost::log::attributes::basic_named_scope< char >::scope_stack
      scope_stack;
  explicit FileAndLineFormatter(std::string const& name) : name_(name) {}
  void operator() (std::ostream& strm, boost::log::record const& rec) const {
    boost::log::extract< scope_stack >(
      name_,
      rec.attribute_values(),
      bind(
        &FileAndLineFormatter::format, boost::ref(strm),
        _1
      )
    );
  }
private:
  static void format(std::ostream& strm, scope_stack const& scopes) {
    strm << "[" << scopes.back().file_name << ":" << scopes.back().line << "]";
  }
private:
  std::string name_;
};
//Function which gets called by main
inline void initLog(std::string a_logfile,int a_logLevel) {
  //Add attributes
  boost::log::core::get()->add_global_attribute("ProcessID", boost::make_shared< attrs::current_process_id >());
  boost::log::core::get()->add_global_attribute("ThreadID", boost::make_shared< attrs::current_thread_id >());
  boost::log::core::get()->add_global_attribute("Scope", boost::make_shared< attrs::named_scope >());
  boost::log::core::get()->add_global_attribute("FileAndLine", boost::make_shared< attrs::named_scope >());
  boost::log::add_common_attributes();
  boost::log::register_formatter_factory("FileAndLine", &logging::scope_formatter_factory);
  boost::log::init_log_to_file  (
    keywords::auto_flush = true,
    keywords::file_name = a_logfile,
    keywords::filter = \
      flt::attr< severity_level_enum >("Severity", std::nothrow) >= a_logLevel,
    keywords::format = (fmt::stream
      << "["
      << fmt::attr< severity_level_enum >(
           "Severity",
           keywords::format = "%-13x"
         )
      << "]"
      << fmt::date_time("TimeStamp", std::nothrow) << "|"
      << logging::FileAndLineFormatter("FileAndLine") << "|"
      << fmt::if_ (
          flt::attr< severity_level_enum >("Severity", std::nothrow) >= error
         ) [
            fmt::named_scope("Scope", keywords::iteration = fmt::forward)
         ]
      << ": "
      << fmt::message()
      )
  );
}
} // namespace logging {

[Andrey Semashev]

That should have been basic_formatter<char, FileAndLineFormatter>.

[shahes]

Is it possible to get a working solution posted for this question?

I have a similar issue and cannot get the formatter to compile when used as an expression.

template<typename CharT>
class SuperCustomFormatter : public boost::log::formatter::basic_formatter<CharT>
{
public:
    explicit SuperCustomFormatter(boost::log::attribute_name const& name)
        : name(name)
    {}

    void operator()(boost::log::formatting_ostream& strm, boost::log::value_ref< SuperCustomObject > const& value) const
    {
        if (value)
        {
            format(strm);
        }        
    }

private:
    boost::log::attribute_name name;
    static void format(boost::log::formatting_ostream& strm) {
        strm << SuperCustomObject Image String;
    }
};

I would like to use this syntax :

keywords::format = ( expr::stream << ????? );

but cannot figure out what replaces '????'.

I have a format factory for this object. Using the string formatter syntax '%MySuperCustomObject% works.
But I would prefer to use the formatter expression syntax.

Using Boost version 1.79.

[Andrey Semashev]

First, you don't derive from basic_formatter. It is not a base class but a wrapper that erases the type of the actual formatter, a-la std::function with a fixed signature.

Next, there are multiple ways to integrate with formatting expressions, but ultimately what you need to do is to turn your formatter function into a Boost.Phoenix terminal. One easy way to do this is to use wrap_formatter:

template<typename CharT>
class SuperCustomFormatter
{
public:
    //! Formatter character type. This will help wrap_formatter type deduction.
    typedef CharT char_type;

    //! Formatter implementation here
    void operator()(record_view const& rec, basic_formatting_ostream< char_type >& strm) const;
};

sink->set_formatter(expr::stream << expr::wrap_formatter(SuperCustomFormatter<char>()));

[shahes]

Thank you. I was able to get the expr::wrap_formatter to work.

[shahes]

Hi, is using the expr::wrap_formatter in multi-threaded log (boost::log::sources::severity_logger_mt) thread safe?

I am running the clang thread sanitizer (https://clang.llvm.org/docs/ThreadSanitizer.html) and getting many data race conditions reported.

Thanks

[Andrey Semashev]

Hi, is using the expr::wrap_formatter in multi-threaded log (boost::log::sources::severity_logger_mt) thread safe?

Yes, meaning that wrap_formatter itself does not introduce data races as it doesn't modify any shared data. The wrapped function though is not protected from concurrent calls.

[shahes]

Andrey, can I get your opinion on a post I saw. Is this an OK idea or a bad idea. It's along the lines of this conversation of how to get file information into the log and it needs to be available for filtering records to boost::log::add_value will not work.

From post:
https://stackoverflow.com/questions/24750218/boost-log-to-print-source-code-file-name-and-line-number

// 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();
}

Thanks in advance for your input.

[Andrey Semashev]

I don't think this is a good idea because you are copying thread-specific attributes and searching for the attribute - twice - per every log record being made. Copying an attribute set involves one or more memory allocations, depending on the number of attributes.

Furthermore, passing the result of set_get_attrib to BOOST_LOG_STREAM_WITH_PARAMS is not intended to work. The list is supposed to be a list of named parameters that is composed onto named parameters pack that is then consumed by open_record method of the logger. Since set_get_attrib returns just an attribute value, and there isn't an operator, overload that takes the value and a named parameter, the built-in operator, discards the attribute value. This will break if such an operator appears in Boost.Parameter in the future (and such an extension would be reasonable since, as I said, you are not supposed to mix named parameters and other random values in the comma-separated parameter list).

[shahes]

Ok, I thought it was going to be a bad idea.

Do you have a suggestion on how to get FILE for every place the logger is called, so it can participate in filtering?

For every "BOOST_LOG_SEV(logger, severity) << msg;" statement in the code we need FILE so we can filter on filename and severity. This needs to be the exact location of the log message so scoping variables will not work.

This is an ongoing question for the logger that no one seems to have a good solution for. Any help is greatly appreciated.

[Andrey Semashev]

I answered it here. Since you need filtering, option 3 fits your case.

One other option is to define a new logger feature that will manage the file and line attributes. This would have better performance since the attributes wouldn't be added/removed on every log record. But this would still require defining a new logging macro since this is the only way to use __FILE__ and __LINE__ macros. You can read about creating logger features here.

[shahes]

Thank you. I missed that post and option 3.

I do have a concern about using BOOST_LOG_SCOPED_LOGGER_ATTR.

I currently use this for setting a TAG field but get get thread sanitizer data race errors.

I'm using "boost::log::sources::severity_logger_mt<>".

I do the following in a few different places.
BOOST_LOG_SCOPED_LOGGER_TAG(lg, "Tag", "some-tag-message");

I then run a multi-threaded test program using the clang thread sanitizer and get a data race on the Tag output.

            expr::stream
                << expr::format_date_time< boost::posix_time::ptime >("TimeStamp", "%Y-%m-%d %H:%M:%S.%f")
                << " " << expr::attr< attributes::current_thread_id::value_type >("ThreadID")
                << " " << expr::attr<LogSeverity>("Severity")               
                << ": " << expr::smessage
                << expr::if_(expr::has_attr("Tag"))
                    [
                        expr::stream << expr::attr< std::string >("Tag") << "]"
                    ]

WARNING: ThreadSanitizer: data race on vptr (ctor/dtor vs virtual call) (pid=67616)
  Write of size 8 at 0x7b0c000034b0 by main thread (mutexes: write M0):
    #0 boost::log::v2_mt_posix::attributes::attribute_value_impl<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > >::~attribute_value_impl() /usr/local/include/boost/log/attributes/attribute_value_impl.hpp:49:7 (testest+0x132ed2) (BuildId: 5df16d3684d1ba30e432491165c4f10c1fbe41e6)
    #1 boost::log::v2_mt_posix::attributes::constant<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > >::impl::~impl() /usr/local/include/boost/log/attributes/constant.hpp:56:32 (testest+0x132ed2)
    #2 boost::log::v2_mt_posix::attribute_set::erase(boost::log::v2_mt_posix::attribute_set::iter<false>) <null> (libboost_log.so.1.77.0+0x3faa5) (BuildId: 8c6f2c31c8238584281c5aa5bbe7b7508bac72f8)
    #3 boost::detail::function::void_function_invoker0<void (*)(), void>::invoke(boost::detail::function::function_buffer&) /usr/local/include/boost/function/function_template.hpp:117:11 (testest+0x137387) (BuildId: 5df16d3684d1ba30e432491165c4f10c1fbe41e6)
    #4 boost::detail::function::function_obj_invoker0<boost::detail::forward, int>::invoke(boost::detail::function::function_buffer&) crtstuff.c (libboost_unit_test_framework.so.1.77.0+0x342a1) (BuildId: 5f6ef147390dd404c824319b92378d46562c0f9c)
    #5 __libc_start_call_main csu/../sysdeps/nptl/libc_start_call_main.h:58:16 (libc.so.6+0x29d8f) (BuildId: 89c3cb85f9e55046776471fed05ec441581d1969)

Is this a known issue? Is there a way to work around it?

Thanks

[Andrey Semashev]

This is off-topic but BOOST_LOG_SCOPED_LOGGER_TAG does not introduce a data race if used with a multi-threaded logger. The backtrace makes no sense to me as Boost.Log doesn't use Boost.Function. Looks like TSan is triggering a race on the virtual function table pointer. This can happen if your code is destroying the attribute while a method is being called on it.

[Andrey Semashev]

I just noticed that the backtrace mentions Boost.Test. AFAIK, Boost.Test is not thread-safe, it should not be used from multiple threads.

[shahes]

The test is multi-threaded but it does not use any of the BOOST macros in any of the threads except the main thread. AFAIK it is the BOOST macros that are not thread safe. Only calls to BOOST_LOG_SCOPED_LOGGER_TAG and BOOST_LOG_SEV(logger, severity) << msg are made in the threads. It's the call to expr::stream << expr::attr< std::string >("Tag") that causes the data race. I don't see how the code could be destroying the Tag attribute while some place else is updating it. The Tag attribute for this test is only set in 2 places.

[shahes]

I'm wondering if we do not have the logger setup correctly to support a multithreaded environment.

Logging.hpp:

BOOST_LOG_GLOBAL_LOGGER(boostLogger, boost::log::sources::severity_logger_mt<LogSeverity>)

Logging.cpp:

BOOST_LOG_GLOBAL_LOGGER_INIT(boostLogger, boost::log::sources::severity_logger_mt<LogSeverity>)
{
    using LoggerType = boost::log::sources::severity_logger_mt<LogSeverity>;
    LoggerType logger;

    boost::log::add_file_log(
        keywords::file_name = fileName,
        keywords::auto_flush = true,
        keywords::open_mode = std::ios_base::app,
        keywords::format =
        (
            expr::stream
                << expr::format_date_time< boost::posix_time::ptime >("TimeStamp", "%Y-%m-%d %H:%M:%S.%f")
                << " " << expr::attr< attributes::current_thread_id::value_type >("ThreadID")
                << " " << expr::attr<LogSeverity>("Severity")
                << " " << expr::smessage
                << expr::if_(expr::has_attr("Tag"))
                    [
                        expr::stream << " [TAG: " << expr::attr< std::string >("Tag") << "]"
                    ]
        )
     );

    boost::log::add_common_attributes();
    return logger;
}

---

Usage:

BOOST_LOG_SCOPED_LOGGER_TAG(boostLogger::get(), "Tag", "sometagmessage");

BOOST_LOG_SCOPED_LOGGER_TAG is called on the main thread and one other thread.

---

Usage:
BOOST_LOG_SEV(boostLogger::get(), sev) << msg;

This is called in many different threads.

---

After multiple executions of the code, we always encounter a data race on:
expr::stream << " [TAG: " << expr::attr< std::string >("Tag") << "]"

[Andrey Semashev]

Do not initialize anything but the logger itself in the global logger initializer. It is not guaranteed that the initializer is only run once.

[shahes]

Hi, to show the data race I modified the following example program:
boost_1_77_0/libs/log/example/advanced_usage/main.cpp

I added the following functions:

void f1(int n, src::severity_logger_mt<severity_level>& slg)
{
    for (int i = 0; i < 25; ++i) {
        BOOST_LOG_SEV(slg, error) << "Thread 1 executing " << i;
        ++n;
        std::this_thread::sleep_for(std::chrono::milliseconds(10));
    }
}

void f2(int& n, src::severity_logger_mt<severity_level>& slg)
{
    BOOST_LOG_SCOPED_LOGGER_TAG(slg, "Tag", "Tagged f2 ");
    for (int i = 0; i < 25; ++i) {
        BOOST_LOG_SEV(slg, error) << "Thread 2 executing " << i;
        ++n;
        std::this_thread::sleep_for(std::chrono::milliseconds(10));
    }
}

At the end of main.cpp, before the call to pSink->reset_filter(), I added the following code.

    int n = 0;
    std::thread t2(f1, n + 1, std::ref(slg));
    std::thread t3(f2, std::ref(n), std::ref(slg));

    t2.join();
    t3.join();

Compile with clang 14 and the thread sanitizer enabled on Ubuntu 22.04.

Run the program a few times and you should encounter the data race.

SUMMARY: ThreadSanitizer: data race on vptr (ctor/dtor vs virtual call) /usr/local/include/boost/log/attributes/attribute_value_impl.hpp:49:7 in boost::log::v2_mt_posix::attributes::attribute_value_impl<std::__cxx11::basic_string\<char, std::char_traits\<char="">, std::allocator\<char> > >::~attribute_value_impl()</char></std::__cxx11::basic_string\<char,>

[Andrey Semashev]

I also had to change slg to severity_logger_mt. I cannot reproduce this on the current develop branch on my Ubuntu 22.04 and clang 14.

Also, please don't post off-topic in this thread. This discussion is about __FILE__ and __LINE__ formatting.

[shahes]

Sorry about the off topic post, but it did relate to an earlier post about using the wrap_formatter and getting a race condition. I upgraded to 1.80 and still can reproduce the data race using log/example/advanced_usage/main.cpp with some minor modifications described above.

[Andrey Semashev]

Did you build Boost with TSan? What compiler flags did you use? What exact source code, with everything irrelevant removed, reproduces it? Please post in another thread.