diff --git a/apps/sim/background/async-preprocessing-correlation.test.ts b/apps/sim/background/async-preprocessing-correlation.test.ts index 2f414d69aaa..3587f33ee7c 100644 --- a/apps/sim/background/async-preprocessing-correlation.test.ts +++ b/apps/sim/background/async-preprocessing-correlation.test.ts @@ -771,4 +771,49 @@ describe('async preprocessing correlation threading', () => { }) ) }) + + it('keeps the enqueuer admission when a reservation refresh throws', async () => { + // A throw is ambiguous: the refresh mutates the local reservation and the + // pointer separately, so it can fail after the slot's TTL was extended. + mockRefreshExecutionSlotExpiry.mockRejectedValueOnce(new Error('Command timed out')) + mockPreprocessExecution.mockResolvedValueOnce({ + success: true, + actorUserId: 'actor-1', + workflowRecord: { + id: 'workflow-1', + userId: 'owner-1', + workspaceId: 'workspace-1', + variables: {}, + }, + billingAttribution, + executionTimeout: {}, + }) + mockExecuteWorkflowCore.mockResolvedValueOnce({ + success: true, + status: 'success', + output: { ok: true }, + metadata: { duration: 10, userId: 'actor-1' }, + }) + + await expect( + executeWorkflowJob({ + principal, + workflowId: 'workflow-1', + userId: 'actor-1', + workspaceId: 'workspace-1', + billingAttribution, + triggerType: 'api', + executionId: 'execution-refresh-throw', + requestId: 'request-refresh-throw', + admissionCompleted: true, + executionTimeoutMs: 60_000, + }) + ).resolves.toEqual(expect.objectContaining({ success: true })) + + // Re-admitting would spend another rate-limit token and could reject a run + // that still holds a valid slot. + expect(mockPreprocessExecution).toHaveBeenCalledWith( + expect.objectContaining({ checkRateLimit: false, skipUsageLimits: true }) + ) + }) }) diff --git a/apps/sim/background/workflow-execution.ts b/apps/sim/background/workflow-execution.ts index e4b82ca8034..2911fb22514 100644 --- a/apps/sim/background/workflow-execution.ts +++ b/apps/sim/background/workflow-execution.ts @@ -165,14 +165,38 @@ export async function executeWorkflowJob( const executionDeadlineAt = getExecutionDeadlineAt(timeoutController.signal)?.getTime() let admissionCompleted = payload.admissionCompleted === true if (admissionCompleted && executionDeadlineAt !== undefined) { - admissionCompleted = await refreshExecutionSlotExpiry( - executionId, - executionDeadlineAt + RESERVATION_TTL_BUFFER_MS - ) - if (!admissionCompleted) { - logger.warn('Queued workflow reservation expired; repeating usage admission', { + try { + admissionCompleted = await refreshExecutionSlotExpiry( + executionId, + executionDeadlineAt + RESERVATION_TTL_BUFFER_MS + ) + if (!admissionCompleted) { + logger.warn('Queued workflow reservation expired; repeating usage admission', { + workflowId, + executionId, + }) + } + } catch (error) { + /** + * Only a `false` return proves the reservation is gone, and that is the + * one outcome re-admission is right for. A throw does not: the refresh + * is several separate Redis mutations, so it can fail after the slot's + * TTL was already extended, and a client-side command timeout abandons + * a call the server may still have applied. Re-admitting on that + * ambiguity would spend another rate-limit token and could reject a run + * that still holds a perfectly valid slot, so keep the admission the + * enqueuing surface already completed. + * + * Worst case the slot lapses before the run ends, which under-counts + * concurrency for this one execution; the later release is already a + * no-op when the reservation is gone. Previously this threw before the + * logging session existed, so the run left no log row at all and simply + * vanished from the workspace's logs. + */ + logger.warn('Reservation refresh failed; continuing on the existing admission', { workflowId, executionId, + error: toError(error).message, }) } } diff --git a/apps/sim/instrumentation-node.ts b/apps/sim/instrumentation-node.ts index 2b9da2a012c..85a0355abed 100644 --- a/apps/sim/instrumentation-node.ts +++ b/apps/sim/instrumentation-node.ts @@ -397,4 +397,14 @@ export async function register() { const { startMemoryTelemetry } = await import('./lib/monitoring/memory-telemetry') startMemoryTelemetry() + + /** + * Open the shared Redis connection during boot so the first request does not + * pay the TLS handshake inside its own command deadline. Deliberately not + * awaited: a slow or unreachable Redis must never hold up serving, and + * `warmRedisConnection` already bounds and swallows its own failures. + */ + void import('./lib/core/config/redis') + .then(({ warmRedisConnection }) => warmRedisConnection()) + .catch((error) => logger.warn('Redis warm-up could not start', { error })) } diff --git a/apps/sim/lib/core/config/redis.test.ts b/apps/sim/lib/core/config/redis.test.ts index 96b0c49e4b6..65a2382ae94 100644 --- a/apps/sim/lib/core/config/redis.test.ts +++ b/apps/sim/lib/core/config/redis.test.ts @@ -29,8 +29,11 @@ import { closeRedisConnection, extendLock, getRedisClient, + getRedisConnectionDefaults, onRedisReconnect, + REDIS_COMMAND_TIMEOUT_MS, resetForTesting, + warmRedisConnection, } from '@/lib/core/config/redis' describe('redis config', () => { @@ -303,6 +306,110 @@ describe('redis config', () => { }) }) + describe('command timeout', () => { + it('stays above the connect timeout so a slow handshake is not reported as a command timeout', () => { + const { connectTimeout } = getRedisConnectionDefaults('redis://localhost:6379') + + expect(connectTimeout).toBeDefined() + expect(REDIS_COMMAND_TIMEOUT_MS).toBeGreaterThan(connectTimeout as number) + }) + + it('applies that timeout to the shared client', () => { + getRedisClient() + + expect(MockRedisConstructor).toHaveBeenCalledWith( + expect.any(String), + expect.objectContaining({ commandTimeout: REDIS_COMMAND_TIMEOUT_MS }) + ) + }) + + it('does not let the command deadline govern how fast a dead connection is detected', async () => { + const listener = vi.fn() + onRedisReconnect(listener) + getRedisClient() + + // A PING that never settles — the failure mode the health check exists for. + mockRedisInstance.ping.mockReturnValue(new Promise(() => {})) + + // Two intervals plus two probe deadlines is well under two command + // deadlines, so this only passes while the probe has its own budget. + await vi.advanceTimersByTimeAsync(15_000) + await vi.advanceTimersByTimeAsync(15_000) + await vi.advanceTimersByTimeAsync(15_000) + + expect(listener).toHaveBeenCalledTimes(1) + expect(3 * 15_000).toBeLessThan(2 * REDIS_COMMAND_TIMEOUT_MS + 2 * 15_000) + }) + }) + + describe('warmRedisConnection', () => { + it('resolves without waiting when the client is already connected', async () => { + mockRedisInstance.status = 'ready' + + await expect(warmRedisConnection()).resolves.toBeUndefined() + expect(mockRedisInstance.once).not.toHaveBeenCalled() + }) + + it('resolves once the connection reports ready', async () => { + mockRedisInstance.status = 'connecting' + const readyHandlers: Array<() => void> = [] + mockRedisInstance.once.mockImplementation((event: string, cb: () => void) => { + if (event === 'ready') readyHandlers.push(cb) + }) + + let settled = false + const warm = warmRedisConnection().then(() => { + settled = true + }) + + await vi.advanceTimersByTimeAsync(2_000) + expect(settled).toBe(false) + + for (const handler of readyHandlers) handler() + await warm + + expect(settled).toBe(true) + }) + + it('gives up at the connect deadline rather than blocking startup forever', async () => { + mockRedisInstance.status = 'connecting' + mockRedisInstance.once.mockImplementation(() => {}) + + let settled = false + const warm = warmRedisConnection().then(() => { + settled = true + }) + + await vi.advanceTimersByTimeAsync(9_000) + expect(settled).toBe(false) + + await vi.advanceTimersByTimeAsync(2_000) + await warm + + expect(settled).toBe(true) + }) + + it('warms a given client once so a warm process pays nothing per unit of work', async () => { + mockRedisInstance.status = 'connecting' + mockRedisInstance.once.mockImplementation((event: string, cb: () => void) => { + if (event === 'ready') cb() + }) + + await warmRedisConnection() + const callsAfterFirst = mockRedisInstance.once.mock.calls.length + + await warmRedisConnection() + + expect(mockRedisInstance.once.mock.calls.length).toBe(callsAfterFirst) + }) + + it('resolves instead of throwing when Redis is not configured', async () => { + mockEnv.REDIS_URL = undefined + + await expect(warmRedisConnection()).resolves.toBeUndefined() + }) + }) + describe('retryStrategy', () => { function captureRetryStrategy(): (times: number) => number { let capturedConfig: Record = {} diff --git a/apps/sim/lib/core/config/redis.ts b/apps/sim/lib/core/config/redis.ts index 04ae9ae53b2..a48ae1bfba1 100644 --- a/apps/sim/lib/core/config/redis.ts +++ b/apps/sim/lib/core/config/redis.ts @@ -36,10 +36,34 @@ function resolveRedisTlsOptions(url: string | undefined): { servername: string } return { servername: env.REDIS_TLS_SERVERNAME } } +const REDIS_CONNECT_TIMEOUT_MS = 10_000 + +/** + * Per-command deadline. MUST stay greater than `REDIS_CONNECT_TIMEOUT_MS`. + * + * `sendCommand` arms this timer *before* it checks whether the socket is + * writable and before the `enableOfflineQueue` branch, so a command issued + * while the connection is still being established is already counting down + * while it waits in the offline queue. Set below the connect timeout, every + * slow handshake surfaces as `Command timed out` — attributed to a Redis that + * never received the command, with a stack containing only ioredis timer + * frames. + * + * The gap between opening a connection and servicing its `connect` callback is + * measured in seconds during an initialization burst — not because the network + * or the server is slow (the `INFO` round-trip that follows completes in ~10ms, + * and the server sits near-idle), but because the callback cannot run while the + * main thread is saturated. This deadline is wall-clock, so it spans that delay + * whether the cause is the network or a busy event loop, which is exactly why it + * has to leave room beyond the connect budget. + */ +export const REDIS_COMMAND_TIMEOUT_MS = 15_000 + /** * Shared connection defaults — keepAlive, connectTimeout, enableOfflineQueue, * and TLS SNI when REDIS_URL targets an IP. Every Redis client we open should - * spread this; callers add their own retry / timeout policy on top. + * spread this; callers add their own retry policy on top and take their command + * deadline from `REDIS_COMMAND_TIMEOUT_MS` so the invariant above holds. */ export function getRedisConnectionDefaults( url: string | undefined @@ -47,7 +71,7 @@ export function getRedisConnectionDefaults( const tls = resolveRedisTlsOptions(url) return { keepAlive: 1000, - connectTimeout: 10000, + connectTimeout: REDIS_CONNECT_TIMEOUT_MS, enableOfflineQueue: true, ...(tls ? { tls } : {}), } @@ -59,6 +83,7 @@ interface RedisState { pingInterval: NodeJS.Timeout | null pingInFlight: boolean reconnectListeners: Array<() => void> + warmPromise: Promise | null } const g = globalThis as typeof globalThis & { _redisState?: RedisState } @@ -69,6 +94,7 @@ if (!g._redisState) { pingInterval: null, pingInFlight: false, reconnectListeners: [], + warmPromise: null, } } const state = g._redisState @@ -76,6 +102,38 @@ const state = g._redisState const PING_INTERVAL_MS = 15_000 const MAX_PING_FAILURES = 2 +/** + * Deadline for a single health probe. + * + * A PING is only ever issued on an already-established connection, so unlike a + * general command it is never waiting on a handshake and takes a much tighter + * deadline. Keeping it independent of `REDIS_COMMAND_TIMEOUT_MS` is what stops + * the wider command deadline from slowing failover: two consecutive misses + * still force a reconnect within roughly two intervals. + */ +const REDIS_PING_TIMEOUT_MS = 5_000 + +/** + * `commandTimeout` cannot express "probe deadline" separately from "command + * deadline" — it is a single client-wide option — so the probe carries its own. + */ +async function pingWithDeadline(redis: Redis): Promise { + let timer: NodeJS.Timeout | undefined + try { + await Promise.race([ + redis.ping(), + new Promise((_, reject) => { + timer = setTimeout( + () => reject(new Error('Redis PING deadline exceeded')), + REDIS_PING_TIMEOUT_MS + ) + }), + ]) + } finally { + if (timer) clearTimeout(timer) + } +} + export function getConfiguredRedisUrl(): string | null { if (getConfiguredCacheProvider() === 'database') return null @@ -101,7 +159,7 @@ function startPingHealthCheck(redis: Redis): void { if (state.pingInFlight) return state.pingInFlight = true try { - await redis.ping() + await pingWithDeadline(redis) state.pingFailures = 0 } catch (error) { state.pingFailures++ @@ -117,6 +175,8 @@ function startPingHealthCheck(redis: Redis): void { state.pingFailures = 0 // Clear before notifying listeners — they may call getRedisClient() and must see the reset state. state.client = null + // The next client is cold again, so let it be warmed before first use. + state.warmPromise = null if (state.pingInterval) { clearInterval(state.pingInterval) state.pingInterval = null @@ -161,7 +221,7 @@ export function getRedisClient(): Redis | null { state.client = new Redis(redisUrl, { ...defaults, - commandTimeout: 5000, + commandTimeout: REDIS_COMMAND_TIMEOUT_MS, maxRetriesPerRequest: 5, retryStrategy: (times) => { @@ -199,6 +259,80 @@ export function getRedisClient(): Redis | null { } } +/** + * Establish the shared connection before the first command needs it. + * + * `commandTimeout` is a total deadline that starts the moment a command is + * issued: ioredis arms it in `sendCommand` before it checks whether the socket + * is writable, so the budget covers handshake and offline-queue wait as well as + * execution. A process whose first command lands on a cold client therefore + * spends that budget waiting for the connection rather than running the command. + * + * Warming separates the two: the wait becomes connection setup, bounded by + * `connectTimeout`, instead of eating a command's deadline. It also follows the + * connection-reuse practice AWS recommends — establishing a connection costs far + * more than the commands that run over it, so it belongs once per process rather + * than once per unit of work. Note this does not make the connection ready any + * sooner when the delay is a saturated event loop rather than the network; it + * only stops that delay from being charged to a command. + * + * Best effort by design — resolves rather than rejects on failure, and is + * bounded by the connect budget, so neither a degraded Redis nor a missing + * configuration can stop a process from starting. Callers that skip warming + * still work; they just wait on their first command as before. + * + * Memoized per client: a warm process returns immediately, and a forced + * reconnect clears it so the replacement connection is warmed in turn. + */ +export function warmRedisConnection(): Promise { + if (state.warmPromise) return state.warmPromise + + let client: Redis | null + try { + client = getRedisClient() + } catch (error) { + logger.warn('Skipping Redis warm-up: client unavailable', { + error: toError(error).message, + }) + return Promise.resolve() + } + + if (!client) return Promise.resolve() + if (client.status === 'ready') return Promise.resolve() + + const startedAt = Date.now() + state.warmPromise = new Promise((resolve) => { + let settled = false + let timer: NodeJS.Timeout | undefined + + const finish = (outcome: 'ready' | 'deadline') => { + if (settled) return + settled = true + if (timer) clearTimeout(timer) + client.off('ready', onReady) + const elapsedMs = Date.now() - startedAt + if (outcome === 'ready') { + logger.info('Redis connection warmed', { elapsedMs }) + } else { + logger.warn('Redis warm-up did not complete before its deadline', { elapsedMs }) + } + resolve() + } + + const onReady = () => finish('ready') + + /** + * Only `ready` settles early. A transient `error` is followed by ioredis's + * own retry, so resolving on it would hand back a still-cold client and + * reintroduce the very race this removes; the deadline is the backstop. + */ + timer = setTimeout(() => finish('deadline'), REDIS_CONNECT_TIMEOUT_MS) + client.once('ready', onReady) + }) + + return state.warmPromise +} + /** * Lua script for safe lock release. * Only deletes the key if the value matches (ownership verification). @@ -354,5 +488,6 @@ export function resetForTesting(): void { state.client = null state.pingFailures = 0 state.pingInFlight = false + state.warmPromise = null state.reconnectListeners.length = 0 } diff --git a/apps/sim/lib/execution/execution-signal.test.ts b/apps/sim/lib/execution/execution-signal.test.ts index 005b9d68357..06d45812e9f 100644 --- a/apps/sim/lib/execution/execution-signal.test.ts +++ b/apps/sim/lib/execution/execution-signal.test.ts @@ -25,6 +25,7 @@ vi.mock('ioredis', () => ({ vi.mock('@/lib/core/config/redis', () => ({ getConfiguredRedisUrl: () => mockRedisUrl.value, getRedisConnectionDefaults: () => ({}), + REDIS_COMMAND_TIMEOUT_MS: 15_000, })) import { diff --git a/apps/sim/lib/execution/execution-signal.ts b/apps/sim/lib/execution/execution-signal.ts index 4c90d43e2ab..b2f5bcc1ced 100644 --- a/apps/sim/lib/execution/execution-signal.ts +++ b/apps/sim/lib/execution/execution-signal.ts @@ -2,7 +2,11 @@ import { createLogger } from '@sim/logger' import { toError } from '@sim/utils/errors' import { isRecordLike } from '@sim/utils/object' import Redis, { type RedisOptions } from 'ioredis' -import { getConfiguredRedisUrl, getRedisConnectionDefaults } from '@/lib/core/config/redis' +import { + getConfiguredRedisUrl, + getRedisConnectionDefaults, + REDIS_COMMAND_TIMEOUT_MS, +} from '@/lib/core/config/redis' const logger = createLogger('ExecutionSignalHub') const EXECUTION_SIGNAL_PREFIX = 'execution:signal:' @@ -28,7 +32,7 @@ class RedisExecutionSignalHub implements ExecutionSignalHub { constructor(redisUrl: string) { const options = { ...getRedisConnectionDefaults(redisUrl), - commandTimeout: 5000, + commandTimeout: REDIS_COMMAND_TIMEOUT_MS, connectionName: 'execution-signal-hub', maxRetriesPerRequest: null, retryStrategy: (attempt: number) => Math.min(attempt * 500, 5000), diff --git a/apps/sim/lib/execution/preprocessing.test.ts b/apps/sim/lib/execution/preprocessing.test.ts index 03f8a83c1f8..f721964041d 100644 --- a/apps/sim/lib/execution/preprocessing.test.ts +++ b/apps/sim/lib/execution/preprocessing.test.ts @@ -62,6 +62,7 @@ vi.mock('@/lib/core/rate-limiter/rate-limiter', () => ({ })) vi.mock('@/lib/logs/execution/logging-session', () => loggingSessionMock) +import { UsageReservationUnavailableError } from '@/lib/billing/calculations/usage-reservation' import { getHighestPrioritySubscription } from '@/lib/billing/core/subscription' import { preprocessExecution, WORKFLOW_NOT_DEPLOYED_CODE } from './preprocessing' @@ -289,6 +290,38 @@ describe('preprocessExecution suppressRetryableFailureLogs option', () => { expect(loggingSession.safeStart).not.toHaveBeenCalled() }) + it('skips the failure row when admission infrastructure is unavailable and a retry remains', async () => { + mockReserveExecutionSlot.mockRejectedValueOnce( + new UsageReservationUnavailableError('Usage admission is temporarily unavailable.') + ) + const loggingSession = makeLoggingSession() + + const result = await preprocessExecution({ + ...baseOptions, + suppressRetryableFailureLogs: true, + loggingSession: loggingSession as any, + }) + + expect(result).toMatchObject({ success: false, error: { statusCode: 503, retryable: true } }) + expect(loggingSession.safeStart).not.toHaveBeenCalled() + }) + + it('records the failure row for an unavailable admission when no retry remains', async () => { + mockReserveExecutionSlot.mockRejectedValueOnce( + new UsageReservationUnavailableError('Usage admission is temporarily unavailable.') + ) + const loggingSession = makeLoggingSession() + + const result = await preprocessExecution({ + ...baseOptions, + suppressRetryableFailureLogs: false, + loggingSession: loggingSession as any, + }) + + expect(result).toMatchObject({ success: false, error: { statusCode: 503, retryable: true } }) + expect(loggingSession.safeStart).toHaveBeenCalled() + }) + it('still records non-retryable failures while suppression is on', async () => { workflowAuthzMockFns.mockGetActiveWorkflowRecord.mockRejectedValueOnce( new Error('column "unknown" does not exist') diff --git a/apps/sim/lib/execution/preprocessing.ts b/apps/sim/lib/execution/preprocessing.ts index c68dda80679..d6724906338 100644 --- a/apps/sim/lib/execution/preprocessing.ts +++ b/apps/sim/lib/execution/preprocessing.ts @@ -816,19 +816,44 @@ export async function preprocessExecution( 'Usage admission is temporarily unavailable. Please retry.', error ) - return { - success: false, - error: { - message: unavailable.message, - statusCode: unavailable.statusCode, + + /** + * Matches the denial path above. Without this a run rejected because the + * admission infrastructure was unreachable left no execution log at all, + * so it disappeared from the workspace's logs rather than showing as a + * failure — the denial branch twenty lines up always recorded one. + * + * Unlike that branch, this one has to honor the suppression: its denial + * descriptors are 402/429, while this failure is 503 and retryable, which + * is precisely what a requeuing caller defers. Recording here regardless + * would write a terminal failure for an execution about to be retried. + */ + const unavailableFailure: PreprocessExecutionError = { + message: unavailable.message, + statusCode: unavailable.statusCode, + code: unavailable.code, + retryable: unavailable.retryable, + ...retryAfterMsFrom(unavailable.retryAfterSeconds), + cause: { code: unavailable.code, - retryable: unavailable.retryable, - ...retryAfterMsFrom(unavailable.retryAfterSeconds), - cause: { - code: unavailable.code, - }, }, } + + if (!isFailureLogSuppressed(unavailableFailure)) { + await recordPreprocessingError({ + workflowId, + executionId, + triggerType, + requestId, + userId: actorUserId, + workspaceId, + errorMessage: unavailable.message, + loggingSession: providedLoggingSession, + triggerData, + }) + } + + return { success: false, error: unavailableFailure } } } diff --git a/apps/sim/trigger.config.ts b/apps/sim/trigger.config.ts index 1e5c0de7171..779fcd02bb0 100644 --- a/apps/sim/trigger.config.ts +++ b/apps/sim/trigger.config.ts @@ -86,8 +86,17 @@ export default defineConfig({ * * @see https://trigger.dev/docs/config/config-file#lifecycle-functions */ - init: () => { + init: async () => { markInsideTriggerRun() + /** + * Every run gets a fresh process, so without this the run's first Redis + * command pays the TLS handshake inside its own command deadline. Awaiting + * here spends that time as connection setup instead, where `connectTimeout` + * bounds it. Imported dynamically so loading this config file — which the + * CLI also does at build time — does not pull in the Redis client. + */ + const { warmRedisConnection } = await import('./lib/core/config/redis') + await warmRedisConnection() }, ...(grafanaTelemetry ? { telemetry: grafanaTelemetry } : {}), build: { diff --git a/packages/testing/src/mocks/redis.mock.ts b/packages/testing/src/mocks/redis.mock.ts index 6771714cb2e..f7e7af8665f 100644 --- a/packages/testing/src/mocks/redis.mock.ts +++ b/packages/testing/src/mocks/redis.mock.ts @@ -50,6 +50,8 @@ export function createMockRedis() { subscribe: vi.fn().mockResolvedValue(undefined), unsubscribe: vi.fn().mockResolvedValue(undefined), on: vi.fn(), + once: vi.fn(), + off: vi.fn(), // Transaction multi: vi.fn(() => ({