diff --git a/.eslintrc.js b/.eslintrc.js index 0dd888b7..30f2d3bd 100644 --- a/.eslintrc.js +++ b/.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", diff --git a/docs/configuration.md b/docs/configuration.md index e69d983e..4e71f8e8 100644 --- a/docs/configuration.md +++ b/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}. diff --git a/docs/contributing.md b/docs/contributing.md index beca0b72..a049cf9d 100644 --- a/docs/contributing.md +++ b/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. diff --git a/docs/writing-plugins.md b/docs/writing-plugins.md index 367922f1..211f7aab 100644 --- a/docs/writing-plugins.md +++ b/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}` )) ); } diff --git a/packages/ctl/ctl.js b/packages/ctl/ctl.js index 15241642..0658725a 100755 --- a/packages/ctl/ctl.js +++ b/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 [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; }); } diff --git a/packages/ctl/package.json b/packages/ctl/package.json index 9ecfa0bd..ad8d98b9 100644 --- a/packages/ctl/package.json +++ b/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": { diff --git a/packages/lib/build_mod.js b/packages/lib/build_mod.js index ffe54f83..6fa8822f 100644 --- a/packages/lib/build_mod.js +++ b/packages/lib/build_mod.js @@ -1,3 +1,4 @@ +/* eslint-disable no-console */ "use strict"; const events = require("events"); const fs = require("fs-extra"); diff --git a/packages/lib/factorio/export.js b/packages/lib/factorio/export.js index 97c051e1..cd101a2e 100644 --- a/packages/lib/factorio/export.js +++ b/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]); } diff --git a/packages/lib/factorio/server.js b/packages/lib/factorio/server.js index 17423007..69bdc04d 100644 --- a/packages/lib/factorio/server.js +++ b/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(() => {}); } diff --git a/packages/lib/link/connectors.js b/packages/lib/link/connectors.js index 20766092..675d7579 100644 --- a/packages/lib/link/connectors.js +++ b/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(); diff --git a/packages/lib/link/link.js b/packages/lib/link/link.js index f602f92f..c2f37953 100644 --- a/packages/lib/link/link.js +++ b/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. diff --git a/packages/lib/link/messages.js b/packages/lib/link/messages.js index b9e011eb..1eb28116 100644 --- a/packages/lib/link/messages.js +++ b/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"], diff --git a/packages/lib/logging.js b/packages/lib/logging.js new file mode 100644 index 00000000..e55fa73e --- /dev/null +++ b/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, +}; diff --git a/packages/lib/logging_utils.js b/packages/lib/logging_utils.js new file mode 100644 index 00000000..990b2597 --- /dev/null +++ b/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, +}; diff --git a/packages/lib/package.json b/packages/lib/package.json index bb91af9b..0844c18a 100644 --- a/packages/lib/package.json +++ b/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" }, diff --git a/packages/lib/plugin.js b/packages/lib/plugin.js index 3a461fea..333e2379 100644 --- a/packages/lib/plugin.js +++ b/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; diff --git a/packages/lib/prometheus.js b/packages/lib/prometheus.js index aaf34c11..bb163ea2 100644 --- a/packages/lib/prometheus.js +++ b/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) { diff --git a/packages/lib/shared_commands.js b/packages/lib/shared_commands.js index 0bd370ce..68df288d 100644 --- a/packages/lib/shared_commands.js +++ b/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; } diff --git a/packages/lib/users.js b/packages/lib/users.js index 803fe8be..a55ef972 100644 --- a/packages/lib/users.js +++ b/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", diff --git a/packages/master/master.js b/packages/master/master.js index f469272c..59523acb 100755 --- a/packages/master/master.js +++ b/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 + // 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 [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(); + } }); } diff --git a/packages/master/package.json b/packages/master/package.json index d8583b85..82fd061b 100644 --- a/packages/master/package.json +++ b/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" }, diff --git a/packages/master/src/generate_ssl_cert.js b/packages/master/src/generate_ssl_cert.js index 0e966b8b..0c63ea03 100644 --- a/packages/master/src/generate_ssl_cert.js +++ b/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`); }; diff --git a/packages/slave/package.json b/packages/slave/package.json index 0558a16e..811cc313 100644 --- a/packages/slave/package.json +++ b/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": { diff --git a/packages/slave/slave.js b/packages/slave/slave.js index 3345b68f..47cfb3bb 100755 --- a/packages/slave/slave.js +++ b/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} * 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 [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 . 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); diff --git a/packages/web_ui/package.json b/packages/web_ui/package.json index f2a1c9b8..b325793e 100644 --- a/packages/web_ui/package.json +++ b/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" diff --git a/packages/web_ui/src/bootstrap.jsx b/packages/web_ui/src/bootstrap.jsx index cda9cf8b..f9fafb14 100644 --- a/packages/web_ui/src/bootstrap.jsx +++ b/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(, document.getElementById("root")); } -load().catch(console.log); +load().catch((err) => logger.fatal(err)); diff --git a/packages/web_ui/src/components/App.jsx b/packages/web_ui/src/components/App.jsx index 454ce9be..54dc63f0 100644 --- a/packages/web_ui/src/components/App.jsx +++ b/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); } diff --git a/packages/web_ui/src/components/InstanceViewPage.jsx b/packages/web_ui/src/components/InstanceViewPage.jsx index c9686485..116b7e54 100644 --- a/packages/web_ui/src/components/InstanceViewPage.jsx +++ b/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 = {output.time.padStart(8)} ; - } else if (output.format === "date") { - time = {output.time} ; + if (parsed.format === "seconds") { + time = {parsed.time.padStart(8)} ; + } else if (parsed.format === "date") { + time = {parsed.time} ; } let info = ""; - if (output.type === "log") { - let level = output.level; + if (parsed.type === "log") { + let level = parsed.level; if (level === "Script") { level = {level}; } else if (level === "Verbose") { level = {level}; } else if (level === "Info") { level = {level}; - } else if (output.level === "Warning") { + } else if (parsed.level === "Warning") { level = {level}; - } else if (output.level === "Error") { + } else if (parsed.level === "Error") { level = {level}; } - info = <>{level} {output.file}: ; + info = <>{level} {parsed.file}: ; - } else if (output.type === "action") { - info = <>[{output.action}] ; + } else if (parsed.type === "action") { + info = <>[{parsed.action}] ; } - return {time}{info}{output.message}
; + return {time}{info}{parsed.message}
; +} + +function formatLog(info, key) { + if (info.level === "server" && info.parsed) { + return formatParsedOutput(info.parsed, key); + } + let level = {info.level}; + return [{level}] {info.message}
; } function InstanceConsole(props) { let control = useContext(ControlContext); - let [lines, setLines] = useState([{""}
]); + let anchor = useRef(); + let [pastLines, setPastLines] = useState([{"Loading past entries..."}
]); + 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([{`Error loading log: ${err.message}`}
]); + }); + + 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 <> + {pastLines} {lines} -
+
; } diff --git a/packages/web_ui/src/components/InstancesPage.jsx b/packages/web_ui/src/components/InstancesPage.jsx index 790525d1..39315a10 100644 --- a/packages/web_ui/src/components/InstancesPage.jsx +++ b/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`); }, }), diff --git a/packages/web_ui/src/components/RoleViewPage.jsx b/packages/web_ui/src/components/RoleViewPage.jsx index feb740ad..25d1fadb 100644 --- a/packages/web_ui/src/components/RoleViewPage.jsx +++ b/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); } diff --git a/packages/web_ui/src/components/RolesPage.jsx b/packages/web_ui/src/components/RolesPage.jsx index bbd81bd0..1b09afea 100644 --- a/packages/web_ui/src/components/RolesPage.jsx +++ b/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`); }, }), diff --git a/packages/web_ui/src/components/UsersPage.jsx b/packages/web_ui/src/components/UsersPage.jsx index 65855ed5..75fee750 100644 --- a/packages/web_ui/src/components/UsersPage.jsx +++ b/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`); }, }), diff --git a/packages/web_ui/src/components/data-table.jsx b/packages/web_ui/src/components/data-table.jsx index 9299a1ec..e9073d55 100644 --- a/packages/web_ui/src/components/data-table.jsx +++ b/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 - {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) || } - ; - }) - } + {( + // 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 => + {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 + ) || } + )}