From fb77f9facbe16cbc57d8ff779877a5bba6a17e0c Mon Sep 17 00:00:00 2001 From: ede1998 Date: Thu, 27 Aug 2026 23:48:33 +0200 Subject: [PATCH] improve logging --- Cargo.toml | 28 +++++---- build.rs | 163 ++++++++++++++++++++++++++++++++++++++++++++++++ src/bin/main.rs | 6 +- src/lib.rs | 1 + src/logging.rs | 83 ++++++++++++++++++++++++ 5 files changed, 268 insertions(+), 13 deletions(-) create mode 100644 src/logging.rs diff --git a/Cargo.toml b/Cargo.toml index 82d1bfc..e0485db 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -1,15 +1,19 @@ [package] -edition = "2024" -name = "creaturedex" +edition = "2024" +name = "creaturedex" rust-version = "1.88" -version = "0.1.0" +version = "0.1.0" [[bin]] name = "creaturedex" path = "./src/bin/main.rs" [dependencies] -esp-hal = { version = "~1.1.0", features = ["esp32s3", "log-04", "unstable"] } #, "embassy", "embassy-time-timg0", "embassy-executor-thread"] } +esp-hal = { version = "~1.1.0", features = [ + "esp32s3", + "log-04", + "unstable", +] } #, "embassy", "embassy-time-timg0", "embassy-executor-thread"] } esp-rtos = { version = "0.3.0", features = [ "embassy", @@ -20,12 +24,11 @@ esp-rtos = { version = "0.3.0", features = [ ] } esp-bootloader-esp-idf = { version = "0.5.0", features = ["esp32s3", "log-04"] } -log = "0.4.27" +log = "0.4.27" critical-section = "1.2.0" embedded-io = "0.7.1" -embassy-executor = { version = "0.10.0", features = [ -] } +embassy-executor = { version = "0.10.0", features = [] } embassy-time = { version = "0.5.1", default-features = false } embassy-futures = "0.1.2" esp-alloc = "0.10.0" @@ -48,6 +51,9 @@ embedded-hal-async = "1.0.0" i2c-character-display = "0.5.1" ch1115 = { version = "0.1.2", features = ["graphics"] } +[build-dependencies] +log = "0.4.27" + [patch.crates-io] ch1115 = { git = "https://github.com/ede1998/ch1115.git", rev = "2d3a3ba38050efe012e6a210afe3e125ec280c37" } @@ -64,10 +70,10 @@ opt-level = 3 debug = 0 [profile.release] -codegen-units = 1 # LLVM can perform better optimizations using a single thread -debug = 2 # prefer slower builds but better debugging experience -lto = 'fat' -opt-level = 's' +codegen-units = 1 # LLVM can perform better optimizations using a single thread +debug = 2 # prefer slower builds but better debugging experience +lto = 'fat' +opt-level = 's' [features] default = [] diff --git a/build.rs b/build.rs index 2b6a670..926a012 100644 --- a/build.rs +++ b/build.rs @@ -1,4 +1,5 @@ fn main() { + generate_filter_snippet(); linker_be_nice(); // make sure linkall.x is the last linker script (otherwise might cause problems with flip-link) println!("cargo:rustc-link-arg=-Tlinkall.x"); @@ -68,3 +69,165 @@ fn linker_be_nice() { std::env::current_exe().unwrap().display() ); } + +// Taken over from esp_println because impossible to just extend their existing env logger. +// https://github.com/esp-rs/esp-hal/blob/8fa6d7e985e724d6ad998e34307429b0920da370/esp-println/build.rs +fn generate_filter_snippet() { + use log::LevelFilter; + use std::{env, path::Path}; + + let out_dir = env::var_os("OUT_DIR").unwrap(); + let dest_path = Path::new(&out_dir).join("log_filter.rs"); + + let filter = env::var("ESP_LOG"); + let snippet = if let Ok(filter) = filter { + let res = parse_spec(&filter); + + if !res.errors.is_empty() { + panic!("Error parsing `ESP_LOG`: {:?}", res.errors); + } else { + let max = res + .directives + .iter() + .map(|v| v.level) + .max() + .unwrap_or(LevelFilter::Off); + let max = match max { + LevelFilter::Off => "Off", + LevelFilter::Error => "Error", + LevelFilter::Warn => "Warn", + LevelFilter::Info => "Info", + LevelFilter::Debug => "Debug", + LevelFilter::Trace => "Trace", + }; + + let mut snippet = String::new(); + + snippet.push_str(&format!( + "pub(crate) const FILTER_MAX: log::LevelFilter = log::LevelFilter::{max};" + )); + + snippet + .push_str("pub(crate) fn is_enabled(level: log::Level, _target: &str) -> bool {"); + + let mut global_level = None; + for directive in res.directives { + let level = match directive.level { + LevelFilter::Off => "Off", + LevelFilter::Error => "Error", + LevelFilter::Warn => "Warn", + LevelFilter::Info => "Info", + LevelFilter::Debug => "Debug", + LevelFilter::Trace => "Trace", + }; + + if let Some(name) = directive.name { + // If a prefix matches, don't continue to the next directive + snippet.push_str(&format!( + "if _target.starts_with(\"{name}\") {{ return level <= log::LevelFilter::{level}; }}" + )); + } else { + if global_level.is_some() { + panic!("Multiple global log levels specified in `ESP_LOG`"); + } + global_level = Some(level); + } + } + + // Place the fallback rule at the end + if let Some(level) = global_level { + snippet.push_str(&format!("level <= log::LevelFilter::{level}")); + } else { + snippet.push_str(" false"); + } + snippet.push('}'); + snippet + } + } else { + "pub(crate) const FILTER_MAX: log::LevelFilter = log::LevelFilter::Off; pub(crate) fn is_enabled(_level: log::Level, _target: &str) -> bool { true }".to_string() + }; + + std::fs::write(&dest_path, &snippet).unwrap(); +} + +#[derive(Default, Debug)] +struct ParseResult { + pub(crate) directives: Vec, + pub(crate) errors: Vec, +} + +impl ParseResult { + fn add_directive(&mut self, directive: Directive) { + self.directives.push(directive); + } + + fn add_error(&mut self, message: String) { + self.errors.push(message); + } +} + +#[derive(Debug)] +struct Directive { + pub(crate) name: Option, + pub(crate) level: log::LevelFilter, +} + +/// Parse a logging specification string (e.g: +/// `crate1,crate2::mod3,crate3::x=error/foo`) and return a vector with log +/// directives. +fn parse_spec(spec: &str) -> ParseResult { + use log::LevelFilter; + + let mut result = ParseResult::default(); + + let mut parts = spec.split('/'); + let mods = parts.next(); + + if let Some(m) = mods { + for s in m.split(',').map(|ss| ss.trim()) { + if s.is_empty() { + continue; + } + let mut parts = s.split('='); + let (log_level, name) = + match (parts.next(), parts.next().map(|s| s.trim()), parts.next()) { + (Some(part0), None, None) => { + // if the single argument is a log-level string or number, + // treat that as a global fallback + match part0.parse() { + Ok(num) => (num, None), + Err(_) => (LevelFilter::max(), Some(part0)), + } + } + (Some(part0), Some(""), None) => (LevelFilter::max(), Some(part0)), + (Some(part0), Some(part1), None) => { + if let Ok(num) = part1.parse() { + (num, Some(part0)) + } else { + result.add_error(format!("invalid logging spec '{part1}'")); + continue; + } + } + _ => { + result.add_error(format!("invalid logging spec '{s}'")); + continue; + } + }; + + result.add_directive(Directive { + name: name.map(|s| s.to_owned()), + level: log_level, + }); + } + } + + // Sort by length so that the most specific prefixes come first + result + .directives + .sort_by(|a, b| match (a.name.as_ref(), b.name.as_ref()) { + (Some(a), Some(b)) => b.len().cmp(&a.len()), + _ => std::cmp::Ordering::Equal, + }); + + result +} diff --git a/src/bin/main.rs b/src/bin/main.rs index bd1ca91..a1a26b8 100644 --- a/src/bin/main.rs +++ b/src/bin/main.rs @@ -52,7 +52,7 @@ esp_bootloader_esp_idf::esp_app_desc!(); )] #[esp_rtos::main] async fn main(spawner: Spawner) { - esp_println::logger::init_logger_from_env(); + creaturedex::logging::init(); let config = esp_hal::Config::default().with_cpu_clock(CpuClock::max()); let peripherals = esp_hal::init(config); @@ -94,7 +94,9 @@ async fn main(spawner: Spawner) { let h = EXAMPLE[HEART]; let e = EXAMPLE[EMPTY]; let b = EXAMPLE[BOX]; - if let Err(e) = lcd.write(&alloc::format!("Custom symbols: {h}{e}{b} And more stuff to wrap and cut off please.")) { + if let Err(e) = lcd.write(&alloc::format!( + "Custom symbols: {h}{e}{b} And more stuff to wrap and cut off please." + )) { log::error!( "Tertiary LCD startup text write failed over shared I2C bus; check the shared bus, wiring, and device responses: {e}" ); diff --git a/src/lib.rs b/src/lib.rs index 857c224..7d65b1d 100644 --- a/src/lib.rs +++ b/src/lib.rs @@ -6,6 +6,7 @@ pub mod background_tasks; pub mod card; pub mod display; pub mod drivers; +pub mod logging; pub mod navigation; pub mod network; pub mod storage; diff --git a/src/logging.rs b/src/logging.rs new file mode 100644 index 0000000..3cdc280 --- /dev/null +++ b/src/logging.rs @@ -0,0 +1,83 @@ +mod logging_config { + include!(concat!(env!("OUT_DIR"), "/log_filter.rs")); +} + +struct EnvLogger; + +impl log::Log for EnvLogger { + fn enabled(&self, metadata: &log::Metadata) -> bool { + let level = metadata.level(); + let target = metadata.target(); + logging_config::is_enabled(level, target) + } + + fn log(&self, record: &log::Record) { + if !self.enabled(record.metadata()) { + return; + } + + // print with color? default to true if env var unset or set but empty. + let with_color = 1 + == option_env!("ESP_LOG_COLOR") + .unwrap_or("1") + .parse() + .unwrap_or(1); + let (color, reset) = if with_color { + const RESET: &str = "\u{001B}[0m"; + const RED: &str = "\u{001B}[31m"; + const GREEN: &str = "\u{001B}[32m"; + const YELLOW: &str = "\u{001B}[33m"; + const BLUE: &str = "\u{001B}[34m"; + const CYAN: &str = "\u{001B}[35m"; + + let color = match record.level() { + log::Level::Error => RED, + log::Level::Warn => YELLOW, + log::Level::Info => GREEN, + log::Level::Debug => BLUE, + log::Level::Trace => CYAN, + }; + let reset = RESET; + (color, reset) + } else { + ("", "") + }; + + let [now_s, now_ms] = { + let now = esp_hal::time::Instant::now() + .duration_since_epoch() + .as_millis(); + + [now / 1000, now % 1000] + }; + + let level = match record.level() { + log::Level::Error => "E", + log::Level::Warn => "W", + log::Level::Info => "I", + log::Level::Debug => "D", + log::Level::Trace => "T", + }; + let args = record.args(); + let line = record.line().unwrap_or(0); + let target = record.target(); + let module = record.module_path().unwrap_or("???"); + + let (module, divider) = if module == target { + ("", "") + } else { + (module, " ") + }; + + esp_println::println!( + "{color}{now_s:>4}.{now_ms:03}s {level} {target}{divider}{module}:{line} - {args}{reset}" + ); + } + + fn flush(&self) {} +} + +pub fn init() { + log::set_logger(&EnvLogger).expect("Failed to init logger."); + log::set_max_level(logging_config::FILTER_MAX); +}