From 09cfd0b408996d19b5f658bc7ecc4d3c89ad0db4 Mon Sep 17 00:00:00 2001 From: YeonGyu-Kim Date: Wed, 18 Mar 2026 14:45:14 +0900 Subject: [PATCH] diag(todo-continuation): add comprehensive debug logging for session idle handling MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Add [TODO-DIAG] console.error statements throughout the todo continuation enforcer to help diagnose why continuation prompts aren't being injected. Changes: - Add session.idle event handler diagnostic in handler.ts - Add detailed blocking reason logging in idle-event.ts for all gate checks - Update JSON schema to reflect circuit breaker config changes 🤖 Generated with assistance of [OhMyOpenCode](https://github.com/code-yeongyu/oh-my-opencode) --- assets/oh-my-opencode.schema.json | 7 +--- .../todo-continuation-enforcer/handler.ts | 4 +++ .../todo-continuation-enforcer/idle-event.ts | 32 +++++++++++++------ 3 files changed, 27 insertions(+), 16 deletions(-) diff --git a/assets/oh-my-opencode.schema.json b/assets/oh-my-opencode.schema.json index 2be24a634..223aba61a 100644 --- a/assets/oh-my-opencode.schema.json +++ b/assets/oh-my-opencode.schema.json @@ -3716,15 +3716,10 @@ "minimum": 10, "maximum": 9007199254740991 }, - "windowSize": { + "consecutiveThreshold": { "type": "integer", "minimum": 5, "maximum": 9007199254740991 - }, - "repetitionThresholdPercent": { - "type": "number", - "exclusiveMinimum": 0, - "maximum": 100 } }, "additionalProperties": false diff --git a/src/hooks/todo-continuation-enforcer/handler.ts b/src/hooks/todo-continuation-enforcer/handler.ts index a3eb71bf7..ab8d6fffc 100644 --- a/src/hooks/todo-continuation-enforcer/handler.ts +++ b/src/hooks/todo-continuation-enforcer/handler.ts @@ -31,6 +31,10 @@ export function createTodoContinuationHandler(args: { return async ({ event }: { event: { type: string; properties?: unknown } }): Promise => { const props = event.properties as Record | undefined + if (event.type === "session.idle") { + console.error(`[TODO-DIAG] handler received session.idle event`, { sessionID: (props?.sessionID as string) }) + } + if (event.type === "session.error") { const sessionID = props?.sessionID as string | undefined if (!sessionID) return diff --git a/src/hooks/todo-continuation-enforcer/idle-event.ts b/src/hooks/todo-continuation-enforcer/idle-event.ts index 7149613ba..1384aa39a 100644 --- a/src/hooks/todo-continuation-enforcer/idle-event.ts +++ b/src/hooks/todo-continuation-enforcer/idle-event.ts @@ -43,10 +43,12 @@ export async function handleSessionIdle(args: { } = args log(`[${HOOK_NAME}] session.idle`, { sessionID }) + console.error(`[TODO-DIAG] session.idle fired for ${sessionID}`) const state = sessionStateStore.getState(sessionID) if (state.isRecovering) { log(`[${HOOK_NAME}] Skipped: in recovery`, { sessionID }) + console.error(`[TODO-DIAG] BLOCKED: isRecovering=true`) return } @@ -54,6 +56,7 @@ export async function handleSessionIdle(args: { const timeSinceAbort = Date.now() - state.abortDetectedAt if (timeSinceAbort < ABORT_WINDOW_MS) { log(`[${HOOK_NAME}] Skipped: abort detected via event ${timeSinceAbort}ms ago`, { sessionID }) + console.error(`[TODO-DIAG] BLOCKED: abort detected ${timeSinceAbort}ms ago`) state.abortDetectedAt = undefined return } @@ -66,6 +69,7 @@ export async function handleSessionIdle(args: { if (hasRunningBgTasks) { log(`[${HOOK_NAME}] Skipped: background tasks running`, { sessionID }) + console.error(`[TODO-DIAG] BLOCKED: background tasks running`, backgroundManager?.getTasksByParentSession(sessionID).filter((t: {status:string}) => t.status === 'running').map((t: {id:string, status:string}) => t.id)) return } @@ -77,10 +81,12 @@ export async function handleSessionIdle(args: { const messages = normalizeSDKResponse(messagesResp, [] as Array<{ info?: MessageInfo }>) if (isLastAssistantMessageAborted(messages)) { log(`[${HOOK_NAME}] Skipped: last assistant message was aborted (API fallback)`, { sessionID }) + console.error(`[TODO-DIAG] BLOCKED: last assistant message aborted`) return } if (hasUnansweredQuestion(messages)) { log(`[${HOOK_NAME}] Skipped: pending question awaiting user response`, { sessionID }) + console.error(`[TODO-DIAG] BLOCKED: hasUnansweredQuestion=true`) return } } catch (error) { @@ -93,24 +99,30 @@ export async function handleSessionIdle(args: { todos = normalizeSDKResponse(response, [] as Todo[], { preferResponseOnMissingData: true }) } catch (error) { log(`[${HOOK_NAME}] Todo fetch failed`, { sessionID, error: String(error) }) + console.error(`[TODO-DIAG] BLOCKED: todo fetch failed`, String(error)) return } if (!todos || todos.length === 0) { + sessionStateStore.resetContinuationProgress(sessionID) sessionStateStore.resetContinuationProgress(sessionID) log(`[${HOOK_NAME}] No todos`, { sessionID }) + console.error(`[TODO-DIAG] BLOCKED: no todos`) return } const incompleteCount = getIncompleteCount(todos) if (incompleteCount === 0) { + sessionStateStore.resetContinuationProgress(sessionID) sessionStateStore.resetContinuationProgress(sessionID) log(`[${HOOK_NAME}] All todos complete`, { sessionID, total: todos.length }) + console.error(`[TODO-DIAG] BLOCKED: all todos complete (${todos.length})`) return } if (state.inFlight) { log(`[${HOOK_NAME}] Skipped: injection in flight`, { sessionID }) + console.error(`[TODO-DIAG] BLOCKED: inFlight=true`) return } @@ -124,22 +136,16 @@ export async function handleSessionIdle(args: { } if (state.consecutiveFailures >= MAX_CONSECUTIVE_FAILURES) { - log(`[${HOOK_NAME}] Skipped: max consecutive failures reached`, { - sessionID, - consecutiveFailures: state.consecutiveFailures, - maxConsecutiveFailures: MAX_CONSECUTIVE_FAILURES, - }) + log(`[${HOOK_NAME}] Skipped: max consecutive failures reached`, { sessionID, consecutiveFailures: state.consecutiveFailures }) + console.error(`[TODO-DIAG] BLOCKED: consecutiveFailures=${state.consecutiveFailures} >= ${MAX_CONSECUTIVE_FAILURES}`) return } const effectiveCooldown = CONTINUATION_COOLDOWN_MS * Math.pow(2, Math.min(state.consecutiveFailures, 5)) if (state.lastInjectedAt && Date.now() - state.lastInjectedAt < effectiveCooldown) { - log(`[${HOOK_NAME}] Skipped: cooldown active`, { - sessionID, - effectiveCooldown, - consecutiveFailures: state.consecutiveFailures, - }) + log(`[${HOOK_NAME}] Skipped: cooldown active`, { sessionID, effectiveCooldown, consecutiveFailures: state.consecutiveFailures }) + console.error(`[TODO-DIAG] BLOCKED: cooldown active (${effectiveCooldown}ms, failures=${state.consecutiveFailures})`) return } @@ -165,10 +171,12 @@ export async function handleSessionIdle(args: { const resolvedAgentName = resolvedInfo?.agent if (resolvedAgentName && skipAgents.some(s => getAgentConfigKey(s) === getAgentConfigKey(resolvedAgentName))) { log(`[${HOOK_NAME}] Skipped: agent in skipAgents list`, { sessionID, agent: resolvedAgentName }) + console.error(`[TODO-DIAG] BLOCKED: agent '${resolvedAgentName}' in skipAgents`) return } if ((compactionGuardActive || encounteredCompaction) && !resolvedInfo?.agent) { log(`[${HOOK_NAME}] Skipped: compaction occurred but no agent info resolved`, { sessionID }) + console.error(`[TODO-DIAG] BLOCKED: compaction guard + no agent`) return } if (state.recentCompactionAt && resolvedInfo?.agent) { @@ -177,18 +185,22 @@ export async function handleSessionIdle(args: { if (isContinuationStopped?.(sessionID)) { log(`[${HOOK_NAME}] Skipped: continuation stopped for session`, { sessionID }) + console.error(`[TODO-DIAG] BLOCKED: isContinuationStopped=true`) return } if (shouldSkipContinuation?.(sessionID)) { log(`[${HOOK_NAME}] Skipped: another continuation hook already injected`, { sessionID }) + console.error(`[TODO-DIAG] BLOCKED: shouldSkipContinuation=true (gptPermissionContinuation recently injected)`) return } const progressUpdate = sessionStateStore.trackContinuationProgress(sessionID, incompleteCount, todos) if (shouldStopForStagnation({ sessionID, incompleteCount, progressUpdate })) { + console.error(`[TODO-DIAG] BLOCKED: stagnation detected (count=${progressUpdate.stagnationCount})`) return } + console.error(`[TODO-DIAG] PASSED all gates! Starting countdown (${incompleteCount}/${todos.length} incomplete)`) startCountdown({ ctx, sessionID,