Merge pull request #341 from Hornwitser/log-system

Implement logging system

.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",

docs/configuration.md

@@ -286,6 +286,14 @@ 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}.
 
 

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/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"
@@ -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}`
             ))
         );
     }

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,48 +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 === "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 (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" });
@@ -69,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));
 	},
 }));
 
@@ -79,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);
 	},
 }));
 
@@ -101,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) {
@@ -124,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));
 	},
 }));
 
@@ -161,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)}`);
 			}
 		}
 	},
@@ -223,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,
 		});
@@ -236,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,
 		});
@@ -253,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;
 	},
 }));
 
@@ -271,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;
 	},
 }));
 
@@ -285,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,
 		});
@@ -324,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));
 	},
 }));
 
@@ -334,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));
 	},
 }));
 
@@ -352,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}`);
 	},
 }));
 
@@ -402,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));
 	},
 }));
 
@@ -504,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;
 	},
 }));
 
@@ -525,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",
@@ -554,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() {
@@ -585,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",
@@ -607,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)));
@@ -630,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();
@@ -644,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);
@@ -663,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 {
@@ -698,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;
 	}
@@ -719,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 {
@@ -745,7 +806,7 @@ async function startControl() {
 		}
 
 	} finally {
-		if (!keepOpen) {
+		if (!control.keepOpen) {
 			await control.shutdown();
 		}
 	}
@@ -753,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
@@ -769,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

@@ -22,6 +22,7 @@
     "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/build_mod.js

@@ -1,3 +1,4 @@
+/* eslint-disable no-console */
 "use strict";
 const events = require("events");
 const fs = require("fs-extra");

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,6 +10,7 @@ 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");
 
 
 /**
@@ -302,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
@@ -383,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); });
 		},
 	},
@@ -391,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); });
 		},
 	},
@@ -402,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);
 		},
 	},
@@ -414,7 +414,7 @@ const outputHeuristics = [
 			type: "log",
 			message: /^Saving game as /,
 		},
-		action: function(output) {
+		action: function() {
 			this.emit("_saving");
 		},
 	},
@@ -430,7 +430,7 @@ const outputHeuristics = [
 				"Can't save to default location: Default location not known",
 			],
 		},
-		action: function(output) {
+		action: function() {
 			this.emit("_saved");
 		},
 	},
@@ -441,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();
 			}
 		},
@@ -463,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}`);
 		},
 	},
 	{
@@ -476,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}`);
 		},
 	},
 ];
@@ -509,6 +509,7 @@ 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`.
@@ -532,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();
@@ -635,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 });
 		}
 	}
 
@@ -653,31 +655,31 @@ class FactorioServer extends events.EventEmitter {
 		}
 
 
-		let output = parseOutput(line, source);
+		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() {
@@ -970,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/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.message || "unknown error");
+			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,9 @@ 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.

packages/lib/link/messages.js

@@ -2,6 +2,7 @@
 "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) {
@@ -207,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}`);
 					}
 
@@ -215,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 });
 				});
@@ -236,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);
@@ -349,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"],
@@ -646,6 +635,50 @@ 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({
@@ -820,7 +853,7 @@ class Event extends Message {
 			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);
 		}
@@ -836,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}`);
 		}
 
@@ -853,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"],
@@ -875,31 +923,6 @@ messages.instanceStatusChanged = new Event({
 	},
 });
 
-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"],

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

@@ -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
@@ -210,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 });
 	}
 
 	/**
@@ -362,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 });
 	}
 
 	/**
@@ -445,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/prometheus.js

@@ -723,6 +723,21 @@ class GaugeChild extends ValueCollectorChild {
 	setToCurrentTime() {
 		this._values.set(this._key, Date.now() / 1000);
 	}
+
+	/**
+	 * Start a timer for setting a duration for label set
+	 *
+	 * @returns {function()}
+	 *     function that when called will set the guage to the duration in
+	 *     seconds from when the timer was started
+	 */
+	startTimer() {
+		let start = process.hrtime.bigint();
+		return () => {
+			let end = process.hrtime.bigint();
+			this.set(Number(end - start) / 1e9);
+		};
+	}
 }
 
 /**
@@ -886,6 +901,18 @@ class Gauge extends ValueCollector {
 	setToCurrentTime() {
 		this._defaultChild.setToCurrentTime();
 	}
+
+	/**
+	 * Start a timer for setting a duration
+	 *
+	 * Note: Only works if this is an unlabeled collector.
+	 * @returns {function()}
+	 *     function that when called will set the guage to the duration in
+	 *     seconds from when the timer was started
+	 */
+	startTimer() {
+		return this._defaultChild.startTimer();
+	}
 }
 
 function formatValue(value) {

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

@@ -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,7 @@ let stopAcceptingNewSessions = false;
 let debugEvents = new events.EventEmitter();
 let loadedPlugins = {};
 let devMiddleware;
+let clusterLogger;
 
 // homebrew modules
 const generateSslCert = require("./src/generate_ssl_cert");
@@ -55,6 +57,8 @@ 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");
@@ -288,13 +292,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 {
@@ -372,7 +376,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);
 }
 
@@ -409,10 +413,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);
@@ -438,14 +442,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}`);
 				}
 			}
 		}
@@ -455,22 +458,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);
 	}
 }
@@ -551,8 +554,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}`);
 			}
 		}
 
@@ -560,6 +562,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) {
@@ -581,13 +588,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);
 			}
@@ -765,8 +782,77 @@ class ControlConnection extends BaseConnection {
 		}
 	}
 
-	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) {
@@ -1001,13 +1087,13 @@ class SlaveConnection extends BaseConnection {
 		// 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) {
-			console.log(`Clusterio | Got bogus update for instance id ${message.data.instance_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);
 	}
 
@@ -1041,9 +1127,7 @@ class SlaveConnection extends BaseConnection {
 				if (masterInstance.status !== instance.status) {
 					let prev = masterInstance.status;
 					masterInstance.status = instance.status;
-					console.log(
-						`Clusterio | Instance ${instanceConfig.get("instance.name")} State: ${instance.status}`
-					);
+					logger.verbose(`Instance ${instanceConfig.get("instance.name")} State: ${instance.status}`);
 					await libPlugin.invokeHook(masterPlugins, "onInstanceStatusChanged", instance, prev);
 				}
 				continue;
@@ -1080,13 +1164,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) {
@@ -1228,7 +1311,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;
@@ -1242,7 +1325,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;
@@ -1270,17 +1353,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
@@ -1328,7 +1411,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();
@@ -1357,7 +1440,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);
@@ -1369,13 +1452,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");
 			});
@@ -1395,14 +1478,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;
@@ -1435,7 +1518,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;
@@ -1473,7 +1556,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;
@@ -1488,16 +1571,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));
 	}
 
@@ -1508,7 +1591,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() {
@@ -1528,7 +1611,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);
@@ -1537,7 +1620,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;
 }
@@ -1554,7 +1637,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.
@@ -1603,13 +1686,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",
@@ -1644,7 +1731,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)));
@@ -1661,20 +1776,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 {
@@ -1683,7 +1798,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"));
@@ -1699,7 +1814,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;
 			}
@@ -1717,16 +1832,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;
 			}
@@ -1738,9 +1854,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);
 			}
 		}
@@ -1752,7 +1869,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");
@@ -1765,12 +1882,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();
 	});
 
@@ -1791,7 +1908,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);
 	}
 
@@ -1818,7 +1935,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));
 	}
 
@@ -1829,7 +1945,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) {
@@ -1849,7 +1965,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}`);
 	}
 }
 
@@ -1867,6 +1983,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
@@ -1876,28 +1993,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

@@ -31,6 +31,7 @@
     "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"
   },

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/package.json

@@ -23,6 +23,7 @@
     "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,6 +35,8 @@ 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 instanceRconCommandDuration = new libPrometheus.Histogram(
@@ -80,7 +83,7 @@ function applyAsConfig(name) {
 		try {
 			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}`);
 		}
 	};
 }
@@ -106,7 +109,7 @@ const serverSettingsActions = {
 				let enabled = Boolean(value[scope]);
 				await instance.sendRcon(`/config set visibility-${scope} ${enabled}`);
 			} catch (err) {
-				console.error(`Error applying visibility ${scope}`, err);
+				logger.error(`Error applying visibility ${scope} ${err}`);
 			}
 		}
 	},
@@ -125,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);
 
@@ -142,6 +150,7 @@ class Instance extends libLink.Link{
 		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"),
@@ -158,19 +167,19 @@ class Instance extends libLink.Link{
 			factorioDir, this._dir, serverOptions
 		);
 
-		this.server.on("output", (output) => {
-			libLink.messages.instanceOutput.send(this, { instance_id: this.config.get("instance.id"), output });
+		this.server.on("output", (parsed, line) => {
+			this.logger.log("server", { message: line, instance_id: this.config.get("instance.id"), parsed });
 
-			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}`);
 			});
 		});
 
@@ -247,7 +256,7 @@ 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) {
@@ -294,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;
 		}
@@ -328,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"));
@@ -340,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)
@@ -352,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(
@@ -362,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");
@@ -377,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");
 	}
 
 	/**
@@ -404,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";
 		}
@@ -414,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();
@@ -488,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());
@@ -515,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());
@@ -685,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();
@@ -698,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" });
@@ -773,11 +782,10 @@ class Instance extends libLink.Link{
  * instanceInfo objects.
  *
  * @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(instancesDir, logger) {
+async function discoverInstances(instancesDir) {
 	let instanceInfos = new Map();
 	for (let entry of await fs.readdir(instancesDir, { withFileTypes: true })) {
 		if (entry.isDirectory()) {
@@ -792,12 +800,12 @@ async function discoverInstances(instancesDir, logger) {
 					continue; // Ignore folders without config.json
 				}
 
-				logger.error(`Error occured while parsing ${configPath}: ${err}`);
+				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,
@@ -889,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;
@@ -948,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);
 			});
 		});
@@ -968,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);
 				});
 			}
@@ -1134,7 +1137,7 @@ 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}`);
+			logger.verbose(`Updated config for ${instanceInfo.path}`);
 
 		} else {
 			instanceInfo = this.discoveredInstanceInfos.get(instance_id);
@@ -1158,7 +1161,7 @@ class Slave extends libLink.Link {
 			}
 
 			this.instanceInfos.set(instance_id, instanceInfo);
-			console.log(`Clusterio | assigned instance ${instanceInfo.config.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
@@ -1191,7 +1194,7 @@ class Slave extends libLink.Link {
 			}
 
 			this.instanceInfos.delete(instanceId);
-			console.log(`Clusterio | unassigned instance ${instanceInfo.config.get("instance.name")}`);
+			logger.verbose(`unassigned instance ${instanceInfo.config.get("instance.name")}`);
 		}
 	}
 
@@ -1301,7 +1304,7 @@ class Slave extends libLink.Link {
 	 * the slave and master server with the new list of instances.
 	 */
 	async updateInstances() {
-		this.discoveredInstanceInfos = await discoverInstances(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.discoveredInstanceInfos) {
 			let instanceConnection = this.instanceConnections.get(instanceId);
@@ -1325,8 +1328,9 @@ class Slave extends libLink.Link {
 							save: null,
 						});
 					} catch (err) {
-						console.error(`Error during auto startup for ${instanceInfo.config.get("instance.name")}:`);
-						console.error(err);
+						logger.error(
+							`Error during auto startup for ${instanceInfo.config.get("instance.name")}:\n${err.stack}`
+						);
 					}
 				}
 			}
@@ -1353,8 +1357,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}`);
 			}
 		}
 
@@ -1423,16 +1426,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));
 			}
 		}
@@ -1444,7 +1446,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);
 
@@ -1462,23 +1464,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",
@@ -1499,7 +1505,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)));
@@ -1516,19 +1538,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 {
@@ -1553,8 +1575,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"+
@@ -1566,8 +1588,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;
 	}
@@ -1579,24 +1601,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();
 }
 
@@ -1610,6 +1636,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
@@ -1619,16 +1646,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

@@ -17,12 +17,16 @@
     "@ant-design/icons": "^4.2.2",
     "@clusterio/lib": "^2.0.0-alpha.2",
     "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,59 +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 (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([<span key={0}>{"<previous messages are not shown>"}<br/></span>]);
+	let anchor = useRef();
+	let [pastLines, setPastLines] = useState([<span key={0}>{"Loading past entries..."}<br/></span>]);
+	let [lines, setLines] = useState([]);
 
 	useEffect(() => {
-		function outputHandler(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(
-				[formatOutputColored(output, currentLines.length)]
+				[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">
+			{pastLines}
 			{lines}
-			<div className="scroll-anchor" />
+			<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 {
@@ -147,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,41 +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.updateInstanceOutputSubscriptions().catch(console.error);
+			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`);
 		}
@@ -94,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/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));
 		});
 	}
 

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/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,19 +4,17 @@ 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));
 		});
 	}
 
@@ -24,7 +22,7 @@ class InstancePlugin extends libPlugin.BaseInstancePlugin {
 		this.pingId = setInterval(() => {
 			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);
@@ -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,8 +61,8 @@ 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));

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})`);
 	}
 }
 

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/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/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);
 			}
 		});

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() {
@@ -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,6 +198,16 @@ 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() {

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 = {
@@ -112,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,9 +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 = await slave._discoverInstances(instancePath, logger);
+			let instanceInfos = await slave._discoverInstances(instancePath);
 
 			let referenceConfig = new libConfig.InstanceConfig();
 			await referenceConfig.init();