validator: improved log targets

src/validator/consensus/pid.rs

@@ -18,6 +18,7 @@
 
 use darkfi_sdk::{blockchain::Slot, pasta::pallas};
 use lazy_static::lazy_static;
+use log::debug;
 
 use super::float_10::{
     fbig2base, Float10, FLOAT10_NEG_ONE, FLOAT10_NEG_TWO, FLOAT10_ONE, FLOAT10_TWO, FLOAT10_ZERO,
@@ -33,6 +34,10 @@ lazy_static! {
     static ref MAX_F: Float10 = Float10::try_from("0.99").unwrap();
     static ref MIN_F: Float10 = Float10::try_from("0.01").unwrap();
     static ref EPSILON: Float10 = Float10::try_from("1").unwrap();
+    // PID controller K values based on constants
+    static ref K1: Float10 = KP.clone() + KI.clone() + KD.clone();
+    static ref K2: Float10 = FLOAT10_NEG_ONE.clone() * KP.clone() + FLOAT10_NEG_TWO.clone() * KD.clone();
+    static ref K3: Float10 = KD.clone();
 }
 
 /// Return 2-term target approximation sigma coefficients,
@@ -48,34 +53,33 @@ pub fn slot_pid_output(
         Float10::try_from(previous_slot.total_tokens + previous_slot.reward).unwrap();
     let (sigma1, sigma2) = calculate_sigmas(f.clone(), total_tokens);
 
-    // TODO: log values
-
     (f.to_f64(), error.to_f64(), sigma1, sigma2)
 }
 
 /// Calculate the inverse probability `f` of becoming a block producer (winning the lottery)
 /// having all the tokens, and the feedback error, represented as Float10.
 fn calculate_f(previous_slot: &Slot, previous_producers: u64) -> (Float10, Float10) {
-    // PID controller K values based on constants
-    let k1 = KP.clone() + KI.clone() + KD.clone();
-    let k2 = FLOAT10_NEG_ONE.clone() * KP.clone() + FLOAT10_NEG_TWO.clone() * KD.clone();
-    let k3 = KD.clone();
-
     // Convert slot values to Float10
     let previous_slot_f = Float10::try_from(previous_slot.pid.f).unwrap();
+    debug!(target: "validator::consensus::pid::calculate_f", "Previous slot f: {previous_slot_f}");
     let previous_slot_error = Float10::try_from(previous_slot.pid.error).unwrap();
+    debug!(target: "validator::consensus::pid::calculate_f", "Previous slot error: {previous_slot_error}");
     let previous_slot_previous_slot_error =
         Float10::try_from(previous_slot.previous.error).unwrap();
+    debug!(target: "validator::consensus::pid::calculate_f", "Previous slot previous slot error: {previous_slot_previous_slot_error}");
 
     // Calculate feedback error based on previous block producers.
     let feedback = Float10::try_from(previous_producers).unwrap();
+    debug!(target: "validator::consensus::pid::calculate_f", "Feedback: {feedback}");
     let error = FLOAT10_ONE.clone() - feedback;
+    debug!(target: "validator::consensus::pid::calculate_f", "Error: {error}");
 
     // Calculate f
     let mut f = previous_slot_f +
-        k1 * error.clone() +
-        k2 * previous_slot_error +
-        k3 * previous_slot_previous_slot_error;
+        K1.clone() * error.clone() +
+        K2.clone() * previous_slot_error +
+        K3.clone() * previous_slot_previous_slot_error;
+    debug!(target: "validator::consensus::pid::calculate_f", "Ounbounded f: {f}");
 
     // Boundaries control
     if f <= *FLOAT10_ZERO {
@@ -83,6 +87,7 @@ fn calculate_f(previous_slot: &Slot, previous_producers: u64) -> (Float10, Float
     } else if f >= *FLOAT10_ONE {
         f = MAX_F.clone()
     }
+    debug!(target: "validator::consensus::pid::calculate_f", "Bounded f: {f}");
 
     (f, error)
 }
@@ -94,15 +99,18 @@ fn calculate_sigmas(f: Float10, total_tokens: Float10) -> (pallas::Base, pallas:
     let x = FLOAT10_ONE.clone() - f;
     let c = x.ln();
     let neg_c = FLOAT10_NEG_ONE.clone() * c;
+    debug!(target: "validator::consensus::pid::calculate_sigmas", "neg_c: {neg_c}");
 
     // Calculate sigma 1
     let sigma1_fbig = neg_c.clone() / (total_tokens.clone() + EPSILON.clone()) * FIELD_P.clone();
     let sigma1 = fbig2base(sigma1_fbig);
+    debug!(target: "validator::consensus::pid::calculate_sigmas", "Sigma 1: {sigma1:?}");
 
     // Calculate sigma 2
     let sigma2_fbig = (neg_c / (total_tokens + EPSILON.clone())).powf(FLOAT10_TWO.clone()) *
         (FIELD_P.clone() / FLOAT10_TWO.clone());
     let sigma2 = fbig2base(sigma2_fbig);
+    debug!(target: "validator::consensus::pid::calculate_sigmas", "Sigma 2: {sigma2:?}");
 
     (sigma1, sigma2)
 }

src/validator/mod.rs

@@ -88,10 +88,10 @@ pub struct Validator {
 
 impl Validator {
     pub async fn new(db: &sled::Db, config: ValidatorConfig) -> Result<ValidatorPtr> {
-        info!(target: "validator", "Initializing Validator");
+        info!(target: "validator::new", "Initializing Validator");
         let testing_mode = config.testing_mode;
 
-        info!(target: "validator", "Initializing Blockchain");
+        info!(target: "validator::new", "Initializing Blockchain");
         let blockchain = Blockchain::new(db)?;
 
         // Create an overlay over whole blockchain so we can write stuff
@@ -102,7 +102,7 @@ impl Validator {
 
         // Add genesis block if blockchain is empty
         if blockchain.genesis().is_err() {
-            info!(target: "validator", "Appending genesis block");
+            info!(target: "validator::new", "Appending genesis block");
             verify_genesis_block(
                 &overlay,
                 &config.time_keeper,
@@ -115,13 +115,13 @@ impl Validator {
         // Write the changes to the actual chain db
         overlay.lock().unwrap().overlay.lock().unwrap().apply()?;
 
-        info!(target: "validator", "Initializing Consensus");
+        info!(target: "validator::new", "Initializing Consensus");
         let consensus = Consensus::new(blockchain.clone(), config.time_keeper);
 
         // Create the actual state
         let state =
             Arc::new(RwLock::new(Self { blockchain, consensus, synced: false, testing_mode }));
-        info!(target: "validator", "Finished initializing validator");
+        info!(target: "validator::new", "Finished initializing validator");
 
         Ok(state)
     }
@@ -136,12 +136,12 @@ impl Validator {
         let tx_in_pending_txs_store = self.blockchain.pending_txs.contains(&tx_hash)?;
 
         if tx_in_txstore || tx_in_pending_txs_store {
-            info!(target: "validator", "append_tx(): We have already seen this tx");
+            info!(target: "validator::append_tx", "We have already seen this tx");
             return Err(TxVerifyFailed::AlreadySeenTx(tx_hash.to_string()).into())
         }
 
         // Verify state transition
-        info!(target: "validator", "append_tx(): Starting state transition validation");
+        info!(target: "validator::append_tx", "Starting state transition validation");
         // TODO: this should be over all forks overlays
         let overlay = BlockchainOverlay::new(&self.blockchain)?;
 
@@ -156,7 +156,7 @@ impl Validator {
 
         // Add transaction to pending txs store
         self.blockchain.add_pending_txs(&[tx])?;
-        info!(target: "validator", "append_tx(): Appended tx to pending txs store");
+        info!(target: "validator::append_tx", "Appended tx to pending txs store");
 
         Ok(())
     }
@@ -175,7 +175,7 @@ impl Validator {
 
     /// Validate a set of [`BlockInfo`] in sequence and apply them if all are valid.
     pub async fn add_blocks(&self, blocks: &[BlockInfo]) -> Result<()> {
-        debug!(target: "validator", "Instantiating BlockchainOverlay");
+        debug!(target: "validator::add_blocks", "Instantiating BlockchainOverlay");
         let overlay = BlockchainOverlay::new(&self.blockchain)?;
 
         // Retrieve last block
@@ -204,7 +204,7 @@ impl Validator {
             .await
             .is_err()
             {
-                error!(target: "validator", "Erroneous block found in set");
+                error!(target: "validator::add_blocks", "Erroneous block found in set");
                 overlay.lock().unwrap().overlay.lock().unwrap().purge_new_trees()?;
                 return Err(Error::BlockIsInvalid(block.blockhash().to_string()))
             };
@@ -213,7 +213,7 @@ impl Validator {
             previous = block;
         }
 
-        debug!(target: "validator", "Applying overlay changes");
+        debug!(target: "validator::add_blocks", "Applying overlay changes");
         overlay.lock().unwrap().overlay.lock().unwrap().apply()?;
         Ok(())
     }
@@ -228,7 +228,7 @@ impl Validator {
         verifying_slot: u64,
         write: bool,
     ) -> Result<()> {
-        debug!(target: "validator", "Instantiating BlockchainOverlay");
+        debug!(target: "validator::add_transactions", "Instantiating BlockchainOverlay");
         let overlay = BlockchainOverlay::new(&self.blockchain)?;
 
         // Generate a time keeper using transaction verifying slot
@@ -245,18 +245,18 @@ impl Validator {
         let lock = overlay.lock().unwrap();
         let mut overlay = lock.overlay.lock().unwrap();
         if !erroneous_txs.is_empty() {
-            warn!(target: "validator", "Erroneous transactions found in set");
+            warn!(target: "validator::add_transactions", "Erroneous transactions found in set");
             overlay.purge_new_trees()?;
             return Err(TxVerifyFailed::ErroneousTxs(erroneous_txs).into())
         }
 
         if !write {
-            debug!(target: "validator", "Skipping apply of state updates because write=false");
+            debug!(target: "validator::add_transactions", "Skipping apply of state updates because write=false");
             overlay.purge_new_trees()?;
             return Ok(())
         }
 
-        debug!(target: "validator", "Applying overlay changes");
+        debug!(target: "validator::add_transactions", "Applying overlay changes");
         overlay.apply()?;
         Ok(())
     }
@@ -264,7 +264,7 @@ impl Validator {
     /// Append to canonical state received slot.
     /// This should be only used for test purposes.
     pub async fn receive_test_slot(&mut self, slot: &Slot) -> Result<()> {
-        debug!(target: "validator", "receive_slot(): Appending slot to ledger");
+        debug!(target: "validator::receive_test_slot", "Appending slot to ledger");
         self.blockchain.slots.insert(&[slot.clone()])?;
 
         Ok(())
@@ -322,7 +322,7 @@ impl Validator {
             .await
             .is_err()
             {
-                error!(target: "validator", "Erroneous block found in set");
+                error!(target: "validator::validate_blockchain", "Erroneous block found in set");
                 overlay.lock().unwrap().overlay.lock().unwrap().purge_new_trees()?;
                 return Err(Error::BlockIsInvalid(block.blockhash().to_string()))
             };

src/validator/utils.rs

@@ -39,7 +39,7 @@ pub fn deploy_native_contracts(
     time_keeper: &TimeKeeper,
     faucet_pubkeys: &Vec<PublicKey>,
 ) -> Result<()> {
-    info!(target: "validator", "Deploying native WASM contracts");
+    info!(target: "validator::utils::deploy_native_contracts", "Deploying native WASM contracts");
 
     // The faucet pubkeys are pubkeys which are allowed to create clear inputs
     // in the Money contract.
@@ -73,16 +73,16 @@ pub fn deploy_native_contracts(
     ];
 
     for nc in native_contracts {
-        info!(target: "validator", "Deploying {} with ContractID {}", nc.0, nc.1);
+        info!(target: "validator::utils::deploy_native_contracts", "Deploying {} with ContractID {}", nc.0, nc.1);
 
         let mut runtime = Runtime::new(&nc.2[..], overlay.clone(), nc.1, time_keeper.clone())?;
 
         runtime.deploy(&nc.3)?;
 
-        info!(target: "validator", "Successfully deployed {}", nc.0);
+        info!(target: "validator::utils::deploy_native_contracts", "Successfully deployed {}", nc.0);
     }
 
-    info!(target: "validator", "Finished deployment of native WASM contracts");
+    info!(target: "validator::utils::deploy_native_contracts", "Finished deployment of native WASM contracts");
 
     Ok(())
 }

src/validator/verification.rs

@@ -43,7 +43,7 @@ pub async fn verify_genesis_block(
     genesis_txs_total: u64,
 ) -> Result<()> {
     let block_hash = block.blockhash().to_string();
-    debug!(target: "validator", "Validating genesis block {}", block_hash);
+    debug!(target: "validator::verification::verify_genesis_block", "Validating genesis block {}", block_hash);
 
     // Check if block already exists
     if overlay.lock().unwrap().has_block(block)? {
@@ -76,14 +76,14 @@ pub async fn verify_genesis_block(
 
     // Genesis transaction must be the Transaction::default() one (empty)
     if block.producer.proposal != Transaction::default() {
-        error!(target: "validator", "Genesis proposal transaction is not default one");
+        error!(target: "validator::verification::verify_genesis_block", "Genesis proposal transaction is not default one");
         return Err(TxVerifyFailed::ErroneousTxs(vec![block.producer.proposal.clone()]).into())
     }
 
     // Verify transactions
     let erroneous_txs = verify_transactions(overlay, time_keeper, &block.txs).await?;
     if !erroneous_txs.is_empty() {
-        warn!(target: "validator", "Erroneous transactions found in set");
+        warn!(target: "validator::verification::verify_genesis_block", "Erroneous transactions found in set");
         overlay.lock().unwrap().overlay.lock().unwrap().purge_new_trees()?;
         return Err(TxVerifyFailed::ErroneousTxs(erroneous_txs).into())
     }
@@ -91,7 +91,7 @@ pub async fn verify_genesis_block(
     // Insert block
     overlay.lock().unwrap().add_block(block)?;
 
-    debug!(target: "validator", "Genesis block {} verified successfully", block_hash);
+    debug!(target: "validator::verification::verify_genesis_block", "Genesis block {} verified successfully", block_hash);
     Ok(())
 }
 
@@ -105,7 +105,7 @@ pub async fn verify_block(
     testing_mode: bool,
 ) -> Result<()> {
     let block_hash = block.blockhash().to_string();
-    debug!(target: "validator", "Validating block {}", block_hash);
+    debug!(target: "validator::verification::verify_block", "Validating block {}", block_hash);
 
     // Check if block already exists
     if overlay.lock().unwrap().has_block(block)? {
@@ -128,7 +128,7 @@ pub async fn verify_block(
     // Verify transactions
     let erroneous_txs = verify_transactions(overlay, time_keeper, &block.txs).await?;
     if !erroneous_txs.is_empty() {
-        warn!(target: "validator", "Erroneous transactions found in set");
+        warn!(target: "validator::verification::verify_block", "Erroneous transactions found in set");
         overlay.lock().unwrap().overlay.lock().unwrap().purge_new_trees()?;
         return Err(TxVerifyFailed::ErroneousTxs(erroneous_txs).into())
     }
@@ -136,7 +136,7 @@ pub async fn verify_block(
     // Insert block
     overlay.lock().unwrap().add_block(block)?;
 
-    debug!(target: "validator", "Block {} verified successfully", block_hash);
+    debug!(target: "validator::verification::verify_block", "Block {} verified successfully", block_hash);
     Ok(())
 }
 
@@ -148,13 +148,13 @@ pub async fn verify_proposal_transaction(
     tx: &Transaction,
 ) -> Result<()> {
     let tx_hash = tx.hash();
-    debug!(target: "validator", "Validating proposal transaction {}", tx_hash);
+    debug!(target: "validator::verification::verify_proposal_transaction", "Validating proposal transaction {}", tx_hash);
 
     // Transaction must contain a single Consensus::Proposal (0x02) call
     if tx.calls.len() != 1 ||
         (tx.calls[0].contract_id != *CONSENSUS_CONTRACT_ID && tx.calls[0].data[0] != 0x02)
     {
-        error!(target: "validator", "Proposal transaction is malformed");
+        error!(target: "validator::verification::verify_proposal_transaction", "Proposal transaction is malformed");
         return Err(TxVerifyFailed::ErroneousTxs(vec![tx.clone()]).into())
     }
 
@@ -168,7 +168,7 @@ pub async fn verify_proposal_transaction(
     // won't have fee
     verify_transaction(overlay, time_keeper, tx, &mut vks).await?;
 
-    debug!(target: "validator", "Proposal transaction {} verified successfully", tx_hash);
+    debug!(target: "validator::verification::verify_proposal_transaction", "Proposal transaction {} verified successfully", tx_hash);
 
     Ok(())
 }
@@ -182,7 +182,7 @@ pub async fn verify_transaction(
     verifying_keys: &mut HashMap<[u8; 32], HashMap<String, VerifyingKey>>,
 ) -> Result<()> {
     let tx_hash = tx.hash();
-    debug!(target: "validator", "Validating transaction {}", tx_hash);
+    debug!(target: "validator::verification::verify_transaction", "Validating transaction {}", tx_hash);
 
     // Table of public inputs used for ZK proof verification
     let mut zkp_table = vec![];
@@ -191,20 +191,20 @@ pub async fn verify_transaction(
 
     // Iterate over all calls to get the metadata
     for (idx, call) in tx.calls.iter().enumerate() {
-        debug!(target: "validator", "Executing contract call {}", idx);
+        debug!(target: "validator::verification::verify_transaction", "Executing contract call {}", idx);
 
         // Write the actual payload data
         let mut payload = vec![];
         payload.write_u32(idx as u32)?; // Call index
         tx.calls.encode(&mut payload)?; // Actual call data
 
-        debug!(target: "validator", "Instantiating WASM runtime");
+        debug!(target: "validator::verification::verify_transaction", "Instantiating WASM runtime");
         let wasm = overlay.lock().unwrap().wasm_bincode.get(call.contract_id)?;
 
         let mut runtime =
             Runtime::new(&wasm, overlay.clone(), call.contract_id, time_keeper.clone())?;
 
-        debug!(target: "validator", "Executing \"metadata\" call");
+        debug!(target: "validator::verification::verify_transaction", "Executing \"metadata\" call");
         let metadata = runtime.metadata(&payload)?;
 
         // Decode the metadata retrieved from the execution
@@ -214,10 +214,10 @@ pub async fn verify_transaction(
         let zkp_pub: Vec<(String, Vec<pallas::Base>)> = Decodable::decode(&mut decoder)?;
         let sig_pub: Vec<PublicKey> = Decodable::decode(&mut decoder)?;
         // TODO: Make sure we've read all the bytes above.
-        debug!(target: "validator", "Successfully executed \"metadata\" call");
+        debug!(target: "validator::verification::verify_transaction", "Successfully executed \"metadata\" call");
 
         // Here we'll look up verifying keys and insert them into the per-contract map.
-        debug!(target: "validator", "Performing VerifyingKey lookups from the sled db");
+        debug!(target: "validator::verification::verify_transaction", "Performing VerifyingKey lookups from the sled db");
         for (zkas_ns, _) in &zkp_pub {
             let inner_vk_map = verifying_keys.get_mut(&call.contract_id.to_bytes()).unwrap();
 
@@ -238,14 +238,14 @@ pub async fn verify_transaction(
 
         // After getting the metadata, we run the "exec" function with the same runtime
         // and the same payload.
-        debug!(target: "validator", "Executing \"exec\" call");
+        debug!(target: "validator::verification::verify_transaction", "Executing \"exec\" call");
         let state_update = runtime.exec(&payload)?;
-        debug!(target: "validator", "Successfully executed \"exec\" call");
+        debug!(target: "validator::verification::verify_transaction", "Successfully executed \"exec\" call");
 
         // If that was successful, we apply the state update in the ephemeral overlay.
-        debug!(target: "validator", "Executing \"apply\" call");
+        debug!(target: "validator::verification::verify_transaction", "Executing \"apply\" call");
         runtime.apply(&state_update)?;
-        debug!(target: "validator", "Successfully executed \"apply\" call");
+        debug!(target: "validator::verification::verify_transaction", "Successfully executed \"apply\" call");
 
         // At this point we're done with the call and move on to the next one.
     }
@@ -253,29 +253,29 @@ pub async fn verify_transaction(
     // When we're done looping and executing over the tx's contract calls, we now
     // move on with verification. First we verify the signatures as that's cheaper,
     // and then finally we verify the ZK proofs.
-    debug!(target: "validator", "Verifying signatures for transaction {}", tx_hash);
+    debug!(target: "validator::verification::verify_transaction", "Verifying signatures for transaction {}", tx_hash);
     if sig_table.len() != tx.signatures.len() {
-        error!(target: "validator", "Incorrect number of signatures in tx {}", tx_hash);
+        error!(target: "validator::verification::verify_transaction", "Incorrect number of signatures in tx {}", tx_hash);
         return Err(TxVerifyFailed::MissingSignatures.into())
     }
 
     // TODO: Go through the ZK circuits that have to be verified and account for the opcodes.
 
     if let Err(e) = tx.verify_sigs(sig_table) {
-        error!(target: "validator", "Signature verification for tx {} failed: {}", tx_hash, e);
+        error!(target: "validator::verification::verify_transaction", "Signature verification for tx {} failed: {}", tx_hash, e);
         return Err(TxVerifyFailed::InvalidSignature.into())
     }
 
-    debug!(target: "validator", "Signature verification successful");
+    debug!(target: "validator::verification::verify_transaction", "Signature verification successful");
 
-    debug!(target: "validator", "Verifying ZK proofs for transaction {}", tx_hash);
+    debug!(target: "validator::verification::verify_transaction", "Verifying ZK proofs for transaction {}", tx_hash);
     if let Err(e) = tx.verify_zkps(verifying_keys, zkp_table).await {
-        error!(target: "validator", "ZK proof verification for tx {} failed: {}", tx_hash, e);
+        error!(target: "validator::verification::verify_transaction", "ZK proof verification for tx {} failed: {}", tx_hash, e);
         return Err(TxVerifyFailed::InvalidZkProof.into())
     }
 
-    debug!(target: "validator", "ZK proof verification successful");
-    debug!(target: "validator", "Transaction {} verified successfully", tx_hash);
+    debug!(target: "validator::verification::verify_transaction", "ZK proof verification successful");
+    debug!(target: "validator::verification::verify_transaction", "Transaction {} verified successfully", tx_hash);
 
     Ok(())
 }
@@ -289,7 +289,7 @@ pub async fn verify_transactions(
     time_keeper: &TimeKeeper,
     txs: &[Transaction],
 ) -> Result<Vec<Transaction>> {
-    debug!(target: "validator", "Verifying {} transactions", txs.len());
+    debug!(target: "validator::verification::verify_transactions", "Verifying {} transactions", txs.len());
 
     // Tracker for failed txs
     let mut erroneous_txs = vec![];
@@ -308,7 +308,7 @@ pub async fn verify_transactions(
     for tx in txs {
         overlay.lock().unwrap().checkpoint();
         if let Err(e) = verify_transaction(overlay, time_keeper, tx, &mut vks).await {
-            warn!(target: "validator", "Transaction verification failed: {}", e);
+            warn!(target: "validator::verification::verify_transactions", "Transaction verification failed: {}", e);
             erroneous_txs.push(tx.clone());
             // TODO: verify this works as expected
             overlay.lock().unwrap().revert_to_checkpoint()?;