Skip to content

Commit 0cb5ab7

Browse files
metrics plugin: healthz + Prometheus exporter, and the hook-scope answer
Process gauges, CPU counters, event-loop lag, and per-route request counters fed by an onResponse hook on api.fastify — whose scope was measured empirically: the hook fires for EVERY plugin's routes (all loader entries share one Fastify register scope, both entry orders proven) and NEVER for core routes (encapsulation shields the parent). So the core/plugin line holds against core, but plugins are not isolated from each other — api.fastify already grants cross-plugin observation and interception with no capability gate. Bonus core bug: logger:false makes core's access-log hook throw per-request (request.log.isLevelEnabled missing on the null logger), silently killing every downstream plugin onResponse hook. /metrics optionally Bearer-guarded (timing-safe); healthz degrades gracefully without loopbackUrl.
1 parent a2d3288 commit 0cb5ab7

4 files changed

Lines changed: 374 additions & 0 deletions

File tree

metrics/README.md

Lines changed: 168 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,168 @@
1+
# metrics — healthz + Prometheus exporter
2+
3+
Ops observability for a JSS deployment, from node builtins only: a
4+
liveness/readiness endpoint (`/healthz`) and a Prometheus text-format
5+
exporter (`/metrics`). No dependencies, no internals — the exposition
6+
format is hand-rolled (`# HELP`/`# TYPE` + `name{labels} value` is all
7+
there is to it).
8+
9+
## Usage
10+
11+
```js
12+
import { createServer } from 'javascript-solid-server/src/server.js';
13+
14+
const fastify = createServer({
15+
root: './data',
16+
plugins: [{
17+
id: 'metrics',
18+
module: './plugins/metrics/plugin.js',
19+
prefix: '/metrics',
20+
config: {
21+
loopbackUrl: 'http://127.0.0.1:3000', // optional: adds a front-door check to healthz
22+
token: 'long-random-string', // optional: Bearer-guards /metrics/metrics
23+
},
24+
}],
25+
});
26+
await fastify.listen({ port: 3000 });
27+
```
28+
29+
**Both config keys are optional** — a deliberate contrast with the plugins
30+
that `throw` on missing config. Without `loopbackUrl` the plugin degrades
31+
gracefully: `/healthz` still answers 200 and reports process liveness, it
32+
just can't vouch for the host's HTTP pipeline. (With `api.serverInfo` the
33+
knob would disappear entirely — the plugin would always know where its own
34+
host lives. See Findings.)
35+
36+
```console
37+
$ curl -s http://localhost:3000/metrics/healthz | jq
38+
{
39+
"status": "ok",
40+
"uptime_seconds": 42.1,
41+
"checks": {
42+
"process": { "ok": true, "pid": 12345 },
43+
"loopback": { "ok": true, "status": 200 }
44+
}
45+
}
46+
47+
$ curl -s -H 'Authorization: Bearer long-random-string' http://localhost:3000/metrics/metrics
48+
# HELP process_uptime_seconds Node.js process uptime in seconds.
49+
# TYPE process_uptime_seconds gauge
50+
process_uptime_seconds 42.1
51+
...
52+
jss_plugin_http_requests_total{method="GET",route="/metrics/healthz",status="200"} 3
53+
```
54+
55+
Prometheus scrape config:
56+
57+
```yaml
58+
scrape_configs:
59+
- job_name: jss
60+
metrics_path: /metrics/metrics
61+
authorization:
62+
type: Bearer
63+
credentials: long-random-string
64+
static_configs:
65+
- targets: ['localhost:3000']
66+
```
67+
68+
### Endpoints
69+
70+
| route | auth | behavior |
71+
|---|---|---|
72+
| `GET <prefix>/healthz` | always open | `{ status, uptime_seconds, checks }`. With `loopbackUrl`: HEAD-probes the host's `/` over loopback (any non-5xx counts as alive — 401/403/404 are policy, not sickness; no credentials forwarded). Probe failure → `status: "degraded"` + HTTP 503, so it works directly as a k8s readinessProbe / LB health check. |
73+
| `GET <prefix>/metrics` | Bearer iff `config.token` | `text/plain; version=0.0.4` exposition. Token compared constant-time (`timingSafeEqual` over sha256 digests). healthz stays open even with a token set — orchestrators can't send headers easily; scrapers can. |
74+
75+
### Metrics exposed
76+
77+
- `process_uptime_seconds`, `process_resident_memory_bytes`,
78+
`process_heap_used_bytes`, `process_heap_total_bytes` (gauges,
79+
`process.memoryUsage()`)
80+
- `process_cpu_user_seconds_total`, `process_cpu_system_seconds_total`
81+
(counters, `process.cpuUsage()`)
82+
- `nodejs_eventloop_lag_seconds` (gauge — `perf_hooks.monitorEventLoopDelay`
83+
mean since the previous scrape, reset per scrape; the sampler is disabled
84+
in `deactivate` so the process exits cleanly)
85+
- `jss_plugin_http_requests_total{method,route,status}` and
86+
`jss_plugin_http_request_duration_seconds` (summary: `_sum`/`_count`) —
87+
counted via an `onResponse` hook on `api.fastify`. **Scope: every route
88+
registered by any plugin in the loader — not core's routes.** The metric
89+
names say `jss_plugin_`, not `jss_http_`, because that is what they
90+
honestly are (the headline finding below). The `route` label is the
91+
registered route pattern, not the raw URL, and a `MAX_SERIES` cap lumps
92+
overflow into `route="_other"`, so cardinality stays bounded.
93+
94+
## What maps / what doesn't
95+
96+
| aspect | status |
97+
|---|---|
98+
| liveness/readiness JSON | ✅ trivially, plugin-owned route |
99+
| host front-door check | ✅ loopback HEAD (the notifications/ pattern, minus auth forwarding) |
100+
| process/runtime metrics | ✅ all from node builtins |
101+
| per-request metrics for **plugin** routes (all plugins) | ✅ `onResponse` hook on `api.fastify` — measured, see Findings |
102+
| per-request metrics for **core** routes (LDP, idp, `.well-known`) | ❌ invisible to plugin hooks — a whole-server exporter is not buildable out-of-tree today |
103+
| LDP-level metrics (pod count, storage bytes, quota) | ❌ no api surface at all (no data-root access, no storage events) — not attempted |
104+
105+
## Findings
106+
107+
1. **Hook scope on `api.fastify` — measured, and it's "all plugins, no
108+
core".** The experiment this plugin exists for: an
109+
`addHook('onResponse')` on the loader's scoped Fastify instance fires
110+
for **(a) this plugin's routes — yes; (b) every OTHER plugin's routes —
111+
yes, regardless of entry order; (c) core routes — never** (the UI root
112+
`/`, LDP pod paths, `/.well-known/*` produce no counter series;
113+
`test.js` asserts all three). Cause, from reading the loader:
114+
`loadPlugins(instance, entries, …)` activates **all** entries against
115+
**one shared `fastify.register` scope**, while core's routes live on the
116+
parent instance, which Fastify encapsulation shields from child-scope
117+
hooks. Two consequences for the NOTES.md #8 / #564 discussion:
118+
- The core/plugin line **holds against core**: a plugin cannot observe
119+
(or modify — `onRequest`/`preHandler`/`onSend` have the same scope)
120+
the request pipeline of routes core owns. Pipeline-touching features
121+
stay core, as #564 concluded.
122+
- But plugins are **not isolated from each other**: `api.fastify`
123+
already grants every plugin observation *and interception* of every
124+
other plugin's routes, with no capability gate. Today that's how this
125+
exporter sees its neighbors' traffic (useful!); it also means a
126+
hypothetical `capabilities: ['hooks']` design shouldn't imagine the
127+
status quo is per-plugin isolation — the existing grant is per-loader.
128+
If per-plugin encapsulation is ever wanted, the loader would need to
129+
`register` each entry in its own child scope (which would *break*
130+
this plugin's cross-plugin counters — the two goals pull opposite
131+
ways, worth deciding deliberately).
132+
2. **Core bug: `logger: false` silently kills every plugin `onResponse`
133+
hook.** Core's access-log hook (`src/server.js`, the "Unified access
134+
log" `onResponse`) calls `request.log.isLevelEnabled('info')`. Booted
135+
with `logger: false`, Fastify's null logger has no `isLevelEnabled`, so
136+
the hook throws `TypeError` on every request — and a throwing
137+
`onResponse` hook aborts the rest of the chain, so plugin `onResponse`
138+
hooks downstream **never run** (earlier stages — `onRequest`,
139+
`preHandler`, `onSend` — are unaffected; measured). Symptom here: the
140+
request counters stay at zero on a logger-less boot; the fix in this
141+
repo's tests is `logger: true, logLevel: 'silent'` (JSS treats
142+
`options.logger` as a boolean and takes the level from
143+
`options.logLevel`). Filed-worthy one-line core fix: guard the call
144+
(`typeof request.log.isLevelEnabled === 'function'`). Note
145+
`helpers.js` boots `logger: false` by default, so any *other* plugin
146+
relying on `onResponse` would hit this in its tests too.
147+
3. **No way to observe core's own request pipeline** (unless finding 1's
148+
scope surprises you the other way — it doesn't). Request/latency/error
149+
metrics for the pod itself — the numbers an operator most wants — are
150+
exactly the routes a plugin hook cannot see. This is the observability
151+
face of the gated-hooks seam (NOTES.md #8): a read-only
152+
`capabilities: ['observe']` (onResponse-only, no payload mutation) would
153+
be a much smaller grant than full pipeline hooks and would make this
154+
exporter a real whole-server exporter.
155+
4. **`loopbackUrl` optional = graceful degradation** — the deliberate
156+
contrast with the ~10 plugins that `throw` for it. An ops plugin should
157+
never take the server down over a missing nicety, so absence just
158+
removes the check from `/healthz`. Same `api.serverInfo` seam as
159+
everywhere else (NOTES.md #3), but this plugin demonstrates the soft
160+
failure mode instead of the loud one.
161+
5. **404s under a plugin's own prefix are invisible too**: an unmatched
162+
path like `<prefix>/typo` falls through to core's catch-all, which the
163+
hook can't see — so `jss_plugin_http_requests_total` has no 404 series
164+
for routes nobody registered. Scrape-side absence, not an error.
165+
6. **Self-observation is included**: the exporter counts its own scrapes
166+
(and their 401s), which is normal Prometheus practice and turned out to
167+
be a free test fixture — the auth-refusal series proves refused requests
168+
still traverse `onResponse`.

metrics/plugin.js

8.14 KB
Binary file not shown.

metrics/test-fixture.js

Lines changed: 9 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,9 @@
1+
// Test-only neighbor plugin: owns one route and nothing else. It exists so
2+
// metrics/test.js can measure the scope of hooks added on api.fastify —
3+
// specifically whether the metrics plugin's onResponse hook observes a
4+
// route registered by a DIFFERENT plugin entry (it does: all plugin entries
5+
// activate inside one shared Fastify register scope — see README Findings).
6+
export async function activate(api) {
7+
api.fastify.get((api.prefix || '') + '/ping', async () => ({ pong: true }));
8+
return {};
9+
}

metrics/test.js

Lines changed: 197 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,197 @@
1+
// Metrics plugin over a real JSS from npm: healthz (with a loopback check),
2+
// Prometheus exposition, Bearer-token guard, and — the experiment this
3+
// plugin exists for — the empirical scope of an onResponse hook added on
4+
// api.fastify. A second "neighbor" plugin (test-fixture.js) is booted
5+
// alongside so the test can prove the hook sees OTHER plugins' routes
6+
// (all entries share one loader register scope) while core routes (/,
7+
// LDP paths, /.well-known) never appear in the counters.
8+
//
9+
// Two host quirks this suite encodes:
10+
// - The main boot passes `logger: true, logLevel: 'silent'` — under
11+
// `logger: false` core's access-log onResponse hook throws
12+
// (request.log.isLevelEnabled is missing on Fastify's null logger) and
13+
// silently kills every downstream onResponse hook, so the request
14+
// counters would stay at zero. See README Findings.
15+
// - The extra boots (no-loopback, dead-loopback) run LAST: a second
16+
// createServer in one process repoints JSS's module-global DATA_ROOT
17+
// (AGENT.md footgun). Harmless here — this plugin never touches
18+
// storage — but the safe ordering is kept anyway.
19+
20+
import { describe, it, after } from 'node:test';
21+
import assert from 'node:assert';
22+
import path from 'node:path';
23+
import { fileURLToPath } from 'node:url';
24+
import { probePort, startJss } from '../helpers.js';
25+
26+
const __dirname = path.dirname(fileURLToPath(new URL(import.meta.url)));
27+
const module_ = path.join(__dirname, 'plugin.js');
28+
const fixture_ = path.join(__dirname, 'test-fixture.js');
29+
30+
const TOKEN = 'metrics-scrape-token-1234567890';
31+
32+
describe('metrics plugin', () => {
33+
let jss;
34+
let base;
35+
const extra = []; // later boots, closed in after()
36+
37+
after(async () => {
38+
for (const s of extra.reverse()) await s.close();
39+
if (jss) await jss.close();
40+
});
41+
42+
const scrape = async (auth = TOKEN) => {
43+
const res = await fetch(`${base}/metrics/metrics`, {
44+
headers: auth ? { authorization: `Bearer ${auth}` } : {},
45+
});
46+
return res;
47+
};
48+
49+
it('boots alongside a neighbor plugin (token + loopbackUrl configured)', async () => {
50+
const port = await probePort();
51+
base = `http://127.0.0.1:${port}`;
52+
jss = await startJss({
53+
port,
54+
logger: true,
55+
logLevel: 'silent', // real logger (so onResponse hooks run), no noise
56+
plugins: [
57+
{
58+
id: 'metrics',
59+
module: module_,
60+
prefix: '/metrics',
61+
config: { loopbackUrl: base, token: TOKEN },
62+
},
63+
{ id: 'neighbor', module: fixture_, prefix: '/neighbor' },
64+
],
65+
});
66+
});
67+
68+
it('GET /metrics/healthz is 200 ok, open (no token), with the loopback check', async () => {
69+
const res = await fetch(`${base}/metrics/healthz`); // no Authorization
70+
assert.strictEqual(res.status, 200);
71+
const body = await res.json();
72+
assert.strictEqual(body.status, 'ok');
73+
assert.ok(typeof body.uptime_seconds === 'number' && body.uptime_seconds > 0);
74+
assert.strictEqual(body.checks.process.ok, true);
75+
assert.strictEqual(body.checks.loopback.ok, true, 'loopback check present and passing');
76+
assert.ok(typeof body.checks.loopback.status === 'number');
77+
});
78+
79+
it('GET /metrics/metrics requires the Bearer token when config.token is set', async () => {
80+
const anon = await scrape(null);
81+
assert.strictEqual(anon.status, 401);
82+
assert.match(anon.headers.get('www-authenticate'), /^Bearer/);
83+
84+
const wrong = await scrape('not-the-token');
85+
assert.strictEqual(wrong.status, 401);
86+
87+
// Same-length wrong token (the compare hashes first, so length is moot).
88+
const sameLen = await scrape('x'.repeat(TOKEN.length));
89+
assert.strictEqual(sameLen.status, 401);
90+
91+
const right = await scrape();
92+
assert.strictEqual(right.status, 200);
93+
});
94+
95+
it('exposition is well-formed Prometheus text with the process gauges', async () => {
96+
const res = await scrape();
97+
assert.strictEqual(res.status, 200);
98+
assert.match(res.headers.get('content-type'), /^text\/plain; version=0\.0\.4/);
99+
const text = await res.text();
100+
101+
assert.match(text, /^# TYPE process_uptime_seconds gauge$/m);
102+
assert.match(text, /^process_uptime_seconds \d+(\.\d+)?$/m, 'well-formed sample value');
103+
for (const name of [
104+
'process_resident_memory_bytes',
105+
'process_heap_used_bytes',
106+
'process_heap_total_bytes',
107+
'process_cpu_user_seconds_total',
108+
'process_cpu_system_seconds_total',
109+
'nodejs_eventloop_lag_seconds',
110+
]) {
111+
assert.match(text, new RegExp(`^${name} \\d+(\\.\\d+)?(e[-+]?\\d+)?$`, 'mi'), name);
112+
}
113+
// Counters really count upward: rss/heap are positive.
114+
const rss = Number(/^process_resident_memory_bytes (\S+)$/m.exec(text)[1]);
115+
assert.ok(rss > 1e6, `plausible RSS, got ${rss}`);
116+
});
117+
118+
it('request counters observe THIS plugin and the NEIGHBOR plugin, never core (the discovered hook scope)', async () => {
119+
// Traffic: 3x own healthz, 2x the neighbor's route, and two core
120+
// routes (the UI root and an LDP pod path).
121+
for (let i = 0; i < 3; i++) assert.strictEqual((await fetch(`${base}/metrics/healthz`)).status, 200);
122+
for (let i = 0; i < 2; i++) assert.strictEqual((await fetch(`${base}/neighbor/ping`)).status, 200);
123+
await fetch(`${base}/`);
124+
await fetch(`${base}/nobody/nothing.txt`);
125+
126+
const text = await (await scrape()).text();
127+
const count = (method, route, status) => {
128+
const m = new RegExp(
129+
`^jss_plugin_http_requests_total\\{method="${method}",route="${route.replace(/[/*]/g, '\\$&')}",status="${status}"\\} (\\d+)$`, 'm',
130+
).exec(text);
131+
return m ? Number(m[1]) : 0;
132+
};
133+
134+
// (a) Own routes: counted (>= because earlier tests hit healthz too).
135+
assert.ok(count('GET', '/metrics/healthz', 200) >= 3, 'own route counted');
136+
// Self-scrapes count as well — /metrics/metrics saw the 401s and 200s above.
137+
assert.ok(count('GET', '/metrics/metrics', 200) >= 1, 'self-scrape counted');
138+
assert.ok(count('GET', '/metrics/metrics', 401) >= 2, 'auth refusals counted');
139+
140+
// (b) ANOTHER plugin's route: counted. All plugin entries activate in
141+
// ONE shared Fastify register scope, so an api.fastify hook observes
142+
// every plugin's routes — a wider grant than "your own prefix".
143+
assert.strictEqual(count('GET', '/neighbor/ping', 200), 2, "neighbor plugin's route counted");
144+
145+
// (c) Core routes: NEVER counted. Fastify encapsulation shields the
146+
// parent instance — core's UI root, LDP catch-all and /.well-known
147+
// don't run plugin hooks, so no core series can appear.
148+
assert.ok(!text.includes('route="/"'), 'core UI root not counted');
149+
assert.ok(!text.includes('route="/*"'), 'core catch-all not counted');
150+
assert.ok(!text.includes('nobody'), 'core LDP path not counted');
151+
152+
// Duration summary covers the counted requests.
153+
const sum = Number(/^jss_plugin_http_request_duration_seconds_sum (\S+)$/m.exec(text)[1]);
154+
const n = Number(/^jss_plugin_http_request_duration_seconds_count (\d+)$/m.exec(text)[1]);
155+
assert.ok(n >= 8, `duration count covers plugin traffic, got ${n}`);
156+
assert.ok(sum > 0, 'duration sum accumulates');
157+
});
158+
159+
it('without loopbackUrl, healthz degrades gracefully to plain process liveness (and /metrics is open without token)', async () => {
160+
const s = await startJss({
161+
logger: true,
162+
logLevel: 'silent',
163+
plugins: [{ id: 'metrics', module: module_, prefix: '/metrics' }], // no config at all
164+
});
165+
extra.push(s);
166+
const res = await fetch(`${s.base}/metrics/healthz`);
167+
assert.strictEqual(res.status, 200);
168+
const body = await res.json();
169+
assert.strictEqual(body.status, 'ok');
170+
assert.strictEqual(body.checks.loopback, undefined, 'no loopback check without loopbackUrl');
171+
172+
const metrics = await fetch(`${s.base}/metrics/metrics`); // no token configured -> open
173+
assert.strictEqual(metrics.status, 200);
174+
assert.match(await metrics.text(), /^process_uptime_seconds /m);
175+
});
176+
177+
it('a failing loopback probe turns healthz into 503 degraded', async () => {
178+
const deadPort = await probePort(); // probed then released: nothing listens
179+
const s = await startJss({
180+
logger: true,
181+
logLevel: 'silent',
182+
plugins: [{
183+
id: 'metrics',
184+
module: module_,
185+
prefix: '/metrics',
186+
config: { loopbackUrl: `http://127.0.0.1:${deadPort}` },
187+
}],
188+
});
189+
extra.push(s);
190+
const res = await fetch(`${s.base}/metrics/healthz`);
191+
assert.strictEqual(res.status, 503);
192+
const body = await res.json();
193+
assert.strictEqual(body.status, 'degraded');
194+
assert.strictEqual(body.checks.loopback.ok, false);
195+
assert.ok(body.checks.loopback.error, 'failure reason reported');
196+
});
197+
});

0 commit comments

Comments
 (0)