feat(logging): add extended log filtering

Cargo.toml

@@ -298,14 +298,15 @@ document-features = { version = "0.2", optional = true }
 embedded-io = { version = "0.7", features = ["alloc"] }
 endian-num = { version = "0.2", optional = true, features = ["linux-types"] }
 enum_dispatch = "0.3"
+env_filter = { version = "1.0.0", default-features = false }
 fdt = { version = "0.1", features = ["pretty-printing"] }
 free-list = "0.3"
 fuse-abi = { version = "0.2", optional = true, features = ["linux"] }
 hashbrown = { version = "0.16", default-features = false }
 heapless = "0.9"
 hermit-entry = { version = "0.10.9", features = ["kernel"] }
 hermit-sync = "0.1"
-log = { version = "0.4", default-features = false }
+log = { version = "0.4", default-features = false, features = ["kv"] }
 mem-barrier = { version = "0.1.0", optional = true, features = ["nightly"] }
 num_enum = { version = "0.7", default-features = false }
 pci-ids = { version = "0.2", optional = true }
@@ -413,6 +414,7 @@ unreadable_literal = "warn"
 
 [patch.crates-io]
 safe-mmio = { git = "https://github.com/hermit-os/safe-mmio", branch = "be" }
+env_filter = { git = "https://github.com/cagatay-y/env_logger", branch = "feature/filter-no_std" }
 
 [profile.profiling]
 inherits = "release"

README.md

@@ -37,13 +37,25 @@ If you want to build the kernel for riscv64, please use `riscv64`.
 
 ### Control the kernel messages verbosity
 
-This kernel uses the lightweight logging crate [log](https://github.com/rust-lang/log) to print kernel messages.
-The environment variable `HERMIT_LOG_LEVEL_FILTER` controls the verbosity. 
-You can change it by setting it at compile time to a string matching the name of a [LevelFilter](https://docs.rs/log/0.4.8/log/enum.LevelFilter.html).
-If the variable is not set, or the name doesn't match, then `LevelFilter::Info` is used by default.
+This kernel uses the lightweight logging crate [log](https://github.com/rust-lang/log) to print kernel messages. The
+compile time environment variable `HERMIT_LOG_DEFAULT` and the runtime environment variable `HERMIT_LOG` control the
+verbosity and follow [the env_logger format](https://docs.rs/env_logger/latest/env_logger/) but without the regex
+support.
+
+The logging level can be changed per module by setting it to a string in the format `[target][=level][,...]`, where the
+level is a string matching the name of a [LevelFilter](https://docs.rs/log/0.4.8/log/enum.LevelFilter.html). If the
+target is omitted, the level is set as the global level. If the level is omitted, logs of all levels are printed for the
+target. A simple search pattern that will filter all modules can be provided after the target-level pairs with 
+`/<pattern>`.
+
+> [!NOTE]
+> For the modules that are part of the kernel, the `hermit::` prefix needs to be provided before the module name.
+
+If the variables are not set, or they do not provide a global level, then `LevelFilter::Info` is used as the global level
+by default.
 
 ```sh
-$ HERMIT_LOG_LEVEL_FILTER=Debug cargo xtask build --arch x86_64
+HERMIT_LOG_LEVEL_FILTER='hermit::virtio=debug/queue' cargo xtask build --arch x86_64
 ```
 
 ## Credits

src/arch/aarch64/kernel/mod.rs

@@ -90,7 +90,6 @@ pub fn boot_processor_init() {
 	crate::mm::init();
 	crate::mm::print_information();
 	CoreLocal::get().add_irq_counter();
-	env::init();
 	interrupts::init();
 	processor::detect_frequency();
 	crate::logging::KERNEL_LOGGER.set_time(true);

src/arch/riscv64/kernel/mod.rs

@@ -108,7 +108,6 @@ pub fn boot_processor_init() {
 	devicetree::init();
 	crate::mm::init();
 	crate::mm::print_information();
-	env::init();
 	interrupts::install();
 
 	finish_processor_init();

src/arch/x86_64/kernel/mod.rs

@@ -104,7 +104,6 @@ pub fn boot_processor_init() {
 	crate::mm::init();
 	crate::mm::print_information();
 	CoreLocal::get().add_irq_counter();
-	env::init();
 	gdt::add_current_core();
 	interrupts::load_idt();
 	pic::init();

src/logging.rs

@@ -1,20 +1,31 @@
 use core::fmt;
 use core::sync::atomic::{AtomicBool, Ordering};
+use core::time::Duration;
 
 use anstyle::AnsiColor;
+use hermit_sync::OnceCell;
 use log::{Level, LevelFilter, Metadata, Record};
 
+use crate::env;
+
 pub static KERNEL_LOGGER: KernelLogger = KernelLogger::new();
+const ARENA_SIZE: usize = 4096;
+static mut ARENA: [u8; ARENA_SIZE] = [0; _];
+
+const TIME_SEC_WIDTH: usize = 5;
+const TIME_SUBSEC_WIDTH: usize = 6;
 
 /// Data structure to filter kernel messages
 pub struct KernelLogger {
 	time: AtomicBool,
+	filter: OnceCell<env_filter::Filter>,
 }
 
 impl KernelLogger {
 	pub const fn new() -> Self {
 		Self {
 			time: AtomicBool::new(false),
+			filter: OnceCell::new(),
 		}
 	}
 
@@ -41,13 +52,21 @@ impl log::Log for KernelLogger {
 			return;
 		}
 
-		// FIXME: Use `super let` once stable
-		let time;
+		if let Some(filter) = self.filter.get()
+			&& !filter.matches(record)
+		{
+			return;
+		}
+
 		let format_time = if self.time() {
-			time = Microseconds(crate::processor::get_timer_ticks());
-			format_args!("[{time}]")
+			let time = Duration::from_micros(crate::processor::get_timer_ticks());
+			format_args!(
+				"{:TIME_SEC_WIDTH$}.{:0TIME_SUBSEC_WIDTH$}",
+				time.as_secs(),
+				time.subsec_micros()
+			)
 		} else {
-			format_args!("[            ]")
+			format_args!("{:1$}", "", TIME_SEC_WIDTH + 1 + TIME_SUBSEC_WIDTH)
 		};
 		let core_id = crate::arch::core_local::core_id();
 		let level = ColorLevel(record.level());
@@ -63,17 +82,7 @@ impl log::Log for KernelLogger {
 		let format_target = format_args!(" {target:<10}");
 
 		let args = record.args();
-		println!("{format_time}[{core_id}][{level}{format_target}] {args}");
-	}
-}
-
-struct Microseconds(u64);
-
-impl fmt::Display for Microseconds {
-	fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
-		let seconds = self.0 / 1_000_000;
-		let microseconds = self.0 % 1_000_000;
-		write!(f, "{seconds:5}.{microseconds:06}")
+		println!("[{format_time}][{core_id}][{level}{format_target}] {args}");
 	}
 }
 
@@ -106,30 +115,37 @@ fn no_color() -> bool {
 
 pub unsafe fn init() {
 	log::set_logger(&KERNEL_LOGGER).expect("Can't initialize logger");
-	// Determines LevelFilter at compile time
-	let log_level: Option<&'static str> = option_env!("HERMIT_LOG_LEVEL_FILTER");
-	let mut max_level = LevelFilter::Info;
-
-	if let Some(log_level) = log_level {
-		max_level = if log_level.eq_ignore_ascii_case("off") {
-			LevelFilter::Off
-		} else if log_level.eq_ignore_ascii_case("error") {
-			LevelFilter::Error
-		} else if log_level.eq_ignore_ascii_case("warn") {
-			LevelFilter::Warn
-		} else if log_level.eq_ignore_ascii_case("info") {
-			LevelFilter::Info
-		} else if log_level.eq_ignore_ascii_case("debug") {
-			LevelFilter::Debug
-		} else if log_level.eq_ignore_ascii_case("trace") {
-			LevelFilter::Trace
-		} else {
-			error!("Could not parse HERMIT_LOG_LEVEL_FILTER, falling back to `info`.");
-			LevelFilter::Info
-		};
+	// To get logs until we determine the actual log level
+	log::set_max_level(LevelFilter::Info);
+
+	#[cfg(target_os = "none")]
+	unsafe {
+		crate::mm::ALLOCATOR
+			.lock()
+			.claim((&raw mut ARENA).cast(), ARENA_SIZE)
+			.unwrap()
+	};
+	env::init();
+
+	let mut filter_builder = env_filter::Builder::new();
+	// The default. It may get overwritten by the parsed filter if it has a global level.
+	filter_builder.filter_level(LevelFilter::Info);
+
+	if let Some(compile_time_filter) = option_env!("HERMIT_LOG_DEFAULT").or_else(|| {
+		option_env!("HERMIT_LOG_LEVEL_FILTER").inspect(|_| {
+			warn!("HERMIT_LOG_LEVEL_FILTER is deprecated in favor of HERMIT_LOG_DEFAULT");
+		})
+	}) {
+		filter_builder.parse(compile_time_filter);
+	}
+
+	if let Some(runtime_filter) = env::var("HERMIT_LOG") {
+		filter_builder.parse(runtime_filter);
 	}
 
-	log::set_max_level(max_level);
+	let filter = filter_builder.build();
+	log::set_max_level(filter.filter());
+	KERNEL_LOGGER.filter.set(filter).unwrap();
 }
 
 #[cfg_attr(target_arch = "riscv64", allow(unused))]