GH-14 Replaced hotstuff logger with vote logger. Moved existing vote …

…related logging to vote_logger.

libraries/chain/block_state.cpp

@@ -46,7 +46,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 ));
    }
 
@@ -160,7 +160,7 @@ vote_status block_state::aggregate_vote(uint32_t connection_id, const vote_messa
                                  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, "finalizer_key (${k}) in vote is not in finalizer policy", ("k", vote.finalizer_key));
       return vote_status::unknown_public_key;
    }
 }

libraries/chain/hotstuff/hotstuff.cpp

@@ -141,12 +141,12 @@ vote_status pending_quorum_certificate::add_vote(uint32_t connection_id, block_n
                                                  bool strong, std::span<const uint8_t> proposal_digest, size_t index,
                                                  const bls_public_key& pubkey, const bls_signature& sig, uint64_t weight) {
    if (has_voted_no_lock(strong, index)) {
-      dlog("connection - ${c} block_num: ${bn}, duplicate", ("c", connection_id)("bn", block_num));
+      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("connection - ${c} signature from finalizer ${k}.. cannot be verified", ("k", pubkey.to_string().substr(8,16)));
+      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;
    }
 
@@ -157,7 +157,7 @@ vote_status pending_quorum_certificate::add_vote(uint32_t connection_id, block_n
    state_t post_state = _state;
    g.unlock();
 
-   dlog("connection - ${c} block_num: ${bn}, vote strong: ${sv}, status: ${s}, pre-state: ${pre}, post-state: ${state}, quorum_met: ${q}",
+   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/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;

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

@@ -215,7 +215,6 @@ class vote_processor_t {
             remove_connection(connection_id);
             g.unlock();
 
-            elog("Exceeded max votes per connection for ${c}", ("c", connection_id));
             emit(connection_id, vote_status::max_exceeded, msg);
          } else if (block_header::num_from_id(msg->block_id) < lib.load(std::memory_order_relaxed)) {
             // ignore

plugins/chain_plugin/chain_plugin.cpp

@@ -1168,6 +1168,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

@@ -2672,7 +2672,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 );
             }
          });
@@ -3731,9 +3732,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);
    }
@@ -4002,7 +4005,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)));
 
@@ -4013,14 +4016,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) {
@@ -4039,7 +4043,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": [