feat: improve logging via env_logger

Configure env_logger from environment, including style (colors).
Simplify how log messages are formatted: drop the timestamp and crate
name, as they're just noise for the case of Subplot.

Adjust log messages so that what a user may want to normally know is
info or above, and at level debug if they want to see in more detail
what's happening.

Handle the error from failing to execute pandoc specially, for a
better error message. The default error message from the pandoc crate
was hard for a user to understand. The new message clearly says what
the exit code is, and logs the stderr, but not stdout, as Pandoc
correctly writes errors only to stderr.

Sponsored-by: author

2 files changed, 53 insertions, 12 deletions

diff --git a/src/bin/subplot.rs b/src/bin/subplot.rs
index 6a41968..479aa79 100644
--- a/src/bin/subplot.rs
+++ b/src/bin/subplot.rs
@@ -3,7 +3,8 @@
 
 use anyhow::Result;
 
-use log::{debug, trace};
+use env_logger::fmt::Color;
+use log::{debug, error, info, trace, warn};
 use structopt::StructOpt;
 use subplot::{
     codegen, load_document, resource, DataFile, Document, MarkupOpts, Style, SubplotError,
@@ -345,7 +346,18 @@ impl Docgen {
             pandoc.set_input_format(pandoc::InputFormat::Json, vec![]);
             pandoc.set_input(pandoc::InputKind::Pipe(doc.ast()?));
             pandoc.set_output(pandoc::OutputKind::File(self.output.clone()));
-            pandoc.execute()?;
+
+            debug!("Executing pandoc to produce {}", self.output.display());
+            let r = pandoc.execute();
+            if let Err(pandoc::PandocError::Err(output)) = r {
+                let code = output.status.code().or(Some(127)).unwrap();
+                let stderr = String::from_utf8_lossy(&output.stderr);
+                error!("Failed to execute Pandoc: exit code {}", code);
+                error!("{}", stderr.strip_suffix('\n').unwrap());
+
+                return Err(anyhow::Error::msg("Pandoc failed"));
+            }
+            r?;
         }
 
         Ok(())
@@ -421,6 +433,7 @@ impl Codegen {
     }
 
     fn run(&self) -> Result<()> {
+        debug!("codegen starts");
         let output = codegen(&self.filename, &self.output, self.template.as_deref())?;
         if self.run {
             let spec = output
@@ -431,7 +444,7 @@ impl Codegen {
                 .spec();
             let run = match spec.run() {
                 None => {
-                    eprintln!(
+                    error!(
                         "Template {} does not specify how to run suites",
                         spec.template_filename().display()
                     );
@@ -442,10 +455,11 @@ impl Codegen {
 
             let status = Command::new(run).arg(&self.output).status()?;
             if !status.success() {
-                eprintln!("Test suite failed!");
+                error!("Test suite failed!");
                 std::process::exit(2);
             }
         }
+        debug!("codegen ends successfully");
         Ok(())
     }
 }
@@ -480,7 +494,7 @@ fn load_linted_doc(
     doc.check_embedded_files_are_used(&template)?;
 
     for w in doc.warnings() {
-        eprintln!("WARNING: {}", w);
+        warn!("{}", w);
     }
 
     if !doc.warnings().is_empty() && !merciful {
@@ -490,8 +504,15 @@ fn load_linted_doc(
     Ok(doc)
 }
 
+fn print_source_errors(e: Option<&dyn std::error::Error>) {
+    if let Some(e) = e {
+        error!("{}", e);
+        print_source_errors(e.source());
+    }
+}
+
 fn real_main() {
-    trace!("Starting Subplot");
+    info!("Starting Subplot");
     let argparser = Toplevel::clap();
     let version = long_version().unwrap();
     let argparser = argparser.long_version(version.as_str());
@@ -500,17 +521,32 @@ fn real_main() {
     args.handle_special_args();
     match args.run() {
         Ok(_) => {
-            trace!("Subplot finished successfully");
+            info!("Subplot finished successfully");
         }
         Err(e) => {
-            debug!("Failed: {:?}", e);
-            eprintln!("Failure: {:?}", e);
+            error!("{}", e);
+            print_source_errors(e.source());
             process::exit(1);
         }
     }
 }
 
 fn main() {
-    env_logger::init_from_env("SUBPLOT_LOG");
+    let env = env_logger::Env::new()
+        .filter_or("SUBPLOT_LOG", "info")
+        .write_style("SUBPLOT_LOG_STYLE");
+    env_logger::Builder::from_env(env)
+        .format_timestamp(None)
+        .format(|buf, record| {
+            let mut level_style = buf.style();
+            level_style.set_color(Color::Red).set_bold(true);
+            writeln!(
+                buf,
+                "{}: {}",
+                level_style.value(record.level()),
+                record.args()
+            )
+        })
+        .init();
     real_main();
 }
diff --git a/src/doc.rs b/src/doc.rs
index 89b9eea..9c5fae8 100644
--- a/src/doc.rs
+++ b/src/doc.rs
@@ -532,7 +532,13 @@ where
 
 /// Generate code for one document.
 pub fn codegen(filename: &Path, output: &Path, template: Option<&str>) -> Result<CodegenOutput> {
-    let mut doc = load_document_with_pullmark(filename, Style::default(), template)?;
+    let r = load_document_with_pullmark(filename, Style::default(), template);
+    let mut doc = match r {
+        Ok(doc) => doc,
+        Err(err) => {
+            return Err(err);
+        }
+    };
     doc.lint()?;
     let template = template
         .map(Ok)
@@ -547,7 +553,6 @@ pub fn codegen(filename: &Path, output: &Path, template: Option<&str>) -> Result
         || !doc.check_embedded_files_are_used(&template)?
     {
         error!("Found problems in document, cannot continue");
-        eprintln!("Unable to continue");
         std::process::exit(1);
     }