From e9cee9bcd389d8e663583f56b8ac24baedcd6a17 Mon Sep 17 00:00:00 2001 From: David Kebler Date: Thu, 21 Nov 2019 08:05:08 -0800 Subject: [PATCH] 0.0.16 prepend pino prettty within the logger with a pretty filter pre processor adds easier filtering of log properties (default) and filtering based on location/where properties support a new env variable UCI_LOG_PRETTY with options like terse,verbose,where --- example/example.js | 17 +++++---- package.json | 10 +++--- readme.md | 20 +++++++---- src/logger.js | 84 +++++++++++++++++++++++++++++++++++---------- test/logger.test.js | 1 + 5 files changed, 96 insertions(+), 36 deletions(-) diff --git a/example/example.js b/example/example.js index 036deaf..13ec306 100644 --- a/example/example.js +++ b/example/example.js @@ -16,7 +16,7 @@ class LogTest { appName:'uci-example-logger', //will be used for logging directory name if supplied and will be logged as well package: '@uci/test', // name of package with scope per package.json // repo: // will use scope-name from package prop if not supplied - id: 'built in id', // can pass a unique if for easy later search/filtering + id: 'id set in package', // can pass a unique if for easy later search/filtering // file: 'example/example.js', // path (to repo root) of actual file running this logger, default is ./src/.js // class: 'LogTest', // The class that created this logger if any @@ -32,8 +32,8 @@ class LogTest { logit() { log.trace('this is a trace level logged message') - log.debug('this is a debug level logged message') - log.info({runtimeprop:'somevalue', msg:'this is a info level logged message'}) + log.debug({line:343,msg:'this is a debug level logged message with a line number'}) + log.info({runtimeprop:'some propetery in context', msg:'this is a info level logged message'}) log.warn('this is a warn level logged message') log.error('this is a error level logged message') log.fatal('this is a fatal level logged message') @@ -41,14 +41,17 @@ class LogTest { } // let test = new LogTest({id:'id-via new instance', pretty:{include:'all'}}) -let test = new LogTest({id:'id-via new instance'}) +let test = new LogTest() -log.div(`the default log level based on option or UCI_LOG_LEVEL ${log.default}`) +log.div(`the default log level based on option or UCI_LOG_LEVEL ${log.level}`) test.logit() -log.lvlset('fatal') +log.lvlset('warn') log.div(`now changing log level manually in code to ${log.level}`) test.logit() -log.div(`reset level back current default ${log.default}`) +log.lvlset('trace') +log.div(`now changing log level to lowest (view all levels) ${log.level}`) +test.logit() log.lvlset() +log.div(`reset level back current default ${log.level}`) test.logit() log.clear('This call to log.clear could clear the file log when implemented') diff --git a/package.json b/package.json index 8d44f60..587dff0 100644 --- a/package.json +++ b/package.json @@ -1,20 +1,22 @@ { "name": "@uci-utils/logger", - "version": "0.0.15", + "version": "0.0.16", "description": "Parent Logger for all UCI modules", "main": "src/logger", "scripts": { "testd": "./node_modules/.bin/nodemon --exec './node_modules/.bin/mocha -r esm --timeout 30000'", "test": "./node_modules/.bin/mocha -r esm --timeout 30000 || exit 0", "dev": "UCI_ENV=dev ./node_modules/.bin/nodemon -r esm example/example", - "dev:all": "UCI_LOG_PRETTY='{\"include\":\"all\"}' npm run dev", - "dev:includes": "UCI_LOG_PRETTY='{\"include\":\"package,appName\"}' npm run dev", + "dev:verbose": "UCI_LOG_PRETTY='verbose' npm run dev", + "dev:terse": "UCI_LOG_PRETTY='terse' npm run dev", + "dev:where": "UCI_LOG_PRETTY='where' npm run dev", + "dev:filter:line": "UCI_LOG_PRETTY='{\"filter\":[\"line\"]}' npm run dev", + "dev:include": "UCI_LOG_PRETTY='{\"include\":\"package,appName\"}' npm run dev", "dev:trace": "UCI_LOG_LEVEL=trace npm run dev", "dev:warn": "UCI_LOG_LEVEL=warn npm run dev", "dev:info:only": "UCI_LOG_SEARCH='level==`30`' npm run dev", "dev:fatal:only": "UCI_LOG_SEARCH='level==`60`' npm run dev", "dev:json": "UCI_LOG_LEVEL=trace UCI_LOG_JSON=true npm run dev", - "dev:colada": "npm run dev:json | ./node_modules/.bin/pino-colada ", "pro": "UCI_ENV='pro' node -r esm example/example", "pro:path": "UCI_LOG_PATH=./example/example.log npm run pro" }, diff --git a/readme.md b/readme.md index bbb8289..39e3e86 100644 --- a/readme.md +++ b/readme.md @@ -37,13 +37,19 @@ then available scripts for example file -- `none`: no logs to console or file -- `dev`: all levels pretty printed to console/stdout -- `dev:info`: show/filter only level 30 (info) logs pretty printed to console -- `dev:fatal`: show/filer only level 60 (fatal) logs pretty printed to console -- `json`: log to console but as raw json -- `pro`: log to a file in the userspace default log directory location -- `pro:alt`: log to a supplied/alternate file (path) location in this case `./example/example.log` +"dev": "UCI_ENV=dev ./node_modules/.bin/nodemon -r esm example/example", +"dev:verbose": "UCI_LOG_PRETTY='verbose' npm run dev", +"dev:terse": "UCI_LOG_PRETTY='terse' npm run dev", +"dev:filter:line": "UCI_LOG_PRETTY='{\"filter\":[\"line\"]}' npm run dev", +"dev:include": "UCI_LOG_PRETTY='{\"include\":\"package,appName\"}' npm run dev", +"dev:trace": "UCI_LOG_LEVEL=trace npm run dev", +"dev:warn": "UCI_LOG_LEVEL=warn npm run dev", +"dev:info:only": "UCI_LOG_SEARCH='level==`30`' npm run dev", +"dev:fatal:only": "UCI_LOG_SEARCH='level==`60`' npm run dev", +"dev:json": "UCI_LOG_LEVEL=trace UCI_LOG_JSON=true npm run dev", +"dev:colada": "npm run dev:json | ./node_modules/.bin/pino-colada ", +"pro": "UCI_ENV='pro' node -r esm example/example", +"pro:path": "UCI_LOG_PATH=./example/example.log npm run pro" ## Environment Variables diff --git a/src/logger.js b/src/logger.js index 89e2e90..6ce7b44 100644 --- a/src/logger.js +++ b/src/logger.js @@ -2,19 +2,22 @@ import pino from 'pino' import envPaths from 'env-paths' import { sync as mkdir } from 'make-dir' import { dirname, basename } from 'path' +import pinoPretty from 'pino-pretty' function child (opts) { const enabled = !!process.env.UCI_ENV - let pretty = false; let LOG_PATH; let DATE_TIME + let pretty; let filter; let LOG_PATH; let DATE_TIME - const PRETTY_DEFAULTS = {translateTime:true, colorize:true, levelFirst:true } + const PRETTY_DEFAULTS = {translateTime:true, colorize:true, levelFirst:true} + const DEFAULT_FILTER_PROPS = ['level','time','v','pid','msg'] + const WHERE_FILTER_PROPS = ['package','file','method','function','line'] let logOpts = { level:opts.level || process.env.UCI_LOG_LEVEL, logPath: LOG_PATH, // if logging to file - appName: opts.appName || opts.name, + appName: process.env.UCI_LOG_APP || opts.appName || opts.name, package: opts.package, repo: opts.repo || ((typeof opts.package==='string') ? opts.package.replace( /[@]+/g, '' ).replace( /[/]+/g, '-' ) : undefined), file: opts.file || ((typeof opts.package==='string') ? `src/${basename(opts.package)}.js` : undefined), @@ -24,23 +27,35 @@ function child (opts) { instanceCreated:Date.now() } - logOpts = Object.assign(logOpts,opts.additional) + // logOpts = Object.assign(logOpts,opts.additional) + + // console.log('log opts', logOpts) if (enabled) { if (opts.env) (opts.envForce) ? (process.env.UCI_ENV = opts.env) : (process.env.UCI_ENV = process.env.UCI_ENV || opts.env) if (process.env.UCI_ENV === 'node') process.env.UCI_ENV = process.env.NODE_ENV - if(process.env.UCI_ENV.indexOf('dev')>-1) { - if (process.env.UCI_LOG_JSON !=='true') { - if (process.env.UCI_LOG_PRETTY && process.env.UCI_LOG_PRETTY !=='true') pretty = JSON.parse(process.env.UCI_LOG_PRETTY) - pretty = pretty || opts.pretty || {} - pretty = Object.assign({},PRETTY_DEFAULTS,pretty) - pretty.search = process.env.UCI_LOG_SEARCH - pretty.include = pretty.include === 'all' ? 'all' : `level,${pretty.include}` - console.log(pretty.include) - pretty.ignore = pretty.include === 'all' ? null : Object.keys(logOpts).filter(key => pretty.include.indexOf(key) === -1 ).join() + if((process.env.UCI_ENV.indexOf('dev')>-1 || process.env.UCI_LOG_PRETTY) && process.env.UCI_LOG_JSON !=='true' ) { // pretty is on + try { + pretty = JSON.parse(process.env.UCI_LOG_PRETTY) } + catch (error) { + // console.log('LOGGER: could not parse',process.env.UCI_LOG_PRETTY ) + if (process.env.UCI_LOG_PRETTY==='verbose') pretty ={include:'all'} + } + pretty = pretty || opts.pretty || {} + pretty = Object.assign({},PRETTY_DEFAULTS,pretty) + pretty.search = process.env.UCI_LOG_SEARCH + pretty.include = pretty.include === 'all' ? 'all' : `level${pretty.include ? ','+ pretty.include : ''}` + pretty.ignore = pretty.include === 'all' ? null : Object.keys(logOpts).filter(key => pretty.include.indexOf(key) === -1 ).join() + + if (process.env.UCI_LOG_PRETTY === 'terse' || process.env.UCI_LOG_PRETTY === 'where' || pretty.filter ) { + filter = filterPretty // only call prefilter if some filter is supplied, otherwise + pretty.filter = [...DEFAULT_FILTER_PROPS,...(process.env.UCI_LOG_PRETTY === 'where' ? WHERE_FILTER_PROPS : []),...(pretty.filter||[])] + pretty.ignore = null + } } + DATE_TIME = new Date().toString() LOG_PATH = ( process.env.UCI_ENV.indexOf('pro') > -1 || process.env.UCI_ENV === 'logfile' ) ? ( process.env.UCI_LOG_PATH || `${envPaths(opts.appName || opts.name || 'default').log}/${opts.logFileName || DATE_TIME}.log`) : undefined @@ -48,8 +63,12 @@ function child (opts) { try { mkdir(dirname(LOG_PATH)) } // makes recursively for any missing parent directories catch(err) { throw err } } - } - // console.log('making logger (env,json,pretty,pretty-search,path)',process.env.UCI_ENV,process.env.UCI_LOG_JSON,pretty,process.env.UCI_LOG_SEARCH,LOG_PATH) + } // end enabled + + + + // console.log('pretty terse logger', pretty.terse) + // console.log('making logger \n(env,json,pretty,pretty-search,path)\n',process.env.UCI_ENV,process.env.UCI_LOG_JSON,pretty,process.env.UCI_LOG_SEARCH,LOG_PATH) const logger = pino({ name: opts.libraryName || process.env.UCI_LOG_NAME || 'UCI', enabled: enabled, @@ -58,7 +77,8 @@ function child (opts) { req: pino.stdSerializers.req, res: pino.stdSerializers.res }, - prettyPrint: pretty + prettyPrint: pretty, + prettifier: filter // only call prefilter if some filter is supplied, otherwise see line 53 }, // if production not enabled then LOG_PATH is empty and logs go to stdout/stderr and can be piped from there LOG_PATH @@ -66,7 +86,7 @@ function child (opts) { let child = logger.child(logOpts) - child.default = opts.level || process.env.UCI_LOG_LEVEL + child.default = process.env.UCI_LOG_LEVEL || opts.level || 'info' child.clear = () => { if (enabled) { if (process.env.UCI_ENV.indexOf('pro') > -1) return null } // enable feature here @@ -75,7 +95,7 @@ function child (opts) { if (enabled) { if (process.env.UCI_ENV.indexOf('dev') > -1) console.log(`===== ${value} ========`)} } - child.lvlset = (level) => { if (enabled) child.level = level || child.default || 'info' } + child.lvlset = (level) => { if (enabled) child.level = level || child.default } return child } @@ -83,3 +103,31 @@ function child (opts) { export default child function capitalize (s) { return s.charAt(0).toUpperCase() + s.slice(1)} + +function filterPretty (options) { + return function prettifier (inputData) { + let log + let parsedData + if (typeof inputData === 'string') { + try { parsedData = JSON.Parse(inputData)} + catch(err){ return inputData } + log = (isPinoLog(parsedData)) ? parsedData : undefined + } else if (isObject(inputData) && isPinoLog(inputData)) { + log = inputData + } + if (!log) return inputData + let filteredLog = {} + options.filter.forEach(prop => filteredLog[prop]= log[prop]) + // console.log('filtered',options.filter, filteredLog) + // if (options.pid) console.log('pid:',logObject.pid) + return pinoPretty(options)(filteredLog) + } + + function isObject (input) { + return Object.prototype.toString.apply(input) === '[object Object]' + } + + function isPinoLog (log) { + return log && (log.hasOwnProperty('v') && log.v === 1) + } +} diff --git a/test/logger.test.js b/test/logger.test.js index eccecb9..4d862da 100644 --- a/test/logger.test.js +++ b/test/logger.test.js @@ -29,6 +29,7 @@ describe('JSON Logging Utility Testing ',async ()=> { } } + // TODO this is available from the logger as .levels let levelName = { 10:'trace', 20:'debug',