From 3022282bef69864101da675c57916af0bb10b758 Mon Sep 17 00:00:00 2001 From: Jacinta Ferrant Date: Fri, 8 Mar 2024 09:54:30 -0500 Subject: [PATCH] CRC: add helper display for signer and reward cycle Signed-off-by: Jacinta Ferrant --- stacks-signer/src/signer.rs | 411 ++++++++++-------------------------- 1 file changed, 112 insertions(+), 299 deletions(-) diff --git a/stacks-signer/src/signer.rs b/stacks-signer/src/signer.rs index 6ac16664ec4..b03a2da366b 100644 --- a/stacks-signer/src/signer.rs +++ b/stacks-signer/src/signer.rs @@ -166,6 +166,16 @@ pub struct Signer { pub signer_db: SignerDb, } +impl std::fmt::Display for Signer { + fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result { + write!( + f, + "Reward Cycle #{} Signer #{}", + self.reward_cycle, self.signer_id, + ) + } +} + impl From for Signer { fn from(signer_config: SignerConfig) -> Self { let stackerdb = StackerDB::from(&signer_config); @@ -267,32 +277,24 @@ impl Signer { }) { Ok(last_round) => last_round, Err(e) => { - error!("Reward cycle #{} Signer #{}: Unable to perform DKG. Failed to get last round from stacks node: {e:?}", self.reward_cycle, self.signer_id); + error!("{self}: Unable to perform DKG. Failed to get last round from stacks node: {e:?}"); return; } }; // The dkg id will increment internally following "start_dkg_round" so do not increment it here self.coordinator.current_dkg_id = vote_round.unwrap_or(0); info!( - "Reward cycle #{} Signer #{}: Starting DKG vote", - self.reward_cycle, - self.signer_id; + "{self}: Starting DKG vote"; "round" => self.coordinator.current_dkg_id.wrapping_add(1), "cycle" => self.reward_cycle, ); match self.coordinator.start_dkg_round() { Ok(msg) => { let ack = self.stackerdb.send_message_with_retry(msg.into()); - debug!( - "Reward cycle #{} Signer #{}: ACK: {ack:?}", - self.reward_cycle, self.signer_id - ); + debug!("{self}: ACK: {ack:?}",); } Err(e) => { - error!( - "Reward cycle #{} Signer #{}: Failed to start DKG: {e:?}", - self.reward_cycle, self.signer_id - ); + error!("{self}: Failed to start DKG: {e:?}",); return; } } @@ -303,7 +305,7 @@ impl Signer { merkle_root, } => { if self.approved_aggregate_public_key.is_none() { - debug!("Reward cycle #{} Signer #{}: Cannot sign a block without an approved aggregate public key. Ignore it.", self.reward_cycle, self.signer_id); + debug!("{self}: Cannot sign a block without an approved aggregate public key. Ignore it."); return; } let signer_signature_hash = block.header.signer_signature_hash(); @@ -313,10 +315,10 @@ impl Signer { .unwrap_or_else(|_| Some(BlockInfo::new(block.clone()))) .unwrap_or_else(|| BlockInfo::new(block.clone())); if block_info.signed_over { - debug!("Reward cycle #{} Signer #{}: Received a sign command for a block we are already signing over. Ignore it.", self.reward_cycle, self.signer_id); + debug!("{self}: Received a sign command for a block we are already signing over. Ignore it."); return; } - info!("Reward cycle #{} Signer #{}: Signing block", self.reward_cycle, self.signer_id; + info!("{self}: Signing block"; "block_consensus_hash" => %block.header.consensus_hash, "block_height" => block.header.chain_length, "pre_sign_block_id" => %block.block_id(), @@ -328,22 +330,16 @@ impl Signer { ) { Ok(msg) => { let ack = self.stackerdb.send_message_with_retry(msg.into()); - debug!( - "Reward cycle #{} Signer #{}: ACK: {ack:?}", - self.reward_cycle, self.signer_id - ); + debug!("{self}: ACK: {ack:?}",); block_info.signed_over = true; self.signer_db .insert_block(&block_info) .unwrap_or_else(|e| { - error!("Failed to insert block in DB: {e:?}"); + error!("{self}: Failed to insert block in DB: {e:?}"); }); } Err(e) => { - error!( - "Reward cycle #{} Signer #{}: Failed to start signing block: {e:?}", - self.reward_cycle, self.signer_id - ); + error!("{self}: Failed to start signing block: {e:?}",); return; } } @@ -359,28 +355,19 @@ impl Signer { State::Idle => { if coordinator_id != self.signer_id { debug!( - "Reward cycle #{} Signer #{}: Coordinator is {coordinator_id:?}. Will not process any commands...", - self.reward_cycle, - self.signer_id + "{self}: Coordinator is {coordinator_id:?}. Will not process any commands...", ); return; } if let Some(command) = self.commands.pop_front() { self.execute_command(stacks_client, &command); } else { - debug!( - "Reward cycle #{} Signer #{}: Nothing to process. Waiting for command...", - self.reward_cycle, self.signer_id - ); + debug!("{self}: Nothing to process. Waiting for command...",); } } State::OperationInProgress => { // We cannot execute the next command until the current one is finished... - debug!( - "Reward cycle #{} Signer #{}: Waiting for coordinator {coordinator_id:?} operation to finish...", - self.reward_cycle, - self.signer_id, - ); + debug!("{self}: Waiting for coordinator {coordinator_id:?} operation to finish...",); } } } @@ -400,14 +387,11 @@ impl Signer { Ok(Some(block_info)) => block_info, Ok(None) => { // We have not seen this block before. Why are we getting a response for it? - debug!("Reward Cycle #{} Signer #{}: Received a block validate response for a block we have not seen before. Ignoring...", self.reward_cycle, self.signer_id); + debug!("{self}: Received a block validate response for a block we have not seen before. Ignoring..."); return; } Err(e) => { - error!( - "Rewrad Cycle #{} Signer #{}: Failed to lookup block in signer db: {:?}", - self.reward_cycle, self.signer_id, e - ); + error!("{self}: Failed to lookup block in signer db: {e:?}",); return; } }; @@ -415,11 +399,9 @@ impl Signer { block_info.valid = Some(is_valid); self.signer_db .insert_block(&block_info) - .expect("Failed to insert block in DB"); + .expect(&format!("{self}: Failed to insert block in DB")); info!( - "Reward cycle #{} Signer #{}: Treating block validation for block {} as valid: {:?}", - self.reward_cycle, - self.signer_id, + "{self}: Treating block validation for block {} as valid: {:?}", &block_info.block.block_id(), block_info.valid ); @@ -431,43 +413,31 @@ impl Signer { Ok(Some(block_info)) => block_info, Ok(None) => { // We have not seen this block before. Why are we getting a response for it? - debug!("Reward Cycle #{} Signer #{}: Received a block validate response for a block we have not seen before. Ignoring...", self.reward_cycle, self.signer_id); + debug!("{self}: Received a block validate response for a block we have not seen before. Ignoring..."); return; } Err(e) => { - error!( - "Reward Cycle #{} Signer #{}: Failed to lookup block in signer db: {:?}", - self.reward_cycle, self.signer_id, e - ); + error!("{self}: Failed to lookup block in signer db: {e:?}"); return; } }; block_info.valid = Some(false); // Submit a rejection response to the .signers contract for miners // to observe so they know to send another block and to prove signers are doing work); - warn!("Reward cycle #{} Signer #{}: Broadcasting a block rejection due to stacks node validation failure...", self.reward_cycle, self.signer_id); + warn!("{self}: Broadcasting a block rejection due to stacks node validation failure..."); if let Err(e) = self .stackerdb .send_message_with_retry(block_validate_reject.clone().into()) { - warn!( - "Reward cycle #{} Signer #{}: Failed to send block rejection to stacker-db: {e:?}", - self.reward_cycle, - self.signer_id - ); + warn!("{self}: Failed to send block rejection to stacker-db: {e:?}",); } block_info } }; if let Some(mut nonce_request) = block_info.nonce_request.take() { - debug!("Reward cycle #{} Signer #{}: Received a block validate response from the stacks node for a block we already received a nonce request for. Responding to the nonce request...", self.reward_cycle, self.signer_id); + debug!("{self}: Received a block validate response from the stacks node for a block we already received a nonce request for. Responding to the nonce request..."); // We have received validation from the stacks node. Determine our vote and update the request message - Self::determine_vote( - self.signer_id, - self.reward_cycle, - &mut block_info, - &mut nonce_request, - ); + self.determine_vote(&mut block_info, &mut nonce_request); // Send the nonce request through with our vote let packet = Packet { msg: Message::NonceRequest(nonce_request), @@ -482,9 +452,7 @@ impl Signer { { // We are the coordinator. Trigger a signing round for this block debug!( - "Reward cycle #{} Signer #{}: triggering a signing round over the block {}", - self.reward_cycle, - self.signer_id, + "{self}: triggering a signing round over the block {}", block_info.block.header.block_hash() ); self.commands.push_back(Command::Sign { @@ -494,7 +462,7 @@ impl Signer { }); } else { debug!( - "Reward cycle #{} Signer #{} ignoring block.", self.reward_cycle, self.signer_id; + "{self}: ignoring block."; "block_hash" => block_info.block.header.block_hash(), "valid" => block_info.valid, "signed_over" => block_info.signed_over, @@ -504,7 +472,7 @@ impl Signer { } self.signer_db .insert_block(&block_info) - .expect("Failed to insert block in DB"); + .expect(&format!("{self}: Failed to insert block in DB")); } /// Handle signer messages submitted to signers stackerdb @@ -535,16 +503,13 @@ impl Signer { self.signer_db .insert_block(&BlockInfo::new(block.clone())) .unwrap_or_else(|e| { - error!("Failed to insert block in DB: {e:?}"); + error!("{self}: Failed to insert block in DB: {e:?}"); }); // Submit the block for validation stacks_client .submit_block_for_validation(block.clone()) .unwrap_or_else(|e| { - warn!( - "Reward cycle #{} Signer #{}: Failed to submit block for validation: {e:?}", - self.reward_cycle, self.signer_id - ); + warn!("{self}: Failed to submit block for validation: {e:?}"); }); } } @@ -561,11 +526,7 @@ impl Signer { .signing_round .process_inbound_messages(packets) .unwrap_or_else(|e| { - error!( - "Reward cycle #{} Signer #{}: Failed to process inbound messages as a signer: {e:?}", - self.reward_cycle, - self.signer_id - ); + error!("{self}: Failed to process inbound messages as a signer: {e:?}",); vec![] }); @@ -574,11 +535,7 @@ impl Signer { .coordinator .process_inbound_messages(packets) .unwrap_or_else(|e| { - error!( - "Reward cycle #{} Signer #{}: Failed to process inbound messages as a coordinator: {e:?}", - self.reward_cycle, - self.signer_id - ); + error!("{self}: Failed to process inbound messages as a coordinator: {e:?}"); (vec![], vec![]) }); @@ -604,9 +561,7 @@ impl Signer { else { // We currently reject anything that is not a block vote debug!( - "Reward cycle #{} Signer #{}: Received a signature share request for an unknown message stream. Reject it.", - self.reward_cycle, - self.signer_id + "{self}: Received a signature share request for an unknown message stream. Reject it.", ); return false; }; @@ -614,15 +569,12 @@ impl Signer { match self .signer_db .block_lookup(&block_vote.signer_signature_hash) - .expect("Failed to connect to signer DB") + .expect(&format!("{self}: Failed to connect to DB")) .map(|b| b.vote) { Some(Some(vote)) => { // Overwrite with our agreed upon value in case another message won majority or the coordinator is trying to cheat... - debug!( - "Reward cycle #{} Signer #{}: set vote for {} to {vote:?}", - self.reward_cycle, self.signer_id, block_vote.rejected - ); + debug!("{self}: set vote for {} to {vote:?}", block_vote.rejected); request.message = vote.serialize_to_vec(); true } @@ -630,14 +582,16 @@ impl Signer { // We never agreed to sign this block. Reject it. // This can happen if the coordinator received enough votes to sign yes // or no on a block before we received validation from the stacks node. - debug!("Reward cycle #{} Signer #{}: Received a signature share request for a block we never agreed to sign. Ignore it.", self.reward_cycle, self.signer_id); + debug!("{self}: Received a signature share request for a block we never agreed to sign. Ignore it."); false } None => { // We will only sign across block hashes or block hashes + b'n' byte for // blocks we have seen a Nonce Request for (and subsequent validation) // We are missing the context here necessary to make a decision. Reject the block - debug!("Reward cycle #{} Signer #{}: Received a signature share request from an unknown block. Reject it.", self.reward_cycle, self.signer_id); + debug!( + "{self}: Received a signature share request from an unknown block. Reject it." + ); false } } @@ -655,11 +609,7 @@ impl Signer { let Some(block): Option = read_next(&mut &nonce_request.message[..]).ok() else { // We currently reject anything that is not a block - debug!( - "Reward cycle #{} Signer #{}: Received a nonce request for an unknown message stream. Reject it.", - self.reward_cycle, - self.signer_id - ); + debug!("{self}: Received a nonce request for an unknown message stream. Reject it.",); return false; }; let signer_signature_hash = block.header.signer_signature_hash(); @@ -670,19 +620,15 @@ impl Signer { { Some(block_info) => block_info, None => { - debug!("Reward Cycle #{} Signer #{}: We have received a block sign request for a block we have not seen before. Cache the nonce request and submit the block for validation...", self.reward_cycle, self.signer_id); + debug!("{self}: We have received a block sign request for a block we have not seen before. Cache the nonce request and submit the block for validation..."); let block_info = BlockInfo::new_with_request(block.clone(), nonce_request.clone()); self.signer_db .insert_block(&block_info) - .expect("Failed to insert block in DB"); + .expect(&format!("{self}: Failed to insert block in DB")); stacks_client .submit_block_for_validation(block) .unwrap_or_else(|e| { - warn!( - "Reward Cycle #{} Signer #{}: Failed to submit block for validation: {e:?}", - self.reward_cycle, - self.signer_id - ); + warn!("{self}: Failed to submit block for validation: {e:?}",); }); return false; } @@ -690,20 +636,15 @@ impl Signer { if block_info.valid.is_none() { // We have not yet received validation from the stacks node. Cache the request and wait for validation - debug!("Reward cycle #{} Signer #{}: We have yet to receive validation from the stacks node for a nonce request. Cache the nonce request and wait for block validation...", self.reward_cycle, self.signer_id); + debug!("{self}: We have yet to receive validation from the stacks node for a nonce request. Cache the nonce request and wait for block validation..."); block_info.nonce_request = Some(nonce_request.clone()); return false; } - Self::determine_vote( - self.signer_id, - self.reward_cycle, - &mut block_info, - nonce_request, - ); + self.determine_vote(&mut block_info, nonce_request); self.signer_db .insert_block(&block_info) - .expect("Failed to insert block in DB"); + .expect(&format!("{self}: Failed to insert block in DB")); true } @@ -716,7 +657,7 @@ impl Signer { if self.approved_aggregate_public_key.is_some() { // We do not enforce a block contain any transactions except the aggregate votes when it is NOT already set // TODO: should be only allow special cased transactions during prepare phase before a key is set? - debug!("Reward cycle #{} Signer #{}: Already have an aggregate key for reward cycle {}. Skipping transaction verification...", self.reward_cycle, self.signer_id, self.reward_cycle); + debug!("{self}: Already have an aggregate key. Skipping transaction verification..."); return true; } if let Ok(expected_transactions) = self.get_expected_transactions(stacks_client) { @@ -727,27 +668,17 @@ impl Signer { .into_iter() .filter_map(|tx| { if !block_tx_hashset.contains(&tx.txid()) { - debug!( - "Reward cycle #{} Signer #{}: expected txid {} is in the block", - self.reward_cycle, - self.signer_id, - &tx.txid() - ); + debug!("{self}: expected txid {} is in the block", &tx.txid()); Some(tx) } else { - debug!( - "Reward cycle #{} Signer #{}: missing expected txid {}", - self.reward_cycle, - self.signer_id, - &tx.txid() - ); + debug!("{self}: missing expected txid {}", &tx.txid()); None } }) .collect::>(); let is_valid = missing_transactions.is_empty(); if !is_valid { - debug!("Reward cycle #{} Signer #{}: Broadcasting a block rejection due to missing expected transactions...", self.reward_cycle, self.signer_id); + debug!("{self}: Broadcasting a block rejection due to missing expected transactions..."); let block_rejection = BlockRejection::new( block.header.signer_signature_hash(), RejectCode::MissingTransactions(missing_transactions), @@ -757,21 +688,13 @@ impl Signer { .stackerdb .send_message_with_retry(block_rejection.into()) { - warn!( - "Reward cycle #{} Signer #{}: Failed to send block rejection to stacker-db: {e:?}", - self.reward_cycle, - self.signer_id - ); + warn!("{self}: Failed to send block rejection to stacker-db: {e:?}",); } } is_valid } else { // Failed to connect to the stacks node to get transactions. Cannot validate the block. Reject it. - debug!( - "Reward cycle #{} Signer #{}: Broadcasting a block rejection due to signer connectivity issues...", - self.reward_cycle, - self.signer_id - ); + debug!("{self}: Broadcasting a block rejection due to signer connectivity issues...",); let block_rejection = BlockRejection::new( block.header.signer_signature_hash(), RejectCode::ConnectivityIssues, @@ -781,11 +704,7 @@ impl Signer { .stackerdb .send_message_with_retry(block_rejection.into()) { - warn!( - "Reward cycle #{} Signer #{}: Failed to send block submission to stacker-db: {e:?}", - self.reward_cycle, - self.signer_id - ); + warn!("{self}: Failed to send block submission to stacker-db: {e:?}",); } false } @@ -816,10 +735,7 @@ impl Signer { stacks_client: &StacksClient, ) -> Result, ClientError> { if self.next_signer_slot_ids.is_empty() { - debug!( - "Reward cycle #{} Signer #{}: No next signers. Skipping transaction retrieval.", - self.reward_cycle, self.signer_id - ); + debug!("{self}: No next signers. Skipping transaction retrieval.",); return Ok(vec![]); } // Get all the account nonces for the next signers @@ -839,27 +755,12 @@ impl Signer { } /// Determine the vote for a block and update the block info and nonce request accordingly - fn determine_vote( - signer_id: u32, - reward_cycle: u64, - block_info: &mut BlockInfo, - nonce_request: &mut NonceRequest, - ) { + fn determine_vote(&self, block_info: &mut BlockInfo, nonce_request: &mut NonceRequest) { let rejected = !block_info.valid.unwrap_or(false); if rejected { - debug!( - "Reward cycle #{} Signer #{}: Rejecting block {}", - reward_cycle, - signer_id, - block_info.block.block_id() - ); + debug!("{self}: Rejecting block {}", block_info.block.block_id()); } else { - debug!( - "Reward cycle #{} Signer #{}: Accepting block {}", - reward_cycle, - signer_id, - block_info.block.block_id() - ); + debug!("{self}: Accepting block {}", block_info.block.block_id()); } let block_vote = NakamotoBlockVote { signer_signature_hash: block_info.block.header.signer_signature_hash(), @@ -902,8 +803,8 @@ impl Signer { Some(packet) } else { debug!( - "Reward cycle #{} Signer #{}: Failed to verify wsts packet with {}: {packet:?}", - self.reward_cycle, self.signer_id, coordinator_public_key + "{self}: Failed to verify wsts packet with {}: {packet:?}", + coordinator_public_key ); None } @@ -920,30 +821,21 @@ impl Signer { // Signers only every trigger non-taproot signing rounds over blocks. Ignore SignTaproot results match operation_result { OperationResult::Sign(signature) => { - debug!( - "Reward cycle #{} Signer #{}: Received signature result", - self.reward_cycle, self.signer_id - ); + debug!("{self}: Received signature result"); self.process_signature(signature); } OperationResult::SignTaproot(_) => { - debug!("Reward cycle #{} Signer #{}: Received a signature result for a taproot signature. Nothing to broadcast as we currently sign blocks with a FROST signature.", self.reward_cycle, self.signer_id); + debug!("{self}: Received a signature result for a taproot signature. Nothing to broadcast as we currently sign blocks with a FROST signature."); } OperationResult::Dkg(dkg_public_key) => { self.process_dkg(stacks_client, dkg_public_key); } OperationResult::SignError(e) => { - warn!( - "Reward cycle #{} Signer #{}: Received a Sign error: {e:?}", - self.reward_cycle, self.signer_id - ); + warn!("{self}: Received a Sign error: {e:?}"); self.process_sign_error(e); } OperationResult::DkgError(e) => { - warn!( - "Reward cycle #{} Signer #{}: Received a DKG error: {e:?}", - self.reward_cycle, self.signer_id - ); + warn!("{self}: Received a DKG error: {e:?}"); // TODO: process these errors and track malicious signers to report } } @@ -959,11 +851,7 @@ impl Signer { }) .unwrap_or(StacksEpochId::Epoch24); let tx_fee = if epoch < StacksEpochId::Epoch30 { - debug!( - "Reward cycle #{} Signer #{}: in pre Epoch 3.0 cycles, must set a transaction fee for the DKG vote.", - self.reward_cycle, - self.signer_id - ); + debug!("{self}: in pre Epoch 3.0 cycles, must set a transaction fee for the DKG vote."); Some(self.tx_fee_ustx) } else { None @@ -978,10 +866,7 @@ impl Signer { .map_err(backoff::Error::transient) }) .map_err(|e| { - warn!( - "Reward cycle #{} Signer #{}: Unable to get signer transactions: {e:?}", - self.reward_cycle, self.signer_id - ); + warn!("{self}: Unable to get signer transactions: {e:?}"); }) .unwrap_or_default(); // If we have a transaction in the stackerdb slot, we need to increment the nonce hence the +1, else should use the account nonce @@ -1005,17 +890,13 @@ impl Signer { new_transaction, ) { warn!( - "Reward cycle #{} Signer #{}: Failed to broadcast DKG public key vote ({dkg_public_key:?}): {e:?}", - self.reward_cycle, - self.signer_id + "{self}: Failed to broadcast DKG public key vote ({dkg_public_key:?}): {e:?}" ); } } Err(e) => { warn!( - "Reward cycle #{} Signer #{}: Failed to build DKG public key vote ({dkg_public_key:?}) transaction: {e:?}.", - self.reward_cycle, - self.signer_id + "{self}: Failed to build DKG public key vote ({dkg_public_key:?}) transaction: {e:?}." ); } } @@ -1034,11 +915,7 @@ impl Signer { .get_account_nonce(address) .map_err(backoff::Error::transient) }) else { - warn!( - "Reward cycle #{} Signer #{}: Unable to get account nonce for address: {address}.", - self.reward_cycle, - self.signer_id - ); + warn!("{self}: Unable to get account nonce for address: {address}."); continue; }; account_nonces.insert(*address, account_nonce); @@ -1058,33 +935,25 @@ impl Signer { if self.approved_aggregate_public_key.is_some() { // We do not enforce a block contain any transactions except the aggregate votes when it is NOT already set info!( - "Reward cycle #{} Signer #{}: Already has an approved aggregate key. Do not broadcast the transaction ({txid:?}).", - self.reward_cycle, self.signer_id + "{self}: Already has an approved aggregate key. Do not broadcast the transaction ({txid:?})." ); return Ok(()); } if epoch >= StacksEpochId::Epoch30 { - debug!("Reward cycle #{} Signer #{}: Received a DKG result while in epoch 3.0. Broadcast the transaction only to stackerDB.", self.reward_cycle, self.signer_id); + debug!("{self}: Received a DKG result while in epoch 3.0. Broadcast the transaction only to stackerDB."); } else if epoch == StacksEpochId::Epoch25 { - debug!("Reward cycle #{} Signer #{}: Received a DKG result while in epoch 2.5. Broadcast the transaction to the mempool.", self.reward_cycle, self.signer_id); + debug!("{self}: Received a DKG result while in epoch 2.5. Broadcast the transaction to the mempool."); stacks_client.submit_transaction(&new_transaction)?; - info!( - "Reward cycle #{} Signer #{}: Submitted DKG vote transaction ({txid:?}) to the mempool", - self.reward_cycle, - self.signer_id - ); + info!("{self}: Submitted DKG vote transaction ({txid:?}) to the mempool"); } else { - debug!("Reward cycle #{} Signer #{}: Received a DKG result, but are in an unsupported epoch. Do not broadcast the transaction ({}).", self.reward_cycle, self.signer_id, new_transaction.txid()); + debug!("{self}: Received a DKG result, but are in an unsupported epoch. Do not broadcast the transaction ({}).", new_transaction.txid()); return Ok(()); } // For all Pox-4 epochs onwards, broadcast the results also to stackerDB for other signers/miners to observe signer_transactions.push(new_transaction); let signer_message = SignerMessage::Transactions(signer_transactions); self.stackerdb.send_message_with_retry(signer_message)?; - info!( - "Reward cycle #{} Signer #{}: Broadcasted DKG vote transaction ({txid}) to stacker DB", - self.reward_cycle, self.signer_id, - ); + info!("{self}: Broadcasted DKG vote transaction ({txid}) to stacker DB"); Ok(()) } @@ -1094,18 +963,14 @@ impl Signer { // Deserialize the signature result and broadcast an appropriate Reject or Approval message to stackerdb let message = self.coordinator.get_message(); let Some(block_vote): Option = read_next(&mut &message[..]).ok() else { - debug!( - "Reward cycle #{} Signer #{}: Received a signature result for a non-block. Nothing to broadcast.", - self.reward_cycle, - self.signer_id - ); + debug!("{self}: Received a signature result for a non-block. Nothing to broadcast."); return; }; // TODO: proper garbage collection...This is currently our only cleanup of blocks self.signer_db .remove_block(&block_vote.signer_signature_hash) - .expect("Failed to remove block from to signer DB"); + .expect(&format!("{self}: Failed to remove block from to signer DB")); let block_submission = if block_vote.rejected { // We signed a rejection message. Return a rejection message @@ -1116,15 +981,9 @@ impl Signer { }; // Submit signature result to miners to observe - debug!( - "Reward cycle #{} Signer #{}: submit block response {block_submission:?}", - self.reward_cycle, self.signer_id - ); + debug!("{self}: submit block response {block_submission:?}"); if let Err(e) = self.stackerdb.send_message_with_retry(block_submission) { - warn!( - "Reward cycle #{} Signer #{}: Failed to send block submission to stacker-db: {e:?}", - self.reward_cycle, self.signer_id - ); + warn!("{self}: Failed to send block submission to stacker-db: {e:?}"); } } @@ -1140,19 +999,17 @@ impl Signer { else { // This is not a block vote either. We cannot process this error debug!( - "Reward Cycle #{} Signer #{}: Received a signature error for a non-block. Nothing to broadcast.", - self.reward_cycle, - self.signer_id + "{self}: Received a signature error for a non-block. Nothing to broadcast." ); return; }; let Some(block_info) = self .signer_db .block_lookup(&block_vote.signer_signature_hash) - .expect("Failed to connect to signer DB") + .expect(&format!("{self}: Failed to connect to signer DB")) else { debug!( - "Reward Cycle #{} Signer #{}: Received a signature result for a block we have not seen before. Ignoring...", self.reward_cycle, self.signer_id + "{self}: Received a signature result for a block we have not seen before. Ignoring..." ); return; }; @@ -1160,20 +1017,13 @@ impl Signer { }); let block_rejection = BlockRejection::new(block.header.signer_signature_hash(), RejectCode::from(e)); - debug!( - "Reward cycle #{} Signer #{}: Broadcasting block rejection: {block_rejection:?}", - self.reward_cycle, self.signer_id - ); + debug!("{self}: Broadcasting block rejection: {block_rejection:?}"); // Submit signature result to miners to observe if let Err(e) = self .stackerdb .send_message_with_retry(block_rejection.into()) { - warn!( - "Reward cycle #{} Signer #{}: Failed to send block rejection submission to stacker-db: {e:?}", - self.reward_cycle, - self.signer_id - ); + warn!("{self}: Failed to send block rejection submission to stacker-db: {e:?}"); } } @@ -1186,17 +1036,10 @@ impl Signer { let nmb_results = operation_results.len(); match res.send(operation_results) { Ok(_) => { - debug!( - "Reward cycle #{} Signer #{}: Successfully sent {} operation result(s)", - self.reward_cycle, self.signer_id, nmb_results - ) + debug!("{self}: Successfully sent {nmb_results} operation result(s)") } Err(e) => { - warn!( - "Reward cycle #{} Signer #{}: Failed to send {nmb_results} operation results: {e:?}", - self.reward_cycle, - self.signer_id - ); + warn!("{self}: Failed to send {nmb_results} operation results: {e:?}"); } } } @@ -1204,24 +1047,15 @@ impl Signer { /// Sending all provided packets through stackerdb with a retry fn send_outbound_messages(&mut self, outbound_messages: Vec) { debug!( - "Reward cycle #{} Signer #{}: Sending {} messages to other stacker-db instances.", - self.reward_cycle, - self.signer_id, + "{self}: Sending {} messages to other stacker-db instances.", outbound_messages.len() ); for msg in outbound_messages { let ack = self.stackerdb.send_message_with_retry(msg.into()); if let Ok(ack) = ack { - debug!( - "Reward cycle #{} Signer #{}: send outbound ACK: {ack:?}", - self.reward_cycle, self.signer_id - ); + debug!("{self}: send outbound ACK: {ack:?}"); } else { - warn!( - "Reward cycle #{} Signer #{}: Failed to send message to stacker-db instance: {ack:?}", - self.reward_cycle, - self.signer_id - ); + warn!("{self}: Failed to send message to stacker-db instance: {ack:?}"); } } } @@ -1239,34 +1073,30 @@ impl Signer { .set_aggregate_public_key(self.approved_aggregate_public_key); // We have an approved aggregate public key. Do nothing further debug!( - "Reward cycle #{} Signer #{}: Have updated DKG value to {:?}.", - self.reward_cycle, self.signer_id, self.approved_aggregate_public_key + "{self}: Have updated DKG value to {:?}.", + self.approved_aggregate_public_key ); return Ok(()); }; let coordinator_id = self.coordinator_selector.get_coordinator().0; if self.signer_id == coordinator_id && self.state == State::Idle { - debug!( - "Reward cycle #{} Signer #{}: Checking if old vote transaction exists in StackerDB...", - self.reward_cycle, - self.signer_id - ); + debug!("{self}: Checking if old vote transaction exists in StackerDB..."); // Have I already voted and have a pending transaction? Check stackerdb for the same round number and reward cycle vote transaction // Only get the account nonce of THIS signer as we only care about our own votes, not other signer votes let signer_address = stacks_client.get_signer_address(); let account_nonces = self.get_account_nonces(stacks_client, &[*signer_address]); let old_transactions = self.get_signer_transactions(&account_nonces).map_err(|e| { - warn!("Reward cycle #{} Signer #{}: Failed to get old signer transactions: {e:?}. May trigger DKG unnecessarily", self.reward_cycle, self.signer_id); + warn!("{self}: Failed to get old signer transactions: {e:?}. May trigger DKG unnecessarily"); }).unwrap_or_default(); // Check if we have an existing vote transaction for the same round and reward cycle for transaction in old_transactions.iter() { let params = - NakamotoSigners::parse_vote_for_aggregate_public_key(transaction).unwrap_or_else(|| panic!("BUG: Signer #{}: Received an invalid {SIGNERS_VOTING_FUNCTION_NAME} transaction in an already filtered list: {transaction:?}", self.signer_id)); + NakamotoSigners::parse_vote_for_aggregate_public_key(transaction).unwrap_or_else(|| panic!("BUG: {self}: Received an invalid {SIGNERS_VOTING_FUNCTION_NAME} transaction in an already filtered list: {transaction:?}")); if Some(params.aggregate_key) == self.coordinator.aggregate_public_key && params.voting_round == self.coordinator.current_dkg_id && reward_cycle == self.reward_cycle { - debug!("Reward cycle #{} Signer #{}: Not triggering a DKG round. Already have a pending vote transaction.", self.reward_cycle, self.signer_id; + debug!("{self}: Not triggering a DKG round. Already have a pending vote transaction."; "txid" => %transaction.txid(), "aggregate_key" => %params.aggregate_key, "voting_round" => params.voting_round @@ -1284,11 +1114,11 @@ impl Signer { { // TODO Check if the vote failed and we need to retrigger the DKG round not just if we have already voted... // TODO need logic to trigger another DKG round if a certain amount of time passes and we still have no confirmed DKG vote - debug!("Reward cycle #{} Signer #{}: Not triggering a DKG round. Already voted and we may need to wait for more votes to arrive.", self.reward_cycle, self.signer_id); + debug!("{self}: Not triggering a DKG round. Already voted and we may need to wait for more votes to arrive."); return Ok(()); } if self.commands.front() != Some(&Command::Dkg) { - info!("Reward cycle #{} Signer #{} is the current coordinator and must trigger DKG. Queuing DKG command...", self.reward_cycle, self.signer_id); + info!("{self} is the current coordinator and must trigger DKG. Queuing DKG command..."); self.commands.push_front(Command::Dkg); } } @@ -1303,28 +1133,19 @@ impl Signer { res: Sender>, current_reward_cycle: u64, ) -> Result<(), ClientError> { - debug!( - "Reward cycle #{} Signer #{}: Processing event: {event:?}", - self.reward_cycle, self.signer_id - ); + debug!("{self}: Processing event: {event:?}"); match event { Some(SignerEvent::BlockValidationResponse(block_validate_response)) => { - debug!( - "Reward cycle #{} Signer #{}: Received a block proposal result from the stacks node...", - self.reward_cycle, - self.signer_id - ); + debug!("{self}: Received a block proposal result from the stacks node..."); self.handle_block_validate_response(stacks_client, block_validate_response, res) } Some(SignerEvent::SignerMessages(signer_set, messages)) => { if *signer_set != self.stackerdb.get_signer_set() { - debug!("Reward cycle #{} Signer #{}: Received a signer message for a reward cycle that does not belong to this signer. Ignoring...", self.reward_cycle, self.signer_id); + debug!("{self}: Received a signer message for a reward cycle that does not belong to this signer. Ignoring..."); return Ok(()); } debug!( - "Reward cycle #{} Signer #{}: Received {} messages from the other signers...", - self.reward_cycle, - self.signer_id, + "{self}: Received {} messages from the other signers...", messages.len() ); self.handle_signer_messages(stacks_client, res, messages); @@ -1332,29 +1153,21 @@ impl Signer { Some(SignerEvent::ProposedBlocks(blocks)) => { if current_reward_cycle != self.reward_cycle { // There is not point in processing blocks if we are not the current reward cycle (we can never actually contribute to signing these blocks) - debug!("Reward cycle #{} Signer #{}: Received a proposed block, but this signer's reward cycle is not the current one ({}). Ignoring...", self.reward_cycle, self.signer_id, current_reward_cycle); + debug!("{self}: Received a proposed block, but this signer's reward cycle is not the current one ({current_reward_cycle}). Ignoring..."); return Ok(()); } debug!( - "Reward cycle #{} Signer #{}: Received {} block proposals from the miners...", - self.reward_cycle, - self.signer_id, + "{self}: Received {} block proposals from the miners...", blocks.len() ); self.handle_proposed_blocks(stacks_client, blocks); } Some(SignerEvent::StatusCheck) => { - debug!( - "Reward cycle #{} Signer #{}: Received a status check event.", - self.reward_cycle, self.signer_id - ) + debug!("{self}: Received a status check event.") } None => { // No event. Do nothing. - debug!( - "Reward cycle #{} Signer #{}: No event received", - self.reward_cycle, self.signer_id - ) + debug!("{self}: No event received") } } Ok(())