commit a91825ce61ca2e31c3990fcc0084552ebd8f23f4 from: int16h date: Tue Dec 9 20:06:23 2025 UTC Shitstorm ending: System now boots to shell with console/tty/pty working (intermittent ramdiskd or related disk I/O issues remain); yield storm tamed. TODO: Work more on ramdiskd/IPC commit - 59b10ca5186d691ee2071af0a3aef145ee195dc2 commit + a91825ce61ca2e31c3990fcc0084552ebd8f23f4 blob - c3fba39129b4073242a9e30c75f445a83e2b40ab blob + 3886cf9661c1f94ff039003cf6984e58efe3a7a9 --- kernel/arch/x86_64/isr.c +++ kernel/arch/x86_64/isr.c @@ -162,6 +162,8 @@ x86_fault_double(struct interrupt_frame *frame, uint64 __attribute__((interrupt)) static void x86_fault_gpf(struct interrupt_frame *frame, uint64_t error_code) { + bool user_mode = (frame->cs & 0x3) == 0x3; + printk("[trap] general protection fault\n"); trap_print_hex64(" error_code=", error_code); x86_log_gpf(error_code); @@ -175,7 +177,22 @@ x86_fault_gpf(struct interrupt_frame *frame, uint64_t } } trap_print_hex64(" last_iret_cs=", x86_last_iret_cs); + printk(" task="); + printk(sched_current_task_name()); + printk("\n"); + if (user_mode) + x86_dump_user_stack(frame->rsp); x86_exception_log_frame(frame); + if (user_mode) { + struct sched_task *task = sched_current_task(); + + printk("[trap] user GPF -> SIGSEGV and task exit\n"); + if (task != NULL) { + sched_task_set_exit_status(task, + wait_status_signal(SIGSEGV, false)); + sched_exit_current(); + } + } panic("general protection fault"); } blob - cd77c6907b6af191481a6ed4da470f294d11a392 blob + 1ca53ff2e1283aaa0ad036ef2170da5afda5b6a5 --- kernel/arch/x86_64/serial.c +++ kernel/arch/x86_64/serial.c @@ -121,7 +121,14 @@ serial_init(void) serial_outb(COM1 + 1, 0x01); /* Enable received-data interrupts. */ x86_idt_set_gate(COM1_VECTOR, x86_serial_isr); pic_unmask_irq(COM1_IRQ); +#ifndef UEFI_BUILD + printk("[serial_init] IRQs ENABLED: COM1_IRQ=4 COM1_VECTOR=36\n"); #endif +#else +#ifndef UEFI_BUILD + printk("[serial_init] POLLING mode (no IRQs)\n"); +#endif +#endif } /* @@ -136,14 +143,19 @@ serial_ready(void) /* * serial_putc - write a single character, expanding '\n' to CRLF. + * Non-blocking: if TX register is not ready, character is dropped to prevent + * deadlock when echo blocks input processing. */ void serial_putc(char c) { if (c == '\n') serial_putc('\r'); /* Preserve CRLF expectations for consoles. */ - while (!serial_ready()) - /* spin until hardware is ready */ ; + /* Non-blocking: check TX ready once, drop if not available. + * This prevents echo from blocking input processing when serial TX is busy. + * For critical output, use serial_write_blocking() instead. */ + if (!serial_ready()) + return; /* TX busy - drop character to avoid blocking */ serial_outb(COM1, (unsigned char)c); } @@ -175,11 +187,55 @@ serial_getc_nonblock(char *c) void serial_irq(void) { + static uint32_t irq_count = 0; + /* Log FIRST call unconditionally to confirm IRQ handler is invoked */ + if (irq_count == 0) { + printk("[serial_irq] FIRST CALL - IRQ handler active\n"); + } + if ((++irq_count % 10) == 0) { + printk("[serial_irq] called #"); + char buf[16]; + uint32_t val = irq_count / 10; + int idx = 0; + if (val == 0) { + buf[idx++] = '0'; + } else { + char tmp[16]; + int t = 0; + while (val > 0) { + tmp[t++] = '0' + (val % 10); + val /= 10; + } + while (t > 0) + buf[idx++] = tmp[--t]; + } + buf[idx] = '\0'; + printk(buf); + printk("*10\n"); + } while ((serial_inb(COM1 + 2) & 0x01) == 0) { unsigned char lsr = serial_inb(COM1 + 5); if ((lsr & 0x01) == 0) break; - serial_buffer_push((char)serial_inb(COM1 + 0)); + char ch = (char)serial_inb(COM1 + 0); + /* Log every character received via IRQ */ + { + const char hex[] = "0123456789abcdef"; + printk("[serial_irq_rx] ch=0x"); + char buf[3]; + unsigned char uc = (unsigned char)ch; + buf[0] = hex[(uc >> 4) & 0xf]; + buf[1] = hex[uc & 0xf]; + buf[2] = '\0'; + printk(buf); + if (uc >= 0x20 && uc <= 0x7e) { + printk(" '"); + printk(&ch); + printk("'"); + } + printk("\n"); + } + serial_buffer_push(ch); } } @@ -190,7 +246,64 @@ serial_poll_rx(void) static int serial_poll_debug; #endif unsigned char lsr; + static uint32_t poll_call_count = 0; + /* Log FIRST poll call to confirm function is being invoked */ + if (poll_call_count == 0) { + printk("[serial_poll_rx] FIRST CALL (IRQ mode, SERIAL_WITH_IRQ=1)\n"); + /* Log serial port state */ + lsr = serial_inb(COM1 + 5); + printk("[serial_poll_rx] LSR=0x"); + { + const char hex[] = "0123456789abcdef"; + char buf[3]; + buf[0] = hex[(lsr >> 4) & 0xf]; + buf[1] = hex[lsr & 0xf]; + buf[2] = '\0'; + printk(buf); + } + printk(" (bit0=DR: "); + printk((lsr & 0x01) ? "1" : "0"); + printk(")\n"); + } + poll_call_count++; + + /* Log periodic polling to confirm serial_poll_rx is being called after shell prompt */ + #ifdef LENIX_DEBUG + if (poll_call_count % 100000 == 0 && poll_call_count > 0) { + lsr = serial_inb(COM1 + 5); + printk("[serial_poll_rx] poll #"); + char buf[16]; + uint32_t val = poll_call_count / 100000; /* Reduced frequency: every 100k instead of 10k */ + int idx = 0; + if (val == 0) { + buf[idx++] = '0'; + } else { + char tmp[16]; + int t = 0; + while (val > 0 && t < 15) { + tmp[t++] = '0' + (val % 10); + val /= 10; + } + while (t > 0) + buf[idx++] = tmp[--t]; + } + buf[idx] = '\0'; + printk(buf); + printk("*100000 LSR=0x"); + const char hex[] = "0123456789abcdef"; + char lsr_buf[3]; + lsr_buf[0] = hex[(lsr >> 4) & 0xf]; + lsr_buf[1] = hex[lsr & 0xf]; + lsr_buf[2] = '\0'; + printk(lsr_buf); + printk(" (DR="); + printk((lsr & 0x01) ? "1" : "0"); + printk(")\n"); + } + #endif + + /* Poll hardware FIFO for new characters */ for (;;) { lsr = serial_inb(COM1 + 5); if ((lsr & 0x01) == 0) @@ -228,7 +341,28 @@ serial_poll_rx(void) #if SERIAL_DEBUG_RX static int serial_poll_debug; #endif + static uint32_t poll_call_count = 0; + unsigned char lsr; + /* Log FIRST poll call to confirm function is being invoked */ + if (poll_call_count == 0) { + printk("[serial_poll_rx] FIRST CALL (non-IRQ mode, SERIAL_WITH_IRQ=0)\n"); + lsr = serial_inb(COM1 + 5); + printk("[serial_poll_rx] LSR=0x"); + { + const char hex[] = "0123456789abcdef"; + char buf[3]; + buf[0] = hex[(lsr >> 4) & 0xf]; + buf[1] = hex[lsr & 0xf]; + buf[2] = '\0'; + printk(buf); + } + printk(" (bit0=DR: "); + printk((lsr & 0x01) ? "1" : "0"); + printk(")\n"); + } + poll_call_count++; + while ((serial_inb(COM1 + 5) & 0x01) != 0) { char ch = (char)serial_inb(COM1 + 0); #if SERIAL_DEBUG_RX blob - a2f7ebb42e585147dc19e05ecbd2fcc624a59bc1 blob + 38e7bbfc78a8bb640290e50fa70c5bd321043256 --- kernel/arch/x86_64/signal.c +++ kernel/arch/x86_64/signal.c @@ -4,6 +4,7 @@ #include #include "arch/x86_64/signal.h" +#include "log/printk.h" #include "mm/aspace.h" #include "sched/task.h" #include "sys/signal.h" @@ -75,6 +76,40 @@ x86_signal_prepare(struct x86_syscall_regs *regs, uint return 0; if (signal_state_get_action(state, sig, &act) != 0) return 0; + + /* Safety check: validate handler address IMMEDIATELY after reading it. + * This prevents null pointer dereferences if the handler is invalid. + * Must check before any other handler comparisons. */ + if (act.handler != (uint64_t)SIG_IGN && + act.handler != (uint64_t)SIG_DFL && + (act.handler == 0 || act.handler >= 0x800000000000ULL)) { + /* Invalid handler address - treat as SIG_DFL TERM */ + #ifdef LENIX_DEBUG + printk("[signal] invalid handler address 0x"); + { + const char hex[] = "0123456789abcdef"; + char buf[17]; + uint64_t val = act.handler; + int idx = 0; + for (int shift = 60; shift >= 0; shift -= 4) { + buf[idx++] = hex[(val >> shift) & 0xf]; + } + buf[idx] = '\0'; + printk(buf); + printk(" for sig="); + printk_dec((uint64_t)sig); + printk(" task="); + printk(sched_task_name(task)); + printk("\n"); + } + #endif + signal_state_clear(state, sig); + sched_task_set_exit_status(task, + wait_status_signal(sig, false)); + sched_exit_current(); + /* NOTREACHED */ + } + if (act.handler == (uint64_t)SIG_IGN) { signal_state_clear(state, sig); return 0; @@ -136,6 +171,36 @@ x86_signal_prepare(struct x86_syscall_regs *regs, uint signal_state_update_blocked(state, SIG_SETMASK, new_mask, NULL); } + /* Handler was already validated above, so it's safe to use here. + * Double-check as a safety measure (should never trigger if validation above works). */ + if (act.handler == 0 || act.handler >= 0x800000000000ULL) { + /* This should never happen - handler was validated above. + * But if it does, treat as fatal error. */ + #ifdef LENIX_DEBUG + printk("[signal] CRITICAL: handler became invalid after validation! handler=0x"); + { + const char hex[] = "0123456789abcdef"; + char buf[17]; + uint64_t val = act.handler; + int idx = 0; + for (int shift = 60; shift >= 0; shift -= 4) { + buf[idx++] = hex[(val >> shift) & 0xf]; + } + buf[idx] = '\0'; + printk(buf); + printk(" sig="); + printk_dec((uint64_t)sig); + printk(" task="); + printk(sched_task_name(task)); + printk("\n"); + } + #endif + sched_task_set_exit_status(task, + wait_status_signal(sig, false)); + sched_exit_current(); + /* NOTREACHED */ + } + regs->rcx = act.handler; regs->rdi = (uint64_t)sig; regs->rsi = frame_addr; blob - a0f279fe63ba6ee14b39b6749c247a0a530f4075 blob + a35f03672feb7454dcb0e80d2fd8c6d76cc67b41 --- kernel/console/line.c +++ kernel/console/line.c @@ -53,18 +53,50 @@ static void line_route_char(char c, uint32_t flags) { static int tty_queue_warned; + uint32_t active_pty; - if (console_service_fallback_enabled() && - console_service_tty_task() == NULL) { + active_pty = console_pty_active(); + + /* PTY 0 (console) doesn't route individual characters - completed lines + * are handled via console_line_listener() -> console_queue_push(). + * Individual character routing is only for non-zero PTYs. */ + if (active_pty == 0) { + return; + } + + /* If tty_task is not registered, use direct forwarding as fallback */ + if (console_service_tty_task() == NULL) { console_pty_forward_line(&c, 1); return; } - if (console_service_tty_queue_char(c, flags)) + /* Try to queue character for ttyd - this handles canonical mode editing */ + if (console_service_tty_queue_char(c, flags)) { + tty_queue_warned = 0; /* Reset warning counter on success */ return; - if (tty_queue_warned < 4) { - printk("[console] tty queue saturated; dropping input\n"); - tty_queue_warned++; } + /* If queueing failed, we have two options: + * 1. Drop the character (current behavior) - but this loses input if ttyd is deadlocked + * 2. Fall back to direct forwarding - bypasses canonical mode but preserves input + * + * We'll use a hybrid: if queue fails repeatedly, fall back to direct forwarding + * to prevent input loss if ttyd is blocked or deadlocked. */ + static uint32_t queue_fail_count = 0; + queue_fail_count++; + if (queue_fail_count < 10) { + /* First few failures: warn and drop (ttyd might catch up) */ + if (tty_queue_warned < 4) { + printk("[console] tty queue full, dropping character (ttyd will catch up)\n"); + tty_queue_warned++; + } + } else { + /* Many failures: ttyd is likely blocked, fall back to direct forwarding */ + if (tty_queue_warned < 5) { + printk("[console] tty queue persistently full, falling back to direct forwarding\n"); + tty_queue_warned++; + } + console_pty_forward_line(&c, 1); + queue_fail_count = 0; /* Reset counter after fallback */ + } } static void @@ -102,9 +134,12 @@ line_echo_char(char c, uint64_t flags) static void emit_line(void) { + uint32_t active_pty = console_pty_active(); + if (line_len >= LINE_BUF_LEN) line_len = LINE_BUF_LEN - 1; line_buf[line_len] = '\0'; + if (hook_cb != NULL) hook_cb(line_buf, hook_arg); /* Notify the passive listener (console server) as well. */ @@ -178,6 +213,7 @@ console_line_rx(char c) uint32_t active_pty; bool raw_cr; + /* Ctrl+N always drives PTY cycling regardless of mode */ if ((unsigned char)c == 0x0e) { console_service_control_event(CONSOLE_PTY_CTRL_NEXT); blob - fdcd63da88ce519ec17064ced9a1d19699452d39 blob + 2ab51d58027262200645f45f122644896bc4c653 --- kernel/console/pty.c +++ kernel/console/pty.c @@ -195,12 +195,28 @@ console_pty_alloc(struct sched_task *owner, uint32_t * uint32_t new_id; int wait_iters = 0; - while (console_service_task == NULL && wait_iters < 100000) { - sched_yield(); + printk("[pty] console_pty_alloc called: owner="); + printk(owner ? sched_task_name(owner) : "NULL"); + printk(" console_service_task="); + printk(console_service_task ? sched_task_name(console_service_task) : "NULL"); + printk("\n"); + + while (console_service_task == NULL && wait_iters < 1000) { + /* Sleep for 10ms at 100Hz instead of busy-waiting */ + sched_sleep_ticks(1); wait_iters++; } - if (owner == NULL || console_service_task == NULL) + if (wait_iters > 0) { + printk("[pty] waited "); + printk_dec((uint64_t)wait_iters); + printk(" iterations\n"); + } + if (owner == NULL || console_service_task == NULL) { + printk("[pty] alloc failed: owner or console_service_task NULL, returning -EINVAL="); + printk_dec((uint64_t)(-SYSCALL_EINVAL)); + printk("\n"); return -SYSCALL_EINVAL; + } mbox = sched_task_mailbox(owner); if (mbox == NULL) return -SYSCALL_EINVAL; @@ -236,6 +252,9 @@ console_pty_alloc(struct sched_task *owner, uint32_t * handle = ipc_portal_create(owner, console_service_task, IPC_PORTAL_RIGHT_SEND); + printk("[pty] portal_create returned handle="); + printk_dec((uint64_t)handle); + printk("\n"); if (handle == IPC_PORTAL_INVALID_HANDLE) { printk("[pty] alloc failed: portal_create returned INVALID\n"); spinlock_lock(&console_pty_lock); @@ -258,6 +277,11 @@ console_pty_alloc(struct sched_task *owner, uint32_t * *pty_id_out = pty->id; if (handle_out != NULL) *handle_out = handle; + printk("[pty] console_pty_alloc success: pty_id="); + printk_dec((uint64_t)pty->id); + printk(" handle="); + printk_dec((uint64_t)handle); + printk(" returning 0\n"); return 0; } @@ -406,6 +430,7 @@ console_pty_set_active(uint32_t pty_id, struct sched_t struct console_pty_entry *pty; bool is_supervisor = false; bool can_activate = false; + const char *req_name = requester ? sched_task_name(requester) : "NULL"; if (pty_id != 0) { spinlock_lock(&console_pty_lock); @@ -419,12 +444,37 @@ console_pty_set_active(uint32_t pty_id, struct sched_t can_activate = (pty != NULL && pty->slave.task == requester); /* Allow console service to activate any PTY */ bool is_console_service = (requester == console_service_task); + /* Allow parent to activate PTY owned by its direct child (for spawn scenarios) */ + bool is_parent = false; + if (pty != NULL && pty->slave.task != NULL && requester != NULL) { + uint64_t requester_pid = sched_task_id(requester); + uint64_t child_parent_pid = sched_task_parent_pid(pty->slave.task); + /* Check if requester is the parent of the PTY owner */ + if (child_parent_pid == requester_pid) + is_parent = true; + } if (pty == NULL) { spinlock_unlock(&console_pty_lock); + printk("[pty] set_active fail: missing id="); + printk_dec((uint64_t)pty_id); + printk(" requester="); + printk(req_name); + printk("\n"); return -SYSCALL_EINVAL; } - if (!can_activate && !is_supervisor && !is_console_service) { + if (!can_activate && !is_supervisor && !is_console_service && !is_parent) { spinlock_unlock(&console_pty_lock); + printk("[pty] set_active deny id="); + printk_dec((uint64_t)pty_id); + printk(" owner="); + printk(pty->slave.task ? sched_task_name(pty->slave.task) : "NULL"); + printk(" requester="); + printk(req_name); + printk(" is_supervisor="); + printk(is_supervisor ? "1" : "0"); + printk(" is_console="); + printk(is_console_service ? "1" : "0"); + printk("\n"); return -SYSCALL_EPERM; } /* Save previous PTY when switching away from it */ @@ -446,6 +496,11 @@ console_pty_set_active(uint32_t pty_id, struct sched_t /* Send SIGWINCH to newly active PTY to trigger shell prompt redisplay */ if (console_pty_active_id != 0) console_pty_send_signal(console_pty_active_id, 28); /* SIGWINCH */ + printk("[pty] set_active SUCCESS id="); + printk_dec((uint64_t)pty_id); + printk(" active_pty_id="); + printk_dec((uint64_t)console_pty_active_id); + printk("\n"); return 0; } @@ -853,10 +908,6 @@ int console_pty_send_signal(uint32_t pty_id, uint32_t signal) { struct console_pty_endpoint ep = {0}; - #ifdef LENIX_DEBUG - char buf[32]; - int written; - #endif bool found = false; uint64_t fg_pgrp = 0; bool delivered = false; @@ -889,12 +940,11 @@ console_pty_send_signal(uint32_t pty_id, uint32_t sign if (!delivered) return -SYSCALL_ESRCH; - /* Only inject the textual hint in debug builds; it confuses shells. */ - #ifdef LENIX_DEBUG - written = lenix_snprintf(buf, sizeof(buf), "[signal %u]\n", signal); - if (written > 0) - console_pty_send_to_slave(&ep, buf, (size_t)written); - #endif + /* NOTE: Signal debug messages were removed because they were being sent + * to the PTY slave endpoint (shell stdin), causing the shell to receive + * "[signal %u]" as input and try to execute it as a command. If signal + * debugging is needed, it should be sent to the console service or logged + * via printk() instead of the PTY slave. */ return 0; } @@ -934,6 +984,22 @@ console_pty_input(uint32_t pty_id, const char *buf, si return 0; } +struct ipc_mailbox * +console_pty_get_slave_mailbox(uint32_t pty_id) +{ + struct ipc_mailbox *mbox = NULL; + + if (pty_id == 0) + return NULL; + spinlock_lock(&console_pty_lock); + struct console_pty_entry *pty = console_pty_find_by_id_locked(pty_id); + if (pty != NULL && pty->slave.mailbox != NULL) { + mbox = pty->slave.mailbox; + } + spinlock_unlock(&console_pty_lock); + return mbox; +} + static void console_pty_apply_active_flags(void) { blob - 31b58b25573823a43e48779adca80212fbc1145f blob + 5acc73906b7b64559273d029b872ebd0c26cff02 --- kernel/console/service.c +++ kernel/console/service.c @@ -101,11 +101,30 @@ void console_service_ttyctl_send(const char *buf, siz #define CONSOLE_BLOCKTRACE_MAX 32U -static void +void +console_note_work_available(void) +{ + /* Stub function for now - work availability tracking not yet implemented */ +} + +void console_wake_service_task(void) { - if (console_task != NULL) + static uint32_t wake_debug_count = 0; + if (console_task != NULL && console_task != sched_current_task()) { + if (wake_debug_count < 10) { + // printk("[console_wake] waking console_task\n"); + wake_debug_count++; + } sched_wake(console_task); + } else if (wake_debug_count < 10) { + // printk("[console_wake] SKIP: task="); + // printk(console_task ? "valid" : "NULL"); + // printk(" current="); + // printk(console_task == sched_current_task() ? "SAME" : "DIFF"); + // printk("\n"); + wake_debug_count++; + } } static bool @@ -453,12 +472,15 @@ console_service_init(void) console_ttyctl_task = NULL; console_line_register_listener(console_line_listener, NULL); console_line_set_echo(true); + printk("[console_service_init] spawning console task\n"); console_task = sched_spawn_kernel("console", console_task_main, NULL); console_service_task = console_task; if (console_task == NULL) { + printk("[console_service_init] FAILED to spawn console task\n"); boot_log_status("console: interactive service online", BOOT_LOG_STATUS_FAIL); } else { + printk("[console_service_init] console task spawned successfully\n"); console_pty_attach_service(console_task); console_pty_set_master(console_master_write, NULL); boot_log_status("console: interactive service online", @@ -716,26 +738,29 @@ console_list_ptys(void) } static void -console_task_main(void *arg) + console_task_main(void *arg) { struct console_queue_entry entry; enum console_pty_control_event ctrl_ev; static int console_idle_debug; + static uint32_t idle_iterations = 0; (void)arg; + printk("[console_task] STARTING - before prompt\n"); console_print_prompt(); - static int console_loop_count = 0; + printk("[console_task] started, entering main loop\n"); + static uint64_t console_loop_count __attribute__((unused)) = 0; for (;;) { #ifdef LENIX_DEBUG - if (console_loop_count == 0 || console_loop_count == 1) { + /* Log first few iterations and then every 1000th iteration to confirm task is running */ + if (console_loop_count < 5 || (console_loop_count % 1000 == 0)) { printk("[console] loop iteration "); console_print_uint64(console_loop_count); printk("\n"); } #endif console_loop_count++; - if (console_loop_count > 10) - console_loop_count = 10; + /* Don't cap the counter - let it wrap naturally if needed */ while (console_ctrl_pop(&ctrl_ev)) { if (diag_flag_enabled(DIAG_FLAG_POLICY)) { printk("[diag] console ctrl dispatch ev="); @@ -744,19 +769,63 @@ console_task_main(void *arg) } console_pty_control_event(ctrl_ev); } + /* Log periodic heartbeat to confirm console task is running (even in release builds). + * Log every 100000 iterations to avoid flooding the log. */ + #ifdef LENIX_DEBUG + if (console_loop_count % 100000 == 0 && console_loop_count > 0) { + printk("[console] heartbeat: loop="); + console_print_uint64(console_loop_count); + printk("\n"); + } + #endif console_tty_drain_queue(); + /* Always poll serial for input, even if queue has entries */ + /* Log periodic polling to confirm console task is running after shell prompt */ + #ifdef LENIX_DEBUG + if (console_loop_count % 100000 == 0 && console_loop_count > 0) { + printk("[console] polling serial (loop="); + console_print_uint64(console_loop_count); + printk(")\n"); + } + #endif + serial_poll_rx(); if (!queue_pop(&entry)) { - /* Drain UART then yield; avoids hangs on missed wakeups */ - serial_poll_rx(); - if (console_idle_debug < 4) { + /* Queue empty - but we MUST keep polling serial for input. + * This is critical: before the yield storm fix, serial_poll_rx() + * ran from timer interrupts every tick, so input was always processed. + * Now it only runs when the console task is scheduled, so we must + * stay scheduled as much as possible. + * + * Yield periodically when idle to allow other tasks to run. + * We yield every 10 idle iterations to prevent CPU monopolization + * while still processing input promptly when available. */ + idle_iterations++; + if (console_idle_debug < 10) { #ifdef LENIX_DEBUG - printk("[console] idle, polling serial\n"); + printk("[console] idle, polling serial (iter="); + console_print_uint64(idle_iterations); + printk(")\n"); #endif console_idle_debug++; } - sched_yield(); + /* Yield periodically when idle (every 100000 idle iterations) to allow + * other tasks to run. We yield very infrequently to ensure we stay + * scheduled and can poll serial input frequently. The scheduler will + * preempt us on timer ticks if other tasks need CPU time. + * + * CRITICAL: Console task must stay runnable to process keyboard input. + * If we yield too frequently and all other tasks are blocked on I/O, + * the system can deadlock. Use a very high threshold (100k iterations) + * to minimize yield frequency while still allowing other tasks to run. */ + if (idle_iterations >= 100000) { + idle_iterations = 0; + sched_yield(); + } + /* Continue immediately to keep polling serial */ continue; } + /* Reset idle counter when we have work */ + idle_iterations = 0; if (entry.len > CONSOLE_LINE_MAX) { entry.len = CONSOLE_LINE_MAX; entry.buf[CONSOLE_LINE_MAX - 1] = '\0'; @@ -830,19 +899,57 @@ console_tty_send_char(char c, uint32_t flags) { struct console_tty_event ev; + if (console_tty_portal == IPC_PORTAL_INVALID_HANDLE || - console_tty_task == NULL) + console_tty_task == NULL) { return false; + } memset(&ev, 0, sizeof(ev)); ev.opcode = CONSOLE_TTY_EVENT_CHAR; ev.pty_id = console_pty_active(); - if (ev.pty_id == 0) + if (ev.pty_id == 0) { return false; + } ev.flags = flags; ev.length = 1; ev.data[0] = c; - if (ipc_portal_send(console_tty_portal, &ev, sizeof(ev)) != 0) + + /* Check mailbox depth before sending to avoid blocking if mailbox is full. + * If the mailbox is getting too full (>50 messages) or the lock is held, + * skip sending to prevent the console task from blocking in mailbox_lock() + * or kmem_alloc(). This prevents system-wide deadlocks. */ + struct ipc_mailbox *mbox = ipc_portal_target_mailbox(console_tty_portal); + if (mbox != NULL) { + /* Try to acquire lock with a quick check - if we can't get it immediately, + * the mailbox is likely contended and we should skip this send. */ + uint32_t lock_val = __atomic_exchange_n(&mbox->lock, 1U, __ATOMIC_ACQUIRE); + if (lock_val != 0) { + /* Lock was held - release our failed acquisition and skip send */ + __atomic_store_n(&mbox->lock, 0U, __ATOMIC_RELEASE); + return false; + } + /* Lock acquired - check depth */ + size_t depth = mbox->depth; + if (depth > 50) { + /* Mailbox too full - release lock and skip send */ + __atomic_store_n(&mbox->lock, 0U, __ATOMIC_RELEASE); + return false; + } + /* Release lock - ipc_portal_send will acquire it again */ + __atomic_store_n(&mbox->lock, 0U, __ATOMIC_RELEASE); + } + + /* Add debug logging before portal_send to catch hangs */ + + /* Try to send - if mailbox is full or ttyd is blocked, drop the character + * rather than hanging the console task. This prevents system-wide deadlocks. */ + int send_rc = ipc_portal_send(console_tty_portal, &ev, sizeof(ev)); + if (send_rc != 0) { + /* If send fails, check if it's because mailbox is full. + * In that case, we should drop the character rather than retrying, + * as retrying could cause a deadlock if ttyd is blocked. */ return false; + } return true; } @@ -852,8 +959,9 @@ console_tty_char_push(char c, uint32_t flags) size_t next; if (console_tty_portal == IPC_PORTAL_INVALID_HANDLE || - console_tty_task == NULL) + console_tty_task == NULL) { return false; + } spinlock_lock(&char_queue_lock); @@ -865,9 +973,6 @@ console_tty_char_push(char c, uint32_t flags) * is not draining the queue fast enough. Log this to alert * administrators that the TTY daemon may be hung or unresponsive. */ - printk("[console] WARN: char queue full, drops="); - console_print_uint64(console_char_queue_drops); - printk("\n"); return false; } @@ -877,6 +982,8 @@ console_tty_char_push(char c, uint32_t flags) console_char_tail++; spinlock_unlock(&char_queue_lock); + + console_wake_service_task(); return true; } @@ -906,8 +1013,19 @@ console_tty_drain_queue(void) { struct console_char_event ev; - while (console_tty_char_pop(&ev)) - console_tty_send_char(ev.c, ev.flags); + while (console_tty_char_pop(&ev)) { + /* Skip null characters - these indicate uninitialized queue entries */ + if (ev.c == 0) { + /* Don't send null characters - they're invalid */ + continue; + } + if (!console_tty_send_char(ev.c, ev.flags)) { + /* If send fails (mailbox full or ttyd blocked), drop the character + * and continue draining the queue. This prevents the console task + * from hanging if ttyd is blocked or not receiving messages. */ + continue; + } + } } int @@ -980,9 +1098,11 @@ console_service_tty_queue_char(char c, uint32_t flags) { uint32_t allowed = CONSOLE_PTY_TERMIOS_FLAGS_LOW_MASK; - if ((flags & ~allowed) != 0) + if ((flags & ~allowed) != 0) { return false; - return console_tty_char_push(c, flags); + } + bool rc = console_tty_char_push(c, flags); + return rc; } void blob - 210868dc8e461e618075747055536096a55c100a blob + 1bde332a878e54903d436b45e2eb1a247df1321d --- kernel/include/console/pty.h +++ kernel/include/console/pty.h @@ -58,3 +58,4 @@ int console_pty_send_signal(uint32_t pty_id, uint32_t uint32_t console_pty_active(void); uint32_t console_pty_previous(void); int console_pty_input(uint32_t pty_id, const char *buf, size_t len); +struct ipc_mailbox *console_pty_get_slave_mailbox(uint32_t pty_id); blob - c7defa74defd2b1f0de3ba100a3e6ce4ee036987 blob + 0ca440bf0faeff41170804a265c24938a888ffa2 --- kernel/include/console/service.h +++ kernel/include/console/service.h @@ -39,3 +39,7 @@ bool console_service_serial_mirror_enabled(void); size_t console_service_char_queue_drops(void); size_t console_service_ctrl_queue_drops(void); size_t console_service_input_drops(void); + +/* Wake console service task (e.g., from serial IRQ when input arrives) */ +void console_note_work_available(void); +void console_wake_service_task(void); blob - 5b5787fbfee9fc486057d289fe978d716e2ddad4 blob + 609d8e00af92be34cc2ceb47d7ac1d1a0b66c75f --- kernel/include/ipc/block_service.h +++ kernel/include/ipc/block_service.h @@ -17,6 +17,7 @@ struct ipc_block_service_request { uint32_t blocks; uint64_t lba; uint32_t data_len; + uint32_t reserved; /* padding to distinguish from backend response (4124 bytes) */ uint8_t data[IPC_BLOCK_SERVICE_MAX_DATA]; }; blob - a3d8253f070118b5925b01f52437386d02d17f50 blob + b8e776e4fffa5566067edd711ed6b658a784e396 --- kernel/include/ipc/mailbox.h +++ kernel/include/ipc/mailbox.h @@ -8,6 +8,7 @@ struct ipc_mailbox; struct sched_task; struct ipc_portal_transport_ops; +struct ipc_mailbox_poll_waiter; #define IPC_MAILBOX_MAX_PAYLOAD 8192U #define IPC_MAILBOX_CONTENTION_THRESHOLD 100U /* warn if lock waits >100 ticks */ @@ -74,14 +75,27 @@ struct ipc_mailbox { /* wait queue for blocked receivers */ struct sched_task *wait_head; struct sched_task *wait_tail; + struct ipc_mailbox_poll_waiter *poll_wait_head; + struct ipc_mailbox_poll_waiter *poll_wait_tail; }; +struct ipc_mailbox_poll_waiter { + struct sched_task *task; + struct ipc_mailbox_poll_waiter *next; + bool in_list; +}; + void ipc_mailbox_init(struct ipc_mailbox *, struct sched_task *); int ipc_mailbox_send(struct ipc_mailbox *, const void *buf, size_t len); int ipc_mailbox_send_from(struct ipc_mailbox *, const void *buf, size_t len, struct sched_task *sender, uint32_t portal_id); struct ipc_message *ipc_mailbox_recv(struct ipc_mailbox *); struct ipc_message *ipc_mailbox_recv_block(struct ipc_mailbox *); +bool ipc_mailbox_has_message(const struct ipc_mailbox *); +void ipc_mailbox_poll_waiter_add(struct ipc_mailbox *, + struct ipc_mailbox_poll_waiter *); +bool ipc_mailbox_poll_waiter_remove_task(struct ipc_mailbox *, + const struct sched_task *); void ipc_mailbox_free(struct ipc_message *); void ipc_mailbox_drain(struct ipc_mailbox *); void ipc_mailbox_set_remote(struct ipc_mailbox *, uint32_t node_id, bool remote); blob - 01ca8e9c2d60f68326013e27cecc121f10a7a0c3 blob + a4116a4c06bcfc30183188ccfea702d7160141cc --- kernel/include/ipc/portal.h +++ kernel/include/ipc/portal.h @@ -60,3 +60,4 @@ void ipc_portal_register_transport( uint64_t ipc_portal_message_count(ipc_portal_handle_t); uint64_t ipc_portal_integrity_violations(ipc_portal_handle_t); uint64_t ipc_portal_created_ticks(ipc_portal_handle_t); +struct ipc_mailbox *ipc_portal_target_mailbox(ipc_portal_handle_t); blob - 0b035678f549d10ed635723092a1615a93bbb6bd blob + f2f4e5ebb630270b8c787b212f61592954ccd283 --- kernel/include/sched/task.h +++ kernel/include/sched/task.h @@ -125,6 +125,10 @@ int sched_task_wait(uint64_t caller_pid, int64_t pid, */ uint64_t sched_task_id(const struct sched_task *); /* + * sched_task_parent_pid - return the parent PID of a specific task + */ +uint64_t sched_task_parent_pid(const struct sched_task *); +/* * sched_task_pgrp - return the process group ID of a task */ uint64_t sched_task_pgrp(const struct sched_task *); @@ -188,6 +192,8 @@ int sched_task_set_cwd(struct sched_task *, const char */ void sched_block_current(void); void sched_wake(struct sched_task *); +void sched_sleep_ticks(uint64_t ticks); +bool sched_sleep_cancel(struct sched_task *); /* Wait queue linkage for IPC blocking */ struct sched_task *sched_task_wait_next(const struct sched_task *); blob - 0a4afde5d0435523b7baf038d00578fd27b6d917 blob + 7c585bf0b01b148ccc1e1c2bcd6e82a5ef0782c5 --- kernel/ipc/block_service.c +++ kernel/ipc/block_service.c @@ -29,9 +29,11 @@ struct block_service_pending { bool in_use; bool ready; uint32_t token; + volatile uint8_t prepared; struct sched_task *client; - struct ipc_block_service_response *resp; /* Allocated from ringbuf data pool */ - uint32_t resp_offset; /* Offset in ringbuf data pool */ + struct sched_task *waiter; + struct ipc_block_service_response *resp; /* Response buffer */ + uint32_t resp_offset; /* Unused while ringbuf is disabled */ }; static spinlock_t block_pending_lock = SPINLOCK_INIT; @@ -79,6 +81,8 @@ block_pending_alloc(void) slot = &block_state.slots[i]; slot->in_use = true; slot->ready = false; + __atomic_store_n((uint8_t *)&slot->prepared, 0, __ATOMIC_RELAXED); + slot->waiter = NULL; break; } } @@ -205,6 +209,9 @@ block_service_register(ipc_portal_handle_t portal) block_state.slots[i].ready = false; block_state.slots[i].resp = NULL; block_state.slots[i].resp_offset = 0; + block_state.slots[i].waiter = NULL; + __atomic_store_n((uint8_t *)&block_state.slots[i].prepared, 0, + __ATOMIC_RELAXED); } #ifdef LENIX_DEBUG @@ -222,7 +229,6 @@ block_service_issue(const struct ipc_block_service_req struct ipc_block_service_request tmp; struct ringbuf *ringbuf; bool warned = false; - uint32_t cpu; /* Suppress verbose block_service_issue logging to keep boot logs clean. */ @@ -237,20 +243,15 @@ block_service_issue(const struct ipc_block_service_req return -1; } - /* Allocate response buffer from per-CPU ringbuf data pool - * Fallback to kmem if ringbuf unavailable */ - cpu = smp_current_cpu(); - ringbuf = sched_cpu_ringbuf(cpu); - if (ringbuf != NULL) { - slot->resp = ringbuf_data_alloc(ringbuf, - sizeof(*slot->resp), &slot->resp_offset); - } + /* + * Allocate response buffer from kmem to avoid any possibility of + * overlap/corruption in the shared ringbuf data pool while we debug + * the block path. This trades some performance for safety. + */ + ringbuf = NULL; + slot->resp = kmem_alloc(sizeof(*slot->resp)); + slot->resp_offset = 0; if (slot->resp == NULL) { - /* Fallback to kmem allocation */ - slot->resp = kmem_alloc(sizeof(*slot->resp)); - slot->resp_offset = 0; - } - if (slot->resp == NULL) { block_diag_log("[diag][block] response allocation failed\n"); spinlock_lock(&block_pending_lock); slot->in_use = false; @@ -263,6 +264,7 @@ block_service_issue(const struct ipc_block_service_req slot->token = block_state.next_token++; if (block_state.next_token == 0) block_state.next_token = 1; + slot->waiter = sched_current_task(); tmp = *req; tmp.token = slot->token; if ((tmp.flags & IPC_BLOCK_SERVICE_F_WRITE) != 0 && @@ -284,10 +286,10 @@ block_service_issue(const struct ipc_block_service_req block_diag_log_request(&tmp); block_trace_record_submit(&tmp); if (ipc_portal_send(block_state.portal, &tmp, sizeof(tmp)) != 0) { - if (ringbuf != NULL && slot->resp_offset != 0) { + if (ringbuf != NULL) { ringbuf_data_free(ringbuf, slot->resp_offset, sizeof(*slot->resp)); - } else if (ringbuf == NULL) { + } else { kmem_free(slot->resp); } slot->resp = NULL; @@ -309,21 +311,38 @@ block_service_issue(const struct ipc_block_service_req uint64_t start_ticks = timer_ticks(); uint64_t timeout_ticks = timer_get_hz() * 5; /* 5s */ + uint64_t sleep_interval = 1; /* 10ms at 100Hz - short sleep to stay responsive */ + size_t spins = 0; + static uint32_t dbg_issue_log = 0; + if (dbg_issue_log < 3) { + printk("[blocksvc] issue: dev="); + printk_dec((uint64_t)tmp.device); + printk(" lba="); + printk_dec(tmp.lba); + printk(" token="); + printk_dec(slot->token); + printk(" waiter="); + printk(slot->waiter ? sched_task_name(slot->waiter) : "NULL"); + printk("\n"); + dbg_issue_log++; + } while (!__atomic_load_n(&slot->ready, __ATOMIC_ACQUIRE)) { + spins++; if (block_state.server == NULL || slot->client == NULL || (timeout_ticks > 0 && (timer_ticks() - start_ticks) > timeout_ticks)) { - if (ringbuf != NULL && slot->resp_offset != 0) { + if (ringbuf != NULL) { ringbuf_data_free(ringbuf, slot->resp_offset, sizeof(*slot->resp)); - } else if (ringbuf == NULL) { + } else { kmem_free(slot->resp); } slot->resp = NULL; slot->resp_offset = 0; spinlock_lock(&block_pending_lock); slot->in_use = false; + slot->waiter = NULL; spinlock_unlock(&block_pending_lock); struct ipc_block_service_response trace_resp = { .token = slot->token, @@ -340,16 +359,43 @@ block_service_issue(const struct ipc_block_service_req block_diag_log("[diag][block] waiting for daemon response\n"); warned = true; } - sched_yield(); + /* Yield briefly then use timed sleep to allow timeout checks */ + if (spins < 64) { + sched_yield(); + } else { + __atomic_store_n((uint8_t *)&slot->prepared, 1, __ATOMIC_RELEASE); + /* Check ready after setting prepared to avoid lost wakeup */ + if (!__atomic_load_n(&slot->ready, __ATOMIC_ACQUIRE)) + sched_sleep_ticks(sleep_interval); + /* Don't clear prepared here - only clear after ready=true */ + } } - /* Copy response from ringbuf buffer to caller's buffer */ + /* Copy response buffer to caller's buffer */ *resp = *slot->resp; + /* Detect short/partial completions even when status is success. */ + if (resp->status == 0) { + uint64_t expected_bytes = (uint64_t)tmp.blocks * 512ULL; + if (resp->bytes_transferred != expected_bytes) { + printk("[blocksvc] WARN: short response bytes_transferred="); + printk_dec((uint64_t)resp->bytes_transferred); + printk(" expected="); + printk_dec(expected_bytes); + printk(" dev="); + printk_dec((uint64_t)tmp.device); + printk(" lba="); + printk_dec(tmp.lba); + printk(" blocks="); + printk_dec((uint64_t)tmp.blocks); + printk("\n"); + } + } + /* Cleanup allocated response buffer */ - if (ringbuf != NULL && slot->resp_offset != 0) { + if (ringbuf != NULL) { ringbuf_data_free(ringbuf, slot->resp_offset, sizeof(*slot->resp)); - } else if (ringbuf == NULL) { + } else { kmem_free(slot->resp); } @@ -358,6 +404,8 @@ block_service_issue(const struct ipc_block_service_req slot->resp_offset = 0; slot->in_use = false; slot->ready = false; + __atomic_store_n((uint8_t *)&slot->prepared, 0, __ATOMIC_RELAXED); + slot->waiter = NULL; slot->client = NULL; spinlock_unlock(&block_pending_lock); perf_counter_inc(PERF_COUNTER_BLOCK_RESPONSES, 1); @@ -375,7 +423,19 @@ block_service_respond(const struct ipc_block_service_r { struct block_service_pending *slot; struct sched_task *task = sched_current_task(); + static uint32_t dbg_respond_log = 0; + if (dbg_respond_log < 3 && resp != NULL) { + printk("[blocksvc] respond: token="); + printk_dec(resp->token); + printk(" status="); + printk_dec((uint64_t)(uint32_t)resp->status); + printk(" bytes="); + printk_dec((uint64_t)resp->bytes_transferred); + printk("\n"); + dbg_respond_log++; + } + if (!block_service_available() || resp == NULL) return -1; if (task != block_state.server) { @@ -410,8 +470,15 @@ block_service_respond(const struct ipc_block_service_r /* Publish with release semantics */ __atomic_store_n(&slot->ready, true, __ATOMIC_RELEASE); + /* Wake the waiting client (if any) now that the response is ready. + * CRITICAL: Always wake if waiter exists, don't check 'prepared' flag. + * The prepared flag is for optimization but missing a wakeup causes hangs + * when responses arrive within first 64 spins before prepared is set. */ + if (slot->waiter != NULL) + sched_wake(slot->waiter); + spinlock_unlock(&block_pending_lock); - block_trace_record_complete(resp); - return 0; -} + block_trace_record_complete(resp); + return 0; + } blob - c3a0f35ce9cbaf3d26450a6f4198bb84d0d1e9a2 blob + 3ec3faaf3faa6881283a3ffafe721d2ed28a18dd --- kernel/ipc/fs_service.c +++ kernel/ipc/fs_service.c @@ -19,6 +19,8 @@ struct fs_pending { bool in_use; uint32_t token; struct sched_task *client; + struct sched_task *waiter; + volatile uint8_t prepared; struct ipc_fs_response response; bool ready; }; @@ -161,6 +163,8 @@ fs_request_issue(const struct ipc_fs_request *req, return -1; /* slot->in_use and slot->ready already set by fs_pending_alloc() */ slot->client = sched_current_task(); + slot->waiter = slot->client; + slot->prepared = 0; slot->token = fs_state.next_token++; if (fs_state.next_token == 0) fs_state.next_token = 1; @@ -172,6 +176,7 @@ fs_request_issue(const struct ipc_fs_request *req, #endif spinlock_lock(&fs_pending_lock); slot->in_use = false; + slot->waiter = NULL; spinlock_unlock(&fs_pending_lock); return -1; } @@ -195,15 +200,29 @@ fs_request_issue(const struct ipc_fs_request *req, #endif spinlock_lock(&fs_pending_lock); slot->in_use = false; + slot->waiter = NULL; + __atomic_store_n(&slot->prepared, 0, __ATOMIC_RELAXED); spinlock_unlock(&fs_pending_lock); return -1; } - sched_yield(); + /* Spin briefly then block to avoid yield storm */ + if (spins < 256) { + sched_yield(); + } else { + __atomic_store_n(&slot->prepared, 1, __ATOMIC_RELEASE); + /* Check ready after setting prepared to avoid lost wakeup */ + if (!__atomic_load_n(&slot->ready, __ATOMIC_ACQUIRE)) + sched_block_current(); + /* Don't clear prepared here - only clear after ready=true */ + } } + /* Clear prepared after successfully receiving response */ + __atomic_store_n(&slot->prepared, 0, __ATOMIC_RELAXED); fs_memcpy(resp, &slot->response, sizeof(*resp)); spinlock_lock(&fs_pending_lock); slot->in_use = false; slot->ready = false; + slot->waiter = NULL; spinlock_unlock(&fs_pending_lock); return 0; } @@ -241,11 +260,20 @@ fs_service_respond(const struct ipc_fs_response *resp) /* Copy response into slot */ fs_memcpy(&slot->response, resp, sizeof(slot->response)); + /* Capture waiter before publishing ready */ + struct sched_task *waiter = slot->waiter; + bool should_wake = (waiter != NULL && + __atomic_load_n(&slot->prepared, __ATOMIC_ACQUIRE)); + /* Publish with release semantics */ __atomic_store_n(&slot->ready, true, __ATOMIC_RELEASE); spinlock_unlock(&fs_pending_lock); + /* Wake blocked waiter outside lock */ + if (should_wake) + sched_wake(waiter); + #ifdef LENIX_DEBUG printk("[fs] respond token="); { blob - 9c61c131f4c3cb54b40b88f3d69cd9b3d3734e90 blob + b5783c44d4bcac545a837ae9c61a0d5e739d681f --- kernel/ipc/mailbox.c +++ kernel/ipc/mailbox.c @@ -139,6 +139,8 @@ ipc_mailbox_init(struct ipc_mailbox *mbox, struct sche mbox->remote_bytes_sent = 0; mbox->wait_head = NULL; mbox->wait_tail = NULL; + mbox->poll_wait_head = NULL; + mbox->poll_wait_tail = NULL; } int @@ -254,6 +256,17 @@ ipc_mailbox_send_from(struct ipc_mailbox *mbox, const /* Check for blocked receivers and wake one if present */ struct sched_task *waiter = NULL; + struct sched_task *poll_task = NULL; + if (mbox->poll_wait_head != NULL) { + struct ipc_mailbox_poll_waiter *poll_waiter = mbox->poll_wait_head; + mbox->poll_wait_head = poll_waiter->next; + if (mbox->poll_wait_head == NULL) + mbox->poll_wait_tail = NULL; + poll_waiter->next = NULL; + poll_waiter->in_list = false; + /* Capture task pointer now; poll() may free waiter after unlock */ + poll_task = poll_waiter->task; + } if (mbox->wait_head != NULL) { waiter = mbox->wait_head; mbox->wait_head = sched_task_wait_next(waiter); @@ -266,6 +279,8 @@ ipc_mailbox_send_from(struct ipc_mailbox *mbox, const /* Wake the blocked receiver outside the lock */ if (waiter != NULL) sched_wake(waiter); + if (poll_task != NULL) + sched_wake(poll_task); perf_mailbox_depth_sample(mbox->depth); perf_counter_inc(PERF_COUNTER_IPC_MAILBOX_ENQUEUE, 1); @@ -343,6 +358,14 @@ ipc_mailbox_recv_block(struct ipc_mailbox *mbox) } mailbox_unlock(mbox); + /* + * Check if a message arrived while we were adding to wait queue. + * This closes the lost wakeup race: sender may have sent a message + * and called sched_wake() before we call sched_block_current(). + */ + if (ipc_mailbox_has_message(mbox)) + continue; /* Message arrived, loop back to receive it */ + /* Block until woken by sender */ sched_block_current(); @@ -350,7 +373,71 @@ ipc_mailbox_recv_block(struct ipc_mailbox *mbox) } } +bool +ipc_mailbox_has_message(const struct ipc_mailbox *mbox) +{ + bool has; + struct ipc_mailbox *mut = (struct ipc_mailbox *)mbox; + + if (mbox == NULL) + return false; + mailbox_lock(mut); + has = (mut->head != NULL); + mailbox_unlock(mut); + return has; +} + void +ipc_mailbox_poll_waiter_add(struct ipc_mailbox *mbox, + struct ipc_mailbox_poll_waiter *waiter) +{ + if (mbox == NULL || waiter == NULL) + return; + mailbox_lock(mbox); + waiter->next = NULL; + waiter->in_list = true; + if (mbox->poll_wait_tail == NULL) { + mbox->poll_wait_head = waiter; + mbox->poll_wait_tail = waiter; + } else { + mbox->poll_wait_tail->next = waiter; + mbox->poll_wait_tail = waiter; + } + mailbox_unlock(mbox); +} + +bool +ipc_mailbox_poll_waiter_remove_task(struct ipc_mailbox *mbox, + const struct sched_task *task) +{ + struct ipc_mailbox_poll_waiter *prev = NULL; + struct ipc_mailbox_poll_waiter *cur; + + if (mbox == NULL || task == NULL) + return false; + mailbox_lock(mbox); + cur = mbox->poll_wait_head; + while (cur != NULL) { + if (cur->task == task) { + if (prev != NULL) + prev->next = cur->next; + else + mbox->poll_wait_head = cur->next; + if (cur == mbox->poll_wait_tail) + mbox->poll_wait_tail = prev; + cur->next = NULL; + cur->in_list = false; + mailbox_unlock(mbox); + return true; + } + prev = cur; + cur = cur->next; + } + mailbox_unlock(mbox); + return false; +} + +void ipc_mailbox_free(struct ipc_message *msg) { if (msg == NULL) blob - 2685f96e4191af4cc97b1748b113ee3d9fef933f blob + ea1409dc3633758f56dc308c50f8afd5f990d25c --- kernel/ipc/portal.c +++ kernel/ipc/portal.c @@ -56,6 +56,7 @@ struct ipc_portal_entry { static struct ipc_portal_entry portal_table[IPC_PORTAL_MAX]; static const struct ipc_portal_transport_ops *portal_transport_ops; static uint32_t portal_cookie_rng = 0x1f123bb5U; +static bool portal_slot0_reserved; /* Global portal table lock for SMP safety */ static spinlock_t portal_lock = SPINLOCK_INIT; @@ -150,6 +151,9 @@ portal_alloc(void) /* First-free search; future work can move to freelists per CPU. */ for (size_t i = 0; i < IPC_PORTAL_MAX; i++) { + /* Once slot 0 has been allocated, never recycle it. */ + if (i == 0 && portal_slot0_reserved) + continue; if (!portal_table[i].in_use) { /* Warn if we're approaching table exhaustion */ if (i >= IPC_PORTAL_CRITICAL_THRESHOLD) { @@ -194,6 +198,8 @@ portal_alloc(void) printk(")\n"); } entry = &portal_table[i]; + if (i == 0) + portal_slot0_reserved = true; break; } } @@ -313,6 +319,9 @@ ipc_portal_revoke(struct sched_task *owner, ipc_portal struct ipc_portal_entry *entry = portal_lookup(handle); if (entry == NULL) return -1; + /* Never revoke the reserved namesvc bootstrap portal (slot 0). */ + if (((uint16_t)handle & 0xffffU) == 0) + return -1; spinlock_lock(&portal_lock); @@ -404,6 +413,9 @@ ipc_portal_revoke_all_by_owner(struct sched_task *owne continue; if (entry->owner != owner) continue; + /* Preserve reserved namesvc portal slot 0 */ + if ((entry->id & 0xffffU) == 0) + continue; #ifdef LENIX_DEBUG_EXIT serial_write("[portal_revoke_all] slot=", @@ -734,3 +746,13 @@ ipc_portal_created_ticks(ipc_portal_handle_t handle) return 0; return entry->created_ticks; } + +struct ipc_mailbox * +ipc_portal_target_mailbox(ipc_portal_handle_t handle) +{ + struct ipc_portal_entry *entry = portal_lookup(handle); + + if (entry == NULL) + return NULL; + return entry->target_mailbox; +} blob - 342823c59e7609f57d0f82f9767013e5897f4d5d blob + 4d127416e8f6ab3c0e95a81ad911da959576cd51 --- kernel/ipc/ringbuf.c +++ kernel/ipc/ringbuf.c @@ -284,19 +284,21 @@ ringbuf_data_alloc(struct ringbuf *buf, uint32_t size, struct ringbuf_datapool *pool = &buf->datapool; - /* Check if allocation would exceed pool size */ - if (pool->free_offset + size > pool->total_size) - return NULL; /* Pool exhausted */ + /* + * Concurrent allocations can race when multiple tasks share a CPU and + * take turns on the same ringbuf. Use an atomic fetch-add to reserve a + * unique slice and roll back on overflow so two callers never overlap. + */ + uint32_t start = __atomic_fetch_add(&pool->free_offset, size, + __ATOMIC_ACQ_REL); + if (start + size > pool->total_size) { + /* Roll back reservation and signal exhaustion */ + __atomic_fetch_sub(&pool->free_offset, size, __ATOMIC_ACQ_REL); + return NULL; + } - /* Record offset before allocation */ - uint32_t offset = pool->free_offset; - - /* Advance allocator */ - pool->free_offset += size; - - /* Return pointer and offset */ - *offset_out = offset; - return (void *)&buf->data[offset]; + *offset_out = start; + return (void *)&buf->data[start]; } /* @@ -314,8 +316,11 @@ ringbuf_data_free(struct ringbuf *buf, uint32_t offset struct ringbuf_datapool *pool = &buf->datapool; /* Simple optimization: reset allocator if freeing from the end */ - if (offset + size == pool->free_offset) { - pool->free_offset = offset; + uint32_t expected = offset + size; + if (expected == __atomic_load_n(&pool->free_offset, __ATOMIC_RELAXED)) { + (void)__atomic_compare_exchange_n(&pool->free_offset, + &expected, offset, false, __ATOMIC_ACQ_REL, + __ATOMIC_RELAXED); } /* Otherwise, leak the allocation (acceptable for FIFO workloads) */ } blob - d18cae1daceb5f4842fd3bdaf0c8df2f7057e05e blob + ce9b1dad913836bd010d9af81b42f1247e9b613a --- kernel/ipc/service_client.c +++ kernel/ipc/service_client.c @@ -6,9 +6,11 @@ #include #include "ipc/service_client.h" +#include "log/printk.h" #include "ipc/portal.h" #include "sched/task.h" #include "sync/spinlock.h" +#include "time/timer.h" /* * Global registry for tracking pending service-to-service requests. @@ -24,6 +26,7 @@ struct pending_service_request { uint32_t token; /* Request token */ struct sched_task *waiter; /* Task waiting on the response */ struct ipc_service_pending *pending_slot; /* Pointer to pending slot in client */ + volatile uint8_t prepared; /* Set when client is prepared to block */ }; static spinlock_t pending_requests_lock = SPINLOCK_INIT; @@ -73,6 +76,8 @@ pending_service_request_alloc(void) res = &pending_requests[i]; /* Mark as in_use under lock */ res->in_use = true; + __atomic_store_n((uint8_t *)&res->prepared, 0, + __ATOMIC_RELAXED); break; } } @@ -162,10 +167,7 @@ ipc_service_request_issue_timeout(struct ipc_service_c struct ipc_service_pending *slot; uint8_t tmp_req[IPC_MAILBOX_MAX_PAYLOAD]; uint64_t spins = 0; - uint64_t spin_limit = 1024; /* Default iteration budget (tuned down to avoid spin storms) */ - - if (spin_limit_override != 0) - spin_limit = spin_limit_override; + (void)spin_limit_override; /* Override no longer used; fixed threshold */ if (client == NULL || req == NULL || resp == NULL) return -1; /* Portal payloads are limited by IPC_MAILBOX_MAX_PAYLOAD; enforce the @@ -216,21 +218,51 @@ ipc_service_request_issue_timeout(struct ipc_service_c return -1; } + /* Debug: log service requests */ + static uint32_t dbg_svc_issue_log = 0; + if (dbg_svc_issue_log < 5) { + printk("[svcclient] issue: token="); + printk_dec(slot->token); + printk(" portal="); + printk_dec((uint64_t)client->server_portal); + printk("\n"); + dbg_svc_issue_log++; + } + /* Wait for response while yielding so other tasks can run */ + uint64_t start_ticks = timer_ticks(); + uint64_t timeout_ticks = timer_get_hz() * 5; /* 5 second timeout */ + uint64_t sleep_interval = 1; /* 10ms at 100Hz - short sleep to stay responsive */ + spins = 0; while (!__atomic_load_n(&slot->ready, __ATOMIC_ACQUIRE)) { - /* - * Block after the first spin to avoid burning CPU while - * waiting for the service to respond. The response path will - * wake us via sched_wake() using the waiter recorded in preq. - */ - if (spins < spin_limit / 4) { - spins++; + spins++; + + /* Time-based timeout */ + if (timeout_ticks > 0 && + (timer_ticks() - start_ticks) > timeout_ticks) { + slot->in_use = false; + spinlock_lock(&pending_requests_lock); + preq->in_use = false; + preq->waiter = NULL; + spinlock_unlock(&pending_requests_lock); + return -1; + } + + /* Yield briefly then use timed sleep to allow timeout checks */ + if (spins < 64) { sched_yield(); - continue; + } else { + __atomic_store_n((uint8_t *)&preq->prepared, 1, + __ATOMIC_RELEASE); + /* Check ready after setting prepared to avoid lost wakeup */ + if (!__atomic_load_n(&slot->ready, __ATOMIC_ACQUIRE)) + sched_sleep_ticks(sleep_interval); + /* Don't clear prepared here - only clear after ready=true */ } - sched_block_current(); } + /* Clear prepared after successfully receiving response */ + __atomic_store_n((uint8_t *)&preq->prepared, 0, __ATOMIC_RELAXED); /* Copy response to caller's buffer */ if (slot->response_len > resp_len) @@ -289,7 +321,17 @@ ipc_service_handle_response(ipc_portal_handle_t portal struct ipc_service_pending *slot; struct sched_task *waiter = NULL; struct sched_task *server_task; + static uint32_t dbg_handle_resp_log = 0; + if (dbg_handle_resp_log < 5) { + printk("[svcclient] handle_response: token="); + printk_dec(token); + printk(" portal="); + printk_dec((uint64_t)portal); + printk("\n"); + dbg_handle_resp_log++; + } + if (portal == IPC_PORTAL_INVALID_HANDLE || resp == NULL) return -1; @@ -335,14 +377,19 @@ ipc_service_handle_response(ipc_portal_handle_t portal /* Publish readiness with release semantics */ __atomic_store_n(&slot->ready, true, __ATOMIC_RELEASE); - /* Clean up the registry entry */ + /* Capture waiter while still holding lock */ waiter = preq->waiter; + + /* Clean up the registry entry */ preq->in_use = false; preq->waiter = NULL; spinlock_unlock(&pending_requests_lock); - /* Wake the waiting client task (if any) now that the response is ready */ + /* Wake the waiting client task (if any) now that the response is ready. + * CRITICAL: Always wake if waiter exists, don't check 'prepared' flag. + * The prepared flag is for optimization but missing a wakeup causes hangs + * when responses arrive within first 64 spins before prepared is set. */ if (waiter != NULL) sched_wake(waiter); blob - 146231de7d4dd46b8e2b53025e950ab300b11332 blob + ee443f40250ddcb87d1442fa37da2621c91f1e8c --- kernel/ipc/vfs_service.c +++ kernel/ipc/vfs_service.c @@ -24,6 +24,7 @@ struct vfs_pending { uint32_t token; struct sched_task *client; struct sched_task *waiter; + volatile uint8_t prepared; struct ipc_vfs_response response; bool ready; }; @@ -64,6 +65,7 @@ vfs_pending_alloc(void) slot->in_use = true; slot->ready = false; slot->waiter = NULL; + __atomic_store_n((uint8_t *)&slot->prepared, 0, __ATOMIC_RELAXED); break; } } @@ -301,12 +303,19 @@ vfs_request_issue(const struct ipc_vfs_request *req, #endif return -1; } - if (spins < (spin_limit / 4)) { + /* Yield briefly then block to avoid yield storm (64 yields max) */ + if (spins < 64) { sched_yield(); } else { - sched_block_current(); + __atomic_store_n((uint8_t *)&slot->prepared, 1, __ATOMIC_RELEASE); + /* Check ready after setting prepared to avoid lost wakeup */ + if (!__atomic_load_n(&slot->ready, __ATOMIC_ACQUIRE)) + sched_block_current(); + /* Don't clear prepared here - only clear after ready=true */ } } + /* Clear prepared after successfully receiving response */ + __atomic_store_n((uint8_t *)&slot->prepared, 0, __ATOMIC_RELAXED); #ifdef LENIX_DEBUG t_wait = __builtin_ia32_rdtsc(); #endif @@ -316,6 +325,7 @@ vfs_request_issue(const struct ipc_vfs_request *req, slot->in_use = false; slot->ready = false; slot->waiter = NULL; + __atomic_store_n((uint8_t *)&slot->prepared, 0, __ATOMIC_RELAXED); spinlock_unlock(&vfs_pending_lock); #ifdef LENIX_DEBUG t_end = __builtin_ia32_rdtsc(); @@ -374,13 +384,18 @@ vfs_service_respond(const struct ipc_vfs_response *res /* Copy response into inline buffer */ vfs_memcpy(&slot->response, resp, sizeof(*resp)); + /* Capture waiter before publishing ready (slot may be reused after unlock) */ + struct sched_task *waiter = slot->waiter; + bool should_wake = (waiter != NULL && + __atomic_load_n((uint8_t *)&slot->prepared, __ATOMIC_ACQUIRE) != 0); + /* Publish with release semantics */ __atomic_store_n(&slot->ready, true, __ATOMIC_RELEASE); spinlock_unlock(&vfs_pending_lock); /* Wake the waiting client (if any) now that the response is ready */ - if (slot->waiter != NULL) - sched_wake(slot->waiter); + if (should_wake) + sched_wake(waiter); return 0; } blob - f9f55a2bd2dcc13250def1b2a555cd10cc4b4b13 blob + f90ffd9d0af9aa3eada187217c8cbda125cc81f9 --- kernel/sched/task.c +++ kernel/sched/task.c @@ -34,6 +34,7 @@ #include "mm/kmem.h" #include "mm/vm_layout.h" #include "trap/print.h" +#include "time/timer.h" #include "mm/vm.h" #include "panic.h" #include "sched/clock.h" @@ -77,6 +78,7 @@ struct sched_task { uint64_t sid; /* Session ID */ uint64_t yield_count; uint64_t block_count; + uint64_t sleep_deadline; enum sched_state state; bool is_idle; void *stack_base; @@ -110,8 +112,11 @@ struct sched_task { struct sched_task *last_ipc_sender; ipc_portal_handle_t last_ipc_portal; struct sched_dma_allocation dma_allocs[SCHED_DMA_MAX_ALLOCATIONS]; + struct sched_task *sleep_next; char cwd[IPC_VFS_MAX_PATH]; size_t cwd_len; + bool sleeping; + bool pending_wake; }; struct sched_cpu_state { @@ -190,6 +195,8 @@ struct task_exit_status { }; static struct task_exit_status exit_status_table[256]; static struct sched_task *task_list_head; +static struct sched_task *sched_sleep_head; +static spinlock_t sched_sleep_lock = SPINLOCK_INIT; static void sched_task_trampoline(void) __attribute__((noreturn)); static void sched_user_launch(void *) __attribute__((noreturn)); @@ -212,6 +219,7 @@ static void exit_status_clear_pid(uint64_t pid); #ifdef LENIX_DEBUG_EXIT static void exit_status_table_dump(const char *tag); #endif +static void sched_wake_sleepers(uint64_t now); #if defined(__x86_64__) extern char __kernel_text_start[]; extern char __kernel_text_end[]; @@ -675,6 +683,7 @@ sched_tick(void) state->tick_count++; if (state->run_length > state->max_run_length) state->max_run_length = state->run_length; + sched_wake_sleepers(timer_ticks()); /* Set need_resched to trigger a context switch at a safe point */ state->need_resched = true; /* Check for portal_recv timeouts (deadlock detection) */ @@ -726,6 +735,10 @@ sched_block_current(void) if (!scheduler_started) return; task = sched_current_task(); + if (task != NULL && task->pending_wake) { + task->pending_wake = false; + return; + } if (task != NULL) task->block_count++; perf_counter_inc(PERF_COUNTER_SCHED_BLOCK, 1); @@ -742,6 +755,14 @@ sched_block_current(void) } /* Mark task as blocked - it will NOT be requeued */ task->state = SCHED_STATE_BLOCKED; + /* Check pending_wake again after changing state to handle race where + * sched_wake() saw RUNNABLE, set pending_wake=true, but we blocked anyway */ + if (task->pending_wake) { + task->pending_wake = false; + task->state = SCHED_STATE_RUNNABLE; + arch_irq_restore(flags); + return; + } /* Switch to next runnable task without requeuing current */ sched_switch(false); arch_irq_restore(flags); @@ -759,11 +780,16 @@ sched_wake(struct sched_task *task) if (task == NULL) return; - if (task->state != SCHED_STATE_BLOCKED) + if (task->sleeping) + (void)sched_sleep_cancel(task); + if (task->state != SCHED_STATE_BLOCKED) { + task->pending_wake = true; return; + } /* Mark as runnable */ task->state = SCHED_STATE_RUNNABLE; + task->pending_wake = false; task->wait_next = NULL; /* Add to appropriate CPU's run queue */ @@ -786,7 +812,11 @@ sched_wake(struct sched_task *task) state->run_length++; spinlock_unlock(&state->runq_lock); - /* Nudge the CPU if it might be idle */ + /* Nudge the CPU to reschedule and run the newly woken task. + * NOTE: This is now safe because we've eliminated the problematic + * interrupt-context callers (serial IRQ disabled, timer no longer + * calls serial_poll_rx). For same-CPU case, this just sets need_resched + * flag which will be checked on next schedule() call. */ sched_nudge_cpu(cpu); } @@ -805,6 +835,145 @@ sched_task_wait_next_set(struct sched_task *task, stru task->wait_next = next; } +static void +sched_sleep_insert_locked(struct sched_task *task, uint64_t deadline) +{ + struct sched_task **cur; + + if (task == NULL) + return; + + task->sleep_deadline = deadline; + task->sleep_next = NULL; + task->sleeping = true; + + cur = &sched_sleep_head; + while (*cur != NULL && (*cur)->sleep_deadline <= deadline) + cur = &(*cur)->sleep_next; + task->sleep_next = *cur; + *cur = task; +} + +static bool +sched_sleep_remove_locked(struct sched_task *task) +{ + struct sched_task **cur; + + if (task == NULL) + return false; + cur = &sched_sleep_head; + while (*cur != NULL) { + if (*cur == task) { + *cur = task->sleep_next; + task->sleep_next = NULL; + task->sleep_deadline = 0; + task->sleeping = false; + return true; + } + cur = &(*cur)->sleep_next; + } + return false; +} + +static void +sched_wake_sleepers(uint64_t now) +{ + struct sched_task *ready_head = NULL; + struct sched_task *ready_tail = NULL; + + spinlock_lock(&sched_sleep_lock); + #ifdef LENIX_DEBUG + if (sched_sleep_head != NULL && sched_sleep_head->sleep_deadline <= now) { + printk("[sched_wake_sleepers] waking task, now="); + sched_print_uint(now); + printk(" deadline="); + sched_print_uint(sched_sleep_head->sleep_deadline); + printk("\n"); + } + #endif + while (sched_sleep_head != NULL && + sched_sleep_head->sleep_deadline <= now) { + struct sched_task *task = sched_sleep_head; + + sched_sleep_head = task->sleep_next; + task->sleep_next = NULL; + task->sleeping = false; + if (ready_tail == NULL) { + ready_head = task; + ready_tail = task; + } else { + ready_tail->sleep_next = task; + ready_tail = task; + } + } + spinlock_unlock(&sched_sleep_lock); + + while (ready_head != NULL) { + struct sched_task *next = ready_head->sleep_next; + + ready_head->sleep_next = NULL; + sched_wake(ready_head); + ready_head = next; + } +} + +void +sched_sleep_ticks(uint64_t ticks) +{ + struct sched_task *task = sched_current_task(); + uint64_t deadline; + + if (task == NULL) + return; + if (ticks == 0) { + sched_yield(); + return; + } + deadline = timer_ticks() + ticks; + #ifdef LENIX_DEBUG + static int sleep_debug_count = 0; + if (sleep_debug_count < 5) { + printk("[sched_sleep_ticks] task="); + printk(sched_task_name(task)); + printk(" now="); + sched_print_uint(timer_ticks()); + printk(" ticks="); + sched_print_uint(ticks); + printk(" deadline="); + sched_print_uint(deadline); + printk("\n"); + sleep_debug_count++; + } + #endif + spinlock_lock(&sched_sleep_lock); + sched_sleep_insert_locked(task, deadline); + spinlock_unlock(&sched_sleep_lock); + sched_block_current(); + #ifdef LENIX_DEBUG + static int wake_debug_count = 0; + if (wake_debug_count < 5) { + printk("[sched_sleep_ticks] woke: task="); + printk(sched_task_name(task)); + printk("\n"); + wake_debug_count++; + } + #endif + (void)sched_sleep_cancel(task); +} + +bool +sched_sleep_cancel(struct sched_task *task) +{ + bool was_sleeping; + + if (task == NULL) + return false; + spinlock_lock(&sched_sleep_lock); + was_sleeping = sched_sleep_remove_locked(task); + spinlock_unlock(&sched_sleep_lock); + return was_sleeping; +} + /* * sched_task_trampoline - first instruction executed by every fresh task. * Enables interrupts, runs the entrypoint, and panics on unexpected return. @@ -1419,7 +1588,7 @@ sched_task_wait(uint64_t caller_pid, int64_t pid, int serial_write("\n", 1); } #endif - sched_yield(); + sched_block_current(); } } @@ -1535,6 +1704,8 @@ sched_task_set_exit_status(struct sched_task *task, in if (parent_task != NULL) (void)sched_task_signal_raise(parent_task, SIGCHLD); + if (parent_task != NULL) + sched_wake(parent_task); } const struct sched_credentials * @@ -1995,6 +2166,8 @@ sched_exit_current(void) if (task == NULL) panic("sched_exit_current: no current task"); + (void)sched_sleep_cancel(task); + #ifdef LENIX_DEBUG_EXIT serial_write("[exit] entry pid=", 17); { @@ -2685,7 +2858,15 @@ sched_task_id(const struct sched_task *task) return (task != NULL) ? task->id : 0; } + uint64_t +sched_task_parent_pid(const struct sched_task *task) +{ + return (task != NULL) ? task->parent_pid : 0; + +} + +uint64_t sched_task_pgrp(const struct sched_task *task) { return (task != NULL) ? task->pgrp : 0; blob - 943c3555f1b7ef047fed76c00460d3ed76f483ba blob + 14e2d19d0193143deb01bc709aa969391c47876b --- kernel/sys/syscall.c +++ kernel/sys/syscall.c @@ -1132,19 +1132,16 @@ sys_stdio_portal_handle(void) if (task == NULL) return IPC_PORTAL_INVALID_HANDLE; handle = sched_task_stdio_portal(task); - if (handle != IPC_PORTAL_INVALID_HANDLE) - return handle; - handle = console_service_client_open(task); - if (handle != IPC_PORTAL_INVALID_HANDLE) - sched_task_set_stdio_portal(task, handle); -#ifdef LENIX_DEBUG_EXIT - serial_write("[stdio_portal_handle] task=", - sizeof("[stdio_portal_handle] task=") - 1); - syscall_debug_serial_write_u64(sched_current_task_id()); - serial_write(" handle=", sizeof(" handle=") - 1); - syscall_debug_serial_write_u64(handle); - serial_write("\n", 1); -#endif + /* + * Don't auto-allocate PTYs here. If a task doesn't have a stdio portal, + * it should explicitly call console_open() to get one. Auto-allocating + * PTYs for service daemons causes their mailboxes to receive PTY input, + * which corrupts their IPC message streams (PTY input like "[signal %u]" + * gets interpreted as IPC requests with garbage opcodes). + * + * Tasks without a stdio portal will have their stdout/stderr written + * directly to serial as a fallback. + */ return handle; } @@ -1388,6 +1385,24 @@ sys_read_impl(uint64_t fd, uint64_t buf_addr, uint64_t return syscall_make_result(copied, 0); } + /* Fallback: try to pull characters directly from serial if mailbox is empty. + * NOTE: serial_getc_nonblock() only READS characters without processing. + * serial_poll_rx() handles line discipline processing. */ + /* DISABLED: Only console task should poll serial */ + /* serial_poll_rx(); */ + #if 1 /* Re-enable: getc no longer processes, just reads */ + { + char tmpc; + while (copied < n && serial_getc_nonblock(&tmpc)) { + if (syscall_copy_to_user(buf_addr + copied, &tmpc, 1) != 0) + return syscall_make_result(-SYSCALL_EFAULT, 0); + copied++; + } + if (copied > 0) + return syscall_make_result(copied, 0); + } + #endif + if (mbox == NULL) return syscall_make_result(-SYSCALL_EBADF, 0); deadlock_recv_start(task, 5000); @@ -1480,6 +1495,18 @@ sys_read_impl(uint64_t fd, uint64_t buf_addr, uint64_t struct ipc_vfs_response resp; size_t req_len = n; +#ifdef LENIX_DEBUG + static int read_debug_count = 0; + if (read_debug_count < 10) { + printk("[sys_read] fd="); + printk_dec(fd); + printk(" requested="); + printk_dec(n); + printk("\n"); + read_debug_count++; + } +#endif + syscall_memset(&req, 0, sizeof(req)); syscall_memset(&resp, 0, sizeof(resp)); if (req_len > IPC_FS_INLINE_DATA_MAX) @@ -1505,6 +1532,23 @@ sys_read_impl(uint64_t fd, uint64_t buf_addr, uint64_t to_copy = IPC_FS_INLINE_DATA_MAX; if (reported < to_copy) to_copy = reported; + +#ifdef LENIX_DEBUG + static int read_resp_debug_count = 0; + if (read_resp_debug_count < 10) { + printk("[sys_read] fd="); + printk_dec(fd); + printk(" status="); + printk_dec(resp.body.read.status); + printk(" data_len="); + printk_dec(resp.body.read.data_len); + printk(" to_copy="); + printk_dec(to_copy); + printk("\n"); + read_resp_debug_count++; + } +#endif + if (syscall_copy_to_user(buf_addr, resp.body.read.data, to_copy) != 0) return syscall_make_result(-SYSCALL_EFAULT, 0); return syscall_make_result(to_copy, 0); @@ -2854,6 +2898,8 @@ sys_poll_impl(uint64_t fds_addr, uint64_t nfds, uint64 uint64_t arg5 __attribute__((unused))) { struct pollfd *kfds = NULL; + struct ipc_mailbox **poll_mboxes = NULL; + struct ipc_mailbox_poll_waiter **poll_waiters = NULL; struct sched_task *task = sched_current_task(); struct signal_state *sigstate = sched_task_signal_state(task); size_t count = (size_t)nfds; @@ -2885,6 +2931,12 @@ sys_poll_impl(uint64_t fds_addr, uint64_t nfds, uint64 kmem_free(kfds); return syscall_make_result(-SYSCALL_EFAULT, 0); } + poll_mboxes = kmem_zalloc(count * sizeof(*poll_mboxes)); + poll_waiters = kmem_zalloc(count * sizeof(*poll_waiters)); + if (poll_mboxes == NULL || poll_waiters == NULL) { + error = -SYSCALL_ENOMEM; + goto out; + } } if (sigmask_addr != 0) { uint32_t mask; @@ -2915,20 +2967,26 @@ sys_poll_impl(uint64_t fds_addr, uint64_t nfds, uint64 goto out; } if (count == 0) { - if (timeout <= 0) - goto out; - wait_ticks = sys_poll_timeout_ticks(timeout); - while (true) { + if (timeout < 0) { if (sigstate != NULL && signal_state_pending(sigstate) != 0) { error = -SYSCALL_EINTR; goto out; } - if (sys_poll_deadline_expired(start_ticks, wait_ticks, - true)) - break; - sched_yield(); + sched_block_current(); + } else if (timeout > 0) { + if (sigstate != NULL && + signal_state_pending(sigstate) != 0) { + error = -SYSCALL_EINTR; + goto out; + } + wait_ticks = sys_poll_timeout_ticks(timeout); + if (wait_ticks > 0) + sched_sleep_ticks(wait_ticks); } + if (sigstate != NULL && + signal_state_pending(sigstate) != 0) + error = -SYSCALL_EINTR; goto out; } infinite_wait = (timeout < 0); @@ -2937,8 +2995,44 @@ sys_poll_impl(uint64_t fds_addr, uint64_t nfds, uint64 have_deadline = true; } while (true) { + bool portal_present = false; + ready_total = 0; for (size_t i = 0; i < count; i++) { + struct ipc_mailbox *mbox = NULL; + + if ((kfds[i].events & POLLIN) != 0) { + struct ipc_mailbox *target_mbox = + ipc_portal_target_mailbox( + (ipc_portal_handle_t)kfds[i].fd); + struct sched_task *portal_owner = + ipc_portal_owner((ipc_portal_handle_t)kfds[i].fd); + if (target_mbox != NULL || portal_owner != NULL) { + /* + * Polling a portal FD means checking the caller's + * mailbox for incoming messages. The portal handle + * proves validity; readiness is driven by the per-task + * mailbox, not the portal target mailbox. + */ + mbox = sched_task_mailbox(task); + if (mbox == NULL) { + kfds[i].revents = POLLERR; + ready_total++; + continue; + } + } + } + if (mbox != NULL) { + poll_mboxes[i] = mbox; + portal_present = true; + kfds[i].revents = 0; + if (ipc_mailbox_has_message(mbox)) { + kfds[i].revents |= POLLIN; + ready_total++; + } + continue; + } + rc = sys_poll_check_fd(&kfds[i]); if (rc > 0) { ready_total++; @@ -2952,16 +3046,78 @@ sys_poll_impl(uint64_t fds_addr, uint64_t nfds, uint64 } if (ready_total > 0 || immediate_timeout) break; - if (sigstate != NULL && - signal_state_pending(sigstate) != 0) { - interrupted_by_signal = true; - break; - } - if (!infinite_wait && - sys_poll_deadline_expired(start_ticks, wait_ticks, - have_deadline)) - break; - sched_yield(); + if (sigstate != NULL && + signal_state_pending(sigstate) != 0) { + interrupted_by_signal = true; + break; + } + if (!infinite_wait && + sys_poll_deadline_expired(start_ticks, wait_ticks, + have_deadline)) + break; + + if (portal_present) { + uint64_t remaining = wait_ticks; + + if (have_deadline) { + uint64_t now_ticks = timer_ticks(); + uint64_t elapsed = now_ticks - start_ticks; + if (elapsed >= wait_ticks) + break; + remaining = wait_ticks - elapsed; + } + + for (size_t i = 0; i < count; i++) { + struct ipc_mailbox *mbox = poll_mboxes[i]; + + if (mbox == NULL || ipc_mailbox_has_message(mbox)) + continue; + + if (poll_waiters[i] == NULL) { + struct ipc_mailbox_poll_waiter *waiter = + kmem_alloc(sizeof(*waiter)); + if (waiter == NULL) + continue; + waiter->task = task; + waiter->next = NULL; + waiter->in_list = false; + poll_waiters[i] = waiter; + ipc_mailbox_poll_waiter_add(mbox, waiter); + } + } + + /* Re-check to close race after arming waiters */ + for (size_t i = 0; i < count; i++) { + struct ipc_mailbox *mbox = poll_mboxes[i]; + if (mbox == NULL) + continue; + if (ipc_mailbox_has_message(mbox)) { + kfds[i].revents |= POLLIN; + ready_total++; + } + } + if (ready_total > 0) + break; + + if (have_deadline && remaining == 0) + break; + if (have_deadline && remaining > 0) + sched_sleep_ticks(remaining); + else + sched_block_current(); + + for (size_t i = 0; i < count; i++) { + if (poll_waiters[i] == NULL) + continue; + (void)ipc_mailbox_poll_waiter_remove_task( + poll_mboxes[i], task); + kmem_free(poll_waiters[i]); + poll_waiters[i] = NULL; + } + continue; + } + + sched_yield(); } if (syscall_copy_to_user(fds_addr, kfds, bytes) != 0) { error = -SYSCALL_EFAULT; @@ -2977,6 +3133,19 @@ sys_poll_impl(uint64_t fds_addr, uint64_t nfds, uint64 out: if (kfds != NULL) kmem_free(kfds); + if (poll_waiters != NULL) { + for (size_t i = 0; i < count; i++) { + if (poll_waiters[i] != NULL) { + (void)ipc_mailbox_poll_waiter_remove_task( + (poll_mboxes != NULL) ? poll_mboxes[i] : NULL, + task); + kmem_free(poll_waiters[i]); + } + } + kmem_free(poll_waiters); + } + if (poll_mboxes != NULL) + kmem_free(poll_mboxes); if (mask_swapped && sigstate != NULL) signal_state_update_blocked(sigstate, SIG_SETMASK, saved_mask, NULL); @@ -4106,6 +4275,13 @@ sys_spawn_impl(uint64_t path_addr, uint64_t argv_addr, goto out; } file_size = (uint64_t)vresp.body.stat.info.size; + +#ifdef LENIX_DEBUG + printk("[sys_spawn] file_size="); + printk_dec(file_size); + printk(" checking validity\n"); +#endif + if (file_size == 0 || file_size > (16 * 1024 * 1024)) { #ifdef LENIX_DEBUG printk("[sys_spawn] bad file_size="); @@ -4116,12 +4292,25 @@ sys_spawn_impl(uint64_t path_addr, uint64_t argv_addr, goto out; } +#ifdef LENIX_DEBUG + printk("[sys_spawn] allocating buffer size="); + printk_dec(file_size); + printk("\n"); +#endif + uint8_t *file_buf = kmem_alloc(file_size); if (file_buf == NULL) { +#ifdef LENIX_DEBUG + printk("[sys_spawn] kmem_alloc failed\n"); +#endif rc = -SYSCALL_ENOMEM; goto out; } +#ifdef LENIX_DEBUG + printk("[sys_spawn] buffer allocated, opening file\n"); +#endif + /* Open the file */ syscall_memset(&vreq, 0, sizeof(vreq)); syscall_memset(&vresp, 0, sizeof(vresp)); @@ -4153,6 +4342,10 @@ sys_spawn_impl(uint64_t path_addr, uint64_t argv_addr, uint32_t prefetch_len = 0; /* Valid bytes in prefetch_buf */ uint32_t prefetch_pos = 0; /* Current position in prefetch_buf */ +#ifdef LENIX_DEBUG + int spawn_read_count = 0; +#endif + while (offset < file_size) { /* Refill prefetch buffer if needed */ if (prefetch_pos >= prefetch_len) { @@ -4160,6 +4353,19 @@ sys_spawn_impl(uint64_t path_addr, uint64_t argv_addr, if (to_read > 4096) to_read = 4096; +#ifdef LENIX_DEBUG + if (spawn_read_count < 10) { + printk("[sys_spawn read] offset="); + printk_dec(offset); + printk(" file_size="); + printk_dec(file_size); + printk(" to_read="); + printk_dec(to_read); + printk("\n"); + spawn_read_count++; + } +#endif + syscall_memset(&vreq, 0, sizeof(vreq)); syscall_memset(&vresp, 0, sizeof(vresp)); vreq.opcode = IPC_VFS_REQ_READ; @@ -4179,6 +4385,19 @@ sys_spawn_impl(uint64_t path_addr, uint64_t argv_addr, goto out_close; } prefetch_len = vresp.body.read.data_len; + +#ifdef LENIX_DEBUG + static int spawn_resp_count = 0; + if (spawn_resp_count < 10) { + printk("[sys_spawn read] resp: status="); + printk_dec(vresp.body.read.status); + printk(" data_len="); + printk_dec(vresp.body.read.data_len); + printk("\n"); + spawn_resp_count++; + } +#endif + if (prefetch_len == 0) { /* EOF or short read - stop without spinning */ file_size = offset; @@ -4343,13 +4562,6 @@ sys_waitpid_impl(uint64_t arg0 __attribute__((unused)) if (syscall_copy_to_user(status_ptr, &status, sizeof(status)) != 0) return syscall_make_result(-SYSCALL_EFAULT, 0); } - if (rc > 0) { - ipc_portal_handle_t std_handle = - sched_task_stdio_portal(sched_current_task()); - if (std_handle != IPC_PORTAL_INVALID_HANDLE) - (void)console_pty_rebind_handle(std_handle, - sched_current_task()); - } if (do_log) { printk("[sys_waitpid] rc="); printk_dec((int64_t)rc); @@ -4674,31 +4886,40 @@ sys_service_request_impl(uint64_t portal_handle, uint6 /* Issue request and wait for response */ if (ipc_service_request_issue(&client, req_buf, req_len, resp_buf, resp_len, &actual_resp_len) != 0) { - printk("[sys_service_request] request_issue failed portal=0x"); - { - const char hex[] = "0123456789abcdef"; - char buf[9]; - uint32_t val = (uint32_t)portal; - for (int shift = 28, idx = 0; shift >= 0; shift -= 4, idx++) - buf[idx] = hex[(val >> shift) & 0xf]; - buf[8] = '\0'; - printk(buf); + /* Rate-limit error messages to prevent flooding serial output */ + static uint32_t error_log_count = 0; + static uint64_t last_error_log_ticks = 0; + uint64_t now_ticks = timer_ticks(); + /* Log first error, then at most once per second */ + if (error_log_count == 0 || + (now_ticks - last_error_log_ticks) >= timer_get_hz()) { + printk("[sys_service_request] request_issue failed portal=0x"); + { + const char hex[] = "0123456789abcdef"; + char buf[9]; + uint32_t val = (uint32_t)portal; + for (int shift = 28, idx = 0; shift >= 0; shift -= 4, idx++) + buf[idx] = hex[(val >> shift) & 0xf]; + buf[8] = '\0'; + printk(buf); + } + printk(" req_len="); + printk_dec((uint64_t)req_len); + printk(" resp_len="); + printk_dec((uint64_t)resp_len); + printk(" src_task="); + printk(sched_task_name(sched_current_task())); + if (error_log_count > 0) { + printk(" (rate-limited, count="); + printk_dec((uint64_t)error_log_count); + printk(")"); + } + printk("\n"); + error_log_count++; + last_error_log_ticks = now_ticks; + } else { + error_log_count++; } - printk(" req_len="); - printk_dec((uint64_t)req_len); - printk(" resp_len="); - printk_dec((uint64_t)resp_len); - printk(" src_task=0x"); - { - const char hex[] = "0123456789abcdef"; - char buf[17]; - uint64_t val = (uint64_t)sched_current_task(); - for (int shift = 60, idx = 0; shift >= 0 && idx < 16; shift -= 4) - buf[idx++] = hex[(val >> shift) & 0xf]; - buf[16] = '\0'; - printk(buf); - } - printk("\n"); if (req_alloc) kmem_free(req_buf); if (resp_alloc) @@ -5402,7 +5623,19 @@ sys_blocksvc_request_impl(uint64_t device, uint64_t lb uint32_t max_blocks; uint32_t copy_len; struct syscall_result result; + static uint32_t dbg_blocksvc_req_log = 0; + if (dbg_blocksvc_req_log < 5) { + printk("[sys_blocksvc_request] dev="); + printk_dec(device); + printk(" lba="); + printk_dec(lba); + printk(" blocks="); + printk_dec(blocks); + printk("\n"); + dbg_blocksvc_req_log++; + } + if (buf_addr == 0) return syscall_make_result(-SYSCALL_EINVAL, 0); if (blocks == 0) @@ -5474,6 +5707,15 @@ sys_blocksvc_request_impl(uint64_t device, uint64_t lb return syscall_make_result(-SYSCALL_EFAULT, 0); } } + if (resp->bytes_transferred != copy_len) { + printk("[blocksvc] WARN: bytes_transferred="); + printk_dec((uint64_t)resp->bytes_transferred); + printk(" expected="); + printk_dec((uint64_t)copy_len); + printk(" status="); + printk_dec((uint64_t)(resp->status < 0 ? -resp->status : resp->status)); + printk("\n"); + } result = syscall_make_result(resp->bytes_transferred, 0); kmem_free(req); kmem_free(resp); @@ -5521,8 +5763,9 @@ sys_console_open_impl(uint64_t arg0 __attribute__((unu uint64_t arg4 __attribute__((unused)), uint64_t arg5 __attribute__((unused))) { + struct sched_task *task = sched_current_task(); ipc_portal_handle_t handle = - console_service_client_open(sched_current_task()); + console_service_client_open(task); #if defined(DEBUG_ALL) DEBUG_SYSCALL_LOG("[syscall] console_open task="); DEBUG_SYSCALL_LOG(sched_current_task_name()); @@ -5542,6 +5785,13 @@ sys_console_open_impl(uint64_t arg0 __attribute__((unu #endif if (handle == IPC_PORTAL_INVALID_HANDLE) return syscall_make_result(-SYSCALL_EBUSY, 0); + /* + * Store the console portal as the task's stdio portal so it can be + * inherited by child processes via posix_spawn/fork. Without this, + * the PTY rebind during spawn will not happen and children won't + * receive keyboard input. + */ + sched_task_set_stdio_portal(task, handle); return syscall_make_result(handle, 0); } @@ -5623,20 +5873,31 @@ sys_pty_alloc_impl(uint64_t desc_addr, uint64_t arg1 _ struct console_pty_alloc_desc desc; uint32_t pty_id; ipc_portal_handle_t handle; + int rc; if (desc_addr == 0) return syscall_make_result(-SYSCALL_EINVAL, 0); - if (console_pty_alloc(sched_current_task(), &pty_id, &handle) != 0) { - printk("[pty] sys_pty_alloc: console_pty_alloc failed\n"); - return syscall_make_result(-SYSCALL_ENOMEM, 0); + rc = console_pty_alloc(sched_current_task(), &pty_id, &handle); + if (rc != 0) { + printk("[pty] sys_pty_alloc: console_pty_alloc failed rc="); + printk_dec((uint64_t)rc); + printk("\n"); + /* Propagate real error code when available */ + if (rc > 0) + rc = -SYSCALL_EIO; + return syscall_make_result((uint64_t)rc, 0); } desc.pty_id = pty_id; desc.reserved = 0; desc.handle = handle; if (syscall_copy_to_user(desc_addr, &desc, sizeof(desc)) != 0) { console_pty_free(pty_id, sched_current_task()); + printk("[pty] sys_pty_alloc: copy_to_user failed\n"); return syscall_make_result(-SYSCALL_EFAULT, 0); } + printk("[pty] sys_pty_alloc: returning 0 (pty_id="); + printk_dec((uint64_t)pty_id); + printk(")\n"); return syscall_make_result(0, 0); } @@ -5660,9 +5921,22 @@ sys_pty_activate_impl(uint64_t pty_id, uint64_t arg1 _ uint64_t arg5 __attribute__((unused))) { struct sched_task *requester = sched_current_task(); + int rc; - if (console_pty_set_active((uint32_t)pty_id, requester) != 0) - return syscall_make_result(-SYSCALL_EPERM, 0); + printk("[sys_pty_activate] entry pty_id="); + printk_dec((uint64_t)pty_id); + printk(" requester="); + printk(sched_task_name(requester)); + printk("\n"); + + rc = console_pty_set_active((uint32_t)pty_id, requester); + if (rc != 0) { + printk("[sys_pty_activate] failed rc="); + printk_dec((uint64_t)(uint32_t)rc); + printk("\n"); + return syscall_make_result(rc, 0); + } + printk("[sys_pty_activate] success\n"); return syscall_make_result(0, 0); } @@ -8020,7 +8294,6 @@ sys_nanosleep_impl(uint64_t req_addr, uint64_t rem_add struct timespec req; uint64_t hz = timer_get_hz(); uint64_t ticks; - uint64_t start; if (req_addr == 0) return syscall_make_result(-SYSCALL_EINVAL, 0); @@ -8038,9 +8311,8 @@ sys_nanosleep_impl(uint64_t req_addr, uint64_t rem_add if (ticks == 0 && (req.tv_sec > 0 || req.tv_nsec > 0)) ticks = 1; - start = timer_ticks(); - while ((timer_ticks() - start) < ticks) - sched_yield(); + if (ticks > 0) + sched_sleep_ticks(ticks); if (rem_addr != 0) { struct timespec zero = { 0, 0 }; blob - f66a1c51bd3c85d97b594ba61a2769d5e365e88e blob + 32e328ce11e5916d91da513d27897ebb8eb498ba --- kernel/time/time.c +++ kernel/time/time.c @@ -114,7 +114,11 @@ timer_seed_wallclock(uint64_t epoch_ns) void timer_handle_tick(void) { - serial_poll_rx(); + /* NOTE: Removed serial_poll_rx() call - it's not safe to call from + * interrupt context as it can trigger complex scheduler wake operations + * (console_wake_service_task -> sched_wake) which can corrupt state + * when combined with sched_tick()'s sched_wake_sleepers(). + * Serial polling happens from console task instead. */ timer_tick_count++; sched_clock_tick(timer_tick_count); sched_tick(); blob - /dev/null blob + 1761152b588670dc718f5526553994db3140167c (mode 755) --- /dev/null +++ rebuild-smp.sh @@ -0,0 +1,15 @@ +#!/bin/sh +export TOOLCHAIN_ROOT=/opt/llvm-mercuron +export MERCURON_SYSROOT=$PWD/third-party/build/sysroot +export HOST_TRIPLE=x86_64-unknown-mercuron +export KERNEL_TRIPLE=x86_64-unknown-lenix + +make clean +make ARCH=x86_64 USE_MERCURON_TOOLCHAIN=1 MERCURON_SYSROOT=$MERCURON_SYSROOT DEBUG_SMP=1 -j4 +make ARCH=x86_64 USE_MERCURON_TOOLCHAIN=1 MERCURON_SYSROOT=$MERCURON_SYSROOT package-runtime +make ARCH=x86_64 USE_MERCURON_TOOLCHAIN=1 MERCURON_SYSROOT=$MERCURON_SYSROOT package-apps +make ARCH=x86_64 USE_MERCURON_TOOLCHAIN=1 MERCURON_SYSROOT=$MERCURON_SYSROOT initrd +make ARCH=x86_64 USE_MERCURON_TOOLCHAIN=1 MERCURON_SYSROOT=$MERCURON_SYSROOT efi +make ARCH=x86_64 USE_MERCURON_TOOLCHAIN=1 MERCURON_SYSROOT=$MERCURON_SYSROOT iso + + blob - b52d797730313aeb3a8a9f81be2cc0b17c57f5f1 blob + 1fffd1edd717e81d6da1bdf42984d615dea368dc --- servers/block/blockd/main.c +++ servers/block/blockd/main.c @@ -48,6 +48,16 @@ static struct ipc_block_service_response blockd_resp; static bool blockd_staged; static volatile int blockd_terminate; +#ifndef BLOCKD_DEBUG +#define BLOCKD_DEBUG 0 /* Default quiet; set to 1 for verbose tracing */ +#endif + +#if BLOCKD_DEBUG +#define BLOCKD_TRACE(...) printf(__VA_ARGS__) +#else +#define BLOCKD_TRACE(...) do { } while (0) +#endif + static void blockd_handle_sigterm(int sig __attribute__((unused))) { @@ -77,7 +87,6 @@ static bool blockd_backend_queue_push(struct blockd_ba static bool blockd_backend_queue_pop(struct blockd_backend_device *slot, struct ipc_block_service_request *req_out); static void blockd_backend_promote_queued(struct blockd_backend_device *slot); -static void blockd_register_with_namesvc(portal_handle_t bootstrap); static void blockd_check_device_timeouts(void); static uint64_t blockd_now_ms(void); @@ -94,8 +103,9 @@ blockd_now_ms(void) static void blockd_log(const char *msg) { - /* Temporarily silence verbose blockd logs to keep boot output readable. */ - (void)msg; + if (!BLOCKD_DEBUG || msg == NULL) + return; + puts(msg); } static void @@ -109,6 +119,8 @@ static void blockd_log_hex64(const char *prefix, uint64_t value) { #ifdef LENIX_DEBUG + if (!BLOCKD_DEBUG) + return; const char hex[] = "0123456789abcdef"; char buf[64]; size_t idx = 0; @@ -133,6 +145,8 @@ static void blockd_log_device(const struct ipc_block_info *info) { #ifdef LENIX_DEBUG + if (!BLOCKD_DEBUG) + return; char buf[96]; const char prefix[] = "[blockd] device "; size_t idx = 0; @@ -249,6 +263,10 @@ blockd_backend_queue_pop(struct blockd_backend_device *req_out = slot->queue[slot->queue_head]; slot->queue_head = (slot->queue_head + 1U) % BLOCKD_BACKEND_QUEUE_DEPTH; slot->queue_len--; + BLOCKD_TRACE("[blockd] queue pop dev=%u token=%u lba=%llu blocks=%u len=%zu\n", + req_out->device, req_out->token, + (unsigned long long)req_out->lba, + req_out->blocks, slot->queue_len); return true; } @@ -271,21 +289,23 @@ blockd_backend_queue_request(struct blockd_backend_dev slot->pending_req = *req; slot->request_pending = true; #ifdef LENIX_DEBUG - blockd_log_int("[blockd] dispatch request token=", - (int)req->token); + BLOCKD_TRACE("[blockd] queue dispatch dev=%u token=%u lba=%llu blocks=%u flags=0x%x\n", + req->device, req->token, (unsigned long long)req->lba, + req->blocks, req->flags); #endif return true; } if (blockd_backend_queue_push(slot, req)) { #ifdef LENIX_DEBUG - blockd_log_int("[blockd] enqueue request token=", - (int)req->token); + BLOCKD_TRACE("[blockd] queue enqueue dev=%u token=%u lba=%llu blocks=%u flags=0x%x len=%zu\n", + req->device, req->token, (unsigned long long)req->lba, + req->blocks, req->flags, slot->queue_len); #endif return true; } #ifdef LENIX_DEBUG - blockd_log_int("[blockd] queue full token=", - (int)req->token); + BLOCKD_TRACE("[blockd] queue full dev=%u token=%u\n", + req->device, req->token); #endif return false; } @@ -295,6 +315,7 @@ blockd_backend_handle_register(const struct ipc_block_ { struct ipc_block_backend_register_response resp; struct blockd_backend_device *slot; + static int register_log_count = 0; if (req == NULL) return; @@ -323,8 +344,17 @@ blockd_backend_handle_register(const struct ipc_block_ .block_count = slot->block_count }; blockd_log_device(&info); + BLOCKD_TRACE("[blockd] backend register ok dev=%u block_size=%u blocks=%llu\n", + slot->device_id, slot->block_size, + (unsigned long long)slot->block_count); resp.device_id = slot->device_id; resp.status = IPC_BLOCK_BACKEND_STATUS_OK; + if (register_log_count < 4) { + printf("[blockd] backend registered dev=%u block_size=%u blocks=%llu\n", + slot->device_id, slot->block_size, + (unsigned long long)slot->block_count); + register_log_count++; + } } if (blockd_backend_portal != IPC_PORTAL_INVALID_HANDLE) ipc_service_respond(blockd_backend_portal, resp.token, @@ -375,9 +405,10 @@ blockd_backend_handle_query(const struct ipc_block_bac resp.info.block_count = slot->block_count; resp.status = IPC_BLOCK_BACKEND_STATUS_OK; } - if (blockd_backend_portal != IPC_PORTAL_INVALID_HANDLE) + if (blockd_backend_portal != IPC_PORTAL_INVALID_HANDLE) { ipc_service_respond(blockd_backend_portal, resp.token, &resp, sizeof(resp)); + } } static void @@ -385,21 +416,31 @@ blockd_backend_handle_io_fetch(const struct ipc_block_ { struct ipc_block_backend_io_request resp; struct blockd_backend_device *slot; + bool responded = false; + static int unknown_dev_log_count = 0; if (req == NULL) return; + slot = blockd_backend_find(req->device_id); + BLOCKD_TRACE("[blockd] backend io_request dev=%u token=%u pending=%s waiting=%s queued=%zu\n", + req->device_id, req->token, + (slot != NULL && slot->request_pending) ? "yes" : "no", + (slot != NULL && slot->waiting_completion) ? "yes" : "no", + (slot != NULL) ? slot->queue_len : 0UL); memset(&resp, 0, sizeof(resp)); resp.opcode = IPC_BLOCK_BACKEND_OPCODE_IO_REQUEST; resp.token = req->token; resp.device_id = req->device_id; resp.status = IPC_BLOCK_BACKEND_STATUS_NOT_FOUND; - slot = blockd_backend_find(req->device_id); if (slot != NULL && !slot->request_pending && !slot->waiting_completion) blockd_backend_promote_queued(slot); if (slot != NULL && slot->request_pending) { const struct ipc_block_service_request *pending = &slot->pending_req; - blockd_log_int("[blockd] backend fetch device=", (int)pending->device); + BLOCKD_TRACE("[blockd] backend fetch dev=%u token=%u lba=%llu blocks=%u flags=0x%x\n", + pending->device, pending->token, + (unsigned long long)pending->lba, + pending->blocks, pending->flags); resp.status = IPC_BLOCK_BACKEND_STATUS_OK; resp.flags = pending->flags; resp.lba = pending->lba; @@ -417,13 +458,24 @@ blockd_backend_handle_io_fetch(const struct ipc_block_ blockd_log_int("[blockd] backend fetch token=", (int)pending->token); #endif + if (blockd_backend_portal != IPC_PORTAL_INVALID_HANDLE) + ipc_service_respond(blockd_backend_portal, resp.token, + &resp, sizeof(resp)); + responded = true; } else if (slot != NULL && slot->waiting_completion) { resp.status = IPC_BLOCK_BACKEND_STATUS_BUSY; } else if (slot != NULL) { /* Device exists but no work is queued; tell backend to back off */ + BLOCKD_TRACE("[blockd] backend fetch idle dev=%u\n", slot->device_id); resp.status = IPC_BLOCK_BACKEND_STATUS_IDLE; + } else { + if (unknown_dev_log_count < 8) { + printf("[blockd] backend fetch unknown device=%u\n", + req->device_id); + unknown_dev_log_count++; + } } - if (blockd_backend_portal != IPC_PORTAL_INVALID_HANDLE) + if (!responded && blockd_backend_portal != IPC_PORTAL_INVALID_HANDLE) ipc_service_respond(blockd_backend_portal, resp.token, &resp, sizeof(resp)); } @@ -442,7 +494,9 @@ blockd_backend_handle_io_response( return; if (!slot->waiting_completion) return; - blockd_log_int("[blockd] backend response token=", (int)resp_pkt->token); + BLOCKD_TRACE("[blockd] backend resp token=%u dev=%u status=%d bytes=%u data_len=%u\n", + resp_pkt->token, resp_pkt->device_id, resp_pkt->status, + resp_pkt->bytes_transferred, resp_pkt->data_len); if (resp_pkt->status != IPC_BLOCK_BACKEND_STATUS_OK) { blockd_log_hex64("[blockd] backend response error status=", (uint64_t)resp_pkt->status); @@ -450,8 +504,17 @@ blockd_backend_handle_io_response( memset(&out, 0, sizeof(out)); out.token = slot->pending_req.token; out.status = resp_pkt->status; - out.bytes_transferred = resp_pkt->bytes_transferred; - out.data_len = 0; + out.bytes_transferred = resp_pkt->bytes_transferred; + out.data_len = 0; + if (out.status == IPC_BLOCK_BACKEND_STATUS_OK) { + uint64_t expect = (uint64_t)slot->pending_req.blocks * 512ULL; + if (out.bytes_transferred != expect) { + BLOCKD_TRACE("[blockd] WARN: short backend resp dev=%u token=%u bytes=%u expect=%llu\n", + slot->device_id, slot->pending_req.token, + out.bytes_transferred, + (unsigned long long)expect); + } + } if ((slot->pending_req.flags & IPC_BLOCK_SERVICE_F_WRITE) == 0 && resp_pkt->data_len > 0) { uint32_t copy = resp_pkt->data_len; @@ -598,11 +661,26 @@ main(int argc, char **argv, char **envp) blockd_log("[blockd] backend service registered"); blockd_backend_portal = bootstrap; } - blockd_register_with_namesvc(bootstrap); + /* Defer namesvc registration - try once but don't block. + * blockd must enter its main loop immediately to process + * block service requests from other daemons (like ext2). */ + static bool namesvc_registered = false; + { + portal_handle_t namesvc = service_resolve("namesvc"); + if (namesvc != IPC_PORTAL_INVALID_HANDLE) { + uint32_t flags = blockd_staged ? IPC_NAMESVC_FLAG_STAGED : 0; + if (namesvc_register(namesvc, "blockd", bootstrap, + IPC_PORTAL_RIGHT_SEND, flags) == 0) { + blockd_log("[blockd] registered with namesvc"); + namesvc_registered = true; + } + } + } blockd_log("[blockd] service online"); static uint8_t portal_buf[BLOCKD_PORTAL_BUF_MAX]; static uint64_t last_diag_ms = 0; + static uint64_t last_namesvc_attempt_ms = 0; while (1) { if (blockd_terminate) { @@ -610,43 +688,107 @@ main(int argc, char **argv, char **envp) return 0; } + /* + * Block on both the client/service portal (bootstrap) and the + * backend portal so responses from ramdiskd/virtio-blk cannot be + * starved by a blocking recv on the other endpoint. + */ + struct pollfd pfds[2]; + nfds_t nfds = 0; + + if (bootstrap != IPC_PORTAL_INVALID_HANDLE) { + pfds[nfds].fd = (int)bootstrap; + pfds[nfds].events = POLLIN; + pfds[nfds].revents = 0; + nfds++; + } + if (blockd_backend_portal != IPC_PORTAL_INVALID_HANDLE && + blockd_backend_portal != bootstrap) { + pfds[nfds].fd = (int)blockd_backend_portal; + pfds[nfds].events = POLLIN; + pfds[nfds].revents = 0; + nfds++; + } + + if (nfds == 0) { + blockd_check_device_timeouts(); + poll(NULL, 0, 1); + continue; + } + + int ready = poll(pfds, nfds, 100); + if (ready <= 0) { + blockd_check_device_timeouts(); + continue; + } + + for (nfds_t i = 0; i < nfds; i++) { + if ((pfds[i].revents & POLLIN) == 0) + continue; + + ssize_t n = portal_recv(portal_buf, sizeof(portal_buf)); + if (n <= 0) + continue; + if ((size_t)n > sizeof(portal_buf)) { + blockd_log("[blockd] portal_recv overflow; dropping message"); + continue; + } + if ((size_t)n != sizeof(blockd_req)) { + blockd_handle_backend_message(portal_buf, (size_t)n); + continue; + } + memcpy(&blockd_req, portal_buf, sizeof(blockd_req)); + struct blockd_backend_device *backend = blockd_backend_find(blockd_req.device); + BLOCKD_TRACE("[blockd] recv token=%u dev=%u lba=%llu blocks=%u flags=0x%x pending=%s waiting=%s\n", + blockd_req.token, blockd_req.device, + (unsigned long long)blockd_req.lba, + blockd_req.blocks, blockd_req.flags, + (backend != NULL && backend->request_pending) ? "yes" : "no", + (backend != NULL && backend->waiting_completion) ? "yes" : "no"); + if (backend != NULL) { + if (!blockd_backend_queue_request(backend, &blockd_req)) { + BLOCKD_TRACE("[blockd] queue_request rejected dev=%u token=%u pending=%s waiting=%s\n", + backend->device_id, blockd_req.token, + backend->request_pending ? "yes" : "no", + backend->waiting_completion ? "yes" : "no"); + memset(&blockd_resp, 0, sizeof(blockd_resp)); + blockd_resp.token = blockd_req.token; + blockd_resp.status = -16; /* EBUSY */ + blockd_resp.bytes_transferred = 0; + blockd_resp.data_len = 0; + block_service_respond(&blockd_resp); + } + continue; + } + BLOCKD_TRACE("[blockd] no backend for dev=%u, responding ENXIO\n", + blockd_req.device); + memset(&blockd_resp, 0, sizeof(blockd_resp)); + blockd_resp.token = blockd_req.token; + blockd_resp.status = -6; /* ENXIO */ + blockd_resp.bytes_transferred = 0; + blockd_resp.data_len = 0; + block_service_respond(&blockd_resp); + } + /* Periodic diagnostic: check for stuck devices */ uint64_t now = blockd_now_ms(); - if (now - last_diag_ms > 5000) { - blockd_check_device_timeouts(); + + /* Retry namesvc registration periodically if it failed initially */ + if (!namesvc_registered && (now - last_namesvc_attempt_ms > 100)) { + last_namesvc_attempt_ms = now; + portal_handle_t namesvc = service_resolve("namesvc"); + if (namesvc != IPC_PORTAL_INVALID_HANDLE) { + uint32_t flags = blockd_staged ? IPC_NAMESVC_FLAG_STAGED : 0; + if (namesvc_register(namesvc, "blockd", bootstrap, + IPC_PORTAL_RIGHT_SEND, flags) == 0) { + blockd_log("[blockd] registered with namesvc (deferred)"); + namesvc_registered = true; + } + } + } + blockd_check_device_timeouts(); + if (now - last_diag_ms > 5000) last_diag_ms = now; - } - - ssize_t n = portal_recv(portal_buf, sizeof(portal_buf)); - if (n <= 0) - continue; - if ((size_t)n > sizeof(portal_buf)) { - blockd_log("[blockd] portal_recv overflow; dropping message"); - continue; - } - if ((size_t)n != sizeof(blockd_req)) { - blockd_handle_backend_message(portal_buf, (size_t)n); - continue; - } - memcpy(&blockd_req, portal_buf, sizeof(blockd_req)); - struct blockd_backend_device *backend = blockd_backend_find(blockd_req.device); - if (backend != NULL) { - if (!blockd_backend_queue_request(backend, &blockd_req)) { - memset(&blockd_resp, 0, sizeof(blockd_resp)); - blockd_resp.token = blockd_req.token; - blockd_resp.status = -16; /* EBUSY */ - blockd_resp.bytes_transferred = 0; - blockd_resp.data_len = 0; - block_service_respond(&blockd_resp); - } - continue; - } - memset(&blockd_resp, 0, sizeof(blockd_resp)); - blockd_resp.token = blockd_req.token; - blockd_resp.status = -6; /* ENXIO */ - blockd_resp.bytes_transferred = 0; - blockd_resp.data_len = 0; - block_service_respond(&blockd_resp); } } @@ -663,7 +805,7 @@ blockd_check_device_timeouts(void) uint64_t wait_ms = now - slot->waiting_since_ms; if (wait_ms > BLOCKD_BACKEND_TIMEOUT_MS) { /* Backend timed out - clear stuck state and fail the request */ - printf("[blockd] TIMEOUT dev=%u waited=%llu ms, clearing stuck state\n", + BLOCKD_TRACE("[blockd] TIMEOUT dev=%u waited=%llu ms, clearing stuck state\n", slot->device_id, (unsigned long long)wait_ms); struct ipc_block_service_response out; @@ -679,37 +821,9 @@ blockd_check_device_timeouts(void) blockd_backend_promote_queued(slot); } else if (wait_ms > 2000) { /* Log warning if waiting more than 2s */ - printf("[blockd] WAITING dev=%u for %llu ms token=%u\n", + BLOCKD_TRACE("[blockd] WAITING dev=%u for %llu ms token=%u\n", slot->device_id, (unsigned long long)wait_ms, slot->pending_req.token); } } } - -static void -blockd_register_with_namesvc(portal_handle_t bootstrap) -{ - const int max_attempts = 1000; - bool ns_wait_logged = false; - for (int attempt = 0; attempt < max_attempts; attempt++) { - portal_handle_t namesvc = service_resolve("namesvc"); - - if (namesvc != IPC_PORTAL_INVALID_HANDLE) { - uint32_t flags = blockd_staged ? IPC_NAMESVC_FLAG_STAGED : 0; - int rc = namesvc_register(namesvc, "blockd", bootstrap, - IPC_PORTAL_RIGHT_SEND, flags); - if (rc == 0) { - blockd_log("[blockd] registered with namesvc"); - return; - } - /* Registration failed; retry */ - } - /* Only log once after 100 iterations if still waiting */ - if (attempt == 100 && !ns_wait_logged) { - blockd_log("[blockd] namesvc registration pending..."); - ns_wait_logged = true; - } - poll(NULL, 0, 1); - } - blockd_log("[blockd] WARN: namesvc registration timed out"); -} blob - d1c4d5e4aeee461471f0ef637db351c94dc009f7 blob + dd1a43a66b91b17e300b153ed564aeaae063c7c8 --- servers/block/ramdiskd/main.c +++ servers/block/ramdiskd/main.c @@ -17,6 +17,18 @@ #include #include +#ifndef RAMDISKD_DEBUG +#define RAMDISKD_DEBUG 0 +#endif + +#if RAMDISKD_DEBUG +#define RAMDISKD_TRACE(...) printf(__VA_ARGS__) +#define RAMDISKD_DEBUG_ENABLED 1 +#else +#define RAMDISKD_TRACE(...) do { } while (0) +#define RAMDISKD_DEBUG_ENABLED 0 +#endif + #define RAMDISK_BLOCK_SIZE 512U #define RAMDISK_PAGE_SIZE 4096U #define RAMDISK_MAX_BYTES (64U * 1024U * 1024U) @@ -160,12 +172,12 @@ ramdisk_map_rootfs(void) } DLOG("[ramdiskd] rootfs_info succeeded"); - #ifdef LENIX_DEBUG +#if defined(LENIX_DEBUG) && RAMDISKD_DEBUG_ENABLED log_line("[ramdiskd] initrd handoff validated successfully"); log_hex64("[ramdiskd] phys_base ", info.phys_base); log_hex64("[ramdiskd] phys_length ", info.length); log_hex64("[ramdiskd] rootfs_alias @ ", (uint64_t)(uintptr_t)rootfs_alias); - #endif +#endif uint64_t phys_base = info.phys_base & ~(uint64_t)(RAMDISK_PAGE_SIZE - 1ULL); uint64_t offset = info.phys_base - phys_base; @@ -175,11 +187,11 @@ ramdisk_map_rootfs(void) map_len = (map_len + (RAMDISK_PAGE_SIZE - 1ULL)) & ~(uint64_t)(RAMDISK_PAGE_SIZE - 1ULL); - #ifdef LENIX_DEBUG +#if defined(LENIX_DEBUG) && RAMDISKD_DEBUG_ENABLED log_hex64("[ramdiskd] page-aligned phys_base ", phys_base); log_hex64("[ramdiskd] map_len (bytes) ", map_len); log_hex64("[ramdiskd] alias offset ", offset); - #endif +#endif DLOG("[ramdiskd] about to call hw_mmio_map..."); if (hw_mmio_map((uint64_t)(uintptr_t)rootfs_alias, phys_base, map_len, HWIO_MAP_READ | HWIO_MAP_WRITE) != 0) { @@ -191,9 +203,9 @@ ramdisk_map_rootfs(void) return -1; } DLOG("[ramdiskd] hw_mmio_map succeeded"); - #ifdef LENIX_DEBUG +#if defined(LENIX_DEBUG) && RAMDISKD_DEBUG_ENABLED log_line("[ramdiskd] initrd mapped successfully"); - #endif +#endif ramdisk_alias_offset = offset; ramdisk_length = info.length; @@ -203,7 +215,7 @@ ramdisk_map_rootfs(void) ramdisk_block_count = (uint32_t)((ramdisk_length + RAMDISK_BLOCK_SIZE - 1ULL) / RAMDISK_BLOCK_SIZE); DLOG("[ramdiskd] ramdisk_block_count = "); - #ifdef LENIX_DEBUG +#if defined(LENIX_DEBUG) && RAMDISKD_DEBUG_ENABLED log_dec64(NULL, ramdisk_block_count); const uint8_t *sample = rootfs_alias + ramdisk_alias_offset + 0x438; uint16_t sample_magic = 0; @@ -215,30 +227,30 @@ ramdisk_map_rootfs(void) return 0; } -#ifdef LENIX_DEBUG -static void -log_hex32(const char *prefix, uint32_t value) -{ - char buf[64]; - const char hex[] = "0123456789abcdef"; - size_t idx = 0; +// #ifdef LENIX_DEBUG +// static void +// log_hex32(const char *prefix, uint32_t value) +// { +// char buf[64]; +// const char hex[] = "0123456789abcdef"; +// size_t idx = 0; - if (prefix != NULL) { - for (size_t p = 0; prefix[p] != '\0' && - idx < sizeof(buf) - 1; p++) - buf[idx++] = prefix[p]; - } - if (idx < sizeof(buf) - 1) - buf[idx++] = '0'; - if (idx < sizeof(buf) - 1) - buf[idx++] = 'x'; - for (int shift = 28; shift >= 0 && idx < sizeof(buf) - 1; - shift -= 4) - buf[idx++] = hex[(value >> shift) & 0xF]; - buf[idx] = '\0'; - puts(buf); -} -#endif +// if (prefix != NULL) { +// for (size_t p = 0; prefix[p] != '\0' && +// idx < sizeof(buf) - 1; p++) +// buf[idx++] = prefix[p]; +// } +// if (idx < sizeof(buf) - 1) +// buf[idx++] = '0'; +// if (idx < sizeof(buf) - 1) +// buf[idx++] = 'x'; +// for (int shift = 28; shift >= 0 && idx < sizeof(buf) - 1; +// shift -= 4) +// buf[idx++] = hex[(value >> shift) & 0xF]; +// buf[idx] = '\0'; +// puts(buf); +// } +// #endif static void ramdisk_handle_request(const struct ipc_block_backend_io_request *req, @@ -307,6 +319,14 @@ ramdisk_handle_request(const struct ipc_block_backend_ resp->bytes_transferred = read_bytes; ramdisk_stats.read_bytes += read_bytes; } + if (resp->status == IPC_BLOCK_BACKEND_STATUS_OK && + resp->bytes_transferred != bytes) { + log_hex64("[ramdiskd] WARN short io bytes=", resp->bytes_transferred); + log_hex64("[ramdiskd] expected bytes=", bytes); + log_hex64("[ramdiskd] device ", req->device_id); + log_hex64("[ramdiskd] lba ", req->lba); + log_hex64("[ramdiskd] blocks ", req->blocks); + } ramdisk_stats.requests_completed++; } @@ -388,29 +408,29 @@ main(void) } } - #ifdef LENIX_DEBUG +#if defined(LENIX_DEBUG) && RAMDISKD_DEBUG_ENABLED log_line("[ramdiskd] initializing service client..."); - #endif +#endif if (ipc_service_client_init(&client, portal) != 0) { DLOG("[ramdiskd] FATAL: ipc_service_client_init failed"); log_line("[ramdiskd] client init failed"); return -1; } DLOG("[ramdiskd] ipc_service_client_init succeeded"); - #ifdef LENIX_DEBUG +#if defined(LENIX_DEBUG) && RAMDISKD_DEBUG_ENABLED log_line("[ramdiskd] client initialized"); log_line("[ramdiskd] mapping rootfs..."); - #endif +#endif if (ramdisk_map_rootfs() != 0) { DLOG("[ramdiskd] WARNING: rootfs mapping failed - yielding backend slot"); log_line("[ramdiskd] WARNING: ramdisk_map_rootfs failed; backend not registered"); disable_backend = true; } else { DLOG("[ramdiskd] loader-provided rootfs mapped successfully"); - #ifdef LENIX_DEBUG - log_line("[ramdiskd] loader-provided rootfs mapped successfully"); - #endif +#if defined(LENIX_DEBUG) && RAMDISKD_DEBUG_ENABLED + log_line("[ramdiskd] loader-provided rootfs mapped successfully"); +#endif } /* Register with blockd */ @@ -419,9 +439,9 @@ main(void) return 0; } - #ifdef LENIX_DEBUG +#if defined(LENIX_DEBUG) && RAMDISKD_DEBUG_ENABLED log_line("[ramdiskd] registering backend device..."); - #endif +#endif DLOG("[ramdiskd] sending REGISTER request..."); reg_req.opcode = IPC_BLOCK_BACKEND_OPCODE_REGISTER; reg_req.block_size = RAMDISK_BLOCK_SIZE; @@ -469,11 +489,11 @@ main(void) device_id = reg_resp.device_id; DLOG("[ramdiskd] SUCCESS: registered as device_id = "); - #ifdef LENIX_DEBUG +#if defined(LENIX_DEBUG) && RAMDISKD_DEBUG_ENABLED log_dec64(NULL, device_id); log_line("[ramdiskd] registered backend device"); log_hex32("[ramdiskd] device_id=", (uint32_t)device_id); - #endif +#endif memset(&fetch, 0, sizeof(fetch)); memset(&work, 0, sizeof(work)); @@ -486,9 +506,9 @@ main(void) /* MAIN SERVICE LOOP */ DLOG("[ramdiskd] entering main service loop - ready for I/O"); - #ifdef LENIX_DEBUG +#if defined(LENIX_DEBUG) && RAMDISKD_DEBUG_ENABLED log_line("[ramdiskd] backend ready for I/O"); - #endif +#endif uint32_t busy_counter = 0; /* Track consecutive BUSY responses */ uint64_t busy_start_ms = 0; /* Timestamp when BUSY streak started */ @@ -505,28 +525,48 @@ main(void) if (fetch.token == 0) fetch.token = 1; - if (ipc_service_request_issue(&client, &fetch, sizeof(fetch), - &work, sizeof(work)) != 0) { - DLOG("[ramdiskd] ipc_service_request_issue failed - retrying"); - poll(NULL, 0, 1); + RAMDISKD_TRACE("[ramdiskd] fetch->blockd token=%u dev=%u lba=%llu blocks=%u\n", + fetch.token, fetch.device_id, + (unsigned long long)fetch.lba, fetch.blocks); + + /* Fetch work from blockd with timeout. If this blocks for too long, + * it could indicate a deadlock (blockd waiting for ramdiskd response + * while ramdiskd is waiting for blockd fetch response). */ + int fetch_rc = ipc_service_request_issue(&client, &fetch, sizeof(fetch), + &work, sizeof(work)); + if (fetch_rc != 0) { + /* Log fetch failures to detect deadlocks */ + static uint32_t fetch_error_count = 0; + fetch_error_count++; + if (fetch_error_count <= 5 || (fetch_error_count % 100) == 0) { + log_line("[ramdiskd] WARN: fetch ipc error (timeout or deadlock?)"); + } + /* On fetch failure, sleep briefly and retry to avoid tight loop */ + poll(NULL, 0, 10); /* Sleep 10ms before retry */ continue; } + RAMDISKD_TRACE("[ramdiskd] fetch status=%d dev=%u lba=%llu blocks=%u token=%u\n", + work.status, work.device_id, + (unsigned long long)work.lba, work.blocks, + work.token); - if (work.status != IPC_BLOCK_BACKEND_STATUS_OK) { - if (work.status == IPC_BLOCK_BACKEND_STATUS_IDLE) { - /* - * IDLE = no work pending at all. - * Back off moderately since there's nothing to do. - * Reset BUSY timeout since this is normal idle state. - * Use 10ms (not 100ms) to stay responsive during boot. - */ - busy_counter = 0; - busy_start_ms = 0; - busy_timeout_logged = false; - poll(NULL, 0, 10); /* 10ms backoff when idle */ - } else if (work.status == IPC_BLOCK_BACKEND_STATUS_BUSY) { - /* - * BUSY = blockd is waiting for completion of prior request. + if (work.status != IPC_BLOCK_BACKEND_STATUS_OK) { + if (work.status == IPC_BLOCK_BACKEND_STATUS_IDLE) { + /* + * IDLE = no work pending at all. + * Sleep for 10ms to reduce CPU contention and allow console task + * to poll serial input frequently. This still maintains reasonable + * latency for block requests while giving other tasks CPU time. + */ + busy_counter = 0; + busy_start_ms = 0; + busy_timeout_logged = false; + poll(NULL, 0, 10); /* Sleep 10ms to reduce CPU contention */ + idle_poll_count++; + continue; + } else if (work.status == IPC_BLOCK_BACKEND_STATUS_BUSY) { + /* + * BUSY = blockd is waiting for completion of prior request. * Use adaptive back-off: * - Tier 1 (first 100): 1ms sleep * - Tier 2 (100-1000): 5ms sleep @@ -552,34 +592,40 @@ main(void) } /* Adaptive sleep based on busy counter */ - if (busy_counter < RAMDISK_BUSY_TIER1_THRESHOLD) { - poll(NULL, 0, 1); - } else if (busy_counter < RAMDISK_BUSY_TIER2_THRESHOLD) { - ramdisk_stats.backoff_steps++; - poll(NULL, 0, 5); - } else { - ramdisk_stats.backoff_steps++; - poll(NULL, 0, 10); - } + int sleep_ms = 1; + if (busy_counter > RAMDISK_BUSY_TIER2_THRESHOLD) + sleep_ms = 10; + else if (busy_counter > RAMDISK_BUSY_TIER1_THRESHOLD) + sleep_ms = 5; + poll(NULL, 0, sleep_ms); + continue; } else if (work.status == IPC_BLOCK_BACKEND_STATUS_NOT_FOUND) { - /* Real error - device was deregistered */ - log_line("[ramdiskd] ERROR: blockd reports device not found"); - break; + /* Device not found - could be a transient error or device was deregistered. + * Instead of exiting immediately, log and retry after a delay. + * This handles race conditions during device registration/deregistration. */ + static uint32_t not_found_count = 0; + not_found_count++; + if (not_found_count <= 5 || (not_found_count % 100) == 0) { + log_line("[ramdiskd] WARN: blockd reports device not found (will retry)"); + } + /* Retry after a short delay - device might be re-registering */ + poll(NULL, 0, 10); /* Sleep 10ms before retry */ + continue; } else { - /* Other error status - log and throttle repeated messages */ - if ((idle_poll_count - last_error_log_time) > 1000000) { - log_line("[ramdiskd] WARN: blockd I/O fetch error, will retry"); - last_error_log_time = idle_poll_count; + /* Other error status - log and throttle repeated messages */ + if ((idle_poll_count - last_error_log_time) > 1000000) { + log_line("[ramdiskd] WARN: blockd I/O fetch error, will retry"); + last_error_log_time = idle_poll_count; + } + poll(NULL, 0, 1); /* Sleep 1ms on unknown errors */ } - poll(NULL, 0, 1); + idle_poll_count++; + continue; } - idle_poll_count++; - continue; - } - /* Reset counters when we get actual work */ - busy_counter = 0; - busy_start_ms = 0; + /* Reset counters when we get actual work */ + busy_counter = 0; + busy_start_ms = 0; busy_timeout_logged = false; idle_poll_count = 0; @@ -591,9 +637,9 @@ main(void) response.token = work.token ? work.token : fetch.token; ramdisk_handle_request(&work, &response); - /* Send response back to blockd */ - if (ipc_service_request_issue(&client, &response, - sizeof(response), &ack, sizeof(ack)) != 0) { + /* Send response back to blockd via portal_send (not service_request). + * blockd receives backend messages via portal_recv(), not service_request handler. */ + if (portal_send(client.server_portal, &response, sizeof(response)) != 0) { DLOG("[ramdiskd] failed to send response - continuing anyway"); continue; } blob - 0075880ee1c40df4d583455662c3ac7a8a0d0e2c blob + 981e866d81b82e36ca71707f3bdb21b05475a21e --- servers/console/ptyctl/main.c +++ servers/console/ptyctl/main.c @@ -349,14 +349,20 @@ main(int argc, char **argv, char **envp) (void)envp; bootstrap = portal_get_bootstrap(); - if (bootstrap == 0) { - puts("[ptyctl] bootstrap handle invalid"); - return 1; - } - if (console_ttyctl_register((portal_handle_t)bootstrap) != 0) { - puts("[ptyctl] console_ttyctl_register failed"); + if (bootstrap == 0) { + puts("[ptyctl] bootstrap handle invalid"); return 1; } + { + int rc = console_ttyctl_register((portal_handle_t)bootstrap); + if (rc < 0) { + printf("[ptyctl] console_ttyctl_register failed rc=%d errno=%d\n", + rc, errno); + return 1; + } + if (rc > 0) + printf("[ptyctl] console_ttyctl_register unexpected rc=%d (continuing)\n", rc); + } if (staged) (void)srv_stage_start(SRV_ID_PTYCTL, 0, &gen); ptyctl_staged = staged; blob - 6d8d00160779966413ae394d1c0fabfbac02a199 blob + 04442e0ecfad76e527d911a61816dc105d3c562b --- servers/console/ttyd/main.c +++ servers/console/ttyd/main.c @@ -2,6 +2,7 @@ #include #include #include +#include #include #include #include @@ -254,7 +255,9 @@ main(void) puts("[ttyd] invalid bootstrap handle"); return 1; } - if (console_tty_register(bootstrap) != 0) { + int reg_rc = console_tty_register(bootstrap); + if (reg_rc != 0 && errno != EBUSY) { + /* EBUSY means kernel already pre-registered us - that's OK */ puts("[ttyd] console_tty_register failed"); return 1; } @@ -262,7 +265,10 @@ main(void) (void)srv_stage_start(SRV_ID_TTYD, 0, &gen); ttyd_staged = staged; #ifdef LENIX_DEBUG - puts("[ttyd] console_tty_register ok"); + if (reg_rc == 0) + puts("[ttyd] console_tty_register ok"); + else + puts("[ttyd] console_tty_register skipped (kernel pre-registered)"); #endif { blob - 1a9d1478349d730bee04745f857a905e9654d1b9 blob + 924031f1060d6c236bf3817eb6f7ba70fce9f0dd --- servers/fs/ext2/main.c +++ servers/fs/ext2/main.c @@ -12,6 +12,7 @@ #include #include #include +#include #include #include @@ -224,6 +225,8 @@ static ssize_t ext2_read_from_inode(const struct ext2_ uint32_t inode_no, uint32_t offset, void *buf, size_t len); static int ext2_read_symlink_target(const struct ext2_inode *inode, uint32_t inode_no, char *out, size_t cap, uint32_t *out_len); +static void ext2_log_request(const struct ipc_fs_request *req); +static void ext2_sig_handler(int sig); static int block_read_sectors(uint64_t lba, uint32_t count, void *buf) { @@ -232,22 +235,38 @@ static int block_read_sectors(uint64_t lba, uint32_t c /* * Batch read multiple sectors per IPC call to reduce overhead. - * Can fit up to 8 sectors (4096B / 512B) per blocksvc call. + * Can fit up to 8 sectors (4096B / 512B) per blocksvc call. If the + * backend returns a short transfer, keep issuing requests until the + * requested range is filled or an error occurs. */ while (remaining > 0) { uint32_t batch_size = remaining; if (batch_size > 8) batch_size = 8; + size_t expected_bytes = (size_t)batch_size * EXT2_SECTOR_SIZE; ssize_t rc = block_service_rw(ext2_device_id, lba, dst, batch_size, 0); - if (rc != (ssize_t)(batch_size * EXT2_SECTOR_SIZE)) { + if (rc < 0) { printf("[ext2] block_read_sectors: lba=%llu batch=%u rc=%zd\n", (unsigned long long)lba, batch_size, rc); return -1; } - lba += batch_size; - dst += batch_size * EXT2_SECTOR_SIZE; - remaining -= batch_size; + if ((size_t)rc > expected_bytes) { + printf("[ext2] block_read_sectors: lba=%llu batch=%u rc=%zd (oversize)\n", + (unsigned long long)lba, batch_size, rc); + return -1; + } + if (rc == 0 || (rc % EXT2_SECTOR_SIZE) != 0) { + printf("[ext2] block_read_sectors: short/unaligned rc=%zd lba=%llu batch=%u\n", + rc, (unsigned long long)lba, batch_size); + return -1; + } + uint32_t read_sectors = (uint32_t)(rc / EXT2_SECTOR_SIZE); + if (read_sectors > batch_size) + read_sectors = batch_size; + lba += read_sectors; + dst += (size_t)read_sectors * EXT2_SECTOR_SIZE; + remaining -= read_sectors; } return 0; } @@ -367,10 +386,38 @@ ext2_read_block(uint32_t block_no, void *buf) return -1; offset = (uint64_t)block_no * ext2_ctx.block_size; limit_bytes = ext2_device_block_size * ext2_device_block_count; - if (offset > limit_bytes || offset + ext2_ctx.block_size > limit_bytes) { - ext2_log_block_error("invalid block", block_no); + + /* Check if block is valid according to filesystem superblock first. + * The filesystem superblock knows the actual filesystem size, so we should + * trust it over device capacity checks. If the filesystem says the block + * exists, it should be valid (the filesystem was created on this device). */ + if (ext2_ctx.super.s_blocks_count != 0 && block_no >= ext2_ctx.super.s_blocks_count) { + ext2_log_block_error("invalid block (exceeds filesystem)", block_no); return -1; } + + /* Then check device capacity as a safety measure. However, if the filesystem + * superblock says the block is valid, we should allow it even if it's close + * to the device limit (filesystem overhead, rounding, etc.). Only reject if + * it's clearly beyond device capacity. */ + if (offset >= limit_bytes) { + ext2_log_block_error("invalid block (exceeds device)", block_no); + return -1; + } + /* If block extends slightly beyond device due to filesystem block size + * being larger than device sector size, read what we can and zero-fill. */ + if (offset + ext2_ctx.block_size > limit_bytes) { + uint64_t available = limit_bytes - offset; + if (available == 0) { + ext2_log_block_error("invalid block (no space)", block_no); + return -1; + } + /* Read partial block - zero-fill the rest */ + if (ext2_read_bytes(offset, buf, (size_t)available) != 0) + return -1; + memset((uint8_t *)buf + available, 0, ext2_ctx.block_size - (size_t)available); + return 0; + } return ext2_read_bytes(offset, buf, ext2_ctx.block_size); } @@ -378,8 +425,15 @@ static int ext2_read_block_with_wait(uint32_t block_no, void *buf) { for (int attempt = 0; attempt < EXT2_BLOCK_WAIT_RETRIES; attempt++) { - if (ext2_read_block(block_no, buf) == 0) + int rc = ext2_read_block(block_no, buf); + if (rc == 0) return 0; +#ifdef LENIX_DEBUG + if (attempt == 0 || attempt < 5 || (attempt % 1000) == 0) { + printf("[ext2] block read retry block=%u attempt=%d rc=%d\n", + block_no, attempt + 1, rc); + } +#endif if (attempt == 0) puts("[ext2] waiting for block service..."); for (int spin = 0; spin < EXT2_BLOCK_WAIT_SPIN; spin++) { @@ -456,6 +510,14 @@ ext2_write_bytes(uint64_t offset, const void *buf, siz size_t chunk = (block_remaining < len) ? block_remaining : len; temp = temp_block; + /* Validate block_off and chunk to prevent buffer overflow */ + if (block_off >= EXT2_MAX_BLOCK_SIZE || chunk > EXT2_MAX_BLOCK_SIZE || + block_off + chunk > EXT2_MAX_BLOCK_SIZE) { + printf("[ext2] write_bytes: invalid block_off=%zu chunk=%zu\n", + block_off, chunk); + return -1; + } + if (block_off == 0 && chunk == ext2_ctx.block_size) { /* Aligned full block write - no RMW needed */ uint64_t sector = block_start / EXT2_SECTOR_SIZE; @@ -501,6 +563,13 @@ ext2_write_bytes(uint64_t offset, const void *buf, siz continue; } /* Partial sector write - need RMW */ + /* Validate sector_off and chunk to prevent buffer overflow */ + if (sector_off >= EXT2_SECTOR_SIZE || chunk > EXT2_SECTOR_SIZE || + sector_off + chunk > EXT2_SECTOR_SIZE) { + printf("[ext2] write_bytes: invalid sector_off=%zu chunk=%zu\n", + sector_off, chunk); + return -1; + } if (block_read_sectors(sector, 1, temp) != 0) return -1; memcpy(temp + sector_off, in, chunk); @@ -1556,13 +1625,26 @@ puts("[ext2] superblock bytes read successfully"); #endif #ifdef LENIX_DEBUG uint32_t gd_block = (ext2_ctx.block_size == 1024) ? 2U : 1U; - // puts("[ext2] reading group descriptor block..."); + puts("[ext2] reading group descriptor block..."); + { + char buf[96]; + snprintf(buf, sizeof(buf), + "[ext2] group descriptor block=%u", gd_block); + puts(buf); + } if (ext2_read_block_with_wait(gd_block, blk) != 0) { // puts("[ext2] failed to read group descriptor"); return -1; } struct ext2_group_desc *gd = (struct ext2_group_desc *)blk; ext2_ctx.inode_table_block = gd->bg_inode_table; + { + char buf[128]; + snprintf(buf, sizeof(buf), + "[ext2] group descriptor read ok inode_table_block=%u", + ext2_ctx.inode_table_block); + puts(buf); + } puts("[ext2] mount complete"); #else if (ext2_read_block_with_wait((ext2_ctx.block_size == 1024) ? 2U : 1U, blk) != 0) @@ -1597,12 +1679,15 @@ ext2_is_valid_inode_no(uint32_t ino) static int ext2_is_valid_block_no(uint32_t block) { - if (block >= ext2_device_block_count) + /* Check against ext2 filesystem block count (not device block count) */ + if (ext2_ctx.super.s_blocks_count != 0 && + block >= ext2_ctx.super.s_blocks_count) return 0; /* Overflow check: ensure block * block_size doesn't overflow */ if (block > (UINT64_MAX / ext2_ctx.block_size)) return 0; uint64_t byte_offset = (uint64_t)block * ext2_ctx.block_size; + /* Also check that byte offset doesn't exceed device capacity */ if (byte_offset > ext2_device_block_size * ext2_device_block_count) return 0; return 1; @@ -1889,6 +1974,15 @@ static int ext2_dir_lookup(const struct ext2_inode *di struct ext2_inode *inode_out, uint32_t dir_inode_no) { uint8_t blk[EXT2_MAX_BLOCK_SIZE]; + #ifdef LENIX_DEBUG + char comp[64]; + size_t nlen = name_len; + if (nlen >= sizeof(comp)) + nlen = sizeof(comp) - 1; + memcpy(comp, name, nlen); + comp[nlen] = '\0'; + printf("[ext2] dir_lookup: ino=%u name='%s'\n", dir_inode_no, comp); + #endif uint32_t max_blocks = 12; if (dir_inode->i_size / ext2_ctx.block_size < 12) max_blocks = (dir_inode->i_size + ext2_ctx.block_size - 1) / @@ -1954,9 +2048,18 @@ static int ext2_lookup(const char *path, struct ext2_i } path_copy[path_len] = '\0'; } + #ifdef LENIX_DEBUG + printf("[ext2] lookup path='%s'\n", (path != NULL) ? path_copy : "(null)"); + #endif + #ifdef LENIX_DEBUG + puts("[ext2] lookup: reading root inode"); + #endif if (ext2_read_inode(2, &inode) != 0) return -1; + #ifdef LENIX_DEBUG + puts("[ext2] lookup: root inode read ok"); + #endif uint32_t current_inode_no = 2; if (path == NULL || path[0] == '\0') { if (inode_out) @@ -1982,6 +2085,10 @@ static int ext2_lookup(const char *path, struct ext2_i size_t len = (size_t)(p - start); struct ext2_inode next; uint32_t child_inode; + #ifdef LENIX_DEBUG + printf("[ext2] lookup: component '%.*s' parent_ino=%u\n", + (int)len, start, current_inode_no); + #endif if ((inode.i_mode & S_IFMT) != S_IFDIR) return -1; if (ext2_dir_lookup(&inode, start, len, &child_inode, &next, @@ -1996,6 +2103,9 @@ static int ext2_lookup(const char *path, struct ext2_i puts(buf); return -1; } + #ifdef LENIX_DEBUG + printf("[ext2] lookup: found ino=%u\n", child_inode); + #endif inode = next; current_inode_no = child_inode; while (*p == '/') @@ -2102,9 +2212,16 @@ ext2_handle_lookup(int fd) int idx = fd - EXT2_FD_BASE; if (idx < 0 || idx >= EXT2_MAX_HANDLES) return NULL; - if (!ext2_handles[idx].in_use) + struct ext2_handle *h = &ext2_handles[idx]; + /* Validate handle pointer is within expected range */ + if ((uintptr_t)h < (uintptr_t)ext2_handles || + (uintptr_t)h >= (uintptr_t)(ext2_handles + EXT2_MAX_HANDLES)) { + printf("[ext2] ext2_handle_lookup: handle pointer out of range: %p\n", (void*)h); return NULL; - return &ext2_handles[idx]; + } + if (!h->in_use) + return NULL; + return h; } static void @@ -2927,6 +3044,7 @@ static void fs_handle_stat(const struct ipc_fs_request path[len] = '\0'; #ifdef LENIX_DEBUG puts("[ext2] fs_handle_stat called"); + printf("[ext2] stat path_len=%zu path='%s'\n", len, path); #endif fs_handle_stat_path(path, req->body.stat.flags, resp); } @@ -2992,6 +3110,20 @@ static void fs_handle_seek(const struct ipc_fs_request return; } + /* Validate handle pointer is reasonable (not a small integer) */ + if ((uintptr_t)h < 0x1000) { + printf("[ext2] fs_handle_seek: invalid handle pointer %p\n", (void*)h); + resp->body.seek.status = EXT2_EBADF; + return; + } + + /* Validate handle is still in use */ + if (!h->in_use) { + printf("[ext2] fs_handle_seek: handle not in use\n"); + resp->body.seek.status = EXT2_EBADF; + return; + } + if (h->type == EXT2_HANDLE_FILE) { int64_t new_off = (int64_t)h->u.file.offset; switch (req->body.seek.whence) { @@ -3002,6 +3134,12 @@ static void fs_handle_seek(const struct ipc_fs_request new_off += req->body.seek.offset; break; case SEEK_END: + /* Validate inode pointer before accessing i_size */ + if ((uintptr_t)&h->u.file.inode < 0x1000) { + printf("[ext2] fs_handle_seek: invalid inode pointer %p\n", (void*)&h->u.file.inode); + resp->body.seek.status = EXT2_EBADF; + return; + } new_off = h->u.file.inode.i_size + req->body.seek.offset; break; default: @@ -3010,8 +3148,11 @@ static void fs_handle_seek(const struct ipc_fs_request } if (new_off < 0) new_off = 0; - if ((uint64_t)new_off > h->u.file.inode.i_size) - new_off = h->u.file.inode.i_size; + /* Validate inode pointer before accessing i_size again */ + if ((uintptr_t)&h->u.file.inode >= 0x1000) { + if ((uint64_t)new_off > h->u.file.inode.i_size) + new_off = h->u.file.inode.i_size; + } h->u.file.offset = (uint32_t)new_off; #if EXT2_READAHEAD_ENABLE /* Invalidate cache on seek */ @@ -3498,6 +3639,11 @@ main(int argc, char **argv, char **envp) #ifdef LENIX_DEBUG puts("[ext2] main() started"); #endif + struct sigaction sa; + memset(&sa, 0, sizeof(sa)); + sa.sa_handler = ext2_sig_handler; + sigaction(SIGSEGV, &sa, NULL); + sigaction(SIGBUS, &sa, NULL); ext2_bootstrap_portal = portal_get_bootstrap(); #ifdef LENIX_DEBUG puts("[ext2] got bootstrap portal"); @@ -3583,6 +3729,7 @@ main(int argc, char **argv, char **envp) continue; if ((size_t)got < sizeof(req)) memset(((uint8_t *)&req) + got, 0, sizeof(req) - (size_t)got); + ext2_log_request(&req); fs_dispatch(&req); #ifdef LENIX_BOOT_PROFILE request_count++; @@ -3602,4 +3749,49 @@ main(int argc, char **argv, char **envp) } return 0; } + +static void +ext2_log_request(const struct ipc_fs_request *req) +{ +#ifdef LENIX_DEBUG + static int log_budget = 64; /* avoid flooding console */ + + if (req == NULL || log_budget == 0) + return; + log_budget--; + + switch (req->opcode) { + case IPC_FS_REQ_OPEN: + printf("[ext2][req] OPEN len=%u flags=0x%x\n", + req->body.open.path_len, req->body.open.flags); + break; + case IPC_FS_REQ_READ: + printf("[ext2][req] READ fd=%d len=%u\n", + req->body.read.fd, req->body.read.length); + break; + case IPC_FS_REQ_SEEK: + printf("[ext2][req] SEEK fd=%d off=%lld whence=%d\n", + req->body.seek.fd, + (long long)req->body.seek.offset, + req->body.seek.whence); + break; + case IPC_FS_REQ_STAT: + printf("[ext2][req] STAT len=%u\n", req->body.stat.path_len); + break; + default: + printf("[ext2][req] opcode=%u\n", req->opcode); + break; + } +#else + (void)req; +#endif +} + +static void +ext2_sig_handler(int sig) +{ + const char msg[] = "[ext2] FATAL: received signal\n"; + write(STDERR_FILENO, msg, sizeof(msg) - 1); + _exit(128 + sig); +} #include blob - 7df4d909c3c886b430584adb030621bdffc8bb35 blob + 14148c7225887861770d8f0479b579e062e3c919 --- servers/fs/vfs/main.c +++ servers/fs/vfs/main.c @@ -1617,14 +1617,32 @@ vfs_respond_read(const struct ipc_vfs_request *req) pos >= handle->cache_file_offset && pos < handle->cache_file_offset + (int64_t)handle->cache_valid) { - size_t cache_off = (size_t)(pos - handle->cache_file_offset); - size_t cache_avail = handle->cache_valid - cache_off; - size_t take = (requested_len < cache_avail) ? requested_len : cache_avail; + /* Bounds check: ensure cache_valid is within reasonable limits */ + if (handle->cache_valid > VFS_READAHEAD_SIZE) { + /* Corrupted cache state - invalidate and fall through to fetch */ + handle->cache_valid = 0; + handle->cache_file_offset = -1; + } else { + size_t cache_off = (size_t)(pos - handle->cache_file_offset); + /* Additional bounds check: ensure cache_off is within cache_valid */ + if (cache_off >= handle->cache_valid) { + /* Corrupted offset - invalidate cache */ + handle->cache_valid = 0; + handle->cache_file_offset = -1; + } else { + size_t cache_avail = handle->cache_valid - cache_off; + size_t take = (requested_len < cache_avail) ? requested_len : cache_avail; + /* Final bounds check: ensure we don't read beyond cache buffer */ + if (cache_off + take > VFS_READAHEAD_SIZE) { + take = VFS_READAHEAD_SIZE - cache_off; + } - memcpy(resp.body.read.data, handle->cache + cache_off, take); - copied = take; - pos += take; - requested_len -= take; + memcpy(resp.body.read.data, handle->cache + cache_off, take); + copied = take; + pos += take; + requested_len -= take; + } + } } /* Step 2: If still need data, fetch with read-ahead */ @@ -1700,6 +1718,13 @@ vfs_respond_read(const struct ipc_vfs_request *req) if (fetched == 0) break; /* EOF */ + /* Bounds check: ensure we don't overflow the cache buffer */ + if (total_fetched + fetched > VFS_READAHEAD_SIZE) { + fetched = VFS_READAHEAD_SIZE - total_fetched; + if (fetched == 0) + break; + } + memcpy(handle->cache + total_fetched, fs_response_buffer.body.read.data, fetched); total_fetched += fetched; blob - f08a0046a594d0d2877f33ed4d471433a43441ee blob + 07d25e2e992bfc5eb1bc2e24026cc215268c1fdc --- servers/namesvc/main.c +++ servers/namesvc/main.c @@ -258,19 +258,27 @@ namesvc_handle_register(const struct ipc_namesvc_reque resp.body.reg.status = -ENFILE; namesvc_log("[namesvc] staged register failed: no free slots"); } else { - memset(entry, 0, sizeof(*entry)); - entry->in_use = true; - entry->staged = true; - entry->name_len = len; - memcpy(entry->name, req->body.reg.name, len); - if (len < IPC_NAMESVC_MAX_NAME) - entry->name[len] = '\0'; - entry->portal = req->body.reg.portal; - entry->rights = req->body.reg.rights; - entry->flags = req->body.reg.flags; - entry->owner = caller; - resp.body.reg.status = 0; - namesvc_log("[namesvc] staged registration accepted"); + /* Validate allocated entry pointer is within registry array */ + if ((uintptr_t)entry < (uintptr_t)registry || + (uintptr_t)entry >= (uintptr_t)(registry + NAMESVC_MAX_ENTRIES)) { + printf("[namesvc] namesvc_alloc returned invalid pointer: %p\n", (void*)entry); + resp.body.reg.status = -ENFILE; + entry = NULL; + } else { + memset(entry, 0, sizeof(*entry)); + entry->in_use = true; + entry->staged = true; + entry->name_len = len; + memcpy(entry->name, req->body.reg.name, len); + if (len < IPC_NAMESVC_MAX_NAME) + entry->name[len] = '\0'; + entry->portal = req->body.reg.portal; + entry->rights = req->body.reg.rights; + entry->flags = req->body.reg.flags; + entry->owner = caller; + resp.body.reg.status = 0; + namesvc_log("[namesvc] staged registration accepted"); + } } } } else { @@ -290,14 +298,32 @@ namesvc_handle_register(const struct ipc_namesvc_reque #endif entry = namesvc_find(req->body.reg.name, len); /* namesvc is single-threaded: no concurrent mutation of entries */ - if (entry != NULL && entry->owner != caller && !is_admin) - resp.body.reg.status = -1; + if (entry != NULL) { + /* Validate entry pointer is within registry array */ + if ((uintptr_t)entry < (uintptr_t)registry || + (uintptr_t)entry >= (uintptr_t)(registry + NAMESVC_MAX_ENTRIES)) { + printf("[namesvc] namesvc_find returned invalid pointer: %p\n", (void*)entry); + resp.body.reg.status = -1; + entry = NULL; + } else if (entry->owner != caller && !is_admin) { + resp.body.reg.status = -1; + } + } if (resp.body.reg.status == 0 && entry == NULL) entry = namesvc_alloc(); + if (entry != NULL) { + /* Validate allocated entry pointer is within registry array */ + if ((uintptr_t)entry < (uintptr_t)registry || + (uintptr_t)entry >= (uintptr_t)(registry + NAMESVC_MAX_ENTRIES)) { + printf("[namesvc] namesvc_alloc returned invalid pointer: %p\n", (void*)entry); + resp.body.reg.status = -2; + entry = NULL; + } + } if (entry == NULL && resp.body.reg.status == 0) { resp.body.reg.status = -2; namesvc_log("[namesvc] register failed: no free slots"); - } else if (resp.body.reg.status == 0) { + } else if (resp.body.reg.status == 0 && entry != NULL) { entry->in_use = true; entry->staged = false; entry->name_len = len; blob - /dev/null blob + 536e0b6c963606255f2f14870754e7759d997b01 (mode 755) --- /dev/null +++ run_legacy-old.sh @@ -0,0 +1,2 @@ +#!/bin/sh +qemu-system-x86_64 -smp 4 -m 8G -cdrom build/x86_64/lenix.iso -serial stdio -display none 2>&1 | tee boot-qemu-x86_64-legacy.log blob - /dev/null blob + 576623adcd1853a2643570ef992cd586ca4238bf (mode 755) --- /dev/null +++ run_legacy.sh @@ -0,0 +1,2 @@ +#!/bin/sh +qemu-system-x86_64 -enable-kvm -cpu host -smp 4 -m 8G -M q35 -cdrom build/x86_64/lenix.iso -serial stdio -display none 2>&1 | tee boot-qemu-x86_64-legacy.log blob - 870adfc3a7deb8a9bdf9c0216e5018e36b36a69b blob + 86d197e7e75232fd4f641f1c6cb85898451a3328 --- user/apps/sh/sh.c +++ user/apps/sh/sh.c @@ -468,20 +468,27 @@ main(void) int rc; struct sigaction sa; + write(STDERR_FILENO, "[sh] main entry\n", 16); shell_pgid = getpgrp(); + write(STDERR_FILENO, "[sh] getpgrp done\n", 18); if (shell_pgid <= 0) { shell_pgid = getpid(); setpgrp(0, shell_pgid); + write(STDERR_FILENO, "[sh] setpgrp done\n", 18); } + write(STDERR_FILENO, "[sh] calling tcsetpgrp\n", 23); tcsetpgrp(STDIN_FILENO, shell_pgid); + write(STDERR_FILENO, "[sh] tcsetpgrp done\n", 20); signal(SIGTTOU, SIG_IGN); signal(SIGTSTP, SIG_IGN); signal(SIGTTIN, SIG_IGN); + write(STDERR_FILENO, "[sh] signals configured\n", 24); memset(&sa, 0, sizeof(sa)); sa.sa_handler = on_sigchld; sigemptyset_local(&sa.sa_mask); sa.sa_flags = 0; sigaction(SIGCHLD, &sa, NULL); + write(STDERR_FILENO, "[sh] entering main loop\n", 24); for (;;) { #ifdef LENIX_DEBUG blob - 20d17edffeea8e9634cab915365bf6560b49ca58 blob + 0417528615454f218fb8288ec5d5c8317b0f2d3f --- user/init/main.c +++ user/init/main.c @@ -462,6 +462,7 @@ main(void) } init_log_time("mounted / via ext2"); + #if 0 /* Disabled: handoff not currently used (services array is empty) */ /* Stage and commit rootfs-backed services (initrd -> rootfs fast-path) */ #ifdef LENIX_DEBUG puts("[init] starting initrd -> rootfs handoff"); @@ -471,6 +472,7 @@ main(void) } else { puts("[init] handoff complete"); } + #endif /* TODO: Mount /tmp as separate ext2 partition when disk partitioning is implemented. * For now, /tmp is mounted as part of the root filesystem (read-only state). @@ -547,13 +549,18 @@ init_log_time("resolving and opening console"); char *argv[] = { "sh", NULL }; char *envp[] = { NULL }; pid_t pid; + write(STDERR_FILENO, "[init] launching /bin/sh\n", 25); + puts("[init] launching /bin/sh"); init_log_time("starting shell (/bin/sh)"); if (posix_spawnp(&pid, "sh", NULL, NULL, argv, envp) != 0) { + write(STDERR_FILENO, "[init] posix_spawnp failed\n", 27); puts("[init] failed to start /bin/sh"); } else { #ifdef LENIX_DEBUG printf("[init] shell spawned pid=%d\n", (int)pid); #endif + write(STDERR_FILENO, "[init] spawn OK\n", 16); + puts("[init] /bin/sh spawn succeeded"); init_log_time("shell spawned"); /* Reassert the console PTY as active after spawn in case activation * was lost during portal handoff. This keeps shell input routed. */ @@ -562,6 +569,20 @@ init_log_time("resolving and opening console"); else puts("[init] warning: cannot activate console PTY (id=0)"); } + + /* + * Keep init alive as a simple reaper/console anchor so the + * shell retains keyboard input and stdio portals are not + * revoked when init exits. Loop forever reaping any child. + */ + for (;;) { + int status = 0; + pid_t reap = waitpid(-1, &status, 0); + if (reap <= 0) { + poll(NULL, 0, 100); + continue; + } + } } init_log_time("done; returning to scheduler"); blob - a2208b0f2956e3127965af89f2ef5b40e9500e85 blob + 3d7fd8f3cc1b0970f32785dcf9a571c9c6f9b429 --- user/runtime/include/lenix/block_service.h +++ user/runtime/include/lenix/block_service.h @@ -14,6 +14,7 @@ struct ipc_block_service_request { uint32_t blocks; uint64_t lba; uint32_t data_len; + uint32_t reserved; /* padding to distinguish from backend response (4124 bytes) */ uint8_t data[IPC_BLOCK_SERVICE_MAX_DATA]; }; blob - b2f2c7442e934f2a1690171a18009a332b313cd0 blob + 3954e6a0e171ee3c34730af7c20dfdca9189a6f8 --- user/runtime/src/syscall.c +++ user/runtime/src/syscall.c @@ -645,14 +645,43 @@ console_get_history(char *buffer, size_t cap) int pty_alloc(struct pty_alloc_desc *desc) { - if (desc == NULL) - return -1; - long ret = __syscall6(SYS_pty_alloc, (long)desc, 0, 0, 0, 0, 0); - if (ret < 0) { - errno = (int)(-ret); - return -1; - } - return (int)ret; + if (desc == NULL) + return -1; + long ret = __syscall6(SYS_pty_alloc, (long)desc, 0, 0, 0, 0, 0); + #ifdef LENIX_DEBUG + /* Debug: trace syscall return value */ + { + char buf[64]; + int i = 0; + const char *prefix = "[pty_alloc] ret="; + while (prefix[i]) buf[i] = prefix[i], i++; + if (ret == 0) { + buf[i++] = '0'; + } else if (ret < 0) { + buf[i++] = '-'; + long abs = -ret; + char tmp[20]; int t = 0; + do { tmp[t++] = '0' + (abs % 10); abs /= 10; } while (abs > 0); + while (t > 0) buf[i++] = tmp[--t]; + } else { + char tmp[20]; int t = 0; + long v = ret; + while (v > 0) { tmp[t++] = '0' + (v % 10); v /= 10; } + while (t > 0) buf[i++] = tmp[--t]; + } + buf[i++] = '\n'; buf[i] = 0; + __syscall6(SYS_write, 1, (long)buf, i, 0, 0, 0); + } + #endif + if (ret > 0) { + /* pty_alloc should never return a positive value; treat as success for now. */ + ret = 0; + } + if (ret < 0) { + errno = (int)(-ret); + return -1; + } + return (int)ret; } int @@ -833,7 +862,16 @@ posix_spawnp(pid_t *pid, const char *file, int fs_register_service(portal_handle_t bootstrap_handle) { - return (int)__syscall6(SYS_fs_register, bootstrap_handle, 0, 0, 0, 0, 0); + long ret = __syscall6(SYS_fs_register, bootstrap_handle, 0, 0, 0, 0, 0); + + /* Unexpected positive values should be treated as success */ + if (ret > 0) + ret = 0; + if (ret < 0) { + errno = (int)(-ret); + return -1; + } + return (int)ret; } int @@ -1452,6 +1490,14 @@ block_rw(uint32_t device, uint64_t lba, void *buf, { if (buf == NULL || blocks == 0) return -1; + + /* Validate buffer pointer is in reasonable user-space range */ + uintptr_t buf_addr = (uintptr_t)buf; + if (buf_addr < 0x1000 || buf_addr > 0x7fffffffffffULL) { + /* Invalid buffer address - likely corrupted pointer */ + return -1; + } + uint8_t *base = (uint8_t *)buf; size_t total = 0; const uint32_t max_blocks_per_req = IPC_BLOCK_SERVICE_MAX_DATA / 512U; @@ -1463,16 +1509,31 @@ block_rw(uint32_t device, uint64_t lba, void *buf, if (batch > max_blocks_per_req) batch = max_blocks_per_req; - size_t bytes = (size_t)batch * 512U; + /* Validate base pointer before each operation */ + uintptr_t base_addr = (uintptr_t)base; + if (base_addr < 0x1000 || base_addr > 0x7fffffffffffULL) { + /* Invalid base address - likely buffer overflow */ + return -1; + } + ssize_t rc = block_service_rw(device, lba, base, batch, flags); if (rc < 0) return rc; + if (rc == 0) { + /* Short transfer - return error to avoid advancing to invalid address */ + return -1; + } - /* block_service_rw returns bytes transferred; ensure it matches expectation */ + /* block_service_rw returns bytes transferred; advance by actual bytes, not expected */ total += (size_t)rc; - base += bytes; - lba += batch; - remaining -= batch; + base += (size_t)rc; /* Advance by actual bytes transferred */ + uint32_t sectors_transferred = (uint32_t)(rc / 512U); + if (sectors_transferred == 0 || (rc % 512U) != 0) { + /* Unaligned or zero transfer - error */ + return -1; + } + lba += sectors_transferred; + remaining -= sectors_transferred; } return (ssize_t)total; } @@ -1511,8 +1572,21 @@ block_service_rw(uint32_t device, uint64_t lba, void * { if (buf == NULL || blocks == 0) return -1; - return __syscall6(SYS_blocksvc_request, device, lba, (long)buf, - blocks, flags, 0); + + /* Retry a few times if the daemon returns a short transfer. */ + const uint32_t max_attempts = 3; + for (uint32_t attempt = 0; attempt < max_attempts; attempt++) { + long ret = __syscall6(SYS_blocksvc_request, device, lba, (long)buf, + blocks, flags, 0); + if (ret == (long)((uint64_t)blocks * 512ULL)) + return ret; /* full success */ + if (ret < 0) + return ret; /* hard error */ + /* Short transfer: try again after a brief pause */ + struct pollfd pfd = { 0 }; + poll(&pfd, 0, 1); + } + return -1; /* give up after retries */ } int