feat: add logging

A lot of logging, if the debug level is chosen. But that's how it
should be.

Sponsored-by: author

6 files changed, 99 insertions, 13 deletions

diff --git a/Cargo.lock b/Cargo.lock
index e9af5eb..4928489 100644
--- a/Cargo.lock
+++ b/Cargo.lock
@@ -231,6 +231,19 @@ source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "e78d4f1cc4ae33bbfc157ed5d5a5ef3bc29227303d595861deb238fcec4e9457"
 
 [[package]]
+name = "env_logger"
+version = "0.7.1"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "44533bbbb3bb3c1fa17d9f2e4e38bbbaf8396ba82193c4cb1b6445d711445d36"
+dependencies = [
+ "atty",
+ "humantime",
+ "log",
+ "regex",
+ "termcolor",
+]
+
+[[package]]
 name = "fake-simd"
 version = "0.1.2"
 source = "registry+https://github.com/rust-lang/crates.io-index"
@@ -416,6 +429,15 @@ source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "02296996cb8796d7c6e3bc2d9211b7802812d36999a51bb754123ead7d37d026"
 
 [[package]]
+name = "humantime"
+version = "1.3.0"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "df004cfca50ef23c36850aaaa59ad52cc70d0e90243c3c7737a4dd32dc7a3c4f"
+dependencies = [
+ "quick-error",
+]
+
+[[package]]
 name = "ignore"
 version = "0.4.18"
 source = "registry+https://github.com/rust-lang/crates.io-index"
@@ -581,6 +603,8 @@ dependencies = [
  "anyhow",
  "fehler",
  "glob",
+ "log",
+ "pretty_env_logger",
  "serde",
  "serde_json",
  "serde_yaml",
@@ -744,6 +768,16 @@ source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "ed0cfbc8191465bed66e1718596ee0b0b35d5ee1f41c5df2189d0fe8bde535ba"
 
 [[package]]
+name = "pretty_env_logger"
+version = "0.4.0"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "926d36b9553851b8b0005f1275891b392ee4d2d833852c417ed025477350fb9d"
+dependencies = [
+ "env_logger",
+ "log",
+]
+
+[[package]]
 name = "proc-macro-error"
 version = "1.0.4"
 source = "registry+https://github.com/rust-lang/crates.io-index"
@@ -789,6 +823,12 @@ dependencies = [
 ]
 
 [[package]]
+name = "quick-error"
+version = "1.2.3"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "a1d01941d82fa2ab50be1e79e6714289dd7cde78eba4c074bc5a4374f650dfe0"
+
+[[package]]
 name = "quote"
 version = "1.0.10"
 source = "registry+https://github.com/rust-lang/crates.io-index"
@@ -1242,6 +1282,15 @@ dependencies = [
 ]
 
 [[package]]
+name = "termcolor"
+version = "1.1.2"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "2dfed899f0eb03f32ee8c6a0aabdb8a7949659e3466561fc0adf54e26d88c5f4"
+dependencies = [
+ "winapi-util",
+]
+
+[[package]]
 name = "textwrap"
 version = "0.11.0"
 source = "registry+https://github.com/rust-lang/crates.io-index"
diff --git a/Cargo.toml b/Cargo.toml
index 4bce24c..bb00a15 100644
--- a/Cargo.toml
+++ b/Cargo.toml
@@ -8,6 +8,8 @@ edition = "2018"
 
 [dependencies]
 anyhow = "1.0.51"
+log = "0.4.14"
+pretty_env_logger = "0.4.0"
 serde = { version = "1.0.101", features = ["derive"] }
 serde_json = "1.0.72"
 serde_yaml = "0.8.21"
diff --git a/src/bin/obnam-benchmark.rs b/src/bin/obnam-benchmark.rs
index 0ad8491..76ab620 100644
--- a/src/bin/obnam-benchmark.rs
+++ b/src/bin/obnam-benchmark.rs
@@ -1,3 +1,4 @@
+use log::{debug, error, info};
 use obnam_benchmark::result::Result;
 use obnam_benchmark::specification::Specification;
 use obnam_benchmark::state::State;
@@ -7,14 +8,20 @@ use std::process::exit;
 use structopt::StructOpt;
 
 fn main() {
+    pretty_env_logger::init_custom_env("OBNAM_BENCHMARK_LOG");
+    info!("obnam-benchmark starts");
     if let Err(err) = real_main() {
         eprintln!("ERROR: {}", err);
+        error!("{}", err);
         exit(1);
     }
+    info!("obnam-benchmark ends successfully");
 }
 
 fn real_main() -> anyhow::Result<()> {
+    debug!("parsing command line");
     let opt = Opt::from_args();
+    debug!("parsed: {:#?}", opt);
 
     match opt.cmd {
         Command::Run(x) => x.run()?,
@@ -52,6 +59,7 @@ struct Run {
 
 impl Run {
     fn run(&self) -> anyhow::Result<()> {
+        info!("running benchmarks from {}", self.spec.display());
         let spec = Specification::from_file(&self.spec)?;
         let mut state = State::new()?;
         let mut result = Result::default();
@@ -60,6 +68,7 @@ impl Run {
                 result.push(m);
             }
         }
+        debug!("writing results to {}", self.output.display());
         let output = File::create(&self.output)?;
         serde_json::to_writer_pretty(&output, &result)?;
         Ok(())
@@ -79,9 +88,12 @@ struct Spec {
 
 impl Spec {
     fn run(&self) -> anyhow::Result<()> {
+        info!("dumping specification file as JSON");
+        debug!("reading specification from {}", self.spec.display());
         let input = File::open(&self.spec)?;
         let spec: Specification = serde_yaml::from_reader(&input)?;
 
+        debug!("writing specification as JSON to {}", self.output.display());
         let output = File::create(&self.output)?;
         serde_json::to_writer(&output, &spec)?;
 
diff --git a/src/data.rs b/src/data.rs
index dbea40f..2069110 100644
--- a/src/data.rs
+++ b/src/data.rs
@@ -1,4 +1,5 @@
 use crate::specification::{Create, FileCount};
+use log::debug;
 use std::fs::File;
 use std::path::{Path, PathBuf};
 use tempfile::{tempdir_in, TempDir};
@@ -37,31 +38,36 @@ pub enum DataError {
 impl Data {
     pub(crate) fn new(tempdir: &Path) -> Result<Self, DataError> {
         let live = tempdir_in(&tempdir)?;
-        Ok(Self {
-            live,
-        })
+        debug!("created temporary directory {}", live.path().display());
+        Ok(Self { live })
     }
 
     pub(crate) fn create(&self, create: &Create) -> Result<(), DataError> {
-        println!("create {:?} in {}", create, self.live.path().display());
+        debug!(
+            "creating {} files in {}",
+            create.files,
+            self.live.path().display()
+        );
         for i in 0..create.files {
             let filename = self.live.path().join(format!("{}", i));
+            debug!("creating {}", filename.display());
             File::create(&filename).map_err(|err| DataError::CreateFile(filename, err))?;
         }
         Ok(())
     }
 
     pub(crate) fn rename(&self, count: &FileCount) -> Result<(), DataError> {
-        println!("rename {:?}", count);
+        debug!("renaming {} files", count.files);
         Ok(())
     }
 
     pub(crate) fn delete(&self, count: &FileCount) -> Result<(), DataError> {
-        println!("delete {:?}", count);
+        debug!("deleting {}", count.files);
         Ok(())
     }
 
     pub(crate) fn file_count(&self) -> Result<u64, DataError> {
+        debug!("counting files in {}", self.live.path().display());
         let mut n = 0;
         for entry in WalkDir::new(&self.live).into_iter() {
             if let Err(err) = entry {
@@ -69,10 +75,21 @@ impl Data {
             }
             n += 1;
         }
+        debug!("found {} files in {}", n, self.live.path().display());
         Ok(n)
     }
 
     pub(crate) fn file_size(&self) -> Result<u64, DataError> {
-        Ok(0)
+        debug!(
+            "counting combined slze of files in {}",
+            self.live.path().display()
+        );
+        let n = 0;
+        debug!(
+            "found {} bytes of data in {}",
+            n,
+            self.live.path().display()
+        );
+        Ok(n)
     }
 }
diff --git a/src/run.rs b/src/run.rs
deleted file mode 100644
index 94261ff..0000000
--- a/src/run.rs
+++ /dev/null
@@ -1,3 +0,0 @@
-/// Runtime state for running Obnam benchmarks.
-pub struct RuntimeState {
-}
diff --git a/src/state.rs b/src/state.rs
index 152d569..d70af11 100644
--- a/src/state.rs
+++ b/src/state.rs
@@ -1,8 +1,9 @@
 use crate::data::{Data, DataError};
 use crate::result::{Measurement, OpMeasurements, Operation};
 use crate::step::Step;
+use log::{debug, info};
+use std::path::Path;
 use std::time::Instant;
-use std::path::{Path};
 use tempfile::{tempdir, TempDir};
 
 /// Runtime state for running Obnam benchmarks.
@@ -44,25 +45,31 @@ impl State {
     }
 
     pub fn execute(&mut self, step: &Step) -> Result<Option<OpMeasurements>, StateError> {
+        debug!("executing step {:?}", step);
         let now = Instant::now();
         let om = match step {
             Step::Start(name) => {
+                info!("starting benchmark {}", name);
                 self.current_benchmark = Some(CurrentBenchmark::new(name, self.tempdir.path())?);
                 None
             }
-            Step::Stop(_) => {
+            Step::Stop(name) => {
+                info!("ending benchmark {}", name);
                 self.current_benchmark = None;
                 None
             }
             Step::Create(x) => {
+                info!("creating {} test data files", x.files);
                 self.current()?.data.create(x)?;
                 None
             }
             Step::Rename(x) => {
+                info!("renaming {} test data files", x.files);
                 self.current()?.data.rename(x)?;
                 None
             }
             Step::Delete(x) => {
+                info!("deleting {} test data files", x.files);
                 self.current()?.data.delete(x)?;
                 None
             }
@@ -70,12 +77,12 @@ impl State {
             Step::Restore(x) => Some(restore(*x, self.current()?)?),
         };
 
-        println!("{:?}", step);
         let t = std::time::Duration::from_millis(10);
         std::thread::sleep(t);
 
         if let Some(mut om) = om {
             let ms = now.elapsed().as_millis();
+            debug!("step duration was {} ms", ms);
             om.push(Measurement::DurationMs(ms));
             Ok(Some(om))
         } else {
@@ -85,6 +92,7 @@ impl State {
 }
 
 fn backup(i: usize, current: &CurrentBenchmark) -> Result<OpMeasurements, StateError> {
+    info!("backing up generation number {}", i);
     let mut om = OpMeasurements::new(&current.name, Operation::Backup(i));
     om.push(Measurement::TotalFiles(current.data.file_count()?));
     om.push(Measurement::TotalData(current.data.file_size()?));
@@ -92,6 +100,7 @@ fn backup(i: usize, current: &CurrentBenchmark) -> Result<OpMeasurements, StateE
 }
 
 fn restore(i: usize, current: &CurrentBenchmark) -> Result<OpMeasurements, StateError> {
+    info!("restoring generation number {}", i);
     Ok(OpMeasurements::new(&current.name, Operation::Restore(i)))
 }