Merge pull request #28 from AntelopeIO/GH-14-vote-loggin

IF: Add logger for vote related logging

libraries/chain/block_state.cpp

@@ -50,7 +50,7 @@ block_state::block_state(const block_header_state&                bhs,
    block->transactions = std::move(trx_receipts);
 
    if( qc ) {
-      dlog("integrate qc ${qc} into block ${bn} ${id}", ("qc", qc->to_qc_claim())("bn", block_num())("id", id()));
+      fc_dlog(vote_logger, "integrate qc ${qc} into block ${bn} ${id}", ("qc", qc->to_qc_claim())("bn", block_num())("id", id()));
       emplace_extension(block->block_extensions, quorum_certificate_extension::extension_id(), fc::raw::pack( *qc ));
    }
 
@@ -159,8 +159,8 @@ void block_state::set_trxs_metas( deque<transaction_metadata_ptr>&& trxs_metas,
    cached_trxs = std::move( trxs_metas );
 }
 
-// Called from net threads
-vote_status block_state::aggregate_vote(const vote_message& vote) {
+// Called from vote threads
+vote_status block_state::aggregate_vote(uint32_t connection_id, const vote_message& vote) {
    const auto& finalizers = active_finalizer_policy->finalizers;
    auto it = std::find_if(finalizers.begin(),
                           finalizers.end(),
@@ -169,15 +169,17 @@ vote_status block_state::aggregate_vote(const vote_message& vote) {
    if (it != finalizers.end()) {
       auto index = std::distance(finalizers.begin(), it);
       auto digest = vote.strong ? strong_digest.to_uint8_span() : std::span<const uint8_t>(weak_digest);
-      return pending_qc.add_vote(block_num(),
+      return pending_qc.add_vote(connection_id,
+                                 block_num(),
                                  vote.strong,
                                  digest,
                                  index,
                                  vote.finalizer_key,
                                  vote.sig,
                                  finalizers[index].weight);
    } else {
-      wlog( "finalizer_key (${k}) in vote is not in finalizer policy", ("k", vote.finalizer_key) );
+      fc_wlog(vote_logger, "connection - ${c} finalizer_key ${k} in vote is not in finalizer policy",
+              ("c", connection_id)("k", vote.finalizer_key.to_string().substr(8,16)));
       return vote_status::unknown_public_key;
    }
 }

libraries/chain/hotstuff/hotstuff.cpp

@@ -137,29 +137,28 @@ vote_status pending_quorum_certificate::add_weak_vote(size_t index, const bls_si
 }
 
 // thread safe
-vote_status pending_quorum_certificate::add_vote(block_num_type block_num, bool strong, std::span<const uint8_t> proposal_digest, size_t index,
+vote_status pending_quorum_certificate::add_vote(uint32_t connection_id, block_num_type block_num,
+                                                 bool strong, std::span<const uint8_t> proposal_digest, size_t index,
                                                  const bls_public_key& pubkey, const bls_signature& sig, uint64_t weight) {
-   vote_status s = vote_status::success;
-
    if (has_voted_no_lock(strong, index)) {
-      dlog("block_num: ${bn}, vote strong: ${sv}, duplicate", ("bn", block_num)("sv", strong));
+      fc_dlog(vote_logger, "connection - ${c} block_num: ${bn}, duplicate", ("c", connection_id)("bn", block_num));
       return vote_status::duplicate;
    }
 
    if (!fc::crypto::blslib::verify(pubkey, proposal_digest, sig)) {
-      wlog( "signature from finalizer ${i} cannot be verified", ("i", index) );
+      fc_wlog(vote_logger, "connection - ${c} signature from finalizer ${k}.. cannot be verified", ("k", pubkey.to_string().substr(8,16)));
       return vote_status::invalid_signature;
    }
 
    std::unique_lock g(*_mtx);
    state_t pre_state = _state;
-   s = strong ? add_strong_vote(index, sig, weight)
-              : add_weak_vote(index, sig, weight);
+   vote_status s = strong ? add_strong_vote(index, sig, weight)
+                          : add_weak_vote(index, sig, weight);
    state_t post_state = _state;
    g.unlock();
 
-   dlog("block_num: ${bn}, vote strong: ${sv}, status: ${s}, pre-state: ${pre}, post-state: ${state}, quorum_met: ${q}",
-        ("bn", block_num)("sv", strong)("s", s)("pre", pre_state)("state", post_state)("q", is_quorum_met(post_state)));
+   fc_dlog(vote_logger, "connection - ${c} block_num: ${bn}, vote strong: ${sv}, status: ${s}, pre-state: ${pre}, post-state: ${state}, quorum_met: ${q}",
+        ("c", connection_id)("bn", block_num)("sv", strong)("s", s)("pre", pre_state)("state", post_state)("q", is_quorum_met(post_state)));
    return s;
 }
 

libraries/chain/hotstuff/test/finality_misc_tests.cpp

@@ -51,11 +51,11 @@ BOOST_AUTO_TEST_CASE(qc_state_transitions) try {
       pubkey.push_back(k.get_public_key());
 
    auto weak_vote = [&](pending_quorum_certificate& qc, const std::vector<uint8_t>& digest, size_t index, uint64_t weight) {
-      return qc.add_vote(0, false, digest, index, pubkey[index], sk[index].sign(digest), weight);
+      return qc.add_vote(0, 0, false, digest, index, pubkey[index], sk[index].sign(digest), weight);
    };
 
    auto strong_vote = [&](pending_quorum_certificate& qc, const std::vector<uint8_t>& digest, size_t index, uint64_t weight) {
-      return qc.add_vote(0, true, digest, index, pubkey[index], sk[index].sign(digest), weight);
+      return qc.add_vote(0, 0, true, digest, index, pubkey[index], sk[index].sign(digest), weight);
    };
 
    constexpr uint64_t weight = 1;

libraries/chain/include/eosio/chain/block_state.hpp

@@ -124,8 +124,8 @@ struct block_state : public block_header_state {     // block_header_state provi
    // Returns finality_data of the current block
    finality_data_t get_finality_data();
 
-   // vote_status
-   vote_status aggregate_vote(const vote_message& vote); // aggregate vote into pending_qc
+   // connection_id only for logging
+   vote_status aggregate_vote(uint32_t connection_id, const vote_message& vote); // aggregate vote into pending_qc
    bool has_voted(const bls_public_key& key) const;
    void verify_qc(const valid_quorum_certificate& qc) const; // verify given qc is valid with respect block_state
 

libraries/chain/include/eosio/chain/hotstuff/hotstuff.hpp

@@ -12,6 +12,8 @@
 
 namespace eosio::chain {
 
+   inline fc::logger vote_logger{"vote"};
+
    using bls_public_key          = fc::crypto::blslib::bls_public_key;
    using bls_signature           = fc::crypto::blslib::bls_signature;
    using bls_aggregate_signature = fc::crypto::blslib::bls_aggregate_signature;
@@ -118,7 +120,8 @@ namespace eosio::chain {
       }
 
       // thread safe
-      vote_status add_vote(block_num_type block_num,
+      vote_status add_vote(uint32_t connection_id,
+                           block_num_type block_num,
                            bool strong,
                            std::span<const uint8_t> proposal_digest,
                            size_t index,

libraries/chain/include/eosio/chain/vote_processor.hpp

@@ -117,7 +117,7 @@ class vote_processor_t {
          auto bsp = get_block(v.msg->block_id, g);
          // g is unlocked
          if (bsp) {
-            vote_status s = bsp->aggregate_vote(*v.msg);
+            vote_status s = bsp->aggregate_vote(v.connection_id, *v.msg);
             emit(v.connection_id, s, v.msg);
 
             g.lock();
@@ -230,7 +230,7 @@ class vote_processor_t {
                g.lock();
                queue_for_later(connection_id, msg);
             } else {
-               vote_status s = bsp->aggregate_vote(*msg);
+               vote_status s = bsp->aggregate_vote(connection_id, *msg);
                emit(connection_id, s, msg);
 
                g.lock();

libraries/libfc/include/fc/log/logger.hpp

@@ -3,9 +3,7 @@
 #include <fc/log/log_message.hpp>
 #include <string>
 
-#ifndef DEFAULT_LOGGER
-#define DEFAULT_LOGGER "default"
-#endif
+inline std::string DEFAULT_LOGGER = "default";
 
 namespace fc
 {
@@ -32,10 +30,10 @@ namespace fc
          logger( const std::string& name, const logger& parent = nullptr );
          logger( std::nullptr_t );
          logger( const logger& c );
-         logger( logger&& c );
+         logger( logger&& c ) noexcept;
          ~logger();
          logger& operator=(const logger&);
-         logger& operator=(logger&&);
+         logger& operator=(logger&&) noexcept;
          friend bool operator==( const logger&, nullptr_t );
          friend bool operator!=( const logger&, nullptr_t );
 
@@ -106,53 +104,38 @@ namespace fc
 
 #define tlog( FORMAT, ... ) \
   FC_MULTILINE_MACRO_BEGIN \
-   if( (fc::logger::get(DEFAULT_LOGGER)).is_enabled( fc::log_level::all ) ) \
-      (fc::logger::get(DEFAULT_LOGGER)).log( FC_LOG_MESSAGE( all, FORMAT, __VA_ARGS__ ) ); \
+   if( auto lL = (fc::logger::get(DEFAULT_LOGGER)); lL.is_enabled( fc::log_level::all ) ) \
+      lL.log( FC_LOG_MESSAGE( all, FORMAT, __VA_ARGS__ ) ); \
   FC_MULTILINE_MACRO_END
 
 #define dlog( FORMAT, ... ) \
   FC_MULTILINE_MACRO_BEGIN \
-   if( (fc::logger::get(DEFAULT_LOGGER)).is_enabled( fc::log_level::debug ) ) \
-      (fc::logger::get(DEFAULT_LOGGER)).log( FC_LOG_MESSAGE( debug, FORMAT, __VA_ARGS__ ) ); \
-  FC_MULTILINE_MACRO_END
-
-/**
- * Sends the log message to a special 'user' log stream designed for messages that
- * the end user may like to see.
- */
-#define ulog( FORMAT, ... ) \
-  FC_MULTILINE_MACRO_BEGIN \
-   if( (fc::logger::get("user")).is_enabled( fc::log_level::debug ) ) \
-      (fc::logger::get("user")).log( FC_LOG_MESSAGE( debug, FORMAT, __VA_ARGS__ ) ); \
+   if( auto lL = (fc::logger::get(DEFAULT_LOGGER)); lL.is_enabled( fc::log_level::debug ) ) \
+      lL.log( FC_LOG_MESSAGE( debug, FORMAT, __VA_ARGS__ ) ); \
   FC_MULTILINE_MACRO_END
 
-
 #define ilog( FORMAT, ... ) \
   FC_MULTILINE_MACRO_BEGIN \
-   if( (fc::logger::get(DEFAULT_LOGGER)).is_enabled( fc::log_level::info ) ) \
-      (fc::logger::get(DEFAULT_LOGGER)).log( FC_LOG_MESSAGE( info, FORMAT, __VA_ARGS__ ) ); \
+   if( auto lL = (fc::logger::get(DEFAULT_LOGGER)); lL.is_enabled( fc::log_level::info ) ) \
+      lL.log( FC_LOG_MESSAGE( info, FORMAT, __VA_ARGS__ ) ); \
   FC_MULTILINE_MACRO_END
 
 #define wlog( FORMAT, ... ) \
   FC_MULTILINE_MACRO_BEGIN \
-   if( (fc::logger::get(DEFAULT_LOGGER)).is_enabled( fc::log_level::warn ) ) \
-      (fc::logger::get(DEFAULT_LOGGER)).log( FC_LOG_MESSAGE( warn, FORMAT, __VA_ARGS__ ) ); \
+   if( auto lL = (fc::logger::get(DEFAULT_LOGGER)); lL.is_enabled( fc::log_level::warn ) ) \
+      lL.log( FC_LOG_MESSAGE( warn, FORMAT, __VA_ARGS__ ) ); \
   FC_MULTILINE_MACRO_END
 
 #define elog( FORMAT, ... ) \
   FC_MULTILINE_MACRO_BEGIN \
-   if( (fc::logger::get(DEFAULT_LOGGER)).is_enabled( fc::log_level::error ) ) \
-      (fc::logger::get(DEFAULT_LOGGER)).log( FC_LOG_MESSAGE( error, FORMAT, __VA_ARGS__ ) ); \
+   if( auto lL = (fc::logger::get(DEFAULT_LOGGER)); lL.is_enabled( fc::log_level::error ) ) \
+      lL.log( FC_LOG_MESSAGE( error, FORMAT, __VA_ARGS__ ) ); \
   FC_MULTILINE_MACRO_END
 
 #include <boost/preprocessor/seq/for_each.hpp>
-#include <boost/preprocessor/seq/enum.hpp>
-#include <boost/preprocessor/seq/size.hpp>
-#include <boost/preprocessor/seq/seq.hpp>
 #include <boost/preprocessor/stringize.hpp>
 #include <boost/preprocessor/punctuation/paren.hpp>
 
-
 #define FC_FORMAT_ARG(r, unused, base) \
   BOOST_PP_STRINGIZE(base) ": ${" BOOST_PP_STRINGIZE( base ) "} "
 

libraries/libfc/src/log/logger.cpp

@@ -38,7 +38,7 @@ namespace fc {
     logger::logger( const logger& l )
     :my(l.my){}
 
-    logger::logger( logger&& l )
+    logger::logger( logger&& l ) noexcept
     :my(std::move(l.my)){}
 
     logger::~logger(){}
@@ -47,7 +47,7 @@ namespace fc {
        my = l.my;
        return *this;
     }
-    logger& logger::operator=( logger&& l ){
+    logger& logger::operator=( logger&& l ) noexcept {
        fc_swap(my,l.my);
        return *this;
     }

plugins/chain_plugin/chain_plugin.cpp

@@ -1171,6 +1171,7 @@ void chain_plugin::plugin_shutdown() {
 
 void chain_plugin::handle_sighup() {
    _deep_mind_log.update_logger( deep_mind_logger_name );
+   fc::logger::update(vote_logger.get_name(), vote_logger);
 }
 
 chain_apis::read_write::read_write(controller& db,

plugins/net_plugin/net_plugin.cpp

@@ -2682,7 +2682,8 @@ namespace eosio {
          if( cp->connection_id == exclude_peer ) return true;
          cp->strand.post( [cp, msg]() {
             if (cp->protocol_version >= proto_instant_finality) {
-               peer_dlog(cp, "sending vote msg");
+               if (vote_logger.is_enabled(fc::log_level::debug))
+                  peer_dlog(cp, "sending vote msg");
                cp->enqueue_buffer( msg, no_reason );
             }
          });
@@ -3741,9 +3742,11 @@ namespace eosio {
    }
 
    void connection::handle_message( const vote_message_ptr& msg ) {
-      peer_dlog(this, "received vote: block #${bn}:${id}.., ${v}, key ${k}..",
-                ("bn", block_header::num_from_id(msg->block_id))("id", msg->block_id.str().substr(8,16))
-                ("v", msg->strong ? "strong" : "weak")("k", msg->finalizer_key.to_string().substr(8, 16)));
+      if (vote_logger.is_enabled(fc::log_level::debug)) {
+         peer_dlog(this, "received vote: block #${bn}:${id}.., ${v}, key ${k}..",
+                   ("bn", block_header::num_from_id(msg->block_id))("id", msg->block_id.str().substr(8,16))
+                   ("v", msg->strong ? "strong" : "weak")("k", msg->finalizer_key.to_string().substr(8, 16)));
+      }
       controller& cc = my_impl->chain_plug->chain();
       cc.process_vote_message(connection_id, msg);
    }
@@ -4014,7 +4017,7 @@ namespace eosio {
 
    // called from other threads including net threads
    void net_plugin_impl::on_voted_block(uint32_t connection_id, vote_status status, const vote_message_ptr& msg) {
-      fc_dlog(logger, "connection - ${c} on voted signal: ${s} block #${bn} ${id}.., ${t}, key ${k}..",
+      fc_dlog(vote_logger, "connection - ${c} on voted signal: ${s} block #${bn} ${id}.., ${t}, key ${k}..",
                 ("c", connection_id)("s", status)("bn", block_header::num_from_id(msg->block_id))("id", msg->block_id.str().substr(8,16))
                 ("t", msg->strong ? "strong" : "weak")("k", msg->finalizer_key.to_string().substr(8, 16)));
 
@@ -4025,14 +4028,15 @@ namespace eosio {
       case vote_status::unknown_public_key:
       case vote_status::invalid_signature:
       case vote_status::max_exceeded:  // close peer immediately
+         fc_elog(vote_logger, "Exceeded max votes per connection for ${c}", ("c", connection_id));
          my_impl->connections.for_each_connection([connection_id](const connection_ptr& c) {
             if (c->connection_id == connection_id) {
                c->close( false );
             }
          });
          break;
       case vote_status::unknown_block: // track the failure
-         fc_dlog(logger, "connection - ${c} vote unknown block #${bn}:${id}..",
+         fc_dlog(vote_logger, "connection - ${c} vote unknown block #${bn}:${id}..",
                  ("c", connection_id)("bn", block_header::num_from_id(msg->block_id))("id", msg->block_id.str().substr(8,16)));
          my_impl->connections.for_each_connection([connection_id](const connection_ptr& c) {
             if (c->connection_id == connection_id) {
@@ -4051,7 +4055,7 @@ namespace eosio {
       buffer_factory buff_factory;
       auto send_buffer = buff_factory.get_send_buffer( *msg );
 
-      fc_dlog(logger, "bcast ${t} vote: block #${bn} ${id}.., ${v}, key ${k}..",
+      fc_dlog(vote_logger, "bcast ${t} vote: block #${bn} ${id}.., ${v}, key ${k}..",
                 ("t", exclude_peer ? "received" : "our")("bn", block_header::num_from_id(msg->block_id))("id", msg->block_id.str().substr(8,16))
                 ("v", msg->strong ? "strong" : "weak")("k", msg->finalizer_key.to_string().substr(8,16)));
 

plugins/producer_plugin/producer_plugin.cpp

@@ -78,9 +78,6 @@ fc::logger        _transient_trx_successful_trace_log;
 const std::string transient_trx_failed_trace_logger_name("transient_trx_failure_tracing");
 fc::logger        _transient_trx_failed_trace_log;
 
-const std::string hotstuff_logger_name("hotstuff");
-fc::logger hotstuff_logger;
-
 namespace eosio {
 
 static auto _producer_plugin = application::register_plugin<producer_plugin>();
@@ -1437,7 +1434,6 @@ void producer_plugin::handle_sighup() {
    fc::logger::update(trx_logger_name, _trx_log);
    fc::logger::update(transient_trx_successful_trace_logger_name, _transient_trx_successful_trace_log);
    fc::logger::update(transient_trx_failed_trace_logger_name, _transient_trx_failed_trace_log);
-   fc::logger::update( hotstuff_logger_name, hotstuff_logger );
 }
 
 void producer_plugin::pause() {

programs/nodeos/logging.json

@@ -159,7 +159,7 @@
       "net"
       ]
     },{
-    "name": "hotstuff",
+    "name": "vote",
     "level": "debug",
     "enabled": true,
     "additivity": false,

tests/TestHarness/logging-template.json

@@ -138,8 +138,8 @@
          "stderr"
         ]
     },{
-       "name": "hotstuff",
-       "level": "all",
+       "name": "vote",
+       "level": "debug",
        "enabled": true,
        "additivity": false,
        "appenders": [

unittests/block_state_tests.cpp

@@ -47,7 +47,7 @@ BOOST_AUTO_TEST_CASE(aggregate_vote_test) try {
          bool strong = (i % 2 == 0); // alternate strong and weak
          auto sig = strong ? private_key[i].sign(strong_digest.to_uint8_span()) : private_key[i].sign(weak_digest);
          vote_message vote{ block_id, strong, public_key[i], sig };
-         BOOST_REQUIRE(bsp->aggregate_vote(vote) == vote_status::success);
+         BOOST_REQUIRE(bsp->aggregate_vote(0, vote) == vote_status::success);
       }
    }
 
@@ -58,7 +58,7 @@ BOOST_AUTO_TEST_CASE(aggregate_vote_test) try {
       bsp->pending_qc = pending_quorum_certificate{ num_finalizers, 1, bsp->active_finalizer_policy->max_weak_sum_before_weak_final() };
 
       vote_message vote {block_id, true, public_key[0], private_key[1].sign(strong_digest.to_uint8_span()) };
-      BOOST_REQUIRE(bsp->aggregate_vote(vote) != vote_status::success);
+      BOOST_REQUIRE(bsp->aggregate_vote(0, vote) != vote_status::success);
    }
 
    {  // duplicate votes 
@@ -68,8 +68,8 @@ BOOST_AUTO_TEST_CASE(aggregate_vote_test) try {
       bsp->pending_qc = pending_quorum_certificate{ num_finalizers, 1, bsp->active_finalizer_policy->max_weak_sum_before_weak_final() };
 
       vote_message vote {block_id, true, public_key[0], private_key[0].sign(strong_digest.to_uint8_span()) };
-      BOOST_REQUIRE(bsp->aggregate_vote(vote) == vote_status::success);
-      BOOST_REQUIRE(bsp->aggregate_vote(vote) != vote_status::success);
+      BOOST_REQUIRE(bsp->aggregate_vote(0, vote) == vote_status::success);
+      BOOST_REQUIRE(bsp->aggregate_vote(0, vote) != vote_status::success);
    }
 
    {  // public key does not exit in finalizer set
@@ -82,7 +82,7 @@ BOOST_AUTO_TEST_CASE(aggregate_vote_test) try {
       bls_public_key new_public_key{ new_private_key.get_public_key() };
 
       vote_message vote {block_id, true, new_public_key, private_key[0].sign(strong_digest.to_uint8_span()) };
-      BOOST_REQUIRE(bsp->aggregate_vote(vote) != vote_status::success);
+      BOOST_REQUIRE(bsp->aggregate_vote(0, vote) != vote_status::success);
    }
 } FC_LOG_AND_RETHROW();
 
@@ -125,7 +125,7 @@ void do_quorum_test(const std::vector<uint64_t>& weights,
       if( to_vote[i] ) {
          auto sig = strong ? private_key[i].sign(strong_digest.to_uint8_span()) : private_key[i].sign(weak_digest);
          vote_message vote{ block_id, strong, public_key[i], sig };
-         BOOST_REQUIRE(bsp->aggregate_vote(vote) == vote_status::success);
+         BOOST_REQUIRE(bsp->aggregate_vote(0, vote) == vote_status::success);
       }
    }