v2.0.0-alpha.3

Alpha 3 preparations

.eslintrc.js

@@ -124,7 +124,7 @@ module.exports = {
 		"no-caller": "error",
 		"no-catch-shadow": "error",
 		"no-confusing-arrow": "error",
-		"no-console": "off",
+		"no-console": "error",
 		"no-constant-condition": ["error", { "checkLoops": false }],
 		"no-constructor-return": "error",
 		"no-continue": "off",
@@ -214,7 +214,7 @@ module.exports = {
 		"no-useless-rename": "error",
 		"no-useless-return": "error",
 		"no-var": "warn",
-		"no-void": "error",
+		"no-void": ["error", { "allowAsStatement": true }],
 		"no-warning-comments": "off",
 		"no-whitespace-before-property": "error",
 		"nonblock-statement-body-position": "error",

.gitattributes

@@ -0,0 +1 @@
+package-lock.json -diff

.travis.yml

@@ -7,8 +7,8 @@ before_install:
   - npm install -g codecov
 script:
   - npx lerna bootstrap --no-ci
-  - node packages/lib/build_mod --source-dir packages/slave/lua/clusterio_lib --bump-patch --factorio-version 0.18 --output-dir temp/test/sharedMods
-  - curl -o temp/test/sharedMods/subspace_storage_1.99.1.zip -L https://github.com/clusterio/factorioClusterioMod/releases/download/1.99.1/subspace_storage_1.99.1.zip
+  - node packages/lib/build_mod --source-dir packages/slave/lua/clusterio_lib --output-dir temp/test/sharedMods
+  - curl -o temp/test/sharedMods/subspace_storage_1.99.8.zip -L https://github.com/clusterio/factorioClusterioMod/releases/download/1.99.6/subspace_storage_1.99.8.zip
   - npx lerna run build
   - npm run-script ci-cover
   - codecov -f coverage/lcov.info

CHANGELOG.md

@@ -27,6 +27,8 @@ Version 2.0.0
   configuration remotely.
 - Packaged and uploaded to npm again, greatly simplifying distribution and
   installation of both Clusterio and plugins.
+- Added centralized logging for the cluster.  All logs from both Clusterio
+  and Factorio is stored in a shared log which can be inspected and queried.
 
 ### Features
 
@@ -46,6 +48,11 @@ Version 2.0.0
   player data.
 - Added synchronization of in-game adminlist, banlist and whitelist to
   Clusterio core.  Previously this was handled by the playerManager plugin.
+- Added stripping of long paths in the Factorio server log.
+- Added option to configure maximum number of commands to send in parallel.
+- Added option to auto start instances on slave startup.
+- Added metric mapping of slave and instance ids to their names, allowing
+  them to be displayed by name in queries that join with the mapping.
 
 ### Changes
 

docs/configuration.md

@@ -84,7 +84,7 @@ heartbeat interval it will be considered stale and closed.  A lower
 value means less time between connections going stale and them being
 closed.
 
-Defaults to 60
+Defaults to 45
 
 
 ### master.connector_shutdown_timeout
@@ -129,7 +129,7 @@ Defaults to "New Slave".
 
 ### slave.id
 
-Imutable numeric id of the slave which uniquely identifies this slave in
+Immutable numeric id of the slave which uniquely identifies this slave in
 the cluster.
 
 Defaults to a random 31 bit number.
@@ -218,6 +218,15 @@ directory for the instance is created on the slave.
 Defaults to null meaning not assigned.
 
 
+### instance.auto_start
+
+If enabled start this instance when the slave it is assigned to is
+started up.  Does not affect start or stop of the instance while the
+slave is running.
+
+Defaults to false
+
+
 ### factorio.version
 
 Version of Factorio to use for this instance.  Can be a version like
@@ -277,9 +286,45 @@ Factorio server.  The settings in `data/server-settings.example.json` of
 the Factorio installation is used as the base and properties specified
 here overrides the properties there.
 
+Changes to the following properties will be applied live if the instance
+is running while it is changed: `afk_autokick_interval`,
+`allow_commands`, `autosave_interval`, `autosave_only_on_server`,
+`description`, `ignore_player_limit_for_returning_players`,
+`max_players`, `max_upload_slots`, `max_upload_in_kilobytes_per_second`,
+`name`, `only_admins_can_pause_the_game`, `game_password`,
+`require_user_verification`, `tags`, `visibility`.
+
 Defaults to {"tags":["clusterio"],"auto_pause":false}.
 
 
+### factorio.verbose_logging
+
+Pass the `--verbose` flag to Factorio when starting the server.  This
+prints more messages to the log.
+
+Defaults to false
+
+
+### factorio.strip_paths
+
+Strip down absolute paths in the server log going to files inside the
+instance directory such that they are relative to the instance
+directory.  This improves the signal to noise ratio of the log.
+
+Sample output when disabled:
+
+    0.487 Loading map /srv/clusterio/instances/test/saves/world.zip: 2615888 bytes.
+    0.614 Checksum for script /srv/clusterio/instances/test/temp/currently-playing/control.lua: 2390553941
+    1.277 Script @/srv/clusterio/instances/test/temp/currently-playing/modules/example/test.lua:7: Example log line.
+
+Sample output when enabled:
+
+    0.487 Loading map saves/world.zip: 2615888 bytes.
+    0.614 Checksum for script temp/currently-playing/control.lua: 2390553941
+    1.277 Script @modules/example/test.lua:7: Example log line.
+
+Defaults to true
+
 ### factorio.sync_adminlist
 
 Synchronize in-game admin list with admin status of the users in
@@ -314,6 +359,39 @@ banned status while the instance is running.
 Defaults to true
 
 
+### factorio.max_concurrent_commands
+
+Maximum number of commands being transmitted into the game in parallel.
+Since the rate at which long commands are streamed into the game is by
+default limeted to 100 bytes/tick and scales down to 25 bytes/tick when
+there's 20 players connected, long commands can hold up the command
+interface and cause large latencies in getting data pushed into the
+game. (The rates are controlled by the `segment_size` options in the
+server settings.)  To counteract this Clusterio sends up to this
+configured value number of commands in parallel over the RCON interface.
+This causes the game updates sent to clients to have this many command
+streams in parallel contained in them, drastically increasing the
+maxiumum size they can become.  Since commands are only processed so
+ofter the maximum rate of commands that can be sustained is roughly 30
+times this configured value per second, though note that large commands
+will lower this value.
+
+The game updates sent by the server is split into roughly 500 byte
+packets, and if any one of those parts are lost the entire update is
+resent.  This means a high number of concurrent commands can amplify
+resends due to packet loss and degrade the player experience up to the
+point of becomming completely unplayable.
+
+Prior to 0.18.7 the maximum practical size of game update sent where
+arround 8 kB due to the UDP receive buffer on windows defaulting to this
+value, larger updates would not get through the receive buffer and cause
+the connection to drop.  To stay below the 8 kB limit the maximum safe
+value for this option would be around 7000 / (3 * game_speed *
+maximum_segment_size), which is around 20 in normal circumstances.
+
+Defaults to 5
+
+
 ### <plugin_name>.enabled
 
 Whether to enable the given plugin on the instance.  Note that plugins

docs/contributing.md

@@ -223,8 +223,8 @@ should be named the same as the class in PascalCase.
 Imported modules from the lib package are prefixed with lib to make them
 easier to distinguish, as the names tend to be very generic.  E.g.:
 
-    const libLink = require("lib/link");
-    const libLuaTools = require("lib/lua_tools");
+    const libLink = require("@clusterio/lib/link");
+    const libLuaTools = require("@clusterio/lib/lua_tools");
 
 
 For lua code lowercase_underscore is used for everything.

docs/how-it-works.md

@@ -27,4 +27,4 @@ that log into instances under its control.  These accounts are used to
 store per player data and authorize management of the cluster.  By
 default users accounts are assigned a Player role that gives a limited
 read access to the cluster resources, and admins of the cluster can be
-assigned an Admin role to get access to manage it.
+assigned a Cluster Admin role to get access to manage it.

docs/managing-a-cluster.md

@@ -107,7 +107,7 @@ Replaces the roles the user has in the cluster with a new list of roles.
 Calling with an empty roles argument will remove all roles from the
 user.
 
-By default there's a roled named Admin which grants access to
+By default there's a roled named Cluster Admin which grants access to
 everything and a role named Player which grants a limited read access to
 the cluster, see [the section on roles](#roles) for more information
 about setting up roles and permissions.

docs/writing-plugins.md

@@ -11,6 +11,7 @@ Contents
 
 - [Plugin Structure](#plugin-structure)
 - [Defining the plugin class](#defining-the-plugin-class)
+- [Logging Messages](#logging-messages)
 - [Plugin Configuration](#plugin-configuration)
 - [Communicating with Factorio](#communicating-with-factorio)
 - [Defining Link Messages](#defining-link-messages)
@@ -170,6 +171,59 @@ result in unpredicatable behaviour.  The async init method is always called
 immediatly after the constructor, so there's little reason to do this.
 
 
+Logging Messages
+----------------
+
+The base plugin classes provide a winston logger for logging messages to
+the shared cluster log.  For instances a copy of the log is also stored
+on the slave the instance is on.  To use it, pass a string to one of the
+log levels functions, for example:
+
+    async init() {
+        this.logger.info("Initializing frobbing");
+    }
+
+Metadata covering which plugin and instance (for instance plugin
+classes) the log event happened on will automatically be attached to the
+log message.
+
+The available levels are fatal, error, warn, audit, info, and verbose.
+These levels have roughly the following meanings:
+
+- fatal: Unrecoverable error that prevents continuing execution of
+  the Node.js process.  Note that Plugins shouldn't have fatal errors.
+- error: An unexpected error condition occured, usually an exception
+  thrown when it wasn't expected.  Should be investigated and fixed.
+- warn: An potential error was detected, but operation continued
+  gracefully.  These may indicate that something is running
+  sub-optimally, or is not working as intedend.
+- audit: Record of actions performed by users of the cluster.  This
+  is usually emitted in response to management requests by a control
+  link.
+- info: A general log message.  May indicae a status or operation
+  completed.  This should not be emitted by periodic tasks that run
+  often.
+- verbose: A verbose log message which might be useful when
+  investigating issues, does not show by default.  Note that logging
+  messages is not a cheap operation even when the messages do not show
+  up and spammy logging should be avoided for the verbose level.
+  If the logs are still valuable in certain cases consider putting them
+  behind a config option.
+
+For guarding unexpected errors the best option is to log a short
+description along with the`stack` property of the Error:
+
+    try {
+        // Operation that should not throw but may end up throwing
+    } catch (err) {
+        this.logger.error(`Operation failed:\n${err.stack}`);
+    )
+
+For plugin hooks expections thrown are automatically catched and logged,
+but for event handlers registered on EventEmitters it's critical that
+exceptions are catched and handled appropriately.
+
+
 Defining Configuration
 ----------------------
 
@@ -203,7 +257,7 @@ for example in the MasterPluginClass:
 
     async init() {
         let level = this.master.config.get("foo_frobber.level");
-        console.log("I got a frobnication level of", level);
+        this.logger.info(`I got a frobnication level of ${level}`);
     }
 
 The same applies for instance configs, replace "master" with "instance"
@@ -230,11 +284,11 @@ Communicating with Factorio
 
 For pushing data into Factorio there's RCON, which lets you send
 arbitrary Lua commands to invoke whatever code you want in the game.
-This is done by calling the `sendRcon` method on the instance's server object.
+This is done by calling the `sendRcon` method on the plugin object.
 For example:
 
     async onStart() {
-        let response = await this.instance.server.sendRcon(
+        let response = await this.sendRcon(
             "/sc rcon.print('data')"
         );
 
@@ -258,8 +312,8 @@ data sent by `send_json`.  For example in the plugin code:
 
     async init() {
         this.instance.server.on("ipc-my_plugin_foo", content =>
-            this.handleFoo(content).catch(err => console.log(
-                "Error handling foo:", foo
+            this.handleFoo(content).catch(err => this.logger.error(
+                `Error handling foo:\n${err.stack}`
             ))
         );
     }

lerna.json

@@ -3,5 +3,5 @@
     "packages/*",
     "plugins/*"
   ],
-  "version": "2.0.0-alpha.2"
+  "version": "2.0.0-alpha.3"
 }

packages/ctl/ctl.js

@@ -9,9 +9,9 @@ const fs = require("fs-extra");
 const yargs = require("yargs");
 const version = require("./package").version;
 const asTable = require("as-table").configure({ delimiter: " | " });
-const chalk = require("chalk");
 const events = require("events");
 const path = require("path");
+const winston = require("winston");
 
 const libLink = require("@clusterio/lib/link");
 const libErrors = require("@clusterio/lib/errors");
@@ -20,44 +20,13 @@ const libPlugin = require("@clusterio/lib/plugin");
 const libPluginLoader = require("@clusterio/lib/plugin_loader");
 const libCommand = require("@clusterio/lib/command");
 const libSharedCommands = require("@clusterio/lib/shared_commands");
+const { ConsoleTransport, levels, logger } = require("@clusterio/lib/logging");
+const libLoggingUtils = require("@clusterio/lib/logging_utils");
 
 
-/**
- * Format a parsed Factorio output message with colors
- *
- * Formats a parsed Factorio output from lib/factorio into a readable
- * colorized output using terminal escape codes that can be printed.
- *
- * @param {Object} output - Factorio server output.
- * @returns {string} terminal colorized message.
- * @private
- */
-function formatOutputColored(output) {
-	let time = "";
-	if (output.format === "seconds") {
-		time = chalk.yellow(output.time.padStart(8)) + " ";
-	} else if (output.format === "date") {
-		time = chalk.yellow(output.time) + " ";
-	}
-
-	let info = "";
-	if (output.type === "log") {
-		let level = output.level;
-		if (level === "Info") {
-			level = chalk.bold.blueBright(level);
-		} else if (output.level === "Warning") {
-			level = chalk.bold.yellowBright(level);
-		} else if (output.level === "Error") {
-			level = chalk.bold.redBright(level);
-		}
-
-		info = level + " " + chalk.gray(output.file) + ": ";
-
-	} else if (output.type === "action") {
-		info = "[" + chalk.yellow(output.action) + "] ";
-	}
-
-	return time + info + output.message;
+function print(...content) {
+	// eslint-disable-next-line no-console
+	console.log(...content);
 }
 
 const slaveCommands = new libCommand.CommandTree({ name: "slave", description: "Slave management" });
@@ -65,7 +34,7 @@ slaveCommands.add(new libCommand.Command({
 	definition: [["list", "l"], "List slaves connected to the master"],
 	handler: async function(args, control) {
 		let response = await libLink.messages.listSlaves.send(control);
-		console.log(asTable(response.list));
+		print(asTable(response.list));
 	},
 }));
 
@@ -75,7 +44,7 @@ slaveCommands.add(new libCommand.Command({
 	}],
 	handler: async function(args, control) {
 		let response = await libLink.messages.generateSlaveToken.send(control, { slave_id: args.id });
-		console.log(response.token);
+		print(response.token);
 	},
 }));
 
@@ -97,9 +66,9 @@ slaveCommands.add(new libCommand.Command({
 
 		let content = JSON.stringify(response.serialized_config, null, 4);
 		if (args.output === "-") {
-			console.log(content);
+			print(content);
 		} else {
-			console.log(`Writing ${args.output}`);
+			logger.info(`Writing ${args.output}`);
 			try {
 				await fs.outputFile(args.output, content, { flag: "wx" });
 			} catch (err) {
@@ -120,7 +89,7 @@ instanceCommands.add(new libCommand.Command({
 	definition: [["list", "l"], "List instances known to the master"],
 	handler: async function(args, control) {
 		let response = await libLink.messages.listInstances.send(control);
-		console.log(asTable(response.list));
+		print(asTable(response.list));
 	},
 }));
 
@@ -157,7 +126,7 @@ instanceConfigCommands.add(new libCommand.Command({
 
 		for (let group of response.serialized_config.groups) {
 			for (let [name, value] of Object.entries(group.fields)) {
-				console.log(`${group.name}.${name} ${JSON.stringify(value)}`);
+				print(`${group.name}.${name} ${JSON.stringify(value)}`);
 			}
 		}
 	},
@@ -199,13 +168,13 @@ instanceConfigCommands.add(new libCommand.Command({
 instanceCommands.add(instanceConfigCommands);
 
 instanceCommands.add(new libCommand.Command({
-	definition: ["assign <instance> <slave>", "Assign instance to a slave", (yargs) => {
+	definition: ["assign <instance> [slave]", "Assign instance to a slave", (yargs) => {
 		yargs.positional("instance", { describe: "Instance to assign", type: "string" });
-		yargs.positional("slave", { describe: "Slave to assign to", type: "string" });
+		yargs.positional("slave", { describe: "Slave to assign to or unassign if none", type: "string" });
 	}],
 	handler: async function(args, control) {
 		let instanceId = await libCommand.resolveInstance(control, args.instance);
-		let slaveId = await libCommand.resolveSlave(control, args.slave);
+		let slaveId = args.slave ? await libCommand.resolveSlave(control, args.slave) : null;
 		await libLink.messages.assignInstanceCommand.send(control, {
 			instance_id: instanceId,
 			slave_id: slaveId,
@@ -219,7 +188,7 @@ instanceCommands.add(new libCommand.Command({
 	}],
 	handler: async function(args, control) {
 		let instanceId = await libCommand.resolveInstance(control, args.instance);
-		await libLink.messages.setInstanceOutputSubscriptions.send(control, { instance_ids: [instanceId] });
+		await control.setLogSubscriptions({ instance_ids: [instanceId] });
 		let response = await libLink.messages.createSave.send(control, {
 			instance_id: instanceId,
 		});
@@ -232,7 +201,7 @@ instanceCommands.add(new libCommand.Command({
 	}],
 	handler: async function(args, control) {
 		let instanceId = await libCommand.resolveInstance(control, args.instance);
-		await libLink.messages.setInstanceOutputSubscriptions.send(control, { instance_ids: [instanceId] });
+		await control.setLogSubscriptions({ instance_ids: [instanceId] });
 		let response = await libLink.messages.exportData.send(control, {
 			instance_id: instanceId,
 		});
@@ -249,11 +218,12 @@ instanceCommands.add(new libCommand.Command({
 	}],
 	handler: async function(args, control) {
 		let instanceId = await libCommand.resolveInstance(control, args.instance);
-		await libLink.messages.setInstanceOutputSubscriptions.send(control, { instance_ids: [instanceId] });
+		await control.setLogSubscriptions({ instance_ids: [instanceId] });
 		let response = await libLink.messages.startInstance.send(control, {
 			instance_id: instanceId,
 			save: args.save || null,
 		});
+		control.keepOpen = args.keepOpen;
 	},
 }));
 
@@ -267,11 +237,12 @@ instanceCommands.add(new libCommand.Command({
 	}],
 	handler: async function(args, control) {
 		let instanceId = await libCommand.resolveInstance(control, args.instance);
-		await libLink.messages.setInstanceOutputSubscriptions.send(control, { instance_ids: [instanceId] });
+		await control.setLogSubscriptions({ instance_ids: [instanceId] });
 		let response = await libLink.messages.loadScenario.send(control, {
 			instance_id: instanceId,
 			scenario: args.scenario || null,
 		});
+		control.keepOpen = args.keepOpen;
 	},
 }));
 
@@ -281,7 +252,7 @@ instanceCommands.add(new libCommand.Command({
 	}],
 	handler: async function(args, control) {
 		let instanceId = await libCommand.resolveInstance(control, args.instance);
-		await libLink.messages.setInstanceOutputSubscriptions.send(control, { instance_ids: [instanceId] });
+		await control.setLogSubscriptions({ instance_ids: [instanceId] });
 		let response = await libLink.messages.stopInstance.send(control, {
 			instance_id: instanceId,
 		});
@@ -320,7 +291,7 @@ permissionCommands.add(new libCommand.Command({
 	definition: [["list", "l"], "List permissions in the cluster"],
 	handler: async function(args, control) {
 		let response = await libLink.messages.listPermissions.send(control);
-		console.log(asTable(response.list));
+		print(asTable(response.list));
 	},
 }));
 
@@ -330,7 +301,7 @@ roleCommands.add(new libCommand.Command({
 	definition: [["list", "l"], "List roles in the cluster"],
 	handler: async function(args, control) {
 		let response = await libLink.messages.listRoles.send(control);
-		console.log(asTable(response.list));
+		print(asTable(response.list));
 	},
 }));
 
@@ -348,7 +319,7 @@ roleCommands.add(new libCommand.Command({
 			description: args.description,
 			permissions: args.permissions,
 		});
-		console.log(`Created role ID ${response.id}`);
+		logger.info(`Created role ID ${response.id}`);
 	},
 }));
 
@@ -398,7 +369,7 @@ userCommands.add(new libCommand.Command({
 	definition: [["list", "l"], "List user in the cluster"],
 	handler: async function(args, control) {
 		let response = await libLink.messages.listUsers.send(control);
-		console.log(asTable(response.list));
+		print(asTable(response.list));
 	},
 }));
 
@@ -500,12 +471,75 @@ userCommands.add(new libCommand.Command({
 	},
 }));
 
+const logCommands = new libCommand.CommandTree({ name: "log", description: "Log inspection" });
+logCommands.add(new libCommand.Command({
+	definition: ["follow", "follow cluster log", (yargs) => {
+		yargs.options({
+			"all": { describe: "Follow the whole cluster log", nargs: 0, type: "boolean", default: false },
+			"master": { describe: "Follow log of the master server", nargs: 0, type: "boolean", default: false },
+			"slave": { describe: "Follow log of given slave", nargs: 1, type: "string", default: null },
+			"instance": { describe: "Follow log of given instance", nargs: 1, type: "string", default: null },
+		});
+	}],
+	handler: async function(args, control) {
+		if (!args.all && !args.master && !args.slave && !args.instance) {
+			logger.error("At least one of --all, --master, --slave and --instance must be passed");
+			process.exitCode = 1;
+			return;
+		}
+		let instance_ids = args.instance ? [await libCommand.resolveInstance(control, args.instance)] : [];
+		let slave_ids = args.slave ? [await libCommand.resolveSlave(control, args.slave)] : [];
+		await control.setLogSubscriptions({ all: args.all, master: args.master, slave_ids, instance_ids });
+		control.keepOpen = true;
+	},
+}));
+
+logCommands.add(new libCommand.Command({
+	definition: ["query", "Query cluster log", (yargs) => {
+		yargs.options({
+			"all": { describe: "Query the whole cluster log", nargs: 0, type: "boolean", default: false },
+			"master": { describe: "Query log of the master server", nargs: 0, type: "boolean", default: false },
+			"slave": { describe: "Query log of given slave", nargs: 1, type: "string", default: null },
+			"instance": { describe: "Query log of given instance", nargs: 1, type: "string", default: null },
+			"max-level": { describe: "Maximum log level to return", nargs: 1, type: "string", default: null },
+		});
+	}],
+	handler: async function(args, control) {
+		if (!args.all && !args.master && !args.slave && !args.instance) {
+			logger.error("At least one of --all, --master, --slave and --instance must be passed");
+			process.exitCode = 1;
+			return;
+		}
+		let instance_ids = args.instance ? [await libCommand.resolveInstance(control, args.instance)] : [];
+		let slave_ids = args.slave ? [await libCommand.resolveSlave(control, args.slave)] : [];
+		let result = await libLink.messages.queryLog.send(control, {
+			all: args.all,
+			master: args.master,
+			slave_ids,
+			instance_ids,
+			max_level: args.maxLevel,
+		});
+
+		let stdoutLogger = winston.createLogger({
+			level: "verbose",
+			levels,
+			format: new libLoggingUtils.TerminalFormat({ showTimestamp: true }),
+			transports: [
+				new ConsoleTransport({ errorLevels: [], warnLevels: [] }),
+			],
+		});
+		for (let info of result.log) {
+			stdoutLogger.log(info);
+		}
+	},
+}));
+
 const debugCommands = new libCommand.CommandTree({ name: "debug", description: "Debugging utilities" });
 debugCommands.add(new libCommand.Command({
 	definition: ["dump-ws", "Dump WebSocket messages sent and received by master", (yargs) => { }],
 	handler: async function(args, control) {
 		await libLink.messages.debugDumpWs.send(control);
-		return new Promise(() => {});
+		control.keepOpen = true;
 	},
 }));
 
@@ -521,7 +555,7 @@ class ControlConnector extends libLink.WebSocketClientConnector {
 	}
 
 	register() {
-		console.log("SOCKET | registering control");
+		logger.verbose("SOCKET | registering control");
 		this.sendHandshake("register_control", {
 			token: this._token,
 			agent: "clusterioctl",
@@ -550,15 +584,32 @@ class Control extends libLink.Link {
 		for (let controlPlugin of controlPlugins.values()) {
 			libPlugin.attachPluginMessages(this, controlPlugin.info, controlPlugin);
 		}
+
+		/**
+		 * Keep the control connection alive after the command completes.
+		 * @type {boolean}
+		 */
+		this.keepOpen = false;
 	}
 
-	async instanceOutputEventHandler(message) {
-		let { instance_id, output } = message.data;
-		console.log(formatOutputColored(output));
+	async setLogSubscriptions({
+		all = false,
+		master = false,
+		slave_ids = [],
+		instance_ids = [],
+		max_level = null,
+	}) {
+		await libLink.messages.setLogSubscriptions.send(this, {
+			all, master, slave_ids, instance_ids, max_level,
+		});
+	}
+
+	async logMessageEventHandler(message) {
+		logger.log(message.data.info);
 	}
 
 	async debugWsMessageEventHandler(message) {
-		console.log("WS", message.data.direction, message.data.content);
+		print("WS", message.data.direction, message.data.content);
 	}
 
 	async shutdown() {
@@ -581,6 +632,13 @@ async function startControl() {
 	yargs
 		.scriptName("clusterioctl")
 		.usage("$0 <command> [options]")
+		.option("log-level", {
+			nargs: 1,
+			describe: "Log level to print to stderr",
+			default: "server",
+			choices: Object.keys(levels),
+			type: "string",
+		})
 		.option("config", {
 			nargs: 1,
 			describe: "config file to get credentails from",
@@ -603,7 +661,14 @@ async function startControl() {
 	// Parse the args first to get the configured plugin list.
 	let args = yargs.argv;
 
-	console.log(`Loading available plugins from ${args.pluginList}`);
+	// Log stream for the ctl session.
+	logger.add(new ConsoleTransport({
+		errorLevels: Object.keys(levels),
+		level: args.logLevel,
+		format: new libLoggingUtils.TerminalFormat(),
+	}));
+
+	logger.verbose(`Loading available plugins from ${args.pluginList}`);
 	let pluginList = new Map();
 	try {
 		pluginList = new Map(JSON.parse(await fs.readFile(args.pluginList)));
@@ -626,9 +691,10 @@ async function startControl() {
 	rootCommands.add(permissionCommands);
 	rootCommands.add(roleCommands);
 	rootCommands.add(userCommands);
+	rootCommands.add(logCommands);
 	rootCommands.add(debugCommands);
 
-	console.log("Loading Plugin info");
+	logger.verbose("Loading Plugin info");
 	let pluginInfos = await libPluginLoader.loadPluginInfos(pluginList);
 	libConfig.registerPluginConfigGroups(pluginInfos);
 	libConfig.finalizeConfigs();
@@ -640,7 +706,7 @@ async function startControl() {
 		}
 
 		let { ControlPlugin } = require(path.posix.join(pluginInfo.requirePath, pluginInfo.controlEntrypoint));
-		let controlPlugin = new ControlPlugin(pluginInfo);
+		let controlPlugin = new ControlPlugin(pluginInfo, logger);
 		controlPlugins.set(pluginInfo.name, controlPlugin);
 		await controlPlugin.init();
 		await controlPlugin.addCommands(rootCommands);
@@ -659,14 +725,14 @@ async function startControl() {
 		.argv
 	;
 
-	console.log(`Loading config from ${args.config}`);
+	logger.verbose(`Loading config from ${args.config}`);
 	let controlConfig = new libConfig.ControlConfig();
 	try {
 		await controlConfig.load(JSON.parse(await fs.readFile(args.config)));
 
 	} catch (err) {
 		if (err.code === "ENOENT") {
-			console.log("Config not found, initializing new config");
+			logger.verbose("Config not found, initializing new config");
 			await controlConfig.init();
 
 		} else {
@@ -694,7 +760,7 @@ async function startControl() {
 
 	// The remaining commands require connecting to the master server.
 	if (!controlConfig.get("control.master_url") || !controlConfig.get("control.master_token")) {
-		console.error("Missing URL and/or token to connect with.  See README.md for setting up access.");
+		logger.error("Missing URL and/or token to connect with.  See README.md for setting up access.");
 		process.exitCode = 1;
 		return;
 	}
@@ -715,25 +781,24 @@ async function startControl() {
 	}
 
 	process.on("SIGINT", () => {
-		console.log("Caught interrupt signal, closing connection");
+		logger.info("Caught interrupt signal, closing connection");
 		control.shutdown().catch(err => {
-			console.error(err);
+			logger.error(err.stack);
 			process.exit(1);
 		});
 	});
 
-	let keepOpen = Boolean(args.keepOpen);
 	try {
 		await targetCommand.run(args, control);
 
 	} catch (err) {
-		keepOpen = false;
+		control.keepOpen = false;
 		if (err instanceof libErrors.CommandError) {
-			console.error(`Error running command: ${err.message}`);
+			logger.error(`Error running command: ${err.message}`);
 			process.exitCode = 1;
 
 		} else if (err instanceof libErrors.RequestError) {
-			console.error(`Error sending request: ${err.message}`);
+			logger.error(`Error sending request: ${err.message}`);
 			process.exitCode = 1;
 
 		} else {
@@ -741,7 +806,7 @@ async function startControl() {
 		}
 
 	} finally {
-		if (!keepOpen) {
+		if (!control.keepOpen) {
 			await control.shutdown();
 		}
 	}
@@ -749,13 +814,11 @@ async function startControl() {
 
 module.exports = {
 	Control,
-
-	// for testing only
-	_formatOutputColored: formatOutputColored,
 };
 
 
 if (module === require.main) {
+	// eslint-disable-next-line no-console
 	console.warn(`
 +==========================================================+
 I WARNING:  This is the development branch for the 2.0     I
@@ -765,21 +828,22 @@ I           version of clusterio.  Expect things to break. I
 	);
 	startControl().catch(err => {
 		if (!(err instanceof libErrors.StartupError)) {
-			console.error(`
+			logger.fatal(`
 +----------------------------------------------------------------+
 | Unexpected error occured while starting control, please report |
 | it to https://github.com/clusterio/factorioClusterio/issues    |
-+----------------------------------------------------------------+`
++----------------------------------------------------------------+
+${err.stack}`
 			);
 		} else {
-			console.error(`
+			logger.error(`
 +---------------------------------+
 | Unable to to start clusterioctl |
-+---------------------------------+`
++---------------------------------+
+${err.stack}`
 			);
 		}
 
-		console.error(err);
 		process.exitCode = 1;
 	});
 }

packages/ctl/package.json

@@ -3,7 +3,7 @@
   "description": "Clusterio command line management tool",
   "author": "Hornwitser",
   "license": "MIT",
-  "version": "2.0.0-alpha.2",
+  "version": "2.0.0-alpha.3",
   "main": "ctl.js",
   "scripts": {
     "test": "echo \"Error: no test specified\" && exit 1"
@@ -18,10 +18,11 @@
     "node": ">=10.16 <11 || >= 12"
   },
   "dependencies": {
-    "@clusterio/lib": "^2.0.0-alpha.2",
+    "@clusterio/lib": "^2.0.0-alpha.3",
     "as-table": "^1.0.31",
     "chalk": "^3.0.0",
     "fs-extra": "^8.1.0",
+    "winston": "^3.3.3",
     "yargs": "^14.2.0"
   },
   "publishConfig": {

packages/lib/README.md

@@ -5,4 +5,4 @@ This package contains functionality shared between master, slave, ctl
 and/or plugins of Clusterio.
 
 See [the Clusterio repository](https://github.com/clusterio/factorioClusterio)
-for more inforation on Clusterio.
+for more information on Clusterio.

packages/lib/build_mod.js

@@ -1,3 +1,4 @@
+/* eslint-disable no-console */
 "use strict";
 const events = require("events");
 const fs = require("fs-extra");
@@ -12,11 +13,10 @@ async function main() {
 		.scriptName("build")
 		.options({
 			"clean": { describe: "Remove previous builds", type: "boolean", default: false },
-			"build": { describe: "Build mod", type: "boolean", default: true },
+			"build": { describe: "Build mod(s)", type: "boolean", default: true },
 			"pack": { describe: "Pack into zip file", type: "boolean", default: true },
 			"source-dir": { describe: "Path to mod source files", nargs: 1, type: "string", demandOption: true },
-			"output-dir": { describe: "Path to output built mod", nargs: 1, type: "string", default: "dist" },
-			"bump-patch": { describe: "Increment patch number of build", type: "boolean", default: false },
+			"output-dir": { describe: "Path to output built mod(s)", nargs: 1, type: "string", default: "dist" },
 			"factorio-version": { describe: "Override factorio_version", type: "string" },
 		})
 		.strict()
@@ -29,12 +29,6 @@ async function main() {
 async function build(args) {
 	let info = JSON.parse(await fs.readFile(path.join(args.sourceDir, "info.json")));
 
-	if (args.bumpPatch) {
-		let [major, minor, patch] = info.version.split(".");
-		patch = String(Number.parseInt(patch, 10) + 1);
-		info.version = [major, minor, patch].join(".");
-	}
-
 	if (args.factorioVersion) {
 		info.factorio_version = args.factorioVersion;
 	}
@@ -58,6 +52,21 @@ async function build(args) {
 		}
 	}
 
+	if (info.variants) {
+		for (let [variant, variantOverrides] of Object.entries(info.variants)) {
+			let variantInfo = {
+				...info,
+				...variantOverrides,
+			};
+			delete variantInfo.variants;
+			await buildMod(args, variantInfo);
+		}
+	} else {
+		await buildMod(args, info);
+	}
+}
+
+async function buildMod(args, info) {
 	if (args.build) {
 		await fs.ensureDir(args.outputDir);
 		let modName = `${info.name}_${info.version}`;
@@ -77,12 +86,12 @@ async function build(args) {
 			;
 			await events.once(walker, "end");
 
-			for (let pathParts of info.additional_files || []) {
+			for (let [fileName, pathParts] of Object.entries(info.additional_files || {})) {
 				let filePath = path.join(args.sourceDir, ...pathParts);
 				if (!await fs.pathExists(filePath)) {
 					throw new Error(`Additional file ${filePath} does not exist`);
 				}
-				zip.file(path.posix.join(modName, path.basename(filePath)), fs.createReadStream(filePath));
+				zip.file(path.posix.join(modName, fileName), fs.createReadStream(filePath));
 			}
 			delete info.additional_files;
 
@@ -101,9 +110,9 @@ async function build(args) {
 			}
 			console.log(`Building ${modDir}`);
 			await fs.copy(args.sourceDir, modDir);
-			for (let pathParts of info.additional_files || []) {
+			for (let [fileName, pathParts] of Object.entries(info.additional_files) || []) {
 				let filePath = path.join(...pathParts);
-				await fs.copy(filePath, path.join(modDir, path.basename(filePath)));
+				await fs.copy(filePath, path.join(modDir, fileName));
 			}
 			delete info.additional_files;
 

packages/lib/config/definitions.js

@@ -78,7 +78,7 @@ MasterGroup.define({
 	title: "Heartbeat Interval",
 	description: "Interval heartbeats are sent out on WebSocket connections",
 	type: "number",
-	initial_value: 60,
+	initial_value: 45,
 });
 MasterGroup.define({
 	name: "connector_shutdown_timeout",
@@ -196,6 +196,12 @@ InstanceGroup.define({
 	type: "number",
 	optional: true,
 });
+InstanceGroup.define({
+	name: "auto_start",
+	description: "Automatically start this instance when the slave hosting it is started up",
+	type: "boolean",
+	initial_value: false,
+});
 InstanceGroup.finalize();
 
 /**
@@ -250,6 +256,18 @@ FactorioGroup.define({
 		"auto_pause": false,
 	},
 });
+FactorioGroup.define({
+	name: "verbose_logging",
+	description: "Enable verbose logging on the Factorio server",
+	type: "boolean",
+	initial_value: false,
+});
+FactorioGroup.define({
+	name: "strip_paths",
+	description: "Strip down instance paths in the log",
+	type: "boolean",
+	initial_value: true,
+});
 FactorioGroup.define({
 	name: "sync_adminlist",
 	description: "Synchronize adminlist with master server",
@@ -268,6 +286,12 @@ FactorioGroup.define({
 	type: "boolean",
 	initial_value: true,
 });
+FactorioGroup.define({
+	name: "max_concurrent_commands",
+	description: "Maximum number of RCON commands trasmitted in parallel",
+	type: "number",
+	initial_value: 5,
+});
 FactorioGroup.finalize();
 
 /**

packages/lib/factorio/export.js

@@ -140,7 +140,7 @@ async function exportItems(server, modVersions, items) {
 				iconCache.set(iconPath, icon);
 			} else {
 				icon = null;
-				console.log(`Warning: ${iconPath} not found`);
+				server._logger.warn(`${iconPath} not found`);
 			}
 			iconCache.set(iconPath, icon);
 		}
@@ -324,9 +324,9 @@ async function exportData(server) {
 
 	server.on("ipc-item_export", data => items.push(data));
 	server.on("ipc-mod_list", data => { modVersions = new Map(Object.entries(data)); });
-	server.on("output", data => {
-		if (data.format === "seconds" && data.type === "generic") {
-			let match = /^Checksum of (.*): \d+$/.exec(data.message);
+	server.on("output", parsed => {
+		if (parsed.format === "seconds" && parsed.type === "generic") {
+			let match = /^Checksum of (.*): \d+$/.exec(parsed.message);
 			if (match) {
 				modOrder.push(match[1]);
 			}

packages/lib/factorio/server.js

@@ -10,8 +10,25 @@ const crypto = require("crypto");
 const ini = require("ini");
 const rconClient = require("rcon-client");
 const libErrors = require("@clusterio/lib/errors");
+const { logger } = require("@clusterio/lib/logging");
 
 
+/**
+ * Escapes text for inclusion in a RegExp
+ *
+ * Adds \ character in front of special meta characters in the passsed in
+ * text so that it can be embedded into a RegExp and only match the text.
+ *
+ * See https://stackoverflow.com/a/9310752
+ *
+ * @param {string} text - Text to escape RegExp meta chars in.
+ * @returns {string} escaped text.
+ * @inner
+ */
+function escapeRegExp(text) {
+	return text.replace(/[-[\]{}()*+?.,\\^$|#\s]/g, "\\$&");
+}
+
 /**
  * Determines the version of Factorio the datadir is pointing to by
  * reading the changelog.txt in it.
@@ -286,7 +303,6 @@ class LineSplitter {
 function parseOutput(line, source) {
 	let output = {
 		source,
-		received: Date.now(),
 	};
 
 	// There are three broad categories of output from Factorio, the first kind
@@ -302,13 +318,15 @@ function parseOutput(line, source) {
 		// A seconds output has two different kinds of formats: The first is a
 		// log level and source location and has a format of
 		// "Level File.cpp:123: message"
-		const secLogRegex = /^(\w+) (\w+\.cpp:\d+): (.*)$/;
+		// "Script @/path/to/file.lua:123: message"
+		// "Script =(command):123: message"
+		const secLogRegex = /^(\w+) ((\w+\.cpp:\d+)|([@=].*?:\d+)): (.*)$/;
 		let secLogMatch = secLogRegex.exec(secContent);
 		if (secLogMatch) {
 			output.type = "log";
 			output.level = secLogMatch[1];
 			output.file = secLogMatch[2];
-			output.message = secLogMatch[3];
+			output.message = secLogMatch[5];
 
 		// The other possibility is that the content is a generic message
 		} else {
@@ -365,7 +383,7 @@ const outputHeuristics = [
 	// Message indicating the RCON interface has started
 	{
 		filter: { type: "log", message: /^Starting RCON interface/ },
-		action: function(output) {
+		action: function() {
 			this._startRcon().catch((err) => { this.emit("error", err); });
 		},
 	},
@@ -373,7 +391,7 @@ const outputHeuristics = [
 	// Message indicating the server is done starting up
 	{
 		filter: { type: "log", message: /^updateTick\(\d+\) changing state from\(CreatingGame\) to\(InGame\)$/ },
-		action: function(output) {
+		action: function() {
 			this._notifyGameReady().catch((err) => { this.emit("error", err); });
 		},
 	},
@@ -384,8 +402,8 @@ const outputHeuristics = [
 			type: "log",
 			message: /^Saving to _autosave\d+ \((non-)?blocking\)\.$/,
 		},
-		action: function(output) {
-			let name = /^Saving to (_autosave\d+) /.exec(output.message)[1];
+		action: function(parsed) {
+			let name = /^Saving to (_autosave\d+) /.exec(parsed.message)[1];
 			this.emit("_autosave", name);
 		},
 	},
@@ -396,7 +414,7 @@ const outputHeuristics = [
 			type: "log",
 			message: /^Saving game as /,
 		},
-		action: function(output) {
+		action: function() {
 			this.emit("_saving");
 		},
 	},
@@ -412,7 +430,7 @@ const outputHeuristics = [
 				"Can't save to default location: Default location not known",
 			],
 		},
-		action: function(output) {
+		action: function() {
 			this.emit("_saved");
 		},
 	},
@@ -423,13 +441,13 @@ const outputHeuristics = [
 			type: "generic",
 			message: /^Quitting: /,
 		},
-		action: function(output) {
+		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
 			// process when this happens.
-			if (process.platform === "win32" && output.message === "Quitting: multiplayer error.") {
+			if (process.platform === "win32" && parsed.message === "Quitting: multiplayer error.") {
 				this._server.kill();
 			}
 		},
@@ -445,8 +463,8 @@ const outputHeuristics = [
 				"MultiplayerManager failed: Host address is already in use.",
 			],
 		},
-		action: function(output) {
-			this._unexpected.push(`Factorio failed to bind to game port: ${output.message}`);
+		action: function(parsed) {
+			this._unexpected.push(`Factorio failed to bind to game port: ${parsed.message}`);
 		},
 	},
 	{
@@ -458,8 +476,8 @@ const outputHeuristics = [
 				"Can't bind socket: Permission denied",
 			],
 		},
-		action: function(output) {
-			this._unexpected.push(`Factorio failed to bind to RCON port: ${output.message}`);
+		action: function(parsed) {
+			this._unexpected.push(`Factorio failed to bind to RCON port: ${parsed.message}`);
 		},
 	},
 ];
@@ -491,12 +509,19 @@ class FactorioServer extends events.EventEmitter {
 	 * @param {string} factorioDir - Directory of the Factorio install(s).
 	 * @param {string} writeDir - Directory to write runtime data to.
 	 * @param {object} options - Optional parameters.
+	 * @param {Logger} options.logger - Logger to use for reporting errors.
 	 * @param {string} options.version -
 	 *     Version of Factorio to use.  Can also be the string "latest" to
 	 *     use the latest version found in `factorioDir`.
 	 * @param {number} options.gamePort - UDP port to host game on.
 	 * @param {number} options.rconPort - TCP port to use for RCON.
 	 * @param {string} options.rconPassword - Password use for RCON.
+	 * @param {boolean} options.enableWhitelist - Turn on whitelisting.
+	 * @param {boolean} options.verboseLogging - Enable verbose logging.
+	 * @param {boolean} options.stripPaths - Strip paths in the console.
+	 * @param {number} options.maxConcurrentCommands -
+	 *     Maximum number of RCON commands transmitted in parallel on the
+	 *     RCON connection.
 	 */
 	constructor(factorioDir, writeDir, options) {
 		super();
@@ -508,6 +533,7 @@ class FactorioServer extends events.EventEmitter {
 		this._version = null;
 		this._dataDir = null;
 
+		this._logger = options.logger || logger;
 		this._targetVersion = options.version || "latest";
 		/** UDP port used for hosting the Factorio game server on */
 		this.gamePort = options.gamePort || randomDynamicPort();
@@ -517,12 +543,29 @@ class FactorioServer extends events.EventEmitter {
 		this.rconPassword = options.rconPassword;
 		/** Enable player whitelist */
 		this.enableWhitelist = options.enableWhitelist;
+		/** Enable verbose logging */
+		this.verboseLogging = options.verboseLogging;
+		/** Maximum number of RCON commands transmitted in parallel on the RCON connection  */
+		this.maxConcurrentCommands = options.maxConcurrentCommands || 5;
 		this._state = "new";
 		this._server = null;
 		this._rconClient = null;
 		this._rconReady = false;
 		this._gameReady = false;
 
+		if (options.stripPaths) {
+			let chars = new Set(this.writePath("temp"));
+			chars.delete(":"); // Having a colon could lead to matching the line number
+			chars = [...chars].join("");
+
+			this._stripRegExp = new RegExp(
+				`(${escapeRegExp(this.writePath("temp", "currently-playing", path.sep))})|` +
+				`(${escapeRegExp(this.writePath(path.sep))})|` +
+				`(\\.\\.\\.[${escapeRegExp(chars)}]*?currently-playing\\${path.sep})`,
+				"g"
+			);
+		}
+
 		// Array of possible causes for an unexpected shutdown
 		this._unexpected = [];
 
@@ -594,7 +637,7 @@ class FactorioServer extends events.EventEmitter {
 		}
 
 		if (!this.emit(`ipc-${channel}`, content)) {
-			console.warn(`Warning: Unhandled ipc-${channel}`, content);
+			this.logger.warn(`Warning: Unhandled ipc-${channel}`, { content });
 		}
 	}
 
@@ -606,31 +649,37 @@ class FactorioServer extends events.EventEmitter {
 
 		this.emit(source, line);
 
-		let output = parseOutput(line.toString("utf-8"), source);
+		line = line.toString("utf-8");
+		if (this._stripRegExp) {
+			line = line.replace(this._stripRegExp, "");
+		}
+
+
+		let parsed = parseOutput(line, source);
 		heuristicLoop: for (let heuristic of outputHeuristics) {
 			for (let [name, expected] of Object.entries(heuristic.filter)) {
-				if (!Object.hasOwnProperty.call(output, name)) {
+				if (!Object.hasOwnProperty.call(parsed, name)) {
 					continue heuristicLoop;
 				}
 
 				if (expected instanceof RegExp) {
-					if (!expected.test(output[name])) {
+					if (!expected.test(parsed[name])) {
 						continue heuristicLoop;
 					}
 				} else if (expected instanceof Array) {
-					if (!expected.includes(output[name])) {
+					if (!expected.includes(parsed[name])) {
 						continue heuristicLoop;
 					}
-				} else if (expected !== output[name]) {
+				} else if (expected !== parsed[name]) {
 					continue heuristicLoop;
 				}
 			}
 
 			// If we get here the filter matched the output
-			heuristic.action.call(this, output);
+			heuristic.action.call(this, parsed);
 		}
 
-		this.emit("output", output);
+		this.emit("output", parsed, line);
 	}
 
 	async _startRcon() {
@@ -647,7 +696,7 @@ class FactorioServer extends events.EventEmitter {
 			port: this.rconPort,
 			password: this.rconPassword,
 			timeout: 200000, // 200s, should allow for commands up to 1250kB in length
-			maxPending: 5,
+			maxPending: this.maxConcurrentCommands,
 		};
 
 		this._rconClient = new rconClient.Rcon(config);
@@ -658,9 +707,31 @@ class FactorioServer extends events.EventEmitter {
 			this._rconReady = false;
 			this._startRcon().catch(() => { /* Ignore */ });
 		});
+		// 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();
 	}
 
+	get maxConcurrentCommands() {
+		return this._maxConcurrentCommands;
+	}
+
+	set maxConcurrentCommands(value) {
+		this._maxConcurrentCommands = value;
+		this.setMaxListeners(value + 5);
+		if (this._rconClient) {
+			if (this._rconClient.sendQueue) {
+				this._rconClient.sendQueue.maxConcurrent = value;
+			}
+			// XXX: Workaround to suppress bogus event listener warning
+			if (this._rconClient.emitter instanceof events.EventEmitter) {
+				this._rconClient.emitter.setMaxListeners(value + 5);
+			}
+		}
+	}
+
 	/**
 	 * Initialize class instance
 	 *
@@ -774,6 +845,7 @@ class FactorioServer extends events.EventEmitter {
 			[
 				"--config", this.writePath("config.ini"),
 				"--create", this.writePath("saves", name),
+				...(this.verboseLogging ? ["--verbose"] : []),
 			],
 			{
 				detached: true,
@@ -816,6 +888,7 @@ class FactorioServer extends events.EventEmitter {
 				"--rcon-port", this.rconPort,
 				"--rcon-password", this.rconPassword,
 				...(this.enableWhitelist ? ["--use-server-whitelist"] : []),
+				...(this.verboseLogging ? ["--verbose"] : []),
 			],
 			{
 				detached: true,
@@ -850,6 +923,7 @@ class FactorioServer extends events.EventEmitter {
 				"--rcon-port", this.rconPort,
 				"--rcon-password", this.rconPassword,
 				...(this.enableWhitelist ? ["--use-server-whitelist"] : []),
+				...(this.verboseLogging ? ["--verbose"] : []),
 			],
 			{
 				detached: true,
@@ -898,11 +972,11 @@ class FactorioServer extends events.EventEmitter {
 		this._check(["running"]);
 
 		let hanged = true;
-		function setAlive(output) { hanged = false; }
+		function setAlive() { hanged = false; }
 
 		let timeoutId = setTimeout(() => {
 			if (hanged) {
-				console.error("Factorio appears to have hanged, sending SIGKILL");
+				logger.error("Factorio appears to have hanged, sending SIGKILL");
 				if (this._rconClient) {
 					this._rconClient.end().catch(() => {});
 				}

packages/lib/helpers.js

@@ -19,6 +19,41 @@ function basicType(value) {
 	return typeof value;
 }
 
+
+/**
+ * Asynchronously wait for the given duration
+ *
+ * @param {number} duration - Time to wait for in milliseconds.
+ */
+async function wait(duration) {
+	await new Promise(resolve => { setTimeout(resolve, duration); });
+}
+
+
+/**
+ * Resolve a promise with a timeout.
+ *
+ * @param {Promise} promise - Promise to wait for.
+ * @param {number} time - Maximum time im milliseconds to wait for.
+ * @param {*=} timeoutResult - Value to return if the operation timed out.
+ */
+async function timeout(promise, time, timeoutResult) {
+	let timer;
+	try {
+		return await Promise.race([
+			promise,
+			new Promise(resolve => {
+				timer = setTimeout(() => resolve(timeoutResult), time);
+			}),
+		]);
+
+	} finally {
+		clearTimeout(timer);
+	}
+}
+
 module.exports = {
 	basicType,
+	wait,
+	timeout,
 };

packages/lib/link/connectors.js

@@ -5,6 +5,7 @@ const WebSocket = require("isomorphic-ws");
 
 const libSchema = require("@clusterio/lib/schema");
 const libErrors = require("@clusterio/lib/errors");
+const { logger } = require("@clusterio/lib/logging");
 
 
 /**
@@ -45,7 +46,7 @@ class WebSocketBaseConnector extends events.EventEmitter {
 	_doHeartbeat() {
 		this._check(["connected", "closing"]);
 		if (Date.now() - this._lastHeartbeat > 2000 * this._heartbeatInterval) {
-			console.log("SOCKET | closing after heartbeat timed out");
+			logger.verbose("SOCKET | closing after heartbeat timed out");
 			this._socket.close(1008, "Heartbeat timeout");
 			clearInterval(this._heartbeatId);
 			this._heartbeatId = null;
@@ -61,9 +62,8 @@ class WebSocketBaseConnector extends events.EventEmitter {
 
 	_processHeartbeat(message) {
 		if (!libSchema.heartbeat(message)) {
-			console.log("SOCKET | closing after received invalid heartbeat:", message);
+			logger.warn("SOCKET | closing after received invalid heartbeat");
 			this._socket.close(1002, "Invalid heartbeat");
-			console.log(libSchema.heartbeat.errors);
 			return;
 		}
 
@@ -236,7 +236,7 @@ class WebSocketClientConnector extends WebSocketBaseConnector {
 		url.pathname += "api/socket";
 
 		// Open WebSocket to master
-		console.log(`SOCKET | connecting to ${url}`);
+		logger.verbose(`SOCKET | connecting to ${url}`);
 
 		// eslint-disable-next-line no-process-env
 		if (process.env.APP_ENV === "browser") {
@@ -266,7 +266,7 @@ class WebSocketClientConnector extends WebSocketBaseConnector {
 		}
 
 		if (this._startedReconnect + this._timeout * 1000 < Date.now()) {
-			console.log("SOCKET | Timed out trying to reconnect");
+			logger.error("SOCKET | Timed out trying to reconnect");
 			this._heartbeatInterval = null;
 			this._lastReceivedSeq = null;
 			this._sessionToken = null;
@@ -277,7 +277,9 @@ class WebSocketClientConnector extends WebSocketBaseConnector {
 		}
 
 		let delay = Math.random() * this._reconnectDelay;
-		console.log(`SOCKET | waiting ${delay.toLocaleString("en", { maximumFractionDigits: 2 })} seconds for reconnect`);
+		logger.verbose(
+			`SOCKET | waiting ${delay.toLocaleString("en", { maximumFractionDigits: 2 })} seconds for reconnect`
+		);
 		this._reconnectId = setTimeout(() => {
 			this._reconnectId = null;
 			this._doConnect();
@@ -286,7 +288,7 @@ class WebSocketClientConnector extends WebSocketBaseConnector {
 
 	_attachSocketHandlers() {
 		this._socket.onclose = event => {
-			console.log(`SOCKET | Close (code: ${event.code}, reason: ${event.reason})`);
+			logger.verbose(`SOCKET | Close (code: ${event.code}, reason: ${event.reason})`);
 			// Authentication failed
 			if (event.code === 4003) {
 				this.emit("error", new libErrors.AuthenticationFailed(event.reason));
@@ -315,11 +317,11 @@ class WebSocketClientConnector extends WebSocketBaseConnector {
 
 		this._socket.onerror = event => {
 			// It's assumed that close is always called by ws
-			console.error("SOCKET | Error:", event);
+			logger.error(`SOCKET | Error: ${event.message || "unknown error"}`);
 		};
 
 		this._socket.onopen = () => {
-			console.log("SOCKET | Open");
+			logger.verbose("SOCKET | Open");
 		};
 
 		// Handle messages
@@ -348,17 +350,17 @@ class WebSocketClientConnector extends WebSocketBaseConnector {
 
 	_processHandshake(message) {
 		if (!libSchema.serverHandshake(message)) {
-			console.log("SOCKET | closing after received invalid handshake:", message);
+			logger.verbose("SOCKET | closing after received invalid handshake");
 			this._socket.close(1002, "Invalid handshake");
 			return;
 		}
 
 		let { seq, type, data } = message;
 		if (type === "hello") {
-			console.log(`SOCKET | received hello from master version ${data.version}`);
+			logger.verbose(`SOCKET | received hello from master version ${data.version}`);
 			this.emit("hello", data);
 			if (this._sessionToken) {
-				console.log("SOCKET | Attempting resume");
+				logger.verbose("SOCKET | Attempting resume");
 				this.sendHandshake("resume", {
 					session_token: this._sessionToken,
 					last_seq: this._lastReceivedSeq,
@@ -368,7 +370,7 @@ class WebSocketClientConnector extends WebSocketBaseConnector {
 			}
 
 		} else if (type === "ready") {
-			console.log("SOCKET | received ready from master");
+			logger.verbose("SOCKET | received ready from master");
 			this._state = "connected";
 			this._sessionToken = data.session_token;
 			this._heartbeatInterval = data.heartbeat_interval;
@@ -381,7 +383,7 @@ class WebSocketClientConnector extends WebSocketBaseConnector {
 			this.emit("connect");
 
 		} else if (type === "continue") {
-			console.log("SOCKET | resuming existing session");
+			logger.verbose("SOCKET | resuming existing session");
 			this._state = "connected";
 			this._heartbeatInterval = data.heartbeat_interval;
 			this.startHeartbeat();

packages/lib/link/link.js

@@ -3,6 +3,7 @@
 
 const libSchema = require("@clusterio/lib/schema");
 const libErrors = require("@clusterio/lib/errors");
+const { logger } = require("@clusterio/lib/logging");
 const messages = require("./messages");
 
 // Some definitions for the terminology used here:
@@ -35,9 +36,21 @@ class Link {
 				this.processMessage(payload);
 			} catch (err) {
 				if (err instanceof libErrors.InvalidMessage) {
-					console.error(`Invalid message on ${this.source}-${this.target} link: ${err.message}`);
+					logger.error(`Invalid message on ${this.source}-${this.target} link: ${err.message}`);
 					if (err.errors) {
-						console.error(err.errors);
+						logger.error(JSON.stringify(err.errors, null, 4));
+					}
+
+					// Send back an error response if this was a request.
+					if (
+						typeof payload.type === "string"
+						&& payload.type.endsWith("_request")
+						&& Number.isInteger(payload.seq)
+					) {
+						this.connector.send(
+							`${payload.type.slice(0, -8)}_response`,
+							{ seq: payload.seq, error: err.message }
+						);
 					}
 				} else {
 					this.connector.emit("error", err);

packages/lib/link/messages.js

@@ -2,6 +2,26 @@
 "use strict";
 const libSchema = require("@clusterio/lib/schema");
 const libErrors = require("@clusterio/lib/errors");
+const { logger } = require("@clusterio/lib/logging");
+
+class MissingLinkHandlerError extends Error {
+	constructor(type, source, target) {
+		super();
+		this.code = "MISSING_LINK_HANDLER";
+		this.type = type;
+		this.source = source;
+		this.target = target;
+		this.handler = null;
+		this.plugin = null;
+	}
+
+	get message() {
+		let handler = this.handler ? `${this.handler}` : "handler";
+		let plugin = this.plugin ? ` on plugin ${this.plugin}` : "";
+
+		return `Missing ${handler}${plugin} for ${this.type} on ${this.source}-${this.target} link`;
+	}
+}
 
 /**
  * Represents a message that can be sent over the link
@@ -168,7 +188,7 @@ class Request extends Message {
 			}
 
 			if (!handler) {
-				throw new Error(`Missing handler for ${this.requestType} on ${link.source}-${link.target} link`);
+				throw new MissingLinkHandlerError(this.requestType, link.source, link.target);
 			}
 
 			// Check permission if this is a handler for a control connection on the master
@@ -188,7 +208,7 @@ class Request extends Message {
 					}
 
 					if (!this._responseValidator({ seq: 0, type: this.responseType, response })) {
-						console.error(this._responseValidator.errors);
+						logger.error(JSON.stringify(this._responseValidator.errors, null, 4));
 						throw new Error(`Validation failed responding to ${this.requestType}`);
 					}
 
@@ -196,7 +216,7 @@ class Request extends Message {
 
 				}).catch(err => {
 					if (!(err instanceof libErrors.RequestError)) {
-						console.error(`Unexpected error while responding to ${this.requestType}`, err);
+						logger.error(`Unexpected error while responding to ${this.requestType}:\n${err.stack}`);
 					}
 					link.connector.send(this.responseType, { seq: message.seq, error: err.message });
 				});
@@ -217,7 +237,7 @@ class Request extends Message {
 	async send(link, data = {}) {
 		// XXX validate link target/source?
 		if (!this._requestValidator({ seq: 0, type: this.requestType, data })) {
-			console.error(this._requestValidator.errors);
+			logger.error(JSON.stringify(this._requestValidator.errors, null, 4));
 			throw new Error(`Validation failed sending ${this.requestType}`);
 		}
 		let seq = link.connector.send(this.requestType, data);
@@ -330,18 +350,6 @@ messages.createSlaveConfig = new Request({
 	},
 });
 
-messages.setInstanceOutputSubscriptions = new Request({
-	type: "set_instance_output_subscriptions",
-	links: ["control-master"],
-	permission: "core.instance.follow_log",
-	requestProperties: {
-		"instance_ids": {
-			type: "array",
-			items: { type: "integer" },
-		},
-	},
-});
-
 messages.createInstance = new Request({
 	type: "create_instance",
 	links: ["control-master"],
@@ -392,19 +400,10 @@ messages.assignInstanceCommand = new Request({
 	permission: "core.instance.assign",
 	requestProperties: {
 		"instance_id": { type: "integer" },
-		"slave_id": { type: "integer" },
+		"slave_id": { type: ["integer", "null"] },
 	},
 });
 
-messages.assignInstance = new Request({
-	type: "assign_instance",
-	links: ["master-slave"],
-	requestProperties: {
-		"serialized_config": { type: "object" },
-	},
-	forwardTo: "instance",
-});
-
 messages.startInstance = new Request({
 	type: "start_instance",
 	links: ["control-master", "master-slave", "slave-instance"],
@@ -636,8 +635,90 @@ messages.deleteUser = new Request({
 	},
 });
 
+messages.setLogSubscriptions = new Request({
+	type: "set_log_subscriptions",
+	links: ["control-master"],
+	permission: "core.log.follow",
+	requestProperties: {
+		"all": { type: "boolean" },
+		"master": { type: "boolean" },
+		"slave_ids": {
+			type: "array",
+			items: { type: "integer" },
+		},
+		"instance_ids": {
+			type: "array",
+			items: { type: "integer" },
+		},
+		"max_level": { type: ["string", "null"] },
+	},
+});
+
+messages.queryLog = new Request({
+	type: "query_log",
+	links: ["control-master"],
+	permission: "core.log.query",
+	requestProperties: {
+		"all": { type: "boolean" },
+		"master": { type: "boolean" },
+		"slave_ids": {
+			type: "array",
+			items: { type: "integer" },
+		},
+		"instance_ids": {
+			type: "array",
+			items: { type: "integer" },
+		},
+		"max_level": { type: ["string", "null"] },
+	},
+	responseProperties: {
+		"log": {
+			type: "array",
+			items: { type: "object" },
+		},
+	},
+});
+
+
+// Internal requests
+messages.updateInstances = new Request({
+	type: "update_instances",
+	links: ["slave-master"],
+	requestProperties: {
+		"instances": {
+			type: "array",
+			items: {
+				type: "object",
+				additionalProperties: false,
+				required: ["serialized_config", "status"],
+				properties: {
+					"serialized_config": { type: "object" },
+					"status": { enum: [
+						"stopped", "starting", "running", "creating_save", "exporting_data",
+					]},
+				},
+			},
+		},
+	},
+});
+
+messages.assignInstance = new Request({
+	type: "assign_instance",
+	links: ["master-slave"],
+	requestProperties: {
+		"serialized_config": { type: "object" },
+	},
+	forwardTo: "instance",
+});
+
+messages.unassignInstance = new Request({
+	type: "unassigne_instance",
+	links: ["master-slave"],
+	forwardTo: "instance",
+});
+
 messages.getMetrics = new Request({
-	type: "statistics_exporter:get_metrics",
+	type: "get_metrics",
 	links: ["master-slave", "slave-instance"],
 	responseProperties: {
 		"results": { type: "array" },
@@ -766,13 +847,13 @@ class Event extends Message {
 			}
 
 			if (!handler) {
-				throw new Error(`Missing handler for ${this.eventType} on ${link.source}-${link.target} link`);
+				throw new MissingLinkHandlerError(this.eventType, link.source, link.target);
 			}
 
 			link.setHandler(this.eventType, message => {
 				// XXX Should event handlers even be allowed to be async?
 				handler.call(link, message, this).catch(err => {
-					console.error(`Unexpected error while handling ${this.eventType}`, err);
+					logger.error(`Unexpected error while handling ${this.eventType}:\n${err.stack}`);
 				});
 			}, this._eventValidator);
 		}
@@ -788,7 +869,7 @@ class Event extends Message {
 	 */
 	send(link, data = {}) {
 		if (!this._eventValidator({ seq: 0, type: this.eventType, data })) {
-			console.error(this._eventValidator.errors);
+			logger.error(JSON.stringify(this._eventValidator.errors, null, 4));
 			throw new Error(`Validation failed sending ${this.eventType}`);
 		}
 
@@ -805,6 +886,21 @@ messages.debugWsMessage = new Event({
 	},
 });
 
+messages.logMessage = new Event({
+	type: "log_message",
+	links: ["slave-master", "master-control"],
+	eventProperties: {
+		"info": {
+			type: "object",
+			required: ["level", "message"],
+			properties: {
+				"level": { type: "string" },
+				"message": { type: "string" },
+			},
+		},
+	},
+});
+
 messages.instanceInitialized = new Event({
 	type: "instance_initialized",
 	links: ["instance-slave"],
@@ -827,52 +923,6 @@ messages.instanceStatusChanged = new Event({
 	},
 });
 
-messages.updateInstances = new Event({
-	type: "update_instances",
-	links: ["slave-master"],
-	eventProperties: {
-		"instances": {
-			type: "array",
-			items: {
-				type: "object",
-				additionalProperties: false,
-				required: ["serialized_config", "status"],
-				properties: {
-					"serialized_config": { type: "object" },
-					"status": { enum: [
-						"stopped", "starting", "running", "creating_save", "exporting_data",
-					]},
-				},
-			},
-		},
-	},
-});
-
-messages.instanceOutput = new Event({
-	type: "instance_output",
-	links: ["instance-slave", "slave-master", "master-control"],
-	forwardTo: "master",
-	eventProperties: {
-		"instance_id": { type: "integer" },
-		"output": {
-			type: "object",
-			additionalProperties: false,
-			required: ["source", "received", "format", "type", "message"],
-			properties: {
-				"source": { type: "string" },
-				"received": { type: "number" },
-				"format": { type: "string" },
-				"time": { type: "string" },
-				"level": { type: "string" },
-				"file": { type: "string" },
-				"type": { type: "string" },
-				"action": { type: "string" },
-				"message": { type: "string" },
-			},
-		},
-	},
-});
-
 messages.masterConnectionEvent = new Event({
 	type: "master_connection_event",
 	links: ["slave-instance"],
@@ -959,7 +1009,15 @@ messages.playerEvent = new Event({
  */
 function attachAllMessages(link) {
 	for (let [name, message] of Object.entries(messages)) {
-		message.attach(link, link[name + message.handlerSuffix]);
+		let handler = `${name}${message.handlerSuffix}`;
+		try {
+			message.attach(link, link[handler]);
+		} catch (err) {
+			if (err.code === "MISSING_LINK_HANDLER") {
+				err.handler = handler;
+			}
+			throw err;
+		}
 	}
 }
 

packages/lib/logging.js

@@ -0,0 +1,94 @@
+"use strict";
+const winston = require("winston");
+const Transport = require("winston-transport");
+const { LEVEL, MESSAGE } = require("triple-beam");
+
+const levels = Object.freeze({
+	fatal: 0,
+	error: 1,
+	warn: 2,
+	audit: 3,
+	info: 4,
+	server: 5,
+	verbose: 6,
+});
+
+const colors = {
+	fatal: "inverse red",
+	error: "bold brightRed",
+	warn: "bold brightYellow",
+	audit: "bold brightGreen",
+	info: "bold brightBlue",
+	server: "bold",
+	verbose: "bold grey",
+};
+winston.addColors(colors);
+
+// The Console Transport is replicated here because it's overly complicated
+// in winston, writes to stdout/err instead of console and doesn't work in
+// the browser.
+class ConsoleTransport extends Transport {
+	constructor(options = {}) {
+		super(options);
+		this.errorLevels = new Set(options.errorLevels || ["fatal", "error"]);
+		this.warnLevels = new Set(options.warnLevels || ["warn"]);
+	}
+
+	log(info, callback) {
+		/* eslint-disable no-console */
+		if (this.errorLevels.has(info[LEVEL])) {
+			console.error(info[MESSAGE]);
+		} else if (this.warnLevels.has(info[LEVEL])) {
+			console.warn(info[MESSAGE]);
+		} else {
+			console.log(info[MESSAGE]);
+		}
+		/* eslint-enable no-console */
+		callback();
+	}
+}
+
+/**
+ * Formats winston log messages for the web console
+ */
+class WebConsoleFormat {
+	constructor(options = {}) {
+		this.options = options;
+	}
+
+	transform(info, options) {
+		let src = " ";
+		if (info.slave_id) {
+			let slaveName = info.slave_id;
+			src += `s:${slaveName} - `;
+		}
+		if (info.instance_id) {
+			let instanceName = info.instance_id;
+			src += `i:${instanceName}`;
+		}
+		if (info.plugin) {
+			src += `${info.plugin}: `;
+		}
+
+		if (info.stack) {
+			info[MESSAGE] = `[${info.level}]${src}${info.stack}`;
+		} else {
+			info[MESSAGE] = `[${info.level}]${src}${info.message}`;
+		}
+		return info;
+	}
+}
+
+const logger = winston.createLogger({
+	level: "verbose",
+	levels,
+	format: winston.format.timestamp(),
+});
+
+module.exports = {
+	ConsoleTransport,
+	WebConsoleFormat,
+	colors,
+	levels,
+	logger,
+};

packages/lib/logging_utils.js

@@ -0,0 +1,131 @@
+"use strict";
+const winston = require("winston");
+const Transport = require("winston-transport");
+const { LEVEL, MESSAGE } = require("triple-beam");
+const chalk = require("chalk");
+
+const libLink = require("@clusterio/lib/link");
+const libErrors = require("@clusterio/lib/errors");
+
+
+/**
+ * Format a parsed Factorio message with colors
+ *
+ * Formats a parsed Factorio output from lib/factorio into a readable
+ * colorized output using terminal escape codes that can be printed.
+ *
+ * @param {Object} parsed - Parsed Factorio server output.
+ * @returns {string} terminal colorized message.
+ * @private
+ */
+function formatServerOutput(parsed) {
+	let time = "";
+	if (parsed.format === "seconds") {
+		time = chalk.yellow(parsed.time.padStart(8)) + " ";
+	} else if (parsed.format === "date") {
+		time = chalk.yellow(parsed.time) + " ";
+	}
+
+	let info = "";
+	if (parsed.type === "log") {
+		let level = parsed.level;
+		if (level === "Script") {
+			level = chalk.bold.greenBright(level);
+		} else if (level === "Verbose") {
+			level = chalk.bold.gray(level);
+		} else if (level === "Info") {
+			level = chalk.bold.blueBright(level);
+		} else if (parsed.level === "Warning") {
+			level = chalk.bold.yellowBright(level);
+		} else if (parsed.level === "Error") {
+			level = chalk.bold.redBright(level);
+		}
+
+		info = level + " " + chalk.gray(parsed.file) + ": ";
+
+	} else if (parsed.type === "action") {
+		info = "[" + chalk.yellow(parsed.action) + "] ";
+	}
+
+	return time + info + parsed.message;
+}
+
+// These are defined here to avoid circular dependencies and pulling them
+// into the web interface code.
+
+/**
+ * Formats winston log messages for a character terminal.
+ */
+class TerminalFormat {
+	constructor(options = {}) {
+		this.options = options;
+		this.colorize = winston.format.colorize(options);
+	}
+
+	transform(info, options) {
+		info = this.colorize.transform(info, this.colorize.options);
+		let ts = "";
+		if (options.showTimestamp && info.timestamp) {
+			ts = `${info.timestamp.replace("T", " ")} `;
+		}
+
+		let src = " ";
+		if (info.instance_name) {
+			src += `i:${info.instance_name} `;
+
+		} else if (info.slave_name) {
+			src += `s:${info.slave_name} `;
+		}
+		if (info.plugin) {
+			src += `${info.plugin}: `;
+		}
+
+		if (info[LEVEL] === "server" && info.parsed) {
+			info.message = formatServerOutput(info.parsed);
+		}
+
+		if (info.stack) {
+			info[MESSAGE] = `${ts}[${info.level}]${src}${info.stack}`;
+		} else {
+			info[MESSAGE] = `${ts}[${info.level}]${src}${info.message}`;
+		}
+		return info;
+	}
+}
+
+/**
+ * Sends logs over a lib/link connection.
+ */
+class LinkTransport extends Transport {
+	constructor(options) {
+		super(options);
+
+		this.link = options.link;
+		this.filter = options.filter || null;
+	}
+
+	log(info, callback) {
+		if (this.filter && !this.filter(info)) {
+			return callback();
+		}
+
+		try {
+			libLink.messages.logMessage.send(this.link, { info });
+		} catch (err) {
+			// Ignore session lost errors.
+			if (!(err instanceof libErrors.SessionLost)) {
+				throw err;
+			}
+		}
+		return callback();
+	}
+}
+
+
+module.exports = {
+	TerminalFormat,
+	LinkTransport,
+
+	// for testing only
+	_formatServerOutput: formatServerOutput,
+};

packages/lib/package.json

@@ -1,7 +1,7 @@
 {
   "name": "@clusterio/lib",
   "description": "Shared library for Clusterio",
-  "version": "2.0.0-alpha.2",
+  "version": "2.0.0-alpha.3",
   "repository": "https://github.com/clusterio/factorioClusterio",
   "license": "MIT",
   "keywords": [
@@ -22,6 +22,9 @@
     "node-forge": "^0.10.0",
     "rcon-client": "^4.2.0",
     "semver": "^7.1.1",
+    "triple-beam": "^1.3.0",
+    "winston": "^3.3.3",
+    "winston-transport": "^4.4.0",
     "ws": "^7.2.3",
     "yargs": "^14.2.0"
   },

packages/lib/plugin.js

@@ -51,6 +51,15 @@ class BaseInstancePlugin {
 		 * @type {module:slave/slave~Slave}
 		 */
 		this.slave = slave;
+
+		/**
+		 * Logger for this plugin
+		 *
+		 * Instance of winston Logger for sending log messages from this
+		 * plugin.  Supported methods and their corresponding log levels are
+		 * `error`, `warn`, `audit`, `info` and `verbose`.
+		 */
+		this.logger = instance.logger.child({ plugin: this.info.name });
 	}
 
 	/**
@@ -117,23 +126,24 @@ class BaseInstancePlugin {
 	 * stderr.  The output is a parsed form of the line and contains the
 	 * following properties:
 	 *
-	 * @param {Object} output - parsed server output.
-	 * @param {string} output.source -
+	 * @param {Object} parsed - parsed server output.
+	 * @param {string} parsed.source -
 	 *     Where the message came from, one of "stdout" and "stderr".
-	 * @param {string} output.format -
+	 * @param {string} parsed.format -
 	 *     Timestamp format, one of "date", "seconds" and "none".
-	 * @param {string=} output.time -
+	 * @param {string=} parsed.time -
 	 *     Timestamp of the message.  Not present if format is "none".
-	 * @param {string} output.type -
+	 * @param {string} parsed.type -
 	 *     Type of message, one of "log", "action" and "generic".
-	 * @param {string=} output.level -
+	 * @param {string=} parsed.level -
 	 *     Log level for "log" type.  i.e "Info" normally.
-	 * @param {string=} output.file - File reported for "log" type.
-	 * @param {string=} output.action -
+	 * @param {string=} parsed.file - File reported for "log" type.
+	 * @param {string=} parsed.action -
 	 *     Kind of action for "action" type. i.e "CHAT" for chat.
-	 * @param {string} output.message - Main content of the line.
+	 * @param {string} parsed.message - Main content of the line.
+	 * @param {string} line - raw line of server output.
 	 */
-	async onOutput(output) { }
+	async onOutput(parsed, line) { }
 
 	/**
 	 * Called when an event on the master connection happens
@@ -192,6 +202,10 @@ class BaseInstancePlugin {
 	 * @param {string} event.name - Name of the player that joined/left.
 	 */
 	async onPlayerEvent(event) { }
+
+	async sendRcon(message, expectEmpty) {
+		return await this.instance.sendRcon(message, expectEmpty, this.info.name);
+	}
 }
 
 /**
@@ -206,10 +220,19 @@ class BaseInstancePlugin {
  * @static
  */
 class BaseMasterPlugin {
-	constructor(info, master, metrics) {
+	constructor(info, master, metrics, logger) {
 		this.info = info;
 		this.master = master;
 		this.metrics = metrics;
+
+		/**
+		 * Logger for this plugin
+		 *
+		 * Instance of winston Logger for sending log messages from this
+		 * plugin.  Supported methods and their corresponding log levels are
+		 * `error`, `warn`, `audit`, `info` and `verbose`.
+		 */
+		this.logger = logger.child({ plugin: this.info.name });
 	}
 
 	/**
@@ -358,11 +381,20 @@ class BaseMasterPlugin {
  * @static
  */
 class BaseControlPlugin {
-	constructor(info) {
+	constructor(info, logger) {
 		/**
 		 * The plugin's own info module
 		 */
 		this.info = info;
+
+		/**
+		 * Logger for this plugin
+		 *
+		 * Instance of winston Logger for sending log messages from this
+		 * plugin.  Supported methods and their corresponding log levels are
+		 * `error`, `warn`, `audit`, `info` and `verbose`.
+		 */
+		this.logger = logger.child({ plugin: this.info.name });
 	}
 
 	/**
@@ -402,13 +434,23 @@ function attachPluginMessages(link, pluginInfo, plugin) {
 		}
 
 		let handler = name + messageFormat.handlerSuffix;
-		if (plugin === null || !plugin[handler]) {
-			messageFormat.attach(link);
+		try {
+			if (plugin === null || !plugin[handler]) {
+				messageFormat.attach(link);
 
-		} else {
-			messageFormat.attach(link, async function(message, format) {
-				return await plugin[handler](message, format, this);
-			});
+			} else {
+				messageFormat.attach(link, async function(message, format) {
+					return await plugin[handler](message, format, this);
+				});
+			}
+
+		} catch (err) {
+			if (err.code === "MISSING_LINK_HANDLER") {
+				err.plugin = pluginInfo.name;
+				err.handler = handler;
+			}
+
+			throw err;
 		}
 	}
 }
@@ -431,7 +473,7 @@ async function invokeHook(plugins, hook, ...args) {
 				results.push(result);
 			}
 		} catch (err) {
-			console.error(`Ignoring error from plugin ${name} in ${hook}:`, err);
+			plugin.logger.error(`Ignoring error from plugin ${name} in ${hook}:\n${err.stack}`);
 		}
 	}
 	return results;

packages/lib/shared_commands.js

@@ -6,9 +6,15 @@
 const fs = require("fs-extra");
 const path = require("path");
 
-const libConfig = require("./config");
+const libConfig = require("@clusterio/lib/config");
+const { logger } = require("@clusterio/lib/logging");
 
 
+function print(...content) {
+	// eslint-disable-next-line no-console
+	console.log(...content);
+}
+
 /**
  * Yargs plugin command
  *
@@ -50,35 +56,34 @@ async function handlePluginCommand(args, pluginList, pluginListPath) {
 		try {
 			pluginInfo = require(path.posix.join(pluginPath, "info"));
 		} catch (err) {
-			console.error(`Unable to import plugin info from ${args.path}`);
-			console.error(err);
+			logger.error(`Unable to import plugin info from ${args.path}:\n${err.stack}`);
 			process.exitCode = 1;
 			return;
 		}
 
 		if (pluginList.has(pluginInfo.name)) {
-			console.error(`Plugin with the same ${pluginInfo.name} already exists`);
+			logger.error(`Plugin with the same ${pluginInfo.name} already exists`);
 			process.exitCode = 1;
 			return;
 		}
 
 		pluginList.set(pluginInfo.name, pluginPath);
 		await fs.outputFile(pluginListPath, JSON.stringify([...pluginList], null, 4));
-		console.log(`Added ${pluginInfo.name}`);
+		print(`Added ${pluginInfo.name}`);
 
 	} else if (command === "remove") {
 		if (!pluginList.delete(args.name)) {
-			console.error(`Plugin with name ${args.name} does not exist`);
+			logger.error(`Plugin with name ${args.name} does not exist`);
 			process.exitCode = 1;
 			return;
 		}
 
 		await fs.outputFile(pluginListPath, JSON.stringify([...pluginList], null, 4));
-		console.log(`Removed ${args.name}`);
+		print(`Removed ${args.name}`);
 
 	} else if (command === "list") {
 		for (let [pluginName, pluginPath] of pluginList) {
-			console.log(`${pluginName} - ${pluginPath}`);
+			print(`${pluginName} - ${pluginPath}`);
 		}
 	}
 }
@@ -119,16 +124,16 @@ async function handleConfigCommand(args, instance, configPath) {
 		for (let GroupClass of instance.constructor.groups.values()) {
 			for (let def of GroupClass.definitions.values()) {
 				let value = instance.get(def.fullName);
-				console.log(`${def.fullName} ${JSON.stringify(value)}`);
+				print(`${def.fullName} ${JSON.stringify(value)}`);
 			}
 		}
 
 	} else if (command === "show") {
 		try {
-			console.log(instance.get(args.field));
+			print(instance.get(args.field));
 		} catch (err) {
 			if (err instanceof libConfig.InvalidField) {
-				console.error(err.message);
+				logger.error(err.message);
 			} else {
 				throw err;
 			}
@@ -144,7 +149,7 @@ async function handleConfigCommand(args, instance, configPath) {
 			await fs.outputFile(configPath, JSON.stringify(instance.serialize(), null, 4));
 		} catch (err) {
 			if (err instanceof libConfig.InvalidField || err instanceof libConfig.InvalidValue) {
-				console.error(err.message);
+				logger.error(err.message);
 			} else {
 				throw err;
 			}

packages/lib/users.js

@@ -102,7 +102,7 @@ class Role {
 function ensureDefaultAdminRole(roles) {
 	let admin = roles.get(0);
 	if (!admin) {
-		admin = new Role({ id: 0, name: "Admin", description: "Cluster wide administrator." });
+		admin = new Role({ id: 0, name: "Cluster Admin", description: "Cluster wide administrator." });
 		roles.set(0, admin);
 	}
 	admin.permissions.add("core.admin");
@@ -345,11 +345,6 @@ definePermission({
 	title: "Assign instance",
 	description: "Assign or reassign instances to a slave.",
 });
-definePermission({
-	name: "core.instance.follow_log",
-	title: "Follow instance log",
-	description: "Listen for the stdout log of instances.",
-});
 definePermission({
 	name: "core.instance.create_save",
 	title: "Create new instance save",
@@ -450,6 +445,16 @@ definePermission({
 	title: "Delete user",
 	description: "Delete users and all data stored for them.",
 });
+definePermission({
+	name: "core.log.follow",
+	title: "Follow cluster log",
+	description: "Receive new entries in the cluster log.  Required to see instance console.",
+});
+definePermission({
+	name: "core.log.query",
+	title: "Query cluster log",
+	description: "Query past entries in the cluster log.  Required to see past entries in instance console.",
+});
 
 definePermission({
 	name: "core.debug.dump_ws",

packages/master/master.js

@@ -30,6 +30,7 @@ const WebSocket = require("ws");
 const JSZip = require("jszip");
 const version = require("./package").version;
 const util = require("util");
+const winston = require("winston");
 
 // ugly globals
 let masterConfig;
@@ -40,6 +41,11 @@ let stopAcceptingNewSessions = false;
 let debugEvents = new events.EventEmitter();
 let loadedPlugins = {};
 let devMiddleware;
+let clusterLogger;
+let db = {
+	instances: new Map(),
+	slaves: new Map(),
+};
 
 // homebrew modules
 const generateSslCert = require("./src/generate_ssl_cert");
@@ -54,6 +60,9 @@ const libPrometheus = require("@clusterio/lib/prometheus");
 const libConfig = require("@clusterio/lib/config");
 const libUsers = require("@clusterio/lib/users");
 const libSharedCommands = require("@clusterio/lib/shared_commands");
+const libHelpers = require("@clusterio/lib/helpers");
+const { ConsoleTransport, levels, logger } = require("@clusterio/lib/logging");
+const libLoggingUtils = require("@clusterio/lib/logging_utils");
 
 const express = require("express");
 const compression = require("compression");
@@ -61,9 +70,9 @@ const cookieParser = require("cookie-parser");
 // Required for express post requests
 const bodyParser = require("body-parser");
 const fileUpload = require("express-fileupload");
-var app = express();
-var httpServer;
-var httpsServer;
+const app = express();
+let httpServer;
+let httpsServer;
 
 app.use(cookieParser());
 app.use(bodyParser.json({
@@ -101,6 +110,41 @@ function serveWeb(route) {
 app.use(express.static(path.join(__dirname, "static")));
 app.use(express.static("static")); // Used for data export files
 
+const slaveMappingGauge = new libPrometheus.Gauge(
+	"clusterio_master_slave_mapping",
+	"Mapping of Slave ID to name",
+	{
+		labels: ["slave_id", "slave_name"],
+		callback: function() {
+			slaveMappingGauge.clear();
+			for (let [id, slave] of db.slaves) {
+				slaveMappingGauge.labels({
+					slave_id: String(id),
+					slave_name: slave.name,
+				}).set(1);
+			};
+		},
+	}
+);
+
+const instanceMappingGauge = new libPrometheus.Gauge(
+	"clusterio_master_instance_mapping",
+	"Mapping of Instance ID to name and slave",
+	{
+		labels: ["instance_id", "instance_name", "slave_id"],
+		callback: function() {
+			instanceMappingGauge.clear();
+			for (let [id, instance] of db.instances) {
+				instanceMappingGauge.labels({
+					instance_id: String(id),
+					instance_name: String(instance.config.get("instance.name")),
+					slave_id: String(instance.config.get("instance.assigned_slave")),
+				}).set(1);
+			}
+		},
+	}
+);
+
 const endpointHitCounter = new libPrometheus.Counter(
 	"clusterio_master_http_endpoint_hits_total",
 	"How many requests a particular HTTP endpoint has gotten",
@@ -147,8 +191,7 @@ async function getMetrics(req, res, next) {
 
 	let requests = [];
 	for (let slaveConnection of slaveConnections.values()) {
-		// XXX this needs a timeout
-		requests.push(libLink.messages.getMetrics.send(slaveConnection));
+		requests.push(libHelpers.timeout(libLink.messages.getMetrics.send(slaveConnection), 8e3, null));
 	}
 
 	for await (let result of await libPrometheus.defaultRegistry.collect()) {
@@ -157,14 +200,28 @@ async function getMetrics(req, res, next) {
 
 	let resultMap = new Map();
 	for (let response of await Promise.all(requests)) {
+		if (!response) {
+			// TODO: Log timeout occured?
+			continue;
+		}
+
 		for (let result of response.results) {
 			if (!resultMap.has(result.metric.name)) {
 				resultMap.set(result.metric.name, result);
 
 			} else {
 				// Merge metrics received by multiple slaves
-				let stored = resultMap.get(result.metric.name);
-				stored.samples.push(...result.samples);
+				let receivedSamples = new Map(result.samples);
+				for (let [suffix, suffixSamples] of resultMap.get(result.metric.name).samples) {
+					if (receivedSamples.has(suffix)) {
+						suffixSamples.push(...receivedSamples.get(suffix));
+						receivedSamples.delete(suffix);
+					}
+				}
+
+				for (let entry of receivedSamples) {
+					result.samples.push(entry);
+				}
 			}
 		}
 	}
@@ -262,9 +319,6 @@ const masterConnectedClientsCount = new libPrometheus.Gauge(
 	},
 );
 
-// set up database
-const db = {};
-
 /**
  * Load Map from JSON file in the database directory.
  *
@@ -274,13 +328,13 @@ const db = {};
  */
 async function loadMap(databaseDirectory, file) {
 	let databasePath = path.resolve(databaseDirectory, file);
-	console.log(`Loading ${databasePath}`);
+	logger.info(`Loading ${databasePath}`);
 	return await libDatabase.loadJsonArrayAsMap(databasePath);
 }
 
 async function loadInstances(databaseDirectory, file) {
 	let filePath = path.join(databaseDirectory, file);
-	console.log(`Loading ${filePath}`);
+	logger.info(`Loading ${filePath}`);
 
 	let instances = new Map();
 	try {
@@ -358,7 +412,7 @@ function createUser(name) {
  */
 async function saveMap(databaseDirectory, file, map) {
 	let databasePath = path.resolve(databaseDirectory, file);
-	console.log(`Saving ${databasePath}`);
+	logger.info(`Saving ${databasePath}`);
 	await libDatabase.saveMapAsJsonArray(databasePath, map);
 }
 
@@ -395,10 +449,10 @@ async function saveUsers(databaseDirectory, file) {
  * Innitiate shutdown of master server
  */
 async function shutdown() {
-	console.log("Shutting down");
+	logger.info("Shutting down");
 	let exitStartTime = Date.now();
 	try {
-		console.log("Saving configs");
+		logger.info("Saving configs");
 		await fs.outputFile(masterConfigPath, JSON.stringify(masterConfig.serialize(), null, 4));
 
 		await saveMap(masterConfig.get("master.database_directory"), "slaves.json", db.slaves);
@@ -424,14 +478,13 @@ async function shutdown() {
 			disconnectTasks.push(slaveConnection.disconnect(1001, "Server Quit"));
 		}
 
-		console.log(`Waiting for ${disconnectTasks.length} connectors to close`);
+		logger.info(`Waiting for ${disconnectTasks.length} connectors to close`);
 		for (let task of disconnectTasks) {
 			try {
 				await task;
 			} catch (err) {
 				if (!(err instanceof libErrors.SessionLost)) {
-					console.log("Unexpected error disconnecting connector");
-					console.log(err);
+					logger.warn(`Unexpected error disconnecting connector:\n${err.stack}`);
 				}
 			}
 		}
@@ -441,22 +494,22 @@ async function shutdown() {
 		}
 
 		let stopTasks = [];
-		console.log("Stopping HTTP(S) server");
+		logger.info("Stopping HTTP(S) server");
 		if (httpServer) { stopTasks.push(new Promise(resolve => httpServer.close(resolve))); }
 		if (httpsServer) { stopTasks.push(new Promise(resolve => httpsServer.close(resolve))); }
 		await Promise.all(stopTasks);
 
-		console.log(`Clusterio cleanly exited in ${Date.now() - exitStartTime}ms`);
+		logger.info(`Clusterio cleanly exited in ${Date.now() - exitStartTime}ms`);
 
 	} catch(err) {
 		setBlocking(true);
-		console.error(`
+		logger.fatal(`
 +--------------------------------------------------------------------+
 | Unexpected error occured while shutting down master, please report |
 | it to https://github.com/clusterio/factorioClusterio/issues        |
-+--------------------------------------------------------------------+`
++--------------------------------------------------------------------+
+${err.stack}`
 		);
-		console.error(err);
 		process.exit(1);
 	}
 }
@@ -537,8 +590,7 @@ class BaseConnection extends libLink.Link {
 			await libLink.messages.prepareDisconnect.send(this);
 		} catch (err) {
 			if (!(err instanceof libErrors.SessionLost)) {
-				console.error("Unexpected error preparing disconnect");
-				console.error(err);
+				logger.error(`"Unexpected error preparing disconnect:\n${err.stack}`);
 			}
 		}
 
@@ -546,6 +598,11 @@ class BaseConnection extends libLink.Link {
 	}
 }
 
+const lastQueryLogTime = new libPrometheus.Gauge(
+	"clusterio_master_last_query_log_duration_seconds",
+	"Time in seconds the last log query took to execute."
+);
+
 let controlConnections = [];
 class ControlConnection extends BaseConnection {
 	constructor(registerData, connector, user) {
@@ -567,13 +624,23 @@ class ControlConnection extends BaseConnection {
 			}
 		});
 
-		this.instanceOutputSubscriptions = new Set();
+		this.logTransport = null;
+		this.logSubscriptions = {
+			all: false,
+			master: false,
+			slave_ids: [],
+			instance_ids: [],
+		};
 
 		this.ws_dumper = null;
 		this.connector.on("connect", () => {
 			this.connector._socket.clusterio_ignore_dump = Boolean(this.ws_dumper);
 		});
 		this.connector.on("close", () => {
+			if (this.logTransport) {
+				this.logTransport = null;
+				logger.remove(this.logTransport);
+			}
 			if (this.ws_dumper) {
 				debugEvents.off("message", this.ws_dumper);
 			}
@@ -712,33 +779,116 @@ class ControlConnection extends BaseConnection {
 	}
 
 	async assignInstanceCommandRequestHandler(message, request) {
-		let instance = db.instances.get(message.data.instance_id);
+		let { slave_id, instance_id } = message.data;
+		let instance = db.instances.get(instance_id);
 		if (!instance) {
-			throw new libErrors.RequestError(`Instance with ID ${message.data.instance_id} does not exist`);
+			throw new libErrors.RequestError(`Instance with ID ${instance_id} does not exist`);
 		}
 
-		// XXX: Should the instance be stopped if it's running on another slave?
-
-		let connection = slaveConnections.get(message.data.slave_id);
-		if (!connection) {
-			// The case of the slave not getting the assign instance message
-			// still have to be handled, so it's not a requirement that the
-			// target slave be connected to the master while doing the
-			// assignment, but it is IMHO a better user experience if this
-			// is the case.
-			throw new libErrors.RequestError("Target slave is not connected to the master server");
+		// Check if target slave is connected
+		let newSlaveConnection;
+		if (slave_id !== null) {
+			newSlaveConnection = slaveConnections.get(slave_id);
+			if (!newSlaveConnection) {
+				// The case of the slave not getting the assign instance message
+				// still have to be handled, so it's not a requirement that the
+				// target slave be connected to the master while doing the
+				// assignment, but it is IMHO a better user experience if this
+				// is the case.
+				throw new libErrors.RequestError("Target slave is not connected to the master server");
+			}
 		}
 
-		instance.config.set("instance.assigned_slave", message.data.slave_id);
+		// Unassign from currently assigned slave if it is connected.
+		let currentAssignedSlave = instance.config.get("instance.assigned_slave");
+		if (currentAssignedSlave !== null && slave_id !== currentAssignedSlave) {
+			let oldSlaveConnection = slaveConnections.get(currentAssignedSlave);
+			if (oldSlaveConnection && !oldSlaveConnection.connector.closing) {
+				await libLink.messages.unassignInstance.send(oldSlaveConnection, { instance_id });
+			}
+		}
 
-		return await libLink.messages.assignInstance.send(connection, {
-			instance_id: instance.config.get("instance.id"),
-			serialized_config: instance.config.serialize(),
-		});
+		// Assign to target
+		instance.config.set("instance.assigned_slave", slave_id);
+		if (slave_id !== null) {
+			await libLink.messages.assignInstance.send(newSlaveConnection, {
+				instance_id,
+				serialized_config: instance.config.serialize(),
+			});
+		}
 	}
 
-	async setInstanceOutputSubscriptionsRequestHandler(message) {
-		this.instanceOutputSubscriptions = new Set(message.data.instance_ids);
+	async setLogSubscriptionsRequestHandler(message) {
+		this.logSubscriptions = message.data;
+		this.updateLogSubscriptions();
+	}
+
+	static logFilter({ all, master, slave_ids, instance_ids, max_level }) {
+		return info => {
+			// Note: reversed to filter out undefined levels
+			if (max_level && !(levels[info.level] <= levels[max_level])) {
+				return false;
+			}
+
+			if (all) {
+				return true;
+			}
+			if (master && info.slave_id === undefined) {
+				return true;
+			}
+			if (info.slave_id && slave_ids.includes(info.slave_id)) {
+				return true;
+			}
+			if (info.instance_id && instance_ids.includes(info.instance_id)) {
+				return true;
+			}
+			return false;
+		};
+	}
+
+	updateLogSubscriptions() {
+		let { all, master, slave_ids, instance_ids } = this.logSubscriptions;
+		if (all || master || slave_ids.length || instance_ids.length) {
+			if (!this.logTransport) {
+				this.logTransport = new libLoggingUtils.LinkTransport({ link: this });
+				clusterLogger.add(this.logTransport);
+			}
+			this.logTransport.filter = this.constructor.logFilter(this.logSubscriptions);
+
+		} else if (this.logTransport) {
+			clusterLogger.remove(this.logTransport);
+			this.logTransport = null;
+		}
+	}
+
+	async queryLogRequestHandler(message) {
+		let transport = new winston.transports.File({ filename: "cluster.log" });
+		let query = util.promisify((options, callback) => transport.query(options, callback));
+
+		// Available options and defaults inferred from reading the source
+		// rows: number = limit || 10
+		// limit: number // alias of rows.
+		// start: number = 0
+		// until: Date = now
+		// from: Date = until - 24h
+		// order: "asc"|"desc" = "desc"
+		// fields: Array<string>
+		// level: string
+		// This interface is junk:
+		// - The level option filters by exact match
+		// - No way to add your own filter
+		// - No way to stream results
+		// - The log file is read starting from the beginning
+		let setDuration = lastQueryLogTime.startTimer();
+		let log = await query({
+			order: "asc",
+			limit: Infinity,
+			from: new Date(0),
+		});
+
+		log = log.filter(this.constructor.logFilter(message.data));
+		setDuration();
+		return { log };
 	}
 
 	async listPermissionsRequestHandler(message) {
@@ -925,7 +1075,7 @@ class ControlConnection extends BaseConnection {
 	}
 }
 
-var slaveConnections = new Map();
+let slaveConnections = new Map();
 /**
  * Represents the connection to a slave
  *
@@ -967,13 +1117,23 @@ class SlaveConnection extends BaseConnection {
 
 	async instanceStatusChangedEventHandler(message, event) {
 		let instance = db.instances.get(message.data.instance_id);
+
+		// It's possible to get updates from an instance that does not exist
+		// or is not assigned to the slave it originated from if it was
+		// reassigned or deleted while the connection to the slave it was
+		// originally on was down at the time.
+		if (!instance || instance.config.get("instance.assigned_slave") !== this._id) {
+			logger.warn(`Got bogus update for instance id ${message.data.instance_id}`);
+			return;
+		}
+
 		let prev = instance.status;
 		instance.status = message.data.status;
-		console.log(`Clusterio | Instance ${instance.config.get("instance.name")} State: ${instance.status}`);
+		logger.verbose(`Instance ${instance.config.get("instance.name")} State: ${instance.status}`);
 		await libPlugin.invokeHook(masterPlugins, "onInstanceStatusChanged", instance, prev);
 	}
 
-	async updateInstancesEventHandler(message) {
+	async updateInstancesRequestHandler(message) {
 		// Push updated instance configs
 		for (let instance of db.instances.values()) {
 			if (instance.config.get("instance.assigned_slave") === this._id) {
@@ -991,10 +1151,19 @@ class SlaveConnection extends BaseConnection {
 
 			let masterInstance = db.instances.get(instanceConfig.get("instance.id"));
 			if (masterInstance) {
+				// Check if this instance is assigned somewhere else.
+				if (masterInstance.config.get("instance.assigned_slave") !== this._id) {
+					await libLink.messages.unassignInstance.send(this, {
+						instance_id: masterInstance.config.get("instance.id"),
+					});
+					continue;
+				}
+
 				// Already have this instance, update state instead
 				if (masterInstance.status !== instance.status) {
 					let prev = masterInstance.status;
 					masterInstance.status = instance.status;
+					logger.verbose(`Instance ${instanceConfig.get("instance.name")} State: ${instance.status}`);
 					await libPlugin.invokeHook(masterPlugins, "onInstanceStatusChanged", instance, prev);
 				}
 				continue;
@@ -1031,13 +1200,12 @@ class SlaveConnection extends BaseConnection {
 		libLink.messages.syncUserLists.send(this, { adminlist, banlist, whitelist });
 	}
 
-	async instanceOutputEventHandler(message) {
-		let { instance_id, output } = message.data;
-		for (let controlConnection of controlConnections) {
-			if (controlConnection.instanceOutputSubscriptions.has(instance_id)) {
-				libLink.messages.instanceOutput.send(controlConnection, message.data);
-			}
-		}
+	async logMessageEventHandler(message) {
+		clusterLogger.log({
+			...message.data.info,
+			slave_id: this._id,
+			slave_name: this._name,
+		});
 	}
 
 	async playerEventEventHandler(message) {
@@ -1179,7 +1347,7 @@ class WebSocketServerConnector extends libLink.WebSocketBaseConnector {
 	}
 
 	_timedOut() {
-		console.log("SOCKET | Connection timed out");
+		logger.verbose("SOCKET | Connection timed out");
 		this._timeoutId = null;
 		this._lastReceivedSeq = null;
 		this._sendBuffer.length = 0;
@@ -1193,7 +1361,7 @@ class WebSocketServerConnector extends libLink.WebSocketBaseConnector {
 		this.startHeartbeat();
 
 		this._socket.on("close", (code, reason) => {
-			console.log(`SOCKET | Close (code: ${code}, reason: ${reason})`);
+			logger.verbose(`SOCKET | Close (code: ${code}, reason: ${reason})`);
 			if (this._state === "closing") {
 				this._lastReceivedSeq = null;
 				this._sendBuffer.length = 0;
@@ -1221,17 +1389,17 @@ class WebSocketServerConnector extends libLink.WebSocketBaseConnector {
 
 		this._socket.on("error", err => {
 			// It's assumed that close is always called by ws
-			console.error("SOCKET | Error:", err);
+			logger.verbose("SOCKET | Error:", err);
 		});
 
 		this._socket.on("open", () => {
-			console.log("SOCKET | Open");
+			logger.verbose("SOCKET | Open");
 		});
 		this._socket.on("ping", data => {
-			console.log(`SOCKET | Ping (data: ${data}`);
+			logger.verbose(`SOCKET | Ping (data: ${data}`);
 		});
 		this._socket.on("pong", data => {
-			console.log(`SOCKET | Pong (data: ${data}`);
+			logger.verbose(`SOCKET | Pong (data: ${data}`);
 		});
 
 		// Handle messages
@@ -1279,7 +1447,7 @@ let pendingSockets = new Set();
 let activeConnectors = new Map();
 
 wss.on("connection", function (socket, req) {
-	console.log(`SOCKET | new connection from ${req.socket.remoteAddress}`);
+	logger.verbose(`SOCKET | new connection from ${req.socket.remoteAddress}`);
 
 	// Track statistics
 	wsConnectionsCounter.inc();
@@ -1308,7 +1476,7 @@ wss.on("connection", function (socket, req) {
 		pendingSockets.add(socket);
 
 		let timeoutId = setTimeout(() => {
-			console.log(`SOCKET | closing ${req.socket.remoteAddress} after timing out on handshake`);
+			logger.verbose(`SOCKET | closing ${req.socket.remoteAddress} after timing out on handshake`);
 			wsRejectedConnectionsCounter.inc();
 			socket.close(1008, "Handshake timeout");
 			pendingSockets.delete(socket);
@@ -1320,13 +1488,13 @@ wss.on("connection", function (socket, req) {
 			handleHandshake(
 				message, socket, req, attachHandler
 			).catch(err => {
-				console.error(`
+				logger.error(`
 +----------------------------------------------------------------+
 | Unexpected error occured in WebSocket handshake, please report |
 | it to https://github.com/clusterio/factorioClusterio/issues    |
-+----------------------------------------------------------------+`
++----------------------------------------------------------------+
+${err.stack}`
 				);
-				console.error(err);
 				wsRejectedConnectionsCounter.inc();
 				socket.close(1011, "Unexpected error");
 			});
@@ -1346,14 +1514,14 @@ async function handleHandshake(message, socket, req, attachHandler) {
 	try {
 		message = JSON.parse(message);
 	} catch (err) {
-		console.log(`SOCKET | closing ${req.socket.remoteAddress} after receiving invalid JSON`);
+		logger.verbose(`SOCKET | closing ${req.socket.remoteAddress} after receiving invalid JSON`);
 		wsRejectedConnectionsCounter.inc();
 		socket.close(1002, "Invalid JSON");
 		return;
 	}
 
 	if (!libSchema.clientHandshake(message)) {
-		console.log(`SOCKET | closing ${req.socket.remoteAddress} after receiving invalid handshake:`, message);
+		logger.verbose(`SOCKET | closing ${req.socket.remoteAddress} after receiving invalid handshake`);
 		wsRejectedConnectionsCounter.inc();
 		socket.close(1002, "Bad handshake");
 		return;
@@ -1386,7 +1554,7 @@ async function handleHandshake(message, socket, req, attachHandler) {
 	}
 
 	if (stopAcceptingNewSessions) {
-		console.log(`SOCKET | closing ${req.socket.remoteAddress}, server is shutting down`);
+		logger.verbose(`SOCKET | closing ${req.socket.remoteAddress}, server is shutting down`);
 		wsRejectedConnectionsCounter.inc();
 		socket.close(1001, "Shutting down");
 		return;
@@ -1424,7 +1592,7 @@ async function handleHandshake(message, socket, req, attachHandler) {
 		}
 
 	} catch (err) {
-		console.error(`SOCKET | authentication failed for ${req.socket.remoteAddress}`);
+		logger.verbose(`SOCKET | authentication failed for ${req.socket.remoteAddress}`);
 		wsRejectedConnectionsCounter.inc();
 		socket.close(4003, `Authentication failed: ${err.message}`);
 		return;
@@ -1439,16 +1607,16 @@ async function handleHandshake(message, socket, req, attachHandler) {
 	if (type === "register_slave") {
 		let connection = slaveConnections.get(data.id);
 		if (connection) {
-			console.log(`SOCKET | disconnecting existing connection for slave ${data.id}`);
+			logger.verbose(`SOCKET | disconnecting existing connection for slave ${data.id}`);
 			connection.connector.setTimeout(15); // Slave connection is likely stalled
 			await connection.disconnect(1008, "Registered from another connection");
 		}
 
-		console.log(`SOCKET | registered slave ${data.id} version ${data.version}`);
+		logger.verbose(`SOCKET | registered slave ${data.id} version ${data.version}`);
 		slaveConnections.set(data.id, new SlaveConnection(data, connector));
 
 	} else if (type === "register_control") {
-		console.log(`SOCKET | registered control from ${req.socket.remoteAddress}`);
+		logger.verbose(`SOCKET | registered control from ${req.socket.remoteAddress}`);
 		controlConnections.push(new ControlConnection(data, connector, user));
 	}
 
@@ -1459,7 +1627,7 @@ async function handleHandshake(message, socket, req, attachHandler) {
 async function pluginManagement() {
 	let startPluginLoad = Date.now();
 	masterPlugins = await loadPlugins();
-	console.log("All plugins loaded in "+(Date.now() - startPluginLoad)+"ms");
+	logger.info(`All plugins loaded in ${Date.now() - startPluginLoad}ms`);
 }
 
 async function loadPlugins() {
@@ -1479,7 +1647,7 @@ async function loadPlugins() {
 			}
 
 			let masterPlugin = new MasterPlugin(
-				pluginInfo, { app, config: masterConfig, db, slaveConnections }, { endpointHitCounter }
+				pluginInfo, { app, config: masterConfig, db, slaveConnections }, { endpointHitCounter }, logger
 			);
 			await masterPlugin.init();
 			plugins.set(pluginInfo.name, masterPlugin);
@@ -1488,7 +1656,7 @@ async function loadPlugins() {
 			throw new libErrors.PluginError(pluginInfo.name, err);
 		}
 
-		console.log(`Clusterio | Loaded plugin ${pluginInfo.name} in ${Date.now() - pluginLoadStarted}ms`);
+		logger.info(`Loaded plugin ${pluginInfo.name} in ${Date.now() - pluginLoadStarted}ms`);
 	}
 	return plugins;
 }
@@ -1505,7 +1673,7 @@ async function loadPlugins() {
 function listen(server, ...args) {
 	return new Promise((resolve, reject) => {
 		server.on("upgrade", (req, socket, head) => {
-			console.log("handling upgrade");
+			logger.verbose("handling WebSocket upgrade");
 
 			// For reasons that defy common sense, the connection event has
 			// to be emitted explictly when using noServer.
@@ -1554,13 +1722,17 @@ async function startServer() {
 	// and as the process name in ps/top on linux.
 	process.title = "clusterioMaster";
 
-	// add better stack traces on promise rejection
-	process.on("unhandledRejection", r => console.log(r));
-
 	// argument parsing
 	let args = yargs
 		.scriptName("master")
 		.usage("$0 <command> [options]")
+		.option("log-level", {
+			nargs: 1,
+			describe: "Log level to print to stdout",
+			default: "info",
+			choices: ["none"].concat(Object.keys(levels)),
+			type: "string",
+		})
 		.option("config", {
 			nargs: 1,
 			describe: "master config file to use",
@@ -1595,7 +1767,35 @@ async function startServer() {
 		.argv
 	;
 
-	console.log(`Loading available plugins from ${args.pluginList}`);
+	// Combined log stream of the whole cluster.
+	clusterLogger = winston.createLogger({
+		format: winston.format.json(),
+		level: "verbose",
+		levels,
+	});
+	clusterLogger.add(new winston.transports.File({
+		filename: "cluster.log",
+	}));
+
+	// Log stream for the master server.
+	logger.add(new winston.transports.File({
+		format: winston.format.json(),
+		filename: "master.log",
+	}));
+	logger.add(new winston.transports.Stream({
+		stream: clusterLogger,
+	}));
+	if (args.logLevel !== "none") {
+		logger.add(new ConsoleTransport({
+			level: args.logLevel,
+			format: new libLoggingUtils.TerminalFormat(),
+		}));
+	}
+
+	// add better stack traces on promise rejection
+	process.on("unhandledRejection", err => logger.error(`Unhandled rejection:\n${err.stack}`));
+
+	logger.info(`Loading available plugins from ${args.pluginList}`);
 	let pluginList = new Map();
 	try {
 		pluginList = new Map(JSON.parse(await fs.readFile(args.pluginList)));
@@ -1612,20 +1812,20 @@ async function startServer() {
 		return;
 	}
 
-	console.log("Loading Plugin info");
+	logger.info("Loading Plugin info");
 	pluginInfos = await libPluginLoader.loadPluginInfos(pluginList);
 	libConfig.registerPluginConfigGroups(pluginInfos);
 	libConfig.finalizeConfigs();
 
 	masterConfigPath = args.config;
-	console.log(`Loading config from ${masterConfigPath}`);
+	logger.info(`Loading config from ${masterConfigPath}`);
 	masterConfig = new libConfig.MasterConfig();
 	try {
 		await masterConfig.load(JSON.parse(await fs.readFile(masterConfigPath)));
 
 	} catch (err) {
 		if (err.code === "ENOENT") {
-			console.log("Config not found, initializing new config");
+			logger.info("Config not found, initializing new config");
 			await masterConfig.init();
 
 		} else {
@@ -1634,7 +1834,7 @@ async function startServer() {
 	}
 
 	if (!masterConfig.get("master.auth_secret")) {
-		console.log("Generating new master authentication secret");
+		logger.info("Generating new master authentication secret");
 		let asyncRandomBytes = util.promisify(crypto.randomBytes);
 		let bytes = await asyncRandomBytes(256);
 		masterConfig.set("master.auth_secret", bytes.toString("base64"));
@@ -1650,7 +1850,7 @@ async function startServer() {
 		await loadUsers(masterConfig.get("master.database_directory"), "users.json");
 		if (subCommand === "create-admin") {
 			if (!args.name) {
-				console.error("name cannot be blank");
+				logger.error("name cannot be blank");
 				process.exitCode = 1;
 				return;
 			}
@@ -1668,16 +1868,17 @@ async function startServer() {
 		} else if (subCommand === "generate-user-token") {
 			let user = db.users.get(args.name);
 			if (!user) {
-				console.error(`No user named '${args.name}'`);
+				logger.error(`No user named '${args.name}'`);
 				process.exitCode = 1;
 				return;
 			}
+			// eslint-disable-next-line no-console
 			console.log(user.createToken(masterConfig.get("master.auth_secret")));
 
 		} else if (subCommand === "create-ctl-config") {
 			let admin = db.users.get(args.name);
 			if (!admin) {
-				console.error(`No user named '${args.name}'`);
+				logger.error(`No user named '${args.name}'`);
 				process.exitCode = 1;
 				return;
 			}
@@ -1689,9 +1890,10 @@ async function startServer() {
 
 			let content = JSON.stringify(controlConfig.serialize(), null, 4);
 			if (args.output === "-") {
+				// eslint-disable-next-line no-console
 				console.log(content);
 			} else {
-				console.log(`Writing ${args.output}`);
+				logger.info(`Writing ${args.output}`);
 				await fs.outputFile(args.output, content);
 			}
 		}
@@ -1703,7 +1905,7 @@ async function startServer() {
 
 	// Start webpack development server if enabled
 	if (args.dev) {
-		console.log("Webpack development mode enabled");
+		logger.warn("Webpack development mode enabled");
 		const webpack = require("webpack");
 		const webpackDevMiddleware = require("webpack-dev-middleware");
 		const webpackConfig = require("./webpack.config");
@@ -1716,12 +1918,12 @@ async function startServer() {
 	let secondSigint = false;
 	process.on("SIGINT", () => {
 		if (secondSigint) {
-			console.log("Caught second interrupt, terminating immediately");
+			logger.fatal("Caught second interrupt, terminating immediately");
 			process.exit(1);
 		}
 
 		secondSigint = true;
-		console.log("Caught interrupt signal, shutting down");
+		logger.info("Caught interrupt signal, shutting down");
 		shutdown();
 	});
 
@@ -1742,7 +1944,7 @@ async function startServer() {
 	let httpPort = masterConfig.get("master.http_port");
 	let httpsPort = masterConfig.get("master.https_port");
 	if (!httpPort && !httpsPort) {
-		console.error("Error: at least one of http_port and https_port must be configured");
+		logger.fatal("Error: at least one of http_port and https_port must be configured");
 		process.exit(1);
 	}
 
@@ -1769,7 +1971,6 @@ async function startServer() {
 
 		let pluginPackagePath = require.resolve(path.posix.join(pluginInfo.requirePath, "package.json"));
 		let staticPath = path.join(path.dirname(pluginPackagePath), "static");
-		console.log(`/plugin/${pluginInfo.name}`, staticPath);
 		app.use(`/plugin/${pluginInfo.name}`, express.static(staticPath));
 	}
 
@@ -1780,7 +1981,7 @@ async function startServer() {
 	if (httpPort) {
 		httpServer = new (require("http").Server)(app);
 		await listen(httpServer, httpPort);
-		console.log("Listening for HTTP on port %s...", httpServer.address().port);
+		logger.info(`Listening for HTTP on port ${httpServer.address().port}`);
 	}
 
 	if (httpsPort) {
@@ -1800,7 +2001,7 @@ async function startServer() {
 			cert: certificate,
 		}, app);
 		await listen(httpsServer, httpsPort);
-		console.log("Listening for HTTPS on port %s...", httpsServer.address().port);
+		logger.info(`Listening for HTTPS on port ${httpsServer.address().port}`);
 	}
 }
 
@@ -1818,6 +2019,7 @@ module.exports = {
 };
 
 if (module === require.main) {
+	// eslint-disable-next-line no-console
 	console.warn(`
 +==========================================================+
 I WARNING:  This is the development branch for the 2.0     I
@@ -1827,28 +2029,31 @@ I           version of clusterio.  Expect things to break. I
 	);
 	startServer().catch(err => {
 		if (err instanceof libErrors.StartupError) {
-			console.error(`
+			logger.fatal(`
 +----------------------------------+
 | Unable to to start master server |
-+----------------------------------+`
++----------------------------------+
+${err.stack}`
 			);
 		} else if (err instanceof libErrors.PluginError) {
-			console.error(`
-Error: ${err.pluginName} plugin threw an unexpected error
-       during startup, please report it to the plugin author.
---------------------------------------------------------------`
+			logger.fatal(`
+${err.pluginName} plugin threw an unexpected error
+during startup, please report it to the plugin author.
+------------------------------------------------------
+${err.original.stack}`
 			);
-			err = err.original;
 		} else {
-			console.error(`
+			logger.fatal(`
 +---------------------------------------------------------------+
 | Unexpected error occured while starting master, please report |
 | it to https://github.com/clusterio/factorioClusterio/issues   |
-+---------------------------------------------------------------+`
++---------------------------------------------------------------+
+${err.stack}`
 			);
 		}
 
-		console.error(err);
-		return shutdown();
+		if (masterConfig) {
+			shutdown();
+		}
 	});
 }

packages/master/package.json

@@ -3,7 +3,7 @@
   "description": "Implementation of Clusterio master server",
   "author": "Hornwitser",
   "license": "MIT",
-  "version": "2.0.0-alpha.2",
+  "version": "2.0.0-alpha.3",
   "main": "master.js",
   "scripts": {
     "build": "webpack-cli --env.production",
@@ -19,7 +19,7 @@
     "node": ">=10.16 <11 || >= 12"
   },
   "dependencies": {
-    "@clusterio/lib": "^2.0.0-alpha.2",
+    "@clusterio/lib": "^2.0.0-alpha.3",
     "body-parser": "^1.18.2",
     "compression": "^1.7.2",
     "cookie-parser": "^1.4.3",
@@ -31,11 +31,12 @@
     "node-factorio-api": "^0.3.8",
     "node-forge": "^0.10.0",
     "set-blocking": "^2.0.0",
+    "winston": "^3.3.3",
     "ws": "^7.2.3",
     "yargs": "^14.2.0"
   },
   "devDependencies": {
-    "@clusterio/web_ui": "^2.0.0-alpha.2",
+    "@clusterio/web_ui": "^2.0.0-alpha.3",
     "babel-loader": "^8.1.0",
     "css-loader": "^4.3.0",
     "fast-deep-equal": "^3.1.3",

packages/master/src/generate_ssl_cert.js

@@ -3,6 +3,8 @@ const forge = require("node-forge");
 const fs = require("fs-extra");
 const util = require("util");
 
+const { logger } = require("@clusterio/lib/logging");
+
 const hrtime = process.hrtime.bigint;
 
 
@@ -10,16 +12,12 @@ module.exports = async function({
 	bits = 2048,
 	sslCertPath,
 	sslPrivKeyPath,
-	doLogging = false,
 } = {}){
-	function log(t) {
-		if(doLogging) console.log("src/generate_ssl_cert.js | "+t);
-	}
-	log("Generating SSL certificate with "+bits+" bits at "+sslCertPath);
+	logger.info(`Generating SSL certificate with ${bits} bits at ${sslCertPath}`);
 
 	let startNs = hrtime();
 	let keypair = await util.promisify(forge.pki.rsa.generateKeyPair)({ bits: bits, e: 0x10001 });
-	log("Generated 2048bit keypair in: "+(Number(hrtime()-startNs) / 1e6)+" ms");
+	logger.info(`Generated ${bits}bit keypair in: ${Number(hrtime()-startNs) / 1e6} ms`);
 
 	startNs = hrtime();
 	let cert = forge.pki.createCertificate();
@@ -41,5 +39,5 @@ module.exports = async function({
 	await fs.outputFile(sslPrivKeyPath, forge.pki.privateKeyToPem(keypair.privateKey));
 	await fs.outputFile(sslCertPath, forge.pki.certificateToPem(cert));
 
-	log("Generated certificate in: "+(Number(hrtime()-startNs) / 1e6)+" ms");
+	logger.info(`Generated certificate in: ${Number(hrtime()-startNs) / 1e6} ms`);
 };

packages/slave/lua/clusterio_lib/changelog.txt

@@ -1,4 +1,8 @@
 ---------------------------------------------------------------------------------------------------
+Version: 0.1.2
+  Features:
+    - Added support for Factorio 1.1.
+---------------------------------------------------------------------------------------------------
 Version: 0.1.1
   Features:
     - Added support for Factorio 0.18.x

packages/slave/lua/clusterio_lib/info.json

@@ -1,12 +1,24 @@
 {
     "name": "clusterio_lib",
-    "version": "0.1.1",
+    "variants": [
+        {
+            "version": "0.1.0",
+            "factorio_version": "0.17"
+        },
+        {
+            "version": "0.1.1",
+            "factorio_version": "0.18"
+        },
+        {
+            "version": "0.1.2",
+            "factorio_version": "1.1"
+        }
+    ],
     "title": "Clusterio Library (Alpha)",
     "author": "Clusterio Team",
     "homepage": "https://github.com/clusterio/factorioClusterio",
     "description": "Library for interfacing with Clusterio.  Warning: work in progress alpha.",
-    "factorio_version": "0.17",
-    "additional_files": [
-        ["..", "..", "modules", "clusterio", "serialize.lua"]
-    ]
+    "additional_files": {
+        "serialize.lua": ["..", "..", "modules", "clusterio", "serialize.lua"]
+    }
 }

packages/slave/package.json

@@ -3,7 +3,7 @@
   "description": "Implementation of Clusterio slave server",
   "author": "Hornwitser",
   "license": "MIT",
-  "version": "2.0.0-alpha.2",
+  "version": "2.0.0-alpha.3",
   "main": "slave.js",
   "scripts": {
     "test": "echo \"Error: no test specified\" && exit 1"
@@ -18,11 +18,12 @@
     "node": ">=10.16 <11 || >= 12"
   },
   "dependencies": {
-    "@clusterio/lib": "^2.0.0-alpha.2",
+    "@clusterio/lib": "^2.0.0-alpha.3",
     "fs-extra": "^8.1.0",
     "phin": "^3.4.1",
     "pidusage": "^2.0.18",
     "set-blocking": "^2.0.0",
+    "winston": "^3.3.3",
     "yargs": "^14.2.0"
   },
   "publishConfig": {

packages/slave/slave.js

@@ -22,6 +22,7 @@ const setBlocking = require("set-blocking");
 const phin = require("phin");
 const util = require("util");
 const version = require("./package").version;
+const winston = require("winston");
 
 // internal libraries
 const libFileOps = require("@clusterio/lib/file_ops");
@@ -34,14 +35,25 @@ const libPrometheus = require("@clusterio/lib/prometheus");
 const libLuaTools = require("@clusterio/lib/lua_tools");
 const libConfig = require("@clusterio/lib/config");
 const libSharedCommands = require("@clusterio/lib/shared_commands");
+const { ConsoleTransport, levels, logger } = require("@clusterio/lib/logging");
+const libLoggingUtils = require("@clusterio/lib/logging_utils");
 
 
-const instanceRconCommandsCounter = new libPrometheus.Counter(
-	"clusterio_instance_rcon_commands_total",
-	"How many commands have been sent to the instance",
+const instanceRconCommandDuration = new libPrometheus.Histogram(
+	"clusterio_instance_rcon_command_duration_seconds",
+	"Histogram of the RCON command duration from request to response.",
 	{ labels: ["instance_id"] }
 );
 
+const instanceRconCommandSize = new libPrometheus.Histogram(
+	"clusterio_instance_rcon_command_size_bytes",
+	"Histogram of the RCON command sizes that are sent.",
+	{
+		labels: ["instance_id", "plugin"],
+		buckets: libPrometheus.Histogram.exponential(16, 2, 12),
+	}
+);
+
 const instanceFactorioCpuTime = new libPrometheus.Gauge(
 	"clusterio_instance_factorio_cpu_time_total",
 	"Factorio CPU time spent in seconds.",
@@ -61,7 +73,7 @@ const instanceFactorioAutosaveSize = new libPrometheus.Gauge(
 );
 
 function applyAsConfig(name) {
-	return async function action(server, value) {
+	return async function action(instance, value) {
 		if (name === "tags" && value instanceof Array) {
 			// Replace spaces with non-break spaces and delimit by spaces.
 			// This does change the defined tags, but there doesn't seem to
@@ -69,9 +81,9 @@ function applyAsConfig(name) {
 			value = value.map(tag => tag.replace(/ /g, "\u00a0")).join(" ");
 		}
 		try {
-			await server.sendRcon(`/config set ${name} ${value}`);
+			await instance.sendRcon(`/config set ${name} ${value}`);
 		} catch (err) {
-			console.error(`Error applying server setting ${name}`, err);
+			logger.error(`Error applying server setting ${name} ${err.message}`);
 		}
 	};
 }
@@ -91,13 +103,13 @@ const serverSettingsActions = {
 	"game_password": applyAsConfig("password"),
 	"require_user_verification": applyAsConfig("require-user-verification"),
 	"tags": applyAsConfig("tags"),
-	"visibility": async (server, value) => {
+	"visibility": async (instance, value) => {
 		for (let scope of ["lan", "public", "steam"]) {
 			try {
 				let enabled = Boolean(value[scope]);
-				await server.sendRcon(`/config set visibility-${scope} ${enabled}`);
+				await instance.sendRcon(`/config set visibility-${scope} ${enabled}`);
 			} catch (err) {
-				console.error(`Error applying visibility ${scope}`, err);
+				logger.error(`Error applying visibility ${scope} ${err}`);
 			}
 		}
 	},
@@ -116,6 +128,11 @@ class Instance extends libLink.Link{
 		this.plugins = new Map();
 		this.config = instanceConfig;
 
+		this.logger = logger.child({
+			instance_id: this.config.get("instance.id"),
+			instance_name: this.config.get("instance.name"),
+		});
+
 		this._configFieldChanged = (group, field, prev) => {
 			let hook = () => libPlugin.invokeHook(this.plugins, "onInstanceConfigFieldChanged", group, field, prev);
 
@@ -124,43 +141,45 @@ class Instance extends libLink.Link{
 			} else if (group.name === "factorio" && field === "enable_whitelist") {
 				this.updateFactorioWhitelist(group.get(field)).finally(hook);
 			} else {
+				if (group.name === "factorio" && field === "max_concurrent_commands") {
+					this.server.maxConcurrentCommands = group.get(field);
+				}
 				hook();
 			}
 		};
 		this.config.on("fieldChanged", this._configFieldChanged);
 
 		let serverOptions = {
+			logger: this.logger,
 			version: this.config.get("factorio.version"),
 			gamePort: this.config.get("factorio.game_port"),
 			rconPort: this.config.get("factorio.rcon_port"),
 			rconPassword: this.config.get("factorio.rcon_password"),
 			enableWhitelist: this.config.get("factorio.enable_whitelist"),
+			verboseLogging: this.config.get("factorio.verbose_logging"),
+			stripPaths: this.config.get("factorio.strip_paths"),
+			maxConcurrentCommands: this.config.get("factorio.max_concurrent_commands"),
 		};
 
+		this._status = "stopped";
 		this._running = false;
 		this.server = new libFactorio.FactorioServer(
 			factorioDir, this._dir, serverOptions
 		);
 
-		let originalSendRcon = this.server.sendRcon;
-		this.server.sendRcon = (...args) => {
-			instanceRconCommandsCounter.labels(String(this.config.get("instance.id"))).inc();
-			return originalSendRcon.call(this.server, ...args);
-		};
+		this.server.on("output", (parsed, line) => {
+			this.logger.log("server", { message: line, instance_id: this.config.get("instance.id"), parsed });
 
-		this.server.on("output", (output) => {
-			libLink.messages.instanceOutput.send(this, { instance_id: this.config.get("instance.id"), output });
-
-			libPlugin.invokeHook(this.plugins, "onOutput", output);
+			libPlugin.invokeHook(this.plugins, "onOutput", parsed, line);
 		});
 
 		this.server.on("error", err => {
-			console.log(`Error in instance ${this.name}:`, err);
+			this.logger.error(`Error in instance ${this.name}:\n${err.stack}`);
 		});
 
 		this.server.on("autosave-finished", name => {
 			this._autosave(name).catch(err => {
-				console.error("Error handling autosave-finished:", err);
+				this.logger.error(`Error handling autosave-finished in instance ${this.name}:\n${err.stack}`);
 			});
 		});
 
@@ -173,17 +192,40 @@ class Instance extends libLink.Link{
 		});
 	}
 
+	async sendRcon(message, expectEmpty, plugin = "") {
+		let instanceId = String(this.config.get("instance.id"));
+		let observeDuration = instanceRconCommandDuration.labels(instanceId).startTimer();
+		try {
+			return await this.server.sendRcon(message, expectEmpty);
+		} finally {
+			observeDuration();
+			instanceRconCommandSize.labels(instanceId, plugin).observe(Buffer.byteLength(message, "utf8"));
+		}
+	}
+
 	async _autosave(name) {
 		let stat = await fs.stat(this.path("saves", `${name}.zip`));
 		instanceFactorioAutosaveSize.labels(String(this.config.get("instance.id"))).set(stat.size);
 	}
 
 	notifyStatus(status) {
+		this._status = status;
 		libLink.messages.instanceStatusChanged.send(this, {
 			instance_id: this.config.get("instance.id"), status,
 		});
 	}
 
+	/**
+	 * Current state of the instance
+	 *
+	 * One of stopped, starting, running, creating_save and exporting_data
+	 *
+	 * @returns {string} instance status.
+	 */
+	get status() {
+		return this._status;
+	}
+
 	notifyExit() {
 		this._running = false;
 		this.notifyStatus("stopped");
@@ -214,10 +256,11 @@ class Instance extends libLink.Link{
 		await instancePlugin.init();
 		libPlugin.attachPluginMessages(this, pluginInfo, instancePlugin);
 
-		console.log(`Clusterio | Loaded plugin ${pluginInfo.name} in ${Date.now() - pluginLoadStarted}ms`);
+		this.logger.info(`Loaded plugin ${pluginInfo.name} in ${Date.now() - pluginLoadStarted}ms`);
 	}
 
 	async init(pluginInfos) {
+		this.notifyStatus("starting");
 		await this.server.init();
 
 		// load plugins
@@ -260,7 +303,7 @@ class Instance extends libLink.Link{
 
 		for (let [key, value] of Object.entries(overrides)) {
 			if (!Object.hasOwnProperty.call(serverSettings, key)) {
-				console.log(`Warning: Server settings does not have the property '${key}'`);
+				this.logger.warn(`Server settings does not have the property '${key}'`);
 			}
 			serverSettings[key] = value;
 		}
@@ -294,7 +337,7 @@ class Instance extends libLink.Link{
 	 * @param {String} factorioDir - Path to factorio installation.
 	 */
 	static async create(instanceDir, factorioDir) {
-		console.log(`Clusterio | Creating ${instanceDir}`);
+		logger.info(`Creating ${instanceDir}`);
 		await fs.ensureDir(instanceDir);
 		await fs.ensureDir(path.join(instanceDir, "script-output"));
 		await fs.ensureDir(path.join(instanceDir, "saves"));
@@ -306,11 +349,11 @@ class Instance extends libLink.Link{
 	 * Writes server settings, admin/ban/white-lists and links mods.
 	 */
 	async prepare() {
-		console.log("Clusterio | Writing server-settings.json");
+		this.logger.verbose("Writing server-settings.json");
 		await this.writeServerSettings();
 
 		if (this.config.get("factorio.sync_adminlist")) {
-			console.log("Clusterio | Writing server-adminlist.json");
+			this.logger.verbose("Writing server-adminlist.json");
 			fs.outputFile(
 				this.server.writePath("server-adminlist.json"),
 				JSON.stringify([...this._slave.adminlist], null, 4)
@@ -318,7 +361,7 @@ class Instance extends libLink.Link{
 		}
 
 		if (this.config.get("factorio.sync_banlist")) {
-			console.log("Clusterio | Writing server-banlist.json");
+			this.logger.verbose("Writing server-banlist.json");
 			fs.outputFile(
 				this.server.writePath("server-banlist.json"),
 				JSON.stringify([...this._slave.banlist].map(
@@ -328,14 +371,14 @@ class Instance extends libLink.Link{
 		}
 
 		if (this.config.get("factorio.sync_whitelist")) {
-			console.log("Clusterio | Writing server-whitelist.json");
+			this.logger.verbose("Writing server-whitelist.json");
 			fs.outputFile(
 				this.server.writePath("server-whitelist.json"),
 				JSON.stringify([...this._slave.whitelist], null, 4)
 			);
 		}
 
-		console.log("Clusterio | Rotating old logs...");
+		this.logger.verbose("Rotating old logs...");
 		// clean old log file to avoid crash
 		try{
 			let logPath = this.path("factorio-current.log");
@@ -343,11 +386,11 @@ class Instance extends libLink.Link{
 			if(stat.isFile()){
 				let logFilename = `factorio-${Math.floor(Date.parse(stat.mtime)/1000)}.log`;
 				await fs.rename(logPath, this.path(logFilename));
-				console.log(`Log rotated as ${logFilename}`);
+				this.logger.verbose(`Log rotated as ${logFilename}`);
 			}
 		}catch(e){}
 
-		await symlinkMods(this, "sharedMods", console);
+		await symlinkMods(this, "sharedMods");
 	}
 
 	/**
@@ -370,7 +413,7 @@ class Instance extends libLink.Link{
 
 		// Create save if no save was found.
 		if (saveName === null) {
-			console.log("Clusterio | Creating new save");
+			this.logger.info("Creating new save");
 			await this.server.create("world.zip");
 			saveName = "world.zip";
 		}
@@ -380,7 +423,7 @@ class Instance extends libLink.Link{
 		}
 
 		// Patch save with lua modules from plugins
-		console.log("Clusterio | Patching save");
+		this.logger.verbose("Patching save");
 
 		// Find plugin modules to patch in
 		let modules = new Map();
@@ -454,7 +497,7 @@ class Instance extends libLink.Link{
 	 */
 	async start(saveName) {
 		this.server.on("rcon-ready", () => {
-			console.log("Clusterio | RCON connection established");
+			this.logger.verbose("RCON connection established");
 		});
 
 		this.server.on("exit", () => this.notifyExit());
@@ -481,7 +524,7 @@ class Instance extends libLink.Link{
 	 */
 	async startScenario(scenario) {
 		this.server.on("rcon-ready", () => {
-			console.log("Clusterio | RCON connection established");
+			this.logger.verbose("RCON connection established");
 		});
 
 		this.server.on("exit", () => this.notifyExit());
@@ -499,7 +542,7 @@ class Instance extends libLink.Link{
 	async updateInstanceData() {
 		let name = libLuaTools.escapeString(this.config.get("instance.name"));
 		let id = this.config.get("instance.id");
-		await this.server.sendRcon(`/sc clusterio_private.update_instance(${id}, "${name}")`, true);
+		await this.sendRcon(`/sc clusterio_private.update_instance(${id}, "${name}")`, true);
 	}
 
 	async updateFactorioSettings(current, previous) {
@@ -508,7 +551,7 @@ class Instance extends libLink.Link{
 
 		for (let [key, action] of Object.entries(serverSettingsActions)) {
 			if (current[key] !== undefined && !util.isDeepStrictEqual(current[key], previous[key])) {
-				await action(this.server, current[key]);
+				await action(this, current[key]);
 			}
 		}
 	}
@@ -521,18 +564,18 @@ class Instance extends libLink.Link{
 	 */
 	async updateFactorioWhitelist(enable) {
 		if (!enable) {
-			await this.server.sendRcon("/whitelist disable");
+			await this.sendRcon("/whitelist disable");
 		}
 
 		if (this.config.get("factorio.sync_whitelist")) {
-			await this.server.sendRcon("/whitelist clear");
+			await this.sendRcon("/whitelist clear");
 			for (let player of this._slave.whitelist) {
-				await this.server.sendRcon(`/whitelist ${player}`);
+				await this.sendRcon(`/whitelist ${player}`);
 			}
 		}
 
 		if (enable) {
-			await this.server.sendRcon("/whitelist enable");
+			await this.sendRcon("/whitelist enable");
 		}
 	}
 
@@ -543,7 +586,7 @@ class Instance extends libLink.Link{
 
 		let { name, admin } = message.data;
 		let command = admin ? `/promote ${name}` : `/demote ${name}`;
-		await this.server.sendRcon(command);
+		await this.sendRcon(command);
 	}
 
 	async banlistUpdateEventHandler(message) {
@@ -553,7 +596,7 @@ class Instance extends libLink.Link{
 
 		let { name, banned, reason } = message.data;
 		let command = banned ? `/ban ${name} ${reason}` : `/unban ${name}`;
-		await this.server.sendRcon(command);
+		await this.sendRcon(command);
 	}
 
 	async whitelistUpdateEventHandler(message) {
@@ -563,7 +606,7 @@ class Instance extends libLink.Link{
 
 		let { name, whitelisted } = message.data;
 		let command = whitelisted ? `/whitelist add ${name}` : `/whiteliste remove ${name}`;
-		await this.server.sendRcon(command);
+		await this.sendRcon(command);
 	}
 
 
@@ -651,11 +694,11 @@ class Instance extends libLink.Link{
 	async createSaveRequestHandler() {
 		this.notifyStatus("creating_save");
 		try {
-			console.log("Clusterio | Writing server-settings.json");
+			this.logger.verbose("Writing server-settings.json");
 			await this.writeServerSettings();
 
-			console.log("Creating save .....");
-			await symlinkMods(this, "sharedMods", console);
+			this.logger.verbose("Creating save .....");
+			await symlinkMods(this, "sharedMods");
 
 		} catch (err) {
 			this.notifyExit();
@@ -664,17 +707,17 @@ class Instance extends libLink.Link{
 
 		this.server.on("exit", () => this.notifyExit());
 		await this.server.create("world");
-		console.log("Clusterio | Successfully created save");
+		this.logger.info("Successfully created save");
 	}
 
 	async exportDataRequestHandler() {
 		this.notifyStatus("exporting_data");
 		try {
-			console.log("Clusterio | Writing server-settings.json");
+			this.logger.verbose("Writing server-settings.json");
 			await this.writeServerSettings();
 
-			console.log("Exporting data .....");
-			await symlinkMods(this, "sharedMods", console);
+			this.logger.info("Exporting data .....");
+			await symlinkMods(this, "sharedMods");
 			let zip = await libFactorio.exportData(this.server);
 
 			let content = await zip.generateAsync({ type: "nodebuffer" });
@@ -703,7 +746,7 @@ class Instance extends libLink.Link{
 	}
 
 	async sendRconRequestHandler(message) {
-		let result = await this.server.sendRcon(message.data.command);
+		let result = await this.sendRcon(message.data.command);
 		return { result };
 	}
 
@@ -735,15 +778,15 @@ class Instance extends libLink.Link{
  * Searches for instances in the provided directory
  *
  * Looks through all sub-dirs of the provided directory for valid
- * instance definitions and updates the mapping of instance id to
+ * instance definitions and return a mapping of instance id to
  * instanceInfo objects.
  *
- * @param {Map<integer, Object>} instanceInfos -
- *     mapping between instance id and information about this instance.
  * @param {string} instancesDir - Directory containing instances
- * @param {Object} logger - console like logging interface.
+ * @returns {Map<integer, Object>}
+ *     mapping between instance id and information about this instance.
  */
-async function discoverInstances(instanceInfos, instancesDir, logger) {
+async function discoverInstances(instancesDir) {
+	let instanceInfos = new Map();
 	for (let entry of await fs.readdir(instancesDir, { withFileTypes: true })) {
 		if (entry.isDirectory()) {
 			let instanceConfig = new libConfig.InstanceConfig();
@@ -757,23 +800,19 @@ async function discoverInstances(instanceInfos, instancesDir, logger) {
 					continue; // Ignore folders without config.json
 				}
 
-				logger.error(`Error occured while parsing ${configPath}: ${err}`);
-				continue;
-			}
-
-			// Ignore instances we have already discovered before.
-			if (instanceInfos.has(instanceConfig.get("instance.id"))) {
+				logger.error(`Error occured while parsing ${configPath}: ${err.message}`);
 				continue;
 			}
 
 			let instancePath = path.join(instancesDir, entry.name);
-			logger.log(`found instance ${instanceConfig.get("instance.name")} in ${instancePath}`);
+			logger.verbose(`found instance ${instanceConfig.get("instance.name")} in ${instancePath}`);
 			instanceInfos.set(instanceConfig.get("instance.id"), {
 				path: instancePath,
 				config: instanceConfig,
 			});
 		}
 	}
+	return instanceInfos;
 }
 
 class InstanceConnection extends libLink.Link {
@@ -794,12 +833,28 @@ class InstanceConnection extends libLink.Link {
 		return await request.send(this.slave, message.data);
 	}
 
+	async forwardRequestToInstance(message, request) {
+		let instanceId = message.data.instance_id;
+		let instanceConnection = this.slave.instanceConnections.get(instanceId);
+		if (!instanceConnection) {
+			// Instance is probably on another slave
+			return await this.forwardRequestToMaster(message, request);
+		}
+
+		if (request.plugin && !instanceConnection.plugins.has(request.plugin)) {
+			throw new libErrors.RequestError(`Instance ID ${instanceId} does not have ${request.plugin} plugin loaded`);
+		}
+
+		return await request.send(instanceConnection, message.data);
+	}
+
+
 	async forwardEventToInstance(message, event) {
 		let instanceId = message.data.instance_id;
 		let instanceConnection = this.slave.instanceConnections.get(instanceId);
 		if (!instanceConnection) {
 			// Instance is probably on another slave
-			await this.slave.forwardEventToMaster(message, event);
+			await this.forwardEventToMaster(message, event);
 			return;
 		}
 		if (event.plugin && !instanceConnection.plugins.has(event.plugin)) { return; }
@@ -842,7 +897,7 @@ class SlaveConnector extends libLink.WebSocketClientConnector {
 	}
 
 	register() {
-		console.log("SOCKET | registering slave");
+		logger.info("SOCKET | registering slave");
 		let plugins = {};
 		for (let pluginInfo of this.pluginInfos) {
 			plugins[pluginInfo.name] = pluginInfo.version;
@@ -879,6 +934,7 @@ class Slave extends libLink.Link {
 		this.config = slaveConfig;
 
 		this.instanceConnections = new Map();
+		this.discoveredInstanceInfos = new Map();
 		this.instanceInfos = new Map();
 
 		this.adminlist = new Set();
@@ -890,6 +946,7 @@ class Slave extends libLink.Link {
 			this.serverPlugins = new Map(Object.entries(data.plugins));
 		});
 
+		this._startup = true;
 		this._disconnecting = false;
 		this._shuttingDown = false;
 
@@ -899,14 +956,12 @@ class Slave extends libLink.Link {
 			}
 
 			this.updateInstances().catch((err) => {
-				console.error("ERROR: Unexpected error updating instances");
-				console.error(err);
+				logger.fatal(`Unexpected error updating instances:\n${err.stack}`);
 				return this.shutdown();
 
 			}).catch((err) => {
 				setBlocking(true);
-				console.error("ERROR: Unexpected error during shutdown");
-				console.error(err);
+				logger.fatal(`Unexpected error during shutdown:\n${err.stack}`);
 				process.exit(1);
 			});
 		});
@@ -919,23 +974,20 @@ class Slave extends libLink.Link {
 			if (this._disconnecting) {
 				this._disconnecting = false;
 				this.connector.connect().catch((err) => {
-					console.error("ERROR: Unexpected error reconnecting to master");
-					console.error(err);
+					logger.fatal(`Unexpected error reconnecting to master:\n${err.stack}`);
 					return this.shutdown();
 
 				}).catch((err) => {
 					setBlocking(true);
-					console.error("ERROR: Unexpected error during shutdown");
-					console.error(err);
+					logger.fatal(`Unexpected error during shutdown:\n${err.stack}`);
 					process.exit(1);
 				});
 
 			} else {
-				console.error("ERROR: Master connection was unexpectedly closed");
+				logger.fatal("Master connection was unexpectedly closed");
 				this.shutdown().catch((err) => {
 					setBlocking(true);
-					console.error("ERROR: Unexpected error during shutdown");
-					console.error(err);
+					logger.fatal(`Unexpected error during shutdown:\n${err.stack}`);
 					process.exit(1);
 				});
 			}
@@ -1007,8 +1059,8 @@ class Slave extends libLink.Link {
 		let updateList = (list, updatedList, prop, event) => {
 			let added = new Set(updatedList);
 			let removed = new Set(list);
-			list.forEach(Set.prototype.delete.bind(added));
-			updatedList.forEach(Set.prototype.delete.bind(removed));
+			list.forEach(el => added.delete(el));
+			updatedList.forEach(el => removed.delete(el));
 
 			for (let name of added) {
 				list.add(name);
@@ -1028,15 +1080,14 @@ class Slave extends libLink.Link {
 		updateList(this.adminlist, message.data.adminlist, "admin", libLink.messages.adminlistUpdate);
 		updateList(this.whitelist, message.data.whitelist, "whitelisted", libLink.messages.whitelistUpdate);
 
-		let updatedBanlist = new Map(message.data.banlist);
-		let addedOrChanged = new Map(updatedBanlist);
+		let addedOrChanged = new Map(message.data.banlist);
 		let removed = new Set(this.banlist.keys());
-		removed.forEach((name, reason) => {
+		addedOrChanged.forEach((_, name) => removed.delete(name));
+		this.banlist.forEach((reason, name) => {
 			if (addedOrChanged.get(name) === reason) {
 				addedOrChanged.delete(name);
 			}
 		});
-		updatedBanlist.forEach(Set.prototype.delete.bind(removed));
 
 		for (let [name, reason] of addedOrChanged) {
 			this.banlist.set(name, reason);
@@ -1085,25 +1136,41 @@ class Slave extends libLink.Link {
 		let instanceInfo = this.instanceInfos.get(instance_id);
 		if (instanceInfo) {
 			instanceInfo.config.update(serialized_config, true);
-			console.log(`Clusterio | Updated config for ${instanceInfo.path}`);
-			// TODO: Notify of update if instance is running
+			logger.verbose(`Updated config for ${instanceInfo.path}`);
 
 		} else {
-			let instanceConfig = new libConfig.InstanceConfig();
-			await instanceConfig.load(serialized_config);
+			instanceInfo = this.discoveredInstanceInfos.get(instance_id);
+			if (instanceInfo) {
+				instanceInfo.config.update(serialized_config, true);
 
-			// XXX: race condition on multiple simultanious calls
-			let instanceDir = await this._findNewInstanceDir(instanceConfig.get("instance.name"));
+			} else {
+				let instanceConfig = new libConfig.InstanceConfig();
+				await instanceConfig.load(serialized_config);
+
+				// XXX: race condition on multiple simultanious calls
+				let instanceDir = await this._findNewInstanceDir(instanceConfig.get("instance.name"));
+
+				await Instance.create(instanceDir, this.config.get("slave.factorio_directory"));
+				instanceInfo = {
+					path: instanceDir,
+					config: instanceConfig,
+				};
+
+				this.discoveredInstanceInfos.set(instance_id, instanceInfo);
+			}
 
-			await Instance.create(instanceDir, this.config.get("slave.factorio_directory"));
-			instanceInfo = {
-				path: instanceDir,
-				config: instanceConfig,
-			};
 			this.instanceInfos.set(instance_id, instanceInfo);
-			console.log(`Clusterio | assigned instance ${instanceConfig.get("instance.name")}`);
+			logger.verbose(`assigned instance ${instanceInfo.config.get("instance.name")}`);
 		}
 
+		// Somewhat hacky, but in the event of a lost session the status is
+		// resent on assigment since the master server sends an assigment
+		// request for all the instances it knows should be on this slave.
+		let instanceConnection = this.instanceConnections.get(instance_id);
+		libLink.messages.instanceStatusChanged.send(this, {
+			instance_id,
+			status: instanceConnection ? instanceConnection.status : "stopped",
+		});
 
 		// save a copy of the instance config
 		let warnedOutput = {
@@ -1114,9 +1181,20 @@ class Slave extends libLink.Link {
 			path.join(instanceInfo.path, "instance.json"),
 			JSON.stringify(warnedOutput, null, 4)
 		);
+	}
 
-		// Notify master the instance is no longer usassigned
-		libLink.messages.instanceStatusChanged.send(this, { instance_id, status: "stopped" });
+	async unassignInstanceRequestHandler(message) {
+		let instanceId = message.data.instance_id;
+		let instanceInfo = this.instanceInfos.get(instanceId);
+		if (instanceInfo) {
+			let instanceConnection = this.instanceConnections.get(instanceId);
+			if (instanceConnection && ["starting", "running"].includes(instanceConnection.status)) {
+				await libLink.messages.stopInstance.send(instanceConnection, { instance_id: instanceId });
+			}
+
+			this.instanceInfos.delete(instanceId);
+			logger.verbose(`unassigned instance ${instanceInfo.config.get("instance.name")}`);
+		}
 	}
 
 	/**
@@ -1140,10 +1218,10 @@ class Slave extends libLink.Link {
 		let instance = new Instance(
 			this, connectionClient, instanceInfo.path, this.config.get("slave.factorio_directory"), instanceInfo.config
 		);
+
+		this.instanceConnections.set(instanceId, instanceConnection);
 		await instance.init(this.pluginInfos);
 
-		// XXX: race condition on multiple simultanious calls
-		this.instanceConnections.set(instanceId, instanceConnection);
 		return instanceConnection;
 	}
 
@@ -1208,13 +1286,14 @@ class Slave extends libLink.Link {
 			throw new libErrors.RequestError(`Instance with ID ${instanceId} is running`);
 		}
 
-		let instanceInfo = this.instanceInfos.get(instanceId);
+		let instanceInfo = this.discoveredInstanceInfos.get(instanceId);
 		if (!instanceInfo) {
 			throw new libErrors.RequestError(`Instance with ID ${instanceId} does not exist`);
 		}
 
-		await fs.remove(instanceInfo.path);
+		this.discoveredInstanceInfos.delete(instanceId);
 		this.instanceInfos.delete(instanceId);
+		await fs.remove(instanceInfo.path);
 	}
 
 	/**
@@ -1224,16 +1303,37 @@ class Slave extends libLink.Link {
 	 * the slave and master server with the new list of instances.
 	 */
 	async updateInstances() {
-		await discoverInstances(this.instanceInfos, this.config.get("slave.instances_directory"), console);
+		this.discoveredInstanceInfos = await discoverInstances(this.config.get("slave.instances_directory"));
 		let list = [];
-		for (let [instanceId, instanceInfo] of this.instanceInfos) {
+		for (let [instanceId, instanceInfo] of this.discoveredInstanceInfos) {
 			let instanceConnection = this.instanceConnections.get(instanceId);
 			list.push({
 				serialized_config: instanceInfo.config.serialize(),
 				status: instanceConnection ? instanceConnection.status : "stopped",
 			});
 		}
-		libLink.messages.updateInstances.send(this, { instances: list });
+		await libLink.messages.updateInstances.send(this, { instances: list });
+
+		// Handle configured auto startup instances
+		if (this._startup) {
+			this._startup = false;
+
+			for (let [instanceId, instanceInfo] of this.instanceInfos) {
+				if (instanceInfo.config.get("instance.auto_start")) {
+					try {
+						let instanceConnection = await this._connectInstance(instanceId);
+						await libLink.messages.startInstance.send(instanceConnection, {
+							instance_id: instanceId,
+							save: null,
+						});
+					} catch (err) {
+						logger.error(
+							`Error during auto startup for ${instanceInfo.config.get("instance.name")}:\n${err.stack}`
+						);
+					}
+				}
+			}
+		}
 	}
 
 	async prepareDisconnectRequestHandler(message, request) {
@@ -1256,8 +1356,7 @@ class Slave extends libLink.Link {
 			await libLink.messages.prepareDisconnect.send(this);
 		} catch (err) {
 			if (!(err instanceof libErrors.SessionLost)) {
-				console.error("Unexpected error preparing disconnect");
-				console.error(err);
+				logger.error(`Unexpected error preparing disconnect:\n${err.stack}`);
 			}
 		}
 
@@ -1326,16 +1425,15 @@ function checkFilename(name) {
  *
  * @param {Instance} instance - Instance to link mods for
  * @param {string} sharedMods - Path to folder to link mods from.
- * @param {object} logger - console like logging interface.
  */
-async function symlinkMods(instance, sharedMods, logger) {
+async function symlinkMods(instance, sharedMods) {
 	await fs.ensureDir(instance.path("mods"));
 
 	// Remove broken symlinks in instance mods.
 	for (let entry of await fs.readdir(instance.path("mods"), { withFileTypes: true })) {
 		if (entry.isSymbolicLink()) {
 			if (!await fs.pathExists(instance.path("mods", entry.name))) {
-				logger.log(`Removing broken symlink ${entry.name}`);
+				instance.logger.verbose(`Removing broken symlink ${entry.name}`);
 				await fs.unlink(instance.path("mods", entry.name));
 			}
 		}
@@ -1347,7 +1445,7 @@ async function symlinkMods(instance, sharedMods, logger) {
 		if (entry.isFile()) {
 			if ([".zip", ".dat"].includes(path.extname(entry.name))) {
 				if (!instanceModsEntries.has(entry.name)) {
-					logger.log(`linking ${entry.name} from ${sharedMods}`);
+					instance.logger.verbose(`linking ${entry.name} from ${sharedMods}`);
 					let target = path.join(sharedMods, entry.name);
 					let link = instance.path("mods", entry.name);
 
@@ -1365,23 +1463,27 @@ async function symlinkMods(instance, sharedMods, logger) {
 				}
 
 			} else {
-				logger.warn(`Warning: ignoring file '${entry.name}' in sharedMods`);
+				instance.logger.warn(`Warning: ignoring file '${entry.name}' in sharedMods`);
 			}
 
 		} else {
-			logger.warn(`Warning: ignoring non-file '${entry.name}' in sharedMods`);
+			instance.logger.warn(`Warning: ignoring non-file '${entry.name}' in sharedMods`);
 		}
 	}
 }
 
 async function startSlave() {
-	// add better stack traces on promise rejection
-	process.on("unhandledRejection", r => console.log(r));
-
 	// argument parsing
 	const args = yargs
 		.scriptName("slave")
 		.usage("$0 <command> [options]")
+		.option("log-level", {
+			nargs: 1,
+			describe: "Log level to print to stdout",
+			default: "info",
+			choices: ["none"].concat(Object.keys(levels)),
+			type: "string",
+		})
 		.option("config", {
 			nargs: 1,
 			describe: "slave config file to use",
@@ -1402,7 +1504,23 @@ async function startSlave() {
 		.argv
 	;
 
-	console.log(`Loading available plugins from ${args.pluginList}`);
+	logger.add(new winston.transports.File({
+		format: winston.format.combine(
+			winston.format.json(),
+		),
+		filename: "slave.log",
+	}));
+	if (args.logLevel !== "none") {
+		logger.add(new ConsoleTransport({
+			level: args.logLevel,
+			format: new libLoggingUtils.TerminalFormat(),
+		}));
+	}
+
+	// add better stack traces on promise rejection
+	process.on("unhandledRejection", err => logger.error(`Unhandled rejection:\n${err.stack}`));
+
+	logger.info(`Loading available plugins from ${args.pluginList}`);
 	let pluginList = new Map();
 	try {
 		pluginList = new Map(JSON.parse(await fs.readFile(args.pluginList)));
@@ -1419,19 +1537,19 @@ async function startSlave() {
 		return;
 	}
 
-	console.log("Loading Plugin info");
+	logger.info("Loading Plugin info");
 	let pluginInfos = await libPluginLoader.loadPluginInfos(pluginList);
 	libConfig.registerPluginConfigGroups(pluginInfos);
 	libConfig.finalizeConfigs();
 
-	console.log(`Loading config from ${args.config}`);
+	logger.info(`Loading config from ${args.config}`);
 	let slaveConfig = new libConfig.SlaveConfig();
 	try {
 		await slaveConfig.load(JSON.parse(await fs.readFile(args.config)));
 
 	} catch (err) {
 		if (err.code === "ENOENT") {
-			console.log("Config not found, initializing new config");
+			logger.info("Config not found, initializing new config");
 			await slaveConfig.init();
 
 		} else {
@@ -1456,8 +1574,8 @@ async function startSlave() {
 
 	// make sure we have the master access token
 	if (slaveConfig.get("slave.master_token") === "enter token here") {
-		console.error("ERROR invalid config!");
-		console.error(
+		logger.fatal("ERROR invalid config!");
+		logger.fatal(
 			"Master server requires an access token for socket operations. As clusterio\n"+
 			"slaves depends upon this, please set your token using the command npx\n"+
 			"clusterioslave config set slave.master_token <token>.  You can generate an\n"+
@@ -1469,8 +1587,8 @@ async function startSlave() {
 
 	// make sure url ends with /
 	if (!slaveConfig.get("slave.master_url").endsWith("/")) {
-		console.error("ERROR invalid config!");
-		console.error("slave.master_url must end with '/'");
+		logger.fatal("ERROR invalid config!");
+		logger.fatal("slave.master_url must end with '/'");
 		process.exitCode = 1;
 		return;
 	}
@@ -1482,24 +1600,28 @@ async function startSlave() {
 	let secondSigint = false;
 	process.on("SIGINT", () => {
 		if (secondSigint) {
-			console.log("Caught second interrupt, terminating immediately");
+			logger.fatal("Caught second interrupt, terminating immediately");
 			process.exit(1);
 		}
 
 		secondSigint = true;
-		console.log("Caught interrupt signal, shutting down");
+		logger.info("Caught interrupt signal, shutting down");
 		slave.shutdown().catch(err => {
-			console.error(`
+			logger.error(`
 +---------------------------------------------------------------+
 | Unexpected error occured while stopping slave, please report  |
 | it to https://github.com/clusterio/factorioClusterio/issues   |
-+---------------------------------------------------------------+`
++---------------------------------------------------------------+
+${err.stack}`
 			);
-			console.error(err);
 			process.exit(1);
 		});
 	});
 
+	slaveConnector.once("connect", () => {
+		logger.add(new libLoggingUtils.LinkTransport({ link: slave }));
+	});
+
 	await slaveConnector.connect();
 }
 
@@ -1513,6 +1635,7 @@ module.exports = {
 };
 
 if (module === require.main) {
+	// eslint-disable-next-line no-console
 	console.warn(`
 +==========================================================+
 I WARNING:  This is the development branch for the 2.0     I
@@ -1522,16 +1645,16 @@ I           version of clusterio.  Expect things to break. I
 	);
 	startSlave().catch(err => {
 		if (err instanceof libErrors.AuthenticationFailed) {
-			console.error(err.message);
+			logger.fatal(err.message);
 
 		} else {
-			console.error(`
+			logger.fatal(`
 +--------------------------------------------------------------+
 | Unexpected error occured while starting slave, please report |
 | it to https://github.com/clusterio/factorioClusterio/issues  |
-+--------------------------------------------------------------+`
++--------------------------------------------------------------+
+${err.stack}`
 			);
-			console.error(err);
 		}
 
 		process.exit(1);

packages/web_ui/package.json

@@ -3,7 +3,7 @@
   "description": "Clusterio web interface implementation",
   "author": "Hornwitser",
   "license": "MIT",
-  "version": "2.0.0-alpha.2",
+  "version": "2.0.0-alpha.3",
   "scripts": {
     "test": "echo \"Error: no test specified\" && exit 1"
   },
@@ -15,14 +15,18 @@
   },
   "dependencies": {
     "@ant-design/icons": "^4.2.2",
-    "@clusterio/lib": "^2.0.0-alpha.2",
+    "@clusterio/lib": "^2.0.0-alpha.3",
     "antd": "^4.6.5",
+    "buffer": "^6.0.2",
     "clean-webpack-plugin": "^3.0.0",
     "events": "^3.2.0",
+    "os-browserify": "^0.3.0",
     "path-browserify": "^1.0.1",
+    "process": "^0.11.10",
     "react": "^16.13.1",
     "react-dom": "^16.13.1",
-    "react-router-dom": "^5.2.0"
+    "react-router-dom": "^5.2.0",
+    "util": "^0.12.3"
   },
   "publishConfig": {
     "access": "public"

packages/web_ui/src/bootstrap.jsx

@@ -4,6 +4,7 @@ import React from "react";
 import ReactDOM from "react-dom";
 
 import libConfig from "@clusterio/lib/config";
+import { ConsoleTransport, WebConsoleFormat, logger } from "@clusterio/lib/logging";
 
 import App from "./components/App";
 import { Control, ControlConnector } from "./util/websocket";
@@ -31,7 +32,7 @@ async function loadPluginInfos() {
 		pluginList = await response.json();
 
 	} else {
-		console.log("Failed to get plugin data, running without plugins");
+		logger.error("Failed to get plugin data, running without plugins");
 		pluginList = [];
 	}
 
@@ -47,14 +48,17 @@ async function loadPluginInfos() {
 			pluginInfos.push(info);
 
 		} catch (err) {
-			console.log(`Failed to load plugin info for ${plugin.name}`);
-			console.log(err);
+			logger.error(`Failed to load plugin info for ${plugin.name}`);
 		}
 	}
 	return pluginInfos;
 }
 
 async function load() {
+	logger.add(new ConsoleTransport({
+		level: "verbose",
+		format: new WebConsoleFormat(),
+	}));
 	let pluginInfos = await loadPluginInfos();
 	libConfig.registerPluginConfigGroups(pluginInfos);
 	libConfig.finalizeConfigs();
@@ -68,4 +72,4 @@ async function load() {
 	ReactDOM.render(<App control={control}/>, document.getElementById("root"));
 }
 
-load().catch(console.log);
+load().catch((err) => logger.fatal(err));

packages/web_ui/src/components/App.jsx

@@ -2,6 +2,8 @@ import events from "events";
 import React, { useEffect, useState } from "react";
 import { BrowserRouter } from "react-router-dom";
 
+import { logger } from "@clusterio/lib/logging";
+
 import basename from "../basename";
 import SiteLayout from "./SiteLayout";
 import ControlContext from "./ControlContext";
@@ -31,7 +33,7 @@ export default function App(props) {
 		}
 
 		function onError(err) {
-			console.error("Unexpected error in connector", err);
+			logger.error(`Unexpected error in connector:\n${err.stack}`);
 			clearToken();
 			setConnected(false);
 		}

packages/web_ui/src/components/InstanceViewPage.jsx

@@ -1,4 +1,4 @@
-import React, { useEffect, useContext, useState } from "react";
+import React, { useEffect, useContext, useRef, useState } from "react";
 import { useHistory, useParams } from "react-router-dom";
 import {
 	notification, Button, Card, Checkbox, Col, Descriptions, Dropdown, Form, Input, InputNumber, Modal,
@@ -72,53 +72,86 @@ function useSlave(id) {
 	return [slave, updateSlave];
 }
 
-function formatOutputColored(output, key) {
+function formatParsedOutput(parsed, key) {
 	let time = "";
-	if (output.format === "seconds") {
-		time = <span className="factorio-time">{output.time.padStart(8)} </span>;
-	} else if (output.format === "date") {
-		time = <span className="factorio-time">{output.time} </span>;
+	if (parsed.format === "seconds") {
+		time = <span className="factorio-time">{parsed.time.padStart(8)} </span>;
+	} else if (parsed.format === "date") {
+		time = <span className="factorio-time">{parsed.time} </span>;
 	}
 
 	let info = "";
-	if (output.type === "log") {
-		let level = output.level;
-		if (level === "Info") {
+	if (parsed.type === "log") {
+		let level = parsed.level;
+		if (level === "Script") {
+			level = <span className="factorio-script">{level}</span>;
+		} else if (level === "Verbose") {
+			level = <span className="factorio-verbose">{level}</span>;
+		} else if (level === "Info") {
 			level = <span className="factorio-info">{level}</span>;
-		} else if (output.level === "Warning") {
+		} else if (parsed.level === "Warning") {
 			level = <span className="factorio-warning">{level}</span>;
-		} else if (output.level === "Error") {
+		} else if (parsed.level === "Error") {
 			level = <span className="factorio-error">{level}</span>;
 		}
 
-		info = <>{level} <span className="factorio-filename">{output.file}: </span></>;
+		info = <>{level} <span className="factorio-filename">{parsed.file}: </span></>;
 
-	} else if (output.type === "action") {
-		info = <>[<span className="factorio-action">{output.action}</span>] </>;
+	} else if (parsed.type === "action") {
+		info = <>[<span className="factorio-action">{parsed.action}</span>] </>;
 	}
 
-	return <span key={key}>{time}{info}{output.message}<br/></span>;
+	return <span key={key}>{time}{info}{parsed.message}<br/></span>;
+}
+
+function formatLog(info, key) {
+	if (info.level === "server" && info.parsed) {
+		return formatParsedOutput(info.parsed, key);
+	}
+	let level = <span className={`log-${info.level}`}>{info.level}</span>;
+	return <span key={key}>[{level}] {info.message}<br/></span>;
 }
 
 function InstanceConsole(props) {
 	let control = useContext(ControlContext);
-	let [lines, setLines] = useState([{ message: "<previous messages are not shown>" }]);
+	let anchor = useRef();
+	let [pastLines, setPastLines] = useState([<span key={0}>{"Loading past entries..."}<br/></span>]);
+	let [lines, setLines] = useState([]);
 
 	useEffect(() => {
-		function outputHandler(output) {
-			setLines(currentLines => currentLines.concat([output]));
+		// Scroll view to the anchor so it sticks to the bottom
+		let parent = anchor.current.parentElement;
+		parent.scrollTop = parent.scrollHeight - parent.clientHeight;
+
+		libLink.messages.queryLog.send(control, {
+			all: false,
+			master: false,
+			slave_ids: [],
+			instance_ids: [props.id],
+			max_level: null,
+		}).then(result => {
+			setPastLines(result.log.slice(-400).map((info, index) => formatLog(info, index)));
+		}).catch(err => {
+			setPastLines([<span key={0}>{`Error loading log: ${err.message}`}<br/></span>]);
+		});
+
+		function logHandler(info) {
+			setLines(currentLines => currentLines.concat(
+				[formatLog(info, currentLines.length)]
+			));
 		}
 
-		control.onInstanceOutput(props.id, outputHandler);
+		control.onInstanceLog(props.id, logHandler);
 		return () => {
-			control.offInstanceOutput(props.id, outputHandler);
+			control.offInstanceLog(props.id, logHandler);
 		};
 	}, [props.id]);
 
 	return <>
 		<Paragraph code className="instance-console">
-			{lines.map(formatOutputColored)}
-			<div className="scroll-anchor" />
+			{pastLines}
+			{lines}
+			<div className="scroll-anchor" ref={anchor} />
 		</Paragraph>
 	</>;
 }

packages/web_ui/src/components/InstancesPage.jsx

@@ -35,17 +35,14 @@ export default function InstancesPage() {
 				insert: async args => {
 					let instanceConfig = new libConfig.InstanceConfig();
 					await instanceConfig.init();
-					console.log("Base config", instanceConfig);
 					instanceConfig.set("instance.name", args.name);
 					let serialized_config = instanceConfig.serialize();
 					let response = await libLink.messages.createInstance.send(control, { serialized_config });
-					console.log("Created instance", response);
 				},
 			}}
 			TableProps={{
 				onRow: (record, rowIndex) => ({
 					onClick: event => {
-						console.log(record, rowIndex);
 						history.push(`/instances/${record.key}/view`);
 					},
 				}),

packages/web_ui/src/components/RoleViewPage.jsx

@@ -78,7 +78,6 @@ export default function RoleViewPage() {
 			initialValues={initialValues}
 			onValuesChange={() => { setEdited(true); }}
 			onFinish={values => {
-				console.log(values);
 				let newPermissions = [];
 				for (let [name, value] of Object.entries(values.permissions)) {
 					if (value) { newPermissions.push(name); }

packages/web_ui/src/components/RolesPage.jsx

@@ -41,7 +41,6 @@ export default function UsersPage() {
 			TableProps={{
 				onRow: (record, rowIndex) => ({
 					onClick: event => {
-						console.log(record, rowIndex);
 						history.push(`/roles/${record.key}/view`);
 					},
 				}),

packages/web_ui/src/components/UsersPage.jsx

@@ -59,7 +59,6 @@ export default function UsersPage() {
 			TableProps={{
 				onRow: (record, rowIndex) => ({
 					onClick: event => {
-						console.log(record, rowIndex);
 						history.push(`/users/${record.key}/view`);
 					},
 				}),

packages/web_ui/src/components/data-table.jsx

@@ -54,7 +54,6 @@ class DataTable extends Component {
 		pagination = pagination || this.state.pagination;
 		filters = filters || this.state.filters;
 		sorter = sorter || this.state.sorter;
-		// console.log(pagination, filters, sorter)
 
 		// eslint-disable-next-line new-cap
 		let data = await this.props.DataFunction();
@@ -67,7 +66,6 @@ class DataTable extends Component {
 		//     sorter,
 		//     recordIdField: this.props.RecordIdField || "Id", // Sort by this
 		// })
-		console.log(data);
 		data = data || {};
 		this.setState({
 			// eslint-disable-next-line new-cap
@@ -96,8 +94,6 @@ class DataTable extends Component {
 	}
 
 	async onEditFinish(values) {
-		console.log("Finished editing", values);
-
 		if (this.state.inserting) { // Create new record
 			await this.props.AddRecord.insert(values);
 		} else { // Edit existing record, capable of doing sparse updates
@@ -126,8 +122,6 @@ class DataTable extends Component {
 		//     record,
 		// }, undefined, true)
 
-		console.log("Deleted record", status);
-
 		if (status.ok) notify("success", status.msg, "success");
 		if (!status.ok) notify("error", status.msg, "error");
 
@@ -150,7 +144,6 @@ class DataTable extends Component {
 				return {
 					onClick: event => {
 						if (event.target.type !== "button") {
-							console.log("onRow", record, rowIndex);
 							if (this.props.Editable) this.showEditModal(record, rowIndex);
 							if (externalOnRow.onClick) externalOnRow.onClick(event);
 						}
@@ -242,20 +235,21 @@ class DataTable extends Component {
 						onFinish={this.onEditFinish.bind(this)}
 						initialValues={this.state.record}
 					>
-						{
-
-							(
-								(this.state.inserting && this.props.AddRecord && this.props.AddRecord.fields) // Use externally supplied form input fields
-								|| this.props.columns.filter && this.props.columns.filter(x => x.dataIndex !== "notInUse") // Generate input fields from external columns
-								|| this.inferColumns(this.state.tableData)).map(col => { // Generate input fields from autogenerated columns (only works with existing data)
-								console.log(this.state.record);
-								return <Form.Item key={col.dataIndex} label={col.title} name={col.dataIndex}>
-									{col.renderEdit && col.renderEdit(this.state.record[col.dataIndex], this.state.record, undefined /* Non spec compliant, is supposed to be index of record */, this.state.tableData) || <Input
-										placeholder={this.state.record[col.dataIndex]}
-									/>}
-								</Form.Item>;
-							})
-						}
+						{(
+							// Use externally supplied form input fields
+							(this.state.inserting && this.props.AddRecord && this.props.AddRecord.fields)
+							// Generate input fields from external columns
+							|| this.props.columns.filter && this.props.columns.filter(x => x.dataIndex !== "notInUse")
+							// Generate input fields from autogenerated columns (only works with existing data)
+							|| this.inferColumns(this.state.tableData)
+						).map(col => <Form.Item key={col.dataIndex} label={col.title} name={col.dataIndex}>
+							{col.renderEdit && col.renderEdit(
+								this.state.record[col.dataIndex],
+								this.state.record,
+								undefined /* Non spec compliant, is supposed to be index of record */,
+								this.state.tableData
+							) || <Input placeholder={this.state.record[col.dataIndex]} />}
+						</Form.Item>)}
 						<Form.Item>
 							<Button type="primary" htmlType="submit">
 								{this.state.inserting ? "Legg til" : "Lagre"}

packages/web_ui/src/index.css

@@ -108,6 +108,11 @@ body {
 	border-color: #252525;
 	height: 300px;
 	overflow-y: scroll;
+	white-space: pre-wrap;
+
+	/* Make sure there's at least one pixel of scroll space, this */
+	/* is necessary for the view to stick on the scroll anchor. */
+	padding-top: 300px;
 }
 
 .instance-console .factorio-time {
@@ -118,6 +123,16 @@ body {
 	color: #808080;
 }
 
+.instance-console .factorio-script {
+	font-weight: bold;
+	color: #49c33c;
+}
+
+.instance-console .factorio-verbose {
+	font-weight: bold;
+	color: #888888;
+}
+
 .instance-console .factorio-info {
 	font-weight: bold;
 	color: #4646ea;
@@ -137,6 +152,37 @@ body {
 	color: #afaf1f;
 }
 
+.log-verbose {
+	font-weight: bold;
+	color: #888888;
+}
+
+.log-info {
+	font-weight: bold;
+	color: #4646ea;
+}
+
+.log-audit {
+	font-weight: bold;
+	color: #49c33c;
+}
+
+.log-warn {
+	font-weight: bold;
+	color: #afaf1f;
+}
+
+.log-error {
+	font-weight: bold;
+	color: #ad3939;
+}
+
+.log-fatal {
+	font-weight: bold;
+	background-color: #ad3939;
+	color: #000;
+}
+
 .config-container {
 	background-color: #111111;
 }

packages/web_ui/src/util/notify.jsx

@@ -1,4 +1,5 @@
 import { notification } from "antd";
+import { logger } from "@clusterio/lib/logging";
 
 
 export default function notify(message, type = "info", description = undefined) {
@@ -7,7 +8,9 @@ export default function notify(message, type = "info", description = undefined)
 		description,
 		placement: "bottomRight",
 	});
-	if (typeof message !== "string") console.error(message);
+	if (typeof message !== "string") {
+		logger.error(message.stack);
+	}
 }
 
 /**
@@ -22,7 +25,7 @@ export default function notify(message, type = "info", description = undefined)
  */
 export function notifyErrorHandler(message) {
 	return function handler(err) {
-		console.error(err);
+		logger.error(err.stack);
 		notification.error({
 			message,
 			description: err.message,

packages/web_ui/src/util/websocket.jsx

@@ -1,7 +1,8 @@
-const libLink = require("@clusterio/lib/link");
-const libPlugin = require("@clusterio/lib/plugin");
-const libErrors = require("@clusterio/lib/errors");
-const version = require("../../package.json").version;
+import libLink from "@clusterio/lib/link";
+import libPlugin from "@clusterio/lib/plugin";
+import libErrors from "@clusterio/lib/errors";
+import { logger } from "@clusterio/lib/logging";
+import packageJson from "../../package.json";
 
 
 /**
@@ -19,11 +20,11 @@ export class ControlConnector extends libLink.WebSocketClientConnector {
 			throw new Error("Token not set");
 		}
 
-		console.log("SOCKET | registering control");
+		logger.verbose("SOCKET | registering control");
 		this.sendHandshake("register_control", {
 			token: this.token,
 			agent: "Clusterio Web UI",
-			version,
+			version: packageJson.version,
 		});
 	}
 }
@@ -48,37 +49,46 @@ export class Control extends libLink.Link {
 			libPlugin.attachPluginMessages(this, controlPlugin.info, controlPlugin);
 		}
 
-		this.instanceOutputHandlers = new Map();
+		this.instanceLogHandlers = new Map();
+
+		this.connector.on("connect", () => {
+			this.updateLogSubscriptions().catch(err => logger.error(
+				`Unexpected error updating log subscriptions:\n${err.stack}`
+			));
+		});
 	}
 
-	async instanceOutputEventHandler(message) {
-		let { instance_id, output } = message.data;
-		let handlers = this.instanceOutputHandlers.get(instance_id);
-		for (let handler of handlers || []) {
-			handler(output);
+	async logMessageEventHandler(message) {
+		let info = message.data.info;
+
+		if (info.instance_id !== undefined) {
+			let instanceHandlers = this.instanceLogHandlers.get(info.instance_id);
+			for (let handler of instanceHandlers || []) {
+				handler(info);
+			}
 		}
 	}
 
-	async onInstanceOutput(id, handler) {
+	async onInstanceLog(id, handler) {
 		if (!Number.isInteger(id)) {
 			throw new Error("Invalid instance id");
 		}
 
-		let handlers = this.instanceOutputHandlers.get(id);
+		let handlers = this.instanceLogHandlers.get(id);
 		if (!handlers) {
 			handlers = [];
-			this.instanceOutputHandlers.set(id, handlers);
+			this.instanceLogHandlers.set(id, handlers);
 		}
 
 		handlers.push(handler);
 
 		if (handlers.length === 1) {
-			await this.updateInstanceOutputSubscriptions();
+			await this.updateLogSubscriptions();
 		}
 	}
 
-	async offInstanceOutput(id, handler) {
-		let handlers = this.instanceOutputHandlers.get(id);
+	async offInstanceLog(id, handler) {
+		let handlers = this.instanceLogHandlers.get(id);
 		if (!handlers || !handlers.length) {
 			throw new Error(`No handlers for instance ${id} exist`);
 		}
@@ -90,17 +100,22 @@ export class Control extends libLink.Link {
 
 		handlers.splice(index, 1);
 		if (!handlers.length) {
-			await this.updateInstanceOutputSubscriptions();
+			await this.updateLogSubscriptions();
 		}
 	}
 
-	async updateInstanceOutputSubscriptions() {
-		await libLink.messages.setInstanceOutputSubscriptions.send(this, {
-			instance_ids: [...this.instanceOutputHandlers.keys()],
+	async updateLogSubscriptions() {
+		await libLink.messages.setLogSubscriptions.send(this, {
+			all: false,
+			master: false,
+			slave_ids: [],
+			instance_ids: [...this.instanceLogHandlers.keys()],
+			max_level: null,
 		});
 	}
 
 	async debugWsMessageEventHandler(message) {
+		// eslint-disable-next-line no-console
 		console.log("WS", message.data.direction, message.data.content);
 	}
 

packages/web_ui/webpack.common.js

@@ -11,6 +11,13 @@ module.exports = (env = {}) => ({
 	},
 	plugins: [
 		new CleanWebpackPlugin(),
+
+		// required for winston
+		new webpack.ProvidePlugin({
+			process: require.resolve("process/browser.js"),
+			Buffer: [require.resolve("buffer/"), "Buffer"],
+		}),
+
 		new webpack.DefinePlugin({
 			"process.env.APP_ENV": JSON.stringify("browser"),
 		}),
@@ -33,6 +40,15 @@ module.exports = (env = {}) => ({
 				test: /node_modules.jsonwebtoken/,
 				use: "null-loader",
 			},
+			{
+				test: /node_modules.winston.dist.winston.transports.(http|file)/,
+				use: "null-loader",
+			},
+			// Colour library used by winston which doesn't work in browser.
+			{
+				test: /node_modules.colors/,
+				use: "null-loader",
+			},
 			{
 				test: /\.css$/,
 				use: [
@@ -72,6 +88,10 @@ module.exports = (env = {}) => ({
 	resolve: {
 		extensions: [".js", ".json", ".jsx"],
 		fallback: {
+			// Required for winston
+			"util": require.resolve("util/"),
+			"os": require.resolve("os-browserify/browser"),
+
 			"events": require.resolve("events/"),
 			"path": require.resolve("path-browserify"),
 		},

plugins/global_chat/instance.js

@@ -33,7 +33,7 @@ class InstancePlugin extends libPlugin.BaseInstancePlugin {
 	async chatEventHandler(message) {
 		// TODO check if cross server chat is enabled
 		let content = `[${message.data.instance_name}] ${removeTags(message.data.content)}`;
-		await this.instance.server.sendRcon(`/sc game.print('${libLuaTools.escapeString(content)}')`, true);
+		await this.sendRcon(`/sc game.print('${libLuaTools.escapeString(content)}')`, true);
 	}
 
 	sendChat(message) {

plugins/global_chat/package.json

@@ -1,6 +1,6 @@
 {
   "name": "@clusterio/plugin-global_chat",
-  "version": "2.0.0-alpha.2",
+  "version": "2.0.0-alpha.3",
   "description": "Clusterio plugin forwarding between Factorio servers",
   "author": "Hornwitser <github@hornwitser.no>",
   "homepage": "https://github.com/clusterio/factorioClusterio#readme",
@@ -17,7 +17,7 @@
     "@clusterio/lib": "^2.0.0-alpha.0"
   },
   "devDependencies": {
-    "@clusterio/web_ui": "^2.0.0-alpha.2",
+    "@clusterio/web_ui": "^2.0.0-alpha.3",
     "babel-loader": "^8.1.0",
     "file-loader": "^6.2.0",
     "null-loader": "^4.0.0",

plugins/research_sync/instance.js

@@ -3,23 +3,21 @@ const libPlugin = require("@clusterio/lib/plugin");
 const libLuaTools = require("@clusterio/lib/lua_tools");
 
 
-function unexpectedError(err) {
-	console.log("Unexpected error in research_sync");
-	console.log("---------------------------------");
-	console.log(err);
-}
-
 class InstancePlugin extends libPlugin.BaseInstancePlugin {
+	unexpectedError(err) {
+		this.logger.error(`Unexpected error:\n${err.stack}`);
+	}
+
 	async init() {
 		if (!this.instance.config.get("factorio.enable_save_patching")) {
 			throw new Error("research_sync plugin requires save patching.");
 		}
 
 		this.instance.server.on("ipc-research_sync:contribution", (tech) => {
-			this.researchContribution(tech).catch(unexpectedError);
+			this.researchContribution(tech).catch(err => this.unexpectedError(err));
 		});
 		this.instance.server.on("ipc-research_sync:finished", (tech) => {
-			this.researchFinished(tech).catch(unexpectedError);
+			this.researchFinished(tech).catch(err => this.unexpectedError(err));
 		});
 	}
 
@@ -29,7 +27,7 @@ class InstancePlugin extends libPlugin.BaseInstancePlugin {
 
 	async progressEventHandler(message) {
 		let techsJson = libLuaTools.escapeString(JSON.stringify(message.data.technologies));
-		await this.instance.server.sendRcon(`/sc research_sync.update_progress("${techsJson}")`, true);
+		await this.sendRcon(`/sc research_sync.update_progress("${techsJson}")`, true);
 	}
 
 	async researchFinished(tech) {
@@ -38,13 +36,13 @@ class InstancePlugin extends libPlugin.BaseInstancePlugin {
 
 	async finishedEventHandler(message) {
 		let { name, level, researched } = message.data;
-		await this.instance.server.sendRcon(
+		await this.sendRcon(
 			`/sc research_sync.research_technology("${libLuaTools.escapeString(name)}", ${level})`, true
 		);
 	}
 
 	async onStart() {
-		let dumpJson = await this.instance.server.sendRcon("/sc research_sync.dump_technologies()");
+		let dumpJson = await this.sendRcon("/sc research_sync.dump_technologies()");
 		let techsToSend = [];
 		let instanceTechs = new Map();
 		for (let tech of JSON.parse(dumpJson)) {
@@ -74,7 +72,7 @@ class InstancePlugin extends libPlugin.BaseInstancePlugin {
 
 		if (techsToSync.length) {
 			let syncJson = libLuaTools.escapeString(JSON.stringify(techsToSync));
-			await this.instance.server.sendRcon(`/sc research_sync.sync_technologies("${syncJson}")`, true);
+			await this.sendRcon(`/sc research_sync.sync_technologies("${syncJson}")`, true);
 		}
 	}
 }

plugins/research_sync/master.js

@@ -7,7 +7,7 @@ const libPlugin = require("@clusterio/lib/plugin");
 
 class MasterPlugin extends libPlugin.BaseMasterPlugin {
 	async init() {
-		this.technologies = await loadTechnologies(this.master.config);
+		this.technologies = await loadTechnologies(this.master.config, this.logger);
 		this.lastProgressBroadcast = Date.now();
 		this.progressBroadcastId = null;
 		this.progressToBroadcast = new Set();
@@ -17,7 +17,7 @@ class MasterPlugin extends libPlugin.BaseMasterPlugin {
 		if (this.progressBroadcastId) {
 			clearTimeout(this.progressBroadcastId);
 		}
-		await saveTechnologies(this.master.config, this.technologies);
+		await saveTechnologies(this.master.config, this.technologies, this.logger);
 	}
 
 	registerProgress() {
@@ -159,15 +159,15 @@ class MasterPlugin extends libPlugin.BaseMasterPlugin {
 	}
 }
 
-async function loadTechnologies(masterConfig) {
+async function loadTechnologies(masterConfig, logger) {
 	let filePath = path.join(masterConfig.get("master.database_directory"), "technologies.json");
-	console.log(`Loading ${filePath}`);
+	logger.verbose(`Loading ${filePath}`);
 	try {
 		return new Map(JSON.parse(await fs.readFile(filePath)));
 
 	} catch (err) {
 		if (err.code === "ENOENT") {
-			console.log("Creating new technologies database");
+			logger.verbose("Creating new technologies database");
 			return new Map();
 
 		} else {
@@ -176,9 +176,9 @@ async function loadTechnologies(masterConfig) {
 	}
 }
 
-async function saveTechnologies(masterConfig, technologies) {
+async function saveTechnologies(masterConfig, technologies, logger) {
 	let filePath = path.join(masterConfig.get("master.database_directory"), "technologies.json");
-	console.log(`writing ${filePath}`);
+	logger.verbose(`writing ${filePath}`);
 	await fs.outputFile(filePath, JSON.stringify([...technologies.entries()], null, 4));
 }
 

plugins/research_sync/package.json

@@ -1,6 +1,6 @@
 {
   "name": "@clusterio/plugin-research_sync",
-  "version": "2.0.0-alpha.2",
+  "version": "2.0.0-alpha.3",
   "description": "Clusterio plugin for synchronizing research between Factorio servers",
   "author": "Hornwitser <github@hornwitser.no>",
   "homepage": "https://github.com/clusterio/factorioClusterio#readme",
@@ -20,7 +20,7 @@
     "fs-extra": "^8.1.0"
   },
   "devDependencies": {
-    "@clusterio/web_ui": "^2.0.0-alpha.2",
+    "@clusterio/web_ui": "^2.0.0-alpha.3",
     "babel-loader": "^8.1.0",
     "file-loader": "^6.2.0",
     "null-loader": "^4.0.0",

plugins/statistics_exporter/README.md

@@ -2,7 +2,7 @@ Clusterio Statistics Exporter Plugin
 ====================================
 
 Plugin exporting item production, fluid production, kill count, entity
-build and poluttion statistics to the Prometheus integration to
+build and pollution statistics to the Prometheus integration to
 Clusterio.
 
 

plugins/statistics_exporter/instance.js

@@ -1,6 +1,7 @@
 "use strict";
 const libPlugin = require("@clusterio/lib/plugin");
 const { Gauge } = require("@clusterio/lib/prometheus");
+const libHelpers = require("@clusterio/lib/helpers");
 
 
 const instancePlayerCount = new Gauge(
@@ -20,6 +21,17 @@ const instanceGameFlowStatistics = new Gauge(
 	{ labels: ["instance_id", "statistic", "direction", "name"] },
 );
 
+function setForceFlowStatistic(instanceId, forceName, statisticName, direction, item, value) {
+	instanceForceFlowStatistics.labels(String(instanceId), forceName, statisticName, direction, item).set(value);
+
+	// For item and fluid statistics it's useful to compare the input flow with the
+	// output flow, to simplify the comparison ensure both directions have a value.
+	if (["item_production_statistics", "fluid_production_statistic"].includes(statisticName)) {
+		let reverseDirection = direction === "input" ? "output" : "input";
+		instanceForceFlowStatistics.labels(String(instanceId), forceName, statisticName, reverseDirection, item);
+	}
+}
+
 
 class InstancePlugin extends libPlugin.BaseInstancePlugin {
 	async init() {
@@ -28,8 +40,8 @@ class InstancePlugin extends libPlugin.BaseInstancePlugin {
 		}
 	}
 
-	async onMetrics() {
-		let string = await this.instance.server.sendRcon("/sc statistics_exporter.export()");
+	async gatherMetrics() {
+		let string = await this.sendRcon("/sc statistics_exporter.export()");
 		let stats;
 		try {
 			stats = JSON.parse(string);
@@ -45,9 +57,7 @@ class InstancePlugin extends libPlugin.BaseInstancePlugin {
 			for (let [statisticName, statistic] of Object.entries(flowStatistics)) {
 				for (let [direction, counts] of Object.entries(statistic)) {
 					for (let [item, value] of Object.entries(counts)) {
-						instanceForceFlowStatistics.labels(
-							String(instanceId), forceName, statisticName, direction, item
-						).set(value);
+						setForceFlowStatistic(instanceId, forceName, statisticName, direction, item, value);
 					}
 				}
 			}
@@ -61,6 +71,14 @@ class InstancePlugin extends libPlugin.BaseInstancePlugin {
 			}
 		}
 	}
+
+	async onMetrics() {
+		// Wait up to 5 seconds for the metrics to be collected.  It may
+		// take a long time for the command to go through if the command
+		// stream is overloaded.  Should this take more than 5 seconds the
+		// previous values for the metrics will end up being sent to master.
+		await libHelpers.timeout(this.gatherMetrics(), 5e3);
+	}
 }
 
 module.exports = {

plugins/statistics_exporter/package.json

@@ -1,6 +1,6 @@
 {
   "name": "@clusterio/plugin-statistics_exporter",
-  "version": "2.0.0-alpha.2",
+  "version": "2.0.0-alpha.3",
   "description": "Clusterio plugin for gathering statistics from Factorio servers",
   "author": "Hornwitser <github@hornwitser.no>",
   "homepage": "https://github.com/clusterio/factorioClusterio#readme",
@@ -17,7 +17,7 @@
     "@clusterio/lib": "^2.0.0-alpha.0"
   },
   "devDependencies": {
-    "@clusterio/web_ui": "^2.0.0-alpha.2",
+    "@clusterio/web_ui": "^2.0.0-alpha.3",
     "babel-loader": "^8.1.0",
     "file-loader": "^6.2.0",
     "null-loader": "^4.0.0",

plugins/subspace_storage/dole.js

@@ -103,6 +103,7 @@ function doleDivider({
 	object,
 	items,
 	logItemTransfers,
+	logger,
 }) {
 	let itemCount = items.getItemCount(object.name);
 	// lower rates will equal more dramatic swings
@@ -115,7 +116,7 @@ function doleDivider({
 	object.count /= ((_doleDivisionFactor[object.name] || 0) + doleDivisionRetardation) / doleDivisionRetardation;
 	object.count = Math.round(object.count);
 	if (logItemTransfers) {
-		console.info(
+		logger.verbose(
 			`Serving ${object.count}/${originalCount} ${object.name} from ${itemCount} ${object.name} `+
 			`with dole division factor ${(_doleDivisionFactor[object.name]||0)} `+
 			`(real=${((_doleDivisionFactor[object.name] || 0) + doleDivisionRetardation) / doleDivisionRetardation}), `+

plugins/subspace_storage/instance.js

@@ -4,33 +4,31 @@ const fs = require("fs-extra");
 const libPlugin = require("@clusterio/lib/plugin");
 const libLuaTools = require("@clusterio/lib/lua_tools");
 
-function unexpectedError(err) {
-	console.log("Unexpected error in subspace_storage");
-	console.log("------------------------------------");
-	console.log(err);
-}
-
 class InstancePlugin extends libPlugin.BaseInstancePlugin {
+	unexpectedError(err) {
+		this.logger.error(`Unexpected error:\n${err.stack}`);
+	}
+
 	async init() {
 		this.instance.server.on("ipc-subspace_storage:output", (output) => {
-			this.provideItems(output).catch(unexpectedError);
+			this.provideItems(output).catch(err => this.unexpectedError(err));
 		});
 		this.instance.server.on("ipc-subspace_storage:orders", (orders) => {
-			this.requestItems(orders).catch(unexpectedError);
+			this.requestItems(orders).catch(err => this.unexpectedError(err));
 		});
 	}
 
 	async onStart() {
 		this.pingId = setInterval(() => {
-			this.instance.server.sendRcon(
+			this.sendRcon(
 				"/sc __subspace_storage__ global.ticksSinceMasterPinged = 0", true
-			).catch(unexpectedError);
+			).catch(err => this.unexpectedError(err));
 		}, 5000);
 
 		let response = await this.info.messages.getStorage.send(this.instance);
 		// TODO Diff with dump of invdata produce minimal command to sync
 		let itemsJson = libLuaTools.escapeString(JSON.stringify(response.items));
-		await this.instance.server.sendRcon(`/sc __subspace_storage__ UpdateInvData("${itemsJson}", true)`, true);
+		await this.sendRcon(`/sc __subspace_storage__ UpdateInvData("${itemsJson}", true)`, true);
 	}
 
 	onExit() {
@@ -45,8 +43,8 @@ class InstancePlugin extends libPlugin.BaseInstancePlugin {
 		});
 
 		if (this.instance.config.get("subspace_storage.log_item_transfers")) {
-			console.log("Exported the following to master:");
-			console.log(items);
+			this.logger.verbose("Exported the following to master:");
+			this.logger.verbose(JSON.stringify(items));
 		}
 	}
 
@@ -63,31 +61,23 @@ class InstancePlugin extends libPlugin.BaseInstancePlugin {
 		}
 
 		if (this.instance.config.get("subspace_storage.log_item_transfers")) {
-			console.log("Imported following from master:");
-			console.log(response.items);
+			this.logger.verbose("Imported following from master:");
+			this.logger.verbose(JSON.stringify(response.items));
 		}
 
 		let itemsJson = libLuaTools.escapeString(JSON.stringify(response.items));
-		await this.instance.server.sendRcon(`/sc __subspace_storage__ Import("${itemsJson}")`, true);
+		await this.sendRcon(`/sc __subspace_storage__ Import("${itemsJson}")`, true);
 	}
 
 	// combinator signals ---------------------------------------------------------
 	async updateStorageEventHandler(message, event) {
 		let items = message.data.items;
 
-		// XXX this should be done on the lua side
-		// Ensure counts don't overflow
-		for (let item of items) {
-			if (item[1] > 0x7fffffff) {
-				item[1] = 0x7fffffff;
-			}
-		}
-
 		// XXX this should be moved to instance/clusterio api
 		items.push(["signal-unixtime", Math.floor(Date.now()/1000)]);
 
 		let itemsJson = libLuaTools.escapeString(JSON.stringify(items));
-		await this.instance.server.sendRcon(`/sc __subspace_storage__ UpdateInvData("${itemsJson}")`, true);
+		await this.sendRcon(`/sc __subspace_storage__ UpdateInvData("${itemsJson}")`, true);
 	}
 }
 

plugins/subspace_storage/master.js

@@ -30,13 +30,11 @@ const masterInventoryGauge = new Gauge(
 class MasterPlugin extends libPlugin.BaseMasterPlugin {
 	async init() {
 
-		this.items = await loadDatabase(this.master.config);
+		this.items = await loadDatabase(this.master.config, this.logger);
 		this.itemsLastUpdate = new Map(this.items._items.entries());
 		this.autosaveId = setInterval(() => {
-			saveDatabase(this.master.config, this.items).catch(err => {
-				console.log("Unexpected error autosaving items in subspace_storage");
-				console.log("-----------------------------------------------------");
-				console.log(err);
+			saveDatabase(this.master.config, this.items, this.logger).catch(err => {
+				this.logger.error(`Unexpected error autosaving items:\n${err.stack}`);
 			});
 		}, this.master.config.get("subspace_storage.autosave_interval") * 1000);
 
@@ -83,8 +81,9 @@ class MasterPlugin extends libPlugin.BaseMasterPlugin {
 		this.updateStorage();
 
 		if (this.master.config.get("subspace_storage.log_item_transfers")) {
-			console.log(`Imported the following from ${message.data.instance_id}:`);
-			console.log(message.data.items);
+			this.logger.verbose(
+				`Imported the following from ${message.data.instance_id}:\n${JSON.stringify(message.data.items)}`
+			);
 		}
 	}
 
@@ -125,6 +124,7 @@ class MasterPlugin extends libPlugin.BaseMasterPlugin {
 						object: { name: item[0], count: item[1], instanceId, instanceName },
 						items: this.items,
 						logItemTransfers: this.master.config.get("subspace_storage.log_item_transfers"),
+						logger: this.logger,
 					});
 					if (count > 0) {
 						itemsRemoved.push([item[0], count]);
@@ -145,8 +145,7 @@ class MasterPlugin extends libPlugin.BaseMasterPlugin {
 			this.updateStorage();
 
 			if (itemsRemoved.length && this.master.config.get("subspace_storage.log_item_transfers")) {
-				console.log(`Exported the following to ${instanceId}`);
-				console.log(itemsRemoved);
+				this.logger.verbose(`Exported the following to ${instanceId}:\n${JSON.stringify(itemsRemoved)}`);
 			}
 		}
 
@@ -166,20 +165,20 @@ class MasterPlugin extends libPlugin.BaseMasterPlugin {
 	async onShutdown() {
 		clearInterval(this.autosaveId);
 		clearInterval(this.doleMagicId);
-		await saveDatabase(this.master.config, this.items);
+		await saveDatabase(this.master.config, this.items, this.logger);
 	}
 }
 
-async function loadDatabase(config) {
+async function loadDatabase(config, logger) {
 	let itemsPath = path.resolve(config.get("master.database_directory"), "items.json");
-	console.log(`Loading ${itemsPath}`);
+	logger.verbose(`Loading ${itemsPath}`);
 	try {
 		let content = await fs.readFile(itemsPath);
 		return new libDatabase.ItemDatabase(JSON.parse(content));
 
 	} catch (err) {
 		if (err.code === "ENOENT") {
-			console.log("Creating new item database");
+			logger.verbose("Creating new item database");
 			return new libDatabase.ItemDatabase();
 
 		} else {
@@ -188,14 +187,14 @@ async function loadDatabase(config) {
 	}
 }
 
-async function saveDatabase(masterConfig, items) {
+async function saveDatabase(masterConfig, items, logger) {
 	if (items && items.size < 50000) {
 		let file = path.resolve(masterConfig.get("master.database_directory"), "items.json");
-		console.log(`writing ${file}`);
+		logger.verbose(`writing ${file}`);
 		let content = JSON.stringify(items.serialize());
 		await fs.outputFile(file, content);
 	} else if (items) {
-		console.error(`Item database too large, not saving (${items.size})`);
+		logger.error(`Item database too large, not saving (${items.size})`);
 	}
 }
 

plugins/subspace_storage/package.json

@@ -1,6 +1,6 @@
 {
   "name": "@clusterio/plugin-subspace_storage",
-  "version": "2.0.0-alpha.2",
+  "version": "2.0.0-alpha.3",
   "description": "Clusterio plugin for sharing storage between Factorio servers",
   "author": "Hornwitser <github@hornwitser.no>",
   "homepage": "https://github.com/clusterio/clusterio#readme",
@@ -20,7 +20,7 @@
     "fs-extra": "^8.1.0"
   },
   "devDependencies": {
-    "@clusterio/web_ui": "^2.0.0-alpha.2",
+    "@clusterio/web_ui": "^2.0.0-alpha.3",
     "antd": "^4.6.5",
     "babel-loader": "^8.1.0",
     "file-loader": "^6.2.0",

test/ctl.js

@@ -1,19 +1,8 @@
 "use strict";
 const assert = require("assert").strict;
 
-const { testLines } = require("./lib/factorio/lines");
 const clusterioctl = require("@clusterio/ctl/ctl.js");
 
 
 describe("clusterioctl", function() {
-	describe("formatOutputColored()", function() {
-		it("should pass the test lines", function() {
-			for (let [reference, output] of testLines) {
-				let line = clusterioctl._formatOutputColored(output);
-				// Strip colours
-				line = line.replace(/\x1B\[\d+m/g, "");
-				assert.deepEqual(line, reference);
-			}
-		});
-	});
 });

test/integration/clusterio.js

@@ -185,6 +185,10 @@ describe("Integration of Clusterio", function() {
 					assert.equal(await sendRcon(44, `/config get ${configName}`), `${expectedResult}\n`);
 				}
 			});
+			it("should not change the instance status", async function() {
+				slowTest(this);
+				await checkInstanceStatus(44, "running");
+			});
 		});
 
 		describe("user set-admin/whitelisted/banned", function() {
@@ -312,7 +316,7 @@ describe("Integration of Clusterio", function() {
 
 		describe("user set-roles", function() {
 			it("should set the roles on the user", async function() {
-				await execCtl("user set-roles temp Admin");
+				await execCtl('user set-roles temp "Cluster Admin"');
 				let result = await libLink.messages.listUsers.send(getControl());
 				let tempUser = result.list.find(user => user.name === "temp");
 				assert.deepEqual(tempUser.roles, [0]);

test/integration/index.js

@@ -1,3 +1,4 @@
+/* eslint-disable no-console */
 "use strict";
 const path = require("path");
 const fs = require("fs-extra");
@@ -9,6 +10,8 @@ const events = require("events");
 
 const libLink = require("@clusterio/lib/link");
 const server = require("@clusterio/lib/factorio/server");
+const { ConsoleTransport, logger } = require("@clusterio/lib/logging");
+const libLoggingUtils = require("@clusterio/lib/logging_utils");
 
 
 class TestControl extends libLink.Link {
@@ -24,7 +27,7 @@ class TestControl extends libLink.Link {
 
 	async debugWsMessageEventHandler() { }
 
-	async instanceOutputEventHandler() { }
+	async logMessageEventHandler() { }
 }
 
 class TestControlConnector extends libLink.WebSocketClientConnector {
@@ -96,7 +99,7 @@ function spawn(name, cmd, waitFor) {
 		let process = child_process.spawn(parts[0], parts.slice(1), { cwd: path.join("temp", "test") });
 		let stdout = new server._LineSplitter((line) => {
 			line = line.toString("utf8");
-			if (line.startsWith(waitFor)) {
+			if (waitFor.test(line)) {
 				resolve(process);
 			}
 			console.log(name, line);
@@ -112,6 +115,12 @@ function spawn(name, cmd, waitFor) {
 before(async function() {
 	this.timeout(20000);
 
+	// Some integration tests may cause log events
+	logger.add(new ConsoleTransport({
+		level: "info",
+		format: new libLoggingUtils.TerminalFormat(),
+	}));
+
 	await fs.remove(databaseDir);
 	await fs.remove(instancesDir);
 
@@ -137,13 +146,13 @@ before(async function() {
 	await exec("node ../../packages/master bootstrap create-admin test");
 	await exec("node ../../packages/master bootstrap create-ctl-config test");
 
-	masterProcess = await spawn("master:", "node ../../packages/master run", "All plugins loaded");
+	masterProcess = await spawn("master:", "node ../../packages/master run", /All plugins loaded/);
 
 	let createArgs = "--id 4 --name slave --generate-token";
 	await execCtl(`slave create-config ${createArgs}`);
 
 	await exec(`node ../../packages/slave config set slave.factorio_directory ${path.join("..", "..", "factorio")}`);
-	slaveProcess = await spawn("slave:", "node ../../packages/slave run", "SOCKET | received ready from master");
+	slaveProcess = await spawn("slave:", "node ../../packages/slave run", /SOCKET \| registering slave/);
 
 	let controlConnector = new TestControlConnector(url, 2);
 	controlConnector.token = controlToken;

test/lib/factorio/lines.js

@@ -143,6 +143,51 @@ let testLines = new Map([
 			message: "Saving finished",
 		},
 	],
+	[
+		"   1.277 Script @/srv/clusterio/instances/test/temp/currently-playing/modules/example/test.lua:7: " +
+		"Example log line.",
+		{
+			format: "seconds",
+			time: "1.277",
+			type: "log",
+			level: "Script",
+			file: "@/srv/clusterio/instances/test/temp/currently-playing/modules/example/test.lua:7",
+			message: "Example log line.",
+		},
+	],
+	[
+		"   1.277 Script @C:\\My Cluster\\temp\\current-save\\file.lua:7: Contrived :12: example",
+		{
+			format: "seconds",
+			time: "1.277",
+			type: "log",
+			level: "Script",
+			file: "@C:\\My Cluster\\temp\\current-save\\file.lua:7",
+			message: "Contrived :12: example",
+		},
+	],
+	[
+		" 344.683 Script =(command):1: test",
+		{
+			format: "seconds",
+			time: "344.683",
+			type: "log",
+			level: "Script",
+			file: "=(command):1",
+			message: "test",
+		},
+	],
+	[
+		"   0.751 Verbose ModManager.cpp:554: Time to load mods: 0.746762",
+		{
+			format: "seconds",
+			time: "0.751",
+			type: "log",
+			level: "Verbose",
+			file: "ModManager.cpp:554",
+			message: "Time to load mods: 0.746762",
+		},
+	],
 ]);
 
 module.exports = {

test/lib/factorio/server.js

@@ -160,7 +160,6 @@ describe("lib/factorio/server", function() {
 			for (let [line, reference] of testLines) {
 				reference.source = "test";
 				let output = libFactorio._parseOutput(line, "test");
-				delete output.received;
 				assert.deepEqual(output, reference);
 			}
 		});
@@ -170,6 +169,17 @@ describe("lib/factorio/server", function() {
 		let writePath = path.join("temp", "test", "server");
 		let server = new libFactorio.FactorioServer(path.join("test", "file", "factorio"), writePath, {});
 
+		describe("constructor()", function() {
+			it("should handle dashes in write path with strapPaths enabled", function() {
+				// eslint-disable-next-line no-new
+				new libFactorio.FactorioServer(
+					path.join("test", "file", "factorio"),
+					path.join("temp", "test", "server-1"),
+					{ stripPaths: true }
+				);
+			});
+		});
+
 		describe(".init()", function() {
 			it("should not throw on first call", async function() {
 				await server.init();

test/lib/helpers.js

@@ -1,5 +1,6 @@
 "use strict";
 const assert = require("assert").strict;
+const hrtime = process.hrtime.bigint;
 
 const libHelpers = require("@clusterio/lib/helpers");
 
@@ -15,4 +16,30 @@ describe("lib/helpers", function() {
 			assert.equal(libHelpers.basicType({ a: 1 }), "object");
 		});
 	});
+
+	describe("wait", function() {
+		it("should wait the approximate amount of time given", async function() {
+			let startNs = hrtime();
+			await libHelpers.wait(100);
+			let duration = Number(hrtime() - startNs) / 1e6;
+
+			assert(duration > 90 && duration < 110, `duration waited (${duration}ms) 10% of expected (100ms)`);
+		});
+	});
+
+	describe("timeout", function() {
+		it("should return the result of an already resolved promise", async function() {
+			assert.equal(await libHelpers.timeout(Promise.resolve("value"), 10, "timeout"), "value");
+		});
+		it("should return the result of the promise if received before timeout", async function() {
+			assert.equal(await libHelpers.timeout(
+				(async () => { await libHelpers.wait(10); return "value"; })(), 20, "timeout"
+			), "value");
+		});
+		it("should return the timeoutResult if not received before timeout", async function() {
+			assert.equal(await libHelpers.timeout(
+				(async () => { await libHelpers.wait(20); return "value"; })(), 10, "timeout"
+			), "timeout");
+		});
+	});
 });

test/lib/link/link.js

@@ -35,6 +35,16 @@ describe("lib/link/link", function() {
 			await assert.rejects(result, new Error("Handler error"));
 		});
 
+		it("should give an error response back on an unhandled request", function() {
+			testConnector.sentMessages = [];
+			testConnector.emit("message", { seq: 1, type: "unhandled_request", data: {}});
+			assert.deepEqual(testConnector.sentMessages, [{
+				type: "unhandled_response",
+				seq: testConnector._seq - 1,
+				data: { seq: 1, error: "No validator for unhandled_request on source-target" },
+			}]);
+		});
+
 		describe(".setValidator()", function() {
 			it("should set the validator", function() {
 				testLink.setValidator("test", () => true);

test/lib/logging_utils.js

@@ -0,0 +1,19 @@
+"use strict";
+const assert = require("assert").strict;
+
+const { testLines } = require("./factorio/lines");
+const libLoggingUtils = require("@clusterio/lib/logging_utils");
+
+
+describe("lib/logging_utils.js", function() {
+	describe("formatServerOutput", function() {
+		it("should pass the test lines", function() {
+			for (let [reference, output] of testLines) {
+				let line = libLoggingUtils._formatServerOutput(output);
+				// Strip colours
+				line = line.replace(/\x1B\[\d+m/g, "");
+				assert.deepEqual(line, reference);
+			}
+		});
+	});
+});

test/lib/plugin.js

@@ -10,7 +10,7 @@ describe("lib/plugin", function() {
 	describe("class BaseInstancePlugin", function() {
 		let instancePlugin;
 		it("should be constructible", async function() {
-			instancePlugin = new libPlugin.BaseInstancePlugin();
+			instancePlugin = new libPlugin.BaseInstancePlugin({}, { logger: new mock.MockLogger() }, {});
 			await instancePlugin.init();
 		});
 		it("should define defaults for hooks", async function() {
@@ -27,7 +27,7 @@ describe("lib/plugin", function() {
 	describe("class BaseMasterPlugin", function() {
 		let masterPlugin;
 		it("should be constructible", async function() {
-			masterPlugin = new libPlugin.BaseMasterPlugin();
+			masterPlugin = new libPlugin.BaseMasterPlugin({}, {}, {}, new mock.MockLogger());
 			await masterPlugin.init();
 		});
 		it("should define defaults for hooks", async function() {
@@ -55,7 +55,7 @@ describe("lib/plugin", function() {
 		it("should throw if missing handler for the given message", function() {
 			assert.throws(
 				() => libPlugin.attachPluginMessages(mockLink, { name: "test", messages: { mockEvent }}, {}),
-				new Error("Missing handler for test:test_event on source-target link")
+				new Error("Missing mockEventEventHandler on plugin test for test:test_event on source-target link")
 			);
 		});
 		it("should throw if message starts with the wrong prefix", function() {
@@ -73,11 +73,13 @@ describe("lib/plugin", function() {
 				test: async function() { },
 				pass: async function(arg) { return arg; },
 				error: async function() { throw new Error("Test"); },
+				logger: new mock.MockLogger(),
 			}],
 			["beta", {
 				test: async function() { betaTestCalled = true; },
 				pass: async function() { },
 				error: async function() { },
+				logger: new mock.MockLogger(),
 			}],
 		]);
 		it("should invoke the hook on the plugin", async function() {

test/lib/prometheus.js

@@ -198,9 +198,206 @@ describe("lib/prometheus", function() {
 				);
 			});
 		});
+		describe(".startTimer()", function() {
+			it("should set the gauge to a short duration", function() {
+				let setDuration = gauge.startTimer();
+				setDuration();
+				assert(
+					gauge._values.get("") > 0 && gauge._values.get("") < 1,
+					"value set is not between 0 and 1"
+				);
+			});
+		});
+	});
+
+	describe("class Histogram", function() {
+		let histogram;
+		let labeledHistogram;
+		beforeEach(function() {
+			histogram = new prometheus.Histogram(
+				"test", "Help", { register: false, buckets: [1, 2, 3, 4, Infinity] }
+			);
+			labeledHistogram = new prometheus.Histogram(
+				"test", "Help", { register: false, buckets: [1, Infinity], labels: ["a", "b"] }
+			);
+		});
+
+		describe("constructor", function() {
+			it("should have buckets, sum and count initialized to 0", function() {
+				assert.deepEqual(
+					histogram.buckets,
+					new Map([[1, 0], [2, 0], [3, 0], [4, 0], [Infinity, 0]])
+				);
+				assert.equal(histogram.sum, 0);
+				assert.equal(histogram.count, 0);
+			});
+			it("should provide a default for buckets", function() {
+				histogram = new prometheus.Histogram(
+					"test", "help", { register: false }
+				);
+				assert(histogram._buckets.length, "no default buckets were made");
+			});
+			it("should add inifinity bucket if not present", function() {
+				histogram = new prometheus.Histogram(
+					"test", "help", { buckets: [1], register: false }
+				);
+				assert.deepEqual(histogram._buckets, [1, Infinity]);
+			});
+			it("should not mutate bucket option passed to it", function() {
+				let buckets = [1];
+				histogram = new prometheus.Histogram(
+					"test", "help", { buckets, register: false }
+				);
+				assert.deepEqual(buckets, [1]);
+			});
+			it("should throw on unrecoginzed option", function() {
+				assert.throws(
+					() => new prometheus.Histogram("test", "help", { invalid: 1 }),
+					new Error("Unrecognized option 'invalid'")
+				);
+			});
+			it("should throw on using le as label", function() {
+				assert.throws(() => {
+					let test = new prometheus.Histogram(
+						"test", "Help", { register: false, labels: ["le", "test"] }
+					);
+				}, new Error("Reserved label 'le'"));
+			});
+		});
+
+		describe(".observe()", function() {
+			it("should increment the appropriate bucket", function() {
+				histogram.observe(2);
+				assert.deepEqual(
+					histogram.buckets,
+					new Map([[1, 0], [2, 1], [3, 1], [4, 1], [Infinity, 1]])
+				);
+				assert.equal(histogram.sum, 2);
+				assert.equal(histogram.count, 1);
+
+				histogram.observe(4);
+				assert.deepEqual(
+					histogram.buckets,
+					new Map([[1, 0], [2, 1], [3, 1], [4, 2], [Infinity, 2]])
+				);
+				assert.equal(histogram.sum, 6);
+				assert.equal(histogram.count, 2);
+			});
+		});
+
+		describe(".startTimer()", function() {
+			it("should add observations when closure is called", function() {
+				let observeDuration = histogram.startTimer();
+				assert.equal(histogram.count, 0);
+				observeDuration();
+				assert.equal(histogram.count, 1);
+				observeDuration();
+				assert.equal(histogram.count, 2);
+			});
+		});
+
+		describe("static .linear()", function() {
+			it("should give back the appropriate buckets", function() {
+				let linear = prometheus.Histogram.linear;
+				assert.deepEqual(linear(1, 2, 3), [1, 3, 5]);
+				assert.deepEqual(linear(-1, 4, 3), [-1, 3, 7]);
+				assert.deepEqual(linear(1, 1, 4), [1, 2, 3, 4]);
+			});
+		});
+
+		describe("static .exponential()", function() {
+			it("should give back the appropriate buckets", function() {
+				let exponential = prometheus.Histogram.exponential;
+				assert.deepEqual(exponential(1, 2, 3), [1, 2, 4]);
+				assert.deepEqual(exponential(2, 10, 3), [2, 20, 200]);
+				assert.deepEqual(exponential(1, 1.5, 4), [1, 1.5, 2.25, 3.375]);
+			});
+		});
+
+		describe(".labels()", function() {
+			it("should initialize a value for the label set", function() {
+				labeledHistogram.labels({ a: "1", b: "2" });
+				assert(labeledHistogram._bucketValues.has('a="1",b="2",le="1"'), "bucket value not set");
+				assert(labeledHistogram._bucketValues.has('a="1",b="2",le="+Inf"'), "bucket value not set");
+				assert(labeledHistogram._sumValues.has('a="1",b="2"'), "sum value not set");
+				assert(labeledHistogram._countValues.has('a="1",b="2"'), "count value not set");
+
+				labeledHistogram.labels("4", "5");
+				assert(labeledHistogram._bucketValues.has('a="4",b="5",le="1"'), "bucket value not set");
+				assert(labeledHistogram._bucketValues.has('a="4",b="5",le="+Inf"'), "bucket value not set");
+				assert(labeledHistogram._sumValues.has('a="4",b="5"'), "sum value not set");
+				assert(labeledHistogram._countValues.has('a="4",b="5"'), "count value not set");
+			});
+			it("should return a child supporting the histogram methods", function() {
+				let child = labeledHistogram.labels({ a: "1", b: "2" });
+				void child.buckets;
+				void child.sum;
+				void child.count;
+				child.observe(2);
+				let observeDuration = child.startTimer();
+				observeDuration();
+				child = labeledHistogram.labels("7", "8");
+				void child.buckets;
+				void child.sum;
+				void child.count;
+				child.observe(2);
+				observeDuration = child.startTimer();
+				observeDuration();
+			});
+			it("should return the same child for the same labels", function() {
+				let child = labeledHistogram.labels("1", "2");
+				assert.equal(labeledHistogram.labels("1", "2"), child);
+				assert.equal(labeledHistogram.labels({ a: "1", b: "2" }), child);
+			});
+		});
+		describe(".remove()", function() {
+			it("should remove a label set created with .labels()", function() {
+				labeledHistogram.labels("1", "2");
+				labeledHistogram.remove("1", "2");
+				assert(!labeledHistogram._bucketValues.has('a="1",b="2",le="1"'), "bucket value not removed");
+				assert(!labeledHistogram._bucketValues.has('a="1",b="2",le="+Inf"'), "bucket value not removed");
+				assert(!labeledHistogram._sumValues.has('a="1",b="2"'), "sum value not removed");
+				assert(!labeledHistogram._countValues.has('a="1",b="2"'), "count value not removed");
+			});
+		});
+		describe(".removeAll()", function() {
+			it("should remove a label set created with .labels()", function() {
+				labeledHistogram.labels("1", "2");
+				labeledHistogram.labels("1", "3");
+				labeledHistogram.labels("4", "6");
+				labeledHistogram.removeAll({ a: "1" });
+				assert.deepEqual(
+					labeledHistogram._bucketValues,
+					new Map([['a="4",b="6",le="1"', 0], ['a="4",b="6",le="+Inf"', 0]])
+				);
+				assert.deepEqual(labeledHistogram._sumValues, new Map([['a="4",b="6"', 0]]));
+				assert.deepEqual(labeledHistogram._countValues, new Map([['a="4",b="6"', 0]]));
+			});
+		});
+		describe(".clear()", function() {
+			it("should remove all label sets created with .labels()", function() {
+				labeledHistogram.labels("1", "2");
+				labeledHistogram.labels("1", "3");
+				labeledHistogram.labels("4", "6");
+				labeledHistogram.clear();
+				assert(labeledHistogram._bucketValues.size === 0, "buckets were not cleared");
+				assert(labeledHistogram._sumValues.size === 0, "sums were not cleared");
+				assert(labeledHistogram._countValues.size === 0, "counts were not cleared");
+			});
+		});
 	});
 
 	describe("class ValueCollector", function() {
+		describe(".get()", function() {
+			it("should return the current value", function() {
+				let gauge = new prometheus.Gauge("test", "Help", { register: false });
+				gauge.set(11);
+				assert.equal(gauge.get(), 11);
+			});
+		});
+	});
+
+	describe("class LabeledCollector", function() {
 		describe("constructor", function() {
 			it("should throw on invalid metric name", function() {
 				for (let name of ["", " ", "0a", "$a"]) {
@@ -242,14 +439,6 @@ describe("lib/prometheus", function() {
 			});
 		});
 
-		describe(".get()", function() {
-			it("should return the current value", function() {
-				let gauge = new prometheus.Gauge("test", "Help", { register: false });
-				gauge.set(11);
-				assert.equal(gauge.get(), 11);
-			});
-		});
-
 		describe(".labels()", function() {
 			let gauge;
 			beforeEach(function() {
@@ -310,6 +499,7 @@ describe("lib/prometheus", function() {
 			it("should return the same child for the same labels", function() {
 				let child = gauge.labels("1", "2");
 				assert.equal(gauge.labels("1", "2"), child);
+				assert.equal(gauge.labels({ a: "1", b: "2" }), child);
 			});
 		});
 		describe(".remove()", function() {
@@ -393,8 +583,9 @@ describe("lib/prometheus", function() {
 					"collector did not give exactly one result"
 				);
 
+				let value = results[0].samples.get("").get("");
 				assert(
-					Math.abs(results[0].samples.get("") - Date.now() / 1000) < 1,
+					Math.abs(value - Date.now() / 1000) < 1,
 					"value set is not close to the current unix time"
 				);
 			});
@@ -413,7 +604,7 @@ describe("lib/prometheus", function() {
 					"collector did not give exactly one result"
 				);
 
-				let value = results[0].samples.get("");
+				let value = results[0].samples.get("").get("");
 				assert(
 					value < 5 && value > 0,
 					`process time is not between 0 and 5 seconds (${value})`
@@ -434,7 +625,7 @@ describe("lib/prometheus", function() {
 					"collector did not give exactly one result"
 				);
 
-				let value = results[0].samples.get("");
+				let value = results[0].samples.get("").get("");
 				assert(
 					value < 200e6 && value > 0,
 					`resident memory is not between 0 and 200 MB (${value})`
@@ -455,7 +646,7 @@ describe("lib/prometheus", function() {
 					"collector did not give exactly one result"
 				);
 
-				let value = results[0].samples.get("");
+				let value = results[0].samples.get("").get("");
 				assert(
 					value < 200e6 && value > 0,
 					`heap is not between 0 and 200 MB (${value})`
@@ -500,6 +691,59 @@ describe("lib/prometheus", function() {
 				'test{a="x",b="y"} 0\n'
 			);
 		});
+		it("should format histogram metrics", async function() {
+			let registry = new prometheus.CollectorRegistry();
+			let histogram = new prometheus.Histogram(
+				"test", "Help", { register: false, buckets: [1, 2, 3, 4] }
+			);
+			for (let value of [2, 2, 5, 2]) {
+				histogram.observe(value);
+			}
+			registry.register(histogram);
+			let exposition = await prometheus.exposition(registry.collect());
+			assert.equal(
+				exposition,
+				"# HELP test Help\n" +
+				"# TYPE test histogram\n" +
+				'test_bucket{le="1"} 0\n' +
+				'test_bucket{le="2"} 3\n' +
+				'test_bucket{le="3"} 3\n' +
+				'test_bucket{le="4"} 3\n' +
+				'test_bucket{le="+Inf"} 4\n' +
+				"test_sum 11\n" +
+				"test_count 4\n"
+			);
+		});
+		it("should format histogram metrics with labels", async function() {
+			let registry = new prometheus.CollectorRegistry();
+			let histogram = new prometheus.Histogram(
+				"test", "Help", { register: false, buckets: [1], labels: ["l"] }
+			);
+			for (let [value, label] of [[1, "a"], [2, "b"], [3, "b"]]) {
+				histogram.labels(label).observe(value);
+			}
+			histogram.labels("c");
+
+			registry.register(histogram);
+			let exposition = await prometheus.exposition(registry.collect());
+			assert.equal(
+				exposition,
+				"# HELP test Help\n" +
+				"# TYPE test histogram\n" +
+				'test_bucket{l="a",le="1"} 1\n' +
+				'test_bucket{l="a",le="+Inf"} 1\n' +
+				'test_bucket{l="b",le="1"} 0\n' +
+				'test_bucket{l="b",le="+Inf"} 2\n' +
+				'test_bucket{l="c",le="1"} 0\n' +
+				'test_bucket{l="c",le="+Inf"} 0\n' +
+				'test_sum{l="a"} 1\n' +
+				'test_sum{l="b"} 5\n' +
+				'test_sum{l="c"} 0\n' +
+				'test_count{l="a"} 1\n' +
+				'test_count{l="b"} 2\n' +
+				'test_count{l="c"} 0\n'
+			);
+		});
 		it("should format Infinity and NaN", async function() {
 			let registry = new prometheus.CollectorRegistry();
 			let gauge = new prometheus.Gauge(
@@ -523,38 +767,64 @@ describe("lib/prometheus", function() {
 
 	let serializedResult = {
 		metric: { type: "type", name: "name", help: "Help", labels: ["a", "b"] },
-		samples: [['a="1",b="2"', 1], ['a="3",b="4"', 5]],
+		samples: [["", [['a="1",b="2"', 1], ['a="3",b="4"', 5]]]],
 	};
 	let deserializedResult = {
 		metric: new prometheus.Metric("type", "name", "Help", ["a", "b"]),
-		samples: new Map([['a="1",b="2"', 1], ['a="3",b="4"', 5]]),
+		samples: new Map([["", new Map([['a="1",b="2"', 1], ['a="3",b="4"', 5]])]]),
 	};
 	describe("serializeResult()", function() {
-		it("should convert a result into plain object", function() {
+		it("should convert real results into the reference serialization", async function() {
+			let counter = new prometheus.Counter("a_counter", "Counter", { register: false });
+			let gauge = new prometheus.Gauge("a_gauge", "Gauge", { register: false, labels: ["a", "b"] });
+			let registry = new prometheus.CollectorRegistry();
+			registry.register(counter);
+			registry.register(gauge);
+
+			counter.inc(3);
+			gauge.labels("1", "2").set(1);
+			gauge.labels("3", "4").set(5);
+
+			let results = [];
+			for await (let result of registry.collect()) {
+				results.push(result);
+			}
+
+			let referenceSerialization = [
+				{
+					metric: { type: "counter", name: "a_counter", help: "Counter", labels: [] },
+					samples: [["", [["", 3]]]],
+				},
+				{
+					metric: { type: "gauge", name: "a_gauge", help: "Gauge", labels: ["a", "b"] },
+					samples: [["", [['a="1",b="2"', 1], ['a="3",b="4"', 5]]]],
+				},
+			];
+
 			assert.deepEqual(
-				prometheus.serializeResult(deserializedResult),
-				serializedResult
+				results.map(result => prometheus.serializeResult(result)),
+				referenceSerialization
 			);
 		});
 		it("should support adding labels", function() {
 			assert.deepEqual(
 				prometheus.serializeResult({
 					metric: new prometheus.Metric("type", "name", "Help"),
-					samples: new Map([["", 2]]),
+					samples: new Map([["name", new Map([["", 2]])]]),
 				}, { addLabels: { c: "8" }}),
 				{
 					metric: { type: "type", name: "name", help: "Help", labels: ["c"] },
-					samples: [['c="8"', 2]],
+					samples: [["name", [['c="8"', 2]]]],
 				}
 			);
 			assert.deepEqual(
 				prometheus.serializeResult({
 					metric: new prometheus.Metric("type", "name", "Help", ["a"]),
-					samples: new Map([['a="4"', 3]]),
+					samples: new Map([["", new Map([['a="4"', 3]])]]),
 				}, { addLabels: { c: "8" }}),
 				{
 					metric: { type: "type", name: "name", help: "Help", labels: ["a", "c"] },
-					samples: [['a="4",c="8"', 3]],
+					samples: [["", [['a="4",c="8"', 3]]]],
 				}
 			);
 		});
@@ -562,21 +832,21 @@ describe("lib/prometheus", function() {
 			assert.deepEqual(
 				prometheus.serializeResult({
 					metric: new prometheus.Metric("type", "name", "Help"),
-					samples: new Map([["", 2]]),
+					samples: new Map([["", new Map([["", 2]])]]),
 				}, { metricName: "new" }),
 				{
 					metric: { type: "type", name: "new", help: "Help", labels: [] },
-					samples: [["", 2]],
+					samples: [["", [["", 2]]]],
 				}
 			);
 			assert.deepEqual(
 				prometheus.serializeResult({
 					metric: new prometheus.Metric("type", "name", "Help"),
-					samples: new Map([["", 2]]),
+					samples: new Map([["", new Map([["", 2]])]]),
 				}, { metricHelp: "old" }),
 				{
 					metric: { type: "type", name: "name", help: "old", labels: [] },
-					samples: [["", 2]],
+					samples: [["", [["", 2]]]],
 				}
 			);
 		});
@@ -584,7 +854,7 @@ describe("lib/prometheus", function() {
 			assert.throws(
 				() => prometheus.serializeResult({
 					metric: new prometheus.Metric("type", "name", "Help"),
-					samples: new Map([["", 3]]),
+					samples: new Map([["", new Map([["", 3]])]]),
 				}, { invalid: true }),
 				new Error("Unrecognized option 'invalid'")
 			);
@@ -600,6 +870,34 @@ describe("lib/prometheus", function() {
 		});
 	});
 
+	describe("integration", function() {
+		it("should round trip serialize histogram results", async function() {
+			let registry = new prometheus.CollectorRegistry();
+			let histogram = new prometheus.Histogram(
+				"test", "Help", { register: false, buckets: [1], labels: ["l"] }
+			);
+			for (let [value, label] of [[1, "a"], [2, "b"], [3, "b"]]) {
+				histogram.labels(label).observe(value);
+			}
+			histogram.labels("c");
+
+			registry.register(histogram);
+			let results = [];
+			for await (let result of registry.collect()) {
+				results.push(result);
+			}
+			let exposition = await prometheus.exposition(results);
+
+			let serialized = results.map(res => prometheus.serializeResult(res));
+			let jsonRoundtrip = JSON.parse(JSON.stringify(serialized));
+			let deserialized = jsonRoundtrip.map(res => prometheus.deserializeResult(res));
+			assert.deepEqual(deserialized, results);
+			let roundTripExposition = await prometheus.exposition(deserialized);
+
+			assert.equal(roundTripExposition, exposition);
+		});
+	});
+
 	describe("post test checks", function() {
 		it("should not have any collectors in the default registry", function() {
 			this.skip(); // XXX Doesn't work in Clusterio's shared testing env

test/master/generate_ssl_cert.js

@@ -25,7 +25,6 @@ describe("generate_ssl_cert", function() {
 			bits: 512, // This is too small for real world usage, but faster to test
 			sslCertPath: certPath,
 			sslPrivKeyPath: privKeyPath,
-			doLogging: false,
 		});
 
 		assert(await fs.exists(certPath), "cert file was not created");

test/mock.js

@@ -4,6 +4,24 @@ const events = require("events");
 const libLink = require("@clusterio/lib/link");
 
 
+class MockLogger {
+	child() { return this; }
+
+	fatal() { }
+
+	error() { }
+
+	warn() { }
+
+	audit() { }
+
+	info() { }
+
+	server() { }
+
+	verbose() { }
+}
+
 class MockSocket {
 	constructor() {
 		this.sentMessages = [];
@@ -82,6 +100,7 @@ class MockServer {
 class MockInstance extends libLink.Link {
 	constructor() {
 		super("instance", "slave", new MockConnector());
+		this.logger = new MockLogger();
 		this.server = new MockServer();
 		this.name = "test";
 		this.config = {
@@ -92,6 +111,10 @@ class MockInstance extends libLink.Link {
 			},
 		};
 	}
+
+	async sendRcon(command, expectEmpty, plugin) {
+		return await this.server.sendRcon(command);
+	}
 }
 
 class MockSlave extends libLink.Link {
@@ -108,6 +131,7 @@ class MockControl extends libLink.Link {
 
 
 module.exports = {
+	MockLogger,
 	MockSocket,
 	MockConnector,
 	MockInstance,

test/slave.js

@@ -85,10 +85,6 @@ describe("Slave testing", function() {
 
 	describe("symlinkMods()", function() {
 		let testDir = path.join("temp", "test", "symlink");
-		let discardingLogger = {
-			warn: function() { },
-			log: function() { },
-		};
 
 		let instance;
 		before(async function() {
@@ -110,7 +106,7 @@ describe("Slave testing", function() {
 		});
 
 		it("should link mods and data files", async function() {
-			await slave._symlinkMods(instance, path.join(testDir, "shared"), discardingLogger);
+			await slave._symlinkMods(instance, path.join(testDir, "shared"));
 
 			assert.equal(await fs.readFile(instance.path("mods", "mod_a.zip"), "utf-8"), "a");
 			assert.equal(await fs.readFile(instance.path("mods", "mod_b.zip"), "utf-8"), "b");
@@ -120,14 +116,14 @@ describe("Slave testing", function() {
 
 		it("should ignore directories", async function() {
 			await fs.ensureDir(path.join(testDir, "shared", "dir"));
-			await slave._symlinkMods(instance, path.join(testDir, "shared"), discardingLogger);
+			await slave._symlinkMods(instance, path.join(testDir, "shared"));
 
 			assert(!await fs.exists(instance.path("mods", "dir"), "utf-8"), "dir was unxpectedly linked");
 		});
 
 		it("should ignore files", async function() {
 			await fs.outputFile(path.join(testDir, "shared", "file"), "f");
-			await slave._symlinkMods(instance, path.join(testDir, "shared"), discardingLogger);
+			await slave._symlinkMods(instance, path.join(testDir, "shared"));
 
 			assert(!await fs.exists(instance.path("mods", "file"), "utf-8"), "dir was unxpectedly linked");
 		});
@@ -139,7 +135,7 @@ describe("Slave testing", function() {
 			}
 
 			await fs.unlink(path.join(testDir, "shared", "mod_a.zip"));
-			await slave._symlinkMods(instance, path.join(testDir, "shared"), discardingLogger);
+			await slave._symlinkMods(instance, path.join(testDir, "shared"));
 
 			await assert.rejects(fs.lstat(instance.path("mods", "mod_a.zip")), { code: "ENOENT" });
 			assert.equal(await fs.readFile(instance.path("mods", "mod_b.zip"), "utf-8"), "b");
@@ -150,10 +146,8 @@ describe("Slave testing", function() {
 
 	describe("discoverInstances()", function() {
 		it("should discover test instance", async function() {
-			let logger = { log: () => {}, error: () => {} };
 			let instancePath = path.join("test", "file", "instances");
-			let instanceInfos = new Map();
-			await slave._discoverInstances(instanceInfos, instancePath, logger);
+			let instanceInfos = await slave._discoverInstances(instancePath);
 
 			let referenceConfig = new libConfig.InstanceConfig();
 			await referenceConfig.init();
@@ -168,4 +162,85 @@ describe("Slave testing", function() {
 			]));
 		});
 	});
+
+	describe("class Slave", function() {
+		describe(".syncUserListsEventHandler()", function() {
+			let mockSlave;
+			beforeEach(function() {
+				mockSlave = {
+					adminlist: new Set(),
+					whitelist: new Set(),
+					banlist: new Map(),
+					broadcasts: [],
+					broadcastEventToInstance(message, event) {
+						this.broadcasts.push(message["data"]);
+					},
+					syncUserListsEventHandler: slave._Slave.prototype.syncUserListsEventHandler,
+					syncLists(adminlist, banlist, whitelist) {
+						return this.syncUserListsEventHandler({ "data": {
+							"adminlist": adminlist,
+							"banlist": banlist,
+							"whitelist": whitelist,
+						}});
+					},
+				};
+			});
+
+			it("should broadcast new entries to adminlist", async function() {
+				await mockSlave.syncLists(["admin1"], [], []);
+				await mockSlave.syncLists(["admin1", "admin2"], [], []);
+
+				assert.deepEqual(mockSlave.broadcasts, [
+					{ "name": "admin1", "admin": true },
+					{ "name": "admin2", "admin": true },
+				]);
+			});
+
+			it("should broadcast removals from adminlist", async function() {
+				mockSlave.adminlist.add("admin1").add("admin2");
+				await mockSlave.syncLists(["admin1"], [], []);
+				assert.deepEqual(mockSlave.broadcasts, [
+					{ "name": "admin2", "admin": false },
+				]);
+			});
+
+			it("should broadcast new entries to whitelist", async function() {
+				await mockSlave.syncLists([], [], ["player1"]);
+				await mockSlave.syncLists([], [], ["player1", "player2"]);
+
+				assert.deepEqual(mockSlave.broadcasts, [
+					{ "name": "player1", "whitelisted": true },
+					{ "name": "player2", "whitelisted": true },
+				]);
+			});
+
+			it("should broadcast removals from whitelist", async function() {
+				mockSlave.whitelist.add("player1").add("player2");
+				await mockSlave.syncLists([], [], ["player1"]);
+
+				assert.deepEqual(mockSlave.broadcasts, [
+					{ "name": "player2", "whitelisted": false },
+				]);
+			});
+
+			it("should broadcast new entries to banlist", async function() {
+				await mockSlave.syncLists([], [["badie1", "greifing"]], []);
+				await mockSlave.syncLists([], [["badie1", "greifing"], ["badie2", "annoying"]], []);
+
+				assert.deepEqual(mockSlave.broadcasts, [
+					{ "name": "badie1", "banned": true, "reason": "greifing" },
+					{ "name": "badie2", "banned": true, "reason": "annoying" },
+				]);
+			});
+
+			it("should broadcast removals to banlist", async function() {
+				mockSlave.banlist.set("badie1", "greifing").set("badie2", "annoying");
+				await mockSlave.syncLists([], [["badie1", "greifing"]], []);
+
+				assert.deepEqual(mockSlave.broadcasts, [
+					{ "name": "badie2", "banned": false, "reason": "" },
+				]);
+			});
+		});
+	});
 });