diff --git a/CHANGELOG.md b/CHANGELOG.md index b54afb492..8af6538b1 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -7,6 +7,31 @@ and this project adheres to [Semantic Versioning](http://semver.org/spec/v2.0.0. ## [Unreleased] +## [6.52.0] +### Added +- Cluster-wide Prometheus `/metrics` aggregation. Each cluster worker keeps its own + prom-client registry, so serving `/metrics` from a single round-robin selected + worker exposed only that worker's counters; Prometheus read the per-scrape braid + of independent monotonic counters as counter resets and inflated `rate()` / + `increase()` on `runtime_http_*` counters by orders of magnitude. In multi-worker + mode the worker answering a scrape now asks the master for a merged, monotonic + view built from every worker's registry over the existing cluster IPC (via + prom-client's `AggregatorRegistry`), with a bounded timeout and a local-registry + fallback. Single-worker mode (`workers === 1`, includes `LINKED`) is unchanged. + Backport of #667 to the 6.x line. +### Fixed +- `runtime_http_*` metrics no longer emit samples without a `handler` label. Requests + that never reach a named handler (unmatched paths, replica-level rate limit + rejections, errors before the route pipeline) were counted with + `handler: undefined`; Node's cluster IPC serializes worker registries as JSON, which + drops `undefined` values, so the aggregated `/metrics` exposed a second, unnamed + series that Prometheus reads as `handler=""`. Those requests are now labelled + `handler="undefined"` — the same value prom-client rendered locally before cluster + aggregation — keeping dashboards and alerts that filter on it working. Backport of + #673 to the 6.x line. +- `/_status` requests are now reported as `handler="builtin:status-track"`, matching + the other builtin handlers, instead of falling into the unnamed bucket. + ## [6.51.0] - 2026-06-23 ### Added - Base `IOClients` getter `janusCatalogSystem` (Janus Catalog) and diff --git a/jest.config.js b/jest.config.js index 9689a2108..8ca529dce 100644 --- a/jest.config.js +++ b/jest.config.js @@ -1,4 +1,17 @@ module.exports = { + moduleNameMapper: { + // jest@25's resolver predates the package "exports" field, so it cannot load the + // modern @vtex/diagnostics-nodejs + OpenTelemetry logger chain that src/service/logger + // pulls in at module-eval time (reached transitively by nearly every service module). + // Stub the package so any suite importing the logger chain can load under the 6.x + // toolchain; the real telemetry/log-client paths are lazy and error-guarded, so this + // has no behavioural effect on the code under test. See jest/stubs/diagnosticsNodejs.js. + '^@vtex/diagnostics-nodejs$': '/jest/stubs/diagnosticsNodejs.js', + // Belt-and-braces for the same chain if it is reached directly rather than through + // the stub above. + '^@opentelemetry/otlp-exporter-base/node-http$': + '/node_modules/@opentelemetry/otlp-exporter-base/build/src/index-node-http.js', + }, roots: ['/src'], transform: { '^.+\\.tsx?$': 'ts-jest', diff --git a/jest/stubs/diagnosticsNodejs.js b/jest/stubs/diagnosticsNodejs.js new file mode 100644 index 000000000..d6d93905c --- /dev/null +++ b/jest/stubs/diagnosticsNodejs.js @@ -0,0 +1,24 @@ +// Test stub for `@vtex/diagnostics-nodejs`. +// +// The 6.x toolchain pins `jest@25`, whose module resolver predates the package +// `exports` field. `@vtex/diagnostics-nodejs` pulls in modern OpenTelemetry +// exporter packages that expose their entry points only through `exports` +// subpaths (e.g. `@opentelemetry/otlp-exporter-base/node-http`), which jest@25 +// cannot resolve. Because `src/service/logger` (imported transitively by nearly +// every service module) loads that chain at module-evaluation time, any test +// touching a service module fails to even load under jest@25. +// +// The real telemetry / log-client paths are lazy and error-guarded (see +// `src/service/logger/logger.ts` and `src/service/telemetry/client.ts`), so +// tests only need the named exports to exist for module evaluation. This stub +// provides just enough surface for that, with no behavioural effect on the code +// under test. +module.exports = { + Exporters: { + CreateExporter: () => ({ initialize: async () => undefined }), + CreateLogsExporterConfig: () => ({}), + }, + NewTelemetryClient: async () => ({ + newLogsClient: async () => ({}), + }), +} diff --git a/package.json b/package.json index 13629567c..daadb48c8 100644 --- a/package.json +++ b/package.json @@ -1,6 +1,6 @@ { "name": "@vtex/api", - "version": "6.51.0", + "version": "6.52.0", "description": "VTEX I/O API client", "main": "lib/index.js", "typings": "lib/index.d.ts", diff --git a/specs/backport-cluster-wide-prom-client-metrics-aggreg.md b/specs/backport-cluster-wide-prom-client-metrics-aggreg.md new file mode 100644 index 000000000..fa2c30229 --- /dev/null +++ b/specs/backport-cluster-wide-prom-client-metrics-aggreg.md @@ -0,0 +1,365 @@ +# Spec: Backport cluster-wide prom-client metrics aggregation (plus undefined-handler-label fix) to 6.x + +> **Status: ⏳ awaiting approval.** This document describes the planned change. +> Implementation follows in a second phase on the same PR. **Base branch: `6.x`** +> (the maintenance line), NOT `master` (the 7.x line). + +--- + +## Context & problem + +VTEX IO runtimes run as a Node.js `cluster`: the master (`src/service/master.ts`) +forks `min(cpus, MAX_WORKERS=4)` workers, each listening on the shared +`HTTP_SERVER_PORT`. Every worker keeps its **own** prom-client default registry +(`register`): the request counters are created per-worker in +`src/service/metrics/requestMetricsMiddleware.ts` (via the +`create*Instrument()` factories in `src/service/tracing/metrics/instruments.ts`), +and `collectDefaultMetrics()` is called per-worker in +`src/service/worker/runtime/builtIn/middlewares.ts`. + +`/metrics` is served by `prometheusLoggerMiddleware` +(`src/service/worker/runtime/builtIn/middlewares.ts`), which answers with +`register.metrics()` — i.e. **only the local registry of whichever worker the OS +round-robin handed the scrape connection to**. Because Node's keep-alive socket +timeout (5s) is shorter than the Prometheus scrape interval, almost every scrape +lands on a *different* worker. + +Consequence: Prometheus sees, under a single `instance` label, an interleaved +braid of 4 independent monotonic counters. Each time a scrape hits a worker whose +local count is lower than the previously scraped worker's, Prometheus treats the +drop as a **counter reset**, so `rate()` / `increase()` over `runtime_*` counters +(notably `runtime_http_requests_total{handler,status_code}`) are inflated by +orders of magnitude (~×40 measured on a live pod). + +This has already been fixed on the 7.x line (`master`): + +- **PR #667** (merge `378e41d8`, feat commit `6911aaff`, follow-ups `5d952ae4`, + `6aac341a`, `4c859625`, `ad57abe3`) — cluster-wide `/metrics` aggregation. + Accepted design doc: `git show origin/master:specs/aggregate-prom-client-metrics-across-cluster-wor.md`. +- **PR #673** (branch `fix/metrics-undefined-handler-label`, base `master`, still + **OPEN** at the time of writing) — never emit `runtime_http_*` samples without a + `handler` label. + +The 6.x maintenance line (currently `@vtex/api@6.51.0`, shipped in older runtimes +such as `service-node` images bundling `6.42.0`) **never received either change**. +This backport ports both, as a single PR, so the 6.x line jumps straight to the +correct end state and never reproduces the broken intermediate state that +`service-node:7.7.14` (`@vtex/api@7.4.1`, aggregation without the handler-label +fix) exhibited. + +### The undefined-handler-label follow-up (PR #673) — why it must ship together + +`ctx.requestHandlerName` is only assigned inside a route pipeline or by a builtin +handler, but `addRequestMetricsMiddleware` is mounted at the top of the chain and +counts **every** request in a `finally` block. Requests that never reach a named +handler (unmatched paths → 404, replica-level rate-limit rejections → 429, +`/_status` polls, unimplemented/unknown route ids, aborted requests) are therefore +counted with `handler: undefined`. + +In-process, prom-client keeps the key and renders it as `handler="undefined"`. +But **Node's cluster IPC serializes messages with `JSON.stringify`, which drops +`undefined` values** — so once aggregation (change 1) is in place, the sample +reaches the master with the `handler` label key gone entirely. That produces a +second, nameless series `runtime_http_requests_total{status_code="200"}`, which +Prometheus reads as `handler=""`. This: + +- is a **different series** from the historical `handler="undefined"`, splitting + panels at the rollout boundary; +- breaks Grafana `{{handler}}` interpolation (falls back to the field name + `Value`); +- breaks exclusion filters — `handler!~"builtin:.*|undefined"` does not match + `""`, so the previously-filtered bucket leaks back in. + +Because the broken series only appears **as a consequence of aggregation**, both +changes must land in the same 6.x PR. + +### 6.x facts verified in-repo + +- 6.x pins `prom-client@^14.2.0` (same as master), so `AggregatorRegistry` and the + cluster IPC protocol are available with no dependency bump. +- `AggregatorRegistry`'s default `registries = [globalRegistry]` is exactly the + `register` our instruments and `collectDefaultMetrics()` write to, so **no** + `setRegistries` call is needed. Its constructor idempotently installs + prom-client's master `cluster.on('message')` collector (master) and worker + `process.on('message')` responder (worker). +- `serviceJSON.workers` is the reliable multi/single switch (already resolves + `LINKED → 1` and caps at `MAX_WORKERS`). +- 6.x `src/service/metrics/` contains **only** `requestMetricsMiddleware.ts` — + there is **no** `otelRequestMetricsMiddleware.ts` and no OpenTelemetry metrics + client. The otel slice of PR #673 is skipped. +- 6.x `master.ts` / `worker/index.ts` / `builtIn/middlewares.ts` have drifted from + master (e.g. 6.x `middlewares.ts` imports `COLOSSUS_ROUTE_ID_HEADER` directly, + master imports `HeaderKeys`; 6.x `worker/index.ts` has no otel middleware and + keeps the `.reduce(mergeDeepRight as any)` form). Intent is ported to match 6.x + code style, not cherry-picked. +- Toolchain: `jest@^25.1.0`, `ts-jest@^25.2.1`, `typescript@^4.4.4`, `tslint@^5`. + Tests must run under this toolchain. + +--- + +## Proposed approach + +**Serve `/metrics` from an aggregate that the master builds from all workers, +requested by the answering worker over the existing cluster IPC — and guarantee +every `runtime_http_*` sample carries a non-empty `handler` label so the aggregate +keeps the historical series identity.** + +### Change 1 — cluster-wide aggregation + +Flow (multi-worker mode, `serviceJSON.workers > 1`): + +1. Master, in `startMaster`, constructs a single `AggregatorRegistry` + (`initMasterAggregatorRegistry()`), enabling prom-client's master-side + collector listener. +2. Each worker, in `startWorker`, constructs an `AggregatorRegistry` + (`ensureWorkerAggregatorRegistry()`), so prom-client's worker-side + `getMetricsReq` responder is installed in every worker. +3. On `GET /metrics`, the worker sends a tagged, correlation-id'd IPC request + (`process.send({ type: AGG_METRICS_REQ, id })`) to the master and awaits a + matching `AGG_METRICS_RES`, with a bounded timeout, then serves the returned + exposition string with `Content-Type: register.contentType`. +4. The master, on `AGG_METRICS_REQ`, calls `aggregatorRegistry.clusterMetrics()`, + which fans `getMetricsReq` out to **all** connected workers (including the + requester — so it is one of N merged sources, never double-counted), merges the + per-metric samples, and replies to that worker only: + `worker.send({ type: AGG_METRICS_RES, id, body })` (or `{ id, error }`). + +Single-worker mode (`serviceJSON.workers === 1`, includes `LINKED`) keeps the +**exact current behaviour**: `await eventLoopLagMeasurer.updateInstrumentsAndReset()` +then `ctx.body = await register.metrics()`, with no IPC. + +Robustness: on IPC error/timeout (prom-client's `clusterMetrics()` has its own 5s +timeout; we guard slightly above at 6s), the worker falls back to serving its +**local** `register.metrics()` and still returns 200. Logged, not fatal. + +Both `onMessage` handlers (master and worker) gain branches to route the new +messages and to **silently ignore** prom-client's own `prom-client:getMetricsReq` +/ `prom-client:getMetricsRes` IPC messages (handled by prom-client's own +listeners) instead of `logger.warn`-ing on them, while `UP_SIGNAL` / +`statusTrack` continue to be handled as before. + +### Change 2 — never emit an empty/missing `handler` label + +A tiny helper resolves the label with an explicit `'undefined'` string fallback +(deliberately that exact string — see below), used at every +`requestMetricsMiddleware` call site, still evaluated inside the callbacks / +`finally` block so the handler name is read *after* the pipeline ran. Plus, +`statusTrackHandler` sets `ctx.requestHandlerName = 'builtin:status-track'` for +parity with the sibling builtins. + +Why the literal `'undefined'` (documented next to the constant): prom-client's +local exposition already rendered `handler: undefined` as `handler="undefined"` +before aggregation existed. Keeping that exact value makes the aggregated output +match the historical series identity so existing dashboards, `{{handler}}` +interpolation, and `handler!~"builtin:.*|undefined"` filters keep working. Empty +strings fall back too (`requestHandlerName || UNNAMED_REQUEST_HANDLER`), so the +label is never emitted empty. + +### New/changed module boundary + +A dedicated module `src/service/metrics/clusterMetricsAggregator.ts` owns the +message-type constants + type guards, the master-side `AggregatorRegistry` +singleton and request handler, and the worker-side registry setup + correlated +request/response + timeout + local fallback. Keeping this in one module keeps +`master.ts`, `worker/index.ts` and `middlewares.ts` changes minimal and testable +in isolation with IPC mocks. + +`src/service/metrics/requestHandlerLabel.ts` owns the label constant + resolver. + +--- + +## Files / components to change + +| File | Change | +| --- | --- | +| `src/service/metrics/clusterMetricsAggregator.ts` *(new)* | Message constants (`AGG_METRICS_REQ`, `AGG_METRICS_RES`) + guards (`isAggMetricsRequest`, `isAggMetricsResponse`, `isPromClientMessage`); master `initMasterAggregatorRegistry()` + `handleWorkerMetricsRequest(worker, message)`; worker `ensureWorkerAggregatorRegistry()`, `requestAggregatedMetrics()`, `handleMasterMetricsResponse(message)`; a `__resetForTests()` helper. Ported ~verbatim from `git show 378e41d8:src/service/metrics/clusterMetricsAggregator.ts`. | +| `src/service/metrics/requestHandlerLabel.ts` *(new)* | `UNNAMED_REQUEST_HANDLER = 'undefined'` (with the documented reasoning) and `requestHandlerLabel(name?) => name || UNNAMED_REQUEST_HANDLER`. | +| `src/service/metrics/requestMetricsMiddleware.ts` | Import `requestHandlerLabel`; wrap `ctx.requestHandlerName` at all four call sites (aborted, response sizes, total, timings). 6.x keeps the `create*Instrument()` factory imports — only the call sites change. | +| `src/service/master.ts` | Import from the aggregator module; export `onMessage` (for tests); in `onMessage`, route `AGG_METRICS_REQ` → `handleWorkerMetricsRequest` and ignore `isPromClientMessage` before the `logger.warn` fallback; in `startMaster`, `if (numWorkers > 1) initMasterAggregatorRegistry()`. | +| `src/service/worker/index.ts` | Import from the aggregator module; export `onMessage`; in `onMessage`, route `AGG_METRICS_RES` → `handleMasterMetricsResponse` and ignore `isPromClientMessage`; in `startWorker`, `if (serviceJSON.workers > 1) ensureWorkerAggregatorRegistry()` and pass the worker count into `prometheusLoggerMiddleware(serviceJSON.workers)`. **Do not** port the master-only otel middleware or the `.reduce`/`filter` typing refactor (that drift is unrelated to this backport). | +| `src/service/worker/runtime/builtIn/middlewares.ts` | `prometheusLoggerMiddleware(workers = 1)`; compute `isMultiWorker = workers > 1`; serve `isMultiWorker ? await requestAggregatedMetrics() : await register.metrics()`. Keep the `/metrics` early return, the `COLOSSUS_ROUTE_ID_HEADER` guard, and `collectDefaultMetrics()`/`eventLoopLagMeasurer` exactly as-is. | +| `src/service/worker/runtime/statusTrack.ts` | `statusTrackHandler` sets `ctx.requestHandlerName = 'builtin:status-track'` and passes it to `setOperationName`. | +| `package.json` | Bump `version` `6.51.0` → `6.52.0`. **Leave `prom-client` unchanged.** | +| `CHANGELOG.md` | Add an `## [Unreleased]` / `6.52.0` entry describing both the aggregation and the handler-label fix. | +| Test files under `__tests__/` *(new)* | See Test plan. | + +**Not created / not changed:** `src/service/metrics/otelRequestMetricsMiddleware.ts` +is deliberately absent on 6.x and must stay absent. No metric name, label name, +help text or bucket changes. + +--- + +## How each `AC:` line will be satisfied + +1. **PR base = 6.x and merge-base on origin/6.x, not origin/master.** The working + branch was recreated with `git reset --hard origin/6.x`; verified + `git merge-base --is-ancestor HEAD origin/6.x` is true and + `--is-ancestor HEAD origin/master` is false. The PR is opened with `--base 6.x`. + +2. **`clusterMetricsAggregator.ts` exports a master-side handler and a worker-side + request fn.** The module exports `handleWorkerMetricsRequest(worker, message)` + (master) and `requestAggregatedMetrics(): Promise` (worker), plus the + supporting setup/guards. + +3. **`requestHandlerLabel.ts` returns `'undefined'` for missing and empty input.** + `requestHandlerLabel(undefined) === 'undefined'` and + `requestHandlerLabel('') === 'undefined'` via `name || UNNAMED_REQUEST_HANDLER`. + +4. **A test asserts aggregating N registries (each `inc`'d once, identical labels) + yields exactly N.** `clusterMetricsAggregator.test.ts` builds N in-memory + worker registries, `inc()`s the same `runtime_http_requests_total{handler,status_code}` + once each, aggregates via `AggregatorRegistry.aggregate`, and asserts the series + equals `N`. + +5. **A test round-trips registries through `JSON.parse(JSON.stringify(...))` before + aggregating and asserts no emitted sample has a missing/empty `handler`.** A test + (in the handler-label suite) applies `overClusterIpc = p => JSON.parse(JSON.stringify(p))` + to each worker's `getMetricsAsJSON()` before `AggregatorRegistry.aggregate`, + drives a request with `ctx.requestHandlerName = undefined`, and asserts every + `runtime_http_*` sample matches `/handler="[^"]+"/` (and that + `runtime_http_requests_total{status_code=` — the label-less series — is absent). + +6. **A test asserts `workers === 1` serves `register.metrics()` and makes no + `process.send` IPC call.** `middlewares.test.ts` builds + `prometheusLoggerMiddleware(1)`, mocks a `/metrics` ctx, asserts + `ctx.body === await register.metrics()`, `Content-Type === register.contentType`, + and that `process.send` was not called. + +7. **A test asserts a `collectDefaultMetrics` series (e.g. + `process_cpu_seconds_total`) is present in the aggregated output.** The + aggregation test enables `collectDefaultMetrics()` into a worker registry and + asserts the merged exposition contains `process_cpu_seconds_total`. + +8. **A test asserts IPC timeout/error → local `register.metrics()` fallback, + still 200.** Using fake timers and a mocked `process.send`, a test drives + `requestAggregatedMetrics()` past `AGG_METRICS_TIMEOUT_MS` (and separately a + throwing `process.send`) and asserts it resolves with the local + `register.metrics()` body; a middleware-level assertion confirms `ctx.status === 200`. + +9. **A test asserts `GET /_status` sets `ctx.requestHandlerName` to + `builtin:status-track`.** `statusTrack.test.ts` calls `statusTrackHandler(ctx)` + and asserts `ctx.requestHandlerName === 'builtin:status-track'` (and that + `setOperationName` received the same value), including the `tracing: undefined` + case. + +10. **`yarn test` exits 0.** New tests target the 6.x jest@25 / ts-jest@25 + toolchain; existing tests stay green because `onMessage` gains branches only + (known messages unchanged). + +11. **`yarn lint` exits 0.** New code follows `tslint-config-vtex` (alphabetized + object literals, import order) as in surrounding 6.x files. + +12. **`yarn build` exits 0.** Types compile under `typescript@^4.4.4`: + `AggregatorRegistry`, `clusterMetrics(): Promise`, message interfaces, + and the `prometheusLoggerMiddleware(workers = 1)` signature. + +13. **`package.json` version bumped above `6.51.0`; `CHANGELOG.md` covers both + changes.** Bump to `6.52.0`; changelog entry describes aggregation + the + handler-label fix. + +14. **No `otelRequestMetricsMiddleware.ts`; `prom-client` unchanged.** That file is + not added; the `prom-client` dependency entry stays `^14.2.0`. + +--- + +## Risks & alternatives considered + +**Assumptions (no human available to confirm):** + +- **Version bump = `6.52.0`.** These are behavioural fixes (bug-fix in effect, but + they change how `/metrics` aggregates and add a handler label). On master the + aggregation shipped as a minor (`7.4.0 → 7.4.1` was the *patch* for the feature + merge, but the feature itself landed in the `7.4.x` line). To stay clearly above + `6.51.0` and signal new behaviour, a minor bump `6.52.0` is chosen. If the 6.x + maintainers prefer a patch (`6.51.1`), that is a one-line change. +- **PR #673 is still OPEN** at authoring time, so its branch + `origin/fix/metrics-undefined-handler-label` is the source of truth for change 2. + If it merges to master before implementation, the merged version is preferred. + The label value `'undefined'` and the `statusTrack` parity are stable regardless. +- **`AGG_METRICS_TIMEOUT_MS = 6000`** (just above prom-client's internal 5s) is + carried over from master. Prometheus scrape timeouts are typically ≥10s, so the + fallback returns well within budget. + +**Risks & mitigations:** + +- *IPC handler collisions / log noise.* prom-client adds its own message listeners + that fire alongside our `onMessage` handlers, which today `warn` on unknown + messages. Both handlers are updated to silently ignore `isPromClientMessage(...)` + and unmatched aggregate ids. Behavioural drift on existing known messages is + avoided by only *adding* branches, never altering the `UP_SIGNAL` / + `statusTrack` / `isLog` branches. +- *Latency / dead worker.* Bounded worker-side wait + local fallback keeps + `/metrics` answering 200 promptly even if a worker is slow/dead. +- *Event-loop-lag gauges.* `AggregatorRegistry` sums gauges across workers by + default, which is not a meaningful aggregation for the lag gauges, and + non-answering workers won't have refreshed their lag gauge at scrape time. This + is a pre-existing per-worker artifact and is **out of scope** (custom aggregators + for the lag gauges are a documented follow-up). The answering worker still calls + `updateInstrumentsAndReset()` in both paths to preserve current behaviour. +- *`io_http_requests_current` gauge* is also summed across workers; that is + arguably the desired "current concurrent requests across the replica" and + matches/improves current behaviour. Noted, not changed. +- *6.x drift.* `worker/index.ts` on 6.x lacks the otel middleware and keeps the + older `.reduce(mergeDeepRight as any)` handler-merge form; only the aggregation + wiring is added, the unrelated master-only refactors are **not** ported. + +**Alternatives considered (from the accepted master spec):** + +- *Move `/metrics` to the master process* (separate listener): cleanest + conceptually but the master is not a Koa HTTP server and doesn't listen on + `HTTP_SERVER_PORT`; too invasive. Rejected. +- *Shared memory / external counter store*: over-engineered; prom-client already + ships the IPC aggregation protocol. Rejected. +- *Sticky-session the scrape to one worker*: still under-reports 3/4 of traffic. + Rejected. +- *A nicer sentinel than `'undefined'` (e.g. `'unnamed'`)*: would split series at + the rollout boundary and break existing exclusion filters. Rejected in favour of + preserving historical series identity. + +--- + +## Test plan + +Framework: existing Jest + ts-jest (jest@25). New specs under `__tests__/` next to +the touched code. + +1. **`src/service/metrics/__tests__/clusterMetricsAggregator.test.ts`** + (ported/adapted from master): + - registry lifecycle: `initMasterAggregatorRegistry` / `ensureWorkerAggregatorRegistry` + idempotent. + - message guards: `isAggMetricsRequest` / `isAggMetricsResponse` / + `isPromClientMessage` recognise the right shapes. + - **AC4** — sum across N workers: N registries each `inc`'d once → series == N. + - **AC7** — `collectDefaultMetrics()` series (`process_cpu_seconds_total`) + present in the aggregate. + - **AC8** — `requestAggregatedMetrics()` falls back to local `register.metrics()` + on timeout (fake timers past 6s) and on a throwing `process.send`; resolves + with the local body. + - request/response correlation: a mocked master reply resolves the pending + promise with `body` by id. +2. **`src/service/metrics/__tests__/requestHandlerLabel.test.ts`**: + - **AC3** — `UNNAMED_REQUEST_HANDLER === 'undefined'`; + `requestHandlerLabel(undefined)` and `requestHandlerLabel('')` both return + `'undefined'`; a named handler passes through untouched. + - **AC5** — drive `addRequestMetricsMiddleware()` with `ctx.requestHandlerName = + undefined`, run the worker registry through `overClusterIpc` (real + `JSON.parse(JSON.stringify(...))`) before `AggregatorRegistry.aggregate`, and + assert every `runtime_http_*` sample matches `/handler="[^"]+"/` and the + label-less `runtime_http_requests_total{status_code=` series is absent. Also + covers aborted requests and named/unnamed as separate series. +3. **`src/service/worker/runtime/builtIn/__tests__/middlewares.test.ts`**: + - **AC6** — `prometheusLoggerMiddleware(1)` on a `/metrics` ctx sets + `ctx.body === register.metrics()`, correct `Content-Type`, and makes no + `process.send` call; multi-worker path uses `requestAggregatedMetrics`. + - non-`/metrics` and `COLOSSUS_ROUTE_ID_HEADER` requests still call `next()` + and are not counted; `ctx.status === 200` on the aggregate path (AC8 surface). +4. **`src/service/worker/runtime/__tests__/statusTrack.test.ts`**: + - **AC9** — `statusTrackHandler` sets `ctx.requestHandlerName === + 'builtin:status-track'` (with and without `ctx.tracing`). +5. **`src/service/__tests__/master.test.ts` / `src/service/worker/__tests__/onMessage.test.ts`** + (adapted to 6.x exported `onMessage`): + - master `onMessage` routes `AGG_METRICS_REQ` and no longer warns on + `prom-client:*`; still handles `statusTrack` / `isLog`. + - worker `onMessage` routes `AGG_METRICS_RES` and no longer warns on + `prom-client:*`; still handles `UP_SIGNAL` / `statusTrack`. +6. **Gates:** `yarn test`, `yarn lint`, `yarn build` all exit 0 (AC10–12). diff --git a/src/service/__tests__/master.test.ts b/src/service/__tests__/master.test.ts new file mode 100644 index 000000000..9a9163c63 --- /dev/null +++ b/src/service/__tests__/master.test.ts @@ -0,0 +1,30 @@ +import { Worker } from 'cluster' + +import { onMessage } from '../master' +import * as aggregator from '../metrics/clusterMetricsAggregator' +import { AGG_METRICS_REQ } from '../metrics/clusterMetricsAggregator' + +describe('master onMessage', () => { + const worker = { process: { pid: 123 }, send: jest.fn() } as unknown as Worker + + afterEach(() => { + jest.restoreAllMocks() + }) + + it('routes aggregate metric requests from workers to the aggregation handler', () => { + const spy = jest.spyOn(aggregator, 'handleWorkerMetricsRequest').mockResolvedValue(undefined) + const message = { id: 1, type: AGG_METRICS_REQ } + + onMessage(worker, message) + + expect(spy).toHaveBeenCalledTimes(1) + expect(spy).toHaveBeenCalledWith(worker, message) + }) + + it('ignores prom-client cluster protocol messages without invoking the handler', () => { + const spy = jest.spyOn(aggregator, 'handleWorkerMetricsRequest') + + expect(() => onMessage(worker, { type: 'prom-client:getMetricsReq' })).not.toThrow() + expect(spy).not.toHaveBeenCalled() + }) +}) diff --git a/src/service/master.ts b/src/service/master.ts index 84f7f6603..468a45262 100644 --- a/src/service/master.ts +++ b/src/service/master.ts @@ -3,19 +3,29 @@ import { constants } from 'os' import { INSPECT_DEBUGGER_PORT, LINKED, UP_SIGNAL } from '../constants' import { isLog, logOnceToDevConsole } from './logger' +import { + handleWorkerMetricsRequest, + initMasterAggregatorRegistry, + isAggMetricsRequest, + isPromClientMessage, +} from './metrics/clusterMetricsAggregator' import { logger } from './worker/listeners' import { broadcastStatusTrack, isStatusTrackBroadcast, trackStatus } from './worker/runtime/statusTrack' import { ServiceJSON } from './worker/runtime/typings' let handledSignal: NodeJS.Signals | undefined -const onMessage = (worker: Worker, message: any) => { +export const onMessage = (worker: Worker, message: any) => { if (isLog(message)) { logOnceToDevConsole(message.message, message.level) } else if (isStatusTrackBroadcast(message)) { trackStatus() broadcastStatusTrack() - } else { + } else if (isAggMetricsRequest(message)) { + handleWorkerMetricsRequest(worker, message) + } else if (!isPromClientMessage(message)) { + // prom-client's own cluster messages are handled by its cluster listener; + // anything else that reaches here is genuinely unexpected. logger.warn({ content: message, message: 'Worker sent message', @@ -77,6 +87,12 @@ export const startMaster = (service: ServiceJSON) => { process.env.DETERMINISTIC_VARY = 'true' } + // Set up the master-side Prometheus aggregator so workers can request a + // merged, monotonic /metrics view across the whole cluster over IPC. + if (numWorkers > 1) { + initMasterAggregatorRegistry() + } + // Setup dubugger if (LINKED) { cluster.setupMaster({ inspectPort: INSPECT_DEBUGGER_PORT }) diff --git a/src/service/metrics/__tests__/clusterMetricsAggregator.test.ts b/src/service/metrics/__tests__/clusterMetricsAggregator.test.ts new file mode 100644 index 000000000..611964e09 --- /dev/null +++ b/src/service/metrics/__tests__/clusterMetricsAggregator.test.ts @@ -0,0 +1,249 @@ +import { AggregatorRegistry, Counter, Registry } from 'prom-client' + +import { + __resetForTests, + AGG_METRICS_REQ, + AGG_METRICS_RES, + AggMetricsResMessage, + ensureWorkerAggregatorRegistry, + handleMasterMetricsResponse, + handleWorkerMetricsRequest, + initMasterAggregatorRegistry, + isAggMetricsRequest, + isAggMetricsResponse, + isPromClientMessage, + requestAggregatedMetrics, +} from '../clusterMetricsAggregator' + +const REQUESTS_TOTAL = { + help: 'The total number of HTTP requests.', + labelNames: ['status_code', 'handler'], + name: 'runtime_http_requests_total', +} + +// Build an isolated registry that mimics one worker's default registry with a +// runtime_http_requests_total counter incremented `count` times. +const buildWorkerRegistry = (count: number, labels = { handler: 'render', status_code: '200' }) => { + const registry = new Registry() + const counter = new Counter({ ...REQUESTS_TOTAL, registers: [registry] }) + for (let i = 0; i < count; i++) { + counter.inc(labels) + } + return registry +} + +// Parse `runtime_http_requests_total{...} ` samples out of exposition text. +const parseSeries = (text: string, metric: string): Record => { + const out: Record = {} + text + .split('\n') + .filter((line) => line.startsWith(metric) && !line.startsWith('# ')) + .forEach((line) => { + const match = line.match(/^(\S+)\s+([\d.eE+-]+)$/) + if (match) { + out[match[1]] = Number(match[2]) + } + }) + return out +} + +// Node's cluster IPC serializes messages as JSON, so worker registries reach the +// master through a JSON round-trip. Reproducing it here keeps these tests honest +// about what the master actually merges (notably: JSON drops `undefined` label +// values, which used to strip the `handler` label from the aggregated output). +const overClusterIpc = (payload: T): T => JSON.parse(JSON.stringify(payload)) + +const aggregateRegistries = async (registries: Registry[]): Promise => { + const jsons = await Promise.all(registries.map(async (r) => overClusterIpc(await r.getMetricsAsJSON()))) + const merged = AggregatorRegistry.aggregate(jsons) + return merged.metrics() +} + +describe('clusterMetricsAggregator', () => { + afterEach(() => { + __resetForTests() + jest.useRealTimers() + delete (process as any).send + }) + + describe('registry lifecycle', () => { + it('creates the master aggregator registry once (idempotent)', () => { + const first = initMasterAggregatorRegistry() + const second = initMasterAggregatorRegistry() + expect(first).toBeInstanceOf(AggregatorRegistry) + expect(second).toBe(first) + }) + + it('creates the worker aggregator registry once (idempotent)', () => { + const first = ensureWorkerAggregatorRegistry() + const second = ensureWorkerAggregatorRegistry() + expect(first).toBeInstanceOf(AggregatorRegistry) + expect(second).toBe(first) + }) + }) + + describe('message guards', () => { + it('recognizes aggregate request/response and prom-client messages', () => { + expect(isAggMetricsRequest({ id: 1, type: AGG_METRICS_REQ })).toBe(true) + expect(isAggMetricsRequest({ type: AGG_METRICS_REQ })).toBe(false) + expect(isAggMetricsResponse({ body: 'x', id: 1, type: AGG_METRICS_RES })).toBe(true) + expect(isAggMetricsResponse('UP')).toBe(false) + expect(isPromClientMessage({ type: 'prom-client:getMetricsReq' })).toBe(true) + expect(isPromClientMessage({ type: 'prom-client:getMetricsRes' })).toBe(true) + expect(isPromClientMessage('UP')).toBe(false) + expect(isPromClientMessage({ statusTrack: true })).toBe(false) + }) + }) + + describe('aggregation across workers', () => { + // AC2: a counter incremented once per worker in N workers reports N. + it('sums a series across N workers', async () => { + const N = 4 + const registries = Array.from({ length: N }, () => buildWorkerRegistry(1)) + const output = await aggregateRegistries(registries) + const series = parseSeries(output, 'runtime_http_requests_total') + const key = Object.keys(series).find((k) => k.includes('runtime_http_requests_total'))! + expect(series[key]).toBe(N) + }) + + it('sums differing per-worker counts', async () => { + const registries = [buildWorkerRegistry(5), buildWorkerRegistry(10), buildWorkerRegistry(2), buildWorkerRegistry(8)] + const output = await aggregateRegistries(registries) + const series = parseSeries(output, 'runtime_http_requests_total') + const key = Object.keys(series).find((k) => k.includes('runtime_http_requests_total'))! + expect(series[key]).toBe(25) + }) + + it('preserves and sums distinct label sets from different workers', async () => { + const registries = [ + buildWorkerRegistry(3, { handler: 'render', status_code: '200' }), + buildWorkerRegistry(4, { handler: 'render', status_code: '500' }), + buildWorkerRegistry(1, { handler: 'render', status_code: '200' }), + ] + const output = await aggregateRegistries(registries) + const series = parseSeries(output, 'runtime_http_requests_total') + const ok = Object.keys(series).find((k) => k.includes('status_code="200"'))! + const err = Object.keys(series).find((k) => k.includes('status_code="500"'))! + expect(series[ok]).toBe(4) + expect(series[err]).toBe(4) + }) + + // AC1: two consecutive scrapes never show a decreasing value, regardless of + // which worker answers (the merge is the same aggregate either way). + it('never decreases across two consecutive scrapes', async () => { + const workerCounts = [5, 10, 2, 8] + const registriesScrape1 = workerCounts.map((c) => buildWorkerRegistry(c)) + const scrape1 = parseSeries(await aggregateRegistries(registriesScrape1), 'runtime_http_requests_total') + + // Between scrapes each worker serves more traffic; counters only grow. + const registriesScrape2 = workerCounts.map((c, i) => buildWorkerRegistry(c + i + 1)) + const scrape2 = parseSeries(await aggregateRegistries(registriesScrape2), 'runtime_http_requests_total') + + Object.keys(scrape1).forEach((key) => { + expect(scrape2[key]).toBeGreaterThanOrEqual(scrape1[key]) + }) + }) + + // AC4: default process metrics remain present in the aggregated output. + it('includes default process metrics collected per worker', async () => { + const registryWithDefaults = new Registry() + // Emulate a default metric present in a worker registry. + const cpu = new Counter({ + help: 'Total user and system CPU time spent in seconds.', + name: 'process_cpu_seconds_total', + registers: [registryWithDefaults], + }) + cpu.inc(1) + const output = await aggregateRegistries([registryWithDefaults, buildWorkerRegistry(1)]) + expect(output).toContain('process_cpu_seconds_total') + }) + }) + + describe('worker IPC request/response', () => { + it('sends AGG_METRICS_REQ and resolves with the master body', async () => { + const sent: any[] = [] + ;(process as any).send = (msg: any) => sent.push(msg) + + const promise = requestAggregatedMetrics() + + expect(sent).toHaveLength(1) + expect(sent[0].type).toBe(AGG_METRICS_REQ) + const { id } = sent[0] + + handleMasterMetricsResponse({ body: 'AGGREGATED_BODY', id, type: AGG_METRICS_RES }) + await expect(promise).resolves.toBe('AGGREGATED_BODY') + }) + + it('falls back to the local registry on timeout', async () => { + jest.useFakeTimers() + ;(process as any).send = () => undefined + + const promise = requestAggregatedMetrics() + jest.advanceTimersByTime(6000) + const body = await promise + // Local register.metrics() output; just assert it is a (possibly empty) string. + expect(typeof body).toBe('string') + }) + + it('falls back to the local registry when the master replies with an error', async () => { + const sent: any[] = [] + ;(process as any).send = (msg: any) => sent.push(msg) + + const promise = requestAggregatedMetrics() + const { id } = sent[0] + const errorMsg: AggMetricsResMessage = { error: 'boom', id, type: AGG_METRICS_RES } + handleMasterMetricsResponse(errorMsg) + const body = await promise + expect(typeof body).toBe('string') + }) + + it('ignores responses with unknown correlation ids', () => { + expect(() => handleMasterMetricsResponse({ body: 'x', id: 9999, type: AGG_METRICS_RES })).not.toThrow() + }) + + it('serves local metrics when process.send is unavailable', async () => { + delete (process as any).send + const body = await requestAggregatedMetrics() + expect(typeof body).toBe('string') + }) + + it('falls back to the local registry when process.send throws', async () => { + (process as any).send = () => { + throw new Error('ipc channel closed') + } + const body = await requestAggregatedMetrics() + expect(typeof body).toBe('string') + }) + }) + + describe('master request handler', () => { + it('replies to the requesting worker with a body', async () => { + const worker: any = { send: jest.fn() } + await handleWorkerMetricsRequest(worker, { id: 7, type: AGG_METRICS_REQ }) + expect(worker.send).toHaveBeenCalledTimes(1) + const reply = worker.send.mock.calls[0][0] + expect(reply.type).toBe(AGG_METRICS_RES) + expect(reply.id).toBe(7) + // No cluster workers in the test process → prom-client aggregates to ''. + expect(typeof reply.body).toBe('string') + }) + + it('replies with an error when the cluster aggregation fails', async () => { + const clusterMetricsSpy = jest + .spyOn(AggregatorRegistry.prototype, 'clusterMetrics') + .mockRejectedValue(new Error('collection failed')) + const worker: any = { send: jest.fn() } + + await handleWorkerMetricsRequest(worker, { id: 3, type: AGG_METRICS_REQ }) + + expect(clusterMetricsSpy).toHaveBeenCalledTimes(1) + const reply = worker.send.mock.calls[0][0] + expect(reply.type).toBe(AGG_METRICS_RES) + expect(reply.id).toBe(3) + expect(reply.error).toBe('collection failed') + expect(reply.body).toBeUndefined() + + clusterMetricsSpy.mockRestore() + }) + }) +}) diff --git a/src/service/metrics/__tests__/requestHandlerLabel.test.ts b/src/service/metrics/__tests__/requestHandlerLabel.test.ts new file mode 100644 index 000000000..5a2d5e01c --- /dev/null +++ b/src/service/metrics/__tests__/requestHandlerLabel.test.ts @@ -0,0 +1,129 @@ +import { EventEmitter } from 'events' +import { AggregatorRegistry, register } from 'prom-client' + +import { requestHandlerLabel, UNNAMED_REQUEST_HANDLER } from '../requestHandlerLabel' +import { addRequestMetricsMiddleware } from '../requestMetricsMiddleware' + +// Node's cluster IPC serializes messages as JSON, which drops properties whose +// value is `undefined`. This is what the master receives from each worker. +const overClusterIpc = (payload: T): T => JSON.parse(JSON.stringify(payload)) + +const aggregatedMetrics = async (): Promise => { + const workerRegistryJson = overClusterIpc(await register.getMetricsAsJSON()) + return AggregatorRegistry.aggregate([workerRegistryJson]).metrics() +} + +// Minimal ServiceContext stand-in for addRequestMetricsMiddleware: it only needs +// `req`/`res` emitters and a `response` with `length` and `status`. +const buildCtx = (requestHandlerName?: string) => { + const res = new EventEmitter() + return { + req: new EventEmitter(), + requestHandlerName, + res, + response: { length: 128, status: 200 }, + } +} + +// Closing the response inside `next()` makes the middleware finish its timings +// synchronously, so no stream plumbing is needed. +const runRequest = async (middleware: any, ctx: any) => { + await middleware(ctx, async () => { + ctx.res.emit('close') + }) +} + +const samplesOf = (text: string, metric: string) => + text + .split('\n') + .filter((line) => line.startsWith(metric) && !line.startsWith('# ')) + +describe('requestHandlerLabel', () => { + it('falls back to "undefined" so the label is never empty or missing', () => { + expect(UNNAMED_REQUEST_HANDLER).toBe('undefined') + expect(requestHandlerLabel(undefined)).toBe(UNNAMED_REQUEST_HANDLER) + expect(requestHandlerLabel('')).toBe(UNNAMED_REQUEST_HANDLER) + }) + + it('keeps a named handler untouched', () => { + expect(requestHandlerLabel('private-handler:ssr')).toBe('private-handler:ssr') + }) +}) + +describe('addRequestMetricsMiddleware handler label', () => { + beforeEach(() => { + // The instruments register into the default registry on construction. + register.clear() + }) + + it('labels requests that never reached a named handler', async () => { + const middleware = addRequestMetricsMiddleware() + await runRequest(middleware, buildCtx(undefined)) + + const local = await register.metrics() + expect(samplesOf(local, 'runtime_http_requests_total')).toEqual([ + 'runtime_http_requests_total{handler="undefined",status_code="200"} 1', + ]) + }) + + // Regression: with `handler: undefined` the label key survived in-process but was + // dropped by the cluster IPC JSON serialization, so the aggregated /metrics + // exposed `runtime_http_requests_total{status_code="200"}` — a second, unnamed + // series (Prometheus reads an absent label as `handler=""`). + it('keeps the handler label through the cluster IPC round-trip', async () => { + const middleware = addRequestMetricsMiddleware() + await runRequest(middleware, buildCtx(undefined)) + + const aggregated = await aggregatedMetrics() + const samples = samplesOf(aggregated, 'runtime_http_requests_total') + + expect(samples).toEqual(['runtime_http_requests_total{handler="undefined",status_code="200"} 1']) + expect(aggregated).not.toContain('runtime_http_requests_total{status_code=') + }) + + it('emits no sample with a missing or empty handler label', async () => { + const middleware = addRequestMetricsMiddleware() + await runRequest(middleware, buildCtx(undefined)) + await runRequest(middleware, buildCtx('private-handler:ssr')) + + const aggregated = await aggregatedMetrics() + const handlerLabelledMetrics = [ + 'runtime_http_requests_total', + 'runtime_http_requests_duration_milliseconds', + 'runtime_http_response_size_bytes', + ] + + handlerLabelledMetrics.forEach((metric) => { + samplesOf(aggregated, metric).forEach((sample) => { + expect(sample).toMatch(/handler="[^"]+"/) + }) + }) + }) + + it('reports named and unnamed handlers as separate series', async () => { + const middleware = addRequestMetricsMiddleware() + await runRequest(middleware, buildCtx('private-handler:ssr')) + await runRequest(middleware, buildCtx(undefined)) + + const aggregated = await aggregatedMetrics() + expect(samplesOf(aggregated, 'runtime_http_requests_total').sort()).toEqual([ + 'runtime_http_requests_total{handler="private-handler:ssr",status_code="200"} 1', + 'runtime_http_requests_total{handler="undefined",status_code="200"} 1', + ]) + }) + + it('labels aborted requests that never reached a named handler', async () => { + const middleware = addRequestMetricsMiddleware() + const ctx: any = buildCtx(undefined) + + await middleware(ctx, async () => { + ctx.req.emit('aborted') + ctx.res.emit('close') + }) + + const aggregated = await aggregatedMetrics() + expect(samplesOf(aggregated, 'runtime_http_aborted_requests_total')).toEqual([ + 'runtime_http_aborted_requests_total{handler="undefined"} 1', + ]) + }) +}) diff --git a/src/service/metrics/clusterMetricsAggregator.ts b/src/service/metrics/clusterMetricsAggregator.ts new file mode 100644 index 000000000..aadd9257d --- /dev/null +++ b/src/service/metrics/clusterMetricsAggregator.ts @@ -0,0 +1,211 @@ +import { Worker } from 'cluster' +import { AggregatorRegistry, register } from 'prom-client' + +import { logger } from '../worker/listeners' + +/** + * Cluster-wide Prometheus metrics aggregation. + * + * In multi-worker mode each cluster worker keeps its own prom-client default + * registry. Serving `/metrics` from a single (round-robin selected) worker + * therefore exposes only that worker's local counters, which makes Prometheus + * treat the per-scrape braid of independent counters as counter resets and + * inflates `rate()`/`increase()` by orders of magnitude. + * + * This module uses prom-client's `AggregatorRegistry` cluster IPC protocol so + * that the worker answering a scrape asks the master for a merged, monotonic + * view built from every worker's registry in one pass (no double-counting of + * the answering worker). + */ + +/** Tagged IPC message: worker -> master, "please build the cluster aggregate". */ +export const AGG_METRICS_REQ = 'vtex-api:aggMetricsReq' +/** Tagged IPC message: master -> worker, carries the aggregate (or an error). */ +export const AGG_METRICS_RES = 'vtex-api:aggMetricsRes' + +/** + * Upper bound for a worker waiting on the master aggregate. prom-client's own + * `clusterMetrics()` has a 5s timeout collecting worker registries; we guard + * slightly above that and fall back to the local registry on expiry so that + * `/metrics` never hangs or returns empty. + */ +const AGG_METRICS_TIMEOUT_MS = 6000 + +export interface AggMetricsReqMessage { + type: typeof AGG_METRICS_REQ + id: number +} + +export interface AggMetricsResMessage { + type: typeof AGG_METRICS_RES + id: number + body?: string + error?: string +} + +export const isAggMetricsRequest = (message: any): message is AggMetricsReqMessage => + message?.type === AGG_METRICS_REQ && typeof message?.id === 'number' + +export const isAggMetricsResponse = (message: any): message is AggMetricsResMessage => + message?.type === AGG_METRICS_RES && typeof message?.id === 'number' + +/** + * prom-client's cluster protocol emits its own tagged IPC messages + * (`prom-client:getMetricsReq` / `prom-client:getMetricsRes`). They are handled + * by prom-client's own cluster listeners, so our `onMessage` handlers must + * ignore them instead of warning about "unknown" messages. + */ +export const isPromClientMessage = (message: any): boolean => + typeof message?.type === 'string' && message.type.startsWith('prom-client:') + +// --------------------------------------------------------------------------- +// Master side +// --------------------------------------------------------------------------- + +let masterAggregatorRegistry: AggregatorRegistry | undefined + +/** + * Constructs the master-side `AggregatorRegistry` (idempotent). Its constructor + * installs prom-client's master `cluster.on('message')` collector, which is + * what makes `clusterMetrics()` work. Must be called in the master before any + * worker can answer a scrape. + */ +export const initMasterAggregatorRegistry = (): AggregatorRegistry => { + if (!masterAggregatorRegistry) { + masterAggregatorRegistry = new AggregatorRegistry() + } + return masterAggregatorRegistry +} + +/** + * Handles an `AGG_METRICS_REQ` from a worker: builds the cluster aggregate and + * replies to that worker only. prom-client fans the request out to *all* + * connected workers (including the requester), so the requester is one of the N + * merged sources and is never double-counted. + */ +export const handleWorkerMetricsRequest = async (worker: Worker, message: AggMetricsReqMessage): Promise => { + const aggregator = initMasterAggregatorRegistry() + let response: AggMetricsResMessage + try { + const body = await aggregator.clusterMetrics() + response = { type: AGG_METRICS_RES, id: message.id, body } + } catch (err) { + response = { type: AGG_METRICS_RES, id: message.id, error: (err as Error)?.message ?? String(err) } + } + + // `worker.send` can throw (e.g. the worker disconnected between the request + // and the reply). This handler is invoked without `await` from the master's + // message listener, so a thrown send would surface as an unhandled rejection + // in the master process. Swallow and log it instead. + try { + worker.send(response) + } catch (err) { + logger.warn({ + content: (err as Error)?.message ?? String(err), + message: 'Failed to send aggregated cluster metrics to worker', + pid: process.pid, + workerId: worker.id, + }) + } +} + +// --------------------------------------------------------------------------- +// Worker side +// --------------------------------------------------------------------------- + +let workerAggregatorRegistry: AggregatorRegistry | undefined + +interface PendingRequest { + resolve: (body: string) => void + timer: NodeJS.Timeout +} + +const pendingRequests = new Map() +let requestCounter = 0 + +/** + * Constructs the worker-side `AggregatorRegistry` (idempotent). Its constructor + * installs prom-client's worker `process.on('message')` responder that answers + * the master's `getMetricsReq` with this worker's registry JSON. + */ +export const ensureWorkerAggregatorRegistry = (): AggregatorRegistry => { + if (!workerAggregatorRegistry) { + workerAggregatorRegistry = new AggregatorRegistry() + } + return workerAggregatorRegistry +} + +/** + * Requests the cluster aggregate from the master over IPC and resolves with the + * merged exposition string. On timeout or any error it falls back to this + * worker's local `register.metrics()` so `/metrics` always answers promptly. + */ +export const requestAggregatedMetrics = async (): Promise => { + if (typeof process.send !== 'function') { + return register.metrics() + } + + const id = requestCounter++ + + return new Promise((resolve) => { + const timer = setTimeout(() => { + pendingRequests.delete(id) + logger.warn({ + message: 'Timed out waiting for aggregated cluster metrics; falling back to local registry', + pid: process.pid, + }) + register.metrics().then(resolve).catch(() => resolve('')) + }, AGG_METRICS_TIMEOUT_MS) + + pendingRequests.set(id, { resolve, timer }) + + try { + process.send!({ type: AGG_METRICS_REQ, id }) + } catch (err) { + clearTimeout(timer) + pendingRequests.delete(id) + logger.warn({ + content: (err as Error)?.message ?? String(err), + message: 'Failed to request aggregated cluster metrics; falling back to local registry', + pid: process.pid, + }) + register.metrics().then(resolve).catch(() => resolve('')) + } + }) +} + +/** + * Resolves the pending `requestAggregatedMetrics` promise correlated by id when + * the master replies. On error it falls back to the local registry. + */ +export const handleMasterMetricsResponse = (message: AggMetricsResMessage): void => { + const pending = pendingRequests.get(message.id) + if (!pending) { + return + } + + pendingRequests.delete(message.id) + clearTimeout(pending.timer) + + if (message.error != null || message.body == null) { + logger.warn({ + content: message.error, + message: 'Master failed to aggregate cluster metrics; falling back to local registry', + pid: process.pid, + }) + register.metrics().then(pending.resolve).catch(() => pending.resolve('')) + return + } + + pending.resolve(message.body) +} + +/** Test-only helper to reset module state between test cases. */ +// tslint:disable-next-line:variable-name +export const __resetForTests = () => { + masterAggregatorRegistry = undefined + workerAggregatorRegistry = undefined + pendingRequests.forEach((p) => clearTimeout(p.timer)) + pendingRequests.clear() + requestCounter = 0 +} diff --git a/src/service/metrics/requestHandlerLabel.ts b/src/service/metrics/requestHandlerLabel.ts new file mode 100644 index 000000000..b3baba733 --- /dev/null +++ b/src/service/metrics/requestHandlerLabel.ts @@ -0,0 +1,28 @@ +/** + * Label value reported for requests that never reached a named handler: unmatched + * paths (Koa answers its default 404), requests rejected before the route pipeline + * (replica-level rate limiter, errors in compress/recorder), and handlers that + * don't set `ctx.requestHandlerName`. + * + * The value must be a non-empty string. `ctx.requestHandlerName` is `undefined` + * for those requests, and Node's cluster IPC serializes each worker's registry as + * JSON, which drops properties whose value is `undefined`. The sample then reaches + * the aggregated `/metrics` with the `handler` label missing altogether, which + * Prometheus reads as `handler=""` — a distinct, unnamed series that shows up as + * an extra "Value" line in dashboards. + * + * `'undefined'` is deliberate rather than a nicer word: prom-client's local + * exposition already rendered `handler: undefined` as `handler="undefined"` before + * the cluster aggregation was introduced, so keeping that value makes the + * aggregated output match the historical series identity and keeps existing + * dashboards, filters and alerts (e.g. `handler!~"builtin:.*|undefined"`) working. + */ +export const UNNAMED_REQUEST_HANDLER = 'undefined' + +/** + * Resolves the `handler` label value for a request, falling back to + * {@link UNNAMED_REQUEST_HANDLER} when the pipeline never named the handler. + * Empty strings fall back too, so the label is never emitted empty. + */ +export const requestHandlerLabel = (requestHandlerName?: string): string => + requestHandlerName || UNNAMED_REQUEST_HANDLER diff --git a/src/service/metrics/requestMetricsMiddleware.ts b/src/service/metrics/requestMetricsMiddleware.ts index 7a333e33a..aa197db6d 100644 --- a/src/service/metrics/requestMetricsMiddleware.ts +++ b/src/service/metrics/requestMetricsMiddleware.ts @@ -9,6 +9,7 @@ import { RequestsMetricLabels, } from '../tracing/metrics/instruments' import { ServiceContext } from '../worker/runtime/typings' +import { requestHandlerLabel } from './requestHandlerLabel' export const addRequestMetricsMiddleware = () => { @@ -23,7 +24,7 @@ export const addRequestMetricsMiddleware = () => { concurrentRequests.inc(1) ctx.req.once('aborted', () => - abortedRequests.inc({ [RequestsMetricLabels.REQUEST_HANDLER]: ctx.requestHandlerName }, 1) + abortedRequests.inc({ [RequestsMetricLabels.REQUEST_HANDLER]: requestHandlerLabel(ctx.requestHandlerName) }, 1) ) let responseClosed = false @@ -35,14 +36,14 @@ export const addRequestMetricsMiddleware = () => { const responseLength = ctx.response.length if (responseLength) { responseSizes.observe( - { [RequestsMetricLabels.REQUEST_HANDLER]: ctx.requestHandlerName }, + { [RequestsMetricLabels.REQUEST_HANDLER]: requestHandlerLabel(ctx.requestHandlerName) }, responseLength ) } totalRequests.inc( { - [RequestsMetricLabels.REQUEST_HANDLER]: ctx.requestHandlerName, + [RequestsMetricLabels.REQUEST_HANDLER]: requestHandlerLabel(ctx.requestHandlerName), [RequestsMetricLabels.STATUS_CODE]: ctx.response.status, }, 1 @@ -51,7 +52,7 @@ export const addRequestMetricsMiddleware = () => { const onResFinished = () => { requestTimings.observe( { - [RequestsMetricLabels.REQUEST_HANDLER]: ctx.requestHandlerName, + [RequestsMetricLabels.REQUEST_HANDLER]: requestHandlerLabel(ctx.requestHandlerName), }, hrToMillisFloat(process.hrtime(start)) ) diff --git a/src/service/worker/__tests__/onMessage.test.ts b/src/service/worker/__tests__/onMessage.test.ts new file mode 100644 index 000000000..33621afb5 --- /dev/null +++ b/src/service/worker/__tests__/onMessage.test.ts @@ -0,0 +1,28 @@ +import * as aggregator from '../../metrics/clusterMetricsAggregator' +import { AGG_METRICS_RES } from '../../metrics/clusterMetricsAggregator' +import { onMessage } from '../index' + +describe('worker onMessage', () => { + const handle = onMessage({} as any) + + afterEach(() => { + jest.restoreAllMocks() + }) + + it('routes aggregate metric responses from the master to the aggregation handler', () => { + const spy = jest.spyOn(aggregator, 'handleMasterMetricsResponse').mockReturnValue(undefined) + const message = { body: 'AGGREGATED', id: 1, type: AGG_METRICS_RES } + + handle(message) + + expect(spy).toHaveBeenCalledTimes(1) + expect(spy).toHaveBeenCalledWith(message) + }) + + it('ignores prom-client cluster protocol messages without invoking the handler', () => { + const spy = jest.spyOn(aggregator, 'handleMasterMetricsResponse') + + expect(() => handle({ type: 'prom-client:getMetricsRes' })).not.toThrow() + expect(spy).not.toHaveBeenCalled() + }) +}) diff --git a/src/service/worker/index.ts b/src/service/worker/index.ts index 420e10ff1..c31c28b7f 100644 --- a/src/service/worker/index.ts +++ b/src/service/worker/index.ts @@ -12,6 +12,12 @@ import { MetricsAccumulator } from '../../metrics/MetricsAccumulator' import { getService } from '../loaders' import { logOnceToDevConsole } from '../logger/console' import { LogLevel } from '../logger/loggerTypes' +import { + ensureWorkerAggregatorRegistry, + handleMasterMetricsResponse, + isAggMetricsResponse, + isPromClientMessage, +} from '../metrics/clusterMetricsAggregator' import { addRequestMetricsMiddleware } from '../metrics/requestMetricsMiddleware' import { TracerSingleton } from '../tracing/TracerSingleton' import { addTracingMiddleware } from '../tracing/tracingMiddlewares' @@ -70,13 +76,17 @@ const upSignal = () => { const isUpSignal = (message: any): message is typeof UP_SIGNAL => message === UP_SIGNAL -const onMessage = (service: ServiceJSON) => (message: any) => { +export const onMessage = (service: ServiceJSON) => (message: any) => { if (isUpSignal(message)) { upSignal() logAvailableRoutes(service) } else if (isStatusTrack(message)) { trackStatus() - } else { + } else if (isAggMetricsResponse(message)) { + handleMasterMetricsResponse(message) + } else if (!isPromClientMessage(message)) { + // prom-client's own cluster messages are handled by its worker listener; + // anything else that reaches here is genuinely unexpected. logger.warn({ content: message, message: 'Master sent message', @@ -216,11 +226,18 @@ export const startWorker = (serviceJSON: ServiceJSON) => { addProcessListeners() const tracer = TracerSingleton.getTracer() + + // In multi-worker mode install prom-client's worker-side cluster responder so + // the master can collect this worker's registry for the aggregated /metrics. + if (serviceJSON.workers > 1) { + ensureWorkerAggregatorRegistry() + } + const app = new Koa() app.proxy = true app .use(error) - .use(prometheusLoggerMiddleware()) + .use(prometheusLoggerMiddleware(serviceJSON.workers)) .use(addTracingMiddleware(tracer)) .use(addRequestMetricsMiddleware()) .use(addMetricsLoggerMiddleware()) diff --git a/src/service/worker/runtime/__tests__/statusTrack.test.ts b/src/service/worker/runtime/__tests__/statusTrack.test.ts new file mode 100644 index 000000000..d249c3a8f --- /dev/null +++ b/src/service/worker/runtime/__tests__/statusTrack.test.ts @@ -0,0 +1,29 @@ +import { statusTrackHandler } from '../statusTrack' +import { ServiceContext } from '../typings' + +describe('statusTrackHandler', () => { + // /_status is served by a handler that answers 200, so its samples must carry a + // handler label like every other builtin (healthcheck, whoami, metrics-logger) + // instead of landing in the catch-all `handler="undefined"` bucket. + it('names the request so metrics are not reported as unnamed', async () => { + const setOperationName = jest.fn() + const ctx: any = { + body: undefined, + tracing: { currentSpan: { setOperationName } }, + } + + await statusTrackHandler(ctx as ServiceContext) + + expect(ctx.requestHandlerName).toBe('builtin:status-track') + expect(setOperationName).toHaveBeenCalledWith('builtin:status-track') + expect(ctx.body).toEqual([]) + }) + + it('works when tracing is disabled for the path', async () => { + const ctx: any = { body: undefined, tracing: undefined } + + await statusTrackHandler(ctx as ServiceContext) + + expect(ctx.requestHandlerName).toBe('builtin:status-track') + }) +}) diff --git a/src/service/worker/runtime/builtIn/__tests__/middlewares.test.ts b/src/service/worker/runtime/builtIn/__tests__/middlewares.test.ts new file mode 100644 index 000000000..f8208a37e --- /dev/null +++ b/src/service/worker/runtime/builtIn/__tests__/middlewares.test.ts @@ -0,0 +1,98 @@ +import { register } from 'prom-client' + +import * as clusterMetricsAggregator from '../../../../metrics/clusterMetricsAggregator' +import { prometheusLoggerMiddleware } from '../middlewares' + +const buildCtx = (path: string, headers: Record = {}) => { + const setHeaders: Record = {} + return { + body: undefined as any, + get: (key: string) => headers[key] ?? '', + request: { path }, + set: (key: string, value: string) => { + setHeaders[key] = value + }, + setHeaders, + status: undefined as any, + } +} + +describe('prometheusLoggerMiddleware', () => { + beforeEach(() => { + // collectDefaultMetrics() and the lag measurer register into the default + // registry on every middleware construction; clear it between cases. + register.clear() + }) + + afterEach(() => { + jest.restoreAllMocks() + }) + + // AC3: workers=1 (LINKED) serves the default registry content unchanged. + it('serves the local default registry in single-worker mode without IPC', async () => { + const sendSpy = jest.fn() + ;(process as any).send = sendSpy + const aggSpy = jest.spyOn(clusterMetricsAggregator, 'requestAggregatedMetrics') + const localMetricsSpy = jest.spyOn(register, 'metrics').mockResolvedValue('LOCAL_REGISTRY') + + const middleware = prometheusLoggerMiddleware(1) + const ctx: any = buildCtx('/metrics') + const next = jest.fn() + + await middleware(ctx, next) + + expect(localMetricsSpy).toHaveBeenCalledTimes(1) + expect(ctx.body).toBe('LOCAL_REGISTRY') + expect(ctx.status).toBe(200) + expect(ctx.setHeaders['Content-Type']).toBe(register.contentType) + expect(aggSpy).not.toHaveBeenCalled() + expect(sendSpy).not.toHaveBeenCalled() + expect(next).not.toHaveBeenCalled() + + delete (process as any).send + }) + + // AC4: default process metrics are present in the single-worker output. + it('includes default process metrics in single-worker output', async () => { + const middleware = prometheusLoggerMiddleware(1) + const ctx: any = buildCtx('/metrics') + await middleware(ctx, () => Promise.resolve()) + expect(ctx.body).toContain('process_cpu_seconds_total') + }) + + it('requests the cluster aggregate in multi-worker mode', async () => { + const aggSpy = jest + .spyOn(clusterMetricsAggregator, 'requestAggregatedMetrics') + .mockResolvedValue('AGGREGATED') + + const middleware = prometheusLoggerMiddleware(4) + const ctx: any = buildCtx('/metrics') + + await middleware(ctx, () => Promise.resolve()) + + expect(aggSpy).toHaveBeenCalledTimes(1) + expect(ctx.body).toBe('AGGREGATED') + expect(ctx.status).toBe(200) + expect(ctx.setHeaders['Content-Type']).toBe(register.contentType) + }) + + it('does not count /metrics scrapes and passes through other routes', async () => { + const aggSpy = jest.spyOn(clusterMetricsAggregator, 'requestAggregatedMetrics') + const middleware = prometheusLoggerMiddleware(4) + + const nonMetricsCtx: any = buildCtx('/some-route') + const next1 = jest.fn().mockResolvedValue(undefined) + await middleware(nonMetricsCtx, next1) + expect(next1).toHaveBeenCalledTimes(1) + expect(nonMetricsCtx.body).toBeUndefined() + + // Requests carrying a colossus route id must pass through, not be answered. + const routedCtx: any = buildCtx('/metrics', { 'x-colossus-route-id': 'my-route' }) + const next2 = jest.fn().mockResolvedValue(undefined) + await middleware(routedCtx, next2) + expect(next2).toHaveBeenCalledTimes(1) + expect(routedCtx.body).toBeUndefined() + + expect(aggSpy).not.toHaveBeenCalled() + }) +}) diff --git a/src/service/worker/runtime/builtIn/middlewares.ts b/src/service/worker/runtime/builtIn/middlewares.ts index a9ce9b055..342a5a836 100644 --- a/src/service/worker/runtime/builtIn/middlewares.ts +++ b/src/service/worker/runtime/builtIn/middlewares.ts @@ -2,6 +2,7 @@ import { collectDefaultMetrics, register } from 'prom-client' import { COLOSSUS_ROUTE_ID_HEADER } from '../../../../constants' import { MetricsLogger } from '../../../logger/metricsLogger' +import { requestAggregatedMetrics } from '../../../metrics/clusterMetricsAggregator' import { EventLoopLagMeasurer } from '../../../tracing/metrics/measurers/EventLoopLagMeasurer' import { ServiceContext } from '../typings' import { Recorder } from '../utils/recorder' @@ -22,11 +23,16 @@ export const addMetricsLoggerMiddleware = () => { } } -export const prometheusLoggerMiddleware = () => { +export const prometheusLoggerMiddleware = (workers = 1) => { collectDefaultMetrics() const eventLoopLagMeasurer = new EventLoopLagMeasurer() eventLoopLagMeasurer.start() + // In multi-worker mode each worker holds only its own registry, so /metrics + // must serve the cluster-wide aggregate requested from the master over IPC. + // In single-worker mode (LINKED / workers:1) the local registry is complete. + const isMultiWorker = workers > 1 + return async (ctx: ServiceContext, next: () => Promise) => { if (ctx.request.path !== '/metrics') { return next() @@ -39,7 +45,7 @@ export const prometheusLoggerMiddleware = () => { await eventLoopLagMeasurer.updateInstrumentsAndReset() ctx.set('Content-Type', register.contentType) - ctx.body = await register.metrics() + ctx.body = isMultiWorker ? await requestAggregatedMetrics() : await register.metrics() ctx.status = 200 } } diff --git a/src/service/worker/runtime/statusTrack.ts b/src/service/worker/runtime/statusTrack.ts index 60ea53752..fa51cf8e1 100644 --- a/src/service/worker/runtime/statusTrack.ts +++ b/src/service/worker/runtime/statusTrack.ts @@ -24,7 +24,10 @@ export const isStatusTrackBroadcast = (message: any): message is typeof BROADCAS message === BROADCAST_STATUS_TRACK export const statusTrackHandler = async (ctx: ServiceContext) => { - ctx.tracing?.currentSpan?.setOperationName('builtin:status-track') + // Parity with the other builtin handlers: name the request so its samples don't + // land in the catch-all `handler="undefined"` bucket. + ctx.requestHandlerName = 'builtin:status-track' + ctx.tracing?.currentSpan?.setOperationName(ctx.requestHandlerName) if (!LINKED) { process.send?.(BROADCAST_STATUS_TRACK) }