diff --git a/CHANGELOG.md b/CHANGELOG.md index b388eaa6..05e6faa9 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -48,6 +48,8 @@ Many thanks to the following for contributing to this release: - Fixed numeric admin name breaking login [#536](https://github.com/clusterio/clusterio/issues/536) - Added factorio.executable_path option which allows overriding the default path to the Factorio executable run. - Added instance version display [#573](https://github.com/clusterio/clusterio/pull/573) +- Added `factorio.shutdown_timeout` config to set the time the host will wait for a Factorio server to shut down befor killing it. +- Changed shutdown logic to prefer sending a /quit command via RCON instead of using diverging logic on Windows and Linux. ### Breaking Changes diff --git a/packages/host/src/Instance.ts b/packages/host/src/Instance.ts index f7e8ae7b..8cbc903b 100644 --- a/packages/host/src/Instance.ts +++ b/packages/host/src/Instance.ts @@ -153,7 +153,9 @@ export default class Instance extends lib.Link { this._configFieldChanged = (field: string, curr: unknown, prev: unknown) => { let hook = () => lib.invokeHook(this.plugins, "onInstanceConfigFieldChanged", field, curr, prev); - if (field === "factorio.settings") { + if (field === "factorio.shutdown_timeout") { + this.server.shutdownTimeoutMs = curr as number * 1000; + } else if (field === "factorio.settings") { this.updateFactorioSettings(curr as any, prev as any).finally(hook); } else if (field === "factorio.enable_whitelist") { this.updateFactorioWhitelist(curr as any).finally(hook); @@ -178,6 +180,7 @@ export default class Instance extends lib.Link { verboseLogging: this.config.get("factorio.verbose_logging"), stripPaths: this.config.get("factorio.strip_paths"), maxConcurrentCommands: this.config.get("factorio.max_concurrent_commands"), + shutdownTimeoutMs: this.config.get("factorio.shutdown_timeout") * 1000, }; this.server = new FactorioServer( diff --git a/packages/host/src/server.ts b/packages/host/src/server.ts index c486e4d4..626dc644 100644 --- a/packages/host/src/server.ts +++ b/packages/host/src/server.ts @@ -351,20 +351,37 @@ const outputHeuristics: Heuristic[] = [ }, }, - // Message indicating the server is shutting down + // Last messages before the server hangs during shutdown waiting for console input on Windows. { filter: { type: "generic", - message: /^Quitting: /, + message: "Quitting: multiplayer error.", }, action: function(parsed) { - this.emit("_quitting"); - // On windows the Factorio server will wait for input on the console input buffer - // when an error occurs. Since we can't send input there we terminate the server + // before shutting down. Since we can't send input there we terminate the server // process when this happens. - if (process.platform === "win32" && parsed.message === "Quitting: multiplayer error.") { + if (process.platform === "win32") { this._server!.kill(); + // Notify that the server is being killed after the last message + // is logged so that it doesn't look like it was killed unnecessarily. + process.nextTick(() => { + this._logger.info("Killing Factorio process to avoid it hanging forever."); + }); + } + }, + }, + { + filter: { + type: "log", + message: /^updateTick\(\d+\) changing state from\(Disconnected\) to\(Closed\)$/, + }, + action: function() { + if (process.platform === "win32") { + this._server!.kill(); + process.nextTick(() => { + this._logger.info("Killing Factorio process to avoid it hanging forever."); + }); } }, }, @@ -428,8 +445,11 @@ export interface FactorioServerOptions { * connection. */ maxConcurrentCommands?: number - /** Timeout in ms to wait for a response to a shutdown command. */ - hangTimeoutMs?: number, + /** + * Timeout in ms to wait after a shutdown is requested before killing the + * process. Defaults to 0 meaning no timeout + */ + shutdownTimeoutMs?: number, } /** @@ -466,8 +486,8 @@ export class FactorioServer extends events.EventEmitter { enableAuthserverBans: boolean; /** Enable verbose logging */ verboseLogging: boolean; - /** Timeout in ms to wait for a response to a shutdown command */ - hangTimeoutMs = 5000; + _shutdownTimeoutMs = 0; + _stopTimeoutId?: ReturnType; _factorioDir: string; _writeDir: string; @@ -523,8 +543,9 @@ export class FactorioServer extends events.EventEmitter { this.verboseLogging = options.verboseLogging || false; /** Maximum number of RCON commands transmitted in parallel on the RCON connection */ this.maxConcurrentCommands = options.maxConcurrentCommands || 5; - /** Timeout in ms to wait for a response to a shutdown command */ - this.hangTimeoutMs = options.hangTimeoutMs ?? 5000; + if (options.shutdownTimeoutMs !== undefined) { + this.shutdownTimeoutMs = options.shutdownTimeoutMs; + } if (options.stripPaths) { let charSet = new Set(path.resolve(this.writePath("temp"))); @@ -666,10 +687,6 @@ export class FactorioServer extends events.EventEmitter { } async _startRcon() { - if (this._state === "stopping") { - return; - } - if (this._rconClient !== null) { throw Error("RCON client is already started"); } @@ -683,16 +700,39 @@ export class FactorioServer extends events.EventEmitter { }; this._rconClient = new Rcon(config); - this._rconClient.on("error", () => { /* Ignore */ }); - this._rconClient.on("authenticated", () => { this._rconReady = true; this.emit("rcon-ready"); }); + this._rconClient.on("error", () => { + // Errors before being authenticated might not emit end + this._rconClient = null; + if (!this._rconReady) { + this._rconReady = true; + this.emit("rcon-ready"); + } + }); + this._rconClient.on("authenticated", () => { + this._rconReady = true; + this.emit("rcon-ready"); + }); this._rconClient.on("end", () => { this._rconClient = null; + if (!this._rconReady) { + this._rconReady = true; + this.emit("rcon-ready"); + } }); // XXX: Workaround to suppress bogus event listener warning if (this._rconClient.emitter instanceof events.EventEmitter) { this._rconClient.emitter.setMaxListeners(this.maxConcurrentCommands + 5); } - await this._rconClient.connect(); + try { + await this._rconClient.connect(); + } catch (err: any) { + this._logger.error(`Failed to start RCON connection:\n${err?.stack ?? err?.message ?? err}`); + this._rconClient = null; + if (!this._rconReady) { + this._rconReady = true; + this.emit("rcon-ready"); + } + } } /** Maximum number of RCON commands transmitted in parallel on the RCON connection */ @@ -764,6 +804,7 @@ export class FactorioServer extends events.EventEmitter { this._rconReady = false; this._gameReady = false; this._unexpected = []; + this._killed = false; this._runningAutosave = null; } @@ -798,6 +839,9 @@ export class FactorioServer extends events.EventEmitter { `\n- ${this._unexpected.join("\n- ")}` )); } + + } else { // if state === "stopping" + this._clearStopTimeout(); } if (this._rconClient) { @@ -1005,6 +1049,44 @@ export class FactorioServer extends events.EventEmitter { return response; } + /** + * Timeout in ms to wait after a shutdown is requested before killing the + * process. Defaults to 0 meaning no timeout + */ + get shutdownTimeoutMs() { + return this._shutdownTimeoutMs; + } + + set shutdownTimeoutMs(newTimeoutMs: number) { + this._shutdownTimeoutMs = newTimeoutMs; + if (this._state === "stopping") { + this._clearStopTimeout(); + this._setStopTimeout(); + } + } + + _setStopTimeout() { + if (this._shutdownTimeoutMs !== 0) { + this._stopTimeoutId = setTimeout( + this.onStopTimeout.bind(this), + this.shutdownTimeoutMs + ); + } + } + + _clearStopTimeout() { + clearTimeout(this._stopTimeoutId); + this._stopTimeoutId = undefined; + } + + onStopTimeout() { + this._logger.error("Factorio appears to have hanged, killing process"); + if (this._rconClient) { + this._rconClient.end().catch(() => {}); + } + this._server!.kill("SIGKILL"); + } + /** * Stop the server * @@ -1013,88 +1095,54 @@ export class FactorioServer extends events.EventEmitter { */ async stop() { this._check(["running"]); - - let hanged = true; - let stopped = false; - function setAlive() { hanged = false; } - - let timeoutId = setTimeout(() => { - if (hanged) { - this._logger.error("Factorio appears to have hanged, sending SIGKILL"); - if (this._rconClient) { - this._rconClient.end().catch(() => {}); - } - this._server!.kill("SIGKILL"); - } - }, this.hangTimeoutMs); - - // It's possible the server decides to exit on its own, in which - // case the stop operation has to be cancelled. - this._server!.once("exit", () => { - stopped = true; - clearTimeout(timeoutId); - }); - this._state = "stopping"; - // On Windows we need to save the map as there's no graceful shutdown. - if (this._rconClient && process.platform === "win32") { - // Not using events.once here as that will reject on error. - let saved = new Promise(resolve => this.once("_saved", resolve)); - this.on("_saving", setAlive); - try { - await this.sendRcon("/server-save"); - await saved; + // It's possible the server doesn't stop if it's stuck in an infinite + // loop or overloaded, kill it if the shutdown takes too long. + this._setStopTimeout(); - } catch (err) { - // Ignore - } - - clearTimeout(timeoutId); - this.off("_saving", setAlive); - } - - if (this._rconClient) { - - // If RCON is not yet fully connected that operation needs to - // complete before the RCON connection can be closed cleanly. - if (!this._rconReady) { - await events.once(this, "rcon-ready"); - } - - await this._rconClient.end(); + // If RCON is not yet fully connected that operation needs to + // complete before the RCON connection can be used + if (!this._rconReady) { + // Not using events.once here to avoid throwing on error events. + await new Promise(resolve => this.once("rcon-ready", resolve)); } // The Factorio server may have decided to get ahead of us and // stop by itself before we had the chance to signal it. - if (stopped) { + if (this._state !== "stopping") { return; } - // On linux this sends SIGTERM to the process. On windows this - // will terminate the process with no cleanup. You can send your - // complaint for the lack of graceful shutdown to the Factorio - // developers. Rcon does not recognize /quit, stdin is not - // recognized, and there's no "send CTRL+C to process" on Windows. - this._server!.kill(); + const waitForExit = events.once(this._server!, "exit"); + waitForExit.catch(() => {}); // Prevent unhandled promise rejection - // There appears to be an race condition where sending SIGTERM - // immediatly before the RCON interface comes online causes the - // Factorio server to hang. It's also possible the server doesn't - // stop if it's stuck with an infinite lua code loop. In either - // case there's no recovering from it. - if (process.platform !== "win32") { - this.on("_quitting", setAlive); - await events.once(this._server!, "exit"); - - clearTimeout(timeoutId); - this.off("_quitting", setAlive); - - // On windows the process is terminated immediately, but to keep - // ordering wait until after the exit event here. + // Stop the server + if (this._rconClient) { + // Use RCON by default to stop the the server as it's available on + // all platforms and simplifies the code. + try { + await this.sendRcon("/quit"); + } catch (err: any) { + // Ignore RCON connection being closed while sending the quit command. + if (err.message !== "Connection closed") { + throw err; + } + } } else { - await events.once(this._server!, "exit"); + // No rcon connection is available, fallback to signal. On linux + // this sends SIGTERM to the process. On windows this + // will terminate the process without saving. You can send your + // complaint for the lack of graceful shutdown options to the + // Factorio developers. I haven't found any way to make stdin work + // and there's no "send CTRL+C to process" API on Windows. + if (process.platform === "win32") { + this._logger.warn("No RCON connection, falling back to killing the server."); + } + this._server!.kill(); } + + await waitForExit; } /** diff --git a/packages/lib/src/config/definitions.ts b/packages/lib/src/config/definitions.ts index 3079e5a7..b50eeaa3 100644 --- a/packages/lib/src/config/definitions.ts +++ b/packages/lib/src/config/definitions.ts @@ -262,6 +262,7 @@ export interface InstanceConfigFields { "factorio.version": string; "factorio.executable_path": string | null; + "factorio.shutdown_timeout": number; "factorio.game_port": number | null; "factorio.host_assigned_game_port": number | null; "factorio.rcon_port": number | null; @@ -320,6 +321,14 @@ export class InstanceConfig extends classes.Config { type: "string", optional: true, }, + "factorio.shutdown_timeout": { + description: + "Timeout in seconds to wait after requesting the server to stop before killing " + + "the process. Set to 0 to disable.", + type: "number", + initialValue: 300, + optional: true, + }, "factorio.game_port": { description: "UDP port to run game on, uses a port in host.factorio_port_range if null", restartRequired: true, diff --git a/test/host/server.js b/test/host/server.js index ea92a06c..1dc541cd 100644 --- a/test/host/server.js +++ b/test/host/server.js @@ -211,27 +211,28 @@ describe("host/server", function() { describe(".stop()", function() { it("should handle server quitting on its own during stop", async function() { - if (process.platform === "win32") { - this.skip(); - } - server.hangTimeoutMs = 20; + server.shutdownTimeoutMs = 20; server._server = new events.EventEmitter(); server._server.kill = () => true; server._state = "running"; - server._rconReady = true; + server._rconReady = false; server._rconClient = { + async sendRcon() { }, async end() { server._rconClient = null; - process.nextTick(() => { - server.emit("_quitting"); - server._server.emit("exit"); - }); }, }; server._watchExit(); - await server.stop(); - await wait(21); // Wait until after hang timeout + const stop = server.stop(); + stop.catch(() => {}); + process.nextTick(() => { + server.emit("rcon-ready"); + server._server.emit("exit"); + }); + + await stop; + await wait(21); // Wait until after shutdown timeout }); }); }); diff --git a/test/integration/clusterio.js b/test/integration/clusterio.js index cfedb438..d2f09f47 100644 --- a/test/integration/clusterio.js +++ b/test/integration/clusterio.js @@ -13,7 +13,7 @@ const { wait } = lib; const testStrings = require("../lib/factorio/test_strings"); const { TestControl, TestControlConnector, url, controlToken, slowTest, - get, exec, execCtl, sendRcon, getControl, spawn, instancesDir, + exec, execCtl, sendRcon, getControl, spawn, instancesDir, factorioDir, } = require("./index"); @@ -41,15 +41,29 @@ async function startAltHost() { await execCtl(`host create-config --id 5 --name alt-host --generate-token --output ${config}`); await exec(`node ../../packages/host --config ${config} config set host.tls_ca ../../test/file/tls/cert.pem`); await exec(`node ../../packages/host --config ${config} config set host.instances_directory alt-instances`); - await exec(`node ../../packages/host --config ${config} config set host.factorio_directory ../../factorio`); + const dir = path.isAbsolute(factorioDir) ? factorioDir : path.join("..", "..", factorioDir); + await exec(`node ../../packages/host --config ${config} config set host.factorio_directory ${dir}`); await exec(`node ../../packages/host --config ${config} config set host.mods_directory alt-mods`); return await spawnAltHost(config); } async function stopAltHost(hostProcess) { if (hostProcess && hostProcess.exitCode === null) { - hostProcess.kill("SIGINT"); - await events.once(hostProcess, "exit"); + const waitForExit = lib.timeout( + events.once(hostProcess, "exit"), + 10e3, + "timeout" + ).catch(() => {}); + try { + await execCtl("host stop 5"); + } catch (err) { + // Some tests cause the host to stop + } + if (await waitForExit === "timeout" && hostProcess.exitCode === null) { + // eslint-disable-next-line no-console + console.warn("Stopping alt-host failed. Killing."); + hostProcess.kill("SIGINT"); + } } } @@ -148,12 +162,6 @@ describe("Integration of Clusterio", function() { describe("clusteriohost", function() { describe("hostUpdateEventHandler()", function() { it("should trigger when a new host is added", async function() { - // On windows there's currently no way to automate graceful shutdown of the host - // process as CTRL+C is some weird terminal thing and SIGINT isn't a thing. - if (process.platform === "win32") { - this.skip(); - } - slowTest(this); getControl().hostUpdates = []; @@ -189,12 +197,6 @@ describe("Integration of Clusterio", function() { }); }); it("should download mods from controller", async function() { - // On windows there's currently no way to automate graceful shutdown of the host - // process as CTRL+C is some weird terminal thing and SIGINT isn't a thing. - if (process.platform === "win32") { - this.skip(); - } - slowTest(this); await runWithAltHost(async () => { const clusterioLib = path.join("temp", "test", "alt-mods", "clusterio_lib_0.1.2.zip"); @@ -206,12 +208,6 @@ describe("Integration of Clusterio", function() { }); }); it("should auto start instances with auto_start enabled", async function() { - // On windows there's currently no way to automate graceful shutdown of the host - // process as CTRL+C is some weird terminal thing and SIGINT isn't a thing. - if (process.platform === "win32") { - this.skip(); - } - slowTest(this); let hostProcess; @@ -310,12 +306,6 @@ describe("Integration of Clusterio", function() { }); describe("host revoke-token", async function() { it("should disconnect existing host", async function() { - // On windows there's currently no way to automate graceful shutdown of the host - // process as CTRL+C is some weird terminal thing and SIGINT isn't a thing. - if (process.platform === "win32") { - this.skip(); - } - slowTest(this); let sawDisconnected; await runWithAltHost(async () => { @@ -774,11 +764,6 @@ describe("Integration of Clusterio", function() { if (remote) { let hostProcess; before(async function() { - // On windows there's currently no way to automate graceful shutdown of the host - // process as CTRL+C is some weird terminal thing and SIGINT isn't a thing. - if (process.platform === "win32") { - this.skip(); - } slowTest(this); hostProcess = await startAltHost(); @@ -907,12 +892,8 @@ describe("Integration of Clusterio", function() { slowTest(this); let statusesToCheck = new Set([ "unassigned", "stopped", "creating_save", "exporting_data", - "starting", "running", "stopping", "deleted", + "starting", "running", "stopping", "deleted", "unknown", ]); - // Windows does not see the unknown status because alt-host is not spawned. - if (process.platform !== "win32") { - statusesToCheck.add("unknown"); - } let statusesNotSeen = new Set(statusesToCheck); for (let update of getControl().instanceUpdates) { diff --git a/test/integration/server.js b/test/integration/server.js index 02d088cf..1035c16e 100644 --- a/test/integration/server.js +++ b/test/integration/server.js @@ -14,9 +14,25 @@ const { slowTest, factorioDir } = require("./index"); describe("Integration of host/src/server", function() { describe("_getVersion()", function() { it("should get a version from factorio's changelog.txt", async function() { + function checkVersion(version) { + if (!/^\d+\.\d+\.\d+$/.test(version)) { + assert.fail(`Detected version '${version}' does not followed the format x.y.z`); + } + } + let version = await _getVersion(path.join(factorioDir, "data", "changelog.txt")); - if (!/^\d+\.\d+\.\d+$/.test(version)) { - assert.fail(`Detected version '${version}' does not followed the format x.y.z`); + if (version !== null) { + checkVersion(version); + } else { + for (let entry of await fs.readdir(factorioDir, { withFileTypes: true })) { + if (!entry.isDirectory()) { + continue; + } + + checkVersion( + await _getVersion(path.join(factorioDir, entry.name, "data", "changelog.txt")) + ); + } } }); }); @@ -93,7 +109,7 @@ describe("Integration of host/src/server", function() { let mapPath = server.writePath("saves", "test.zip"); assert(!await fs.exists(mapPath), "save exist before test"); - await server.create("test.zip"); + await server.create("test.zip", undefined, { width: 50, height: 50 }); assert(await fs.exists(mapPath), "test did not create save"); }); }); @@ -213,16 +229,79 @@ describe("Integration of host/src/server", function() { server.sendRcon("/c while true do end").catch(() => {}); await new Promise((resolve) => setTimeout(resolve, 300)); log(".stop() for hang detection"); + server.shutdownTimeoutMs = 2000; await server.stop(); + server.shutdownTimeoutMs = 0; + }); + it("should not hang if RCON fails to connect while stopping", async function() { + slowTest(this); + + const origWaitForReady = server._waitForReady; + server._waitForReady = () => { + server._waitForReady = origWaitForReady; + server.rconPort -= 1; // Mangle port so it fails to connect. + return server._waitForReady(); + }; + try { + await server.start("test.zip"); + if (server._rconReady) { + assert.fail("Test failed, RCON managed to connect"); + } + await server.stop(); + + } finally { + if (server._state !== "init") { + await server.kill(); + assert.fail("Server did not stop"); + } + } + }); + it("should not hang if RCON fails to connect before stopping", async function() { + slowTest(this); + + const origWaitForReady = server._waitForReady; + server._waitForReady = () => { + server._waitForReady = origWaitForReady; + server.rconPassword = "wrong"; // Mangle password so it fails to authenticate. + return server._waitForReady(); + }; + try { + await server.start("test.zip"); + if (server._rconReady) { + assert.fail("Test failed, RCON managed to connect"); + } + await events.once(server, "rcon-ready"); + await server.stop(); + + } finally { + if (server._state !== "init") { + await server.kill(); + assert.fail("Server did not stop"); + } + } + }); + it("should work if RCON has dropped out", async function() { + slowTest(this); + + try { + await server.start("test.zip"); + if (!server._rconReady) { + await events.once(server, "rcon-ready"); + } + await server._rconClient.end(); + await server.stop(); + + } finally { + if (server._state !== "init") { + await server.kill(); + assert.fail("Server did not stop"); + } + } }); }); describe(".start() termination detection", function() { it("should tell if Factorio got killed", async function() { - // This does not work on Windows - if (process.platform === "win32") { - this.skip(); - } slowTest(this); log(".start() for kill detection");