From dd91a68212873ab527831040ee2d0686bebc0c5b Mon Sep 17 00:00:00 2001 From: Hanting Zhang Date: Tue, 29 Aug 2023 18:11:21 -0700 Subject: [PATCH] Standardize logging with `tracing` crate + implement micro-benchmarking (#627) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit * initial commit * attempt to remove log * chore: Refactor logging remnants to tracing - Removed `log` as a workspace dependency and replaced it with `tracing` throughout the project, - Updated clippy linting configuration in `.cargo/config`. - Adapted from `log` crate's `info` module to `tracing` crate's `info` module in `lurk-metrics/src/data.rs` * chore: clippy * fix: adjust test_basic_functionality * chore: fmt * cargo fmt * remove pretty_env_logger * deduplicate sha test * remove dbg! * add env_filter to restore old behavior * cargo fmt * address comments * clippy --------- Co-authored-by: François Garillot --- .cargo/config | 1 + Cargo.toml | 30 ++++------ benches/fibonacci.rs | 3 +- clutch/Cargo.toml | 7 ++- clutch/src/main.rs | 7 ++- examples/circom.rs | 1 - examples/sha256.rs | 94 ++++++++++++++++++------------ fcomm/Cargo.toml | 7 ++- fcomm/src/bin/fcomm.rs | 11 ++-- fcomm/src/lib.rs | 2 +- lurk-metrics/Cargo.toml | 7 +-- lurk-metrics/src/data.rs | 2 +- lurk-metrics/src/lib.rs | 31 +++------- src/circuit/circuit_frame.rs | 29 +++++---- src/circuit/gadgets/pointer.rs | 2 +- src/cli/lurk_proof.rs | 2 +- src/cli/mod.rs | 9 +-- src/cli/repl.rs | 2 +- src/config.rs | 2 +- src/eval/mod.rs | 3 +- src/eval/reduction.rs | 2 +- src/eval/tests/mod.rs | 10 ++-- src/hash_witness.rs | 10 +++- src/lem/var_map.rs | 2 +- src/main.rs | 12 +++- src/proof/mod.rs | 6 +- src/proof/nova.rs | 24 ++++---- src/public_parameters/mem_cache.rs | 10 ++-- src/repl.rs | 10 ++-- src/store.rs | 3 +- tests/lurk-cli-tests.rs | 15 +++-- 31 files changed, 197 insertions(+), 159 deletions(-) diff --git a/.cargo/config b/.cargo/config index c44ced1eef..31f41f0f0b 100644 --- a/.cargo/config +++ b/.cargo/config @@ -8,6 +8,7 @@ xclippy = [ "-Wclippy::all", "-Wclippy::match_same_arms", "-Wclippy::cast_lossless", + "-Wclippy::dbg_macro", "-Wclippy::disallowed_methods", "-Wclippy::derive_partial_eq_without_eq", "-Wclippy::filter_map_next", diff --git a/Cargo.toml b/Cargo.toml index 1565c150f7..0b879df497 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -21,6 +21,7 @@ bellpepper-core = { workspace = true } bellperson = { workspace = true } bincode = { workspace = true } blstrs = { workspace = true } +camino = { workspace = true } clap = { workspace = true, features = ["derive"] } config = "0.13.3" dashmap = "5.5.0" @@ -29,7 +30,6 @@ generic-array = "0.14.7" hex = { version = "0.4.3", features = ["serde"] } indexmap = { version = "1.9.3", features = ["rayon"] } itertools = "0.9" -log = { workspace = true } lurk-macros = { path = "lurk-macros" } lurk-metrics = { path = "lurk-metrics" } metrics = { workspace = true } @@ -45,7 +45,6 @@ once_cell = { workspace = true } pairing = { workspace = true } pasta_curves = { workspace = true, features = ["repr-c", "serde"] } peekmore = "1.3.0" -pretty_env_logger = { workspace = true } rand = { workspace = true } rand_core = { version = "0.6.4", default-features = false } rand_xorshift = "0.3.0" @@ -58,7 +57,6 @@ serde_repr = "0.1.14" tap = "1.0.1" stable_deref_trait = "1.2.0" thiserror = { workspace = true } -camino = { workspace = true } abomonation = { workspace = true} abomonation_derive = { git = "https://github.com/lurk-lab/abomonation_derive.git" } crossbeam = "0.8.2" @@ -67,6 +65,9 @@ circom-scotia = { git = "https://github.com/lurk-lab/circom-scotia", branch = "d sha2 = { version = "0.10.2" } reqwest = { version = "0.11.18", features = ["stream", "blocking"] } ansi_term = "0.12.1" +tracing = { workspace = true } +tracing-texray = { workspace = true } +tracing-subscriber = { workspace = true, features = ["env-filter"] } [target.'cfg(not(target_arch = "wasm32"))'.dependencies] memmap = { version = "0.5.10", package = "memmap2" } @@ -83,22 +84,10 @@ rustyline = { version = "11.0", features = ["derive"], default-features = false [features] default = [] -opencl = [ - "neptune/opencl", - "bellperson/opencl", - "nova/opencl" -] -cuda = [ - "neptune/cuda", - "bellperson/cuda", - "nova/cuda" -] +opencl = ["neptune/opencl", "bellperson/opencl", "nova/opencl"] +cuda = ["neptune/cuda", "bellperson/cuda", "nova/cuda"] # compile without ISA extensions -portable = [ - "blstrs/portable", - "pasta-msm/portable", - "nova/portable" -] +portable = ["blstrs/portable", "pasta-msm/portable", "nova/portable"] flamegraph = ["pprof/flamegraph", "pprof/criterion"] [dev-dependencies] @@ -136,7 +125,6 @@ bincode = "1.3.3" blstrs = { git = "https://github.com/lurk-lab/blstrs", branch = "dev" } clap = "4.3.17" ff = "0.13" -log = "0.4.19" metrics = "0.21.1" neptune = { git = "https://github.com/lurk-lab/neptune", branch = "dev" } nova = { git = "https://github.com/lurk-lab/arecibo", branch = "dev", package = "nova-snark" } @@ -144,7 +132,6 @@ once_cell = "1.18.0" pairing = { version = "0.23" } pasta_curves = { git = "https://github.com/lurk-lab/pasta_curves", branch = "dev" } pasta-msm = { git = "https://github.com/lurk-lab/pasta-msm", branch = "dev" } -pretty_env_logger = "0.4" proptest = "1.2.0" proptest-derive = "0.3.0" rand = "0.8" @@ -153,6 +140,9 @@ serde_json = { version = "1.0" } tempfile = "3.6.0" camino = "1.1.6" thiserror = "1.0.44" +tracing = "0.1.37" +tracing-texray = "0.2.0" +tracing-subscriber = "0.3.17" [[bin]] name = "lurk" diff --git a/benches/fibonacci.rs b/benches/fibonacci.rs index a5a015c790..fdc5a259d5 100644 --- a/benches/fibonacci.rs +++ b/benches/fibonacci.rs @@ -23,6 +23,7 @@ use lurk::{ }; const PUBLIC_PARAMS_PATH: &str = "/var/tmp/lurk_benches/public_params"; + fn fib(store: &mut Store, state: Rc>, _a: u64) -> Ptr { let program = r#" (letrec ((next (lambda (a b) (next b (+ a b)))) @@ -109,7 +110,7 @@ fn fibo_prove( } fn fibonacci_prove(c: &mut Criterion) { - let _ = dbg!(&*lurk::config::CONFIG); + tracing::debug!("{:?}", &*lurk::config::CONFIG); let reduction_counts = vec![100, 600, 700, 800, 900]; let batch_sizes = vec![100, 200]; let mut group: BenchmarkGroup<'_, _> = c.benchmark_group("Prove"); diff --git a/clutch/Cargo.toml b/clutch/Cargo.toml index 8997bc25c3..de1a557078 100644 --- a/clutch/Cargo.toml +++ b/clutch/Cargo.toml @@ -11,14 +11,17 @@ repository = "https://github.com/lurk-lab/lurk-rs" [dependencies] anyhow = { workspace = true } blstrs = { workspace = true } +camino = { workspace = true } clap = { workspace = true } fcomm = { path = "../fcomm" } ff = "0.13" lurk = { path = "../" } pasta_curves = { workspace = true, features = ["repr-c", "serde"] } -pretty_env_logger = "0.4" serde = { workspace = true, features = ["derive"] } -camino = { workspace = true } +tracing = { workspace = true } +tracing-texray = { workspace = true } +tracing-subscriber = { workspace = true } + [dev-dependencies] assert_cmd = "2.0.12" diff --git a/clutch/src/main.rs b/clutch/src/main.rs index fb575f2a63..0c9eb2e37b 100644 --- a/clutch/src/main.rs +++ b/clutch/src/main.rs @@ -6,9 +6,14 @@ use lurk::eval::lang::{Coproc, Lang}; use lurk::field::LanguageField; use lurk::repl::repl_cli; use pasta_curves::pallas; +use tracing_subscriber::{fmt, prelude::*, EnvFilter, Registry}; fn main() -> Result<()> { - pretty_env_logger::init(); + let subscriber = Registry::default() + // TODO: correctly filter log level with `clap_verbosity_flag` + .with(fmt::layer().pretty()) + .with(EnvFilter::from_default_env()); + tracing::subscriber::set_global_default(subscriber).unwrap(); let default_field = LanguageField::Pallas; let field = if let Ok(lurk_field) = std::env::var("LURK_FIELD") { diff --git a/examples/circom.rs b/examples/circom.rs index 08c24443db..0009b34c5c 100644 --- a/examples/circom.rs +++ b/examples/circom.rs @@ -110,7 +110,6 @@ fn main() { ); let coproc_expr = format!("{}", sym_str); - dbg!(coproc_expr.clone()); let expr = format!("({coproc_expr})"); let ptr = store.read(&expr).unwrap(); diff --git a/examples/sha256.rs b/examples/sha256.rs index 960790fd0e..4af8cfee12 100644 --- a/examples/sha256.rs +++ b/examples/sha256.rs @@ -11,22 +11,24 @@ use lurk::eval::{empty_sym_env, lang::Lang}; use lurk::field::LurkField; use lurk::proof::{nova::NovaProver, Prover}; use lurk::ptr::Ptr; -use lurk::public_parameters::with_public_params; +use lurk::public_parameters::{public_params, public_params_default_dir}; use lurk::state::user_sym; use lurk::store::Store; use lurk_macros::Coproc; -use bellpepper::gadgets::multipack::pack_bits; -use bellpepper::gadgets::sha256::sha256; -use bellpepper_core::boolean::{AllocatedBit, Boolean}; -use bellpepper_core::num::AllocatedNum; -use bellpepper_core::{ConstraintSystem, SynthesisError}; +use bellperson::gadgets::boolean::{AllocatedBit, Boolean}; +use bellperson::gadgets::multipack::pack_bits; +use bellperson::gadgets::num::AllocatedNum; +use bellperson::gadgets::sha256::sha256; +use bellperson::{ConstraintSystem, SynthesisError}; use pasta_curves::pallas::Scalar as Fr; use serde::{Deserialize, Serialize}; use sha2::{Digest, Sha256}; +use tracing_subscriber::{fmt, prelude::*, EnvFilter, Registry}; +use tracing_texray::TeXRayLayer; -const REDUCTION_COUNT: usize = 100; +const REDUCTION_COUNT: usize = 10; #[derive(Clone, Debug, Serialize, Deserialize)] pub(crate) struct Sha256Coprocessor { @@ -152,8 +154,17 @@ enum Sha256Coproc { /// Run the example in this file with /// `cargo run --release --example sha256 1 f5a5fd42d16a20302798ef6ed309979b43003d2320d9f0e8ea9831a92759fb4b false` +/// +/// To see the `texray` outputs, run with +/// ` +/// `RUST_LOG=info cargo run --release --example sha256 1 f5a5fd42d16a20302798ef6ed309979b43003d2320d9f0e8ea9831a92759fb4b false` fn main() { - pretty_env_logger::init(); + let subscriber = Registry::default() + .with(fmt::layer().pretty()) + .with(EnvFilter::from_default_env()) + .with(TeXRayLayer::new()); + tracing::subscriber::set_global_default(subscriber).unwrap(); + let args: Vec = env::args().collect(); let num_of_64_bytes = args[1].parse::().unwrap(); @@ -177,48 +188,55 @@ fn main() { store, vec![(cproc_sym, Sha256Coprocessor::new(input_size, u).into())], ); - let lang_rc = Arc::new(lang.clone()); let cproc_call = store.list(&[cproc_sym_ptr]); - let nova_prover = NovaProver::>::new(REDUCTION_COUNT, lang); + let nova_prover = NovaProver::>::new(REDUCTION_COUNT, lang.clone()); + let lang_rc = Arc::new(lang); - println!("Setting up public parameters (rc = {REDUCTION_COUNT})..."); + println!("Setting up public parameters..."); let pp_start = Instant::now(); + let pp = public_params::<_, Sha256Coproc>( + REDUCTION_COUNT, + true, + lang_rc.clone(), + &public_params_default_dir(), + ) + .unwrap(); + let pp_end = pp_start.elapsed(); - // see the documentation on `with_public_params` - with_public_params(REDUCTION_COUNT, lang_rc.clone(), |pp| { - let pp_end = pp_start.elapsed(); - println!("Public parameters took {:?}", pp_end); + println!("Public parameters took {:?}", pp_end); - if setup_only { - return; - } + if setup_only { + return; + } + + println!("Beginning proof step..."); - println!("Beginning proof step..."); - let proof_start = Instant::now(); - let (proof, z0, zi, num_steps) = nova_prover - .evaluate_and_prove(pp, cproc_call, empty_sym_env(store), store, 10000, lang_rc) - .unwrap(); - let proof_end = proof_start.elapsed(); + let proof_start = Instant::now(); + let (proof, z0, zi, num_steps) = tracing_texray::examine(tracing::info_span!("prog_start")) + .in_scope(|| { + nova_prover + .evaluate_and_prove(&pp, cproc_call, empty_sym_env(store), store, 10000, lang_rc) + .unwrap() + }); + let proof_end = proof_start.elapsed(); - println!("Proofs took {:?}", proof_end); + println!("Proofs took {:?}", proof_end); - println!("Verifying proof..."); + println!("Verifying proof..."); - let verify_start = Instant::now(); - let res = proof.verify(pp, num_steps, &z0, &zi).unwrap(); - let verify_end = verify_start.elapsed(); + let verify_start = Instant::now(); + let res = proof.verify(&pp, num_steps, &z0, &zi).unwrap(); + let verify_end = verify_start.elapsed(); - println!("Verify took {:?}", verify_end); + println!("Verify took {:?}", verify_end); - if res { - println!( - "Congratulations! You proved and verified a SHA256 hash calculation in {:?} time!", - pp_end + proof_end + verify_end - ); - } - }) - .unwrap(); + if res { + println!( + "Congratulations! You proved and verified a SHA256 hash calculation in {:?} time!", + pp_end + proof_end + verify_end + ); + } } diff --git a/fcomm/Cargo.toml b/fcomm/Cargo.toml index 4d607a0f83..14bfbdc66a 100644 --- a/fcomm/Cargo.toml +++ b/fcomm/Cargo.toml @@ -18,25 +18,26 @@ base64 = { workspace = true } bellpepper-core = { workspace = true } bincode = { workspace = true } blstrs = { workspace = true } +camino = { workspace = true } clap = { workspace = true, features = ["derive"] } clap-verbosity-flag = "2.0" ff = { workspace = true } hex = { version = "0.4.3", features = ["serde"] } -log = { workspace = true } lurk = { path = "../", package = "lurk" } lurk-macros = { path = "../lurk-macros" } nova = { workspace = true } once_cell = { workspace = true } pairing = { workspace = true } pasta_curves = { workspace = true, features = ["repr-c", "serde"] } -pretty_env_logger = { workspace = true } proptest = { workspace = true } proptest-derive = { workspace = true } rand = { workspace = true } serde = { workspace = true, features = ["derive"] } serde_json = { workspace = true } thiserror = { workspace = true } -camino = { workspace = true } +tracing = { workspace = true } +tracing-texray = { workspace = true } +tracing-subscriber = { workspace = true, features = ["env-filter"] } [dev-dependencies] assert_cmd = "2.0.12" diff --git a/fcomm/src/bin/fcomm.rs b/fcomm/src/bin/fcomm.rs index 3403178764..04d89ed510 100644 --- a/fcomm/src/bin/fcomm.rs +++ b/fcomm/src/bin/fcomm.rs @@ -1,5 +1,4 @@ use abomonation::Abomonation; -use log::info; use lurk::lurk_sym_ptr; use lurk::proof::nova::{CurveCycleEquipped, G1, G2}; use nova::traits::Group; @@ -9,6 +8,8 @@ use std::fs::read_to_string; use std::io; use std::path::{Path, PathBuf}; use std::sync::Arc; +use tracing::info; +use tracing_subscriber::{fmt, prelude::*, EnvFilter, Registry}; use hex::FromHex; use serde::de::DeserializeOwned; @@ -520,9 +521,11 @@ where fn main() { let cli = Cli::parse(); - pretty_env_logger::formatted_builder() - .filter_level(cli.verbose.log_level_filter()) - .init(); + let subscriber = Registry::default() + // TODO: correctly filter log level with `clap_verbosity_flag` + .with(fmt::layer().pretty()) + .with(EnvFilter::from_default_env()); + tracing::subscriber::set_global_default(subscriber).unwrap(); // TODO: make this properly configurable, e.g. allowing coprocessors let lang = Lang::new(); diff --git a/fcomm/src/lib.rs b/fcomm/src/lib.rs index bf10e1fdc8..781462f116 100644 --- a/fcomm/src/lib.rs +++ b/fcomm/src/lib.rs @@ -1,8 +1,8 @@ use ::nova::traits::Group; use abomonation::Abomonation; -use log::info; use std::convert::TryFrom; use std::sync::Arc; +use tracing::info; #[cfg(not(target_arch = "wasm32"))] use proptest::prelude::*; diff --git a/lurk-metrics/Cargo.toml b/lurk-metrics/Cargo.toml index 9918a5a7b9..4b26dcc79b 100644 --- a/lurk-metrics/Cargo.toml +++ b/lurk-metrics/Cargo.toml @@ -10,10 +10,9 @@ repository = "https://github.com/lurk-lab/lurk-rs" [dependencies] metrics = { workspace = true } once_cell = { workspace = true } -log = { workspace = true } hdrhistogram = { version = "7.5.2", default-features = false } - +tracing = { workspace = true } [dev-dependencies] -expect-test = "1" -testing_logger = "0.1.1" \ No newline at end of file +regex = { version = "1.9.4", features = ["unicode-case"] } +tracing-test = { version = "0.2", features = ["no-env-filter"] } \ No newline at end of file diff --git a/lurk-metrics/src/data.rs b/lurk-metrics/src/data.rs index 50acd982e4..792386e8f8 100644 --- a/lurk-metrics/src/data.rs +++ b/lurk-metrics/src/data.rs @@ -1,8 +1,8 @@ use std::collections::HashMap; use std::fmt::{self, Display, Formatter}; -use log::info; use metrics::Key; +use tracing::info; pub const METRICS_TARGET_NAME: &str = "lurk::metrics"; diff --git a/lurk-metrics/src/lib.rs b/lurk-metrics/src/lib.rs index 35c9c2d7a4..623f068ffa 100644 --- a/lurk-metrics/src/lib.rs +++ b/lurk-metrics/src/lib.rs @@ -170,12 +170,11 @@ impl ThreadMetricsSinkHandle { #[cfg(test)] mod tests { - use log::Level; - use metrics::Label; - use super::*; + use metrics::Label; + use tracing_test::traced_test; - // TODO: this uses, but does not clean up the global sink, clobbering the state for any further test + #[traced_test] #[test] fn test_basic_metrics() { let sink = MetricsSink::new(); @@ -229,25 +228,11 @@ mod tests { } } - testing_logger::setup(); MetricsSink::publish(metrics); - - testing_logger::validate(|captured_logs| { - assert_eq!(captured_logs.len(), 4); - let snapshot = expect_test::expect![[r#" - test_counter[type=bar]: 7 (n=3) - test_counter[type=foo]: 6 (n=3) - test_gauge[type=bar]: 3 (n=1) - test_gauge[type=foo]: 2 (n=1)"#]]; - - snapshot.assert_eq( - &captured_logs - .iter() - .map(|line| line.body.clone()) - .collect::>() - .join("\n"), - ); - assert_eq!(captured_logs[0].level, Level::Info); - }); + assert!(logs_contain("test_counter")); + assert!(logs_contain("test_counter[type=bar]: 7 (n=3)")); + assert!(logs_contain("test_counter[type=foo]: 6 (n=3)")); + assert!(logs_contain("test_gauge[type=bar]: 3 (n=1)")); + assert!(logs_contain("test_gauge[type=foo]: 2 (n=1)")); } } diff --git a/src/circuit/circuit_frame.rs b/src/circuit/circuit_frame.rs index 584e1ab66e..b41f6b5e04 100644 --- a/src/circuit/circuit_frame.rs +++ b/src/circuit/circuit_frame.rs @@ -514,6 +514,7 @@ impl> CircuitFrame<'_, F, C> { } impl> Circuit for MultiFrame<'_, F, C> { + #[tracing::instrument(skip_all, name = "::synthesize")] fn synthesize>(self, cs: &mut CS) -> Result<(), SynthesisError> { //////////////////////////////////////////////////////////////////////////////// // Bind public inputs. @@ -851,11 +852,11 @@ fn reduce_expression, C: Coprocessor>( lang: &Lang, g: &GlobalAllocations, ) -> Result<(AllocatedPtr, AllocatedPtr, AllocatedContPtr), SynthesisError> { - // dbg!("reduce_expression"); - // dbg!(&expr.fetch_and_write_str(store)); - // dbg!(&expr); - // dbg!(&env.fetch_and_write_str(store)); - // dbg!(&cont.fetch_and_write_cont_str(store), &cont); + // tracing::debug!("reduce_expression"); + // tracing::debug!("{}", &expr.fetch_and_write_str(store)); + // tracing::debug!("{:?}", &expr); + // tracing::debug!("{}", &env.fetch_and_write_str(store)); + // tracing::debug!("{} {:?}", &cont.fetch_and_write_cont_str(store), &cont); let mut results = Results::default(); { // Self-evaluating expressions @@ -1116,10 +1117,10 @@ fn reduce_expression, C: Coprocessor>( allocated_cons_witness.assert_final_invariants(); allocated_cont_witness.assert_final_invariants(); - // dbg!(&result_expr.fetch_and_write_str(store)); - // dbg!(&result_env.fetch_and_write_str(store)); - // dbg!(&result_cont.fetch_and_write_cont_str(store)); - // dbg!(expr, env, cont); + // tracing::debug!("{}", &result_expr.fetch_and_write_str(store)); + // tracing::debug!("{}", &result_env.fetch_and_write_str(store)); + // tracing::debug!("{}", &result_cont.fetch_and_write_cont_str(store)); + // tracing::debug!("{:?} {:?} {:?}", expr, env, cont); Ok((result_expr, result_env, result_cont)) } @@ -5115,7 +5116,11 @@ fn car_cdr_named>( )?; if cons_not_dummy.get_value().unwrap_or(false) && !real_cons.get_value().unwrap_or(true) { - dbg!(maybe_cons.hash().get_value(), &allocated_digest.get_value()); + tracing::debug!( + "{:?} {:?}", + maybe_cons.hash().get_value(), + &allocated_digest.get_value() + ); panic!( "tried to take car_cdr of a non-dummy cons ({:?}) but supplied wrong value", name @@ -5479,10 +5484,10 @@ mod tests { .expect("failed to synthesize"); let delta = cs.delta(&cs_blank, false); - dbg!(&delta); + tracing::debug!("{:?}", &delta); assert!(delta == Delta::Equal); - //println!("{}", print_cs(&cs)); + // println!("{}", print_cs(&cs)); assert_eq!(12032, cs.num_constraints()); assert_eq!(13, cs.num_inputs()); assert_eq!(11688, cs.aux().len()); diff --git a/src/circuit/gadgets/pointer.rs b/src/circuit/gadgets/pointer.rs index 123639f8cf..52780f372d 100644 --- a/src/circuit/gadgets/pointer.rs +++ b/src/circuit/gadgets/pointer.rs @@ -343,7 +343,7 @@ impl AllocatedPtr { implies!(cs, not_dummy, &cons_is_real); if not_dummy.get_value().unwrap_or(false) && !cons_is_real.get_value().unwrap_or(true) { - dbg!(name); + tracing::debug!("{:?}", name); panic!("uh oh!"); } diff --git a/src/cli/lurk_proof.rs b/src/cli/lurk_proof.rs index 393ec76547..21676d7a5f 100644 --- a/src/cli/lurk_proof.rs +++ b/src/cli/lurk_proof.rs @@ -104,7 +104,7 @@ impl<'a> LurkProof<'a, Scalar> { rc, lang, } => { - log::info!("Loading public parameters"); + tracing::info!("Loading public parameters"); let pp = public_params(rc, true, std::sync::Arc::new(lang), &public_params_dir())?; Ok(proof.verify(&pp, num_steps, &public_inputs, &public_outputs)?) } diff --git a/src/cli/mod.rs b/src/cli/mod.rs index 1a1ab23d7e..77275517a2 100644 --- a/src/cli/mod.rs +++ b/src/cli/mod.rs @@ -366,7 +366,7 @@ impl ReplCli { }}; } let config = get_config(&self.config)?; - log::info!("Configured variables: {:?}", config); + tracing::info!("Configured variables: {:?}", config); set_lurk_dirs( &config, &self.public_params_dir, @@ -417,7 +417,7 @@ impl LoadCli { }}; } let config = get_config(&self.config)?; - log::info!("Configured variables: {:?}", config); + tracing::info!("Configured variables: {:?}", config); set_lurk_dirs( &config, &self.public_params_dir, @@ -511,7 +511,7 @@ impl Cli { Command::Verify(verify_args) => { use crate::cli::lurk_proof::LurkProof; let config = get_config(&verify_args.config)?; - log::info!("Configured variables: {:?}", config); + tracing::info!("Configured variables: {:?}", config); set_lurk_dirs( &config, &verify_args.public_params_dir, @@ -529,7 +529,7 @@ impl Cli { } let config = get_config(&circom_args.config)?; - log::info!("Configured variables: {:?}", config); + tracing::info!("Configured variables: {:?}", config); set_lurk_dirs(&config, &None, &None, &None, &circom_args.circom_dir); create_circom_gadget(circom_args.circom_folder, circom_args.name)?; @@ -539,6 +539,7 @@ impl Cli { } } +// TODO: deal with `clap_verbosity_flag` and set logger here instead? /// Parses CLI arguments and continues the program flow accordingly pub fn parse_and_run() -> Result<()> { if let Ok(cli) = Cli::try_parse() { diff --git a/src/cli/repl.rs b/src/cli/repl.rs index 9ea2f9fbbd..85c8827228 100644 --- a/src/cli/repl.rs +++ b/src/cli/repl.rs @@ -6,7 +6,6 @@ use std::sync::Arc; use anyhow::{bail, Context, Result}; use camino::{Utf8Path, Utf8PathBuf}; -use log::info; use rustyline::{ error::ReadlineError, history::DefaultHistory, @@ -14,6 +13,7 @@ use rustyline::{ Config, Editor, }; use rustyline_derive::{Completer, Helper, Highlighter, Hinter}; +use tracing::info; use super::{commitment::Commitment, field_data::load, paths::commitment_path}; diff --git a/src/config.rs b/src/config.rs index 2cc71b54ee..a36b6485d5 100644 --- a/src/config.rs +++ b/src/config.rs @@ -8,7 +8,7 @@ fn canned_config_from_env() -> Option { if let Ok(x) = std::env::var("LURK_CANNED_CONFIG") { let canned = CannedConfig::try_from(x.as_str()).ok(); - dbg!(&canned); + tracing::debug!("{:?}", &canned); canned } else { diff --git a/src/eval/mod.rs b/src/eval/mod.rs index b47590b694..d69ba83b2c 100644 --- a/src/eval/mod.rs +++ b/src/eval/mod.rs @@ -11,7 +11,6 @@ use crate::writer::Write; use crate::{lurk_sym_ptr, store}; use lang::Lang; -use log::info; #[cfg(not(target_arch = "wasm32"))] use lurk_macros::serde_test; #[cfg(not(target_arch = "wasm32"))] @@ -20,6 +19,7 @@ use serde::{Deserialize, Serialize}; use std::cmp::PartialEq; use std::iter::{Iterator, Take}; use std::marker::PhantomData; +use tracing::info; pub mod lang; @@ -486,6 +486,7 @@ where Ok(frames) } + #[tracing::instrument(skip_all, name = "Evaluator::generate_frames")] pub fn generate_frames bool>( expr: Ptr, env: Ptr, diff --git a/src/eval/reduction.rs b/src/eval/reduction.rs index bf1359dbe8..b85fe8f756 100644 --- a/src/eval/reduction.rs +++ b/src/eval/reduction.rs @@ -566,7 +566,7 @@ fn reduce_with_witness_inner>( // `fun_form` must be a function or potentially evaluate to one. if !fun_form.is_potentially(ExprTag::Fun) { - dbg!("not potentially fun"); + tracing::debug!("not potentially fun"); Control::Error(expr, env) } else if args.is_nil() { Control::Return( diff --git a/src/eval/tests/mod.rs b/src/eval/tests/mod.rs index 6ca9f680f3..0a52c0920e 100644 --- a/src/eval/tests/mod.rs +++ b/src/eval/tests/mod.rs @@ -2515,29 +2515,29 @@ fn op_syntax_error() { { let expr = format!("({name} . 1)"); - dbg!(&expr); + tracing::debug!("{}", &expr); test_aux::>(s, &expr, None, None, Some(error), None, 1, None); } if !op.supports_arity(0) { let expr = format!("({name})"); - dbg!(&expr); + tracing::debug!("{}", &expr); test_aux::>(s, &expr, None, None, Some(error), None, 1, None); } if !op.supports_arity(1) { let expr = format!("({name} 123)"); - dbg!(&expr); + tracing::debug!("{}", &expr); test_aux::>(s, &expr, None, None, Some(error), None, 1, None); } if !op.supports_arity(2) { let expr = format!("({name} 123 456)"); - dbg!(&expr); + tracing::debug!("{}", &expr); test_aux::>(s, &expr, None, None, Some(error), None, 1, None); } if !op.supports_arity(3) { let expr = format!("({name} 123 456 789)"); - dbg!(&expr); + tracing::debug!("{}", &expr); let iterations = if op.supports_arity(2) { 2 } else { 1 }; test_aux::>(s, &expr, None, None, Some(error), None, iterations, None); } diff --git a/src/hash_witness.rs b/src/hash_witness.rs index 3bd28aebd6..191953839a 100644 --- a/src/hash_witness.rs +++ b/src/hash_witness.rs @@ -450,7 +450,13 @@ impl HashWitness, MAX_CONSES_PER_REDUCTION, F> { if !store.ptr_eq(&hash.cons, &nil).unwrap() { use crate::writer::Write; let cons = hash.cons.fmt_to_string(store, state); - dbg!(hash.cons, cons, name, existing_name); + tracing::debug!( + "{:?} {:?} {:?} {:?}", + hash.cons, + cons, + name, + existing_name + ); panic!("duplicate"); } } @@ -640,7 +646,7 @@ impl ContStub { match self { Self::Dummy => { let continuation = store.fetch_cont(cont)?; - // dbg!("overwriting dummy", continuation, store.hash_cont(&cont)); + // tracing::debug!("overwriting dummy {:?} {:?}", continuation, store.hash_cont(&cont)); *self = Self::Value(Cont { cont_ptr: *cont, continuation, diff --git a/src/lem/var_map.rs b/src/lem/var_map.rs index b47af238e4..82ef94d342 100644 --- a/src/lem/var_map.rs +++ b/src/lem/var_map.rs @@ -1,6 +1,6 @@ use anyhow::{bail, Result}; -use log::info; use std::collections::{hash_map::Entry, HashMap}; +use tracing::info; use super::Var; diff --git a/src/main.rs b/src/main.rs index 2a109420a5..da441c4402 100644 --- a/src/main.rs +++ b/src/main.rs @@ -1,14 +1,24 @@ use anyhow::Result; +use tracing_subscriber::{fmt, prelude::*, EnvFilter, Registry}; +use tracing_texray::TeXRayLayer; fn main() -> Result<()> { // this handle should be held until the end of the program, // do not replace by let _ = ... let _metrics_handle = lurk_metrics::MetricsSink::init(); - pretty_env_logger::init(); + + let subscriber = Registry::default() + .with(fmt::layer().pretty()) + .with(EnvFilter::from_default_env()) + // note: we don't `tracing_texray::examine` anywhere in lurkrs, so no spans are printed *yet* + .with(TeXRayLayer::new()); + tracing::subscriber::set_global_default(subscriber).unwrap(); + println!( "commit: {} {}", env!("VERGEN_GIT_COMMIT_DATE"), env!("VERGEN_GIT_SHA") ); + lurk::cli::parse_and_run() } diff --git a/src/proof/mod.rs b/src/proof/mod.rs index 5b168f1114..57252521ee 100644 --- a/src/proof/mod.rs +++ b/src/proof/mod.rs @@ -38,18 +38,18 @@ pub fn verify_sequential_css>( for (i, (multiframe, cs)) in css.iter().enumerate() { if let Some(prev) = previous_frame { if !prev.precedes(multiframe) { - dbg!(i, "not preceeding frame"); + tracing::debug!("frame {}: not preceeding frame", i); return Ok(false); } } if !cs.is_satisfied() { - dbg!(i, "cs not satisfied"); + tracing::debug!("frame {}: cs not satisfied", i); return Ok(false); } let public_inputs = multiframe.public_inputs(); if !cs.verify(&public_inputs) { - dbg!(i, "cs not verified"); + tracing::debug!("frame {}: cs not verified", i); return Ok(false); } previous_frame = Some(multiframe); diff --git a/src/proof/nova.rs b/src/proof/nova.rs index 26e829020f..4f2f5bc40e 100644 --- a/src/proof/nova.rs +++ b/src/proof/nova.rs @@ -343,6 +343,7 @@ impl<'a, F: LurkField, C: Coprocessor> StepCircuit for MultiFrame<'a, F, C 6 } + #[tracing::instrument(skip_all, name = "::synthesize")] fn synthesize( &self, cs: &mut CS, @@ -418,6 +419,7 @@ where < as Group>::Scalar as ff::PrimeField>::Repr: Abomonation, { /// Proves the computation recursively, generating a recursive SNARK proof. + #[tracing::instrument(skip_all, name = "Proof::prove_recursively")] pub fn prove_recursively( pp: &'a PublicParams<'_, F, C>, store: &'a Store, @@ -441,7 +443,7 @@ where TrivialTestCircuit< as Group>::Scalar>, ) = C1::<'a>::circuits(num_iters_per_step, lang); - dbg!(circuits.len()); + tracing::debug!("circuits.len: {}", circuits.len()); // produce a recursive SNARK let mut recursive_snark: Option, G2, C1<'a, F, C>, C2>> = None; @@ -729,7 +731,7 @@ pub mod tests { let res = proof.verify(&pp, num_steps, &z0, &zi); if res.is_err() { - dbg!(&res); + tracing::debug!("{:?}", &res); } assert!(res.unwrap()); @@ -761,24 +763,24 @@ pub mod tests { let mut cs = TestConstraintSystem::new(); let mut wcs = WitnessCS::new(); - dbg!("synthesizing test cs"); + tracing::debug!("synthesizing test cs"); multiframe.clone().synthesize(&mut cs).unwrap(); - dbg!("synthesizing witness cs"); + tracing::debug!("synthesizing witness cs"); multiframe.clone().synthesize(&mut wcs).unwrap(); if let Some(prev) = previous_frame { assert!(prev.precedes(multiframe)); }; - // dbg!(i); + // tracing::debug!("frame {}" i); let unsat = cs.which_is_unsatisfied(); if unsat.is_some() { // For some reason, this isn't getting printed from within the implementation as expected. // Since we always want to know this information, if the condition occurs, just print it here. - dbg!(unsat); + tracing::debug!("{:?}", unsat); } assert!(cs.is_satisfied()); assert!(cs.verify(&multiframe.public_inputs())); - dbg!("cs is satisfied!"); + tracing::debug!("cs is satisfied!"); let cs_inputs = cs.scalar_inputs(); let cs_aux = cs.scalar_aux(); @@ -1374,23 +1376,23 @@ pub mod tests { if !op.supports_arity(0) { let expr = format!("({name})"); - dbg!(&expr); + tracing::debug!("{:?}", &expr); test_aux::>(s, &expr, None, None, Some(error), None, 1, None); } if !op.supports_arity(1) { let expr = format!("({name} 123)"); - dbg!(&expr); + tracing::debug!("{:?}", &expr); test_aux::>(s, &expr, None, None, Some(error), None, 1, None); } if !op.supports_arity(2) { let expr = format!("({name} 123 456)"); - dbg!(&expr); + tracing::debug!("{:?}", &expr); test_aux::>(s, &expr, None, None, Some(error), None, 1, None); } if !op.supports_arity(3) { let expr = format!("({name} 123 456 789)"); - dbg!(&expr); + tracing::debug!("{:?}", &expr); let iterations = if op.supports_arity(2) { 2 } else { 1 }; test_aux::>(s, &expr, None, None, Some(error), None, iterations, None); } diff --git a/src/public_parameters/mem_cache.rs b/src/public_parameters/mem_cache.rs index 0e821c963a..735156a909 100644 --- a/src/public_parameters/mem_cache.rs +++ b/src/public_parameters/mem_cache.rs @@ -5,10 +5,10 @@ use std::{ use abomonation::{decode, Abomonation}; use camino::Utf8Path; -use log::info; use nova::traits::Group; use once_cell::sync::Lazy; use tap::TapFallible; +use tracing::info; use crate::{ coprocessor::Coprocessor, @@ -66,7 +66,7 @@ impl PublicParamMemCache { if abomonated { match disk_cache.get_raw_bytes(&key) { Ok(mut bytes) => { - info!("Using abomonated public params for lang {lang_key}"); + info!("loading abomonated {lang_key}"); let (pp, rest) = unsafe { decode::>(&mut bytes).unwrap() }; assert!(rest.is_empty()); @@ -78,7 +78,7 @@ impl PublicParamMemCache { // maybe just directly write disk_cache .set_abomonated(&key, &*pp) - .tap_ok(|_| info!("Writing public params to disk-cache: {}", lang_key)) + .tap_ok(|_| info!("writing public params to disk-cache: {}", lang_key)) .map_err(|e| Error::CacheError(format!("Disk write error: {e}")))?; Ok(pp) } @@ -86,13 +86,13 @@ impl PublicParamMemCache { } else { // read the file if it exists, otherwise initialize if let Ok(pp) = disk_cache.get(&key) { - info!("Using disk-cached public params for lang {lang_key}"); + info!("loading abomonated {lang_key}"); Ok(Arc::new(pp)) } else { let pp = default(lang); disk_cache .set(&key, &*pp) - .tap_ok(|_| info!("Writing public params to disk-cache: {}", lang_key)) + .tap_ok(|_| info!("writing public params to disk-cache: {}", lang_key)) .map_err(|e| Error::CacheError(format!("Disk write error: {e}")))?; Ok(pp) } diff --git a/src/repl.rs b/src/repl.rs index 91f9d36bc0..ad1096de9c 100644 --- a/src/repl.rs +++ b/src/repl.rs @@ -289,12 +289,12 @@ pub fn run_repl, F: LurkField, T: ReplTrait, C: Coprocessor Ok((_, expr, is_meta)) => { if is_meta { if let Err(e) = repl.state.handle_meta(s, state.clone(), expr, p) { - eprintln!("!Error: {e:?}"); + eprintln!("!Error: {e}"); }; continue; } else { if let Err(e) = repl.state.handle_non_meta(s, &state.borrow(), expr) { - eprintln!("REPL Error: {e:?}"); + eprintln!("REPL Error: {e}"); } continue; @@ -304,7 +304,7 @@ pub fn run_repl, F: LurkField, T: ReplTrait, C: Coprocessor continue; } Err(e) => { - eprintln!("Read error: {e:?}") + eprintln!("Read error: {e}") } } } @@ -313,7 +313,7 @@ pub fn run_repl, F: LurkField, T: ReplTrait, C: Coprocessor break; } Err(err) => { - eprintln!("Error: {err:?}"); + eprintln!("Error: {err}"); break; } } @@ -626,7 +626,7 @@ impl> ReplTrait for ReplState { } Err(e) => { - eprintln!("Evaluation error: {e:?}"); + eprintln!("Evaluation error: {e}"); Err(e.into()) } } diff --git a/src/store.rs b/src/store.rs index 043b93c344..ad10aa8f53 100644 --- a/src/store.rs +++ b/src/store.rs @@ -1352,6 +1352,7 @@ impl Store { /// Fill the cache for Scalars. Only Ptrs which have been interned since last hydration will be hashed, so it is /// safe to call this incrementally. However, for best proving performance, we should call exactly once so all /// hashing can be batched, e.g. on the GPU. + #[tracing::instrument(skip_all, name = "Store::hydrate_scalar_cache")] pub fn hydrate_scalar_cache(&mut self) { self.ensure_constants(); @@ -2273,7 +2274,7 @@ pub mod test { let sym1 = store.car(&expr).unwrap(); let sss = store.fetch_sym(&sym); let hash = store.hash_expr(&sym); - dbg!(&sym1, &sss, &hash); + tracing::debug!("{:?} {:?} {:?}", &sym1, &sss, &hash); assert_eq!(sym, sym1); } diff --git a/tests/lurk-cli-tests.rs b/tests/lurk-cli-tests.rs index ef51e1fa54..0662881644 100644 --- a/tests/lurk-cli-tests.rs +++ b/tests/lurk-cli-tests.rs @@ -4,6 +4,8 @@ use std::fs::File; use std::io::prelude::*; use std::process::Command; use tempfile::Builder; +use tracing_subscriber::{fmt, prelude::*, EnvFilter, Registry}; +use tracing_texray::TeXRayLayer; fn lurk_cmd() -> Command { Command::cargo_bin("lurk").unwrap() @@ -45,10 +47,15 @@ fn test_bad_command() { #[test] fn test_config_file() { - pretty_env_logger::formatted_builder() - .is_test(true) - .try_init() - .unwrap(); + let subscriber = Registry::default() + .with(fmt::layer().pretty().with_test_writer()) + .with(EnvFilter::from_default_env()) + // note: we don't `tracing_texray::examine` anything below, so no spans are printed + // but we add the layer to allow the option in the future, maybe with a feature? + .with(TeXRayLayer::new()); + + tracing::subscriber::set_global_default(subscriber).unwrap(); + let tmp_dir = Builder::new().prefix("tmp").tempdir().unwrap(); let tmp_dir = Utf8Path::from_path(tmp_dir.path()).unwrap(); let config_dir = tmp_dir.join("lurk.toml");