From 891218f108cdeab8e1fa4f3c4ebf24f4b76928d2 Mon Sep 17 00:00:00 2001 From: cylewitruk Date: Fri, 10 Jan 2025 10:26:17 +0100 Subject: [PATCH 1/7] logging tweaks for new_block endpoint --- signer/src/api/new_block.rs | 59 ++++++++++++++++++++++++++++++++++--- 1 file changed, 55 insertions(+), 4 deletions(-) diff --git a/signer/src/api/new_block.rs b/signer/src/api/new_block.rs index 8c43c242a..215530ca3 100644 --- a/signer/src/api/new_block.rs +++ b/signer/src/api/new_block.rs @@ -114,7 +114,14 @@ pub async fn new_block_handler(state: State>, body: Strin .into_iter() .filter(|x| x.committed) .filter_map(|x| x.contract_event.map(|ev| (ev, x.txid))) - .filter(|(ev, _)| &ev.contract_identifier == registry_address && ev.topic == "print"); + .filter(|(ev, _)| &ev.contract_identifier == registry_address && ev.topic == "print") + .collect::>(); + + if events.is_empty() { + // If there are no events to process, we return early with a 200 OK + // status code so that the node does not retry the webhook. + return StatusCode::OK; + } let stacks_chaintip = StacksBlock { block_hash: new_block_event.index_block_hash.into(), @@ -124,6 +131,15 @@ pub async fn new_block_handler(state: State>, body: Strin }; let block_id = new_block_event.index_block_hash; + tracing::debug!( + count = %events.len(), + block_hash = %stacks_chaintip.block_hash, + block_height = stacks_chaintip.block_height, + parent_hash = %stacks_chaintip.parent_hash, + bitcoin_anchor = %stacks_chaintip.bitcoin_anchor, + "processing events for new stack block" + ); + // Create vectors to store the processed events for Emily. let mut completed_deposits = Vec::new(); let mut updated_withdrawals = Vec::new(); @@ -240,6 +256,11 @@ pub async fn new_block_handler(state: State>, body: Strin /// - `Result`: On success, returns a `DepositUpdate` struct containing /// information on the completed deposit to be sent to Emily. /// In case of a database error, returns an `Error` +#[tracing::instrument(skip_all, fields( + bitcoin_txid = %event.outpoint.txid, + bitcoin_vout = event.outpoint.vout, + stacks_txid = %event.txid +))] async fn handle_completed_deposit( ctx: &impl Context, event: CompletedDepositEvent, @@ -248,6 +269,9 @@ async fn handle_completed_deposit( ctx.get_storage_mut() .write_completed_deposit_event(&event) .await?; + + tracing::info!("handled completed deposit event"); + // If the deposit request is not found, we don't want to update Emily about it because // we don't have the necessary information to compute the fee. let deposit_request = ctx @@ -292,6 +316,10 @@ async fn handle_completed_deposit( /// - `Result`: On success, returns a `WithdrawalUpdate` struct /// for Emily containing relevant withdrawal information. /// In case of a database error, returns an `Error` +#[tracing::instrument(skip_all, fields( + stacks_txid = %event.txid, + request_id = %event.request_id +))] async fn handle_withdrawal_accept( ctx: &impl Context, event: WithdrawalAcceptEvent, @@ -301,6 +329,8 @@ async fn handle_withdrawal_accept( .write_withdrawal_accept_event(&event) .await?; + tracing::info!("handled withdrawal accept event"); + Ok(WithdrawalUpdate { request_id: event.request_id, status: Status::Confirmed, @@ -329,6 +359,10 @@ async fn handle_withdrawal_accept( /// # Returns /// - `Result`: On success, returns a `CreateWithdrawalRequestBody` /// with withdrawal information. In case of a database error, returns an `Error` +#[tracing::instrument(skip_all, fields( + stacks_txid = %event.txid, + request_id = %event.request_id +))] async fn handle_withdrawal_create( ctx: &impl Context, event: WithdrawalCreateEvent, @@ -338,6 +372,8 @@ async fn handle_withdrawal_create( .write_withdrawal_create_event(&event) .await?; + tracing::debug!("handled withdrawal creation event"); + Ok(CreateWithdrawalRequestBody { amount: event.amount, parameters: Box::new(WithdrawalParameters { max_fee: event.max_fee }), @@ -360,6 +396,10 @@ async fn handle_withdrawal_create( /// # Returns /// - `Result`: Returns a `WithdrawalUpdate` with rejection information. /// In case of a database error, returns an `Error`. +#[tracing::instrument(skip_all, fields( + stacks_txid = %event.txid, + request_id = %event.request_id +))] async fn handle_withdrawal_reject( ctx: &impl Context, event: WithdrawalRejectEvent, @@ -369,6 +409,8 @@ async fn handle_withdrawal_reject( .write_withdrawal_reject_event(&event) .await?; + tracing::info!("handled withdrawal rejection event"); + Ok(WithdrawalUpdate { fulfillment: None, last_update_block_hash: stacks_chaintip.block_hash.to_hex(), @@ -379,6 +421,11 @@ async fn handle_withdrawal_reject( }) } +#[tracing::instrument(skip_all, fields( + %stacks_txid, + address = %event.new_address.to_string(), + aggregate_key = %event.new_aggregate_pubkey +))] async fn handle_key_rotation( ctx: &impl Context, event: KeyRotationEvent, @@ -391,9 +438,13 @@ async fn handle_key_rotation( signer_set: event.new_keys.into_iter().map(Into::into).collect(), signatures_required: event.new_signature_threshold, }; + ctx.get_storage_mut() .write_rotate_keys_transaction(&key_rotation_tx) .await?; + + tracing::info!("handled rotate-keys event"); + Ok(()) } @@ -550,19 +601,19 @@ mod tests { ctx.with_emily_client(|client| { client .expect_update_deposits() - .times(1) + .times(0) .returning(move |_| { Box::pin(async { Ok(UpdateDepositsResponse { deposits: vec![] }) }) }); client .expect_update_withdrawals() - .times(1) + .times(0) .returning(move |_| { Box::pin(async { Ok(UpdateWithdrawalsResponse { withdrawals: vec![] }) }) }); client .expect_create_withdrawals() - .times(1) + .times(0) .returning(move |_| Box::pin(async { vec![] })); }) .await; From 0e785fe4f2f91204c955c291700e075bb22255d2 Mon Sep 17 00:00:00 2001 From: cylewitruk Date: Fri, 10 Jan 2025 10:30:42 +0100 Subject: [PATCH 2/7] fmt lint --- signer/src/api/new_block.rs | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/signer/src/api/new_block.rs b/signer/src/api/new_block.rs index 215530ca3..2e9c5c16b 100644 --- a/signer/src/api/new_block.rs +++ b/signer/src/api/new_block.rs @@ -257,7 +257,7 @@ pub async fn new_block_handler(state: State>, body: Strin /// information on the completed deposit to be sent to Emily. /// In case of a database error, returns an `Error` #[tracing::instrument(skip_all, fields( - bitcoin_txid = %event.outpoint.txid, + bitcoin_txid = %event.outpoint.txid, bitcoin_vout = event.outpoint.vout, stacks_txid = %event.txid ))] @@ -422,7 +422,7 @@ async fn handle_withdrawal_reject( } #[tracing::instrument(skip_all, fields( - %stacks_txid, + %stacks_txid, address = %event.new_address.to_string(), aggregate_key = %event.new_aggregate_pubkey ))] From 00945a19b49a5d432099e8623eca9f3223bb80be Mon Sep 17 00:00:00 2001 From: cylewitruk Date: Fri, 10 Jan 2025 11:18:03 +0100 Subject: [PATCH 3/7] tweaks --- signer/src/api/new_block.rs | 43 +++++++++++++++++++++---------------- 1 file changed, 25 insertions(+), 18 deletions(-) diff --git a/signer/src/api/new_block.rs b/signer/src/api/new_block.rs index 2e9c5c16b..619b0245d 100644 --- a/signer/src/api/new_block.rs +++ b/signer/src/api/new_block.rs @@ -75,9 +75,13 @@ enum UpdateResult { /// fixed number of times. /// /// [^1]: -#[tracing::instrument(skip_all, name = "new-block")] +#[tracing::instrument(skip_all, name = "new-block", fields( + block_hash = tracing::field::Empty, + block_height = tracing::field::Empty, + parent_hash = tracing::field::Empty, + bitcoin_anchor = tracing::field::Empty, +))] pub async fn new_block_handler(state: State>, body: String) -> StatusCode { - tracing::debug!("received a new block event from stacks-core"); metrics::counter!( Metrics::BlocksObservedTotal, "blockchain" => STACKS_BLOCKCHAIN, @@ -106,6 +110,24 @@ pub async fn new_block_handler(state: State>, body: Strin } }; + let stacks_chaintip = StacksBlock { + block_hash: new_block_event.index_block_hash.into(), + block_height: new_block_event.block_height, + parent_hash: new_block_event.parent_index_block_hash.into(), + bitcoin_anchor: new_block_event.burn_block_hash.into(), + }; + let block_id = new_block_event.index_block_hash; + + { + let span = tracing::span::Span::current(); + span.record("block_hash", stacks_chaintip.block_hash.to_hex()); + span.record("block_height", stacks_chaintip.block_height); + span.record("parent_hash", stacks_chaintip.parent_hash.to_hex()); + span.record("bitcoin_anchor", stacks_chaintip.bitcoin_anchor.to_string()); + } + + tracing::debug!("received a new block event from stacks-core"); + // Although transactions can fail, only successful transactions emit // sBTC print events, since those events are emitted at the very end of // the contract call. @@ -123,22 +145,7 @@ pub async fn new_block_handler(state: State>, body: Strin return StatusCode::OK; } - let stacks_chaintip = StacksBlock { - block_hash: new_block_event.index_block_hash.into(), - block_height: new_block_event.block_height, - parent_hash: new_block_event.parent_index_block_hash.into(), - bitcoin_anchor: new_block_event.burn_block_hash.into(), - }; - let block_id = new_block_event.index_block_hash; - - tracing::debug!( - count = %events.len(), - block_hash = %stacks_chaintip.block_hash, - block_height = stacks_chaintip.block_height, - parent_hash = %stacks_chaintip.parent_hash, - bitcoin_anchor = %stacks_chaintip.bitcoin_anchor, - "processing events for new stack block" - ); + tracing::debug!(count = %events.len(), "processing events for new stack block"); // Create vectors to store the processed events for Emily. let mut completed_deposits = Vec::new(); From 7624ebbcc503d7e9c1cae0ba5d5b280b802b5429 Mon Sep 17 00:00:00 2001 From: cylewitruk Date: Mon, 13 Jan 2025 13:04:48 +0100 Subject: [PATCH 4/7] remove scoping around span/record --- signer/src/api/new_block.rs | 12 +++++------- 1 file changed, 5 insertions(+), 7 deletions(-) diff --git a/signer/src/api/new_block.rs b/signer/src/api/new_block.rs index 619b0245d..2a6d6c566 100644 --- a/signer/src/api/new_block.rs +++ b/signer/src/api/new_block.rs @@ -118,13 +118,11 @@ pub async fn new_block_handler(state: State>, body: Strin }; let block_id = new_block_event.index_block_hash; - { - let span = tracing::span::Span::current(); - span.record("block_hash", stacks_chaintip.block_hash.to_hex()); - span.record("block_height", stacks_chaintip.block_height); - span.record("parent_hash", stacks_chaintip.parent_hash.to_hex()); - span.record("bitcoin_anchor", stacks_chaintip.bitcoin_anchor.to_string()); - } + let span = tracing::span::Span::current(); + span.record("block_hash", stacks_chaintip.block_hash.to_hex()); + span.record("block_height", stacks_chaintip.block_height); + span.record("parent_hash", stacks_chaintip.parent_hash.to_hex()); + span.record("bitcoin_anchor", stacks_chaintip.bitcoin_anchor.to_string()); tracing::debug!("received a new block event from stacks-core"); From 7a002b8986ffe52f98ceb40115447da1b5f5fc9e Mon Sep 17 00:00:00 2001 From: cylewitruk Date: Mon, 13 Jan 2025 13:05:25 +0100 Subject: [PATCH 5/7] fix typo --- signer/src/api/new_block.rs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/signer/src/api/new_block.rs b/signer/src/api/new_block.rs index 2a6d6c566..26c884e37 100644 --- a/signer/src/api/new_block.rs +++ b/signer/src/api/new_block.rs @@ -143,7 +143,7 @@ pub async fn new_block_handler(state: State>, body: Strin return StatusCode::OK; } - tracing::debug!(count = %events.len(), "processing events for new stack block"); + tracing::debug!(count = %events.len(), "processing events for new stacks block"); // Create vectors to store the processed events for Emily. let mut completed_deposits = Vec::new(); From fa00743c54a613f750d1c0b336ec67013240a0f3 Mon Sep 17 00:00:00 2001 From: cylewitruk Date: Mon, 13 Jan 2025 13:09:35 +0100 Subject: [PATCH 6/7] use actual event names in a separate tracing field --- signer/src/api/new_block.rs | 10 +++++----- 1 file changed, 5 insertions(+), 5 deletions(-) diff --git a/signer/src/api/new_block.rs b/signer/src/api/new_block.rs index 26c884e37..5c591fff1 100644 --- a/signer/src/api/new_block.rs +++ b/signer/src/api/new_block.rs @@ -275,7 +275,7 @@ async fn handle_completed_deposit( .write_completed_deposit_event(&event) .await?; - tracing::info!("handled completed deposit event"); + tracing::debug!(topic = "completed-deposit", "handled stacks event"); // If the deposit request is not found, we don't want to update Emily about it because // we don't have the necessary information to compute the fee. @@ -334,7 +334,7 @@ async fn handle_withdrawal_accept( .write_withdrawal_accept_event(&event) .await?; - tracing::info!("handled withdrawal accept event"); + tracing::debug!(topic = "withdrawal-accept", "handled stacks event"); Ok(WithdrawalUpdate { request_id: event.request_id, @@ -377,7 +377,7 @@ async fn handle_withdrawal_create( .write_withdrawal_create_event(&event) .await?; - tracing::debug!("handled withdrawal creation event"); + tracing::debug!(topic = "withdrawal-create", "handled stacks event"); Ok(CreateWithdrawalRequestBody { amount: event.amount, @@ -414,7 +414,7 @@ async fn handle_withdrawal_reject( .write_withdrawal_reject_event(&event) .await?; - tracing::info!("handled withdrawal rejection event"); + tracing::debug!(topic = "withdrawal-reject", "handled stacks event"); Ok(WithdrawalUpdate { fulfillment: None, @@ -448,7 +448,7 @@ async fn handle_key_rotation( .write_rotate_keys_transaction(&key_rotation_tx) .await?; - tracing::info!("handled rotate-keys event"); + tracing::debug!(topic = "key-rotation", "handled stacks event"); Ok(()) } From 897386a5bb4309020ae082dbf50de413f52ba047 Mon Sep 17 00:00:00 2001 From: cylewitruk Date: Mon, 13 Jan 2025 13:13:25 +0100 Subject: [PATCH 7/7] use outpoint instead of txid+vout --- signer/src/api/new_block.rs | 3 +-- 1 file changed, 1 insertion(+), 2 deletions(-) diff --git a/signer/src/api/new_block.rs b/signer/src/api/new_block.rs index 5c591fff1..1bd9f555d 100644 --- a/signer/src/api/new_block.rs +++ b/signer/src/api/new_block.rs @@ -262,8 +262,7 @@ pub async fn new_block_handler(state: State>, body: Strin /// information on the completed deposit to be sent to Emily. /// In case of a database error, returns an `Error` #[tracing::instrument(skip_all, fields( - bitcoin_txid = %event.outpoint.txid, - bitcoin_vout = event.outpoint.vout, + bitcoin_outpoint = %event.outpoint, stacks_txid = %event.txid ))] async fn handle_completed_deposit(