fix(hook): raise + env-configure the augment deadline, breadcrumb on fire

The 300ms in-process SIGALRM budget in hook-augment self-terminated
with a silent _exit(0) on real cold starts (SQLite/mmap open under
load), so PreToolUse augmentation never appeared in real sessions
(reporter: 0/24 observed) while warm manual invocations worked - and a
fired deadline was indistinguishable from a legitimate no-match run.

Default budget is now 2000ms (the settings.json hook timeout stays the
outer backstop), overridable via CBM_HOOK_DEADLINE_MS (clamped
50..10000). When the deadline fires, the handler write()s a
pre-formatted breadcrumb (deadline, pid, the env knob to raise) to
~/.cache/codebase-memory-mcp/logs/hook-augment-timeouts.log before
exiting - fd and message are prepared at arm time so the handler stays
async-signal-safe; CBM_HOOK_TIMEOUT_LOG overrides the path for tests.
Windows keeps relying on the settings.json timeout (unchanged no-op).

Deterministic reproduction: stdin is a pipe whose writer never sends,
so the read blocks past a 60ms deadline - the timer must fire, exit 0
(fail-open), and leave the breadcrumb. RED before (no breadcrumb),
GREEN after.

Closes #858

Signed-off-by: Martin Vogel <martin.vogel.tech@gmail.com>
This commit is contained in:
Martin Vogel
2026-07-12 19:06:47 +02:00
parent db330bf3a0
commit 39ffb97ceb
2 changed files with 147 additions and 6 deletions
+72 -6
View File
@@ -17,6 +17,8 @@
*/
#include "cli/cli.h"
#include "foundation/compat_fs.h"
#include "foundation/constants.h"
#include "foundation/mem.h"
#include "mcp/mcp.h"
#include "pipeline/pipeline.h"
@@ -29,6 +31,7 @@
#include <string.h>
#ifndef _WIN32
#include <fcntl.h>
#include <signal.h>
#include <sys/time.h>
#include <unistd.h>
@@ -38,21 +41,84 @@
#define HA_MIN_TOKEN 4 /* skip short/noisy patterns before any work */
#define HA_MAX_TOKEN 96
#define HA_RESULT_LIMIT 5
#define HA_MAX_WALKUP 8 /* cwd may be a subdir of the indexed root */
#define HA_DEADLINE_MS 300 /* hard in-process budget (see also: the */
/* settings.json "timeout" backstop) */
#define HA_MAX_WALKUP 8 /* cwd may be a subdir of the indexed root */
#define HA_DEADLINE_DEFAULT_MS 2000 /* in-process budget; see ha_deadline_ms() */
#define HA_DEADLINE_MIN_MS 50
#define HA_DEADLINE_MAX_MS 10000
/* #858: the original 300ms budget silently self-terminated on real cold
* starts (SQLite/mmap open under load), so augmentation never appeared in
* real sessions (0/24 observed) while manual warm invocations worked. The
* budget is now generous by default and env-configurable; the settings.json
* hook "timeout" remains the outer backstop. */
static int ha_deadline_ms(void) {
const char *env = getenv("CBM_HOOK_DEADLINE_MS");
if (!env || !env[0]) {
return HA_DEADLINE_DEFAULT_MS;
}
int v = atoi(env);
if (v < HA_DEADLINE_MIN_MS) {
return HA_DEADLINE_MIN_MS;
}
if (v > HA_DEADLINE_MAX_MS) {
return HA_DEADLINE_MAX_MS;
}
return v;
}
/* ── Hard deadline ────────────────────────────────────────────────
* A slow SQLite open or query must never stall the agent. When the timer
* fires we _exit(0) immediately. Output is written exactly once at the very
* end, so firing mid-work simply yields a clean no-op (no partial JSON). */
* end, so firing mid-work simply yields a clean no-op (no partial JSON).
*
* Observability (#858): a fired deadline is otherwise indistinguishable from
* "no matches", so the handler first write()s a pre-formatted breadcrumb to
* ~/.cache/codebase-memory-mcp/logs/hook-augment-timeouts.log (fd and message
* prepared at arm time — only async-signal-safe write/_exit in the handler). */
#ifndef _WIN32
static int g_ha_crumb_fd = -1;
static char g_ha_crumb_msg[160];
static size_t g_ha_crumb_len = 0;
static void ha_deadline_exit(int sig) {
(void)sig;
if (g_ha_crumb_fd >= 0 && g_ha_crumb_len > 0) {
ssize_t w = write(g_ha_crumb_fd, g_ha_crumb_msg, g_ha_crumb_len);
(void)w;
}
_exit(0);
}
static void ha_open_crumb_log(int deadline_ms) {
const char *override = getenv("CBM_HOOK_TIMEOUT_LOG"); /* tests + power users */
char path[CBM_SZ_1K];
if (override && override[0]) {
snprintf(path, sizeof(path), "%s", override);
} else {
const char *home = getenv("HOME");
if (!home || !home[0]) {
return;
}
char dir[CBM_SZ_1K];
snprintf(dir, sizeof(dir), "%s/.cache/codebase-memory-mcp/logs", home);
cbm_mkdir_p(dir, 0755);
snprintf(path, sizeof(path), "%s/hook-augment-timeouts.log", dir);
}
g_ha_crumb_fd = open(path, O_WRONLY | O_CREAT | O_APPEND, 0644);
if (g_ha_crumb_fd < 0) {
return;
}
int n = snprintf(g_ha_crumb_msg, sizeof(g_ha_crumb_msg),
"hook-augment: deadline_exceeded ms=%d pid=%ld (raise via "
"CBM_HOOK_DEADLINE_MS)\n",
deadline_ms, (long)getpid());
g_ha_crumb_len = (n > 0 && n < (int)sizeof(g_ha_crumb_msg)) ? (size_t)n : 0;
}
static void ha_arm_deadline(void) {
int ms = ha_deadline_ms();
ha_open_crumb_log(ms);
struct sigaction sa;
memset(&sa, 0, sizeof(sa));
sa.sa_handler = ha_deadline_exit;
@@ -60,8 +126,8 @@ static void ha_arm_deadline(void) {
struct itimerval it;
memset(&it, 0, sizeof(it));
it.it_value.tv_sec = HA_DEADLINE_MS / 1000;
it.it_value.tv_usec = (HA_DEADLINE_MS % 1000) * 1000;
it.it_value.tv_sec = ms / 1000;
it.it_value.tv_usec = (ms % 1000) * 1000;
setitimer(ITIMER_REAL, &it, NULL);
}
#else
+75
View File
@@ -20,6 +20,9 @@
#include <stdio.h>
#include <sys/stat.h>
#include <unistd.h>
#ifndef _WIN32
#include <sys/wait.h>
#endif
#include <errno.h>
#include <zlib.h>
@@ -2480,6 +2483,77 @@ TEST(cli_hook_augment_path_is_abs) {
PASS();
}
/* #858: a fired hook-augment deadline used to be a SILENT _exit(0) —
* indistinguishable from "no matches" — and the 300ms default self-terminated
* on real cold starts, so augmentation never appeared in real sessions
* (0/24 observed). The deadline is now env-configurable
* (CBM_HOOK_DEADLINE_MS, generous default) and a fired deadline leaves an
* observable breadcrumb in a local log. Deterministic reproduction: stdin is
* a pipe with a live writer that never sends data, so ha_read_stdin blocks
* past a 60ms deadline and the timer must fire, breadcrumb, and _exit(0). */
TEST(cli_hook_augment_deadline_breadcrumb_issue858) {
#ifdef _WIN32
SKIP_PLATFORM("in-process SIGALRM deadline is POSIX-only (settings.json timeout on Windows)");
#else
char tmpdir[256];
snprintf(tmpdir, sizeof(tmpdir), "/tmp/cli-hookdl-XXXXXX");
if (!cbm_mkdtemp(tmpdir))
FAIL("cbm_mkdtemp failed");
char logpath[512];
snprintf(logpath, sizeof(logpath), "%s/timeouts.log", tmpdir);
int fds[2];
if (pipe(fds) != 0) {
test_rmdir_r(tmpdir);
FAIL("pipe failed");
}
fflush(NULL);
pid_t pid = fork();
if (pid == 0) {
/* Child: hook-augment with a 60ms deadline and stdin that blocks
* forever (parent keeps the write end open, sends nothing). */
close(fds[1]);
dup2(fds[0], 0);
close(fds[0]);
setenv("CBM_HOOK_DEADLINE_MS", "60", 1);
setenv("CBM_HOOK_TIMEOUT_LOG", logpath, 1);
alarm(10); /* backstop: never hang the suite */
_exit(cbm_cmd_hook_augment());
}
ASSERT_GT(pid, 0);
close(fds[0]);
int status = 0;
waitpid(pid, &status, 0);
close(fds[1]);
/* The deadline must have fired as a clean exit 0 (fail-open, no signal). */
ASSERT(WIFEXITED(status));
ASSERT_EQ(WEXITSTATUS(status), 0);
/* RED before the fix: no breadcrumb existed — a fired deadline was
* indistinguishable from a no-match run. GREEN: the log names the
* deadline and the knob. */
FILE *f = fopen(logpath, "r");
if (!f) {
fprintf(stderr, " [858] FAIL no timeout breadcrumb written to %s\n", logpath);
}
ASSERT_NOT_NULL(f);
char line[256] = "";
char *got = fgets(line, sizeof(line), f);
fclose(f);
ASSERT_NOT_NULL(got);
ASSERT(strstr(line, "deadline_exceeded") != NULL);
ASSERT(strstr(line, "CBM_HOOK_DEADLINE_MS") != NULL);
cbm_unsetenv("CBM_HOOK_DEADLINE_MS");
cbm_unsetenv("CBM_HOOK_TIMEOUT_LOG");
test_rmdir_r(tmpdir);
PASS();
#endif
}
TEST(cli_upsert_claude_hook_existing) {
char tmpdir[256];
snprintf(tmpdir, sizeof(tmpdir), "/tmp/cli-hook-XXXXXX");
@@ -3211,6 +3285,7 @@ SUITE(cli) {
/* Claude Code hooks (5 tests — group D) */
RUN_TEST(cli_hook_gate_script_no_predictable_tmp_issue384);
RUN_TEST(cli_hook_augment_path_is_abs);
RUN_TEST(cli_hook_augment_deadline_breadcrumb_issue858);
RUN_TEST(cli_upsert_claude_hook_fresh);
RUN_TEST(cli_upsert_claude_hook_existing);
RUN_TEST(cli_upsert_claude_hook_replace);