Merge branch 'liw/logging' into 'main'

feat! change logging to use log/env_logger instead of tracing

See merge request subplot/subplot!262

11 files changed, 156 insertions, 257 deletions

diff --git a/CONTRIBUTING.md b/CONTRIBUTING.md
index 113ffd3..95d7ac1 100644
--- a/CONTRIBUTING.md
+++ b/CONTRIBUTING.md
@@ -94,20 +94,12 @@ further work or attention.
 
 Ideally as a **user** of subplot you shouldn't need this, all error messages
 should give you sufficient context to chase down your problems. However if you
-are debugging a change to subplot itself then you may need to know how to do the
-following:
-
-1. You can change the logging level of subplot by means of the `SUBPLOT_LOG`
-   environment variable. If you set it to `trace` then it will show you absolutely
-   everything traced inside the program. You can learn about the syntax for
-   this variable on the [EnvFilter][] docs on `docs.rs`.
-2. You can redirect the logging to a file by means of the `SUBPLOT_LOG_FILE`
-   environment variable. Simply set it to the path you want to store logging to.
-   Subplot will _append_ to that file, so it's safe to have it in your environment
-   for multiple runs.
-3. To change the logging format, you can set `SUBPLOT_LOG_FORMAT` to one of:
-   `pretty` to have a multiline pretty format, `default` or `oneline` for a
-   basic one-line-per-event log format and `json` for a one-line-per-event JSON
-   log format.
-
-[envfilter]: https://docs.rs/tracing-subscriber/0.2.20/tracing_subscriber/filter/struct.EnvFilter.html
+are debugging a change to subplot itself then you may need to know how
+to configure logging.
+
+You can change the logging level of subplot by means of the `SUBPLOT_LOG`
+environment variable. If you set it to `trace` then it will show you absolutely
+everything traced inside the program. You can learn about the syntax for
+this variable on the [env_logger][] docs on `docs.rs`.
+
+[env_logger]: https://docs.rs/env_logger/latest/env_logger/
diff --git a/Cargo.lock b/Cargo.lock
index 7d11ba7..e819ded 100644
--- a/Cargo.lock
+++ b/Cargo.lock
@@ -225,6 +225,32 @@ 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 1.3.0",
+ "log",
+ "regex",
+ "termcolor",
+]
+
+[[package]]
+name = "env_logger"
+version = "0.9.0"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "0b2cf0344971ee6c64c31be0d530793fba457d322dfec2810c453d0ef228f9c3"
+dependencies = [
+ "atty",
+ "humantime 2.1.0",
+ "log",
+ "regex",
+ "termcolor",
+]
+
+[[package]]
 name = "fake-simd"
 version = "0.1.2"
 source = "registry+https://github.com/rust-lang/crates.io-index"
@@ -419,6 +445,21 @@ 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 = "humantime"
+version = "2.1.0"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "9a3a5bfb195931eeb336b2a7b4d761daec841b97f947d34394601737a7bba5e4"
+
+[[package]]
 name = "ignore"
 version = "0.4.18"
 source = "registry+https://github.com/rust-lang/crates.io-index"
@@ -490,9 +531,9 @@ checksum = "7fb9b38af92608140b86b693604b9ffcc5824240a484d1ecd4795bacb2fe88f3"
 
 [[package]]
 name = "log"
-version = "0.4.14"
+version = "0.4.16"
 source = "registry+https://github.com/rust-lang/crates.io-index"
-checksum = "51b9bbe6c47d51fc3e1a9b945965946b4c44142ab8792c50835a980d362c2710"
+checksum = "6389c490849ff5bc16be905ae24bc913a9c8892e19b2341dbc175e14c341c2b8"
 dependencies = [
  "cfg-if",
 ]
@@ -749,6 +790,16 @@ source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "eb9f9e6e233e5c4a35559a617bf40a4ec447db2e84c20b55a6f83167b7e57872"
 
 [[package]]
+name = "pretty_env_logger"
+version = "0.4.0"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "926d36b9553851b8b0005f1275891b392ee4d2d833852c417ed025477350fb9d"
+dependencies = [
+ "env_logger 0.7.1",
+ "log",
+]
+
+[[package]]
 name = "proc-macro-error"
 version = "1.0.4"
 source = "registry+https://github.com/rust-lang/crates.io-index"
@@ -794,6 +845,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.15"
 source = "registry+https://github.com/rust-lang/crates.io-index"
@@ -1123,13 +1180,16 @@ version = "0.3.1"
 dependencies = [
  "anyhow",
  "base64",
+ "env_logger 0.9.0",
  "file_diff",
  "git-testament",
  "lazy_static",
+ "log",
  "pandoc",
  "pandoc_ast 0.7.3",
  "pandoc_ast 0.8.0",
  "pikchr",
+ "pretty_env_logger",
  "pulldown-cmark",
  "regex",
  "roadmap",
@@ -1143,9 +1203,6 @@ dependencies = [
  "tera",
  "thiserror",
  "time 0.3.7",
- "tracing",
- "tracing-appender",
- "tracing-subscriber",
  "walkdir",
 ]
 
@@ -1249,6 +1306,15 @@ dependencies = [
 ]
 
 [[package]]
+name = "termcolor"
+version = "1.1.3"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "bab24d30b911b2376f3a13cc2cd443142f0c81dda04c118693e35b3835757755"
+dependencies = [
+ "winapi-util",
+]
+
+[[package]]
 name = "textwrap"
 version = "0.11.0"
 source = "registry+https://github.com/rust-lang/crates.io-index"
@@ -1338,17 +1404,6 @@ dependencies = [
 ]
 
 [[package]]
-name = "tracing-appender"
-version = "0.2.1"
-source = "registry+https://github.com/rust-lang/crates.io-index"
-checksum = "9ab026b18a46ac429e5c98bec10ca06424a97b3ad7b3949d9b4a102fff6623c4"
-dependencies = [
- "crossbeam-channel",
- "time 0.3.7",
- "tracing-subscriber",
-]
-
-[[package]]
 name = "tracing-attributes"
 version = "0.1.20"
 source = "registry+https://github.com/rust-lang/crates.io-index"
@@ -1381,16 +1436,6 @@ dependencies = [
 ]
 
 [[package]]
-name = "tracing-serde"
-version = "0.1.3"
-source = "registry+https://github.com/rust-lang/crates.io-index"
-checksum = "bc6b213177105856957181934e4920de57730fc69bf42c37ee5bb664d406d9e1"
-dependencies = [
- "serde",
- "tracing-core",
-]
-
-[[package]]
 name = "tracing-subscriber"
 version = "0.3.9"
 source = "registry+https://github.com/rust-lang/crates.io-index"
@@ -1400,15 +1445,12 @@ dependencies = [
  "lazy_static",
  "matchers",
  "regex",
- "serde",
- "serde_json",
  "sharded-slab",
  "smallvec",
  "thread_local",
  "tracing",
  "tracing-core",
  "tracing-log",
- "tracing-serde",
 ]
 
 [[package]]
diff --git a/Cargo.toml b/Cargo.toml
index ea435b5..7a1a297 100644
--- a/Cargo.toml
+++ b/Cargo.toml
@@ -28,10 +28,12 @@ base64 = "0.13.0"
 file_diff = "1"
 git-testament = "0.2"
 lazy_static = "1"
+log = "0.4.16"
 pandoc = "0.8.0"
 pandoc_ast_07 = { package = "pandoc_ast", version = "0.7", optional = true }
 pandoc_ast_08 = { package = "pandoc_ast", version = "0.8", optional = true }
 pikchr = "0.1"
+pretty_env_logger = "0.4.0"
 pulldown-cmark = "0.9.0"
 regex = "1"
 roadmap = "0.4"
@@ -43,10 +45,8 @@ structopt = "0.3"
 tempfile = "3.1.0"
 tempfile-fast = "0.3.1"
 thiserror = "1"
-tracing = "0.1"
-tracing-appender = "0.2"
-tracing-subscriber = { version = "0.3", features = ["env-filter", "json"] }
 time = { version = "0.3", features = ["formatting", "macros"] }
+env_logger = "0.9.0"
 
 [dependencies.tera]
 version = "1"
diff --git a/src/ast.rs b/src/ast.rs
index b070c32..eb10efc 100644
--- a/src/ast.rs
+++ b/src/ast.rs
@@ -1,11 +1,11 @@
 use lazy_static::lazy_static;
+use log::trace;
 use pandoc_ast::{Attr, Block, Inline, Map, MetaValue, Pandoc};
 use pulldown_cmark::{CodeBlockKind, Event, Options, Parser, Tag};
 use regex::Regex;
 use serde::Deserialize;
 use std::collections::BTreeMap;
 use std::path::{Path, PathBuf};
-use tracing::{event, span, Level};
 
 lazy_static! {
     // Pattern that recognises a YAML block at the beginning of a file.
@@ -51,40 +51,38 @@ impl std::str::FromStr for AbstractSyntaxTree {
 
     /// Create an abstract syntax tree from a string.
     fn from_str(markdown: &str) -> Result<Self, Self::Err> {
-        let span = span!(Level::TRACE, "parse markdown");
-        let _ = span.enter();
-        event!(Level::TRACE, "Parsing markdown");
+        trace!("Parsing markdown");
         let ast = if let Some((yaml, markdown)) = get_yaml(&LEADING_YAML_PATTERN, markdown) {
-            event!(Level::TRACE, ?yaml, "Found leading YAML");
+            trace!("Found leading YAML: {:?}", yaml);
             let meta = Metadata::new(yaml)?.to_map();
             let blocks = parse_blocks(markdown);
             AbstractSyntaxTree::new(meta, blocks)
         } else if let Some((yaml, _markdown)) = get_yaml(&TRAILING_YAML_PATTERN, markdown) {
-            event!(Level::TRACE, ?yaml, "Found trailing YAML");
+            trace!("Found trailing YAML: {:?}", yaml);
             let meta = Metadata::new(yaml)?.to_map();
             let blocks = parse_blocks(markdown);
             AbstractSyntaxTree::new(meta, blocks)
         } else {
-            event!(Level::TRACE, "No YAML to be found");
+            trace!("No YAML to be found");
             let blocks = parse_blocks(markdown);
             AbstractSyntaxTree::new(Map::new(), blocks)
         };
-        event!(Level::TRACE, "Parsing markdown: OK");
+        trace!("Parsing markdown: OK");
         Ok(ast)
     }
 }
 
 // Extract a YAML metadata block using a given regex.
 fn get_yaml<'a>(pat: &Regex, markdown: &'a str) -> Option<(&'a str, &'a str)> {
-    event!(Level::TRACE, ?markdown, "Markdown");
+    trace!("Markdown: {:?}", markdown);
     if let Some(c) = pat.captures(markdown) {
-        event!(Level::TRACE, ?c, "YAML regex matches");
+        trace!("YAML regex matches: {:?}", c);
         let yaml = c.name("yaml");
         let text = c.name("text");
-        event!(Level::TRACE, ?yaml, "YAML metadata");
-        event!(Level::TRACE, ?text, "markdown");
+        trace!("YAML metadata: {:?}", yaml);
+        trace!("markdown: {:?}", text);
         if yaml.is_some() && text.is_some() {
-            event!(Level::TRACE, "YAML regex captures YAML and text");
+            trace!("YAML regex captures YAML and text");
             let yaml = yaml?;
             let text = text?;
             let yaml = &markdown[yaml.start()..yaml.end()];
@@ -93,17 +91,17 @@ fn get_yaml<'a>(pat: &Regex, markdown: &'a str) -> Option<(&'a str, &'a str)> {
             assert!(yaml.ends_with("...\n"));
             return Some((yaml, text));
         } else {
-            event!(Level::TRACE, "YAML regex fails to capture YAML");
+            trace!("YAML regex fails to capture YAML");
         }
     } else {
-        event!(Level::TRACE, ?pat, "YAML regex does not match");
+        trace!("YAML regex does not match");
     }
     None
 }
 
 // Parse Markdown into a sequence of Blocks.
 fn parse_blocks(markdown: &str) -> Vec<Block> {
-    event!(Level::TRACE, "Parsing blocks");
+    trace!("Parsing blocks");
 
     // Define the Markdown parser.
     let mut options = Options::empty();
@@ -122,7 +120,7 @@ fn parse_blocks(markdown: &str) -> Vec<Block> {
     let mut inlines: Vec<Inline> = vec![];
 
     for event in parser {
-        event!(Level::TRACE, ?event);
+        trace!("Parsing event: {:?}", event);
         match event {
             // We ignore these for now. They're not needed for codegen.
             Event::Html(_)
@@ -160,7 +158,7 @@ fn parse_blocks(markdown: &str) -> Vec<Block> {
     // We MUST have emptied all inline elements.
     // assert!(inlines.is_empty());
 
-    event!(Level::TRACE, "Parsing blocks: OK");
+    trace!("Parsing blocks: OK");
     blocks
 }
 
@@ -192,15 +190,15 @@ fn image_block(dest: &str, title: &str) -> Block {
 }
 
 fn code_block(kind: &CodeBlockKind, inlines: &mut Vec<Inline>) -> Block {
-    event!(Level::TRACE, ?kind, "code block");
+    trace!("code block: {:?}", kind);
     let attr = if let CodeBlockKind::Fenced(lang) = kind {
-        event!(Level::TRACE, ?lang, "fenced code block");
+        trace!("fenced code block, lang={:?}", lang);
         parse_code_block_attrs(lang)
     } else {
-        event!(Level::TRACE, "indented code block");
+        trace!("indented code block");
         parse_code_block_attrs("")
     };
-    event!(Level::TRACE, ?attr, "code block attrs");
+    trace!("code block attrs: {:?}", attr);
     let mut code = String::new();
     for inline in inlines.drain(0..) {
         let text = plain_text_inline(inline);
@@ -231,7 +229,7 @@ fn plain_text_inline(inline: Inline) -> String {
 }
 
 fn parse_code_block_attrs(attrs: &str) -> Attr {
-    event!(Level::TRACE, ?attrs, "parsing code block attrs");
+    trace!("parsing code block attrs: {:?}", attrs);
     let mut id = "".to_string();
     let mut classes = vec![];
     let mut keyvalues = vec![];
@@ -304,13 +302,13 @@ struct Metadata {
 
 impl Metadata {
     fn new(yaml_text: &str) -> Result<Self, Error> {
-        event!(Level::TRACE, ?yaml_text, "Parsing YAML");
+        trace!("Parsing YAML");
         let meta: Self = serde_yaml::from_str(yaml_text)?;
         Ok(meta)
     }
 
     fn to_map(&self) -> Map<String, MetaValue> {
-        event!(Level::TRACE, "Creating metadata map from parsed YAML");
+        trace!("Creating metadata map from parsed YAML");
         let mut map: Map<String, MetaValue> = Map::new();
         map.insert(s("title"), meta_string(&self.title));
         if let Some(v) = &self.subtitle {
@@ -342,12 +340,7 @@ impl Metadata {
         if let Some(v) = &self.documentclass {
             map.insert(s("documentclass"), meta_string(v));
         }
-        event!(
-            Level::TRACE,
-            ?self,
-            ?map,
-            "Created metadata map from parsed YAML"
-        );
+        trace!("Created metadata map from parsed YAML");
         map
     }
 }
diff --git a/src/bin/cli/mod.rs b/src/bin/cli/mod.rs
index 52f5fb1..a16df87 100644
--- a/src/bin/cli/mod.rs
+++ b/src/bin/cli/mod.rs
@@ -3,13 +3,13 @@
 #![allow(unused)]
 
 use anyhow::Result;
+use log::trace;
 use serde::Serialize;
 use std::fmt::Debug;
 use std::path::Path;
 use std::str::FromStr;
 use std::{collections::HashMap, convert::TryFrom};
 use subplot::{DataFile, Document, Style, SubplotError};
-use tracing::{event, instrument, Level};
 
 pub fn extract_file<'a>(doc: &'a Document, filename: &str) -> Result<&'a DataFile> {
     for file in doc.files() {
diff --git a/src/bin/subplot.rs b/src/bin/subplot.rs
index 6028f76..2ad2df1 100644
--- a/src/bin/subplot.rs
+++ b/src/bin/subplot.rs
@@ -3,13 +3,13 @@
 
 use anyhow::Result;
 
+use log::{debug, trace};
 use structopt::StructOpt;
 use subplot::{
     codegen, load_document, load_document_with_pullmark, resource, DataFile, Document, MarkupOpts,
     Style,
 };
 use time::{format_description::FormatItem, macros::format_description, OffsetDateTime};
-use tracing::{event, instrument, span, Level, Subscriber};
 
 use std::convert::TryFrom;
 use std::ffi::OsString;
@@ -39,6 +39,7 @@ struct Toplevel {
 
 impl Toplevel {
     fn run(&self) -> Result<()> {
+        trace!("Toplevel: {:?}", self);
         self.command.run()
     }
 
@@ -161,8 +162,6 @@ impl Extract {
     }
 
     fn run(&self) -> Result<()> {
-        let span = span!(Level::TRACE, "extract");
-        let _enter = span.enter();
         let doc = load_document(&self.filename, Style::default(), None)?;
 
         let files: Vec<&DataFile> = if self.embedded.is_empty() {
@@ -217,8 +216,6 @@ impl Filter {
     }
 
     fn run(&self) -> Result<()> {
-        let span = span!(Level::TRACE, "filter");
-        let _enter = span.enter();
         let mut buffer = String::new();
         if let Some(filename) = &self.input {
             File::open(filename)?.read_to_string(&mut buffer)?;
@@ -267,8 +264,6 @@ impl Metadata {
     }
 
     fn run(&self) -> Result<()> {
-        let span = span!(Level::TRACE, "metadata");
-        let _enter = span.enter();
         let mut doc = load_document_with_pullmark(&self.filename, Style::default(), None)?;
         let meta = cli::Metadata::try_from(&mut doc)?;
         match self.output_format {
@@ -308,21 +303,18 @@ 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");
+            trace!("PDF output chosen");
             style.typeset_links_as_notes();
         }
         let mut doc = load_document(&self.input, style, None)?;
-        event!(Level::TRACE, "Got doc, now linting it");
+        trace!("Got doc, now linting it");
         doc.lint()?;
-        event!(Level::TRACE, "Doc linted ok");
+        trace!("Doc linted ok");
         let meta = doc.meta();
-        event!(Level::TRACE, ?meta, "Looking for template");
+        trace!("Looking for template, meta={:#?}", meta);
         let template = self
             .template
             .as_deref()
@@ -330,7 +322,7 @@ impl Docgen {
             .unwrap_or_else(|| doc.template())
             .unwrap_or("");
         let template = template.to_string();
-        event!(Level::TRACE, ?template);
+        trace!("Template: {:#?}", template);
         if !doc.check_named_files_exist(&template)?
             || !doc.check_matched_steps_have_impl(&template)
             || !doc.check_embedded_files_are_used(&template)?
@@ -437,9 +429,6 @@ impl Codegen {
     }
 
     fn run(&self) -> Result<()> {
-        let span = span!(Level::TRACE, "codegen");
-        let _enter = span.enter();
-
         let output = codegen(&self.filename, &self.output, self.template.as_deref())?;
         if self.run {
             let spec = output
@@ -470,7 +459,7 @@ impl Codegen {
 }
 
 fn real_main() {
-    event!(Level::TRACE, "Starting Subplot");
+    trace!("Starting Subplot");
     let argparser = Toplevel::clap();
     let version = long_version().unwrap();
     let argparser = argparser.long_version(version.as_str());
@@ -479,76 +468,17 @@ fn real_main() {
     args.handle_special_args();
     match args.run() {
         Ok(_) => {
-            event!(Level::TRACE, "Finished successfully");
+            trace!("Subplot finished successfully");
         }
         Err(e) => {
-            event!(Level::DEBUG, error = ?e, "Failed: {:?}", e);
+            debug!("Failed: {:?}", e);
             eprintln!("Failure: {:?}", e);
             process::exit(1);
         }
     }
 }
 
-enum LogFormat {
-    Pretty,
-    OneLine,
-    Json,
-}
-
 fn main() {
-    let filter = match tracing_subscriber::EnvFilter::try_from_env("SUBPLOT_LOG") {
-        Ok(f) => f,
-        Err(e) => {
-            if std::env::var_os("SUBPLOT_LOG").is_none() {
-                // Missing SUBPLOT_LOG, default filter should be INFO
-                tracing_subscriber::EnvFilter::new("info")
-            } else {
-                eprintln!("Unable to parse log directive from SUBPLOT_LOG: {:?}", e);
-                process::exit(1);
-            }
-        }
-    };
-    let format = match std::env::var("SUBPLOT_LOG_FORMAT")
-        .map(|v| v.to_ascii_lowercase())
-        .as_deref()
-    {
-        Err(_) | Ok("oneline") | Ok("default") => LogFormat::OneLine,
-        Ok("pretty") => LogFormat::Pretty,
-        Ok("json") => LogFormat::Json,
-        Ok(v) => {
-            eprintln!("Unknown log format: {:?}", v);
-            process::exit(1);
-        }
-    };
-    match std::env::var("SUBPLOT_LOG_FILE").ok().as_deref() {
-        None | Some("") | Some("-") => {
-            let subscriber = tracing_subscriber::fmt().with_env_filter(filter);
-            let subscriber: Box<dyn Subscriber + Send + Sync + 'static> = match format {
-                LogFormat::OneLine => Box::new(subscriber.finish()),
-                LogFormat::Pretty => Box::new(subscriber.pretty().finish()),
-                LogFormat::Json => Box::new(subscriber.json().with_ansi(false).finish()),
-            };
-            tracing::subscriber::with_default(subscriber, real_main);
-        }
-        Some(fname) => {
-            let curdir = std::path::Component::CurDir;
-            let location = PathBuf::from(fname);
-            let parent = location.parent().unwrap_or_else(|| curdir.as_ref());
-            let fname = location
-                .file_name()
-                .expect("No filename given in SUBPLOT_TRACE_LOG");
-            let appender = tracing_appender::rolling::never(parent, fname);
-            let (non_blocking, _guard) = tracing_appender::non_blocking(appender);
-            let subscriber = tracing_subscriber::fmt()
-                .with_writer(non_blocking)
-                .with_env_filter(filter)
-                .with_ansi(false);
-            let subscriber: Box<dyn Subscriber + Send + Sync + 'static> = match format {
-                LogFormat::OneLine => Box::new(subscriber.finish()),
-                LogFormat::Pretty => Box::new(subscriber.pretty().finish()),
-                LogFormat::Json => Box::new(subscriber.json().finish()),
-            };
-            tracing::subscriber::with_default(subscriber, real_main);
-        }
-    }
+    env_logger::init_from_env("SUBPLOT_LOG");
+    real_main();
 }
diff --git a/src/bindings.rs b/src/bindings.rs
index 2d5f062..0837553 100644
--- a/src/bindings.rs
+++ b/src/bindings.rs
@@ -16,8 +16,8 @@ use std::str::FromStr;
 use std::sync::Arc;
 
 use lazy_static::lazy_static;
+use log::trace;
 use regex::{escape, Regex, RegexBuilder};
-use tracing::{event, instrument, Level};
 
 #[derive(Debug, PartialEq, Eq, Hash, Copy, Clone, Serialize, Deserialize)]
 #[serde(rename_all = "lowercase")]
@@ -462,7 +462,6 @@ 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 {
@@ -500,14 +499,13 @@ impl Bindings {
     }
 
     /// Add bindings from a file.
-    #[instrument(level = "trace", skip(self))]
     pub fn add_from_file<P>(&mut self, filename: P, template: Option<&str>) -> Result<()>
     where
         P: AsRef<Path> + Debug,
     {
         let yaml = resource::read_as_string(filename.as_ref(), template)
             .map_err(|e| SubplotError::BindingsFileNotFound(filename.as_ref().into(), e))?;
-        event!(Level::TRACE, "Loaded file content");
+        trace!("Loaded file content");
         self.add_from_yaml(&yaml).map_err(|e| {
             SubplotError::BindingFileParseError(filename.as_ref().to_owned(), Box::new(e))
         })?;
@@ -524,7 +522,6 @@ 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();
@@ -560,16 +557,10 @@ 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 acquired binding"
-    );
+    trace!("Successfully acquired binding");
 
     let mut ret = Binding::new(kind, &pattern, parsed.case_sensitive, types)?;
-    event!(Level::TRACE, "Binding parsed OK");
+    trace!("Binding parsed OK");
     for (template, pimpl) in &parsed.impls {
         ret.add_impl(template, &pimpl.function, pimpl.cleanup.as_deref());
     }
diff --git a/src/doc.rs b/src/doc.rs
index 5c81e27..2ff1484 100644
--- a/src/doc.rs
+++ b/src/doc.rs
@@ -23,7 +23,7 @@ use std::str::FromStr;
 
 use pandoc_ast::{MutVisitor, Pandoc};
 
-use tracing::{event, instrument, span, Level};
+use log::{error, trace};
 
 /// The set of known (special) classes which subplot will always recognise
 /// as being valid.
@@ -102,7 +102,6 @@ impl<'a> Document {
         }
     }
 
-    #[instrument(level = "trace", skip(ast))]
     fn from_ast<P>(
         basedir: P,
         markdowns: Vec<PathBuf>,
@@ -115,7 +114,7 @@ impl<'a> Document {
     {
         let meta = Metadata::new(basedir, &ast, template)?;
         let mut linter = LintingVisitor::default();
-        event!(Level::TRACE, "Walking AST for linting...");
+        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
@@ -123,12 +122,11 @@ impl<'a> Document {
         }
         let files = DataFiles::new(&mut ast);
         let doc = Document::new(markdowns, ast, meta, files, style);
-        event!(Level::TRACE, "Loaded from JSON OK");
+        trace!("Loaded from JSON OK");
         Ok(doc)
     }
 
     /// Construct a Document from a JSON AST
-    #[instrument(level = "trace", skip(json))]
     pub fn from_json<P>(
         basedir: P,
         markdowns: Vec<PathBuf>,
@@ -139,7 +137,7 @@ impl<'a> Document {
     where
         P: AsRef<Path> + Debug,
     {
-        event!(Level::TRACE, "Parsing document...");
+        trace!("Parsing document...");
         let ast: Pandoc = serde_json::from_str(json)?;
         Self::from_ast(basedir, markdowns, ast, style, template)
     }
@@ -149,7 +147,6 @@ 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,
@@ -170,13 +167,13 @@ impl<'a> Document {
         // Add external Pandoc filters.
         crate::policy::add_citeproc(&mut pandoc);
 
-        event!(Level::TRACE, ?filename, "Invoking Pandoc to parse document");
+        trace!("Invoking Pandoc to parse document {:?}", filename);
         let output = match pandoc.execute()? {
             pandoc::PandocOutput::ToBuffer(o) => o,
             _ => return Err(SubplotError::NotJson),
         };
         let doc = Document::from_json(basedir, markdowns, &output, style, template)?;
-        event!(Level::TRACE, "Loaded document OK");
+        trace!("Loaded document OK");
         Ok(doc)
     }
 
@@ -185,23 +182,18 @@ impl<'a> Document {
     /// The file can be in the CommonMark format, with some
     /// extensions. This uses the pulldown-cmark crate to parse the
     /// file into an AST.
-    #[instrument(level = "trace")]
     pub fn from_file_with_pullmark(
         basedir: &Path,
         filename: &Path,
         style: Style,
         template: Option<&str>,
     ) -> Result<Document> {
-        event!(
-            Level::TRACE,
-            ?filename,
-            "Parsing document with pullmark-cmark"
-        );
+        trace!("Parsing document with pullmark-cmark from {:?}", filename);
         let filename = filename.to_path_buf();
         let markdown = std::fs::read_to_string(&filename)?;
         let ast = ast::AbstractSyntaxTree::from_str(&markdown)?;
 
-        event!(Level::TRACE, "Parsed document OK");
+        trace!("Parsed document OK");
         Self::from_ast(basedir, vec![filename], ast.to_pandoc(), style, template)
     }
 
@@ -269,13 +261,12 @@ impl<'a> Document {
     }
 
     /// Check the document for common problems.
-    #[instrument(level = "trace", skip(self))]
     pub fn lint(&self) -> Result<()> {
-        event!(Level::TRACE, "Linting document");
+        trace!("Linting document");
         self.check_doc_has_title()?;
         self.check_filenames_are_unique()?;
         self.check_block_classes()?;
-        event!(Level::TRACE, "No linting problems found");
+        trace!("No linting problems found");
         Ok(())
     }
 
@@ -334,14 +325,13 @@ 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");
+        trace!("Checking that files exist");
         let mut okay = true;
         let scenarios = match self.matched_scenarios(template) {
             Ok(scenarios) => scenarios,
@@ -365,14 +355,13 @@ impl<'a> Document {
     }
 
     /// Check that all embedded files are used by matched steps.
-    #[instrument(level = "trace", skip(self))]
     pub fn check_embedded_files_are_used(&mut self, template: &str) -> Result<bool> {
         let mut filenames: HashSet<_> = self
             .files()
             .iter()
             .map(|f| f.filename().to_lowercase())
             .collect();
-        event!(Level::TRACE, ?filenames, "Checking that files are used");
+        trace!("Checking that files are used");
         let scenarios = match self.matched_scenarios(template) {
             Ok(scenarios) => scenarios,
             Err(_) => return Ok(true), // We can't do the check, so say it's okay.
@@ -403,21 +392,16 @@ 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");
+        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");
+        trace!("Found {} scenarios", scenarios.len());
         for scenario in scenarios {
-            event!(
-                Level::TRACE,
-                title = scenario.title(),
-                "Checking that steps in scenario"
-            );
+            trace!("Checking that steps in scenario");
             let mut said_scenario = false;
             for step in scenario.steps() {
                 if step.function().is_none() {
@@ -427,11 +411,7 @@ impl<'a> Document {
                         said_scenario = true;
                     }
                     eprintln!("  Step missing implementation: '{}'", step.text());
-                    event!(
-                        Level::ERROR,
-                        step = step.text(),
-                        "Missing step implementation"
-                    );
+                    trace!("Missing step implementation: {:?}", step.text());
                     okay = false;
                 }
             }
@@ -465,11 +445,9 @@ impl<'a> Document {
     }
 
     /// Return matched scenarios in a document.
-    #[instrument(skip(self))]
     pub fn matched_scenarios(&mut self, template: &str) -> Result<Vec<MatchedScenario>> {
         let scenarios = self.scenarios()?;
-        event!(
-            Level::TRACE,
+        trace!(
             "Found {} scenarios, checking their bindings",
             scenarios.len()
         );
@@ -496,24 +474,20 @@ impl<'a> Document {
 /// Load a `Document` from a file.
 ///
 /// This version uses Pandoc to parse the Markdown.
-#[instrument(level = "trace")]
 pub fn load_document<P>(filename: P, style: Style, template: Option<&str>) -> Result<Document>
 where
     P: AsRef<Path> + Debug,
 {
     let filename = filename.as_ref();
     let base_path = get_basedir_from(filename);
-    event!(
-        Level::TRACE,
-        ?filename,
-        ?base_path,
+    trace!(
         "Loading document based at `{}` called `{}` with {:?}",
         base_path.display(),
         filename.display(),
         style
     );
     let doc = Document::from_file(&base_path, filename, style, template)?;
-    event!(Level::TRACE, "Loaded doc from file OK");
+    trace!("Loaded doc from file OK");
 
     Ok(doc)
 }
@@ -521,7 +495,6 @@ where
 /// Load a `Document` from a file.
 ///
 /// This version uses the `cmark-pullmark` crate to parse Markdown.
-#[instrument(level = "trace")]
 pub fn load_document_with_pullmark<P>(
     filename: P,
     style: Style,
@@ -532,10 +505,7 @@ where
 {
     let filename = filename.as_ref();
     let base_path = get_basedir_from(filename);
-    event!(
-        Level::TRACE,
-        ?filename,
-        ?base_path,
+    trace!(
         "Loading document based at `{}` called `{}` with {:?} using pullmark-cmark",
         base_path.display(),
         filename.display(),
@@ -543,22 +513,19 @@ where
     );
     crate::resource::add_search_path(filename.parent().unwrap());
     let doc = Document::from_file_with_pullmark(&base_path, filename, style, template)?;
-    event!(Level::TRACE, "Loaded doc from file OK");
+    trace!("Loaded doc from file OK");
     Ok(doc)
 }
 
 /// Generate code for one document.
 pub fn codegen(filename: &Path, output: &Path, template: Option<&str>) -> Result<CodegenOutput> {
-    let span = span!(Level::TRACE, "codegen");
-    let _enter = span.enter();
-
     let mut doc = load_document_with_pullmark(filename, Style::default(), template)?;
     doc.lint()?;
     let template = template
         .map(Ok)
         .unwrap_or_else(|| doc.template())?
         .to_string();
-    event!(Level::TRACE, ?template);
+    trace!("Template: {:?}", template);
     if !doc.meta().templates().any(|t| t == template) {
         return Err(SubplotError::TemplateSupportNotPresent);
     }
@@ -566,15 +533,15 @@ pub fn codegen(filename: &Path, output: &Path, template: Option<&str>) -> Result
         || !doc.check_matched_steps_have_impl(&template)
         || !doc.check_embedded_files_are_used(&template)?
     {
-        event!(Level::ERROR, "Found problems in document, cannot continue");
+        error!("Found problems in document, cannot continue");
         eprintln!("Unable to continue");
         std::process::exit(1);
     }
 
-    event!(Level::TRACE, "Generating code");
+    trace!("Generating code");
 
     generate_test_program(&mut doc, output, &template)?;
-    event!(Level::TRACE, "Finished generating code");
+    trace!("Finished generating code");
 
     Ok(CodegenOutput::new(template, doc))
 }
diff --git a/src/metadata.rs b/src/metadata.rs
index 3bc7268..0248891 100644
--- a/src/metadata.rs
+++ b/src/metadata.rs
@@ -8,7 +8,7 @@ use std::path::{Path, PathBuf};
 
 use pandoc_ast::{Inline, Map, MetaValue, Pandoc};
 
-use tracing::{event, instrument, Level};
+use log::trace;
 
 /// Metadata of a document, as needed by Subplot.
 #[derive(Debug)]
@@ -31,7 +31,6 @@ pub struct DocumentImpl {
 
 impl Metadata {
     /// Construct a Metadata from a Document, if possible.
-    #[instrument(level = "trace", skip(doc))]
     pub fn new<P>(basedir: P, doc: &Pandoc, template: Option<&str>) -> Result<Metadata>
     where
         P: AsRef<Path> + Debug,
@@ -41,15 +40,7 @@ impl Metadata {
         let bindings_filenames = get_bindings_filenames(&doc.meta);
         let bibliographies = get_bibliographies(basedir.as_ref(), &doc.meta);
         let classes = get_classes(&doc.meta);
-        event!(
-            Level::TRACE,
-            ?title,
-            ?date,
-            ?bindings_filenames,
-            ?bibliographies,
-            ?classes,
-            "Loaded basic metadata"
-        );
+        trace!("Loaded basic metadata");
 
         let mut impls = HashMap::new();
 
@@ -64,11 +55,7 @@ impl Metadata {
                     }
                 }
                 _ => {
-                    event!(
-                        Level::WARN,
-                        value = ?raw_impls,
-                        "Ignoring unknown raw implementation value"
-                    );
+                    trace!("Ignoring unknown raw implementation value");
                 }
             }
         }
@@ -79,7 +66,7 @@ impl Metadata {
 
         get_bindings(&bindings_filenames, &mut bindings, template)?;
 
-        event!(Level::TRACE, "Loaded all metadata successfully");
+        trace!("Loaded all metadata successfully");
 
         Ok(Metadata {
             title,
diff --git a/src/policy.rs b/src/policy.rs
index 00a18d3..972d081 100644
--- a/src/policy.rs
+++ b/src/policy.rs
@@ -1,7 +1,7 @@
 use std::path::{Component, Path, PathBuf};
 
+use log::trace;
 use pandoc::{InputFormat, InputKind, OutputFormat, OutputKind, Pandoc, PandocOption};
-use tracing::{event, instrument, Level};
 
 /// Get the base directory given the name of the markdown file.
 ///
@@ -22,7 +22,6 @@ pub fn get_basedir_from(filename: &Path) -> PathBuf {
 ///
 /// This attempts to determine if `--citeproc` or `--filter pandoc-citeproc`
 /// is needed, and then does that specific thing.
-#[instrument(skip(pandoc))]
 pub fn add_citeproc(pandoc: &mut Pandoc) {
     let mut guesser = Pandoc::new();
     guesser.set_input(InputKind::Pipe("".to_string()));
@@ -31,10 +30,10 @@ pub fn add_citeproc(pandoc: &mut Pandoc) {
     guesser.set_output(OutputKind::Pipe);
     guesser.add_option(PandocOption::Citeproc);
     if guesser.execute().is_ok() {
-        event!(Level::TRACE, "Discovered --citeproc");
+        trace!("Discovered --citeproc");
         pandoc.add_option(PandocOption::Citeproc);
     } else {
-        event!(Level::TRACE, "Discovered --filter pandoc-citeproc");
+        trace!("Discovered --filter pandoc-citeproc");
         pandoc.add_option(PandocOption::Filter("pandoc-citeproc".into()));
     }
 }
diff --git a/src/visitor/datafiles.rs b/src/visitor/datafiles.rs
index 09d9245..53ab7bb 100644
--- a/src/visitor/datafiles.rs
+++ b/src/visitor/datafiles.rs
@@ -3,7 +3,6 @@ use crate::DataFile;
 use crate::DataFiles;
 
 use pandoc_ast::{Block, MutVisitor};
-use tracing::{event, Level};
 
 impl MutVisitor for DataFiles {
     fn visit_vec_block(&mut self, vec_block: &mut Vec<Block>) {
@@ -12,7 +11,6 @@ impl MutVisitor for DataFiles {
             match block {
                 Block::CodeBlock(attr, contents) => {
                     if is_class(attr, "file") {
-                        event!(Level::TRACE, ?attr, "visiting code block");
                         let add_newline = match panhelper::find_attr_kv(attr, "add-newline").next()
                         {
                             None | Some("auto") => !contents.ends_with('\n'),