diff --git a/src/kernel/apic.cpp b/src/kernel/apic.cpp index 0a31cd9..8609ce7 100644 --- a/src/kernel/apic.cpp +++ b/src/kernel/apic.cpp @@ -32,7 +32,7 @@ apic_read(uint32_t volatile *apic, uint16_t offset) static void apic_write(uint32_t volatile *apic, uint16_t offset, uint32_t value) { - log::debug(logs::apic, "LAPIC write: %x = %08lx", offset, value); + log::spam(logs::apic, "LAPIC write: %x = %08lx", offset, value); *(apic + offset/sizeof(uint32_t)) = value; } @@ -161,7 +161,7 @@ lapic::enable_timer(isr vector, bool repeat) lvte |= 0x20000; apic_write(m_base, lapic_lvt_timer, lvte); - log::debug(logs::apic, "Enabling APIC timer at isr %02x", vector); + log::verbose(logs::apic, "Enabling APIC timer at isr %02x", vector); } uint32_t @@ -200,7 +200,7 @@ lapic::enable_lint(uint8_t num, isr vector, bool nmi, uint16_t flags) lvte |= (1 << 15); apic_write(m_base, off, lvte); - log::debug(logs::apic, "APIC LINT%d enabled as %s %d %s-triggered, active %s.", + log::verbose(logs::apic, "APIC LINT%d enabled as %s %d %s-triggered, active %s.", num, nmi ? "NMI" : "ISR", vector, polarity == 3 ? "level" : "edge", trigger == 3 ? "low" : "high"); @@ -211,7 +211,7 @@ lapic::enable() { apic_write(m_base, lapic_spurious, apic_read(m_base, lapic_spurious) | 0x100); - log::debug(logs::apic, "LAPIC enabled!"); + log::verbose(logs::apic, "LAPIC enabled!"); } void @@ -219,7 +219,7 @@ lapic::disable() { apic_write(m_base, lapic_spurious, apic_read(m_base, lapic_spurious) & ~0x100); - log::debug(logs::apic, "LAPIC disabled."); + log::verbose(logs::apic, "LAPIC disabled."); } @@ -233,7 +233,7 @@ ioapic::ioapic(uintptr_t base, uint32_t base_gsi) : m_id = (id >> 24) & 0xff; m_version = version & 0xff; m_num_gsi = (version >> 16) & 0xff; - log::debug(logs::apic, "IOAPIC %d loaded, version %d, GSIs %d-%d", + log::verbose(logs::apic, "IOAPIC %d loaded, version %d, GSIs %d-%d", m_id, m_version, base_gsi, base_gsi + (m_num_gsi - 1)); for (uint8_t i = 0; i < m_num_gsi; ++i) { @@ -246,7 +246,7 @@ ioapic::ioapic(uintptr_t base, uint32_t base_gsi) : void ioapic::redirect(uint8_t irq, isr vector, uint16_t flags, bool masked) { - log::debug(logs::apic, "IOAPIC %d redirecting irq %3d to vector %3d [%04x]%s", + log::verbose(logs::apic, "IOAPIC %d redirecting irq %3d to vector %3d [%04x]%s", m_id, irq, vector, flags, masked ? " (masked)" : ""); uint64_t entry = static_cast(vector); @@ -269,7 +269,7 @@ ioapic::redirect(uint8_t irq, isr vector, uint16_t flags, bool masked) void ioapic::mask(uint8_t irq, bool masked) { - log::debug(logs::apic, "IOAPIC %d %smasking irq %3d", + log::verbose(logs::apic, "IOAPIC %d %smasking irq %3d", m_id, masked ? "" : "un", irq); uint32_t entry = ioapic_read(m_base, (2 * irq) + 0x10); @@ -284,7 +284,7 @@ ioapic::mask(uint8_t irq, bool masked) void ioapic::dump_redirs() const { - log::debug(logs::apic, "IOAPIC %d redirections:", m_id); + log::spam(logs::apic, "IOAPIC %d redirections:", m_id); for (uint8_t i = 0; i < m_num_gsi; ++i) { uint64_t low = ioapic_read(m_base, 0x10 + (2 *i)); @@ -300,7 +300,7 @@ ioapic::dump_redirs() const uint8_t mask = (redir >> 16) & 0x1; uint8_t dest = (redir >> 56) & 0xff; - log::debug(logs::apic, " %2d: vec %3d %s active, %s-triggered %s dest %d: %x", + log::spam(logs::apic, " %2d: vec %3d %s active, %s-triggered %s dest %d: %x", m_base_gsi + i, vector, polarity ? "low" : "high", trigger ? "level" : "edge", diff --git a/src/kernel/cpu.cpp b/src/kernel/cpu.cpp index 3b9f0e7..05db372 100644 --- a/src/kernel/cpu.cpp +++ b/src/kernel/cpu.cpp @@ -38,16 +38,16 @@ cpu_validate() cpu::cpu_id::features features = cpu.validate(); log::info(logs::boot, "CPU: %s", brand_name); - log::debug(logs::boot, " Vendor is %s", cpu.vendor_id()); + log::info(logs::boot, " Vendor is %s", cpu.vendor_id()); - log::debug(logs::boot, " Higest basic CPUID: 0x%02x", cpu.highest_basic()); - log::debug(logs::boot, " Higest ext CPUID: 0x%02x", cpu.highest_ext() & ~cpu::cpu_id::cpuid_extended); + log::spam(logs::boot, " Higest basic CPUID: 0x%02x", cpu.highest_basic()); + log::spam(logs::boot, " Higest ext CPUID: 0x%02x", cpu.highest_ext() & ~cpu::cpu_id::cpuid_extended); #define CPU_FEATURE_OPT(name, ...) \ - log::debug(logs::boot, " Supports %9s: %s", #name, features[cpu::feature::name] ? "yes" : "no"); + log::verbose(logs::boot, " Supports %9s: %s", #name, features[cpu::feature::name] ? "yes" : "no"); #define CPU_FEATURE_REQ(name, feat_leaf, feat_sub, regname, bit) \ - log::debug(logs::boot, " Supports %9s: %s", #name, features[cpu::feature::name] ? "yes" : "no"); \ + log::verbose(logs::boot, " Supports %9s: %s", #name, features[cpu::feature::name] ? "yes" : "no"); \ kassert(features[cpu::feature::name], "Missing required CPU feature " #name ); #include "cpu/features.inc" @@ -121,7 +121,7 @@ bsp_late_init() asm ("mov %%cr4, %0" : "=r"(cr4v)); uint64_t efer = rdmsr(msr::ia32_efer); - log::debug(logs::boot, "Control regs: cr0:%lx cr4:%lx efer:%lx", cr0v, cr4v, efer); + log::spam(logs::boot, "Control regs: cr0:%lx cr4:%lx efer:%lx", cr0v, cr4v, efer); } cpu_data * diff --git a/src/kernel/device_manager.cpp b/src/kernel/device_manager.cpp index a0a35da..ede9f99 100644 --- a/src/kernel/device_manager.cpp +++ b/src/kernel/device_manager.cpp @@ -137,7 +137,7 @@ device_manager::load_xsdt(const acpi_table_header *header) log::info(logs::device, "ACPI 2.0+ tables loading"); put_sig(sig, xsdt->header.type); - log::debug(logs::device, " Found table %s", sig); + log::verbose(logs::device, " Found table %s", sig); size_t num_tables = acpi_table_entries(xsdt, sizeof(void*)); for (size_t i = 0; i < num_tables; ++i) { @@ -145,7 +145,7 @@ device_manager::load_xsdt(const acpi_table_header *header) mem::to_virtual(xsdt->headers[i]); put_sig(sig, header->type); - log::debug(logs::device, " Found table %s", sig); + log::verbose(logs::device, " Found table %s", sig); kassert(header->validate(), "Table failed validation."); @@ -216,7 +216,7 @@ device_manager::load_apic(const acpi_table_header *header) uint8_t id = util::read_from(p+3); m_apic_ids.append(id); - log::debug(logs::device, " Local APIC uid %x id %x", uid, id); + log::spam(logs::device, " Local APIC uid %x id %x", uid, id); } break; @@ -225,7 +225,7 @@ device_manager::load_apic(const acpi_table_header *header) uint32_t base_gsi = util::read_from(p+8); m_ioapics.emplace(base, base_gsi); - log::debug(logs::device, " IO APIC gsi %x base %x", base_gsi, base); + log::spam(logs::device, " IO APIC gsi %x base %x", base_gsi, base); } break; @@ -236,7 +236,7 @@ device_manager::load_apic(const acpi_table_header *header) o.flags = util::read_from(p+8); m_overrides.append(o); - log::debug(logs::device, " Intr source override IRQ %d -> %d Pol %d Tri %d", + log::spam(logs::device, " Intr source override IRQ %d -> %d Pol %d Tri %d", o.source, o.gsi, (o.flags & 0x3), ((o.flags >> 2) & 0x3)); } break; @@ -248,13 +248,13 @@ device_manager::load_apic(const acpi_table_header *header) nmi.flags = util::read_from(p + 3); m_nmis.append(nmi); - log::debug(logs::device, " LAPIC NMI Proc %02x LINT%d Pol %d Tri %d", + log::spam(logs::device, " LAPIC NMI Proc %02x LINT%d Pol %d Tri %d", nmi.cpu, nmi.lint, nmi.flags & 0x3, (nmi.flags >> 2) & 0x3); } break; default: - log::debug(logs::device, " APIC entry type %d", type); + log::spam(logs::device, " APIC entry type %d", type); } p += length; @@ -281,7 +281,7 @@ device_manager::load_mcfg(const acpi_table_header *header) m_pci[i].bus_end = mcfge.bus_end; m_pci[i].base = mem::to_virtual(mcfge.base); - log::debug(logs::device, " Found MCFG entry: base %lx group %d bus %d-%d", + log::spam(logs::device, " Found MCFG entry: base %lx group %d bus %d-%d", mcfge.base, mcfge.group, mcfge.bus_start, mcfge.bus_end); } @@ -293,7 +293,7 @@ device_manager::load_hpet(const acpi_table_header *header) { const auto *hpet = check_get_table(header); - log::debug(logs::device, " Found HPET device #%3d: base %016lx pmin %d attr %02x", + log::verbose(logs::device, " Found HPET device #%3d: base %016lx pmin %d attr %02x", hpet->index, hpet->base_address.address, hpet->periodic_min, hpet->attributes); uint32_t hwid = hpet->hardware_id; @@ -303,9 +303,9 @@ device_manager::load_hpet(const acpi_table_header *header) uint8_t legacy_replacement = (hwid >> 15) & 1; uint32_t pci_vendor_id = (hwid >> 16); - log::debug(logs::device, " rev:%02d comparators:%02d count_size_cap:%1d legacy_repl:%1d", + log::spam(logs::device, " rev:%02d comparators:%02d count_size_cap:%1d legacy_repl:%1d", rev_id, comparators, count_size_cap, legacy_replacement); - log::debug(logs::device, " pci vendor id: %04x", pci_vendor_id); + log::spam(logs::device, " pci vendor id: %04x", pci_vendor_id); m_hpets.emplace(hpet->index, reinterpret_cast(hpet->base_address.address + mem::linear_offset)); @@ -315,7 +315,7 @@ void device_manager::probe_pci() { for (auto &pci : m_pci) { - log::debug(logs::device, "Probing PCI group at base %016lx", pci.base); + log::verbose(logs::device, "Probing PCI group at base %016lx", pci.base); for (int bus = pci.bus_start; bus <= pci.bus_end; ++bus) { for (int dev = 0; dev < 32; ++dev) { @@ -419,7 +419,7 @@ device_manager::allocate_msi(const char *name, pci_device &device, irq_callback isr vector = isr::irq00 + irq; m_irqs.append({name, cb, data}); - log::debug(logs::device, "Allocating IRQ %02x to %s.", irq, name); + log::spam(logs::device, "Allocating IRQ %02x to %s.", irq, name); device.write_msi_regs( 0xFEE00000, diff --git a/src/kernel/hpet.cpp b/src/kernel/hpet.cpp index 08394f2..e96a9cc 100644 --- a/src/kernel/hpet.cpp +++ b/src/kernel/hpet.cpp @@ -41,30 +41,30 @@ hpet::hpet(uint8_t index, uint64_t *base) : // .install_irq(2, "HPET Timer", hpet_irq_callback, this); // kassert(installed, "Installing HPET IRQ handler"); - log::debug(logs::timer, "HPET %d capabilities:", index); - log::debug(logs::timer, " revision: %d", caps & 0xff); - log::debug(logs::timer, " timers: %d", m_timers); - log::debug(logs::timer, " bits: %d", ((caps >> 13) & 1) ? 64 : 32); - log::debug(logs::timer, " LRR capable: %d", ((caps >> 15) & 1)); - log::debug(logs::timer, " period: %dns", m_period / 1000000); - log::debug(logs::timer, " global enabled: %d", config & 1); - log::debug(logs::timer, " LRR enable: %d", (config >> 1) & 1); + log::spam(logs::timer, "HPET %d capabilities:", index); + log::spam(logs::timer, " revision: %d", caps & 0xff); + log::spam(logs::timer, " timers: %d", m_timers); + log::spam(logs::timer, " bits: %d", ((caps >> 13) & 1) ? 64 : 32); + log::spam(logs::timer, " LRR capable: %d", ((caps >> 15) & 1)); + log::spam(logs::timer, " period: %dns", m_period / 1000000); + log::spam(logs::timer, " global enabled: %d", config & 1); + log::spam(logs::timer, " LRR enable: %d", (config >> 1) & 1); for (unsigned i = 0; i < m_timers; ++i) { disable_timer(i); uint64_t config = *timer_config(m_base, i); - log::debug(logs::timer, "HPET %d timer %d:", index, i); - log::debug(logs::timer, " int type: %d", (config >> 1) & 1); - log::debug(logs::timer, " int enable: %d", (config >> 2) & 1); - log::debug(logs::timer, " timer type: %d", (config >> 3) & 1); - log::debug(logs::timer, " periodic cap: %d", (config >> 4) & 1); - log::debug(logs::timer, " bits: %d", ((config >> 5) & 1) ? 64 : 32); - log::debug(logs::timer, " 32 mode: %d", (config >> 8) & 1); - log::debug(logs::timer, " int route: %d", (config >> 9) & 0x1f); - log::debug(logs::timer, " FSB enable: %d", (config >> 14) & 1); - log::debug(logs::timer, " FSB capable: %d", (config >> 15) & 1); - log::debug(logs::timer, " rotung cap: %08x", (config >> 32)); + log::spam(logs::timer, "HPET %d timer %d:", index, i); + log::spam(logs::timer, " int type: %d", (config >> 1) & 1); + log::spam(logs::timer, " int enable: %d", (config >> 2) & 1); + log::spam(logs::timer, " timer type: %d", (config >> 3) & 1); + log::spam(logs::timer, " periodic cap: %d", (config >> 4) & 1); + log::spam(logs::timer, " bits: %d", ((config >> 5) & 1) ? 64 : 32); + log::spam(logs::timer, " 32 mode: %d", (config >> 8) & 1); + log::spam(logs::timer, " int route: %d", (config >> 9) & 0x1f); + log::spam(logs::timer, " FSB enable: %d", (config >> 14) & 1); + log::spam(logs::timer, " FSB capable: %d", (config >> 15) & 1); + log::spam(logs::timer, " rotung cap: %08x", (config >> 32)); } } @@ -95,13 +95,13 @@ hpet::disable_timer(unsigned timer) void hpet::callback() { - log::debug(logs::timer, "HPET %d got irq", m_index); + log::spam(logs::timer, "HPET %d got irq", m_index); } void hpet::enable() { - log::debug(logs::timer, "HPET %d enabling", m_index); + log::verbose(logs::timer, "HPET %d enabling", m_index); *configuration(m_base) = (*configuration(m_base) & 0x3) | 1; } diff --git a/src/kernel/idt.cpp b/src/kernel/idt.cpp index 92f1447..1c4f077 100644 --- a/src/kernel/idt.cpp +++ b/src/kernel/idt.cpp @@ -144,7 +144,7 @@ IDT::dump(unsigned index) const } if (idt[i].flags & 0x80) { - log::debug(logs::boot, + log::spam(logs::boot, " Entry %3d: Base:%lx Sel(rpl %d, ti %d, %3d) IST:%d %s DPL:%d", i, base, (idt[i].selector & 0x3), ((idt[i].selector & 0x4) >> 2), diff --git a/src/kernel/logger.cpp b/src/kernel/logger.cpp index 26500f8..133a406 100644 --- a/src/kernel/logger.cpp +++ b/src/kernel/logger.cpp @@ -22,7 +22,7 @@ log::logger &g_logger = __g_logger_storage.value; namespace log { logger *logger::s_log = nullptr; -const char *logger::s_level_names[] = {"", "debug", "info", "warn", "error", "fatal"}; +const char *logger::s_level_names[] = {"", "fatal", "error", "warn", "info", "verbose", "spam"}; const char *logger::s_area_names[] = { #define LOG(name, lvl) #name , #include @@ -112,14 +112,15 @@ logger::get_entry(void *buffer, size_t size) logger *l = logger::s_log; \ if (!l) return; \ level limit = l->get_level(area); \ - if (limit == level::none || level::name < limit) return; \ + if (level::name > limit) return; \ va_list args; \ va_start(args, fmt); \ l->output(level::name, area, fmt, args); \ va_end(args); \ } -LOG_LEVEL_FUNCTION(debug); +LOG_LEVEL_FUNCTION(spam); +LOG_LEVEL_FUNCTION(verbose); LOG_LEVEL_FUNCTION(info); LOG_LEVEL_FUNCTION(warn); LOG_LEVEL_FUNCTION(error); diff --git a/src/kernel/logger.h b/src/kernel/logger.h index 0fe4fce..d3397a4 100644 --- a/src/kernel/logger.h +++ b/src/kernel/logger.h @@ -20,7 +20,7 @@ enum class logs : uint8_t { namespace log { enum class level : uint8_t { - none, debug, info, warn, error, fatal, max + silent, fatal, error, warn, info, verbose, spam, max }; constexpr unsigned areas_count = @@ -53,8 +53,7 @@ public: inline void log(level severity, logs area, const char *fmt, ...) { level limit = get_level(area); - if (limit == level::none || severity < limit) - return; + if (severity > limit) return; va_list args; va_start(args, fmt); @@ -81,11 +80,12 @@ public: inline bool has_log() const { return m_buffer.size(); } private: - friend void debug(logs area, const char *fmt, ...); - friend void info (logs area, const char *fmt, ...); - friend void warn (logs area, const char *fmt, ...); - friend void error(logs area, const char *fmt, ...); - friend void fatal(logs area, const char *fmt, ...); + friend void spam (logs area, const char *fmt, ...); + friend void verbose(logs area, const char *fmt, ...); + friend void info (logs area, const char *fmt, ...); + friend void warn (logs area, const char *fmt, ...); + friend void error (logs area, const char *fmt, ...); + friend void fatal (logs area, const char *fmt, ...); void output(level severity, logs area, const char *fmt, va_list args); @@ -109,11 +109,12 @@ private: static const char *s_level_names[static_cast(level::max)]; }; -void debug(logs area, const char *fmt, ...); -void info (logs area, const char *fmt, ...); -void warn (logs area, const char *fmt, ...); -void error(logs area, const char *fmt, ...); -void fatal(logs area, const char *fmt, ...); +void spam (logs area, const char *fmt, ...); +void verbose(logs area, const char *fmt, ...); +void info (logs area, const char *fmt, ...); +void warn (logs area, const char *fmt, ...); +void error (logs area, const char *fmt, ...); +void fatal (logs area, const char *fmt, ...); extern log::logger &g_logger; diff --git a/src/kernel/main.cpp b/src/kernel/main.cpp index 23a108f..522f75b 100644 --- a/src/kernel/main.cpp +++ b/src/kernel/main.cpp @@ -43,11 +43,11 @@ kernel_main(bootproto::args *args) kassert(args->magic == bootproto::args_magic, "Bad kernel args magic number"); - log::debug(logs::boot, "jsix init args are at: %016lx", args); - log::debug(logs::boot, " Memory map is at: %016lx", args->mem_map); - log::debug(logs::boot, "ACPI root table is at: %016lx", args->acpi_table); - log::debug(logs::boot, "Runtime service is at: %016lx", args->runtime_services); - log::debug(logs::boot, " Kernel PML4 is at: %016lx", args->pml4); + log::verbose(logs::boot, "jsix init args are at: %016lx", args); + log::verbose(logs::boot, " Memory map is at: %016lx", args->mem_map); + log::verbose(logs::boot, "ACPI root table is at: %016lx", args->acpi_table); + log::verbose(logs::boot, "Runtime service is at: %016lx", args->runtime_services); + log::verbose(logs::boot, " Kernel PML4 is at: %016lx", args->pml4); disable_legacy_pic(); diff --git a/src/kernel/objects/thread.cpp b/src/kernel/objects/thread.cpp index 7682e72..62e1c40 100644 --- a/src/kernel/objects/thread.cpp +++ b/src/kernel/objects/thread.cpp @@ -143,7 +143,7 @@ thread::setup_kernel_stack() for (unsigned i = 0; i < null_frame_entries; ++i) null_frame[i] = 0; - log::debug(logs::memory, "Created kernel stack at %016lx size 0x%lx", + log::verbose(logs::memory, "Created kernel stack at %016lx size 0x%lx", stack_addr, stack_bytes); m_tcb.kernel_stack = stack_addr; diff --git a/src/kernel/pci.cpp b/src/kernel/pci.cpp index 7e6d051..c7984c1 100644 --- a/src/kernel/pci.cpp +++ b/src/kernel/pci.cpp @@ -103,13 +103,16 @@ pci_device::pci_device(pci_group &group, uint8_t bus, uint8_t device, uint8_t fu log::info(logs::device, "Found PCIe device at %02d:%02d:%d of type %x.%x.%x id %04x:%04x", bus, device, func, m_class, m_subclass, m_progif, m_vendor, m_device); + log::spam(logs::device, " = BAR0 %016lld", get_bar(0)); + log::spam(logs::device, " = BAR1 %016lld", get_bar(1)); + if (*status & 0x0010) { // Walk the extended capabilities list uint8_t next = m_base[13] & 0xff; while (next) { pci_cap *cap = reinterpret_cast(util::offset_pointer(m_base, next)); next = cap->next; - log::debug(logs::device, " - found PCI cap type %02x", cap->id); + log::verbose(logs::device, " - found PCI cap type %02x", cap->id); if (cap->id == pci_cap::type::msi) { m_msi = cap; diff --git a/src/kernel/scheduler.cpp b/src/kernel/scheduler.cpp index 9485521..f07b968 100644 --- a/src/kernel/scheduler.cpp +++ b/src/kernel/scheduler.cpp @@ -78,10 +78,10 @@ scheduler::create_kernel_task(void (*task)(), uint8_t priority, bool constant) th->set_state(thread::state::ready); - log::debug(logs::task, "Creating kernel task: thread %llx pri %d", th->koid(), tcb->priority); - log::debug(logs::task, " RSP0 %016lx", tcb->rsp0); - log::debug(logs::task, " RSP %016lx", tcb->rsp); - log::debug(logs::task, " PML4 %016lx", tcb->pml4); + log::verbose(logs::task, "Creating kernel task: thread %llx pri %d", th->koid(), tcb->priority); + log::verbose(logs::task, " RSP0 %016lx", tcb->rsp0); + log::verbose(logs::task, " RSP %016lx", tcb->rsp); + log::verbose(logs::task, " PML4 %016lx", tcb->pml4); } uint32_t @@ -157,7 +157,7 @@ scheduler::prune(run_queue &queue, uint64_t now) delete &p; } else { queue.blocked.remove(remove); - log::debug(logs::sched, "Prune: readying unblocked thread %llx", th->koid()); + log::spam(logs::sched, "Prune: readying unblocked thread %llx", th->koid()); queue.ready[remove->priority].push_back(remove); } } @@ -186,7 +186,7 @@ scheduler::check_promotions(run_queue &queue, uint64_t now) tcb->priority -= 1; tcb->time_left = quantum(tcb->priority); queue.ready[tcb->priority].push_back(tcb); - log::info(logs::sched, "Scheduler promoting thread %llx, priority %d", + log::verbose(logs::sched, "Scheduler promoting thread %llx, priority %d", th->koid(), tcb->priority); } } @@ -236,7 +236,7 @@ scheduler::steal_work(cpu_data &cpu) other_queue_lock.release(); if (stolen) - log::debug(logs::sched, "CPU%02x stole %2d tasks from CPU%02x", + log::verbose(logs::sched, "CPU%02x stole %2d tasks from CPU%02x", cpu.index, stolen, i); } } @@ -276,7 +276,7 @@ scheduler::schedule() if (priority < max_priority && !constant) { // Process used its whole timeslice, demote it ++queue.current->priority; - log::debug(logs::sched, "Scheduler demoting thread %llx, priority %d", + log::verbose(logs::sched, "Scheduler demoting thread %llx, priority %d", th->koid(), queue.current->priority); } queue.current->time_left = quantum(queue.current->priority); @@ -322,11 +322,11 @@ scheduler::schedule() cpu.process = &next_thread->parent(); queue.current = next; - log::debug(logs::sched, "CPU%02x switching threads %llx->%llx", + log::spam(logs::sched, "CPU%02x switching threads %llx->%llx", cpu.index, th->koid(), next_thread->koid()); - log::debug(logs::sched, " priority %d time left %d @ %lld.", + log::spam(logs::sched, " priority %d time left %d @ %lld.", next->priority, next->time_left, now); - log::debug(logs::sched, " PML4 %llx", next->pml4); + log::spam(logs::sched, " PML4 %llx", next->pml4); queue.lock.release(&waiter); task_switch(queue.current); diff --git a/src/kernel/smp.cpp b/src/kernel/smp.cpp index b086203..5eca86d 100644 --- a/src/kernel/smp.cpp +++ b/src/kernel/smp.cpp @@ -88,7 +88,7 @@ start(cpu_data &bsp, void *kpml4) // Kick it off! size_t current_count = ap_startup_count; - log::debug(logs::boot, "Starting AP %d: stack %llx", cpu->index, stack_end); + log::verbose(logs::boot, "Starting AP %d: stack %llx", cpu->index, stack_end); lapic::ipi startup = lapic::ipi::startup | lapic::ipi::assert; diff --git a/src/kernel/syscall.cpp.cog b/src/kernel/syscall.cpp.cog index 8556f6a..2f173b2 100644 --- a/src/kernel/syscall.cpp.cog +++ b/src/kernel/syscall.cpp.cog @@ -83,7 +83,7 @@ syscall_initialize(bool enable_test) indent = " " cog.outl(f"{indent}syscall_registry[{id}] = reinterpret_cast(syscalls::_syscall_verify_{name});") - cog.outl(f"""{indent}log::debug(logs::syscall, "Enabling syscall {id:02x} as {name}");""") + cog.outl(f"""{indent}log::spam(logs::syscall, "Enabling syscall {id:02x} as {name}");""") if "test" in method.options: cog.outl("}") diff --git a/src/kernel/syscalls/system.cpp b/src/kernel/syscalls/system.cpp index 2e9d0fa..615f942 100644 --- a/src/kernel/syscalls/system.cpp +++ b/src/kernel/syscalls/system.cpp @@ -32,7 +32,7 @@ j6_status_t noop() { thread &th = thread::current(); - log::debug(logs::syscall, "Thread %llx called noop syscall.", th.koid()); + log::verbose(logs::syscall, "Thread %llx called noop syscall.", th.koid()); return j6_status_ok; } diff --git a/src/kernel/syscalls/thread.cpp b/src/kernel/syscalls/thread.cpp index 22349c4..d1af3d4 100644 --- a/src/kernel/syscalls/thread.cpp +++ b/src/kernel/syscalls/thread.cpp @@ -22,7 +22,7 @@ thread_create(j6_handle_t *self, process *proc, uintptr_t stack_top, uintptr_t e *self = child->self_handle(); child->set_state(thread::state::ready); - log::debug(logs::task, "Thread %llx:%llx spawned new thread %llx:%llx", + log::verbose(logs::task, "Thread %llx:%llx spawned new thread %llx:%llx", parent_pr.koid(), parent_th.koid(), proc->koid(), child->koid()); return j6_status_ok; @@ -32,7 +32,7 @@ j6_status_t thread_exit(int32_t status) { thread &th = thread::current(); - log::debug(logs::task, "Thread %llx exiting with code %d", th.koid(), status); + log::verbose(logs::task, "Thread %llx exiting with code %d", th.koid(), status); th.exit(status); log::error(logs::task, "returned to exit syscall"); @@ -42,7 +42,7 @@ thread_exit(int32_t status) j6_status_t thread_kill(thread *self) { - log::debug(logs::task, "Killing thread %llx", self->koid()); + log::verbose(logs::task, "Killing thread %llx", self->koid()); self->exit(-1); return j6_status_ok; } @@ -54,7 +54,7 @@ thread_sleep(uint64_t duration) uint64_t til = clock::get().value() + duration; - log::debug(logs::task, "Thread %llx sleeping until %llu", th.koid(), til); + log::verbose(logs::task, "Thread %llx sleeping until %llu", th.koid(), til); th.set_wake_timeout(til); th.block(); return j6_status_ok; diff --git a/src/kernel/tss.cpp b/src/kernel/tss.cpp index 0a9ab65..8fc3a5d 100644 --- a/src/kernel/tss.cpp +++ b/src/kernel/tss.cpp @@ -56,7 +56,7 @@ TSS::create_ist_stacks(uint8_t ist_entries) uintptr_t stack_bottom = g_kernel_stacks.get_section(); uintptr_t stack_top = stack_bottom + stack_bytes - 2 * sizeof(uintptr_t); - log::debug(logs::memory, "Created IST stack at %016lx size 0x%lx", + log::verbose(logs::memory, "Created IST stack at %016lx size 0x%lx", stack_bottom, stack_bytes); // Pre-realize these stacks, they're no good if they page fault diff --git a/src/kernel/vm_space.cpp b/src/kernel/vm_space.cpp index 63e8946..f123506 100644 --- a/src/kernel/vm_space.cpp +++ b/src/kernel/vm_space.cpp @@ -200,7 +200,7 @@ vm_space::page_in(const obj::vm_area &vma, uintptr_t offset, uintptr_t phys, siz for (size_t i = 0; i < count; ++i) { uint64_t &entry = it.entry(page_table::level::pt); entry = (phys + i * frame_size) | flags; - log::debug(logs::paging, "Setting entry for %016llx: %016llx [%04llx]", + log::spam(logs::paging, "Setting entry for %016llx: %016llx [%04llx]", it.vaddress(), (phys + i * frame_size), flags); ++it; } diff --git a/src/libraries/j6/j6/tables/log_areas.inc b/src/libraries/j6/j6/tables/log_areas.inc index a85c5b6..77c55ad 100644 --- a/src/libraries/j6/j6/tables/log_areas.inc +++ b/src/libraries/j6/j6/tables/log_areas.inc @@ -1,16 +1,16 @@ LOG(apic, info) -LOG(boot, debug) -LOG(clock, debug) -LOG(device, debug) +LOG(boot, verbose) +LOG(clock, verbose) +LOG(device, verbose) LOG(driver, info) LOG(fs, info) LOG(irq, info) -LOG(loader, debug) -LOG(memory, debug) -LOG(objs, debug) +LOG(loader, verbose) +LOG(memory, verbose) +LOG(objs, verbose) LOG(paging, info) LOG(sched, info) -LOG(syscall,debug) -LOG(task, debug) -LOG(timer, debug) -LOG(vmem, debug) +LOG(syscall,verbose) +LOG(task, verbose) +LOG(timer, verbose) +LOG(vmem, verbose) diff --git a/src/tests/logger.cpp b/src/tests/logger.cpp index 4b53da7..3a624a2 100644 --- a/src/tests/logger.cpp +++ b/src/tests/logger.cpp @@ -15,8 +15,8 @@ log::area_t hash2 = "test_area2"_h; TEST_CASE( "logger writing", "[logger]" ) { log::logger logger(test_log_buffer, sizeof(test_log_buffer)); - logger.register_area(hash1, name1, log::level::debug); - logger.register_area(hash2, name2, log::level::debug); + logger.register_area(hash1, name1, log::level::verbose); + logger.register_area(hash2, name2, log::level::verbose); CHECK( hash1 != hash2 ); const char *check1 = logger.area_name(hash1); @@ -25,7 +25,7 @@ TEST_CASE( "logger writing", "[logger]" ) CHECK( check1 == name1 ); CHECK( check2 == name2 ); - log::debug(hash1, "This is a thing %016lx", 35); + log::verbose(hash1, "This is a thing %016lx", 35); log::info(hash2, "This is a string %s", "foo"); log::warn(hash1, "This is a thing %016lx", 682); log::error(hash2, "This is a string %s", "bar"); diff --git a/src/user/srv.logger/main.cpp b/src/user/srv.logger/main.cpp index cb451b2..c7520fd 100644 --- a/src/user/srv.logger/main.cpp +++ b/src/user/srv.logger/main.cpp @@ -28,8 +28,8 @@ struct entry char message[0]; }; -static const uint8_t level_colors[] = {0x07, 0x07, 0x0f, 0x0b, 0x09}; -char const * const level_names[] = {"", "debug", "info", "warn", "error", "fatal"}; +static const uint8_t level_colors[] = {0x00, 0x09, 0x01, 0x0b, 0x0f, 0x07, 0x08}; +char const * const level_names[] = {"", "fatal", "error", "warn", "info", "verbose", "spam"}; char const * const area_names[] = { #define LOG(name, lvl) #name , #include @@ -100,7 +100,7 @@ log_pump_proc(j6_handle_t cout) uint8_t level_color = level_colors[e->severity]; size_t len = snprintf(stringbuf, sizeof(stringbuf), - "\e[38;5;%dm%7s %5s: %s\e[38;5;0m\r\n", + "\e[38;5;%dm%7s %7s: %s\e[38;5;0m\r\n", level_color, area_name, level_name, e->message); send_all(cout, stringbuf, len); }