siftlode/frontend/src/lib/diagnostics.dom.test.ts

// @vitest-environment jsdom
//
// E22 S5: the consented level applied to the tab, and the stream it opens. The module keeps its state
// at module level (what is applied, the queue), so every test imports a fresh copy — and the log
// from that same copy, or it would be reading a different ring.
import { afterEach, beforeEach, describe, expect, it, vi } from "vitest";

const sent: unknown[][] = [];
const unloaded: unknown[][] = [];
let answer: () => Promise<unknown> = () => Promise.resolve({ ok: true, stored: 0 });

vi.mock("./api", async () => {
  const core = await vi.importActual<typeof import("./api/core")>("./api/core");
  return {
    HttpError: core.HttpError,
    DIAGNOSTICS_EVENTS_PATH: "/api/diagnostics/events",
    api: {
      sendLogEvents: (events: unknown[]) => {
        sent.push(events);
        return answer();
      },
      sendLogEventsOnUnload: (events: unknown[]) => void unloaded.push(events),
    },
  };
});

beforeEach(() => {
  vi.useFakeTimers();
  vi.resetModules();
  sent.length = 0;
  unloaded.length = 0;
  answer = () => Promise.resolve({ ok: true, stored: 0 });
});
let current: typeof import("./diagnostics") | null = null;
afterEach(() => {
  // A module copy left streaming would still hear `pagehide` in the next test.
  current?.applyDiagnostics(
    { level: "INFO", until: null, retention_days: 7, session_minutes: 60 },
    null,
    () => {},
  );
  current = null;
  vi.useRealTimers();
});

async function fresh() {
  const diagnostics = await import("./diagnostics");
  current = diagnostics;
  const logMod = await import("./log");
  const apiMod = await import("./api");
  return { ...diagnostics, ...logMod, HttpError: apiMod.HttpError };
}

const raised = (level: "DEBUG" | "TRACE", hours = 24) => ({
  level,
  until: new Date(Date.now() + hours * 3_600_000).toISOString(),
  retention_days: 7,
  session_minutes: 60,
});
const codes = (batch: unknown[] | undefined) =>
  (batch ?? []).map((e) => (e as { event: string }).event);

describe("diagnostics level", () => {
  it("the base level at boot sets INFO, streams nothing and logs nothing", async () => {
    const d = await fresh();
    d.applyDiagnostics(
      { level: "INFO", until: null, retention_days: 7, session_minutes: 60 },
      null,
      () => {},
    );
    d.log.info("nav.view", "x");
    await vi.advanceTimersByTimeAsync(60_000);
    expect(sent).toEqual([]);
    expect(d.enabled("DEBUG")).toBe(false);
    expect(codes(d.events())).toEqual(["nav.view"]);
  });

  it("a raised level streams only what happens after it, without its own request lines", async () => {
    const d = await fresh();
    d.log.info("before.consent", "not sent");
    d.applyDiagnostics(raised("DEBUG"), null, () => {});
    expect(d.enabled("DEBUG")).toBe(true);
    d.log.debug("ui.click", "click");
    d.log.request("INFO", "POST", { path: "/api/diagnostics/events", status: 200 }, "abcdef0123");
    d.log.request("INFO", "GET", { path: "/api/feed", status: 200 }, "abcdef0124");
    await vi.advanceTimersByTimeAsync(5_000);
    expect(sent).toHaveLength(1);
    expect(codes(sent[0])).toEqual(["diagnostics.level", "ui.click", "http.request"]);
    expect(JSON.stringify(sent[0])).not.toContain("/api/diagnostics/events");
  });

  it("sends in batches of at most 100, and a full batch goes without waiting", async () => {
    const d = await fresh();
    d.applyDiagnostics(raised("DEBUG"), null, () => {});
    for (let i = 0; i < 250; i++) d.log.debug("ui.click", `click ${i}`);
    await vi.advanceTimersByTimeAsync(0);
    expect(sent.map((b) => b.length)).toEqual([100]);
    await vi.advanceTimersByTimeAsync(5_000);
    await vi.advanceTimersByTimeAsync(5_000);
    expect(sent.every((b) => b.length <= 100)).toBe(true);
    expect(sent.flat()).toHaveLength(251); // the 250 clicks + the line that opened the stream
  });

  it("stops at once when the level is lowered, and drops what was not sent yet", async () => {
    const d = await fresh();
    d.applyDiagnostics(raised("TRACE"), null, () => {});
    d.log.trace("search.typed", "lofi");
    d.applyDiagnostics(
      { level: "INFO", until: null, retention_days: 7, session_minutes: 60 },
      null,
      () => {},
    );
    d.log.info("nav.view", "after");
    await vi.advanceTimersByTimeAsync(60_000);
    expect(sent).toEqual([]);
    expect(d.enabled("TRACE")).toBe(false);
  });

  it("lapses on its own timer and tells the app to refetch", async () => {
    const d = await fresh();
    const lapsed = vi.fn();
    d.applyDiagnostics(raised("DEBUG", 1), null, lapsed);
    await vi.advanceTimersByTimeAsync(3_600_000 + 1);
    expect(lapsed).toHaveBeenCalledOnce();
    expect(d.enabled("DEBUG")).toBe(false);
    sent.length = 0;
    d.log.info("nav.view", "after the lapse");
    await vi.advanceTimersByTimeAsync(10_000);
    expect(sent).toEqual([]);
  });

  it("an already-expired level is the base level", async () => {
    const d = await fresh();
    d.applyDiagnostics(raised("DEBUG", -1), null, () => {});
    expect(d.enabled("DEBUG")).toBe(false);
  });

  it("the server saying it is off stops the stream; being told to slow down keeps the batch", async () => {
    const d = await fresh();
    const lapsed = vi.fn();
    d.applyDiagnostics(raised("DEBUG"), null, lapsed);
    answer = () => Promise.reject(new d.HttpError(429, "slow down"));
    d.log.debug("ui.click", "kept for later");
    await vi.advanceTimersByTimeAsync(5_000);
    answer = () => Promise.reject(new d.HttpError(409, "off"));
    await vi.advanceTimersByTimeAsync(15_000);
    expect(codes(sent[1])).toEqual(codes(sent[0])); // the same batch, retried after the back-off
    expect(lapsed).toHaveBeenCalledOnce();
    expect(d.enabled("DEBUG")).toBe(false);
  });

  it("after a 429 nothing is sent until the back-off is over, however full the queue", async () => {
    const d = await fresh();
    d.applyDiagnostics(raised("DEBUG"), null, () => {});
    answer = () => Promise.reject(new d.HttpError(429, "slow down"));
    for (let i = 0; i < 99; i++) d.log.debug("ui.click", `click ${i}`);
    await vi.advanceTimersByTimeAsync(0);
    expect(sent).toHaveLength(1); // the full batch went at once, and was refused
    answer = () => Promise.resolve({ ok: true, stored: 0 });
    for (let i = 0; i < 50; i++) d.log.debug("ui.click", `more ${i}`);
    await vi.advanceTimersByTimeAsync(14_000);
    expect(sent).toHaveLength(1); // one POST per new event is exactly the storm to avoid
    await vi.advanceTimersByTimeAsync(1_000);
    expect(codes(sent[1])).toEqual(codes(sent[0]));
  });

  it("past the queue cap the oldest events go, a refused batch included", async () => {
    const d = await fresh();
    d.applyDiagnostics(raised("DEBUG"), null, () => {});
    answer = () => Promise.reject(new d.HttpError(429, "slow down"));
    for (let i = 0; i < 99; i++) d.log.debug("ui.click", `click ${i}`);
    await vi.advanceTimersByTimeAsync(0);
    answer = () => Promise.resolve({ ok: true, stored: 0 });
    for (let i = 99; i < 1_100; i++) d.log.debug("ui.click", `click ${i}`);
    await vi.advanceTimersByTimeAsync(60_000);
    const msgs = sent
      .slice(1)
      .flat()
      .map((e) => (e as { msg: string }).msg);
    expect(msgs).toHaveLength(1_000);
    expect(msgs[0]).toBe("click 100");
    expect(msgs[msgs.length - 1]).toBe("click 1099");
  });

  it("a batch refused after the level was lowered is not sent under a later consent", async () => {
    const d = await fresh();
    let refuse: (err: unknown) => void = () => {};
    answer = () => new Promise((_, reject) => (refuse = reject));
    d.applyDiagnostics(raised("DEBUG"), null, () => {});
    d.log.debug("ui.click", "under the first consent");
    await vi.advanceTimersByTimeAsync(5_000); // in flight
    d.applyDiagnostics(
      { level: "INFO", until: null, retention_days: 7, session_minutes: 60 },
      null,
      () => {},
    );
    refuse(new d.HttpError(429, "slow down"));
    await vi.advanceTimersByTimeAsync(0);
    answer = () => Promise.resolve({ ok: true, stored: 0 });
    d.applyDiagnostics(raised("TRACE"), null, () => {});
    await vi.advanceTimersByTimeAsync(60_000);
    const later = sent
      .slice(1)
      .flat()
      .map((e) => (e as { msg: string }).msg);
    expect(later).not.toContain("under the first consent");
    expect(later).toContain("diagnostics level raised");
  });

  it("a batch refused after a re-raise is still not sent: it was taken under the old consent", async () => {
    // The test above settles the refusal while the stream is STOPPED, so `unsubscribe` is what
    // blocks the requeue there. Here it settles after the new consent is already streaming — the
    // ordering only the `session` counter can catch, and the one that would leak events across a
    // withdrawal if it did not.
    const d = await fresh();
    let refuse: (err: unknown) => void = () => {};
    answer = () => new Promise((_, reject) => (refuse = reject));
    d.applyDiagnostics(raised("DEBUG"), null, () => {});
    d.log.debug("ui.click", "under the first consent");
    await vi.advanceTimersByTimeAsync(5_000); // in flight
    d.applyDiagnostics(
      { level: "INFO", until: null, retention_days: 7, session_minutes: 60 },
      null,
      () => {},
    );
    answer = () => Promise.resolve({ ok: true, stored: 0 });
    d.applyDiagnostics(raised("TRACE"), null, () => {});
    refuse(new d.HttpError(429, "slow down")); // only now does the old consent's batch come back
    await vi.advanceTimersByTimeAsync(60_000);
    const later = sent
      .slice(1)
      .flat()
      .map((e) => (e as { msg: string }).msg);
    expect(later).not.toContain("under the first consent");
    expect(later).toContain("diagnostics level raised");
  });

  it("a 409 for a batch taken under the old consent does not lapse the new one", async () => {
    const d = await fresh();
    const lapsed = vi.fn();
    let refuse: (err: unknown) => void = () => {};
    answer = () => new Promise((_, reject) => (refuse = reject));
    d.applyDiagnostics(raised("DEBUG"), null, lapsed);
    d.log.debug("ui.click", "under the first consent");
    await vi.advanceTimersByTimeAsync(5_000); // in flight
    d.applyDiagnostics(
      { level: "INFO", until: null, retention_days: 7, session_minutes: 60 },
      null,
      lapsed,
    );
    answer = () => Promise.resolve({ ok: true, stored: 0 });
    d.applyDiagnostics(raised("TRACE"), null, lapsed);
    refuse(new d.HttpError(409, "off"));
    await vi.advanceTimersByTimeAsync(60_000);
    expect(lapsed).not.toHaveBeenCalled();
    expect(d.enabled("TRACE")).toBe(true);
  });

  it("a 409 answering a batch the user themselves cancelled is not called a lapse", async () => {
    // "Alap" is the user revoking their own consent; the server answers the still-flying batch with
    // the same 409 a real expiry gets. Their own log must not tell them the consent ran out.
    const d = await fresh();
    const lapsed = vi.fn();
    let refuse: (err: unknown) => void = () => {};
    answer = () => new Promise((_, reject) => (refuse = reject));
    d.applyDiagnostics(raised("DEBUG"), null, lapsed);
    d.log.debug("ui.click", "under the consent");
    await vi.advanceTimersByTimeAsync(5_000); // in flight
    d.applyDiagnostics(
      { level: "INFO", until: null, retention_days: 7, session_minutes: 60 },
      null,
      lapsed,
    );
    refuse(new d.HttpError(409, "off"));
    await vi.advanceTimersByTimeAsync(0);
    expect(lapsed).not.toHaveBeenCalled();
    expect(d.events().map((e) => e.msg)).not.toContain("diagnostics level lapsed");
  });

  it("a refused batch that comes back to a full queue is what goes, not the events since", async () => {
    // The cap test above fills the queue AFTER the refusal landed, so the trim it measures is the
    // one on the subscribe path. This one has the queue already at the cap when the batch comes
    // back — the only state where the trim in the 429 handler decides anything.
    const d = await fresh();
    let refuse: (err: unknown) => void = () => {};
    answer = () => new Promise((_, reject) => (refuse = reject));
    d.applyDiagnostics(raised("DEBUG"), null, () => {});
    for (let i = 0; i < 99; i++) d.log.debug("ui.click", `old ${i}`);
    await vi.advanceTimersByTimeAsync(0); // the 100 oldest are in flight, the queue is empty
    for (let i = 0; i < 1_000; i++) d.log.debug("ui.click", `new ${i}`);
    answer = () => Promise.resolve({ ok: true, stored: 0 });
    refuse(new d.HttpError(429, "slow down")); // 1_000 + 100 back = 1_100, over the cap
    await vi.advanceTimersByTimeAsync(60_000);
    const msgs = sent
      .slice(1)
      .flat()
      .map((e) => (e as { msg: string }).msg);
    expect(msgs).toHaveLength(1_000);
    expect(msgs).not.toContain("old 0");
    expect([msgs[0], msgs[msgs.length - 1]]).toEqual(["new 0", "new 999"]);
  });

  it("a closing tab sends what is still waiting with a keepalive request", async () => {
    const d = await fresh();
    d.applyDiagnostics(raised("DEBUG"), null, () => {});
    d.log.debug("ui.click", "last click");
    window.dispatchEvent(new Event("pagehide"));
    expect(codes(unloaded[0])).toEqual(["diagnostics.level", "ui.click"]);
    expect(sent).toEqual([]);
  });
});