chore(server): add session-create-vs-resume + lifetime instrumentation (refs #41 #42) (#51)

Adds structured logging for the two forensic candidates so the eventual
fixes can be evidence-driven (per #41/#42 bodies: "Evidence needed before
code change — do not patch speculatively"). NO bug fix in this PR — the
stale-create-entry behavior (#41) and the lastUsed-resistant-expiry
behavior (#42) are intentionally left unchanged so they can be observed
in production /logs.

Three changes (server.mjs):

1. Session-create branch records `firstSeen` alongside `lastUsed` (same
   timestamp), giving the sweep loop an absolute-age signal independent
   of the actively-bumped `lastUsed` field. Resume branch is untouched
   so `firstSeen` is preserved across resumes.

2. handleSessionFailure now emits a structured `session_failure` event
   with `mode: "resume"` (action: "deleted") OR `mode: "create"`
   (action: "kept"). The "kept" branch makes #41's "stale create entries
   never deleted" pattern visible in /logs without changing behavior.

3. TTL sweep emits `session_expired` (info, with idleMs + ageMs) on
   actual expiry, and `session_long_lived` (warn) when ageMs > 4×TTL
   but the entry is not being expired this tick. The latter is the
   #42 evidence trigger — a session whose lastUsed keeps getting bumped
   and so resists idle-based expiry.

cli.js citation: N/A — logEvent payloads are OCP-internal observability,
never sent on the wire to the Anthropic API. ALIGNMENT.md Rule 2 (no
invention) is scoped to endpoints/headers/request/response fields, not
to internal server logging.

Independent reviewer: fresh-context sonnet APPROVE_WITH_MINOR.
Two minor notes — repeated `session_long_lived` emissions per 60s
sweep tick is expected (downstream analysis dedupes by conversationId).
LOC: +19 / -3 = +16 net.

Co-authored-by: Claude Opus 4.7 <noreply@anthropic.com>
This commit is contained in:
dtzp555-max
2026-04-25 19:19:38 +10:00
committed by GitHub
co-authored by Claude Opus 4.7
parent ca2d23d230
commit 733a2ed4c2
+19 -3
View File
@@ -165,9 +165,18 @@ const sessions = new Map(); // conversationId → { uuid, messageCount, lastUsed
const sessionCleanupInterval = setInterval(() => { const sessionCleanupInterval = setInterval(() => {
const now = Date.now(); const now = Date.now();
for (const [id, s] of sessions) { for (const [id, s] of sessions) {
if (now - s.lastUsed > SESSION_TTL) { const idleMs = now - s.lastUsed;
const ageMs = s.firstSeen ? now - s.firstSeen : null;
if (idleMs > SESSION_TTL) {
sessions.delete(id); sessions.delete(id);
console.log(`[session] expired ${id.slice(0, 12)}... (idle ${Math.round((now - s.lastUsed) / 60000)}m)`); console.log(`[session] expired ${id.slice(0, 12)}... (idle ${Math.round(idleMs / 60000)}m)`);
logEvent("info", "session_expired", { conversationId: id.slice(0, 12) + "...", idleMs, ageMs });
} else if (ageMs !== null && ageMs > 4 * SESSION_TTL) {
// #42 evidence-gathering: a session whose firstSeen is more than 4× TTL old
// but whose lastUsed keeps getting bumped (never idle long enough to expire)
// is the suspected bug. Log without action so the pattern can be confirmed
// in /logs. Do NOT enforce an absolute age cap here speculatively.
logEvent("warn", "session_long_lived", { conversationId: id.slice(0, 12) + "...", idleMs, ageMs });
} }
} }
}, 60000); }, 60000);
@@ -406,7 +415,8 @@ function spawnClaudeProcess(model, messages, conversationId) {
} else if (conversationId) { } else if (conversationId) {
const uuid = randomUUID(); const uuid = randomUUID();
sessions.set(conversationId, { uuid, messageCount: messages.length, lastUsed: Date.now(), model: cliModel }); const now = Date.now();
sessions.set(conversationId, { uuid, messageCount: messages.length, firstSeen: now, lastUsed: now, model: cliModel });
sessionInfo = { uuid, resume: false }; sessionInfo = { uuid, resume: false };
stats.sessionMisses++; stats.sessionMisses++;
prompt = messagesToPrompt(messages); prompt = messagesToPrompt(messages);
@@ -458,7 +468,13 @@ function spawnClaudeProcess(model, messages, conversationId) {
function handleSessionFailure() { function handleSessionFailure() {
if (sessionInfo?.resume && conversationId) { if (sessionInfo?.resume && conversationId) {
console.warn(`[session] resume failed for ${conversationId.slice(0, 12)}..., removing stale session`); console.warn(`[session] resume failed for ${conversationId.slice(0, 12)}..., removing stale session`);
logEvent("warn", "session_failure", { mode: "resume", conversationId: conversationId.slice(0, 12) + "...", action: "deleted" });
sessions.delete(conversationId); sessions.delete(conversationId);
} else if (sessionInfo && !sessionInfo.resume && conversationId) {
// #41 evidence-gathering: session-create failures currently leave a stale entry
// in the sessions map. Log without action so the staleness pattern can be
// confirmed in /logs before any code change. Do NOT delete here speculatively.
logEvent("warn", "session_failure", { mode: "create", conversationId: conversationId.slice(0, 12) + "...", action: "kept" });
} }
} }