From 041f6af6c234bd198f6f4d262e494120ed5e3b36 Mon Sep 17 00:00:00 2001 From: MFrizo Date: Mon, 8 Jun 2020 10:58:29 -0300 Subject: [PATCH 1/3] Update Dependencies --- package.json | 8 ++++++-- 1 file changed, 6 insertions(+), 2 deletions(-) diff --git a/package.json b/package.json index fa86bf0..b37e9d0 100644 --- a/package.json +++ b/package.json @@ -4,8 +4,12 @@ "description": "Winston logger with custom 5A configuration", "main": "src/main.js", "dependencies": { - "winston": "^3.1.0", - "winston-raven-sentry": "^2.0.0" + "@sentry/node": "^5.17.0", + "lodash": "^4.17.15", + "stack-trace": "0.0.10", + "util": "^0.12.3", + "winston": "^3.2.1", + "winston-transport": "^4.3.0" }, "scripts": { "test": "echo \"Error: no test specified\" && exit 1" From dc85db8ad1bf88a8e64ada8730fade736efb833c Mon Sep 17 00:00:00 2001 From: MFrizo Date: Mon, 8 Jun 2020 11:42:59 -0300 Subject: [PATCH 2/3] Implements new logger version --- src/customFormats.js | 65 ------------- src/main.js | 227 ++++++++++++++++++++++++++++++++++++------- src/transports.js | 125 ++++++++++++++++++++++++ 3 files changed, 315 insertions(+), 102 deletions(-) delete mode 100644 src/customFormats.js create mode 100644 src/transports.js diff --git a/src/customFormats.js b/src/customFormats.js deleted file mode 100644 index 5a21c33..0000000 --- a/src/customFormats.js +++ /dev/null @@ -1,65 +0,0 @@ -const { format } = require('winston'); - -function fillExcept(info, fillExceptKeys, metadataKey) { - const savedKeys = fillExceptKeys.reduce((acc, key) => { - acc[key] = info[key]; - delete info[key]; - return acc; - }, {}); - const metadata = Object.keys(info).reduce((acc, key) => { - acc[key] = info[key]; - delete info[key]; - return acc; - }, {}); - - Object.assign(info, savedKeys, { - [metadataKey]: metadata - }); - return info; -} - -function fillWith(info, fillWithKeys, metadataKey) { - info[metadataKey] = fillWithKeys.reduce((acc, key) => { - acc[key] = info[key]; - delete info[key]; - return acc; - }, {}); - return info; -} - -const extraData = format((info, opts = {}) => { - let metadataKey = 'extra_data'; - if (opts.key) { - metadataKey = opts.key; - } - - let fillExceptKeys = []; - if (!opts.fillExcept && !opts.fillWith) { - fillExceptKeys.push('level'); - fillExceptKeys.push('message'); - } - - if (opts.fillExcept) { - fillExceptKeys = opts.fillExcept; - } - - if (fillExceptKeys.length > 0) { - return fillExcept(info, fillExceptKeys, metadataKey); - } - - if (opts.fillWith) { - return fillWith(info, opts.fillWith, metadataKey); - } - - return info; -}); - -const loggerName = format((info, path) => { - info.logger_name = path; - return info; -}); - -module.exports = { - loggerName, - extraData, -}; diff --git a/src/main.js b/src/main.js index 21819ba..f1dd6b7 100644 --- a/src/main.js +++ b/src/main.js @@ -1,43 +1,196 @@ -const { transports, format, createLogger } = require('winston'); -const Sentry = require('winston-raven-sentry'); -const { loggerName, extraData } = require('./customFormats'); - -function getLogger(mod) { - const path = mod.filename.split('/').slice(-2).join('/'); - const winstonTransports = [ - new transports.Console({ - format: format.combine( - extraData(), - loggerName(path), - format.timestamp(), - format.json(), - ), - level: process.env.CONSOLE_LOG_LEVEL || 'info', - stderrLevels: ['error'], - }), - ]; - - if (process.env.SENTRY_DSN) { - winstonTransports.push(new Sentry({ - level: 'warn', - dsn: process.env.SENTRY_DSN, - tags: { - app: process.env.SENTRY_APP, +const util = require('util'); +const stackTrace = require('stack-trace'); +const Sentry = require('@sentry/node'); +const { createLogger } = require('winston'); +const { + sentryTransport, + consoleTransport, +} = require('./transports'); + +const winstonTransports = [ + sentryTransport, + consoleTransport, +]; + +if(process.env.SENTRY_DSN && process.env.NODE_ENV !== 'development') { + Sentry.init({ + serverName: process.env.SENTRY_APP, + dsn: process.env.SENTRY_DSN, environment: process.env.SENTRY_ENVIRONMENT, - }, - config: { - captureUnhandledRejections: process.env.CAPTURE_UNHANDLED_REJECTIONS || false, - }, - release: process.env.SENTRY_RELEASE, - install: true, - })); - } - - return createLogger({ + debug: process.env.NODE_ENV !== 'production', + release: process.env.SENTRY_RELEASE, + }); +} + +let tracer; +const prettyLogs = process.env.PRETTY_LOGS; +const winstonLogger = createLogger({ transports: winstonTransports, - }); +}); + +function getFunctionCaller(func) { + return func.caller; +} + +function getFunctionData(func) { + const trace = stackTrace.get(func || getFunctionCaller(getFunctionData)); + const callerData = trace[0]; + const data = { + filePath: `${callerData.getFileName()}:${callerData.getLineNumber()}:${callerData.getColumnNumber()}`, + }; + + const caller = callerData.getMethodName() + ? `${callerData.getTypeName()}.${callerData.getMethodName()}` + : callerData.getFunctionName(); + + if (caller) { + data.caller = caller; + } + + return data; +} + +function formatParams(params, module, funcCallerParam) { + function formatError(err) { + return { + message: err.message, + stack: err.stack, + }; + } + + const funcCaller = funcCallerParam || {}; + const result = []; + const metadata = {}; + + if (tracer && tracer.currentRootSpan && tracer.currentRootSpan.traceId) { + metadata.traceId = tracer.currentRootSpan.traceId; + } + + if (typeof params[0] === 'string') { + result[0] = params[0]; + } else if (params[0] instanceof Error) { + result[0] = params[0].message; + metadata.error = formatError(params[0]); + } else { + result[0] = util.inspect(params[0], { + compact: prettyLogs, + colors: prettyLogs, + depth: null, + breakLength: Infinity, + }); + } + + for (let i = 1; i < params.length; i++) { + if (params[i] instanceof Error) { + metadata.error = formatError(params[i]); + } else if (typeof params[i] === 'object') { + if (!metadata.extra) { + metadata.extra = {}; + } + + Object.assign(metadata.extra, params[i]); + } + } + + if(module) { + metadata.module = module; + } + + Object.assign(metadata, funcCaller); + result.push(metadata); + return result; +} + +function debugAndFuncCaller(funcCaller, module, ...params) { + const formattedParams = formatParams(params, module, funcCaller); + winstonLogger.debug(...formattedParams); +} + +function errorAndFuncCaller(funcCaller, module, ...params) { + const formattedParams = formatParams(params, module, funcCaller); + winstonLogger.error(...formattedParams); +} + +function warnAndFuncCaller(funcCaller, module, ...params) { + const formattedParams = formatParams(params, module, funcCaller); + winstonLogger.warn(...formattedParams); +} + +function debugLog(module, ...params) { + if (!winstonLogger.isLevelEnabled('debug')) { + return; + } + debugAndFuncCaller(getFunctionData(debugLog), module, ...params); +} + +function infoLog(module, ...params) { + if (!winstonLogger.isLevelEnabled('info')) { + return; + } + const formattedParams = formatParams(params, module); + winstonLogger.info(...formattedParams); +} + +function errorLog(module, ...params) { + if (!winstonLogger.isLevelEnabled('error')) { + return; + } + errorAndFuncCaller(getFunctionData(errorLog), module, ...params); +} + +function warnLog(module, ...params) { + if (!winstonLogger.isLevelEnabled('warn')) { + return; + } + warnAndFuncCaller(getFunctionData(warnLog), module, ...params); +} + +const _consoleLog = console.log; +const _consoleError = console.error; +const _consoleWarn = console.warn; + +const sentryMessageToAvoid = 'Sentry Logger'; +const sentryMessageType = 'string'; + +if (process.env.NODE_ENV === 'test') { + console.log = function (...params) { + _consoleLog.apply(console, ['\u001b[31;1m', ...params, '\u001b[39;49m']); + if ((typeof params[0] === sentryMessageType) && (params[0].includes(sentryMessageToAvoid))) return; + if (!winstonLogger.isLevelEnabled('debug')) { + return; + } + debugAndFuncCaller(getFunctionData(console.log), undefined, ...params); + }; + + console.error = function (...params) { + _consoleError.apply(console, ['\u001b[31;1m', ...params, '\u001b[39;49m']); + if ((typeof params[0] === sentryMessageType) && (params[0].includes(sentryMessageToAvoid))) return; + if (!winstonLogger.isLevelEnabled('error')) { + return; + } + errorAndFuncCaller(getFunctionData(console.error), undefined, ...params); + }; + + console.warn = function (...params) { + _consoleWarn.apply(console, ['\u001b[31;1m', ...params, '\u001b[39;49m']); + if ((typeof params[0] === sentryMessageType) && (params[0].includes(sentryMessageToAvoid))) return; + if (!winstonLogger.isLevelEnabled('warn')) { + return; + } + warnAndFuncCaller(getFunctionData(console.warn), undefined, ...params); + }; } module.exports = { - getLogger, + setTracer: (newTracer) => tracer = newTracer, + getLogger: (mod) => { + const module = mod.filename.split('/').slice(-2).join('/'); + + return { + error: (...params) => errorLog(module, ...params), + warn: (...params) => warnLog(module, ...params), + info: (...params) => infoLog(module, ...params), + debug: (...params) => debugLog(module, ...params), + }; + } }; diff --git a/src/transports.js b/src/transports.js new file mode 100644 index 0000000..4025dae --- /dev/null +++ b/src/transports.js @@ -0,0 +1,125 @@ +const _ = require('lodash'); +const Sentry = require('@sentry/node'); +const { transports, format } = require('winston'); +const Transport = require('winston-transport'); +const util = require('util'); + +const prettyLogs = process.env.PRETTY_LOGS; +const escapeSequences = { + separator: prettyLogs ? '\n' : ' ', + red: '\u001b[31;1m', + uncolorize: '\u001b[39;49m', +}; + +class SentryTransport extends Transport { + constructor(options) { + options = options || {}; + options = _.defaultsDeep(options, { + name: 'SentryTransport', + silent: false, + level: process.env.SENTRY_LOGGER_LEVEL || 'warn', + levelsMap: { + silly: 'debug', + verbose: 'debug', + info: 'info', + debug: 'debug', + warn: 'warning', + error: 'error', + }, + }); + + super(_.omit(options, [ + 'levelsMap', + ])); + + this._silent = options.silent; + this._levelsMap = options.levelsMap; + } + + log(info, next) { + if (this.silent) return next(null, true); + if (!(info.level in this._levelsMap)) return next(null, true); + + const thereIsErrorExtraData = info.extra && info.extra.error && (info.extra.error instanceof Error); + + let error = {}; + + if (thereIsErrorExtraData) { + error = info.extra.error; + info.extra.error = util.inspect(error, { showHidden: false, depth: null }); + } + + Sentry.configureScope((scope) => { + scope.setLevel(this._levelsMap[info.level]); + scope.setExtra('context', info); + }); + + if (thereIsErrorExtraData) Sentry.captureMessage(error); + else Sentry.captureMessage(info.message); + + return next(); + } +} + +const sentryTransport = new SentryTransport(); + +const fillExcept = ['message', 'level', 'label', 'traceId']; +if (process.env.NODE_ENV === 'production') { + fillExcept.push('timestamp'); +} + +let loggerFormat = format.combine( + format.timestamp(), + format.metadata({ fillExcept }), + format.printf((info) => { + const metadata = info.metadata; + let out = `[${info.level}] ${info.message}`; + if (info.traceId) { + out += ` [trace-id: ${info.traceId}]`; + } + + const error = info.metadata.error; + + if (error && prettyLogs) { + delete metadata.error; + } + + if (Object.keys(metadata).length > 0) { + out += escapeSequences.separator; + out += util.inspect(metadata, { + compact: false, colors: prettyLogs, depth: null, breakLength: Infinity, + }); + out += escapeSequences.separator; + } + + if (error && prettyLogs) { + out += escapeSequences.separator; + out += `${escapeSequences.red}${error.stack}${escapeSequences.uncolorize}`; + out += escapeSequences.separator; + } + + if (!prettyLogs) { + out = out.replace(/\n/g, '').replace(/\s\s+/g, ' '); + } + + return out; + }), +); + +if (prettyLogs) { + loggerFormat = format.combine( + format.colorize(), + loggerFormat, + ); +} + +const consoleTransport = new transports.Console({ + format: loggerFormat, + level: process.env.CONSOLE_LOG_LEVEL || 'info', + stderrLevels: ['error'], +}); + +module.exports = { + sentryTransport, + consoleTransport, +}; From c69007dba19f649c8d43aee5af88c14670f2cfb5 Mon Sep 17 00:00:00 2001 From: MFrizo Date: Mon, 8 Jun 2020 13:05:40 -0300 Subject: [PATCH 3/3] Update Read Me --- README.md | 62 ++++++++++++++++++++++++++++++++++++++++++++++++------- 1 file changed, 54 insertions(+), 8 deletions(-) diff --git a/README.md b/README.md index 1eeaa9a..97e8256 100644 --- a/README.md +++ b/README.md @@ -1,29 +1,31 @@ # node-logger -Winston logger with sentry configuration included. Also show the file from which the log originated. +Winston logger with sentry configuration included. Also show the module, file path and caller from which the log originated. ## Environment variable | Name | Description | | -------------------- | -------------------------------------------- | -| SENTRY_DSN | Sentry's DNS | +| CONSOLE_LOG_LEVEL | The level of the logs displayed on the console (optional, defaults to info) | +| NODE_ENV | The application environment running (development, test, production) | +| PRETTY_LOGS | Enable colored logs with clean spacing | | SENTRY_APP | The application's name | +| SENTRY_DSN | Sentry's DNS | | SENTRY_ENVIRONMENT | The environment running (dev, staging, prod) | +| SENTRY_LOGGER_LEVEL | The level of the logs displayed at Sentry (optional, defaults to warn) | | SENTRY_RELEASE | The current release | -| CONSOLE_LOG_LEVEL | The level of the logs displayed on the console (optional, defaults to info) | -| CAPTURE_UNHANDLED_REJECTIONS | A value (true or false) saying if you want these exceptions to be logged in you app | ## Setting up ```sh -npm install --save git+https://github.com/quintoandar/node-logger.git# +npm install github:quintoandar/node-logger#semver:~ ``` Or add it on your `package.json` file like: ```sh "dependencies": { - "quintoandar-logger": "git+https://github.com/quintoandar/node-logger.git#", + "quintoandar-logger": "github:quintoandar/node-logger#semver:~ }, ``` @@ -33,6 +35,8 @@ Or add it on your `package.json` file like: With info, warn and error messages the behaviour is the same. You are able to send the string (the info message) plus any other metadata you want as the second parameter, but be sure to add this data on a specific key named `extra` so that Sentry knows how to parse it and display it. +Since the Kibana application, by default, set a timestamp value to its logs, if the `NODE_ENV` env var was equals to `production` this field will be supressed at the logs. To enable it to show, its necessary to set a different value to this variable: (`development` or `test`). + ```js const logger = require('quintoandar-logger').getLogger(module); @@ -43,13 +47,55 @@ logger.error(`Some error while processing cool object with id ${object.id}`, { e ``` On the console it will be logged as a json: + +```sh +[info] Some info about processing cool object with id 11 { extra: { extra: { data: { id: 11, someInfo: 'someInfo' } } }, module: 'path/to/my/file.js', timestamp: '2020-06-09T22:46:21.759Z'} +``` + +With pretty log enabled: + ```sh -{"level":"info","message":"Some info about processing cool object with id 10","extra_data":{"extra":{"data":{"id":"11","someInfo":"someInfo"}}},"logger_name":"path/to/my/file.js","timestamp":"2018-12-19T18:15:57.078Z"} +[info] Some info about processing cool object with id 11 +{ + extra: { + extra: { + data: { + id: 11, + someInfo: 'someInfo' + } + } + }, + module: 'path/to/my/file.js', + timestamp: '2020-06-08T15:35:29.122Z' +} ``` And on Sentry the data on `extra` will be displayed under the field `Additional Data`. +### Tracer + +If your project is using the honeycomb tracer library, you can include the tracer Id of the instance running to the logger. + +On your code, you just need to intanciate the tracer within the logger library once. + +```js +const tracer = { currentRootSpan: { traceId: 'TRACER-ID' } }; + +const quintoandarLogger = require('./src/main'); +quintoandarLogger.setTracer(tracer); + +const logger = quintoandarLogger.getLogger(module); + +const object = { id: 11, someInfo: 'someInfo' } +logger.info(`Some info about processing cool object with id ${object.id}`, { extra: { data: object } }); +``` + +At your console, the logs now contain the trace-id identifier: + +```sh +[info] Some info about processing cool object with id 11 [trace-id: TRACER-ID] { extra: { extra: { data: { id: 11, someInfo: 'someInfo' } } }, module: 'path/to/my/file.js', timestamp: '2020-06-09T22:46:21.759Z'} +``` + ## TODO - Create Express Middleware Request Logger -