Merge pull request #1036 from bbassie/fix/host-save-details-ownership

Reject save detail updates for instances not on the sending host

packages/controller/src/HostConnection.ts

@@ -9,6 +9,9 @@ import InstanceRecord from "./InstanceRecord.js";
 import HostRecord from "./HostRecord.js";
 
 
+// How long log message warnings are suppressed for after one is logged.
+const logMessageWarnIntervalMs = 5 * 60 * 1000;
+
 /**
  * Represents the connection to a host
  *
@@ -18,6 +21,8 @@ import HostRecord from "./HostRecord.js";
 export default class HostConnection extends BaseConnection {
 	private info: HostRecord;
 	plugins: Map<string, string>;
+	// Shared by all log message warnings, a misbehaving host could log in a loop.
+	private _lastLogMessageWarnMs = Number.NEGATIVE_INFINITY;
 
 	constructor(
 		registerData: lib.RegisterHostData,
@@ -295,7 +300,37 @@ export default class HostConnection extends BaseConnection {
 		await this.send(new lib.SyncUserListsEvent(adminlist, banlist, whitelist));
 	}
 
+	// A host may only report on instances assigned to it. Otherwise any host
+	// could speak for an instance on a different host. See
+	// handleInstanceStatusChangedEvent.
+	private _assignedInstance(instanceId: number) {
+		const instance = this._controller.instances.get(instanceId);
+		return instance?.config.get("instance.assigned_host") === this.id ? instance : undefined;
+	}
+
+	// Host connections live for days, so the suppression expires instead of
+	// latching for the life of the connection.
+	private _warnLogMessage(message: string) {
+		const now = Date.now();
+		if (now - this._lastLogMessageWarnMs < logMessageWarnIntervalMs) {
+			return;
+		}
+		this._lastLogMessageWarnMs = now;
+		logger.warn(message);
+	}
+
 	async handleInstanceSaveDetailsUpdatesEvent(event: lib.InstanceSaveDetailsUpdatesEvent) {
+		// Otherwise any host could inject save records for, or wipe the save
+		// list of, an instance on a different host.
+		if (event.instanceId !== undefined && !this._assignedInstance(event.instanceId)) {
+			logger.warn(`Got bogus save updates for instance id ${event.instanceId}`);
+			return;
+		}
+		if (event.updates.some(save => !this._assignedInstance(save.instanceId))) {
+			logger.warn(`Got bogus save updates from host id ${this.id}`);
+			return;
+		}
+
 		const updates: lib.SaveDetails[] = [];
 		const deletes: lib.SaveDetails[] = [];
 		for (const save of event.updates) {
@@ -320,8 +355,33 @@ export default class HostConnection extends BaseConnection {
 	}
 
 	async handleLogMessageEvent(event: lib.LogMessageEvent) {
+		// Fields beyond level and message survive schema validation, so the
+		// instance a log line claims to come from is whatever the host sent.
+		const info: typeof event.info & { instance_id?: number, instance_name?: string } = { ...event.info };
+		if (info.instance_id !== undefined) {
+			const instance = this._assignedInstance(info.instance_id);
+			if (!instance) {
+				// Demote to a host level line instead of dropping it. The host did
+				// log this, it just does not get to pin it on someone else's
+				// instance, and a host racing a reassignment still gets heard.
+				this._warnLogMessage(`Got bogus log message for instance id ${info.instance_id}`);
+				delete info.instance_id;
+				delete info.instance_name;
+			} else {
+				// The name the host sent may be stale or made up, ours is authoritative.
+				const name = instance.config.get("instance.name");
+				if (info.instance_name !== name) {
+					this._warnLogMessage(
+						`Got log message for instance id ${info.instance_id} named ` +
+						`${info.instance_name} which is named ${name} on the controller`
+					);
+					info.instance_name = name;
+				}
+			}
+		}
+
 		this._controller.clusterLogger.log({
-			...event.info,
+			...info,
 			host_id: this.id,
 			host_name: this.info.name,
 		});

test/controller/HostConnection.test.js

@@ -0,0 +1,187 @@
+import assert from "node:assert/strict";
+import * as lib from "@clusterio/lib";
+import { HostConnection } from "@clusterio/controller";
+
+function makeSave(instanceId, name) {
+	return new lib.SaveDetails(instanceId, "file", name, 0, 0, false, false, 0, false);
+}
+
+// Mock saves datastore backed by a Map keyed on SaveDetails.id.
+class MockSaves {
+	constructor(saves = []) {
+		this.saves = new Map(saves.map(s => [s.id, s]));
+	}
+
+	get(id) { return this.saves.get(id); }
+
+	values() { return this.saves.values(); }
+
+	setMany(saves) { for (const s of saves) { this.saves.set(s.id, s); } }
+
+	deleteMany(saves) { for (const s of saves) { this.saves.delete(s.id); } }
+}
+
+// Mock instances manager where instance id -> assigned host id, and
+// optionally instance id -> the name the controller has on record.
+function makeInstances(assignments, names = new Map()) {
+	return {
+		get(id) {
+			if (!assignments.has(id)) {
+				return undefined;
+			}
+			const host = assignments.get(id);
+			return { config: { get(field) {
+				if (field === "instance.assigned_host") { return host; }
+				if (field === "instance.name") { return names.get(id); }
+				return undefined;
+			} } };
+		},
+	};
+}
+
+describe("controller/src/HostConnection", function() {
+	describe(".handleInstanceSaveDetailsUpdatesEvent()", function() {
+		// Instance 1 is on host 10, instance 2 is on host 20.
+		const assignments = new Map([[1, 10], [2, 20]]);
+
+		// Inherit the prototype, handlers call other methods on this.
+		function run(hostId, saves, event) {
+			const saveStore = new MockSaves(saves);
+			const ctx = Object.assign(Object.create(HostConnection.prototype), {
+				info: { id: hostId },
+				_controller: { instances: makeInstances(assignments), saves: saveStore },
+			});
+			ctx.handleInstanceSaveDetailsUpdatesEvent(event);
+			return saveStore;
+		}
+
+		it("applies updates for an instance assigned to this host", async function() {
+			const store = run(10, [], new lib.InstanceSaveDetailsUpdatesEvent([makeSave(1, "a.zip")], 1));
+			assert.deepEqual([...store.values()].map(s => s.id), ["1/a.zip"]);
+		});
+
+		it("sweeps missing saves for an instance assigned to this host", async function() {
+			const store = run(10, [makeSave(1, "old.zip")], new lib.InstanceSaveDetailsUpdatesEvent([], 1));
+			assert.deepEqual([...store.values()], []);
+		});
+
+		it("ignores injected saves for an instance on another host", async function() {
+			const store = run(30, [], new lib.InstanceSaveDetailsUpdatesEvent([makeSave(1, "HACKED.zip")]));
+			assert.deepEqual([...store.values()], [], "foreign save must not be stored");
+		});
+
+		it("ignores a wipe of an instance on another host", async function() {
+			const existing = makeSave(1, "keep.zip");
+			const store = run(30, [existing], new lib.InstanceSaveDetailsUpdatesEvent([], 1));
+			assert.deepEqual([...store.values()].map(s => s.id), ["1/keep.zip"], "existing save must survive");
+		});
+
+		it("ignores updates for a nonexistent instance", async function() {
+			const store = run(30, [], new lib.InstanceSaveDetailsUpdatesEvent([makeSave(999, "x.zip")]));
+			assert.deepEqual([...store.values()], []);
+		});
+	});
+
+	describe(".handleLogMessageEvent()", function() {
+		// Instance 1 is on host 10, instance 2 is on host 20.
+		const assignments = new Map([[1, 10], [2, 20]]);
+		const names = new Map([[1, "one"], [2, "two"]]);
+
+		let warnings = [];
+		let originalWarn;
+		beforeEach(function() {
+			warnings = [];
+			originalWarn = lib.logger.warn;
+			lib.logger.warn = msg => { warnings.push(msg); };
+		});
+		afterEach(function() {
+			lib.logger.warn = originalWarn;
+		});
+
+		// Handlers call other methods on this, so inherit the prototype.
+		function makeConnection(hostId) {
+			const logged = [];
+			const ctx = Object.assign(Object.create(HostConnection.prototype), {
+				info: { id: hostId, name: `host-${hostId}` },
+				_controller: {
+					instances: makeInstances(assignments, names),
+					clusterLogger: { log(entry) { logged.push(entry); } },
+				},
+			});
+			return [ctx, logged];
+		}
+
+		function run(hostId, info) {
+			const [ctx, logged] = makeConnection(hostId);
+			ctx.handleLogMessageEvent(new lib.LogMessageEvent(info));
+			return logged;
+		}
+
+		it("keeps instance fields for an instance assigned to this host", async function() {
+			const logged = run(10, { level: "info", message: "hello", instance_id: 1, instance_name: "one" });
+			assert.deepEqual(logged, [{
+				level: "info", message: "hello", instance_id: 1, instance_name: "one",
+				host_id: 10, host_name: "host-10",
+			}]);
+			assert.deepEqual(warnings, [], "a matching name must not warn");
+		});
+
+		it("corrects an instance name which does not match the controller", async function() {
+			const logged = run(10, { level: "info", message: "hi", instance_id: 1, instance_name: "wrong" });
+			assert.deepEqual(logged, [{
+				level: "info", message: "hi", instance_id: 1, instance_name: "one",
+				host_id: 10, host_name: "host-10",
+			}]);
+			assert.equal(warnings.length, 1, "a misaligned name must warn");
+		});
+
+		it("warns about a misaligned name again after five minutes", async function() {
+			const [ctx, logged] = makeConnection(10);
+			const info = { level: "info", message: "hi", instance_id: 1, instance_name: "wrong" };
+			ctx.handleLogMessageEvent(new lib.LogMessageEvent(info));
+			ctx.handleLogMessageEvent(new lib.LogMessageEvent(info));
+			assert.equal(warnings.length, 1, "the warning must not repeat immediately");
+
+			// Pretend the last warning happened just over five minutes ago.
+			ctx._lastLogMessageWarnMs -= 5 * 60 * 1000 + 1;
+			ctx.handleLogMessageEvent(new lib.LogMessageEvent(info));
+			assert.equal(warnings.length, 2, "the warning must resurface after the timeout");
+			assert.equal(logged.length, 3);
+			assert.deepEqual(logged.map(e => e.instance_name), ["one", "one", "one"]);
+		});
+
+		it("shares the warning suppression between bogus id and misaligned name", async function() {
+			const [ctx, logged] = makeConnection(10);
+			// Instance 2 is on host 20, so this line is bogus.
+			ctx.handleLogMessageEvent(new lib.LogMessageEvent(
+				{ level: "info", message: "hi", instance_id: 2, instance_name: "two" }
+			));
+			assert.equal(warnings.length, 1);
+			ctx.handleLogMessageEvent(new lib.LogMessageEvent(
+				{ level: "info", message: "hi", instance_id: 1, instance_name: "wrong" }
+			));
+			assert.equal(warnings.length, 1, "both warnings must share the suppression");
+			assert.equal(logged[1].instance_name, "one", "the name is still corrected while suppressed");
+		});
+
+		it("logs host level messages unchanged", async function() {
+			const logged = run(10, { level: "info", message: "hello" });
+			assert.deepEqual(logged, [{ level: "info", message: "hello", host_id: 10, host_name: "host-10" }]);
+		});
+
+		it("strips instance fields claiming an instance on another host", async function() {
+			const logged = run(30, { level: "info", message: "hi", instance_id: 1, instance_name: "one" });
+			assert.deepEqual(logged, [{ level: "info", message: "hi", host_id: 30, host_name: "host-30" }]);
+		});
+
+		it("strips instance fields claiming a nonexistent instance", async function() {
+			const logged = run(30, { level: "info", message: "hi", instance_id: 999, instance_name: "ghost" });
+			assert.deepEqual(logged, [{ level: "info", message: "hi", host_id: 30, host_name: "host-30" }]);
+		});
+
+		it("overrides host fields sent by the host", async function() {
+			const logged = run(10, { level: "info", message: "hi", host_id: 99, host_name: "spoofed" });
+			assert.deepEqual(logged, [{ level: "info", message: "hi", host_id: 10, host_name: "host-10" }]);
+		});
+	});
+});