Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

test: add operation_id to log messages #3633

Merged
merged 3 commits into from
Dec 2, 2021
Merged

test: add operation_id to log messages #3633

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
3 commits
Select commit Hold shift + click to select a range
9a5d22a
Add operation_id to log messages
hansieodendaal Nov 30, 2021
eeea909
Merge branch 'development' into h_add_operation_id_log_msg
philipr-za Dec 2, 2021
f9b51e4
Merge branch 'development' into h_add_operation_id_log_msg
aviator-app[bot] Dec 2, 2021
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
57 changes: 37 additions & 20 deletions base_layer/wallet/src/output_manager_service/tasks/txo_validation_task.rs
View file
Open in desktop
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!(
Copy link
Collaborator

Choose a reason for hiding this comment

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

Suggested change
info!(
debug!(

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
Open in desktop
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