feat: Add request logging and traffic metrics for API performance monitoring

2026-10-20 23:31:08 +03:00
parent e28d65310d
commit de72d003b8
6 changed files with 304 additions and 2 deletions
--- a/README.md
+++ b/README.md
@@ -51,6 +51,19 @@ Vite работает на http://127.0.0.1:5173 и проксирует `/api`

 **Проверка каталога по ETag.** Сервер сам проверяет каталог университета раз в 5 минут, а не только когда приходит запрос. У каждой папки Nextcloud есть ETag, и он меняется, когда меняется что‑то внутри. Сервер хранит листинги прошлого обхода (`.data/catalog-tree.json`) и заново запрашивает только папки с новым ETag. Проверка неизменного каталога — 2 запроса вместо ~100: корень и папка года. Перезалитый документ стоит ещё пары запросов по пути к нему. Раз в 6 часов на всякий случай идёт полный обход. Индекс пересобирается, только если изменился какой‑то документ, поэтому ETag расписаний и кэши клиентов между проверками не сбрасываются. В `/api/health` поле `catalog.lastCrawl` показывает последний обход: число запросов, полный ли он, сколько папок взято из кэша. Поле `watch` показывает время и ошибку последней проверки.

+**Журнал запросов и метрики.** На каждый запрос к `/api` в журнал (`docker logs`) пишется одна строка JSON: время, метод, путь с параметрами, статус, время ответа в мс, код ошибки, размер ответа и адрес клиента без последней части (`203.0.113.0`, у IPv6 — /48). Точные адреса не сохраняются. Проверки здоровья (`/api/health`, `/api/ready`) не пишутся и не считаются. Журнал выключается переменной `PSU_REQUEST_LOG=off`.
+
+Поле `traffic` в `/api/health` — сводка за последний час (`lastHour`) и с запуска (`total`):
+- сколько было запросов и какая доля ушла пустым `304`;
+- ошибки клиента и сервера;
+- срабатывания лимита (`limited`) и таймаута (`timeouts`);
+- ответы `502`/`504` из‑за университета (`sourceErrors`) и упавшие запросы к нему (`sourceFailures`);
+- медленные ответы, дольше секунды;
+- медиана и 95‑й процентиль времени ответа — как граница корзины: 25, 50, 100, 250… мс;
+- десять самых частых адресов API со средним временем.
+
+За последний час есть ещё число разных клиентов и три самых активных. Так видно, если кто‑то перебирает API.
+
 **Оповещения в Telegram.** Если заданы `TELEGRAM_BOT_TOKEN` и `TELEGRAM_CHAT_ID`, сервер пишет владельцу после проверок каталога:
 - появился новый документ — с его группами и подозрительными ячейками;
 - документ не читается;
--- a/server/index.js
+++ b/server/index.js
@@ -13,6 +13,7 @@ import { catalogDiagnostics } from "./diagnostics.js";
 import { securityHeaders, requestTimeout } from "./protect.js";
 import { startWatch, watchOnce, watchStatus } from "./watch.js";
 import { telegram } from "./alerts.js";
+import { requestLog, trafficStatus } from "./metrics.js";
 import {
  getIndex,
  indexStatus,
@@ -40,6 +41,9 @@ app.disable("x-powered-by");
 app.set("trust proxy", "loopback, linklocal, uniquelocal");
 const dist = fileURLToPath(new URL("../dist/", import.meta.url));
 app.use(securityHeaders(dist + "index.html"));
+// One JSON line per API request and the counters of /api/health; first, so limited and timed
+// out requests are in them too.
+app.use("/api", requestLog());
 // gzip or brotli: a semester of lessons is about 200 KB of JSON and shrinks tenfold.
 app.use(compression());
 // A generous limit per address: students behind one dormitory or university NAT share it, so
@@ -70,8 +74,9 @@ app.use("/api", (_req, res, next) => {
 // 8 — /api/ready, and `ready` in /api/health;
 // 9 — a request limit on /api (429 too_many_requests), a 30 s time limit (504 timeout), security headers;
 // 10 — parserVersion in /api/catalog;
-// 11 — the catalog is checked by ETag every 5 minutes; `watch`, `telegram` and `catalog.lastCrawl` in /api/health.
-const API_VERSION = 11;
+// 11 — the catalog is checked by ETag every 5 minutes; `watch`, `telegram` and `catalog.lastCrawl` in /api/health;
+// 12 — a JSON log line per request and `traffic` in /api/health.
+const API_VERSION = 12;

 /**
 * What the server still waits for before it answers from memory: the catalog, the week table
@@ -94,6 +99,8 @@ app.get("/api/health", async (req, res) => {
    directory: indexStatus(),
    // The server's own checks of the catalog and its messages to the owner.
    watch: watchStatus,
+    // What the API was asked in the last hour and since the start (server/metrics.js).
+    traffic: trafficStatus(),
    telegram: { enabled: telegram.enabled, sent: telegram.sent, lastSentAt: telegram.lastSentAt, lastError: telegram.lastError },
  });
 });
--- a/server/metrics.js
+++ b/server/metrics.js
@@ -0,0 +1,197 @@
+// What the API is asked and how it answers: one JSON line per request in the log (docker logs),
+// and counters for /api/health over the last hour and since the start. Enough to see what is
+// slow, how often clients revalidate for free (304), whether someone hammers the API and how
+// often the university fails.
+
+// Response time histogram bounds, ms; percentiles are reported as the bound they fall under.
+const BOUNDS = [25, 50, 100, 250, 500, 1000, 2500, 5000, 10000];
+const SLOW_MS = 1000;
+const WINDOW_MINUTES = 60;
+const MAX_ENDPOINTS = 40;
+const LOG = process.env.PSU_REQUEST_LOG !== "off";
+// Docker and the proxy ask these every few seconds; they would drown the log and the counters.
+const QUIET = new Set(["/api/health", "/api/ready"]);
+
+const fresh = () => ({
+  requests: 0,
+  notModified: 0,
+  clientErrors: 0,
+  serverErrors: 0,
+  limited: 0,
+  timeouts: 0,
+  sourceErrors: 0,
+  slow: 0,
+  histogram: Array(BOUNDS.length + 1).fill(0),
+  endpoints: {},
+  clients: new Map(),
+  sourceFailures: 0,
+});
+
+const started = new Date().toISOString();
+const total = fresh();
+// One bucket per minute of the last hour.
+const minutes = new Map();
+
+function bucket(now = Date.now()) {
+  const minute = Math.floor(now / 60000);
+  let b = minutes.get(minute);
+  if (!b) {
+    minutes.set(minute, (b = fresh()));
+    for (const key of minutes.keys()) if (key <= minute - WINDOW_MINUTES) minutes.delete(key);
+  }
+  return b;
+}
+
+/**
+ * The client's address without its last part (IPv4 /24, IPv6 /48): enough to tell one runaway
+ * client from many students, without keeping anyone's exact address.
+ */
+export function anonymize(ip = "") {
+  const v4 = ip.replace(/^::ffff:/, "");
+  if (/^\d+\.\d+\.\d+\.\d+$/.test(v4)) return v4.replace(/\.\d+$/, ".0");
+  if (ip.includes(":")) return ip.split(":").slice(0, 3).join(":") + "::";
+  return ip || "unknown";
+}
+
+/** "/api/original/0fcb72d4cc36" → "/api/original/:id": one counter per endpoint, not per document. */
+export function endpointOf(path) {
+  return path
+    .split("/")
+    .map((part) => (/^[0-9a-f]{12,}$/i.test(part) || /^\d+$/.test(part) ? ":id" : part))
+    .join("/");
+}
+
+/** The upper bound (ms) under which a share `q` of the counted responses fell. */
+export function percentile(histogram, q) {
+  const count = histogram.reduce((a, b) => a + b, 0);
+  if (!count) return null;
+  let seen = 0;
+  for (let i = 0; i < histogram.length; i++) {
+    seen += histogram[i];
+    if (seen >= q * count) return BOUNDS[i] ?? `>${BOUNDS.at(-1)}`;
+  }
+  return null;
+}
+
+function count(b, { status, ms, code, endpoint, client }) {
+  b.requests++;
+  if (status === 304) b.notModified++;
+  else if (status >= 500) b.serverErrors++;
+  else if (status >= 400) b.clientErrors++;
+  if (status === 429) b.limited++;
+  if (code === "timeout") b.timeouts++;
+  if (code === "source_unavailable" || code === "source_timeout") b.sourceErrors++;
+  if (ms >= SLOW_MS) b.slow++;
+  const i = BOUNDS.findIndex((bound) => ms <= bound);
+  b.histogram[i < 0 ? BOUNDS.length : i]++;
+  // Scanners ask for anything; past a few dozen paths the rest share one counter.
+  const key = endpoint in b.endpoints || Object.keys(b.endpoints).length < MAX_ENDPOINTS ? endpoint : "other";
+  const e = (b.endpoints[key] ||= { requests: 0, slow: 0, errors: 0, msTotal: 0 });
+  e.requests++;
+  e.msTotal += ms;
+  if (ms >= SLOW_MS) e.slow++;
+  if (status >= 500) e.errors++;
+  if (b !== total) b.clients.set(client, (b.clients.get(client) || 0) + 1);
+}
+
+/** Express middleware for /api: times every request and counts and logs its answer. */
+export function requestLog() {
+  return (req, res, next) => {
+    const path = req.baseUrl + req.path;
+    if (QUIET.has(path)) return next();
+    const start = process.hrtime.bigint();
+    // The error code, read from the JSON body the client gets.
+    let code = null;
+    const json = res.json.bind(res);
+    res.json = (body) => {
+      if (body && typeof body === "object" && typeof body.code === "string") code = body.code;
+      return json(body);
+    };
+    res.on("finish", () => {
+      const ms = Math.round(Number(process.hrtime.bigint() - start) / 1e6);
+      const entry = {
+        status: res.statusCode,
+        ms,
+        code,
+        endpoint: endpointOf(path),
+        client: anonymize(req.ip),
+      };
+      count(total, entry);
+      count(bucket(), entry);
+      if (LOG)
+        console.log(
+          JSON.stringify({
+            t: new Date().toISOString(),
+            method: req.method,
+            path: req.originalUrl.slice(0, 200),
+            status: res.statusCode,
+            ms,
+            ...(code && { code }),
+            ...(res.get("Content-Length") && { bytes: Number(res.get("Content-Length")) }),
+            ip: entry.client,
+          }),
+        );
+    });
+    next();
+  };
+}
+
+/** A request to the university that failed (source.js): counted beside the API's own answers. */
+export function sourceFailed() {
+  total.sourceFailures++;
+  bucket().sourceFailures++;
+}
+
+function summary(b) {
+  const out = {
+    requests: b.requests,
+    notModified: b.notModified,
+    // Share of answers that cost the client nothing but headers.
+    notModifiedShare: b.requests ? Math.round((b.notModified / b.requests) * 100) / 100 : null,
+    clientErrors: b.clientErrors,
+    serverErrors: b.serverErrors,
+    limited: b.limited,
+    timeouts: b.timeouts,
+    sourceErrors: b.sourceErrors,
+    sourceFailures: b.sourceFailures,
+    slow: b.slow,
+    p50Ms: percentile(b.histogram, 0.5),
+    p95Ms: percentile(b.histogram, 0.95),
+    endpoints: Object.fromEntries(
+      Object.entries(b.endpoints)
+        .sort((a, z) => z[1].requests - a[1].requests)
+        .slice(0, 10)
+        .map(([key, e]) => [key, { requests: e.requests, avgMs: Math.round(e.msTotal / e.requests), slow: e.slow, errors: e.errors }]),
+    ),
+  };
+  return out;
+}
+
+/** The counters for /api/health: the last hour, with its busiest clients, and since the start. */
+export function trafficStatus(now = Date.now()) {
+  bucket(now);
+  const hour = fresh();
+  for (const b of minutes.values()) {
+    for (const key of ["requests", "notModified", "clientErrors", "serverErrors", "limited", "timeouts", "sourceErrors", "slow", "sourceFailures"])
+      hour[key] += b[key];
+    b.histogram.forEach((n, i) => (hour.histogram[i] += n));
+    for (const [key, e] of Object.entries(b.endpoints)) {
+      const h = (hour.endpoints[key] ||= { requests: 0, slow: 0, errors: 0, msTotal: 0 });
+      h.requests += e.requests;
+      h.slow += e.slow;
+      h.errors += e.errors;
+      h.msTotal += e.msTotal;
+    }
+    for (const [client, n] of b.clients) hour.clients.set(client, (hour.clients.get(client) || 0) + n);
+  }
+  const busiest = [...hour.clients.entries()].sort((a, z) => z[1] - a[1]).slice(0, 3);
+  return {
+    since: started,
+    lastHour: {
+      ...summary(hour),
+      clients: hour.clients.size,
+      busiestClients: busiest.map(([client, requests]) => ({ client, requests })),
+    },
+    total: summary(total),
+  };
+}
--- a/server/source.js
+++ b/server/source.js
@@ -4,6 +4,7 @@ import { createHash } from "node:crypto";
 import { parseWeeksDocx, parseBellsDocx } from "./calendar.js";
 import { apiError, sourceError } from "./errors.js";
 import { DATA } from "./paths.js";
+import { sourceFailed } from "./metrics.js";
 import {
  academicStartYear,
  assignSemesters,
@@ -78,6 +79,7 @@ export async function request(path, method = "GET") {
    }
    return Buffer.concat(chunks);
  } catch (error) {
+    sourceFailed();
    throw sourceError(error);
  }
 }
--- a/test/metrics.test.js
+++ b/test/metrics.test.js
@@ -0,0 +1,81 @@
+import { test, before, after, mock } from "node:test";
+import assert from "node:assert/strict";
+import { anonymize, endpointOf, percentile } from "../server/metrics.js";
+import { startApi } from "./support/nextcloud.js";
+
+test("Метрики: адрес без последней части, адреса документов в одном счётчике", () => {
+  assert.equal(anonymize("203.0.113.57"), "203.0.113.0");
+  assert.equal(anonymize("::ffff:192.168.1.20"), "192.168.1.0");
+  assert.equal(anonymize("2001:db8:85a3:8d3:1319:8a2e:370:7348"), "2001:db8:85a3::");
+  assert.equal(endpointOf("/api/original/0fcb72d4cc36c729aa"), "/api/original/:id");
+  assert.equal(endpointOf("/api/timetable"), "/api/timetable");
+  // Bounds 25, 50, 100, …: half the answers took up to 50 ms, 95% up to 1000 ms.
+  const histogram = [3, 3, 2, 1, 0, 1, 0, 0, 0, 0];
+  assert.equal(percentile(histogram, 0.5), 50);
+  assert.equal(percentile(histogram, 0.95), 1000);
+  assert.equal(percentile(Array(10).fill(0), 0.5), null);
+});
+
+// The API with its log on, a low request limit and the log lines caught.
+let api;
+const lines = [];
+before(async () => {
+  mock.method(console, "log", (line) => lines.push(line));
+  api = await startApi({ PSU_REQUEST_LOG: "on", PSU_API_RATE_LIMIT: "6" });
+});
+after(() => {
+  mock.restoreAll();
+  api?.stop();
+});
+const get = (path, headers) => fetch(api.base + path, { headers });
+
+test("Метрики: строка журнала на запрос и сводка в /api/health", async () => {
+  const groups = await get("/api/groups?" + new URLSearchParams({ q: "23-БА" }));
+  const doc = (await groups.json()).results.find((g) => g.group === "23-БА").fileId;
+  const path = "/api/timetable?" + new URLSearchParams({ doc, group: "23-БА", from: "2026-10-19", days: 7 });
+  const etag = (await get(path)).headers.get("etag");
+  assert.equal((await get(path, { "If-None-Match": etag, "Cache-Control": "max-age=0" })).status, 304);
+  assert.equal((await get("/api/nope")).status, 404);
+  // Health checks are neither logged nor counted.
+  await get("/api/health");
+  await get("/api/ready");
+
+  const logged = lines.map((l) => JSON.parse(l));
+  assert.equal(logged.length, 4);
+  assert.deepEqual(logged.map((l) => l.status), [200, 200, 304, 404]);
+  const notFound = logged.at(-1);
+  assert.equal(notFound.method, "GET");
+  assert.equal(notFound.path, "/api/nope");
+  assert.equal(notFound.code, "unknown_endpoint");
+  assert.equal(notFound.ip, "127.0.0.0");
+  assert.equal(typeof notFound.ms, "number");
+  assert.ok(!logged.some((l) => l.path.startsWith("/api/health")));
+
+  const { traffic } = await (await get("/api/health")).json();
+  const hour = traffic.lastHour;
+  assert.equal(hour.requests, 4);
+  assert.equal(hour.notModified, 1);
+  assert.equal(hour.notModifiedShare, 0.25);
+  assert.equal(hour.clientErrors, 1);
+  assert.equal(hour.serverErrors, 0);
+  assert.equal(hour.clients, 1);
+  assert.deepEqual(hour.busiestClients, [{ client: "127.0.0.0", requests: 4 }]);
+  assert.equal(hour.endpoints["/api/timetable"].requests, 2);
+  assert.ok(hour.p50Ms !== null && hour.p95Ms !== null);
+  assert.equal(traffic.total.requests, 4);
+});
+
+test("Метрики: лимит запросов и сбои университета считаются отдельно", async () => {
+  const catalog = await (await get("/api/catalog")).json();
+  const broken = catalog.files.find((f) => f.name === "Сломанный.docx");
+  assert.equal((await get(`/api/original/${broken.id}`)).status, 502);
+  // The limit of 6 is reached: 4 earlier requests, the catalog and the original above.
+  assert.equal((await get("/api/nope")).status, 429);
+  const { traffic } = await (await get("/api/health")).json();
+  const hour = traffic.lastHour;
+  assert.equal(hour.limited, 1);
+  assert.equal(hour.sourceErrors, 1);
+  assert.ok(hour.sourceFailures >= 1);
+  assert.equal(hour.serverErrors, 1);
+  assert.equal(hour.endpoints["/api/original/:id"].errors, 1);
+});
--- a/test/support/nextcloud.js
+++ b/test/support/nextcloud.js
@@ -73,6 +73,8 @@ export async function startApi(env = {}) {
    PSU_SOURCE_ORIGIN: `http://127.0.0.1:${source.address().port}`,
    PSU_DATA_DIR: data,
    PSU_SOURCE_TIMEOUT_MS: "500",
+    // The request log would drown the test output; the metrics test turns it on.
+    PSU_REQUEST_LOG: "off",
    ...env,
  });
  const { app } = await import("../../server/index.js");