From 729b14e676875b4dc65e3f51d0eebf68d8ab9fd3 Mon Sep 17 00:00:00 2001 From: Denis Silva Date: Mon, 3 Aug 2026 14:39:10 -0300 Subject: [PATCH 1/3] fix(metrics): always label requests with a handler MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Requests that never reach a named handler (unmatched paths answered by Koa's default 404, rejections by the replica-level rate limiter, errors thrown before the route pipeline) were counted with `handler: undefined`, because `ctx.requestHandlerName` is only assigned inside a route pipeline while addRequestMetricsMiddleware counts every request in a `finally` block. prom-client keeps the label key in memory, so the local exposition rendered it as `handler="undefined"`. Node's cluster IPC serializes each worker's registry as JSON, and JSON.stringify drops properties whose value is `undefined`, so once /metrics started serving the cluster aggregate those samples arrived at the master without the `handler` key at all. Prometheus reads an absent label as `handler=""`, producing a second, unnamed series that dashboards render as a nameless "Value" line and that filters such as `handler!~"builtin:.*|undefined"` no longer exclude. Resolve the label through a single helper that falls back to `"undefined"` — the value prom-client already rendered locally — so the aggregated output keeps the historical series identity and existing dashboards and alerts keep working. The same fallback is applied to the OpenTelemetry request instruments. The aggregation tests now round-trip worker registries through JSON, reproducing what the master really receives; without the fallback five of the new cases fail. --- .../clusterMetricsAggregator.test.ts | 8 +- .../__tests__/requestHandlerLabel.test.ts | 129 ++++++++++++++++++ .../metrics/otelRequestMetricsMiddleware.ts | 11 +- src/service/metrics/requestHandlerLabel.ts | 28 ++++ .../metrics/requestMetricsMiddleware.ts | 9 +- 5 files changed, 176 insertions(+), 9 deletions(-) create mode 100644 src/service/metrics/__tests__/requestHandlerLabel.test.ts create mode 100644 src/service/metrics/requestHandlerLabel.ts diff --git a/src/service/metrics/__tests__/clusterMetricsAggregator.test.ts b/src/service/metrics/__tests__/clusterMetricsAggregator.test.ts index b20c51163..7b08fcc8d 100644 --- a/src/service/metrics/__tests__/clusterMetricsAggregator.test.ts +++ b/src/service/metrics/__tests__/clusterMetricsAggregator.test.ts @@ -47,8 +47,14 @@ const parseSeries = (text: string, metric: string): Record => { 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: Array): Promise => { - const jsons = await Promise.all(registries.map((r) => r.getMetricsAsJSON())) + const jsons = await Promise.all(registries.map(async (r) => overClusterIpc(await r.getMetricsAsJSON()))) const merged = AggregatorRegistry.aggregate(jsons) return merged.metrics() } 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/otelRequestMetricsMiddleware.ts b/src/service/metrics/otelRequestMetricsMiddleware.ts index 8db771841..779ca2815 100644 --- a/src/service/metrics/otelRequestMetricsMiddleware.ts +++ b/src/service/metrics/otelRequestMetricsMiddleware.ts @@ -2,6 +2,7 @@ import { finished as onStreamFinished } from 'stream' import { hrToMillisFloat } from '../../utils' import { ServiceContext } from '../worker/runtime/typings' import { getOtelInstruments, OtelRequestInstruments, RequestsMetricLabels } from './metrics' +import { requestHandlerLabel } from './requestHandlerLabel' const INSTRUMENTS_INITIALIZATION_TIMEOUT = 500 @@ -38,7 +39,9 @@ export const addOtelRequestMetricsMiddleware = () => { ctx.req.once('aborted', () => { if (instruments) { - instruments.abortedRequests.add(1, { [RequestsMetricLabels.REQUEST_HANDLER]: ctx.requestHandlerName }) + instruments.abortedRequests.add(1, { + [RequestsMetricLabels.REQUEST_HANDLER]: requestHandlerLabel(ctx.requestHandlerName), + }) } }) @@ -53,7 +56,7 @@ export const addOtelRequestMetricsMiddleware = () => { instruments.responseSizes.record( responseLength, { - [RequestsMetricLabels.REQUEST_HANDLER]: ctx.requestHandlerName, + [RequestsMetricLabels.REQUEST_HANDLER]: requestHandlerLabel(ctx.requestHandlerName), [RequestsMetricLabels.STATUS_CODE]: ctx.response.status, [RequestsMetricLabels.ACCOUNT_NAME]: ctx.vtex?.account || 'unknown', } @@ -64,7 +67,7 @@ export const addOtelRequestMetricsMiddleware = () => { instruments.totalRequests.add( 1, { - [RequestsMetricLabels.REQUEST_HANDLER]: ctx.requestHandlerName, + [RequestsMetricLabels.REQUEST_HANDLER]: requestHandlerLabel(ctx.requestHandlerName), [RequestsMetricLabels.STATUS_CODE]: ctx.response.status, [RequestsMetricLabels.ACCOUNT_NAME]: ctx.vtex?.account || 'unknown', } @@ -76,7 +79,7 @@ export const addOtelRequestMetricsMiddleware = () => { instruments.requestTimings.record( hrToMillisFloat(process.hrtime(start)), { - [RequestsMetricLabels.REQUEST_HANDLER]: ctx.requestHandlerName, + [RequestsMetricLabels.REQUEST_HANDLER]: requestHandlerLabel(ctx.requestHandlerName), [RequestsMetricLabels.STATUS_CODE]: ctx.response.status, [RequestsMetricLabels.ACCOUNT_NAME]: ctx.vtex?.account || 'unknown', } 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)) ) From ee897b2b7dfbedea4991b298833bb67534cbe920 Mon Sep 17 00:00:00 2001 From: Denis Silva Date: Mon, 3 Aug 2026 14:39:18 -0300 Subject: [PATCH 2/3] fix(metrics): report /_status as builtin:status-track MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit statusTrackHandler answers 200 (it assigns `ctx.body`), so its requests do reach a handler — it just never set `ctx.requestHandlerName`, unlike healthcheck, whoami and metrics-logger, which set both the request handler name and the span operation name. Its samples therefore landed in the catch-all unnamed bucket. Set `ctx.requestHandlerName` for parity, which also makes the existing setOperationName call meaningful for callers that keep tracing enabled (/_status is in PATHS_BLACKLISTED_FOR_TRACING, so the span is usually absent). --- .../runtime/__tests__/statusTrack.test.ts | 29 +++++++++++++++++++ src/service/worker/runtime/statusTrack.ts | 5 +++- 2 files changed, 33 insertions(+), 1 deletion(-) create mode 100644 src/service/worker/runtime/__tests__/statusTrack.test.ts 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/statusTrack.ts b/src/service/worker/runtime/statusTrack.ts index 34e1caf2b..84420c6fa 100644 --- a/src/service/worker/runtime/statusTrack.ts +++ b/src/service/worker/runtime/statusTrack.ts @@ -25,7 +25,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) } From 95810664016008f083b35866c4f05245380f454d Mon Sep 17 00:00:00 2001 From: Denis Silva Date: Mon, 3 Aug 2026 14:39:19 -0300 Subject: [PATCH 3/3] chore(changelog): document handler label fixes --- CHANGELOG.md | 11 +++++++++++ 1 file changed, 11 insertions(+) diff --git a/CHANGELOG.md b/CHANGELOG.md index 8b1424a45..b3dd77789 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -6,6 +6,17 @@ The format is based on [Keep a Changelog](http://keepachangelog.com/en/1.0.0/) and this project adheres to [Semantic Versioning](http://semver.org/spec/v2.0.0.html). ## [Unreleased] +### 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. +- `/_status` requests are now reported as `handler="builtin:status-track"`, matching + the other builtin handlers, instead of falling into the unnamed bucket. ## [7.4.0] - 2026-06-22 ### Changed