From 974679985e2077200f8f7b504d727c00a5b2e319 Mon Sep 17 00:00:00 2001 From: "Panagiotis \"Ivory\" Vasilopoulos" Date: Sat, 11 Oct 2025 12:34:17 +0200 Subject: [PATCH 1/2] style: improve user-facing kernel messages - Move subjects to beginning of each message - Unify certain messages across architecture-specific implementations - State the component/task at the beginning of most messages (before verbs) to make log scrolling and pinpointing failures easier - Grammar-related improvements - Increase consistency of used wording - In some cases, display relevant variables - Replace debug! with error! before errors are returned. - Replace some debug! instances with trace! - Decrease the length of some sentences - Make messages of standard actions (e.g. driver init) consistent (mostly.) - Correct mentions of RTL8139 in the driver's messages - Add more variables inside of placeholders This change is not intended to be perfect and does not improve ALL messages, with many changes being highly subjective. It has a primary focus on debugging information and drivers. The primary motivation for this change is mostly the high amount of time spent trying to understand sequences of actions (and e.g. where specifically the booting of a kernel may break), while also assisting those that do not have a full picture of the kernel's source code. Some messages were not modified to include the name of the component, as it may be self-evident depending on the context and the debugging activity (see: src/drivers/gem.rs) and increase the mental noise, rather than decrease it. --- src/arch/aarch64/kernel/interrupts.rs | 25 +++---- src/arch/aarch64/kernel/mmio.rs | 20 +++--- src/arch/aarch64/kernel/mod.rs | 12 ++-- src/arch/aarch64/kernel/pci.rs | 25 ++++--- src/arch/aarch64/kernel/processor.rs | 3 +- src/arch/aarch64/kernel/scheduler.rs | 8 +-- src/arch/aarch64/kernel/systemtime.rs | 4 +- src/arch/riscv64/kernel/devicetree.rs | 55 +++++++-------- src/arch/riscv64/kernel/interrupts.rs | 2 +- src/arch/riscv64/kernel/mod.rs | 22 +++--- src/arch/riscv64/kernel/processor.rs | 2 +- src/arch/riscv64/kernel/scheduler.rs | 12 ++-- src/arch/x86_64/kernel/acpi.rs | 13 ++-- src/arch/x86_64/kernel/apic.rs | 46 ++++++------- src/arch/x86_64/kernel/pci.rs | 6 +- src/arch/x86_64/kernel/scheduler.rs | 10 +-- src/drivers/console/pci.rs | 8 +-- src/drivers/fs/virtio_fs.rs | 8 +-- src/drivers/fs/virtio_pci.rs | 8 +-- src/drivers/net/gem.rs | 16 ++--- src/drivers/net/rtl8139.rs | 23 +++---- src/drivers/net/virtio/mmio.rs | 4 +- src/drivers/net/virtio/mod.rs | 39 ++++++----- src/drivers/net/virtio/pci.rs | 12 ++-- src/drivers/pci.rs | 2 +- src/drivers/virtio/mod.rs | 10 +-- src/drivers/virtio/transport/mmio.rs | 22 +++--- src/drivers/virtio/transport/pci.rs | 60 ++++++++-------- src/drivers/virtio/virtqueue/packed.rs | 7 +- src/drivers/virtio/virtqueue/split.rs | 2 +- src/drivers/vsock/mod.rs | 17 +++-- src/drivers/vsock/pci.rs | 8 +-- src/executor/network.rs | 2 +- src/executor/vsock.rs | 2 +- src/fs/fuse.rs | 94 ++++++++++---------------- src/fs/uhyve.rs | 4 +- src/mm/mod.rs | 5 +- src/scheduler/mod.rs | 25 ++++--- src/scheduler/task.rs | 10 +-- src/syscalls/mman.rs | 8 +-- src/syscalls/mod.rs | 18 ++--- src/syscalls/tasks.rs | 10 +-- src/syscalls/timer.rs | 18 ++--- 43 files changed, 337 insertions(+), 370 deletions(-) diff --git a/src/arch/aarch64/kernel/interrupts.rs b/src/arch/aarch64/kernel/interrupts.rs index 7aa8702502..ae51186bac 100644 --- a/src/arch/aarch64/kernel/interrupts.rs +++ b/src/arch/aarch64/kernel/interrupts.rs @@ -260,7 +260,7 @@ pub(crate) extern "C" fn do_error(_state: &State) -> ! { } pub fn wakeup_core(core_id: CoreId) { - debug!("Wakeup core {core_id}"); + debug!("CPU {core_id}: Waking up core..."); let reschedid = IntId::sgi(SGI_RESCHED.into()); GicV3::send_sgi( @@ -276,8 +276,7 @@ pub fn wakeup_core(core_id: CoreId) { } pub(crate) fn init() { - info!("Initialize generic interrupt controller"); - + info!("GIC: Initializing..."); let fdt = env::fdt().unwrap(); let intc_node = fdt.find_node("/intc").unwrap(); @@ -307,15 +306,13 @@ pub(crate) fn init() { panic!("{compatible} isn't supported") }; - info!("Found GIC Distributor interface at {gicd_start:p} (size {gicd_size:#X})"); - info!( - "Found generic interrupt controller redistributor at {gicr_start:p} (size {gicr_size:#X})" - ); + info!("GIC Distributor: Found interface at {gicd_start:p} (size {gicd_size:#X})"); + info!("GIC Redistributor: Found interface at {gicr_start:p} (size {gicr_size:#X})"); let layout = PageLayout::from_size_align(gicd_size.try_into().unwrap(), 0x10000).unwrap(); let page_range = KERNEL_FREE_LIST.lock().allocate(layout).unwrap(); let gicd_address = VirtAddr::from(page_range.start()); - debug!("Mapping GIC Distributor interface to virtual address {gicd_address:p}"); + debug!("GIC: Mapping distributor interface to virtual address {gicd_address:p}"); let mut flags = PageTableEntryFlags::empty(); flags.device().writable().execute_disable(); @@ -329,7 +326,7 @@ pub(crate) fn init() { let layout = PageLayout::from_size_align(gicr_size.try_into().unwrap(), 0x10000).unwrap(); let page_range = KERNEL_FREE_LIST.lock().allocate(layout).unwrap(); let gicr_address = VirtAddr::from(page_range.start()); - debug!("Mapping generic interrupt controller to virtual address {gicr_address:p}"); + debug!("GIC: Mapping controller to virtual address {gicr_address:p}"); paging::map::( gicr_address, gicr_start, @@ -378,7 +375,7 @@ pub(crate) fn init() { } else if irqtype == 0 { IntId::spi(irq) } else { - panic!("Invalid interrupt type"); + panic!("Invalid interrupt type {irqtype}!"); }; gic.set_interrupt_priority(timer_irqid, Some(cpu_id), 0x00); if (irqflags & 0xf) == 4 || (irqflags & 0xf) == 8 { @@ -416,7 +413,7 @@ pub(crate) fn init() { } else if irqtype == 0 { IntId::spi(irq) } else { - panic!("Invalid interrupt type"); + panic!("Invalid interrupt type {irqtype}!"); }; gic.set_interrupt_priority(uart_irqid, Some(cpu_id), 0x00); if (irqflags & 0xf) == 4 || (irqflags & 0xf) == 8 { @@ -442,7 +439,7 @@ pub fn init_cpu() { let cpu_id: usize = core_id().try_into().unwrap(); if let Some(ref mut gic) = *GIC.lock() { - debug!("Mark cpu {cpu_id} as awake"); + debug!("CPU {cpu_id}: Marking as awake"); gic.setup(cpu_id); GicV3::set_priority_mask(0xff); @@ -469,7 +466,7 @@ pub fn init_cpu() { } else if irqtype == 0 { IntId::spi(irq) } else { - panic!("Invalid interrupt type"); + panic!("Invalid interrupt type {irqtype}!"); }; gic.set_interrupt_priority(timer_irqid, Some(cpu_id), 0x00); if (irqflags & 0xf) == 4 || (irqflags & 0xf) == 8 { @@ -493,7 +490,7 @@ static IRQ_NAMES: InterruptTicketMutex> = #[allow(dead_code)] pub(crate) fn add_irq_name(irq_number: u8, name: &'static str) { - debug!("Register name \"{name}\" for interrupt {irq_number}"); + debug!("Assigning register name \"{name}\" for interrupt {irq_number}"); IRQ_NAMES.lock().insert(SPI_START + irq_number, name); } diff --git a/src/arch/aarch64/kernel/mmio.rs b/src/arch/aarch64/kernel/mmio.rs index c50041bf33..96a63a421a 100644 --- a/src/arch/aarch64/kernel/mmio.rs +++ b/src/arch/aarch64/kernel/mmio.rs @@ -66,7 +66,7 @@ pub fn init_drivers() { if i == "virtio,mmio" { let virtio_region = node .reg() - .expect("reg property for virtio mmio not found in FDT") + .expect("DT: reg property for virtio-mmio not found in FDT") .next() .unwrap(); let mut irq = 0; @@ -104,15 +104,17 @@ pub fn init_drivers() { const MMIO_MAGIC_VALUE: u32 = 0x7472_6976; if magic != MMIO_MAGIC_VALUE { - error!("It's not a MMIO-device at {mmio:p}"); + error!("virtio-mmio: No MMIO device present at {mmio:p}"); } if version != 2 { - warn!("Found a legacy device, which isn't supported"); + warn!( + "virtio-mmio: Found an unsupported legacy device (version: {version})" + ); } // We found a MMIO-device (whose 512-bit address in this structure). - trace!("Found a MMIO-device at {mmio:p}"); + trace!("virtio-mmio: Device found at {mmio:p}"); // Verify the device-ID to find the network card let id = mmio.as_ptr().device_id().read(); @@ -122,7 +124,7 @@ pub fn init_drivers() { #[cfg(feature = "virtio-net")] virtio::Id::Net => { debug!( - "Found network card at {mmio:p}, irq: {irq}, type: {irqtype}, flags: {irqflags}" + "virtio-net: Network card found at {mmio:p} (irq: {irq}, type: {irqtype}, flags: {irqflags})" ); if let Ok(VirtioDriver::Network(drv)) = mmio_virtio::init_device(mmio, irq.try_into().unwrap()) @@ -134,7 +136,7 @@ pub fn init_drivers() { } else if irqtype == 0 { IntId::spi(irq) } else { - panic!("Invalid interrupt type"); + panic!("Invalid interrupt type {irqtype}!"); }; gic.set_interrupt_priority( virtio_irqid, @@ -164,7 +166,7 @@ pub fn init_drivers() { #[cfg(feature = "console")] virtio::Id::Console => { debug!( - "Found console at {mmio:p}, irq: {irq}, type: {irqtype}, flags: {irqflags}" + "virtio-console: Console found at {mmio:p} (irq: {irq}, type: {irqtype}, flags: {irqflags})" ); if let Ok(VirtioDriver::Console(drv)) = mmio_virtio::init_device(mmio, irq.try_into().unwrap()) @@ -176,7 +178,7 @@ pub fn init_drivers() { } else if irqtype == 0 { IntId::spi(irq) } else { - panic!("Invalid interrupt type"); + panic!("Invalid interrupt type {irqtype}!"); }; gic.set_interrupt_priority( virtio_irqid, @@ -214,7 +216,7 @@ pub fn init_drivers() { } } } else { - error!("No device tree found, cannot initialize MMIO drivers"); + error!("Device tree not found: MMIO drivers cannot be initialized."); } }); diff --git a/src/arch/aarch64/kernel/mod.rs b/src/arch/aarch64/kernel/mod.rs index 8986ebc020..383b351828 100644 --- a/src/arch/aarch64/kernel/mod.rs +++ b/src/arch/aarch64/kernel/mod.rs @@ -111,8 +111,7 @@ pub fn application_processor_init() { } fn finish_processor_init() { - debug!("Initialized processor {}", core_id()); - + debug!("CPU {}: Initialized", core_id()); // Allocate stack for the CPU and pass the addresses. let layout = Layout::from_size_align(KERNEL_STACK_SIZE, BasePageSize::SIZE as usize).unwrap(); let stack = unsafe { alloc(layout) }; @@ -139,8 +138,8 @@ pub fn boot_next_processor() { let phys_start = virtual_to_physical(virt_start).unwrap(); assert!(virt_start.as_u64() == phys_start.as_u64()); - trace!("Virtual address of smp_start 0x{virt_start:x}"); - trace!("Physical address of smp_start 0x{phys_start:x}"); + trace!("Virtual address of smp_start: 0x{virt_start:x}"); + trace!("Physical address of smp_start: 0x{phys_start:x}"); let fdt = env::fdt().unwrap(); let psci_node = fdt.find_node("/psci").unwrap(); @@ -164,8 +163,7 @@ pub fn boot_next_processor() { TTBR0.store(ttbr0, Ordering::Relaxed); for cpu_id in 1..get_possible_cpus() { - debug!("Try to wake-up core {cpu_id}"); - + debug!("CPU {cpu_id}: Attempting to wake up..."); if method == "hvc" { // call hypervisor to wakeup next core unsafe { @@ -177,7 +175,7 @@ pub fn boot_next_processor() { asm!("smc #0", in("x0") cpu_on, in("x1") cpu_id, in("x2") phys_start.as_u64(), in("x3") cpu_id, options(nomem, nostack)); } } else { - warn!("Method {method} isn't supported!"); + warn!("CPU {cpu_id}: Wakeup method {method} not supported!"); return; } diff --git a/src/arch/aarch64/kernel/pci.rs b/src/arch/aarch64/kernel/pci.rs index 9023997179..b0d81db5e0 100644 --- a/src/arch/aarch64/kernel/pci.rs +++ b/src/arch/aarch64/kernel/pci.rs @@ -79,7 +79,7 @@ fn detect_pci_regions(pci_node: FdtNode<'_, '_>) -> (u64, u64, u64) { 0b01 => { debug!("IO space"); if io_start != 0 { - warn!("Found already IO space"); + warn!("IO space: Already found (io_start: {io_start:#x})"); } (value_slice, residual_slice) = @@ -88,9 +88,9 @@ fn detect_pci_regions(pci_node: FdtNode<'_, '_>) -> (u64, u64, u64) { } 0b10 => { let prefetchable = high.get_bit(30); - debug!("32 bit memory space: prefetchable {prefetchable}"); + debug!("32-bit memory space: prefetchable {prefetchable}"); if mem32_start != 0 { - warn!("Found already 32 bit memory space"); + warn!("32-bit memory space: Already found (mem32_start: {mem32_start:#x}"); } (value_slice, residual_slice) = @@ -99,9 +99,9 @@ fn detect_pci_regions(pci_node: FdtNode<'_, '_>) -> (u64, u64, u64) { } 0b11 => { let prefetchable = high.get_bit(30); - debug!("64 bit memory space: prefetchable {prefetchable}"); + debug!("64-bit memory space: prefetchable {prefetchable}"); if mem64_start != 0 { - warn!("Found already 64 bit memory space"); + warn!("64-bit memory space: Already found (mem64_start: {mem64_start:#x})"); } (value_slice, residual_slice) = @@ -189,7 +189,6 @@ fn detect_interrupt( let irq_flags = u32::from_be_bytes(value_slice.try_into().unwrap()); trace!("Interrupt type {irq_type:#x}, number {irq_number:#x} flags {irq_flags:#x}"); - if high.get_bits(0..24) == addr { pin += 1; if irq_type == 0 { @@ -228,7 +227,7 @@ pub fn init() { let page_range = KERNEL_FREE_LIST.lock().allocate(layout).unwrap(); let pci_address = VirtAddr::from(page_range.start()); info!( - "Mapping PCI Enhanced Configuration Space interface to virtual address {pci_address:p} (size {size:#X})" + "PCI Enhanced Configuration Space: Mapping interface to virtual address {pci_address:p} (size {size:#X})" ); let mut flags = PageTableEntryFlags::empty(); @@ -242,9 +241,9 @@ pub fn init() { let (mut io_start, mut mem32_start, mut mem64_start) = detect_pci_regions(pci_node); - debug!("IO address space starts at{io_start:#X}"); - debug!("Memory32 address space starts at {mem32_start:#X}"); - debug!("Memory64 address space starts {mem64_start:#X}"); + debug!("IO space: Starts at {io_start:#X}"); + debug!("32-bit memory space: Starts at {mem32_start:#X}"); + debug!("64-bit memory space: Starts at {mem64_start:#X}"); assert!(io_start > 0); assert!(mem32_start > 0); assert!(mem64_start > 0); @@ -253,7 +252,7 @@ pub fn init() { / (u64::from(PCI_MAX_DEVICE_NUMBER) * u64::from(PCI_MAX_FUNCTION_NUMBER) * BasePageSize::SIZE); - info!("Scanning PCI Busses 0 to {}", max_bus_number - 1); + info!("PCI: Scanning {max_bus_number} buses (zero-indexed)"); let pci_config = PciConfigRegion::new(pci_address); for bus in 0..max_bus_number { @@ -326,7 +325,7 @@ pub fn init() { detect_interrupt(bus.try_into().unwrap(), device.into(), fdt, pci_node) { debug!( - "Initialize interrupt pin {pin} and line {line} for device {device_id}" + "Device {device_id}: Initialize interrupt pin {pin} and line {line}" ); dev.set_irq(pin, line); } @@ -338,7 +337,7 @@ pub fn init() { return; } else if let Some(_pci_node) = fdt.find_compatible(&["pci-host-cam-generic"]) { - warn!("Currently, pci-host-cam-generic isn't supported!"); + warn!("pci-host-cam-generic is not currently supported!"); } warn!("Unable to find PCI bus"); diff --git a/src/arch/aarch64/kernel/processor.rs b/src/arch/aarch64/kernel/processor.rs index 376de31dd2..de26ccc1aa 100644 --- a/src/arch/aarch64/kernel/processor.rs +++ b/src/arch/aarch64/kernel/processor.rs @@ -312,7 +312,8 @@ pub fn configure() { out(reg) pmcr_el0, options(nostack, nomem), ); - debug!("PMCR_EL0 (has RES1 bits and therefore mustn't be zero): {pmcr_el0:#X}"); + // Has RES1 bits, therefore must not be zero. + debug!("PMCR_EL0 contents: {pmcr_el0:#X}"); pmcr_el0 |= (1 << 0) | (1 << 2) | (1 << 6); asm!( "msr pmcr_el0, {}", diff --git a/src/arch/aarch64/kernel/scheduler.rs b/src/arch/aarch64/kernel/scheduler.rs index f20a01f7d3..0313c01d3f 100644 --- a/src/arch/aarch64/kernel/scheduler.rs +++ b/src/arch/aarch64/kernel/scheduler.rs @@ -142,11 +142,11 @@ impl TaskStacks { let frame_range = PHYSICAL_FREE_LIST .lock() .allocate(frame_layout) - .expect("Failed to allocate Physical Memory for TaskStacks"); + .expect("Task stacks: Physical memory allocation failed!"); let phys_addr = PhysAddr::from(frame_range.start()); debug!( - "Create stacks at {:p} with a size of {} KB", + "Task stacks: Create at virtual {:p} (size: {}KB)", virt_addr, total_size >> 10 ); @@ -188,7 +188,7 @@ impl TaskStacks { pub fn from_boot_stacks() -> TaskStacks { let stack = VirtAddr::new(CURRENT_STACK_ADDRESS.load(Ordering::Relaxed) as u64); - debug!("Using boot stack {stack:p}"); + debug!("Task stacks: Deriving from boot stack {stack:p}"); TaskStacks::Boot(BootStack { stack }) } @@ -231,7 +231,7 @@ impl Drop for TaskStacks { TaskStacks::Boot(_) => {} TaskStacks::Common(stacks) => { debug!( - "Deallocating stacks at {:p} with a size of {} KB", + "Task stacks: Deallocating at {:p} (size: {}KB)", stacks.virt_addr, stacks.total_size >> 10, ); diff --git a/src/arch/aarch64/kernel/systemtime.rs b/src/arch/aarch64/kernel/systemtime.rs index f6612c8349..54c558faa4 100644 --- a/src/arch/aarch64/kernel/systemtime.rs +++ b/src/arch/aarch64/kernel/systemtime.rs @@ -63,13 +63,13 @@ pub fn init() { let addr = PhysAddr::from(reg.starting_address.addr()); let size = u64::try_from(reg.size.unwrap()).unwrap(); - debug!("Found RTC at {addr:p} (size {size:#X})"); + debug!("RTC: Found at {addr:p} (size {size:#X})"); let layout = PageLayout::from_size(size.try_into().unwrap()).unwrap(); let page_range = KERNEL_FREE_LIST.lock().allocate(layout).unwrap(); let pl031_address = VirtAddr::from(page_range.start()); PL031_ADDRESS.set(pl031_address).unwrap(); - debug!("Mapping RTC to virtual address {pl031_address:p}"); + debug!("RTC: Mapping to virtual address {pl031_address:p}"); let mut flags = PageTableEntryFlags::empty(); flags.device().writable().execute_disable(); diff --git a/src/arch/riscv64/kernel/devicetree.rs b/src/arch/riscv64/kernel/devicetree.rs index dec8b1bd5d..d79a8eabcf 100644 --- a/src/arch/riscv64/kernel/devicetree.rs +++ b/src/arch/riscv64/kernel/devicetree.rs @@ -45,7 +45,7 @@ enum Model { /// Inits variables based on the device tree /// This function should only be called once pub fn init() { - debug!("Init devicetree"); + trace!("FDT: Initialize device tree"); if !get_dtb_ptr().is_null() { unsafe { let fdt = Fdt::from_ptr(get_dtb_ptr()).expect("FDT is invalid"); @@ -54,7 +54,7 @@ pub fn init() { .find_node("/") .unwrap() .property("compatible") - .expect("compatible not found in FDT") + .expect("DT: compatible property not found in FDT") .as_str() .unwrap(); @@ -67,7 +67,7 @@ pub fn init() { { PLATFORM_MODEL = Model::Fux40; } else { - warn!("Unknown platform, guessing PLIC context 1"); + warn!("DT: Unknown platform, guessing PLIC context 1"); PLATFORM_MODEL = Model::Unknown; } info!("Model: {model}"); @@ -80,13 +80,13 @@ pub fn init() { pub fn init_drivers() { // TODO: Implement devicetree correctly if !get_dtb_ptr().is_null() { + trace!("DT: Init drivers using devicetree"); unsafe { - debug!("Init drivers using devicetree"); let fdt = Fdt::from_ptr(get_dtb_ptr()).expect("FDT is invalid"); // Init PLIC first if let Some(plic_node) = fdt.find_compatible(&["sifive,plic-1.0.0"]) { - debug!("Found interrupt controller"); + debug!("DT: Found interrupt controller"); let plic_region = plic_node .reg() .expect("Reg property for PLIC not found in FDT") @@ -95,7 +95,7 @@ pub fn init_drivers() { let plic_region_start = PhysAddr::new(plic_region.starting_address as u64); debug!( - "Init PLIC at {:p}, size: {:x}", + "DT: Initialize PLIC at {:p} (size: {:x})", plic_region_start, plic_region.size.unwrap() ); @@ -118,41 +118,40 @@ pub fn init_drivers() { // Init GEM #[cfg(all(feature = "gem-net", not(feature = "pci")))] if let Some(gem_node) = fdt.find_compatible(&["sifive,fu540-c000-gem"]) { - debug!("Found Ethernet controller"); - + debug!("DT: Found Ethernet controller"); let gem_region = gem_node .reg() - .expect("reg property for GEM not found in FDT") + .expect("DT: reg property for GEM not found in FDT") .next() .unwrap(); let irq = gem_node .interrupts() - .expect("interrupts property for GEM not found in FDT") + .expect("DT: interrupts property for GEM not found in FDT") .next() .unwrap(); let mac = gem_node .property("local-mac-address") - .expect("local-mac-address property for GEM not found in FDT") + .expect("DT: local-mac-address property for GEM not found in FDT") .value; - debug!("Local MAC address: {mac:x?}"); + debug!("DT: Local MAC address: {mac:x?}"); let mut phy_addr = u32::MAX; let phy_node = gem_node .children() .next() - .expect("GEM node has no child node (i. e. ethernet-phy)"); + .expect("DT: GEM node has no child node (i. e. ethernet-phy)"); if phy_node.name.contains("ethernet-phy") { phy_addr = phy_node .property("reg") - .expect("reg property for ethernet-phy not found in FDT") + .expect("DT: reg property for ethernet-phy not found in FDT") .as_usize() .unwrap() as u32; } else { - warn!("Expected ethernet-phy node, found something else"); + warn!("DT: Expected ethernet-phy node, found something else"); } let gem_region_start = PhysAddr::new(gem_region.starting_address as u64); - debug!("Init GEM at {gem_region_start:p}, irq: {irq}, phy_addr: {phy_addr}"); + debug!("DT: init GEM at {gem_region_start:p}, irq: {irq}, phy_addr: {phy_addr}"); assert!( gem_region.size.unwrap() < usize::try_from(paging::HugePageSize::SIZE).unwrap() ); @@ -171,21 +170,21 @@ pub fn init_drivers() { // Init virtio-mmio #[cfg(all(any(feature = "virtio-net", feature = "console"), not(feature = "pci")))] if let Some(virtio_node) = fdt.find_compatible(&["virtio,mmio"]) { - debug!("Found virtio mmio device"); + debug!("virtio-mmio: Device found"); let virtio_region = virtio_node .reg() - .expect("reg property for virtio mmio not found in FDT") + .expect("virtio-mmio: reg property not found in FDT") .next() .unwrap(); let irq = virtio_node .interrupts() - .expect("interrupts property for virtio mmio not found in FDT") + .expect("virtio-mmio: interrupts property not found in FDT") .next() .unwrap(); let virtio_region_start = PhysAddr::new(virtio_region.starting_address as u64); - debug!("Init virtio_mmio at {virtio_region_start:p}, irq: {irq}"); + debug!("virtio-mmio: Init at {virtio_region_start:p}, irq: {irq}"); assert!( virtio_region.size.unwrap() < usize::try_from(paging::HugePageSize::SIZE).unwrap() @@ -201,16 +200,16 @@ pub fn init_drivers() { const MMIO_MAGIC_VALUE: u32 = 0x7472_6976; if magic != MMIO_MAGIC_VALUE { - error!("It's not a MMIO-device at {mmio:p}"); + error!("virtio-mmio: No MMIO device present at {mmio:p}"); } if version != 2 { - warn!("Found a legacy device, which isn't supported"); + warn!("virtio-mmio: Found an unsupported legacy device (version: {version})"); return; } // We found a MMIO-device (whose 512-bit address in this structure). - trace!("Found a MMIO-device at {mmio:p}"); + trace!("virtio-mmio: Device found at {mmio:p}"); // Verify the device-ID to find the network card let id = mmio.as_ptr().device_id().read(); @@ -233,8 +232,7 @@ pub fn init_drivers() { match id { #[cfg(all(feature = "virtio-net", not(feature = "gem-net")))] virtio::Id::Net => { - debug!("Found virtio network card at {mmio:p}"); - + debug!("virtio-net: Network card found at {mmio:p} (irq: {irq})"); if let Ok(VirtioDriver::Network(drv)) = mmio_virtio::init_device(mmio, irq.try_into().unwrap()) { @@ -243,8 +241,7 @@ pub fn init_drivers() { } #[cfg(feature = "console")] virtio::Id::Console => { - debug!("Found virtio console at {mmio:p}"); - + debug!("virtio-console: Console found at {mmio:p} (irq: {irq})"); if let Ok(VirtioDriver::Console(drv)) = mmio_virtio::init_device(mmio, irq.try_into().unwrap()) { @@ -254,7 +251,7 @@ pub fn init_drivers() { } } _ => { - warn!("Found unknown virtio device with ID {id:?} at {mmio:p}"); + warn!("virtio: Found unknown device with ID {id:?} at {mmio:p}"); } } } @@ -270,7 +267,7 @@ pub fn init_drivers() { #[cfg(feature = "console")] { if get_console_driver().is_some() { - info!("Switch to virtio console"); + info!("virtio-console: Switch to virtio console"); crate::console::CONSOLE .lock() .replace_device(IoDevice::Virtio(VirtioUART::new())); diff --git a/src/arch/riscv64/kernel/interrupts.rs b/src/arch/riscv64/kernel/interrupts.rs index 9537272875..0c64ad9c2b 100644 --- a/src/arch/riscv64/kernel/interrupts.rs +++ b/src/arch/riscv64/kernel/interrupts.rs @@ -56,7 +56,7 @@ static IRQ_NAMES: InterruptTicketMutex> = #[allow(dead_code)] pub(crate) fn add_irq_name(irq_number: u8, name: &'static str) { - debug!("Register name \"{name}\" for interrupt {irq_number}"); + debug!("Assigning name \"{name}\" for interrupt {irq_number}"); IRQ_NAMES.lock().insert(irq_number, name); } diff --git a/src/arch/riscv64/kernel/mod.rs b/src/arch/riscv64/kernel/mod.rs index 984e146227..5e83777457 100644 --- a/src/arch/riscv64/kernel/mod.rs +++ b/src/arch/riscv64/kernel/mod.rs @@ -154,37 +154,35 @@ fn finish_processor_init() { pub fn boot_next_processor() { let new_hart_mask = HART_MASK.load(Ordering::Relaxed); - debug!("HART_MASK = {new_hart_mask:#x}"); + debug!("HART: New mask is equal to {new_hart_mask:#x}"); let next_hart_index = lsb(new_hart_mask); if let Some(next_hart_id) = next_hart_index { { - debug!("Allocating stack for hard_id {next_hart_id}"); + debug!("HART: Allocating stack for ID {next_hart_id}"); let frame_layout = PageLayout::from_size(KERNEL_STACK_SIZE).unwrap(); - let frame_range = PHYSICAL_FREE_LIST - .lock() - .allocate(frame_layout) - .expect("Failed to allocate boot stack for new core"); + let frame_range = PHYSICAL_FREE_LIST.lock().allocate(frame_layout).expect( + "HART: Unable to allocate boot stack for new core with hart id: {next_hart_id})", + ); let stack = PhysAddr::from(frame_range.start()); CURRENT_STACK_ADDRESS.store(stack.as_usize() as _, Ordering::Relaxed); } - info!( - "Starting CPU {} with hart_id {}", - core_id() + 1, - next_hart_id + debug!( + "CPU {}: Start with with hart_id {next_hart_id}", + core_id() + 1 ); // TODO: Old: Changing cpu_online will cause uhyve to start the next processor CPU_ONLINE.fetch_add(1, Ordering::Release); - //When running bare-metal/QEMU we use the firmware to start the next hart + // When running bare-metal/QEMU, we use the firmware to start the next hart if !env::is_uhyve() { sbi_rt::hart_start(next_hart_id as usize, start::_start as usize, 0).unwrap(); } } else { - info!("All processors are initialized"); + debug!("All processors have been initialized."); CPU_ONLINE.fetch_add(1, Ordering::Release); } } diff --git a/src/arch/riscv64/kernel/processor.rs b/src/arch/riscv64/kernel/processor.rs index 608494a99e..30e439ceee 100644 --- a/src/arch/riscv64/kernel/processor.rs +++ b/src/arch/riscv64/kernel/processor.rs @@ -289,6 +289,6 @@ pub fn set_oneshot_timer(wakeup_time: Option) { pub fn wakeup_core(core_to_wakeup: CoreId) { let hart_id = HARTS_AVAILABLE.finalize()[core_to_wakeup as usize]; - debug!("Wakeup core: {core_to_wakeup} , hart_id: {hart_id}"); + debug!("Wakeup core: {core_to_wakeup}, hart_id: {hart_id}"); sbi_rt::send_ipi(sbi_rt::HartMask::from_mask_base(0b1, hart_id)); } diff --git a/src/arch/riscv64/kernel/scheduler.rs b/src/arch/riscv64/kernel/scheduler.rs index 39b65517e5..15c9cce380 100644 --- a/src/arch/riscv64/kernel/scheduler.rs +++ b/src/arch/riscv64/kernel/scheduler.rs @@ -126,11 +126,11 @@ impl TaskStacks { let frame_range = PHYSICAL_FREE_LIST .lock() .allocate(frame_layout) - .expect("Failed to allocate Physical Memory for TaskStacks"); + .expect("Task stacks: Physical memory allocation failed!"); let phys_addr = PhysAddr::from(frame_range.start()); debug!( - "Create stacks at {:#X} with a size of {} KB", + "Task stacks: Create at virtual {:#X} (size: {}KB)", virt_addr, total_size >> 10 ); @@ -166,7 +166,7 @@ impl TaskStacks { ); // clear user stack - debug!("Clearing user stack..."); + debug!("Task stacks: Clearing user stack..."); unsafe { ptr::write_bytes( (virt_addr + KERNEL_STACK_SIZE + DEFAULT_STACK_SIZE + 3 * BasePageSize::SIZE) @@ -177,7 +177,7 @@ impl TaskStacks { ); } - debug!("Creating stacks finished"); + debug!("Task stacks: Creation complete."); TaskStacks::Common(CommonStack { virt_addr, @@ -247,7 +247,7 @@ impl Drop for TaskStacks { TaskStacks::Boot(_) => {} TaskStacks::Common(stacks) => { debug!( - "Deallocating stacks at {:#X} with a size of {} KB", + "Task stacks: Deallocating at {:#X} (size: {}KB)", stacks.virt_addr, stacks.total_size >> 10, ); @@ -447,7 +447,7 @@ pub fn timer_handler() { #[cfg(feature = "smp")] pub fn wakeup_handler() { - debug!("Received Wakeup Interrupt"); + debug!("Wakeup interrupt received"); //increment_irq_counter(WAKEUP_INTERRUPT_NUMBER.into()); let core_scheduler = core_scheduler(); core_scheduler.check_input(); diff --git a/src/arch/x86_64/kernel/acpi.rs b/src/arch/x86_64/kernel/acpi.rs index 0b79c799a2..ff1f51a00b 100644 --- a/src/arch/x86_64/kernel/acpi.rs +++ b/src/arch/x86_64/kernel/acpi.rs @@ -315,21 +315,21 @@ fn detect_rsdp(start_address: PhysAddr, end_address: PhysAddr) -> Result<&'stati // Verify the basic checksum. if verify_checksum(current_address, RSDP_CHECKSUM_LENGTH).is_err() { - debug!("Found an ACPI table at {current_address:#X}, but its RSDP checksum is invalid"); + debug!("ACPI: Table found at {current_address:#X}, but its RSDP checksum is invalid"); continue; } // Verify the extended checksum if this is an ACPI 2.0-compliant table. if rsdp.revision >= 2 && verify_checksum(current_address, RSDP_XCHECKSUM_LENGTH).is_err() { debug!( - "Found an ACPI table at {current_address:#X}, but its RSDP extended checksum is invalid" + "ACPI: Table found at {current_address:#X}, but its RSDP extended checksum is invalid" ); continue; } // We were successful! Return a pointer to the RSDT (whose 64-bit address is called XSDT in this structure). info!( - "Found an ACPI revision {} table at {:#X} with OEM ID \"{}\"", + "ACPI: Revision {} table found at {:#X} with OEM ID \"{}\"", rsdp.revision, current_address, rsdp.oem_id() @@ -501,7 +501,7 @@ pub fn poweroff() { if let (Some(mut pm1a_cnt_blk), Some(&slp_typa)) = (PM1A_CNT_BLK.get().cloned(), SLP_TYPA.get()) { let bits = (u16::from(slp_typa) << 10) | SLP_EN; - debug!("Powering Off through ACPI (port {pm1a_cnt_blk:?}, bitmask {bits:#X})"); + debug!("Powering off using ACPI (port {pm1a_cnt_blk:?}, bitmask {bits:#X})"); unsafe { pm1a_cnt_blk.write(bits); } @@ -548,7 +548,10 @@ pub fn init() { }; let table = AcpiTable::map(table_physical_address); - debug!("Found ACPI table: {}", table.header.signature()); + debug!( + "ACPI: Found table with signature {}", + table.header.signature() + ); if table.header.signature() == "APIC" { // The "Multiple APIC Description Table" (MADT) aka "APIC Table" (APIC) diff --git a/src/arch/x86_64/kernel/apic.rs b/src/arch/x86_64/kernel/apic.rs index 865e44faed..d726e9dba4 100644 --- a/src/arch/x86_64/kernel/apic.rs +++ b/src/arch/x86_64/kernel/apic.rs @@ -259,7 +259,7 @@ impl fmt::Display for IoApicRecord { #[cfg(feature = "smp")] extern "x86-interrupt" fn tlb_flush_handler(stack_frame: interrupts::ExceptionStackFrame) { swapgs(&stack_frame); - debug!("Received TLB Flush Interrupt"); + debug!("TLB Flush Interrupt received"); increment_irq_counter(TLB_FLUSH_INTERRUPT_NUMBER); let (frame, val) = Cr3::read_raw(); unsafe { @@ -271,7 +271,7 @@ extern "x86-interrupt" fn tlb_flush_handler(stack_frame: interrupts::ExceptionSt extern "x86-interrupt" fn error_interrupt_handler(stack_frame: interrupts::ExceptionStackFrame) { swapgs(&stack_frame); - error!("APIC LVT Error Interrupt"); + error!("APIC LVT Error Interrupt received"); error!("ESR: {:#X}", local_apic_read(IA32_X2APIC_ESR)); error!("{stack_frame:#?}"); eoi(); @@ -289,7 +289,7 @@ extern "x86-interrupt" fn wakeup_handler(stack_frame: interrupts::ExceptionStack swapgs(&stack_frame); use crate::scheduler::PerCoreSchedulerExt; - debug!("Received Wakeup Interrupt"); + debug!("Wakeup interrupt received"); increment_irq_counter(WAKEUP_INTERRUPT_NUMBER); let core_scheduler = core_scheduler(); core_scheduler.check_input(); @@ -321,7 +321,7 @@ fn init_ioapic_address(phys_addr: PhysAddr) { let page_range = KERNEL_FREE_LIST.lock().allocate(layout).unwrap(); let ioapic_address = VirtAddr::from(page_range.start()); IOAPIC_ADDRESS.set(ioapic_address).unwrap(); - debug!("Mapping IOAPIC at {phys_addr:p} to virtual address {ioapic_address:p}"); + debug!("IOAPIC: Mapping {phys_addr:p} to virtual address {ioapic_address:p}"); let mut flags = PageTableEntryFlags::empty(); flags.device().writable().execute_disable(); @@ -357,7 +357,7 @@ fn detect_from_acpi() -> Result { let processor_local_apic_record = unsafe { &*(ptr::with_exposed_provenance::(current_address)) }; - debug!("Found Processor Local APIC record: {processor_local_apic_record}"); + debug!("Processor Local APIC record found: {processor_local_apic_record}"); if processor_local_apic_record.flags & CPU_FLAG_ENABLED > 0 { add_local_apic_id(processor_local_apic_record.apic_id); @@ -367,7 +367,7 @@ fn detect_from_acpi() -> Result { // I/O APIC let ioapic_record = unsafe { &*(ptr::with_exposed_provenance::(current_address)) }; - debug!("Found I/O APIC record: {ioapic_record}"); + debug!("IOAPIC record found: {ioapic_record}"); init_ioapic_address(PhysAddr::new(ioapic_record.address.into())); } @@ -436,7 +436,7 @@ fn detect_from_mp() -> Result { Err(()) }?; - info!("Found MP config at {:#x}", { mp_float.mp_config }); + info!("MP config: Found at {:#x}", { mp_float.mp_config }); info!( "System uses Multiprocessing Specification 1.{}", mp_float.version @@ -466,7 +466,7 @@ fn detect_from_mp() -> Result { (virtual_address | (u64::from(mp_float.mp_config) & (BasePageSize::SIZE - 1))) as usize; let mp_config: &ApicConfigTable = unsafe { &*(ptr::with_exposed_provenance(addr)) }; if mp_config.signature != MP_CONFIG_SIGNATURE { - warn!("Invalid MP config table"); + warn!("MP config table is invalid!"); let range = PageRange::from_start_len(virtual_address.as_usize(), BasePageSize::SIZE as usize) .unwrap(); @@ -477,7 +477,7 @@ fn detect_from_mp() -> Result { } if mp_config.entry_count == 0 { - warn!("No MP table entries! Guess IO-APIC!"); + warn!("No MP table entries found: Guessing IO-APIC as a fallback!"); let default_address = PhysAddr::new(0xfec0_0000); init_ioapic_address(default_address); @@ -499,7 +499,7 @@ fn detect_from_mp() -> Result { 2 => { let io_entry: &ApicIoEntry = unsafe { &*(ptr::with_exposed_provenance(addr)) }; let ioapic = PhysAddr::new(io_entry.addr.into()); - info!("Found IOAPIC at 0x{ioapic:p}"); + info!("IOAPIC: Found at 0x{ioapic:p}"); init_ioapic_address(ioapic); @@ -516,10 +516,8 @@ fn detect_from_mp() -> Result { } fn default_apic() -> PhysAddr { - warn!("Try to use default APIC address"); - + warn!("APIC: Trying to use address..."); let default_address = PhysAddr::new(0xfee0_0000); - // currently, uhyve doesn't support an IO-APIC if !env::is_uhyve() { init_ioapic_address(default_address); @@ -554,7 +552,7 @@ pub fn init() { let local_apic_address = VirtAddr::from(page_range.start()); LOCAL_APIC_ADDRESS.set(local_apic_address).unwrap(); debug!( - "Mapping Local APIC at {local_apic_physical_address:p} to virtual address {local_apic_address:p}" + "Local APIC: Mapping {local_apic_physical_address:p} to virtual address {local_apic_address:p}" ); let mut flags = PageTableEntryFlags::empty(); @@ -604,7 +602,7 @@ pub fn init() { fn init_ioapic() { let max_entry = ioapic_max_redirection_entry() + 1; - info!("IOAPIC v{} has {} entries", ioapic_version(), max_entry); + info!("IOAPIC: v{} has {} entries", ioapic_version(), max_entry); // now lets turn everything else on for i in 0..max_entry { @@ -622,7 +620,7 @@ fn ioapic_set_interrupt(irq: u8, apicid: u8, enabled: bool) { let ioredirect_upper = u32::from(apicid) << 24; let mut ioredirect_lower = u32::from(0x20 + irq); if !enabled { - debug!("Disabling irq {irq}"); + debug!("IOAPIC: Disabling irq {irq}"); ioredirect_lower |= 1 << 16; } @@ -678,9 +676,7 @@ fn calibrate_timer() { CALIBRATED_COUNTER_VALUE .set(calibrated_counter_value) .unwrap(); - debug!( - "Calibrated APIC Timer with a counter value of {calibrated_counter_value} for 1 microsecond", - ); + debug!("APIC: Timer calibrated with counter value of {calibrated_counter_value} for 1us",); } fn __set_oneshot_timer(wakeup_time: Option) { @@ -769,11 +765,11 @@ pub fn boot_application_processors() { let smp_boot_code = include_bytes!(concat!(core::env!("OUT_DIR"), "/boot.bin")); // We shouldn't have any problems fitting the boot code into a single page, but let's better be sure. + debug!("SMP: Boot code size is {} bytes", smp_boot_code.len()); assert!( smp_boot_code.len() < BasePageSize::SIZE as usize, - "SMP Boot Code is larger than a page" + "SMP: Boot code is larger than a single page" ); - debug!("SMP boot code is {} bytes long", smp_boot_code.len()); if env::is_uefi() { // Since UEFI already provides identity-mapped pagetables, we only have to sanity-check the identity mapping @@ -783,7 +779,7 @@ pub fn boot_application_processors() { assert_eq!(phys_addr.as_u64(), virt_addr.as_u64()); } else { // Identity-map the boot code page and copy over the code. - debug!("Mapping SMP boot code to physical and virtual address {SMP_BOOT_CODE_ADDRESS:p}"); + debug!("SMP: Mapping boot code to physical and virtual address {SMP_BOOT_CODE_ADDRESS:p}"); let mut flags = PageTableEntryFlags::empty(); flags.normal().writable(); paging::map::( @@ -809,7 +805,7 @@ pub fn boot_application_processors() { value.try_into().unwrap(); // Set entry point debug!( - "Set entry point for application processor to {:p}", + "SMP: Set application processor entry point to {:p}", start::_start as *const () ); ptr::write_unaligned( @@ -831,7 +827,7 @@ pub fn boot_application_processors() { } let destination = u64::from(apic_id) << 32; - debug!("Waking up CPU {core_id_to_boot} with Local APIC ID {apic_id}"); + debug!("CPU {core_id_to_boot}: Waking up with with Local APIC ID {apic_id}"); init_next_processor_variables(); // Save the current number of initialized CPUs. @@ -860,7 +856,7 @@ pub fn boot_application_processors() { | APIC_ICR_DELIVERY_MODE_STARTUP | ((SMP_BOOT_CODE_ADDRESS.as_u64()) >> 12), ); - debug!("Waiting for it to respond"); + debug!("SMP: Waiting for application processor to respond to local APIC write..."); // Wait until the application processor has finished initializing. // It will indicate this by counting up cpu_online. diff --git a/src/arch/x86_64/kernel/pci.rs b/src/arch/x86_64/kernel/pci.rs index aa9ae7184e..a25eb42f83 100644 --- a/src/arch/x86_64/kernel/pci.rs +++ b/src/arch/x86_64/kernel/pci.rs @@ -87,7 +87,7 @@ impl ConfigRegionAccess for LegacyPciConfigRegion { pub(crate) fn init() { #[cfg(feature = "acpi")] if pcie::init_pcie() { - info!("Initialized PCIe"); + info!("PCIe: Initialized"); return; } @@ -97,11 +97,11 @@ pub(crate) fn init() { 0..PCI_MAX_BUS_NUMBER, PciConfigRegion::Pci(LegacyPciConfigRegion::new()), ); - info!("Initialized PCI"); + info!("PCI: Initialized"); } fn scan_bus(bus_range: Range, pci_config: PciConfigRegion) { - debug!("Scanning PCI buses {bus_range:?}"); + info!("PCI: Scanning bus range {bus_range:?}"); // Hermit only uses PCI for network devices. // Therefore, multifunction devices as well as additional bridges are not scanned. diff --git a/src/arch/x86_64/kernel/scheduler.rs b/src/arch/x86_64/kernel/scheduler.rs index 06469082d9..a832e03131 100644 --- a/src/arch/x86_64/kernel/scheduler.rs +++ b/src/arch/x86_64/kernel/scheduler.rs @@ -111,11 +111,11 @@ impl TaskStacks { let frame_range = PHYSICAL_FREE_LIST .lock() .allocate(frame_layout) - .expect("Failed to allocate Physical Memory for TaskStacks"); + .expect("Task stacks: Physical memory allocation failed!"); let phys_addr = PhysAddr::from(frame_range.start()); debug!( - "Create stacks at {:p} with a size of {} KB", + "Task stacks: Create at virtual {:p} (size: {}KB)", virt_addr, total_size >> 10 ); @@ -170,11 +170,11 @@ impl TaskStacks { tss.privilege_stack_table[0].as_u64() + Self::MARKER_SIZE as u64 - KERNEL_STACK_SIZE as u64, ); - debug!("Using boot stack {stack:p}"); + debug!("Task stacks: Deriving from boot stack {stack:p}"); let ist1 = VirtAddr::new( tss.interrupt_stack_table[0].as_u64() + Self::MARKER_SIZE as u64 - IST_SIZE as u64, ); - debug!("IST1 is located at {ist1:p}"); + debug!("Task stacks: IST1 located at {ist1:p}"); TaskStacks::Boot(BootStack { stack, ist1 }) } @@ -228,7 +228,7 @@ impl Drop for TaskStacks { TaskStacks::Boot(_) => {} TaskStacks::Common(stacks) => { debug!( - "Deallocating stacks at {:p} with a size of {} KB", + "Task stacks: Deallocating at {:p} (size: {}KB)", stacks.virt_addr, stacks.total_size >> 10, ); diff --git a/src/drivers/console/pci.rs b/src/drivers/console/pci.rs index c0422d77b3..2d556bf292 100644 --- a/src/drivers/console/pci.rs +++ b/src/drivers/console/pci.rs @@ -38,7 +38,7 @@ impl VirtioConsoleDriver { } = caps_coll; let Some(dev_cfg) = dev_cfg_list.iter().find_map(VirtioConsoleDriver::map_cfg) else { - error!("No dev config. Aborting!"); + error!("virtio-console: No dev config present. Aborting!"); return Err(error::VirtioConsoleError::NoDevCfg(device_id)); }; @@ -66,12 +66,12 @@ impl VirtioConsoleDriver { Ok(caps) => match VirtioConsoleDriver::new(caps, device) { Ok(driver) => driver, Err(console_err) => { - error!("Initializing new virtio console device driver failed. Aborting!"); + error!("virtio-console: Driver initialization failed. Aborting!"); return Err(VirtioError::ConsoleDriver(console_err)); } }, Err(err) => { - error!("Mapping capabilities failed. Aborting!"); + error!("virtio-console: Mapping capabilities failed. Aborting!"); return Err(err); } }; @@ -79,7 +79,7 @@ impl VirtioConsoleDriver { match drv.init_dev() { Ok(()) => { info!( - "Console device with id {:x}, has been initialized by driver!", + "Console device with ID {:x}, has been initialized by driver!", drv.dev_cfg.dev_id ); diff --git a/src/drivers/fs/virtio_fs.rs b/src/drivers/fs/virtio_fs.rs index 9219a7a250..3d3e8a93cc 100644 --- a/src/drivers/fs/virtio_fs.rs +++ b/src/drivers/fs/virtio_fs.rs @@ -70,9 +70,7 @@ impl VirtioFsDriver { let device_features = virtio::fs::F::from(self.com_cfg.dev_features()); if device_features.requirements_satisfied() { - debug!( - "Feature set wanted by filesystem driver are in conformance with specification." - ); + debug!("virtiofs: Feature set requested by driver is spec-conforming."); } else { return Err(VirtioFsError::FeatureRequirementsNotMet(device_features)); } @@ -114,7 +112,7 @@ impl VirtioFsDriver { // Checks if the device has accepted final set. This finishes feature negotiation. if self.com_cfg.check_features() { info!( - "Features have been negotiated between virtio filesystem device {:x} and driver.", + "virtiofs: Features negotiated between filesystem device {:x} and driver.", self.dev_cfg.dev_id ); // Set feature set in device config fur future use. @@ -132,7 +130,7 @@ impl VirtioFsDriver { .read() .to_ne() + 1; if vqnum == 0 { - error!("0 request queues requested from device. Aborting!"); + error!("virtiofs: 0 request queues requested from device. Aborting!"); return Err(VirtioFsError::Unknown); } diff --git a/src/drivers/fs/virtio_pci.rs b/src/drivers/fs/virtio_pci.rs index 86dc7c5689..72e5e3b82d 100644 --- a/src/drivers/fs/virtio_pci.rs +++ b/src/drivers/fs/virtio_pci.rs @@ -39,7 +39,7 @@ impl VirtioFsDriver { } = caps_coll; let Some(dev_cfg) = dev_cfg_list.iter().find_map(VirtioFsDriver::map_cfg) else { - error!("No dev config. Aborting!"); + error!("virtiofs: No dev config present. Aborting!"); return Err(error::VirtioFsError::NoDevCfg(device_id)); }; @@ -59,19 +59,19 @@ impl VirtioFsDriver { Ok(caps) => match VirtioFsDriver::new(caps, device) { Ok(driver) => driver, Err(fs_err) => { - error!("Initializing new network driver failed. Aborting!"); + error!("virtiofs: Driver initialization failed. Aborting!"); return Err(VirtioError::FsDriver(fs_err)); } }, Err(err) => { - error!("Mapping capabilities failed. Aborting!"); + error!("virtiofs: Mapping capabilities failed. Aborting!"); return Err(err); } }; match drv.init_dev() { Ok(()) => info!( - "Filesystem device with id {:x}, has been initialized by driver!", + "virtiofs: Driver initialized filesystem device with ID {:x}!", drv.get_dev_id() ), Err(fs_err) => { diff --git a/src/drivers/net/gem.rs b/src/drivers/net/gem.rs index a26d78f76f..48d1114f10 100644 --- a/src/drivers/net/gem.rs +++ b/src/drivers/net/gem.rs @@ -247,13 +247,12 @@ impl NetworkDriver for GEMDriver { } fn has_packet(&self) -> bool { - debug!("has_packet"); - + trace!("has_packet"); self.next_rx_index().is_some() } fn set_polling_mode(&mut self, value: bool) { - debug!("set_polling_mode"); + trace!("set_polling_mode"); if value { // disable interrupts from the NIC unsafe { @@ -564,8 +563,7 @@ impl Drop for TxToken<'_> { impl Drop for GEMDriver { fn drop(&mut self) { - debug!("Dropping GEMDriver!"); - + trace!("GEM: Dropping GEMDriver!"); unsafe { // Software reset // Clear the Network Control register @@ -586,10 +584,8 @@ pub fn init_device( phy_addr: u32, mac: [u8; 6], ) -> Result { - debug!("Init GEM at {gem_base:p}"); - + debug!("GEM: Initializing at {gem_base:p}..."); let gem = gem_base.as_mut_ptr::(); - unsafe { // Initialize the Controller @@ -719,7 +715,7 @@ pub fn init_device( // TODO - Next Page does not seem to be emulated by QEMU //info!("PHY auto-negotiation completed:\n Speed: {}\nDuplex"); - debug!("PHY auto-negotiation completed: Partner Ability {partner_ability:x}"); + debug!("GEM: PHY auto-negotiation complete. Partner Ability: {partner_ability:x}"); } } @@ -804,7 +800,7 @@ pub fn init_device( (*gem).tx_qbar.set(tx_qbar); // Configure Interrupts - debug!("Install interrupt handler for GEM"); + debug!("GEM: Install interrupt handler"); (*gem).int_enable.write(Interrupts::FRAMERX::SET); // + Interrupts::TXCOMPL::SET diff --git a/src/drivers/net/rtl8139.rs b/src/drivers/net/rtl8139.rs index 75c38b6422..81cfe7672b 100644 --- a/src/drivers/net/rtl8139.rs +++ b/src/drivers/net/rtl8139.rs @@ -331,7 +331,7 @@ impl<'a> smoltcp::phy::TxToken for TxToken<'a> { assert!( !token.tx_fields.tx_in_use[id] && len <= TX_BUF_LEN, - "Unable to get TX buffer" + "RTL8139: Unable to get TX buffer" ); token.tx_fields.tx_in_use[id] = true; @@ -408,7 +408,7 @@ impl NetworkDriver for RTL8139Driver { return true; } else { warn!( - "RTL8192: invalid header {:#x}, rx_pos {}\n", + "RTL8139: invalid header {:#x}, rx_pos {}\n", header, self.rx_fields.rxpos ); } @@ -438,15 +438,15 @@ impl NetworkDriver for RTL8139Driver { } if (isr_contents & ISR_RER) == ISR_RER { - error!("RTL88139: RX error detected!\n"); + error!("RTL8139: RX error detected!\n"); } if (isr_contents & ISR_TER) == ISR_TER { - trace!("RTL88139r: TX error detected!\n"); + trace!("RTL8139r: TX error detected!\n"); } if (isr_contents & ISR_RXOVW) == ISR_RXOVW { - trace!("RTL88139: RX overflow detected!\n"); + trace!("RTL8139: RX overflow detected!\n"); } unsafe { @@ -493,7 +493,7 @@ impl RTL8139Driver { impl Drop for RTL8139Driver { fn drop(&mut self) { - debug!("Dropping RTL8129Driver!"); + debug!("RTL8139: Dropping driver!"); // Software reset unsafe { @@ -519,7 +519,7 @@ pub(crate) fn init_device( .try_into() .unwrap(); - debug!("Found RTL8139 at iobase {iobase:#x} (irq {irq})"); + debug!("RTL8139: Found at iobase {iobase:#x} (irq {irq})"); device.set_command(CommandRegister::BUS_MASTER_ENABLE); @@ -541,7 +541,7 @@ pub(crate) fn init_device( unsafe { if Port::::new(iobase + TCR).read() == 0x00ff_ffffu32 { - error!("Unable to initialize RTL8192"); + error!("RTL8139: Initialization failed"); return Err(DriverError::InitRTL8139DevFail(RTL8139Error::InitFailed)); } @@ -557,7 +557,7 @@ pub(crate) fn init_device( } if tmp == 0 { - error!("RTL8139 reset failed"); + error!("RTL8139: Reset failed"); return Err(DriverError::InitRTL8139DevFail(RTL8139Error::ResetFailed)); } @@ -598,8 +598,7 @@ pub(crate) fn init_device( let txbuffer = Box::new_zeroed_slice_in(NO_TX_BUFFERS * TX_BUF_LEN, DeviceAlloc); let mut txbuffer = unsafe { txbuffer.assume_init() }; - debug!("Allocate TxBuffer at {txbuffer:p} and RxBuffer at {rxbuffer:p}"); - + debug!("RTL8139: Allocate TxBuffer at {txbuffer:p} and RxBuffer at {rxbuffer:p}"); let phys_addr = |p| DeviceAlloc.phys_addr_from(p).as_u64().try_into().unwrap(); unsafe { @@ -642,7 +641,7 @@ pub(crate) fn init_device( ); } - info!("RTL8139 use interrupt line {irq}"); + info!("RTL8139: Using interrupt line {irq}"); add_irq_name(irq, "rtl8139"); Ok(RTL8139Driver { diff --git a/src/drivers/net/virtio/mmio.rs b/src/drivers/net/virtio/mmio.rs index fa20012c60..97433ee9c7 100644 --- a/src/drivers/net/virtio/mmio.rs +++ b/src/drivers/net/virtio/mmio.rs @@ -67,7 +67,7 @@ impl VirtioNetDriver { } } } else { - error!("Unable to create Driver. Aborting!"); + error!("virtio-net: Driver initialization failed. Aborting!"); Err(VirtioError::Unknown) } } @@ -77,7 +77,7 @@ impl VirtioNetDriver { pub fn print_information(&mut self) { self.com_cfg.print_information(); if self.dev_status() == virtio::net::S::LINK_UP { - info!("The link of the network device is up!"); + info!("virtio-net: Link is up!"); } } } diff --git a/src/drivers/net/virtio/mod.rs b/src/drivers/net/virtio/mod.rs index 0ceef6a133..f643a780c0 100644 --- a/src/drivers/net/virtio/mod.rs +++ b/src/drivers/net/virtio/mod.rs @@ -392,13 +392,13 @@ impl NetworkDriver for VirtioNetDriver { #[cfg(not(feature = "pci"))] if status.contains(virtio::mmio::InterruptStatus::CONFIGURATION_CHANGE_NOTIFICATION) { - info!("Configuration changes are not possible! Aborting"); + info!("virtio-net: Configuration changes are not possible! Aborting"); todo!("Implement possibility to change config on the fly...") } #[cfg(feature = "pci")] if status.contains(virtio::pci::IsrStatus::DEVICE_CONFIGURATION_INTERRUPT) { - info!("Configuration changes are not possible! Aborting"); + info!("virtio-net: Configuration changes are not possible! Aborting"); todo!("Implement possibility to change config on the fly...") } @@ -662,14 +662,14 @@ impl VirtioNetDriver { // Aborts in case incompatible features are selected by the driver or the device does not support min_feat_set. match self.negotiate_features(features) { Ok(()) => info!( - "Driver found a subset of features for virtio device {:x}. Features are: {features:?}", + "virtio-net: Driver found feature subset for virtio device {:x}. Features are: {features:?}", self.dev_cfg.dev_id ), Err(vnet_err) => { match vnet_err { VirtioNetError::FeatureRequirementsNotMet(features) => { error!( - "Network drivers feature set {features:?} does not satisfy rules in section 5.1.3.1 of specification v1.1. Aborting!" + "virtio-net: Network drivers a feature set {features:?}, which is not spec-compliant (Section 5.1.3.1, v1.1). Aborting!" ); return Err(vnet_err); } @@ -677,7 +677,7 @@ impl VirtioNetDriver { // Create a new matching feature set for device and driver if the minimal set is met! if !dev_feats.contains(minimal_features) { error!( - "Device features set, does not satisfy minimal features needed. Aborting!" + "virtio-net: Device features set, minimal features not present. Aborting!" ); return Err(VirtioNetError::FailFeatureNeg(self.dev_cfg.dev_id)); } @@ -685,7 +685,7 @@ impl VirtioNetDriver { let common_features = drv_feats & dev_feats; if common_features.is_empty() { error!( - "Feature negotiation failed with minimal feature set. Aborting!" + "virtio-net: Feature negotiation failed with minimal feature set. Aborting!" ); return Err(VirtioNetError::FailFeatureNeg(self.dev_cfg.dev_id)); } @@ -693,19 +693,19 @@ impl VirtioNetDriver { match self.negotiate_features(features) { Ok(()) => info!( - "Driver found a subset of features for virtio device {:x}. Features are: {features:?}", + "virtio-net: Driver found feature subset for virtio device {:x}. Features are: {features:?}", self.dev_cfg.dev_id ), Err(vnet_err) => match vnet_err { VirtioNetError::FeatureRequirementsNotMet(features) => { error!( - "Network device offers a feature set {features:?} when used completely does not satisfy rules in section 5.1.3.1 of specification v1.1. Aborting!" + "virtio-net: Network device offers a feature set {features:?}, which is not spec-compliant (Section 5.1.3.1, v1.1) when used completely. Aborting!" ); return Err(vnet_err); } _ => { error!( - "Feature Set after reduction still not usable. Set: {features:?}. Aborting!" + "virtio-net: Feature set still unusable after reduction. Set: {features:?}. Aborting!" ); return Err(vnet_err); } @@ -714,13 +714,13 @@ impl VirtioNetDriver { } VirtioNetError::FailFeatureNeg(_) => { error!( - "Wanted set of features is NOT supported by device. Set: {features:?}" + "virtio-net: Device does not supported wanted feature set. Set: {features:?}. Aborting!" ); return Err(vnet_err); } #[cfg(feature = "pci")] VirtioNetError::NoDevCfg(_) => { - error!("No device config found."); + error!("virtio-net: No device config found."); return Err(vnet_err); } } @@ -734,7 +734,7 @@ impl VirtioNetDriver { // Checks if the device has accepted final set. This finishes feature negotiation. if self.com_cfg.check_features() { info!( - "Features have been negotiated between virtio network device {:x} and driver.", + "virtio-net: Driver negotiated features with virtio network device {:x}.", self.dev_cfg.dev_id ); // Set feature set in device config fur future use. @@ -751,11 +751,14 @@ impl VirtioNetDriver { send_capacity: 0, }; - debug!("Using RX buffer size of {}", inner.recv_vqs.buf_size); + debug!( + "virtio-net: Using RX buffer size of {}.", + inner.recv_vqs.buf_size + ); self.dev_spec_init(&mut inner)?; info!( - "Device specific initialization for Virtio network device {:x} finished", + "virtio-net: Initialized virtio network device {:x}.", self.dev_cfg.dev_id ); @@ -774,7 +777,7 @@ impl VirtioNetDriver { self.checksums.udp = Checksum::Tx; self.checksums.tcp = Checksum::Tx; } - debug!("{:?}", self.checksums); + debug!("virtio-net: checksums {:?}", self.checksums); Ok(VirtioNetDriver { dev_cfg: self.dev_cfg, @@ -797,7 +800,9 @@ impl VirtioNetDriver { let device_features = virtio::net::F::from(self.com_cfg.dev_features()); if device_features.requirements_satisfied() { - info!("Feature set wanted by network driver are in conformance with specification."); + info!( + "virtio-net: Feature set wanted by network driver are in conformance with specification." + ); } else { return Err(VirtioNetError::FeatureRequirementsNotMet(device_features)); } @@ -817,7 +822,7 @@ impl VirtioNetDriver { /// Device Specific initialization according to Virtio specifictation v1.1. - 5.1.5 fn dev_spec_init(&mut self, inner: &mut Init) -> Result<(), VirtioNetError> { self.virtqueue_init(inner)?; - info!("Network driver successfully initialized virtqueues."); + info!("virtio-net: Driver successfully initialized virtqueues."); // Add a control if feature is negotiated if self.dev_cfg.features.contains(virtio::net::F::CTRL_VQ) { diff --git a/src/drivers/net/virtio/pci.rs b/src/drivers/net/virtio/pci.rs index d3b7282fb8..7847815020 100644 --- a/src/drivers/net/virtio/pci.rs +++ b/src/drivers/net/virtio/pci.rs @@ -44,7 +44,7 @@ impl VirtioNetDriver { } = caps_coll; let Some(dev_cfg) = dev_cfg_list.iter().find_map(VirtioNetDriver::map_cfg) else { - error!("No dev config. Aborting!"); + error!("virtio-net: No dev config present. Aborting!"); return Err(error::VirtioNetError::NoDevCfg(device_id)); }; @@ -78,12 +78,12 @@ impl VirtioNetDriver { Ok(caps) => match VirtioNetDriver::new(caps, device) { Ok(driver) => driver, Err(vnet_err) => { - error!("Initializing new network driver failed. Aborting!"); + error!("virtio-net: Driver initialization failed. Aborting!"); return Err(VirtioError::NetDriver(vnet_err)); } }, Err(err) => { - error!("Mapping capabilities failed. Aborting!"); + error!("virtio-net: Capability mapping failed. Aborting!"); return Err(err); } }; @@ -91,7 +91,7 @@ impl VirtioNetDriver { let initialized_drv = match drv.init_dev() { Ok(initialized_drv) => { info!( - "Network device with id {:x}, has been initialized by driver!", + "virtio-net: Initialized network device with ID {:x}", initialized_drv.get_dev_id() ); initialized_drv @@ -102,9 +102,9 @@ impl VirtioNetDriver { }; if initialized_drv.is_link_up() { - info!("Virtio-net link is up after initialization."); + info!("virtio-net: Link is up after initialization."); } else { - info!("Virtio-net link is down after initialization!"); + info!("virtio-net: Link is down after initialization!"); } Ok(initialized_drv) diff --git a/src/drivers/pci.rs b/src/drivers/pci.rs index dba74e2caa..781c694774 100644 --- a/src/drivers/pci.rs +++ b/src/drivers/pci.rs @@ -519,7 +519,7 @@ pub(crate) fn init() { #[cfg(feature = "console")] Ok(VirtioDriver::Console(drv)) => { register_driver(PciDriver::VirtioConsole(InterruptTicketMutex::new(*drv))); - info!("Switch to virtio console"); + info!("virtio-console: Switch to console"); crate::console::CONSOLE .lock() .replace_device(IoDevice::Virtio(VirtioUART::new())); diff --git a/src/drivers/virtio/mod.rs b/src/drivers/virtio/mod.rs index 50d59b3272..70858f77a1 100644 --- a/src/drivers/virtio/mod.rs +++ b/src/drivers/virtio/mod.rs @@ -59,19 +59,19 @@ pub mod error { VirtioError::FromPci(pci_error) => match pci_error { PciError::General(id) => write!( f, - "Driver failed to initialize device with id: {id:#x}. Due to unknown reasosn!" + "Driver failed to initialize device with ID: {id:#x}. Reason: Unknown." ), PciError::NoBar(id) => write!( f, - "Driver failed to initialize device with id: {id:#x}. Reason: No BAR's found." + "Driver failed to initialize device with ID: {id:#x}. Reason: No BAR's found." ), PciError::NoCapPtr(id) => write!( f, - "Driver failed to initialize device with id: {id:#x}. Reason: No Capabilities pointer found." + "Driver failed to initialize device with ID: {id:#x}. Reason: No capabilities pointer found." ), PciError::NoVirtioCaps(id) => write!( f, - "Driver failed to initialize device with id: {id:#x}. Reason: No Virtio capabilities were found." + "Driver failed to initialize device with ID: {id:#x}. Reason: No virtio capabilities found." ), }, #[cfg(feature = "pci")] @@ -90,7 +90,7 @@ pub mod error { "Virtio driver failed, for device {id:x}, due to a missing or malformed notification config!" ), VirtioError::DevNotSupported(id) => { - write!(f, "Device with id {id:#x} not supported.") + write!(f, "Device with ID {id:#x} not supported.") } #[cfg(all( not(all(target_arch = "riscv64", feature = "gem-net", not(feature = "pci"))), diff --git a/src/drivers/virtio/transport/mmio.rs b/src/drivers/virtio/transport/mmio.rs index d81d2d6f32..c581def3a1 100644 --- a/src/drivers/virtio/transport/mmio.rs +++ b/src/drivers/virtio/transport/mmio.rs @@ -378,7 +378,7 @@ pub(crate) fn init_device( let dev_id: u16 = 0; if registers.as_ptr().version().read().to_ne() == 0x1 { - error!("Legacy interface isn't supported!"); + error!("virtio: Legacy interface is not supported!"); return Err(DriverError::InitVirtioDevFail( VirtioError::DevNotSupported(dev_id), )); @@ -389,50 +389,50 @@ pub(crate) fn init_device( #[cfg(feature = "virtio-net")] virtio::Id::Net => match VirtioNetDriver::init(dev_id, registers, irq_no) { Ok(virt_net_drv) => { - info!("Virtio network driver initialized."); + info!("virtio: virtio-net driver initialized."); crate::arch::interrupts::add_irq_name(irq_no, "virtio"); - info!("Virtio interrupt handler at line {irq_no}"); + info!("virtio: virtio-net interrupt handler at line {irq_no}"); Ok(VirtioDriver::Network(virt_net_drv)) } Err(virtio_error) => { - error!("Virtio network driver could not be initialized with device"); + error!("virtio: virtio-net driver could not be initialized with device."); Err(DriverError::InitVirtioDevFail(virtio_error)) } }, #[cfg(feature = "console")] virtio::Id::Console => match VirtioConsoleDriver::init(dev_id, registers, irq_no) { Ok(virt_console_drv) => { - info!("Virtio console driver initialized."); + info!("virtio: virtio-console driver initialized."); crate::arch::interrupts::add_irq_name(irq_no, "virtio"); - info!("Virtio interrupt handler at line {}", irq_no); + info!("virtio: virtio-console interrupt handler at line {irq_no}"); Ok(VirtioDriver::Console(Box::new(virt_console_drv))) } Err(virtio_error) => { - error!("Virtio console driver could not be initialized with device"); + error!("virtio: virtio-console driver could not be initialized with device."); Err(DriverError::InitVirtioDevFail(virtio_error)) } }, #[cfg(feature = "vsock")] virtio::Id::Vsock => match VirtioVsockDriver::init(dev_id, registers, irq_no) { Ok(virt_net_drv) => { - info!("Virtio sock driver initialized."); + info!("virtio: vsock driver initialized."); crate::arch::interrupts::add_irq_name(irq_no, "virtio"); - info!("Virtio interrupt handler at line {}", irq_no); + info!("virtio: vsock interrupt handler at line {}", irq_no); Ok(VirtioDriver::Vsock(virt_vsock_drv)) } Err(virtio_error) => { - error!("Virtio sock driver could not be initialized with device"); + error!("virtio: vsock driver could not be initialized with device."); Err(DriverError::InitVirtioDevFail(virtio_error)) } }, device_id => { - error!("Device with id {device_id:?} is currently not supported!"); + error!("virtio: Device with ID {device_id:?} is not supported!"); // Return Driver error inidacting device is not supported Err(DriverError::InitVirtioDevFail( VirtioError::DevNotSupported(dev_id), diff --git a/src/drivers/virtio/transport/pci.rs b/src/drivers/virtio/transport/pci.rs index 2f250bd525..ad8283149b 100644 --- a/src/drivers/virtio/transport/pci.rs +++ b/src/drivers/virtio/transport/pci.rs @@ -43,13 +43,13 @@ use crate::drivers::vsock::VirtioVsockDriver; /// returns a static reference to it. pub fn map_dev_cfg(cap: &PciCap) -> Option<&'static mut T> { if cap.cap.cfg_type != CapCfgType::Device { - error!("Capability of device config has wrong id. Mapping not possible..."); + error!("virtio: Capability of device config has wrong id. Mapping not possible..."); return None; }; if cap.bar_len() < cap.len() + cap.offset() { error!( - "Device config of device {:x}, does not fit into memory specified by bar!", + "virtio: Device config of device {:x}, does not fit into memory specified by bar!", cap.dev_id(), ); return None; @@ -58,7 +58,7 @@ pub fn map_dev_cfg(cap: &PciCap) -> Option<&'static mut T> { // Drivers MAY do this check. See Virtio specification v1.1. - 4.1.4.1 if cap.len() < u64::try_from(mem::size_of::()).unwrap() { error!( - "Device specific config from device {:x}, does not represent actual structure specified by the standard!", + "virtio: Device specific config from device {:x}, does not represent structure specified by the standard!", cap.dev_id() ); return None; @@ -117,7 +117,7 @@ impl PciCap { fn map_common_cfg(&self) -> Option> { if self.bar.length < self.len() + self.offset() { error!( - "Common config of the capability with id {} of device {:x} does not fit into memory specified by bar {:x}!", + "virtio: Common config of the capability with ID {} of device {:x} does not fit into memory specified by bar {:x}!", self.cap.id, self.dev_id, self.bar.index ); return None; @@ -126,7 +126,7 @@ impl PciCap { // Drivers MAY do this check. See Virtio specification v1.1. - 4.1.4.1 if self.len() < u64::try_from(mem::size_of::()).unwrap() { error!( - "Common config of with id {}, does not represent actual structure specified by the standard!", + "virtio: Common config of with ID {}, does not represent actual structure specified by the standard!", self.cap.id ); return None; @@ -147,7 +147,7 @@ impl PciCap { fn map_isr_status(&self) -> Option> { if self.bar.length < self.len() + self.offset() { error!( - "ISR status config with id {} of device {:x}, does not fit into memory specified by bar {:x}!", + "virtio: ISR status config with ID {} of device {:x}, does not fit into memory specified by bar {:x}!", self.cap.id, self.dev_id, self.bar.index ); return None; @@ -443,7 +443,7 @@ impl NotifCfg { fn new(cap: &PciCap) -> Option { if cap.bar.length < cap.len() + cap.offset() { error!( - "Notification config with id {} of device {:x}, does not fit into memory specified by bar {:x}!", + "virtio: Notification config with ID {} of device {:x}, does not fit into memory specified by bar {:x}!", cap.cap.id, cap.dev_id, cap.bar.index ); return None; @@ -582,7 +582,7 @@ impl ShMemCfg { fn new(cap: &PciCap) -> Option { if cap.bar.length < cap.len() + cap.offset() { error!( - "Shared memory config of with id {} of device {:x}, does not fit into memory specified by bar {:x}!", + "virtio: Shared memory config of with ID {} of device {:x}, does not fit into memory specified by bar {:x}!", cap.cap.id, cap.dev_id, cap.bar.index ); return None; @@ -702,7 +702,7 @@ fn read_caps(device: &PciDevice) -> Result, PciErro .collect::>(); if capabilities.is_empty() { - error!("No virtio capability found for device {device_id:x}"); + error!("virtio: No virtio capability found for device {device_id:x}"); Err(PciError::NoVirtioCaps(device_id)) } else { Ok(capabilities) @@ -714,7 +714,7 @@ pub(crate) fn map_caps(device: &PciDevice) -> Result) -> Result com_cfg = Some(ComCfg::new(cap, pci_cap.cap.id)), None => error!( - "Common config capability with id {}, of device {:x}, could not be mapped!", + "virtio: Common config capability with ID {}, of device {:x}, could not be mapped!", pci_cap.cap.id, device_id ), } @@ -748,7 +748,7 @@ pub(crate) fn map_caps(device: &PciDevice) -> Result notif_cfg = Some(notif), None => error!( - "Notification config capability with id {}, of device {device_id:x} could not be used!", + "virtio: Notification config capability with ID {}, of device {device_id:x} could not be used!", pci_cap.cap.id ), } @@ -759,7 +759,7 @@ pub(crate) fn map_caps(device: &PciDevice) -> Result isr_cfg = Some(IsrStatus::new(isr_stat, pci_cap.cap.id)), None => error!( - "ISR status config capability with id {}, of device {device_id:x} could not be used!", + "virtio: ISR status config capability with ID {}, of device {device_id:x} could not be used!", pci_cap.cap.id ), } @@ -768,7 +768,7 @@ pub(crate) fn map_caps(device: &PciDevice) -> Result match ShMemCfg::new(&pci_cap) { Some(sh_mem) => sh_mem_cfg_list.push(sh_mem), None => error!( - "Shared Memory config capability with id {}, of device {device_id:x} could not be used!", + "virtio: Shared Memory config capability with ID {}, of device {device_id:x} could not be used!", pci_cap.cap.id, ), }, @@ -798,9 +798,7 @@ pub(crate) fn init_device( let device_id = device.device_id(); if device_id < 0x1040 { - warn!( - "Legacy/transitional Virtio device, with id: {device_id:#x} is NOT supported, skipping!" - ); + warn!("virtio: Legacy virtio device with ID: {device_id:#x} is not supported, skipping!"); // Return Driver error inidacting device is not supported return Err(DriverError::InitVirtioDevFail( @@ -818,17 +816,17 @@ pub(crate) fn init_device( ))] virtio::Id::Net => match VirtioNetDriver::init(device) { Ok(virt_net_drv) => { - info!("Virtio network driver initialized."); + info!("virtio: virtio-net driver initialized."); let irq = device.get_irq().unwrap(); crate::arch::interrupts::add_irq_name(irq, "virtio"); - info!("Virtio interrupt handler at line {irq}"); + info!("virtio: virtio-net interrupt handler at line {irq}"); Ok(VirtioDriver::Network(virt_net_drv)) } Err(virtio_error) => { error!( - "Virtio networkd driver could not be initialized with device: {device_id:x}" + "virtio: virtio-net driver could not be initialized with device: {device_id:x}" ); Err(DriverError::InitVirtioDevFail(virtio_error)) } @@ -836,32 +834,36 @@ pub(crate) fn init_device( #[cfg(feature = "console")] virtio::Id::Console => match VirtioConsoleDriver::init(device) { Ok(virt_console_drv) => { - info!("Virtio console driver initialized."); + info!("virtio: virtio-console driver initialized."); let irq = device.get_irq().unwrap(); crate::arch::interrupts::add_irq_name(irq, "virtio"); - info!("Virtio interrupt handler at line {irq}"); + info!("virtio: virtio-console interrupt handler at line {irq}"); Ok(VirtioDriver::Console(Box::new(virt_console_drv))) } Err(virtio_error) => { - error!("Virtio console driver could not be initialized with device: {device_id:x}"); + error!( + "virtio: virtio-console driver could not be initialized with device: {device_id:x}" + ); Err(DriverError::InitVirtioDevFail(virtio_error)) } }, #[cfg(feature = "vsock")] virtio::Id::Vsock => match VirtioVsockDriver::init(device) { Ok(virt_sock_drv) => { - info!("Virtio sock driver initialized."); + info!("virtio: virtio-sock driver initialized."); let irq = device.get_irq().unwrap(); crate::arch::interrupts::add_irq_name(irq, "virtio"); - info!("Virtio interrupt handler at line {irq}"); + info!("virtio: virtio-sock interrupt handler at line {irq}"); Ok(VirtioDriver::Vsock(Box::new(virt_sock_drv))) } Err(virtio_error) => { - error!("Virtio sock driver could not be initialized with device: {device_id:x}"); + error!( + "virtio: virtio-sock driver could not be initialized with device: {device_id:x}" + ); Err(DriverError::InitVirtioDevFail(virtio_error)) } }, @@ -871,19 +873,19 @@ pub(crate) fn init_device( // TODO: proper error handling on driver creation fail match VirtioFsDriver::init(device) { Ok(virt_fs_drv) => { - info!("Virtio filesystem driver initialized."); + info!("virtio: virtiofs driver initialized."); Ok(VirtioDriver::FileSystem(virt_fs_drv)) } Err(virtio_error) => { error!( - "Virtio filesystem driver could not be initialized with device: {device_id:x}" + "virtio: virtiofs driver could not be initialized with device: {device_id:x}" ); Err(DriverError::InitVirtioDevFail(virtio_error)) } } } id => { - warn!("Virtio device {id:?} is not supported, skipping!"); + warn!("virtio: Device {id:?} is not supported, skipping!"); // Return Driver error inidacting device is not supported Err(DriverError::InitVirtioDevFail( diff --git a/src/drivers/virtio/virtqueue/packed.rs b/src/drivers/virtio/virtqueue/packed.rs index 4b7391519e..976a9bfd1d 100644 --- a/src/drivers/virtio/virtqueue/packed.rs +++ b/src/drivers/virtio/virtqueue/packed.rs @@ -671,7 +671,7 @@ impl PackedVq { // carry a feature u64 in order to check which features are used currently // and adjust its ReadCtrl accordingly. if features.contains(virtio::F::IN_ORDER) { - info!("PackedVq has no support for VIRTIO_F_IN_ORDER. Aborting..."); + info!("virtqueue: PackedVq has no support for VIRTIO_F_IN_ORDER. Aborting..."); return Err(VirtqError::FeatureNotSupported(virtio::F::IN_ORDER)); } @@ -731,7 +731,10 @@ impl PackedVq { vq_handler.enable_queue(); - info!("Created PackedVq: idx={}, size={}", index.0, vq_size); + info!( + "virtqueue: Created PackedVq: idx={}, size={}", + index.0, vq_size + ); Ok(PackedVq { descr_ring, diff --git a/src/drivers/virtio/virtqueue/split.rs b/src/drivers/virtio/virtqueue/split.rs index 2398d6bc4f..c8124f6b40 100644 --- a/src/drivers/virtio/virtqueue/split.rs +++ b/src/drivers/virtio/virtqueue/split.rs @@ -311,7 +311,7 @@ impl SplitVq { vq_handler.enable_queue(); - info!("Created SplitVq: idx={}, size={}", index.0, size); + info!("virtqueue: Created SplitVq: idx={}, size={}", index.0, size); Ok(SplitVq { ring: descr_ring, diff --git a/src/drivers/vsock/mod.rs b/src/drivers/vsock/mod.rs index 457959a65b..a5783928b1 100644 --- a/src/drivers/vsock/mod.rs +++ b/src/drivers/vsock/mod.rs @@ -40,8 +40,7 @@ fn fill_queue(vq: &mut VirtQueue, num_packets: u16, packet_size: u32) { ) { Ok(tkn) => tkn, Err(_vq_err) => { - error!("Setup of network queue failed, which should not happen!"); - panic!("setup of network queue failed!"); + panic!("vsock: Setup of network queue failed, which should not happen!"); } }; @@ -72,7 +71,7 @@ impl RxQueue { pub fn add(&mut self, mut vq: VirtQueue) { const BUFF_PER_PACKET: u16 = 2; let num_packets: u16 = u16::from(vq.size()) / BUFF_PER_PACKET; - info!("num_packets {num_packets}"); + info!("vsock: num_packets {num_packets}"); fill_queue(&mut vq, num_packets, self.packet_size); self.vq = Some(vq); @@ -112,7 +111,7 @@ impl RxQueue { fill_queue(vq, 1, self.packet_size); } else { - panic!("Invalid length of receive queue"); + panic!("vsock: Invalid length of receive queue"); } } } @@ -188,7 +187,7 @@ impl TxQueue { result } else { - panic!("Unable to get send queue"); + panic!("vsock: Unable to get send queue"); } } } @@ -293,13 +292,13 @@ impl VirtioVsockDriver { #[cfg(not(feature = "pci"))] if status.contains(virtio::mmio::InterruptStatus::CONFIGURATION_CHANGE_NOTIFICATION) { - info!("Configuration changes are not possible! Aborting"); + info!("vsock: Configuration changes are not possible! Aborting"); todo!("Implement possibility to change config on the fly...") } #[cfg(feature = "pci")] if status.contains(virtio::pci::IsrStatus::DEVICE_CONFIGURATION_INTERRUPT) { - info!("Configuration changes are not possible! Aborting"); + info!("vsock: Configuration changes are not possible! Aborting"); todo!("Implement possibility to change config on the fly...") } @@ -315,7 +314,7 @@ impl VirtioVsockDriver { let device_features = virtio::vsock::F::from(self.com_cfg.dev_features()); if device_features.requirements_satisfied() { - info!("Feature set wanted by vsock driver are in conformance with specification."); + info!("vsock: Feature set requested by driver is spec-conforming."); } else { return Err(VirtioVsockError::FeatureRequirementsNotMet(device_features)); } @@ -357,7 +356,7 @@ impl VirtioVsockDriver { // Checks if the device has accepted final set. This finishes feature negotiation. if self.com_cfg.check_features() { info!( - "Features have been negotiated between virtio socket device {:x} and driver.", + "vsock: Features negotiated between virtio socket device {:x} and driver.", self.dev_cfg.dev_id ); // Set feature set in device config fur future use. diff --git a/src/drivers/vsock/pci.rs b/src/drivers/vsock/pci.rs index 7b2db01f2b..8fd45e4409 100644 --- a/src/drivers/vsock/pci.rs +++ b/src/drivers/vsock/pci.rs @@ -44,7 +44,7 @@ impl VirtioVsockDriver { } = caps_coll; let Some(dev_cfg) = dev_cfg_list.iter().find_map(VirtioVsockDriver::map_cfg) else { - error!("No dev config. Aborting!"); + error!("No dev config present. Aborting!"); return Err(error::VirtioVsockError::NoDevCfg(device_id)); }; @@ -70,12 +70,12 @@ impl VirtioVsockDriver { Ok(caps) => match VirtioVsockDriver::new(caps, device) { Ok(driver) => driver, Err(vsock_err) => { - error!("Initializing new virtio socket device driver failed. Aborting!"); + error!("vsock: Driver initialization failed. Aborting!"); return Err(VirtioError::VsockDriver(vsock_err)); } }, Err(err) => { - error!("Mapping capabilities failed. Aborting!"); + error!("vsock: Mapping capabilities failed. Aborting!"); return Err(err); } }; @@ -83,7 +83,7 @@ impl VirtioVsockDriver { match drv.init_dev() { Ok(()) => { info!( - "Socket device with cid {:x}, has been initialized by driver!", + "vsock: Driver initialized socket device with cid {:x}", drv.dev_cfg.raw.guest_cid ); diff --git a/src/executor/network.rs b/src/executor/network.rs index 0b07ed6e1f..07930c5501 100644 --- a/src/executor/network.rs +++ b/src/executor/network.rs @@ -245,7 +245,7 @@ pub(crate) async fn get_query_result(query: QueryHandle) -> io::Result io::Result { - debug!("FUSE lseek: offset: {offset}, whence: {whence:?}"); - - // Seek on fuse file systems seems to be a little odd: All reads are referenced from the - // beginning of the file, thus we have to track the offset ourself. Also, a read doesn't - // move the read pointer on the remote side, so we can't get the current position using - // remote lseek when referencing from `Cur` and we have to use the internally tracked - // position instead. - match whence { - SeekWhence::End | SeekWhence::Data | SeekWhence::Hole => { - if let (Some(nid), Some(fh)) = (self.fuse_nid, self.fuse_fh) { - let (cmd, rsp_payload_len) = ops::Lseek::create(nid, fh, offset, whence); - let rsp = get_filesystem_driver() - .ok_or(Errno::Nosys)? - .lock() - .send_command(cmd, rsp_payload_len)?; - - if rsp.headers.out_header.error < 0 { - return Err(Errno::Io); - } - - let rsp_offset = rsp.headers.op_header.offset; - self.offset = rsp.headers.op_header.offset.try_into().unwrap(); + trace!("FUSE lseek (offset: {offset}, whence: {whence:?})"); + if let (Some(nid), Some(fh)) = (self.fuse_nid, self.fuse_fh) { + let (cmd, rsp_payload_len) = ops::Lseek::create(nid, fh, offset, whence); + let rsp = get_filesystem_driver() + .ok_or(Errno::Nosys)? + .lock() + .send_command(cmd, rsp_payload_len)?; - Ok(rsp_offset.try_into().unwrap()) - } else { - Err(Errno::Io) - } - } - SeekWhence::Set => { - self.offset = offset.try_into().map_err(|_e| Errno::Inval)?; - Ok(self.offset as isize) - } - SeekWhence::Cur => { - self.offset = (self.offset as isize + offset) - .try_into() - .map_err(|_e| Errno::Inval)?; - Ok(self.offset as isize) + if rsp.headers.out_header.error < 0 { + return Err(Errno::Io); } + + let rsp_offset = rsp.headers.op_header.offset; + self.offset = rsp.headers.op_header.offset.try_into().unwrap(); + + Ok(rsp_offset.try_into().unwrap()) + } else { + Err(Errno::Io) } } fn fstat(&mut self) -> io::Result { - debug!("FUSE getattr"); + trace!("FUSE getattr"); if let (Some(nid), Some(fh)) = (self.fuse_nid, self.fuse_fh) { let (cmd, rsp_payload_len) = ops::Getattr::create(nid, fh, FUSE_GETATTR_FH); let rsp = get_filesystem_driver() @@ -783,7 +763,7 @@ impl FuseFileHandleInner { } fn set_attr(&mut self, attr: FileAttr, valid: SetAttrValidFields) -> io::Result { - debug!("FUSE setattr"); + trace!("FUSE setattr"); if let (Some(nid), Some(fh)) = (self.fuse_nid, self.fuse_fh) { let (cmd, rsp_payload_len) = ops::Setattr::create(nid, fh, attr, valid); let rsp = get_filesystem_driver() @@ -808,7 +788,10 @@ impl Read for FuseFileHandleInner { fn read(&mut self, buf: &mut [u8]) -> Result { let mut len = buf.len(); if len > MAX_READ_LEN { - debug!("Reading longer than max_read_len: {len}"); + warn!( + "Overriding read buffer length (longer than MAX_READ_LEN: {} > {MAX_READ_LEN})", + buf.len() + ); len = MAX_READ_LEN; } if let (Some(nid), Some(fh)) = (self.fuse_nid, self.fuse_fh) { @@ -831,7 +814,7 @@ impl Read for FuseFileHandleInner { Ok(len) } else { - debug!("File not open, cannot read!"); + error!("fuse: Cannot read file without handle: {self:?}"); Err(Errno::Noent) } } @@ -839,13 +822,12 @@ impl Read for FuseFileHandleInner { impl Write for FuseFileHandleInner { fn write(&mut self, buf: &[u8]) -> Result { - debug!("FUSE write!"); + trace!("FUSE write"); let mut truncated_len = buf.len(); if truncated_len > MAX_WRITE_LEN { debug!( - "Writing longer than max_write_len: {} > {}", + "Overriding write buffer length (longer than MAX_WRITE_LEN: {} > {MAX_WRITE_LEN})", buf.len(), - MAX_WRITE_LEN ); truncated_len = MAX_WRITE_LEN; } @@ -871,7 +853,7 @@ impl Write for FuseFileHandleInner { self.offset += rsp_len; Ok(rsp_len) } else { - warn!("File not open, cannot read!"); + error!("fuse: Cannot write file without handle: {self:?}"); Err(Errno::Noent) } } @@ -1019,7 +1001,7 @@ impl ObjectInterface for FuseDirectoryHandle { ); if len <= core::mem::size_of::() { - debug!("FUSE no new dirs"); + trace!("FUSE no new dirs"); return Err(Errno::Noent); } @@ -1087,7 +1069,7 @@ impl ObjectInterface for FuseDirectoryHandle { /// userspace applications have no way of knowing valid offsets) async fn lseek(&self, offset: isize, whence: SeekWhence) -> io::Result { if whence != SeekWhence::Set && offset != 0 { - error!("Invalid offset for directory lseek ({offset})"); + error!("fuse: Invalid offset for directory lseek ({offset})"); return Err(Errno::Inval); } *self.read_position.lock().await = offset as usize; @@ -1150,7 +1132,6 @@ impl VfsNode for FuseDirectory { fn traverse_readdir(&self, components: &mut Vec<&str>) -> io::Result> { let path = self.traversal_path(components); - debug!("FUSE opendir: {path:#?}"); let fuse_nid = lookup(path.clone()).ok_or(Errno::Noent)?; @@ -1230,7 +1211,6 @@ impl VfsNode for FuseDirectory { fn traverse_stat(&self, components: &mut Vec<&str>) -> io::Result { let path = self.traversal_path(components); - debug!("FUSE stat: {path:#?}"); // Is there a better way to implement this? @@ -1258,7 +1238,6 @@ impl VfsNode for FuseDirectory { fn traverse_lstat(&self, components: &mut Vec<&str>) -> io::Result { let path = self.traversal_path(components); - debug!("FUSE lstat: {path:#?}"); let (cmd, rsp_payload_len) = ops::Lookup::create(path); @@ -1276,7 +1255,6 @@ impl VfsNode for FuseDirectory { mode: AccessPermission, ) -> io::Result>> { let path = self.traversal_path(components); - debug!("FUSE open: {path:#?}, {opt:?} {mode:?}"); if opt.contains(OpenOption::O_DIRECTORY) { @@ -1390,12 +1368,12 @@ impl VfsNode for FuseDirectory { } pub(crate) fn init() { - debug!("Try to initialize fuse filesystem"); + debug!("fuse: Initializing..."); if let Some(driver) = get_filesystem_driver() { let (cmd, rsp_payload_len) = ops::Init::create(); let rsp = driver.lock().send_command(cmd, rsp_payload_len).unwrap(); - trace!("fuse init answer: {rsp:?}"); + trace!("fuse: init answer: {rsp:?}"); let mount_point = driver.lock().get_mount_point(); if mount_point == "/" { @@ -1435,7 +1413,7 @@ pub(crate) fn init() { assert!( len > core::mem::size_of::(), - "FUSE no new dirs" + "fuse: no new dirs" ); let mut entries: Vec = Vec::new(); @@ -1478,7 +1456,7 @@ pub(crate) fn init() { entries.retain(|x| x != "tmp"); entries.retain(|x| x != "proc"); warn!( - "Fuse don't mount the host directories 'tmp' and 'proc' into the guest file system!" + "The FUSE driver will not mount the host directories 'tmp' and 'proc' into the guest!" ); for i in entries { @@ -1492,7 +1470,7 @@ pub(crate) fn init() { let attr = FileAttr::from(rsp.headers.op_header.attr); if attr.st_mode.contains(AccessPermission::S_IFDIR) { - info!("Fuse mount {i} to /{i}"); + info!("fuse: Mount {i} to /{i}"); fs::FILESYSTEM .get() .unwrap() @@ -1500,7 +1478,7 @@ pub(crate) fn init() { &("/".to_owned() + i.as_str()), Box::new(FuseDirectory::new(Some(i))), ) - .expect("Mount failed. Invalid mount_point?"); + .expect("fuse: Mount failed. Invalid mount_point?"); } else { warn!("Fuse don't mount {i}. It isn't a directory!"); } @@ -1512,12 +1490,12 @@ pub(crate) fn init() { "/".to_owned() + &mount_point }; - info!("Mounting virtio-fs at {mount_point}"); + info!("virtio-fs: Mounting at {mount_point}"); fs::FILESYSTEM .get() .unwrap() .mount(mount_point.as_str(), Box::new(FuseDirectory::new(None))) - .expect("Mount failed. Invalid mount_point?"); + .expect("fuse: Mount failed. Invalid mount_point?"); } } } diff --git a/src/fs/uhyve.rs b/src/fs/uhyve.rs index d180497f65..955743250f 100644 --- a/src/fs/uhyve.rs +++ b/src/fs/uhyve.rs @@ -229,10 +229,10 @@ impl VfsNode for UhyveDirectory { } pub(crate) fn init() { - info!("Try to initialize uhyve filesystem"); + info!("uhyve hostfs: Initializing..."); if is_uhyve() { let mount_point = hermit_var_or!("UHYVE_MOUNT", "/root").to_string(); - info!("Mounting uhyve filesystem at {mount_point}"); + info!("uhyve hostfs: Mounting uhyve filesystem at {mount_point}"); fs::FILESYSTEM .get() .unwrap() diff --git a/src/mm/mod.rs b/src/mm/mod.rs index 79241449dc..444663f988 100644 --- a/src/mm/mod.rs +++ b/src/mm/mod.rs @@ -343,9 +343,6 @@ pub(crate) fn unmap(virtual_address: VirtAddr, size: usize) { KERNEL_FREE_LIST.lock().deallocate(range).unwrap(); } } else { - panic!( - "No page table entry for virtual address {:p}", - virtual_address - ); + panic!("No page table entry for virtual address {virtual_address:p}",); } } diff --git a/src/scheduler/mod.rs b/src/scheduler/mod.rs index 21f2fb5da1..8919ad116c 100644 --- a/src/scheduler/mod.rs +++ b/src/scheduler/mod.rs @@ -297,11 +297,11 @@ impl PerCoreScheduler { core_scheduler().ready_queue.push(task); false } else { - panic!("Invalid core_id {}!", core_id) + panic!("Invalid core_id {core_id}!") } }; - debug!("Creating task {tid} with priority {prio} on core {core_id}"); + debug!("CPU {core_id}: Creating task {tid} with priority {prio}."); if wakeup { arch::wakeup_core(core_id); @@ -373,7 +373,7 @@ impl PerCoreScheduler { core_scheduler().ready_queue.push(clone_task); false } else { - panic!("Invalid core_id {}!", core_id); + panic!("Invalid core_id {core_id}!"); } }; @@ -634,14 +634,13 @@ impl PerCoreScheduler { pub fn set_current_task_priority(&mut self, prio: Priority) { without_interrupts(|| { - trace!("Change priority of the current task"); + trace!("Scheduler: Change priority of current task ."); self.current_task.borrow_mut().prio = prio; }); } pub fn set_priority(&mut self, id: TaskId, prio: Priority) -> Result<(), ()> { - trace!("Change priority of task {id} to priority {prio}"); - + trace!("Scheduler: Change priority of task {id} to priority {prio}."); without_interrupts(|| { let task = get_task_handle(id).ok_or(())?; #[cfg(feature = "smp")] @@ -650,13 +649,13 @@ impl PerCoreScheduler { let other_core = false; if other_core { - warn!("Have to change the priority on another core"); + warn!("Scheduler: Must change the priority on another core."); } else if self.current_task.borrow().id == task.get_id() { self.current_task.borrow_mut().prio = prio; } else { self.ready_queue .set_priority(task, prio) - .expect("Do not find valid task in ready queue"); + .expect("Scheduler: No valid task found in ready queue."); } Ok(()) @@ -680,7 +679,7 @@ impl PerCoreScheduler { pub fn fpu_switch(&mut self) { if !Rc::ptr_eq(&self.current_task, &self.fpu_owner) { debug!( - "Switching FPU owner from task {} to {}", + "Scheduler: Switching FPU owner from task {} to {}", self.fpu_owner.borrow().id, self.current_task.borrow().id ); @@ -695,7 +694,7 @@ impl PerCoreScheduler { fn cleanup_tasks(&mut self) { // Pop the first finished task and remove it from the TASKS list, which implicitly deallocates all associated memory. while let Some(finished_task) = self.finished_tasks.pop_front() { - debug!("Cleaning up task {}", finished_task.borrow().id); + debug!("Scheduler: Cleaning up task {}", finished_task.borrow().id); } } @@ -794,11 +793,11 @@ impl PerCoreScheduler { // Check if there is any available task and get the one with the highest priority. if let Some(task) = self.ready_queue.pop() { // This available task becomes the new task. - debug!("Task is available."); + debug!("Scheduler: Task is available."); new_task = Some(task); } else if status != TaskStatus::Idle { // The Idle task becomes the new task. - debug!("Only Idle Task is available."); + debug!("Scheduler: Only Idle Task is available."); new_task = Some(self.idle_task.clone()); } } @@ -896,7 +895,7 @@ pub(crate) fn add_current_core() { ), ); // Initialize a scheduler for this core. - debug!("Initializing scheduler for core {core_id} with idle task {tid}"); + debug!("Initializing scheduler for core {core_id} with IDle task {tid}"); let boxed_scheduler = Box::new(PerCoreScheduler { #[cfg(feature = "smp")] core_id, diff --git a/src/scheduler/task.rs b/src/scheduler/task.rs index 78d523b757..f90259f769 100644 --- a/src/scheduler/task.rs +++ b/src/scheduler/task.rs @@ -421,7 +421,7 @@ impl Task { >, >, ) -> Task { - debug!("Creating new task {tid} on core {core_id}"); + debug!("Scheduler: Creating new task {tid} on core {core_id}"); Task { id: tid, @@ -441,7 +441,7 @@ impl Task { } pub fn new_idle(tid: TaskId, core_id: CoreId) -> Task { - debug!("Creating idle task {tid}"); + debug!("Scheduler: Creating idle task {tid}"); /// All cores use the same mapping between file descriptor and the referenced object static OBJECT_MAP: OnceCell< @@ -533,7 +533,7 @@ impl Task { /*impl Drop for Task { fn drop(&mut self) { - debug!("Drop task {}", self.id); + debug!("Scheduler: Drop task {}", self.id); } }*/ @@ -566,7 +566,7 @@ impl BlockedTaskQueue { fn mark_ready(task: &RefCell) { let mut borrowed = task.borrow_mut(); debug!( - "Waking up task {} on core {}", + "Scheduler: Waking up task {} on core {}", borrowed.id, borrowed.core_id ); @@ -605,7 +605,7 @@ impl BlockedTaskQueue { { // Set the task status to Blocked. let mut borrowed = task.borrow_mut(); - debug!("Blocking task {}", borrowed.id); + debug!("Scheduler: Blocking task {}", borrowed.id); assert_eq!( borrowed.status, diff --git a/src/syscalls/mman.rs b/src/syscalls/mman.rs index ec1078c2b6..b0c374ebca 100644 --- a/src/syscalls/mman.rs +++ b/src/syscalls/mman.rs @@ -43,7 +43,7 @@ pub extern "C" fn sys_mmap(size: usize, prot_flags: MemoryProtection, ret: &mut let frame_range = PHYSICAL_FREE_LIST.lock().allocate(frame_layout).unwrap(); let physical_address = PhysAddr::from(frame_range.start()); - debug!("Mmap {physical_address:X} -> {virtual_address:X} ({size})"); + debug!("sys_mmap: {physical_address:X} -> {virtual_address:X} ({size})"); let count = size / BasePageSize::SIZE as usize; let mut flags = PageTableEntryFlags::empty(); flags.normal().writable(); @@ -73,12 +73,12 @@ pub extern "C" fn sys_munmap(ptr: *mut u8, size: usize) -> i32 { virtual_address, size / BasePageSize::SIZE as usize, ); - debug!("Unmapping {virtual_address:X} ({size}) -> {physical_address:X}"); + debug!("sys_munmap: {virtual_address:X} ({size}) -> {physical_address:X}"); let range = PageRange::from_start_len(physical_address.as_u64() as usize, size).unwrap(); if let Err(_err) = unsafe { PHYSICAL_FREE_LIST.lock().deallocate(range) } { // FIXME: return EINVAL instead, once wasmtime can handle it - error!("Unable to deallocate {range:?}"); + error!("sys_munmap: Unable to deallocate {range:?}"); } } @@ -109,7 +109,7 @@ pub extern "C" fn sys_mprotect(ptr: *mut u8, size: usize, prot_flags: MemoryProt let virtual_address = VirtAddr::from_ptr(ptr); - debug!("Mprotect {virtual_address:X} ({size}) -> {prot_flags:?})"); + debug!("sys_mprotect: {virtual_address:X} ({size}) -> {prot_flags:?})"); if let Some(physical_address) = arch::mm::paging::virtual_to_physical(virtual_address) { arch::mm::paging::map::(virtual_address, physical_address, count, flags); 0 diff --git a/src/syscalls/mod.rs b/src/syscalls/mod.rs index fc3fa592ef..a4bdd76639 100644 --- a/src/syscalls/mod.rs +++ b/src/syscalls/mod.rs @@ -93,7 +93,7 @@ pub(crate) fn init() { pub extern "C" fn sys_alloc(size: usize, align: usize) -> *mut u8 { let layout_res = Layout::from_size_align(size, align); if layout_res.is_err() || size == 0 { - warn!("__sys_alloc called with size {size:#x}, align {align:#x} is an invalid layout!"); + warn!("__sys_alloc: called with size {size:#x}, align {align:#x} is an invalid layout!"); return core::ptr::null_mut(); } let layout = layout_res.unwrap(); @@ -111,7 +111,7 @@ pub extern "C" fn sys_alloc_zeroed(size: usize, align: usize) -> *mut u8 { let layout_res = Layout::from_size_align(size, align); if layout_res.is_err() || size == 0 { warn!( - "__sys_alloc_zeroed called with size {size:#x}, align {align:#x} is an invalid layout!" + "__sys_alloc_zeroed: called with size {size:#x}, align {align:#x} is an invalid layout!" ); return core::ptr::null_mut(); } @@ -129,7 +129,7 @@ pub extern "C" fn sys_alloc_zeroed(size: usize, align: usize) -> *mut u8 { pub extern "C" fn sys_malloc(size: usize, align: usize) -> *mut u8 { let layout_res = Layout::from_size_align(size, align); if layout_res.is_err() || size == 0 { - warn!("__sys_malloc called with size {size:#x}, align {align:#x} is an invalid layout!"); + warn!("__sys_malloc: called with size {size:#x}, align {align:#x} is an invalid layout!"); return core::ptr::null_mut(); } let layout = layout_res.unwrap(); @@ -172,7 +172,7 @@ pub unsafe extern "C" fn sys_realloc( let layout_res = Layout::from_size_align(size, align); if layout_res.is_err() || size == 0 || new_size == 0 { warn!( - "__sys_realloc called with ptr {ptr:p}, size {size:#x}, align {align:#x}, new_size {new_size:#x} is an invalid layout!" + "__sys_realloc: called with ptr {ptr:p}, size {size:#x}, align {align:#x}, new_size {new_size:#x} is an invalid layout!" ); return core::ptr::null_mut(); } @@ -181,7 +181,7 @@ pub unsafe extern "C" fn sys_realloc( if new_ptr.is_null() { debug!( - "__sys_realloc failed to resize ptr {ptr:p} with size {size:#x}, align {align:#x}, new_size {new_size:#x} !" + "__sys_realloc: failed to resize ptr {ptr:p} with size {size:#x}, align {align:#x}, new_size {new_size:#x} !" ); } else { trace!("__sys_realloc: resized memory at {ptr:p}, new address {new_ptr:p}"); @@ -208,7 +208,7 @@ pub unsafe extern "C" fn sys_dealloc(ptr: *mut u8, size: usize, align: usize) { let layout_res = Layout::from_size_align(size, align); if layout_res.is_err() || size == 0 { warn!( - "__sys_dealloc called with size {size:#x}, align {align:#x} is an invalid layout!" + "__sys_dealloc: called with size {size:#x}, align {align:#x} is an invalid layout!" ); debug_assert!(layout_res.is_err(), "__sys_dealloc error: Invalid layout"); debug_assert_ne!(size, 0, "__sys_dealloc error: size cannot be 0"); @@ -227,7 +227,7 @@ pub unsafe extern "C" fn sys_free(ptr: *mut u8, size: usize, align: usize) { unsafe { let layout_res = Layout::from_size_align(size, align); if layout_res.is_err() || size == 0 { - warn!("__sys_free called with size {size:#x}, align {align:#x} is an invalid layout!"); + warn!("__sys_free: called with size {size:#x}, align {align:#x} is an invalid layout!"); debug_assert!(layout_res.is_err(), "__sys_free error: Invalid layout"); debug_assert_ne!(size, 0, "__sys_free error: size cannot be 0"); } else { @@ -438,7 +438,7 @@ pub unsafe extern "C" fn sys_faccessat( fs::read_lstat(name) } } else { - warn!("faccessat with directory relative to fd is not implemented!"); + error!("sys_faccessat: directory relative to fd is not implemented!"); return -i32::from(Errno::Nosys); }; @@ -790,7 +790,7 @@ pub unsafe extern "C" fn sys_getdents64( dirp: *mut Dirent64, count: usize, ) -> i64 { - debug!("getdents for fd {fd:?} - count: {count}"); + debug!("sys_getdents64: for fd {fd:?} - count: {count}"); if dirp.is_null() || count == 0 { return (-i32::from(Errno::Inval)).into(); } diff --git a/src/syscalls/tasks.rs b/src/syscalls/tasks.rs index ca5fa8b120..3286106b51 100644 --- a/src/syscalls/tasks.rs +++ b/src/syscalls/tasks.rs @@ -68,7 +68,7 @@ pub extern "C" fn sys_abort() -> ! { pub(super) fn usleep(usecs: u64) { if usecs >= 10_000 { // Enough time to set a wakeup timer and block the current task. - debug!("sys_usleep blocking the task for {usecs} microseconds"); + debug!("sys_usleep: task blocked for {usecs} microseconds"); let wakeup_time = arch::processor::get_timer_ticks() + usecs; let core_scheduler = core_scheduler(); core_scheduler.block_current_task(Some(wakeup_time)); @@ -101,11 +101,11 @@ pub extern "C" fn sys_usleep(usecs: u64) { pub unsafe extern "C" fn sys_nanosleep(rqtp: *const timespec, _rmtp: *mut timespec) -> i32 { assert!( !rqtp.is_null(), - "sys_nanosleep called with a zero rqtp parameter" + "sys_nanosleep: called with a zero rqtp parameter" ); let requested_time = unsafe { &*rqtp }; if requested_time.tv_sec < 0 || requested_time.tv_nsec > 999_999_999 { - debug!("sys_nanosleep called with an invalid requested time, returning -EINVAL"); + debug!("sys_nanosleep: called with an invalid requested time, returning -EINVAL"); return -i32::from(Errno::Inval); } @@ -252,7 +252,7 @@ pub extern "C" fn sys_set_priority(id: Tid, prio: u8) { .set_priority(TaskId::from(id), Priority::from(prio)) .expect("Unable to set priority"); } else { - panic!("Invalid priority {}", prio); + panic!("Invalid priority {prio}"); } } @@ -263,6 +263,6 @@ pub extern "C" fn sys_set_current_task_priority(prio: u8) { if prio > 0 { core_scheduler().set_current_task_priority(Priority::from(prio)); } else { - panic!("Invalid priority {}", prio); + panic!("Invalid priority {prio}"); } } diff --git a/src/syscalls/timer.rs b/src/syscalls/timer.rs index 81eab5f4f7..73c3fb8fdd 100644 --- a/src/syscalls/timer.rs +++ b/src/syscalls/timer.rs @@ -27,7 +27,7 @@ pub(crate) const TIMER_ABSTIME: i32 = 4; pub unsafe extern "C" fn sys_clock_getres(clock_id: clockid_t, res: *mut timespec) -> i32 { assert!( !res.is_null(), - "sys_clock_getres called with a zero res parameter" + "sys_clock_getres: called with a zero res parameter" ); let result = unsafe { &mut *res }; @@ -38,7 +38,7 @@ pub unsafe extern "C" fn sys_clock_getres(clock_id: clockid_t, res: *mut timespe 0 } _ => { - debug!("Called sys_clock_getres for unsupported clock {clock_id}"); + error!("sys_clock_getres: called for unsupported clock {clock_id}"); -i32::from(Errno::Inval) } } @@ -57,7 +57,7 @@ pub unsafe extern "C" fn sys_clock_getres(clock_id: clockid_t, res: *mut timespe pub unsafe extern "C" fn sys_clock_gettime(clock_id: clockid_t, tp: *mut timespec) -> i32 { assert!( !tp.is_null(), - "sys_clock_gettime called with a zero tp parameter" + "sys_clock_gettime: called with a zero tp parameter" ); let result = unsafe { &mut *tp }; @@ -71,7 +71,7 @@ pub unsafe extern "C" fn sys_clock_gettime(clock_id: clockid_t, tp: *mut timespe 0 } _ => { - debug!("Called sys_clock_gettime for unsupported clock {clock_id}"); + error!("sys_clock_gettime: called for unsupported clock {clock_id}"); -i32::from(Errno::Inval) } } @@ -96,11 +96,11 @@ pub unsafe extern "C" fn sys_clock_nanosleep( ) -> i32 { assert!( !rqtp.is_null(), - "sys_clock_nanosleep called with a zero rqtp parameter" + "sys_clock_nanosleep: called with a zero rqtp parameter" ); let requested_time = unsafe { &*rqtp }; if requested_time.tv_sec < 0 || requested_time.tv_nsec > 999_999_999 { - debug!("sys_clock_nanosleep called with an invalid requested time, returning -EINVAL"); + error!("sys_clock_nanosleep: called with an invalid requested time, returning -EINVAL"); return -i32::from(Errno::Inval); } @@ -128,7 +128,7 @@ pub unsafe extern "C" fn sys_clock_nanosleep( #[unsafe(no_mangle)] pub unsafe extern "C" fn sys_clock_settime(_clock_id: clockid_t, _tp: *const timespec) -> i32 { // We don't support setting any clocks yet. - debug!("sys_clock_settime is unimplemented, returning -EINVAL"); + error!("sys_clock_settime: unimplemented, returning -EINVAL"); -i32::from(Errno::Inval) } @@ -149,7 +149,7 @@ pub unsafe extern "C" fn sys_gettimeofday(tp: *mut timeval, tz: usize) -> i32 { } if tz > 0 { - debug!("The tz parameter in sys_gettimeofday is unimplemented, returning -EINVAL"); + error!("sys_gettimeofday: tz parameter is unimplemented, returning -EINVAL"); return -i32::from(Errno::Inval); } @@ -163,6 +163,6 @@ pub unsafe extern "C" fn sys_setitimer( _value: *const itimerval, _ovalue: *mut itimerval, ) -> i32 { - debug!("Called sys_setitimer, which is unimplemented and always returns 0"); + error!("sys_setitimer: unimplemented, always returns 0"); 0 } From 57d104e704519aa606a6f0d0773f15e0b68284b7 Mon Sep 17 00:00:00 2001 From: "Panagiotis \"Ivory\" Vasilopoulos" Date: Sat, 11 Oct 2025 15:37:03 +0200 Subject: [PATCH 2/2] style(executor/device): improve styling of networking messages --- src/executor/device.rs | 12 ++++++------ 1 file changed, 6 insertions(+), 6 deletions(-) diff --git a/src/executor/device.rs b/src/executor/device.rs index fbe32872fc..d7d1e619d5 100644 --- a/src/executor/device.rs +++ b/src/executor/device.rs @@ -58,16 +58,16 @@ impl<'a> NetworkInterface<'a> { #[cfg(feature = "trace")] let mut device = Tracer::new(device, |timestamp, printer| trace!("{timestamp} {printer}")); - if hermit_var!("HERMIT_IP").is_some() { + if let Some(hermit_ip) = hermit_var!("HERMIT_IP") { warn!( - "A static IP address is specified with the environment variable HERMIT_IP, but the device is configured to use DHCPv4!" + "Device is configured to use DHCPv4, but the environment variable HERMIT_IP has set the following static IP address: {hermit_ip}" ); } let ethernet_addr = EthernetAddress([mac[0], mac[1], mac[2], mac[3], mac[4], mac[5]]); let hardware_addr = HardwareAddress::Ethernet(ethernet_addr); - info!("MAC address {hardware_addr}"); + info!("MAC Address: {hardware_addr}"); let capabilities = device.capabilities(); info!("{:?}", capabilities.checksum); info!("MTU: {} bytes", capabilities.max_transmission_unit); @@ -132,9 +132,9 @@ impl<'a> NetworkInterface<'a> { let hardware_addr = HardwareAddress::Ethernet(ethernet_addr); let ip_addr = IpCidr::from(Ipv4Cidr::from_netmask(myip, mymask).unwrap()); - info!("MAC address {hardware_addr}"); - info!("Configure network interface with address {ip_addr}"); - info!("Configure gateway with address {mygw}"); + info!("MAC Address: {hardware_addr}"); + info!("IPv4: {ip_addr}"); + info!("Gateway IP: {mygw}"); let capabilities = device.capabilities(); info!("{:?}", capabilities.checksum); info!("MTU: {} bytes", capabilities.max_transmission_unit);