diag(todo-continuation): add comprehensive debug logging for session idle handling

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)
This commit is contained in:
YeonGyu-Kim
2026-03-18 14:45:14 +09:00
parent d48ea025f0
commit 09cfd0b408
3 changed files with 27 additions and 16 deletions

View File

@@ -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

View File

@@ -31,6 +31,10 @@ export function createTodoContinuationHandler(args: {
return async ({ event }: { event: { type: string; properties?: unknown } }): Promise<void> => {
const props = event.properties as Record<string, unknown> | 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

View File

@@ -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,