Merge pull request #1139 from 0xPolygonMiden/andrew-assembler-logging

Add logging to the VM

CHANGELOG.md

@@ -18,6 +18,7 @@
 - Introduced the `Event` decorator and an associated `on_event` handler on the `Host` trait (#1119).
 - Updated Winterfell dependency to v0.7 (#1121).
 - Added methods `StackOutputs::get_stack_item()` and `StackOutputs::get_stack_word()` (#1155).
+- Added [Tracing](https://crates.io/crates/tracing) logger to the VM (#1139).
 
 #### CLI
 - Introduced the `!use` command for the Miden REPL (#1162).

assembly/Cargo.toml

@@ -18,8 +18,9 @@ doctest = false
 
 [features]
 default = ["std"]
-std = ["vm-core/std"]
+std = ["vm-core/std", "tracing/attributes"]
 
 [dependencies]
 num_enum = "0.7"
+tracing = { version = "0.1", default-features = false, optional = true }
 vm-core = { package = "miden-core", path = "../core", version = "0.8", default-features = false }

assembly/src/assembler/mod.rs

@@ -1,3 +1,5 @@
+#[cfg(feature = "std")]
+use super::ast::instrument;
 use super::{
     ast::{Instruction, ModuleAst, Node, ProcedureAst, ProgramAst},
     btree_map,
@@ -139,6 +141,7 @@ impl Assembler {
     ///
     /// # Errors
     /// Returns an error if the compilation of the specified program fails.
+    #[cfg_attr(feature = "std", instrument("Compile AST", skip_all))]
     pub fn compile_ast(&self, program: &ProgramAst) -> Result<Program, AssemblyError> {
         // compile the program
         let mut context = AssemblyContext::for_program(Some(program));
@@ -194,6 +197,9 @@ impl Assembler {
     /// - If a module with the same path already exists in the module stack of the
     ///   [AssemblyContext].
     /// - If a lock to the [ProcedureCache] can not be attained.
+    #[cfg_attr(feature = "std", instrument(level = "trace", 
+                 name = "Compiling module", 
+                 fields(module = path.unwrap_or(&LibraryPath::anon_path()).path()), skip_all))]
     pub fn compile_module(
         &self,
         module: &ModuleAst,

assembly/src/ast/mod.rs

@@ -2,7 +2,6 @@
 //!
 //! Structs in this module (specifically [ProgramAst] and [ModuleAst]) can be used to parse source
 //! code into relevant ASTs. This can be done via their `parse()` methods.
-
 use super::{
     crypto::hash::RpoDigest, BTreeMap, ByteReader, ByteWriter, Deserializable,
     DeserializationError, Felt, LabelError, LibraryPath, ParsingError, ProcedureId, ProcedureName,
@@ -11,6 +10,9 @@ use super::{
 };
 use vm_core::utils::bound_into_included_u64;
 
+#[cfg(feature = "std")]
+pub use tracing::{event, info_span, instrument, Level};
+
 pub use super::tokens::SourceLocation;
 
 mod nodes;
@@ -91,3 +93,17 @@ fn sort_procs_into_vec(proc_map: LocalProcMap) -> Vec<ProcedureAst> {
 
     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) {
+            event!(Level::WARN, "unused import: \"{}\"", lib);
+        }
+    }
+}

assembly/src/ast/module.rs

@@ -1,3 +1,5 @@
+#[cfg(feature = "std")]
+use super::check_unused_imports;
 use super::{
     format::*,
     imports::ModuleImports,
@@ -10,6 +12,7 @@ use super::{
         String, ToString, Token, TokenStream, Vec,
     },
 };
+
 use core::{fmt, str::from_utf8};
 use vm_core::utils::Serializable;
 
@@ -107,6 +110,9 @@ impl ModuleAst {
         // get module docs and make sure the size is within the limit
         let docs = tokens.take_module_comments();
 
+        #[cfg(feature = "std")]
+        check_unused_imports(context.import_info);
+
         Ok(Self::new(local_procs, reexported_procs, docs)?.with_import_info(import_info))
     }
 

assembly/src/ast/program.rs

@@ -16,10 +16,13 @@ use super::{
         SliceReader, Token, TokenStream, Vec,
     },
 };
+
 use core::{fmt, iter};
 #[cfg(feature = "std")]
-use std::{fs, io, path::Path};
-
+use {
+    super::{check_unused_imports, instrument},
+    std::{fs, io, path::Path},
+};
 // PROGRAM AST
 // ================================================================================================
 
@@ -120,6 +123,7 @@ impl ProgramAst {
     /// Parses the provided source into a [ProgramAst].
     ///
     /// A program consist of a body and a set of internal (i.e., not exported) procedures.
+    #[cfg_attr(feature = "std", instrument(name = "Parsing program", skip_all))]
     pub fn parse(source: &str) -> Result<ProgramAst, ParsingError> {
         let mut tokens = TokenStream::new(source)?;
         let mut import_info = ModuleImports::parse(&mut tokens)?;
@@ -178,6 +182,9 @@ 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)?

assembly/src/library/masl.rs

@@ -1,3 +1,5 @@
+#[cfg(feature = "std")]
+use super::super::ast::instrument;
 use super::{
     super::BTreeSet, AstSerdeOptions, ByteReader, ByteWriter, Deserializable, DeserializationError,
     Library, LibraryError, LibraryNamespace, LibraryPath, Module, ModuleAst, Serializable, Vec,
@@ -184,6 +186,7 @@ mod use_std {
         }
 
         /// Read a library from a file.
+        #[instrument(name = "Reading library file", fields(path = %path.as_ref().display()))]
         pub fn read_from_file<P>(path: P) -> Result<MaslLibrary, LibraryError>
         where
             P: AsRef<Path>,

assembly/src/library/path.rs

@@ -86,6 +86,11 @@ impl LibraryPath {
     // PUBLIC ACCESSORS
     // --------------------------------------------------------------------------------------------
 
+    /// Returns the full path of the Library
+    pub fn path(&self) -> &str {
+        &self.path
+    }
+
     /// Returns the first component of the path.
     ///
     /// The first component is the leftmost token separated by `::`.

docs/src/intro/usage.md

@@ -85,6 +85,13 @@ For example:
 
 To execute a program using the Miden VM there needs to be a `.masm` file containing the Miden Assembly code and a `.inputs` file containing the inputs.
 
+#### Enabling logging
+You can use `MIDEN_LOG` environment variable to control how much logging output the VM produces. For example:
+```
+MIDEN_LOG=trace ./target/optimized/miden [subcommand] [parameters]
+```
+If the level is not specified, `warn` level is set as default. 
+
 ### Inputs
 
 As described [here](https://0xpolygonmiden.github.io/miden-vm/intro/overview.html#inputs-and-outputs) the Miden VM can consume public and secret inputs.

miden/Cargo.toml

@@ -40,24 +40,25 @@ path = "tests/integration/main.rs"
 [features]
 concurrent = ["prover/concurrent", "std"]
 default = ["std"]
-executable = ["dep:env_logger", "dep:hex", "hex?/std", "std", "dep:serde", "serde?/std", "dep:serde_derive", "dep:serde_json", "serde_json?/std", "dep:clap", "dep:rustyline"]
+executable = ["dep:hex", "hex?/std", "std", "dep:serde", "serde?/std", "dep:serde_derive", "dep:serde_json", "serde_json?/std", "dep:clap", "dep:rustyline"]
 metal = ["prover/metal", "std"]
-std = ["assembly/std", "log/std", "processor/std", "prover/std", "verifier/std"]
+std = ["assembly/std", "processor/std", "prover/std", "tracing/attributes", "verifier/std"]
 
 [dependencies]
 assembly = { package = "miden-assembly", path = "../assembly", version = "0.8", default-features = false }
 blake3 = "1.5"
 clap = { version = "4.4", features = ["derive"], optional = true }
-env_logger = { version = "0.10", default-features = false, optional = true }
 hex = { version = "0.4", optional = true }
-log = { version = "0.4", default-features = false, optional = true }
 processor = { package = "miden-processor", path = "../processor", version = "0.8", default-features = false }
 prover = { package = "miden-prover", path = "../prover", version = "0.8", default-features = false }
 rustyline = { version = "13.0", default-features = false, optional = true }
 serde = {version = "1.0", optional = true }
 serde_derive = {version = "1.0", optional = true }
 serde_json = {version = "1.0", optional = true }
 stdlib = { package = "miden-stdlib", path = "../stdlib", version = "0.8", default-features = false }
+tracing = { version = "0.1", default-features = false, optional = true }
+tracing-subscriber = { version = "0.3", features = ["std", "env-filter"] }
+tracing-forest = { version = "0.1", features = ["ansi", "smallvec"] }
 verifier = { package = "miden-verifier", path = "../verifier", version = "0.8", default-features = false }
 vm-core = { package = "miden-core", path = "../core", version = "0.8", default-features = false }