From db789bbaba163b90780244ebad2149ae10728716 Mon Sep 17 00:00:00 2001 From: nrs <38722970+nrslib@users.noreply.github.com> Date: Sun, 8 Feb 2026 07:20:36 +0900 Subject: [PATCH] takt: github-issue-114-debaggu-puron (#139) --- src/__tests__/debug.test.ts | 80 ++++++++ src/__tests__/it-sigint-interrupt.test.ts | 2 + .../pieceExecution-debug-prompts.test.ts | 190 ++++++++++++++++++ src/features/tasks/execute/pieceExecution.ts | 37 +++- src/shared/utils/debug.ts | 43 +++- src/shared/utils/types.ts | 10 + 6 files changed, 356 insertions(+), 6 deletions(-) create mode 100644 src/__tests__/pieceExecution-debug-prompts.test.ts diff --git a/src/__tests__/debug.test.ts b/src/__tests__/debug.test.ts index 81adcd8..05aea16 100644 --- a/src/__tests__/debug.test.ts +++ b/src/__tests__/debug.test.ts @@ -14,11 +14,21 @@ import { debugLog, infoLog, errorLog, + writePromptLog, } from '../shared/utils/index.js'; import { existsSync, readFileSync, mkdirSync, rmSync } from 'node:fs'; import { join } from 'node:path'; import { tmpdir } from 'node:os'; +function resolvePromptsLogFilePath(): string { + const debugLogFile = getDebugLogFile(); + expect(debugLogFile).not.toBeNull(); + if (!debugLogFile!.endsWith('.log')) { + throw new Error(`unexpected debug log file path: ${debugLogFile!}`); + } + return debugLogFile!.replace(/\.log$/, '-prompts.jsonl'); +} + describe('debug logging', () => { beforeEach(() => { resetDebugLogger(); @@ -69,6 +79,21 @@ describe('debug logging', () => { } }); + it('should create prompts log file with -prompts suffix', () => { + const projectDir = join(tmpdir(), 'takt-test-debug-prompts-' + Date.now()); + mkdirSync(projectDir, { recursive: true }); + + try { + initDebugLogger({ enabled: true }, projectDir); + const promptsLogFile = resolvePromptsLogFilePath(); + expect(promptsLogFile).toContain(join(projectDir, '.takt', 'logs')); + expect(promptsLogFile).toMatch(/debug-.*-prompts\.jsonl$/); + expect(existsSync(promptsLogFile)).toBe(true); + } finally { + rmSync(projectDir, { recursive: true, force: true }); + } + }); + it('should not create log file when projectDir is not provided', () => { initDebugLogger({ enabled: true }); expect(isDebugEnabled()).toBe(true); @@ -83,7 +108,9 @@ describe('debug logging', () => { try { initDebugLogger({ enabled: true, logFile }, '/tmp'); expect(getDebugLogFile()).toBe(logFile); + expect(resolvePromptsLogFilePath()).toBe(join(logDir, 'test-prompts.jsonl')); expect(existsSync(logFile)).toBe(true); + expect(existsSync(join(logDir, 'test-prompts.jsonl'))).toBe(true); const content = readFileSync(logFile, 'utf-8'); expect(content).toContain('TAKT Debug Log'); @@ -122,6 +149,59 @@ describe('debug logging', () => { }); }); + describe('writePromptLog', () => { + it('should append prompt log record when debug is enabled', () => { + const projectDir = join(tmpdir(), 'takt-test-debug-write-prompts-' + Date.now()); + mkdirSync(projectDir, { recursive: true }); + + try { + initDebugLogger({ enabled: true }, projectDir); + const promptsLogFile = resolvePromptsLogFilePath(); + + writePromptLog({ + movement: 'plan', + phase: 1, + iteration: 2, + prompt: 'prompt text', + response: 'response text', + timestamp: '2026-02-07T00:00:00.000Z', + }); + + const content = readFileSync(promptsLogFile, 'utf-8').trim(); + expect(content).not.toBe(''); + const parsed = JSON.parse(content) as { + movement: string; + phase: number; + iteration: number; + prompt: string; + response: string; + timestamp: string; + }; + expect(parsed.movement).toBe('plan'); + expect(parsed.phase).toBe(1); + expect(parsed.iteration).toBe(2); + expect(parsed.prompt).toBe('prompt text'); + expect(parsed.response).toBe('response text'); + expect(parsed.timestamp).toBe('2026-02-07T00:00:00.000Z'); + } finally { + rmSync(projectDir, { recursive: true, force: true }); + } + }); + + it('should do nothing when debug is disabled', () => { + writePromptLog({ + movement: 'plan', + phase: 1, + iteration: 1, + prompt: 'ignored prompt', + response: 'ignored response', + timestamp: '2026-02-07T00:00:00.000Z', + }); + + expect(getDebugLogFile()).toBeNull(); + }); + }); + describe('setVerboseConsole / isVerboseConsole', () => { it('should default to false', () => { expect(isVerboseConsole()).toBe(false); diff --git a/src/__tests__/it-sigint-interrupt.test.ts b/src/__tests__/it-sigint-interrupt.test.ts index f9c0df9..7c0944a 100644 --- a/src/__tests__/it-sigint-interrupt.test.ts +++ b/src/__tests__/it-sigint-interrupt.test.ts @@ -128,6 +128,8 @@ vi.mock('../shared/utils/index.js', () => ({ }), notifySuccess: vi.fn(), notifyError: vi.fn(), + isDebugEnabled: vi.fn().mockReturnValue(false), + writePromptLog: vi.fn(), })); vi.mock('../shared/prompt/index.js', () => ({ diff --git a/src/__tests__/pieceExecution-debug-prompts.test.ts b/src/__tests__/pieceExecution-debug-prompts.test.ts new file mode 100644 index 0000000..7d9ca04 --- /dev/null +++ b/src/__tests__/pieceExecution-debug-prompts.test.ts @@ -0,0 +1,190 @@ +/** + * Integration tests: debug prompt log wiring in executePiece(). + */ + +import { describe, it, expect, beforeEach, vi } from 'vitest'; +import type { PieceConfig } from '../core/models/index.js'; + +const { mockIsDebugEnabled, mockWritePromptLog, MockPieceEngine } = vi.hoisted(() => { + // eslint-disable-next-line @typescript-eslint/no-require-imports + const { EventEmitter: EE } = require('node:events') as typeof import('node:events'); + + const mockIsDebugEnabled = vi.fn().mockReturnValue(true); + const mockWritePromptLog = vi.fn(); + + class MockPieceEngine extends EE { + private config: PieceConfig; + + constructor(config: PieceConfig, _cwd: string, _task: string, _options: unknown) { + super(); + this.config = config; + } + + abort(): void {} + + async run(): Promise<{ status: string; iteration: number }> { + const step = this.config.movements[0]!; + const timestamp = new Date('2026-02-07T00:00:00.000Z'); + + this.emit('movement:start', step, 1, 'movement instruction'); + this.emit('phase:start', step, 1, 'execute', 'phase prompt'); + this.emit('phase:complete', step, 1, 'execute', 'phase response', 'done'); + this.emit( + 'movement:complete', + step, + { + persona: step.personaDisplayName, + status: 'done', + content: 'movement response', + timestamp, + }, + 'movement instruction' + ); + this.emit('piece:complete', { status: 'completed', iteration: 1 }); + + return { status: 'completed', iteration: 1 }; + } + } + + return { mockIsDebugEnabled, mockWritePromptLog, MockPieceEngine }; +}); + +vi.mock('../core/piece/index.js', () => ({ + PieceEngine: MockPieceEngine, +})); + +vi.mock('../infra/claude/index.js', () => ({ + callAiJudge: vi.fn(), + detectRuleIndex: vi.fn(), + interruptAllQueries: vi.fn(), +})); + +vi.mock('../infra/config/index.js', () => ({ + loadPersonaSessions: vi.fn().mockReturnValue({}), + updatePersonaSession: vi.fn(), + loadWorktreeSessions: vi.fn().mockReturnValue({}), + updateWorktreeSession: vi.fn(), + loadGlobalConfig: vi.fn().mockReturnValue({ provider: 'claude' }), + saveSessionState: vi.fn(), +})); + +vi.mock('../shared/context.js', () => ({ + isQuietMode: vi.fn().mockReturnValue(true), +})); + +vi.mock('../shared/ui/index.js', () => ({ + header: vi.fn(), + info: vi.fn(), + warn: vi.fn(), + error: vi.fn(), + success: vi.fn(), + status: vi.fn(), + blankLine: vi.fn(), + StreamDisplay: vi.fn().mockImplementation(() => ({ + createHandler: vi.fn().mockReturnValue(vi.fn()), + flush: vi.fn(), + })), +})); + +vi.mock('../infra/fs/index.js', () => ({ + generateSessionId: vi.fn().mockReturnValue('test-session-id'), + createSessionLog: vi.fn().mockReturnValue({ + startTime: new Date().toISOString(), + iterations: 0, + }), + finalizeSessionLog: vi.fn().mockImplementation((log, status) => ({ + ...log, + status, + endTime: new Date().toISOString(), + })), + updateLatestPointer: vi.fn(), + initNdjsonLog: vi.fn().mockReturnValue('/tmp/test-log.jsonl'), + appendNdjsonLine: vi.fn(), +})); + +vi.mock('../shared/utils/index.js', () => ({ + createLogger: vi.fn().mockReturnValue({ + debug: vi.fn(), + info: vi.fn(), + warn: vi.fn(), + error: vi.fn(), + }), + notifySuccess: vi.fn(), + notifyError: vi.fn(), + preventSleep: vi.fn(), + isDebugEnabled: mockIsDebugEnabled, + writePromptLog: mockWritePromptLog, +})); + +vi.mock('../shared/prompt/index.js', () => ({ + selectOption: vi.fn(), + promptInput: vi.fn(), +})); + +vi.mock('../shared/i18n/index.js', () => ({ + getLabel: vi.fn().mockImplementation((key: string) => key), +})); + +vi.mock('../shared/exitCodes.js', () => ({ + EXIT_SIGINT: 130, +})); + +import { executePiece } from '../features/tasks/execute/pieceExecution.js'; + +describe('executePiece debug prompts logging', () => { + beforeEach(() => { + vi.clearAllMocks(); + }); + + function makeConfig(): PieceConfig { + return { + name: 'test-piece', + maxIterations: 5, + initialMovement: 'implement', + movements: [ + { + name: 'implement', + persona: '../agents/coder.md', + personaDisplayName: 'coder', + instructionTemplate: 'Implement task', + passPreviousResponse: true, + rules: [{ condition: 'done', next: 'COMPLETE' }], + }, + ], + }; + } + + it('should write prompt log record when debug is enabled', async () => { + mockIsDebugEnabled.mockReturnValue(true); + + await executePiece(makeConfig(), 'task', '/tmp/project', { + projectCwd: '/tmp/project', + }); + + expect(mockWritePromptLog).toHaveBeenCalledTimes(1); + const record = mockWritePromptLog.mock.calls[0]?.[0] as { + movement: string; + phase: number; + iteration: number; + prompt: string; + response: string; + timestamp: string; + }; + expect(record.movement).toBe('implement'); + expect(record.phase).toBe(1); + expect(record.iteration).toBe(1); + expect(record.prompt).toBe('phase prompt'); + expect(record.response).toBe('phase response'); + expect(record.timestamp).toMatch(/^\d{4}-\d{2}-\d{2}T/); + }); + + it('should not write prompt log record when debug is disabled', async () => { + mockIsDebugEnabled.mockReturnValue(false); + + await executePiece(makeConfig(), 'task', '/tmp/project', { + projectCwd: '/tmp/project', + }); + + expect(mockWritePromptLog).not.toHaveBeenCalled(); + }); +}); diff --git a/src/features/tasks/execute/pieceExecution.ts b/src/features/tasks/execute/pieceExecution.ts index 87c6e21..049ea2b 100644 --- a/src/features/tasks/execute/pieceExecution.ts +++ b/src/features/tasks/execute/pieceExecution.ts @@ -46,7 +46,15 @@ import { type NdjsonInteractiveStart, type NdjsonInteractiveEnd, } from '../../../infra/fs/index.js'; -import { createLogger, notifySuccess, notifyError, preventSleep } from '../../../shared/utils/index.js'; +import { + createLogger, + notifySuccess, + notifyError, + preventSleep, + isDebugEnabled, + writePromptLog, +} from '../../../shared/utils/index.js'; +import type { PromptLogRecord } from '../../../shared/utils/index.js'; import { selectOption, promptInput } from '../../../shared/prompt/index.js'; import { EXIT_SIGINT } from '../../../shared/exitCodes.js'; import { getLabel } from '../../../shared/i18n/index.js'; @@ -241,6 +249,8 @@ export async function executePiece( let abortReason: string | undefined; let lastMovementContent: string | undefined; let lastMovementName: string | undefined; + let currentIteration = 0; + const phasePrompts = new Map(); engine.on('phase:start', (step, phase, phaseName, instruction) => { log.debug('Phase starting', { step: step.name, phase, phaseName }); @@ -253,6 +263,10 @@ export async function executePiece( ...(instruction ? { instruction } : {}), }; appendNdjsonLine(ndjsonLogPath, record); + + if (isDebugEnabled()) { + phasePrompts.set(`${step.name}:${phase}`, instruction); + } }); engine.on('phase:complete', (step, phase, phaseName, content, phaseStatus, phaseError) => { @@ -263,15 +277,34 @@ export async function executePiece( phase, phaseName, status: phaseStatus, - content: content ?? '', + content, timestamp: new Date().toISOString(), ...(phaseError ? { error: phaseError } : {}), }; appendNdjsonLine(ndjsonLogPath, record); + + const promptKey = `${step.name}:${phase}`; + const prompt = phasePrompts.get(promptKey); + phasePrompts.delete(promptKey); + + if (isDebugEnabled()) { + if (prompt) { + const promptRecord: PromptLogRecord = { + movement: step.name, + phase, + iteration: currentIteration, + prompt, + response: content, + timestamp: new Date().toISOString(), + }; + writePromptLog(promptRecord); + } + } }); engine.on('movement:start', (step, iteration, instruction) => { log.debug('Movement starting', { step: step.name, persona: step.personaDisplayName, iteration }); + currentIteration = iteration; info(`[${iteration}/${pieceConfig.maxIterations}] ${step.name} (${step.personaDisplayName})`); // Log prompt content for debugging diff --git a/src/shared/utils/debug.ts b/src/shared/utils/debug.ts index 5716a85..c3f8b7c 100644 --- a/src/shared/utils/debug.ts +++ b/src/shared/utils/debug.ts @@ -6,6 +6,7 @@ import { existsSync, appendFileSync, mkdirSync, writeFileSync } from 'node:fs'; import { dirname, join } from 'node:path'; +import type { PromptLogRecord } from './types.js'; /** Debug configuration (duplicated from core/models to avoid shared → core dependency) */ interface DebugConfig { enabled: boolean; @@ -21,6 +22,7 @@ export class DebugLogger { private debugEnabled = false; private debugLogFile: string | null = null; + private debugPromptsLogFile: string | null = null; private initialized = false; private verboseConsoleEnabled = false; @@ -38,10 +40,10 @@ export class DebugLogger { DebugLogger.instance = null; } - /** Get default debug log file path */ - private static getDefaultLogFile(projectDir: string): string { + /** Get default debug log file prefix */ + private static getDefaultLogPrefix(projectDir: string): string { const timestamp = new Date().toISOString().replace(/[:.]/g, '-').slice(0, 19); - return join(projectDir, '.takt', 'logs', `debug-${timestamp}.log`); + return join(projectDir, '.takt', 'logs', `debug-${timestamp}`); } /** Initialize debug logger from config */ @@ -55,8 +57,15 @@ export class DebugLogger { if (this.debugEnabled) { if (config?.logFile) { this.debugLogFile = config.logFile; + if (config.logFile.endsWith('.log')) { + this.debugPromptsLogFile = config.logFile.slice(0, -4) + '-prompts.jsonl'; + } else { + this.debugPromptsLogFile = `${config.logFile}-prompts.jsonl`; + } } else if (projectDir) { - this.debugLogFile = DebugLogger.getDefaultLogFile(projectDir); + const logPrefix = DebugLogger.getDefaultLogPrefix(projectDir); + this.debugLogFile = `${logPrefix}.log`; + this.debugPromptsLogFile = `${logPrefix}-prompts.jsonl`; } if (this.debugLogFile) { @@ -76,6 +85,14 @@ export class DebugLogger { writeFileSync(this.debugLogFile, header, 'utf-8'); } + + if (this.debugPromptsLogFile) { + const promptsLogDir = dirname(this.debugPromptsLogFile); + if (!existsSync(promptsLogDir)) { + mkdirSync(promptsLogDir, { recursive: true }); + } + writeFileSync(this.debugPromptsLogFile, '', 'utf-8'); + } } this.initialized = true; @@ -85,6 +102,7 @@ export class DebugLogger { reset(): void { this.debugEnabled = false; this.debugLogFile = null; + this.debugPromptsLogFile = null; this.initialized = false; this.verboseConsoleEnabled = false; } @@ -153,6 +171,19 @@ export class DebugLogger { } } + /** Write a prompt/response debug log entry */ + writePromptLog(record: PromptLogRecord): void { + if (!this.debugEnabled || !this.debugPromptsLogFile) { + return; + } + + try { + appendFileSync(this.debugPromptsLogFile, JSON.stringify(record) + '\n', 'utf-8'); + } catch { + // Silently fail - logging errors should not interrupt main flow + } + } + /** Create a scoped logger for a component */ createLogger(component: string) { return { @@ -203,6 +234,10 @@ export function errorLog(component: string, message: string, data?: unknown): vo DebugLogger.getInstance().writeLog('ERROR', component, message, data); } +export function writePromptLog(record: PromptLogRecord): void { + DebugLogger.getInstance().writePromptLog(record); +} + export function traceEnter(component: string, funcName: string, args?: Record): void { debugLog(component, `>> ${funcName}()`, args); } diff --git a/src/shared/utils/types.ts b/src/shared/utils/types.ts index 1968d58..3e4b24f 100644 --- a/src/shared/utils/types.ts +++ b/src/shared/utils/types.ts @@ -129,3 +129,13 @@ export interface LatestLogPointer { updatedAt: string; iterations: number; } + +/** Record for debug prompt/response log (debug-*-prompts.jsonl) */ +export interface PromptLogRecord { + movement: string; + phase: 1 | 2 | 3; + iteration: number; + prompt: string; + response: string; + timestamp: string; +}