From eb2a13de6cdc304b07cd0598989492886218b5c2 Mon Sep 17 00:00:00 2001 From: Giacomo Pasini Date: Fri, 14 May 2021 16:51:10 +0200 Subject: [PATCH] Add logging --- Cargo.lock | 31 ++++++++- catalyst-toolbox-cli/Cargo.toml | 3 +- .../src/cli/recovery/tally.rs | 12 +++- catalyst-toolbox-lib/Cargo.toml | 1 + catalyst-toolbox-lib/src/recovery/tally.rs | 66 ++++++++++--------- 5 files changed, 77 insertions(+), 36 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index 7a3a9c7f..b781ad79 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -321,11 +321,13 @@ dependencies = [ "itertools 0.10.0", "jcli", "jormungandr-lib", + "log", "rand 0.8.3", "reqwest", "serde", "serde_json", "serde_yaml", + "stderrlog", "structopt", "thiserror", "versionisator", @@ -345,6 +347,7 @@ dependencies = [ "jcli", "jormungandr-lib", "jormungandr-testing-utils", + "log", "rand 0.8.3", "serde", "serde_json", @@ -3221,6 +3224,19 @@ version = "1.1.0" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "a2eb9349b6444b326872e140eb1cf5e7c522154d69e7a0ffb0fb81c06b37543f" +[[package]] +name = "stderrlog" +version = "0.5.1" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "45a53e2eff3e94a019afa6265e8ee04cb05b9d33fe9f5078b14e4e391d155a38" +dependencies = [ + "atty", + "chrono", + "log", + "termcolor", + "thread_local", +] + [[package]] name = "strsim" version = "0.8.0" @@ -3407,6 +3423,15 @@ dependencies = [ "winapi", ] +[[package]] +name = "termcolor" +version = "1.1.2" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "2dfed899f0eb03f32ee8c6a0aabdb8a7949659e3466561fc0adf54e26d88c5f4" +dependencies = [ + "winapi-util", +] + [[package]] name = "terminal_size" version = "0.1.16" @@ -3458,11 +3483,11 @@ dependencies = [ [[package]] name = "thread_local" -version = "1.1.3" +version = "1.0.1" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "8018d24e04c95ac8790716a5987d0fec4f8b27249ffa0f7d33f1369bdfb88cbd" +checksum = "d40c6d1b69745a6ec6fb1ca717914848da4b44ae29d9b3080cbee91d72a69b14" dependencies = [ - "once_cell", + "lazy_static", ] [[package]] diff --git a/catalyst-toolbox-cli/Cargo.toml b/catalyst-toolbox-cli/Cargo.toml index 3b89c675..78fa1174 100644 --- a/catalyst-toolbox-cli/Cargo.toml +++ b/catalyst-toolbox-cli/Cargo.toml @@ -23,8 +23,9 @@ serde_json = "1.0" structopt = "0.3" thiserror = "1.0" rand = "0.8.3" - +stderrlog = "0.5" serde_yaml = "0.8.17" +log = "0.4" [build-dependencies] versionisator = "1.0.3" diff --git a/catalyst-toolbox-cli/src/cli/recovery/tally.rs b/catalyst-toolbox-cli/src/cli/recovery/tally.rs index 7987fac8..8dc80d80 100644 --- a/catalyst-toolbox-cli/src/cli/recovery/tally.rs +++ b/catalyst-toolbox-cli/src/cli/recovery/tally.rs @@ -9,6 +9,7 @@ use jormungandr_lib::interfaces::{ load_persistent_fragments_logs_from_folder_path, VotePlanStatus, }; +use log::warn; use std::io::{BufReader, Write}; use std::path::PathBuf; @@ -50,6 +51,10 @@ pub struct Replay { #[structopt(flatten)] output_format: OutputFormat, + + /// Verbose mode (-v, -vv, -vvv, etc) + #[structopt(short = "v", long = "verbose", parse(from_occurrences))] + verbose: usize, } fn read_block0(path: PathBuf) -> std::io::Result { @@ -64,15 +69,18 @@ impl Replay { logs_path, output, output_format, + verbose, } = self; + stderrlog::new().verbosity(verbose).init().unwrap(); let block0 = read_block0(block0_path)?; + let fragments = load_persistent_fragments_logs_from_folder_path(&logs_path)?; let (ledger, failed) = recover_ledger_from_logs(&block0, fragments)?; if !failed.is_empty() { - eprintln!("{} fragments couldn't be properly processed", failed.len()); + warn!("{} fragments couldn't be properly processed", failed.len()); for failed_fragment in failed { - eprintln!("{}", failed_fragment.id()); + warn!("{}", failed_fragment.id()); } } let voteplans = ledger.active_vote_plans(); diff --git a/catalyst-toolbox-lib/Cargo.toml b/catalyst-toolbox-lib/Cargo.toml index e9d02071..2a3b3ff5 100644 --- a/catalyst-toolbox-lib/Cargo.toml +++ b/catalyst-toolbox-lib/Cargo.toml @@ -22,3 +22,4 @@ serde_json = "1.0" structopt = "0.3" thiserror = "1.0" rand = "0.8" +log = "0.4" diff --git a/catalyst-toolbox-lib/src/recovery/tally.rs b/catalyst-toolbox-lib/src/recovery/tally.rs index 1f2c4b2c..a3ec99da 100644 --- a/catalyst-toolbox-lib/src/recovery/tally.rs +++ b/catalyst-toolbox-lib/src/recovery/tally.rs @@ -32,6 +32,7 @@ use jormungandr_lib::{ time::SecondsSinceUnixEpoch, }; use jormungandr_testing_utils::wallet::Wallet; +use log::{debug, error, trace, warn}; use std::collections::{HashMap, HashSet}; #[allow(clippy::large_enum_variant)] @@ -148,9 +149,10 @@ fn verify_original_tx( SpendingCounter::from(new_spending_counter), ); if witness.verify(account.as_ref(), &tidsc) == chain_crypto::Verification::Success { - eprintln!( + trace!( "expected: {} found: {}", - spending_counter, new_spending_counter + spending_counter, + new_spending_counter ); return (true, new_spending_counter); } @@ -177,7 +179,6 @@ pub fn recover_ledger_from_logs( ) -> Result<(Ledger, Vec), Error> { let block0_configuration = Block0Configuration::from_block(block0).unwrap(); let mut failed_fragments = Vec::new(); - let (mut fragment_replayer, new_block0) = FragmentReplayer::from_block0(block0)?; // we use block0 header id instead of the new one, to keep validation on old tx that uses the original block0 id. @@ -217,33 +218,30 @@ pub fn recover_ledger_from_logs( let block_date = fragment_log_timestamp_to_blockdate(time, &timeframe, &ledger) .expect("BlockDates should always be valid for logs timestamps"); - eprintln!("Fragment processed {}", fragment.hash()); + debug!("Fragment processed {}", fragment.hash()); let new_fragment = match &fragment { fragment @ Fragment::VoteCast(_) => { - if let Ok(new_fragment) = - fragment_replayer.replay(fragment.clone()).map_err(|e| { - eprintln!( - "Fragment {} couldn't be processed:\n\t {:?}", - fragment.id(), - e - ); - }) - { - if vote_start > block_date || vote_end <= block_date { - eprintln!( - "Fragment {} skipped because it was out of voting time ({}-{}-{})", - fragment.id(), - vote_start, - block_date, - vote_end, - ); - None - } else { - Some(new_fragment) - } - } else { - failed_fragments.push(fragment.clone()); + if vote_start > block_date || vote_end <= block_date { + warn!( + "Fragment {} skipped because it was out of voting time ({}-{}-{})", + fragment.id(), + vote_start, + block_date, + vote_end, + ); None + } else { + fragment_replayer + .replay(fragment.clone()) + .map_err(|e| { + failed_fragments.push(fragment.clone()); + warn!( + "Fragment {} couldn't be processed:\n\t {:?}", + fragment.id(), + e + ); + }) + .ok() } } new_fragment @ Fragment::VoteTally(_) => { @@ -261,7 +259,7 @@ pub fn recover_ledger_from_logs( } } Err(e) => { - eprintln!("Error deserializing PersistentFragmentLog: {:?}", e); + error!("Error deserializing PersistentFragmentLog: {:?}", e); } } } @@ -315,7 +313,7 @@ impl FragmentReplayer { let new_initial_utxo = wallet.to_initial_fund(utxo.value.into()); wallets.insert(utxo.address.clone(), wallet); if committee_members.contains(&utxo.address) { - eprintln!("Committee account found {}", &utxo.address); + trace!("Committee account found {}", &utxo.address); // push new mirror address new_committee_accounts.push(new_initial_utxo); } else { @@ -433,16 +431,24 @@ impl FragmentReplayer { .voteplans .get(vote_cast.vote_plan()) .ok_or(Error::MissingVoteplanError)?; + let proposals_idx = vote_cast.proposal_index(); // we still use the old block0 hash because the new ledger will still use the old one for // verifications. This makes possible the usage of old VoteTally transactions without the need // to be replayed. + debug!( + "replaying vote from {}, vote plan: {}, proposal idx: {}, choice: {:?}", + identifier, + &vote_plan.to_id(), + proposals_idx, + &choice + ); let res = wallet .issue_vote_cast_cert( &self.old_block0_hash, &self.fees, &vote_plan, - vote_cast.proposal_index(), + proposals_idx, &choice, ) .unwrap();