Skip to content
This repository has been archived by the owner on Nov 15, 2023. It is now read-only.

Collator protocol debug #5129

Merged
merged 7 commits into from
Mar 16, 2022
Merged

Collator protocol debug #5129

Changes from all commits
Commits
Show all changes
7 commits
Select commit Hold shift + click to select a range
af0dd1e
add two more timers
drahnr Mar 15, 2022
6f82ae0
Update node/network/availability-recovery/src/metrics.rs
drahnr Mar 15, 2022
eb61aa4
Try to improve comments spelling
vstakhov Mar 15, 2022
a55a41b
Cargo fmt iteration
vstakhov Mar 15, 2022
0cb75d1
Add some presumably useful debugging for collator protocol
vstakhov Mar 15, 2022
a05e5e3
Merge branch 'master' into vstakhov-collator-protocol-debug
vstakhov Mar 15, 2022
5bed6a9
Address review comments
vstakhov Mar 15, 2022
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
88 changes: 79 additions & 9 deletions node/network/collator-protocol/src/validator_side/mod.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -547,11 +547,11 @@ impl CollationsPerRelayParent {
/// the passed in `finished_one` is the currently `waiting_collation`.
pub fn get_next_collation_to_fetch(
&mut self,
finished_one: Option<CollatorId>,
finished_one: Option<&CollatorId>,
) -> Option<(PendingCollation, CollatorId)> {
// If finished one does not match waiting_collation, then we already dequeued another fetch
// to replace it.
if self.waiting_collation != finished_one {
if self.waiting_collation.as_ref() != finished_one {
gum::trace!(
target: LOG_TARGET,
waiting_collation = ?self.waiting_collation,
Expand Down Expand Up @@ -660,8 +660,26 @@ async fn fetch_collation<Context>(
.collation_fetch_timeouts
.push(timeout(id.clone(), relay_parent.clone()).boxed());

if state.peer_data.get(&peer_id).map_or(false, |d| d.has_advertised(&relay_parent)) {
request_collation(ctx, state, relay_parent, para_id, peer_id, tx).await;
if let Some(peer_data) = state.peer_data.get(&peer_id) {
if peer_data.has_advertised(&relay_parent) {
request_collation(ctx, state, relay_parent, para_id, peer_id, tx).await;
} else {
gum::debug!(
target: LOG_TARGET,
?peer_id,
?para_id,
?relay_parent,
"Collation is not advertised for the relay parent by the peer, do not request it",
);
}
} else {
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This does also trigger if there is no peer data for that peer.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yes, I think this message shoul be on the warn! level as it is quite unlikely.

gum::warn!(
target: LOG_TARGET,
?peer_id,
?para_id,
?relay_parent,
"Requested to fetch a collation from an unknown peer",
);
}

state.collation_fetches.push(rx.map(|r| ((id, pc), r)).boxed());
Expand Down Expand Up @@ -825,17 +843,35 @@ async fn process_incoming_peer_message<Context>(
let peer_data = match state.peer_data.get_mut(&origin) {
Some(p) => p,
None => {
gum::debug!(
target: LOG_TARGET,
peer_id = ?origin,
?para_id,
"Unknown peer",
);
modify_reputation(ctx, origin, COST_UNEXPECTED_MESSAGE).await;
return
},
};

if peer_data.is_collating() {
gum::debug!(
target: LOG_TARGET,
peer_id = ?origin,
?para_id,
"Peer is not in the collating state",
);
modify_reputation(ctx, origin, COST_UNEXPECTED_MESSAGE).await;
return
}

if !signature.verify(&*protocol_v1::declare_signature_payload(&origin), &collator_id) {
gum::debug!(
target: LOG_TARGET,
peer_id = ?origin,
?para_id,
"Signature verification failure",
);
modify_reputation(ctx, origin, COST_INVALID_SIGNATURE).await;
return
}
Expand Down Expand Up @@ -883,6 +919,12 @@ async fn process_incoming_peer_message<Context>(

let peer_data = match state.peer_data.get_mut(&origin) {
None => {
gum::debug!(
target: LOG_TARGET,
peer_id = ?origin,
?relay_parent,
"Advertise collation message has been received from an unknown peer",
);
modify_reputation(ctx, origin, COST_UNEXPECTED_MESSAGE).await;
return
},
Expand All @@ -905,15 +947,31 @@ async fn process_incoming_peer_message<Context>(
state.collations_per_relay_parent.entry(relay_parent).or_default();

match collations.status {
CollationStatus::Fetching | CollationStatus::WaitingOnValidation =>
collations.unfetched_collations.push((pending_collation, id)),
CollationStatus::Fetching | CollationStatus::WaitingOnValidation => {
gum::trace!(
target: LOG_TARGET,
peer_id = ?origin,
%para_id,
?relay_parent,
"Added collation to the pending list"
);
collations.unfetched_collations.push((pending_collation, id));
},
CollationStatus::Waiting => {
collations.status = CollationStatus::Fetching;
collations.waiting_collation = Some(id.clone());

fetch_collation(ctx, state, pending_collation.clone(), id).await;
},
CollationStatus::Seconded => {},
CollationStatus::Seconded => {
gum::trace!(
target: LOG_TARGET,
peer_id = ?origin,
%para_id,
?relay_parent,
"Valid seconded collation"
);
},
}
},
Err(error) => {
Expand Down Expand Up @@ -996,7 +1054,12 @@ where
// declare.
if let Some(para_id) = peer_data.collating_para() {
if !state.active_paras.is_current(&para_id) {
gum::trace!(target: LOG_TARGET, "Disconnecting peer on view change");
gum::trace!(
target: LOG_TARGET,
?peer_id,
?para_id,
"Disconnecting peer on view change (not current parachain id)"
);
disconnect_peer(ctx, peer_id.clone()).await;
}
}
Expand Down Expand Up @@ -1251,7 +1314,7 @@ async fn dequeue_next_collation_and_fetch(
if let Some((next, id)) = state
.collations_per_relay_parent
.get_mut(&relay_parent)
.and_then(|c| c.get_next_collation_to_fetch(Some(previous_fetch)))
.and_then(|c| c.get_next_collation_to_fetch(Some(&previous_fetch)))
{
gum::debug!(
target: LOG_TARGET,
Expand All @@ -1260,6 +1323,13 @@ async fn dequeue_next_collation_and_fetch(
"Successfully dequeued next advertisement - fetching ..."
);
fetch_collation(ctx, state, next, id).await;
} else {
gum::debug!(
target: LOG_TARGET,
?relay_parent,
previous_collator = ?previous_fetch,
"No collations are available to fetch"
);
}
}

Expand Down