tracing: Add a bunch of TRACE level tracing

Signed-off-by: Daniel Silverstone <dsilvers@digital-scurf.org>

4 files changed, 61 insertions, 10 deletions

diff --git a/src/bin/cli/mod.rs b/src/bin/cli/mod.rs
index c686cab..5da5bf9 100644
--- a/src/bin/cli/mod.rs
+++ b/src/bin/cli/mod.rs
@@ -4,15 +4,29 @@
 
 use anyhow::Result;
 use serde::Serialize;
-use subplot::{DataFile, Document, Style, SubplotError};
-
 use std::convert::TryFrom;
+use std::fmt::Debug;
 use std::path::Path;
 use std::str::FromStr;
+use subplot::{DataFile, Document, Style, SubplotError};
+use tracing::{event, instrument, Level};
 
-pub fn load_document<P: AsRef<Path>>(filename: P, style: Style) -> Result<Document> {
+#[instrument(level = "trace")]
+pub fn load_document<P>(filename: P, style: Style) -> Result<Document>
+where
+    P: AsRef<Path> + Debug,
+{
     let filename = filename.as_ref();
     let base_path = subplot::get_basedir_from(filename);
+    event!(
+        Level::TRACE,
+        ?filename,
+        ?base_path,
+        "Loading document based at `{}` called `{}` with {:?}",
+        base_path.display(),
+        filename.display(),
+        style
+    );
     let doc = Document::from_file(&base_path, filename, style)?;
 
     Ok(doc)
diff --git a/src/bindings.rs b/src/bindings.rs
index 98de428..5909316 100644
--- a/src/bindings.rs
+++ b/src/bindings.rs
@@ -9,11 +9,13 @@ use serde::{Deserialize, Serialize};
 use serde_aux::prelude::*;
 
 use std::collections::HashMap;
+use std::fmt::Debug;
 use std::path::Path;
 use std::str::FromStr;
 
 use lazy_static::lazy_static;
 use regex::{escape, Regex, RegexBuilder};
+use tracing::{event, instrument, Level};
 
 #[derive(Debug, PartialEq, Eq, Hash, Copy, Clone, Serialize, Deserialize)]
 #[serde(rename_all = "lowercase")]
@@ -465,6 +467,7 @@ impl Bindings {
     }
 
     /// Add bindings from a YAML string
+    #[instrument(level = "trace", skip(self, yaml))]
     pub fn add_from_yaml(&mut self, yaml: &str) -> Result<()> {
         let bindings: Vec<ParsedBindingWrapper> = serde_yaml::from_str(yaml)?;
         for wrapper in bindings {
@@ -502,12 +505,14 @@ impl Bindings {
     }
 
     /// Add bindings from a file.
+    #[instrument(level = "trace", skip(self))]
     pub fn add_from_file<P>(&mut self, filename: P) -> Result<()>
     where
-        P: AsRef<Path>,
+        P: AsRef<Path> + Debug,
     {
         let yaml = resource::read_as_string(filename.as_ref())
             .map_err(|e| SubplotError::BindingsFileNotFound(filename.as_ref().into(), e))?;
+        event!(Level::TRACE, "Loaded file content");
         self.add_from_yaml(&yaml)?;
         Ok(())
     }
@@ -522,6 +527,7 @@ impl Bindings {
     }
 }
 
+#[instrument(level = "trace", skip(parsed))]
 fn from_hashmap(parsed: &ParsedBinding) -> Result<Binding> {
     let given: i32 = parsed.given.is_some().into();
     let when: i32 = parsed.when.is_some().into();
@@ -557,6 +563,14 @@ fn from_hashmap(parsed: &ParsedBinding) -> Result<Binding> {
         regex_from_simple_pattern(pattern, parsed.regex.is_some(), &mut types)?
     };
 
+    event!(
+        Level::TRACE,
+        ?kind,
+        ?pattern,
+        ?types,
+        "Successfully prepared binding"
+    );
+
     Binding::new(
         kind,
         &pattern,
diff --git a/src/doc.rs b/src/doc.rs
index 61e60a5..1fa9b3b 100644
--- a/src/doc.rs
+++ b/src/doc.rs
@@ -13,11 +13,14 @@ use crate::{Result, SubplotError};
 
 use std::collections::HashSet;
 use std::default::Default;
+use std::fmt::Debug;
 use std::ops::Deref;
 use std::path::{Path, PathBuf};
 
 use pandoc_ast::{MutVisitor, Pandoc};
 
+use tracing::{event, instrument, Level};
+
 /// The set of known (special) classes which subplot will always recognise
 /// as being valid.
 static SPECIAL_CLASSES: &[&str] = &["scenario", "file", "dot", "pikchr", "plantuml", "roadmap"];
@@ -96,6 +99,7 @@ impl<'a> Document {
     }
 
     /// Construct a Document from a JSON AST
+    #[instrument(level = "trace", skip(json))]
     pub fn from_json<P>(
         basedir: P,
         markdowns: Vec<PathBuf>,
@@ -103,11 +107,13 @@ impl<'a> Document {
         style: Style,
     ) -> Result<Document>
     where
-        P: AsRef<Path>,
+        P: AsRef<Path> + Debug,
     {
+        event!(Level::TRACE, "Parsing document...");
         let mut ast: Pandoc = serde_json::from_str(json)?;
         let meta = Metadata::new(basedir, &ast)?;
         let mut linter = LintingVisitor::default();
+        event!(Level::TRACE, "Walking AST for linting...");
         linter.walk_pandoc(&mut ast);
         if !linter.issues.is_empty() {
             // Currently we can't really return more than one error so return one
@@ -122,6 +128,7 @@ impl<'a> Document {
     /// The file can be in any format Pandoc understands. This runs
     /// Pandoc to parse the file into an AST, so it can be a little
     /// slow.
+    #[instrument(level = "trace")]
     pub fn from_file(basedir: &Path, filename: &Path, style: Style) -> Result<Document> {
         let markdowns = vec![filename.to_path_buf()];
 
@@ -138,6 +145,7 @@ 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...");
         let output = match pandoc.execute()? {
             pandoc::PandocOutput::ToBuffer(o) => o,
             _ => return Err(SubplotError::NotJson),
diff --git a/src/metadata.rs b/src/metadata.rs
index c598bb0..be15380 100644
--- a/src/metadata.rs
+++ b/src/metadata.rs
@@ -1,11 +1,14 @@
 use crate::{resource, Result};
 use crate::{Bindings, TemplateSpec};
 
+use std::fmt::Debug;
 use std::ops::Deref;
 use std::path::{Path, PathBuf};
 
 use pandoc_ast::{Inline, Map, MetaValue, Pandoc};
 
+use tracing::{event, instrument, Level};
+
 /// Metadata of a document, as needed by Subplot.
 #[derive(Debug)]
 pub struct Metadata {
@@ -23,26 +26,38 @@ pub struct Metadata {
 
 impl Metadata {
     /// Construct a Metadata from a Document, if possible.
+    #[instrument(level = "trace", skip(doc))]
     pub fn new<P>(basedir: P, doc: &Pandoc) -> Result<Metadata>
     where
-        P: AsRef<Path>,
+        P: AsRef<Path> + Debug,
     {
         let title = get_title(&doc.meta);
         let date = get_date(&doc.meta);
         let bindings_filenames = get_bindings_filenames(basedir.as_ref(), &doc.meta);
         let functions_filenames = get_functions_filenames(basedir.as_ref(), &doc.meta);
+        let bibliographies = get_bibliographies(basedir.as_ref(), &doc.meta);
+        let classes = get_classes(&doc.meta);
+        event!(
+            Level::TRACE,
+            ?title,
+            ?date,
+            ?bindings_filenames,
+            ?functions_filenames,
+            ?bibliographies,
+            ?classes,
+            "Loaded basic metadata"
+        );
         let (template, spec) = if let Some((template, spec)) = get_template_spec(&doc.meta)? {
             resource::set_template(&template);
             (Some(template), Some(spec))
         } else {
             (None, None)
         };
+        event!(Level::TRACE, ?template, ?spec, "Loaded template spec");
         let mut bindings = Bindings::new();
 
-        let bibliographies = get_bibliographies(basedir.as_ref(), &doc.meta);
-        let classes = get_classes(&doc.meta);
-
         get_bindings(&bindings_filenames, &mut bindings)?;
+        event!(Level::TRACE, "Loaded all metadata successfully");
         Ok(Metadata {
             title,
             date,
@@ -281,7 +296,7 @@ mod test_join {
 
 fn get_bindings<P>(filenames: &[P], bindings: &mut Bindings) -> Result<()>
 where
-    P: AsRef<Path>,
+    P: AsRef<Path> + Debug,
 {
     for filename in filenames {
         bindings.add_from_file(filename)?;