mirror of
https://github.com/MBombeck/HealthLog.git
synced 2026-11-09 04:50:59 +00:00
fix(observability): keep heap samples out of the admin log ring and harden the snapshot directory
runtime.heap.sampled is written every minute while the heap is above 70 % of its limit, which turned the 500-entry ring behind the admin log page over in hours and pushed out the events an operator opens it for. emitEvent takes a skipMemoryRing option; the sample sets it and still reaches stdout and Loki, while the pressure and snapshot lines go everywhere as before. The snapshot directory was /tmp/healthlog-heap-<pid>, a predictable name (pid 1 in most containers) that mkdirSync accepted when it already existed or was a symlink. It now comes from mkdtempSync and is checked with lstat to be a real directory owned by the process user and closed to others before the snapshot is written.
This commit is contained in:
1 parent
16024397c8
commit
d08e2b4e6d
4 files changed
+134
-27
No files matched your search
@@ -6,7 +6,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 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.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.
|
||||
|
||||
The heap is read every five seconds, a single call that takes microseconds. Tracking requests costs one map insert and one delete per request.
|
||||
@@ -26,13 +26,13 @@ HEALTHLOG_HEAP_SNAPSHOT=1
|
||||
HEALTHLOG_DIAG_DIR=/tmp # default; a path inside the container
|
||||
```
|
||||
|
||||
With the switch set, the first `runtime.heap.pressure` event is followed by one `v8.writeHeapSnapshot()` and a `runtime.heap.snapshot` event naming the file. At most one snapshot is written per process. The file goes into a `healthlog-heap-<pid>` directory with mode 0700 and is itself mode 0600.
|
||||
With the switch set, the first `runtime.heap.pressure` event is followed by one `v8.writeHeapSnapshot()` and a `runtime.heap.snapshot` event naming the file. At most one snapshot is written per process. The file goes into a new directory with a random name, `healthlog-heap-XXXXXX`, created with mode 0700 and checked to be a real directory owned by the app's user before anything is written; the file itself is mode 0600. The event names the full path.
|
||||
|
||||
**A heap snapshot contains everything the process held in memory: decrypted health records, session data, API tokens and the encryption keys.** Treat it like a database dump with the keys attached.
|
||||
|
||||
- HealthLog never uploads or logs a snapshot. Only its path appears in the log.
|
||||
- Copy it off the container only to a machine you trust, for example `docker compose cp app:/tmp/healthlog-heap-<pid> ./`, and open it in Chrome DevTools (Memory tab, Load).
|
||||
- Delete it as soon as you are done, inside the container and wherever you copied it: `docker compose exec app rm -rf /tmp/healthlog-heap-<pid>`. A file under `/tmp` in the container also disappears when the container is recreated, not when it restarts.
|
||||
- Copy it off the container only to a machine you trust, for example `docker compose cp app:/tmp/healthlog-heap-XXXXXX ./`, and open it in Chrome DevTools (Memory tab, Load).
|
||||
- Delete it as soon as you are done, inside the container and wherever you copied it: `docker compose exec app rm -rf /tmp/healthlog-heap-XXXXXX`. A file under `/tmp` in the container also disappears when the container is recreated, not when it restarts.
|
||||
- Do not attach a snapshot to an issue or send it to anyone.
|
||||
|
||||
Writing a snapshot blocks the process for several seconds and needs memory roughly the size of the heap on top of what is in use. Near the container's memory limit that can end the process sooner than the heap would have. The pressure report is written before the snapshot starts, so it is on record either way. Turn the switch off again when you have what you need.
|
||||
@@ -239,28 +239,43 @@ export function _resetLokiTransportForTests(): void {
|
||||
* Event emittieren falls Sampling-Kriterien erfuellt.
|
||||
* Zentraler Einstiegspunkt — entfernt Stack Traces falls konfiguriert.
|
||||
*/
|
||||
export function emitIfSampled(event: WideEvent): void {
|
||||
export function emitIfSampled(
|
||||
event: WideEvent,
|
||||
options: EmitOptions = {},
|
||||
): void {
|
||||
const config = getLoggingConfig();
|
||||
if (!config.includeStackTrace && event.error?.stack) {
|
||||
delete event.error.stack;
|
||||
}
|
||||
if (shouldEmit(event)) {
|
||||
emitEvent(event);
|
||||
emitEvent(event, options);
|
||||
}
|
||||
}
|
||||
|
||||
export interface EmitOptions {
|
||||
/**
|
||||
* Keep the event out of the in-memory ring `/admin/app-logs` reads, while
|
||||
* it still reaches stdout and Loki. For periodic telemetry only: a line
|
||||
* written every minute would otherwise evict the events an operator opens
|
||||
* that page to find. Never set it on a warn or error event.
|
||||
*/
|
||||
skipMemoryRing?: boolean;
|
||||
}
|
||||
|
||||
/** Zentraler Emit: stdout + optional Loki-Buffer + in-memory ring buffer */
|
||||
export function emitEvent(event: WideEvent): void {
|
||||
export function emitEvent(event: WideEvent, options: EmitOptions = {}): void {
|
||||
emitToStdout(event);
|
||||
|
||||
// Push into the per-process in-memory ring buffer so admins can drill
|
||||
// into the most recent ~500 wide events from the `/admin/app-logs`
|
||||
// page without standing up a Loki stack. See `in-memory-buffer.ts`.
|
||||
// Wrapped in try/catch so a buffer bug never poisons the request.
|
||||
try {
|
||||
appendLogEvent(event);
|
||||
} catch {
|
||||
/* logging must never crash the handler */
|
||||
if (!options.skipMemoryRing) {
|
||||
try {
|
||||
appendLogEvent(event);
|
||||
} catch {
|
||||
/* logging must never crash the handler */
|
||||
}
|
||||
}
|
||||
|
||||
const config = getLoggingConfig();
|
||||
|
||||
@@ -1,14 +1,23 @@
|
||||
import {
|
||||
chmodSync,
|
||||
mkdirSync,
|
||||
mkdtempSync,
|
||||
readdirSync,
|
||||
readFileSync,
|
||||
rmSync,
|
||||
statSync,
|
||||
symlinkSync,
|
||||
} from "node:fs";
|
||||
import { tmpdir } from "node:os";
|
||||
import { join } from "node:path";
|
||||
|
||||
import { describe, expect, it } from "vitest";
|
||||
import { describe, expect, it, vi } from "vitest";
|
||||
|
||||
import {
|
||||
clearLogBuffer,
|
||||
getLogBufferSize,
|
||||
readLogBuffer,
|
||||
} from "@/lib/logging/in-memory-buffer";
|
||||
|
||||
import { walkSourceFiles } from "@/__tests__/helpers/source-files";
|
||||
|
||||
@@ -22,6 +31,8 @@ import {
|
||||
HeapMonitor,
|
||||
type HeapFigures,
|
||||
type HeapMonitorDeps,
|
||||
emitHeapLine,
|
||||
isPrivateDirectory,
|
||||
writeDiagnosticHeapSnapshot,
|
||||
} from "../heap-monitor";
|
||||
import { InFlightRegistry } from "../in-flight";
|
||||
@@ -212,7 +223,7 @@ describe("runtime.heap task names", () => {
|
||||
});
|
||||
|
||||
describe("default snapshot writer", () => {
|
||||
it("writes into a 0700 directory, the file 0600", () => {
|
||||
it("writes into a fresh random 0700 directory, the file 0600", () => {
|
||||
const dir = mkdtempSync(join(tmpdir(), "hl-heap-test-"));
|
||||
const previous = process.env.HEALTHLOG_DIAG_DIR;
|
||||
process.env.HEALTHLOG_DIAG_DIR = dir;
|
||||
@@ -220,13 +231,65 @@ describe("default snapshot writer", () => {
|
||||
const outcome = writeDiagnosticHeapSnapshot();
|
||||
expect(outcome.snapshot).toBe("written");
|
||||
if (outcome.snapshot !== "written") return;
|
||||
const sub = readdirSync(dir)[0];
|
||||
const [sub] = readdirSync(dir);
|
||||
expect(sub).toMatch(/^healthlog-heap-/);
|
||||
// Not derived from the pid, which is 1 in most containers.
|
||||
expect(sub).not.toBe(`healthlog-heap-${process.pid}`);
|
||||
expect(statSync(join(dir, sub)).mode & 0o777).toBe(0o700);
|
||||
expect(statSync(outcome.snapshot_path).mode & 0o777).toBe(0o600);
|
||||
expect(outcome.snapshot_path.startsWith(join(dir, sub) + "/")).toBe(true);
|
||||
} finally {
|
||||
if (previous === undefined) delete process.env.HEALTHLOG_DIAG_DIR;
|
||||
else process.env.HEALTHLOG_DIAG_DIR = previous;
|
||||
rmSync(dir, { recursive: true, force: true });
|
||||
}
|
||||
}, 90_000);
|
||||
|
||||
it("accepts only a real directory of its own user closed to others", () => {
|
||||
const dir = mkdtempSync(join(tmpdir(), "hl-heap-dir-"));
|
||||
try {
|
||||
const own = join(dir, "own");
|
||||
mkdirSync(own, { mode: 0o700 });
|
||||
chmodSync(own, 0o700);
|
||||
expect(isPrivateDirectory(own)).toBe(true);
|
||||
|
||||
const open = join(dir, "open");
|
||||
mkdirSync(open);
|
||||
chmodSync(open, 0o755);
|
||||
expect(isPrivateDirectory(open)).toBe(false);
|
||||
|
||||
// A symlink to a private directory is still refused: lstat, not stat.
|
||||
const link = join(dir, "link");
|
||||
symlinkSync(own, link);
|
||||
expect(isPrivateDirectory(link)).toBe(false);
|
||||
} finally {
|
||||
rmSync(dir, { recursive: true, force: true });
|
||||
}
|
||||
});
|
||||
});
|
||||
|
||||
describe("admin log ring", () => {
|
||||
it("keeps periodic samples out, and pressure reports in", () => {
|
||||
const write = vi
|
||||
.spyOn(process.stdout, "write")
|
||||
.mockImplementation(() => true);
|
||||
try {
|
||||
clearLogBuffer();
|
||||
for (let i = 0; i < 20; i++) {
|
||||
emitHeapLine(HEAP_TASK_NAMES.sampled, "info", { heap_used_mb: i });
|
||||
}
|
||||
// The samples still reach stdout.
|
||||
expect(write).toHaveBeenCalledTimes(20);
|
||||
expect(getLogBufferSize("all")).toBe(0);
|
||||
|
||||
emitHeapLine(HEAP_TASK_NAMES.pressure, "warn", { heap_used_mb: 900 });
|
||||
expect(getLogBufferSize("all")).toBe(1);
|
||||
expect(getLogBufferSize("problems")).toBe(1);
|
||||
const [event] = readLogBuffer({ ring: "problems" });
|
||||
expect(event.background?.task_name).toBe(HEAP_TASK_NAMES.pressure);
|
||||
} finally {
|
||||
write.mockRestore();
|
||||
clearLogBuffer();
|
||||
}
|
||||
});
|
||||
});
|
||||
@@ -1,4 +1,4 @@
|
||||
import { chmodSync, mkdirSync } from "node:fs";
|
||||
import { chmodSync, lstatSync, mkdtempSync } from "node:fs";
|
||||
import { join } from "node:path";
|
||||
import {
|
||||
getHeapSpaceStatistics,
|
||||
@@ -25,7 +25,8 @@ import { inFlightRegistry, type InFlightRegistry } from "./in-flight";
|
||||
*
|
||||
* - `runtime.heap.sampled`, every five minutes, and every minute while the
|
||||
* heap stands at or above 70 % of its limit. About 290 lines a day on a
|
||||
* quiet process, a trend line rather than a flood.
|
||||
* quiet process, a trend line rather than a flood. It goes to stdout and
|
||||
* Loki but not into the admin log ring, which it would otherwise flush.
|
||||
* - `runtime.heap.pressure`, at `warn`, the first time the heap reaches 85 %
|
||||
* of its limit: the heap figures plus the oldest requests and jobs in
|
||||
* flight and the routes most of them share (see `in-flight.ts`). It
|
||||
@@ -42,8 +43,8 @@ import { inFlightRegistry, type InFlightRegistry } from "./in-flight";
|
||||
*
|
||||
* Opt-in heap snapshot: with `HEALTHLOG_HEAP_SNAPSHOT=1`, the first pressure
|
||||
* report is followed by one `v8.writeHeapSnapshot()` into
|
||||
* `HEALTHLOG_DIAG_DIR` (default `/tmp`), inside a directory only the process
|
||||
* user can open, the file chmod 0600. One per process, ever. A snapshot is a
|
||||
* `HEALTHLOG_DIAG_DIR` (default `/tmp`), inside a fresh randomly named
|
||||
* directory only the process user can open, the file chmod 0600. One per process, ever. A snapshot is a
|
||||
* copy of the whole heap, decrypted health records and keys included: it is
|
||||
* never uploaded, never logged, and only its path is reported. Writing it
|
||||
* blocks the process for seconds and needs memory of its own, so it is a tool
|
||||
@@ -133,7 +134,8 @@ function defaultReadFigures(registry: InFlightRegistry): HeapFigures {
|
||||
};
|
||||
}
|
||||
|
||||
function defaultEmit(
|
||||
/** The production emit; exported for its ring-buffer test. */
|
||||
export function emitHeapLine(
|
||||
taskName: string,
|
||||
level: "info" | "warn",
|
||||
meta: Record<string, unknown>,
|
||||
@@ -143,18 +145,45 @@ function defaultEmit(
|
||||
for (const [key, value] of Object.entries(meta)) event.addMeta(key, value);
|
||||
if (level === "warn") event.elevateLevel("warn");
|
||||
event.finish();
|
||||
emitIfSampled(event.toJSON());
|
||||
// The periodic sample stays out of the admin log ring: at a minute apart
|
||||
// under load it would evict the very events someone opens that page for.
|
||||
// stdout and Loki still get it; the pressure and snapshot lines (warn) go
|
||||
// everywhere.
|
||||
emitIfSampled(event.toJSON(), {
|
||||
skipMemoryRing: taskName === HEAP_TASK_NAMES.sampled,
|
||||
});
|
||||
}
|
||||
|
||||
/** The opt-in heap snapshot; exported for its file-mode test. */
|
||||
/**
|
||||
* Whether `path` is a real directory (not a symlink) owned by this process's
|
||||
* user and closed to everyone else. Checked before a snapshot is written into
|
||||
* it, because the snapshot holds decrypted health data.
|
||||
*/
|
||||
export function isPrivateDirectory(path: string): boolean {
|
||||
const stat = lstatSync(path);
|
||||
if (!stat.isDirectory() || stat.isSymbolicLink()) return false;
|
||||
if (typeof process.getuid === "function" && stat.uid !== process.getuid()) {
|
||||
return false;
|
||||
}
|
||||
return (stat.mode & 0o077) === 0;
|
||||
}
|
||||
|
||||
/**
|
||||
* The opt-in heap snapshot; exported for its file-mode test.
|
||||
*
|
||||
* The directory comes from `mkdtempSync`: an unpredictable name created
|
||||
* atomically with mode 0700, so nobody can have placed a directory or a
|
||||
* symlink there first (a pid-based name is not that: in a container the pid
|
||||
* is usually 1). It is re-checked with `lstat` before anything is written.
|
||||
*/
|
||||
export function writeDiagnosticHeapSnapshot(): SnapshotOutcome {
|
||||
try {
|
||||
const dir = join(
|
||||
envOr("HEALTHLOG_DIAG_DIR", "/tmp"),
|
||||
`healthlog-heap-${process.pid}`,
|
||||
const dir = mkdtempSync(
|
||||
join(envOr("HEALTHLOG_DIAG_DIR", "/tmp"), "healthlog-heap-"),
|
||||
);
|
||||
mkdirSync(dir, { recursive: true, mode: 0o700 });
|
||||
chmodSync(dir, 0o700);
|
||||
if (!isPrivateDirectory(dir)) {
|
||||
return { snapshot: "failed", snapshot_error: "unsafe_directory" };
|
||||
}
|
||||
const stamp = new Date().toISOString().replace(/[:.]/g, "-");
|
||||
const path = writeHeapSnapshot(join(dir, `heap-${stamp}.heapsnapshot`));
|
||||
chmodSync(path, 0o600);
|
||||
@@ -255,7 +284,7 @@ export function startHeapMonitor(overrides: Partial<HeapMonitorDeps> = {}) {
|
||||
readHeap: defaultReadHeap,
|
||||
readFigures: () => defaultReadFigures(registry),
|
||||
registry,
|
||||
emit: defaultEmit,
|
||||
emit: emitHeapLine,
|
||||
snapshotEnabled: envFlag("HEALTHLOG_HEAP_SNAPSHOT"),
|
||||
writeSnapshot: writeDiagnosticHeapSnapshot,
|
||||
...overrides,
|
||||
|
||||
Reference in new issue
Block a user