feat(logging): add extented log filtering

The new environment variable `HERMIT_LOG_EXTENDED_FILTER` allows log
filters of different levels to be applied on a per module basis. It also
allows filtering by regex.

Author: cagatay-y

Cargo.lock

@@ -332,7 +332,7 @@ heapless = "0.9"
 hermit-entry = { version = "0.10.9", features = ["kernel"] }
 hermit-sync = "0.1"
 lock_api = "0.4"
-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 }
@@ -391,6 +391,11 @@ trapframe = "0.10"
 memory_addresses = { version = "0.3", default-features = false, features = [
 	"riscv64",
 ] }
+env_filter = { version = "1.0.0", default-features = false }
+
+# regex breaks linking for riscv64 on debug builds
+[target.'cfg(not(target_arch = "riscv64"))'.dependencies]
+env_filter = { version = "1.0.0", default-features = false, features = ["regex"] }
 
 [dev-dependencies]
 float-cmp = "0.10"
@@ -412,6 +417,7 @@ exclude = [
 
 [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 = "feat-no_std-alloc" }
 
 [profile.profiling]
 inherits = "release"

Cargo.toml

@@ -46,6 +46,20 @@ If the variable is not set, or the name doesn't match, then `LevelFilter::Info`
 $ HERMIT_LOG_LEVEL_FILTER=Debug cargo xtask build --arch x86_64
 ```
 
+Additionally, logging level can be adjusted by module and regex using the `HERMIT_LOG_EXTENDED_FILTER` environment
+variable. The format is `[target][=level][,...]`. 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 regular expression that will in be effect for all
+modules can be provided at the end after a `/`. If a new global level is not provided, `HERMIT_LOG_LEVEL_FILTER` (or its
+default) will be the global level.
+
+```sh
+HERMIT_LOG_LEVEL_FILTER=warn HERMIT_LOG_EXTENDED_FILTER='smoltcp,virtio=info/feature|send' cargo xtask build --arch x86_64
+```
+
+Note that `HERMIT_LOG_EXTENDED_FILTER` is activated relatively late in the boot process due to its dynamic allocation
+requirement. Early boot logging can only be influenced with `HERMIT_LOG_LEVEL_FILTER`.
+
+
 ## Credits
 
 This kernel is derived from following tutorials and software distributions:

README.md

@@ -273,6 +273,9 @@ fn boot_processor_main() -> ! {
 	info!("tls_info = {:#x?}", env::boot_info().load_info.tls_info);
 	arch::boot_processor_init();
 
+	// We can't initialize the module filter during logger initialization as the allocations fail at that point.
+	logging::init_module_filter();
+
 	#[cfg(not(target_arch = "riscv64"))]
 	scheduler::add_current_core();
 	interrupts::enable();

src/lib.rs

@@ -3,6 +3,7 @@ use core::sync::atomic::{AtomicBool, Ordering};
 use core::time::Duration;
 
 use anstyle::AnsiColor;
+use hermit_sync::OnceCell;
 use log::{Level, LevelFilter, Metadata, Record};
 
 pub static KERNEL_LOGGER: KernelLogger = KernelLogger::new();
@@ -13,12 +14,14 @@ 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(),
 		}
 	}
 
@@ -45,6 +48,23 @@ impl log::Log for KernelLogger {
 			return;
 		}
 
+		let target = record.target();
+		let (crate_, modules) = target.split_once("::").unwrap_or((target, ""));
+		let (_modules, module) = modules.rsplit_once("::").unwrap_or(("", modules));
+		let target = if !module.is_empty() && crate_ == "hermit" {
+			module
+		} else {
+			crate_
+		};
+
+		if self.filter.get().is_some_and(|filter| {
+			// We want the target that we match against to match the target we display.
+			let record = record.to_builder().target(target).build();
+			!filter.matches(&record)
+		}) {
+			return;
+		}
+
 		let format_time = if self.time() {
 			let time = Duration::from_micros(crate::processor::get_timer_ticks());
 			format_args!(
@@ -58,14 +78,6 @@ impl log::Log for KernelLogger {
 		let core_id = crate::arch::core_local::core_id();
 		let level = ColorLevel(record.level());
 
-		let target = record.target();
-		let (crate_, modules) = target.split_once("::").unwrap_or((target, ""));
-		let (_modules, module) = modules.rsplit_once("::").unwrap_or(("", modules));
-		let target = if !module.is_empty() && crate_ == "hermit" {
-			module
-		} else {
-			crate_
-		};
 		let format_target = format_args!(" {target:<10}");
 
 		let args = record.args();
@@ -118,6 +130,20 @@ pub unsafe fn init() {
 	log::set_max_level(max_level);
 }
 
+pub(crate) fn init_module_filter() {
+	// We use a separate environment variable in order to avoid unnecessary cost when the basic filter is sufficient.
+	let Some(log_level) = option_env!("HERMIT_LOG_EXTENDED_FILTER") else {
+		return;
+	};
+	let filter = env_filter::Builder::new()
+		// What was set via `HERMIT_LOG_LEVEL_FILTER` or the default. It may get overwritten by the parsed filter if it has a global level.
+		.filter_level(log::max_level())
+		.parse(log_level)
+		.build();
+	log::set_max_level(filter.filter());
+	KERNEL_LOGGER.filter.set(filter).unwrap();
+}
+
 #[cfg_attr(target_arch = "riscv64", allow(unused))]
 macro_rules! infoheader {
 	// This should work on paper, but it's currently not supported :(