Skip to content
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
80 changes: 80 additions & 0 deletions src/__tests__/debug.test.ts
Original file line number Diff line number Diff line change
Expand Up @@ -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();
Expand Down Expand Up @@ -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);
Expand All @@ -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');
Expand Down Expand Up @@ -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);
Expand Down
2 changes: 2 additions & 0 deletions src/__tests__/it-sigint-interrupt.test.ts
Original file line number Diff line number Diff line change
Expand Up @@ -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', () => ({
Expand Down
190 changes: 190 additions & 0 deletions src/__tests__/pieceExecution-debug-prompts.test.ts
Original file line number Diff line number Diff line change
@@ -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();
});
});
37 changes: 35 additions & 2 deletions src/features/tasks/execute/pieceExecution.ts
Original file line number Diff line number Diff line change
Expand Up @@ -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';
Expand Down Expand Up @@ -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<string, string>();

engine.on('phase:start', (step, phase, phaseName, instruction) => {
log.debug('Phase starting', { step: step.name, phase, phaseName });
Expand All @@ -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) => {
Expand All @@ -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
Expand Down
Loading