diff --git a/build.sh b/build.sh index 148e9ad..0739df7 100755 --- a/build.sh +++ b/build.sh @@ -3,7 +3,16 @@ set -euo pipefail export CC=clang -meson setup build --reconfigure +LOG_LEVEL=1 +for arg in "${@}"; do + case "${arg}" in + -v) LOG_LEVEL=2 ;; + -vv) LOG_LEVEL=3 ;; + -vvv) LOG_LEVEL=4 ;; + esac +done + +meson setup build --reconfigure -Dc_args="-DLOG_LEVEL=${LOG_LEVEL}" meson compile -v -C build sector_size=512 diff --git a/src/kernel/log.h b/src/kernel/log.h index ae32ab4..1770f1a 100644 --- a/src/kernel/log.h +++ b/src/kernel/log.h @@ -6,6 +6,15 @@ extern stream_t *kernel_log; +#ifndef LOG_LEVEL +#define LOG_LEVEL 1 +#endif + +#define LOG_LEVEL_INFO 1 +#define LOG_LEVEL_STEP 2 +#define LOG_LEVEL_DATA 3 +#define LOG_LEVEL_TRACE 4 + #define PRINT(stream, fmt, ...) \ do { \ uint64_t _size = string_length(fmt) * 10; \ @@ -13,7 +22,7 @@ extern stream_t *kernel_log; _size = string_format(fmt, _size, _string, ##__VA_ARGS__); \ stream->write(stream, _string, _size); \ memory_free(_string); \ - } while (0) + } while (0); #define PRINT_LN(stream, fmt, ...) \ do { \ @@ -25,22 +34,39 @@ extern stream_t *kernel_log; stream->write(stream, _string, _size); \ stream->write(stream, "\n", 1); \ memory_free(_string); \ - } while (0) + } while (0); -#define LOG(fmt, ...) PRINT(kernel_log, fmt, ##__VA_ARGS__) +#define PRINT_VAL(stream, v, f) PRINT_LN(#v = f, v) -#define TRACE(fmt, ...) +#define LOG_INFO(fmt, ...) \ + if (LOG_LEVEL >= LOG_LEVEL_INFO) \ + PRINT(kernel_log, fmt, ##__VA_ARGS__) +#define LOG_STEP(fmt, ...) \ + if (LOG_LEVEL >= LOG_LEVEL_STEP) \ + PRINT(kernel_log, fmt, ##__VA_ARGS__) +#define LOG_DATA(fmt, ...) \ + if (LOG_LEVEL >= LOG_LEVEL_DATA) \ + PRINT(kernel_log, fmt, ##__VA_ARGS__) +#define LOG_TRACE(fmt, ...) \ + if (LOG_LEVEL >= LOG_LEVEL_TRACE) \ + PRINT(kernel_log, fmt, ##__VA_ARGS__) -#define LOG_LN(fmt, ...) PRINT_LN(kernel_log, fmt, ##__VA_ARGS__) +#define LOG_LN_INFO(fmt, ...) \ + if (LOG_LEVEL >= LOG_LEVEL_INFO) \ + PRINT_LN(kernel_log, fmt, ##__VA_ARGS__) +#define LOG_LN_STEP(fmt, ...) \ + if (LOG_LEVEL >= LOG_LEVEL_STEP) \ + PRINT_LN(kernel_log, fmt, ##__VA_ARGS__) +#define LOG_LN_DATA(fmt, ...) \ + if (LOG_LEVEL >= LOG_LEVEL_DATA) \ + PRINT_LN(kernel_log, fmt, ##__VA_ARGS__) +#define LOG_LN_TRACE(fmt, ...) \ + if (LOG_LEVEL >= LOG_LEVEL_TRACE) \ + PRINT_LN(kernel_log, fmt, ##__VA_ARGS__) -#define LOG_VAL(v) LOG_LN(#v "=%x") - -#define LOG_VAL_F(v, f) LOG_LN(#v "=" f, v) - -#define TRACE_LN(fmt, ...) - -#define TRACE_VAL(v) TRACE_LN(#v "=%lx") - -#define TRACE_VAL_F(v, f) TRACE_LN(#v "=" f, v) +#define LOG_VAL_INFO(v, f) LOG_LN_INFO(#v "=" f, v) +#define LOG_VAL_STEP(v, f) LOG_LN_STEP(#v "=" f, v) +#define LOG_VAL_DATA(v, f) LOG_LN_DATA(#v "=" f, v) +#define LOG_VAL_TRACE(v, f) LOG_LN_TRACE(#v "=" f, v) void log_init(stream_t *log); diff --git a/src/kernel/memory.c b/src/kernel/memory.c index e63b1b6..4afb10f 100644 --- a/src/kernel/memory.c +++ b/src/kernel/memory.c @@ -67,10 +67,10 @@ void memory_page_map(uint64_t *pml4, void *virt, void *phys, uint64_t flags) { const uint64_t pd_index = (ivirt >> 21) & 0x1FF; const uint64_t pt_index = (ivirt >> 12) & 0x1FF; - TRACE_LN("Mapping physical %lx to virtual %lx / [%u, %u, %u, %u]...", phys, virt, pml4_index, pdpt_index, pd_index, pt_index); + LOG_LN_TRACE("Mapping physical %lx to virtual %lx / [%u, %u, %u, %u]...", phys, virt, pml4_index, pdpt_index, pd_index, pt_index); if (!(pml4[pml4_index] & PAGE_PRESENT)) { - TRACE_LN("PML4 entry %u does not exist, creating...", pml4_index); + LOG_LN_TRACE("PML4 entry %u does not exist, creating...", pml4_index); uint64_t *pdpt = memory_page_allocate(); memory_set(0, PAGE_SIZE, PHYS_TO_VIRT(pdpt)); pml4[pml4_index] = (uint64_t)pdpt | PAGE_PRESENT | PAGE_WRITABLE | PAGE_USER; @@ -78,7 +78,7 @@ void memory_page_map(uint64_t *pml4, void *virt, void *phys, uint64_t flags) { uint64_t *pdpt = PHYS_TO_VIRT(pml4[pml4_index] & ~(uint64_t)0xFFF); if (!(pdpt[pdpt_index] & PAGE_PRESENT)) { - TRACE_LN("PDPT entry %u does not exist, creating...", pdpt_index); + LOG_LN_TRACE("PDPT entry %u does not exist, creating...", pdpt_index); uint64_t *pd = memory_page_allocate(); memory_set(0, PAGE_SIZE, PHYS_TO_VIRT(pd)); pdpt[pdpt_index] = (uint64_t)pd | PAGE_PRESENT | PAGE_WRITABLE | PAGE_USER; @@ -87,7 +87,7 @@ void memory_page_map(uint64_t *pml4, void *virt, void *phys, uint64_t flags) { uint64_t *pd = PHYS_TO_VIRT(pdpt[pdpt_index] & ~(uint64_t)0xFFF); ASSERT(!(pd[pd_index] & 0x80), "memory_page_map: Huge page in PD."); if (!(pd[pd_index] & PAGE_PRESENT)) { - TRACE_LN("PD entry %u does not exist, creating...", pd_index); + LOG_LN_TRACE("PD entry %u does not exist, creating...", pd_index); uint64_t *pt = memory_page_allocate(); memory_set(0, PAGE_SIZE, PHYS_TO_VIRT(pt)); pd[pd_index] = (uint64_t)pt | PAGE_PRESENT | PAGE_WRITABLE | PAGE_USER; @@ -97,11 +97,11 @@ void memory_page_map(uint64_t *pml4, void *virt, void *phys, uint64_t flags) { ASSERT(!(pt[pt_index] & PAGE_PRESENT), "memory_page_map: Page already mapped.") - TRACE_LN("PT entry %u does not exist, creating...", pt_index); + LOG_LN_TRACE("PT entry %u does not exist, creating...", pt_index); pt[pt_index] = (uint64_t)phys | flags | PAGE_PRESENT; - TRACE_VAL(pt[pt_index]); + LOG_VAL_TRACE(pt[pt_index], "%lx"); - TRACE_LN("Done."); + LOG_LN_TRACE("Done."); } void memory_page_unmap(uint64_t *pml4, void *virt) { diff --git a/src/kernel/nvme.c b/src/kernel/nvme.c index f812eff..f518d22 100644 --- a/src/kernel/nvme.c +++ b/src/kernel/nvme.c @@ -89,118 +89,118 @@ static uint16_t io_cq_head = 0; static void admin_exec_sync(nvme_sqe_t *cmd) { cmd->cid = admin_sq_tail; - TRACE_LN("Queueing submission..."); - TRACE_VAL_F(cmd->opc, "%hhx"); - TRACE_VAL_F(cmd->nsid, "%x"); - TRACE_VAL_F(cmd->cdw10, "%x"); - TRACE_VAL_F(cmd->cdw11, "%x"); - TRACE_VAL_F(cmd->cdw12, "%x"); - TRACE_VAL_F(cmd->prp1, "%lx"); - TRACE_VAL_F(cmd->prp2, "%lx"); + LOG_LN_STEP("Queueing submission..."); + LOG_VAL_TRACE(cmd->opc, "%hhx"); + LOG_VAL_TRACE(cmd->nsid, "%x"); + LOG_VAL_TRACE(cmd->cdw10, "%x"); + LOG_VAL_TRACE(cmd->cdw11, "%x"); + LOG_VAL_TRACE(cmd->cdw12, "%x"); + LOG_VAL_TRACE(cmd->prp1, "%lx"); + LOG_VAL_TRACE(cmd->prp2, "%lx"); memory_copy(cmd, sizeof(nvme_sqe_t), &admin_sq[admin_sq_tail]); - TRACE_LN("Advancing submission doorbell..."); + LOG_LN_STEP("Advancing submission doorbell..."); db_regs[0] = admin_sq_tail = (admin_sq_tail + 1) % QUEUE_DEPTH; - TRACE_VAL_F(admin_sq_tail, "%u"); + LOG_VAL_TRACE(admin_sq_tail, "%u"); - TRACE_LN("Waiting for completion..."); + LOG_LN_STEP("Waiting for completion..."); nvme_cqe_t *cmp = &admin_cq[admin_cq_head]; while (NVME_CQE_P(cmp) != admin_cq_phase) ; - TRACE_LN("Received completion..."); - TRACE_VAL_F(cmp->dw0, "%x"); - TRACE_VAL_F(cmp->reserved, "%x"); - TRACE_VAL_F(cmp->sqhd, "%hx"); - TRACE_VAL_F(cmp->sqid, "%hx"); - TRACE_VAL_F(cmp->cid, "%hx"); - TRACE_VAL_F(cmp->status, "%hx"); + LOG_LN_STEP("Received completion..."); + LOG_VAL_TRACE(cmp->dw0, "%x"); + LOG_VAL_TRACE(cmp->reserved, "%x"); + LOG_VAL_TRACE(cmp->sqhd, "%hx"); + LOG_VAL_TRACE(cmp->sqid, "%hx"); + LOG_VAL_TRACE(cmp->cid, "%hx"); + LOG_VAL_TRACE(cmp->status, "%hx"); ASSERT(NVME_CQE_STATUS(cmp) == 0, "admin_exec_sync: NVMe command failed."); - TRACE_LN("Advancing completion doorbell..."); + LOG_LN_STEP("Advancing completion doorbell..."); db_regs[1] = admin_cq_head = (admin_cq_head + 1) % QUEUE_DEPTH; admin_cq_phase ^= (admin_cq_head == 0); - TRACE_LN("Done."); + LOG_LN_STEP("Done."); } static void io_exec_sync(nvme_sqe_t *cmd) { cmd->cid = io_sq_tail; - TRACE_LN("Queueing submission..."); - TRACE_VAL_F(cmd->opc, "%hhx"); - TRACE_VAL_F(cmd->nsid, "%x"); - TRACE_VAL_F(cmd->cdw10, "%x"); - TRACE_VAL_F(cmd->cdw11, "%x"); - TRACE_VAL_F(cmd->cdw12, "%x"); - TRACE_VAL_F(cmd->prp1, "%x"); - TRACE_VAL_F(cmd->prp2, "%x"); + LOG_LN_STEP("Queueing submission..."); + LOG_VAL_TRACE(cmd->opc, "%hhx"); + LOG_VAL_TRACE(cmd->nsid, "%x"); + LOG_VAL_TRACE(cmd->cdw10, "%x"); + LOG_VAL_TRACE(cmd->cdw11, "%x"); + LOG_VAL_TRACE(cmd->cdw12, "%x"); + LOG_VAL_TRACE(cmd->prp1, "%x"); + LOG_VAL_TRACE(cmd->prp2, "%x"); memory_copy(cmd, sizeof(nvme_sqe_t), &io_sq[io_sq_tail]); - TRACE_LN("Advancing submission doorbell..."); + LOG_LN_STEP("Advancing submission doorbell..."); db_regs[2] = io_sq_tail = (io_sq_tail + 1) % QUEUE_DEPTH; - TRACE_LN("Waiting for completion..."); + LOG_LN_STEP("Waiting for completion..."); nvme_cqe_t *cmp = &io_cq[io_cq_head]; while (NVME_CQE_P(cmp) != io_cq_phase) ; - TRACE_LN("Received completion..."); - TRACE_VAL_F(cmp->dw0, "%x"); - TRACE_VAL_F(cmp->reserved, "%x"); - TRACE_VAL_F(cmp->sqhd, "%hx"); - TRACE_VAL_F(cmp->sqid, "%hx"); - TRACE_VAL_F(cmp->cid, "%hx"); - TRACE_VAL_F(cmp->status, "%hx"); + LOG_LN_STEP("Received completion..."); + LOG_VAL_TRACE(cmp->dw0, "%x"); + LOG_VAL_TRACE(cmp->reserved, "%x"); + LOG_VAL_TRACE(cmp->sqhd, "%hx"); + LOG_VAL_TRACE(cmp->sqid, "%hx"); + LOG_VAL_TRACE(cmp->cid, "%hx"); + LOG_VAL_TRACE(cmp->status, "%hx"); ASSERT(NVME_CQE_STATUS(cmp) == 0, "io_exec_sync: NVMe command failed."); - TRACE_LN("Advancing completion doorbell..."); + LOG_LN_STEP("Advancing completion doorbell..."); db_regs[3] = io_cq_head = (io_cq_head + 1) % QUEUE_DEPTH; io_cq_phase ^= (io_cq_head == 0); - TRACE_LN("Done."); + LOG_LN_STEP("Done."); } void nvme_init() { - TRACE_LN("Searching for suitable device..."); + LOG_LN_INFO("Searching for suitable device..."); pci_bdf_t bdf = pci_find_by_class(NVME_PCI_CLASS, NVME_PCI_SUBCLASS, NUL); ASSERT(bdf, "nvme_init: No suitable devices found."); - TRACE_LN("Mapping device to virtual memory..."); + LOG_LN_INFO("Mapping device to virtual memory..."); pci_map(bdf, regs, 4); ASSERT(NVME_REGS_NVME_CS_SUPPORTED(regs), "nvme_init: NVM command set not supported."); ASSERT(QUEUE_DEPTH <= NVME_REGS_MQES(regs), "nvme_init: Command queues are too big.") - TRACE_LN("Disabling device..."); + LOG_LN_INFO("Disabling device..."); regs->cc = 0; - TRACE_VAL_F(regs->cc, "%lx"); + LOG_VAL_DATA(regs->cc, "%lx"); while (NVME_REGS_RDY(regs)) ; - TRACE_VAL_F(regs->cc, "%lx"); + LOG_VAL_DATA(regs->cc, "%lx"); - TRACE_LN("Configuring device..."); + LOG_LN_INFO("Configuring device..."); NVME_REGS_ASQS_W(regs, QUEUE_DEPTH - 1); regs->asq = (uint64_t)(VIRT_TO_PHYS(admin_sq)); NVME_REGS_ACQS_W(regs, QUEUE_DEPTH - 1); regs->acq = (uint64_t)(VIRT_TO_PHYS(admin_cq)); - TRACE_VAL_F(regs->asq, "%lx"); - TRACE_VAL_F(regs->acq, "%lx"); - TRACE_VAL_F(regs->aqa, "%lx"); + LOG_VAL_DATA(regs->asq, "%lx"); + LOG_VAL_DATA(regs->acq, "%lx"); + LOG_VAL_DATA(regs->aqa, "%lx"); - TRACE_LN("Enabling device..."); + LOG_LN_INFO("Enabling device..."); NVME_REGS_IOCQES_W(regs, 4); NVME_REGS_IOSQES_W(regs, 6); NVME_REGS_CSS_W(regs, 0); NVME_REGS_EN_W(regs, 1); - TRACE_VAL_F(regs->cc, "%lx"); + LOG_VAL_DATA(regs->cc, "%lx"); while (!NVME_REGS_RDY(regs)) ; - TRACE_VAL_F(regs->cc, "%lx"); + LOG_VAL_DATA(regs->cc, "%lx"); - TRACE_LN("Creating I/O completion queue..."); + LOG_LN_INFO("Creating I/O completion queue..."); nvme_sqe_t create_io_cq = { .opc = 0x05, .prp1 = (uint64_t)VIRT_TO_PHYS(io_cq), @@ -209,7 +209,7 @@ void nvme_init() { }; admin_exec_sync(&create_io_cq); - TRACE_LN("Creating I/O submission queue..."); + LOG_LN_INFO("Creating I/O submission queue..."); nvme_sqe_t create_io_sq = { .opc = 0x01, .prp1 = (uint64_t)VIRT_TO_PHYS(io_sq), @@ -218,11 +218,11 @@ void nvme_init() { }; admin_exec_sync(&create_io_sq); - TRACE_LN("Done."); + LOG_LN_INFO("Done."); } void nvme_read_sectors(uint32_t index, uint8_t count, void *to) { - TRACE_LN("Reading %u sectors at %u...", count, index); + LOG_LN_STEP("Reading %u sectors at %u...", count, index); while (count) { uint64_t remainder = PAGE_SIZE - (uint64_t)to % PAGE_SIZE; @@ -246,11 +246,11 @@ void nvme_read_sectors(uint32_t index, uint8_t count, void *to) { to = (void *)((uint8_t *)to + i_count * SECTOR_SIZE); } - TRACE_LN("Done."); + LOG_LN_STEP("Done."); } void nvme_write_sectors(uint32_t index, uint8_t count, const void *from) { - TRACE_LN("Writing %u sectors at %u...", count, index); + LOG_LN_STEP("Writing %u sectors at %u...", count, index); while (count) { uint64_t remainder = PAGE_SIZE - (uint64_t)from % PAGE_SIZE; @@ -274,5 +274,5 @@ void nvme_write_sectors(uint32_t index, uint8_t count, const void *from) { from = (void *)((uint8_t *)from + i_count * SECTOR_SIZE); } - TRACE_LN("Done."); + LOG_LN_STEP("Done."); } diff --git a/src/kernel/pci.c b/src/kernel/pci.c index 59e6cd9..e78d302 100644 --- a/src/kernel/pci.c +++ b/src/kernel/pci.c @@ -46,9 +46,9 @@ static void pci_write(pci_bdf_t bdf, uint8_t offset, uint32_t value) { } void pci_init() { - LOG_LN("Scanning devices..."); + PRINT_LN(kernel_log, "Scanning devices..."); pci_enumerate(kernel_log); - LOG_LN("Done."); + PRINT_LN(kernel_log, "Done."); } void pci_enumerate(stream_t *out) { @@ -60,8 +60,8 @@ void pci_enumerate(stream_t *out) { continue; } uint32_t class = pci_read(PCI_BDF(b, d, f), PCI_OFFSET_CLASS_REVISION); - PRINT_LN(out, "%hx:%hx class=%hhx subclass=%hhx iface=%hhx.", PCI_VENDOR(id), PCI_DEVICE(id), PCI_CLASS(class), - PCI_SUBCLASS(class), PCI_INTERFACE(class)); + PRINT_LN(out, "%hx:%hx class=%hhx subclass=%hhx iface=%hhx.", PCI_VENDOR(id), PCI_DEVICE(id), PCI_CLASS(class), PCI_SUBCLASS(class), + PCI_INTERFACE(class)); } } } @@ -93,7 +93,7 @@ void pci_map(pci_bdf_t bdf, volatile void *virt, uint8_t pages) { uint64_t bar = ((uint64_t)pci_read(bdf, PCI_OFFSET_BAR_1) << 32) | (pci_read(bdf, PCI_OFFSET_BAR_0) & 0xFFFFFFF0); - LOG_LN("Mapping BAR to memory, phys %lx <-> virt %lx...", bar, virt); + LOG_LN_STEP("Mapping BAR to memory, phys %lx <-> virt %lx...", bar, virt); for (uint8_t i = 0; i < pages; i++) { memory_page_map((void *)KERNEL_VIRTUAL_PML4, (void *)((uint8_t *)virt + i * PAGE_SIZE), (void *)((uint8_t *)bar + i * PAGE_SIZE), PAGE_WRITABLE | PAGE_PCD | PAGE_USER); @@ -101,7 +101,7 @@ void pci_map(pci_bdf_t bdf, volatile void *virt, uint8_t pages) { } void pci_unmap(pci_bdf_t bdf, volatile void *virt, uint8_t pages) { - LOG_LN("Unmapping BAR from memory, virt %lx...", virt); + LOG_LN_STEP("Unmapping BAR from memory, virt %lx...", virt); for (uint8_t i = 0; i < pages; i++) { memory_page_unmap((void *)KERNEL_VIRTUAL_PML4, (void *)((uint8_t *)virt + i * PAGE_SIZE)); } diff --git a/src/kernel/usb.c b/src/kernel/usb.c index 6bfb4e0..3a7ad6b 100644 --- a/src/kernel/usb.c +++ b/src/kernel/usb.c @@ -23,9 +23,9 @@ typedef struct __attribute__((packed)) { static usb_device_descriptor_t device_descriptor __attribute__((aligned(64))); void usb_init() { - LOG_LN("Enumerating devices..."); + PRINT_LN(kernel_log, "Enumerating devices..."); usb_enumerate(kernel_log); - LOG_LN("Done."); + PRINT_LN(kernel_log, "Done."); } void usb_enumerate(stream_t *out) { diff --git a/src/kernel/xhci.c b/src/kernel/xhci.c index c4501d5..1006b1a 100644 --- a/src/kernel/xhci.c +++ b/src/kernel/xhci.c @@ -199,10 +199,10 @@ static uint8_t tr_i = 0; static xhci_trb_t tr[RING_LENGTH + 1] __attribute__((aligned(PAGE_SIZE))); static const xhci_trb_t *command_exec_sync(const xhci_trb_t *cmd) { - LOG_LN("Queueing command TRB..."); - LOG_VAL_F(cmd->parameter, "%lx"); - LOG_VAL_F(cmd->status, "%x"); - LOG_VAL_F(cmd->control, "%x"); + LOG_LN_STEP("Queueing command TRB..."); + LOG_VAL_TRACE(cmd->parameter, "%lx"); + LOG_VAL_TRACE(cmd->status, "%x"); + LOG_VAL_TRACE(cmd->control, "%x"); xhci_trb_t *cre = &cr[cr_i]; @@ -213,12 +213,12 @@ static const xhci_trb_t *command_exec_sync(const xhci_trb_t *cmd) { XHCI_TRB_CYCLE_W((&cr[RING_LENGTH]), cr_cycle); cr_cycle ^= (cr_i == 0); - LOG_LN("Ringing command doorbell..."); - LOG_VAL_F(op_regs->usbsts, "%x"); + LOG_LN_STEP("Ringing command doorbell..."); + LOG_VAL_TRACE(op_regs->usbsts, "%x"); db_regs[0] = 0; - LOG_VAL_F(op_regs->usbsts, "%x"); + LOG_VAL_TRACE(op_regs->usbsts, "%x"); - LOG_LN("Waiting for completion..."); + LOG_LN_STEP("Waiting for completion..."); while (1) { xhci_trb_t *cmp = &er[er_i]; while (XHCI_TRB_CYCLE_R(cmp) != er_cycle) @@ -229,75 +229,77 @@ static const xhci_trb_t *command_exec_sync(const xhci_trb_t *cmd) { er_cycle ^= (er_i == 0); if (XHCI_TRB_TRB_TYPE_R(cmp) != XHCI_TRB_TYPE_EVENT_COMMAND_COMPLETION || (void *)cmp->parameter != VIRT_TO_PHYS(cre)) { - LOG_LN("Received irrelevant event, skipping..."); + LOG_LN_STEP("Received irrelevant event, skipping..."); } else { - LOG_LN("Received command completion event..."); + LOG_LN_STEP("Received command completion event..."); - LOG_VAL_F(cmp->parameter, "%lx"); - LOG_VAL_F(cmp->status, "%x"); - LOG_VAL_F(cmp->control, "%x"); + LOG_VAL_TRACE(cmp->parameter, "%lx"); + LOG_VAL_TRACE(cmp->status, "%x"); + LOG_VAL_TRACE(cmp->control, "%x"); ASSERT(XHCI_TRB_COMPLETION_CODE(cmp) == 1, "command_exec_sync: Command failed."); + LOG_LN_STEP("Done."); + return cmp; } } } void xhci_init() { - TRACE_LN("Searching for suitable controller..."); + LOG_LN_INFO("Searching for suitable controller..."); pci_bdf_t bdf = pci_find_by_class(XHCI_PCI_CLASS, XHCI_PCI_SUBCLASS, XHCI_PCI_INTERFACE); ASSERT(bdf, "xhci_init: No suitable controllers found."); - TRACE_LN("Mapping controller to virtual memory..."); + LOG_LN_INFO("Mapping controller to virtual memory..."); pci_map(bdf, cap_regs, 4); op_regs = (xhci_op_regs_t *)((uint8_t *)cap_regs + cap_regs->caplength); port_regs = (xhci_port_regs_t *)((uint8_t *)cap_regs + cap_regs->caplength + 0x400); intr_regs = (xhci_intr_regs_t *)((uint8_t *)cap_regs + cap_regs->rtsoff + 0x20); db_regs = (uint32_t *)((uint8_t *)cap_regs + cap_regs->dboff); - TRACE_VAL_F(cap_regs->caplength, "%hhx"); - TRACE_VAL_F(cap_regs->hciversion, "%hx"); - TRACE_VAL_F(cap_regs->hcsparams1, "%x"); - TRACE_VAL_F(cap_regs->hcsparams2, "%x"); - TRACE_VAL_F(cap_regs->hcsparams3, "%x"); - TRACE_VAL_F(cap_regs->hccparams1, "%x"); - TRACE_VAL_F(cap_regs->dboff, "%x"); - TRACE_VAL_F(cap_regs->rtsoff, "%x"); - TRACE_VAL_F(cap_regs->hccparams2, "%x"); + LOG_VAL_DATA(cap_regs->caplength, "%hhx"); + LOG_VAL_DATA(cap_regs->hciversion, "%hx"); + LOG_VAL_DATA(cap_regs->hcsparams1, "%x"); + LOG_VAL_DATA(cap_regs->hcsparams2, "%x"); + LOG_VAL_DATA(cap_regs->hcsparams3, "%x"); + LOG_VAL_DATA(cap_regs->hccparams1, "%x"); + LOG_VAL_DATA(cap_regs->dboff, "%x"); + LOG_VAL_DATA(cap_regs->rtsoff, "%x"); + LOG_VAL_DATA(cap_regs->hccparams2, "%x"); - TRACE_VAL_F(op_regs->usbcmd, "%x"); - TRACE_VAL_F(op_regs->usbsts, "%x"); - TRACE_VAL_F(op_regs->pagesize, "%x"); - TRACE_VAL_F(op_regs->dnctrl, "%x"); - TRACE_VAL_F(op_regs->crcr, "%lx"); - TRACE_VAL_F(op_regs->dcbaap, "%lx"); - TRACE_VAL_F(op_regs->config, "%x"); + LOG_VAL_DATA(op_regs->usbcmd, "%x"); + LOG_VAL_DATA(op_regs->usbsts, "%x"); + LOG_VAL_DATA(op_regs->pagesize, "%x"); + LOG_VAL_DATA(op_regs->dnctrl, "%x"); + LOG_VAL_DATA(op_regs->crcr, "%lx"); + LOG_VAL_DATA(op_regs->dcbaap, "%lx"); + LOG_VAL_DATA(op_regs->config, "%x"); - TRACE_LN("Stopping controller..."); + LOG_LN_INFO("Stopping controller..."); XHCI_OP_REGS_RS_W(op_regs, 0); - TRACE_VAL_F(op_regs->usbcmd, "%x"); - TRACE_VAL_F(op_regs->usbsts, "%x"); + LOG_VAL_DATA(op_regs->usbcmd, "%x"); + LOG_VAL_DATA(op_regs->usbsts, "%x"); while (!XHCI_OP_REGS_HCH(op_regs)) ; - TRACE_VAL_F(op_regs->usbcmd, "%x"); - TRACE_VAL_F(op_regs->usbsts, "%x"); + LOG_VAL_DATA(op_regs->usbcmd, "%x"); + LOG_VAL_DATA(op_regs->usbsts, "%x"); - TRACE_LN("Resetting controller..."); + LOG_LN_INFO("Resetting controller..."); XHCI_OP_REGS_EINT_W(op_regs, 0); XHCI_OP_REGS_HCRST_W(op_regs, 1); - TRACE_VAL_F(op_regs->usbcmd, "%x"); - TRACE_VAL_F(op_regs->usbsts, "%x"); + LOG_VAL_DATA(op_regs->usbcmd, "%x"); + LOG_VAL_DATA(op_regs->usbsts, "%x"); while (XHCI_OP_REGS_HCRST_R(op_regs)) ; - TRACE_VAL_F(op_regs->usbcmd, "%x"); - TRACE_VAL_F(op_regs->usbsts, "%x"); + LOG_VAL_DATA(op_regs->usbcmd, "%x"); + LOG_VAL_DATA(op_regs->usbsts, "%x"); while (XHCI_OP_REGS_CNR(op_regs)) ; - TRACE_VAL_F(op_regs->usbcmd, "%x"); - TRACE_VAL_F(op_regs->usbsts, "%x"); + LOG_VAL_DATA(op_regs->usbcmd, "%x"); + LOG_VAL_DATA(op_regs->usbsts, "%x"); - TRACE_LN("Setting up command ring..."); + LOG_LN_INFO("Setting up command ring..."); xhci_trb_t *wrapper = &cr[RING_LENGTH]; wrapper->parameter = (uint64_t)VIRT_TO_PHYS(cr); wrapper->status = 0; @@ -305,7 +307,7 @@ void xhci_init() { XHCI_TRB_TOGGLE_CYCLE_W(wrapper, 1); XHCI_TRB_CYCLE_W(wrapper, cr_cycle); - TRACE_LN("Configuring controller..."); + LOG_LN_INFO("Configuring controller..."); XHCI_OP_REGS_MAX_SLOTS_EN_W(op_regs, MAX_SLOTS); op_regs->dcbaap = (uint64_t)VIRT_TO_PHYS(dcbaa); op_regs->crcr = (uint64_t)VIRT_TO_PHYS(cr) | cr_cycle; @@ -315,30 +317,29 @@ void xhci_init() { intr_regs->erstba = (uint64_t)VIRT_TO_PHYS(erst); intr_regs->erdp = erst[0].base; - TRACE_VAL_F(op_regs->config, "%x"); - TRACE_VAL_F(op_regs->dcbaap, "%lx"); - TRACE_VAL_F(op_regs->crcr, "%lx"); - TRACE_VAL_F(intr_regs->erstba, "%lx"); - TRACE_VAL_F(intr_regs->erstsz, "%x"); - TRACE_VAL_F(intr_regs->erdp, "%lx"); - TRACE_VAL_F(erst[0].size, "%hx"); - TRACE_VAL_F(erst[0].base, "%lx"); + LOG_VAL_DATA(op_regs->config, "%x"); + LOG_VAL_DATA(op_regs->dcbaap, "%lx"); + LOG_VAL_DATA(op_regs->crcr, "%lx"); + LOG_VAL_DATA(intr_regs->erstba, "%lx"); + LOG_VAL_DATA(intr_regs->erstsz, "%x"); + LOG_VAL_DATA(intr_regs->erdp, "%lx"); + LOG_VAL_DATA(erst[0].size, "%hx"); + LOG_VAL_DATA(erst[0].base, "%lx"); - TRACE_LN("Starting controller..."); - TRACE_VAL_F(op_regs->usbcmd, "%x"); - TRACE_VAL_F(op_regs->usbsts, "%x"); + LOG_LN_INFO("Starting controller..."); + LOG_VAL_DATA(op_regs->usbcmd, "%x"); + LOG_VAL_DATA(op_regs->usbsts, "%x"); XHCI_OP_REGS_RS_W(op_regs, 1); - TRACE_VAL_F(op_regs->usbcmd, "%x"); - TRACE_VAL_F(op_regs->usbsts, "%x"); + LOG_VAL_DATA(op_regs->usbcmd, "%x"); + LOG_VAL_DATA(op_regs->usbsts, "%x"); while (XHCI_OP_REGS_HCH(op_regs)) ; - TRACE_VAL_F(op_regs->usbcmd, "%x"); - TRACE_VAL_F(op_regs->usbsts, "%x"); + LOG_VAL_DATA(op_regs->usbcmd, "%x"); + LOG_VAL_DATA(op_regs->usbsts, "%x"); - LOG_LN("Enumerating ports..."); + PRINT_LN(kernel_log, "Enumerating ports..."); xhci_enumerate(kernel_log); - - LOG_LN("Done."); + PRINT_LN(kernel_log, "Done."); } void xhci_enumerate(stream_t *out) { @@ -357,6 +358,8 @@ uint8_t xhci_port_connected(uint8_t port) { } xhci_slot_t xhci_attach(uint8_t port) { + LOG_LN_STEP("Attaching port %d ...", port); + ASSERT(!tr_attached_slot, "xhci_attach: Can only attach one port at a time.") ASSERT(XHCI_PORT_REGS_CCS(&port_regs[port]), "xhci_attach: Port is not connected."); @@ -364,21 +367,21 @@ xhci_slot_t xhci_attach(uint8_t port) { tr_i = 0; tr_cycle = 1; - LOG_LN("Resetting device..."); + LOG_LN_STEP("Resetting device..."); port_regs[port].portsc = 1 << 4; while (XHCI_PORT_REGS_PR_R(&port_regs[port])) ; while (!XHCI_PORT_REGS_PED(&port_regs[port])) ; - TRACE_VAL_F(XHCI_PORT_REGS_PED(&port_regs[port]), "%hhx"); + LOG_VAL_TRACE(XHCI_PORT_REGS_PED(&port_regs[port]), "%hhx"); - LOG_LN("Enabling a slot..."); + LOG_LN_STEP("Enabling a slot..."); xhci_trb_t cmd_es; memory_set(0, sizeof(xhci_trb_t), &cmd_es); XHCI_TRB_TRB_TYPE_W(&cmd_es, XHCI_TRB_TYPE_COMMAND_ENABLE_SLOT); xhci_slot_t slot = XHCI_TRB_SLOT_ID_R(command_exec_sync(&cmd_es)); - LOG_LN("Addressing device..."); + LOG_LN_STEP("Addressing device..."); memory_set(0, sizeof(input_ctx), &input_ctx); input_ctx.control.add_flags = 0b11; XHCI_SLOT_CTX_CTX_ENTRIES_W(&input_ctx.slot, 1); @@ -399,13 +402,15 @@ xhci_slot_t xhci_attach(uint8_t port) { tr_attached_slot = slot; + LOG_LN_STEP("Done."); + return slot; } uint64_t xhci_control_transfer(xhci_slot_t slot, uint64_t setup, void *data, uint16_t length) { ASSERT(tr_attached_slot == slot, "xhci_control_transfer: Can only attach one port at a time."); - LOG_LN("Queueing transfer TRBs..."); + LOG_LN_STEP("Queueing transfer TRBs..."); tr[tr_i].parameter = setup; tr[tr_i].status = sizeof(setup); @@ -414,9 +419,9 @@ uint64_t xhci_control_transfer(xhci_slot_t slot, uint64_t setup, void *data, uin BITS_W(tr[tr_i].control, 6, 6, 1); XHCI_TRB_CYCLE_W(&tr[tr_i], tr_cycle); - LOG_VAL_F(tr[tr_i].parameter, "%lx"); - LOG_VAL_F(tr[tr_i].status, "%x"); - LOG_VAL_F(tr[tr_i].control, "%x"); + LOG_VAL_TRACE(tr[tr_i].parameter, "%lx"); + LOG_VAL_TRACE(tr[tr_i].status, "%x"); + LOG_VAL_TRACE(tr[tr_i].control, "%x"); tr_i = (tr_i + 1) % RING_LENGTH; XHCI_TRB_CYCLE_W(&tr[RING_LENGTH], tr_cycle); @@ -428,9 +433,9 @@ uint64_t xhci_control_transfer(xhci_slot_t slot, uint64_t setup, void *data, uin BITS_W(tr[tr_i].control, 16, 16, 1); XHCI_TRB_CYCLE_W(&tr[tr_i], tr_cycle); - LOG_VAL_F(tr[tr_i].parameter, "%lx"); - LOG_VAL_F(tr[tr_i].status, "%x"); - LOG_VAL_F(tr[tr_i].control, "%x"); + LOG_VAL_TRACE(tr[tr_i].parameter, "%lx"); + LOG_VAL_TRACE(tr[tr_i].status, "%x"); + LOG_VAL_TRACE(tr[tr_i].control, "%x"); tr_i = (tr_i + 1) % RING_LENGTH; XHCI_TRB_CYCLE_W(&tr[RING_LENGTH], tr_cycle); @@ -447,10 +452,10 @@ uint64_t xhci_control_transfer(xhci_slot_t slot, uint64_t setup, void *data, uin XHCI_TRB_CYCLE_W(&tr[RING_LENGTH], tr_cycle); tr_cycle ^= (tr_i == 0); - LOG_LN("Ringing slot doorbell..."); + LOG_LN_STEP("Ringing slot doorbell..."); db_regs[tr_attached_slot] = 1; - LOG_LN("Waiting for completion..."); + LOG_LN_STEP("Waiting for completion..."); while (1) { xhci_trb_t *cmp = &er[er_i]; while (XHCI_TRB_CYCLE_R(cmp) != er_cycle) @@ -461,22 +466,26 @@ uint64_t xhci_control_transfer(xhci_slot_t slot, uint64_t setup, void *data, uin er_cycle ^= (er_i == 0); if (XHCI_TRB_TRB_TYPE_R(cmp) != XHCI_TRB_TYPE_EVENT_TRANSFER_COMPLETION || (void *)cmp->parameter != VIRT_TO_PHYS(tre)) { - LOG_LN("Received irrelevant event, skipping..."); + LOG_LN_STEP("Received irrelevant event, skipping..."); } else { - LOG_LN("Received transfer completion event..."); + LOG_LN_STEP("Received transfer completion event..."); - LOG_VAL_F(cmp->parameter, "%lx"); - LOG_VAL_F(cmp->status, "%x"); - LOG_VAL_F(cmp->control, "%x"); + LOG_VAL_TRACE(cmp->parameter, "%lx"); + LOG_VAL_TRACE(cmp->status, "%x"); + LOG_VAL_TRACE(cmp->control, "%x"); ASSERT(XHCI_TRB_COMPLETION_CODE(cmp) == 1, "xhci_control_transfer: Transfer failed."); + LOG_LN_STEP("Done."); + return length - (cmp->status & 0xFFFFFF); } } } void xhci_detach(xhci_slot_t slot) { + LOG_LN_STEP("Detaching slot %d...", slot); + ASSERT(tr_attached_slot == slot, "xhci_detach: Slot not attached."); xhci_trb_t cmd_ds; @@ -487,4 +496,6 @@ void xhci_detach(xhci_slot_t slot) { dcbaa[slot] = 0; tr_attached_slot = 0; + + LOG_LN_STEP("Done."); }