Skip to content

Commit 47fb805

Browse files
authored
improvement(logs): log each execution failure once at its owning boundary (#8872)
* improvement(logs): log each execution failure once at its owning boundary A single external tool failure was logged at ERROR up to eight times as it propagated from the tool layer through the block executor, the engine, execution-core, and the trigger surfaces. Each boundary now calls logFailureOnce, which skips a failure an inner boundary already logged and sets severity by attribution: the author's input, configuration, or code at info, a third-party 4xx or 5xx at warn, and Sim's own faults (database, retryable setup, hosted-key rejection, anything unattributed) at error. The logged mark and attribution live in WeakMap/WeakSet side tables keyed by the thrown value, walked through the cause chain, and carried on the flattened tool failure's output so they survive a handler rebuilding a failed tool result as a new error. Run logs and trace spans are unchanged. * test(logs): pin the logged mark and attribution at the block executor Asserts the block executor's thrown error is already logged and attributed (database failure internal, user Stop user), switches the tool-boundary test to the central jsonResponse helper, and updates exact-argument log assertions for the added failureKind and executionId fields. * fix(logs): scope the logged mark to one propagation and attribute in-process failures Never mark a raw thrown value as logged: a persistent fault that rethrows one object (a rejected dynamic import, a memoized rejected promise) was logged once per process and then silenced everywhere. Only carriers created during the propagation (the flattened tool failure output, the block error, a handler's rebuilt error) carry the mark, and execution-level boundaries scope a raw value's mark to their execution id. Handlers that rebuild a failed tool result now call adoptToolFailure instead of relying on the result output being copied by reference. The child workflow and agent handlers no longer log failures the block executor logs with the block's and run's identity. In-process operations are attributed to Sim (4xx user, 5xx internal) rather than to a third party, only external HTTP failures log their response body, a missing required field is the only serializer refusal at info, and the size-limit and JSON-parse paths no longer log twice. * refactor(logs): build failure log metadata lazily and attribute author failures by type logFailureOnce takes its metadata as a thunk so a skipped boundary does no secret projection, adds the execution id itself, and returns the attribution it logged with. UserFailure attributes author-caused failures by type (missing required fields, boundary-safe custom block refusals, no start block) wherever they surface, replacing a try/catch at one serializer caller. One inheritFailureMarks carries both marks across a boundary that drops cause, the hosted-key check reuses classifyHostedKeyFailure, the Pi backends share one toolResultError, and the sandbox and Function route no longer log author code failures the tool boundary already logs. * test(logs): attribute the serializer refusal at its owner and pin block log redaction Moves the missing-required-fields attribution check to the serializer that throws it, drops an execution-core case whose internal row passed by default, and covers the block failure line's secret projection now that it, not the Agent handler, logs provider errors. Tightens comments the diff added. * improvement(logs): drop casts and test-only exports from the failure log Reads status and cause without casts, keeps the thrown missing-required-fields error's name and stack unchanged, ignores an empty execution id when scoping a logged mark, unexports wasFailureLogged and FailureKind (tests observe the outer boundary through logFailureOnce instead), and shrinks the explicit-any baseline for the Agent handler. * fix(logs): close the remaining double logs found in review Carries failure marks through the scrubbed Pi error and normalizes a non-Error node failure before logging so the engine sees its mark; drops the condition handler's and response-size handler's own error lines in favor of the owning boundary; logs MCP failures once and marks their output; passes the block id to the API and Function tool calls so the tool line carries it; attributes custom tool parameter validation and condition expression errors to the author; checks the whole cause chain for a retryable setup failure before honoring a mark; and restores the sandbox failure logs, whose adapters cannot yet tell a provider exception from a non-zero exit. * fix(logs): keep run identity on every remaining failure line Fixes the type error on the external failure body, attributes a provider error payload on a 2xx to the provider, and adds workflow, execution, and block ids to the MCP failure lines that replace the block executor's. The condition batch carries its failed result's marks and passes its block id. Pi GitHub calls carry no run identity, so their errors now carry only the tool layer's attribution and the block executor still logs them with ids. Restores the HITL notification warning, which covers soft failures the tool layer never logs, and attributes refused tool and proxy URLs to the author. * fix(logs): attribute a revoked OAuth credential to its owner A CredentialRevokedError anywhere in the cause chain classifies as a user failure, so the boundaries that log it after token resolution's WARN write INFO rather than ERROR. * fix(logs): keep one logged mark per execution and attribute unparseable responses A raw value logged at an execution boundary now remembers every execution that logged it (bounded), so overlapping runs sharing one persistent rejection each log it once. A 2xx body that is not JSON is the endpoint's failure, not Sim's.
1 parent 842c5ac commit 47fb805

37 files changed

Lines changed: 1201 additions & 567 deletions

‎apps/sim/app/api/workflows/[id]/execute/route.ts‎

Lines changed: 10 additions & 8 deletions
Original file line numberDiff line numberDiff line change
@@ -26,6 +26,7 @@ import {
2626
requireBillingAttributionHeader,
2727
} from '@/lib/billing/core/billing-attribution'
2828
import { admissionRejectedResponse, tryAdmit } from '@/lib/core/admission/gate'
29+
import { logFailureOnce } from '@/lib/core/errors/failure-log'
2930
import {
3031
createTimeoutAbortController,
3132
getTimeoutErrorMessage,
@@ -1615,10 +1616,11 @@ async function handleExecutePost(
16151616
return payloadTooLargeResponse()
16161617
}
16171618

1618-
reqLogger.error(
1619-
'Non-SSE execution failed',
1620-
loggingSession.projectDiagnosticError(error, { isTimeout: executionTimedOut })
1621-
)
1619+
logFailureOnce(reqLogger, 'Non-SSE execution failed', error, {
1620+
metadata: () =>
1621+
loggingSession.projectDiagnosticError(error, { isTimeout: executionTimedOut }),
1622+
executionId,
1623+
})
16221624

16231625
const executionResult = hasExecutionResult(error) ? error.executionResult : undefined
16241626
const status = executionTimedOut ? 408 : getExecutionErrorStatus(error)
@@ -2420,10 +2422,10 @@ async function handleExecutePost(
24202422
? getTimeoutErrorMessage(timeoutController.timeoutMs)
24212423
: getErrorMessage(error, 'Unknown error')
24222424

2423-
reqLogger.error(
2424-
'SSE execution failed',
2425-
loggingSession.projectDiagnosticError(error, { isTimeout })
2426-
)
2425+
logFailureOnce(reqLogger, 'SSE execution failed', error, {
2426+
metadata: () => loggingSession.projectDiagnosticError(error, { isTimeout }),
2427+
executionId,
2428+
})
24272429

24282430
const executionResult = hasExecutionResult(error) ? error.executionResult : undefined
24292431
let compactErrorLogs: BlockLog[] | undefined

‎apps/sim/background/async-preprocessing-correlation.test.ts‎

Lines changed: 2 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -488,12 +488,10 @@ describe('async preprocessing correlation threading', () => {
488488
}),
489489
})
490490
)
491-
expect(loggingSessionMockFns.mockProjectDiagnosticError).toHaveBeenCalledWith(rawError, {
492-
executionId: 'execution-fault',
493-
})
491+
expect(loggingSessionMockFns.mockProjectDiagnosticError).toHaveBeenCalledWith(rawError)
494492
expect(workflowExecutionLogger.error).toHaveBeenCalledWith(
495493
'[request-fault] Workflow execution failed: workflow-1',
496-
{ executionId: 'execution-fault', error: projectedError }
494+
{ executionId: 'execution-fault', error: projectedError, failureKind: 'internal' }
497495
)
498496
const loggerPayload = JSON.stringify(workflowExecutionLogger.error.mock.calls)
499497
expect(loggerPayload).not.toContain(secret)

‎apps/sim/background/webhook-execution.test.ts‎

Lines changed: 7 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -486,7 +486,13 @@ describe('executeWebhookJob fault vs error handling', () => {
486486
})
487487
expect(webhookExecutionLogger.error).toHaveBeenCalledWith(
488488
'[request-1] Webhook execution failed',
489-
{ workflowId: 'workflow-1', provider: 'gmail', error: projectedError }
489+
{
490+
executionId: 'execution-1',
491+
workflowId: 'workflow-1',
492+
provider: 'gmail',
493+
error: projectedError,
494+
failureKind: 'internal',
495+
}
490496
)
491497
const loggerPayload = JSON.stringify(webhookExecutionLogger.error.mock.calls)
492498
expect(loggerPayload).not.toContain(secret)

‎apps/sim/background/webhook-execution.ts‎

Lines changed: 9 additions & 7 deletions
Original file line numberDiff line numberDiff line change
@@ -25,6 +25,7 @@ import {
2525
import { getJobQueue } from '@/lib/core/async-jobs'
2626
import type { AsyncExecutionCorrelation } from '@/lib/core/async-jobs/types'
2727
import { env, envNumber } from '@/lib/core/config/env'
28+
import { logFailureOnce } from '@/lib/core/errors/failure-log'
2829
import {
2930
describeRetryableInfrastructureError,
3031
isRetryableInfrastructureError,
@@ -1267,13 +1268,14 @@ async function executeWebhookJobInternal(
12671268
throw new RetryableSetupError(errorMessage, { cause: retryableSetupCause })
12681269
}
12691270

1270-
logger.error(
1271-
`[${requestId}] Webhook execution failed`,
1272-
loggingSession.projectDiagnosticError(error, {
1273-
workflowId: payload.workflowId,
1274-
provider: payload.provider,
1275-
})
1276-
)
1271+
logFailureOnce(logger, `[${requestId}] Webhook execution failed`, error, {
1272+
metadata: () =>
1273+
loggingSession.projectDiagnosticError(error, {
1274+
workflowId: payload.workflowId,
1275+
provider: payload.provider,
1276+
}),
1277+
executionId,
1278+
})
12771279

12781280
// The finalized flag is set inside a fire-and-forget post-execution promise; await it so the
12791281
// signal is reliable and the failure is fully persisted before we decide fault vs error.

‎apps/sim/background/workflow-execution.ts‎

Lines changed: 5 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -16,6 +16,7 @@ import {
1616
type BillingAttributionSnapshot,
1717
} from '@/lib/billing/core/billing-attribution'
1818
import type { AsyncExecutionCorrelation } from '@/lib/core/async-jobs/types'
19+
import { logFailureOnce } from '@/lib/core/errors/failure-log'
1920
import {
2021
capExecutionTimeoutMs,
2122
createTimeoutAbortController,
@@ -306,10 +307,10 @@ export async function executeWorkflowJob(
306307
metadata: payload.metadata,
307308
}
308309
} catch (error: unknown) {
309-
logger.error(
310-
`[${requestId}] Workflow execution failed: ${workflowId}`,
311-
loggingSession.projectDiagnosticError(error, { executionId })
312-
)
310+
logFailureOnce(logger, `[${requestId}] Workflow execution failed: ${workflowId}`, error, {
311+
metadata: () => loggingSession.projectDiagnosticError(error),
312+
executionId,
313+
})
313314

314315
if (error instanceof ExecutionTimeoutError) throw error
315316

‎apps/sim/executor/errors/boundary.ts‎

Lines changed: 3 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -1,3 +1,5 @@
1+
import { UserFailure } from '@/lib/core/errors/user-failure'
2+
13
/**
24
* Machine-readable class of a custom-block failure. Every member describes a
35
* fact the CONSUMER already knows or can act on — never the source workflow's
@@ -39,7 +41,7 @@ export interface CustomBlockFailure {
3941
* replaces the older convention of throwing *before* the `try` block to dodge
4042
* the catch's sanitizer, where redaction depended on lexical position.
4143
*/
42-
export class BoundarySafeError extends Error {
44+
export class BoundarySafeError extends UserFailure {
4345
readonly errorType: CustomBlockErrorType
4446

4547
constructor(options: { message: string; errorType: CustomBlockErrorType }) {

‎apps/sim/executor/execution/block-executor.test.ts‎

Lines changed: 121 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -1,17 +1,20 @@
1+
import { createLogger } from '@sim/logger'
12
import { loggerMock } from '@sim/testing'
23
import { maskClientMock, maskClientMockFns } from '@sim/testing/mocks/mask-client.mock'
34
import { permissionCheckMock } from '@sim/testing/mocks/permission-check.mock'
45
import { storageServiceMockFns } from '@sim/testing/mocks/storage-service.mock'
56
import { uploadsMock } from '@sim/testing/mocks/uploads.mock'
67
import { DrizzleQueryError } from 'drizzle-orm/errors'
78
import { beforeEach, describe, expect, it, vi } from 'vitest'
9+
import { classifyFailure, logFailureOnce } from '@/lib/core/errors/failure-log'
810
import { clearLargeValueCacheForTests } from '@/lib/execution/payloads/cache'
911
import { createLargeArrayManifest } from '@/lib/execution/payloads/large-array-manifest'
1012
import { isLargeValueRef } from '@/lib/execution/payloads/large-value-ref'
1113
import { buildTraceSpans } from '@/lib/logs/execution/trace-spans/trace-spans'
1214
import { validateBlockType } from '@/ee/access-control/utils/permission-check'
1315
import { BlockType, EDGE } from '@/executor/constants'
1416
import type { DAGNode } from '@/executor/dag/builder'
17+
import { ChildWorkflowError } from '@/executor/errors/child-workflow-error'
1518
import { BlockExecutor } from '@/executor/execution/block-executor'
1619
import { ExecutionState } from '@/executor/execution/state'
1720
import type { BlockHandler, ExecutionContext } from '@/executor/types'
@@ -496,6 +499,9 @@ describe('BlockExecutor', () => {
496499
expect.objectContaining({ cause: expect.objectContaining({ code: 'ECONNRESET' }) })
497500
)
498501
expect(JSON.stringify(logged)).not.toContain('owner-secret-id')
502+
/** Logged here at error, so the engine and the run surfaces must see it as already logged. */
503+
expect(classifyFailure(thrown)).toBe('internal')
504+
expect(logFailureOnce(createLogger('OuterBoundary'), 'probe', thrown)).toBeUndefined()
499505
})
500506

501507
it('fires block completion callbacks for pausing blocks so clients receive pause output', async () => {
@@ -572,6 +578,116 @@ describe('BlockExecutor', () => {
572578
expect(state.getBlockOutput(block.id)).toEqual(output)
573579
})
574580

581+
function failBlockWith(thrown: unknown) {
582+
const block = createBlock()
583+
const workflow: SerializedWorkflow = {
584+
version: '1',
585+
blocks: [block],
586+
connections: [],
587+
loops: {},
588+
parallels: {},
589+
}
590+
const state = new ExecutionState()
591+
const resolver = new VariableResolver(workflow, {}, state)
592+
const handler: BlockHandler = {
593+
canHandle: () => true,
594+
execute: async () => {
595+
throw thrown
596+
},
597+
}
598+
const executor = new BlockExecutor([handler], resolver, {}, state)
599+
const ctx = createContext(state)
600+
ctx.resolvedSecretTraceRegistry = new ResolvedSecretTraceRegistry([])
601+
return executor.execute(ctx, createNode(block), block).catch((error) => error)
602+
}
603+
604+
function blockFailureLogsSince(loggerIndex: number) {
605+
const loggers = new Set<{ error: { mock: { calls: unknown[][] } } }>(
606+
blockExecutorBaseLogger.withMetadata.mock.results
607+
.slice(loggerIndex)
608+
.map((result: { value: { error: { mock: { calls: unknown[][] } } } }) => result.value)
609+
)
610+
return [...loggers].flatMap((logger) =>
611+
logger.error.mock.calls.filter(([message]) => message === 'Block execution failed')
612+
)
613+
}
614+
615+
it('logs every block failure that rethrows one persistent object, not just the first', async () => {
616+
/** A rejected dynamic `import()` or memoized rejected promise rethrows the same object. */
617+
const persistentFault = new Error('handler module failed to load')
618+
const loggerIndex = blockExecutorBaseLogger.withMetadata.mock.results.length
619+
620+
await failBlockWith(persistentFault)
621+
await failBlockWith(persistentFault)
622+
623+
expect(blockFailureLogsSince(loggerIndex)).toHaveLength(2)
624+
})
625+
626+
it.each([
627+
['projects secrets and runtime identifiers out of', false],
628+
['fails closed to a structural', true],
629+
] as const)('%s the block failure line for a provider error', async (_name, incomplete) => {
630+
const secret = 'block-failure-secret'
631+
/** The Agent handler hands its provider error registry to the block executor this way. */
632+
const errorRegistry = new ResolvedSecretTraceRegistry([
633+
{ name: 'TOKEN', plaintext: secret, encryptedValue: 'encrypted-block-failure-secret' },
634+
])
635+
errorRegistry.recordResolved('TOKEN', secret)
636+
if (incomplete) errorRegistry.markIncomplete('unspecified')
637+
const block = createBlock()
638+
const workflow: SerializedWorkflow = {
639+
version: '1',
640+
blocks: [block],
641+
connections: [],
642+
loops: {},
643+
parallels: {},
644+
}
645+
const loggerIndex = blockExecutorBaseLogger.withMetadata.mock.results.length
646+
const state = new ExecutionState()
647+
const handler: BlockHandler = {
648+
canHandle: () => true,
649+
execute: async (ctx) => {
650+
ctx.errorResolvedSecretTraceRegistry = errorRegistry
651+
throw new Error(`provider failed with ${secret} __var_TOKEN __sim_runtime_test_1`)
652+
},
653+
}
654+
const executor = new BlockExecutor(
655+
[handler],
656+
new VariableResolver(workflow, {}, state),
657+
{},
658+
state
659+
)
660+
661+
await executor.execute(createContext(state), createNode(block), block).catch(() => undefined)
662+
663+
const logged = JSON.stringify(blockFailureLogsSince(loggerIndex))
664+
expect(logged).toContain('Block execution failed')
665+
for (const leaked of [secret, '__var_', '__sim_']) expect(logged).not.toContain(leaked)
666+
})
667+
668+
it('logs an internal child workflow fault with the block and run identity', async () => {
669+
const loggerIndex = blockExecutorBaseLogger.withMetadata.mock.results.length
670+
671+
await failBlockWith(
672+
new ChildWorkflowError({
673+
message: '"Child" failed: child load blew up',
674+
childWorkflowName: 'Child',
675+
cause: new TypeError('child load blew up'),
676+
})
677+
)
678+
679+
const [[, logged]] = blockFailureLogsSince(loggerIndex)
680+
expect(logged).toEqual(
681+
expect.objectContaining({
682+
blockId: 'function-block-1',
683+
executionId: 'execution-1',
684+
workflowId: 'workflow-1',
685+
error: '"Child" failed: child load blew up',
686+
failureKind: 'internal',
687+
})
688+
)
689+
})
690+
575691
it('does not soft-succeed non-agent blocks on user AbortError', async () => {
576692
const block = createBlock()
577693
const workflow: SerializedWorkflow = {
@@ -614,11 +730,15 @@ describe('BlockExecutor', () => {
614730
const ctx = createContext(state)
615731
ctx.abortSignal = abortController.signal
616732

617-
await expect(executor.execute(ctx, createNode(block), block)).rejects.toThrow(/abort/i)
733+
const thrown = await executor.execute(ctx, createNode(block), block).catch((error) => error)
734+
expect(thrown).toBeInstanceOf(Error)
735+
expect(thrown.message).toMatch(/abort/i)
618736

619737
const output = state.getBlockOutput(block.id)
620738
expect(output?.error).toBeTruthy()
621739
expect(output).not.toEqual({ content: '' })
740+
/** A user Stop is not a Sim fault, so it must not page at error. */
741+
expect(classifyFailure(thrown)).toBe('user')
622742
})
623743

624744
it('keeps Sim Chat secret policy in runtime inputs and out of trace inputs', async () => {

0 commit comments

Comments
 (0)