Commit ecee4ead authored by Dominik Charousset's avatar Dominik Charousset

Fix logger output for class names

parent bfce1cee
...@@ -27,14 +27,15 @@ ...@@ -27,14 +27,15 @@
#include <type_traits> #include <type_traits>
#include <unordered_map> #include <unordered_map>
#include "caf/fwd.hpp"
#include "caf/config.hpp"
#include "caf/unifyn.hpp"
#include "caf/type_nr.hpp"
#include "caf/timestamp.hpp"
#include "caf/ref_counted.hpp"
#include "caf/abstract_actor.hpp" #include "caf/abstract_actor.hpp"
#include "caf/config.hpp"
#include "caf/deep_to_string.hpp" #include "caf/deep_to_string.hpp"
#include "caf/fwd.hpp"
#include "caf/ref_counted.hpp"
#include "caf/string_view.hpp"
#include "caf/timestamp.hpp"
#include "caf/type_nr.hpp"
#include "caf/unifyn.hpp"
#include "caf/intrusive/drr_queue.hpp" #include "caf/intrusive/drr_queue.hpp"
#include "caf/intrusive/fifo_inbox.hpp" #include "caf/intrusive/fifo_inbox.hpp"
...@@ -71,20 +72,24 @@ public: ...@@ -71,20 +72,24 @@ public:
struct event : intrusive::singly_linked<event> { struct event : intrusive::singly_linked<event> {
event() = default; event() = default;
event(int lvl, const char* cat, const char* fun, const char* fn, int line, event(int lvl, string_view cat, string_view full_fun, string_view fun,
std::string msg, std::thread::id t, actor_id a, timestamp ts); string_view fn, int line, std::string msg, std::thread::id t,
actor_id a, timestamp ts);
/// Level/priority of the event. /// Level/priority of the event.
int level; int level;
/// Name of the category (component) logging the event. /// Name of the category (component) logging the event.
const char* category_name; string_view category_name;
/// Name of the current context as reported by `__PRETTY_FUNCTION__`. /// Name of the current function as reported by `__PRETTY_FUNCTION__`.
const char* pretty_fun; string_view pretty_fun;
/// Name of the current function as reported by `__func__`.
string_view simple_fun;
/// Name of the current file. /// Name of the current file.
const char* file_name; string_view file_name;
/// Current line in the file. /// Current line in the file.
int line_number; int line_number;
...@@ -179,6 +184,8 @@ public: ...@@ -179,6 +184,8 @@ public:
line_builder& operator<<(const std::string& str); line_builder& operator<<(const std::string& str);
line_builder& operator<<(string_view str);
line_builder& operator<<(const char* str); line_builder& operator<<(const char* str);
line_builder& operator<<(char x); line_builder& operator<<(char x);
...@@ -206,12 +213,7 @@ public: ...@@ -206,12 +213,7 @@ public:
static logger* current_logger(); static logger* current_logger();
bool accepts(int level, const char* cname_begin, const char* cname_end); bool accepts(int level, string_view cname);
template <size_t N>
bool accepts(int level, const char (&component)[N]) {
return accepts(level, component, component + N - 1);
}
/** @endcond */ /** @endcond */
...@@ -226,10 +228,10 @@ public: ...@@ -226,10 +228,10 @@ public:
} }
/// Renders the prefix (namespace and class) of a fully qualified function. /// Renders the prefix (namespace and class) of a fully qualified function.
static void render_fun_prefix(std::ostream& out, const char* pretty_fun); static void render_fun_prefix(std::ostream& out, const event& x);
/// Renders the name of a fully qualified function. /// Renders the name of a fully qualified function.
static void render_fun_name(std::ostream& out, const char* pretty_fun); static void render_fun_name(std::ostream& out, const event& x);
/// Renders the difference between `t0` and `tn` in milliseconds. /// Renders the difference between `t0` and `tn` in milliseconds.
static void render_time_diff(std::ostream& out, timestamp t0, timestamp tn); static void render_time_diff(std::ostream& out, timestamp t0, timestamp tn);
...@@ -245,7 +247,7 @@ public: ...@@ -245,7 +247,7 @@ public:
static line_format parse_format(const std::string& format_str); static line_format parse_format(const std::string& format_str);
/// Skips path in `filename`. /// Skips path in `filename`.
static const char* skip_path(const char* filename); static string_view skip_path(string_view filename);
/// Returns a string representation of the joined groups of `x` if `x` is an /// Returns a string representation of the joined groups of `x` if `x` is an
/// actor with the `subscriber` mixin. /// actor with the `subscriber` mixin.
...@@ -383,18 +385,23 @@ inline caf::actor_id caf_set_aid_dummy() { return 0; } ...@@ -383,18 +385,23 @@ inline caf::actor_id caf_set_aid_dummy() { return 0; }
#else // CAF_LOG_LEVEL #else // CAF_LOG_LEVEL
#define CAF_LOG_MAKE_EVENT(aid, component, loglvl, message) \
::caf::logger::event { \
loglvl, component, CAF_PRETTY_FUN, __func__, \
caf::logger::skip_path(__FILE__), __LINE__, \
(::caf::logger::line_builder{} << message).get(), \
::std::this_thread::get_id(), aid, ::caf::make_timestamp() \
}
#define CAF_LOG_IMPL(component, loglvl, message) \ #define CAF_LOG_IMPL(component, loglvl, message) \
do { \ do { \
auto CAF_UNIFYN(caf_logger) = caf::logger::current_logger(); \ auto CAF_UNIFYN(caf_logger) = caf::logger::current_logger(); \
if (CAF_UNIFYN(caf_logger) != nullptr \ if (CAF_UNIFYN(caf_logger) != nullptr \
&& CAF_UNIFYN(caf_logger)->accepts(loglvl, component)) \ && CAF_UNIFYN(caf_logger)->accepts(loglvl, component)) \
CAF_UNIFYN(caf_logger) \ CAF_UNIFYN(caf_logger) \
->log(new ::caf::logger::event{ \ ->log( \
loglvl, component, CAF_PRETTY_FUN, caf::logger::skip_path(__FILE__), \ new CAF_LOG_MAKE_EVENT(CAF_UNIFYN(caf_logger)->thread_local_aid(), \
__LINE__, (::caf::logger::line_builder{} << message).get(), \ component, loglvl, message)); \
::std::this_thread::get_id(), \
CAF_UNIFYN(caf_logger)->thread_local_aid(), \
::caf::make_timestamp()}); \
} while (false) } while (false)
#define CAF_PUSH_AID(aarg) \ #define CAF_PUSH_AID(aarg) \
......
...@@ -47,7 +47,7 @@ namespace caf { ...@@ -47,7 +47,7 @@ namespace caf {
namespace { namespace {
constexpr const char* log_level_name[] = { constexpr string_view log_level_name[] = {
"ERROR", "ERROR",
"WARN", "WARN",
"INFO", "INFO",
...@@ -55,6 +55,90 @@ constexpr const char* log_level_name[] = { ...@@ -55,6 +55,90 @@ constexpr const char* log_level_name[] = {
"TRACE" "TRACE"
}; };
constexpr string_view fun_prefixes[] = {
"virtual ",
"static ",
"const ",
"signed ",
"unsigned ",
};
constexpr string_view anon_ns = "(anonymous namespace)";
/// Reduces symbol by printing all prefixes to `out` and returning the
/// remainder. For example, "ns::foo::bar" prints "ns.foo" to `out` and returns
/// "bar".
string_view reduce_symbol(std::ostream& out, string_view symbol) {
string_view last = "";
bool printed = false;
// Prints the content of `last` and then replaces it with `x`.
auto set_last = [&](string_view y) {
if (!last.empty()) {
if (printed)
out << ".";
else
printed = true;
for (auto ch : last)
if (ch == ' ')
out << "%20";
else
out << ch;
}
last = y;
};
size_t pos = 0;
auto advance = [&](size_t n) {
set_last(symbol.substr(0, pos));
symbol.remove_prefix(pos + n);
pos = 0;
};
auto flush = [&] {
advance(1);
// Some compilers put a whitespace after nested templates that we wish to
// ignore here, e.g.,
// foo::tpl<foo::tpl<int> >::fun(int)
// ^
if (last != " ")
set_last("");
};
while (pos < symbol.size()) {
switch (symbol[pos]) {
// A colon can only appear as scope separator, i.e., "::".
case ':':
advance(2);
break;
// This either marks the beginning of the argument list *or* on GCC
// is part of "(anonymous namespace)".
case '(':
if (starts_with(symbol, anon_ns)) {
set_last("$");
// The anonymous namespace is always followed by "::".
symbol.remove_prefix(anon_ns.size() + 2);
pos = 0;
break;
}
// We reached the end of the function name. Print "GLOBAL" if we didn't
// print anything yet as "global namespace".
set_last("");
if (!printed)
out << "GLOBAL";
return symbol;
case '<':
flush();
out << '<';
symbol = reduce_symbol(out, symbol);
break;
case '>':
flush();
out << '>';
return symbol;
default:
++pos;
}
}
return symbol;
}
#if CAF_LOG_LEVEL >= 0 #if CAF_LOG_LEVEL >= 0
#if defined(CAF_NO_THREAD_LOCAL) #if defined(CAF_NO_THREAD_LOCAL)
...@@ -112,12 +196,13 @@ inline logger* get_current_logger() { ...@@ -112,12 +196,13 @@ inline logger* get_current_logger() {
} // namespace <anonymous> } // namespace <anonymous>
logger::event::event(int lvl, const char* cat, const char* fun, const char* fn, logger::event::event(int lvl, string_view cat, string_view full_fun,
int line, std::string msg, std::thread::id t, actor_id a, string_view fun, string_view fn, int line, std::string msg,
timestamp ts) std::thread::id t, actor_id a, timestamp ts)
: level(lvl), : level(lvl),
category_name(cat), category_name(cat),
pretty_fun(fun), pretty_fun(full_fun),
simple_fun(fun),
file_name(fn), file_name(fn),
line_number(line), line_number(line),
message(std::move(msg)), message(std::move(msg)),
...@@ -146,6 +231,13 @@ logger::line_builder& logger::line_builder::operator<<(const std::string& str) { ...@@ -146,6 +231,13 @@ logger::line_builder& logger::line_builder::operator<<(const std::string& str) {
return *this; return *this;
} }
logger::line_builder& logger::line_builder::operator<<(string_view str) {
if (!str_.empty() && str_.back() != ' ')
str_ += " ";
str_.insert(str_.end(), str.begin(), str.end());
return *this;
}
logger::line_builder& logger::line_builder::operator<<(const char* str) { logger::line_builder& logger::line_builder::operator<<(const char* str) {
if (!str_.empty()) if (!str_.empty())
str_ += " "; str_ += " ";
...@@ -211,15 +303,13 @@ logger* logger::current_logger() { ...@@ -211,15 +303,13 @@ logger* logger::current_logger() {
return get_current_logger(); return get_current_logger();
} }
bool logger::accepts(int level, const char* cname_begin, bool logger::accepts(int level, string_view cname) {
const char* cname_end) {
CAF_ASSERT(cname_begin != nullptr && cname_end != nullptr);
CAF_ASSERT(level >= 0 && level <= 4); CAF_ASSERT(level >= 0 && level <= 4);
if (level > max_level_) if (level > max_level_)
return false; return false;
if (!component_filter.empty()) { if (!component_filter.empty()) {
auto it = std::search(component_filter.begin(), component_filter.end(), auto it = std::search(component_filter.begin(), component_filter.end(),
cname_begin, cname_end); cname.begin(), cname.end());
return it != component_filter.end(); return it != component_filter.end();
} }
return true; return true;
...@@ -302,55 +392,60 @@ void logger::init(actor_system_config& cfg) { ...@@ -302,55 +392,60 @@ void logger::init(actor_system_config& cfg) {
#endif #endif
} }
void logger::render_fun_prefix(std::ostream& out, const char* pretty_fun) { void logger::render_fun_prefix(std::ostream& out, const event& x) {
auto first = pretty_fun; // Extract the prefix of a function name. For example:
// set end to beginning of arguments // virtual std::vector<int> my::namespace::foo(int);
const char* last = strchr(pretty_fun, '('); // ^~~~~~~~~~~~~
if (last == nullptr) // Here, we output Java-style "my.namespace" to `out`.
return; auto reduced = x.pretty_fun;
auto strsize = static_cast<size_t>(last - first); // Skip all prefixes that can preceed the return type.
auto jump_to_next_whitespace = [&] { auto skip = [&](string_view str) {
// leave `first` unchanged if no whitespaces is present, if (starts_with(reduced, str)) {
// e.g., in constructor signatures reduced.remove_prefix(str.size());
auto tmp = std::find(first, last, ' '); return true;
if (tmp != last) }
first = tmp + 1; return false;
}; };
// skip "virtual" prefix if present // Remove any type of the return type.
if (strncmp(pretty_fun, "virtual ", std::min<size_t>(strsize, 8)) == 0) while (std::any_of(std::begin(fun_prefixes), std::end(fun_prefixes), skip))
jump_to_next_whitespace(); ; // Repeat.
// skip "static" prefix if present // Skip the return type.
if (strncmp(pretty_fun, "static ", std::min<size_t>(strsize, 7)) == 0) auto skip_return_type = [&] {
jump_to_next_whitespace(); size_t template_nesting = 0;
// skip return type size_t pos = 0;
jump_to_next_whitespace(); for (size_t pos = 0; pos < reduced.size(); ++pos) {
if (first == last) switch (reduced[pos]) {
return; case ' ':
const char sep[] = "::"; // separator for namespaces and classes if (template_nesting == 0) {
auto sep_first = std::begin(sep); // Skip any pointers and references. We need to loop, because each
auto sep_last = sep_first + 2; // using end() includes \0 // pointer/reference can be const-qualified.
auto colons = first; do {
decltype(colons) nextcs; pos = reduced.find_first_not_of(" *&", pos);
while ((nextcs = std::search(colons + 1, last, sep_first, sep_last)) != last) reduced.remove_prefix(pos);
colons = nextcs; pos = 0;
std::string result; } while (skip("const"));
result.assign(first, colons);
detail::prettify_type_name(result);
out << result;
}
void logger::render_fun_name(std::ostream& out, const char* pretty_fun) {
// Find the end of the function name by looking for the opening parenthesis
// trailing it.
CAF_ASSERT(pretty_fun != nullptr);
const char* e = strchr(pretty_fun, '(');
if (e == nullptr)
return; return;
/// Now look for the beginning of the function name. }
using rev_iter = std::reverse_iterator<const char*>; break;
auto b = std::find_if(rev_iter(e), rev_iter(pretty_fun), case '<':
[](char x) { return x == ':' || x == ' '; }); ++template_nesting;
out.write(b.base(), e - b.base()); break;
case '>':
--template_nesting;
break;
default:
break;
}
}
reduced.remove_prefix(pos);
};
skip_return_type();
// We reached the function name itself and can recursively print the prefix.
reduce_symbol(out, reduced);
}
void logger::render_fun_name(std::ostream& out, const event& e) {
out << e.simple_fun;
} }
void logger::render_time_diff(std::ostream& out, timestamp t0, timestamp tn) { void logger::render_time_diff(std::ostream& out, timestamp t0, timestamp tn) {
...@@ -366,12 +461,12 @@ void logger::render(std::ostream& out, const line_format& lf, ...@@ -366,12 +461,12 @@ void logger::render(std::ostream& out, const line_format& lf,
for (auto& f : lf) for (auto& f : lf)
switch (f.kind) { switch (f.kind) {
case category_field: out << x.category_name; break; case category_field: out << x.category_name; break;
case class_name_field: render_fun_prefix(out, x.pretty_fun); break; case class_name_field: render_fun_prefix(out, x); break;
case date_field: render_date(out, x.tstamp); break; case date_field: render_date(out, x.tstamp); break;
case file_field: out << x.file_name; break; case file_field: out << x.file_name; break;
case line_field: out << x.line_number; break; case line_field: out << x.line_number; break;
case message_field: out << x.message; break; case message_field: out << x.message; break;
case method_field: render_fun_name(out, x.pretty_fun); break; case method_field: render_fun_name(out, x); break;
case newline_field: out << std::endl; break; case newline_field: out << std::endl; break;
case priority_field: out << log_level_name[x.level]; break; case priority_field: out << log_level_name[x.level]; break;
case runtime_field: render_time_diff(out, t0_, x.tstamp); break; case runtime_field: render_time_diff(out, t0_, x.tstamp); break;
...@@ -428,9 +523,11 @@ logger::line_format logger::parse_format(const std::string& format_str) { ...@@ -428,9 +523,11 @@ logger::line_format logger::parse_format(const std::string& format_str) {
return res; return res;
} }
const char* logger::skip_path(const char* path) { string_view logger::skip_path(string_view path) {
auto ptr = strrchr(path, '/'); auto find_slash = [&] { return path.find('/'); };
return ptr == nullptr ? path : (ptr + 1); for (auto p = find_slash(); p != string_view::npos; p = find_slash())
path.remove_prefix(p + 1);
return path;
} }
void logger::run() { void logger::run() {
...@@ -509,6 +606,7 @@ void logger::log_first_line() { ...@@ -509,6 +606,7 @@ void logger::log_first_line() {
return {CAF_LOG_LEVEL_INFO, return {CAF_LOG_LEVEL_INFO,
CAF_LOG_COMPONENT, CAF_LOG_COMPONENT,
CAF_PRETTY_FUN, CAF_PRETTY_FUN,
__func__,
__FILE__, __FILE__,
__LINE__, __LINE__,
std::move(msg), std::move(msg),
...@@ -526,6 +624,7 @@ void logger::log_last_line() { ...@@ -526,6 +624,7 @@ void logger::log_last_line() {
event tmp{CAF_LOG_LEVEL_INFO, event tmp{CAF_LOG_LEVEL_INFO,
CAF_LOG_COMPONENT, CAF_LOG_COMPONENT,
CAF_PRETTY_FUN, CAF_PRETTY_FUN,
__func__,
__FILE__, __FILE__,
__LINE__, __LINE__,
"EOF", "EOF",
......
...@@ -27,9 +27,28 @@ ...@@ -27,9 +27,28 @@
#include "caf/all.hpp" #include "caf/all.hpp"
using namespace caf; using namespace caf;
using namespace std;
using namespace std::chrono; using namespace std::chrono;
using std::string;
#define CHECK_FUN_PREFIX(PrefixName) \
do { \
auto e = CAF_LOG_MAKE_EVENT(0, "caf", CAF_LOG_LEVEL_DEBUG, ""); \
std::ostringstream oss; \
::caf::logger::render_fun_prefix(oss, e); \
auto prefix = oss.str(); \
if (prefix != PrefixName) \
CAF_ERROR("rendering the prefix of " << e.pretty_fun << " produced " \
<< prefix << " instead of " \
<< PrefixName); \
else \
CAF_CHECK_EQUAL(prefix, PrefixName); \
} while (false)
void global_fun() {
CHECK_FUN_PREFIX("GLOBAL");
}
namespace { namespace {
struct fixture { struct fixture {
...@@ -48,8 +67,8 @@ struct fixture { ...@@ -48,8 +67,8 @@ struct fixture {
template <class F, class... Ts> template <class F, class... Ts>
string render(F f, Ts&&... xs) { string render(F f, Ts&&... xs) {
ostringstream oss; std::ostringstream oss;
f(oss, forward<Ts>(xs)...); f(oss, std::forward<Ts>(xs)...);
return oss.str(); return oss.str();
} }
...@@ -57,6 +76,52 @@ struct fixture { ...@@ -57,6 +76,52 @@ struct fixture {
logger::line_format lf; logger::line_format lf;
}; };
void fun() {
CHECK_FUN_PREFIX("$");
}
const char* ptr_fun(const char* x) {
CHECK_FUN_PREFIX("$");
return x;
}
const int& ref_fun(const int& x) {
CHECK_FUN_PREFIX("$");
return x;
}
template <class T>
struct tpl {
static void run(std::string t_name) {
CHECK_FUN_PREFIX("$.tpl<" + t_name + ">");
}
};
namespace foo {
void fun() {
CHECK_FUN_PREFIX("$.foo");
}
const char* ptr_fun(const char* x) {
CHECK_FUN_PREFIX("$.foo");
return x;
}
const int& ref_fun(const int& x) {
CHECK_FUN_PREFIX("$.foo");
return x;
}
template <class T>
struct tpl {
static void run(std::string t_name) {
CHECK_FUN_PREFIX("$.foo.tpl<" + t_name + ">");
}
};
} // namespace foo
constexpr const char* file_format = "%r %c %p %a %t %C %M %F:%L %m%n"; constexpr const char* file_format = "%r %c %p %a %t %C %M %F:%L %m%n";
} // namespace <anonymous> } // namespace <anonymous>
...@@ -95,10 +160,6 @@ CAF_TEST(parse_default_format_strings) { ...@@ -95,10 +160,6 @@ CAF_TEST(parse_default_format_strings) {
} }
CAF_TEST(rendering) { CAF_TEST(rendering) {
// Rendering of type names and function names.
const char* foobar = "void ns::foo::bar()";
CAF_CHECK_EQUAL(render(logger::render_fun_name, foobar), "bar");
CAF_CHECK_EQUAL(render(logger::render_fun_prefix, foobar), "ns.foo");
// Rendering of time points. // Rendering of time points.
timestamp t0; timestamp t0;
timestamp t1{timestamp::duration{5000000}}; // epoch + 5000000ns (5ms) timestamp t1{timestamp::duration{5000000}}; // epoch + 5000000ns (5ms)
...@@ -113,13 +174,17 @@ CAF_TEST(rendering) { ...@@ -113,13 +174,17 @@ CAF_TEST(rendering) {
CAF_LOG_LEVEL_WARNING, CAF_LOG_LEVEL_WARNING,
"unit.test", "unit.test",
"void ns::foo::bar()", "void ns::foo::bar()",
"bar",
"foo.cpp", "foo.cpp",
42, 42,
"hello world", "hello world",
this_thread::get_id(), std::this_thread::get_id(),
0, 0,
t0 t0
}; };
CAF_CHECK_EQUAL(render(logger::render_fun_name, e), string_view{"bar"});
CAF_CHECK_EQUAL(render(logger::render_fun_prefix, e),
string_view{"ns.foo"});
// Exclude %r and %t from rendering test because they are nondeterministic. // Exclude %r and %t from rendering test because they are nondeterministic.
actor_system sys{cfg}; actor_system sys{cfg};
auto lf = logger::parse_format("%c %p %a %C %M %F:%L %m"); auto lf = logger::parse_format("%c %p %a %C %M %F:%L %m");
...@@ -130,4 +195,21 @@ CAF_TEST(rendering) { ...@@ -130,4 +195,21 @@ CAF_TEST(rendering) {
"unit.test WARN actor0 ns.foo bar foo.cpp:42 hello world"); "unit.test WARN actor0 ns.foo bar foo.cpp:42 hello world");
} }
CAF_TEST(render_fun_prefix) {
int i = 42;
global_fun();
fun();
ptr_fun(nullptr);
ref_fun(i);
tpl<int>::run("int");
tpl<unsigned int>::run("unsigned%20int");
tpl<tpl<signed char>>::run("$.tpl<signed%20char>");
foo::fun();
foo::ptr_fun(nullptr);
foo::ref_fun(i);
foo::tpl<int>::run("int");
foo::tpl<unsigned int>::run("unsigned%20int");
foo::tpl<foo::tpl<signed char>>::run("$.foo.tpl<signed%20char>");
}
CAF_TEST_FIXTURE_SCOPE_END() CAF_TEST_FIXTURE_SCOPE_END()
Markdown is supported
0%
or
You are about to add 0 people to the discussion. Proceed with caution.
Finish editing this message first!
Please register or to comment