From c27c5fcf66f435478ae77a90ecb65c9918b3af98 Mon Sep 17 00:00:00 2001 From: Andrey Khmuro Date: Mon, 13 Nov 2023 22:31:34 +0100 Subject: [PATCH] refactor: change print to log --- assembly/src/assembler/mod.rs | 16 +++++-- assembly/src/ast/mod.rs | 20 ++++++++- miden/examples/logger/logger.inputs | 3 ++ miden/examples/logger/logger.masl | Bin 0 -> 135 bytes miden/examples/logger/logger.masm | 6 +++ miden/examples/merkle_store/merkle_store.masm | 7 ---- miden/src/cli/bundle.rs | 8 ++-- miden/src/cli/compile.rs | 8 ++-- miden/src/cli/data.rs | 39 +++++++++--------- miden/src/cli/debug/mod.rs | 12 +++--- miden/src/cli/prove.rs | 14 +++---- miden/src/cli/run.rs | 16 +++---- miden/src/cli/verify.rs | 10 ++--- miden/src/main.rs | 5 ++- 14 files changed, 96 insertions(+), 68 deletions(-) create mode 100644 miden/examples/logger/logger.inputs create mode 100644 miden/examples/logger/logger.masl create mode 100644 miden/examples/logger/logger.masm diff --git a/assembly/src/assembler/mod.rs b/assembly/src/assembler/mod.rs index dba05fd9d8..e4957d4f17 100644 --- a/assembly/src/assembler/mod.rs +++ b/assembly/src/assembler/mod.rs @@ -9,6 +9,9 @@ use super::{ use core::{borrow::Borrow, cell::RefCell}; use vm_core::{utils::group_vector_elements, Decorator, DecoratorList}; +#[cfg(feature = "std")] +use std::time::Instant; + mod instruction; mod module_provider; @@ -200,6 +203,9 @@ impl Assembler { path: Option<&LibraryPath>, context: &mut AssemblyContext, ) -> Result, AssemblyError> { + #[cfg(feature = "std")] + let now = Instant::now(); + // a variable to track MAST roots of all procedures exported from this module let mut proc_roots = Vec::new(); context.begin_module(path.unwrap_or(&LibraryPath::anon_path()), module)?; @@ -264,10 +270,12 @@ impl Assembler { } } - // log the completion of the module - log::debug!( - "\n - Module \"{}\" has been compiled", - path.unwrap_or(&LibraryPath::anon_path()) + // log the module compilation completion + #[cfg(feature = "std")] + log::trace!( + "\n- Compiled \"{}\" module in {} ms", + path.unwrap_or(&LibraryPath::anon_path()), + now.elapsed().as_millis() ); Ok(proc_roots) diff --git a/assembly/src/ast/mod.rs b/assembly/src/ast/mod.rs index 4a6be8bb65..faff0c4d6d 100644 --- a/assembly/src/ast/mod.rs +++ b/assembly/src/ast/mod.rs @@ -7,7 +7,7 @@ use super::{ crypto::hash::RpoDigest, BTreeMap, ByteReader, ByteWriter, Deserializable, DeserializationError, Felt, LabelError, LibraryPath, ParsingError, ProcedureId, ProcedureName, Serializable, SliceReader, StarkField, String, ToString, Token, TokenStream, Vec, - MAX_LABEL_LEN, + MAX_LABEL_LEN, }; use core::{fmt, iter, str::from_utf8}; #[cfg(feature = "std")] @@ -224,8 +224,12 @@ impl ProgramAst { return Err(ParsingError::dangling_ops_after_program(token)); } + #[cfg(feature = "std")] + check_unused_imports(context.import_info); + let local_procs = sort_procs_into_vec(context.local_procs); let (nodes, locations) = body.into_parts(); + Ok(Self::new(nodes, local_procs)? .with_source_locations(locations, start) .with_import_info(import_info)) @@ -938,3 +942,17 @@ fn sort_procs_into_vec(proc_map: LocalProcMap) -> Vec { procedures.into_iter().map(|(_idx, proc)| proc).collect() } + +/// Logging a warning message for every imported but unused module. +#[cfg(feature = "std")] +fn check_unused_imports(import_info: &ModuleImports) { + let import_lib_paths = import_info.import_paths(); + let invoked_procs_paths: Vec<&LibraryPath> = + import_info.invoked_procs().iter().map(|(_id, (_name, path))| path).collect(); + + for lib in import_lib_paths { + if !invoked_procs_paths.contains(&lib) { + log::warn!("\nwarning: unused imports: \"{}\"", lib); + } + } +} diff --git a/miden/examples/logger/logger.inputs b/miden/examples/logger/logger.inputs new file mode 100644 index 0000000000..bc0dadb254 --- /dev/null +++ b/miden/examples/logger/logger.inputs @@ -0,0 +1,3 @@ +{ + "operand_stack": [] +} diff --git a/miden/examples/logger/logger.masl b/miden/examples/logger/logger.masl new file mode 100644 index 0000000000000000000000000000000000000000..bceabef66704d6c82e23343ae70435ec4c464115 GIT binary patch literal 135 zcmZR}%}*)KNo8PQWB>ss22O^8#F7jvtNc8mAOtWnFefDzft4^aY-D0)fvG7e&j*PL yGC&NmvO?0z$Z)h}@r*O4%mS~zntS=(MRlX6d`(?2gP7Cu!CHa3H!?9YF#rJ4 Result<(), String> { - println!("============================================================"); - println!("Build library"); - println!("============================================================"); + log::info!("============================================================\n"); + log::info!("Build library\n"); + log::info!("============================================================\n"); let namespace = match &self.namespace { Some(namespace) => namespace.to_string(), @@ -50,7 +50,7 @@ impl BundleCmd { // write the masl output stdlib.write_to_dir(self.dir.clone()).map_err(|e| e.to_string())?; - println!("Built library {}", namespace); + log::info!("Built library {}\n", namespace); Ok(()) } diff --git a/miden/src/cli/compile.rs b/miden/src/cli/compile.rs index 7b0de2e6ce..1761d310b5 100644 --- a/miden/src/cli/compile.rs +++ b/miden/src/cli/compile.rs @@ -19,9 +19,9 @@ pub struct CompileCmd { impl CompileCmd { pub fn execute(&self) -> Result<(), String> { - println!("============================================================"); - println!("Compile program"); - println!("============================================================"); + log::info!("============================================================\n"); + log::info!("Compile program\n"); + log::info!("============================================================\n"); // load the program from file and parse it let program = ProgramFile::read(&self.assembly_file)?; @@ -34,7 +34,7 @@ impl CompileCmd { // report program hash to user let program_hash: [u8; 32] = compiled_program.hash().into(); - println!("program hash is {}", hex::encode(program_hash)); + log::info!("program hash is {}\n", hex::encode(program_hash)); // write the compiled file program.write(self.output_file.clone()) diff --git a/miden/src/cli/data.rs b/miden/src/cli/data.rs index 0ff8927781..a625ea2e27 100644 --- a/miden/src/cli/data.rs +++ b/miden/src/cli/data.rs @@ -10,7 +10,7 @@ use serde_derive::{Deserialize, Serialize}; use std::{ collections::HashMap, fs, - io::{stdout, Write}, + io::Write, path::{Path, PathBuf}, time::Instant, }; @@ -100,7 +100,7 @@ impl InputFile { None => program_path.with_extension("inputs"), }; - println!("Reading input file `{}`", path.display()); + log::info!("Reading input file `{}`\n", path.display()); // read input file to string let inputs_file = fs::read_to_string(&path) @@ -199,15 +199,15 @@ impl InputFile { let tree = MerkleTree::new(leaves) .map_err(|e| format!("failed to parse a Merkle tree: {e}"))?; merkle_store.extend(tree.inner_nodes()); - println!("Added Merkle tree with root {} to the Merkle store", tree.root()); + log::trace!("Added Merkle tree with root {} to the Merkle store\n", tree.root()); } MerkleData::SparseMerkleTree(data) => { let entries = Self::parse_sparse_merkle_tree(data)?; let tree = SimpleSmt::with_leaves(u64::BITS as u8, entries) .map_err(|e| format!("failed to parse a Sparse Merkle Tree: {e}"))?; merkle_store.extend(tree.inner_nodes()); - println!( - "Added Sparse Merkle tree with root {} to the Merkle store", + log::trace!( + "Added Sparse Merkle tree with root {} to the Merkle store\n", tree.root() ); } @@ -216,8 +216,8 @@ impl InputFile { let tree = PartialMerkleTree::with_leaves(entries) .map_err(|e| format!("failed to parse a Partial Merkle Tree: {e}"))?; merkle_store.extend(tree.inner_nodes()); - println!( - "Added Partial Merkle tree with root {} to the Merkle store", + log::trace!( + "Added Partial Merkle tree with root {} to the Merkle store\n", tree.root() ); } @@ -324,7 +324,7 @@ impl OutputFile { None => program_path.with_extension("outputs"), }; - println!("Reading output file `{}`", path.display()); + log::info!("Reading output file `{}`\n", path.display()); // read outputs file to string let outputs_file = fs::read_to_string(&path) @@ -340,13 +340,13 @@ impl OutputFile { /// Write the output file pub fn write(stack_outputs: &StackOutputs, path: &PathBuf) -> Result<(), String> { // if path provided, create output file - println!("Creating output file `{}`", path.display()); + log::info!("Creating output file `{}`\n", path.display()); let file = fs::File::create(&path).map_err(|err| { format!("Failed to create output file `{}` - {}", path.display(), err) })?; - println!("Writing data to output file"); + log::info!("Writing data to output file\n"); // write outputs to output file serde_json::to_writer_pretty(file, &Self::new(stack_outputs)) @@ -381,17 +381,17 @@ impl ProgramFile { /// Reads the masm file at the specified path and parses it into a [ProgramAst]. pub fn read(path: &PathBuf) -> Result { // read program file to string - println!("Reading program file `{}`", path.display()); + log::info!("Reading program file `{}`\n", path.display()); let source = fs::read_to_string(&path) .map_err(|err| format!("Failed to open program file `{}` - {}", path.display(), err))?; // parse the program into an AST - print!("Parsing program... "); + log::info!("Parsing program... "); let now = Instant::now(); let ast = ProgramAst::parse(&source).map_err(|err| { format!("Failed to parse program file `{}` - {}", path.display(), err) })?; - println!("done ({} ms)", now.elapsed().as_millis()); + log::info!("\ndone ({} ms)\n", now.elapsed().as_millis()); Ok(Self { ast, @@ -405,8 +405,7 @@ impl ProgramFile { I: IntoIterator, L: Library, { - print!("Compiling program... "); - stdout().flush().expect("Couldn't flush stdout"); + log::info!("Compiling program... "); let now = Instant::now(); // compile program @@ -423,7 +422,7 @@ impl ProgramFile { .compile_ast(&self.ast) .map_err(|err| format!("Failed to compile program - {}", err))?; - println!("done ({} ms)", now.elapsed().as_millis()); + log::info!("\ndone ({} ms)\n", now.elapsed().as_millis()); Ok(program) } @@ -462,7 +461,7 @@ impl ProofFile { None => program_path.with_extension("proof"), }; - println!("Reading proof file `{}`", path.display()); + log::info!("Reading proof file `{}`\n", path.display()); // read the file to bytes let file = fs::read(&path) @@ -486,7 +485,7 @@ impl ProofFile { None => program_path.with_extension("proof"), }; - println!("Creating proof file `{}`", path.display()); + log::info!("Creating proof file `{}`\n", path.display()); // create output fille let mut file = fs::File::create(&path) @@ -494,7 +493,7 @@ impl ProofFile { let proof_bytes = proof.to_bytes(); - println!("Writing data to proof file - size {} KB", proof_bytes.len() / 1024); + log::info!("Writing data to proof file - size {} KB\n", proof_bytes.len() / 1024); // write proof bytes to file file.write_all(&proof_bytes).unwrap(); @@ -542,7 +541,7 @@ impl Libraries { let mut libraries = Vec::new(); for path in paths { - println!("Reading library file `{}`", path.as_ref().display()); + log::info!("Reading library file `{}`\n", path.as_ref().display()); let library = MaslLibrary::read_from_file(path) .map_err(|e| format!("Failed to read library: {e}"))?; diff --git a/miden/src/cli/debug/mod.rs b/miden/src/cli/debug/mod.rs index bd683fde29..fe5df15ba3 100644 --- a/miden/src/cli/debug/mod.rs +++ b/miden/src/cli/debug/mod.rs @@ -28,9 +28,9 @@ pub struct DebugCmd { impl DebugCmd { pub fn execute(&self) -> Result<(), String> { - println!("============================================================"); - println!("Debug program"); - println!("============================================================"); + log::info!("============================================================\n"); + log::info!("Debug program\n"); + log::info!("============================================================\n"); // load libraries from files let libraries = Libraries::new(&self.library_paths)?; @@ -40,7 +40,7 @@ impl DebugCmd { ProgramFile::read(&self.assembly_file)?.compile(&Debug::On, libraries.libraries)?; let program_hash: [u8; 32] = program.hash().into(); - println!("Debugging program with hash {}... ", hex::encode(program_hash)); + log::info!("Debugging program with hash {}... \n", hex::encode(program_hash)); // load input data from file let input_data = InputFile::read(&self.input_file, &self.assembly_file)?; @@ -63,14 +63,14 @@ impl DebugCmd { let mut rl = DefaultEditor::with_config(rl_config).expect("Readline couldn't be initialized"); - println!("Welcome! Enter `h` for help."); + log::info!("Welcome! Enter `h` for help.\n"); loop { match rl.readline(">> ") { Ok(command) => match DebugCommand::parse(&command) { Ok(Some(command)) => { if !debug_executor.execute(command) { - println!("Debugging complete"); + log::info!("Debugging complete\n"); break; } } diff --git a/miden/src/cli/prove.rs b/miden/src/cli/prove.rs index 0c13cbf8d1..82409812f6 100644 --- a/miden/src/cli/prove.rs +++ b/miden/src/cli/prove.rs @@ -61,9 +61,9 @@ impl ProveCmd { } pub fn execute(&self) -> Result<(), String> { - println!("============================================================"); - println!("Prove program"); - println!("============================================================"); + log::info!("============================================================\n"); + log::info!("Prove program\n"); + log::info!("============================================================\n"); // load libraries from files let libraries = Libraries::new(&self.library_paths)?; @@ -76,7 +76,7 @@ impl ProveCmd { let input_data = InputFile::read(&self.input_file, &self.assembly_file)?; let program_hash: [u8; 32] = program.hash().into(); - println!("Proving program with hash {}...", hex::encode(program_hash)); + log::info!("Proving program with hash {}...\n", hex::encode(program_hash)); let now = Instant::now(); // fetch the stack and program inputs from the arguments @@ -90,8 +90,8 @@ impl ProveCmd { prover::prove(&program, stack_inputs, host, proving_options) .map_err(|err| format!("Failed to prove program - {:?}", err))?; - println!( - "Program with hash {} proved in {} ms", + log::info!( + "Program with hash {} proved in {} ms\n", hex::encode(program_hash), now.elapsed().as_millis() ); @@ -111,7 +111,7 @@ impl ProveCmd { OutputFile::write(&stack_outputs, &self.assembly_file.with_extension("outputs"))?; // print stack outputs to screen. - println!("Output: {:?}", stack); + log::info!("Output: {:?}\n", stack); } Ok(()) diff --git a/miden/src/cli/run.rs b/miden/src/cli/run.rs index f123093dd2..c239df75b8 100644 --- a/miden/src/cli/run.rs +++ b/miden/src/cli/run.rs @@ -37,9 +37,9 @@ pub struct RunCmd { impl RunCmd { pub fn execute(&self) -> Result<(), String> { - println!("============================================================"); - println!("Run program"); - println!("============================================================"); + log::info!("============================================================\n"); + log::info!("Run program\n"); + log::info!("============================================================\n"); // load libraries from files let libraries = Libraries::new(&self.library_paths)?; @@ -60,21 +60,21 @@ impl RunCmd { let host = DefaultHost::new(input_data.parse_advice_provider()?); let program_hash: [u8; 32] = program.hash().into(); - print!("Executing program with hash {}... ", hex::encode(program_hash)); + log::info!("Executing program with hash {}... ", hex::encode(program_hash)); let now = Instant::now(); // execute program and generate outputs let trace = processor::execute(&program, stack_inputs, host, execution_options) .map_err(|err| format!("Failed to generate execution trace = {:?}", err))?; - println!("done ({} ms)", now.elapsed().as_millis()); + log::info!("done ({} ms)\n", now.elapsed().as_millis()); if let Some(output_path) = &self.output_file { // write outputs to file if one was specified OutputFile::write(trace.stack_outputs(), output_path)?; } else { // write the stack outputs to the screen. - println!("Output: {:?}", trace.stack_outputs().stack_truncated(self.num_outputs)); + log::info!("Output: {:?}\n", trace.stack_outputs().stack_truncated(self.num_outputs)); } // calculate the percentage of padded rows @@ -83,7 +83,7 @@ impl RunCmd { * 100 / trace.trace_len_summary().padded_trace_len(); // print the required cycles for each component - println!( + log::info!( "VM cycles: {} extended to {} steps ({}% padding). ├── Stack rows: {} ├── Range checker rows: {} @@ -91,7 +91,7 @@ impl RunCmd { ├── Hash chiplet rows: {} ├── Bitwise chiplet rows: {} ├── Memory chiplet rows: {} - └── Kernel ROM rows: {}", + └── Kernel ROM rows: {}\n", trace.trace_len_summary().trace_len(), trace.trace_len_summary().padded_trace_len(), padding_percentage, diff --git a/miden/src/cli/verify.rs b/miden/src/cli/verify.rs index 9e81863b26..90e6361556 100644 --- a/miden/src/cli/verify.rs +++ b/miden/src/cli/verify.rs @@ -22,9 +22,9 @@ pub struct VerifyCmd { impl VerifyCmd { pub fn execute(&self) -> Result<(), String> { - println!("============================================================"); - println!("Verify program"); - println!("============================================================"); + log::info!("============================================================\n"); + log::info!("Verify program\n"); + log::info!("============================================================\n"); // read program hash from input let program_hash = ProgramHash::read(&self.program_hash)?; @@ -41,7 +41,7 @@ impl VerifyCmd { // load proof from file let proof = ProofFile::read(&Some(self.proof_file.clone()), &self.proof_file)?; - println!("verifying program..."); + log::info!("verifying program...\n"); let now = Instant::now(); // TODO accept kernel as CLI argument @@ -52,7 +52,7 @@ impl VerifyCmd { verifier::verify(program_info, stack_inputs, outputs_data.stack_outputs()?, proof) .map_err(|err| format!("Program failed verification! - {}", err))?; - println!("Verification complete in {} ms", now.elapsed().as_millis()); + log::info!("Verification complete in {} ms\n", now.elapsed().as_millis()); Ok(()) } diff --git a/miden/src/main.rs b/miden/src/main.rs index 9e51f05725..41462add05 100644 --- a/miden/src/main.rs +++ b/miden/src/main.rs @@ -57,11 +57,12 @@ pub fn main() { // configure logging // if logging level is not specified, set level to "warn" if std::env::var("MIDEN_LOG").is_err() { - std::env::set_var("MIDEN_LOG", "warn"); + std::env::set_var("MIDEN_LOG", "info"); } // use "MIDEN_LOG" environment variable to change the logging level env_logger::Builder::from_env("MIDEN_LOG") - .format(|buf, record| writeln!(buf, "{}", record.args())) + .target(env_logger::Target::Stdout) + .format(|buf, record| write!(buf, "{}", record.args())) .init(); // execute cli action