From 898d024fae76a09599907d0ec1031ad947fdf7c8 Mon Sep 17 00:00:00 2001 From: caroline-church Date: Wed, 21 Mar 2018 10:22:17 +0000 Subject: [PATCH] Revert Logging (#3646) * Revert "two many underscores (#3638)" This reverts commit 81475b3 Signed-off-by: Caroline Church * Revert "Serviceability issues (#3592)" This reverts commit 0b9b607 Signed-off-by: Caroline Church --- .../lib/cmds/network/lib/loglevel.js | 14 +- .../lib/cmds/network/loglevelCommand.js | 5 +- .../composer-cli/test/network/loglevel.js | 14 - .../composer-common/lib/log/consolelogger.js | 39 +- packages/composer-common/lib/log/logger.js | 470 ++++------- packages/composer-common/lib/log/node.js | 28 +- packages/composer-common/lib/log/tree.js | 41 +- .../lib/log/winstonInjector.js | 113 +-- .../composer-common/test/log/consolelogger.js | 58 +- packages/composer-common/test/log/logger.js | 768 ++++++------------ packages/composer-common/test/log/tree.js | 56 +- .../test/embeddedconnection.js | 1 - packages/composer-connector-server/cli.js | 7 +- .../test/connectorserver.js | 10 - .../test/webconnection.js | 1 - packages/composer-playground-api/cli.js | 33 +- packages/composer-playground/cli.js | 33 +- .../src/app/footer/footer.component.ts | 3 + .../src/app/services/admin.service.ts | 5 + .../src/app/services/identity-card.service.ts | 5 + .../lib/embeddedloggingservice.js | 18 - .../test/embeddedloggingservice.js | 8 - .../lib/nodeloggingservice.js | 190 +++-- packages/composer-runtime-hlfv1/package.json | 4 +- .../composer-runtime-hlfv1/test/composer.js | 34 + .../test/nodecontainer.js | 18 +- .../test/nodedatacollection.js | 4 - .../test/nodedataservice.js | 3 - .../test/nodehttpservice.js | 3 - .../test/nodeloggingservice.js | 293 ++++++- .../lib/webloggingservice.js | 18 - .../test/webloggingservice.js | 7 - packages/composer-runtime/lib/engine.js | 57 +- .../composer-runtime/lib/engine.logging.js | 2 +- .../composer-runtime/lib/loggingservice.js | 55 +- .../composer-runtime/lib/networkmanager.js | 6 +- .../test/engine.businessnetworks.js | 7 +- packages/composer-runtime/test/engine.js | 45 +- .../composer-runtime/test/engine.logging.js | 38 +- .../composer-runtime/test/engine.queries.js | 13 +- .../test/engine.registries.js | 11 +- .../composer-runtime/test/engine.resources.js | 10 +- .../test/engine.transactions.js | 12 +- .../composer-runtime/test/loggingservice.js | 61 +- .../composer-runtime/test/networkmanager.js | 15 +- .../jekylldocs/problems/diagnostics.md | 232 ++---- 46 files changed, 1295 insertions(+), 1573 deletions(-) diff --git a/packages/composer-cli/lib/cmds/network/lib/loglevel.js b/packages/composer-cli/lib/cmds/network/lib/loglevel.js index 40a82f9019..931590ccf4 100644 --- a/packages/composer-cli/lib/cmds/network/lib/loglevel.js +++ b/packages/composer-cli/lib/cmds/network/lib/loglevel.js @@ -16,7 +16,7 @@ const chalk = require('chalk'); const cmdUtil = require('../../utils/cmdutils'); -const Pretty = require('prettyjson'); + /** *

* Composer "network loglevel" command @@ -46,17 +46,9 @@ class LogLevel { }) .then((result) => { if (newlevel) { - cmdUtil.log(chalk.blue.bold('The logging level was successfully changed to: ')+newlevel); + cmdUtil.log(chalk.blue.bold('The logging level was successfully changed to: ') + newlevel); } else { - cmdUtil.log(chalk.blue.bold('The current logging level is: ')+result.debug); - if(argv.x){ - cmdUtil.log(chalk.blue.bold('\nFull details: ')); - cmdUtil.log(Pretty.render(result,{ - keysColor: 'blue', - dashColor: 'blue', - stringColor: 'white' - })); - } + cmdUtil.log(chalk.blue.bold('The current logging level is: ') + result); } }); } diff --git a/packages/composer-cli/lib/cmds/network/loglevelCommand.js b/packages/composer-cli/lib/cmds/network/loglevelCommand.js index 160fdc1554..2c5cc1d42d 100644 --- a/packages/composer-cli/lib/cmds/network/loglevelCommand.js +++ b/packages/composer-cli/lib/cmds/network/loglevelCommand.js @@ -19,9 +19,8 @@ const logLevel = require ('./lib/loglevel.js'); module.exports.command = 'loglevel [options]'; module.exports.describe = 'Change the logging level of a business network'; module.exports.builder = { - newlevel: { alias: 'l', optional: true, describe: 'the new logging level', type: 'string'}, - card: { alias: 'c', required: true, description: 'The cardname to use to change the log level the network', type:'string'}, - full: { alias: 'x', required: false, description: 'The full settings of the currently configured debug log', hidden: true}, + newlevel: { alias: 'l', optional: true, describe: 'the new logging level', choices : ['INFO', 'WARNING', 'ERROR', 'DEBUG'] }, + card: { alias: 'c', required: true, description: 'The cardname to use to change the log level the network', type:'string'} }; module.exports.handler = (argv) => { diff --git a/packages/composer-cli/test/network/loglevel.js b/packages/composer-cli/test/network/loglevel.js index 8f18e28084..64fcd42dce 100644 --- a/packages/composer-cli/test/network/loglevel.js +++ b/packages/composer-cli/test/network/loglevel.js @@ -72,19 +72,5 @@ describe('composer network logLevel CLI unit tests', () => { }); }); - it('should get the logLevel and produce the full-output', () => { - let argv = { - card:'cardname' , - x: true - }; - - return LogLevel.handler(argv) - .then((res) => { - argv.thePromise.should.be.a('promise'); - sinon.assert.calledOnce(mockAdminConnection.connect); - sinon.assert.calledWith(mockAdminConnection.connect, 'cardname'); - sinon.assert.calledOnce(mockAdminConnection.getLogLevel); - }); - }); }); diff --git a/packages/composer-common/lib/log/consolelogger.js b/packages/composer-common/lib/log/consolelogger.js index d48bc91e75..7da4c4106e 100644 --- a/packages/composer-common/lib/log/consolelogger.js +++ b/packages/composer-common/lib/log/consolelogger.js @@ -17,27 +17,27 @@ const util = require('util'); /** + * A functional logger implementation that simply writes to the console. * @private */ class ConsoleLogger { -/** - * Called to format. - * @param {string} method The method. - * @param {string} msg The message. - * @param {*} [args] The arguments. - * @returns {string} The formatted message. - * @private - */ + /** + * Called to format. + * @param {string} method The method. + * @param {string} msg The message. + * @param {*} [args] The arguments. + * @returns {string} The formatted message. + */ format(method, msg, args) { if (!args) { return util.format('%s %s', method, msg); } let formattedArguments = args.map((arg) => { - if (typeof (arg) === 'function') { + if (typeof(arg) === 'function') { return ''; } else if (arg === Object(arg)) { - // It's an object, array, or function, so serialize it as JSON. + // It's an object, array, or function, so serialize it as JSON. try { return JSON.stringify(arg); } catch (e) { @@ -50,14 +50,13 @@ class ConsoleLogger { return util.format('%s %s %s', method, msg, formattedArguments); } -/** - * Called to log. - * @param {string} level The logging level. - * @param {string} method The method. - * @param {string} msg The message. - * @param {*} [args] The arguments. - * @private - */ + /** + * Called to log. + * @param {string} level The logging level. + * @param {string} method The method. + * @param {string} msg The message. + * @param {*} [args] The arguments. + */ log(level, method, msg, args) { const formattedMessage = this.format(method, msg, args); switch (level) { @@ -81,6 +80,4 @@ class ConsoleLogger { } -module.exports.getLogger = function (config) { - return new ConsoleLogger(); -}; +module.exports = ConsoleLogger; diff --git a/packages/composer-common/lib/log/logger.js b/packages/composer-common/lib/log/logger.js index 1c6d166cd2..517bb37b8b 100644 --- a/packages/composer-common/lib/log/logger.js +++ b/packages/composer-common/lib/log/logger.js @@ -13,51 +13,30 @@ */ 'use strict'; -const composerUtil = require('../util'); -const path = require('path'); -const Tree = require('./tree.js'); -// Note, sprintf is being used here solely to help format the filename of the log file. -// It is inefficient to use it for general formatting as part of logging. -const sprintf = require('sprintf-js').sprintf; +const Tree = require('./tree.js'); -// Current configuration -let _config; +// Root node of the selection tree +let _tree = null; -// Core logger that is in use -let _logger; +// Core logger that is in use (user configurable) +let _logger = null; // Set of instances of this logger class that acts as a proxy to the core logger let _clInstances = {}; -// the default control string - log from everthing but only at the error level -let _envDebug = 'composer[error]:*'; - -// callback to use to get additional information -let _callback; - -// Settings for log levels -// These are based on the NPM log levels -// NPM log levels are -//{ -// error: 0, -// warn: 1, -// info: 2, -// verbose: 3, -// debug: 4, -// silly: 5 -//} -const LOG_LEVEL_SILLY = 5; -const LOG_LEVEL_DEBUG = 4; -const LOG_LEVEL_VERBOSE = 3; -const LOG_LEVEL_INFO = 2; -const LOG_LEVEL_WARN = 1; -const LOG_LEVEL_ERROR = 0; -const LOG_LEVEL_NONE = -1; +// Settins for log levels +const LOG_LEVEL_ALL = 6; +const LOG_LEVEL_DEBUG = 5; +const LOG_LEVEL_VERBOSE = 4; +const LOG_LEVEL_INFO = 3; +const LOG_LEVEL_WARN = 2; +const LOG_LEVEL_ERROR = 1; +const LOG_LEVEL_NONE = 0; // Mapping between strings and log levels. const _logLevelAsString = { - silly: LOG_LEVEL_SILLY, + all: LOG_LEVEL_ALL, debug: LOG_LEVEL_DEBUG, verbose: LOG_LEVEL_VERBOSE, info: LOG_LEVEL_INFO, @@ -66,10 +45,8 @@ const _logLevelAsString = { none: LOG_LEVEL_NONE }; -// If composer[debug]:acls is provided, the debug level of trace will be used for specified string. -const PROFILES = { - 'acls' : ['composer[#]:AccessController'] -}; +// Current log level +let _logLevel = LOG_LEVEL_ALL; /** * @description Class that provides the API to enable parts of the *Composer* @@ -108,17 +85,27 @@ const PROFILES = { */ class Logger { + /** + * Set the new log level. + * @param {string} logLevel The new log level. + */ + static setLogLevel(logLevel) { + const newLogLevel = _logLevelAsString[logLevel.toLowerCase()]; + if (newLogLevel === undefined) { + throw new Error(`Unrecognized log level ${logLevel}`); + } + _logLevel = newLogLevel; + } + /** * Constructor *THIS SHOULD ONLY BE CALLED INTERNALLY* - * Sets up an array of 25 spaces to help with speedy padding - * - * @param {String} name Classname for this logger + * @param {String} name Classname or other filename for this logger * @private + * */ constructor(name) { this.className = name; - // 26 due to the way this actually works... - this.str25 = Array(26).join(' '); + this.str25 = Array(25).join(' '); } /** @@ -137,30 +124,35 @@ class Logger { * logging systems. This method does basic formatting before passing to the * log method of the selected logger implementation. * - * Required fn here is to form up the arguments into a suitable string, and - * process any errors to capture the stack trace. The core logger is then CALLED - * - * The assumption is that this logger has a method called `log`. with this prototype - * `log(String logLevel, String codeunit, String message, Array[optional] data)` - * + * Internal method * * @private - * @param {String} logLevel log logLevel + * @param {String} logLevel log loglevel * @param {String} method method name * @param {String} msg to log * @param {others} arguments parameters are treated as data points to be logged */ intlog(logLevel,method,msg){ - let callbackData; - - // if callback has been registered get the data. - if(_callback){ - callbackData = _callback() || ''; - } + // first we need to make sure that we have logger setup + this._intLogFirst.apply(this,arguments); + } + /** + * @description Main internal logging method + * Required fn here is to form up the arguments into a suitable string, and + * process any errors to capture the stack trace. The core logger is then CALLED + * + * The assumption is that this logger has a method called `log`. with this prototype + * `log(String loglevel, String codeunit, String message, Array[optional] data)` + * + * @param {String} loglevel log loglevel + * @param {String} method method name + * @param {String} msg to log + */ + _intLogMain(loglevel,method,msg){ if (typeof arguments[3] ==='undefined'){ // this is the case where there are no additional arguments; data for example - _logger.log(logLevel,callbackData+':'+this.padRight(this.str25,this.className)+':'+this.padRight(this.str25,method+'()'),msg); + _logger.log(loglevel,this.padRight(this.str25,this.className)+':'+this.padRight(this.str25,method+'()'),msg); } else { // loop over the arguments - if any are Errors make sure that the stack trace is captured let args = []; @@ -173,13 +165,32 @@ class Logger { } } - // use the local version of padding rather than sprintf etc for speed - _logger.log(logLevel,callbackData+':'+this.padRight(this.str25,this.className)+':'+this.padRight(this.str25,method+'()'),msg, args); + _logger.log(loglevel,this.padRight(this.str25,this.className)+':'+this.padRight(this.str25,method+'()'),msg, args); } } - // Individual log methods follow for specific cases + /** + * @description initial internal log function that sets up the logger to use. + * Then it calls the normal internal log method (and modifies the original + * function definition) + * + * @param {String} logLevel log loglevel + * @param {String} method method name + * @param {String} msg to log + */ + _intLogFirst(logLevel,method,msg){ + + // call the setup logger to make sure that things are setup + // this is done now to be as late as possible + Logger._setupLog(this); + + //reroute the ingLog method to the main implementation + // and call + this.intLog = this._intLogMain; + // this._intLogMain.apply(this,arguments); + this._intLogMain.apply(this,arguments); + } /** * @description Log a message at the _debug_level @@ -191,7 +202,7 @@ class Logger { * @private */ debug(method, msg, data) { - if (!(this.include && this.logLevel >= LOG_LEVEL_DEBUG)) { + if (_logLevel < LOG_LEVEL_DEBUG) { return; } const length = arguments.length; @@ -213,7 +224,7 @@ class Logger { * @private */ warn(method, msg, data) { - if (!(this.include && this.logLevel >= LOG_LEVEL_WARN)) { + if (_logLevel < LOG_LEVEL_WARN) { return; } const length = arguments.length; @@ -235,7 +246,7 @@ class Logger { * @private */ info(method, msg, data) { - if (!(this.include && this.logLevel >= LOG_LEVEL_INFO)) { + if (_logLevel < LOG_LEVEL_INFO) { return; } const length = arguments.length; @@ -250,14 +261,14 @@ class Logger { /** * @description Log a message at the _verbose_ level * - * @param {String} method cupdateLoggerCfgalling method + * @param {String} method calling method * @param {String} msg Text Message * @param {stuff} data Data to log at a verbose level * * @private */ verbose(method,msg, data) { - if (!(this.include && this.logLevel >= LOG_LEVEL_VERBOSE)) { + if (_logLevel < LOG_LEVEL_VERBOSE) { return; } const length = arguments.length; @@ -279,7 +290,7 @@ class Logger { * @private */ error(method, msg,data) { - if (!(this.include && this.logLevel >= LOG_LEVEL_ERROR)) { + if (_logLevel < LOG_LEVEL_ERROR) { return; } const length = arguments.length; @@ -300,7 +311,7 @@ class Logger { * @private */ entry(method, data) { - if (!(this.include && this.logLevel >= LOG_LEVEL_DEBUG)) { + if (_logLevel < LOG_LEVEL_DEBUG) { return; } const length = arguments.length; @@ -321,7 +332,7 @@ class Logger { * @private */ exit(method, data) { - if(!(this.include && this.logLevel >= LOG_LEVEL_DEBUG)) { + if (_logLevel < LOG_LEVEL_DEBUG) { return; } const length = arguments.length; @@ -333,6 +344,31 @@ class Logger { args.unshift('debug', method, '<'); this.intlog.apply(this, args); } + + /** + * Get the selection tree. + * @return {Tree} The selection tree. + */ + static getSelectionTree() { + return _tree; + } + + /** + * Set the selection tree. + * @param {Tree} tree The selection tree. + */ + static setSelectionTree(tree) { + _tree = tree; + } + + /** + * Get the functional logger. + * @return {Object} The functional logger. + */ + static getFunctionalLogger() { + return _logger; + } + /** * @description Method to call passing an instance of an object that has the * method definition @@ -346,43 +382,18 @@ class Logger { static setFunctionalLogger(newlogger){ _logger = newlogger; } - /** - * Get the selection tree. This is a tree based structure to help determine what should and should not be included in the log files. - * - * @return {Tree} The selection tree. - */ - static getSelectionTree() { - return _config.tree; - } - /** - * Add a default set of JSON formated LoggerConfig - programatically. - * Overrides any user setting - * - * @param {Object} loggerCfg Object that has the config - * @param {boolean} [force] If true, force a refresh of the configuration, default is false - * @return {Object} the log configuration that is now inforce - */ - static setLoggerCfg(loggerCfg,force=false){ - _config = Logger.processLoggerConfig(loggerCfg); - _logger = Logger._loadLogger(_config); - - if(force){ - Object.keys(_clInstances).forEach(function(key) { - Logger._setupLog(_clInstances[key]); - }); - } - return _config; - } /** - * return the log configuration that is in force, note that this method just returns the information - * it does create, modify or delete it + * @description what is the debug environment variable set to + * Note that the _envDebug property of this object is for debugging the debugging log + * and emergency use ONLY + * + * @return {String} String of the DEBUG env variable * - * @return {Object} config data */ - static getLoggerCfg(){ - return _config; + static getDebugEnv(){ + return process.env.DEBUG || Logger._envDebug || ''; } /** @@ -397,97 +408,40 @@ class Logger { * The 'config' property is required - but the contents of this property are passed * as is to the class defined in the logger property. * - * Order of precedence: (most significant to least significant) - * - Internal API call to setLoggerConfig() - * - User specified via the Config module - * - defaults - * - * @param {Object} localConfig 'starter' configuration information - * @param {boolean} replace true if this should merge the start config and anything calculate over the top of the exist config * @return {Object} with the config information * */ - static processLoggerConfig(localConfig,replace=false){ - - - localConfig = localConfig || { 'origin': 'default-logger-module' }; - - // load the config from config module - this can completely change the behaviour + static getLoggerConfig(){ try { // This weird code is needed to trick browserify. process.env.SUPPRESS_NO_CONFIG_WARNING = 'y'; const mod = 'config'; const req = require; const config = req(mod); - - if (config.has('composer.log.logger') && !localConfig.logger){ - localConfig.logger = config.get('composer.log.logger'); - } - if (config.has('composer.log.file') && !localConfig.file){ - localConfig.file = config.get('composer.log.file'); - } - if (config.has('composer.log.debug') && !localConfig.debug){ - localConfig.debug = config.get('composer.log.debug'); - } - if (config.has('composer.log.console') && !localConfig.console){ - localConfig.console = config.get('composer.log.console'); + if (config.has('composer.debug')){ + return config.get('composer.debug'); } } catch (e) { // We don't care if we can't find the config module, it won't be // there when the code is running inside a browser/chaincode. } - // For each part of the potential configuration apply a set of defaults - if (!localConfig.logger){ - localConfig.logger = './winstonInjector.js' ; - } + return { + 'logger': './winstonInjector.js', + 'config': { + 'console': { + 'enabledLevel': 'info', + 'alwaysLevel': 'none' - // if the file section is not there, create a default - if (!localConfig.file) { - // process filename - - // see if there is a env variable for fast override - let defaultFilename = path.join(composerUtil.homeDirectory(), '.composer', 'logs', 'trace_DATESTAMP.log'); - let resolvedFilename = process.env.COMPOSER_LOGFILE || defaultFilename; - let maxsize = process.env.COMPOSER_LOGFILE_SIZE || 10000000; //10Mb - let maxfiles = process.env.COMPOSER_LOGFILE_QTY || 100; - - let d = new Date(); - let timestamp = sprintf('%d%02d%02d-%02d%02d%02d-%03d',d.getUTCFullYear(),d.getUTCMonth()+1,d.getUTCDate()+1,d.getHours(),d.getMinutes(),d.getSeconds(),d.getMilliseconds()); - let datestamp = sprintf('%d%02d%02d',d.getUTCFullYear(),d.getUTCMonth()+1,d.getUTCDate()+1); - resolvedFilename = resolvedFilename.replace(/DATESTAMP/g, datestamp); - resolvedFilename = resolvedFilename.replace(/TIMESTAMP/g, timestamp); - resolvedFilename = resolvedFilename.replace(/PID/g, process.pid); - - localConfig.file = { - 'filename': resolvedFilename, - 'maxLevel': 'silly', - 'maxsize' : maxsize, - 'maxfiles': maxfiles - }; - - } - - // if no debug ctrl variable - if (!localConfig.debug){ - localConfig.debug = (process.env.DEBUG || _envDebug ); - } - - // if no console setting - if (!localConfig.console){ - let consoleLevel = process.env.COMPOSER_LOG_CONSOLE || 'none'; - localConfig.console={ - 'maxLevel': consoleLevel.toLowerCase() - }; - } + }, + 'file': { - // This is an important method for parsing the control string and getting the details of what should be logged - // This creates the tree that permits the efficient determination of what should be logger - localConfig.tree = Logger._parseLoggerConfig(localConfig); + 'filename': 'trace_TIMESTAMP.log', + 'enabledLevel': 'debug', + 'alwaysLevel': 'error' + } + }}; - // it can be useful at this point to output the config being returned. - // see the debug_debug() fn in this class for an example on how to do it - return localConfig; } /** @@ -499,15 +453,11 @@ class Logger { * @private */ static getLog(classname) { - - // see if there is a cached version of this logger for the classname, otherwise create and setup - let composerLogger = _clInstances[classname]; - if(!composerLogger) { - composerLogger = new Logger(classname); - Logger._setupLog(composerLogger); - _clInstances[classname] = composerLogger; + if(typeof _clInstances[classname] === 'undefined') { + _clInstances[classname] = new Logger(classname); + _clInstances[classname].log = Logger._intLogFirst; } - return composerLogger; + return _clInstances[classname]; } /** @@ -520,80 +470,52 @@ class Logger { */ static _setupLog(composerLogger){ - // get the config from it's respective locations - if (!_config){ - _config = Logger.processLoggerConfig(); + let configElements = []; + + // Parse the logger configuration if it hasn't been done already. + if (_tree === null){ + _tree = Logger._parseLoggerConfig(configElements); } // Load the logger if it hasn't been done already. - if(!_logger) { - _logger = Logger._loadLogger(_config); + if(_logger === null) { + _logger = Logger._loadLogger(configElements); } // now we need to check if the name that has come in and should be traced - // this is prefiltering and log level setup - let node = Logger.getSelectionTree().getNode(composerLogger.className); - composerLogger.include = node.isIncluded(); - composerLogger.logLevel = node.getLogLevel(); + composerLogger.include = _tree.getInclusion(composerLogger.className); + + return ; } /** - * Parse the logger configuration - sole purpose is to produce the selection tree that permits - * the easy determination of what should and shouldn't be logged. - * - * @param {object} localConfig The configuration elements for the logger. + * Parse the logger configuration. + * @param {string[]} configElements The configuration elements for the logger. * @return {Tree} The configuration tree. * @private */ - static _parseLoggerConfig(localConfig) { + static _parseLoggerConfig(configElements) { // need to do the filtering to see if this should be enabled or not - let string = localConfig.debug; + let string = Logger.getDebugEnv(); let details = string.split(/[\s,]+/); - let tree = new Tree(false,4); - - // regex to process the debug control string - const regex = /(-?)composer\[?(info|warn|debug|error|verbose)?\]?:([\w\/\*]*)/; + let tree = new Tree(); + const regex = /(-?)composer:(.*)?/; // now we have an array of the elements that we might need to be enabled + // for (let i=0; i< details.length;i++){ let e = details[i]; - if (e === '*'){ + if (e === '*' || e ==='composer:*'){ tree.setRootInclusion(); - tree.setRootLevel(_logLevelAsString.info); - break; } // determine if the element is for composer or not let machResult = e.match(regex); if (machResult!==null){ - let include = (machResult[1]===''); - let logLevel = machResult[2]; - if (!logLevel) { - logLevel= 'info'; - } - let className = machResult[3]; - // got a result that we need to trace therefore setup the child node correctly - if (className === '*'){ - tree.setRootInclusion(); - tree.setRootLevel(_logLevelAsString[logLevel]); - break; - }else { - tree.addNode(className, _logLevelAsString[logLevel], include); - } - - // we need to support the ability to use 'profiles'. for example - // composer:acls - // that would then expand to include composer[debug]:acls,composer[debug]:someotherclass - // this has also added acls as a class node, so it is possible to specifically get a logger for acls reasons - - let additionalElements = PROFILES[className]; - if (additionalElements){ - additionalElements.forEach((e)=>{ - // if the string has a # in it replace with the user specified level - details.push( e.replace(/#/g,logLevel)); - }); - } + tree.addNode(machResult[2] ,(machResult[1]==='') ); + // make a note of the debug settings that permit the config elements + configElements.push(machResult[2]); } } return tree; @@ -601,23 +523,22 @@ class Logger { /** * Load the logger module specified in the logger configuration, and get a logger. - * @param {Object} localConfig The configuration elements for the logger. + * @param {string[]} configElements The configuration elements for the logger. * @return {Logger} The logger. * @private */ - static _loadLogger(localConfig) { + static _loadLogger(configElements) { + let localConfig = Logger.getLoggerConfig(); - // attempts to load the specified logger module implementation. if not then put out an error - const loggerToUse = localConfig.logger; + // use the config package to get configuration to see what we should be doing. + // and pass the rest of the data to the logger indicated along with the + // array of the data that might have been passed on the DEBUG variable. + let loggerToUse = localConfig.logger; let myLogger; try { - // const mod = 'config'; - const req = require; - // const config = req(mod); - myLogger = req(loggerToUse); + myLogger = require(loggerToUse); } catch (e) { - // Print the error to the console and just use the null logger instead. - // eslint-disable-next-line no-console + // Print the error to the console and just use the null logger instead. console.error(`Failed to load logger module ${loggerToUse}: ${e.message}`); myLogger = { getLogger: () => { @@ -628,70 +549,19 @@ class Logger { }; } - // get the instance of the logger to use - passing the localConfig for reference (eg filenames) - return myLogger.getLogger(localConfig); - - // For reference, hard coding just to get the Winston logger is as follows - // return WinstonInjector.getLogger(localConfig); - } - - /** - * This is a simple callback function, to permit additional data to be inserted into the logged output - * - * @param {Function} fn function to be called to get information - */ - static setCallBack(fn){ - _callback=fn; - } - - /** - * Get the function set as a callback - * @return {Function} function set as the callback - */ - static getCallBack(){ - return _callback; + // primary used to determine what has been enabled to allow the logger to + // go into a default mode.. NOT MEANT TO BE USED FOR FILTERING. + return myLogger.getLogger(localConfig.config,{ 'debug' : configElements } ); } /** - * Resets the logger - for test and emergency use only + * @description clean up the logger; required if anything is dynamically changed */ - static __reset(){ - _config=null; + static reset(){ + _tree=null; _logger=null; - _envDebug = 'composer[error]:*'; - _clInstances = {}; - - } - - /** - * Sets up the config for the cli appls - */ - static setCLIDefaults(){ - let envVariable = process.env.DEBUG; - if (!envVariable){ - envVariable = 'composer[info]:*'; - } - Logger.setLoggerCfg({ - 'console': { - 'maxLevel': 'silly' - }, - 'debug' : envVariable - },true); - } - - /** - * Invokes all the levels of log, to be used when attempting to help with diagnostics - * - * @param {Logger} logger instance to call - */ - static invokeAllLevels(logger){ - logger.debug('TestAll','Debug level message'); - logger.entry('TestAll','Entry level message'); - logger.exit('TestAll','Exit level message'); - logger.verbose('TestAll','Verbose level message'); - logger.info('TestAll','Info level message'); - logger.warn('TestAll','Warn level message'); - logger.error('TestAll','Error level message'); + _clInstances={}; + _logLevel = LOG_LEVEL_ALL; } } diff --git a/packages/composer-common/lib/log/node.js b/packages/composer-common/lib/log/node.js index 8b922286be..f4b75a5385 100644 --- a/packages/composer-common/lib/log/node.js +++ b/packages/composer-common/lib/log/node.js @@ -21,20 +21,20 @@ class Node { /** @description creates a new node + * @TODO replace the include with a filter level * * @param {String} name name of the node i.e. package & class - * @param {int} logLevel loglevel for this node * @param {boolean} include should this included in the trace * * @private */ - constructor(name,logLevel,include){ + constructor(name,include){ this.name=name; this.include =include; - this.logLevel=logLevel; this.children=[]; } + /** * @description adds a new node as a child of this at the start of the listTitles * @param {Node} node Child node to add @@ -55,25 +55,6 @@ class Node { return this.name; } - /** - * @description what is the loglevel of this node? - * @return {int} loglevel as set on constructor - * - * @private - */ - getLogLevel(){ - return this.logLevel; - } - - /** - * @description what is the loglevel of this node? - * @param {int} loglevel as set on constructor - * @private - */ - setLogLevel(loglevel){ - this.logLevel = loglevel; - } - /** * @description is this node included in the set trace settings * @return {boolean} included true or false @@ -84,6 +65,7 @@ class Node { return this.include; } + /** * @description Set the node to be an inclusion */ @@ -99,7 +81,7 @@ class Node { * @private */ findChild(nameToFind){ - // do an array search of the children and match the nameToFind + // do an array search of the children and match the nameToFind return this.children.find(function(element){ return element.getName()===this; },nameToFind); diff --git a/packages/composer-common/lib/log/tree.js b/packages/composer-common/lib/log/tree.js index d019e4a1b9..a943c9321c 100644 --- a/packages/composer-common/lib/log/tree.js +++ b/packages/composer-common/lib/log/tree.js @@ -23,11 +23,9 @@ const Node = require('./node.js'); class Tree { /** Create the tree and setup the root node - * @param {boolean} rootInclude inclusion setting for the root - * @param {int} rootLogLevel log level for the root */ - constructor(rootInclude,rootLogLevel){ - this.root = new Node('composer',rootLogLevel,rootInclude); + constructor(){ + this.root = new Node('composer',false); } /** Mark the root to be included - defaults to false @@ -36,24 +34,15 @@ class Tree { this.root.setIncluded(); } - /** - * Sets the log level of the root node - * @param {int} level loglevel of the root node - */ - setRootLevel(level){ - this.root.setLogLevel(level); - } - /** * Add a new node to the tree * * @param {String} name name of the node to add - * @param {int} logLevel loglevel for this node * @param {boolean} include should this be included or not * @return {Node} the new node created */ - addNode(name, logLevel, include){ - return this._insertChildNode(name,logLevel,include,this.root); + addNode(name, include){ + return this._insertChildNode(name,include,this.root); } /** @@ -62,15 +51,6 @@ class Tree { * @return {boolean} inclusion policy - true or false */ getInclusion(name){ - return this._findNode(name,this.root).isIncluded(); - } - - /** - * Find inclusion property for a given node - * @param {String} name name of the node to search the tree for - * @return {Node} node - */ - getNode(name){ return this._findNode(name,this.root); } @@ -88,7 +68,7 @@ class Tree { let foundNode = parent.findChild(newNodeName); if ( typeof foundNode === 'undefined' ){ - return parent; + return parent.isIncluded(); } else { return this._findNode(details.join('/'),foundNode); } @@ -98,14 +78,13 @@ class Tree { /** * Insert a new node based on this parent * @param {String} name name of the node to add - * @param {int} logLevel loglevel for this node * @param {boolean} include should this be included or not * @param {Node} parent node to use as the parent for the children * @return {Node} newly inserted node * * @private */ - _insertChildNode(name, logLevel, include, parent){ + _insertChildNode(name, include, parent){ // split the name up based on the marker / let details = name.split(/\//); @@ -116,19 +95,19 @@ class Tree { if (typeof child === 'undefined' ){ if (details.length === 0) { - let newNode = new Node(newNodeName,logLevel,include); + let newNode = new Node(newNodeName,include); parent.addChildNodeAtStart(newNode); // at the leaf node return the new node created return newNode; } else { - let newNode = new Node(newNodeName,parent.getLogLevel(),parent.isIncluded()); + let newNode = new Node(newNodeName,parent.isIncluded()); parent.addChildNodeAtStart(newNode); // request another new node to be created. - return this._insertChildNode(details.join('/'),logLevel,include,newNode); + return this._insertChildNode(details.join('/'),include,newNode); } } else { // we have found a node already that matches the name. - return this._insertChildNode(details.join('/'),logLevel,include,child); + return this._insertChildNode(details.join('/'),include,child); } } diff --git a/packages/composer-common/lib/log/winstonInjector.js b/packages/composer-common/lib/log/winstonInjector.js index 778b00522b..9f3bab0074 100644 --- a/packages/composer-common/lib/log/winstonInjector.js +++ b/packages/composer-common/lib/log/winstonInjector.js @@ -13,30 +13,35 @@ */ 'use strict'; -const fs = require('fs'); -const path = require('path'); +const fs = require('fs-extra'); const winston = require('winston'); const sprintf = require('sprintf-js').sprintf; -const mkdirp = require('mkdirp'); - -const PRODUCT_LABEL='Hyperledger-Composer'; /** * This the default core logger that is used for Hyperledger-Composer. This function * setups up the Winston logging for both file and console output. * * @param {Object} config JSON structure with specific configuration information + * @param {Array} configElements JSON struction with the DEBUG env variables for composer * * @returns {Object} object that is the logger to use */ -exports.getLogger = function (config){ +exports.getLogger = function (config,configElements){ + + let consoleLevel; + let fileLevel; - let consoleLevel = config.console.maxLevel; - let fileLevel = config.file.maxLevel; - let filename = config.file.filename; + // if the length of the configured elements are 0 then put this into a default + // only mode. + if (configElements.debug.length === 0){ + consoleLevel=config.console.alwaysLevel; + fileLevel=config.file.alwaysLevel; + } else { + fileLevel=config.file.enabledLevel; + consoleLevel=config.console.enabledLevel; + } // setup the formatter functions - // TODO remove the sprintf fn for something faster let formatterFn = function(options) { // Return string will be passed to logger. @@ -54,69 +59,41 @@ exports.getLogger = function (config){ return new Date(Date.now()).toISOString(); }; + // process the file name and make sure the directory has been created + let resolvedFilename = config.file.filename.replace(/PID/g, process.pid); - // create the transports - let transports =[]; - let consoleOptions = { - name: 'info-file', - colorize: true, - label: PRODUCT_LABEL, - silent: (consoleLevel===null), - level: consoleLevel - }; + // process the filename and get the timestampe replaced + let d = new Date(); + let timestamp = sprintf('%d%02d%02d-%02d%02d%02d-%03d',d.getUTCFullYear(),d.getUTCMonth()+1,d.getUTCDate()+1,d.getHours(),d.getMinutes(),d.getSeconds(),d.getMilliseconds()); + resolvedFilename = resolvedFilename.replace(/TIMESTAMP/g, timestamp); - transports.push( - new(winston.transports.Console)(consoleOptions) - ); - - if (filename){ - let dir = path.parse(filename).dir; - if (!fs.existsSync(dir)){ - // try to create it - mkdirp.sync(dir); - } - - // take the additional configuration options - let fileConfig = { - name:'debug-file', - json:false, - filename: filename, - timestamp: timestampFn, - formatter: formatterFn, - level: fileLevel, - tailable: true, - silent: (fileLevel==='none') - }; - - if(config.file.maxFiles){ - fileConfig.maxFiles = config.file.maxFiles; - } - if(config.file.maxsize){ - fileConfig.maxFiles = config.file.maxsize; - } - - transports.push( - new(winston.transports.File)(fileConfig)); + let dir = './composer-logs'; + fs.ensureDirSync(dir); - } - - - if(winston.loggers.has(PRODUCT_LABEL)){ - let logger = winston.loggers.get(PRODUCT_LABEL); - logger.clear(); - transports.forEach( (tr) =>{ - logger.add(tr,{},true); - }); - } else { // create the Winston logger with the two transports. - let newWinstonLogger = { - transports: transports - }; - // add to the Winston system and return - winston.loggers.add(PRODUCT_LABEL,newWinstonLogger); - } + let newWinstonLogger = { + transports: [ + new(winston.transports.Console)({ + name: 'info-file', + timestamp: timestampFn, + formatter: formatterFn , + level: consoleLevel + }), + new(winston.transports.File)({ + name:'debug-file', + json:false, + filename: dir+ '/' + resolvedFilename, + timestamp: timestampFn, + formatter: formatterFn , + level: fileLevel + }) + + ] + }; - return winston.loggers.get(PRODUCT_LABEL); + // add to the winnston system and return + winston.loggers.add('Hyperledger-Composer',newWinstonLogger); + return winston.loggers.get('Hyperledger-Composer'); }; diff --git a/packages/composer-common/test/log/consolelogger.js b/packages/composer-common/test/log/consolelogger.js index b504c59178..8a072030f3 100644 --- a/packages/composer-common/test/log/consolelogger.js +++ b/packages/composer-common/test/log/consolelogger.js @@ -16,7 +16,6 @@ const ConsoleLogger = require('../../lib/log/consolelogger'); - require('chai').should(); const sinon = require('sinon'); @@ -25,42 +24,36 @@ describe('ConsoleLogger', () => { let sandbox; let logger; - describe('#format', () => { - let stdout; - beforeEach(() => { - sandbox = sinon.sandbox.create(); - logger = ConsoleLogger.getLogger(); - stdout = sandbox.spy(console, 'log'); - }); + beforeEach(() => { + sandbox = sinon.sandbox.create(); + logger = new ConsoleLogger(); + }); - afterEach(() => { - sandbox.restore(); - }); + afterEach(() => { + sandbox.restore(); + }); + + describe('#format', () => { it('should handle no arguments', () => { - logger.log('debug','func1', 'some msg'); - sinon.assert.calledWith(stdout,'func1 some msg'); + logger.format('func1', 'some msg').should.equal('func1 some msg'); }); it('should handle basic arguments', () => { - logger.log('debug','func1', 'some msg', [ 'arg1', 3.142, true, null, undefined ]); - sinon.assert.calledWith(stdout,'func1 some msg arg1, 3.142, true, null, undefined'); + logger.format('func1', 'some msg', [ 'arg1', 3.142, true, null, undefined ]).should.equal('func1 some msg arg1, 3.142, true, null, undefined'); }); it('should handle object arguments', () => { - logger.log('debug','func1', 'some msg', [ { prop1: 'value1' } ]); - sinon.assert.calledWith(stdout,'func1 some msg {"prop1":"value1"}'); + logger.format('func1', 'some msg', [ { prop1: 'value1' } ]).should.equal('func1 some msg {"prop1":"value1"}'); }); it('should handle array arguments', () => { - logger.log('debug','func1', 'some msg', [ [ 'value1', 'value2' ] ]); - sinon.assert.calledWith(stdout,'func1 some msg ["value1","value2"]'); + logger.format('func1', 'some msg', [ [ 'value1', 'value2' ] ]).should.equal('func1 some msg ["value1","value2"]'); }); it('should handle function arguments', () => { const cb = () => { }; - logger.log('debug','func1', 'some msg', [ cb ]); - sinon.assert.calledWith(stdout,'func1 some msg '); + logger.format('func1', 'some msg', [ cb ]).should.equal('func1 some msg '); }); it('should handle JSON serialization errors', () => { @@ -70,58 +63,47 @@ describe('ConsoleLogger', () => { throw new Error('mwahahaha'); } }; - logger.log('debug','func1', 'some msg', [ badObject ]); - sinon.assert.calledWith(stdout,'func1 some msg [object Object]'); + logger.format('func1', 'some msg', [ badObject ]).should.equal('func1 some msg [object Object]'); }); }); describe('#log', () => { - let sandbox; - beforeEach(() => { - sandbox = sinon.sandbox.create(); - logger = ConsoleLogger.getLogger(); - sandbox.stub(logger,'format'); - - }); - - afterEach(() => { - sandbox.restore(); - }); it('should log debug level', () => { const spy = sandbox.spy(console, 'log'); logger.log('debug', 'func1', 'some msg', [ 'arg1', 'arg2' ]); sinon.assert.calledOnce(spy); + sinon.assert.calledWith(spy, 'func1 some msg arg1, arg2'); }); it('should log warn level', () => { const spy = sandbox.spy(console, 'warn'); logger.log('warn', 'func1', 'some msg', [ 'arg1', 'arg2' ]); sinon.assert.calledOnce(spy); - + sinon.assert.calledWith(spy, 'func1 some msg arg1, arg2'); }); it('should log info level', () => { const spy = sandbox.spy(console, 'info'); logger.log('info', 'func1', 'some msg', [ 'arg1', 'arg2' ]); sinon.assert.calledOnce(spy); - + sinon.assert.calledWith(spy, 'func1 some msg arg1, arg2'); }); it('should log verbose level', () => { const spy = sandbox.spy(console, 'log'); logger.log('verbose', 'func1', 'some msg', [ 'arg1', 'arg2' ]); sinon.assert.calledOnce(spy); - + sinon.assert.calledWith(spy, 'func1 some msg arg1, arg2'); }); it('should log error level', () => { const spy = sandbox.spy(console, 'error'); logger.log('error', 'func1', 'some msg', [ 'arg1', 'arg2' ]); sinon.assert.calledOnce(spy); - + sinon.assert.calledWith(spy, 'func1 some msg arg1, arg2'); }); }); diff --git a/packages/composer-common/test/log/logger.js b/packages/composer-common/test/log/logger.js index 7e86dfa83c..adbf814095 100644 --- a/packages/composer-common/test/log/logger.js +++ b/packages/composer-common/test/log/logger.js @@ -16,434 +16,269 @@ const Logger = require('../../lib/log/logger'); const Tree = require('../../lib/log/tree.js'); -const TreeNode = require('../../lib/log/node.js'); -const fs = require('fs'); -const mkdirp = require('mkdirp'); + const WinstonInjector = require('../../lib/log/winstonInjector.js'); const chai = require('chai'); - +const should = chai.should(); chai.use(require('chai-things')); const mockery = require('mockery'); const sinon = require('sinon'); describe('Logger', () => { + let sandbox; - describe('#constructor', () => { - - it ('should setup default padding', ()=>{ - let logger = new Logger('testcode'); - logger.className.should.equals('testcode'); - logger.str25.length.should.equal(25); - logger.str25.should.equals(' '); + beforeEach(() => { + Logger.reset(); + mockery.enable({ + warnOnReplace: false, + warnOnUnregistered: false }); - + sandbox = sinon.sandbox.create(); }); - describe('#intlog', ()=>{ + afterEach(() => { + sandbox.restore(); + mockery.deregisterAll(); + Logger.reset(); + }); - let sandbox; + describe('#setLogLevel', () => { - beforeEach(()=>{ - delete Logger._envDebug; - delete process.env.DEBUG; - delete Logger._config; - delete Logger._clInstances; - sandbox = sinon.sandbox.create(); + it('should fail for an unrecognized log level', () => { + (() => { + Logger.setLogLevel('BLAH'); + }).should.throw(/Unrecognized log level BLAH/); }); - afterEach(()=>{ - delete Logger._envDebug; - delete process.env.DEBUG; - delete Logger._config; - delete Logger._clInstances; - sandbox.restore(); + ['info', 'debug', 'warn', 'error', 'verbose', 'INFO', 'DEBUG', 'WARN', 'ERROR', 'VERBOSE'].forEach((logLevel) => { + it(`should not fail for a recognized log level ${logLevel}`, () => { + (() => { + Logger.setLogLevel(logLevel); + }).should.not.throw(); + }); }); - it('should log to the functional logger', () => { - let stubLogger= { - log: sinon.stub() - }; - Logger.setFunctionalLogger(stubLogger); - Logger._envDebug='composer[debug]:*'; - let logger = new Logger('ScriptManager'); - logger.intlog('debug','methodname','message'); - sinon.assert.calledOnce(stubLogger.log); - sinon.assert.calledWith(stubLogger.log, 'debug', sinon.match(/ScriptManager.*methodname\(\)/), 'message'); - }); + }); - it('should make the callback to get extra data', () => { - let stubLogger= { - log: sinon.stub() - }; + ['info', 'debug', 'warn', 'error', 'verbose'].forEach((logLevel) => { - let callbackFn = sinon.stub().returns('data'); - Logger.setCallBack(callbackFn); - Logger.setFunctionalLogger(stubLogger); - Logger._envDebug='composer[debug]:*'; - let logger = new Logger('ScriptManager'); + describe(`#${logLevel}`, () => { - logger.intlog('debug','methodname','message'); - sinon.assert.calledOnce(stubLogger.log); - sinon.assert.calledWith(stubLogger.log, 'debug', sinon.match(/ScriptManager.*methodname\(\)/), 'message'); - sinon.assert.calledOnce(callbackFn); - }); + it('should log the message to the functional logger', () => { + const functionalLogger = { + log: sinon.stub() + }; + Logger.setFunctionalLogger(functionalLogger); + const logger = Logger.getLog('ScriptManager'); + logger[logLevel]('Method', 'Message'); + sinon.assert.calledOnce(functionalLogger.log); + sinon.assert.calledWith(functionalLogger.log, logLevel, sinon.match(/ScriptManager.*Method\(\)/), 'Message'); + }); - it('should make the callback to get extra data - but it returns undefined', () => { - let stubLogger= { - log: sinon.stub() - }; + it('should log the message and arguments to the functional logger', () => { + const functionalLogger = { + log: sinon.stub() + }; + Logger.setFunctionalLogger(functionalLogger); + const logger = Logger.getLog('ScriptManager'); + logger[logLevel]('Method', 'Message', 'Data'); + sinon.assert.calledOnce(functionalLogger.log); + sinon.assert.calledWith(functionalLogger.log, logLevel, sinon.match(/ScriptManager.*Method\(\)/), 'Message', ['Data']); + }); - let callbackFn = sinon.stub().returns(undefined); - Logger.setCallBack(callbackFn); - Logger.getCallBack().should.equal(callbackFn); - Logger.setFunctionalLogger(stubLogger); - Logger._envDebug='composer[debug]:*'; - let logger = new Logger('ScriptManager'); + it('should log an error to the functional logger', () => { + const functionalLogger = { + log: sinon.stub() + }; + Logger.setFunctionalLogger(functionalLogger); + const logger = Logger.getLog('ScriptManager'); + const error = new Error('such error'); + logger[logLevel]('Method', 'Message', error); + sinon.assert.calledOnce(functionalLogger.log); + sinon.assert.calledWith(functionalLogger.log, logLevel, sinon.match(/ScriptManager.*Method\(\)/), 'Message', [{ + stack: `{${error.name}}${error.message} ${error.stack}`.match(/[^\r\n]+/g) + }]); + }); + + it('should not log the message to the functional logger if the log level is lower', () => { + const useLogLevels = { + error: 'none', + warn: 'error', + info: 'warn', + verbose: 'info', + debug: 'verbose' + }; + const useLogLevel = useLogLevels[logLevel]; + Logger.setLogLevel(useLogLevel); + const functionalLogger = { + log: sinon.stub() + }; + Logger.setFunctionalLogger(functionalLogger); + const logger = Logger.getLog('ScriptManager'); + logger[logLevel]('Method', 'Message'); + sinon.assert.notCalled(functionalLogger.log); + }); - logger.intlog('debug','methodname','message'); - sinon.assert.calledOnce(stubLogger.log); - sinon.assert.calledWith(stubLogger.log, 'debug', sinon.match(/ScriptManager.*methodname\(\)/), 'message'); - sinon.assert.calledOnce(callbackFn); }); - it('should log to the functional logger, multiargs', () => { - let stubLogger= { + }); + + describe('#entry', () => { + + it('should log to the functional logger', () => { + const functionalLogger = { log: sinon.stub() }; - Logger.setFunctionalLogger(stubLogger); - Logger._envDebug='composer[debug]:*'; - let logger = new Logger('ScriptManager'); - - logger.intlog('debug','methodname','message','arg1','arg2','arg3'); - sinon.assert.calledOnce(stubLogger.log); - sinon.assert.calledWith(stubLogger.log, 'debug', sinon.match(/ScriptManager.*methodname\(\)/), 'message',['arg1','arg2','arg3']); + Logger.setFunctionalLogger(functionalLogger); + const logger = Logger.getLog('ScriptManager'); + logger.entry('Method', 'Message', 'Data'); + sinon.assert.calledOnce(functionalLogger.log); + sinon.assert.calledWith(functionalLogger.log, 'debug', sinon.match(/ScriptManager.*Method\(\)/), '>', ['Message', 'Data']); }); - it('should log to the functional logger, errors', () => { - let stubLogger= { + it('should not log the message to the functional logger if the log level is lower', () => { + Logger.setLogLevel('none'); + const functionalLogger = { log: sinon.stub() }; - Logger.setFunctionalLogger(stubLogger); - Logger._envDebug='composer[debug]:*'; - let logger = new Logger('ScriptManager'); - - let err = new Error('Computer says no'); - err.cause = new Error('The diodes on my left side hurt'); - - logger.intlog('debug','methodname','message','arg1',err,'arg3'); - sinon.assert.calledOnce(stubLogger.log); - sinon.assert.calledWith(stubLogger.log, 'debug', sinon.match(/ScriptManager.*methodname\(\)/), 'message',['arg1',{'stack':sinon.match.any},'arg3']); + Logger.setFunctionalLogger(functionalLogger); + const logger = Logger.getLog('ScriptManager'); + logger.entry('Method', 'Message', 'Data'); + sinon.assert.notCalled(functionalLogger.log); }); }); - describe('#specificLevelMethods', () => { - let logger; - let levelsandbox; - - before(()=>{ - Logger._envDebug='composer[debug]:*'; - logger = Logger.getLog('ScriptManager'); - logger.logLevel=99; - }); - - beforeEach(() => { - levelsandbox = sinon.sandbox.create(); - levelsandbox.stub(logger,'intlog'); - }); - - afterEach(() => { - levelsandbox.restore(); - }); - + describe('#exit', () => { - - it('warn method should call warn level, no args', () => { - logger.warn('Method', 'Message', 'Data'); - sinon.assert.calledOnce(logger.intlog); - sinon.assert.calledWith(logger.intlog, 'warn', 'Method','Message','Data'); - }); - - it('debug method should call debug level, no args', () => { - logger.debug('Method', 'Message', 'Data'); - sinon.assert.calledOnce(logger.intlog); - sinon.assert.calledWith(logger.intlog, 'debug', 'Method','Message','Data'); + it('should log to the functional logger', () => { + const functionalLogger = { + log: sinon.stub() + }; + Logger.setFunctionalLogger(functionalLogger); + const logger = Logger.getLog('ScriptManager'); + logger.exit('Method', 'Message', 'Data'); + sinon.assert.calledOnce(functionalLogger.log); + sinon.assert.calledWith(functionalLogger.log, 'debug', sinon.match(/ScriptManager.*Method\(\)/), '<', ['Message', 'Data']); }); - it('info method should call debug level, no args', () => { - logger.info('Method', 'Message', 'Data'); - sinon.assert.calledOnce(logger.intlog); - sinon.assert.calledWith(logger.intlog, 'info', 'Method','Message','Data'); + it('should not log the message to the functional logger if the log level is lower', () => { + Logger.setLogLevel('none'); + const functionalLogger = { + log: sinon.stub() + }; + Logger.setFunctionalLogger(functionalLogger); + const logger = Logger.getLog('ScriptManager'); + logger.exit('Method', 'Message', 'Data'); + sinon.assert.notCalled(functionalLogger.log); }); - it('verbose method should call debug level, no args', () => { - logger.verbose('Method', 'Message', 'Data'); - sinon.assert.calledOnce(logger.intlog); - sinon.assert.calledWith(logger.intlog, 'verbose', 'Method','Message','Data'); - }); + }); - it('error method should call debug level, no args', () => { - logger.error('Method', 'Message', 'Data'); - sinon.assert.calledOnce(logger.intlog); - sinon.assert.calledWith(logger.intlog, 'error', 'Method','Message','Data'); - }); + describe('#getSelectionTree', () => { - it('entry method should call debug level, no args', () => { - logger.entry('Method', 'Message', 'Data'); - sinon.assert.calledOnce(logger.intlog); - sinon.assert.calledWith(logger.intlog, 'debug', 'Method','>','Message','Data'); + it('should return null by default', () => { + should.equal(Logger.getSelectionTree(), null); }); - it('exit method should call debug level, no args', () => { - logger.exit('Method', 'Message', 'Data'); - sinon.assert.calledOnce(logger.intlog); - sinon.assert.calledWith(logger.intlog, 'debug', 'Method','<','Message','Data'); - }); }); - describe('#specificLevelMethods notincluded', () => { - let logger; - let levelsandbox; - - before(()=>{ - Logger._envDebug='composer[debug]:*'; - logger = Logger.getLog('ScriptManager'); - logger.logLevel=99; - logger.include=false; - }); + describe('#setSelectionTree', () => { - beforeEach(() => { - levelsandbox = sinon.sandbox.create(); - levelsandbox.stub(logger,'intlog'); + it('should set a new selection tree', () => { + const tree = sinon.createStubInstance(Tree); + Logger.setSelectionTree(tree); + Logger.getSelectionTree().should.equal(tree); }); - afterEach(() => { - Logger.__reset(); - levelsandbox.restore(); - }); + }); - it('warn method should call warn level, no args', () => { - logger.warn('Method', 'Message', 'Data'); - sinon.assert.notCalled(logger.intlog); - }); + describe('#getFunctionalLogger', () => { - it('debug method should call debug level, no args', () => { - logger.debug('Method', 'Message', 'Data'); - sinon.assert.notCalled(logger.intlog); + it('should return null by default', () => { + should.equal(Logger.getFunctionalLogger(), null); }); - it('info method should call debug level, no args', () => { - logger.info('Method', 'Message', 'Data'); - sinon.assert.notCalled(logger.intlog); - }); + }); - it('verbose method should call debug level, no args', () => { - logger.verbose('Method', 'Message', 'Data'); - sinon.assert.notCalled(logger.intlog); - }); + describe('#setFunctionalLogger', () => { - it('error method should call debug level, no args', () => { - logger.error('Method', 'Message', 'Data'); - sinon.assert.notCalled(logger.intlog); - }); + it('should set a new fmockConfigunctional logger', () => { + const logger = { + log: () => { - it('entry method should call debug level, no args', () => { - logger.entry('Method', 'Message', 'Data'); - sinon.assert.notCalled(logger.intlog); + } + }; + Logger.setFunctionalLogger(logger); + Logger.getFunctionalLogger().should.equal(logger); }); - it('exit method should call debug level, no args', () => { - logger.exit('Method', 'Message', 'Data'); - sinon.assert.notCalled(logger.intlog); - }); }); - describe('#setLoggerCfg',()=>{ - let sandbox; + describe('#getDebugEnv', () => { - beforeEach(()=>{ - Logger.__reset(); - sandbox = sinon.sandbox.create(); + beforeEach(() => { + delete process.env.DEBUG; + delete Logger._envDebug; }); - afterEach(()=>{ - Logger.__reset(); - sandbox.restore(); + afterEach(() => { + delete process.env.DEBUG; + delete Logger._envDebug; }); - it('set the cfg, with force defaulting to false',()=>{ - let cfg = { - 'logger': './winstonInjector.js', - 'debug': 'composer[debug]:*', - 'console': { - 'maxLevel': 'error' - }, - 'file': { - 'maxLevel': 'none' - } - }; - - sandbox.stub(Logger,'_loadLogger'); - sandbox.stub(Logger,'_setupLog'); - Logger.setLoggerCfg(cfg); - sinon.assert.calledOnce(Logger._loadLogger); - sinon.assert.notCalled(Logger._setupLog); - + it('should return DEBUG environment variable if set', () => { + process.env.DEBUG = 'composer:ScriptManager'; + Logger.getDebugEnv().should.equal('composer:ScriptManager'); }); - it('set the cfg, with force true',()=>{ - let cfg = { - 'logger': './winstonInjector.js', - 'debug': 'composer[debug]:*', - 'console': { - 'maxLevel': 'error' - }, - 'file': { - 'maxLevel': 'none' - } - }; - - sandbox.stub(Logger,'_loadLogger'); - sandbox.stub(Logger,'_setupLog'); - Logger.getLog('wibble'); - Logger.setLoggerCfg(cfg,true); - - - sinon.assert.calledOnce(Logger._loadLogger); - sinon.assert.calledTwice(Logger._setupLog); + it('should return _envDebug property if set', () => { + Logger._envDebug = 'composer:Connection'; + Logger.getDebugEnv().should.equal('composer:Connection'); }); - it('set the cfg twice, with force true',()=>{ - let cfg = { - 'logger': './winstonInjector.js', - 'debug': 'composer[debug]:*', - 'console': { - 'maxLevel': 'error' - }, - 'file': { - 'maxLevel': 'none' - } - }; - sandbox.stub(Logger,'_loadLogger'); - sandbox.stub(Logger,'_setupLog'); - Logger.setLoggerCfg(cfg,true); - Logger.getLog('wibble'); - Logger.setLoggerCfg(cfg,true); - sinon.assert.calledTwice(Logger._loadLogger); - sinon.assert.calledTwice(Logger._setupLog); + it('should return empty string when neither DEBUG or _envDebug are set', () => { + Logger.getDebugEnv().should.equal(''); }); - }); - - describe('#getLoggerCfg', () => { - let sandbox; - beforeEach(()=>{ - Logger.__reset(); - - mockery.enable({ - warnOnReplace: false, - warnOnUnregistered: false - }); + }); - sandbox = sinon.sandbox.create(); - }); + describe('#getLoggerConfig', () => { - afterEach(()=>{ - mockery.deregisterAll(); - Logger.__reset(); - sandbox.restore(); + it('should return the default winston logger', () => { + Logger.getLoggerConfig().logger.should.equal('./winstonInjector.js'); }); - - it('should load the config module and use settings from that', () => { + it('should load the config module but ignore a missing composer.debug setting', () => { const mockConfig = { has: sinon.stub(), get: sinon.stub() }; - mockConfig.has.withArgs('composer.log.logger').returns(true); - mockConfig.get.withArgs('composer.log.logger').returns('./myOwnLogger.js'); - mockConfig.has.withArgs('composer.log.file').returns(true); - mockConfig.get.withArgs('composer.log.file').returns('filename'); - mockConfig.has.withArgs('composer.log.debug').returns(true); - mockConfig.get.withArgs('composer.log.debug').returns('composer[debug]:*'); - mockConfig.has.withArgs('composer.log.console').returns(true); - mockConfig.get.withArgs('composer.log.console').returns('console'); + mockConfig.has.withArgs('composer.debug').returns(false); + mockConfig.get.withArgs('composer.debug').throws(new Error('such error')); mockery.registerMock('config', mockConfig); - - let treeStub = sinon.createStubInstance(Tree); - sandbox.stub(Logger,'_parseLoggerConfig').returns(treeStub); - - - let localConfig = Logger.processLoggerConfig(); - sinon.assert.calledOnce(Logger._parseLoggerConfig); - localConfig.logger.should.equal('./myOwnLogger.js'); - localConfig.file.should.equal('filename'); - localConfig.debug.should.equal('composer[debug]:*'); - localConfig.console.should.equal('console'); + Logger.getLoggerConfig().logger.should.equal('./winstonInjector.js'); }); - - it('should load the config module and use no settings as not present', () => { + it('should load the config module and use a present composer.debug setting', () => { const mockConfig = { has: sinon.stub(), get: sinon.stub() }; - mockConfig.has.withArgs('composer.log.logger').returns(false); - mockConfig.has.withArgs('composer.log.file').returns(false); - mockConfig.has.withArgs('composer.log.debug').returns(false); - mockConfig.has.withArgs('composer.log.console').returns(false); - + mockConfig.has.withArgs('composer.debug').returns(true); + mockConfig.get.withArgs('composer.debug').returns({ + logger: 'foolog' + }); mockery.registerMock('config', mockConfig); - - let treeStub = sinon.createStubInstance(Tree); - sandbox.stub(Logger,'_parseLoggerConfig').returns(treeStub); - - let localConfig = Logger.processLoggerConfig(); - sinon.assert.calledOnce(Logger._parseLoggerConfig); - localConfig.logger.should.equal('./winstonInjector.js'); - - localConfig.file.maxLevel.should.equal('silly'); - localConfig.debug.should.equal('composer[error]:*'); - localConfig.console.maxLevel.should.equal('none'); - }); - - }); - - describe('#getLoggerCfg', () => { - let sandbox; - - beforeEach(()=>{ - Logger.__reset(); - sandbox = sinon.sandbox.create(); - }); - - afterEach(()=>{ - Logger.__reset(); - sandbox.restore(); - }); - - it('should return the correct set of cfg',()=>{ - Logger.getLog('randomname'); - sinon.assert.match(Logger.getLoggerCfg(),{}); + Logger.getLoggerConfig().logger.should.equal('foolog'); }); }); describe('#getLog', () => { - let sandbox; - - beforeEach(()=>{ - Logger.__reset(); - sandbox = sinon.sandbox.create(); - }); - - afterEach(()=>{ - Logger.__reset(); - sandbox.restore(); - }); it('should return a new logger', () => { Logger.getLog('ScriptManager').should.be.an.instanceOf(Logger); @@ -461,95 +296,84 @@ describe('Logger', () => { describe('#_setupLog', () => { - let sandbox; - - afterEach(()=>{ - Logger.__reset(); - sandbox.restore(); - }); - beforeEach(() => { - Logger.__reset(); - sandbox = sinon.sandbox.create(); + const loggerConfig = { + logger: 'foolog', + config: { + log: 'config', + more: 'details' + } + }; + const loggerModule = { + getLogger: sinon.stub() + }; + const mockLogger = {}; + loggerModule.getLogger.returns(mockLogger); + mockery.registerMock('foolog', loggerModule); + sandbox.stub(Logger, 'getLoggerConfig').returns(loggerConfig); }); it('should handle a logger class that should be included', () => { const composerLogger = { className: 'Connection' }; - let treeStub = sinon.createStubInstance(Tree); - let nodeStub = sinon.createStubInstance(TreeNode); - sandbox.stub(Logger, 'getLoggerCfg').returns({'config':'set'}); - sandbox.stub(Logger, '_loadLogger').returns(composerLogger); - sandbox.stub(Logger,'getSelectionTree').returns(treeStub); - treeStub.getNode.returns(nodeStub); - nodeStub.isIncluded.returns(true); - nodeStub.getLogLevel.returns(4); + sandbox.stub(Logger, 'getDebugEnv').returns('composer:Connection'); Logger._setupLog(composerLogger); composerLogger.include.should.be.true; - composerLogger.logLevel.should.equal(4); }); - it('should handle a logger class that should be included (called twice)', () => { + it('should handle a logger class that should be included and cache the tree/logger', () => { const composerLogger = { className: 'Connection' }; - let treeStub = sinon.createStubInstance(Tree); - let nodeStub = sinon.createStubInstance(TreeNode); - sandbox.stub(Logger, 'getLoggerCfg').returns({'config':'set'}); - sandbox.stub(Logger, '_loadLogger').returns(composerLogger); - sandbox.stub(Logger,'getSelectionTree').returns(treeStub); - treeStub.getNode.returns(nodeStub); - nodeStub.isIncluded.returns(true); - nodeStub.getLogLevel.returns(4); + sandbox.stub(Logger, 'getDebugEnv').returns('composer:Connection'); Logger._setupLog(composerLogger); - - // call twice to test the protection logic + const tree = Logger.getSelectionTree(); + const logger = Logger.getFunctionalLogger(); Logger._setupLog(composerLogger); + tree.should.equal(Logger.getSelectionTree()); + logger.should.equal(Logger.getFunctionalLogger()); composerLogger.include.should.be.true; - composerLogger.logLevel.should.equal(4); }); - }); - - describe('#_parseLoggerConfig', () => { - let sandbox; - beforeEach(()=>{ - Logger.__reset(); - sandbox = sinon.sandbox.create(); + it('should handle a logger class that should not be included', () => { + const composerLogger = { + className: 'Connection' + }; + sandbox.stub(Logger, 'getDebugEnv').returns('composer:ScriptManager'); + Logger._setupLog(composerLogger); + composerLogger.include.should.be.false; }); - afterEach(()=>{ - Logger.__reset(); - sandbox.restore(); + it('should handle a logger class that should not be included and cache the tree/logger', () => { + const composerLogger = { + className: 'Connection' + }; + sandbox.stub(Logger, 'getDebugEnv').returns('composer:ScriptManager'); + Logger._setupLog(composerLogger); + const tree = Logger.getSelectionTree(); + const logger = Logger.getFunctionalLogger(); + Logger._setupLog(composerLogger); + tree.should.equal(Logger.getSelectionTree()); + logger.should.equal(Logger.getFunctionalLogger()); + composerLogger.include.should.be.false; }); - it('should not parse anything that is not composer', () => { - const configElements = {'debug':'express'}; - sandbox.stub(Logger, 'getDebugEnv').returns(); - const tree = Logger._parseLoggerConfig(configElements); - tree.should.be.an.instanceOf(Tree); - tree.root.isIncluded().should.be.false; - }); + }); - it('should parse a very wildcard logger configuration', () => { - const configElements = {'debug':'*'}; - sandbox.stub(Logger, 'getDebugEnv').returns(); - const tree = Logger._parseLoggerConfig(configElements); - tree.should.be.an.instanceOf(Tree); - tree.root.isIncluded().should.be.true; - }); + describe('#_parseLoggerConfig', () => { it('should parse a wildcard logger configuration', () => { - const configElements = {'debug':'composer:*'}; - sandbox.stub(Logger, 'getDebugEnv').returns(); + const configElements = []; + sandbox.stub(Logger, 'getDebugEnv').returns('composer:*'); const tree = Logger._parseLoggerConfig(configElements); tree.should.be.an.instanceOf(Tree); tree.root.isIncluded().should.be.true; }); it('should parse a single logger configuration', () => { - const configElements ={ 'debug':'composer:ScriptManager'}; + const configElements = []; + sandbox.stub(Logger, 'getDebugEnv').returns('composer:ScriptManager'); const tree = Logger._parseLoggerConfig(configElements); tree.should.be.an.instanceOf(Tree); tree.root.isIncluded().should.be.false; @@ -558,16 +382,9 @@ describe('Logger', () => { tree.getInclusion('ScriptManager').should.be.true; }); - it('should parse a single profile configuration', () => { - const configElements ={ 'debug':'composer:acls'}; - const tree = Logger._parseLoggerConfig(configElements); - tree.should.be.an.instanceOf(Tree); - tree.root.isIncluded().should.be.false; - tree.getInclusion('AccessController').should.be.true; - }); - it('should parse a multiple logger configuration', () => { - const configElements = {'debug':'composer:Connection,composer:ScriptManager'}; + const configElements = []; + sandbox.stub(Logger, 'getDebugEnv').returns('composer:Connection,composer:ScriptManager'); const tree = Logger._parseLoggerConfig(configElements); tree.should.be.an.instanceOf(Tree); tree.root.isIncluded().should.be.false; @@ -579,17 +396,8 @@ describe('Logger', () => { }); describe('#_loadLogger', () => { - let sandbox; - beforeEach(()=>{ - Logger.__reset(); - sandbox = sinon.sandbox.create(); - }); - - afterEach(()=>{ - Logger.__reset(); - sandbox.restore(); - }); + const configElements = [ 'Connection', 'ModelUtil', 'ScriptManager' ]; it('should load a logger', () => { const loggerConfig = { @@ -602,22 +410,20 @@ describe('Logger', () => { const loggerModule = { getLogger: sinon.stub() }; - let stubLogger = { - log: sinon.stub() - }; - loggerModule.getLogger.withArgs(loggerConfig).returns(stubLogger); + const mockLogger = {}; + loggerModule.getLogger.withArgs(loggerConfig.config, { debug: configElements }).returns(mockLogger); mockery.registerMock('foolog', loggerModule); - - let actualLogger = Logger._loadLogger(loggerConfig); + sandbox.stub(Logger, 'getLoggerConfig').returns(loggerConfig); + const actualLogger = Logger._loadLogger(configElements); sinon.assert.calledOnce(loggerModule.getLogger); - sinon.assert.calledWith(loggerModule.getLogger, loggerConfig); - actualLogger.should.equal(stubLogger); + sinon.assert.calledWith(loggerModule.getLogger, loggerConfig.config, { debug: configElements }); + actualLogger.should.equal(mockLogger); }); it('should use the null logger if the specified logger cannot be loaded', () => { const spy = sandbox.spy(console, 'error'); const loggerConfig = { - logger: 'dontexist', + logger: 'foolog', config: { log: 'config', more: 'details' @@ -627,68 +433,16 @@ describe('Logger', () => { getLogger: sinon.stub() }; const mockLogger = {}; - loggerModule.getLogger.withArgs(loggerConfig).returns(mockLogger); - sandbox.stub(Logger, 'getLoggerCfg').returns(loggerConfig); - const actualLogger = Logger._loadLogger(loggerConfig); - sinon.assert.calledWith(spy, sinon.match(/Failed to load logger module dontexist/)); + loggerModule.getLogger.withArgs(loggerConfig.config, { debug: configElements }).returns(mockLogger); + sandbox.stub(Logger, 'getLoggerConfig').returns(loggerConfig); + const actualLogger = Logger._loadLogger(configElements); + sinon.assert.calledWith(spy, sinon.match(/Failed to load logger module foolog/)); actualLogger.log('foo', 'bar'); }); }); - describe('#setCLIDefaults', () => { - let sandbox; - - beforeEach(()=>{ - Logger.__reset(); - delete process.env.DEBUG; - sandbox = sinon.sandbox.create(); - }); - - afterEach(()=>{ - Logger.__reset(); - sandbox.restore(); - }); - - it('should call setLoggerCfg with defaults for the cli', () => { - sandbox.stub(Logger,'setLoggerCfg'); - Logger.setCLIDefaults(); - sinon.assert.calledOnce(Logger.setLoggerCfg); - sinon.assert.calledWith(Logger.setLoggerCfg,{ - 'console': { - 'maxLevel': 'silly' - }, - 'debug' : 'composer[info]:*' - },true); - }); - - it('should call setLoggerCfg with defaults for the cli, custom debug string', () => { - sandbox.stub(Logger,'setLoggerCfg'); - process.env.DEBUG='Everything'; - Logger.setCLIDefaults(); - sinon.assert.calledOnce(Logger.setLoggerCfg); - sinon.assert.calledWith(Logger.setLoggerCfg,{ - 'console': { - 'maxLevel': 'silly' - }, - 'debug' : 'Everything' - },true); - }); - }); - describe('#WinstonInjector',()=>{ - - let sandbox; - - beforeEach(()=>{ - Logger.__reset(); - sandbox = sinon.sandbox.create(); - }); - - afterEach(()=>{ - Logger.__reset(); - sandbox.restore(); - }); it('additional code paths ',()=>{ let config = { 'console': { @@ -702,73 +456,11 @@ describe('Logger', () => { 'enabledLevel': 'debug', 'alwaysLevel': 'error' }}; - - WinstonInjector.getLogger(config); - - - }); - - it('dir for trace file can not be created',()=>{ - let config = { - 'console': { - 'enabledLevel': 'info', - 'alwaysLevel': 'none' - - }, - 'file': { - 'enabledLevel': 'debug', - 'alwaysLevel': 'error' - }}; - - WinstonInjector.getLogger(config); - }); - - it('no filename specified',()=>{ - let config = { - 'console': { - 'enabledLevel': 'info', - 'alwaysLevel': 'none' - - }, - 'file': { - 'filename':'not/createable/at/all', - 'enabledLevel': 'debug', - 'alwaysLevel': 'error', - 'maxFiles':'42' - }}; - sandbox.stub(fs,'existsSync').returns(false); - let syncStub = sandbox.stub(mkdirp, 'sync'); - syncStub.returns(); - - WinstonInjector.getLogger(config); + let configElements = {debug: {things:'here'}}; + WinstonInjector.getLogger(config,configElements); }); - - }); - - describe('#invokeAllLevels', ()=>{ - let logger = { - debug: sinon.stub(), - entry: sinon.stub(), - exit: sinon.stub(), - verbose: sinon.stub(), - info: sinon.stub(), - warn: sinon.stub(), - error: sinon.stub() - }; - - Logger.invokeAllLevels(logger); - - sinon.assert.calledOnce(logger.debug); - sinon.assert.calledOnce(logger.entry); - sinon.assert.calledOnce(logger.exit); - sinon.assert.calledOnce(logger.verbose); - sinon.assert.calledOnce(logger.info); - sinon.assert.calledOnce(logger.warn); - sinon.assert.calledOnce(logger.error); - - }); }); diff --git a/packages/composer-common/test/log/tree.js b/packages/composer-common/test/log/tree.js index 2d4f4c6e80..e29b3e95a8 100644 --- a/packages/composer-common/test/log/tree.js +++ b/packages/composer-common/test/log/tree.js @@ -21,72 +21,55 @@ require('chai').should(); describe('Tree', () => { + let tree; + beforeEach(() => { + tree = new Tree(); + }); describe('#setRootInclusion', () => { it('should set the root node to included', () => { - let tree = new Tree(false,4); tree.setRootInclusion(); tree.root.isIncluded().should.be.true; }); }); - describe('#setRootLevel', () => { - - it('should set the root node to included', () => { - let tree = new Tree(false,6); - tree.setRootLevel(4); - tree.root.getLogLevel().should.equal(4); - }); - - }); - describe('#addNode', () => { it('should add a not included node', () => { - let tree = new Tree(false,4); - tree.addNode('alpha', 4, false); + tree.addNode('alpha', false); const node = tree.root.findChild('alpha'); node.should.be.an.instanceOf(Node); node.isIncluded().should.be.false; - node.getLogLevel().should.equal(4); }); it('should add an included node', () => { - let tree = new Tree(false,4); - tree.addNode('alpha', 4,true); + tree.addNode('alpha', true); const node = tree.root.findChild('alpha'); node.should.be.an.instanceOf(Node); node.isIncluded().should.be.true; - node.getLogLevel().should.equal(4); }); it('should add a deep not included node', () => { - let tree = new Tree(true,1); - tree.addNode('alpha/beta/gamma/delta', 4, false); + tree.addNode('alpha/beta/gamma/delta', false); let node = tree.root.findChild('alpha'); node.should.be.an.instanceOf(Node); - node.isIncluded().should.be.true; - node.getLogLevel().should.equal(1); + node.isIncluded().should.be.false; node = node.findChild('beta'); node.should.be.an.instanceOf(Node); - node.getLogLevel().should.equal(1); - node.isIncluded().should.be.true; + node.isIncluded().should.be.false; node = node.findChild('gamma'); node.should.be.an.instanceOf(Node); - node.getLogLevel().should.equal(1); - node.isIncluded().should.be.true; + node.isIncluded().should.be.false; node = node.findChild('delta'); node.should.be.an.instanceOf(Node); - node.getLogLevel().should.equal(4); node.isIncluded().should.be.false; }); it('should add a deep included node', () => { - let tree = new Tree(false,4); - tree.addNode('alpha/beta/gamma/delta',4, true); + tree.addNode('alpha/beta/gamma/delta', true); let node = tree.root.findChild('alpha'); node.should.be.an.instanceOf(Node); node.isIncluded().should.be.false; @@ -102,8 +85,7 @@ describe('Tree', () => { }); it('should cope with an existing node', () => { - let tree = new Tree(false,4); - tree.addNode('alpha', 4,false); + tree.addNode('alpha', false); const node = tree.root.findChild('alpha'); node.should.be.an.instanceOf(Node); node.isIncluded().should.be.false; @@ -119,42 +101,36 @@ describe('Tree', () => { describe('#getInclusion', () => { it('should return false for no nodes and if root not included', () => { - let tree = new Tree(false,4); tree.getInclusion('alpha').should.be.false; tree.getInclusion('alpha/beta/gamma/delta').should.be.false; }); it('should return true for no nodes and if root included', () => { - let tree = new Tree(false,4); tree.setRootInclusion(); tree.getInclusion('alpha').should.be.true; tree.getInclusion('alpha/beta/gamma/delta').should.be.true; }); it('should return false for a node that is not included', () => { - let tree = new Tree(false,4); - tree.addNode('alpha',4, false); + tree.addNode('alpha', false); tree.getInclusion('alpha').should.be.false; tree.getInclusion('omega').should.be.false; }); it('should return true for a node that is included', () => { - let tree = new Tree(false,4); - tree.addNode('alpha',4, true); + tree.addNode('alpha', true); tree.getInclusion('alpha').should.be.true; tree.getInclusion('omega').should.be.false; }); it('should return false for a deep node that is not included', () => { - let tree = new Tree(false,4); - tree.addNode('alpha/beta/gama/delta', 4, false); + tree.addNode('alpha/beta/gama/delta', false); tree.getInclusion('alpha').should.be.false; tree.getInclusion('omega').should.be.false; }); it('should return true for a deep node that is included', () => { - let tree = new Tree(false,4); - tree.addNode('alpha/beta/gamma/delta', 4, true); + tree.addNode('alpha/beta/gamma/delta', true); tree.getInclusion('alpha/beta/gamma/delta').should.be.true; tree.getInclusion('omega').should.be.false; }); diff --git a/packages/composer-connector-embedded/test/embeddedconnection.js b/packages/composer-connector-embedded/test/embeddedconnection.js index 290919ee02..69b9ffe2ba 100644 --- a/packages/composer-connector-embedded/test/embeddedconnection.js +++ b/packages/composer-connector-embedded/test/embeddedconnection.js @@ -75,7 +75,6 @@ describe('EmbeddedConnection', () => { let mockContainer = sinon.createStubInstance(EmbeddedContainer); let mockLoggingService = sinon.createStubInstance(LoggingService); mockContainer.getLoggingService.returns(mockLoggingService); - mockLoggingService.getLoggerCfg.returns({}); EmbeddedConnection.createEngine(mockContainer).should.be.an.instanceOf(Engine); }); diff --git a/packages/composer-connector-server/cli.js b/packages/composer-connector-server/cli.js index d636304458..57c178ded0 100755 --- a/packages/composer-connector-server/cli.js +++ b/packages/composer-connector-server/cli.js @@ -30,12 +30,13 @@ const argv = require('yargs') const ConnectionProfileManager = require('composer-common').ConnectionProfileManager; const NetworkCardStoreManager = require('composer-common').NetworkCardStoreManager; const ConnectorServer = require('.'); +const ConsoleLogger = require('composer-common').ConsoleLogger; const io = require('socket.io')(argv.port); - -// setup the logger for CLIs, Console output only with 'composer[info]:*' setting const Logger = require('composer-common').Logger; -Logger.setCLIDefaults(); + +Logger.setFunctionalLogger(new ConsoleLogger()); + const LOG = Logger.getLog('ConnectorServer'); const method = 'main'; diff --git a/packages/composer-connector-server/test/connectorserver.js b/packages/composer-connector-server/test/connectorserver.js index 9ac9af38c5..ceff6ffbaf 100644 --- a/packages/composer-connector-server/test/connectorserver.js +++ b/packages/composer-connector-server/test/connectorserver.js @@ -22,7 +22,6 @@ const ConnectionManager = require('composer-common').ConnectionManager; const ConnectionProfileManager = require('composer-common').ConnectionProfileManager; const ConnectorServer = require('..'); const SecurityContext = require('composer-common').SecurityContext; -const Logger= require('composer-common').Logger; const uuid = require('uuid'); const should = require('chai').should(); @@ -59,7 +58,6 @@ describe('ConnectorServer', () => { let mockSocket; let mockBusinessNetworkDefinition; let connectorServer; - let mockLogger; let sandbox; beforeEach(() => { @@ -77,14 +75,6 @@ describe('ConnectorServer', () => { connectorServer = new ConnectorServer(mockBusinessNetworkCardStore, mockConnectionProfileManager, mockSocket); sandbox = sinon.sandbox.create(); sandbox.stub(BusinessNetworkDefinition, 'fromArchive').resolves(mockBusinessNetworkDefinition); - - mockLogger = { - log: sinon.stub() - }; - - - Logger.setFunctionalLogger(mockLogger); - }); afterEach(() => { diff --git a/packages/composer-connector-web/test/webconnection.js b/packages/composer-connector-web/test/webconnection.js index 79456fd8c7..5ac0d24606 100644 --- a/packages/composer-connector-web/test/webconnection.js +++ b/packages/composer-connector-web/test/webconnection.js @@ -88,7 +88,6 @@ describe('WebConnection', () => { let mockContainer = sinon.createStubInstance(WebContainer); let mockLoggingService = sinon.createStubInstance(LoggingService); mockContainer.getLoggingService.returns(mockLoggingService); - mockLoggingService.getLoggerCfg.returns({}); WebConnection.createEngine(mockContainer).should.be.an.instanceOf(Engine); }); diff --git a/packages/composer-playground-api/cli.js b/packages/composer-playground-api/cli.js index c9faab3d01..4542d0b3ee 100755 --- a/packages/composer-playground-api/cli.js +++ b/packages/composer-playground-api/cli.js @@ -36,10 +36,39 @@ const argv = require('yargs') .argv; const Logger = require('composer-common').Logger; -Logger.setCLIDefaults(); -const LOG = Logger.getLog('PlaygroundAPI'); +const util = require('util'); +const LOG = Logger.getLog('PlaygroundAPI'); +Logger.setFunctionalLogger({ + log: (level, method, msg, args) => { + args = args || []; + let formattedArguments = args.map((arg) => { + if (arg === Object(arg)) { + // It's an object, array, or function, so serialize it as JSON. + try { + return JSON.stringify(arg); + } catch (e) { + return arg; + } + } else { + return arg; + } + }).join(', '); + switch (level) { + case 'debug': + return console.log(util.format('%s %s %s', method, msg, formattedArguments)); + case 'warn': + return console.warn(util.format('%s %s %s', method, msg, formattedArguments)); + case 'info': + return console.info(util.format('%s %s %s', method, msg, formattedArguments)); + case 'verbose': + return console.log(util.format('%s %s %s', method, msg, formattedArguments)); + case 'error': + return console.error(util.format('%s %s %s', method, msg, formattedArguments)); + } + } +}); const method = 'main'; LOG.entry(method); diff --git a/packages/composer-playground/cli.js b/packages/composer-playground/cli.js index 9a83d7749b..3d8e02b8a1 100755 --- a/packages/composer-playground/cli.js +++ b/packages/composer-playground/cli.js @@ -34,10 +34,41 @@ const argv = require('yargs') const isDocker = require('is-docker'); const Logger = require('composer-common').Logger; const opener = require('opener'); +const util = require('util'); const LOG = Logger.getLog('Composer'); -Logger.setCLIDefaults(); +Logger.setFunctionalLogger({ + log: (level, method, msg, args) => { + args = args || []; + let formattedArguments = args.map((arg) => { + if (arg === Object(arg)) { + // It's an object, array, or function, so serialize it as JSON. + try { + return JSON.stringify(arg); + } catch (e) { + return arg; + } + } else { + return arg; + } + }).join(', '); + /* eslint-disable no-console */ + switch (level) { + case 'debug': + return console.log(util.format('%s %s %s', method, msg, formattedArguments)); + case 'warn': + return console.warn(util.format('%s %s %s', method, msg, formattedArguments)); + case 'info': + return console.info(util.format('%s %s %s', method, msg, formattedArguments)); + case 'verbose': + return console.log(util.format('%s %s %s', method, msg, formattedArguments)); + case 'error': + return console.error(util.format('%s %s %s', method, msg, formattedArguments)); + } + /* eslint-enable no-console */ + } +}); let config; if (process.env.COMPOSER_CONFIG) { diff --git a/packages/composer-playground/src/app/footer/footer.component.ts b/packages/composer-playground/src/app/footer/footer.component.ts index ca2af323f4..8943ea211b 100644 --- a/packages/composer-playground/src/app/footer/footer.component.ts +++ b/packages/composer-playground/src/app/footer/footer.component.ts @@ -47,6 +47,9 @@ export class FooterComponent implements OnInit { return this.aboutService.getVersions() .then((versions) => { this.playgroundVersion = versions.playground.version; + }) + .catch((err) => { + this.alertService.errorStatus$.next(err); }); } } diff --git a/packages/composer-playground/src/app/services/admin.service.ts b/packages/composer-playground/src/app/services/admin.service.ts index 5df8900c22..b8e7dbe503 100644 --- a/packages/composer-playground/src/app/services/admin.service.ts +++ b/packages/composer-playground/src/app/services/admin.service.ts @@ -31,6 +31,11 @@ export class AdminService { constructor(private alertService: AlertService, private businessNetworkCardStoreService: BusinessNetworkCardStoreService) { + Logger.setFunctionalLogger({ + // tslint:disable-next-line:no-empty + log: () => { + } + }); // The proxy connection manager defaults to http://localhost:15699, // but that is not suitable for anything other than development. if (ENV && ENV !== 'development') { diff --git a/packages/composer-playground/src/app/services/identity-card.service.ts b/packages/composer-playground/src/app/services/identity-card.service.ts index f77cb77001..ee6d6ecd4c 100644 --- a/packages/composer-playground/src/app/services/identity-card.service.ts +++ b/packages/composer-playground/src/app/services/identity-card.service.ts @@ -49,6 +49,11 @@ export class IdentityCardService { constructor(private adminService: AdminService, private localStorageService: LocalStorageService) { + Logger.setFunctionalLogger({ + // tslint:disable-next-line:no-empty + log: () => { + } + }); } public getCurrentCardRef(): string { diff --git a/packages/composer-runtime-embedded/lib/embeddedloggingservice.js b/packages/composer-runtime-embedded/lib/embeddedloggingservice.js index 178fd1fdaa..ac3d862126 100644 --- a/packages/composer-runtime-embedded/lib/embeddedloggingservice.js +++ b/packages/composer-runtime-embedded/lib/embeddedloggingservice.js @@ -90,24 +90,6 @@ class EmbeddedLoggingService extends LoggingService { return 'UnsetLogLevel'; } } - - /** - * Return the logger config... basically the usual default setting for debug - * Console only maxLevel error, and nothing file based - * @return {Object} config - console only - */ - getLoggerCfg(){ - return { - 'logger': './winstonInjector.js', - 'debug': 'composer[debug]:*', - 'console': { - 'maxLevel': 'error' - }, - 'file': { - 'maxLevel': 'none' - } - }; - } } module.exports = EmbeddedLoggingService; diff --git a/packages/composer-runtime-embedded/test/embeddedloggingservice.js b/packages/composer-runtime-embedded/test/embeddedloggingservice.js index d43f26d2f1..9b881ce20e 100644 --- a/packages/composer-runtime-embedded/test/embeddedloggingservice.js +++ b/packages/composer-runtime-embedded/test/embeddedloggingservice.js @@ -100,12 +100,4 @@ describe('EmbeddedLoggingService', () => { }); }); - - describe('#getLoggerCfg', () => { - - it('should call the console logger', () => { - loggingService.getLoggerCfg(); - }); - - }); }); diff --git a/packages/composer-runtime-hlfv1/lib/nodeloggingservice.js b/packages/composer-runtime-hlfv1/lib/nodeloggingservice.js index 999dd74533..46dc598eb0 100644 --- a/packages/composer-runtime-hlfv1/lib/nodeloggingservice.js +++ b/packages/composer-runtime-hlfv1/lib/nodeloggingservice.js @@ -15,8 +15,29 @@ 'use strict'; const LoggingService = require('composer-runtime').LoggingService; -const LOGLEVEL_KEY = 'ComposerLogCfg'; -const Logger = require('composer-common').Logger; + + +const LOG_LEVELS = { + CRITICAL: 0, + ERROR: 100, + WARNING: 200, + NOTICE: 300, + INFO: 400, + DEBUG: 500 +}; + +const LOOKUP_LOG_LEVELS = { + '-1': 'NOT_ENABLED', + 0: 'CRITICAL', + 100: 'ERROR', + 200: 'WARNING', + 300: 'NOTICE', + 400: 'INFO', + 500: 'DEBUG' +}; + +const LOGLEVEL_KEY = 'ComposerLogLevel'; + /** * Base class representing the logging service provided by a {@link Container}. * @protected @@ -29,92 +50,151 @@ class NodeLoggingService extends LoggingService { constructor() { super(); this.stub = null; + this.currentLogLevel = -1; } + /** + * Log a message. + * @private + * @param {string} message The message to log. + * @param {*} logLevel The log level. + */ + _outputMessage(message, logLevel) { + const timestamp = new Date().toISOString(); + const logStr = LOOKUP_LOG_LEVELS[logLevel].padEnd(8); + if (this.stub) { + const shortTxId = this.stub.getTxID().substring(0, 8); + console.log(timestamp, `[${shortTxId}]`, `[${logStr}]`, message); + } else { + console.log(timestamp, `[${logStr}]`, message); + } + } /** + * Initialise the logging service for the incoming request. + * This will need to stub for the request so it saves the stub for later use. + * And enables the logging level currently set. * - * @param {Object} stub node chaincode stub + * @param {any} stub The stub to save */ async initLogging(stub) { this.stub = stub; - - let json = await this.getLoggerCfg(); - Logger.setLoggerCfg(json,true); - Logger.setCallBack(function(){ - return stub.getTxID().substring(0, 8); - }); - if( json.origin && json.origin==='default-logger-module'){ - await this.setLoggerCfg(this.getDefaultCfg()); + if (this.currentLogLevel >= 0) { + return; } - + await this._enableLogging(); } /** - * - * @param {Object} cfg to set + * Enable logging for the current request based on the level set in the world state + * or the CORE_CHAINCODE_LOGGING_LEVEL environment variable. If neither are set + * then default to INFO. */ - async setLoggerCfg(cfg) { - await this.stub.putState(LOGLEVEL_KEY, Buffer.from(JSON.stringify(cfg))); + async _enableLogging() { + try { + let result = await this.stub.getState(LOGLEVEL_KEY); + if (result.length === 0) { + result = process.env.CORE_CHAINCODE_LOGGING_LEVEL; + if (!result) { + result = 'INFO'; + } + } + this.currentLogLevel = LOG_LEVELS[result] ? LOG_LEVELS[result] : LOG_LEVELS.INFO; + } + catch(err) { + this.currentLogLevel = LOG_LEVELS.INFO; + this.logWarning('failed to get logging level from world state: ' + err); + } } /** - * Return the logger config... basically the usual default setting for debug - * Console only. maxLevel needs to be high here as all the logs goto the stdout/stderr - * - * @returns {Object} configuration + * Write a critical message to the log. + * @param {string} message The message to write to the log. */ - async getLoggerCfg(){ - - let result = await this.stub.getState(LOGLEVEL_KEY); - if (result.length === 0) { - let d = this.getDefaultCfg(); - await this.setLoggerCfg(d); - return d; - - } else { - let json = JSON.parse(result.toString()); - return json; + logCritical(message) { + if (this.currentLogLevel >= LOG_LEVELS.CRITICAL) { + this._outputMessage(message, LOG_LEVELS.CRITICAL); } - } /** - * @returns {String} information to add + * Write a debug message to the log. + * @param {string} message The message to write to the log. */ - callback(){ - if (this.stub) { - const shortTxId = this.stub.getTxID().substring(0, 8); - return `[${shortTxId}]`; + logDebug(message) { + if (this.currentLogLevel >= LOG_LEVELS.DEBUG) { + this._outputMessage(message, LOG_LEVELS.DEBUG); + } + } - } else { - return('Warning - No stub'); + /** + * Write an error message to the log. + * @param {string} message The message to write to the log. + */ + logError(message) { + if (this.currentLogLevel >= LOG_LEVELS.ERROR) { + this._outputMessage(message, LOG_LEVELS.ERROR); + } + } + /** + * Write a informational message to the log. + * @param {string} message The message to write to the log. + */ + logInfo(message) { + if (this.currentLogLevel >= LOG_LEVELS.INFO) { + this._outputMessage(message, LOG_LEVELS.INFO); } + } + /** + * Write a notice message to the log. + * @param {string} message The message to write to the log. + */ + logNotice(message) { + if (this.currentLogLevel >= LOG_LEVELS.NOTICE) { + this._outputMessage(message, LOG_LEVELS.NOTICE); + } } /** - * @return {Object} the default cfg + * Write a warning message to the log. + * @param {string} message The message to write to the log. */ - getDefaultCfg(){ + logWarning(message) { + if (this.currentLogLevel >= LOG_LEVELS.WARNING) { + this._outputMessage(message, LOG_LEVELS.WARNING); + } + } - let envVariable = process.env.CORE_CHAINCODE_LOGGING_LEVEL; - if (!envVariable){ - envVariable = 'composer[error]:*'; + /** + * Set the log level for the runtime. + * @param {string} newLogLevel The new log level to apply. + */ + async setLogLevel(newLogLevel) { + newLogLevel = newLogLevel.toUpperCase(); + if (LOG_LEVELS[newLogLevel]) { + try { + await this.stub.putState(LOGLEVEL_KEY, newLogLevel); + this.currentLogLevel = LOG_LEVELS[newLogLevel]; + this.logWarning('Setting Composer log level to ' + newLogLevel); + } + catch(err) { + throw new Error('failed to set the new log level. ' + err); + } } - return { - 'file': { - 'maxLevel': 'none' - }, - 'console': { - 'maxLevel': 'silly' - }, - 'debug' : envVariable, - 'logger': './consolelogger.js', - 'origin':'default-runtime-hlfv1' - }; + else { + throw new Error(`${newLogLevel} is not a valid log level. Log level not changed.`); + } + } + + /** + * Get the current log level for the runtime. + * @return {string} the current log level. + */ + getLogLevel() { + return LOOKUP_LOG_LEVELS[this.currentLogLevel]; } } diff --git a/packages/composer-runtime-hlfv1/package.json b/packages/composer-runtime-hlfv1/package.json index d524595573..024c84f282 100644 --- a/packages/composer-runtime-hlfv1/package.json +++ b/packages/composer-runtime-hlfv1/package.json @@ -15,9 +15,7 @@ "postdoc": "npm run lint", "lint": "eslint .", "test": "nyc mocha test", - "start": "node start.js", - "mocha": "mocha test", - "nyc": "nyc mocha test" + "start": "node start.js" }, "repository": { "type": "git", diff --git a/packages/composer-runtime-hlfv1/test/composer.js b/packages/composer-runtime-hlfv1/test/composer.js index d84487339f..80a08a68fe 100644 --- a/packages/composer-runtime-hlfv1/test/composer.js +++ b/packages/composer-runtime-hlfv1/test/composer.js @@ -70,6 +70,23 @@ describe('Composer', () => { }); }); + it('initialise logging throws an error', () => { + sandbox.stub(shim, 'error').returns(); + let error = new Error('some loginit error'); + sinon.stub(composer.container, 'initLogging').rejects(error); + mockStub.getFunctionAndParameters.returns({fcn:'someFn', params:[]}); + mockEngine.init.resolves(); + + + return composer.Init(mockStub) + .then(() => { + sinon.assert.calledWith(composer._createContext, mockEngine, mockStub); + sinon.assert.notCalled(mockEngine.init); + sinon.assert.calledOnce(shim.error); + sinon.assert.calledWith(shim.error, error); + }); + }); + it('engine invoke throws an error', () => { sandbox.stub(shim, 'error').returns(); sinon.stub(composer.container, 'initLogging').resolves(); @@ -175,6 +192,23 @@ describe('Composer', () => { }); }); + + it('initialise logging throws an error', () => { + sandbox.stub(shim, 'error').returns(); + let error = new Error('some loginit error'); + sinon.stub(composer.container, 'initLogging').rejects(error); + mockStub.getFunctionAndParameters.returns({fcn:'someFn', params:[]}); + mockEngine.invoke.resolves(); + + return composer.Invoke(mockStub) + .then(() => { + sinon.assert.calledWith(composer._createContext, mockEngine, mockStub); + sinon.assert.notCalled(mockEngine.invoke); + sinon.assert.calledOnce(shim.error); + sinon.assert.calledWith(shim.error, error); + }); + }); + it('engine invoke throws an error', () => { sandbox.stub(shim, 'error').returns(); sinon.stub(composer.container, 'initLogging').resolves(); diff --git a/packages/composer-runtime-hlfv1/test/nodecontainer.js b/packages/composer-runtime-hlfv1/test/nodecontainer.js index 54720586b6..6730937980 100644 --- a/packages/composer-runtime-hlfv1/test/nodecontainer.js +++ b/packages/composer-runtime-hlfv1/test/nodecontainer.js @@ -18,18 +18,17 @@ const Container = require('composer-runtime').Container; const LoggingService = require('composer-runtime').LoggingService; const NodeContainer = require('../lib/nodecontainer'); const version = require('../package.json').version; -const ChaincodeStub = require('fabric-shim/lib/stub'); + require('chai').should(); const sinon = require('sinon'); describe('NodeContainer', () => { - let sandbox, container,mockStub; + let sandbox, container; beforeEach(() => { sandbox = sinon.sandbox.create(); container = new NodeContainer(); - mockStub = sinon.createStubInstance(ChaincodeStub); }); afterEach(() => { @@ -59,14 +58,13 @@ describe('NodeContainer', () => { }); }); + describe('#initLogging', () => { - describe('#getLoggingService', () => { - - it('should return the container logging service',async () => { - mockStub.getState.returns([]); - container.loggingService = { initLogging: sinon.stub() }; - await container.initLogging(mockStub); - + it('should initialise the logging service', () => { + let initLoggingStub = sinon.stub(container.getLoggingService(), 'initLogging').resolves(); + container.initLogging('a stub'); + sinon.assert.calledOnce(initLoggingStub); + sinon.assert.calledWith(initLoggingStub, 'a stub'); }); }); diff --git a/packages/composer-runtime-hlfv1/test/nodedatacollection.js b/packages/composer-runtime-hlfv1/test/nodedatacollection.js index 14a1ad7036..dedb9c98a5 100644 --- a/packages/composer-runtime-hlfv1/test/nodedatacollection.js +++ b/packages/composer-runtime-hlfv1/test/nodedatacollection.js @@ -45,10 +45,6 @@ describe('NodeDataCollection', () => { it('should be a type of DataCollection', () => { dataCollection.should.be.an.instanceOf(DataCollection); }); - - it('should produce something useful as toString', ()=>{ - dataCollection.toString().should.equal('[DataCollection: + anID]'); - }); }); describe('#get', () => { diff --git a/packages/composer-runtime-hlfv1/test/nodedataservice.js b/packages/composer-runtime-hlfv1/test/nodedataservice.js index 7b8ef6e3b0..8a292297d5 100644 --- a/packages/composer-runtime-hlfv1/test/nodedataservice.js +++ b/packages/composer-runtime-hlfv1/test/nodedataservice.js @@ -47,9 +47,6 @@ describe('NodeDataService', () => { it('should be a type of DataService', () => { dataService.should.be.an.instanceOf(DataService); }); - it('should produce something useful as toString', ()=>{ - dataService.toString().should.equal('DataService'); - }); }); describe('#createCollection', () => { diff --git a/packages/composer-runtime-hlfv1/test/nodehttpservice.js b/packages/composer-runtime-hlfv1/test/nodehttpservice.js index 872e174f2c..82fa6584c9 100644 --- a/packages/composer-runtime-hlfv1/test/nodehttpservice.js +++ b/packages/composer-runtime-hlfv1/test/nodehttpservice.js @@ -44,9 +44,6 @@ describe('NodeHTTPService', () => { it('should create an instance', () => { httpService.should.be.an.instanceOf(HTTPService); }); - it('should produce something useful as toString', ()=>{ - httpService.toString().should.equal('Instance of HTTPService'); - }); }); describe('#post', () => { diff --git a/packages/composer-runtime-hlfv1/test/nodeloggingservice.js b/packages/composer-runtime-hlfv1/test/nodeloggingservice.js index fe80f5f0ce..a42a274803 100644 --- a/packages/composer-runtime-hlfv1/test/nodeloggingservice.js +++ b/packages/composer-runtime-hlfv1/test/nodeloggingservice.js @@ -15,7 +15,6 @@ 'use strict'; const LoggingService = require('composer-runtime').LoggingService; -const Logger = require('composer-common').Logger; const NodeLoggingService = require('../lib/nodeloggingservice'); const ChaincodeStub = require('fabric-shim/lib/stub'); @@ -23,14 +22,12 @@ const chai = require('chai'); chai.should(); chai.use(require('chai-as-promised')); const sinon = require('sinon'); -let chaiSubset = require('chai-subset'); -chai.use(chaiSubset); describe('NodeLoggingService', () => { let loggingService; let sandbox, mockStub; - + let outputStub; beforeEach(() => { loggingService = new NodeLoggingService(); @@ -53,66 +50,290 @@ describe('NodeLoggingService', () => { }); + describe('#logCritical', () => { + beforeEach(() => { + outputStub = sinon.stub(loggingService, '_outputMessage'); + }); + + it('should call the console logger and log', () => { + loggingService.currentLogLevel = 500; //debug level + loggingService.logCritical('doge1'); + sinon.assert.calledOnce(outputStub); + sinon.assert.calledWith(outputStub, 'doge1'); + + loggingService.currentLogLevel = 0; //critical + loggingService.logCritical('doge'); + sinon.assert.calledTwice(outputStub); + }); + + it('should call the console logger but not log', () => { + loggingService.currentLogLevel = -1; //off + loggingService.logCritical('doge'); + sinon.assert.notCalled(outputStub); + }); + + }); + + describe('#logDebug', () => { + beforeEach(() => { + outputStub = sinon.stub(loggingService, '_outputMessage'); + }); - describe('#getDefaultCfg', () => { + it('should call the console logger', () => { + loggingService.currentLogLevel = 500; // debug + loggingService.logDebug('doge2'); + sinon.assert.calledOnce(outputStub); + sinon.assert.calledWith(outputStub, 'doge2'); + }); - it('should return the default values', () => { - let value = loggingService.getDefaultCfg(); - value.debug.should.equal('composer[error]:*'); + it('should call the console logger but not log', () => { + loggingService.currentLogLevel = 400; // info + loggingService.logDebug('doge'); + sinon.assert.notCalled(outputStub); }); - it('should return the enviroment variable values', () => { - process.env.CORE_CHAINCODE_LOGGING_LEVEL='wibble'; - let value = loggingService.getDefaultCfg(); - value.debug.should.equal('wibble'); + }); + + describe('#logError', () => { + beforeEach(() => { + outputStub = sinon.stub(loggingService, '_outputMessage'); + }); + + it('should call the console logger', () => { + loggingService.currentLogLevel = 500; //debug + loggingService.logError('doge3'); + sinon.assert.calledOnce(outputStub); + sinon.assert.calledWith(outputStub, 'doge3'); + + loggingService.currentLogLevel = 100; //error + loggingService.logError('doge'); + sinon.assert.calledTwice(outputStub); + }); + + it('should call the console logger but not log', () => { + loggingService.currentLogLevel = 0; // critical + loggingService.logError('doge'); + sinon.assert.notCalled(outputStub); }); }); - describe('#callback', () => { + describe('#logInfo', () => { + beforeEach(() => { + outputStub = sinon.stub(loggingService, '_outputMessage'); + }); + + it('should call the console logger', () => { + loggingService.currentLogLevel = 500; //debug + loggingService.logInfo('doge4'); + sinon.assert.calledOnce(outputStub); + sinon.assert.calledWith(outputStub, 'doge4'); - it('should return warning if no stub', () => { - loggingService.stub = undefined; - loggingService.callback().should.equal('Warning - No stub'); + loggingService.currentLogLevel = 400; //info + loggingService.logInfo('doge'); + sinon.assert.calledTwice(outputStub); }); - it('should return the fake tx id', () => { - loggingService.callback().should.equal('[1548a95f]'); + it('should call the console logger but not log', () => { + loggingService.currentLogLevel = 300; //notice + loggingService.logInfo('doge'); + sinon.assert.notCalled(outputStub); }); }); + describe('#logNotice', () => { + beforeEach(() => { + outputStub = sinon.stub(loggingService, '_outputMessage'); + }); - describe('#getLoggerCfg',async () => { + it('should call the console logger', () => { + loggingService.currentLogLevel = 500; //debug + loggingService.logNotice('doge5'); + sinon.assert.calledOnce(outputStub); + sinon.assert.calledWith(outputStub, 'doge5'); - it('should default if nothing in state', async () => { - loggingService.stub.getState.returns([]); - let result = await loggingService.getLoggerCfg(); - chai.expect(result).to.containSubset({'origin':'default-runtime-hlfv1'}); + loggingService.currentLogLevel = 300; //notice + loggingService.logNotice('doge'); + sinon.assert.calledTwice(outputStub); }); - it('should return what was in state',async () => { - loggingService.stub.getState.returns(JSON.stringify({batman:'hero'})); - let result = await loggingService.getLoggerCfg(); - chai.expect(result).to.containSubset({batman:'hero'}); + it('should call the console logger but not log', () => { + loggingService.currentLogLevel = 200; // warning + loggingService.logNotice('doge'); + sinon.assert.notCalled(outputStub); }); - mockStub.getState.returns(JSON.stringify({origin:'default-logger-module'})); + }); - describe('#initLogging', async () => { + describe('#logWarning', () => { + beforeEach(() => { + outputStub = sinon.stub(loggingService, '_outputMessage'); + }); + + it('should call the console logger', () => { + loggingService.currentLogLevel = 500; //debug + loggingService.logWarning('doge6'); + sinon.assert.calledOnce(outputStub); + sinon.assert.calledWith(outputStub, 'doge6'); + + loggingService.currentLogLevel = 200; //warning + loggingService.logWarning('doge'); + sinon.assert.calledTwice(outputStub); + }); + + it('should call the console logger but not log', () => { + loggingService.currentLogLevel = 100; //error + loggingService.logInfo('doge'); + sinon.assert.notCalled(outputStub); + }); + + + }); - it('should default if nothing in state', async () => { - mockStub.getState.returns(JSON.stringify({batman:'hero'})); - await loggingService.initLogging(mockStub); + describe('#initLogging', () => { + it('should init logging if not init', () => { + let enableStub = sinon.stub(loggingService, '_enableLogging').resolves(); + return loggingService.initLogging(mockStub) + .then(() => { + sinon.assert.calledOnce(enableStub); + }); }); - it('should return what was in state',async () => { - mockStub.getState.returns(JSON.stringify({origin:'default-logger-module'})); - await loggingService.initLogging(mockStub); - (Logger.getCallBack())(); + it('should no-op if logging already enabled', () => { + let enableStub = sinon.stub(loggingService, '_enableLogging').resolves(); + loggingService.currentLogLevel = 100; + return loggingService.initLogging(mockStub) + .then(() => { + sinon.assert.notCalled(enableStub); + }); }); }); + + + describe('#_enableLogging', () => { + + it('should get logging level from world state', () => { + mockStub.getState.resolves('WARNING'); + return loggingService._enableLogging() + .then(() => { + loggingService.currentLogLevel.should.equal(200); + }); + }); + + it('should get logging level from env', () => { + mockStub.getState.resolves(''); + process.env.CORE_CHAINCODE_LOGGING_LEVEL = 'DEBUG'; + return loggingService._enableLogging() + .then(() => { + loggingService.currentLogLevel.should.equal(500); + delete process.env.CORE_CHAINCODE_LOGGING_LEVEL; + }); + }); + + it('should default to INFO if no other source', () => { + mockStub.getState.resolves(''); + return loggingService._enableLogging() + .then(() => { + loggingService.currentLogLevel.should.equal(400); + }); + }); + + it('should default to INFO if getState returns unknown log level', () => { + mockStub.getState.resolves('ALEVEL'); + return loggingService._enableLogging() + .then(() => { + loggingService.currentLogLevel.should.equal(400); + }); + }); + + it('should default to INFO if env returns unknown log level', () => { + mockStub.getState.resolves(''); + process.env.CORE_CHAINCODE_LOGGING_LEVEL = 'ALEVEL'; + return loggingService._enableLogging() + .then(() => { + loggingService.currentLogLevel.should.equal(400); + delete process.env.CORE_CHAINCODE_LOGGING_LEVEL; + }); + }); + + it('should default to INFO if getState returns an error', () => { + mockStub.getState.rejects(new Error('an error')); + return loggingService._enableLogging() + .then(() => { + loggingService.currentLogLevel.should.equal(400); + }); + }); + + }); + + describe('#setLogLevel', () => { + it('should set the log level', () => { + mockStub.putState.resolves(); + loggingService.setLogLevel('notice') + .then(() => { + loggingService.currentLogLevel.should.equal(300); + sinon.assert.calledOnce(mockStub.putState); + sinon.assert.calledWith(mockStub.putState, 'ComposerLogLevel', 'NOTICE'); + }); + }); + + it('should throw error if putState fails', () => { + mockStub.putState.rejects(new Error('put failed')); + loggingService.setLogLevel('notice') + .should.be.rejectedWith(/put failed/); + }); + + it('should throw error if not a valid log level', () => { + loggingService.setLogLevel('rubbish') + .should.be.rejectedWith(/not a valid/); + }); + + + + }); + + describe('#getLogLevel', () => { + + it('should return correct log level string', () => { + + loggingService.currentLogLevel = -1; + loggingService.getLogLevel().should.equal('NOT_ENABLED'); + loggingService.currentLogLevel = 0; + loggingService.getLogLevel().should.equal('CRITICAL'); + loggingService.currentLogLevel = 100; + loggingService.getLogLevel().should.equal('ERROR'); + loggingService.currentLogLevel = 200; + loggingService.getLogLevel().should.equal('WARNING'); + loggingService.currentLogLevel = 300; + loggingService.getLogLevel().should.equal('NOTICE'); + loggingService.currentLogLevel = 400; + loggingService.getLogLevel().should.equal('INFO'); + loggingService.currentLogLevel = 500; + loggingService.getLogLevel().should.equal('DEBUG'); + + }); + + }); + + describe('#_outputMessage', () => { + + it('should output a message', () => { + sandbox.stub(console, 'log'); + mockStub.getTxID.returns('tx1'); + loggingService._outputMessage('a message', 500); + // should be called with timestamp, txn, loglevel, message + sinon.assert.calledWith(console.log, sinon.match.string, sinon.match(/tx1/), sinon.match(/DEBUG/), 'a message'); + }); + + it('should output a message if no stub provided', () => { + delete loggingService.stub; + sandbox.stub(console, 'log'); + loggingService._outputMessage('a message 2', 400); + sinon.assert.calledWith(console.log, sinon.match.string, sinon.match(/INFO/), 'a message 2'); + }); + }); }); diff --git a/packages/composer-runtime-web/lib/webloggingservice.js b/packages/composer-runtime-web/lib/webloggingservice.js index 94be90751b..f611ce2139 100644 --- a/packages/composer-runtime-web/lib/webloggingservice.js +++ b/packages/composer-runtime-web/lib/webloggingservice.js @@ -70,24 +70,6 @@ class WebLoggingService extends LoggingService { console.warn(message); } - /** - * Return the logger config... basically the usual default setting for debug - * Console only maxLevel error, and nothing file based - * @return {Object} logging configuration - */ - getLoggerCfg(){ - return { - 'logger': './winstonInjector.js', - 'debug': 'composer[debug]:*', - 'console': { - 'maxLevel': 'error' - }, - 'file': { - 'maxLevel': 'none' - } - }; - } - } module.exports = WebLoggingService; diff --git a/packages/composer-runtime-web/test/webloggingservice.js b/packages/composer-runtime-web/test/webloggingservice.js index 1c66f9e4cb..bfa7879269 100644 --- a/packages/composer-runtime-web/test/webloggingservice.js +++ b/packages/composer-runtime-web/test/webloggingservice.js @@ -109,11 +109,4 @@ describe('WebLoggingService', () => { }); - describe('#getLoggerCfg', () => { - - it('should call the console logger', () => { - loggingService.getLoggerCfg(); - }); - - }); }); diff --git a/packages/composer-runtime/lib/engine.js b/packages/composer-runtime/lib/engine.js index 518ee4071a..aa50b53d17 100644 --- a/packages/composer-runtime/lib/engine.js +++ b/packages/composer-runtime/lib/engine.js @@ -35,6 +35,7 @@ class Engine { */ constructor(container) { this.container = container; + this.installLogger(); const method = 'constructor'; LOG.entry(method); LOG.exit(method); @@ -53,27 +54,27 @@ class Engine { */ installLogger() { let loggingService = this.container.getLoggingService(); - let loggerCfg = loggingService.getLoggerCfg(); - Logger.setLoggerCfg(loggerCfg,true); - - } - - /** Internal method to set any log level - * @param {Context} context Context to use - * @param {String} level logLevel String - * - * @return {Promise} resolved when set - */ - _setLogLevel(context,level){ - if (level){ - return context.getLoggingService().getLoggerCfg() - .then((cfg)=>{ - let c = Logger.setLoggerCfg(Object.assign(cfg,{debug:level}),true); - return context.getLoggingService().setLoggerCfg(c); - }); - }else { - return Promise.resolve(); - } + let loggingProxy = { + log: (level, method, msg, args) => { + args = args || []; + let formattedArguments = args.map((arg) => { + return String(arg); + }).join(', '); + switch (level) { + case 'debug': + return loggingService.logDebug(util.format('@JS : %s %s %s', method, msg, formattedArguments)); + case 'warn': + return loggingService.logWarning(util.format('@JS : %s %s %s', method, msg, formattedArguments)); + case 'info': + return loggingService.logInfo(util.format('@JS : %s %s %s', method, msg, formattedArguments)); + case 'verbose': + return loggingService.logDebug(util.format('@JS : %s %s %s', method, msg, formattedArguments)); + case 'error': + return loggingService.logError(util.format('@JS : %s %s %s', method, msg, formattedArguments)); + } + } + }; + Logger.setFunctionalLogger(loggingProxy); } /** @@ -123,20 +124,22 @@ class Engine { throw new Error('The business network archive specified is not valid'); } - - + // Extract and validate the optional log level property. + const logLevel = transactionData.logLevel; + if (logLevel) { + this.getContainer().getLoggingService().setLogLevel(logLevel); + } let dataService = context.getDataService(); let businessNetworkHash, businessNetworkRecord, businessNetworkDefinition; let compiledScriptBundle, compiledQueryBundle, compiledAclBundle; let sysregistries, sysdata; - - - // Extract and validate the optional log level property. - return this._setLogLevel(context,transactionData.logLevel) + return Promise.resolve() .then(() => { + // Start the transaction. return context.transactionStart(false); + }) .then(() => { diff --git a/packages/composer-runtime/lib/engine.logging.js b/packages/composer-runtime/lib/engine.logging.js index 6af6491e84..b3019e42a0 100644 --- a/packages/composer-runtime/lib/engine.logging.js +++ b/packages/composer-runtime/lib/engine.logging.js @@ -50,7 +50,7 @@ class EngineLogging { return context.getAccessController().check(resource, 'READ'); }) .then(() => { - let ll = Logger.getLoggerCfg(); + let ll = context.getLoggingService().getLogLevel(); LOG.exit(method,'loglevel',ll); return ll; }); diff --git a/packages/composer-runtime/lib/loggingservice.js b/packages/composer-runtime/lib/loggingservice.js index af06b4ce33..415a2e52dc 100644 --- a/packages/composer-runtime/lib/loggingservice.js +++ b/packages/composer-runtime/lib/loggingservice.js @@ -24,32 +24,77 @@ const Service = require('./service'); */ class LoggingService extends Service { - /** Get the config (if possible) for the standard winston logger + /** + * Write a critical message to the log. + * @abstract + * @param {string} message The message to write to the log. + */ + logCritical(message) { + throw new Error('abstract function called'); + } + + /** + * Write a debug message to the log. * @abstract + * @param {string} message The message to write to the log. */ - getLoggerCfg() { + logDebug(message) { throw new Error('abstract function called'); } /** + * Write an error message to the log. * @abstract + * @param {string} message The message to write to the log. */ - setLoggerCfg() { + logError(message) { throw new Error('abstract function called'); } + + /** + * Write a informational message to the log. + * @abstract + * @param {string} message The message to write to the log. + */ + logInfo(message) { + throw new Error('abstract function called'); + } + /** + * Write a notice message to the log. * @abstract + * @param {string} message The message to write to the log. */ - initLogging(){ + logNotice(message) { throw new Error('abstract function called'); } /** + * Write a warning message to the log. * @abstract + * @param {string} message The message to write to the log. */ - callback(){ + logWarning(message) { throw new Error('abstract function called'); } + + /** + * Set the log level for the runtime. + * @abstract + * @param {string} newLogLevel The new log level to apply. + */ + setLogLevel(newLogLevel) { + throw new Error('abstract function called'); + } + + /** + * Get the current log level for the runtime. + * @abstract + */ + getLogLevel() { + throw new Error('abstract function called'); + } + } module.exports = LoggingService; diff --git a/packages/composer-runtime/lib/networkmanager.js b/packages/composer-runtime/lib/networkmanager.js index d41dbde585..4b958649c2 100644 --- a/packages/composer-runtime/lib/networkmanager.js +++ b/packages/composer-runtime/lib/networkmanager.js @@ -76,11 +76,7 @@ class NetworkManager extends TransactionHandler { return this.context.getAccessController().check(resource, 'UPDATE'); }) .then(() => { - return this.context.getLoggingService().getLoggerCfg(); - }) - .then((cfg)=>{ - let c = Logger.setLoggerCfg(Object.assign(cfg,{debug:transaction.newLogLevel}),true); - return this.context.getLoggingService().setLoggerCfg(c); + return this.context.getLoggingService().setLogLevel(transaction.newLogLevel); }); diff --git a/packages/composer-runtime/test/engine.businessnetworks.js b/packages/composer-runtime/test/engine.businessnetworks.js index 0f57639cd0..00570a09aa 100644 --- a/packages/composer-runtime/test/engine.businessnetworks.js +++ b/packages/composer-runtime/test/engine.businessnetworks.js @@ -25,7 +25,7 @@ const RegistryManager = require('../lib/registrymanager'); const version = require('../package.json').version; const Serializer = require('composer-common').Serializer; const AccessController = require('../lib/accesscontroller'); -const Logger = require('composer-common').Logger; + const chai = require('chai'); chai.should(); chai.use(require('chai-as-promised')); @@ -67,11 +67,8 @@ describe('EngineBusinessNetworks', () => { mockAccessController = sinon.createStubInstance(AccessController); mockContext.getAccessController.returns(mockAccessController); - - sandbox = sinon.sandbox.create(); - sandbox.stub(Logger,'setLoggerCfg'); - engine = new Engine(mockContainer); + sandbox = sinon.sandbox.create(); }); afterEach(() => { diff --git a/packages/composer-runtime/test/engine.js b/packages/composer-runtime/test/engine.js index ded8f4bce4..d77b81d7a3 100644 --- a/packages/composer-runtime/test/engine.js +++ b/packages/composer-runtime/test/engine.js @@ -41,6 +41,9 @@ const should = chai.should(); chai.use(require('chai-as-promised')); const sinon = require('sinon'); + +const LOG = Logger.getLog('Engine'); + describe('Engine', () => { let modelManager; @@ -61,10 +64,6 @@ describe('Engine', () => { mockContainer = sinon.createStubInstance(Container); mockLoggingService = sinon.createStubInstance(LoggingService); mockContainer.getLoggingService.returns(mockLoggingService); - mockLoggingService.getLoggerCfg.resolves( { - 'logger':'config' - }); - mockLoggingService.setLoggerCfg.resolves(); mockContainer.getVersion.returns(version); mockContext = sinon.createStubInstance(Context); mockContext.initialize.resolves(); @@ -73,18 +72,13 @@ describe('Engine', () => { mockContext.transactionCommit.resolves(); mockContext.transactionRollback.resolves(); mockContext.transactionEnd.resolves(); - mockDataService = sinon.createStubInstance(DataService); mockRegistryManager = sinon.createStubInstance(RegistryManager); mockContext.initialize.resolves(); mockContext.getDataService.returns(mockDataService); mockContext.getRegistryManager.returns(mockRegistryManager); - mockContext.getLoggingService.returns(mockLoggingService); - - sandbox = sinon.sandbox.create(); - sandbox.stub(Logger,'setLoggerCfg'); - engine = new Engine(mockContainer); + sandbox = sinon.sandbox.create(); }); afterEach(() => { @@ -102,9 +96,34 @@ describe('Engine', () => { describe('#installLogger', () => { it('should install a logger for debug level logging', () => { - engine.installLogger(); + LOG.debug('installLogger', 'hello', 'world'); + sinon.assert.calledWith(mockLoggingService.logDebug, sinon.match(/hello.*world/)); + }); + + it('should install a logger for warn level logging', () => { + LOG.warn('installLogger', 'hello', 'world'); + sinon.assert.calledWith(mockLoggingService.logWarning, sinon.match(/hello.*world/)); }); + it('should install a logger for info level logging', () => { + LOG.info('installLogger', 'hello', 'world'); + sinon.assert.calledWith(mockLoggingService.logInfo, sinon.match(/hello.*world/)); + }); + + it('should install a logger for verbose level logging', () => { + LOG.verbose('installLogger', 'hello', 'world'); + sinon.assert.calledWith(mockLoggingService.logDebug, sinon.match(/hello.*world/)); + }); + + it('should install a logger for error level logging', () => { + LOG.error('installLogger', 'hello', 'world'); + sinon.assert.calledWith(mockLoggingService.logError, sinon.match(/hello.*world/)); + }); + + it('should format multiple arguments into a comma separated list', () => { + LOG.debug('installLogger', 'hello', 'world', 'i', 'am', 'simon'); + sinon.assert.calledWith(mockLoggingService.logDebug, sinon.match(/world, i, am, simon/)); + }); }); @@ -197,6 +216,8 @@ describe('Engine', () => { json.logLevel = 'DEBUG'; return engine.init(mockContext, 'init', [JSON.stringify(json)]) .then(() => { + sinon.assert.calledOnce(mockLoggingService.setLogLevel); + sinon.assert.calledWith(mockLoggingService.setLogLevel, 'DEBUG'); sinon.assert.calledTwice(mockDataService.ensureCollection); sinon.assert.calledWith(mockDataService.ensureCollection, '$sysdata'); @@ -275,7 +296,7 @@ describe('Engine', () => { mockRegistryManager.createDefaults.resolves(); return engine.init(mockContext, 'init', [JSON.stringify(json)]) .then(() => { - + sinon.assert.notCalled(mockLoggingService.setLogLevel); sinon.assert.calledTwice(mockDataService.ensureCollection); sinon.assert.calledWith(mockDataService.ensureCollection, '$sysdata'); sinon.assert.calledOnce(BusinessNetworkDefinition.fromArchive); diff --git a/packages/composer-runtime/test/engine.logging.js b/packages/composer-runtime/test/engine.logging.js index 6afb4e9405..e25ae9dab8 100644 --- a/packages/composer-runtime/test/engine.logging.js +++ b/packages/composer-runtime/test/engine.logging.js @@ -22,7 +22,6 @@ const IdentityManager = require('../lib/identitymanager'); const LoggingService = require('../lib/loggingservice'); const DataCollection = require('../lib/datacollection'); const DataService = require('../lib/dataservice'); -const Logger = require('composer-common').Logger; const chai = require('chai'); chai.should(); chai.use(require('chai-as-promised')); @@ -41,7 +40,7 @@ describe('EngineLogging', () => { let mockDataCollection; let mockSerializer; let mockAccessController; - let sandbox; + beforeEach(() => { mockSerializer = sinon.createStubInstance(Serializer); mockAccessController = sinon.createStubInstance(AccessController); @@ -64,16 +63,8 @@ describe('EngineLogging', () => { mockDataService.getCollection.resolves(mockDataCollection); mockIdentityManager = sinon.createStubInstance(IdentityManager); mockContext.getIdentityManager.returns(mockIdentityManager); - - mockSerializer.fromJSON.returns(); - - sandbox = sinon.sandbox.create(); - sandbox.stub(Logger,'getLoggerCfg').returns('composer[error]:*'); - engine = new Engine(mockContainer); - }); - afterEach(() => { - sandbox.restore(); + mockSerializer.fromJSON.returns(); }); @@ -82,9 +73,9 @@ describe('EngineLogging', () => { it('should work for the good path', () => { mockAccessController.check.resolves(); - + mockLoggingService.getLogLevel.returns('LEVEL'); return engine.invoke(mockContext, 'getLogLevel', ['wrong', 'args', 'count', 'here']) - .should.eventually.be.deep.equal('composer[error]:*'); + .should.eventually.be.deep.equal('LEVEL'); }); it('should throw if not authorized', () => { @@ -93,6 +84,27 @@ describe('EngineLogging', () => { return result.should.be.rejectedWith(/Authorization Failure/); }); + it('should set the log level if user authorised and empty args array', () => { + mockContext.getParticipant.returns(null); + mockLoggingService.getLogLevel.returns('ERROR'); + return engine.invoke(mockContext, 'getLogLevel', []) + .then((response) => { + sinon.assert.calledOnce(mockLoggingService.getLogLevel); + response.should.equal('ERROR'); + }); + }); + + it('should set the log level if user authorised and no args', () => { + mockContext.getParticipant.returns(null); + mockLoggingService.getLogLevel.returns('ERROR'); + return engine.invoke(mockContext, 'getLogLevel') + .then((response) => { + sinon.assert.calledOnce(mockLoggingService.getLogLevel); + response.should.equal('ERROR'); + }); + }); + + }); diff --git a/packages/composer-runtime/test/engine.queries.js b/packages/composer-runtime/test/engine.queries.js index 8c717f433e..972195a76c 100644 --- a/packages/composer-runtime/test/engine.queries.js +++ b/packages/composer-runtime/test/engine.queries.js @@ -25,7 +25,7 @@ const AclManager = require('composer-common').AclManager; const AclFile = require('composer-common').AclFile; const Resource = require('composer-common').Resource; const Serializer = require('composer-common').Serializer; -const Logger = require('composer-common').Logger; + const chai = require('chai'); chai.should(); chai.use(require('chai-as-promised')); @@ -44,7 +44,6 @@ describe('EngineQueries', () => { let mockSerializer; let mockResource1, mockResource2; let engine; - let sandbox; beforeEach(() => { mockContainer = sinon.createStubInstance(Container); @@ -73,7 +72,7 @@ describe('EngineQueries', () => { mockResource1.$identifier = 'ASSET_1'; mockResource2 = sinon.createStubInstance(Resource); mockResource2.$identifier = 'ASSET_2'; - + engine = new Engine(mockContainer); mockCompiledQueryBundle.buildQuery.returns('5769993d7c0a008e0cb45e30a36e3f2797c47c065be7f214c5dcee90419d326f'); mockCompiledQueryBundle.execute.resolves([ { $identifier: 'ASSET_1', $registryId: 'registry1' }, @@ -83,14 +82,6 @@ describe('EngineQueries', () => { mockSerializer.fromJSON.withArgs({ $identifier: 'ASSET_2' }).returns(mockResource2); mockSerializer.toJSON.withArgs(mockResource1).returns({ $identifier: 'ASSET_1' }); mockSerializer.toJSON.withArgs(mockResource2).returns({ $identifier: 'ASSET_2' }); - sandbox = sinon.sandbox.create(); - sandbox.stub(Logger,'setLoggerCfg'); - - engine = new Engine(mockContainer); - }); - - afterEach(()=>{ - sandbox.restore(); }); describe('#executeQuery', () => { diff --git a/packages/composer-runtime/test/engine.registries.js b/packages/composer-runtime/test/engine.registries.js index ad20f857bf..021da7ec4f 100644 --- a/packages/composer-runtime/test/engine.registries.js +++ b/packages/composer-runtime/test/engine.registries.js @@ -20,10 +20,9 @@ const Engine = require('../lib/engine'); const LoggingService = require('../lib/loggingservice'); const Registry = require('../lib/registry'); const RegistryManager = require('../lib/registrymanager'); -const Logger = require('composer-common').Logger; + const chai = require('chai'); chai.should(); -chai.use(require('chai-as-promised')); chai.use(require('chai-things')); const sinon = require('sinon'); @@ -35,7 +34,6 @@ describe('EngineRegistries', () => { let mockContext; let mockRegistryManager; let engine; - let sandbox; beforeEach(() => { mockContainer = sinon.createStubInstance(Container); @@ -50,16 +48,9 @@ describe('EngineRegistries', () => { mockContext.transactionEnd.resolves(); mockRegistryManager = sinon.createStubInstance(RegistryManager); mockContext.getRegistryManager.returns(mockRegistryManager); - sandbox = sinon.sandbox.create(); - sandbox.stub(Logger,'setLoggerCfg'); - engine = new Engine(mockContainer); }); - afterEach(()=>{ - sandbox.restore(); - }); - describe('#getAllRegistries', () => { it('should throw for invalid arguments', () => { diff --git a/packages/composer-runtime/test/engine.resources.js b/packages/composer-runtime/test/engine.resources.js index 2a8ac10fa3..4c6ff8ed8b 100644 --- a/packages/composer-runtime/test/engine.resources.js +++ b/packages/composer-runtime/test/engine.resources.js @@ -23,7 +23,7 @@ const RegistryManager = require('../lib/registrymanager'); const Resolver = require('../lib/resolver'); const Resource = require('composer-common').Resource; const Serializer = require('composer-common').Serializer; -const Logger = require('composer-common').Logger; + const chai = require('chai'); chai.should(); chai.use(require('chai-as-promised')); @@ -41,7 +41,6 @@ describe('EngineResources', () => { let mockResolver; let mockSerializer; let engine; - let sandbox; beforeEach(() => { mockContainer = sinon.createStubInstance(Container); @@ -62,16 +61,9 @@ describe('EngineResources', () => { mockContext.getSerializer.returns(mockSerializer); mockResolver = sinon.createStubInstance(Resolver); mockContext.getResolver.returns(mockResolver); - sandbox = sinon.sandbox.create(); - sandbox.stub(Logger,'setLoggerCfg'); - engine = new Engine(mockContainer); }); - afterEach(()=>{ - sandbox.restore(); - }); - describe('#getAllResourcesInRegistry', () => { it('should throw for invalid arguments', () => { diff --git a/packages/composer-runtime/test/engine.transactions.js b/packages/composer-runtime/test/engine.transactions.js index c642452be0..8035a4aad7 100644 --- a/packages/composer-runtime/test/engine.transactions.js +++ b/packages/composer-runtime/test/engine.transactions.js @@ -30,7 +30,7 @@ const Resource = require('composer-common').Resource; const ScriptManager = require('composer-common').ScriptManager; const Serializer = require('composer-common').Serializer; const Factory = require('composer-common').Factory; -const Logger = require('composer-common').Logger; + const TransactionHandler = require('../lib/transactionhandler'); const chai = require('chai'); @@ -61,7 +61,6 @@ describe('EngineTransactions', () => { let mockParticipant; let mockEventService; let mockIdentity; - let sandbox; beforeEach(() => { mockContainer = sinon.createStubInstance(Container); @@ -74,7 +73,7 @@ describe('EngineTransactions', () => { mockContext.transactionCommit.resolves(); mockContext.transactionRollback.resolves(); mockContext.transactionEnd.resolves(); - + engine = new Engine(mockContainer); mockRegistryManager = sinon.createStubInstance(RegistryManager); mockResourceManager = sinon.createStubInstance(ResourceManager); mockContext.getRegistryManager.returns(mockRegistryManager); @@ -112,14 +111,7 @@ describe('EngineTransactions', () => { mockIdentityManager.getIdentity.resolves(mockIdentity); mockParticipant = sinon.createStubInstance(Resource); mockEventService = sinon.createStubInstance(EventService); - sandbox = sinon.sandbox.create(); - sandbox.stub(Logger,'setLoggerCfg'); - - engine = new Engine(mockContainer); - }); - afterEach(()=>{ - sandbox.restore(); }); describe('#submitTransaction', () => { diff --git a/packages/composer-runtime/test/loggingservice.js b/packages/composer-runtime/test/loggingservice.js index 404424d160..e6d99aa885 100644 --- a/packages/composer-runtime/test/loggingservice.js +++ b/packages/composer-runtime/test/loggingservice.js @@ -22,40 +22,85 @@ describe('LoggingService', () => { let loggingService = new LoggingService(); - describe('#getLoggerCfg', () => { + describe('#logCritical', () => { it('should throw as abstract method', () => { (() => { - loggingService.getLoggerCfg(); + loggingService.logCritical('wow such log'); }).should.throw(/abstract function called/); }); }); - describe('#setLoggerCfg', () => { + + describe('#logDebug', () => { + + it('should throw as abstract method', () => { + (() => { + loggingService.logDebug('wow such log'); + }).should.throw(/abstract function called/); + }); + + }); + + describe('#logError', () => { it('should throw as abstract method', () => { (() => { - loggingService.setLoggerCfg(); + loggingService.logError('wow such log'); }).should.throw(/abstract function called/); }); }); - describe('#initLogging', () => { + + describe('#logInfo', () => { it('should throw as abstract method', () => { (() => { - loggingService.initLogging(); + loggingService.logInfo('wow such log'); }).should.throw(/abstract function called/); }); }); - describe('#callback', () => { + + describe('#logNotice', () => { + + it('should throw as abstract method', () => { + (() => { + loggingService.logNotice('wow such log'); + }).should.throw(/abstract function called/); + }); + + }); + + describe('#logWarning', () => { it('should throw as abstract method', () => { (() => { - loggingService.callback(); + loggingService.logWarning('wow such log'); }).should.throw(/abstract function called/); }); }); + + describe('#setLogLevel', () => { + + it('should throw as abstract method', () => { + (() => { + loggingService.setLogLevel('wow such log'); + }).should.throw(/abstract function called/); + }); + + }); + + describe('#getLogLevel', () => { + + it('should throw as abstract method', () => { + (() => { + loggingService.getLogLevel(); + }).should.throw(/abstract function called/); + }); + + }); + + }); diff --git a/packages/composer-runtime/test/networkmanager.js b/packages/composer-runtime/test/networkmanager.js index d52aca54b0..5f83cefe30 100644 --- a/packages/composer-runtime/test/networkmanager.js +++ b/packages/composer-runtime/test/networkmanager.js @@ -34,7 +34,6 @@ const ModelManager = require('composer-common').ModelManager; const Registry = require('../lib/registry'); const NetworkManager = require('../lib/networkmanager'); const Resolver = require('../lib/resolver'); -const Logger = require('composer-common').Logger; const LoggingService = require('../lib/loggingservice'); const chai = require('chai'); @@ -221,22 +220,16 @@ describe('NetworkManager', () => { mockRegistryManager.createDefaults.resolves(); mockRegistryManager.remove.returns; - sinon.stub(Logger,'setDebugEnv'); - + let mockLoggingService = sinon.createStubInstance(LoggingService); + mockLoggingService.setLogLevel.returns(); + mockContext.getLoggingService.returns(mockLoggingService); let mockAccessController = sinon.createStubInstance(AccessController); mockContext.getAccessController.returns(mockAccessController); - let mockLoggingService=sinon.createStubInstance(LoggingService); - mockContext.getLoggingService.returns(mockLoggingService); - mockLoggingService.getLoggerCfg.resolves({ - 'fakelogger':'config' - }); - mockLoggingService.setLoggerCfg.resolves(); - sinon.spy(Logger.setLoggerCfg); mockAccessController.check.resolves(); mockRegistryManager.getAll.resolves([mockRegistry]); return networkManager.setLogLevel(mockApi, {newLogLevel:'level'}) .then(() => { - sinon.assert.calledOnce(mockLoggingService.setLoggerCfg); + sinon.assert.calledWith(mockLoggingService.setLogLevel,'level'); }); }); diff --git a/packages/composer-website/jekylldocs/problems/diagnostics.md b/packages/composer-website/jekylldocs/problems/diagnostics.md index c923303700..f8abd348ac 100644 --- a/packages/composer-website/jekylldocs/problems/diagnostics.md +++ b/packages/composer-website/jekylldocs/problems/diagnostics.md @@ -8,24 +8,33 @@ section: diagnostics index-order: 900 --- -# Overview +# Diagnosing Problems -{{site.data.conrefs.composer_full}} uses the [Winston](https://github.com/winstonjs/winston) framework by default for producing log output. Configuration of this uses the Config framework. +Composer uses the Winston logging module by default - and will use the Config module to look for any configuration information. If none is found, then a set of defaults will be used. ->Please note: {{site.data.conrefs.composer_full}} is a framework - so your application will need to have it's own logging framework. Also, your application could also have configuration information to control {{site.data.conrefs.composer_full}}'s own logging. +The config module does write out a warning, if there are no configuration files set. Eg. `WARNING: No configurations found in configuration directory`. This can be suppressed with an environment variable if you are happy with the defaults and don't wish to use config in your application. See more information [here](https://github.com/lorenwest/node-config/wiki/Environment-Variables#suppress_no_config_warning). -For application level problem diagnosis, it is unlikely that you will need to be very familar with all of the information here. However a basic understanding and ability to enable the default levels of logging will be useful. -# Diagnosing Issues +# Diagnosing Problems -There are two places or environments where logging takes place +If something should ever go wrong with an application, what should you do about getting diagnostics? -- the one the application is running in +Let's look at the `digitalproperty-app` sample, and use that to explain how to get diagnostics out of the framework. + +>Please note: This is a framework - so your application will need to have it's own logging framework. Also, your application could also have configuration information to control {{site.data.conrefs.composer_full}}'s own logging. + +There are two containers that are relevant to logging; + +- the one the application is running in, and - the chain code container that executes the transaction functions. -## Overview +## Application + +Internally, {{site.data.conrefs.composer_full}} uses the [Winston](https://github.com/winstonjs/winston) node.js logging package by default, with an initial level of log points and destinations set up. + +## Default Configuration -The framework will log information at these levels, as defined by Winston inline with the NPM defaults +The framework will log information at these levels. - Error - Warn @@ -33,195 +42,66 @@ The framework will log information at these levels, as defined by Winston inline - Verbose - Debug -The code has different levels of logging that can be enabled that are the standard NPM log levels of, Error, Warn, Info, Verbose, Debug, Silly are used. (Silly is used just to be log everything - we don't have any specific points at this level. Also a None level is used to signify nothing). - -Within in the code, log messages are written at a selection of these levels depending on the type of message. Entry and Exit to functions in the code are logged specifically at the Debug level. - -Application side there are two locations where these log messages are written. A text file contain the log messages, and stdout. Within the chaincode container, by default only stdout is used. - -## Control of what is produced - -To control both the location and the type of information that is produced a simple JSON based object configuration is used. The [Config] module is used to help assemble this JSON structure - therefore end user control can be done by environment variables and other formats that Config supports. - -> Short cut environment variables are provided to make working with this JSON structure easy! - -With that structure, control can be broke into two parts - -- What level log messages are produced at -- Where these messages are sent - -### What is produced? - -What to log and at what level and components are controlled by the *DEBUG* control string, as used by many node applications. This is a comma-separated list of components. A single * means everything, and a - sign infront of any component means do *not\* log this - -``` -DEBUG=, -``` - -The string 'composer' is used to indetify Hyperledger Composer. For example - -``` -DEBUG=express,composer,http -``` - -Would log all the composer log points, as well as whatever Express and HTTP wanted to do. -To specifically control the Composer information a string can accept further detail. - -``` -DEBUG=composer[tracelevel]:fqn/class/name -``` +The 'Silly' level doesn't get used. -The [tracelevel] including the [ ] is optional and defaults to _error_; the `fqn/class/name` is dependant on how the code is written and the name of the logger that it requests. (subject for more work later) +## Locations of information -Examples are +By default, there are two locations for data: -* `composer:*` Everything at _error_ level -* `composer[error]:*` Everything at _error_ level -* `composer[info]:*` Everything at _info_ level -* `composer[info]:BusinessNetworkConnection` Solely _BusinessNetworkConnection_ at the _info_ level -* `-composer:BusinessNetworkConnection,composer[error]:*` Do not trace anything in the BusinessNetworkConnection class, but do trace anywhere else that has errors. _the do not takes effect at all levels of trace_ +- One is a text file that is the location `${CurrentWorkingDir}/logs/trace_.trc` ->The values above are called the *debug control string* +- The other is `stdout`. By default, `stdout` will only show any data logged with a level of 'error' and the file will show any data logged with 'info' or above (i.e. info, warn and error). -### Controlling where the information goes to - -#### Application side -The details of where the files are written are controlled as follows. - -Default settings are: - -- Console has *no* logging output (the exception being and errors encountered during log setup) -- File, a set of three files, of 1Mb limited in size are written to - - Location of this is in `~/.composer/logs` - - A separate set of files is written on every calendar day. +## Control of what is produced -Each of the console or file can be controlled. These are controlled using the [Config](https://www.npmjs.com/package/config) npm module used. Typically this is controlled by using a json file in a `config` directory in the current working directory. +The Config module is used to locate information to control how the logs are produced. -The structure should be (including an example of application use of the file) would look like +For example ``` { - "loadAssets": { - "cardName": "admin@bsn-local" - }, - "composer": { - "log": { - "debug": "composer[debug]:*", - "console": { - "maxLevel": "error" - }, - "file": { - "filename" : "./log.txt" - } + "gettingstarted": { + "cardname": "admin@digitalproperty-network" + }, + "ComposerConfig": { + "debug": { + "logger": "default", + "config": { + "console": { + "enabledLevel": "info", + "alwaysLevel": "none" + }, + "file": { + "filename": "./trace_PID.log", + "enabledLevel": "silly", + "alwaysLevel": "info" + } + } + } } - } } ``` -This example does several things. -- Debug control string enables debug trace for everything. Equivalent to the `DEBUG=composer[debug]:*` -- Enable logging to the console, at the maximum level of error (so just errors) -- And the log file should be in an unlimited file called `./log.txt` (by default the max log level is set to silly so as to get everything). However as the [debug] is present this pre-filters the log. - - -#### Shortcuts -The config file above, can be specified as a single environment variable on the command line. -``` -NODE_CONFIG=' { .... JSON HERE } ' -``` +The first section is specific to the Getting Started application, the second `ComposerConfig` section is for the {{site.data.conrefs.composer_full}}. -For quick access for logging the following environment variables allow quick, coarse grained access +- `logger` is used to refer the module that does actual logging. default is implying that this is the winston framework +- `config` is passed to the logger to control what it does. So this section is specific to the logger in use. -- `COMPOSER_LOGFILE` Filename to write the log file to -- `COMPOSER_LOGFILE_SIZE` maxsize property - the size per log file. Default = 10Mb -- `COMPOSER_LOGFILE_QTY` maxFiles property - the number of log files Default = 100 -- `COMPOSER_LOG_CONSOLE` Max level to enable for the console, Default is none +## Enabling more information +The standard way of enabling node.js applications for debug is to use the `DEBUG` environment variable. So therefore -## Examples - -- `node app.js` Logs at *error* to the ~/.composer/logs/log_date.txt -- `DEBUG=composer[info]:* node app.js` Logs at *info* to the ~/.composer/logs/log_date.txt -- `DEBUG=composer[debug]:* COMPOSR_LOGFILE=./log.txt node app.js` Logs everything at *debug* level to the cwd file called `log.txt` -- `COMPOSE_LOG_CONSOLE=error node app.js` Log to file and errors to the console - -#### Chaincode Container -Within the container that is running the chaincode, and therefore the business network transaction functions the logging system is the same. - -The major differences are how this is controlled, and where the output is formatted to. - -##### Format -As this is running within a container it is better to output the logs to stdout instead. This is then captured by docker or the container management system. - -To achieve this there is a runtime *LoggingService* that provides a configuration specifically for this purpose. The same framework is therefore used but with a specific configuration. This is for the `composer-runtime-hlfv1` defined as being - -``` - getDefaultCfg(){ - return { - 'logger': './winstonInjector.js', - 'debug': 'composer[error]:*', - 'console': { - 'maxLevel': 'silly' - - }, - 'file': { - 'maxLevel': 'none' - }, - 'origin':'default-runtime-hlfv1', - }; - } -``` -This routes all log to the console, none to the file system. The default control string is all errors. - -##### Transaction Id -An important part of the runtime is the transaction id that is currently being used. This is essential to be able to link together all logs from client, runtime and Fabric. - -To achieve this, a *callback* mechanism is in place to permit the retrieval of data that only the runtime will know at the point in time the log call is made. - -This permits the output in the logs to include the transaction id. For example *88bae779* in this line -``` -2018-01-16T12:56:58.987Z [88bae779] [INFO ] @JS : IdentityManager :() Binding in the tx names and impl -``` - -##### Control -The same essential control is available and is focused around provision of the 'debug control string'. Though within a container there need to be alternative ways to pass this in. Environment variables can be set for example in the docker-compose files. - -The 'setLogLevel' and 'getLogLevel' transactions, can be used to set/get the value of this debug string. The syntax of the string is the same, - -For example issuing the command to get the log level in a fresh setup... ``` -$> composer network loglevel --card admin@bsn-local -The current logging level is: composer[error]:* - -Command succeeded -``` - -This can then be modified to say include all debug level log points from the TransactionHandler but still errors everywhere else -``` -composer network loglevel --card admin@bsn-local -l "composer[debug]:TransactionHandler,composer[error]:*" -The logging level was successfully changed to: composer[debug]:TransactionHandler,composer[error]:* - -Command succeeded -``` -## Component Profiles - -Using the debug string for another other than broad logging, requires a knowledge of what file/class to trace. If you want to take logging from say ACLs, then -this there is the concept of 'profiles'. For example for ACLs, you can enable trace with - -``` -DEBUG=composer[debug]:acls +DEBUG=composer:* node myApplication.js ``` -The syntax is the same, but internally 'acls' is expanded to a debug string specifically for ACLs. - - - - - - - - +Will enabled more tracing - this then will use the levels marked as `enabledLevel` in the configuration above. +# How to find out which chaincode container has the deployed network? +Each Business Network is deployed to it's own Chaincode container. In the case of errors say with a transaction function, it can be helpful to look at the logs from that container and see what has happened. +To identify which Docker container has the deployed network run the following command: + docker ps +The Docker container name should include the name of the deployed network.