Merge pull request #661 from Hornwitser/windows-rework

Rework Factorio server stop logic
This commit is contained in:
Hornwitser authored and GitHub committed 2024-09-14 18:15:19 +02:00
commit a1c7173dd2
7 files changed
+268 -145

No files matched your search

+2
View File
@@ -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
+4 -1
View File
@@ -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(
+136 -88
View File
@@ -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<typeof setTimeout>;
_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;
}
/**
+9
View File
@@ -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<InstanceConfigFields> {
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,
+12 -11
View File
@@ -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
});
});
});
+19 -38
View File
@@ -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) {
+86 -7
View File
@@ -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");