From bca1d2036a7a05c6badc4b5176df7c4d9a03fb25 Mon Sep 17 00:00:00 2001 From: Adrian Heine Date: Fri, 3 Mar 2023 19:29:37 +0100 Subject: [PATCH] Much nicer logs --- src/setup/core.rs | 26 ++++----- src/setup/setup.rs | 111 +++++++++++++++++++++++-------------- src/setup/symbol_runner.rs | 16 +++--- src/setup/util.rs | 21 ++++--- 4 files changed, 98 insertions(+), 76 deletions(-) diff --git a/src/setup/core.rs b/src/setup/core.rs index 8ba5b7a..9512fb5 100644 --- a/src/setup/core.rs +++ b/src/setup/core.rs @@ -150,39 +150,33 @@ where force_run: bool, ) -> InternalAddResult { 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?; diff --git a/src/setup/setup.rs b/src/setup/setup.rs index 776ca27..7536146 100644 --- a/src/setup/setup.rs +++ b/src/setup/setup.rs @@ -144,26 +144,11 @@ impl< RegularSetupCore: SetupCore>, { 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(&self, resource: R) -> AddResult @@ -186,36 +171,43 @@ impl< RegularSetupCore: 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>) { + 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( &self, symbol: &S, - _logger: &Logger, + logger: &Logger, force: bool, ) -> Result> { + 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)); + }); + } } diff --git a/src/setup/symbol_runner.rs b/src/setup/symbol_runner.rs index 10695ca..ea628a3 100644 --- a/src/setup/symbol_runner.rs +++ b/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> { 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> { - 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 } diff --git a/src/setup/util.rs b/src/setup/util.rs index eb091ed..402adc2 100644 --- a/src/setup/util.rs +++ b/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), ""); } }