From 8f8526b587d63c7bc210d9dc18289d50a052ec11 Mon Sep 17 00:00:00 2001 From: Kevin Heifner Date: Mon, 15 Apr 2024 08:06:55 -0500 Subject: [PATCH] GH-14 Replaced hotstuff logger with vote logger. Moved existing vote related logging to vote_logger. --- libraries/chain/block_state.cpp | 4 ++-- libraries/chain/hotstuff/hotstuff.cpp | 6 +++--- .../include/eosio/chain/hotstuff/hotstuff.hpp | 2 ++ .../include/eosio/chain/vote_processor.hpp | 1 - plugins/chain_plugin/chain_plugin.cpp | 1 + plugins/net_plugin/net_plugin.cpp | 18 +++++++++++------- plugins/producer_plugin/producer_plugin.cpp | 4 ---- programs/nodeos/logging.json | 2 +- tests/TestHarness/logging-template.json | 4 ++-- 9 files changed, 22 insertions(+), 20 deletions(-) diff --git a/libraries/chain/block_state.cpp b/libraries/chain/block_state.cpp index 5c09ab633a..5dd64e9993 100644 --- a/libraries/chain/block_state.cpp +++ b/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; } } diff --git a/libraries/chain/hotstuff/hotstuff.cpp b/libraries/chain/hotstuff/hotstuff.cpp index 5cf54e7094..92e27ee28c 100644 --- a/libraries/chain/hotstuff/hotstuff.cpp +++ b/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 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; } diff --git a/libraries/chain/include/eosio/chain/hotstuff/hotstuff.hpp b/libraries/chain/include/eosio/chain/hotstuff/hotstuff.hpp index 4a2a148cd4..e0e327854f 100644 --- a/libraries/chain/include/eosio/chain/hotstuff/hotstuff.hpp +++ b/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; diff --git a/libraries/chain/include/eosio/chain/vote_processor.hpp b/libraries/chain/include/eosio/chain/vote_processor.hpp index af076b207e..55dc6d919c 100644 --- a/libraries/chain/include/eosio/chain/vote_processor.hpp +++ b/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 diff --git a/plugins/chain_plugin/chain_plugin.cpp b/plugins/chain_plugin/chain_plugin.cpp index 526bd18104..ec2fd4ced1 100644 --- a/plugins/chain_plugin/chain_plugin.cpp +++ b/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, diff --git a/plugins/net_plugin/net_plugin.cpp b/plugins/net_plugin/net_plugin.cpp index 67c70fb8ae..5e8672e6cd 100644 --- a/plugins/net_plugin/net_plugin.cpp +++ b/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,6 +4016,7 @@ 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 ); @@ -4020,7 +4024,7 @@ namespace eosio { }); 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))); diff --git a/plugins/producer_plugin/producer_plugin.cpp b/plugins/producer_plugin/producer_plugin.cpp index 91f23c1798..891d4de45a 100644 --- a/plugins/producer_plugin/producer_plugin.cpp +++ b/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(); @@ -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() { diff --git a/programs/nodeos/logging.json b/programs/nodeos/logging.json index 95de98eb68..42707b376f 100644 --- a/programs/nodeos/logging.json +++ b/programs/nodeos/logging.json @@ -159,7 +159,7 @@ "net" ] },{ - "name": "hotstuff", + "name": "vote", "level": "debug", "enabled": true, "additivity": false, diff --git a/tests/TestHarness/logging-template.json b/tests/TestHarness/logging-template.json index 79250422fa..aad42b487a 100644 --- a/tests/TestHarness/logging-template.json +++ b/tests/TestHarness/logging-template.json @@ -138,8 +138,8 @@ "stderr" ] },{ - "name": "hotstuff", - "level": "all", + "name": "vote", + "level": "debug", "enabled": true, "additivity": false, "appenders": [