From b79bd8370dc45e69a753d162a3c5e32c76d8f448 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Marc-Andr=C3=A9=20Bombeck?= Date: Tue, 20 Oct 2026 03:42:26 +0200 Subject: [PATCH] fix(heap): report again at 95 % and leave a report on an out-of-memory exit The pressure report re-armed only after the heap fell under 70 % and half an hour passed, so a heap that climbed to its limit soon after an 85 % report died with only that older report on record. A 95 % tier now writes the same report at once, whatever the cooldown, and re-arms under 85 %. The image sets NODE_OPTIONS so Node writes its diagnostic report to stderr when the heap runs out, with environment variables and network interfaces excluded. The heap-diagnostics and scaling docs say how to keep the flags when overriding NODE_OPTIONS. Heap figures share one megabytes helper with the support report. --- Dockerfile | 9 +++++ docs/ops/heap-diagnostics.md | 12 +++++- docs/self-hosting/scaling.md | 6 ++- .../__tests__/heap-monitor.test.ts | 37 +++++++++++++++++++ src/lib/observability/heap-monitor.ts | 37 +++++++++++++++---- src/lib/support/heap-limit.ts | 7 +++- src/lib/support/report.ts | 7 ++-- 7 files changed, 101 insertions(+), 14 deletions(-) diff --git a/Dockerfile b/Dockerfile index a06be1896..2630d356c 100644 --- a/Dockerfile +++ b/Dockerfile @@ -76,6 +76,15 @@ ENV NODE_ENV=production ENV NEXT_TELEMETRY_DISABLED=1 ENV TZ=Europe/Berlin +# When the heap runs out, Node writes a diagnostic report (the JavaScript +# and native stacks, heap spaces, libuv handles) to stderr, where +# `docker compose logs` and Loki keep it; without it the log holds one +# line. Environment variables and network interfaces are left out, so no +# key, password or address from the environment reaches the log. An +# operator who sets NODE_OPTIONS replaces this value and should carry these +# flags over (docs/ops/heap-diagnostics.md). +ENV NODE_OPTIONS="--report-on-fatalerror --report-filename=stderr --report-exclude-env --report-exclude-network" + # v1.4.43 B11 — forward NEXT_PUBLIC_APP_VERSION from the builder stage # into the runner so /api/version reads the build-arg value instead of # the package.json fallback. The variable is keyed to the CI tag ref diff --git a/docs/ops/heap-diagnostics.md b/docs/ops/heap-diagnostics.md index f7a1f02c5..87b12052f 100644 --- a/docs/ops/heap-diagnostics.md +++ b/docs/ops/heap-diagnostics.md @@ -7,7 +7,7 @@ A Node process that reaches its heap limit stops with `JavaScript heap out of me Two background wide events, no configuration needed: - `runtime.heap.sampled` (info), every five minutes, and every minute while the heap is at or above 70 % of its limit. It goes to stdout and Loki but not to Admin > App logs, so it cannot push other events out of that page's 500-entry buffer. It carries `heap_used_mb`, `heap_total_mb`, `heap_limit_mb`, `heap_used_ratio`, `old_space_mb`, `rss_mb`, `external_mb`, `array_buffers_mb`, `active_requests`, `active_jobs`, `in_flight_dropped` and `uptime_s`. -- `runtime.heap.pressure` (warn), the first time the heap reaches 85 % of its limit. Besides the figures above it lists the 50 oldest requests and jobs in flight (`in_flight_oldest`: kind, method, route, age in seconds, whether it was a server action) and the routes most of them share (`in_flight_by_route`). Routes are reduced to their shape: no query string, secret path segments replaced by `[REDACTED]`, ids by `:id`, anything unusual by `:x`. It writes again only after the heap has dropped below 70 % and thirty minutes have passed. +- `runtime.heap.pressure` (warn), the first time the heap reaches 85 % of its limit. Besides the figures above it lists the 50 oldest requests and jobs in flight (`in_flight_oldest`: kind, method, route, age in seconds, whether it was a server action) and the routes most of them share (`in_flight_by_route`). Routes are reduced to their shape: no query string, secret path segments replaced by `[REDACTED]`, ids by `:id`, anything unusual by `:x`. It writes again only after the heap has dropped below 70 % and thirty minutes have passed. One exception: when the heap reaches 95 %, the same report is written again at once, with `pressure_ratio: 0.95`, whatever the cooldown; that tier re-arms as soon as the heap is back under 85 %. A heap that climbs to its limit shortly after an 85 % report therefore still leaves a report naming the work that pushed it over. The heap is read every five seconds, a single call that takes microseconds. Tracking requests costs one map insert and one delete per request. @@ -17,6 +17,16 @@ To find the last lines before a crash: docker compose logs app --since 2h | grep '"runtime.heap.' ``` +## The report Node writes when the heap runs out + +The image sets `NODE_OPTIONS="--report-on-fatalerror --report-filename=stderr --report-exclude-env --report-exclude-network"`. When the process runs out of heap, Node writes a diagnostic report, about 10 KB of JSON with `"trigger": "OOMError"`, to stderr just before it exits: the JavaScript stack at the failed allocation, the native stack, the heap spaces and the open handles. It lands in the container log beside the `runtime.heap.*` lines: + +```sh +docker compose logs app --since 2h | grep -A400 '"trigger": "OOMError"' +``` + +The two exclude flags keep environment variables (keys, passwords, the database URL) and network interfaces out of the report. If you set `NODE_OPTIONS` yourself, for example to raise `--max-old-space-size`, your value replaces the image's; add the four flags to it to keep the report. + ## Optional heap snapshot A snapshot shows what the heap is made of, which the events above cannot. Turn it on only while you are chasing a specific crash: diff --git a/docs/self-hosting/scaling.md b/docs/self-hosting/scaling.md index c39d30b5a..77759eeeb 100644 --- a/docs/self-hosting/scaling.md +++ b/docs/self-hosting/scaling.md @@ -79,9 +79,13 @@ Raise the limit on the container that runs the worker and re-upload: services: app: environment: - NODE_OPTIONS: --max-old-space-size=1024 + NODE_OPTIONS: --max-old-space-size=1024 --report-on-fatalerror --report-filename=stderr --report-exclude-env --report-exclude-network ``` +Your `NODE_OPTIONS` replaces the image's, so carry the four `--report-*` +flags over: they make an out-of-memory exit leave a diagnostic report in +the container log (see `docs/ops/heap-diagnostics.md`). + An import interrupted by a container restart or an out-of-memory kill does not stay stuck: the worker reconciles non-terminal import jobs at boot and every 15 minutes, flipping orphaned rows to `failed` diff --git a/src/lib/observability/__tests__/heap-monitor.test.ts b/src/lib/observability/__tests__/heap-monitor.test.ts index 4d99544dd..9e686a52d 100644 --- a/src/lib/observability/__tests__/heap-monitor.test.ts +++ b/src/lib/observability/__tests__/heap-monitor.test.ts @@ -23,7 +23,9 @@ import { walkSourceFiles } from "@/__tests__/helpers/source-files"; import { HEAP_CHECK_INTERVAL_MS, + HEAP_CRITICAL_RATIO, HEAP_PRESSURE_COOLDOWN_MS, + HEAP_PRESSURE_RATIO, HEAP_PRESSURE_LIST_MAX, HEAP_SAMPLE_INTERVAL_ELEVATED_MS, HEAP_SAMPLE_INTERVAL_MS, @@ -175,6 +177,41 @@ describe("heap pressure report", () => { expect(h.named(HEAP_TASK_NAMES.pressure)).toHaveLength(2); }); + it("reports again at 95 % inside the cooldown, once per climb", () => { + const h = harness(); + h.state.used = 900; + h.run(60_000); + // Ten minutes later, well inside the cooldown, the heap nears its limit. + h.state.used = 800; + h.run(10 * 60_000); + h.state.used = 960; + h.run(60_000); + const pressure = h.named(HEAP_TASK_NAMES.pressure); + expect(pressure.map((p) => p.meta.pressure_ratio)).toEqual([ + HEAP_PRESSURE_RATIO, + HEAP_CRITICAL_RATIO, + ]); + expect(pressure[1].meta).toHaveProperty("in_flight_oldest"); + + // Hovering at 95 % writes nothing more; back under 85 % re-arms it. + h.run(5 * 60_000); + expect(h.named(HEAP_TASK_NAMES.pressure)).toHaveLength(2); + h.state.used = 840; + h.run(HEAP_CHECK_INTERVAL_MS); + h.state.used = 970; + h.run(HEAP_CHECK_INTERVAL_MS); + expect(h.named(HEAP_TASK_NAMES.pressure)).toHaveLength(3); + }); + + it("writes one report at the tier a sudden jump reaches", () => { + const h = harness(); + h.state.used = 990; + h.run(60_000); + const pressure = h.named(HEAP_TASK_NAMES.pressure); + expect(pressure).toHaveLength(1); + expect(pressure[0].meta.pressure_ratio).toBe(HEAP_CRITICAL_RATIO); + }); + it("writes no snapshot unless opted in, and at most one when it is", () => { const off = harness(); off.state.used = 900; diff --git a/src/lib/observability/heap-monitor.ts b/src/lib/observability/heap-monitor.ts index e05d4eb94..362a9f7ae 100644 --- a/src/lib/observability/heap-monitor.ts +++ b/src/lib/observability/heap-monitor.ts @@ -9,6 +9,7 @@ import { import { envFlag, envOr } from "@/lib/env"; import { WideEventBuilder } from "@/lib/logging/event-builder"; import { emitIfSampled } from "@/lib/logging/transports"; +import { megabytes } from "@/lib/support/heap-limit"; import { inFlightRegistry, type InFlightRegistry } from "./in-flight"; @@ -32,7 +33,11 @@ import { inFlightRegistry, type InFlightRegistry } from "./in-flight"; * flight and the routes most of them share (see `in-flight.ts`). It * re-arms only after the heap has fallen back under 70 % AND thirty minutes * have passed, so a heap hovering at the line writes one report, not one - * every check. + * every check. A second tier at 95 % writes the same report with no + * cooldown at all, and re-arms as soon as the heap is back under 85 %: + * a heap that climbs to its limit within the half hour after an 85 % + * report would otherwise die with only that older report on record, the + * requests that pushed it over missing from it. * - `runtime.heap.snapshot`, at `warn`, only with the opt-in below: where * the snapshot was written, or that writing it failed. * @@ -63,6 +68,7 @@ export const HEAP_SAMPLE_INTERVAL_MS = 5 * 60_000; export const HEAP_SAMPLE_INTERVAL_ELEVATED_MS = 60_000; export const HEAP_ELEVATED_RATIO = 0.7; export const HEAP_PRESSURE_RATIO = 0.85; +export const HEAP_CRITICAL_RATIO = 0.95; export const HEAP_PRESSURE_COOLDOWN_MS = 30 * 60_000; export const HEAP_PRESSURE_LIST_MAX = 50; @@ -101,10 +107,6 @@ export interface HeapMonitorDeps { writeSnapshot: () => SnapshotOutcome; } -function megabytes(bytes: number): number { - return Math.round(bytes / 1024 / 1024); -} - function defaultReadHeap(): { used: number; limit: number } { const stats = getHeapStatistics(); return { used: stats.used_heap_size, limit: stats.heap_size_limit }; @@ -205,6 +207,7 @@ export function writeDiagnosticHeapSnapshot(): SnapshotOutcome { export class HeapMonitor { private lastSampleAt: number | null = null; private pressureArmed = true; + private criticalArmed = true; private lastPressureAt: number | null = null; private snapshotTaken = false; @@ -225,11 +228,29 @@ export class HeapMonitor { this.pressureArmed = true; } + if (!this.criticalArmed && ratio < HEAP_PRESSURE_RATIO) { + this.criticalArmed = true; + } + if (this.pressureArmed && ratio >= HEAP_PRESSURE_RATIO) { this.pressureArmed = false; this.lastPressureAt = at; this.lastSampleAt = at; - this.reportPressure(at); + // A heap that jumps straight past 95 % gets one report, at the tier + // it reached. + const critical = ratio >= HEAP_CRITICAL_RATIO; + if (critical) this.criticalArmed = false; + this.reportPressure( + at, + critical ? HEAP_CRITICAL_RATIO : HEAP_PRESSURE_RATIO, + ); + return; + } + + if (this.criticalArmed && ratio >= HEAP_CRITICAL_RATIO) { + this.criticalArmed = false; + this.lastSampleAt = at; + this.reportPressure(at, HEAP_CRITICAL_RATIO); return; } @@ -245,7 +266,7 @@ export class HeapMonitor { } } - private reportPressure(at: number): void { + private reportPressure(at: number, tier: number): void { const { registry, emit, readFigures } = this.deps; const inFlight = registry.report(at, HEAP_PRESSURE_LIST_MAX); const willSnapshot = this.deps.snapshotEnabled && !this.snapshotTaken; @@ -253,7 +274,7 @@ export class HeapMonitor { // process over, the report is already on stdout. emit(HEAP_TASK_NAMES.pressure, "warn", { ...readFigures(), - pressure_ratio: HEAP_PRESSURE_RATIO, + pressure_ratio: tier, in_flight_oldest: inFlight.oldest, in_flight_by_route: inFlight.by_route, snapshot: willSnapshot ? "pending" : "disabled", diff --git a/src/lib/support/heap-limit.ts b/src/lib/support/heap-limit.ts index e11c9656e..80f0dcfc6 100644 --- a/src/lib/support/heap-limit.ts +++ b/src/lib/support/heap-limit.ts @@ -14,9 +14,14 @@ import { getHeapStatistics } from "node:v8"; /** Below this, the heap is flagged. Between the 1g (524) and 1536m (792) heaps. */ export const LOW_HEAP_LIMIT_MB = 700; +/** Bytes as whole megabytes (MiB), the unit every heap figure is shown in. */ +export function megabytes(bytes: number): number { + return Math.round(bytes / 1024 / 1024); +} + /** V8's heap limit for this process, in megabytes. */ export function heapLimitMb(): number { - return Math.round(getHeapStatistics().heap_size_limit / 1024 / 1024); + return megabytes(getHeapStatistics().heap_size_limit); } export function isHeapLimitLow(limitMb: number): boolean { diff --git a/src/lib/support/report.ts b/src/lib/support/report.ts index 15ac11743..1160b0327 100644 --- a/src/lib/support/report.ts +++ b/src/lib/support/report.ts @@ -25,6 +25,7 @@ import { heapLimitMb, isHeapLimitLow, lowHeapLimitAdvice, + megabytes, } from "@/lib/support/heap-limit"; import { shouldEmitSecureCookie } from "@/lib/auth/secure-cookie"; import { isOidcConfigured, isOidcOnly } from "@/lib/auth/oidc"; @@ -692,8 +693,8 @@ function or(value: string | number | null | undefined, fallback = "unknown") { : String(value); } -function megabytes(bytes: number | null): string { - return bytes === null ? "unknown" : `${Math.round(bytes / 1024 / 1024)} MB`; +function sizeLine(bytes: number | null): string { + return bytes === null ? "unknown" : `${megabytes(bytes)} MB`; } function runLine(run: QueueRunFact | null): string { @@ -741,7 +742,7 @@ export function renderSupportReport(facts: SupportReportFacts): string { section("Database"); row("PostgreSQL", facts.database.version); row("Server time zone", facts.database.timezone); - row("Size", megabytes(facts.database.sizeBytes)); + row("Size", sizeLine(facts.database.sizeBytes)); row( "Last migration", facts.database.lastMigration