From 838f1cccec5d9fae65e6832dcf6fe4cbf3cd3bd6 Mon Sep 17 00:00:00 2001 From: Jack Grigg Date: Tue, 5 Apr 2022 14:55:28 +0000 Subject: [PATCH 1/5] Add trace-level logging to the Orchard wallet This can be enabled with `zcash-cli setlogfilter trace` (or a more specific filter to target just the Orchard wallet trace lines). --- src/rust/src/wallet.rs | 44 +++++++++++++++++++++++++++++++++++++----- 1 file changed, 39 insertions(+), 5 deletions(-) diff --git a/src/rust/src/wallet.rs b/src/rust/src/wallet.rs index 526d07327..8418d7324 100644 --- a/src/rust/src/wallet.rs +++ b/src/rust/src/wallet.rs @@ -253,14 +253,20 @@ impl Wallet { /// the last checkpointed block height (unless the note commitment tree is empty, /// in which case it unconditionally succeeds). This must be called exactly once /// per block. + #[tracing::instrument(level = "trace", skip(self))] pub fn checkpoint(&mut self, block_height: BlockHeight) -> bool { // checkpoints must be in order of sequential block height and every // block must be checkpointed - if self - .last_checkpoint - .map_or(false, |last_height| block_height != last_height + 1) - { - return false; + if let Some(last_height) = self.last_checkpoint { + let expected_height = last_height + 1; + if block_height != expected_height { + tracing::trace!( + "Expected checkpoint height {}, given {}", + expected_height, + block_height + ); + return false; + } } self.witness_tree.checkpoint(); @@ -285,12 +291,15 @@ impl Wallet { /// In the case that no checkpoints exist but the note commitment tree also records no witness /// information, we allow the wallet to continue to rewind, under the assumption that the state /// of the note commitment tree will be overwritten prior to the next append. + #[tracing::instrument(level = "trace", skip(self))] pub fn rewind(&mut self, to_height: BlockHeight) -> Result { if let Some(checkpoint_height) = self.last_checkpoint { if to_height >= checkpoint_height { + tracing::trace!("Last checkpoint is before the rewind height, nothing to do."); return Ok(checkpoint_height); } + tracing::trace!("Rewinding witness tree"); let blocks_to_rewind = ::from(checkpoint_height) - ::from(to_height); let checkpoint_count = self.witness_tree.checkpoints().len(); for _ in 0..blocks_to_rewind { @@ -319,6 +328,7 @@ impl Wallet { } }) .collect(); + tracing::trace!("Retaining notes in transactions {:?}", to_retain); self.mined_notes.retain(|_, v| to_retain.contains(&v.txid)); @@ -345,6 +355,8 @@ impl Wallet { Ok(to_height) } else if self.witness_tree.witnessed_indices().is_empty() { + tracing::trace!("No witnessed notes in tree, allowing rewind without checkpoints"); + // If we have no witnessed notes, it's okay to keep "rewinding" even though // we have no checkpoints. We then allow last_observed to assume the height // to which we have reset the tree state. @@ -363,6 +375,7 @@ impl Wallet { /// incoming viewing keys to the wallet, and return a a data structure that describes /// the actions that are involved with this wallet, either spending notes belonging /// to this wallet or creating new notes owned by this wallet. + #[tracing::instrument(level = "trace", skip(self))] pub fn add_notes_from_bundle( &mut self, txid: &TxId, @@ -400,6 +413,7 @@ impl Wallet { /// - `potential_spend_idxs`: a list of action indices that were previously /// detected as spending our notes. If an index is out of range, `load_bundle` /// will return an error. + #[tracing::instrument(level = "trace", skip(self))] pub fn load_bundle( &mut self, txid: &TxId, @@ -437,6 +451,7 @@ impl Wallet { // Common functionality for add_notes_from_bundle and load_bundle #[allow(clippy::too_many_arguments)] + #[tracing::instrument(level = "trace", skip(self))] fn add_decrypted_note( &mut self, txid: &TxId, @@ -449,6 +464,7 @@ impl Wallet { // Generate the nullifier for the received note and add it to the nullifiers map so // that we can detect when the note is later spent. if let Some(fvk) = self.key_store.viewing_keys.get(&ivk) { + tracing::trace!("Adding decrypted note to the wallet"); let outpoint = OutPoint { txid: *txid, action_idx, @@ -477,6 +493,7 @@ impl Wallet { true } else { + tracing::trace!("Can't add decrypted note to the wallet, missing FVK"); false } } @@ -484,6 +501,7 @@ impl Wallet { /// For each Orchard action in the provided bundle, if the wallet /// is tracking a note corresponding to the action's revealed nullifer, /// mark that note as potentially spent. + #[tracing::instrument(level = "trace", skip(self))] pub fn add_potential_spends( &mut self, txid: &TxId, @@ -512,6 +530,11 @@ impl Wallet { } fn add_potential_spend(&mut self, nf: &Nullifier, inpoint: InPoint) { + tracing::trace!( + "Adding potential spend of nullifier {:?} in {:?}", + nf, + inpoint + ); self.potential_spends .entry(*nf) .or_insert_with(BTreeSet::new) @@ -527,6 +550,7 @@ impl Wallet { /// * `block_tx_idx` - Index of the transaction within the block /// * `txid` - Identifier of the transaction. /// * `bundle` - Orchard component of the transaction. + #[tracing::instrument(level = "trace", skip(self))] pub fn append_bundle_commitments( &mut self, block_height: BlockHeight, @@ -559,6 +583,7 @@ impl Wallet { // update the block height recorded for the transaction let my_notes_for_tx = self.wallet_received_notes.get(txid); if my_notes_for_tx.is_some() { + tracing::trace!("Tx is ours, marking as mined"); self.wallet_note_positions.insert( *txid, NotePositions { @@ -583,6 +608,7 @@ impl Wallet { .and_then(|n| n.decrypted_notes.get(&action_idx)) .is_some() { + tracing::trace!("Witnessing Orchard note ({}, {})", txid, action_idx); let pos = self.witness_tree.witness().expect("tree is not empty"); self.wallet_note_positions .get_mut(txid) @@ -614,12 +640,14 @@ impl Wallet { || self.nullifiers.values().any(|v| v.txid == *txid) } + #[tracing::instrument(level = "trace", skip(self))] pub fn get_filtered_notes( &self, ivk: Option<&IncomingViewingKey>, ignore_mined: bool, require_spending_key: bool, ) -> Vec<(OutPoint, DecryptedNote)> { + tracing::trace!("Filtering notes"); self.wallet_received_notes .iter() .flat_map(|(txid, tx_notes)| { @@ -643,6 +671,7 @@ impl Wallet { { None } else { + tracing::trace!("Selected note at {:?}", outpoint); Some((outpoint, (*dnote).clone())) } }) @@ -660,17 +689,20 @@ impl Wallet { /// /// Returns `None` if the `OutPoint` is not known to the wallet, or the Orchard bundle /// containing the note has not been passed to `Wallet::append_bundle_commitments`. + #[tracing::instrument(level = "trace", skip(self))] pub fn get_spend_info( &self, outpoint: OutPoint, ) -> Result { // TODO: Take `confirmations` parameter and obtain the Merkle path to the root at // that checkpoint, not the latest root. + tracing::trace!("Searching for {:?}", outpoint); let dnote = self .wallet_received_notes .get(&outpoint.txid) .and_then(|tx_notes| tx_notes.decrypted_notes.get(&outpoint.action_idx)) .ok_or(SpendRetrievalError::DecryptedNoteNotFound(outpoint))?; + tracing::trace!("Found decrypted note for outpoint: {:?}", dnote); let fvk = self .key_store @@ -682,12 +714,14 @@ impl Wallet { .get(ivk) .ok_or_else(|| SpendRetrievalError::FvkNotFound(ivk.clone())) })?; + tracing::trace!("Found FVK for note"); let position = self .wallet_note_positions .get(&outpoint.txid) .and_then(|tx_notes| tx_notes.note_positions.get(&outpoint.action_idx)) .ok_or(SpendRetrievalError::NoteNotPositioned(outpoint))?; + tracing::trace!("Found position for note: {:?}", position); assert_eq!( self.witness_tree From b3b54299567f3a8f9ee4d8de6654536a685fa3ff Mon Sep 17 00:00:00 2001 From: Jack Grigg Date: Tue, 5 Apr 2022 18:19:20 +0000 Subject: [PATCH 2/5] wallet: Add assertions during Orchard wallet bundle appends `Wallet::append_bundle_commitments` should never be called twice on the same bundle, as that breaks sequentiality requirements (which we already check for), so it is safe to assert that the inserted values do not overwrite any existing data. --- src/rust/src/wallet.rs | 40 ++++++++++++++++++++++++---------------- 1 file changed, 24 insertions(+), 16 deletions(-) diff --git a/src/rust/src/wallet.rs b/src/rust/src/wallet.rs index 8418d7324..08e87c5df 100644 --- a/src/rust/src/wallet.rs +++ b/src/rust/src/wallet.rs @@ -584,13 +584,16 @@ impl Wallet { let my_notes_for_tx = self.wallet_received_notes.get(txid); if my_notes_for_tx.is_some() { tracing::trace!("Tx is ours, marking as mined"); - self.wallet_note_positions.insert( - *txid, - NotePositions { - tx_height: block_height, - note_positions: BTreeMap::default(), - }, - ); + assert!(self + .wallet_note_positions + .insert( + *txid, + NotePositions { + tx_height: block_height, + note_positions: BTreeMap::default(), + }, + ) + .is_none()); } for (action_idx, action) in bundle.actions().iter().enumerate() { @@ -610,23 +613,28 @@ impl Wallet { { tracing::trace!("Witnessing Orchard note ({}, {})", txid, action_idx); let pos = self.witness_tree.witness().expect("tree is not empty"); - self.wallet_note_positions + assert!(self + .wallet_note_positions .get_mut(txid) .expect("We created this above") .note_positions - .insert(action_idx, pos); + .insert(action_idx, pos) + .is_none()); } // For nullifiers that are ours that we detect as spent by this action, // we will record that input as being mined. if let Some(outpoint) = self.nullifiers.get(action.nullifier()) { - self.mined_notes.insert( - *outpoint, - InPoint { - txid: *txid, - action_idx, - }, - ); + assert!(self + .mined_notes + .insert( + *outpoint, + InPoint { + txid: *txid, + action_idx, + }, + ) + .is_none()); } } From 484edf2cdbafaa8c5f8ab5a38f047f60f2b09ab1 Mon Sep 17 00:00:00 2001 From: Jack Grigg Date: Tue, 5 Apr 2022 18:22:36 +0000 Subject: [PATCH 3/5] wallet: Remove duplicate nullifier insertion into Orchard wallet We have the same insertion a few lines earlier. --- src/rust/src/wallet.rs | 2 -- 1 file changed, 2 deletions(-) diff --git a/src/rust/src/wallet.rs b/src/rust/src/wallet.rs index 08e87c5df..059085265 100644 --- a/src/rust/src/wallet.rs +++ b/src/rust/src/wallet.rs @@ -485,8 +485,6 @@ impl Wallet { .decrypted_notes .insert(action_idx, note_data); - self.nullifiers.insert(nf, outpoint); - // add the association between the address and the IVK used // to decrypt the note self.key_store.add_raw_address(recipient, ivk.clone()); From a06406d0872ea466c16d668df5dd5461847a0514 Mon Sep 17 00:00:00 2001 From: Jack Grigg Date: Fri, 8 Apr 2022 15:43:44 +0000 Subject: [PATCH 4/5] wallet: Bump a trace log message to error in `Wallet::checkpoint` If we hit this error, the node is going to end up with an assertion failure, so there's no verbosity harm in logging here. --- src/rust/src/wallet.rs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/rust/src/wallet.rs b/src/rust/src/wallet.rs index 059085265..45197421f 100644 --- a/src/rust/src/wallet.rs +++ b/src/rust/src/wallet.rs @@ -260,7 +260,7 @@ impl Wallet { if let Some(last_height) = self.last_checkpoint { let expected_height = last_height + 1; if block_height != expected_height { - tracing::trace!( + tracing::error!( "Expected checkpoint height {}, given {}", expected_height, block_height From 70167dd2aab40f14785b9f2dacf15d0385496657 Mon Sep 17 00:00:00 2001 From: Jack Grigg Date: Fri, 8 Apr 2022 15:47:13 +0000 Subject: [PATCH 5/5] rpc: Document that enabling trace-level logging is unsafe --- src/rpc/server.cpp | 3 +++ 1 file changed, 3 insertions(+) diff --git a/src/rpc/server.cpp b/src/rpc/server.cpp index 9ba7e6b00..2b553007d 100644 --- a/src/rpc/server.cpp +++ b/src/rpc/server.cpp @@ -255,6 +255,9 @@ UniValue setlogfilter(const UniValue& params, bool fHelp) + strprintf("\n %s", LogConfigFilter()) + "\n" "\nPassing a valid filter here will replace the existing filter.\n" "Passing an empty string will reset the filter to the default.\n" + "\nNote that enabling trace-level events should always be considered\n" + "unsafe, as they can result in sensitive information like decrypted\n" + "notes and private keys being printed to the log output.\n" "\nArguments:\n" "1. newFilterDirectives (string, required) The new log filter.\n" "\nExamples:\n"