From 9e808aee546db3e460a61c7ac96547af7e0e72d0 Mon Sep 17 00:00:00 2001 From: Kevin Heifner Date: Thu, 27 Feb 2025 08:20:17 -0600 Subject: [PATCH 1/5] Add _peer and _nver to logger variant for peer logging. Add log when block not sent because connection busy sending. --- plugins/net_plugin/net_plugin.cpp | 33 ++++++++++++++++++++----------- 1 file changed, 21 insertions(+), 12 deletions(-) diff --git a/plugins/net_plugin/net_plugin.cpp b/plugins/net_plugin/net_plugin.cpp index 8ef39be1b1..5f2963ec01 100644 --- a/plugins/net_plugin/net_plugin.cpp +++ b/plugins/net_plugin/net_plugin.cpp @@ -1028,10 +1028,11 @@ namespace eosio { void sync_wait(); void queue_write(msg_type_t net_msg, + block_num_type block_num, queued_buffer::queue_t queue, const std::shared_ptr>& buff, std::function callback); - void do_queue_write(); + void do_queue_write(block_num_type block_num); bool is_valid( const handshake_message& msg ) const; @@ -1070,14 +1071,16 @@ namespace eosio { fc::variant_object get_logger_variant() const { fc::mutable_variant_object mvo; - mvo( "_name", log_p2p_address) + mvo( "_peer", peer_addr.empty() ? log_p2p_address : peer_addr ) + ( "_name", log_p2p_address) ( "_cid", connection_id ) ( "_id", conn_node_id ) ( "_sid", short_conn_node_id ) ( "_ip", log_remote_endpoint_ip ) ( "_port", log_remote_endpoint_port ) ( "_lip", local_endpoint_ip ) - ( "_lport", local_endpoint_port ); + ( "_lport", local_endpoint_port ) + ( "_nver", protocol_version.load() ); return mvo; } @@ -1649,6 +1652,7 @@ namespace eosio { // called from connection strand void connection::queue_write(msg_type_t net_msg, + block_num_type block_num, queued_buffer::queue_t queue, const std::shared_ptr>& buff, std::function callback) { @@ -1657,20 +1661,23 @@ namespace eosio { close(); return; } - do_queue_write(); + do_queue_write(block_num); } // called from connection strand - void connection::do_queue_write() { - if( !buffer_queue.ready_to_send(connection_id) || closed() ) + void connection::do_queue_write(block_num_type block_num) { + if( !buffer_queue.ready_to_send(connection_id) || closed() ) { + if (block_num > 0) { + peer_dlog(this, "not sending block yet ${n}", ("n", block_num) ); + } return; - connection_ptr c(shared_from_this()); + } std::vector bufs; buffer_queue.fill_out_buffer( bufs ); boost::asio::async_write( *socket, bufs, - boost::asio::bind_executor( strand, [c, socket=socket]( boost::system::error_code ec, std::size_t w ) { + boost::asio::bind_executor( strand, [c=shared_from_this(), socket=socket]( boost::system::error_code ec, std::size_t w ) { try { peer_dlog(c, "async write complete"); // May have closed connection and cleared buffer_queue @@ -1704,7 +1711,7 @@ namespace eosio { c->buffer_queue.clear_out_queue(ec, w); c->enqueue_sync_block(); - c->do_queue_write(); + c->do_queue_write(0); } catch ( const std::bad_alloc& ) { throw; } catch ( const boost::interprocess::bad_alloc& ) { @@ -1949,8 +1956,8 @@ namespace eosio { go_away_reason close_after_send) { connection_ptr self = shared_from_this(); - queue_write(net_msg, queue, send_buffer, - [conn{std::move(self)}, close_after_send, net_msg, block_num](boost::system::error_code ec, std::size_t ) { + queue_write(net_msg, block_num, queue, send_buffer, + [conn{std::move(self)}, close_after_send, net_msg, block_num](boost::system::error_code ec, std::size_t s) { if (ec) { if (ec != boost::asio::error::operation_aborted && ec != boost::asio::error::connection_reset && conn->socket_is_open()) { fc_elog(logger, "Connection - ${cid} - send failed with: ${e}", ("cid", conn->connection_id)("e", ec.message())); @@ -4383,6 +4390,7 @@ namespace eosio { ( "peer-log-format", bpo::value()->default_value( "[\"${_name}\" - ${_cid} ${_ip}:${_port}] " ), "The string used to format peers when logging messages about them. Variables are escaped with ${}.\n" "Available Variables:\n" + " _peer \tendpoint name\n\n" " _name \tself-reported name\n\n" " _cid \tassigned connection id\n\n" " _id \tself-reported ID (64 hex characters)\n\n" @@ -4390,7 +4398,8 @@ namespace eosio { " _ip \tremote IP address of peer\n\n" " _port \tremote port number of peer\n\n" " _lip \tlocal IP address connected to peer\n\n" - " _lport \tlocal port number connected to peer\n\n") + " _lport \tlocal port number connected to peer\n\n" + " _nver \tp2p protocol version\n\n") ( "p2p-keepalive-interval-ms", bpo::value()->default_value(def_keepalive_interval), "peer heartbeat keepalive message interval in milliseconds") ; From 7b3e9b294be8de974ed6aee4ffbb3f51a7c4b5f6 Mon Sep 17 00:00:00 2001 From: Kevin Heifner Date: Thu, 27 Feb 2025 08:26:45 -0600 Subject: [PATCH 2/5] Changed peer-log-format to use _peer instead of _name by default --- plugins/net_plugin/net_plugin.cpp | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/plugins/net_plugin/net_plugin.cpp b/plugins/net_plugin/net_plugin.cpp index 5f2963ec01..9a727dae52 100644 --- a/plugins/net_plugin/net_plugin.cpp +++ b/plugins/net_plugin/net_plugin.cpp @@ -4387,7 +4387,7 @@ namespace eosio { ( "sync-peer-limit", bpo::value()->default_value(3), "Number of peers to sync from") ( "use-socket-read-watermark", bpo::value()->default_value(false), "Enable experimental socket read watermark optimization") - ( "peer-log-format", bpo::value()->default_value( "[\"${_name}\" - ${_cid} ${_ip}:${_port}] " ), + ( "peer-log-format", bpo::value()->default_value( "[\"${_peer}\" - ${_cid} ${_ip}:${_port}] " ), "The string used to format peers when logging messages about them. Variables are escaped with ${}.\n" "Available Variables:\n" " _peer \tendpoint name\n\n" From 447d4bc0fcd86fccba5b1c177f58977f212381fe Mon Sep 17 00:00:00 2001 From: Kevin Heifner Date: Thu, 27 Feb 2025 09:06:01 -0600 Subject: [PATCH 3/5] Use optional block_num --- plugins/net_plugin/net_plugin.cpp | 42 ++++++++++++++++++------------- 1 file changed, 24 insertions(+), 18 deletions(-) diff --git a/plugins/net_plugin/net_plugin.cpp b/plugins/net_plugin/net_plugin.cpp index 9a727dae52..7755453c98 100644 --- a/plugins/net_plugin/net_plugin.cpp +++ b/plugins/net_plugin/net_plugin.cpp @@ -1015,9 +1015,9 @@ namespace eosio { void enqueue( const net_message& msg ); size_t enqueue_block( const std::vector& sb, uint32_t block_num, queued_buffer::queue_t queue ); void enqueue_buffer( msg_type_t net_msg, + std::optional block_num, queued_buffer::queue_t queue, const std::shared_ptr>& send_buffer, - block_num_type block_num, go_away_reason close_after_send); void cancel_sync(); void flush_queues(); @@ -1028,11 +1028,11 @@ namespace eosio { void sync_wait(); void queue_write(msg_type_t net_msg, - block_num_type block_num, + std::optional block_num, queued_buffer::queue_t queue, const std::shared_ptr>& buff, std::function callback); - void do_queue_write(block_num_type block_num); + void do_queue_write(std::optional block_num); bool is_valid( const handshake_message& msg ) const; @@ -1154,7 +1154,7 @@ namespace eosio { void operator()( const block_notice_message& msg ) const { // continue call to handle_message on connection strand - peer_dlog( c, "handle block_notice_message #${bn}:${id}", ("bn", block_header::num_from_id(msg.id))("id", msg.id) ); + peer_ilog( c, "handle block_notice_message #${bn}:${id}", ("bn", block_header::num_from_id(msg.id))("id", msg.id) ); c->handle_message( msg ); } }; @@ -1652,7 +1652,7 @@ namespace eosio { // called from connection strand void connection::queue_write(msg_type_t net_msg, - block_num_type block_num, + std::optional block_num, queued_buffer::queue_t queue, const std::shared_ptr>& buff, std::function callback) { @@ -1665,13 +1665,17 @@ namespace eosio { } // called from connection strand - void connection::do_queue_write(block_num_type block_num) { - if( !buffer_queue.ready_to_send(connection_id) || closed() ) { - if (block_num > 0) { - peer_dlog(this, "not sending block yet ${n}", ("n", block_num) ); + void connection::do_queue_write(std::optional block_num) { + if( !buffer_queue.ready_to_send(connection_id) ) { + if (block_num) { + peer_dlog(this, "connection currently sending, queueing block ${n}", ("n", *block_num) ); } return; } + if (closed()) { + peer_dlog(this, "connection closed, not sending queued write"); + return; + } std::vector bufs; buffer_queue.fill_out_buffer( bufs ); @@ -1711,7 +1715,7 @@ namespace eosio { c->buffer_queue.clear_out_queue(ec, w); c->enqueue_sync_block(); - c->do_queue_write(0); + c->do_queue_write(std::nullopt); } catch ( const std::bad_alloc& ) { throw; } catch ( const boost::interprocess::bad_alloc& ) { @@ -1933,7 +1937,7 @@ namespace eosio { buffer_factory buff_factory; const auto& send_buffer = buff_factory.get_send_buffer( m ); - enqueue_buffer( to_msg_type_t(m.index()), queued_buffer::queue_t::general, send_buffer, 0, close_after_send ); + enqueue_buffer( to_msg_type_t(m.index()), std::nullopt, queued_buffer::queue_t::general, send_buffer, close_after_send ); } // called from connection strand @@ -1944,15 +1948,15 @@ namespace eosio { block_buffer_factory buff_factory; const auto& sb = buff_factory.get_send_buffer( b ); latest_blk_time = std::chrono::steady_clock::now(); - enqueue_buffer( msg_type_t::signed_block, queue, sb, block_num, no_reason); + enqueue_buffer( msg_type_t::signed_block, block_num, queue, sb, no_reason); return sb->size(); } // called from connection strand void connection::enqueue_buffer( msg_type_t net_msg, + std::optional block_num, // only valid for net_msg == signed_block variant which queued_buffer::queue_t queue, const std::shared_ptr>& send_buffer, - block_num_type block_num, // only valid for net_msg == signed_block variant which go_away_reason close_after_send) { connection_ptr self = shared_from_this(); @@ -1964,8 +1968,8 @@ namespace eosio { } return; } - if (net_msg == msg_type_t::signed_block) - fc_dlog(logger, "Connection - ${cid} - done sending block ${bn}", ("cid", conn->connection_id)("bn", block_num)); + if (net_msg == msg_type_t::signed_block && block_num) + fc_dlog(logger, "Connection - ${cid} - done sending block ${bn}", ("cid", conn->connection_id)("bn", *block_num)); if (close_after_send != no_reason) { fc_ilog( logger, "sent a go away message: ${r}, closing connection ${cid}", ("r", reason_str(close_after_send))("cid", conn->connection_id) ); @@ -2807,6 +2811,7 @@ namespace eosio { cp->latest_blk_time = std::chrono::steady_clock::now(); peer_dlog( cp, "bcast block_notice ${b}", ("b", bnum) ); cp->enqueue_buffer( msg_type_t::block_notice_message, queued_buffer::queue_t::general, send_buffer, 0, no_reason ); + cp->enqueue_buffer( msg_type_t::block_notice_message, std::nullopt, queued_buffer::queue_t::general, send_buffer, no_reason ); }); return; } @@ -2821,6 +2826,7 @@ namespace eosio { if( !has_block ) { peer_dlog( cp, "bcast block ${b}", ("b", bnum) ); cp->enqueue_buffer( msg_type_t::signed_block, queued_buffer::queue_t::general, sb, bnum, no_reason ); + cp->enqueue_buffer( msg_type_t::signed_block, bnum, queued_buffer::queue_t::general, sb, no_reason ); } }); } ); @@ -2834,7 +2840,7 @@ namespace eosio { boost::asio::post(cp->strand, [cp, msg]() { if (vote_logger.is_enabled(fc::log_level::debug)) peer_dlog(cp, "sending vote msg"); - cp->enqueue_buffer( msg_type_t::vote_message, queued_buffer::queue_t::general, msg, 0, no_reason ); + cp->enqueue_buffer( msg_type_t::vote_message, std::nullopt, queued_buffer::queue_t::general, msg, no_reason ); }); return true; } ); @@ -2855,7 +2861,7 @@ namespace eosio { send_buffer_type sb = buff_factory.get_send_buffer( trx ); fc_dlog( logger, "sending trx: ${id}, to connection - ${cid}", ("id", trx->id())("cid", cp->connection_id) ); boost::asio::post(cp->strand, [cp, sb{std::move(sb)}]() { - cp->enqueue_buffer( msg_type_t::packed_transaction, queued_buffer::queue_t::general, sb, 0, no_reason ); + cp->enqueue_buffer( msg_type_t::packed_transaction, std::nullopt, queued_buffer::queue_t::general, sb, no_reason ); } ); } ); } @@ -3303,7 +3309,7 @@ namespace eosio { buffer_factory buff_factory; auto send_buffer = buff_factory.get_send_buffer( block_nack_message{block_id} ); - enqueue_buffer( msg_type_t::block_nack_message, queued_buffer::queue_t::general, send_buffer, 0, no_reason ); + enqueue_buffer( msg_type_t::block_nack_message, std::nullopt, queued_buffer::queue_t::general, send_buffer, no_reason ); } void net_plugin_impl::plugin_shutdown() { From a076c8d2ca8b90f8c83b02b50d4f585ef895b07b Mon Sep 17 00:00:00 2001 From: Kevin Heifner Date: Thu, 27 Feb 2025 09:07:35 -0600 Subject: [PATCH 4/5] Use optional block_num --- plugins/net_plugin/net_plugin.cpp | 2 -- 1 file changed, 2 deletions(-) diff --git a/plugins/net_plugin/net_plugin.cpp b/plugins/net_plugin/net_plugin.cpp index 7755453c98..f7de92cd40 100644 --- a/plugins/net_plugin/net_plugin.cpp +++ b/plugins/net_plugin/net_plugin.cpp @@ -2810,7 +2810,6 @@ namespace eosio { boost::asio::post(cp->strand, [cp, send_buffer{std::move(send_buffer)}, bnum]() { cp->latest_blk_time = std::chrono::steady_clock::now(); peer_dlog( cp, "bcast block_notice ${b}", ("b", bnum) ); - cp->enqueue_buffer( msg_type_t::block_notice_message, queued_buffer::queue_t::general, send_buffer, 0, no_reason ); cp->enqueue_buffer( msg_type_t::block_notice_message, std::nullopt, queued_buffer::queue_t::general, send_buffer, no_reason ); }); return; @@ -2825,7 +2824,6 @@ namespace eosio { bool has_block = cp->peer_fork_db_root_num >= bnum; if( !has_block ) { peer_dlog( cp, "bcast block ${b}", ("b", bnum) ); - cp->enqueue_buffer( msg_type_t::signed_block, queued_buffer::queue_t::general, sb, bnum, no_reason ); cp->enqueue_buffer( msg_type_t::signed_block, bnum, queued_buffer::queue_t::general, sb, no_reason ); } }); From 27f8e99f11ae5ef7494bcd51ddd5ce084c5674cd Mon Sep 17 00:00:00 2001 From: Kevin Heifner Date: Thu, 27 Feb 2025 09:09:34 -0600 Subject: [PATCH 5/5] Revert back to debug log --- plugins/net_plugin/net_plugin.cpp | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/plugins/net_plugin/net_plugin.cpp b/plugins/net_plugin/net_plugin.cpp index f7de92cd40..fc3e8abb38 100644 --- a/plugins/net_plugin/net_plugin.cpp +++ b/plugins/net_plugin/net_plugin.cpp @@ -1154,7 +1154,7 @@ namespace eosio { void operator()( const block_notice_message& msg ) const { // continue call to handle_message on connection strand - peer_ilog( c, "handle block_notice_message #${bn}:${id}", ("bn", block_header::num_from_id(msg.id))("id", msg.id) ); + peer_dlog( c, "handle block_notice_message #${bn}:${id}", ("bn", block_header::num_from_id(msg.id))("id", msg.id) ); c->handle_message( msg ); } };