Мониторинг и логирование: что собирать и как реагировать

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

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]",
  },
});

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;
}

$ 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"}

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);

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 };

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
      - stock

global:
  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

# 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"]}]}}

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"

$ 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"}]}}