Skip to content

Commit

Permalink
test: add operation_id to log messages (tari-project#3633)
Browse files Browse the repository at this point in the history 
Description
---
Added operation_id to log messages to enable more efficient tracing in log files.

Motivation and Context
---
See above

How Has This Been Tested?
---
`cargo clippy --all-targets -- -D warnings`
  • Loading branch information
@hansieodendaal
hansieodendaal authored Dec 2, 2021
1 parent ddb9268 commit c53be9b
Show file tree
Hide file tree
Showing 2 changed files with 89 additions and 39 deletions.
57 changes: 37 additions & 20 deletions base_layer/wallet/src/output_manager_service/tasks/txo_validation_task.rs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -94,6 +94,10 @@ where
self.update_spent_outputs(&mut base_node_client, last_mined_header)
.await?;
self.publish_event(OutputManagerEvent::TxoValidationSuccess(self.operation_id));
info!(
target: LOG_TARGET,
"Finished TXO validation protocol (Id: {})", self.operation_id,
);
Ok(self.operation_id)
}

Expand All @@ -115,8 +119,9 @@ where
for batch in mined_outputs.chunks(self.config.tx_validator_batch_size) {
debug!(
target: LOG_TARGET,
"Asking base node for status of {} mmr_positions",
batch.len()
"Asking base node for status of {} mmr_positions (Operation ID: {})",
batch.len(),
self.operation_id
);

// We have to send positions to the base node because if the base node cannot find the hash of the output
Expand Down Expand Up @@ -174,10 +179,11 @@ where
.for_protocol(self.operation_id)?;
info!(
target: LOG_TARGET,
"Updating output comm:{}: hash {} as spent at tip height {}",
"Updating output comm:{}: hash {} as spent at tip height {} (Operation ID: {})",
output.commitment.to_hex(),
output.hash.to_hex(),
deleted_bitmap_response.height_of_longest_chain
deleted_bitmap_response.height_of_longest_chain,
self.operation_id
);
}

Expand All @@ -196,10 +202,11 @@ where
.for_protocol(self.operation_id)?;
info!(
target: LOG_TARGET,
"Updating output comm:{}: hash {} as unspent at tip height {}",
"Updating output comm:{}: hash {} as unspent at tip height {} (Operation ID: {})",
output.commitment.to_hex(),
output.hash.to_hex(),
deleted_bitmap_response.height_of_longest_chain
deleted_bitmap_response.height_of_longest_chain,
self.operation_id
);
}
}
Expand All @@ -220,27 +227,30 @@ where
for batch in unconfirmed_outputs.chunks(self.config.tx_validator_batch_size) {
info!(
target: LOG_TARGET,
"Asking base node for location of {} unconfirmed outputs by hash",
batch.len()
"Asking base node for location of {} unconfirmed outputs by hash (Operation ID: {})",
batch.len(),
self.operation_id
);
let (mined, unmined, tip_height) = self
.query_base_node_for_outputs(batch, wallet_client)
.await
.for_protocol(self.operation_id)?;
debug!(
target: LOG_TARGET,
"Base node returned {} outputs as mined and {} outputs as unmined",
"Base node returned {} outputs as mined and {} outputs as unmined (Operation ID: {})",
mined.len(),
unmined.len()
unmined.len(),
self.operation_id
);
for (output, mined_height, mined_in_block, mmr_position) in &mined {
info!(
target: LOG_TARGET,
"Updating output comm:{}: hash {} as mined at height {} with current tip at {}",
"Updating output comm:{}: hash {} as mined at height {} with current tip at {} (Operation ID: {})",
output.commitment.to_hex(),
output.hash.to_hex(),
mined_height,
tip_height
tip_height,
self.operation_id
);
self.update_output_as_mined(output, mined_in_block, *mined_height, *mmr_position, tip_height)
.await?;
Expand All @@ -258,7 +268,7 @@ where
let mut last_mined_header_hash = None;
info!(
target: LOG_TARGET,
"Checking last mined TXO to see if the base node has re-orged"
"Checking last mined TXO to see if the base node has re-orged (Operation ID: {})", self.operation_id
);

while let Some(last_spent_output) = self.db.get_last_spent_output().await.for_protocol(self.operation_id)? {
Expand All @@ -285,8 +295,9 @@ where
warn!(
target: LOG_TARGET,
"The block that output ({}) was spent in has been reorged out, will try to find this output \
again, but these funds have potentially been re-orged out of the chain",
last_spent_output.commitment.to_hex()
again, but these funds have potentially been re-orged out of the chain (Operation ID: {})",
last_spent_output.commitment.to_hex(),
self.operation_id
);
self.db
.mark_output_as_unspent(last_spent_output.hash.clone())
Expand All @@ -295,7 +306,8 @@ where
} else {
info!(
target: LOG_TARGET,
"Last mined transaction is still in the block chain according to base node."
"Last mined transaction is still in the block chain according to base node. (Operation ID: {})",
self.operation_id
);
break;
}
Expand All @@ -321,8 +333,9 @@ where
warn!(
target: LOG_TARGET,
"The block that output ({}) was in has been reorged out, will try to find this output again, but \
these funds have potentially been re-orged out of the chain",
last_mined_output.commitment.to_hex()
these funds have potentially been re-orged out of the chain (Operation ID: {})",
last_mined_output.commitment.to_hex(),
self.operation_id
);
self.db
.set_output_to_unmined(last_mined_output.hash.clone())
Expand All @@ -331,7 +344,8 @@ where
} else {
info!(
target: LOG_TARGET,
"Last mined transaction is still in the block chain according to base node."
"Last mined transaction is still in the block chain according to base node (Operation ID: {}).",
self.operation_id
);
last_mined_header_hash = Some(mined_in_block_hash);
break;
Expand All @@ -350,7 +364,10 @@ where
let result = match client.get_header_by_height(height).await {
Ok(r) => r,
Err(rpc_error) => {
info!(target: LOG_TARGET, "Error asking base node for header:{}", rpc_error);
info!(
target: LOG_TARGET,
"Error asking base node for header:{} (Operation ID: {})", rpc_error, self.operation_id
);
match &rpc_error {
RequestFailed(status) => {
if status.as_status_code().is_not_found() {
Expand Down
71 changes: 52 additions & 19 deletions base_layer/wallet/src/transaction_service/protocols/transaction_validation_protocol.rs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -102,7 +102,7 @@ where
self.check_for_reorgs(&mut *base_node_wallet_client).await?;
info!(
target: LOG_TARGET,
"Checking if transactions have been mined since last we checked"
"Checking if transactions have been mined since last we checked (Operation ID: {})", self.operation_id
);
// Fetch completed but unconfirmed transactions that were not imported
let unconfirmed_transactions = self
Expand All @@ -120,12 +120,19 @@ where
.for_protocol(self.operation_id)?;
info!(
target: LOG_TARGET,
"Base node returned {} as mined and {} as unmined",
"Base node returned {} as mined and {} as unmined (Operation ID: {})",
mined.len(),
unmined.len()
unmined.len(),
self.operation_id
);
for (mined_tx, mined_height, mined_in_block, num_confirmations) in &mined {
info!(target: LOG_TARGET, "Updating transaction {} as mined", mined_tx.tx_id);
info!(
target: LOG_TARGET,
"Updating transaction {} as mined and confirmed '{}' (Operation ID: {})",
mined_tx.tx_id,
*num_confirmations >= self.config.num_confirmations_required,
self.operation_id
);
self.update_transaction_as_mined(
mined_tx.tx_id,
&mined_tx.status,
Expand All @@ -141,7 +148,12 @@ where
// Treat coinbases separately
if unmined_tx.is_coinbase() {
if unmined_tx.coinbase_block_height.unwrap_or_default() <= tip_height {
info!(target: LOG_TARGET, "Updated coinbase {} as abandoned", unmined_tx.tx_id);
info!(
target: LOG_TARGET,
"Updated coinbase {} as abandoned (Operation ID: {})",
unmined_tx.tx_id,
self.operation_id
);
self.update_coinbase_as_abandoned(
unmined_tx.tx_id,
&tip_block,
Expand All @@ -154,15 +166,16 @@ where
info!(
target: LOG_TARGET,
"Coinbase not found, but it is for a block that is not yet in the chain. Coinbase \
height: {}, tip height:{}",
height: {}, tip height:{} (Operation ID: {})",
unmined_tx.coinbase_block_height.unwrap_or_default(),
tip_height
tip_height,
self.operation_id
);
}
} else {
info!(
target: LOG_TARGET,
"Updated transaction {} as unmined", unmined_tx.tx_id
"Updated transaction {} as unmined (Operation ID: {})", unmined_tx.tx_id, self.operation_id
);
self.update_transaction_as_unmined(unmined_tx.tx_id, &unmined_tx.status)
.await?;
Expand Down Expand Up @@ -192,7 +205,8 @@ where
) -> Result<(), TransactionServiceProtocolError> {
info!(
target: LOG_TARGET,
"Checking last mined transactions to see if the base node has re-orged"
"Checking last mined transactions to see if the base node has re-orged (Operation ID: {})",
self.operation_id
);
while let Some(last_mined_transaction) = self
.db
Expand Down Expand Up @@ -229,14 +243,16 @@ where
warn!(
target: LOG_TARGET,
"The block that transaction (excess:{}) was in has been reorged out, will try to find this \
transaction again, but these funds have potentially been re-orged out of the chain",
transaction again, but these funds have potentially been re-orged out of the chain (Operation \
ID: {})",
last_mined_transaction
.transaction
.body
.kernels()
.first()
.map(|k| k.excess.to_hex())
.unwrap()
.unwrap(),
self.operation_id
);
self.update_transaction_as_unmined(last_mined_transaction.tx_id, &last_mined_transaction.status)
.await?;
Expand All @@ -246,7 +262,8 @@ where
} else {
info!(
target: LOG_TARGET,
"Last mined transaction is still in the block chain according to base node."
"Last mined transaction is still in the block chain according to base node (Operation ID: {}).",
self.operation_id
);
break;
}
Expand Down Expand Up @@ -278,14 +295,18 @@ where
}

if batch_signatures.is_empty() {
info!(target: LOG_TARGET, "No transactions needed to query with the base node");
info!(
target: LOG_TARGET,
"No transactions needed to query with the base node (Operation ID: {})", self.operation_id
);
return Ok((mined, unmined, None));
}

info!(
target: LOG_TARGET,
"Asking base node for location of {} transactions by excess signature",
batch_signatures.len()
"Asking base node for location of {} transactions by excess signature (Operation ID: {})",
batch_signatures.len(),
self.operation_id
);

let batch_response = base_node_client
Expand Down Expand Up @@ -334,7 +355,10 @@ where
let result = match client.get_header_by_height(height).await {
Ok(r) => r,
Err(rpc_error) => {
warn!(target: LOG_TARGET, "Error asking base node for header:{}", rpc_error);
warn!(
target: LOG_TARGET,
"Error asking base node for header:{} (Operation ID: {})", rpc_error, self.operation_id
);
match &rpc_error {
RequestFailed(status) => {
if status.as_status_code() == NotFound {
Expand Down Expand Up @@ -391,7 +415,10 @@ where
if let Err(e) = self.output_manager_handle.set_coinbase_abandoned(tx_id, false).await {
warn!(
target: LOG_TARGET,
"Could not mark coinbase output for TxId: {} as not abandoned: {}", tx_id, e
"Could not mark coinbase output for TxId: {} as not abandoned: {} (Operation ID: {})",
tx_id,
e,
self.operation_id
);
};
}
Expand Down Expand Up @@ -422,7 +449,10 @@ where
if let Err(e) = self.output_manager_handle.set_coinbase_abandoned(tx_id, true).await {
warn!(
target: LOG_TARGET,
"Could not mark coinbase output for TxId: {} as abandoned: {}", tx_id, e
"Could not mark coinbase output for TxId: {} as abandoned: {} (Operation ID: {})",
tx_id,
e,
self.operation_id
);
};

Expand All @@ -445,7 +475,10 @@ where
if let Err(e) = self.output_manager_handle.set_coinbase_abandoned(tx_id, false).await {
warn!(
target: LOG_TARGET,
"Could not mark coinbase output for TxId: {} as not abandoned: {}", tx_id, e
"Could not mark coinbase output for TxId: {} as not abandoned: {} (Operation ID: {})",
tx_id,
e,
self.operation_id
);
};
}
Expand Down

0 comments on commit c53be9b

Please sign in to comment.