From 060b3d561e8cbc96b47ab1b3b30837f4860ffb62 Mon Sep 17 00:00:00 2001 From: Lin Huang Date: Thu, 15 Aug 2024 09:52:42 -0400 Subject: [PATCH 1/3] Better logging for aggregate_vote failure and add logging for proposer policy becoming active --- libraries/chain/block_header_state.cpp | 12 ++++++++++-- libraries/chain/block_state.cpp | 2 +- libraries/chain/finality/qc.cpp | 12 +++++++----- libraries/chain/include/eosio/chain/finality/qc.hpp | 2 +- 4 files changed, 19 insertions(+), 9 deletions(-) diff --git a/libraries/chain/block_header_state.cpp b/libraries/chain/block_header_state.cpp index 3821b16c38..b5522e3831 100644 --- a/libraries/chain/block_header_state.cpp +++ b/libraries/chain/block_header_state.cpp @@ -338,9 +338,17 @@ void finish_next(const block_header_state& prev, if (next_header_state.active_finalizer_policy != prev.active_finalizer_policy) { const auto& act = next_header_state.active_finalizer_policy; - ilog("Finalizer policy generation change: ${old_gen} -> ${new_gen}", + dlog("Finalizer policy generation change: ${old_gen} -> ${new_gen}", ("old_gen", prev.active_finalizer_policy->generation)("new_gen",act->generation)); - ilog("New finalizer policy becoming active in block ${n}:${id}: ${pol}", + dlog("New finalizer policy becoming active in block ${n}:${id}: ${pol}", + ("n",block_header::num_from_id(id))("id", id)("pol", *act)); + } + + if (next_header_state.active_proposer_policy != prev.active_proposer_policy) { + const auto& act = next_header_state.active_proposer_policy; + dlog("Proposer policy version change: ${old_ver} -> ${new_ver}", + ("old_ver", prev.active_proposer_policy->proposer_schedule.version)("new_ver",act->proposer_schedule.version)); + dlog("New proposer policy becoming active in block ${n}:${id}: ${pol}", ("n",block_header::num_from_id(id))("id", id)("pol", *act)); } } diff --git a/libraries/chain/block_state.cpp b/libraries/chain/block_state.cpp index c1034ae81d..ac7f51652f 100644 --- a/libraries/chain/block_state.cpp +++ b/libraries/chain/block_state.cpp @@ -177,7 +177,7 @@ void block_state::set_trxs_metas( deque&& trxs_metas, // Called from vote threads aggregate_vote_result_t block_state::aggregate_vote(uint32_t connection_id, const vote_message& vote) { auto finalizer_digest = vote.strong ? strong_digest.to_uint8_span() : std::span(weak_digest); - return aggregating_qc.aggregate_vote(connection_id, vote, block_num(), finalizer_digest); + return aggregating_qc.aggregate_vote(connection_id, vote, block_id, finalizer_digest); } // Only used for testing diff --git a/libraries/chain/finality/qc.cpp b/libraries/chain/finality/qc.cpp index 1eac72aab7..48eaa817af 100644 --- a/libraries/chain/finality/qc.cpp +++ b/libraries/chain/finality/qc.cpp @@ -1,5 +1,6 @@ #include #include +#include #include namespace eosio::chain { @@ -429,15 +430,16 @@ bool aggregating_qc_t::received_qc_is_strong() const { } aggregate_vote_result_t aggregating_qc_t::aggregate_vote(uint32_t connection_id, const vote_message& vote, - block_num_type block_num, std::span finalizer_digest) + const block_id_type& block_id, std::span finalizer_digest) { aggregate_vote_result_t r; + block_num_type block_num = block_header::num_from_id(block_id); bool verified_sig = false; auto verify_sig = [&]() -> vote_result_t { if (!verified_sig && !fc::crypto::blslib::verify(vote.finalizer_key, finalizer_digest, vote.sig)) { - fc_wlog(vote_logger, "connection - ${c} signature from finalizer ${k}.. cannot be verified", - ("c", connection_id)("k", vote.finalizer_key.to_string().substr(8,16))); + fc_wlog(vote_logger, "connection - ${c} block_num: ${bn} block_id: ${id}, signature from finalizer ${k}.. cannot be verified, vote strong: ${sv}", + ("c", connection_id)("bn", block_num)("id", block_id)("k", vote.finalizer_key.to_string().substr(8,16))("sv", vote.strong)); return vote_result_t::invalid_signature; } verified_sig = true; @@ -452,8 +454,8 @@ aggregate_vote_result_t aggregating_qc_t::aggregate_vote(uint32_t connection_id, auth = finalizer_authority_ptr{finalizer_policy, &(*itr)}; // use aliasing shared_ptr constructor auto index = std::distance(finalizers.begin(), itr); if (agg_qc_sig.has_voted(index)) { - fc_tlog(vote_logger, "connection - ${c} block_num: ${bn}, duplicate finalizer ${k}..", - ("c", connection_id)("bn", block_num)("k", vote.finalizer_key.to_string().substr(8,16))); + fc_tlog(vote_logger, "connection - ${c} block_num: ${bn} block_id: ${id}, duplicate finalizer ${k}..", + ("c", connection_id)("bn", block_num)("id", block_id)("k", vote.finalizer_key.to_string().substr(8,16))); return vote_result_t::duplicate; } if (vote_result_t vs = verify_sig(); vs != vote_result_t::success) diff --git a/libraries/chain/include/eosio/chain/finality/qc.hpp b/libraries/chain/include/eosio/chain/finality/qc.hpp index cbff21bc3e..7c7c4833e6 100644 --- a/libraries/chain/include/eosio/chain/finality/qc.hpp +++ b/libraries/chain/include/eosio/chain/finality/qc.hpp @@ -258,7 +258,7 @@ namespace eosio::chain { bool set_received_qc(const qc_t& qc); bool received_qc_is_strong() const; aggregate_vote_result_t aggregate_vote(uint32_t connection_id, const vote_message& vote, - block_num_type block_num, std::span finalizer_digest); + const block_id_type& block_id, std::span finalizer_digest); vote_status_t has_voted(const bls_public_key& key) const; bool is_quorum_met() const; From cb6c6c48bd6b7b2c92d590f934bc10421f207ccd Mon Sep 17 00:00:00 2001 From: Lin Huang Date: Thu, 15 Aug 2024 10:10:17 -0400 Subject: [PATCH 2/3] revert to ilog for finalizer_policy becoming active --- libraries/chain/block_header_state.cpp | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/libraries/chain/block_header_state.cpp b/libraries/chain/block_header_state.cpp index b5522e3831..c540c3c0e7 100644 --- a/libraries/chain/block_header_state.cpp +++ b/libraries/chain/block_header_state.cpp @@ -338,9 +338,9 @@ void finish_next(const block_header_state& prev, if (next_header_state.active_finalizer_policy != prev.active_finalizer_policy) { const auto& act = next_header_state.active_finalizer_policy; - dlog("Finalizer policy generation change: ${old_gen} -> ${new_gen}", + ilog("Finalizer policy generation change: ${old_gen} -> ${new_gen}", ("old_gen", prev.active_finalizer_policy->generation)("new_gen",act->generation)); - dlog("New finalizer policy becoming active in block ${n}:${id}: ${pol}", + ilog("New finalizer policy becoming active in block ${n}:${id}: ${pol}", ("n",block_header::num_from_id(id))("id", id)("pol", *act)); } From 87ecd378c4ea72d213aabbba68f161273bb6e27d Mon Sep 17 00:00:00 2001 From: Lin Huang Date: Thu, 15 Aug 2024 10:52:39 -0400 Subject: [PATCH 3/3] User proposer_schedule.version for comparison --- libraries/chain/block_header_state.cpp | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/libraries/chain/block_header_state.cpp b/libraries/chain/block_header_state.cpp index c540c3c0e7..c0fa591eb5 100644 --- a/libraries/chain/block_header_state.cpp +++ b/libraries/chain/block_header_state.cpp @@ -344,7 +344,7 @@ void finish_next(const block_header_state& prev, ("n",block_header::num_from_id(id))("id", id)("pol", *act)); } - if (next_header_state.active_proposer_policy != prev.active_proposer_policy) { + if (next_header_state.active_proposer_policy->proposer_schedule.version != prev.active_proposer_policy->proposer_schedule.version) { const auto& act = next_header_state.active_proposer_policy; dlog("Proposer policy version change: ${old_ver} -> ${new_ver}", ("old_ver", prev.active_proposer_policy->proposer_schedule.version)("new_ver",act->proposer_schedule.version));