dn724/dncurrency
1
0
Fork 0
Code Issues Pull requests Projects Releases Packages 1 Wiki Activity Actions

Lazy log formatting

Browse source
This commit is contained in:
Piotr Wójcik 2025-01-21 17:39:17 +01:00
commit e38d9bf96d
19 changed files with 144 additions and 134 deletions
Download patch file Download diff file Expand all files Collapse all files

2
nano/lib/CMakeLists.txt
View file

@ -55,6 +55,8 @@ add_library(
errors.cpp errors.cpp
files.hpp files.hpp
files.cpp files.cpp
formatting.hpp
formatting.cpp
fwd.hpp fwd.hpp
id_dispenser.hpp id_dispenser.hpp
interval.hpp interval.hpp

2
nano/lib/common.hpp
View file

@ -2,6 +2,7 @@
namespace boost::asio::ip namespace boost::asio::ip
{ {
class address;
class tcp; class tcp;
template <typename InternetProtocol> template <typename InternetProtocol>
class basic_endpoint; class basic_endpoint;
@ -9,6 +10,7 @@ class basic_endpoint;
namespace nano namespace nano
{ {
using ip_address = boost::asio::ip::address;
using endpoint = boost::asio::ip::basic_endpoint<boost::asio::ip::tcp>; using endpoint = boost::asio::ip::basic_endpoint<boost::asio::ip::tcp>;
using tcp_endpoint = endpoint; using tcp_endpoint = endpoint;
} }

1
nano/lib/formatting.cpp Normal file
View file

@ -0,0 +1 @@
#include <nano/lib/formatting.hpp>

61
nano/lib/formatting.hpp Normal file
View file

@ -0,0 +1,61 @@
#pragma once
#include <nano/lib/common.hpp>
#include <nano/lib/numbers.hpp>
#include <fmt/ostream.h>
template <>
struct fmt::formatter<nano::endpoint> : fmt::ostream_formatter
{
};
template <>
struct fmt::formatter<nano::ip_address> : fmt::ostream_formatter
{
};
template <>
struct fmt::formatter<nano::uint128_t> : fmt::ostream_formatter
{
};
template <>
struct fmt::formatter<nano::uint256_t> : fmt::ostream_formatter
{
};
template <>
struct fmt::formatter<nano::uint512_t> : fmt::ostream_formatter
{
};
template <>
struct fmt::formatter<nano::uint128_union> : fmt::ostream_formatter
{
};
template <>
struct fmt::formatter<nano::uint256_union> : fmt::ostream_formatter
{
};
template <>
struct fmt::formatter<nano::uint512_union> : fmt::ostream_formatter
{
};
template <>
struct fmt::formatter<nano::hash_or_account> : fmt::ostream_formatter
{
};
template <>
struct fmt::formatter<nano::block_hash> : fmt::formatter<nano::uint256_union>
{
};
template <>
struct fmt::formatter<nano::public_key> : fmt::formatter<nano::uint256_union>
{
};
template <>
struct fmt::formatter<nano::qualified_root> : fmt::formatter<nano::uint512_union>
{
};
template <>
struct fmt::formatter<nano::root> : fmt::formatter<nano::hash_or_account>
{
};

1
nano/lib/logging.hpp
View file

@ -1,5 +1,6 @@
#pragma once #pragma once
#include <nano/lib/formatting.hpp>
#include <nano/lib/logging_enums.hpp> #include <nano/lib/logging_enums.hpp>
#include <nano/lib/object_stream.hpp> #include <nano/lib/object_stream.hpp>
#include <nano/lib/object_stream_adapters.hpp> #include <nano/lib/object_stream_adapters.hpp>

39
nano/lib/numbers.hpp
View file

@ -617,42 +617,3 @@ struct hash<::nano::uint512_union>;
template <> template <>
struct hash<::nano::qualified_root>; struct hash<::nano::qualified_root>;
} }
/*
* Formatters
*/
template <>
struct fmt::formatter<nano::uint128_union> : fmt::ostream_formatter
{
};
template <>
struct fmt::formatter<nano::uint256_union> : fmt::ostream_formatter
{
};
template <>
struct fmt::formatter<nano::uint512_union> : fmt::ostream_formatter
{
};
template <>
struct fmt::formatter<nano::hash_or_account> : fmt::ostream_formatter
{
};
template <>
struct fmt::formatter<nano::block_hash> : fmt::formatter<nano::uint256_union>
{
};
template <>
struct fmt::formatter<nano::public_key> : fmt::formatter<nano::uint256_union>
{
};
template <>
struct fmt::formatter<nano::qualified_root> : fmt::formatter<nano::uint512_union>
{
};

4
nano/node/active_elections.cpp
View file

@ -440,7 +440,7 @@ nano::election_insertion_result nano::active_elections::insert (std::shared_ptr<
nano::log::arg{ "election", result.election }); nano::log::arg{ "election", result.election });
node.logger.debug (nano::log::type::active_elections, "Started new election for block: {} (behavior: {}, active immediately: {})", node.logger.debug (nano::log::type::active_elections, "Started new election for block: {} (behavior: {}, active immediately: {})",
hash.to_string (), hash,
to_string (election_behavior_a), to_string (election_behavior_a),
activate_immediately); activate_immediately);
} }
@ -578,7 +578,7 @@ bool nano::active_elections::publish (std::shared_ptr<nano::block> const & block
node.vote_cache_processor.trigger (block_a->hash ()); node.vote_cache_processor.trigger (block_a->hash ());
node.stats.inc (nano::stat::type::active, nano::stat::detail::election_block_conflict); node.stats.inc (nano::stat::type::active, nano::stat::detail::election_block_conflict);
node.logger.debug (nano::log::type::active_elections, "Block was added to an existing election: {}", block_a->hash ().to_string ()); node.logger.debug (nano::log::type::active_elections, "Block was added to an existing election: {}", block_a->hash ());
} }
} }
return result; return result;

16
nano/node/bootstrap/bootstrap_service.cpp
View file

@ -542,8 +542,8 @@ bool nano::bootstrap_service::request (nano::account account, size_t count, std:
tag.hash = info->head; tag.hash = info->head;
logger.debug (nano::log::type::bootstrap, "Requesting blocks for {} starting from account frontier: {} (optimistic: {})", logger.debug (nano::log::type::bootstrap, "Requesting blocks for {} starting from account frontier: {} (optimistic: {})",
account.to_account (), // TODO: Lazy eval account,
tag.start.to_string (), // TODO: Lazy eval tag.start,
optimistic_reuest); optimistic_reuest);
} }
else // Pessimistic (safe) request case else // Pessimistic (safe) request case
@ -557,8 +557,8 @@ bool nano::bootstrap_service::request (nano::account account, size_t count, std:
tag.hash = conf_info->height; tag.hash = conf_info->height;
logger.debug (nano::log::type::bootstrap, "Requesting blocks for {} starting from confirmation frontier: {} (optimistic: {})", logger.debug (nano::log::type::bootstrap, "Requesting blocks for {} starting from confirmation frontier: {} (optimistic: {})",
account.to_account (), // TODO: Lazy eval account,
tag.start.to_string (), // TODO: Lazy eval tag.start,
optimistic_reuest); optimistic_reuest);
} }
else else
@ -567,7 +567,7 @@ bool nano::bootstrap_service::request (nano::account account, size_t count, std:
tag.start = account; tag.start = account;
logger.debug (nano::log::type::bootstrap, "Requesting blocks for {} starting from account root (optimistic: {})", logger.debug (nano::log::type::bootstrap, "Requesting blocks for {} starting from account root (optimistic: {})",
account.to_account (), // TODO: Lazy eval account,
optimistic_reuest); optimistic_reuest);
} }
} }
@ -579,7 +579,7 @@ bool nano::bootstrap_service::request (nano::account account, size_t count, std:
tag.type = query_type::blocks_by_account; tag.type = query_type::blocks_by_account;
tag.start = account; tag.start = account;
logger.debug (nano::log::type::bootstrap, "Requesting blocks for {}", account.to_account ()); // TODO: Lazy eval logger.debug (nano::log::type::bootstrap, "Requesting blocks for {}", account);
} }
} }
@ -594,7 +594,7 @@ bool nano::bootstrap_service::request_info (nano::block_hash hash, std::shared_p
tag.start = hash; tag.start = hash;
tag.hash = hash; tag.hash = hash;
logger.debug (nano::log::type::bootstrap, "Requesting account info for: {}", hash.to_string ()); // TODO: Lazy eval logger.debug (nano::log::type::bootstrap, "Requesting account info for: {}", hash);
return send (channel, tag); return send (channel, tag);
} }
@ -606,7 +606,7 @@ bool nano::bootstrap_service::request_frontiers (nano::account start, std::share
tag.source = source; tag.source = source;
tag.start = start; tag.start = start;
logger.debug (nano::log::type::bootstrap, "Requesting frontiers starting from: {}", start.to_account ()); // TODO: Lazy eval logger.debug (nano::log::type::bootstrap, "Requesting frontiers starting from: {}", start);
return send (channel, tag); return send (channel, tag);
} }

2
nano/node/bounded_backlog.cpp
View file

@ -292,7 +292,7 @@ std::deque<nano::block_hash> nano::bounded_backlog::perform_rollbacks (std::dequ
// Here we check that the block is still OK to rollback, there could be a delay between gathering the targets and performing the rollbacks // Here we check that the block is still OK to rollback, there could be a delay between gathering the targets and performing the rollbacks
if (auto block = ledger.any.block_get (transaction, hash)) if (auto block = ledger.any.block_get (transaction, hash))
{ {
logger.debug (nano::log::type::bounded_backlog, "Rolling back: {}, account: {}", hash.to_string (), block->account ().to_account ()); logger.debug (nano::log::type::bounded_backlog, "Rolling back: {}, account: {}", hash, block->account ());
std::deque<std::shared_ptr<nano::block>> rollback_list; std::deque<std::shared_ptr<nano::block>> rollback_list;
bool error = ledger.rollback (transaction, hash, rollback_list); bool error = ledger.rollback (transaction, hash, rollback_list);

4
nano/node/confirming_set.cpp
View file

@ -263,12 +263,12 @@ void nano::confirming_set::run_batch (std::unique_lock<std::mutex> & lock)
if (success) if (success)
{ {
stats.inc (nano::stat::type::confirming_set, nano::stat::detail::cemented_hash); stats.inc (nano::stat::type::confirming_set, nano::stat::detail::cemented_hash);
logger.debug (nano::log::type::confirming_set, "Cemented block: {} (total cemented: {})", hash.to_string (), cemented_count); logger.debug (nano::log::type::confirming_set, "Cemented block: {} (total cemented: {})", hash, cemented_count);
} }
else else
{ {
stats.inc (nano::stat::type::confirming_set, nano::stat::detail::cementing_failed); stats.inc (nano::stat::type::confirming_set, nano::stat::detail::cementing_failed);
logger.debug (nano::log::type::confirming_set, "Failed to cement block: {}", hash.to_string ()); logger.debug (nano::log::type::confirming_set, "Failed to cement block: {}", hash);
// Requeue failed blocks for processing later // Requeue failed blocks for processing later
// Add them to the deferred set while still holding the exclusive database write transaction to avoid block processor races // Add them to the deferred set while still holding the exclusive database write transaction to avoid block processor races

56
nano/node/distributed_work.cpp
View file

@ -96,7 +96,8 @@ void nano::distributed_work::start ()
} }
else else
{ {
this_l->node.logger.error (nano::log::type::distributed_work, "Error resolving work peer: {}:{} ({})", peer.first, peer.second, ec.message ()); this_l->node.logger.error (nano::log::type::distributed_work, "Error resolving work peer: {}:{} ({})",
peer.first, peer.second, ec.message ());
this_l->failure (); this_l->failure ();
} }
@ -169,9 +170,8 @@ void nano::distributed_work::do_request (nano::tcp_endpoint const & endpoint_a)
} }
else if (ec) else if (ec)
{ {
this_l->node.logger.error (nano::log::type::distributed_work, "Work peer responded with an error {}:{} ({})", this_l->node.logger.error (nano::log::type::distributed_work, "Work peer responded with an error {} ({})",
nano::util::to_str (connection->endpoint.address ()), connection->endpoint,
connection->endpoint.port (),
ec.message ()); ec.message ());
this_l->add_bad_peer (connection->endpoint); this_l->add_bad_peer (connection->endpoint);
@ -187,9 +187,8 @@ void nano::distributed_work::do_request (nano::tcp_endpoint const & endpoint_a)
} }
else if (ec && ec != boost::system::errc::operation_canceled) else if (ec && ec != boost::system::errc::operation_canceled)
{ {
this_l->node.logger.error (nano::log::type::distributed_work, "Unable to write to work peer {}:{} ({})", this_l->node.logger.error (nano::log::type::distributed_work, "Unable to write to work peer {} ({})",
nano::util::to_str (connection->endpoint.address ()), connection->endpoint,
connection->endpoint.port (),
ec.message ()); ec.message ());
this_l->add_bad_peer (connection->endpoint); this_l->add_bad_peer (connection->endpoint);
@ -199,9 +198,8 @@ void nano::distributed_work::do_request (nano::tcp_endpoint const & endpoint_a)
} }
else if (ec && ec != boost::system::errc::operation_canceled) else if (ec && ec != boost::system::errc::operation_canceled)
{ {
this_l->node.logger.error (nano::log::type::distributed_work, "Unable to connect to work peer {}:{} ({})", this_l->node.logger.error (nano::log::type::distributed_work, "Unable to connect to work peer {} ({})",
nano::util::to_str (connection->endpoint.address ()), connection->endpoint,
connection->endpoint.port (),
ec.message ()); ec.message ());
this_l->add_bad_peer (connection->endpoint); this_l->add_bad_peer (connection->endpoint);
@ -234,9 +232,8 @@ void nano::distributed_work::do_cancel (nano::tcp_endpoint const & endpoint_a)
[this_l, peer_cancel, cancelling_l] (boost::system::error_code const & ec, std::size_t bytes_transferred) { [this_l, peer_cancel, cancelling_l] (boost::system::error_code const & ec, std::size_t bytes_transferred) {
if (ec && ec != boost::system::errc::operation_canceled) if (ec && ec != boost::system::errc::operation_canceled)
{ {
this_l->node.logger.error (nano::log::type::distributed_work, "Unable to send work cancel to work peer {}:{} ({})", this_l->node.logger.error (nano::log::type::distributed_work, "Unable to send work cancel to work peer {} ({})",
nano::util::to_str (cancelling_l->endpoint.address ()), cancelling_l->endpoint,
cancelling_l->endpoint.port (),
ec.message ()); ec.message ());
} }
})); }));
@ -265,27 +262,24 @@ void nano::distributed_work::success (std::string const & body_a, nano::tcp_endp
} }
else else
{ {
node.logger.error (nano::log::type::distributed_work, "Incorrect work response from {}:{} for root {} with difficulty {}: {}", node.logger.error (nano::log::type::distributed_work, "Incorrect work response from {} for root {} with difficulty {}: {}",
nano::util::to_str (endpoint_a.address ()), endpoint_a,
endpoint_a.port (), request.root,
request.root.to_string (),
nano::to_string_hex (request.difficulty), nano::to_string_hex (request.difficulty),
work_text); work_text);
} }
} }
else else
{ {
node.logger.error (nano::log::type::distributed_work, "Work response from {}:{} wasn't a number: {}", node.logger.error (nano::log::type::distributed_work, "Work response from {} wasn't a number: {}",
nano::util::to_str (endpoint_a.address ()), endpoint_a,
endpoint_a.port (),
work_text); work_text);
} }
} }
catch (...) catch (...)
{ {
node.logger.error (nano::log::type::distributed_work, "Work response from {}:{} wasn't parsable: {}", node.logger.error (nano::log::type::distributed_work, "Work response from {} wasn't parsable: {}",
nano::util::to_str (endpoint_a.address ()), endpoint_a,
endpoint_a.port (),
body_a); body_a);
} }
if (error) if (error)
@ -319,17 +313,15 @@ void nano::distributed_work::stop_once (bool const local_stop_a)
connection_l->socket.close (ec); connection_l->socket.close (ec);
if (ec) if (ec)
{ {
this_l->node.logger.error (nano::log::type::distributed_work, "Error closing socket with work peer: {}:{} ({})", this_l->node.logger.error (nano::log::type::distributed_work, "Error closing socket with work peer: {} ({})",
nano::util::to_str (connection_l->endpoint.address ()), connection_l->endpoint,
connection_l->endpoint.port (),
ec.message ()); ec.message ());
} }
} }
else else
{ {
this_l->node.logger.error (nano::log::type::distributed_work, "Error cancelling operation with work peer: {}:{} ({})", this_l->node.logger.error (nano::log::type::distributed_work, "Error cancelling operation with work peer: {} ({})",
nano::util::to_str (connection_l->endpoint.address ()), connection_l->endpoint,
connection_l->endpoint.port (),
ec.message ()); ec.message ());
} }
} }
@ -347,7 +339,7 @@ void nano::distributed_work::set_once (uint64_t const work_a, std::string const
elapsed.stop (); elapsed.stop ();
node.logger.info (nano::log::type::distributed_work, "Work generation for {}, with a threshold difficulty of {} (multiplier {}x) complete: {} ms", node.logger.info (nano::log::type::distributed_work, "Work generation for {}, with a threshold difficulty of {} (multiplier {}x) complete: {} ms",
request.root.to_string (), request.root,
nano::to_string_hex (request.difficulty), nano::to_string_hex (request.difficulty),
nano::to_string (nano::difficulty::to_multiplier (request.difficulty, node.default_difficulty (request.version)), 2), nano::to_string (nano::difficulty::to_multiplier (request.difficulty, node.default_difficulty (request.version)), 2),
elapsed.value ().count ()); elapsed.value ().count ());
@ -369,7 +361,7 @@ void nano::distributed_work::cancel ()
elapsed.stop (); elapsed.stop ();
node.logger.info (nano::log::type::distributed_work, "Work generation for {} was cancelled after {} ms", node.logger.info (nano::log::type::distributed_work, "Work generation for {} was cancelled after {} ms",
request.root.to_string (), request.root,
elapsed.value ().count ()); elapsed.value ().count ());
status = work_generation_status::cancelled; status = work_generation_status::cancelled;
@ -397,7 +389,7 @@ void nano::distributed_work::handle_failure ()
if (!local_generation_started && !finished.exchange (true)) if (!local_generation_started && !finished.exchange (true))
{ {
node.logger.info (nano::log::type::distributed_work, "Work peer(s) failed to generate work for root {}, retrying... (backoff: {}s)", node.logger.info (nano::log::type::distributed_work, "Work peer(s) failed to generate work for root {}, retrying... (backoff: {}s)",
request.root.to_string (), request.root,
backoff.count ()); backoff.count ());
status = work_generation_status::failure_peers; status = work_generation_status::failure_peers;

29
nano/node/election.cpp
View file

@ -65,7 +65,7 @@ void nano::election::confirm_once (nano::unique_lock<nano::mutex> & lock)
nano::log::arg{ "status", extended_status }); nano::log::arg{ "status", extended_status });
node.logger.debug (nano::log::type::election, "Election confirmed with winner: {} (behavior: {}, state: {}, voters: {}, blocks: {}, duration: {}ms, confirmation requests: {})", node.logger.debug (nano::log::type::election, "Election confirmed with winner: {} (behavior: {}, state: {}, voters: {}, blocks: {}, duration: {}ms, confirmation requests: {})",
status_l.winner->hash ().to_string (), status_l.winner->hash (),
to_string (behavior_m), to_string (behavior_m),
to_string (state_m), to_string (state_m),
extended_status.status.voter_count, extended_status.status.voter_count,
@ -179,7 +179,7 @@ void nano::election::send_confirm_req (nano::confirmation_solicitor & solicitor_
node.stats.inc (nano::stat::type::election, nano::stat::detail::confirmation_request); node.stats.inc (nano::stat::type::election, nano::stat::detail::confirmation_request);
node.logger.debug (nano::log::type::election, "Sent confirmation request for root: {} (behavior: {}, state: {}, voters: {}, blocks: {}, duration: {}ms, confirmation requests: {})", node.logger.debug (nano::log::type::election, "Sent confirmation request for root: {} (behavior: {}, state: {}, voters: {}, blocks: {}, duration: {}ms, confirmation requests: {})",
qualified_root.to_string (), qualified_root,
to_string (behavior_m), to_string (behavior_m),
to_string (state_m), to_string (state_m),
status.voter_count, status.voter_count,
@ -210,7 +210,7 @@ bool nano::election::transition_priority ()
node.logger.debug (nano::log::type::election, "Transitioned election behavior to priority from {} for root: {} (duration: {}ms)", node.logger.debug (nano::log::type::election, "Transitioned election behavior to priority from {} for root: {} (duration: {}ms)",
to_string (behavior_m), to_string (behavior_m),
qualified_root.to_string (), qualified_root,
duration ().count ()); duration ().count ());
return true; return true;
@ -270,8 +270,8 @@ void nano::election::broadcast_block (nano::confirmation_solicitor & solicitor_a
node.stats.inc (nano::stat::type::election, last_block_hash.is_zero () ? nano::stat::detail::broadcast_block_initial : nano::stat::detail::broadcast_block_repeat); node.stats.inc (nano::stat::type::election, last_block_hash.is_zero () ? nano::stat::detail::broadcast_block_initial : nano::stat::detail::broadcast_block_repeat);
node.logger.debug (nano::log::type::election, "Broadcasting current winner: {} for root: {} (behavior: {}, state: {}, voters: {}, blocks: {}, duration: {}ms)", node.logger.debug (nano::log::type::election, "Broadcasting current winner: {} for root: {} (behavior: {}, state: {}, voters: {}, blocks: {}, duration: {}ms)",
status.winner->hash ().to_string (), status.winner->hash (),
qualified_root.to_string (), qualified_root,
to_string (behavior_m), to_string (behavior_m),
to_string (state_m), to_string (state_m),
status.voter_count, status.voter_count,
@ -558,11 +558,11 @@ nano::vote_code nano::election::vote (nano::account const & rep, uint64_t timest
nano::log::arg{ "weight", weight }); nano::log::arg{ "weight", weight });
node.logger.debug (nano::log::type::election, "Vote received for: {} from: {} root: {} (final: {}, weight: {}, source: {})", node.logger.debug (nano::log::type::election, "Vote received for: {} from: {} root: {} (final: {}, weight: {}, source: {})",
block_hash_a.to_string (), block_hash_a,
rep.to_account (), rep,
qualified_root.to_string (), qualified_root,
nano::vote::is_final_timestamp (timestamp_a), nano::vote::is_final_timestamp (timestamp_a),
weight.convert_to<std::string> (), weight,
to_string (vote_source_a)); to_string (vote_source_a));
if (!confirmed_locked ()) if (!confirmed_locked ())
@ -839,11 +839,10 @@ bool nano::election::contains (nano::block_hash const & hash) const
return last_blocks.contains (hash); return last_blocks.contains (hash);
} }
// TODO: Remove the need for .to_string () calls
void nano::election::operator() (nano::object_stream & obs) const void nano::election::operator() (nano::object_stream & obs) const
{ {
obs.write ("id", id); obs.write ("id", id);
obs.write ("qualified_root", qualified_root.to_string ()); obs.write ("qualified_root", qualified_root);
obs.write ("behavior", behavior_m); obs.write ("behavior", behavior_m);
obs.write ("height", height); obs.write ("height", height);
obs.write ("status", current_status ()); obs.write ("status", current_status ());
@ -851,7 +850,7 @@ void nano::election::operator() (nano::object_stream & obs) const
void nano::election_extended_status::operator() (nano::object_stream & obs) const void nano::election_extended_status::operator() (nano::object_stream & obs) const
{ {
obs.write ("winner", status.winner->hash ().to_string ()); obs.write ("winner", status.winner->hash ());
obs.write ("tally_amount", status.tally.to_string_dec ()); obs.write ("tally_amount", status.tally.to_string_dec ());
obs.write ("final_tally_amount", status.final_tally.to_string_dec ()); obs.write ("final_tally_amount", status.final_tally.to_string_dec ());
obs.write ("confirmation_request_count", status.confirmation_request_count); obs.write ("confirmation_request_count", status.confirmation_request_count);
@ -862,8 +861,8 @@ void nano::election_extended_status::operator() (nano::object_stream & obs) cons
obs.write_range ("votes", votes, [] (auto const & entry, nano::object_stream & obs) { obs.write_range ("votes", votes, [] (auto const & entry, nano::object_stream & obs) {
auto & [account, info] = entry; auto & [account, info] = entry;
obs.write ("account", account.to_account ()); obs.write ("account", account);
obs.write ("hash", info.hash.to_string ()); obs.write ("hash", info.hash);
obs.write ("final", nano::vote::is_final_timestamp (info.timestamp)); obs.write ("final", nano::vote::is_final_timestamp (info.timestamp));
obs.write ("timestamp", info.timestamp); obs.write ("timestamp", info.timestamp);
obs.write ("time", info.time.time_since_epoch ().count ()); obs.write ("time", info.time.time_since_epoch ().count ());
@ -876,7 +875,7 @@ void nano::election_extended_status::operator() (nano::object_stream & obs) cons
obs.write_range ("tally", tally, [] (auto const & entry, nano::object_stream & obs) { obs.write_range ("tally", tally, [] (auto const & entry, nano::object_stream & obs) {
auto & [amount, block] = entry; auto & [amount, block] = entry;
obs.write ("hash", block->hash ().to_string ()); obs.write ("hash", block->hash ());
obs.write ("amount", amount); obs.write ("amount", amount);
}); });
} }

2
nano/node/epoch_upgrader.cpp
View file

@ -65,7 +65,7 @@ void nano::epoch_upgrader::upgrade_impl (nano::raw_key const & prv_a, nano::epoc
bool fork (result == nano::block_status::fork); bool fork (result == nano::block_status::fork);
logger.error (nano::log::type::epoch_upgrader, "Failed to upgrade account {} (valid signature: {}, valid work: {}, fork: {})", logger.error (nano::log::type::epoch_upgrader, "Failed to upgrade account {} (valid signature: {}, valid work: {}, fork: {})",
account_a.to_account (), account_a,
valid_signature, valid_signature,
valid_work, valid_work,
fork); fork);

2
nano/node/local_block_broadcaster.cpp
View file

@ -192,7 +192,7 @@ void nano::local_block_broadcaster::run_broadcasts (nano::unique_lock<nano::mute
} }
logger.debug (nano::log::type::local_block_broadcaster, "Broadcasting block: {} (rebroadcasts so far: {})", logger.debug (nano::log::type::local_block_broadcaster, "Broadcasting block: {} (rebroadcasts so far: {})",
entry.block->hash ().to_string (), entry.block->hash (),
entry.rebroadcasts); entry.rebroadcasts);
stats.inc (nano::stat::type::local_block_broadcaster, nano::stat::detail::broadcast, nano::stat::dir::out); stats.inc (nano::stat::type::local_block_broadcaster, nano::stat::detail::broadcast, nano::stat::dir::out);

2
nano/node/node.cpp
View file

@ -483,7 +483,7 @@ void nano::node::process_active (std::shared_ptr<nano::block> const & incoming)
[[nodiscard]] nano::block_status nano::node::process (secure::write_transaction const & transaction, std::shared_ptr<nano::block> block) [[nodiscard]] nano::block_status nano::node::process (secure::write_transaction const & transaction, std::shared_ptr<nano::block> block)
{ {
auto status = ledger.process (transaction, block); auto status = ledger.process (transaction, block);
logger.debug (nano::log::type::node, "Directly processed block: {} (status: {})", block->hash ().to_string (), to_string (status)); logger.debug (nano::log::type::node, "Directly processed block: {} (status: {})", block->hash (), to_string (status));
return status; return status;
} }

16
nano/node/repcrawler.cpp
View file

@ -91,8 +91,8 @@ void nano::rep_crawler::validate_and_process (nano::unique_lock<nano::mutex> & l
if (rep_weight < minimum) if (rep_weight < minimum)
{ {
logger.debug (nano::log::type::rep_crawler, "Ignoring vote from account: {} with too little voting weight: {}", logger.debug (nano::log::type::rep_crawler, "Ignoring vote from account: {} with too little voting weight: {}",
vote->account.to_account (), vote->account,
fmt::streamed (rep_weight)); rep_weight);
continue; // Skip this vote continue; // Skip this vote
} }
@ -220,8 +220,8 @@ void nano::rep_crawler::cleanup ()
erase_if (reps, [this] (rep_entry const & rep) { erase_if (reps, [this] (rep_entry const & rep) {
if (!rep.channel->alive ()) if (!rep.channel->alive ())
{ {
logger.info (nano::log::type::rep_crawler, "Evicting representative: {} with dead channel at: {}", rep.account.to_account (), rep.channel->to_string ());
stats.inc (nano::stat::type::rep_crawler, nano::stat::detail::channel_dead); stats.inc (nano::stat::type::rep_crawler, nano::stat::detail::channel_dead);
logger.info (nano::log::type::rep_crawler, "Evicting representative: {} with dead channel at: {}", rep.account, rep.channel->to_string ());
return true; // Erase return true; // Erase
} }
return false; return false;
@ -233,13 +233,13 @@ void nano::rep_crawler::cleanup ()
{ {
if (query.replies == 0) if (query.replies == 0)
{ {
logger.debug (nano::log::type::rep_crawler, "Aborting unresponsive query for block: {} from: {}", query.hash.to_string (), query.channel->to_string ());
stats.inc (nano::stat::type::rep_crawler, nano::stat::detail::query_timeout); stats.inc (nano::stat::type::rep_crawler, nano::stat::detail::query_timeout);
logger.debug (nano::log::type::rep_crawler, "Aborting unresponsive query for block: {} from: {}", query.hash, query.channel->to_string ());
} }
else else
{ {
logger.debug (nano::log::type::rep_crawler, "Completion of query with: {} replies for block: {} from: {}", query.replies, query.hash.to_string (), query.channel->to_string ());
stats.inc (nano::stat::type::rep_crawler, nano::stat::detail::query_completion); stats.inc (nano::stat::type::rep_crawler, nano::stat::detail::query_completion);
logger.debug (nano::log::type::rep_crawler, "Completion of query with: {} replies for block: {} from: {}", query.replies, query.hash, query.channel->to_string ());
} }
return true; // Erase return true; // Erase
} }
@ -345,8 +345,8 @@ void nano::rep_crawler::query (std::deque<std::shared_ptr<nano::transport::chann
bool tracked = track_rep_request (hash_root, channel); bool tracked = track_rep_request (hash_root, channel);
if (tracked) if (tracked)
{ {
logger.debug (nano::log::type::rep_crawler, "Sending query for block: {} to: {}", hash_root.first.to_string (), channel->to_string ());
stats.inc (nano::stat::type::rep_crawler, nano::stat::detail::query_sent); stats.inc (nano::stat::type::rep_crawler, nano::stat::detail::query_sent);
logger.debug (nano::log::type::rep_crawler, "Sending query for block: {} to: {}", hash_root.first, channel->to_string ());
auto const & [hash, root] = hash_root; auto const & [hash, root] = hash_root;
nano::confirm_req req{ network_constants, hash, root }; nano::confirm_req req{ network_constants, hash, root };
@ -357,8 +357,8 @@ void nano::rep_crawler::query (std::deque<std::shared_ptr<nano::transport::chann
} }
else else
{ {
logger.debug (nano::log::type::rep_crawler, "Ignoring duplicate query for block: {} to: {}", hash_root.first.to_string (), channel->to_string ());
stats.inc (nano::stat::type::rep_crawler, nano::stat::detail::query_duplicate); stats.inc (nano::stat::type::rep_crawler, nano::stat::detail::query_duplicate);
logger.debug (nano::log::type::rep_crawler, "Ignoring duplicate query for block: {} to: {}", hash_root.first, channel->to_string ());
} }
} }
} }
@ -393,8 +393,8 @@ bool nano::rep_crawler::process (std::shared_ptr<nano::vote> const & vote, std::
}); });
if (found) if (found)
{ {
logger.debug (nano::log::type::rep_crawler, "Processing response for block: {} from: {}", target_hash.to_string (), channel->to_string ());
stats.inc (nano::stat::type::rep_crawler, nano::stat::detail::response); stats.inc (nano::stat::type::rep_crawler, nano::stat::detail::response);
logger.debug (nano::log::type::rep_crawler, "Processing response for block: {} from: {}", target_hash, channel->to_string ());
// Track response time // Track response time
stats.sample (nano::stat::sample::rep_response_time, nano::log::milliseconds_delta (it->time), { 0, config.query_timeout.count () }); stats.sample (nano::stat::sample::rep_response_time, nano::log::milliseconds_delta (it->time), { 0, config.query_timeout.count () });

11
nano/node/request_aggregator.cpp
View file

@ -253,19 +253,18 @@ auto nano::request_aggregator::aggregate (nano::secure::transaction const & tran
if (should_generate_final_vote (block)) if (should_generate_final_vote (block))
{ {
to_generate_final.push_back (block); to_generate_final.push_back (block);
stats.inc (nano::stat::type::requests, nano::stat::detail::requests_final); stats.inc (nano::stat::type::requests, nano::stat::detail::requests_final);
logger.debug (nano::log::type::request_aggregator, "Replying with final vote for: {} to: {}", logger.debug (nano::log::type::request_aggregator, "Replying with final vote for: {} to: {}",
block->hash ().to_string (), // TODO: Lazy eval block->hash (), channel_a->to_string ()); // TODO: Lazy eval
channel_a->to_string ()); // TODO: Lazy eval
} }
else else
{ {
stats.inc (nano::stat::type::requests, nano::stat::detail::requests_non_final); stats.inc (nano::stat::type::requests, nano::stat::detail::requests_non_final);
logger.debug (nano::log::type::request_aggregator, "Skipping reply with normal vote for: {} (requested by: {})", logger.debug (nano::log::type::request_aggregator, "Skipping reply with normal vote for: {} (requested by: {})",
block->hash ().to_string (), // TODO: Lazy eval block->hash (), channel_a->to_string ()); // TODO: Lazy eval
channel_a->to_string ()); // TODO: Lazy eval
} }
} }
else else
@ -273,9 +272,7 @@ auto nano::request_aggregator::aggregate (nano::secure::transaction const & tran
stats.inc (nano::stat::type::requests, nano::stat::detail::requests_unknown); stats.inc (nano::stat::type::requests, nano::stat::detail::requests_unknown);
logger.debug (nano::log::type::request_aggregator, "Cannot reply, block not found: {} with root: {} (requested by: {})", logger.debug (nano::log::type::request_aggregator, "Cannot reply, block not found: {} with root: {} (requested by: {})",
hash.to_string (), // TODO: Lazy eval hash, root, channel_a->to_string ()); // TODO: Lazy eval
root.to_string (), // TODO: Lazy eval
channel_a->to_string ()); // TODO: Lazy eval
} }
} }

2
nano/node/scheduler/priority.cpp
View file

@ -135,7 +135,7 @@ bool nano::scheduler::priority::activate (secure::transaction const & transactio
{ {
stats.inc (nano::stat::type::election_scheduler, nano::stat::detail::activated); stats.inc (nano::stat::type::election_scheduler, nano::stat::detail::activated);
logger.trace (nano::log::type::election_scheduler, nano::log::detail::block_activated, logger.trace (nano::log::type::election_scheduler, nano::log::detail::block_activated,
nano::log::arg{ "account", account.to_account () }, // TODO: Convert to lazy eval nano::log::arg{ "account", account },
nano::log::arg{ "block", block }, nano::log::arg{ "block", block },
nano::log::arg{ "time", account_info.modified }, nano::log::arg{ "time", account_info.modified },
nano::log::arg{ "priority_balance", priority_balance }, nano::log::arg{ "priority_balance", priority_balance },

26
nano/node/transport/tcp_listener.cpp
View file

@ -186,7 +186,7 @@ void nano::transport::tcp_listener::cleanup ()
if (connection.socket.expired () && connection.server.expired ()) if (connection.socket.expired () && connection.server.expired ())
{ {
stats.inc (nano::stat::type::tcp_listener, nano::stat::detail::erase_dead); stats.inc (nano::stat::type::tcp_listener, nano::stat::detail::erase_dead);
logger.debug (nano::log::type::tcp_listener, "Evicting dead connection: {}", fmt::streamed (connection.endpoint)); logger.debug (nano::log::type::tcp_listener, "Evicting dead connection: {}", connection.endpoint);
return true; return true;
} }
else else
@ -216,7 +216,7 @@ void nano::transport::tcp_listener::timeout ()
stats.inc (nano::stat::type::tcp_listener, nano::stat::detail::attempt_timeout); stats.inc (nano::stat::type::tcp_listener, nano::stat::detail::attempt_timeout);
logger.debug (nano::log::type::tcp_listener, "Connection attempt timed out: {} (started {}s ago)", logger.debug (nano::log::type::tcp_listener, "Connection attempt timed out: {} (started {}s ago)",
fmt::streamed (attempt.endpoint), nano::log::seconds_delta (attempt.start)); attempt.endpoint, nano::log::seconds_delta (attempt.start));
} }
} }
} }
@ -239,7 +239,7 @@ bool nano::transport::tcp_listener::connect (asio::ip::address ip, uint16_t port
{ {
stats.inc (nano::stat::type::tcp_listener_rejected, nano::stat::detail::max_attempts, nano::stat::dir::out); stats.inc (nano::stat::type::tcp_listener_rejected, nano::stat::detail::max_attempts, nano::stat::dir::out);
logger.debug (nano::log::type::tcp_listener, "Max connection attempts reached ({}), rejected connection attempt: {}", logger.debug (nano::log::type::tcp_listener, "Max connection attempts reached ({}), rejected connection attempt: {}",
count, ip.to_string ()); count, ip);
return false; // Rejected return false; // Rejected
} }
@ -248,7 +248,7 @@ bool nano::transport::tcp_listener::connect (asio::ip::address ip, uint16_t port
{ {
stats.inc (nano::stat::type::tcp_listener_rejected, nano::stat::detail::max_attempts_per_ip, nano::stat::dir::out); stats.inc (nano::stat::type::tcp_listener_rejected, nano::stat::detail::max_attempts_per_ip, nano::stat::dir::out);
logger.debug (nano::log::type::tcp_listener, "Connection attempt already in progress ({}), rejected connection attempt: {}", logger.debug (nano::log::type::tcp_listener, "Connection attempt already in progress ({}), rejected connection attempt: {}",
count, ip.to_string ()); count, ip);
return false; // Rejected return false; // Rejected
} }
@ -264,7 +264,7 @@ bool nano::transport::tcp_listener::connect (asio::ip::address ip, uint16_t port
nano::tcp_endpoint const endpoint{ ip, port }; nano::tcp_endpoint const endpoint{ ip, port };
stats.inc (nano::stat::type::tcp_listener, nano::stat::detail::connect_initiate, nano::stat::dir::out); stats.inc (nano::stat::type::tcp_listener, nano::stat::detail::connect_initiate, nano::stat::dir::out);
logger.debug (nano::log::type::tcp_listener, "Initiating outgoing connection to: {}", fmt::streamed (endpoint)); logger.debug (nano::log::type::tcp_listener, "Initiating outgoing connection to: {}", endpoint);
auto task = nano::async::task (strand, connect_impl (endpoint)); auto task = nano::async::task (strand, connect_impl (endpoint));
@ -438,9 +438,7 @@ auto nano::transport::tcp_listener::check_limits (asio::ip::address const & ip,
if (node.network.excluded_peers.check (ip)) // true => error if (node.network.excluded_peers.check (ip)) // true => error
{ {
stats.inc (nano::stat::type::tcp_listener_rejected, nano::stat::detail::excluded, to_stat_dir (type)); stats.inc (nano::stat::type::tcp_listener_rejected, nano::stat::detail::excluded, to_stat_dir (type));
logger.debug (nano::log::type::tcp_listener, "Rejected connection from excluded peer: {} ({})", logger.debug (nano::log::type::tcp_listener, "Rejected connection from excluded peer: {} ({})", ip, to_string (type));
ip.to_string (),
to_string (type));
return accept_result::rejected; return accept_result::rejected;
} }
@ -451,9 +449,7 @@ auto nano::transport::tcp_listener::check_limits (asio::ip::address const & ip,
{ {
stats.inc (nano::stat::type::tcp_listener_rejected, nano::stat::detail::max_per_ip, to_stat_dir (type)); 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 a new connection ({})", logger.debug (nano::log::type::tcp_listener, "Max connections: {} per IP: {} reached, unable to open a new connection ({})",
count, count, ip, to_string (type));
ip.to_string (),
to_string (type));
return accept_result::rejected; return accept_result::rejected;
} }
@ -466,9 +462,7 @@ auto nano::transport::tcp_listener::check_limits (asio::ip::address const & ip,
{ {
stats.inc (nano::stat::type::tcp_listener_rejected, nano::stat::detail::max_per_subnetwork, to_stat_dir (type)); 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 of IP: {} reached, unable to open a new connection ({})", logger.debug (nano::log::type::tcp_listener, "Max connections: {} per subnetwork of IP: {} reached, unable to open a new connection ({})",
count, count, ip, to_string (type));
ip.to_string (),
to_string (type));
return accept_result::rejected; return accept_result::rejected;
} }
@ -482,7 +476,7 @@ auto nano::transport::tcp_listener::check_limits (asio::ip::address const & ip,
{ {
stats.inc (nano::stat::type::tcp_listener_rejected, nano::stat::detail::max_attempts, to_stat_dir (type)); 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 ()); count, ip);
return accept_result::rejected; return accept_result::rejected;
} }
@ -493,7 +487,7 @@ auto nano::transport::tcp_listener::check_limits (asio::ip::address const & ip,
{ {
stats.inc (nano::stat::type::tcp_listener_rejected, nano::stat::detail::max_attempts, to_stat_dir (type)); 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 ()); count, ip);
return accept_result::rejected; return accept_result::rejected;
} }