diff --git a/.changeset/sentry-allowlisted-logs.md b/.changeset/sentry-allowlisted-logs.md new file mode 100644 index 0000000000..5d00375096 --- /dev/null +++ b/.changeset/sentry-allowlisted-logs.md @@ -0,0 +1,6 @@ +--- +'@truefoundry/trueforge': patch +'@truefoundry/trueforge-core': patch +--- + +Report logged failures to Sentry except HTTP statuses from 200 through 499, including when that status sits on a wrapped cause. The log message is the Sentry title, and the thrown error is the cause and stack. Those events include the active tenant, request, session, and turn ids. Printed lines omit that marker even when Sentry is off. diff --git a/packages/trueforge-core/src/agent-session/SessionHandle.ts b/packages/trueforge-core/src/agent-session/SessionHandle.ts index 815dafee7c..16e1e4d187 100644 --- a/packages/trueforge-core/src/agent-session/SessionHandle.ts +++ b/packages/trueforge-core/src/agent-session/SessionHandle.ts @@ -336,6 +336,7 @@ export class SessionHandle< await input.resolver.close().catch((closeError: unknown) => { input.resolver.logger.warn('TurnResourceResolver.close() failed after createTurn() error', { err: closeError, + reportable_error: { error: closeError }, }); }); throw error; diff --git a/packages/trueforge-core/src/agent-session/TurnHandle.ts b/packages/trueforge-core/src/agent-session/TurnHandle.ts index 560bed739c..a101f20356 100644 --- a/packages/trueforge-core/src/agent-session/TurnHandle.ts +++ b/packages/trueforge-core/src/agent-session/TurnHandle.ts @@ -374,7 +374,10 @@ export class TurnHandle> { } await resolver.close().catch((err: unknown) => { - resolver.logger.warn('TurnResourceResolver.close() failed', { err }); + resolver.logger.warn('TurnResourceResolver.close() failed', { + err, + reportable_error: { error: err }, + }); }); if (!frozenByStore) { diff --git a/packages/trueforge-core/src/core/capabilities/builtins/LargeToolResponse.ts b/packages/trueforge-core/src/core/capabilities/builtins/LargeToolResponse.ts index 974782ea9e..c72f05552e 100644 --- a/packages/trueforge-core/src/core/capabilities/builtins/LargeToolResponse.ts +++ b/packages/trueforge-core/src/core/capabilities/builtins/LargeToolResponse.ts @@ -181,7 +181,10 @@ export class LargeToolResponseProcessor implements ToolResponseProcessor { entry.toolCallResult.isStructuredContent = false; return stored.sandboxCreated; } catch (error) { - this.logger.error('Failed to upload to sandbox', extractErrorLogFields(error)); + this.logger.error('Failed to upload to sandbox', { + ...extractErrorLogFields(error), + reportable_error: { error }, + }); return undefined; } } diff --git a/packages/trueforge-core/src/core/index.ts b/packages/trueforge-core/src/core/index.ts index ceb7c6a4f9..88a73d4b0d 100644 --- a/packages/trueforge-core/src/core/index.ts +++ b/packages/trueforge-core/src/core/index.ts @@ -158,7 +158,7 @@ export type { // Errors / utils export { AgentHarnessError, McpConnectionError, McpDcrConfigurationError } from './errors'; export { REDIS_KEY_NAMESPACE, redisKey } from './redisKeys'; -export { describeUnknownError, extractErrorLogFields } from './util/errorLogFields'; +export { describeUnknownError, extractErrorLogFields, isReportableError } from './util/errorLogFields'; export { DEFAULT_MCP_HTTP_BODY_TIMEOUT_MS, DEFAULT_MCP_HTTP_CONNECT_TIMEOUT_MS, @@ -181,6 +181,7 @@ export { ssrfFetch, } from './util/outboundFetch'; export { PromiseTimeoutError, withTimeout } from './util/promiseUtils'; +export { type ReportableErrorLog } from './util/reportableErrorLog'; export { assertSafeOutboundUrl, configureOutboundUrlGuard, diff --git a/packages/trueforge-core/src/core/llm/VercelAILLM.ts b/packages/trueforge-core/src/core/llm/VercelAILLM.ts index a1dc948d5c..fa59e0e893 100644 --- a/packages/trueforge-core/src/core/llm/VercelAILLM.ts +++ b/packages/trueforge-core/src/core/llm/VercelAILLM.ts @@ -35,7 +35,7 @@ import type { } from 'openai/resources/chat'; import type { Logger } from 'winston'; import { ModelProviderError } from '../errors'; -import { describeUnknownError, extractErrorLogFields } from '../util/errorLogFields'; +import { describeUnknownError, extractErrorLogFields, isReportableError } from '../util/errorLogFields'; import { modelSsrfFetch } from '../util/outboundFetch'; import type { ILLM, LLMCreateParams, LLMCreateParamsStreaming } from './ILLM'; import { @@ -1447,7 +1447,10 @@ export class VercelAILLM implements ILLM { if (this.signal?.aborted) { this.logger.debug('LLM call aborted', extractErrorLogFields(streamError)); } else { - this.logger.error('Error creating streaming chat completion', extractErrorLogFields(streamError)); + this.logger.error('Error creating streaming chat completion', { + ...extractErrorLogFields(streamError), + ...(isReportableError(error) ? { reportable_error: { error: streamError } } : {}), + }); } throw streamError; } @@ -1486,7 +1489,10 @@ export class VercelAILLM implements ILLM { if (this.signal?.aborted) { this.logger.debug('LLM stream aborted', extractErrorLogFields(streamError)); } else { - this.logger.error('Error reading LLM stream', extractErrorLogFields(streamError)); + this.logger.error('Error reading LLM stream', { + ...extractErrorLogFields(streamError), + ...(isReportableError(error) ? { reportable_error: { error: streamError } } : {}), + }); } throw streamError; } diff --git a/packages/trueforge-core/src/core/runtime/AgentThread.ts b/packages/trueforge-core/src/core/runtime/AgentThread.ts index a8338ae850..91b5eb429c 100644 --- a/packages/trueforge-core/src/core/runtime/AgentThread.ts +++ b/packages/trueforge-core/src/core/runtime/AgentThread.ts @@ -12,7 +12,7 @@ import type { } from '../capabilities/AgentContextProcessor'; import { SUB_AGENT_IDENTITY } from '../capabilities/builtins/DynamicSubAgents'; import type { ToolResponseProcessor } from '../capabilities/ToolResponseProcessor'; -import { AgentHarnessError, InvalidAgentSendInputError } from '../errors'; +import { AgentHarnessError, InvalidAgentSendInputError, ModelProviderError } from '../errors'; import type { RegisteredPassthroughEvent } from '../events/PassthroughEvents'; import { EventType, @@ -55,7 +55,7 @@ import { executeToolCalls } from '../mcp/executeToolCalls'; import type { IToolSet, MCPAuthRequired } from '../mcp/IMCPServer'; import type { HarnessSandbox, SandboxInfo } from '../sandbox/Sandbox'; import type { AgentTracing } from '../tracing/AgentTracing'; -import { describeUnknownError, extractErrorLogFields } from '../util/errorLogFields'; +import { describeUnknownError, extractErrorLogFields, isReportableError } from '../util/errorLogFields'; import type { AgentDefinition } from './AgentDefinition'; import type { AgentThreadConstructorInput, @@ -1516,7 +1516,11 @@ export class AgentThread { } catch (error) { // Providers / transports often reject with plain objects; instanceof Error would // otherwise collapse those into an opaque "Unknown error occurred" in Agent Steps. - this.logger.error('Agent thread execution failed', extractErrorLogFields(error)); + // Model-provider failures are classified at the LLM call. turn.done only keeps the message. + this.logger.error('Agent thread execution failed', { + ...extractErrorLogFields(error), + ...(error instanceof ModelProviderError || !isReportableError(error) ? {} : { reportable_error: { error } }), + }); yield this.generateErrorEvent(describeUnknownError(error)); } finally { this.contextBusy = false; diff --git a/packages/trueforge-core/src/core/sandbox/Sandbox.ts b/packages/trueforge-core/src/core/sandbox/Sandbox.ts index 9162eb1c6d..b08b0eb31e 100644 --- a/packages/trueforge-core/src/core/sandbox/Sandbox.ts +++ b/packages/trueforge-core/src/core/sandbox/Sandbox.ts @@ -541,7 +541,10 @@ export class Sandbox extends LocalToolMCP { try { ({ sandboxInfo, sandboxCreated } = await this.ensureReadySandbox()); } catch (e) { - this.logger.error('Sandbox initialization failed', extractErrorLogFields(e)); + this.logger.error('Sandbox initialization failed', { + ...extractErrorLogFields(e), + reportable_error: { error: e }, + }); const message = e instanceof Error ? e.message : 'Sandbox initialization failed'; const fallback = this.existingSandboxInfo; return toolResultResponse({ @@ -801,6 +804,7 @@ export class Sandbox extends LocalToolMCP { this.logger.error('Code Mode transport start failed', { ...extractErrorLogFields(e), sandboxId, + reportable_error: { error: e, extra: { sandboxId } }, }); return undefined; } diff --git a/packages/trueforge-core/src/core/sandbox/codeMode/CodeModeDispatcher.ts b/packages/trueforge-core/src/core/sandbox/codeMode/CodeModeDispatcher.ts index 1eb2953331..aa71150b3a 100644 --- a/packages/trueforge-core/src/core/sandbox/codeMode/CodeModeDispatcher.ts +++ b/packages/trueforge-core/src/core/sandbox/codeMode/CodeModeDispatcher.ts @@ -87,7 +87,10 @@ export class CodeModeDispatcher { } catch (e) { const source = classifyErrorSource(e); const errorMessage = e instanceof Error ? e.message : 'Unknown Code Mode dispatch error'; - this.logger.error(`Code Mode dispatch failed (source=${source})`, extractErrorLogFields(e)); + this.logger.error(`Code Mode dispatch failed (source=${source})`, { + ...extractErrorLogFields(e), + ...(source === 'internal' ? { reportable_error: { error: e, extra: { source } } } : {}), + }); return { ok: false, error: errorMessage, source }; } } diff --git a/packages/trueforge-core/src/core/sandbox/codeMode/nats/CodeModeNatsTransport.ts b/packages/trueforge-core/src/core/sandbox/codeMode/nats/CodeModeNatsTransport.ts index d028c716f9..d486f6d521 100644 --- a/packages/trueforge-core/src/core/sandbox/codeMode/nats/CodeModeNatsTransport.ts +++ b/packages/trueforge-core/src/core/sandbox/codeMode/nats/CodeModeNatsTransport.ts @@ -93,7 +93,10 @@ export class CodeModeNatsTransport implements CodeModeTransport { try { await withTimeout(nc.drain(), NATS_DRAIN_TIMEOUT_MS); } catch (e) { - this.logger.warn('Code Mode NATS drain failed/timed out; forcing close', extractErrorLogFields(e)); + this.logger.warn('Code Mode NATS drain failed/timed out; forcing close', { + ...extractErrorLogFields(e), + reportable_error: { error: e }, + }); await nc.close().catch(() => { /* no-op */ }); @@ -160,7 +163,10 @@ export class CodeModeNatsTransport implements CodeModeTransport { private async handleMessage(err: Error | null, msg: Msg): Promise { if (err) { - this.logger.error('Code Mode NATS subscription error', extractErrorLogFields(err)); + this.logger.error('Code Mode NATS subscription error', { + ...extractErrorLogFields(err), + reportable_error: { error: err }, + }); return; } if (!msg.reply) { @@ -173,7 +179,10 @@ export class CodeModeNatsTransport implements CodeModeTransport { try { msg.respond(this.encode({ ok: false, error: 'Code Mode dispatcher is not configured', source: 'internal' })); } catch (e) { - this.logger.warn(`Failed to send dispatcher-missing reply on '${msg.subject}'`, extractErrorLogFields(e)); + this.logger.warn(`Failed to send dispatcher-missing reply on '${msg.subject}'`, { + ...extractErrorLogFields(e), + reportable_error: { error: e }, + }); } return; } @@ -192,11 +201,17 @@ export class CodeModeNatsTransport implements CodeModeTransport { try { request = this.decode(msg); } catch (e) { - this.logger.error(`Failed to decode Code Mode NATS request on '${msg.subject}'`, extractErrorLogFields(e)); + this.logger.error(`Failed to decode Code Mode NATS request on '${msg.subject}'`, { + ...extractErrorLogFields(e), + reportable_error: { error: e }, + }); try { msg.respond(this.encode({ ok: false, error: 'Malformed Code Mode request', source: 'caller' })); } catch (respondErr) { - this.logger.warn(`Failed to send decode-error reply on '${msg.subject}'`, extractErrorLogFields(respondErr)); + this.logger.warn(`Failed to send decode-error reply on '${msg.subject}'`, { + ...extractErrorLogFields(respondErr), + reportable_error: { error: respondErr }, + }); } return; } @@ -205,7 +220,10 @@ export class CodeModeNatsTransport implements CodeModeTransport { try { msg.respond(this.encode(reply)); } catch (e) { - this.logger.error('Failed to publish Code Mode NATS reply', extractErrorLogFields(e)); + this.logger.error('Failed to publish Code Mode NATS reply', { + ...extractErrorLogFields(e), + reportable_error: { error: e }, + }); } } diff --git a/packages/trueforge-core/src/core/sandbox/provider/DaytonaProvider.ts b/packages/trueforge-core/src/core/sandbox/provider/DaytonaProvider.ts index 473cf3f513..a482280744 100644 --- a/packages/trueforge-core/src/core/sandbox/provider/DaytonaProvider.ts +++ b/packages/trueforge-core/src/core/sandbox/provider/DaytonaProvider.ts @@ -81,8 +81,6 @@ export interface DaytonaSandboxProviderOptions { /** Defaults to 1 hour (same as the gateway's max agent execution time). */ previewUrlExpirySeconds?: number; logger: Logger; - /** Host alert hook (e.g. Sentry P1). */ - onCriticalAlert?: (error: Error) => void; } export class DaytonaSandboxProvider implements SandboxProvider { @@ -99,7 +97,6 @@ export class DaytonaSandboxProvider implements SandboxProvider void) | undefined; private readonly daytona: Daytona; private static readonly cachedSandboxes = new Map(); // De-dupes concurrent recovery attempts on the same sandbox to a single refreshData+start round-trip. @@ -117,7 +114,6 @@ export class DaytonaSandboxProvider implements SandboxProvider= 500 + ? { + reportable_error: { + error: new Error(`Sandbox server returned ${String(response.status)}`), + extra: { status: response.status }, + }, + } + : {}), + }); return { success: false, error: `Sandbox server returned ${String(response.status)} from ${execUrl}: ${text}`, @@ -184,13 +194,18 @@ export class TFYSandboxProvider implements SandboxProvider { this.logger.error(`Sandbox exec timed out after ${String(timeoutSeconds)}s`, { url: execUrl, ...extractErrorLogFields(e), + reportable_error: { error: e }, }); return { success: false, error: `Sandbox exec to ${execUrl} timed out after ${String(timeoutSeconds)}s`, }; } - this.logger.error('Sandbox exec failed', { url: execUrl, ...extractErrorLogFields(e) }); + this.logger.error('Sandbox exec failed', { + url: execUrl, + ...extractErrorLogFields(e), + reportable_error: { error: e }, + }); return { success: false, error: `Sandbox exec to ${execUrl} failed: ${describeUnknownError(e)}`, diff --git a/packages/trueforge-core/src/core/util/errorLogFields.ts b/packages/trueforge-core/src/core/util/errorLogFields.ts index 32c6223f37..c883dd63b9 100644 --- a/packages/trueforge-core/src/core/util/errorLogFields.ts +++ b/packages/trueforge-core/src/core/util/errorLogFields.ts @@ -107,6 +107,40 @@ function stackWithCauses(error: Error): string | undefined { return stacks.length > 0 ? stacks.join('\nCaused by: ') : undefined; } +function readIntegerProperty(error: object, key: string): number | undefined { + if (!(key in error)) { + return undefined; + } + const value: unknown = Reflect.get(error, key); + return typeof value === 'number' && Number.isInteger(value) ? value : undefined; +} + +/** `statusCode` (AI SDK, MCP) or `status` (OAuth, HTTPException). */ +function readHttpStatus(error: object): number | undefined { + return readIntegerProperty(error, 'statusCode') ?? readIntegerProperty(error, 'status'); +} + +function httpStatusInChain(error: unknown, seen: Set): number | undefined { + if (typeof error !== 'object' || error === null || seen.has(error)) { + return undefined; + } + seen.add(error); + const status = readHttpStatus(error); + if (status !== undefined) { + return status; + } + if (!('cause' in error)) { + return undefined; + } + return httpStatusInChain(Reflect.get(error, 'cause'), seen); +} + +/** Every failure is reported except an HTTP status from 200 through 499, including on `cause`. */ +export function isReportableError(error: unknown): boolean { + const status = httpStatusInChain(error, new Set()); + return status === undefined || status > 499; +} + export function extractErrorLogFields(error: unknown): ErrorLogFields { if (error instanceof Error) { const chain = describeErrorChain(error, new Set()); diff --git a/packages/trueforge-core/src/core/util/promiseUtils.ts b/packages/trueforge-core/src/core/util/promiseUtils.ts index f146e1503d..fa5144ebeb 100644 --- a/packages/trueforge-core/src/core/util/promiseUtils.ts +++ b/packages/trueforge-core/src/core/util/promiseUtils.ts @@ -43,7 +43,10 @@ export async function* mergeAsyncGenerators( } const nextPromise = generator.next().then(result => ({ idx, result })); nextPromise.catch((error: unknown) => { - logger.error(`Unexpected error in mergeAsyncGenerators generator ${String(idx)}`, extractErrorLogFields(error)); + logger.error(`Unexpected error in mergeAsyncGenerators generator ${String(idx)}`, { + ...extractErrorLogFields(error), + reportable_error: { error, extra: { generator: idx } }, + }); }); return nextPromise; }; diff --git a/packages/trueforge-core/src/core/util/reportableErrorLog.ts b/packages/trueforge-core/src/core/util/reportableErrorLog.ts new file mode 100644 index 0000000000..ff218175d4 --- /dev/null +++ b/packages/trueforge-core/src/core/util/reportableErrorLog.ts @@ -0,0 +1,5 @@ +export interface ReportableErrorLog { + error: unknown; + extra?: Record; + filepath?: string; +} diff --git a/packages/trueforge-core/src/request-reply/executor.ts b/packages/trueforge-core/src/request-reply/executor.ts index b1936e8e91..8bc5ba019a 100644 --- a/packages/trueforge-core/src/request-reply/executor.ts +++ b/packages/trueforge-core/src/request-reply/executor.ts @@ -106,12 +106,20 @@ export class RequestReplyExecutor { this.logger.error('[RequestReplyExecutor] Subscriber error', { executorId: this.executorId, ...extractErrorLogFields(err), + reportable_error: { + error: err, + extra: { executorId: this.executorId }, + }, }); this.onError?.(err, { executorId: this.executorId, channel: this.channel }); // error is often transient; the client can reconnect and fire ready again. Do not stop the heartbeat. }); + // Shutdown drains the executor, then closes the client. That close emits `end`. + // Only an end while the executor is still open is an unexpected drop. this.subscriberClient.on('end', () => { - this.logger.warn('[RequestReplyExecutor] Subscriber connection ended', { executorId: this.executorId }); + this.logger.warn('[RequestReplyExecutor] Subscriber connection ended', { + executorId: this.executorId, + }); this.stopHeartbeat(); }); // ready fires on the first connect and every reconnect; re-subscribing is @@ -141,6 +149,10 @@ export class RequestReplyExecutor { this.logger.error('[RequestReplyExecutor] Error subscribing to request channel', { executorId: this.executorId, ...extractErrorLogFields(error), + reportable_error: { + error, + extra: { executorId: this.executorId }, + }, }); this.onError?.(error, { executorId: this.executorId, channel: this.channel }); this.stopHeartbeat(); @@ -155,6 +167,10 @@ export class RequestReplyExecutor { this.logger.error('[RequestReplyExecutor] Heartbeat error', { executorId: this.executorId, ...extractErrorLogFields(err), + reportable_error: { + error: err, + extra: { executorId: this.executorId }, + }, }); } } @@ -187,7 +203,13 @@ export class RequestReplyExecutor { raw = JSON.parse(message); } catch (err) { // Drop the request, this should never happen - this.logger.warn('[RequestReplyExecutor] Request message is not valid JSON', { executorId: this.executorId }); + this.logger.warn('[RequestReplyExecutor] Request message is not valid JSON', { + executorId: this.executorId, + reportable_error: { + error: err, + extra: { executorId: this.executorId }, + }, + }); this.onError?.( new Error(`Request message is not valid JSON for executorId: ${this.executorId}`, { cause: err, @@ -207,6 +229,10 @@ export class RequestReplyExecutor { this.logger.warn('[RequestReplyExecutor] Invalid request message shape', { executorId: this.executorId, zod: zodError, + reportable_error: { + error: parsedRequest.error, + extra: { executorId: this.executorId }, + }, }); this.onError?.( new Error( @@ -239,6 +265,10 @@ export class RequestReplyExecutor { executorId: this.executorId, replyKey, ...extractErrorLogFields(err), + reportable_error: { + error: err, + extra: { executorId: this.executorId }, + }, }); } } diff --git a/packages/trueforge-core/tests/core/llm/VercelAILLM.stream.test.ts b/packages/trueforge-core/tests/core/llm/VercelAILLM.stream.test.ts index 593e2f3bb4..4d3b3e703f 100644 --- a/packages/trueforge-core/tests/core/llm/VercelAILLM.stream.test.ts +++ b/packages/trueforge-core/tests/core/llm/VercelAILLM.stream.test.ts @@ -20,6 +20,7 @@ import { normalizeUsage, toStreamError, } from '../../../src/core/llm/VercelAILLM'; +import { isReportableError } from '../../../src/core/util/errorLogFields'; // ─────────── Helpers ─────────── @@ -685,3 +686,53 @@ describe('mapStreamToChunks', () => { expect(nonFinishChunks).toHaveLength(0); }); }); + +describe('isReportableError', () => { + it('reports timeouts, dropped connections, and provider 5xx', () => { + const timedOut = new Error('timed out'); + timedOut.name = 'TimeoutError'; + const refused = new TypeError('fetch failed', { + cause: Object.assign(new Error('connect ECONNREFUSED'), { code: 'ECONNREFUSED' }), + }); + const providerNetwork = new APICallError({ + message: 'fetch failed', + url: 'https://example.com', + requestBodyValues: {}, + cause: Object.assign(new Error('socket hang up'), { code: 'ECONNRESET' }), + }); + const providerOutage = new APICallError({ + message: 'provider unavailable', + url: 'https://example.com', + requestBodyValues: {}, + statusCode: 503, + }); + + expect(isReportableError(timedOut)).toBe(true); + expect(isReportableError(refused)).toBe(true); + expect(isReportableError(providerNetwork)).toBe(true); + expect(isReportableError(providerOutage)).toBe(true); + expect(isReportableError(new Error('model produced an invalid tool call'))).toBe(true); + }); + + it('skips a stream error part that wraps a provider 4xx with a socket cause', async () => { + const cause = new APICallError({ + message: 'rate limit', + url: 'https://example.com', + requestBodyValues: {}, + statusCode: 429, + cause: Object.assign(new Error('socket hang up'), { code: 'ECONNRESET' }), + }); + let thrown: unknown; + try { + await drainStream( + mapStreamToChunks({ + stream: makeStream([{ type: 'error', error: cause }]), + chunkMeta: CHUNK_META, + }), + ); + } catch (error) { + thrown = error; + } + expect(isReportableError(thrown)).toBe(false); + }); +}); diff --git a/packages/trueforge/src/apis/auth.ts b/packages/trueforge/src/apis/auth.ts index 8998bfc498..c87322921a 100644 --- a/packages/trueforge/src/apis/auth.ts +++ b/packages/trueforge/src/apis/auth.ts @@ -1,5 +1,5 @@ import { OpenAPIHono } from '@hono/zod-openapi'; -import { extractErrorLogFields } from '@truefoundry/trueforge-core/core'; +import { extractErrorLogFields, isReportableError } from '@truefoundry/trueforge-core/core'; import type { Context, MiddlewareHandler } from 'hono'; import type { Configuration } from 'openid-client'; import type { Logger } from 'winston'; @@ -61,7 +61,10 @@ export function createAuthRouter(params: { }); return c.redirect(authorizationUrl, 302); } catch (error) { - params.logger.error('Failed to build login authorization', extractErrorLogFields(error)); + params.logger.error('Failed to build login authorization', { + ...extractErrorLogFields(error), + reportable_error: { error }, + }); return c.redirect(oauthErrorRedirect('login_failed'), 302); } } @@ -70,7 +73,10 @@ export function createAuthRouter(params: { try { return c.redirect(resolveTrueFoundryLoginReturnTo(returnTo), 302); } catch (error) { - params.logger.error('Failed to build TrueFoundry external login URL', extractErrorLogFields(error)); + params.logger.error('Failed to build TrueFoundry external login URL', { + ...extractErrorLogFields(error), + reportable_error: { error }, + }); return c.redirect(oauthErrorRedirect('login_failed'), 302); } } @@ -114,7 +120,10 @@ export function createAuthRouter(params: { }); return c.redirect(safeReturnTo(pending.return_to), 302); } catch (error) { - params.logger.error('Failed to exchange authorization code', extractErrorLogFields(error)); + params.logger.error('Failed to exchange authorization code', { + ...extractErrorLogFields(error), + ...(isReportableError(error) ? { reportable_error: { error } } : {}), + }); const soft = await redirectIfAlreadyAuthenticated({ context: c, whenAuthenticated: safeReturnTo(pending.return_to), diff --git a/packages/trueforge/src/apis/mcpOAuth.ts b/packages/trueforge/src/apis/mcpOAuth.ts index d00d82dd87..5c24c6c49f 100644 --- a/packages/trueforge/src/apis/mcpOAuth.ts +++ b/packages/trueforge/src/apis/mcpOAuth.ts @@ -119,7 +119,10 @@ export function createMcpOAuthRouter(deps: McpOAuthRouterDeps(deps: McpServersRouterDeps< } return c.json({ error: { message: error.message } }, 500); } - deps.logger.error(`MCP authorize unexpected failure for "${name}"`, extractErrorLogFields(error)); + deps.logger.error(`MCP authorize unexpected failure for "${name}"`, { + ...extractErrorLogFields(error), + reportable_error: { error, extra: { mcp_server_name: name } }, + }); return c.json({ error: { message: 'Internal server error' } }, 500); } }; diff --git a/packages/trueforge/src/apis/sessions.ts b/packages/trueforge/src/apis/sessions.ts index 28209b8246..e99ebd7e18 100644 --- a/packages/trueforge/src/apis/sessions.ts +++ b/packages/trueforge/src/apis/sessions.ts @@ -202,9 +202,15 @@ export async function cancelSessionTurn( ...extractErrorLogFields(error), }; if (error instanceof RequestTimeoutError) { - deps.logger.warn('Timed out waiting for owning executor to cancel; freezing the running turn', fields); + deps.logger.warn('Timed out waiting for owning executor to cancel; freezing the running turn', { + ...fields, + reportable_error: { error, extra: { turn_id: turnId, owner } }, + }); } else { - deps.logger.warn('Failed to reach owning executor over Redis; freezing the running turn', fields); + deps.logger.warn('Failed to reach owning executor over Redis; freezing the running turn', { + ...fields, + reportable_error: { error, extra: { turn_id: turnId, owner } }, + }); } } await freezeTurnIgnoringMissing(deps.session, { turnId, reason }); diff --git a/packages/trueforge/src/apis/turns.ts b/packages/trueforge/src/apis/turns.ts index 26995c0870..2753f353dc 100644 --- a/packages/trueforge/src/apis/turns.ts +++ b/packages/trueforge/src/apis/turns.ts @@ -377,6 +377,29 @@ export function turnStreamId(tenantId: string, sessionId: string, turnId: string return redisKey('agent', 'turn', tenantId, sessionId, turnId, 'stream'); } +/** Client cancel and a turn replaced by the next one are expected endings. */ +function reportUnexpectedTurnDone({ event, logger }: { event: TurnStreamingEvent; logger: Logger }): void { + if (event.type !== EventType.TURN_DONE) { + return; + } + const { state } = event; + if (state.status === 'error') { + // Only the message remains here. The thrown error was already classified, including provider 4xx. + logger.error('turn.done error', extractErrorLogFields(new Error(state.message))); + return; + } + if ( + state.status === 'cancelled' && + (state.reason === CancellationReason.Abandoned || state.reason === CancellationReason.ServerExecutionTimeout) + ) { + const error = new Error(state.reason); + logger.error('turn.done cancelled', { + ...extractErrorLogFields(error), + reportable_error: { error, extra: { reason: state.reason } }, + }); + } +} + /** * Dual-write turn events to the resumable subscription registry, then optionally * forward each sequenced event (SSE path). Shared by streaming and non-streaming @@ -392,6 +415,7 @@ export async function drainTurnEvents(input: { const { trackedStream, turnEventStream, maxExecutionTimer, logger, onEvent } = input; try { for await (const event of trackedStream) { + reportUnexpectedTurnDone({ event, logger }); // Dual-write before any client sink so subscribers can resume after disconnect. const sequenceNumber = await turnEventStream.put(event, { streamTTLSeconds: streamTTLSecondsFor(event), @@ -402,7 +426,10 @@ export async function drainTurnEvents(input: { if (error instanceof SessionStoreNotFoundError) { logger.warn('Turn stream ended after session/turn was removed', extractErrorLogFields(error)); } else { - logger.error('Unexpected error in turn event drain', extractErrorLogFields(error)); + logger.error('Unexpected error in turn event drain', { + ...extractErrorLogFields(error), + reportable_error: { error }, + }); } } finally { clearTimeout(maxExecutionTimer); @@ -725,6 +752,7 @@ export function createTurnsRouter(deps: TurnsRouterDeps) { ...extractErrorLogFields(error), sandboxId, path, + reportable_error: { error, extra: { sandboxId, path } }, }); return c.json({ error: { message: 'Failed to download file from sandbox' } }, 424); } @@ -968,7 +996,10 @@ export function createTurnsRouter(deps: TurnsRouterDeps) { } } catch (error) { if (!subscribeAbort.signal.aborted) { - deps.logger.error('Unexpected error in turn subscribe SSE loop', extractErrorLogFields(error)); + deps.logger.error('Unexpected error in turn subscribe SSE loop', { + ...extractErrorLogFields(error), + reportable_error: { error }, + }); } } finally { clearTimeout(timeoutHandler); diff --git a/packages/trueforge/src/app.ts b/packages/trueforge/src/app.ts index b66bbab552..85656c178e 100644 --- a/packages/trueforge/src/app.ts +++ b/packages/trueforge/src/app.ts @@ -159,6 +159,7 @@ export function createAppErrorHandler(params: { logger: Logger }): ErrorHandler path: c.req.path, status, ...extractErrorLogFields(error), + ...(status >= 500 ? { reportable_error: { error } } : {}), }; if (status >= 500) { params.logger.error(message, fields); diff --git a/packages/trueforge/src/controller.ts b/packages/trueforge/src/controller.ts index 21e5958f61..6c28b34d31 100644 --- a/packages/trueforge/src/controller.ts +++ b/packages/trueforge/src/controller.ts @@ -54,7 +54,11 @@ export function runController(params: { // Passes only hold short transactions, so the deadline should never elapse. setTimeout(() => { - logger.warn(`Controller drain timed out after ${String(gracefulTimeoutSeconds)}s, exiting`); + logger.warn(`Controller drain timed out after ${String(gracefulTimeoutSeconds)}s, exiting`, { + reportable_error: { + error: new Error(`Controller drain timed out after ${String(gracefulTimeoutSeconds)}s, exiting`), + }, + }); process.exit(1); }, gracefulTimeoutSeconds * 1000).unref(); diff --git a/packages/trueforge/src/controller/Controller.ts b/packages/trueforge/src/controller/Controller.ts index 04b5de6bcd..9cb32d957b 100644 --- a/packages/trueforge/src/controller/Controller.ts +++ b/packages/trueforge/src/controller/Controller.ts @@ -119,7 +119,11 @@ export class Controller { if (signal.aborted) { return; } - this.#logger.error('Control loop pass failed', { loop: loop.name, error }); + this.#logger.error('Control loop pass failed', { + loop: loop.name, + error, + reportable_error: { error, extra: { loop: loop.name } }, + }); } })(); diff --git a/packages/trueforge/src/controller/sandboxEnvBuild.ts b/packages/trueforge/src/controller/sandboxEnvBuild.ts index 865f4c4cc3..c1ff4eba0a 100644 --- a/packages/trueforge/src/controller/sandboxEnvBuild.ts +++ b/packages/trueforge/src/controller/sandboxEnvBuild.ts @@ -1,9 +1,8 @@ /** * Control loop: list pending sandbox-env versions and hand each to the server over HTTP. */ -import { TrueForgeApi } from '@truefoundry/trueforge-sdk'; +import { TrueForgeApi, TrueForgeError } from '@truefoundry/trueforge-sdk'; import type { Logger } from 'winston'; -import { captureCriticalException } from '../sentry'; import type { ControlLoop } from './Controller'; import { internalTrueForgeClient } from './internalTrueForgeClient'; @@ -25,19 +24,21 @@ export async function dispatchSandboxEnvBuilds({ logger }: { logger: Logger }): logger.warn('Sandbox environment version not found; skipping', { environment_version_id: environmentVersionId, }); - captureCriticalException(error, { - tags: { module: 'sandboxEnvBuild', operation: 'progressNotFound' }, - extra: { environment_version_id: environmentVersionId }, - }); continue; } + // A status means the API handler already logged the failure. Report a call that got no response. + const serverResponded = error instanceof TrueForgeError && typeof error.statusCode === 'number'; logger.error('Sandbox environment version progress failed', { environment_version_id: environmentVersionId, error: error instanceof Error ? error.message : String(error), - }); - captureCriticalException(error, { - tags: { module: 'sandboxEnvBuild', operation: 'progress' }, - extra: { environment_version_id: environmentVersionId }, + ...(serverResponded + ? {} + : { + reportable_error: { + error, + extra: { environment_version_id: environmentVersionId }, + }, + }), }); } } diff --git a/packages/trueforge/src/controller/scheduleDispatch.ts b/packages/trueforge/src/controller/scheduleDispatch.ts index c1dd6797bc..cd2f754d48 100644 --- a/packages/trueforge/src/controller/scheduleDispatch.ts +++ b/packages/trueforge/src/controller/scheduleDispatch.ts @@ -10,7 +10,6 @@ import { import type { WithTransaction } from '../db/transaction'; import { nextTriggerAfter } from '../runtime/cron'; import { InvalidCronError, type ScheduleRunStatus } from '../schemas/schedule'; -import { captureCriticalException } from '../sentry'; import type { ControlLoop } from './Controller'; import { internalTrueForgeClient } from './internalTrueForgeClient'; @@ -295,13 +294,13 @@ export async function dispatchScheduledRuns(params: { schedule_id: schedule.id, run_id: run.id, error, - }); - captureCriticalException(error, { - tags: { module: 'scheduleDispatch', operation: 'handoff' }, - extra: { - tenant_id: run.tenant_id, - schedule_id: schedule.id, - run_id: run.id, + reportable_error: { + error, + extra: { + tenant_id: run.tenant_id, + schedule_id: schedule.id, + run_id: run.id, + }, }, }); await finishScheduledRun({ @@ -329,13 +328,13 @@ export async function dispatchScheduledRuns(params: { schedule_id: run.schedule_id, run_id: run.id, error, - }); - captureCriticalException(error, { - tags: { module: 'scheduleDispatch', operation: 'processRun' }, - extra: { - tenant_id: run.tenant_id, - schedule_id: run.schedule_id, - run_id: run.id, + reportable_error: { + error, + extra: { + tenant_id: run.tenant_id, + schedule_id: run.schedule_id, + run_id: run.id, + }, }, }); } diff --git a/packages/trueforge/src/logger.ts b/packages/trueforge/src/logger.ts index f6c366e092..6a1ddcb98a 100644 --- a/packages/trueforge/src/logger.ts +++ b/packages/trueforge/src/logger.ts @@ -131,11 +131,19 @@ function jsonFormat(): winston.Logform.Format { ); } +/** Logging metadata. Removed before print so a line never shows it when Sentry does not start. */ +function omitReportableErrorFormat(): winston.Logform.Format { + return winston.format(info => { + Reflect.deleteProperty(info, 'reportable_error'); + return info; + })(); +} + function serverLogFormat(options: { standalone: boolean }): winston.Logform.Format { - if (options.standalone) { - return standaloneFormat(shouldColorize()); - } - return jsonFormat(); + return winston.format.combine( + omitReportableErrorFormat(), + options.standalone ? standaloneFormat(shouldColorize()) : jsonFormat(), + ); } function createLogger(options: { level: string; standalone: boolean; component: 'server' | 'controller' }): Logger { diff --git a/packages/trueforge/src/main.ts b/packages/trueforge/src/main.ts index 6098482859..51de5e35b5 100644 --- a/packages/trueforge/src/main.ts +++ b/packages/trueforge/src/main.ts @@ -330,8 +330,9 @@ function buildResolveAgentStore(options: { persistenceStore: PostgresAgentStore; db: Kysely; client: TrueFoundryServiceFoundryServerClient | undefined; + logger: Logger; }): (rc: RequestContext) => IAgentStore> { - const { persistenceStore, client, db } = options; + const { persistenceStore, client, db, logger } = options; return rc => { if (client) { return new TrueFoundryAgentStore({ @@ -339,6 +340,7 @@ function buildResolveAgentStore(options: { client, context: rc, db, + logger, }); } return persistenceStore; @@ -568,6 +570,7 @@ async function createDistributedPersistence(options: { persistenceStore: agentStore, db, client: serviceFoundryClient, + logger, }); const resolveSandboxProviderStore = buildResolveSandboxProviderStore({ persistenceStore: sandboxProviderStore, @@ -862,7 +865,10 @@ try { if (redis.mode !== 'sentinel') { requestReplySubscriber = redis.client.duplicate(); requestReplySubscriber.on('error', (error: Error) => { - logger.error('[RedisSubscriber] Client error', extractErrorLogFields(error)); + logger.error('[RedisSubscriber] Client error', { + ...extractErrorLogFields(error), + reportable_error: { error }, + }); }); await requestReplySubscriber.connect(); } else { @@ -921,7 +927,11 @@ try { // Arm at the start of each shutdown; unref so this timer alone cannot keep the process alive. setTimeout(() => { - logger.warn(`Drain timed out after ${String(configuration.GRACEFUL_TIMEOUT_SECONDS)}s, exiting`); + logger.warn(`Drain timed out after ${String(configuration.GRACEFUL_TIMEOUT_SECONDS)}s, exiting`, { + reportable_error: { + error: new Error(`Drain timed out after ${String(configuration.GRACEFUL_TIMEOUT_SECONDS)}s, exiting`), + }, + }); process.exit(1); }, configuration.GRACEFUL_TIMEOUT_SECONDS * 1000).unref(); diff --git a/packages/trueforge/src/runtime/redis.ts b/packages/trueforge/src/runtime/redis.ts index 9563ba04b3..4895f73a83 100644 --- a/packages/trueforge/src/runtime/redis.ts +++ b/packages/trueforge/src/runtime/redis.ts @@ -152,7 +152,10 @@ async function connectSentinelWithRetry(input: { }); // Without an 'error' listener node-redis crashes the process on emit. client.on('error', (error: Error) => { - input.logger.error('[Redis] Client error', extractErrorLogFields(error)); + input.logger.error('[Redis] Client error', { + ...extractErrorLogFields(error), + reportable_error: { error }, + }); }); try { await client.connect(); @@ -171,6 +174,7 @@ async function connectSentinelWithRetry(input: { input.logger.error('[Redis] Sentinel connect failed, rebuilding and retrying', { attempt, ...extractErrorLogFields(error), + reportable_error: { error, extra: { attempt } }, }); await sleep(Math.min(SENTINEL_RETRY_BASE_MS * 2 ** attempt, SENTINEL_RETRY_MAX_MS)); } @@ -215,7 +219,10 @@ export async function connectRedis(input: ConnectRedisInput): Promise { - input.logger.error('[Redis] Client error', extractErrorLogFields(error)); + input.logger.error('[Redis] Client error', { + ...extractErrorLogFields(error), + reportable_error: { error }, + }); }); await created.connect(); input.logger.info('Connected to Redis'); diff --git a/packages/trueforge/src/sandbox/progressSandboxEnvironmentVersion.ts b/packages/trueforge/src/sandbox/progressSandboxEnvironmentVersion.ts index 6a803aa4d6..0e345a33e8 100644 --- a/packages/trueforge/src/sandbox/progressSandboxEnvironmentVersion.ts +++ b/packages/trueforge/src/sandbox/progressSandboxEnvironmentVersion.ts @@ -11,7 +11,6 @@ import { toSandboxEnvironment, toSandboxStatus, } from '../sandbox/providerUtils'; -import { captureCriticalException } from '../sentry'; export async function progressSandboxEnvironmentVersion({ sandboxEnvironmentStore, @@ -27,9 +26,8 @@ export async function progressSandboxEnvironmentVersion({ const pending = await sandboxEnvironmentStore.getSandboxEnvironmentVersion({ environment_version_id }); if (pending === undefined) { const error = new HTTPException(404, { message: 'Sandbox environment version not found' }); - captureCriticalException(error, { - tags: { module: 'progressSandboxEnvironmentVersion', operation: 'notFound' }, - extra: { environment_version_id }, + logger.warn('Sandbox environment version not found', { + environment_version_id, }); throw error; } @@ -77,16 +75,8 @@ export async function progressSandboxEnvironmentVersion({ environment_version_id, status_reason, }); - captureCriticalException(error, { - tags: { module: 'progressSandboxEnvironmentVersion', operation: 'authz' }, - extra: { environment_version_id, tenant_id: pending.tenant_id, status_reason }, - }); return; } - captureCriticalException(error, { - tags: { module: 'progressSandboxEnvironmentVersion', operation: 'build' }, - extra: { environment_version_id, tenant_id: pending.tenant_id }, - }); throw error; } } diff --git a/packages/trueforge/src/sandbox/providerUtils.ts b/packages/trueforge/src/sandbox/providerUtils.ts index fc74a13653..9dbfefc05a 100644 --- a/packages/trueforge/src/sandbox/providerUtils.ts +++ b/packages/trueforge/src/sandbox/providerUtils.ts @@ -16,7 +16,6 @@ import { type SandboxStatus, type StoredSandboxProviderManifest, } from '../schemas/sandboxProvider'; -import { captureCriticalException } from '../sentry'; /** Bound Daytona RPCs so API requests and controller ticks cannot hang indefinitely. */ export const DAYTONA_RPC_TIMEOUT_MS = 5_000; @@ -110,11 +109,6 @@ export function toDaytonaSandboxProvider({ tenantName: tenant_id, fileMaxBytesForDownload: configuration.SANDBOX_FILE_MAX_BYTES_FOR_DOWNLOAD, logger, - onCriticalAlert: error => { - captureCriticalException(error, { - tags: { module: 'DaytonaProvider', operation: 'sandboxCreate', priority: 'P1' }, - }); - }, }); } diff --git a/packages/trueforge/src/sentry/captureCriticalException.ts b/packages/trueforge/src/sentry/captureCriticalException.ts index 062ae33971..4830c0ce13 100644 --- a/packages/trueforge/src/sentry/captureCriticalException.ts +++ b/packages/trueforge/src/sentry/captureCriticalException.ts @@ -1,12 +1,32 @@ import * as Sentry from '@sentry/node'; +import { currentLogContext, type LogContext } from '../logger'; + +const LOG_CONTEXT_TAG_KEYS: (keyof LogContext)[] = ['tenant_id', 'request_id', 'session_id', 'turn_id']; + +function logContextTags(): Record { + const context = currentLogContext(); + if (context === undefined) { + return {}; + } + const tags: Record = {}; + for (const key of LOG_CONTEXT_TAG_KEYS) { + const value = context[key]; + if (value !== undefined) { + tags[key] = value; + } + } + return tags; +} + export function captureCriticalException( err: unknown, options?: { tags?: Record; extra?: Record }, ): void { + const tags: Record = { ...logContextTags(), ...options?.tags }; Sentry.withScope(scope => { - if (options?.tags) { - scope.setTags(options.tags); + if (Object.keys(tags).length > 0) { + scope.setTags(tags); } if (options?.extra) { scope.setExtras(options.extra); diff --git a/packages/trueforge/src/sentry/initSentry.ts b/packages/trueforge/src/sentry/initSentry.ts index 0fd48a8384..53c5df64b8 100644 --- a/packages/trueforge/src/sentry/initSentry.ts +++ b/packages/trueforge/src/sentry/initSentry.ts @@ -1,9 +1,10 @@ import * as Sentry from '@sentry/node'; -import type { Logger } from 'winston'; +import winston, { type Logger } from 'winston'; import { isTrueFoundryModeEnabled, type ServerConfiguration } from '../config'; import { PACKAGE_VERSION } from '../packageVersion'; import { initTrueFoundrySentry } from '../truefoundry/initTrueFoundrySentry'; +import { reportMarkedLogFormat } from './reportMarkedLog'; function isLocalLikeEnv(nodeEnv: string | undefined): boolean { return nodeEnv === 'development' || nodeEnv === 'test' || nodeEnv === 'local'; @@ -20,9 +21,13 @@ export interface InitSentryOptions { tags?: Record; } +function attachMarkedLogReporting(logger: Pick): void { + logger.format = winston.format.combine(reportMarkedLogFormat(), logger.format); +} + export async function initSentry( config: ServerConfiguration, - logger: Pick, + logger: Pick, options?: InitSentryOptions, ): Promise { if (!config.SENTRY_ENABLED || isLocalLikeEnv(config.NODE_ENV)) { @@ -38,7 +43,10 @@ export async function initSentry( }; if (isTrueFoundryModeEnabled(config)) { - await initTrueFoundrySentry({ logger, tags: globalTags }); + const ready = await initTrueFoundrySentry({ logger, tags: globalTags }); + if (ready) { + attachMarkedLogReporting(logger); + } return; } @@ -51,8 +59,9 @@ export async function initSentry( dsn, includeLocalVariables: false, defaultIntegrations: false, - integrations: [], + integrations: [Sentry.linkedErrorsIntegration()], }); applyGlobalTags(globalTags); + attachMarkedLogReporting(logger); logger.info('Sentry initialised'); } diff --git a/packages/trueforge/src/sentry/reportMarkedLog.ts b/packages/trueforge/src/sentry/reportMarkedLog.ts new file mode 100644 index 0000000000..c83c05a80f --- /dev/null +++ b/packages/trueforge/src/sentry/reportMarkedLog.ts @@ -0,0 +1,85 @@ +import winston from 'winston'; +import { captureCriticalException } from './captureCriticalException'; + +function readExtra(value: unknown): Record | undefined { + if (typeof value !== 'object' || value === null || Array.isArray(value)) { + return undefined; + } + const extra: Record = {}; + for (const key of Object.keys(value)) { + extra[key] = Reflect.get(value, key); + } + return extra; +} + +function readFilePath(value: unknown): string | undefined { + if (typeof value !== 'object' || value === null || !('filepath' in value)) { + return undefined; + } + const filepath = Reflect.get(value, 'filepath'); + if (typeof filepath !== 'string' || filepath.length === 0) { + return undefined; + } + return filepath; +} + +function readReportableError( + value: unknown, +): { error: unknown; extra: Record | undefined; filepath: string | undefined } | undefined { + if (typeof value !== 'object' || value === null || !('error' in value)) { + return undefined; + } + return { + error: Reflect.get(value, 'error'), + extra: readExtra(Reflect.get(value, 'extra')), + filepath: readFilePath(value), + }; +} + +function toError(value: unknown): Error | undefined { + if (value instanceof Error) { + return value; + } + if (typeof value !== 'string' || value.length === 0) { + return undefined; + } + return new Error(value, { cause: value }); +} + +/** Log message is the Sentry title. The thrown error stays the cause and supplies the stack frames. */ +function errorWithLogTitle({ message, cause }: { message: string; cause: Error }): Error { + const titled = new Error(message, { cause }); + const causeStack = cause.stack; + if (causeStack === undefined) { + titled.stack = `${titled.name}: ${message}`; + return titled; + } + const frameStart = causeStack.indexOf('\n'); + const frames = frameStart === -1 ? '' : causeStack.slice(frameStart); + titled.stack = `${titled.name}: ${message}${frames}`; + return titled; +} + +function reportedError({ message, cause }: { message: unknown; cause: Error }): Error { + if (typeof message === 'string' && message.length > 0) { + return errorWithLogTitle({ message, cause }); + } + return cause; +} + +export function reportMarkedLogFormat(): winston.Logform.Format { + return winston.format(info => { + const marked = readReportableError(info['reportable_error']); + if (marked !== undefined) { + const cause = toError(marked.error); + if (cause !== undefined) { + captureCriticalException(reportedError({ message: info.message, cause }), { + ...(marked.filepath !== undefined ? { tags: { filepath: marked.filepath } } : {}), + ...(marked.extra !== undefined ? { extra: marked.extra } : {}), + }); + } + } + Reflect.deleteProperty(info, 'reportable_error'); + return info; + })(); +} diff --git a/packages/trueforge/src/truefoundry/TrueFoundryAgentStore.ts b/packages/trueforge/src/truefoundry/TrueFoundryAgentStore.ts index c6b7464ad9..facf72094f 100644 --- a/packages/trueforge/src/truefoundry/TrueFoundryAgentStore.ts +++ b/packages/trueforge/src/truefoundry/TrueFoundryAgentStore.ts @@ -1,5 +1,7 @@ import type { AgentSpec, TokenPagination } from '@truefoundry/trueforge-core/agent-session'; +import { extractErrorLogFields } from '@truefoundry/trueforge-core/core'; import { sql, type Kysely, type Transaction } from 'kysely'; +import type { Logger } from 'winston'; import type { RequestContext } from '../auth/identity'; import { type AgentCatalogUsageRow, @@ -19,7 +21,6 @@ import { import { PostgresAgentStore } from '../db/postgres/agent-store/PostgresAgentStore'; import type { Database } from '../db/postgres/types'; import { AGENT_DESCRIPTION_MAX_LENGTH } from '../schemas/agent'; -import { captureCriticalException } from '../sentry'; import { callerAccessToken, type ResolveServiceFoundryAuthorization } from './accessToken'; import { TrueFoundryServiceFoundryServerClient, @@ -80,17 +81,20 @@ export class TrueFoundryAgentStore implements IAgentStore> readonly #client: TrueFoundryServiceFoundryServerClient; readonly #resolveAccessToken: ResolveServiceFoundryAuthorization; readonly #db: Kysely; + readonly #logger: Logger; constructor(input: { inner: PostgresAgentStore; client: TrueFoundryServiceFoundryServerClient; context: RequestContext; db: Kysely; + logger: Logger; }) { this.#inner = input.inner; this.#client = input.client; this.#resolveAccessToken = callerAccessToken(input.context); this.#db = input.db; + this.#logger = input.logger; } listAgents( @@ -190,13 +194,20 @@ export class TrueFoundryAgentStore implements IAgentStore> const aggregate = new AggregateError(failures, 'createAgent failed and cleanup also failed', { cause: error, }); - captureCriticalException(aggregate, { - tags: { module: 'TrueFoundryAgentStore', operation: 'dualWrite' }, - extra: { - agent_id: created.id, - agent_name: created.name, - tenant_id: input.tenant_id, - external_id: externalId, + this.#logger.error('createAgent failed and cleanup also failed', { + ...extractErrorLogFields(aggregate), + agent_id: created.id, + agent_name: created.name, + tenant_id: input.tenant_id, + external_id: externalId, + reportable_error: { + error: aggregate, + extra: { + agent_id: created.id, + agent_name: created.name, + tenant_id: input.tenant_id, + external_id: externalId, + }, }, }); throw aggregate; @@ -256,13 +267,20 @@ export class TrueFoundryAgentStore implements IAgentStore> 'updateAgent failed and ServiceFoundry restore also failed', { cause: restoreError }, ); - captureCriticalException(aggregate, { - tags: { module: 'TrueFoundryAgentStore', operation: 'dualWrite' }, - extra: { - agent_id: input.id, - agent_name: previous.name, - tenant_id: input.tenant_id, - external_id: previous.external_id, + this.#logger.error('updateAgent failed and ServiceFoundry restore also failed', { + ...extractErrorLogFields(aggregate), + agent_id: input.id, + agent_name: previous.name, + tenant_id: input.tenant_id, + external_id: previous.external_id, + reportable_error: { + error: aggregate, + extra: { + agent_id: input.id, + agent_name: previous.name, + tenant_id: input.tenant_id, + external_id: previous.external_id, + }, }, }); throw aggregate; diff --git a/packages/trueforge/src/truefoundry/TrueFoundryServiceFoundryServerClient.ts b/packages/trueforge/src/truefoundry/TrueFoundryServiceFoundryServerClient.ts index 58cf51f576..81e013d20d 100644 --- a/packages/trueforge/src/truefoundry/TrueFoundryServiceFoundryServerClient.ts +++ b/packages/trueforge/src/truefoundry/TrueFoundryServiceFoundryServerClient.ts @@ -272,6 +272,7 @@ export class TrueFoundryServiceFoundryServerClient { if (!parsed.success) { this.#logger.error('TrueFoundry ServiceFoundry put remote agent returned an unexpected response', { ...extractErrorLogFields(parsed.error), + reportable_error: { error: parsed.error }, }); throw new HTTPException(424, { message: 'TrueFoundry ServiceFoundry put remote agent returned an unexpected response', @@ -422,6 +423,7 @@ export class TrueFoundryServiceFoundryServerClient { this.#logger.error('TrueFoundry ServiceFoundry MCP authorize returned an unexpected response', { mcpServerId: input.mcpServerId, ...extractErrorLogFields(error), + reportable_error: { error, extra: { mcp_server_id: input.mcpServerId } }, }); throw new HTTPException(424, { message: 'TrueFoundry ServiceFoundry MCP authorize returned an unexpected response', @@ -451,6 +453,7 @@ export class TrueFoundryServiceFoundryServerClient { this.#logger.error('TrueFoundry ServiceFoundry MCP auth status returned an unexpected response', { mcpServerId: input.mcpServerId, ...extractErrorLogFields(error), + reportable_error: { error, extra: { mcp_server_id: input.mcpServerId } }, }); throw new HTTPException(424, { message: 'TrueFoundry ServiceFoundry MCP auth status returned an unexpected response', @@ -566,6 +569,7 @@ export class TrueFoundryServiceFoundryServerClient { if (!parsed.success) { this.#logger.error('TrueFoundry ServiceFoundry agent permissions response was malformed', { ...extractErrorLogFields(parsed.error), + reportable_error: { error: parsed.error }, }); throw new HTTPException(424, { message: 'TrueFoundry ServiceFoundry agent permissions response was malformed', @@ -589,6 +593,7 @@ export class TrueFoundryServiceFoundryServerClient { if (!parsed.success) { this.#logger.error('TrueFoundry ServiceFoundry tenant permissions response was malformed', { ...extractErrorLogFields(parsed.error), + reportable_error: { error: parsed.error }, }); throw new HTTPException(424, { message: 'TrueFoundry ServiceFoundry tenant permissions response was malformed', @@ -624,6 +629,7 @@ export class TrueFoundryServiceFoundryServerClient { if (!parsed.success) { this.#logger.error('TrueFoundry ServiceFoundry vend-token response was malformed', { ...extractErrorLogFields(parsed.error), + reportable_error: { error: parsed.error }, }); throw new HTTPException(424, { message: 'TrueFoundry ServiceFoundry vend-token response was malformed', @@ -638,6 +644,7 @@ export class TrueFoundryServiceFoundryServerClient { if (!parsed.success) { this.#logger.error('TrueFoundry ServiceFoundry server returned an unexpected list response', { ...extractErrorLogFields(parsed.error), + reportable_error: { error: parsed.error }, }); throw new HTTPException(424, { message: 'TrueFoundry ServiceFoundry server returned an unexpected list response', @@ -736,6 +743,7 @@ export class TrueFoundryServiceFoundryServerClient { this.#logger.error('TrueFoundry ServiceFoundry server returned non-JSON', { url: input.url.href, ...extractErrorLogFields(error), + reportable_error: { error }, }); throw new HTTPException(424, { message: 'TrueFoundry ServiceFoundry server returned non-JSON', diff --git a/packages/trueforge/src/truefoundry/errors.ts b/packages/trueforge/src/truefoundry/errors.ts index b0233b148f..22da3c7322 100644 --- a/packages/trueforge/src/truefoundry/errors.ts +++ b/packages/trueforge/src/truefoundry/errors.ts @@ -1,6 +1,5 @@ import { HTTPException } from 'hono/http-exception'; import type { AgentRecord } from '../db/agentStore'; -import { captureCriticalException } from '../sentry'; export const AGENT_EXTERNAL_ID_REQUIRED = 'Agent is missing a TrueFoundry external id'; export const TRUEFOUNDRY_MANAGED_STATUS = 424 as const; @@ -11,16 +10,7 @@ export function requireTrueFoundryAgentExternalId( agent: Pick, ): string { if (agent.external_id === null) { - const error = new HTTPException(500, { message: AGENT_EXTERNAL_ID_REQUIRED }); - captureCriticalException(error, { - tags: { module: 'truefoundry', operation: 'requireExternalId' }, - extra: { - agent_id: agent.id, - tenant_id: agent.tenant_id, - agent_name: agent.name, - }, - }); - throw error; + throw new HTTPException(500, { message: AGENT_EXTERNAL_ID_REQUIRED }); } return agent.external_id; } diff --git a/packages/trueforge/src/truefoundry/initTrueFoundrySentry.ts b/packages/trueforge/src/truefoundry/initTrueFoundrySentry.ts index e160ac0c3c..cf33ee6629 100644 --- a/packages/trueforge/src/truefoundry/initTrueFoundrySentry.ts +++ b/packages/trueforge/src/truefoundry/initTrueFoundrySentry.ts @@ -75,7 +75,7 @@ export async function initTrueFoundrySentry(input: { Object.assign(sentryInitOptions, authData); sentryInitOptions.includeLocalVariables = false; sentryInitOptions.defaultIntegrations = false; - sentryInitOptions.integrations = []; + sentryInitOptions.integrations = [Sentry.linkedErrorsIntegration()]; Sentry.init(sentryInitOptions); Sentry.getGlobalScope().setTag('TRUEFORGE_VERSION', PACKAGE_VERSION); if (tags) { diff --git a/packages/trueforge/tests/unit/apis/auth.test.ts b/packages/trueforge/tests/unit/apis/auth.test.ts index ca88e04207..522abc5837 100644 --- a/packages/trueforge/tests/unit/apis/auth.test.ts +++ b/packages/trueforge/tests/unit/apis/auth.test.ts @@ -441,6 +441,7 @@ describe('auth router (auth enabled)', () => { // openid-client throws with the token-endpoint response embedded in the message, which // carries the issuer host and upstream error body. None of that may reach the browser's // address bar, where it lands in history, screenshots and support tickets. + const errorLog = jest.spyOn(logger, 'error'); const router = createTestAuthRouter({ oidcClient }); const loginRes = await router.request('/login?return_to=/', { redirect: 'manual' }); const stateCookieRaw = cookieValue(setCookies(loginRes), STATE_COOKIE) ?? ''; @@ -469,6 +470,11 @@ describe('auth router (auth enabled)', () => { expect(location).toBe('/?error=login_failed'); expect(location).not.toContain(new URL(ISSUER).host); expect(location).not.toContain('invalid_grant'); + expect(errorLog).toHaveBeenCalledWith( + 'Failed to exchange authorization code', + expect.not.objectContaining({ reportable_error: expect.anything() }), + ); + errorLog.mockRestore(); }); it('GET /callback keeps login_failed when exchange fails and the leftover cookie is blocked', async () => { diff --git a/packages/trueforge/tests/unit/appErrorHandler.test.ts b/packages/trueforge/tests/unit/appErrorHandler.test.ts index b2d8b1bad9..0e4e4abcdf 100644 --- a/packages/trueforge/tests/unit/appErrorHandler.test.ts +++ b/packages/trueforge/tests/unit/appErrorHandler.test.ts @@ -41,6 +41,9 @@ describe('createAppErrorHandler', () => { status: 500, error: thrown.message, stack: thrown.stack, + reportable_error: expect.objectContaining({ + error: thrown, + }), }); }); @@ -60,6 +63,30 @@ describe('createAppErrorHandler', () => { status, error: thrown.message, stack: thrown.stack, + reportable_error: expect.objectContaining({ + error: thrown, + }), + }); + }); + + it('marks a 500 that wraps an earlier error', async () => { + const logger = winston.createLogger({ silent: true }); + const errorLog = jest.spyOn(logger, 'error'); + const cause = new Error('socket hang up'); + const thrown = new HTTPException(500, { message: 'Service unavailable', cause }); + + const response = await appThrowing(logger, thrown).request('/test'); + + expect(response.status).toBe(500); + expect(errorLog).toHaveBeenCalledWith('Server API error', { + method: 'GET', + path: '/test', + status: 500, + error: `${thrown.message}: ${cause.message}`, + stack: `${thrown.stack ?? ''}\nCaused by: ${cause.stack ?? ''}`, + reportable_error: expect.objectContaining({ + error: thrown, + }), }); }); diff --git a/packages/trueforge/tests/unit/logger.test.ts b/packages/trueforge/tests/unit/logger.test.ts index ffb93efca8..f29e2713a6 100644 --- a/packages/trueforge/tests/unit/logger.test.ts +++ b/packages/trueforge/tests/unit/logger.test.ts @@ -1,4 +1,6 @@ -import { currentLogContext, runWithLogContext } from '../../src/logger'; +import { Writable } from 'node:stream'; +import winston from 'winston'; +import { createServerLogger, currentLogContext, runWithLogContext } from '../../src/logger'; describe('log context AsyncLocalStorage', () => { it('is empty when an AbortSignal listener runs after the request store exits', async () => { @@ -34,3 +36,31 @@ describe('log context AsyncLocalStorage', () => { }); }); }); + +describe('printed logs', () => { + function captureLines(standalone: boolean): { logger: winston.Logger; lines: string[] } { + const lines: string[] = []; + const stream = new Writable({ + write(chunk: Buffer | string, _encoding: BufferEncoding, callback: (error?: Error | null) => void) { + lines.push(chunk.toString()); + callback(); + }, + }); + const logger = createServerLogger({ level: 'info', standalone }); + logger.clear(); + logger.add(new winston.transports.Stream({ stream })); + return { logger, lines }; + } + + it('omits reportable_error when Sentry has not started', () => { + for (const standalone of [false, true]) { + const { logger, lines } = captureLines(standalone); + logger.error('Unhandled error', { + error: 'boom', + reportable_error: { error: new Error('boom'), extra: undefined, filepath: 'trueforge/src/app.ts' }, + }); + expect(lines.join('')).not.toContain('reportable_error'); + expect(lines.join('')).toContain('boom'); + } + }); +}); diff --git a/packages/trueforge/tests/unit/sandbox/progressSandboxEnvironmentVersion.test.ts b/packages/trueforge/tests/unit/sandbox/progressSandboxEnvironmentVersion.test.ts index 5f54b4a978..4d1c2e13e9 100644 --- a/packages/trueforge/tests/unit/sandbox/progressSandboxEnvironmentVersion.test.ts +++ b/packages/trueforge/tests/unit/sandbox/progressSandboxEnvironmentVersion.test.ts @@ -5,11 +5,6 @@ import type { ISandboxEnvironmentStore } from '../../../src/db/sandboxEnvironmen import type { ISandboxProviderStore } from '../../../src/db/sandboxProviderStore'; import { progressSandboxEnvironmentVersion } from '../../../src/sandbox/progressSandboxEnvironmentVersion'; import * as providerUtils from '../../../src/sandbox/providerUtils'; -import * as sentry from '../../../src/sentry'; - -jest.mock('../../../src/sentry', () => ({ - captureCriticalException: jest.fn(), -})); jest.mock('../../../src/sandbox/providerUtils', () => { const actual = jest.requireActual( @@ -76,11 +71,11 @@ function mockProvider(methods: Record): void { describe('progressSandboxEnvironmentVersion', () => { beforeEach(() => { jest.mocked(providerUtils.toDaytonaSandboxProvider).mockReset(); - jest.mocked(sentry.captureCriticalException).mockClear(); }); it('throws 404 when the version is missing', async () => { const { sandboxEnvironmentStore, sandboxProviderStore } = makeStores({ pending: null }); + const warn = jest.spyOn(logger, 'warn'); await expect( progressSandboxEnvironmentVersion({ sandboxEnvironmentStore, @@ -89,6 +84,9 @@ describe('progressSandboxEnvironmentVersion', () => { logger, }), ).rejects.toMatchObject({ status: 404 } satisfies Partial); + expect(warn).toHaveBeenCalledWith('Sandbox environment version not found', { + environment_version_id: 'missing', + }); }); it('marks ready when getBuildStatus reports ready', async () => { diff --git a/packages/trueforge/tests/unit/sentry/reportMarkedLog.test.ts b/packages/trueforge/tests/unit/sentry/reportMarkedLog.test.ts new file mode 100644 index 0000000000..3dcd8d2bb2 --- /dev/null +++ b/packages/trueforge/tests/unit/sentry/reportMarkedLog.test.ts @@ -0,0 +1,70 @@ +import { Writable } from 'node:stream'; +import winston from 'winston'; +import { captureCriticalException } from '../../../src/sentry/captureCriticalException'; +import { reportMarkedLogFormat } from '../../../src/sentry/reportMarkedLog'; + +jest.mock('../../../src/sentry/captureCriticalException', () => ({ + captureCriticalException: jest.fn(), +})); + +function loggedLines(): { logger: winston.Logger; lines: string[] } { + const lines: string[] = []; + const stream = new Writable({ + write(chunk: Buffer | string, _encoding: BufferEncoding, callback: (error?: Error | null) => void) { + lines.push(chunk.toString()); + callback(); + }, + }); + const logger = winston.createLogger({ + format: winston.format.combine(reportMarkedLogFormat(), winston.format.json()), + transports: [new winston.transports.Stream({ stream })], + }); + return { logger, lines }; +} + +describe('reportMarkedLogFormat', () => { + beforeEach(() => { + jest.mocked(captureCriticalException).mockClear(); + }); + + it('reports a marked record and removes the marker from the printed line', () => { + const failure = new Error('boom'); + const { logger, lines } = loggedLines(); + logger.error('Unhandled error', { + error: 'boom', + reportable_error: { error: failure, extra: { path: '/api' } }, + }); + + expect(captureCriticalException).toHaveBeenCalledWith(expect.any(Error), { + extra: { path: '/api' }, + }); + const reported: unknown = jest.mocked(captureCriticalException).mock.calls[0]?.[0]; + expect(reported).toBeInstanceOf(Error); + if (!(reported instanceof Error)) { + return; + } + expect(reported.message).toBe('Unhandled error'); + expect(reported.cause).toBe(failure); + const reportedFrames = reported.stack?.slice(reported.stack.indexOf('\n') + 1); + const causeFrames = failure.stack?.slice((failure.stack?.indexOf('\n') ?? -1) + 1); + expect(reportedFrames).toBe(causeFrames); + expect(failure.message).toBe('boom'); + expect(lines.join('')).not.toContain('reportable_error'); + }); + + it('leaves unmarked lines in Winston only', () => { + const { logger } = loggedLines(); + logger.error('Client API error', { error: 'bad request' }); + logger.error('Error reading LLM stream', { error: 'invalid api key' }); + + expect(captureCriticalException).not.toHaveBeenCalled(); + }); + + it('reports each repeated marked log', () => { + const { logger } = loggedLines(); + const failure = new Error('socket closed'); + logger.error('[Redis] Client error', { reportable_error: { error: failure } }); + logger.error('[Redis] Client error', { reportable_error: { error: failure } }); + expect(captureCriticalException).toHaveBeenCalledTimes(2); + }); +}); diff --git a/packages/trueforge/tests/unit/truefoundry/TrueFoundryAgentStore.test.ts b/packages/trueforge/tests/unit/truefoundry/TrueFoundryAgentStore.test.ts index 9d66285fe9..7c39dcc7eb 100644 --- a/packages/trueforge/tests/unit/truefoundry/TrueFoundryAgentStore.test.ts +++ b/packages/trueforge/tests/unit/truefoundry/TrueFoundryAgentStore.test.ts @@ -106,6 +106,7 @@ function tfStore(input: { user_credential: input.accessToken ?? TOKEN, }, db: input.db ?? mockDb(), + logger: LOGGER, }); }