diff --git a/apps/sim/lib/core/config/redis.test.ts b/apps/sim/lib/core/config/redis.test.ts index 61c33523c49..6a03ef905cd 100644 --- a/apps/sim/lib/core/config/redis.test.ts +++ b/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: (_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', () => { diff --git a/apps/sim/lib/core/config/redis.ts b/apps/sim/lib/core/config/redis.ts index 2926ea901db..b604664b24d 100644 --- a/apps/sim/lib/core/config/redis.ts +++ b/apps/sim/lib/core/config/redis.ts @@ -153,8 +153,17 @@ 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() @@ -162,13 +171,13 @@ export function describeRedisConnection(): RedisConnectionDiagnostics { 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