diff --git a/nano/core_test/CMakeLists.txt b/nano/core_test/CMakeLists.txt index 5e73f135..60616873 100644 --- a/nano/core_test/CMakeLists.txt +++ b/nano/core_test/CMakeLists.txt @@ -8,6 +8,7 @@ add_executable (core_test entry.cpp gap_cache.cpp ledger.cpp + logger.cpp network.cpp node.cpp message.cpp diff --git a/nano/core_test/logger.cpp b/nano/core_test/logger.cpp new file mode 100644 index 00000000..88b56e02 --- /dev/null +++ b/nano/core_test/logger.cpp @@ -0,0 +1,178 @@ +#include +#include +#include +#include +#include +#include + +using namespace std::chrono_literals; + +TEST (logging, serialization) +{ + auto path (nano::unique_path ()); + nano::logging logging1; + logging1.init (path); + logging1.ledger_logging_value = !logging1.ledger_logging_value; + logging1.ledger_duplicate_logging_value = !logging1.ledger_duplicate_logging_value; + logging1.network_logging_value = !logging1.network_logging_value; + logging1.network_message_logging_value = !logging1.network_message_logging_value; + logging1.network_publish_logging_value = !logging1.network_publish_logging_value; + logging1.network_packet_logging_value = !logging1.network_packet_logging_value; + logging1.network_keepalive_logging_value = !logging1.network_keepalive_logging_value; + logging1.network_node_id_handshake_logging_value = !logging1.network_node_id_handshake_logging_value; + logging1.node_lifetime_tracing_value = !logging1.node_lifetime_tracing_value; + logging1.insufficient_work_logging_value = !logging1.insufficient_work_logging_value; + logging1.log_rpc_value = !logging1.log_rpc_value; + logging1.bulk_pull_logging_value = !logging1.bulk_pull_logging_value; + logging1.work_generation_time_value = !logging1.work_generation_time_value; + logging1.log_to_cerr_value = !logging1.log_to_cerr_value; + logging1.max_size = 10; + logging1.min_time_between_log_output = 100ms; + nano::jsonconfig tree; + logging1.serialize_json (tree); + nano::logging logging2; + logging2.init (path); + bool upgraded (false); + ASSERT_FALSE (logging2.deserialize_json (upgraded, tree)); + ASSERT_FALSE (upgraded); + ASSERT_EQ (logging1.ledger_logging_value, logging2.ledger_logging_value); + ASSERT_EQ (logging1.ledger_duplicate_logging_value, logging2.ledger_duplicate_logging_value); + ASSERT_EQ (logging1.network_logging_value, logging2.network_logging_value); + ASSERT_EQ (logging1.network_message_logging_value, logging2.network_message_logging_value); + ASSERT_EQ (logging1.network_publish_logging_value, logging2.network_publish_logging_value); + ASSERT_EQ (logging1.network_packet_logging_value, logging2.network_packet_logging_value); + ASSERT_EQ (logging1.network_keepalive_logging_value, logging2.network_keepalive_logging_value); + ASSERT_EQ (logging1.network_node_id_handshake_logging_value, logging2.network_node_id_handshake_logging_value); + ASSERT_EQ (logging1.node_lifetime_tracing_value, logging2.node_lifetime_tracing_value); + ASSERT_EQ (logging1.insufficient_work_logging_value, logging2.insufficient_work_logging_value); + ASSERT_EQ (logging1.log_rpc_value, logging2.log_rpc_value); + ASSERT_EQ (logging1.bulk_pull_logging_value, logging2.bulk_pull_logging_value); + ASSERT_EQ (logging1.work_generation_time_value, logging2.work_generation_time_value); + ASSERT_EQ (logging1.log_to_cerr_value, logging2.log_to_cerr_value); + ASSERT_EQ (logging1.max_size, logging2.max_size); + ASSERT_EQ (logging1.min_time_between_log_output, logging2.min_time_between_log_output); +} + +TEST (logging, upgrade_v1_v2) +{ + auto path1 (nano::unique_path ()); + auto path2 (nano::unique_path ()); + nano::logging logging1; + logging1.init (path1); + nano::logging logging2; + logging2.init (path2); + nano::jsonconfig tree; + logging1.serialize_json (tree); + tree.erase ("version"); + tree.erase ("vote"); + bool upgraded (false); + ASSERT_FALSE (logging2.deserialize_json (upgraded, tree)); + ASSERT_LE (2, tree.get ("version")); + ASSERT_FALSE (tree.get ("vote")); +} + +TEST (logging, upgrade_v6_v7) +{ + auto path1 (nano::unique_path ()); + auto path2 (nano::unique_path ()); + nano::logging logging1; + logging1.init (path1); + nano::logging logging2; + logging2.init (path2); + nano::jsonconfig tree; + logging1.serialize_json (tree); + tree.erase ("version"); + tree.erase ("min_time_between_output"); + bool upgraded (false); + ASSERT_FALSE (logging2.deserialize_json (upgraded, tree)); + ASSERT_TRUE (upgraded); + ASSERT_LE (7, tree.get ("version")); + ASSERT_EQ (5, tree.get ("min_time_between_output")); +} + +namespace +{ +class boost_log_cerr_redirect +{ +public: + boost_log_cerr_redirect (std::streambuf * new_buffer) : + old (std::cerr.rdbuf (new_buffer)) + { + console_sink = (boost::log::add_console_log (std::cerr, boost::log::keywords::format = "%Message%")); + } + + ~boost_log_cerr_redirect () + { + std::cerr.rdbuf (old); + boost::log::core::get ()->remove_sink (console_sink); + } + +private: + std::streambuf * old; + boost::shared_ptr> console_sink; +}; +} + +TEST (logger, changing_time_interval) +{ + auto path1 (nano::unique_path ()); + nano::logging logging; + logging.init (path1); + logging.min_time_between_log_output = 0ms; + nano::logger_mt my_logger (logging.min_time_between_log_output); + auto error (my_logger.try_log ("logger.changing_time_interval1")); + ASSERT_FALSE (error); + logging.min_time_between_log_output = 20s; + error = my_logger.try_log ("logger, changing_time_interval2"); + ASSERT_TRUE (error); +} + +TEST (logger, try_log) +{ + auto path1 (nano::unique_path ()); + std::stringstream ss; + boost_log_cerr_redirect redirect_cerr (ss.rdbuf ()); + nano::logger_mt my_logger (3ms); + auto output1 = "logger.try_log1"; + auto error (my_logger.try_log (output1)); + ASSERT_FALSE (error); + auto output2 = "logger.try_log2"; + error = my_logger.try_log (output2); + ASSERT_TRUE (error); // Fails as it is occuring too soon + + // Sleep for a bit and then confirm + std::this_thread::sleep_for (3ms); + error = my_logger.try_log (output2); + ASSERT_FALSE (error); + + std::string str; + std::getline (ss, str, '\n'); + ASSERT_STREQ (str.c_str (), output1); + std::getline (ss, str, '\n'); + ASSERT_STREQ (str.c_str (), output2); +} + +TEST (logger, always_log) +{ + auto path1 (nano::unique_path ()); + std::stringstream ss; + boost_log_cerr_redirect redirect_cerr (ss.rdbuf ()); + nano::logger_mt my_logger (20s); // Make time interval effectively unreachable + auto output1 = "logger.always_log1"; + auto error (my_logger.try_log (output1)); + ASSERT_FALSE (error); + + // Time is too soon after, so it won't be logged + auto output2 = "logger.always_log2"; + error = my_logger.try_log (output2); + ASSERT_TRUE (error); + + // Force it to be logged + my_logger.always_log (output2); + + std::string str; + std::getline (ss, str, '\n'); + ASSERT_STREQ (str.c_str (), output1); + std::getline (ss, str, '\n'); + ASSERT_STREQ (str.c_str (), output2); +} diff --git a/nano/core_test/node.cpp b/nano/core_test/node.cpp index 53829696..8a619c80 100644 --- a/nano/core_test/node.cpp +++ b/nano/core_test/node.cpp @@ -421,68 +421,6 @@ TEST (node, working) ASSERT_FALSE (path.empty ()); } -TEST (logging, serialization) -{ - auto path (nano::unique_path ()); - nano::logging logging1; - logging1.init (path); - logging1.ledger_logging_value = !logging1.ledger_logging_value; - logging1.ledger_duplicate_logging_value = !logging1.ledger_duplicate_logging_value; - logging1.network_logging_value = !logging1.network_logging_value; - logging1.network_message_logging_value = !logging1.network_message_logging_value; - logging1.network_publish_logging_value = !logging1.network_publish_logging_value; - logging1.network_packet_logging_value = !logging1.network_packet_logging_value; - logging1.network_keepalive_logging_value = !logging1.network_keepalive_logging_value; - logging1.network_node_id_handshake_logging_value = !logging1.network_node_id_handshake_logging_value; - logging1.node_lifetime_tracing_value = !logging1.node_lifetime_tracing_value; - logging1.insufficient_work_logging_value = !logging1.insufficient_work_logging_value; - logging1.log_rpc_value = !logging1.log_rpc_value; - logging1.bulk_pull_logging_value = !logging1.bulk_pull_logging_value; - logging1.work_generation_time_value = !logging1.work_generation_time_value; - logging1.log_to_cerr_value = !logging1.log_to_cerr_value; - logging1.max_size = 10; - nano::jsonconfig tree; - logging1.serialize_json (tree); - nano::logging logging2; - logging2.init (path); - bool upgraded (false); - ASSERT_FALSE (logging2.deserialize_json (upgraded, tree)); - ASSERT_FALSE (upgraded); - ASSERT_EQ (logging1.ledger_logging_value, logging2.ledger_logging_value); - ASSERT_EQ (logging1.ledger_duplicate_logging_value, logging2.ledger_duplicate_logging_value); - ASSERT_EQ (logging1.network_logging_value, logging2.network_logging_value); - ASSERT_EQ (logging1.network_message_logging_value, logging2.network_message_logging_value); - ASSERT_EQ (logging1.network_publish_logging_value, logging2.network_publish_logging_value); - ASSERT_EQ (logging1.network_packet_logging_value, logging2.network_packet_logging_value); - ASSERT_EQ (logging1.network_keepalive_logging_value, logging2.network_keepalive_logging_value); - ASSERT_EQ (logging1.network_node_id_handshake_logging_value, logging2.network_node_id_handshake_logging_value); - ASSERT_EQ (logging1.node_lifetime_tracing_value, logging2.node_lifetime_tracing_value); - ASSERT_EQ (logging1.insufficient_work_logging_value, logging2.insufficient_work_logging_value); - ASSERT_EQ (logging1.log_rpc_value, logging2.log_rpc_value); - ASSERT_EQ (logging1.bulk_pull_logging_value, logging2.bulk_pull_logging_value); - ASSERT_EQ (logging1.work_generation_time_value, logging2.work_generation_time_value); - ASSERT_EQ (logging1.log_to_cerr_value, logging2.log_to_cerr_value); - ASSERT_EQ (logging1.max_size, logging2.max_size); -} - -TEST (logging, upgrade_v1_v2) -{ - auto path1 (nano::unique_path ()); - auto path2 (nano::unique_path ()); - nano::logging logging1; - logging1.init (path1); - nano::logging logging2; - logging2.init (path2); - nano::jsonconfig tree; - logging1.serialize_json (tree); - tree.erase ("version"); - tree.erase ("vote"); - bool upgraded (false); - ASSERT_FALSE (logging2.deserialize_json (upgraded, tree)); - ASSERT_LE (2, tree.get ("version")); - ASSERT_FALSE (tree.get ("vote")); -} - TEST (node, price) { nano::system system (24000, 1); diff --git a/nano/node/blockprocessor.cpp b/nano/node/blockprocessor.cpp index 67bcef50..39a3f33e 100644 --- a/nano/node/blockprocessor.cpp +++ b/nano/node/blockprocessor.cpp @@ -77,7 +77,7 @@ void nano::block_processor::add (nano::unchecked_info const & info_a) } else { - BOOST_LOG (node.log) << "nano::block_processor::add called for hash " << info_a.block->hash ().to_string () << " with invalid work " << nano::to_string_hex (info_a.block->block_work ()); + node.logger.try_log ("nano::block_processor::add called for hash ", info_a.block->hash ().to_string (), " with invalid work ", nano::to_string_hex (info_a.block->block_work ())); assert (false && "nano::block_processor::add called with invalid work"); } } @@ -216,7 +216,7 @@ void nano::block_processor::verify_state_blocks (nano::transaction const & trans } if (node.config.logging.timing_logging ()) { - BOOST_LOG (node.log) << boost::str (boost::format ("Batch verified %1% state blocks in %2% %3%") % size % timer_l.stop ().count () % timer_l.unit ()); + node.logger.try_log (boost::str (boost::format ("Batch verified %1% state blocks in %2% %3%") % size % timer_l.stop ().count () % timer_l.unit ())); } } else @@ -268,7 +268,7 @@ void nano::block_processor::process_batch (std::unique_lock & lock_a if (log_this_record) { first_time = false; - BOOST_LOG (node.log) << boost::str (boost::format ("%1% blocks (+ %2% state blocks) (+ %3% forced) in processing queue") % blocks.size () % state_blocks.size () % forced.size ()); + node.logger.always_log (boost::str (boost::format ("%1% blocks (+ %2% state blocks) (+ %3% forced) in processing queue") % blocks.size () % state_blocks.size () % forced.size ())); } nano::unchecked_info info; bool force (false); @@ -293,10 +293,10 @@ void nano::block_processor::process_batch (std::unique_lock & lock_a if (successor != nullptr && successor->hash () != hash) { // Replace our block with the winner and roll back any dependent blocks - BOOST_LOG (node.log) << boost::str (boost::format ("Rolling back %1% and replacing with %2%") % successor->hash ().to_string () % hash.to_string ()); + node.logger.always_log (boost::str (boost::format ("Rolling back %1% and replacing with %2%") % successor->hash ().to_string () % hash.to_string ())); std::vector rollback_list; node.ledger.rollback (transaction, successor->hash (), rollback_list); - BOOST_LOG (node.log) << boost::str (boost::format ("%1% blocks rolled back") % rollback_list.size ()); + node.logger.always_log (boost::str (boost::format ("%1% blocks rolled back") % rollback_list.size ())); lock_a.lock (); // Prevent rolled back blocks second insertion auto inserted (rolled_back.insert (nano::rolled_hash{ std::chrono::steady_clock::now (), successor->hash () })); @@ -333,7 +333,7 @@ void nano::block_processor::process_batch (std::unique_lock & lock_a if (node.config.logging.timing_logging ()) { - BOOST_LOG (node.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.stop ().count () % timer_l.unit ()); + 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.stop ().count () % timer_l.unit ())); } } @@ -386,7 +386,7 @@ nano::process_return nano::block_processor::process_one (nano::transaction const { std::string block; info_a.block->serialize_json (block); - BOOST_LOG (node.log) << boost::str (boost::format ("Processing block %1%: %2%") % hash.to_string () % block); + node.logger.try_log (boost::str (boost::format ("Processing block %1%: %2%") % hash.to_string () % block)); } if (info_a.modified > nano::seconds_since_epoch () - 300 && node.block_arrival.recent (hash)) { @@ -399,7 +399,7 @@ nano::process_return nano::block_processor::process_one (nano::transaction const { if (node.config.logging.ledger_logging ()) { - BOOST_LOG (node.log) << boost::str (boost::format ("Gap previous for: %1%") % hash.to_string ()); + node.logger.try_log (boost::str (boost::format ("Gap previous for: %1%") % hash.to_string ())); } info_a.verified = result.verified; if (info_a.modified == 0) @@ -414,7 +414,7 @@ nano::process_return nano::block_processor::process_one (nano::transaction const { if (node.config.logging.ledger_logging ()) { - BOOST_LOG (node.log) << boost::str (boost::format ("Gap source for: %1%") % hash.to_string ()); + node.logger.try_log (boost::str (boost::format ("Gap source for: %1%") % hash.to_string ())); } info_a.verified = result.verified; if (info_a.modified == 0) @@ -429,7 +429,7 @@ nano::process_return nano::block_processor::process_one (nano::transaction const { if (node.config.logging.ledger_duplicate_logging ()) { - BOOST_LOG (node.log) << boost::str (boost::format ("Old for: %1%") % hash.to_string ()); + node.logger.try_log (boost::str (boost::format ("Old for: %1%") % hash.to_string ())); } if (!node.flags.fast_bootstrap) { @@ -442,7 +442,7 @@ nano::process_return nano::block_processor::process_one (nano::transaction const { if (node.config.logging.ledger_logging ()) { - BOOST_LOG (node.log) << boost::str (boost::format ("Bad signature for: %1%") % hash.to_string ()); + node.logger.try_log (boost::str (boost::format ("Bad signature for: %1%") % hash.to_string ())); } break; } @@ -450,7 +450,7 @@ nano::process_return nano::block_processor::process_one (nano::transaction const { if (node.config.logging.ledger_logging ()) { - BOOST_LOG (node.log) << boost::str (boost::format ("Negative spend for: %1%") % hash.to_string ()); + node.logger.try_log (boost::str (boost::format ("Negative spend for: %1%") % hash.to_string ())); } break; } @@ -458,7 +458,7 @@ nano::process_return nano::block_processor::process_one (nano::transaction const { if (node.config.logging.ledger_logging ()) { - BOOST_LOG (node.log) << boost::str (boost::format ("Unreceivable for: %1%") % hash.to_string ()); + node.logger.try_log (boost::str (boost::format ("Unreceivable for: %1%") % hash.to_string ())); } break; } @@ -472,20 +472,20 @@ nano::process_return nano::block_processor::process_one (nano::transaction const } if (node.config.logging.ledger_logging ()) { - BOOST_LOG (node.log) << boost::str (boost::format ("Fork for: %1% root: %2%") % hash.to_string () % info_a.block->root ().to_string ()); + node.logger.try_log (boost::str (boost::format ("Fork for: %1% root: %2%") % hash.to_string () % info_a.block->root ().to_string ())); } break; } case nano::process_result::opened_burn_account: { - BOOST_LOG (node.log) << boost::str (boost::format ("*** Rejecting open block for burn account ***: %1%") % hash.to_string ()); + node.logger.always_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 ()) { - BOOST_LOG (node.log) << boost::str (boost::format ("Balance mismatch for: %1%") % hash.to_string ()); + node.logger.try_log (boost::str (boost::format ("Balance mismatch for: %1%") % hash.to_string ())); } break; } @@ -493,7 +493,7 @@ nano::process_return nano::block_processor::process_one (nano::transaction const { if (node.config.logging.ledger_logging ()) { - BOOST_LOG (node.log) << boost::str (boost::format ("Representative mismatch for: %1%") % hash.to_string ()); + node.logger.try_log (boost::str (boost::format ("Representative mismatch for: %1%") % hash.to_string ())); } break; } @@ -501,7 +501,7 @@ nano::process_return nano::block_processor::process_one (nano::transaction const { if (node.config.logging.ledger_logging ()) { - BOOST_LOG (node.log) << boost::str (boost::format ("Block %1% cannot follow predecessor %2%") % hash.to_string () % info_a.block->previous ().to_string ()); + node.logger.try_log (boost::str (boost::format ("Block %1% cannot follow predecessor %2%") % hash.to_string () % info_a.block->previous ().to_string ())); } break; } diff --git a/nano/node/bootstrap.cpp b/nano/node/bootstrap.cpp index df73cf42..2fcfa58c 100644 --- a/nano/node/bootstrap.cpp +++ b/nano/node/bootstrap.cpp @@ -101,7 +101,7 @@ void nano::socket::checkup () { if (this_l->node->config.logging.bulk_pull_logging ()) { - BOOST_LOG (this_l->node->log) << boost::str (boost::format ("Disconnecting from %1% due to timeout") % this_l->remote_endpoint ()); + this_l->node->logger.try_log (boost::str (boost::format ("Disconnecting from %1% due to timeout") % this_l->remote_endpoint ())); } this_l->close (); } @@ -175,7 +175,7 @@ void nano::bootstrap_client::run () { if (this_l->node->config.logging.bulk_pull_logging ()) { - BOOST_LOG (this_l->node->log) << boost::str (boost::format ("Connection established to %1%") % this_l->endpoint); + this_l->node->logger.try_log (boost::str (boost::format ("Connection established to %1%") % this_l->endpoint)); } this_l->attempt->pool_connection (this_l->shared_from_this ()); } @@ -186,7 +186,7 @@ void nano::bootstrap_client::run () switch (ec.value ()) { default: - BOOST_LOG (this_l->node->log) << boost::str (boost::format ("Error initiating bootstrap connection to %1%: %2%") % this_l->endpoint % ec.message ()); + this_l->node->logger.try_log (boost::str (boost::format ("Error initiating bootstrap connection to %1%: %2%") % this_l->endpoint % ec.message ())); break; case boost::system::errc::connection_refused: case boost::system::errc::operation_canceled: @@ -221,7 +221,7 @@ void nano::frontier_req_client::run () { if (this_l->connection->node->config.logging.network_logging ()) { - BOOST_LOG (this_l->connection->node->log) << boost::str (boost::format ("Error while sending bootstrap request %1%") % ec.message ()); + this_l->connection->node->logger.try_log (boost::str (boost::format ("Error while sending bootstrap request %1%") % ec.message ())); } } }); @@ -260,7 +260,7 @@ void nano::frontier_req_client::receive_frontier () { if (this_l->connection->node->config.logging.network_message_logging ()) { - BOOST_LOG (this_l->connection->node->log) << boost::str (boost::format ("Invalid size: expected %1%, got %2%") % nano::frontier_req_client::size_frontier % size_a); + this_l->connection->node->logger.try_log (boost::str (boost::format ("Invalid size: expected %1%, got %2%") % nano::frontier_req_client::size_frontier % size_a)); } } }); @@ -306,13 +306,13 @@ void nano::frontier_req_client::received_frontier (boost::system::error_code con double blocks_per_sec = static_cast (count) / elapsed_sec; if (elapsed_sec > bootstrap_connection_warmup_time_sec && blocks_per_sec < bootstrap_minimum_frontier_blocks_per_sec) { - BOOST_LOG (connection->node->log) << boost::str (boost::format ("Aborting frontier req because it was too slow")); + connection->node->logger.try_log (boost::str (boost::format ("Aborting frontier req because it was too slow"))); promise.set_value (true); return; } if (connection->attempt->should_log ()) { - BOOST_LOG (connection->node->log) << boost::str (boost::format ("Received %1% frontiers from %2%") % std::to_string (count) % connection->socket->remote_endpoint ()); + connection->node->logger.always_log (boost::str (boost::format ("Received %1% frontiers from %2%") % std::to_string (count) % connection->socket->remote_endpoint ())); } auto transaction (connection->node->store.tx_begin_read ()); if (!account.is_zero ()) @@ -370,7 +370,7 @@ void nano::frontier_req_client::received_frontier (boost::system::error_code con } if (connection->node->config.logging.bulk_pull_logging ()) { - BOOST_LOG (connection->node->log) << "Bulk push cost: " << bulk_push_cost; + connection->node->logger.try_log ("Bulk push cost: ", bulk_push_cost); } { try @@ -388,7 +388,7 @@ void nano::frontier_req_client::received_frontier (boost::system::error_code con { if (connection->node->config.logging.network_logging ()) { - BOOST_LOG (connection->node->log) << boost::str (boost::format ("Error while receiving frontier %1%") % ec.message ()); + connection->node->logger.try_log (boost::str (boost::format ("Error while receiving frontier %1%") % ec.message ())); } } } @@ -442,7 +442,7 @@ nano::bulk_pull_client::~bulk_pull_client () connection->attempt->requeue_pull (pull); if (connection->node->config.logging.bulk_pull_logging ()) { - BOOST_LOG (connection->node->log) << boost::str (boost::format ("Bulk pull end block is not expected %1% for account %2%") % pull.end.to_string () % pull.account.to_account ()); + connection->node->logger.try_log (boost::str (boost::format ("Bulk pull end block is not expected %1% for account %2%") % pull.end.to_string () % pull.account.to_account ())); } } { @@ -469,12 +469,12 @@ void nano::bulk_pull_client::request () if (connection->node->config.logging.bulk_pull_logging ()) { std::unique_lock lock (connection->attempt->mutex); - BOOST_LOG (connection->node->log) << boost::str (boost::format ("Requesting account %1% from %2%. %3% accounts in queue") % req.start.to_account () % connection->endpoint % connection->attempt->pulls.size ()); + connection->node->logger.try_log (boost::str (boost::format ("Requesting account %1% from %2%. %3% accounts in queue") % req.start.to_account () % connection->endpoint % connection->attempt->pulls.size ())); } else if (connection->node->config.logging.network_logging () && connection->attempt->should_log ()) { std::unique_lock lock (connection->attempt->mutex); - BOOST_LOG (connection->node->log) << boost::str (boost::format ("%1% accounts in pull queue") % connection->attempt->pulls.size ()); + connection->node->logger.always_log (boost::str (boost::format ("%1% accounts in pull queue") % connection->attempt->pulls.size ())); } auto this_l (shared_from_this ()); connection->socket->async_write (buffer, [this_l](boost::system::error_code const & ec, size_t size_a) { @@ -486,7 +486,7 @@ void nano::bulk_pull_client::request () { if (this_l->connection->node->config.logging.bulk_pull_logging ()) { - BOOST_LOG (this_l->connection->node->log) << boost::str (boost::format ("Error sending bulk pull request to %1%: to %2%") % ec.message () % this_l->connection->endpoint); + this_l->connection->node->logger.try_log (boost::str (boost::format ("Error sending bulk pull request to %1%: to %2%") % ec.message () % this_l->connection->endpoint)); } } }); @@ -504,7 +504,7 @@ void nano::bulk_pull_client::receive_block () { if (this_l->connection->node->config.logging.bulk_pull_logging ()) { - BOOST_LOG (this_l->connection->node->log) << boost::str (boost::format ("Error receiving block type: %1%") % ec.message ()); + this_l->connection->node->logger.try_log (boost::str (boost::format ("Error receiving block type: %1%") % ec.message ())); } } }); @@ -564,7 +564,7 @@ void nano::bulk_pull_client::received_type () { if (connection->node->config.logging.network_packet_logging ()) { - BOOST_LOG (connection->node->log) << boost::str (boost::format ("Unknown type received as block type: %1%") % static_cast (type)); + connection->node->logger.try_log (boost::str (boost::format ("Unknown type received as block type: %1%") % static_cast (type))); } break; } @@ -584,7 +584,7 @@ void nano::bulk_pull_client::received_block (boost::system::error_code const & e { std::string block_l; block->serialize_json (block_l); - BOOST_LOG (connection->node->log) << boost::str (boost::format ("Pulled block %1% %2%") % hash.to_string () % block_l); + connection->node->logger.try_log (boost::str (boost::format ("Pulled block %1% %2%") % hash.to_string () % block_l)); } // Is block expected? bool block_expected (false); @@ -632,7 +632,7 @@ void nano::bulk_pull_client::received_block (boost::system::error_code const & e { if (connection->node->config.logging.bulk_pull_logging ()) { - BOOST_LOG (connection->node->log) << "Error deserializing block received from pull request"; + connection->node->logger.try_log ("Error deserializing block received from pull request"); } } } @@ -640,7 +640,7 @@ void nano::bulk_pull_client::received_block (boost::system::error_code const & e { if (connection->node->config.logging.bulk_pull_logging ()) { - BOOST_LOG (connection->node->log) << boost::str (boost::format ("Error bulk receiving block: %1%") % ec.message ()); + connection->node->logger.try_log (boost::str (boost::format ("Error bulk receiving block: %1%") % ec.message ())); } } } @@ -673,7 +673,7 @@ void nano::bulk_push_client::start () { if (this_l->connection->node->config.logging.bulk_pull_logging ()) { - BOOST_LOG (this_l->connection->node->log) << boost::str (boost::format ("Unable to send bulk_push request: %1%") % ec.message ()); + this_l->connection->node->logger.try_log (boost::str (boost::format ("Unable to send bulk_push request: %1%") % ec.message ())); } } }); @@ -709,7 +709,7 @@ void nano::bulk_push_client::push (nano::transaction const & transaction_a) { if (connection->node->config.logging.bulk_pull_logging ()) { - BOOST_LOG (connection->node->log) << "Bulk pushing range " << current_target.first.to_string () << " down to " << current_target.second.to_string (); + connection->node->logger.try_log ("Bulk pushing range ", current_target.first.to_string (), " down to ", current_target.second.to_string ()); } } } @@ -732,7 +732,7 @@ void nano::bulk_push_client::send_finished () connection->node->stats.inc (nano::stat::type::bootstrap, nano::stat::detail::bulk_push, nano::stat::dir::out); if (connection->node->config.logging.network_logging ()) { - BOOST_LOG (connection->node->log) << "Bulk push finished"; + connection->node->logger.try_log ("Bulk push finished"); } auto this_l (shared_from_this ()); connection->socket->async_write (buffer, [this_l](boost::system::error_code const & ec, size_t size_a) { @@ -764,7 +764,7 @@ void nano::bulk_push_client::push_block (nano::block const & block_a) { if (this_l->connection->node->config.logging.bulk_pull_logging ()) { - BOOST_LOG (this_l->connection->node->log) << boost::str (boost::format ("Error sending block during bulk push: %1%") % ec.message ()); + this_l->connection->node->logger.try_log (boost::str (boost::format ("Error sending block during bulk push: %1%") % ec.message ())); } } }); @@ -802,12 +802,12 @@ void nano::bulk_pull_account_client::request () if (connection->node->config.logging.bulk_pull_logging ()) { std::unique_lock lock (connection->attempt->mutex); - BOOST_LOG (connection->node->log) << boost::str (boost::format ("Requesting pending for account %1% from %2%. %3% accounts in queue") % req.account.to_account () % connection->endpoint % connection->attempt->wallet_accounts.size ()); + connection->node->logger.try_log (boost::str (boost::format ("Requesting pending for account %1% from %2%. %3% accounts in queue") % req.account.to_account () % connection->endpoint % connection->attempt->wallet_accounts.size ())); } else if (connection->node->config.logging.network_logging () && connection->attempt->should_log ()) { std::unique_lock lock (connection->attempt->mutex); - BOOST_LOG (connection->node->log) << boost::str (boost::format ("%1% accounts in pull queue") % connection->attempt->wallet_accounts.size ()); + connection->node->logger.always_log (boost::str (boost::format ("%1% accounts in pull queue") % connection->attempt->wallet_accounts.size ())); } auto this_l (shared_from_this ()); connection->socket->async_write (buffer, [this_l](boost::system::error_code const & ec, size_t size_a) { @@ -820,7 +820,7 @@ void nano::bulk_pull_account_client::request () this_l->connection->attempt->requeue_pending (this_l->account); if (this_l->connection->node->config.logging.bulk_pull_logging ()) { - BOOST_LOG (this_l->connection->node->log) << boost::str (boost::format ("Error starting bulk pull request to %1%: to %2%") % ec.message () % this_l->connection->endpoint); + this_l->connection->node->logger.try_log (boost::str (boost::format ("Error starting bulk pull request to %1%: to %2%") % ec.message () % this_l->connection->endpoint)); } } }); @@ -877,7 +877,7 @@ void nano::bulk_pull_account_client::receive_pending () this_l->connection->attempt->requeue_pending (this_l->account); if (this_l->connection->node->config.logging.network_logging ()) { - BOOST_LOG (this_l->connection->node->log) << boost::str (boost::format ("Error while receiving bulk pull account frontier %1%") % ec.message ()); + this_l->connection->node->logger.try_log (boost::str (boost::format ("Error while receiving bulk pull account frontier %1%") % ec.message ())); } } } @@ -886,7 +886,7 @@ void nano::bulk_pull_account_client::receive_pending () this_l->connection->attempt->requeue_pending (this_l->account); if (this_l->connection->node->config.logging.network_message_logging ()) { - BOOST_LOG (this_l->connection->node->log) << boost::str (boost::format ("Invalid size: expected %1%, got %2%") % size_l % size_a); + this_l->connection->node->logger.try_log (boost::str (boost::format ("Invalid size: expected %1%, got %2%") % size_l % size_a)); } } }); @@ -921,13 +921,13 @@ stopped (false), mode (nano::bootstrap_mode::legacy), lazy_stopped (0) { - BOOST_LOG (node->log) << "Starting bootstrap attempt"; + node->logger.always_log ("Starting bootstrap attempt"); node->bootstrap_initiator.notify_listeners (true); } nano::bootstrap_attempt::~bootstrap_attempt () { - BOOST_LOG (node->log) << "Exiting bootstrap attempt"; + node->logger.always_log ("Exiting bootstrap attempt"); node->bootstrap_initiator.notify_listeners (false); } @@ -969,11 +969,11 @@ bool nano::bootstrap_attempt::request_frontier (std::unique_lock & l { if (!result) { - BOOST_LOG (node->log) << boost::str (boost::format ("Completed frontier request, %1% out of sync accounts according to %2%") % pulls.size () % connection_l->endpoint); + node->logger.try_log (boost::str (boost::format ("Completed frontier request, %1% out of sync accounts according to %2%") % pulls.size () % connection_l->endpoint)); } else { - BOOST_LOG (node->log) << "frontier_req failed, reattempting"; + node->logger.try_log ("frontier_req failed, reattempting"); } } } @@ -1026,10 +1026,10 @@ void nano::bootstrap_attempt::request_push (std::unique_lock & lock_ } if (node->config.logging.network_logging ()) { - BOOST_LOG (node->log) << "Exiting bulk push client"; + node->logger.try_log ("Exiting bulk push client"); if (error) { - BOOST_LOG (node->log) << "Bulk push client failed"; + node->logger.try_log ("Bulk push client failed"); } } } @@ -1083,15 +1083,15 @@ void nano::bootstrap_attempt::run () } } // Flushing may resolve forks which can add more pulls - BOOST_LOG (node->log) << "Flushing unchecked blocks"; + node->logger.try_log ("Flushing unchecked blocks"); lock.unlock (); node->block_processor.flush (); lock.lock (); - BOOST_LOG (node->log) << "Finished flushing unchecked blocks"; + node->logger.try_log ("Finished flushing unchecked blocks"); } if (!stopped) { - BOOST_LOG (node->log) << "Completed pulls"; + node->logger.try_log ("Completed pulls"); request_push (lock); runs_count++; // Start wallet lazy bootstrap if required @@ -1199,7 +1199,7 @@ void nano::bootstrap_attempt::populate_connections () { if (node->config.logging.bulk_pull_logging ()) { - BOOST_LOG (node->log) << boost::str (boost::format ("Stopping slow peer %1% (elapsed sec %2%s > %3%s and %4% blocks per second < %5%)") % client->endpoint.address ().to_string () % elapsed_sec % bootstrap_minimum_termination_time_sec % blocks_per_sec % bootstrap_minimum_blocks_per_sec); + 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->endpoint.address ().to_string () % elapsed_sec % bootstrap_minimum_termination_time_sec % blocks_per_sec % bootstrap_minimum_blocks_per_sec)); } client->stop (true); @@ -1221,7 +1221,7 @@ void nano::bootstrap_attempt::populate_connections () if (node->config.logging.bulk_pull_logging ()) { - BOOST_LOG (node->log) << boost::str (boost::format ("Dropping %1% bulk pull peers, target connections %2%") % drop % target); + node->logger.try_log (boost::str (boost::format ("Dropping %1% bulk pull peers, target connections %2%") % drop % target)); } for (int i = 0; i < drop; i++) @@ -1230,7 +1230,7 @@ void nano::bootstrap_attempt::populate_connections () if (node->config.logging.bulk_pull_logging ()) { - BOOST_LOG (node->log) << boost::str (boost::format ("Dropping peer with block rate %1%, block count %2% (%3%) ") % client->block_rate () % client->block_count % client->endpoint.address ().to_string ()); + 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->endpoint.address ().to_string ())); } client->stop (false); @@ -1241,7 +1241,7 @@ void nano::bootstrap_attempt::populate_connections () if (node->config.logging.bulk_pull_logging ()) { std::unique_lock lock (mutex); - BOOST_LOG (node->log) << boost::str (boost::format ("Bulk pull connections: %1%, rate: %2% blocks/sec, remaining account pulls: %3%, total blocks: %4%") % connections.load () % (int)rate_sum % pulls.size () % (int)total_blocks.load ()); + node->logger.try_log (boost::str (boost::format ("Bulk pull connections: %1%, rate: %2% blocks/sec, remaining account pulls: %3%, total blocks: %4%") % connections.load () % (int)rate_sum % pulls.size () % (int)total_blocks.load ())); } if (connections < target) @@ -1263,7 +1263,7 @@ void nano::bootstrap_attempt::populate_connections () } else if (connections == 0) { - BOOST_LOG (node->log) << boost::str (boost::format ("Bootstrap stopped because there are no peers")); + node->logger.try_log (boost::str (boost::format ("Bootstrap stopped because there are no peers"))); stopped = true; condition.notify_all (); } @@ -1365,7 +1365,7 @@ void nano::bootstrap_attempt::requeue_pull (nano::pull_info const & pull_a) { if (node->config.logging.bulk_pull_logging ()) { - BOOST_LOG (node->log) << boost::str (boost::format ("Failed to pull account %1% down to %2% after %3% attempts") % pull.account.to_account () % pull.end.to_string () % pull.attempts); + node->logger.try_log (boost::str (boost::format ("Failed to pull account %1% down to %2% after %3% attempts") % pull.account.to_account () % pull.end.to_string () % pull.attempts)); } } } @@ -1493,7 +1493,7 @@ void nano::bootstrap_attempt::lazy_run () } if (!stopped) { - BOOST_LOG (node->log) << "Completed lazy pulls"; + node->logger.try_log ("Completed lazy pulls"); std::unique_lock lazy_lock (lazy_mutex); runs_count++; // Start wallet lazy bootstrap if required @@ -1741,7 +1741,7 @@ void nano::bootstrap_attempt::wallet_run () } if (!stopped) { - BOOST_LOG (node->log) << "Completed wallet lazy pulls"; + node->logger.try_log ("Completed wallet lazy pulls"); runs_count++; // Start lazy bootstrap if some lazy keys were inserted if (!lazy_finished ()) @@ -1946,7 +1946,7 @@ void nano::bootstrap_listener::start () acceptor.bind (local, ec); if (ec) { - BOOST_LOG (node.log) << boost::str (boost::format ("Error while binding for bootstrap on port %1%: %2%") % local.port () % ec.message ()); + node.logger.try_log (boost::str (boost::format ("Error while binding for bootstrap on port %1%: %2%") % local.port () % ec.message ())); throw std::runtime_error (ec.message ()); } @@ -1986,7 +1986,7 @@ void nano::bootstrap_listener::accept_connection () } else { - BOOST_LOG (node.log) << boost::str (boost::format ("Unable to accept new TCP network sockets (have %1% concurrent connections, limit of %2%), will try to accept again in 1s") % connections.size () % node.config.bootstrap_connections_max); + node.logger.try_log (boost::str (boost::format ("Unable to accept new TCP network sockets (have %1% concurrent connections, limit of %2%), will try to accept again in 1s") % connections.size () % node.config.bootstrap_connections_max)); defer_acceptor.expires_after (std::chrono::seconds (1)); defer_acceptor.async_wait ([this](const boost::system::error_code & ec) { /* @@ -2021,7 +2021,7 @@ void nano::bootstrap_listener::accept_action (boost::system::error_code const & } else { - BOOST_LOG (node.log) << boost::str (boost::format ("Error while accepting bootstrap connections: %1%") % ec.message ()); + node.logger.try_log (boost::str (boost::format ("Error while accepting bootstrap connections: %1%") % ec.message ())); } } @@ -2051,7 +2051,7 @@ nano::bootstrap_server::~bootstrap_server () { if (node->config.logging.bulk_pull_logging ()) { - BOOST_LOG (node->log) << "Exiting bootstrap server"; + node->logger.try_log ("Exiting bootstrap server"); } std::lock_guard lock (node->bootstrap.mutex); node->bootstrap.connections.erase (this); @@ -2131,7 +2131,7 @@ void nano::bootstrap_server::receive_header_action (boost::system::error_code co { if (node->config.logging.network_logging ()) { - BOOST_LOG (node->log) << boost::str (boost::format ("Received invalid type from bootstrap connection %1%") % static_cast (header.type)); + node->logger.try_log (boost::str (boost::format ("Received invalid type from bootstrap connection %1%") % static_cast (header.type))); } break; } @@ -2142,7 +2142,7 @@ void nano::bootstrap_server::receive_header_action (boost::system::error_code co { if (node->config.logging.bulk_pull_logging ()) { - BOOST_LOG (node->log) << boost::str (boost::format ("Error while receiving type: %1%") % ec.message ()); + node->logger.try_log (boost::str (boost::format ("Error while receiving type: %1%") % ec.message ())); } } } @@ -2158,7 +2158,7 @@ void nano::bootstrap_server::receive_bulk_pull_action (boost::system::error_code { if (node->config.logging.bulk_pull_logging ()) { - BOOST_LOG (node->log) << boost::str (boost::format ("Received bulk pull for %1% down to %2%, maximum of %3%") % request->start.to_string () % request->end.to_string () % (request->count ? request->count : std::numeric_limits::infinity ())); + node->logger.try_log (boost::str (boost::format ("Received bulk pull for %1% down to %2%, maximum of %3%") % request->start.to_string () % request->end.to_string () % (request->count ? request->count : std::numeric_limits::infinity ()))); } add_request (std::unique_ptr (request.release ())); receive (); @@ -2178,7 +2178,7 @@ void nano::bootstrap_server::receive_bulk_pull_account_action (boost::system::er { if (node->config.logging.bulk_pull_logging ()) { - BOOST_LOG (node->log) << boost::str (boost::format ("Received bulk pull account for %1% with a minimum amount of %2%") % request->account.to_account () % nano::amount (request->minimum_amount).format_balance (nano::Mxrb_ratio, 10, true)); + node->logger.try_log (boost::str (boost::format ("Received bulk pull account for %1% with a minimum amount of %2%") % request->account.to_account () % nano::amount (request->minimum_amount).format_balance (nano::Mxrb_ratio, 10, true))); } add_request (std::unique_ptr (request.release ())); receive (); @@ -2203,7 +2203,7 @@ void nano::bootstrap_server::receive_keepalive_action (boost::system::error_code { if (node->config.logging.network_keepalive_logging ()) { - BOOST_LOG (node->log) << boost::str (boost::format ("Error receiving keepalive from: %1%") % ec.message ()); + node->logger.try_log (boost::str (boost::format ("Error receiving keepalive from: %1%") % ec.message ())); } } } @@ -2219,7 +2219,7 @@ void nano::bootstrap_server::receive_frontier_req_action (boost::system::error_c { if (node->config.logging.bulk_pull_logging ()) { - BOOST_LOG (node->log) << boost::str (boost::format ("Received frontier request for %1% with age %2%") % request->start.to_string () % request->age); + node->logger.try_log (boost::str (boost::format ("Received frontier request for %1% with age %2%") % request->start.to_string () % request->age)); } add_request (std::unique_ptr (request.release ())); receive (); @@ -2229,7 +2229,7 @@ void nano::bootstrap_server::receive_frontier_req_action (boost::system::error_c { if (node->config.logging.network_logging ()) { - BOOST_LOG (node->log) << boost::str (boost::format ("Error sending receiving frontier request: %1%") % ec.message ()); + node->logger.try_log (boost::str (boost::format ("Error sending receiving frontier request: %1%") % ec.message ())); } } } @@ -2269,7 +2269,7 @@ public: { if (connection->node->config.logging.network_keepalive_logging ()) { - BOOST_LOG (connection->node->log) << boost::str (boost::format ("Received keepalive message from %1%") % connection->socket->remote_endpoint ()); + connection->node->logger.try_log (boost::str (boost::format ("Received keepalive message from %1%") % connection->socket->remote_endpoint ())); } connection->node->stats.inc (nano::stat::type::message, nano::stat::detail::keepalive, nano::stat::dir::in); connection->node->network.merge_peers (message_a.peers); @@ -2278,14 +2278,14 @@ public: auto bytes = message.to_bytes (); if (connection->node->config.logging.network_keepalive_logging ()) { - BOOST_LOG (connection->node->log) << boost::str (boost::format ("Keepalive req sent to %1%") % connection->socket->remote_endpoint ()); + connection->node->logger.try_log (boost::str (boost::format ("Keepalive req sent to %1%") % connection->socket->remote_endpoint ())); } connection->socket->async_write (bytes, [connection = connection](boost::system::error_code const & ec, size_t size_a) { if (ec) { if (connection->node->config.logging.network_keepalive_logging ()) { - BOOST_LOG (connection->node->log) << boost::str (boost::format ("Error sending keepalive to %1%: %2%") % connection->socket->remote_endpoint () % ec.message ()); + connection->node->logger.try_log (boost::str (boost::format ("Error sending keepalive to %1%: %2%") % connection->socket->remote_endpoint () % ec.message ())); } } else @@ -2366,7 +2366,7 @@ void nano::bulk_pull_server::set_current_end () { if (connection->node->config.logging.bulk_pull_logging ()) { - BOOST_LOG (connection->node->log) << boost::str (boost::format ("Bulk pull end block doesn't exist: %1%, sending everything") % request->end.to_string ()); + connection->node->logger.try_log (boost::str (boost::format ("Bulk pull end block doesn't exist: %1%, sending everything") % request->end.to_string ())); } request->end.clear (); } @@ -2375,7 +2375,7 @@ void nano::bulk_pull_server::set_current_end () { if (connection->node->config.logging.bulk_pull_logging ()) { - BOOST_LOG (connection->node->log) << boost::str (boost::format ("Bulk pull request for block hash: %1%") % request->start.to_string ()); + connection->node->logger.try_log (boost::str (boost::format ("Bulk pull request for block hash: %1%") % request->start.to_string ())); } current = request->start; @@ -2389,7 +2389,7 @@ void nano::bulk_pull_server::set_current_end () { if (connection->node->config.logging.bulk_pull_logging ()) { - BOOST_LOG (connection->node->log) << boost::str (boost::format ("Request for unknown account: %1%") % request->start.to_account ()); + connection->node->logger.try_log (boost::str (boost::format ("Request for unknown account: %1%") % request->start.to_account ())); } current = request->end; } @@ -2403,7 +2403,7 @@ void nano::bulk_pull_server::set_current_end () { if (connection->node->config.logging.bulk_pull_logging ()) { - BOOST_LOG (connection->node->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 ()); + connection->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 ())); } current = request->end; } @@ -2435,7 +2435,7 @@ void nano::bulk_pull_server::send_next () auto this_l (shared_from_this ()); if (connection->node->config.logging.bulk_pull_logging ()) { - BOOST_LOG (connection->node->log) << boost::str (boost::format ("Sending block: %1%") % block->hash ().to_string ()); + connection->node->logger.try_log (boost::str (boost::format ("Sending block: %1%") % block->hash ().to_string ())); } connection->socket->async_write (send_buffer, [this_l](boost::system::error_code const & ec, size_t size_a) { this_l->sent_action (ec, size_a); @@ -2529,7 +2529,7 @@ void nano::bulk_pull_server::sent_action (boost::system::error_code const & ec, { if (connection->node->config.logging.bulk_pull_logging ()) { - BOOST_LOG (connection->node->log) << boost::str (boost::format ("Unable to bulk send block: %1%") % ec.message ()); + connection->node->logger.try_log (boost::str (boost::format ("Unable to bulk send block: %1%") % ec.message ())); } } } @@ -2541,7 +2541,7 @@ void nano::bulk_pull_server::send_finished () auto this_l (shared_from_this ()); if (connection->node->config.logging.bulk_pull_logging ()) { - BOOST_LOG (connection->node->log) << "Bulk sending finished"; + connection->node->logger.try_log ("Bulk sending finished"); } connection->socket->async_write (send_buffer, [this_l](boost::system::error_code const & ec, size_t size_a) { this_l->no_block_sent (ec, size_a); @@ -2559,7 +2559,7 @@ void nano::bulk_pull_server::no_block_sent (boost::system::error_code const & ec { if (connection->node->config.logging.bulk_pull_logging ()) { - BOOST_LOG (connection->node->log) << "Unable to send not-a-block"; + connection->node->logger.try_log ("Unable to send not-a-block"); } } } @@ -2605,7 +2605,7 @@ void nano::bulk_pull_account_server::set_params () { if (connection->node->config.logging.bulk_pull_logging ()) { - BOOST_LOG (connection->node->log) << boost::str (boost::format ("Invalid bulk_pull_account flags supplied %1%") % static_cast (request->flags)); + connection->node->logger.try_log (boost::str (boost::format ("Invalid bulk_pull_account flags supplied %1%") % static_cast (request->flags))); } invalid_request = true; @@ -2692,7 +2692,7 @@ void nano::bulk_pull_account_server::send_next_block () if (connection->node->config.logging.bulk_pull_logging ()) { - BOOST_LOG (connection->node->log) << boost::str (boost::format ("Sending address: %1%") % block_info->source.to_string ()); + connection->node->logger.try_log (boost::str (boost::format ("Sending address: %1%") % block_info->source.to_string ())); } write (output_stream, block_info->source.bytes); @@ -2703,7 +2703,7 @@ void nano::bulk_pull_account_server::send_next_block () if (connection->node->config.logging.bulk_pull_logging ()) { - BOOST_LOG (connection->node->log) << boost::str (boost::format ("Sending block: %1%") % block_info_key->hash.to_string ()); + connection->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); @@ -2730,7 +2730,7 @@ void nano::bulk_pull_account_server::send_next_block () */ if (connection->node->config.logging.bulk_pull_logging ()) { - BOOST_LOG (connection->node->log) << boost::str (boost::format ("Done sending blocks")); + connection->node->logger.try_log (boost::str (boost::format ("Done sending blocks"))); } send_finished (); @@ -2826,7 +2826,7 @@ void nano::bulk_pull_account_server::sent_action (boost::system::error_code cons { if (connection->node->config.logging.bulk_pull_logging ()) { - BOOST_LOG (connection->node->log) << boost::str (boost::format ("Unable to bulk send block: %1%") % ec.message ()); + connection->node->logger.try_log (boost::str (boost::format ("Unable to bulk send block: %1%") % ec.message ())); } } } @@ -2864,7 +2864,7 @@ void nano::bulk_pull_account_server::send_finished () if (connection->node->config.logging.bulk_pull_logging ()) { - BOOST_LOG (connection->node->log) << "Bulk sending for an account finished"; + connection->node->logger.try_log ("Bulk sending for an account finished"); } connection->socket->async_write (send_buffer, [this_l](boost::system::error_code const & ec, size_t size_a) { @@ -2898,7 +2898,7 @@ void nano::bulk_pull_account_server::complete (boost::system::error_code const & { if (connection->node->config.logging.bulk_pull_logging ()) { - BOOST_LOG (connection->node->log) << "Unable to pending-as-zero"; + connection->node->logger.try_log ("Unable to pending-as-zero"); } } } @@ -2928,7 +2928,7 @@ void nano::bulk_push_server::receive () { if (connection->node->config.logging.bulk_pull_logging ()) { - BOOST_LOG (connection->node->log) << "Aborting bulk_push because a bootstrap attempt is in progress"; + connection->node->logger.try_log ("Aborting bulk_push because a bootstrap attempt is in progress"); } } else @@ -2943,7 +2943,7 @@ void nano::bulk_push_server::receive () { if (this_l->connection->node->config.logging.bulk_pull_logging ()) { - BOOST_LOG (this_l->connection->node->log) << boost::str (boost::format ("Error receiving block type: %1%") % ec.message ()); + this_l->connection->node->logger.try_log (boost::str (boost::format ("Error receiving block type: %1%") % ec.message ())); } } }); @@ -3005,7 +3005,7 @@ void nano::bulk_push_server::received_type () { if (connection->node->config.logging.network_packet_logging ()) { - BOOST_LOG (connection->node->log) << "Unknown type received as block type"; + connection->node->logger.try_log ("Unknown type received as block type"); } break; } @@ -3030,7 +3030,7 @@ void nano::bulk_push_server::received_block (boost::system::error_code const & e { if (connection->node->config.logging.bulk_pull_logging ()) { - BOOST_LOG (connection->node->log) << "Error deserializing block received from pull request"; + connection->node->logger.try_log ("Error deserializing block received from pull request"); } } } @@ -3060,7 +3060,7 @@ void nano::frontier_req_server::send_next () auto this_l (shared_from_this ()); if (connection->node->config.logging.bulk_pull_logging ()) { - BOOST_LOG (connection->node->log) << boost::str (boost::format ("Sending frontier for %1% %2%") % current.to_account () % frontier.to_string ()); + connection->node->logger.try_log (boost::str (boost::format ("Sending frontier for %1% %2%") % current.to_account () % frontier.to_string ())); } next (); connection->socket->async_write (send_buffer, [this_l](boost::system::error_code const & ec, size_t size_a) { @@ -3085,7 +3085,7 @@ void nano::frontier_req_server::send_finished () auto this_l (shared_from_this ()); if (connection->node->config.logging.network_logging ()) { - BOOST_LOG (connection->node->log) << "Frontier sending finished"; + connection->node->logger.try_log ("Frontier sending finished"); } connection->socket->async_write (send_buffer, [this_l](boost::system::error_code const & ec, size_t size_a) { this_l->no_block_sent (ec, size_a); @@ -3102,7 +3102,7 @@ void nano::frontier_req_server::no_block_sent (boost::system::error_code const & { if (connection->node->config.logging.network_logging ()) { - BOOST_LOG (connection->node->log) << boost::str (boost::format ("Error sending frontier finish: %1%") % ec.message ()); + connection->node->logger.try_log (boost::str (boost::format ("Error sending frontier finish: %1%") % ec.message ())); } } } @@ -3118,7 +3118,7 @@ void nano::frontier_req_server::sent_action (boost::system::error_code const & e { if (connection->node->config.logging.network_logging ()) { - BOOST_LOG (connection->node->log) << boost::str (boost::format ("Error sending frontier pair: %1%") % ec.message ()); + connection->node->logger.try_log (boost::str (boost::format ("Error sending frontier pair: %1%") % ec.message ())); } } } diff --git a/nano/node/cli.cpp b/nano/node/cli.cpp index b250e459..e662558c 100644 --- a/nano/node/cli.cpp +++ b/nano/node/cli.cpp @@ -338,7 +338,7 @@ std::error_code nano::handle_node_options (boost::program_options::variables_map environment.dump (std::cout); std::stringstream stream; environment.dump (stream); - BOOST_LOG (node.logging.log) << stream.str (); + node.logging.logger.always_log (stream.str ()); } else { diff --git a/nano/node/ipc.cpp b/nano/node/ipc.cpp index 6dd40d66..2043ea0e 100644 --- a/nano/node/ipc.cpp +++ b/nano/node/ipc.cpp @@ -100,7 +100,7 @@ public: { if (node.config.logging.log_ipc ()) { - BOOST_LOG (node.log) << "IPC: created session with id: " << session_id; + node.logger.always_log ("IPC: created session with id: ", session_id); } } @@ -136,7 +136,7 @@ public: { if (this_l->node.config.logging.log_ipc ()) { - BOOST_LOG (this_l->node.log) << boost::str (boost::format ("IPC: error reading %1% ") % ec.message ()); + this_l->node.logger.always_log (boost::str (boost::format ("IPC: error reading %1% ") % ec.message ())); } } else if (bytes_transferred_a > 0) @@ -176,13 +176,13 @@ public: } else if (this_l->node.config.logging.log_ipc ()) { - BOOST_LOG (this_l->node.log) << "IPC: Write failed: " << error_a.message (); + this_l->node.logger.always_log ("IPC: Write failed: ", error_a.message ()); } }); if (this_l->node.config.logging.log_ipc ()) { - BOOST_LOG (this_l->node.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.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 ())); } }); @@ -206,7 +206,7 @@ public: { if (this_l->node.config.logging.log_ipc ()) { - BOOST_LOG (this_l->node.log) << "IPC: Invalid preamble"; + this_l->node.logger.always_log ("IPC: Invalid preamble"); } } else if (this_l->buffer[preamble_offset::encoding] == static_cast (nano::ipc::payload_encoding::json_legacy)) @@ -223,7 +223,7 @@ public: } else if (this_l->node.config.logging.log_ipc ()) { - BOOST_LOG (this_l->node.log) << "IPC: Unsupported payload encoding"; + this_l->node.logger.always_log ("IPC: Unsupported payload encoding"); } }); } @@ -313,7 +313,7 @@ public: } else { - BOOST_LOG (server.node.log) << "IPC: acceptor error: " << ec.message (); + server.node.logger.always_log ("IPC: acceptor error: ", ec.message ()); } if (acceptor->is_open () && ec != boost::asio::error::operation_aborted) @@ -322,7 +322,7 @@ public: } else { - BOOST_LOG (server.node.log) << "IPC: shutting down"; + server.node.logger.always_log ("IPC: shutting down"); } }); } @@ -378,7 +378,7 @@ node (node_a), rpc (rpc_a) 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 - BOOST_LOG (node.log) << "IPC: Domain sockets are not supported on this platform"; + node.logger.always_log ("IPC: Domain sockets are not supported on this platform"); #endif } @@ -388,17 +388,17 @@ node (node_a), rpc (rpc_a) 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)); } - BOOST_LOG (node.log) << "IPC: server started"; + node.logger.always_log ("IPC: server started"); } catch (std::runtime_error const & ex) { - BOOST_LOG (node.log) << "IPC: " << ex.what (); + node.logger.always_log ("IPC: ", ex.what ()); } } nano::ipc::ipc_server::~ipc_server () { - BOOST_LOG (node.log) << "IPC: server stopped"; + node.logger.always_log ("IPC: server stopped"); } void nano::ipc::ipc_server::stop () diff --git a/nano/node/lmdb.cpp b/nano/node/lmdb.cpp index 7fd6e364..898da8e9 100644 --- a/nano/node/lmdb.cpp +++ b/nano/node/lmdb.cpp @@ -1234,7 +1234,7 @@ void nano::mdb_store::upgrade_v12_to_v13 (size_t const batch_size) { if (cost >= batch_size) { - BOOST_LOG (logging.log) << boost::str (boost::format ("Upgrading sideband information for account %1%... height %2%") % first.to_account ().substr (0, 24) % std::to_string (height)); + logging.logger.always_log (boost::str (boost::format ("Upgrading sideband information for account %1%... height %2%") % first.to_account ().substr (0, 24) % std::to_string (height))); auto tx (boost::polymorphic_downcast (transaction.impl.get ())); auto status0 (mdb_txn_commit (*tx)); release_assert (status0 == MDB_SUCCESS); @@ -1267,7 +1267,7 @@ void nano::mdb_store::upgrade_v12_to_v13 (size_t const batch_size) } if (account == not_an_account) { - BOOST_LOG (logging.log) << boost::str (boost::format ("Completed sideband upgrade")); + logging.logger.always_log (boost::str (boost::format ("Completed sideband upgrade"))); version_put (transaction, 13); } } diff --git a/nano/node/logging.cpp b/nano/node/logging.cpp index fd8e2a89..1f873600 100644 --- a/nano/node/logging.cpp +++ b/nano/node/logging.cpp @@ -5,31 +5,6 @@ #include #include -nano::logging::logging () : -ledger_logging_value (false), -ledger_duplicate_logging_value (false), -vote_logging_value (false), -network_logging_value (true), -network_message_logging_value (false), -network_publish_logging_value (false), -network_packet_logging_value (false), -network_keepalive_logging_value (false), -network_node_id_handshake_logging_value (false), -node_lifetime_tracing_value (false), -insufficient_work_logging_value (true), -log_rpc_value (true), -log_ipc_value (true), -bulk_pull_logging_value (false), -work_generation_time_value (true), -upnp_details_logging_value (false), -timing_logging_value (false), -log_to_cerr_value (false), -flush (true), -max_size (128 * 1024 * 1024), -rotation_size (4 * 1024 * 1024) -{ -} - void nano::logging::init (boost::filesystem::path const & application_path_a) { static std::atomic_flag logging_already_added = ATOMIC_FLAG_INIT; @@ -40,7 +15,8 @@ void nano::logging::init (boost::filesystem::path const & application_path_a) { boost::log::add_console_log (std::cerr, boost::log::keywords::format = "[%TimeStamp%]: %Message%"); } - boost::log::add_file_log (boost::log::keywords::target = application_path_a / "log", boost::log::keywords::file_name = application_path_a / "log" / "log_%Y-%m-%d_%H-%M-%S.%N.log", boost::log::keywords::rotation_size = rotation_size, boost::log::keywords::auto_flush = flush, boost::log::keywords::scan_method = boost::log::sinks::file::scan_method::scan_matching, boost::log::keywords::max_size = max_size, boost::log::keywords::format = "[%TimeStamp%]: %Message%"); + auto path = application_path_a / "log"; + boost::log::add_file_log (boost::log::keywords::target = path, boost::log::keywords::file_name = path / "log_%Y-%m-%d_%H-%M-%S.%N.log", boost::log::keywords::rotation_size = rotation_size, boost::log::keywords::auto_flush = flush, boost::log::keywords::scan_method = boost::log::sinks::file::scan_method::scan_matching, boost::log::keywords::max_size = max_size, boost::log::keywords::format = "[%TimeStamp%]: %Message%"); } } @@ -68,6 +44,7 @@ nano::error nano::logging::serialize_json (nano::jsonconfig & json) const json.put ("max_size", max_size); json.put ("rotation_size", rotation_size); json.put ("flush", flush); + json.put ("min_time_between_output", min_time_between_log_output.count ()); return json.get_error (); } @@ -99,6 +76,10 @@ bool nano::logging::upgrade_json (unsigned version_a, nano::jsonconfig & json) json.put ("log_ipc", true); upgraded_l = true; case 6: + json.put ("min_time_between_output", min_time_between_log_output.count ()); + upgraded_l = true; + break; + case 7: break; default: throw std::runtime_error ("Unknown logging_config version"); @@ -150,7 +131,9 @@ nano::error nano::logging::deserialize_json (bool & upgraded_a, nano::jsonconfig json.get ("flush", flush); json.get ("max_size", max_size); json.get ("rotation_size", rotation_size); - + uintmax_t min_time_between_log_output_raw; + json.get ("min_time_between_output", min_time_between_log_output_raw); + min_time_between_log_output = std::chrono::milliseconds (min_time_between_log_output_raw); return json.get_error (); } diff --git a/nano/node/logging.hpp b/nano/node/logging.hpp index 49c5acfa..fb2db289 100644 --- a/nano/node/logging.hpp +++ b/nano/node/logging.hpp @@ -9,12 +9,85 @@ #define FATAL_LOG_PREFIX "FATAL ERROR: " +using namespace std::chrono; + namespace nano { +// A wrapper around a boost logger object to allow +// minimum time spaced output to prevent logging happening +// too quickly. +class logger_mt +{ +private: + void add_to_stream (boost::log::record_ostream & stream) + { + } + + template + void add_to_stream (boost::log::record_ostream & stream, const LogItem & first_log_item, LogItems &&... remainder_log_items) + { + stream << first_log_item; + add_to_stream (stream, remainder_log_items...); + } + + template + void output (LogItems &&... log_items) + { + boost::log::record rec = boost_logger_mt.open_record (); + if (rec) + { + boost::log::record_ostream strm (rec); + add_to_stream (strm, std::forward (log_items)...); + strm.flush (); + boost_logger_mt.push_record (std::move (rec)); + } + } + +public: + /** + * @param min_log_delta_a The minimum time between successive output + */ + explicit logger_mt (std::chrono::milliseconds const & min_log_delta_a) : + min_log_delta (min_log_delta_a) + { + } + + /* + * @param log_items A collection of objects with overloaded operator<< to be output to the log file + */ + template + void always_log (LogItems &&... log_items) + { + output (std::forward (log_items)...); + } + + /* + * @param log_items Output to the log file if the last write was over min_log_delta time ago. + * @return true if the log was successful + */ + template + bool try_log (LogItems &&... log_items) + { + auto error (true); + auto time_now = steady_clock::now (); + if (((time_now - last_log_time) > min_log_delta) || last_log_time == steady_clock::time_point{}) + { + output (std::forward (log_items)...); + last_log_time = time_now; + error = false; + } + return error; + } + +private: + milliseconds const & min_log_delta; + steady_clock::time_point last_log_time; + boost::log::sources::logger_mt boost_logger_mt; +}; + class logging { public: - logging (); nano::error serialize_json (nano::jsonconfig &) const; nano::error deserialize_json (bool &, nano::jsonconfig &); bool upgrade_json (unsigned, nano::jsonconfig &); @@ -39,31 +112,32 @@ public: bool log_to_cerr () const; void init (boost::filesystem::path const &); - bool ledger_logging_value; - bool ledger_duplicate_logging_value; - bool vote_logging_value; - bool network_logging_value; - bool network_message_logging_value; - bool network_publish_logging_value; - bool network_packet_logging_value; - bool network_keepalive_logging_value; - bool network_node_id_handshake_logging_value; - bool node_lifetime_tracing_value; - bool insufficient_work_logging_value; - bool log_rpc_value; - bool log_ipc_value; - bool bulk_pull_logging_value; - bool work_generation_time_value; - bool upnp_details_logging_value; - bool timing_logging_value; - bool log_to_cerr_value; - bool flush; - uintmax_t max_size; - uintmax_t rotation_size; - boost::log::sources::logger_mt log; + bool ledger_logging_value{ false }; + bool ledger_duplicate_logging_value{ false }; + bool vote_logging_value{ false }; + bool network_logging_value{ true }; + bool network_message_logging_value{ false }; + bool network_publish_logging_value{ false }; + bool network_packet_logging_value{ false }; + bool network_keepalive_logging_value{ false }; + bool network_node_id_handshake_logging_value{ false }; + bool node_lifetime_tracing_value{ false }; + bool insufficient_work_logging_value{ true }; + bool log_rpc_value{ true }; + bool log_ipc_value{ true }; + bool bulk_pull_logging_value{ false }; + bool work_generation_time_value{ true }; + bool upnp_details_logging_value{ false }; + bool timing_logging_value{ false }; + bool log_to_cerr_value{ false }; + bool flush{ true }; + uintmax_t max_size{ 128 * 1024 * 1024 }; + uintmax_t rotation_size{ 4 * 1024 * 1024 }; + milliseconds min_time_between_log_output{ 5 }; + nano::logger_mt logger{ min_time_between_log_output }; int json_version () const { - return 6; + return 7; } }; } diff --git a/nano/node/node.cpp b/nano/node/node.cpp index 09680f72..f220c3dd 100644 --- a/nano/node/node.cpp +++ b/nano/node/node.cpp @@ -59,27 +59,27 @@ on (true) } catch (boost::system::error_code & ec) { - BOOST_LOG (this->node.log) << FATAL_LOG_PREFIX << ec.message (); + this->node.logger.try_log (FATAL_LOG_PREFIX, ec.message ()); release_assert (false); } catch (std::error_code & ec) { - BOOST_LOG (this->node.log) << FATAL_LOG_PREFIX << ec.message (); + this->node.logger.try_log (FATAL_LOG_PREFIX, ec.message ()); release_assert (false); } catch (std::runtime_error & err) { - BOOST_LOG (this->node.log) << FATAL_LOG_PREFIX << err.what (); + this->node.logger.try_log (FATAL_LOG_PREFIX, err.what ()); release_assert (false); } catch (...) { - BOOST_LOG (this->node.log) << FATAL_LOG_PREFIX << "Unknown exception"; + this->node.logger.try_log (FATAL_LOG_PREFIX, "Unknown exception"); release_assert (false); } if (this->node.config.logging.network_packet_logging ()) { - BOOST_LOG (this->node.log) << "Exiting packet processing thread"; + this->node.logger.try_log ("Exiting packet processing thread"); } })); } @@ -105,7 +105,7 @@ void nano::network::receive () { if (node.config.logging.network_packet_logging ()) { - BOOST_LOG (node.log) << "Receiving packet"; + node.logger.try_log ("Receiving packet"); } std::unique_lock lock (socket_mutex); auto data (buffer_container.allocate ()); @@ -123,7 +123,7 @@ void nano::network::receive () { if (this->node.config.logging.network_logging ()) { - BOOST_LOG (this->node.log) << boost::str (boost::format ("UDP Receive error: %1%") % error.message ()); + this->node.logger.try_log (boost::str (boost::format ("UDP Receive error: %1%") % error.message ())); } } if (this->on) @@ -170,7 +170,7 @@ void nano::network::send_keepalive (nano::endpoint const & endpoint_a) auto bytes = message.to_bytes (); if (node.config.logging.network_keepalive_logging ()) { - BOOST_LOG (node.log) << boost::str (boost::format ("Keepalive req sent to %1%") % endpoint_a); + node.logger.try_log (boost::str (boost::format ("Keepalive req sent to %1%") % endpoint_a)); } std::weak_ptr node_w (node.shared ()); send_buffer (bytes->data (), bytes->size (), endpoint_a, [bytes, node_w, endpoint_a](boost::system::error_code const & ec, size_t) { @@ -178,7 +178,7 @@ void nano::network::send_keepalive (nano::endpoint const & endpoint_a) { if (ec && node_l->config.logging.network_keepalive_logging ()) { - BOOST_LOG (node_l->log) << boost::str (boost::format ("Error sending keepalive to %1%: %2%") % endpoint_a % ec.message ()); + node_l->logger.try_log (boost::str (boost::format ("Error sending keepalive to %1%: %2%") % endpoint_a % ec.message ())); } else { @@ -202,7 +202,7 @@ void nano::node::keepalive (std::string const & address_a, uint16_t port_a, bool } else { - BOOST_LOG (node_l->log) << boost::str (boost::format ("Error resolving address: %1%:%2%: %3%") % address_a % port_a % ec.message ()); + node_l->logger.try_log (boost::str (boost::format ("Error resolving address: %1%:%2%: %3%") % address_a % port_a % ec.message ())); } }); } @@ -220,7 +220,7 @@ void nano::network::send_node_id_handshake (nano::endpoint const & endpoint_a, b auto bytes = message.to_bytes (); if (node.config.logging.network_node_id_handshake_logging ()) { - BOOST_LOG (node.log) << boost::str (boost::format ("Node ID handshake sent with node ID %1% to %2%: query %3%, respond_to %4% (signature %5%)") % node.node_id.pub.to_account () % endpoint_a % (query ? query->to_string () : std::string ("[none]")) % (respond_to ? respond_to->to_string () : std::string ("[none]")) % (response ? response->second.to_string () : std::string ("[none]"))); + node.logger.try_log (boost::str (boost::format ("Node ID handshake sent with node ID %1% to %2%: query %3%, respond_to %4% (signature %5%)") % node.node_id.pub.to_account () % endpoint_a % (query ? query->to_string () : std::string ("[none]")) % (respond_to ? respond_to->to_string () : std::string ("[none]")) % (response ? response->second.to_string () : std::string ("[none]")))); } node.stats.inc (nano::stat::type::message, nano::stat::detail::node_id_handshake, nano::stat::dir::out); std::weak_ptr node_w (node.shared ()); @@ -229,7 +229,7 @@ void nano::network::send_node_id_handshake (nano::endpoint const & endpoint_a, b { if (ec && node_l->config.logging.network_node_id_handshake_logging ()) { - BOOST_LOG (node_l->log) << boost::str (boost::format ("Error sending node ID handshake to %1% %2%") % endpoint_a % ec.message ()); + node_l->logger.try_log (boost::str (boost::format ("Error sending node ID handshake to %1% %2%") % endpoint_a % ec.message ())); } } }); @@ -239,7 +239,7 @@ void nano::network::republish (nano::block_hash const & hash_a, std::shared_ptr< { if (node.config.logging.network_publish_logging ()) { - BOOST_LOG (node.log) << boost::str (boost::format ("Publishing %1% to %2%") % hash_a.to_string () % endpoint_a); + node.logger.try_log (boost::str (boost::format ("Publishing %1% to %2%") % hash_a.to_string () % endpoint_a)); } std::weak_ptr node_w (node.shared ()); send_buffer (buffer_a->data (), buffer_a->size (), endpoint_a, [buffer_a, node_w, endpoint_a](boost::system::error_code const & ec, size_t size) { @@ -247,7 +247,7 @@ void nano::network::republish (nano::block_hash const & hash_a, std::shared_ptr< { if (ec && node_l->config.logging.network_logging ()) { - BOOST_LOG (node_l->log) << boost::str (boost::format ("Error sending publish to %1%: %2%") % endpoint_a % ec.message ()); + node_l->logger.try_log (boost::str (boost::format ("Error sending publish to %1%: %2%") % endpoint_a % ec.message ())); } else { @@ -363,7 +363,7 @@ void nano::network::republish_block (std::shared_ptr block) } if (node.config.logging.network_logging ()) { - BOOST_LOG (node.log) << boost::str (boost::format ("Block %1% was republished to peers") % hash.to_string ()); + node.logger.try_log (boost::str (boost::format ("Block %1% was republished to peers") % hash.to_string ())); } } @@ -379,7 +379,7 @@ void nano::network::republish_block (std::shared_ptr block, nano::e republish (hash, std::make_shared> (bytes), peer_a); if (node.config.logging.network_logging ()) { - BOOST_LOG (node.log) << boost::str (boost::format ("Block %1% was republished to peer") % hash.to_string ()); + node.logger.try_log (boost::str (boost::format ("Block %1% was republished to peers") % hash.to_string ())); } } @@ -449,7 +449,7 @@ void nano::network::broadcast_confirm_req_base (std::shared_ptr blo const size_t max_reps = 10; if (!resumption && node.config.logging.network_logging ()) { - BOOST_LOG (node.log) << boost::str (boost::format ("Broadcasting confirm req for block %1% to %2% representatives") % block_a->hash ().to_string () % endpoints_a->size ()); + 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) @@ -477,7 +477,7 @@ void nano::network::broadcast_confirm_req_batch (std::unordered_map node_w (node.shared ()); node.stats.inc (nano::stat::type::message, nano::stat::detail::confirm_req, nano::stat::dir::out); @@ -549,7 +549,7 @@ void nano::network::send_confirm_req (nano::endpoint const & endpoint_a, std::sh { if (ec && node_l->config.logging.network_logging ()) { - BOOST_LOG (node_l->log) << boost::str (boost::format ("Error sending confirm request: %1%") % ec.message ()); + node_l->logger.try_log (boost::str (boost::format ("Error sending confirm request: %1%") % ec.message ())); } } }); @@ -561,7 +561,7 @@ void nano::network::send_confirm_req_hashes (nano::endpoint const & endpoint_a, auto buffer_l (message.to_bytes ()); if (node.config.logging.network_message_logging ()) { - BOOST_LOG (node.log) << boost::str (boost::format ("Sending confirm req hashes to %1%") % endpoint_a); + node.logger.try_log (boost::str (boost::format ("Sending confirm req hashes to %1%") % endpoint_a)); } std::weak_ptr node_w (node.shared ()); node.stats.inc (nano::stat::type::message, nano::stat::detail::confirm_req, nano::stat::dir::out); @@ -570,7 +570,7 @@ void nano::network::send_confirm_req_hashes (nano::endpoint const & endpoint_a, { if (ec && node_l->config.logging.network_logging ()) { - BOOST_LOG (node_l->log) << boost::str (boost::format ("Error sending confirm request: %1%") % ec.message ()); + node_l->logger.try_log (boost::str (boost::format ("Error sending confirm request: %1%") % ec.message ())); } } }); @@ -619,7 +619,7 @@ public: { if (node.config.logging.network_keepalive_logging ()) { - BOOST_LOG (node.log) << boost::str (boost::format ("Received keepalive message from %1%") % sender); + node.logger.try_log (boost::str (boost::format ("Received keepalive message from %1%") % sender)); } node.stats.inc (nano::stat::type::message, nano::stat::detail::keepalive, nano::stat::dir::in); if (node.peers.contacted (sender, message_a.header.version_using)) @@ -637,7 +637,7 @@ public: { if (node.config.logging.network_message_logging ()) { - BOOST_LOG (node.log) << boost::str (boost::format ("Publish message from %1% for %2%") % sender % message_a.block->hash ().to_string ()); + node.logger.try_log (boost::str (boost::format ("Publish message from %1% for %2%") % sender % message_a.block->hash ().to_string ())); } node.stats.inc (nano::stat::type::message, nano::stat::detail::publish, nano::stat::dir::in); node.peers.contacted (sender, message_a.header.version_using); @@ -653,11 +653,11 @@ public: { if (!message_a.roots_hashes.empty ()) { - BOOST_LOG (node.log) << boost::str (boost::format ("Confirm_req message from %1% for hashes:roots %2%") % sender % message_a.roots_string ()); + node.logger.try_log (boost::str (boost::format ("Confirm_req message from %1% for hashes:roots %2%") % sender % message_a.roots_string ())); } else { - BOOST_LOG (node.log) << boost::str (boost::format ("Confirm_req message from %1% for %2%") % sender % message_a.block->hash ().to_string ()); + node.logger.try_log (boost::str (boost::format ("Confirm_req message from %1% for %2%") % sender % message_a.block->hash ().to_string ())); } } node.stats.inc (nano::stat::type::message, nano::stat::detail::confirm_req, nano::stat::dir::in); @@ -725,7 +725,7 @@ public: { if (node.config.logging.network_message_logging ()) { - BOOST_LOG (node.log) << boost::str (boost::format ("Received confirm_ack message from %1% for %2%sequence %3%") % sender % message_a.vote->hashes_string () % std::to_string (message_a.vote->sequence)); + node.logger.try_log (boost::str (boost::format ("Received confirm_ack message from %1% for %2%sequence %3%") % sender % message_a.vote->hashes_string () % std::to_string (message_a.vote->sequence))); } node.stats.inc (nano::stat::type::message, nano::stat::detail::confirm_ack, nano::stat::dir::in); node.peers.contacted (sender, message_a.header.version_using); @@ -763,7 +763,7 @@ public: { if (node.config.logging.network_node_id_handshake_logging ()) { - BOOST_LOG (node.log) << boost::str (boost::format ("Received node_id_handshake message from %1% with query %2% and response account %3%") % sender % (message_a.query ? message_a.query->to_string () : std::string ("[none]")) % (message_a.response ? message_a.response->first.to_account () : std::string ("[none]"))); + node.logger.try_log (boost::str (boost::format ("Received node_id_handshake message from %1% with query %2% and response account %3%") % sender % (message_a.query ? message_a.query->to_string () : std::string ("[none]")) % (message_a.response ? message_a.response->first.to_account () : std::string ("[none]")))); } auto endpoint_l (nano::map_endpoint_to_v6 (sender)); boost::optional out_query; @@ -785,7 +785,7 @@ public: } else if (node.config.logging.network_node_id_handshake_logging ()) { - BOOST_LOG (node.log) << boost::str (boost::format ("Failed to validate syn cookie signature %1% by %2%") % message_a.response->second.to_string () % message_a.response->first.to_account ()); + node.logger.try_log (boost::str (boost::format ("Failed to validate syn cookie signature %1% by %2%") % message_a.response->second.to_string () % message_a.response->first.to_account ())); } } if (!validated_response && !node.peers.known_peer (endpoint_l)) @@ -870,7 +870,7 @@ void nano::network::receive_action (nano::udp_data * data_a, nano::endpoint cons if (node.config.logging.network_logging () && parser.status != nano::message_parser::parse_status::outdated_version) { - BOOST_LOG (node.log) << "Could not parse message. Error: " << parser.status_string (); + node.logger.try_log ("Could not parse message. Error: ", parser.status_string ()); } } else @@ -882,7 +882,7 @@ void nano::network::receive_action (nano::udp_data * data_a, nano::endpoint cons { if (node.config.logging.network_logging ()) { - BOOST_LOG (node.log) << boost::str (boost::format ("Reserved sender %1%") % data_a->endpoint.address ().to_string ()); + node.logger.try_log (boost::str (boost::format ("Reserved sender %1%") % data_a->endpoint.address ().to_string ())); } node.stats.inc_detail_only (nano::stat::type::error, nano::stat::detail::bad_sender); @@ -1080,7 +1080,7 @@ void nano::vote_processor::process_loop () * the results are probably not useful as well, * so don't spam the logs. */ - BOOST_LOG (node.log) << boost::str (boost::format ("Processed %1% votes in %2% milliseconds (rate of %3% votes per second)") % votes_l.size () % elapsed_time_ms_int % ((votes_l.size () * 1000ULL) / elapsed_time_ms_int)); + node.logger.try_log (boost::str (boost::format ("Processed %1% votes in %2% milliseconds (rate of %3% votes per second)") % votes_l.size () % elapsed_time_ms_int % ((votes_l.size () * 1000ULL) / elapsed_time_ms_int))); } } } @@ -1142,7 +1142,7 @@ void nano::vote_processor::vote (std::shared_ptr vote_a, nano::endpo node.stats.inc (nano::stat::type::vote, nano::stat::detail::vote_overflow); if (node.config.logging.vote_logging ()) { - BOOST_LOG (node.log) << "Votes overflow"; + node.logger.try_log ("Votes overflow"); } } } @@ -1236,7 +1236,7 @@ nano::vote_code nano::vote_processor::vote_blocking (nano::transaction const & t } if (node.config.logging.vote_logging ()) { - BOOST_LOG (node.log) << boost::str (boost::format ("Vote from: %1% sequence: %2% block(s): %3%status: %4%") % vote_a->account.to_account () % std::to_string (vote_a->sequence) % vote_a->hashes_string () % status); + node.logger.try_log (boost::str (boost::format ("Vote from: %1% sequence: %2% block(s): %3%status: %4%") % vote_a->account.to_account () % std::to_string (vote_a->sequence) % vote_a->hashes_string () % status)); } return result; } @@ -1407,6 +1407,7 @@ config (config_a), flags (flags_a), alarm (alarm_a), work (work_a), +logger (config_a.logging.min_time_between_log_output), store_impl (std::make_unique (init_a.block_store_init, config.logging, application_path_a / "data.ldb", config_a.lmdb_max_dbs, !flags.disable_unchecked_drop, flags.sideband_batch_size)), store (*store_impl), wallets_store_impl (std::make_unique (init_a.wallets_store_init, application_path_a / "wallets.ldb", config_a.lmdb_max_dbs)), @@ -1495,7 +1496,7 @@ startup_time (std::chrono::steady_clock::now ()) { if (node_l->config.logging.callback_logging ()) { - BOOST_LOG (node_l->log) << boost::str (boost::format ("Error resolving callback: %1%:%2%: %3%") % address % port % ec.message ()); + node_l->logger.always_log (boost::str (boost::format ("Error resolving callback: %1%:%2%: %3%") % address % port % ec.message ())); } node_l->stats.inc (nano::stat::type::error, nano::stat::detail::http_callback, nano::stat::dir::out); } @@ -1534,7 +1535,7 @@ startup_time (std::chrono::steady_clock::now ()) // We see a valid non-replay vote for a block we requested, this node is probably a representative if (this->peers.rep_response (endpoint_a, vote_a->account, rep_weight)) { - BOOST_LOG (log) << boost::str (boost::format ("Found a representative at %1%") % endpoint_a); + logger.try_log (boost::str (boost::format ("Found a representative at %1%") % endpoint_a)); // Rebroadcasting all active votes to new representative auto blocks (this->active.list_blocks (true)); for (auto i (blocks.begin ()), n (blocks.end ()); i != n; ++i) @@ -1550,19 +1551,19 @@ startup_time (std::chrono::steady_clock::now ()) }); if (NANO_VERSION_PATCH == 0) { - BOOST_LOG (log) << "Node starting, version: " << NANO_MAJOR_MINOR_VERSION; + logger.always_log ("Node starting, version: ", NANO_MAJOR_MINOR_VERSION); } else { - BOOST_LOG (log) << "Node starting, version: " << NANO_MAJOR_MINOR_RC_VERSION; + logger.always_log ("Node starting, version: ", NANO_MAJOR_MINOR_RC_VERSION); } - BOOST_LOG (log) << boost::str (boost::format ("Work pool running %1% threads") % work.threads.size ()); + logger.always_log (boost::str (boost::format ("Work pool running %1% threads") % work.threads.size ())); if (!init_a.error ()) { if (config.logging.node_lifetime_tracing ()) { - BOOST_LOG (log) << "Constructing node"; + logger.always_log ("Constructing node"); } nano::genesis genesis; auto transaction (store.tx_begin_write ()); @@ -1573,12 +1574,12 @@ startup_time (std::chrono::steady_clock::now ()) } if (!store.block_exists (transaction, genesis.hash ())) { - BOOST_LOG (log) << "Genesis block not found. Make sure the node network ID is correct."; + logger.always_log ("Genesis block not found. Make sure the node network ID is correct."); std::exit (1); } node_id = nano::keypair (store.get_node_id (transaction)); - BOOST_LOG (log) << "Node ID: " << node_id.pub.to_account (); + logger.always_log ("Node ID: ", node_id.pub.to_account ()); } peers.online_weight_minimum = config.online_weight_minimum.number (); if (nano::is_live_network || nano::is_beta_network) @@ -1604,7 +1605,7 @@ startup_time (std::chrono::steady_clock::now ()) { break; } - BOOST_LOG (log) << "Using bootstrap rep weight: " << account.to_account () << " -> " << weight.format_balance (Mxrb_ratio, 0, true) << " XRB"; + logger.always_log ("Using bootstrap rep weight: ", account.to_account (), " -> ", weight.format_balance (Mxrb_ratio, 0, true), " XRB"); ledger.bootstrap_weights[account] = weight.number (); } } @@ -1616,7 +1617,7 @@ nano::node::~node () { if (config.logging.node_lifetime_tracing ()) { - BOOST_LOG (log) << "Destructing node"; + logger.always_log ("Destructing node"); } stop (); } @@ -1654,7 +1655,7 @@ void nano::node::do_rpc_callback (boost::asio::ip::tcp::resolver::iterator i_a, { if (node_l->config.logging.callback_logging ()) { - BOOST_LOG (node_l->log) << boost::str (boost::format ("Callback to %1%:%2% failed with status: %3%") % address % port % resp->result ()); + node_l->logger.try_log (boost::str (boost::format ("Callback to %1%:%2% failed with status: %3%") % address % port % resp->result ())); } node_l->stats.inc (nano::stat::type::error, nano::stat::detail::http_callback, nano::stat::dir::out); } @@ -1663,7 +1664,7 @@ void nano::node::do_rpc_callback (boost::asio::ip::tcp::resolver::iterator i_a, { if (node_l->config.logging.callback_logging ()) { - BOOST_LOG (node_l->log) << boost::str (boost::format ("Unable complete callback: %1%:%2%: %3%") % address % port % ec.message ()); + node_l->logger.try_log (boost::str (boost::format ("Unable complete callback: %1%:%2%: %3%") % address % port % ec.message ())); } node_l->stats.inc (nano::stat::type::error, nano::stat::detail::http_callback, nano::stat::dir::out); }; @@ -1673,7 +1674,7 @@ void nano::node::do_rpc_callback (boost::asio::ip::tcp::resolver::iterator i_a, { if (node_l->config.logging.callback_logging ()) { - BOOST_LOG (node_l->log) << boost::str (boost::format ("Unable to send callback: %1%:%2%: %3%") % address % port % ec.message ()); + node_l->logger.try_log (boost::str (boost::format ("Unable to send callback: %1%:%2%: %3%") % address % port % ec.message ())); } node_l->stats.inc (nano::stat::type::error, nano::stat::detail::http_callback, nano::stat::dir::out); } @@ -1683,7 +1684,7 @@ void nano::node::do_rpc_callback (boost::asio::ip::tcp::resolver::iterator i_a, { if (node_l->config.logging.callback_logging ()) { - BOOST_LOG (node_l->log) << boost::str (boost::format ("Unable to connect to callback address: %1%:%2%: %3%") % address % port % ec.message ()); + node_l->logger.try_log (boost::str (boost::format ("Unable to connect to callback address: %1%:%2%: %3%") % address % port % ec.message ())); } node_l->stats.inc (nano::stat::type::error, nano::stat::detail::http_callback, nano::stat::dir::out); ++i_a; @@ -1732,7 +1733,7 @@ void nano::node::process_fork (nano::transaction const & transaction_a, std::sha } })) { - BOOST_LOG (log) << boost::str (boost::format ("Resolving fork between our block: %1% and block %2% both with root %3%") % ledger_block->hash ().to_string () % block_a->hash ().to_string () % block_a->root ().to_string ()); + logger.always_log (boost::str (boost::format ("Resolving fork between our block: %1% and block %2% both with root %3%") % ledger_block->hash ().to_string () % block_a->hash ().to_string () % block_a->root ().to_string ())); network.broadcast_confirm_req (ledger_block); } } @@ -1831,7 +1832,7 @@ void nano::gap_cache::vote (std::shared_ptr vote_a) { if (!node_l->bootstrap_initiator.in_progress ()) { - BOOST_LOG (node_l->log) << boost::str (boost::format ("Missing block %1% which has enough votes to warrant lazy bootstrapping it") % hash.to_string ()); + node_l->logger.try_log (boost::str (boost::format ("Missing block %1% which has enough votes to warrant lazy bootstrapping it") % hash.to_string ())); } if (!node_l->flags.disable_lazy_bootstrap) { @@ -1877,7 +1878,7 @@ void nano::network::confirm_send (nano::confirm_ack const & confirm_a, std::shar { if (node.config.logging.network_publish_logging ()) { - BOOST_LOG (node.log) << boost::str (boost::format ("Sending confirm_ack for block(s) %1%to %2% sequence %3%") % confirm_a.vote->hashes_string () % endpoint_a % std::to_string (confirm_a.vote->sequence)); + node.logger.try_log (boost::str (boost::format ("Sending confirm_ack for block(s) %1%to %2% sequence %3%") % confirm_a.vote->hashes_string () % endpoint_a % std::to_string (confirm_a.vote->sequence))); } std::weak_ptr node_w (node.shared ()); node.network.send_buffer (bytes_a->data (), bytes_a->size (), endpoint_a, [bytes_a, node_w, endpoint_a](boost::system::error_code const & ec, size_t size_a) { @@ -1885,7 +1886,7 @@ void nano::network::confirm_send (nano::confirm_ack const & confirm_a, std::shar { if (ec && node_l->config.logging.network_logging ()) { - BOOST_LOG (node_l->log) << boost::str (boost::format ("Error broadcasting confirm_ack to %1%: %2%") % endpoint_a % ec.message ()); + node_l->logger.try_log (boost::str (boost::format ("Error broadcasting confirm_ack to %1%: %2%") % endpoint_a % ec.message ())); } else { @@ -1949,7 +1950,7 @@ void nano::node::start () void nano::node::stop () { - BOOST_LOG (log) << "Node stopping"; + logger.always_log ("Node stopping"); block_processor.stop (); if (block_processor_thread.joinable ()) { @@ -2315,7 +2316,7 @@ public: } else { - BOOST_LOG (this_l->node->log) << boost::str (boost::format ("Error resolving work peer: %1%:%2%: %3%") % current.first % current.second % ec.message ()); + this_l->node->logger.try_log (boost::str (boost::format ("Error resolving work peer: %1%:%2%: %3%") % current.first % current.second % ec.message ())); } this_l->start (); }); @@ -2364,27 +2365,27 @@ public: } else { - BOOST_LOG (this_l->node->log) << boost::str (boost::format ("Work peer responded with an error %1% %2%: %3%") % connection->address % connection->port % connection->response.result ()); + this_l->node->logger.try_log (boost::str (boost::format ("Work peer responded with an error %1% %2%: %3%") % connection->address % connection->port % connection->response.result ())); this_l->failure (connection->address); } } else { - BOOST_LOG (this_l->node->log) << boost::str (boost::format ("Unable to read from work_peer %1% %2%: %3% (%4%)") % connection->address % connection->port % ec.message () % ec.value ()); + this_l->node->logger.try_log (boost::str (boost::format ("Unable to read from work_peer %1% %2%: %3% (%4%)") % connection->address % connection->port % ec.message () % ec.value ())); this_l->failure (connection->address); } }); } else { - BOOST_LOG (this_l->node->log) << boost::str (boost::format ("Unable to write to work_peer %1% %2%: %3% (%4%)") % connection->address % connection->port % ec.message () % ec.value ()); + this_l->node->logger.try_log (boost::str (boost::format ("Unable to write to work_peer %1% %2%: %3% (%4%)") % connection->address % connection->port % ec.message () % ec.value ())); this_l->failure (connection->address); } }); } else { - BOOST_LOG (this_l->node->log) << boost::str (boost::format ("Unable to connect to work_peer %1% %2%: %3% (%4%)") % connection->address % connection->port % ec.message () % ec.value ()); + this_l->node->logger.try_log (boost::str (boost::format ("Unable to connect to work_peer %1% %2%: %3% (%4%)") % connection->address % connection->port % ec.message () % ec.value ())); this_l->failure (connection->address); } }); @@ -2445,19 +2446,19 @@ public: } else { - BOOST_LOG (node->log) << boost::str (boost::format ("Incorrect work response from %1% for root %2%: %3%") % address % root.to_string () % work_text); + node->logger.try_log (boost::str (boost::format ("Incorrect work response from %1% for root %2%: %3%") % address % root.to_string () % work_text)); handle_failure (last); } } else { - BOOST_LOG (node->log) << boost::str (boost::format ("Work response from %1% wasn't a number: %2%") % address % work_text); + node->logger.try_log (boost::str (boost::format ("Work response from %1% wasn't a number: %2%") % address % work_text)); handle_failure (last); } } catch (...) { - BOOST_LOG (node->log) << boost::str (boost::format ("Work response from %1% wasn't parsable: %2%") % address % body_a); + node->logger.try_log (boost::str (boost::format ("Work response from %1% wasn't parsable: %2%") % address % body_a)); handle_failure (last); } } @@ -2493,7 +2494,7 @@ public: { if (backoff == 1 && node->config.logging.work_generation_time ()) { - BOOST_LOG (node->log) << "Work peer(s) failed to generate work for root " << root.to_string () << ", retrying..."; + node->logger.try_log ("Work peer(s) failed to generate work for root ", root.to_string (), ", retrying..."); } auto now (std::chrono::steady_clock::now ()); auto root_l (root); @@ -2637,12 +2638,12 @@ public: { if (!node.store.block_exists (transaction, hash)) { - BOOST_LOG (node.log) << boost::str (boost::format ("Confirmed block is missing: %1%") % hash.to_string ()); + node.logger.try_log (boost::str (boost::format ("Confirmed block is missing: %1%") % hash.to_string ())); assert (false && "Confirmed block is missing"); } else { - BOOST_LOG (node.log) << boost::str (boost::format ("Block %1% has already been received") % hash.to_string ()); + node.logger.try_log (boost::str (boost::format ("Block %1% has already been received") % hash.to_string ())); } } } @@ -2730,7 +2731,7 @@ nano::endpoint nano::network::endpoint () auto port (socket.local_endpoint (ec).port ()); if (ec) { - BOOST_LOG (node.log) << "Unable to retrieve port: " << ec.message (); + node.logger.try_log ("Unable to retrieve port: ", ec.message ()); } return nano::endpoint (boost::asio::ip::address_v6::loopback (), port); } @@ -2977,7 +2978,7 @@ void nano::network::send_buffer (uint8_t const * data_a, size_t size_a, nano::en std::unique_lock lock (socket_mutex); if (node.config.logging.network_packet_logging ()) { - BOOST_LOG (node.log) << "Sending packet"; + node.logger.try_log ("Sending packet"); } if (on.load ()) { @@ -2990,7 +2991,7 @@ void nano::network::send_buffer (uint8_t const * data_a, size_t size_a, nano::en } if (this->node.config.logging.network_packet_logging ()) { - BOOST_LOG (this->node.log) << "Packet send complete"; + this->node.logger.try_log ("Packet send complete"); } }); } @@ -3159,7 +3160,7 @@ void nano::election::log_votes (nano::tally_t const & tally_a) { tally << boost::str (boost::format ("\n%1% %2%") % i->first.to_account () % i->second.hash.to_string ()); } - BOOST_LOG (node.log) << tally.str (); + node.logger.try_log (tally.str ()); } nano::election_vote_result nano::election::vote (nano::account rep, uint64_t sequence, nano::block_hash block_hash) @@ -3419,7 +3420,7 @@ void nano::active_transactions::request_confirm (std::unique_lock & ++j; if (node.config.logging.vote_logging ()) { - BOOST_LOG (node.log) << "Representative did not respond to confirm_req, retrying: " << rep_acct.to_account (); + node.logger.try_log ("Representative did not respond to confirm_req, retrying: ", rep_acct.to_account ()); } } } @@ -3515,7 +3516,7 @@ void nano::active_transactions::request_confirm (std::unique_lock & } if (unconfirmed_count > 0) { - BOOST_LOG (node.log) << boost::str (boost::format ("%1% blocks have been unconfirmed averaging %2% announcements") % unconfirmed_count % (unconfirmed_announcements / unconfirmed_count)); + node.logger.try_log (boost::str (boost::format ("%1% blocks have been unconfirmed averaging %2% announcements") % unconfirmed_count % (unconfirmed_announcements / unconfirmed_count))); } } @@ -3674,7 +3675,7 @@ void nano::active_transactions::erase (nano::block const & block_a) if (roots.find (nano::uint512_union (block_a.previous (), block_a.root ())) != roots.end ()) { roots.erase (nano::uint512_union (block_a.previous (), block_a.root ())); - BOOST_LOG (node.log) << boost::str (boost::format ("Election erased for block block %1% root %2%") % block_a.hash ().to_string () % block_a.root ().to_string ()); + node.logger.try_log (boost::str (boost::format ("Election erased for block block %1% root %2%") % block_a.hash ().to_string () % block_a.root ().to_string ())); } } diff --git a/nano/node/node.hpp b/nano/node/node.hpp index c627e818..b7e42d29 100644 --- a/nano/node/node.hpp +++ b/nano/node/node.hpp @@ -489,7 +489,7 @@ public: nano::node_flags flags; nano::alarm & alarm; nano::work_pool & work; - boost::log::sources::logger_mt log; + nano::logger_mt logger; std::unique_ptr store_impl; nano::block_store & store; std::unique_ptr wallets_store_impl; diff --git a/nano/node/openclwork.cpp b/nano/node/openclwork.cpp index 263d8541..8534e1e3 100644 --- a/nano/node/openclwork.cpp +++ b/nano/node/openclwork.cpp @@ -606,85 +606,85 @@ logging (logging_a) } else { - BOOST_LOG (logging.log) << boost::str (boost::format ("Bind argument 3 error %1%") % arg3_error); + logging.logger.always_log (boost::str (boost::format ("Bind argument 3 error %1%") % arg3_error)); } } else { - BOOST_LOG (logging.log) << boost::str (boost::format ("Bind argument 2 error %1%") % arg2_error); + logging.logger.always_log (boost::str (boost::format ("Bind argument 2 error %1%") % arg2_error)); } } else { - BOOST_LOG (logging.log) << boost::str (boost::format ("Bind argument 1 error %1%") % arg1_error); + logging.logger.always_log (boost::str (boost::format ("Bind argument 1 error %1%") % arg1_error)); } } else { - BOOST_LOG (logging.log) << boost::str (boost::format ("Bind argument 0 error %1%") % arg0_error); + logging.logger.always_log (boost::str (boost::format ("Bind argument 0 error %1%") % arg0_error)); } } else { - BOOST_LOG (logging.log) << boost::str (boost::format ("Create kernel error %1%") % kernel_error); + logging.logger.always_log (boost::str (boost::format ("Create kernel error %1%") % kernel_error)); } } else { - BOOST_LOG (logging.log) << boost::str (boost::format ("Build program error %1%") % clBuildProgramError); + logging.logger.always_log (boost::str (boost::format ("Build program error %1%") % clBuildProgramError)); for (auto i (selected_devices.begin ()), n (selected_devices.end ()); i != n; ++i) { 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); - BOOST_LOG (logging.log) << log.data (); + logging.logger.always_log (log.data ()); } } } else { - BOOST_LOG (logging.log) << boost::str (boost::format ("Create program error %1%") % program_error); + logging.logger.always_log (boost::str (boost::format ("Create program error %1%") % program_error)); } } else { - BOOST_LOG (logging.log) << boost::str (boost::format ("Difficulty buffer error %1%") % difficulty_error); + logging.logger.always_log (boost::str (boost::format ("Difficulty buffer error %1%") % difficulty_error)); } } else { - BOOST_LOG (logging.log) << boost::str (boost::format ("Item buffer error %1%") % item_error); + logging.logger.always_log (boost::str (boost::format ("Item buffer error %1%") % item_error)); } } else { - BOOST_LOG (logging.log) << boost::str (boost::format ("Result buffer error %1%") % result_error); + logging.logger.always_log (boost::str (boost::format ("Result buffer error %1%") % result_error)); } } else { - BOOST_LOG (logging.log) << boost::str (boost::format ("Attempt buffer error %1%") % attempt_error); + logging.logger.always_log (boost::str (boost::format ("Attempt buffer error %1%") % attempt_error)); } } else { - BOOST_LOG (logging.log) << boost::str (boost::format ("Unable to create command queue %1%") % queue_error); + logging.logger.always_log (boost::str (boost::format ("Unable to create command queue %1%") % queue_error)); } } else { - BOOST_LOG (logging.log) << boost::str (boost::format ("Unable to create context %1%") % createContextError); + logging.logger.always_log (boost::str (boost::format ("Unable to create context %1%") % createContextError)); } } else { - BOOST_LOG (logging.log) << boost::str (boost::format ("Requested device %1%, and only have %2%") % config.device % platform.devices.size ()); + logging.logger.always_log (boost::str (boost::format ("Requested device %1%, and only have %2%") % config.device % platform.devices.size ())); } } else { - BOOST_LOG (logging.log) << boost::str (boost::format ("Requested platform %1% and only have %2%") % config.platform % environment_a.platforms.size ()); + logging.logger.always_log (boost::str (boost::format ("Requested platform %1% and only have %2%") % config.platform % environment_a.platforms.size ())); } } @@ -737,37 +737,37 @@ boost::optional nano::opencl_work::generate_work (nano::uint256_union else { error = true; - BOOST_LOG (logging.log) << boost::str (boost::format ("Error finishing queue %1%") % finishError); + logging.logger.always_log (boost::str (boost::format ("Error finishing queue %1%") % finishError)); } } else { error = true; - BOOST_LOG (logging.log) << boost::str (boost::format ("Error reading result %1%") % read_error1); + logging.logger.always_log (boost::str (boost::format ("Error reading result %1%") % read_error1)); } } else { error = true; - BOOST_LOG (logging.log) << boost::str (boost::format ("Error enqueueing kernel %1%") % enqueue_error); + logging.logger.always_log (boost::str (boost::format ("Error enqueueing kernel %1%") % enqueue_error)); } } else { error = true; - BOOST_LOG (logging.log) << boost::str (boost::format ("Error writing item %1%") % write_error3); + logging.logger.always_log (boost::str (boost::format ("Error writing item %1%") % write_error3)); } } else { error = true; - BOOST_LOG (logging.log) << boost::str (boost::format ("Error writing item %1%") % write_error2); + logging.logger.always_log (boost::str (boost::format ("Error writing item %1%") % write_error2)); } } else { error = true; - BOOST_LOG (logging.log) << boost::str (boost::format ("Error writing attempt %1%") % write_error1); + logging.logger.always_log (boost::str (boost::format ("Error writing attempt %1%") % write_error1)); } } boost::optional value; @@ -787,7 +787,7 @@ std::unique_ptr nano::opencl_work::create (bool create_a, nan nano::opencl_environment environment (error); std::stringstream stream; environment.dump (stream); - BOOST_LOG (logging_a.log) << stream.str (); + logging_a.logger.always_log (stream.str ()); if (!error) { result.reset (new nano::opencl_work (error, config_a, environment, logging_a)); diff --git a/nano/node/portmapping.cpp b/nano/node/portmapping.cpp index ef319fb6..e4c92646 100644 --- a/nano/node/portmapping.cpp +++ b/nano/node/portmapping.cpp @@ -36,12 +36,12 @@ void nano::port_mapping::refresh_devices () } if (check_count % 15 == 0) { - BOOST_LOG (node.log) << boost::str (boost::format ("UPnP local address: %1%, discovery: %2%, IGD search: %3%") % local_address.data () % discover_error % igd_error); + node.logger.always_log (boost::str (boost::format ("UPnP local address: %1%, discovery: %2%, IGD search: %3%") % local_address.data () % discover_error % igd_error)); if (node.config.logging.upnp_details_logging ()) { for (auto i (devices); i != nullptr; i = i->pNext) { - BOOST_LOG (node.log) << boost::str (boost::format ("UPnP device url: %1% st: %2% usn: %3%") % i->descURL % i->st % i->usn); + node.logger.always_log (boost::str (boost::format ("UPnP device url: %1% st: %2% usn: %3%") % i->descURL % i->st % i->usn)); } } } @@ -63,7 +63,7 @@ void nano::port_mapping::refresh_mapping () auto add_port_mapping_error (UPNP_AddAnyPortMapping (urls.controlURL, data.first.servicetype, node_port.c_str (), node_port.c_str (), address.to_string ().c_str (), nullptr, protocol.name, nullptr, std::to_string (mapping_timeout).c_str (), actual_external_port.data ())); if (check_count % 15 == 0) { - BOOST_LOG (node.log) << boost::str (boost::format ("UPnP %1% port mapping response: %2%, actual external port %3%") % protocol.name % add_port_mapping_error % actual_external_port.data ()); + node.logger.always_log (boost::str (boost::format ("UPnP %1% port mapping response: %2%, actual external port %3%") % protocol.name % add_port_mapping_error % actual_external_port.data ())); } if (add_port_mapping_error == UPNPCOMMAND_SUCCESS) { @@ -115,7 +115,7 @@ int nano::port_mapping::check_mapping () } if (check_count % 15 == 0) { - BOOST_LOG (node.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 % external_ip_error % external_address.data () % address.to_string () % remaining_mapping_duration.data ()); + 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 % external_ip_error % external_address.data () % address.to_string () % remaining_mapping_duration.data ())); } } } @@ -140,7 +140,7 @@ void nano::port_mapping::check_mapping_loop () wait_duration = 300; if (check_count < 10) { - BOOST_LOG (node.log) << boost::str (boost::format ("UPnP No IGD devices found")); + node.logger.always_log (boost::str (boost::format ("UPnP No IGD devices found"))); } } ++check_count; @@ -163,7 +163,7 @@ void nano::port_mapping::stop () { // Be a good citizen for the router and shut down our mapping auto delete_error (UPNP_DeletePortMapping (urls.controlURL, data.first.servicetype, std::to_string (protocol.external_port).c_str (), protocol.name, address.to_string ().c_str ())); - BOOST_LOG (node.log) << boost::str (boost::format ("Shutdown port mapping response: %1%") % delete_error); + node.logger.always_log (boost::str (boost::format ("Shutdown port mapping response: %1%") % delete_error)); } } freeUPNPDevlist (devices); diff --git a/nano/node/rpc.cpp b/nano/node/rpc.cpp index c6ecb43b..aaac2a3f 100644 --- a/nano/node/rpc.cpp +++ b/nano/node/rpc.cpp @@ -40,7 +40,7 @@ void nano::rpc::start (bool rpc_enabled_a) acceptor.bind (endpoint, ec); if (ec) { - BOOST_LOG (node.log) << boost::str (boost::format ("Error while binding for RPC on port %1%: %2%") % endpoint.port () % ec.message ()); + node.logger.always_log (boost::str (boost::format ("Error while binding for RPC on port %1%: %2%") % endpoint.port () % ec.message ())); throw std::runtime_error (ec.message ()); } @@ -69,7 +69,7 @@ void nano::rpc::accept () } else { - BOOST_LOG (this->node.log) << boost::str (boost::format ("Error accepting RPC connections: %1% (%2%)") % ec.message () % ec.value ()); + this->node.logger.always_log (boost::str (boost::format ("Error accepting RPC connections: %1% (%2%)") % ec.message () % ec.value ())); } }); } @@ -2407,7 +2407,7 @@ void nano::rpc_handler::payment_begin () wallet->free_accounts.erase (existing); if (wallet->store.find (transaction, account) == wallet->store.end ()) { - BOOST_LOG (node.log) << boost::str (boost::format ("Transaction wallet %1% externally modified listing account %2% as free but no longer exists") % id.to_string () % account.to_account ()); + node.logger.always_log (boost::str (boost::format ("Transaction wallet %1% externally modified listing account %2% as free but no longer exists") % id.to_string () % account.to_account ())); account.clear (); } else @@ -2415,7 +2415,7 @@ void nano::rpc_handler::payment_begin () auto block_transaction (node.store.tx_begin_read ()); if (!node.ledger.account_balance (block_transaction, account).is_zero ()) { - BOOST_LOG (node.log) << boost::str (boost::format ("Skipping account %1% for use as a transaction account: non-zero balance") % account.to_account ()); + node.logger.always_log (boost::str (boost::format ("Skipping account %1% for use as a transaction account: non-zero balance") % account.to_account ())); account.clear (); } } @@ -4329,7 +4329,7 @@ void nano::rpc_connection::read () if (this_l->node->config.logging.log_rpc ()) { - BOOST_LOG (this_l->node->log) << boost::str (boost::format ("RPC request %2% completed in: %1% microseconds") % std::chrono::duration_cast (std::chrono::steady_clock::now () - start).count () % request_id); + this_l->node->logger.always_log (boost::str (boost::format ("RPC request %2% completed in: %1% microseconds") % std::chrono::duration_cast (std::chrono::steady_clock::now () - start).count () % request_id)); } }); auto method = this_l->request.method (); @@ -4359,7 +4359,7 @@ void nano::rpc_connection::read () } else { - BOOST_LOG (this_l->node->log) << "RPC read error: " << ec.message (); + this_l->node->logger.always_log ("RPC read error: ", ec.message ()); } }); } @@ -4432,7 +4432,7 @@ void nano::rpc_handler::process_request () std::string action (request.get ("action")); if (node.config.logging.log_rpc ()) { - BOOST_LOG (node.log) << boost::str (boost::format ("%1% ") % request_id) << filter_request (request); + rpc.node.logger.always_log (boost::str (boost::format ("%1% ") % request_id), filter_request (request)); } if (action == "account_balance") { @@ -4964,7 +4964,7 @@ void nano::payment_observer::complete (nano::payment_status status) { if (rpc.node.config.logging.log_rpc ()) { - BOOST_LOG (rpc.node.log) << boost::str (boost::format ("Exiting payment_observer for account %1% status %2%") % account.to_account () % static_cast (status)); + rpc.node.logger.always_log (boost::str (boost::format ("Exiting payment_observer for account %1% status %2%") % account.to_account () % static_cast (status))); } switch (status) { diff --git a/nano/node/testing.cpp b/nano/node/testing.cpp index aa9a5e27..0f7b6226 100644 --- a/nano/node/testing.cpp +++ b/nano/node/testing.cpp @@ -441,7 +441,7 @@ void nano::landing::write_store () { std::stringstream str; store.serialize (str); - BOOST_LOG (node.log) << boost::str (boost::format ("Error writing store file %1%") % str.str ()); + node.logger.always_log (boost::str (boost::format ("Error writing store file %1%") % str.str ())); } } @@ -502,13 +502,13 @@ void nano::landing::distribute_one () last = wallet->send_sync (store.source, store.destination, amount); if (!last.is_zero ()) { - BOOST_LOG (node.log) << boost::str (boost::format ("Successfully distributed %1% in block %2%") % amount % last.to_string ()); + node.logger.always_log (boost::str (boost::format ("Successfully distributed %1% in block %2%") % amount % last.to_string ())); store.last += distribution_interval.count (); write_store (); } else { - BOOST_LOG (node.log) << "Error while sending distribution"; + node.logger.always_log ("Error while sending distribution"); } } } @@ -516,7 +516,7 @@ void nano::landing::distribute_one () void nano::landing::distribute_ongoing () { distribute_one (); - BOOST_LOG (node.log) << "Waiting for next distribution cycle"; + node.logger.always_log ("Waiting for next distribution cycle"); node.alarm.add (std::chrono::steady_clock::now () + sleep_seconds, [this]() { distribute_ongoing (); }); } diff --git a/nano/node/wallet.cpp b/nano/node/wallet.cpp index dc8bfcfc..526545bd 100644 --- a/nano/node/wallet.cpp +++ b/nano/node/wallet.cpp @@ -948,7 +948,7 @@ std::shared_ptr nano::wallet::receive_action (nano::block const & s } else { - BOOST_LOG (wallets.node.log) << "Unable to receive, wallet locked"; + wallets.node.logger.try_log ("Unable to receive, wallet locked"); } } else @@ -963,14 +963,14 @@ std::shared_ptr nano::wallet::receive_action (nano::block const & s } else { - BOOST_LOG (wallets.node.log) << boost::str (boost::format ("Not receiving block %1% due to minimum receive threshold") % hash.to_string ()); + wallets.node.logger.try_log (boost::str (boost::format ("Not receiving block %1% due to minimum receive threshold") % hash.to_string ())); // Someone sent us something below the threshold of receiving } if (block != nullptr) { if (nano::work_validate (*block)) { - BOOST_LOG (wallets.node.log) << boost::str (boost::format ("Cached or provided work for block %1% account %2% is invalid, regenerating") % block->hash ().to_string () % account.to_account ()); + wallets.node.logger.try_log (boost::str (boost::format ("Cached or provided work for block %1% account %2% is invalid, regenerating") % block->hash ().to_string () % account.to_account ())); wallets.node.work_generate_blocking (*block); } wallets.node.process_active (block); @@ -1012,7 +1012,7 @@ std::shared_ptr nano::wallet::change_action (nano::account const & { if (nano::work_validate (*block)) { - BOOST_LOG (wallets.node.log) << boost::str (boost::format ("Cached or provided work for block %1% account %2% is invalid, regenerating") % block->hash ().to_string () % source_a.to_account ()); + wallets.node.logger.try_log (boost::str (boost::format ("Cached or provided work for block %1% account %2% is invalid, regenerating") % block->hash ().to_string () % source_a.to_account ())); wallets.node.work_generate_blocking (*block); } wallets.node.process_active (block); @@ -1098,7 +1098,7 @@ std::shared_ptr nano::wallet::send_action (nano::account const & so { if (nano::work_validate (*block)) { - BOOST_LOG (wallets.node.log) << boost::str (boost::format ("Cached or provided work for block %1% account %2% is invalid, regenerating") % block->hash ().to_string () % account_a.to_account ()); + wallets.node.logger.try_log (boost::str (boost::format ("Cached or provided work for block %1% account %2% is invalid, regenerating") % block->hash ().to_string () % account_a.to_account ())); wallets.node.work_generate_blocking (*block); } wallets.node.process_active (block); @@ -1187,7 +1187,7 @@ void nano::wallet::work_update (nano::transaction const & transaction_a, nano::a } else { - BOOST_LOG (wallets.node.log) << "Cached work no longer valid, discarding"; + wallets.node.logger.try_log ("Cached work no longer valid, discarding"); } } @@ -1204,7 +1204,7 @@ bool nano::wallet::search_pending () auto result (!store.valid_password (transaction)); if (!result) { - BOOST_LOG (wallets.node.log) << "Beginning pending block search"; + wallets.node.logger.try_log ("Beginning pending block search"); for (auto i (store.begin (transaction)), n (store.end ()); i != n; ++i) { auto block_transaction (wallets.node.store.tx_begin_read ()); @@ -1220,17 +1220,17 @@ bool nano::wallet::search_pending () auto amount (pending.amount.number ()); if (wallets.node.config.receive_minimum.number () <= amount) { - BOOST_LOG (wallets.node.log) << boost::str (boost::format ("Found a pending block %1% for account %2%") % hash.to_string () % pending.source.to_account ()); + wallets.node.logger.try_log (boost::str (boost::format ("Found a pending block %1% for account %2%") % hash.to_string () % pending.source.to_account ())); wallets.node.block_confirm (wallets.node.store.block_get (block_transaction, hash)); } } } } - BOOST_LOG (wallets.node.log) << "Pending block search phase complete"; + wallets.node.logger.try_log ("Pending block search phase complete"); } else { - BOOST_LOG (wallets.node.log) << "Stopping search, wallet is locked"; + wallets.node.logger.try_log ("Stopping search, wallet is locked"); } return result; } @@ -1319,7 +1319,7 @@ void nano::wallet::work_cache_blocking (nano::account const & account_a, nano::b */ auto difficulty (nano::work_pool::publish_threshold); - BOOST_LOG (wallets.node.log) << "Work generation for " << root_a.to_string () << ", with a difficulty of " << difficulty << " complete: " << (std::chrono::duration_cast (std::chrono::steady_clock::now () - begin).count ()) << " us"; + wallets.node.logger.try_log ("Work generation for ", root_a.to_string (), ", with a difficulty of ", difficulty, " complete: ", (std::chrono::duration_cast (std::chrono::steady_clock::now () - begin).count ()), " us"); } auto transaction (wallets.tx_begin_write ()); if (live () && store.exists (transaction, account_a)) @@ -1560,7 +1560,7 @@ void nano::wallets::foreach_representative (nano::transaction const & transactio if (last_log < std::chrono::steady_clock::now () - std::chrono::seconds (60)) { last_log = std::chrono::steady_clock::now (); - BOOST_LOG (node.log) << boost::str (boost::format ("Representative locked inside wallet %1%") % i->first.to_string ()); + node.logger.always_log (boost::str (boost::format ("Representative locked inside wallet %1%") % i->first.to_string ())); } } }