diff --git a/plugins/randpa_plugin/include/eosio/randpa_plugin/randpa.hpp b/plugins/randpa_plugin/include/eosio/randpa_plugin/randpa.hpp index c5a4865aaae..e3baf57b6be 100644 --- a/plugins/randpa_plugin/include/eosio/randpa_plugin/randpa.hpp +++ b/plugins/randpa_plugin/include/eosio/randpa_plugin/randpa.hpp @@ -2,6 +2,7 @@ #include "network_messages.hpp" #include "round.hpp" +#include "randpa_logger.hpp" #include #include @@ -23,33 +24,6 @@ using ::fc::static_variant; using mutex_guard = std::lock_guard; -const fc::string randpa_logger_name("randpa_plugin"); -fc::logger randpa_logger; - -#define randpa_dlog(FORMAT, ...) \ - FC_MULTILINE_MACRO_BEGIN \ - if (randpa_logger.is_enabled(fc::log_level::debug)) \ - randpa_logger.log(FC_LOG_MESSAGE(debug, FORMAT, __VA_ARGS__)); \ - FC_MULTILINE_MACRO_END - -#define randpa_ilog(FORMAT, ...) \ - FC_MULTILINE_MACRO_BEGIN \ - if (randpa_logger.is_enabled(fc::log_level::info)) \ - randpa_logger.log(FC_LOG_MESSAGE(info, FORMAT, __VA_ARGS__)); \ - FC_MULTILINE_MACRO_END - -#define randpa_wlog(FORMAT, ...) \ - FC_MULTILINE_MACRO_BEGIN \ - if (randpa_logger.is_enabled(fc::log_level::warn)) \ - randpa_logger.log(FC_LOG_MESSAGE(warn, FORMAT, __VA_ARGS__)); \ - FC_MULTILINE_MACRO_END - -#define randpa_elog(FORMAT, ...) \ - FC_MULTILINE_MACRO_BEGIN \ - if (randpa_logger.is_enabled(fc::log_level::error)) \ - randpa_logger.log( FC_LOG_MESSAGE(error, FORMAT, __VA_ARGS__)); \ - FC_MULTILINE_MACRO_END - //---------- types ----------// template @@ -366,7 +340,6 @@ class randpa { void subscribe() { _in_net_channel->subscribe([&](const randpa_net_msg& msg) { - randpa_dlog("Randpa received net message, type: ${type}", ("type", msg.data.which())); #ifdef SYNC_RANDPA process_msg(std::make_shared(msg)); #else @@ -387,10 +360,6 @@ class randpa { template void send(uint32_t ses_id, const T & msg) { auto net_msg = randpa_net_msg { ses_id, msg }; - randpa_dlog("Randpa net message sent, type: ${type}, ses_id: ${ses_id}", - ("type", net_msg.data.which()) - ("ses_id", ses_id) - ); _out_net_channel->send(net_msg); } @@ -711,8 +680,8 @@ class randpa { ); if (get_block_num(event.block_id) <= get_block_num(_prefix_tree->get_root()->block_id)) { - randpa_wlog("Randpa handled on_irreversible for old block: block_num: ${blk_num}", - ("blk_num", get_block_num(event.block_id)) + randpa_dlog("Randpa handled on_irreversible for old block: block_num: ${blk_num}", + ("blk_num", get_block_num(event.block_id)) ); return; } diff --git a/plugins/randpa_plugin/include/eosio/randpa_plugin/randpa_logger.hpp b/plugins/randpa_plugin/include/eosio/randpa_plugin/randpa_logger.hpp new file mode 100644 index 00000000000..d69f281ecd7 --- /dev/null +++ b/plugins/randpa_plugin/include/eosio/randpa_plugin/randpa_logger.hpp @@ -0,0 +1,31 @@ +#pragma once + +namespace randpa_finality { + +const fc::string randpa_logger_name("randpa_plugin"); +fc::logger randpa_logger; + +#define randpa_dlog(FORMAT, ...) \ + FC_MULTILINE_MACRO_BEGIN \ + if (randpa_logger.is_enabled(fc::log_level::debug)) \ + randpa_logger.log(FC_LOG_MESSAGE(debug, FORMAT, __VA_ARGS__)); \ + FC_MULTILINE_MACRO_END + +#define randpa_ilog(FORMAT, ...) \ + FC_MULTILINE_MACRO_BEGIN \ + if (randpa_logger.is_enabled(fc::log_level::info)) \ + randpa_logger.log(FC_LOG_MESSAGE(info, FORMAT, __VA_ARGS__)); \ + FC_MULTILINE_MACRO_END + +#define randpa_wlog(FORMAT, ...) \ + FC_MULTILINE_MACRO_BEGIN \ + if (randpa_logger.is_enabled(fc::log_level::warn)) \ + randpa_logger.log(FC_LOG_MESSAGE(warn, FORMAT, __VA_ARGS__)); \ + FC_MULTILINE_MACRO_END + +#define randpa_elog(FORMAT, ...) \ + FC_MULTILINE_MACRO_BEGIN \ + if (randpa_logger.is_enabled(fc::log_level::error)) \ + randpa_logger.log( FC_LOG_MESSAGE(error, FORMAT, __VA_ARGS__)); \ + FC_MULTILINE_MACRO_END +} // randpa_finality \ No newline at end of file diff --git a/plugins/randpa_plugin/include/eosio/randpa_plugin/round.hpp b/plugins/randpa_plugin/include/eosio/randpa_plugin/round.hpp index 7983ad38a9c..bd723ae6e20 100644 --- a/plugins/randpa_plugin/include/eosio/randpa_plugin/round.hpp +++ b/plugins/randpa_plugin/include/eosio/randpa_plugin/round.hpp @@ -3,6 +3,7 @@ #include "types.hpp" #include "prefix_chain_tree.hpp" #include "network_messages.hpp" +#include "randpa_logger.hpp" namespace randpa_finality { @@ -61,9 +62,9 @@ class randpa_round { , precommit_bcaster{std::move(precommit_bcaster)} , done_cb{std::move(done_cb)} { - dlog("Randpa round started, num: ${n}, primary: ${p}", - ("n", num) - ("p", primary) + randpa_dlog("Randpa round started, num: ${n}, primary: ${p}", + ("n", num) + ("p", primary) ); prevote(); @@ -89,12 +90,12 @@ class randpa_round { void on(const prevote_msg& msg) { if (state != state_type::prevote && state != state_type::ready_to_precommit) { - dlog("Skipping prevote, round: ${r}", ("r", num)); + randpa_dlog("Skipping prevote, round: ${r}", ("r", num)); return; } if (!validate_prevote(msg)) { - dlog("Invalid prevote for round ${num}", ("num", num)); + randpa_dlog("Invalid prevote for round ${num}", ("num", num)); return; } @@ -103,12 +104,12 @@ class randpa_round { void on(const precommit_msg& msg) { if (state != state_type::precommit && state != state_type::ready_to_precommit) { - dlog("Skipping precommit, round: ${r}", ("r", num)); + randpa_dlog("Skipping precommit, round: ${r}", ("r", num)); return; } if (!validate_precommit(msg)) { - dlog("Invalid precommit for round ${num}", ("num", num)); + randpa_dlog("Invalid precommit for round ${num}", ("num", num)); return; } @@ -117,14 +118,16 @@ class randpa_round { void end_prevote() { if (state != state_type::ready_to_precommit) { - dlog("Round failed, num: ${n}, state: ${s}", - ("n", num) - ("s", static_cast(state)) + randpa_dlog("Round failed, num: ${n}, state: ${s}", + ("n", num) + ("s", static_cast(state)) ); state = state_type::fail; return; } + randpa_dlog("Prevote finished for round ${r}, best_block: ${id}", ("r", num)("id", best_node->block_id)); + proof.round_num = num; proof.best_block = best_node->block_id; @@ -136,9 +139,9 @@ class randpa_round { bool finish() { if (state != state_type::done) { - dlog("Round failed, num: ${n}, state: ${s}", - ("n", num) - ("s", static_cast(state)) + randpa_dlog("Round failed, num: ${n}, state: ${s}", + ("n", num) + ("s", static_cast(state)) ); state = state_type::fail; return false; @@ -154,7 +157,7 @@ class randpa_round { auto last_node = tree->get_last_inserted_block(primary); if (!last_node) { - wlog("Not found last node in tree for primary, primary: ${p}", ("p", primary)); + randpa_wlog("Not found last node in tree for primary, primary: ${p}", ("p", primary)); return; } @@ -180,16 +183,16 @@ class randpa_round { bool validate_prevote(const prevote_msg& msg) { if (num != msg.data.round_num) { - dlog("Randpa received prevote for wrong round, received for: ${rr}, expected: ${er}", - ("rr", msg.data.round_num) - ("er", num) + randpa_dlog("Randpa received prevote for wrong round, received for: ${rr}, expected: ${er}", + ("rr", msg.data.round_num) + ("er", num) ); return false; } for (const auto& public_key : msg.public_keys()) { if (prevoted_keys.count(public_key)) { - dlog("Randpa received prevote second time for key"); + randpa_dlog("Randpa received prevote second time for key"); return false; } } @@ -197,14 +200,14 @@ class randpa_round { auto node = find_last_node(msg.data.base_block, msg.data.blocks); if (!node) { - dlog("Randpa received prevote for unknown blocks"); + randpa_dlog("Randpa received prevote for unknown blocks"); return false; } for (const auto& public_key : msg.public_keys()) { if (!node->active_bp_keys.count(public_key)) { - dlog("Randpa received prevote for block from not active producer, id : ${id}", - ("id", node->block_id) + randpa_dlog("Randpa received prevote for block from not active producer, id : ${id}", + ("id", node->block_id) ); return false; } @@ -215,31 +218,31 @@ class randpa_round { bool validate_precommit(const precommit_msg& msg) { if (num != msg.data.round_num) { - dlog("Randpa received precommit for wrong round, received for: ${rr}, expected: ${er}", - ("rr", msg.data.round_num) - ("er", num) + randpa_dlog("Randpa received precommit for wrong round, received for: ${rr}, expected: ${er}", + ("rr", msg.data.round_num) + ("er", num) ); return false; } for (const auto& public_key : msg.public_keys()) { if (precommited_keys.count(public_key)) { - dlog("Randpa received precommit second time for key"); + randpa_dlog("Randpa received precommit second time for key"); return false; } } if (msg.data.block_id != best_node->block_id) { - dlog("Randpa received precommit for not best block, id: ${id}, best_id: ${best_id}", - ("id", msg.data.block_id) - ("best_id", best_node->block_id) + randpa_dlog("Randpa received precommit for not best block, id: ${id}, best_id: ${best_id}", + ("id", msg.data.block_id) + ("best_id", best_node->block_id) ); return false; } for (const auto& public_key : msg.public_keys()) { if (!best_node->has_confirmation(public_key)) { - dlog("Randpa received precommit from not prevoted peer"); + randpa_dlog("Randpa received precommit from not prevoted peer"); return false; } } @@ -256,18 +259,18 @@ class randpa_round { FC_ASSERT(max_prevote_node, "confirmation should be insertable"); prevoted_keys.insert(public_key); - dlog("Prevote inserted, round: ${r}, from: ${f}, max_confs: ${c}", - ("r", num) - ("f", public_key) - ("c", max_prevote_node->confirmation_number()) + randpa_dlog("Prevote inserted, round: ${r}, from: ${f}, max_confs: ${c}", + ("r", num) + ("f", public_key) + ("c", max_prevote_node->confirmation_number()) ); if (has_threshold_prevotes(max_prevote_node)) { state = state_type::ready_to_precommit; best_node = max_prevote_node; - dlog("Prevote threshold reached, round: ${r}, best block: ${b}", - ("r", num) - ("b", best_node->block_id) + randpa_dlog("Prevote threshold reached, round: ${r}, best block: ${b}", + ("r", num) + ("b", best_node->block_id) ); return; } @@ -279,10 +282,15 @@ class randpa_round { precommited_keys.insert(public_key); proof.precommits.push_back(msg); + randpa_dlog("Precommit inserted, round: ${r}, from: ${f}", + ("r", num) + ("f", public_key) + ); + if (proof.precommits.size() > 2 * best_node->active_bp_keys.size() / 3) { - dlog("Precommit threshold reached, round: ${r}, best block: ${b}", - ("r", num) - ("b", best_node->block_id) + randpa_dlog("Precommit threshold reached, round: ${r}, best block: ${b}", + ("r", num) + ("b", best_node->block_id) ); state = state_type::done; done_cb();