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

We don't use async in Subplot, and the mental overhead of learning
tracing and the code overhead to add support for logging custom
values (implementing the Value trait for Subplot internal types) does
not seem worthwhile.

Sponsored-by: author

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'),