commit 2b4233ff2aff2093784c67e84ca4def9b306af90 from: int16h date: Thu Dec 4 19:02:09 2025 UTC Unblocking portal issue with filetest exit commit - 0a0ef0d75760df941fb4e94320a4f99a1bffe1da commit + 2b4233ff2aff2093784c67e84ca4def9b306af90 blob - fbfb55b454d93b7b732c42abae5d18e5da979100 blob + 7c0ac70927c6f8ba0d6a8e3274de06e8d210fc9a --- GNUmakefile +++ GNUmakefile @@ -82,6 +82,9 @@ endif ifeq ($(DEBUG_SMP),1) BASE_CFLAGS += -DLENIX_DEBUG_SMP endif +ifeq ($(DEBUG_EXIT),1) +BASE_CFLAGS += -DLENIX_DEBUG_EXIT +endif TARGET_FLAGS := LINKER_SCRIPT := UEFI_SUPPORTED := 0 blob - 8fed7a55a932f6b2a6c1660481f5c12c13fbcf7a blob + fdcd63da88ce519ec17064ced9a1d19699452d39 --- kernel/console/pty.c +++ kernel/console/pty.c @@ -15,6 +15,7 @@ #include "sched/task.h" #include "sched/clock.h" #include "log/printk.h" +#include "log/serial.h" #include "sys/diag.h" #include "sys/syscall.h" #include "sys/signal.h" @@ -46,6 +47,9 @@ static console_pty_master_cb console_master_cb; static void *console_master_arg; static struct console_pty_termios console_pty_active_tios; static uint64_t console_pty_active_mask_cache; +#ifdef LENIX_DEBUG_EXIT +static void console_debug_serial_write_u64(uint64_t v); +#endif static void console_pty_apply_active_flags(void); static uint32_t console_pty_allocate_id_locked(void); @@ -265,11 +269,24 @@ console_pty_rebind_handle(ipc_portal_handle_t handle, struct ipc_mailbox *mbox; int rc = -SYSCALL_EINVAL; - if (new_owner == NULL) + if (new_owner == NULL) { +#ifdef LENIX_DEBUG_EXIT + serial_write("[pty_rebind] new_owner=NULL\n", + sizeof("[pty_rebind] new_owner=NULL\n") - 1); +#endif return -SYSCALL_EINVAL; + } mbox = sched_task_mailbox(new_owner); - if (mbox == NULL) + if (mbox == NULL) { +#ifdef LENIX_DEBUG_EXIT + serial_write("[pty_rebind] mailbox NULL caller=", + sizeof("[pty_rebind] mailbox NULL caller=") - 1); + console_debug_serial_write_u64( + (uint64_t)sched_task_id(new_owner)); + serial_write("\n", 1); +#endif return -SYSCALL_EINVAL; + } spinlock_lock(&console_pty_lock); pty = console_pty_find_by_handle_locked(handle); @@ -279,6 +296,18 @@ console_pty_rebind_handle(ipc_portal_handle_t handle, rc = 0; } spinlock_unlock(&console_pty_lock); +#ifdef LENIX_DEBUG_EXIT + serial_write("[pty_rebind] handle=", sizeof("[pty_rebind] handle=") - 1); + console_debug_serial_write_u64(handle); + serial_write(" owner=", sizeof(" owner=") - 1); + console_debug_serial_write_u64((uint64_t)sched_task_id(new_owner)); + serial_write(" rc=", sizeof(" rc=") - 1); + console_debug_serial_write_u64((uint64_t)rc); + if (pty == NULL) + serial_write(" (not found)\n", sizeof(" (not found)\n") - 1); + else + serial_write("\n", 1); +#endif return rc; } @@ -457,6 +486,28 @@ console_pty_query(uint32_t pty_id, struct console_pty_ return 0; } +#ifdef LENIX_DEBUG_EXIT +static void +console_debug_serial_write_u64(uint64_t v) +{ + char buf[21]; + size_t i = 0; + if (v == 0) { + buf[i++] = '0'; + } else { + char tmp[21]; + size_t t = 0; + while (v > 0 && t < sizeof(tmp)) { + tmp[t++] = '0' + (v % 10); + v /= 10; + } + while (t > 0) + buf[i++] = tmp[--t]; + } + serial_write(buf, i); +} +#endif + size_t console_pty_enum(uint32_t *ids, size_t max_ids) { blob - 544829c12a20359e7bbaf24eceee4d8a86927aeb blob + 2f2f632d5eb6672d60d600fd52b401c2f15ef189 --- kernel/console/service.c +++ kernel/console/service.c @@ -1007,7 +1007,7 @@ console_service_register_ttyctl(struct sched_task *tas * early_console_write() will continue to buffer messages to the ring * buffer for audit/diagnostics, but won't write to serial. * PTY master output (console_master_write) becomes the only path to serial. */ - early_console_disable_serial_write(); + //reearly_console_disable_serial_write(); #ifdef LENIX_DEBUG serial_write("[console] early console serial writes disabled\n", 48); #endif blob - bd616d631422fec826166102a7985364720775ea blob + 01ca8e9c2d60f68326013e27cecc121f10a7a0c3 --- kernel/include/ipc/portal.h +++ kernel/include/ipc/portal.h @@ -31,6 +31,7 @@ ipc_portal_handle_t ipc_portal_create(struct sched_tas struct sched_task *target, uint32_t rights); int ipc_portal_revoke(struct sched_task *owner, ipc_portal_handle_t handle); +void ipc_portal_revoke_all_by_owner(struct sched_task *owner); int ipc_portal_send(ipc_portal_handle_t handle, const void *buf, size_t len); struct sched_task *ipc_portal_owner(ipc_portal_handle_t handle); blob - b488a12607f602f433fed57c47a2307576d43acd blob + 2685f96e4191af4cc97b1748b113ee3d9fef933f --- kernel/ipc/portal.c +++ kernel/ipc/portal.c @@ -9,6 +9,7 @@ #include "ipc/portal.h" #include "ipc/mailbox.h" #include "log/printk.h" +#include "log/serial.h" #include "metrics/perf.h" #include "sched/task.h" #include "sync/spinlock.h" @@ -59,6 +60,10 @@ static uint32_t portal_cookie_rng = 0x1f123bb5U; /* Global portal table lock for SMP safety */ static spinlock_t portal_lock = SPINLOCK_INIT; +#ifdef LENIX_DEBUG_EXIT +static void portal_debug_serial_write_u64(uint64_t v); +#endif + static uint16_t portal_cookie_next(void) { @@ -102,9 +107,37 @@ portal_lookup(ipc_portal_handle_t handle) entry = &portal_table[idx]; bool in_use = __atomic_load_n(&entry->in_use, __ATOMIC_ACQUIRE); - if (!in_use || entry->cookie != cookie) + if (!in_use || entry->cookie != cookie) { +#ifdef LENIX_DEBUG_EXIT + serial_write("[portal_lookup_miss] handle=", + sizeof("[portal_lookup_miss] handle=") - 1); + portal_debug_serial_write_u64(handle); + serial_write(" idx=", sizeof(" idx=") - 1); + portal_debug_serial_write_u64(idx); + serial_write(" in_use=", sizeof(" in_use=") - 1); + portal_debug_serial_write_u64(in_use ? 1 : 0); + serial_write(" cookie=", sizeof(" cookie=") - 1); + portal_debug_serial_write_u64(cookie); + serial_write(" entry_cookie=", sizeof(" entry_cookie=") - 1); + portal_debug_serial_write_u64(entry->cookie); + if (in_use) { + serial_write(" entry_id=", sizeof(" entry_id=") - 1); + portal_debug_serial_write_u64(entry->id); + serial_write(" entry_owner=", + sizeof(" entry_owner=") - 1); + portal_debug_serial_write_u64( + (entry->owner != NULL) ? + (uint64_t)sched_task_id(entry->owner) : 0); + serial_write(" entry_target=", + sizeof(" entry_target=") - 1); + portal_debug_serial_write_u64( + (entry->target != NULL) ? + (uint64_t)sched_task_id(entry->target) : 0); + } + serial_write("\n", 1); +#endif return NULL; - + } return entry; } @@ -254,6 +287,20 @@ ipc_portal_create(struct sched_task *owner, struct sch /* Finally publish the portal entry with a release store */ __atomic_store_n(&entry->in_use, true, __ATOMIC_RELEASE); +#ifdef LENIX_DEBUG_EXIT + serial_write("[portal_create] slot=", sizeof("[portal_create] slot=") - 1); + portal_debug_serial_write_u64(idx); + serial_write(" handle=", sizeof(" handle=") - 1); + portal_debug_serial_write_u64(entry->id); + serial_write(" owner=", sizeof(" owner=") - 1); + portal_debug_serial_write_u64((uint64_t)sched_task_id(owner)); + serial_write(" target=", sizeof(" target=") - 1); + portal_debug_serial_write_u64((uint64_t)sched_task_id(target)); + serial_write(" rights=", sizeof(" rights=") - 1); + portal_debug_serial_write_u64(rights); + serial_write("\n", 1); +#endif + spinlock_unlock(&portal_lock); arch_irq_restore(flags); @@ -271,15 +318,47 @@ ipc_portal_revoke(struct sched_task *owner, ipc_portal /* Re-check under lock to avoid races */ if (!entry->in_use || entry->id != handle) { +#ifdef LENIX_DEBUG_EXIT + serial_write("[portal_revoke] handle mismatch handle=", + sizeof("[portal_revoke] handle mismatch handle=") - 1); + portal_debug_serial_write_u64(handle); + serial_write(" in_use=", sizeof(" in_use=") - 1); + portal_debug_serial_write_u64(entry->in_use ? 1 : 0); + serial_write(" entry_id=", sizeof(" entry_id=") - 1); + portal_debug_serial_write_u64(entry->id); + serial_write("\n", 1); +#endif spinlock_unlock(&portal_lock); return -1; } if (owner != NULL && entry->owner != owner) { +#ifdef LENIX_DEBUG_EXIT + serial_write("[portal_revoke] owner mismatch handle=", + sizeof("[portal_revoke] owner mismatch handle=") - 1); + portal_debug_serial_write_u64(handle); + serial_write(" entry_owner=", sizeof(" entry_owner=") - 1); + portal_debug_serial_write_u64( + (uint64_t)sched_task_id(entry->owner)); + serial_write(" caller=", sizeof(" caller=") - 1); + portal_debug_serial_write_u64((uint64_t)sched_task_id(owner)); + serial_write("\n", 1); +#endif spinlock_unlock(&portal_lock); return -1; } +#ifdef LENIX_DEBUG_EXIT + serial_write("[portal_revoke] handle=", sizeof("[portal_revoke] handle=") - 1); + portal_debug_serial_write_u64(handle); + serial_write(" owner=", sizeof(" owner=") - 1); + portal_debug_serial_write_u64( + (uint64_t)((owner != NULL) ? sched_task_id(owner) : 0)); + serial_write(" entry_cookie=", sizeof(" entry_cookie=") - 1); + portal_debug_serial_write_u64(entry->cookie); + serial_write("\n", 1); +#endif + /* Optionally clear fields, or at least bump cookie */ entry->cookie = portal_cookie_next(); entry->rights = 0; @@ -298,6 +377,60 @@ ipc_portal_revoke(struct sched_task *owner, ipc_portal return 0; } +/* + * Revoke all portals owned by the given task. + * Called during task exit to clean up orphaned portals that would otherwise + * leak and potentially cause issues when services try to use them. + */ +void +ipc_portal_revoke_all_by_owner(struct sched_task *owner) +{ + if (owner == NULL) + return; + + spinlock_lock(&portal_lock); + +#ifdef LENIX_DEBUG_EXIT + serial_write("[portal_revoke_all] owner=", + sizeof("[portal_revoke_all] owner=") - 1); + portal_debug_serial_write_u64((uint64_t)sched_task_id(owner)); + serial_write("\n", 1); +#endif + + for (size_t i = 0; i < IPC_PORTAL_MAX; i++) { + struct ipc_portal_entry *entry = &portal_table[i]; + + if (!entry->in_use) + continue; + if (entry->owner != owner) + continue; + +#ifdef LENIX_DEBUG_EXIT + serial_write("[portal_revoke_all] slot=", + sizeof("[portal_revoke_all] slot=") - 1); + portal_debug_serial_write_u64((uint64_t)i); + serial_write(" handle=", sizeof(" handle=") - 1); + portal_debug_serial_write_u64(entry->id); + serial_write("\n", 1); +#endif + + /* Clear the portal entry */ + entry->cookie = portal_cookie_next(); + entry->rights = 0; + entry->owner = NULL; + entry->target = NULL; + entry->target_mailbox = NULL; + entry->remote_valid = false; + entry->route = NULL; + entry->route_ctx = NULL; + entry->message_count = 0; + entry->integrity_violations = 0; + __atomic_store_n(&entry->in_use, false, __ATOMIC_RELEASE); + } + + spinlock_unlock(&portal_lock); +} + int ipc_portal_send(ipc_portal_handle_t handle, const void *buf, size_t len) { @@ -407,18 +540,53 @@ ipc_portal_transfer_owner(struct sched_task *old_owner struct ipc_portal_entry *entry; uint64_t flags; - if (old_owner == NULL || new_owner == NULL) + if (old_owner == NULL || new_owner == NULL) { +#ifdef LENIX_DEBUG_EXIT + serial_write("[portal_transfer] invalid owner pointers\n", + sizeof("[portal_transfer] invalid owner pointers\n") - 1); +#endif return -1; + } entry = portal_lookup(handle); - if (entry == NULL) + if (entry == NULL) { +#ifdef LENIX_DEBUG_EXIT + serial_write("[portal_transfer] handle not found handle=", + sizeof("[portal_transfer] handle not found handle=") - 1); + portal_debug_serial_write_u64(handle); + serial_write("\n", 1); +#endif return -1; + } flags = arch_irq_save(); if (entry->owner != old_owner) { arch_irq_restore(flags); +#ifdef LENIX_DEBUG_EXIT + serial_write("[portal_transfer] owner mismatch handle=", + sizeof("[portal_transfer] owner mismatch handle=") - 1); + portal_debug_serial_write_u64(handle); + serial_write(" current_owner=", + sizeof(" current_owner=") - 1); + portal_debug_serial_write_u64( + (uint64_t)sched_task_id(entry->owner)); + serial_write(" expected=", + sizeof(" expected=") - 1); + portal_debug_serial_write_u64( + (uint64_t)sched_task_id(old_owner)); + serial_write("\n", 1); +#endif return -1; } entry->owner = new_owner; arch_irq_restore(flags); +#ifdef LENIX_DEBUG_EXIT + serial_write("[portal_transfer] ok handle=", + sizeof("[portal_transfer] ok handle=") - 1); + portal_debug_serial_write_u64(handle); + serial_write(" new_owner=", + sizeof(" new_owner=") - 1); + portal_debug_serial_write_u64((uint64_t)sched_task_id(new_owner)); + serial_write("\n", 1); +#endif return 0; } @@ -452,6 +620,28 @@ ipc_portal_set_label(ipc_portal_handle_t handle, uint3 entry->label = label; } +#ifdef LENIX_DEBUG_EXIT +static void +portal_debug_serial_write_u64(uint64_t v) +{ + char buf[21]; + size_t i = 0; + if (v == 0) { + buf[i++] = '0'; + } else { + char tmp[21]; + size_t t = 0; + while (v > 0 && t < sizeof(tmp)) { + tmp[t++] = '0' + (v % 10); + v /= 10; + } + while (t > 0) + buf[i++] = tmp[--t]; + } + serial_write(buf, i); +} +#endif + uint32_t ipc_portal_label(ipc_portal_handle_t handle) { blob - 390afdc633b57a3d35a34339d37dd7563cf2f8c0 blob + e5ccd6b63d9f4530d7e98acabbce4140db186d59 --- kernel/kmain.c +++ kernel/kmain.c @@ -255,23 +255,23 @@ kmain_post_mm(void) boot_log_result("ramdiskd", rc == 0); } - rc = user_pci_server_prepare(); - #ifdef LENIX_DEBUG - boot_log_result("Preparing pci-daemon...", rc == 0); - #endif - if (rc == 0) { - rc = user_pci_server_launch(); - boot_log_result("pci-server", rc == 0); - } + // rc = user_pci_server_prepare(); + // #ifdef LENIX_DEBUG + // boot_log_result("Preparing pci-daemon...", rc == 0); + // #endif + // if (rc == 0) { + // rc = user_pci_server_launch(); + // boot_log_result("pci-server", rc == 0); + // } - rc = user_virtio_blk_server_prepare(); - #ifdef LENIX_DEBUG - boot_log_result("Preparing virtio-blk driver...", rc == 0); - #endif - if (rc == 0) { - rc = user_virtio_blk_server_launch(); - boot_log_result("virtio-blk driver", rc == 0); - } + // rc = user_virtio_blk_server_prepare(); + // #ifdef LENIX_DEBUG + // boot_log_result("Preparing virtio-blk driver...", rc == 0); + // #endif + // if (rc == 0) { + // rc = user_virtio_blk_server_launch(); + // boot_log_result("virtio-blk driver", rc == 0); + // } rc = user_fs_server_prepare(); #ifdef LENIX_DEBUG @@ -282,14 +282,14 @@ kmain_post_mm(void) boot_log_result("fs-server", rc == 0); } - // rc = user_tmpfs_server_prepare(); - // #ifdef LENIX_DEBUG - // boot_log_result("Preparing tmpfs-server...", rc == 0); - // #endif - // if (rc == 0) { - // rc = user_tmpfs_server_launch(); - // boot_log_result("tmpfs-server", rc == 0); - // } + rc = user_tmpfs_server_prepare(); + #ifdef LENIX_DEBUG + boot_log_result("Preparing tmpfs-server...", rc == 0); + #endif + if (rc == 0) { + rc = user_tmpfs_server_launch(); + boot_log_result("tmpfs-server", rc == 0); + } rc = user_vfs_server_prepare(); #ifdef LENIX_DEBUG @@ -300,32 +300,32 @@ kmain_post_mm(void) boot_log_result("vfs", rc == 0); } - // rc = user_netd_server_prepare(); - // #ifdef LENIX_DEBUG - // boot_log_result("Preparing netd...", rc == 0); - // #endif - // if (rc == 0) { - // rc = user_netd_server_launch(); - // boot_log_result("netd", rc == 0); - // } + rc = user_netd_server_prepare(); + #ifdef LENIX_DEBUG + boot_log_result("Preparing netd...", rc == 0); + #endif + if (rc == 0) { + rc = user_netd_server_launch(); + boot_log_result("netd", rc == 0); + } - // rc = user_sock_udp_server_prepare(); - // #ifdef LENIX_DEBUG - // boot_log_result("Preparing sock.udp...", rc == 0); - // #endif - // if (rc == 0) { - // rc = user_sock_udp_server_launch(); - // boot_log_result("sock.udp", rc == 0); - // } + rc = user_sock_udp_server_prepare(); + #ifdef LENIX_DEBUG + boot_log_result("Preparing sock.udp...", rc == 0); + #endif + if (rc == 0) { + rc = user_sock_udp_server_launch(); + boot_log_result("sock.udp", rc == 0); + } - // rc = user_sock_tcp_server_prepare(); - // #ifdef LENIX_DEBUG - // boot_log_result("Preparing sock.tcp...", rc == 0); - // #endif - // if (rc == 0) { - // rc = user_sock_tcp_server_launch(); - // boot_log_result("sock.tcp", rc == 0); - // } + rc = user_sock_tcp_server_prepare(); + #ifdef LENIX_DEBUG + boot_log_result("Preparing sock.tcp...", rc == 0); + #endif + if (rc == 0) { + rc = user_sock_tcp_server_launch(); + boot_log_result("sock.tcp", rc == 0); + } rc = user_tty_server_prepare(); #ifdef LENIX_DEBUG blob - c0cca4bac2a500dedcbe6ee6e75a83ca073979b1 blob + ec9ca0551e543f1cd9bfc30c54a55ec0dd74b4e1 --- kernel/sched/task.c +++ kernel/sched/task.c @@ -28,6 +28,7 @@ #include "log/bootlog.h" #include "log/debug.h" #include "log/printk.h" +#include "log/serial.h" #include "metrics/perf.h" #include "mm/aspace.h" #include "mm/kmem.h" @@ -42,6 +43,7 @@ #include "ipc/ringbuf.h" #include "sys/signal.h" #include "sys/wait.h" +#include #include "sys/driver.h" #include "string.h" #include "mm/aspace.h" @@ -190,6 +192,13 @@ static void sched_task_init_cwd(struct sched_task *tas static int sched_dispatch_task(struct sched_task *task, uint32_t cpu_hint); static void sched_print_uint(uint64_t value); static void exit_status_clear_pid(uint64_t pid); +#ifdef LENIX_DEBUG_EXIT +static void exit_status_table_dump(const char *tag); +#endif +#ifdef LENIX_DEBUG_EXIT +static void debug_serial_write_u64(uint64_t v); +static void debug_serial_write_i64(int64_t v); +#endif struct sched_cpu_state * sched_state_for_cpu(uint32_t cpu) @@ -433,8 +442,35 @@ sched_switch(bool requeue_prev) if (next == NULL) next = &state->idle_task; prev = state->current; - if (next == prev) +#ifdef LENIX_DEBUG_EXIT + /* Only log during task exit (state UNUSED) to avoid flooding serial */ + if (prev != NULL && prev->state == SCHED_STATE_UNUSED) { + serial_write("[switch] EXIT prev=", 19); + if (prev->name != NULL) { + size_t nlen = 0; + while (prev->name[nlen] && nlen < 16) nlen++; + serial_write(prev->name, nlen); + } else { + serial_write("(null)", 6); + } + serial_write(" next=", 6); + if (next != NULL && next->name != NULL) { + size_t nlen = 0; + while (next->name[nlen] && nlen < 16) nlen++; + serial_write(next->name, nlen); + } else { + serial_write("(null)", 6); + } + serial_write("\n", 1); + } +#endif + if (next == prev) { +#ifdef LENIX_DEBUG_EXIT + if (prev != NULL && prev->state == SCHED_STATE_UNUSED) + serial_write("[switch] next==prev BUG!\n", 25); +#endif return; + } perf_counter_inc(PERF_COUNTER_SCHED_CONTEXT_SWITCH, 1); state->current = next; @@ -460,10 +496,17 @@ sched_switch(bool requeue_prev) sched_enqueue(state, prev); if (prev == NULL) { +#ifdef LENIX_DEBUG_EXIT + serial_write("[switch] prev==NULL, start_context\n", 35); +#endif arch_fpu_restore(&next->ctx); arch_start_context(&next->ctx); __builtin_unreachable(); } +#ifdef LENIX_DEBUG_EXIT + if (prev != NULL && prev->state == SCHED_STATE_UNUSED) + serial_write("[switch] EXIT arch_switch_context\n", 34); +#endif prev->state = (prev->is_idle) ? SCHED_STATE_RUNNING : prev->state; arch_fpu_save(&prev->ctx); arch_fpu_restore(&next->ctx); @@ -844,31 +887,69 @@ sched_task_set_cwd(struct sched_task *task, const char static void exit_status_clear_pid(uint64_t pid) { - for (size_t i = 0; i < (sizeof(exit_status_table) / - sizeof(exit_status_table[0])); i++) { - if (!exit_status_table[i].in_use) - continue; - if (exit_status_table[i].pid != pid) - continue; - exit_status_table[i].in_use = false; - exit_status_table[i].pid = 0; - exit_status_table[i].parent_pid = 0; - exit_status_table[i].status = 0; - } + (void)pid; + /* + * TEMPORARILY DISABLED: + * We suspect a race where exit_status_clear_pid() is called on PID reuse + * and clears a pending exit status before the real parent calls + * waitpid(). For debugging, do not clear exit_status_table entries here. + * + * NOTE: This will leak exit_status_table entries if parents never reap + * children, but that is acceptable for debugging. + */ } static void exit_status_record(uint64_t pid, uint64_t parent_pid, int status) { +#ifdef LENIX_DEBUG_EXIT + bool reused = false; +#endif + for (size_t i = 0; i < (sizeof(exit_status_table) / sizeof(exit_status_table[0])); i++) { if (exit_status_table[i].in_use && exit_status_table[i].pid != pid) continue; +#ifdef LENIX_DEBUG_EXIT + reused = exit_status_table[i].in_use; +#endif exit_status_table[i].in_use = true; exit_status_table[i].pid = pid; exit_status_table[i].parent_pid = parent_pid; exit_status_table[i].status = status; +#ifdef LENIX_DEBUG_EXIT + serial_write("[exit_status_record] slot=", + sizeof("[exit_status_record] slot=") - 1); + debug_serial_write_u64(i); + serial_write(" reused=", sizeof(" reused=") - 1); + debug_serial_write_u64(reused ? 1 : 0); + serial_write(" pid=", sizeof(" pid=") - 1); + debug_serial_write_u64(pid); + serial_write(" parent=", sizeof(" parent=") - 1); + debug_serial_write_u64(parent_pid); + serial_write(" status=", sizeof(" status=") - 1); + debug_serial_write_i64(status); + serial_write("\n", 1); + /* Dump table snapshot after insert */ + for (size_t j = 0; j < (sizeof(exit_status_table) / + sizeof(exit_status_table[0])); j++) { + if (!exit_status_table[j].in_use) + continue; + serial_write("[exit_status_record_table] slot=", + sizeof("[exit_status_record_table] slot=") - 1); + debug_serial_write_u64(j); + serial_write(" pid=", sizeof(" pid=") - 1); + debug_serial_write_u64(exit_status_table[j].pid); + serial_write(" parent=", sizeof(" parent=") - 1); + debug_serial_write_u64( + exit_status_table[j].parent_pid); + serial_write(" status=", sizeof(" status=") - 1); + debug_serial_write_i64( + exit_status_table[j].status); + serial_write("\n", 1); + } +#endif return; } /* Table full: overwrite slot 0 */ @@ -876,29 +957,132 @@ exit_status_record(uint64_t pid, uint64_t parent_pid, exit_status_table[0].pid = pid; exit_status_table[0].parent_pid = parent_pid; exit_status_table[0].status = status; +#ifdef LENIX_DEBUG_EXIT + serial_write("[exit_status_record] slot=0 overwrite pid=", + sizeof("[exit_status_record] slot=0 overwrite pid=") - 1); + debug_serial_write_u64(pid); + serial_write(" parent=", sizeof(" parent=") - 1); + debug_serial_write_u64(parent_pid); + serial_write(" status=", sizeof(" status=") - 1); + debug_serial_write_i64(status); + serial_write("\n", 1); + for (size_t j = 0; j < (sizeof(exit_status_table) / + sizeof(exit_status_table[0])); j++) { + if (!exit_status_table[j].in_use) + continue; + serial_write("[exit_status_record_table] slot=", sizeof("[exit_status_record_table] slot=") - 1); + debug_serial_write_u64(j); + serial_write(" pid=", sizeof(" pid=") - 1); + debug_serial_write_u64(exit_status_table[j].pid); + serial_write(" parent=", sizeof(" parent=") - 1); + debug_serial_write_u64(exit_status_table[j].parent_pid); + serial_write(" status=", sizeof(" status=") - 1); + debug_serial_write_i64(exit_status_table[j].status); + serial_write("\n", 1); + } +#endif } int sched_task_exit_status_consume(uint64_t caller_pid, uint64_t pid, int *status_out) { +#ifdef LENIX_DEBUG_EXIT + static uint32_t wait_consume_miss_dump_count; + static uint32_t wait_consume_parent_mismatch_log; + bool did_dump = false; +#endif + for (size_t i = 0; i < (sizeof(exit_status_table) / sizeof(exit_status_table[0])); i++) { if (!exit_status_table[i].in_use) continue; - if (exit_status_table[i].parent_pid != caller_pid) + if (exit_status_table[i].parent_pid == 0) { +#ifdef LENIX_DEBUG_EXIT + serial_write("[wait_consume_stale] caller=", + sizeof("[wait_consume_stale] caller=") - 1); + debug_serial_write_u64(caller_pid); + serial_write(" pid=", sizeof(" pid=") - 1); + debug_serial_write_u64(exit_status_table[i].pid); + serial_write(" parent=0 clear stale\n", + sizeof(" parent=0 clear stale\n") - 1); +#endif + exit_status_table[i].in_use = false; + exit_status_table[i].pid = 0; + exit_status_table[i].parent_pid = 0; + exit_status_table[i].status = 0; continue; + } + if (exit_status_table[i].parent_pid != caller_pid) { +#ifdef LENIX_DEBUG_EXIT + if (wait_consume_parent_mismatch_log < 8) { + serial_write("[wait_consume_mismatch] caller=", + sizeof("[wait_consume_mismatch] caller=") - 1); + debug_serial_write_u64(caller_pid); + serial_write(" slot=", sizeof(" slot=") - 1); + debug_serial_write_u64(i); + serial_write(" pid=", sizeof(" pid=") - 1); + debug_serial_write_u64(exit_status_table[i].pid); + serial_write(" parent=", sizeof(" parent=") - 1); + debug_serial_write_u64( + exit_status_table[i].parent_pid); + serial_write("\n", 1); + wait_consume_parent_mismatch_log++; + } +#endif + continue; + } if (pid != 0 && pid != (uint64_t)(-1) && exit_status_table[i].pid != pid) continue; if (status_out != NULL) *status_out = exit_status_table[i].status; uint64_t found = exit_status_table[i].pid; +#ifdef LENIX_DEBUG_EXIT + int log_status = (status_out != NULL) ? *status_out : 0; + serial_write("[wait_consume] caller=", + sizeof("[wait_consume] caller=") - 1); + debug_serial_write_u64(caller_pid); + serial_write(" child=", sizeof(" child=") - 1); + debug_serial_write_u64(found); + serial_write(" status=", sizeof(" status=") - 1); + debug_serial_write_i64((int64_t)log_status); + serial_write("\n", 1); +#endif exit_status_table[i].in_use = false; exit_status_table[i].pid = 0; + exit_status_table[i].parent_pid = 0; exit_status_table[i].status = 0; return (int)found; } +#ifdef LENIX_DEBUG_EXIT + serial_write("[wait_consume_miss] caller=", + sizeof("[wait_consume_miss] caller=") - 1); + debug_serial_write_u64(caller_pid); + serial_write(" pid=", sizeof(" pid=") - 1); + debug_serial_write_u64(pid); + serial_write(" -> ECHILD\n", sizeof(" -> ECHILD\n") - 1); + if (!did_dump && wait_consume_miss_dump_count < 8) { + serial_write("[wait_consume_table] in_use entries:\n", + sizeof("[wait_consume_table] in_use entries:\n") - 1); + for (size_t i = 0; i < (sizeof(exit_status_table) / + sizeof(exit_status_table[0])); i++) { + if (!exit_status_table[i].in_use) + continue; + serial_write(" slot=", sizeof(" slot=") - 1); + debug_serial_write_u64(i); + serial_write(" pid=", sizeof(" pid=") - 1); + debug_serial_write_u64(exit_status_table[i].pid); + serial_write(" parent=", sizeof(" parent=") - 1); + debug_serial_write_u64(exit_status_table[i].parent_pid); + serial_write(" status=", sizeof(" status=") - 1); + debug_serial_write_i64(exit_status_table[i].status); + serial_write("\n", 1); + } + wait_consume_miss_dump_count++; + did_dump = true; + } +#endif return -SYSCALL_ECHILD; } @@ -906,15 +1090,27 @@ static bool sched_task_child_exists(uint64_t parent_pid, uint64_t target_pid) { struct sched_task *task; + bool result = false; for (task = task_list_head; task != NULL; task = task->next_global) { if (task->parent_pid != parent_pid) continue; if (target_pid > 0 && task->id != (uint64_t)target_pid) continue; - return true; + result = true; + break; } - return false; +#ifdef LENIX_DEBUG_EXIT + serial_write("[child_exists] caller=", + sizeof("[child_exists] caller=") - 1); + debug_serial_write_u64(parent_pid); + serial_write(" pid=", sizeof(" pid=") - 1); + debug_serial_write_i64(target_pid); + serial_write(" -> ", sizeof(" -> ") - 1); + debug_serial_write_u64(result ? 1 : 0); + serial_write("\n", 1); +#endif + return result; } int @@ -923,6 +1119,10 @@ sched_task_wait(uint64_t caller_pid, int64_t pid, int { uint64_t want_pid = 0; int rc; +#ifdef LENIX_DEBUG_EXIT + static uint64_t wait_spin_counter; + static uint32_t wait_return_log_count; +#endif if (options & ~WNOHANG) return -SYSCALL_EINVAL; @@ -931,17 +1131,52 @@ sched_task_wait(uint64_t caller_pid, int64_t pid, int for (;;) { rc = sched_task_exit_status_consume(caller_pid, want_pid, status_out); - if (rc >= 0) + if (rc >= 0) { +#ifdef LENIX_DEBUG_EXIT + if (wait_return_log_count < 64) { + serial_write("[wait_return] caller=", + sizeof("[wait_return] caller=") - 1); + debug_serial_write_u64(caller_pid); + serial_write(" pid=", sizeof(" pid=") - 1); + debug_serial_write_i64(pid); + serial_write(" rc=", sizeof(" rc=") - 1); + debug_serial_write_i64(rc); + if (status_out != NULL) { + serial_write(" status=", + sizeof(" status=") - 1); + debug_serial_write_i64(*status_out); + } + serial_write("\n", 1); + wait_return_log_count++; + } +#endif return rc; - if (!sched_task_child_exists(caller_pid, pid)) { -#ifdef LENIX_DEBUG_FULL - printk("[wait] no child: caller="); - trap_print_hex64("", caller_pid); - printk(" pid="); - trap_print_hex64("", pid); - printk("\n"); + } + if (rc == -SYSCALL_ECHILD) { +#ifdef LENIX_DEBUG_EXIT + exit_status_table_dump("[wait_echild_table]\n"); + exit_status_table_dump("[wait_echild_table]\n"); #endif - return -SYSCALL_ECHILD; + if (!sched_task_child_exists(caller_pid, pid)) + return rc; + /* Child still exists but no status yet; keep waiting */ + } else if (!sched_task_child_exists(caller_pid, pid)) { + rc = -SYSCALL_ECHILD; +#ifdef LENIX_DEBUG_EXIT + if (wait_return_log_count < 32) { + serial_write("[wait_return] caller=", + sizeof("[wait_return] caller=") - 1); + debug_serial_write_u64(caller_pid); + serial_write(" pid=", sizeof(" pid=") - 1); + debug_serial_write_i64(pid); + serial_write(" rc=", sizeof(" rc=") - 1); + debug_serial_write_i64(rc); + serial_write(" child_exists=0\n", + sizeof(" child_exists=0\n") - 1); + wait_return_log_count++; + } +#endif + return rc; } if ((options & WNOHANG) != 0) return 0; @@ -958,10 +1193,48 @@ sched_task_wait(uint64_t caller_pid, int64_t pid, int wait_spin_debug++; } #endif +#ifdef LENIX_DEBUG_EXIT + wait_spin_counter++; + if ((wait_spin_counter % 1000ULL) == 0) { + serial_write("[wait_spin] caller=", + sizeof("[wait_spin] caller=") - 1); + debug_serial_write_u64(caller_pid); + serial_write(" pid=", sizeof(" pid=") - 1); + debug_serial_write_i64(pid); + serial_write(" want=", sizeof(" want=") - 1); + debug_serial_write_u64(want_pid); + serial_write("\n", 1); + } +#endif sched_yield(); } } +#ifdef LENIX_DEBUG_EXIT +static void +exit_status_table_dump(const char *tag) +{ + size_t len = 0; + while (tag[len] != '\0') + len++; + serial_write(tag, len); + for (size_t i = 0; i < (sizeof(exit_status_table) / + sizeof(exit_status_table[0])); i++) { + if (!exit_status_table[i].in_use) + continue; + serial_write(" slot=", sizeof(" slot=") - 1); + debug_serial_write_u64(i); + serial_write(" pid=", sizeof(" pid=") - 1); + debug_serial_write_u64(exit_status_table[i].pid); + serial_write(" parent=", sizeof(" parent=") - 1); + debug_serial_write_u64(exit_status_table[i].parent_pid); + serial_write(" status=", sizeof(" status=") - 1); + debug_serial_write_i64(exit_status_table[i].status); + serial_write("\n", 1); + } +} +#endif + void sched_task_set_exit_status(struct sched_task *task, int status) { @@ -975,6 +1248,20 @@ sched_task_set_exit_status(struct sched_task *task, in return; task->exit_status_set = true; task->exit_status = status; +#ifdef LENIX_DEBUG_EXIT + printk("[exit_status_set] child="); + printk_dec(pid); + printk(" parent="); + printk_dec(parent); + printk(" status="); + if (status < 0) { + printk("-"); + printk_dec((uint64_t)(-status)); + } else { + printk_dec((uint64_t)status); + } + printk("\n"); +#endif exit_status_record(pid, parent, status); if (parent != 0) parent_task = sched_find_task(parent); @@ -986,8 +1273,21 @@ sched_task_set_exit_status(struct sched_task *task, in * so it is not revoked when this task tears down. */ if (task->stdio_portal_ready && parent_task != NULL) { - if (ipc_portal_transfer_owner(task, parent_task, - task->stdio_portal) == 0) { + int transfer_rc = ipc_portal_transfer_owner(task, parent_task, + task->stdio_portal); +#ifdef LENIX_DEBUG_EXIT + serial_write("[exit_stdio_transfer] child=", + sizeof("[exit_stdio_transfer] child=") - 1); + debug_serial_write_u64(pid); + serial_write(" parent=", sizeof(" parent=") - 1); + debug_serial_write_u64(parent); + serial_write(" portal=", sizeof(" portal=") - 1); + debug_serial_write_u64(task->stdio_portal); + serial_write(" rc=", sizeof(" rc=") - 1); + debug_serial_write_i64(transfer_rc); + serial_write("\n", 1); +#endif + if (transfer_rc == 0) { sched_task_set_stdio_portal(parent_task, task->stdio_portal); (void)console_pty_rebind_handle(task->stdio_portal, @@ -995,6 +1295,22 @@ sched_task_set_exit_status(struct sched_task *task, in /* Drop ownership in the child to avoid double revoke */ task->stdio_portal_ready = false; task->stdio_portal = IPC_PORTAL_INVALID_HANDLE; + } else { +#ifdef LENIX_DEBUG_EXIT + serial_write("[exit_stdio_transfer_fallback] rebind parent\n", + sizeof("[exit_stdio_transfer_fallback] rebind parent\n") - 1); +#endif + /* + * Debug fallback: even if transfer fails, hand the portal + * handle to the parent and rebind so console ownership + * is not stranded on the exiting child. + */ + sched_task_set_stdio_portal(parent_task, + task->stdio_portal); + (void)console_pty_rebind_handle(task->stdio_portal, + parent_task); + task->stdio_portal_ready = false; + task->stdio_portal = IPC_PORTAL_INVALID_HANDLE; } } @@ -1460,6 +1776,25 @@ sched_exit_current(void) if (task == NULL) panic("sched_exit_current: no current task"); +#ifdef LENIX_DEBUG_EXIT + serial_write("[exit] entry pid=", 17); + { + char buf[12]; + uint64_t pid = task->id; + int i = 0; + if (pid == 0) buf[i++] = '0'; + else { + char tmp[12]; + int j = 0; + while (pid > 0 && j < 10) { tmp[j++] = '0' + (pid % 10); pid /= 10; } + while (j > 0) buf[i++] = tmp[--j]; + } + buf[i] = '\0'; + serial_write(buf, i); + } + serial_write("\n", 1); +#endif + arch_disable_interrupts(); task->state = SCHED_STATE_UNUSED; @@ -1487,14 +1822,63 @@ sched_exit_current(void) task->sys_private_dtor = NULL; if (task->stdio_portal_ready) { - ipc_portal_revoke(task, task->stdio_portal); - task->stdio_portal = IPC_PORTAL_INVALID_HANDLE; - task->stdio_portal_ready = false; +#ifdef LENIX_DEBUG_EXIT + serial_write("[exit] portal_revoke\n", 21); + serial_write("[stdio_portal_revoke] task=", + sizeof("[stdio_portal_revoke] task=") - 1); + debug_serial_write_u64(task->id); + serial_write(" handle=", sizeof(" handle=") - 1); + debug_serial_write_u64(task->stdio_portal); + serial_write("\n", 1); +#endif + /* + * If this task still has children, attempt to hand stdio + * ownership to one of them to avoid revoking a handle they + * may still be using (debug instrumentation). + */ + struct sched_task *child = NULL; + for (child = task_list_head; child != NULL; + child = child->next_global) { + if (child->parent_pid == task->id) + break; + } + if (child != NULL && + ipc_portal_transfer_owner(task, child, + task->stdio_portal) == 0) { +#ifdef LENIX_DEBUG_EXIT + serial_write("[stdio_portal_reassign_child] parent=", + sizeof("[stdio_portal_reassign_child] parent=") - 1); + debug_serial_write_u64(task->id); + serial_write(" child=", sizeof(" child=") - 1); + debug_serial_write_u64(child->id); + serial_write(" handle=", sizeof(" handle=") - 1); + debug_serial_write_u64(task->stdio_portal); + serial_write("\n", 1); +#endif + (void)console_pty_rebind_handle(task->stdio_portal, + child); + task->stdio_portal = IPC_PORTAL_INVALID_HANDLE; + task->stdio_portal_ready = false; + } else { + ipc_portal_revoke(task, task->stdio_portal); + task->stdio_portal = IPC_PORTAL_INVALID_HANDLE; + task->stdio_portal_ready = false; + } } if (!task->exit_status_set) sched_task_set_exit_status(task, wait_status_exit_code(0)); + /* + * Revoke all portals owned by this task to prevent orphaned entries + * in the portal table that could cause hangs when services try to + * use them after the task is gone. + */ + ipc_portal_revoke_all_by_owner(task); + +#ifdef LENIX_DEBUG_EXIT + serial_write("[exit] mailbox_destroy\n", 23); +#endif sched_mailbox_destroy(task); /* Unlink from global list and recycle PID for reuse. */ @@ -1511,10 +1895,46 @@ sched_exit_current(void) task->prev_global = NULL; task->next_global = NULL; +#ifdef LENIX_DEBUG_EXIT + serial_write("[exit] sched_switch\n", 20); +#endif /* Leave interrupts disabled across sched_switch to avoid re-entrancy. */ sched_switch(false); panic("sched_exit_current: scheduler returned"); } + +#ifdef LENIX_DEBUG_EXIT +static void +debug_serial_write_u64(uint64_t v) +{ + char buf[21]; + size_t i = 0; + if (v == 0) { + buf[i++] = '0'; + } else { + char tmp[21]; + size_t t = 0; + while (v > 0 && t < sizeof(tmp)) { + tmp[t++] = '0' + (v % 10); + v /= 10; + } + while (t > 0) + buf[i++] = tmp[--t]; + } + serial_write(buf, i); +} + +static void +debug_serial_write_i64(int64_t v) +{ + if (v < 0) { + serial_write("-", 1); + debug_serial_write_u64((uint64_t)(-v)); + } else { + debug_serial_write_u64((uint64_t)v); + } +} +#endif struct sched_task * sched_spawn_user(const char *name, struct vm_space *space, uint64_t entry, uint64_t stack, uint64_t arg) @@ -2058,10 +2478,20 @@ sched_task_stdio_portal(const struct sched_task *task) void sched_task_set_stdio_portal(struct sched_task *task, - ipc_portal_handle_t handle) + ipc_portal_handle_t handle) { if (task == NULL) return; +#ifdef LENIX_DEBUG_EXIT + serial_write("[stdio_portal_set] task=", + sizeof("[stdio_portal_set] task=") - 1); + debug_serial_write_u64((uint64_t)sched_task_id(task)); + serial_write(" handle=", sizeof(" handle=") - 1); + debug_serial_write_u64(handle); + serial_write(" ready=", sizeof(" ready=") - 1); + debug_serial_write_u64((handle != IPC_PORTAL_INVALID_HANDLE) ? 1 : 0); + serial_write("\n", 1); +#endif task->stdio_portal = handle; task->stdio_portal_ready = (handle != IPC_PORTAL_INVALID_HANDLE); blob - c5e90c7c1c075c6db8d87ccf7444c96f3f4610dd blob + 85a3e35904db9c528f4bd3ff5c390100b305bde3 --- kernel/sys/syscall.c +++ kernel/sys/syscall.c @@ -38,6 +38,10 @@ #include "ipc/service_client.h" #include "ipc/mailbox.h" #include "sched/task.h" /* for struct sched_task fields */ +#ifdef LENIX_DEBUG_EXIT +static void syscall_debug_serial_write_u64(uint64_t v); +static void syscall_debug_serial_write_i64(int64_t v); +#endif #include "ipc/portal.h" #include "ipc/ringbuf.h" #include "lenix/server.h" @@ -1109,6 +1113,14 @@ sys_stdio_portal_handle(void) 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 return handle; } @@ -3256,6 +3268,25 @@ sys_exit_impl(uint64_t code, uint64_t arg1 __attribute bool do_log = false; struct sched_task *t = sched_current_task(); +#ifdef LENIX_DEBUG_EXIT + serial_write("[exit] sys_exit code=", 21); + { + char buf[12]; + uint64_t c = code; + int i = 0; + if (c == 0) buf[i++] = '0'; + else { + char tmp[12]; + int j = 0; + while (c > 0 && j < 10) { tmp[j++] = '0' + (c % 10); c /= 10; } + while (j > 0) buf[i++] = tmp[--j]; + } + buf[i] = '\0'; + serial_write(buf, i); + } + serial_write("\n", 1); +#endif + #if defined(LENIX_DEBUG) do_log = false; #else @@ -4183,6 +4214,24 @@ out_close: if (parent_stdio != IPC_PORTAL_INVALID_HANDLE) { sched_task_set_stdio_portal(child, parent_stdio); (void)console_pty_rebind_handle(parent_stdio, child); + /* + * Transfer portal ownership to the child so the exit + * path can transfer it back to the parent. Without + * this, the parent remains owner and the exit transfer + * fails with owner mismatch. + */ + (void)ipc_portal_transfer_owner(parent, child, + parent_stdio); +#ifdef LENIX_DEBUG_EXIT + serial_write("[stdio_inherit] parent=", + sizeof("[stdio_inherit] parent=") - 1); + syscall_debug_serial_write_u64(sched_task_id(parent)); + serial_write(" child=", sizeof(" child=") - 1); + syscall_debug_serial_write_u64(sched_task_id(child)); + serial_write(" handle=", sizeof(" handle=") - 1); + syscall_debug_serial_write_u64(parent_stdio); + serial_write("\n", 1); +#endif } } @@ -4239,6 +4288,16 @@ sys_waitpid_impl(uint64_t arg0 __attribute__((unused)) printk_dec((int64_t)arg2); printk("\n"); } +#ifdef LENIX_DEBUG_EXIT + serial_write("[sys_waitpid] entry caller=", + sizeof("[sys_waitpid] entry caller=") - 1); + syscall_debug_serial_write_u64(sched_current_task_id()); + serial_write(" pid=", sizeof(" pid=") - 1); + syscall_debug_serial_write_i64(pid); + serial_write(" opts=", sizeof(" opts=") - 1); + syscall_debug_serial_write_u64(arg2); + serial_write("\n", 1); +#endif rc = sched_task_wait(sched_current_task_id(), pid, (int)arg2, &status); if (rc < 0) @@ -4261,6 +4320,14 @@ sys_waitpid_impl(uint64_t arg0 __attribute__((unused)) printk_dec((int64_t)status); printk("\n"); } +#ifdef LENIX_DEBUG_EXIT + serial_write("[sys_waitpid] exit rc=", + sizeof("[sys_waitpid] exit rc=") - 1); + syscall_debug_serial_write_i64(rc); + serial_write(" status=", sizeof(" status=") - 1); + syscall_debug_serial_write_i64(status); + serial_write("\n", 1); +#endif return syscall_make_result((uint64_t)rc, 0); } @@ -4891,26 +4958,64 @@ block_backend_query_device_info(uint32_t device_id, struct ipc_block_backend_query_response resp = {0}; struct ipc_service_client client; ipc_portal_handle_t portal; + #ifdef LENIX_DEBUG_EXIT + static uint32_t dbg_fail_count; + #endif if (task == NULL || info == NULL) return -1; portal = block_backend_service_client_portal(task); - if (portal == IPC_PORTAL_INVALID_HANDLE) + if (portal == IPC_PORTAL_INVALID_HANDLE) { +#ifdef LENIX_DEBUG_EXIT + if (dbg_fail_count < 4 || (dbg_fail_count % 1000000U) == 0) { + printk("[wait_device_registered] no backend portal (dev="); + printk_dec(device_id); + printk(")\n"); + } + dbg_fail_count++; +#endif return -1; - if (ipc_service_client_init(&client, portal) != 0) + } + if (ipc_service_client_init(&client, portal) != 0) { +#ifdef LENIX_DEBUG_EXIT + if (dbg_fail_count < 4 || (dbg_fail_count % 1000000U) == 0) + printk("[wait_device_registered] client_init failed\n"); + dbg_fail_count++; +#endif return -1; + } syscall_memset(&req, 0, sizeof(req)); req.opcode = IPC_BLOCK_BACKEND_OPCODE_QUERY_INFO; req.device_id = device_id; if (ipc_service_request_issue(&client, &req, sizeof(req), - &resp, sizeof(resp), NULL) != 0) + &resp, sizeof(resp), NULL) != 0) { +#ifdef LENIX_DEBUG_EXIT + if (dbg_fail_count < 4 || (dbg_fail_count % 1000000U) == 0) + printk("[wait_device_registered] request_issue failed\n"); + dbg_fail_count++; +#endif return -1; - if (resp.status != IPC_BLOCK_BACKEND_STATUS_OK) + } + if (resp.status != IPC_BLOCK_BACKEND_STATUS_OK) { +#ifdef LENIX_DEBUG_EXIT + if (dbg_fail_count < 4 || (dbg_fail_count % 1000000U) == 0) { + printk("[wait_device_registered] backend status "); + printk_dec(resp.status); + printk(" dev="); + printk_dec(device_id); + printk("\n"); + } + dbg_fail_count++; +#endif return -1; + } *info = resp.info; +#ifdef LENIX_DEBUG_EXIT + dbg_fail_count = 0; +#endif return 0; } @@ -8000,9 +8105,45 @@ sys_fstatat_impl(uint64_t dirfd, uint64_t path_addr, u return sys_stat_impl(path_addr, buf_addr, dir_handle, stat_flags, 0, 0); } +#ifdef LENIX_DEBUG_EXIT +static void +syscall_debug_serial_write_u64(uint64_t v) +{ + char buf[21]; + size_t i = 0; + if (v == 0) { + buf[i++] = '0'; + } else { + char tmp[21]; + size_t t = 0; + while (v > 0 && t < sizeof(tmp)) { + tmp[t++] = '0' + (v % 10); + v /= 10; + } + while (t > 0) + buf[i++] = tmp[--t]; + } + serial_write(buf, i); +} + +static void +syscall_debug_serial_write_i64(int64_t v) +{ + if (v < 0) { + serial_write("-", 1); + syscall_debug_serial_write_u64((uint64_t)(-v)); + } else { + syscall_debug_serial_write_u64((uint64_t)v); + } +} +#endif + __attribute__((noreturn)) void syscall_exit_to_kernel(uint64_t code) { +#ifdef LENIX_DEBUG_EXIT + serial_write("[exit] syscall_exit_to_kernel\n", 30); +#endif sched_task_set_exit_status(sched_current_task(), wait_status_exit_code((int)code)); sched_exit_current(); blob - /dev/null blob + 6888981cc3e98f3d5e744b6b2a2fbb4fa9ac17ef (mode 755) --- /dev/null +++ rebuild-debug-exit.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_EXIT=1 -j4 +make ARCH=x86_64 USE_MERCURON_TOOLCHAIN=1 MERCURON_SYSROOT=$MERCURON_SYSROOT DEBUG_EXIT=1 package-runtime +make ARCH=x86_64 USE_MERCURON_TOOLCHAIN=1 MERCURON_SYSROOT=$MERCURON_SYSROOT DEBUG_EXIT=1 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 - 7c737f9d90b0781c7cfe8f1dc1c5b5a489428937 blob + 3367d28ded4c545ef5db7d70a1a0c8d7a9042367 --- rebuild-debug.sh +++ rebuild-debug.sh @@ -5,9 +5,9 @@ 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=1 LENIX_DEBUG=1 DEBUG_ALL=1 LENIX_DEBUG_VNODE_CACHE=1 -j4 -make ARCH=x86_64 USE_MERCURON_TOOLCHAIN=1 MERCURON_SYSROOT=$MERCURON_SYSROOT DEBUG=1 LENIX_DEBUG=1 DEBUG_ALL=1 package-runtime -make ARCH=x86_64 USE_MERCURON_TOOLCHAIN=1 MERCURON_SYSROOT=$MERCURON_SYSROOT DEBUG=1 LENIX_DEBUG=1 DEBUG_ALL=1 package-apps +make ARCH=x86_64 USE_MERCURON_TOOLCHAIN=1 MERCURON_SYSROOT=$MERCURON_SYSROOT DEBUG=1 LENIX_DEBUG=1 DEBUG_ALL=1 LENIX_DEBUG_VNODE_CACHE=1 DEBUG_EXIT=1 -j4 +make ARCH=x86_64 USE_MERCURON_TOOLCHAIN=1 MERCURON_SYSROOT=$MERCURON_SYSROOT DEBUG=1 LENIX_DEBUG=1 DEBUG_ALL=1 DEBUG_EXIT=1 package-runtime +make ARCH=x86_64 USE_MERCURON_TOOLCHAIN=1 MERCURON_SYSROOT=$MERCURON_SYSROOT DEBUG=1 LENIX_DEBUG=1 DEBUG_ALL=1 DEBUG_EXIT=1 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 - 4ea7ff746b0585c76a48e703533a6b1889f3370f blob + c8a44830303f6cc04bf624602c1539c00af6a9a7 --- servers/block/blockd/main.c +++ servers/block/blockd/main.c @@ -9,8 +9,6 @@ #include #include #include -#include -#include #include #include #include @@ -22,8 +20,6 @@ struct blockd_backend_device { uint64_t block_count; bool request_pending; bool waiting_completion; - uint64_t waiting_since_ms; /* timestamp when waiting started */ - bool backend_sick; /* backend marked unresponsive */ struct ipc_block_service_request pending_req; struct ipc_block_service_request queue[8]; size_t queue_head; @@ -31,18 +27,8 @@ struct blockd_backend_device { size_t queue_len; }; -/* Telemetry counters for diagnostics */ -struct blockd_telemetry { - uint64_t timeouts_fired; - uint64_t stale_responses; - uint64_t queue_full_events; - uint64_t backend_errors; - uint64_t requests_completed; -}; - #define BLOCKD_BACKEND_MAX_DEVICES 8 #define BLOCKD_BACKEND_QUEUE_DEPTH 8 -#define BLOCKD_BACKEND_TIMEOUT_MS 5000U /* 5 second timeout for backend responses */ #define BLOCKD_MAX(a, b) ((a) > (b) ? (a) : (b)) #define BLOCKD_PORTAL_BUF_MAX \ @@ -57,18 +43,7 @@ static struct ipc_block_service_request blockd_req; static struct ipc_block_service_response blockd_resp; static bool blockd_staged; static volatile int blockd_terminate; -static struct blockd_telemetry blockd_stats; -/* Get current time in milliseconds (monotonic) */ -static uint64_t -blockd_get_time_ms(void) -{ - struct timespec ts; - if (clock_gettime(CLOCK_MONOTONIC, &ts) != 0) - return 0; - return (uint64_t)ts.tv_sec * 1000ULL + (uint64_t)ts.tv_nsec / 1000000ULL; -} - static void blockd_handle_sigterm(int sig __attribute__((unused))) { @@ -99,8 +74,6 @@ static bool blockd_backend_queue_pop(struct blockd_bac 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 void blockd_handle_device_timeout(struct blockd_backend_device *dev); static void blockd_log(const char *msg) @@ -194,13 +167,10 @@ static void blockd_backend_init(void) { blockd_next_backend_id = 2; - memset(&blockd_stats, 0, sizeof(blockd_stats)); for (size_t i = 0; i < BLOCKD_BACKEND_MAX_DEVICES; i++) { blockd_backend_devices[i].in_use = false; blockd_backend_devices[i].request_pending = false; blockd_backend_devices[i].waiting_completion = false; - blockd_backend_devices[i].waiting_since_ms = 0; - blockd_backend_devices[i].backend_sick = false; blockd_backend_queue_reset(&blockd_backend_devices[i]); } } @@ -426,7 +396,6 @@ blockd_backend_handle_io_fetch(const struct ipc_block_ memcpy(resp.data, pending->data, resp.data_len); slot->request_pending = false; slot->waiting_completion = true; - slot->waiting_since_ms = blockd_get_time_ms(); #ifdef LENIX_DEBUG blockd_log_int("[blockd] backend fetch token=", (int)pending->token); @@ -448,91 +417,31 @@ blockd_backend_handle_io_response( { struct blockd_backend_device *slot; struct ipc_block_service_response out; - size_t max_expected; - size_t max_payload; - bool validation_failed = false; if (resp_pkt == NULL) return; slot = blockd_backend_find(resp_pkt->device_id); - if (slot == NULL) + if (slot == NULL || !slot->waiting_completion) return; - - /* Handle stale response (e.g., we already timed out this request) */ - if (!slot->waiting_completion) { - blockd_stats.stale_responses++; -#ifdef LENIX_DEBUG - blockd_log_int("[blockd] WARN: stale response for device=", - (int)resp_pkt->device_id); -#endif - return; - } - blockd_log_int("[blockd] backend response token=", (int)resp_pkt->token); if (resp_pkt->status != IPC_BLOCK_BACKEND_STATUS_OK) { blockd_log_hex64("[blockd] backend response error status=", (uint64_t)resp_pkt->status); - blockd_stats.backend_errors++; } - - /* Validate backend response before forwarding */ - max_expected = (size_t)slot->pending_req.blocks * slot->block_size; - max_payload = IPC_BLOCK_SERVICE_MAX_DATA; - - /* Validation checks for read responses */ - if ((slot->pending_req.flags & IPC_BLOCK_SERVICE_F_WRITE) == 0 && - resp_pkt->status == IPC_BLOCK_BACKEND_STATUS_OK) { - if (resp_pkt->data_len == 0 && slot->pending_req.blocks > 0) { - blockd_log("[blockd] ERROR: zero data_len for non-zero blocks"); - validation_failed = true; - } - if (resp_pkt->data_len > max_payload) { - blockd_log("[blockd] ERROR: data_len exceeds max payload"); - validation_failed = true; - } - if (resp_pkt->bytes_transferred > max_expected) { - blockd_log("[blockd] ERROR: bytes_transferred exceeds expected"); - validation_failed = true; - } - } - - /* If status is error but has data, ignore the data */ - if (resp_pkt->status != IPC_BLOCK_BACKEND_STATUS_OK && - (resp_pkt->data_len > 0 || resp_pkt->bytes_transferred > 0)) { -#ifdef LENIX_DEBUG - blockd_log("[blockd] WARN: error status with non-zero data, ignoring data"); -#endif - } - memset(&out, 0, sizeof(out)); out.token = slot->pending_req.token; - - if (validation_failed) { - out.status = -EIO; - out.bytes_transferred = 0; - out.data_len = 0; - blockd_stats.backend_errors++; - } else { - out.status = resp_pkt->status; - out.bytes_transferred = resp_pkt->bytes_transferred; - out.data_len = 0; - if ((slot->pending_req.flags & IPC_BLOCK_SERVICE_F_WRITE) == 0 && - resp_pkt->status == IPC_BLOCK_BACKEND_STATUS_OK && - resp_pkt->data_len > 0) { - /* Clamp copy length to avoid buffer overrun */ - uint32_t copy = resp_pkt->data_len; - if (copy > IPC_BLOCK_SERVICE_MAX_DATA) - copy = IPC_BLOCK_SERVICE_MAX_DATA; - memcpy(out.data, resp_pkt->data, copy); - out.data_len = copy; - } + out.status = resp_pkt->status; + out.bytes_transferred = resp_pkt->bytes_transferred; + out.data_len = 0; + if ((slot->pending_req.flags & IPC_BLOCK_SERVICE_F_WRITE) == 0 && + resp_pkt->data_len > 0) { + uint32_t copy = resp_pkt->data_len; + if (copy > IPC_BLOCK_SERVICE_MAX_DATA) + copy = IPC_BLOCK_SERVICE_MAX_DATA; + memcpy(out.data, resp_pkt->data, copy); + out.data_len = copy; } - slot->waiting_completion = false; - slot->waiting_since_ms = 0; - slot->backend_sick = false; /* Backend responded, mark healthy */ - blockd_stats.requests_completed++; - #ifdef LENIX_DEBUG blockd_log_int("[blockd] backend response token=", (int)slot->pending_req.token); @@ -599,66 +508,6 @@ blockd_handle_backend_message(const uint8_t *buf, size } } -/* - * Handle timeout for a device that has been waiting too long for backend response. - * Sends synthetic ETIMEDOUT response to the original client. - */ -static void -blockd_handle_device_timeout(struct blockd_backend_device *dev) -{ - struct ipc_block_service_response out; - - if (dev == NULL || !dev->waiting_completion) - return; - - blockd_stats.timeouts_fired++; - blockd_log_int("[blockd] TIMEOUT: device=", (int)dev->device_id); - blockd_log_int("[blockd] TIMEOUT: pending token=", - (int)dev->pending_req.token); - - /* Build synthetic failure response */ - memset(&out, 0, sizeof(out)); - out.token = dev->pending_req.token; - out.status = -ETIMEDOUT; - out.bytes_transferred = 0; - out.data_len = 0; - - /* Clear waiting state */ - dev->waiting_completion = false; - dev->waiting_since_ms = 0; - dev->backend_sick = true; /* Mark backend as potentially sick */ - - /* Respond to client with timeout error */ - block_service_respond(&out); - - /* Try to process next queued request */ - blockd_backend_promote_queued(dev); -} - -/* - * Check all devices for timeout conditions. - * Called periodically from main loop. - */ -static void -blockd_check_device_timeouts(void) -{ - uint64_t now = blockd_get_time_ms(); - - for (size_t i = 0; i < BLOCKD_BACKEND_MAX_DEVICES; i++) { - struct blockd_backend_device *dev = &blockd_backend_devices[i]; - uint64_t elapsed; - - if (!dev->in_use || !dev->waiting_completion) - continue; - if (dev->waiting_since_ms == 0) - continue; - - elapsed = now - dev->waiting_since_ms; - if (elapsed > BLOCKD_BACKEND_TIMEOUT_MS) - blockd_handle_device_timeout(dev); - } -} - int main(int argc, char **argv, char **envp) { @@ -666,7 +515,6 @@ main(int argc, char **argv, char **envp) bool staged = srv_should_stage(); uint32_t gen = 0; struct sigaction sa; - uint64_t last_timeout_check_ms = 0; (void)argc; (void)argv; (void)envp; @@ -737,20 +585,10 @@ main(int argc, char **argv, char **envp) static uint8_t portal_buf[BLOCKD_PORTAL_BUF_MAX]; while (1) { - uint64_t now_ms; - if (blockd_terminate) { blockd_log("[blockd] SIGTERM received, exiting cleanly"); return 0; } - - /* Periodic timeout check (~100ms intervals) */ - now_ms = blockd_get_time_ms(); - if (now_ms - last_timeout_check_ms > 100) { - blockd_check_device_timeouts(); - last_timeout_check_ms = now_ms; - } - ssize_t n = portal_recv(portal_buf, sizeof(portal_buf)); if (n <= 0) continue; @@ -766,10 +604,9 @@ main(int argc, char **argv, char **envp) struct blockd_backend_device *backend = blockd_backend_find(blockd_req.device); if (backend != NULL) { if (!blockd_backend_queue_request(backend, &blockd_req)) { - blockd_stats.queue_full_events++; memset(&blockd_resp, 0, sizeof(blockd_resp)); blockd_resp.token = blockd_req.token; - blockd_resp.status = -EBUSY; + blockd_resp.status = -16; /* EBUSY */ blockd_resp.bytes_transferred = 0; blockd_resp.data_len = 0; block_service_respond(&blockd_resp); @@ -778,7 +615,7 @@ main(int argc, char **argv, char **envp) } memset(&blockd_resp, 0, sizeof(blockd_resp)); blockd_resp.token = blockd_req.token; - blockd_resp.status = -ENXIO; + blockd_resp.status = -6; /* ENXIO */ blockd_resp.bytes_transferred = 0; blockd_resp.data_len = 0; block_service_respond(&blockd_resp); blob - bf708e59d4666464ef48da1ba5655b227d6c3686 blob + b518395d87e6688d7d6fe0cd158bacba5ca22d6f --- servers/fs/ext2/main.c +++ servers/fs/ext2/main.c @@ -255,23 +255,13 @@ static int block_read_sectors(uint64_t lba, uint32_t c static uint32_t ext2_select_device(void) { - struct ipc_block_info info; struct ipc_block_info ramdisk; - /* Prefer virtio-blk (device 1) if available and sane; otherwise fall back to ramdisk (device 2). */ - if (block_get_info(1, &info) == 0 && info.block_count > 0 && - info.block_size == EXT2_SECTOR_SIZE) { - ext2_device_id = info.device; - ext2_device_block_size = info.block_size; - ext2_device_block_count = info.block_count; - ext2_log_device(ext2_device_id); - #ifdef LENIX_DEBUG - puts("[ext2] device selection complete (virtio-blk)"); - #endif - return ext2_device_id; - } - - /* Fall back to ramdisk backend (device 2) for stability. */ + /* + * Debug: force ramdisk (device 2). We keep virtio-blk disabled here + * until device numbering stabilises; blockd currently assigns IDs + * starting at 2 (ramdisk=2, virtio-blk=3). + */ if (block_get_info(2, &ramdisk) != 0) { puts("[ext2] ERROR: block_get_info(2) failed"); return EXT2_DEVICE_INVALID; @@ -1405,7 +1395,7 @@ ext2_register_with_namesvc(portal_handle_t bootstrap) if (namesvc != IPC_PORTAL_INVALID_HANDLE) { rc = namesvc_register(namesvc, "fs.ext2", bootstrap, IPC_PORTAL_RIGHT_SEND, flags); -#ifdef LENIX_DEBUG +#if defined(LENIX_DEBUG) || defined(LENIX_DEBUG_EXIT) { char buf[64]; size_t idx = 0; @@ -1418,6 +1408,9 @@ ext2_register_with_namesvc(portal_handle_t bootstrap) } #endif if (rc == 0) { +#ifdef LENIX_DEBUG_EXIT + puts("[ext2] namesvc_register success"); +#endif portal_revoke(namesvc); return; } @@ -1425,7 +1418,7 @@ ext2_register_with_namesvc(portal_handle_t bootstrap) portal_revoke(namesvc); } if ((attempt % 100) == 0) { -#ifdef LENIX_DEBUG +#if defined(LENIX_DEBUG) || defined(LENIX_DEBUG_EXIT) puts("[ext2] waiting for namesvc to register..."); #endif }