#debugging#post-mortem#observability#reliability#backend

Post-Mortem Analysis: Taming Cascading Failures, Memory Leaks, and Connection Starvation

"On October 24 at 14:22 UTC, our primary transaction processing cluster experienced a cascading failure across three availability zones. Service degradation esc"

By huud
0 views
~6 min read
Post-Mortem Analysis: Taming Cascading Failures, Memory Leaks, and Connection Starvation

On October 24 at 14:22 UTC, our primary transaction processing cluster experienced a cascading failure across three availability zones. Service degradation escalated from an initial p99 latency regression (45ms12,500ms45\text{ms} \to 12,500\text{ms}) to total transaction processing failure, producing an aggregate error rate of 84.2%84.2\% across a 43-minute window.

This post-mortem details the compounding technical triggers behind the incident: a closure-retained buffer memory leak in the application layer, connection pool starvation governed by queueing dynamics, and distributed relational database deadlocks under high concurrency.


1. System Architecture and Incident Timeline

The payment orchestration tier uses an Envoy edge proxy routing traffic to an auto-scaled fleet of Node.js/TypeScript microservices. Services interface with a PostgreSQL 15 primary-replica cluster via PgBouncer for transaction-level connection pooling.

scss
[ Ingress / Envoy ]
        │
        ▼
[ Node.js Worker Fleet ] ──(PgBouncer)──▶ [ PostgreSQL Primary ]
        │                                         │
  (Memory Leak)                            (Row Deadlocks)
        ▼                                         ▼
[ Heap Blowout / OOM ]                 [ Lock Graph Contention ]
  • 14:22 UTC: Marketing campaign triggered a 3.2×3.2\times traffic surge to 12,500 req/sec12,500 \text{ req/sec}.
  • 14:28 UTC: Node.js worker RSS memory exceeded the 85%85\% container limit (1.7GB/2.0GB1.7\text{GB}/2.0\text{GB}). V8 garbage collection (GC) stop-the-world pauses escalated to 1,800ms1,800\text{ms}.
  • 14:31 UTC: Kubernetes liveness probes failed; container runtimes issued OOMKilled signals. Remaining pods absorbed traffic, saturating the PgBouncer pool.
  • 14:34 UTC: Database lock-acquisition timeouts surged. PostgreSQL engine reported circular wait deadlocks on account ledger rows.
  • 14:41 UTC: Ingress circuit breakers tripped; automated load shedding dropped non-critical traffic.
  • 15:05 UTC: Patched container image deployed; stale database locks cleared; nominal cluster operation restored.

2. Root Cause 1: Closure-Retained Buffer Heap Leak

Post-incident heap snapshot diffing confirmed rapid allocation growth in (closure) and ArrayBuffer retainers. A telemetry interceptor captured incoming payload buffers to compute SHA-256 idempotency hashes. The logger registered completion handlers on the request emitter without handling aborted connections.

typescript
// Faulty Implementation: Closure retaining full request payload
export function attachAuditLogger(req: Request, emitter: EventEmitter) {
  const payloadBuffer = req.rawBody; // Large ArrayBuffer (up to 2MB)
  
  const onComplete = () => {
    // Retains lexical scope enclosing `payloadBuffer`
    metricsClient.record({
      path: req.path,
      checksum: crypto.createHash("sha256").update(payloadBuffer).digest("hex"),
    });
  };

  // Bug: onComplete was never detached if the client aborted the connection
  emitter.on("finish", onComplete);
}

When client timeouts or proxy drops terminated connections prematurely, the finish event never emitted. The onComplete reference remained in the emitter registry, keeping the parent scope and its allocated ArrayBuffer rooted in the V8 garbage collector heap.

Remediation

We refactored the interceptor to digest the checksum synchronously, release references to the raw payload, and listen for both finish and close lifecycle events:

typescript
// Corrected Implementation: Explicit lifecycle cleanup and direct extraction
export function attachAuditLogger(req: Request, emitter: EventEmitter) {
  const checksum = crypto.createHash("sha256").update(req.rawBody).digest("hex");
  const path = req.path;

  const cleanup = () => {
    emitter.removeListener("finish", onComplete);
    emitter.removeListener("close", cleanup);
  };

  const onComplete = () => {
    cleanup();
    metricsClient.record({ path, checksum });
  };

  emitter.once("finish", onComplete);
  emitter.once("close", cleanup);
}

3. Root Cause 2: Connection Pool Exhaustion and Latency Cascades

As V8 garbage collection cycles consumed host CPU, request processing latencies increased. Connection pool demand scaled proportionally according to Little's Law:

L=λWL = \lambda \cdot W

Where:

  • LL is the mean concurrent connections required,
  • λ\lambda is arrival rate (12,500 req/sec12,500 \text{ req/sec}),
  • WW is mean transaction latency.

When GC latency inflation shifted WW from 35ms35\text{ms} to 850ms850\text{ms}, required concurrent database connections LL surpassed system limits:

Lsurge=12,5000.85=10,625 connectionsL_{\text{surge}} = 12,500 \cdot 0.85 = 10,625 \text{ connections}

PgBouncer was provisioned with a hard ceiling of 2,0002,000 server connections. Once saturated, client worker connection queues grew unbounded. When connection acquisition exceeded configured client-side timeouts, worker threads failed with 503 Service Unavailable.

less
Incoming Requests ──▶ [ Thread Pool Wait Queue ] ──(Timeout: 5000ms)──▶ [ Connection Pool (Saturated) ][ Client Aborts ] ──▶ Orphaned Queries Running on DB

Remediation

We implemented strict connection pool sizing, dropped acquisition timeouts to sub-second thresholds to fail fast, and enabled aggressive connection recycling:

json
{
  "pool": {
    "max": 20,
    "min": 5,
    "acquireTimeoutMillis": 1500,
    "createTimeoutMillis": 1500,
    "idleTimeoutMillis": 10000,
    "reapIntervalMillis": 1000,
    "createRetryIntervalMillis": 100
  }
}

4. Root Cause 3: Lock-Ordering Database Deadlocks

Surviving application workers processed balance transfer retries concurrently. The balance update queries acquired row-level ExclusiveLock primitives in arbitrary order:

sql
-- Transaction A (Transfer User 101 -> User 202)
BEGIN;
UPDATE accounts SET balance = balance - 100 WHERE id = 101; -- Locks row 101 (ExclusiveLock)
UPDATE accounts SET balance = balance + 100 WHERE id = 202; -- Waits for row 202
COMMIT;

-- Transaction B (Transfer User 202 -> User 101)
BEGIN;
UPDATE accounts SET balance = balance - 50 WHERE id = 202;  -- Locks row 202 (ExclusiveLock)
UPDATE accounts SET balance = balance + 50 WHERE id = 101;  -- Waits for row 101 -> DEADLOCK
COMMIT;

When Transaction A and Transaction B ran concurrently, each held a row lock while waiting for the other's resource. PostgreSQL resolved these conflicts only after deadlock_timeout (1,000ms1,000\text{ms}) elapsed by terminating one transaction, amplifying client retry storms.

Resolution: Deterministic Lock Acquisition

We enforced deterministic primary-key sorting across all multi-row mutations using SELECT ... FOR UPDATE before applying balance mutations:

sql
-- Deterministic ordered locking
BEGIN;
SELECT id FROM accounts 
WHERE id IN (101, 202) 
ORDER BY id ASC 
FOR UPDATE;

-- Safe to execute mutations without deadlock risk
UPDATE accounts SET balance = balance - 100 WHERE id = 101;
UPDATE accounts SET balance = balance + 100 WHERE id = 202;
COMMIT;

5. High-Signal, Zero-Noise Observability Architecture

During the incident, engineers received over 400 alerts triggered by symptomatic thresholds (CPU utilization, pod restarts, query times), obscuring root-cause identification.

We replaced static alerts with multi-window, multi-burn-rate alerts tracking our Service Level Objectives (SLOs).

Error Budget Burn-Rate Alerting

Alert evaluation now measures consumption of the 30-day rolling Error Budget (EBEB):

Burn Rate (B)=1SLI1SLO\text{Burn Rate } (B) = \frac{1 - \text{SLI}}{1 - \text{SLO}}

Alerts trigger only when error rates deplete budget thresholds across short and long time windows concurrently:

yaml
# Prometheus AlertManager Rule: Multi-Window Multi-Burn-Rate
- alert: HighErrorBudgetBurnRate
  expr: |
    (
      sum(rate(http_requests_total{status=~"5.."}[1h])) 
      / 
      sum(rate(http_requests_total[1h])) 
      > (1 - 0.999) * 14.4
    )
    and
    (
      sum(rate(http_requests_total{status=~"5.."}[5m])) 
      / 
      sum(rate(http_requests_total[5m])) 
      > (1 - 0.999) * 14.4
    )
  for: 2m
  labels:
    severity: page
    tier: platform
  annotations:
    summary: "High error budget consumption (14.4x burn rate over 1h and 5m)"
    runbook_url: "https://wiki.internal/ops/runbooks/inc-8492-remediation"

Architectural Safeguards

  1. Deterministic Resource Ordering: All multi-row transactions sort locking keys numerically to eliminate lock graph cycles.
  2. Context-Bounded Lifecycles: Event listeners bind to connection lifecycle terminations (close, abort) to ensure immediate garbage collection.
  3. Fail-Fast Pooling: Database connection acquisition uses bounded queues and 1,500ms1,500\text{ms} timeouts to reject excess load instead of queueing.
  4. Burn-Rate Paging: On-call paging triggers strictly on validated SLO budget burn rates rather than localized resource utilization.

About the Author

huud

huud

@huud

About →

Systems architect and software engineer building high-performance distributed platforms.