takt: github-issue-114-debaggu-puron (#139)

This commit is contained in:
nrs 2026-02-08 07:20:36 +09:00 committed by GitHub
parent e23359b1bf
commit db789bbaba
No known key found for this signature in database
GPG Key ID: B5690EEEBB952194
6 changed files with 356 additions and 6 deletions

View File

@ -14,11 +14,21 @@ import {
debugLog, debugLog,
infoLog, infoLog,
errorLog, errorLog,
writePromptLog,
} from '../shared/utils/index.js'; } from '../shared/utils/index.js';
import { existsSync, readFileSync, mkdirSync, rmSync } from 'node:fs'; import { existsSync, readFileSync, mkdirSync, rmSync } from 'node:fs';
import { join } from 'node:path'; import { join } from 'node:path';
import { tmpdir } from 'node:os'; 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', () => { describe('debug logging', () => {
beforeEach(() => { beforeEach(() => {
resetDebugLogger(); 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', () => { it('should not create log file when projectDir is not provided', () => {
initDebugLogger({ enabled: true }); initDebugLogger({ enabled: true });
expect(isDebugEnabled()).toBe(true); expect(isDebugEnabled()).toBe(true);
@ -83,7 +108,9 @@ describe('debug logging', () => {
try { try {
initDebugLogger({ enabled: true, logFile }, '/tmp'); initDebugLogger({ enabled: true, logFile }, '/tmp');
expect(getDebugLogFile()).toBe(logFile); expect(getDebugLogFile()).toBe(logFile);
expect(resolvePromptsLogFilePath()).toBe(join(logDir, 'test-prompts.jsonl'));
expect(existsSync(logFile)).toBe(true); expect(existsSync(logFile)).toBe(true);
expect(existsSync(join(logDir, 'test-prompts.jsonl'))).toBe(true);
const content = readFileSync(logFile, 'utf-8'); const content = readFileSync(logFile, 'utf-8');
expect(content).toContain('TAKT Debug Log'); 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', () => { describe('setVerboseConsole / isVerboseConsole', () => {
it('should default to false', () => { it('should default to false', () => {
expect(isVerboseConsole()).toBe(false); expect(isVerboseConsole()).toBe(false);

View File

@ -128,6 +128,8 @@ vi.mock('../shared/utils/index.js', () => ({
}), }),
notifySuccess: vi.fn(), notifySuccess: vi.fn(),
notifyError: vi.fn(), notifyError: vi.fn(),
isDebugEnabled: vi.fn().mockReturnValue(false),
writePromptLog: vi.fn(),
})); }));
vi.mock('../shared/prompt/index.js', () => ({ vi.mock('../shared/prompt/index.js', () => ({

View File

@ -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();
});
});

View File

@ -46,7 +46,15 @@ import {
type NdjsonInteractiveStart, type NdjsonInteractiveStart,
type NdjsonInteractiveEnd, type NdjsonInteractiveEnd,
} from '../../../infra/fs/index.js'; } 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 { selectOption, promptInput } from '../../../shared/prompt/index.js';
import { EXIT_SIGINT } from '../../../shared/exitCodes.js'; import { EXIT_SIGINT } from '../../../shared/exitCodes.js';
import { getLabel } from '../../../shared/i18n/index.js'; import { getLabel } from '../../../shared/i18n/index.js';
@ -241,6 +249,8 @@ export async function executePiece(
let abortReason: string | undefined; let abortReason: string | undefined;
let lastMovementContent: string | undefined; let lastMovementContent: string | undefined;
let lastMovementName: string | undefined; let lastMovementName: string | undefined;
let currentIteration = 0;
const phasePrompts = new Map<string, string>();
engine.on('phase:start', (step, phase, phaseName, instruction) => { engine.on('phase:start', (step, phase, phaseName, instruction) => {
log.debug('Phase starting', { step: step.name, phase, phaseName }); log.debug('Phase starting', { step: step.name, phase, phaseName });
@ -253,6 +263,10 @@ export async function executePiece(
...(instruction ? { instruction } : {}), ...(instruction ? { instruction } : {}),
}; };
appendNdjsonLine(ndjsonLogPath, record); appendNdjsonLine(ndjsonLogPath, record);
if (isDebugEnabled()) {
phasePrompts.set(`${step.name}:${phase}`, instruction);
}
}); });
engine.on('phase:complete', (step, phase, phaseName, content, phaseStatus, phaseError) => { engine.on('phase:complete', (step, phase, phaseName, content, phaseStatus, phaseError) => {
@ -263,15 +277,34 @@ export async function executePiece(
phase, phase,
phaseName, phaseName,
status: phaseStatus, status: phaseStatus,
content: content ?? '', content,
timestamp: new Date().toISOString(), timestamp: new Date().toISOString(),
...(phaseError ? { error: phaseError } : {}), ...(phaseError ? { error: phaseError } : {}),
}; };
appendNdjsonLine(ndjsonLogPath, record); 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) => { engine.on('movement:start', (step, iteration, instruction) => {
log.debug('Movement starting', { step: step.name, persona: step.personaDisplayName, iteration }); log.debug('Movement starting', { step: step.name, persona: step.personaDisplayName, iteration });
currentIteration = iteration;
info(`[${iteration}/${pieceConfig.maxIterations}] ${step.name} (${step.personaDisplayName})`); info(`[${iteration}/${pieceConfig.maxIterations}] ${step.name} (${step.personaDisplayName})`);
// Log prompt content for debugging // Log prompt content for debugging

View File

@ -6,6 +6,7 @@
import { existsSync, appendFileSync, mkdirSync, writeFileSync } from 'node:fs'; import { existsSync, appendFileSync, mkdirSync, writeFileSync } from 'node:fs';
import { dirname, join } from 'node:path'; import { dirname, join } from 'node:path';
import type { PromptLogRecord } from './types.js';
/** Debug configuration (duplicated from core/models to avoid shared → core dependency) */ /** Debug configuration (duplicated from core/models to avoid shared → core dependency) */
interface DebugConfig { interface DebugConfig {
enabled: boolean; enabled: boolean;
@ -21,6 +22,7 @@ export class DebugLogger {
private debugEnabled = false; private debugEnabled = false;
private debugLogFile: string | null = null; private debugLogFile: string | null = null;
private debugPromptsLogFile: string | null = null;
private initialized = false; private initialized = false;
private verboseConsoleEnabled = false; private verboseConsoleEnabled = false;
@ -38,10 +40,10 @@ export class DebugLogger {
DebugLogger.instance = null; DebugLogger.instance = null;
} }
/** Get default debug log file path */ /** Get default debug log file prefix */
private static getDefaultLogFile(projectDir: string): string { private static getDefaultLogPrefix(projectDir: string): string {
const timestamp = new Date().toISOString().replace(/[:.]/g, '-').slice(0, 19); 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 */ /** Initialize debug logger from config */
@ -55,8 +57,15 @@ export class DebugLogger {
if (this.debugEnabled) { if (this.debugEnabled) {
if (config?.logFile) { if (config?.logFile) {
this.debugLogFile = 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) { } 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) { if (this.debugLogFile) {
@ -76,6 +85,14 @@ export class DebugLogger {
writeFileSync(this.debugLogFile, header, 'utf-8'); 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; this.initialized = true;
@ -85,6 +102,7 @@ export class DebugLogger {
reset(): void { reset(): void {
this.debugEnabled = false; this.debugEnabled = false;
this.debugLogFile = null; this.debugLogFile = null;
this.debugPromptsLogFile = null;
this.initialized = false; this.initialized = false;
this.verboseConsoleEnabled = 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 */ /** Create a scoped logger for a component */
createLogger(component: string) { createLogger(component: string) {
return { return {
@ -203,6 +234,10 @@ export function errorLog(component: string, message: string, data?: unknown): vo
DebugLogger.getInstance().writeLog('ERROR', component, message, data); 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<string, unknown>): void { export function traceEnter(component: string, funcName: string, args?: Record<string, unknown>): void {
debugLog(component, `>> ${funcName}()`, args); debugLog(component, `>> ${funcName}()`, args);
} }

View File

@ -129,3 +129,13 @@ export interface LatestLogPointer {
updatedAt: string; updatedAt: string;
iterations: number; 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;
}