Stats & logging

This commit is contained in:
Piotr Wójcik 2024-11-14 21:21:48 +01:00
commit 44e0417035
7 changed files with 46 additions and 17 deletions

View file

@ -55,6 +55,7 @@ enum class type
socket,
socket_server,
tcp,
tcp_socket,
tcp_server,
tcp_listener,
tcp_channels,

View file

@ -32,7 +32,7 @@ enum class type
tcp_server,
tcp_channel,
tcp_channel_queued,
tcp_channel_sent,
tcp_channel_send,
tcp_channel_drop,
tcp_channel_ec,
tcp_channels,
@ -158,6 +158,8 @@ enum class detail
requeued,
evicted,
other,
drop,
queued,
// processing queue
queue,
@ -315,8 +317,6 @@ enum class detail
generic,
// tcp
tcp_write_drop,
tcp_write_no_socket_drop,
tcp_silent_connection_drop,
tcp_io_timeout_drop,
tcp_connect_error,

View file

@ -62,6 +62,11 @@ void nano::network::start ()
run_reachout ();
});
}
else
{
node.logger.warn (nano::log::type::network, "Peer reachout is disabled");
}
if (config.cached_peer_reachout.count () > 0)
{
reachout_cached_thread = std::thread ([this] () {
@ -69,11 +74,19 @@ void nano::network::start ()
run_reachout_cached ();
});
}
else
{
node.logger.warn (nano::log::type::network, "Cached peer reachout is disabled");
}
if (!node.flags.disable_tcp_realtime)
{
tcp_channels.start ();
}
else
{
node.logger.warn (nano::log::type::network, "Realtime TCP is disabled");
}
}
void nano::network::stop ()

View file

@ -82,12 +82,14 @@ bool nano::transport::tcp_channel::send_buffer (nano::shared_const_buffer const
{
queue.push (traffic_type, { buffer, callback });
lock.unlock ();
node.stats.inc (nano::stat::type::tcp_channel, nano::stat::detail::queued, nano::stat::dir::out);
node.stats.inc (nano::stat::type::tcp_channel_queued, to_stat_detail (traffic_type), nano::stat::dir::out);
sending_task.notify ();
return true;
}
else
{
node.stats.inc (nano::stat::type::tcp_channel, nano::stat::detail::drop, nano::stat::dir::out);
node.stats.inc (nano::stat::type::tcp_channel_drop, to_stat_detail (traffic_type), nano::stat::dir::out);
}
return false;
@ -177,7 +179,8 @@ asio::awaitable<void> nano::transport::tcp_channel::send_one (traffic_type type,
co_return;
}
node.stats.inc (nano::stat::type::tcp_channel_sent, to_stat_detail (type), nano::stat::dir::out);
node.stats.inc (nano::stat::type::tcp_channel, nano::stat::detail::send, nano::stat::dir::out);
node.stats.inc (nano::stat::type::tcp_channel_send, to_stat_detail (type), nano::stat::dir::out);
socket_l->async_write (
buffer,

View file

@ -56,7 +56,7 @@ bool nano::transport::tcp_channels::check (const nano::tcp_endpoint & endpoint,
if (node.network.not_a_peer (nano::transport::map_tcp_to_endpoint (endpoint), node.config.allow_local_peers))
{
node.stats.inc (nano::stat::type::tcp_channels_rejected, nano::stat::detail::not_a_peer);
node.logger.debug (nano::log::type::tcp_channels, "Rejected invalid endpoint channel from: {}", fmt::streamed (endpoint));
node.logger.debug (nano::log::type::tcp_channels, "Rejected invalid endpoint channel: {}", fmt::streamed (endpoint));
return false; // Reject
}
@ -76,7 +76,7 @@ bool nano::transport::tcp_channels::check (const nano::tcp_endpoint & endpoint,
if (has_duplicate)
{
node.stats.inc (nano::stat::type::tcp_channels_rejected, nano::stat::detail::channel_duplicate);
node.logger.debug (nano::log::type::tcp_channels, "Duplicate channel rejected from: {} ({})", fmt::streamed (endpoint), node_id.to_node_id ());
node.logger.debug (nano::log::type::tcp_channels, "Rejected duplicate channel: {} ({})", fmt::streamed (endpoint), node_id.to_node_id ());
return false; // Reject
}
@ -100,15 +100,16 @@ std::shared_ptr<nano::transport::tcp_channel> nano::transport::tcp_channels::cre
if (!check (endpoint, node_id))
{
node.stats.inc (nano::stat::type::tcp_channels, nano::stat::detail::channel_rejected);
node.logger.debug (nano::log::type::tcp_channels, "Rejected new channel from: {} ({})", fmt::streamed (endpoint), node_id.to_node_id ());
node.logger.debug (nano::log::type::tcp_channels, "Rejected channel: {} ({})", fmt::streamed (endpoint), node_id.to_node_id ());
// Rejection reason should be logged earlier
return nullptr;
}
node.stats.inc (nano::stat::type::tcp_channels, nano::stat::detail::channel_accepted);
node.logger.debug (nano::log::type::tcp_channels, "Accepted new channel from: {} ({})",
node.logger.debug (nano::log::type::tcp_channels, "Accepted channel: {} ({}) ({})",
fmt::streamed (socket->remote_endpoint ()),
to_string (socket->endpoint_type ()),
node_id.to_node_id ());
auto channel = std::make_shared<nano::transport::tcp_channel> (node, socket);

View file

@ -447,7 +447,7 @@ auto nano::transport::tcp_listener::check_limits (asio::ip::address const & ip,
if (auto count = count_per_ip (ip); count >= node.config.network.max_peers_per_ip)
{
stats.inc (nano::stat::type::tcp_listener_rejected, nano::stat::detail::max_per_ip, to_stat_dir (type));
logger.debug (nano::log::type::tcp_listener, "Max connections per IP reached ({}), unable to open new connection: {} ({})",
logger.debug (nano::log::type::tcp_listener, "Max connections: {} per IP: {} reached, unable to open a new connection ({})",
count,
ip.to_string (),
to_string (type));
@ -462,7 +462,7 @@ auto nano::transport::tcp_listener::check_limits (asio::ip::address const & ip,
if (auto count = count_per_subnetwork (ip); count >= node.config.network.max_peers_per_subnetwork)
{
stats.inc (nano::stat::type::tcp_listener_rejected, nano::stat::detail::max_per_subnetwork, to_stat_dir (type));
logger.debug (nano::log::type::tcp_listener, "Max connections per subnetwork reached ({}), unable to open new connection: {} ({})",
logger.debug (nano::log::type::tcp_listener, "Max connections: {} per subnetwork of IP: {} reached, unable to open a new connection ({})",
count,
ip.to_string (),
to_string (type));
@ -478,7 +478,7 @@ auto nano::transport::tcp_listener::check_limits (asio::ip::address const & ip,
if (auto count = count_per_type (connection_type::inbound); count >= config.max_inbound_connections)
{
stats.inc (nano::stat::type::tcp_listener_rejected, nano::stat::detail::max_attempts, to_stat_dir (type));
logger.debug (nano::log::type::tcp_listener, "Max inbound connections reached ({}), unable to accept new connection: {}",
logger.debug (nano::log::type::tcp_listener, "Max inbound connections reached: {}, unable to accept new connection: {}",
count, ip.to_string ());
return accept_result::rejected;
@ -489,7 +489,7 @@ auto nano::transport::tcp_listener::check_limits (asio::ip::address const & ip,
if (auto count = count_per_type (connection_type::outbound); count >= config.max_outbound_connections)
{
stats.inc (nano::stat::type::tcp_listener_rejected, nano::stat::detail::max_attempts, to_stat_dir (type));
logger.debug (nano::log::type::tcp_listener, "Max outbound connections reached ({}), unable to initiate new connection: {}",
logger.debug (nano::log::type::tcp_listener, "Max outbound connections reached: {}, unable to initiate new connection: {}",
count, ip.to_string ());
return accept_result::rejected;

View file

@ -61,8 +61,7 @@ void nano::transport::tcp_socket::async_connect (nano::tcp_endpoint const & endp
boost::asio::post (strand, [this_l = shared_from_this (), endpoint_a, callback = std::move (callback_a)] () {
this_l->raw_socket.async_connect (endpoint_a,
boost::asio::bind_executor (this_l->strand,
[this_l, callback = std::move (callback), endpoint_a] (boost::system::error_code const & ec) {
boost::asio::bind_executor (this_l->strand, [this_l, callback = std::move (callback), endpoint_a] (boost::system::error_code const & ec) {
debug_assert (this_l->strand.running_in_this_thread ());
auto node_l = this_l->node_w.lock ();
@ -72,6 +71,7 @@ void nano::transport::tcp_socket::async_connect (nano::tcp_endpoint const & endp
}
this_l->remote = endpoint_a;
if (ec)
{
node_l->stats.inc (nano::stat::type::tcp, nano::stat::detail::tcp_connect_error, nano::stat::dir::in);
@ -85,6 +85,10 @@ void nano::transport::tcp_socket::async_connect (nano::tcp_endpoint const & endp
boost::system::error_code ec;
this_l->local = this_l->raw_socket.local_endpoint (ec);
}
node_l->logger.debug (nano::log::type::tcp_socket, "Successfully connected to: {}, local: {}",
fmt::streamed (this_l->remote),
fmt::streamed (this_l->local));
}
callback (ec);
}));
@ -316,8 +320,8 @@ void nano::transport::tcp_socket::ongoing_checkup ()
if (condition_to_disconnect)
{
node_l->logger.debug (nano::log::type::tcp_server, "Closing socket due to timeout ({})", nano::util::to_str (this_l->remote));
// TODO: Stats
node_l->logger.debug (nano::log::type::tcp_socket, "Socket timeout, closing: {}", fmt::streamed (this_l->remote));
this_l->timed_out = true;
this_l->close ();
}
@ -393,7 +397,14 @@ void nano::transport::tcp_socket::close_internal ()
if (ec)
{
node_l->stats.inc (nano::stat::type::socket, nano::stat::detail::error_socket_close);
node_l->logger.error (nano::log::type::socket, "Failed to close socket gracefully: {} ({})", ec.message (), nano::util::to_str (remote));
node_l->logger.error (nano::log::type::tcp_socket, "Failed to close socket gracefully: {} ({})",
fmt::streamed (remote),
ec.message ());
}
else
{
// TODO: Stats
node_l->logger.debug (nano::log::type::tcp_socket, "Closed socket: {}", fmt::streamed (remote));
}
}