psu-schedule/server/metrics.js

// 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);
  // Minute by minute, oldest first, empty minutes included: the dashboard's chart.
  const current = Math.floor(now / 60000);
  const series = Array.from({ length: WINDOW_MINUTES }, (_, i) => {
    const minute = current - WINDOW_MINUTES + 1 + i;
    const b = minutes.get(minute);
    return {
      t: new Date(minute * 60000).toISOString(),
      requests: b?.requests || 0,
      notModified: b?.notModified || 0,
      errors: (b?.clientErrors || 0) + (b?.serverErrors || 0),
      serverErrors: b?.serverErrors || 0,
      slow: b?.slow || 0,
    };
  });
  return {
    since: started,
    series,
    lastHour: {
      ...summary(hour),
      clients: hour.clients.size,
      busiestClients: busiest.map(([client, requests]) => ({ client, requests })),
    },
    total: summary(total),
  };
}