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/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..d9eaf1c8 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 libLink.messages.setLogSubscriptions.send(control, { all: false, 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 libLink.messages.setLogSubscriptions.send(control, { all: false, instance_ids: [instanceId] }); let response = await libLink.messages.exportData.send(control, { instance_id: instanceId, }); @@ -253,7 +218,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 libLink.messages.setLogSubscriptions.send(control, { all: false, instance_ids: [instanceId] }); let response = await libLink.messages.startInstance.send(control, { instance_id: instanceId, save: args.save || null, @@ -271,7 +236,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 libLink.messages.setLogSubscriptions.send(control, { all: false, instance_ids: [instanceId] }); let response = await libLink.messages.loadScenario.send(control, { instance_id: instanceId, scenario: args.scenario || null, @@ -285,7 +250,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 libLink.messages.setLogSubscriptions.send(control, { all: false, instance_ids: [instanceId] }); let response = await libLink.messages.stopInstance.send(control, { instance_id: instanceId, }); @@ -324,7 +289,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 +299,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 +317,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 +367,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)); }, })); @@ -525,7 +490,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", @@ -556,13 +521,12 @@ class Control extends libLink.Link { } } - async instanceOutputEventHandler(message) { - let { instance_id, output } = message.data; - console.log(formatOutputColored(output)); + 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 +549,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 +578,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))); @@ -632,7 +610,7 @@ async function startControl() { rootCommands.add(userCommands); 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 +622,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 +641,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 +676,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,9 +697,9 @@ 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); }); }); @@ -733,11 +711,11 @@ async function startControl() { } catch (err) { 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 { @@ -753,13 +731,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 +745,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..3b1a9b48 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,19 @@ messages.deleteUser = new Request({ }, }); +messages.setLogSubscriptions = new Request({ + type: "set_log_subscriptions", + links: ["control-master"], + permission: "core.log.follow", + requestProperties: { + "all": { type: "boolean" }, + "instance_ids": { + type: "array", + items: { type: "integer" }, + }, + }, +}); + // Internal requests messages.updateInstances = new Request({ @@ -820,7 +822,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 +838,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 +855,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 +892,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..26a554a8 --- /dev/null +++ b/packages/lib/logging_utils.js @@ -0,0 +1,126 @@ +"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 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] = `[${info.level}]${src}${info.stack}`; + } else { + info[MESSAGE] = `[${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/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..81097243 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,11 @@ 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.debug.dump_ws", diff --git a/packages/master/master.js b/packages/master/master.js index f469272c..b0cdeebe 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}`); } } @@ -581,13 +583,21 @@ class ControlConnection extends BaseConnection { } }); - this.instanceOutputSubscriptions = new Set(); + this.logTransport = null; + this.logSubscriptions = { + all: false, + 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 +775,32 @@ class ControlConnection extends BaseConnection { } } - async setInstanceOutputSubscriptionsRequestHandler(message) { - this.instanceOutputSubscriptions = new Set(message.data.instance_ids); + async setLogSubscriptionsRequestHandler(message) { + this.logSubscriptions = message.data; + this.updateLogSubscriptions(); + } + + updateLogSubscriptions() { + if (this.logSubscriptions.all || this.logSubscriptions.instance_ids.length) { + if (!this.logTransport) { + this.logTransport = new libLoggingUtils.LinkTransport({ link: this }); + clusterLogger.add(this.logTransport); + } + if (this.logSubscriptions.all) { + this.logTransport.filter = null; + } else { + this.logTransport.filter = info => { + if (info.instance_id && this.logSubscriptions.instance_ids.includes(info.instance_id)) { + return true; + } + return false; + }; + } + + } else if (this.logTransport) { + clusterLogger.remove(this.logTransport); + this.logTransport = null; + } } async listPermissionsRequestHandler(message) { @@ -1001,13 +1035,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 +1075,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 +1112,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 +1259,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 +1273,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 +1301,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 +1359,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 +1388,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 +1400,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 +1426,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 +1466,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 +1504,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 +1519,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 +1539,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 +1559,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 +1568,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 +1585,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 +1634,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 +1679,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 +1724,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 +1746,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 +1762,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 +1780,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 +1802,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 +1817,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 +1830,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 +1856,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 +1883,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 +1893,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 +1913,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 +1931,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 +1941,32 @@ 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.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..46733bef 100644 --- a/packages/web_ui/src/components/InstanceViewPage.jsx +++ b/packages/web_ui/src/components/InstanceViewPage.jsx @@ -72,36 +72,44 @@ 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) { @@ -109,15 +117,15 @@ function InstanceConsole(props) { let [lines, setLines] = useState([{""}
]); useEffect(() => { - function outputHandler(output) { + 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]); 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 + ) || } + )}