From 00c75212fe1ab87f5122808efcfb72afae6591da Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?=C3=87a=C4=9Fatay=20Yi=C4=9Fit=20=C5=9Eahin?= Date: Wed, 18 Mar 2026 10:28:49 +0100 Subject: [PATCH 1/4] refactor(logging): avoid magic numbers --- src/logging.rs | 10 ++++++++-- 1 file changed, 8 insertions(+), 2 deletions(-) diff --git a/src/logging.rs b/src/logging.rs index b67a3b3e18..9ef35bf552 100644 --- a/src/logging.rs +++ b/src/logging.rs @@ -6,6 +6,9 @@ use log::{Level, LevelFilter, Metadata, Record}; pub static KERNEL_LOGGER: KernelLogger = KernelLogger::new(); +const TIME_SEC_WIDTH: usize = 5; +const TIME_SUBSEC_WIDTH: usize = 6; + /// Data structure to filter kernel messages pub struct KernelLogger { time: AtomicBool, @@ -47,7 +50,7 @@ impl log::Log for KernelLogger { time = Microseconds(crate::processor::get_timer_ticks()); format_args!("[{time}]") } 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()); @@ -73,7 +76,10 @@ 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}") + write!( + f, + "{seconds:TIME_SEC_WIDTH$}.{microseconds:0TIME_SUBSEC_WIDTH$}" + ) } } From a365aba438a7bf2537b13523e062ac0d30e394e5 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?=C3=87a=C4=9Fatay=20Yi=C4=9Fit=20=C5=9Eahin?= Date: Wed, 18 Mar 2026 10:48:00 +0100 Subject: [PATCH 2/4] refactor(logging): use stdlib Duration to represent time It is not possible to use a Display implementation as both the trait Display and the type Duration are foreign. --- src/logging.rs | 28 +++++++++------------------- 1 file changed, 9 insertions(+), 19 deletions(-) diff --git a/src/logging.rs b/src/logging.rs index 9ef35bf552..abedcf78bb 100644 --- a/src/logging.rs +++ b/src/logging.rs @@ -1,5 +1,6 @@ use core::fmt; use core::sync::atomic::{AtomicBool, Ordering}; +use core::time::Duration; use anstyle::AnsiColor; use log::{Level, LevelFilter, Metadata, Record}; @@ -44,13 +45,15 @@ impl log::Log for KernelLogger { return; } - // FIXME: Use `super let` once stable - let time; 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!("[{:1$}]", "", TIME_SEC_WIDTH + 1 + TIME_SUBSEC_WIDTH) + format_args!("{:1$}", "", TIME_SEC_WIDTH + 1 + TIME_SUBSEC_WIDTH) }; let core_id = crate::arch::core_local::core_id(); let level = ColorLevel(record.level()); @@ -66,20 +69,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:TIME_SEC_WIDTH$}.{microseconds:0TIME_SUBSEC_WIDTH$}" - ) + println!("[{format_time}][{core_id}][{level}{format_target}] {args}"); } } From 6b3ed5bab0400c8a01af14a799d99ee4fd4f094f Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?=C3=87a=C4=9Fatay=20Yi=C4=9Fit=20=C5=9Eahin?= Date: Wed, 8 Apr 2026 15:45:54 +0200 Subject: [PATCH 3/4] feat(logging): add extended log filtering Allows log filters of different levels to be applied on a per module basis. --- Cargo.lock | 9 +++++++++ Cargo.toml | 4 +++- README.md | 19 ++++++++++++++----- src/logging.rs | 51 ++++++++++++++++++++++++++++++-------------------- 4 files changed, 57 insertions(+), 26 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index 63b2c18fec..b09370a166 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -570,6 +570,14 @@ dependencies = [ "syn", ] +[[package]] +name = "env_filter" +version = "1.0.1" +source = "git+https://github.com/cagatay-y/env_logger?branch=feature%2Ffilter-no_std#364726a16347dfdff2ce11e6faab11e5fa2bd8d2" +dependencies = [ + "log", +] + [[package]] name = "errno" version = "0.3.14" @@ -835,6 +843,7 @@ dependencies = [ "embedded-io", "endian-num", "enum_dispatch", + "env_filter", "fdt", "float-cmp", "free-list", diff --git a/Cargo.toml b/Cargo.toml index 75adae9fa6..7d8ddad0c8 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -298,6 +298,7 @@ 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"] } @@ -305,7 +306,7 @@ 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" diff --git a/README.md b/README.md index b522db547b..a77806b457 100644 --- a/README.md +++ b/README.md @@ -37,13 +37,22 @@ 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 +environment variable `HERMIT_LOG_LEVEL_FILTER` controls the verbosity and follows [the env_logger +format](https://docs.rs/env_logger/latest/env_logger/) but without the regex support. You can change it per module by +setting it at compile time 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 `/`. + +> [!NOTE] +> For the modules that are part of the kernel, the `hermit::` prefix needs to be provided before the module name. + +If the variable is not set, or it does 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 diff --git a/src/logging.rs b/src/logging.rs index abedcf78bb..ab7004334e 100644 --- a/src/logging.rs +++ b/src/logging.rs @@ -3,9 +3,12 @@ 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(); +const ARENA_SIZE: usize = 4096; +static mut ARENA: [u8; ARENA_SIZE] = [0; _]; const TIME_SEC_WIDTH: usize = 5; const TIME_SUBSEC_WIDTH: usize = 6; @@ -13,12 +16,14 @@ const TIME_SUBSEC_WIDTH: usize = 6; /// Data structure to filter kernel messages pub struct KernelLogger { time: AtomicBool, + filter: OnceCell, } impl KernelLogger { pub const fn new() -> Self { Self { time: AtomicBool::new(false), + filter: OnceCell::new(), } } @@ -45,6 +50,12 @@ impl log::Log for KernelLogger { return; } + if let Some(filter) = self.filter.get() + && !filter.matches(record) + { + return; + } + let format_time = if self.time() { let time = Duration::from_micros(crate::processor::get_timer_ticks()); format_args!( @@ -101,29 +112,29 @@ fn no_color() -> bool { } pub unsafe fn init() { + #[cfg(target_os = "none")] + unsafe { + crate::mm::ALLOCATOR + .lock() + .claim((&raw mut ARENA).cast(), ARENA_SIZE) + .unwrap() + }; + 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 - }; - } + let max_level = if let Some(log_level) = log_level { + let filter = env_filter::Builder::new() + // The default. It may get overwritten by the parsed filter if it has a global level. + .filter_level(LevelFilter::Info) + .parse(log_level) + .build(); + let max_level = filter.filter(); + KERNEL_LOGGER.filter.set(filter).unwrap(); + max_level + } else { + LevelFilter::Info + }; log::set_max_level(max_level); } From d490b01846f2390f525be193d3610afa43060f54 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?=C3=87a=C4=9Fatay=20Yi=C4=9Fit=20=C5=9Eahin?= Date: Tue, 7 Apr 2026 16:33:30 +0200 Subject: [PATCH 4/4] feat(logging): align log envvars with the log crate --- README.md | 17 ++++++++------ src/arch/aarch64/kernel/mod.rs | 1 - src/arch/riscv64/kernel/mod.rs | 1 - src/arch/x86_64/kernel/mod.rs | 1 - src/logging.rs | 41 +++++++++++++++++++++------------- 5 files changed, 35 insertions(+), 26 deletions(-) diff --git a/README.md b/README.md index a77806b457..bcb8eb0831 100644 --- a/README.md +++ b/README.md @@ -38,17 +38,20 @@ 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 and follows [the env_logger -format](https://docs.rs/env_logger/latest/env_logger/) but without the regex support. You can change it per module by -setting it at compile time 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 `/`. +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 +`/`. > [!NOTE] > For the modules that are part of the kernel, the `hermit::` prefix needs to be provided before the module name. -If the variable is not set, or it does not provide a global level, then `LevelFilter::Info` is used as the global level +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 diff --git a/src/arch/aarch64/kernel/mod.rs b/src/arch/aarch64/kernel/mod.rs index 3305a13b23..c54741084b 100644 --- a/src/arch/aarch64/kernel/mod.rs +++ b/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); diff --git a/src/arch/riscv64/kernel/mod.rs b/src/arch/riscv64/kernel/mod.rs index 44c66100a7..7b53dd8574 100644 --- a/src/arch/riscv64/kernel/mod.rs +++ b/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(); diff --git a/src/arch/x86_64/kernel/mod.rs b/src/arch/x86_64/kernel/mod.rs index 3c74007148..71b9a961f0 100644 --- a/src/arch/x86_64/kernel/mod.rs +++ b/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(); diff --git a/src/logging.rs b/src/logging.rs index ab7004334e..f64a01f44d 100644 --- a/src/logging.rs +++ b/src/logging.rs @@ -6,6 +6,8 @@ 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; _]; @@ -112,6 +114,10 @@ fn no_color() -> bool { } pub unsafe fn init() { + log::set_logger(&KERNEL_LOGGER).expect("Can't initialize logger"); + // To get logs until we determine the actual log level + log::set_max_level(LevelFilter::Info); + #[cfg(target_os = "none")] unsafe { crate::mm::ALLOCATOR @@ -119,24 +125,27 @@ pub unsafe fn init() { .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); + } - 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 max_level = if let Some(log_level) = log_level { - let filter = env_filter::Builder::new() - // The default. It may get overwritten by the parsed filter if it has a global level. - .filter_level(LevelFilter::Info) - .parse(log_level) - .build(); - let max_level = filter.filter(); - KERNEL_LOGGER.filter.set(filter).unwrap(); - max_level - } else { - LevelFilter::Info - }; + 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))]