Track player stats on instances

Track which players are online and record basic stats for each player on
each instance including when save patching is disabled.

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<string, module:slave/src/Instance~PlayerStat>}
+		 */
+		this.playerStats = new Map();
+
+		/**
+		 * Players currently online on the instance.
+		 * @type {Map<string, string>}
+		 */
+		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");
 

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 <server>. Reason: unspecified.",
+		{
+			format: "date",
+			time: "2019-01-20 15:46:34",
+			type: "action",
+			action: "KICK",
+			message: "User was kicked by <server>. Reason: unspecified.",
+		},
+	],
+	[
+		"2019-01-20 15:47:50 [BAN] User was banned by <server>. Reason: unspecified.",
+		{
+			format: "date",
+			time: "2019-01-20 15:47:50",
+			type: "action",
+			action: "BAN",
+			message: "User was banned by <server>. Reason: unspecified.",
+		},
+	],
+	[
+		"2019-01-20 15:48:28 [UNBANNED] User was unbanned by <server>.",
+		{
+			format: "date",
+			time: "2019-01-20 15:48:28",
+			type: "action",
+			action: "UNBANNED",
+			message: "User was unbanned by <server>.",
+		},
+	],
 	[
 		"Error while running event level::on_nth_tick(1)",
 		{

test/mock.js

@@ -242,6 +242,7 @@ module.exports = {
 	MockLogger,
 	MockSocket,
 	MockConnector,
+	MockServer,
 	MockInstance,
 	MockSlave,
 	MockControl,

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");

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" },
+				},
+			);
+		});
+	});
+});