[cyb-519] improve logging

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 <fc/exception/exception.hpp>
 #include <fc/io/json.hpp>
@@ -23,34 +24,6 @@ using ::fc::static_variant;
 
 using mutex_guard = std::lock_guard<std::mutex>;
 
-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
-
-
 template <typename message_type>
 class message_queue {
 public:
@@ -357,7 +330,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<randpa_message>(msg));
 #else
@@ -378,10 +350,6 @@ class randpa {
  template <typename T>
  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);
  }
 
@@ -702,8 +670,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;
  }

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

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<uint32_t>(state))
+ randpa_dlog("Round failed, num: ${n}, state: ${s}",
+  ("n", num)
+  ("s", static_cast<uint32_t>(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<uint32_t>(state))
+ randpa_dlog("Round failed, num: ${n}, state: ${s}",
+  ("n", num)
+  ("s", static_cast<uint32_t>(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,31 +183,31 @@ 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;
  }
  }
 
  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();