ipx/tests/load/run.js

// Load tests: k6 against a scratch daemon with a catalogue the size of production's, for what
// the browser tests cannot show -- many people at once, and what that does to latency, to the
// database and to the healthcheck. The browser suite drives one person against a handful of
// feeds, one request at a time.
//
//   node tests/load/run.js [--postgres] [browse|listening|media|signin ...]     default: all four
//
// It builds a release binary (debug Argon2 alone takes a second a sign-in, which would measure
// the build, not ipx), serves generated feeds from this process, starts a daemon on its own
// config and data under /tmp/ipx-load, wiped first, seeds listeners, then runs each k6 script.
// While each runs, `ipx status` -- the Docker healthcheck -- is run every second, and the run
// fails if any answer takes as long as the healthcheck's 5s timeout.
//
// The daemon is on SQLite unless --postgres, which puts it in IPX_TEST_DATABASE_URL, the
// database the Rust tests use on Postgres too (ipodderx_test on the server production's is on, in
// /src/.envrc), in a schema of its own, ipx_load, made afresh each run (#139). Postgres's numbers
// are what production would see.
// IPX_LOAD_FEEDS sets the catalogue's size (1500, near production's), IPX_LOAD_USERS the
// listeners (100), IPX_LOAD_LOG=1 shows the daemon's log.
const http = require('http');
const fs = require('fs');
const path = require('path');
const { spawn, spawnSync, execFile, execFileSync } = require('child_process');

const repo = path.resolve(__dirname, '../..');
const root = '/tmp/ipx-load';
const WEB = 8793, GEN = 8794;
const FEEDS = Number(process.env.IPX_LOAD_FEEDS || 1500);
const USERS = Number(process.env.IPX_LOAD_USERS || 100);
// The first few feeds carry real files, downloaded for the media test.
const MEDIA = 4;
const ITEMS = 20;
const BASE = `http://127.0.0.1:${WEB}`;
const bin = path.join(repo, 'target/release/ipx');
const SCRIPTS = ['browse', 'listening', 'media', 'signin'];
const POSTGRES = process.argv.includes('--postgres');
const PG_URL = process.env.IPX_TEST_DATABASE_URL || '';
const PG_SCHEMA = 'ipx_load';
const env = {
  ...process.env,
  IPX_CONFIG: `${root}/config/config.toml`,
  IPX_DATA_DIR: `${root}/data`,
  IPX_LOG: 'ipx=info',
  IPX_LOG_FORMAT: 'json',
  // Nothing of the test reaches production's database or traces, or a paid API.
  // In its own schema, as Db::memory puts each Rust test, and with notices off, as url_for does.
  IPX_DATABASE_URL: POSTGRES
    ? `${PG_URL}${PG_URL.includes('?') ? '&' : '?'}options=-c%20search_path%3D${PG_SCHEMA}%20-c%20client_min_messages%3Dwarning`
    : '',
  OTEL_EXPORTER_OTLP_ENDPOINT: '',
  TYPESAFE_KEY: '',
};

// ---- the feeds ------------------------------------------------------------------------------

// Apple's categories, some with a subcategory, so the Directory has tiles and pages to draw.
const CATS = [['Technology'], ['News', 'Tech News'], ['Comedy'], ['Leisure', 'Video Games'],
  ['Society & Culture', 'Documentary'], ['Sports', 'Soccer'], ['Arts', 'Books'],
  ['Science', 'Astronomy'], ['History'], ['True Crime'], ['Business', 'Investing'],
  ['Education', 'Self-Improvement'], ['Health & Fitness', 'Mental Health'], ['Music']];
const esc = s => s.replace(/&/g, '&amp;').replace(/</g, '&lt;').replace(/"/g, '&quot;');
const now = Date.now();
// Every third feed is a blog: no files, as most of production's are.
const isBlog = n => n % 3 === 2 && n >= MEDIA;
function feedXml(n) {
  const [cat, sub] = CATS[n % CATS.length];
  const category = sub
    ? `<itunes:category text="${esc(cat)}"><itunes:category text="${esc(sub)}"/></itunes:category>`
    : `<itunes:category text="${esc(cat)}"/>`;
  const items = Array.from({ length: ITEMS }, (_, i) => `<item>
    <title>Episode ${ITEMS - i} of Show ${n}</title><guid>gen-${n}-${i}</guid>
    <pubDate>${new Date(now - (i * 3 + n % 3) * 86400e3).toUTCString()}</pubDate>
    <description>&lt;p&gt;Show ${n}, episode ${ITEMS - i}: an hour on the news, the weather and whatever came up.&lt;/p&gt;</description>
    ${isBlog(n) ? '' : `<itunes:duration>${1800 + i * 60}</itunes:duration>
    <enclosure url="http://127.0.0.1:${GEN}/media/${n}/${i}.mp3" length="${MEDIA_BYTES.length}" type="audio/mpeg"/>`}
  </item>`).join('');
  return `<?xml version="1.0"?><rss version="2.0" xmlns:itunes="http://www.itunes.com/dtds/podcast-1.0.dtd"><channel>
    <title>Generated Show ${n}</title><link>http://127.0.0.1:${GEN}/site/${n}</link>
    <description>Generated show number ${n}, for the load tests.</description>
    <itunes:image href="http://127.0.0.1:${GEN}/art/${n}.jpg"/>${category}${items}</channel></rss>`;
}
// A file whose every byte is known from its offset, so the media test can check that a range
// it asked for is the range it got, not merely that it got something that long. ID3 first, so
// ipx takes it for audio.
const mediaByte = k => (k * 31 + 7) & 255;
const MEDIA_BYTES = Buffer.from(Uint8Array.from({ length: 2 * 1024 * 1024 }, (_, k) => mediaByte(k)));
Buffer.from('ID3\x03\x00\x00\x00\x00\x00\x00', 'latin1').copy(MEDIA_BYTES);
const art = fs.readFileSync(path.join(repo, 'tests/ui/fixtures/art.jpg'));

function serveFeeds() {
  return http.createServer((req, res) => {
    const m = req.url.match(/^\/(feed|media|art)\/(\d+)/);
    if (m?.[1] === 'feed') { res.writeHead(200, { 'content-type': 'application/rss+xml' }); return res.end(feedXml(Number(m[2]))); }
    if (m?.[1] === 'media') { res.writeHead(200, { 'content-type': 'audio/mpeg', 'content-length': MEDIA_BYTES.length }); return res.end(MEDIA_BYTES); }
    if (m?.[1] === 'art') { res.writeHead(200, { 'content-type': 'image/jpeg' }); return res.end(art); }
    res.writeHead(404).end();
  }).listen(GEN, '127.0.0.1');
}
const feedId = n => `gen-${String(n).padStart(4, '0')}`;
const feedUrl = n => `http://127.0.0.1:${GEN}/feed/${n}.xml`;

// ---- the daemon -----------------------------------------------------------------------------

/// The load tests' schema dropped and made again, as /tmp/ipx-load is wiped. Only in a database
/// made for tests: the URL is production's server and role, and one slip of a name would
/// otherwise point this at production's database.
function freshPostgres() {
  const u = PG_URL && new URL(PG_URL);
  if (!u || !/_test$/.test(u.pathname)) {
    throw new Error('--postgres needs IPX_TEST_DATABASE_URL, a database whose name ends in _test (. /src/.envrc)');
  }
  psql(`DROP SCHEMA IF EXISTS ${PG_SCHEMA} CASCADE`, `CREATE SCHEMA ${PG_SCHEMA}`);
}

/// Statements run in the test database, given by its URL in psql's environment, not its
/// arguments, where every process on Tower could read the password.
function psql(...sql) {
  const u = new URL(PG_URL);
  const env = { ...process.env, PGHOST: u.hostname, PGPORT: u.port || '5432', PGUSER: decodeURIComponent(u.username),
    PGPASSWORD: decodeURIComponent(u.password), PGDATABASE: u.pathname.slice(1), PGOPTIONS: `-c search_path=${PG_SCHEMA}` };
  execFileSync('psql', ['-q', '-v', 'ON_ERROR_STOP=1', ...sql.flatMap(s => ['-c', s])], { env, stdio: ['ignore', 'ignore', 'inherit'] });
}

function writeConfig() {
  fs.rmSync(root, { recursive: true, force: true });
  for (const d of ['config', 'data', 'downloads']) fs.mkdirSync(path.join(root, d), { recursive: true });
  // Read into the database's catalogue on the first start, as an existing config.toml is. Only
  // the media feeds download: a forced scan of a listener's 30 feeds would otherwise fetch a
  // 2 MB episode of each, every time.
  const feeds = Array.from({ length: FEEDS }, (_, n) =>
    `[feeds.${feedId(n)}]\nurl = "${feedUrl(n)}"\nauto_download = ${n < MEDIA}\n`).join('\n');
  fs.writeFileSync(env.IPX_CONFIG, `
[general]
download_dir = "${root}/downloads"
socket = "${root}/ipx.sock"
schedule = "every 60m"
max_new_per_check = 1

[torrent]
enabled = false

[web]
enabled = true
bind = "127.0.0.1:${WEB}"
token = "loadtokenloadtokenloadtoken12345"
# Each k6 user signs in by name, as Cloudflare Access does in production: no password to hash
# for every one of a hundred listeners. Only the sign-in test uses a password.
trusted_header = "X-Load-User"
trusted_proxies = ["127.0.0.1"]
auto_create_users = true

${feeds}`);
}

/// Resolves with the first log line matching `test`, read from the daemon's JSON log, which it
/// writes to stderr.
function waitForLog(daemon, test, ms) {
  return new Promise((resolve, reject) => {
    let buf = '';
    const timer = setTimeout(() => { daemon.stderr.off('data', on); reject(new Error(`no log line in ${ms / 1000}s for ${test}`)); }, ms);
    const on = chunk => {
      buf += chunk;
      let i;
      while ((i = buf.indexOf('\n')) >= 0) {
        const line = buf.slice(0, i); buf = buf.slice(i + 1);
        let ev; try { ev = JSON.parse(line); } catch { continue; }
        if (test(ev)) { clearTimeout(timer); daemon.stderr.off('data', on); return resolve(ev); }
      }
    };
    daemon.stderr.on('data', on);
  });
}

const as = name => ({ 'X-Load-User': name, 'Content-Type': 'application/json' });
async function api(name, url, opts = {}) {
  const r = await fetch(BASE + url, { ...opts, headers: { ...as(name), ...opts.headers } });
  if (!r.ok) throw new Error(`${opts.method || 'GET'} ${url} as ${name}: ${r.status} ${await r.text()}`);
  return r.status === 204 ? null : r.json().catch(() => null);
}
const opml = ns => `<?xml version="1.0"?><opml version="2.0"><head><title>load</title></head><body>${
  ns.map(n => `<outline type="rss" text="${feedId(n)}" xmlUrl="${feedUrl(n)}"/>`).join('')}</body></opml>`;

async function seed() {
  // The first account made is the admin.
  await api('admin', '/api/me');
  // Every listener subscribes to 30 feeds, overlapping as people's do; one OPML each, one scan.
  for (let u = 0; u < USERS; u++) {
    const mine = Array.from({ length: 30 }, (_, k) => (u * 7 + k * 41) % FEEDS);
    await api(`load-${u}`, '/api/opml', { method: 'POST', body: JSON.stringify({ xml: opml(mine) }) });
  }
  // The media test's listener takes the feeds with files. They may be downloaded already: the
  // first start subscribes the admin to the whole catalogue, so the first scan fetched them.
  for (let n = 0; n < MEDIA; n++) await api('listener', `/api/popular/${feedId(n)}`, { method: 'POST' });
  for (let t = Date.now(); ; await new Promise(r => setTimeout(r, 500))) {
    const got = await api('listener', '/api/entries?filter=downloaded&limit=50');
    if (got.entries.flatMap(e => e.enclosures).filter(x => x.path).length >= MEDIA) break;
    if (Date.now() - t > 120_000) throw new Error(`the listener's ${MEDIA} files did not download in 120s`);
  }
  // A password, for the sign-in test; the CLI hashes it as `ipx user add` always does.
  execFileSync(bin, ['user', 'add', 'piper'], { input: 'piperpassword', env });
}

// ---- the run --------------------------------------------------------------------------------

/// `ipx status` once a second until stopped: the slowest answer, and any that failed. Not
/// spawnSync: blocked in it, this process stops draining the daemon's log, the pipe fills, and
/// the daemon stalls writing its next line, which is the test measuring itself.
function watchHealth() {
  const seen = { slowest: 0, failed: 0 };
  let on = true;
  (async () => {
    while (on) {
      const t = Date.now();
      const ok = await new Promise(res => execFile(bin, ['status'], { env, timeout: 5000 }, err => res(!err)));
      seen.slowest = Math.max(seen.slowest, Date.now() - t);
      if (!ok) seen.failed++;
      await new Promise(res => setTimeout(res, 1000));
    }
  })();
  return () => { on = false; return seen; };
}

function k6(script) {
  return new Promise(resolve => {
    const run = spawn('k6', ['run', '--quiet', '-e', `BASE=${BASE}`, '-e', `USERS=${USERS}`, '-e', `FEEDS=${FEEDS}`,
      '-e', `DB=${POSTGRES ? 'postgres' : 'sqlite'}`,
      path.join(__dirname, `${script}.js`)], { stdio: 'inherit' });
    run.on('exit', code => resolve(code));
  });
}

(async () => {
  const only = process.argv.slice(2).filter(a => a !== '--postgres');
  for (const s of only) if (!SCRIPTS.includes(s)) { console.error(`no load test called ${s}: ${SCRIPTS.join(', ')}`); process.exit(2); }
  if (spawnSync('k6', ['version']).error) { console.error('k6 is not installed: see install.sh'); process.exit(2); }
  console.log('building the release binary...');
  execFileSync('cargo', ['build', '--release', '-q'], { cwd: repo, stdio: 'inherit' });

  const feeds = serveFeeds();
  writeConfig();
  if (POSTGRES) freshPostgres();
  console.log(`on ${POSTGRES ? 'Postgres' : 'SQLite'}`);
  // Its log kept out of this run's output, which is k6's; IPX_LOAD_LOG=1 shows it.
  const daemon = spawn(bin, ['daemon'], { env, stdio: ['ignore', process.env.IPX_LOAD_LOG ? 'inherit' : 'ignore', 'pipe'] });
  daemon.stderr.setEncoding('utf8');
  if (process.env.IPX_LOAD_LOG) daemon.stderr.on('data', d => process.stderr.write(d));
  // Stopped by hand, the daemon goes too, by its own PID, or it holds the ports for the next run.
  for (const sig of ['SIGINT', 'SIGTERM']) process.on(sig, () => { daemon.kill('SIGTERM'); process.exit(130); });
  let failed = 0;
  try {
    const t = Date.now();
    const first = await waitForLog(daemon, ev => ev.ev === 'scan_done' && ev.feeds > 0, 600_000);
    console.log(`first scan: ${first.feeds} feeds in ${((Date.now() - t) / 1000).toFixed(1)}s`);
    await seed();
    // The planner's statistics, as production's long-standing tables have them. A schema filled
    // seconds ago has none until autovacuum gets to it, which it did partway through a test, and
    // the search's p95 swung from 40ms to 166ms between runs with the plan it changed.
    if (POSTGRES) psql('ANALYZE');
    // The log is drained from here on, or the pipe fills and the daemon blocks writing to it.
    daemon.stderr.resume();
    for (const script of only.length ? only : SCRIPTS) {
      console.log(`\n=== ${script}`);
      const stop = watchHealth();
      const code = await k6(script);
      const health = stop();
      console.log(`ipx status: slowest ${health.slowest}ms, ${health.failed} failed`);
      if (code !== 0) { failed++; console.log(`${script}: thresholds failed (k6 exit ${code})`); }
      if (health.failed || health.slowest >= 5000) { failed++; console.log(`${script}: the healthcheck would have failed`); }
    }
  } catch (e) {
    console.error(e.message);
    failed++;
  } finally {
    // Its own PID, never a pkill: Tower sees production's ipx too (#38).
    daemon.kill('SIGTERM');
    feeds.close();
  }
  console.log(failed ? `\n${failed} failure(s)` : '\nall load tests passed');
  process.exit(failed ? 1 : 0);
})();