From fbcdee432dd1f07d9af8535c851226d9f7d4019b Mon Sep 17 00:00:00 2001 From: Cascade Bot Date: Sat, 14 Mar 2026 18:34:31 +0000 Subject: [PATCH] refactor(backends): extract shared LLM call logging helper --- src/backends/claude-code/index.ts | 23 +- src/backends/codex/index.ts | 20 +- src/backends/opencode/index.ts | 24 +- src/backends/shared/llmCallLogger.ts | 53 ++++ .../backends/shared-llmCallLogger.test.ts | 230 ++++++++++++++++++ 5 files changed, 304 insertions(+), 46 deletions(-) create mode 100644 src/backends/shared/llmCallLogger.ts create mode 100644 tests/unit/backends/shared-llmCallLogger.test.ts diff --git a/src/backends/claude-code/index.ts b/src/backends/claude-code/index.ts index cfd61596..4e34c1b4 100644 --- a/src/backends/claude-code/index.ts +++ b/src/backends/claude-code/index.ts @@ -10,7 +10,6 @@ import type { SDKStatusMessage, SDKSystemMessage, } from '@anthropic-ai/claude-agent-sdk'; -import { storeLlmCall } from '../../db/repositories/runsRepository.js'; import { logger } from '../../utils/logging.js'; import { extractPRUrl } from '../../utils/prUrl.js'; import { getWorkspaceDir } from '../../utils/repo.js'; @@ -23,6 +22,7 @@ import { } from '../completion.js'; import { cleanupContextFiles } from '../contextFiles.js'; import { buildSystemPrompt, buildTaskPrompt } from '../nativeTools.js'; +import { logLlmCall } from '../shared/llmCallLogger.js'; import type { AgentEngine, AgentEngineResult, AgentExecutionPlan } from '../types.js'; import { buildClaudeEnv } from './env.js'; import { buildHooks } from './hooks.js'; @@ -306,13 +306,13 @@ function resolveNativeTools(nativeToolCapabilities?: string[]): string[] { return tools.size > 0 ? [...tools] : ['Read', 'Write', 'Edit', 'Bash', 'Glob', 'Grep']; } -function logLlmCall( +function logClaudeCodeLlmCall( input: AgentExecutionPlan, assistantMsg: SDKAssistantMessage, turnCount: number, model: string, ): void { - if (!input.runId || !assistantMsg.message?.usage) return; + if (!assistantMsg.message?.usage) return; const usage = assistantMsg.message.usage; let response: string | undefined; @@ -322,23 +322,16 @@ function logLlmCall( // Ignore serialization errors } - storeLlmCall({ + logLlmCall({ runId: input.runId, callNumber: turnCount, - request: undefined, - response, + model, inputTokens: usage.input_tokens, outputTokens: usage.output_tokens, cachedTokens: undefined, costUsd: undefined, - durationMs: undefined, - model, - }).catch((err) => { - logger.warn('Failed to store Claude Code LLM call in real-time', { - runId: input.runId, - turn: turnCount, - error: String(err), - }); + response, + engineLabel: 'Claude Code', }); } @@ -374,7 +367,7 @@ async function consumeStream( await input.progressReporter.onIteration(turnCount, input.maxIterations); processAssistantMessage(assistantMsg, turnCount, input); toolCallCount += countToolCalls(assistantMsg); - logLlmCall(input, assistantMsg, turnCount, model); + logClaudeCodeLlmCall(input, assistantMsg, turnCount, model); } else if (message.type === 'system') { const sysMsg = message as { subtype: string; [key: string]: unknown }; if (sysMsg.subtype === 'task_notification') { diff --git a/src/backends/codex/index.ts b/src/backends/codex/index.ts index dc15a379..117db9b9 100644 --- a/src/backends/codex/index.ts +++ b/src/backends/codex/index.ts @@ -9,12 +9,11 @@ import { findCredentialIdByEnvVarKey, updateCredential, } from '../../db/repositories/credentialsRepository.js'; -import { storeLlmCall } from '../../db/repositories/runsRepository.js'; -import { logger } from '../../utils/logging.js'; import { extractPRUrl } from '../../utils/prUrl.js'; import { CODEX_ENGINE_DEFINITION } from '../catalog.js'; import { cleanupContextFiles } from '../contextFiles.js'; import { buildSystemPrompt, buildTaskPrompt } from '../nativeTools.js'; +import { logLlmCall } from '../shared/llmCallLogger.js'; import type { AgentEngine, AgentEngineResult, AgentExecutionPlan, LogWriter } from '../types.js'; import { buildEnv } from './env.js'; import { CODEX_MODEL_IDS, DEFAULT_CODEX_MODEL } from './models.js'; @@ -249,26 +248,17 @@ function logText(context: CodexLineContext, text: string): void { function trackUsage(context: CodexLineContext, responseLine: string, usage: UsageSummary): void { context.cost = usage.costUsd ?? context.cost; - if (!context.input.runId) return; - context.llmCallCount += 1; - void storeLlmCall({ + logLlmCall({ runId: context.input.runId, callNumber: context.llmCallCount, - request: undefined, - response: responseLine, + model: context.model, inputTokens: usage.inputTokens, outputTokens: usage.outputTokens, cachedTokens: usage.cachedTokens, costUsd: usage.costUsd, - durationMs: undefined, - model: context.model, - }).catch((error) => { - logger.warn('Failed to store Codex LLM call in real-time', { - runId: context.input.runId, - call: context.llmCallCount, - error: String(error), - }); + response: responseLine, + engineLabel: 'Codex', }); } diff --git a/src/backends/opencode/index.ts b/src/backends/opencode/index.ts index c62e48a2..f07a742b 100644 --- a/src/backends/opencode/index.ts +++ b/src/backends/opencode/index.ts @@ -12,7 +12,6 @@ import type { ToolPart, } from '@opencode-ai/sdk/client'; -import { storeLlmCall } from '../../db/repositories/runsRepository.js'; import { logger } from '../../utils/logging.js'; import { extractPRUrl } from '../../utils/prUrl.js'; import { OPENCODE_ENGINE_DEFINITION } from '../catalog.js'; @@ -28,6 +27,7 @@ import { retryNativeToolOperation, } from '../nativeToolRetry.js'; import { buildSystemPrompt, buildTaskPrompt } from '../nativeTools.js'; +import { logLlmCall } from '../shared/llmCallLogger.js'; import type { AgentEngine, AgentEngineResult, AgentExecutionPlan } from '../types.js'; import { buildEnv } from './env.js'; import { DEFAULT_OPENCODE_MODEL } from './models.js'; @@ -276,24 +276,22 @@ function reportToolPart( input.progressReporter.onToolCall(part.tool, part.state.input); } -async function storeUsage( +function storeUsage( input: AgentExecutionPlan, model: string, llmCallCount: number, part: Extract, -): Promise { - if (!input.runId) return; - await storeLlmCall({ +): void { + logLlmCall({ runId: input.runId, callNumber: llmCallCount, - request: undefined, - response: JSON.stringify(part), + model, inputTokens: part.tokens.input, outputTokens: part.tokens.output, cachedTokens: part.tokens.cache.read, costUsd: part.cost, - durationMs: undefined, - model, + response: JSON.stringify(part), + engineLabel: 'OpenCode', }); } @@ -402,13 +400,7 @@ async function handleMessagePartUpdated( if (part.type === 'step-finish') { state.llmCallCount += 1; state.totalCost += part.cost; - await storeUsage(state.input, state.model, state.llmCallCount, part).catch((error) => { - logger.warn('Failed to store OpenCode LLM call in real-time', { - runId: state.input.runId, - call: state.llmCallCount, - error: String(error), - }); - }); + storeUsage(state.input, state.model, state.llmCallCount, part); return; } diff --git a/src/backends/shared/llmCallLogger.ts b/src/backends/shared/llmCallLogger.ts new file mode 100644 index 00000000..66adcd7d --- /dev/null +++ b/src/backends/shared/llmCallLogger.ts @@ -0,0 +1,53 @@ +import { storeLlmCall } from '../../db/repositories/runsRepository.js'; +import { logger } from '../../utils/logging.js'; + +export interface LlmCallLogPayload { + /** The run ID. If undefined or empty, the call is a no-op. */ + runId: string | undefined; + /** Sequential call number within the run. */ + callNumber: number; + /** Model identifier string. */ + model: string; + /** Number of input tokens consumed. */ + inputTokens?: number; + /** Number of output tokens generated. */ + outputTokens?: number; + /** Number of cached tokens (optional; some engines don't report this). */ + cachedTokens?: number; + /** Cost in USD (optional; some engines don't report this). */ + costUsd?: number; + /** Raw response payload to store (optional). */ + response?: string; + /** Human-readable engine label used in warning logs (e.g. "Claude Code"). */ + engineLabel: string; +} + +/** + * Shared fire-and-forget helper for storing LLM call records. + * + * Guards on runId (no-op when absent), calls storeLlmCall asynchronously, + * and catches/logs any storage errors using the engine label for context. + * Returns void — callers do not need to await. + */ +export function logLlmCall(payload: LlmCallLogPayload): void { + if (!payload.runId) return; + + storeLlmCall({ + runId: payload.runId, + callNumber: payload.callNumber, + request: undefined, + response: payload.response, + inputTokens: payload.inputTokens, + outputTokens: payload.outputTokens, + cachedTokens: payload.cachedTokens, + costUsd: payload.costUsd, + durationMs: undefined, + model: payload.model, + }).catch((err) => { + logger.warn(`Failed to store ${payload.engineLabel} LLM call in real-time`, { + runId: payload.runId, + call: payload.callNumber, + error: String(err), + }); + }); +} diff --git a/tests/unit/backends/shared-llmCallLogger.test.ts b/tests/unit/backends/shared-llmCallLogger.test.ts new file mode 100644 index 00000000..7a9d7b8c --- /dev/null +++ b/tests/unit/backends/shared-llmCallLogger.test.ts @@ -0,0 +1,230 @@ +import { afterEach, beforeEach, describe, expect, it, vi } from 'vitest'; +import type { LlmCallLogPayload } from '../../../src/backends/shared/llmCallLogger.js'; +import { logLlmCall } from '../../../src/backends/shared/llmCallLogger.js'; + +// Mock the DB repository +vi.mock('../../../src/db/repositories/runsRepository.js', () => ({ + storeLlmCall: vi.fn(), +})); + +// Mock the logger +vi.mock('../../../src/utils/logging.js', () => ({ + logger: { + warn: vi.fn(), + }, +})); + +import { storeLlmCall } from '../../../src/db/repositories/runsRepository.js'; +import { logger } from '../../../src/utils/logging.js'; + +describe('logLlmCall (shared helper)', () => { + const mockStoreLlmCall = vi.mocked(storeLlmCall); + const mockLoggerWarn = vi.mocked(logger.warn); + + beforeEach(() => { + vi.clearAllMocks(); + }); + + afterEach(() => { + vi.restoreAllMocks(); + }); + + describe('guard on runId', () => { + it('is a no-op when runId is undefined', () => { + const payload: LlmCallLogPayload = { + runId: undefined, + callNumber: 1, + model: 'claude-sonnet-4-5', + engineLabel: 'Claude Code', + }; + + logLlmCall(payload); + + expect(mockStoreLlmCall).not.toHaveBeenCalled(); + }); + + it('is a no-op when runId is an empty string', () => { + const payload: LlmCallLogPayload = { + runId: '', + callNumber: 1, + model: 'gpt-4o', + engineLabel: 'Codex', + }; + + logLlmCall(payload); + + expect(mockStoreLlmCall).not.toHaveBeenCalled(); + }); + }); + + describe('fire-and-forget behavior', () => { + it('calls storeLlmCall with the expected fields when runId is present', async () => { + mockStoreLlmCall.mockResolvedValueOnce(undefined); + + const payload: LlmCallLogPayload = { + runId: 'run-abc-123', + callNumber: 3, + model: 'claude-sonnet-4-5', + inputTokens: 500, + outputTokens: 200, + cachedTokens: undefined, + costUsd: undefined, + response: '["text block"]', + engineLabel: 'Claude Code', + }; + + logLlmCall(payload); + + // Give the microtask queue time to settle + await Promise.resolve(); + + expect(mockStoreLlmCall).toHaveBeenCalledOnce(); + expect(mockStoreLlmCall).toHaveBeenCalledWith({ + runId: 'run-abc-123', + callNumber: 3, + request: undefined, + response: '["text block"]', + inputTokens: 500, + outputTokens: 200, + cachedTokens: undefined, + costUsd: undefined, + durationMs: undefined, + model: 'claude-sonnet-4-5', + }); + }); + + it('passes cachedTokens and costUsd from OpenCode-style payloads', async () => { + mockStoreLlmCall.mockResolvedValueOnce(undefined); + + const payload: LlmCallLogPayload = { + runId: 'run-opencode-1', + callNumber: 2, + model: 'anthropic/claude-opus-4-5', + inputTokens: 1000, + outputTokens: 300, + cachedTokens: 400, + costUsd: 0.0045, + response: '{"type":"step-finish"}', + engineLabel: 'OpenCode', + }; + + logLlmCall(payload); + + await Promise.resolve(); + + expect(mockStoreLlmCall).toHaveBeenCalledWith( + expect.objectContaining({ + runId: 'run-opencode-1', + cachedTokens: 400, + costUsd: 0.0045, + }), + ); + }); + + it('passes costUsd from Codex-style payloads', async () => { + mockStoreLlmCall.mockResolvedValueOnce(undefined); + + const payload: LlmCallLogPayload = { + runId: 'run-codex-1', + callNumber: 5, + model: 'codex-mini-latest', + inputTokens: 800, + outputTokens: 150, + cachedTokens: 200, + costUsd: 0.002, + response: '{"total_cost_usd":0.002}', + engineLabel: 'Codex', + }; + + logLlmCall(payload); + + await Promise.resolve(); + + expect(mockStoreLlmCall).toHaveBeenCalledWith( + expect.objectContaining({ + costUsd: 0.002, + cachedTokens: 200, + }), + ); + }); + + it('always passes request as undefined', async () => { + mockStoreLlmCall.mockResolvedValueOnce(undefined); + + logLlmCall({ + runId: 'run-42', + callNumber: 1, + model: 'some-model', + engineLabel: 'Test', + }); + + await Promise.resolve(); + + expect(mockStoreLlmCall).toHaveBeenCalledWith( + expect.objectContaining({ request: undefined }), + ); + }); + }); + + describe('error catch logging', () => { + it('logs a warning with the engine label when storeLlmCall rejects', async () => { + const storageError = new Error('DB connection failed'); + mockStoreLlmCall.mockRejectedValueOnce(storageError); + + logLlmCall({ + runId: 'run-err-1', + callNumber: 7, + model: 'claude-haiku', + engineLabel: 'Claude Code', + }); + + // Let the rejection propagate through the microtask queue + await Promise.resolve(); + await Promise.resolve(); + + expect(mockLoggerWarn).toHaveBeenCalledOnce(); + expect(mockLoggerWarn).toHaveBeenCalledWith( + 'Failed to store Claude Code LLM call in real-time', + expect.objectContaining({ + runId: 'run-err-1', + call: 7, + error: 'Error: DB connection failed', + }), + ); + }); + + it('includes the engine label in the warning message for each engine', async () => { + for (const engineLabel of ['Claude Code', 'Codex', 'OpenCode']) { + mockStoreLlmCall.mockRejectedValueOnce(new Error('fail')); + + logLlmCall({ + runId: 'run-label-test', + callNumber: 1, + model: 'model', + engineLabel, + }); + + await Promise.resolve(); + await Promise.resolve(); + } + + expect(mockLoggerWarn).toHaveBeenCalledTimes(3); + expect(mockLoggerWarn.mock.calls[0][0]).toContain('Claude Code'); + expect(mockLoggerWarn.mock.calls[1][0]).toContain('Codex'); + expect(mockLoggerWarn.mock.calls[2][0]).toContain('OpenCode'); + }); + + it('does not throw even when storeLlmCall rejects', () => { + mockStoreLlmCall.mockRejectedValueOnce(new Error('boom')); + + expect(() => { + logLlmCall({ + runId: 'run-no-throw', + callNumber: 1, + model: 'model', + engineLabel: 'Test', + }); + }).not.toThrow(); + }); + }); +});