log fixes (#3240)

* Disregard env setting when level is set manually

* Sort filter rules

* Changelog

* Remove no-longer-true doc line

* Fex typo

Author: bugadani

esp-println/CHANGELOG.md

@@ -15,6 +15,9 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0
 
 ### Fixed
 
+- Manually setting a log level now correctly ignores `ESP_LOG`. (#3240)
+- Fixed logging rules being order-dependent. (#3240)
+
 ### Removed
 
 ## [0.13.1] - 2025-02-24

esp-println/build.rs

@@ -81,6 +81,7 @@ fn generate_filter_snippet() {
             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 {
                     log::LevelFilter::Off => "Off",
@@ -92,18 +93,25 @@ fn generate_filter_snippet() {
                 };
 
                 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(\"{}\") && level <= log::LevelFilter::{} {{ return true; }}",
-                &name, level
-            ));
-                } else {
-                    snippet.push_str(&format!(
-                        "if level <= log::LevelFilter::{} {{ return true; }}",
-                        level
+                        "if _target.starts_with(\"{}\") {{ return level <= log::LevelFilter::{}; }}",
+                        &name, level
                     ));
+                } else {
+                    if global_level.is_some() {
+                        panic!("Multiple global log levels specified in `ESP_LOG`");
+                    }
+                    global_level = Some(level);
                 }
             }
-            snippet.push_str(" false");
+
+            // 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
         }
@@ -183,5 +191,13 @@ fn parse_spec(spec: &str) -> ParseResult {
         }
     }
 
+    // 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
 }

esp-println/src/logger.rs

@@ -7,8 +7,6 @@ include!(concat!(env!("OUT_DIR"), "/log_filter.rs"));
 include!(concat!(env!("OUT_DIR"), "\\log_filter.rs"));
 
 /// Initialize the logger with the given maximum log level.
-///
-/// `ESP_LOG` environment variable will still be honored if set.
 pub fn init_logger(level: log::LevelFilter) {
     unsafe {
         log::set_logger_racy(&EspLogger).unwrap();
@@ -19,14 +17,31 @@ pub fn init_logger(level: log::LevelFilter) {
 /// Initialize the logger from the `ESP_LOG` environment variable.
 pub fn init_logger_from_env() {
     unsafe {
-        log::set_logger_racy(&EspLogger).unwrap();
+        log::set_logger_racy(&EspEnvLogger).unwrap();
         log::set_max_level_racy(FILTER_MAX);
     }
 }
 
 struct EspLogger;
 
 impl log::Log for EspLogger {
+    #[allow(unused)]
+    fn enabled(&self, _: &log::Metadata) -> bool {
+        // Filtered by `log` already
+        true
+    }
+
+    #[allow(unused)]
+    fn log(&self, record: &log::Record) {
+        print_log_record(record);
+    }
+
+    fn flush(&self) {}
+}
+
+struct EspEnvLogger;
+
+impl log::Log for EspEnvLogger {
     fn enabled(&self, metadata: &log::Metadata) -> bool {
         let level = metadata.level();
         let target = metadata.target();
@@ -35,49 +50,51 @@ impl log::Log for EspLogger {
 
     #[allow(unused)]
     fn log(&self, record: &log::Record) {
-        if !self.enabled(&record.metadata()) {
-            return;
+        if self.enabled(&record.metadata()) {
+            print_log_record(record);
         }
-
-        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";
-
-        #[cfg(feature = "colors")]
-        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,
-        };
-        #[cfg(feature = "colors")]
-        let reset = RESET;
-
-        #[cfg(not(feature = "colors"))]
-        let color = "";
-        #[cfg(not(feature = "colors"))]
-        let reset = "";
-
-        #[cfg(feature = "timestamp")]
-        println!(
-            "{}{} ({}) - {}{}",
-            color,
-            record.level(),
-            unsafe { _esp_println_timestamp() },
-            record.args(),
-            reset
-        );
-        #[cfg(not(feature = "timestamp"))]
-        println!("{}{} - {}{}", color, record.level(), record.args(), reset);
     }
 
     fn flush(&self) {}
 }
 
+fn print_log_record(record: &log::Record) {
+    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";
+
+    #[cfg(feature = "colors")]
+    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,
+    };
+    #[cfg(feature = "colors")]
+    let reset = RESET;
+
+    #[cfg(not(feature = "colors"))]
+    let color = "";
+    #[cfg(not(feature = "colors"))]
+    let reset = "";
+
+    #[cfg(feature = "timestamp")]
+    println!(
+        "{}{} ({}) - {}{}",
+        color,
+        record.level(),
+        unsafe { _esp_println_timestamp() },
+        record.args(),
+        reset
+    );
+    #[cfg(not(feature = "timestamp"))]
+    println!("{}{} - {}{}", color, record.level(), record.args(), reset);
+}
+
 /// A user-provided hook to supply a timestamp in milliseconds for logging.
 ///
 /// When enabled via the `"timestamp"` feature, this function should be