mirror of
https://github.com/simstudioai/sim.git
synced 2026-09-01 14:59:19 +08:00
fix(observability): attach the real cause at three error-swallowing sites (#6336)
Three log sites discarded the underlying error, which blocked root-cause
analysis in production.
- Trace secret projection swallowed TraceSecretProjectionError in four
catch blocks (per-field omission, whole-tree fallback, post-transform
invariant, structural traversal) across ~30 distinct throw sites, so no
warning said which invariant fired. Each now reports the failure. Only
TraceSecretProjectionError messages are logged — they are fixed literals
describing an invariant. A failure raised outside the module may quote
trace content (a JSON parse error embeds the text it choked on), so those
are reported by name only.
- ExecutionLogger's unbilled-charge error logged `"error":{}` because a
plain Error has non-enumerable message/stack. It now logs describeError.
- WorkspaceFileStorage / FetchExternalUrl logged `saveError:{}` for the
same reason, and the upload wrapper rethrew without a cause, so Drizzle's
`Failed query:` wrapper dropped the Postgres SQLSTATE. The wrapper now
chains the cause and both sites log describeError, which reports the
deepest link's code.
describeError additionally strips the `params:` tail Drizzle appends to its
message, so bound parameter values never reach logs.
This commit is contained in:
@@ -16,7 +16,7 @@ import type { SerializableExecutionState } from '@/executor/execution/types'
|
||||
afterAll(resetDbChainMock)
|
||||
|
||||
/** Flat logger whose withMetadata() children share one spy set, so log level is assertable. */
|
||||
const { mockLogger } = vi.hoisted(() => {
|
||||
const { mockLogger, statsLogErrorMock } = vi.hoisted(() => {
|
||||
const mockLogger: Record<string, ReturnType<typeof vi.fn>> = {
|
||||
info: vi.fn(),
|
||||
warn: vi.fn(),
|
||||
@@ -27,7 +27,7 @@ const { mockLogger } = vi.hoisted(() => {
|
||||
}
|
||||
mockLogger.child = vi.fn(() => mockLogger)
|
||||
mockLogger.withMetadata = vi.fn(() => mockLogger)
|
||||
return { mockLogger }
|
||||
return { mockLogger, statsLogErrorMock: mockLogger.error }
|
||||
})
|
||||
|
||||
vi.mock('@sim/logger', () => ({
|
||||
@@ -1230,4 +1230,32 @@ describe('recordExecutionUsage boundary-delta reconciliation', () => {
|
||||
// The ledger INSERT participates in the locked transaction.
|
||||
expect(vi.mocked(recordUsage).mock.calls[0][0]).toHaveProperty('tx')
|
||||
})
|
||||
|
||||
test('reports the driver cause and SQLSTATE when the ledger write fails', async () => {
|
||||
const driver = Object.assign(new Error('cannot execute INSERT in a read-only transaction'), {
|
||||
code: '25006',
|
||||
})
|
||||
vi.mocked(recordUsage).mockRejectedValueOnce(
|
||||
new Error('Failed query: insert into "usage_log"\nparams: user-1', { cause: driver })
|
||||
)
|
||||
|
||||
await run(
|
||||
costSummary({
|
||||
models: {
|
||||
'gpt-4o': { input: 0, output: 0, total: 1, tokens: { input: 0, output: 0, total: 0 } },
|
||||
},
|
||||
}),
|
||||
[]
|
||||
)
|
||||
|
||||
expect(statsLogErrorMock).toHaveBeenCalledWith(
|
||||
'Failed to record execution usage to usage_log ledger; charge may be unbilled',
|
||||
expect.objectContaining({
|
||||
cause: expect.objectContaining({
|
||||
code: '25006',
|
||||
message: 'cannot execute INSERT in a read-only transaction',
|
||||
}),
|
||||
})
|
||||
)
|
||||
})
|
||||
})
|
||||
|
||||
@@ -10,7 +10,7 @@ import {
|
||||
workspace,
|
||||
} from '@sim/db/schema'
|
||||
import { createLogger } from '@sim/logger'
|
||||
import { getErrorMessage } from '@sim/utils/errors'
|
||||
import { describeError, getErrorMessage } from '@sim/utils/errors'
|
||||
import { generateId } from '@sim/utils/id'
|
||||
import { and, eq, inArray, sql } from 'drizzle-orm'
|
||||
import { checkUsageStatus as checkResolvedUsageStatus } from '@/lib/billing/calculations/usage-monitor'
|
||||
@@ -1768,7 +1768,7 @@ export class ExecutionLogger implements IExecutionLoggerService {
|
||||
statsLog.error(
|
||||
'Failed to record execution usage to usage_log ledger; charge may be unbilled',
|
||||
{
|
||||
error,
|
||||
cause: describeError(error),
|
||||
actorUserId,
|
||||
costSummary,
|
||||
}
|
||||
|
||||
@@ -4,9 +4,19 @@
|
||||
import { createHash } from 'node:crypto'
|
||||
import { beforeEach, describe, expect, it, vi } from 'vitest'
|
||||
|
||||
const { materializeLargeValueRefMock, storeLargeValueMock } = vi.hoisted(() => ({
|
||||
const { materializeLargeValueRefMock, storeLargeValueMock, warnMock } = vi.hoisted(() => ({
|
||||
materializeLargeValueRefMock: vi.fn(),
|
||||
storeLargeValueMock: vi.fn(),
|
||||
warnMock: vi.fn(),
|
||||
}))
|
||||
|
||||
vi.mock('@sim/logger', () => ({
|
||||
createLogger: () => ({
|
||||
debug: vi.fn(),
|
||||
info: vi.fn(),
|
||||
warn: warnMock,
|
||||
error: vi.fn(),
|
||||
}),
|
||||
}))
|
||||
|
||||
vi.mock('@/lib/execution/payloads/store', () => ({
|
||||
@@ -24,6 +34,8 @@ import {
|
||||
ResolvedSecretTraceRegistry,
|
||||
} from '@/executor/utils/resolved-secret-trace-registry'
|
||||
|
||||
const MAX_CONTENT_NODES = 100_000
|
||||
|
||||
const STORE = {
|
||||
workspaceId: 'workspace-1',
|
||||
workflowId: 'workflow-1',
|
||||
@@ -438,6 +450,25 @@ describe('projectTraceSpansForSecrets', () => {
|
||||
expect(source[0].output).toEqual({ apiKey: '[REDACTED]' })
|
||||
})
|
||||
|
||||
it('names the invariant that forced the structural fallback', async () => {
|
||||
const source = [createSpan({ output: { apiKey: '[REDACTED]' } })]
|
||||
|
||||
await enforceTraceSpanSecretInvariant(source, {
|
||||
registry: createRegistry([{ plaintext: 'E', replacement: '{{X}}' }]),
|
||||
store: STORE,
|
||||
})
|
||||
|
||||
expect(warnMock).toHaveBeenCalledWith(
|
||||
'Trace secret invariant failed; retaining structural spans only',
|
||||
{
|
||||
failure: {
|
||||
name: 'TraceSecretProjectionError',
|
||||
reason: expect.any(String),
|
||||
},
|
||||
}
|
||||
)
|
||||
})
|
||||
|
||||
it('fails the final invariant closed when provenance is incomplete', async () => {
|
||||
const source = [createSpan({ output: { value: 'ordinary' } })]
|
||||
|
||||
@@ -1149,6 +1180,64 @@ describe('projectTraceSpansForSecrets', () => {
|
||||
expect(result[0].output).toEqual({ token: '{{API_SECRET}}' })
|
||||
})
|
||||
|
||||
it('names the invariant that forced content to be omitted', async () => {
|
||||
const output: Record<string, unknown> = { token: 'top-secret' }
|
||||
output.self = output
|
||||
|
||||
const [result] = await projectTraceSpansForSecrets([createSpan({ output })], {
|
||||
registry: createRegistry([{ plaintext: 'top-secret', replacement: '{{API_SECRET}}' }]),
|
||||
store: STORE,
|
||||
})
|
||||
|
||||
expect(result).not.toHaveProperty('output')
|
||||
expect(warnMock).toHaveBeenCalledWith('Omitting trace content that could not be sanitized', {
|
||||
failure: {
|
||||
name: 'TraceSecretProjectionError',
|
||||
reason: 'Trace content could not be sanitized',
|
||||
},
|
||||
})
|
||||
})
|
||||
|
||||
it('withholds the message of a failure raised outside the projection module', async () => {
|
||||
const descriptorSpy = vi.spyOn(Object, 'getOwnPropertyDescriptor').mockImplementation(() => {
|
||||
throw new SyntaxError('Unexpected token in "sk-live-top-secret"')
|
||||
})
|
||||
|
||||
try {
|
||||
await projectTraceSpansForSecrets([createSpan({ output: { token: 'top-secret' } })], {
|
||||
registry: createRegistry([{ plaintext: 'top-secret', replacement: '{{API_SECRET}}' }]),
|
||||
store: STORE,
|
||||
})
|
||||
} finally {
|
||||
descriptorSpy.mockRestore()
|
||||
}
|
||||
|
||||
expect(warnMock).toHaveBeenCalledWith('Omitting trace content that could not be sanitized', {
|
||||
failure: { name: 'SyntaxError' },
|
||||
})
|
||||
})
|
||||
|
||||
it('names the invariant that forced the whole-tree structural fallback', async () => {
|
||||
const source = Array(MAX_CONTENT_NODES + 1).fill(
|
||||
createSpan({ output: { token: 'top-secret' } })
|
||||
)
|
||||
|
||||
await projectTraceSpansForSecrets(source, {
|
||||
registry: createRegistry([{ plaintext: 'top-secret', replacement: '{{API_SECRET}}' }]),
|
||||
store: STORE,
|
||||
})
|
||||
|
||||
expect(warnMock).toHaveBeenCalledWith(
|
||||
'Trace secret projection failed; retaining structural spans only',
|
||||
{
|
||||
failure: {
|
||||
name: 'TraceSecretProjectionError',
|
||||
reason: 'Trace structure array exceeds the projection limit',
|
||||
},
|
||||
}
|
||||
)
|
||||
})
|
||||
|
||||
it('uses bounded structural fallback when matcher construction fails', async () => {
|
||||
let source = createSpan({ id: 'depth-150', output: { secret: 'raw' } })
|
||||
for (let depth = 149; depth >= 0; depth -= 1) {
|
||||
|
||||
@@ -1,4 +1,5 @@
|
||||
import { createLogger } from '@sim/logger'
|
||||
import { toError } from '@sim/utils/errors'
|
||||
import { isPlainRecord, omit } from '@sim/utils/object'
|
||||
import {
|
||||
isLargeArrayManifest,
|
||||
@@ -128,6 +129,21 @@ class TraceSecretProjectionError extends Error {
|
||||
}
|
||||
}
|
||||
|
||||
/**
|
||||
* Diagnostic payload for a projection fallback.
|
||||
*
|
||||
* Every {@link TraceSecretProjectionError} message is a fixed literal describing
|
||||
* which invariant fired, so it is safe to log. Any other failure originates
|
||||
* outside this module and may embed trace content (a JSON parse error quotes the
|
||||
* text it choked on), so only its name is reported.
|
||||
*/
|
||||
function describeProjectionFailure(error: unknown): { name: string; reason?: string } {
|
||||
return {
|
||||
name: toError(error).name,
|
||||
...(error instanceof TraceSecretProjectionError ? { reason: error.message } : {}),
|
||||
}
|
||||
}
|
||||
|
||||
function createProjectionContext(
|
||||
matcher: ResolvedSecretMatcher,
|
||||
store: LargeValueStoreContext,
|
||||
@@ -786,8 +802,10 @@ async function sanitizeContentField(
|
||||
): Promise<unknown | typeof OMIT> {
|
||||
try {
|
||||
return await sanitizeMaterializedValue(value, context)
|
||||
} catch {
|
||||
logger.warn('Omitting trace content that could not be sanitized')
|
||||
} catch (error) {
|
||||
logger.warn('Omitting trace content that could not be sanitized', {
|
||||
failure: describeProjectionFailure(error),
|
||||
})
|
||||
return OMIT
|
||||
}
|
||||
}
|
||||
@@ -1182,8 +1200,10 @@ function projectBoundedTraceSpans(
|
||||
function structuralOnlyTraceSpans(traceSpans: TraceSpan[]): TraceSpan[] {
|
||||
try {
|
||||
return projectBoundedTraceSpans(traceSpans, structuralOnlySpan)
|
||||
} catch {
|
||||
logger.warn('Trace structure could not be safely traversed; omitting projected spans')
|
||||
} catch (error) {
|
||||
logger.warn('Trace structure could not be safely traversed; omitting projected spans', {
|
||||
failure: describeProjectionFailure(error),
|
||||
})
|
||||
return []
|
||||
}
|
||||
}
|
||||
@@ -1522,8 +1542,10 @@ export async function enforceTraceSpanSecretInvariant(
|
||||
|
||||
await assertPostTransformTraceSpansAreSafe(traceSpans, matcher, options.store)
|
||||
return traceSpans
|
||||
} catch {
|
||||
logger.warn('Trace secret invariant failed; retaining structural spans only')
|
||||
} catch (error) {
|
||||
logger.warn('Trace secret invariant failed; retaining structural spans only', {
|
||||
failure: describeProjectionFailure(error),
|
||||
})
|
||||
return structuralOnlyTraceSpans(traceSpans)
|
||||
}
|
||||
}
|
||||
@@ -1560,8 +1582,10 @@ export async function projectTraceSpansForSecrets(
|
||||
}
|
||||
assertTraceSpansContentIsSafe(projected, context)
|
||||
return projected
|
||||
} catch {
|
||||
logger.warn('Trace secret projection failed; retaining structural spans only')
|
||||
} catch (error) {
|
||||
logger.warn('Trace secret projection failed; retaining structural spans only', {
|
||||
failure: describeProjectionFailure(error),
|
||||
})
|
||||
return structuralOnlyTraceSpans(traceSpans)
|
||||
}
|
||||
}
|
||||
|
||||
@@ -9,6 +9,13 @@
|
||||
* the module graph is fresh or reused.
|
||||
*/
|
||||
import { afterAll, beforeEach, describe, expect, it, vi } from 'vitest'
|
||||
|
||||
const { warnMock } = vi.hoisted(() => ({ warnMock: vi.fn() }))
|
||||
|
||||
vi.mock('@sim/logger', () => ({
|
||||
createLogger: () => ({ debug: vi.fn(), info: vi.fn(), warn: warnMock, error: vi.fn() }),
|
||||
}))
|
||||
|
||||
import * as inputValidation from '@/lib/core/security/input-validation.server'
|
||||
import {
|
||||
ExternalUrlValidationError,
|
||||
@@ -200,6 +207,33 @@ describe('fetchExternalUrlToWorkspace', () => {
|
||||
expect(result.savedWorkspaceFile).toBeUndefined()
|
||||
})
|
||||
|
||||
it('logs the driver cause and SQLSTATE behind a swallowed workspace save error', async () => {
|
||||
const driver = Object.assign(
|
||||
new Error('cannot execute SELECT FOR UPDATE in a read-only transaction'),
|
||||
{ code: '25006' }
|
||||
)
|
||||
secureFetchWithPinnedIPSpy.mockResolvedValue(makeResponse('bytes', 'text/plain'))
|
||||
uploadWorkspaceFileSpy.mockRejectedValueOnce(
|
||||
new Error('Failed to upload file: storage accounting failed', { cause: driver })
|
||||
)
|
||||
|
||||
await fetchExternalUrlToWorkspace({
|
||||
url: 'https://example.com/file.txt',
|
||||
userId: 'user-1',
|
||||
workspaceId: 'workspace-1',
|
||||
})
|
||||
|
||||
expect(warnMock).toHaveBeenCalledWith(
|
||||
'Failed to save fetched URL to workspace storage',
|
||||
expect.objectContaining({
|
||||
cause: expect.objectContaining({
|
||||
code: '25006',
|
||||
message: 'cannot execute SELECT FOR UPDATE in a read-only transaction',
|
||||
}),
|
||||
})
|
||||
)
|
||||
})
|
||||
|
||||
it('forwards custom headers to the fetch', async () => {
|
||||
secureFetchWithPinnedIPSpy.mockResolvedValue(makeResponse('bytes', 'text/plain'))
|
||||
|
||||
|
||||
@@ -1,6 +1,7 @@
|
||||
import type { Buffer } from 'buffer'
|
||||
import path from 'path'
|
||||
import { createLogger } from '@sim/logger'
|
||||
import { describeError } from '@sim/utils/errors'
|
||||
import {
|
||||
secureFetchWithPinnedIP,
|
||||
validateUrlWithDNS,
|
||||
@@ -134,7 +135,7 @@ export async function fetchExternalUrlToWorkspace(
|
||||
logger.warn('Failed to save fetched URL to workspace storage', {
|
||||
workspaceId,
|
||||
filename,
|
||||
saveError,
|
||||
cause: describeError(saveError),
|
||||
})
|
||||
}
|
||||
} else if (permission === null) {
|
||||
|
||||
@@ -7,7 +7,12 @@ import { randomBytes } from 'crypto'
|
||||
import { db } from '@sim/db'
|
||||
import { workspaceFiles } from '@sim/db/schema'
|
||||
import { createLogger } from '@sim/logger'
|
||||
import { getErrorMessage, getPostgresConstraintName, getPostgresErrorCode } from '@sim/utils/errors'
|
||||
import {
|
||||
describeError,
|
||||
getErrorMessage,
|
||||
getPostgresConstraintName,
|
||||
getPostgresErrorCode,
|
||||
} from '@sim/utils/errors'
|
||||
import { generateShortId } from '@sim/utils/id'
|
||||
import { and, eq, isNotNull, isNull, or, sql } from 'drizzle-orm'
|
||||
import type { ShareRecord } from '@/lib/api/contracts/public-shares'
|
||||
@@ -446,15 +451,18 @@ export async function uploadWorkspaceFile(
|
||||
)
|
||||
continue
|
||||
}
|
||||
logger.error(`Failed to upload workspace file ${fileName}:`, error)
|
||||
throw new Error(`Failed to upload file: ${getErrorMessage(error, 'Unknown error')}`)
|
||||
logger.error(`Failed to upload workspace file ${fileName}:`, {
|
||||
cause: describeError(error),
|
||||
})
|
||||
throw new Error(`Failed to upload file: ${getErrorMessage(error, 'Unknown error')}`, {
|
||||
cause: error,
|
||||
})
|
||||
}
|
||||
}
|
||||
|
||||
logger.error(
|
||||
`Failed to upload workspace file after ${MAX_UPLOAD_UNIQUE_RETRIES} attempts`,
|
||||
lastError
|
||||
)
|
||||
logger.error(`Failed to upload workspace file after ${MAX_UPLOAD_UNIQUE_RETRIES} attempts`, {
|
||||
cause: describeError(lastError),
|
||||
})
|
||||
throw new FileConflictError(fileName)
|
||||
}
|
||||
|
||||
|
||||
@@ -2,6 +2,7 @@
|
||||
* @vitest-environment node
|
||||
*/
|
||||
import { dbChainMockFns, resetDbChainMock } from '@sim/testing'
|
||||
import { describeError } from '@sim/utils/errors'
|
||||
import { beforeEach, describe, expect, it, vi } from 'vitest'
|
||||
|
||||
const {
|
||||
@@ -159,6 +160,32 @@ describe('workspace file metadata and storage accounting', () => {
|
||||
)
|
||||
})
|
||||
|
||||
it('preserves the driver cause so the SQLSTATE survives the upload wrapper', async () => {
|
||||
const driver = Object.assign(
|
||||
new Error('cannot execute SELECT FOR UPDATE in a read-only transaction'),
|
||||
{ code: '25006' }
|
||||
)
|
||||
dbChainMockFns.returning.mockResolvedValueOnce([FILE_ROW])
|
||||
mockIncrementStorageUsageForBillingContextInTx.mockRejectedValueOnce(
|
||||
new Error(
|
||||
'Failed query: select "storage_used_bytes" from "workspace" where id = $1 limit $2 for update\nparams: ws-1,1',
|
||||
{ cause: driver }
|
||||
)
|
||||
)
|
||||
|
||||
const thrown = await uploadWorkspaceFile(
|
||||
FILE_ROW.workspaceId,
|
||||
FILE_ROW.userId,
|
||||
Buffer.from('hello'),
|
||||
FILE_ROW.originalName,
|
||||
FILE_ROW.contentType
|
||||
).catch((error: unknown) => error)
|
||||
|
||||
const described = describeError(thrown)
|
||||
expect(described.code).toBe('25006')
|
||||
expect(described.message).toBe('cannot execute SELECT FOR UPDATE in a read-only transaction')
|
||||
})
|
||||
|
||||
it('keeps an ordinary workspace upload on the legacy untracked path', async () => {
|
||||
dbChainMockFns.returning.mockResolvedValueOnce([FILE_ROW])
|
||||
|
||||
|
||||
@@ -102,6 +102,30 @@ describe('describeError', () => {
|
||||
])
|
||||
})
|
||||
|
||||
it('redacts driver-appended bound parameter values from every reported message', () => {
|
||||
const driver = Object.assign(
|
||||
new Error('cannot execute SELECT FOR UPDATE in a read-only transaction'),
|
||||
{
|
||||
code: '25006',
|
||||
}
|
||||
)
|
||||
const wrapped = new Error(
|
||||
'Failed query: select "storage_used_bytes" from "workspace" where id = $1 limit $2 for update\nparams: ws-secret-id,1',
|
||||
{ cause: driver }
|
||||
)
|
||||
const described = describeError(wrapped)
|
||||
expect(described.code).toBe('25006')
|
||||
expect(described.causeChain?.[0]).toBe(
|
||||
'Error: Failed query: select "storage_used_bytes" from "workspace" where id = $1 limit $2 for update\nparams: [redacted]'
|
||||
)
|
||||
expect(JSON.stringify(described)).not.toContain('ws-secret-id')
|
||||
})
|
||||
|
||||
it('redacts bound parameter values from an unwrapped driver error message', () => {
|
||||
const described = describeError(new Error('Failed query: select 1\nparams: ws-secret-id'))
|
||||
expect(described.message).toBe('Failed query: select 1\nparams: [redacted]')
|
||||
})
|
||||
|
||||
it('always returns the cause for unclassified errors (AbortError)', () => {
|
||||
const aborted = Object.assign(new Error('The operation was aborted'), { name: 'AbortError' })
|
||||
expect(describeError(aborted)).toEqual({
|
||||
|
||||
@@ -60,6 +60,10 @@ export interface DescribedError {
|
||||
*
|
||||
* Loggers do not serialize the non-enumerable `Error.prototype.cause`, so pass
|
||||
* the result as an explicit structured field rather than the raw error.
|
||||
*
|
||||
* Bound parameter values are stripped from every reported message: Drizzle's
|
||||
* `DrizzleQueryError` appends `\nparams: <values>` to the failing SQL, and those
|
||||
* values are user data that must never reach logs.
|
||||
*/
|
||||
export function describeError(error: unknown): DescribedError {
|
||||
const chain: Error[] = []
|
||||
@@ -73,7 +77,7 @@ export function describeError(error: unknown): DescribedError {
|
||||
|
||||
if (chain.length === 0) {
|
||||
const normalized = toError(error)
|
||||
return { name: normalized.name, message: normalized.message }
|
||||
return { name: normalized.name, message: redactBoundParameters(normalized.message) }
|
||||
}
|
||||
|
||||
const deepest = chain[chain.length - 1] as Error & Record<string, unknown>
|
||||
@@ -85,14 +89,22 @@ export function describeError(error: unknown): DescribedError {
|
||||
|
||||
return {
|
||||
name: deepest.name,
|
||||
message: deepest.message,
|
||||
message: redactBoundParameters(deepest.message),
|
||||
...(code ? { code } : {}),
|
||||
...(errno ? { errno } : {}),
|
||||
...(syscall ? { syscall } : {}),
|
||||
...(chain.length > 1 ? { causeChain: chain.map((e) => `${e.name}: ${e.message}`) } : {}),
|
||||
...(chain.length > 1
|
||||
? { causeChain: chain.map((e) => `${e.name}: ${redactBoundParameters(e.message)}`) }
|
||||
: {}),
|
||||
}
|
||||
}
|
||||
|
||||
/** Replaces a driver-appended `params: <values>` tail with a redaction marker. */
|
||||
function redactBoundParameters(message: string): string {
|
||||
const index = message.indexOf('\nparams:')
|
||||
return index === -1 ? message : `${message.slice(0, index)}\nparams: [redacted]`
|
||||
}
|
||||
|
||||
/**
|
||||
* First link in the `.cause` chain (including `error` itself) matching
|
||||
* `predicate`. Lets a caller recover a specific wrapped error class instead of
|
||||
|
||||
Reference in New Issue
Block a user