From 843e0a3217be863a71eaba4f8c70572c341650bb Mon Sep 17 00:00:00 2001 From: Andrew Stewart Date: Mon, 13 Jul 2015 13:55:42 -0700 Subject: [PATCH 1/2] Simplify logger This commit adds a simplified logging system, with two primary methods: - `Logger#log(String) :: void` (for normal logging) - `Logger#debug(String) :: void` (for debug logging) This helps dramatically simplify logging infrastructure, as well as enabling simpler toggling of log modes. The configuration values for the Logger have also been updated: - `logger :: Function` - function to log output to (both normal + debug) - `silent :: Boolean` - whether to log default normal messages or not (`--silent` flag) - `debug :: Boolean` - whether or not to log debug output (`--debug` flag) Additionally, the following CLI flags are supported re: logging: - `--silent` disables normal logging (will override all other settings) - `--debug` enables debug logging Deprecation notices have been added for old log methods, with first-run messages to this effect. This change should have negligible impact on end-users, with minor inconvenience for library developers, as they need to switch their logging function calls over. Logging configuration is still possible via both `Cylon.Config.update(Object)`, and directly calling `Cylon.Logger.setup(Object)`. --- lib/api.js | 2 +- lib/config.js | 4 +- lib/logger.js | 96 ++++++++++++++------ lib/logger/basic_logger.js | 25 ------ lib/logger/null_logger.js | 11 --- lib/mcp.js | 2 +- lib/robot.js | 32 ++++--- lib/validator.js | 4 +- spec/lib/logger.spec.js | 130 +++++---------------------- spec/lib/logger/basic_logger.spec.js | 70 --------------- spec/lib/robot.spec.js | 15 ++-- 11 files changed, 116 insertions(+), 275 deletions(-) delete mode 100644 lib/logger/basic_logger.js delete mode 100644 lib/logger/null_logger.js delete mode 100644 spec/lib/logger/basic_logger.spec.js diff --git a/lib/api.js b/lib/api.js index 4de7927..b2cc72b 100644 --- a/lib/api.js +++ b/lib/api.js @@ -38,7 +38,7 @@ api.create = function create(Server, opts) { [ "Cannot find the " + req + " API module.", "You may be able to install it: `npm install " + req + "`" - ].forEach(_.arity(Logger.fatal, 1)); + ].forEach(_.arity(Logger.log, 1)); throw new Error("Missing API plugin - cannot proceed"); } diff --git a/lib/config.js b/lib/config.js index befd71e..1621acd 100644 --- a/lib/config.js +++ b/lib/config.js @@ -6,9 +6,11 @@ var config = module.exports = {}, callbacks = []; // default data -config.logging = {}; config.haltTimeout = 3000; config.testMode = false; +config.logger = null; +config.silent = false; +config.debug = false; /** * Updates the Config, and triggers handler callbacks diff --git a/lib/logger.js b/lib/logger.js index 9f03bff..a7fad95 100644 --- a/lib/logger.js +++ b/lib/logger.js @@ -1,44 +1,82 @@ "use strict"; -var levels = ["debug", "info", "warn", "error", "fatal"]; +/* eslint no-use-before-define: 0 */ -var BasicLogger = require("./logger/basic_logger"), - NullLogger = require("./logger/null_logger"), - Config = require("./config"), +var Config = require("./config"), _ = require("./utils/helpers"); +var BasicLogger = function basiclogger(str) { + var prefix = new Date().toISOString() + " : "; + console.log(prefix + str); +}; + +var NullLogger = function nulllogger() {}; + var Logger = module.exports = { - setup: function(opts) { - if (_.isObject(opts)) { _.extend(Config.logging, opts); } + setup: setup, - var logger = Config.logging.logger, - level = Config.logging.level || "info"; - - // --debug CLI flag overrides any other option - if (_.includes(process.argv, "--debug")) { - level = "debug"; - } - - logger = (logger == null) ? BasicLogger : logger; - - Logger.logger = logger || NullLogger; - Logger.level = level; - - return Logger; + should: { + log: true, + debug: false }, - toString: function() { - return Logger.logger.toString(); + log: function log(str) { + if (Logger.should.log) { + Logger.logger.call(Logger.logger, str); + } + }, + + debug: function debug(str) { + if (Logger.should.log && Logger.should.debug) { + Logger.logger.call(Logger.logger, str); + } } }; -Logger.setup(); -Config.subscribe(Logger.setup); +function setup(opts) { + if (_.isObject(opts)) { _.extend(Config, opts); } -levels.forEach(function(level) { - Logger[level] = function() { - if (levels.indexOf(level) >= levels.indexOf(Logger.level)) { - return Logger.logger[level].apply(Logger.logger, arguments); - } + var logger = Config.logger; + + // if no logger supplied, use basic logger + if (logger == null) { logger = BasicLogger; } + + // if logger is still falsy, use NullLogger + Logger.logger = logger || NullLogger; + + Logger.should.log = !Config.silent; + Logger.should.debug = Config.debug; + + // --silent CLI flag overrides + if (_.includes(process.argv, "--silent")) { + Logger.should.log = false; + } + + // --debug CLI flag overrides + if (_.includes(process.argv, "--debug")) { + Logger.should.debug = false; + } + + return Logger; +} + +setup(); +Config.subscribe(setup); + +// deprecated holdovers +["info", "warn", "error", "fatal"].forEach(function(method) { + var called = false; + + function showDeprecationNotice() { + console.log("The method Logger#" + method + " has been deprecated."); + console.log("It will be removed in Cylon 2.0.0."); + console.log("Please switch to using the #log or #debug Logger methods"); + + called = true; + } + + Logger[method] = function() { + if (!called) { showDeprecationNotice(); } + Logger.log.apply(null, arguments); }; }); diff --git a/lib/logger/basic_logger.js b/lib/logger/basic_logger.js deleted file mode 100644 index 46a6db5..0000000 --- a/lib/logger/basic_logger.js +++ /dev/null @@ -1,25 +0,0 @@ -"use strict"; - -var getArgs = function(args) { - return args.length >= 1 ? [].slice.call(args, 0) : []; -}; - -var logString = function(type) { - var time = new Date().toISOString(), - upcase = String(type).toUpperCase(), - padded = String(" " + upcase).slice(-5); - - return upcase[0] + ", [" + time + "] " + padded + " -- :"; -}; - -// The BasicLogger logs to console.log -var BasicLogger = module.exports = { - toString: function() { return "BasicLogger"; }, -}; - -["debug", "info", "warn", "error", "fatal"].forEach(function(type) { - BasicLogger[type] = function() { - var args = getArgs(arguments); - return console.log.apply(console, [].concat(logString(type), args)); - }; -}); diff --git a/lib/logger/null_logger.js b/lib/logger/null_logger.js deleted file mode 100644 index 0daadc8..0000000 --- a/lib/logger/null_logger.js +++ /dev/null @@ -1,11 +0,0 @@ -"use strict"; - -// The NullLogger is designed for cases where you want absolutely nothing to -// print to anywhere. Every proxied method from the Logger returns a noop. -var NullLogger = module.exports = { - toString: function() { return "NullLogger"; } -}; - -["debug", "info", "warn", "error", "fatal"].forEach(function(type) { - NullLogger[type] = function() {}; -}); diff --git a/lib/mcp.js b/lib/mcp.js index 112e23b..f054f66 100644 --- a/lib/mcp.js +++ b/lib/mcp.js @@ -31,7 +31,7 @@ mcp.create = function create(opts) { var str = "Robot names must be unique. Renaming '"; str += original + "' to '" + opts.name + "'"; - Logger.warn(str); + Logger.log(str); } var bot = new Robot(opts); diff --git a/lib/robot.js b/lib/robot.js index d578db7..379a45f 100644 --- a/lib/robot.js +++ b/lib/robot.js @@ -118,7 +118,7 @@ Robot.prototype.connection = function(name, conn) { str = "Connection names must be unique."; str += "Renaming '" + original + "' to '" + conn.name + "'"; - this.log("warn", str); + this.log(str); } this.connections[conn.name] = initializer("adaptor", conn); @@ -144,7 +144,7 @@ Robot.prototype.initRobot = function(opts) { this.commands = {}; if (!this.work) { - this.work = function() { this.log("debug", "No work yet."); }; + this.work = function() { this.log("No work yet."); }; } _.each(opts.connections, function(conn, key) { @@ -189,13 +189,13 @@ Robot.prototype.device = function(name, device) { str = "Device names must be unique."; str += "Renaming '" + original + "' to '" + device.name + "'"; - this.log("warn", str); + this.log(str); } if (_.isString(device.connection)) { if (this.connections[device.connection] == null) { str = "No connection found with the name " + device.connection + ".\n"; - this.log("fatal", str); + this.log(str); process.emit("SIGINT"); } @@ -238,8 +238,8 @@ Robot.prototype.start = function(callback) { start ], function(err, results) { if (err) { - this.log("fatal", "An error occured while trying to start the robot:"); - this.log("fatal", err); + this.log("An error occured while trying to start the robot:"); + this.log(err); this.halt(function() { if (_.isFunction(this.error)) { @@ -266,7 +266,7 @@ Robot.prototype.start = function(callback) { * @return {void} */ Robot.prototype.startWork = function() { - this.log("info", "Working."); + this.log("Working."); this.emit("ready", this); this.work.call(this, this); @@ -281,7 +281,7 @@ Robot.prototype.startWork = function() { * @return {void} */ Robot.prototype.startConnections = function(callback) { - this.log("info", "Starting connections."); + this.log("Starting connections."); var starters = _.map(this.connections, function(conn, name) { this[name] = conn; @@ -295,7 +295,7 @@ Robot.prototype.startConnections = function(callback) { str += " on port " + conn.port; } - this.log("debug", str + "."); + this.log(str + "."); return conn.connect.call(conn, cb); }.bind(this); }, this); @@ -313,7 +313,7 @@ Robot.prototype.startConnections = function(callback) { Robot.prototype.startDevices = function(callback) { var log = this.log; - log("info", "Starting devices."); + log("Starting devices."); var starters = _.map(this.devices, function(device, name) { this[name] = device; @@ -325,7 +325,7 @@ Robot.prototype.startDevices = function(callback) { str += " on pin " + device.pin; } - log("debug", str + "."); + log(str + "."); return device.start.call(device, cb); }; }, this); @@ -355,8 +355,8 @@ Robot.prototype.halt = function(callback) { }); } catch (e) { var msg = "An error occured while attempting to safely halt the robot"; - this.log("error", msg); - this.log("error", e.message); + this.log(msg); + this.log(e.message); } this.running = false; @@ -371,8 +371,6 @@ Robot.prototype.toString = function() { return "[Robot name='" + this.name + "']"; }; -Robot.prototype.log = function(level) { - var args = Array.prototype.slice.call(arguments, 1); - args.unshift("[" + this.name + "] -"); - Logger[level].apply(null, args); +Robot.prototype.log = function(str) { + Logger.log("[" + this.name + "] - " + str); }; diff --git a/lib/validator.js b/lib/validator.js index 6e1f4a4..bce606a 100644 --- a/lib/validator.js +++ b/lib/validator.js @@ -17,12 +17,12 @@ function die() { function warn(messages) { messages = [].concat(messages); - messages.map(function(msg) { Logger.warn(msg); }); + messages.map(function(msg) { Logger.log(msg); }); } function fatal(messages) { messages = [].concat(messages); - messages.map(function(msg) { Logger.fatal(msg); }); + messages.map(function(msg) { Logger.log(msg); }); die(); } diff --git a/spec/lib/logger.spec.js b/spec/lib/logger.spec.js index 69aeb70..e5eab46 100644 --- a/spec/lib/logger.spec.js +++ b/spec/lib/logger.spec.js @@ -1,48 +1,38 @@ "use strict"; var Logger = lib("logger"), - Config = lib("config"), - NullLogger = lib("logger/null_logger"); + Config = lib("config"); describe("Logger", function() { afterEach(function() { // to be friendly to other specs - Config.logging = { logger: false, level: "debug" }; + Config.logger = false; Logger.setup(); }); describe("#setup", function() { context("with no arguments", function() { it("sets up a BasicLogger", function() { - Config.logging = {}; + Config.logger = null; Logger.setup(); - expect(Logger.toString()).to.be.eql("BasicLogger"); + expect(Logger.logger.name).to.be.eql("basiclogger"); }); }); context("with false", function() { it("sets up a NullLogger", function() { - Config.logging = { logger: false }; + Config.logger = false; Logger.setup(); - expect(Logger.toString()).to.be.eql("NullLogger"); + expect(Logger.logger.name).to.be.eql("nulllogger"); }); }); context("with a custom logger", function() { it("uses the custom logger", function() { - var logger = { toString: function() { return "custom"; } }; - Config.logging = { logger: logger }; + function customlogger() {} + Config.logger = customlogger; Logger.setup(); - expect(Logger.toString()).to.be.eql("custom"); - }); - }); - - context("with a custom logger, provided directly", function() { - it("uses the custom logger", function() { - var logger = { toString: function() { return "custom"; } }; - Logger.setup({ logger: logger }); - expect(Logger.toString()).to.be.eql("custom"); - expect(Config.logging.logger).to.be.eql(logger); + expect(Logger.logger.name).to.be.eql("customlogger"); }); }); }); @@ -51,107 +41,31 @@ describe("Logger", function() { var logger; beforeEach(function() { - logger = Config.logging.logger = { - debug: spy(), - info: spy(), - warn: spy(), - error: spy(), - fatal: spy() - }; - - Logger.setup(); + logger = spy(); + Logger.logger = logger; }); describe("#debug", function() { - it("proxies to the Logger's #debug method", function() { - Logger.debug("Hello", "World"); - expect(logger.debug).to.be.calledWith("Hello", "World"); + it("proxies to the logger method", function() { + Logger.should.debug = true; + Logger.debug("debug message"); + Logger.should.debug = false; + expect(logger).to.be.calledWith("debug message"); }); }); - describe("#info", function() { - it("proxies to the Logger's #info method", function() { - Logger.info("Hello", "World"); - expect(logger.info).to.be.calledWith("Hello", "World"); + describe("#log", function() { + it("proxies to the logger method", function() { + Logger.log("log message"); + expect(logger).to.be.calledWith("log message"); }); }); - - describe("#warn", function() { - it("proxies to the Logger's #warn method", function() { - Logger.warn("Hello", "World"); - expect(logger.warn).to.be.calledWith("Hello", "World"); - }); - }); - - describe("#error", function() { - it("proxies to the Logger's #error method", function() { - Logger.error("Hello", "World"); - expect(logger.error).to.be.calledWith("Hello", "World"); - }); - }); - - describe("#fatal", function() { - it("proxies to the Logger's #fatal method", function() { - Logger.fatal("Hello", "World"); - expect(logger.fatal).to.be.calledWith("Hello", "World"); - }); - }); - }); - - describe("log levels", function() { - var logger; - - beforeEach(function() { - logger = { - debug: spy(), - info: spy(), - warn: spy(), - error: spy(), - fatal: spy() - }; - - Config.logging = { - logger: logger, - level: "warn" - }; - - Logger.setup(); - }); - - it("prevents logging below the specified level", function() { - Logger.debug("debug message"); - Logger.info("info message"); - - expect(logger.debug).to.not.be.called; - expect(logger.info).to.not.be.called; - }); - - it("still logs levels equal/greater than the specified level", function() { - Logger.warn("warn message"); - Logger.error("error message"); - Logger.fatal("fatal message"); - - expect(logger.warn).to.be.calledWith("warn message"); - expect(logger.error).to.be.calledWith("error message"); - expect(logger.fatal).to.be.calledWith("fatal message"); - }); - - it("defaults to 'info' level", function() { - delete Config.logging.level; - Logger.setup(); - - Logger.debug("debug message"); - Logger.info("info message"); - - expect(logger.debug).to.not.be.called; - expect(logger.info).to.be.calledWith("info message"); - }); }); it("automatically updates if configuration changed", function() { var custom = spy(); - expect(Logger.logger).to.be.eql(NullLogger); - Config.update({ logging: { logger: custom } }); + expect(Logger.logger.name).to.be.eql("basiclogger"); + Config.update({ logger: custom }); expect(Logger.logger).to.be.eql(custom); }); }); diff --git a/spec/lib/logger/basic_logger.spec.js b/spec/lib/logger/basic_logger.spec.js deleted file mode 100644 index 5b73531..0000000 --- a/spec/lib/logger/basic_logger.spec.js +++ /dev/null @@ -1,70 +0,0 @@ -"use strict"; - -var logger = lib("logger/basic_logger"); - -var date = new Date(0).toISOString(); - -describe("BasicLogger", function() { - var clock; - - beforeEach(function() { - stub(console, "log"); - clock = sinon.useFakeTimers(0); - }); - - afterEach(function() { - console.log.restore(); - clock.restore(); - }); - - describe("#toString", function() { - it("returns 'BasicLogger'", function() { - expect(logger.toString()).to.be.eql("BasicLogger"); - }); - }); - - describe("#debug", function() { - it("logs to the console with a debug string", function() { - var logstring = "D, [" + date + "] DEBUG -- :"; - - logger.debug("Hello, World"); - expect(console.log).to.be.calledWith(logstring, "Hello, World"); - }); - }); - - describe("#info", function() { - it("logs to the console with a info string", function() { - var logstring = "I, [" + date + "] INFO -- :"; - - logger.info("Hello, World"); - expect(console.log).to.be.calledWith(logstring, "Hello, World"); - }); - }); - - describe("#warn", function() { - it("logs to the console with a warn string", function() { - var logstring = "W, [" + date + "] WARN -- :"; - - logger.warn("Hello, World"); - expect(console.log).to.be.calledWith(logstring, "Hello, World"); - }); - }); - - describe("#error", function() { - it("logs to the console with a error string", function() { - var logstring = "E, [" + date + "] ERROR -- :"; - - logger.error("Hello, World"); - expect(console.log).to.be.calledWith(logstring, "Hello, World"); - }); - }); - - describe("#fatal", function() { - it("logs to the console with a fatal string", function() { - var logstring = "F, [" + date + "] FATAL -- :"; - - logger.fatal("Hello, World"); - expect(console.log).to.be.calledWith(logstring, "Hello, World"); - }); - }); -}); diff --git a/spec/lib/robot.spec.js b/spec/lib/robot.spec.js index 60cd98b..2f1fd0b 100644 --- a/spec/lib/robot.spec.js +++ b/spec/lib/robot.spec.js @@ -488,22 +488,17 @@ describe("Robot", function() { describe("#log", function() { beforeEach(function() { - stub(Logger, "info"); - stub(Logger, "fatal"); - - robot.log("info", "an informative message"); - robot.log("fatal", "a fatal error"); + stub(Logger, "log"); + robot.log("an informative message"); }); afterEach(function() { - Logger.info.restore(); - Logger.fatal.restore(); + Logger.log.restore(); }); it("it passes messages onto Logger, with the Robot's name", function() { - var nameStr = "[" + robot.name + "] -"; - expect(Logger.info).to.be.calledWith(nameStr, "an informative message"); - expect(Logger.fatal).to.be.calledWith(nameStr, "a fatal error"); + var nameStr = "[" + robot.name + "] - "; + expect(Logger.log).to.be.calledWith(nameStr + "an informative message"); }); }); }); From 8a582fcf8d01cbac8b14e83780e18d9c39a2d847 Mon Sep 17 00:00:00 2001 From: Andrew Stewart Date: Mon, 13 Jul 2015 14:08:21 -0700 Subject: [PATCH 2/2] _.arity call no longer necessary --- lib/api.js | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/lib/api.js b/lib/api.js index b2cc72b..94a51e5 100644 --- a/lib/api.js +++ b/lib/api.js @@ -38,7 +38,7 @@ api.create = function create(Server, opts) { [ "Cannot find the " + req + " API module.", "You may be able to install it: `npm install " + req + "`" - ].forEach(_.arity(Logger.log, 1)); + ].forEach(Logger.log); throw new Error("Missing API plugin - cannot proceed"); }