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.

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

First pass focusing on warn and info level logging. Couple debugs #4923

Merged
merged 2 commits into from
Jul 9, 2024
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
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
15 changes: 11 additions & 4 deletions stackslib/src/burnchains/affirmation.rs
Original file line number Diff line number Diff line change
Expand Up @@ -974,7 +974,8 @@ pub fn find_heaviest_block_commit<B: BurnchainHeaderReader>(
// found
debug!(
"PoX anchor block-commit {},{},{} has {} burnt, {} confs",
&opdata.txid, opdata.block_height, opdata.vtxindex, most_burnt, most_confs
&opdata.txid, opdata.block_height, opdata.vtxindex, most_burnt, most_confs;
"stacks_block_hash" => opdata.block_header_hash
);

// sanity check -- there should be exactly as many confirmations on the suspected
Expand All @@ -996,19 +997,25 @@ pub fn find_heaviest_block_commit<B: BurnchainHeaderReader>(
if *op_ancestor_height == ancestor_block
&& *op_ancestor_vtxindex == ancestor_vtxindex
{
debug!("Block-commit {},{} descends from likely PoX anchor block {},{}", opdata.block_height, opdata.vtxindex, op_ancestor_height, op_ancestor_vtxindex);
debug!("Block-commit {},{} descends from likely PoX anchor block {},{}", opdata.block_height, opdata.vtxindex, op_ancestor_height, op_ancestor_vtxindex;
"stacks_block_hash" => opdata.block_header_hash
);
block_descendancy.push(true);
if !found_conf {
conf_count += 1;
found_conf = true;
}
burn_count += opdata.burn_fee;
} else {
debug!("Block-commit {},{} does NOT descend from likely PoX anchor block {},{}", opdata.block_height, opdata.vtxindex, ancestor_block, ancestor_vtxindex);
debug!("Block-commit {},{} does NOT descend from likely PoX anchor block {},{}", opdata.block_height, opdata.vtxindex, ancestor_block, ancestor_vtxindex;
"stacks_block_hash" => opdata.block_header_hash
);
block_descendancy.push(false);
}
} else {
debug!("Block-commit {},{} does NOT descend from likely PoX anchor block {},{}", opdata.block_height, opdata.vtxindex, ancestor_block, ancestor_vtxindex);
debug!("Block-commit {},{} does NOT descend from likely PoX anchor block {},{}", opdata.block_height, opdata.vtxindex, ancestor_block, ancestor_vtxindex;
"stacks_block_hash" => opdata.block_header_hash
);
block_descendancy.push(false);
}
}
Expand Down
35 changes: 24 additions & 11 deletions stackslib/src/burnchains/burnchain.rs
Original file line number Diff line number Diff line change
Expand Up @@ -249,8 +249,11 @@ impl BurnchainStateTransition {
for blocks_back in 0..(epoch_id.mining_commitment_window() - 1) {
if parent_snapshot.block_height < (blocks_back as u64) {
debug!("Mining commitment window shortened because block height is less than window size";
"block_height" => %parent_snapshot.block_height,
"window_size" => %epoch_id.mining_commitment_window());
"block_height" => %parent_snapshot.block_height,
"window_size" => %epoch_id.mining_commitment_window(),
"burn_block_hash" => %parent_snapshot.burn_header_hash,
"consensus_hash" => %parent_snapshot.consensus_hash
);
break;
}
let block_height = parent_snapshot.block_height - (blocks_back as u64);
Expand All @@ -275,13 +278,17 @@ impl BurnchainStateTransition {
"Block {} is in a reward phase with PoX. Miner commit window is {}: {:?}",
parent_snapshot.block_height + 1,
windowed_block_commits.len(),
&windowed_block_commits
&windowed_block_commits;
"burn_block_hash" => %parent_snapshot.burn_header_hash,
"consensus_hash" => %parent_snapshot.consensus_hash
);
} else {
// PoX reward-phase is not active, or we're starting a new epoch
debug!(
"Block {} is in a prepare phase, in the post-PoX sunset, or in an epoch transition, so no windowing will take place",
parent_snapshot.block_height + 1
parent_snapshot.block_height + 1;
"burn_block_hash" => %parent_snapshot.burn_header_hash,
"consensus_hash" => %parent_snapshot.consensus_hash
);

assert_eq!(windowed_block_commits.len(), 1);
Expand Down Expand Up @@ -342,7 +349,8 @@ impl BurnchainStateTransition {
for op in all_block_commits.values() {
warn!(
"REJECTED({}) block commit {} at {},{}: Committed to an already-consumed VRF key",
op.block_height, &op.txid, op.block_height, op.vtxindex
op.block_height, &op.txid, op.block_height, op.vtxindex;
"stacks_block_hash" => %op.block_header_hash
);
}

Expand Down Expand Up @@ -1001,7 +1009,8 @@ impl Burnchain {
// duplicate
warn!(
"REJECTED({}) leader key register {} at {},{}: Duplicate VRF key",
data.block_height, &data.txid, data.block_height, data.vtxindex
data.block_height, &data.txid, data.block_height, data.vtxindex;
"consensus_hash" => %data.consensus_hash
);
false
} else {
Expand Down Expand Up @@ -1071,7 +1080,7 @@ impl Burnchain {
"prev_reward_cycle" => %prev_reward_cycle,
"this_reward_cycle" => %this_reward_cycle,
"block_height" => %block_height,
"cycle-length" => %burnchain.pox_constants.reward_cycle_length
"cycle_length" => %burnchain.pox_constants.reward_cycle_length,
);
update_pox_affirmation_maps(burnchain_db, indexer, prev_reward_cycle, burnchain)?;
}
Expand Down Expand Up @@ -1312,7 +1321,8 @@ impl Burnchain {
"Parsed block {} (epoch {}) in {}ms",
burnchain_block.block_height(),
cur_epoch.epoch_id,
parse_end.saturating_sub(parse_start)
parse_end.saturating_sub(parse_start);
"burn_block_hash" => %burnchain_block.block_hash()
);

db_send
Expand Down Expand Up @@ -1350,7 +1360,8 @@ impl Burnchain {
debug!(
"Inserted block {} in {}ms",
burnchain_block.block_height(),
insert_end.saturating_sub(insert_start)
insert_end.saturating_sub(insert_start);
"burn_block_hash" => %burnchain_block.block_hash()
);
}
Ok(last_processed)
Expand Down Expand Up @@ -1647,7 +1658,8 @@ impl Burnchain {
"Parsed block {} (in epoch {}) in {}ms",
burnchain_block.block_height(),
cur_epoch.epoch_id,
parse_end.saturating_sub(parse_start)
parse_end.saturating_sub(parse_start);
"burn_block_hash" => %burnchain_block.block_hash()
);

db_send
Expand Down Expand Up @@ -1699,7 +1711,8 @@ impl Burnchain {
debug!(
"Inserted block {} in {}ms",
burnchain_block.block_height(),
insert_end.saturating_sub(insert_start)
insert_end.saturating_sub(insert_start);
"burn_block_hash" => %burnchain_block.block_hash()
);
}
Ok(last_processed)
Expand Down
16 changes: 9 additions & 7 deletions stackslib/src/burnchains/db.rs
Original file line number Diff line number Diff line change
Expand Up @@ -404,12 +404,12 @@ impl<'a> BurnchainDBTransaction<'a> {
match self.sql_tx.execute(sql, args) {
Ok(_) => {
info!(
"Set anchor block for reward cycle {} to {},{},{},{}",
target_reward_cycle,
&block_commit.burn_header_hash,
&block_commit.txid,
&block_commit.block_height,
&block_commit.vtxindex
"Setting anchor block for reward cycle {target_reward_cycle}.";
"burn_block_hash" => %block_commit.burn_header_hash,
"stacks_block_hash" => %block_commit.block_header_hash,
"block_commit_txid" => %block_commit.txid,
"block_commit_height" => block_commit.block_height,
"block_commit_vtxindex" => block_commit.vtxindex,
);
Ok(())
}
Expand Down Expand Up @@ -1419,7 +1419,9 @@ impl BurnchainDB {
) -> Result<Vec<BlockstackOperationType>, BurnchainError> {
let header = block.header();
debug!("Storing new burnchain block";
"burn_header_hash" => %header.block_hash.to_string());
"burn_block_hash" => %header.block_hash,
"block_height" => header.block_height
);
let mut blockstack_ops =
self.get_blockstack_transactions(burnchain, indexer, block, &header, epoch_id);
apply_blockstack_txs_safety_checks(header.block_height, &mut blockstack_ops);
Expand Down
6 changes: 4 additions & 2 deletions stackslib/src/chainstate/burn/db/processing.rs
Original file line number Diff line number Diff line change
Expand Up @@ -48,7 +48,8 @@ impl<'a> SortitionHandleTx<'a> {
op.check(burnchain, self).map_err(|e| {
warn!(
"REJECTED({}) leader key register {} at {},{}: {:?}",
op.block_height, &op.txid, op.block_height, op.vtxindex, &e
op.block_height, &op.txid, op.block_height, op.vtxindex, &e;
"consensus_hash" => %op.consensus_hash
);
BurnchainError::OpError(e)
})
Expand All @@ -63,7 +64,8 @@ impl<'a> SortitionHandleTx<'a> {
op.vtxindex,
op.parent_block_ptr,
op.parent_vtxindex,
&e
&e;
"stacks_block_hash" => %op.block_header_hash
);
BurnchainError::OpError(e)
})
Expand Down
22 changes: 15 additions & 7 deletions stackslib/src/chainstate/burn/db/sortdb.rs
Original file line number Diff line number Diff line change
Expand Up @@ -1618,8 +1618,10 @@ impl<'a> SortitionHandleTx<'a> {
.map(|ix| {
let recipient = reward_set.rewarded_addresses[ix as usize].clone();
info!("PoX recipient chosen";
"recipient" => recipient.to_burnchain_repr(),
"block_height" => block_height);
"recipient" => recipient.to_burnchain_repr(),
"block_height" => block_height,
"anchor_stacks_block_hash" => &anchor_block,
);
(recipient, u16::try_from(ix).unwrap())
})
.collect(),
Expand Down Expand Up @@ -1651,8 +1653,10 @@ impl<'a> SortitionHandleTx<'a> {
let ix = u16::try_from(ix).unwrap();
let recipient = self.get_reward_set_entry(ix)?;
info!("PoX recipient chosen";
"recipient" => recipient.to_burnchain_repr(),
"block_height" => block_height);
"recipient" => recipient.to_burnchain_repr(),
"block_height" => block_height,
"stacks_block_hash" => %anchor_block
);
recipients.push((recipient, ix));
}
Ok(Some(RewardSetInfo {
Expand Down Expand Up @@ -5532,15 +5536,18 @@ impl<'a> SortitionHandleTx<'a> {
BlockstackOperationType::LeaderKeyRegister(ref op) => {
info!(
"ACCEPTED({}) leader key register {} at {},{}",
op.block_height, &op.txid, op.block_height, op.vtxindex
op.block_height, &op.txid, op.block_height, op.vtxindex;
"consensus_hash" => %op.consensus_hash,
"burn_header_hash" => %op.burn_header_hash
);
self.insert_leader_key(op, sort_id)
}
BlockstackOperationType::LeaderBlockCommit(ref op) => {
info!(
"ACCEPTED({}) leader block commit {} at {},{}",
op.block_height, &op.txid, op.block_height, op.vtxindex;
"apparent_sender" => %op.apparent_sender
"apparent_sender" => %op.apparent_sender,
"stacks_block_hash" => %op.block_header_hash
);
self.insert_block_commit(op, sort_id)
}
Expand All @@ -5561,7 +5568,8 @@ impl<'a> SortitionHandleTx<'a> {
BlockstackOperationType::PreStx(ref op) => {
info!(
"ACCEPTED({}) pre stack stx op {} at {},{}",
op.block_height, &op.txid, op.block_height, op.vtxindex
op.block_height, &op.txid, op.block_height, op.vtxindex;
"burn_header_hash" => %op.burn_header_hash
);
// no need to store this op in the sortition db.
Ok(())
Expand Down
13 changes: 7 additions & 6 deletions stackslib/src/chainstate/burn/sortition.rs
Original file line number Diff line number Diff line change
Expand Up @@ -680,9 +680,10 @@ impl BlockSnapshot {
}

if let Some(reject_winner_reason) = reject_winner_reason {
info!("SORTITION({}): WINNER REJECTED: {}", block_height, &reject_winner_reason;
info!("SORTITION({block_height}): WINNER REJECTED: {reject_winner_reason:?}";
"txid" => %winning_block.txid,
"block_hash" => %winning_block.block_header_hash);
"stacks_block_hash" => %winning_block.block_header_hash,
"burn_block_hash" => %winning_block.burn_header_hash);

// N.B. can't use `make_snapshot_no_sortition()` helper here because then `sort_tx`
// would be mutably borrowed twice.
Expand Down Expand Up @@ -714,10 +715,10 @@ impl BlockSnapshot {
my_pox_id,
)?;

info!(
"SORTITION({}): WINNER IS {:?} (from {:?})",
block_height, &winning_block.block_header_hash, &winning_block.txid
);
info!("SORTITION({block_height}): WINNER SELECTED";
"txid" => %winning_block.txid,
"stacks_block_hash" => %winning_block.block_header_hash,
"burn_block_hash" => %winning_block.burn_header_hash);

let miner_pk_hash = sort_tx
.get_leader_key_at(
Expand Down
Loading