Boost logging, filter by named scope

Question

I am using boost log in my application, and while it has been tricky to configure it is generally working well.

Now however, I would like to add some more advanced filtering logic to my application, and I can't figure it out.

What I would like is to have two "levels" of filtering:

1. I am already using a "severity logger" with different levels like debug, warn, note etc. This is setup and working.
2. I would like to add an additional way to filter records by looking at the "named scope" that the record emanates from.

So I would like for instance to be able to see only the records with severity >= note, AND within a NAMED_SCOPE of monthly.

I have successfully been able to use the BOOST_LOG_NAMED_SCOPE() macro and can see the scope stack in the log messages.

I have tried implementing a custom filter with boost::phoenix, but I can't get it to work.

The code I have pasted here compiles in my application (I am working on stripping this down so I can include a complete working minimal example here), but nothing appears to happen in the my_filter(..) function. I think that I am not correctly passing the scope stack into the bound function, because if I put a std::cout statement within the loop over the scope stack, I do not see anything printed.

Minimal example here:

// Excerpt from MyLogger.cpp class

bool my_filter(attrs::named_scope_list const& scopeList) {
  for (attrs::named_scope_list::const_iterator iter = scopeList.begin(); iter != scopeList.end(); ++iter) {
    if ( (*iter).scope_name == "monthly") {
      return true;
    }
  }
  return false;
}

void setup_logging(std::string lvl) {

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

  logging::add_console_log(
    std::clog,
    keywords::format = (
      expr::stream
        << "[" << severity << "] "
        << "[" << named_scope << "] "
        << expr::smessage
    )
  );

  try {
    // set the severity level...
    EnumParser<severity_level> parser;
    logging::core::get()->set_filter(
      (
        severity >= parser.parseEnum(lvl) &&
        ( expr::has_attr("Scope") && ( boost::phoenix::bind(&my_filter, attrs::named_scope::get_scopes() ) ) )
      )
    );
  } catch (std::runtime_error& e) {
    std::cout << e.what() << std::endl;
    std::cout << "'" << lvl << "' is an invalid --log-level! Must be one of "
              << "[debug, info, note, warn, err, fatal]\n";
    exit(-1);
  }

}

EDIT Updated with minimal working example:

TEMLogger.h

#ifndef _TEMLOGGER_H_
#define _TEMLOGGER_H_

#include <string>
#include <iostream>
#include <sstream>
#include <cstdlib>
#include <exception>
#include <map>
#include <iomanip>

#include <boost/log/core.hpp>
#include <boost/log/trivial.hpp>
#include <boost/log/sources/global_logger_storage.hpp>
#include <boost/log/sources/severity_feature.hpp>
#include <boost/log/sources/severity_logger.hpp>
#include <boost/log/expressions.hpp>
#include <boost/log/utility/setup/console.hpp>

#include <boost/log/attributes/current_process_id.hpp>
#include <boost/log/attributes/scoped_attribute.hpp>


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

/** Define the "severity levels" for Boost::Log's severity logger. */
enum severity_level {
  debug, info, note, warn, err, fatal
};

/** Convert from string to enum integer value.
 *
 * Inspired by: http://stackoverflow.com/questions/726664/string-to-enum-in-c
 */
template <typename T>
class EnumParser {
    std::map <std::string, T> enumMap;
public:
    EnumParser(){};

    T parseEnum(const std::string &value) { 
        typename std::map<std::string, T>::const_iterator iValue = enumMap.find(value);
        if (iValue == enumMap.end())
            throw std::runtime_error("Value not found in enum!");
        return iValue->second;
    }
};


BOOST_LOG_GLOBAL_LOGGER(my_logger, src::severity_logger< severity_level >);

/** Send string representing an enum value to stream 
 */
std::ostream& operator<< (std::ostream& strm, severity_level lvl);

void setup_logging(std::string lvl);

#endif /* _TEMLOGGER_H_ */

TEMLogger.cpp

#include <boost/log/expressions/formatters/named_scope.hpp>
#include <boost/log/expressions.hpp>
#include <boost/phoenix.hpp>

#include "TEMLogger.h"

// Create the global logger object
src::severity_logger< severity_level > glg;

// Add a bunch of attributes to it
BOOST_LOG_ATTRIBUTE_KEYWORD(severity, "Severity", severity_level)
BOOST_LOG_ATTRIBUTE_KEYWORD(named_scope, "Scope", attrs::named_scope::value_type)

/** Initialize the enum parser map from strings to the enum levels.*/
template<>
EnumParser< severity_level >::EnumParser() {
    enumMap["debug"] = debug;
    enumMap["info"] = info;
    enumMap["note"] = note;
    enumMap["warn"] = warn;
    enumMap["err"] = err;
    enumMap["fatal"] = fatal;
}

std::ostream& operator<< (std::ostream& strm, severity_level level) {
    static const char* strings[] = { 
      "debug", "info", "note", "warn", "err", "fatal"
    };

    if (static_cast< std::size_t >(level) < sizeof(strings) / sizeof(*strings))
        strm << strings[level];
    else
        strm << static_cast< int >(level);

    return strm;
}

bool my_filter(boost::log::value_ref< attrs::named_scope > const& theNamedScope) {

  // I think I want something like this:
  // for (attrs::named_scope_list::const_iterator iter = scopeList.begin(); iter != scopeList.end(); ++iter) {
  //   if ( (*iter).scope_name == "monthly"){
  //     return true;
  //   }
  // }
  return true;
}

void setup_logging(std::string lvl) {

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

  logging::add_console_log(
    std::clog,
    keywords::format = (
      expr::stream
        << "[" << severity << "] "
        << "[" << named_scope << "] "
        << expr::smessage
    )
  );

  try {
    // set the severity level...
    EnumParser<severity_level> parser;
    logging::core::get()->set_filter(
      (
        severity >= parser.parseEnum(lvl) &&
        ( expr::has_attr("Scope") && ( boost::phoenix::bind(&my_filter, expr::attr< attrs::named_scope >("Scope").or_none()) ) )
      )
    );
  } catch (std::runtime_error& e) {
    std::cout << e.what() << std::endl;
    std::cout << "'" << lvl << "' is an invalid --log-level! Must be one of "
              << "[debug, info, note, warn, err, fatal]\n";
    exit(-1);
  }

}

Main Program

#include "TEMLogger.h"

extern src::severity_logger< severity_level > glg;

void func1() {
  BOOST_LOG_NAMED_SCOPE("monthly");
  for (int i=0; i<5; ++i) {
    BOOST_LOG_SEV(glg, note) << "doing iteration " << i << "within monthly scope!";
  }

}

int main(int argc, char* argv[]) {

  std::cout << "Setting up logging...\n";

  setup_logging("debug");

  BOOST_LOG_SEV(glg, note) << "Some message in the main scope";

  func1();

  BOOST_LOG_SEV(glg, note) << "Another message in the main scope";

  return 0;
}

Compile

(I am on a Mac, and due to the way I installed Boost I have to specify the compiler, and the method of linking the Boost libs. YMMV)

g++-4.8 -o TEMLogger.o -c -g -DBOOST_ALL_DYN_LINK TEMLogger.cpp
g++-4.8 -o log-filter-example.o -c -g -DBOOST_ALL_DYN_LINK log-filter-example.cpp
g++-4.8 -o a.out log-filter-example.o TEMLogger.o -L/usr/local/lib -lboost_system-mt -lboost_filesystem-mt -lboost_thread-mt -lboost_log-mt

Run

$ ./a.out 
Setting up logging...
[note] [] Some message in the main scope
[note] [monthly] doing iteration 0within monthly scope!
[note] [monthly] doing iteration 1within monthly scope!
[note] [monthly] doing iteration 2within monthly scope!
[note] [monthly] doing iteration 3within monthly scope!
[note] [monthly] doing iteration 4within monthly scope!
[note] [] Another message in the main scope

Answer 1

Analysis

Your problems lie in how you use phoenix::bind to create the filtering expression.

boost::phoenix::bind(&my_filter
    , attrs::named_scope::get_scopes())

The way it's written, it will bind to the value returned by get_scopes() at the time of binding. Instead, we want lazy evaluation, which will happen just before the my_filter function is invoked for each message. This is accomplished by boost::log::expressions::attribute_actor, which we can create using boost::log::expressions::attr(...)

boost::phoenix::bind(&my_filter
    , expr::attr<attrs::named_scope>("Scope").or_none())

---

The next issue lies in boost::log::attributes::named_scope. As the documentation says

The basic_named_scope attribute is essentially a hook to the thread-specific instance of scope list.

Instead of this dummy attribute, we're actually interested in extracting the current scope stack for the given message. According to the value_type, this is an instance of boost::log::attributes::named_scope_list. Hence, we should change the code to

boost::phoenix::bind(&my_filter
    , expr::attr<attrs::named_scope_list>("Scope").or_none())

and also adjust the signature of my_filter(...) to match:

bool my_filter(boost::log::value_ref<attrs::named_scope_list> const& scopes)

---

Now, since we're using .or_none() to create the attribute_actor, we can drop from our filter expression the check for existence of attribute "Scope"

expr::has_attr("Scope") // This goes away

and do this test in our filter function instead

if (!scopes.empty()) { // ...
} else { return false; }

---

Finally, we should probably have a way to configure the scope we want to filter. So, let's add a parameter to the filter function:

bool my_filter(boost::log::value_ref<attrs::named_scope_list> const& scopes
    , std::string const& target_scope)
{ // ...
}

And bind it to the desired value

std::string target_scope("scope_2"); // Or read from config

// .....
    (boost::phoenix::bind(&my_filter
        , expr::attr<attrs::named_scope_list>("Scope").or_none()
        , target_scope)) 

---

Sample Code

Includes, type definitions:

#include <boost/log/core.hpp>
#include <boost/log/trivial.hpp>

#include <boost/log/utility/setup/console.hpp>
#include <boost/log/utility/setup/common_attributes.hpp>

// NB: The following two are just convenience
// Reduce them to just the headers needed to reduce compile time
#include <boost/log/attributes.hpp>
#include <boost/log/expressions.hpp>

#include <boost/phoenix.hpp>
// ============================================================================
namespace bl = boost::log;
// ----------------------------------------------------------------------------
typedef bl::sources::severity_logger <bl::trivial::severity_level> logger_t;
typedef bl::trivial::severity_level log_level;
// ----------------------------------------------------------------------------
BOOST_LOG_ATTRIBUTE_KEYWORD(my_named_scope, "Scope", bl::attributes::named_scope::value_type)
// ============================================================================

The filter function:

// ============================================================================
bool my_filter(bl::value_ref<bl::attributes::named_scope_list> const& scopes
    , std::string const& target_scope)
{
    bool matched(false);
    if (!scopes.empty()) {
        for (auto& scope : scopes.get()) {
            if (scope.scope_name == target_scope) {
                matched = matched || true; // Any scope name matches...
            }
        }
    }
    return matched;
}
// ============================================================================

Logger initialization:

// ============================================================================
void init_logging()
{
    bl::core::get()->add_global_attribute(
        "Scope", bl::attributes::named_scope()
        );

    bl::add_console_log(std::clog
        , bl::keywords::format = (
            bl::expressions::stream
                << "[" << bl::trivial::severity << "] "
                << "[" << my_named_scope << "] "
                // Alternative way to format this:
                // << bl::expressions::format_named_scope("Scope", bl::keywords::format = "[%n] ")
                << bl::expressions::smessage
        ));

    // Hard-coded, determine this as appropriate from config
    log_level target_severity(log_level::info);
    std::string target_scope("scope_2");

    bl::core::get()->set_filter(
        (bl::trivial::severity >= target_severity)
        &&  (boost::phoenix::bind(&my_filter
            , bl::expressions::attr<bl::attributes::named_scope_list>("Scope").or_none()
            , target_scope)) 
        );
}
// ============================================================================

Finally testing it:

// ============================================================================
void log_it(logger_t& log, int n)
{
    BOOST_LOG_SEV(log, log_level::debug) << "A" << n;
    BOOST_LOG_SEV(log, log_level::trace) << "B" << n;
    BOOST_LOG_SEV(log, log_level::info) << "C" << n;
    BOOST_LOG_SEV(log, log_level::warning) << "D" << n;
    BOOST_LOG_SEV(log, log_level::error) << "E" << n;
    BOOST_LOG_SEV(log, log_level::fatal) << "F" << n;
}
// ============================================================================
int main()
{
    init_logging();

    logger_t log;

    log_it(log, 1);
    {
        BOOST_LOG_NAMED_SCOPE("scope_1");
        log_it(log, 2);
    }
    {
        BOOST_LOG_NAMED_SCOPE("scope_2");
        log_it(log, 3);
        {
            BOOST_LOG_NAMED_SCOPE("scope_3");
            log_it(log, 4);
        }
        log_it(log, 5);
    }

    return 0;
}
// ============================================================================

---

Test Run

Output without filtering:

[debug] [] A1
[trace] [] B1
[info] [] C1
[warning] [] D1
[error] [] E1
[fatal] [] F1
[debug] [scope_1] A2
[trace] [scope_1] B2
[info] [scope_1] C2
[warning] [scope_1] D2
[error] [scope_1] E2
[fatal] [scope_1] F2
[debug] [scope_2] A3
[trace] [scope_2] B3
[info] [scope_2] C3
[warning] [scope_2] D3
[error] [scope_2] E3
[fatal] [scope_2] F3
[debug] [scope_2->scope_3] A4
[trace] [scope_2->scope_3] B4
[info] [scope_2->scope_3] C4
[warning] [scope_2->scope_3] D4
[error] [scope_2->scope_3] E4
[fatal] [scope_2->scope_3] F4
[debug] [scope_2] A5
[trace] [scope_2] B5
[info] [scope_2] C5
[warning] [scope_2] D5
[error] [scope_2] E5
[fatal] [scope_2] F5

Output with filtering (as in sample code, only info level and higher, and only those with some scope named "scope_2"):

[info] [scope_2] C3
[warning] [scope_2] D3
[error] [scope_2] E3
[fatal] [scope_2] F3
[info] [scope_2->scope_3] C4
[warning] [scope_2->scope_3] D4
[error] [scope_2->scope_3] E4
[fatal] [scope_2->scope_3] F4
[info] [scope_2] C5
[warning] [scope_2] D5
[error] [scope_2] E5
[fatal] [scope_2] F5