Skip to content

Commit 9334a4d

Browse files
committed
feat(observability): record Redis connection state on failed slot operations
A Redis command that never gets a reply fails identically whether the connection was still being established, was reconnecting with the command parked in the offline queue, or was a socket that had silently died. ioredis reports all three the same way — `Error: Command timed out` with only its own timer frames in the stack, no app frame naming the call, and no lifecycle event saying which happened. Nothing recorded anywhere distinguishes them, so the cause can only be inferred from timing. Adds `describeRedisConnection()`: client status, connection and ready ages, offline-queue depth, lifecycle counters, and whether the configured host is an IP or a DNS name. `status` alone usually decides it; queue depth confirms, since a parked command was waiting on connection setup while one written to a `ready` socket that never answered means the socket died unreported. Host kind rules DNS resolution in or out, which no server-side telemetry can see. Attaches it to the usage-reservation slot operations — the first Redis calls a queued workflow makes, so an unusable connection surfaces there first. Connect and ready now log elapsed-since-construction, making the wait before a connection becomes usable directly measurable; today it is spent inside a command's deadline, where it reads as a command timeout rather than as connection latency. Purely additive. Redis call arguments are unchanged, the wrapper rethrows the original error object, and `describeRedisConnection` never throws — it runs inside catch blocks where a throw would replace the real failure. All three have tests that fail if the behavior is removed. Only non-sensitive facts are derived from REDIS_URL, which carries the AUTH token and is never logged.
1 parent 603f1c2 commit 9334a4d

5 files changed

Lines changed: 353 additions & 16 deletions

File tree

apps/sim/lib/billing/calculations/usage-reservation.test.ts

Lines changed: 7 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -339,6 +339,13 @@ describe('usage-reservation', () => {
339339
})
340340

341341
describe('refreshExecutionSlotExpiry', () => {
342+
it('rethrows the original error object rather than the diagnostic wrapper', async () => {
343+
const original = Object.assign(new Error('Command timed out'), { code: 'ETIMEDOUT' })
344+
getMock.mockRejectedValueOnce(original)
345+
346+
await expect(refreshExecutionSlotExpiry('exec-1', Date.now() + 60_000)).rejects.toBe(original)
347+
})
348+
342349
it('refreshes only the locally owned slot and matching pointer', async () => {
343350
evalMock.mockResolvedValueOnce(1).mockResolvedValueOnce(1)
344351
await reserveExecutionSlot(memberParams)

apps/sim/lib/billing/calculations/usage-reservation.ts

Lines changed: 50 additions & 14 deletions
Original file line numberDiff line numberDiff line change
@@ -9,7 +9,7 @@ import {
99
type ReservationDenialReason,
1010
} from '@/lib/core/admission/transient-failure'
1111
import { isBillingEnabled, isHosted } from '@/lib/core/config/env-flags'
12-
import { getRedisClient } from '@/lib/core/config/redis'
12+
import { describeRedisConnection, getRedisClient } from '@/lib/core/config/redis'
1313
import { getExecutionReservationTtlMs } from '@/lib/core/execution-limits'
1414

1515
const logger = createLogger('UsageReservation')
@@ -425,6 +425,34 @@ export type ReserveExecutionSlotResult =
425425
reason: ReservationDenialReason
426426
}
427427

428+
/**
429+
* Records connection state alongside a failed slot operation.
430+
*
431+
* These three functions are the first Redis calls a queued workflow makes, so
432+
* when the connection is not usable they are where it surfaces — as an
433+
* `Error: Command timed out` carrying no app frame and no indication of which
434+
* of several very different causes applied. Pairing the failure with
435+
* `describeRedisConnection()` is what makes the next occurrence self-diagnosing
436+
* instead of another inference from timing alone.
437+
*/
438+
async function withReservationDiagnostics<T>(
439+
operation: string,
440+
reservationId: string,
441+
run: () => Promise<T>
442+
): Promise<T> {
443+
try {
444+
return await run()
445+
} catch (error) {
446+
logger.error('Usage reservation Redis operation failed', {
447+
operation,
448+
reservationId,
449+
error: toError(error).message,
450+
redis: describeRedisConnection(),
451+
})
452+
throw error
453+
}
454+
}
455+
428456
/**
429457
* Atomic admission reservation that closes the usage-cap check-then-use race.
430458
*
@@ -510,6 +538,7 @@ export async function reserveExecutionSlot(
510538
error: toError(error).message,
511539
entityKey,
512540
reservationId,
541+
redis: describeRedisConnection(),
513542
})
514543
throw new UsageReservationUnavailableError(
515544
'Usage admission is temporarily unavailable. Please retry.',
@@ -622,7 +651,11 @@ export async function refreshExecutionSlotExpiry(
622651

623652
const boundedReservationId = requireBoundedIdentifier(reservationId, 'reservation id')
624653
const pointerKey = `${POINTER_KEY_PREFIX}${boundedReservationId}`
625-
const descriptorValue = await redis.get(pointerKey)
654+
const descriptorValue = await withReservationDiagnostics(
655+
'refresh:read-pointer',
656+
boundedReservationId,
657+
() => redis.get(pointerKey)
658+
)
626659
if (!descriptorValue) return false
627660
const descriptor = parseDescriptor(descriptorValue)
628661
if (!descriptor) {
@@ -633,22 +666,25 @@ export async function refreshExecutionSlotExpiry(
633666
const expiryAt = Math.min(expiresAt, now + getExecutionReservationTtlMs())
634667
const keys = buildLocalKeys(descriptor, boundedReservationId)
635668
const keyArgs = localKeyArguments(keys)
636-
const localResult = await redis.eval(
637-
REFRESH_LOCAL_SCRIPT,
638-
keyArgs.length,
639-
...keyArgs,
669+
const localResult = await withReservationDiagnostics(
670+
'refresh:extend-local',
640671
boundedReservationId,
641-
descriptorValue,
642-
expiryAt.toString()
672+
() =>
673+
redis.eval(
674+
REFRESH_LOCAL_SCRIPT,
675+
keyArgs.length,
676+
...keyArgs,
677+
boundedReservationId,
678+
descriptorValue,
679+
expiryAt.toString()
680+
)
643681
)
644682
if (localResult !== 1) return false
645683

646-
const pointerResult = await redis.eval(
647-
REFRESH_POINTER_SCRIPT,
648-
1,
649-
pointerKey,
650-
descriptorValue,
651-
expiryAt.toString()
684+
const pointerResult = await withReservationDiagnostics(
685+
'refresh:extend-pointer',
686+
boundedReservationId,
687+
() => redis.eval(REFRESH_POINTER_SCRIPT, 1, pointerKey, descriptorValue, expiryAt.toString())
652688
)
653689
if (pointerResult !== 1) {
654690
throw new UsageReservationUnavailableError(

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

Lines changed: 118 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -27,6 +27,7 @@ vi.mock('ioredis', () => ({
2727
import {
2828
acquireLock,
2929
closeRedisConnection,
30+
describeRedisConnection,
3031
extendLock,
3132
getRedisClient,
3233
onRedisReconnect,
@@ -38,6 +39,8 @@ describe('redis config', () => {
3839
vi.clearAllMocks()
3940
vi.useFakeTimers()
4041
resetForTesting()
42+
mockRedisInstance.status = 'ready'
43+
Object.assign(mockRedisInstance, { offlineQueue: undefined })
4144
mockEnv.REDIS_URL = 'redis://localhost:6379'
4245
mockEnv.REDIS_TLS_SERVERNAME = undefined
4346
MockRedisConstructor.mockImplementation(
@@ -159,6 +162,121 @@ describe('redis config', () => {
159162
})
160163
})
161164

165+
describe('describeRedisConnection', () => {
166+
it('reports no client before one is built', () => {
167+
const d = describeRedisConnection()
168+
169+
expect(d.status).toBe('no-client')
170+
expect(d.clientAgeMs).toBeNull()
171+
expect(d.readyAgeMs).toBeNull()
172+
expect(d.connects).toBe(0)
173+
})
174+
175+
it('separates a connecting client from a ready one', () => {
176+
// The constructor copies the mock's fields, so each state has to be set
177+
// before the client is built.
178+
mockRedisInstance.status = 'connecting'
179+
getRedisClient()
180+
expect(describeRedisConnection().status).toBe('connecting')
181+
182+
resetForTesting()
183+
mockRedisInstance.status = 'ready'
184+
getRedisClient()
185+
expect(describeRedisConnection().status).toBe('ready')
186+
})
187+
188+
it('surfaces the offline queue depth that proves a command was waiting on the connection', () => {
189+
Object.assign(mockRedisInstance, { offlineQueue: { length: 3 } })
190+
getRedisClient()
191+
192+
expect(describeRedisConnection().queuedCommands).toBe(3)
193+
})
194+
195+
it('counts lifecycle events so a reconnect is distinguishable from a first connect', async () => {
196+
getRedisClient()
197+
const handler = (event: string) =>
198+
mockRedisInstance.on.mock.calls.find((c: unknown[]) => c[0] === event)?.[1] as
199+
| (() => void)
200+
| undefined
201+
202+
handler('connect')?.()
203+
handler('ready')?.()
204+
const afterConnect = describeRedisConnection()
205+
expect(afterConnect.connects).toBe(1)
206+
expect(afterConnect.readyAgeMs).not.toBeNull()
207+
208+
const errorHandler = mockRedisInstance.on.mock.calls.find(
209+
(c: unknown[]) => c[0] === 'error'
210+
)?.[1] as ((e: Error) => void) | undefined
211+
errorHandler?.(new Error('ECONNRESET'))
212+
213+
const afterError = describeRedisConnection()
214+
expect(afterError.errors).toBe(1)
215+
expect(afterError.lastErrorMessage).toBe('ECONNRESET')
216+
})
217+
218+
it('classifies the host without ever exposing the URL that carries the auth token', () => {
219+
mockEnv.REDIS_URL = 'rediss://10.0.0.5:6379'
220+
mockEnv.REDIS_TLS_SERVERNAME = 'primary.example.cache.amazonaws.com'
221+
222+
const d = describeRedisConnection()
223+
224+
expect(d).toMatchObject({ hostKind: 'ip', tls: true, sniOverride: true })
225+
expect(JSON.stringify(d)).not.toContain('10.0.0.5')
226+
})
227+
228+
it('never throws, so it cannot mask the error it is describing', () => {
229+
// Called from catch blocks: a throw here would replace the real failure.
230+
mockEnv.REDIS_URL = undefined
231+
expect(() => describeRedisConnection()).not.toThrow()
232+
233+
mockEnv.REDIS_URL = 'not a url'
234+
expect(() => describeRedisConnection()).not.toThrow()
235+
expect(describeRedisConnection().hostKind).toBe('unknown')
236+
237+
// rediss:// to a bare IP with no REDIS_TLS_SERVERNAME makes the URL
238+
// resolution throw; the snapshot must still come back.
239+
mockEnv.REDIS_URL = 'rediss://10.0.0.5:6379'
240+
mockEnv.REDIS_TLS_SERVERNAME = undefined
241+
expect(() => describeRedisConnection()).not.toThrow()
242+
})
243+
244+
it('does not date a connection that has been discarded', async () => {
245+
mockRedisInstance.status = 'ready'
246+
getRedisClient()
247+
expect(describeRedisConnection().clientAgeMs).not.toBeNull()
248+
249+
// Two consecutive PING failures drop the cached client.
250+
mockRedisInstance.ping.mockRejectedValue(new Error('ETIMEDOUT'))
251+
await vi.advanceTimersByTimeAsync(15_000)
252+
await vi.advanceTimersByTimeAsync(15_000)
253+
254+
const d = describeRedisConnection()
255+
expect(d.status).toBe('no-client')
256+
expect(d.clientAgeMs).toBeNull()
257+
expect(d.readyAgeMs).toBeNull()
258+
expect(d.msSinceLastPingOk).toBeNull()
259+
// Lifecycle counters stay cumulative for the process.
260+
expect(d.reconnects).toBeGreaterThanOrEqual(0)
261+
})
262+
263+
it('classifies an IPv6 literal as an IP, not a DNS name', () => {
264+
mockEnv.REDIS_URL = 'rediss://[2600:1f18::1]:6379'
265+
266+
const d = describeRedisConnection()
267+
268+
expect(d.hostKind).toBe('ip')
269+
// Mirrors resolveRedisTlsOptions, which applies the override for IPv4 only.
270+
expect(d.sniOverride).toBe(false)
271+
})
272+
273+
it('reports a DNS host so resolution latency can be ruled in or out', () => {
274+
mockEnv.REDIS_URL = 'rediss://primary.example.cache.amazonaws.com:6379'
275+
276+
expect(describeRedisConnection()).toMatchObject({ hostKind: 'dns', sniOverride: false })
277+
})
278+
})
279+
162280
describe('closeRedisConnection', () => {
163281
it('should clear the PING interval', async () => {
164282
getRedisClient()

0 commit comments

Comments
 (0)