Merge pull request #1028 from bbassie/fix/instance-config-change-crash

Log errors from instance config change handlers instead of exiting the host

packages/host/src/Instance.ts

@@ -22,6 +22,11 @@ const scriptCommands = [
 	"/silent-command", "/sc",
 ];
 
+// Statuses the instance passes through on its way to running or stopped.
+const transitoryStatuses: ReadonlySet<Instance["_status"]> = new Set([
+	"starting", "stopping", "creating_save", "exporting_data",
+]);
+
 const instanceRconCommandDuration = new lib.Histogram(
 	"clusterio_instance_rcon_command_duration_seconds",
 	"Histogram of the RCON command duration from request to response.",
@@ -61,7 +66,7 @@ function applyAsConfig(name: string) {
 			// Replace spaces with non-break spaces and delimit by spaces.
 			// This does change the defined tags, but there doesn't seem to
 			// be a way to include a space into a tag from the console.
-			value = value.map(tag => tag.replace(/ /g, "\u00a0")).join(" ");
+			value = value.map(tag => String(tag).replace(/ /g, "\u00a0")).join(" ");
 		}
 		try {
 			await instance.sendRcon(`/config set ${name} ${value}`);
@@ -170,6 +175,7 @@ export default class Instance extends lib.Link {
 	_hadPlayersOnline = false;
 	_playerAutosaveSlot = 1;
 	_expectedUserUpdates: { action: string, name: string, reason: string }[] = [];
+	_settleWaiters: (() => void)[] = [];
 
 	constructor(
 		host: Host,
@@ -194,20 +200,18 @@ export default class Instance extends lib.Link {
 		this.hooks = new InstanceHooks(this.logger);
 
 		this._configFieldChanged = (field: string, curr: unknown, prev: unknown) => {
-			let hook = () => this.hooks.instanceConfigFieldChanged.invoke(field, curr, prev);
-
 			if (field === "factorio.shutdown_timeout") {
 				this.server.shutdownTimeoutMs = curr as number * 1000;
+			} else if (field === "factorio.max_concurrent_commands") {
+				this.server.maxConcurrentCommands = curr as number;
 			} else if (field === "factorio.settings") {
-				this.updateFactorioSettings(curr as any, prev as any).finally(hook);
+				this._applyWhenRunning(
+					"server settings", () => this.updateFactorioSettings(curr as any, prev as any)
+				);
 			} else if (field === "factorio.enable_whitelist") {
-				this.updateFactorioWhitelist(curr as any).finally(hook);
-			} else {
-				if (field === "factorio.max_concurrent_commands") {
-					this.server.maxConcurrentCommands = curr as number;
-				}
-				hook();
+				this._applyWhenRunning("whitelist", () => this.updateFactorioWhitelist(curr as any));
 			}
+			this.hooks.instanceConfigFieldChanged.invoke(field, curr, prev);
 		};
 		this.config.on("fieldChanged", this._configFieldChanged);
 
@@ -562,6 +566,13 @@ end`.replace(/\r?\n/g, " ");
 
 	notifyStatus(status: Instance["_status"]) {
 		this._status = status;
+		if (!transitoryStatuses.has(status)) {
+			const waiters = this._settleWaiters;
+			this._settleWaiters = [];
+			for (const resolve of waiters) {
+				resolve();
+			}
+		}
 		this.sendTo(
 			"controller",
 			new lib.InstanceStatusChangedEvent(
@@ -583,6 +594,26 @@ end`.replace(/\r?\n/g, " ");
 		return this._status;
 	}
 
+	/** Wait for a transitory status to settle and return the status settled on */
+	async _waitForSettledStatus() {
+		while (transitoryStatuses.has(this._status)) {
+			await new Promise<void>(resolve => this._settleWaiters.push(resolve));
+		}
+		return this._status;
+	}
+
+	/** Apply work to the running server, waiting out transitory statuses and skipping it if it stopped */
+	async _applyWhenRunning(description: string, fn: () => Promise<void>) {
+		if (await this._waitForSettledStatus() !== "running") {
+			return;
+		}
+		try {
+			await fn();
+		} catch (err: any) {
+			this.logger.error(`Error updating ${description}:\n${err.stack}`);
+		}
+	}
+
 	notifyExit() {
 		this._loadedSave = null;
 		this.notifyStatus("stopped");
@@ -1140,6 +1171,10 @@ end`.replace(/\r?\n/g, " ");
 	}
 
 	async handleInstanceAdminlistUpdateEvent(request: lib.InstanceAdminlistUpdateEvent) {
+		if (await this._waitForSettledStatus() !== "running") {
+			return;
+		}
+
 		const { name, admin } = request;
 		const sync = this.config.get("factorio.sync_adminlist");
 		if (sync === "disabled") {
@@ -1153,6 +1188,10 @@ end`.replace(/\r?\n/g, " ");
 	}
 
 	async handleInstanceBanlistUpdateEvent(request: lib.InstanceBanlistUpdateEvent) {
+		if (await this._waitForSettledStatus() !== "running") {
+			return;
+		}
+
 		const { name, banned, reason } = request;
 		const sync = this.config.get("factorio.sync_banlist");
 		if (sync === "disabled") {
@@ -1166,6 +1205,10 @@ end`.replace(/\r?\n/g, " ");
 	}
 
 	async handleInstanceWhitelistUpdateEvent(request: lib.InstanceWhitelistUpdateEvent) {
+		if (await this._waitForSettledStatus() !== "running") {
+			return;
+		}
+
 		const { name, whitelisted } = request;
 		const sync = this.config.get("factorio.sync_whitelist");
 		if (this.config.get("factorio.sync_whitelist") === "disabled") {

test/host/Instance.js

@@ -4,7 +4,7 @@ import path from "node:path";
 import * as lib from "@clusterio/lib";
 import { PlayerStats, wait } from "@clusterio/lib";
 import Instance from "@clusterio/host/dist/node/src/Instance.js";
-import { MockConnector, MockServer } from "../mock.js";
+import { MockConnector, MockLogger, MockServer } from "../mock.js";
 
 const addr = lib.Address.fromShorthand;
 
@@ -38,6 +38,161 @@ describe("class Instance", function() {
 		});
 	});
 
+	describe("config fieldChanged", function() {
+		let errors;
+		let rejections;
+		let hookInvoked;
+		function onRejection(err) { rejections.push(err); }
+		beforeEach(function() {
+			errors = [];
+			rejections = [];
+			instance.logger = new MockLogger();
+			instance.logger.error = message => errors.push(message);
+			instance.server.exampleSettings = async () => ({});
+			instance.notifyStatus("running");
+			hookInvoked = new Promise(resolve => {
+				instance.hooks.instanceConfigFieldChanged.attach("test", field => resolve(field));
+			});
+			process.on("unhandledRejection", onRejection);
+		});
+		afterEach(function() {
+			process.off("unhandledRejection", onRejection);
+		});
+
+		it("should log whitelist update errors and invoke the hook", async function() {
+			instance.server.sendRcon = async () => { throw new Error("Expected state running,stopping"); };
+			instance.config.set("factorio.enable_whitelist", true);
+			assert.equal(await hookInvoked, "factorio.enable_whitelist");
+			await wait(10);
+			assert.deepEqual(rejections, []);
+			assert.equal(errors.length, 1);
+			assert.match(errors[0], /^Error updating whitelist:\nError: Expected state running,stopping/);
+		});
+
+		it("should log server settings update errors and invoke the hook", async function() {
+			instance.server.exampleSettings = async () => { throw new Error("no example settings"); };
+			instance.config.set("factorio.settings", { name: "bar" });
+			assert.equal(await hookInvoked, "factorio.settings");
+			await wait(10);
+			assert.deepEqual(rejections, []);
+			assert.equal(errors.length, 1);
+			assert.match(errors[0], /^Error updating server settings:\nError: no example settings/);
+		});
+
+		it("should apply tags with non-string elements", async function() {
+			instance.config.set("factorio.settings", { tags: [1, "a b"] });
+			await hookInvoked;
+			await wait(10);
+			assert.deepEqual(rejections, []);
+			assert.deepEqual(errors, []);
+			assert.deepEqual(instance.server.rconCommands, ["/config set tags 1 a b"]);
+		});
+
+		it("should defer changes made while starting until the instance is running", async function() {
+			instance.notifyStatus("starting");
+			instance.config.set("factorio.settings", { tags: ["a"] });
+			await wait(10);
+			assert.deepEqual(instance.server.rconCommands, [], "command sent while starting");
+			instance.notifyStatus("running");
+			await wait(10);
+			assert.deepEqual(instance.server.rconCommands, ["/config set tags a"]);
+			assert.deepEqual(errors, []);
+			assert.deepEqual(rejections, []);
+		});
+
+		it("should drop changes made while starting if the instance stops", async function() {
+			instance.notifyStatus("starting");
+			instance.config.set("factorio.settings", { tags: ["a"] });
+			await wait(10);
+			instance.notifyStatus("stopped");
+			await wait(10);
+			assert.deepEqual(instance.server.rconCommands, []);
+			assert.deepEqual(errors, []);
+			assert.deepEqual(rejections, []);
+		});
+
+		it("should do nothing for changes made while stopped", async function() {
+			instance.notifyStatus("stopped");
+			instance.config.set("factorio.settings", { tags: ["a"] });
+			await wait(10);
+			assert.deepEqual(instance.server.rconCommands, []);
+			assert.deepEqual(errors, []);
+			assert.deepEqual(rejections, []);
+		});
+
+		it("should invoke the hook while starting without waiting for the instance", async function() {
+			instance.notifyStatus("starting");
+			instance.config.set("factorio.settings", { tags: ["a"] });
+			assert.equal(await hookInvoked, "factorio.settings");
+			assert.deepEqual(instance.server.rconCommands, [], "command sent while starting");
+			instance.notifyStatus("stopped");
+			await wait(10);
+		});
+
+		it("should invoke the hook for fields applied to the server directly", async function() {
+			instance.config.set("factorio.shutdown_timeout", 30);
+			assert.equal(await hookInvoked, "factorio.shutdown_timeout");
+			assert.equal(instance.server.shutdownTimeoutMs, 30000);
+			await wait(10);
+			assert.deepEqual(errors, []);
+			assert.deepEqual(rejections, []);
+		});
+
+		it("should invoke the hook exactly once per field changed", async function() {
+			let invoked = [];
+			instance._host.whitelist = new Set();
+			instance.hooks.instanceConfigFieldChanged.attach("count", field => { invoked.push(field); });
+			instance.config.set("factorio.settings", { tags: ["a"] });
+			instance.config.set("factorio.enable_whitelist", true);
+			instance.config.set("factorio.shutdown_timeout", 30);
+			instance.config.set("factorio.max_concurrent_commands", 3);
+			await wait(10);
+			assert.deepEqual(invoked, [
+				"factorio.settings",
+				"factorio.enable_whitelist",
+				"factorio.shutdown_timeout",
+				"factorio.max_concurrent_commands",
+			]);
+			assert.equal(instance.server.maxConcurrentCommands, 3);
+			assert.deepEqual(errors, []);
+			assert.deepEqual(rejections, []);
+		});
+	});
+
+	describe("list update events", function() {
+		let errors;
+		beforeEach(function() {
+			errors = [];
+			instance.logger = new MockLogger();
+			instance.logger.error = message => errors.push(message);
+		});
+
+		it("should apply an update received while starting once running", async function() {
+			instance.notifyStatus("starting");
+			let handled = instance.handleInstanceAdminlistUpdateEvent(
+				new lib.InstanceAdminlistUpdateEvent("player", true)
+			);
+			await wait(10);
+			assert.deepEqual(instance.server.rconCommands, [], "command sent while starting");
+			instance.notifyStatus("running");
+			await handled;
+			assert.deepEqual(instance.server.rconCommands, ["/promote player"]);
+			assert.deepEqual(errors, []);
+		});
+
+		it("should drop an update received while starting if the instance stops", async function() {
+			instance.notifyStatus("starting");
+			let handled = instance.handleInstanceAdminlistUpdateEvent(
+				new lib.InstanceAdminlistUpdateEvent("player", true)
+			);
+			await wait(10);
+			instance.notifyStatus("stopped");
+			await handled;
+			assert.deepEqual(instance.server.rconCommands, []);
+			assert.deepEqual(errors, []);
+		});
+	});
+
 	describe(".checkModPackVersion()", function() {
 		function modPack(factorioVersion) {
 			return lib.ModPack.fromJSON({ name: "pack", factorio_version: factorioVersion });