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..7e72ba4b 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"); } @@ -798,6 +815,9 @@ export class FactorioServer extends events.EventEmitter { `\n- ${this._unexpected.join("\n- ")}` )); } + + } else { // if state === "stopping" + this._clearStopTimeout(); } if (this._rconClient) { @@ -1005,6 +1025,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 +1071,53 @@ 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) { + await events.once(this, "rcon-ready"); } // 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 d4d51b18..1dc541cd 100644 --- a/test/host/server.js +++ b/test/host/server.js @@ -211,24 +211,28 @@ describe("host/server", function() { describe(".stop()", function() { it("should handle server quitting on its own during stop", async function() { - 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/server.js b/test/integration/server.js index 34890699..13c03b3f 100644 --- a/test/integration/server.js +++ b/test/integration/server.js @@ -229,7 +229,51 @@ 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", 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 assert.rejects( + server.stop(), + { code: "ECONNREFUSED" } + ); + + } finally { + if (server._state !== "init") { + await server.kill(); + } + } + }); + 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(); + } + } }); });