From 2cfe2ea23229867d1d17d98ebd976ce360a4174f Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Piotr=20Wo=CC=81jcik?= <3044353+pwojcikdev@users.noreply.github.com> Date: Tue, 9 Jan 2024 21:53:24 +0100 Subject: [PATCH] Replace legacy logging calls --- nano/core_test/block_store.cpp | 96 ++++----- nano/core_test/bootstrap.cpp | 6 +- nano/core_test/bootstrap_ascending.cpp | 21 +- nano/core_test/confirmation_height.cpp | 31 ++- nano/core_test/core_test_main.cc | 3 +- nano/core_test/ledger.cpp | 25 +-- nano/core_test/message.cpp | 16 -- nano/core_test/node.cpp | 21 +- nano/core_test/processor_service.cpp | 5 +- nano/core_test/work_pool.cpp | 4 +- nano/lib/blocks.cpp | 6 + nano/lib/blocks.hpp | 3 + nano/lib/config.cpp | 20 ++ nano/lib/config.hpp | 2 + nano/lib/numbers.cpp | 21 ++ nano/lib/numbers.hpp | 7 + nano/lib/stats_enums.hpp | 8 +- nano/lib/tlsconfig.cpp | 8 +- nano/lib/tlsconfig.hpp | 4 +- nano/lib/utility.hpp | 41 ++++ nano/load_test/entry.cpp | 2 + nano/nano_node/daemon.cpp | 57 +++--- nano/nano_node/daemon.hpp | 8 +- nano/nano_node/entry.cpp | 21 +- nano/nano_rpc/entry.cpp | 17 +- nano/nano_wallet/entry.cpp | 16 +- nano/node/active_transactions.cpp | 20 +- nano/node/blockprocessor.cpp | 85 ++------ nano/node/blockprocessor.hpp | 1 + nano/node/bootstrap/bootstrap_attempt.cpp | 7 +- nano/node/bootstrap/bootstrap_bulk_pull.cpp | 150 ++++---------- nano/node/bootstrap/bootstrap_bulk_push.cpp | 42 +--- nano/node/bootstrap/bootstrap_connections.cpp | 53 ++--- nano/node/bootstrap/bootstrap_frontier.cpp | 50 ++--- nano/node/bootstrap/bootstrap_lazy.cpp | 6 +- nano/node/bootstrap/bootstrap_legacy.cpp | 36 ++-- nano/node/cli.cpp | 4 +- nano/node/confirmation_height_bounded.cpp | 29 +-- nano/node/confirmation_height_bounded.hpp | 7 +- nano/node/confirmation_height_processor.cpp | 6 +- nano/node/confirmation_height_processor.hpp | 5 +- nano/node/confirmation_height_unbounded.cpp | 18 +- nano/node/confirmation_height_unbounded.hpp | 7 +- nano/node/distributed_work.cpp | 84 +++++--- nano/node/election.cpp | 27 --- nano/node/election.hpp | 5 +- nano/node/epoch_upgrader.cpp | 26 ++- nano/node/epoch_upgrader.hpp | 6 +- nano/node/gap_cache.cpp | 2 +- nano/node/ipc/ipc_broker.cpp | 12 +- nano/node/ipc/ipc_server.cpp | 70 +++---- nano/node/json_handler.cpp | 5 +- nano/node/make_store.cpp | 2 +- nano/node/make_store.hpp | 4 +- nano/node/messages.cpp | 168 ++++++++-------- nano/node/messages.hpp | 4 +- nano/node/network.cpp | 93 ++------- nano/node/network.hpp | 4 +- nano/node/node.cpp | 189 ++++++++---------- nano/node/node.hpp | 10 +- nano/node/openclwork.cpp | 57 +++--- nano/node/openclwork.hpp | 8 +- nano/node/portmapping.cpp | 84 +++++--- nano/node/repcrawler.cpp | 19 +- nano/node/transport/channel.cpp | 13 +- nano/node/transport/message_deserializer.cpp | 77 +------ nano/node/transport/message_deserializer.hpp | 8 +- nano/node/transport/socket.cpp | 66 +++--- nano/node/transport/socket.hpp | 2 + nano/node/transport/tcp.cpp | 61 +++--- nano/node/transport/tcp_server.cpp | 89 ++++----- nano/node/vote_processor.cpp | 17 +- nano/node/vote_processor.hpp | 6 +- nano/node/wallet.cpp | 35 ++-- nano/node/websocket.cpp | 87 ++++---- nano/node/websocket.hpp | 32 +-- nano/node/websocket_stream.cpp | 10 + nano/node/websocket_stream.hpp | 2 + nano/qt/qt.cpp | 4 +- nano/qt_test/entry.cpp | 3 + nano/qt_test/qt.cpp | 6 +- nano/rpc/rpc.cpp | 13 +- nano/rpc/rpc.hpp | 4 +- nano/rpc/rpc_connection.cpp | 19 +- nano/rpc/rpc_connection.hpp | 5 +- nano/rpc/rpc_handler.cpp | 15 +- nano/rpc/rpc_handler.hpp | 6 +- nano/rpc/rpc_secure.cpp | 4 +- nano/rpc_test/entry.cpp | 3 + nano/secure/common.cpp | 1 + nano/secure/ledger.cpp | 5 +- nano/secure/ledger.hpp | 3 - nano/secure/vote.cpp | 21 +- nano/secure/vote.hpp | 11 - nano/slow_test/entry.cpp | 3 + nano/slow_test/node.cpp | 10 +- nano/store/lmdb/lmdb.cpp | 50 +++-- nano/store/lmdb/lmdb.hpp | 8 +- nano/store/lmdb/transaction.cpp | 13 +- nano/store/lmdb/transaction_impl.hpp | 9 +- nano/store/rocksdb/rocksdb.cpp | 25 ++- nano/store/rocksdb/rocksdb.hpp | 10 +- nano/test_common/ledger.cpp | 2 +- nano/test_common/ledger.hpp | 2 +- nano/test_common/system.hpp | 1 + 105 files changed, 1248 insertions(+), 1387 deletions(-) diff --git a/nano/core_test/block_store.cpp b/nano/core_test/block_store.cpp index fd9a99e7d2..eef550e611 100644 --- a/nano/core_test/block_store.cpp +++ b/nano/core_test/block_store.cpp @@ -27,7 +27,7 @@ using namespace std::chrono_literals; TEST (block_store, construction) { - nano::logger_mt logger; + nano::nlogger logger; auto store = nano::make_store (logger, nano::unique_path (), nano::dev::constants); ASSERT_TRUE (!store->init_error ()); } @@ -102,7 +102,7 @@ TEST (block_store, sideband_serialization) TEST (block_store, add_item) { - nano::logger_mt logger; + nano::nlogger logger; auto store = nano::make_store (logger, nano::unique_path (), nano::dev::constants); ASSERT_TRUE (!store->init_error ()); nano::block_builder builder; @@ -133,7 +133,7 @@ TEST (block_store, add_item) TEST (block_store, clear_successor) { - nano::logger_mt logger; + nano::nlogger logger; auto store = nano::make_store (logger, nano::unique_path (), nano::dev::constants); ASSERT_TRUE (!store->init_error ()); nano::block_builder builder; @@ -180,7 +180,7 @@ TEST (block_store, clear_successor) TEST (block_store, add_nonempty_block) { - nano::logger_mt logger; + nano::nlogger logger; auto store = nano::make_store (logger, nano::unique_path (), nano::dev::constants); ASSERT_TRUE (!store->init_error ()); nano::keypair key1; @@ -207,7 +207,7 @@ TEST (block_store, add_nonempty_block) TEST (block_store, add_two_items) { - nano::logger_mt logger; + nano::nlogger logger; auto store = nano::make_store (logger, nano::unique_path (), nano::dev::constants); ASSERT_TRUE (!store->init_error ()); nano::keypair key1; @@ -253,7 +253,7 @@ TEST (block_store, add_two_items) TEST (block_store, add_receive) { - nano::logger_mt logger; + nano::nlogger logger; auto store = nano::make_store (logger, nano::unique_path (), nano::dev::constants); ASSERT_TRUE (!store->init_error ()); nano::keypair key1; @@ -289,7 +289,7 @@ TEST (block_store, add_receive) TEST (block_store, add_pending) { - nano::logger_mt logger; + nano::nlogger logger; auto store = nano::make_store (logger, nano::unique_path (), nano::dev::constants); ASSERT_TRUE (!store->init_error ()); nano::keypair key1; @@ -307,7 +307,7 @@ TEST (block_store, add_pending) TEST (block_store, pending_iterator) { - nano::logger_mt logger; + nano::nlogger logger; auto store = nano::make_store (logger, nano::unique_path (), nano::dev::constants); ASSERT_TRUE (!store->init_error ()); auto transaction (store->tx_begin_write ()); @@ -332,7 +332,7 @@ TEST (block_store, pending_iterator) */ TEST (block_store, pending_iterator_comparison) { - nano::logger_mt logger; + nano::nlogger logger; auto store = nano::make_store (logger, nano::unique_path (), nano::dev::constants); ASSERT_TRUE (!store->init_error ()); nano::stats stats; @@ -375,7 +375,7 @@ TEST (block_store, pending_iterator_comparison) TEST (block_store, genesis) { - nano::logger_mt logger; + nano::nlogger logger; auto store = nano::make_store (logger, nano::unique_path (), nano::dev::constants); ASSERT_TRUE (!store->init_error ()); nano::ledger_cache ledger_cache; @@ -403,7 +403,7 @@ TEST (block_store, genesis) TEST (block_store, empty_accounts) { - nano::logger_mt logger; + nano::nlogger logger; auto store = nano::make_store (logger, nano::unique_path (), nano::dev::constants); ASSERT_TRUE (!store->init_error ()); auto transaction (store->tx_begin_read ()); @@ -414,7 +414,7 @@ TEST (block_store, empty_accounts) TEST (block_store, one_block) { - nano::logger_mt logger; + nano::nlogger logger; auto store = nano::make_store (logger, nano::unique_path (), nano::dev::constants); ASSERT_TRUE (!store->init_error ()); nano::block_builder builder; @@ -435,7 +435,7 @@ TEST (block_store, one_block) TEST (block_store, empty_bootstrap) { nano::test::system system{}; - nano::logger_mt logger; + nano::nlogger logger; nano::unchecked_map unchecked{ system.stats, false }; size_t count = 0; unchecked.for_each ([&count] (nano::unchecked_key const & key, nano::unchecked_info const & info) { @@ -446,7 +446,7 @@ TEST (block_store, empty_bootstrap) TEST (block_store, unchecked_begin_search) { - nano::logger_mt logger; + nano::nlogger logger; auto store = nano::make_store (logger, nano::unique_path (), nano::dev::constants); ASSERT_TRUE (!store->init_error ()); nano::keypair key0; @@ -471,7 +471,7 @@ TEST (block_store, unchecked_begin_search) TEST (block_store, frontier_retrieval) { - nano::logger_mt logger; + nano::nlogger logger; auto store = nano::make_store (logger, nano::unique_path (), nano::dev::constants); ASSERT_TRUE (!store->init_error ()); nano::account account1{}; @@ -486,7 +486,7 @@ TEST (block_store, frontier_retrieval) TEST (block_store, one_account) { - nano::logger_mt logger; + nano::nlogger logger; auto store = nano::make_store (logger, nano::unique_path (), nano::dev::constants); ASSERT_TRUE (!store->init_error ()); nano::account account{}; @@ -513,7 +513,7 @@ TEST (block_store, one_account) TEST (block_store, two_block) { - nano::logger_mt logger; + nano::nlogger logger; auto store = nano::make_store (logger, nano::unique_path (), nano::dev::constants); ASSERT_TRUE (!store->init_error ()); nano::block_builder builder; @@ -551,7 +551,7 @@ TEST (block_store, two_block) TEST (block_store, two_account) { - nano::logger_mt logger; + nano::nlogger logger; auto store = nano::make_store (logger, nano::unique_path (), nano::dev::constants); ASSERT_TRUE (!store->init_error ()); nano::account account1 (1); @@ -593,7 +593,7 @@ TEST (block_store, two_account) TEST (block_store, latest_find) { - nano::logger_mt logger; + nano::nlogger logger; auto store = nano::make_store (logger, nano::unique_path (), nano::dev::constants); ASSERT_TRUE (!store->init_error ()); nano::account account1 (1); @@ -627,7 +627,7 @@ TEST (mdb_block_store, supported_version_upgrades) } // Check that upgrading from an unsupported version is not supported auto path (nano::unique_path () / "data.ldb"); - nano::logger_mt logger; + nano::nlogger logger; { nano::store::lmdb::component store (logger, path, nano::dev::constants); nano::stats stats; @@ -671,7 +671,7 @@ TEST (mdb_block_store, bad_path) // Don't test this in rocksdb mode GTEST_SKIP (); } - nano::logger_mt logger; + nano::nlogger logger; try { auto path = nano::unique_path (); @@ -696,14 +696,14 @@ TEST (block_store, DISABLED_already_open) // File can be shared std::ofstream file; file.open (path.string ().c_str ()); ASSERT_TRUE (file.is_open ()); - nano::logger_mt logger; + nano::nlogger logger; auto store = nano::make_store (logger, path, nano::dev::constants); ASSERT_TRUE (store->init_error ()); } TEST (block_store, roots) { - nano::logger_mt logger; + nano::nlogger logger; auto store = nano::make_store (logger, nano::unique_path (), nano::dev::constants); ASSERT_TRUE (!store->init_error ()); nano::block_builder builder; @@ -745,7 +745,7 @@ TEST (block_store, roots) TEST (block_store, pending_exists) { - nano::logger_mt logger; + nano::nlogger logger; auto store = nano::make_store (logger, nano::unique_path (), nano::dev::constants); ASSERT_TRUE (!store->init_error ()); nano::pending_key two (2, 0); @@ -758,7 +758,7 @@ TEST (block_store, pending_exists) TEST (block_store, latest_exists) { - nano::logger_mt logger; + nano::nlogger logger; auto store = nano::make_store (logger, nano::unique_path (), nano::dev::constants); ASSERT_TRUE (!store->init_error ()); nano::account two (2); @@ -772,7 +772,7 @@ TEST (block_store, latest_exists) TEST (block_store, large_iteration) { - nano::logger_mt logger; + nano::nlogger logger; auto store = nano::make_store (logger, nano::unique_path (), nano::dev::constants); ASSERT_TRUE (!store->init_error ()); std::unordered_set accounts1; @@ -811,7 +811,7 @@ TEST (block_store, large_iteration) TEST (block_store, frontier) { - nano::logger_mt logger; + nano::nlogger logger; auto store = nano::make_store (logger, nano::unique_path (), nano::dev::constants); ASSERT_TRUE (!store->init_error ()); auto transaction (store->tx_begin_write ()); @@ -826,7 +826,7 @@ TEST (block_store, frontier) TEST (block_store, block_replace) { - nano::logger_mt logger; + nano::nlogger logger; auto store = nano::make_store (logger, nano::unique_path (), nano::dev::constants); ASSERT_TRUE (!store->init_error ()); nano::block_builder builder; @@ -858,7 +858,7 @@ TEST (block_store, block_replace) TEST (block_store, block_count) { - nano::logger_mt logger; + nano::nlogger logger; auto store = nano::make_store (logger, nano::unique_path (), nano::dev::constants); ASSERT_TRUE (!store->init_error ()); { @@ -883,7 +883,7 @@ TEST (block_store, block_count) TEST (block_store, account_count) { - nano::logger_mt logger; + nano::nlogger logger; auto store = nano::make_store (logger, nano::unique_path (), nano::dev::constants); ASSERT_TRUE (!store->init_error ()); { @@ -899,7 +899,7 @@ TEST (block_store, account_count) TEST (block_store, cemented_count_cache) { - nano::logger_mt logger; + nano::nlogger logger; auto store = nano::make_store (logger, nano::unique_path (), nano::dev::constants); ASSERT_TRUE (!store->init_error ()); auto transaction (store->tx_begin_write ()); @@ -910,7 +910,7 @@ TEST (block_store, cemented_count_cache) TEST (block_store, block_random) { - nano::logger_mt logger; + nano::nlogger logger; auto store = nano::make_store (logger, nano::unique_path (), nano::dev::constants); { nano::ledger_cache ledger_cache; @@ -925,7 +925,7 @@ TEST (block_store, block_random) TEST (block_store, pruned_random) { - nano::logger_mt logger; + nano::nlogger logger; auto store = nano::make_store (logger, nano::unique_path (), nano::dev::constants); ASSERT_TRUE (!store->init_error ()); nano::block_builder builder; @@ -952,7 +952,7 @@ TEST (block_store, pruned_random) TEST (block_store, state_block) { - nano::logger_mt logger; + nano::nlogger logger; auto store = nano::make_store (logger, nano::unique_path (), nano::dev::constants); ASSERT_FALSE (store->init_error ()); nano::keypair key1; @@ -999,7 +999,7 @@ TEST (mdb_block_store, sideband_height) // Don't test this in rocksdb mode GTEST_SKIP (); } - nano::logger_mt logger; + nano::nlogger logger; nano::keypair key1; nano::keypair key2; nano::keypair key3; @@ -1152,7 +1152,7 @@ TEST (mdb_block_store, sideband_height) TEST (block_store, peers) { - nano::logger_mt logger; + nano::nlogger logger; auto store = nano::make_store (logger, nano::unique_path (), nano::dev::constants); ASSERT_TRUE (!store->init_error ()); @@ -1250,7 +1250,7 @@ TEST (block_store, endpoint_key_byte_order) TEST (block_store, online_weight) { - nano::logger_mt logger; + nano::nlogger logger; auto store = nano::make_store (logger, nano::unique_path (), nano::dev::constants); ASSERT_FALSE (store->init_error ()); { @@ -1285,7 +1285,7 @@ TEST (block_store, online_weight) TEST (block_store, pruned_blocks) { - nano::logger_mt logger; + nano::nlogger logger; auto store = nano::make_store (logger, nano::unique_path (), nano::dev::constants); ASSERT_TRUE (!store->init_error ()); @@ -1372,7 +1372,7 @@ TEST (mdb_block_store, upgrade_v21_v22) } auto path (nano::unique_path () / "data.ldb"); - nano::logger_mt logger; + nano::nlogger logger; nano::stats stats; auto const check_correct_state = [&] () { nano::store::lmdb::component store (logger, path, nano::dev::constants); @@ -1411,7 +1411,7 @@ TEST (rocksdb_block_store, upgrade_v21_v22) } auto const path = nano::unique_path () / "rocksdb"; - nano::logger_mt logger; + nano::nlogger logger; nano::stats stats; auto const check_correct_state = [&] () { nano::store::rocksdb::component store (logger, path, nano::dev::constants); @@ -1471,7 +1471,7 @@ TEST (mdb_block_store, upgrade_backup) }; { - nano::logger_mt logger; + nano::nlogger logger; nano::store::lmdb::component store (logger, path, nano::dev::constants); auto transaction (store.tx_begin_write ()); store.version.put (transaction, store.version_minimum); @@ -1479,7 +1479,7 @@ TEST (mdb_block_store, upgrade_backup) ASSERT_EQ (get_backup_path ().string (), dir.string ()); // Now do the upgrade and confirm that backup is saved - nano::logger_mt logger; + nano::nlogger logger; nano::store::lmdb::component store (logger, path, nano::dev::constants, nano::txn_tracking_config{}, std::chrono::seconds (5), nano::lmdb_config{}, true); ASSERT_FALSE (store.init_error ()); auto transaction (store.tx_begin_read ()); @@ -1496,7 +1496,7 @@ TEST (block_store, confirmation_height) GTEST_SKIP (); } auto path (nano::unique_path ()); - nano::logger_mt logger; + nano::nlogger logger; auto store = nano::make_store (logger, path, nano::dev::constants); nano::account account1{}; @@ -1542,7 +1542,7 @@ TEST (block_store, final_vote) GTEST_SKIP (); } auto path (nano::unique_path ()); - nano::logger_mt logger; + nano::nlogger logger; auto store = nano::make_store (logger, path, nano::dev::constants); { @@ -1567,7 +1567,7 @@ TEST (block_store, final_vote) TEST (block_store, incompatible_version) { auto path (nano::unique_path ()); - nano::logger_mt logger; + nano::nlogger logger; { auto store = nano::make_store (logger, path, nano::dev::constants); ASSERT_FALSE (store->init_error ()); @@ -1590,7 +1590,7 @@ TEST (block_store, incompatible_version) TEST (block_store, reset_renew_existing_transaction) { - nano::logger_mt logger; + nano::nlogger logger; auto store = nano::make_store (logger, nano::unique_path (), nano::dev::constants); ASSERT_TRUE (!store->init_error ()); @@ -1630,7 +1630,7 @@ TEST (block_store, reset_renew_existing_transaction) TEST (block_store, rocksdb_force_test_env_variable) { - nano::logger_mt logger; + nano::nlogger logger; // Set environment variable constexpr auto env_var = "TEST_USE_ROCKSDB"; @@ -1660,7 +1660,7 @@ TEST (rocksdb_block_store, tombstone_count) GTEST_SKIP (); } nano::test::system system; - nano::logger_mt logger; + nano::nlogger logger; auto store = std::make_unique (logger, nano::unique_path () / "rocksdb", nano::dev::constants); ASSERT_TRUE (!store->init_error ()); nano::block_builder builder; diff --git a/nano/core_test/bootstrap.cpp b/nano/core_test/bootstrap.cpp index c5536c34a5..739b4e91a0 100644 --- a/nano/core_test/bootstrap.cpp +++ b/nano/core_test/bootstrap.cpp @@ -944,7 +944,7 @@ TEST (bootstrap_processor, lazy_hash_pruning) ASSERT_EQ (5, node1->ledger.cache.block_count); ASSERT_EQ (5, node1->ledger.cache.cemented_count); // Pruning action - node1->ledger_pruning (2, false, false); + node1->ledger_pruning (2, false); ASSERT_EQ (9, node0->ledger.cache.block_count); ASSERT_EQ (0, node0->ledger.cache.pruned_count); ASSERT_EQ (5, node1->ledger.cache.block_count); @@ -1326,7 +1326,7 @@ TEST (bootstrap_processor, lazy_pruning_missing_block) ASSERT_EQ (5, node1->ledger.cache.block_count); ASSERT_EQ (5, node1->ledger.cache.cemented_count); // Pruning action - node1->ledger_pruning (2, false, false); + node1->ledger_pruning (2, false); ASSERT_EQ (5, node1->ledger.cache.block_count); ASSERT_EQ (1, node1->ledger.cache.pruned_count); ASSERT_TRUE (node1->ledger.block_or_pruned_exists (send1->hash ())); // true for pruned @@ -2031,7 +2031,7 @@ TEST (bulk, DISABLED_genesis_pruning) election->force_confirm (); } ASSERT_TIMELY (2s, node1->active.empty () && node1->block_confirmed (send3->hash ())); - node1->ledger_pruning (2, false, false); + node1->ledger_pruning (2, false); ASSERT_EQ (2, node1->ledger.cache.pruned_count); ASSERT_EQ (4, node1->ledger.cache.block_count); ASSERT_TRUE (node1->ledger.block_or_pruned_exists (send1->hash ())); // true for pruned diff --git a/nano/core_test/bootstrap_ascending.cpp b/nano/core_test/bootstrap_ascending.cpp index f90e5d2a7c..7599ed5c5f 100644 --- a/nano/core_test/bootstrap_ascending.cpp +++ b/nano/core_test/bootstrap_ascending.cpp @@ -1,3 +1,4 @@ +#include #include #include #include @@ -24,7 +25,7 @@ nano::block_hash random_hash () TEST (account_sets, construction) { nano::stats stats; - nano::logger_mt logger; + nano::nlogger logger; auto store = nano::make_store (logger, nano::unique_path (), nano::dev::constants); ASSERT_FALSE (store->init_error ()); nano::bootstrap_ascending::account_sets sets{ stats }; @@ -34,7 +35,7 @@ TEST (account_sets, empty_blocked) { nano::account account{ 1 }; nano::stats stats; - nano::logger_mt logger; + nano::nlogger logger; auto store = nano::make_store (logger, nano::unique_path (), nano::dev::constants); ASSERT_FALSE (store->init_error ()); nano::bootstrap_ascending::account_sets sets{ stats }; @@ -45,7 +46,7 @@ TEST (account_sets, block) { nano::account account{ 1 }; nano::stats stats; - nano::logger_mt logger; + nano::nlogger logger; auto store = nano::make_store (logger, nano::unique_path (), nano::dev::constants); ASSERT_FALSE (store->init_error ()); nano::bootstrap_ascending::account_sets sets{ stats }; @@ -57,7 +58,7 @@ TEST (account_sets, unblock) { nano::account account{ 1 }; nano::stats stats; - nano::logger_mt logger; + nano::nlogger logger; auto store = nano::make_store (logger, nano::unique_path (), nano::dev::constants); ASSERT_FALSE (store->init_error ()); nano::bootstrap_ascending::account_sets sets{ stats }; @@ -71,7 +72,7 @@ TEST (account_sets, priority_base) { nano::account account{ 1 }; nano::stats stats; - nano::logger_mt logger; + nano::nlogger logger; auto store = nano::make_store (logger, nano::unique_path (), nano::dev::constants); ASSERT_FALSE (store->init_error ()); nano::bootstrap_ascending::account_sets sets{ stats }; @@ -82,7 +83,7 @@ TEST (account_sets, priority_blocked) { nano::account account{ 1 }; nano::stats stats; - nano::logger_mt logger; + nano::nlogger logger; auto store = nano::make_store (logger, nano::unique_path (), nano::dev::constants); ASSERT_FALSE (store->init_error ()); nano::bootstrap_ascending::account_sets sets{ stats }; @@ -95,7 +96,7 @@ TEST (account_sets, priority_unblock_keep) { nano::account account{ 1 }; nano::stats stats; - nano::logger_mt logger; + nano::nlogger logger; auto store = nano::make_store (logger, nano::unique_path (), nano::dev::constants); ASSERT_FALSE (store->init_error ()); nano::bootstrap_ascending::account_sets sets{ stats }; @@ -113,7 +114,7 @@ TEST (account_sets, priority_up_down) { nano::account account{ 1 }; nano::stats stats; - nano::logger_mt logger; + nano::nlogger logger; auto store = nano::make_store (logger, nano::unique_path (), nano::dev::constants); ASSERT_FALSE (store->init_error ()); nano::bootstrap_ascending::account_sets sets{ stats }; @@ -128,7 +129,7 @@ TEST (account_sets, priority_down_sat) { nano::account account{ 1 }; nano::stats stats; - nano::logger_mt logger; + nano::nlogger logger; auto store = nano::make_store (logger, nano::unique_path (), nano::dev::constants); ASSERT_FALSE (store->init_error ()); nano::bootstrap_ascending::account_sets sets{ stats }; @@ -141,7 +142,7 @@ TEST (account_sets, saturate_priority) { nano::account account{ 1 }; nano::stats stats; - nano::logger_mt logger; + nano::nlogger logger; auto store = nano::make_store (logger, nano::unique_path (), nano::dev::constants); ASSERT_FALSE (store->init_error ()); nano::bootstrap_ascending::account_sets sets{ stats }; diff --git a/nano/core_test/confirmation_height.cpp b/nano/core_test/confirmation_height.cpp index 7a014447ef..e0a65a3a92 100644 --- a/nano/core_test/confirmation_height.cpp +++ b/nano/core_test/confirmation_height.cpp @@ -1,3 +1,4 @@ +#include #include #include #include @@ -1159,8 +1160,7 @@ TEST (confirmation_heightDeathTest, rollback_added_block) // valgrind can be noisy with death tests if (!nano::running_within_valgrind ()) { - nano::logger_mt logger; - nano::logging logging; + nano::nlogger logger; auto path (nano::unique_path ()); auto store = nano::make_store (logger, path, nano::dev::constants); ASSERT_TRUE (!store->init_error ()); @@ -1186,13 +1186,13 @@ TEST (confirmation_heightDeathTest, rollback_added_block) uint64_t batch_write_size = 2048; std::atomic stopped{ false }; nano::confirmation_height_unbounded unbounded_processor ( - ledger, write_database_queue, 10ms, logging, logger, stopped, batch_write_size, [] (auto const &) {}, [] (auto const &) {}, [] () { return 0; }); + ledger, write_database_queue, 10ms, logger, stopped, batch_write_size, [] (auto const &) {}, [] (auto const &) {}, [] () { return 0; }); // Processing a block which doesn't exist should bail ASSERT_DEATH_IF_SUPPORTED (unbounded_processor.process (send), ""); nano::confirmation_height_bounded bounded_processor ( - ledger, write_database_queue, 10ms, logging, logger, stopped, batch_write_size, [] (auto const &) {}, [] (auto const &) {}, [] () { return 0; }); + ledger, write_database_queue, 10ms, logger, stopped, batch_write_size, [] (auto const &) {}, [] (auto const &) {}, [] () { return 0; }); // Processing a block which doesn't exist should bail ASSERT_DEATH_IF_SUPPORTED (bounded_processor.process (send), ""); } @@ -1251,8 +1251,7 @@ TEST (confirmation_heightDeathTest, modified_chain) // valgrind can be noisy with death tests if (!nano::running_within_valgrind ()) { - nano::logging logging; - nano::logger_mt logger; + nano::nlogger logger; auto path (nano::unique_path ()); auto store = nano::make_store (logger, path, nano::dev::constants); ASSERT_TRUE (!store->init_error ()); @@ -1279,7 +1278,7 @@ TEST (confirmation_heightDeathTest, modified_chain) uint64_t batch_write_size = 2048; std::atomic stopped{ false }; nano::confirmation_height_bounded bounded_processor ( - ledger, write_database_queue, 10ms, logging, logger, stopped, batch_write_size, [] (auto const &) {}, [] (auto const &) {}, [] () { return 0; }); + ledger, write_database_queue, 10ms, logger, stopped, batch_write_size, [] (auto const &) {}, [] (auto const &) {}, [] () { return 0; }); { // This reads the blocks in the account, but prevents any writes from occuring yet @@ -1298,7 +1297,7 @@ TEST (confirmation_heightDeathTest, modified_chain) store->confirmation_height.put (store->tx_begin_write (), nano::dev::genesis->account (), { 1, nano::dev::genesis->hash () }); nano::confirmation_height_unbounded unbounded_processor ( - ledger, write_database_queue, 10ms, logging, logger, stopped, batch_write_size, [] (auto const &) {}, [] (auto const &) {}, [] () { return 0; }); + ledger, write_database_queue, 10ms, logger, stopped, batch_write_size, [] (auto const &) {}, [] (auto const &) {}, [] () { return 0; }); { // This reads the blocks in the account, but prevents any writes from occuring yet @@ -1329,8 +1328,7 @@ TEST (confirmation_heightDeathTest, modified_chain_account_removed) // valgrind can be noisy with death tests if (!nano::running_within_valgrind ()) { - nano::logging logging; - nano::logger_mt logger; + nano::nlogger logger; auto path (nano::unique_path ()); auto store = nano::make_store (logger, path, nano::dev::constants); ASSERT_TRUE (!store->init_error ()); @@ -1368,7 +1366,7 @@ TEST (confirmation_heightDeathTest, modified_chain_account_removed) uint64_t batch_write_size = 2048; std::atomic stopped{ false }; nano::confirmation_height_unbounded unbounded_processor ( - ledger, write_database_queue, 10ms, logging, logger, stopped, batch_write_size, [] (auto const &) {}, [] (auto const &) {}, [] () { return 0; }); + ledger, write_database_queue, 10ms, logger, stopped, batch_write_size, [] (auto const &) {}, [] (auto const &) {}, [] () { return 0; }); { // This reads the blocks in the account, but prevents any writes from occuring yet @@ -1388,7 +1386,7 @@ TEST (confirmation_heightDeathTest, modified_chain_account_removed) store->confirmation_height.put (store->tx_begin_write (), nano::dev::genesis->account (), { 1, nano::dev::genesis->hash () }); nano::confirmation_height_bounded bounded_processor ( - ledger, write_database_queue, 10ms, logging, logger, stopped, batch_write_size, [] (auto const &) {}, [] (auto const &) {}, [] () { return 0; }); + ledger, write_database_queue, 10ms, logger, stopped, batch_write_size, [] (auto const &) {}, [] (auto const &) {}, [] () { return 0; }); { // This reads the blocks in the account, but prevents any writes from occuring yet @@ -2041,7 +2039,7 @@ TEST (confirmation_height, unbounded_block_cache_iteration) // Don't test this in rocksdb mode GTEST_SKIP (); } - nano::logger_mt logger; + nano::nlogger logger; auto path (nano::unique_path ()); auto store = nano::make_store (logger, path, nano::dev::constants); ASSERT_TRUE (!store->init_error ()); @@ -2050,7 +2048,6 @@ TEST (confirmation_height, unbounded_block_cache_iteration) nano::write_database_queue write_database_queue (false); boost::latch initialized_latch{ 0 }; nano::work_pool pool{ nano::dev::network_params.network, std::numeric_limits::max () }; - nano::logging logging; nano::keypair key1; nano::block_builder builder; auto send = builder @@ -2076,7 +2073,7 @@ TEST (confirmation_height, unbounded_block_cache_iteration) ASSERT_EQ (nano::process_result::progress, ledger.process (transaction, *send1).code); } - nano::confirmation_height_processor confirmation_height_processor (ledger, write_database_queue, 10ms, logging, logger, initialized_latch, nano::confirmation_height_mode::unbounded); + nano::confirmation_height_processor confirmation_height_processor (ledger, write_database_queue, 10ms, logger, initialized_latch, nano::confirmation_height_mode::unbounded); nano::timer<> timer; timer.start (); { @@ -2105,7 +2102,7 @@ TEST (confirmation_height, unbounded_block_cache_iteration) TEST (confirmation_height, pruned_source) { - nano::logger_mt logger; + nano::nlogger logger; nano::logging logging; auto path (nano::unique_path ()); auto store = nano::make_store (logger, path, nano::dev::constants); @@ -2180,7 +2177,7 @@ TEST (confirmation_height, pruned_source) std::atomic stopped{ false }; bool first_time{ true }; nano::confirmation_height_bounded bounded_processor ( - ledger, write_database_queue, 10ms, logging, logger, stopped, batch_write_size, [&] (auto const & cemented_blocks_a) { + ledger, write_database_queue, 10ms, logger, stopped, batch_write_size, [&] (auto const & cemented_blocks_a) { if (first_time) { // Prune the send diff --git a/nano/core_test/core_test_main.cc b/nano/core_test/core_test_main.cc index 6f5c4fc499..158256de69 100644 --- a/nano/core_test/core_test_main.cc +++ b/nano/core_test/core_test_main.cc @@ -1,5 +1,6 @@ #include "gtest/gtest.h" +#include #include #include #include @@ -19,7 +20,7 @@ void force_nano_dev_network (); GTEST_API_ int main (int argc, char ** argv) { - printf ("Running main() from core_test_main.cc\n"); + nano::initialize_logging (nano::log::preset::tests); nano::set_file_descriptor_limit (OPEN_FILE_DESCRIPTORS_LIMIT); nano::force_nano_dev_network (); nano::node_singleton_memory_pool_purge_guard memory_pool_cleanup_guard; diff --git a/nano/core_test/ledger.cpp b/nano/core_test/ledger.cpp index 8970b97ef5..bec97994d5 100644 --- a/nano/core_test/ledger.cpp +++ b/nano/core_test/ledger.cpp @@ -1,3 +1,4 @@ +#include #include #include #include @@ -817,7 +818,7 @@ TEST (ledger, representation) TEST (ledger, double_open) { - nano::logger_mt logger; + nano::nlogger logger; auto store = nano::make_store (logger, nano::unique_path (), nano::dev::constants); ASSERT_TRUE (!store->init_error ()); nano::stats stats; @@ -4161,7 +4162,7 @@ TEST (ledger, block_hash_account_conflict) TEST (ledger, could_fit) { - nano::logger_mt logger; + nano::nlogger logger; auto store = nano::make_store (logger, nano::unique_path (), nano::dev::constants); ASSERT_TRUE (!store->init_error ()); nano::stats stats; @@ -4799,7 +4800,7 @@ TEST (ledger, dependents_confirmed) TEST (ledger, dependents_confirmed_pruning) { - nano::logger_mt logger; + nano::nlogger logger; auto store = nano::make_store (logger, nano::unique_path (), nano::dev::constants); ASSERT_FALSE (store->init_error ()); nano::stats stats; @@ -4989,7 +4990,7 @@ TEST (ledger, cache) TEST (ledger, pruning_action) { - nano::logger_mt logger; + nano::nlogger logger; auto store = nano::make_store (logger, nano::unique_path (), nano::dev::constants); ASSERT_TRUE (!store->init_error ()); nano::stats stats; @@ -5073,7 +5074,7 @@ TEST (ledger, pruning_action) TEST (ledger, pruning_large_chain) { - nano::logger_mt logger; + nano::nlogger logger; auto store = nano::make_store (logger, nano::unique_path (), nano::dev::constants); ASSERT_TRUE (!store->init_error ()); nano::stats stats; @@ -5128,7 +5129,7 @@ TEST (ledger, pruning_large_chain) TEST (ledger, pruning_source_rollback) { - nano::logger_mt logger; + nano::nlogger logger; auto store = nano::make_store (logger, nano::unique_path (), nano::dev::constants); ASSERT_TRUE (!store->init_error ()); nano::stats stats; @@ -5216,7 +5217,7 @@ TEST (ledger, pruning_source_rollback) TEST (ledger, pruning_source_rollback_legacy) { - nano::logger_mt logger; + nano::nlogger logger; auto store = nano::make_store (logger, nano::unique_path (), nano::dev::constants); ASSERT_TRUE (!store->init_error ()); nano::stats stats; @@ -5329,7 +5330,7 @@ TEST (ledger, pruning_source_rollback_legacy) TEST (ledger, pruning_process_error) { - nano::logger_mt logger; + nano::nlogger logger; auto store = nano::make_store (logger, nano::unique_path (), nano::dev::constants); ASSERT_TRUE (!store->init_error ()); nano::stats stats; @@ -5376,7 +5377,7 @@ TEST (ledger, pruning_process_error) TEST (ledger, pruning_legacy_blocks) { - nano::logger_mt logger; + nano::nlogger logger; auto store = nano::make_store (logger, nano::unique_path (), nano::dev::constants); ASSERT_TRUE (!store->init_error ()); nano::stats stats; @@ -5462,7 +5463,7 @@ TEST (ledger, pruning_legacy_blocks) TEST (ledger, pruning_safe_functions) { - nano::logger_mt logger; + nano::nlogger logger; auto store = nano::make_store (logger, nano::unique_path (), nano::dev::constants); ASSERT_TRUE (!store->init_error ()); nano::stats stats; @@ -5523,7 +5524,7 @@ TEST (ledger, pruning_safe_functions) TEST (ledger, hash_root_random) { - nano::logger_mt logger; + nano::nlogger logger; auto store = nano::make_store (logger, nano::unique_path (), nano::dev::constants); ASSERT_TRUE (!store->init_error ()); nano::stats stats; @@ -5587,7 +5588,7 @@ TEST (ledger, migrate_lmdb_to_rocksdb) { nano::test::system system{}; auto path = nano::unique_path (); - nano::logger_mt logger{}; + nano::nlogger logger; boost::asio::ip::address_v6 address (boost::asio::ip::make_address_v6 ("::ffff:127.0.0.1")); uint16_t port = 100; nano::store::lmdb::component store{ logger, path / "data.ldb", nano::dev::constants }; diff --git a/nano/core_test/message.cpp b/nano/core_test/message.cpp index 29e70e371c..c26e359a45 100644 --- a/nano/core_test/message.cpp +++ b/nano/core_test/message.cpp @@ -362,22 +362,6 @@ TEST (message, confirm_req_hash_batch_serialization_v2) ASSERT_TRUE (header.confirm_is_v2 ()); } -// this unit test checks that conversion of message_header to string works as expected -TEST (message, message_header_to_string) -{ - // calculate expected string - int maxver = nano::dev::network_params.network.protocol_version; - int minver = nano::dev::network_params.network.protocol_version_min; - std::stringstream ss; - ss << "NetID: 5241(dev), VerMaxUsingMin: " << maxver << "/" << maxver << "/" << minver << ", MsgType: 2(keepalive), Extensions: 0000"; - auto expected_str = ss.str (); - - // check expected vs real - nano::keepalive keepalive_msg{ nano::dev::network_params.network }; - std::string header_string = keepalive_msg.header.to_string (); - ASSERT_EQ (expected_str, header_string); -} - /** * Test that a confirm_ack can encode an empty hash set */ diff --git a/nano/core_test/node.cpp b/nano/core_test/node.cpp index 2627406a02..aa7d8e82ee 100644 --- a/nano/core_test/node.cpp +++ b/nano/core_test/node.cpp @@ -1,4 +1,5 @@ #include +#include #include #include #include @@ -3304,7 +3305,7 @@ TEST (node, dont_write_lock_node) std::promise write_lock_held_promise; std::promise finished_promise; std::thread ([&path, &write_lock_held_promise, &finished_promise] () { - nano::logger_mt logger; + nano::nlogger logger; auto store = nano::make_store (logger, path, nano::dev::constants, false, true); { nano::ledger_cache ledger_cache; @@ -4230,13 +4231,13 @@ TEST (node, pruning_age) ASSERT_EQ (3, node1.ledger.cache.block_count); // Pruning with default age 1 day - node1.ledger_pruning (1, true, false); + node1.ledger_pruning (1, true); ASSERT_EQ (0, node1.ledger.cache.pruned_count); ASSERT_EQ (3, node1.ledger.cache.block_count); // Pruning with max age 0 node1.config.max_pruning_age = std::chrono::seconds{ 0 }; - node1.ledger_pruning (1, true, false); + node1.ledger_pruning (1, true); ASSERT_EQ (1, node1.ledger.cache.pruned_count); ASSERT_EQ (3, node1.ledger.cache.block_count); @@ -4293,13 +4294,13 @@ TEST (node, pruning_depth) ASSERT_EQ (3, node1.ledger.cache.block_count); // Pruning with default depth (unlimited) - node1.ledger_pruning (1, true, false); + node1.ledger_pruning (1, true); ASSERT_EQ (0, node1.ledger.cache.pruned_count); ASSERT_EQ (3, node1.ledger.cache.block_count); // Pruning with max depth 1 node1.config.max_pruning_depth = 1; - node1.ledger_pruning (1, true, false); + node1.ledger_pruning (1, true); ASSERT_EQ (1, node1.ledger.cache.pruned_count); ASSERT_EQ (3, node1.ledger.cache.block_count); @@ -4310,7 +4311,7 @@ TEST (node, pruning_depth) TEST (node_config, node_id_private_key_persistence) { - nano::logger_mt logger; + nano::test::system system; // create the directory and the file auto path = nano::unique_path (); @@ -4318,19 +4319,19 @@ TEST (node_config, node_id_private_key_persistence) auto priv_key_filename = path / "node_id_private.key"; // check that the key generated is random when the key does not exist - nano::keypair kp1 = nano::load_or_create_node_id (path, logger); + nano::keypair kp1 = nano::load_or_create_node_id (path, system.nlogger); std::filesystem::remove (priv_key_filename); - nano::keypair kp2 = nano::load_or_create_node_id (path, logger); + nano::keypair kp2 = nano::load_or_create_node_id (path, system.nlogger); ASSERT_NE (kp1.prv, kp2.prv); // check that the key persists - nano::keypair kp3 = nano::load_or_create_node_id (path, logger); + nano::keypair kp3 = nano::load_or_create_node_id (path, system.nlogger); ASSERT_EQ (kp2.prv, kp3.prv); // write the key file manually and check that right key is loaded std::ofstream ofs (priv_key_filename.string (), std::ofstream::out | std::ofstream::trunc); ofs << "3F28D035B8AA75EA53DF753BFD065CF6138E742971B2C99B84FD8FE328FED2D9" << std::flush; ofs.close (); - nano::keypair kp4 = nano::load_or_create_node_id (path, logger); + nano::keypair kp4 = nano::load_or_create_node_id (path, system.nlogger); ASSERT_EQ (kp4.prv, nano::keypair ("3F28D035B8AA75EA53DF753BFD065CF6138E742971B2C99B84FD8FE328FED2D9").prv); } diff --git a/nano/core_test/processor_service.cpp b/nano/core_test/processor_service.cpp index 42893a97d0..6e48598762 100644 --- a/nano/core_test/processor_service.cpp +++ b/nano/core_test/processor_service.cpp @@ -1,3 +1,4 @@ +#include #include #include #include @@ -10,7 +11,7 @@ TEST (processor_service, bad_send_signature) { - nano::logger_mt logger; + nano::nlogger logger; auto store = nano::make_store (logger, nano::unique_path (), nano::dev::constants); ASSERT_FALSE (store->init_error ()); nano::stats stats; @@ -36,7 +37,7 @@ TEST (processor_service, bad_send_signature) TEST (processor_service, bad_receive_signature) { - nano::logger_mt logger; + nano::nlogger logger; auto store = nano::make_store (logger, nano::unique_path (), nano::dev::constants); ASSERT_FALSE (store->init_error ()); nano::stats stats; diff --git a/nano/core_test/work_pool.cpp b/nano/core_test/work_pool.cpp index 99fafac728..44e726a8b9 100644 --- a/nano/core_test/work_pool.cpp +++ b/nano/core_test/work_pool.cpp @@ -1,6 +1,6 @@ #include #include -#include +#include #include #include #include @@ -92,7 +92,7 @@ TEST (work, opencl) { nano::logging logging; logging.init (nano::unique_path ()); - nano::logger_mt logger; + nano::nlogger logger; bool error (false); nano::opencl_environment environment (error); ASSERT_TRUE (!error || !nano::opencl_loaded); diff --git a/nano/lib/blocks.cpp b/nano/lib/blocks.cpp index 15881b3e50..7a77dfc3b7 100644 --- a/nano/lib/blocks.cpp +++ b/nano/lib/blocks.cpp @@ -11,6 +11,7 @@ #include #include +#include /** Compare blocks, first by type, then content. This is an optimization over dynamic_cast, which is very slow on some platforms. */ namespace @@ -1864,3 +1865,8 @@ bool nano::block_sideband::deserialize (nano::stream & stream_a, nano::block_typ return result; } + +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 5a9ab168bc..acc44601d5 100644 --- a/nano/lib/blocks.hpp +++ b/nano/lib/blocks.hpp @@ -29,6 +29,9 @@ enum class block_type : uint8_t change = 5, state = 6 }; + +std::string_view to_string (block_type); + class block_details { static_assert (std::is_same::type, uint8_t> (), "Epoch enum is not the proper type"); diff --git a/nano/lib/config.cpp b/nano/lib/config.cpp index 13273e1096..add89753c2 100644 --- a/nano/lib/config.cpp +++ b/nano/lib/config.cpp @@ -355,3 +355,23 @@ uint32_t nano::test_scan_wallet_reps_delay () auto test_env = nano::get_env_or_default ("NANO_TEST_WALLET_SCAN_REPS_DELAY", "900000"); // 15 minutes by default return boost::lexical_cast (test_env); } + +std::string_view nano::to_string (nano::networks network) +{ + switch (network) + { + case nano::networks::invalid: + return "invalid"; + case nano::networks::nano_beta_network: + return "beta"; + case nano::networks::nano_dev_network: + return "dev"; + case nano::networks::nano_live_network: + return "live"; + case nano::networks::nano_test_network: + return "test"; + // default case intentionally omitted to cause warnings for unhandled enums + } + + return "n/a"; +} \ No newline at end of file diff --git a/nano/lib/config.hpp b/nano/lib/config.hpp index db8ef89752..cadf272b26 100644 --- a/nano/lib/config.hpp +++ b/nano/lib/config.hpp @@ -127,6 +127,8 @@ enum class networks : uint16_t nano_test_network = 0x5258, // 'R', 'X' }; +std::string_view to_string (nano::networks); + enum class work_version { unspecified, diff --git a/nano/lib/numbers.cpp b/nano/lib/numbers.cpp index 65cb8ac86d..f33d6f3cb3 100644 --- a/nano/lib/numbers.cpp +++ b/nano/lib/numbers.cpp @@ -894,6 +894,27 @@ std::string nano::to_string (double const value_a, int const precision_a) return stream.str (); } +std::ostream & nano::operator<< (std::ostream & os, const uint128_union & val) +{ + // TODO: Replace with streaming implementation + os << val.to_string (); + return os; +} + +std::ostream & nano::operator<< (std::ostream & os, const uint256_union & val) +{ + // TODO: Replace with streaming implementation + os << val.to_string (); + return os; +} + +std::ostream & nano::operator<< (std::ostream & os, const uint512_union & val) +{ + // TODO: Replace with streaming implementation + os << val.to_string (); + return os; +} + #ifdef _WIN32 #pragma warning(push) #pragma warning(disable : 4146) // warning C4146: unary minus operator applied to unsigned type, result still unsigned diff --git a/nano/lib/numbers.hpp b/nano/lib/numbers.hpp index d73310d1b4..3021524c4c 100644 --- a/nano/lib/numbers.hpp +++ b/nano/lib/numbers.hpp @@ -4,6 +4,7 @@ #include #include +#include namespace nano { @@ -61,6 +62,7 @@ class amount : public uint128_union using uint128_union::uint128_union; }; class raw_key; + class uint256_union { public: @@ -265,6 +267,11 @@ std::string to_string_hex (uint64_t const); std::string to_string_hex (uint16_t const); bool from_string_hex (std::string const &, uint64_t &); +/* Printing adapters */ +std::ostream & operator<< (std::ostream & os, const uint128_union & val); +std::ostream & operator<< (std::ostream & os, const uint256_union & val); +std::ostream & operator<< (std::ostream & os, const uint512_union & val); + /** * Convert a double to string in fixed format * @param precision_a (optional) use a specific precision (default is the maximum) diff --git a/nano/lib/stats_enums.hpp b/nano/lib/stats_enums.hpp index 7473d85c66..ff9ef58190 100644 --- a/nano/lib/stats_enums.hpp +++ b/nano/lib/stats_enums.hpp @@ -21,6 +21,8 @@ enum class type : uint8_t http_callback, ipc, tcp, + channel, + socket, confirmation_height, confirmation_observer, drop, @@ -311,7 +313,7 @@ enum class dir : uint8_t namespace nano { -std::string_view to_string (stat::type type); -std::string_view to_string (stat::detail detail); -std::string_view to_string (stat::dir dir); +std::string_view to_string (stat::type); +std::string_view to_string (stat::detail); +std::string_view to_string (stat::dir); } diff --git a/nano/lib/tlsconfig.cpp b/nano/lib/tlsconfig.cpp index 064fce24d8..9a6eb15fe3 100644 --- a/nano/lib/tlsconfig.cpp +++ b/nano/lib/tlsconfig.cpp @@ -1,5 +1,5 @@ #include -#include +#include #include #include @@ -138,7 +138,7 @@ namespace } #endif -nano::error read_tls_config_toml (std::filesystem::path const & data_path_a, nano::tls_config & config_a, nano::logger_mt & logger_a, std::vector const & config_overrides) +nano::error read_tls_config_toml (std::filesystem::path const & data_path_a, nano::tls_config & config_a, nano::nlogger & nlogger, std::vector const & config_overrides) { nano::error error; auto toml_config_path = nano::get_tls_toml_config_path (data_path_a); @@ -176,9 +176,7 @@ nano::error read_tls_config_toml (std::filesystem::path const & data_path_a, nan #ifdef NANO_SECURE_RPC load_certs (config_a, logger_a); #else - auto msg ("https or wss is enabled in the TLS configuration, but the node is not built with NANO_SECURE_RPC"); - std::cerr << msg << std::endl; - logger_a.always_log (msg); + nlogger.critical (nano::log::tag::tls, "HTTPS or WSS is enabled in the TLS configuration, but the node is not built with NANO_SECURE_RPC"); std::exit (1); #endif } diff --git a/nano/lib/tlsconfig.hpp b/nano/lib/tlsconfig.hpp index 3afc605327..d7d18f4202 100644 --- a/nano/lib/tlsconfig.hpp +++ b/nano/lib/tlsconfig.hpp @@ -13,7 +13,7 @@ namespace nano { -class logger_mt; +class nlogger; class jsonconfig; class tomlconfig; @@ -54,5 +54,5 @@ class tls_config final #endif }; -nano::error read_tls_config_toml (std::filesystem::path const & data_path_a, nano::tls_config & config_a, nano::logger_mt & logger_a, std::vector const & config_overrides = std::vector ()); +nano::error read_tls_config_toml (std::filesystem::path const & data_path_a, nano::tls_config & config_a, nano::nlogger &, std::vector const & config_overrides = std::vector ()); } diff --git a/nano/lib/utility.hpp b/nano/lib/utility.hpp index 7155ca4760..5ec06f6e9e 100644 --- a/nano/lib/utility.hpp +++ b/nano/lib/utility.hpp @@ -3,6 +3,7 @@ #include #include +#include #include #include @@ -10,6 +11,7 @@ #include #include #include +#include #include #include @@ -210,3 +212,42 @@ bool elapsed (nano::clock::time_point const & last, Duration duration) return elapsed (last, duration, nano::clock::now ()); } } + +namespace nano::util +{ +/** + * Joins elements with specified delimiter while transforming those elements via specified transform function + */ +template +std::string join (InputIt first, InputIt last, std::string_view delimiter, Func transform) +{ + bool start = true; + std::stringstream ss; + while (first != last) + { + if (start) + { + start = false; + } + else + { + ss << delimiter << " "; + } + ss << transform (*first); + ++first; + } + return ss.str (); +} + +template +std::string join (Container const & container, std::string_view delimiter, Func transform) +{ + return join (container.begin (), container.end (), delimiter, transform); +} + +template +std::string to_str (T const & val) +{ + return boost::lexical_cast (val); +} +} \ No newline at end of file diff --git a/nano/load_test/entry.cpp b/nano/load_test/entry.cpp index db0ecc5f47..858104a60e 100644 --- a/nano/load_test/entry.cpp +++ b/nano/load_test/entry.cpp @@ -4,6 +4,7 @@ #include #include #include +#include #include #include #include @@ -490,6 +491,7 @@ account_info account_info_rpc (boost::asio::io_context & ioc, tcp::resolver::res /** This launches a node and fires a lot of send/recieve RPC requests at it (configurable), then other nodes are tested to make sure they observe these blocks as well. */ int main (int argc, char * const * argv) { + nano::initialize_logging (nano::log::preset::tests); nano::force_nano_dev_network (); boost::program_options::options_description description ("Command line options"); diff --git a/nano/nano_node/daemon.cpp b/nano/nano_node/daemon.cpp index 6344fd8e21..40a8cc6822 100644 --- a/nano/nano_node/daemon.cpp +++ b/nano/nano_node/daemon.cpp @@ -20,6 +20,8 @@ #include #include +#include + namespace { void nano_abort_signal_handler (int signum) @@ -59,8 +61,12 @@ volatile sig_atomic_t sig_int_or_term = 0; constexpr std::size_t OPEN_FILE_DESCRIPTORS_LIMIT = 16384; } -void nano_daemon::daemon::run (std::filesystem::path const & data_path, nano::node_flags const & flags) +void nano::daemon::run (std::filesystem::path const & data_path, nano::node_flags const & flags) { + nano::initialize_logging (nano::log::preset::daemon); + + nlogger.info (nano::log::tag::daemon, "Daemon started"); + install_abort_signal_handler (); std::filesystem::create_directories (data_path); @@ -78,10 +84,9 @@ void nano_daemon::daemon::run (std::filesystem::path const & data_path, nano::no if (!error) { config.node.logging.init (data_path); - nano::logger_mt logger{ config.node.logging.min_time_between_log_output }; auto tls_config (std::make_shared ()); - error = nano::read_tls_config_toml (data_path, *tls_config, logger); + error = nano::read_tls_config_toml (data_path, *tls_config, nlogger); if (error) { std::cerr << error.get_message () << std::endl; @@ -93,30 +98,25 @@ void nano_daemon::daemon::run (std::filesystem::path const & data_path, nano::no } boost::asio::io_context io_ctx; - auto opencl (nano::opencl_work::create (config.opencl_enable, config.opencl, logger, config.node.network_params.work)); + auto opencl (nano::opencl_work::create (config.opencl_enable, config.opencl, nlogger, config.node.network_params.work)); nano::work_pool opencl_work (config.node.network_params.network, config.node.work_threads, config.node.pow_sleep_interval, opencl ? [&opencl] (nano::work_version const version_a, nano::root const & root_a, uint64_t difficulty_a, std::atomic & ticket_a) { return opencl->generate_work (version_a, root_a, difficulty_a, ticket_a); } : std::function (nano::work_version const, nano::root const &, uint64_t, std::atomic &)> (nullptr)); try { - // This avoid a blank prompt during any node initialization delays - auto initialization_text = "Starting up Nano node..."; - std::cout << initialization_text << std::endl; - logger.always_log (initialization_text); + // This avoids a blank prompt during any node initialization delays + nlogger.info (nano::log::tag::daemon, "Starting up Nano node..."); // Print info about number of logical cores detected, those are used to decide how many IO, worker and signature checker threads to spawn - logger.always_log (boost::format ("Hardware concurrency: %1% ( configured: %2% )") % std::thread::hardware_concurrency () % nano::hardware_concurrency ()); + nlogger.info (nano::log::tag::daemon, "Hardware concurrency: {} ( configured: {} )", std::thread::hardware_concurrency (), nano::hardware_concurrency ()); nano::set_file_descriptor_limit (OPEN_FILE_DESCRIPTORS_LIMIT); auto const file_descriptor_limit = nano::get_file_descriptor_limit (); + nlogger.info (nano::log::tag::daemon, "File descriptors limit: {}", file_descriptor_limit); if (file_descriptor_limit < OPEN_FILE_DESCRIPTORS_LIMIT) { - logger.always_log (boost::format ("WARNING: open file descriptors limit is %1%, lower than the %2% recommended. Node was unable to change it.") % file_descriptor_limit % OPEN_FILE_DESCRIPTORS_LIMIT); - } - else - { - logger.always_log (boost::format ("Open file descriptors limit is %1%") % file_descriptor_limit); + nlogger.warn (nano::log::tag::daemon, "File descriptors limit is lower than the {} recommended. Node was unable to change it.", OPEN_FILE_DESCRIPTORS_LIMIT); } // for the daemon start up, if the user hasn't specified a port in @@ -133,18 +133,15 @@ void nano_daemon::daemon::run (std::filesystem::path const & data_path, nano::no auto network_label = node->network_params.network.get_current_network_as_string (); std::time_t dateTime = std::time (nullptr); - std::cout << "Network: " << network_label << ", version: " << NANO_VERSION_STRING << "\n" - << "Path: " << node->application_path.string () << "\n" - << "Build Info: " << BUILD_INFO << "\n" - << "Database backend: " << node->store.vendor_get () << "\n" - << "Start time: " << std::put_time (std::gmtime (&dateTime), "%c UTC") << std::endl; + nlogger.info (nano::log::tag::daemon, "Network: {}", network_label); + nlogger.info (nano::log::tag::daemon, "Version: {}", NANO_VERSION_STRING); + nlogger.info (nano::log::tag::daemon, "Data path: '{}'", node->application_path.string ()); + nlogger.info (nano::log::tag::daemon, "Build info: {}", BUILD_INFO); + nlogger.info (nano::log::tag::daemon, "Database backend: {}", node->store.vendor_get ()); + nlogger.info (nano::log::tag::daemon, "Start time: {:%c} UTC", fmt::gmtime (dateTime)); - auto voting (node->wallets.reps ().voting); - if (voting > 1) - { - std::cout << "Voting with more than one representative can limit performance: " << voting << " representatives are configured" << std::endl; - } node->start (); + nano::ipc::ipc_server ipc_server (*node, config.rpc); std::unique_ptr rpc_process; std::unique_ptr rpc; @@ -187,7 +184,9 @@ void nano_daemon::daemon::run (std::filesystem::path const & data_path, nano::no } debug_assert (!nano::signal_handler_impl); - nano::signal_handler_impl = [&io_ctx] () { + nano::signal_handler_impl = [this, &io_ctx] () { + nlogger.warn (nano::log::tag::daemon, "Interrupt signal received, stopping..."); + io_ctx.stop (); sig_int_or_term = 1; }; @@ -219,16 +218,18 @@ void nano_daemon::daemon::run (std::filesystem::path const & data_path, nano::no } else { - std::cerr << "Error initializing node\n"; + nlogger.critical (nano::log::tag::daemon, "Error initializing node"); } } catch (std::runtime_error const & e) { - std::cerr << "Error while running node (" << e.what () << ")\n"; + nlogger.critical (nano::log::tag::daemon, "Error while running node: {}", e.what ()); } } else { - std::cerr << "Error deserializing config: " << error.get_message () << std::endl; + nlogger.critical (nano::log::tag::daemon, "Error deserializing config: {}", error.get_message ()); } + + nlogger.info (nano::log::tag::daemon, "Daemon exiting..."); } diff --git a/nano/nano_node/daemon.hpp b/nano/nano_node/daemon.hpp index d56a26c907..3b4c232e77 100644 --- a/nano/nano_node/daemon.hpp +++ b/nano/nano_node/daemon.hpp @@ -1,11 +1,13 @@ +#include + namespace nano { class node_flags; -} -namespace nano_daemon -{ + class daemon { + nano::nlogger nlogger; + public: void run (std::filesystem::path const &, nano::node_flags const & flags); }; diff --git a/nano/nano_node/entry.cpp b/nano/nano_node/entry.cpp index 250428f542..6b4b319064 100644 --- a/nano/nano_node/entry.cpp +++ b/nano/nano_node/entry.cpp @@ -54,7 +54,10 @@ class address_library_pair int main (int argc, char * const * argv) { nano::set_umask (); + nano::initialize_logging (); + nano::node_singleton_memory_pool_purge_guard memory_pool_cleanup_guard; + boost::program_options::options_description description ("Command line options"); // clang-format off description.add_options () @@ -138,7 +141,7 @@ int main (int argc, char * const * argv) { if (vm.count ("daemon") > 0) { - nano_daemon::daemon daemon; + nano::daemon daemon; nano::node_flags flags; auto flags_ec = nano::update_flags (flags, vm); if (flags_ec) @@ -281,14 +284,14 @@ int main (int argc, char * const * argv) { if (sample.diff > log_threshold) { - node->logger.always_log (sample.get_entry ()); + std::cout << '\t' << sample.get_entry () << '\n'; } } for (auto const & newcomer : newcomers) { if (newcomer.second > log_threshold) { - node->logger.always_log (newcomer_entry (newcomer)); + std::cout << '\t' << newcomer_entry (newcomer) << '\n'; } } } @@ -610,9 +613,9 @@ int main (int argc, char * const * argv) error |= device >= environment.platforms[platform].devices.size (); if (!error) { - nano::logger_mt logger; + nano::nlogger nlogger; nano::opencl_config config (platform, device, threads); - auto opencl (nano::opencl_work::create (true, config, logger, network_params.work)); + auto opencl (nano::opencl_work::create (true, config, nlogger, network_params.work)); nano::work_pool work_pool{ network_params.network, 0, std::chrono::nanoseconds (0), opencl ? [&opencl] (nano::work_version const version_a, nano::root const & root_a, uint64_t difficulty_a, std::atomic &) { return opencl->generate_work (version_a, root_a, difficulty_a); } @@ -1871,7 +1874,7 @@ int main (int argc, char * const * argv) nano::update_flags (node_flags, vm); nano::inactive_node inactive_node (data_path, node_flags); auto node = inactive_node.node; - node->ledger_pruning (node_flags.block_processor_batch_size != 0 ? node_flags.block_processor_batch_size : 16 * 1024, true, true); + node->ledger_pruning (node_flags.block_processor_batch_size != 0 ? node_flags.block_processor_batch_size : 16 * 1024, true); } else if (vm.count ("debug_stacktrace")) { @@ -1887,7 +1890,11 @@ int main (int argc, char * const * argv) } #endif auto inactive_node = nano::default_inactive_node (data_path, vm); - inactive_node->node->logger.always_log (nano::severity_level::error, "Testing system logger"); + inactive_node->node->nlogger.critical ({}, "Testing system logger (CRITICAL)"); + inactive_node->node->nlogger.error ({}, "Testing system logger (ERROR)"); + inactive_node->node->nlogger.warn ({}, "Testing system logger (WARN)"); + inactive_node->node->nlogger.info ({}, "Testing system logger (INFO)"); + inactive_node->node->nlogger.debug ({}, "Testing system logger (DEBUG)"); } else if (vm.count ("debug_account_versions")) { diff --git a/nano/nano_rpc/entry.cpp b/nano/nano_rpc/entry.cpp index 415beb9f5f..a7f1de7912 100644 --- a/nano/nano_rpc/entry.cpp +++ b/nano/nano_rpc/entry.cpp @@ -1,5 +1,6 @@ #include #include +#include #include #include #include @@ -17,6 +18,8 @@ namespace { +nano::nlogger nlogger; + void logging_init (std::filesystem::path const & application_path_a) { static std::atomic_flag logging_already_added = ATOMIC_FLAG_INIT; @@ -36,6 +39,10 @@ volatile sig_atomic_t sig_int_or_term = 0; void run (std::filesystem::path const & data_path, std::vector const & config_overrides) { + nano::initialize_logging (nano::log::preset::daemon); + + nlogger.info (nano::log::tag::daemon, "Daemon started (RPC)"); + std::filesystem::create_directories (data_path); boost::system::error_code error_chmod; nano::set_secure_perm_directory (data_path, error_chmod); @@ -47,13 +54,12 @@ void run (std::filesystem::path const & data_path, std::vector cons if (!error) { logging_init (data_path); - nano::logger_mt logger; auto tls_config (std::make_shared ()); - error = nano::read_tls_config_toml (data_path, *tls_config, logger); + error = nano::read_tls_config_toml (data_path, *tls_config, nlogger); if (error) { - std::cerr << error.get_message () << std::endl; + nlogger.critical (nano::log::tag::daemon, "Error reading RPC TLS config: {}", error.get_message ()); std::exit (1); } else @@ -88,12 +94,12 @@ void run (std::filesystem::path const & data_path, std::vector cons } catch (std::runtime_error const & e) { - std::cerr << "Error while running rpc (" << e.what () << ")\n"; + nlogger.critical (nano::log::tag::daemon, "Error while running RPC: {}", e.what ()); } } else { - std::cerr << "Error deserializing config: " << error.get_message () << std::endl; + nlogger.critical (nano::log::tag::daemon, "Error deserializing config: {}", error.get_message ()); } } } @@ -101,6 +107,7 @@ void run (std::filesystem::path const & data_path, std::vector cons int main (int argc, char * const * argv) { nano::set_umask (); + nano::initialize_logging (); boost::program_options::options_description description ("Command line options"); diff --git a/nano/nano_wallet/entry.cpp b/nano/nano_wallet/entry.cpp index 440e5ddf80..d8cb2f2df7 100644 --- a/nano/nano_wallet/entry.cpp +++ b/nano/nano_wallet/entry.cpp @@ -25,13 +25,18 @@ namespace { +nano::nlogger nlogger; + void show_error (std::string const & message_a) { + nlogger.critical (nano::log::tag::daemon, "{}", message_a); + QMessageBox message (QMessageBox::Critical, "Error starting Nano", message_a.c_str ()); message.setModal (true); message.show (); message.exec (); } + void show_help (std::string const & message_a) { QMessageBox message (QMessageBox::NoIcon, "Help", "see launch options "); @@ -68,6 +73,10 @@ nano::error read_wallet_config (nano::wallet_config & config_a, std::filesystem: int run_wallet (QApplication & application, int argc, char * const * argv, std::filesystem::path const & data_path, nano::node_flags const & flags) { + nano::initialize_logging (nano::log::preset::daemon); + + nlogger.info (nano::log::tag::daemon, "Daemon started (wallet)"); + int result (0); nano_qt::eventloop_processor processor; boost::system::error_code error_chmod; @@ -100,10 +109,9 @@ int run_wallet (QApplication & application, int argc, char * const * argv, std:: nano::set_use_memory_pools (config.node.use_memory_pools); config.node.logging.init (data_path); - nano::logger_mt logger{ config.node.logging.min_time_between_log_output }; auto tls_config (std::make_shared ()); - error = nano::read_tls_config_toml (data_path, *tls_config, logger); + error = nano::read_tls_config_toml (data_path, *tls_config, nlogger); if (error) { splash->hide (); @@ -121,7 +129,7 @@ int run_wallet (QApplication & application, int argc, char * const * argv, std:: std::shared_ptr node; std::shared_ptr gui; nano::set_application_icon (application); - auto opencl (nano::opencl_work::create (config.opencl_enable, config.opencl, logger, config.node.network_params.work)); + auto opencl (nano::opencl_work::create (config.opencl_enable, config.opencl, nlogger, config.node.network_params.work)); nano::work_pool work{ config.node.network_params.network, config.node.work_threads, config.node.pow_sleep_interval, opencl ? [&opencl] (nano::work_version const version_a, nano::root const & root_a, uint64_t difficulty_a, std::atomic &) { return opencl->generate_work (version_a, root_a, difficulty_a); } @@ -237,6 +245,8 @@ int run_wallet (QApplication & application, int argc, char * const * argv, std:: int main (int argc, char * const * argv) { nano::set_umask (); + nano::initialize_logging (); + nano::node_singleton_memory_pool_purge_guard memory_pool_cleanup_guard; QApplication application (argc, const_cast (argv)); diff --git a/nano/node/active_transactions.cpp b/nano/node/active_transactions.cpp index 2e15791551..aeea7edcea 100644 --- a/nano/node/active_transactions.cpp +++ b/nano/node/active_transactions.cpp @@ -300,11 +300,6 @@ void nano::active_transactions::request_confirm (nano::unique_lock solicitor.flush (); lock_a.lock (); - - if (node.config.logging.timing_logging ()) - { - node.logger.try_log (boost::str (boost::format ("Processed %1% elections (%2% were already confirmed) in %3% %4%") % this_loop_target_l % (this_loop_target_l - unconfirmed_count_l) % elapsed.value ().count () % elapsed.unit ())); - } } void nano::active_transactions::cleanup_election (nano::unique_lock & lock_a, std::shared_ptr election) @@ -312,7 +307,6 @@ void nano::active_transactions::cleanup_election (nano::unique_lock debug_assert (!mutex.try_lock ()); debug_assert (lock_a.owns_lock ()); - node.stats.inc (completion_type (*election), nano::to_stat_detail (election->behavior ())); // Keep track of election count by election type debug_assert (count_by_behavior[election->behavior ()] > 0); count_by_behavior[election->behavior ()]--; @@ -324,10 +318,15 @@ void nano::active_transactions::cleanup_election (nano::unique_lock (void)erased; debug_assert (erased == 1); } + roots.get ().erase (roots.get ().find (election->qualified_root)); lock_a.unlock (); + + node.stats.inc (completion_type (*election), nano::to_stat_detail (election->behavior ())); + vacancy_update (); + for (auto const & [hash, block] : blocks_l) { // Notify observers about dropped elections & blocks lost confirmed elections @@ -342,11 +341,6 @@ void nano::active_transactions::cleanup_election (nano::unique_lock node.network.publish_filter.clear (block); } } - - if (node.config.logging.election_result_logging ()) - { - node.logger.try_log (boost::str (boost::format ("Election erased for root %1%, confirmed: %2$b") % election->qualified_root.to_string () % election->confirmed ())); - } } nano::stat::type nano::active_transactions::completion_type (nano::election const & election) const @@ -452,6 +446,7 @@ nano::election_insertion_result nano::active_transactions::insert_impl (nano::un election_behavior_a); roots.get ().emplace (nano::active_transactions::conflict_info{ root, result.election }); blocks.emplace (hash, result.election); + // Keep track of election count by election type debug_assert (count_by_behavior[result.election->behavior ()] >= 0); count_by_behavior[result.election->behavior ()]++; @@ -461,8 +456,11 @@ nano::election_insertion_result nano::active_transactions::insert_impl (nano::un { cache->fill (result.election); } + node.stats.inc (nano::stat::type::active_started, nano::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 6d843fea54..f0e565b05c 100644 --- a/nano/node/blockprocessor.cpp +++ b/nano/node/blockprocessor.cpp @@ -112,19 +112,17 @@ void nano::block_processor::rollback_competitor (store::write_transaction const if (successor != nullptr && successor->hash () != hash) { // Replace our block with the winner and roll back any dependent blocks - if (node.config.logging.ledger_rollback_logging ()) - { - node.logger.always_log (boost::str (boost::format ("Rolling back %1% and replacing with %2%") % successor->hash ().to_string () % hash.to_string ())); - } + node.nlogger.debug (nano::log::tag::blockprocessor, "Rolling back: {} and replacing with: {}", successor->hash ().to_string (), hash.to_string ()); + std::vector> rollback_list; if (node.ledger.rollback (transaction, successor->hash (), rollback_list)) { node.stats.inc (nano::stat::type::ledger, nano::stat::detail::rollback_failed); - node.logger.always_log (nano::severity_level::error, boost::str (boost::format ("Failed to roll back %1% because it or a successor was confirmed") % successor->hash ().to_string ())); + node.nlogger.error (nano::log::tag::blockprocessor, "Failed to roll back: {} because it or a successor was confirmed", successor->hash ().to_string ()); } - else if (node.config.logging.ledger_rollback_logging ()) + else { - node.logger.always_log (boost::str (boost::format ("%1% blocks rolled back") % rollback_list.size ())); + node.nlogger.debug (nano::log::tag::blockprocessor, "Blocks rolled back: {}", rollback_list.size ()); } // Deleting from votes cache, stop active transaction for (auto & i : rollback_list) @@ -218,10 +216,12 @@ auto nano::block_processor::process_batch (nano::unique_lock & lock auto store_batch_reached = [&number_of_blocks_processed, max = node.store.max_block_write_batch_num ()] { return number_of_blocks_processed >= max; }; while (have_blocks_ready () && (!deadline_reached () || !processor_batch_reached ()) && !store_batch_reached ()) { + // TODO: Cleaner periodical logging if ((blocks.size () + forced.size () > 64) && should_log ()) { - node.logger.always_log (boost::str (boost::format ("%1% blocks (+ %2% forced) in processing queue") % blocks.size () % forced.size ())); + node.nlogger.debug (nano::log::tag::blockprocessor, "{} blocks (+ {} forced) in processing queue", blocks.size (), forced.size ()); } + std::shared_ptr block; nano::block_hash hash (0); bool force (false); @@ -251,10 +251,11 @@ auto nano::block_processor::process_batch (nano::unique_lock & lock } lock_a.unlock (); - if (node.config.logging.timing_logging () && number_of_blocks_processed != 0 && timer_l.stop () > std::chrono::milliseconds (100)) + if (number_of_blocks_processed != 0 && timer_l.stop () > std::chrono::milliseconds (100)) { - node.logger.always_log (boost::str (boost::format ("Processed %1% blocks (%2% blocks were forced) in %3% %4%") % number_of_blocks_processed % number_of_forced_processed % timer_l.value ().count () % timer_l.unit ())); + node.nlogger.debug (nano::log::tag::blockprocessor, "Processed {} blocks ({} forced) in {} {}", number_of_blocks_processed, number_of_forced_processed, timer_l.value ().count (), timer_l.unit ()); } + return processed; } @@ -263,16 +264,13 @@ nano::process_return nano::block_processor::process_one (store::write_transactio nano::process_return result; auto hash (block->hash ()); result = node.ledger.process (transaction_a, *block); + + node.stats.inc (nano::stat::type::blockprocessor, to_stat_detail (result.code)); + switch (result.code) { case nano::process_result::progress: { - if (node.config.logging.ledger_logging ()) - { - std::string block_string; - block->serialize_json (block_string, node.config.logging.single_line_record ()); - node.logger.try_log (boost::str (boost::format ("Processing block %1%: %2%") % hash.to_string () % block_string)); - } queue_unchecked (transaction_a, hash); /* For send blocks check epoch open unchecked (gap pending). For state blocks check only send subtype and only if block epoch is not last epoch. @@ -287,120 +285,65 @@ nano::process_return nano::block_processor::process_one (store::write_transactio } case nano::process_result::gap_previous: { - if (node.config.logging.ledger_logging ()) - { - node.logger.try_log (boost::str (boost::format ("Gap previous for: %1%") % hash.to_string ())); - } node.unchecked.put (block->previous (), block); node.stats.inc (nano::stat::type::ledger, nano::stat::detail::gap_previous); break; } case nano::process_result::gap_source: { - if (node.config.logging.ledger_logging ()) - { - node.logger.try_log (boost::str (boost::format ("Gap source for: %1%") % hash.to_string ())); - } node.unchecked.put (node.ledger.block_source (transaction_a, *block), block); node.stats.inc (nano::stat::type::ledger, nano::stat::detail::gap_source); break; } case nano::process_result::gap_epoch_open_pending: { - if (node.config.logging.ledger_logging ()) - { - node.logger.try_log (boost::str (boost::format ("Gap pending entries for epoch open: %1%") % hash.to_string ())); - } node.unchecked.put (block->account (), block); // Specific unchecked key starting with epoch open block account public key node.stats.inc (nano::stat::type::ledger, nano::stat::detail::gap_source); break; } case nano::process_result::old: { - if (node.config.logging.ledger_duplicate_logging ()) - { - node.logger.try_log (boost::str (boost::format ("Old for: %1%") % hash.to_string ())); - } node.stats.inc (nano::stat::type::ledger, nano::stat::detail::old); break; } case nano::process_result::bad_signature: { - if (node.config.logging.ledger_logging ()) - { - node.logger.try_log (boost::str (boost::format ("Bad signature for: %1%") % hash.to_string ())); - } break; } case nano::process_result::negative_spend: { - if (node.config.logging.ledger_logging ()) - { - node.logger.try_log (boost::str (boost::format ("Negative spend for: %1%") % hash.to_string ())); - } break; } case nano::process_result::unreceivable: { - if (node.config.logging.ledger_logging ()) - { - node.logger.try_log (boost::str (boost::format ("Unreceivable for: %1%") % hash.to_string ())); - } break; } case nano::process_result::fork: { node.stats.inc (nano::stat::type::ledger, nano::stat::detail::fork); - if (node.config.logging.ledger_logging ()) - { - node.logger.try_log (boost::str (boost::format ("Fork for: %1% root: %2%") % hash.to_string () % block->root ().to_string ())); - } break; } case nano::process_result::opened_burn_account: { - if (node.config.logging.ledger_logging ()) - { - node.logger.try_log (boost::str (boost::format ("Rejecting open block for burn account: %1%") % hash.to_string ())); - } break; } case nano::process_result::balance_mismatch: { - if (node.config.logging.ledger_logging ()) - { - node.logger.try_log (boost::str (boost::format ("Balance mismatch for: %1%") % hash.to_string ())); - } break; } case nano::process_result::representative_mismatch: { - if (node.config.logging.ledger_logging ()) - { - node.logger.try_log (boost::str (boost::format ("Representative mismatch for: %1%") % hash.to_string ())); - } break; } case nano::process_result::block_position: { - if (node.config.logging.ledger_logging ()) - { - node.logger.try_log (boost::str (boost::format ("Block %1% cannot follow predecessor %2%") % hash.to_string () % block->previous ().to_string ())); - } break; } case nano::process_result::insufficient_work: { - if (node.config.logging.ledger_logging ()) - { - node.logger.try_log (boost::str (boost::format ("Insufficient work for %1% : %2% (difficulty %3%)") % hash.to_string () % nano::to_string_hex (block->block_work ()) % nano::to_string_hex (node.network_params.work.difficulty (*block)))); - } break; } } - - node.stats.inc (nano::stat::type::blockprocessor, nano::to_stat_detail (result.code)); - return result; } diff --git a/nano/node/blockprocessor.hpp b/nano/node/blockprocessor.hpp index 5e87663897..fc6c7172a0 100644 --- a/nano/node/blockprocessor.hpp +++ b/nano/node/blockprocessor.hpp @@ -1,6 +1,7 @@ #pragma once #include +#include #include #include diff --git a/nano/node/bootstrap/bootstrap_attempt.cpp b/nano/node/bootstrap/bootstrap_attempt.cpp index 4656ad5f4f..d574ec44f7 100644 --- a/nano/node/bootstrap/bootstrap_attempt.cpp +++ b/nano/node/bootstrap/bootstrap_attempt.cpp @@ -20,7 +20,8 @@ nano::bootstrap_attempt::bootstrap_attempt (std::shared_ptr const & id = nano::hardened_constants::get ().random_128.to_string (); } - node_a->logger.always_log (boost::str (boost::format ("Starting %1% bootstrap attempt with ID %2%") % mode_text () % id)); + node_a->nlogger.debug (nano::log::tag::bootstrap, "Starting bootstrap attempt with ID: {} (mode: {})", mode_text (), id); + node_a->bootstrap_initiator.notify_listeners (true); if (node_a->websocket.server) { @@ -36,7 +37,9 @@ nano::bootstrap_attempt::~bootstrap_attempt () { return; } - node->logger.always_log (boost::str (boost::format ("Exiting %1% bootstrap attempt with ID %2%") % mode_text () % id)); + + node->nlogger.debug (nano::log::tag::bootstrap, "Exiting bootstrap attempt with ID: {} (mode: {})", mode_text (), id); + node->bootstrap_initiator.notify_listeners (false); if (node->websocket.server) { diff --git a/nano/node/bootstrap/bootstrap_bulk_pull.cpp b/nano/node/bootstrap/bootstrap_bulk_pull.cpp index 5c0daa4602..f10055d064 100644 --- a/nano/node/bootstrap/bootstrap_bulk_pull.cpp +++ b/nano/node/bootstrap/bootstrap_bulk_pull.cpp @@ -46,10 +46,8 @@ nano::bulk_pull_client::~bulk_pull_client () } pull.processed += pull_blocks - unexpected_count; node->bootstrap_initiator.connections->requeue_pull (pull, network_error); - if (node->config.logging.bulk_pull_logging ()) - { - node->logger.try_log (boost::str (boost::format ("Bulk pull end block is not expected %1% for account %2% or head block %3%") % pull.end.to_string () % pull.account_or_head.to_account () % pull.account_or_head.to_string ())); - } + + node->nlogger.debug (nano::log::tag::bulk_pull_client, "Bulk pull end block is not expected {} for account {} or head block {}", pull.end.to_string (), pull.account_or_head.to_account (), pull.account_or_head.to_string ()); } else { @@ -82,14 +80,11 @@ void nano::bulk_pull_client::request () req.count = pull.count; req.set_count_present (pull.count != 0); - if (node->config.logging.bulk_pull_logging ()) - { - node->logger.try_log (boost::str (boost::format ("Requesting account %1% or head block %2% from %3%. %4% accounts in queue") % pull.account_or_head.to_account () % pull.account_or_head.to_string () % connection->channel->to_string () % attempt->pulling)); - } - else if (node->config.logging.network_logging () && attempt->should_log ()) + if (attempt->should_log ()) { - node->logger.always_log (boost::str (boost::format ("%1% accounts in pull queue") % attempt->pulling)); + node->nlogger.debug (nano::log::tag::bulk_pull_client, "Accounts in pull queue: {}", attempt->pulling.load ()); } + auto this_l (shared_from_this ()); connection->channel->send ( req, [this_l] (boost::system::error_code const & ec, std::size_t size_a) { @@ -104,10 +99,7 @@ void nano::bulk_pull_client::request () } else { - if (node->config.logging.bulk_pull_logging ()) - { - node->logger.try_log (boost::str (boost::format ("Error sending bulk pull request to %1%: to %2%") % ec.message () % this_l->connection->channel->to_string ())); - } + node->nlogger.debug (nano::log::tag::bulk_pull_client, "Error sending bulk pull request to: {} ({})", this_l->connection->channel->to_string (), ec.message ()); node->stats.inc (nano::stat::type::bootstrap, nano::stat::detail::bulk_pull_request_failure, nano::stat::dir::in); } }, @@ -168,20 +160,12 @@ void nano::bulk_pull_client::received_block (boost::system::error_code ec, std:: } if (node->network_params.work.validate_entry (*block)) { - if (node->config.logging.bulk_pull_logging ()) - { - node->logger.try_log (boost::str (boost::format ("Insufficient work for bulk pull block: %1%") % block->hash ().to_string ())); - } - node->stats.inc_detail_only (nano::stat::type::error, nano::stat::detail::insufficient_work); + node->nlogger.debug (nano::log::tag::bulk_pull_client, "Insufficient work for bulk pull block: {}", block->hash ().to_string ()); + node->stats.inc (nano::stat::type::error, nano::stat::detail::insufficient_work); return; } auto hash = block->hash (); - if (node->config.logging.bulk_pull_logging ()) - { - std::string block_l; - block->serialize_json (block_l, node->config.logging.single_line_record ()); - node->logger.try_log (boost::str (boost::format ("Pulled block %1% %2%") % hash.to_string () % block_l)); - } + // 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 (...) @@ -247,14 +231,12 @@ void nano::bulk_pull_account_client::request () req.account = account; req.minimum_amount = node->config.receive_minimum; req.flags = nano::bulk_pull_account_flags::pending_hash_and_amount; - if (node->config.logging.bulk_pull_logging ()) - { - node->logger.try_log (boost::str (boost::format ("Requesting pending for account %1% from %2%. %3% accounts in queue") % req.account.to_account () % connection->channel->to_string () % attempt->wallet_size ())); - } - else if (node->config.logging.network_logging () && attempt->should_log ()) + + if (attempt->should_log ()) { - node->logger.always_log (boost::str (boost::format ("%1% accounts in pull queue") % attempt->wallet_size ())); + node->nlogger.debug (nano::log::tag::bulk_pull_account_client, "Accounts in pull queue: {}", attempt->wallet_size ()); } + auto this_l (shared_from_this ()); connection->channel->send ( req, [this_l] (boost::system::error_code const & ec, std::size_t size_a) { @@ -269,12 +251,10 @@ void nano::bulk_pull_account_client::request () } else { - this_l->attempt->requeue_pending (this_l->account); - if (node->config.logging.bulk_pull_logging ()) - { - node->logger.try_log (boost::str (boost::format ("Error starting bulk pull request to %1%: to %2%") % ec.message () % this_l->connection->channel->to_string ())); - } + node->nlogger.debug (nano::log::tag::bulk_pull_account_client, "Error starting bulk pull request to: {} ({})", this_l->connection->channel->to_string (), ec.message ()); node->stats.inc (nano::stat::type::bootstrap, nano::stat::detail::bulk_pull_error_starting_request, nano::stat::dir::in); + + this_l->attempt->requeue_pending (this_l->account); } }, nano::transport::buffer_drop_policy::no_limiter_drop); @@ -334,20 +314,16 @@ void nano::bulk_pull_account_client::receive_pending () } else { + node->nlogger.debug (nano::log::tag::bulk_pull_account_client, "Error while receiving bulk pull account frontier: {}", ec.message ()); + this_l->attempt->requeue_pending (this_l->account); - if (node->config.logging.network_logging ()) - { - node->logger.try_log (boost::str (boost::format ("Error while receiving bulk pull account frontier %1%") % ec.message ())); - } } } else { + node->nlogger.debug (nano::log::tag::bulk_pull_account_client, "Invalid size: Expected {}, got: {}", size_l, size_a); + this_l->attempt->requeue_pending (this_l->account); - if (node->config.logging.network_message_logging ()) - { - node->logger.try_log (boost::str (boost::format ("Invalid size: expected %1%, got %2%") % size_l % size_a)); - } } }); } @@ -379,19 +355,14 @@ void nano::bulk_pull_server::set_current_end () auto transaction (node->store.tx_begin_read ()); if (!node->store.block.exists (transaction, request->end)) { - if (node->config.logging.bulk_pull_logging ()) - { - node->logger.try_log (boost::str (boost::format ("Bulk pull end block doesn't exist: %1%, sending everything") % request->end.to_string ())); - } + node->nlogger.debug (nano::log::tag::bulk_pull_server, "Bulk pull end block doesn't exist: {}, sending everything", request->end.to_string ()); + request->end.clear (); } if (node->store.block.exists (transaction, request->start.as_block_hash ())) { - if (node->config.logging.bulk_pull_logging ()) - { - node->logger.try_log (boost::str (boost::format ("Bulk pull request for block hash: %1%") % request->start.to_string ())); - } + node->nlogger.debug (nano::log::tag::bulk_pull_server, "Bulk pull request for block hash: {}", request->start.to_string ()); current = ascending () ? node->store.block.successor (transaction, request->start.as_block_hash ()) : request->start.as_block_hash (); include_start = true; @@ -401,10 +372,8 @@ void nano::bulk_pull_server::set_current_end () auto info = node->ledger.account_info (transaction, request->start.as_account ()); if (!info) { - if (node->config.logging.bulk_pull_logging ()) - { - node->logger.try_log (boost::str (boost::format ("Request for unknown account: %1%") % request->start.to_account ())); - } + node->nlogger.debug (nano::log::tag::bulk_pull_server, "Request for unknown account: {}", request->start.to_account ()); + current = request->end; } else @@ -415,10 +384,8 @@ void nano::bulk_pull_server::set_current_end () auto account (node->ledger.account (transaction, request->end)); if (account != request->start.as_account ()) { - if (node->config.logging.bulk_pull_logging ()) - { - node->logger.try_log (boost::str (boost::format ("Request for block that is not on account chain: %1% not on %2%") % request->end.to_string () % request->start.to_account ())); - } + node->nlogger.debug (nano::log::tag::bulk_pull_server, "Request for block that is not on account chain: {} not on {}", request->end.to_string (), request->start.to_account ()); + current = request->end; } } @@ -451,10 +418,7 @@ void nano::bulk_pull_server::send_next () nano::vectorstream stream (send_buffer); nano::serialize_block (stream, *block); } - if (node->config.logging.bulk_pull_logging ()) - { - node->logger.try_log (boost::str (boost::format ("Sending block: %1%") % block->hash ().to_string ())); - } + connection->socket->async_write (nano::shared_const_buffer (std::move (send_buffer)), [this_l = shared_from_this ()] (boost::system::error_code const & ec, std::size_t size_a) { this_l->sent_action (ec, size_a); }); @@ -556,10 +520,7 @@ void nano::bulk_pull_server::sent_action (boost::system::error_code const & ec, } else { - if (node->config.logging.bulk_pull_logging ()) - { - node->logger.try_log (boost::str (boost::format ("Unable to bulk send block: %1%") % ec.message ())); - } + node->nlogger.debug (nano::log::tag::bulk_pull_server, "Unable to bulk send block: {}", ec.message ()); } } @@ -572,10 +533,9 @@ void nano::bulk_pull_server::send_finished () } nano::shared_const_buffer send_buffer (static_cast (nano::block_type::not_a_block)); auto this_l (shared_from_this ()); - if (node->config.logging.bulk_pull_logging ()) - { - node->logger.try_log ("Bulk sending finished"); - } + + node->nlogger.debug (nano::log::tag::bulk_pull_server, "Bulk sending finished"); + connection->socket->async_write (send_buffer, [this_l] (boost::system::error_code const & ec, std::size_t size_a) { this_l->no_block_sent (ec, size_a); }); @@ -595,10 +555,7 @@ void nano::bulk_pull_server::no_block_sent (boost::system::error_code const & ec } else { - if (node->config.logging.bulk_pull_logging ()) - { - node->logger.try_log ("Unable to send not-a-block"); - } + node->nlogger.debug (nano::log::tag::bulk_pull_server, "Unable to bulk send not-a-block: {}", ec.message ()); } } @@ -650,13 +607,9 @@ void nano::bulk_pull_account_server::set_params () } else { - if (node->config.logging.bulk_pull_logging ()) - { - node->logger.try_log (boost::str (boost::format ("Invalid bulk_pull_account flags supplied %1%") % static_cast (request->flags))); - } + node->nlogger.debug (nano::log::tag::bulk_pull_account_server, "Invalid bulk_pull_account flags supplied: {}", static_cast (request->flags)); invalid_request = true; - return; } @@ -729,23 +682,11 @@ void nano::bulk_pull_account_server::send_next_block () if (pending_address_only) { nano::vectorstream output_stream (send_buffer); - - if (node->config.logging.bulk_pull_logging ()) - { - node->logger.try_log (boost::str (boost::format ("Sending address: %1%") % block_info->source.to_string ())); - } - write (output_stream, block_info->source.bytes); } else { nano::vectorstream output_stream (send_buffer); - - if (node->config.logging.bulk_pull_logging ()) - { - node->logger.try_log (boost::str (boost::format ("Sending block: %1%") % block_info_key->hash.to_string ())); - } - write (output_stream, block_info_key->hash.bytes); write (output_stream, block_info->amount.bytes); @@ -768,10 +709,7 @@ void nano::bulk_pull_account_server::send_next_block () /* * Otherwise, finalize the connection */ - if (node->config.logging.bulk_pull_logging ()) - { - node->logger.try_log (boost::str (boost::format ("Done sending blocks"))); - } + node->nlogger.debug (nano::log::tag::bulk_pull_account_server, "Done sending blocks"); send_finished (); } @@ -876,10 +814,7 @@ void nano::bulk_pull_account_server::sent_action (boost::system::error_code cons } else { - if (node->config.logging.bulk_pull_logging ()) - { - node->logger.try_log (boost::str (boost::format ("Unable to bulk send block: %1%") % ec.message ())); - } + node->nlogger.debug (nano::log::tag::bulk_pull_account_server, "Unable to bulk send block: {}", ec.message ()); } } @@ -916,13 +851,9 @@ void nano::bulk_pull_account_server::send_finished () } } - auto this_l (shared_from_this ()); - - if (node->config.logging.bulk_pull_logging ()) - { - node->logger.try_log ("Bulk sending for an account finished"); - } + node->nlogger.debug (nano::log::tag::bulk_pull_account_server, "Bulk sending for an account finished"); + auto this_l (shared_from_this ()); connection->socket->async_write (nano::shared_const_buffer (std::move (send_buffer)), [this_l] (boost::system::error_code const & ec, std::size_t size_a) { this_l->complete (ec, size_a); }); @@ -957,10 +888,7 @@ void nano::bulk_pull_account_server::complete (boost::system::error_code const & } else { - if (node->config.logging.bulk_pull_logging ()) - { - node->logger.try_log ("Unable to pending-as-zero"); - } + node->nlogger.debug (nano::log::tag::bulk_pull_account_server, "Unable to pending-as-zero: {}", ec.message ()); } } diff --git a/nano/node/bootstrap/bootstrap_bulk_push.cpp b/nano/node/bootstrap/bootstrap_bulk_push.cpp index dd1fc76f3c..124182d887 100644 --- a/nano/node/bootstrap/bootstrap_bulk_push.cpp +++ b/nano/node/bootstrap/bootstrap_bulk_push.cpp @@ -38,10 +38,7 @@ void nano::bulk_push_client::start () } else { - if (node->config.logging.bulk_pull_logging ()) - { - node->logger.try_log (boost::str (boost::format ("Unable to send bulk_push request: %1%") % ec.message ())); - } + node->nlogger.debug (nano::log::tag::bulk_push_client, "Unable to send bulk push request: {}", ec.message ()); } }, nano::transport::buffer_drop_policy::no_limiter_drop); @@ -71,10 +68,7 @@ void nano::bulk_push_client::push () } else { - if (node->config.logging.bulk_pull_logging ()) - { - node->logger.try_log ("Bulk pushing range ", current_target.first.to_string (), " down to ", current_target.second.to_string ()); - } + node->nlogger.debug (nano::log::tag::bulk_push_client, "Bulk pushing range: [{}:{}]", current_target.first.to_string (), current_target.second.to_string ()); } } } @@ -124,10 +118,7 @@ void nano::bulk_push_client::push_block (nano::block const & block_a) } else { - if (node->config.logging.bulk_pull_logging ()) - { - node->logger.try_log (boost::str (boost::format ("Error sending block during bulk push: %1%") % ec.message ())); - } + node->nlogger.debug (nano::log::tag::bulk_push_client, "Error sending block during bulk push: {}", ec.message ()); } }); } @@ -171,10 +162,7 @@ void nano::bulk_push_server::receive () } if (node->bootstrap_initiator.in_progress ()) { - if (node->config.logging.bulk_pull_logging ()) - { - node->logger.try_log ("Aborting bulk_push because a bootstrap attempt is in progress"); - } + node->nlogger.debug (nano::log::tag::bulk_push_server, "Aborting bulk push because a bootstrap attempt is in progress"); } else { @@ -191,10 +179,7 @@ void nano::bulk_push_server::receive () } else { - if (node->config.logging.bulk_pull_logging ()) - { - node->logger.try_log (boost::str (boost::format ("Error receiving block type: %1%") % ec.message ())); - } + node->nlogger.debug (nano::log::tag::bulk_push_server, "Error receiving block type: {}", ec.message ()); } }); } @@ -258,10 +243,7 @@ void nano::bulk_push_server::received_type () } default: { - if (node->config.logging.network_packet_logging ()) - { - node->logger.try_log ("Unknown type received as block type"); - } + node->nlogger.debug (nano::log::tag::bulk_push_server, "Unknown type received as block type"); break; } } @@ -282,11 +264,8 @@ void nano::bulk_push_server::received_block (boost::system::error_code const & e { if (node->network_params.work.validate_entry (*block)) { - if (node->config.logging.bulk_pull_logging ()) - { - node->logger.try_log (boost::str (boost::format ("Insufficient work for bulk push block: %1%") % block->hash ().to_string ())); - } - node->stats.inc_detail_only (nano::stat::type::error, nano::stat::detail::insufficient_work); + node->nlogger.debug (nano::log::tag::bulk_push_server, "Insufficient work for bulk push block: {}", block->hash ().to_string ()); + node->stats.inc (nano::stat::type::error, nano::stat::detail::insufficient_work); return; } node->process_active (std::move (block)); @@ -294,10 +273,7 @@ void nano::bulk_push_server::received_block (boost::system::error_code const & e } else { - if (node->config.logging.bulk_pull_logging ()) - { - node->logger.try_log ("Error deserializing block received from pull request"); - } + node->nlogger.debug (nano::log::tag::bulk_push_server, "Error deserializing block received from pull request"); } } } diff --git a/nano/node/bootstrap/bootstrap_connections.cpp b/nano/node/bootstrap/bootstrap_connections.cpp index 21f86262bf..b589871791 100644 --- a/nano/node/bootstrap/bootstrap_connections.cpp +++ b/nano/node/bootstrap/bootstrap_connections.cpp @@ -91,7 +91,8 @@ std::shared_ptr nano::bootstrap_connections::connection } if (result == nullptr && connections_count == 0 && new_connections_empty && attempt_a != nullptr) { - node.logger.try_log (boost::str (boost::format ("Bootstrap attempt stopped because there are no peers"))); + node.nlogger.debug (nano::log::tag::bootstrap, "Bootstrap attempt stopped because there are no peers"); + lock.unlock (); attempt_a->stop (); } @@ -157,10 +158,8 @@ void nano::bootstrap_connections::connect_client (nano::tcp_endpoint const & end [this_l, socket, endpoint_a, push_front] (boost::system::error_code const & ec) { if (!ec) { - if (this_l->node.config.logging.bulk_pull_logging ()) - { - this_l->node.logger.try_log (boost::str (boost::format ("Connection established to %1%") % endpoint_a)); - } + this_l->node.nlogger.debug (nano::log::tag::bootstrap, "Connection established to: {}", nano::util::to_str (endpoint_a)); + auto client (std::make_shared (this_l->node.shared (), std::make_shared (*this_l->node.shared (), socket), socket)); this_l->pool_connection (client, true, push_front); } @@ -171,7 +170,7 @@ void nano::bootstrap_connections::connect_client (nano::tcp_endpoint const & end switch (ec.value ()) { default: - this_l->node.logger.try_log (boost::str (boost::format ("Error initiating bootstrap connection to %1%: %2%") % endpoint_a % ec.message ())); + this_l->node.nlogger.debug (nano::log::tag::bootstrap, "Error initiating bootstrap connection to: {} ({})", nano::util::to_str (endpoint_a), ec.message ()); break; case boost::system::errc::connection_refused: case boost::system::errc::operation_canceled: @@ -236,10 +235,12 @@ void nano::bootstrap_connections::populate_connections (bool repeat) // This is ~1.5kilobits/sec. if (elapsed_sec > nano::bootstrap_limits::bootstrap_minimum_termination_time_sec && blocks_per_sec < nano::bootstrap_limits::bootstrap_minimum_blocks_per_sec) { - if (node.config.logging.bulk_pull_logging ()) - { - node.logger.try_log (boost::str (boost::format ("Stopping slow peer %1% (elapsed sec %2%s > %3%s and %4% blocks per second < %5%)") % client->channel->to_string () % elapsed_sec % nano::bootstrap_limits::bootstrap_minimum_termination_time_sec % blocks_per_sec % nano::bootstrap_limits::bootstrap_minimum_blocks_per_sec)); - } + node.nlogger.debug (nano::log::tag::bootstrap, "Stopping slow peer {} (elapsed sec {} > {} and {} blocks per second < {})", + client->channel->to_string (), + elapsed_sec, + nano::bootstrap_limits::bootstrap_minimum_termination_time_sec, + blocks_per_sec, + nano::bootstrap_limits::bootstrap_minimum_blocks_per_sec); client->stop (true); new_clients.pop_back (); @@ -259,29 +260,27 @@ void nano::bootstrap_connections::populate_connections (bool repeat) // 4 -> 1, 8 -> 2, 16 -> 4, arbitrary, but seems to work well. auto drop = (int)roundf (sqrtf ((float)target - 2.0f)); - if (node.config.logging.bulk_pull_logging ()) - { - node.logger.try_log (boost::str (boost::format ("Dropping %1% bulk pull peers, target connections %2%") % drop % target)); - } + node.nlogger.debug (nano::log::tag::bootstrap, "Dropping {} bulk pull peers, target connections {}", drop, target); for (int i = 0; i < drop; i++) { auto client = sorted_connections.top (); - if (node.config.logging.bulk_pull_logging ()) - { - node.logger.try_log (boost::str (boost::format ("Dropping peer with block rate %1%, block count %2% (%3%) ") % client->block_rate % client->block_count % client->channel->to_string ())); - } + node.nlogger.debug (nano::log::tag::bootstrap, "Dropping peer with block rate {} and block count {} ({})", + client->block_rate.load (), + client->block_count.load (), + client->channel->to_string ()); client->stop (false); sorted_connections.pop (); } } - if (node.config.logging.bulk_pull_logging ()) - { - node.logger.try_log (boost::str (boost::format ("Bulk pull connections: %1%, rate: %2% blocks/sec, bootstrap attempts %3%, remaining pulls: %4%") % connections_count.load () % (int)rate_sum % attempts_count % num_pulls)); - } + node.nlogger.debug (nano::log::tag::bootstrap, "Bulk pull connections: {}, rate: {} blocks/sec, bootstrap attempts {}, remaining pulls: {}", + connections_count.load (), + (int)rate_sum, + attempts_count, + num_pulls); if (connections_count < target && (attempts_count != 0 || new_connections_empty) && !stopped) { @@ -423,11 +422,13 @@ void nano::bootstrap_connections::requeue_pull (nano::pull_info const & pull_a, } else { - if (node.config.logging.bulk_pull_logging ()) - { - node.logger.try_log (boost::str (boost::format ("Failed to pull account %1% or head block %2% down to %3% after %4% attempts and %5% blocks processed") % pull.account_or_head.to_account () % pull.account_or_head.to_string () % pull.end.to_string () % pull.attempts % pull.processed)); - } node.stats.inc (nano::stat::type::bootstrap, nano::stat::detail::bulk_pull_failed_account, nano::stat::dir::in); + node.nlogger.debug (nano::log::tag::bootstrap, "Failed to pull account {} or head block {} down to {} after {} attempts and {} blocks processed", + pull.account_or_head.to_account (), + pull.account_or_head.to_string (), + pull.end.to_string (), + pull.attempts, + pull.processed); if (lazy && pull.processed > 0) { diff --git a/nano/node/bootstrap/bootstrap_frontier.cpp b/nano/node/bootstrap/bootstrap_frontier.cpp index 6b8766fc24..c12045cf02 100644 --- a/nano/node/bootstrap/bootstrap_frontier.cpp +++ b/nano/node/bootstrap/bootstrap_frontier.cpp @@ -42,10 +42,7 @@ void nano::frontier_req_client::run (nano::account const & start_account_a, uint } else { - if (node->config.logging.network_logging ()) - { - node->logger.try_log (boost::str (boost::format ("Error while sending bootstrap request %1%") % ec.message ())); - } + node->nlogger.debug (nano::log::tag::frontier_req_client, "Error while sending bootstrap request: {}", ec.message ()); } }, nano::transport::buffer_drop_policy::no_limiter_drop); @@ -76,10 +73,7 @@ void nano::frontier_req_client::receive_frontier () } else { - if (node->config.logging.network_message_logging ()) - { - node->logger.try_log (boost::str (boost::format ("Invalid size: expected %1%, got %2%") % nano::frontier_req_client::size_frontier % size_a)); - } + node->nlogger.debug (nano::log::tag::frontier_req_client, "Invalid size: expected {}, got {}", nano::frontier_req_client::size_frontier, size_a); } }); } @@ -137,14 +131,17 @@ void nano::frontier_req_client::received_frontier (boost::system::error_code con double age_factor = (frontiers_age == std::numeric_limits::max ()) ? 1.0 : 1.5; // Allow slower frontiers receive for requests with age if (elapsed_sec > nano::bootstrap_limits::bootstrap_connection_warmup_time_sec && blocks_per_sec * age_factor < nano::bootstrap_limits::bootstrap_minimum_frontier_blocks_per_sec) { - node->logger.try_log (boost::str (boost::format ("Aborting frontier req because it was too slow: %1% frontiers per second, last %2%") % blocks_per_sec % account.to_account ())); + node->nlogger.debug (nano::log::tag::frontier_req_client, "Aborting frontier req because it was too slow: {} frontiers per second, last {}", blocks_per_sec, account.to_account ()); + promise.set_value (true); return; } + if (attempt->should_log ()) { - node->logger.always_log (boost::str (boost::format ("Received %1% frontiers from %2%") % std::to_string (count) % connection->channel->to_string ())); + node->nlogger.debug (nano::log::tag::frontier_req_client, "Received {} frontiers from {}", count, connection->channel->to_string ()); } + if (!account.is_zero () && count <= count_limit) { last_account = account; @@ -203,10 +200,8 @@ void nano::frontier_req_client::received_frontier (boost::system::error_code con } // Prevent new frontier_req requests attempt->set_start_account (std::numeric_limits::max ()); - if (node->config.logging.bulk_pull_logging ()) - { - node->logger.try_log ("Bulk push cost: ", bulk_push_cost); - } + + node->nlogger.debug (nano::log::tag::frontier_req_client, "Bulk push cost: {}", bulk_push_cost); } else { @@ -225,10 +220,7 @@ void nano::frontier_req_client::received_frontier (boost::system::error_code con } else { - if (node->config.logging.network_logging ()) - { - node->logger.try_log (boost::str (boost::format ("Error while receiving frontier %1%") % ec.message ())); - } + node->nlogger.debug (nano::log::tag::frontier_req_client, "Error while receiving frontier: {}", ec.message ()); } } @@ -291,11 +283,8 @@ void nano::frontier_req_server::send_next () debug_assert (!current.is_zero ()); debug_assert (!frontier.is_zero ()); } + auto this_l (shared_from_this ()); - if (node->config.logging.bulk_pull_logging ()) - { - node->logger.try_log (boost::str (boost::format ("Sending frontier for %1% %2%") % current.to_account () % frontier.to_string ())); - } next (); connection->socket->async_write (nano::shared_const_buffer (std::move (send_buffer)), [this_l] (boost::system::error_code const & ec, std::size_t size_a) { this_l->sent_action (ec, size_a); @@ -321,11 +310,10 @@ void nano::frontier_req_server::send_finished () write (stream, zero.bytes); write (stream, zero.bytes); } + + node->nlogger.debug (nano::log::tag::frontier_req_server, "Frontier sending finished"); + auto this_l (shared_from_this ()); - if (node->config.logging.network_logging ()) - { - node->logger.try_log ("Frontier sending finished"); - } connection->socket->async_write (nano::shared_const_buffer (std::move (send_buffer)), [this_l] (boost::system::error_code const & ec, std::size_t size_a) { this_l->no_block_sent (ec, size_a); }); @@ -344,10 +332,7 @@ void nano::frontier_req_server::no_block_sent (boost::system::error_code const & } else { - if (node->config.logging.network_logging ()) - { - node->logger.try_log (boost::str (boost::format ("Error sending frontier finish: %1%") % ec.message ())); - } + node->nlogger.debug (nano::log::tag::frontier_req_server, "Error sending frontier finish: {}", ec.message ()); } } @@ -368,10 +353,7 @@ void nano::frontier_req_server::sent_action (boost::system::error_code const & e } else { - if (node->config.logging.network_logging ()) - { - node->logger.try_log (boost::str (boost::format ("Error sending frontier pair: %1%") % ec.message ())); - } + node->nlogger.debug (nano::log::tag::frontier_req_server, "Error sending frontier pair: {}", ec.message ()); } } diff --git a/nano/node/bootstrap/bootstrap_lazy.cpp b/nano/node/bootstrap/bootstrap_lazy.cpp index 28e5cf6ad0..96d94736ca 100644 --- a/nano/node/bootstrap/bootstrap_lazy.cpp +++ b/nano/node/bootstrap/bootstrap_lazy.cpp @@ -250,11 +250,11 @@ void nano::bootstrap_attempt_lazy::run () } if (!stopped) { - node->logger.try_log ("Completed lazy pulls"); + node->nlogger.debug (nano::log::tag::bootstrap_lazy, "Completed lazy pulls"); } if (lazy_has_expired ()) { - node->logger.try_log (boost::str (boost::format ("Lazy bootstrap attempt ID %1% expired") % id)); + node->nlogger.debug (nano::log::tag::bootstrap_lazy, "Lazy bootstrap attempt ID {} expired", id); } lock.unlock (); stop (); @@ -613,7 +613,7 @@ void nano::bootstrap_attempt_wallet::run () } if (!stopped) { - node->logger.try_log ("Completed wallet lazy pulls"); + node->nlogger.info (nano::log::tag::bootstrap_lazy, "Completed wallet lazy pulls"); } lock.unlock (); stop (); diff --git a/nano/node/bootstrap/bootstrap_legacy.cpp b/nano/node/bootstrap/bootstrap_legacy.cpp index 481d6df85b..075c6aa5e8 100644 --- a/nano/node/bootstrap/bootstrap_legacy.cpp +++ b/nano/node/bootstrap/bootstrap_legacy.cpp @@ -88,14 +88,6 @@ void nano::bootstrap_attempt_legacy::request_push (nano::unique_lockconfig.logging.network_logging ()) - { - node->logger.try_log ("Exiting bulk push client"); - if (error) - { - node->logger.try_log ("Bulk push client failed"); - } - } } void nano::bootstrap_attempt_legacy::add_frontier (nano::pull_info const & pull_a) @@ -186,16 +178,13 @@ bool nano::bootstrap_attempt_legacy::request_frontier (nano::unique_lockconfig.logging.network_logging ()) + if (!result) { - if (!result) - { - node->logger.try_log (boost::str (boost::format ("Completed frontier request, %1% out of sync accounts according to %2%") % account_count % connection_l->channel->to_string ())); - } - else - { - node->stats.inc (nano::stat::type::error, nano::stat::detail::frontier_req, nano::stat::dir::out); - } + node->nlogger.debug (nano::log::tag::bootstrap_legacy, "Completed frontier request, {} out of sync accounts according to {}", account_count.load (), connection_l->channel->to_string ()); + } + else + { + node->stats.inc (nano::stat::type::error, nano::stat::detail::frontier_req, nano::stat::dir::out); } } return result; @@ -233,25 +222,24 @@ void nano::bootstrap_attempt_legacy::run () // clang-format off condition.wait (lock, [&stopped = stopped, &pulling = pulling] { return stopped || pulling == 0; }); } + // Flushing may resolve forks which can add more pulls - node->logger.try_log ("Flushing unchecked blocks"); lock.unlock (); node->block_processor.flush (); lock.lock (); + if (start_account.number () != std::numeric_limits::max ()) { - node->logger.try_log (boost::str (boost::format ("Finished flushing unchecked blocks, requesting new frontiers after %1%") % start_account.to_account ())); + node->nlogger.debug(nano::log::tag::bootstrap_legacy, "Requesting new frontiers after: {}", start_account.to_account ()); + // Requesting new frontiers run_start (lock); } - else - { - node->logger.try_log ("Finished flushing unchecked blocks"); - } } if (!stopped) { - node->logger.try_log ("Completed legacy pulls"); + node->nlogger.debug(nano::log::tag::bootstrap_legacy, "Completed legacy pulls"); + if (!node->flags.disable_bootstrap_bulk_push_client) { request_push (lock); diff --git a/nano/node/cli.cpp b/nano/node/cli.cpp index 721edd67ff..431f7b397f 100644 --- a/nano/node/cli.cpp +++ b/nano/node/cli.cpp @@ -254,6 +254,8 @@ std::error_code nano::handle_node_options (boost::program_options::variables_map if (vm.count ("initialize")) { + nano::initialize_logging (nano::log::preset::daemon); + auto node_flags = nano::inactive_node_flag_defaults (); node_flags.read_only = false; nano::update_flags (node_flags, vm); @@ -730,7 +732,7 @@ std::error_code nano::handle_node_options (boost::program_options::variables_map environment.dump (std::cout); std::stringstream stream; environment.dump (stream); - inactive_node->node->logger.always_log (stream.str ()); + std::cout << stream.str () << std::endl; } else { diff --git a/nano/node/confirmation_height_bounded.cpp b/nano/node/confirmation_height_bounded.cpp index a2301f891d..9476d2c321 100644 --- a/nano/node/confirmation_height_bounded.cpp +++ b/nano/node/confirmation_height_bounded.cpp @@ -12,12 +12,11 @@ #include -nano::confirmation_height_bounded::confirmation_height_bounded (nano::ledger & ledger_a, nano::write_database_queue & write_database_queue_a, std::chrono::milliseconds batch_separate_pending_min_time_a, nano::logging const & logging_a, nano::logger_mt & logger_a, std::atomic & stopped_a, uint64_t & batch_write_size_a, std::function> const &)> const & notify_observers_callback_a, std::function const & notify_block_already_cemented_observers_callback_a, std::function const & awaiting_processing_size_callback_a) : +nano::confirmation_height_bounded::confirmation_height_bounded (nano::ledger & ledger_a, nano::write_database_queue & write_database_queue_a, std::chrono::milliseconds batch_separate_pending_min_time_a, nano::nlogger & nlogger_a, std::atomic & stopped_a, uint64_t & batch_write_size_a, std::function> const &)> const & notify_observers_callback_a, std::function const & notify_block_already_cemented_observers_callback_a, std::function const & awaiting_processing_size_callback_a) : ledger (ledger_a), write_database_queue (write_database_queue_a), batch_separate_pending_min_time (batch_separate_pending_min_time_a), - logging (logging_a), - logger (logger_a), + nlogger (nlogger_a), stopped (stopped_a), batch_write_size (batch_write_size_a), notify_observers_callback (notify_observers_callback_a), @@ -101,9 +100,8 @@ void nano::confirmation_height_bounded::process (std::shared_ptr or } else { - auto error_str = (boost::format ("Ledger mismatch trying to set confirmation height for block %1% (bounded processor)") % current.to_string ()).str (); - logger.always_log (error_str); - std::cerr << error_str << std::endl; + nlogger.critical (nano::log::tag::conf_processor_bounded, "Ledger mismatch trying to set confirmation height for block {} (bounded processor)", current.to_string ()); + release_assert (block); } } @@ -433,9 +431,8 @@ void nano::confirmation_height_bounded::cement_blocks (nano::write_guard & scope { if (!block) { - auto error_str = (boost::format ("Failed to write confirmation height for block %1% (bounded processor)") % new_cemented_frontier.to_string ()).str (); - logger.always_log (error_str); - std::cerr << error_str << std::endl; + nlogger.critical (nano::log::tag::conf_processor_bounded, "Failed to write confirmation height for block {} (bounded processor)", new_cemented_frontier.to_string ()); + // Undo any blocks about to be cemented from this account for this pending write. cemented_blocks.erase (cemented_blocks.end () - num_blocks_iterated, cemented_blocks.end ()); error = true; @@ -455,10 +452,6 @@ void nano::confirmation_height_bounded::cement_blocks (nano::write_guard & scope total_blocks_cemented += num_blocks_cemented; write_confirmation_height (num_blocks_cemented, start_height + total_blocks_cemented - 1, new_cemented_frontier); transaction.commit (); - if (logging.timing_logging ()) - { - logger.always_log (boost::str (boost::format ("Cemented %1% blocks in %2% %3% (bounded processor)") % cemented_blocks.size () % time_spent_cementing % cemented_batch_timer.unit ())); - } // Update the maximum amount of blocks to write next time based on the time it took to cement this batch. if (time_spent_cementing > maximum_batch_write_time) @@ -521,11 +514,8 @@ void nano::confirmation_height_bounded::cement_blocks (nano::write_guard & scope --pending_writes_size; } } - auto time_spent_cementing = cemented_batch_timer.since_start ().count (); - if (logging.timing_logging () && time_spent_cementing > 50) - { - logger.always_log (boost::str (boost::format ("Cemented %1% blocks in %2% %3% (bounded processor)") % cemented_blocks.size () % time_spent_cementing % cemented_batch_timer.unit ())); - } + + auto time_spent_cementing = cemented_batch_timer.since_start (); // Scope guard could have been released earlier (0 cemented_blocks would indicate that) if (scoped_write_guard_a.is_owned () && !cemented_blocks.empty ()) @@ -537,7 +527,8 @@ void nano::confirmation_height_bounded::cement_blocks (nano::write_guard & scope // Bail if there was an error. This indicates that there was a fatal issue with the ledger // (the blocks probably got rolled back when they shouldn't have). release_assert (!error); - if (time_spent_cementing > maximum_batch_write_time) + + if (time_spent_cementing.count () > maximum_batch_write_time) { // Reduce (unless we have hit a floor) batch_write_size = std::max (minimum_batch_write_size, batch_write_size - amount_to_change); diff --git a/nano/node/confirmation_height_bounded.hpp b/nano/node/confirmation_height_bounded.hpp index c176b41686..c42cd61397 100644 --- a/nano/node/confirmation_height_bounded.hpp +++ b/nano/node/confirmation_height_bounded.hpp @@ -1,5 +1,6 @@ #pragma once +#include #include #include #include @@ -19,7 +20,8 @@ class write_guard; class confirmation_height_bounded final { public: - confirmation_height_bounded (nano::ledger &, nano::write_database_queue &, std::chrono::milliseconds batch_separate_pending_min_time, nano::logging const &, nano::logger_mt &, std::atomic & stopped, uint64_t & batch_write_size, std::function> const &)> const & cemented_callback, std::function const & already_cemented_callback, std::function const & awaiting_processing_size_query); + confirmation_height_bounded (nano::ledger &, nano::write_database_queue &, std::chrono::milliseconds batch_separate_pending_min_time, nano::nlogger &, std::atomic & stopped, uint64_t & batch_write_size, std::function> const &)> const & cemented_callback, std::function const & already_cemented_callback, std::function const & awaiting_processing_size_query); + bool pending_empty () const; void clear_process_vars (); void process (std::shared_ptr original_block); @@ -121,8 +123,7 @@ class confirmation_height_bounded final nano::ledger & ledger; nano::write_database_queue & write_database_queue; std::chrono::milliseconds batch_separate_pending_min_time; - nano::logging const & logging; - nano::logger_mt & logger; + nano::nlogger & nlogger; std::atomic & stopped; uint64_t & batch_write_size; std::function> const &)> notify_observers_callback; diff --git a/nano/node/confirmation_height_processor.cpp b/nano/node/confirmation_height_processor.cpp index 6cf9772999..6e937c54c1 100644 --- a/nano/node/confirmation_height_processor.cpp +++ b/nano/node/confirmation_height_processor.cpp @@ -9,16 +9,16 @@ #include -nano::confirmation_height_processor::confirmation_height_processor (nano::ledger & ledger_a, nano::write_database_queue & write_database_queue_a, std::chrono::milliseconds batch_separate_pending_min_time_a, nano::logging const & logging_a, nano::logger_mt & logger_a, boost::latch & latch, confirmation_height_mode mode_a) : +nano::confirmation_height_processor::confirmation_height_processor (nano::ledger & ledger_a, nano::write_database_queue & write_database_queue_a, std::chrono::milliseconds batch_separate_pending_min_time_a, nano::nlogger & nlogger_a, boost::latch & latch, confirmation_height_mode mode_a) : ledger (ledger_a), write_database_queue (write_database_queue_a), unbounded_processor ( - ledger_a, write_database_queue_a, batch_separate_pending_min_time_a, logging_a, logger_a, stopped, batch_write_size, + ledger_a, write_database_queue_a, batch_separate_pending_min_time_a, nlogger_a, stopped, batch_write_size, /* cemented_callback */ [this] (auto & cemented_blocks) { this->notify_cemented (cemented_blocks); }, /* already cemented_callback */ [this] (auto const & block_hash_a) { this->notify_already_cemented (block_hash_a); }, /* awaiting_processing_size_query */ [this] () { return this->awaiting_processing_size (); }), bounded_processor ( - ledger_a, write_database_queue_a, batch_separate_pending_min_time_a, logging_a, logger_a, stopped, batch_write_size, + ledger_a, write_database_queue_a, batch_separate_pending_min_time_a, nlogger_a, stopped, batch_write_size, /* cemented_callback */ [this] (auto & cemented_blocks) { this->notify_cemented (cemented_blocks); }, /* already cemented_callback */ [this] (auto const & block_hash_a) { this->notify_already_cemented (block_hash_a); }, /* awaiting_processing_size_query */ [this] () { return this->awaiting_processing_size (); }), diff --git a/nano/node/confirmation_height_processor.hpp b/nano/node/confirmation_height_processor.hpp index 88f2d1a15b..1767f82106 100644 --- a/nano/node/confirmation_height_processor.hpp +++ b/nano/node/confirmation_height_processor.hpp @@ -1,5 +1,6 @@ #pragma once +#include #include #include #include @@ -24,14 +25,14 @@ class latch; namespace nano { class ledger; -class logger_mt; class write_database_queue; class confirmation_height_processor final { public: - confirmation_height_processor (nano::ledger &, nano::write_database_queue &, std::chrono::milliseconds, nano::logging const &, nano::logger_mt &, boost::latch & initialized_latch, confirmation_height_mode = confirmation_height_mode::automatic); + confirmation_height_processor (nano::ledger &, nano::write_database_queue &, std::chrono::milliseconds, nano::nlogger &, boost::latch & initialized_latch, confirmation_height_mode = confirmation_height_mode::automatic); ~confirmation_height_processor (); + void pause (); void unpause (); void stop (); diff --git a/nano/node/confirmation_height_unbounded.cpp b/nano/node/confirmation_height_unbounded.cpp index 9a458b9c8c..4168f767e6 100644 --- a/nano/node/confirmation_height_unbounded.cpp +++ b/nano/node/confirmation_height_unbounded.cpp @@ -12,12 +12,11 @@ #include -nano::confirmation_height_unbounded::confirmation_height_unbounded (nano::ledger & ledger_a, nano::write_database_queue & write_database_queue_a, std::chrono::milliseconds batch_separate_pending_min_time_a, nano::logging const & logging_a, nano::logger_mt & logger_a, std::atomic & stopped_a, uint64_t & batch_write_size_a, std::function> const &)> const & notify_observers_callback_a, std::function const & notify_block_already_cemented_observers_callback_a, std::function const & awaiting_processing_size_callback_a) : +nano::confirmation_height_unbounded::confirmation_height_unbounded (nano::ledger & ledger_a, nano::write_database_queue & write_database_queue_a, std::chrono::milliseconds batch_separate_pending_min_time_a, nano::nlogger & nlogger_a, std::atomic & stopped_a, uint64_t & batch_write_size_a, std::function> const &)> const & notify_observers_callback_a, std::function const & notify_block_already_cemented_observers_callback_a, std::function const & awaiting_processing_size_callback_a) : ledger (ledger_a), write_database_queue (write_database_queue_a), batch_separate_pending_min_time (batch_separate_pending_min_time_a), - logging (logging_a), - logger (logger_a), + nlogger (nlogger_a), stopped (stopped_a), batch_write_size (batch_write_size_a), notify_observers_callback (notify_observers_callback_a), @@ -77,9 +76,7 @@ void nano::confirmation_height_unbounded::process (std::shared_ptr } if (!block) { - auto error_str = (boost::format ("Ledger mismatch trying to set confirmation height for block %1% (unbounded processor)") % current.to_string ()).str (); - logger.always_log (error_str); - std::cerr << error_str << std::endl; + nlogger.critical (nano::log::tag::conf_processor_unbounded, "Ledger mismatch trying to set confirmation height for block {} (unbounded processor)", current.to_string ()); } release_assert (block); @@ -395,9 +392,8 @@ void nano::confirmation_height_unbounded::cement_blocks (nano::write_guard & sco } else { - auto error_str = (boost::format ("Failed to write confirmation height for block %1% (unbounded processor)") % pending.hash.to_string ()).str (); - logger.always_log (error_str); - std::cerr << error_str << std::endl; + nlogger.critical (nano::log::tag::conf_processor_unbounded, "Failed to write confirmation height for block {} (unbounded processor)", pending.hash.to_string ()); + error = true; break; } @@ -424,10 +420,6 @@ void nano::confirmation_height_unbounded::cement_blocks (nano::write_guard & sco } auto time_spent_cementing = cemented_batch_timer.since_start ().count (); - if (logging.timing_logging () && time_spent_cementing > 50) - { - logger.always_log (boost::str (boost::format ("Cemented %1% blocks in %2% %3% (unbounded processor)") % cemented_blocks.size () % time_spent_cementing % cemented_batch_timer.unit ())); - } scoped_write_guard_a.release (); notify_observers_callback (cemented_blocks); diff --git a/nano/node/confirmation_height_unbounded.hpp b/nano/node/confirmation_height_unbounded.hpp index 0af353e69a..9bee338c4d 100644 --- a/nano/node/confirmation_height_unbounded.hpp +++ b/nano/node/confirmation_height_unbounded.hpp @@ -1,5 +1,6 @@ #pragma once +#include #include #include #include @@ -20,7 +21,8 @@ class write_guard; class confirmation_height_unbounded final { public: - confirmation_height_unbounded (nano::ledger &, nano::write_database_queue &, std::chrono::milliseconds batch_separate_pending_min_time, nano::logging const &, nano::logger_mt &, std::atomic & stopped, uint64_t & batch_write_size, std::function> const &)> const & cemented_callback, std::function const & already_cemented_callback, std::function const & awaiting_processing_size_query); + confirmation_height_unbounded (nano::ledger &, nano::write_database_queue &, std::chrono::milliseconds batch_separate_pending_min_time, nano::nlogger &, std::atomic & stopped, uint64_t & batch_write_size, std::function> const &)> const & cemented_callback, std::function const & already_cemented_callback, std::function const & awaiting_processing_size_query); + bool pending_empty () const; void clear_process_vars (); void process (std::shared_ptr original_block); @@ -98,10 +100,9 @@ class confirmation_height_unbounded final nano::ledger & ledger; nano::write_database_queue & write_database_queue; std::chrono::milliseconds batch_separate_pending_min_time; - nano::logger_mt & logger; + nano::nlogger & nlogger; std::atomic & stopped; uint64_t & batch_write_size; - nano::logging const & logging; std::function> const &)> notify_observers_callback; std::function notify_block_already_cemented_observers_callback; diff --git a/nano/node/distributed_work.cpp b/nano/node/distributed_work.cpp index b710c41552..ed755baaca 100644 --- a/nano/node/distributed_work.cpp +++ b/nano/node/distributed_work.cpp @@ -94,7 +94,8 @@ void nano::distributed_work::start () } else { - this_l->node.logger.try_log (boost::str (boost::format ("Error resolving work peer: %1%:%2%: %3%") % peer.first % peer.second % ec.message ())); + this_l->node.nlogger.error (nano::log::tag::distributed_work, "Error resolving work peer: {}:{} ({})", peer.first, peer.second, ec.message ()); + this_l->failure (); } }); @@ -166,7 +167,11 @@ void nano::distributed_work::do_request (nano::tcp_endpoint const & endpoint_a) } else if (ec) { - this_l->node.logger.try_log (boost::str (boost::format ("Work peer responded with an error %1% %2%: %3%") % connection->endpoint.address () % connection->endpoint.port () % connection->response.result ())); + this_l->node.nlogger.error (nano::log::tag::distributed_work, "Work peer responded with an error {}:{} ({})", + nano::util::to_str (connection->endpoint.address ()), + connection->endpoint.port (), + ec.message ()); + this_l->add_bad_peer (connection->endpoint); this_l->failure (); } @@ -180,7 +185,11 @@ void nano::distributed_work::do_request (nano::tcp_endpoint const & endpoint_a) } else if (ec && ec != boost::system::errc::operation_canceled) { - this_l->node.logger.try_log (boost::str (boost::format ("Unable to write to work_peer %1% %2%: %3% (%4%)") % connection->endpoint.address () % connection->endpoint.port () % ec.message () % ec.value ())); + this_l->node.nlogger.error (nano::log::tag::distributed_work, "Unable to write to work peer {}:{} ({})", + nano::util::to_str (connection->endpoint.address ()), + connection->endpoint.port (), + ec.message ()); + this_l->add_bad_peer (connection->endpoint); this_l->failure (); } @@ -188,7 +197,11 @@ void nano::distributed_work::do_request (nano::tcp_endpoint const & endpoint_a) } else if (ec && ec != boost::system::errc::operation_canceled) { - this_l->node.logger.try_log (boost::str (boost::format ("Unable to connect to work_peer %1% %2%: %3% (%4%)") % connection->endpoint.address () % connection->endpoint.port () % ec.message () % ec.value ())); + this_l->node.nlogger.error (nano::log::tag::distributed_work, "Unable to connect to work peer {}:{} ({})", + nano::util::to_str (connection->endpoint.address ()), + connection->endpoint.port (), + ec.message ()); + this_l->add_bad_peer (connection->endpoint); this_l->failure (); } @@ -219,7 +232,10 @@ void nano::distributed_work::do_cancel (nano::tcp_endpoint const & endpoint_a) [this_l, peer_cancel, cancelling_l] (boost::system::error_code const & ec, std::size_t bytes_transferred) { if (ec && ec != boost::system::errc::operation_canceled) { - this_l->node.logger.try_log (boost::str (boost::format ("Unable to send work_cancel to work_peer %1% %2%: %3% (%4%)") % cancelling_l->endpoint.address () % cancelling_l->endpoint.port () % ec.message () % ec.value ())); + this_l->node.nlogger.error (nano::log::tag::distributed_work, "Unable to send work cancel to work peer {}:{} ({})", + nano::util::to_str (cancelling_l->endpoint.address ()), + cancelling_l->endpoint.port (), + ec.message ()); } })); } @@ -247,17 +263,28 @@ void nano::distributed_work::success (std::string const & body_a, nano::tcp_endp } else { - node.logger.try_log (boost::str (boost::format ("Incorrect work response from %1%:%2% for root %3% with diffuculty %4%: %5%") % endpoint_a.address () % endpoint_a.port () % request.root.to_string () % nano::to_string_hex (request.difficulty) % work_text)); + node.nlogger.error (nano::log::tag::distributed_work, "Incorrect work response from {}:{} for root {} with diffuculty {}: {}", + nano::util::to_str (endpoint_a.address ()), + endpoint_a.port (), + request.root.to_string (), + nano::to_string_hex (request.difficulty), + work_text); } } else { - node.logger.try_log (boost::str (boost::format ("Work response from %1%:%2% wasn't a number: %3%") % endpoint_a.address () % endpoint_a.port () % work_text)); + node.nlogger.error (nano::log::tag::distributed_work, "Work response from {}:{} wasn't a number: {}", + nano::util::to_str (endpoint_a.address ()), + endpoint_a.port (), + work_text); } } catch (...) { - node.logger.try_log (boost::str (boost::format ("Work response from %1%:%2% wasn't parsable: %3%") % endpoint_a.address () % endpoint_a.port () % body_a)); + node.nlogger.error (nano::log::tag::distributed_work, "Work response from {}:{} wasn't parsable: {}", + nano::util::to_str (endpoint_a.address ()), + endpoint_a.port (), + body_a); } if (error) { @@ -290,12 +317,18 @@ void nano::distributed_work::stop_once (bool const local_stop_a) connection_l->socket.close (ec); if (ec) { - this_l->node.logger.try_log (boost::str (boost::format ("Error closing socket with work_peer %1% %2%: %3%") % connection_l->endpoint.address () % connection_l->endpoint.port () % ec.message () % ec.value ())); + this_l->node.nlogger.error (nano::log::tag::distributed_work, "Error closing socket with work peer: {}:{} ({})", + nano::util::to_str (connection_l->endpoint.address ()), + connection_l->endpoint.port (), + ec.message ()); } } else { - this_l->node.logger.try_log (boost::str (boost::format ("Error cancelling operation with work_peer %1% %2%: %3%") % connection_l->endpoint.address () % connection_l->endpoint.port () % ec.message () % ec.value ())); + this_l->node.nlogger.error (nano::log::tag::distributed_work, "Error cancelling operation with work peer: {}:{} ({})", + nano::util::to_str (connection_l->endpoint.address ()), + connection_l->endpoint.port (), + ec.message ()); } } })); @@ -310,6 +343,13 @@ void nano::distributed_work::set_once (uint64_t const work_a, std::string const if (!finished.exchange (true)) { elapsed.stop (); + + node.nlogger.info (nano::log::tag::distributed_work, "Work generation for {}, with a threshold difficulty of {} (multiplier {}x) complete: {} ms", + request.root.to_string (), + nano::to_string_hex (request.difficulty), + nano::to_string (nano::difficulty::to_multiplier (request.difficulty, node.default_difficulty (request.version)), 2), + elapsed.value ().count ()); + status = work_generation_status::success; if (request.callback) { @@ -317,12 +357,6 @@ void nano::distributed_work::set_once (uint64_t const work_a, std::string const } winner = source_a; work_result = work_a; - if (node.config.logging.work_generation_time ()) - { - boost::format unformatted_l ("Work generation for %1%, with a threshold difficulty of %2% (multiplier %3%x) complete: %4% ms"); - auto multiplier_text_l (nano::to_string (nano::difficulty::to_multiplier (request.difficulty, node.default_difficulty (request.version)), 2)); - node.logger.try_log (boost::str (unformatted_l % request.root.to_string () % nano::to_string_hex (request.difficulty) % multiplier_text_l % elapsed.value ().count ())); - } } } @@ -331,16 +365,17 @@ void nano::distributed_work::cancel () if (!finished.exchange (true)) { elapsed.stop (); + + node.nlogger.info (nano::log::tag::distributed_work, "Work generation for {} was cancelled after {} ms", + request.root.to_string (), + elapsed.value ().count ()); + status = work_generation_status::cancelled; if (request.callback) { request.callback (boost::none); } stop_once (true); - if (node.config.logging.work_generation_time ()) - { - node.logger.try_log (boost::str (boost::format ("Work generation for %1% was cancelled after %2% ms") % request.root.to_string () % elapsed.value ().count ())); - } } } @@ -359,11 +394,12 @@ void nano::distributed_work::handle_failure () node.unresponsive_work_peers = true; if (!local_generation_started && !finished.exchange (true)) { + node.nlogger.info (nano::log::tag::distributed_work, "Work peer(s) failed to generate work for root {}, retrying... (backoff: {}s)", + request.root.to_string (), + backoff.count ()); + status = work_generation_status::failure_peers; - if (backoff == std::chrono::seconds (1) && node.config.logging.work_generation_time ()) - { - node.logger.always_log ("Work peer(s) failed to generate work for root ", request.root.to_string (), ", retrying..."); - } + auto now (std::chrono::steady_clock::now ()); std::weak_ptr node_weak (node.shared ()); auto next_backoff (std::min (backoff * 2, std::chrono::seconds (5 * 60))); diff --git a/nano/node/election.cpp b/nano/node/election.cpp index ae477559f0..b92a11d6f8 100644 --- a/nano/node/election.cpp +++ b/nano/node/election.cpp @@ -240,10 +240,6 @@ bool nano::election::transition_time (nano::confirmation_solicitor & solicitor_a if (!state_change (state_m.load (), nano::election::state_t::expired_unconfirmed)) { result = true; // Return true to indicate this election should be cleaned up - if (node.config.logging.election_expiration_tally_logging ()) - { - log_votes (tally_impl (), "Election expired: "); - } status.type = nano::election_status_type::stopped; } } @@ -365,10 +361,6 @@ void nano::election::confirm_if_quorum (nano::unique_lock & lock_a) } if (!node.ledger.cache.final_votes_confirmation_canary.load () || final_weight >= node.online_reps.delta ()) { - if (node.config.logging.vote_logging () || (node.config.logging.election_fork_tally_logging () && last_blocks.size () > 1)) - { - log_votes (tally_l); - } confirm_once (lock_a, nano::election_status_type::active_confirmed_quorum); } } @@ -409,25 +401,6 @@ nano::election_status nano::election::set_status_type (nano::election_status_typ return status_l; } -void nano::election::log_votes (nano::tally_t const & tally_a, std::string const & prefix_a) const -{ - std::stringstream tally; - std::string line_end (node.config.logging.single_line_record () ? "\t" : "\n"); - tally << boost::str (boost::format ("%1%%2%Vote tally for root %3%, final weight:%4%") % prefix_a % line_end % root.to_string () % final_weight); - for (auto i (tally_a.begin ()), n (tally_a.end ()); i != n; ++i) - { - tally << boost::str (boost::format ("%1%Block %2% weight %3%") % line_end % i->second->hash ().to_string () % i->first.convert_to ()); - } - for (auto i (last_votes.begin ()), n (last_votes.end ()); i != n; ++i) - { - if (i->first != nullptr) - { - tally << boost::str (boost::format ("%1%%2% %3% %4%") % line_end % i->first.to_account () % std::to_string (i->second.timestamp) % i->second.hash.to_string ()); - } - } - node.logger.try_log (tally.str ()); -} - std::shared_ptr nano::election::find (nano::block_hash const & hash_a) const { std::shared_ptr result; diff --git a/nano/node/election.hpp b/nano/node/election.hpp index b28337dacf..3468ac7a50 100644 --- a/nano/node/election.hpp +++ b/nano/node/election.hpp @@ -1,5 +1,6 @@ #pragma once +#include #include #include #include @@ -63,6 +64,9 @@ enum class election_behavior nano::stat::detail to_stat_detail (nano::election_behavior); +// map of vote weight per block, ordered greater first +using tally_t = std::map, std::greater>; + struct election_extended_status final { nano::election_status status; @@ -122,7 +126,6 @@ class election final : public std::enable_shared_from_this std::shared_ptr winner () const; std::atomic confirmation_request_count{ 0 }; - void log_votes (nano::tally_t const &, std::string const & = "") const; nano::tally_t tally () const; bool have_quorum (nano::tally_t const &) const; diff --git a/nano/node/epoch_upgrader.cpp b/nano/node/epoch_upgrader.cpp index a731bb4da8..05193b1bb3 100644 --- a/nano/node/epoch_upgrader.cpp +++ b/nano/node/epoch_upgrader.cpp @@ -2,12 +2,12 @@ #include #include -nano::epoch_upgrader::epoch_upgrader (nano::node & node_a, nano::ledger & ledger_a, nano::store::component & store_a, nano::network_params & network_params_a, nano::logger_mt & logger_a) : +nano::epoch_upgrader::epoch_upgrader (nano::node & node_a, nano::ledger & ledger_a, nano::store::component & store_a, nano::network_params & network_params_a, nano::nlogger & nlogger_a) : node{ node_a }, ledger{ ledger_a }, store{ store_a }, network_params{ network_params_a }, - logger{ logger_a } + nlogger{ nlogger_a } { } @@ -59,7 +59,12 @@ void nano::epoch_upgrader::upgrade_impl (nano::raw_key const & prv_a, nano::epoc else { bool fork (result == nano::process_result::fork); - logger.always_log (boost::str (boost::format ("Failed to upgrade account %1%. Valid signature: %2%. Valid work: %3%. Block processor fork: %4%") % account_a.to_account () % valid_signature % valid_work % fork)); + + nlogger.error (nano::log::tag::epoch_upgrader, "Failed to upgrade account {} (valid signature: {}, valid work: {}, fork: {})", + account_a.to_account (), + valid_signature, + valid_work, + fork); } }; @@ -181,12 +186,16 @@ void nano::epoch_upgrader::upgrade_impl (nano::raw_key const & prv_a, nano::epoc if (!accounts_list.empty ()) { - logger.always_log (boost::str (boost::format ("%1% accounts were upgraded to new epoch, %2% remain...") % total_upgraded_accounts % (accounts_list.size () - upgraded_accounts))); + nlogger.info (nano::log::tag::epoch_upgrader, "{} accounts were upgraded to new epoch, {} remain...", + total_upgraded_accounts, + accounts_list.size () - upgraded_accounts); + accounts_list.clear (); } else { - logger.always_log (boost::str (boost::format ("%1% total accounts were upgraded to new epoch") % total_upgraded_accounts)); + nlogger.info (nano::log::tag::epoch_upgrader, "{} total accounts were upgraded to new epoch", total_upgraded_accounts); + finished_accounts = true; } } @@ -284,11 +293,12 @@ void nano::epoch_upgrader::upgrade_impl (nano::raw_key const & prv_a, nano::epoc // Repeat if some pending accounts were upgraded if (upgraded_pending != 0) { - logger.always_log (boost::str (boost::format ("%1% unopened accounts with pending blocks were upgraded to new epoch...") % total_upgraded_pending)); + nlogger.info (nano::log::tag::epoch_upgrader, "{} unopened accounts with pending blocks were upgraded to new epoch...", total_upgraded_pending); } else { - logger.always_log (boost::str (boost::format ("%1% total unopened accounts with pending blocks were upgraded to new epoch") % total_upgraded_pending)); + nlogger.info (nano::log::tag::epoch_upgrader, "{} total unopened accounts with pending blocks were upgraded to new epoch", total_upgraded_pending); + finished_pending = true; } } @@ -296,5 +306,5 @@ void nano::epoch_upgrader::upgrade_impl (nano::raw_key const & prv_a, nano::epoc finished_upgrade = (total_upgraded_accounts == 0) && (total_upgraded_pending == 0); } - logger.always_log ("Epoch upgrade is completed"); + nlogger.info (nano::log::tag::epoch_upgrader, "Epoch upgrade is completed"); } diff --git a/nano/node/epoch_upgrader.hpp b/nano/node/epoch_upgrader.hpp index ab0499fb14..3f85b9985b 100644 --- a/nano/node/epoch_upgrader.hpp +++ b/nano/node/epoch_upgrader.hpp @@ -2,6 +2,7 @@ #include #include +#include #include #include @@ -15,12 +16,11 @@ namespace store class component; } class network_params; -class logger_mt; class epoch_upgrader final { public: - epoch_upgrader (nano::node &, nano::ledger &, nano::store::component &, nano::network_params &, nano::logger_mt &); + epoch_upgrader (nano::node &, nano::ledger &, nano::store::component &, nano::network_params &, nano::nlogger &); bool start (nano::raw_key const & prv, nano::epoch epoch, uint64_t count_limit, uint64_t threads); void stop (); @@ -30,7 +30,7 @@ class epoch_upgrader final nano::ledger & ledger; nano::store::component & store; nano::network_params & network_params; - nano::logger_mt & logger; + nano::nlogger & nlogger; private: void upgrade_impl (nano::raw_key const & prv, nano::epoch epoch, uint64_t count_limit, uint64_t threads); diff --git a/nano/node/gap_cache.cpp b/nano/node/gap_cache.cpp index 022544e9c7..ce642df85c 100644 --- a/nano/node/gap_cache.cpp +++ b/nano/node/gap_cache.cpp @@ -101,7 +101,7 @@ void nano::gap_cache::bootstrap_start (nano::block_hash const & hash_a) { if (!node_l->bootstrap_initiator.in_progress ()) { - node_l->logger.try_log (boost::str (boost::format ("Missing block %1% which has enough votes to warrant lazy bootstrapping it") % hash_a.to_string ())); + node_l->nlogger.debug (nano::log::tag::gap_cache, "Block {} has enough votes to warrant lazy bootstrapping it", hash_a.to_string ()); } if (!node_l->flags.disable_lazy_bootstrap) { diff --git a/nano/node/ipc/ipc_broker.cpp b/nano/node/ipc/ipc_broker.cpp index 5176b3b131..3b959f0425 100644 --- a/nano/node/ipc/ipc_broker.cpp +++ b/nano/node/ipc/ipc_broker.cpp @@ -65,17 +65,17 @@ void nano::ipc::broker::start () } catch (nano::error const & err) { - this_l->node.logger.always_log ("IPC: could not broadcast message: ", err.get_message ()); + this_l->node.nlogger.error (nano::log::tag::ipc, "Could not broadcast message: {}", err.get_message ()); } }); } template -void subscribe_or_unsubscribe (nano::logger_mt & logger, COLL & subscriber_collection, std::weak_ptr const & subscriber_a, TOPIC_TYPE topic_a) +void subscribe_or_unsubscribe (nano::nlogger & nlogger, COLL & subscriber_collection, std::weak_ptr const & subscriber_a, TOPIC_TYPE topic_a) { // Evict subscribers from dead sessions. Also remove current subscriber if unsubscribing. subscriber_collection.erase (std::remove_if (subscriber_collection.begin (), subscriber_collection.end (), - [&logger = logger, topic_a, subscriber_a] (auto & sub) { + [&nlogger = nlogger, topic_a, subscriber_a] (auto & sub) { bool remove = false; auto subscriber_l = sub.subscriber.lock (); if (subscriber_l) @@ -85,7 +85,7 @@ void subscribe_or_unsubscribe (nano::logger_mt & logger, COLL & subscriber_colle remove = topic_a->unsubscribe && subscriber_l->get_id () == calling_subscriber_l->get_id (); if (remove) { - logger.always_log ("IPC: unsubscription from subscriber #", calling_subscriber_l->get_id ()); + nlogger.info (nano::log::tag::ipc, "Subscriber ubsubscribed #{}", calling_subscriber_l->get_id ()); } } } @@ -106,7 +106,7 @@ void subscribe_or_unsubscribe (nano::logger_mt & logger, COLL & subscriber_colle void nano::ipc::broker::subscribe (std::weak_ptr const & subscriber_a, std::shared_ptr const & confirmation_a) { auto subscribers = confirmation_subscribers.lock (); - subscribe_or_unsubscribe (node.logger, subscribers.get (), subscriber_a, confirmation_a); + subscribe_or_unsubscribe (node.nlogger, subscribers.get (), subscriber_a, confirmation_a); } void nano::ipc::broker::broadcast (std::shared_ptr const & confirmation_a) @@ -257,5 +257,5 @@ void nano::ipc::broker::service_stop (std::string const & service_name_a) void nano::ipc::broker::subscribe (std::weak_ptr const & subscriber_a, std::shared_ptr const & service_stop_a) { auto subscribers = service_stop_subscribers.lock (); - subscribe_or_unsubscribe (node.logger, subscribers.get (), subscriber_a, service_stop_a); + subscribe_or_unsubscribe (node.nlogger, subscribers.get (), subscriber_a, service_stop_a); } diff --git a/nano/node/ipc/ipc_server.cpp b/nano/node/ipc/ipc_server.cpp index 9eaf1e7509..d3c90ff05f 100644 --- a/nano/node/ipc/ipc_server.cpp +++ b/nano/node/ipc/ipc_server.cpp @@ -39,10 +39,7 @@ class session final : public nano::ipc::socket_base, public std::enable_shared_f server (server_a), node (server_a.node), session_id (server_a.id_dispenser.fetch_add (1)), io_ctx (io_ctx_a), strand (io_ctx_a.get_executor ()), socket (io_ctx_a), config_transport (config_transport_a) { - if (node.config.logging.log_ipc ()) - { - node.logger.always_log ("IPC: created session with id: ", session_id.load ()); - } + node.nlogger.debug (nano::log::tag::ipc, "Creating session with id: ", session_id.load ()); } ~session () @@ -234,10 +231,7 @@ class session final : public nano::ipc::socket_base, public std::enable_shared_f this_l->timer_cancel (); if (ec == boost::asio::error::broken_pipe || ec == boost::asio::error::connection_aborted || ec == boost::asio::error::connection_reset || ec == boost::asio::error::connection_refused) { - if (this_l->node.config.logging.log_ipc ()) - { - this_l->node.logger.always_log (boost::str (boost::format ("IPC: error reading %1% ") % ec.message ())); - } + this_l->node.nlogger.error (nano::log::tag::ipc, "Error reading: ", ec.message ()); } else if (bytes_transferred_a > 0) { @@ -260,10 +254,11 @@ class session final : public nano::ipc::socket_base, public std::enable_shared_f auto buffer (std::make_shared> ()); buffer->insert (buffer->end (), reinterpret_cast (&big), reinterpret_cast (&big) + sizeof (std::uint32_t)); buffer->insert (buffer->end (), body.begin (), body.end ()); - if (this_l->node.config.logging.log_ipc ()) - { - this_l->node.logger.always_log (boost::str (boost::format ("IPC/RPC request %1% completed in: %2% %3%") % request_id_l % this_l->session_timer.stop ().count () % this_l->session_timer.unit ())); - } + + this_l->node.nlogger.debug (nano::log::tag::ipc, "IPC/RPC request {} completed in: {} {}", + request_id_l, + this_l->session_timer.stop ().count (), + this_l->session_timer.unit ()); this_l->timer_start (std::chrono::seconds (this_l->config_transport.io_timeout)); this_l->queued_write (boost::asio::buffer (buffer->data (), buffer->size ()), [this_l, buffer] (boost::system::error_code const & error_a, std::size_t size_a) { @@ -272,9 +267,9 @@ class session final : public nano::ipc::socket_base, public std::enable_shared_f { this_l->read_next_request (); } - else if (this_l->node.config.logging.log_ipc ()) + else { - this_l->node.logger.always_log ("IPC: Write failed: ", error_a.message ()); + this_l->node.nlogger.error (nano::log::tag::ipc, "Write failed: ", error_a.message ()); } }); @@ -307,10 +302,7 @@ class session final : public nano::ipc::socket_base, public std::enable_shared_f this_l->active_encoding = static_cast (encoding); if (this_l->buffer[nano::ipc::preamble_offset::lead] != 'N' || this_l->buffer[nano::ipc::preamble_offset::reserved_1] != 0 || this_l->buffer[nano::ipc::preamble_offset::reserved_2] != 0) { - if (this_l->node.config.logging.log_ipc ()) - { - this_l->node.logger.always_log ("IPC: Invalid preamble"); - } + this_l->node.nlogger.error (nano::log::tag::ipc, "Invalid preamble"); } else if (encoding == static_cast (nano::ipc::payload_encoding::json_v1) || encoding == static_cast (nano::ipc::payload_encoding::json_v1_unsafe)) { @@ -344,10 +336,9 @@ class session final : public nano::ipc::socket_base, public std::enable_shared_f if (encoding == static_cast (nano::ipc::payload_encoding::flatbuffers_json)) { this_l->flatbuffers_handler->process_json (this_l->buffer.data (), this_l->buffer_size, [this_l] (std::shared_ptr const & body) { - if (this_l->node.config.logging.log_ipc ()) - { - this_l->node.logger.always_log (boost::str (boost::format ("IPC/Flatbuffer request completed in: %1% %2%") % this_l->session_timer.stop ().count () % this_l->session_timer.unit ())); - } + this_l->node.nlogger.debug (nano::log::tag::ipc, "IPC/Flatbuffer request completed in: {} {}", + this_l->session_timer.stop ().count (), + this_l->session_timer.unit ()); auto big_endian_length = std::make_shared (boost::endian::native_to_big (static_cast (body->size ()))); boost::array buffers = { @@ -360,9 +351,9 @@ class session final : public nano::ipc::socket_base, public std::enable_shared_f { this_l->read_next_request (); } - else if (this_l->node.config.logging.log_ipc ()) + else { - this_l->node.logger.always_log ("IPC: Write failed: ", error_a.message ()); + this_l->node.nlogger.error (nano::log::tag::ipc, "Write failed: {}", error_a.message ()); } }); }); @@ -370,10 +361,9 @@ class session final : public nano::ipc::socket_base, public std::enable_shared_f else { this_l->flatbuffers_handler->process (this_l->buffer.data (), this_l->buffer_size, [this_l] (std::shared_ptr const & fbb) { - if (this_l->node.config.logging.log_ipc ()) - { - this_l->node.logger.always_log (boost::str (boost::format ("IPC/Flatbuffer request completed in: %1% %2%") % this_l->session_timer.stop ().count () % this_l->session_timer.unit ())); - } + this_l->node.nlogger.debug (nano::log::tag::ipc, "IPC/Flatbuffer request completed in: {} {}", + this_l->session_timer.stop ().count (), + this_l->session_timer.unit ()); auto big_endian_length = std::make_shared (boost::endian::native_to_big (static_cast (fbb->GetSize ()))); boost::array buffers = { @@ -386,9 +376,9 @@ class session final : public nano::ipc::socket_base, public std::enable_shared_f { this_l->read_next_request (); } - else if (this_l->node.config.logging.log_ipc ()) + else { - this_l->node.logger.always_log ("IPC: Write failed: ", error_a.message ()); + this_l->node.nlogger.error (nano::log::tag::ipc, "Write failed: {}", error_a.message ()); } }); }); @@ -396,9 +386,9 @@ class session final : public nano::ipc::socket_base, public std::enable_shared_f }); }); } - else if (this_l->node.config.logging.log_ipc ()) + else { - this_l->node.logger.always_log ("IPC: Unsupported payload encoding"); + this_l->node.nlogger.error (nano::log::tag::ipc, "Unsupported payload encoding"); } }); } @@ -523,7 +513,7 @@ class socket_transport : public nano::ipc::transport } else { - node->logger.always_log ("IPC: acceptor error: ", ec.message ()); + node->nlogger.error (nano::log::tag::ipc, "Acceptor error: ", ec.message ()); } if (ec != boost::asio::error::operation_aborted && acceptor->is_open ()) @@ -532,7 +522,7 @@ class socket_transport : public nano::ipc::transport } else { - node->logger.always_log ("IPC: shutting down"); + node->nlogger.info (nano::log::tag::ipc, "Shutting down"); } }); } @@ -625,7 +615,7 @@ nano::ipc::ipc_server::ipc_server (nano::node & node_a, nano::node_rpc_config co boost::asio::local::stream_protocol::endpoint ep{ node_a.config.ipc_config.transport_domain.path }; transports.push_back (std::make_shared (*this, ep, node_a.config.ipc_config.transport_domain, threads)); #else - node.logger.always_log ("IPC: Domain sockets are not supported on this platform"); + node.nlogger.error (nano::log::tag::ipc_server, "Domain sockets are not supported on this platform"); #endif } @@ -635,7 +625,7 @@ nano::ipc::ipc_server::ipc_server (nano::node & node_a, nano::node_rpc_config co transports.push_back (std::make_shared (*this, boost::asio::ip::tcp::endpoint (boost::asio::ip::tcp::v6 (), node_a.config.ipc_config.transport_tcp.port), node_a.config.ipc_config.transport_tcp, threads)); } - node.logger.always_log ("IPC: server started"); + node.nlogger.debug (nano::log::tag::ipc_server, "Server started"); if (!transports.empty ()) { @@ -644,13 +634,13 @@ nano::ipc::ipc_server::ipc_server (nano::node & node_a, nano::node_rpc_config co } catch (std::runtime_error const & ex) { - node.logger.always_log ("IPC: ", ex.what ()); + node.nlogger.error (nano::log::tag::ipc_server, "Error: {}", ex.what ()); } } nano::ipc::ipc_server::~ipc_server () { - node.logger.always_log ("IPC: server stopped"); + node.nlogger.debug (nano::log::tag::ipc_server, "Server stopped"); } void nano::ipc::ipc_server::stop () @@ -690,9 +680,7 @@ nano::error nano::ipc::ipc_server::reload_access_config () nano::error access_config_error (nano::ipc::read_access_config_toml (node.application_path, access)); if (access_config_error) { - auto error (boost::str (boost::format ("IPC: invalid access configuration file: %1%") % access_config_error.get_message ())); - std::cerr << error << std::endl; - node.logger.always_log (error); + node.nlogger.error (nano::log::tag::ipc_server, "Invalid access configuration file: {}", access_config_error.get_message ()); } return access_config_error; } diff --git a/nano/node/json_handler.cpp b/nano/node/json_handler.cpp index 3e6683da74..380cc6fa12 100644 --- a/nano/node/json_handler.cpp +++ b/nano/node/json_handler.cpp @@ -2955,7 +2955,7 @@ void nano::json_handler::password_change () rpc_l->response_l.put ("changed", error ? "0" : "1"); if (!error) { - rpc_l->node.logger.try_log ("Wallet password changed"); + rpc_l->node.nlogger.warn (nano::log::tag::rpc, "Wallet password changed"); } } } @@ -4773,7 +4773,8 @@ void nano::json_handler::wallet_lock () empty.clear (); wallet->store.password.value_set (empty); response_l.put ("locked", "1"); - node.logger.try_log ("Wallet locked"); + + node.nlogger.warn (nano::log::tag::rpc, "Wallet locked"); } response_errors (); } diff --git a/nano/node/make_store.cpp b/nano/node/make_store.cpp index 7f24c649cf..fda5c9ac20 100644 --- a/nano/node/make_store.cpp +++ b/nano/node/make_store.cpp @@ -2,7 +2,7 @@ #include #include -std::unique_ptr nano::make_store (nano::logger_mt & logger, std::filesystem::path const & path, nano::ledger_constants & constants, bool read_only, bool add_db_postfix, nano::rocksdb_config const & rocksdb_config, nano::txn_tracking_config const & txn_tracking_config_a, std::chrono::milliseconds block_processor_batch_max_time_a, nano::lmdb_config const & lmdb_config_a, bool backup_before_upgrade) +std::unique_ptr nano::make_store (nano::nlogger & logger, std::filesystem::path const & path, nano::ledger_constants & constants, bool read_only, bool add_db_postfix, nano::rocksdb_config const & rocksdb_config, nano::txn_tracking_config const & txn_tracking_config_a, std::chrono::milliseconds block_processor_batch_max_time_a, nano::lmdb_config const & lmdb_config_a, bool backup_before_upgrade) { if (rocksdb_config.enable) { diff --git a/nano/node/make_store.hpp b/nano/node/make_store.hpp index 1e7bdd2dc1..b467c07ce8 100644 --- a/nano/node/make_store.hpp +++ b/nano/node/make_store.hpp @@ -2,7 +2,7 @@ #include #include -#include +#include #include #include @@ -22,5 +22,5 @@ class component; namespace nano { -std::unique_ptr make_store (nano::logger_mt & logger, std::filesystem::path const & path, nano::ledger_constants & constants, bool open_read_only = false, bool add_db_postfix = true, nano::rocksdb_config const & rocksdb_config = nano::rocksdb_config{}, nano::txn_tracking_config const & txn_tracking_config_a = nano::txn_tracking_config{}, std::chrono::milliseconds block_processor_batch_max_time_a = std::chrono::milliseconds (5000), nano::lmdb_config const & lmdb_config_a = nano::lmdb_config{}, bool backup_before_upgrade = false); +std::unique_ptr make_store (nano::nlogger &, std::filesystem::path const & path, nano::ledger_constants & constants, bool open_read_only = false, bool add_db_postfix = true, nano::rocksdb_config const & rocksdb_config = nano::rocksdb_config{}, nano::txn_tracking_config const & txn_tracking_config_a = nano::txn_tracking_config{}, std::chrono::milliseconds block_processor_batch_max_time_a = std::chrono::milliseconds (5000), nano::lmdb_config const & lmdb_config_a = nano::lmdb_config{}, bool backup_before_upgrade = false); } diff --git a/nano/node/messages.cpp b/nano/node/messages.cpp index 3b6079b432..0631dcddfa 100644 --- a/nano/node/messages.cpp +++ b/nano/node/messages.cpp @@ -82,86 +82,6 @@ bool nano::message_header::deserialize (nano::stream & stream_a) return error; } -std::string nano::to_string (nano::message_type type) -{ - switch (type) - { - case nano::message_type::invalid: - return "invalid"; - case nano::message_type::not_a_type: - return "not_a_type"; - case nano::message_type::keepalive: - return "keepalive"; - case nano::message_type::publish: - return "publish"; - case nano::message_type::confirm_req: - return "confirm_req"; - case nano::message_type::confirm_ack: - return "confirm_ack"; - case nano::message_type::bulk_pull: - return "bulk_pull"; - case nano::message_type::bulk_push: - return "bulk_push"; - case nano::message_type::frontier_req: - return "frontier_req"; - case nano::message_type::node_id_handshake: - return "node_id_handshake"; - case nano::message_type::bulk_pull_account: - return "bulk_pull_account"; - case nano::message_type::telemetry_req: - return "telemetry_req"; - case nano::message_type::telemetry_ack: - return "telemetry_ack"; - case nano::message_type::asc_pull_req: - return "asc_pull_req"; - case nano::message_type::asc_pull_ack: - return "asc_pull_ack"; - // default case intentionally omitted to cause warnings for unhandled enums - } - - return "n/a"; -} - -nano::stat::detail nano::to_stat_detail (nano::message_type type) -{ - switch (type) - { - case nano::message_type::invalid: - return nano::stat::detail::invalid; - case nano::message_type::not_a_type: - return nano::stat::detail::not_a_type; - case nano::message_type::keepalive: - return nano::stat::detail::keepalive; - case nano::message_type::publish: - return nano::stat::detail::publish; - case nano::message_type::confirm_req: - return nano::stat::detail::confirm_req; - case nano::message_type::confirm_ack: - return nano::stat::detail::confirm_ack; - case nano::message_type::bulk_pull: - return nano::stat::detail::bulk_pull; - case nano::message_type::bulk_push: - return nano::stat::detail::bulk_push; - case nano::message_type::frontier_req: - return nano::stat::detail::frontier_req; - case nano::message_type::node_id_handshake: - return nano::stat::detail::node_id_handshake; - case nano::message_type::bulk_pull_account: - return nano::stat::detail::bulk_pull_account; - case nano::message_type::telemetry_req: - return nano::stat::detail::telemetry_req; - case nano::message_type::telemetry_ack: - return nano::stat::detail::telemetry_ack; - case nano::message_type::asc_pull_req: - return nano::stat::detail::asc_pull_req; - case nano::message_type::asc_pull_ack: - return nano::stat::detail::asc_pull_ack; - // default case intentionally omitted to cause warnings for unhandled enums - } - debug_assert (false); - return {}; -} - 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. @@ -169,11 +89,11 @@ std::string nano::message_header::to_string () const 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); - std::string type_text = nano::to_string (type); + auto type_text = nano::to_string (type); std::stringstream stream; - stream << boost::format ("NetID: %1%(%2%), ") % nano::to_string_hex (static_cast (network)) % nano::network::to_string (network); + 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 ())); @@ -2068,3 +1988,87 @@ void nano::asc_pull_ack::frontiers_payload::deserialize (nano::stream & stream) current = deserialize_frontier (stream); } } + +/* + * + */ + +std::string_view nano::to_string (nano::message_type type) +{ + switch (type) + { + case nano::message_type::invalid: + return "invalid"; + case nano::message_type::not_a_type: + return "not_a_type"; + case nano::message_type::keepalive: + return "keepalive"; + case nano::message_type::publish: + return "publish"; + case nano::message_type::confirm_req: + return "confirm_req"; + case nano::message_type::confirm_ack: + return "confirm_ack"; + case nano::message_type::bulk_pull: + return "bulk_pull"; + case nano::message_type::bulk_push: + return "bulk_push"; + case nano::message_type::frontier_req: + return "frontier_req"; + case nano::message_type::node_id_handshake: + return "node_id_handshake"; + case nano::message_type::bulk_pull_account: + return "bulk_pull_account"; + case nano::message_type::telemetry_req: + return "telemetry_req"; + case nano::message_type::telemetry_ack: + return "telemetry_ack"; + case nano::message_type::asc_pull_req: + return "asc_pull_req"; + case nano::message_type::asc_pull_ack: + return "asc_pull_ack"; + // default case intentionally omitted to cause warnings for unhandled enums + } + + return "n/a"; +} + +nano::stat::detail nano::to_stat_detail (nano::message_type type) +{ + switch (type) + { + case nano::message_type::invalid: + return nano::stat::detail::invalid; + case nano::message_type::not_a_type: + return nano::stat::detail::not_a_type; + case nano::message_type::keepalive: + return nano::stat::detail::keepalive; + case nano::message_type::publish: + return nano::stat::detail::publish; + case nano::message_type::confirm_req: + return nano::stat::detail::confirm_req; + case nano::message_type::confirm_ack: + return nano::stat::detail::confirm_ack; + case nano::message_type::bulk_pull: + return nano::stat::detail::bulk_pull; + case nano::message_type::bulk_push: + return nano::stat::detail::bulk_push; + case nano::message_type::frontier_req: + return nano::stat::detail::frontier_req; + case nano::message_type::node_id_handshake: + return nano::stat::detail::node_id_handshake; + case nano::message_type::bulk_pull_account: + return nano::stat::detail::bulk_pull_account; + case nano::message_type::telemetry_req: + return nano::stat::detail::telemetry_req; + case nano::message_type::telemetry_ack: + return nano::stat::detail::telemetry_ack; + case nano::message_type::asc_pull_req: + return nano::stat::detail::asc_pull_req; + case nano::message_type::asc_pull_ack: + return nano::stat::detail::asc_pull_ack; + // default case intentionally omitted to cause warnings for unhandled enums + } + debug_assert (false); + return {}; +} diff --git a/nano/node/messages.hpp b/nano/node/messages.hpp index d808f8a7ee..e97e860845 100644 --- a/nano/node/messages.hpp +++ b/nano/node/messages.hpp @@ -45,8 +45,8 @@ enum class message_type : uint8_t asc_pull_ack = 0x0f, }; -std::string to_string (message_type); -stat::detail to_stat_detail (message_type); +std::string_view to_string (nano::message_type); +stat::detail to_stat_detail (nano::message_type); enum class bulk_pull_account_flags : uint8_t { diff --git a/nano/node/network.cpp b/nano/node/network.cpp index a9c1974399..b9ac045fbb 100644 --- a/nano/node/network.cpp +++ b/nano/node/network.cpp @@ -1,5 +1,6 @@ #include #include +#include #include #include #include @@ -27,10 +28,9 @@ nano::network::network (nano::node & node_a, uint16_t port_a) : port (port_a), disconnect_observer ([] () {}) { - // TCP for (std::size_t i = 0; i < node.config.network_threads && !node.flags.disable_tcp_realtime; ++i) { - packet_processing_threads.emplace_back (nano::thread_attributes::get_default (), [this] () { + packet_processing_threads.emplace_back (nano::thread_attributes::get_default (), [this, i] () { nano::thread_role::set (nano::thread_role::name::packet_processing); try { @@ -38,28 +38,24 @@ nano::network::network (nano::node & node_a, uint16_t port_a) : } catch (boost::system::error_code & ec) { - this->node.logger.always_log (FATAL_LOG_PREFIX, ec.message ()); + node.nlogger.critical (nano::log::tag::network, "Error: {}", ec.message ()); release_assert (false); } catch (std::error_code & ec) { - this->node.logger.always_log (FATAL_LOG_PREFIX, ec.message ()); + node.nlogger.critical (nano::log::tag::network, "Error: {}", ec.message ()); release_assert (false); } catch (std::runtime_error & err) { - this->node.logger.always_log (FATAL_LOG_PREFIX, err.what ()); + node.nlogger.critical (nano::log::tag::network, "Error: {}", err.what ()); release_assert (false); } catch (...) { - this->node.logger.always_log (FATAL_LOG_PREFIX, "Unknown exception"); + node.nlogger.critical (nano::log::tag::network, "Unknown error"); release_assert (false); } - if (this->node.config.logging.network_packet_logging ()) - { - this->node.logger.try_log ("Exiting TCP packet processing thread"); - } }); } } @@ -131,10 +127,11 @@ void nano::network::send_node_id_handshake (std::shared_ptrget_endpoint () % (query ? query->cookie.to_string () : std::string ("[none]")) % (respond_to ? respond_to->to_string () : std::string ("[none]")) % (response ? response->signature.to_string () : std::string ("[none]")))); - } + node.nlogger.debug (nano::log::tag::network, "Node ID handshake sent to: {} (query: {}, respond to: {}, signature: {})", + nano::util::to_str (channel_a->get_endpoint ()), + (query ? query->cookie.to_string () : ""), + (respond_to ? respond_to->to_string () : ""), + (response ? response->signature.to_string () : "")); channel_a->send (message); } @@ -260,10 +257,6 @@ void nano::network::broadcast_confirm_req (std::shared_ptr const & void nano::network::broadcast_confirm_req_base (std::shared_ptr const & block_a, std::shared_ptr>> const & endpoints_a, unsigned delay_a, bool resumption) { std::size_t const max_reps = 10; - if (!resumption && node.config.logging.network_logging ()) - { - node.logger.try_log (boost::str (boost::format ("Broadcasting confirm req for block %1% to %2% representatives") % block_a->hash ().to_string () % endpoints_a->size ())); - } auto count (0); while (!endpoints_a->empty () && count < max_reps) { @@ -288,11 +281,6 @@ void nano::network::broadcast_confirm_req_base (std::shared_ptr con void nano::network::broadcast_confirm_req_batched_many (std::unordered_map, std::deque>> request_bundle_a, std::function callback_a, unsigned delay_a, bool resumption_a) { - if (!resumption_a && node.config.logging.network_logging ()) - { - node.logger.try_log (boost::str (boost::format ("Broadcasting batch confirm req to %1% representatives") % request_bundle_a.size ())); - } - for (auto i (request_bundle_a.begin ()), n (request_bundle_a.end ()); i != n;) { std::vector> roots_hashes_l; @@ -365,18 +353,13 @@ class network_message_visitor : public nano::message_visitor { public: network_message_visitor (nano::node & node_a, std::shared_ptr const & channel_a) : - node (node_a), - channel (channel_a) + node{ node_a }, + channel{ channel_a } { } void keepalive (nano::keepalive const & message_a) override { - if (node.config.logging.network_keepalive_logging ()) - { - node.logger.try_log (boost::str (boost::format ("Received keepalive message from %1%") % channel->to_string ())); - } - node.network.merge_peers (message_a.peers); // Check for special node port data @@ -393,11 +376,6 @@ class network_message_visitor : public nano::message_visitor void publish (nano::publish const & message_a) override { - if (node.config.logging.network_message_logging ()) - { - node.logger.try_log (boost::str (boost::format ("Publish message from %1% for %2%") % channel->to_string () % message_a.block->hash ().to_string ())); - } - if (!node.block_processor.full ()) { node.process_active (message_a.block); @@ -411,14 +389,6 @@ class network_message_visitor : public nano::message_visitor void confirm_req (nano::confirm_req const & message_a) override { - if (node.config.logging.network_message_logging ()) - { - if (!message_a.roots_hashes.empty ()) - { - node.logger.try_log (boost::str (boost::format ("Confirm_req message from %1% for hashes:roots %2%") % channel->to_string () % message_a.roots_string ())); - } - } - // Don't load nodes with disabled voting if (node.config.enable_voting && node.wallets.reps ().voting > 0) { @@ -431,11 +401,6 @@ class network_message_visitor : public nano::message_visitor void confirm_ack (nano::confirm_ack const & message_a) override { - if (node.config.logging.network_message_logging ()) - { - node.logger.try_log (boost::str (boost::format ("Received confirm_ack message from %1% for %2% timestamp %3%") % channel->to_string () % message_a.vote->hashes_string () % std::to_string (message_a.vote->timestamp ()))); - } - if (!message_a.vote->account.is_zero ()) { node.vote_processor.vote (message_a.vote, channel); @@ -469,11 +434,6 @@ class network_message_visitor : public nano::message_visitor void telemetry_req (nano::telemetry_req const & message_a) override { - if (node.config.logging.network_telemetry_logging ()) - { - node.logger.try_log (boost::str (boost::format ("Telemetry_req message from %1%") % channel->to_string ())); - } - // Send an empty telemetry_ack if we do not want, just to acknowledge that we have received the message to // remove any timeouts on the server side waiting for a message. nano::telemetry_ack telemetry_ack{ node.network_params.network }; @@ -487,11 +447,6 @@ class network_message_visitor : public nano::message_visitor void telemetry_ack (nano::telemetry_ack const & message_a) override { - if (node.config.logging.network_telemetry_logging ()) - { - node.logger.try_log (boost::str (boost::format ("Received telemetry_ack message from %1%") % channel->to_string ())); - } - node.telemetry.process (message_a, channel); } @@ -515,7 +470,7 @@ void nano::network::process_message (nano::message const & message, std::shared_ { node.stats.inc (nano::stat::type::message, nano::to_stat_detail (message.header.type), nano::stat::dir::in); - network_message_visitor visitor (node, channel); + network_message_visitor visitor{ node, channel }; message.visit (visitor); } @@ -998,23 +953,3 @@ std::unique_ptr nano::syn_cookies::collect_conta composite->add_component (std::make_unique (container_info{ "syn_cookies_per_ip", syn_cookies_per_ip_count, sizeof (decltype (cookies_per_ip)::value_type) })); return composite; } - -std::string nano::network::to_string (nano::networks network) -{ - switch (network) - { - case nano::networks::invalid: - return "invalid"; - case nano::networks::nano_beta_network: - return "beta"; - case nano::networks::nano_dev_network: - return "dev"; - case nano::networks::nano_live_network: - return "live"; - case nano::networks::nano_test_network: - return "test"; - // default case intentionally omitted to cause warnings for unhandled enums - } - - return "n/a"; -} diff --git a/nano/node/network.hpp b/nano/node/network.hpp index 56f6f23b86..f0785d9441 100644 --- a/nano/node/network.hpp +++ b/nano/node/network.hpp @@ -1,5 +1,6 @@ #pragma once +#include #include #include #include @@ -133,8 +134,6 @@ class network final std::optional prepare_handshake_query (nano::endpoint const & remote_endpoint); nano::node_id_handshake::response_payload prepare_handshake_response (nano::node_id_handshake::query_payload const & query, bool v2) const; - static std::string to_string (nano::networks); - private: void process_message (nano::message const &, std::shared_ptr const &); @@ -158,5 +157,6 @@ class network final static std::size_t const confirm_req_hashes_max = 7; static std::size_t const confirm_ack_hashes_max = 12; }; + std::unique_ptr collect_container_info (network & network, std::string const & name); } diff --git a/nano/node/node.cpp b/nano/node/node.cpp index fb14c3c81c..6a5f4c47e4 100644 --- a/nano/node/node.cpp +++ b/nano/node/node.cpp @@ -85,7 +85,7 @@ void nano::node::keepalive (std::string const & address_a, uint16_t port_a) } else { - node_l->logger.try_log (boost::str (boost::format ("Error resolving address: %1%:%2%: %3%") % address_a % port_a % ec.message ())); + node_l->nlogger.error (nano::log::tag::node, "Error resolving address for keepalive: {}:{} ({})", address_a, port_a, ec.message ()); } }); } @@ -104,13 +104,14 @@ std::unique_ptr nano::collect_container_info (re return composite; } -nano::keypair nano::load_or_create_node_id (std::filesystem::path const & application_path, nano::logger_mt & logger) +nano::keypair nano::load_or_create_node_id (std::filesystem::path const & application_path, nano::nlogger & nlogger) { auto node_private_key_path = application_path / "node_id_private.key"; std::ifstream ifs (node_private_key_path.c_str ()); if (ifs.good ()) { - logger.always_log (boost::str (boost::format ("%1% exists, reading node id from it") % node_private_key_path.string ())); + nlogger.debug (nano::log::tag::node, "Reading node id from: '{}'", node_private_key_path.string ()); + std::string node_private_key; ifs >> node_private_key; release_assert (node_private_key.size () == 64); @@ -120,7 +121,8 @@ nano::keypair nano::load_or_create_node_id (std::filesystem::path const & applic else { // no node_id found, generate new one - logger.always_log (boost::str (boost::format ("%1% does not exist, creating a new node_id") % node_private_key_path.string ())); + nlogger.debug (nano::log::tag::node, "Generating a new node id, saving to: '{}'", node_private_key_path.string ()); + nano::keypair kp; std::ofstream ofs (node_private_key_path.c_str (), std::ofstream::out | std::ofstream::trunc); ofs << kp.prv.to_string () << std::endl @@ -149,7 +151,7 @@ nano::node::node (boost::asio::io_context & io_ctx_a, std::filesystem::path cons work (work_a), distributed_work (*this), logger (config_a.logging.min_time_between_log_output), - store_impl (nano::make_store (logger, application_path_a, network_params.ledger, flags.read_only, true, config_a.rocksdb_config, config_a.diagnostics_config.txn_tracking, config_a.block_processor_batch_max_time, config_a.lmdb_config, config_a.backup_before_upgrade)), + store_impl (nano::make_store (nlogger, application_path_a, network_params.ledger, flags.read_only, true, config_a.rocksdb_config, config_a.diagnostics_config.txn_tracking, config_a.block_processor_batch_max_time, config_a.lmdb_config, config_a.backup_before_upgrade)), store (*store_impl), unchecked{ stats, flags.disable_block_processor_unchecked_deletion }, wallets_store_impl (std::make_unique (application_path_a / "wallets.ldb", config_a.lmdb_config)), @@ -175,13 +177,13 @@ nano::node::node (boost::asio::io_context & io_ctx_a, std::filesystem::path cons application_path (application_path_a), port_mapping (*this), rep_crawler (*this), - vote_processor (active, observers, stats, config, flags, logger, online_reps, rep_crawler, ledger, network_params), + vote_processor (active, observers, stats, config, flags, nlogger, online_reps, rep_crawler, ledger, network_params), warmed_up (0), block_processor (*this, write_database_queue), online_reps (ledger, config), history{ config.network_params.voting }, vote_uniquer{}, - confirmation_height_processor (ledger, write_database_queue, config.conf_height_processor_batch_min_time, config.logging, logger, node_initialized_latch, flags.confirmation_height_processor_mode), + confirmation_height_processor (ledger, write_database_queue, config.conf_height_processor_batch_min_time, nlogger, 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 }, @@ -192,8 +194,8 @@ nano::node::node (boost::asio::io_context & io_ctx_a, std::filesystem::path cons wallets (wallets_store.init_error (), *this), backlog{ nano::backlog_population_config (config), store, stats }, ascendboot{ config, block_processor, ledger, network, stats }, - websocket{ config.websocket_config, observers, wallets, ledger, io_ctx, logger }, - epoch_upgrader{ *this, ledger, store, network_params, logger }, + websocket{ config.websocket_config, observers, wallets, ledger, io_ctx, nlogger }, + epoch_upgrader{ *this, ledger, store, network_params, nlogger }, startup_time (std::chrono::steady_clock::now ()), node_seq (seq), block_broadcast{ network, block_arrival, !flags.disable_block_processor_republishing }, @@ -201,6 +203,8 @@ nano::node::node (boost::asio::io_context & io_ctx_a, std::filesystem::path cons gap_tracker{ gap_cache }, process_live_dispatcher{ ledger, scheduler.priority, vote_cache, websocket } { + nlogger.debug (nano::log::tag::node, "Constructing node..."); + block_broadcast.connect (block_processor); block_publisher.connect (block_processor); gap_tracker.connect (block_processor); @@ -289,10 +293,7 @@ nano::node::node (boost::asio::io_context & io_ctx_a, std::filesystem::path cons } else { - if (node_l->config.logging.callback_logging ()) - { - node_l->logger.always_log (boost::str (boost::format ("Error resolving callback: %1%:%2%: %3%") % address % port % ec.message ())); - } + node_l->nlogger.error (nano::log::tag::rpc_callbacks, "Error resolving callback: {}:{} ({})", address, port, ec.message ()); node_l->stats.inc (nano::stat::type::error, nano::stat::detail::http_callback, nano::stat::dir::out); } }); @@ -343,26 +344,24 @@ nano::node::node (boost::asio::io_context & io_ctx_a, std::filesystem::path cons this->distributed_work.cancel (root_a); }); - logger.always_log ("Node starting, version: ", NANO_VERSION_STRING); - logger.always_log ("Build information: ", BUILD_INFO); - logger.always_log ("Database backend: ", store.vendor_get ()); - auto const network_label = network_params.network.get_current_network_as_string (); - logger.always_log ("Active network: ", network_label); - logger.always_log (boost::str (boost::format ("Work pool running %1% threads %2%") % work.threads.size () % (work.opencl ? "(1 for OpenCL)" : ""))); - logger.always_log (boost::str (boost::format ("%1% work peers configured") % config.work_peers.size ())); - if (!work_generation_enabled ()) - { - logger.always_log ("Work generation is disabled"); - } + nlogger.info (nano::log::tag::node, "Node starting, version: {}", NANO_VERSION_STRING); + nlogger.info (nano::log::tag::node, "Build information: {}", BUILD_INFO); + nlogger.info (nano::log::tag::node, "Active network: {}", network_label); + nlogger.info (nano::log::tag::node, "Database backend: {}", store.vendor_get ()); + nlogger.info (nano::log::tag::node, "Data path: {}", application_path.string ()); + nlogger.info (nano::log::tag::node, "Work pool threads: {} ({})", work.threads.size (), (work.opencl ? "OpenCL" : "CPU")); + nlogger.info (nano::log::tag::node, "Work peers: {}", config.work_peers.size ()); - if (config.logging.node_lifetime_tracing ()) + if (!work_generation_enabled ()) { - logger.always_log ("Constructing node"); + nlogger.info (nano::log::tag::node, "Work generation is disabled"); } - logger.always_log (boost::str (boost::format ("Outbound Voting Bandwidth limited to %1% bytes per second, burst ratio %2%") % config.bandwidth_limit % config.bandwidth_limit_burst_ratio)); + nlogger.info (nano::log::tag::node, "Outbound bandwidth limit: {} bytes/s, burst ratio: {}", + config.bandwidth_limit, + config.bandwidth_limit_burst_ratio); // First do a pass with a read to see if any writing needs doing, this saves needing to open a write lock (and potentially blocking) auto is_initialized (false); @@ -380,59 +379,72 @@ nano::node::node (boost::asio::io_context & io_ctx_a, std::filesystem::path cons if (!ledger.block_or_pruned_exists (config.network_params.ledger.genesis->hash ())) { - std::stringstream ss; - ss << "Genesis block not found. This commonly indicates a configuration issue, check that the --network or --data_path command line arguments are correct, " - "and also the ledger backend node config option. If using a read-only CLI command a ledger must already exist, start the node with --daemon first."; + nlogger.critical (nano::log::tag::node, "Genesis block not found. This commonly indicates a configuration issue, check that the --network or --data_path command line arguments are correct, and also the ledger backend node config option. If using a read-only CLI command a ledger must already exist, start the node with --daemon first."); + if (network_params.network.is_beta_network ()) { - ss << " Beta network may have reset, try clearing database files"; + nlogger.critical (nano::log::tag::node, "Beta network may have reset, try clearing database files"); } - auto const str = ss.str (); - logger.always_log (str); - std::cerr << str << std::endl; std::exit (1); } if (config.enable_voting) { - std::ostringstream stream; - stream << "Voting is enabled, more system resources will be used"; - auto voting (wallets.reps ().voting); - if (voting > 0) + auto reps = wallets.reps (); + nlogger.info (nano::log::tag::node, "Voting is enabled, more system resources will be used, local representatives: {}", reps.accounts.size ()); + for (auto const & account : reps.accounts) { - stream << ". " << voting << " representative(s) are configured"; - if (voting > 1) - { - stream << ". Voting with more than one representative can limit performance"; - } + nlogger.info (nano::log::tag::node, "Local representative: {}", account.to_account ()); + } + if (reps.accounts.size () > 1) + { + nlogger.warn (nano::log::tag::node, "Voting with more than one representative can limit performance"); } - logger.always_log (stream.str ()); } - node_id = nano::load_or_create_node_id (application_path, logger); - logger.always_log ("Node ID: ", node_id.pub.to_node_id ()); + node_id = nano::load_or_create_node_id (application_path, nlogger); + nlogger.info (nano::log::tag::node, "Node ID: {}", node_id.pub.to_node_id ()); if ((network_params.network.is_live_network () || network_params.network.is_beta_network ()) && !flags.inactive_node) { auto const bootstrap_weights = get_bootstrap_weights (); + ledger.bootstrap_weight_max_blocks = bootstrap_weights.first; + + nlogger.info (nano::log::tag::node, "Initial bootstrap height: {}", ledger.bootstrap_weight_max_blocks); + nlogger.info (nano::log::tag::node, "Current ledger height: {}", ledger.cache.block_count.load ()); + // Use bootstrap weights if initial bootstrap is not completed const bool use_bootstrap_weight = ledger.cache.block_count < bootstrap_weights.first; if (use_bootstrap_weight) { + nlogger.info (nano::log::tag::node, "Using predefined representative weights, since block count is less than bootstrap threshold"); + ledger.bootstrap_weights = bootstrap_weights.second; - for (auto const & rep : ledger.bootstrap_weights) + + nlogger.info (nano::log::tag::node, "************************************ Bootstrap weights ************************************"); + + // Sort the weights + std::vector> sorted_weights (ledger.bootstrap_weights.begin (), ledger.bootstrap_weights.end ()); + std::sort (sorted_weights.begin (), sorted_weights.end (), [] (auto const & entry1, auto const & entry2) { + return entry1.second > entry2.second; + }); + + for (auto const & rep : sorted_weights) { - logger.always_log ("Using bootstrap rep weight: ", rep.first.to_account (), " -> ", nano::uint128_union (rep.second).format_balance (Mxrb_ratio, 0, true), " XRB"); + nlogger.info (nano::log::tag::node, "Using bootstrap rep weight: {} -> {}", + rep.first.to_account (), + nano::uint128_union (rep.second).format_balance (Mxrb_ratio, 0, true)); } + + nlogger.info (nano::log::tag::node, "************************************ ================= ************************************"); } - ledger.bootstrap_weight_max_blocks = bootstrap_weights.first; // Drop unchecked blocks if initial bootstrap is completed if (!flags.disable_unchecked_drop && !use_bootstrap_weight && !flags.read_only) { + nlogger.info (nano::log::tag::node, "Dropping unchecked blocks..."); unchecked.clear (); - logger.always_log ("Dropping unchecked blocks"); } } @@ -442,16 +454,12 @@ nano::node::node (boost::asio::io_context & io_ctx_a, std::filesystem::path cons { if (config.enable_voting && !flags.inactive_node) { - std::string str = "Incompatibility detected between config node.enable_voting and existing pruned blocks"; - logger.always_log (str); - std::cerr << str << std::endl; + nlogger.critical (nano::log::tag::node, "Incompatibility detected between config node.enable_voting and existing pruned blocks"); std::exit (1); } else if (!flags.enable_pruning && !flags.inactive_node) { - std::string str = "To start node with existing pruned blocks use launch flag --enable_pruning"; - logger.always_log (str); - std::cerr << str << std::endl; + nlogger.critical (nano::log::tag::node, "To start node with existing pruned blocks use launch flag --enable_pruning"); std::exit (1); } } @@ -461,13 +469,11 @@ nano::node::node (boost::asio::io_context & io_ctx_a, std::filesystem::path cons nano::node::~node () { - if (config.logging.node_lifetime_tracing ()) - { - logger.always_log ("Destructing node"); - } + nlogger.debug (nano::log::tag::node, "Destructing node..."); stop (); } +// TODO: Move to a separate class void nano::node::do_rpc_callback (boost::asio::ip::tcp::resolver::iterator i_a, std::string const & address, uint16_t port, std::shared_ptr const & target, std::shared_ptr const & body, std::shared_ptr const & resolver) { if (i_a != boost::asio::ip::tcp::resolver::iterator{}) @@ -499,41 +505,30 @@ void nano::node::do_rpc_callback (boost::asio::ip::tcp::resolver::iterator i_a, } else { - if (node_l->config.logging.callback_logging ()) - { - node_l->logger.try_log (boost::str (boost::format ("Callback to %1%:%2% failed with status: %3%") % address % port % resp->result ())); - } + node_l->nlogger.error (nano::log::tag::rpc_callbacks, "Callback to {}:{} failed [status: {}]", address, port, nano::util::to_str (resp->result ())); node_l->stats.inc (nano::stat::type::error, nano::stat::detail::http_callback, nano::stat::dir::out); } } else { - if (node_l->config.logging.callback_logging ()) - { - node_l->logger.try_log (boost::str (boost::format ("Unable complete callback: %1%:%2%: %3%") % address % port % ec.message ())); - } + node_l->nlogger.error (nano::log::tag::rpc_callbacks, "Unable to complete callback: {}:{} ({})", address, port, ec.message ()); node_l->stats.inc (nano::stat::type::error, nano::stat::detail::http_callback, nano::stat::dir::out); }; }); } else { - if (node_l->config.logging.callback_logging ()) - { - node_l->logger.try_log (boost::str (boost::format ("Unable to send callback: %1%:%2%: %3%") % address % port % ec.message ())); - } + node_l->nlogger.error (nano::log::tag::rpc_callbacks, "Unable to send callback: {}:{} ({})", address, port, ec.message ()); node_l->stats.inc (nano::stat::type::error, nano::stat::detail::http_callback, nano::stat::dir::out); } }); } else { - if (node_l->config.logging.callback_logging ()) - { - node_l->logger.try_log (boost::str (boost::format ("Unable to connect to callback address: %1%:%2%: %3%") % address % port % ec.message ())); - } + node_l->nlogger.error (nano::log::tag::rpc_callbacks, "Unable to connect to callback address: {}:{} ({})", address, port, ec.message ()); node_l->stats.inc (nano::stat::type::error, nano::stat::detail::http_callback, nano::stat::dir::out); ++i_a; + node_l->do_rpc_callback (i_a, address, port, target, body, resolver); } }); @@ -654,7 +649,7 @@ void nano::node::start () network.port = tcp_listener.port; } - logger.always_log (boost::str (boost::format ("Node started with peering port `%1%`.") % network.port)); + nlogger.info (nano::log::tag::node, "Node peering port: {}", network.port.load ()); } if (!flags.disable_backup) @@ -701,7 +696,7 @@ void nano::node::stop () return; } - logger.always_log ("Node stopping"); + nlogger.info (nano::log::tag::node, "Node stopping..."); // Cancels ongoing work generation tasks, which may be blocking other threads // No tasks may wait for work generation in I/O threads, or termination signal capturing will be unable to call node::stop() @@ -810,7 +805,7 @@ void nano::node::long_inactivity_cleanup () { store.online_weight.clear (transaction); store.peer.clear (transaction); - logger.always_log ("Removed records of peers and online weight after a long period of inactivity"); + nlogger.info (nano::log::tag::node, "Removed records of peers and online weight after a long period of inactivity"); } } @@ -974,7 +969,7 @@ void nano::node::unchecked_cleanup () } if (!cleaning_list.empty ()) { - logger.always_log (boost::str (boost::format ("Deleting %1% old unchecked blocks") % cleaning_list.size ())); + nlogger.info (nano::log::tag::node, "Deleting {} old unchecked blocks", cleaning_list.size ()); } // Delete old unchecked keys in batches while (!cleaning_list.empty ()) @@ -1055,7 +1050,7 @@ bool nano::node::collect_ledger_pruning_targets (std::deque & return !finish_transaction || last_account_a.is_zero (); } -void nano::node::ledger_pruning (uint64_t const batch_size_a, bool bootstrap_weight_reached_a, bool log_to_cout_a) +void nano::node::ledger_pruning (uint64_t const batch_size_a, bool bootstrap_weight_reached_a) { uint64_t const max_depth (config.max_pruning_depth != 0 ? config.max_pruning_depth : std::numeric_limits::max ()); uint64_t const cutoff_time (bootstrap_weight_reached_a ? nano::seconds_since_epoch () - config.max_pruning_age.count () : std::numeric_limits::max ()); @@ -1085,32 +1080,18 @@ void nano::node::ledger_pruning (uint64_t const batch_size_a, bool bootstrap_wei pruning_targets.pop_front (); } pruned_count += transaction_write_count; - auto log_message (boost::str (boost::format ("%1% blocks pruned") % pruned_count)); - if (!log_to_cout_a) - { - logger.try_log (log_message); - } - else - { - std::cout << log_message << std::endl; - } + + nlogger.debug (nano::log::tag::prunning, "Pruned blocks: {}", pruned_count); } } - auto const log_message (boost::str (boost::format ("Total recently pruned block count: %1%") % pruned_count)); - if (!log_to_cout_a) - { - logger.always_log (log_message); - } - else - { - std::cout << log_message << std::endl; - } + + nlogger.debug (nano::log::tag::prunning, "Total recently pruned block count: {}", pruned_count); } void nano::node::ongoing_ledger_pruning () { auto bootstrap_weight_reached (ledger.cache.block_count >= ledger.bootstrap_weight_max_blocks); - ledger_pruning (flags.block_processor_batch_size != 0 ? flags.block_processor_batch_size : 2 * 1024, bootstrap_weight_reached, false); + ledger_pruning (flags.block_processor_batch_size != 0 ? flags.block_processor_batch_size : 2 * 1024, bootstrap_weight_reached); auto const ledger_pruning_interval (bootstrap_weight_reached ? config.max_pruning_age : std::min (config.max_pruning_age, std::chrono::seconds (15 * 60))); auto this_l (shared ()); workers.add_timed_task (std::chrono::steady_clock::now () + ledger_pruning_interval, [this_l] () { @@ -1237,7 +1218,7 @@ void nano::node::add_initial_peers () { if (flags.disable_add_initial_peers) { - logger.always_log ("Skipping add_initial_peers because disable_add_initial_peers is set"); + nlogger.warn (nano::log::tag::node, "Not adding initial peers because `disable_add_initial_peers` flag is set"); return; } @@ -1317,12 +1298,12 @@ void nano::node::receive_confirmed (store::transaction const & block_transaction { if (!ledger.block_or_pruned_exists (block_transaction_a, hash_a)) { - logger.try_log (boost::str (boost::format ("Confirmed block is missing: %1%") % hash_a.to_string ())); - debug_assert (false && "Confirmed block is missing"); + nlogger.warn (nano::log::tag::node, "Confirmed block is missing: {}", hash_a.to_string ()); + debug_assert (false, "Confirmed block is missing"); } else { - logger.try_log (boost::str (boost::format ("Block %1% has already been received") % hash_a.to_string ())); + nlogger.warn (nano::log::tag::node, "Block has already been received: {}", hash_a.to_string ()); } } } diff --git a/nano/node/node.hpp b/nano/node/node.hpp index e396f20a0c..435962312a 100644 --- a/nano/node/node.hpp +++ b/nano/node/node.hpp @@ -1,6 +1,8 @@ #pragma once #include +#include +#include #include #include #include @@ -68,6 +70,9 @@ outbound_bandwidth_limiter::config outbound_bandwidth_limiter_config (node_confi class node final : public std::enable_shared_from_this { +public: + nano::nlogger nlogger; + public: node (boost::asio::io_context &, uint16_t, std::filesystem::path const &, nano::logging const &, nano::work_pool &, nano::node_flags = nano::node_flags (), unsigned seq = 0); node (boost::asio::io_context &, std::filesystem::path const &, nano::node_config const &, nano::work_pool &, nano::node_flags = nano::node_flags (), unsigned seq = 0); @@ -106,7 +111,7 @@ class node final : public std::enable_shared_from_this void bootstrap_wallet (); void unchecked_cleanup (); bool collect_ledger_pruning_targets (std::deque &, nano::account &, uint64_t const, uint64_t const, uint64_t const); - void ledger_pruning (uint64_t const, bool, bool); + void ledger_pruning (uint64_t const, bool); void ongoing_ledger_pruning (); int price (nano::uint128_t const &, int); // The default difficulty updates to base only when the first epoch_2 block is processed @@ -228,7 +233,8 @@ class node final : public std::enable_shared_from_this void long_inactivity_cleanup (); }; -nano::keypair load_or_create_node_id (std::filesystem::path const & application_path, nano::logger_mt & logger); +nano::keypair load_or_create_node_id (std::filesystem::path const & application_path, nano::nlogger &); + std::unique_ptr collect_container_info (node & node, std::string const & name); nano::node_flags const & inactive_node_flag_defaults (); diff --git a/nano/node/openclwork.cpp b/nano/node/openclwork.cpp index 8389a19fb3..5d20638721 100644 --- a/nano/node/openclwork.cpp +++ b/nano/node/openclwork.cpp @@ -1,4 +1,5 @@ #include +#include #include #include #include @@ -249,7 +250,7 @@ void nano::opencl_environment::dump (std::ostream & stream) } } -nano::opencl_work::opencl_work (bool & error_a, nano::opencl_config const & config_a, nano::opencl_environment & environment_a, nano::logger_mt & logger_a, nano::work_thresholds & work) : +nano::opencl_work::opencl_work (bool & error_a, nano::opencl_config const & config_a, nano::opencl_environment & environment_a, nano::nlogger & nlogger_a, nano::work_thresholds & work) : config (config_a), context (0), attempt_buffer (0), @@ -259,7 +260,7 @@ nano::opencl_work::opencl_work (bool & error_a, nano::opencl_config const & conf program (0), kernel (0), queue (0), - logger (logger_a), + nlogger (nlogger_a), work{ work } { error_a |= config.platform >= environment_a.platforms.size (); @@ -343,85 +344,85 @@ nano::opencl_work::opencl_work (bool & error_a, nano::opencl_config const & conf } else { - logger.always_log (boost::str (boost::format ("Bind argument 3 error %1%") % arg3_error)); + nlogger.error (nano::log::tag::opencl_work, "Bind argument 3 error: {}", arg3_error); } } else { - logger.always_log (boost::str (boost::format ("Bind argument 2 error %1%") % arg2_error)); + nlogger.error (nano::log::tag::opencl_work, "Bind argument 2 error: {}", arg2_error); } } else { - logger.always_log (boost::str (boost::format ("Bind argument 1 error %1%") % arg1_error)); + nlogger.error (nano::log::tag::opencl_work, "Bind argument 1 error: {}", arg1_error); } } else { - logger.always_log (boost::str (boost::format ("Bind argument 0 error %1%") % arg0_error)); + nlogger.error (nano::log::tag::opencl_work, "Bind argument 0 error: {}", arg0_error); } } else { - logger.always_log (boost::str (boost::format ("Create kernel error %1%") % kernel_error)); + nlogger.error (nano::log::tag::opencl_work, "Create kernel error: {}", kernel_error); } } else { - logger.always_log (boost::str (boost::format ("Build program error %1%") % clBuildProgramError)); + nlogger.error (nano::log::tag::opencl_work, "Build program error: {}", clBuildProgramError); for (auto i (selected_devices.begin ()), n (selected_devices.end ()); i != n; ++i) { std::size_t log_size (0); clGetProgramBuildInfo (program, *i, CL_PROGRAM_BUILD_LOG, 0, nullptr, &log_size); std::vector log (log_size); clGetProgramBuildInfo (program, *i, CL_PROGRAM_BUILD_LOG, log.size (), log.data (), nullptr); - logger.always_log (log.data ()); + nlogger.info (nano::log::tag::opencl_work, "Device log: {}", log.data ()); } } } else { - logger.always_log (boost::str (boost::format ("Create program error %1%") % program_error)); + nlogger.error (nano::log::tag::opencl_work, "Create program error: {}", program_error); } } else { - logger.always_log (boost::str (boost::format ("Difficulty buffer error %1%") % difficulty_error)); + nlogger.error (nano::log::tag::opencl_work, "Difficulty buffer error: {}", difficulty_error); } } else { - logger.always_log (boost::str (boost::format ("Item buffer error %1%") % item_error)); + nlogger.error (nano::log::tag::opencl_work, "Item buffer error: {}", item_error); } } else { - logger.always_log (boost::str (boost::format ("Result buffer error %1%") % result_error)); + nlogger.error (nano::log::tag::opencl_work, "Result buffer error: {}", result_error); } } else { - logger.always_log (boost::str (boost::format ("Attempt buffer error %1%") % attempt_error)); + nlogger.error (nano::log::tag::opencl_work, "Attempt buffer error: {}", attempt_error); } } else { - logger.always_log (boost::str (boost::format ("Unable to create command queue %1%") % queue_error)); + nlogger.error (nano::log::tag::opencl_work, "Unable to create command queue: {}", queue_error); } } else { - logger.always_log (boost::str (boost::format ("Unable to create context %1%") % createContextError)); + nlogger.error (nano::log::tag::opencl_work, "Unable to create context: {}", createContextError); } } else { - logger.always_log (boost::str (boost::format ("Requested device %1%, and only have %2%") % config.device % platform.devices.size ())); + nlogger.error (nano::log::tag::opencl_work, "Requested device {} and only have {}", config.device, platform.devices.size ()); } } else { - logger.always_log (boost::str (boost::format ("Requested platform %1% and only have %2%") % config.platform % environment_a.platforms.size ())); + nlogger.error (nano::log::tag::opencl_work, "Requested platform {} and only have {}", config.platform, environment_a.platforms.size ()); } } @@ -480,37 +481,37 @@ boost::optional nano::opencl_work::generate_work (nano::work_version c else { error = true; - logger.always_log (boost::str (boost::format ("Error finishing queue %1%") % finishError)); + nlogger.error (nano::log::tag::opencl_work, "Error finishing queue: {}", finishError); } } else { error = true; - logger.always_log (boost::str (boost::format ("Error reading result %1%") % read_error1)); + nlogger.error (nano::log::tag::opencl_work, "Error reading result: {}", read_error1); } } else { error = true; - logger.always_log (boost::str (boost::format ("Error enqueueing kernel %1%") % enqueue_error)); + nlogger.error (nano::log::tag::opencl_work, "Error enqueueing kernel: {}", enqueue_error); } } else { error = true; - logger.always_log (boost::str (boost::format ("Error writing item %1%") % write_error3)); + nlogger.error (nano::log::tag::opencl_work, "Error writing difficulty: {}", write_error3); } } else { error = true; - logger.always_log (boost::str (boost::format ("Error writing item %1%") % write_error2)); + nlogger.error (nano::log::tag::opencl_work, "Error writing item: {}", write_error2); } } else { error = true; - logger.always_log (boost::str (boost::format ("Error writing attempt %1%") % write_error1)); + nlogger.error (nano::log::tag::opencl_work, "Error writing attempt: {}", write_error1); } } boost::optional value; @@ -521,19 +522,21 @@ boost::optional nano::opencl_work::generate_work (nano::work_version c return value; } -std::unique_ptr nano::opencl_work::create (bool create_a, nano::opencl_config const & config_a, nano::logger_mt & logger_a, nano::work_thresholds & work) +std::unique_ptr nano::opencl_work::create (bool create_a, nano::opencl_config const & config_a, nano::nlogger & nlogger_a, nano::work_thresholds & work) { std::unique_ptr result; if (create_a) { auto error (false); + nano::opencl_environment environment (error); std::stringstream stream; environment.dump (stream); - logger_a.always_log (stream.str ()); + nlogger_a.info (nano::log::tag::opencl_work, "OpenCL environment: {}", stream.str ()); + if (!error) { - result.reset (new nano::opencl_work (error, config_a, environment, logger_a, work)); + result.reset (new nano::opencl_work (error, config_a, environment, nlogger_a, work)); if (error) { result.reset (); diff --git a/nano/node/openclwork.hpp b/nano/node/openclwork.hpp index 2f452e092e..de76e6e416 100644 --- a/nano/node/openclwork.hpp +++ b/nano/node/openclwork.hpp @@ -21,7 +21,7 @@ namespace nano { extern bool opencl_loaded; -class logger_mt; +class nlogger; class opencl_platform { public: @@ -40,11 +40,11 @@ class work_pool; class opencl_work { public: - opencl_work (bool &, nano::opencl_config const &, nano::opencl_environment &, nano::logger_mt &, nano::work_thresholds & work); + opencl_work (bool &, nano::opencl_config const &, nano::opencl_environment &, nano::nlogger &, nano::work_thresholds & work); ~opencl_work (); boost::optional generate_work (nano::work_version const, nano::root const &, uint64_t const); boost::optional generate_work (nano::work_version const, nano::root const &, uint64_t const, std::atomic &); - static std::unique_ptr create (bool, nano::opencl_config const &, nano::logger_mt &, nano::work_thresholds & work); + static std::unique_ptr create (bool, nano::opencl_config const &, nano::nlogger &, nano::work_thresholds & work); nano::opencl_config const & config; nano::mutex mutex; cl_context context; @@ -56,7 +56,7 @@ class opencl_work cl_kernel kernel; cl_command_queue queue; nano::xorshift1024star rand; - nano::logger_mt & logger; + nano::nlogger & nlogger; nano::work_thresholds & work; }; } diff --git a/nano/node/portmapping.cpp b/nano/node/portmapping.cpp index 690b7ce907..580416a6a8 100644 --- a/nano/node/portmapping.cpp +++ b/nano/node/portmapping.cpp @@ -60,17 +60,19 @@ void nano::port_mapping::refresh_devices () std::array local_address_l; local_address_l.fill (0); auto igd_error_l (UPNP_GetValidIGD (upnp_l.devices, &upnp_l.urls, &upnp_l.data, local_address_l.data (), sizeof (local_address_l))); - if (check_count % 15 == 0 || node.config.logging.upnp_details_logging ()) + + // Bump logging level periodically + node.nlogger.log ((check_count % 15 == 0) ? nano::log::level::info : nano::log::level::debug, + nano::log::tag::upnp, "UPnP local address {}, discovery: {}, IGD search: {}", + local_address_l.data (), + discover_error_l, + igd_error_l); + + for (auto i (upnp_l.devices); i != nullptr; i = i->pNext) { - node.logger.always_log (boost::str (boost::format ("UPnP local address: %1%, discovery: %2%, IGD search: %3%") % local_address_l.data () % discover_error_l % igd_error_l)); - if (node.config.logging.upnp_details_logging ()) - { - for (auto i (upnp_l.devices); i != nullptr; i = i->pNext) - { - node.logger.always_log (boost::str (boost::format ("UPnP device url: %1% st: %2% usn: %3%") % i->descURL % i->st % i->usn)); - } - } + node.nlogger.debug (nano::log::tag::upnp, "UPnP device url: {}, st: {}, usn: {}", i->descURL, i->st, i->usn); } + // Update port mapping nano::lock_guard guard_l (mutex); upnp = std::move (upnp_l); @@ -114,14 +116,23 @@ void nano::port_mapping::refresh_mapping () if (add_port_mapping_error_l == UPNPCOMMAND_SUCCESS) { protocol.external_port = static_cast (std::atoi (config_port_l.data ())); - auto fmt = boost::format ("UPnP %1% %2%:%3% mapped to %4%") % protocol.name % protocol.external_address % config_port_l % node_port_l; - node.logger.always_log (boost::str (fmt)); + + node.nlogger.info (nano::log::tag::upnp, "UPnP {} {}:{} mapped to: {}", + protocol.name, + protocol.external_address.to_string (), + config_port_l, + node_port_l); } else { protocol.external_port = 0; - auto fmt = boost::format ("UPnP %1% %2%:%3% FAILED") % protocol.name % add_port_mapping_error_l % strupnperror (add_port_mapping_error_l); - node.logger.always_log (boost::str (fmt)); + + node.nlogger.warn (nano::log::tag::upnp, "UPnP {} {}:{} failed: {} ({})", + protocol.name, + protocol.external_address.to_string (), + config_port_l, + add_port_mapping_error_l, + strupnperror (add_port_mapping_error_l)); } } } @@ -149,12 +160,19 @@ bool nano::port_mapping::check_lost_or_old_mapping () if (verify_port_mapping_error_l != UPNPCOMMAND_SUCCESS) { result_l = true; - node.logger.always_log (boost::str (boost::format ("UPNP_GetSpecificPortMappingEntry failed %1%: %2%") % verify_port_mapping_error_l % strupnperror (verify_port_mapping_error_l))); + + node.nlogger.warn (nano::log::tag::upnp, "UPnP get specific port mapping failed: {} ({})", + verify_port_mapping_error_l, + strupnperror (verify_port_mapping_error_l)); } if (!recent_lease) { result_l = true; - node.logger.always_log (boost::str (boost::format ("UPnP leasing time getting old, remaining time: %1%, lease time: %2%, below the threshold: %3%") % remaining_from_port_mapping % lease_duration % lease_duration_divided_by_two)); + + node.nlogger.info (nano::log::tag::upnp, "UPnP lease time getting old, remaining time: {}, lease time: {}, below the threshold: {}", + remaining_from_port_mapping, + lease_duration, + lease_duration_divided_by_two); } std::array external_address_l; external_address_l.fill (0); @@ -168,12 +186,19 @@ bool nano::port_mapping::check_lost_or_old_mapping () else { protocol.external_address = boost::asio::ip::address_v4::any (); - node.logger.always_log (boost::str (boost::format ("UPNP_GetExternalIPAddress failed %1%: %2%") % verify_port_mapping_error_l % strupnperror (verify_port_mapping_error_l))); - } - if (node.config.logging.upnp_details_logging ()) - { - node.logger.always_log (boost::str (boost::format ("UPnP %1% mapping verification response: %2%, external ip response: %3%, external ip: %4%, internal ip: %5%, remaining lease: %6%") % protocol.name % verify_port_mapping_error_l % external_ip_error_l % external_address_l.data () % address.to_string () % remaining_mapping_duration_l.data ())); + + node.nlogger.warn (nano::log::tag::upnp, "UPnP get external ip address failed: {} ({})", + external_ip_error_l, + strupnperror (external_ip_error_l)); } + + node.nlogger.debug (nano::log::tag::upnp, "UPnP {} mapping verification response: {}, external ip response: {}, external ip: {}, internal ip: {}, remaining lease: {}", + protocol.name, + verify_port_mapping_error_l, + external_ip_error_l, + external_address_l.data (), + address.to_string (), + remaining_mapping_duration_l.data ()); } return result_l; } @@ -194,15 +219,14 @@ void nano::port_mapping::check_mapping_loop () } else { - node.logger.always_log (boost::str (boost::format ("UPnP No need to refresh the mapping"))); + node.nlogger.info (nano::log::tag::upnp, "UPnP No need to refresh the mapping"); } } else { - if (check_count < 10 || node.config.logging.upnp_details_logging ()) - { - node.logger.always_log (boost::str (boost::format ("UPnP No IGD devices found"))); - } + // Bump logging level periodically + node.nlogger.log ((check_count % 15 == 0) ? nano::log::level::info : nano::log::level::debug, + nano::log::tag::upnp, "UPnP No IGD devices found"); } // Check for new devices or after health_check_period @@ -225,11 +249,17 @@ void nano::port_mapping::stop () auto delete_error_l (UPNP_DeletePortMapping (upnp.urls.controlURL, upnp.data.first.servicetype, std::to_string (protocol.external_port).c_str (), protocol.name, address.to_string ().c_str ())); if (delete_error_l) { - node.logger.always_log (boost::str (boost::format ("UPnP shutdown %1% port mapping response: %2%") % protocol.name % delete_error_l)); + node.nlogger.warn (nano::log::tag::upnp, "UPnP shutdown {} port mapping failed: {} ({})", + protocol.name, + delete_error_l, + strupnperror (delete_error_l)); } else { - node.logger.always_log (boost::str (boost::format ("UPnP shutdown %1% port mapping successful: %2%:%3%") % protocol.name % protocol.external_address % protocol.external_port)); + node.nlogger.info (nano::log::tag::upnp, "UPnP shutdown {} port mapping successful: {}:{}", + protocol.name, + protocol.external_address.to_string (), + protocol.external_port); } } } diff --git a/nano/node/repcrawler.cpp b/nano/node/repcrawler.cpp index 2a8aad7a04..1a83a2ecb9 100644 --- a/nano/node/repcrawler.cpp +++ b/nano/node/repcrawler.cpp @@ -45,20 +45,18 @@ void nano::rep_crawler::validate () if (channel->get_type () == nano::transport::transport_type::loopback) { - if (node.config.logging.rep_crawler_logging ()) - { - node.logger.try_log (boost::str (boost::format ("rep_crawler ignoring vote from loopback channel %1%") % channel->to_string ())); - } + node.nlogger.debug (nano::log::tag::repcrawler, "Ignoring vote from loopback channel: {}", channel->to_string ()); + continue; } nano::uint128_t rep_weight = node.ledger.weight (vote->account); if (rep_weight < minimum) { - if (node.config.logging.rep_crawler_logging ()) - { - node.logger.try_log (boost::str (boost::format ("rep_crawler ignoring vote from account %1% with too little voting weight %2%") % vote->account.to_account () % rep_weight)); - } + node.nlogger.debug (nano::log::tag::repcrawler, "Ignoring vote from account {} with too little voting weight: {}", + vote->account.to_account (), + nano::util::to_str (rep_weight)); + continue; } @@ -95,12 +93,11 @@ void nano::rep_crawler::validate () if (inserted) { - node.logger.try_log (boost::str (boost::format ("Found representative %1% at %2%") % vote->account.to_account () % channel->to_string ())); + node.nlogger.info (nano::log::tag::repcrawler, "Found representative {} at {}", vote->account.to_account (), channel->to_string ()); } - if (updated) { - node.logger.try_log (boost::str (boost::format ("Updated representative %1% at %2% (was at: %3%)") % vote->account.to_account () % channel->to_string () % prev_channel->to_string ())); + node.nlogger.warn (nano::log::tag::repcrawler, "Updated representative {} at {} (was at: {})", vote->account.to_account (), channel->to_string (), prev_channel->to_string ()); } } } diff --git a/nano/node/transport/channel.cpp b/nano/node/transport/channel.cpp index 39037b734b..4649726786 100644 --- a/nano/node/transport/channel.cpp +++ b/nano/node/transport/channel.cpp @@ -22,23 +22,20 @@ void nano::transport::channel::send (nano::message & message_a, std::function #include +#include + nano::transport::message_deserializer::message_deserializer (nano::network_constants const & network_constants_a, nano::network_filter & publish_filter_a, nano::block_uniquer & block_uniquer_a, nano::vote_uniquer & vote_uniquer_a, read_query read_op) : read_buffer{ std::make_shared> () }, @@ -380,8 +382,10 @@ std::unique_ptr nano::transport::message_deserializer::deser return {}; } -nano::stat::detail nano::transport::message_deserializer::to_stat_detail (parse_status status) +nano::stat::detail nano::to_stat_detail (nano::transport::message_deserializer::parse_status status) { + using parse_status = nano::transport::message_deserializer::parse_status; + // Keep additional `break` for readability switch (status) { @@ -449,74 +453,7 @@ nano::stat::detail nano::transport::message_deserializer::to_stat_detail (parse_ return {}; } -std::string nano::transport::message_deserializer::to_string (parse_status status) +std::string_view nano::to_string (nano::transport::message_deserializer::parse_status status) { - // Keep additional `break` for readability - switch (status) - { - case parse_status::none: - return "none"; - break; - case parse_status::success: - return "success"; - break; - case parse_status::insufficient_work: - return "insufficient_work"; - break; - case parse_status::invalid_header: - return "invalid_header"; - break; - case parse_status::invalid_message_type: - return "invalid_message_type"; - break; - case parse_status::invalid_keepalive_message: - return "invalid_keepalive_message"; - break; - case parse_status::invalid_publish_message: - return "invalid_publish_message"; - break; - case parse_status::invalid_confirm_req_message: - return "invalid_confirm_req_message"; - break; - case parse_status::invalid_confirm_ack_message: - return "invalid_confirm_ack_message"; - break; - case parse_status::invalid_node_id_handshake_message: - return "invalid_node_id_handshake_message"; - break; - case parse_status::invalid_telemetry_req_message: - return "invalid_telemetry_req_message"; - break; - case parse_status::invalid_telemetry_ack_message: - return "invalid_telemetry_ack_message"; - break; - case parse_status::invalid_bulk_pull_message: - return "invalid_bulk_pull_message"; - break; - case parse_status::invalid_bulk_pull_account_message: - return "invalid_bulk_pull_account_message"; - break; - case parse_status::invalid_frontier_req_message: - return "invalid_frontier_req_message"; - break; - case parse_status::invalid_asc_pull_req_message: - return "invalid_asc_pull_req_message"; - break; - case parse_status::invalid_asc_pull_ack_message: - return "invalid_asc_pull_ack_message"; - break; - case parse_status::invalid_network: - return "invalid_network"; - break; - case parse_status::outdated_version: - return "outdated_version"; - break; - case parse_status::duplicate_publish_message: - return "duplicate_publish_message"; - break; - case parse_status::message_size_too_big: - return "message_size_too_big"; - break; - } - return "n/a"; + return magic_enum::enum_name (status); } diff --git a/nano/node/transport/message_deserializer.hpp b/nano/node/transport/message_deserializer.hpp index 0a85454e51..9a2fbc21c6 100644 --- a/nano/node/transport/message_deserializer.hpp +++ b/nano/node/transport/message_deserializer.hpp @@ -89,11 +89,9 @@ namespace transport nano::block_uniquer & block_uniquer_m; nano::vote_uniquer & vote_uniquer_m; read_query read_op; - - public: - static stat::detail to_stat_detail (parse_status); - static std::string to_string (parse_status); }; - } + +nano::stat::detail to_stat_detail (nano::transport::message_deserializer::parse_status); +std::string_view to_string (nano::transport::message_deserializer::parse_status); } diff --git a/nano/node/transport/socket.cpp b/nano/node/transport/socket.cpp index 629fe3b5fa..596e599cc2 100644 --- a/nano/node/transport/socket.cpp +++ b/nano/node/transport/socket.cpp @@ -74,6 +74,7 @@ void nano::transport::socket::async_connect (nano::tcp_endpoint const & endpoint this_l->tcp_socket.async_connect (endpoint_a, boost::asio::bind_executor (this_l->strand, [this_l, callback = std::move (callback_a), endpoint_a] (boost::system::error_code const & ec) { + this_l->remote = endpoint_a; if (ec) { this_l->node.stats.inc (nano::stat::type::tcp, nano::stat::detail::tcp_connect_error, nano::stat::dir::in); @@ -82,9 +83,13 @@ void nano::transport::socket::async_connect (nano::tcp_endpoint const & endpoint else { this_l->set_last_completion (); + { + // Best effort attempt to get endpoint address + boost::system::error_code ec; + this_l->local = this_l->tcp_socket.local_endpoint (ec); + } + this_l->node.observers.socket_connected.notify (*this_l); } - this_l->remote = endpoint_a; - this_l->node.observers.socket_connected.notify (*this_l); callback (ec); })); } @@ -261,23 +266,22 @@ void nano::transport::socket::ongoing_checkup () if (this_l->endpoint_type () == endpoint_type_t::server && (now - this_l->last_receive_time_or_init) > static_cast (this_l->silent_connection_tolerance_time.count ())) { this_l->node.stats.inc (nano::stat::type::tcp, nano::stat::detail::tcp_silent_connection_drop, nano::stat::dir::in); + condition_to_disconnect = true; } // if there is no activity for timeout seconds then disconnect if ((now - this_l->last_completion_time_or_init) > this_l->timeout) { - this_l->node.stats.inc (nano::stat::type::tcp, nano::stat::detail::tcp_io_timeout_drop, - this_l->endpoint_type () == endpoint_type_t::server ? nano::stat::dir::in : nano::stat::dir::out); + this_l->node.stats.inc (nano::stat::type::tcp, nano::stat::detail::tcp_io_timeout_drop, this_l->endpoint_type () == endpoint_type_t::server ? nano::stat::dir::in : nano::stat::dir::out); + condition_to_disconnect = true; } if (condition_to_disconnect) { - if (this_l->node.config.logging.network_timeout_logging ()) - { - this_l->node.logger.try_log (boost::str (boost::format ("Disconnecting from %1% due to timeout") % this_l->remote)); - } + this_l->node.nlogger.debug (nano::log::tag::tcp_server, "Closing socket due to timeout ({})", nano::util::to_str (this_l->remote)); + this_l->timed_out = true; this_l->close (); } @@ -350,19 +354,21 @@ void nano::transport::socket::close_internal () if (ec) { - node.logger.try_log ("Failed to close socket gracefully: ", ec.message ()); - node.stats.inc (nano::stat::type::bootstrap, nano::stat::detail::error_socket_close); + node.stats.inc (nano::stat::type::socket, nano::stat::detail::error_socket_close); + node.nlogger.error (nano::log::tag::socket, "Failed to close socket gracefully: {} ({})", ec.message (), nano::util::to_str (remote)); } } nano::tcp_endpoint nano::transport::socket::remote_endpoint () const { + // Using cached value to avoid calling tcp_socket.remote_endpoint() which may be invalid (throw) after closing the socket return remote; } nano::tcp_endpoint nano::transport::socket::local_endpoint () const { - return tcp_socket.local_endpoint (); + // Using cached value to avoid calling tcp_socket.local_endpoint() which may be invalid (throw) after closing the socket + return local; } /* @@ -550,7 +556,7 @@ void nano::transport::server_socket::on_connection (std::functionacceptor.is_open ()) { - this_l->node.logger.always_log ("Network: Acceptor is not open"); + this_l->node.nlogger.error (nano::log::tag::socket_server, "Acceptor is not open"); return; } @@ -563,20 +569,18 @@ void nano::transport::server_socket::on_connection (std::functionconnections_per_address.size () >= this_l->max_inbound_connections) { - this_l->node.logger.try_log ("Network: max_inbound_connections reached, unable to open new connection"); this_l->node.stats.inc (nano::stat::type::tcp, nano::stat::detail::tcp_accept_failure, nano::stat::dir::in); + this_l->node.nlogger.debug (nano::log::tag::socket_server, "Max connections reached ({}), unable to open new connection", this_l->connections_per_address.size ()); + this_l->on_connection_requeue_delayed (std::move (cbk)); return; } if (this_l->limit_reached_for_incoming_ip_connections (new_connection)) { - auto const remote_ip_address = new_connection->remote_endpoint ().address (); - auto const log_message = boost::str ( - boost::format ("Network: max connections per IP (max_peers_per_ip) was reached for %1%, unable to open new connection") - % remote_ip_address.to_string ()); - this_l->node.logger.try_log (log_message); this_l->node.stats.inc (nano::stat::type::tcp, nano::stat::detail::tcp_max_per_ip, nano::stat::dir::in); + this_l->node.nlogger.debug (nano::log::tag::socket_server, "Max connections per IP reached ({}), unable to open new connection", new_connection->remote_endpoint ().address ().to_string ()); + this_l->on_connection_requeue_delayed (std::move (cbk)); return; } @@ -586,37 +590,47 @@ void nano::transport::server_socket::on_connection (std::functionremote_endpoint ().address (); debug_assert (remote_ip_address.is_v6 ()); auto const remote_subnet = socket_functions::get_ipv6_subnet_address (remote_ip_address.to_v6 (), this_l->node.network_params.network.max_peers_per_subnetwork); - auto const log_message = boost::str ( - boost::format ("Network: max connections per subnetwork (max_peers_per_subnetwork) was reached for subnetwork %1% (remote IP: %2%), unable to open new connection") - % remote_subnet.canonical ().to_string () - % remote_ip_address.to_string ()); - this_l->node.logger.try_log (log_message); + this_l->node.stats.inc (nano::stat::type::tcp, nano::stat::detail::tcp_max_per_subnetwork, nano::stat::dir::in); + this_l->node.nlogger.debug (nano::log::tag::socket_server, "Max connections per subnetwork reached (subnetwork: {}, ip: {}), unable to open new connection", + remote_subnet.canonical ().to_string (), + remote_ip_address.to_string ()); + this_l->on_connection_requeue_delayed (std::move (cbk)); return; } if (!ec_a) { + { + // Best effort attempt to get endpoint addresses + boost::system::error_code ec; + new_connection->local = new_connection->tcp_socket.local_endpoint (ec); + } + // Make sure the new connection doesn't idle. Note that in most cases, the callback is going to start // an IO operation immediately, which will start a timer. new_connection->start (); new_connection->set_timeout (this_l->node.network_params.network.idle_timeout); + this_l->node.stats.inc (nano::stat::type::tcp, nano::stat::detail::tcp_accept_success, nano::stat::dir::in); + this_l->connections_per_address.emplace (new_connection->remote.address (), new_connection); this_l->node.observers.socket_accepted.notify (*new_connection); + if (cbk (new_connection, ec_a)) { this_l->on_connection (std::move (cbk)); return; } - this_l->node.logger.always_log ("Network: Stopping to accept connections"); + + this_l->node.nlogger.warn (nano::log::tag::socket_server, "Stopping to accept new connections"); return; } // accept error - this_l->node.logger.try_log ("Network: Unable to accept connection: ", ec_a.message ()); this_l->node.stats.inc (nano::stat::type::tcp, nano::stat::detail::tcp_accept_failure, nano::stat::dir::in); + this_l->node.nlogger.error (nano::log::tag::socket_server, "Unable to accept connection: {} ({})", ec_a.message (), new_connection->remote_endpoint ().address ().to_string ()); if (is_temporary_error (ec_a)) { @@ -633,7 +647,7 @@ void nano::transport::server_socket::on_connection (std::functionnode.logger.always_log ("Network: Stopping to accept connections"); + this_l->node.nlogger.warn (nano::log::tag::socket_server, "Stopping to accept new connections"); })); })); } diff --git a/nano/node/transport/socket.hpp b/nano/node/transport/socket.hpp index d0afec196b..1f7d768510 100644 --- a/nano/node/transport/socket.hpp +++ b/nano/node/transport/socket.hpp @@ -4,6 +4,7 @@ #include #include #include +#include #include #include @@ -159,6 +160,7 @@ class socket : public std::enable_shared_from_this /** The other end of the connection */ boost::asio::ip::tcp::endpoint remote; + boost::asio::ip::tcp::endpoint local; /** number of seconds of inactivity that causes a socket timeout * activity is any successful connect, send or receive event diff --git a/nano/node/transport/tcp.cpp b/nano/node/transport/tcp.cpp index c62bf3dbed..7a85721a4a 100644 --- a/nano/node/transport/tcp.cpp +++ b/nano/node/transport/tcp.cpp @@ -98,7 +98,7 @@ void nano::transport::channel_tcp::send_buffer (nano::shared_const_buffer const std::string nano::transport::channel_tcp::to_string () const { - return boost::str (boost::format ("%1%") % get_tcp_endpoint ()); + return nano::util::to_str (get_tcp_endpoint ()); } void nano::transport::channel_tcp::set_endpoint () @@ -555,10 +555,9 @@ void nano::transport::tcp_channels::start_tcp (nano::endpoint const & endpoint_a auto query = node_l->network.prepare_handshake_query (endpoint_a); nano::node_id_handshake message{ node_l->network_params.network, query }; - if (node_l->config.logging.network_node_id_handshake_logging ()) - { - node_l->logger.try_log (boost::str (boost::format ("Node ID handshake request sent with node ID %1% to %2%: query %3%") % node_l->node_id.pub.to_node_id () % endpoint_a % (query ? query->cookie.to_string () : "not set"))); - } + node_l->nlogger.debug (nano::log::tag::tcp, "Handshake sent to: {} (query: {})", + nano::util::to_str (endpoint_a), + (query ? query->cookie.to_string () : "")); channel->set_endpoint (); std::shared_ptr> receive_buffer (std::make_shared> ()); @@ -572,30 +571,25 @@ void nano::transport::tcp_channels::start_tcp (nano::endpoint const & endpoint_a } else { + node_l->nlogger.debug (nano::log::tag::tcp, "Error sending handshake to: {} ({})", nano::util::to_str (endpoint_a), ec.message ()); + if (auto socket_l = channel->socket.lock ()) { socket_l->close (); } - if (node_l->config.logging.network_node_id_handshake_logging ()) - { - node_l->logger.try_log (boost::str (boost::format ("Error sending node_id_handshake to %1%: %2%") % endpoint_a % ec.message ())); - } } } }); } else { - if (node_l->config.logging.network_logging ()) + if (ec) { - if (ec) - { - node_l->logger.try_log (boost::str (boost::format ("Error connecting to %1%: %2%") % endpoint_a % ec.message ())); - } - else - { - node_l->logger.try_log (boost::str (boost::format ("Error connecting to %1%") % endpoint_a)); - } + node_l->nlogger.debug (nano::log::tag::tcp, "Error connecting to: {} ({})", nano::util::to_str (endpoint_a), ec.message ()); + } + else + { + node_l->nlogger.debug (nano::log::tag::tcp, "Error connecting to: {}", nano::util::to_str (endpoint_a)); } } } @@ -633,10 +627,8 @@ void nano::transport::tcp_channels::start_tcp_receive_node_id (std::shared_ptrconfig.logging.network_node_id_handshake_logging ()) - { - node_l->logger.try_log (boost::str (boost::format ("Error reading node_id_handshake from %1%: %2%") % endpoint_a % ec.message ())); - } + node_l->nlogger.debug (nano::log::tag::tcp, "Error reading handshake from: {} ({})", nano::util::to_str (endpoint_a), ec.message ()); + cleanup_node_id_handshake_socket (endpoint_a); return; } @@ -646,10 +638,8 @@ void nano::transport::tcp_channels::start_tcp_receive_node_id (std::shared_ptrtype () != nano::message_type::node_id_handshake) { - if (node_l->config.logging.network_node_id_handshake_logging ()) - { - node_l->logger.try_log (boost::str (boost::format ("Error reading node_id_handshake message header from %1%") % endpoint_a)); - } + node_l->nlogger.debug (nano::log::tag::tcp, "Error reading handshake header from: {} ({})", nano::util::to_str (endpoint_a), ec.message ()); + cleanup_node_id_handshake_socket (endpoint_a); return; } @@ -678,10 +668,8 @@ void nano::transport::tcp_channels::start_tcp_receive_node_id (std::shared_ptrconfig.logging.network_node_id_handshake_logging ()) - { - node_l->logger.try_log (boost::str (boost::format ("Error reading node_id_handshake from %1%") % endpoint_a)); - } + node_l->nlogger.debug (nano::log::tag::tcp, "Error reading handshake payload from: {} ({})", nano::util::to_str (endpoint_a), ec.message ()); + cleanup_node_id_handshake_socket (endpoint_a); return; } @@ -714,10 +702,9 @@ void nano::transport::tcp_channels::start_tcp_receive_node_id (std::shared_ptrnetwork.prepare_handshake_response (*handshake.query, handshake.is_v2 ()); nano::node_id_handshake handshake_response (node_l->network_params.network, std::nullopt, response); - if (node_l->config.logging.network_node_id_handshake_logging ()) - { - node_l->logger.try_log (boost::str (boost::format ("Node ID handshake response sent with node ID %1% to %2%: query %3%") % node_l->node_id.pub.to_node_id () % endpoint_a % handshake.query->cookie.to_string ())); - } + node_l->nlogger.debug (nano::log::tag::tcp, "Handshake response sent to {} (query: {})", + nano::util::to_str (endpoint_a), + handshake.query->cookie.to_string ()); channel_a->send (handshake_response, [node_w, channel_a, endpoint_a, cleanup_node_id_handshake_socket] (boost::system::error_code const & ec, std::size_t size_a) { auto node_l = node_w.lock (); @@ -727,10 +714,8 @@ void nano::transport::tcp_channels::start_tcp_receive_node_id (std::shared_ptrconfig.logging.network_node_id_handshake_logging ()) - { - node_l->logger.try_log (boost::str (boost::format ("Error sending node_id_handshake to %1%: %2%") % endpoint_a % ec.message ())); - } + node_l->nlogger.debug (nano::log::tag::tcp, "Error sending handshake response to: {} ({})", nano::util::to_str (endpoint_a), ec.message ()); + cleanup_node_id_handshake_socket (endpoint_a); return; } diff --git a/nano/node/transport/tcp_server.cpp b/nano/node/transport/tcp_server.cpp index e9ea664a87..3a45c4ee09 100644 --- a/nano/node/transport/tcp_server.cpp +++ b/nano/node/transport/tcp_server.cpp @@ -29,7 +29,7 @@ void nano::transport::tcp_listener::start () listening_socket->start (ec); if (ec) { - node.logger.always_log (boost::str (boost::format ("Network: Error while binding for incoming TCP/bootstrap on port %1%: %2%") % listening_socket->listening_port () % ec.message ())); + node.nlogger.critical (nano::log::tag::tcp_server, "Error while binding for incoming TCP: {} (port: {})", ec.message (), port); throw std::runtime_error (ec.message ()); } @@ -99,10 +99,7 @@ void nano::transport::tcp_listener::accept_action (boost::system::error_code con else { node.stats.inc (nano::stat::type::tcp, nano::stat::detail::tcp_excluded); - if (node.config.logging.network_rejected_logging ()) - { - node.logger.try_log ("Rejected connection from excluded peer ", socket_a->remote_endpoint ()); - } + node.nlogger.debug (nano::log::tag::tcp_server, "Rejected connection from excluded peer: {}", nano::util::to_str (socket_a->remote_endpoint ())); } } @@ -153,10 +150,8 @@ nano::transport::tcp_server::~tcp_server () { return; } - if (node->config.logging.bulk_pull_logging ()) - { - node->logger.try_log ("Exiting incoming TCP/bootstrap server"); - } + + node->nlogger.debug (nano::log::tag::tcp_server, "Exiting TCP server ({})", nano::util::to_str (remote_endpoint)); if (socket->type () == nano::transport::socket::type_t::bootstrap) { @@ -189,6 +184,12 @@ void nano::transport::tcp_server::start () remote_endpoint = socket->remote_endpoint (); debug_assert (remote_endpoint.port () != 0); } + + if (auto node_l = node.lock (); node_l) + { + node_l->nlogger.debug (nano::log::tag::tcp_server, "Starting TCP server ({})", nano::util::to_str (remote_endpoint)); + } + receive_message (); } @@ -216,7 +217,12 @@ void nano::transport::tcp_server::receive_message () if (ec) { // IO error or critical error when deserializing message - node->stats.inc (nano::stat::type::error, nano::transport::message_deserializer::to_stat_detail (this_l->message_deserializer->status)); + node->stats.inc (nano::stat::type::error, nano::to_stat_detail (this_l->message_deserializer->status)); + node->nlogger.debug (nano::log::tag::tcp_server, "Error reading message: {}, status: {} ({})", + ec.message (), + nano::to_string (this_l->message_deserializer->status), + nano::util::to_str (this_l->remote_endpoint)); + this_l->stop (); } else @@ -242,11 +248,19 @@ void nano::transport::tcp_server::received_message (std::unique_ptrstatus != transport::message_deserializer::parse_status::success); - node->stats.inc (nano::stat::type::error, nano::transport::message_deserializer::to_stat_detail (message_deserializer->status)); + + node->stats.inc (nano::stat::type::error, nano::to_stat_detail (message_deserializer->status)); if (message_deserializer->status == transport::message_deserializer::parse_status::duplicate_publish_message) { node->stats.inc (nano::stat::type::filter, nano::stat::detail::duplicate_publish); } + else + { + // Avoid too much noise about `duplicate_publish_message` errors + node->nlogger.debug (nano::log::tag::tcp_server, "Error deserializing message: {} ({})", + nano::to_string (message_deserializer->status), + nano::util::to_str (remote_endpoint)); + } } if (should_continue) @@ -297,6 +311,10 @@ bool nano::transport::tcp_server::process_message (std::unique_ptrnlogger.debug (nano::log::tag::tcp_server, "Neither handshake nor bootstrap received when in handshake mode: {} ({})", + nano::to_string (message->header.type), + nano::util::to_str (remote_endpoint)); + return true; } } @@ -349,10 +367,8 @@ void nano::transport::tcp_server::handshake_message_visitor::node_id_handshake ( } if (node->flags.disable_tcp_realtime) { - if (node->config.logging.network_node_id_handshake_logging ()) - { - node->logger.try_log (boost::str (boost::format ("Disabled realtime TCP for handshake %1%") % server->remote_endpoint)); - } + node->nlogger.debug (nano::log::tag::tcp_server, "Handshake attempted with disabled realtime TCP ({})", nano::util::to_str (server->remote_endpoint)); + // Stop invalid handshake server->stop (); return; @@ -360,10 +376,8 @@ void nano::transport::tcp_server::handshake_message_visitor::node_id_handshake ( if (message.query && server->handshake_query_received) { - if (node->config.logging.network_node_id_handshake_logging ()) - { - node->logger.try_log (boost::str (boost::format ("Detected multiple node_id_handshake query from %1%") % server->remote_endpoint)); - } + node->nlogger.debug (nano::log::tag::tcp_server, "Detected multiple handshake queries ({})", nano::util::to_str (server->remote_endpoint)); + // Stop invalid handshake server->stop (); return; @@ -371,10 +385,7 @@ void nano::transport::tcp_server::handshake_message_visitor::node_id_handshake ( server->handshake_query_received = true; - if (node->config.logging.network_node_id_handshake_logging ()) - { - node->logger.try_log (boost::str (boost::format ("Received node_id_handshake message from %1%") % server->remote_endpoint)); - } + node->nlogger.debug (nano::log::tag::tcp_server, "Handshake query received ({})", nano::util::to_str (server->remote_endpoint)); if (message.query) { @@ -418,10 +429,8 @@ void nano::transport::tcp_server::send_handshake_response (nano::node_id_handsha } if (ec) { - if (node->config.logging.network_node_id_handshake_logging ()) - { - node->logger.try_log (boost::str (boost::format ("Error sending node_id_handshake to %1%: %2%") % this_l->remote_endpoint % ec.message ())); - } + node->nlogger.debug (nano::log::tag::tcp_server, "Error sending handshake response: {} ({})", ec.message (), nano::util::to_str (this_l->remote_endpoint)); + // Stop invalid handshake this_l->stop (); } @@ -541,11 +550,6 @@ void nano::transport::tcp_server::bootstrap_message_visitor::bulk_pull (const na return; } - if (node->config.logging.bulk_pull_logging ()) - { - node->logger.try_log (boost::str (boost::format ("Received bulk pull for %1% down to %2%, maximum of %3% from %4%") % message.start.to_string () % message.end.to_string () % message.count % server->remote_endpoint)); - } - node->bootstrap_workers.push_task ([server = server, message = message] () { // TODO: Add completion callback to bulk pull server // TODO: There should be no need to re-copy message as unique pointer, refactor those bulk/frontier pull/push servers @@ -568,11 +572,6 @@ void nano::transport::tcp_server::bootstrap_message_visitor::bulk_pull_account ( return; } - if (node->config.logging.bulk_pull_logging ()) - { - node->logger.try_log (boost::str (boost::format ("Received bulk pull account for %1% with a minimum amount of %2%") % message.account.to_account () % nano::amount (message.minimum_amount).format_balance (nano::Mxrb_ratio, 10, true))); - } - node->bootstrap_workers.push_task ([server = server, message = message] () { // TODO: Add completion callback to bulk pull server // TODO: There should be no need to re-copy message as unique pointer, refactor those bulk/frontier pull/push servers @@ -606,10 +605,6 @@ void nano::transport::tcp_server::bootstrap_message_visitor::frontier_req (const { return; } - if (node->config.logging.bulk_pull_logging ()) - { - node->logger.try_log (boost::str (boost::format ("Received frontier request for %1% with age %2%") % message.start.to_string () % message.age)); - } node->bootstrap_workers.push_task ([server = server, message = message] () { // TODO: There should be no need to re-copy message as unique pointer, refactor those bulk/frontier pull/push servers @@ -631,10 +626,8 @@ void nano::transport::tcp_server::timeout () } if (socket->has_timed_out ()) { - if (node->config.logging.bulk_pull_logging ()) - { - node->logger.try_log ("Closing incoming tcp / bootstrap server by timeout"); - } + node->nlogger.debug (nano::log::tag::tcp_server, "Closing TCP server due to timeout ({})", nano::util::to_str (remote_endpoint)); + { nano::lock_guard lock{ node->tcp_listener.mutex }; node->tcp_listener.connections.erase (this); @@ -669,6 +662,9 @@ bool nano::transport::tcp_server::to_bootstrap_connection () ++node->tcp_listener.bootstrap_count; socket->type_set (nano::transport::socket::type_t::bootstrap); + + node->nlogger.debug (nano::log::tag::tcp_server, "Switched to bootstrap mode ({})", nano::util::to_str (remote_endpoint)); + return true; } @@ -684,6 +680,9 @@ bool nano::transport::tcp_server::to_realtime_connection (nano::account const & remote_node_id = node_id; ++node->tcp_listener.realtime_count; socket->type_set (nano::transport::socket::type_t::realtime); + + node->nlogger.debug (nano::log::tag::tcp_server, "Switched to realtime mode ({})", nano::util::to_str (remote_endpoint)); + return true; } return false; diff --git a/nano/node/vote_processor.cpp b/nano/node/vote_processor.cpp index 34b86f70fc..3586664327 100644 --- a/nano/node/vote_processor.cpp +++ b/nano/node/vote_processor.cpp @@ -16,12 +16,12 @@ #include using namespace std::chrono_literals; -nano::vote_processor::vote_processor (nano::active_transactions & active_a, nano::node_observers & observers_a, nano::stats & stats_a, nano::node_config & config_a, nano::node_flags & flags_a, nano::logger_mt & logger_a, nano::online_reps & online_reps_a, nano::rep_crawler & rep_crawler_a, nano::ledger & ledger_a, nano::network_params & network_params_a) : +nano::vote_processor::vote_processor (nano::active_transactions & active_a, nano::node_observers & observers_a, nano::stats & stats_a, nano::node_config & config_a, nano::node_flags & flags_a, nano::nlogger & nlogger_a, nano::online_reps & online_reps_a, nano::rep_crawler & rep_crawler_a, nano::ledger & ledger_a, nano::network_params & network_params_a) : active (active_a), observers (observers_a), stats (stats_a), config (config_a), - logger (logger_a), + nlogger (nlogger_a), online_reps (online_reps_a), rep_crawler (rep_crawler_a), ledger (ledger_a), @@ -77,8 +77,12 @@ void nano::vote_processor::process_loop () if (log_this_iteration && elapsed.stop () > std::chrono::milliseconds (100)) { - logger.try_log (boost::str (boost::format ("Processed %1% votes in %2% milliseconds (rate of %3% votes per second)") % votes_l.size () % elapsed.value ().count () % ((votes_l.size () * 1000ULL) / elapsed.value ().count ()))); + nlogger.debug (nano::log::tag::vote_processor, "Processed {} votes in {} milliseconds (rate of {} votes per second)", + votes_l.size (), + elapsed.value ().count (), + ((votes_l.size () * 1000ULL) / elapsed.value ().count ())); } + lock.lock (); } else @@ -169,10 +173,7 @@ nano::vote_code nano::vote_processor::vote_blocking (std::shared_ptr stats.inc (nano::stat::type::vote, nano::stat::detail::vote_indeterminate); break; } - if (config.logging.vote_logging ()) - { - logger.try_log (boost::str (boost::format ("Vote from: %1% timestamp: %2% duration %3%ms block(s): %4% status: %5%") % vote_a->account.to_account () % std::to_string (vote_a->timestamp ()) % std::to_string (vote_a->duration ().count ()) % vote_a->hashes_string () % status)); - } + return result; } @@ -198,7 +199,7 @@ void nano::vote_processor::flush () }); if (!success) { - logger.always_log ("WARNING: vote_processor::flush timeout while waiting for flush"); + nlogger.error (nano::log::tag::vote_processor, "Flush timeout"); debug_assert (false && "vote_processor::flush timeout while waiting for flush"); } } diff --git a/nano/node/vote_processor.hpp b/nano/node/vote_processor.hpp index 4ee3c6f0ea..6ae37d16b2 100644 --- a/nano/node/vote_processor.hpp +++ b/nano/node/vote_processor.hpp @@ -20,7 +20,7 @@ namespace store class node_observers; class stats; class node_config; -class logger_mt; +class nlogger; class online_reps; class rep_crawler; class ledger; @@ -36,7 +36,7 @@ namespace transport class vote_processor final { public: - vote_processor (nano::active_transactions & active_a, nano::node_observers & observers_a, nano::stats & stats_a, nano::node_config & config_a, nano::node_flags & flags_a, nano::logger_mt & logger_a, nano::online_reps & online_reps_a, nano::rep_crawler & rep_crawler_a, nano::ledger & ledger_a, nano::network_params & network_params_a); + vote_processor (nano::active_transactions & active_a, nano::node_observers & observers_a, nano::stats & stats_a, nano::node_config & config_a, nano::node_flags & flags_a, nano::nlogger &, nano::online_reps & online_reps_a, nano::rep_crawler & rep_crawler_a, nano::ledger & ledger_a, nano::network_params & network_params_a); /** Returns false if the vote was processed */ bool vote (std::shared_ptr const &, std::shared_ptr const &); @@ -60,7 +60,7 @@ class vote_processor final nano::node_observers & observers; nano::stats & stats; nano::node_config & config; - nano::logger_mt & logger; + nano::nlogger & nlogger; nano::online_reps & online_reps; nano::rep_crawler & rep_crawler; nano::ledger & ledger; diff --git a/nano/node/wallet.cpp b/nano/node/wallet.cpp index ec128f296b..114668594a 100644 --- a/nano/node/wallet.cpp +++ b/nano/node/wallet.cpp @@ -699,15 +699,16 @@ bool nano::wallet::enter_password (store::transaction const & transaction_a, std auto result (store.attempt_password (transaction_a, password_a)); if (!result) { + wallets.node.nlogger.info (nano::log::tag::wallet, "Wallet unlocked"); + auto this_l (shared_from_this ()); wallets.node.background ([this_l] () { this_l->search_receivable (this_l->wallets.tx_begin_read ()); }); - wallets.node.logger.try_log ("Wallet unlocked"); } else { - wallets.node.logger.try_log ("Invalid password, wallet locked"); + wallets.node.nlogger.warn (nano::log::tag::wallet, "Invalid password, wallet locked"); } lock_observer (result, password_a.empty ()); return result; @@ -864,7 +865,7 @@ std::shared_ptr nano::wallet::receive_action (nano::block_hash cons } else { - wallets.node.logger.try_log ("Unable to receive, wallet locked"); + wallets.node.nlogger.warn (nano::log::tag::wallet, "Unable to receive, wallet locked"); } } else @@ -879,8 +880,8 @@ std::shared_ptr nano::wallet::receive_action (nano::block_hash cons } else { - wallets.node.logger.try_log (boost::str (boost::format ("Not receiving block %1% due to minimum receive threshold") % send_hash_a.to_string ())); // Someone sent us something below the threshold of receiving + wallets.node.nlogger.warn (nano::log::tag::wallet, "Not receiving block {} due to minimum receive threshold", send_hash_a.to_string ()); } if (block != nullptr) { @@ -1042,7 +1043,10 @@ bool nano::wallet::action_complete (std::shared_ptr const & block_a auto required_difficulty{ wallets.node.network_params.work.threshold (block_a->work_version (), details_a) }; if (wallets.node.network_params.work.difficulty (*block_a) < required_difficulty) { - wallets.node.logger.try_log (boost::str (boost::format ("Cached or provided work for block %1% account %2% is invalid, regenerating") % block_a->hash ().to_string () % account_a.to_account ())); + wallets.node.nlogger.info (nano::log::tag::wallet, "Cached or provided work for block {} account {} is invalid, regenerating...", + block_a->hash ().to_string (), + account_a.to_account ()); + debug_assert (required_difficulty <= wallets.node.max_work_generate_difficulty (block_a->work_version ())); error = !wallets.node.work_generate_blocking (*block_a, required_difficulty).is_initialized (); } @@ -1138,7 +1142,7 @@ void nano::wallet::work_update (store::transaction const & transaction_a, nano:: } else { - wallets.node.logger.try_log ("Cached work no longer valid, discarding"); + wallets.node.nlogger.warn (nano::log::tag::wallet, "Cached work no longer valid, discarding"); } } @@ -1167,7 +1171,8 @@ bool nano::wallet::search_receivable (store::transaction const & wallet_transact auto result (!store.valid_password (wallet_transaction_a)); if (!result) { - wallets.node.logger.try_log ("Beginning receivable block search"); + wallets.node.nlogger.info (nano::log::tag::wallet, "Beginning receivable block search"); + for (auto i (store.begin (wallet_transaction_a)), n (store.end ()); i != n; ++i) { auto block_transaction (wallets.node.store.tx_begin_read ()); @@ -1183,7 +1188,8 @@ bool nano::wallet::search_receivable (store::transaction const & wallet_transact auto amount (pending.amount.number ()); if (wallets.node.config.receive_minimum.number () <= amount) { - wallets.node.logger.try_log (boost::str (boost::format ("Found a receivable block %1% for account %2%") % hash.to_string () % pending.source.to_account ())); + wallets.node.nlogger.info (nano::log::tag::wallet, "Found a receivable block {} for account {}", hash.to_string (), pending.source.to_account ()); + if (wallets.node.ledger.block_confirmed (block_transaction, hash)) { auto representative = store.representative (wallet_transaction_a); @@ -1203,11 +1209,12 @@ bool nano::wallet::search_receivable (store::transaction const & wallet_transact } } } - wallets.node.logger.try_log ("Receivable block search phase completed"); + + wallets.node.nlogger.info (nano::log::tag::wallet, "Receivable block search phase complete"); } else { - wallets.node.logger.try_log ("Stopping search, wallet is locked"); + wallets.node.nlogger.warn (nano::log::tag::wallet, "Stopping search, wallet is locked"); } return result; } @@ -1299,7 +1306,7 @@ void nano::wallet::work_cache_blocking (nano::account const & account_a, nano::r } else if (!wallets.node.stopped) { - wallets.node.logger.try_log (boost::str (boost::format ("Could not precache work for root %1% due to work generation failure") % root_a.to_string ())); + wallets.node.nlogger.warn (nano::log::tag::wallet, "Could not precache work for root {} due to work generation failure", root_a.to_string ()); } } } @@ -1387,7 +1394,7 @@ nano::wallets::wallets (bool error_a, nano::node & node_a) : char const * store_path; mdb_env_get_path (env, &store_path); std::filesystem::path const path (store_path); - nano::store::lmdb::component::create_backup_file (env, path, node_a.logger); + nano::store::lmdb::component::create_backup_file (env, path, node_a.nlogger); } for (auto & item : items) { @@ -1555,11 +1562,13 @@ void nano::wallets::foreach_representative (std::functionfirst.to_string ())); + + node.nlogger.warn (nano::log::tag::wallet, "Representative locked inside wallet: {}", i->first.to_string ()); } } } diff --git a/nano/node/websocket.cpp b/nano/node/websocket.cpp index 8fa5a13184..60a777b5f0 100644 --- a/nano/node/websocket.cpp +++ b/nano/node/websocket.cpp @@ -1,6 +1,7 @@ #include #include #include +#include #include #include #include @@ -15,14 +16,15 @@ #include #include -nano::websocket::confirmation_options::confirmation_options (nano::wallets & wallets_a) : - wallets (wallets_a) +nano::websocket::confirmation_options::confirmation_options (nano::wallets & wallets_a, nano::nlogger & nlogger_a) : + wallets (wallets_a), + nlogger (nlogger_a) { } -nano::websocket::confirmation_options::confirmation_options (boost::property_tree::ptree const & options_a, nano::wallets & wallets_a, nano::logger_mt & logger_a) : +nano::websocket::confirmation_options::confirmation_options (boost::property_tree::ptree const & options_a, nano::wallets & wallets_a, nano::nlogger & nlogger_a) : wallets (wallets_a), - logger (logger_a) + nlogger (nlogger_a) { // Non-account filtering options include_block = options_a.get ("include_block", true); @@ -63,7 +65,7 @@ nano::websocket::confirmation_options::confirmation_options (boost::property_tre if (!include_block) { - logger_a.always_log ("Websocket: Filtering option \"all_local_accounts\" requires that \"include_block\" is set to true to be effective"); + nlogger.warn (nano::log::tag::websocket, "Filtering option \"all_local_accounts\" requires that \"include_block\" is set to true to be effective"); } } auto accounts_l (options_a.get_child_optional ("accounts")); @@ -80,13 +82,13 @@ nano::websocket::confirmation_options::confirmation_options (boost::property_tre } else { - logger_a.always_log ("Websocket: invalid account provided for filtering blocks: ", account_l.second.data ()); + nlogger.warn (nano::log::tag::websocket, "Invalid account provided for filtering blocks: ", account_l.second.data ()); } } if (!include_block) { - logger_a.always_log ("Websocket: Filtering option \"accounts\" requires that \"include_block\" is set to true to be effective"); + nlogger.warn (nano::log::tag::websocket, "Filtering option \"accounts\" requires that \"include_block\" is set to true to be effective"); } } check_filter_empty (); @@ -159,9 +161,9 @@ bool nano::websocket::confirmation_options::update (boost::property_tree::ptree this->accounts.erase (encoded_l); } } - else if (this->logger.is_initialized ()) + else { - this->logger->always_log ("Websocket: invalid account provided for filtering blocks: ", account_l.second.data ()); + nlogger.warn (nano::log::tag::websocket, "Invalid account provided for filtering blocks: ", account_l.second.data ()); } } }; @@ -187,13 +189,13 @@ bool nano::websocket::confirmation_options::update (boost::property_tree::ptree void nano::websocket::confirmation_options::check_filter_empty () const { // Warn the user if the options resulted in an empty filter - if (logger.is_initialized () && has_account_filtering_options && !all_local_accounts && accounts.empty ()) + if (has_account_filtering_options && !all_local_accounts && accounts.empty ()) { - logger->always_log ("Websocket: provided options resulted in an empty block confirmation filter"); + nlogger.warn (nano::log::tag::websocket, "Provided options resulted in an empty account confirmation filter"); } } -nano::websocket::vote_options::vote_options (boost::property_tree::ptree const & options_a, nano::logger_mt & logger_a) +nano::websocket::vote_options::vote_options (boost::property_tree::ptree const & options_a, nano::nlogger & nlogger) { include_replays = options_a.get ("include_replays", false); include_indeterminate = options_a.get ("include_indeterminate", false); @@ -210,13 +212,13 @@ nano::websocket::vote_options::vote_options (boost::property_tree::ptree const & } else { - logger_a.always_log ("Websocket: invalid account given to filter votes: ", representative_l.second.data ()); + nlogger.warn (nano::log::tag::websocket, "Invalid account provided for filtering votes: ", representative_l.second.data ()); } } // Warn the user if the option will be ignored if (representatives.empty ()) { - logger_a.always_log ("Websocket: account filter for votes is empty, no messages will be filtered"); + nlogger.warn (nano::log::tag::websocket, "Account filter for votes is empty, no messages will be filtered"); } } } @@ -241,15 +243,25 @@ bool nano::websocket::vote_options::should_filter (nano::websocket::message cons nano::websocket::session::session (nano::websocket::listener & listener_a, socket_type socket_a, boost::asio::ssl::context & ctx_a) : ws_listener (listener_a), ws (std::move (socket_a), ctx_a) { - ws_listener.get_logger ().try_log ("Websocket: secure session started"); } #endif -nano::websocket::session::session (nano::websocket::listener & listener_a, socket_type socket_a) : - ws_listener (listener_a), ws (std::move (socket_a)) +nano::websocket::session::session (nano::websocket::listener & listener_a, socket_type socket_a, nano::nlogger & nlogger_a) : + ws_listener (listener_a), + ws (std::move (socket_a)), + nlogger (nlogger_a) { - ws_listener.get_logger ().try_log ("Websocket: session started"); + { + // Best effort attempt to get endpoint addresses + boost::system::error_code ec; + remote = ws.get_socket ().remote_endpoint (ec); + debug_assert (!ec); + local = ws.get_socket ().local_endpoint (ec); + debug_assert (!ec); + } + + nlogger.info (nano::log::tag::websocket, "Session started ({})", nano::util::to_str (remote)); } nano::websocket::session::~session () @@ -274,14 +286,14 @@ void nano::websocket::session::handshake () } else { - this_l->ws_listener.get_logger ().always_log ("Websocket: handshake failed: ", ec.message ()); + this_l->nlogger.error (nano::log::tag::websocket, "Handshake failed: {} ({})", ec.message (), nano::util::to_str (this_l->remote)); } }); } void nano::websocket::session::close () { - ws_listener.get_logger ().try_log ("Websocket: session closing"); + nlogger.info (nano::log::tag::websocket, "Session closing ({})", nano::util::to_str (remote)); auto this_l (shared_from_this ()); boost::asio::dispatch (ws.get_strand (), @@ -357,12 +369,12 @@ void nano::websocket::session::read () } catch (boost::property_tree::json_parser::json_parser_error const & ex) { - this_l->ws_listener.get_logger ().try_log ("Websocket: json parsing failed: ", ex.what ()); + this_l->nlogger.error (nano::log::tag::websocket, "JSON parsing failed: {} ({})", ex.what (), nano::util::to_str (this_l->remote)); } } else if (ec != boost::asio::error::eof) { - this_l->ws_listener.get_logger ().try_log ("Websocket: read failed: ", ec.message ()); + this_l->nlogger.error (nano::log::tag::websocket, "Read failed: {} ({})", ec.message (), nano::util::to_str (this_l->remote)); } }); }); @@ -484,11 +496,11 @@ void nano::websocket::session::handle_message (boost::property_tree::ptree const std::unique_ptr options_l{ nullptr }; if (options_text_l && topic_l == nano::websocket::topic::confirmation) { - options_l = std::make_unique (options_text_l.get (), ws_listener.get_wallets (), ws_listener.get_logger ()); + options_l = std::make_unique (options_text_l.get (), ws_listener.get_wallets (), nlogger); } else if (options_text_l && topic_l == nano::websocket::topic::vote) { - options_l = std::make_unique (options_text_l.get (), ws_listener.get_logger ()); + options_l = std::make_unique (options_text_l.get (), nlogger); } else { @@ -497,13 +509,15 @@ void nano::websocket::session::handle_message (boost::property_tree::ptree const auto existing (subscriptions.find (topic_l)); if (existing != subscriptions.end ()) { + nlogger.info (nano::log::tag::websocket, "Updated subscription to topic: {} ({})", from_topic (topic_l), nano::util::to_str (remote)); + existing->second = std::move (options_l); - ws_listener.get_logger ().always_log ("Websocket: updated subscription to topic: ", from_topic (topic_l)); } else { + nlogger.info (nano::log::tag::websocket, "New subscription to topic: {} ({})", from_topic (topic_l), nano::util::to_str (remote)); + subscriptions.emplace (topic_l, std::move (options_l)); - ws_listener.get_logger ().always_log ("Websocket: new subscription to topic: ", from_topic (topic_l)); ws_listener.increase_subscriber_count (topic_l); } action_succeeded = true; @@ -526,7 +540,8 @@ void nano::websocket::session::handle_message (boost::property_tree::ptree const nano::lock_guard lk (subscriptions_mutex); if (subscriptions.erase (topic_l)) { - ws_listener.get_logger ().always_log ("Websocket: removed subscription to topic: ", from_topic (topic_l)); + nlogger.info (nano::log::tag::websocket, "Removed subscription to topic: {} ({})", from_topic (topic_l), nano::util::to_str (remote)); + ws_listener.decrease_subscriber_count (topic_l); } action_succeeded = true; @@ -560,9 +575,9 @@ void nano::websocket::listener::stop () sessions.clear (); } -nano::websocket::listener::listener (std::shared_ptr const & tls_config_a, nano::logger_mt & logger_a, nano::wallets & wallets_a, boost::asio::io_context & io_ctx_a, boost::asio::ip::tcp::endpoint endpoint_a) : +nano::websocket::listener::listener (std::shared_ptr const & tls_config_a, nano::nlogger & nlogger_a, nano::wallets & wallets_a, boost::asio::io_context & io_ctx_a, boost::asio::ip::tcp::endpoint endpoint_a) : tls_config (tls_config_a), - logger (logger_a), + nlogger (nlogger_a), wallets (wallets_a), acceptor (io_ctx_a), socket (io_ctx_a) @@ -580,7 +595,7 @@ nano::websocket::listener::listener (std::shared_ptr const & t } catch (std::exception const & ex) { - logger.always_log ("Websocket: listen failed: ", ex.what ()); + nlogger.error (nano::log::tag::websocket, "Listen failed: {}", ex.what ()); } } @@ -605,7 +620,7 @@ void nano::websocket::listener::on_accept (boost::system::error_code ec) { if (ec) { - logger.always_log ("Websocket: accept failed: ", ec.message ()); + nlogger.error (nano::log::tag::websocket, "Accept failed: {}", ec.message ()); } else { @@ -619,7 +634,7 @@ void nano::websocket::listener::on_accept (boost::system::error_code ec) } else { - session = std::make_shared (*this, std::move (socket)); + session = std::make_shared (*this, std::move (socket), nlogger); } sessions_mutex.lock (); @@ -651,7 +666,7 @@ void nano::websocket::listener::broadcast_confirmation (std::shared_ptrsubscriptions.find (nano::websocket::topic::confirmation)); if (subscription != session_ptr->subscriptions.end ()) { - nano::websocket::confirmation_options default_options (wallets); + nano::websocket::confirmation_options default_options (wallets, nlogger); auto conf_options (dynamic_cast (subscription->second.get ())); if (conf_options == nullptr) { @@ -968,13 +983,13 @@ std::string nano::websocket::message::to_string () const * websocket_server */ -nano::websocket_server::websocket_server (nano::websocket::config & config_a, nano::node_observers & observers_a, nano::wallets & wallets_a, nano::ledger & ledger_a, boost::asio::io_context & io_ctx_a, nano::logger_mt & logger_a) : +nano::websocket_server::websocket_server (nano::websocket::config & config_a, nano::node_observers & observers_a, nano::wallets & wallets_a, nano::ledger & ledger_a, boost::asio::io_context & io_ctx_a, nano::nlogger & nlogger_a) : config{ config_a }, observers{ observers_a }, wallets{ wallets_a }, ledger{ ledger_a }, io_ctx{ io_ctx_a }, - logger{ logger_a } + nlogger{ nlogger_a } { if (!config.enabled) { @@ -982,7 +997,7 @@ nano::websocket_server::websocket_server (nano::websocket::config & config_a, na } auto endpoint = nano::tcp_endpoint{ boost::asio::ip::make_address_v6 (config.address), config.port }; - server = std::make_shared (config.tls_config, logger, wallets, io_ctx, endpoint); + server = std::make_shared (config.tls_config, nlogger, wallets, io_ctx, endpoint); observers.blocks.add ([this] (nano::election_status const & status_a, std::vector const & votes_a, nano::account const & account_a, nano::amount const & amount_a, bool is_state_send_a, bool is_state_epoch_a) { debug_assert (status_a.type != nano::election_status_type::ongoing); diff --git a/nano/node/websocket.hpp b/nano/node/websocket.hpp index 9d197dcfb6..84fdf60c8d 100644 --- a/nano/node/websocket.hpp +++ b/nano/node/websocket.hpp @@ -21,7 +21,7 @@ namespace nano { class wallets; -class logger_mt; +class nlogger; class vote; class election_status; class telemetry_data; @@ -142,8 +142,8 @@ namespace websocket class confirmation_options final : public options { public: - confirmation_options (nano::wallets & wallets_a); - confirmation_options (boost::property_tree::ptree const & options_a, nano::wallets & wallets_a, nano::logger_mt & logger_a); + confirmation_options (nano::wallets & wallets_a, nano::nlogger &); + confirmation_options (boost::property_tree::ptree const & options_a, nano::wallets & wallets_a, nano::nlogger &); /** * Checks if a message should be filtered for given block confirmation options. @@ -195,7 +195,8 @@ namespace websocket void check_filter_empty () const; nano::wallets & wallets; - boost::optional logger; + nano::nlogger & nlogger; + bool include_election_info{ false }; bool include_election_info_with_votes{ false }; bool include_sideband_info{ false }; @@ -214,7 +215,7 @@ namespace websocket class vote_options final : public options { public: - vote_options (boost::property_tree::ptree const & options_a, nano::logger_mt & logger_a); + vote_options (boost::property_tree::ptree const & options_a, nano::nlogger &); /** * Checks if a message should be filtered for given vote received options. @@ -240,7 +241,7 @@ namespace websocket explicit session (nano::websocket::listener & listener_a, socket_type socket_a, boost::asio::ssl::context & ctx_a); #endif /** Constructor that takes ownership over \p socket_a */ - explicit session (nano::websocket::listener & listener_a, socket_type socket_a); + explicit session (nano::websocket::listener & listener_a, socket_type socket_a, nano::nlogger &); ~session (); @@ -261,11 +262,17 @@ namespace websocket nano::websocket::listener & ws_listener; /** Websocket stream, supporting both plain and tls connections */ nano::websocket::stream ws; + nano::nlogger & nlogger; + /** Buffer for received messages */ boost::beast::multi_buffer read_buffer; /** Outgoing messages. The send queue is protected by accessing it only through the strand */ std::deque send_queue; + /** Cache remote & local endpoints to make them available after the socket is closed */ + socket_type::endpoint_type remote; + socket_type::endpoint_type local; + /** Hash functor for topic enums */ struct topic_hash { @@ -291,7 +298,7 @@ namespace websocket class listener final : public std::enable_shared_from_this { public: - listener (std::shared_ptr const & tls_config_a, nano::logger_mt & logger_a, nano::wallets & wallets_a, boost::asio::io_context & io_ctx_a, boost::asio::ip::tcp::endpoint endpoint_a); + listener (std::shared_ptr const & tls_config_a, nano::nlogger &, nano::wallets & wallets_a, boost::asio::io_context & io_ctx_a, boost::asio::ip::tcp::endpoint endpoint_a); /** Start accepting connections */ void run (); @@ -307,11 +314,6 @@ namespace websocket /** Broadcast \p message to all session subscribing to the message topic. */ void broadcast (nano::websocket::message message_a); - nano::logger_mt & get_logger () const - { - return logger; - } - std::uint16_t listening_port () { return acceptor.local_endpoint ().port (); @@ -346,7 +348,7 @@ namespace websocket void decrease_subscriber_count (nano::websocket::topic const & topic_a); std::shared_ptr tls_config; - nano::logger_mt & logger; + nano::nlogger & nlogger; nano::wallets & wallets; boost::asio::ip::tcp::acceptor acceptor; socket_type socket; @@ -363,7 +365,7 @@ namespace websocket class websocket_server { public: - websocket_server (nano::websocket::config &, nano::node_observers &, nano::wallets &, nano::ledger &, boost::asio::io_context &, nano::logger_mt &); + websocket_server (nano::websocket::config &, nano::node_observers &, nano::wallets &, nano::ledger &, boost::asio::io_context &, nano::nlogger &); void start (); void stop (); @@ -374,7 +376,7 @@ class websocket_server nano::wallets & wallets; nano::ledger & ledger; boost::asio::io_context & io_ctx; - nano::logger_mt & logger; + nano::nlogger & nlogger; public: // TODO: Encapsulate, this is public just because existing code needs it diff --git a/nano/node/websocket_stream.cpp b/nano/node/websocket_stream.cpp index 74d5eaf8a3..d680e999d2 100644 --- a/nano/node/websocket_stream.cpp +++ b/nano/node/websocket_stream.cpp @@ -67,6 +67,11 @@ class stream_wrapper : public nano::websocket::websocket_stream_concept return strand; } + socket_type & get_socket () override + { + return ws.next_layer (); + } + void close (boost::beast::websocket::close_reason const & reason_a, boost::system::error_code & ec_a) override { ws.close (reason_a, ec_a); @@ -105,6 +110,11 @@ nano::websocket::stream::stream (socket_type socket_a) return impl->get_strand (); } +[[nodiscard]] socket_type & nano::websocket::stream::get_socket () +{ + return impl->get_socket (); +} + void nano::websocket::stream::handshake (std::function callback_a) { impl->handshake (callback_a); diff --git a/nano/node/websocket_stream.hpp b/nano/node/websocket_stream.hpp index 03e21490ce..5a5cb86c45 100644 --- a/nano/node/websocket_stream.hpp +++ b/nano/node/websocket_stream.hpp @@ -32,6 +32,7 @@ class websocket_stream_concept public: virtual ~websocket_stream_concept () = default; virtual boost::asio::strand & get_strand () = 0; + virtual socket_type & get_socket () = 0; virtual void handshake (std::function callback_a) = 0; virtual void close (boost::beast::websocket::close_reason const & reason_a, boost::system::error_code & ec_a) = 0; virtual void async_write (nano::shared_const_buffer const & buffer_a, std::function callback_a) = 0; @@ -51,6 +52,7 @@ class stream final : public websocket_stream_concept stream (socket_type socket_a); [[nodiscard]] boost::asio::strand & get_strand () override; + [[nodiscard]] socket_type & get_socket () override; void handshake (std::function callback_a) override; void close (boost::beast::websocket::close_reason const & reason_a, boost::system::error_code & ec_a) override; void async_write (nano::shared_const_buffer const & buffer_a, std::function callback_a) override; diff --git a/nano/qt/qt.cpp b/nano/qt/qt.cpp index 2c8b6cfb1b..b0ac4243ba 100644 --- a/nano/qt/qt.cpp +++ b/nano/qt/qt.cpp @@ -1546,7 +1546,7 @@ nano_qt::settings::settings (nano_qt::wallet & wallet_a) : retype_password->setPlaceholderText ("Retype password"); show_button_success (*change); change->setText ("Password was changed"); - this->wallet.node.logger.try_log ("Wallet password changed"); + this->wallet.node.nlogger.warn (nano::log::tag::qt, "Wallet password changed"); update_locked (false, false); this->wallet.node.workers.add_timed_task (std::chrono::steady_clock::now () + std::chrono::seconds (5), [this] () { this->wallet.application.postEvent (&this->wallet.processor, new eventloop_event ([this] () { @@ -1639,7 +1639,7 @@ nano_qt::settings::settings (nano_qt::wallet & wallet_a) : this->wallet.wallet_m->store.password.value_set (empty); update_locked (true, true); lock_toggle->setText ("Unlock"); - this->wallet.node.logger.try_log ("Wallet locked"); + this->wallet.node.nlogger.warn (nano::log::tag::qt, "Wallet locked"); password->setEnabled (1); } else diff --git a/nano/qt_test/entry.cpp b/nano/qt_test/entry.cpp index 0352439ec6..9b05a964bd 100644 --- a/nano/qt_test/entry.cpp +++ b/nano/qt_test/entry.cpp @@ -1,8 +1,10 @@ +#include #include #include #include + QApplication * test_application = nullptr; namespace nano { @@ -15,6 +17,7 @@ void force_nano_dev_network (); int main (int argc, char ** argv) { + nano::initialize_logging (nano::log::preset::tests); nano::force_nano_dev_network (); nano::node_singleton_memory_pool_purge_guard memory_pool_cleanup_guard; QApplication application (argc, argv); diff --git a/nano/qt_test/qt.cpp b/nano/qt_test/qt.cpp index 8e3dea40b7..dc0bcc4bb8 100644 --- a/nano/qt_test/qt.cpp +++ b/nano/qt_test/qt.cpp @@ -519,7 +519,8 @@ TEST (history, short_text) account = system.account (transaction, 0); } auto wallet (std::make_shared (*test_application, processor, *system.nodes[0], system.wallet (0), account)); - auto store = nano::make_store (system.nodes[0]->logger, nano::unique_path (), nano::dev::constants); + nano::nlogger nlogger; + auto store = nano::make_store (nlogger, nano::unique_path (), nano::dev::constants); ASSERT_TRUE (!store->init_error ()); nano::ledger ledger (*store, system.nodes[0]->stats, nano::dev::constants); { @@ -556,7 +557,8 @@ TEST (history, pruned_source) account = system.account (transaction, 0); } auto wallet (std::make_shared (*test_application, processor, *system.nodes[0], system.wallet (0), account)); - auto store = nano::make_store (system.nodes[0]->logger, nano::unique_path (), nano::dev::constants); + nano::nlogger nlogger; + auto store = nano::make_store (nlogger, nano::unique_path (), nano::dev::constants); ASSERT_TRUE (!store->init_error ()); nano::ledger ledger (*store, system.nodes[0]->stats, nano::dev::constants); ledger.pruning = true; diff --git a/nano/rpc/rpc.cpp b/nano/rpc/rpc.cpp index 18c0e5a227..053b2d8e2e 100644 --- a/nano/rpc/rpc.cpp +++ b/nano/rpc/rpc.cpp @@ -15,7 +15,6 @@ nano::rpc::rpc (boost::asio::io_context & io_ctx_a, nano::rpc_config config_a, nano::rpc_handler_interface & rpc_handler_interface_a) : config (std::move (config_a)), acceptor (io_ctx_a), - logger (std::chrono::milliseconds (0)), io_ctx (io_ctx_a), rpc_handler_interface (rpc_handler_interface_a) { @@ -33,13 +32,13 @@ nano::rpc::~rpc () void nano::rpc::start () { auto endpoint (boost::asio::ip::tcp::endpoint (boost::asio::ip::make_address_v6 (config.address), config.port)); + bool const is_loopback = (endpoint.address ().is_loopback () || (endpoint.address ().to_v6 ().is_v4_mapped () && boost::asio::ip::make_address_v4 (boost::asio::ip::v4_mapped, endpoint.address ().to_v6 ()).is_loopback ())); if (!is_loopback && config.enable_control) { - auto warning = boost::str (boost::format ("WARNING: control-level RPCs are enabled on non-local address %1%, potentially allowing wallet access outside local computer") % endpoint.address ().to_string ()); - std::cout << warning << std::endl; - logger.always_log (warning); + nlogger.warn (nano::log::tag::rpc, "WARNING: Control-level RPCs are enabled on non-local address {}, potentially allowing wallet access outside local computer", endpoint.address ().to_string ()); } + acceptor.open (endpoint.protocol ()); acceptor.set_option (boost::asio::ip::tcp::acceptor::reuse_address (true)); @@ -47,7 +46,7 @@ void nano::rpc::start () acceptor.bind (endpoint, ec); if (ec) { - logger.always_log (boost::str (boost::format ("Error while binding for RPC on port %1%: %2%") % endpoint.port () % ec.message ())); + nlogger.critical (nano::log::tag::rpc, "Error while binding for RPC on port: {} ({})", endpoint.port (), ec.message ()); throw std::runtime_error (ec.message ()); } acceptor.listen (); @@ -56,7 +55,7 @@ void nano::rpc::start () void nano::rpc::accept () { - auto connection (std::make_shared (config, io_ctx, logger, rpc_handler_interface)); + auto connection (std::make_shared (config, io_ctx, nlogger, rpc_handler_interface)); acceptor.async_accept (connection->socket, boost::asio::bind_executor (connection->strand, [this, connection] (boost::system::error_code const & ec) { if (ec != boost::asio::error::operation_aborted && acceptor.is_open ()) { @@ -68,7 +67,7 @@ void nano::rpc::accept () } else { - logger.always_log (boost::str (boost::format ("Error accepting RPC connections: %1% (%2%)") % ec.message () % ec.value ())); + nlogger.error (nano::log::tag::rpc, "Error accepting RPC connection: {}", ec.message ()); } })); } diff --git a/nano/rpc/rpc.hpp b/nano/rpc/rpc.hpp index 40c096f37c..2f4bcb115e 100644 --- a/nano/rpc/rpc.hpp +++ b/nano/rpc/rpc.hpp @@ -1,7 +1,7 @@ #pragma once #include -#include +#include #include #include @@ -31,9 +31,9 @@ class rpc return acceptor.local_endpoint ().port (); } + nano::nlogger nlogger; nano::rpc_config config; boost::asio::ip::tcp::acceptor acceptor; - nano::logger_mt logger; boost::asio::io_context & io_ctx; nano::rpc_handler_interface & rpc_handler_interface; bool stopped{ false }; diff --git a/nano/rpc/rpc_connection.cpp b/nano/rpc/rpc_connection.cpp index f4d96be45b..11e0b018c4 100644 --- a/nano/rpc/rpc_connection.cpp +++ b/nano/rpc/rpc_connection.cpp @@ -14,11 +14,11 @@ #endif #include -nano::rpc_connection::rpc_connection (nano::rpc_config const & rpc_config, boost::asio::io_context & io_ctx, nano::logger_mt & logger, nano::rpc_handler_interface & rpc_handler_interface) : +nano::rpc_connection::rpc_connection (nano::rpc_config const & rpc_config, boost::asio::io_context & io_ctx, nano::nlogger & nlogger, nano::rpc_handler_interface & rpc_handler_interface) : socket (io_ctx), strand (io_ctx.get_executor ()), io_ctx (io_ctx), - logger (logger), + nlogger (nlogger), rpc_config (rpc_config), rpc_handler_interface (rpc_handler_interface) { @@ -84,7 +84,7 @@ void nano::rpc_connection::read (STREAM_TYPE & stream) } else { - this_l->logger.always_log ("RPC header error: ", ec.message ()); + this_l->nlogger.error (nano::log::tag::rpc_connection, "RPC header error: ", ec.message ()); // Respond with the reason for the invalid header auto response_handler ([this_l, &stream] (std::string const & tree_a) { @@ -123,12 +123,9 @@ void nano::rpc_connection::parse_request (STREAM_TYPE & stream, std::shared_ptr< this_l->write_completion_handler (this_l); })); - std::stringstream ss; - if (this_l->rpc_config.rpc_logging.log_rpc) - { - ss << "RPC request " << request_id << " completed in: " << std::chrono::duration_cast (std::chrono::steady_clock::now () - start).count () << " microseconds"; - this_l->logger.always_log (ss.str ().c_str ()); - } + // Bump logging level if RPC request logging is enabled + this_l->nlogger.log (this_l->rpc_config.rpc_logging.log_rpc ? nano::log::level::info : nano::log::level::debug, + nano::log::tag::rpc_request, "RPC request {} completed in {} microseconds", request_id, std::chrono::duration_cast (std::chrono::steady_clock::now () - start).count ()); }); std::string api_path_l = "/api/v2"; @@ -139,7 +136,7 @@ void nano::rpc_connection::parse_request (STREAM_TYPE & stream, std::shared_ptr< { case boost::beast::http::verb::post: { - auto handler (std::make_shared (this_l->rpc_config, req.body (), request_id, response_handler, this_l->rpc_handler_interface, this_l->logger)); + auto handler (std::make_shared (this_l->rpc_config, req.body (), request_id, response_handler, this_l->rpc_handler_interface, this_l->nlogger)); nano::rpc_handler_request_params request_params; request_params.rpc_version = rpc_version_l; request_params.credentials = header_field_credentials_l; @@ -168,7 +165,7 @@ void nano::rpc_connection::parse_request (STREAM_TYPE & stream, std::shared_ptr< } else { - this_l->logger.always_log ("RPC read error: ", ec.message ()); + this_l->nlogger.error (nano::log::tag::rpc_connection, "RPC read error: ", ec.message ()); } })); } diff --git a/nano/rpc/rpc_connection.hpp b/nano/rpc/rpc_connection.hpp index 3226e28064..e0f18367ff 100644 --- a/nano/rpc/rpc_connection.hpp +++ b/nano/rpc/rpc_connection.hpp @@ -4,6 +4,7 @@ #include #include #include +#include #include @@ -25,7 +26,7 @@ class rpc_handler_interface; class rpc_connection : public std::enable_shared_from_this { public: - rpc_connection (nano::rpc_config const & rpc_config, boost::asio::io_context & io_ctx, nano::logger_mt & logger, nano::rpc_handler_interface & rpc_handler_interface_a); + rpc_connection (nano::rpc_config const & rpc_config, boost::asio::io_context & io_ctx, nano::nlogger &, nano::rpc_handler_interface & rpc_handler_interface_a); virtual ~rpc_connection () = default; virtual void parse_connection (); virtual void write_completion_handler (std::shared_ptr const & rpc_connection); @@ -38,7 +39,7 @@ class rpc_connection : public std::enable_shared_from_this boost::asio::strand strand; std::atomic_flag responded; boost::asio::io_context & io_ctx; - nano::logger_mt & logger; + nano::nlogger & nlogger; nano::rpc_config const & rpc_config; nano::rpc_handler_interface & rpc_handler_interface; diff --git a/nano/rpc/rpc_handler.cpp b/nano/rpc/rpc_handler.cpp index 7148d45d63..9053793c03 100644 --- a/nano/rpc/rpc_handler.cpp +++ b/nano/rpc/rpc_handler.cpp @@ -18,13 +18,13 @@ std::unordered_set rpc_control_impl_set = create_rpc_control_impls std::string filter_request (boost::property_tree::ptree tree_a); } -nano::rpc_handler::rpc_handler (nano::rpc_config const & rpc_config, std::string const & body_a, std::string const & request_id_a, std::function const & response_a, nano::rpc_handler_interface & rpc_handler_interface_a, nano::logger_mt & logger) : +nano::rpc_handler::rpc_handler (nano::rpc_config const & rpc_config, std::string const & body_a, std::string const & request_id_a, std::function const & response_a, nano::rpc_handler_interface & rpc_handler_interface_a, nano::nlogger & nlogger) : body (body_a), request_id (request_id_a), response (response_a), rpc_config (rpc_config), rpc_handler_interface (rpc_handler_interface_a), - logger (logger) + nlogger (nlogger) { } @@ -62,13 +62,10 @@ void nano::rpc_handler::process_request (nano::rpc_handler_request_params const } auto action = request.get ("action"); - if (rpc_config.rpc_logging.log_rpc) - { - // Creating same string via stringstream as using it directly is generating a TSAN warning - std::stringstream ss; - ss << request_id; - logger.always_log (ss.str (), " ", filter_request (request)); - } + + // Bump logging level if RPC request logging is enabled + nlogger.log (rpc_config.rpc_logging.log_rpc ? nano::log::level::info : nano::log::level::debug, + nano::log::tag::rpc_request, "Request {} : {}", request_id, filter_request (request)); // Check if this is a RPC command which requires RPC enabled control std::error_code rpc_control_disabled_ec = nano::error_rpc::rpc_control_disabled; diff --git a/nano/rpc/rpc_handler.hpp b/nano/rpc/rpc_handler.hpp index 2e919f303a..92850497cc 100644 --- a/nano/rpc/rpc_handler.hpp +++ b/nano/rpc/rpc_handler.hpp @@ -1,5 +1,7 @@ #pragma once +#include + #include #include @@ -15,7 +17,7 @@ class rpc_handler_request_params; class rpc_handler : public std::enable_shared_from_this { public: - rpc_handler (nano::rpc_config const & rpc_config, std::string const & body_a, std::string const & request_id_a, std::function const & response_a, nano::rpc_handler_interface & rpc_handler_interface_a, nano::logger_mt & logger); + rpc_handler (nano::rpc_config const & rpc_config, std::string const & body_a, std::string const & request_id_a, std::function const & response_a, nano::rpc_handler_interface & rpc_handler_interface_a, nano::nlogger &); void process_request (nano::rpc_handler_request_params const & request_params); private: @@ -25,6 +27,6 @@ class rpc_handler : public std::enable_shared_from_this std::function response; nano::rpc_config const & rpc_config; nano::rpc_handler_interface & rpc_handler_interface; - nano::logger_mt & logger; + nano::nlogger & nlogger; }; } diff --git a/nano/rpc/rpc_secure.cpp b/nano/rpc/rpc_secure.cpp index 3f596a7cba..8d758e8b46 100644 --- a/nano/rpc/rpc_secure.cpp +++ b/nano/rpc/rpc_secure.cpp @@ -15,7 +15,7 @@ nano::rpc_secure::rpc_secure (boost::asio::io_context & context_a, nano::rpc_con void nano::rpc_secure::accept () { - auto connection (std::make_shared (config, io_ctx, logger, rpc_handler_interface, config.tls_config->ssl_context)); + auto connection (std::make_shared (config, io_ctx, nlogger, rpc_handler_interface, config.tls_config->ssl_context)); acceptor.async_accept (connection->socket, boost::asio::bind_executor (connection->strand, [this, connection] (boost::system::error_code const & ec) { if (ec != boost::asio::error::operation_aborted && acceptor.is_open ()) { @@ -27,7 +27,7 @@ void nano::rpc_secure::accept () } else { - logger.always_log (boost::str (boost::format ("Error accepting RPC connections: %1%") % ec)); + nlogger.error (nano::log::tag::rpc, "Error accepting RPC connection: {}", ec.message ()); } })); } diff --git a/nano/rpc_test/entry.cpp b/nano/rpc_test/entry.cpp index 530f146c98..e04e9398f9 100644 --- a/nano/rpc_test/entry.cpp +++ b/nano/rpc_test/entry.cpp @@ -1,7 +1,9 @@ +#include #include #include #include + namespace nano { namespace test @@ -13,6 +15,7 @@ void force_nano_dev_network (); int main (int argc, char ** argv) { + nano::initialize_logging (nano::log::preset::tests); nano::force_nano_dev_network (); nano::set_use_memory_pools (false); nano::node_singleton_memory_pool_purge_guard cleanup_guard; diff --git a/nano/secure/common.cpp b/nano/secure/common.cpp index 35b5ad68f9..525083669d 100644 --- a/nano/secure/common.cpp +++ b/nano/secure/common.cpp @@ -2,6 +2,7 @@ #include #include #include +#include #include #include diff --git a/nano/secure/ledger.cpp b/nano/secure/ledger.cpp index e7c7f1abf9..e7c511b8bd 100644 --- a/nano/secure/ledger.cpp +++ b/nano/secure/ledger.cpp @@ -1,3 +1,4 @@ +#include #include #include #include @@ -1558,13 +1559,13 @@ bool nano::ledger::migrate_lmdb_to_rocksdb (std::filesystem::path const & data_p auto rockdb_data_path = data_path_a / "rocksdb"; std::filesystem::remove_all (rockdb_data_path); - nano::logger_mt logger; + nano::nlogger nlogger; auto error (false); // Open rocksdb database nano::rocksdb_config rocksdb_config; rocksdb_config.enable = true; - auto rocksdb_store = nano::make_store (logger, data_path_a, nano::dev::constants, false, true, rocksdb_config); + auto rocksdb_store = nano::make_store (nlogger, data_path_a, nano::dev::constants, false, true, rocksdb_config); if (!rocksdb_store->init_error ()) { diff --git a/nano/secure/ledger.hpp b/nano/secure/ledger.hpp index c1e2b11817..6cabac2eee 100644 --- a/nano/secure/ledger.hpp +++ b/nano/secure/ledger.hpp @@ -17,9 +17,6 @@ namespace nano { class stats; -// map of vote weight per block, ordered greater first -using tally_t = std::map, std::greater>; - class uncemented_info { public: diff --git a/nano/secure/vote.cpp b/nano/secure/vote.cpp index 2f19c9748e..208aca4de1 100644 --- a/nano/secure/vote.cpp +++ b/nano/secure/vote.cpp @@ -165,13 +165,9 @@ std::string nano::vote::to_json () const std::string nano::vote::hashes_string () const { - std::string result; - for (auto const & hash : hashes) - { - result += hash.to_string (); - result += ", "; - } - return result; + return nano::util::join (hashes, ",", [] (auto const & hash) { + return hash.to_string (); + }); } uint64_t nano::vote::packed_timestamp (uint64_t timestamp, uint8_t duration) @@ -184,13 +180,4 @@ 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 (); -} - -/* - * iterate_vote_blocks_as_hash - */ - -nano::block_hash nano::iterate_vote_blocks_as_hash::operator() (nano::block_hash const & item) const -{ - return item; -} +} \ No newline at end of file diff --git a/nano/secure/vote.hpp b/nano/secure/vote.hpp index 35d7308a13..d7c9b62b32 100644 --- a/nano/secure/vote.hpp +++ b/nano/secure/vote.hpp @@ -12,14 +12,6 @@ namespace nano { -using vote_blocks_vec_iter = std::vector::const_iterator; -class iterate_vote_blocks_as_hash final -{ -public: - iterate_vote_blocks_as_hash () = default; - nano::block_hash operator() (nano::block_hash const & item) const; -}; - class vote final { public: @@ -43,9 +35,6 @@ class vote final bool operator== (nano::vote const &) const; bool operator!= (nano::vote const &) const; - boost::transform_iterator begin () const; - boost::transform_iterator end () const; - void serialize_json (boost::property_tree::ptree & tree) const; std::string to_json () const; std::string hashes_string () const; diff --git a/nano/slow_test/entry.cpp b/nano/slow_test/entry.cpp index cc8fd2e18e..db177c24cd 100644 --- a/nano/slow_test/entry.cpp +++ b/nano/slow_test/entry.cpp @@ -1,6 +1,8 @@ +#include #include #include + namespace nano { namespace test @@ -12,6 +14,7 @@ void force_nano_dev_network (); int main (int argc, char ** argv) { + nano::initialize_logging (nano::log::preset::tests); nano::force_nano_dev_network (); nano::node_singleton_memory_pool_purge_guard memory_pool_cleanup_guard; testing::InitGoogleTest (&argc, argv); diff --git a/nano/slow_test/node.cpp b/nano/slow_test/node.cpp index 2d1ac20bc5..ef0b52a22b 100644 --- a/nano/slow_test/node.cpp +++ b/nano/slow_test/node.cpp @@ -1,4 +1,5 @@ #include +#include #include #include #include @@ -118,7 +119,7 @@ TEST (system, receive_while_synchronizing) TEST (ledger, deep_account_compute) { - nano::logger_mt logger; + nano::nlogger logger; auto store = nano::make_store (logger, nano::unique_path (), nano::dev::constants); ASSERT_FALSE (store->init_error ()); nano::stats stats; @@ -538,7 +539,7 @@ TEST (store, vote_load) */ TEST (store, pruned_load) { - nano::logger_mt logger; + nano::nlogger logger; auto path (nano::unique_path ()); constexpr auto num_pruned = 2000000; auto const expected_result = num_pruned / 2; @@ -1224,8 +1225,7 @@ TEST (confirmation_height, many_accounts_send_receive_self_no_elections) // Don't test this in rocksdb mode return; } - nano::logger_mt logger; - nano::logging logging; + nano::nlogger logger; auto path (nano::unique_path ()); auto store = nano::make_store (logger, path, nano::dev::constants); ASSERT_TRUE (!store->init_error ()); @@ -1237,7 +1237,7 @@ TEST (confirmation_height, many_accounts_send_receive_self_no_elections) boost::latch initialized_latch{ 0 }; nano::block_hash block_hash_being_processed{ 0 }; - nano::confirmation_height_processor confirmation_height_processor{ ledger, write_database_queue, 10ms, logging, logger, initialized_latch, confirmation_height_mode::automatic }; + nano::confirmation_height_processor confirmation_height_processor{ ledger, write_database_queue, 10ms, logger, initialized_latch, confirmation_height_mode::automatic }; auto const num_accounts = 100000; diff --git a/nano/store/lmdb/lmdb.cpp b/nano/store/lmdb/lmdb.cpp index 8834c38d01..a88eb14d0e 100644 --- a/nano/store/lmdb/lmdb.cpp +++ b/nano/store/lmdb/lmdb.cpp @@ -12,7 +12,7 @@ #include -nano::store::lmdb::component::component (nano::logger_mt & logger_a, std::filesystem::path const & path_a, nano::ledger_constants & constants, nano::txn_tracking_config const & txn_tracking_config_a, std::chrono::milliseconds block_processor_batch_max_time_a, nano::lmdb_config const & lmdb_config_a, bool backup_before_upgrade_a) : +nano::store::lmdb::component::component (nano::nlogger & nlogger_a, std::filesystem::path const & path_a, nano::ledger_constants & constants, nano::txn_tracking_config const & txn_tracking_config_a, std::chrono::milliseconds block_processor_batch_max_time_a, nano::lmdb_config const & lmdb_config_a, bool backup_before_upgrade_a) : // clang-format off nano::store::component{ block_store, @@ -37,9 +37,9 @@ nano::store::lmdb::component::component (nano::logger_mt & logger_a, std::filesy confirmation_height_store{ *this }, final_vote_store{ *this }, version_store{ *this }, - logger (logger_a), + nlogger{ nlogger_a }, env (error, path_a, nano::store::lmdb::env::options::make ().set_config (lmdb_config_a).set_use_no_mem_init (true)), - mdb_txn_tracker (logger_a, txn_tracking_config_a, block_processor_batch_max_time_a), + mdb_txn_tracker (nlogger_a, txn_tracking_config_a, block_processor_batch_max_time_a), txn_tracking_enabled (txn_tracking_config_a.enable) { if (!error) @@ -66,10 +66,11 @@ nano::store::lmdb::component::component (nano::logger_mt & logger_a, std::filesy { if (!is_fresh_db) { - logger.always_log ("Upgrade in progress..."); + nlogger.info (nano::log::tag::lmdb, "Upgrade in progress..."); + if (backup_before_upgrade_a) { - create_backup_file (env, path_a, logger_a); + create_backup_file (env, path_a, nlogger); } } auto needs_vacuuming = false; @@ -84,9 +85,18 @@ nano::store::lmdb::component::component (nano::logger_mt & logger_a, std::filesy if (needs_vacuuming) { - logger.always_log ("Preparing vacuum..."); + nlogger.info (nano::log::tag::lmdb, "Ledger vaccum in progress..."); + auto vacuum_success = vacuum_after_upgrade (path_a, lmdb_config_a); - logger.always_log (vacuum_success ? "Vacuum succeeded." : "Failed to vacuum. (Optional) Ensure enough disk space is available for a copy of the database and try to vacuum after shutting down the node"); + if (vacuum_success) + { + nlogger.info (nano::log::tag::lmdb, "Ledger vacuum completed"); + } + else + { + nlogger.error (nano::log::tag::lmdb, "Ledger vaccum failed"); + nlogger.error (nano::log::tag::lmdb, "(Optional) Please ensure enough disk space is available for a copy of the database and try to vacuum after shutting down the node"); + } } } else @@ -202,7 +212,7 @@ bool nano::store::lmdb::component::do_upgrades (store::write_transaction & trans auto version_l = version.get (transaction_a); if (version_l < version_minimum) { - logger.always_log (boost::str (boost::format ("The version of the ledger (%1%) is lower than the minimum (%2%) which is supported for upgrades. Either upgrade to a v19, v20 or v21 node first or delete the ledger.") % version_l % version_minimum)); + nlogger.critical (nano::log::tag::lmdb, "The version of the ledger ({}) is lower than the minimum ({}) which is supported for upgrades. Either upgrade a node first or delete the ledger.", version_l, version_minimum); return true; } switch (version_l) @@ -213,7 +223,7 @@ bool nano::store::lmdb::component::do_upgrades (store::write_transaction & trans case 22: break; default: - logger.always_log (boost::str (boost::format ("The version of the ledger (%1%) is too high for this node") % version_l)); + nlogger.critical (nano::log::tag::lmdb, "The version of the ledger ({}) is too high for this node", version_l); error = true; break; } @@ -222,16 +232,18 @@ bool nano::store::lmdb::component::do_upgrades (store::write_transaction & trans void nano::store::lmdb::component::upgrade_v21_to_v22 (store::write_transaction const & transaction_a) { - logger.always_log ("Preparing v21 to v22 database upgrade..."); + nlogger.info (nano::log::tag::lmdb, "Upgrading database from v21 to v22..."); + MDB_dbi unchecked_handle{ 0 }; release_assert (!mdb_dbi_open (env.tx (transaction_a), "unchecked", MDB_CREATE, &unchecked_handle)); release_assert (!mdb_drop (env.tx (transaction_a), unchecked_handle, 1)); // del = 1, to delete it from the environment and close the DB handle. version.put (transaction_a, 22); - logger.always_log ("Finished removing unchecked table"); + + nlogger.info (nano::log::tag::lmdb, "Upgrading database from v21 to v22 completed"); } /** Takes a filepath, appends '_backup_' to the end (but before any extension) and saves that file in the same directory */ -void nano::store::lmdb::component::create_backup_file (nano::store::lmdb::env & env_a, std::filesystem::path const & filepath_a, nano::logger_mt & logger_a) +void nano::store::lmdb::component::create_backup_file (nano::store::lmdb::env & env_a, std::filesystem::path const & filepath_a, nano::nlogger & nlogger) { auto extension = filepath_a.extension (); auto filename_without_extension = filepath_a.filename ().replace_extension (""); @@ -242,22 +254,18 @@ void nano::store::lmdb::component::create_backup_file (nano::store::lmdb::env & backup_filename += std::to_string (std::chrono::system_clock::now ().time_since_epoch ().count ()); backup_filename += extension; auto backup_filepath = backup_path / backup_filename; - auto start_message (boost::str (boost::format ("Performing %1% backup before database upgrade...") % filepath_a.filename ())); - logger_a.always_log (start_message); - std::cout << start_message << std::endl; + + nlogger.info (nano::log::tag::lmdb, "Performing {} backup before database upgrade...", filepath_a.filename ().string ()); + auto error (mdb_env_copy (env_a, backup_filepath.string ().c_str ())); if (error) { - auto error_message (boost::str (boost::format ("%1% backup failed") % filepath_a.filename ())); - logger_a.always_log (error_message); - std::cerr << error_message << std::endl; + nlogger.critical (nano::log::tag::lmdb, "Database backup failed"); std::exit (1); } else { - auto success_message (boost::str (boost::format ("Backup created: %1%") % backup_filename)); - logger_a.always_log (success_message); - std::cout << success_message << std::endl; + nlogger.info (nano::log::tag::lmdb, "Database backup completed. Backup can be found at: {}", backup_filepath.string ()); } } diff --git a/nano/store/lmdb/lmdb.hpp b/nano/store/lmdb/lmdb.hpp index 91822f7f95..5b28dbdf11 100644 --- a/nano/store/lmdb/lmdb.hpp +++ b/nano/store/lmdb/lmdb.hpp @@ -2,7 +2,7 @@ #include #include -#include +#include #include #include #include @@ -63,7 +63,7 @@ class component : public nano::store::component friend class nano::store::lmdb::version; public: - component (nano::logger_mt &, std::filesystem::path const &, nano::ledger_constants & constants, nano::txn_tracking_config const & txn_tracking_config_a = nano::txn_tracking_config{}, std::chrono::milliseconds block_processor_batch_max_time_a = std::chrono::milliseconds (5000), nano::lmdb_config const & lmdb_config_a = nano::lmdb_config{}, bool backup_before_upgrade = false); + component (nano::nlogger &, std::filesystem::path const &, nano::ledger_constants & constants, nano::txn_tracking_config const & txn_tracking_config_a = nano::txn_tracking_config{}, std::chrono::milliseconds block_processor_batch_max_time_a = std::chrono::milliseconds (5000), nano::lmdb_config const & lmdb_config_a = nano::lmdb_config{}, bool backup_before_upgrade = false); store::write_transaction tx_begin_write (std::vector const & tables_requiring_lock = {}, std::vector const & tables_no_lock = {}) override; store::read_transaction tx_begin_read () const override; @@ -71,14 +71,14 @@ class component : public nano::store::component void serialize_mdb_tracker (boost::property_tree::ptree &, std::chrono::milliseconds, std::chrono::milliseconds) override; - static void create_backup_file (nano::store::lmdb::env &, std::filesystem::path const &, nano::logger_mt &); + static void create_backup_file (nano::store::lmdb::env &, std::filesystem::path const &, nano::nlogger &); void serialize_memory_stats (boost::property_tree::ptree &) override; unsigned max_block_write_batch_num () const override; private: - nano::logger_mt & logger; + nano::nlogger & nlogger; bool error{ false }; public: diff --git a/nano/store/lmdb/transaction.cpp b/nano/store/lmdb/transaction.cpp index a01698c09d..bf7e0c3820 100644 --- a/nano/store/lmdb/transaction.cpp +++ b/nano/store/lmdb/transaction.cpp @@ -1,5 +1,5 @@ #include -#include +#include #include #include #include @@ -116,8 +116,8 @@ bool nano::store::lmdb::write_transaction_impl::contains (nano::tables table_a) return true; } -nano::mdb_txn_tracker::mdb_txn_tracker (nano::logger_mt & logger_a, nano::txn_tracking_config const & txn_tracking_config_a, std::chrono::milliseconds block_processor_batch_max_time_a) : - logger (logger_a), +nano::mdb_txn_tracker::mdb_txn_tracker (nano::nlogger & nlogger_a, nano::txn_tracking_config const & txn_tracking_config_a, std::chrono::milliseconds block_processor_batch_max_time_a) : + nlogger (nlogger_a), txn_tracking_config (txn_tracking_config_a), block_processor_batch_max_time (block_processor_batch_max_time_a) { @@ -194,7 +194,12 @@ void nano::mdb_txn_tracker::log_if_held_long_enough (nano::mdb_txn_stats const & if (!should_ignore && ((is_write && time_open >= txn_tracking_config.min_write_txn_time) || (!is_write && time_open >= txn_tracking_config.min_read_txn_time))) { debug_assert (mdb_txn_stats.stacktrace); - logger.always_log (boost::str (boost::format ("%1%ms %2% held on thread %3%\n%4%") % mdb_txn_stats.timer.since_start ().count () % (is_write ? "write lock" : "read") % mdb_txn_stats.thread_name % *mdb_txn_stats.stacktrace)); + + nlogger.warn (nano::log::tag::txn_tracker, "{}ms {} held on thread {}\n{}", + time_open.count (), + is_write ? "write lock" : "read", + mdb_txn_stats.thread_name, + nano::util::to_str (*mdb_txn_stats.stacktrace)); } } diff --git a/nano/store/lmdb/transaction_impl.hpp b/nano/store/lmdb/transaction_impl.hpp index 001fd896a3..971908b5da 100644 --- a/nano/store/lmdb/transaction_impl.hpp +++ b/nano/store/lmdb/transaction_impl.hpp @@ -2,6 +2,7 @@ #include #include +#include #include #include #include @@ -11,10 +12,6 @@ #include -namespace nano -{ -class logger_mt; -} namespace nano::store::lmdb { class env; @@ -75,7 +72,7 @@ class mdb_txn_stats class mdb_txn_tracker { public: - mdb_txn_tracker (nano::logger_mt & logger_a, nano::txn_tracking_config const & txn_tracking_config_a, std::chrono::milliseconds block_processor_batch_max_time_a); + mdb_txn_tracker (nano::nlogger &, nano::txn_tracking_config const & txn_tracking_config_a, std::chrono::milliseconds block_processor_batch_max_time_a); void serialize_json (boost::property_tree::ptree & json, std::chrono::milliseconds min_read_time, std::chrono::milliseconds min_write_time); void add (store::transaction_impl const * transaction_impl); void erase (store::transaction_impl const * transaction_impl); @@ -83,7 +80,7 @@ class mdb_txn_tracker private: nano::mutex mutex; std::vector stats; - nano::logger_mt & logger; + nano::nlogger & nlogger; nano::txn_tracking_config txn_tracking_config; std::chrono::milliseconds block_processor_batch_max_time; diff --git a/nano/store/rocksdb/rocksdb.cpp b/nano/store/rocksdb/rocksdb.cpp index 054fec0a82..bb5a79ef4c 100644 --- a/nano/store/rocksdb/rocksdb.cpp +++ b/nano/store/rocksdb/rocksdb.cpp @@ -34,7 +34,7 @@ class event_listener : public rocksdb::EventListener }; } -nano::store::rocksdb::component::component (nano::logger_mt & logger_a, std::filesystem::path const & path_a, nano::ledger_constants & constants, nano::rocksdb_config const & rocksdb_config_a, bool open_read_only_a) : +nano::store::rocksdb::component::component (nano::nlogger & nlogger_a, std::filesystem::path const & path_a, nano::ledger_constants & constants, nano::rocksdb_config const & rocksdb_config_a, bool open_read_only_a) : // clang-format off nano::store::component{ block_store, @@ -59,7 +59,7 @@ nano::store::rocksdb::component::component (nano::logger_mt & logger_a, std::fil confirmation_height_store{ *this }, final_vote_store{ *this }, version_store{ *this }, - logger{ logger_a }, + nlogger{ nlogger_a }, constants{ constants }, rocksdb_config{ rocksdb_config_a }, max_block_write_batch_num_m{ nano::narrow_cast (blocks_memtable_size_bytes () / (2 * (sizeof (nano::block_type) + nano::state_block::size + nano::block_sideband::size (nano::block_type::state)))) }, @@ -95,14 +95,16 @@ nano::store::rocksdb::component::component (nano::logger_mt & logger_a, std::fil auto version_l = version.get (transaction); if (version_l > version_current) { + nlogger.critical (nano::log::tag::rocksdb, "The version of the ledger ({}) is too high for this node", version_l); + error = true; - logger.always_log (boost::str (boost::format ("The version of the ledger (%1%) is too high for this node") % version_l)); return; } else if (version_l < version_minimum) { + nlogger.critical (nano::log::tag::rocksdb, "The version of the ledger ({}) is lower than the minimum ({}) which is supported for upgrades. Either upgrade a node first or delete the ledger.", version_l, version_minimum); + error = true; - logger.always_log (boost::str (boost::format ("The version of the ledger (%1%) is lower than the minimum (%2%) which is supported for upgrades. Either upgrade to a v19, v20 or v21 node first or delete the ledger.") % version_l % version_minimum)); return; } is_fully_upgraded = (version_l == version_current); @@ -149,7 +151,8 @@ nano::store::rocksdb::component::component (nano::logger_mt & logger_a, std::fil open (error, path_a, open_read_only_a, options, get_current_column_families (path_a.string (), options)); if (!error) { - logger.always_log ("Upgrade in progress..."); + nlogger.info (nano::log::tag::rocksdb, "Upgrade in progress..."); + auto transaction = tx_begin_write (); error |= do_upgrades (transaction); } @@ -240,7 +243,7 @@ bool nano::store::rocksdb::component::do_upgrades (store::write_transaction cons case 22: break; default: - logger.always_log (boost::str (boost::format ("The version of the ledger (%1%) is too high for this node") % version_l)); + nlogger.critical (nano::log::tag::rocksdb, "The version of the ledger ({}) is too high for this node", version_l); error_l = true; break; } @@ -249,7 +252,8 @@ bool nano::store::rocksdb::component::do_upgrades (store::write_transaction cons void nano::store::rocksdb::component::upgrade_v21_to_v22 (store::write_transaction const & transaction_a) { - logger.always_log ("Preparing v21 to v22 database upgrade..."); + nlogger.info (nano::log::tag::rocksdb, "Upgrading database from v21 to v22..."); + if (column_family_exists ("unchecked")) { auto const unchecked_handle = get_column_family ("unchecked"); @@ -264,9 +268,12 @@ void nano::store::rocksdb::component::upgrade_v21_to_v22 (store::write_transacti } return false; }); + nlogger.debug (nano::log::tag::rocksdb, "Finished removing unchecked table"); } + version.put (transaction_a, 22); - logger.always_log ("Finished removing unchecked table"); + + nlogger.info (nano::log::tag::rocksdb, "Upgrading database from v21 to v22 completed"); } void nano::store::rocksdb::component::generate_tombstone_map () @@ -909,7 +916,7 @@ bool nano::store::rocksdb::component::copy_db (std::filesystem::path const & des // Open it so that it flushes all WAL files if (status.ok ()) { - nano::store::rocksdb::component rocksdb_store{ logger, destination_path.string (), constants, rocksdb_config, false }; + nano::store::rocksdb::component rocksdb_store{ nlogger, destination_path.string (), constants, rocksdb_config, false }; return !rocksdb_store.init_error (); } return false; diff --git a/nano/store/rocksdb/rocksdb.hpp b/nano/store/rocksdb/rocksdb.hpp index 9490ed9522..92a093504f 100644 --- a/nano/store/rocksdb/rocksdb.hpp +++ b/nano/store/rocksdb/rocksdb.hpp @@ -1,7 +1,7 @@ #pragma once #include -#include +#include #include #include #include @@ -36,8 +36,8 @@ namespace nano::store::rocksdb class rocksdb_block_store_upgrade_v21_v22_Test; /** - * rocksdb implementation of the block store - */ + * rocksdb implementation of the block store + */ class component : public nano::store::component { private: @@ -64,7 +64,7 @@ class component : public nano::store::component friend class nano::store::rocksdb::pruned; friend class nano::store::rocksdb::version; - explicit component (nano::logger_mt &, std::filesystem::path const &, nano::ledger_constants & constants, nano::rocksdb_config const & = nano::rocksdb_config{}, bool open_read_only = false); + explicit component (nano::nlogger &, std::filesystem::path const &, nano::ledger_constants & constants, nano::rocksdb_config const & = nano::rocksdb_config{}, bool open_read_only = false); store::write_transaction tx_begin_write (std::vector const & tables_requiring_lock = {}, std::vector const & tables_no_lock = {}) override; store::read_transaction tx_begin_read () const override; @@ -103,7 +103,7 @@ class component : public nano::store::component private: bool error{ false }; - nano::logger_mt & logger; + nano::nlogger & nlogger; nano::ledger_constants & constants; // Optimistic transactions are used in write mode ::rocksdb::OptimisticTransactionDB * optimistic_db = nullptr; diff --git a/nano/test_common/ledger.cpp b/nano/test_common/ledger.cpp index a3337bc925..7755ebaa7a 100644 --- a/nano/test_common/ledger.cpp +++ b/nano/test_common/ledger.cpp @@ -3,7 +3,7 @@ #include nano::test::context::ledger_context::ledger_context (std::deque> && blocks) : - store_m{ nano::make_store (logger, nano::unique_path (), nano::dev::constants) }, + store_m{ nano::make_store (nlogger, nano::unique_path (), nano::dev::constants) }, ledger_m{ *store_m, stats_m, nano::dev::constants }, blocks_m{ blocks } { diff --git a/nano/test_common/ledger.hpp b/nano/test_common/ledger.hpp index 17bafae687..7e86ea90f7 100644 --- a/nano/test_common/ledger.hpp +++ b/nano/test_common/ledger.hpp @@ -27,7 +27,7 @@ namespace test std::deque> const & blocks () const; private: - nano::logger_mt logger; + nano::nlogger nlogger; std::unique_ptr store_m; nano::stats stats_m; nano::ledger ledger_m; diff --git a/nano/test_common/system.hpp b/nano/test_common/system.hpp index e03532ccef..f0f31afd92 100644 --- a/nano/test_common/system.hpp +++ b/nano/test_common/system.hpp @@ -68,6 +68,7 @@ namespace test std::vector> nodes; nano::logging logging; nano::stats stats; + nano::nlogger nlogger; nano::work_pool work{ nano::dev::network_params.network, std::max (nano::hardware_concurrency (), 1u) }; std::chrono::time_point> deadline{ std::chrono::steady_clock::time_point::max () }; double deadline_scaling_factor{ 1.0 };