debug: add tracing calls to help debug

I needed these to figure out a problem that wasn't in Subplot itself.
I'd like to keep them for the future.

Sponsored-by: author

3 files changed, 37 insertions, 4 deletions

diff --git a/src/bin/cli/mod.rs b/src/bin/cli/mod.rs
index 5da5bf9..30f5601 100644
--- a/src/bin/cli/mod.rs
+++ b/src/bin/cli/mod.rs
@@ -28,6 +28,7 @@ where
         style
     );
     let doc = Document::from_file(&base_path, filename, style)?;
+    event!(Level::TRACE, "Loaded doc from file OK");
 
     Ok(doc)
 }
diff --git a/src/bin/subplot.rs b/src/bin/subplot.rs
index 034cbb2..48406f1 100644
--- a/src/bin/subplot.rs
+++ b/src/bin/subplot.rs
@@ -8,7 +8,7 @@ use structopt::StructOpt;
 use subplot::{
     generate_test_program, resource, template_spec, DataFile, Document, MarkupOpts, Style,
 };
-use tracing::{event, span, Level, Subscriber};
+use tracing::{event, instrument, span, Level, Subscriber};
 
 use std::convert::TryFrom;
 use std::ffi::OsString;
@@ -301,16 +301,23 @@ impl Docgen {
         self.input.parent()
     }
 
+    #[instrument(level = "trace", skip(self))]
     fn run(&self) -> Result<()> {
         let span = span!(Level::TRACE, "docgen");
         let _enter = span.enter();
         let mut style = Style::default();
         if self.output.extension() == Some(&OsString::from("pdf")) {
+            event!(Level::TRACE, "PDF output chosen");
             style.typeset_links_as_notes();
         }
         let mut doc = cli::load_document(&self.input, style)?;
+        event!(Level::TRACE, "Got doc, now linting it");
         doc.lint()?;
-        let template = doc.meta().template_name().unwrap_or("").to_string();
+        event!(Level::TRACE, "Doc linted ok");
+        let meta = doc.meta();
+        event!(Level::TRACE, ?meta, "Looking for template");
+        let template = meta.template_name().unwrap_or("").to_string();
+        event!(Level::TRACE, ?template);
         if !doc.check_named_files_exist(&template)? || !doc.check_matched_steps_have_impl(&template)
         {
             eprintln!("Continuing despite warnings");
@@ -415,14 +422,18 @@ impl Codegen {
             .template_name()
             .ok_or_else(|| anyhow::anyhow!("No template name given"))?
             .to_string();
+        event!(Level::TRACE, ?template);
         if !doc.check_named_files_exist(&template)? || !doc.check_matched_steps_have_impl(&template)
         {
+            event!(Level::ERROR, "Found problems in document, cannot continue");
             eprintln!("Unable to continue");
             std::process::exit(1);
         }
 
+        event!(Level::TRACE, "Generating code");
         let spec = template_spec(&doc)?;
         generate_test_program(&mut doc, &spec, &self.output, &template)?;
+        event!(Level::TRACE, "Finished generating code");
 
         if self.run {
             let run = match spec.run() {
diff --git a/src/doc.rs b/src/doc.rs
index 5d9d3b1..5294738 100644
--- a/src/doc.rs
+++ b/src/doc.rs
@@ -120,7 +120,9 @@ impl<'a> Document {
             return Err(linter.issues.remove(0));
         }
         let files = DataFiles::new(&mut ast);
-        Ok(Document::new(markdowns, ast, meta, files, style))
+        let doc = Document::new(markdowns, ast, meta, files, style);
+        event!(Level::TRACE, "Loaded from JSON OK");
+        Ok(doc)
     }
 
     /// Construct a Document from a named file.
@@ -145,12 +147,13 @@ impl<'a> Document {
         let citeproc = std::path::Path::new("pandoc-citeproc");
         pandoc.add_option(pandoc::PandocOption::Filter(citeproc.to_path_buf()));
 
-        event!(Level::TRACE, ?filename, "Invoking pandoc...");
+        event!(Level::TRACE, ?filename, "Invoking Pandoc to parse document");
         let output = match pandoc.execute()? {
             pandoc::PandocOutput::ToBuffer(o) => o,
             _ => return Err(SubplotError::NotJson),
         };
         let doc = Document::from_json(basedir, markdowns, &output, style)?;
+        event!(Level::TRACE, "Loaded document OK");
         Ok(doc)
     }
 
@@ -206,10 +209,13 @@ impl<'a> Document {
     }
 
     /// Check the document for common problems.
+    #[instrument(level = "trace", skip(self))]
     pub fn lint(&self) -> Result<()> {
+        event!(Level::TRACE, "Linting document");
         self.check_doc_has_title()?;
         self.check_filenames_are_unique()?;
         self.check_block_classes()?;
+        event!(Level::TRACE, "No linting problems found");
         Ok(())
     }
 
@@ -268,12 +274,14 @@ impl<'a> Document {
 
     /// Check that all named files (in matched steps) are actually present in the
     /// document.
+    #[instrument(level = "trace", skip(self))]
     pub fn check_named_files_exist(&mut self, template: &str) -> Result<bool> {
         let filenames: HashSet<_> = self
             .files()
             .iter()
             .map(|f| f.filename().to_lowercase())
             .collect();
+        event!(Level::TRACE, ?filenames, "Checking that files exist");
         let mut okay = true;
         let scenarios = match self.matched_scenarios(template) {
             Ok(scenarios) => scenarios,
@@ -297,13 +305,21 @@ impl<'a> Document {
     }
 
     /// Check that all matched steps actually have function implementations
+    #[instrument(level = "trace", skip(self))]
     pub fn check_matched_steps_have_impl(&mut self, template: &str) -> bool {
+        event!(Level::TRACE, "Checking that steps have implementations");
         let mut okay = true;
         let scenarios = match self.matched_scenarios(template) {
             Ok(scenarios) => scenarios,
             Err(_) => return true, // No matches means no missing impls
         };
+        event!(Level::TRACE, count = scenarios.len(), "Found scenarios");
         for scenario in scenarios {
+            event!(
+                Level::TRACE,
+                title = scenario.title(),
+                "Checking that steps in scenario"
+            );
             let mut said_scenario = false;
             for step in scenario.steps() {
                 if step.function().is_none() {
@@ -313,6 +329,11 @@ impl<'a> Document {
                         said_scenario = true;
                     }
                     eprintln!("  Step missing implementation: '{}'", step.text());
+                    event!(
+                        Level::ERROR,
+                        step = step.text(),
+                        "Missing step implementation"
+                    );
                     okay = false;
                 }
             }