Skip to content

Commit 0d9f4dd

Browse files
committed
fix(redis): stop a slow handshake from failing as a command timeout
ioredis arms the commandTimeout timer in sendCommand before it checks whether the socket is writable, so the budget covers connection setup and offline-queue wait as well as execution. With commandTimeout below connectTimeout, any handshake slower than the command deadline surfaced as "Command timed out" from a Redis that never received the command. - Raise the command deadline above the connect budget and derive both from named constants so the invariant cannot drift - Give the PING health check its own deadline so the wider command budget does not slow failover detection - Warm the shared connection at process start (Trigger.dev init, Next instrumentation) so a run's first command does not pay the handshake inside its own deadline - Record an execution log when admission infrastructure is unreachable, so those runs show as failed instead of disappearing - Re-admit rather than abort when a reservation refresh throws
1 parent 2795922 commit 0d9f4dd

9 files changed

Lines changed: 312 additions & 13 deletions

File tree

apps/sim/background/workflow-execution.ts

Lines changed: 24 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -165,14 +165,32 @@ export async function executeWorkflowJob(
165165
const executionDeadlineAt = getExecutionDeadlineAt(timeoutController.signal)?.getTime()
166166
let admissionCompleted = payload.admissionCompleted === true
167167
if (admissionCompleted && executionDeadlineAt !== undefined) {
168-
admissionCompleted = await refreshExecutionSlotExpiry(
169-
executionId,
170-
executionDeadlineAt + RESERVATION_TTL_BUFFER_MS
171-
)
172-
if (!admissionCompleted) {
173-
logger.warn('Queued workflow reservation expired; repeating usage admission', {
168+
/**
169+
* A refresh that *returns* false already degrades into repeating usage
170+
* admission below. A refresh that *throws* — a Redis timeout on the first
171+
* command this fresh worker process issues — used to kill the run here,
172+
* before the logging session exists, so the execution left no log row at
173+
* all and simply vanished from the workspace's logs. Route both outcomes
174+
* into the same re-admission path: preprocessing owns the reservation
175+
* retry, and any failure it hits is recorded against a live session.
176+
*/
177+
try {
178+
admissionCompleted = await refreshExecutionSlotExpiry(
179+
executionId,
180+
executionDeadlineAt + RESERVATION_TTL_BUFFER_MS
181+
)
182+
if (!admissionCompleted) {
183+
logger.warn('Queued workflow reservation expired; repeating usage admission', {
184+
workflowId,
185+
executionId,
186+
})
187+
}
188+
} catch (error) {
189+
admissionCompleted = false
190+
logger.warn('Reservation refresh failed; repeating usage admission', {
174191
workflowId,
175192
executionId,
193+
error: toError(error).message,
176194
})
177195
}
178196
}

apps/sim/instrumentation-node.ts

Lines changed: 10 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -397,4 +397,14 @@ export async function register() {
397397

398398
const { startMemoryTelemetry } = await import('./lib/monitoring/memory-telemetry')
399399
startMemoryTelemetry()
400+
401+
/**
402+
* Open the shared Redis connection during boot so the first request does not
403+
* pay the TLS handshake inside its own command deadline. Deliberately not
404+
* awaited: a slow or unreachable Redis must never hold up serving, and
405+
* `warmRedisConnection` already bounds and swallows its own failures.
406+
*/
407+
void import('./lib/core/config/redis')
408+
.then(({ warmRedisConnection }) => warmRedisConnection())
409+
.catch((error) => logger.warn('Redis warm-up could not start', { error }))
400410
}

apps/sim/lib/core/config/redis.test.ts

Lines changed: 107 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -29,8 +29,11 @@ import {
2929
closeRedisConnection,
3030
extendLock,
3131
getRedisClient,
32+
getRedisConnectionDefaults,
3233
onRedisReconnect,
34+
REDIS_COMMAND_TIMEOUT_MS,
3335
resetForTesting,
36+
warmRedisConnection,
3437
} from '@/lib/core/config/redis'
3538

3639
describe('redis config', () => {
@@ -303,6 +306,110 @@ describe('redis config', () => {
303306
})
304307
})
305308

309+
describe('command timeout', () => {
310+
it('stays above the connect timeout so a slow handshake is not reported as a command timeout', () => {
311+
const { connectTimeout } = getRedisConnectionDefaults('redis://localhost:6379')
312+
313+
expect(connectTimeout).toBeDefined()
314+
expect(REDIS_COMMAND_TIMEOUT_MS).toBeGreaterThan(connectTimeout as number)
315+
})
316+
317+
it('applies that timeout to the shared client', () => {
318+
getRedisClient()
319+
320+
expect(MockRedisConstructor).toHaveBeenCalledWith(
321+
expect.any(String),
322+
expect.objectContaining({ commandTimeout: REDIS_COMMAND_TIMEOUT_MS })
323+
)
324+
})
325+
326+
it('does not let the command deadline govern how fast a dead connection is detected', async () => {
327+
const listener = vi.fn()
328+
onRedisReconnect(listener)
329+
getRedisClient()
330+
331+
// A PING that never settles — the failure mode the health check exists for.
332+
mockRedisInstance.ping.mockReturnValue(new Promise(() => {}))
333+
334+
// Two intervals plus two probe deadlines is well under two command
335+
// deadlines, so this only passes while the probe has its own budget.
336+
await vi.advanceTimersByTimeAsync(15_000)
337+
await vi.advanceTimersByTimeAsync(15_000)
338+
await vi.advanceTimersByTimeAsync(15_000)
339+
340+
expect(listener).toHaveBeenCalledTimes(1)
341+
expect(3 * 15_000).toBeLessThan(2 * REDIS_COMMAND_TIMEOUT_MS + 2 * 15_000)
342+
})
343+
})
344+
345+
describe('warmRedisConnection', () => {
346+
it('resolves without waiting when the client is already connected', async () => {
347+
mockRedisInstance.status = 'ready'
348+
349+
await expect(warmRedisConnection()).resolves.toBeUndefined()
350+
expect(mockRedisInstance.once).not.toHaveBeenCalled()
351+
})
352+
353+
it('resolves once the connection reports ready', async () => {
354+
mockRedisInstance.status = 'connecting'
355+
const readyHandlers: Array<() => void> = []
356+
mockRedisInstance.once.mockImplementation((event: string, cb: () => void) => {
357+
if (event === 'ready') readyHandlers.push(cb)
358+
})
359+
360+
let settled = false
361+
const warm = warmRedisConnection().then(() => {
362+
settled = true
363+
})
364+
365+
await vi.advanceTimersByTimeAsync(2_000)
366+
expect(settled).toBe(false)
367+
368+
for (const handler of readyHandlers) handler()
369+
await warm
370+
371+
expect(settled).toBe(true)
372+
})
373+
374+
it('gives up at the connect deadline rather than blocking startup forever', async () => {
375+
mockRedisInstance.status = 'connecting'
376+
mockRedisInstance.once.mockImplementation(() => {})
377+
378+
let settled = false
379+
const warm = warmRedisConnection().then(() => {
380+
settled = true
381+
})
382+
383+
await vi.advanceTimersByTimeAsync(9_000)
384+
expect(settled).toBe(false)
385+
386+
await vi.advanceTimersByTimeAsync(2_000)
387+
await warm
388+
389+
expect(settled).toBe(true)
390+
})
391+
392+
it('warms a given client once so a warm process pays nothing per unit of work', async () => {
393+
mockRedisInstance.status = 'connecting'
394+
mockRedisInstance.once.mockImplementation((event: string, cb: () => void) => {
395+
if (event === 'ready') cb()
396+
})
397+
398+
await warmRedisConnection()
399+
const callsAfterFirst = mockRedisInstance.once.mock.calls.length
400+
401+
await warmRedisConnection()
402+
403+
expect(mockRedisInstance.once.mock.calls.length).toBe(callsAfterFirst)
404+
})
405+
406+
it('resolves instead of throwing when Redis is not configured', async () => {
407+
mockEnv.REDIS_URL = undefined
408+
409+
await expect(warmRedisConnection()).resolves.toBeUndefined()
410+
})
411+
})
412+
306413
describe('retryStrategy', () => {
307414
function captureRetryStrategy(): (times: number) => number {
308415
let capturedConfig: Record<string, unknown> = {}

apps/sim/lib/core/config/redis.ts

Lines changed: 133 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -36,18 +36,38 @@ function resolveRedisTlsOptions(url: string | undefined): { servername: string }
3636
return { servername: env.REDIS_TLS_SERVERNAME }
3737
}
3838

39+
const REDIS_CONNECT_TIMEOUT_MS = 10_000
40+
41+
/**
42+
* Per-command deadline. MUST stay greater than `REDIS_CONNECT_TIMEOUT_MS`.
43+
*
44+
* `sendCommand` arms this timer *before* it checks whether the socket is
45+
* writable and before the `enableOfflineQueue` branch, so a command issued
46+
* while the connection is still being established is already counting down
47+
* while it waits in the offline queue. Set below the connect timeout, every
48+
* slow handshake surfaces as `Command timed out` — attributed to a Redis that
49+
* never received the command, with a stack containing only ioredis timer
50+
* frames.
51+
*
52+
* Production handshakes to ElastiCache measure 2-6s when several connections
53+
* are opened at once, so a 5s command timeout failed roughly 3% of cold-start
54+
* commands on Trigger.dev workers, which open a fresh connection per run.
55+
*/
56+
export const REDIS_COMMAND_TIMEOUT_MS = 15_000
57+
3958
/**
4059
* Shared connection defaults — keepAlive, connectTimeout, enableOfflineQueue,
4160
* and TLS SNI when REDIS_URL targets an IP. Every Redis client we open should
42-
* spread this; callers add their own retry / timeout policy on top.
61+
* spread this; callers add their own retry policy on top and take their command
62+
* deadline from `REDIS_COMMAND_TIMEOUT_MS` so the invariant above holds.
4363
*/
4464
export function getRedisConnectionDefaults(
4565
url: string | undefined
4666
): Pick<RedisOptions, 'keepAlive' | 'connectTimeout' | 'enableOfflineQueue' | 'tls'> {
4767
const tls = resolveRedisTlsOptions(url)
4868
return {
4969
keepAlive: 1000,
50-
connectTimeout: 10000,
70+
connectTimeout: REDIS_CONNECT_TIMEOUT_MS,
5171
enableOfflineQueue: true,
5272
...(tls ? { tls } : {}),
5373
}
@@ -59,6 +79,7 @@ interface RedisState {
5979
pingInterval: NodeJS.Timeout | null
6080
pingInFlight: boolean
6181
reconnectListeners: Array<() => void>
82+
warmPromise: Promise<void> | null
6283
}
6384

6485
const g = globalThis as typeof globalThis & { _redisState?: RedisState }
@@ -69,13 +90,46 @@ if (!g._redisState) {
6990
pingInterval: null,
7091
pingInFlight: false,
7192
reconnectListeners: [],
93+
warmPromise: null,
7294
}
7395
}
7496
const state = g._redisState
7597

7698
const PING_INTERVAL_MS = 15_000
7799
const MAX_PING_FAILURES = 2
78100

101+
/**
102+
* Deadline for a single health probe.
103+
*
104+
* A PING is only ever issued on an already-established connection, so unlike a
105+
* general command it is never waiting on a handshake and takes a much tighter
106+
* deadline. Keeping it independent of `REDIS_COMMAND_TIMEOUT_MS` is what stops
107+
* the wider command deadline from slowing failover: two consecutive misses
108+
* still force a reconnect within roughly two intervals.
109+
*/
110+
const REDIS_PING_TIMEOUT_MS = 5_000
111+
112+
/**
113+
* `commandTimeout` cannot express "probe deadline" separately from "command
114+
* deadline" — it is a single client-wide option — so the probe carries its own.
115+
*/
116+
async function pingWithDeadline(redis: Redis): Promise<void> {
117+
let timer: NodeJS.Timeout | undefined
118+
try {
119+
await Promise.race([
120+
redis.ping(),
121+
new Promise<never>((_, reject) => {
122+
timer = setTimeout(
123+
() => reject(new Error('Redis PING deadline exceeded')),
124+
REDIS_PING_TIMEOUT_MS
125+
)
126+
}),
127+
])
128+
} finally {
129+
if (timer) clearTimeout(timer)
130+
}
131+
}
132+
79133
export function getConfiguredRedisUrl(): string | null {
80134
if (getConfiguredCacheProvider() === 'database') return null
81135

@@ -101,7 +155,7 @@ function startPingHealthCheck(redis: Redis): void {
101155
if (state.pingInFlight) return
102156
state.pingInFlight = true
103157
try {
104-
await redis.ping()
158+
await pingWithDeadline(redis)
105159
state.pingFailures = 0
106160
} catch (error) {
107161
state.pingFailures++
@@ -117,6 +171,8 @@ function startPingHealthCheck(redis: Redis): void {
117171
state.pingFailures = 0
118172
// Clear before notifying listeners — they may call getRedisClient() and must see the reset state.
119173
state.client = null
174+
// The next client is cold again, so let it be warmed before first use.
175+
state.warmPromise = null
120176
if (state.pingInterval) {
121177
clearInterval(state.pingInterval)
122178
state.pingInterval = null
@@ -161,7 +217,7 @@ export function getRedisClient(): Redis | null {
161217

162218
state.client = new Redis(redisUrl, {
163219
...defaults,
164-
commandTimeout: 5000,
220+
commandTimeout: REDIS_COMMAND_TIMEOUT_MS,
165221
maxRetriesPerRequest: 5,
166222

167223
retryStrategy: (times) => {
@@ -199,6 +255,78 @@ export function getRedisClient(): Redis | null {
199255
}
200256
}
201257

258+
/**
259+
* Establish the shared connection before the first command needs it.
260+
*
261+
* `commandTimeout` is a total deadline that starts the moment a command is
262+
* issued: ioredis arms it in `sendCommand` before it checks whether the socket
263+
* is writable, so the budget covers handshake and offline-queue wait as well as
264+
* execution. A process whose first command lands on a cold client therefore
265+
* spends most of that budget on the TLS handshake, which measures 2-6s against
266+
* ElastiCache when several connections open at once.
267+
*
268+
* Warming at process start moves that cost off the first command's clock, which
269+
* is the connection-reuse practice AWS recommends: establishing a TCP+TLS
270+
* connection is far more expensive than the commands that run over it, so it
271+
* should be paid once per process rather than once per unit of work.
272+
*
273+
* Best effort by design — resolves rather than rejects on failure, and is
274+
* bounded by the connect budget, so neither a degraded Redis nor a missing
275+
* configuration can stop a process from starting. Callers that skip warming
276+
* still work; they just pay the handshake on their first command as before.
277+
*
278+
* Memoized per client: a warm process returns immediately, and a forced
279+
* reconnect clears it so the replacement connection is warmed in turn.
280+
*/
281+
export function warmRedisConnection(): Promise<void> {
282+
if (state.warmPromise) return state.warmPromise
283+
284+
let client: Redis | null
285+
try {
286+
client = getRedisClient()
287+
} catch (error) {
288+
logger.warn('Skipping Redis warm-up: client unavailable', {
289+
error: toError(error).message,
290+
})
291+
return Promise.resolve()
292+
}
293+
294+
if (!client) return Promise.resolve()
295+
if (client.status === 'ready') return Promise.resolve()
296+
297+
const startedAt = Date.now()
298+
state.warmPromise = new Promise<void>((resolve) => {
299+
let settled = false
300+
let timer: NodeJS.Timeout | undefined
301+
302+
const finish = (outcome: 'ready' | 'deadline') => {
303+
if (settled) return
304+
settled = true
305+
if (timer) clearTimeout(timer)
306+
client.off('ready', onReady)
307+
const elapsedMs = Date.now() - startedAt
308+
if (outcome === 'ready') {
309+
logger.info('Redis connection warmed', { elapsedMs })
310+
} else {
311+
logger.warn('Redis warm-up did not complete before its deadline', { elapsedMs })
312+
}
313+
resolve()
314+
}
315+
316+
const onReady = () => finish('ready')
317+
318+
/**
319+
* Only `ready` settles early. A transient `error` is followed by ioredis's
320+
* own retry, so resolving on it would hand back a still-cold client and
321+
* reintroduce the very race this removes; the deadline is the backstop.
322+
*/
323+
timer = setTimeout(() => finish('deadline'), REDIS_CONNECT_TIMEOUT_MS)
324+
client.once('ready', onReady)
325+
})
326+
327+
return state.warmPromise
328+
}
329+
202330
/**
203331
* Lua script for safe lock release.
204332
* Only deletes the key if the value matches (ownership verification).
@@ -354,5 +482,6 @@ export function resetForTesting(): void {
354482
state.client = null
355483
state.pingFailures = 0
356484
state.pingInFlight = false
485+
state.warmPromise = null
357486
state.reconnectListeners.length = 0
358487
}

apps/sim/lib/execution/execution-signal.test.ts

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -25,6 +25,7 @@ vi.mock('ioredis', () => ({
2525
vi.mock('@/lib/core/config/redis', () => ({
2626
getConfiguredRedisUrl: () => mockRedisUrl.value,
2727
getRedisConnectionDefaults: () => ({}),
28+
REDIS_COMMAND_TIMEOUT_MS: 15_000,
2829
}))
2930

3031
import {

0 commit comments

Comments
 (0)