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

Time limited logging (#1789)

Browse source 
* Add time limited logging object

* Always log IPC server started

* Use console logger so that it works on travis

* Remove unused function

* Invert bool logic to be error instead and check for default time point when trying to log

* Fix comment formatting in parameter

* Always log trying to open burned account

* More to always log in node.cpp

* Always log should_log in classes which manage their own log timing
This commit is contained in:
Wesley Shillingford 2019-02-26 17:00:43 +00:00 • committed by GitHub
commit c69b509ddc
No known key found for this signature in database
GPG key ID: 4AEE18F83AFDEB23
17 changed files with 527 additions and 352 deletions
Download patch file Download diff file Expand all files Collapse all files

1
nano/core_test/CMakeLists.txt
View file

@ -8,6 +8,7 @@ add_executable (core_test
entry.cpp
gap_cache.cpp
ledger.cpp
logger.cpp
network.cpp
node.cpp
message.cpp

178
nano/core_test/logger.cpp Normal file
View file

@ -0,0 +1,178 @@
#include <boost/log/utility/setup/console.hpp>
#include <chrono>
#include <gtest/gtest.h>
#include <nano/node/logging.hpp>
#include <nano/secure/utility.hpp>
#include <regex>
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<int> ("version"));
ASSERT_FALSE (tree.get<bool> ("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<int> ("version"));
ASSERT_EQ (5, tree.get<uintmax_t> ("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<boost::log::sinks::synchronous_sink<boost::log::sinks::text_ostream_backend>> 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);
}

62
nano/core_test/node.cpp
View file

@ -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<int> ("version"));
ASSERT_FALSE (tree.get<bool> ("vote"));
}
TEST (node, price)
{
nano::system system (24000, 1);

36
nano/node/blockprocessor.cpp
View file

@ -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<std::mutex> & 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<std::mutex> & 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<nano::block_hash> 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<std::mutex> & 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;
}

162
nano/node/bootstrap.cpp
View file

@ -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<double> (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<std::mutex> 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<std::mutex> 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<int> (type));
connection->node->logger.try_log (boost::str (boost::format ("Unknown type received as block type: %1%") % static_cast<int> (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<std::mutex> 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<std::mutex> 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<std::mutex> & 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<std::mutex> & 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<std::mutex> 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<std::mutex> 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<std::mutex> 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<uint8_t> (header.type));
node->logger.try_log (boost::str (boost::format ("Received invalid type from bootstrap connection %1%") % static_cast<uint8_t> (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<double>::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<double>::infinity ())));
}
add_request (std::unique_ptr<nano::message> (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<nano::message> (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<nano::message> (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<uint8_t> (request->flags));
connection->node->logger.try_log (boost::str (boost::format ("Invalid bulk_pull_account flags supplied %1%") % static_cast<uint8_t> (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 ()));
}
}
}

2
nano/node/cli.cpp
View file

@ -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
{

24
nano/node/ipc.cpp
View file

@ -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<uint8_t> (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<socket_transport<boost::asio::local::stream_protocol::acceptor, boost::asio::local::stream_protocol::socket, boost::asio::local::stream_protocol::endpoint>> (*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<socket_transport<boost::asio::ip::tcp::acceptor, boost::asio::ip::tcp::socket, boost::asio::ip::tcp::endpoint>> (*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 ()

4
nano/node/lmdb.cpp
View file

@ -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<nano::mdb_txn *> (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);
}
}

37
nano/node/logging.cpp
View file

@ -5,31 +5,6 @@
#include <boost/property_tree/ptree.hpp>
#include <nano/node/logging.hpp>
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<bool> ("flush", flush);
json.get<uintmax_t> ("max_size", max_size);
json.get<uintmax_t> ("rotation_size", rotation_size);
uintmax_t min_time_between_log_output_raw;
json.get<uintmax_t> ("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 ();
}

122
nano/node/logging.hpp
View file

@ -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 <typename LogItem, typename... LogItems>
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 <typename... LogItems>
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<LogItems> (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 <typename... LogItems>
void always_log (LogItems &&... log_items)
{
output (std::forward<LogItems> (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 <typename... LogItems>
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<LogItems> (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;
}
};
}

143
nano/node/node.cpp
View file

@ -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<std::mutex> 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<nano::node> 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<nano::node> 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<nano::node> 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<nano::block> 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<nano::block> block, nano::e
republish (hash, std::make_shared<std::vector<uint8_t>> (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<nano::block> 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<nano::endpoi
const size_t max_reps = 10;
if (!resumption && node.config.logging.network_logging ())
{
BOOST_LOG (node.log) << boost::str (boost::format ("Broadcasting batch confirm req to %1% representatives") % request_bundle_a.size ());
node.logger.try_log (boost::str (boost::format ("Broadcasting batch confirm req to %1% representatives") % request_bundle_a.size ()));
}
auto count (0);
while (!request_bundle_a.empty () && count < max_reps)
@ -540,7 +540,7 @@ void nano::network::send_confirm_req (nano::endpoint const & endpoint_a, std::sh
auto bytes = message.to_bytes ();
if (node.config.logging.network_message_logging ())
{
BOOST_LOG (node.log) << boost::str (boost::format ("Sending confirm req to %1%") % endpoint_a);
node.logger.try_log (boost::str (boost::format ("Sending confirm req to %1%") % endpoint_a));
}
std::weak_ptr<nano::node> 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<nano::node> 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<nano::uint256_union> 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<nano::vote> 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<nano::mdb_store> (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<nano::mdb_wallets_store> (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<nano::vote> 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<nano::node> 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<std::mutex> 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<std::mutex> &
++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<std::mutex> &
}
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 ()));
}
}

2
nano/node/node.hpp
View file

@ -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<nano::block_store> store_impl;
nano::block_store & store;
std::unique_ptr<nano::wallets_store> wallets_store_impl;

46
nano/node/openclwork.cpp
View file

@ -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<char> 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<uint64_t> 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<uint64_t> value;
@ -787,7 +787,7 @@ std::unique_ptr<nano::opencl_work> 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));

12
nano/node/portmapping.cpp
View file

@ -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);

16
nano/node/rpc.cpp
View file

@ -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::microseconds> (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::microseconds> (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<std::string> ("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<unsigned> (status));
rpc.node.logger.always_log (boost::str (boost::format ("Exiting payment_observer for account %1% status %2%") % account.to_account () % static_cast<unsigned> (status)));
}
switch (status)
{

8
nano/node/testing.cpp
View file

@ -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 (); });
}

24
nano/node/wallet.cpp
View file

@ -948,7 +948,7 @@ std::shared_ptr<nano::block> 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::block> 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::block> 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::block> 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::microseconds> (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::microseconds> (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 ()));
}
}
}