style: improve user-facing kernel messages

- Move subjects to beginning of each message
- Unify certain messages across architecture-specific implementations
- State the component/task at the beginning of most messages
  (before verbs) to make log scrolling and pinpointing failures easier
- Grammar-related improvements
- Increase consistency of used wording
- In some cases, display relevant variables
- Replace debug! with error! before errors are returned.
- Replace some debug! instances with trace!
- Decrease the length of some sentences
- Make messages of standard actions (e.g. driver init) consistent
  (mostly.)
- Correct mentions of RTL8139 in the driver's messages
- Add more variables inside of placeholders

This change is not intended to be perfect and does not improve ALL
messages, with many changes being highly subjective.

It has a primary focus on debugging information and drivers.
The primary motivation for this change is mostly the high amount of
time spent trying to understand sequences of actions (and e.g. where
specifically the booting of a kernel may break), while also assisting
those that do not have a full picture of the kernel's source code.

Some messages were not modified to include the name of the component,
as it may be self-evident depending on the context and the debugging
activity (see: src/drivers/gem.rs) and increase the mental noise,
rather than decrease it.

Author: n0toose

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::<BasePageSize>(
 		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<HashMap<u8, &'static str, RandomState>> =
 
 #[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);
 }
 

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.");
 		}
 	});
 

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

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");

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, {}",

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,
 				);

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();