Implement log levels

.justfile

@@ -10,7 +10,7 @@ alias u := update
 # Build and serve
 [group: 'develop']
 run host='::1' port='3003' *args:
-    DEBUG=${DEBUG:-1} {{ debug_vars }} cargo run -- \
+    DEBUG=${DEBUG:-debug} {{ debug_vars }} cargo run -- \
         --hostname {{ host }} --port {{ port }} {{ args }}
 
 alias r := run

src/dev.rs

@@ -1,149 +0,0 @@
-#[allow(clippy::print_stderr)]
-pub fn elog(function: &str, message: &str) {
-    eprintln!("{:?} [{function}] {message}", crate::ONSET.elapsed());
-}
-
-// Paths in this slice suppress logging if found in the stack trace
-pub const SKIP_PATHS: &[&str] = &["en::types::Graph::parse"];
-
-#[macro_export]
-macro_rules! log {
-        ($fmt:expr $(, $($arg:tt)+ )? ) => {{
-        let mut display_path = String::default();
-        let mut path = std::any::type_name_of_val(&|| {})
-            .to_string().replace("::{{closure}}", "");
-
-        let trace = format!("{:?}", std::backtrace::Backtrace::capture());
-
-        let level: u8 = std::env::var("DEBUG")
-            .unwrap_or("0".to_string()).trim().parse().unwrap_or(0);
-
-        if path.matches("::").count() > 3 {
-
-            if let Some(s) = path.split(" as ").next()
-                .map(|parent| parent.replace(['<', '>'], ""))
-                .and_then(|parent| { path.split(" as ").nth(1)
-                    .and_then(|s| s.split("::").last())
-                    .map(|caller| format!("{parent}::{caller}"))
-                }) { path = s; }
-
-            let path_vec: Vec<&str> = path.split("::").collect();
-
-            if let (
-                Some(last),
-                Some(second_to_last),
-                Some(third_to_last),
-            ) = (
-                path_vec.get(path_vec.len().saturating_sub(1)),
-                path_vec.get(path_vec.len().saturating_sub(2)),
-                path_vec.get(path_vec.len().saturating_sub(3)),
-            ) {
-                display_path = if level > 4 {
-                    format!("{} -> {}", trace, path.clone())
-                } else if level > 3 {
-                    path.clone()
-                } else if level > 1 {
-                    format!("{third_to_last}::{second_to_last}::{last}")
-                } else {
-                    format!("{second_to_last}::{last}")
-                };
-            }
-        } else {
-            display_path = path.clone()
-        };
-
-        let filter = std::env::var("DEBUG_FILTER").unwrap_or("any".to_string());
-
-        if $crate::dev::SKIP_PATHS.iter().all(|&s| !trace.contains(s)) &&
-        (filter == "any" || filter.is_empty() || path.contains(&filter)) &&
-        level > 0
-        {
-            $crate::dev::elog(&display_path, &format!($fmt $(, $($arg)+ )?));
-        };
-
-    }};
-}
-
-pub fn wrap(s: &str) -> String {
-    fn symbolize(s: &str) -> String {
-        if s == r"\n" {
-            String::from('↳')
-        } else {
-            String::from(s)
-        }
-    }
-
-    fn quote(s: &str) -> String {
-        if s.contains(' ') {
-            format!("'{s}'")
-        } else {
-            String::from(s)
-        }
-    }
-
-    fn escape(s: &str) -> String {
-        s.escape_debug().collect()
-    }
-
-    symbolize(&quote(&escape(s)))
-}
-
-#[cfg(test)]
-mod tests {
-    use super::*;
-
-    #[test]
-    fn wrap_newline() {
-        assert_eq!(wrap("\n"), String::from("↳"));
-    }
-
-    #[test]
-    fn wrap_space() {
-        assert_eq!(wrap(" "), String::from("' '"));
-    }
-
-    #[test]
-    fn wrap_spaces() {
-        assert_eq!(wrap("  "), String::from("'  '"));
-    }
-
-    #[test]
-    fn wrap_containing_space() {
-        assert_eq!(wrap("< "), String::from("'< '"));
-    }
-
-    fn run_in_debug_level(level: &str) {
-        #[allow(unsafe_code)]
-        unsafe {
-            std::env::set_var("DEBUG", level);
-            log!("Debug is set to {level}");
-        }
-    }
-
-    #[test]
-    fn debug_var_set() {
-        for level in 0..9 {
-            run_in_debug_level(&level.to_string());
-        }
-        run_in_debug_level("");
-        run_in_debug_level("駄目！");
-    }
-
-    #[test]
-    fn trait_stripping() {
-        pub trait Loggable {
-            fn test(&self);
-        }
-
-        struct Logger {}
-
-        impl Loggable for Logger {
-            fn test(&self) {
-                log!("This is inside a trait implementation");
-            }
-        }
-
-        let logger = Logger {};
-        logger.test();
-    }
-}

src/graph.rs

@@ -324,15 +324,16 @@ impl Graph {
         let collapsed_query = query.trim().replace(" ", "");
 
         if query == collapsed_query {
-            log!("Chasing candidate for query {query}");
+            log!(VERBOSE, "Chasing candidate for query {query}");
         } else {
             log!(
+                VERBOSE,
                 "Chasing candidate for query {query}, collapsed {collapsed_query}"
             );
         }
 
         let candidate = if let Some(exact_match) = self.nodes.get(query) {
-            log!("Elected exact match {exact_match}");
+            log!(VERBOSE, "Elected exact match {exact_match}");
             QueryResult {
                 node: Some(exact_match.clone()),
                 exact: true,
@@ -341,21 +342,24 @@ impl Graph {
         } else if let Some(lower_key) =
             self.lowercase_keymap.get(&collapsed_query.to_lowercase())
         {
-            log!("Elected non-exact match through lower key {lower_key}");
+            log!(
+                VERBOSE,
+                "Elected non-exact match through lower key {lower_key}"
+            );
             QueryResult {
                 node: self.nodes.get(lower_key).cloned(),
                 exact: false,
                 redirect: false,
             }
         } else {
-            log!("No candidate found");
+            log!(VERBOSE, "No candidate found");
             QueryResult::default()
         };
 
         if let Some(candidate_node) = &candidate.node
             && !candidate_node.redirect.is_empty()
         {
-            log!("Recursing: candidate is a redirect");
+            log!(VERBOSE, "Recursing: candidate is a redirect");
             if let Some(recursive_match) =
                 self.find_node(&candidate_node.redirect).node
             {
@@ -368,7 +372,7 @@ impl Graph {
                 QueryResult::default()
             }
         } else {
-            log!("Returning candidate {candidate}");
+            log!(VERBOSE, "Returning candidate {candidate}");
             candidate
         }
     }

src/lib.rs

@@ -2,12 +2,15 @@ use std::{sync, time};
 
 pub mod prelude {
     pub use crate::log;
+    pub use crate::tlog;
+    pub use crate::log::Level::*;
+    pub use crate::log::now;
 }
 
 pub mod graph;
 pub mod router;
 pub mod syntax;
-pub mod dev;
+pub mod log;
 
 pub static ONSET: sync::LazyLock<time::Instant> =
     sync::LazyLock::new(time::Instant::now);

src/log.rs

@@ -0,0 +1,276 @@
+use std::{backtrace::Backtrace, env, time::Instant};
+
+pub use level::*;
+
+mod level;
+
+/// Strings in this slice suppress logging if found in the stack trace
+pub const EXCLUSIONS: &[&str] = &["en::graph::Graph::parse_config"];
+
+#[derive(Debug)]
+pub struct Data {
+    pub env_level: Level,
+    pub exclude: String,
+    pub filter: String,
+    pub message_level: Level,
+    pub path: String,
+    pub should_log: bool,
+    pub trace: std::backtrace::Backtrace,
+}
+
+impl Data {
+    pub fn new(
+        message_level_opt: Option<Level>,
+        captured_path: &str,
+        trace: Backtrace,
+    ) -> Data {
+        let trace_string = format!("{trace:?}");
+        let filter = env::var("DEBUG_FILTER").unwrap_or_default();
+        let exclude = env::var("DEBUG_EXCLUDE").unwrap_or_default();
+        let env_level = Data::env_level();
+        let message_level = message_level_opt.unwrap_or(MESSAGE_DEFAULT);
+        let path = make_display_path(captured_path, &env_level);
+
+        let is_silent = env_level <= Level::SILENT;
+        let message_level_is_within_env_level = message_level <= env_level;
+        let excluded_in_code =
+            !EXCLUSIONS.iter().all(|&s| !trace_string.contains(s));
+        let excluded_by_env =
+            !exclude.is_empty() && !trace_string.contains(&exclude);
+        let matches_filter =
+            filter.is_empty() || captured_path.contains(&filter);
+
+        let should_log = !is_silent
+            && message_level_is_within_env_level
+            && !excluded_in_code
+            && !excluded_by_env
+            && matches_filter;
+
+        #[allow(clippy::print_stderr)]
+        if env_level == Level::META {
+            eprintln!(
+                "Log decision for message from {path}: {should_log} given\n\
+                is_silent: {is_silent} (expected false)\n\
+                message_level_is_within_env_level: {message_level_is_within_env_level}\n\
+                excluded_in_code: {excluded_in_code} (expected false)\n\
+                excluded_by_env: {excluded_by_env} (expected false)\n\
+                matches_filter: {matches_filter}\n\
+            "
+            );
+        }
+
+        Data {
+            env_level,
+            exclude,
+            filter,
+            message_level,
+            path,
+            should_log,
+            trace,
+        }
+    }
+
+    pub fn env_level() -> Level {
+        if let Ok(level) = env::var("DEBUG") {
+            Level::from(level.as_str())
+        } else {
+            ENV_DEFAULT
+        }
+    }
+}
+
+#[allow(clippy::print_stderr)]
+pub fn print_state() {
+    let env_level = Data::env_level();
+    let version = env!("CARGO_PKG_VERSION");
+    if env_level == ENV_DEFAULT {
+        eprintln!("en {version}");
+    } else {
+        eprintln!("en {version} [logging level {env_level}]");
+    }
+}
+
+#[allow(clippy::print_stderr)]
+pub fn timed(past: &Instant, message: &str) -> Instant {
+    let now = Instant::now();
+    let level = Data::env_level();
+    let duration = now.duration_since(*past);
+    let display_duration = if duration.as_millis() > 1000 {
+        format!("{}s {}ms", duration.as_secs(), duration.subsec_millis())
+    } else if duration.as_millis() == 0 {
+        format!("{}ns", duration.as_nanos())
+    } else {
+        format!("{}ms", duration.as_millis())
+    };
+    if !message.is_empty() && Level::DEBUG <= level {
+        eprintln!("[tlog] +{display_duration} {message}");
+    }
+    now
+}
+
+#[macro_export]
+macro_rules! tlog {
+    ($instant:expr, $fmt:expr $(, $($arg:tt)+ )?) => {{
+        $crate::log::timed($instant, &format!($fmt $(, $($arg)+ )?))
+    }};
+}
+
+pub fn now() -> Instant {
+    Instant::now()
+}
+
+#[allow(clippy::print_stderr)]
+pub fn elog(function: &str, message: &str) {
+    eprintln!("{:?} [{function}] {message}", crate::ONSET.elapsed());
+}
+
+#[macro_export]
+macro_rules! log {
+    ($level:path, $fmt:expr $(, $($arg:tt)+ )?) => {{
+
+         let data = $crate::log::Data::new(
+            Some($level),
+            std::any::type_name_of_val(&|| {}),
+            std::backtrace::Backtrace::capture(),
+        );
+
+        if data.should_log {
+            $crate::log::elog(&data.path, &format!($fmt $(, $($arg)+ )?));
+        }
+    }};
+    ($fmt:expr $(, $($arg:tt)+ )?) => {{
+
+        let data = $crate::log::Data::new(
+            None,
+            std::any::type_name_of_val(&|| {}),
+            std::backtrace::Backtrace::capture(),
+        );
+
+        if data.should_log {
+            $crate::log::elog(&data.path, &format!($fmt $(, $($arg)+ )?));
+        };
+
+    }};
+}
+
+pub fn make_display_path(type_path: &str, env_level: &Level) -> String {
+    let mut path = type_path.to_string().replace("::{{closure}}", "");
+
+    if let Some(s) = path
+        .split(" as ")
+        .next()
+        .map(|parent| parent.replace(['<', '>'], ""))
+        .and_then(|parent| {
+            path.split(" as ")
+                .nth(1)
+                .and_then(|s| s.split("::").last())
+                .map(|caller| format!("{parent}::{caller}"))
+        })
+    {
+        path = s;
+    }
+
+    let path_vec: Vec<&str> = path.split("::").collect();
+
+    if let (Some(last), Some(second_to_last), Some(third_to_last)) = (
+        path_vec.get(path_vec.len().saturating_sub(1)),
+        path_vec.get(path_vec.len().saturating_sub(2)),
+        path_vec.get(path_vec.len().saturating_sub(3)),
+    ) {
+        if *env_level > Level::VERBOSE {
+            path.clone()
+        } else if *env_level > Level::DEBUG {
+            format!("{third_to_last}::{second_to_last}::{last}")
+        } else if *env_level >= ENV_DEFAULT {
+            format!("{second_to_last}::{last}")
+        } else {
+            String::from(*last)
+        }
+    } else {
+        path.clone()
+    }
+}
+
+pub fn wrap(s: &str) -> String {
+    fn symbolize(s: &str) -> String {
+        if s == r"\n" {
+            String::from('↳')
+        } else {
+            String::from(s)
+        }
+    }
+
+    fn quote(s: &str) -> String {
+        if s.contains(' ') {
+            format!("'{s}'")
+        } else {
+            String::from(s)
+        }
+    }
+
+    fn escape(s: &str) -> String {
+        s.escape_debug().collect()
+    }
+
+    symbolize(&quote(&escape(s)))
+}
+
+#[cfg(test)]
+mod tests {
+    use super::*;
+
+    #[test]
+    fn wrap_newline() {
+        assert_eq!(wrap("\n"), String::from("↳"));
+    }
+
+    #[test]
+    fn wrap_space() {
+        assert_eq!(wrap(" "), String::from("' '"));
+    }
+
+    #[test]
+    fn wrap_spaces() {
+        assert_eq!(wrap("  "), String::from("'  '"));
+    }
+
+    #[test]
+    fn wrap_containing_space() {
+        assert_eq!(wrap("< "), String::from("'< '"));
+    }
+
+    fn run_in_debug_level(level: &str) {
+        #[allow(unsafe_code)]
+        unsafe {
+            std::env::set_var("DEBUG", level);
+            log!("Debug is set to {level}");
+        }
+    }
+
+    #[test]
+    fn debug_var_set() {
+        for level in 0..9 {
+            run_in_debug_level(&level.to_string());
+        }
+        run_in_debug_level("");
+        run_in_debug_level("駄目！");
+    }
+
+    #[test]
+    fn trait_stripping() {
+        pub trait Loggable {
+            fn test(&self);
+        }
+
+        struct Logger {}
+
+        impl Loggable for Logger {
+            fn test(&self) {
+                log!("This is inside a trait implementation");
+            }
+        }
+
+        let logger = Logger {};
+        logger.test();
+    }
+}

src/log/level.rs

@@ -0,0 +1,105 @@
+#[derive(PartialEq, Eq, PartialOrd, Ord, Clone, Debug)]
+#[repr(u16)]
+pub enum Level {
+    SILENT = 0,
+    FATAL = 1,
+    ERROR = 2,
+    WARN = 3,
+    INFO = 4,
+    DEBUG = 5,
+    VERBOSE = 6,
+    TRACE = 7,
+    META = 37,
+}
+
+pub const ENV_DEFAULT: Level = Level::WARN;
+pub const MESSAGE_DEFAULT: Level = Level::DEBUG;
+
+impl From<Level> for u16 {
+    fn from(level: Level) -> u16 {
+        match level {
+            Level::SILENT => 0,
+            Level::FATAL => 1,
+            Level::ERROR => 2,
+            Level::WARN => 3,
+            Level::INFO => 4,
+            Level::DEBUG => 5,
+            Level::VERBOSE => 6,
+            Level::TRACE => 7,
+            Level::META => 37,
+        }
+    }
+}
+
+impl From<u16> for Level {
+    fn from(numeric: u16) -> Level {
+        if numeric == 0 {
+            Level::SILENT
+        } else if numeric == 1 {
+            Level::FATAL
+        } else if numeric == 2 {
+            Level::ERROR
+        } else if numeric == 3 {
+            Level::WARN
+        } else if numeric == 4 {
+            Level::INFO
+        } else if numeric == 5 {
+            Level::DEBUG
+        } else if numeric == 6 {
+            Level::VERBOSE
+        } else if numeric == 7 {
+            Level::TRACE
+        } else if numeric == 37 {
+            Level::META
+        } else {
+            super::ENV_DEFAULT
+        }
+    }
+}
+
+impl From<&str> for Level {
+    fn from(s: &str) -> Level {
+        if s == "0" || s == "SILENT" || s == "silent" {
+            Level::SILENT
+        } else if s == "1" || s == "FATAL" || s == "fatal" {
+            Level::FATAL
+        } else if s == "2" || s == "ERROR" || s == "error" {
+            Level::ERROR
+        } else if s == "3"
+            || s == "WARN"
+            || s == "warn"
+            || s == "WARNING"
+            || s == "warning"
+        {
+            Level::WARN
+        } else if s == "4" || s == "INFO" || s == "info" {
+            Level::INFO
+        } else if s == "5" || s == "DEBUG" || s == "debug" {
+            Level::DEBUG
+        } else if s == "6" || s == "VERBOSE" || s == "verbose" {
+            Level::VERBOSE
+        } else if s == "7" || s == "TRACE" || s == "trace" {
+            Level::TRACE
+        } else if s == "37" || s == "META" || s == "meta" {
+            Level::META
+        } else {
+            super::ENV_DEFAULT
+        }
+    }
+}
+impl std::fmt::Display for Level {
+    fn fmt(&self, f: &mut std::fmt::Formatter) -> std::fmt::Result {
+        let s = match self {
+            Level::SILENT => "SILENT",
+            Level::FATAL => "FATAL",
+            Level::ERROR => "ERROR",
+            Level::WARN => "WARNING",
+            Level::INFO => "INFO",
+            Level::DEBUG => "DEBUG",
+            Level::VERBOSE => "VERBOSE",
+            Level::TRACE => "TRACE",
+            Level::META => "META",
+        };
+        write!(f, "{s}")
+    }
+}

src/main.rs

@@ -1,15 +1,17 @@
 use std::{backtrace, io, panic};
 
-use en::{prelude::*, ONSET, graph::Graph, syntax};
+use en::{prelude::*, log, ONSET, graph::Graph, syntax};
 
 #[tokio::main]
+#[allow(clippy::print_stderr, clippy::print_stdout)]
 async fn main() -> io::Result<()> {
-    print_debugging_state();
+    log::print_state();
+    let mut instant = now();
 
     let args = syntax::command::Arguments::default().parse();
     let address = args.make_address();
+    instant = tlog!(&instant, "Parsed CLI arguments");
 
-    #[allow(clippy::print_stderr)]
     panic::set_hook(Box::new(|info| {
         let payload = info
             .payload_as_str()
@@ -33,17 +35,22 @@ async fn main() -> io::Result<()> {
             eprintln!("\n  Stack trace:\n{trace:#?}");
         }
     }));
+    instant = tlog!(&instant, "Set up panic hook");
 
     let graph = Graph::load();
+    instant = tlog!(&instant, "Loaded graph");
+
     let router = en::router::new(&graph);
+    tlog!(&instant, "Initialized router");
 
     let listener =
         tokio::net::TcpListener::bind(&address).await.map_err(|e| {
-            log!("Failed to create listener at {address}: {e:#?}");
+            log!(ERROR, "Failed to create listener at {address}: {e:#?}");
             e
         })?;
+    tlog!(&instant, "Initialized listener");
 
-    log!(
+    println!(
         "Listening on {}",
         listener
             .local_addr()
@@ -52,23 +59,9 @@ async fn main() -> io::Result<()> {
     );
 
     axum::serve(listener, router).await.map_err(|e| {
-        log!("Failed to serve application: {e:#?}");
+        log!(ERROR, "Failed to serve application: {e:#?}");
         io::Error::other(e)
     })?;
 
     Ok(())
 }
-
-fn print_debugging_state() {
-    let level: u8 = std::env::var("DEBUG")
-        .unwrap_or("0".to_string())
-        .trim()
-        .parse()
-        .unwrap_or(0);
-
-    let filter = std::env::var("DEBUG_FILTER").unwrap_or_default();
-
-    if level > 0 || !filter.is_empty() {
-        log!("DEBUG = {level}, DEBUG_FILTER = {filter:?}");
-    }
-}

src/router/handlers/fixed.rs

@@ -13,6 +13,7 @@ use crate::{
 /// Will panic if file read fails.
 #[expect(clippy::unused_async)]
 pub async fn file(file_path: &str, content_type: &str) -> Response<Body> {
+    let instant = now();
     let content = match std::fs::read(file_path) {
         Ok(s) => s,
         Err(e) => {
@@ -27,9 +28,16 @@ pub async fn file(file_path: &str, content_type: &str) -> Response<Body> {
     if let Ok(header_value) = HeaderValue::from_str(content_type) {
         response.headers_mut().append(header, header_value);
     } else {
-        log!("Failed to create content type header value from {content_type}");
+        log!(
+            WARN,
+            "Failed to create content type header value from {content_type}"
+        );
     }
 
+    tlog!(
+        &instant,
+        "Assembled response for {content_type} {file_path}"
+    );
     response
 }
 

src/router/handlers/graph.rs

@@ -1,9 +1,10 @@
 use axum::response::IntoResponse as _;
 use axum::{body::Body, extract::Path, http::Response, response::Redirect};
 
-use crate::{graph::Graph, router::handlers, graph::Node};
+use crate::{prelude::*, graph::Graph, router::handlers, graph::Node};
 
 pub async fn node(Path(id): Path<String>) -> Response<Body> {
+    let instant = now();
     let graph = Graph::load();
     let result = graph.find_node(&id);
     let found = result.node.is_some();
@@ -28,6 +29,7 @@ pub async fn node(Path(id): Path<String>) -> Response<Body> {
     context.insert("node", &node);
     context.insert("incoming", &graph.incoming.get(&id));
 
+    tlog!(&instant, "Assembled response for node {}", node.id);
     handlers::template::by_filename(
         "node.html",
         &context,

src/router/handlers/navigation.rs

@@ -6,21 +6,25 @@ use axum::{
 };
 
 use crate::{
+    prelude::*,
     graph::{Graph, Node},
     router::handlers,
 };
 
 #[expect(clippy::unused_async)]
 pub async fn page(template: &str) -> Response<Body> {
+    let instant = now();
     let mut context = tera::Context::default();
     let graph = Graph::load();
 
     context.insert("graph", &graph);
 
+    tlog!(&instant, "Assembled response for template {template}");
     handlers::template::by_filename(template, &context, 500, None, false)
 }
 
 pub async fn tree() -> Response<Body> {
+    let instant = now();
     let mut context = tera::Context::default();
     let mut graph = Graph::load();
 
@@ -39,10 +43,12 @@ pub async fn tree() -> Response<Body> {
         );
     }
 
+    tlog!(&instant, "Assembled response for tree endpoint");
     handlers::template::by_filename("tree.html", &context, 500, None, false)
 }
 
 pub async fn data() -> Response<Body> {
+    let instant = now();
     let mut context = tera::Context::default();
     let graph = Graph::load();
 
@@ -54,6 +60,7 @@ pub async fn data() -> Response<Body> {
     context.insert("detached_count", &graph.stats.detached.len());
     context.insert("detached_pairs", &detached_pairs);
 
+    tlog!(&instant, "Assembled response for data endpoint");
     handlers::template::by_filename("data.html", &context, 500, None, false)
 }
 

src/router/handlers/raw.rs

@@ -21,13 +21,14 @@ pub(in crate::router::handlers) fn make_response(
                 response.headers_mut().insert(header.0.clone(), wrapped)
             {
                 log!(
+                    WARN,
                     "Overwrote header {overwritten:?} \
                         because another for key {} already existed",
                     header.0
                 );
             }
         } else {
-            log!("Failed to create header value from {}", header.1);
+            log!(ERROR, "Failed to create header value from {}", header.1);
         }
     }
 

src/router/handlers/template.rs

@@ -26,6 +26,7 @@ pub(in crate::router::handlers) fn render(
     context: &tera::Context,
     error_message: Option<String>,
 ) -> (String, u16) {
+    let instant = now();
     // TODO just return an Option/String> here
     let tera = match tera::Tera::new("./templates/**/*") {
         Ok(t) => t,
@@ -35,7 +36,10 @@ pub(in crate::router::handlers) fn render(
     };
 
     match tera.render(name, context) {
-        Ok(t) => (t, 200),
+        Ok(t) => {
+            tlog!(&instant, "Rendered template {name}");
+            (t, 200)
+        },
         Err(e) => {
             let mut error_context = tera::Context::default();
 
@@ -69,7 +73,7 @@ pub(in crate::router::handlers) fn render(
 }
 
 fn emergency_wrap(error: &tera::Error) -> String {
-    log!("{error:#?}");
+    log!(ERROR, "{error:#?}");
     format!(
         r#"<!DOCTYPE html>
         <html>

src/syntax/command.rs

@@ -1,7 +1,12 @@
-use std::path::PathBuf;
+use std::{
+    path::PathBuf,
+    sync::atomic::{AtomicBool, Ordering},
+};
 
 use crate::prelude::*;
 
+static FIRST_PARSE: AtomicBool = AtomicBool::new(true);
+
 #[derive(Clone, Debug, PartialEq)]
 pub struct Arguments {
     pub hostname: String,
@@ -51,7 +56,10 @@ fn parse(defaults: &Arguments, args: &[String]) -> Arguments {
             } else if argument.eq("-g") || argument.eq("--graph") {
                 out_args.graph_path = PathBuf::from(parameter);
             } else {
-                log!("Dropped unrecognized argument {argument}");
+                if FIRST_PARSE.load(Ordering::SeqCst) {
+                    log!(WARN, "Dropped unrecognized argument {argument}");
+                    FIRST_PARSE.store(false, Ordering::SeqCst);
+                }
             }
         } else {
             panic!("Argument {arg:?} has no corresponding value")

src/syntax/content/parser.rs

@@ -21,13 +21,17 @@ const LEXMAP: LexMap = &[
 ];
 
 fn lex(text: &str, map: LexMap, graph: &Graph, blocking: bool) -> TokenOutput {
+    let mut instant = now();
     let mut tokens: Vec<Token> = Vec::default();
     let mut state = State::default();
 
     let segments = segment::segment(text);
+    let segments_count = segments.len();
+    instant = tlog!(&instant, "Segmented {segments_count} segments");
     let lexemes = Lexeme::collect(&segments);
+    instant = tlog!(&instant, "{segments_count} segments: Collected lexemes");
 
-    log!("Segments: {segments:?}");
+    log!(VERBOSE, "Segments: {segments:?}");
 
     let mut iterator = lexemes.iter().peekable();
     while let Some(lexeme) = iterator.next() {
@@ -67,14 +71,17 @@ fn lex(text: &str, map: LexMap, graph: &Graph, blocking: bool) -> TokenOutput {
         for (probe, lex) in map {
             if probe(lexeme) {
                 let token = lex(lexeme);
-                log!("Lexmap lexed {lexeme} into {token}");
+                log!(VERBOSE, "Lexmap lexed {lexeme} into {token}");
                 tokens.push(token);
                 break;
             }
         }
     }
+    instant = tlog!(&instant, "{segments_count} segments: Parsed");
 
     context::close(&state, &mut tokens);
+    tlog!(&instant, "{segments_count} segments: Closed");
+
     TokenOutput {
         tokens,
         format_tokens: state.format_tokens,
@@ -107,7 +114,7 @@ pub fn format(input: &str, graph: &Graph) -> (String, Vec<Token>) {
 pub fn flatten(input: &str, graph: &Graph) -> String {
     let tokens = lex(input, LEXMAP, graph, true).tokens;
     let flat = tokens.iter().map(Token::flatten).collect::<String>();
-    log!("Flattened {tokens:?} to {flat}");
+    log!(VERBOSE, "Flattened {tokens:?} to {flat}");
     flat
 }
 

src/syntax/content/parser/context/anchor.rs

@@ -17,7 +17,7 @@ pub fn parse(
     tokens: &mut Vec<Token>,
     graph: &Graph,
 ) -> bool {
-    log!("Solving: {}", state.clone().buffers.anchor);
+    log!(VERBOSE, "Solving: {}", state.clone().buffers.anchor);
     let buffer = &mut state.buffers.anchor;
     let candidate = &mut buffer.candidate;
 
@@ -25,16 +25,18 @@ pub fn parse(
     // would already have set its text to the word before the first pipe
     if candidate.text().is_empty() {
         log!(
+            VERBOSE,
             "Seeking end of text at {:#?} -> {:#?}",
             lexeme.text(),
             lexeme.next()
         );
         if lexeme.next() == "|" {
-            log!("End: Next lexeme is a pipe");
+            log!(VERBOSE, "End: Next lexeme is a pipe");
             buffer.text.push_str(&lexeme.text());
             candidate.set_text(&buffer.text.clone());
         } else {
             log!(
+                VERBOSE,
                 "Pushing non-terminal {:#?} into buffer {:#?}",
                 lexeme.text(),
                 buffer.text
@@ -46,6 +48,7 @@ pub fn parse(
 
     if candidate.destination().is_none() {
         log!(
+            VERBOSE,
             "Seeking end of destination at {:#?} -> {:#?}",
             lexeme.text(),
             lexeme.next()
@@ -57,7 +60,7 @@ pub fn parse(
             && lexeme.is_next_boundary()
             && !lexeme.match_next_char('|')
         {
-            log!("End: Plural anchor");
+            log!(VERBOSE, "End: Plural anchor");
             candidate.set_destination(Some(&candidate.text().clone()));
             candidate.text_push("s");
             if lexeme.last() {
@@ -65,7 +68,7 @@ pub fn parse(
             }
             return true;
         } else if lexeme.match_char('|') && lexeme.is_next_delimiter() {
-            log!("End: Pipe followed by delimiter");
+            log!(VERBOSE, "End: Pipe followed by delimiter");
             if buffer.destination.is_empty() {
                 if candidate.text().contains(':') {
                     candidate.set_external(true);
@@ -76,29 +79,32 @@ pub fn parse(
             }
             return true;
         } else if lexeme.match_char('|') && !candidate.balanced() {
-            log!("State: Found a pipe, but no boundary: destination follows");
+            log!(
+                VERBOSE,
+                "State: Found a pipe, but no boundary: destination follows"
+            );
             candidate.set_balanced(true);
             return true;
         } else if lexeme.match_char(':') {
-            log!("State: Found a colon, marking anchor as external");
+            log!(VERBOSE, "State: Found a colon, marking anchor as external");
             candidate.set_external(true);
             buffer.destination.push_str(&lexeme.text());
             return true;
         } else if lexeme.match_char('|') {
-            log!("End: Explicit end-of-destination pipe");
+            log!(VERBOSE, "End: Explicit end-of-destination pipe");
             candidate.set_destination(Some(&buffer.destination.clone()));
             return true;
         } else if !candidate.external() && lexeme.is_delimiter() {
-            log!("End: Internal anchor trailed by delimiter");
+            log!(VERBOSE, "End: Internal anchor trailed by delimiter");
             push(Some(&buffer.destination.clone()), tokens, state, graph);
             return false;
         } else if lexeme.is_next_whitespace() {
-            log!("End: next is whitespace");
+            log!(VERBOSE, "End: next is whitespace");
             buffer.destination.push_str(&lexeme.text());
             push(Some(&buffer.destination.clone()), tokens, state, graph);
             return true;
         } else if lexeme.last() {
-            log!("End: end of input");
+            log!(VERBOSE, "End: end of input");
             buffer.destination.push_str(&lexeme.text());
             push(Some(&buffer.destination.clone()), tokens, state, graph);
             return true;
@@ -107,6 +113,7 @@ pub fn parse(
         // pushing lexemes into the buffer until an end is found above
         } else {
             log!(
+                VERBOSE,
                 "Pushing non-terminal {:#?} into buffer {:#?}",
                 lexeme.text(),
                 buffer.destination,

src/syntax/content/parser/context/block.rs

@@ -22,7 +22,7 @@ pub fn parse(
     match state.context.block {
         Block::None => {
             if PreFormat::probe(lexeme) {
-                log!("Block Context: None -> PreFormat on {lexeme}");
+                log!(VERBOSE, "Block Context: None -> PreFormat on {lexeme}");
                 state.context.block = Block::PreFormat;
                 tokens.push(Token::PreFormat(PreFormat::new(true)));
                 return true;
@@ -33,19 +33,19 @@ pub fn parse(
                     iterator.peek().map_or(&Lexeme::default(), |l| l),
                     &mut state.dom_ids,
                 ));
-                log!("Block Context: None -> Header on {lexeme}");
+                log!(VERBOSE, "Block Context: None -> Header on {lexeme}");
                 state.context.block = Block::Header(header.level());
                 tokens.push(Token::Header(header));
                 return true;
             } else if List::probe(lexeme) {
-                log!("Block Context: None -> List on {lexeme}");
+                log!(VERBOSE, "Block Context: None -> List on {lexeme}");
                 state.context.block = Block::List;
                 state.buffers.list.candidate.ordered = lexeme.match_char('+');
                 return super::list::parse(
                     lexeme, state, tokens, iterator, graph,
                 );
             } else if Paragraph::probe(lexeme) {
-                log!("Block Context: None -> Paragraph on {lexeme}");
+                log!(VERBOSE, "Block Context: None -> Paragraph on {lexeme}");
                 state.context.block = Block::Paragraph;
                 tokens.push(Token::Paragraph(Paragraph::new(true)));
             }
@@ -53,7 +53,7 @@ pub fn parse(
         Block::PreFormat => {
             if PreFormat::probe(lexeme) {
                 tokens.push(Token::PreFormat(PreFormat::new(false)));
-                log!("Block Context: PreFormat -> None on {lexeme}");
+                log!(VERBOSE, "Block Context: PreFormat -> None on {lexeme}");
                 state.context.block = Block::None;
             } else {
                 tokens.push(Token::Literal(Literal::lex(lexeme)));
@@ -63,14 +63,14 @@ pub fn parse(
         Block::Paragraph => {
             if Paragraph::probe_end(lexeme) {
                 tokens.push(Token::Paragraph(Paragraph::new(false)));
-                log!("Block Context: Paragraph -> None on {lexeme}");
+                log!(VERBOSE, "Block Context: Paragraph -> None on {lexeme}");
                 state.context.block = Block::None;
             }
         },
         Block::Header(n) => {
             if lexeme.text() == "\n" {
                 tokens.push(Token::Header(Header::from_u8(n, false, None)));
-                log!("Block Context: Header -> None on {lexeme}");
+                log!(VERBOSE, "Block Context: Header -> None on {lexeme}");
                 state.context.block = Block::None;
             }
         },

src/syntax/content/parser/context/inline.rs

@@ -24,12 +24,12 @@ pub fn parse(
     match state.context.inline {
         Inline::None => {
             if Code::probe(lexeme) {
-                log!("Inline Context: None -> Code on {lexeme}");
+                log!(VERBOSE, "Inline Context: None -> Code on {lexeme}");
                 state.context.inline = Inline::Code;
                 tokens.push(Token::Code(Code::new(true)));
                 return true;
             } else if Anchor::probe(lexeme) {
-                log!("Inline Context: None -> Anchor on {lexeme}");
+                log!(VERBOSE, "Inline Context: None -> Anchor on {lexeme}");
                 state.context.inline = Inline::Anchor;
                 state.buffers.anchor = AnchorBuffer::default();
 
@@ -46,7 +46,7 @@ pub fn parse(
         },
         Inline::Code => {
             if Code::probe(lexeme) {
-                log!("Inline Context: Code -> None on {lexeme}");
+                log!(VERBOSE, "Inline Context: Code -> None on {lexeme}");
                 state.context.inline = Inline::None;
                 tokens.push(Token::Code(Code::new(false)));
                 return true;

src/syntax/content/parser/context/list.rs

@@ -55,14 +55,14 @@ pub fn parse(
                     candidate.items.push(item_candidate.clone());
                 }
                 // push list candidate, reset state and exit context
-                log!("Accepting list candidate {candidate}");
+                log!(VERBOSE, "Accepting list candidate {candidate}");
                 tokens.push(Token::List(candidate.clone()));
                 state.context.block = Block::None;
                 iterator.next();
                 *buffer = state::ListBuffer::default();
             } else if lexeme.match_char('\n') {
                 // found end of item, push it and reset state
-                log!("Accepting item candidate {item_candidate}");
+                log!(VERBOSE, "Accepting item candidate {item_candidate}");
                 let (text, format_tokens) = format(&item_candidate.text, graph);
                 item_candidate.text = text;
                 state.format_tokens.extend_from_slice(&format_tokens);

src/syntax/content/parser/lexeme.rs

@@ -1,6 +1,6 @@
 use std::fmt;
 
-use crate::{prelude::*, syntax::content::parser::segment::delimiter::Delimiters};
+use crate::{syntax::content::parser::segment::delimiter::Delimiters};
 
 #[derive(Clone, Debug, Default)]
 pub struct Lexeme {
@@ -27,9 +27,6 @@ impl Lexeme {
     }
 
     pub fn next(&self) -> String {
-        if self.next.is_empty() && !self.last {
-            log!("Returning an empty string for next of non-last {self:?}");
-        }
         self.next.clone()
     }
 
@@ -239,7 +236,7 @@ impl Lexeme {
 
 impl fmt::Display for Lexeme {
     fn fmt(&self, f: &mut fmt::Formatter) -> fmt::Result {
-        use crate::dev::wrap;
+        use crate::log::wrap;
 
         let properties = if self.last && self.first {
             "[S] "

src/syntax/content/parser/point.rs

@@ -24,30 +24,30 @@ pub fn parse(
     }
 
     if Underline::probe(lexeme) {
-        log!("Underline probed: {lexeme}");
+        log!(VERBOSE, "Underline probed: {lexeme}");
         tokens
             .push(Token::Underline(Underline::new(!state.switches.underline)));
         state.switches.underline = !state.switches.underline;
         iterator.next();
         return true;
     } else if Oblique::probe(lexeme) {
-        log!("Oblique probed: {lexeme}");
+        log!(VERBOSE, "Oblique probed: {lexeme}");
         tokens.push(Token::Oblique(Oblique::new(!state.switches.oblique)));
         state.switches.oblique = !state.switches.oblique;
         return true;
     } else if Strike::probe(lexeme) {
-        log!("Strike probed: {lexeme}");
+        log!(VERBOSE, "Strike probed: {lexeme}");
         tokens.push(Token::Strike(Strike::new(!state.switches.crossout)));
         state.switches.crossout = !state.switches.crossout;
         iterator.next();
         return true;
     } else if Bold::probe(lexeme) {
-        log!("Bold probed: {lexeme}");
+        log!(VERBOSE, "Bold probed: {lexeme}");
         tokens.push(Token::Bold(Bold::new(!state.switches.bold)));
         state.switches.bold = !state.switches.bold;
         return true;
     } else if CheckBox::probe(lexeme) {
-        log!("CheckBox probed: {lexeme}");
+        log!(VERBOSE, "CheckBox probed: {lexeme}");
         tokens.push(Token::CheckBox(CheckBox::lex(lexeme)));
         iterator.next();
         iterator.next();

src/syntax/content/parser/segment.rs

@@ -105,6 +105,7 @@ pub mod delimiter {
                 atomized.push(c.to_string());
             }
         }
+
         atomized
     }
 

src/syntax/content/parser/token/anchor.rs

@@ -161,7 +161,7 @@ impl Parseable for Anchor {
 
 impl std::fmt::Display for Anchor {
     fn fmt(&self, f: &mut std::fmt::Formatter) -> std::fmt::Result {
-        use crate::dev::wrap;
+        use crate::log::wrap;
 
         let wrapped_text = wrap(&self.text);
         let display_text = if wrapped_text.is_empty() {

src/syntax/content/parser/token/checkbox.rs

@@ -21,7 +21,7 @@ impl Parseable for CheckBox {
 
     fn lex(lexeme: &Lexeme) -> CheckBox {
         use crate::prelude::*;
-        log!("Lexing: {lexeme}");
+        log!(VERBOSE, "Lexing: {lexeme}");
         if lexeme.match_next_char('x') {
             CheckBox::new(true)
         } else {

src/syntax/content/parser/token/header.rs

@@ -172,7 +172,7 @@ impl From<usize> for Level {
         let u8 = match u8::try_from(z) {
             Ok(u) => u,
             Err(e) => {
-                log!("Truncating header level {z} to 6: {e:?}");
+                log!(INFO, "Truncating header level {z} to 6: {e:?}");
                 6
             },
         };

src/syntax/content/parser/token/literal.rs

@@ -27,7 +27,7 @@ impl Parseable for Literal {
 
 impl std::fmt::Display for Literal {
     fn fmt(&self, f: &mut std::fmt::Formatter) -> std::fmt::Result {
-        write!(f, "Literal {}", crate::dev::wrap(&self.text))
+        write!(f, "Literal {}", crate::log::wrap(&self.text))
     }
 }