Commit 582d8171 authored by Dominik Charousset's avatar Dominik Charousset

improved logging output

added logging output to all run_later functors and removed logging
output from default_actor_addressing to keep logfiles readable
parent 3e04d670
...@@ -54,19 +54,16 @@ actor_registry::actor_registry() : m_running(0), m_ids(1) { ...@@ -54,19 +54,16 @@ actor_registry::actor_registry() : m_running(0), m_ids(1) {
} }
actor_registry::value_type actor_registry::get_entry(actor_id key) const { actor_registry::value_type actor_registry::get_entry(actor_id key) const {
CPPA_LOG_TRACE("key = " << key);
shared_guard guard(m_instances_mtx); shared_guard guard(m_instances_mtx);
auto i = m_entries.find(key); auto i = m_entries.find(key);
if (i != m_entries.end()) { if (i != m_entries.end()) {
CPPA_LOG_DEBUG("result = " << i->second.first.get());
return i->second; return i->second;
} }
CPPA_LOG_DEBUG("result = nullptr"); CPPA_LOG_DEBUG("no cache entry found for " << CPPA_ARG(key));
return {nullptr, exit_reason::not_exited}; return {nullptr, exit_reason::not_exited};
} }
void actor_registry::put(actor_id key, const actor_ptr& value) { void actor_registry::put(actor_id key, const actor_ptr& value) {
CPPA_LOG_TRACE("key = " << key << ", ptr = " << value.get());
bool add_attachable = false; bool add_attachable = false;
if (value != nullptr) { if (value != nullptr) {
shared_guard guard(m_instances_mtx); shared_guard guard(m_instances_mtx);
...@@ -80,6 +77,7 @@ void actor_registry::put(actor_id key, const actor_ptr& value) { ...@@ -80,6 +77,7 @@ void actor_registry::put(actor_id key, const actor_ptr& value) {
} }
} }
if (add_attachable) { if (add_attachable) {
CPPA_LOG_INFO("added " << key);
struct eraser : attachable { struct eraser : attachable {
actor_id m_id; actor_id m_id;
actor_registry* m_registry; actor_registry* m_registry;
...@@ -96,11 +94,11 @@ void actor_registry::put(actor_id key, const actor_ptr& value) { ...@@ -96,11 +94,11 @@ void actor_registry::put(actor_id key, const actor_ptr& value) {
} }
void actor_registry::erase(actor_id key, std::uint32_t reason) { void actor_registry::erase(actor_id key, std::uint32_t reason) {
CPPA_LOG_TRACE("key = " << key << ", reason = " << std::hex << reason);
exclusive_guard guard(m_instances_mtx); exclusive_guard guard(m_instances_mtx);
auto i = m_entries.find(key); auto i = m_entries.find(key);
if (i != m_entries.end()) { if (i != m_entries.end()) {
auto& entry = i->second; auto& entry = i->second;
CPPA_LOG_INFO("erased " << key << ", reason = " << std::hex << reason);
entry.first = nullptr; entry.first = nullptr;
entry.second = reason; entry.second = reason;
} }
...@@ -131,6 +129,7 @@ void actor_registry::dec_running() { ...@@ -131,6 +129,7 @@ void actor_registry::dec_running() {
} }
void actor_registry::await_running_count_equal(size_t expected) { void actor_registry::await_running_count_equal(size_t expected) {
CPPA_LOG_TRACE(CPPA_ARG(expected));
std::unique_lock<std::mutex> guard(m_running_mtx); std::unique_lock<std::mutex> guard(m_running_mtx);
while (m_running.load() != expected) { while (m_running.load() != expected) {
m_running_cv.wait(guard); m_running_cv.wait(guard);
......
...@@ -54,7 +54,6 @@ atom_value default_actor_addressing::technology_id() const { ...@@ -54,7 +54,6 @@ atom_value default_actor_addressing::technology_id() const {
} }
void default_actor_addressing::write(serializer* sink, const actor_ptr& ptr) { void default_actor_addressing::write(serializer* sink, const actor_ptr& ptr) {
CPPA_LOG_TRACE("sink = " << sink << ", ptr" << ptr.get());
CPPA_REQUIRE(sink != nullptr); CPPA_REQUIRE(sink != nullptr);
if (ptr == nullptr) { if (ptr == nullptr) {
CPPA_LOG_DEBUG("serialized nullptr"); CPPA_LOG_DEBUG("serialized nullptr");
...@@ -64,7 +63,7 @@ void default_actor_addressing::write(serializer* sink, const actor_ptr& ptr) { ...@@ -64,7 +63,7 @@ void default_actor_addressing::write(serializer* sink, const actor_ptr& ptr) {
else { else {
// local actor? // local actor?
if (*ptr->parent_process_ptr() == *process_information::get()) { if (*ptr->parent_process_ptr() == *process_information::get()) {
detail::singleton_manager::get_actor_registry()->put(ptr->id(), ptr); detail::singleton_manager::get_actor_registry()->put(ptr->id(), ptr);
} }
primitive_variant ptup[2]; primitive_variant ptup[2];
ptup[0] = ptr->id(); ptup[0] = ptr->id();
...@@ -78,7 +77,6 @@ void default_actor_addressing::write(serializer* sink, const actor_ptr& ptr) { ...@@ -78,7 +77,6 @@ void default_actor_addressing::write(serializer* sink, const actor_ptr& ptr) {
} }
actor_ptr default_actor_addressing::read(deserializer* source) { actor_ptr default_actor_addressing::read(deserializer* source) {
CPPA_LOG_TRACE("source = " << source);
CPPA_REQUIRE(source != nullptr); CPPA_REQUIRE(source != nullptr);
auto cname = source->seek_object(); auto cname = source->seek_object();
if (cname == "@0") { if (cname == "@0") {
...@@ -112,19 +110,19 @@ actor_ptr default_actor_addressing::read(deserializer* source) { ...@@ -112,19 +110,19 @@ actor_ptr default_actor_addressing::read(deserializer* source) {
} }
size_t default_actor_addressing::count_proxies(const process_information& inf) { size_t default_actor_addressing::count_proxies(const process_information& inf) {
CPPA_LOG_TRACE("inf = " << to_string(inf));
auto i = m_proxies.find(inf); auto i = m_proxies.find(inf);
return (i != m_proxies.end()) ? i->second.size() : 0; return (i != m_proxies.end()) ? i->second.size() : 0;
} }
actor_ptr default_actor_addressing::get(const process_information& inf, actor_ptr default_actor_addressing::get(const process_information& inf,
actor_id aid) { actor_id aid) {
CPPA_LOG_TRACE("inf = " << to_string(inf) << ", aid = " << aid);
auto& submap = m_proxies[inf]; auto& submap = m_proxies[inf];
auto i = submap.find(aid); auto i = submap.find(aid);
if (i != submap.end()) { if (i != submap.end()) {
auto result = i->second.promote(); auto result = i->second.promote();
CPPA_LOG_INFO_IF(!result, "proxy instance expired"); CPPA_LOG_INFO_IF(!result, "proxy instance expired; "
<< CPPA_TARG(inf, to_string) << ", "
<< CPPA_ARG(aid));
return result; return result;
} }
return nullptr; return nullptr;
...@@ -154,6 +152,8 @@ actor_ptr default_actor_addressing::get_or_put(const process_information& inf, ...@@ -154,6 +152,8 @@ actor_ptr default_actor_addressing::get_or_put(const process_information& inf,
actor_id aid) { actor_id aid) {
auto result = get(inf, aid); auto result = get(inf, aid);
if (result == nullptr) { if (result == nullptr) {
CPPA_LOG_INFO("created new proxy instance; "
<< CPPA_TARG(inf, to_string) << ", " << CPPA_ARG(aid));
auto ptr = make_counted<default_actor_proxy>(aid, new process_information(inf), m_parent); auto ptr = make_counted<default_actor_proxy>(aid, new process_information(inf), m_parent);
put(inf, aid, ptr); put(inf, aid, ptr);
result = ptr; result = ptr;
......
...@@ -71,11 +71,13 @@ void default_actor_proxy::forward_msg(const actor_ptr& sender, any_tuple msg, me ...@@ -71,11 +71,13 @@ void default_actor_proxy::forward_msg(const actor_ptr& sender, any_tuple msg, me
actor_ptr receiver = this; actor_ptr receiver = this;
auto proto = m_proto; auto proto = m_proto;
m_proto->run_later([proto, node, sender, receiver, msg, mid] { m_proto->run_later([proto, node, sender, receiver, msg, mid] {
CPPA_LOGF_TRACE("lambda from default_actor_proxy::forward_msg; " CPPA_LOGF_TRACE("lambda from default_actor_proxy::forward_msg");
/*
<< "node = " << to_string(*node) << "node = " << to_string(*node)
<< ", sender =" << to_string(sender) << ", sender =" << to_string(sender)
<< ", receiver = " << to_string(receiver) << ", receiver = " << to_string(receiver)
<< ", proto = " << to_string(proto->identifier())); << ", proto = " << to_string(proto->identifier()));
*/
auto p = proto->get_peer(*node); auto p = proto->get_peer(*node);
if (p) p->enqueue(addressed_message(sender, receiver, msg, mid)); if (p) p->enqueue(addressed_message(sender, receiver, msg, mid));
}); });
......
...@@ -358,7 +358,7 @@ void default_peer::enqueue(const addressed_message& msg) { ...@@ -358,7 +358,7 @@ void default_peer::enqueue(const addressed_message& msg) {
<< endl; << endl;
return; return;
} }
CPPA_LOG_DEBUG("serialized: " << to_string(msg)); CPPA_LOG_DEBUG("serialized: " << to_string(msg.content()));
size = (m_wr_buf.size() - before) - sizeof(std::uint32_t); size = (m_wr_buf.size() - before) - sizeof(std::uint32_t);
// update size in buffer // update size in buffer
memcpy(m_wr_buf.data() + before, &size, sizeof(std::uint32_t)); memcpy(m_wr_buf.data() + before, &size, sizeof(std::uint32_t));
......
...@@ -67,11 +67,14 @@ void default_protocol::publish(const actor_ptr& whom, variant_args args) { ...@@ -67,11 +67,14 @@ void default_protocol::publish(const actor_ptr& whom, variant_args args) {
auto i = args.begin(); auto i = args.begin();
if (args.size() == 1) { if (args.size() == 1) {
auto port = get<uint16_t>(*i); auto port = get<uint16_t>(*i);
CPPA_LOG_INFO("publish " << to_string(whom) << " on port " << port);
publish(whom, ipv4_acceptor::create(port), {}); publish(whom, ipv4_acceptor::create(port), {});
} }
else if (args.size() == 2) { else if (args.size() == 2) {
auto port = get<uint16_t>(*i++); auto port = get<uint16_t>(*i++);
auto& addr = get<string>(*i); auto& addr = get<string>(*i);
CPPA_LOG_INFO("publish " << to_string(whom) << " on port " << port
<< " with addr = " << addr);
publish(whom, ipv4_acceptor::create(port, addr.c_str()), {}); publish(whom, ipv4_acceptor::create(port, addr.c_str()), {});
} }
else throw logic_error("wrong number of arguments, expected one or two"); else throw logic_error("wrong number of arguments, expected one or two");
......
...@@ -69,10 +69,11 @@ class logging_impl : public logging { ...@@ -69,10 +69,11 @@ class logging_impl : public logging {
void start() { void start() {
m_thread = thread([this] { (*this)(); }); m_thread = thread([this] { (*this)(); });
log("TRACE ", "logging", "run", __FILE__, 31337, "ENTRY");
} }
void stop() { void stop() {
log("DEBUG", "logging", "stop", __FILE__, __LINE__, "shutting down"); log("TRACE ", "logging", "run", __FILE__, 31337, "EXIT");
// an empty string means: shut down // an empty string means: shut down
m_queue.push_back(new log_event{0, ""}); m_queue.push_back(new log_event{0, ""});
m_thread.join(); m_thread.join();
......
...@@ -450,7 +450,10 @@ class middleman_impl : public abstract_middleman { ...@@ -450,7 +450,10 @@ class middleman_impl : public abstract_middleman {
} }
void stop() { void stop() {
run_later([this] { this->m_done = true; }); run_later([this] {
CPPA_LOG_TRACE("lambda from middleman_impl::stop");
this->m_done = true;
});
//enqueue_message(middleman_message::create()); //enqueue_message(middleman_message::create());
m_thread.join(); m_thread.join();
close(m_pipe_read); close(m_pipe_read);
...@@ -484,9 +487,11 @@ class middleman_overseer : public continuable_reader { ...@@ -484,9 +487,11 @@ class middleman_overseer : public continuable_reader {
: super(pipe_fd), m_queue(q) { } : super(pipe_fd), m_queue(q) { }
continue_reading_result continue_reading() { continue_reading_result continue_reading() {
CPPA_LOG_TRACE("");
static constexpr size_t num_dummies = 64; static constexpr size_t num_dummies = 64;
uint8_t dummies[num_dummies]; uint8_t dummies[num_dummies];
auto read_result = ::read(read_handle(), dummies, num_dummies); auto read_result = ::read(read_handle(), dummies, num_dummies);
CPPA_LOG_DEBUG("read " << read_result << " messages from queue");
if (read_result < 0) { if (read_result < 0) {
if (errno == EAGAIN || errno == EWOULDBLOCK) { if (errno == EAGAIN || errno == EWOULDBLOCK) {
// try again later // try again later
...@@ -504,6 +509,7 @@ class middleman_overseer : public continuable_reader { ...@@ -504,6 +509,7 @@ class middleman_overseer : public continuable_reader {
CPPA_LOG_ERROR("nullptr dequeued"); CPPA_LOG_ERROR("nullptr dequeued");
CPPA_CRITICAL("nullptr dequeued"); CPPA_CRITICAL("nullptr dequeued");
} }
CPPA_LOG_DEBUG("execute run_later functor");
(*msg)(); (*msg)();
} }
return read_continue_later; return read_continue_later;
...@@ -566,7 +572,7 @@ void middleman_loop(middleman_impl* impl) { ...@@ -566,7 +572,7 @@ void middleman_loop(middleman_impl* impl) {
case event::none: break; case event::none: break;
case event::both: case event::both:
case event::write: { case event::write: {
CPPA_LOGF_DEBUG("handle event::write"); CPPA_LOGF_DEBUG("handle event::write for " << i->ptr());
switch (i->continue_writing()) { switch (i->continue_writing()) {
case write_closed: case write_closed:
case write_failure: case write_failure:
...@@ -583,7 +589,7 @@ void middleman_loop(middleman_impl* impl) { ...@@ -583,7 +589,7 @@ void middleman_loop(middleman_impl* impl) {
CPPA_LOGF_DEBUG("handle event::both; fall through"); CPPA_LOGF_DEBUG("handle event::both; fall through");
} }
case event::read: { case event::read: {
CPPA_LOGF_DEBUG("handle event::read"); CPPA_LOGF_DEBUG("handle event::read for " << i->ptr());
switch (i->continue_reading()) { switch (i->continue_reading()) {
case read_closed: case read_closed:
case read_failure: case read_failure:
...@@ -595,9 +601,9 @@ void middleman_loop(middleman_impl* impl) { ...@@ -595,9 +601,9 @@ void middleman_loop(middleman_impl* impl) {
break; break;
} }
case event::error: { case event::error: {
CPPA_LOGF_DEBUG("event::error; remove peer " << i->ptr());
impl->stop_reader(i->ptr()); impl->stop_reader(i->ptr());
impl->stop_writer(i->ptr()); impl->stop_writer(i->ptr());
CPPA_LOGF_DEBUG("event::error; remove peer");
} }
} }
i->handled(); i->handled();
......
...@@ -38,7 +38,7 @@ namespace cppa { namespace network { ...@@ -38,7 +38,7 @@ namespace cppa { namespace network {
protocol::protocol(abstract_middleman* parent) : m_parent(parent) { } protocol::protocol(abstract_middleman* parent) : m_parent(parent) { }
void protocol::run_later(std::function<void()> fun) { void protocol::run_later(std::function<void()> fun) {
m_parent->run_later([=] { fun(); }); m_parent->run_later(std::move(fun));
} }
void protocol::continue_reader(continuable_reader* ptr) { void protocol::continue_reader(continuable_reader* ptr) {
......
...@@ -53,6 +53,7 @@ ...@@ -53,6 +53,7 @@
#include "cppa/util/duration.hpp" #include "cppa/util/duration.hpp"
#include "cppa/util/void_type.hpp" #include "cppa/util/void_type.hpp"
#include "cppa/detail/logging.hpp"
#include "cppa/detail/demangle.hpp" #include "cppa/detail/demangle.hpp"
#include "cppa/detail/object_array.hpp" #include "cppa/detail/object_array.hpp"
#include "cppa/detail/actor_registry.hpp" #include "cppa/detail/actor_registry.hpp"
...@@ -396,6 +397,7 @@ class addr_msg_tinfo : public util::abstract_uniform_type_info<network::addresse ...@@ -396,6 +397,7 @@ class addr_msg_tinfo : public util::abstract_uniform_type_info<network::addresse
public: public:
virtual void serialize(const void* instance, serializer* sink) const { virtual void serialize(const void* instance, serializer* sink) const {
CPPA_LOG_TRACE("");
auto& msg = *reinterpret_cast<const network::addressed_message*>(instance); auto& msg = *reinterpret_cast<const network::addressed_message*>(instance);
auto& data = msg.content(); auto& data = msg.content();
sink->begin_object(name()); sink->begin_object(name());
...@@ -411,6 +413,7 @@ class addr_msg_tinfo : public util::abstract_uniform_type_info<network::addresse ...@@ -411,6 +413,7 @@ class addr_msg_tinfo : public util::abstract_uniform_type_info<network::addresse
} }
virtual void deserialize(void* instance, deserializer* source) const { virtual void deserialize(void* instance, deserializer* source) const {
CPPA_LOG_TRACE("");
assert_type_name(source); assert_type_name(source);
source->begin_object(name()); source->begin_object(name());
auto& msg = *reinterpret_cast<network::addressed_message*>(instance); auto& msg = *reinterpret_cast<network::addressed_message*>(instance);
......
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