justin/jsix_import
1
0
Fork 0
Code Issues 1 Pull Requests Actions Packages Projects Releases Wiki Activity

[kernel] Change kernel log levels

Browse Source 
The kernel log levels are now numerically reversed so that more-verbose
levels can be added to the end. Replaced 'debug' with 'verbose', and
added new 'spam' level.
This commit is contained in:
Justin C. Miller
2022-09-25 17:25:43 -07:00
parent 7b8fd76af0
commit 11b61ab345
20 changed files with 115 additions and 110 deletions
Download Patch File Download Diff File Expand all files Collapse all files

20
src/kernel/apic.cpp
View File

@@ -32,7 +32,7 @@ apic_read(uint32_t volatile *apic, uint16_t offset)
static void static void
apic_write(uint32_t volatile *apic, uint16_t offset, uint32_t value) 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; *(apic + offset/sizeof(uint32_t)) = value;
} }
@@ -161,7 +161,7 @@ lapic::enable_timer(isr vector, bool repeat)
lvte |= 0x20000; lvte |= 0x20000;
apic_write(m_base, lapic_lvt_timer, lvte); 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 uint32_t
@@ -200,7 +200,7 @@ lapic::enable_lint(uint8_t num, isr vector, bool nmi, uint16_t flags)
lvte |= (1 << 15); lvte |= (1 << 15);
apic_write(m_base, off, lvte); 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, num, nmi ? "NMI" : "ISR", vector,
polarity == 3 ? "level" : "edge", polarity == 3 ? "level" : "edge",
trigger == 3 ? "low" : "high"); trigger == 3 ? "low" : "high");
@@ -211,7 +211,7 @@ lapic::enable()
{ {
apic_write(m_base, lapic_spurious, apic_write(m_base, lapic_spurious,
apic_read(m_base, lapic_spurious) | 0x100); apic_read(m_base, lapic_spurious) | 0x100);
log::debug(logs::apic, "LAPIC enabled!"); log::verbose(logs::apic, "LAPIC enabled!");
} }
void void
@@ -219,7 +219,7 @@ lapic::disable()
{ {
apic_write(m_base, lapic_spurious, apic_write(m_base, lapic_spurious,
apic_read(m_base, lapic_spurious) & ~0x100); 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_id = (id >> 24) & 0xff;
m_version = version & 0xff; m_version = version & 0xff;
m_num_gsi = (version >> 16) & 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)); m_id, m_version, base_gsi, base_gsi + (m_num_gsi - 1));
for (uint8_t i = 0; i < m_num_gsi; ++i) { for (uint8_t i = 0; i < m_num_gsi; ++i) {
@@ -246,7 +246,7 @@ ioapic::ioapic(uintptr_t base, uint32_t base_gsi) :
void void
ioapic::redirect(uint8_t irq, isr vector, uint16_t flags, bool masked) 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)" : ""); m_id, irq, vector, flags, masked ? " (masked)" : "");
uint64_t entry = static_cast<uint64_t>(vector); uint64_t entry = static_cast<uint64_t>(vector);
@@ -269,7 +269,7 @@ ioapic::redirect(uint8_t irq, isr vector, uint16_t flags, bool masked)
void void
ioapic::mask(uint8_t irq, bool masked) 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); m_id, masked ? "" : "un", irq);
uint32_t entry = ioapic_read(m_base, (2 * irq) + 0x10); uint32_t entry = ioapic_read(m_base, (2 * irq) + 0x10);
@@ -284,7 +284,7 @@ ioapic::mask(uint8_t irq, bool masked)
void void
ioapic::dump_redirs() const 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) { for (uint8_t i = 0; i < m_num_gsi; ++i) {
uint64_t low = ioapic_read(m_base, 0x10 + (2 *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 mask = (redir >> 16) & 0x1;
uint8_t dest = (redir >> 56) & 0xff; 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, m_base_gsi + i, vector,
polarity ? "low" : "high", polarity ? "low" : "high",
trigger ? "level" : "edge", trigger ? "level" : "edge",

12
src/kernel/cpu.cpp
View File

@@ -38,16 +38,16 @@ cpu_validate()
cpu::cpu_id::features features = cpu.validate(); cpu::cpu_id::features features = cpu.validate();
log::info(logs::boot, "CPU: %s", brand_name); 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::spam(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 ext CPUID: 0x%02x", cpu.highest_ext() & ~cpu::cpu_id::cpuid_extended);
#define CPU_FEATURE_OPT(name, ...) \ #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) \ #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 ); kassert(features[cpu::feature::name], "Missing required CPU feature " #name );
#include "cpu/features.inc" #include "cpu/features.inc"
@@ -121,7 +121,7 @@ bsp_late_init()
asm ("mov %%cr4, %0" : "=r"(cr4v)); asm ("mov %%cr4, %0" : "=r"(cr4v));
uint64_t efer = rdmsr(msr::ia32_efer); 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 * cpu_data *

26
src/kernel/device_manager.cpp
View File

@@ -137,7 +137,7 @@ device_manager::load_xsdt(const acpi_table_header *header)
log::info(logs::device, "ACPI 2.0+ tables loading"); log::info(logs::device, "ACPI 2.0+ tables loading");
put_sig(sig, xsdt->header.type); 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*)); size_t num_tables = acpi_table_entries(xsdt, sizeof(void*));
for (size_t i = 0; i < num_tables; ++i) { 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]); mem::to_virtual(xsdt->headers[i]);
put_sig(sig, header->type); 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."); 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<uint8_t>(p+3); uint8_t id = util::read_from<uint8_t>(p+3);
m_apic_ids.append(id); 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; break;
@@ -225,7 +225,7 @@ device_manager::load_apic(const acpi_table_header *header)
uint32_t base_gsi = util::read_from<uint32_t>(p+8); uint32_t base_gsi = util::read_from<uint32_t>(p+8);
m_ioapics.emplace(base, base_gsi); 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; break;
@@ -236,7 +236,7 @@ device_manager::load_apic(const acpi_table_header *header)
o.flags = util::read_from<uint16_t>(p+8); o.flags = util::read_from<uint16_t>(p+8);
m_overrides.append(o); 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)); o.source, o.gsi, (o.flags & 0x3), ((o.flags >> 2) & 0x3));
} }
break; break;
@@ -248,13 +248,13 @@ device_manager::load_apic(const acpi_table_header *header)
nmi.flags = util::read_from<uint16_t>(p + 3); nmi.flags = util::read_from<uint16_t>(p + 3);
m_nmis.append(nmi); 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); nmi.cpu, nmi.lint, nmi.flags & 0x3, (nmi.flags >> 2) & 0x3);
} }
break; break;
default: default:
log::debug(logs::device, " APIC entry type %d", type); log::spam(logs::device, " APIC entry type %d", type);
} }
p += length; 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].bus_end = mcfge.bus_end;
m_pci[i].base = mem::to_virtual<uint32_t>(mcfge.base); m_pci[i].base = mem::to_virtual<uint32_t>(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); 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<acpi_hpet>(header); const auto *hpet = check_get_table<acpi_hpet>(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); hpet->index, hpet->base_address.address, hpet->periodic_min, hpet->attributes);
uint32_t hwid = hpet->hardware_id; 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; uint8_t legacy_replacement = (hwid >> 15) & 1;
uint32_t pci_vendor_id = (hwid >> 16); 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); 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, m_hpets.emplace(hpet->index,
reinterpret_cast<uint64_t*>(hpet->base_address.address + mem::linear_offset)); reinterpret_cast<uint64_t*>(hpet->base_address.address + mem::linear_offset));
@@ -315,7 +315,7 @@ void
device_manager::probe_pci() device_manager::probe_pci()
{ {
for (auto &pci : m_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 bus = pci.bus_start; bus <= pci.bus_end; ++bus) {
for (int dev = 0; dev < 32; ++dev) { 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; isr vector = isr::irq00 + irq;
m_irqs.append({name, cb, data}); 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( device.write_msi_regs(
0xFEE00000, 0xFEE00000,

42
src/kernel/hpet.cpp
View File

@@ -41,30 +41,30 @@ hpet::hpet(uint8_t index, uint64_t *base) :
// .install_irq(2, "HPET Timer", hpet_irq_callback, this); // .install_irq(2, "HPET Timer", hpet_irq_callback, this);
// kassert(installed, "Installing HPET IRQ handler"); // kassert(installed, "Installing HPET IRQ handler");
log::debug(logs::timer, "HPET %d capabilities:", index); log::spam(logs::timer, "HPET %d capabilities:", index);
log::debug(logs::timer, " revision: %d", caps & 0xff); log::spam(logs::timer, " revision: %d", caps & 0xff);
log::debug(logs::timer, " timers: %d", m_timers); log::spam(logs::timer, " timers: %d", m_timers);
log::debug(logs::timer, " bits: %d", ((caps >> 13) & 1) ? 64 : 32); log::spam(logs::timer, " bits: %d", ((caps >> 13) & 1) ? 64 : 32);
log::debug(logs::timer, " LRR capable: %d", ((caps >> 15) & 1)); log::spam(logs::timer, " LRR capable: %d", ((caps >> 15) & 1));
log::debug(logs::timer, " period: %dns", m_period / 1000000); log::spam(logs::timer, " period: %dns", m_period / 1000000);
log::debug(logs::timer, " global enabled: %d", config & 1); log::spam(logs::timer, " global enabled: %d", config & 1);
log::debug(logs::timer, " LRR enable: %d", (config >> 1) & 1); log::spam(logs::timer, " LRR enable: %d", (config >> 1) & 1);
for (unsigned i = 0; i < m_timers; ++i) { for (unsigned i = 0; i < m_timers; ++i) {
disable_timer(i); disable_timer(i);
uint64_t config = *timer_config(m_base, i); uint64_t config = *timer_config(m_base, i);
log::debug(logs::timer, "HPET %d timer %d:", index, i); log::spam(logs::timer, "HPET %d timer %d:", index, i);
log::debug(logs::timer, " int type: %d", (config >> 1) & 1); log::spam(logs::timer, " int type: %d", (config >> 1) & 1);
log::debug(logs::timer, " int enable: %d", (config >> 2) & 1); log::spam(logs::timer, " int enable: %d", (config >> 2) & 1);
log::debug(logs::timer, " timer type: %d", (config >> 3) & 1); log::spam(logs::timer, " timer type: %d", (config >> 3) & 1);
log::debug(logs::timer, " periodic cap: %d", (config >> 4) & 1); log::spam(logs::timer, " periodic cap: %d", (config >> 4) & 1);
log::debug(logs::timer, " bits: %d", ((config >> 5) & 1) ? 64 : 32); log::spam(logs::timer, " bits: %d", ((config >> 5) & 1) ? 64 : 32);
log::debug(logs::timer, " 32 mode: %d", (config >> 8) & 1); log::spam(logs::timer, " 32 mode: %d", (config >> 8) & 1);
log::debug(logs::timer, " int route: %d", (config >> 9) & 0x1f); log::spam(logs::timer, " int route: %d", (config >> 9) & 0x1f);
log::debug(logs::timer, " FSB enable: %d", (config >> 14) & 1); log::spam(logs::timer, " FSB enable: %d", (config >> 14) & 1);
log::debug(logs::timer, " FSB capable: %d", (config >> 15) & 1); log::spam(logs::timer, " FSB capable: %d", (config >> 15) & 1);
log::debug(logs::timer, " rotung cap: %08x", (config >> 32)); log::spam(logs::timer, " rotung cap: %08x", (config >> 32));
} }
} }
@@ -95,13 +95,13 @@ hpet::disable_timer(unsigned timer)
void void
hpet::callback() hpet::callback()
{ {
log::debug(logs::timer, "HPET %d got irq", m_index); log::spam(logs::timer, "HPET %d got irq", m_index);
} }
void void
hpet::enable() 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; *configuration(m_base) = (*configuration(m_base) & 0x3) | 1;
} }

2
src/kernel/idt.cpp
View File

@@ -144,7 +144,7 @@ IDT::dump(unsigned index) const
} }
if (idt[i].flags & 0x80) { 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, " Entry %3d: Base:%lx Sel(rpl %d, ti %d, %3d) IST:%d %s DPL:%d", i, base,
(idt[i].selector & 0x3), (idt[i].selector & 0x3),
((idt[i].selector & 0x4) >> 2), ((idt[i].selector & 0x4) >> 2),

7
src/kernel/logger.cpp
View File

@@ -22,7 +22,7 @@ log::logger &g_logger = __g_logger_storage.value;
namespace log { namespace log {
logger *logger::s_log = nullptr; 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[] = { const char *logger::s_area_names[] = {
#define LOG(name, lvl) #name , #define LOG(name, lvl) #name ,
#include <j6/tables/log_areas.inc> #include <j6/tables/log_areas.inc>
@@ -112,14 +112,15 @@ logger::get_entry(void *buffer, size_t size)
logger *l = logger::s_log; \ logger *l = logger::s_log; \
if (!l) return; \ if (!l) return; \
level limit = l->get_level(area); \ level limit = l->get_level(area); \
if (limit == level::none || level::name < limit) return; \ if (level::name > limit) return; \
va_list args; \ va_list args; \
va_start(args, fmt); \ va_start(args, fmt); \
l->output(level::name, area, fmt, args); \ l->output(level::name, area, fmt, args); \
va_end(args); \ va_end(args); \
} }
LOG_LEVEL_FUNCTION(debug); LOG_LEVEL_FUNCTION(spam);
LOG_LEVEL_FUNCTION(verbose);
LOG_LEVEL_FUNCTION(info); LOG_LEVEL_FUNCTION(info);
LOG_LEVEL_FUNCTION(warn); LOG_LEVEL_FUNCTION(warn);
LOG_LEVEL_FUNCTION(error); LOG_LEVEL_FUNCTION(error);

19
src/kernel/logger.h
View File

@@ -20,7 +20,7 @@ enum class logs : uint8_t {
namespace log { namespace log {
enum class level : uint8_t { enum class level : uint8_t {
none, debug, info, warn, error, fatal, max silent, fatal, error, warn, info, verbose, spam, max
}; };
constexpr unsigned areas_count = constexpr unsigned areas_count =
@@ -53,8 +53,7 @@ public:
inline void log(level severity, logs area, const char *fmt, ...) inline void log(level severity, logs area, const char *fmt, ...)
{ {
level limit = get_level(area); level limit = get_level(area);
if (limit == level::none || severity < limit) if (severity > limit) return;
return;
va_list args; va_list args;
va_start(args, fmt); va_start(args, fmt);
@@ -81,11 +80,12 @@ public:
inline bool has_log() const { return m_buffer.size(); } inline bool has_log() const { return m_buffer.size(); }
private: private:
friend void debug(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 info (logs area, const char *fmt, ...);
friend void warn (logs area, const char *fmt, ...); friend void warn (logs area, const char *fmt, ...);
friend void error(logs area, const char *fmt, ...); friend void error (logs area, const char *fmt, ...);
friend void fatal(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); 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<unsigned>(level::max)]; static const char *s_level_names[static_cast<unsigned>(level::max)];
}; };
void debug(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 info (logs area, const char *fmt, ...);
void warn (logs area, const char *fmt, ...); void warn (logs area, const char *fmt, ...);
void error(logs area, const char *fmt, ...); void error (logs area, const char *fmt, ...);
void fatal(logs area, const char *fmt, ...); void fatal (logs area, const char *fmt, ...);
extern log::logger &g_logger; extern log::logger &g_logger;

10
src/kernel/main.cpp
View File

@@ -43,11 +43,11 @@ kernel_main(bootproto::args *args)
kassert(args->magic == bootproto::args_magic, kassert(args->magic == bootproto::args_magic,
"Bad kernel args magic number"); "Bad kernel args magic number");
log::debug(logs::boot, "jsix init args are at: %016lx", args); log::verbose(logs::boot, "jsix init args are at: %016lx", args);
log::debug(logs::boot, " Memory map is at: %016lx", args->mem_map); log::verbose(logs::boot, " Memory map is at: %016lx", args->mem_map);
log::debug(logs::boot, "ACPI root table is at: %016lx", args->acpi_table); log::verbose(logs::boot, "ACPI root table is at: %016lx", args->acpi_table);
log::debug(logs::boot, "Runtime service is at: %016lx", args->runtime_services); log::verbose(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, " Kernel PML4 is at: %016lx", args->pml4);
disable_legacy_pic(); disable_legacy_pic();

2
src/kernel/objects/thread.cpp
View File

@@ -143,7 +143,7 @@ thread::setup_kernel_stack()
for (unsigned i = 0; i < null_frame_entries; ++i) for (unsigned i = 0; i < null_frame_entries; ++i)
null_frame[i] = 0; 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); stack_addr, stack_bytes);
m_tcb.kernel_stack = stack_addr; m_tcb.kernel_stack = stack_addr;

5
src/kernel/pci.cpp
View File

@@ -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", 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); 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) { if (*status & 0x0010) {
// Walk the extended capabilities list // Walk the extended capabilities list
uint8_t next = m_base[13] & 0xff; uint8_t next = m_base[13] & 0xff;
while (next) { while (next) {
pci_cap *cap = reinterpret_cast<pci_cap *>(util::offset_pointer(m_base, next)); pci_cap *cap = reinterpret_cast<pci_cap *>(util::offset_pointer(m_base, next));
next = cap->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) { if (cap->id == pci_cap::type::msi) {
m_msi = cap; m_msi = cap;

22
src/kernel/scheduler.cpp
View File

@@ -78,10 +78,10 @@ scheduler::create_kernel_task(void (*task)(), uint8_t priority, bool constant)
th->set_state(thread::state::ready); th->set_state(thread::state::ready);
log::debug(logs::task, "Creating kernel task: thread %llx pri %d", th->koid(), tcb->priority); log::verbose(logs::task, "Creating kernel task: thread %llx pri %d", th->koid(), tcb->priority);
log::debug(logs::task, " RSP0 %016lx", tcb->rsp0); log::verbose(logs::task, " RSP0 %016lx", tcb->rsp0);
log::debug(logs::task, " RSP %016lx", tcb->rsp); log::verbose(logs::task, " RSP %016lx", tcb->rsp);
log::debug(logs::task, " PML4 %016lx", tcb->pml4); log::verbose(logs::task, " PML4 %016lx", tcb->pml4);
} }
uint32_t uint32_t
@@ -157,7 +157,7 @@ scheduler::prune(run_queue &queue, uint64_t now)
delete &p; delete &p;
} else { } else {
queue.blocked.remove(remove); 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); queue.ready[remove->priority].push_back(remove);
} }
} }
@@ -186,7 +186,7 @@ scheduler::check_promotions(run_queue &queue, uint64_t now)
tcb->priority -= 1; tcb->priority -= 1;
tcb->time_left = quantum(tcb->priority); tcb->time_left = quantum(tcb->priority);
queue.ready[tcb->priority].push_back(tcb); 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); th->koid(), tcb->priority);
} }
} }
@@ -236,7 +236,7 @@ scheduler::steal_work(cpu_data &cpu)
other_queue_lock.release(); other_queue_lock.release();
if (stolen) 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); cpu.index, stolen, i);
} }
} }
@@ -276,7 +276,7 @@ scheduler::schedule()
if (priority < max_priority && !constant) { if (priority < max_priority && !constant) {
// Process used its whole timeslice, demote it // Process used its whole timeslice, demote it
++queue.current->priority; ++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); th->koid(), queue.current->priority);
} }
queue.current->time_left = quantum(queue.current->priority); queue.current->time_left = quantum(queue.current->priority);
@@ -322,11 +322,11 @@ scheduler::schedule()
cpu.process = &next_thread->parent(); cpu.process = &next_thread->parent();
queue.current = next; 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()); 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); 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); queue.lock.release(&waiter);
task_switch(queue.current); task_switch(queue.current);

2
src/kernel/smp.cpp
View File

@@ -88,7 +88,7 @@ start(cpu_data &bsp, void *kpml4)
// Kick it off! // Kick it off!
size_t current_count = ap_startup_count; 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; lapic::ipi startup = lapic::ipi::startup | lapic::ipi::assert;

2
src/kernel/syscall.cpp.cog
View File

@@ -83,7 +83,7 @@ syscall_initialize(bool enable_test)
indent = " " indent = " "
cog.outl(f"{indent}syscall_registry[{id}] = reinterpret_cast<uintptr_t>(syscalls::_syscall_verify_{name});") cog.outl(f"{indent}syscall_registry[{id}] = reinterpret_cast<uintptr_t>(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: if "test" in method.options:
cog.outl("}") cog.outl("}")

2
src/kernel/syscalls/system.cpp
View File

@@ -32,7 +32,7 @@ j6_status_t
noop() noop()
{ {
thread &th = thread::current(); 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; return j6_status_ok;
} }

8
src/kernel/syscalls/thread.cpp
View File

@@ -22,7 +22,7 @@ thread_create(j6_handle_t *self, process *proc, uintptr_t stack_top, uintptr_t e
*self = child->self_handle(); *self = child->self_handle();
child->set_state(thread::state::ready); 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()); parent_pr.koid(), parent_th.koid(), proc->koid(), child->koid());
return j6_status_ok; return j6_status_ok;
@@ -32,7 +32,7 @@ j6_status_t
thread_exit(int32_t status) thread_exit(int32_t status)
{ {
thread &th = thread::current(); 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); th.exit(status);
log::error(logs::task, "returned to exit syscall"); log::error(logs::task, "returned to exit syscall");
@@ -42,7 +42,7 @@ thread_exit(int32_t status)
j6_status_t j6_status_t
thread_kill(thread *self) 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); self->exit(-1);
return j6_status_ok; return j6_status_ok;
} }
@@ -54,7 +54,7 @@ thread_sleep(uint64_t duration)
uint64_t til = clock::get().value() + 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.set_wake_timeout(til);
th.block(); th.block();
return j6_status_ok; return j6_status_ok;

2
src/kernel/tss.cpp
View File

@@ -56,7 +56,7 @@ TSS::create_ist_stacks(uint8_t ist_entries)
uintptr_t stack_bottom = g_kernel_stacks.get_section(); uintptr_t stack_bottom = g_kernel_stacks.get_section();
uintptr_t stack_top = stack_bottom + stack_bytes - 2 * sizeof(uintptr_t); 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); stack_bottom, stack_bytes);
// Pre-realize these stacks, they're no good if they page fault // Pre-realize these stacks, they're no good if they page fault

2
src/kernel/vm_space.cpp
View File

@@ -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) { for (size_t i = 0; i < count; ++i) {
uint64_t &entry = it.entry(page_table::level::pt); uint64_t &entry = it.entry(page_table::level::pt);
entry = (phys + i * frame_size) | flags; 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.vaddress(), (phys + i * frame_size), flags);
++it; ++it;
} }

20
src/libraries/j6/j6/tables/log_areas.inc
View File

@@ -1,16 +1,16 @@
LOG(apic, info) LOG(apic, info)
LOG(boot, debug) LOG(boot, verbose)
LOG(clock, debug) LOG(clock, verbose)
LOG(device, debug) LOG(device, verbose)
LOG(driver, info) LOG(driver, info)
LOG(fs, info) LOG(fs, info)
LOG(irq, info) LOG(irq, info)
LOG(loader, debug) LOG(loader, verbose)
LOG(memory, debug) LOG(memory, verbose)
LOG(objs, debug) LOG(objs, verbose)
LOG(paging, info) LOG(paging, info)
LOG(sched, info) LOG(sched, info)
LOG(syscall,debug) LOG(syscall,verbose)
LOG(task, debug) LOG(task, verbose)
LOG(timer, debug) LOG(timer, verbose)
LOG(vmem, debug) LOG(vmem, verbose)

6
src/tests/logger.cpp
View File

@@ -15,8 +15,8 @@ log::area_t hash2 = "test_area2"_h;
TEST_CASE( "logger writing", "[logger]" ) TEST_CASE( "logger writing", "[logger]" )
{ {
log::logger logger(test_log_buffer, sizeof(test_log_buffer)); log::logger logger(test_log_buffer, sizeof(test_log_buffer));
logger.register_area(hash1, name1, log::level::debug); logger.register_area(hash1, name1, log::level::verbose);
logger.register_area(hash2, name2, log::level::debug); logger.register_area(hash2, name2, log::level::verbose);
CHECK( hash1 != hash2 ); CHECK( hash1 != hash2 );
const char *check1 = logger.area_name(hash1); const char *check1 = logger.area_name(hash1);
@@ -25,7 +25,7 @@ TEST_CASE( "logger writing", "[logger]" )
CHECK( check1 == name1 ); CHECK( check1 == name1 );
CHECK( check2 == name2 ); 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::info(hash2, "This is a string %s", "foo");
log::warn(hash1, "This is a thing %016lx", 682); log::warn(hash1, "This is a thing %016lx", 682);
log::error(hash2, "This is a string %s", "bar"); log::error(hash2, "This is a string %s", "bar");

6
src/user/srv.logger/main.cpp
View File

@@ -28,8 +28,8 @@ struct entry
char message[0]; char message[0];
}; };
static const uint8_t level_colors[] = {0x07, 0x07, 0x0f, 0x0b, 0x09}; static const uint8_t level_colors[] = {0x00, 0x09, 0x01, 0x0b, 0x0f, 0x07, 0x08};
char const * const level_names[] = {"", "debug", "info", "warn", "error", "fatal"}; char const * const level_names[] = {"", "fatal", "error", "warn", "info", "verbose", "spam"};
char const * const area_names[] = { char const * const area_names[] = {
#define LOG(name, lvl) #name , #define LOG(name, lvl) #name ,
#include <j6/tables/log_areas.inc> #include <j6/tables/log_areas.inc>
@@ -100,7 +100,7 @@ log_pump_proc(j6_handle_t cout)
uint8_t level_color = level_colors[e->severity]; uint8_t level_color = level_colors[e->severity];
size_t len = snprintf(stringbuf, sizeof(stringbuf), 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); level_color, area_name, level_name, e->message);
send_all(cout, stringbuf, len); send_all(cout, stringbuf, len);
} }