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()`, a snapshot of 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. Those are 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.

Derives only non-sensitive facts from REDIS_URL; the URL carries the AUTH token
and is never logged.

Author: waleedlatif1

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

@@ -9,7 +9,7 @@ import {
   type ReservationDenialReason,
 } from '@/lib/core/admission/transient-failure'
 import { isBillingEnabled, isHosted } from '@/lib/core/config/env-flags'
-import { getRedisClient } from '@/lib/core/config/redis'
+import { describeRedisConnection, getRedisClient } from '@/lib/core/config/redis'
 import { getExecutionReservationTtlMs } from '@/lib/core/execution-limits'
 
 const logger = createLogger('UsageReservation')
@@ -433,6 +433,34 @@ export type ReserveExecutionSlotResult =
  * proven. A newly-created local reservation is rolled back if pointer
  * registration fails; TTL is only the bounded crash fallback.
  */
+/**
+ * Records connection state alongside a failed slot operation.
+ *
+ * These three functions are the first Redis calls a queued workflow makes, so
+ * when the connection is not usable they are where it surfaces — as an
+ * `Error: Command timed out` carrying no app frame and no indication of which
+ * of several very different causes applied. Pairing the failure with
+ * `describeRedisConnection()` is what makes the next occurrence self-diagnosing
+ * instead of another inference from timing alone.
+ */
+async function withReservationDiagnostics<T>(
+  operation: string,
+  reservationId: string,
+  run: () => Promise<T>
+): Promise<T> {
+  try {
+    return await run()
+  } catch (error) {
+    logger.error('Usage reservation Redis operation failed', {
+      operation,
+      reservationId,
+      error: toError(error).message,
+      redis: describeRedisConnection(),
+    })
+    throw error
+  }
+}
+
 export async function reserveExecutionSlot(
   params: ReserveExecutionSlotParams
 ): Promise<ReserveExecutionSlotResult> {
@@ -510,6 +538,7 @@ export async function reserveExecutionSlot(
       error: toError(error).message,
       entityKey,
       reservationId,
+      redis: describeRedisConnection(),
     })
     throw new UsageReservationUnavailableError(
       'Usage admission is temporarily unavailable. Please retry.',
@@ -622,7 +651,11 @@ export async function refreshExecutionSlotExpiry(
 
   const boundedReservationId = requireBoundedIdentifier(reservationId, 'reservation id')
   const pointerKey = `${POINTER_KEY_PREFIX}${boundedReservationId}`
-  const descriptorValue = await redis.get(pointerKey)
+  const descriptorValue = await withReservationDiagnostics(
+    'refresh:read-pointer',
+    boundedReservationId,
+    () => redis.get(pointerKey)
+  )
   if (!descriptorValue) return false
   const descriptor = parseDescriptor(descriptorValue)
   if (!descriptor) {
@@ -633,22 +666,25 @@ export async function refreshExecutionSlotExpiry(
   const expiryAt = Math.min(expiresAt, now + getExecutionReservationTtlMs())
   const keys = buildLocalKeys(descriptor, boundedReservationId)
   const keyArgs = localKeyArguments(keys)
-  const localResult = await redis.eval(
-    REFRESH_LOCAL_SCRIPT,
-    keyArgs.length,
-    ...keyArgs,
+  const localResult = await withReservationDiagnostics(
+    'refresh:extend-local',
     boundedReservationId,
-    descriptorValue,
-    expiryAt.toString()
+    () =>
+      redis.eval(
+        REFRESH_LOCAL_SCRIPT,
+        keyArgs.length,
+        ...keyArgs,
+        boundedReservationId,
+        descriptorValue,
+        expiryAt.toString()
+      )
   )
   if (localResult !== 1) return false
 
-  const pointerResult = await redis.eval(
-    REFRESH_POINTER_SCRIPT,
-    1,
-    pointerKey,
-    descriptorValue,
-    expiryAt.toString()
+  const pointerResult = await withReservationDiagnostics(
+    'refresh:extend-pointer',
+    boundedReservationId,
+    () => redis.eval(REFRESH_POINTER_SCRIPT, 1, pointerKey, descriptorValue, expiryAt.toString())
   )
   if (pointerResult !== 1) {
     throw new UsageReservationUnavailableError(

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

@@ -27,6 +27,7 @@ vi.mock('ioredis', () => ({
 import {
   acquireLock,
   closeRedisConnection,
+  describeRedisConnection,
   extendLock,
   getRedisClient,
   onRedisReconnect,
@@ -38,6 +39,8 @@ describe('redis config', () => {
     vi.clearAllMocks()
     vi.useFakeTimers()
     resetForTesting()
+    mockRedisInstance.status = 'ready'
+    Object.assign(mockRedisInstance, { offlineQueue: undefined })
     mockEnv.REDIS_URL = 'redis://localhost:6379'
     mockEnv.REDIS_TLS_SERVERNAME = undefined
     MockRedisConstructor.mockImplementation(
@@ -159,6 +162,76 @@ describe('redis config', () => {
     })
   })
 
+  describe('describeRedisConnection', () => {
+    it('reports no client before one is built', () => {
+      const d = describeRedisConnection()
+
+      expect(d.status).toBe('no-client')
+      expect(d.clientAgeMs).toBeNull()
+      expect(d.readyAgeMs).toBeNull()
+      expect(d.connects).toBe(0)
+    })
+
+    it('separates a connecting client from a ready one', () => {
+      // The constructor copies the mock's fields, so each state has to be set
+      // before the client is built.
+      mockRedisInstance.status = 'connecting'
+      getRedisClient()
+      expect(describeRedisConnection().status).toBe('connecting')
+
+      resetForTesting()
+      mockRedisInstance.status = 'ready'
+      getRedisClient()
+      expect(describeRedisConnection().status).toBe('ready')
+    })
+
+    it('surfaces the offline queue depth that proves a command was waiting on the connection', () => {
+      Object.assign(mockRedisInstance, { offlineQueue: { length: 3 } })
+      getRedisClient()
+
+      expect(describeRedisConnection().queuedCommands).toBe(3)
+    })
+
+    it('counts lifecycle events so a reconnect is distinguishable from a first connect', async () => {
+      getRedisClient()
+      const handler = (event: string) =>
+        mockRedisInstance.on.mock.calls.find((c: unknown[]) => c[0] === event)?.[1] as
+          | (() => void)
+          | undefined
+
+      handler('connect')?.()
+      handler('ready')?.()
+      const afterConnect = describeRedisConnection()
+      expect(afterConnect.connects).toBe(1)
+      expect(afterConnect.readyAgeMs).not.toBeNull()
+
+      const errorHandler = mockRedisInstance.on.mock.calls.find(
+        (c: unknown[]) => c[0] === 'error'
+      )?.[1] as ((e: Error) => void) | undefined
+      errorHandler?.(new Error('ECONNRESET'))
+
+      const afterError = describeRedisConnection()
+      expect(afterError.errors).toBe(1)
+      expect(afterError.lastErrorMessage).toBe('ECONNRESET')
+    })
+
+    it('classifies the host without ever exposing the URL that carries the auth token', () => {
+      mockEnv.REDIS_URL = 'rediss://10.0.0.5:6379'
+      mockEnv.REDIS_TLS_SERVERNAME = 'primary.example.cache.amazonaws.com'
+
+      const d = describeRedisConnection()
+
+      expect(d).toMatchObject({ hostKind: 'ip', tls: true, sniOverride: true })
+      expect(JSON.stringify(d)).not.toContain('10.0.0.5')
+    })
+
+    it('reports a DNS host so resolution latency can be ruled in or out', () => {
+      mockEnv.REDIS_URL = 'rediss://primary.example.cache.amazonaws.com:6379'
+
+      expect(describeRedisConnection()).toMatchObject({ hostKind: 'dns', sniOverride: false })
+    })
+  })
+
   describe('closeRedisConnection', () => {
     it('should clear the PING interval', async () => {
       getRedisClient()

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

@@ -59,6 +59,13 @@ interface RedisState {
   pingInterval: NodeJS.Timeout | null
   pingInFlight: boolean
   reconnectListeners: Array<() => void>
+  clientCreatedAt: number | null
+  lastReadyAt: number | null
+  lastPingOkAt: number | null
+  connects: number
+  reconnects: number
+  errors: number
+  lastErrorMessage: string | null
 }
 
 const g = globalThis as typeof globalThis & { _redisState?: RedisState }
@@ -69,10 +76,104 @@ if (!g._redisState) {
     pingInterval: null,
     pingInFlight: false,
     reconnectListeners: [],
+    clientCreatedAt: null,
+    lastReadyAt: null,
+    lastPingOkAt: null,
+    connects: 0,
+    reconnects: 0,
+    errors: 0,
+    lastErrorMessage: null,
   }
 }
 const state = g._redisState
 
+/**
+ * A command that never gets a reply fails identically whichever of three states
+ * the client was in — still establishing its connection, reconnecting with the
+ * command parked in the offline queue, or holding a socket that has silently
+ * died. ioredis reports all three the same way: an `Error: Command timed out`
+ * whose stack contains only its own timer frames, with no app frame naming the
+ * call and no lifecycle event to say which happened.
+ *
+ * This snapshot is what separates them. `status` alone is usually decisive
+ * (`connecting`/`reconnecting`/`ready`), and `queuedCommands` confirms it: a
+ * command parked in the offline queue was waiting on connection setup, while a
+ * command written to a `ready` socket that never answered means the socket is
+ * dead in a way nothing reported.
+ */
+export interface RedisConnectionDiagnostics {
+  status: string
+  /** Age of the client object — distinguishes one created for this unit of work from an inherited one. */
+  clientAgeMs: number | null
+  /** Time since the connection last reached `ready`. */
+  readyAgeMs: number | null
+  /** Time since the last PING round-trip actually completed; the health check runs every 15s. */
+  msSinceLastPingOk: number | null
+  /** Depth of ioredis's offline queue — non-zero means commands are waiting on the connection. */
+  queuedCommands: number | null
+  connects: number
+  reconnects: number
+  errors: number
+  lastErrorMessage: string | null
+  /** Whether REDIS_URL targets an IP literal or a DNS name. Names DNS resolution in or out. */
+  hostKind: 'ip' | 'dns' | 'unknown'
+  tls: boolean
+  /** Whether the TLS SNI override is in play (set when the host is a bare IP). */
+  sniOverride: boolean
+}
+
+/** ioredis keeps no public accessor for its offline queue, but its depth is the tiebreaker above. */
+interface OfflineQueueView {
+  offlineQueue?: { length?: number }
+}
+
+function describeRedisUrl(
+  url: string | null
+): Pick<RedisConnectionDiagnostics, 'hostKind' | 'tls' | 'sniOverride'> {
+  if (!url) return { hostKind: 'unknown', tls: false, sniOverride: false }
+  try {
+    const parsed = new URL(url)
+    const isIp = /^\d{1,3}(\.\d{1,3}){3}$/.test(parsed.hostname)
+    const tls = parsed.protocol === 'rediss:'
+    return { hostKind: isIp ? 'ip' : 'dns', tls, sniOverride: tls && isIp }
+  } catch {
+    return { hostKind: 'unknown', tls: false, sniOverride: false }
+  }
+}
+
+/**
+ * Connection state at a point in time, safe to attach to any log line.
+ *
+ * Derives only non-sensitive facts from REDIS_URL — never the URL itself, which
+ * carries the AUTH token.
+ */
+export function describeRedisConnection(): RedisConnectionDiagnostics {
+  const now = Date.now()
+  let url: string | null = null
+  try {
+    url = getConfiguredRedisUrl()
+  } catch {
+    url = null
+  }
+
+  const client = state.client
+  // double-cast-allowed: ioredis omits offlineQueue from its public type, and its depth is what separates a command waiting on connection setup from one written to a live socket
+  const queued = (client as unknown as OfflineQueueView | null)?.offlineQueue?.length
+
+  return {
+    status: client?.status ?? 'no-client',
+    clientAgeMs: state.clientCreatedAt === null ? null : now - state.clientCreatedAt,
+    readyAgeMs: state.lastReadyAt === null ? null : now - state.lastReadyAt,
+    msSinceLastPingOk: state.lastPingOkAt === null ? null : now - state.lastPingOkAt,
+    queuedCommands: typeof queued === 'number' ? queued : null,
+    connects: state.connects,
+    reconnects: state.reconnects,
+    errors: state.errors,
+    lastErrorMessage: state.lastErrorMessage,
+    ...describeRedisUrl(url),
+  }
+}
+
 const PING_INTERVAL_MS = 15_000
 const MAX_PING_FAILURES = 2
 
@@ -103,6 +204,7 @@ function startPingHealthCheck(redis: Redis): void {
     try {
       await redis.ping()
       state.pingFailures = 0
+      state.lastPingOkAt = Date.now()
     } catch (error) {
       state.pingFailures++
       logger.warn('Redis PING failed', {
@@ -172,6 +274,7 @@ export function getRedisClient(): Redis | null {
         const base = Math.min(1000 * 2 ** (times - 1), 10000)
         const jitter = randomFloat() * base * 0.3
         const delay = Math.round(base + jitter)
+        state.reconnects++
         logger.warn('Redis reconnecting', { attempt: times, nextRetryMs: delay })
         return delay
       },
@@ -182,9 +285,30 @@ export function getRedisClient(): Redis | null {
       },
     })
 
-    state.client.on('connect', () => logger.info('Redis connected'))
-    state.client.on('ready', () => logger.info('Redis ready'))
+    state.clientCreatedAt = Date.now()
+    state.lastReadyAt = null
+    state.lastPingOkAt = null
+
+    state.client.on('connect', () => {
+      state.connects++
+      // Elapsed since construction, because the wait before a connection becomes
+      // usable is the number this path has never been able to produce: it is
+      // spent inside a command's deadline, where it surfaces as a command
+      // timeout rather than as connection latency.
+      logger.info('Redis connected', {
+        elapsedMs: state.clientCreatedAt === null ? null : Date.now() - state.clientCreatedAt,
+        attempt: state.connects,
+      })
+    })
+    state.client.on('ready', () => {
+      state.lastReadyAt = Date.now()
+      logger.info('Redis ready', {
+        elapsedMs: state.clientCreatedAt === null ? null : Date.now() - state.clientCreatedAt,
+      })
+    })
     state.client.on('error', (err: Error) => {
+      state.errors++
+      state.lastErrorMessage = err.message
       logger.error('Redis error', { error: err.message, code: (err as any).code })
     })
     state.client.on('close', () => logger.warn('Redis connection closed'))
@@ -355,4 +479,11 @@ export function resetForTesting(): void {
   state.pingFailures = 0
   state.pingInFlight = false
   state.reconnectListeners.length = 0
+  state.clientCreatedAt = null
+  state.lastReadyAt = null
+  state.lastPingOkAt = null
+  state.connects = 0
+  state.reconnects = 0
+  state.errors = 0
+  state.lastErrorMessage = null
 }