From f69f79cc2067086156510b532fa7d5c97a0316de Mon Sep 17 00:00:00 2001
From: =?UTF-8?q?Bastian=20K=C3=B6cher?= <bkchr@users.noreply.github.com>
Date: Thu, 18 Mar 2021 12:16:42 +0100
Subject: [PATCH] Improve logging in network gossip (#8389)
* Improve logging in network gossip
This adds some more information to the logging output to get a better
understanding when something fails.
* Update client/network-gossip/src/state_machine.rs
Co-authored-by: Peter Goodspeed-Niklaus <coriolinus@users.noreply.github.com>
Co-authored-by: Peter Goodspeed-Niklaus <coriolinus@users.noreply.github.com>
---
substrate/Cargo.lock | 1 +
substrate/client/network-gossip/Cargo.toml | 1 +
.../network-gossip/src/state_machine.rs | 69 ++++++++++++++++---
3 files changed, 60 insertions(+), 11 deletions(-)
diff --git a/substrate/Cargo.lock b/substrate/Cargo.lock
index be95ca238f3..100461b2099 100644
--- a/substrate/Cargo.lock
+++ b/substrate/Cargo.lock
@@ -7548,6 +7548,7 @@ dependencies = [
"sp-runtime",
"substrate-prometheus-endpoint",
"substrate-test-runtime-client",
+ "tracing",
"wasm-timer",
]
diff --git a/substrate/client/network-gossip/Cargo.toml b/substrate/client/network-gossip/Cargo.toml
index b5f3b754af0..146bc41cb16 100644
--- a/substrate/client/network-gossip/Cargo.toml
+++ b/substrate/client/network-gossip/Cargo.toml
@@ -24,6 +24,7 @@ prometheus-endpoint = { package = "substrate-prometheus-endpoint", version = "0.
sc-network = { version = "0.9.0", path = "../network" }
sp-runtime = { version = "3.0.0", path = "../../primitives/runtime" }
wasm-timer = "0.2"
+tracing = "0.1.25"
[dev-dependencies]
async-std = "1.6.5"
diff --git a/substrate/client/network-gossip/src/state_machine.rs b/substrate/client/network-gossip/src/state_machine.rs
index a58432d8c24..4c006f288f0 100644
--- a/substrate/client/network-gossip/src/state_machine.rs
+++ b/substrate/client/network-gossip/src/state_machine.rs
@@ -23,7 +23,6 @@ use std::collections::{HashMap, HashSet};
use std::sync::Arc;
use std::iter;
use std::time;
-use log::{debug, error, trace};
use lru::LruCache;
use libp2p::PeerId;
use prometheus_endpoint::{register, Counter, PrometheusError, Registry, U64};
@@ -146,7 +145,13 @@ fn propagate<'a, B: BlockT, I>(
peer.known_messages.insert(message_hash.clone());
- trace!(target: "gossip", "Propagating to {}: {:?}", id, message);
+ tracing::trace!(
+ target: "gossip",
+ to = %id,
+ %protocol,
+ ?message,
+ "Propagating message",
+ );
network.write_notification(id.clone(), protocol.clone(), message.clone());
}
}
@@ -173,7 +178,7 @@ impl<B: BlockT> ConsensusGossip<B> {
let metrics = match metrics_registry.map(Metrics::register) {
Some(Ok(metrics)) => Some(metrics),
Some(Err(e)) => {
- debug!(target: "gossip", "Failed to register metrics: {:?}", e);
+ tracing::debug!(target: "gossip", "Failed to register metrics: {:?}", e);
None
}
None => None,
@@ -197,7 +202,13 @@ impl<B: BlockT> ConsensusGossip<B> {
return;
}
- trace!(target:"gossip", "Registering {:?} {}", role, who);
+ tracing::trace!(
+ target:"gossip",
+ %who,
+ protocol = %self.protocol,
+ ?role,
+ "Registering peer",
+ );
self.peers.insert(who.clone(), PeerConsensus {
known_messages: HashSet::new(),
});
@@ -301,7 +312,10 @@ impl<B: BlockT> ConsensusGossip<B> {
metrics.expired_messages.inc_by(expired_messages as u64)
}
- trace!(target: "gossip", "Cleaned up {} stale messages, {} left ({} known)",
+ tracing::trace!(
+ target: "gossip",
+ protocol = %self.protocol,
+ "Cleaned up {} stale messages, {} left ({} known)",
expired_messages,
self.messages.len(),
known_messages.len(),
@@ -331,14 +345,25 @@ impl<B: BlockT> ConsensusGossip<B> {
let mut to_forward = vec![];
if !messages.is_empty() {
- trace!(target: "gossip", "Received {} messages from peer {}", messages.len(), who);
+ tracing::trace!(
+ target: "gossip",
+ messages_num = %messages.len(),
+ %who,
+ protocol = %self.protocol,
+ "Received messages from peer",
+ );
}
for message in messages {
let message_hash = HashFor::<B>::hash(&message[..]);
if self.known_messages.contains(&message_hash) {
- trace!(target:"gossip", "Ignored already known message from {}", who);
+ tracing::trace!(
+ target: "gossip",
+ %who,
+ protocol = %self.protocol,
+ "Ignored already known message",
+ );
network.report_peer(who.clone(), rep::DUPLICATE_GOSSIP);
continue;
}
@@ -354,7 +379,12 @@ impl<B: BlockT> ConsensusGossip<B> {
ValidationResult::ProcessAndKeep(topic) => (topic, true),
ValidationResult::ProcessAndDiscard(topic) => (topic, false),
ValidationResult::Discard => {
- trace!(target:"gossip", "Discard message from peer {}", who);
+ tracing::trace!(
+ target: "gossip",
+ %who,
+ protocol = %self.protocol,
+ "Discard message from peer",
+ );
continue;
},
};
@@ -362,7 +392,12 @@ impl<B: BlockT> ConsensusGossip<B> {
let peer = match self.peers.get_mut(&who) {
Some(peer) => peer,
None => {
- error!(target:"gossip", "Got message from unregistered peer {}", who);
+ tracing::error!(
+ target: "gossip",
+ %who,
+ protocol = %self.protocol,
+ "Got message from unregistered peer",
+ );
continue;
}
};
@@ -415,7 +450,13 @@ impl<B: BlockT> ConsensusGossip<B> {
peer.known_messages.insert(entry.message_hash.clone());
- trace!(target: "gossip", "Sending topic message to {}: {:?}", who, entry.message);
+ tracing::trace!(
+ target: "gossip",
+ to = %who,
+ protocol = %self.protocol,
+ ?entry.message,
+ "Sending topic message",
+ );
network.write_notification(who.clone(), self.protocol.clone(), entry.message.clone());
}
}
@@ -457,7 +498,13 @@ impl<B: BlockT> ConsensusGossip<B> {
let message_hash = HashFor::<B>::hash(&message);
- trace!(target: "gossip", "Sending direct to {}: {:?}", who, message);
+ tracing::trace!(
+ target: "gossip",
+ to = %who,
+ protocol = %self.protocol,
+ ?message,
+ "Sending direct message",
+ );
peer.known_messages.insert(message_hash);
network.write_notification(who.clone(), self.protocol.clone(), message);
--
GitLab