OmniRoute/tests/unit/stream-timing.test.ts

/**
 * tests/unit/stream-timing.test.ts
 *
 * Canonical stream instrumentation (open-sse/utils/streamTiming.ts):
 *  - TTFT = first-forwarded-SSE-chunk latency (NOT token-level) — documented
 *  - ITL = mean inter-chunk gap (chunk-latency proxy)
 *  - first-byte vs first-forward distinction
 *  - interruption marking
 *  - malformed/empty chunks do not corrupt timing
 */
import test from "node:test";
import assert from "node:assert/strict";
import { createStreamTiming, type StreamTiming } from "../../open-sse/utils/streamTiming.ts";

// streamTiming samples a high-resolution monotonic clock (performance.now).
// `setTimeout(N)` does NOT guarantee that clock advances by a full N ms before
// the callback runs: libuv schedules timers against its own cached loop clock,
// which can trail performance.now() by a fraction of a millisecond, so a freshly
// sampled performance.now() delta occasionally lands just under the nominal
// sleep. Lower-bound timing assertions allow this scheduling slack. Event-loop
// load only makes timers fire LATE (larger delta), never earlier, so the bound
// stays safe on slow CI while remaining tight enough to prove a real delay.
const TIMER_SLACK_MS = 5;

test("ttft() is null when nothing was forwarded", () => {
  const t = createStreamTiming();
  t.markByte();
  assert.equal(t.ttftMs(), null);
  assert.equal(t.avgItlMs(), null);
});

test("ttft() measures first-forwarded-chunk latency (byte vs forward distinguished)", async () => {
  const t = createStreamTiming();
  t.markByte(); // first upstream byte arrives immediately
  await new Promise((r) => setTimeout(r, 20));
  t.markForward(); // first chunk forwarded 20ms later
  const ttft = t.ttftMs();
  assert.ok(ttft !== null && ttft >= 20 - TIMER_SLACK_MS && ttft < 5000, `ttft=${ttft}`);
  assert.ok(t.firstByteAt !== null);
  assert.ok(t.firstByteAt! < t.firstForwardAt!, "first byte precedes first forward");
});

test("avgItlMs() measures mean inter-chunk gap across multiple chunks", async () => {
  const t = createStreamTiming();
  for (let i = 0; i < 4; i++) {
    t.markForward();
    await new Promise((r) => setTimeout(r, 10));
  }
  const itl = t.avgItlMs();
  assert.ok(itl !== null && itl >= 10 - TIMER_SLACK_MS && itl < 5000, `itl=${itl}`);
  assert.equal(t.forwardedChunks, 4);
});

test("empty chunks do not corrupt timing (markByte without forward)", () => {
  const t = createStreamTiming();
  t.markByte();
  t.markByte(); // duplicate bytes are idempotent for first-byte
  assert.equal(t.ttftMs(), null, "no forward → no ttft");
  t.markForward();
  assert.ok(t.ttftMs() !== null);
});

test("malformed/keepalive-only traffic (no forward) yields no ttft", () => {
  const t = createStreamTiming();
  // Simulate a provider that only sends keepalives/blank lines, never data.
  for (let i = 0; i < 5; i++) t.markByte();
  assert.equal(t.ttftMs(), null);
  assert.equal(t.forwardedChunks, 0);
});

test("interruption is recorded and does not reset other timing", async () => {
  const t = createStreamTiming();
  t.markForward();
  await new Promise((r) => setTimeout(r, 5));
  t.markForward();
  t.markInterrupted();
  assert.equal(t.interrupted, true);
  assert.ok(t.ttftMs() !== null);
  assert.ok(t.avgItlMs() !== null);
});

test("normal completion: totalMs() is monotonic and >= first-forward latency", async () => {
  const t = createStreamTiming();
  await new Promise((r) => setTimeout(r, 15));
  t.markForward();
  const total = t.totalMs();
  const ttft = t.ttftMs();
  assert.ok(total >= 15 - TIMER_SLACK_MS, `total=${total}`);
  assert.ok(ttft !== null && ttft <= total, "ttft must be <= total duration");
});

test("max inter-chunk samples are bounded (memory bound)", async () => {
  const t = createStreamTiming();
  for (let i = 0; i < 200; i++) t.markForward();
  assert.ok(t.interChunkGaps.length <= 32, `bounded to 32 samples, got ${t.interChunkGaps.length}`);
});

/**
 * Wall-clock robustness: TTFT/ITL must be sampled from a MONOTONIC clock, so a
 * mid-stream NTP correction or manual wall-clock adjustment cannot poison them.
 * These metrics feed the router (OTel, quality EWMA, usage_history.ttft_ms,
 * speedRanking), so a corrupted value degrades a healthy provider.
 *
 * We simulate a wall-clock jump by stubbing `Date.now` between marks. With the
 * fix (`performance.now`, monotonic) the injected jump has no effect. If the
 * seam ever regresses to `Date.now`, the injected jump leaks straight into the
 * reported metric and these assertions fail.
 */
function withStubbedDateNow(run: (jumpMs: (delta: number) => void) => void): void {
  const realNow = Date.now;
  let fake = realNow.call(Date);
  Date.now = () => fake;
  try {
    run((delta) => {
      fake += delta;
    });
  } finally {
    Date.now = realNow;
  }
}

test("forward wall-clock jump does not inflate TTFT (monotonic clock)", () => {
  withStubbedDateNow((jumpMs) => {
    const t = createStreamTiming();
    t.markByte();
    jumpMs(5_000); // +5s NTP step between first byte and first forward
    t.markForward();
    const ttft = t.ttftMs();
    // Real elapsed is sub-millisecond; a Date.now-based seam would report ~5000.
    assert.ok(ttft !== null && ttft >= 0 && ttft < 1_000, `ttft must ignore +5s wall jump, got ${ttft}`);
  });
});

test("backward wall-clock jump does not yield negative TTFT (monotonic clock)", () => {
  withStubbedDateNow((jumpMs) => {
    const t = createStreamTiming();
    t.markByte();
    jumpMs(-2_000); // clock stepped backwards between byte and forward
    t.markForward();
    const ttft = t.ttftMs();
    // A Date.now-based seam would report ~-2000, silently discarded downstream
    // by the `ttft >= 0` guard (invisible data loss).
    assert.ok(ttft !== null && ttft >= 0 && ttft < 1_000, `ttft must never go negative, got ${ttft}`);
  });
});

test("wall-clock jump does not corrupt inter-chunk ITL (monotonic clock)", () => {
  withStubbedDateNow((jumpMs) => {
    const t = createStreamTiming();
    t.markForward();
    jumpMs(3_000); // +3s NTP step between two forwarded chunks
    t.markForward();
    const itl = t.avgItlMs();
    // A Date.now-based seam would record a 3000ms gap; monotonic stays near 0.
    assert.ok(itl !== null && itl >= 0 && itl < 1_000, `itl must ignore +3s wall jump, got ${itl}`);
  });
});