From 70c823ae9f9cf62d9c03f1017c32c1c5ced3c3aa Mon Sep 17 00:00:00 2001 From: bbassie <17990055+bbassie@users.noreply.github.com> Date: Sun, 13 Sep 2026 17:09:53 +0000 Subject: [PATCH] Correct misaligned instance names on forwarded log messages The instance name on a log line is whatever the host sent, so a host can attribute a line for one of its own instances to the wrong name. Compare it with the name the controller has on record and replace it when they differ. Host connections can live for days, so the warning suppression expires after five minutes instead of latching for the life of the connection, and the bogus instance and misaligned name warnings share it so the two together cannot spam the log. Co-Authored-By: Claude Opus 5 (1M context) --- packages/controller/src/HostConnection.ts | 54 ++++++++++++----- test/controller/HostConnection.test.js | 72 +++++++++++++++++++++-- 2 files changed, 106 insertions(+), 20 deletions(-) diff --git a/packages/controller/src/HostConnection.ts b/packages/controller/src/HostConnection.ts index 5bbc59e2..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,8 +21,8 @@ import HostRecord from "./HostRecord.js"; export default class HostConnection extends BaseConnection { private info: HostRecord; plugins: Map; - // Warn once per connection, a misbehaving host could log in a loop. - private _warnedBogusLogMessage = false; + // Shared by all log message warnings, a misbehaving host could log in a loop. + private _lastLogMessageWarnMs = Number.NEGATIVE_INFINITY; constructor( registerData: lib.RegisterHostData, @@ -300,19 +303,30 @@ export default class HostConnection extends BaseConnection { // 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 _assignedHere(instanceId: number) { + private _assignedInstance(instanceId: number) { const instance = this._controller.instances.get(instanceId); - return instance !== undefined && instance.config.get("instance.assigned_host") === this.id; + 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._assignedHere(event.instanceId)) { + 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._assignedHere(save.instanceId))) { + if (event.updates.some(save => !this._assignedInstance(save.instanceId))) { logger.warn(`Got bogus save updates from host id ${this.id}`); return; } @@ -344,16 +358,26 @@ export default class HostConnection extends BaseConnection { // 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 && !this._assignedHere(info.instance_id)) { - // 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. - if (!this._warnedBogusLogMessage) { - this._warnedBogusLogMessage = true; - logger.warn(`Got bogus log message for instance id ${info.instance_id}`); + 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; + } } - delete info.instance_id; - delete info.instance_name; } this._controller.clusterLogger.log({ diff --git a/test/controller/HostConnection.test.js b/test/controller/HostConnection.test.js index fe884c98..7c86e278 100644 --- a/test/controller/HostConnection.test.js +++ b/test/controller/HostConnection.test.js @@ -21,15 +21,20 @@ class MockSaves { deleteMany(saves) { for (const s of saves) { this.saves.delete(s.id); } } } -// Mock instances manager where instance id -> assigned host id. -function makeInstances(assignments) { +// 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: name => (name === "instance.assigned_host" ? host : undefined) } }; + return { config: { get(field) { + if (field === "instance.assigned_host") { return host; } + if (field === "instance.name") { return names.get(id); } + return undefined; + } } }; }, }; } @@ -80,16 +85,34 @@ describe("controller/src/HostConnection", function() { 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"]]); - function run(hostId, info) { + 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), + 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; } @@ -100,6 +123,45 @@ describe("controller/src/HostConnection", function() { 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() {