commit - 1a155fb7a2b4ca3780be755801dcde3ce94a8034
commit + 0a0ef0d75760df941fb4e94320a4f99a1bffe1da
blob - e1232717e513b49db1caca7bdad5e844f28b3c19
blob + 969385e66cba8036b54c153133e51614d8fd8fc3
--- changelog.md
+++ changelog.md
# 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
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
#include <lenix/server.h>
#include <lenix/signal.h>
#include <lenix/namesvc_client.h>
+#include <lenix/time.h>
+#include <lenix/errno.h>
#include <ipc/block_protocol.h>
#include <ipc/block_backend.h>
#include <stdbool.h>
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;
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 \
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)))
{
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)
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]);
}
}
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);
{
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);
}
}
+/*
+ * 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)
{
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;
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;
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);
}
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
#include <lenix/namesvc_client.h>
#include <lenix/server.h>
#include <lenix/signal.h>
+#include <lenix/time.h>
+#include <lenix/errno.h>
#include <ipc/block_backend.h>
#include <ipc/block_protocol.h>
#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)));
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)
base = rootfs_alias + ramdisk_alias_offset;
if (bytes == 0) {
+ ramdisk_stats.validation_errors++;
resp->status = IPC_BLOCK_BACKEND_STATUS_INVALID;
return;
}
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++;
}
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;
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");
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");
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
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;
