fix: detect Server_id collisions between live servers

e2e/README.md

@@ -68,7 +68,10 @@ refusal with any other stated reason fails the test.
 - `docker-compose.yml` — db + toxiproxy + `server-a`/`server-b`
   (`itzg/minecraft-server`); the mod jar path is injected via `PLAYERSYNC_JAR` by the
   runner script. The servers reach MariaDB through toxiproxy (`host = "toxiproxy"`);
-  its HTTP API is on `127.0.0.1:8474` for fault injection.
+  its HTTP API is on `127.0.0.1:8474` for fault injection. Each server has its own proxy, e.g.
+  `mariadb` (`:3306`) for server-a, `mariadb-b` (`:3307`) for server-b. So a toxic slows only
+  one server's DB traffic. A scenario that injects a fault must name the proxy of
+  the server it means to slow.
 - `Dockerfile` — builds `playersync-e2e-forge:1.20.1-47.4.0` on top of the pinned
   `itzg/minecraft-server` base, baking the Forge install into a layer. Both servers run
   that one image, so Forge is downloaded once at image build instead of by each server on

e2e/bot/lib.js

@@ -7,15 +7,26 @@
  */
 
 const crypto = require('crypto');
+const { execFile } = require('child_process');
+const path = require('path');
 const mineflayer = require('mineflayer');
 const { Rcon } = require('rcon-client');
 const mysql = require('mysql2/promise');
 
 const VERSION = '1.20.1';
 const HOST = process.env.MC_HOST || '127.0.0.1';
-const SERVER_A = { name: 'server-a', port: 25565, rconPort: 25575 };
-const SERVER_B = { name: 'server-b', port: 25566, rconPort: 25576 };
+// dbProxy is the toxiproxy proxy carrying *this* server's database traffic.
+// There is one per server (see toxiproxy.json), so a toxic slows the named server alone
+const SERVER_A = { name: 'server-a', port: 25565, rconPort: 25575, dbProxy: 'mariadb' };
+const SERVER_B = { name: 'server-b', port: 25566, rconPort: 25576, dbProxy: 'mariadb-b' };
 const RCON_PASSWORD = process.env.RCON_PASSWORD || 'e2e-rcon';
+const TOXIPROXY_URL = process.env.TOXIPROXY_URL || 'http://127.0.0.1:8474';
+
+const E2E_DIR = path.resolve(__dirname, '..');
+// The suite's own compose file.
+const COMPOSE_FILE = path.join(E2E_DIR, 'docker-compose.yml');
+// The mod config as the server actually loaded it, inside the container.
+const MOD_CONFIG = '/data/config/playersync-common.toml';
 
 // Minecraft reports a failed command as ordinary response text on an otherwise successful
 // send, so a silently no-op'd give/xp would only surface later as an unrelated timeout.
@@ -109,9 +120,132 @@ async function waitForPlayer(db, uuid, predicate, timeoutMs, description) {
   return waitFor(description, timeoutMs, async () => predicate(await queryPlayer(db, uuid)));
 }
 
+// The mod stores the inventory as Java's HashMap#toString of {slot=serialized-nbt}, one entry per
+// main-inventory slot, each value base64 of the stack's SNBT (use_legacy_serialization is off in
+// the e2e config). Summarize it as {itemId: count} so assertions read items, not an opaque blob.
+function summarizeInventory(blob) {
+  const summary = {};
+  const open = blob ? blob.indexOf('{') : -1;
+  const close = blob ? blob.lastIndexOf('}') : -1;
+  if (open < 0 || close <= open) return summary;
+  for (const entry of blob.slice(open + 1, close).split(',')) {
+    const equalIndex = entry.indexOf('=');
+    if (equalIndex < 0) continue;
+    const value = entry.slice(equalIndex + 1).trim();
+    if (!value.startsWith('B64:')) continue;
+    const snbt = Buffer.from(value.slice(4), 'base64').toString('utf8');
+    const id = /id:"([^"]+)"/.exec(snbt);
+    if (!id) continue; // empty slot, serialized as "{}"
+    const count = /Count:(\d+)b/.exec(snbt);
+    summary[id[1]] = (summary[id[1]] || 0) + (count ? Number(count[1]) : 0);
+  }
+  return summary;
+}
+
+// The stored inventory of a player as both the raw column and an {itemId: count} summary.
+async function dbInventory(db, uuid) {
+  const [rows] = await db.query('SELECT inventory FROM player_data WHERE uuid = ?', [uuid]);
+  if (!rows.length) return null;
+  // inventory is a mediumblob, so mysql2 hands back a Buffer.
+  const blob = rows[0].inventory == null ? null : rows[0].inventory.toString('utf8');
+  return { blob, items: summarizeInventory(blob) };
+}
+
+// Runs a command to completion and returns its combined output. maxBuffer is generous: a
+// server's whole console log comes back through here.
+function run(cmd, args, timeoutMs = 60_000) {
+  return new Promise((resolve, reject) => {
+    execFile(cmd, args, { timeout: timeoutMs, maxBuffer: 256 * 1024 * 1024 }, (err, stdout, stderr) => {
+      if (err) {
+        reject(new Error(`\`${cmd} ${args.join(' ')}\` failed: ${err.message}\n${stderr}`));
+        return;
+      }
+      resolve(stdout + stderr);
+    });
+  });
+}
+
+// `docker compose ...` against the suite's stack. `overlays` are extra compose files (absolute
+// paths, see composeFile) layered on top, which is how a scenario swaps a server's config mount.
+function compose(args, { overlays = [], timeoutMs } = {}) {
+  const files = [COMPOSE_FILE, ...overlays].flatMap((file) => ['-f', file]);
+  return run('docker', ['compose', ...files, ...args], timeoutMs);
+}
+
+// Absolute path of a compose file in e2e/, for compose()'s `overlays`.
+function composeFile(name) {
+  return path.join(E2E_DIR, name);
+}
+
+async function containerId(service) {
+  const id = (await compose(['ps', '-q', service])).trim();
+  if (!id) {
+    throw new Error(`No running container for ${service}: is the compose stack up?`);
+  }
+  return id;
+}
+
+// Occurrences of `marker` in a container's console log. Recreating a container resets its log,
+// so counts are only ever comparable within one container's lifetime.
+async function logCount(id, marker) {
+  const logs = await run('docker', ['logs', id], 120_000);
+  return logs.split('\n').filter((line) => line.includes(marker)).length;
+}
+
+// The name of a container's anonymous /data volume, so a recreate can drop the one it orphans.
+async function dataVolume(id) {
+  const out = await run('docker', ['inspect', '-f',
+    '{{range .Mounts}}{{if eq .Destination "/data"}}{{.Name}}{{end}}{{end}}', id]);
+  return out.trim();
+}
+
+// The value a server actually loaded for a mod config key, read from the config inside the
+// container rather than from the mount source, so a config that never reached /data is caught
+// here instead of masquerading as a build that misbehaves.
+async function loadedModConfig(id, key) {
+  const out = await run('docker', ['exec', id, 'grep', '-E', `^[[:space:]]*${key}`, MOD_CONFIG]);
+  const match = out.match(new RegExp(`${key}\\s*=\\s*(\\S+)`));
+  if (!match) {
+    throw new Error(`Could not read ${key} from ${MOD_CONFIG}: '${out.trim()}'`);
+  }
+  return match[1];
+}
+
 function createHarness(tag) {
   const log = (msg) => console.log(`[${tag}] ${new Date().toISOString()} ${msg}`);
 
+  // Fault injection: a toxiproxy latency toxic on one server's database traffic, or 0 to remove
+  // it. `server` is SERVER_A/SERVER_B — each has its own proxy, so the caller has to name the
+  // server it means to slow; slowing the other one silently tests nothing. Latency (not a paused
+  // DB) because some of the mod's queries run on the server thread, and a frozen DB deadlocks it.
+  async function setDbLatency(server, latencyMs) {
+    const toxic = `${TOXIPROXY_URL}/proxies/${server.dbProxy}/toxics/db_latency`;
+    const remove = async () => {
+      const res = await fetch(toxic, { method: 'DELETE' });
+      if (!res.ok && res.status !== 404) {
+        throw new Error(`Failed to remove ${server.dbProxy} latency toxic: HTTP ${res.status} ${await res.text()}`);
+      }
+    };
+    if (latencyMs <= 0) {
+      await remove();
+      log(`DB latency toxic removed from ${server.dbProxy} (${server.name})`);
+      return;
+    }
+    await remove(); // clear any toxic left by a previous KEEP=1 run so the POST can't 409
+    const res = await fetch(`${TOXIPROXY_URL}/proxies/${server.dbProxy}/toxics`, {
+      method: 'POST',
+      headers: { 'Content-Type': 'application/json' },
+      body: JSON.stringify({
+        name: 'db_latency', type: 'latency', stream: 'downstream',
+        attributes: { latency: latencyMs, jitter: 0 },
+      }),
+    });
+    if (!res.ok) {
+      throw new Error(`Failed to add ${server.dbProxy} latency toxic: HTTP ${res.status} ${await res.text()}`);
+    }
+    log(`DB latency toxic enabled on ${server.dbProxy} (${server.name}): ${latencyMs}ms per round-trip`);
+  }
+
   // Resolves with the spawned bot. `opts.timeoutMs` (optional) bounds the wait: if neither
   // spawn nor a pre-spawn failure lands in that window the promise rejects with
   // code JOIN_TIMEOUT and the connection is torn down, so an abandoned login cannot spawn
@@ -188,6 +322,22 @@ function createHarness(tag) {
     }
   }
 
+  // Like rcon(), but hands back the reply and waits longer for it. Used where the reply *is* the
+  // assertion (`tag <player> list`), or where the server thread may be mid-query on a
+  // latency-toxic'd DB and answer late (`save-all`) — rcon-client's default read timeout is 2s.
+  async function rconAsk(server, command, timeoutMs = 20_000) {
+    const conn = await Rcon.connect({
+      host: HOST, port: server.rconPort, password: RCON_PASSWORD, timeout: timeoutMs,
+    });
+    try {
+      const response = (await conn.send(command)).trim();
+      log(`rcon@${server.name} '${command}' -> ${response || '(no output)'}`);
+      return response;
+    } finally {
+      await conn.end().catch(() => { /* already closed */ });
+    }
+  }
+
   async function rcon(server, ...commands) {
     const conn = await Rcon.connect({ host: HOST, port: server.rconPort, password: RCON_PASSWORD });
     try {
@@ -212,7 +362,7 @@ function createHarness(tag) {
     }, timeoutMs);
   }
 
-  return { log, join, verifyServerUuid, rcon, startWatchdog };
+  return { log, join, verifyServerUuid, rcon, rconAsk, setDbLatency, startWatchdog };
 }
 
 module.exports = {
@@ -229,5 +379,14 @@ module.exports = {
   connectDb,
   queryPlayer,
   waitForPlayer,
+  summarizeInventory,
+  dbInventory,
+  run,
+  compose,
+  composeFile,
+  containerId,
+  logCount,
+  dataVolume,
+  loadedModConfig,
   createHarness,
 };

e2e/bot/test-disconnect-during-sync.js

@@ -24,11 +24,10 @@ const {
   offlineUUID, connectDb, queryPlayer, waitForPlayer, createHarness,
 } = require('./lib');
 
-const { log, join, rcon, startWatchdog } = createHarness('e2e-race');
+const { log, join, rcon, setDbLatency, startWatchdog } = createHarness('e2e-race');
 
 const BOT_NAME = 'RaceTester';
 const BOT_UUID = offlineUUID(BOT_NAME);
-const TOXIPROXY_URL = process.env.TOXIPROXY_URL || 'http://127.0.0.1:8474';
 
 const SEED_DIAMONDS = 3;
 // ~2s per DB round-trip. The sync task's online=1 write is several round-trips in, so this
@@ -42,37 +41,6 @@ const DISCONNECT_AFTER_MS = 2000;
 // online=1 write lands tens of seconds after the disconnect — poll generously for it.
 const SYNC_OBSERVE_MS = 90_000;
 
-async function removeDbLatency() {
-  const res = await fetch(`${TOXIPROXY_URL}/proxies/mariadb/toxics/db_latency`, { method: 'DELETE' });
-  if (!res.ok && res.status !== 404) {
-    throw new Error(`Failed to remove latency toxic: HTTP ${res.status} ${await res.text()}`);
-  }
-}
-
-async function setDbLatency(latencyMs) {
-  if (latencyMs > 0) {
-    // Clear any toxic left behind by a previous (KEEP=1) run so the POST can't 409.
-    await removeDbLatency();
-    const res = await fetch(`${TOXIPROXY_URL}/proxies/mariadb/toxics`, {
-      method: 'POST',
-      headers: { 'Content-Type': 'application/json' },
-      body: JSON.stringify({
-        name: 'db_latency',
-        type: 'latency',
-        stream: 'downstream',
-        attributes: { latency: latencyMs, jitter: 0 },
-      }),
-    });
-    if (!res.ok) {
-      throw new Error(`Failed to add latency toxic: HTTP ${res.status} ${await res.text()}`);
-    }
-    log(`DB latency toxic enabled: ${latencyMs}ms per round-trip`);
-  } else {
-    await removeDbLatency();
-    log('DB latency toxic removed');
-  }
-}
-
 async function main() {
   const db = await connectDb();
   try {
@@ -88,7 +56,7 @@ async function main() {
     log(`Seed complete: ${SEED_DIAMONDS} diamonds persisted, player offline`);
 
     // --- Phase 1: disconnect while the sync task is mid-flight, then watch the race ---
-    await setDbLatency(DB_LATENCY_MS);
+    await setDbLatency(SERVER_A, DB_LATENCY_MS);
     try {
       const raceBot = await join(SERVER_A, BOT_NAME);
       await sleep(DISCONNECT_AFTER_MS);
@@ -117,7 +85,7 @@ async function main() {
       await waitForPlayer(db, BOT_UUID, (p) => p && p.online === 0, SYNC_OBSERVE_MS,
         'online reverted to 0 after disconnect-during-sync (no ghost)');
     } finally {
-      await setDbLatency(0);
+      await setDbLatency(SERVER_A, 0);
     }
 
     // --- Phase 2: end-to-end confirmation that server B accepts the join and restores state.
@@ -141,7 +109,7 @@ startWatchdog(5 * 60_000);
 
 main().catch(async (err) => {
   // Best effort: never leave the latency toxic behind a failure.
-  try { await setDbLatency(0); } catch (ignored) { /* already gone */ }
+  try { await setDbLatency(SERVER_A, 0); } catch (ignored) { /* already gone */ }
   console.error(`[e2e-race] FAIL: ${err.stack || err}`);
   process.exit(1);
 });

e2e/bot/test-revert-respects-owner.js

@@ -25,12 +25,11 @@ const {
   offlineUUID, connectDb, queryPlayer, waitForPlayer, createHarness,
 } = require('./lib');
 
-const { log, join, startWatchdog } = createHarness('e2e-owner');
+const { log, join, setDbLatency, startWatchdog } = createHarness('e2e-owner');
 
 const BOT_NAME = 'OwnerGuardTester';
 const BOT_UUID = offlineUUID(BOT_NAME);
 const SERVER_B_ID = 2; // server-b's Server_id (see e2e/config/server-b/playersync-common.toml)
-const TOXIPROXY_URL = process.env.TOXIPROXY_URL || 'http://127.0.0.1:8474';
 
 const DB_LATENCY_MS = 2000;
 const DISCONNECT_AFTER_MS = 2000;
@@ -42,32 +41,6 @@ const SYNC_OBSERVE_MS = 90_000;
 // cannot pass merely because the revert had not fired yet.
 const CLOBBER_WATCH_MS = 90_000;
 
-async function removeDbLatency() {
-  const res = await fetch(`${TOXIPROXY_URL}/proxies/mariadb/toxics/db_latency`, { method: 'DELETE' });
-  if (!res.ok && res.status !== 404) {
-    throw new Error(`Failed to remove latency toxic: HTTP ${res.status} ${await res.text()}`);
-  }
-}
-
-async function setDbLatency(latencyMs) {
-  if (latencyMs > 0) {
-    await removeDbLatency(); // clear any toxic left by a previous KEEP=1 run so POST can't 409
-    const res = await fetch(`${TOXIPROXY_URL}/proxies/mariadb/toxics`, {
-      method: 'POST',
-      headers: { 'Content-Type': 'application/json' },
-      body: JSON.stringify({
-        name: 'db_latency', type: 'latency', stream: 'downstream',
-        attributes: { latency: latencyMs, jitter: 0 },
-      }),
-    });
-    if (!res.ok) throw new Error(`Failed to add latency toxic: HTTP ${res.status} ${await res.text()}`);
-    log(`DB latency toxic enabled: ${latencyMs}ms per round-trip`);
-  } else {
-    await removeDbLatency();
-    log('DB latency toxic removed');
-  }
-}
-
 async function main() {
   const db = await connectDb();
   try {
@@ -81,7 +54,7 @@ async function main() {
     log('Seed complete: player_data row exists, offline');
 
     // --- Phase 1: disconnect mid-sync, then race the revert against a move to server B ---
-    await setDbLatency(DB_LATENCY_MS);
+    await setDbLatency(SERVER_A, DB_LATENCY_MS);
     try {
       const raceBot = await join(SERVER_A, BOT_NAME);
       await sleep(DISCONNECT_AFTER_MS);
@@ -126,7 +99,7 @@ async function main() {
       }
       log("Server B's session intact: server A's stale revert did not clobber online");
     } finally {
-      await setDbLatency(0);
+      await setDbLatency(SERVER_A, 0);
     }
   } finally {
     await db.end();
@@ -139,7 +112,7 @@ async function main() {
 startWatchdog(5 * 60_000);
 
 main().catch(async (err) => {
-  try { await setDbLatency(0); } catch (ignored) { /* already gone */ }
+  try { await setDbLatency(SERVER_A, 0); } catch (ignored) { /* already gone */ }
   console.error(`[e2e-owner] FAIL: ${err.stack || err}`);
   process.exit(1);
 });