Skip to content

Commit ae31a78

Browse files
lexnvlexnv
authored
kad: Add query id to log messages (#174)
This tiny PR adds the query ID to some kademlia log messages from the `FIND_NODE` and `GET_RECORDS` commands. Used to provide better debug information and upgrade a few missing states from trace to warn. cc @paritytech/networking --------- Signed-off-by: Alexandru Vasile <[email protected]>
1 parent 8294617 commit ae31a78

File tree

3 files changed

+22
-17
lines changed

3 files changed

+22
-17
lines changed

‎src/protocol/libp2p/kademlia/mod.rs

+10-9
Original file line numberDiff line numberDiff line change
@@ -386,7 +386,7 @@ impl Kademlia {
386386
message: BytesMut,
387387
substream: Substream,
388388
) -> crate::Result<()> {
389-
tracing::trace!(target: LOG_TARGET, ?peer, ?query_id, "handle message from peer");
389+
tracing::trace!(target: LOG_TARGET, ?peer, query = ?query_id, "handle message from peer");
390390

391391
match KademliaMessage::from_bytes(message).ok_or(Error::InvalidData)? {
392392
ref message @ KademliaMessage::FindNode {
@@ -399,6 +399,7 @@ impl Kademlia {
399399
target: LOG_TARGET,
400400
?peer,
401401
?target,
402+
query = ?query_id,
402403
"handle `FIND_NODE` response",
403404
);
404405

@@ -447,7 +448,7 @@ impl Kademlia {
447448
tracing::trace!(
448449
target: LOG_TARGET,
449450
?peer,
450-
?query_id,
451+
query = ?query_id,
451452
?peers,
452453
?record,
453454
"handle `GET_VALUE` response",
@@ -531,7 +532,7 @@ impl Kademlia {
531532
tracing::trace!(
532533
target: LOG_TARGET,
533534
?peer,
534-
?query_id,
535+
query = ?query_id,
535536
?address,
536537
"report failure for pending query",
537538
);
@@ -748,11 +749,11 @@ impl Kademlia {
748749

749750
match result {
750751
QueryResult::SendSuccess { substream } => {
751-
tracing::trace!(target: LOG_TARGET, ?peer, ?query_id, "message sent to peer");
752+
tracing::trace!(target: LOG_TARGET, ?peer, query = ?query_id, "message sent to peer");
752753
let _ = substream.close().await;
753754
}
754755
QueryResult::ReadSuccess { substream, message } => {
755-
tracing::trace!(target: LOG_TARGET, ?peer, ?query_id, "message read from peer");
756+
tracing::trace!(target: LOG_TARGET, ?peer, query = ?query_id, "message read from peer");
756757

757758
if let Err(error) = self.on_message_received(peer, query_id, message, substream).await {
758759
tracing::debug!(target: LOG_TARGET, ?peer, ?error, "failed to process message");
@@ -762,7 +763,7 @@ impl Kademlia {
762763
tracing::debug!(
763764
target: LOG_TARGET,
764765
?peer,
765-
?query_id,
766+
query = ?query_id,
766767
?result,
767768
"failed to read message from substream",
768769
);
@@ -774,7 +775,7 @@ impl Kademlia {
774775
command = self.cmd_rx.recv() => {
775776
match command {
776777
Some(KademliaCommand::FindNode { peer, query_id }) => {
777-
tracing::debug!(target: LOG_TARGET, ?peer, ?query_id, "starting `FIND_NODE` query");
778+
tracing::debug!(target: LOG_TARGET, ?peer, query = ?query_id, "starting `FIND_NODE` query");
778779

779780
self.engine.start_find_node(
780781
query_id,
@@ -783,7 +784,7 @@ impl Kademlia {
783784
);
784785
}
785786
Some(KademliaCommand::PutRecord { mut record, query_id }) => {
786-
tracing::debug!(target: LOG_TARGET, ?query_id, key = ?record.key, "store record to DHT");
787+
tracing::debug!(target: LOG_TARGET, query = ?query_id, key = ?record.key, "store record to DHT");
787788

788789
// For `PUT_VALUE` requests originating locally we are always the publisher.
789790
record.publisher = Some(self.local_key.clone().into_preimage());
@@ -802,7 +803,7 @@ impl Kademlia {
802803
);
803804
}
804805
Some(KademliaCommand::PutRecordToPeers { mut record, query_id, peers, update_local_store }) => {
805-
tracing::debug!(target: LOG_TARGET, ?query_id, key = ?record.key, "store record to DHT to specified peers");
806+
tracing::debug!(target: LOG_TARGET, query = ?query_id, key = ?record.key, "store record to DHT to specified peers");
806807

807808
// Make sure TTL is set.
808809
record.expires = record.expires.or_else(|| Some(Instant::now() + self.record_ttl));

‎src/protocol/libp2p/kademlia/query/find_node.rs

+7-4
Original file line numberDiff line numberDiff line change
@@ -104,7 +104,7 @@ impl<T: Clone + Into<Vec<u8>>> FindNodeContext<T> {
104104
/// Register response failure for `peer`.
105105
pub fn register_response_failure(&mut self, peer: PeerId) {
106106
let Some(peer) = self.pending.remove(&peer) else {
107-
tracing::debug!(target: LOG_TARGET, ?peer, "pending peer doesn't exist");
107+
tracing::debug!(target: LOG_TARGET, query = ?self.config.query, ?peer, "pending peer doesn't exist");
108108
return;
109109
};
110110

@@ -113,9 +113,10 @@ impl<T: Clone + Into<Vec<u8>>> FindNodeContext<T> {
113113

114114
/// Register `FIND_NODE` response from `peer`.
115115
pub fn register_response(&mut self, peer: PeerId, peers: Vec<KademliaPeer>) {
116+
tracing::trace!(target: LOG_TARGET, query = ?self.config.query, ?peer, "received response from peer");
117+
116118
let Some(peer) = self.pending.remove(&peer) else {
117-
tracing::warn!(target: LOG_TARGET, ?peer, "received response from peer but didn't expect it");
118-
debug_assert!(false);
119+
tracing::debug!(target: LOG_TARGET, query = ?self.config.query, ?peer, "received response from peer but didn't expect it");
119120
return;
120121
};
121122

@@ -185,12 +186,14 @@ impl<T: Clone + Into<Vec<u8>>> FindNodeContext<T> {
185186
tracing::trace!(target: LOG_TARGET, query = ?self.config.query, "get next peer");
186187

187188
let (_, candidate) = self.candidates.pop_first()?;
189+
let peer = candidate.peer;
188190

191+
tracing::trace!(target: LOG_TARGET, query = ?self.config.query, ?peer, "current candidate");
189192
self.pending.insert(candidate.peer, candidate.clone());
190193

191194
Some(QueryAction::SendMessage {
192195
query: self.config.query,
193-
peer: candidate.peer,
196+
peer,
194197
message: self.kad_message.clone(),
195198
})
196199
}

‎src/protocol/libp2p/kademlia/query/get_record.rs

+5-4
Original file line numberDiff line numberDiff line change
@@ -135,7 +135,7 @@ impl GetRecordContext {
135135
/// Register response failure for `peer`.
136136
pub fn register_response_failure(&mut self, peer: PeerId) {
137137
let Some(peer) = self.pending.remove(&peer) else {
138-
tracing::trace!(target: LOG_TARGET, ?peer, "pending peer doesn't exist");
138+
tracing::debug!(target: LOG_TARGET, query = ?self.config.query, ?peer, "pending peer doesn't exist");
139139
return;
140140
};
141141

@@ -149,8 +149,10 @@ impl GetRecordContext {
149149
record: Option<Record>,
150150
peers: Vec<KademliaPeer>,
151151
) {
152+
tracing::trace!(target: LOG_TARGET, query = ?self.config.query, ?peer, "received response from peer");
153+
152154
let Some(peer) = self.pending.remove(&peer) else {
153-
tracing::trace!(target: LOG_TARGET, ?peer, "received response from peer but didn't expect it");
155+
tracing::debug!(target: LOG_TARGET, query = ?self.config.query, ?peer, "received response from peer but didn't expect it");
154156
return;
155157
};
156158

@@ -207,10 +209,9 @@ impl GetRecordContext {
207209
tracing::trace!(target: LOG_TARGET, query = ?self.config.query, "get next peer");
208210

209211
let (_, candidate) = self.candidates.pop_first()?;
210-
211212
let peer = candidate.peer;
212213

213-
tracing::trace!(target: LOG_TARGET, ?peer, "current candidate");
214+
tracing::trace!(target: LOG_TARGET, query = ?self.config.query, ?peer, "current candidate");
214215
self.pending.insert(candidate.peer, candidate);
215216

216217
Some(QueryAction::SendMessage {

0 commit comments

Comments
 (0)