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/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); 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 }