SnapOtter/tests/benchmark/fault-injection.mjs

#!/usr/bin/env node
/**
 * Fault injection against a live stack with work in flight.
 *
 * Every scenario follows the same shape: put real jobs into the system, break
 * something while they are running, then reconcile against the database rather
 * than against whatever the HTTP client happened to see. That matters because
 * several of these faults deliberately destroy the client's connection: a
 * harness that only watched its own sockets would call a correctly recovered
 * job a loss.
 *
 * Verdict per scenario is built from seven independent checks:
 *   terminal          every job created in the window reached a terminal state
 *   artifacts         every completed job still serves valid output bytes
 *   noOrphanedOutputs no job's output bytes are stranded on disk unreferenced
 *   noDuplicates      no job completed more than once (one output set per job)
 *   drained           every queue returned to zero waiting and zero active
 *   healthy           the API answered /health again, and how long that took
 *   eventsLive        both completion paths still signal, not just finish
 *
 * noOrphanedOutputs was added for PERF-20260726-006. `terminal` alone does not
 * pin that finding: a fix that marked the stranded jobs failed would satisfy
 * it while the finished AVIF still on disk stayed unreachable, and `artifacts`
 * would not notice because it only visits completed jobs. So the workspace is
 * read directly and every job whose output directory holds real bytes must be
 * completed and must reference them.
 *
 * eventsLive was added for PERF-20260726-007, where every other check passed
 * while the application had quietly stopped signalling completion: jobs ran,
 * wrote correct output and reached terminal rows, but no client was ever told.
 * Reconciling against the database cannot see that, because the database is
 * exactly what stayed right. So both paths are exercised after the stack
 * settles: a job that finishes in milliseconds has to come back 200 inside the
 * sync window (which only the BullMQ QueueEvents stream can deliver), and a
 * client attached to a job that is still running has to be released by a live
 * pub/sub frame rather than by replay-on-connect.
 *
 *   node tests/benchmark/fault-injection.mjs --scenario all --out faults.jsonl
 */
import { execFile } from "node:child_process";
import { appendFileSync } from "node:fs";
import { readFile } from "node:fs/promises";
import { loadavg } from "node:os";
import { basename, dirname, join, resolve } from "node:path";
import { fileURLToPath } from "node:url";
import { promisify } from "node:util";
import { validateArtifact, waitForTerminalEvent } from "./lib/job-aware.mjs";

const execFileAsync = promisify(execFile);
const FIXTURE_ROOT = resolve(dirname(fileURLToPath(import.meta.url)), "../fixtures");
const POOLS = ["image", "media", "ai", "docs", "system"];
const TERMINAL = new Set(["completed", "failed", "canceled"]);

/** Long enough that the fault always lands mid-flight, short enough to iterate. */
const JOB_MIX = [
  {
    tool: "image/convert",
    file: "image/valid/stress-large.jpg",
    settings: { format: "avif", quality: 50 },
  },
  {
    tool: "image/convert",
    file: "image/valid/stress-large.jpg",
    settings: { format: "avif", quality: 40 },
  },
  {
    tool: "image/convert",
    file: "image/valid/stress-large.jpg",
    settings: { format: "avif", quality: 30 },
  },
  { tool: "image/resize", file: "image/valid/stress-large.jpg", settings: { width: 900 } },
  { tool: "pdf/rotate-pdf", file: "document/valid/multipage-6.pdf", settings: { angle: 180 } },
  { tool: "audio/trim-audio", file: "audio/valid/media-30s.wav", settings: { startS: 0, endS: 8 } },
];

/**
 * The two probes behind the `eventsLive` check.
 *
 * `sync` is milliseconds of real work, so a 202 can only mean the sync window
 * expired without the completion event arriving. `live` cannot finish inside
 * the window, so the client attaches while it is still running and only a live
 * pub/sub frame can end the stream; a frame that arrives instantly came from
 * replay-on-connect and proves nothing, which is why the wait is recorded.
 */
const SYNC_PROBE = {
  tool: "files/csv-json",
  file: "data/valid/tiny.csv",
  settings: { pretty: true },
};
const LIVE_PROBE = {
  tool: "image/convert",
  file: "image/valid/stress-large.jpg",
  settings: { format: "avif", quality: 50 },
};
/** Below this, the terminal frame was replayed rather than delivered live. */
const LIVE_FRAME_FLOOR_S = 0.5;
/** How long the pools get to drain once every job row is terminal. */
const DRAIN_TIMEOUT_MS = 120_000;

function parseArgs(argv) {
  const args = {};
  for (let index = 0; index < argv.length; index += 1) {
    if (!argv[index].startsWith("--")) continue;
    const key = argv[index].slice(2);
    const value = argv[index + 1];
    args[key] = value === undefined || value.startsWith("--") ? "true" : value;
    if (args[key] !== "true") index += 1;
  }
  return args;
}

const args = parseArgs(process.argv.slice(2));
const cfg = {
  baseUrl: args["base-url"] ?? process.env.PERF_BASE_URL ?? "http://127.0.0.1:13496",
  username: args.username ?? process.env.PERF_USERNAME ?? "admin",
  password: args.password ?? process.env.PERF_PASSWORD ?? "",
  app: args["app-container"] ?? process.env.PERF_APP_CONTAINER ?? "",
  pg: args["pg-container"] ?? process.env.PERF_PG_CONTAINER ?? "",
  redis: args["redis-container"] ?? process.env.PERF_REDIS_CONTAINER ?? "",
  redisPassword: args["redis-password"] ?? process.env.PERF_REDIS_PASSWORD ?? "snapotter",
  out: args.out ?? "",
  injectAfterMs: Number(args["inject-after-ms"] ?? 6000),
  settleMs: Number(args["settle-ms"] ?? 240_000),
};

function emit(record) {
  const line = `${JSON.stringify({ ts: new Date().toISOString(), ...record })}\n`;
  if (cfg.out) appendFileSync(cfg.out, line);
  else process.stdout.write(line);
}

function log(message) {
  process.stderr.write(`[${new Date().toISOString().slice(11, 19)}] ${message}\n`);
}

const sleep = (ms) => new Promise((done) => setTimeout(done, ms));

async function docker(...argv) {
  const { stdout } = await execFileAsync("docker", argv, { timeout: 120_000 });
  return stdout.trim();
}

async function psql(sql) {
  return docker("exec", cfg.pg, "psql", "-U", "snapotter", "-d", "snapotter", "-tAc", sql);
}

async function login() {
  const response = await fetch(new URL("/api/auth/login", cfg.baseUrl), {
    method: "POST",
    headers: { "content-type": "application/json" },
    body: JSON.stringify({ username: cfg.username, password: cfg.password }),
  });
  if (!response.ok) throw new Error(`login returned HTTP ${response.status}`);
  return (await response.json()).token;
}

async function submit(token, spec, fixtures) {
  const form = new FormData();
  const fixture = fixtures.get(spec.file);
  form.append("file", new Blob([fixture]), basename(spec.file));
  form.append("settings", JSON.stringify(spec.settings));
  try {
    const response = await fetch(new URL(`/api/v1/tools/${spec.tool}`, cfg.baseUrl), {
      method: "POST",
      headers: { authorization: `Bearer ${token}` },
      body: form,
      signal: AbortSignal.timeout(120_000),
    });
    const text = await response.text();
    return { tool: spec.tool, status: response.status, body: text.slice(0, 200) };
  } catch (error) {
    return { tool: spec.tool, status: 0, clientError: String(error?.message ?? error) };
  }
}

/**
 * Prove the application can still tell a client that a job finished.
 *
 * Both paths run over Redis connections that only ever read once they are
 * established, which is what made PERF-20260726-007 invisible to every
 * database-side check: a consumer whose socket died without a reset keeps the
 * jobs running and the rows correct while nobody is ever notified.
 */
async function probeEventPaths(token, fixtures) {
  const syncStarted = performance.now();
  const sync = await submit(token, SYNC_PROBE, fixtures);
  const syncS = Number(((performance.now() - syncStarted) / 1000).toFixed(3));

  const live = await submit(token, LIVE_PROBE, fixtures);
  let liveTerminal = live.status === 200 ? "inline" : null;
  let liveWaitS = 0;
  if (live.status === 202) {
    const jobId = JSON.parse(live.body).jobId;
    const started = performance.now();
    liveTerminal = await waitForTerminalEvent({
      baseUrl: cfg.baseUrl,
      token,
      jobId,
      timeoutMs: 120_000,
      fetchImpl: fetch,
    })
      .then(() => "complete")
      .catch((error) => `error:${String(error?.message ?? error)}`);
    liveWaitS = Number(((performance.now() - started) / 1000).toFixed(3));
  }

  return {
    syncStatus: sync.status,
    syncS,
    syncClientError: sync.clientError,
    liveStatus: live.status,
    liveTerminal,
    liveWaitS,
    // "inline" means the encode beat the sync window, so no client ever
    // attached and the live path was not exercised. Rare, and not a pass.
    ok: sync.status === 200 && liveTerminal === "complete" && liveWaitS > LIVE_FRAME_FLOOR_S,
  };
}

async function jobsSince(iso) {
  const rows = await psql(
    `select id || '|' || status || '|' || attempts || '|' || coalesce(tool_id,'-') || '|' || coalesce(jsonb_array_length(output_refs),0) from jobs where created_at >= '${iso}'::timestamptz order by created_at`,
  );
  if (!rows) return [];
  return rows
    .split("\n")
    .filter(Boolean)
    .map((line) => {
      const [id, status, attempts, toolId, outputs] = line.split("|");
      return { id, status, attempts: Number(attempts), toolId, outputs: Number(outputs) };
    });
}

async function queueDepths() {
  const script = `local r={} for _,q in ipairs(ARGV) do r[#r+1]=redis.call('llen','bull:snapotter-'..q..':wait') r[#r+1]=redis.call('llen','bull:snapotter-'..q..':active') end return r`;
  const stdout = await docker(
    "exec",
    cfg.redis,
    "redis-cli",
    "-a",
    cfg.redisPassword,
    "--no-auth-warning",
    "eval",
    script,
    "0",
    ...POOLS,
  );
  const numbers = stdout.split("\n").map(Number);
  const depths = {};
  POOLS.forEach((pool, index) => {
    depths[pool] = { waiting: numbers[index * 2] ?? 0, active: numbers[index * 2 + 1] ?? 0 };
  });
  return depths;
}

async function waitHealthy(timeoutMs = 180_000) {
  const started = performance.now();
  while (performance.now() - started < timeoutMs) {
    try {
      const response = await fetch(new URL("/api/v1/health", cfg.baseUrl), {
        signal: AbortSignal.timeout(5000),
      });
      if (response.ok) return Number(((performance.now() - started) / 1000).toFixed(2));
    } catch {
      // The API is expected to be unreachable for part of every scenario.
    }
    await sleep(1000);
  }
  return null;
}

/**
 * Downloads a completed job's output and proves it is still valid bytes.
 *
 * The download URL comes out of the job row, not out of whatever the client
 * saw. Half these scenarios destroy the client's connection on purpose, so the
 * database is the only place the answer reliably survives. (`output-meta.json`
 * is written for batch and pipeline results only; a plain tool job stores its
 * URL in progress.result.downloadUrl and its object key in output_refs.)
 */
async function verifyArtifact(token, jobId) {
  const stored = await psql(
    `select coalesce(progress->'result'->>'downloadUrl', '/api/v1/download/' || id || '/' || regexp_replace(coalesce(output_refs->>0,''), '^.*/', '')) from jobs where id = '${jobId}'`,
  );
  const downloadUrl = stored.trim();
  if (!downloadUrl || downloadUrl.endsWith("/")) {
    return { jobId, ok: false, error: "job row carries no output reference" };
  }
  const response = await fetch(new URL(downloadUrl, cfg.baseUrl), {
    headers: { authorization: `Bearer ${token}` },
  });
  if (!response.ok) return { jobId, ok: false, error: `download HTTP ${response.status}` };
  const bytes = Buffer.from(await response.arrayBuffer());
  try {
    const artifact = validateArtifact(bytes, response.headers.get("content-type"));
    return { jobId, ok: true, bytes: artifact.outputSize, mime: artifact.outputMime };
  } catch (error) {
    return { jobId, ok: false, error: String(error?.message ?? error) };
  }
}

/**
 * Finds output bytes that survived the fault but are unreachable through the
 * API because their job row never learned about them.
 *
 * The workspace is read from inside the app container rather than through the
 * API on purpose: the whole failure mode is a row that does not know its own
 * result, so asking the API would ask the very record that is wrong. Previews
 * are excluded because they are a derived convenience file, never the result.
 * Local storage only, which is what every scenario in this file runs on.
 */
async function findOrphanedOutputs(jobs) {
  const orphaned = [];
  for (const job of jobs) {
    const listing = await docker(
      "exec",
      cfg.app,
      "sh",
      "-c",
      `ls -1 /tmp/workspace/outputs/${job.id} 2>/dev/null || true`,
    ).catch(() => "");
    const files = listing
      .split("\n")
      .map((name) => name.trim())
      .filter((name) => name && !/^preview\./.test(name));
    if (files.length === 0) continue;
    if (job.status !== "completed" || job.outputs === 0) {
      orphaned.push({ id: job.id, status: job.status, outputRefs: job.outputs, files });
    }
  }
  return orphaned;
}

const SCENARIOS = {
  "app-restart": {
    what: "docker restart of the application container with jobs mid-flight",
    inject: () => docker("restart", "-t", "10", cfg.app),
  },
  "worker-sigkill": {
    what: "SIGKILL to the application container (ungraceful worker death)",
    inject: async () => {
      await docker("kill", "-s", "KILL", cfg.app);
      // restart: unless-stopped brings it back on its own; give Docker a beat.
      await sleep(2000);
      await docker("start", cfg.app).catch(() => "");
    },
  },
  "redis-outage": {
    what: "Redis stopped for 20s while jobs are queued, then restarted",
    inject: async () => {
      await docker("stop", "-t", "5", cfg.redis);
      await sleep(20_000);
      await docker("start", cfg.redis);
    },
  },
  "postgres-outage": {
    what: "Postgres stopped for 20s while jobs are running, then restarted",
    inject: async () => {
      await docker("stop", "-t", "5", cfg.pg);
      await sleep(20_000);
      await docker("start", cfg.pg);
    },
  },
  "network-partition": {
    what: "Postgres and Redis detached from the stack network for 20s, then reattached",
    inject: async () => {
      // Detaching the dependencies rather than the app is deliberate. Pulling
      // the app off the network would also tear down its published-port
      // endpoint, so the harness would be measuring a lost port mapping rather
      // than how the application copes with unreachable dependencies.
      const network = await networkOf(cfg.pg);
      await docker("network", "disconnect", network, cfg.pg);
      await docker("network", "disconnect", network, cfg.redis);
      await sleep(20_000);
      await docker("network", "connect", "--alias", "postgres", network, cfg.pg);
      await docker("network", "connect", "--alias", "redis", network, cfg.redis);
    },
  },
  "redis-readdress": {
    what: "Redis leaves the network for 20s and comes back at a different address",
    /**
     * The minimal form of PERF-20260726-007, and the reason that finding was
     * filed as needing isolation: it is what "network-partition" degenerates
     * into whenever Docker hands Postgres the address Redis had. A connection
     * parked on a blocking read has nothing left to send, so it never draws a
     * reset, so ioredis never reconnects it. Moving Redis explicitly makes that
     * deterministic instead of dependent on reattachment order, and it is the
     * harsher half of the pair: with the old address vacated rather than taken
     * over by a live host, not even a write draws a reset.
     */
    inject: async () => {
      const network = await networkOf(cfg.redis);
      const subnet = await docker(
        "network",
        "inspect",
        "--format",
        "{{(index .IPAM.Config 0).Subnet}}",
        network,
      );
      const base = subnet.split("/")[0].split(".").slice(0, 3).join(".");
      const current = await containerAddress(cfg.redis);
      const target = current.endsWith(".200") ? `${base}.201` : `${base}.200`;
      await docker("network", "disconnect", network, cfg.redis);
      await sleep(20_000);
      await docker("network", "connect", "--alias", "redis", "--ip", target, network, cfg.redis);
    },
  },
};

async function networkOf(container) {
  return docker(
    "inspect",
    "--format",
    "{{range $k,$v := .NetworkSettings.Networks}}{{$k}}{{end}}",
    container,
  );
}

async function containerAddress(container) {
  return docker(
    "inspect",
    "--format",
    "{{range .NetworkSettings.Networks}}{{.IPAddress}}{{end}}",
    container,
  );
}

async function restartCount(container) {
  return Number(await docker("inspect", "--format", "{{.RestartCount}}", container));
}

async function runScenario(name, fixtures) {
  const scenario = SCENARIOS[name];
  log(`scenario ${name}: ${scenario.what}`);
  const token = await login();
  const restartsBefore = {
    app: await restartCount(cfg.app),
    redis: await restartCount(cfg.redis),
    postgres: await restartCount(cfg.pg),
  };
  const since = (await psql("select (now() - interval '2 seconds')::text")).trim();

  const submissions = JOB_MIX.map((spec) => submit(token, spec, fixtures));
  await sleep(cfg.injectAfterMs);

  const inFlight = await jobsSince(since);
  const injectedAt = new Date().toISOString();
  let injectError = null;
  try {
    await scenario.inject();
  } catch (error) {
    injectError = String(error?.message ?? error);
  }

  const recoveredInS = await waitHealthy();
  const admissions = await Promise.all(submissions);

  // Reconcile against the database: several scenarios kill the client's socket
  // on purpose, so the HTTP replies are evidence about the client, not the job.
  const freshToken = await login().catch(() => token);
  const settleStarted = performance.now();
  const deadline = Date.now() + cfg.settleMs;
  let jobs = [];
  let stuck = [];
  while (Date.now() < deadline) {
    jobs = await jobsSince(since).catch(() => []);
    stuck = jobs.filter((job) => !TERMINAL.has(job.status));
    if (jobs.length > 0 && stuck.length === 0) break;
    await sleep(3000);
  }
  // How long the last job took to reach a terminal state. Recovery that leans
  // on a periodic reconciler is legitimate but not free, so record the cost.
  const settledInS = Number(((performance.now() - settleStarted) / 1000).toFixed(2));

  const completed = jobs.filter((job) => job.status === "completed");
  const artifacts = [];
  for (const job of completed) {
    artifacts.push(await verifyArtifact(freshToken, job.id));
  }
  // BullMQ can still hold an active entry after every row is terminal, when a
  // completion landed on a connection that had to be re-established, and its
  // stalled-detection reaps that on its own schedule. Sampling once made this a
  // race, so wait for the drain the same way terminal state is waited for. An
  // unreadable depth is not a drain: an empty object would satisfy `every`.
  const drainStarted = performance.now();
  const drainDeadline = Date.now() + DRAIN_TIMEOUT_MS;
  let depths = {};
  let drained = false;
  while (Date.now() < drainDeadline) {
    depths = await queueDepths().catch(() => ({}));
    const pools = Object.values(depths);
    drained = pools.length > 0 && pools.every((d) => d.waiting === 0 && d.active === 0);
    if (drained) break;
    await sleep(3000);
  }
  const drainedInS = Number(((performance.now() - drainStarted) / 1000).toFixed(2));
  const duplicated = completed.filter((job) => job.outputs > 1);
  const orphanedOutputs = await findOrphanedOutputs(jobs);
  // Last, on a settled stack: the queues are empty by now, so a slow admission
  // here is the notification path failing rather than a busy pool.
  const eventPaths = await probeEventPaths(freshToken, fixtures).catch((error) => ({
    ok: false,
    probeError: String(error?.message ?? error),
  }));

  const checks = {
    terminal: stuck.length === 0,
    artifacts: artifacts.every((a) => a.ok),
    noOrphanedOutputs: orphanedOutputs.length === 0,
    noDuplicates: duplicated.length === 0,
    drained,
    healthy: recoveredInS !== null,
    eventsLive: eventPaths.ok,
  };
  const record = {
    kind: "fault",
    scenario: name,
    what: scenario.what,
    injectedAt,
    injectError,
    hostLoad: loadavg()[0].toFixed(2),
    submitted: JOB_MIX.length,
    inFlightAtInjection: inFlight.length,
    jobRows: jobs.length,
    byStatus: jobs.reduce((acc, job) => {
      acc[job.status] = (acc[job.status] ?? 0) + 1;
      return acc;
    }, {}),
    maxAttempts: Math.max(0, ...jobs.map((job) => job.attempts)),
    stuck: stuck.map((job) => ({ id: job.id, status: job.status, toolId: job.toolId })),
    admissions: admissions.map((a) => ({
      tool: a.tool,
      status: a.status,
      clientError: a.clientError,
    })),
    clientLosses: admissions.filter((a) => a.status === 0).length,
    artifactsVerified: artifacts.length,
    artifactFailures: artifacts.filter((a) => !a.ok),
    orphanedOutputs,
    duplicatedOutputs: duplicated.length,
    queueDepths: depths,
    drainedInS,
    eventPaths,
    recoveredInS,
    settledInS,
    restartsBefore,
    restartsAfter: {
      app: await restartCount(cfg.app),
      redis: await restartCount(cfg.redis),
      postgres: await restartCount(cfg.pg),
    },
    checks,
    verdict: Object.values(checks).every(Boolean) ? "pass" : "fail",
  };
  emit(record);
  log(`scenario ${name}: ${record.verdict} ${JSON.stringify(checks)}`);
  return record;
}

async function main() {
  if (!cfg.password) throw new Error("--password is required");
  const fixtures = new Map();
  for (const spec of [...JOB_MIX, SYNC_PROBE, LIVE_PROBE]) {
    if (!fixtures.has(spec.file))
      fixtures.set(spec.file, await readFile(join(FIXTURE_ROOT, spec.file)));
  }
  const requested = args.scenario ?? "all";
  const names = requested === "all" ? Object.keys(SCENARIOS) : requested.split(",");
  const records = [];
  for (const name of names) {
    if (!SCENARIOS[name]) throw new Error(`unknown scenario ${name}`);
    records.push(await runScenario(name, fixtures));
    await sleep(10_000);
  }
  emit({
    kind: "fault-summary",
    scenarios: records.length,
    passed: records.filter((r) => r.verdict === "pass").length,
    failed: records.filter((r) => r.verdict === "fail").map((r) => r.scenario),
  });
  if (records.some((r) => r.verdict === "fail")) process.exitCode = 1;
}

await main();