Clean up logging (#195)

* fix backoff

* fix logging

* more small fixes

* enforce as clippy rules

clippy.toml

@@ -4,4 +4,13 @@ disallowed-types = [
     "std::collections::HashSet",
     # prefer instant crate, it works on wasm
     "std::time::Instant",
+]
+
+disallowed-macros = [
+    # only allowed in main.rs
+    "std::print",
+    "std::println",
+    # use log crate instead
+    "std::eprint",
+    "std::eprintln",
 ]

src/lib.rs

@@ -217,6 +217,7 @@ pub struct EGraph {
     pub global_bindings: HashMap<Symbol, (ArcSort, Value, u32)>,
     extract_report: Option<ExtractReport>,
     run_report: Option<RunReport>,
+    msgs: Vec<String>,
 }
 
 #[derive(Clone, Debug)]
@@ -251,6 +252,7 @@ impl Default for EGraph {
             seminaive: true,
             extract_report: None,
             run_report: None,
+            msgs: Default::default(),
         };
         egraph.rulesets.insert("".into(), Default::default());
         egraph
@@ -514,7 +516,8 @@ impl EGraph {
         Ok((terms, termdag))
     }
 
-    pub fn print_function(&mut self, sym: Symbol, n: usize) -> Result<String, Error> {
+    pub fn print_function(&mut self, sym: Symbol, n: usize) -> Result<(), Error> {
+        log::info!("Printing up to {n} tuples of table {sym}: ");
         let (terms_with_outputs, termdag) = self.function_to_dag(sym, n)?;
         let f = self
             .functions
@@ -524,20 +527,34 @@ impl EGraph {
 
         let mut buf = String::new();
         let s = &mut buf;
+        s.push_str("(\n");
+        if terms_with_outputs.is_empty() {
+            log::info!("   (none)");
+        }
         for (term, output) in terms_with_outputs {
-            write!(s, "{}", termdag.to_string(&term)).unwrap();
-            if !out_is_unit {
-                write!(s, " -> {}", termdag.to_string(&output)).unwrap();
-            }
+            let tuple_str = format!(
+                "   {}{}",
+                termdag.to_string(&term),
+                if !out_is_unit {
+                    termdag.to_string(&output)
+                } else {
+                    "".into()
+                },
+            );
+            log::info!("{}", tuple_str);
+            s.push_str(&tuple_str);
             s.push('\n');
         }
-
-        Ok(buf)
+        s.push_str(")\n");
+        self.print_msg(buf);
+        Ok(())
     }
 
-    pub fn print_size(&self, sym: Symbol) -> Result<String, Error> {
+    pub fn print_size(&mut self, sym: Symbol) -> Result<(), Error> {
         let f = self.functions.get(&sym).ok_or(TypeError::Unbound(sym))?;
-        Ok(format!("Function {} has size {}", sym, f.nodes.len()))
+        log::info!("Function {} has size {}", sym, f.nodes.len());
+        self.print_msg(f.nodes.len().to_string());
+        Ok(())
     }
 
     // returns whether the egraph was updated
@@ -888,7 +905,7 @@ impl EGraph {
         }
     }
 
-    fn run_command(&mut self, command: NCommand, should_run: bool) -> Result<String, Error> {
+    fn run_command(&mut self, command: NCommand, should_run: bool) -> Result<(), Error> {
         let pre_rebuild = Instant::now();
         self.extract_report = None;
         self.run_report = None;
@@ -904,47 +921,47 @@ impl EGraph {
 
         self.extract_report = None;
         self.run_report = None;
-        let res = Ok(match command {
+        match command {
             NCommand::SetOption { name, value } => {
                 let str = format!("Set option {} to {}", name, value);
                 self.set_option(name.into(), value);
-                str
+                log::info!("{}", str)
             }
             // Sorts are already declared during typechecking
-            NCommand::Sort(name, _presort_and_args) => format!("Declared sort {}.", name),
+            NCommand::Sort(name, _presort_and_args) => log::info!("Declared sort {}.", name),
             NCommand::Function(fdecl) => {
                 self.declare_function(&fdecl)?;
-                format!("Declared function {}.", fdecl.name)
+                log::info!("Declared function {}.", fdecl.name)
             }
             NCommand::AddRuleset(name) => {
                 self.add_ruleset(name);
-                format!("Declared ruleset {name}.")
+                log::info!("Declared ruleset {name}.");
             }
             NCommand::NormRule {
                 ruleset,
                 rule,
                 name,
             } => {
                 self.add_rule(rule.to_rule(), ruleset)?;
-                format!("Declared rule {name}.")
+                log::info!("Declared rule {name}.")
             }
             NCommand::RunSchedule(sched) => {
                 if should_run {
                     self.run_report = Some(self.run_schedule(&sched));
-                    format!("Ran schedule {}.", sched)
+                    log::info!("Ran schedule {}.", sched)
                 } else {
-                    "Skipping schedule.".to_string()
+                    log::warn!("Skipping schedule.")
                 }
             }
             NCommand::Check(facts) => {
                 if should_run {
                     self.check_facts(&facts)?;
-                    "Checked.".into()
+                    log::info!("Checked fact {:?}.", facts);
                 } else {
-                    "Skipping check.".into()
+                    log::warn!("Skipping check.")
                 }
             }
-            NCommand::CheckProof => "TODO implement proofs".into(),
+            NCommand::CheckProof => log::error!("TODO implement proofs"),
             NCommand::NormAction(action) => {
                 if should_run {
                     match &action {
@@ -979,36 +996,30 @@ impl EGraph {
                             self.eval_actions(std::slice::from_ref(&action.to_action()))?;
                         }
                     }
-                    "".to_string()
                 } else {
-                    format!("Skipping running {action}.")
+                    log::warn!("Skipping running {action}.")
                 }
             }
             NCommand::Push(n) => {
                 (0..n).for_each(|_| self.push());
-                format!("Pushed {n} levels.")
+                log::info!("Pushed {n} levels.")
             }
             NCommand::Pop(n) => {
                 for _ in 0..n {
                     self.pop()?;
                 }
-                format!("Popped {n} levels.")
+                log::info!("Popped {n} levels.")
             }
             NCommand::PrintTable(f, n) => {
-                let msg = self.print_function(f, n)?;
-                println!("{}", msg);
-                msg
+                self.print_function(f, n)?;
             }
             NCommand::PrintSize(f) => {
-                let msg = self.print_size(f)?;
-                println!("{}", msg);
-                msg
+                self.print_size(f)?;
             }
             NCommand::Fail(c) => {
                 let result = self.run_command(*c, should_run);
                 if let Err(e) = result {
-                    eprintln!("Expect failure: {}", e);
-                    "Command failed as expected".into()
+                    log::info!("Command failed as expected: {}", e);
                 } else {
                     return Err(Error::ExpectFail);
                 }
@@ -1064,7 +1075,7 @@ impl EGraph {
                     });
                 }
                 self.eval_actions(&actions)?;
-                format!("Read {} facts into {name} from '{file}'.", actions.len())
+                log::info!("Read {} facts into {name} from '{file}'.", actions.len())
             }
             NCommand::Output { file, exprs } => {
                 let mut filename = self.fact_directory.clone().unwrap_or_default();
@@ -1084,11 +1095,10 @@ impl EGraph {
                         .map_err(|e| Error::IoError(filename.clone(), e))?;
                 }
 
-                format!("Output to '{filename:?}'.")
+                log::info!("Output to '{filename:?}'.")
             }
-        });
-
-        res
+        };
+        Ok(())
     }
 
     pub fn clear(&mut self) {
@@ -1185,25 +1195,19 @@ impl EGraph {
     }
 
     pub fn run_program(&mut self, program: Vec<Command>) -> Result<Vec<String>, Error> {
-        let mut msgs = vec![];
         let should_run = true;
 
         for command in program {
             // Important to process each command individually
             // because push and pop create new scopes
             for processed in self.process_command(command, CompilerPassStop::All)? {
-                let msg = self.run_command(processed.command, should_run)?;
-                if !msg.is_empty() {
-                    log::info!("{}", msg);
-                }
-                msgs.push(msg);
+                self.run_command(processed.command, should_run)?;
             }
         }
         log::logger().flush();
 
         // remove consecutive empty lines
-        msgs.dedup_by(|a, b| a.is_empty() && b.is_empty());
-        Ok(msgs)
+        Ok(self.flush_msgs())
     }
 
     // this is bad because we shouldn't inspect values like this, we should use type information
@@ -1252,6 +1256,15 @@ impl EGraph {
         serialized.inline_leaves();
         serialized
     }
+
+    pub(crate) fn print_msg(&mut self, msg: String) {
+        self.msgs.push(msg);
+    }
+
+    fn flush_msgs(&mut self) -> Vec<String> {
+        self.msgs.dedup_by(|a, b| a.is_empty() && b.is_empty());
+        std::mem::take(&mut self.msgs)
+    }
 }
 
 #[derive(Debug, Error)]

src/main.rs

@@ -29,6 +29,7 @@ struct Args {
     to_svg: bool,
 }
 
+#[allow(clippy::disallowed_macros)]
 fn main() {
     env_logger::Builder::new()
         .filter_level(log::LevelFilter::Info)
@@ -60,7 +61,11 @@ fn main() {
         for line in BufReader::new(stdin).lines() {
             match line {
                 Ok(line_str) => match egraph.parse_and_run_program(&line_str) {
-                    Ok(_msgs) => {}
+                    Ok(msgs) => {
+                        for msg in msgs {
+                            println!("{msg}");
+                        }
+                    }
                     Err(err) => {
                         log::error!("{}", err);
                     }
@@ -72,7 +77,7 @@ fn main() {
             }
             log::logger().flush();
             if egraph.is_interactive_mode() {
-                eprintln!("(done)");
+                println!("(done)");
             }
         }
 
@@ -110,7 +115,11 @@ fn main() {
             println!("{}", desugared_str);
         } else {
             match egraph.parse_and_run_program(&program) {
-                Ok(_msgs) => {}
+                Ok(msgs) => {
+                    for msg in msgs {
+                        println!("{msg}");
+                    }
+                }
                 Err(err) => {
                     log::error!("{}", err);
                     std::process::exit(1)

src/serialize.rs

@@ -153,7 +153,7 @@ impl EGraph {
                         .collect();
                     // If this is a container sort, use the name, otherwise use the value
                     let op: String = if sort.is_container_sort() {
-                        println!("{} is a container sort", sort.name());
+                        log::warn!("{} is a container sort", sort.name());
                         sort.name().to_string()
                     } else {
                         sort.make_expr(self, *value).to_string()

src/typecheck.rs

@@ -888,21 +888,24 @@ impl EGraph {
                         );
                         let extracted = termdag.to_string(&expr);
                         log::info!("extracted with cost {cost}: {}", extracted);
-                        println!("{}", extracted);
+                        self.print_msg(extracted);
                     } else {
                         if variants < 0 {
                             panic!("Cannot extract negative number of variants");
                         }
                         let extracted =
                             self.extract_variants(values[0], variants as usize, &mut termdag);
                         log::info!("extracted variants:");
-                        println!("(");
+                        let mut msg = String::default();
+                        msg += "(\n";
+                        assert!(!extracted.is_empty());
                         for expr in extracted {
                             let str = termdag.to_string(&expr);
                             log::info!("   {}", str);
-                            println!("   {}", str);
+                            msg += &format!("   {}\n", str);
                         }
-                        println!(")");
+                        msg += ")";
+                        self.print_msg(msg);
                     }
 
                     stack.truncate(new_len);