diff --git a/packages/controller/src/HostConnection.ts b/packages/controller/src/HostConnection.ts index 3080c1be..56d5d489 100644 --- a/packages/controller/src/HostConnection.ts +++ b/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; + // 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, }); diff --git a/test/controller/HostConnection.test.js b/test/controller/HostConnection.test.js new file mode 100644 index 00000000..7c86e278 --- /dev/null +++ b/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" }]); + }); + }); +});