diff --git a/README.md b/README.md index 3e3b7e5..d6b0d6c 100644 --- 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`, сервер пишет владельцу после проверок каталога: - появился новый документ — с его группами и подозрительными ячейками; - документ не читается; diff --git a/server/index.js b/server/index.js index 1dc0fd2..7cdefcb 100644 --- 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 }, }); }); diff --git a/server/metrics.js b/server/metrics.js new file mode 100644 index 0000000..290d8ce --- /dev/null +++ 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), + }; +} diff --git a/server/source.js b/server/source.js index 4334638..c04c248 100644 --- 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); } } diff --git a/test/metrics.test.js b/test/metrics.test.js new file mode 100644 index 0000000..b1a2715 --- /dev/null +++ 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); +}); diff --git a/test/support/nextcloud.js b/test/support/nextcloud.js index 8ddc351..1a7e593 100644 --- 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");