From 0fc60e41dd06f2c47f1ba416e6eb1c08ee9024c4 Mon Sep 17 00:00:00 2001 From: Liav A Date: Sun, 1 Mar 2020 21:45:39 +0200 Subject: [PATCH] Kernel: Use klog() instead of kprintf() Also, duplicate data in dbg() and klog() calls were removed. In addition, leakage of virtual address to kernel log is prevented. This is done by replacing kprintf() calls to dbg() calls with the leaked data instead. Also, other kprintf() calls were replaced with klog(). --- Kernel/ACPI/ACPIDynamicParser.cpp | 4 +- Kernel/ACPI/ACPIParser.cpp | 18 +- Kernel/ACPI/ACPIStaticParser.cpp | 30 +-- Kernel/ACPI/DMIDecoder.cpp | 22 +-- Kernel/ACPI/MultiProcessorParser.cpp | 22 +-- Kernel/Arch/i386/CPU.cpp | 126 ++++++------- Kernel/Devices/BXVGADevice.cpp | 2 +- Kernel/Devices/DiskPartition.cpp | 4 +- Kernel/Devices/EBRPartitionTable.cpp | 28 +-- Kernel/Devices/FloppyDiskDevice.cpp | 58 +++--- Kernel/Devices/GPTPartitionTable.cpp | 14 +- Kernel/Devices/MBRPartitionTable.cpp | 12 +- Kernel/Devices/PATAChannel.cpp | 6 +- Kernel/Devices/PIT.cpp | 2 +- Kernel/Devices/PS2MouseDevice.cpp | 8 +- Kernel/Devices/SB16.cpp | 8 +- Kernel/Devices/VMWareBackdoor.cpp | 6 +- Kernel/FileSystem/DiskBackedFileSystem.cpp | 6 +- Kernel/FileSystem/Ext2FileSystem.cpp | 36 ++-- Kernel/FileSystem/FIFO.cpp | 8 +- Kernel/FileSystem/Inode.cpp | 2 +- Kernel/FileSystem/VirtualFileSystem.cpp | 8 +- Kernel/Heap/kmalloc.cpp | 4 +- Kernel/Interrupts/APIC.cpp | 4 +- Kernel/Interrupts/IOAPIC.cpp | 6 +- Kernel/Interrupts/InterruptManagement.cpp | 6 +- Kernel/Interrupts/PIC.cpp | 2 +- Kernel/Interrupts/SharedIRQHandler.cpp | 8 +- .../Interrupts/SpuriousInterruptHandler.cpp | 2 +- Kernel/KSyms.cpp | 4 +- Kernel/Lock.cpp | 2 +- Kernel/Net/IPv4Socket.cpp | 24 +-- Kernel/Net/LocalSocket.cpp | 10 +- Kernel/Net/NetworkTask.cpp | 172 ++++++------------ Kernel/Net/Routing.cpp | 33 +--- Kernel/Net/Socket.cpp | 6 +- Kernel/Net/TCPSocket.cpp | 19 +- Kernel/Net/UDPSocket.cpp | 6 +- Kernel/PCI/Access.cpp | 2 +- Kernel/PCI/IOAccess.cpp | 2 +- Kernel/PCI/Initializer.cpp | 22 +-- Kernel/PCI/MMIOAccess.cpp | 8 +- Kernel/Process.cpp | 45 ++--- Kernel/RTC.cpp | 3 +- Kernel/SharedBuffer.cpp | 2 +- Kernel/Syscall.cpp | 2 +- Kernel/TestModule.cpp | 9 +- Kernel/Thread.cpp | 8 +- Kernel/VM/MemoryManager.cpp | 59 ++---- Kernel/VM/PageDirectory.cpp | 6 +- Kernel/VM/RangeAllocator.cpp | 4 +- Kernel/VM/Region.cpp | 12 +- Kernel/init.cpp | 48 ++--- 53 files changed, 397 insertions(+), 573 deletions(-) diff --git a/Kernel/ACPI/ACPIDynamicParser.cpp b/Kernel/ACPI/ACPIDynamicParser.cpp index c46031956a..ab369337a0 100644 --- a/Kernel/ACPI/ACPIDynamicParser.cpp +++ b/Kernel/ACPI/ACPIDynamicParser.cpp @@ -47,13 +47,13 @@ namespace ACPI { , StaticParser() { - kprintf("ACPI: Dynamic Parsing Enabled, Can parse AML\n"); + klog() << "ACPI: Dynamic Parsing Enabled, Can parse AML"; } DynamicParser::DynamicParser(PhysicalAddress rsdp) : IRQHandler(9) , StaticParser(rsdp) { - kprintf("ACPI: Dynamic Parsing Enabled, Can parse AML\n"); + klog() << "ACPI: Dynamic Parsing Enabled, Can parse AML"; } void DynamicParser::handle_irq(RegisterState&) diff --git a/Kernel/ACPI/ACPIParser.cpp b/Kernel/ACPI/ACPIParser.cpp index bfbf3eaf16..cd8d8bc150 100644 --- a/Kernel/ACPI/ACPIParser.cpp +++ b/Kernel/ACPI/ACPIParser.cpp @@ -51,49 +51,49 @@ namespace ACPI { Parser::Parser(bool usable) { if (usable) { - kprintf("ACPI: Setting up a functional parser\n"); + klog() << "ACPI: Setting up a functional parser"; } else { - kprintf("ACPI: Limited Initialization. Vital functions are disabled by a request\n"); + klog() << "ACPI: Limited Initialization. Vital functions are disabled by a request"; } s_acpi_parser = this; } PhysicalAddress Parser::find_table(const char*) { - kprintf("ACPI: Requested to search for a table, Abort!\n"); + klog() << "ACPI: Requested to search for a table, Abort!"; return {}; } void Parser::do_acpi_reboot() { - kprintf("ACPI: Cannot invoke reboot!\n"); + klog() << "ACPI: Cannot invoke reboot!"; ASSERT_NOT_REACHED(); } void Parser::do_acpi_shutdown() { - kprintf("ACPI: Cannot invoke shutdown!\n"); + klog() << "ACPI: Cannot invoke shutdown!"; ASSERT_NOT_REACHED(); } void Parser::enable_aml_interpretation() { - kprintf("ACPI: No AML Interpretation Allowed\n"); + klog() << "ACPI: No AML Interpretation Allowed"; ASSERT_NOT_REACHED(); } void Parser::enable_aml_interpretation(File&) { - kprintf("ACPI: No AML Interpretation Allowed\n"); + klog() << "ACPI: No AML Interpretation Allowed"; ASSERT_NOT_REACHED(); } void Parser::enable_aml_interpretation(u8*, u32) { - kprintf("ACPI: No AML Interpretation Allowed\n"); + klog() << "ACPI: No AML Interpretation Allowed"; ASSERT_NOT_REACHED(); } void Parser::disable_aml_interpretation() { - kprintf("ACPI Limited: No AML Interpretation Allowed\n"); + klog() << "ACPI Limited: No AML Interpretation Allowed"; ASSERT_NOT_REACHED(); } bool Parser::is_operable() diff --git a/Kernel/ACPI/ACPIStaticParser.cpp b/Kernel/ACPI/ACPIStaticParser.cpp index 21e1272d36..d97f321fa4 100644 --- a/Kernel/ACPI/ACPIStaticParser.cpp +++ b/Kernel/ACPI/ACPIStaticParser.cpp @@ -88,8 +88,8 @@ namespace ACPI { void StaticParser::init_fadt() { - kprintf("ACPI: Initializing Fixed ACPI data\n"); - kprintf("ACPI: Searching for the Fixed ACPI Data Table\n"); + klog() << "ACPI: Initializing Fixed ACPI data"; + klog() << "ACPI: Searching for the Fixed ACPI Data Table"; m_fadt = find_table("FACP"); ASSERT(!m_fadt.is_null()); @@ -99,7 +99,7 @@ namespace ACPI { #ifdef ACPI_DEBUG dbg() << "ACPI: FADT @ V " << sdt << ", P " << (void*)fadt.as_ptr(); #endif - kprintf("ACPI: Fixed ACPI data, Revision %u, Length %u bytes\n", sdt->revision, sdt->length); + klog() << "ACPI: Fixed ACPI data, Revision " << sdt->revision << ", Length " << sdt->length << " bytes"; } void StaticParser::do_acpi_reboot() @@ -111,10 +111,10 @@ namespace ACPI { auto region = MM.allocate_kernel_region(m_fadt.page_base(), (PAGE_SIZE * 2), "ACPI Static Parser", Region::Access::Read); auto* fadt = (const Structures::FADT*)region->vaddr().offset(m_fadt.offset_in_page().get()).as_ptr(); if (fadt->h.revision >= 2) { - kprintf("ACPI: Reboot, Sending value 0%x to Port 0x%x\n", fadt->reset_value, fadt->reset_reg.address); + klog() << "ACPI: Reboot, Sending value 0x" << String::format("%x", fadt->reset_value) << " to Port 0x" << String::format("%x", fadt->reset_reg.address); IO::out8(fadt->reset_reg.address, fadt->reset_value); } else { - kprintf("ACPI: Reboot, Not supported!\n"); + klog() << "ACPI: Reboot, Not supported!"; } ASSERT_NOT_REACHED(); /// If rebooting didn't work, halt. @@ -122,7 +122,7 @@ namespace ACPI { void StaticParser::do_acpi_shutdown() { - kprintf("ACPI: Shutdown is not supported with the current configuration, Abort!\n"); + klog() << "ACPI: Shutdown is not supported with the current configuration, Abort!"; ASSERT_NOT_REACHED(); } @@ -159,12 +159,12 @@ namespace ACPI { auto main_sdt_region = MM.allocate_kernel_region(m_main_system_description_table.page_base(), PAGE_ROUND_UP(length) + PAGE_SIZE, "ACPI Static Parser Initialization", Region::Access::Read, false, true); auto* sdt = (volatile Structures::SDTHeader*)main_sdt_region->vaddr().offset(m_main_system_description_table.offset_in_page().get()).as_ptr(); - kprintf("ACPI: Main Description Table valid? 0x%x\n", StaticParsing::validate_table(const_cast(*sdt), length)); + klog() << "ACPI: Main Description Table valid? " << StaticParsing::validate_table(const_cast(*sdt), length); if (m_xsdt_supported) { volatile auto* xsdt = (volatile Structures::XSDT*)sdt; - kprintf("ACPI: Using XSDT, Enumerating tables @ P 0x%x\n", m_main_system_description_table.get()); - kprintf("ACPI: XSDT Revision %d, Total length - %u\n", revision, length); + klog() << "ACPI: Using XSDT, Enumerating tables @ P " << String::format("%p", m_main_system_description_table.get()); + klog() << "ACPI: XSDT Revision " << revision << ", Total length - " << length; #ifdef ACPI_DEBUG dbg() << "ACPI: XSDT pointer @ V " << xsdt; #endif @@ -176,8 +176,8 @@ namespace ACPI { } } else { volatile auto* rsdt = (volatile Structures::RSDT*)sdt; - kprintf("ACPI: Using RSDT, Enumerating tables @ P 0x%x\n", m_main_system_description_table.get()); - kprintf("ACPI: RSDT Revision %d, Total length - %u\n", revision, length); + klog() << "ACPI: Using RSDT, Enumerating tables @ P " << String::format("%p", m_main_system_description_table.get()); + klog() << "ACPI: RSDT Revision " << revision << ", Total length - " << length; #ifdef ACPI_DEBUG dbg() << "ACPI: RSDT pointer @ V " << rsdt; #endif @@ -215,12 +215,12 @@ namespace ACPI { , m_rsdp(StaticParsing::search_rsdp()) { if (!m_rsdp.is_null()) { - kprintf("ACPI: Using RSDP @ P 0x%x\n", m_rsdp); + klog() << "ACPI: Using RSDP @ P " << String::format("%p", m_rsdp); m_operable = true; locate_static_data(); } else { m_operable = false; - kprintf("ACPI: Disabled, due to RSDP being absent\n"); + klog() << "ACPI: Disabled, due to RSDP being absent"; } } @@ -228,7 +228,7 @@ namespace ACPI { : Parser(true) , m_rsdp(rsdp) { - kprintf("ACPI: Using RSDP @ Px%x\n", rsdp.get()); + klog() << "ACPI: Using RSDP @ P " << String::format("%p", rsdp.get()); m_operable = true; locate_static_data(); } @@ -279,7 +279,7 @@ namespace ACPI { PhysicalAddress rsdp; auto region = MM.allocate_kernel_region(PhysicalAddress(0), PAGE_SIZE, "ACPI RSDP Searching", Region::Access::Read); u16 ebda_seg = (u16) * ((uint16_t*)((region->vaddr().get() & PAGE_MASK) + 0x40e)); - kprintf("ACPI: Probing EBDA, Segment 0x%x\n", ebda_seg); + klog() << "ACPI: Probing EBDA, Segment 0x" << String::format("%x", ebda_seg); rsdp = search_rsdp_in_ebda(ebda_seg); if (!rsdp.is_null()) diff --git a/Kernel/ACPI/DMIDecoder.cpp b/Kernel/ACPI/DMIDecoder.cpp index dc74794174..6db8b73ef6 100644 --- a/Kernel/ACPI/DMIDecoder.cpp +++ b/Kernel/ACPI/DMIDecoder.cpp @@ -62,7 +62,7 @@ void DMIDecoder::initialize_untrusted() void DMIDecoder::set_64_bit_entry_initialization_values(PhysicalAddress entry) { - kprintf("DMIDecoder: SMBIOS 64bit Entry point @ P 0x%x\n", m_entry64bit_point.get()); + klog() << "DMIDecoder: SMBIOS 64bit Entry point @ P " << String::format("%p", m_entry64bit_point.get()); m_use_64bit_entry = true; auto region = MM.allocate_kernel_region(entry.page_base(), PAGE_ROUND_UP(SMBIOS_SEARCH_AREA_SIZE), "DMI Decoder 64 bit Initialization", Region::Access::Read, false, false); @@ -74,7 +74,7 @@ void DMIDecoder::set_64_bit_entry_initialization_values(PhysicalAddress entry) void DMIDecoder::set_32_bit_entry_initialization_values(PhysicalAddress entry) { - kprintf("DMIDecoder: SMBIOS 32bit Entry point @ P 0x%x\n", m_entry32bit_point.get()); + klog() << "DMIDecoder: SMBIOS 32bit Entry point @ P " << String::format("%p", m_entry32bit_point.get()); m_use_64bit_entry = false; auto region = MM.allocate_kernel_region(entry.page_base(), PAGE_ROUND_UP(SMBIOS_SEARCH_AREA_SIZE), "DMI Decoder 32 bit Initialization", Region::Access::Read, false, false); @@ -90,18 +90,18 @@ void DMIDecoder::initialize_parser() if (m_entry32bit_point.is_null() && m_entry64bit_point.is_null()) { m_operable = false; - kprintf("DMI Decoder is disabled. Cannot find SMBIOS tables.\n"); + klog() << "DMI Decoder is disabled. Cannot find SMBIOS tables."; return; } m_operable = true; - kprintf("DMI Decoder is enabled\n"); + klog() << "DMI Decoder is enabled"; if (!m_entry64bit_point.is_null()) { set_64_bit_entry_initialization_values(m_entry64bit_point); } else if (!m_entry32bit_point.is_null()) { set_32_bit_entry_initialization_values(m_entry32bit_point); } - kprintf("DMIDecoder: Data table @ P 0x%x\n", m_structure_table.get()); + klog() << "DMIDecoder: Data table @ P " << String::format("%p", m_structure_table.get()); enumerate_smbios_tables(); } @@ -125,10 +125,10 @@ void DMIDecoder::enumerate_smbios_tables() #endif structures_count++; if (v_table_ptr->type == (u8)SMBIOS::TableType::EndOfTable) { - kprintf("DMIDecoder: Detected table with type 127, End of SMBIOS data.\n"); + klog() << "DMIDecoder: Detected table with type 127, End of SMBIOS data."; break; } - kprintf("DMIDecoder: Detected table with type %d\n", v_table_ptr->type); + klog() << "DMIDecoder: Detected table with type " << v_table_ptr->type; m_smbios_tables.append(p_table); table_length -= v_table_ptr->length; @@ -205,7 +205,7 @@ DMIDecoder::DMIDecoder(bool trusted) , m_untrusted(!trusted) { if (!trusted) { - kprintf("DMI Decoder initialized as untrusted due to user request.\n"); + klog() << "DMI Decoder initialized as untrusted due to user request."; } initialize_parser(); } @@ -249,7 +249,7 @@ PhysicalAddress DMIDecoder::find_entry32bit_point() Vector& DMIDecoder::get_physical_memory_areas() { // FIXME: Implement it... - kprintf("DMIDecoder::get_physical_memory_areas() is not implemented.\n"); + klog() << "DMIDecoder::get_physical_memory_areas() is not implemented."; ASSERT_NOT_REACHED(); } bool DMIDecoder::is_reliable() @@ -264,7 +264,7 @@ u64 DMIDecoder::get_bios_characteristics() auto* bios_info = (SMBIOS::BIOSInfo*)get_smbios_physical_table_by_type(0).as_ptr(); ASSERT(bios_info != nullptr); - kprintf("DMIDecoder: BIOS info @ P 0x%x\n", bios_info); + klog() << "DMIDecoder: BIOS info @ P " << String::format("%p", bios_info); return bios_info->bios_characteristics; } @@ -272,7 +272,7 @@ char* DMIDecoder::get_smbios_string(PhysicalAddress, u8) { // FIXME: Implement it... // FIXME: Make sure we have some mapping here so we don't rely on existing identity mapping... - kprintf("DMIDecoder::get_smbios_string() is not implemented.\n"); + klog() << "DMIDecoder::get_smbios_string() is not implemented."; ASSERT_NOT_REACHED(); return nullptr; } diff --git a/Kernel/ACPI/MultiProcessorParser.cpp b/Kernel/ACPI/MultiProcessorParser.cpp index af0713a27b..eb00b90de7 100644 --- a/Kernel/ACPI/MultiProcessorParser.cpp +++ b/Kernel/ACPI/MultiProcessorParser.cpp @@ -48,11 +48,11 @@ MultiProcessorParser::MultiProcessorParser() , m_operable((m_floating_pointer != (uintptr_t) nullptr)) { if (m_floating_pointer != (uintptr_t) nullptr) { - kprintf("MultiProcessor: Floating Pointer Structure @ P 0x%x\n", m_floating_pointer); + klog() << "MultiProcessor: Floating Pointer Structure @ P " << String::format("%p", m_floating_pointer); parse_floating_pointer_data(); parse_configuration_table(); } else { - kprintf("MultiProcessor: Can't Locate Floating Pointer Structure, disabled.\n"); + klog() << "MultiProcessor: Can't Locate Floating Pointer Structure, disabled."; } } @@ -128,7 +128,7 @@ uintptr_t MultiProcessorParser::search_floating_pointer() uintptr_t mp_floating_pointer = (uintptr_t) nullptr; auto region = MM.allocate_kernel_region(PhysicalAddress(0), PAGE_SIZE, "MultiProcessor Parser Floating Pointer Structure Finding", Region::Access::Read); u16 ebda_seg = (u16) * ((uint16_t*)((region->vaddr().get() & PAGE_MASK) + 0x40e)); - kprintf("MultiProcessor: Probing EBDA, Segment 0x%x\n", ebda_seg); + klog() << "MultiProcessor: Probing EBDA, Segment 0x" << String::format("%x", ebda_seg); mp_floating_pointer = search_floating_pointer_in_ebda(ebda_seg); if (mp_floating_pointer != (uintptr_t) nullptr) @@ -195,12 +195,7 @@ Vector> MultiProcessorParser::get_pci_inter for (auto id : pci_bus_ids) { if (id == v_entry_ptr->source_bus_id) { - kprintf("Interrupts: Bus %d, Polarity 0x%x, Trigger Mode 0x%x, INT %x, IOAPIC %d, IOAPIC INTIN %d\n", v_entry_ptr->source_bus_id, - v_entry_ptr->polarity, - v_entry_ptr->trigger_mode, - v_entry_ptr->source_bus_irq, - v_entry_ptr->destination_ioapic_id, - v_entry_ptr->destination_ioapic_intin_pin); + klog() << "Interrupts: Bus " << v_entry_ptr->source_bus_id << ", Polarity " << v_entry_ptr->polarity << ", Trigger Mode " << v_entry_ptr->trigger_mode << ", INT " << v_entry_ptr->source_bus_irq << ", IOAPIC " << v_entry_ptr->destination_ioapic_id << ", IOAPIC INTIN " << v_entry_ptr->destination_ioapic_intin_pin; overrides.append(adopt(*new PCIInterruptOverrideMetadata( v_entry_ptr->source_bus_id, v_entry_ptr->polarity, @@ -213,14 +208,7 @@ Vector> MultiProcessorParser::get_pci_inter } for (auto override_metadata : overrides) { - kprintf("Interrupts: Bus %d, Polarity 0x%x, PCI Device %d, Trigger Mode 0x%x, INT %x, IOAPIC %d, IOAPIC INTIN %d\n", - override_metadata->bus(), - override_metadata->polarity(), - override_metadata->pci_device_number(), - override_metadata->trigger_mode(), - override_metadata->pci_interrupt_pin(), - override_metadata->ioapic_id(), - override_metadata->ioapic_interrupt_pin()); + klog() << "Interrupts: Bus " << override_metadata->bus() << ", Polarity " << override_metadata->polarity() << ", PCI Device " << override_metadata->pci_device_number() << ", Trigger Mode " << override_metadata->trigger_mode() << ", INT " << override_metadata->pci_interrupt_pin() << ", IOAPIC " << override_metadata->ioapic_id() << ", IOAPIC INTIN " << override_metadata->ioapic_interrupt_pin(); } return overrides; } diff --git a/Kernel/Arch/i386/CPU.cpp b/Kernel/Arch/i386/CPU.cpp index 639b4f1c89..c8cb0cd41b 100644 --- a/Kernel/Arch/i386/CPU.cpp +++ b/Kernel/Arch/i386/CPU.cpp @@ -25,6 +25,7 @@ */ #include +#include #include #include #include @@ -140,13 +141,12 @@ static void dump(const RegisterState& regs) esp = regs.userspace_esp; } - kprintf("exception code: %04x (isr: %04x)\n", regs.exception_code, regs.isr_number); - kprintf(" pc=%04x:%08x flags=%04x\n", (u16)regs.cs, regs.eip, (u16)regs.eflags); - kprintf(" stk=%04x:%08x\n", ss, esp); - kprintf(" ds=%04x es=%04x fs=%04x gs=%04x\n", (u16)regs.ds, (u16)regs.es, (u16)regs.fs, (u16)regs.gs); - kprintf("eax=%08x ebx=%08x ecx=%08x edx=%08x\n", regs.eax, regs.ebx, regs.ecx, regs.edx); - kprintf("ebp=%08x esp=%08x esi=%08x edi=%08x\n", regs.ebp, esp, regs.esi, regs.edi); - + klog() << "exception code: " << String::format("%04x", regs.exception_code) << " (isr: " << String::format("%04x", regs.isr_number); + klog() << " pc=" << String::format("%04x", (u16)regs.cs) << ":" << String::format("%08x", regs.eip) << " flags=" << String::format("%04x", (u16)regs.eflags); + klog() << " stk=" << String::format("%04x", ss) << ":" << String::format("%08x", esp); + klog() << " ds=" << String::format("%04x", (u16)regs.ds) << " es=" << String::format("%04x", (u16)regs.es) << " fs=" << String::format("%04x", (u16)regs.fs) << " gs=" << String::format("%04x", (u16)regs.gs); + klog() << "eax=" << String::format("%08x", regs.eax) << " ebx=" << String::format("%08x", regs.ebx) << " ecx=" << String::format("%08x", regs.ecx) << " edx=" << String::format("%08x", regs.edx); + klog() << "ebp=" << String::format("%08x", regs.ebp) << " esp=" << String::format("%08x", regs.esp) << " esi=" << String::format("%08x", regs.esi) << " edi=" << String::format("%08x", regs.edi); u32 cr0; asm("movl %%cr0, %%eax" : "=a"(cr0)); @@ -157,27 +157,19 @@ static void dump(const RegisterState& regs) u32 cr4; asm("movl %%cr4, %%eax" : "=a"(cr4)); - kprintf("cr0=%08x cr2=%08x cr3=%08x cr4=%08x\n", cr0, cr2, cr3, cr4); + klog() << "cr0=" << String::format("%08x", cr0) << " cr2=" << String::format("%08x", cr2) << " cr3=" << String::format("%08x", cr3) << " cr4=" << String::format("%08x", cr4); if (Process::current && Process::current->validate_read((void*)regs.eip, 8)) { SmapDisabler disabler; u8* codeptr = (u8*)regs.eip; - kprintf("code: %02x %02x %02x %02x %02x %02x %02x %02x\n", - codeptr[0], - codeptr[1], - codeptr[2], - codeptr[3], - codeptr[4], - codeptr[5], - codeptr[6], - codeptr[7]); + klog() << "code: " << String::format("%02x", codeptr[0]) << " " << String::format("%02x", codeptr[1]) << " " << String::format("%02x", codeptr[2]) << " " << String::format("%02x", codeptr[3]) << " " << String::format("%02x", codeptr[4]) << " " << String::format("%02x", codeptr[5]) << " " << String::format("%02x", codeptr[6]) << " " << String::format("%02x", codeptr[7]); } } void handle_crash(RegisterState& regs, const char* description, int signal) { if (!Process::current) { - kprintf("%s with !current\n", description); + klog() << description << " with !current"; hang(); } @@ -185,16 +177,11 @@ void handle_crash(RegisterState& regs, const char* description, int signal) // make sure we switch back to the right page tables. MM.enter_process_paging_scope(*Process::current); - kprintf("\033[31;1mCRASH: %s. %s: %s(%u)\033[0m\n", - description, - Process::current->is_ring0() ? "Kernel" : "Process", - Process::current->name().characters(), - Process::current->pid()); - + klog() << "CRASH: " << description << ". " << (Process::current->is_ring0() ? "Kernel" : "Process") << ": " << Process::current->name().characters() << "(" << Process::current->pid() << ")"; dump(regs); if (Process::current->is_ring0()) { - kprintf("Oh shit, we've crashed in ring 0 :(\n"); + klog() << "Oh shit, we've crashed in ring 0 :("; dump_backtrace(); hang(); } @@ -272,15 +259,7 @@ void page_fault_handler(RegisterState regs) return; } - kprintf("\033[31;1m%s(%u:%u) Unrecoverable page fault, %s%s%s address %p\033[0m\n", - Process::current->name().characters(), - Process::current->pid(), - Thread::current->tid(), - regs.exception_code & PageFaultFlags::ReservedBitViolation ? "reserved bit violation / " : "", - regs.exception_code & PageFaultFlags::InstructionFetch ? "instruction fetch / " : "", - regs.exception_code & PageFaultFlags::Write ? "write to" : "read from", - fault_address); - + klog() << "tid - (" << Thread::current->tid() << ") Unrecoverable page fault, " << (regs.exception_code & PageFaultFlags::ReservedBitViolation ? "reserved bit violation / " : "") << ":" << (regs.exception_code & PageFaultFlags::InstructionFetch ? "instruction fetch / " : "") << ":" << (regs.exception_code & PageFaultFlags::Write ? "write to" : "read from") << " address " << String::format("%p", fault_address); u32 malloc_scrub_pattern = explode_byte(MALLOC_SCRUB_BYTE); u32 free_scrub_pattern = explode_byte(FREE_SCRUB_BYTE); u32 kmalloc_scrub_pattern = explode_byte(KMALLOC_SCRUB_BYTE); @@ -288,19 +267,19 @@ void page_fault_handler(RegisterState regs) u32 slab_alloc_scrub_pattern = explode_byte(SLAB_ALLOC_SCRUB_BYTE); u32 slab_dealloc_scrub_pattern = explode_byte(SLAB_DEALLOC_SCRUB_BYTE); if ((fault_address & 0xffff0000) == (malloc_scrub_pattern & 0xffff0000)) { - kprintf("\033[33;1mNote: Address %p looks like it may be uninitialized malloc() memory\033[0m\n", fault_address); + klog() << "Note: Address " << String::format("%p", fault_address) << " looks like it may be uninitialized malloc() memory"; } else if ((fault_address & 0xffff0000) == (free_scrub_pattern & 0xffff0000)) { - kprintf("\033[33;1mNote: Address %p looks like it may be recently free()'d memory\033[0m\n", fault_address); + klog() << "Note: Address " << String::format("%p", fault_address) << " looks like it may be recently free()'d memory"; } else if ((fault_address & 0xffff0000) == (kmalloc_scrub_pattern & 0xffff0000)) { - kprintf("\033[33;1mNote: Address %p looks like it may be uninitialized kmalloc() memory\033[0m\n", fault_address); + klog() << "Note: Address " << String::format("%p", fault_address) << " looks like it may be uninitialized kmalloc() memory"; } else if ((fault_address & 0xffff0000) == (kfree_scrub_pattern & 0xffff0000)) { - kprintf("\033[33;1mNote: Address %p looks like it may be recently kfree()'d memory\033[0m\n", fault_address); + klog() << "Note: Address " << String::format("%p", fault_address) << " looks like it may be recently kfree()'d memory"; } else if ((fault_address & 0xffff0000) == (slab_alloc_scrub_pattern & 0xffff0000)) { - kprintf("\033[33;1mNote: Address %p looks like it may be uninitialized slab_alloc() memory\033[0m\n", fault_address); + klog() << "Note: Address " << String::format("%p", fault_address) << " looks like it may be uninitialized slab_alloc() memory"; } else if ((fault_address & 0xffff0000) == (slab_dealloc_scrub_pattern & 0xffff0000)) { - kprintf("\033[33;1mNote: Address %p looks like it may be recently slab_dealloc()'d memory\033[0m\n", fault_address); + klog() << "Note: Address " << String::format("%p", fault_address) << " looks like it may be recently slab_dealloc()'d memory"; } else if (fault_address < 4096) { - kprintf("\033[33;1mNote: Address %p looks like a possible nullptr dereference\033[0m\n", fault_address); + klog() << "Note: Address " << String::format("%p", fault_address) << " looks like a possible nullptr dereference"; } handle_crash(regs, "Page Fault", SIGSEGV); @@ -313,21 +292,21 @@ void page_fault_handler(RegisterState regs) } } -#define EH(i, msg) \ - static void _exception##i() \ - { \ - kprintf(msg "\n"); \ - u32 cr0, cr2, cr3, cr4; \ - asm("movl %%cr0, %%eax" \ - : "=a"(cr0)); \ - asm("movl %%cr2, %%eax" \ - : "=a"(cr2)); \ - asm("movl %%cr3, %%eax" \ - : "=a"(cr3)); \ - asm("movl %%cr4, %%eax" \ - : "=a"(cr4)); \ - kprintf("CR0=%x CR2=%x CR3=%x CR4=%x\n", cr0, cr2, cr3, cr4); \ - hang(); \ +#define EH(i, msg) \ + static void _exception##i() \ + { \ + klog() << msg; \ + u32 cr0, cr2, cr3, cr4; \ + asm("movl %%cr0, %%eax" \ + : "=a"(cr0)); \ + asm("movl %%cr2, %%eax" \ + : "=a"(cr2)); \ + asm("movl %%cr3, %%eax" \ + : "=a"(cr3)); \ + asm("movl %%cr4, %%eax" \ + : "=a"(cr4)); \ + klog() << "CR0=" << String::format("%x", cr0) << " CR2=" << String::format("%x", cr2) << " CR3=" << String::format("%x", cr3) << " CR4=" << String::format("%x", cr4); \ + hang(); \ } EH(1, "Debug exception") @@ -409,7 +388,7 @@ void gdt_init() static void unimp_trap() { - kprintf("Unhandled IRQ."); + klog() << "Unhandled IRQ."; hang(); } @@ -735,7 +714,7 @@ void cpu_setup() if (g_cpu_supports_sse) { sse_init(); - kprintf("x86: SSE support enabled\n"); + klog() << "x86: SSE support enabled"; } asm volatile( @@ -743,7 +722,7 @@ void cpu_setup() "orl $0x00010000, %%eax\n" "movl %%eax, %%cr0\n" :: : "%eax", "memory"); - kprintf("x86: WP support enabled\n"); + klog() << "x86: WP support enabled"; if (g_cpu_supports_pge) { // Turn on CR4.PGE so the CPU will respect the G bit in page tables. @@ -751,9 +730,9 @@ void cpu_setup() "mov %cr4, %eax\n" "orl $0x80, %eax\n" "mov %eax, %cr4\n"); - kprintf("x86: PGE support enabled\n"); + klog() << "x86: PGE support enabled"; } else { - kprintf("x86: PGE support not detected\n"); + klog() << "x86: PGE support not detected"; } if (g_cpu_supports_nx) { @@ -763,9 +742,9 @@ void cpu_setup() "rdmsr\n" "orl $0x800, %eax\n" "wrmsr\n"); - kprintf("x86: NX support enabled\n"); + klog() << "x86: NX support enabled"; } else { - kprintf("x86: NX support not detected\n"); + klog() << "x86: NX support not detected"; } if (g_cpu_supports_smep) { @@ -774,21 +753,21 @@ void cpu_setup() "mov %cr4, %eax\n" "orl $0x100000, %eax\n" "mov %eax, %cr4\n"); - kprintf("x86: SMEP support enabled\n"); + klog() << "x86: SMEP support enabled"; } else { - kprintf("x86: SMEP support not detected\n"); + klog() << "x86: SMEP support not detected"; } if (g_cpu_supports_smap) { // Turn on CR4.SMAP - kprintf("x86: Enabling SMAP\n"); + klog() << "x86: Enabling SMAP"; asm volatile( "mov %cr4, %eax\n" "orl $0x200000, %eax\n" "mov %eax, %cr4\n"); - kprintf("x86: SMAP support enabled\n"); + klog() << "x86: SMAP support enabled"; } else { - kprintf("x86: SMAP support not detected\n"); + klog() << "x86: SMAP support not detected"; } if (g_cpu_supports_umip) { @@ -796,7 +775,7 @@ void cpu_setup() "mov %cr4, %eax\n" "orl $0x800, %eax\n" "mov %eax, %cr4\n"); - kprintf("x86: UMIP support enabled\n"); + klog() << "x86: UMIP support enabled"; } if (g_cpu_supports_tsc) { @@ -804,13 +783,13 @@ void cpu_setup() "mov %cr4, %eax\n" "orl $0x4, %eax\n" "mov %eax, %cr4\n"); - kprintf("x86: RDTSC support restricted\n"); + klog() << "x86: RDTSC support restricted"; } if (g_cpu_supports_rdrand) { - kprintf("x86: Using RDRAND for good randomness\n"); + klog() << "x86: Using RDRAND for good randomness"; } else { - kprintf("x86: No RDRAND support detected. Randomness will be shitty\n"); + klog() << "x86: No RDRAND support detected. Randomness will be shitty"; } } @@ -834,7 +813,8 @@ void write_cr3(u32 cr3) void __assertion_failed(const char* msg, const char* file, unsigned line, const char* func) { asm volatile("cli"); - kprintf("ASSERTION FAILED: %s\n%s:%u in %s\n", msg, file, line, func); + klog() << "ASSERTION FAILED: " << msg << "\n" + << file << ":" << line << " in " << func; // Switch back to the current process's page tables if there are any. // Otherwise stack walking will be a disaster. diff --git a/Kernel/Devices/BXVGADevice.cpp b/Kernel/Devices/BXVGADevice.cpp index 807456b21e..5ace534de3 100644 --- a/Kernel/Devices/BXVGADevice.cpp +++ b/Kernel/Devices/BXVGADevice.cpp @@ -160,7 +160,7 @@ u32 BXVGADevice::find_framebuffer_address() PCI::enumerate_all([&framebuffer_address](const PCI::Address& address, PCI::ID id) { if (id == bochs_vga_id || id == virtualbox_vga_id) { framebuffer_address = PCI::get_BAR0(address) & 0xfffffff0; - kprintf("BXVGA: framebuffer @ P%x\n", framebuffer_address); + klog() << "BXVGA: framebuffer @ P " << String::format("%p", framebuffer_address); } }); return framebuffer_address; diff --git a/Kernel/Devices/DiskPartition.cpp b/Kernel/Devices/DiskPartition.cpp index bf0d6e4318..ac6504dad9 100644 --- a/Kernel/Devices/DiskPartition.cpp +++ b/Kernel/Devices/DiskPartition.cpp @@ -50,7 +50,7 @@ DiskPartition::~DiskPartition() bool DiskPartition::read_blocks(unsigned index, u16 count, u8* out) { #ifdef OFFD_DEBUG - kprintf("DiskPartition::read_blocks %u (really: %u) count=%u\n", index, m_block_offset + index, count); + klog() << "DiskPartition::read_blocks " << index << " (really: " << (m_block_offset + index) << ") count=" << count; #endif return m_device->read_blocks(m_block_offset + index, count, out); @@ -59,7 +59,7 @@ bool DiskPartition::read_blocks(unsigned index, u16 count, u8* out) bool DiskPartition::write_blocks(unsigned index, u16 count, const u8* data) { #ifdef OFFD_DEBUG - kprintf("DiskPartition::write_blocks %u (really: %u) count=%u\n", index, m_block_offset + index, count); + klog() << "DiskPartition::write_blocks " << index << " (really: " << (m_block_offset + index) << ") count=" << count; #endif return m_device->write_blocks(m_block_offset + index, count, data); diff --git a/Kernel/Devices/EBRPartitionTable.cpp b/Kernel/Devices/EBRPartitionTable.cpp index fa672f222d..d10d3bfa85 100644 --- a/Kernel/Devices/EBRPartitionTable.cpp +++ b/Kernel/Devices/EBRPartitionTable.cpp @@ -69,11 +69,11 @@ bool EBRPartitionTable::initialize() m_ebr_container_id = index_of_ebr_container() + 1; #ifdef EBR_DEBUG - kprintf("EBRPartitionTable::initialize: MBR_signature=%#x\n", header.mbr_signature); + klog() << "EBRPartitionTable::initialize: MBR_signature=0x" << String::format("%x", header.mbr_signature); #endif if (header.mbr_signature != MBR_SIGNATURE) { - kprintf("EBRPartitionTable::initialize: bad MBR signature %#x\n", header.mbr_signature); + klog() << "EBRPartitionTable::initialize: bad MBR signature 0x" << String::format("%x", header.mbr_signature); return false; } @@ -94,7 +94,7 @@ bool EBRPartitionTable::initialize() m_ebr_chained_extensions_count = index; - kprintf("EBRPartitionTable::initialize: Extended partitions count - %d\n", m_ebr_chained_extensions_count); + klog() << "EBRPartitionTable::initialize: Extended partitions count - " << m_ebr_chained_extensions_count; return true; } @@ -105,19 +105,19 @@ RefPtr EBRPartitionTable::get_non_extended_partition(unsigned ind auto& entry = header.entry[index - 1]; #ifdef EBR_DEBUG - kprintf("EBRPartitionTable::partition: status=%#x offset=%#x\n", entry.status, entry.offset); + klog() << "EBRPartitionTable::partition: status=0x" << String::format("%x", entry.status) << " offset=0x" << String::format("%x", entry.offset); #endif if (entry.offset == 0x00) { #ifdef EBR_DEBUG - kprintf("EBRPartitionTable::partition: missing partition requested index=%d\n", index); + klog() << "EBRPartitionTable::partition: missing partition requested index=" << index; #endif return nullptr; } #ifdef EBR_DEBUG - kprintf("EBRPartitionTable::partition: found partition index=%d type=%x\n", index, entry.type); + klog() << "EBRPartitionTable::partition: found partition index=" << index << " type=" << String::format("%x", entry.type); #endif return DiskPartition::create(m_device, entry.offset, (entry.offset + entry.length)); @@ -130,12 +130,12 @@ RefPtr EBRPartitionTable::get_extended_partition(unsigned index) auto& header = this->header(); #ifdef EBR_DEBUG - kprintf("EBRPartitionTable::partition: relative index %d\n", relative_index); + klog() << "EBRPartitionTable::partition: relative index " << relative_index; #endif auto& ebr_entry = header.entry[m_ebr_container_id - 1]; #ifdef EBR_DEBUG - kprintf("EBRPartitionTable::partition: Extended partition, offset 0x%x, type %x\n", ebr_entry.offset, ebr_entry.type); + klog() << "EBRPartitionTable::partition: Extended partition, offset 0x" << String::format("%x", ebr_entry.offset) << ", type " << String::format("%x", ebr_entry.type); #endif if (!m_device->read_block(ebr_entry.offset, m_cached_ebr_header)) { @@ -144,8 +144,8 @@ RefPtr EBRPartitionTable::get_extended_partition(unsigned index) size_t i = 0; while (i < relative_index) { #ifdef EBR_DEBUG - kprintf("EBRPartitionTable::partition: logical partition, relative offset 0x%x, type %x\n", ebr_extension().entry.offset, ebr_extension().entry.type); - kprintf("EBRPartitionTable::partition: next logical partition, relative offset 0x%x, type %x\n", ebr_extension().next_chained_ebr_extension.offset, ebr_extension().next_chained_ebr_extension.type); + klog() << "EBRPartitionTable::partition: logical partition, relative offset 0x" << String::format("%x", ebr_extension().entry.offset) << ", type " << String::format("%x", ebr_extension().entry.type); + klog() << "EBRPartitionTable::partition: next logical partition, relative offset 0x" << String::format("%x", ebr_extension().next_chained_ebr_extension.offset) << ", type " << String::format("%x", ebr_extension().next_chained_ebr_extension.type); #endif if (ebr_extension().next_chained_ebr_extension.offset == 0 && ebr_extension().next_chained_ebr_extension.type == 0) { break; @@ -158,19 +158,19 @@ RefPtr EBRPartitionTable::get_extended_partition(unsigned index) } #ifdef EBR_DEBUG - kprintf("EBRPartitionTable::partition: status=%#x offset=%#x\n", ebr_extension().entry.status, ebr_extension().entry.offset + ebr_entry.offset); + klog() << "EBRPartitionTable::partition: status=" << String::format("%x", ebr_extension().entry.status) << " offset=" << String::format("%x", ebr_extension().entry.offset + ebr_entry.offset); #endif if (ebr_extension().entry.offset == 0x00) { #ifdef EBR_DEBUG - kprintf("EBRPartitionTable::partition: missing partition requested index=%d\n", index); + klog() << "EBRPartitionTable::partition: missing partition requested index=" << index; #endif return nullptr; } #ifdef EBR_DEBUG - kprintf("EBRPartitionTable::partition: found partition index=%d type=%x\n", index, ebr_extension().entry.type); + klog() << "EBRPartitionTable::partition: found partition index=" << index << " type=" << String::format("%x", ebr_extension().entry.type); #endif return DiskPartition::create(m_device, ebr_extension().entry.offset + ebr_entry.offset, (ebr_extension().entry.offset + ebr_entry.offset + ebr_extension().entry.length)); @@ -187,7 +187,7 @@ RefPtr EBRPartitionTable::partition(unsigned index) auto& header = this->header(); if (header.mbr_signature != MBR_SIGNATURE) { - kprintf("EBRPartitionTable::initialize: bad MBR signature - not initalized? %#x\n", header.mbr_signature); + klog() << "EBRPartitionTable::initialize: bad MBR signature - not initalized? 0x" << String::format("%x", header.mbr_signature); return nullptr; } if (index_is_extended_partition(index)) diff --git a/Kernel/Devices/FloppyDiskDevice.cpp b/Kernel/Devices/FloppyDiskDevice.cpp index 9be3858530..dfe1f8cdaa 100644 --- a/Kernel/Devices/FloppyDiskDevice.cpp +++ b/Kernel/Devices/FloppyDiskDevice.cpp @@ -134,7 +134,7 @@ bool FloppyDiskDevice::read_sectors_with_dma(u16 lba, u16 count, u8* outbuf) { LOCKER(m_lock); // Acquire lock #ifdef FLOPPY_DEBUG - kprintf("fdc: read_sectors_with_dma lba = %d count = %d\n", lba, count); + klog() << "fdc: read_sectors_with_dma lba = " << lba << " count = " << count; #endif motor_enable(is_slave()); // Should I bother casting this?! @@ -142,7 +142,7 @@ bool FloppyDiskDevice::read_sectors_with_dma(u16 lba, u16 count, u8* outbuf) recalibrate(); if (!seek(lba)) { - kprintf("fdc: failed to seek to lba = %d!\n", lba); + klog() << "fdc: failed to seek to lba = " << lba << "!"; return false; } @@ -168,7 +168,7 @@ bool FloppyDiskDevice::read_sectors_with_dma(u16 lba, u16 count, u8* outbuf) u16 sector = lba2sector(lba); #ifdef FLOPPY_DEBUG - kprintf("fdc: addr = 0x%x c = %d h = %d s = %d\n", lba * BYTES_PER_SECTOR, cylinder, head, sector); + klog() << "fdc: addr = 0x" << String::format("%x", lba * BYTES_PER_SECTOR) << " c = " << cylinder << " h = " << head << " s = " << sector; #endif // Intel recommends 3 attempts for a read/write @@ -194,13 +194,13 @@ bool FloppyDiskDevice::read_sectors_with_dma(u16 lba, u16 count, u8* outbuf) // the command executed correctly u8 cmd_st0 = read_byte(); if ((cmd_st0 & 0xc0) != 0) { - kprintf("fdc: read failed with error code (st0) 0x%x\n", cmd_st0 >> 6); + klog() << "fdc: read failed with error code (st0) 0x" << String::format("%x", cmd_st0 >> 6); return false; } u8 cmd_st1 = read_byte(); if (cmd_st1 != 0) { - kprintf("fdc: read failed with error code (st1) 0x%x\n", cmd_st1); + klog() << "fdc: read failed with error code (st1) 0x" << String::format("%x", cmd_st1); return false; } @@ -212,7 +212,7 @@ bool FloppyDiskDevice::read_sectors_with_dma(u16 lba, u16 count, u8* outbuf) if (cyl != cylinder) { #ifdef FLOPPY_DEBUG - kprintf("fdc: cyl != cylinder (cyl = %d cylinder = %d)! Retrying...\n", cyl, cylinder); + klog() << "fdc: cyl != cylinder (cyl = " << cyl << " cylinder = " << cylinder << ")! Retrying..."; #endif continue; } @@ -230,7 +230,7 @@ bool FloppyDiskDevice::read_sectors_with_dma(u16 lba, u16 count, u8* outbuf) } #ifdef FLOPPY_DEBUG - kprintf("fdc: out of read attempts (check your hardware maybe!?)\n"); + klog() << "fdc: out of read attempts (check your hardware maybe!?)"; #endif return false; } @@ -239,7 +239,7 @@ bool FloppyDiskDevice::write_sectors_with_dma(u16 lba, u16 count, const u8* inbu { LOCKER(m_lock); // Acquire lock #ifdef FLOPPY_DEBUG - kprintf("fdc: write_sectors_with_dma lba = %d count = %d\n", lba, count); + klog() << "fdc: write_sectors_with_dma lba = " << lba << " count = " << count; #endif motor_enable(is_slave() ? 1 : 0); // Should I bother casting this?! @@ -247,7 +247,7 @@ bool FloppyDiskDevice::write_sectors_with_dma(u16 lba, u16 count, const u8* inbu recalibrate(); // Recalibrate the drive if (!seek(lba)) { - kprintf("fdc: failed to seek to lba = %d!\n", lba); + klog() << "fdc: failed to seek to lba = " << lba << "!"; return false; } @@ -269,7 +269,7 @@ bool FloppyDiskDevice::write_sectors_with_dma(u16 lba, u16 count, const u8* inbu u16 sector = lba2sector(lba); #ifdef FLOPPY_DEBUG - kprintf("fdc: addr = 0x%x c = %d h = %d s = %d\n", lba * BYTES_PER_SECTOR, cylinder, head, sector); + klog() << "fdc: addr = 0x" << String::format("%x", lba * BYTES_PER_SECTOR) << " c = " << cylinder << " h = " << head << " s = " << sector; #endif for (int i = 0; i < 3; i++) { @@ -292,13 +292,13 @@ bool FloppyDiskDevice::write_sectors_with_dma(u16 lba, u16 count, const u8* inbu // Flush FIFO u8 cmd_st0 = read_byte(); if ((cmd_st0 & 0xc0) != 0) { - kprintf("fdc: write failed! Error code 0x%x\n", cmd_st0 >> 6); + klog() << "fdc: write failed! Error code 0x" << String::format("%x", cmd_st0 >> 6); return false; } u8 cmd_st1 = read_byte(); if (cmd_st1 != 0) { - kprintf("fdc: write failed with error code (st1) 0x%x\n", cmd_st1); + klog() << "fdc: write failed with error code (st1) 0x" << String::format("%x", cmd_st1); return false; } @@ -310,7 +310,7 @@ bool FloppyDiskDevice::write_sectors_with_dma(u16 lba, u16 count, const u8* inbu if (cyl != cylinder) { #ifdef FLOPPY_DEBUG - kprintf("fdc: cyl != cylinder (cyl = %d cylinder = %d)! Retrying...\n", cyl, cylinder); + klog() << "fdc: cyl != cylinder (cyl = " << cyl << " cylinder = " << cylinder << ")! Retrying..."; #endif continue; } @@ -328,7 +328,7 @@ bool FloppyDiskDevice::write_sectors_with_dma(u16 lba, u16 count, const u8* inbu } #ifdef FLOPPY_DEBUG - kprintf("fdc: out of read attempts (check your hardware maybe!?)\n"); + klog() << "fdc: out of read attempts (check your hardware maybe!?)"; #endif return false; } @@ -336,7 +336,7 @@ bool FloppyDiskDevice::write_sectors_with_dma(u16 lba, u16 count, const u8* inbu bool FloppyDiskDevice::wait_for_irq() { #ifdef FLOPPY_DEBUG - kprintf("fdc: Waiting for interrupt...\n"); + klog() << "fdc: Waiting for interrupt..."; #endif while (!m_interrupted) { @@ -353,7 +353,7 @@ void FloppyDiskDevice::handle_irq(RegisterState&) m_interrupted = true; #ifdef FLOPPY_DEBUG - kprintf("fdc: Received IRQ!\n"); + klog() << "fdc: Received IRQ!"; #endif } @@ -367,7 +367,7 @@ void FloppyDiskDevice::send_byte(u8 value) const } #ifdef FLOPPY_DEBUG - kprintf("fdc: FIFO write timed out!\n"); + klog() << "fdc: FIFO write timed out!"; #endif } @@ -381,7 +381,7 @@ void FloppyDiskDevice::send_byte(FloppyCommand value) const } #ifdef FLOPPY_DEBUG - kprintf("fdc: FIFO write timed out!\n"); + klog() << "fdc: FIFO write timed out!"; #endif } @@ -394,7 +394,7 @@ u8 FloppyDiskDevice::read_byte() const } #ifdef FLOPPY_DEBUG - kprintf("fdc: FIFO read timed out!\n"); + klog() << "fdc: FIFO read timed out!"; #endif return 0xff; @@ -429,7 +429,7 @@ bool FloppyDiskDevice::is_busy() const bool FloppyDiskDevice::recalibrate() { #ifdef FLOPPY_DEBUG - kprintf("fdc: recalibrating drive...\n"); + klog() << "fdc: recalibrating drive..."; #endif u8 slave = is_slave(); @@ -451,7 +451,7 @@ bool FloppyDiskDevice::recalibrate() } #ifdef FLOPPY_DEBUG - kprintf("fdc: failed to calibrate drive (check your hardware!)\n"); + klog() << "fdc: failed to calibrate drive (check your hardware!)"; #endif return false; } @@ -465,7 +465,7 @@ bool FloppyDiskDevice::seek(u16 lba) // First, we need to enable the correct drive motor motor_enable(slave); #ifdef FLOPPY_DEBUG - kprintf("fdc: seeking to cylinder %d on side %d on drive %d\n", cylinder, head, slave); + klog() << "fdc: seeking to cylinder " << cylinder << " on side " << head << " on drive " << slave; #endif // Try at most 5 times to seek to the desired cylinder @@ -482,7 +482,7 @@ bool FloppyDiskDevice::seek(u16 lba) if ((st0 >> 5) != 1 || pcn != cylinder || (st0 & 0x01)) { #ifdef FLOPPY_DEBUG - kprintf("fdc: failed to seek to cylinder %d on attempt %d!\n", cylinder, attempt); + klog() << "fdc: failed to seek to cylinder " << cylinder << " on attempt " << attempt << "!"; #endif continue; } @@ -490,7 +490,7 @@ bool FloppyDiskDevice::seek(u16 lba) return true; } - kprintf("fdc: failed to seek after 3 attempts! Aborting...\n"); + klog() << "fdc: failed to seek after 3 attempts! Aborting..."; return false; } @@ -498,7 +498,7 @@ bool FloppyDiskDevice::seek(u16 lba) void FloppyDiskDevice::initialize() { #ifdef FLOPPY_DEBUG - kprintf("fdc: m_io_base = 0x%x IRQn = %d\n", m_io_base_addr, IRQ_FLOPPY_DRIVE); + klog() << "fdc: m_io_base = 0x" << String::format("%x", m_io_base_addr) << " IRQn = " << IRQ_FLOPPY_DRIVE; #endif enable_irq(); @@ -506,7 +506,7 @@ void FloppyDiskDevice::initialize() // Get the version of the Floppy Disk Controller send_byte(FloppyCommand::Version); m_controller_version = read_byte(); - kprintf("fdc: Version = 0x%x\n", m_controller_version); + klog() << "fdc: Version = 0x" << String::format("%x", m_controller_version); // Reset write_dor(0); @@ -523,7 +523,7 @@ void FloppyDiskDevice::initialize() u8 sr0 = read_byte(); u8 trk = read_byte(); - kprintf("sr0 = 0x%x, cyl = 0x%x\n", sr0, trk); + klog() << "sr0 = 0x" << String::format("%x", sr0) << ", cyl = 0x" << String::format("%x", trk); } // This is hardcoded for a 3.5" floppy disk drive @@ -534,7 +534,7 @@ void FloppyDiskDevice::initialize() // Allocate a buffer page for us to read into. This only needs to be one sector in size. m_dma_buffer_page = MM.allocate_supervisor_physical_page(); #ifdef FLOPPY_DEBUG - kprintf("fdc: allocated supervisor page at paddr 0x%x\n", m_dma_buffer_page->paddr()); + klog() << "fdc: allocated supervisor page at paddr 0x", String::format("%x", m_dma_buffer_page->paddr()); #endif // Now, let's initialise channel 2 of the DMA controller! @@ -557,7 +557,7 @@ void FloppyDiskDevice::initialize() IO::out8(0xA, 0x2); // Unmask Channel 2 #ifdef FLOPPY_DEBUG - kprintf("fdc: fd%d initialised succesfully!\n", is_slave() ? 1 : 0); + klog() << "fdc: fd" << (is_slave() ? 1 : 0) << " initialised succesfully!"; #endif } diff --git a/Kernel/Devices/GPTPartitionTable.cpp b/Kernel/Devices/GPTPartitionTable.cpp index 12a2698240..f0701701ed 100644 --- a/Kernel/Devices/GPTPartitionTable.cpp +++ b/Kernel/Devices/GPTPartitionTable.cpp @@ -54,11 +54,11 @@ bool GPTPartitionTable::initialize() auto& header = this->header(); #ifdef GPT_DEBUG - kprintf("GPTPartitionTable::initialize: gpt_signature=%#x%x\n", header.sig[1], header.sig[0]); + klog() << "GPTPartitionTable::initialize: gpt_signature=0x" << String::format("%x", header.sig[1]) << String::format("%x", header.sig[0]); #endif if (header.sig[0] != GPT_SIGNATURE && header.sig[1] != GPT_SIGNATURE2) { - kprintf("GPTPartitionTable::initialize: bad GPT signature %#x%x\n", header.sig[1], header.sig[0]); + klog() << "GPTPartitionTable::initialize: bad GPT signature 0x" << String::format("%x", header.sig[1]) << String::format("%x", header.sig[0]); return false; } @@ -73,7 +73,7 @@ RefPtr GPTPartitionTable::partition(unsigned index) unsigned lba = header.partition_array_start_lba + (((index - 1) * header.partition_entry_size) / BytesPerSector); if (header.sig[0] != GPT_SIGNATURE) { - kprintf("GPTPartitionTable::initialize: bad gpt signature - not initalized? %#x\n", header.sig); + klog() << "GPTPartitionTable::initialize: bad gpt signature - not initalized? 0x" << String::format("%x", header.sig); return nullptr; } @@ -84,20 +84,20 @@ RefPtr GPTPartitionTable::partition(unsigned index) GPTPartitionEntry& entry = entries[((index - 1) % entries_per_sector)]; #ifdef GPT_DEBUG - kprintf("GPTPartitionTable::partition %d\n", index); - kprintf("GPTPartitionTable - offset = %d%d\n", entry.first_lba[1], entry.first_lba[0]); + klog() << "GPTPartitionTable::partition " << index; + klog() << "GPTPartitionTable - offset = " << entry.first_lba[1] << entry.first_lba[0]; #endif if (entry.first_lba[0] == 0x00) { #ifdef GPT_DEBUG - kprintf("GPTPartitionTable::partition: missing partition requested index=%d\n", index); + klog() << "GPTPartitionTable::partition: missing partition requested index=" << index; #endif return nullptr; } #ifdef GPT_DEBUG - kprintf("GPTPartitionTable::partition: found partition index=%d type=%x-%x-%x-%x\n", index, entry.partition_guid[3], entry.partition_guid[2], entry.partition_guid[1], entry.partition_guid[0]); + klog() << "GPTPartitionTable::partition: found partition index=" << index << " type=" << String::format("%x", entry.partition_guid[3]) << "-" << String::format("%x", entry.partition_guid[2]) << "-" << String::format("%x", entry.partition_guid[1]) << "-" << String::format("%x", entry.partition_guid[0]); #endif return DiskPartition::create(m_device, entry.first_lba[0], entry.last_lba[0]); } diff --git a/Kernel/Devices/MBRPartitionTable.cpp b/Kernel/Devices/MBRPartitionTable.cpp index ea8e1e6231..bd9baa38a6 100644 --- a/Kernel/Devices/MBRPartitionTable.cpp +++ b/Kernel/Devices/MBRPartitionTable.cpp @@ -54,11 +54,11 @@ bool MBRPartitionTable::initialize() auto& header = this->header(); #ifdef MBR_DEBUG - kprintf("MBRPartitionTable::initialize: mbr_signature=%#x\n", header.mbr_signature); + klog() << "MBRPartitionTable::initialize: mbr_signature=0x" << String::format("%x", header.mbr_signature); #endif if (header.mbr_signature != MBR_SIGNATURE) { - kprintf("MBRPartitionTable::initialize: bad mbr signature %#x\n", header.mbr_signature); + klog() << "MBRPartitionTable::initialize: bad mbr signature 0x" << String::format("%x", header.mbr_signature); return false; } @@ -87,24 +87,24 @@ RefPtr MBRPartitionTable::partition(unsigned index) auto& entry = header.entry[index - 1]; if (header.mbr_signature != MBR_SIGNATURE) { - kprintf("MBRPartitionTable::initialize: bad mbr signature - not initalized? %#x\n", header.mbr_signature); + klog() << "MBRPartitionTable::initialize: bad mbr signature - not initalized? 0x" << String::format("%x", header.mbr_signature); return nullptr; } #ifdef MBR_DEBUG - kprintf("MBRPartitionTable::partition: status=%#x offset=%#x\n", entry.status, entry.offset); + klog() << "MBRPartitionTable::partition: status=0x" << String::format("%x", entry.status) << " offset=0x" << String::format("%x", entry.offset); #endif if (entry.offset == 0x00) { #ifdef MBR_DEBUG - kprintf("MBRPartitionTable::partition: missing partition requested index=%d\n", index); + klog() << "MBRPartitionTable::partition: missing partition requested index=" << index; #endif return nullptr; } #ifdef MBR_DEBUG - kprintf("MBRPartitionTable::partition: found partition index=%d type=%x\n", index, entry.type); + klog() << "MBRPartitionTable::partition: found partition index=" << index << " type=" << String::format("%x", entry.type); #endif return DiskPartition::create(m_device, entry.offset, (entry.offset + entry.length)); diff --git a/Kernel/Devices/PATAChannel.cpp b/Kernel/Devices/PATAChannel.cpp index 771c0b3ba8..2ddf05212a 100644 --- a/Kernel/Devices/PATAChannel.cpp +++ b/Kernel/Devices/PATAChannel.cpp @@ -261,7 +261,7 @@ bool PATAChannel::ata_read_sectors_with_dma(u32 lba, u16 count, u8* outbuf, bool { LOCKER(s_lock()); #ifdef PATA_DEBUG - dbg() << Process::current->name().characters() << "(" << Process::current->pid() << "): PATAChannel::ata_read_sectors_with_dma (" << lba << " x" << count << ") -> " << outbuf; + dbg() << "PATAChannel::ata_read_sectors_with_dma (" << lba << " x" << count << ") -> " << outbuf; #endif prdt().offset = m_dma_buffer_page->paddr(); @@ -332,7 +332,7 @@ bool PATAChannel::ata_write_sectors_with_dma(u32 lba, u16 count, const u8* inbuf { LOCKER(s_lock()); #ifdef PATA_DEBUG - dbg() << Process::current->name().characters() << "(" << Process::current->pid() << "): PATAChannel::ata_write_sectors_with_dma (" << lba << " x" << count << ") <- " << inbuf; + dbg() << "PATAChannel::ata_write_sectors_with_dma (" << lba << " x" << count << ") <- " << inbuf; #endif prdt().offset = m_dma_buffer_page->paddr(); @@ -401,7 +401,7 @@ bool PATAChannel::ata_read_sectors(u32 start_sector, u16 count, u8* outbuf, bool ASSERT(count <= 256); LOCKER(s_lock()); #ifdef PATA_DEBUG - dbg() << Process::current->name().characters() << "(" << Process::current->pid() << "): PATAChannel::ata_read_sectors request (" << count << " sector(s) @ " << start_sector << " into " << outbuf << ")"; + dbg() << "PATAChannel::ata_read_sectors request (" << count << " sector(s) @ " << start_sector << " into " << outbuf << ")"; #endif while (m_io_base.offset(ATA_REG_STATUS).in() & ATA_SR_BSY) diff --git a/Kernel/Devices/PIT.cpp b/Kernel/Devices/PIT.cpp index 9fa2e7a190..e6e6ed6dda 100644 --- a/Kernel/Devices/PIT.cpp +++ b/Kernel/Devices/PIT.cpp @@ -84,7 +84,7 @@ PIT::PIT() IO::out8(PIT_CTL, TIMER0_SELECT | WRITE_WORD | MODE_SQUARE_WAVE); - kprintf("PIT: %u Hz, square wave (%x)\n", TICKS_PER_SECOND, m_default_timer_reload); + klog() << "PIT: " << TICKS_PER_SECOND << " Hz, square wave (" << String::format("%x", m_default_timer_reload) << ")"; IO::out8(TIMER0_CTL, LSB(m_default_timer_reload)); IO::out8(TIMER0_CTL, MSB(m_default_timer_reload)); diff --git a/Kernel/Devices/PS2MouseDevice.cpp b/Kernel/Devices/PS2MouseDevice.cpp index 8248d4bcc4..946e62f172 100644 --- a/Kernel/Devices/PS2MouseDevice.cpp +++ b/Kernel/Devices/PS2MouseDevice.cpp @@ -246,7 +246,7 @@ void PS2MouseDevice::check_device_presence() u8 maybe_ack = mouse_read(); if (maybe_ack == I8042_ACK) { m_device_present = true; - kprintf("PS2MouseDevice: Device detected\n"); + klog() << "PS2MouseDevice: Device detected"; // the mouse will send a packet of data, since that's what we asked // for. we don't care about the content. @@ -255,7 +255,7 @@ void PS2MouseDevice::check_device_presence() mouse_read(); } else { m_device_present = false; - kprintf("PS2MouseDevice: Device not detected\n"); + klog() << "PS2MouseDevice: Device not detected"; } } @@ -307,9 +307,9 @@ void PS2MouseDevice::initialize_device() if (device_id == PS2MOUSE_INTELLIMOUSE_ID) { m_has_wheel = true; - kprintf("PS2MouseDevice: Mouse wheel enabled!\n"); + klog() << "PS2MouseDevice: Mouse wheel enabled!"; } else { - kprintf("PS2MouseDevice: No mouse wheel detected!\n"); + klog() << "PS2MouseDevice: No mouse wheel detected!"; } enable_irq(); diff --git a/Kernel/Devices/SB16.cpp b/Kernel/Devices/SB16.cpp index 5d30d817e2..b18a862212 100644 --- a/Kernel/Devices/SB16.cpp +++ b/Kernel/Devices/SB16.cpp @@ -103,7 +103,7 @@ void SB16::initialize() auto data = dsp_read(); if (data != 0xaa) { - kprintf("SB16: sb not ready"); + klog() << "SB16: sb not ready"; return; } @@ -112,9 +112,9 @@ void SB16::initialize() m_major_version = dsp_read(); auto vmin = dsp_read(); - kprintf("SB16: found version %d.%d\n", m_major_version, vmin); + klog() << "SB16: found version " << m_major_version << "." << vmin; set_irq_register(SB16_DEFAULT_IRQ); - kprintf("SB16: IRQ %d\n", get_irq_line()); + klog() << "SB16: IRQ " << get_irq_line(); } void SB16::set_irq_register(u8 irq_number) @@ -235,7 +235,7 @@ ssize_t SB16::write(FileDescription&, const u8* data, ssize_t length) } #ifdef SB16_DEBUG - kprintf("SB16: Writing buffer of %d bytes\n", length); + klog() << "SB16: Writing buffer of " << length << " bytes"; #endif ASSERT(length <= PAGE_SIZE); const int BLOCK_SIZE = 32 * 1024; diff --git a/Kernel/Devices/VMWareBackdoor.cpp b/Kernel/Devices/VMWareBackdoor.cpp index 4505f1d066..38068e72cf 100644 --- a/Kernel/Devices/VMWareBackdoor.cpp +++ b/Kernel/Devices/VMWareBackdoor.cpp @@ -97,11 +97,11 @@ VMWareBackdoor& VMWareBackdoor::the() VMWareBackdoor::VMWareBackdoor() { if (!detect_presence()) { - kprintf("VMWare Backdoor: Not supported!\n"); + klog() << "VMWare Backdoor: Not supported!"; m_supported = false; return; } - kprintf("VMWare Backdoor: Supported.\n"); + klog() << "VMWare Backdoor: Supported."; m_supported = true; } bool VMWareBackdoor::detect_presence() @@ -153,7 +153,7 @@ void VMWareBackdoor::enable_absolute_vmmouse() command.command = VMMOUSE_STATUS; send(command); if (command.ax == 0xFFFF0000) { - kprintf("VMMouse retuned bad status.\n"); + klog() << "VMMouse retuned bad status."; return; } diff --git a/Kernel/FileSystem/DiskBackedFileSystem.cpp b/Kernel/FileSystem/DiskBackedFileSystem.cpp index 62b61285d4..98233da3ad 100644 --- a/Kernel/FileSystem/DiskBackedFileSystem.cpp +++ b/Kernel/FileSystem/DiskBackedFileSystem.cpp @@ -125,7 +125,7 @@ DiskBackedFS::~DiskBackedFS() bool DiskBackedFS::write_block(unsigned index, const u8* data, FileDescription* description) { #ifdef DBFS_DEBUG - kprintf("DiskBackedFileSystem::write_block %u, size=%u\n", index, data.size()); + klog() << "DiskBackedFileSystem::write_block " << index << ", size=" << data.size(); #endif bool allow_cache = !description || !description->is_direct(); @@ -149,7 +149,7 @@ bool DiskBackedFS::write_block(unsigned index, const u8* data, FileDescription* bool DiskBackedFS::write_blocks(unsigned index, unsigned count, const u8* data, FileDescription* description) { #ifdef DBFS_DEBUG - kprintf("DiskBackedFileSystem::write_blocks %u x%u\n", index, count); + klog() << "DiskBackedFileSystem::write_blocks " << index << " x%u" << count; #endif for (unsigned i = 0; i < count; ++i) write_block(index + i, data + i * block_size(), description); @@ -159,7 +159,7 @@ bool DiskBackedFS::write_blocks(unsigned index, unsigned count, const u8* data, bool DiskBackedFS::read_block(unsigned index, u8* buffer, FileDescription* description) const { #ifdef DBFS_DEBUG - kprintf("DiskBackedFileSystem::read_block %u\n", index); + klog() << "DiskBackedFileSystem::read_block " << index; #endif bool allow_cache = !description || !description->is_direct(); diff --git a/Kernel/FileSystem/Ext2FileSystem.cpp b/Kernel/FileSystem/Ext2FileSystem.cpp index 868859d781..fe6c282ff9 100644 --- a/Kernel/FileSystem/Ext2FileSystem.cpp +++ b/Kernel/FileSystem/Ext2FileSystem.cpp @@ -100,20 +100,20 @@ bool Ext2FS::initialize() auto& super_block = this->super_block(); #ifdef EXT2_DEBUG - kprintf("ext2fs: super block magic: %x (super block size: %u)\n", super_block.s_magic, sizeof(ext2_super_block)); + klog() << "ext2fs: super block magic: " << String::format("%x", super_block.s_magic) << " (super block size: " << sizeof(ext2_super_block) << ")"; #endif if (super_block.s_magic != EXT2_SUPER_MAGIC) return false; #ifdef EXT2_DEBUG - kprintf("ext2fs: %u inodes, %u blocks\n", super_block.s_inodes_count, super_block.s_blocks_count); - kprintf("ext2fs: block size = %u\n", EXT2_BLOCK_SIZE(&super_block)); - kprintf("ext2fs: first data block = %u\n", super_block.s_first_data_block); - kprintf("ext2fs: inodes per block = %u\n", inodes_per_block()); - kprintf("ext2fs: inodes per group = %u\n", inodes_per_group()); - kprintf("ext2fs: free inodes = %u\n", super_block.s_free_inodes_count); - kprintf("ext2fs: desc per block = %u\n", EXT2_DESC_PER_BLOCK(&super_block)); - kprintf("ext2fs: desc size = %u\n", EXT2_DESC_SIZE(&super_block)); + klog() << "ext2fs: " << super_block.s_inodes_count << " inodes, " << super_block.s_blocks_count << " blocks"; + klog() << "ext2fs: block size = " << EXT2_BLOCK_SIZE(&super_block); + klog() << "ext2fs: first data block = " << super_block.s_first_data_block; + klog() << "ext2fs: inodes per block = " << inodes_per_block(); + klog() << "ext2fs: inodes per group = " << inodes_per_group(); + klog() << "ext2fs: free inodes = " << super_block.s_free_inodes_count; + klog() << "ext2fs: desc per block = " << EXT2_DESC_PER_BLOCK(&super_block); + klog() << "ext2fs: desc size = " << EXT2_DESC_SIZE(&super_block); #endif set_block_size(EXT2_BLOCK_SIZE(&super_block)); @@ -123,7 +123,7 @@ bool Ext2FS::initialize() m_block_group_count = ceil_div(super_block.s_blocks_count, super_block.s_blocks_per_group); if (m_block_group_count == 0) { - kprintf("ext2fs: no block groups :(\n"); + klog() << "ext2fs: no block groups :("; return false; } @@ -135,11 +135,7 @@ bool Ext2FS::initialize() #ifdef EXT2_DEBUG for (unsigned i = 1; i <= m_block_group_count; ++i) { auto& group = group_descriptor(i); - kprintf("ext2fs: group[%u] { block_bitmap: %u, inode_bitmap: %u, inode_table: %u }\n", - i, - group.bg_block_bitmap, - group.bg_inode_bitmap, - group.bg_inode_table); + klog() << "ext2fs: group[" << i << "] { block_bitmap: " << group.bg_block_bitmap << ", inode_bitmap: " << group.bg_inode_bitmap << ", inode_table: " << group.bg_inode_table << " }"; } #endif @@ -662,7 +658,7 @@ ssize_t Ext2FSInode::read_bytes(off_t offset, ssize_t count, u8* buffer, FileDes m_block_list = fs().block_list_for_inode(m_raw_inode); if (m_block_list.is_empty()) { - kprintf("ext2fs: read_bytes: empty block list for inode %u\n", index()); + klog() << "ext2fs: read_bytes: empty block list for inode " << index(); return -EIO; } @@ -690,7 +686,7 @@ ssize_t Ext2FSInode::read_bytes(off_t offset, ssize_t count, u8* buffer, FileDes ASSERT(block_index); bool success = fs().read_block(block_index, block, description); if (!success) { - kprintf("ext2fs: read_bytes: read_block(%u) failed (lbi: %u)\n", block_index, bi); + klog() << "ext2fs: read_bytes: read_block(" << block_index << ") failed (lbi: " << bi << ")"; return -EIO; } @@ -1182,7 +1178,7 @@ unsigned Ext2FS::find_a_free_inode(GroupIndex preferred_group, off_t expected_si } if (!group_index) { - kprintf("Ext2FS: find_a_free_inode: no suitable group found for new inode with %u blocks needed :(\n", needed_blocks); + klog() << "Ext2FS: find_a_free_inode: no suitable group found for new inode with " << needed_blocks << " blocks needed :("; return 0; } @@ -1206,7 +1202,7 @@ unsigned Ext2FS::find_a_free_inode(GroupIndex preferred_group, off_t expected_si } if (!first_free_inode_in_group) { - kprintf("Ext2FS: first_free_inode_in_group returned no inode, despite bgd claiming there are inodes :(\n"); + klog() << "Ext2FS: first_free_inode_in_group returned no inode, despite bgd claiming there are inodes :("; return 0; } @@ -1433,7 +1429,7 @@ KResultOr> Ext2FS::create_inode(InodeIdentifier parent_id, // NOTE: This doesn't commit the inode allocation just yet! auto inode_id = find_a_free_inode(0, size); if (!inode_id) { - kprintf("Ext2FS: create_inode: allocate_inode failed\n"); + klog() << "Ext2FS: create_inode: allocate_inode failed"; return KResult(-ENOSPC); } diff --git a/Kernel/FileSystem/FIFO.cpp b/Kernel/FileSystem/FIFO.cpp index af84301e0b..e1ae8d59b4 100644 --- a/Kernel/FileSystem/FIFO.cpp +++ b/Kernel/FileSystem/FIFO.cpp @@ -78,12 +78,12 @@ void FIFO::attach(Direction direction) if (direction == Direction::Reader) { ++m_readers; #ifdef FIFO_DEBUG - kprintf("open reader (%u)\n", m_readers); + klog() << "open reader (" << m_readers << ")"; #endif } else if (direction == Direction::Writer) { ++m_writers; #ifdef FIFO_DEBUG - kprintf("open writer (%u)\n", m_writers); + klog() << "open writer (" << m_writers << ")"; #endif } } @@ -92,13 +92,13 @@ void FIFO::detach(Direction direction) { if (direction == Direction::Reader) { #ifdef FIFO_DEBUG - kprintf("close reader (%u - 1)\n", m_readers); + klog() << "close reader (" << m_readers << " - 1)"; #endif ASSERT(m_readers); --m_readers; } else if (direction == Direction::Writer) { #ifdef FIFO_DEBUG - kprintf("close writer (%u - 1)\n", m_writers); + klog() << "close writer (" << m_writers << " - 1)"; #endif ASSERT(m_writers); --m_writers; diff --git a/Kernel/FileSystem/Inode.cpp b/Kernel/FileSystem/Inode.cpp index 862df5f5ec..0442dd0a0e 100644 --- a/Kernel/FileSystem/Inode.cpp +++ b/Kernel/FileSystem/Inode.cpp @@ -79,7 +79,7 @@ ByteBuffer Inode::read_entire(FileDescription* descriptor) const break; } if (nread < 0) { - kprintf("Inode::read_entire: ERROR: %d\n", nread); + klog() << "Inode::read_entire: ERROR: " << nread; return nullptr; } diff --git a/Kernel/FileSystem/VirtualFileSystem.cpp b/Kernel/FileSystem/VirtualFileSystem.cpp index d1d9064c12..65f28051da 100644 --- a/Kernel/FileSystem/VirtualFileSystem.cpp +++ b/Kernel/FileSystem/VirtualFileSystem.cpp @@ -52,7 +52,7 @@ VFS& VFS::the() VFS::VFS() { #ifdef VFS_DEBUG - kprintf("VFS: Constructing VFS\n"); + klog() << "VFS: Constructing VFS"; #endif s_the = this; } @@ -112,7 +112,7 @@ KResult VFS::unmount(InodeIdentifier guest_inode_id) bool VFS::mount_root(FS& file_system) { if (m_root_inode) { - kprintf("VFS: mount_root can't mount another root\n"); + klog() << "VFS: mount_root can't mount another root"; return false; } @@ -121,7 +121,7 @@ bool VFS::mount_root(FS& file_system) auto root_inode_id = mount.guest().fs()->root_inode(); auto root_inode = mount.guest().fs()->get_inode(root_inode_id); if (!root_inode->is_directory()) { - kprintf("VFS: root inode (%02u:%08u) for / is not a directory :(\n", root_inode_id.fsid(), root_inode_id.index()); + klog() << "VFS: root inode (" << String::format("%02u", root_inode_id.fsid()) << ":" << String::format("%08u", root_inode_id.index()) << ") for / is not a directory :("; return false; } @@ -133,7 +133,7 @@ bool VFS::mount_root(FS& file_system) } else { sprintf(device_name, "not-a-disk"); } - kprintf("VFS: mounted root on %s (%s)\n", m_root_inode->fs().class_name(), device_name); + klog() << "VFS: mounted root on " << m_root_inode->fs().class_name() << " (" << device_name << ")"; m_mounts.append(move(mount)); return true; diff --git a/Kernel/Heap/kmalloc.cpp b/Kernel/Heap/kmalloc.cpp index 936e4b1553..f068a38912 100644 --- a/Kernel/Heap/kmalloc.cpp +++ b/Kernel/Heap/kmalloc.cpp @@ -124,7 +124,7 @@ void* kmalloc_impl(size_t size) if (sum_free < real_size) { Kernel::dump_backtrace(); - kprintf("%s(%u) kmalloc(): PANIC! Out of memory (sucks, dude)\nsum_free=%u, real_size=%u\n", Kernel::Process::current->name().characters(), Kernel::Process::current->pid(), sum_free, real_size); + klog() << "kmalloc(): PANIC! Out of memory (sucks, dude)\nsum_free=" << sum_free << ", real_size=" << real_size; Kernel::hang(); } @@ -174,7 +174,7 @@ void* kmalloc_impl(size_t size) } } - kprintf("%s(%u) kmalloc(): PANIC! Out of memory (no suitable block for size %u)\n", Kernel::Process::current->name().characters(), Kernel::Process::current->pid(), size); + klog() << "kmalloc(): PANIC! Out of memory (no suitable block for size " << size << ")"; Kernel::dump_backtrace(); Kernel::hang(); } diff --git a/Kernel/Interrupts/APIC.cpp b/Kernel/Interrupts/APIC.cpp index ef7abac388..b950c85acd 100644 --- a/Kernel/Interrupts/APIC.cpp +++ b/Kernel/Interrupts/APIC.cpp @@ -172,7 +172,7 @@ namespace APIC { return false; PhysicalAddress apic_base = get_base(); - kprintf("Initializing APIC, base: P%x\n", apic_base); + klog() << "Initializing APIC, base: P " << String::format("%p", apic_base); set_base(apic_base); g_apic_base = apic_base.as_ptr(); @@ -188,7 +188,7 @@ namespace APIC { void enable(u32 cpu) { - kprintf("Enabling local APIC for cpu #%u\n", cpu); + klog() << "Enabling local APIC for cpu #" << cpu; // set spurious interrupt vector write_register(APIC_REG_SIV, read_register(APIC_REG_SIV) | 0x100); diff --git a/Kernel/Interrupts/IOAPIC.cpp b/Kernel/Interrupts/IOAPIC.cpp index a3a312d956..21700dc596 100644 --- a/Kernel/Interrupts/IOAPIC.cpp +++ b/Kernel/Interrupts/IOAPIC.cpp @@ -51,9 +51,9 @@ IOAPIC::IOAPIC(ioapic_mmio_regs& regs, u32 gsi_base, Vector(kmalloc_eternal(sizeof(KSym) * ksym_count)); ++bufptr; // skip newline - kprintf("Loading ksyms..."); + klog() << "Loading ksyms..."; unsigned current_ksym_index = 0; @@ -110,7 +110,7 @@ static void load_ksyms_from_data(const ByteBuffer& buffer) ++bufptr; ++current_ksym_index; } - kprintf("ok\n"); + klog() << "ok"; ksyms_ready = true; } diff --git a/Kernel/Lock.cpp b/Kernel/Lock.cpp index 4d3625f2ee..ae3a1b8736 100644 --- a/Kernel/Lock.cpp +++ b/Kernel/Lock.cpp @@ -34,7 +34,7 @@ void Lock::lock() { ASSERT(!Scheduler::is_active()); if (!are_interrupts_enabled()) { - kprintf("Interrupts disabled when trying to take Lock{%s}\n", m_name); + klog() << "Interrupts disabled when trying to take Lock{" << m_name << "}"; dump_backtrace(); hang(); } diff --git a/Kernel/Net/IPv4Socket.cpp b/Kernel/Net/IPv4Socket.cpp index df07aef537..2ab9c553ff 100644 --- a/Kernel/Net/IPv4Socket.cpp +++ b/Kernel/Net/IPv4Socket.cpp @@ -68,7 +68,7 @@ IPv4Socket::IPv4Socket(int type, int protocol) : Socket(AF_INET, type, protocol) { #ifdef IPV4_SOCKET_DEBUG - kprintf("%s(%u) IPv4Socket{%p} created with type=%u, protocol=%d\n", Process::current->name().characters(), Process::current->pid(), this, type, protocol); + dbg() << "IPv4Socket{" << this << "} created with type=" << type << ", protocol=" << protocol; #endif m_buffer_mode = type == SOCK_STREAM ? BufferMode::Bytes : BufferMode::Packets; if (m_buffer_mode == BufferMode::Bytes) { @@ -138,7 +138,7 @@ KResult IPv4Socket::listen(size_t backlog) m_role = Role::Listener; #ifdef IPV4_SOCKET_DEBUG - kprintf("IPv4Socket{%p} listening with backlog=%zu\n", this, backlog); + dbg() << "IPv4Socket{" << this << "} listening with backlog=" << backlog; #endif return protocol_listen(); @@ -201,7 +201,7 @@ ssize_t IPv4Socket::sendto(FileDescription&, const void* data, size_t data_lengt if (addr) { if (addr->sa_family != AF_INET) { - kprintf("sendto: Bad address family: %u is not AF_INET!\n", addr->sa_family); + klog() << "sendto: Bad address family: " << addr->sa_family << " is not AF_INET!"; return -EAFNOSUPPORT; } @@ -222,7 +222,7 @@ ssize_t IPv4Socket::sendto(FileDescription&, const void* data, size_t data_lengt return rc; #ifdef IPV4_SOCKET_DEBUG - kprintf("sendto: destination=%s:%u\n", m_peer_address.to_string().characters(), m_peer_port); + klog() << "sendto: destination=" << m_peer_address.to_string().characters() << ":" << m_peer_port; #endif if (type() == SOCK_RAW) { @@ -283,13 +283,13 @@ ssize_t IPv4Socket::receive_packet_buffered(FileDescription& description, void* packet = m_receive_queue.take_first(); m_can_read = !m_receive_queue.is_empty(); #ifdef IPV4_SOCKET_DEBUG - kprintf("IPv4Socket(%p): recvfrom without blocking %d bytes, packets in queue: %zu\n", this, packet.data.value().size(), m_receive_queue.size_slow()); + dbg() << "IPv4Socket(" << this << "): recvfrom without blocking " << packet.data.value().size() << " bytes, packets in queue: " << m_receive_queue.size_slow(); #endif } } if (!packet.data.has_value()) { if (protocol_is_disconnected()) { - kprintf("IPv4Socket{%p} is protocol-disconnected, returning 0 in recvfrom!\n", this); + dbg() << "IPv4Socket{" << this << "} is protocol-disconnected, returning 0 in recvfrom!"; return 0; } @@ -308,7 +308,7 @@ ssize_t IPv4Socket::receive_packet_buffered(FileDescription& description, void* packet = m_receive_queue.take_first(); m_can_read = !m_receive_queue.is_empty(); #ifdef IPV4_SOCKET_DEBUG - kprintf("IPv4Socket(%p): recvfrom with blocking %d bytes, packets in queue: %zu\n", this, packet.data.value().size(), m_receive_queue.size_slow()); + dbg() << "IPv4Socket(" << this << "): recvfrom with blocking " << packet.data.value().size() << " bytes, packets in queue: " << m_receive_queue.size_slow(); #endif } ASSERT(packet.data.has_value()); @@ -341,7 +341,7 @@ ssize_t IPv4Socket::recvfrom(FileDescription& description, void* buffer, size_t return -EINVAL; #ifdef IPV4_SOCKET_DEBUG - kprintf("recvfrom: type=%d, local_port=%u\n", type(), local_port()); + klog() << "recvfrom: type=" << type() << ", local_port=" << local_port(); #endif ssize_t nreceived = 0; @@ -367,7 +367,7 @@ bool IPv4Socket::did_receive(const IPv4Address& source_address, u16 source_port, if (buffer_mode() == BufferMode::Bytes) { size_t space_in_receive_buffer = m_receive_buffer.space_for_writing(); if (packet_size > space_in_receive_buffer) { - kprintf("IPv4Socket(%p): did_receive refusing packet since buffer is full.\n", this); + dbg() << "IPv4Socket(" << this << "): did_receive refusing packet since buffer is full."; ASSERT(m_can_read); return false; } @@ -377,7 +377,7 @@ bool IPv4Socket::did_receive(const IPv4Address& source_address, u16 source_port, } else { // FIXME: Maybe track the number of packets so we don't have to walk the entire packet queue to count them.. if (m_receive_queue.size_slow() > 2000) { - kprintf("IPv4Socket(%p): did_receive refusing packet since queue is full.\n", this); + dbg() << "IPv4Socket(" << this << "): did_receive refusing packet since queue is full."; return false; } m_receive_queue.append({ source_address, source_port, move(packet) }); @@ -386,9 +386,9 @@ bool IPv4Socket::did_receive(const IPv4Address& source_address, u16 source_port, m_bytes_received += packet_size; #ifdef IPV4_SOCKET_DEBUG if (buffer_mode() == BufferMode::Bytes) - kprintf("IPv4Socket(%p): did_receive %d bytes, total_received=%u\n", this, packet_size, m_bytes_received); + dbg() << "IPv4Socket(" << this << "): did_receive " << packet_size << " bytes, total_received=" << m_bytes_received; else - kprintf("IPv4Socket(%p): did_receive %d bytes, total_received=%u, packets in queue: %zu\n", this, packet_size, m_bytes_received, m_receive_queue.size_slow()); + dbg() << "IPv4Socket(" << this << "): did_receive " << packet_size << " bytes, total_received=" << m_bytes_received << ", packets in queue: " << m_receive_queue.size_slow(); #endif return true; } diff --git a/Kernel/Net/LocalSocket.cpp b/Kernel/Net/LocalSocket.cpp index eb956a2f7f..4a72b267dc 100644 --- a/Kernel/Net/LocalSocket.cpp +++ b/Kernel/Net/LocalSocket.cpp @@ -68,7 +68,7 @@ LocalSocket::LocalSocket(int type) m_prebind_mode = 0666; #ifdef DEBUG_LOCAL_SOCKET - kprintf("%s(%u) LocalSocket{%p} created with type=%u\n", Process::current->name().characters(), Process::current->pid(), this, type); + dbg() << "LocalSocket{" << this << "} created with type=" << type; #endif } @@ -105,7 +105,7 @@ KResult LocalSocket::bind(const sockaddr* user_address, socklen_t address_size) auto path = String(address.sun_path, strnlen(address.sun_path, sizeof(address.sun_path))); #ifdef DEBUG_LOCAL_SOCKET - kprintf("%s(%u) LocalSocket{%p} bind(%s)\n", Process::current->name().characters(), Process::current->pid(), this, safe_address); + dbg() << "LocalSocket{" << this << "} bind(" << safe_address << ")"; #endif mode_t mode = S_IFSOCK | (m_prebind_mode & 04777); @@ -145,7 +145,7 @@ KResult LocalSocket::connect(FileDescription& description, const sockaddr* addre memcpy(safe_address, local_address.sun_path, sizeof(local_address.sun_path)); #ifdef DEBUG_LOCAL_SOCKET - kprintf("%s(%u) LocalSocket{%p} connect(%s)\n", Process::current->name().characters(), Process::current->pid(), this, safe_address); + dbg() << "LocalSocket{" << this << "} connect(" << safe_address << ")"; #endif auto description_or_error = VFS::the().open(safe_address, O_RDWR, 0, Process::current->current_directory()); @@ -181,7 +181,7 @@ KResult LocalSocket::connect(FileDescription& description, const sockaddr* addre } #ifdef DEBUG_LOCAL_SOCKET - kprintf("%s(%u) LocalSocket{%p} connect(%s) status is %s\n", Process::current->name().characters(), Process::current->pid(), this, safe_address, to_string(setup_state())); + dbg() << "LocalSocket{" << this << "} connect(" << safe_address << ") status is " << to_string(setup_state()); #endif if (!is_connected()) { @@ -200,7 +200,7 @@ KResult LocalSocket::listen(size_t backlog) set_backlog(backlog); m_connect_side_role = m_role = Role::Listener; #ifdef DEBUG_LOCAL_SOCKET - kprintf("LocalSocket{%p} listening with backlog=%zu\n", this, backlog); + dbg() << "LocalSocket{" << this << "} listening with backlog=" << backlog; #endif return KSuccess; } diff --git a/Kernel/Net/NetworkTask.cpp b/Kernel/Net/NetworkTask.cpp index 9e3e8b296c..3cd116e1ef 100644 --- a/Kernel/Net/NetworkTask.cpp +++ b/Kernel/Net/NetworkTask.cpp @@ -72,12 +72,7 @@ void NetworkTask_main() adapter.set_ipv4_gateway({ 10, 0, 2, 2 }); } - kprintf("NetworkTask: %s network adapter found: hw=%s address=%s netmask=%s gateway=%s\n", - adapter.class_name(), - adapter.mac_address().to_string().characters(), - adapter.ipv4_address().to_string().characters(), - adapter.ipv4_netmask().to_string().characters(), - adapter.ipv4_gateway().to_string().characters()); + klog() << "NetworkTask: " << adapter.class_name() << " network adapter found: hw=" << adapter.mac_address().to_string().characters() << " address=" << adapter.ipv4_address().to_string().characters() << " netmask=" << adapter.ipv4_netmask().to_string().characters() << " gateway=" << adapter.ipv4_gateway().to_string().characters(); adapter.on_receive = [&]() { pending_packets++; @@ -95,7 +90,7 @@ void NetworkTask_main() packet_size = adapter.dequeue_packet(buffer, buffer_size); pending_packets--; #ifdef NETWORK_TASK_DEBUG - kprintf("NetworkTask: Dequeued packet from %s (%d bytes)\n", adapter.name().characters(), packet_size); + klog() << "NetworkTask: Dequeued packet from " << adapter.name().characters() << " (" << packet_size << " bytes)"; #endif }); return packet_size; @@ -105,7 +100,7 @@ void NetworkTask_main() auto buffer_region = MM.allocate_kernel_region(buffer_size, "Kernel Packet Buffer", Region::Access::Read | Region::Access::Write, false, true); auto buffer = (u8*)buffer_region->vaddr().get(); - kprintf("NetworkTask: Enter main loop.\n"); + klog() << "NetworkTask: Enter main loop."; for (;;) { size_t packet_size = dequeue_packet(buffer, buffer_size); if (!packet_size) { @@ -113,36 +108,32 @@ void NetworkTask_main() continue; } if (packet_size < sizeof(EthernetFrameHeader)) { - kprintf("NetworkTask: Packet is too small to be an Ethernet packet! (%zu)\n", packet_size); + klog() << "NetworkTask: Packet is too small to be an Ethernet packet! (" << packet_size << ")"; continue; } auto& eth = *(const EthernetFrameHeader*)buffer; #ifdef ETHERNET_DEBUG - kprintf("NetworkTask: From %s to %s, ether_type=%w, packet_length=%u\n", - eth.source().to_string().characters(), - eth.destination().to_string().characters(), - eth.ether_type(), - packet_size); + klog() << "NetworkTask: From " << eth.source().to_string().characters() << " to " << eth.destination().to_string().characters() << ", ether_type=" << String::format("%w", eth.ether_type()) << ", packet_length=" << packet_size; #endif #ifdef ETHERNET_VERY_DEBUG for (size_t i = 0; i < packet_size; i++) { - kprintf("%b", buffer[i]); + klog() << String::format("%b", buffer[i]); switch (i % 16) { case 7: - kprintf(" "); + klog() << " "; break; case 15: - kprintf("\n"); + klog() << ""; break; default: - kprintf(" "); + klog() << " "; break; } } - kprintf("\n"); + klog() << ""; #endif switch (eth.ether_type()) { @@ -156,7 +147,7 @@ void NetworkTask_main() // ignore break; default: - kprintf("NetworkTask: Unknown ethernet type %#04x\n", eth.ether_type()); + klog() << "NetworkTask: Unknown ethernet type 0x" << String::format("%x", eth.ether_type()); } } } @@ -165,30 +156,21 @@ void handle_arp(const EthernetFrameHeader& eth, size_t frame_size) { constexpr size_t minimum_arp_frame_size = sizeof(EthernetFrameHeader) + sizeof(ARPPacket); if (frame_size < minimum_arp_frame_size) { - kprintf("handle_arp: Frame too small (%d, need %d)\n", frame_size, minimum_arp_frame_size); + klog() << "handle_arp: Frame too small (" << frame_size << ", need " << minimum_arp_frame_size << ")"; return; } auto& packet = *static_cast(eth.payload()); if (packet.hardware_type() != 1 || packet.hardware_address_length() != sizeof(MACAddress)) { - kprintf("handle_arp: Hardware type not ethernet (%w, len=%u)\n", - packet.hardware_type(), - packet.hardware_address_length()); + klog() << "handle_arp: Hardware type not ethernet (" << String::format("%w", packet.hardware_type()) << ", len=" << packet.hardware_address_length() << ")"; return; } if (packet.protocol_type() != EtherType::IPv4 || packet.protocol_address_length() != sizeof(IPv4Address)) { - kprintf("handle_arp: Protocol type not IPv4 (%w, len=%u)\n", - packet.hardware_type(), - packet.protocol_address_length()); + klog() << "handle_arp: Protocol type not IPv4 (" << String::format("%w", packet.hardware_type()) << ", len=" << packet.protocol_address_length() << ")"; return; } #ifdef ARP_DEBUG - kprintf("handle_arp: operation=%w, sender=%s/%s, target=%s/%s\n", - packet.operation(), - packet.sender_hardware_address().to_string().characters(), - packet.sender_protocol_address().to_string().characters(), - packet.target_hardware_address().to_string().characters(), - packet.target_protocol_address().to_string().characters()); + klog() << "handle_arp: operation=" << String::format("%w", packet.operation()) << ", sender=" << packet.sender_hardware_address().to_string().characters() << "/" << packet.sender_protocol_address().to_string().characters() << ", target=" << packet.target_hardware_address().to_string().characters() << "/" << packet.target_protocol_address().to_string().characters(); #endif if (!packet.sender_hardware_address().is_zero() && !packet.sender_protocol_address().is_zero()) { @@ -198,9 +180,9 @@ void handle_arp(const EthernetFrameHeader& eth, size_t frame_size) LOCKER(arp_table().lock()); arp_table().resource().set(packet.sender_protocol_address(), packet.sender_hardware_address()); - kprintf("ARP table (%d entries):\n", arp_table().resource().size()); + klog() << "ARP table (" << arp_table().resource().size() << " entries):"; for (auto& it : arp_table().resource()) { - kprintf("%s :: %s\n", it.value.to_string().characters(), it.key.to_string().characters()); + klog() << it.value.to_string().characters() << " :: " << it.key.to_string().characters(); } } @@ -208,8 +190,7 @@ void handle_arp(const EthernetFrameHeader& eth, size_t frame_size) // Who has this IP address? if (auto adapter = NetworkAdapter::from_ipv4_address(packet.target_protocol_address())) { // We do! - kprintf("handle_arp: Responding to ARP request for my IPv4 address (%s)\n", - adapter->ipv4_address().to_string().characters()); + klog() << "handle_arp: Responding to ARP request for my IPv4 address (" << adapter->ipv4_address().to_string().characters() << ")"; ARPPacket response; response.set_operation(ARPOperation::Response); response.set_target_hardware_address(packet.sender_hardware_address()); @@ -227,26 +208,24 @@ void handle_ipv4(const EthernetFrameHeader& eth, size_t frame_size) { constexpr size_t minimum_ipv4_frame_size = sizeof(EthernetFrameHeader) + sizeof(IPv4Packet); if (frame_size < minimum_ipv4_frame_size) { - kprintf("handle_ipv4: Frame too small (%d, need %d)\n", frame_size, minimum_ipv4_frame_size); + klog() << "handle_ipv4: Frame too small (" << frame_size << ", need " << minimum_ipv4_frame_size << ")"; return; } auto& packet = *static_cast(eth.payload()); if (packet.length() < sizeof(IPv4Packet)) { - kprintf("handle_ipv4: IPv4 packet too short (%u, need %u)\n", packet.length(), sizeof(IPv4Packet)); + klog() << "handle_ipv4: IPv4 packet too short (" << packet.length() << ", need " << sizeof(IPv4Packet) << ")"; return; } size_t actual_ipv4_packet_length = frame_size - sizeof(EthernetFrameHeader); if (packet.length() > actual_ipv4_packet_length) { - kprintf("handle_ipv4: IPv4 packet claims to be longer than it is (%u, actually %zu)\n", packet.length(), actual_ipv4_packet_length); + klog() << "handle_ipv4: IPv4 packet claims to be longer than it is (" << packet.length() << ", actually " << actual_ipv4_packet_length << ")"; return; } #ifdef IPV4_DEBUG - kprintf("handle_ipv4: source=%s, target=%s\n", - packet.source().to_string().characters(), - packet.destination().to_string().characters()); + klog() << "handle_ipv4: source=" << packet.source().to_string().characters() << ", target=" << packet.destination().to_string().characters(); #endif switch ((IPv4Protocol)packet.protocol()) { @@ -257,7 +236,7 @@ void handle_ipv4(const EthernetFrameHeader& eth, size_t frame_size) case IPv4Protocol::TCP: return handle_tcp(packet); default: - kprintf("handle_ipv4: Unhandled protocol %u\n", packet.protocol()); + klog() << "handle_ipv4: Unhandled protocol " << packet.protocol(); break; } } @@ -266,11 +245,7 @@ void handle_icmp(const EthernetFrameHeader& eth, const IPv4Packet& ipv4_packet) { auto& icmp_header = *static_cast(ipv4_packet.payload()); #ifdef ICMP_DEBUG - kprintf("handle_icmp: source=%s, destination=%s, type=%b, code=%b\n", - ipv4_packet.source().to_string().characters(), - ipv4_packet.destination().to_string().characters(), - icmp_header.type(), - icmp_header.code()); + klog() << "handle_icmp: source=" << ipv4_packet.source().to_string().characters() << ", destination=" << ipv4_packet.destination().to_string().characters() << ", type=" << String::format("%b", icmp_header.type()) << ", code=" << String::format("%b", icmp_header.code()); #endif { @@ -289,10 +264,7 @@ void handle_icmp(const EthernetFrameHeader& eth, const IPv4Packet& ipv4_packet) if (icmp_header.type() == ICMPType::EchoRequest) { auto& request = reinterpret_cast(icmp_header); - kprintf("handle_icmp: EchoRequest from %s: id=%u, seq=%u\n", - ipv4_packet.source().to_string().characters(), - (u16)request.identifier, - (u16)request.sequence_number); + klog() << "handle_icmp: EchoRequest from " << ipv4_packet.source().to_string().characters() << ": id=" << (u16)request.identifier << ", seq=" << (u16)request.sequence_number; size_t icmp_packet_size = ipv4_packet.payload_size(); auto buffer = ByteBuffer::create_zeroed(icmp_packet_size); auto& response = *(ICMPEchoPacket*)buffer.data(); @@ -311,29 +283,24 @@ void handle_icmp(const EthernetFrameHeader& eth, const IPv4Packet& ipv4_packet) void handle_udp(const IPv4Packet& ipv4_packet) { if (ipv4_packet.payload_size() < sizeof(UDPPacket)) { - kprintf("handle_udp: Packet too small (%u, need %zu)\n", ipv4_packet.payload_size()); + klog() << "handle_udp: Packet too small (" << ipv4_packet.payload_size() << ", need " << sizeof(UDPPacket) << ")"; return; } auto adapter = NetworkAdapter::from_ipv4_address(ipv4_packet.destination()); if (!adapter) { - kprintf("handle_udp: this packet is not for me, it's for %s\n", ipv4_packet.destination().to_string().characters()); + klog() << "handle_udp: this packet is not for me, it's for " << ipv4_packet.destination().to_string().characters(); return; } auto& udp_packet = *static_cast(ipv4_packet.payload()); #ifdef UDP_DEBUG - kprintf("handle_udp: source=%s:%u, destination=%s:%u length=%u\n", - ipv4_packet.source().to_string().characters(), - udp_packet.source_port(), - ipv4_packet.destination().to_string().characters(), - udp_packet.destination_port(), - udp_packet.length()); + klog() << "handle_udp: source=" << ipv4_packet.source().to_string().characters() << ":" << udp_packet.source_port() << ", destination=" << ipv4_packet.destination().to_string().characters() << ":" << udp_packet.destination_port() << " length=" << udp_packet.length(); #endif auto socket = UDPSocket::from_port(udp_packet.destination_port()); if (!socket) { - kprintf("handle_udp: No UDP socket for port %u\n", udp_packet.destination_port()); + klog() << "handle_udp: No UDP socket for port " << udp_packet.destination_port(); return; } @@ -345,7 +312,7 @@ void handle_udp(const IPv4Packet& ipv4_packet) void handle_tcp(const IPv4Packet& ipv4_packet) { if (ipv4_packet.payload_size() < sizeof(TCPPacket)) { - kprintf("handle_tcp: IPv4 payload is too small to be a TCP packet (%u, need %zu)\n", ipv4_packet.payload_size(), sizeof(TCPPacket)); + klog() << "handle_tcp: IPv4 payload is too small to be a TCP packet (" << ipv4_packet.payload_size() << ", need " << sizeof(TCPPacket) << ")"; return; } @@ -354,62 +321,36 @@ void handle_tcp(const IPv4Packet& ipv4_packet) size_t minimum_tcp_header_size = 5 * sizeof(u32); size_t maximum_tcp_header_size = 15 * sizeof(u32); if (tcp_packet.header_size() < minimum_tcp_header_size || tcp_packet.header_size() > maximum_tcp_header_size) { - kprintf("handle_tcp: TCP packet header has invalid size %zu\n", tcp_packet.header_size()); + klog() << "handle_tcp: TCP packet header has invalid size " << tcp_packet.header_size(); } if (ipv4_packet.payload_size() < tcp_packet.header_size()) { - kprintf("handle_tcp: IPv4 payload is smaller than TCP header claims (%u, supposedly %u)\n", ipv4_packet.payload_size(), tcp_packet.header_size()); + klog() << "handle_tcp: IPv4 payload is smaller than TCP header claims (" << ipv4_packet.payload_size() << ", supposedly " << tcp_packet.header_size() << ")"; return; } size_t payload_size = ipv4_packet.payload_size() - tcp_packet.header_size(); #ifdef TCP_DEBUG - kprintf("handle_tcp: source=%s:%u, destination=%s:%u seq_no=%u, ack_no=%u, flags=%w (%s%s%s%s), window_size=%u, payload_size=%u\n", - ipv4_packet.source().to_string().characters(), - tcp_packet.source_port(), - ipv4_packet.destination().to_string().characters(), - tcp_packet.destination_port(), - tcp_packet.sequence_number(), - tcp_packet.ack_number(), - tcp_packet.flags(), - tcp_packet.has_syn() ? "SYN " : "", - tcp_packet.has_ack() ? "ACK " : "", - tcp_packet.has_fin() ? "FIN " : "", - tcp_packet.has_rst() ? "RST " : "", - tcp_packet.window_size(), - payload_size); + klog() << "handle_tcp: source=" << ipv4_packet.source().to_string().characters() << ":" << tcp_packet.source_port() << ", destination=" << ipv4_packet.destination().to_string().characters() << ":" << tcp_packet.destination_port() << " seq_no=" << tcp_packet.sequence_number() << ", ack_no=" << tcp_packet.ack_number() << ", flags=" << String::format("%w", tcp_packet.flags()) << " (" << (tcp_packet.has_syn() ? "SYN " : "") << (tcp_packet.has_ack() ? "ACK " : "") << (tcp_packet.has_fin() ? "FIN " : "") << (tcp_packet.has_rst() ? "RST " : "") << "), window_size=" << tcp_packet.window_size() << ", payload_size=" << payload_size; #endif auto adapter = NetworkAdapter::from_ipv4_address(ipv4_packet.destination()); if (!adapter) { - kprintf("handle_tcp: this packet is not for me, it's for %s\n", ipv4_packet.destination().to_string().characters()); + klog() << "handle_tcp: this packet is not for me, it's for " << ipv4_packet.destination().to_string().characters(); return; } IPv4SocketTuple tuple(ipv4_packet.destination(), tcp_packet.destination_port(), ipv4_packet.source(), tcp_packet.source_port()); #ifdef TCP_DEBUG - kprintf("handle_tcp: looking for socket; tuple=%s\n", tuple.to_string().characters()); + klog() << "handle_tcp: looking for socket; tuple=" << tuple.to_string().characters(); #endif auto socket = TCPSocket::from_tuple(tuple); if (!socket) { - kprintf("handle_tcp: No TCP socket for tuple %s\n", tuple.to_string().characters()); - kprintf("handle_tcp: source=%s:%u, destination=%s:%u seq_no=%u, ack_no=%u, flags=%w (%s%s%s%s), window_size=%u, payload_size=%u\n", - ipv4_packet.source().to_string().characters(), - tcp_packet.source_port(), - ipv4_packet.destination().to_string().characters(), - tcp_packet.destination_port(), - tcp_packet.sequence_number(), - tcp_packet.ack_number(), - tcp_packet.flags(), - tcp_packet.has_syn() ? "SYN " : "", - tcp_packet.has_ack() ? "ACK " : "", - tcp_packet.has_fin() ? "FIN " : "", - tcp_packet.has_rst() ? "RST " : "", - tcp_packet.window_size(), - payload_size); + klog() << "handle_tcp: No TCP socket for tuple " << tuple.to_string().characters(); + klog() << "handle_tcp: source=" << ipv4_packet.source().to_string().characters() << ":" << tcp_packet.source_port() << ", destination=" << ipv4_packet.destination().to_string().characters() << ":" << tcp_packet.destination_port() << " seq_no=" << tcp_packet.sequence_number() << ", ack_no=" << tcp_packet.ack_number() << ", flags=" << String::format("%w", tcp_packet.flags()) << " (" << (tcp_packet.has_syn() ? "SYN " : "") << (tcp_packet.has_ack() ? "ACK " : "") << (tcp_packet.has_fin() ? "FIN " : "") << (tcp_packet.has_rst() ? "RST " : "") << "), window_size=" << tcp_packet.window_size() << ", payload_size=" << payload_size; return; } @@ -417,18 +358,18 @@ void handle_tcp(const IPv4Packet& ipv4_packet) ASSERT(socket->local_port() == tcp_packet.destination_port()); #ifdef TCP_DEBUG - kprintf("handle_tcp: got socket; state=%s\n", socket->tuple().to_string().characters(), TCPSocket::to_string(socket->state())); + klog() << "handle_tcp: got socket; state=" << socket->tuple().to_string().characters() << " " << TCPSocket::to_string(socket->state()); #endif socket->receive_tcp_packet(tcp_packet, ipv4_packet.payload_size()); switch (socket->state()) { case TCPSocket::State::Closed: - kprintf("handle_tcp: unexpected flags in Closed state\n"); + klog() << "handle_tcp: unexpected flags in Closed state"; // TODO: we may want to send an RST here, maybe as a configurable option return; case TCPSocket::State::TimeWait: - kprintf("handle_tcp: unexpected flags in TimeWait state\n"); + klog() << "handle_tcp: unexpected flags in TimeWait state"; socket->send_tcp_packet(TCPFlags::RST); socket->set_state(TCPSocket::State::Closed); return; @@ -436,17 +377,17 @@ void handle_tcp(const IPv4Packet& ipv4_packet) switch (tcp_packet.flags()) { case TCPFlags::SYN: { #ifdef TCP_DEBUG - kprintf("handle_tcp: incoming connection\n"); + klog() << "handle_tcp: incoming connection"; #endif auto& local_address = ipv4_packet.destination(); auto& peer_address = ipv4_packet.source(); auto client = socket->create_client(local_address, tcp_packet.destination_port(), peer_address, tcp_packet.source_port()); if (!client) { - kprintf("handle_tcp: couldn't create client socket\n"); + klog() << "handle_tcp: couldn't create client socket"; return; } #ifdef TCP_DEBUG - kprintf("handle_tcp: created new client socket with tuple %s\n", client->tuple().to_string().characters()); + klog() << "handle_tcp: created new client socket with tuple " << client->tuple().to_string().characters(); #endif client->set_sequence_number(1000); client->set_ack_number(tcp_packet.sequence_number() + payload_size + 1); @@ -455,7 +396,7 @@ void handle_tcp(const IPv4Packet& ipv4_packet) return; } default: - kprintf("handle_tcp: unexpected flags in Listen state\n"); + klog() << "handle_tcp: unexpected flags in Listen state"; // socket->send_tcp_packet(TCPFlags::RST); return; } @@ -488,7 +429,7 @@ void handle_tcp(const IPv4Packet& ipv4_packet) socket->set_setup_state(Socket::SetupState::Completed); return; default: - kprintf("handle_tcp: unexpected flags in SynSent state\n"); + klog() << "handle_tcp: unexpected flags in SynSent state"; socket->send_tcp_packet(TCPFlags::RST); socket->set_state(TCPSocket::State::Closed); socket->set_error(TCPSocket::Error::UnexpectedFlagsDuringConnect); @@ -503,7 +444,7 @@ void handle_tcp(const IPv4Packet& ipv4_packet) switch (socket->direction()) { case TCPSocket::Direction::Incoming: if (!socket->has_originator()) { - kprintf("handle_tcp: connection doesn't have an originating socket; maybe it went away?\n"); + klog() << "handle_tcp: connection doesn't have an originating socket; maybe it went away?"; socket->send_tcp_packet(TCPFlags::RST); socket->set_state(TCPSocket::State::Closed); return; @@ -519,7 +460,7 @@ void handle_tcp(const IPv4Packet& ipv4_packet) socket->set_connected(true); return; default: - kprintf("handle_tcp: got ACK in SynReceived state but direction is invalid (%s)\n", TCPSocket::to_string(socket->direction())); + klog() << "handle_tcp: got ACK in SynReceived state but direction is invalid (" << TCPSocket::to_string(socket->direction()) << ")"; socket->send_tcp_packet(TCPFlags::RST); socket->set_state(TCPSocket::State::Closed); return; @@ -527,7 +468,7 @@ void handle_tcp(const IPv4Packet& ipv4_packet) return; default: - kprintf("handle_tcp: unexpected flags in SynReceived state\n"); + klog() << "handle_tcp: unexpected flags in SynReceived state"; socket->send_tcp_packet(TCPFlags::RST); socket->set_state(TCPSocket::State::Closed); return; @@ -535,7 +476,7 @@ void handle_tcp(const IPv4Packet& ipv4_packet) case TCPSocket::State::CloseWait: switch (tcp_packet.flags()) { default: - kprintf("handle_tcp: unexpected flags in CloseWait state\n"); + klog() << "handle_tcp: unexpected flags in CloseWait state"; socket->send_tcp_packet(TCPFlags::RST); socket->set_state(TCPSocket::State::Closed); return; @@ -547,7 +488,7 @@ void handle_tcp(const IPv4Packet& ipv4_packet) socket->set_state(TCPSocket::State::Closed); return; default: - kprintf("handle_tcp: unexpected flags in LastAck state\n"); + klog() << "handle_tcp: unexpected flags in LastAck state"; socket->send_tcp_packet(TCPFlags::RST); socket->set_state(TCPSocket::State::Closed); return; @@ -563,7 +504,7 @@ void handle_tcp(const IPv4Packet& ipv4_packet) socket->set_state(TCPSocket::State::Closing); return; default: - kprintf("handle_tcp: unexpected flags in FinWait1 state\n"); + klog() << "handle_tcp: unexpected flags in FinWait1 state"; socket->send_tcp_packet(TCPFlags::RST); socket->set_state(TCPSocket::State::Closed); return; @@ -578,7 +519,7 @@ void handle_tcp(const IPv4Packet& ipv4_packet) socket->set_state(TCPSocket::State::Closed); return; default: - kprintf("handle_tcp: unexpected flags in FinWait2 state\n"); + klog() << "handle_tcp: unexpected flags in FinWait2 state"; socket->send_tcp_packet(TCPFlags::RST); socket->set_state(TCPSocket::State::Closed); return; @@ -590,7 +531,7 @@ void handle_tcp(const IPv4Packet& ipv4_packet) socket->set_state(TCPSocket::State::TimeWait); return; default: - kprintf("handle_tcp: unexpected flags in Closing state\n"); + klog() << "handle_tcp: unexpected flags in Closing state"; socket->send_tcp_packet(TCPFlags::RST); socket->set_state(TCPSocket::State::Closed); return; @@ -610,12 +551,7 @@ void handle_tcp(const IPv4Packet& ipv4_packet) socket->set_ack_number(tcp_packet.sequence_number() + payload_size); #ifdef TCP_DEBUG - kprintf("Got packet with ack_no=%u, seq_no=%u, payload_size=%u, acking it with new ack_no=%u, seq_no=%u\n", - tcp_packet.ack_number(), - tcp_packet.sequence_number(), - payload_size, - socket->ack_number(), - socket->sequence_number()); + klog() << "Got packet with ack_no=" << tcp_packet.ack_number() << ", seq_no=" << tcp_packet.sequence_number() << ", payload_size=" << payload_size << ", acking it with new ack_no=" << socket->ack_number() << ", seq_no=" << socket->sequence_number(); #endif if (payload_size) { diff --git a/Kernel/Net/Routing.cpp b/Kernel/Net/Routing.cpp index f101a4e4e0..84b5fee6ba 100644 --- a/Kernel/Net/Routing.cpp +++ b/Kernel/Net/Routing.cpp @@ -76,8 +76,7 @@ RoutingDecision route_to(const IPv4Address& target, const IPv4Address& source) if (!local_adapter && !gateway_adapter) { #ifdef ROUTING_DEBUG - kprintf("Routing: Couldn't find a suitable adapter for route to %s\n", - target.to_string().characters()); + klog() << "Routing: Couldn't find a suitable adapter for route to " << target.to_string().characters(); #endif return { nullptr, {} }; } @@ -87,22 +86,13 @@ RoutingDecision route_to(const IPv4Address& target, const IPv4Address& source) if (local_adapter) { #ifdef ROUTING_DEBUG - kprintf("Routing: Got adapter for route (direct): %s (%s/%s) for %s\n", - local_adapter->name().characters(), - local_adapter->ipv4_address().to_string().characters(), - local_adapter->ipv4_netmask().to_string().characters(), - target.to_string().characters()); + klog() << "Routing: Got adapter for route (direct): " << local_adapter->name().characters() << " (" << local_adapter->ipv4_address().to_string().characters() << "/" << local_adapter->ipv4_netmask().to_string().characters() << ") for " << target.to_string().characters(); #endif adapter = local_adapter; next_hop_ip = target; } else if (gateway_adapter) { #ifdef ROUTING_DEBUG - kprintf("Routing: Got adapter for route (using gateway %s): %s (%s/%s) for %s\n", - gateway_adapter->ipv4_gateway().to_string().characters(), - gateway_adapter->name().characters(), - gateway_adapter->ipv4_address().to_string().characters(), - gateway_adapter->ipv4_netmask().to_string().characters(), - target.to_string().characters()); + klog() << "Routing: Got adapter for route (using gateway " << gateway_adapter->ipv4_gateway().to_string().characters() << "): " << gateway_adapter->name().characters() << " (" << gateway_adapter->ipv4_address().to_string().characters() << "/" << gateway_adapter->ipv4_netmask().to_string().characters() << ") for " << target.to_string().characters(); #endif adapter = gateway_adapter; next_hop_ip = gateway_adapter->ipv4_gateway(); @@ -115,18 +105,14 @@ RoutingDecision route_to(const IPv4Address& target, const IPv4Address& source) auto addr = arp_table().resource().get(next_hop_ip); if (addr.has_value()) { #ifdef ROUTING_DEBUG - kprintf("Routing: Using cached ARP entry for %s (%s)\n", - next_hop_ip.to_string().characters(), - addr.value().to_string().characters()); + klog() << "Routing: Using cached ARP entry for " << next_hop_ip.to_string().characters() << " (" << addr.value().to_string().characters() << ")"; #endif return { adapter, addr.value() }; } } #ifdef ROUTING_DEBUG - kprintf("Routing: Sending ARP request via adapter %s for IPv4 address %s\n", - adapter->name().characters(), - next_hop_ip.to_string().characters()); + klog() << "Routing: Sending ARP request via adapter " << adapter->name().characters() << " for IPv4 address " << next_hop_ip.to_string().characters(); #endif ARPPacket request; @@ -146,19 +132,14 @@ RoutingDecision route_to(const IPv4Address& target, const IPv4Address& source) auto addr = arp_table().resource().get(next_hop_ip); if (addr.has_value()) { #ifdef ROUTING_DEBUG - kprintf("Routing: Got ARP response using adapter %s for %s (%s)\n", - adapter->name().characters(), - next_hop_ip.to_string().characters(), - addr.value().to_string().characters()); + klog() << "Routing: Got ARP response using adapter " << adapter->name().characters() << " for " << next_hop_ip.to_string().characters() << " (" << addr.value().to_string().characters() << ")"; #endif return { adapter, addr.value() }; } } #ifdef ROUTING_DEBUG - kprintf("Routing: Couldn't find route using adapter %s for %s\n", - adapter->name().characters(), - target.to_string().characters()); + klog() << "Routing: Couldn't find route using adapter " << adapter->name().characters() << " for " << target.to_string().characters(); #endif return { nullptr, {} }; diff --git a/Kernel/Net/Socket.cpp b/Kernel/Net/Socket.cpp index 9d923e84bc..ed1092902a 100644 --- a/Kernel/Net/Socket.cpp +++ b/Kernel/Net/Socket.cpp @@ -65,7 +65,7 @@ Socket::~Socket() void Socket::set_setup_state(SetupState new_setup_state) { #ifdef SOCKET_DEBUG - kprintf("%s(%u) Socket{%p} setup state moving from %s to %s\n", Process::current->name().characters(), Process::current->pid(), this, to_string(m_setup_state), to_string(new_setup_state)); + dbg() << "Socket{" << this << "} setup state moving from " << to_string(m_setup_state) << " to " << to_string(new_setup_state); #endif m_setup_state = new_setup_state; @@ -77,7 +77,7 @@ RefPtr Socket::accept() if (m_pending.is_empty()) return nullptr; #ifdef SOCKET_DEBUG - kprintf("%s(%u) Socket{%p} de-queueing connection\n", Process::current->name().characters(), Process::current->pid(), this); + dbg() << "Socket{" << this << "} de-queueing connection"; #endif auto client = m_pending.take_first(); ASSERT(!client->is_connected()); @@ -91,7 +91,7 @@ RefPtr Socket::accept() KResult Socket::queue_connection_from(NonnullRefPtr peer) { #ifdef SOCKET_DEBUG - kprintf("%s(%u) Socket{%p} queueing connection\n", Process::current->name().characters(), Process::current->pid(), this); + dbg() << "Socket{" << this << "} queueing connection"; #endif LOCKER(m_lock); if (m_pending.size() >= m_backlog) diff --git a/Kernel/Net/TCPSocket.cpp b/Kernel/Net/TCPSocket.cpp index 508675a6d9..9e8fed62cc 100644 --- a/Kernel/Net/TCPSocket.cpp +++ b/Kernel/Net/TCPSocket.cpp @@ -48,9 +48,7 @@ void TCPSocket::for_each(Function callback) void TCPSocket::set_state(State new_state) { #ifdef TCP_SOCKET_DEBUG - kprintf("%s(%u) TCPSocket{%p} state moving from %s to %s\n", - Process::current->name().characters(), Process::current->pid(), this, - to_string(m_state), to_string(new_state)); + dbg() << "TCPSocket{" << this << "} state moving from " << to_string(m_state) << " to " << to_string(new_state); #endif m_state = new_state; @@ -170,7 +168,7 @@ int TCPSocket::protocol_receive(const KBuffer& packet_buffer, void* buffer, size auto& tcp_packet = *static_cast(ipv4_packet.payload()); size_t payload_size = packet_buffer.size() - sizeof(IPv4Packet) - tcp_packet.header_size(); #ifdef TCP_SOCKET_DEBUG - kprintf("payload_size %u, will it fit in %u?\n", payload_size, buffer_size); + klog() << "payload_size " << payload_size << ", will it fit in " << buffer_size << "?"; #endif ASSERT(buffer_size >= payload_size); memcpy(buffer, tcp_packet.payload(), payload_size); @@ -243,18 +241,7 @@ void TCPSocket::send_outgoing_packets() #ifdef TCP_SOCKET_DEBUG auto& tcp_packet = *(TCPPacket*)(packet.buffer.data()); - kprintf("sending tcp packet from %s:%u to %s:%u with (%s%s%s%s) seq_no=%u, ack_no=%u, tx_counter=%u\n", - local_address().to_string().characters(), - local_port(), - peer_address().to_string().characters(), - peer_port(), - tcp_packet.has_syn() ? "SYN " : "", - tcp_packet.has_ack() ? "ACK " : "", - tcp_packet.has_fin() ? "FIN " : "", - tcp_packet.has_rst() ? "RST " : "", - tcp_packet.sequence_number(), - tcp_packet.ack_number(), - packet.tx_counter); + klog() << "sending tcp packet from " << local_address().to_string().characters() << ":" << local_port() << " to " << peer_address().to_string().characters() << ":" << peer_port() << " with (" << (tcp_packet.has_syn() ? "SYN " : "") << (tcp_packet.has_ack() ? "ACK " : "") << (tcp_packet.has_fin() ? "FIN " : "") << (tcp_packet.has_rst() ? "RST " : "") << ") seq_no=" << tcp_packet.sequence_number() << ", ack_no=" << tcp_packet.ack_number() << ", tx_counter=" << packet.tx_counter; #endif routing_decision.adapter->send_ipv4( routing_decision.next_hop, peer_address(), IPv4Protocol::TCP, diff --git a/Kernel/Net/UDPSocket.cpp b/Kernel/Net/UDPSocket.cpp index c3d02d8421..8794b9b7a6 100644 --- a/Kernel/Net/UDPSocket.cpp +++ b/Kernel/Net/UDPSocket.cpp @@ -101,11 +101,7 @@ int UDPSocket::protocol_send(const void* data, size_t data_length) udp_packet.set_destination_port(peer_port()); udp_packet.set_length(sizeof(UDPPacket) + data_length); memcpy(udp_packet.payload(), data, data_length); - kprintf("sending as udp packet from %s:%u to %s:%u!\n", - routing_decision.adapter->ipv4_address().to_string().characters(), - local_port(), - peer_address().to_string().characters(), - peer_port()); + klog() << "sending as udp packet from " << routing_decision.adapter->ipv4_address().to_string().characters() << ":" << local_port() << " to " << peer_address().to_string().characters() << ":" << peer_port() << "!"; routing_decision.adapter->send_ipv4(routing_decision.next_hop, peer_address(), IPv4Protocol::UDP, buffer.data(), buffer.size(), ttl()); return data_length; } diff --git a/Kernel/PCI/Access.cpp b/Kernel/PCI/Access.cpp index cd86f257f5..99957c7ed6 100644 --- a/Kernel/PCI/Access.cpp +++ b/Kernel/PCI/Access.cpp @@ -57,7 +57,7 @@ void PCI::Access::enumerate_functions(int type, u8 bus, u8 slot, u8 function, Fu if (read_type(address) == PCI_TYPE_BRIDGE) { u8 secondary_bus = read8_field(address, PCI_SECONDARY_BUS); #ifdef PCI_DEBUG - kprintf("PCI: Found secondary bus: %u\n", secondary_bus); + klog() << "PCI: Found secondary bus: " << secondary_bus; #endif ASSERT(secondary_bus != bus); enumerate_bus(type, secondary_bus, callback); diff --git a/Kernel/PCI/IOAccess.cpp b/Kernel/PCI/IOAccess.cpp index 2a2b486195..4049b3672b 100644 --- a/Kernel/PCI/IOAccess.cpp +++ b/Kernel/PCI/IOAccess.cpp @@ -37,7 +37,7 @@ void PCI::IOAccess::initialize() PCI::IOAccess::IOAccess() { - kprintf("PCI: Using IO Mechanism for PCI Configuartion Space Access\n"); + klog() << "PCI: Using IO Mechanism for PCI Configuartion Space Access"; } u8 PCI::IOAccess::read8_field(Address address, u32 field) diff --git a/Kernel/PCI/Initializer.cpp b/Kernel/PCI/Initializer.cpp index 34f359da1a..0ddd6e5fee 100644 --- a/Kernel/PCI/Initializer.cpp +++ b/Kernel/PCI/Initializer.cpp @@ -58,13 +58,7 @@ void PCI::Initializer::initialize_pci_io_access() void PCI::Initializer::detect_devices() { PCI::enumerate_all([&](const PCI::Address& address, PCI::ID id) { - kprintf("PCI: device @ %w:%b:%b.%d [%w:%w]\n", - address.seg(), - address.bus(), - address.slot(), - address.function(), - id.vendor_id, - id.device_id); + klog() << "PCI: device @ " << String::format("%w", address.seg()) << ":" << String::format("%b", address.bus()) << ":" << String::format("%b", address.slot()) << "." << String::format("%d", address.function()) << " [" << String::format("%w", id.vendor_id) << ":" << String::format("%w", id.device_id) << "]"; E1000NetworkAdapter::detect(address); RTL8139NetworkAdapter::detect(address); }); @@ -76,7 +70,7 @@ void PCI::Initializer::test_and_initialize(bool disable_pci_mmio) if (test_pci_io()) { initialize_pci_io_access(); } else { - kprintf("No PCI Bus Access Method Detected, Halt!\n"); + klog() << "No PCI Bus Access Method Detected, Halt!"; ASSERT_NOT_REACHED(); // NO PCI Access ?! } return; @@ -88,7 +82,7 @@ void PCI::Initializer::test_and_initialize(bool disable_pci_mmio) if (test_pci_io()) { initialize_pci_io_access(); } else { - kprintf("No PCI Bus Access Method Detected, Halt!\n"); + klog() << "No PCI Bus Access Method Detected, Halt!"; ASSERT_NOT_REACHED(); // NO PCI Access ?! } } @@ -96,7 +90,7 @@ void PCI::Initializer::test_and_initialize(bool disable_pci_mmio) if (test_pci_io()) { initialize_pci_io_access(); } else { - kprintf("No PCI Bus Access Method Detected, Halt!\n"); + klog() << "No PCI Bus Access Method Detected, Halt!"; ASSERT_NOT_REACHED(); // NO PCI Access ?! } } @@ -114,16 +108,16 @@ bool PCI::Initializer::test_acpi() bool PCI::Initializer::test_pci_io() { - kprintf("Testing PCI via manual probing... "); + klog() << "Testing PCI via manual probing... "; u32 tmp = 0x80000000; IO::out32(PCI_ADDRESS_PORT, tmp); tmp = IO::in32(PCI_ADDRESS_PORT); if (tmp == 0x80000000) { - kprintf("PCI IO Supported!\n"); + klog() << "PCI IO Supported!"; return true; } - kprintf("PCI IO Not Supported!\n"); + klog() << "PCI IO Not Supported!"; return false; } @@ -141,7 +135,7 @@ void PCI::Initializer::dismiss() { if (s_pci_initializer == nullptr) return; - kprintf("PCI Subsystem Initializer dismissed.\n"); + klog() << "PCI Subsystem Initializer dismissed."; delete s_pci_initializer; s_pci_initializer = nullptr; } diff --git a/Kernel/PCI/MMIOAccess.cpp b/Kernel/PCI/MMIOAccess.cpp index e27282fc9a..bb7572d7b8 100644 --- a/Kernel/PCI/MMIOAccess.cpp +++ b/Kernel/PCI/MMIOAccess.cpp @@ -58,7 +58,7 @@ PCI::MMIOAccess::MMIOAccess(PhysicalAddress p_mcfg) , m_segments(*new HashMap()) , m_mapped_address(ChangeableAddress(0xFFFF, 0xFF, 0xFF, 0xFF)) { - kprintf("PCI: Using MMIO Mechanism for PCI Configuartion Space Access\n"); + klog() << "PCI: Using MMIO Mechanism for PCI Configuartion Space Access"; m_mmio_window_region = MM.allocate_kernel_region(PAGE_ROUND_UP(PCI_MMIO_CONFIG_SPACE_SIZE), "PCI MMIO", Region::Access::Read | Region::Access::Write); auto checkup_region = MM.allocate_kernel_region(p_mcfg.page_base(), (PAGE_SIZE * 2), "PCI MCFG Checkup", Region::Access::Read | Region::Access::Write); @@ -70,7 +70,7 @@ PCI::MMIOAccess::MMIOAccess(PhysicalAddress p_mcfg) u32 length = sdt->length; u8 revision = sdt->revision; - kprintf("PCI: MCFG, length - %u, revision %d\n", length, revision); + klog() << "PCI: MCFG, length - " << length << ", revision " << revision; checkup_region->unmap(); auto mcfg_region = MM.allocate_kernel_region(p_mcfg.page_base(), PAGE_ROUND_UP(length) + PAGE_SIZE, "PCI Parsing MCFG", Region::Access::Read | Region::Access::Write); @@ -86,10 +86,10 @@ PCI::MMIOAccess::MMIOAccess(PhysicalAddress p_mcfg) u32 lower_addr = mcfg.descriptors[index].base_addr; m_segments.set(index, new PCI::MMIOSegment(PhysicalAddress(lower_addr), start_bus, end_bus)); - kprintf("PCI: New PCI segment @ P 0x%x, PCI buses (%d-%d)\n", lower_addr, start_bus, end_bus); + klog() << "PCI: New PCI segment @ P " << String::format("%p", lower_addr) << ", PCI buses (" << start_bus << "-" << end_bus << ")"; } mcfg_region->unmap(); - kprintf("PCI: MMIO segments - %d\n", m_segments.size()); + klog() << "PCI: MMIO segments - " << m_segments.size(); InterruptDisabler disabler; #ifdef PCI_DEBUG dbg() << "PCI: mapped address (" << String::format("%w", m_mapped_address.seg()) << ":" << String::format("%b", m_mapped_address.bus()) << ":" << String::format("%b", m_mapped_address.slot()) << "." << String::format("%b", m_mapped_address.function()) << ")"; diff --git a/Kernel/Process.cpp b/Kernel/Process.cpp index 3f6679b1f0..5c22737c90 100644 --- a/Kernel/Process.cpp +++ b/Kernel/Process.cpp @@ -742,7 +742,7 @@ pid_t Process::sys$fork(RegisterState& regs) g_processes->prepend(child); } #ifdef TASK_DEBUG - kprintf("Process %u (%s) forked from %u @ %p\n", child->pid(), child->name().characters(), m_pid, child_tss.eip); + klog() << "Process " << child->pid() << " (" << child->name().characters() << ") forked from " << m_pid << " @ " << String::format("%p", child_tss.eip); #endif child_first_thread->set_state(Thread::State::Skip1SchedulerPass); @@ -915,14 +915,14 @@ int Process::do_exec(NonnullRefPtr main_program_description, Ve }; bool success = loader->load(); if (!success) { - kprintf("do_exec: Failure loading %s\n", path.characters()); + klog() << "do_exec: Failure loading " << path.characters(); return -ENOEXEC; } // FIXME: Validate that this virtual address is within executable region, // instead of just non-null. You could totally have a DSO with entry point of // the beginning of the text segement. if (!loader->entry().offset(totally_random_offset).get()) { - kprintf("do_exec: Failure loading %s, entry pointer is invalid! (%p)\n", path.characters(), loader->entry().offset(totally_random_offset).get()); + klog() << "do_exec: Failure loading " << path.characters() << ", entry pointer is invalid! (" << String::format("%p", loader->entry().offset(totally_random_offset).get()) << ")"; return -ENOEXEC; } @@ -934,7 +934,7 @@ int Process::do_exec(NonnullRefPtr main_program_description, Ve kill_threads_except_self(); #ifdef EXEC_DEBUG - kprintf("Memory layout after ELF load:"); + klog() << "Memory layout after ELF load:"; dump_regions(); #endif } @@ -1033,7 +1033,7 @@ int Process::do_exec(NonnullRefPtr main_program_description, Ve tss.ss2 = m_pid; #ifdef TASK_DEBUG - kprintf("Process %u (%s) exec'd %s @ %p\n", pid(), name().characters(), path.characters(), tss.eip); + klog() << "Process exec'd " << path.characters() << " @ " << String::format("%p", tss.eip); #endif if (was_profiling) @@ -1315,7 +1315,7 @@ Process* Process::create_user_process(Thread*& first_thread, const String& path, g_processes->prepend(process); } #ifdef TASK_DEBUG - kprintf("Process %u (%s) spawned @ %p\n", process->pid(), process->name().characters(), first_thread->tss().eip); + klog() << "Process " << process->pid() << " (" << process->name().characters() << ") spawned @ " << String::format("%p", first_thread->tss().eip); #endif error = 0; return process; @@ -1330,7 +1330,7 @@ Process* Process::create_kernel_process(Thread*& first_thread, String&& name, vo InterruptDisabler disabler; g_processes->prepend(process); #ifdef TASK_DEBUG - kprintf("Kernel process %u (%s) spawned @ %p\n", process->pid(), process->name().characters(), first_thread->tss().eip); + klog() << "Kernel process " << process->pid() << " (" << process->name().characters() << ") spawned @ " << String::format("%p", first_thread->tss().eip); #endif } @@ -1376,22 +1376,11 @@ Process::~Process() void Process::dump_regions() { - kprintf("Process %s(%u) regions:\n", name().characters(), pid()); - kprintf("BEGIN END SIZE ACCESS NAME\n"); + klog() << "Process regions:"; + klog() << "BEGIN END SIZE ACCESS NAME"; for (auto& region : m_regions) { - kprintf("%08x -- %08x %08x %c%c%c%c%c%c %s\n", - region.vaddr().get(), - region.vaddr().offset(region.size() - 1).get(), - region.size(), - region.is_readable() ? 'R' : ' ', - region.is_writable() ? 'W' : ' ', - region.is_executable() ? 'X' : ' ', - region.is_shared() ? 'S' : ' ', - region.is_stack() ? 'T' : ' ', - region.vmobject().is_purgeable() ? 'P' : ' ', - region.name().characters()); + klog() << String::format("%08x", region.vaddr().get()) << " -- " << String::format("%08x", region.vaddr().offset(region.size() - 1).get()) << " " << String::format("%08x", region.size()) << " " << (region.is_readable() ? 'R' : ' ') << (region.is_writable() ? 'W' : ' ') << (region.is_executable() ? 'X' : ' ') << (region.is_shared() ? 'S' : ' ') << (region.is_stack() ? 'T' : ' ') << (region.vmobject().is_purgeable() ? 'P' : ' ') << " " << region.name().characters(); } - MM.dump_kernel_regions(); } @@ -1399,7 +1388,7 @@ void Process::sys$exit(int status) { cli(); #ifdef TASK_DEBUG - kprintf("sys$exit: %s(%u) exit with status %d\n", name().characters(), pid(), status); + klog() << "sys$exit: exit with status " << status; #endif if (status != 0) @@ -2145,7 +2134,7 @@ KResult Process::do_kill(Process& process, int signal) if (!is_superuser() && m_euid != process.m_uid && m_uid != process.m_uid) return KResult(-EPERM); if (process.is_ring0() && signal == SIGKILL) { - kprintf("%s(%u) attempted to send SIGKILL to ring 0 process %s(%u)\n", name().characters(), m_pid, process.name().characters(), process.pid()); + klog() << "attempted to send SIGKILL to ring 0 process " << process.name().characters() << "(" << process.pid() << ")"; return KResult(-EPERM); } if (signal != 0) @@ -3561,7 +3550,7 @@ int Process::sys$shbuf_create(int size, void** buffer) copy_to_user(buffer, &address); ASSERT((int)shared_buffer->size() >= size); #ifdef SHARED_BUFFER_DEBUG - kprintf("%s(%u): Created shared buffer %d @ %p (%u bytes, vmobject is %u)\n", name().characters(), pid(), shbuf_id, buffer, size, shared_buffer->size()); + klog() << "Created shared buffer " << shbuf_id << " @ " << buffer << " (" << size << " bytes, vmobject is " << shared_buffer->size() << ")"; #endif shared_buffers().resource().set(shbuf_id, move(shared_buffer)); @@ -3615,7 +3604,7 @@ int Process::sys$shbuf_release(int shbuf_id) if (!shared_buffer.is_shared_with(m_pid)) return -EPERM; #ifdef SHARED_BUFFER_DEBUG - kprintf("%s(%u): Releasing shared buffer %d, buffer count: %u\n", name().characters(), pid(), shbuf_id, shared_buffers().resource().size()); + klog() << "Releasing shared buffer " << shbuf_id << ", buffer count: " << shared_buffers().resource().size(); #endif shared_buffer.deref_for_process(*this); return 0; @@ -3634,7 +3623,7 @@ void* Process::sys$shbuf_get(int shbuf_id, size_t* user_size) if (!shared_buffer.is_shared_with(m_pid)) return (void*)-EPERM; #ifdef SHARED_BUFFER_DEBUG - kprintf("%s(%u): Retaining shared buffer %d, buffer count: %u\n", name().characters(), pid(), shbuf_id, shared_buffers().resource().size()); + klog() << "Retaining shared buffer " << shbuf_id << ", buffer count: " << shared_buffers().resource().size(); #endif if (user_size) { size_t size = shared_buffer.size(); @@ -3654,7 +3643,7 @@ int Process::sys$shbuf_seal(int shbuf_id) if (!shared_buffer.is_shared_with(m_pid)) return -EPERM; #ifdef SHARED_BUFFER_DEBUG - kprintf("%s(%u): Sealing shared buffer %d\n", name().characters(), pid(), shbuf_id); + klog() << "Sealing shared buffer " << shbuf_id; #endif shared_buffer.seal(); return 0; @@ -3671,7 +3660,7 @@ int Process::sys$shbuf_set_volatile(int shbuf_id, bool state) if (!shared_buffer.is_shared_with(m_pid)) return -EPERM; #ifdef SHARED_BUFFER_DEBUG - kprintf("%s(%u): Set shared buffer %d volatile: %u\n", name().characters(), pid(), shbuf_id, state); + klog() << "Set shared buffer " << shbuf_id << " volatile: " << state; #endif if (!state) { bool was_purged = shared_buffer.vmobject().was_purged(); diff --git a/Kernel/RTC.cpp b/Kernel/RTC.cpp index 8c5e0d9eb9..c1f1ed55b8 100644 --- a/Kernel/RTC.cpp +++ b/Kernel/RTC.cpp @@ -25,6 +25,7 @@ */ #include +#include #include #include @@ -154,7 +155,7 @@ time_t now() unsigned year, month, day, hour, minute, second; read_registers(year, month, day, hour, minute, second); - kprintf("year: %d, month: %d, day: %d\n", year, month, day); + klog() << "year: " << year << ", month: " << month << ", day: " << day; ASSERT(year >= 2018); diff --git a/Kernel/SharedBuffer.cpp b/Kernel/SharedBuffer.cpp index 32b67a4ecd..3ca3feb99c 100644 --- a/Kernel/SharedBuffer.cpp +++ b/Kernel/SharedBuffer.cpp @@ -173,7 +173,7 @@ void SharedBuffer::destroy_if_unused() sanity_check("destroy_if_unused"); if (m_total_refs == 0) { #ifdef SHARED_BUFFER_DEBUG - kprintf("Destroying unused SharedBuffer{%p} id: %d\n", this, m_shbuf_id); + dbg() << "Destroying unused SharedBuffer{" << this << "} id: " << m_shbuf_id; #endif auto count_before = shared_buffers().resource().size(); shared_buffers().resource().remove(m_shbuf_id); diff --git a/Kernel/Syscall.cpp b/Kernel/Syscall.cpp index ed8cb39aa3..f3eb90ef02 100644 --- a/Kernel/Syscall.cpp +++ b/Kernel/Syscall.cpp @@ -70,7 +70,7 @@ static int handle(RegisterState&, u32 function, u32 arg1, u32 arg2, u32 arg3); void initialize() { register_user_callable_interrupt_handler(0x82, syscall_asm_entry); - kprintf("Syscall: int 0x82 handler installed\n"); + klog() << "Syscall: int 0x82 handler installed"; } #pragma GCC diagnostic ignored "-Wcast-function-type" diff --git a/Kernel/TestModule.cpp b/Kernel/TestModule.cpp index 2e2969573a..3be421c934 100644 --- a/Kernel/TestModule.cpp +++ b/Kernel/TestModule.cpp @@ -30,17 +30,14 @@ extern "C" const char module_name[] = "TestModule"; extern "C" void module_init() { - kprintf("TestModule has booted!\n"); + klog() << "TestModule has booted!"; for (int i = 0; i < 3; ++i) { - kprintf("i is now %d\n", i); + klog() << "i is now " << i; } - - kprintf("current pid: %d\n", Process::current->sys$getpid()); - kprintf("current process name: %s\n", Process::current->name().characters()); } extern "C" void module_fini() { - kprintf("TestModule is being removed!\n"); + klog() << "TestModule is being removed!"; } diff --git a/Kernel/Thread.cpp b/Kernel/Thread.cpp index bf7d1df503..10d880c331 100644 --- a/Kernel/Thread.cpp +++ b/Kernel/Thread.cpp @@ -284,7 +284,7 @@ const char* Thread::state_string() const ASSERT(m_blocker != nullptr); return m_blocker->state_string(); } - kprintf("Thread::state_string(): Invalid state: %u\n", state()); + klog() << "Thread::state_string(): Invalid state: " << state(); ASSERT_NOT_REACHED(); return nullptr; } @@ -485,7 +485,7 @@ ShouldUnblockThread Thread::dispatch_signal(u8 signal) ASSERT(!process().is_ring0()); #ifdef SIGNAL_DEBUG - kprintf("dispatch_signal %s(%u) <- %u\n", process().name().characters(), pid(), signal); + klog() << "dispatch_signal <- " << signal; #endif auto& action = m_signal_action_data[signal]; @@ -536,7 +536,7 @@ ShouldUnblockThread Thread::dispatch_signal(u8 signal) if (handler_vaddr.as_ptr() == SIG_IGN) { #ifdef SIGNAL_DEBUG - kprintf("%s(%u) ignored signal %u\n", process().name().characters(), pid(), signal); + klog() << "ignored signal " << signal; #endif return ShouldUnblockThread::Yes; } @@ -612,7 +612,7 @@ ShouldUnblockThread Thread::dispatch_signal(u8 signal) } #ifdef SIGNAL_DEBUG - kprintf("signal: Okay, %s(%u) {%s} has been primed with signal handler %w:%x\n", process().name().characters(), pid(), state_string(), m_tss.cs, m_tss.eip); + klog() << "signal: Okay, {" << state_string() << "} has been primed with signal handler " << String::format("%w", m_tss.cs) << ":" << String::format("%x", m_tss.eip); #endif return ShouldUnblockThread::Yes; } diff --git a/Kernel/VM/MemoryManager.cpp b/Kernel/VM/MemoryManager.cpp index 9e8a47a843..88de838f16 100644 --- a/Kernel/VM/MemoryManager.cpp +++ b/Kernel/VM/MemoryManager.cpp @@ -31,11 +31,11 @@ #include #include #include -#include #include #include #include #include +#include #include //#define MM_DEBUG @@ -121,13 +121,7 @@ void MemoryManager::parse_memory_map() auto* mmap = (multiboot_memory_map_t*)(low_physical_to_virtual(multiboot_info_ptr->mmap_addr)); for (; (unsigned long)mmap < (low_physical_to_virtual(multiboot_info_ptr->mmap_addr)) + (multiboot_info_ptr->mmap_length); mmap = (multiboot_memory_map_t*)((unsigned long)mmap + mmap->size + sizeof(mmap->size))) { - kprintf("MM: Multiboot mmap: base_addr = 0x%x%08x, length = 0x%x%08x, type = 0x%x\n", - (uintptr_t)(mmap->addr >> 32), - (uintptr_t)(mmap->addr & 0xffffffff), - (uintptr_t)(mmap->len >> 32), - (uintptr_t)(mmap->len & 0xffffffff), - (uintptr_t)mmap->type); - + klog() << "MM: Multiboot mmap: base_addr = " << String::format("0x%08x", mmap->addr) << ", length = " << String::format("0x%08x", mmap->len) << ", type = 0x" << String::format("%x", mmap->type); if (mmap->type != MULTIBOOT_MEMORY_AVAILABLE) continue; @@ -140,23 +134,22 @@ void MemoryManager::parse_memory_map() auto diff = (uintptr_t)mmap->addr % PAGE_SIZE; if (diff != 0) { - kprintf("MM: got an unaligned region base from the bootloader; correcting %p by %d bytes\n", mmap->addr, diff); + klog() << "MM: got an unaligned region base from the bootloader; correcting " << String::format("%p", mmap->addr) << " by " << diff << " bytes"; diff = PAGE_SIZE - diff; mmap->addr += diff; mmap->len -= diff; } if ((mmap->len % PAGE_SIZE) != 0) { - kprintf("MM: got an unaligned region length from the bootloader; correcting %d by %d bytes\n", mmap->len, mmap->len % PAGE_SIZE); + klog() << "MM: got an unaligned region length from the bootloader; correcting " << mmap->len << " by " << (mmap->len % PAGE_SIZE) << " bytes"; mmap->len -= mmap->len % PAGE_SIZE; } if (mmap->len < PAGE_SIZE) { - kprintf("MM: memory region from bootloader is too small; we want >= %d bytes, but got %d bytes\n", PAGE_SIZE, mmap->len); + klog() << "MM: memory region from bootloader is too small; we want >= " << PAGE_SIZE << " bytes, but got " << mmap->len << " bytes"; continue; } #ifdef MM_DEBUG - kprintf("MM: considering memory at %p - %p\n", - (uintptr_t)mmap->addr, (uintptr_t)(mmap->addr + mmap->len)); + klog() << "MM: considering memory at " << String::format("%p", (uintptr_t)mmap->addr) << " - " << String::format("%p", (uintptr_t)(mmap->addr + mmap->len)); #endif for (size_t page_base = mmap->addr; page_base < (mmap->addr + mmap->len); page_base += PAGE_SIZE) { @@ -301,7 +294,7 @@ PageFaultResponse MemoryManager::handle_page_fault(const PageFault& fault) #endif auto* region = region_from_vaddr(fault.vaddr()); if (!region) { - kprintf("NP(error) fault at invalid address V%p\n", fault.vaddr().get()); + klog() << "NP(error) fault at invalid address V" << String::format("%p", fault.vaddr().get()); return PageFaultResponse::ShouldCrash; } @@ -366,9 +359,7 @@ void MemoryManager::deallocate_user_physical_page(PhysicalPage&& page) { for (auto& region : m_user_physical_regions) { if (!region.contains(page)) { - kprintf( - "MM: deallocate_user_physical_page: %p not in %p -> %p\n", - page.paddr().get(), region.lower().get(), region.upper().get()); + klog() << "MM: deallocate_user_physical_page: " << page.paddr() << " not in " << region.lower() << " -> " << region.upper(); continue; } @@ -378,7 +369,7 @@ void MemoryManager::deallocate_user_physical_page(PhysicalPage&& page) return; } - kprintf("MM: deallocate_user_physical_page couldn't figure out region for user page @ %p\n", page.paddr().get()); + klog() << "MM: deallocate_user_physical_page couldn't figure out region for user page @ " << page.paddr(); ASSERT_NOT_REACHED(); } @@ -400,7 +391,7 @@ RefPtr MemoryManager::allocate_user_physical_page(ShouldZeroFill s if (!page) { if (m_user_physical_regions.is_empty()) { - kprintf("MM: no user physical regions available (?)\n"); + klog() << "MM: no user physical regions available (?)"; } for_each_vmobject([&](auto& vmobject) { @@ -408,7 +399,7 @@ RefPtr MemoryManager::allocate_user_physical_page(ShouldZeroFill s auto& purgeable_vmobject = static_cast(vmobject); int purged_page_count = purgeable_vmobject.purge_with_interrupts_disabled({}); if (purged_page_count) { - kprintf("MM: Purge saved the day! Purged %d pages from PurgeableVMObject{%p}\n", purged_page_count, &purgeable_vmobject); + klog() << "MM: Purge saved the day! Purged " << purged_page_count << " pages from PurgeableVMObject{" << &purgeable_vmobject << "}"; page = find_free_user_physical_page(); ASSERT(page); return IterationDecision::Break; @@ -418,7 +409,7 @@ RefPtr MemoryManager::allocate_user_physical_page(ShouldZeroFill s }); if (!page) { - kprintf("MM: no user physical pages available\n"); + klog() << "MM: no user physical pages available"; ASSERT_NOT_REACHED(); return {}; } @@ -442,9 +433,7 @@ void MemoryManager::deallocate_supervisor_physical_page(PhysicalPage&& page) { for (auto& region : m_super_physical_regions) { if (!region.contains(page)) { - kprintf( - "MM: deallocate_supervisor_physical_page: %p not in %p -> %p\n", - page.paddr().get(), region.lower().get(), region.upper().get()); + klog() << "MM: deallocate_supervisor_physical_page: " << page.paddr() << " not in " << region.lower() << " -> " << region.upper(); continue; } @@ -453,7 +442,7 @@ void MemoryManager::deallocate_supervisor_physical_page(PhysicalPage&& page) return; } - kprintf("MM: deallocate_supervisor_physical_page couldn't figure out region for super page @ %p\n", page.paddr().get()); + klog() << "MM: deallocate_supervisor_physical_page couldn't figure out region for super page @ " << page.paddr(); ASSERT_NOT_REACHED(); } @@ -470,10 +459,10 @@ RefPtr MemoryManager::allocate_supervisor_physical_page() if (!page) { if (m_super_physical_regions.is_empty()) { - kprintf("MM: no super physical regions available (?)\n"); + klog() << "MM: no super physical regions available (?)"; } - kprintf("MM: no super physical pages available\n"); + klog() << "MM: no super physical pages available"; ASSERT_NOT_REACHED(); return {}; } @@ -680,20 +669,10 @@ void MemoryManager::unregister_region(Region& region) void MemoryManager::dump_kernel_regions() { - kprintf("Kernel regions:\n"); - kprintf("BEGIN END SIZE ACCESS NAME\n"); + klog() << "Kernel regions:"; + klog() << "BEGIN END SIZE ACCESS NAME"; for (auto& region : MM.m_kernel_regions) { - kprintf("%08x -- %08x %08x %c%c%c%c%c%c %s\n", - region.vaddr().get(), - region.vaddr().offset(region.size() - 1).get(), - region.size(), - region.is_readable() ? 'R' : ' ', - region.is_writable() ? 'W' : ' ', - region.is_executable() ? 'X' : ' ', - region.is_shared() ? 'S' : ' ', - region.is_stack() ? 'T' : ' ', - region.vmobject().is_purgeable() ? 'P' : ' ', - region.name().characters()); + klog() << String::format("%08x", region.vaddr().get()) << " -- " << String::format("%08x", region.vaddr().offset(region.size() - 1).get()) << " " << String::format("%08x", region.size()) << " " << (region.is_readable() ? 'R' : ' ') << (region.is_writable() ? 'W' : ' ') << (region.is_executable() ? 'X' : ' ') << (region.is_shared() ? 'S' : ' ') << (region.is_stack() ? 'T' : ' ') << (region.vmobject().is_purgeable() ? 'P' : ' ') << " " << region.name().characters(); } } diff --git a/Kernel/VM/PageDirectory.cpp b/Kernel/VM/PageDirectory.cpp index 0f6fc4ad72..aff510ce72 100644 --- a/Kernel/VM/PageDirectory.cpp +++ b/Kernel/VM/PageDirectory.cpp @@ -63,9 +63,9 @@ PageDirectory::PageDirectory() PhysicalAddress boot_pdpt_paddr(virtual_to_low_physical((uintptr_t)boot_pdpt)); PhysicalAddress boot_pd0_paddr(virtual_to_low_physical((uintptr_t)boot_pd0)); PhysicalAddress boot_pd3_paddr(virtual_to_low_physical((uintptr_t)boot_pd3)); - kprintf("MM: boot_pdpt @ P%p\n", boot_pdpt_paddr.get()); - kprintf("MM: boot_pd0 @ P%p\n", boot_pd0_paddr.get()); - kprintf("MM: boot_pd3 @ P%p\n", boot_pd3_paddr.get()); + klog() << "MM: boot_pdpt @ " << boot_pdpt_paddr; + klog() << "MM: boot_pd0 @ " << boot_pd0_paddr; + klog() << "MM: boot_pd3 @ " << boot_pd3_paddr; m_directory_table = PhysicalPage::create(boot_pdpt_paddr, true, false); m_directory_pages[0] = PhysicalPage::create(boot_pd0_paddr, true, false); m_directory_pages[3] = PhysicalPage::create(boot_pd3_paddr, true, false); diff --git a/Kernel/VM/RangeAllocator.cpp b/Kernel/VM/RangeAllocator.cpp index edbb76192d..6ceee3ce68 100644 --- a/Kernel/VM/RangeAllocator.cpp +++ b/Kernel/VM/RangeAllocator.cpp @@ -130,7 +130,7 @@ Range RangeAllocator::allocate_anywhere(size_t size, size_t alignment) #endif return allocated_range; } - kprintf("VRA: Failed to allocate anywhere: %zu, %zu\n", size, alignment); + klog() << "VRA: Failed to allocate anywhere: " << size << ", " << alignment; return {}; } @@ -155,7 +155,7 @@ Range RangeAllocator::allocate_specific(VirtualAddress base, size_t size) #endif return allocated_range; } - kprintf("VRA: Failed to allocate specific range: %x(%u)\n", base.get(), size); + dbg() << "VRA: Failed to allocate specific range: " << base << "(" << size << ")"; return {}; } diff --git a/Kernel/VM/Region.cpp b/Kernel/VM/Region.cpp index 1fd3b48cba..d498ca910a 100644 --- a/Kernel/VM/Region.cpp +++ b/Kernel/VM/Region.cpp @@ -124,7 +124,7 @@ bool Region::commit(size_t page_index) return true; auto physical_page = MM.allocate_user_physical_page(MemoryManager::ShouldZeroFill::Yes); if (!physical_page) { - kprintf("MM: commit was unable to allocate a physical page\n"); + klog() << "MM: commit was unable to allocate a physical page"; return false; } vmobject_physical_page_entry = move(physical_page); @@ -322,7 +322,7 @@ PageFaultResponse Region::handle_fault(const PageFault& fault) } return handle_cow_fault(page_index_in_region); } - kprintf("PV(error) fault in Region{%p}[%u] at V%p\n", this, page_index_in_region, fault.vaddr().get()); + dbg() << "PV(error) fault in Region{" << this << "}[" << page_index_in_region << "] at " << fault.vaddr(); return PageFaultResponse::ShouldCrash; } @@ -350,7 +350,7 @@ PageFaultResponse Region::handle_zero_fault(size_t page_index_in_region) auto physical_page = MM.allocate_user_physical_page(MemoryManager::ShouldZeroFill::Yes); if (physical_page.is_null()) { - kprintf("MM: handle_zero_fault was unable to allocate a physical page\n"); + klog() << "MM: handle_zero_fault was unable to allocate a physical page"; return PageFaultResponse::ShouldCrash; } @@ -385,7 +385,7 @@ PageFaultResponse Region::handle_cow_fault(size_t page_index_in_region) auto physical_page_to_copy = move(vmobject_physical_page_entry); auto physical_page = MM.allocate_user_physical_page(MemoryManager::ShouldZeroFill::No); if (physical_page.is_null()) { - kprintf("MM: handle_cow_fault was unable to allocate a physical page\n"); + klog() << "MM: handle_cow_fault was unable to allocate a physical page"; return PageFaultResponse::ShouldCrash; } u8* dest_ptr = MM.quickmap_page(*physical_page); @@ -436,7 +436,7 @@ PageFaultResponse Region::handle_inode_fault(size_t page_index_in_region) auto& inode = inode_vmobject.inode(); auto nread = inode.read_bytes((first_page_index() + page_index_in_region) * PAGE_SIZE, PAGE_SIZE, page_buffer, nullptr); if (nread < 0) { - kprintf("MM: handle_inode_fault had error (%d) while reading!\n", nread); + klog() << "MM: handle_inode_fault had error (" << nread << ") while reading!"; return PageFaultResponse::ShouldCrash; } if (nread < PAGE_SIZE) { @@ -446,7 +446,7 @@ PageFaultResponse Region::handle_inode_fault(size_t page_index_in_region) cli(); vmobject_physical_page_entry = MM.allocate_user_physical_page(MemoryManager::ShouldZeroFill::No); if (vmobject_physical_page_entry.is_null()) { - kprintf("MM: handle_inode_fault was unable to allocate a physical page\n"); + klog() << "MM: handle_inode_fault was unable to allocate a physical page"; return PageFaultResponse::ShouldCrash; } diff --git a/Kernel/init.cpp b/Kernel/init.cpp index 956d461e81..33407c7ecd 100644 --- a/Kernel/init.cpp +++ b/Kernel/init.cpp @@ -117,7 +117,7 @@ extern "C" [[noreturn]] void init() new Console; - kprintf("Starting SerenityOS...\n"); + klog() << "Starting SerenityOS..."; __stack_chk_guard = get_good_random(); @@ -146,7 +146,7 @@ extern "C" [[noreturn]] void init() VirtualConsole::switch_to(0); // Sample test to see if the ACPI parser is working... - kprintf("ACPI: HPET table @ P 0x%x\n", ACPI::Parser::the().find_table("HPET").get()); + klog() << "ACPI: HPET table @ " << ACPI::Parser::the().find_table("HPET"); setup_pci(); @@ -229,7 +229,7 @@ void init_stage2() } if (!root.starts_with("/dev/hda")) { - kprintf("init_stage2: root filesystem must be on the first IDE hard drive (/dev/hda)\n"); + klog() << "init_stage2: root filesystem must be on the first IDE hard drive (/dev/hda)"; hang(); } @@ -243,14 +243,14 @@ void init_stage2() unsigned partition_number = root.to_uint(ok); if (!ok) { - kprintf("init_stage2: couldn't parse partition number from root kernel parameter\n"); + klog() << "init_stage2: couldn't parse partition number from root kernel parameter"; hang(); } MBRPartitionTable mbr(root_dev); if (!mbr.initialize()) { - kprintf("init_stage2: couldn't read MBR from disk\n"); + klog() << "init_stage2: couldn't read MBR from disk"; hang(); } @@ -258,12 +258,12 @@ void init_stage2() dbg() << "GPT Partitioned Storage Detected!"; GPTPartitionTable gpt(root_dev); if (!gpt.initialize()) { - kprintf("init_stage2: couldn't read GPT from disk\n"); + klog() << "init_stage2: couldn't read GPT from disk"; hang(); } auto partition = gpt.partition(partition_number); if (!partition) { - kprintf("init_stage2: couldn't get partition %d\n", partition_number); + klog() << "init_stage2: couldn't get partition " << partition_number; hang(); } root_dev = *partition; @@ -272,23 +272,23 @@ void init_stage2() if (mbr.contains_ebr()) { EBRPartitionTable ebr(root_dev); if (!ebr.initialize()) { - kprintf("init_stage2: couldn't read EBR from disk\n"); + klog() << "init_stage2: couldn't read EBR from disk"; hang(); } auto partition = ebr.partition(partition_number); if (!partition) { - kprintf("init_stage2: couldn't get partition %d\n", partition_number); + klog() << "init_stage2: couldn't get partition " << partition_number; hang(); } root_dev = *partition; } else { if (partition_number < 1 || partition_number > 4) { - kprintf("init_stage2: invalid partition number %d; expected 1 to 4\n", partition_number); + klog() << "init_stage2: invalid partition number " << partition_number << "; expected 1 to 4"; hang(); } auto partition = mbr.partition(partition_number); if (!partition) { - kprintf("init_stage2: couldn't get partition %d\n", partition_number); + klog() << "init_stage2: couldn't get partition " << partition_number; hang(); } root_dev = *partition; @@ -297,12 +297,12 @@ void init_stage2() } auto e2fs = Ext2FS::create(root_dev); if (!e2fs->initialize()) { - kprintf("init_stage2: couldn't open root filesystem\n"); + klog() << "init_stage2: couldn't open root filesystem"; hang(); } if (!VFS::the().mount_root(e2fs)) { - kprintf("VFS::mount_root failed\n"); + klog() << "VFS::mount_root failed"; hang(); } @@ -318,16 +318,16 @@ void init_stage2() RefPtr fd1; if ((detect >> 4) & 0x4) { fd0 = FloppyDiskDevice::create(FloppyDiskDevice::DriveType::Master); - kprintf("fd0 is 1.44MB floppy drive\n"); + klog() << "fd0 is 1.44MB floppy drive"; } else { - kprintf("fd0 type unsupported! Type == 0x%x\n", detect >> 4); + klog() << "fd0 type unsupported! Type == 0x", String::format("%x", detect >> 4); } if (detect & 0x0f) { fd1 = FloppyDiskDevice::create(FloppyDiskDevice::DriveType::Slave); - kprintf("fd1 is 1.44MB floppy drive"); + klog() << "fd1 is 1.44MB floppy drive"; } else { - kprintf("fd1 type unsupported! Type == 0x%x\n", detect & 0x0f); + klog() << "fd1 type unsupported! Type == 0x", String::format("%x", detect & 0x0f); } int error; @@ -340,7 +340,7 @@ void init_stage2() Thread* thread = nullptr; Process::create_user_process(thread, "/bin/Shell", (uid_t)0, (gid_t)0, (pid_t)0, error, {}, {}, tty0); if (error != 0) { - kprintf("init_stage2: error spawning Shell: %d\n", error); + klog() << "init_stage2: error spawning Shell: " << error; hang(); } thread->set_priority(THREAD_PRIORITY_HIGH); @@ -349,7 +349,7 @@ void init_stage2() Thread* thread = nullptr; Process::create_user_process(thread, "/bin/SystemServer", (uid_t)0, (gid_t)0, (pid_t)0, error, {}, {}, tty0); if (error != 0) { - kprintf("init_stage2: error spawning SystemServer: %d\n", error); + klog() << "init_stage2: error spawning SystemServer: " << error; hang(); } thread->set_priority(THREAD_PRIORITY_HIGH); @@ -376,7 +376,7 @@ void setup_serial_debug() return true; }; - // serial_debug will output all the kprintf and dbgprintf data to COM1 at + // serial_debug will output all the klog() and dbg() data to COM1 at // 8-N-1 57600 baud. this is particularly useful for debugging the boot // process on live hardware. // @@ -420,7 +420,7 @@ void setup_acpi() ACPI::StaticParser::initialize_without_rsdp(); return; } - kprintf("acpi boot argmuent has an invalid value.\n"); + klog() << "acpi boot argmuent has an invalid value."; hang(); } @@ -438,7 +438,7 @@ void setup_vmmouse() VMWareBackdoor::the().enable_absolute_vmmouse(); return; } - kprintf("vmmouse boot argmuent has an invalid value.\n"); + klog() << "vmmouse boot argmuent has an invalid value."; hang(); } @@ -455,7 +455,7 @@ void setup_pci() } else if (pci_mmio == "off") { PCI::Initializer::the().test_and_initialize(true); } else { - kprintf("pci_mmio boot argmuent has an invalid value.\n"); + klog() << "pci_mmio boot argmuent has an invalid value."; hang(); } PCI::Initializer::the().dismiss(); @@ -482,7 +482,7 @@ void setup_interrupts() return; } - kprintf("smp boot argmuent has an invalid value.\n"); + klog() << "smp boot argmuent has an invalid value."; hang(); } }