Commit 3fc7be40 authored by Dominik Charousset's avatar Dominik Charousset

Fix initialization bug in logger

parent 47f9a907
...@@ -17,3 +17,4 @@ libcaf_core/caf/detail/build_config.hpp ...@@ -17,3 +17,4 @@ libcaf_core/caf/detail/build_config.hpp
blog_release_note.md blog_release_note.md
github_release_note.md github_release_note.md
.make-release-steps.bash .make-release-steps.bash
*.swo
...@@ -496,7 +496,6 @@ private: ...@@ -496,7 +496,6 @@ private:
CAF_SET_LOGGER_SYS(this); CAF_SET_LOGGER_SYS(this);
auto res = make_actor<C>(next_actor_id(), node(), this, auto res = make_actor<C>(next_actor_id(), node(), this,
cfg, std::forward<Ts>(xs)...); cfg, std::forward<Ts>(xs)...);
CAF_PUSH_AID(res->id());
auto ptr = static_cast<C*>(actor_cast<abstract_actor*>(res)); auto ptr = static_cast<C*>(actor_cast<abstract_actor*>(res));
ptr->launch(cfg.host, has_lazy_init_flag(Os), has_hide_flag(Os)); ptr->launch(cfg.host, has_lazy_init_flag(Os), has_hide_flag(Os));
return res; return res;
......
...@@ -31,11 +31,11 @@ ...@@ -31,11 +31,11 @@
#include "caf/fwd.hpp" #include "caf/fwd.hpp"
#include "caf/config.hpp" #include "caf/config.hpp"
#include "caf/unifyn.hpp" #include "caf/unifyn.hpp"
#include "caf/type_nr.hpp"
#include "caf/ref_counted.hpp" #include "caf/ref_counted.hpp"
#include "caf/abstract_actor.hpp" #include "caf/abstract_actor.hpp"
#include "caf/deep_to_string.hpp" #include "caf/deep_to_string.hpp"
#include "caf/type_nr.hpp"
#include "caf/detail/scope_guard.hpp" #include "caf/detail/scope_guard.hpp"
#include "caf/detail/shared_spinlock.hpp" #include "caf/detail/shared_spinlock.hpp"
#include "caf/detail/single_reader_queue.hpp" #include "caf/detail/single_reader_queue.hpp"
...@@ -163,6 +163,8 @@ public: ...@@ -163,6 +163,8 @@ public:
private: private:
logger(actor_system& sys); logger(actor_system& sys);
void init(actor_system_config& cfg);
void run(); void run();
void start(); void start();
...@@ -171,7 +173,8 @@ private: ...@@ -171,7 +173,8 @@ private:
void log_prefix(std::ostream& out, int level, const char* component, void log_prefix(std::ostream& out, int level, const char* component,
const std::string& class_name, const char* function_name, const std::string& class_name, const char* function_name,
const char* file_name, int line_num); const char* file_name, int line_num,
const std::thread::id& tid = std::this_thread::get_id());
actor_system& system_; actor_system& system_;
int level_; int level_;
...@@ -181,6 +184,7 @@ private: ...@@ -181,6 +184,7 @@ private:
std::mutex queue_mtx_; std::mutex queue_mtx_;
std::condition_variable queue_cv_; std::condition_variable queue_cv_;
detail::single_reader_queue<event> queue_; detail::single_reader_queue<event> queue_;
std::thread::id parent_thread_;
}; };
} // namespace caf } // namespace caf
...@@ -331,9 +335,8 @@ inline caf::actor_id caf_set_aid_dummy() { return 0; } ...@@ -331,9 +335,8 @@ inline caf::actor_id caf_set_aid_dummy() { return 0; }
CAF_LOG_DEBUG("SPAWN ; ID =" << aid \ CAF_LOG_DEBUG("SPAWN ; ID =" << aid \
<< "; ARGS =" << deep_to_string(aargs).c_str()) << "; ARGS =" << deep_to_string(aargs).c_str())
#define CAF_LOG_INIT_EVENT(aName, aLazy, aHide) \ #define CAF_LOG_INIT_EVENT(aName, aHide) \
CAF_LOG_DEBUG("INIT ; NAME =" << aName << "; LAZY =" << aLazy \ CAF_LOG_DEBUG("INIT ; NAME =" << aName << "; HIDDEN =" << aHide)
<< "; HIDDEN =" << aHide)
/// Logs /// Logs
#define CAF_LOG_SEND_EVENT(ptr) \ #define CAF_LOG_SEND_EVENT(ptr) \
......
...@@ -77,6 +77,7 @@ public: ...@@ -77,6 +77,7 @@ public:
CAF_LOG_DEBUG("make_behavior() did return a valid behavior"); CAF_LOG_DEBUG("make_behavior() did return a valid behavior");
this->do_become(std::move(bhvr.unbox()), true); this->do_become(std::move(bhvr.unbox()), true);
} }
super::initialize();
} }
protected: protected:
......
...@@ -245,6 +245,7 @@ actor_system::actor_system(actor_system_config& cfg) ...@@ -245,6 +245,7 @@ actor_system::actor_system(actor_system_config& cfg)
} }
// initialize state for each module and give each module the opportunity // initialize state for each module and give each module the opportunity
// to influence the system configuration, e.g., by adding more types // to influence the system configuration, e.g., by adding more types
logger_->init(cfg);
for (auto& mod : modules_) for (auto& mod : modules_)
if (mod) if (mod)
mod->init(cfg); mod->init(cfg);
......
...@@ -82,7 +82,6 @@ const char* blocking_actor::name() const { ...@@ -82,7 +82,6 @@ const char* blocking_actor::name() const {
} }
void blocking_actor::launch(execution_unit*, bool, bool hide) { void blocking_actor::launch(execution_unit*, bool, bool hide) {
CAF_LOG_INIT_EVENT(name(), false, hide);
CAF_LOG_TRACE(CAF_ARG(hide)); CAF_LOG_TRACE(CAF_ARG(hide));
CAF_ASSERT(getf(is_blocking_flag)); CAF_ASSERT(getf(is_blocking_flag));
if (!hide) if (!hide)
...@@ -95,6 +94,7 @@ void blocking_actor::launch(execution_unit*, bool, bool hide) { ...@@ -95,6 +94,7 @@ void blocking_actor::launch(execution_unit*, bool, bool hide) {
auto self = static_cast<blocking_actor*>(this_ptr); auto self = static_cast<blocking_actor*>(this_ptr);
CAF_SET_LOGGER_SYS(ptr->home_system); CAF_SET_LOGGER_SYS(ptr->home_system);
CAF_PUSH_AID_FROM_PTR(self); CAF_PUSH_AID_FROM_PTR(self);
self->initialize();
error rsn; error rsn;
# ifndef CAF_NO_EXCEPTIONS # ifndef CAF_NO_EXCEPTIONS
try { try {
......
...@@ -41,6 +41,7 @@ void event_based_actor::initialize() { ...@@ -41,6 +41,7 @@ void event_based_actor::initialize() {
CAF_LOG_DEBUG("make_behavior() did return a valid behavior"); CAF_LOG_DEBUG("make_behavior() did return a valid behavior");
become(std::move(bhvr)); become(std::move(bhvr));
} }
extended_base::initialize();
} }
behavior event_based_actor::make_behavior() { behavior event_based_actor::make_behavior() {
......
...@@ -174,7 +174,7 @@ error local_actor::load_state(deserializer&, const unsigned int) { ...@@ -174,7 +174,7 @@ error local_actor::load_state(deserializer&, const unsigned int) {
} }
void local_actor::initialize() { void local_actor::initialize() {
// nop CAF_LOG_INIT_EVENT(name(), !getf(is_registered_flag));
} }
bool local_actor::cleanup(error&& fail_state, execution_unit* host) { bool local_actor::cleanup(error&& fail_state, execution_unit* host) {
......
...@@ -252,7 +252,7 @@ actor_id logger::thread_local_aid(actor_id aid) { ...@@ -252,7 +252,7 @@ actor_id logger::thread_local_aid(actor_id aid) {
void logger::log_prefix(std::ostream& out, int level, const char* component, void logger::log_prefix(std::ostream& out, int level, const char* component,
const std::string& class_name, const std::string& class_name,
const char* function_name, const char* c_full_file_name, const char* function_name, const char* c_full_file_name,
int line_num) { int line_num, const std::thread::id& tid) {
std::string file_name; std::string file_name;
std::string full_file_name = c_full_file_name; std::string full_file_name = c_full_file_name;
auto ri = find(full_file_name.rbegin(), full_file_name.rend(), '/'); auto ri = find(full_file_name.rbegin(), full_file_name.rend(), '/');
...@@ -268,9 +268,9 @@ void logger::log_prefix(std::ostream& out, int level, const char* component, ...@@ -268,9 +268,9 @@ void logger::log_prefix(std::ostream& out, int level, const char* component,
std::ostringstream prefix; std::ostringstream prefix;
out << timestamp_to_string(make_timestamp()) << " " << component << " " out << timestamp_to_string(make_timestamp()) << " " << component << " "
<< log_level_name[level] << " " << log_level_name[level] << " "
<< "actor" << thread_local_aid() << " " << std::this_thread::get_id() << "actor" << thread_local_aid() << " " << tid << " "
<< " " << class_name << " " << function_name << " " << file_name << ":" << class_name << " " << function_name << " "
<< line_num; << file_name << ":" << line_num;
} }
void logger::log(int level, const char* component, void logger::log(int level, const char* component,
...@@ -320,6 +320,30 @@ logger::logger(actor_system& sys) : system_(sys) { ...@@ -320,6 +320,30 @@ logger::logger(actor_system& sys) : system_(sys) {
// nop // nop
} }
void logger::init(actor_system_config& cfg) {
auto lvl_atom = cfg.logger_verbosity;
switch (static_cast<uint64_t>(lvl_atom)) {
case error_log_lvl_atom::uint_value():
level_ = CAF_LOG_LEVEL_ERROR;
break;
case warning_log_lvl_atom::uint_value():
level_ = CAF_LOG_LEVEL_WARNING;
break;
case info_log_lvl_atom::uint_value():
level_ = CAF_LOG_LEVEL_INFO;
break;
case debug_log_lvl_atom::uint_value():
level_ = CAF_LOG_LEVEL_DEBUG;
break;
case trace_log_lvl_atom::uint_value():
level_ = CAF_LOG_LEVEL_TRACE;
break;
default: {
level_ = CAF_LOG_LEVEL;
}
}
}
void logger::run() { void logger::run() {
#if defined(CAF_LOG_LEVEL) #if defined(CAF_LOG_LEVEL)
auto f = system_.config().logger_filename; auto f = system_.config().logger_filename;
...@@ -348,34 +372,13 @@ void logger::run() { ...@@ -348,34 +372,13 @@ void logger::run() {
return; return;
} }
// log first entry // log first entry
auto lvl_atom = system_.config().logger_verbosity;
switch (static_cast<uint64_t>(lvl_atom)) {
case error_log_lvl_atom::uint_value():
level_ = CAF_LOG_LEVEL_ERROR;
break;
case warning_log_lvl_atom::uint_value():
level_ = CAF_LOG_LEVEL_WARNING;
break;
case info_log_lvl_atom::uint_value():
level_ = CAF_LOG_LEVEL_INFO;
break;
case debug_log_lvl_atom::uint_value():
level_ = CAF_LOG_LEVEL_DEBUG;
break;
case trace_log_lvl_atom::uint_value():
level_ = CAF_LOG_LEVEL_TRACE;
break;
default: {
constexpr atom_value level_names[] = { constexpr atom_value level_names[] = {
error_log_lvl_atom::value, warning_log_lvl_atom::value, error_log_lvl_atom::value, warning_log_lvl_atom::value,
info_log_lvl_atom::value, debug_log_lvl_atom::value, info_log_lvl_atom::value, debug_log_lvl_atom::value,
trace_log_lvl_atom::value}; trace_log_lvl_atom::value};
lvl_atom = level_names[CAF_LOG_LEVEL]; auto lvl_atom = level_names[CAF_LOG_LEVEL];
level_ = CAF_LOG_LEVEL;
}
}
log_prefix(file, CAF_LOG_LEVEL_INFO, "caf", "caf.logger", "start", log_prefix(file, CAF_LOG_LEVEL_INFO, "caf", "caf.logger", "start",
__FILE__, __LINE__); __FILE__, __LINE__, parent_thread_);
file << " level = " << to_string(lvl_atom) << ", node = " << to_string(system_.node()) file << " level = " << to_string(lvl_atom) << ", node = " << to_string(system_.node())
<< std::endl; << std::endl;
// receive log entries from other threads and actors // receive log entries from other threads and actors
...@@ -420,7 +423,7 @@ void logger::run() { ...@@ -420,7 +423,7 @@ void logger::run() {
} }
} }
log_prefix(file, CAF_LOG_LEVEL_INFO, "caf", "caf.logger", "stop", log_prefix(file, CAF_LOG_LEVEL_INFO, "caf", "caf.logger", "stop",
__FILE__, __LINE__); __FILE__, __LINE__, parent_thread_);
file << " EOF" << std::endl; file << " EOF" << std::endl;
file.close(); file.close();
#endif #endif
...@@ -428,6 +431,7 @@ void logger::run() { ...@@ -428,6 +431,7 @@ void logger::run() {
void logger::start() { void logger::start() {
#if defined(CAF_LOG_LEVEL) #if defined(CAF_LOG_LEVEL)
parent_thread_ = std::this_thread::get_id();
if (system_.config().logger_verbosity == quiet_log_lvl_atom::value) if (system_.config().logger_verbosity == quiet_log_lvl_atom::value)
return; return;
thread_ = std::thread{[this] { this->run(); }}; thread_ = std::thread{[this] { this->run(); }};
......
...@@ -163,7 +163,6 @@ const char* scheduled_actor::name() const { ...@@ -163,7 +163,6 @@ const char* scheduled_actor::name() const {
} }
void scheduled_actor::launch(execution_unit* eu, bool lazy, bool hide) { void scheduled_actor::launch(execution_unit* eu, bool lazy, bool hide) {
CAF_LOG_INIT_EVENT(name(), lazy, hide);
CAF_LOG_TRACE(CAF_ARG(lazy) << CAF_ARG(hide)); CAF_LOG_TRACE(CAF_ARG(lazy) << CAF_ARG(hide));
CAF_ASSERT(!getf(is_blocking_flag)); CAF_ASSERT(!getf(is_blocking_flag));
if (!hide) if (!hide)
......
...@@ -46,13 +46,14 @@ public: ...@@ -46,13 +46,14 @@ public:
} // namespace <anonymous> } // namespace <anonymous>
scoped_actor::scoped_actor(actor_system& sys, bool hide) : context_(&sys) { scoped_actor::scoped_actor(actor_system& sys, bool hide) : context_(&sys) {
CAF_SET_LOGGER_SYS(&sys);
actor_config cfg{&context_}; actor_config cfg{&context_};
self_ = make_actor<impl, strong_actor_ptr>(sys.next_actor_id(), sys.node(), self_ = make_actor<impl, strong_actor_ptr>(sys.next_actor_id(), sys.node(),
&sys, cfg); &sys, cfg);
prev_ = CAF_SET_AID(self_->id());
CAF_LOG_INIT_EVENT("scoped_actor", false, hide);
if (!hide) if (!hide)
ptr()->register_at_system(); ptr()->register_at_system();
prev_ = CAF_SET_AID(self_->id());
ptr()->initialize();
} }
scoped_actor::~scoped_actor() { scoped_actor::~scoped_actor() {
......
...@@ -46,16 +46,14 @@ void abstract_broker::enqueue(mailbox_element_ptr ptr, execution_unit*) { ...@@ -46,16 +46,14 @@ void abstract_broker::enqueue(mailbox_element_ptr ptr, execution_unit*) {
scheduled_actor::enqueue(std::move(ptr), &backend()); scheduled_actor::enqueue(std::move(ptr), &backend());
} }
void abstract_broker::launch(execution_unit* eu, bool is_lazy, bool is_hidden) { void abstract_broker::launch(execution_unit* eu, bool lazy, bool hide) {
CAF_LOG_INIT_EVENT(name(), is_lazy, is_hidden);
CAF_ASSERT(eu != nullptr); CAF_ASSERT(eu != nullptr);
CAF_ASSERT(eu == &backend()); CAF_ASSERT(eu == &backend());
CAF_LOG_TRACE(CAF_ARG(lazy) << CAF_ARG(hide));
// add implicit reference count held by middleman/multiplexer // add implicit reference count held by middleman/multiplexer
if (!is_hidden) if (!hide)
register_at_system(); register_at_system();
CAF_PUSH_AID(id()); if (lazy && mailbox().try_block())
CAF_LOG_TRACE("init and launch broker:" << CAF_ARG(id()));
if (is_lazy && mailbox().try_block())
return; return;
intrusive_ptr_add_ref(ctrl()); intrusive_ptr_add_ref(ctrl());
eu->exec_later(this); eu->exec_later(this);
......
#include <cctype>
#include <string> #include <string>
#include <vector> #include <vector>
#include <cctype>
#include <utility> #include <utility>
#include <cassert> #include <cassert>
#include <fstream> #include <fstream>
...@@ -15,7 +15,7 @@ using std::string; ...@@ -15,7 +15,7 @@ using std::string;
using namespace caf; using namespace caf;
using thread_id = std::string; using thread_id = string;
using vector_timestamp = std::vector<size_t>; using vector_timestamp = std::vector<size_t>;
// -- convenience functions for strings // -- convenience functions for strings
...@@ -471,7 +471,7 @@ expected<se_event> parse_event(const enhanced_log_entry& x) { ...@@ -471,7 +471,7 @@ expected<se_event> parse_event(const enhanced_log_entry& x) {
CHECK_FIELDS("ID", "ARGS"); CHECK_FIELDS("ID", "ARGS");
break; break;
ATM_CASE("INIT", init); ATM_CASE("INIT", init);
CHECK_FIELDS("NAME", "LAZY", "HIDDEN"); CHECK_FIELDS("NAME", "HIDDEN");
break; break;
ATM_CASE("SEND", send); ATM_CASE("SEND", send);
CHECK_FIELDS("TO", "FROM", "STAGES", "CONTENT"); CHECK_FIELDS("TO", "FROM", "STAGES", "CONTENT");
...@@ -500,25 +500,6 @@ expected<se_event> parse_event(const enhanced_log_entry& x) { ...@@ -500,25 +500,6 @@ expected<se_event> parse_event(const enhanced_log_entry& x) {
return {std::move(y)}; return {std::move(y)};
} }
bool matches(const se_event& x, const se_event& y) {
switch (x.type) {
default:
return false;
case se_type::receive:
if (y.type == se_type::send) {
// TODO
//return x.receiver == y.receiver && x.sender == y.sender
// && x.stages == y.stages && x.content == y.content;
}
return false;
case se_type::init:
if (y.type == se_type::spawn) {
// TODO: return x.id == y.id
}
return false;
}
}
std::ostream& operator<<(std::ostream& out, const enhanced_log_entry& x) { std::ostream& operator<<(std::ostream& out, const enhanced_log_entry& x) {
return out << x.json_vstamp << ' ' << x.data.timestamp << ' ' return out << x.json_vstamp << ' ' << x.data.timestamp << ' '
<< x.data.component << ' ' << x.data.level << ' ' << x.data.component << ' ' << x.data.level << ' '
...@@ -726,7 +707,6 @@ void second_pass(blocking_actor* self, const group& grp, ...@@ -726,7 +707,6 @@ void second_pass(blocking_actor* self, const group& grp,
} else { } else {
std::cerr << "*** cannot match init event to a previous spawn" std::cerr << "*** cannot match init event to a previous spawn"
<< endl; << endl;
//merge(st.clock, fetch_message(se_type::spawn, pred).vstamp);
} }
break; break;
} }
...@@ -777,6 +757,8 @@ struct config : public actor_system_config { ...@@ -777,6 +757,8 @@ struct config : public actor_system_config {
.add(include_hidden_actors, "include-hidden-actors,i", .add(include_hidden_actors, "include-hidden-actors,i",
"Include hidden (system-level) actors") "Include hidden (system-level) actors")
.add(verbosity, "verbosity,v", "Debug output (from 0 to 2)"); .add(verbosity, "verbosity,v", "Debug output (from 0 to 2)");
// shutdown logging per default
logger_verbosity = quiet_log_lvl_atom::value;
} }
}; };
......
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