From 45e7a8d3df7df08518ddad845ec980a8f04af170 Mon Sep 17 00:00:00 2001 From: Attila Klenik Date: Mon, 7 Oct 2019 12:44:22 +0000 Subject: [PATCH] Improve logging style flexibility Signed-off-by: Attila Klenik --- packages/caliper-core/lib/config/Config.js | 39 ++-- packages/caliper-core/lib/config/default.yaml | 37 ++-- .../caliper-core/lib/utils/log-formats.js | 64 ++++++ .../caliper-core/lib/utils/logging-util.js | 186 ++++++++++-------- packages/caliper-core/package.json | 5 +- .../2org1peercouchdb/fabric-node.yaml | 2 +- .../scripts/run-tests.sh | 7 +- 7 files changed, 217 insertions(+), 123 deletions(-) create mode 100644 packages/caliper-core/lib/utils/log-formats.js diff --git a/packages/caliper-core/lib/config/Config.js b/packages/caliper-core/lib/config/Config.js index 2a08146e9..3bd1d7433 100644 --- a/packages/caliper-core/lib/config/Config.js +++ b/packages/caliper-core/lib/config/Config.js @@ -45,12 +45,32 @@ const keys = { Template: 'caliper-logging-template', FormatsRoot: 'caliper-logging-formats', Formats: { - Align: 'caliper-logging-formats-align', + Timestamp: 'caliper-logging-formats-timestamp', + Label: 'caliper-logging-formats-label', + JsonRoot: 'caliper-logging-formats-json', + Json: { + Space: 'caliper-logging-formats-json-space' + }, Pad: 'caliper-logging-formats-pad', + Align: 'caliper-logging-formats-align', + AttributeFormatRoot: 'caliper-logging-formats-attributeformat', + AttributeFormat: { + Timestamp: 'caliper-logging-formats-attributeformat-timestamp', + Label: 'caliper-logging-formats-attributeformat-label', + Level: 'caliper-logging-formats-attributeformat-level', + Module: 'caliper-logging-formats-attributeformat-module', + Message: 'caliper-logging-formats-attributeformat-message', + Metadata: 'caliper-logging-formats-attributeformat-metadata' + }, ColorizeRoot: 'caliper-logging-formats-colorize', Colorize: { + All: 'caliper-logging-formats-colorize-all', + Timestamp: 'caliper-logging-formats-colorize-timestamp', + Label: 'caliper-logging-formats-colorize-label', Level: 'caliper-logging-formats-colorize-level', + Module: 'caliper-logging-formats-colorize-module', Message: 'caliper-logging-formats-colorize-message', + Metadata: 'caliper-logging-formats-colorize-metadata', Colors: { Info: 'caliper-logging-formats-colorize-colors-info', Error: 'caliper-logging-formats-colorize-colors-error', @@ -58,23 +78,6 @@ const keys = { Debug: 'caliper-logging-formats-colorize-colors-debug', } }, - ErrorsRoot: 'caliper-logging-formats-errors', - Errors: { - Stack: 'caliper-logging-formats-errors-stack' - }, - JsonRoot: 'caliper-logging-formats-json', - Json: { - Space: 'caliper-logging-formats-json-space' - }, - LabelRoot: 'caliper-logging-formats-label', - Label: { - Label: 'caliper-logging-formats-label-label', - Message: 'caliper-logging-formats-label-message' - }, - TimestampRoot: 'caliper-logging-formats-timestamp', - Timestamp: { - Format: 'caliper-logging-formats-timestamp-format' - } }, Targets: 'caliper-logging-targets' }, diff --git a/packages/caliper-core/lib/config/default.yaml b/packages/caliper-core/lib/config/default.yaml index 9b16559db..e9603c003 100644 --- a/packages/caliper-core/lib/config/default.yaml +++ b/packages/caliper-core/lib/config/default.yaml @@ -52,15 +52,31 @@ caliper: # Configurations related to the logging mechanism logging: # Specifies the message structure through placeholders - template: '%time% %level% [%label%] [%module%] %message% %meta%' + template: '%timestamp%%level%%label%%module%%message%%metadata%' # Enables the different formats to apply to the log messages FOR ALL transports # Each format can be disabled by setting it to false formats: - # adds a tab delimiter before the message to align it in the same place - align: true + # Adds a timestamp to the messages with the following format + timestamp: 'YYYY.MM.DD-HH:mm:ss.SSS' + # Adds a specified label to every message. Useful for distributed client scenario + label: caliper + # serializes the log messages as JSON + json: false # pads the levels to be the same length pad: true - # defines coloring for the different levels + # adds a tab delimiter before the message to align it in the same place + align: true + # specifies formatting strings for different log message attributes + attributeformat: + # add a space before the level + level: ' %attribute%' + # put [] around the label and space before it + label: ' [%attribute%]' + # put [] around the module name and space before/after it + module: ' [%attribute%] ' + # put () around the metadata and space before it + metadata: ' (%attribute%)' + # defines coloring for the different levels for each (or all) message property colorize: # Apply it to levels level: true @@ -72,19 +88,6 @@ caliper: error: red warn: yellow debug: grey - # specifies whether to print stack traces - errors: - stack: true - # serializes the log messages as JSON - json: false - # Adds a specified label to every message. Useful for distributed client scenario - label: - label: caliper - message: false - # Adds a timestamp to the messages - timestamp: - # The timestamp format string - format: YYYY.MM.DD-HH:mm:ss.SSS # Lists the targets (winston transports) targets: console: diff --git a/packages/caliper-core/lib/utils/log-formats.js b/packages/caliper-core/lib/utils/log-formats.js new file mode 100644 index 000000000..f09d98326 --- /dev/null +++ b/packages/caliper-core/lib/utils/log-formats.js @@ -0,0 +1,64 @@ +/* +* Licensed under the Apache License, Version 2.0 (the "License"); +* you may not use this file except in compliance with the License. +* You may obtain a copy of the License at +* +* http://www.apache.org/licenses/LICENSE-2.0 +* +* Unless required by applicable law or agreed to in writing, software +* distributed under the License is distributed on an "AS IS" BASIS, +* WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +* See the License for the specific language governing permissions and +* limitations under the License. +*/ + +'use strict'; + +const colors = require('colors/safe'); +const { format } = require('logform'); +const { LEVEL } = require('triple-beam'); + +const attributeRegex = /%attribute%/gi; + +const colorizeExtra = format((info, opts) => { + // The immutable level string of the message (the normal property could be mutated already) + let lev = info[LEVEL]; + // colors enables multiple styles separated by spaces + let colorStyles = opts.colors[lev].split(' '); + + for (let key of Object.keys(info)) { + if (info[key] !== undefined && (opts.all || opts[key])) { + // surround the value with the style codes one by one + for (let style of colorStyles) { + info[key] = colors[style](info[key]); + } + } + } + + return info; +}); + +const padLevelExtra = format(info => { + + let padding = ' '.repeat(Math.max(5 - info[LEVEL].length, 0)); + info.level = `${info.level}${padding}`; + return info; +}); + +const attributeFormat = format((info, opts) => { + for (let key of Object.keys(info)) { + if (typeof opts[key] === 'string') { + if (typeof info[key] !== 'string') { + info[key] = JSON.stringify(info[key]); + } + + info[key] = opts[key].replace(attributeRegex, info[key]); + } + } + + return info; +}); + +module.exports.ColorizerExtra = colorizeExtra; +module.exports.PadLevelExtra = padLevelExtra; +module.exports.AttributeFormat = attributeFormat; diff --git a/packages/caliper-core/lib/utils/logging-util.js b/packages/caliper-core/lib/utils/logging-util.js index ef8ca7276..63407daa0 100644 --- a/packages/caliper-core/lib/utils/logging-util.js +++ b/packages/caliper-core/lib/utils/logging-util.js @@ -17,6 +17,7 @@ const path = require('path'); const { createLogger, format, transports } = require('winston'); +const { ColorizerExtra, PadLevelExtra, AttributeFormat } = require('./log-formats.js'); require('winston-daily-rotate-file'); const conf = require('../config/config-util.js'); @@ -28,26 +29,26 @@ const conf = require('../config/config-util.js'); */ function _messageFormat() { let template = conf.get(conf.keys.Logging.Template, - '%time% %level% [%label%] [%module%] %message% %meta%'); + '%timestamp%%level%%label%%module%%message%%metadata%'); - let timeRegex = /%time%/gi; + let timestampRegex = /%timestamp%/gi; let levelRegex = /%level%/gi; let labelRegex = /%label%/gi; let moduleRegex = /%module%/gi; let messageRegex = /%message%/gi; - let metaRegex = /%meta%/gi; + let metadataRegex = /%metadata%/gi; return format.printf(info => { // NOTE: info will contain the mandatory "level" and "message" properties - // additionally it contains the "moduleName" due to our wrapping approach + // additionally it contains the "module" due to our wrapping approach // plus it might contain the "timestamp" and "label" properties, if those formats are enabled - let output = template.replace(timeRegex, info.timestamp || ''); + let output = template.replace(timestampRegex, info.timestamp || ''); output = output.replace(levelRegex, info.level || ''); output = output.replace(labelRegex, info.label || ''); - output = output.replace(moduleRegex, info.moduleName || ''); + output = output.replace(moduleRegex, info.module || ''); output = output.replace(messageRegex, info.message || ''); - return output.replace(metaRegex, info.meta ? JSON.stringify(info.meta) : ''); + return output.replace(metadataRegex, info.meta || ''); }); } @@ -59,13 +60,27 @@ function _messageFormat() { function _assembleDefaultFormat() { let formats = []; + // add timestamp + formats.push(format.timestamp({ + format: 'YYYY.MM.DD-HH:mm:ss.SSS' + })); + + // pad level strings + formats.push(PadLevelExtra()); + // enable aligning log messages formats.push(format.align()); - // enable colors for log levels - formats.push(format.colorize({ - level: true, - message: false, + formats.push(AttributeFormat({ + level: ' %attribute%', + label: ' [%attribute%]', + module: ' [%attribute%] ', + metadata: ' (%attribute%)' + })); + + // enable colors for every attribute + formats.push(ColorizerExtra({ + all: true, colors: { info: 'green', error: 'red', @@ -74,18 +89,6 @@ function _assembleDefaultFormat() { } })); - // enable printing stacktrace - formats.push(format.errors({ - stack: true - })); - - // add timestamp - formats.push(format.timestamp({ - format: 'YYYY.MM.DD-HH:mm:ss.SSS' - })); - - formats.push(format.padLevels()); - // message format formats.push(_messageFormat()); @@ -104,78 +107,88 @@ function _processFormatOptions() { // 1) The format options are queried directly (i.e., not using the "logging.formats" root object), // so the user can change them from the command line or from evn vars // 2) The sub-properties of the formats are also queried directly for the same reason + // 3) The formats are applied in the following order: timestamp, label, json, + // if not json, then padding, align, attributeformat, colorize let formatKey = conf.keys.Logging.Formats; - // aligning - let align = conf.get(formatKey.Align); - if (align && align === true) { - formats.push(format.align()); - } - - // colorize - let colorize = conf.get(formatKey.ColorizeRoot); - if (colorize && colorize !== false) { + // timestamp + let timestamp = conf.get(formatKey.Timestamp); + if (timestamp && typeof timestamp === 'string') { let opts = { - level: conf.get(formatKey.Colorize.Level), - message: conf.get(formatKey.Colorize.Message), - colors: { - info: conf.get(formatKey.Colorize.Colors.Info), - error: conf.get(formatKey.Colorize.Colors.Error), - warn: conf.get(formatKey.Colorize.Colors.Warn), - debug: conf.get(formatKey.Colorize.Colors.Debug) - } + format: timestamp }; - formats.push(format.colorize(opts)); - } else { - formats.push(format.uncolorize({ - level: true, - message: true - })); + formats.push(format.timestamp(opts)); } - // errors - let errors = conf.get(formatKey.ErrorsRoot); - if (errors && errors !== false) { + // label + let label = conf.get(formatKey.Label); + if (label && typeof label === 'string') { let opts = { - stack: conf.get(formatKey.Errors.Stack) + label: label, + message: false }; - formats.push(format.errors(opts)); + formats.push(format.label(opts)); } // JSON let json = conf.get(formatKey.JsonRoot); - if (json && json !== false) { + if (json && typeof json === 'object') { let opts = { - space: conf.get(formatKey.Json.Space) + space: conf.get(formatKey.Json.Space, 0) }; formats.push(format.json(opts)); + + // return now, since the other formats are mutually exclusive with the JSON format + return format.combine(...formats); } - // label - let label = conf.get(formatKey.LabelRoot); - if (label && label !== false) { - let opts = { - label: conf.get(formatKey.Label.Label), - message: conf.get(formatKey.Label.Message) - }; - formats.push(format.label(opts)); + // padding + let pad = conf.get(formatKey.Pad); + if (pad === true) { + formats.push(PadLevelExtra()); } - // timestamp - let timestamp = conf.get(formatKey.TimestampRoot); - if (timestamp && timestamp !== false) { + // aligning + let align = conf.get(formatKey.Align); + if (align === true) { + formats.push(format.align()); + } + + // attribute formatter + let attributeFormat = conf.get(formatKey.AttributeFormatRoot); + if (attributeFormat && typeof attributeFormat === 'object') { let opts = { - format: conf.get(formatKey.Timestamp.Format) + timestamp: conf.get(formatKey.AttributeFormat.Timestamp), + label: conf.get(formatKey.AttributeFormat.Label), + level: conf.get(formatKey.AttributeFormat.Level), + module: conf.get(formatKey.AttributeFormat.Module), + message: conf.get(formatKey.AttributeFormat.Message), + metadata: conf.get(formatKey.AttributeFormat.Metadata) }; - formats.push(format.timestamp(opts)); + formats.push(AttributeFormat(opts)); } - // padding - let pad = conf.get(formatKey.Pad); - if (pad && pad === true) { - formats.push(format.padLevels()); + // colorize + let colorize = conf.get(formatKey.ColorizeRoot); + if (colorize && typeof colorize === 'object') { + let opts = { + all: conf.get(formatKey.Colorize.All), + timestamp: conf.get(formatKey.Colorize.Timestamp), + label: conf.get(formatKey.Colorize.Label), + level: conf.get(formatKey.Colorize.Level), + module: conf.get(formatKey.Colorize.Module), + message: conf.get(formatKey.Colorize.Message), + metadata: conf.get(formatKey.Colorize.Metadata), + colors: { + info: conf.get(formatKey.Colorize.Colors.Info), + error: conf.get(formatKey.Colorize.Colors.Error), + warn: conf.get(formatKey.Colorize.Colors.Warn), + debug: conf.get(formatKey.Colorize.Colors.Debug) + } + }; + formats.push(ColorizerExtra(opts)); } // message format @@ -208,26 +221,31 @@ function _saveLogger(logger) { */ function _wrapWithLoggerName(logger, name) { const newLogger = Object.assign({}, logger); + + // wrap the following methods of the winston logger ['debug', 'info', 'warn', 'error'].forEach((method) => { const originalFunction = logger[method]; - // NOTE: this needs some explanation due to the magical winston mechanics - // 1) Without wrapping, the winston info/warn/etc. functions receive a message as first argument - // 2) They can also accept any extra arguments (metadata), that will be merged into the "info" object passed to the format pipeline - // 3) The "function (message, ...metadata)" signature matches this interface - // 4) To flexibly handle the extra module name, it is not prepended to the message, like before - // 5) Instead, a new "metadata" object is constructed, that contains the "moduleName" key, plus every originally passed metadata, if any - // 6) Don't pass "metadata" to the "meta" field if it's empty (as is the case when no extra args were passed...) - newLogger[method] = (function (context, loggerName, f) { - return function (message, ...metadata) { - let logMeta = { - moduleName: loggerName, - meta: metadata.length > 0 ? metadata : undefined + // NOTE: the winston info/warn/etc functions expect a message, and a metadata/info object. + // This wrapper function adds the "module" name as part of the winston metadata, collecting other + // passed objects (if any) under a single "metadata" property (unwrapping arrays if it can). + // The "info" object will be extended by winston with the "message" and "level" properties automatically, + // and this "info" objects will be processed by the format pipeline + const wrapMethod = function (context, loggerName, f) { + return function (message, ...objects) { + let info = { + module: loggerName }; - f.apply(context, [message, logMeta]); + if (objects.length > 0) { + info.metadata = objects.length === 1 ? objects[0] : objects; + } + + f.apply(context, [message, info]); }; - })(logger, name, originalFunction); + }; + + newLogger[method] = wrapMethod(logger, name, originalFunction); }); return newLogger; diff --git a/packages/caliper-core/package.json b/packages/caliper-core/package.json index babc4d559..0b8ed89d9 100644 --- a/packages/caliper-core/package.json +++ b/packages/caliper-core/package.json @@ -33,7 +33,10 @@ "systeminformation": "^3.23.7", "table": "^4.0.1", "winston": "^3.2.1", - "winston-daily-rotate-file": "^4.2.1" + "winston-daily-rotate-file": "^4.2.1", + "triple-beam": "^1.3.0", + "logform": "^2.1.2", + "colors": "^1.4.0" }, "devDependencies": { "chai": "^3.5.0", diff --git a/packages/caliper-samples/network/fabric-v1.4.1/2org1peercouchdb/fabric-node.yaml b/packages/caliper-samples/network/fabric-v1.4.1/2org1peercouchdb/fabric-node.yaml index ff255a375..d2c0f3ac1 100644 --- a/packages/caliper-samples/network/fabric-v1.4.1/2org1peercouchdb/fabric-node.yaml +++ b/packages/caliper-samples/network/fabric-v1.4.1/2org1peercouchdb/fabric-node.yaml @@ -61,7 +61,7 @@ channels: definition: capabilities: [] consortium: 'SampleConsortium' - msps: ['Org1MSP', 'Org2MSP', 'Org3MSP'] + msps: ['Org1MSP', 'Org2MSP'] version: 0 orderers: - orderer.example.com diff --git a/packages/caliper-tests-integration/scripts/run-tests.sh b/packages/caliper-tests-integration/scripts/run-tests.sh index 861a5841e..ec3ea7d67 100755 --- a/packages/caliper-tests-integration/scripts/run-tests.sh +++ b/packages/caliper-tests-integration/scripts/run-tests.sh @@ -40,15 +40,18 @@ if [[ "${BENCHMARK}" == "composer" ]]; then rc=$? exit $rc; elif [[ "${BENCHMARK}" == "fabric" ]]; then + export CALIPER_FABRIC_SLEEPAFTER_CREATECHANNEL=10000 + export CALIPER_FABRIC_SLEEPAFTER_JOINCHANNEL=10000 + export CALIPER_FABRIC_SLEEPAFTER_INSTANTIATECHAINCODE=10000 # Run with channel creation using a createChannelTx in couchDB, using a Gateway - ${CALL_METHOD} benchmark run --caliper-benchconfig benchmark/simple/config.yaml --caliper-networkconfig network/fabric-v1.4/2org1peercouchdb/fabric-node.yaml --caliper-workspace ../caliper-samples/ --caliper-fabric-usegateway + ${CALL_METHOD} benchmark run --caliper-benchconfig benchmark/simple/config.yaml --caliper-networkconfig network/fabric-v1.4.1/2org1peercouchdb/fabric-node.yaml --caliper-workspace ../caliper-samples/ --caliper-fabric-usegateway rc=$? if [[ $rc != 0 ]]; then exit $rc; else # Run with channel creation using an existing tx file in LevelDB, using a low level Caliper client - ${CALL_METHOD} benchmark run --caliper-benchconfig benchmark/simple/config.yaml --caliper-networkconfig network/fabric-v1.4/2org1peergoleveldb/fabric-go.yaml --caliper-workspace ../caliper-samples/ + ${CALL_METHOD} benchmark run --caliper-benchconfig benchmark/simple/config.yaml --caliper-networkconfig network/fabric-v1.4.1/2org1peergoleveldb/fabric-go.yaml --caliper-workspace ../caliper-samples/ rc=$? exit $rc; fi