Much nicer logs

src/setup/core.rs

@@ -150,39 +150,33 @@ where
     force_run: bool,
   ) -> InternalAddResult<R> {
     let resource = resource.as_ref();
-    debug!(logger, "Adding {:?} ... ", resource);
-    debug!(logger, "(force_run is {})", force_run);
+    let logger = Rc::new(logger.new(o!("resource" => format!("{resource:?}"))));
+    trace!(logger, "(force_run is {})", force_run);
     let (location, location_prereqs) = L::locate(resource);
-    trace!(logger, "Adding location prereqs for {:?}", resource);
-    let location_prereq_logger = Rc::new(logger.new(o!("prereq" => "location")));
-    let (_, location_prereqs_did_run) = setup
-      .add_generic(&location_prereq_logger, location_prereqs)
-      .await?;
+    trace!(logger, "Adding location prereqs ...");
+    let (_, location_prereqs_did_run) = setup.add_generic(&logger, location_prereqs).await?;
     trace!(
       logger,
-      "Location prereqs for {:?} did_run: {}",
-      resource,
+      "Location prereqs did_run: {}",
       location_prereqs_did_run
     );
 
-    trace!(logger, "Adding implementation prereqs for {:?}", resource);
-    let impl_prereq_logger = Rc::new(logger.new(o!("prereq" => "implementation")));
+    trace!(logger, "Adding implementation prereqs ...");
     let (prereqs, prereqs_did_run) = setup
-      .add_generic(&impl_prereq_logger, B::prerequisites(resource))
+      .add_generic(&logger, B::prerequisites(resource))
       .await?;
     trace!(
       logger,
-      "Implementation prereqs for {:?} did_run: {}",
-      resource,
+      "Implementation prereqs did_run: {}",
       prereqs_did_run
     );
 
-    trace!(logger, "Running implementation for {:?}", resource);
+    trace!(logger, "Running implementation ...");
     let implementation = B::create(resource, &location, prereqs);
     let did_run = implementation
       .run(
         &self.symbol_runner,
-        logger,
+        &logger,
         force_run || location_prereqs_did_run || prereqs_did_run,
       )
       .await?;

src/setup/setup.rs

@@ -144,26 +144,11 @@ impl<
     RegularSetupCore<SR, L, B>: SetupCore<R, Setup<SR, L, B, Rs, As>>,
   {
     let recorder = Recorder::default();
-    let drain = recorder.clone();
-    let log = Rc::new(slog::Logger::root(
-      drain,
-      o!("resource" => format!("{resource:?}")),
-    ));
-
-    let result = self.1.add(&log, resource, force_run).await;
-    match &result {
-      Ok((_, did_run)) => {
-        if *did_run {
-          let log = recorder.to_string(slog::Level::Info);
-          if !log.is_empty() {
-            self.0.writeln(3, &log);
-            return result;
-          }
-        }
-        self.0.write(3, ".");
-      }
-      Err(_) => self.0.writeln(2, &recorder.to_string(slog::Level::Trace)),
-    }
+    let result = {
+      let log = Rc::new(slog::Logger::root(recorder.clone(), o!()));
+      self.1.add(&log, resource, force_run).await
+    };
+    self.log_result(recorder, result.as_ref().map(|(_, did_run)| *did_run));
     result
   }
   pub async fn add<R: AddableResource>(&self, resource: R) -> AddResult<R>
@@ -186,36 +171,43 @@ impl<
     RegularSetupCore<SR, L, B>: SymbolRunner,
   {
     let recorder = Recorder::default();
-    let drain = recorder.clone();
-    let log = Rc::new(slog::Logger::root(
-      drain,
-      o!("symbol" => format!("{symbol:?}")),
-    ));
-
-    let result = (self.1).0.core.run_symbol(&symbol, &log, force).await;
-    self.0.write(
-      3,
-      &recorder.to_string(if result.is_ok() {
-        slog::Level::Info
-      } else {
-        slog::Level::Trace
-      }),
-    );
+    let result = {
+      let log = Rc::new(slog::Logger::root(
+        recorder.clone(),
+        o!("symbol" => format!("{symbol:?}")),
+      ));
+      (self.1).0.core.run_symbol(&symbol, &log, force).await
+    };
+    self.log_result(recorder, result.as_ref().copied());
     result
   }
+
+  fn log_result(&self, recorder: Recorder, result: Result<bool, &Box<dyn Error>>) {
+    let log = match result {
+      Ok(false) => String::new(),
+      Ok(true) => recorder.into_string(slog::Level::Info),
+      Err(e) => recorder.into_string(slog::Level::Trace),
+    };
+    if log.is_empty() {
+      self.0.write(3, ".");
+    } else {
+      self.0.writeln(3, &log);
+    }
+  }
 }
 
 #[cfg(test)]
 mod test {
   use super::SymbolRunner;
   use crate::async_utils::run;
-  use crate::loggers::StoringLogger;
+  use crate::loggers::{Entry, StoringLogger};
   use crate::resources::{FromArtifact, FromResource, Resource};
   use crate::symbols::Symbol;
   use crate::to_artifact::ToArtifact;
   use crate::{ImplementationBuilder, ResourceLocator, Setup};
   use async_trait::async_trait;
-  use slog::Logger;
+  use regex::Regex;
+  use slog::{info, Logger};
   use std::cell::RefCell;
   use std::error::Error;
   use std::fmt::Debug;
@@ -230,9 +222,10 @@ mod test {
     async fn run_symbol<S: Symbol + Debug>(
       &self,
       symbol: &S,
-      _logger: &Logger,
+      logger: &Logger,
       force: bool,
     ) -> Result<bool, Box<dyn Error>> {
+      info!(logger, "run");
       let run = force || !symbol.target_reached().await?;
       if run {
         *self.count.borrow_mut() += 1;
@@ -342,26 +335,62 @@ mod test {
       Resources,
       Artifacts,
     >,
+    StoringLogger,
   ) {
     let count = Rc::new(RefCell::new(0));
     let runner = TestSymbolRunner {
       count: Rc::clone(&count),
     };
-    (count, Setup::new_with(runner, StoringLogger::new()))
+    let logger = StoringLogger::new();
+    (count, Setup::new_with(runner, logger.clone()), logger)
   }
 
   #[test]
   fn correctly_uses_force() {
     run(async {
-      let (count, setup) = get_setup();
+      let (count, setup, _) = get_setup();
       setup.add(TestResource("A", "b")).await.unwrap();
       assert_eq!(*count.borrow(), 2);
       setup.add(TestResource("A", "b")).await.unwrap();
       assert_eq!(*count.borrow(), 2);
 
-      let (count, setup) = get_setup();
+      let (count, setup, _) = get_setup();
       setup.add(TestResource("A", "B")).await.unwrap();
       assert_eq!(*count.borrow(), 0);
     });
   }
+
+  #[test]
+  fn run_reached_symbol() {
+    run(async {
+      let (count, setup, log) = get_setup();
+      let did_run = setup
+        .run_symbol(TestSymbol { reached: true }, false)
+        .await
+        .unwrap();
+      drop(setup);
+      assert!(!did_run);
+      assert_eq!(*count.borrow(), 0);
+      assert_eq!(log.release(), vec![Entry(3, ".".into())]);
+    });
+  }
+
+  #[test]
+  fn run_not_reached_symbol() {
+    run(async {
+      let (count, setup, log) = get_setup();
+      let did_run = setup
+        .run_symbol(TestSymbol { reached: false }, false)
+        .await
+        .unwrap();
+      drop(setup);
+      assert!(did_run);
+      assert_eq!(*count.borrow(), 1);
+      let log = log.release();
+      assert_eq!(log.len(), 1);
+      assert_eq!(log[0].0, 3);
+      let re = Regex::new(r"^symbol: TestSymbol \{ reached: false \}\n \w+ \d{1,2} \d{2}:\d{2}:\d{2}.\d{3} INFO run\n$").unwrap();
+      assert!(re.is_match(&log[0].1));
+    });
+  }
 }

src/setup/symbol_runner.rs

@@ -1,8 +1,7 @@
 use crate::async_utils::sleep;
 use crate::symbols::Symbol;
 use async_trait::async_trait;
-use slog::Logger;
-use slog::{debug, info, trace};
+use slog::{debug, info, o, trace, Logger};
 use std::error::Error;
 use std::fmt;
 use std::fmt::Debug;
@@ -149,7 +148,7 @@ impl SymbolRunner for DrySymbolRunner {
     force: bool,
   ) -> Result<bool, Box<dyn Error>> {
     let would_execute = if force {
-      info!(logger, "Would force-execute {:?}", symbol);
+      info!(logger, "Would force-execute");
       true
     } else {
       let target_reached = symbol.target_reached().await?;
@@ -158,7 +157,7 @@ impl SymbolRunner for DrySymbolRunner {
         "Symbol reports target_reached: {:?}", target_reached
       );
       if !target_reached {
-        info!(logger, "Would execute {:?}", symbol);
+        info!(logger, "Would execute");
       }
       !target_reached
     };
@@ -187,12 +186,13 @@ where
     logger: &Logger,
     force: bool,
   ) -> Result<bool, Box<dyn Error>> {
-    debug!(logger, "Running symbol {:?}", symbol);
-    let res = self.0.run_symbol(symbol, logger, force).await;
+    let logger = logger.new(o!("symbol" => format!("{symbol:?}")));
+    debug!(logger, "Running ...");
+    let res = self.0.run_symbol(symbol, &logger, force).await;
     if let Err(ref e) = res {
-      info!(logger, "Failed on {:?} with {}, aborting.", symbol, e);
+      info!(logger, "failed with {}", e);
     } else {
-      debug!(logger, "Successfully finished {:?}", symbol);
+      debug!(logger, "Successfully finished");
     }
     res
   }

src/setup/util.rs

@@ -1,7 +1,6 @@
 use crate::resources::Resource;
 use crate::to_artifact::ToArtifact;
-use slog::Drain;
-use slog::{OwnedKVList, Record};
+use slog::{Drain, Filter, OwnedKVList, Record};
 use slog_async::AsyncRecord;
 use std::cell::RefCell;
 use std::error::Error;
@@ -54,17 +53,17 @@ impl Drain for Recorder {
 }
 
 impl Recorder {
-  pub fn to_string(&self, filter_level: slog::Level) -> String {
+  pub fn into_string(self, filter_level: slog::Level) -> String {
     let output = Output::new(vec![]);
     {
       let decorator = slog_term::PlainDecorator::new(output.clone());
-      let drain = slog_term::CompactFormat::new(decorator).build();
-      for record in &*self.0.lock().unwrap() {
-        record.as_record_values(|record, kv| {
-          if record.level() <= filter_level {
-            drain.log(record, kv).unwrap();
-          }
-        });
+      let drain = Filter::new(
+        slog_term::CompactFormat::new(decorator).build(),
+        move |record| record.level().is_at_least(filter_level),
+      );
+      let Ok(mutex) = Arc::try_unwrap(self.0) else { panic!("cannot unwrap Arc") }; // AsyncRecord does not implement Debug, so we cannot unwrap
+      for record in mutex.into_inner().unwrap() {
+        record.log_to(&drain).unwrap();
       }
     }
     String::from_utf8(Rc::try_unwrap(output.0).unwrap().into_inner())
@@ -80,6 +79,6 @@ mod test {
   #[test]
   fn records_no_output() {
     let recorder = Recorder::default();
-    assert_eq!(recorder.to_string(Level::Trace), "");
+    assert_eq!(recorder.into_string(Level::Trace), "");
   }
 }