A service needs three kinds of telemetry: structured logs to investigate a specific request, metrics to see trends and drive alerts, and traces to follow a request across several services. The minimal metric set is the four golden signals from the Google SRE book: latency, traffic, errors and saturation. An alert should fire on a symptom users can see, with a threshold and a hold duration, not on anything that merely looks odd.
After this you will be able to
- set up structured JSON logs with pino, with levels, secret redaction and a
reqIdon every line - pass a correlation id between two services in the
X-Request-Idheader and collect every line of one request by it - expose RED metrics on
/metricsand compute the error ratio and p95 with PromQL - write an alerting rule with a threshold and
forand confirm it reachesfiring
Know beforehand
Verified with
Node.js 24 LTS (24.18)Express 5.3.0pino 10.4.0pino-http 11.0.0@prometheus-io/client 0.16.1Prometheus 3.15.0Docker Compose 5.3
Checked against docs: October 11, 2026
Contents
- Logs, metrics, traces: what is what
- What to measure: the four golden signals, RED and USE
- Structured logs with pino: levels and redaction
- Correlation id: one thread through every service
- Health and readiness: is the process alive and ready for traffic
- Prometheus metrics: /metrics and PromQL queries
- Alerts: thresholds, hold time and noise
- Grafana, OpenTelemetry and exercises
Logs, metrics, traces: what is what
A user tells support that their request "didn't go through". Without telemetry the team guesses: the server crashed, the database is slow, or the frontend has a bug. Monitoring answers the two questions that chapter 6 of the Google SRE book, "Monitoring Distributed Systems", puts this way: what is broken (the symptom) and why (the cause). Three signals are used to answer them — OpenTelemetry uses the same term.
Log
- What it is
- A record of an event: time, level, message and fields
- Question it answers
- What exactly happened to this request?
- Typical tool
- pino, Loki, Elasticsearch
Metric
- What it is
- A number over time: counter, current value, histogram
- Question it answers
- How many, how fast, is the problem growing?
- Typical tool
- Prometheus, Grafana
Trace
- What it is
- The path of one request through services, split into spans
- Question it answers
- Where exactly did the request spend its time?
- Typical tool
- OpenTelemetry, Jaeger, Tempo
The signals complement each other. A metric is cheap — one number per interval no matter how many requests there were — so graphs and alerts are built on metrics. A log is expensive — one line per event — but it carries context: which order, which error, which stack trace. A typical investigation goes: a metric alert says "errors are at 25%" → filter logs by time and level error → take the request id of one request → see every line of that request in every service.
The SRE book distinguishes white-box monitoring — metrics and logs from inside the system — from black-box monitoring, which tests externally visible behaviour the way a user sees it. Google relies heavily on white-box monitoring with modest but critical use of black-box: an external probe catches what is broken right now, while internal metrics reveal imminent problems and failures masked by retries.
What to measure: the four golden signals, RED and USE
The Google SRE book (chapter 6, "The Four Golden Signals") states it directly: if you can only measure four metrics of your user-facing system, measure latency, traffic, errors and saturation. If you page a human when one of them is problematic, the service is "at least decently covered by monitoring".
Latency
- Definition in the SRE book
- The time it takes to service a request; track successful and failed request latency separately
- How to measure it in a Node.js HTTP API
- Histogram
http_request_duration_secondswith astatus_codelabel, p95/p99
Traffic
- Definition in the SRE book
- Demand placed on the system in its own units — for a web service usually HTTP requests per second
- How to measure it in a Node.js HTTP API
rate()of a request counter
Errors
- Definition in the SRE book
- The rate of failed requests: explicit (500), implicit (200 with wrong content) or by policy (slower than promised)
- How to measure it in a Node.js HTTP API
- Share of
5xxresponses among all responses
Saturation
- Definition in the SRE book
- How "full" the service is: the most constrained resource — memory, CPU, a queue, disk
- How to measure it in a Node.js HTTP API
- Process memory, event loop lag, job queue length, free disk space
One important detail from the same chapter is the tail. An average latency of 100 ms can hide 1% of requests taking 5 seconds, and an average CPU figure can hide one overloaded server among idle ones. That is why latency is collected as a histogram — request counts per duration bucket — and read as percentiles: p95 means 95% of requests were faster than this value. A slow error, the authors remind us, is even worse than a fast one.
Two short methods are often confused with the golden signals. Brendan Gregg's USE method is for resources: for every resource (CPU, disk, network) check Utilization, Saturation (queued work it cannot service) and Errors. Tom Wilkie's RED method (Grafana Labs) is for services: Rate (requests per second), Errors (how many of them fail) and Duration (the distribution of request time). The author of RED recommends using both: RED tells you how your users feel, USE tells you how your machines feel.
Structured logs with pino: levels and redaction
A line like console.log("order failed", id) is handy in a terminal but useless when searching thousands of lines. A structured log is one JSON line per event with stable fields: time, level, service, request id, message and data. Log pipelines (Loki, Elasticsearch, cloud logging) parse such lines without regular expressions and filter by field. Pino writes JSON to standard output by default — and in a container, stdout is exactly where logs belong.
The example in this lesson is two small Express 5 services: orders returns an order and calls stock for the available quantity. The same code runs twice with different environment variables. Start with the project and the logger.
mkdir orders-observability && cd orders-observability
npm init -y
npm pkg set type=module
npm pkg set scripts.start="node src/server.js"
npm install --save-exact express@5.3.0 pino@10.4.0 pino-http@11.0.0 @prometheus-io/client@0.16.1@prometheus-io/client package is the former prom-client: from version 0.16 it became a Prometheus subproject and was renamed.import { pino } from "pino";
export const logger = pino({
name: process.env.SERVICE_NAME ?? "orders-api",
level: process.env.LOG_LEVEL ?? "info",
// ISO time and a level name instead of a number: easier to search
timestamp: pino.stdTimeFunctions.isoTime,
formatters: { level: (label) => ({ level: label }) },
// secrets and personal data never reach the log
redact: {
paths: ["password", "*.password", "*.token", "*.phone"],
censor: "[REDACTED]",
},
});fatal
- Number
- 60
- When to use it
- The process cannot continue and is about to exit
error
- Number
- 50
- When to use it
- A request or job failed: a 5xx response, an exception
warn
- Number
- 40
- When to use it
- Odd but handled: a 4xx response, a retry, close to a limit
info
- Number
- 30
- When to use it
- Meaningful events: server started, request completed, order created
debug
- Number
- 20
- When to use it
- Development detail; usually off in production
trace
- Number
- 10
- When to use it
- Maximum detail; enabled selectively and briefly
The default level is info: pino does not even build lines below it, which saves resources. Here the level comes from LOG_LEVEL, so debug can be turned on without a code change. The formatters.level option writes the level as a word instead of a number; the pino docs note that with multiple transport targets the numeric level field must be kept, but we have a single output.
The redact option replaces values at the given paths with [REDACTED]. The path *.phone covers a phone field one level deep, while a top-level field has to be listed separately — hence both password and *.password. In the check, logger.info({ lead: { name: "Test", phone: "+70000000000" }, password: "x" }) came out as "phone":"[REDACTED]" and "password":"[REDACTED]".
Correlation id: one thread through every service
A user request passes through several services, and each writes its own logs. To put them back together, the request gets an identifier — a correlation id, or request id — that is passed on to every downstream call. Here the X-Request-Id header does the job: if it arrives and looks like an id, we use it; otherwise we generate a new UUID and return it to the client in the response.
import { randomUUID } from "node:crypto";
import express from "express";
import { pinoHttp } from "pino-http";
import { logger } from "./logger.js";
import { metricsMiddleware, register } from "./metrics.js";
// accept an incoming id only if it looks like an id: no junk or forged log lines
const REQUEST_ID = /^[A-Za-z0-9-]{8,64}$/;
const QUIET = new Set(["/metrics", "/healthz", "/readyz"]);
export const state = { ready: false };
export function createApp({ stockUrl, failRate = 0 } = {}) {
const app = express();
app.use(
pinoHttp({
logger,
genReqId(req, res) {
const incoming = req.headers["x-request-id"];
const id = typeof incoming === "string" && REQUEST_ID.test(incoming) ? incoming : randomUUID();
res.setHeader("X-Request-Id", id);
return id;
},
customLogLevel(req, res, err) {
if (err || res.statusCode >= 500) return "error";
if (res.statusCode >= 400) return "warn";
return "info";
},
autoLogging: { ignore: (req) => QUIET.has(req.url) },
// req.log carries only reqId; full req/res go to one summary line per request
quietReqLogger: true,
serializers: {
req: (req) => ({ method: req.method, url: req.url }),
res: (res) => ({ statusCode: res.statusCode }),
},
}),
);
app.use(metricsMiddleware);
// liveness: the process is alive and serves requests
app.get("/healthz", (req, res) => res.json({ status: "ok" }));
// readiness: this instance can take traffic (started, not shutting down)
app.get("/readyz", (req, res) => {
if (!state.ready) return res.status(503).json({ status: "not ready" });
res.json({ status: "ready" });
});
app.get("/metrics", async (req, res) => {
res.set("Content-Type", register.contentType);
res.send(await register.metrics());
});
// "stock": a slow dependency that sometimes fails
app.get("/api/stock/:sku", async (req, res) => {
await new Promise((r) => setTimeout(r, 20 + Math.random() * 80));
if (Math.random() < failRate) throw new Error("stock db timeout");
res.json({ sku: req.params.sku, available: 7 });
});
// "orders": calls stock and forwards the same X-Request-Id
app.get("/api/orders/:id", async (req, res) => {
const r = await fetch(`${stockUrl}/api/stock/${encodeURIComponent(req.params.id)}`, {
headers: { "x-request-id": req.id },
signal: AbortSignal.timeout(2000),
});
if (!r.ok) throw new Error(`stock service responded ${r.status}`);
const stock = await r.json();
req.log.info({ orderId: req.params.id, available: stock.available }, "order loaded");
res.json({ id: req.params.id, status: "new", stock });
});
app.use((req, res) => res.status(404).json({ error: "not_found" }));
// Express 5 forwards errors from async handlers here by itself
app.use((err, req, res, next) => {
res.err = err; // pino-http adds the error with its stack to the summary line
res.status(500).json({ error: "internal_error", requestId: req.id });
});
return app;
}genReqIdis the pino-http hook for the request id; without it pino-http uses an incrementing integer, which its README warns is a poor fit when you run several instances- The incoming id is checked with a regular expression, so line breaks, quotes or a megabyte-long string from an attacker never reach the log
quietReqLogger: trueleaves onlyreqIdonreq.log, while the fullreqandresgo to a single summary line per requestcustomLogLevelpicks the level of the summary line: 5xx iserror, 4xx iswarn, everything else isinfoautoLogging.ignorekeeps/metricsand health checks out of the logs — they are hit every few secondsorderssendsreq.idin thex-request-idheader when it callsstock— that is how the id crosses the service boundary
The error handler puts the exception into res.err — pino-http checks that field and writes the error with its stack into the request's summary line, so one failed request produces one error line, not two. The client only receives requestId, without technical details: support can use it to find the request in the logs. Below is real output: one request, two services, a shared reqId, and it is immediately clear that the root cause is in stock.
$ FAIL_RATE=0.3 docker compose up -d --build --wait
$ curl -s -H "X-Request-Id: check-7f3a-0004" localhost:3000/api/orders/1042
{"error":"internal_error","requestId":"check-7f3a-0004"}
$ docker compose logs --no-log-prefix orders stock | grep check-7f3a-0004
{"level":"error","time":"2026-10-12T01:31:14.981Z","pid":1,"hostname":"e383b1a6fba4","name":"stock-api","reqId":"check-7f3a-0004","req":{"method":"GET","url":"/api/stock/1042"},"res":{"statusCode":500},"err":{"type":"Error","message":"stock db timeout","stack":"Error: stock db timeout\n at file:///app/src/app.js:56:41"},"responseTime":44,"msg":"request errored"}
{"level":"error","time":"2026-10-12T01:31:14.982Z","pid":1,"hostname":"b41fddb93326","name":"orders-api","reqId":"check-7f3a-0004","req":{"method":"GET","url":"/api/orders/1042"},"res":{"statusCode":500},"err":{"type":"Error","message":"stock service responded 500","stack":"Error: stock service responded 500\n at file:///app/src/app.js:66:22\n at process.processTicksAndRejections (node:internal/process/task_queues:104:5)"},"responseTime":46,"msg":"request errored"}reqId.Health and readiness: is the process alive and ready for traffic
An orchestrator (Kubernetes, Docker, a load balancer) needs to know two different things about each service instance. The Kubernetes documentation splits them into separate probes, and the same names stuck for HTTP endpoints.
Liveness
- Question
- Is the process alive and not stuck?
- What the orchestrator does on failure
- Restarts the container
- In the example
GET /healthz→ 200
Readiness
- Question
- Can this instance take requests?
- What the orchestrator does on failure
- Stops sending traffic but does not kill it
- In the example
GET /readyz→ 200 or 503
Startup
- Question
- Has a slow start finished?
- What the orchestrator does on failure
- Holds off the other probes
- In the example
- Not used: the service starts instantly
import { createApp, state } from "./app.js";
import { logger } from "./logger.js";
const port = Number(process.env.PORT ?? 3000);
const app = createApp({
stockUrl: process.env.STOCK_URL ?? `http://localhost:${port}`,
failRate: Number(process.env.FAIL_RATE ?? 0),
});
const server = app.listen(port, () => {
state.ready = true;
logger.info({ port }, "server started");
});
function shutdown(signal) {
logger.info({ signal }, "shutting down");
state.ready = false; // the balancer stops sending traffic, in-flight requests finish
server.close(() => process.exit(0));
setTimeout(() => process.exit(1), 10_000).unref();
}
process.on("SIGTERM", shutdown);
process.on("SIGINT", shutdown);On SIGTERM (sent by docker stop and by Kubernetes during a rollout) the service first marks itself not ready, then server.close() waits for in-flight requests, and only then does the process exit. If something hangs, a timer force-exits after 10 seconds. In the check, the stopped container logged "signal":"SIGTERM","msg":"shutting down" and exited with code 0.
You also need a black box on the outside: an external uptime service that requests your public address once a minute and checks for a 200. It catches what the service cannot see from inside — an expired TLS certificate, a DNS error, a dead load balancer. The SRE book notes that for a 99.9% availability target, probing for a 200 more than once or twice a minute is probably unnecessarily frequent.
Prometheus metrics: /metrics and PromQL queries
Prometheus uses a pull model: every interval it calls each service's /metrics, reads a plain-text list of numbers and stores them as time series. The Node.js client collects standard process metrics — memory, CPU, event loop lag, garbage collection — and provides the Counter, Gauge, Histogram and Summary types.
import { Histogram, collectDefaultMetrics, register } from "@prometheus-io/client";
// memory, CPU, event loop lag, GC: Node.js process metrics
collectDefaultMetrics();
// one histogram gives all three RED signals:
// _count = requests (rate), _count{status_code=~"5.."} = errors, _bucket = duration
export const httpDuration = new Histogram({
name: "http_request_duration_seconds",
help: "HTTP request duration in seconds",
labelNames: ["method", "route", "status_code"],
buckets: [0.005, 0.01, 0.025, 0.05, 0.1, 0.25, 0.5, 1, 2.5, 5],
});
export function metricsMiddleware(req, res, next) {
const end = httpDuration.startTimer();
res.on("finish", () => {
// route template, not the raw URL: /api/orders/:id, not /api/orders/1042
const route = req.route ? req.baseUrl + req.route.path : "unmatched";
end({ method: req.method, route, status_code: String(res.statusCode) });
});
next();
}
export { register };The names follow Prometheus conventions: base units (seconds, not milliseconds) and a unit suffix in the name. The route label takes the route template, not the actual path. This matters: every unique label combination is a separate time series, and the Prometheus docs explicitly say not to put high-cardinality values such as user IDs, email addresses or raw URLs into labels. Requests that matched no route get route="unmatched".
Now package the service as an image and run Prometheus next to it. Docker Compose starts three containers: orders, stock and prom/prometheus. The Compose health check calls /readyz with the fetch built into Node.js, so the image needs neither curl nor wget.
FROM node:24-alpine
WORKDIR /app
ENV NODE_ENV=production
COPY package*.json ./
RUN npm ci --omit=dev
COPY src ./src
USER node
EXPOSE 3000
CMD ["node", "src/server.js"]services:
orders:
build: .
environment:
SERVICE_NAME: orders-api
STOCK_URL: http://stock:3000
ports:
- "3000:3000"
healthcheck: &ready
test: ["CMD", "node", "-e", "fetch('http://localhost:3000/readyz').then(r => process.exit(r.ok ? 0 : 1), () => process.exit(1))"]
interval: 10s
timeout: 3s
retries: 3
depends_on:
stock:
condition: service_healthy
stock:
build: .
environment:
SERVICE_NAME: stock-api
FAIL_RATE: ${FAIL_RATE:-0}
healthcheck: *ready
prometheus:
image: prom/prometheus:v3.15.0
ports:
- "9090:9090"
volumes:
- ./prometheus:/etc/prometheus:ro
depends_on:
- orders
- stockglobal:
scrape_interval: 5s # demo value; the default is 1m
evaluation_interval: 5s
rule_files:
- alerts.yml
scrape_configs:
- job_name: node-api
static_configs:
- targets: ["orders:3000", "stock:3000"]$ curl -s localhost:3000/healthz; curl -s localhost:3000/readyz
{"status":"ok"}{"status":"ready"}
$ curl -s localhost:3000/metrics | grep 'route="/api/orders/:id"' | grep -E 'le="0.1"|_sum|_count'
http_request_duration_seconds_bucket{le="0.1",method="GET",route="/api/orders/:id",status_code="200"} 0
http_request_duration_seconds_sum{method="GET",route="/api/orders/:id",status_code="200"} 0.118051033
http_request_duration_seconds_count{method="GET",route="/api/orders/:id",status_code="200"} 1/metrics: three of the forty-odd histogram lines.Generate load with errors: FAIL_RATE=0.3 makes stock fail on roughly a third of requests. Then ask Prometheus through its HTTP API — the same expressions work in the web UI at localhost:9090.
# two minutes of load: requests hit orders, which calls stock
end=$((SECONDS+120)); while [ $SECONDS -lt $end ]; do
curl -s -o /dev/null localhost:3000/api/orders/$RANDOM
done$ curl -s -G localhost:9090/api/v1/query --data-urlencode \
'query=sum by (instance) (rate(http_request_duration_seconds_count{status_code=~"5.."}[1m])) / sum by (instance) (rate(http_request_duration_seconds_count[1m]))'
{"status":"success","data":{"resultType":"vector","result":[{"metric":{"instance":"stock:3000"},"value":[1791768977.267,"0.24901960784313726"]},{"metric":{"instance":"orders:3000"},"value":[1791768977.267,"0.24754420432220037"]}]}}
$ curl -s -G localhost:9090/api/v1/query --data-urlencode \
'query=histogram_quantile(0.95, sum by (instance, le) (rate(http_request_duration_seconds_bucket{route=~"/api/.*"}[5m])))'
{"status":"success","data":{"resultType":"vector","result":[{"metric":{"instance":"stock:3000"},"value":[1791768977.334,"0.09608341223427372"]},{"metric":{"instance":"orders:3000"},"value":[1791768977.334,"0.09826923076923078"]}]}}Traffic, requests/s
- PromQL query
sum by (instance) (rate(http_request_duration_seconds_count[1m]))
Error ratio
- PromQL query
sum(rate(http_request_duration_seconds_count{status_code=~"5.."}[1m])) / sum(rate(http_request_duration_seconds_count[1m]))
Latency p95, s
- PromQL query
histogram_quantile(0.95, sum by (le) (rate(http_request_duration_seconds_bucket[5m])))
Saturation: event loop lag
- PromQL query
nodejs_eventloop_lag_p99_seconds
Scrape target is reachable
- PromQL query
up{job="node-api"}
rate() computes the per-second average increase of a counter over the window and handles counter resets when the service restarts. The error ratio here counts every response, including /metrics and health checks; a production dashboard usually filters those out by route.
Alerts: thresholds, hold time and noise
A Prometheus alerting rule is a PromQL expression plus a condition. While the expression returns at least one series, the alert is active for that series. The for field sets a hold time: the alert first sits in pending and only moves to firing if the condition holds for the whole duration. That way a single spike does not wake the on-call engineer.
groups:
- name: node-api
rules:
- alert: InstanceDown
expr: up{job="node-api"} == 0
for: 1m
labels:
severity: page
annotations:
summary: "{{ $labels.instance }} does not answer scrapes"
- alert: HighErrorRate
expr: |
sum by (instance) (rate(http_request_duration_seconds_count{status_code=~"5.."}[1m]))
/ sum by (instance) (rate(http_request_duration_seconds_count[1m]))
> 0.05
for: 1m
labels:
severity: page
annotations:
summary: "{{ $labels.instance }}: more than 5% of responses are 5xx"
description: "Error ratio is {{ $value | humanizePercentage }}"
- alert: SlowRequestsP95
expr: |
histogram_quantile(0.95,
sum by (instance, le) (rate(http_request_duration_seconds_bucket{route=~"/api/.*"}[5m]))
) > 0.5
for: 10m
labels:
severity: ticket
annotations:
summary: "{{ $labels.instance }}: p95 latency above 500 ms"The three rules cover different scenarios: InstanceDown — Prometheus cannot scrape the service (it crashed or is unreachable); HighErrorRate — more than 5% of responses are errors; SlowRequestsP95 — slow but working, hence severity: ticket (a task in a queue) rather than a page. The 1-minute windows are chosen so the demo alert fires quickly; in production, windows and for are usually longer. The syntax is checked with promtool check config from the same image.
$ curl -s localhost:9090/api/v1/alerts
{"status":"success","data":{"alerts":[{"labels":{"alertname":"HighErrorRate","instance":"stock:3000","severity":"page"},"annotations":{"description":"Error ratio is 24.9%","summary":"stock:3000: more than 5% of responses are 5xx"},"state":"firing","activeAt":"2026-10-12T01:34:25.655482362Z","value":"2.4901960784313726e-01"},{"labels":{"alertname":"HighErrorRate","instance":"orders:3000","severity":"page"},"annotations":{"description":"Error ratio is 24.75%","summary":"orders:3000: more than 5% of responses are 5xx"},"state":"firing","activeAt":"2026-10-12T01:34:25.655482362Z","value":"2.4754420432220037e-01"}]}}FAIL_RATE=0.3.Did the error alert fire
After the load,
HighErrorRatemoved tofiringfor both services, with an error ratio of about 25% in the annotation.Does the outage alert fire
docker compose stop stock— a minute later/api/v1/alertsshowsInstanceDownforstock:3000in thefiringstate, andordersreturns 500.Does it clear by itself
Once the load stopped,
HighErrorRatedisappeared from the list: with no requests, the expression returns no series.
Prometheus only evaluates rules. Sending notifications — to email, a chat or an on-call system — is the job of a separate component, Alertmanager: it groups alerts, silences repeats and can inhibit consequences when the cause is already known.
Note that HighErrorRate fired twice — for stock and for orders — although there is one problem. The Prometheus alerting guide recommends paging on user-visible errors as high up the stack as possible and not paging separately for lower layers. The SRE book adds questions worth asking before every new rule:
- The rule detects an urgent condition that users see or are about to see, and nothing else detects it
- This alert cannot be safely ignored as benign
- Someone can and should act on it now rather than in the morning — otherwise it is a ticket, not a page
- The annotation has a clear description and a link to a runbook
- The response requires thought; if it is mechanical, it should be automated
Grafana, OpenTelemetry and exercises
The Prometheus web UI is fine for one-off queries, but permanent dashboards usually live in Grafana: it connects Prometheus as a data source, and the same PromQL expressions become graphs. The Grafana documentation has a step-by-step guide, "Get started with Grafana and Prometheus". Container stdout logs are shipped by a separate agent to Loki or Elasticsearch, so you can search by reqId across all services at once instead of using docker compose logs.
OpenTelemetry is an open standard and set of SDKs for generating and exporting traces, metrics and logs; it is not a storage backend and sends data to Prometheus, Jaeger or commercial systems. Once you have more than two or three services, its traces replace a home-grown X-Request-Id: every step of the request becomes a span with a duration, and context travels in the traceparent header. The documentation notes that the OpenTelemetry logging library for Node.js is still under development, so "pino for logs plus OpenTelemetry for traces" remains a sensible combination.
How this was verified4 · passedchecked 11 October 2026
“Run” means the code was executed in a scratch project or container and the output in the article comes from that run. “Partial” means it was checked against stubs instead of external services. “Not run” means it needs a device, an account or a key; the steps were checked against the official documentation. The verification project files and run logs are kept in the InterLAB archive.