From 2890684042f3c883a137b3bd8a94cbc5e429c300 Mon Sep 17 00:00:00 2001 From: Kevin Heifner Date: Wed, 12 Jun 2024 19:44:24 -0500 Subject: [PATCH 1/4] GH-278 Use chain_head instead of fork_db head for syncing so we do not get too far ahead of chain_head --- plugins/net_plugin/net_plugin.cpp | 78 ++++++++++++++++++------------- 1 file changed, 46 insertions(+), 32 deletions(-) diff --git a/plugins/net_plugin/net_plugin.cpp b/plugins/net_plugin/net_plugin.cpp index e6c401f08a..9a23294f2e 100644 --- a/plugins/net_plugin/net_plugin.cpp +++ b/plugins/net_plugin/net_plugin.cpp @@ -9,7 +9,6 @@ #include #include #include -#include #include #include @@ -512,10 +511,12 @@ namespace eosio { struct chain_info_t { - uint32_t lib_num = 0; block_id_type lib_id; - uint32_t head_num = 0; + uint32_t lib_num = 0; block_id_type head_id; + uint32_t head_num = 0; + block_id_type fork_head_id; + uint32_t fork_head_num = 0; }; @@ -533,6 +534,7 @@ namespace eosio { chain_info_t get_chain_info() const; uint32_t get_chain_lib_num() const; uint32_t get_chain_head_num() const; + uint32_t get_fork_head_num() const; void on_accepted_block_header( const signed_block_ptr& block, const block_id_type& id ); void on_accepted_block( const signed_block_ptr& block, const block_id_type& id ); @@ -1499,7 +1501,7 @@ namespace eosio { // called from connection strand void connection::blk_send_branch( const block_id_type& msg_head_id ) { - uint32_t head_num = my_impl->get_chain_head_num(); + uint32_t head_num = my_impl->get_fork_head_num(); peer_dlog(this, "head_num = ${h}",("h",head_num)); if(head_num == 0) { @@ -2145,11 +2147,11 @@ namespace eosio { auto chain_info = my_impl->get_chain_info(); fc_dlog( logger, "sync_last_requested_num: ${r}, sync_next_expected_num: ${e}, sync_known_lib_num: ${k}, sync_req_span: ${s}, head: ${h}, lib: ${lib}", - ("r", sync_last_requested_num)("e", sync_next_expected_num)("k", sync_known_lib_num)("s", sync_req_span)("h", chain_info.head_num)("lib", chain_info.lib_num) ); + ("r", sync_last_requested_num)("e", sync_next_expected_num)("k", sync_known_lib_num)("s", sync_req_span)("h", chain_info.fork_head_num)("lib", chain_info.lib_num) ); - if( chain_info.head_num + sync_req_span < sync_last_requested_num && sync_source && sync_source->current() ) { + if( chain_info.fork_head_num + sync_req_span < sync_last_requested_num && sync_source && sync_source->current() ) { fc_dlog( logger, "ignoring request, head is ${h} last req = ${r}, sync_next_expected_num: ${e}, sync_known_lib_num: ${k}, sync_req_span: ${s}, source connection ${c}", - ("h", chain_info.head_num)("r", sync_last_requested_num)("e", sync_next_expected_num) + ("h", chain_info.fork_head_num)("r", sync_last_requested_num)("e", sync_next_expected_num) ("k", sync_known_lib_num)("s", sync_req_span)("c", sync_source->connection_id) ); return; } @@ -2157,7 +2159,7 @@ namespace eosio { if (conn) { // p2p_high_latency_test.py test depends on this exact log statement. peer_ilog(conn, "Catching up with chain, our last req is ${cc}, theirs is ${t}, next expected ${n}, head ${h}", - ("cc", sync_last_requested_num)("t", sync_known_lib_num)("n", sync_next_expected_num)("h", chain_info.head_num)); + ("cc", sync_last_requested_num)("t", sync_known_lib_num)("n", sync_next_expected_num)("h", chain_info.fork_head_num)); } /* ---------- @@ -2189,7 +2191,7 @@ namespace eosio { sync_last_requested_num = end; sync_source = new_sync_source; request_sent = true; - new_sync_source->strand.post( [new_sync_source, start, end, head_num=chain_info.head_num, lib=chain_info.lib_num]() { + new_sync_source->strand.post( [new_sync_source, start, end, head_num=chain_info.fork_head_num, lib=chain_info.lib_num]() { peer_ilog( new_sync_source, "requesting range ${s} to ${e}, head ${h}, lib ${lib}", ("s", start)("e", end)("h", head_num)("lib", lib) ); new_sync_source->request_sync_blocks( start, end ); } ); @@ -2288,16 +2290,16 @@ namespace eosio { // //----------------------------- - if (chain_info.head_id == msg.head_id) { + if (chain_info.fork_head_id == msg.head_id) { peer_ilog( c, "handshake lib ${lib}, head ${head}, head id ${id}.. sync 0, lib ${l}", ("lib", msg.last_irreversible_block_num)("head", msg.head_num)("id", msg.head_id.str().substr(8,16))("l", chain_info.lib_num) ); c->peer_syncing_from_us = false; return; } - if (chain_info.head_num < msg.last_irreversible_block_num) { + if (chain_info.fork_head_num < msg.last_irreversible_block_num) { peer_ilog( c, "handshake lib ${lib}, head ${head}, head id ${id}.. sync 1, head ${h}, lib ${l}", ("lib", msg.last_irreversible_block_num)("head", msg.head_num)("id", msg.head_id.str().substr(8,16)) - ("h", chain_info.head_num)("l", chain_info.lib_num) ); + ("h", chain_info.fork_head_num)("l", chain_info.lib_num) ); c->peer_syncing_from_us = false; if (c->sent_handshake_count > 0) { c->send_handshake(); @@ -2307,15 +2309,15 @@ namespace eosio { if (chain_info.lib_num > msg.head_num + nblk_combined_latency + min_blocks_distance) { peer_ilog( c, "handshake lib ${lib}, head ${head}, head id ${id}.. sync 2, head ${h}, lib ${l}", ("lib", msg.last_irreversible_block_num)("head", msg.head_num)("id", msg.head_id.str().substr(8,16)) - ("h", chain_info.head_num)("l", chain_info.lib_num) ); + ("h", chain_info.fork_head_num)("l", chain_info.lib_num) ); if (msg.generation > 1 || c->protocol_version > proto_base) { controller& cc = my_impl->chain_plug->chain(); notice_message note; note.known_trx.pending = chain_info.lib_num; note.known_trx.mode = last_irr_catch_up; note.known_blocks.mode = last_irr_catch_up; - note.known_blocks.pending = chain_info.head_num; - note.known_blocks.ids.push_back(chain_info.head_id); + note.known_blocks.pending = chain_info.fork_head_num; + note.known_blocks.ids.push_back(chain_info.fork_head_id); if (c->protocol_version >= proto_block_range) { // begin, more efficient to encode a block num instead of retrieving actual block id note.known_blocks.ids.push_back(make_block_id(cc.earliest_available_block_num())); @@ -2326,24 +2328,24 @@ namespace eosio { return; } - if (chain_info.head_num + nblk_combined_latency < msg.head_num ) { + if (chain_info.fork_head_num + nblk_combined_latency < msg.head_num ) { peer_ilog( c, "handshake lib ${lib}, head ${head}, head id ${id}.. sync 3, head ${h}, lib ${l}", ("lib", msg.last_irreversible_block_num)("head", msg.head_num)("id", msg.head_id.str().substr(8,16)) - ("h", chain_info.head_num)("l", chain_info.lib_num) ); + ("h", chain_info.fork_head_num)("l", chain_info.lib_num) ); c->peer_syncing_from_us = false; verify_catchup(c, msg.head_num, msg.head_id); return; - } else if(chain_info.head_num >= msg.head_num + nblk_combined_latency) { + } else if(chain_info.fork_head_num >= msg.head_num + nblk_combined_latency) { peer_ilog( c, "handshake lib ${lib}, head ${head}, head id ${id}.. sync 4, head ${h}, lib ${l}", ("lib", msg.last_irreversible_block_num)("head", msg.head_num)("id", msg.head_id.str().substr(8,16)) - ("h", chain_info.head_num)("l", chain_info.lib_num) ); + ("h", chain_info.fork_head_num)("l", chain_info.lib_num) ); if (msg.generation > 1 || c->protocol_version > proto_base) { controller& cc = my_impl->chain_plug->chain(); notice_message note; note.known_trx.mode = none; note.known_blocks.mode = catch_up; - note.known_blocks.pending = chain_info.head_num; - note.known_blocks.ids.push_back(chain_info.head_id); + note.known_blocks.pending = chain_info.fork_head_num; + note.known_blocks.ids.push_back(chain_info.fork_head_id); if (c->protocol_version >= proto_block_range) { // begin, more efficient to encode a block num instead of retrieving actual block id note.known_blocks.ids.push_back(make_block_id(cc.earliest_available_block_num())); @@ -2404,7 +2406,7 @@ namespace eosio { c->fork_head_num = num; } - req.req_blocks.ids.emplace_back( chain_info.head_id ); + req.req_blocks.ids.emplace_back( chain_info.fork_head_id ); } else { peer_ilog( c, "none notice while in ${s}, head num = ${hn}, id ${id}...", ("s", stage_str( sync_state ))("hn", num)("id", id.str().substr(8,16)) ); @@ -2554,6 +2556,7 @@ namespace eosio { } } + // use chain head instead of fork head so we do not get too far ahead of applied blocks uint32_t head = my_impl->get_chain_head_num(); if (head + sync_req_span > sync_last_requested_num) { // don't allow to get too far head (one sync_req_span) if (sync_next_expected_num > sync_last_requested_num && sync_last_requested_num < sync_known_lib_num) { @@ -3153,10 +3156,10 @@ namespace eosio { pending_message_buffer.advance_read_ptr( message_length ); return true; } - peer_dlog( this, "received block ${num}, id ${id}..., latency: ${latency}ms, head ${h}", + peer_dlog( this, "received block ${num}, id ${id}..., latency: ${latency}ms, head ${h}, fdb_head ${f}", ("num", bh.block_num())("id", blk_id.str().substr(8,16)) ("latency", (fc::time_point::now() - bh.timestamp).count()/1000) - ("h", my_impl->get_chain_head_num())); + ("h", my_impl->get_chain_head_num())("f", my_impl->get_fork_head_num())); if( !my_impl->sync_master->syncing_from_peer() ) { // guard against peer thinking it needs to send us old blocks uint32_t lib_num = my_impl->get_chain_lib_num(); if( blk_num <= lib_num ) { @@ -3287,29 +3290,35 @@ namespace eosio { // call only from main application thread void net_plugin_impl::update_chain_info() { controller& cc = chain_plug->chain(); - uint32_t lib_num = 0, head_num = 0; + uint32_t lib_num = 0, head_num = 0, fork_head_num = 0; { fc::lock_guard g( chain_info_mtx ); chain_info.lib_id = cc.last_irreversible_block_id(); chain_info.lib_num = lib_num = block_header::num_from_id(chain_info.lib_id); - chain_info.head_id = cc.fork_db_head_block_id(); + chain_info.head_id = cc.head_block_id(); chain_info.head_num = head_num = block_header::num_from_id(chain_info.head_id); + chain_info.fork_head_id = cc.fork_db_head_block_id(); + chain_info.fork_head_num = fork_head_num = block_header::num_from_id(chain_info.fork_head_id); } - fc_dlog( logger, "updating chain info lib ${lib}, head ${h}", ("lib", lib_num)("h", head_num) ); + fc_dlog( logger, "updating chain info lib ${lib}, head ${h} fdb_head ${f}", ("lib", lib_num)("h", head_num)("f", fork_head_num) ); } // call only from main application thread void net_plugin_impl::update_chain_info(const block_id_type& lib) { controller& cc = chain_plug->chain(); - uint32_t lib_num = 0, head_num = 0; + uint32_t lib_num = 0, head_num = 0, fork_head_num = 0; { fc::lock_guard g( chain_info_mtx ); chain_info.lib_num = lib_num = block_header::num_from_id(lib); chain_info.lib_id = lib; chain_info.head_id = cc.fork_db_head_block_id(); chain_info.head_num = head_num = block_header::num_from_id(chain_info.head_id); + chain_info.fork_head_id = cc.fork_db_head_block_id(); + chain_info.fork_head_num = head_num = block_header::num_from_id(chain_info.fork_head_id); + chain_info.fork_head_id = cc.fork_db_head_block_id(); + chain_info.fork_head_num = fork_head_num = block_header::num_from_id(chain_info.fork_head_id); } - fc_dlog( logger, "updating chain info lib ${lib}, head ${h}", ("lib", lib_num)("h", head_num) ); + fc_dlog( logger, "updating chain info lib ${lib}, head ${h} fdb_head ${f}", ("lib", lib_num)("h", head_num)("f", fork_head_num) ); } @@ -3328,6 +3337,11 @@ namespace eosio { return chain_info.head_num; } + uint32_t net_plugin_impl::get_fork_head_num() const { + fc::lock_guard g( chain_info_mtx ); + return chain_info.fork_head_num; + } + bool connection::is_valid( const handshake_message& msg ) const { // Do some basic validation of an incoming handshake_message, so things // that really aren't handshake messages can be quickly discarded without @@ -4182,13 +4196,13 @@ namespace eosio { auto now = sc::duration_cast(sc::system_clock::now().time_since_epoch()).count(); constexpr int64_t hs_delay = sc::duration_cast(sc::milliseconds(50)).count(); // nothing as changed since last handshake and one was sent recently, so skip sending - if (chain_info.head_id == hello.head_id && (hello.time + hs_delay > now)) + if (chain_info.fork_head_id == hello.head_id && (hello.time + hs_delay > now)) return false; hello.network_version = net_version_base + net_version; hello.last_irreversible_block_num = chain_info.lib_num; hello.last_irreversible_block_id = chain_info.lib_id; - hello.head_num = chain_info.head_num; - hello.head_id = chain_info.head_id; + hello.head_num = chain_info.fork_head_num; + hello.head_id = chain_info.fork_head_id; hello.chain_id = my_impl->chain_id; hello.node_id = my_impl->node_id; hello.key = my_impl->get_authentication_key(); From 5e262ccf14c1ca03060b730b0628324e1af7b9e6 Mon Sep 17 00:00:00 2001 From: Kevin Heifner Date: Thu, 13 Jun 2024 07:48:00 -0500 Subject: [PATCH 2/4] GH-278 Fix update_chain_info --- plugins/net_plugin/net_plugin.cpp | 6 ++---- 1 file changed, 2 insertions(+), 4 deletions(-) diff --git a/plugins/net_plugin/net_plugin.cpp b/plugins/net_plugin/net_plugin.cpp index 9a23294f2e..07c3e1adf9 100644 --- a/plugins/net_plugin/net_plugin.cpp +++ b/plugins/net_plugin/net_plugin.cpp @@ -3309,13 +3309,11 @@ namespace eosio { uint32_t lib_num = 0, head_num = 0, fork_head_num = 0; { fc::lock_guard g( chain_info_mtx ); - chain_info.lib_num = lib_num = block_header::num_from_id(lib); chain_info.lib_id = lib; - chain_info.head_id = cc.fork_db_head_block_id(); + chain_info.lib_num = lib_num = block_header::num_from_id(lib); + chain_info.head_id = cc.head_block_id(); chain_info.head_num = head_num = block_header::num_from_id(chain_info.head_id); chain_info.fork_head_id = cc.fork_db_head_block_id(); - chain_info.fork_head_num = head_num = block_header::num_from_id(chain_info.fork_head_id); - chain_info.fork_head_id = cc.fork_db_head_block_id(); chain_info.fork_head_num = fork_head_num = block_header::num_from_id(chain_info.fork_head_id); } fc_dlog( logger, "updating chain info lib ${lib}, head ${h} fdb_head ${f}", ("lib", lib_num)("h", head_num)("f", fork_head_num) ); From 7685b90d95fa63ac42e267e35c9b95afcabc71f7 Mon Sep 17 00:00:00 2001 From: Kevin Heifner Date: Thu, 13 Jun 2024 11:00:17 -0500 Subject: [PATCH 3/4] GH-278 Consistently use fhead in logs for fork head. Also fix one use of chain head instead of fork head --- plugins/net_plugin/net_plugin.cpp | 74 +++++++++++++++---------------- 1 file changed, 37 insertions(+), 37 deletions(-) diff --git a/plugins/net_plugin/net_plugin.cpp b/plugins/net_plugin/net_plugin.cpp index 07c3e1adf9..f83afc706e 100644 --- a/plugins/net_plugin/net_plugin.cpp +++ b/plugins/net_plugin/net_plugin.cpp @@ -867,7 +867,7 @@ namespace eosio { bool is_transactions_connection() const { return connection_type != blocks_only; } // thread safe, atomic bool is_blocks_connection() const { return connection_type != transactions_only; } // thread safe, atomic uint32_t get_peer_start_block_num() const { return peer_start_block_num.load(); } - uint32_t get_peer_head_block_num() const { return peer_head_block_num.load(); } + uint32_t get_peer_fork_head_block_num() const { return peer_fork_head_block_num.load(); } uint32_t get_last_received_block_num() const { return last_received_block_num.load(); } uint32_t get_unique_blocks_rcvd_count() const { return unique_blocks_rcvd_count.load(); } size_t get_bytes_received() const { return bytes_received.load(); } @@ -907,7 +907,7 @@ namespace eosio { std::atomic connection_type{both}; std::atomic peer_start_block_num{0}; - std::atomic peer_head_block_num{0}; + std::atomic peer_fork_head_block_num{0}; std::atomic last_received_block_num{0}; std::atomic unique_blocks_rcvd_count{0}; std::atomic bytes_received{0}; @@ -1063,7 +1063,7 @@ namespace eosio { /** @} */ void blk_send_branch( const block_id_type& msg_head_id ); - void blk_send_branch( uint32_t msg_head_num, uint32_t lib_num, uint32_t head_num ); + void blk_send_branch( uint32_t msg_head_num, uint32_t lib_num, uint32_t fork_head_num ); void blk_send(const block_id_type& blkid); void stop_send(); @@ -1427,14 +1427,14 @@ namespace eosio { // thread safe bool connection::should_sync_from(uint32_t sync_next_expected_num, uint32_t sync_known_lib_num) const { - fc_dlog(logger, "id: ${id} blocks conn: ${t} current: ${c} socket_open: ${so} syncing from us: ${s} state: ${con} peer_start_block: ${sb} peer_head: ${h} ping: ${p}us no_retry: ${g}", + fc_dlog(logger, "id: ${id} blocks conn: ${t} current: ${c} socket_open: ${so} syncing from us: ${s} state: ${con} peer_start_block: ${sb} peer_fhead: ${h} ping: ${p}us no_retry: ${g}", ("id", connection_id)("t", is_blocks_connection()) ("c", current())("so", socket_is_open())("s", peer_syncing_from_us.load())("con", state_str(state())) - ("sb", peer_start_block_num.load())("h", peer_head_block_num.load())("p", get_peer_ping_time_ns()/1000)("g", reason_str(no_retry))); + ("sb", peer_start_block_num.load())("h", peer_fork_head_block_num.load())("p", get_peer_ping_time_ns()/1000)("g", reason_str(no_retry))); if (is_blocks_connection() && current()) { if (no_retry == go_away_reason::no_reason) { if (peer_start_block_num <= sync_next_expected_num) { // has blocks we want - if (peer_head_block_num >= sync_known_lib_num) { // is in sync + if (peer_fork_head_block_num >= sync_known_lib_num) { // is in sync return true; } } @@ -1501,10 +1501,10 @@ namespace eosio { // called from connection strand void connection::blk_send_branch( const block_id_type& msg_head_id ) { - uint32_t head_num = my_impl->get_fork_head_num(); + uint32_t fork_head_num = my_impl->get_fork_head_num(); - peer_dlog(this, "head_num = ${h}",("h",head_num)); - if(head_num == 0) { + peer_dlog(this, "fhead_num = ${h}",("h",fork_head_num)); + if(fork_head_num == 0) { notice_message note; note.known_blocks.mode = normal; note.known_blocks.pending = 0; @@ -1543,18 +1543,18 @@ namespace eosio { } else { if( on_fork ) msg_head_num = 0; // if peer on fork, start at their last lib, otherwise we can start at msg_head+1 - blk_send_branch( msg_head_num, lib_num, head_num ); + blk_send_branch( msg_head_num, lib_num, fork_head_num ); } } // called from connection strand - void connection::blk_send_branch( uint32_t msg_head_num, uint32_t lib_num, uint32_t head_num ) { + void connection::blk_send_branch( uint32_t msg_head_num, uint32_t lib_num, uint32_t fork_head_num ) { if( !peer_requested ) { auto last = msg_head_num != 0 ? msg_head_num : lib_num; - peer_requested = peer_sync_state( last+1, head_num, last ); + peer_requested = peer_sync_state( last+1, fork_head_num, last ); } else { auto last = msg_head_num != 0 ? msg_head_num : std::min( peer_requested->last, lib_num ); - uint32_t end = std::max( peer_requested->end_block, head_num ); + uint32_t end = std::max( peer_requested->end_block, fork_head_num ); peer_requested = peer_sync_state( last+1, end, last ); } if( peer_requested->start_block <= peer_requested->end_block ) { @@ -1600,10 +1600,10 @@ namespace eosio { c->last_handshake_sent.generation = ++c->sent_handshake_count; auto last_handshake = c->last_handshake_sent; g_conn.unlock(); - peer_ilog( c, "Sending handshake generation ${g}, lib ${lib}, head ${head}, id ${id}", + peer_ilog( c, "Sending handshake generation ${g}, lib ${lib}, fhead ${h}, id ${id}", ("g", last_handshake.generation) ("lib", last_handshake.last_irreversible_block_num) - ("head", last_handshake.head_num)("id", last_handshake.head_id.str().substr(8,16)) ); + ("h", last_handshake.head_num)("id", last_handshake.head_id.str().substr(8,16)) ); c->enqueue( last_handshake ); } }); @@ -2146,11 +2146,11 @@ namespace eosio { void sync_manager::request_next_chunk( const connection_ptr& conn ) REQUIRES(sync_mtx) { auto chain_info = my_impl->get_chain_info(); - fc_dlog( logger, "sync_last_requested_num: ${r}, sync_next_expected_num: ${e}, sync_known_lib_num: ${k}, sync_req_span: ${s}, head: ${h}, lib: ${lib}", + fc_dlog( logger, "sync_last_requested_num: ${r}, sync_next_expected_num: ${e}, sync_known_lib_num: ${k}, sync_req_span: ${s}, fhead: ${h}, lib: ${lib}", ("r", sync_last_requested_num)("e", sync_next_expected_num)("k", sync_known_lib_num)("s", sync_req_span)("h", chain_info.fork_head_num)("lib", chain_info.lib_num) ); if( chain_info.fork_head_num + sync_req_span < sync_last_requested_num && sync_source && sync_source->current() ) { - fc_dlog( logger, "ignoring request, head is ${h} last req = ${r}, sync_next_expected_num: ${e}, sync_known_lib_num: ${k}, sync_req_span: ${s}, source connection ${c}", + fc_dlog( logger, "ignoring request, fhead is ${h} last req = ${r}, sync_next_expected_num: ${e}, sync_known_lib_num: ${k}, sync_req_span: ${s}, source connection ${c}", ("h", chain_info.fork_head_num)("r", sync_last_requested_num)("e", sync_next_expected_num) ("k", sync_known_lib_num)("s", sync_req_span)("c", sync_source->connection_id) ); return; @@ -2158,7 +2158,7 @@ namespace eosio { if (conn) { // p2p_high_latency_test.py test depends on this exact log statement. - peer_ilog(conn, "Catching up with chain, our last req is ${cc}, theirs is ${t}, next expected ${n}, head ${h}", + peer_ilog(conn, "Catching up with chain, our last req is ${cc}, theirs is ${t}, next expected ${n}, fhead ${h}", ("cc", sync_last_requested_num)("t", sync_known_lib_num)("n", sync_next_expected_num)("h", chain_info.fork_head_num)); } @@ -2191,8 +2191,8 @@ namespace eosio { sync_last_requested_num = end; sync_source = new_sync_source; request_sent = true; - new_sync_source->strand.post( [new_sync_source, start, end, head_num=chain_info.fork_head_num, lib=chain_info.lib_num]() { - peer_ilog( new_sync_source, "requesting range ${s} to ${e}, head ${h}, lib ${lib}", ("s", start)("e", end)("h", head_num)("lib", lib) ); + new_sync_source->strand.post( [new_sync_source, start, end, fork_head_num=chain_info.fork_head_num, lib=chain_info.lib_num]() { + peer_ilog( new_sync_source, "requesting range ${s} to ${e}, fhead ${h}, lib ${lib}", ("s", start)("e", end)("h", fork_head_num)("lib", lib) ); new_sync_source->request_sync_blocks( start, end ); } ); } @@ -2214,9 +2214,9 @@ namespace eosio { } bool sync_manager::is_sync_required( uint32_t fork_head_block_num ) REQUIRES(sync_mtx) { - fc_dlog( logger, "last req = ${req}, last recv = ${recv} known = ${known} our head = ${head}", + fc_dlog( logger, "last req = ${req}, last recv = ${recv} known = ${known} our fhead = ${h}", ("req", sync_last_requested_num)( "recv", sync_next_expected_num )( "known", sync_known_lib_num ) - ("head", fork_head_block_num ) ); + ("h", fork_head_block_num ) ); return( sync_last_requested_num < sync_known_lib_num || sync_next_expected_num < sync_last_requested_num ); @@ -2230,9 +2230,9 @@ namespace eosio { } auto chain_info = my_impl->get_chain_info(); - if( !is_sync_required( chain_info.head_num ) || target <= chain_info.lib_num ) { - peer_dlog( c, "We are already caught up, my irr = ${b}, head = ${h}, target = ${t}", - ("b", chain_info.lib_num)( "h", chain_info.head_num )( "t", target ) ); + if( !is_sync_required( chain_info.fork_head_num ) || target <= chain_info.lib_num ) { + peer_dlog( c, "We are already caught up, my irr = ${b}, fhead = ${h}, target = ${t}", + ("b", chain_info.lib_num)( "h", chain_info.fork_head_num )( "t", target ) ); c->send_handshake(); // let peer know it is not syncing from us return; } @@ -2297,7 +2297,7 @@ namespace eosio { return; } if (chain_info.fork_head_num < msg.last_irreversible_block_num) { - peer_ilog( c, "handshake lib ${lib}, head ${head}, head id ${id}.. sync 1, head ${h}, lib ${l}", + peer_ilog( c, "handshake lib ${lib}, head ${head}, head id ${id}.. sync 1, fhead ${h}, lib ${l}", ("lib", msg.last_irreversible_block_num)("head", msg.head_num)("id", msg.head_id.str().substr(8,16)) ("h", chain_info.fork_head_num)("l", chain_info.lib_num) ); c->peer_syncing_from_us = false; @@ -2307,7 +2307,7 @@ namespace eosio { return; } if (chain_info.lib_num > msg.head_num + nblk_combined_latency + min_blocks_distance) { - peer_ilog( c, "handshake lib ${lib}, head ${head}, head id ${id}.. sync 2, head ${h}, lib ${l}", + peer_ilog( c, "handshake lib ${lib}, head ${head}, head id ${id}.. sync 2, fhead ${h}, lib ${l}", ("lib", msg.last_irreversible_block_num)("head", msg.head_num)("id", msg.head_id.str().substr(8,16)) ("h", chain_info.fork_head_num)("l", chain_info.lib_num) ); if (msg.generation > 1 || c->protocol_version > proto_base) { @@ -2329,14 +2329,14 @@ namespace eosio { } if (chain_info.fork_head_num + nblk_combined_latency < msg.head_num ) { - peer_ilog( c, "handshake lib ${lib}, head ${head}, head id ${id}.. sync 3, head ${h}, lib ${l}", + peer_ilog( c, "handshake lib ${lib}, head ${head}, head id ${id}.. sync 3, fhead ${h}, lib ${l}", ("lib", msg.last_irreversible_block_num)("head", msg.head_num)("id", msg.head_id.str().substr(8,16)) ("h", chain_info.fork_head_num)("l", chain_info.lib_num) ); c->peer_syncing_from_us = false; verify_catchup(c, msg.head_num, msg.head_id); return; } else if(chain_info.fork_head_num >= msg.head_num + nblk_combined_latency) { - peer_ilog( c, "handshake lib ${lib}, head ${head}, head id ${id}.. sync 4, head ${h}, lib ${l}", + peer_ilog( c, "handshake lib ${lib}, head ${head}, head id ${id}.. sync 4, fhead ${h}, lib ${l}", ("lib", msg.last_irreversible_block_num)("head", msg.head_num)("id", msg.head_id.str().substr(8,16)) ("h", chain_info.fork_head_num)("l", chain_info.lib_num) ); if (msg.generation > 1 || c->protocol_version > proto_base) { @@ -2389,7 +2389,7 @@ namespace eosio { if( req.req_blocks.mode == catch_up ) { { fc::lock_guard g( sync_mtx ); - peer_ilog( c, "catch_up while in ${s}, head num = ${hn} " + peer_ilog( c, "catch_up while in ${s}, fhead = ${hn} " "target LIB = ${lib} next_expected = ${ne}, id ${id}...", ("s", stage_str( sync_state ))("hn", num)("lib", sync_known_lib_num) ("ne", sync_next_expected_num)("id", id.str().substr( 8, 16 )) ); @@ -2408,7 +2408,7 @@ namespace eosio { req.req_blocks.ids.emplace_back( chain_info.fork_head_id ); } else { - peer_ilog( c, "none notice while in ${s}, head num = ${hn}, id ${id}...", + peer_ilog( c, "none notice while in ${s}, fhead = ${hn}, id ${id}...", ("s", stage_str( sync_state ))("hn", num)("id", id.str().substr(8,16)) ); fc::lock_guard g_conn( c->conn_mtx ); c->fork_head = block_id_type(); @@ -3156,7 +3156,7 @@ namespace eosio { pending_message_buffer.advance_read_ptr( message_length ); return true; } - peer_dlog( this, "received block ${num}, id ${id}..., latency: ${latency}ms, head ${h}, fdb_head ${f}", + peer_dlog( this, "received block ${num}, id ${id}..., latency: ${latency}ms, head ${h}, fhead ${f}", ("num", bh.block_num())("id", blk_id.str().substr(8,16)) ("latency", (fc::time_point::now() - bh.timestamp).count()/1000) ("h", my_impl->get_chain_head_num())("f", my_impl->get_fork_head_num())); @@ -3300,7 +3300,7 @@ namespace eosio { chain_info.fork_head_id = cc.fork_db_head_block_id(); chain_info.fork_head_num = fork_head_num = block_header::num_from_id(chain_info.fork_head_id); } - fc_dlog( logger, "updating chain info lib ${lib}, head ${h} fdb_head ${f}", ("lib", lib_num)("h", head_num)("f", fork_head_num) ); + fc_dlog( logger, "updating chain info lib ${lib}, head ${h} fhead ${f}", ("lib", lib_num)("h", head_num)("f", fork_head_num) ); } // call only from main application thread @@ -3316,7 +3316,7 @@ namespace eosio { chain_info.fork_head_id = cc.fork_db_head_block_id(); chain_info.fork_head_num = fork_head_num = block_header::num_from_id(chain_info.fork_head_id); } - fc_dlog( logger, "updating chain info lib ${lib}, head ${h} fdb_head ${f}", ("lib", lib_num)("h", head_num)("f", fork_head_num) ); + fc_dlog( logger, "updating chain info lib ${lib}, head ${h} fhead ${f}", ("lib", lib_num)("h", head_num)("f", fork_head_num) ); } @@ -3395,7 +3395,7 @@ namespace eosio { ("g", msg.generation)("lib", msg.last_irreversible_block_num)("head", msg.head_num) ); peer_lib_num = msg.last_irreversible_block_num; - peer_head_block_num = msg.head_num; + peer_fork_head_block_num = msg.head_num; fc::unique_lock g_conn( conn_mtx ); last_handshake_recv = msg; auto c_time = last_handshake_sent.time; @@ -3704,7 +3704,7 @@ namespace eosio { peer_start_block_num = block_header::num_from_id(msg.known_blocks.ids[1]); } if (msg.known_blocks.ids.size() > 0) { - peer_head_block_num = block_header::num_from_id(msg.known_blocks.ids[0]); + peer_fork_head_block_num = block_header::num_from_id(msg.known_blocks.ids[0]); } my_impl->sync_master->sync_recv_notice( shared_from_this(), msg ); break; @@ -4947,7 +4947,7 @@ namespace eosio { , .accepting_blocks = c->is_blocks_connection() , .last_received_block = c->get_last_received_block_num() , .first_available_block = c->get_peer_start_block_num() - , .last_available_block = c->get_peer_head_block_num() + , .last_available_block = c->get_peer_fork_head_block_num() , .unique_first_block_count = c->get_unique_blocks_rcvd_count() , .latency = c->get_peer_ping_time_ns() , .bytes_received = c->get_bytes_received() From 9c5b945da7296772d079f8d5951f0a317cfe2c48 Mon Sep 17 00:00:00 2001 From: Kevin Heifner Date: Thu, 13 Jun 2024 13:14:27 -0500 Subject: [PATCH 4/4] GH-278 Rename handshake head_num to fork_head_num and head_id to fork_head_id --- .../include/eosio/net_plugin/protocol.hpp | 6 +- plugins/net_plugin/net_plugin.cpp | 59 +++++++++---------- 2 files changed, 32 insertions(+), 33 deletions(-) diff --git a/plugins/net_plugin/include/eosio/net_plugin/protocol.hpp b/plugins/net_plugin/include/eosio/net_plugin/protocol.hpp index 71be9a26f3..7539fd5659 100644 --- a/plugins/net_plugin/include/eosio/net_plugin/protocol.hpp +++ b/plugins/net_plugin/include/eosio/net_plugin/protocol.hpp @@ -34,8 +34,8 @@ namespace eosio { string p2p_address; uint32_t last_irreversible_block_num = 0; block_id_type last_irreversible_block_id; - uint32_t head_num = 0; - block_id_type head_id; + uint32_t fork_head_num = 0; + block_id_type fork_head_id; string os; string agent; int16_t generation = 0; @@ -155,7 +155,7 @@ FC_REFLECT( eosio::handshake_message, (network_version)(chain_id)(node_id)(key) (time)(token)(sig)(p2p_address) (last_irreversible_block_num)(last_irreversible_block_id) - (head_num)(head_id) + (fork_head_num)(fork_head_id) (os)(agent)(generation) ) FC_REFLECT( eosio::go_away_message, (reason)(node_id) ) FC_REFLECT( eosio::time_message, (org)(rec)(xmt)(dst) ) diff --git a/plugins/net_plugin/net_plugin.cpp b/plugins/net_plugin/net_plugin.cpp index f83afc706e..0b6267c7d3 100644 --- a/plugins/net_plugin/net_plugin.cpp +++ b/plugins/net_plugin/net_plugin.cpp @@ -14,7 +14,7 @@ #include #include #include -#include +#include #include #include #include @@ -30,7 +30,6 @@ #include #include #include -#include using namespace eosio::chain::plugin_interface; @@ -1516,7 +1515,7 @@ namespace eosio { fc::unique_lock g_conn( conn_mtx ); if( last_handshake_recv.generation >= 1 ) { peer_dlog( this, "maybe truncating branch at = ${h}:${id}", - ("h", block_header::num_from_id(last_handshake_recv.head_id))("id", last_handshake_recv.head_id) ); + ("h", block_header::num_from_id(last_handshake_recv.fork_head_id))("id", last_handshake_recv.fork_head_id) ); } } const auto lib_num = peer_lib_num; @@ -1603,7 +1602,7 @@ namespace eosio { peer_ilog( c, "Sending handshake generation ${g}, lib ${lib}, fhead ${h}, id ${id}", ("g", last_handshake.generation) ("lib", last_handshake.last_irreversible_block_num) - ("h", last_handshake.head_num)("id", last_handshake.head_id.str().substr(8,16)) ); + ("h", last_handshake.fork_head_num)("id", last_handshake.fork_head_id.str().substr(8,16)) ); c->enqueue( last_handshake ); } }); @@ -2290,15 +2289,15 @@ namespace eosio { // //----------------------------- - if (chain_info.fork_head_id == msg.head_id) { - peer_ilog( c, "handshake lib ${lib}, head ${head}, head id ${id}.. sync 0, lib ${l}", - ("lib", msg.last_irreversible_block_num)("head", msg.head_num)("id", msg.head_id.str().substr(8,16))("l", chain_info.lib_num) ); + if (chain_info.fork_head_id == msg.fork_head_id) { + peer_ilog( c, "handshake lib ${lib}, fhead ${h}, id ${id}.. sync 0, lib ${l}", + ("lib", msg.last_irreversible_block_num)("h", msg.fork_head_num)("id", msg.fork_head_id.str().substr(8,16))("l", chain_info.lib_num) ); c->peer_syncing_from_us = false; return; } if (chain_info.fork_head_num < msg.last_irreversible_block_num) { - peer_ilog( c, "handshake lib ${lib}, head ${head}, head id ${id}.. sync 1, fhead ${h}, lib ${l}", - ("lib", msg.last_irreversible_block_num)("head", msg.head_num)("id", msg.head_id.str().substr(8,16)) + peer_ilog( c, "handshake lib ${lib}, fhead ${mh}, id ${id}.. sync 1, fhead ${h}, lib ${l}", + ("lib", msg.last_irreversible_block_num)("mh", msg.fork_head_num)("id", msg.fork_head_id.str().substr(8,16)) ("h", chain_info.fork_head_num)("l", chain_info.lib_num) ); c->peer_syncing_from_us = false; if (c->sent_handshake_count > 0) { @@ -2306,9 +2305,9 @@ namespace eosio { } return; } - if (chain_info.lib_num > msg.head_num + nblk_combined_latency + min_blocks_distance) { - peer_ilog( c, "handshake lib ${lib}, head ${head}, head id ${id}.. sync 2, fhead ${h}, lib ${l}", - ("lib", msg.last_irreversible_block_num)("head", msg.head_num)("id", msg.head_id.str().substr(8,16)) + if (chain_info.lib_num > msg.fork_head_num + nblk_combined_latency + min_blocks_distance) { + peer_ilog( c, "handshake lib ${lib}, fhead ${mh}, id ${id}.. sync 2, fhead ${h}, lib ${l}", + ("lib", msg.last_irreversible_block_num)("mh", msg.fork_head_num)("id", msg.fork_head_id.str().substr(8,16)) ("h", chain_info.fork_head_num)("l", chain_info.lib_num) ); if (msg.generation > 1 || c->protocol_version > proto_base) { controller& cc = my_impl->chain_plug->chain(); @@ -2328,16 +2327,16 @@ namespace eosio { return; } - if (chain_info.fork_head_num + nblk_combined_latency < msg.head_num ) { - peer_ilog( c, "handshake lib ${lib}, head ${head}, head id ${id}.. sync 3, fhead ${h}, lib ${l}", - ("lib", msg.last_irreversible_block_num)("head", msg.head_num)("id", msg.head_id.str().substr(8,16)) + if (chain_info.fork_head_num + nblk_combined_latency < msg.fork_head_num ) { + peer_ilog( c, "handshake lib ${lib}, fhead ${mh}, id ${id}.. sync 3, fhead ${h}, lib ${l}", + ("lib", msg.last_irreversible_block_num)("mh", msg.fork_head_num)("id", msg.fork_head_id.str().substr(8,16)) ("h", chain_info.fork_head_num)("l", chain_info.lib_num) ); c->peer_syncing_from_us = false; - verify_catchup(c, msg.head_num, msg.head_id); + verify_catchup(c, msg.fork_head_num, msg.fork_head_id); return; - } else if(chain_info.fork_head_num >= msg.head_num + nblk_combined_latency) { - peer_ilog( c, "handshake lib ${lib}, head ${head}, head id ${id}.. sync 4, fhead ${h}, lib ${l}", - ("lib", msg.last_irreversible_block_num)("head", msg.head_num)("id", msg.head_id.str().substr(8,16)) + } else if(chain_info.fork_head_num >= msg.fork_head_num + nblk_combined_latency) { + peer_ilog( c, "handshake lib ${lib}, fhead ${mh}, id ${id}.. sync 4, fhead ${h}, lib ${l}", + ("lib", msg.last_irreversible_block_num)("mh", msg.fork_head_num)("id", msg.fork_head_id.str().substr(8,16)) ("h", chain_info.fork_head_num)("l", chain_info.lib_num) ); if (msg.generation > 1 || c->protocol_version > proto_base) { controller& cc = my_impl->chain_plug->chain(); @@ -2356,7 +2355,7 @@ namespace eosio { bool on_fork = true; try { controller& cc = my_impl->chain_plug->chain(); - on_fork = cc.get_block_id_for_num( msg.head_num ) != msg.head_id; // thread-safe + on_fork = cc.get_block_id_for_num( msg.fork_head_num ) != msg.fork_head_id; // thread-safe } catch( ... ) {} if( on_fork ) { request_message req; @@ -3345,9 +3344,9 @@ namespace eosio { // that really aren't handshake messages can be quickly discarded without // affecting state. bool valid = true; - if (msg.last_irreversible_block_num > msg.head_num) { - peer_wlog( this, "Handshake message validation: last irreversible block (${i}) is greater than head block (${h})", - ("i", msg.last_irreversible_block_num)("h", msg.head_num) ); + if (msg.last_irreversible_block_num > msg.fork_head_num) { + peer_wlog( this, "Handshake message validation: last irreversible (${i}) is greater than fhead (${h})", + ("i", msg.last_irreversible_block_num)("h", msg.fork_head_num) ); valid = false; } if (msg.p2p_address.empty()) { @@ -3391,11 +3390,11 @@ namespace eosio { enqueue( go_away_message( fatal_other ) ); return; } - peer_dlog( this, "received handshake gen ${g}, lib ${lib}, head ${head}", - ("g", msg.generation)("lib", msg.last_irreversible_block_num)("head", msg.head_num) ); + peer_dlog( this, "received handshake gen ${g}, lib ${lib}, fhead ${head}", + ("g", msg.generation)("lib", msg.last_irreversible_block_num)("head", msg.fork_head_num) ); peer_lib_num = msg.last_irreversible_block_num; - peer_fork_head_block_num = msg.head_num; + peer_fork_head_block_num = msg.fork_head_num; fc::unique_lock g_conn( conn_mtx ); last_handshake_recv = msg; auto c_time = last_handshake_sent.time; @@ -3679,7 +3678,7 @@ namespace eosio { case none: case last_irr_catch_up: { fc::unique_lock g_conn( conn_mtx ); - last_handshake_recv.head_num = std::max(msg.known_blocks.pending, last_handshake_recv.head_num); + last_handshake_recv.fork_head_num = std::max(msg.known_blocks.pending, last_handshake_recv.fork_head_num); g_conn.unlock(); break; } @@ -4194,13 +4193,13 @@ namespace eosio { auto now = sc::duration_cast(sc::system_clock::now().time_since_epoch()).count(); constexpr int64_t hs_delay = sc::duration_cast(sc::milliseconds(50)).count(); // nothing as changed since last handshake and one was sent recently, so skip sending - if (chain_info.fork_head_id == hello.head_id && (hello.time + hs_delay > now)) + if (chain_info.fork_head_id == hello.fork_head_id && (hello.time + hs_delay > now)) return false; hello.network_version = net_version_base + net_version; hello.last_irreversible_block_num = chain_info.lib_num; hello.last_irreversible_block_id = chain_info.lib_id; - hello.head_num = chain_info.fork_head_num; - hello.head_id = chain_info.fork_head_id; + hello.fork_head_num = chain_info.fork_head_num; + hello.fork_head_id = chain_info.fork_head_id; hello.chain_id = my_impl->chain_id; hello.node_id = my_impl->node_id; hello.key = my_impl->get_authentication_key();