From 9a80f294dc7761a1c547d38e09e4a5348f70b363 Mon Sep 17 00:00:00 2001
From: =?UTF-8?q?Piotr=20Wo=CC=81jcik?=
 <3044353+pwojcikdev@users.noreply.github.com>
Date: Fri, 9 Feb 2024 15:19:57 +0100
Subject: [PATCH] Stats & logs

---
 nano/core_test/node.cpp      |  2 +-
 nano/lib/stats_enums.hpp     | 10 +++++++--
 nano/node/blockprocessor.cpp | 41 ++++++++++++++++++++++++++----------
 nano/node/blockprocessor.hpp |  1 +
 4 files changed, 40 insertions(+), 14 deletions(-)

diff --git a/nano/core_test/node.cpp b/nano/core_test/node.cpp
index 0f7410e7..34f1de2b 100644
--- a/nano/core_test/node.cpp
+++ b/nano/core_test/node.cpp
@@ -2911,7 +2911,7 @@ TEST (node, block_processor_reject_state)
 	send1->signature.bytes[0] ^= 1;
 	ASSERT_FALSE (node.ledger.block_or_pruned_exists (send1->hash ()));
 	node.process_active (send1);
-	ASSERT_TIMELY_EQ (5s, 1, node.stats.count (nano::stat::type::blockprocessor, nano::stat::detail::bad_signature));
+	ASSERT_TIMELY_EQ (5s, 1, node.stats.count (nano::stat::type::blockprocessor_result, nano::stat::detail::bad_signature));
 	ASSERT_FALSE (node.ledger.block_or_pruned_exists (send1->hash ()));
 	auto send2 = builder.make_block ()
 				 .account (nano::dev::genesis_key.pub)
diff --git a/nano/lib/stats_enums.hpp b/nano/lib/stats_enums.hpp
index 9a726472..63c90bdd 100644
--- a/nano/lib/stats_enums.hpp
+++ b/nano/lib/stats_enums.hpp
@@ -36,7 +36,8 @@ enum class type : uint8_t
 	vote_cache,
 	hinting,
 	blockprocessor,
-	blockprocessor_sources,
+	blockprocessor_source,
+	blockprocessor_result,
 	bootstrap_server,
 	active,
 	active_started,
@@ -112,7 +113,12 @@ enum class detail : uint8_t
 	representative_mismatch,
 	block_position,
 
-	// blockprocessor result
+	// blockprocessor
+	process_blocking,
+	process_blocking_timeout,
+	force,
+
+	// block source
 	live,
 	bootstrap,
 	bootstrap_legacy,
diff --git a/nano/node/blockprocessor.cpp b/nano/node/blockprocessor.cpp
index 3130da49..8d762378 100644
--- a/nano/node/blockprocessor.cpp
+++ b/nano/node/blockprocessor.cpp
@@ -88,14 +88,22 @@ void nano::block_processor::add (std::shared_ptr<nano::block> const & block, blo
 		node.stats.inc (nano::stat::type::blockprocessor, nano::stat::detail::insufficient_work);
 		return;
 	}
+
+	node.stats.inc (nano::stat::type::blockprocessor, nano::stat::detail::process);
+	node.logger.debug (nano::log::type::blockprocessor, "Processing block (async): {} (source: {})", block->hash ().to_string (), to_string (source));
+
 	add_impl (block, context{ source });
 }
 
 std::optional<nano::process_return> nano::block_processor::add_blocking (std::shared_ptr<nano::block> const & block, block_source const source)
 {
+	node.stats.inc (nano::stat::type::blockprocessor, nano::stat::detail::process_blocking);
+	node.logger.debug (nano::log::type::blockprocessor, "Processing block (blocking): {} (source: {})", block->hash ().to_string (), to_string (source));
+
 	context ctx{ source };
 	auto future = ctx.get_future ();
 	add_impl (block, std::move (ctx));
+
 	try
 	{
 		auto status = future.wait_for (node.config.block_process_timeout);
@@ -107,10 +115,25 @@ std::optional<nano::process_return> nano::block_processor::add_blocking (std::sh
 	}
 	catch (std::future_error const &)
 	{
+		node.stats.inc (nano::stat::type::blockprocessor, nano::stat::detail::process_blocking_timeout);
+		node.logger.error (nano::log::type::blockprocessor, "Timeout processing block: {}", block->hash ().to_string ());
 	}
+
 	return std::nullopt;
 }
 
+void nano::block_processor::force (std::shared_ptr<nano::block> const & block_a)
+{
+	node.stats.inc (nano::stat::type::blockprocessor, nano::stat::detail::force);
+	node.logger.debug (nano::log::type::blockprocessor, "Forcing block: {}", block_a->hash ().to_string ());
+
+	{
+		nano::lock_guard<nano::mutex> lock{ mutex };
+		forced.emplace_back (entry{ block_a, context{ block_source::forced } });
+	}
+	condition.notify_all ();
+}
+
 void nano::block_processor::rollback_competitor (store::write_transaction const & transaction, nano::block const & block)
 {
 	auto hash = block.hash ();
@@ -143,15 +166,6 @@ void nano::block_processor::rollback_competitor (store::write_transaction const
 	}
 }
 
-void nano::block_processor::force (std::shared_ptr<nano::block> const & block_a)
-{
-	{
-		nano::lock_guard<nano::mutex> lock{ mutex };
-		forced.emplace_back (entry{ block_a, context{ block_source::forced } });
-	}
-	condition.notify_all ();
-}
-
 void nano::block_processor::process_blocks ()
 {
 	nano::unique_lock<nano::mutex> lock{ mutex };
@@ -304,8 +318,8 @@ nano::process_return nano::block_processor::process_one (store::write_transactio
 	auto const hash = block->hash ();
 	nano::process_return result = node.ledger.process (transaction_a, *block);
 
-	node.stats.inc (nano::stat::type::blockprocessor, to_stat_detail (result.code));
-	node.stats.inc (nano::stat::type::blockprocessor_sources, to_stat_detail (context.source));
+	node.stats.inc (nano::stat::type::blockprocessor_result, to_stat_detail (result.code));
+	node.stats.inc (nano::stat::type::blockprocessor_source, to_stat_detail (context.source));
 	node.logger.trace (nano::log::type::blockprocessor, nano::log::detail::block_processed,
 	nano::log::arg{ "result", result.code },
 	nano::log::arg{ "source", context.source },
@@ -415,6 +429,11 @@ std::unique_ptr<nano::container_info_component> nano::collect_container_info (bl
 	return composite;
 }
 
+std::string_view nano::to_string (nano::block_source source)
+{
+	return magic_enum::enum_name (source);
+}
+
 nano::stat::detail nano::to_stat_detail (nano::block_source type)
 {
 	auto value = magic_enum::enum_cast<nano::stat::detail> (magic_enum::enum_name (type));
diff --git a/nano/node/blockprocessor.hpp b/nano/node/blockprocessor.hpp
index 97dbb71e..65bb62e7 100644
--- a/nano/node/blockprocessor.hpp
+++ b/nano/node/blockprocessor.hpp
@@ -31,6 +31,7 @@ enum class block_source
 	forced,
 };
 
+std::string_view to_string (nano::block_source);
 nano::stat::detail to_stat_detail (block_source);
 
 /**