From d78e2fbf86023790efbc3eb88a2336eb987fb18d Mon Sep 17 00:00:00 2001
From: Arkadiy Paronyan <arkady.paronyan@gmail.com>
Date: Wed, 24 Mar 2021 17:24:54 +0100
Subject: [PATCH] Additional logging (#2693)

---
 .../network/approval-distribution/src/lib.rs  | 78 +++++++++++++++++--
 1 file changed, 73 insertions(+), 5 deletions(-)

diff --git a/polkadot/node/network/approval-distribution/src/lib.rs b/polkadot/node/network/approval-distribution/src/lib.rs
index 21c12df631e..53fba468e3d 100644
--- a/polkadot/node/network/approval-distribution/src/lib.rs
+++ b/polkadot/node/network/approval-distribution/src/lib.rs
@@ -410,6 +410,14 @@ impl State {
 			Some(entry) => entry,
 			None => {
 				if let Some(peer_id) = source.peer_id() {
+					tracing::debug!(
+						target: LOG_TARGET,
+						?source,
+						?peer_id,
+						?block_hash,
+						?validator_index,
+						"Unexpected assignment",
+					);
 					modify_reputation(ctx, peer_id, COST_UNEXPECTED_MESSAGE).await;
 				}
 				return;
@@ -428,11 +436,25 @@ impl State {
 			match entry.known_by.entry(peer_id.clone()) {
 				hash_map::Entry::Occupied(knowledge) => {
 					if knowledge.get().known_messages.contains(&fingerprint) {
+						tracing::debug!(
+							target: LOG_TARGET,
+							?source,
+							?peer_id,
+							?fingerprint,
+							"Duplicate assignment",
+						);
 						modify_reputation(ctx, peer_id, COST_DUPLICATE_MESSAGE).await;
 						return;
 					}
 				}
 				hash_map::Entry::Vacant(_) => {
+					tracing::debug!(
+						target: LOG_TARGET,
+						?source,
+						?peer_id,
+						?fingerprint,
+						"Assignment from unknown peer",
+					);
 					modify_reputation(ctx, peer_id.clone(), COST_UNEXPECTED_MESSAGE).await;
 				}
 			}
@@ -441,6 +463,13 @@ impl State {
 			if entry.knowledge.known_messages.contains(&fingerprint) {
 				modify_reputation(ctx, peer_id.clone(), BENEFIT_VALID_MESSAGE).await;
 				if let Some(peer_knowledge) = entry.known_by.get_mut(&peer_id) {
+					tracing::trace!(
+						target: LOG_TARGET,
+						?source,
+						?peer_id,
+						?fingerprint,
+						"Known assignment",
+					);
 					peer_knowledge.known_messages.insert(fingerprint.clone());
 				}
 				return;
@@ -465,6 +494,14 @@ impl State {
 				}
 			};
 
+			tracing::trace!(
+				target: LOG_TARGET,
+				?source,
+				?peer_id,
+				?fingerprint,
+				?result,
+				"Checked assignment",
+			);
 			match result {
 				AssignmentCheckResult::Accepted => {
 					modify_reputation(ctx, peer_id.clone(), BENEFIT_VALID_MESSAGE_FIRST).await;
@@ -488,11 +525,6 @@ impl State {
 				}
 				AssignmentCheckResult::Bad => {
 					modify_reputation(ctx, peer_id, COST_INVALID_MESSAGE).await;
-					tracing::info!(
-						target: LOG_TARGET,
-						?peer_id,
-						"Got a bad assignment from peer",
-					);
 					return;
 				}
 			}
@@ -599,6 +631,13 @@ impl State {
 			);
 
 			if !entry.knowledge.known_messages.contains(&assignment_fingerprint) {
+				tracing::debug!(
+					target: LOG_TARGET,
+					?source,
+					?peer_id,
+					?fingerprint,
+					"Unknown approval assignment",
+				);
 				modify_reputation(ctx, peer_id, COST_UNEXPECTED_MESSAGE).await;
 				return;
 			}
@@ -606,18 +645,39 @@ impl State {
 			// check if our knowledge of the peer already contains this approval
 			match entry.known_by.entry(peer_id.clone()) {
 				hash_map::Entry::Occupied(knowledge) => {
+					tracing::debug!(
+						target: LOG_TARGET,
+						?source,
+						?peer_id,
+						?fingerprint,
+						"Duplicate approval",
+					);
 					if knowledge.get().known_messages.contains(&fingerprint) {
 						modify_reputation(ctx, peer_id, COST_DUPLICATE_MESSAGE).await;
 						return;
 					}
 				}
 				hash_map::Entry::Vacant(_) => {
+					tracing::debug!(
+						target: LOG_TARGET,
+						?source,
+						?peer_id,
+						?fingerprint,
+						"Approval from unknown peer",
+					);
 					modify_reputation(ctx, peer_id.clone(), COST_UNEXPECTED_MESSAGE).await;
 				}
 			}
 
 			// if the approval is known to be valid, reward the peer
 			if entry.knowledge.known_messages.contains(&fingerprint) {
+				tracing::trace!(
+					target: LOG_TARGET,
+					?source,
+					?peer_id,
+					?fingerprint,
+					"Known approval",
+				);
 				modify_reputation(ctx, peer_id.clone(), BENEFIT_VALID_MESSAGE).await;
 				if let Some(peer_knowledge) = entry.known_by.get_mut(&peer_id) {
 					peer_knowledge.known_messages.insert(fingerprint.clone());
@@ -643,6 +703,14 @@ impl State {
 				}
 			};
 
+			tracing::trace!(
+				target: LOG_TARGET,
+				?source,
+				?peer_id,
+				?fingerprint,
+				?result,
+				"Checked approval",
+			);
 			match result {
 				ApprovalCheckResult::Accepted => {
 					modify_reputation(ctx, peer_id.clone(), BENEFIT_VALID_MESSAGE_FIRST).await;
-- 
GitLab