diff --git a/.justfile b/.justfile index 6519990..cd3f175 100644 --- a/.justfile +++ b/.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 diff --git a/src/dev.rs b/src/dev.rs deleted file mode 100644 index ffdf2ac..0000000 --- a/src/dev.rs +++ /dev/null @@ -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("e(&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(); - } -} diff --git a/src/graph.rs b/src/graph.rs index 0b11fef..7c539a4 100644 --- a/src/graph.rs +++ b/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 } } diff --git a/src/lib.rs b/src/lib.rs index b5d5f34..2a71d03 100644 --- a/src/lib.rs +++ b/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 = sync::LazyLock::new(time::Instant::now); diff --git a/src/log.rs b/src/log.rs new file mode 100644 index 0000000..7bd8ff3 --- /dev/null +++ b/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, + 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("e(&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(); + } +} diff --git a/src/log/level.rs b/src/log/level.rs new file mode 100644 index 0000000..c5054c1 --- /dev/null +++ b/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 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 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}") + } +} diff --git a/src/main.rs b/src/main.rs index 08a096e..5b037b3 100644 --- a/src/main.rs +++ b/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:?}"); - } -} diff --git a/src/router/handlers/fixed.rs b/src/router/handlers/fixed.rs index 4f242ac..6fcc911 100644 --- a/src/router/handlers/fixed.rs +++ b/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 { + 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 { 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 } diff --git a/src/router/handlers/graph.rs b/src/router/handlers/graph.rs index 3a4a563..581b002 100644 --- a/src/router/handlers/graph.rs +++ b/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) -> Response { + 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) -> Response { 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, diff --git a/src/router/handlers/navigation.rs b/src/router/handlers/navigation.rs index 795c29a..fa9503a 100644 --- a/src/router/handlers/navigation.rs +++ b/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 { + 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 { + let instant = now(); let mut context = tera::Context::default(); let mut graph = Graph::load(); @@ -39,10 +43,12 @@ pub async fn tree() -> Response { ); } + tlog!(&instant, "Assembled response for tree endpoint"); handlers::template::by_filename("tree.html", &context, 500, None, false) } pub async fn data() -> Response { + let instant = now(); let mut context = tera::Context::default(); let graph = Graph::load(); @@ -54,6 +60,7 @@ pub async fn data() -> Response { 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) } diff --git a/src/router/handlers/raw.rs b/src/router/handlers/raw.rs index 9ba49ad..789e4c2 100644 --- a/src/router/handlers/raw.rs +++ b/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); } } diff --git a/src/router/handlers/template.rs b/src/router/handlers/template.rs index 323f6fe..199fbca 100644 --- a/src/router/handlers/template.rs +++ b/src/router/handlers/template.rs @@ -26,6 +26,7 @@ pub(in crate::router::handlers) fn render( context: &tera::Context, error_message: Option, ) -> (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#" diff --git a/src/syntax/command.rs b/src/syntax/command.rs index ef1539d..948866f 100644 --- a/src/syntax/command.rs +++ b/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") diff --git a/src/syntax/content/parser.rs b/src/syntax/content/parser.rs index 353c2f7..fa2318f 100644 --- a/src/syntax/content/parser.rs +++ b/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 = 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) { pub fn flatten(input: &str, graph: &Graph) -> String { let tokens = lex(input, LEXMAP, graph, true).tokens; let flat = tokens.iter().map(Token::flatten).collect::(); - log!("Flattened {tokens:?} to {flat}"); + log!(VERBOSE, "Flattened {tokens:?} to {flat}"); flat } diff --git a/src/syntax/content/parser/context/anchor.rs b/src/syntax/content/parser/context/anchor.rs index c8c9cef..d9a861a 100644 --- a/src/syntax/content/parser/context/anchor.rs +++ b/src/syntax/content/parser/context/anchor.rs @@ -17,7 +17,7 @@ pub fn parse( tokens: &mut Vec, 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, diff --git a/src/syntax/content/parser/context/block.rs b/src/syntax/content/parser/context/block.rs index d6eb9e8..cbf51b2 100644 --- a/src/syntax/content/parser/context/block.rs +++ b/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; } }, diff --git a/src/syntax/content/parser/context/inline.rs b/src/syntax/content/parser/context/inline.rs index e98e9e2..27c4675 100644 --- a/src/syntax/content/parser/context/inline.rs +++ b/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; diff --git a/src/syntax/content/parser/context/list.rs b/src/syntax/content/parser/context/list.rs index 37fe6ac..415c0ea 100644 --- a/src/syntax/content/parser/context/list.rs +++ b/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); diff --git a/src/syntax/content/parser/lexeme.rs b/src/syntax/content/parser/lexeme.rs index 9f6267a..acaf378 100644 --- a/src/syntax/content/parser/lexeme.rs +++ b/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] " diff --git a/src/syntax/content/parser/point.rs b/src/syntax/content/parser/point.rs index 2895e47..38aaec0 100644 --- a/src/syntax/content/parser/point.rs +++ b/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(); diff --git a/src/syntax/content/parser/segment.rs b/src/syntax/content/parser/segment.rs index 28cfdb1..f8ee4b9 100644 --- a/src/syntax/content/parser/segment.rs +++ b/src/syntax/content/parser/segment.rs @@ -105,6 +105,7 @@ pub mod delimiter { atomized.push(c.to_string()); } } + atomized } diff --git a/src/syntax/content/parser/token/anchor.rs b/src/syntax/content/parser/token/anchor.rs index 6d9397e..94aac28 100644 --- a/src/syntax/content/parser/token/anchor.rs +++ b/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() { diff --git a/src/syntax/content/parser/token/checkbox.rs b/src/syntax/content/parser/token/checkbox.rs index a8f410d..656f419 100644 --- a/src/syntax/content/parser/token/checkbox.rs +++ b/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 { diff --git a/src/syntax/content/parser/token/header.rs b/src/syntax/content/parser/token/header.rs index c9c7661..f238f73 100644 --- a/src/syntax/content/parser/token/header.rs +++ b/src/syntax/content/parser/token/header.rs @@ -172,7 +172,7 @@ impl From 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 }, }; diff --git a/src/syntax/content/parser/token/literal.rs b/src/syntax/content/parser/token/literal.rs index b6af9d8..ca521ae 100644 --- a/src/syntax/content/parser/token/literal.rs +++ b/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)) } }