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() {