Merge pull request #4822 from pwojcikdev/fix-activate-immediately

Fix activate immediately logic

nano/core_test/node.cpp

@@ -1385,6 +1385,12 @@ TEST (node, bootstrap_fork_open)
 {
 	nano::test::system system;
 	nano::node_config node_config (system.get_available_port ());
+	node_config.bootstrap.account_sets.cooldown = 100ms; // Reduce cooldown to speed up fork resolution
+	// Disable automatic election activation
+	node_config.backlog_scan.enable = false;
+	node_config.priority_scheduler.enable = false;
+	node_config.hinted_scheduler.enable = false;
+	node_config.optimistic_scheduler.enable = false;
 	auto node0 = system.add_node (node_config);
 	node_config.peering_port = system.get_available_port ();
 	auto node1 = system.add_node (node_config);
@@ -1411,26 +1417,30 @@ TEST (node, bootstrap_fork_open)
 				 .sign (key0.prv, key0.pub)
 				 .work (*system.work.generate (key0.pub))
 				 .build ();
+
 	// Both know about send0
 	ASSERT_EQ (nano::block_status::progress, node0->process (send0));
 	ASSERT_EQ (nano::block_status::progress, node1->process (send0));
+
 	// Confirm send0 to allow starting and voting on the following blocks
-	for (auto node : system.nodes)
-	{
-		node->start_election (node->block (node->latest (nano::dev::genesis_key.pub)));
-		ASSERT_TIMELY (1s, node->active.election (send0->qualified_root ()));
-		auto election = node->active.election (send0->qualified_root ());
-		ASSERT_NE (nullptr, election);
-		election->force_confirm ();
-		ASSERT_TIMELY (2s, node->active.empty ());
-	}
-	ASSERT_TIMELY (3s, node0->block_confirmed (send0->hash ()));
+	nano::test::confirm (*node0, { send0 });
+	nano::test::confirm (*node1, { send0 });
+	ASSERT_TIMELY (5s, node0->block_confirmed (send0->hash ()));
+	ASSERT_TIMELY (5s, node1->block_confirmed (send0->hash ()));
+
 	// They disagree about open0/open1
 	ASSERT_EQ (nano::block_status::progress, node0->process (open0));
+	node0->confirming_set.add (open0->hash ());
+	ASSERT_TIMELY (5s, node0->block_confirmed (open0->hash ()));
+
 	ASSERT_EQ (nano::block_status::progress, node1->process (open1));
+	ASSERT_TRUE (node1->block_or_pruned_exists (open1->hash ()));
+	node1->start_election (open1); // Start election for open block which is necessary to resolve the fork
+	ASSERT_TIMELY (5s, node1->active.active (*open1));
+
+	// Allow node0 to vote on its fork
 	system.wallet (0)->insert_adhoc (nano::dev::genesis_key.prv);
-	ASSERT_FALSE (node1->block_or_pruned_exists (open0->hash ()));
-	ASSERT_TIMELY (1s, node1->active.empty ());
+
 	ASSERT_TIMELY (10s, !node1->block_or_pruned_exists (open1->hash ()) && node1->block_or_pruned_exists (open0->hash ()));
 }
 

nano/lib/logging_enums.hpp

@@ -86,6 +86,7 @@ enum class type
 	monitor,
 	confirming_set,
 	bounded_backlog,
+	request_aggregator,
 
 	// bootstrap
 	bulk_pull_client,

nano/lib/stats_enums.hpp

@@ -288,6 +288,7 @@ enum class detail
 	broadcast_block_repeat,
 	confirm_once,
 	confirm_once_failed,
+	confirmation_request,
 
 	// election types
 	manual,
@@ -462,6 +463,7 @@ enum class detail
 	transition_priority,
 	transition_priority_failed,
 	election_cleanup,
+	activate_immediately,
 
 	// active_elections
 	started,

nano/node/active_elections.cpp

@@ -419,11 +419,16 @@ nano::election_insertion_result nano::active_elections::insert (std::shared_ptr<
 			count_by_behavior[result.election->behavior ()]++;
 
 			// Skip passive phase for blocks without cached votes to avoid bootstrap delays
-			bool active_immediately = false;
-			if (node.vote_cache.contains (hash))
+			bool activate_immediately = false;
+			if (!node.vote_cache.contains (hash))
 			{
+				activate_immediately = true;
+			}
+
+			if (activate_immediately)
+			{
+				node.stats.inc (nano::stat::type::active_elections, nano::stat::detail::activate_immediately);
 				result.election->transition_active ();
-				active_immediately = true;
 			}
 
 			node.stats.inc (nano::stat::type::active_elections, nano::stat::detail::started);
@@ -436,7 +441,7 @@ nano::election_insertion_result nano::active_elections::insert (std::shared_ptr<
 			node.logger.debug (nano::log::type::active_elections, "Started new election for block: {} (behavior: {}, active immediately: {})",
 			hash.to_string (),
 			to_string (election_behavior_a),
-			active_immediately);
+			activate_immediately);
 		}
 		else
 		{

nano/node/block_processor.cpp

@@ -392,41 +392,51 @@ nano::block_status nano::block_processor::process_one (secure::write_transaction
 			stats.inc (nano::stat::type::ledger, nano::stat::detail::old);
 			break;
 		}
+		// These are unexpected and indicate erroneous/malicious behavior, log debug info to highlight the issue
 		case nano::block_status::bad_signature:
 		{
+			logger.debug (nano::log::type::block_processor, "Block signature is invalid: {}", hash);
 			break;
 		}
 		case nano::block_status::negative_spend:
 		{
+			logger.debug (nano::log::type::block_processor, "Block spends negative amount: {}", hash);
 			break;
 		}
 		case nano::block_status::unreceivable:
 		{
+			logger.debug (nano::log::type::block_processor, "Block is unreceivable: {}", hash);
 			break;
 		}
 		case nano::block_status::fork:
 		{
 			stats.inc (nano::stat::type::ledger, nano::stat::detail::fork);
+			logger.debug (nano::log::type::block_processor, "Block is a fork: {}", hash);
 			break;
 		}
 		case nano::block_status::opened_burn_account:
 		{
+			logger.debug (nano::log::type::block_processor, "Block opens burn account: {}", hash);
 			break;
 		}
 		case nano::block_status::balance_mismatch:
 		{
+			logger.debug (nano::log::type::block_processor, "Block balance mismatch: {}", hash);
 			break;
 		}
 		case nano::block_status::representative_mismatch:
 		{
+			logger.debug (nano::log::type::block_processor, "Block representative mismatch: {}", hash);
 			break;
 		}
 		case nano::block_status::block_position:
 		{
+			logger.debug (nano::log::type::block_processor, "Block is in incorrect position: {}", hash);
 			break;
 		}
 		case nano::block_status::insufficient_work:
 		{
+			logger.debug (nano::log::type::block_processor, "Block has insufficient work: {}", hash);
 			break;
 		}
 	}

nano/node/bootstrap/bootstrap_service.cpp

@@ -524,33 +524,58 @@ bool nano::bootstrap_service::request (nano::account account, size_t count, std:
 		// Check if the account picked has blocks, if it does, start the pull from the highest block
 		if (auto info = ledger.store.account.get (transaction, account))
 		{
-			tag.type = query_type::blocks_by_hash;
-
 			// Probabilistically choose between requesting blocks from account frontier or confirmed frontier
 			// Optimistic requests start from the (possibly unconfirmed) account frontier and are vulnerable to bootstrap poisoning
 			// Safe requests start from the confirmed frontier and given enough time will eventually resolve forks
 			bool optimistic_reuest = rng.random (100) < config.optimistic_request_percentage;
-			if (!optimistic_reuest)
+
+			if (optimistic_reuest) // Optimistic request case
+			{
+				stats.inc (nano::stat::type::bootstrap_request_blocks, nano::stat::detail::optimistic);
+
+				tag.type = query_type::blocks_by_hash;
+				tag.start = info->head;
+				tag.hash = info->head;
+
+				logger.debug (nano::log::type::bootstrap, "Requesting blocks for {} starting from account frontier: {} (optimistic: {})",
+				account.to_account (), // TODO: Lazy eval
+				tag.start.to_string (), // TODO: Lazy eval
+				optimistic_reuest);
+			}
+			else // Pessimistic (safe) request case
 			{
+				stats.inc (nano::stat::type::bootstrap_request_blocks, nano::stat::detail::safe);
+
 				if (auto conf_info = ledger.store.confirmation_height.get (transaction, account))
 				{
-					stats.inc (nano::stat::type::bootstrap_request_blocks, nano::stat::detail::safe);
+					tag.type = query_type::blocks_by_hash;
 					tag.start = conf_info->frontier;
 					tag.hash = conf_info->height;
+
+					logger.debug (nano::log::type::bootstrap, "Requesting blocks for {} starting from confirmation frontier: {} (optimistic: {})",
+					account.to_account (), // TODO: Lazy eval
+					tag.start.to_string (), // TODO: Lazy eval
+					optimistic_reuest);
+				}
+				else
+				{
+					tag.type = query_type::blocks_by_account;
+					tag.start = account;
+
+					logger.debug (nano::log::type::bootstrap, "Requesting blocks for {} starting from account root (optimistic: {})",
+					account.to_account (), // TODO: Lazy eval
+					optimistic_reuest);
 				}
-			}
-			if (tag.start.is_zero ())
-			{
-				stats.inc (nano::stat::type::bootstrap_request_blocks, nano::stat::detail::optimistic);
-				tag.start = info->head;
-				tag.hash = info->head;
 			}
 		}
 		else
 		{
 			stats.inc (nano::stat::type::bootstrap_request_blocks, nano::stat::detail::base);
+
 			tag.type = query_type::blocks_by_account;
 			tag.start = account;
+
+			logger.debug (nano::log::type::bootstrap, "Requesting blocks for {}", account.to_account ()); // TODO: Lazy eval
 		}
 	}
 
@@ -1056,6 +1081,8 @@ void nano::bootstrap_service::process_frontiers (std::deque<std::pair<nano::acco
 	stats.add (nano::stat::type::bootstrap_frontiers, nano::stat::detail::outdated, outdated);
 	stats.add (nano::stat::type::bootstrap_frontiers, nano::stat::detail::pending, pending);
 
+	logger.debug (nano::log::type::bootstrap, "Processed {} frontiers of which outdated: {}, pending: {}", frontiers.size (), outdated, pending);
+
 	nano::lock_guard<nano::mutex> guard{ mutex };
 
 	for (auto const & account : result)

nano/node/election.cpp

@@ -168,12 +168,24 @@ std::chrono::milliseconds nano::election::confirm_req_time () const
 
 void nano::election::send_confirm_req (nano::confirmation_solicitor & solicitor_a)
 {
+	debug_assert (!mutex.try_lock ());
+
 	if (confirm_req_time () < (std::chrono::steady_clock::now () - last_req))
 	{
 		if (!solicitor_a.add (*this))
 		{
 			last_req = std::chrono::steady_clock::now ();
 			++confirmation_request_count;
+
+			node.stats.inc (nano::stat::type::election, nano::stat::detail::confirmation_request);
+			node.logger.debug (nano::log::type::election, "Sent confirmation request for root: {} (behavior: {}, state: {}, voters: {}, blocks: {}, duration: {}ms, confirmation requests: {})",
+			qualified_root.to_string (),
+			to_string (behavior_m),
+			to_string (state_m),
+			status.voter_count,
+			status.block_count,
+			duration ().count (),
+			confirmation_request_count.load ());
 		}
 	}
 }
@@ -196,9 +208,10 @@ bool nano::election::transition_priority ()
 	behavior_m = nano::election_behavior::priority;
 	last_vote = std::chrono::steady_clock::time_point{}; // allow new outgoing votes immediately
 
-	node.logger.debug (nano::log::type::election, "Transitioned election behavior to priority from {} for root: {}",
+	node.logger.debug (nano::log::type::election, "Transitioned election behavior to priority from {} for root: {} (duration: {}ms)",
 	to_string (behavior_m),
-	qualified_root.to_string ());
+	qualified_root.to_string (),
+	duration ().count ());
 
 	return true;
 }
@@ -252,10 +265,18 @@ void nano::election::broadcast_block (nano::confirmation_solicitor & solicitor_a
 	{
 		if (!solicitor_a.broadcast (*this))
 		{
-			node.stats.inc (nano::stat::type::election, last_block_hash.is_zero () ? nano::stat::detail::broadcast_block_initial : nano::stat::detail::broadcast_block_repeat);
-
 			last_block = std::chrono::steady_clock::now ();
 			last_block_hash = status.winner->hash ();
+
+			node.stats.inc (nano::stat::type::election, last_block_hash.is_zero () ? nano::stat::detail::broadcast_block_initial : nano::stat::detail::broadcast_block_repeat);
+			node.logger.debug (nano::log::type::election, "Broadcasting current winner: {} for root: {} (behavior: {}, state: {}, voters: {}, blocks: {}, duration: {}ms)",
+			status.winner->hash ().to_string (),
+			qualified_root.to_string (),
+			to_string (behavior_m),
+			to_string (state_m),
+			status.voter_count,
+			status.block_count,
+			duration ().count ());
 		}
 	}
 }
@@ -536,6 +557,14 @@ nano::vote_code nano::election::vote (nano::account const & rep, uint64_t timest
 	nano::log::arg{ "vote_source", vote_source_a },
 	nano::log::arg{ "weight", weight });
 
+	node.logger.debug (nano::log::type::election, "Vote received for: {} from: {} root: {} (final: {}, weight: {}, source: {})",
+	block_hash_a.to_string (),
+	rep.to_account (),
+	qualified_root.to_string (),
+	nano::vote::is_final_timestamp (timestamp_a),
+	weight.convert_to<std::string> (),
+	to_string (vote_source_a));
+
 	if (!confirmed_locked ())
 	{
 		confirm_if_quorum (lock);

nano/node/node.cpp

@@ -172,7 +172,7 @@ nano::node::node (std::shared_ptr<boost::asio::io_context> io_ctx_a, std::filesy
 	final_generator{ *final_generator_impl },
 	scheduler_impl{ std::make_unique<nano::scheduler::component> (config, *this, ledger, bucketing, block_processor, active, online_reps, vote_cache, confirming_set, stats, logger) },
 	scheduler{ *scheduler_impl },
-	aggregator_impl{ std::make_unique<nano::request_aggregator> (config.request_aggregator, *this, stats, generator, final_generator, history, ledger, wallets, vote_router) },
+	aggregator_impl{ std::make_unique<nano::request_aggregator> (config.request_aggregator, *this, generator, final_generator, history, ledger, wallets, vote_router) },
 	aggregator{ *aggregator_impl },
 	backlog_scan_impl{ std::make_unique<nano::backlog_scan> (config.backlog_scan, ledger, stats) },
 	backlog_scan{ *backlog_scan_impl },