diff --git a/packages/slave/src/Instance.js b/packages/slave/src/Instance.js index 7d48d707..8c71e2ba 100644 --- a/packages/slave/src/Instance.js +++ b/packages/slave/src/Instance.js @@ -247,12 +247,131 @@ class Instance extends libLink.Link { }); this.server.on("ipc-player_event", event => { - libLink.messages.playerEvent.send(this, { - instance_id: this.id, - ...event, - }); - libPlugin.invokeHook(this.plugins, "onPlayerEvent", event); + if (event.type === "join") { + this._recordPlayerJoin(event.name); + } else if (event.type === "leave") { + this._recordPlayerLeave(event.name); + } }); + + /** + * @typedef module:slave/src/Instance~PlayerStat + * @type {object} + * @property {number} lastJoinAt - + * Unix timestamp in ms the player was last seen joining this + * instance. + * @property {number=} lastLeaveAt - + * Unix timestamp in ms the player was last seen leaving this + * instance. Not present if player has yet to leave after first + * time joining. + * @property {number} joinCount - + * Count of the number of times this player has been seen + * joining this server. + * @property {number} onlineTimeMs - + * Time in ms this player has been seen online on this instance. + */ + + /** + * Per player statistics recorded by this instance. + * @type {Map} + */ + this.playerStats = new Map(); + + /** + * Players currently online on the instance. + * @type {Map} + */ + this.playersOnline = new Set(); + this._playerCheckInterval = null; + } + + _watchPlayerJoinsByChat() { + this.server.on("output", (parsed, line) => { + if (parsed.type !== "action") { + return; + } + + let name = /^([^ ]+)/.exec(parsed.message)[1]; + if (parsed.action === "JOIN") { + this._recordPlayerJoin(name); + } else if (["LEAVE", "KICK", "BAN"].includes(parsed.action)) { + this._recordPlayerLeave(name); + } + }); + + // Leave log entries are unreliable and sometimes don't show up. + this._playerCheckInterval = setInterval(() => { + this._checkOnlinePlayers().catch(err => { + this.logger.error(`Error checking online players:\n${err.stack}`); + }); + }, 60e3); + } + + async _checkOnlinePlayers() { + if (this.playersOnline.size) { + let actualPlayers = (await this.sendRcon("/players online")) + .split("\n") + .slice(1, -1) // Remove header and trailing newline + .map(s => s.slice(2, -" (online)".length)) + ; + let left = new Set(this.playersOnline); + actualPlayers.map(player => left.delete(player)); + let joined = new Set(actualPlayers); + this.playersOnline.forEach(player => joined.delete(player)); + + for (let player of left) { + this._recordPlayerLeave(player); + } + + // Missing join messages is not supposed to happen. + if (joined.size) { + this.logger.warn(`Missed join message for ${[...joined].join(", ")}`); + for (let player of joined) { + this._recordPlayerJoin(player); + } + } + } + } + + _recordPlayerJoin(name) { + if (this.playersOnline.has(name)) { + return; + } + this.playersOnline.add(name); + + let stats = this.playerStats.get(name); + if (!stats) { + stats = { joinCount: 0, onlineTimeMs: 0 }; + this.playerStats.set(name, stats); + } + stats.lastJoinAt = Date.now(); + stats.joinCount += 1; + + let event = { + instance_id: this.id, + type: "join", + name, + }; + libLink.messages.playerEvent.send(this, event); + libPlugin.invokeHook(this.plugins, "onPlayerEvent", event); + } + + _recordPlayerLeave(name) { + if (!this.playersOnline.delete(name)) { + return; + } + + let stats = this.playerStats.get(name); + stats.lastLeaveAt = Date.now(); + stats.onlineTimeMs += stats.lastLeaveAt - stats.lastJoinAt; + + let event = { + instance_id: this.id, + type: "leave", + name, + }; + libLink.messages.playerEvent.send(this, event); + libPlugin.invokeHook(this.plugins, "onPlayerEvent", event); } async sendRcon(message, expectEmpty, plugin = "") { @@ -337,6 +456,7 @@ class Instance extends libLink.Link { this.notifyStatus("stopped"); this.config.off("fieldChanged", this._configFieldChanged); + clearTimeout(this._playerCheckInterval); // Clear metrics this instance is exporting for (let collector of libPrometheus.defaultRegistry.collectors) { @@ -352,6 +472,8 @@ class Instance extends libLink.Link { for (let pluginInstance of this.plugins.values()) { pluginInstance.onExit(); } + + this._saveStats().catch(err => this.logger.error(`Error saving stats:\n${err.stack}`)); } async _loadPlugin(pluginInfo, slave) { @@ -365,9 +487,28 @@ class Instance extends libLink.Link { this.logger.info(`Loaded plugin ${pluginInfo.name} in ${Date.now() - pluginLoadStarted}ms`); } + async _loadStats() { + let stats; + try { + stats = JSON.parse(await fs.readFile(this.path("instance-stats.json"))); + } catch (err) { + if (err.code === "ENOENT") { + return; + } + throw err; + } + this.playerStats = new Map(stats["players"]); + } + + async _saveStats() { + let content = JSON.stringify({ players: [...this.playerStats] }, null, 4); + await libFileOps.safeOutputFile(this.path("instance-stats.json"), content); + } + async init(pluginInfos) { this.notifyStatus("starting"); try { + await this._loadStats(); await this.server.init(); } catch (err) { this.notifyExit(); @@ -626,6 +767,8 @@ class Instance extends libLink.Link { if (this.config.get("factorio.enable_save_patching")) { await this.server.disableAchievements(); await this.updateInstanceData(); + } else { + this._watchPlayerJoinsByChat(); } await this.sendSaveListUpdate(); @@ -652,6 +795,7 @@ class Instance extends libLink.Link { this.server.on("exit", () => this.notifyExit()); await this.server.startScenario(scenario, seed, mapGenSettings, mapSettings); + this._watchPlayerJoinsByChat(); await libPlugin.invokeHook(this.plugins, "onStart"); diff --git a/test/lib/factorio/lines.js b/test/lib/factorio/lines.js index aeba4b9d..f520c742 100644 --- a/test/lib/factorio/lines.js +++ b/test/lib/factorio/lines.js @@ -102,6 +102,36 @@ let testLines = new Map([ message: "User left the game", }, ], + [ + "2019-01-20 15:46:34 [KICK] User was kicked by . Reason: unspecified.", + { + format: "date", + time: "2019-01-20 15:46:34", + type: "action", + action: "KICK", + message: "User was kicked by . Reason: unspecified.", + }, + ], + [ + "2019-01-20 15:47:50 [BAN] User was banned by . Reason: unspecified.", + { + format: "date", + time: "2019-01-20 15:47:50", + type: "action", + action: "BAN", + message: "User was banned by . Reason: unspecified.", + }, + ], + [ + "2019-01-20 15:48:28 [UNBANNED] User was unbanned by .", + { + format: "date", + time: "2019-01-20 15:48:28", + type: "action", + action: "UNBANNED", + message: "User was unbanned by .", + }, + ], [ "Error while running event level::on_nth_tick(1)", { diff --git a/test/mock.js b/test/mock.js index c66b3d0b..00d46ceb 100644 --- a/test/mock.js +++ b/test/mock.js @@ -242,6 +242,7 @@ module.exports = { MockLogger, MockSocket, MockConnector, + MockServer, MockInstance, MockSlave, MockControl, diff --git a/test/slave.js b/test/slave.js index a1fe4247..36772faa 100644 --- a/test/slave.js +++ b/test/slave.js @@ -13,31 +13,6 @@ describe("Slave testing", function() { libConfig.InstanceConfig.finalize(); }); - describe("class Instance", function() { - let instance; - before(async function() { - let instanceConfig = new libConfig.InstanceConfig("slave"); - await instanceConfig.init(); - instanceConfig.set("instance.name", "foo"); - instance = new Instance({}, new libLink.VirtualConnector(), "dir", "factorioDir", instanceConfig); - }); - - describe(".name", function() { - it("should give the name of the instance", function() { - assert.equal(instance.name, "foo"); - }); - }); - - describe(".path()", function() { - it("should give the path when called without arguments", function() { - assert.equal(instance.path(), "dir"); - }); - it("should join path with arguments", function() { - assert.equal(instance.path("bar"), path.join("dir", "bar")); - }); - }); - }); - describe("checkFilename()", function() { it("should allow a basic name", function() { Slave._checkFilename("file"); diff --git a/test/slave/Instance.js b/test/slave/Instance.js new file mode 100644 index 00000000..0008489f --- /dev/null +++ b/test/slave/Instance.js @@ -0,0 +1,156 @@ +"use strict"; +const assert = require("assert").strict; +const path = require("path"); + +const libConfig = require("@clusterio/lib/config"); +const { wait } = require("@clusterio/lib/helpers"); +const Instance = require("@clusterio/slave/src/Instance"); +const { MockConnector, MockServer } = require("../mock"); + + +describe("class Instance", function() { + before(function() { + libConfig.InstanceConfig.finalize(); + }); + + let instance; + let connector; + beforeEach(async function() { + let instanceConfig = new libConfig.InstanceConfig("slave"); + await instanceConfig.init(); + instanceConfig.set("instance.name", "foo"); + connector = new MockConnector(); + instance = new Instance({}, connector, "dir", "factorioDir", instanceConfig); + instance.server = new MockServer(); + }); + + describe(".name", function() { + it("should give the name of the instance", function() { + assert.equal(instance.name, "foo"); + }); + }); + + describe(".path()", function() { + it("should give the path when called without arguments", function() { + assert.equal(instance.path(), "dir"); + }); + it("should join path with arguments", function() { + assert.equal(instance.path("bar"), path.join("dir", "bar")); + }); + }); + + describe("._recordPlayerJoin()", function() { + it("should add player to playersOnline", function() { + instance._recordPlayerJoin("player"); + assert(instance.playersOnline.has("player"), "player was not added"); + }); + + it("should create playerStats entry", function() { + assert(!instance.playerStats.has("player")); + instance._recordPlayerJoin("player"); + assert(instance.playerStats.has("player"), "player was not added to stats"); + }); + + + it("should send player_event", function() { + instance._recordPlayerJoin("player"); + assert.deepEqual( + connector.sentMessages[0], + { + seq: 1, + type: "player_event_event", + data: { type: "join", instance_id: instance.id, name: "player" }, + }, + ); + }); + + it("should be idempotent", function() { + instance._recordPlayerJoin("player"); + instance._recordPlayerJoin("player"); + assert(instance.playersOnline.has("player"), "player was not added"); + assert.equal(connector.sentMessages.length, 1); + }); + }); + + describe("._recordPlayerLeave()", function() { + it("should remove player to playersOnline", function() { + instance._recordPlayerJoin("player"); + instance._recordPlayerLeave("player"); + assert(!instance.playersOnline.has("player"), "player was not removed"); + }); + + it("should update playerStats", async function() { + instance._recordPlayerJoin("player"); + await wait(10); + instance._recordPlayerLeave("player"); + assert(instance.playerStats.has("player"), "playerStats record missing"); + assert(instance.playerStats.get("player").onlineTimeMs > 0, "no onlineTimeMs recorded"); + }); + + it("should send player_event", function() { + instance._recordPlayerJoin("player"); + instance._recordPlayerLeave("player"); + assert.deepEqual( + connector.sentMessages[1], + { + seq: 2, + type: "player_event_event", + data: { type: "leave", instance_id: instance.id, name: "player" }, + }, + ); + }); + + it("should be idempotent", function() { + instance._recordPlayerJoin("player"); + instance._recordPlayerLeave("player"); + instance._recordPlayerLeave("player"); + assert(!instance.playersOnline.has("player"), "player was not removed"); + assert.equal(connector.sentMessages.length, 2); + }); + }); + + describe("._checkOnlinePlayers()", function() { + it("should do nothing on empty server", async function() { + await instance._checkOnlinePlayers(); + assert.equal(instance.server.rconCommands.length, 0, "commands were sent"); + assert.equal(connector.sentMessages.length, 0, "messages were sent"); + }); + + it("should do nothing on correct online presence", async function() { + instance.server.rconCommandResults.set("/players online", "Online Players (1):\n player (online)\n"); + instance.playersOnline.add("player"); + await instance._checkOnlinePlayers(); + assert.equal(connector.sentMessages.length, 0, "messages were sent"); + }); + + it("should add missing players", async function() { + instance.server.rconCommandResults.set( + "/players online", "Online Players (2):\n player (online)\n foo (online)\n" + ); + instance._recordPlayerJoin("player"); + await instance._checkOnlinePlayers(); + assert.deepEqual( + connector.sentMessages[1], + { + seq: 2, + type: "player_event_event", + data: { type: "join", instance_id: instance.id, name: "foo" }, + }, + ); + }); + + it("should remove extra players", async function() { + instance.server.rconCommandResults.set("/players online", "Online Players (0):\n"); + instance._recordPlayerJoin("player"); + await instance._checkOnlinePlayers(); + assert.deepEqual( + connector.sentMessages[1], + { + seq: 2, + type: "player_event_event", + data: { type: "leave", instance_id: instance.id, name: "player" }, + }, + ); + }); + }); +});