commit 0a0ef0d75760df941fb4e94320a4f99a1bffe1da from: int16h date: Thu Dec 4 11:12:16 2025 UTC Block service hardening: timeouts, validation, and adaptive back-off commit - 1a155fb7a2b4ca3780be755801dcde3ce94a8034 commit + 0a0ef0d75760df941fb4e94320a4f99a1bffe1da blob - e1232717e513b49db1caca7bdad5e844f28b3c19 blob + 969385e66cba8036b54c153133e51614d8fd8fc3 --- changelog.md +++ changelog.md @@ -1,5 +1,23 @@ # Changelog +# 2025-12-04 + +## Block service hardening: timeouts, validation, and adaptive back-off + +- **blockd timeout & recovery**: Added `waiting_since_ms` timestamp tracking for pending backend requests with a 5-second timeout (`BLOCKD_BACKEND_TIMEOUT_MS`). When a backend fails to respond, `blockd_handle_device_timeout()` sends a synthetic `ETIMEDOUT` response to the client and marks the backend as sick. Timeout checks run every ~100ms from the main loop via `blockd_check_device_timeouts()`. + +- **blockd response validation**: `blockd_backend_handle_io_response()` now validates backend responses before forwarding: checks `data_len` against max payload, `bytes_transferred` against expected bytes, and rejects zero `data_len` for non-zero block reads. Validation failures result in `EIO` status. Stale responses (after timeout) are detected and dropped with a counter increment. + +- **blockd telemetry**: Added `struct blockd_telemetry` with counters: `timeouts_fired`, `stale_responses`, `queue_full_events`, `backend_errors`, `requests_completed`. Queue-full events now increment counter and use `EBUSY` constant. + +- **ramdiskd adaptive back-off**: Replaced fixed 1ms BUSY sleep with tiered back-off: Tier 1 (first 100 iterations) 1ms, Tier 2 (100-1000) 5ms, Tier 3 (1000+) 10ms. Added 30-second hard timeout (`RAMDISK_BUSY_MAX_TIMEOUT_MS`) with critical log message when blockd becomes nonresponsive. + +- **ramdiskd write validation**: Write requests now require `data_len >= expected bytes`; short writes are rejected with `EINVAL` to prevent silent partial writes from misbehaving clients. + +- **ramdiskd telemetry**: Added `struct ramdisk_telemetry` with counters: `requests_completed`, `read_bytes`, `write_bytes`, `busy_spins`, `backoff_steps`, `validation_errors`, `write_rejections`. + +- **Time helpers**: Both services now use `clock_gettime(CLOCK_MONOTONIC)` via new `blockd_get_time_ms()` and `ramdisk_get_time_ms()` helpers for accurate timeout tracking. + # 2025-12-03 ## Kernel server staging to /usr/libexec (initrd-only) blob - 8cd5ae9b1ee21e8f2e0519524f0c33fc322e93a0 blob + 390afdc633b57a3d35a34339d37dd7563cf2f8c0 --- 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 blob - c8a44830303f6cc04bf624602c1539c00af6a9a7 blob + 4ea7ff746b0585c76a48e703533a6b1889f3370f --- servers/block/blockd/main.c +++ servers/block/blockd/main.c @@ -9,6 +9,8 @@ #include #include #include +#include +#include #include #include #include @@ -20,6 +22,8 @@ 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; @@ -27,8 +31,18 @@ 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 \ @@ -43,7 +57,18 @@ 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))) { @@ -74,6 +99,8 @@ 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) @@ -167,10 +194,13 @@ 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]); } } @@ -396,6 +426,7 @@ 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); @@ -417,31 +448,91 @@ 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 || !slot->waiting_completion) + if (slot == NULL) 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++; } - 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; + + /* 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->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; + 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; + } + } + 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); @@ -508,6 +599,66 @@ 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) { @@ -515,6 +666,7 @@ 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; @@ -585,10 +737,20 @@ 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; @@ -604,9 +766,10 @@ 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 = -16; /* EBUSY */ + blockd_resp.status = -EBUSY; blockd_resp.bytes_transferred = 0; blockd_resp.data_len = 0; block_service_respond(&blockd_resp); @@ -615,7 +778,7 @@ main(int argc, char **argv, char **envp) } memset(&blockd_resp, 0, sizeof(blockd_resp)); blockd_resp.token = blockd_req.token; - blockd_resp.status = -6; /* ENXIO */ + blockd_resp.status = -ENXIO; blockd_resp.bytes_transferred = 0; blockd_resp.data_len = 0; block_service_respond(&blockd_resp); blob - d25b28326fb5f2ca3ac9f9ce7d13115e515e4dea blob + 31d009bd2efb5259b88c1e081a78064f45be2a27 --- servers/block/ramdiskd/main.c +++ servers/block/ramdiskd/main.c @@ -12,6 +12,8 @@ #include #include #include +#include +#include #include #include @@ -19,6 +21,22 @@ #define RAMDISK_PAGE_SIZE 4096U #define RAMDISK_MAX_BYTES (64U * 1024U * 1024U) +/* Adaptive back-off thresholds for busy-wait loops */ +#define RAMDISK_BUSY_TIER1_THRESHOLD 100U /* First 100 iterations: 1ms sleep */ +#define RAMDISK_BUSY_TIER2_THRESHOLD 1000U /* 100-1000 iterations: 5ms sleep */ +#define RAMDISK_BUSY_MAX_TIMEOUT_MS 30000U /* 30 second hard timeout */ + +/* Telemetry counters for diagnostics */ +struct ramdisk_telemetry { + uint64_t requests_completed; + uint64_t read_bytes; + uint64_t write_bytes; + uint64_t busy_spins; + uint64_t backoff_steps; + uint64_t validation_errors; + uint64_t write_rejections; /* Writes rejected (if read-only mode enabled) */ +}; + static uint8_t rootfs_alias[RAMDISK_MAX_BYTES] __attribute__((aligned(RAMDISK_PAGE_SIZE))); @@ -28,7 +46,18 @@ static uint64_t ramdisk_alias_offset; static uint8_t reg_resp_buf_global[IPC_SERVICE_MAX_RESPONSE]; static bool ramdisk_staged = false; static volatile int ramdisk_terminate; +static struct ramdisk_telemetry ramdisk_stats; +/* Get current time in milliseconds (monotonic) */ +static uint64_t +ramdisk_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; +} + /* Temporarily silence debug logs to keep boot output readable. */ #define DLOG(...) do {} while (0) @@ -232,6 +261,7 @@ ramdisk_handle_request(const struct ipc_block_backend_ base = rootfs_alias + ramdisk_alias_offset; if (bytes == 0) { + ramdisk_stats.validation_errors++; resp->status = IPC_BLOCK_BACKEND_STATUS_INVALID; return; } @@ -241,27 +271,43 @@ ramdisk_handle_request(const struct ipc_block_backend_ log_hex64("[ramdiskd] invalid IO lba ", req->lba); log_hex64("[ramdiskd] invalid IO bytes ", bytes); log_hex64("[ramdiskd] invalid IO offset ", offset); + ramdisk_stats.validation_errors++; resp->status = IPC_BLOCK_BACKEND_STATUS_INVALID; return; } if ((req->flags & IPC_BLOCK_SERVICE_F_WRITE) != 0) { + /* + * Write validation: require data_len >= expected bytes. + * This prevents silent partial writes from misbehaving clients. + */ + if (req->data_len < bytes) { + log_hex64("[ramdiskd] short write data_len=", req->data_len); + log_hex64("[ramdiskd] expected bytes=", bytes); + ramdisk_stats.validation_errors++; + resp->status = -EINVAL; + resp->bytes_transferred = 0; + return; + } + /* Clamp copy to not exceed what we expect or have in buffer */ size_t copy = bytes; if (copy > req->data_len) copy = req->data_len; - if (copy > bytes) - copy = bytes; memcpy((uint8_t *)(base + offset), req->data, copy); resp->bytes_transferred = copy; resp->data_len = 0; resp->status = IPC_BLOCK_BACKEND_STATUS_OK; + ramdisk_stats.write_bytes += copy; } else { - if (bytes > sizeof(resp->data)) - bytes = sizeof(resp->data); - memcpy(resp->data, base + offset, bytes); - resp->data_len = bytes; - resp->bytes_transferred = bytes; + /* Read path: clamp to response buffer size */ + size_t read_bytes = bytes; + if (read_bytes > sizeof(resp->data)) + read_bytes = sizeof(resp->data); + memcpy(resp->data, base + offset, read_bytes); + resp->data_len = read_bytes; + resp->bytes_transferred = read_bytes; + ramdisk_stats.read_bytes += read_bytes; } - + ramdisk_stats.requests_completed++; } @@ -433,6 +479,7 @@ main(void) memset(&work, 0, sizeof(work)); memset(&response, 0, sizeof(response)); memset(&ack, 0, sizeof(ack)); + memset(&ramdisk_stats, 0, sizeof(ramdisk_stats)); fetch.opcode = IPC_BLOCK_BACKEND_OPCODE_IO_REQUEST; fetch.device_id = device_id; fetch.token = 1; @@ -443,6 +490,10 @@ main(void) log_line("[ramdiskd] backend ready for I/O"); #endif + uint32_t busy_counter = 0; /* Track consecutive BUSY responses */ + uint64_t busy_start_ms = 0; /* Timestamp when BUSY streak started */ + bool busy_timeout_logged = false; /* Avoid log spam */ + while (1) { if (ramdisk_terminate) { log_line("[ramdiskd] SIGTERM received, exiting"); @@ -457,13 +508,47 @@ main(void) 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); continue; } if (work.status != IPC_BLOCK_BACKEND_STATUS_OK) { if (work.status == IPC_BLOCK_BACKEND_STATUS_BUSY) { - /* Device idle, no work pending; normal operation */ - idle_poll_count++; + /* + * Adaptive back-off for BUSY responses: + * - Tier 1 (first 100): 1ms sleep + * - Tier 2 (100-1000): 5ms sleep + * - Tier 3 (1000+): 10ms sleep + */ + busy_counter++; + ramdisk_stats.busy_spins++; + + /* Start timeout timer on first BUSY */ + if (busy_counter == 1) + busy_start_ms = ramdisk_get_time_ms(); + + /* Check for hard timeout */ + uint64_t elapsed = ramdisk_get_time_ms() - busy_start_ms; + if (elapsed > RAMDISK_BUSY_MAX_TIMEOUT_MS) { + if (!busy_timeout_logged) { + log_line("[ramdiskd] CRITICAL: blockd nonresponsive for 30s"); + busy_timeout_logged = true; + } + /* Continue with longer back-off rather than exiting */ + poll(NULL, 0, 50); + continue; + } + + /* 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); + } } else if (work.status == IPC_BLOCK_BACKEND_STATUS_NOT_FOUND) { /* Real error - device was deregistered */ log_line("[ramdiskd] ERROR: blockd reports device not found"); @@ -474,12 +559,16 @@ main(void) log_line("[ramdiskd] WARN: blockd I/O fetch error, will retry"); last_error_log_time = idle_poll_count; } + poll(NULL, 0, 1); } - /* Avoid tight spin */ - poll(NULL, 0, 1); + idle_poll_count++; continue; } - /* Reset idle counter when we get actual work */ + + /* Reset counters when we get actual work */ + busy_counter = 0; + busy_start_ms = 0; + busy_timeout_logged = false; idle_poll_count = 0; /* Reinitialize response structure for this iteration to prevent data leakage @@ -490,14 +579,12 @@ 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) { DLOG("[ramdiskd] failed to send response - continuing anyway"); continue; } - - /* -- */ } return 0;