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..bcb8eb0831 100644 --- a/README.md +++ b/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 +`/`. + +> [!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 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 b67a3b3e18..f64a01f44d 100644 --- a/src/logging.rs +++ b/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, } 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))]