From 401719e3066d9e99e449af2613a20b3c56061b1d Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Piotr=20Wo=CC=81jcik?= <3044353+pwojcikdev@users.noreply.github.com> Date: Tue, 23 Jan 2024 00:39:41 +0100 Subject: [PATCH 01/12] Unique object id generation --- nano/lib/id_dispenser.hpp | 13 +++++++++++++ nano/node/election.hpp | 2 ++ nano/store/lmdb/lmdb_env.hpp | 7 +------ 3 files changed, 16 insertions(+), 6 deletions(-) diff --git a/nano/lib/id_dispenser.hpp b/nano/lib/id_dispenser.hpp index 4b0cc53fe5..91aa651a17 100644 --- a/nano/lib/id_dispenser.hpp +++ b/nano/lib/id_dispenser.hpp @@ -59,4 +59,17 @@ class id_dispenser return dist; } }; + +inline id_dispenser & id_gen () +{ + static id_dispenser id_gen; + return id_gen; +} + +using id_t = id_dispenser::id_t; + +inline id_t next_id () +{ + return id_gen ().next_id (); +} } \ No newline at end of file diff --git a/nano/node/election.hpp b/nano/node/election.hpp index 8c025f654a..ffc0d9981b 100644 --- a/nano/node/election.hpp +++ b/nano/node/election.hpp @@ -75,6 +75,8 @@ struct election_extended_status final class election final : public std::enable_shared_from_this { + nano::id_t const id{ nano::next_id () }; // Track individual objects when tracing + public: enum class vote_source { diff --git a/nano/store/lmdb/lmdb_env.hpp b/nano/store/lmdb/lmdb_env.hpp index f947077c6b..e912653250 100644 --- a/nano/store/lmdb/lmdb_env.hpp +++ b/nano/store/lmdb/lmdb_env.hpp @@ -5,11 +5,6 @@ #include #include -namespace -{ -nano::id_dispenser id_gen; -} - namespace nano::store::lmdb { /** @@ -68,6 +63,6 @@ class env final store::write_transaction tx_begin_write (txn_callbacks callbacks = txn_callbacks{}) const; MDB_txn * tx (store::transaction const & transaction_a) const; MDB_env * environment; - nano::id_dispenser::id_t const store_id{ id_gen.next_id () }; + nano::id_t const store_id{ nano::next_id () }; }; } // namespace nano::store::lmdb From 1dd8ab4746d0bc2603cdac94cea496adfc03c011 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Piotr=20Wo=CC=81jcik?= <3044353+pwojcikdev@users.noreply.github.com> Date: Tue, 23 Jan 2024 12:42:29 +0100 Subject: [PATCH 02/12] Logger id lookup improvements --- nano/lib/logging.cpp | 109 ++++++++++++++++++++++++++----------------- nano/lib/logging.hpp | 48 ++++++++++--------- 2 files changed, 94 insertions(+), 63 deletions(-) diff --git a/nano/lib/logging.cpp b/nano/lib/logging.cpp index 3630c23d02..2860d76eb8 100644 --- a/nano/lib/logging.cpp +++ b/nano/lib/logging.cpp @@ -3,6 +3,7 @@ #include #include +#include #include #include #include @@ -24,8 +25,8 @@ nano::log_config nano::logger::global_config{}; std::vector nano::logger::global_sinks{}; // By default, use only the tag as the logger name, since only one node is running in the process -std::function nano::logger::global_name_formatter{ [] (auto tag, auto identifier) { - return std::string{ to_string (tag) }; +std::function nano::logger::global_name_formatter{ [] (nano::log::logger_id logger_id, std::string identifier) { + return to_string (logger_id); } }; void nano::logger::initialize (nano::log_config fallback, std::optional data_path, std::vector const & config_overrides) @@ -96,8 +97,8 @@ void nano::logger::initialize_for_tests (nano::log_config fallback) initialize_common (config, /* store log file in current workdir */ std::filesystem::current_path ()); // Use tag and identifier as the logger name, since multiple nodes may be running in the same process - global_name_formatter = [] (nano::log::type tag, std::string identifier) { - return fmt::format ("{}::{}", identifier, to_string (tag)); + global_name_formatter = [] (nano::log::logger_id logger_id, std::string identifier) { + return fmt::format ("{}::{}", identifier, to_string (logger_id)); }; // Setup formatter to include information about node identifier `[%i]` and tag `[%n]` @@ -209,13 +210,13 @@ nano::logger::~logger () flush (); } -spdlog::logger & nano::logger::get_logger (nano::log::type tag) +spdlog::logger & nano::logger::get_logger (nano::log::type type, nano::log::detail detail) { // This is a two-step process to avoid exclusively locking the mutex in the common case { std::shared_lock lock{ mutex }; - if (auto it = spd_loggers.find (tag); it != spd_loggers.end ()) + if (auto it = spd_loggers.find ({ type, detail }); it != spd_loggers.end ()) { return *it->second; } @@ -224,31 +225,42 @@ spdlog::logger & nano::logger::get_logger (nano::log::type tag) { std::unique_lock lock{ mutex }; - auto [it, inserted] = spd_loggers.emplace (tag, make_logger (tag)); + auto [it, inserted] = spd_loggers.emplace (std::make_pair (type, detail), make_logger ({ type, detail })); return *it->second; } } -std::shared_ptr nano::logger::make_logger (nano::log::type tag) +std::shared_ptr nano::logger::make_logger (nano::log::logger_id logger_id) { auto const & config = global_config; auto const & sinks = global_sinks; - auto name = global_name_formatter (tag, identifier); + auto name = global_name_formatter (logger_id, identifier); auto spd_logger = std::make_shared (name, sinks.begin (), sinks.end ()); - if (auto it = config.levels.find ({ tag, nano::log::detail::all }); it != config.levels.end ()) + spd_logger->set_level (to_spdlog_level (find_level (logger_id))); + spd_logger->flush_on (to_spdlog_level (config.flush_level)); + + return spd_logger; +} + +nano::log::level nano::logger::find_level (nano::log::logger_id logger_id) const +{ + auto const & config = global_config; + auto const & [type, detail] = logger_id; + + // Check for a specific level for this logger + if (auto it = config.levels.find (logger_id); it != config.levels.end ()) { - spd_logger->set_level (to_spdlog_level (it->second)); + return it->second; } - else + // Check for a default level for this logger type + if (auto it = config.levels.find ({ type, nano::log::detail::all }); it != config.levels.end ()) { - spd_logger->set_level (to_spdlog_level (config.default_level)); + return it->second; } - - spd_logger->flush_on (to_spdlog_level (config.flush_level)); - - return spd_logger; + // Use the default level + return config.default_level; } spdlog::level::level_enum nano::logger::to_spdlog_level (nano::log::level level) @@ -400,7 +412,7 @@ void nano::log_config::deserialize (nano::tomlconfig & toml) { auto & [name_str, level_str] = level; auto logger_level = nano::log::parse_level (level_str); - auto logger_id = parse_logger_id (name_str); + auto logger_id = nano::log::parse_logger_id (name_str); levels[logger_id] = logger_level; } @@ -413,29 +425,9 @@ void nano::log_config::deserialize (nano::tomlconfig & toml) } } -/** - * Parse `logger_name[:logger_detail]` into a pair of `log::type` and `log::detail` - * @throw std::invalid_argument if `logger_name` or `logger_detail` are invalid - */ -nano::log_config::logger_id_t nano::log_config::parse_logger_id (const std::string & logger_name) +std::map nano::log_config::default_levels (nano::log::level default_level) { - auto pos = logger_name.find ("::"); - if (pos == std::string::npos) - { - return { nano::log::parse_type (logger_name), nano::log::detail::all }; - } - else - { - auto logger_type = logger_name.substr (0, pos); - auto logger_detail = logger_name.substr (pos + 1); - - return { nano::log::parse_type (logger_type), nano::log::parse_detail (logger_detail) }; - } -} - -std::map nano::log_config::default_levels (nano::log::level default_level) -{ - std::map result; + std::map result; for (auto const & type : nano::log::all_types ()) { result.emplace (std::make_pair (type, nano::log::detail::all), default_level); @@ -475,7 +467,7 @@ nano::log_config nano::load_log_config (nano::log_config fallback, const std::fi auto env_levels = nano::get_env ("NANO_LOG_LEVELS"); if (env_levels) { - std::map levels; + std::map levels; for (auto const & env_level_str : nano::util::split (*env_levels, ',')) { try @@ -490,7 +482,7 @@ nano::log_config nano::load_log_config (nano::log_config fallback, const std::fi auto name_str = arr[0]; auto level_str = arr[1]; - auto logger_id = nano::log_config::parse_logger_id (name_str); + auto logger_id = nano::log::parse_logger_id (name_str); auto logger_level = nano::log::parse_level (level_str); levels[logger_id] = logger_level; @@ -517,4 +509,37 @@ nano::log_config nano::load_log_config (nano::log_config fallback, const std::fi std::cerr << "Unable to load log config. Using defaults. Error: " << ex.what () << std::endl; } return fallback; +} + +std::string nano::log::to_string (nano::log::logger_id logger_id) +{ + auto const & [type, detail] = logger_id; + if (detail == nano::log::detail::all) + { + return fmt::format ("{}", to_string (type)); + } + else + { + return fmt::format ("{}::{}", to_string (type), to_string (detail)); + } +} + +/** + * Parse `logger_name[:logger_detail]` into a pair of `log::type` and `log::detail` + * @throw std::invalid_argument if `logger_name` or `logger_detail` are invalid + */ +nano::log::logger_id nano::log::parse_logger_id (const std::string & logger_name) +{ + auto pos = logger_name.find ("::"); + if (pos == std::string::npos) + { + return { nano::log::parse_type (logger_name), nano::log::detail::all }; + } + else + { + auto logger_type = logger_name.substr (0, pos); + auto logger_detail = logger_name.substr (pos + 1); + + return { nano::log::parse_type (logger_type), nano::log::parse_detail (logger_detail) }; + } } \ No newline at end of file diff --git a/nano/lib/logging.hpp b/nano/lib/logging.hpp index 55f08ad64f..00b1cddbab 100644 --- a/nano/lib/logging.hpp +++ b/nano/lib/logging.hpp @@ -10,6 +10,14 @@ #include +namespace nano::log +{ +using logger_id = std::pair; + +std::string to_string (logger_id); +logger_id parse_logger_id (std::string const &); +} + namespace nano { class log_config final @@ -26,8 +34,7 @@ class log_config final nano::log::level default_level{ nano::log::level::info }; nano::log::level flush_level{ nano::log::level::error }; - using logger_id_t = std::pair; - std::map levels; + std::map levels; struct console_config { @@ -52,11 +59,9 @@ class log_config final static log_config tests_default (); static log_config sample_config (); // For auto-generated sample config files - static logger_id_t parse_logger_id (std::string const &); - private: /// Returns placeholder log levels for all loggers - static std::map default_levels (nano::log::level); + static std::map default_levels (nano::log::level); }; nano::log_config load_log_config (nano::log_config fallback, std::filesystem::path const & data_path, std::vector const & config_overrides = {}); @@ -79,56 +84,57 @@ class logger final static bool global_initialized; static nano::log_config global_config; static std::vector global_sinks; - static std::function global_name_formatter; + static std::function global_name_formatter; static void initialize_common (nano::log_config const &, std::optional data_path); public: template - void log (nano::log::level level, nano::log::type tag, spdlog::format_string_t fmt, Args &&... args) + void log (nano::log::level level, nano::log::type type, spdlog::format_string_t fmt, Args &&... args) { - get_logger (tag).log (to_spdlog_level (level), fmt, std::forward (args)...); + get_logger (type).log (to_spdlog_level (level), fmt, std::forward (args)...); } template - void debug (nano::log::type tag, spdlog::format_string_t fmt, Args &&... args) + void debug (nano::log::type type, spdlog::format_string_t fmt, Args &&... args) { - get_logger (tag).debug (fmt, std::forward (args)...); + get_logger (type).debug (fmt, std::forward (args)...); } template - void info (nano::log::type tag, spdlog::format_string_t fmt, Args &&... args) + void info (nano::log::type type, spdlog::format_string_t fmt, Args &&... args) { - get_logger (tag).info (fmt, std::forward (args)...); + get_logger (type).info (fmt, std::forward (args)...); } template - void warn (nano::log::type tag, spdlog::format_string_t fmt, Args &&... args) + void warn (nano::log::type type, spdlog::format_string_t fmt, Args &&... args) { - get_logger (tag).warn (fmt, std::forward (args)...); + get_logger (type).warn (fmt, std::forward (args)...); } template - void error (nano::log::type tag, spdlog::format_string_t fmt, Args &&... args) + void error (nano::log::type type, spdlog::format_string_t fmt, Args &&... args) { - get_logger (tag).error (fmt, std::forward (args)...); + get_logger (type).error (fmt, std::forward (args)...); } template - void critical (nano::log::type tag, spdlog::format_string_t fmt, Args &&... args) + void critical (nano::log::type type, spdlog::format_string_t fmt, Args &&... args) { - get_logger (tag).critical (fmt, std::forward (args)...); + get_logger (type).critical (fmt, std::forward (args)...); } private: const std::string identifier; - std::unordered_map> spd_loggers; + std::map> spd_loggers; std::shared_mutex mutex; private: - spdlog::logger & get_logger (nano::log::type tag); - std::shared_ptr make_logger (nano::log::type tag); + spdlog::logger & get_logger (nano::log::type, nano::log::detail = nano::log::detail::all); + std::shared_ptr make_logger (nano::log::logger_id); + nano::log::level find_level (nano::log::logger_id) const; static spdlog::level::level_enum to_spdlog_level (nano::log::level); }; From 7ac49e8ffdec7681c442ec898209543de1920926 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Piotr=20Wo=CC=81jcik?= <3044353+pwojcikdev@users.noreply.github.com> Date: Tue, 23 Jan 2024 00:30:39 +0100 Subject: [PATCH 03/12] Election locks fix --- nano/node/election.cpp | 16 ++++++++-------- nano/node/election.hpp | 2 +- 2 files changed, 9 insertions(+), 9 deletions(-) diff --git a/nano/node/election.cpp b/nano/node/election.cpp index a8f03dae5a..228da61a94 100644 --- a/nano/node/election.cpp +++ b/nano/node/election.cpp @@ -165,16 +165,16 @@ void nano::election::transition_active () state_change (nano::election::state_t::passive, nano::election::state_t::active); } -bool nano::election::confirmed_locked (nano::unique_lock & lock) const +bool nano::election::confirmed_locked () const { - debug_assert (lock.owns_lock ()); + debug_assert (!mutex.try_lock ()); return state_m == nano::election::state_t::confirmed || state_m == nano::election::state_t::expired_confirmed; } bool nano::election::confirmed () const { nano::unique_lock lock{ mutex }; - return confirmed_locked (lock); + return confirmed_locked (); } bool nano::election::failed () const @@ -245,7 +245,7 @@ bool nano::election::transition_time (nano::confirmation_solicitor & solicitor_a break; } - if (!confirmed_locked (lock) && time_to_live () < std::chrono::steady_clock::now () - election_start) + if (!confirmed_locked () && time_to_live () < std::chrono::steady_clock::now () - election_start) { // It is possible the election confirmed while acquiring the mutex // state_change returning true would indicate it @@ -383,7 +383,7 @@ boost::optional nano::election::try_confirm (nano::b if (winner && winner->hash () == hash) { // Determine if the block was confirmed explicitly via election confirmation or implicitly via confirmation height - if (!confirmed_locked (election_lock)) + if (!confirmed_locked ()) { confirm_once (election_lock, nano::election_status_type::active_confirmation_height); status_type = nano::election_status_type::active_confirmation_height; @@ -466,7 +466,7 @@ nano::election_vote_result nano::election::vote (nano::account const & rep, uint node.stats.inc (nano::stat::type::election, vote_source_a == vote_source::live ? nano::stat::detail::vote_new : nano::stat::detail::vote_cached); - if (!confirmed_locked (lock)) + if (!confirmed_locked ()) { confirm_if_quorum (lock); } @@ -478,7 +478,7 @@ bool nano::election::publish (std::shared_ptr const & block_a) nano::unique_lock lock{ mutex }; // Do not insert new blocks if already confirmed - auto result (confirmed_locked (lock)); + auto result (confirmed_locked ()); if (!result && last_blocks.size () >= max_blocks && last_blocks.find (block_a->hash ()) == last_blocks.end ()) { if (!replace_by_weight (lock, block_a->hash ())) @@ -544,7 +544,7 @@ void nano::election::broadcast_vote_locked (nano::unique_lock & loc { node.stats.inc (nano::stat::type::election, nano::stat::detail::generate_vote); - if (confirmed_locked (lock) || have_quorum (tally_impl ())) + if (confirmed_locked () || have_quorum (tally_impl ())) { node.stats.inc (nano::stat::type::election, nano::stat::detail::generate_vote_final); node.final_generator.add (root, status.winner->hash ()); // Broadcasts vote to the network diff --git a/nano/node/election.hpp b/nano/node/election.hpp index ffc0d9981b..b9561fc68a 100644 --- a/nano/node/election.hpp +++ b/nano/node/election.hpp @@ -168,7 +168,7 @@ class election final : public std::enable_shared_from_this private: nano::tally_t tally_impl () const; - bool confirmed_locked (nano::unique_lock & lock) const; + bool confirmed_locked () const; // lock_a does not own the mutex on return void confirm_once (nano::unique_lock & lock_a, nano::election_status_type = nano::election_status_type::active_confirmed_quorum); void broadcast_block (nano::confirmation_solicitor &); From 0f7b60df45012a585487aa9fe860d761e96a2496 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Piotr=20Wo=CC=81jcik?= <3044353+pwojcikdev@users.noreply.github.com> Date: Sun, 28 Jan 2024 21:32:18 +0100 Subject: [PATCH 04/12] Improve `nano::util::join` --- nano/lib/utility.hpp | 2 +- nano/secure/vote.cpp | 2 +- 2 files changed, 2 insertions(+), 2 deletions(-) diff --git a/nano/lib/utility.hpp b/nano/lib/utility.hpp index 61beefeeb4..97d8bd3ad5 100644 --- a/nano/lib/utility.hpp +++ b/nano/lib/utility.hpp @@ -232,7 +232,7 @@ std::string join (InputIt first, InputIt last, std::string_view delimiter, Func } else { - ss << delimiter << " "; + ss << delimiter; } ss << transform (*first); ++first; diff --git a/nano/secure/vote.cpp b/nano/secure/vote.cpp index 208aca4de1..9ffeabe04a 100644 --- a/nano/secure/vote.cpp +++ b/nano/secure/vote.cpp @@ -165,7 +165,7 @@ std::string nano::vote::to_json () const std::string nano::vote::hashes_string () const { - return nano::util::join (hashes, ",", [] (auto const & hash) { + return nano::util::join (hashes, ", ", [] (auto const & hash) { return hash.to_string (); }); } From 18749c26ce96fd0dd91eda2af812934fe2203742 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Piotr=20Wo=CC=81jcik?= <3044353+pwojcikdev@users.noreply.github.com> Date: Mon, 22 Jan 2024 20:51:21 +0100 Subject: [PATCH 05/12] Tracing --- CMakeLists.txt | 6 + ci/build.sh | 1 + nano/core_test/CMakeLists.txt | 3 +- nano/core_test/election.cpp | 4 +- nano/core_test/logger.cpp | 16 - nano/core_test/logging.cpp | 106 ++++ nano/core_test/object_stream.cpp | 559 ++++++++++++++++++++ nano/lib/CMakeLists.txt | 3 + nano/lib/blocks.cpp | 123 ++++- nano/lib/blocks.hpp | 37 ++ nano/lib/logging.cpp | 57 +- nano/lib/logging.hpp | 52 +- nano/lib/logging_enums.cpp | 35 ++ nano/lib/logging_enums.hpp | 47 +- nano/lib/object_stream.cpp | 28 + nano/lib/object_stream.hpp | 555 +++++++++++++++++++ nano/lib/object_stream_adapters.hpp | 127 +++++ nano/lib/stats_enums.hpp | 8 + nano/node/active_transactions.cpp | 16 +- nano/node/blockprocessor.cpp | 4 + nano/node/bootstrap/bootstrap_bulk_pull.cpp | 20 + nano/node/bootstrap/bootstrap_frontier.cpp | 5 + nano/node/election.cpp | 93 +++- nano/node/election.hpp | 8 + nano/node/messages.cpp | 334 ++++++------ nano/node/messages.hpp | 108 +++- nano/node/network.cpp | 3 +- nano/node/node.cpp | 6 +- nano/node/scheduler/priority.cpp | 17 +- nano/node/transport/channel.cpp | 15 + nano/node/transport/channel.hpp | 4 + nano/node/transport/socket.cpp | 25 +- nano/node/transport/socket.hpp | 5 +- nano/node/transport/tcp.cpp | 7 + nano/node/transport/tcp.hpp | 4 + nano/node/vote_processor.cpp | 4 + nano/node/voting.cpp | 12 +- nano/node/voting.hpp | 4 +- nano/secure/common.hpp | 1 + nano/secure/vote.cpp | 8 + nano/secure/vote.hpp | 3 + 41 files changed, 2216 insertions(+), 257 deletions(-) delete mode 100644 nano/core_test/logger.cpp create mode 100644 nano/core_test/logging.cpp create mode 100644 nano/core_test/object_stream.cpp create mode 100644 nano/lib/object_stream.cpp create mode 100644 nano/lib/object_stream.hpp create mode 100644 nano/lib/object_stream_adapters.hpp diff --git a/CMakeLists.txt b/CMakeLists.txt index a4c1ba48de..408ed1880a 100644 --- a/CMakeLists.txt +++ b/CMakeLists.txt @@ -133,6 +133,12 @@ if(NANO_STACKTRACE_BACKTRACE) endif() endif() +option(NANO_TRACING "Enable trace logging" OFF) +if(NANO_TRACING) + message(STATUS "Using trace logging") + add_compile_definitions(NANO_TRACING) +endif() + if(${NANO_TIMED_LOCKS} GREATER 0) add_definitions(-DNANO_TIMED_LOCKS=${NANO_TIMED_LOCKS}) add_definitions(-DNANO_TIMED_LOCKS_FILTER=${NANO_TIMED_LOCKS_FILTER}) diff --git a/ci/build.sh b/ci/build.sh index 7c25a724b5..07976992a4 100755 --- a/ci/build.sh +++ b/ci/build.sh @@ -57,6 +57,7 @@ cmake \ -DACTIVE_NETWORK=nano_${NANO_NETWORK:-"live"}_network \ -DNANO_TEST=${NANO_TEST:-OFF} \ -DNANO_GUI=${NANO_GUI:-OFF} \ +-DNANO_TRACING=${NANO_TRACING:-OFF} \ -DCOVERAGE=${COVERAGE:-OFF} \ -DCI_TAG=${CI_TAG:-OFF} \ -DCI_VERSION_PRE_RELEASE=${CI_VERSION_PRE_RELEASE:-OFF} \ diff --git a/nano/core_test/CMakeLists.txt b/nano/core_test/CMakeLists.txt index 623e6f2601..dda4bccab5 100644 --- a/nano/core_test/CMakeLists.txt +++ b/nano/core_test/CMakeLists.txt @@ -26,13 +26,14 @@ add_executable( ipc.cpp ledger.cpp locks.cpp - logger.cpp + logging.cpp message.cpp message_deserializer.cpp memory_pool.cpp network.cpp network_filter.cpp node.cpp + object_stream.cpp optimistic_scheduler.cpp processing_queue.cpp processor_service.cpp diff --git a/nano/core_test/election.cpp b/nano/core_test/election.cpp index 24450b7802..74b520f4fa 100644 --- a/nano/core_test/election.cpp +++ b/nano/core_test/election.cpp @@ -303,6 +303,6 @@ TEST (election, continuous_voting) ASSERT_TRUE (nano::test::process (node1, { send2 })); ASSERT_TIMELY (5s, node1.active.active (*send2)); - // Ensure votes are generated in continuous manner - ASSERT_TIMELY (5s, node1.stats.count (nano::stat::type::election, nano::stat::detail::generate_vote) >= 5); + // Ensure votes are broadcasted in continuous manner + ASSERT_TIMELY (5s, node1.stats.count (nano::stat::type::election, nano::stat::detail::broadcast_vote) >= 5); } diff --git a/nano/core_test/logger.cpp b/nano/core_test/logger.cpp deleted file mode 100644 index a282736058..0000000000 --- a/nano/core_test/logger.cpp +++ /dev/null @@ -1,16 +0,0 @@ - -#include -#include - -#include - -#include -#include -#include - -using namespace std::chrono_literals; - -TEST (logger, basic) -{ - // TODO -} diff --git a/nano/core_test/logging.cpp b/nano/core_test/logging.cpp new file mode 100644 index 0000000000..0ee857d158 --- /dev/null +++ b/nano/core_test/logging.cpp @@ -0,0 +1,106 @@ +#include +#include + +#include + +#include + +using namespace std::chrono_literals; + +namespace +{ +struct non_copyable +{ + non_copyable () = default; + non_copyable (non_copyable const &) = delete; + non_copyable (non_copyable &&) = default; + non_copyable & operator= (non_copyable const &) = delete; + non_copyable & operator= (non_copyable &&) = default; + + friend std::ostream & operator<< (std::ostream & os, non_copyable const & nc) + { + os << "non_copyable"; + return os; + } +}; +} + +TEST (tracing, no_copy) +{ + non_copyable nc; + + nano::logger logger; + logger.trace (nano::log::type::test, nano::log::detail::test, nano::log::arg{ "non_copyable", nc }); +} + +namespace +{ +struct non_moveable +{ + non_moveable () = default; + non_moveable (non_moveable const &) = delete; + non_moveable (non_moveable &&) = delete; + non_moveable & operator= (non_moveable const &) = delete; + non_moveable & operator= (non_moveable &&) = delete; + + friend std::ostream & operator<< (std::ostream & os, non_moveable const & nm) + { + os << "non_moveable"; + return os; + } +}; +} + +TEST (tracing, no_move) +{ + non_moveable nm; + + nano::logger logger; + logger.trace (nano::log::type::test, nano::log::detail::test, nano::log::arg{ "non_moveable", nm }); +} + +TEST (log_parse, parse_level) +{ + ASSERT_EQ (nano::log::parse_level ("error"), nano::log::level::error); + ASSERT_EQ (nano::log::parse_level ("off"), nano::log::level::off); + ASSERT_THROW (nano::log::parse_level ("enumnotpresent"), std::invalid_argument); + ASSERT_THROW (nano::log::parse_level (""), std::invalid_argument); + ASSERT_THROW (nano::log::parse_level ("_last"), std::invalid_argument); + ASSERT_THROW (nano::log::parse_level ("_error"), std::invalid_argument); +} + +TEST (log_parse, parse_type) +{ + ASSERT_EQ (nano::log::parse_type ("node"), nano::log::type::node); + ASSERT_THROW (nano::log::parse_type ("enumnotpresent"), std::invalid_argument); + ASSERT_THROW (nano::log::parse_type (""), std::invalid_argument); + ASSERT_THROW (nano::log::parse_type ("_last"), std::invalid_argument); + ASSERT_THROW (nano::log::parse_type ("_node"), std::invalid_argument); +} + +TEST (log_parse, parse_detail) +{ + ASSERT_EQ (nano::log::parse_detail ("all"), nano::log::detail::all); + ASSERT_EQ (nano::log::parse_detail ("process_confirmed"), nano::log::detail::process_confirmed); + ASSERT_THROW (nano::log::parse_detail ("enumnotpresent"), std::invalid_argument); + ASSERT_THROW (nano::log::parse_detail (""), std::invalid_argument); + ASSERT_THROW (nano::log::parse_detail ("_last"), std::invalid_argument); + ASSERT_THROW (nano::log::parse_detail ("_all"), std::invalid_argument); +} + +TEST (log_parse, parse_logger_id) +{ + ASSERT_EQ (nano::log::parse_logger_id ("node"), std::make_pair (nano::log::type::node, nano::log::detail::all)); + ASSERT_EQ (nano::log::parse_logger_id ("node::all"), std::make_pair (nano::log::type::node, nano::log::detail::all)); + ASSERT_EQ (nano::log::parse_logger_id ("node::process_confirmed"), std::make_pair (nano::log::type::node, nano::log::detail::process_confirmed)); + ASSERT_THROW (nano::log::parse_logger_id ("_last"), std::invalid_argument); + ASSERT_THROW (nano::log::parse_logger_id ("node::enumnotpresent"), std::invalid_argument); + ASSERT_THROW (nano::log::parse_logger_id ("node::"), std::invalid_argument); + ASSERT_THROW (nano::log::parse_logger_id ("node::_all"), std::invalid_argument); + ASSERT_THROW (nano::log::parse_logger_id ("enumnotpresent"), std::invalid_argument); + ASSERT_THROW (nano::log::parse_logger_id ("invalid."), std::invalid_argument); + ASSERT_THROW (nano::log::parse_logger_id ("invalid._all"), std::invalid_argument); + ASSERT_THROW (nano::log::parse_logger_id ("::"), std::invalid_argument); + ASSERT_THROW (nano::log::parse_logger_id ("::all"), std::invalid_argument); + ASSERT_THROW (nano::log::parse_logger_id (""), std::invalid_argument); +} \ No newline at end of file diff --git a/nano/core_test/object_stream.cpp b/nano/core_test/object_stream.cpp new file mode 100644 index 0000000000..59c09db3bc --- /dev/null +++ b/nano/core_test/object_stream.cpp @@ -0,0 +1,559 @@ +#include +#include +#include +#include + +#include + +#include + +#include +#include +#include +#include +#include + +#include + +namespace +{ +std::string trim (std::string_view str) +{ + return boost::trim_copy (std::string{ str }); +} +} + +TEST (object_stream, primitive_string) +{ + std::stringstream ss; + + nano::object_stream obs{ ss }; + obs.write ("field_name_1", "field_value"); + + auto expected = R"(field_name_1: "field_value")"; + ASSERT_EQ (ss.str (), expected); +} + +TEST (object_stream, primitive_string_view) +{ + std::stringstream ss; + + nano::object_stream obs{ ss }; + obs.write ("field_name_1", std::string_view{ "field_value" }); + + auto expected = R"(field_name_1: "field_value")"; + ASSERT_EQ (ss.str (), expected); +} + +TEST (object_stream, primitive_char) +{ + std::stringstream ss; + + nano::object_stream obs{ ss }; + obs.write ("field_name_1", 'a'); + + auto expected = R"(field_name_1: "a")"; + ASSERT_EQ (ss.str (), expected); +} + +TEST (object_stream, primitive_bool) +{ + std::stringstream ss; + + nano::object_stream obs{ ss }; + obs.write ("bool_field_1", true); + obs.write ("bool_field_2", false); + + auto expected = trim (R"( +bool_field_1: true, +bool_field_2: false +)"); + + ASSERT_EQ (ss.str (), expected); +} + +TEST (object_stream, primitive_int) +{ + std::stringstream ss; + + nano::object_stream obs{ ss }; + obs.write ("int_field_1", 1234); + obs.write ("int_field_2", -1234); + obs.write ("int_field_3", std::numeric_limits::max ()); + obs.write ("int_field_4", std::numeric_limits::min ()); + + auto expected = trim (R"( +int_field_1: 1234, +int_field_2: -1234, +int_field_3: 2147483647, +int_field_4: -2147483648 +)"); + + ASSERT_EQ (ss.str (), expected); +} + +TEST (object_stream, primitive_uint) +{ + std::stringstream ss; + + nano::object_stream obs{ ss }; + obs.write ("uint_field_1", static_cast (1234)); + obs.write ("uint_field_2", static_cast (-1234)); + obs.write ("uint_field_3", std::numeric_limits::max ()); + obs.write ("uint_field_4", std::numeric_limits::min ()); + + auto expected = trim (R"( +uint_field_1: 1234, +uint_field_2: 4294966062, +uint_field_3: 4294967295, +uint_field_4: 0 +)"); + + ASSERT_EQ (ss.str (), expected); +} + +TEST (object_stream, primitive_uint64) +{ + std::stringstream ss; + + nano::object_stream obs{ ss }; + obs.write ("uint64_field_1", static_cast (1234)); + obs.write ("uint64_field_2", static_cast (-1234)); + obs.write ("uint64_field_3", std::numeric_limits::max ()); + obs.write ("uint64_field_4", std::numeric_limits::min ()); + + auto expected = trim (R"( +uint64_field_1: 1234, +uint64_field_2: 18446744073709550382, +uint64_field_3: 18446744073709551615, +uint64_field_4: 0 +)"); + + ASSERT_EQ (ss.str (), expected); +} + +TEST (object_stream, primitive_int8) +{ + std::stringstream ss; + + nano::object_stream obs{ ss }; + obs.write ("int8_field_1", static_cast (123)); + + auto expected = R"(int8_field_1: 123)"; + ASSERT_EQ (ss.str (), expected); +} + +TEST (object_stream, primitive_uint8) +{ + std::stringstream ss; + + nano::object_stream obs{ ss }; + obs.write ("uint8_field_1", static_cast (123)); + + auto expected = R"(uint8_field_1: 123)"; + ASSERT_EQ (ss.str (), expected); +} + +TEST (object_stream, primitive_float) +{ + std::stringstream ss; + + nano::object_stream obs{ ss }; + obs.write ("float_field_1", 1234.5678f); + obs.write ("float_field_2", -1234.5678f); + obs.write ("float_field_3", std::numeric_limits::max ()); + obs.write ("float_field_4", std::numeric_limits::min ()); + obs.write ("float_field_5", std::numeric_limits::lowest ()); + + auto expected = trim (R"( +float_field_1: 1234.57, +float_field_2: -1234.57, +float_field_3: 340282346638528859811704183484516925440.00, +float_field_4: 0.00, +float_field_5: -340282346638528859811704183484516925440.00 +)"); + + ASSERT_EQ (ss.str (), expected); +} + +TEST (object_stream, primitive_double) +{ + std::stringstream ss; + + nano::object_stream obs{ ss }; + obs.write ("double_field_1", 1234.5678f); + obs.write ("double_field_2", -1234.5678f); + obs.write ("double_field_3", std::numeric_limits::max ()); + obs.write ("double_field_4", std::numeric_limits::min ()); + obs.write ("double_field_5", std::numeric_limits::lowest ()); + + auto expected = trim (R"( +double_field_1: 1234.57, +double_field_2: -1234.57, +double_field_3: 179769313486231570814527423731704356798070567525844996598917476803157260780028538760589558632766878171540458953514382464234321326889464182768467546703537516986049910576551282076245490090389328944075868508455133942304583236903222948165808559332123348274797826204144723168738177180919299881250404026184124858368.00, +double_field_4: 0.00, +double_field_5: -179769313486231570814527423731704356798070567525844996598917476803157260780028538760589558632766878171540458953514382464234321326889464182768467546703537516986049910576551282076245490090389328944075868508455133942304583236903222948165808559332123348274797826204144723168738177180919299881250404026184124858368.00 +)"); + + ASSERT_EQ (ss.str (), expected); +} + +TEST (object_stream, object_writer_basic) +{ + std::stringstream ss; + + nano::object_stream obs{ ss }; + obs.write ("object_field", [] (nano::object_stream & obs) { + obs.write ("field1", "value1"); + obs.write ("field2", "value2"); + obs.write ("field3", true); + obs.write ("field4", 1234); + }); + + auto expected = trim (R"( +object_field: { + field1: "value1", + field2: "value2", + field3: true, + field4: 1234 +} +)"); + + ASSERT_EQ (ss.str (), expected); +} + +TEST (object_stream, object_writer_nested) +{ + std::stringstream ss; + + nano::object_stream obs{ ss }; + obs.write ("object_field", [] (nano::object_stream & obs) { + obs.write ("field1", "value1"); + + obs.write ("nested_object", [] (nano::object_stream & obs) { + obs.write ("nested_field1", "nested_value1"); + obs.write ("nested_field2", false); + obs.write ("nested_field3", -1234); + }); + + obs.write ("field2", "value2"); + obs.write ("field3", true); + obs.write ("field4", 1234); + }); + + auto expected = trim (R"( +object_field: { + field1: "value1", + nested_object: { + nested_field1: "nested_value1", + nested_field2: false, + nested_field3: -1234 + }, + field2: "value2", + field3: true, + field4: 1234 +} +)"); + + ASSERT_EQ (ss.str (), expected); +} + +TEST (object_stream, array_writer_basic) +{ + std::stringstream ss; + + nano::object_stream obs{ ss }; + obs.write ("array_field", [] (nano::array_stream & ars) { + ars.write (std::views::iota (0, 3)); + }); + + auto expected = trim (R"( +array_field: [ + 0, + 1, + 2 +] +)"); + + ASSERT_EQ (ss.str (), expected); +} + +namespace +{ +class object_basic +{ +public: + nano::uint256_union uint256_union_field{ 0 }; + nano::block_hash block_hash{ 0 }; + + void operator() (nano::object_stream & obs) const + { + obs.write ("uint256_union_field", uint256_union_field); + obs.write ("block_hash", block_hash); + } +}; +} + +TEST (object_stream, object_basic) +{ + std::stringstream ss; + + nano::object_stream obs{ ss }; + object_basic test_object; + obs.write ("test_object", test_object); + + auto expected = trim (R"( +test_object: { + uint256_union_field: "0000000000000000000000000000000000000000000000000000000000000000", + block_hash: "0000000000000000000000000000000000000000000000000000000000000000" +} +)"); + + ASSERT_EQ (ss.str (), expected); +} + +TEST (object_stream, array_writer_objects) +{ + std::stringstream ss; + + std::vector objects; + objects.push_back ({ .block_hash = 0 }); + objects.push_back ({ .block_hash = 1 }); + objects.push_back ({ .block_hash = 2 }); + + nano::object_stream obs{ ss }; + obs.write ("array_field", [&objects] (nano::array_stream & ars) { + ars.write (objects); + }); + + auto expected = trim (R"( +array_field: [ + { + uint256_union_field: "0000000000000000000000000000000000000000000000000000000000000000", + block_hash: "0000000000000000000000000000000000000000000000000000000000000000" + }, + { + uint256_union_field: "0000000000000000000000000000000000000000000000000000000000000000", + block_hash: "0000000000000000000000000000000000000000000000000000000000000001" + }, + { + uint256_union_field: "0000000000000000000000000000000000000000000000000000000000000000", + block_hash: "0000000000000000000000000000000000000000000000000000000000000002" + } +] +)"); + + ASSERT_EQ (ss.str (), expected); +} + +namespace +{ +class object_array_basic +{ +public: + std::vector values{ 1, 2, 3 }; + + void operator() (nano::array_stream & ars) const + { + ars.write (values); + } +}; +} + +TEST (object_stream, object_array_basic) +{ + std::stringstream ss; + + nano::object_stream obs{ ss }; + object_array_basic test_object; + obs.write ("test_object_array", test_object); + + auto expected = trim (R"( +test_object_array: [ + 1, + 2, + 3 +] +)"); + + ASSERT_EQ (ss.str (), expected); +} + +namespace +{ +class object_nested +{ +public: + nano::uint256_union uint256_union_field{ 0 }; + nano::block_hash block_hash{ 0 }; + + object_basic nested_object; + object_array_basic nested_array_object; + + void operator() (nano::object_stream & obs) const + { + obs.write ("uint256_union_field", uint256_union_field); + obs.write ("block_hash", block_hash); + obs.write ("nested_object", nested_object); + obs.write ("nested_array_object", nested_array_object); + } +}; +} + +TEST (object_stream, object_nested) +{ + std::stringstream ss; + + nano::object_stream obs{ ss }; + object_nested test_object; + obs.write ("test_object", test_object); + + auto expected = trim (R"( +test_object: { + uint256_union_field: "0000000000000000000000000000000000000000000000000000000000000000", + block_hash: "0000000000000000000000000000000000000000000000000000000000000000", + nested_object: { + uint256_union_field: "0000000000000000000000000000000000000000000000000000000000000000", + block_hash: "0000000000000000000000000000000000000000000000000000000000000000" + }, + nested_array_object: [ + 1, + 2, + 3 + ] +} +)"); + + ASSERT_EQ (ss.str (), expected); +} + +namespace nano +{ +using builtin_array_with_pair = std::vector>; + +void stream_as (std::pair const & entry, nano::object_stream & obs) +{ + auto const & [hash, value] = entry; + obs.write ("hash", hash); + obs.write ("value", value); +} +} + +TEST (object_stream, builtin_array) +{ + using namespace nano; + + std::stringstream ss; + + builtin_array_with_pair array; + array.push_back ({ nano::block_hash{ 1 }, 1 }); + array.push_back ({ nano::block_hash{ 2 }, 2 }); + array.push_back ({ nano::block_hash{ 3 }, 3 }); + + nano::object_stream obs{ ss }; + obs.write_range ("array_field", array); + + auto expected = trim (R"( +array_field: [ + { + hash: "0000000000000000000000000000000000000000000000000000000000000001", + value: 1 + }, + { + hash: "0000000000000000000000000000000000000000000000000000000000000002", + value: 2 + }, + { + hash: "0000000000000000000000000000000000000000000000000000000000000003", + value: 3 + } +] +)"); + + ASSERT_EQ (ss.str (), expected); +} + +namespace +{ +class streamable_object +{ +public: + nano::uint256_union uint256_union_field{ 0 }; + nano::block_hash block_hash{ 0 }; + + void operator() (nano::object_stream & obs) const + { + obs.write ("uint256_union_field", uint256_union_field); + obs.write ("block_hash", block_hash); + } +}; +} + +TEST (object_stream, ostream_adapter) +{ + using namespace nano::object_stream_adapters; + + std::stringstream ss1, ss2; + + streamable_object test_object; + ss1 << test_object; // Using automatic ostream adapter (in `nano::ostream_operators`) + ss2 << nano::streamed (test_object); // Using explicit ostream adapter + + auto expected = trim (R"( +{ + uint256_union_field: "0000000000000000000000000000000000000000000000000000000000000000", + block_hash: "0000000000000000000000000000000000000000000000000000000000000000" +} +)"); + + ASSERT_EQ (ss1.str (), expected); + ASSERT_EQ (ss2.str (), expected); +} + +TEST (object_stream, fmt_adapter) +{ + streamable_object test_object; + auto str1 = fmt::format ("{}", test_object); // Using automatic fmt adapter + auto str2 = fmt::format ("{}", nano::streamed (test_object)); // Using explicit fmt adapter + + auto expected = trim (R"( +{ + uint256_union_field: "0000000000000000000000000000000000000000000000000000000000000000", + block_hash: "0000000000000000000000000000000000000000000000000000000000000000" +} +)"); + + ASSERT_EQ (str1, expected); + ASSERT_EQ (str2, expected); +} + +TEST (object_stream, to_string) +{ + using namespace nano::object_stream_adapters; + + streamable_object test_object; + auto str = to_string (test_object); // Using automatic to_string adapter + + auto expected = trim (R"( +{ + uint256_union_field: "0000000000000000000000000000000000000000000000000000000000000000", + block_hash: "0000000000000000000000000000000000000000000000000000000000000000" +} +)"); + + ASSERT_EQ (str, expected); +} + +TEST (object_stream, to_json) +{ + using namespace nano::object_stream_adapters; + + streamable_object test_object; + auto str = to_json (test_object); // Using automatic to_string adapter + + auto expected = trim (R"( +{"uint256_union_field":"0000000000000000000000000000000000000000000000000000000000000000","block_hash":"0000000000000000000000000000000000000000000000000000000000000000"} +)"); + + ASSERT_EQ (str, expected); +} \ No newline at end of file diff --git a/nano/lib/CMakeLists.txt b/nano/lib/CMakeLists.txt index 84fa0e1a6a..e93429ead3 100644 --- a/nano/lib/CMakeLists.txt +++ b/nano/lib/CMakeLists.txt @@ -58,6 +58,9 @@ add_library( memory.cpp numbers.hpp numbers.cpp + object_stream.hpp + object_stream.cpp + object_stream_adapters.hpp observer_set.hpp optional_ptr.hpp processing_queue.hpp diff --git a/nano/lib/blocks.cpp b/nano/lib/blocks.cpp index 7a77dfc3b7..3a13bb3868 100644 --- a/nano/lib/blocks.cpp +++ b/nano/lib/blocks.cpp @@ -45,6 +45,10 @@ void nano::block_memory_pool_purge () nano::purge_shared_ptr_singleton_pool_memory (); } +/* + * block + */ + std::string nano::block::to_json () const { std::string result; @@ -183,7 +187,7 @@ nano::account const & nano::block::account () const nano::qualified_root nano::block::qualified_root () const { - return nano::qualified_root (root (), previous ()); + return { root (), previous () }; } nano::amount const & nano::block::balance () const @@ -192,6 +196,21 @@ nano::amount const & nano::block::balance () const return amount; } +void nano::block::operator() (nano::object_stream & obs) const +{ + obs.write ("type", type ()); + obs.write ("hash", hash ()); + + if (has_sideband ()) + { + obs.write ("sideband", sideband ()); + } +} + +/* + * send_block + */ + void nano::send_block::visit (nano::block_visitor & visitor_a) const { visitor_a.send_block (*this); @@ -472,6 +491,21 @@ void nano::send_block::signature_set (nano::signature const & signature_a) signature = signature_a; } +void nano::send_block::operator() (nano::object_stream & obs) const +{ + nano::block::operator() (obs); // Write common data + + obs.write ("previous", hashables.previous); + obs.write ("destination", hashables.destination); + obs.write ("balance", hashables.balance); + obs.write ("signature", signature); + obs.write ("work", work); +} + +/* + * open_block + */ + nano::open_hashables::open_hashables (nano::block_hash const & source_a, nano::account const & representative_a, nano::account const & account_a) : source (source_a), representative (representative_a), @@ -748,6 +782,21 @@ void nano::open_block::signature_set (nano::signature const & signature_a) signature = signature_a; } +void nano::open_block::operator() (nano::object_stream & obs) const +{ + nano::block::operator() (obs); // Write common data + + obs.write ("source", hashables.source); + obs.write ("representative", hashables.representative); + obs.write ("account", hashables.account); + obs.write ("signature", signature); + obs.write ("work", work); +} + +/* + * change_block + */ + nano::change_hashables::change_hashables (nano::block_hash const & previous_a, nano::account const & representative_a) : previous (previous_a), representative (representative_a) @@ -999,6 +1048,20 @@ void nano::change_block::signature_set (nano::signature const & signature_a) signature = signature_a; } +void nano::change_block::operator() (nano::object_stream & obs) const +{ + nano::block::operator() (obs); // Write common data + + obs.write ("previous", hashables.previous); + obs.write ("representative", hashables.representative); + obs.write ("signature", signature); + obs.write ("work", work); +} + +/* + * state_block + */ + nano::state_hashables::state_hashables (nano::account const & account_a, nano::block_hash const & previous_a, nano::account const & representative_a, nano::amount const & balance_a, nano::link const & link_a) : account (account_a), previous (previous_a), @@ -1319,6 +1382,23 @@ void nano::state_block::signature_set (nano::signature const & signature_a) signature = signature_a; } +void nano::state_block::operator() (nano::object_stream & obs) const +{ + nano::block::operator() (obs); // Write common data + + obs.write ("account", hashables.account); + obs.write ("previous", hashables.previous); + obs.write ("representative", hashables.representative); + obs.write ("balance", hashables.balance); + obs.write ("link", hashables.link); + obs.write ("signature", signature); + obs.write ("work", work); +} + +/* + * + */ + std::shared_ptr nano::deserialize_block_json (boost::property_tree::ptree const & tree_a, nano::block_uniquer * uniquer_a) { std::shared_ptr result; @@ -1428,6 +1508,10 @@ std::shared_ptr nano::deserialize_block (nano::stream & stream_a, n return result; } +/* + * receive_block + */ + void nano::receive_block::visit (nano::block_visitor & visitor_a) const { visitor_a.receive_block (*this); @@ -1683,6 +1767,20 @@ void nano::receive_hashables::hash (blake2b_state & hash_a) const blake2b_update (&hash_a, source.bytes.data (), sizeof (source.bytes)); } +void nano::receive_block::operator() (nano::object_stream & obs) const +{ + nano::block::operator() (obs); // Write common data + + obs.write ("previous", hashables.previous); + obs.write ("source", hashables.source); + obs.write ("signature", signature); + obs.write ("work", work); +} + +/* + * block_details + */ + nano::block_details::block_details (nano::epoch const epoch_a, bool const is_send_a, bool const is_receive_a, bool const is_epoch_a) : epoch (epoch_a), is_send (is_send_a), is_receive (is_receive_a), is_epoch (is_epoch_a) { @@ -1734,6 +1832,14 @@ bool nano::block_details::deserialize (nano::stream & stream_a) return result; } +void nano::block_details::operator() (nano::object_stream & obs) const +{ + obs.write ("epoch", epoch); + obs.write ("is_send", is_send); + obs.write ("is_receive", is_receive); + obs.write ("is_epoch", is_epoch); +} + std::string nano::state_subtype (nano::block_details const details_a) { debug_assert (details_a.is_epoch + details_a.is_receive + details_a.is_send <= 1); @@ -1755,6 +1861,10 @@ std::string nano::state_subtype (nano::block_details const details_a) } } +/* + * block_sideband + */ + nano::block_sideband::block_sideband (nano::account const & account_a, nano::block_hash const & successor_a, nano::amount const & balance_a, uint64_t const height_a, nano::seconds_t const timestamp_a, nano::block_details const & details_a, nano::epoch const source_epoch_a) : successor (successor_a), account (account_a), @@ -1866,6 +1976,17 @@ bool nano::block_sideband::deserialize (nano::stream & stream_a, nano::block_typ return result; } +void nano::block_sideband::operator() (nano::object_stream & obs) const +{ + obs.write ("successor", successor); + obs.write ("account", account); + obs.write ("balance", balance); + obs.write ("height", height); + obs.write ("timestamp", timestamp); + obs.write ("source_epoch", source_epoch); + obs.write ("details", details); +} + std::string_view nano::to_string (nano::block_type type) { return magic_enum::enum_name (type); diff --git a/nano/lib/blocks.hpp b/nano/lib/blocks.hpp index acc44601d5..19c31d95eb 100644 --- a/nano/lib/blocks.hpp +++ b/nano/lib/blocks.hpp @@ -4,6 +4,7 @@ #include #include #include +#include #include #include #include @@ -19,6 +20,7 @@ namespace nano { class block_visitor; class mutable_block_visitor; + enum class block_type : uint8_t { invalid = 0, @@ -55,6 +57,9 @@ class block_details private: uint8_t packed () const; void unpack (uint8_t); + +public: // Logging + void operator() (nano::object_stream &) const; }; std::string state_subtype (nano::block_details const); @@ -75,7 +80,11 @@ class block_sideband final uint64_t timestamp{ 0 }; nano::block_details details; nano::epoch source_epoch{ nano::epoch::epoch_0 }; + +public: // Logging + void operator() (nano::object_stream &) const; }; + class block { public: @@ -132,6 +141,9 @@ class block private: nano::block_hash generate_hash () const; + +public: // Logging + virtual void operator() (nano::object_stream &) const; }; using block_list_t = std::vector>; @@ -149,6 +161,7 @@ class send_hashables nano::amount balance; static std::size_t constexpr size = sizeof (previous) + sizeof (destination) + sizeof (balance); }; + class send_block : public nano::block { public: @@ -182,7 +195,11 @@ class send_block : public nano::block nano::signature signature; uint64_t work; static std::size_t constexpr size = nano::send_hashables::size + sizeof (signature) + sizeof (work); + +public: // Logging + void operator() (nano::object_stream &) const override; }; + class receive_hashables { public: @@ -195,6 +212,7 @@ class receive_hashables nano::block_hash source; static std::size_t constexpr size = sizeof (previous) + sizeof (source); }; + class receive_block : public nano::block { public: @@ -227,7 +245,11 @@ class receive_block : public nano::block nano::signature signature; uint64_t work; static std::size_t constexpr size = nano::receive_hashables::size + sizeof (signature) + sizeof (work); + +public: // Logging + void operator() (nano::object_stream &) const override; }; + class open_hashables { public: @@ -241,6 +263,7 @@ class open_hashables nano::account account; static std::size_t constexpr size = sizeof (source) + sizeof (representative) + sizeof (account); }; + class open_block : public nano::block { public: @@ -276,7 +299,11 @@ class open_block : public nano::block nano::signature signature; uint64_t work; static std::size_t constexpr size = nano::open_hashables::size + sizeof (signature) + sizeof (work); + +public: // Logging + void operator() (nano::object_stream &) const override; }; + class change_hashables { public: @@ -289,6 +316,7 @@ class change_hashables nano::account representative; static std::size_t constexpr size = sizeof (previous) + sizeof (representative); }; + class change_block : public nano::block { public: @@ -321,7 +349,11 @@ class change_block : public nano::block nano::signature signature; uint64_t work; static std::size_t constexpr size = nano::change_hashables::size + sizeof (signature) + sizeof (work); + +public: // Logging + void operator() (nano::object_stream &) const override; }; + class state_hashables { public: @@ -347,6 +379,7 @@ class state_hashables // Serialized size static std::size_t constexpr size = sizeof (account) + sizeof (previous) + sizeof (representative) + sizeof (balance) + sizeof (link); }; + class state_block : public nano::block { public: @@ -382,7 +415,11 @@ class state_block : public nano::block nano::signature signature; uint64_t work; static std::size_t constexpr size = nano::state_hashables::size + sizeof (signature) + sizeof (work); + +public: // Logging + void operator() (nano::object_stream &) const override; }; + class block_visitor { public: diff --git a/nano/lib/logging.cpp b/nano/lib/logging.cpp index 2860d76eb8..7fbfb0b6e0 100644 --- a/nano/lib/logging.cpp +++ b/nano/lib/logging.cpp @@ -1,5 +1,6 @@ #include #include +#include #include #include @@ -23,6 +24,7 @@ nano::logger & nano::default_logger () bool nano::logger::global_initialized{ false }; nano::log_config nano::logger::global_config{}; std::vector nano::logger::global_sinks{}; +nano::object_stream_config nano::logger::global_tracing_config{}; // By default, use only the tag as the logger name, since only one node is running in the process std::function nano::logger::global_name_formatter{ [] (nano::log::logger_id logger_id, std::string identifier) { @@ -43,7 +45,6 @@ namespace /// Takes a qualified identifier in the form `node_identifier::tag` and splits it into a pair of `identifier` and `tag` /// It is a limitation of spldlog that we cannot attach additional data to the logger, so we have to encode the node identifier in the logger name /// @returns - std::pair split_qualified_identifier (std::string_view qualified_identifier) { auto pos = qualified_identifier.find ("::"); @@ -185,6 +186,17 @@ void nano::logger::initialize_common (nano::log_config const & config, std::opti global_sinks.push_back (file_sink); } } + + // Tracing setup + switch (config.tracing_format) + { + case nano::log::tracing_format::standard: + global_tracing_config = nano::object_stream_config::default_config (); + break; + case nano::log::tracing_format::json: + global_tracing_config = nano::object_stream_config::json_config (); + break; + } } void nano::logger::flush () @@ -453,9 +465,10 @@ nano::log_config nano::load_log_config (nano::log_config fallback, const std::fi { try { - config.default_level = nano::log::parse_level (*env_level); + auto level = nano::log::parse_level (*env_level); + config.default_level = level; - std::cerr << "Using default log level from NANO_LOG environment variable: " << *env_level << std::endl; + std::cerr << "Using default log level from NANO_LOG environment variable: " << to_string (level) << std::endl; } catch (std::invalid_argument const & ex) { @@ -487,7 +500,7 @@ nano::log_config nano::load_log_config (nano::log_config fallback, const std::fi levels[logger_id] = logger_level; - std::cerr << "Using logger log level from NANO_LOG_LEVELS environment variable: " << name_str << "=" << level_str << std::endl; + std::cerr << "Using logger log level from NANO_LOG_LEVELS environment variable: " << to_string (logger_id) << "=" << to_string (logger_level) << std::endl; } catch (std::invalid_argument const & ex) { @@ -502,6 +515,42 @@ nano::log_config nano::load_log_config (nano::log_config fallback, const std::fi } } + auto env_tracing_format = nano::get_env ("NANO_TRACE_FORMAT"); + if (env_tracing_format) + { + try + { + auto tracing_format = nano::log::parse_tracing_format (*env_tracing_format); + config.tracing_format = tracing_format; + + std::cerr << "Using trace format from NANO_TRACE_FORMAT environment variable: " << to_string (tracing_format) << std::endl; + } + catch (std::invalid_argument const & ex) + { + std::cerr << "Invalid trace format from NANO_TRACE_FORMAT environment variable: " << ex.what () << std::endl; + } + } + + auto tracing_configured = [&] () { + if (config.default_level == nano::log::level::trace) + { + return true; + } + for (auto const & [logger_id, level] : config.levels) + { + if (level == nano::log::level::trace) + { + return true; + } + } + return false; + }; + + if (tracing_configured () && !is_tracing_enabled ()) + { + std::cerr << "WARNING: Tracing is not enabled in this build, but log level is set to trace" << std::endl; + } + return config; } catch (std::runtime_error const & ex) diff --git a/nano/lib/logging.hpp b/nano/lib/logging.hpp index 00b1cddbab..8a77dae27d 100644 --- a/nano/lib/logging.hpp +++ b/nano/lib/logging.hpp @@ -1,6 +1,8 @@ #pragma once #include +#include +#include #include #include @@ -8,10 +10,24 @@ #include #include +#include #include namespace nano::log { +template +struct arg +{ + std::string_view name; + T const & value; + + arg (std::string_view name_a, T const & value_a) : + name{ name_a }, + value{ value_a } + { + } +}; + using logger_id = std::pair; std::string to_string (logger_id); @@ -20,6 +36,15 @@ logger_id parse_logger_id (std::string const &); namespace nano { +consteval bool is_tracing_enabled () +{ +#ifdef NANO_TRACING + return true; +#else + return false; +#endif +} + class log_config final { public: @@ -53,6 +78,8 @@ class log_config final console_config console; file_config file; + nano::log::tracing_format tracing_format{ nano::log::tracing_format::standard }; + public: // Predefined defaults static log_config cli_default (); static log_config daemon_default (); @@ -76,7 +103,7 @@ class logger final logger (logger const &) = delete; public: - static void initialize (nano::log_config fallback, std::optional data_path = std::nullopt, std::vector const & config_overrides = std::vector ()); + static void initialize (nano::log_config fallback, std::optional data_path = std::nullopt, std::vector const & config_overrides = {}); static void initialize_for_tests (nano::log_config fallback); static void flush (); @@ -85,6 +112,7 @@ class logger final static nano::log_config global_config; static std::vector global_sinks; static std::function global_name_formatter; + static nano::object_stream_config global_tracing_config; static void initialize_common (nano::log_config const &, std::optional data_path); @@ -125,6 +153,28 @@ class logger final get_logger (type).critical (fmt, std::forward (args)...); } +public: + template + void trace (nano::log::type type, nano::log::detail detail, Args &&... args) + { + if constexpr (is_tracing_enabled ()) + { + debug_assert (detail != nano::log::detail::all); + + // Include info about precise time of the event + auto now = std::chrono::high_resolution_clock::now (); + auto now_micros = std::chrono::duration_cast (now.time_since_epoch ()).count (); + + // TODO: Improve code indentation config + auto logger = get_logger (type, detail); + logger.trace ("{}", + nano::streamed_args (global_tracing_config, + nano::log::arg{ "event", to_string (std::make_pair (type, detail)) }, + nano::log::arg{ "time", now_micros }, + std::forward (args)...)); + } + } + private: const std::string identifier; diff --git a/nano/lib/logging_enums.cpp b/nano/lib/logging_enums.cpp index a7bbd1c7ba..7111ca6591 100644 --- a/nano/lib/logging_enums.cpp +++ b/nano/lib/logging_enums.cpp @@ -75,4 +75,39 @@ nano::log::detail nano::log::parse_detail (std::string_view name) { throw std::invalid_argument ("Invalid log detail: " + std::string (name)); } +} + +std::string_view nano::log::to_string (nano::log::tracing_format format) +{ + return magic_enum::enum_name (format); +} + +nano::log::tracing_format nano::log::parse_tracing_format (std::string_view name) +{ + auto value = magic_enum::enum_cast (name); + if (value.has_value ()) + { + return value.value (); + } + else + { + auto all_formats_str = nano::util::join (nano::log::all_tracing_formats (), ", ", [] (auto const & fmt) { + return to_string (fmt); + }); + + throw std::invalid_argument ("Invalid tracing format: " + std::string (name) + ". Must be one of: " + all_formats_str); + } +} + +const std::vector & nano::log::all_tracing_formats () +{ + static std::vector all = [] () { + std::vector result; + for (auto const & fmt : magic_enum::enum_values ()) + { + result.push_back (fmt); + } + return result; + }(); + return all; } \ No newline at end of file diff --git a/nano/lib/logging_enums.hpp b/nano/lib/logging_enums.hpp index af2ebfda84..d3df7ed774 100644 --- a/nano/lib/logging_enums.hpp +++ b/nano/lib/logging_enums.hpp @@ -24,6 +24,7 @@ enum class type all = 0, // reserved generic, + test, init, config, logging, @@ -46,7 +47,9 @@ enum class type election, blockprocessor, network, + network_processed, channel, + channel_sent, socket, socket_server, tcp, @@ -65,6 +68,10 @@ enum class type txn_tracker, gap_cache, vote_processor, + election_scheduler, + vote_generator, + + // bootstrap bulk_pull_client, bulk_pull_server, bulk_pull_account_client, @@ -84,6 +91,8 @@ enum class detail { all = 0, // reserved + test, + // node process_confirmed, @@ -94,6 +103,7 @@ enum class detail // election election_confirmed, election_expired, + broadcast_vote, // blockprocessor block_processed, @@ -102,10 +112,17 @@ enum class detail vote_processed, // network - message_received, + message_processed, message_sent, message_dropped, + // election_scheduler + block_activated, + + // vote_generator + candidate_processed, + should_vote, + // bulk pull/push pulled_block, sending_block, @@ -114,6 +131,24 @@ enum class detail requesting_account_or_head, requesting_pending, + // message types + not_a_type, + invalid, + keepalive, + publish, + republish_vote, + confirm_req, + confirm_ack, + node_id_handshake, + telemetry_req, + telemetry_ack, + asc_pull_req, + asc_pull_ack, + bulk_pull, + bulk_push, + frontier_req, + bulk_pull_account, + _last // Must be the last enum }; @@ -127,6 +162,12 @@ enum class category _last // Must be the last enum }; + +enum class tracing_format +{ + standard, + json, +}; } namespace nano::log @@ -146,6 +187,10 @@ nano::log::detail parse_detail (std::string_view); std::vector const & all_levels (); std::vector const & all_types (); + +std::string_view to_string (nano::log::tracing_format); +nano::log::tracing_format parse_tracing_format (std::string_view); +std::vector const & all_tracing_formats (); } // Ensure that the enum_range is large enough to hold all values (including future ones) diff --git a/nano/lib/object_stream.cpp b/nano/lib/object_stream.cpp new file mode 100644 index 0000000000..b733fc0eca --- /dev/null +++ b/nano/lib/object_stream.cpp @@ -0,0 +1,28 @@ +#include + +nano::object_stream_config const & nano::object_stream_config::default_config () +{ + static object_stream_config const config{}; + return config; +} + +nano::object_stream_config const & nano::object_stream_config::json_config () +{ + static object_stream_config const config{ + .field_name_begin = "\"", + .field_name_end = "\"", + .field_assignment = ":", + .field_separator = ",", + .object_begin = "{", + .object_end = "}", + .array_begin = "[", + .array_end = "]", + .array_element_begin = "", + .array_element_end = "", + .array_element_separator = ",", + .indent = "", + .newline = "", + .precision = 4, + }; + return config; +} \ No newline at end of file diff --git a/nano/lib/object_stream.hpp b/nano/lib/object_stream.hpp new file mode 100644 index 0000000000..02b20bf44b --- /dev/null +++ b/nano/lib/object_stream.hpp @@ -0,0 +1,555 @@ +#pragma once + +#include +#include +#include +#include +#include +#include +#include + +#include +#include + +namespace nano +{ +struct object_stream_config +{ + std::string field_name_begin{ "" }; + std::string field_name_end{ "" }; + std::string field_assignment{ ": " }; + std::string field_separator{ "," }; + + std::string object_begin{ "{" }; + std::string object_end{ "}" }; + + std::string array_begin{ "[" }; + std::string array_end{ "]" }; + + std::string array_element_begin{ "" }; + std::string array_element_end{ "" }; + std::string array_element_separator{ "," }; + + std::string string_begin{ "\"" }; + std::string string_end{ "\"" }; + + std::string true_value{ "true" }; + std::string false_value{ "false" }; + std::string null_value{ "null" }; + + std::string indent{ "\t" }; + std::string newline{ "\n" }; + + /** Number of decimal places to show for `float` and `double` */ + int precision{ 2 }; + + static object_stream_config const & default_config (); + static object_stream_config const & json_config (); +}; + +class object_stream_context +{ +public: + object_stream_config const & config; + + explicit object_stream_context (std::ostream & os, object_stream_config const & config = object_stream_config::default_config ()) : + os{ os }, + config{ config } + { + } + + // Bump indent level when nesting objects + object_stream_context (object_stream_context const & other) : + os{ other.os }, + config{ other.config }, + indent_level{ other.indent_level + 1 } + { + } + +private: + std::ostream & os; + int indent_level{ 0 }; + bool needs_newline{ false }; + +public: // Keep these defined in the header for inlining + std::ostream & begin_stream () + { + return os; + } + + void begin_field (std::string_view name, bool first) + { + if (!first) + { + os << config.field_separator; + } + if (std::exchange (needs_newline, false)) + { + os << config.newline; + } + indent (); + os << config.field_name_begin << name << config.field_name_end << config.field_assignment; + } + + void end_field () + { + needs_newline = true; + } + + void begin_object () + { + os << config.object_begin; + os << config.newline; + } + + void end_object () + { + os << config.newline; + indent (); + os << config.object_end; + needs_newline = true; + } + + void begin_array () + { + os << config.array_begin; + os << config.newline; + } + + void end_array () + { + os << config.newline; + indent (); + os << config.array_end; + needs_newline = true; + } + + void begin_array_element (bool first) + { + if (!first) + { + os << config.array_element_separator; + } + if (std::exchange (needs_newline, false)) + { + os << config.newline; + } + indent (); + os << config.array_element_begin; + } + + void end_array_element () + { + os << config.array_element_end; + needs_newline = true; + } + + void begin_string () + { + os << config.string_begin; + } + + void end_string () + { + os << config.string_end; + } + +private: + void indent () + { + if (!config.indent.empty ()) + { + for (int i = 0; i < indent_level; ++i) + { + os << config.indent; + } + } + } +}; + +class object_stream; +class array_stream; + +/* + * Concepts used for choosing the correct writing function + */ + +template +concept object_streamable = requires (T const & obj, object_stream & obs) { + { + stream_as (obj, obs) + }; +}; + +template +concept array_streamable = requires (T const & obj, array_stream & ars) { + { + stream_as (obj, ars) + }; +}; + +template +concept object_or_array_streamable = object_streamable || array_streamable; + +class object_stream_base +{ +public: + explicit object_stream_base (object_stream_context const & ctx) : + ctx{ ctx } + { + } + + explicit object_stream_base (std::ostream & os, object_stream_config const & config = object_stream_config::default_config ()) : + ctx{ os, config } + { + } + +protected: + object_stream_context ctx; +}; + +/** + * Used to serialize an object. + * Outputs: `field1: value1, field2: value2, ...` (without enclosing `{}`) + */ +class object_stream : private object_stream_base +{ +public: + // Inherit default constructors + using object_stream_base::object_stream_base; + + object_stream (object_stream const &) = delete; // Disallow copying + +public: + template + void write (std::string_view name, Value const & value) + { + ctx.begin_field (name, std::exchange (first_field, false)); + stream_as_value (value, ctx); + ctx.end_field (); + } + + // Handle `.write_range ("name", container)` + template + inline void write_range (std::string_view name, Container const & container); + + // Handle `.write_range ("name", container, [] (auto const & entry) { ... })` + template + requires (std::is_invocable_v) + void write_range (std::string_view name, Container const & container, Transform transform) + { + write_range (name, std::views::transform (container, transform)); + } + + // Handle `.write_range ("name", container, [] (auto const & entry, nano::object_stream &) { ... })` + template + requires (std::is_invocable_v) + void write_range (std::string_view name, Container const & container, Writer writer) + { + write_range (name, container, [&writer] (auto const & el) { + return [&writer, &el] (object_stream & obs) { + writer (el, obs); + }; + }); + } + + // Handle `.write_range ("name", container, [] (auto const & entry, nano::array_stream &) { ... })` + template + requires (std::is_invocable_v) + void write_range (std::string_view name, Container const & container, Writer writer) + { + write_range (name, container, [&writer] (auto const & el) { + return [&writer, &el] (array_stream & obs) { + writer (el, obs); + }; + }); + } + +private: + bool first_field{ true }; +}; + +/** + * Used to serialize an array of objects. + * Outputs: `[value1, value2, ...]` + */ +class array_stream : private object_stream_base +{ +public: + // Inherit default constructors + using object_stream_base::object_stream_base; + + array_stream (array_stream const &) = delete; // Disallow copying + +private: + template + void write_single (Value const & value) + { + ctx.begin_array_element (std::exchange (first_element, false)); + stream_as_value (value, ctx); + ctx.end_array_element (); + } + +public: + // Handle `.write (container)` + template + void write (Container const & container) + { + for (auto const & el : container) + { + write_single (el); + }; + } + + // Handle `.write (container, [] (auto const & entry) { ... })` + template + requires (std::is_invocable_v) + void write (Container const & container, Transform transform) + { + write (std::views::transform (container, transform)); + } + + // Handle `.write (container, [] (auto const & entry, nano::object_stream &) { ... })` + template + requires (std::is_invocable_v) + void write (Container const & container, Writer writer) + { + write (container, [&writer] (auto const & el) { + return [&writer, &el] (object_stream & obs) { + writer (el, obs); + }; + }); + } + + // Handle `.write_range (container, [] (auto const & entry, nano::array_stream &) { ... })` + template + requires (std::is_invocable_v) + void write (Container const & container, Writer writer) + { + write (container, [&writer] (auto const & el) { + return [&writer, &el] (array_stream & obs) { + writer (el, obs); + }; + }); + } + +private: + bool first_element{ true }; +}; + +/** + * Used for human readable object serialization. Should be used to serialize a single object. + * Outputs: `{ field1: value1, field2: value2, ... }` + */ +class root_object_stream : private object_stream_base +{ +public: + // Inherit default constructors + using object_stream_base::object_stream_base; + +public: + template + void write (Value const & value) + { + stream_as_value (value, ctx); + } + + // Handle `.write_range (container)` + template + inline void write_range (Container const & container); + + // Handle `.write_range (container, [] (auto const & entry) { ... })` + template + requires (std::is_invocable_v) + void write_range (Container const & container, Transform transform) + { + write_range (std::views::transform (container, transform)); + } + + // Handle `.write_range (container, [] (auto const & entry, nano::object_stream &) { ... })` + template + requires (std::is_invocable_v) + void write_range (Container const & container, Writer writer) + { + write_range (container, [&writer] (auto const & el) { + return [&writer, &el] (object_stream & obs) { + writer (el, obs); + }; + }); + } + + // Handle `.write_range (container, [] (auto const & entry, nano::array_stream &) { ... })` + template + requires (std::is_invocable_v) + void write_range (Container const & container, Writer writer) + { + write_range (container, [&writer] (auto const & el) { + return [&writer, &el] (array_stream & obs) { + writer (el, obs); + }; + }); + } +}; + +/* + * Implementation for `write_range` functions + */ + +template +inline void nano::object_stream::write_range (std::string_view name, Container const & container) +{ + write (name, [&container] (array_stream & ars) { + ars.write (container); + }); +} + +template +inline void nano::root_object_stream::write_range (Container const & container) +{ + write ([&container] (array_stream & ars) { + ars.write (container); + }); +} + +/* + * Writers + */ + +template +inline void stream_as_value (Value const & value, object_stream_context & ctx) +{ + // Automatically support printing all enums + using magic_enum::iostream_operators::operator<<; + + ctx.begin_string (); + ctx.begin_stream () << value; // Write using type specific ostream operator + ctx.end_string (); +} + +template +inline void stream_as_value (Value const & value, object_stream_context & ctx) +{ + ctx.begin_object (); + + // Write as object + nano::object_stream obs{ ctx }; + stream_as (value, obs); + + ctx.end_object (); +} + +template +inline void stream_as_value (Value const & value, object_stream_context & ctx) +{ + ctx.begin_array (); + + // Write as array + nano::array_stream ars{ ctx }; + stream_as (value, ars); + + ctx.end_array (); +} + +/* + * Adapters for types implementing convenience `obj(object_stream &)` & `obj(array_stream &)` functions + */ + +template +concept simple_object_streamable = requires (T const & obj, object_stream & obs) { + { + obj (obs) + }; +}; + +template +concept simple_array_streamable = requires (T const & obj, array_stream & ars) { + { + obj (ars) + }; +}; + +template +inline void stream_as (Value const & value, object_stream & obs) +{ + value (obs); +} + +template +inline void stream_as (Value const & value, array_stream & ars) +{ + value (ars); +} +} + +/* + * Specializations for primitive types + */ + +namespace nano +{ +template + requires (std::is_integral_v && sizeof (Value) > 1) // Exclude bool, char, etc. +inline void stream_as_value (const Value & value, object_stream_context & ctx) +{ + ctx.begin_stream () << value; +} + +template + requires (std::is_floating_point_v) +inline void stream_as_value (const Value & value, object_stream_context & ctx) +{ + ctx.begin_stream () << std::fixed << std::setprecision (ctx.config.precision) << value; +} + +inline void stream_as_value (bool const & value, object_stream_context & ctx) +{ + ctx.begin_stream () << (value ? ctx.config.true_value : ctx.config.false_value); +} + +inline void stream_as_value (const int8_t & value, object_stream_context & ctx) +{ + ctx.begin_stream () << static_cast (value); // Avoid printing as char +} + +inline void stream_as_value (const uint8_t & value, object_stream_context & ctx) +{ + ctx.begin_stream () << static_cast (value); // Avoid printing as char +} + +template +inline void stream_as_optional (const Opt & opt, object_stream_context & ctx) +{ + if (opt) + { + stream_as_value (*opt, ctx); + } + else + { + ctx.begin_stream () << ctx.config.null_value; + } +} + +template +inline void stream_as_value (std::shared_ptr const & value, object_stream_context & ctx) +{ + stream_as_optional (value, ctx); +} + +template +inline void stream_as_value (std::unique_ptr const & value, object_stream_context & ctx) +{ + stream_as_optional (value, ctx); +} + +template +inline void stream_as_value (std::weak_ptr const & value, object_stream_context & ctx) +{ + stream_as_optional (value.lock (), ctx); +} + +template +inline void stream_as_value (std::optional const & value, object_stream_context & ctx) +{ + stream_as_optional (value, ctx); +} +} \ No newline at end of file diff --git a/nano/lib/object_stream_adapters.hpp b/nano/lib/object_stream_adapters.hpp new file mode 100644 index 0000000000..8be5b445f4 --- /dev/null +++ b/nano/lib/object_stream_adapters.hpp @@ -0,0 +1,127 @@ +#pragma once + +#include + +#include +#include + +#include + +namespace nano +{ +template +struct object_stream_formatter +{ + nano::object_stream_config const & config; + Streamable const & value; + + explicit object_stream_formatter (Streamable const & value, nano::object_stream_config const & config) : + config{ config }, + value{ value } + { + } + + friend std::ostream & operator<< (std::ostream & os, object_stream_formatter const & self) + { + nano::root_object_stream obs{ os, self.config }; + obs.write (self.value); + return os; + } + + // Needed for fmt formatting, uses the ostream operator under the hood + friend auto format_as (object_stream_formatter const & val) + { + return fmt::streamed (val); + } +}; + +template +auto streamed (Streamable const & value) +{ + return object_stream_formatter{ value, nano::object_stream_config::default_config () }; +} + +template +auto streamed_as_json (Streamable const & value) +{ + return object_stream_formatter{ value, nano::object_stream_config::json_config () }; +} + +/** + * Wraps {name,value} args and provides `<<(std::ostream &, ...)` and fmt format operator that writes the arguments to the stream in a lazy manner. + */ +template +struct object_stream_args_formatter +{ + nano::object_stream_config const & config; + std::tuple args; + + explicit object_stream_args_formatter (nano::object_stream_config const & config, Args &&... args) : + config{ config }, + args{ std::forward (args)... } + { + } + + friend std::ostream & operator<< (std::ostream & os, object_stream_args_formatter const & self) + { + nano::object_stream obs{ os, self.config }; + std::apply ([&obs] (auto &&... args) { + ((obs.write (args.name, args.value)), ...); + }, + self.args); + return os; + } + + // Needed for fmt formatting, uses the ostream operator under the hood + friend auto format_as (object_stream_args_formatter const & val) + { + return fmt::streamed (val); + } +}; + +template +auto streamed_args (nano::object_stream_config const & config, Args &&... args) +{ + return object_stream_args_formatter{ config, std::forward (args)... }; +} +} + +/* + * Adapter that allows for printing using '<<' operator for all classes that implement object streaming + */ +namespace nano::object_stream_adapters +{ +template +std::ostream & operator<< (std::ostream & os, Value const & value) +{ + return os << nano::streamed (value); +} + +template +std::string to_string (Value const & value) +{ + std::stringstream ss; + ss << nano::streamed (value); + return ss.str (); +} + +template +std::string to_json (Value const & value) +{ + std::stringstream ss; + ss << nano::streamed_as_json (value); + return ss.str (); +} +} + +/* + * Adapter that allows for printing using fmt library for all classes that implement object streaming + */ +template +struct fmt::formatter : fmt::ostream_formatter +{ + auto format (Streamable const & value, format_context & ctx) + { + return fmt::ostream_formatter::format (nano::streamed (value), ctx); + } +}; \ No newline at end of file diff --git a/nano/lib/stats_enums.hpp b/nano/lib/stats_enums.hpp index b6373996ca..2bfda59d3c 100644 --- a/nano/lib/stats_enums.hpp +++ b/nano/lib/stats_enums.hpp @@ -152,6 +152,14 @@ enum class detail : uint8_t vote_processed, vote_cached, election_block_conflict, + election_restart, + election_not_confirmed, + election_hinted_overflow, + election_hinted_confirmed, + election_hinted_drop, + broadcast_vote, + broadcast_vote_normal, + broadcast_vote_final, generate_vote, generate_vote_normal, generate_vote_final, diff --git a/nano/node/active_transactions.cpp b/nano/node/active_transactions.cpp index a66f69119d..88c85c1e5b 100644 --- a/nano/node/active_transactions.cpp +++ b/nano/node/active_transactions.cpp @@ -322,9 +322,10 @@ void nano::active_transactions::cleanup_election (nano::unique_lock roots.get ().erase (roots.get ().find (election->qualified_root)); - lock_a.unlock (); - node.stats.inc (completion_type (*election), to_stat_detail (election->behavior ())); + node.logger.trace (nano::log::type::active_transactions, nano::log::detail::active_stopped, nano::log::arg{ "election", election }); + + lock_a.unlock (); vacancy_update (); @@ -421,7 +422,9 @@ nano::election_insertion_result nano::active_transactions::insert (std::shared_p nano::election_insertion_result result; if (stopped) + { return result; + } auto const root = block_a->qualified_root (); auto const hash = block_a->hash (); @@ -442,6 +445,11 @@ nano::election_insertion_result nano::active_transactions::insert (std::shared_p // Keep track of election count by election type debug_assert (count_by_behavior[result.election->behavior ()] >= 0); count_by_behavior[result.election->behavior ()]++; + + node.stats.inc (nano::stat::type::active_started, to_stat_detail (election_behavior_a)); + node.logger.trace (nano::log::type::active_transactions, nano::log::detail::active_started, + nano::log::arg{ "behavior", election_behavior_a }, + nano::log::arg{ "election", result.election }); } else { @@ -457,11 +465,13 @@ nano::election_insertion_result nano::active_transactions::insert (std::shared_p if (result.inserted) { + release_assert (result.election); + if (auto const cache = node.vote_cache.find (hash); cache) { cache->fill (result.election); } - node.stats.inc (nano::stat::type::active_started, to_stat_detail (election_behavior_a)); + node.observers.active_started.notify (hash); vacancy_update (); } diff --git a/nano/node/blockprocessor.cpp b/nano/node/blockprocessor.cpp index 76786fd247..27090889c9 100644 --- a/nano/node/blockprocessor.cpp +++ b/nano/node/blockprocessor.cpp @@ -255,6 +255,10 @@ nano::process_return nano::block_processor::process_one (store::write_transactio result = node.ledger.process (transaction_a, *block); node.stats.inc (nano::stat::type::blockprocessor, to_stat_detail (result.code)); + node.logger.trace (nano::log::type::blockprocessor, nano::log::detail::block_processed, + nano::log::arg{ "result", result.code }, + nano::log::arg{ "forced", forced_a }, + nano::log::arg{ "block", block }); switch (result.code) { diff --git a/nano/node/bootstrap/bootstrap_bulk_pull.cpp b/nano/node/bootstrap/bootstrap_bulk_pull.cpp index 33fb6717a2..2fcd9653a2 100644 --- a/nano/node/bootstrap/bootstrap_bulk_pull.cpp +++ b/nano/node/bootstrap/bootstrap_bulk_pull.cpp @@ -80,6 +80,10 @@ void nano::bulk_pull_client::request () req.count = pull.count; req.set_count_present (pull.count != 0); + node->logger.trace (nano::log::type::bulk_pull_client, nano::log::detail::requesting_account_or_head, + nano::log::arg{ "account_or_head", pull.account_or_head }, + nano::log::arg{ "channel", connection->channel }); + if (attempt->should_log ()) { node->logger.debug (nano::log::type::bulk_pull_client, "Accounts in pull queue: {}", attempt->pulling.load ()); @@ -166,6 +170,8 @@ void nano::bulk_pull_client::received_block (boost::system::error_code ec, std:: } auto hash = block->hash (); + node->logger.trace (nano::log::type::bulk_pull_client, nano::log::detail::pulled_block, nano::log::arg{ "block", block }); + // Is block expected? bool block_expected (false); // Unconfirmed head is used only for lazy destinations if legacy bootstrap is not available, see nano::bootstrap_attempt::lazy_destinations_increment (...) @@ -232,6 +238,10 @@ void nano::bulk_pull_account_client::request () req.minimum_amount = node->config.receive_minimum; req.flags = nano::bulk_pull_account_flags::pending_hash_and_amount; + node->logger.trace (nano::log::type::bulk_pull_account_client, nano::log::detail::requesting_pending, + nano::log::arg{ "account", req.account.to_account () }, // TODO: Convert to lazy eval + nano::log::arg{ "connection", connection->channel }); + if (attempt->should_log ()) { node->logger.debug (nano::log::type::bulk_pull_account_client, "Accounts in pull queue: {}", attempt->wallet_size ()); @@ -413,6 +423,10 @@ void nano::bulk_pull_server::send_next () auto block = get_next (); if (block != nullptr) { + node->logger.trace (nano::log::type::bulk_pull_server, nano::log::detail::sending_block, + nano::log::arg{ "block", block }, + nano::log::arg{ "socket", connection->socket }); + std::vector send_buffer; { nano::vectorstream stream (send_buffer); @@ -681,11 +695,17 @@ void nano::bulk_pull_account_server::send_next_block () std::vector send_buffer; if (pending_address_only) { + node->logger.trace (nano::log::type::bulk_pull_account_server, nano::log::detail::sending_pending, + nano::log::arg{ "pending", block_info->source }); + nano::vectorstream output_stream (send_buffer); write (output_stream, block_info->source.bytes); } else { + node->logger.trace (nano::log::type::bulk_pull_account_server, nano::log::detail::sending_block, + nano::log::arg{ "block", block_info_key->hash }); + nano::vectorstream output_stream (send_buffer); write (output_stream, block_info_key->hash.bytes); write (output_stream, block_info->amount.bytes); diff --git a/nano/node/bootstrap/bootstrap_frontier.cpp b/nano/node/bootstrap/bootstrap_frontier.cpp index 7a9d580361..76fa692177 100644 --- a/nano/node/bootstrap/bootstrap_frontier.cpp +++ b/nano/node/bootstrap/bootstrap_frontier.cpp @@ -275,6 +275,11 @@ void nano::frontier_req_server::send_next () } if (!current.is_zero () && count < request->count) { + node->logger.trace (nano::log::type::frontier_req_server, nano::log::detail::sending_frontier, + nano::log::arg{ "account", current.to_account () }, // TODO: Convert to lazy eval + nano::log::arg{ "frontier", frontier }, + nano::log::arg{ "socket", connection->socket }); + std::vector send_buffer; { nano::vectorstream stream (send_buffer); diff --git a/nano/node/election.cpp b/nano/node/election.cpp index 228da61a94..ae3afd7ce6 100644 --- a/nano/node/election.cpp +++ b/nano/node/election.cpp @@ -20,6 +20,10 @@ nano::election_vote_result::election_vote_result (bool replay_a, bool processed_ processed = processed_a; } +/* + * election + */ + nano::election::election (nano::node & node_a, std::shared_ptr const & block_a, std::function const &)> const & confirmation_action_a, std::function const & live_vote_action_a, nano::election_behavior election_behavior_a) : confirmation_action (confirmation_action_a), live_vote_action (live_vote_action_a), @@ -56,6 +60,11 @@ void nano::election::confirm_once (nano::unique_lock & lock_a, nano node.active.recently_confirmed.put (qualified_root, status_l.winner->hash ()); + node.logger.trace (nano::log::type::election, nano::log::detail::election_confirmed, + nano::log::arg{ "id", id }, + nano::log::arg{ "qualified_root", qualified_root }, + nano::log::arg{ "status", current_status_locked () }); + lock_a.unlock (); node.background ([node_l = node.shared (), status_l, confirmation_action_l = confirmation_action] () { @@ -251,6 +260,11 @@ bool nano::election::transition_time (nano::confirmation_solicitor & solicitor_a // state_change returning true would indicate it if (!state_change (state_m, nano::election::state_t::expired_unconfirmed)) { + node.logger.trace (nano::log::type::election, nano::log::detail::election_expired, + nano::log::arg{ "id", id }, + nano::log::arg{ "qualified_root", qualified_root }, + nano::log::arg{ "status", current_status_locked () }); + result = true; // Return true to indicate this election should be cleaned up status.type = nano::election_status_type::stopped; } @@ -458,6 +472,7 @@ nano::election_vote_result nano::election::vote (nano::account const & rep, uint return nano::election_vote_result (false, false); } } + last_votes[rep] = { std::chrono::steady_clock::now (), timestamp_a, block_hash_a }; if (vote_source_a == vote_source::live) { @@ -465,6 +480,15 @@ nano::election_vote_result nano::election::vote (nano::account const & rep, uint } node.stats.inc (nano::stat::type::election, vote_source_a == vote_source::live ? nano::stat::detail::vote_new : nano::stat::detail::vote_cached); + node.logger.trace (nano::log::type::election, nano::log::detail::vote_processed, + nano::log::arg{ "id", id }, + nano::log::arg{ "qualified_root", qualified_root }, + nano::log::arg{ "account", rep }, + nano::log::arg{ "hash", block_hash_a }, + nano::log::arg{ "final", nano::vote::is_final_timestamp (timestamp_a) }, + nano::log::arg{ "timestamp", timestamp_a }, + nano::log::arg{ "vote_source", vote_source_a }, + nano::log::arg{ "weight", weight }); if (!confirmed_locked ()) { @@ -518,11 +542,18 @@ bool nano::election::publish (std::shared_ptr const & block_a) nano::election_extended_status nano::election::current_status () const { nano::lock_guard guard{ mutex }; + return current_status_locked (); +} + +nano::election_extended_status nano::election::current_status_locked () const +{ + debug_assert (!mutex.try_lock ()); + nano::election_status status_l = status; status_l.confirmation_request_count = confirmation_request_count; status_l.block_count = nano::narrow_cast (last_blocks.size ()); status_l.voter_count = nano::narrow_cast (last_votes.size ()); - return nano::election_extended_status{ status_l, last_votes, tally_impl () }; + return nano::election_extended_status{ status_l, last_votes, last_blocks, tally_impl () }; } std::shared_ptr nano::election::winner () const @@ -540,18 +571,31 @@ void nano::election::broadcast_vote_locked (nano::unique_lock & loc return; } last_vote = std::chrono::steady_clock::now (); + if (node.config.enable_voting && node.wallets.reps ().voting > 0) { - node.stats.inc (nano::stat::type::election, nano::stat::detail::generate_vote); + node.stats.inc (nano::stat::type::election, nano::stat::detail::broadcast_vote); if (confirmed_locked () || have_quorum (tally_impl ())) { - node.stats.inc (nano::stat::type::election, nano::stat::detail::generate_vote_final); + node.stats.inc (nano::stat::type::election, nano::stat::detail::broadcast_vote_final); + node.logger.trace (nano::log::type::election, nano::log::detail::broadcast_vote, + nano::log::arg{ "id", id }, + nano::log::arg{ "qualified_root", qualified_root }, + nano::log::arg{ "winner", status.winner }, + nano::log::arg{ "type", "final" }); + node.final_generator.add (root, status.winner->hash ()); // Broadcasts vote to the network } else { - node.stats.inc (nano::stat::type::election, nano::stat::detail::generate_vote_normal); + node.stats.inc (nano::stat::type::election, nano::stat::detail::broadcast_vote_normal); + node.logger.trace (nano::log::type::election, nano::log::detail::broadcast_vote, + nano::log::arg{ "id", id }, + nano::log::arg{ "qualified_root", qualified_root }, + nano::log::arg{ "winner", status.winner }, + nano::log::arg{ "type", "normal" }); + node.generator.add (root, status.winner->hash ()); // Broadcasts vote to the network } } @@ -701,3 +745,44 @@ nano::election_behavior nano::election::behavior () const { return behavior_m; } + +// TODO: Remove the need for .to_string () calls +void nano::election::operator() (nano::object_stream & obs) const +{ + obs.write ("id", id); + obs.write ("qualified_root", qualified_root.to_string ()); + obs.write ("behaviour", behavior_m); + obs.write ("height", height); + obs.write ("status", current_status ()); +} + +void nano::election_extended_status::operator() (nano::object_stream & obs) const +{ + obs.write ("winner", status.winner->hash ().to_string ()); + obs.write ("tally_amount", status.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 ("block_count", status.block_count); + obs.write ("voter_count", status.voter_count); + obs.write ("type", status.type); + + obs.write_range ("votes", votes, [] (auto const & entry, nano::object_stream & obs) { + auto & [account, info] = entry; + obs.write ("account", account.to_account ()); + obs.write ("hash", info.hash.to_string ()); + obs.write ("final", nano::vote::is_final_timestamp (info.timestamp)); + obs.write ("timestamp", info.timestamp); + obs.write ("time", info.time.time_since_epoch ().count ()); + }); + + obs.write_range ("blocks", blocks, [] (auto const & entry) { + auto [hash, block] = entry; + return block; + }); + + obs.write_range ("tally", tally, [] (auto const & entry, nano::object_stream & obs) { + auto & [amount, block] = entry; + obs.write ("hash", block->hash ().to_string ()); + obs.write ("amount", amount); + }); +} \ No newline at end of file diff --git a/nano/node/election.hpp b/nano/node/election.hpp index b9561fc68a..48f695c2fe 100644 --- a/nano/node/election.hpp +++ b/nano/node/election.hpp @@ -1,5 +1,6 @@ #pragma once +#include #include #include #include @@ -70,7 +71,10 @@ struct election_extended_status final { nano::election_status status; std::unordered_map votes; + std::unordered_map> blocks; nano::tally_t tally; + + void operator() (nano::object_stream &) const; }; class election final : public std::enable_shared_from_this @@ -169,6 +173,7 @@ class election final : public std::enable_shared_from_this private: nano::tally_t tally_impl () const; bool confirmed_locked () const; + nano::election_extended_status current_status_locked () const; // lock_a does not own the mutex on return void confirm_once (nano::unique_lock & lock_a, nano::election_status_type = nano::election_status_type::active_confirmed_quorum); void broadcast_block (nano::confirmation_solicitor &); @@ -203,6 +208,9 @@ class election final : public std::enable_shared_from_this mutable nano::mutex mutex; +public: // Logging + void operator() (nano::object_stream &) const; + private: // Constants static std::size_t constexpr max_blocks{ 10 }; diff --git a/nano/node/messages.cpp b/nano/node/messages.cpp index b27e26c151..b4a19784fe 100644 --- a/nano/node/messages.cpp +++ b/nano/node/messages.cpp @@ -19,6 +19,8 @@ #include #include #include +#include +#include #include #include #include @@ -82,25 +84,6 @@ bool nano::message_header::deserialize (nano::stream & stream_a) return error; } -std::string nano::message_header::to_string () const -{ - // Cast to uint16_t to get integer value since uint8_t is treated as an unsigned char in string formatting. - uint16_t type_l = static_cast (type); - uint16_t version_max_l = static_cast (version_max); - uint16_t version_using_l = static_cast (version_using); - uint16_t version_min_l = static_cast (version_min); - auto type_text = nano::to_string (type); - - std::stringstream stream; - - stream << boost::format ("NetID: %1%(%2%), ") % nano::to_string_hex (static_cast (network)) % nano::to_string (network); - stream << boost::format ("VerMaxUsingMin: %1%/%2%/%3%, ") % version_max_l % version_using_l % version_min_l; - stream << boost::format ("MsgType: %1%(%2%), ") % type_l % type_text; - stream << boost::format ("Extensions: %1%") % nano::to_string_hex (static_cast (extensions.to_ulong ())); - - return stream.str (); -} - nano::block_type nano::message_header::block_type () const { return static_cast (((extensions & block_type_mask) >> 8).to_ullong ()); @@ -316,6 +299,17 @@ bool nano::message_header::is_valid_message_type () const } } +void nano::message_header::operator() (nano::object_stream & obs) const +{ + obs.write ("type", type); + obs.write ("network", to_string (network)); + obs.write ("network_raw", static_cast (network)); + obs.write ("version", static_cast (version_using)); + obs.write ("version_min", static_cast (version_min)); + obs.write ("version_max", static_cast (version_max)); + obs.write ("extensions", static_cast (extensions.to_ulong ())); +} + /* * message */ @@ -348,6 +342,11 @@ nano::message_type nano::message::type () const return header.type; } +void nano::message::operator() (nano::object_stream & obs) const +{ + obs.write ("header", header); +} + /* * keepalive */ @@ -413,19 +412,11 @@ bool nano::keepalive::operator== (nano::keepalive const & other_a) const return peers == other_a.peers; } -std::string nano::keepalive::to_string () const +void nano::keepalive::operator() (nano::object_stream & obs) const { - std::stringstream stream; + nano::message::operator() (obs); // Write common data - stream << header.to_string (); - - for (auto peer = peers.begin (); peer != peers.end (); ++peer) - { - stream << "\n" - << peer->address ().to_string () + ":" + std::to_string (peer->port ()); - } - - return stream.str (); + obs.write_range ("peers", peers); } /* @@ -474,9 +465,11 @@ bool nano::publish::operator== (nano::publish const & other_a) const return *block == *other_a.block; } -std::string nano::publish::to_string () const +void nano::publish::operator() (nano::object_stream & obs) const { - return header.to_string () + "\n" + block->to_json (); + nano::message::operator() (obs); // Write common data + + obs.write ("block", block); } /* @@ -579,19 +572,6 @@ bool nano::confirm_req::operator== (nano::confirm_req const & other_a) const return equal; } -std::string nano::confirm_req::roots_string () const -{ - std::string result; - for (auto & root_hash : roots_hashes) - { - result += root_hash.first.to_string (); - result += ":"; - result += root_hash.second.to_string (); - result += ", "; - } - return result; -} - uint8_t nano::confirm_req::hash_count (const nano::message_header & header) { if (header.confirm_is_v2 ()) @@ -610,16 +590,16 @@ std::size_t nano::confirm_req::size (nano::message_header const & header) return count * (sizeof (decltype (roots_hashes)::value_type::first) + sizeof (decltype (roots_hashes)::value_type::second)); } -std::string nano::confirm_req::to_string () const +void nano::confirm_req::operator() (nano::object_stream & obs) const { - std::string s = header.to_string (); + nano::message::operator() (obs); // Write common data - for (auto && roots_hash : roots_hashes) - { - s += "\n" + roots_hash.first.to_string () + ":" + roots_hash.second.to_string (); - } - - return s; + // Write roots as: [ { root: ##, hash: ## } ,...] + obs.write_range ("roots", roots_hashes, [] (auto const & root_hash, nano::object_stream & obs) { + auto [root, hash] = root_hash; + obs.write ("root", root); + obs.write ("hash", hash); + }); } /* @@ -691,9 +671,11 @@ std::size_t nano::confirm_ack::size (const nano::message_header & header) return nano::vote::size (count); } -std::string nano::confirm_ack::to_string () const +void nano::confirm_ack::operator() (nano::object_stream & obs) const { - return header.to_string () + "\n" + vote->to_json (); + nano::message::operator() (obs); // Write common data + + obs.write ("vote", vote); } /* @@ -750,13 +732,13 @@ bool nano::frontier_req::operator== (nano::frontier_req const & other_a) const return start == other_a.start && age == other_a.age && count == other_a.count; } -std::string nano::frontier_req::to_string () const +void nano::frontier_req::operator() (nano::object_stream & obs) const { - std::string s = header.to_string (); - s += "\nstart=" + start.to_string (); - s += " maxage=" + std::to_string (age); - s += " count=" + std::to_string (count); - return s; + nano::message::operator() (obs); // Write common data + + obs.write ("start", start); + obs.write ("age", age); + obs.write ("count", count); } /* @@ -859,13 +841,13 @@ void nano::bulk_pull::set_count_present (bool value_a) header.extensions.set (count_present_flag, value_a); } -std::string nano::bulk_pull::to_string () const +void nano::bulk_pull::operator() (nano::object_stream & obs) const { - std::string s = header.to_string (); - s += "\nstart=" + start.to_string (); - s += " end=" + end.to_string (); - s += " cnt=" + std::to_string (count); - return s; + nano::message::operator() (obs); // Write common data + + obs.write ("start", start); + obs.write ("end", end); + obs.write ("count", count); } /* @@ -917,27 +899,13 @@ bool nano::bulk_pull_account::deserialize (nano::stream & stream_a) return error; } -std::string nano::bulk_pull_account::to_string () const +void nano::bulk_pull_account::operator() (nano::object_stream & obs) const { - std::string s = header.to_string () + "\n"; - s += "acc=" + account.to_string (); - s += " min=" + minimum_amount.to_string (); - switch (flags) - { - case bulk_pull_account_flags::pending_hash_and_amount: - s += " pending_hash_and_amount"; - break; - case bulk_pull_account_flags::pending_address_only: - s += " pending_address_only"; - break; - case bulk_pull_account_flags::pending_hash_amount_and_address: - s += " pending_hash_amount_and_address"; - break; - default: - s += " unknown flags"; - break; - } - return s; + nano::message::operator() (obs); // Write common data + + obs.write ("account", account); + obs.write ("minimum_amount", minimum_amount); + obs.write ("flags", static_cast (flags)); // TODO: Prettier flag printing } /* @@ -970,6 +938,11 @@ void nano::bulk_push::visit (nano::message_visitor & visitor_a) const visitor_a.bulk_push (*this); } +void nano::bulk_push::operator() (nano::object_stream & obs) const +{ + nano::message::operator() (obs); // Write common data +} + /* * telemetry_req */ @@ -1000,9 +973,9 @@ void nano::telemetry_req::visit (nano::message_visitor & visitor_a) const visitor_a.telemetry_req (*this); } -std::string nano::telemetry_req::to_string () const +void nano::telemetry_req::operator() (nano::object_stream & obs) const { - return header.to_string (); + nano::message::operator() (obs); // Write common data } /* @@ -1080,18 +1053,14 @@ bool nano::telemetry_ack::is_empty_payload () const return size () == 0; } -std::string nano::telemetry_ack::to_string () const +void nano::telemetry_ack::operator() (nano::object_stream & obs) const { - std::string s = header.to_string () + "\n"; - if (is_empty_payload ()) - { - s += "empty telemetry payload"; - } - else + nano::message::operator() (obs); // Write common data + + if (!is_empty_payload ()) { - s += data.to_string (); + obs.write ("data", data); } - return s; } /* @@ -1247,15 +1216,6 @@ nano::error nano::telemetry_data::deserialize_json (nano::jsonconfig & json, boo return json.get_error (); } -std::string nano::telemetry_data::to_string () const -{ - nano::jsonconfig jc; - serialize_json (jc, true); - std::stringstream ss; - jc.write (ss); - return ss.str (); -} - bool nano::telemetry_data::operator== (nano::telemetry_data const & data_a) const { return (signature == data_a.signature && node_id == data_a.node_id && block_count == data_a.block_count && cemented_count == data_a.cemented_count && unchecked_count == data_a.unchecked_count && account_count == data_a.account_count && bandwidth_cap == data_a.bandwidth_cap && uptime == data_a.uptime && peer_count == data_a.peer_count && protocol_version == data_a.protocol_version && genesis_block == data_a.genesis_block && major_version == data_a.major_version && minor_version == data_a.minor_version && patch_version == data_a.patch_version && pre_release_version == data_a.pre_release_version && maker == data_a.maker && timestamp == data_a.timestamp && active_difficulty == data_a.active_difficulty && unknown_data == data_a.unknown_data); @@ -1289,6 +1249,11 @@ bool nano::telemetry_data::validate_signature () const return nano::validate_message (node_id, bytes.data (), bytes.size (), signature); } +void nano::telemetry_data::operator() (nano::object_stream & obs) const +{ + // TODO: Telemetry data +} + /* * node_id_handshake */ @@ -1406,19 +1371,12 @@ std::size_t nano::node_id_handshake::size (nano::message_header const & header) return result; } -std::string nano::node_id_handshake::to_string () const +void nano::node_id_handshake::operator() (nano::object_stream & obs) const { - std::string s = header.to_string (); - if (query) - { - s += "\ncookie=" + query->cookie.to_string (); - } - if (response) - { - s += "\nresp_node_id=" + response->node_id.to_string (); - s += "\nresp_sig=" + response->signature.to_string (); - } - return s; + nano::message::operator() (obs); // Write common data + + obs.write ("query", query); + obs.write ("response", response); } /* @@ -1435,6 +1393,11 @@ void nano::node_id_handshake::query_payload::deserialize (nano::stream & stream) nano::read (stream, cookie); } +void nano::node_id_handshake::query_payload::operator() (nano::object_stream & obs) const +{ + obs.write ("cookie", cookie); +} + /* * node_id_handshake::response_payload */ @@ -1518,6 +1481,19 @@ bool nano::node_id_handshake::response_payload::validate (const nano::uint256_un return true; // OK } +void nano::node_id_handshake::response_payload::operator() (nano::object_stream & obs) const +{ + obs.write ("node_id", node_id); + obs.write ("signature", signature); + + obs.write ("v2", v2.has_value ()); + if (v2) + { + obs.write ("salt", v2->salt); + obs.write ("genesis", v2->genesis); + } +} + /* * asc_pull_req */ @@ -1648,35 +1624,16 @@ bool nano::asc_pull_req::verify_consistency () const return true; // Just for convenience of calling from asserts } -std::string nano::asc_pull_req::to_string () const +void nano::asc_pull_req::operator() (nano::object_stream & obs) const { - std::string s = header.to_string () + "\n"; - - std::visit ([&s] (auto && arg) { - using T = std::decay_t; - - if constexpr (std::is_same_v) - { - s += "missing payload"; - } + nano::message::operator() (obs); // Write common data - else if constexpr (std::is_same_v) - { - s += "acc:" + arg.start.to_string (); - s += " max block count:" + to_string_hex (static_cast (arg.count)); - s += " hash type:" + to_string_hex (static_cast (arg.start_type)); - } - - else if constexpr (std::is_same_v) - { - s += "target:" + arg.target.to_string (); - s += " hash type:" + to_string_hex (static_cast (arg.target_type)); - } - }, - payload); + obs.write ("type", type); + obs.write ("id", id); - return s; + std::visit ([&obs] (auto && pld) { pld (obs); }, payload); // Log payload } + /* * asc_pull_req::blocks_payload */ @@ -1695,6 +1652,13 @@ void nano::asc_pull_req::blocks_payload::deserialize (nano::stream & stream) nano::read (stream, start_type); } +void nano::asc_pull_req::blocks_payload::operator() (nano::object_stream & obs) const +{ + obs.write ("start", start); + obs.write ("start_type", start_type); + obs.write ("count", count); +} + /* * asc_pull_req::account_info_payload */ @@ -1711,6 +1675,12 @@ void nano::asc_pull_req::account_info_payload::deserialize (stream & stream) nano::read (stream, target_type); } +void nano::asc_pull_req::account_info_payload::operator() (nano::object_stream & obs) const +{ + obs.write ("target", target); + obs.write ("target_type", target_type); +} + /* * asc_pull_req::frontiers_payload */ @@ -1727,6 +1697,12 @@ void nano::asc_pull_req::frontiers_payload::deserialize (nano::stream & stream) nano::read_big_endian (stream, count); } +void nano::asc_pull_req::frontiers_payload::operator() (nano::object_stream & obs) const +{ + obs.write ("start", start); + obs.write ("count", count); +} + /* * asc_pull_ack */ @@ -1858,43 +1834,14 @@ bool nano::asc_pull_ack::verify_consistency () const return true; // Just for convenience of calling from asserts } -std::string nano::asc_pull_ack::to_string () const +void nano::asc_pull_ack::operator() (nano::object_stream & obs) const { - std::string s = header.to_string () + "\n"; - - std::visit ([&s] (auto && arg) { - using T = std::decay_t; - - if constexpr (std::is_same_v) - { - s += "missing payload"; - } + nano::message::operator() (obs); // Write common data - else if constexpr (std::is_same_v) - { - auto block = std::begin (arg.blocks); - auto end_block = std::end (arg.blocks); - - while (block != end_block) - { - s += (*block)->to_json (); - ++block; - } - } - - else if constexpr (std::is_same_v) - { - s += "account public key:" + arg.account.to_account (); - s += " account open:" + arg.account_open.to_string (); - s += " account head:" + arg.account_head.to_string (); - s += " block count:" + to_string_hex (arg.account_block_count); - s += " confirmation frontier:" + arg.account_conf_frontier.to_string (); - s += " confirmation height:" + to_string_hex (arg.account_conf_height); - } - }, - payload); + obs.write ("type", type); + obs.write ("id", id); - return s; + std::visit ([&obs] (auto && pld) { pld (obs); }, payload); // Log payload } /* @@ -1924,6 +1871,11 @@ void nano::asc_pull_ack::blocks_payload::deserialize (nano::stream & stream) } } +void nano::asc_pull_ack::blocks_payload::operator() (nano::object_stream & obs) const +{ + obs.write_range ("blocks", blocks); +} + /* * asc_pull_ack::account_info_payload */ @@ -1948,6 +1900,16 @@ void nano::asc_pull_ack::account_info_payload::deserialize (nano::stream & strea nano::read_big_endian (stream, account_conf_height); } +void nano::asc_pull_ack::account_info_payload::operator() (nano::object_stream & obs) const +{ + obs.write ("account", account); + obs.write ("open", account_open); + obs.write ("head", account_head); + obs.write ("block_count", account_block_count); + obs.write ("conf_frontier", account_conf_frontier); + obs.write ("conf_height", account_conf_height); +} + /* * asc_pull_ack::frontiers_payload */ @@ -1989,6 +1951,15 @@ void nano::asc_pull_ack::frontiers_payload::deserialize (nano::stream & stream) } } +void nano::asc_pull_ack::frontiers_payload::operator() (nano::object_stream & obs) const +{ + obs.write_range ("frontiers", frontiers, [] (auto const & entry, nano::object_stream & obs) { + auto & [account, hash] = entry; + obs.write ("account", account); + obs.write ("hash", hash); + }); +} + /* * */ @@ -2004,3 +1975,10 @@ nano::stat::detail nano::to_stat_detail (nano::message_type type) debug_assert (value); return value.value_or (nano::stat::detail{}); } + +nano::log::detail nano::to_log_detail (nano::message_type type) +{ + auto value = magic_enum::enum_cast (magic_enum::enum_name (type)); + debug_assert (value); + return value.value_or (nano::log::detail{}); +} diff --git a/nano/node/messages.hpp b/nano/node/messages.hpp index d662054bdb..68d5d4247a 100644 --- a/nano/node/messages.hpp +++ b/nano/node/messages.hpp @@ -5,7 +5,10 @@ #include #include #include +#include +#include #include +#include #include #include #include @@ -46,6 +49,7 @@ enum class message_type : uint8_t std::string_view to_string (nano::message_type); stat::detail to_stat_detail (nano::message_type); +log::detail to_log_detail (nano::message_type); enum class bulk_pull_account_flags : uint8_t { @@ -67,8 +71,6 @@ class message_header final void serialize (nano::stream &) const; bool deserialize (nano::stream &); - std::string to_string () const; - public: // Payload nano::networks network; uint8_t version_max; @@ -112,6 +114,9 @@ class message_header final static extensions_bitset_t constexpr count_v2_mask_left{ 0xf000 }; static extensions_bitset_t constexpr count_v2_mask_right{ 0x00f0 }; static extensions_bitset_t constexpr telemetry_size_mask{ 0x3ff }; + +public: // Logging + void operator() (nano::object_stream &) const; }; class message @@ -130,6 +135,9 @@ class message public: nano::message_header header; + +public: // Logging + virtual void operator() (nano::object_stream &) const; }; class keepalive final : public message @@ -143,7 +151,9 @@ class keepalive final : public message bool operator== (nano::keepalive const &) const; std::array peers; static std::size_t constexpr size = 8 * (16 + 2); - std::string to_string () const; + +public: // Logging + void operator() (nano::object_stream &) const override; }; class publish final : public message @@ -157,7 +167,9 @@ class publish final : public message bool operator== (nano::publish const &) const; std::shared_ptr block; nano::uint128_t digest{ 0 }; - std::string to_string () const; + +public: // Logging + void operator() (nano::object_stream &) const override; }; class confirm_req final : public message @@ -172,7 +184,6 @@ class confirm_req final : public message void visit (nano::message_visitor &) const override; bool operator== (nano::confirm_req const &) const; std::string roots_string () const; - std::string to_string () const; static std::size_t size (nano::message_header const &); @@ -181,6 +192,9 @@ class confirm_req final : public message public: // Payload std::vector> roots_hashes; + +public: // Logging + void operator() (nano::object_stream &) const override; }; class confirm_ack final : public message @@ -192,7 +206,6 @@ class confirm_ack final : public message void serialize (nano::stream &) const override; void visit (nano::message_visitor &) const override; bool operator== (nano::confirm_ack const &) const; - std::string to_string () const; static std::size_t size (nano::message_header const &); @@ -201,6 +214,9 @@ class confirm_ack final : public message public: // Payload std::shared_ptr vote; + +public: // Logging + void operator() (nano::object_stream &) const override; }; class frontier_req final : public message @@ -216,7 +232,9 @@ class frontier_req final : public message uint32_t age; uint32_t count; static std::size_t constexpr size = sizeof (start) + sizeof (age) + sizeof (count); - std::string to_string () const; + +public: // Logging + void operator() (nano::object_stream &) const override; }; enum class telemetry_maker : uint8_t @@ -256,13 +274,16 @@ class telemetry_data bool validate_signature () const; bool operator== (nano::telemetry_data const &) const; bool operator!= (nano::telemetry_data const &) const; - std::string to_string () const; // Size does not include unknown_data static auto constexpr size = sizeof (signature) + sizeof (node_id) + sizeof (block_count) + sizeof (cemented_count) + sizeof (unchecked_count) + sizeof (account_count) + sizeof (bandwidth_cap) + sizeof (peer_count) + sizeof (protocol_version) + sizeof (uptime) + sizeof (genesis_block) + sizeof (major_version) + sizeof (minor_version) + sizeof (patch_version) + sizeof (pre_release_version) + sizeof (maker) + sizeof (uint64_t) + sizeof (active_difficulty); static auto constexpr latest_size = size; // This needs to be updated for each new telemetry version + private: void serialize_without_signature (nano::stream &) const; + +public: // Logging + void operator() (nano::object_stream &) const; }; class telemetry_req final : public message @@ -273,7 +294,9 @@ class telemetry_req final : public message void serialize (nano::stream &) const override; bool deserialize (nano::stream &); void visit (nano::message_visitor &) const override; - std::string to_string () const; + +public: // Logging + void operator() (nano::object_stream &) const override; }; class telemetry_ack final : public message @@ -287,9 +310,11 @@ class telemetry_ack final : public message bool deserialize (nano::stream &); uint16_t size () const; bool is_empty_payload () const; - std::string to_string () const; static uint16_t size (nano::message_header const &); nano::telemetry_data data; + +public: // Logging + void operator() (nano::object_stream &) const override; }; class bulk_pull final : public message @@ -309,7 +334,9 @@ class bulk_pull final : public message static std::size_t constexpr count_present_flag = nano::message_header::bulk_pull_count_present_flag; static std::size_t constexpr extended_parameters_size = 8; static std::size_t constexpr size = sizeof (start) + sizeof (end); - std::string to_string () const; + +public: // Logging + void operator() (nano::object_stream &) const override; }; class bulk_pull_account final : public message @@ -324,7 +351,9 @@ class bulk_pull_account final : public message nano::amount minimum_amount; bulk_pull_account_flags flags; static std::size_t constexpr size = sizeof (account) + sizeof (minimum_amount) + sizeof (bulk_pull_account_flags); - std::string to_string () const; + +public: // Logging + void operator() (nano::object_stream &) const override; }; class bulk_push final : public message @@ -335,6 +364,9 @@ class bulk_push final : public message void serialize (nano::stream &) const override; bool deserialize (nano::stream &); void visit (nano::message_visitor &) const override; + +public: // Logging + void operator() (nano::object_stream &) const override; }; class node_id_handshake final : public message @@ -350,6 +382,9 @@ class node_id_handshake final : public message public: nano::uint256_union cookie; + + public: // Logging + void operator() (nano::object_stream &) const; }; class response_payload @@ -380,6 +415,9 @@ class node_id_handshake final : public message static std::size_t constexpr size_v1 = sizeof (nano::account) + sizeof (nano::signature); static std::size_t constexpr size_v2 = sizeof (nano::account) + sizeof (nano::signature) + sizeof (v2_payload); static std::size_t size (nano::message_header const &); + + public: // Logging + void operator() (nano::object_stream &) const; }; public: @@ -392,7 +430,6 @@ class node_id_handshake final : public message void visit (nano::message_visitor &) const override; std::size_t size () const; static std::size_t size (nano::message_header const &); - std::string to_string () const; public: // Header static uint8_t constexpr query_flag = 0; @@ -407,6 +444,9 @@ class node_id_handshake final : public message public: // Payload std::optional query; std::optional response; + +public: // Logging + void operator() (nano::object_stream &) const override; }; /** @@ -432,6 +472,10 @@ struct empty_payload { debug_assert (false); } + void operator() (nano::object_stream &) const + { + debug_assert (false); + } }; /** @@ -459,7 +503,6 @@ class asc_pull_req final : public message void serialize_payload (nano::stream &) const; void deserialize_payload (nano::stream &); - std::string to_string () const; private: // Debug /** @@ -479,10 +522,13 @@ class asc_pull_req final : public message void serialize (nano::stream &) const; void deserialize (nano::stream &); - // Payload + public: // Payload nano::hash_or_account start{ 0 }; uint8_t count{ 0 }; hash_type start_type{}; + + public: // Logging + void operator() (nano::object_stream &) const; }; struct account_info_payload @@ -490,9 +536,12 @@ class asc_pull_req final : public message void serialize (nano::stream &) const; void deserialize (nano::stream &); - // Payload + public: // Payload nano::hash_or_account target{ 0 }; hash_type target_type{}; + + public: // Logging + void operator() (nano::object_stream &) const; }; struct frontiers_payload @@ -500,9 +549,12 @@ class asc_pull_req final : public message void serialize (nano::stream &) const; void deserialize (nano::stream &); - // Payload + public: // Payload nano::account start{ 0 }; uint16_t count{ 0 }; + + public: // Logging + void operator() (nano::object_stream &) const; }; public: // Payload @@ -515,6 +567,9 @@ class asc_pull_req final : public message public: /** Size of message without payload */ constexpr static std::size_t partial_size = sizeof (type) + sizeof (id); + +public: // Logging + void operator() (nano::object_stream &) const override; }; /** @@ -542,7 +597,6 @@ class asc_pull_ack final : public message void serialize_payload (nano::stream &) const; void deserialize_payload (nano::stream &); - std::string to_string () const; private: // Debug /** @@ -559,8 +613,11 @@ class asc_pull_ack final : public message void serialize (nano::stream &) const; void deserialize (nano::stream &); - // Payload + public: // Payload std::vector> blocks; + + public: // Logging + void operator() (nano::object_stream &) const; }; struct account_info_payload @@ -568,13 +625,16 @@ class asc_pull_ack final : public message void serialize (nano::stream &) const; void deserialize (nano::stream &); - // Payload + public: // Payload nano::account account{ 0 }; nano::block_hash account_open{ 0 }; nano::block_hash account_head{ 0 }; uint64_t account_block_count{ 0 }; nano::block_hash account_conf_frontier{ 0 }; uint64_t account_conf_height{ 0 }; + + public: // Logging + void operator() (nano::object_stream &) const; }; struct frontiers_payload @@ -590,8 +650,11 @@ class asc_pull_ack final : public message static void serialize_frontier (nano::stream &, frontier const &); static frontier deserialize_frontier (nano::stream &); - // Payload + public: // Payload std::vector frontiers; + + public: // Logging + void operator() (nano::object_stream &) const; }; public: // Payload @@ -604,6 +667,9 @@ class asc_pull_ack final : public message public: /** Size of message without payload */ constexpr static std::size_t partial_size = sizeof (type) + sizeof (id); + +public: // Logging + void operator() (nano::object_stream &) const override; }; class message_visitor diff --git a/nano/node/network.cpp b/nano/node/network.cpp index 9f33370cc1..cc41cd3c3d 100644 --- a/nano/node/network.cpp +++ b/nano/node/network.cpp @@ -468,7 +468,8 @@ class network_message_visitor : public nano::message_visitor void nano::network::process_message (nano::message const & message, std::shared_ptr const & channel) { - node.stats.inc (nano::stat::type::message, to_stat_detail (message.header.type), nano::stat::dir::in); + node.stats.inc (nano::stat::type::message, to_stat_detail (message.type ()), nano::stat::dir::in); + node.logger.trace (nano::log::type::network_processed, to_log_detail (message.type ()), nano::log::arg{ "message", message }); network_message_visitor visitor{ node, channel }; message.visit (visitor); diff --git a/nano/node/node.cpp b/nano/node/node.cpp index cb854c326f..24a2e31158 100644 --- a/nano/node/node.cpp +++ b/nano/node/node.cpp @@ -185,8 +185,8 @@ nano::node::node (boost::asio::io_context & io_ctx_a, std::filesystem::path cons vote_uniquer{}, confirmation_height_processor (ledger, write_database_queue, config.conf_height_processor_batch_min_time, logger, node_initialized_latch, flags.confirmation_height_processor_mode), vote_cache{ config.vote_cache, stats }, - generator{ config, ledger, wallets, vote_processor, history, network, stats, /* non-final */ false }, - final_generator{ config, ledger, wallets, vote_processor, history, network, stats, /* final */ true }, + generator{ config, ledger, wallets, vote_processor, history, network, stats, logger, /* non-final */ false }, + final_generator{ config, ledger, wallets, vote_processor, history, network, stats, logger, /* final */ true }, active (*this, confirmation_height_processor), scheduler_impl{ std::make_unique (*this) }, scheduler{ *scheduler_impl }, @@ -1298,6 +1298,8 @@ void nano::node::process_confirmed (nano::election_status const & status_a, uint decltype (iteration_a) const num_iters = (config.block_processor_batch_max_time / network_params.node.process_confirmed_interval) * 4; if (auto block_l = ledger.store.block.get (ledger.store.tx_begin_read (), hash)) { + logger.trace (nano::log::type::node, nano::log::detail::process_confirmed, nano::log::arg{ "block", block_l }); + confirmation_height_processor.add (block_l); } else if (iteration_a < num_iters) diff --git a/nano/node/scheduler/priority.cpp b/nano/node/scheduler/priority.cpp index c75c5b0976..8232a4b653 100644 --- a/nano/node/scheduler/priority.cpp +++ b/nano/node/scheduler/priority.cpp @@ -51,12 +51,21 @@ bool nano::scheduler::priority::activate (nano::account const & account_a, store debug_assert (block != nullptr); if (node.ledger.dependents_confirmed (transaction, *block)) { - stats.inc (nano::stat::type::election_scheduler, nano::stat::detail::activated); - auto balance = node.ledger.balance (transaction, hash); - auto previous_balance = node.ledger.balance (transaction, conf_info.frontier); + auto const balance = node.ledger.balance (transaction, hash); + auto const previous_balance = node.ledger.balance (transaction, conf_info.frontier); + auto const balance_priority = std::max (balance, previous_balance); + + node.stats.inc (nano::stat::type::election_scheduler, nano::stat::detail::activated); + node.logger.trace (nano::log::type::election_scheduler, nano::log::detail::block_activated, + nano::log::arg{ "account", account_a.to_account () }, // TODO: Convert to lazy eval + nano::log::arg{ "block", block }, + nano::log::arg{ "time", info->modified }, + nano::log::arg{ "priority", balance_priority }); + nano::lock_guard lock{ mutex }; - buckets->push (info->modified, block, std::max (balance, previous_balance)); + buckets->push (info->modified, block, balance_priority); notify (); + return true; // Activated } } diff --git a/nano/node/transport/channel.cpp b/nano/node/transport/channel.cpp index 99581f4712..9be0940f13 100644 --- a/nano/node/transport/channel.cpp +++ b/nano/node/transport/channel.cpp @@ -23,12 +23,20 @@ void nano::transport::channel::send (nano::message & message_a, std::function +#include #include #include #include @@ -140,6 +141,9 @@ class channel protected: nano::node & node; + +public: // Logging + virtual void operator() (nano::object_stream &) const; }; } diff --git a/nano/node/transport/socket.cpp b/nano/node/transport/socket.cpp index 609bb75220..4271905534 100644 --- a/nano/node/transport/socket.cpp +++ b/nano/node/transport/socket.cpp @@ -13,6 +13,8 @@ #include #include +#include + /* * socket */ @@ -351,6 +353,14 @@ nano::tcp_endpoint nano::transport::socket::local_endpoint () const return local; } +void nano::transport::socket::operator() (nano::object_stream & obs) const +{ + obs.write ("remote_endpoint", remote_endpoint ()); + obs.write ("local_endpoint", local_endpoint ()); + obs.write ("type", type_m); + obs.write ("endpoint_type", endpoint_type_m); +} + /* * write_queue */ @@ -458,18 +468,7 @@ std::size_t network_prefix) return counted_connections; } -std::string nano::transport::socket_type_to_string (nano::transport::socket::type_t type) +std::string_view nano::transport::to_string (nano::transport::socket::type_t type) { - switch (type) - { - case nano::transport::socket::type_t::undefined: - return "undefined"; - case nano::transport::socket::type_t::bootstrap: - return "bootstrap"; - case nano::transport::socket::type_t::realtime: - return "realtime"; - case nano::transport::socket::type_t::realtime_response_server: - return "realtime_response_server"; - } - return "n/a"; + return magic_enum::enum_name (type); } diff --git a/nano/node/transport/socket.hpp b/nano/node/transport/socket.hpp index 0ac01400fc..91f7d008fc 100644 --- a/nano/node/transport/socket.hpp +++ b/nano/node/transport/socket.hpp @@ -207,9 +207,12 @@ class socket final : public std::enable_shared_from_this>; diff --git a/nano/node/transport/tcp.cpp b/nano/node/transport/tcp.cpp index 25fd21a5ba..c9a6c19dd2 100644 --- a/nano/node/transport/tcp.cpp +++ b/nano/node/transport/tcp.cpp @@ -112,6 +112,13 @@ void nano::transport::channel_tcp::set_endpoint () } } +void nano::transport::channel_tcp::operator() (nano::object_stream & obs) const +{ + nano::transport::channel::operator() (obs); // Write common data + + obs.write ("socket", socket); +} + /* * tcp_channels */ diff --git a/nano/node/transport/tcp.hpp b/nano/node/transport/tcp.hpp index 80196a3089..7b6efd9420 100644 --- a/nano/node/transport/tcp.hpp +++ b/nano/node/transport/tcp.hpp @@ -93,7 +93,11 @@ namespace transport private: nano::tcp_endpoint endpoint{ boost::asio::ip::address_v6::any (), 0 }; + + public: // Logging + void operator() (nano::object_stream &) const override; }; + class tcp_channels final { friend class nano::transport::channel_tcp; diff --git a/nano/node/vote_processor.cpp b/nano/node/vote_processor.cpp index 0885da8332..524dbdc8ee 100644 --- a/nano/node/vote_processor.cpp +++ b/nano/node/vote_processor.cpp @@ -174,6 +174,10 @@ nano::vote_code nano::vote_processor::vote_blocking (std::shared_ptr break; } + logger.trace (nano::log::type::vote_processor, nano::log::detail::vote_processed, + nano::log::arg{ "vote", vote_a }, + nano::log::arg{ "result", result }); + return result; } diff --git a/nano/node/voting.cpp b/nano/node/voting.cpp index 401ebe8327..b238f38538 100644 --- a/nano/node/voting.cpp +++ b/nano/node/voting.cpp @@ -161,7 +161,7 @@ std::unique_ptr nano::collect_container_info (na return composite; } -nano::vote_generator::vote_generator (nano::node_config const & config_a, nano::ledger & ledger_a, nano::wallets & wallets_a, nano::vote_processor & vote_processor_a, nano::local_vote_history & history_a, nano::network & network_a, nano::stats & stats_a, bool is_final_a) : +nano::vote_generator::vote_generator (nano::node_config const & config_a, nano::ledger & ledger_a, nano::wallets & wallets_a, nano::vote_processor & vote_processor_a, nano::local_vote_history & history_a, nano::network & network_a, nano::stats & stats_a, nano::logger & logger_a, bool is_final_a) : config (config_a), ledger (ledger_a), wallets (wallets_a), @@ -170,6 +170,7 @@ nano::vote_generator::vote_generator (nano::node_config const & config_a, nano:: spacing{ config_a.network_params.voting.delay }, network (network_a), stats (stats_a), + logger (logger_a), is_final (is_final_a), vote_generation_queue{ stats, nano::stat::type::vote_generator, nano::thread_role::name::vote_generator_queue, /* single threaded */ 1, /* max queue size */ 1024 * 32, /* max batch size */ 1024 * 4 } { @@ -185,18 +186,23 @@ nano::vote_generator::~vote_generator () bool nano::vote_generator::should_vote (store::write_transaction const & transaction, nano::root const & root_a, nano::block_hash const & hash_a) { + auto block = ledger.store.block.get (transaction, hash_a); bool should_vote = false; if (is_final) { - auto block (ledger.store.block.get (transaction, hash_a)); should_vote = block != nullptr && ledger.dependents_confirmed (transaction, *block) && ledger.store.final_vote.put (transaction, block->qualified_root (), hash_a); debug_assert (block == nullptr || root_a == block->root ()); } else { - auto block (ledger.store.block.get (transaction, hash_a)); should_vote = block != nullptr && ledger.dependents_confirmed (transaction, *block); } + + logger.trace (nano::log::type::vote_generator, nano::log::detail::should_vote, + nano::log::arg{ "should_vote", should_vote }, + nano::log::arg{ "block", block }, + nano::log::arg{ "is_final", is_final }); + return should_vote; } diff --git a/nano/node/voting.hpp b/nano/node/voting.hpp index def5f78a56..6a2b2c79b6 100644 --- a/nano/node/voting.hpp +++ b/nano/node/voting.hpp @@ -1,6 +1,7 @@ #pragma once #include +#include #include #include #include @@ -121,7 +122,7 @@ class vote_generator final using queue_entry_t = std::pair; public: - vote_generator (nano::node_config const & config_a, nano::ledger & ledger_a, nano::wallets & wallets_a, nano::vote_processor & vote_processor_a, nano::local_vote_history & history_a, nano::network & network_a, nano::stats & stats_a, bool is_final_a); + vote_generator (nano::node_config const &, nano::ledger &, nano::wallets &, nano::vote_processor &, nano::local_vote_history &, nano::network &, nano::stats &, nano::logger &, bool is_final); ~vote_generator (); /** Queue items for vote generation, or broadcast votes already in cache */ @@ -159,6 +160,7 @@ class vote_generator final nano::vote_spacing spacing; nano::network & network; nano::stats & stats; + nano::logger & logger; private: processing_queue vote_generation_queue; diff --git a/nano/secure/common.hpp b/nano/secure/common.hpp index b14323edf5..503d4d1271 100644 --- a/nano/secure/common.hpp +++ b/nano/secure/common.hpp @@ -6,6 +6,7 @@ #include #include #include +#include #include #include #include diff --git a/nano/secure/vote.cpp b/nano/secure/vote.cpp index 9ffeabe04a..28002f25f0 100644 --- a/nano/secure/vote.cpp +++ b/nano/secure/vote.cpp @@ -180,4 +180,12 @@ uint64_t nano::vote::packed_timestamp (uint64_t timestamp, uint8_t duration) bool nano::vote::is_final_timestamp (uint64_t timestamp) { return timestamp == std::numeric_limits::max (); +} + +void nano::vote::operator() (nano::object_stream & obs) const +{ + obs.write ("account", account); + obs.write ("final", is_final_timestamp (timestamp_m)); + obs.write ("timestamp", timestamp_m); + obs.write_range ("hashes", hashes); } \ No newline at end of file diff --git a/nano/secure/vote.hpp b/nano/secure/vote.hpp index d7c9b62b32..9ae7b0689f 100644 --- a/nano/secure/vote.hpp +++ b/nano/secure/vote.hpp @@ -71,6 +71,9 @@ class vote final static std::string const hash_prefix; static uint64_t packed_timestamp (uint64_t timestamp, uint8_t duration); + +public: // Logging + void operator() (nano::object_stream &) const; }; using vote_uniquer = nano::uniquer; From 7452def2e78d104812012e6ed6e293dbb27427e2 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Piotr=20Wo=CC=81jcik?= <3044353+pwojcikdev@users.noreply.github.com> Date: Fri, 26 Jan 2024 18:55:48 +0100 Subject: [PATCH 06/12] Fix parsing logger ids --- nano/lib/logging.cpp | 18 ++++++++---------- nano/lib/utility.hpp | 14 +++++++++----- 2 files changed, 17 insertions(+), 15 deletions(-) diff --git a/nano/lib/logging.cpp b/nano/lib/logging.cpp index 7fbfb0b6e0..7f6a6bd35a 100644 --- a/nano/lib/logging.cpp +++ b/nano/lib/logging.cpp @@ -481,12 +481,12 @@ nano::log_config nano::load_log_config (nano::log_config fallback, const std::fi if (env_levels) { std::map levels; - for (auto const & env_level_str : nano::util::split (*env_levels, ',')) + for (auto const & env_level_str : nano::util::split (*env_levels, ",")) { try { // Split 'logger_name=level' into a pair of 'logger_name' and 'level' - auto arr = nano::util::split (env_level_str, '='); + auto arr = nano::util::split (env_level_str, "="); if (arr.size () != 2) { throw std::invalid_argument ("Invalid entry: " + env_level_str); @@ -579,16 +579,14 @@ std::string nano::log::to_string (nano::log::logger_id logger_id) */ nano::log::logger_id nano::log::parse_logger_id (const std::string & logger_name) { - auto pos = logger_name.find ("::"); - if (pos == std::string::npos) + auto parts = nano::util::split (logger_name, "::"); + if (parts.size () == 1) { - return { nano::log::parse_type (logger_name), nano::log::detail::all }; + return { nano::log::parse_type (parts[0]), nano::log::detail::all }; } - else + if (parts.size () == 2) { - auto logger_type = logger_name.substr (0, pos); - auto logger_detail = logger_name.substr (pos + 1); - - return { nano::log::parse_type (logger_type), nano::log::parse_detail (logger_detail) }; + return { nano::log::parse_type (parts[0]), nano::log::parse_detail (parts[1]) }; } + throw std::invalid_argument ("Invalid logger name: " + logger_name); } \ No newline at end of file diff --git a/nano/lib/utility.hpp b/nano/lib/utility.hpp index 97d8bd3ad5..7b2ce35cab 100644 --- a/nano/lib/utility.hpp +++ b/nano/lib/utility.hpp @@ -246,15 +246,19 @@ std::string join (Container const & container, std::string_view delimiter, Func return join (container.begin (), container.end (), delimiter, transform); } -inline std::vector split (const std::string & str, char delimiter) +inline std::vector split (std::string const & input, std::string_view delimiter) { - std::stringstream ss{ str }; std::vector result; - std::string item; - while (std::getline (ss, item, delimiter)) + std::size_t startPos = 0; + std::size_t delimiterPos = input.find (delimiter, startPos); + while (delimiterPos != std::string::npos) { - result.push_back (item); + std::string token = input.substr (startPos, delimiterPos - startPos); + result.push_back (token); + startPos = delimiterPos + delimiter.length (); + delimiterPos = input.find (delimiter, startPos); } + result.push_back (input.substr (startPos)); return result; } From fde4588dcb7e24038d9b68f7630668fcd34afbf7 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Piotr=20Wo=CC=81jcik?= <3044353+pwojcikdev@users.noreply.github.com> Date: Tue, 30 Jan 2024 18:08:08 +0100 Subject: [PATCH 07/12] Enable tracing in debug builds by default --- CMakeLists.txt | 6 ++++++ 1 file changed, 6 insertions(+) diff --git a/CMakeLists.txt b/CMakeLists.txt index 408ed1880a..ee95085841 100644 --- a/CMakeLists.txt +++ b/CMakeLists.txt @@ -134,6 +134,12 @@ if(NANO_STACKTRACE_BACKTRACE) endif() option(NANO_TRACING "Enable trace logging" OFF) +# Check if the build type is Debug, and if so, enable NANO_TRACING by default +if(CMAKE_BUILD_TYPE STREQUAL "Debug") + set(NANO_TRACING + ON + CACHE BOOL "Enable trace logging" FORCE) +endif() if(NANO_TRACING) message(STATUS "Using trace logging") add_compile_definitions(NANO_TRACING) From 3805e36b5a276ba622734dffd502e0abca7acd3f Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Piotr=20Wo=CC=81jcik?= <3044353+pwojcikdev@users.noreply.github.com> Date: Tue, 30 Jan 2024 19:29:05 +0100 Subject: [PATCH 08/12] Use spaces for indentation --- nano/core_test/object_stream.cpp | 124 +++++++++++++++---------------- nano/lib/object_stream.hpp | 2 +- 2 files changed, 63 insertions(+), 63 deletions(-) diff --git a/nano/core_test/object_stream.cpp b/nano/core_test/object_stream.cpp index 59c09db3bc..ead8bad719 100644 --- a/nano/core_test/object_stream.cpp +++ b/nano/core_test/object_stream.cpp @@ -212,10 +212,10 @@ TEST (object_stream, object_writer_basic) auto expected = trim (R"( object_field: { - field1: "value1", - field2: "value2", - field3: true, - field4: 1234 + field1: "value1", + field2: "value2", + field3: true, + field4: 1234 } )"); @@ -243,15 +243,15 @@ TEST (object_stream, object_writer_nested) auto expected = trim (R"( object_field: { - field1: "value1", - nested_object: { - nested_field1: "nested_value1", - nested_field2: false, - nested_field3: -1234 - }, - field2: "value2", - field3: true, - field4: 1234 + field1: "value1", + nested_object: { + nested_field1: "nested_value1", + nested_field2: false, + nested_field3: -1234 + }, + field2: "value2", + field3: true, + field4: 1234 } )"); @@ -269,9 +269,9 @@ TEST (object_stream, array_writer_basic) auto expected = trim (R"( array_field: [ - 0, - 1, - 2 + 0, + 1, + 2 ] )"); @@ -304,8 +304,8 @@ TEST (object_stream, object_basic) auto expected = trim (R"( test_object: { - uint256_union_field: "0000000000000000000000000000000000000000000000000000000000000000", - block_hash: "0000000000000000000000000000000000000000000000000000000000000000" + uint256_union_field: "0000000000000000000000000000000000000000000000000000000000000000", + block_hash: "0000000000000000000000000000000000000000000000000000000000000000" } )"); @@ -328,18 +328,18 @@ TEST (object_stream, array_writer_objects) auto expected = trim (R"( array_field: [ - { - uint256_union_field: "0000000000000000000000000000000000000000000000000000000000000000", - block_hash: "0000000000000000000000000000000000000000000000000000000000000000" - }, - { - uint256_union_field: "0000000000000000000000000000000000000000000000000000000000000000", - block_hash: "0000000000000000000000000000000000000000000000000000000000000001" - }, - { - uint256_union_field: "0000000000000000000000000000000000000000000000000000000000000000", - block_hash: "0000000000000000000000000000000000000000000000000000000000000002" - } + { + uint256_union_field: "0000000000000000000000000000000000000000000000000000000000000000", + block_hash: "0000000000000000000000000000000000000000000000000000000000000000" + }, + { + uint256_union_field: "0000000000000000000000000000000000000000000000000000000000000000", + block_hash: "0000000000000000000000000000000000000000000000000000000000000001" + }, + { + uint256_union_field: "0000000000000000000000000000000000000000000000000000000000000000", + block_hash: "0000000000000000000000000000000000000000000000000000000000000002" + } ] )"); @@ -370,9 +370,9 @@ TEST (object_stream, object_array_basic) auto expected = trim (R"( test_object_array: [ - 1, - 2, - 3 + 1, + 2, + 3 ] )"); @@ -410,17 +410,17 @@ TEST (object_stream, object_nested) auto expected = trim (R"( test_object: { - uint256_union_field: "0000000000000000000000000000000000000000000000000000000000000000", - block_hash: "0000000000000000000000000000000000000000000000000000000000000000", - nested_object: { - uint256_union_field: "0000000000000000000000000000000000000000000000000000000000000000", - block_hash: "0000000000000000000000000000000000000000000000000000000000000000" - }, - nested_array_object: [ - 1, - 2, - 3 - ] + uint256_union_field: "0000000000000000000000000000000000000000000000000000000000000000", + block_hash: "0000000000000000000000000000000000000000000000000000000000000000", + nested_object: { + uint256_union_field: "0000000000000000000000000000000000000000000000000000000000000000", + block_hash: "0000000000000000000000000000000000000000000000000000000000000000" + }, + nested_array_object: [ + 1, + 2, + 3 + ] } )"); @@ -455,18 +455,18 @@ TEST (object_stream, builtin_array) auto expected = trim (R"( array_field: [ - { - hash: "0000000000000000000000000000000000000000000000000000000000000001", - value: 1 - }, - { - hash: "0000000000000000000000000000000000000000000000000000000000000002", - value: 2 - }, - { - hash: "0000000000000000000000000000000000000000000000000000000000000003", - value: 3 - } + { + hash: "0000000000000000000000000000000000000000000000000000000000000001", + value: 1 + }, + { + hash: "0000000000000000000000000000000000000000000000000000000000000002", + value: 2 + }, + { + hash: "0000000000000000000000000000000000000000000000000000000000000003", + value: 3 + } ] )"); @@ -501,8 +501,8 @@ TEST (object_stream, ostream_adapter) auto expected = trim (R"( { - uint256_union_field: "0000000000000000000000000000000000000000000000000000000000000000", - block_hash: "0000000000000000000000000000000000000000000000000000000000000000" + uint256_union_field: "0000000000000000000000000000000000000000000000000000000000000000", + block_hash: "0000000000000000000000000000000000000000000000000000000000000000" } )"); @@ -518,8 +518,8 @@ TEST (object_stream, fmt_adapter) auto expected = trim (R"( { - uint256_union_field: "0000000000000000000000000000000000000000000000000000000000000000", - block_hash: "0000000000000000000000000000000000000000000000000000000000000000" + uint256_union_field: "0000000000000000000000000000000000000000000000000000000000000000", + block_hash: "0000000000000000000000000000000000000000000000000000000000000000" } )"); @@ -536,8 +536,8 @@ TEST (object_stream, to_string) auto expected = trim (R"( { - uint256_union_field: "0000000000000000000000000000000000000000000000000000000000000000", - block_hash: "0000000000000000000000000000000000000000000000000000000000000000" + uint256_union_field: "0000000000000000000000000000000000000000000000000000000000000000", + block_hash: "0000000000000000000000000000000000000000000000000000000000000000" } )"); diff --git a/nano/lib/object_stream.hpp b/nano/lib/object_stream.hpp index 02b20bf44b..40c638df91 100644 --- a/nano/lib/object_stream.hpp +++ b/nano/lib/object_stream.hpp @@ -37,7 +37,7 @@ struct object_stream_config std::string false_value{ "false" }; std::string null_value{ "null" }; - std::string indent{ "\t" }; + std::string indent{ " " }; std::string newline{ "\n" }; /** Number of decimal places to show for `float` and `double` */ From 4b1408fafd416df11f3139f7a833cbaf2eea40db Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Piotr=20Wo=CC=81jcik?= <3044353+pwojcikdev@users.noreply.github.com> Date: Mon, 5 Feb 2024 20:54:53 +0100 Subject: [PATCH 09/12] Use `nano::log::microseconds` helper --- nano/lib/logging.hpp | 9 +++++++-- 1 file changed, 7 insertions(+), 2 deletions(-) diff --git a/nano/lib/logging.hpp b/nano/lib/logging.hpp index 8a77dae27d..1415281ba9 100644 --- a/nano/lib/logging.hpp +++ b/nano/lib/logging.hpp @@ -32,6 +32,12 @@ using logger_id = std::pair; std::string to_string (logger_id); logger_id parse_logger_id (std::string const &); + +template +auto microseconds (std::chrono::time_point time) +{ + return std::chrono::duration_cast (time.time_since_epoch ()).count (); +} } namespace nano @@ -163,14 +169,13 @@ class logger final // Include info about precise time of the event auto now = std::chrono::high_resolution_clock::now (); - auto now_micros = std::chrono::duration_cast (now.time_since_epoch ()).count (); // TODO: Improve code indentation config auto logger = get_logger (type, detail); logger.trace ("{}", nano::streamed_args (global_tracing_config, nano::log::arg{ "event", to_string (std::make_pair (type, detail)) }, - nano::log::arg{ "time", now_micros }, + nano::log::arg{ "time", nano::log::microseconds (now) }, std::forward (args)...)); } } From ed60faf7217fca059852b840f4cf585e14ceea79 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Piotr=20Wo=CC=81jcik?= <3044353+pwojcikdev@users.noreply.github.com> Date: Mon, 5 Feb 2024 21:31:49 +0100 Subject: [PATCH 10/12] Better handling of debug build check --- CMakeLists.txt | 9 ++++----- 1 file changed, 4 insertions(+), 5 deletions(-) diff --git a/CMakeLists.txt b/CMakeLists.txt index ee95085841..0123485cdf 100644 --- a/CMakeLists.txt +++ b/CMakeLists.txt @@ -133,12 +133,11 @@ if(NANO_STACKTRACE_BACKTRACE) endif() endif() -option(NANO_TRACING "Enable trace logging" OFF) -# Check if the build type is Debug, and if so, enable NANO_TRACING by default +# Enable NANO_TRACING by default in Debug builds if(CMAKE_BUILD_TYPE STREQUAL "Debug") - set(NANO_TRACING - ON - CACHE BOOL "Enable trace logging" FORCE) + option(NANO_TRACING "Enable trace logging" ON) +else() + option(NANO_TRACING "Enable trace logging" OFF) endif() if(NANO_TRACING) message(STATUS "Using trace logging") From 330856a37883f5e5d4d8dcbf9657df2d2ad92e62 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Piotr=20Wo=CC=81jcik?= <3044353+pwojcikdev@users.noreply.github.com> Date: Tue, 6 Feb 2024 20:52:09 +0100 Subject: [PATCH 11/12] Lazy trace event formatter --- nano/lib/logging.hpp | 16 ++++++++++++++-- 1 file changed, 14 insertions(+), 2 deletions(-) diff --git a/nano/lib/logging.hpp b/nano/lib/logging.hpp index 1415281ba9..14e6e2fc3a 100644 --- a/nano/lib/logging.hpp +++ b/nano/lib/logging.hpp @@ -171,15 +171,27 @@ class logger final auto now = std::chrono::high_resolution_clock::now (); // TODO: Improve code indentation config - auto logger = get_logger (type, detail); + auto & logger = get_logger (type, detail); logger.trace ("{}", nano::streamed_args (global_tracing_config, - nano::log::arg{ "event", to_string (std::make_pair (type, detail)) }, + nano::log::arg{ "event", event_formatter{ type, detail } }, nano::log::arg{ "time", nano::log::microseconds (now) }, std::forward (args)...)); } } +private: + struct event_formatter final + { + nano::log::type type; + nano::log::detail detail; + + friend std::ostream & operator<< (std::ostream & os, event_formatter const & self) + { + return os << to_string (self.type) << "::" << to_string (self.detail); + } + }; + private: const std::string identifier; From 3ebb6f737b285dfdc21006c388e4c8b0376138db Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Piotr=20Wo=CC=81jcik?= <3044353+pwojcikdev@users.noreply.github.com> Date: Tue, 6 Feb 2024 22:54:26 +0100 Subject: [PATCH 12/12] Rework flow of `channel::send` --- nano/node/transport/channel.cpp | 30 +++++++++++++----------------- 1 file changed, 13 insertions(+), 17 deletions(-) diff --git a/nano/node/transport/channel.cpp b/nano/node/transport/channel.cpp index 9be0940f13..26680ddc72 100644 --- a/nano/node/transport/channel.cpp +++ b/nano/node/transport/channel.cpp @@ -16,28 +16,24 @@ nano::transport::channel::channel (nano::node & node_a) : void nano::transport::channel::send (nano::message & message_a, std::function const & callback_a, nano::transport::buffer_drop_policy drop_policy_a, nano::transport::traffic_type traffic_type) { - auto buffer (message_a.to_shared_const_buffer ()); - auto detail = to_stat_detail (message_a.header.type); - auto is_droppable_by_limiter = (drop_policy_a == nano::transport::buffer_drop_policy::limiter); - auto should_pass (node.outbound_limiter.should_pass (buffer.size (), to_bandwidth_limit_type (traffic_type))); - if (!is_droppable_by_limiter || should_pass) - { - node.stats.inc (nano::stat::type::message, detail, nano::stat::dir::out); - node.logger.trace (nano::log::type::channel_sent, nano::to_log_detail (message_a.type ()), - nano::log::arg{ "message", message_a }, - nano::log::arg{ "channel", *this }, - nano::log::arg{ "dropped", false }); + auto buffer = message_a.to_shared_const_buffer (); + + bool is_droppable_by_limiter = (drop_policy_a == nano::transport::buffer_drop_policy::limiter); + bool should_pass = node.outbound_limiter.should_pass (buffer.size (), to_bandwidth_limit_type (traffic_type)); + bool pass = !is_droppable_by_limiter || should_pass; + + node.stats.inc (pass ? nano::stat::type::message : nano::stat::type::drop, to_stat_detail (message_a.type ()), nano::stat::dir::out); + node.logger.trace (nano::log::type::channel_sent, to_log_detail (message_a.type ()), + nano::log::arg{ "message", message_a }, + nano::log::arg{ "channel", *this }, + nano::log::arg{ "dropped", !pass }); + if (pass) + { send_buffer (buffer, callback_a, drop_policy_a, traffic_type); } else { - node.stats.inc (nano::stat::type::drop, detail, nano::stat::dir::out); - node.logger.trace (nano::log::type::channel_sent, nano::to_log_detail (message_a.type ()), - nano::log::arg{ "message", message_a }, - nano::log::arg{ "channel", *this }, - nano::log::arg{ "dropped", true }); - if (callback_a) { node.background ([callback_a] () {