observability: tracing gum, automatically cross ref traceID (#5079)

* add some gum

* bump expander

* gum

* fix all remaining issues

* last fixup

* Update node/gum/proc-macro/src/lib.rs

Co-authored-by: Bastian Köcher <bkchr@users.noreply.github.com>

* change

* netowrk

* fixins

* chore

* allow optional fmt str + args, prep for expr as kv field

* tracing -> gum rename fallout

* restrict further

* allow multiple levels of field accesses

* another round of docs and a slip of the pen

* update ADR

* fixup lock fiel

* use target: instead of target=

* minors

* fix

* chore

* Update node/gum/README.md

Co-authored-by: Andrei Sandu <54316454+sandreim@users.noreply.github.com>

Co-authored-by: Bastian Köcher <bkchr@users.noreply.github.com>
Co-authored-by: Andrei Sandu <54316454+sandreim@users.noreply.github.com>
This commit is contained in:
Bernhard Schuster
2022-03-15 12:05:16 +01:00
committed by GitHub
parent fa359fd1f7
commit d631f1dea8
130 changed files with 1708 additions and 808 deletions
@@ -8,7 +8,7 @@ edition = "2021"
always-assert = "0.1.2"
futures = "0.3.21"
futures-timer = "3"
tracing = "0.1.32"
gum = { package = "tracing-gum", path = "../../gum" }
sp-core = { git = "https://github.com/paritytech/substrate", branch = "master" }
sp-runtime = { git = "https://github.com/paritytech/substrate", branch = "master" }
@@ -345,7 +345,7 @@ where
// This collation is not in the active-leaves set.
if !state.view.contains(&relay_parent) {
tracing::warn!(
gum::warn!(
target: LOG_TARGET,
?relay_parent,
"distribute collation message parent is outside of our view",
@@ -364,7 +364,7 @@ where
let (our_core, num_cores) = match determine_core(ctx, id, relay_parent).await? {
Some(core) => core,
None => {
tracing::warn!(
gum::warn!(
target: LOG_TARGET,
para_id = %id,
?relay_parent,
@@ -380,7 +380,7 @@ where
determine_our_validators(ctx, runtime, our_core, num_cores, relay_parent).await?;
if current_validators.validators.is_empty() {
tracing::warn!(
gum::warn!(
target: LOG_TARGET,
core = ?our_core,
"there are no validators assigned to core",
@@ -389,7 +389,7 @@ where
return Ok(())
}
tracing::debug!(
gum::debug!(
target: LOG_TARGET,
para_id = %id,
relay_parent = %relay_parent,
@@ -472,7 +472,7 @@ where
.get_session_info_by_index(ctx.sender(), relay_parent, session_index)
.await?
.session_info;
tracing::debug!(target: LOG_TARGET, ?session_index, "Received session info");
gum::debug!(target: LOG_TARGET, ?session_index, "Received session info");
let groups = &info.validator_groups;
let rotation_info = get_group_rotation_info(ctx, relay_parent).await?;
@@ -554,7 +554,7 @@ async fn advertise_collation<Context>(
match (state.collations.get_mut(&relay_parent), should_advertise) {
(None, _) => {
tracing::trace!(
gum::trace!(
target: LOG_TARGET,
?relay_parent,
peer_id = %peer,
@@ -563,7 +563,7 @@ async fn advertise_collation<Context>(
return
},
(_, false) => {
tracing::debug!(
gum::debug!(
target: LOG_TARGET,
?relay_parent,
peer_id = %peer,
@@ -572,7 +572,7 @@ async fn advertise_collation<Context>(
return
},
(Some(collation), true) => {
tracing::debug!(
gum::debug!(
target: LOG_TARGET,
?relay_parent,
peer_id = %peer,
@@ -626,7 +626,7 @@ where
Some(id) if receipt.descriptor.para_id != id => {
// If the ParaId of a collation requested to be distributed does not match
// the one we expect, we ignore the message.
tracing::warn!(
gum::warn!(
target: LOG_TARGET,
para_id = %receipt.descriptor.para_id,
collating_on = %id,
@@ -638,7 +638,7 @@ where
.await?;
},
None => {
tracing::warn!(
gum::warn!(
target: LOG_TARGET,
para_id = %receipt.descriptor.para_id,
"DistributeCollation message while not collating on any",
@@ -647,14 +647,14 @@ where
}
},
ReportCollator(_) => {
tracing::warn!(
gum::warn!(
target: LOG_TARGET,
"ReportCollator message is not expected on the collator side of the protocol",
);
},
NetworkBridgeUpdateV1(event) => {
if let Err(e) = handle_network_msg(ctx, runtime, state, event).await {
tracing::warn!(
gum::warn!(
target: LOG_TARGET,
err = ?e,
"Failed to handle incoming network message",
@@ -686,14 +686,14 @@ async fn send_collation(
};
if let Err(_) = request.send_outgoing_response(response) {
tracing::warn!(target: LOG_TARGET, "Sending collation response failed");
gum::warn!(target: LOG_TARGET, "Sending collation response failed");
}
state.active_collation_fetches.push(
async move {
let r = rx.timeout(MAX_UNSHARED_UPLOAD_TIME).await;
if r.is_none() {
tracing::debug!(
gum::debug!(
target: LOG_TARGET,
?relay_parent,
?peer_id,
@@ -724,7 +724,7 @@ where
match msg {
Declare(_, _, _) => {
tracing::trace!(
gum::trace!(
target: LOG_TARGET,
?origin,
"Declare message is not expected on the collator side of the protocol",
@@ -735,7 +735,7 @@ where
.await;
},
AdvertiseCollation(_) => {
tracing::trace!(
gum::trace!(
target: LOG_TARGET,
?origin,
"AdvertiseCollation message is not expected on the collator side of the protocol",
@@ -753,7 +753,7 @@ where
},
CollationSeconded(relay_parent, statement) => {
if !matches!(statement.unchecked_payload(), Statement::Seconded(_)) {
tracing::warn!(
gum::warn!(
target: LOG_TARGET,
?statement,
?origin,
@@ -769,7 +769,7 @@ where
state.collation_result_senders.remove(&statement.payload().candidate_hash());
if let Some(sender) = removed {
tracing::trace!(
gum::trace!(
target: LOG_TARGET,
?statement,
?origin,
@@ -806,7 +806,7 @@ where
collation.status.advance_to_requested();
(collation.receipt.clone(), collation.pov.clone())
} else {
tracing::warn!(
gum::warn!(
target: LOG_TARGET,
relay_parent = %req.payload.relay_parent,
"received a `RequestCollation` for a relay parent we don't have collation stored.",
@@ -823,7 +823,7 @@ where
state.waiting_collation_fetches.entry(req.payload.relay_parent).or_default();
if !waiting.waiting_peers.insert(req.peer) {
tracing::debug!(
gum::debug!(
target: LOG_TARGET,
"Dropping incoming request as peer has a request in flight already."
);
@@ -840,7 +840,7 @@ where
}
},
Some(our_para_id) => {
tracing::warn!(
gum::warn!(
target: LOG_TARGET,
for_para_id = %req.payload.para_id,
our_para_id = %our_para_id,
@@ -848,7 +848,7 @@ where
);
},
None => {
tracing::warn!(
gum::warn!(
target: LOG_TARGET,
for_para_id = %req.payload.para_id,
"received a `RequestCollation` while not collating on any para",
@@ -896,9 +896,9 @@ where
PeerConnected(peer_id, observed_role, maybe_authority) => {
// If it is possible that a disconnected validator would attempt a reconnect
// it should be handled here.
tracing::trace!(target: LOG_TARGET, ?peer_id, ?observed_role, "Peer connected");
gum::trace!(target: LOG_TARGET, ?peer_id, ?observed_role, "Peer connected");
if let Some(authority_ids) = maybe_authority {
tracing::trace!(
gum::trace!(
target: LOG_TARGET,
?authority_ids,
?peer_id,
@@ -910,16 +910,16 @@ where
}
},
PeerViewChange(peer_id, view) => {
tracing::trace!(target: LOG_TARGET, ?peer_id, ?view, "Peer view change");
gum::trace!(target: LOG_TARGET, ?peer_id, ?view, "Peer view change");
handle_peer_view_change(ctx, state, peer_id, view).await;
},
PeerDisconnected(peer_id) => {
tracing::trace!(target: LOG_TARGET, ?peer_id, "Peer disconnected");
gum::trace!(target: LOG_TARGET, ?peer_id, "Peer disconnected");
state.peer_views.remove(&peer_id);
state.peer_ids.remove(&peer_id);
},
OurViewChange(view) => {
tracing::trace!(target: LOG_TARGET, ?view, "Own view change");
gum::trace!(target: LOG_TARGET, ?view, "Own view change");
handle_our_view_change(state, view).await?;
},
PeerMessage(remote, msg) => {
@@ -936,25 +936,25 @@ where
/// Handles our view changes.
async fn handle_our_view_change(state: &mut State, view: OurView) -> Result<()> {
for removed in state.view.difference(&view) {
tracing::debug!(target: LOG_TARGET, relay_parent = ?removed, "Removing relay parent because our view changed.");
gum::debug!(target: LOG_TARGET, relay_parent = ?removed, "Removing relay parent because our view changed.");
if let Some(collation) = state.collations.remove(removed) {
state.collation_result_senders.remove(&collation.receipt.hash());
match collation.status {
CollationStatus::Created => tracing::warn!(
CollationStatus::Created => gum::warn!(
target: LOG_TARGET,
candidate_hash = ?collation.receipt.hash(),
pov_hash = ?collation.pov.hash(),
"Collation wasn't advertised to any validator.",
),
CollationStatus::Advertised => tracing::debug!(
CollationStatus::Advertised => gum::debug!(
target: LOG_TARGET,
candidate_hash = ?collation.receipt.hash(),
pov_hash = ?collation.pov.hash(),
"Collation was advertised but not requested by any validator.",
),
CollationStatus::Requested => tracing::debug!(
CollationStatus::Requested => gum::debug!(
target: LOG_TARGET,
candidate_hash = ?collation.receipt.hash(),
pov_hash = ?collation.pov.hash(),
@@ -1035,7 +1035,7 @@ where
}
Err(error) => {
let jfyi = error.split().map_err(incoming::Error::from)?;
tracing::debug!(
gum::debug!(
target: LOG_TARGET,
error = ?jfyi,
"Decoding incoming request failed"
@@ -226,7 +226,7 @@ fn test_harness<T: Future<Output = TestHarness>>(
const TIMEOUT: Duration = Duration::from_millis(100);
async fn overseer_send(overseer: &mut VirtualOverseer, msg: CollatorProtocolMessage) {
tracing::trace!(?msg, "sending message");
gum::trace!(?msg, "sending message");
overseer
.send(FromOverseer::Communication { msg })
.timeout(TIMEOUT)
@@ -239,7 +239,7 @@ async fn overseer_recv(overseer: &mut VirtualOverseer) -> AllMessages {
.await
.expect(&format!("{:?} is more than enough to receive messages", TIMEOUT));
tracing::trace!(?msg, "received message");
gum::trace!(?msg, "received message");
msg
}
@@ -248,7 +248,7 @@ async fn overseer_recv_with_timeout(
overseer: &mut VirtualOverseer,
timeout: Duration,
) -> Option<AllMessages> {
tracing::trace!("waiting for message...");
gum::trace!("waiting for message...");
overseer.recv().timeout(timeout).await
}
@@ -56,7 +56,7 @@ pub fn log_error(result: Result<()>, ctx: &'static str) -> std::result::Result<(
match result.into_nested()? {
Ok(()) => Ok(()),
Err(jfyi) => {
tracing::warn!(target: LOG_TARGET, error = ?jfyi, ctx);
gum::warn!(target: LOG_TARGET, error = ?jfyi, ctx);
Ok(())
},
}
@@ -133,7 +133,7 @@ async fn modify_reputation<Context>(ctx: &mut Context, peer: PeerId, rep: Rep)
where
Context: SubsystemContext,
{
tracing::trace!(
gum::trace!(
target: LOG_TARGET,
rep = ?rep,
peer_id = %peer,
@@ -371,7 +371,7 @@ impl ActiveParas {
let (validators, groups, rotation_info, cores) = match (mv, mg, mc) {
(Some(v), Some((g, r)), Some(c)) => (v, g, r, c),
_ => {
tracing::debug!(
gum::debug!(
target: LOG_TARGET,
?relay_parent,
"Failed to query runtime API for relay-parent",
@@ -393,7 +393,7 @@ impl ActiveParas {
cores.get(core_now.0 as usize).and_then(|c| c.para_id())
},
None => {
tracing::trace!(target: LOG_TARGET, ?relay_parent, "Not a validator");
gum::trace!(target: LOG_TARGET, ?relay_parent, "Not a validator");
continue
},
@@ -411,7 +411,7 @@ impl ActiveParas {
let entry = self.current_assignments.entry(para_now).or_default();
*entry += 1;
if *entry == 1 {
tracing::debug!(
gum::debug!(
target: LOG_TARGET,
?relay_parent,
para_id = ?para_now,
@@ -435,7 +435,7 @@ impl ActiveParas {
*occupied.get_mut() -= 1;
if *occupied.get() == 0 {
occupied.remove_entry();
tracing::debug!(
gum::debug!(
target: LOG_TARGET,
para_id = ?cur,
"Unassigned from a parachain",
@@ -533,7 +533,7 @@ impl CollationsPerRelayParent {
// If finished one does not match waiting_collation, then we already dequeued another fetch
// to replace it.
if self.waiting_collation != finished_one {
tracing::trace!(
gum::trace!(
target: LOG_TARGET,
waiting_collation = ?self.waiting_collation,
?finished_one,
@@ -728,7 +728,7 @@ async fn request_collation<Context>(
Context: SubsystemContext<Message = CollatorProtocolMessage>,
{
if !state.view.contains(&relay_parent) {
tracing::debug!(
gum::debug!(
target: LOG_TARGET,
peer_id = %peer_id,
para_id = %para_id,
@@ -739,7 +739,7 @@ async fn request_collation<Context>(
}
let pending_collation = PendingCollation::new(relay_parent, &para_id, &peer_id);
if state.requested_collations.contains_key(&pending_collation) {
tracing::warn!(
gum::warn!(
target: LOG_TARGET,
peer_id = %pending_collation.peer_id,
%pending_collation.para_id,
@@ -768,7 +768,7 @@ async fn request_collation<Context>(
.requested_collations
.insert(PendingCollation::new(relay_parent, &para_id, &peer_id), per_request);
tracing::debug!(
gum::debug!(
target: LOG_TARGET,
peer_id = %peer_id,
%para_id,
@@ -821,7 +821,7 @@ async fn process_incoming_peer_message<Context>(
}
if state.active_paras.is_current(&para_id) {
tracing::debug!(
gum::debug!(
target: LOG_TARGET,
peer_id = ?origin,
?collator_id,
@@ -831,7 +831,7 @@ async fn process_incoming_peer_message<Context>(
peer_data.set_collating(collator_id, para_id);
} else {
tracing::debug!(
gum::debug!(
target: LOG_TARGET,
peer_id = ?origin,
?collator_id,
@@ -840,7 +840,7 @@ async fn process_incoming_peer_message<Context>(
);
modify_reputation(ctx, origin.clone(), COST_UNNEEDED_COLLATOR).await;
tracing::trace!(target: LOG_TARGET, "Disconnecting unneeded collator");
gum::trace!(target: LOG_TARGET, "Disconnecting unneeded collator");
disconnect_peer(ctx, origin).await;
}
},
@@ -850,7 +850,7 @@ async fn process_incoming_peer_message<Context>(
.get(&relay_parent)
.map(|s| s.child("advertise-collation"));
if !state.view.contains(&relay_parent) {
tracing::debug!(
gum::debug!(
target: LOG_TARGET,
peer_id = ?origin,
?relay_parent,
@@ -871,7 +871,7 @@ async fn process_incoming_peer_message<Context>(
match peer_data.insert_advertisement(relay_parent, &state.view) {
Ok((id, para_id)) => {
tracing::debug!(
gum::debug!(
target: LOG_TARGET,
peer_id = ?origin,
%para_id,
@@ -897,7 +897,7 @@ async fn process_incoming_peer_message<Context>(
}
},
Err(error) => {
tracing::debug!(
gum::debug!(
target: LOG_TARGET,
peer_id = ?origin,
?relay_parent,
@@ -910,7 +910,7 @@ async fn process_incoming_peer_message<Context>(
}
},
CollationSeconded(_, _) => {
tracing::warn!(
gum::warn!(
target: LOG_TARGET,
peer_id = ?origin,
"Unexpected `CollationSeconded` message, decreasing reputation",
@@ -976,7 +976,7 @@ where
// declare.
if let Some(para_id) = peer_data.collating_para() {
if !state.active_paras.is_current(&para_id) {
tracing::trace!(target: LOG_TARGET, "Disconnecting peer on view change");
gum::trace!(target: LOG_TARGET, "Disconnecting peer on view change");
disconnect_peer(ctx, peer_id.clone()).await;
}
}
@@ -1040,14 +1040,14 @@ async fn process_msg<Context>(
match msg {
CollateOn(id) => {
tracing::warn!(
gum::warn!(
target: LOG_TARGET,
para_id = %id,
"CollateOn message is not expected on the validator side of the protocol",
);
},
DistributeCollation(_, _, _) => {
tracing::warn!(
gum::warn!(
target: LOG_TARGET,
"DistributeCollation message is not expected on the validator side of the protocol",
);
@@ -1057,7 +1057,7 @@ async fn process_msg<Context>(
},
NetworkBridgeUpdateV1(event) => {
if let Err(e) = handle_network_msg(ctx, state, keystore, event).await {
tracing::warn!(
gum::warn!(
target: LOG_TARGET,
err = ?e,
"Failed to handle incoming network message",
@@ -1075,7 +1075,7 @@ async fn process_msg<Context>(
collations.status = CollationStatus::Seconded;
}
} else {
tracing::debug!(
gum::debug!(
target: LOG_TARGET,
relay_parent = ?parent,
"Collation has been seconded, but the relay parent is deactivated",
@@ -1089,7 +1089,7 @@ async fn process_msg<Context>(
Some(candidate_receipt.commitments_hash) =>
entry.remove().0,
Entry::Occupied(_) => {
tracing::error!(
gum::error!(
target: LOG_TARGET,
relay_parent = ?parent,
candidate = ?candidate_receipt.hash(),
@@ -1150,7 +1150,7 @@ where
res = ctx.recv().fuse() => {
match res {
Ok(FromOverseer::Communication { msg }) => {
tracing::trace!(target: LOG_TARGET, msg = ?msg, "received a message");
gum::trace!(target: LOG_TARGET, msg = ?msg, "received a message");
process_msg(
&mut ctx,
&keystore,
@@ -1170,7 +1170,7 @@ where
}
res = state.collation_fetch_timeouts.select_next_some() => {
let (collator_id, relay_parent) = res;
tracing::debug!(
gum::debug!(
target: LOG_TARGET,
?relay_parent,
?collator_id,
@@ -1233,7 +1233,7 @@ async fn dequeue_next_collation_and_fetch(
.get_mut(&relay_parent)
.and_then(|c| c.get_next_collation_to_fetch(Some(previous_fetch)))
{
tracing::debug!(
gum::debug!(
target: LOG_TARGET,
?relay_parent,
?id,
@@ -1260,7 +1260,7 @@ async fn handle_collation_fetched_result<Context>(
let (candidate_receipt, pov) = match res {
Ok(res) => res,
Err(e) => {
tracing::debug!(
gum::debug!(
target: LOG_TARGET,
relay_parent = ?collation_event.1.relay_parent,
para_id = ?collation_event.1.para_id,
@@ -1277,7 +1277,7 @@ async fn handle_collation_fetched_result<Context>(
if let Some(collations) = state.collations_per_relay_parent.get_mut(&relay_parent) {
if let CollationStatus::Seconded = collations.status {
tracing::debug!(
gum::debug!(
target: LOG_TARGET,
?relay_parent,
"Already seconded - no longer interested in collation fetch result."
@@ -1298,7 +1298,7 @@ async fn handle_collation_fetched_result<Context>(
entry.insert(collation_event);
} else {
tracing::trace!(
gum::trace!(
target: LOG_TARGET,
?relay_parent,
candidate = ?candidate_receipt.hash(),
@@ -1320,7 +1320,7 @@ async fn disconnect_inactive_peers<Context>(
{
for (peer, peer_data) in peers {
if peer_data.is_inactive(&eviction_policy) {
tracing::trace!(target: LOG_TARGET, "Disconnecting inactive peer");
gum::trace!(target: LOG_TARGET, "Disconnecting inactive peer");
disconnect_peer(ctx, peer.clone()).await;
}
}
@@ -1353,7 +1353,7 @@ async fn poll_collation_response(
per_req: &mut PerRequest,
) -> CollationFetchResult {
if never!(per_req.from_collator.is_terminated()) {
tracing::error!(
gum::error!(
target: LOG_TARGET,
"We remove pending responses once received, this should not happen."
);
@@ -1371,7 +1371,7 @@ async fn poll_collation_response(
let result = match response {
Err(RequestError::InvalidResponse(err)) => {
tracing::warn!(
gum::warn!(
target: LOG_TARGET,
hash = ?pending_collation.relay_parent,
para_id = ?pending_collation.para_id,
@@ -1382,7 +1382,7 @@ async fn poll_collation_response(
CollationFetchResult::Error(Some(COST_CORRUPTED_MESSAGE))
},
Err(err) if err.is_timed_out() => {
tracing::debug!(
gum::debug!(
target: LOG_TARGET,
hash = ?pending_collation.relay_parent,
para_id = ?pending_collation.para_id,
@@ -1394,7 +1394,7 @@ async fn poll_collation_response(
CollationFetchResult::Error(None)
},
Err(RequestError::NetworkError(err)) => {
tracing::debug!(
gum::debug!(
target: LOG_TARGET,
hash = ?pending_collation.relay_parent,
para_id = ?pending_collation.para_id,
@@ -1409,7 +1409,7 @@ async fn poll_collation_response(
CollationFetchResult::Error(Some(COST_NETWORK_ERROR))
},
Err(RequestError::Canceled(err)) => {
tracing::debug!(
gum::debug!(
target: LOG_TARGET,
hash = ?pending_collation.relay_parent,
para_id = ?pending_collation.para_id,
@@ -1422,7 +1422,7 @@ async fn poll_collation_response(
Ok(CollationFetchingResponse::Collation(receipt, _))
if receipt.descriptor().para_id != pending_collation.para_id =>
{
tracing::debug!(
gum::debug!(
target: LOG_TARGET,
expected_para_id = ?pending_collation.para_id,
got_para_id = ?receipt.descriptor().para_id,
@@ -1433,7 +1433,7 @@ async fn poll_collation_response(
CollationFetchResult::Error(Some(COST_WRONG_PARA))
},
Ok(CollationFetchingResponse::Collation(receipt, pov)) => {
tracing::debug!(
gum::debug!(
target: LOG_TARGET,
para_id = %pending_collation.para_id,
hash = ?pending_collation.relay_parent,
@@ -1447,7 +1447,7 @@ async fn poll_collation_response(
let result = tx.send((receipt, pov));
if let Err(_) = result {
tracing::warn!(
gum::warn!(
target: LOG_TARGET,
hash = ?pending_collation.relay_parent,
para_id = ?pending_collation.para_id,
@@ -166,7 +166,7 @@ fn test_harness<T: Future<Output = VirtualOverseer>>(test: impl FnOnce(TestHarne
const TIMEOUT: Duration = Duration::from_millis(200);
async fn overseer_send(overseer: &mut VirtualOverseer, msg: CollatorProtocolMessage) {
tracing::trace!("Sending message:\n{:?}", &msg);
gum::trace!("Sending message:\n{:?}", &msg);
overseer
.send(FromOverseer::Communication { msg })
.timeout(TIMEOUT)
@@ -179,7 +179,7 @@ async fn overseer_recv(overseer: &mut VirtualOverseer) -> AllMessages {
.await
.expect(&format!("{:?} is enough to receive messages.", TIMEOUT));
tracing::trace!("Received message:\n{:?}", &msg);
gum::trace!("Received message:\n{:?}", &msg);
msg
}
@@ -188,7 +188,7 @@ async fn overseer_recv_with_timeout(
overseer: &mut VirtualOverseer,
timeout: Duration,
) -> Option<AllMessages> {
tracing::trace!("Waiting for message...");
gum::trace!("Waiting for message...");
overseer.recv().timeout(timeout).await
}
@@ -350,7 +350,7 @@ fn act_on_advertisement() {
let TestHarness { mut virtual_overseer } = test_harness;
let pair = CollatorPair::generate().0;
tracing::trace!("activating");
gum::trace!("activating");
overseer_send(
&mut virtual_overseer,