Skip to content

Commit 39ffb97

Browse files
committed
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>
1 parent db330bf commit 39ffb97

2 files changed

Lines changed: 147 additions & 6 deletions

File tree

src/cli/hook_augment.c

Lines changed: 72 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -17,6 +17,8 @@
1717
*/
1818

1919
#include "cli/cli.h"
20+
#include "foundation/compat_fs.h"
21+
#include "foundation/constants.h"
2022
#include "foundation/mem.h"
2123
#include "mcp/mcp.h"
2224
#include "pipeline/pipeline.h"
@@ -29,6 +31,7 @@
2931
#include <string.h>
3032

3133
#ifndef _WIN32
34+
#include <fcntl.h>
3235
#include <signal.h>
3336
#include <sys/time.h>
3437
#include <unistd.h>
@@ -38,30 +41,93 @@
3841
#define HA_MIN_TOKEN 4 /* skip short/noisy patterns before any work */
3942
#define HA_MAX_TOKEN 96
4043
#define HA_RESULT_LIMIT 5
41-
#define HA_MAX_WALKUP 8 /* cwd may be a subdir of the indexed root */
42-
#define HA_DEADLINE_MS 300 /* hard in-process budget (see also: the */
43-
/* settings.json "timeout" backstop) */
44+
#define HA_MAX_WALKUP 8 /* cwd may be a subdir of the indexed root */
45+
#define HA_DEADLINE_DEFAULT_MS 2000 /* in-process budget; see ha_deadline_ms() */
46+
#define HA_DEADLINE_MIN_MS 50
47+
#define HA_DEADLINE_MAX_MS 10000
48+
49+
/* #858: the original 300ms budget silently self-terminated on real cold
50+
* starts (SQLite/mmap open under load), so augmentation never appeared in
51+
* real sessions (0/24 observed) while manual warm invocations worked. The
52+
* budget is now generous by default and env-configurable; the settings.json
53+
* hook "timeout" remains the outer backstop. */
54+
static int ha_deadline_ms(void) {
55+
const char *env = getenv("CBM_HOOK_DEADLINE_MS");
56+
if (!env || !env[0]) {
57+
return HA_DEADLINE_DEFAULT_MS;
58+
}
59+
int v = atoi(env);
60+
if (v < HA_DEADLINE_MIN_MS) {
61+
return HA_DEADLINE_MIN_MS;
62+
}
63+
if (v > HA_DEADLINE_MAX_MS) {
64+
return HA_DEADLINE_MAX_MS;
65+
}
66+
return v;
67+
}
4468

4569
/* ── Hard deadline ────────────────────────────────────────────────
4670
* A slow SQLite open or query must never stall the agent. When the timer
4771
* fires we _exit(0) immediately. Output is written exactly once at the very
48-
* end, so firing mid-work simply yields a clean no-op (no partial JSON). */
72+
* end, so firing mid-work simply yields a clean no-op (no partial JSON).
73+
*
74+
* Observability (#858): a fired deadline is otherwise indistinguishable from
75+
* "no matches", so the handler first write()s a pre-formatted breadcrumb to
76+
* ~/.cache/codebase-memory-mcp/logs/hook-augment-timeouts.log (fd and message
77+
* prepared at arm time — only async-signal-safe write/_exit in the handler). */
4978
#ifndef _WIN32
79+
static int g_ha_crumb_fd = -1;
80+
static char g_ha_crumb_msg[160];
81+
static size_t g_ha_crumb_len = 0;
82+
5083
static void ha_deadline_exit(int sig) {
5184
(void)sig;
85+
if (g_ha_crumb_fd >= 0 && g_ha_crumb_len > 0) {
86+
ssize_t w = write(g_ha_crumb_fd, g_ha_crumb_msg, g_ha_crumb_len);
87+
(void)w;
88+
}
5289
_exit(0);
5390
}
5491

92+
static void ha_open_crumb_log(int deadline_ms) {
93+
const char *override = getenv("CBM_HOOK_TIMEOUT_LOG"); /* tests + power users */
94+
char path[CBM_SZ_1K];
95+
if (override && override[0]) {
96+
snprintf(path, sizeof(path), "%s", override);
97+
} else {
98+
const char *home = getenv("HOME");
99+
if (!home || !home[0]) {
100+
return;
101+
}
102+
char dir[CBM_SZ_1K];
103+
snprintf(dir, sizeof(dir), "%s/.cache/codebase-memory-mcp/logs", home);
104+
cbm_mkdir_p(dir, 0755);
105+
snprintf(path, sizeof(path), "%s/hook-augment-timeouts.log", dir);
106+
}
107+
g_ha_crumb_fd = open(path, O_WRONLY | O_CREAT | O_APPEND, 0644);
108+
if (g_ha_crumb_fd < 0) {
109+
return;
110+
}
111+
int n = snprintf(g_ha_crumb_msg, sizeof(g_ha_crumb_msg),
112+
"hook-augment: deadline_exceeded ms=%d pid=%ld (raise via "
113+
"CBM_HOOK_DEADLINE_MS)\n",
114+
deadline_ms, (long)getpid());
115+
g_ha_crumb_len = (n > 0 && n < (int)sizeof(g_ha_crumb_msg)) ? (size_t)n : 0;
116+
}
117+
55118
static void ha_arm_deadline(void) {
119+
int ms = ha_deadline_ms();
120+
ha_open_crumb_log(ms);
121+
56122
struct sigaction sa;
57123
memset(&sa, 0, sizeof(sa));
58124
sa.sa_handler = ha_deadline_exit;
59125
sigaction(SIGALRM, &sa, NULL);
60126

61127
struct itimerval it;
62128
memset(&it, 0, sizeof(it));
63-
it.it_value.tv_sec = HA_DEADLINE_MS / 1000;
64-
it.it_value.tv_usec = (HA_DEADLINE_MS % 1000) * 1000;
129+
it.it_value.tv_sec = ms / 1000;
130+
it.it_value.tv_usec = (ms % 1000) * 1000;
65131
setitimer(ITIMER_REAL, &it, NULL);
66132
}
67133
#else

tests/test_cli.c

Lines changed: 75 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -20,6 +20,9 @@
2020
#include <stdio.h>
2121
#include <sys/stat.h>
2222
#include <unistd.h>
23+
#ifndef _WIN32
24+
#include <sys/wait.h>
25+
#endif
2326
#include <errno.h>
2427
#include <zlib.h>
2528

@@ -2480,6 +2483,77 @@ TEST(cli_hook_augment_path_is_abs) {
24802483
PASS();
24812484
}
24822485

2486+
/* #858: a fired hook-augment deadline used to be a SILENT _exit(0) —
2487+
* indistinguishable from "no matches" — and the 300ms default self-terminated
2488+
* on real cold starts, so augmentation never appeared in real sessions
2489+
* (0/24 observed). The deadline is now env-configurable
2490+
* (CBM_HOOK_DEADLINE_MS, generous default) and a fired deadline leaves an
2491+
* observable breadcrumb in a local log. Deterministic reproduction: stdin is
2492+
* a pipe with a live writer that never sends data, so ha_read_stdin blocks
2493+
* past a 60ms deadline and the timer must fire, breadcrumb, and _exit(0). */
2494+
TEST(cli_hook_augment_deadline_breadcrumb_issue858) {
2495+
#ifdef _WIN32
2496+
SKIP_PLATFORM("in-process SIGALRM deadline is POSIX-only (settings.json timeout on Windows)");
2497+
#else
2498+
char tmpdir[256];
2499+
snprintf(tmpdir, sizeof(tmpdir), "/tmp/cli-hookdl-XXXXXX");
2500+
if (!cbm_mkdtemp(tmpdir))
2501+
FAIL("cbm_mkdtemp failed");
2502+
char logpath[512];
2503+
snprintf(logpath, sizeof(logpath), "%s/timeouts.log", tmpdir);
2504+
2505+
int fds[2];
2506+
if (pipe(fds) != 0) {
2507+
test_rmdir_r(tmpdir);
2508+
FAIL("pipe failed");
2509+
}
2510+
2511+
fflush(NULL);
2512+
pid_t pid = fork();
2513+
if (pid == 0) {
2514+
/* Child: hook-augment with a 60ms deadline and stdin that blocks
2515+
* forever (parent keeps the write end open, sends nothing). */
2516+
close(fds[1]);
2517+
dup2(fds[0], 0);
2518+
close(fds[0]);
2519+
setenv("CBM_HOOK_DEADLINE_MS", "60", 1);
2520+
setenv("CBM_HOOK_TIMEOUT_LOG", logpath, 1);
2521+
alarm(10); /* backstop: never hang the suite */
2522+
_exit(cbm_cmd_hook_augment());
2523+
}
2524+
ASSERT_GT(pid, 0);
2525+
close(fds[0]);
2526+
2527+
int status = 0;
2528+
waitpid(pid, &status, 0);
2529+
close(fds[1]);
2530+
2531+
/* The deadline must have fired as a clean exit 0 (fail-open, no signal). */
2532+
ASSERT(WIFEXITED(status));
2533+
ASSERT_EQ(WEXITSTATUS(status), 0);
2534+
2535+
/* RED before the fix: no breadcrumb existed — a fired deadline was
2536+
* indistinguishable from a no-match run. GREEN: the log names the
2537+
* deadline and the knob. */
2538+
FILE *f = fopen(logpath, "r");
2539+
if (!f) {
2540+
fprintf(stderr, " [858] FAIL no timeout breadcrumb written to %s\n", logpath);
2541+
}
2542+
ASSERT_NOT_NULL(f);
2543+
char line[256] = "";
2544+
char *got = fgets(line, sizeof(line), f);
2545+
fclose(f);
2546+
ASSERT_NOT_NULL(got);
2547+
ASSERT(strstr(line, "deadline_exceeded") != NULL);
2548+
ASSERT(strstr(line, "CBM_HOOK_DEADLINE_MS") != NULL);
2549+
2550+
cbm_unsetenv("CBM_HOOK_DEADLINE_MS");
2551+
cbm_unsetenv("CBM_HOOK_TIMEOUT_LOG");
2552+
test_rmdir_r(tmpdir);
2553+
PASS();
2554+
#endif
2555+
}
2556+
24832557
TEST(cli_upsert_claude_hook_existing) {
24842558
char tmpdir[256];
24852559
snprintf(tmpdir, sizeof(tmpdir), "/tmp/cli-hook-XXXXXX");
@@ -3211,6 +3285,7 @@ SUITE(cli) {
32113285
/* Claude Code hooks (5 tests — group D) */
32123286
RUN_TEST(cli_hook_gate_script_no_predictable_tmp_issue384);
32133287
RUN_TEST(cli_hook_augment_path_is_abs);
3288+
RUN_TEST(cli_hook_augment_deadline_breadcrumb_issue858);
32143289
RUN_TEST(cli_upsert_claude_hook_fresh);
32153290
RUN_TEST(cli_upsert_claude_hook_existing);
32163291
RUN_TEST(cli_upsert_claude_hook_replace);

0 commit comments

Comments
 (0)