improvement(redis): pair lock acquire failures with connection state (#7669)

* improvement(redis): pair lock acquire failures with connection state

A lock acquire is often a process's first Redis call, so an unusable
connection surfaces there as `Error: Command timed out` — a rejection
carrying only ioredis timer frames, no app frame, and nothing to separate a
handshake still in flight from a socket that died silently. `status` is what
separates them, so log it alongside the failure.

Read before the reclaim, which awaits and would otherwise report the state it
left behind rather than the one that failed.

* fix(redis): describe the client that ran the failed command

A command can outlive the client that issued it: the PING health check drops
`state.client` after consecutive failures, which is the same unhealthy stretch
in which that command is timing out. Reading the global in the failure path
then described the replacement — reporting `no-client` or a fresh `connecting`
for a failure belonging to the connection before it, misclassifying the very
timeout the diagnostic exists to explain.

Take the client as an argument, and withhold the ages when `state` no longer
holds it rather than dating a connection its timestamps never measured.

Author: waleedlatif1

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

@@ -1,12 +1,20 @@
 import { createMockRedis } from '@sim/testing'
 import { afterEach, beforeEach, describe, expect, it, vi } from 'vitest'
 
-const { mockEnv, MockRedisConstructor } = vi.hoisted(() => ({
+const { mockEnv, MockRedisConstructor, mockLogger } = vi.hoisted(() => ({
   mockEnv: {
     REDIS_URL: 'redis://localhost:6379' as string | undefined,
     REDIS_TLS_SERVERNAME: undefined as string | undefined,
   },
   MockRedisConstructor: vi.fn(),
+  mockLogger: {
+    info: vi.fn(),
+    warn: vi.fn(),
+    error: vi.fn(),
+    debug: vi.fn(),
+    trace: vi.fn(),
+    fatal: vi.fn(),
+  },
 }))
 
 const mockRedisInstance = createMockRedis()
@@ -20,6 +28,15 @@ MockRedisConstructor.mockImplementation(
 
 vi.unmock('@/lib/core/config/redis')
 vi.mock('@/lib/core/config/env', () => ({ env: mockEnv }))
+/** Overrides the global mock, whose `createLogger` returns a fresh spy per call,
+ *  so assertions can reach the instance this module captured at import. */
+vi.mock('@sim/logger', () => ({
+  createLogger: () => mockLogger,
+  logger: mockLogger,
+  runWithRequestContext: <T>(_ctx: unknown, fn: () => T): T => fn(),
+  getRequestContext: () => undefined,
+  setRequestTraceId: () => {},
+}))
 vi.mock('ioredis', () => ({
   default: MockRedisConstructor,
 }))
@@ -383,6 +400,76 @@ describe('redis config', () => {
       expect(await acquireLock(lockKey, value, ttlSeconds)).toBe(true)
       expect(mockRedisInstance.set).not.toHaveBeenCalled()
     })
+
+    it('pairs the failure with connection state so the cause is not left to timing', async () => {
+      // The bare rejection carries only ioredis timer frames, so without this
+      // there is nothing to separate a handshake still in flight from a socket
+      // that died silently.
+      mockRedisInstance.status = 'connecting'
+      mockRedisInstance.set.mockRejectedValueOnce(new Error('Command timed out'))
+
+      await expect(acquireLock(lockKey, value, ttlSeconds)).rejects.toThrow('Command timed out')
+      expect(mockLogger.error).toHaveBeenCalledWith(
+        'Redis lock acquire failed',
+        expect.objectContaining({
+          lockKey,
+          error: 'Command timed out',
+          redis: expect.objectContaining({ status: 'connecting' }),
+        })
+      )
+    })
+
+    it('reads connection state before the reclaim, which resolves against a live socket', async () => {
+      // The reclaim awaits, so a connection that completes inside that window
+      // would leave a diagnostic read after it reporting `ready` — hiding the
+      // very handshake that failed.
+      mockRedisInstance.status = 'connecting'
+      mockRedisInstance.set.mockRejectedValueOnce(new Error('Command timed out'))
+      // Mutates the constructed client, not the shared instance it was copied from.
+      mockRedisInstance.eval.mockImplementationOnce(async () => {
+        Object.assign(getRedisClient() ?? {}, { status: 'ready' })
+        return 1
+      })
+
+      await expect(
+        acquireLock(lockKey, value, ttlSeconds, { reclaimOnFailure: true })
+      ).rejects.toThrow('Command timed out')
+      expect(mockLogger.error).toHaveBeenCalledWith(
+        'Redis lock acquire failed',
+        expect.objectContaining({ redis: expect.objectContaining({ status: 'connecting' }) })
+      )
+    })
+
+    it('describes the client that ran the command, not one that replaced it mid-flight', async () => {
+      // The PING check drops `state.client` after consecutive failures — the same
+      // unhealthy stretch in which the command is timing out. Reading the global
+      // then would report the replacement and misclassify the very failure this
+      // diagnostic exists to explain.
+      mockRedisInstance.status = 'connecting'
+      mockRedisInstance.set.mockImplementationOnce(async () => {
+        resetForTesting()
+        throw new Error('Command timed out')
+      })
+
+      await expect(acquireLock(lockKey, value, ttlSeconds)).rejects.toThrow('Command timed out')
+      expect(mockLogger.error).toHaveBeenCalledWith(
+        'Redis lock acquire failed',
+        expect.objectContaining({
+          // Timestamps belong to whatever `state` holds now, so they are withheld
+          // rather than dated against a connection they never measured.
+          redis: expect.objectContaining({ status: 'connecting', clientAgeMs: null }),
+        })
+      )
+    })
+
+    it('stays quiet on the taken and contended paths, which poll routes run constantly', async () => {
+      mockRedisInstance.set.mockResolvedValueOnce('OK')
+      await acquireLock(lockKey, value, ttlSeconds)
+      mockRedisInstance.set.mockResolvedValueOnce(null)
+      await acquireLock(lockKey, value, ttlSeconds)
+
+      expect(mockLogger.error).not.toHaveBeenCalled()
+    })
   })
 
   describe('capability validation', () => {

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

@@ -153,22 +153,31 @@ function describeRedisUrl(
  *
  * Derives only non-sensitive facts from REDIS_URL — never the URL itself, which
  * carries the AUTH token.
+ *
+ * Pass the client whose command is being diagnosed when it may not be the one
+ * `state` still holds. A command can outlive its client — the PING health check
+ * drops `state.client` after consecutive failures, which is the same unhealthy
+ * stretch in which that command is timing out — and reading the global then
+ * describes the replacement, reporting `no-client` or a fresh `connecting` for a
+ * failure that belongs to the connection before it.
  */
-export function describeRedisConnection(): RedisConnectionDiagnostics {
+export function describeRedisConnection(
+  client: Redis | null = state.client
+): RedisConnectionDiagnostics {
   let url: string | null = null
   try {
     url = getConfiguredRedisUrl()
   } catch {
     url = null
   }
 
-  const client = state.client
-
   // Ages describe the client currently held. A discarded client leaves its
   // timestamps behind until the next `getRedisClient()` rebuilds them, and
-  // reporting those against `no-client` would date a connection that no longer
-  // exists. The counters below are deliberately cumulative for the process.
-  const ageOf = (at: number | null) => (client === null ? null : elapsedSince(at))
+  // reporting those against `no-client` — or against a client that has since
+  // been replaced — would date a connection these timestamps never measured.
+  // The counters below are deliberately cumulative for the process.
+  const timestampsDescribeClient = client !== null && client === state.client
+  const ageOf = (at: number | null) => (timestampsDescribeClient ? elapsedSince(at) : null)
 
   return {
     status: client?.status ?? 'no-client',
@@ -406,6 +415,20 @@ export async function acquireLock(
     const result = await redis.set(lockKey, value, 'EX', expirySeconds, 'NX')
     return result === 'OK'
   } catch (error) {
+    /**
+     * Read the connection state before the reclaim below, which awaits and so
+     * would report the state it left behind rather than the one that failed.
+     * A lock acquire is often a run's first Redis call, so it is where an
+     * unusable connection surfaces — as an `Error: Command timed out` carrying
+     * only ioredis timer frames, no app frame, and no way to tell a handshake
+     * still in flight from a socket that died silently. `status` separates
+     * them, which is what makes the next occurrence self-diagnosing.
+     */
+    logger.error('Redis lock acquire failed', {
+      lockKey,
+      error: toError(error).message,
+      redis: describeRedisConnection(redis),
+    })
     // Best effort, and the same compare-and-delete `releaseLock` runs on the
     // success path: it deletes only while `value` still owns the key. If Redis
     // is still unreachable the TTL stays the backstop, which is the behavior