From b7c0067744ce41d3aa1165e60b62a1971d0ef433 Mon Sep 17 00:00:00 2001 From: overthelex Date: Fri, 10 Jul 2026 00:50:59 +0300 Subject: [PATCH] fix(redis): tear down half-open client socket + alert on stuck Redis MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Prod incident 2026-07: the backend's node-redis client went half-open during a blue-green cutover. node-redis kept it "connected" but never tore the dead socket down, so it never reconnected and EVERY cache / rate-limit / chat-search op hit the 2500ms CacheAdapter timeout indefinitely (6+ min) until a manual restart. keepAlive + pingInterval (already present) were not enough on their own. Fix + observability: - redis-client: add socket.socketTimeout (60s) so a read-inactivity window closes a dead socket and triggers reconnectStrategy; PONG traffic from pingInterval (lowered 30s->20s) keeps a healthy link well under the timeout. Wire ready/reconnecting/end events to a connection-state hook. - cache-adapter: setMetricsCallback fired on every timed-out/errored op. - metrics: backend_redis_client_up gauge + redis_command_errors_total counter (named distinctly from redis_exporter's server-side redis_up). - http-server: wire the gauge (via state hook) and the error counter. - alert-rules: BackendRedisClientDown (gauge==0 2m) and BackendRedisCommandErrors (rate>0.2/s 3m) — the latter is the signal that catches a stuck client while it still reports "up". Co-Authored-By: Claude Opus 4.8 (1M context) --- deployment/prometheus/rules/alert-rules.yml | 18 ++++++++ mcp_backend/src/http-server.ts | 9 +++- .../adapters/__tests__/cache-adapter.test.ts | 16 +++++++ .../infrastructure/adapters/cache-adapter.ts | 16 +++++++ mcp_backend/src/services/metrics-service.ts | 23 ++++++++++ mcp_backend/src/utils/redis-client.ts | 44 ++++++++++++++++--- 6 files changed, 119 insertions(+), 7 deletions(-) diff --git a/deployment/prometheus/rules/alert-rules.yml b/deployment/prometheus/rules/alert-rules.yml index 033c84dbd..18e034e03 100644 --- a/deployment/prometheus/rules/alert-rules.yml +++ b/deployment/prometheus/rules/alert-rules.yml @@ -37,6 +37,24 @@ groups: summary: "Redis evicting keys" description: "Redis is evicting keys due to memory pressure. Rate: {{ $value }}/s" + - alert: BackendRedisClientDown + expr: backend_redis_client_up == 0 + for: 2m + labels: + severity: critical + annotations: + summary: "Backend Redis client disconnected on {{ $labels.job }}" + description: "The backend's own Redis client has been down/reconnecting for 2+ minutes. Rate limiting, chat-search caching and auth caching are degraded. If it does not self-heal, restart the backend." + + - alert: BackendRedisCommandErrors + expr: sum by (job) (rate(redis_command_errors_total[2m])) > 0.2 + for: 3m + labels: + severity: critical + annotations: + summary: "Backend Redis commands failing on {{ $labels.job }}" + description: "Backend Redis cache ops are timing out/erroring at {{ $value | printf \"%.2f\" }}/s for 3+ minutes. This is the signature of a stuck/half-open client (the socketTimeout auto-reconnect should clear it; if not, restart the backend). Prod incident 2026-07." + - alert: PgCacheHitLow expr: (pg_stat_database_blks_hit + pg_stat_database_blks_read) > 0 and pg_stat_database_blks_hit / (pg_stat_database_blks_hit + pg_stat_database_blks_read) < 0.95 for: 10m diff --git a/mcp_backend/src/http-server.ts b/mcp_backend/src/http-server.ts index 0dfb27014..8e94e2c5b 100644 --- a/mcp_backend/src/http-server.ts +++ b/mcp_backend/src/http-server.ts @@ -41,7 +41,7 @@ import { createTeamService } from './services/team-service.js'; import { createTestEmailRoute } from './routes/test-email-route.js'; import passport from 'passport'; import { createApiKeyRouter } from './routes/api-key-routes.js'; -import { getRedisClient } from './utils/redis-client.js'; +import { getRedisClient, setRedisStateHook } from './utils/redis-client.js'; import { getOpenAIManager } from '@secondlayer/shared'; import { CacheAdapter } from './infrastructure/adapters/cache-adapter.js'; import { LLMAdapter } from './infrastructure/adapters/llm-adapter.js'; @@ -1017,7 +1017,14 @@ class HTTPMCPServer { // Initialize Redis cache for services (optional) const redis = await getRedisClient(); if (redis) { + // Surface Redis client health to Prometheus: the gauge tracks connection state (reconnect + // events) and the counter tracks failed cache ops — together they alert on a stuck client + // even when the socket still reports "connected" (prod incident 2026-07). + const metrics = this.app_.metricsService; + setRedisStateHook((up) => metrics.backendRedisClientUp.set(up ? 1 : 0)); + metrics.backendRedisClientUp.set(1); // singleton already connected by this point const cache = new CacheAdapter(redis); + cache.setMetricsCallback((operation) => metrics.redisCommandErrors.inc({ operation })); this.services.legislationTools.setRedisClient(cache); this.services.zoAdapter.setCachePort(cache); this.services.zoPracticeAdapter.setCachePort(cache); diff --git a/mcp_backend/src/infrastructure/adapters/__tests__/cache-adapter.test.ts b/mcp_backend/src/infrastructure/adapters/__tests__/cache-adapter.test.ts index 717019c6f..623324ecf 100644 --- a/mcp_backend/src/infrastructure/adapters/__tests__/cache-adapter.test.ts +++ b/mcp_backend/src/infrastructure/adapters/__tests__/cache-adapter.test.ts @@ -51,4 +51,20 @@ describe('CacheAdapter — fast-fail on a hung Redis client', () => { const adapter = new CacheAdapter(makeClient({ ping: jest.fn(() => new Promise(() => {})) })); await expect(adapter.ping()).resolves.toBe(false); }); + + it('fires the metrics callback with the operation label on a failed op', async () => { + const adapter = new CacheAdapter(makeClient({ get: jest.fn(() => new Promise(() => {})) })); + const onError = jest.fn(); + adapter.setMetricsCallback(onError); + await expect(adapter.get('k')).rejects.toThrow(/timed out/i); + expect(onError).toHaveBeenCalledWith('GET'); + }); + + it('does not fire the metrics callback on a successful op', async () => { + const adapter = new CacheAdapter(makeClient()); + const onError = jest.fn(); + adapter.setMetricsCallback(onError); + await adapter.get('k'); + expect(onError).not.toHaveBeenCalled(); + }); }); diff --git a/mcp_backend/src/infrastructure/adapters/cache-adapter.ts b/mcp_backend/src/infrastructure/adapters/cache-adapter.ts index d237e150d..fd003b6b9 100644 --- a/mcp_backend/src/infrastructure/adapters/cache-adapter.ts +++ b/mcp_backend/src/infrastructure/adapters/cache-adapter.ts @@ -22,13 +22,26 @@ type RedisClient = ReturnType; // failing fast on a genuinely dead socket (which keepAlive/pingInterval also detect ~30s). const REDIS_OP_TIMEOUT_MS = Number(process.env.REDIS_OP_TIMEOUT_MS || 2500); +/** Emitted on every failed cache op (timeout or connection error) so the caller can meter it. */ +type CacheErrorCallback = (operation: string) => void; + export class CacheAdapter implements ICachePort { private client: RedisClient; + private onError: CacheErrorCallback | null = null; constructor(client: RedisClient) { this.client = client; } + /** + * Register a metrics hook fired whenever a cache op times out or errors. Wired to a Prometheus + * counter from the composition root so a stuck client (sustained op errors) is alertable — + * this is the signal that catches a half-open socket even while the client still reports "up". + */ + setMetricsCallback(cb: CacheErrorCallback): void { + this.onError = cb; + } + private async withTimeout(op: Promise, label: string): Promise { let timer: ReturnType | undefined; try { @@ -41,6 +54,9 @@ export class CacheAdapter implements ICachePort { ); }), ]); + } catch (err) { + this.onError?.(label); + throw err; } finally { if (timer) clearTimeout(timer); } diff --git a/mcp_backend/src/services/metrics-service.ts b/mcp_backend/src/services/metrics-service.ts index 14b278a71..41091789d 100644 --- a/mcp_backend/src/services/metrics-service.ts +++ b/mcp_backend/src/services/metrics-service.ts @@ -59,6 +59,10 @@ export class MetricsService { readonly chatCapHits: Counter; readonly chatCapHitRequests: Counter; + // Backend Redis client health + readonly backendRedisClientUp: Gauge; + readonly redisCommandErrors: Counter; + constructor() { this.registry = new Registry(); @@ -261,11 +265,30 @@ export class MetricsService { registers: [this.registry], }); + // --- Backend Redis client health --- + // backendRedisClientUp: named distinctly from the redis_exporter's `redis_up` (server-side) + // — this tracks the backend's OWN client connection. redisCommandErrors: rate of failed cache + // ops; a sustained rate flags a stuck/half-open client even while the gauge still reads 1. + this.backendRedisClientUp = new Gauge({ + name: 'backend_redis_client_up', + help: 'Backend Redis client connection state (1=ready, 0=down/reconnecting)', + registers: [this.registry], + }); + this.redisCommandErrors = new Counter({ + name: 'redis_command_errors_total', + help: 'Backend Redis cache command failures (timeout or connection error) by operation', + labelNames: ['operation'] as const, // GET|SET|SETEX|DEL|INCR|PING + registers: [this.registry], + }); + // Pre-initialize external API counters so Prometheus always has these series // (counters don't appear until first .inc() otherwise) for (const svc of ['openai', 'anthropic', 'rada', 'diia']) { this.externalApiCallsTotal.inc({ service: svc, status: 'success' }, 0); } + // Pre-initialize so the alert expression has a series before the first error/connect. + this.redisCommandErrors.inc({ operation: 'GET' }, 0); + this.backendRedisClientUp.set(0); // Pre-initialize cap-hit counters so the "share of truncated requests" // ratio resolves to 0 (not "no data") before the first cap fires. for (const kind of ['repeat', 'total']) { diff --git a/mcp_backend/src/utils/redis-client.ts b/mcp_backend/src/utils/redis-client.ts index 73b65c0e5..e0a975ca6 100644 --- a/mcp_backend/src/utils/redis-client.ts +++ b/mcp_backend/src/utils/redis-client.ts @@ -3,6 +3,17 @@ import { logger } from './logger'; let redisClient: ReturnType | null = null; +/** + * Optional hook to surface the client's live connection state (1=ready, 0=down). + * Wired to a Prometheus gauge from the composition root so we can alert on a + * disconnected / reconnecting backend Redis client. No-op until set. + */ +type RedisStateHook = (up: boolean) => void; +let stateHook: RedisStateHook | null = null; +export function setRedisStateHook(hook: RedisStateHook): void { + stateHook = hook; +} + /** * Получает singleton экземпляр Redis клиента. * Автоматически подключается при первом вызове. @@ -14,18 +25,26 @@ export async function getRedisClient(): Promise try { const redisUrl = process.env.REDIS_URL || 'redis://localhost:6379'; - // keepAlive surfaces a dead TCP connection at the socket layer; pingInterval probes idle - // connections from the app so a silently-dropped socket is detected and reconnected before - // it stalls a request (see CacheAdapter — these timeouts are the second line of defense). + // Half-open-socket protection. keepAlive/pingInterval alone are NOT enough: a silently + // dropped connection (e.g. mid blue-green cutover) can leave node-redis "connected" with a + // dead socket. Without a read-inactivity timeout node-redis never tears it down, so it never + // reconnects and EVERY command hangs until the CacheAdapter 2500ms timeout — indefinitely + // (prod incident 2026-07: all cache/rate-limit ops timed out for 6+ min until a manual + // restart). socketTimeout closes the socket when no bytes arrive within the window; because + // pingInterval keeps PONG traffic flowing on a healthy link (~every 20s), it only fires on a + // genuinely dead socket → reconnectStrategy re-establishes a working connection automatically. + // socketTimeout MUST be comfortably larger than pingInterval so a couple of missed PONGs on a + // healthy but momentarily busy link don't cause a spurious teardown. redisClient = createClient({ url: redisUrl, socket: { keepAlive: true, keepAliveInitialDelay: 30_000, connectTimeout: 10_000, + socketTimeout: 60_000, reconnectStrategy: (retries) => Math.min(retries * 100, 3_000), }, - pingInterval: 30_000, + pingInterval: 20_000, }); redisClient.on('error', (err) => { @@ -36,11 +55,24 @@ export async function getRedisClient(): Promise logger.info('[Redis] Connected successfully'); }); - redisClient.on('disconnect', () => { - logger.warn('[Redis] Disconnected'); + redisClient.on('ready', () => { + stateHook?.(true); + }); + + // node-redis emits 'reconnecting' when the socket dropped (incl. socketTimeout teardown) and + // 'end' when the client gives up. Both mean the client can't serve commands right now. + redisClient.on('reconnecting', () => { + logger.warn('[Redis] Reconnecting'); + stateHook?.(false); + }); + + redisClient.on('end', () => { + logger.warn('[Redis] Connection ended'); + stateHook?.(false); }); await redisClient.connect(); + stateHook?.(true); logger.info('[Redis] Client initialized'); return redisClient;