From 51728b5272d9ddef2795403709a11fa5cc78f6a4 Mon Sep 17 00:00:00 2001 From: Kevin Heifner Date: Sat, 13 Apr 2024 14:21:58 -0500 Subject: [PATCH 1/8] GH-14 Avoid one mutex lock and std::string construction on every log call. Remove unused ulog. --- libraries/libfc/include/fc/log/logger.hpp | 35 +++++++---------------- 1 file changed, 11 insertions(+), 24 deletions(-) diff --git a/libraries/libfc/include/fc/log/logger.hpp b/libraries/libfc/include/fc/log/logger.hpp index bf22ba1bf7..87a251796e 100644 --- a/libraries/libfc/include/fc/log/logger.hpp +++ b/libraries/libfc/include/fc/log/logger.hpp @@ -3,9 +3,7 @@ #include #include -#ifndef DEFAULT_LOGGER -#define DEFAULT_LOGGER "default" -#endif +inline std::string DEFAULT_LOGGER = "default"; namespace fc { @@ -106,43 +104,32 @@ 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__ ) ); \ + 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 -/** - * 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__ ) ); \ - 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 From b9a4ea6feb5e325eb7aa6994e3854a311b94341a Mon Sep 17 00:00:00 2001 From: Kevin Heifner Date: Sat, 13 Apr 2024 14:22:53 -0500 Subject: [PATCH 2/8] GH-14 Add connection id to vote log output --- libraries/chain/block_state.cpp | 7 ++++--- libraries/chain/hotstuff/hotstuff.cpp | 17 ++++++++--------- .../chain/hotstuff/test/finality_misc_tests.cpp | 4 ++-- .../chain/include/eosio/chain/block_state.hpp | 2 +- .../include/eosio/chain/hotstuff/hotstuff.hpp | 3 ++- .../include/eosio/chain/vote_processor.hpp | 2 +- unittests/block_state_tests.cpp | 12 ++++++------ 7 files changed, 24 insertions(+), 23 deletions(-) diff --git a/libraries/chain/block_state.cpp b/libraries/chain/block_state.cpp index 4735e81de4..5c09ab633a 100644 --- a/libraries/chain/block_state.cpp +++ b/libraries/chain/block_state.cpp @@ -141,8 +141,8 @@ void block_state::set_trxs_metas( deque&& 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(), @@ -151,7 +151,8 @@ 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(weak_digest); - return pending_qc.add_vote(block_num(), + return pending_qc.add_vote(connection_id, + block_num(), vote.strong, digest, index, diff --git a/libraries/chain/hotstuff/hotstuff.cpp b/libraries/chain/hotstuff/hotstuff.cpp index ca39f7d93f..5cf54e7094 100644 --- a/libraries/chain/hotstuff/hotstuff.cpp +++ b/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 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 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)); + dlog("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) ); + wlog("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))); + dlog("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/hotstuff/test/finality_misc_tests.cpp b/libraries/chain/hotstuff/test/finality_misc_tests.cpp index ba58a06ed5..a86f9b230d 100644 --- a/libraries/chain/hotstuff/test/finality_misc_tests.cpp +++ b/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& 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& 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; diff --git a/libraries/chain/include/eosio/chain/block_state.hpp b/libraries/chain/include/eosio/chain/block_state.hpp index a212f1655f..0326c758af 100644 --- a/libraries/chain/include/eosio/chain/block_state.hpp +++ b/libraries/chain/include/eosio/chain/block_state.hpp @@ -125,7 +125,7 @@ struct block_state : public block_header_state { // block_header_state provi finality_data_t get_finality_data(); // vote_status - vote_status aggregate_vote(const vote_message& vote); // aggregate vote into pending_qc + 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 diff --git a/libraries/chain/include/eosio/chain/hotstuff/hotstuff.hpp b/libraries/chain/include/eosio/chain/hotstuff/hotstuff.hpp index 9e8682b905..4a2a148cd4 100644 --- a/libraries/chain/include/eosio/chain/hotstuff/hotstuff.hpp +++ b/libraries/chain/include/eosio/chain/hotstuff/hotstuff.hpp @@ -118,7 +118,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 proposal_digest, size_t index, diff --git a/libraries/chain/include/eosio/chain/vote_processor.hpp b/libraries/chain/include/eosio/chain/vote_processor.hpp index 793705acbc..af076b207e 100644 --- a/libraries/chain/include/eosio/chain/vote_processor.hpp +++ b/libraries/chain/include/eosio/chain/vote_processor.hpp @@ -181,7 +181,7 @@ class vote_processor_t { g.unlock(); // do not hold lock when posting for (auto& v : to_process) { boost::asio::post(thread_pool.get_executor(), [this, bsp, v=std::move(v)]() { - vote_status s = bsp->aggregate_vote(*v.msg); + vote_status s = bsp->aggregate_vote(v.connection_id, *v.msg); if (s != vote_status::duplicate) { // don't bother emitting duplicates emit(v.connection_id, s, v.msg); } diff --git a/unittests/block_state_tests.cpp b/unittests/block_state_tests.cpp index 434dace32b..51e073dd98 100644 --- a/unittests/block_state_tests.cpp +++ b/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& 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); } } From 8deae48c58f174926fda599de5ea3307847b0f63 Mon Sep 17 00:00:00 2001 From: Kevin Heifner Date: Sat, 13 Apr 2024 14:30:57 -0500 Subject: [PATCH 3/8] GH-14 Remove unneeded includes --- libraries/libfc/include/fc/log/logger.hpp | 8 ++------ 1 file changed, 2 insertions(+), 6 deletions(-) diff --git a/libraries/libfc/include/fc/log/logger.hpp b/libraries/libfc/include/fc/log/logger.hpp index 87a251796e..f4a66c37ec 100644 --- a/libraries/libfc/include/fc/log/logger.hpp +++ b/libraries/libfc/include/fc/log/logger.hpp @@ -30,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 ); @@ -133,13 +133,9 @@ namespace fc FC_MULTILINE_MACRO_END #include -#include -#include -#include #include #include - #define FC_FORMAT_ARG(r, unused, base) \ BOOST_PP_STRINGIZE(base) ": ${" BOOST_PP_STRINGIZE( base ) "} " From 9249e47d808e97220b0080dc08510f2a121e5480 Mon Sep 17 00:00:00 2001 From: Kevin Heifner Date: Sat, 13 Apr 2024 14:31:31 -0500 Subject: [PATCH 4/8] GH-14 Add noexcept --- libraries/libfc/src/log/logger.cpp | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/libraries/libfc/src/log/logger.cpp b/libraries/libfc/src/log/logger.cpp index 5b04382e61..f68e3b996b 100644 --- a/libraries/libfc/src/log/logger.cpp +++ b/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; } From 8f8526b587d63c7bc210d9dc18289d50a052ec11 Mon Sep 17 00:00:00 2001 From: Kevin Heifner Date: Mon, 15 Apr 2024 08:06:55 -0500 Subject: [PATCH 5/8] 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": [ From c8975e6c570b15aabd7c206ade1925d869f812e7 Mon Sep 17 00:00:00 2001 From: Kevin Heifner Date: Mon, 15 Apr 2024 09:00:39 -0500 Subject: [PATCH 6/8] GH-14 Log connection id --- libraries/chain/block_state.cpp | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/libraries/chain/block_state.cpp b/libraries/chain/block_state.cpp index 5dd64e9993..51eb66934c 100644 --- a/libraries/chain/block_state.cpp +++ b/libraries/chain/block_state.cpp @@ -160,7 +160,8 @@ vote_status block_state::aggregate_vote(uint32_t connection_id, const vote_messa vote.sig, finalizers[index].weight); } else { - fc_wlog(vote_logger, "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; } } From 3e6d8368bd7989968b4a2cae304153c38c949317 Mon Sep 17 00:00:00 2001 From: Kevin Heifner Date: Mon, 15 Apr 2024 09:37:17 -0500 Subject: [PATCH 7/8] GH-14 Add comment that connection_id only for logging --- libraries/chain/include/eosio/chain/block_state.hpp | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/libraries/chain/include/eosio/chain/block_state.hpp b/libraries/chain/include/eosio/chain/block_state.hpp index 0326c758af..97a543c944 100644 --- a/libraries/chain/include/eosio/chain/block_state.hpp +++ b/libraries/chain/include/eosio/chain/block_state.hpp @@ -124,7 +124,7 @@ 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 + // 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 From 6eb9d324baa38641c8595a1e09af11d0026dad4d Mon Sep 17 00:00:00 2001 From: Kevin Heifner Date: Fri, 19 Apr 2024 07:21:57 -0500 Subject: [PATCH 8/8] GH-14 Fix merge issue --- libraries/chain/include/eosio/chain/vote_processor.hpp | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/libraries/chain/include/eosio/chain/vote_processor.hpp b/libraries/chain/include/eosio/chain/vote_processor.hpp index 6db78e286e..c6078e148d 100644 --- a/libraries/chain/include/eosio/chain/vote_processor.hpp +++ b/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();