From c2638ea4c161e586db726f1bdcfb805936c5dfca Mon Sep 17 00:00:00 2001 From: David Kebler Date: Sat, 10 Aug 2019 14:52:24 -0700 Subject: [PATCH] 0.0.15 Got some testing going for console output, Log/pretty output can now control which properties get displayed via .ignnore and new property .include. improved the scripts in package.json and updated and cleaned all dependencies. --- example/example.js | 17 +++++---- example/example.log | 18 +++++++++ example/filter.sh | 1 + package.json | 29 ++++++++------- src/logger.js | 40 ++++++++++++-------- test/logger.test.js | 91 +++++++++++++++++++++++++++++++++++++++++++++ 6 files changed, 159 insertions(+), 37 deletions(-) create mode 100644 example/example.log create mode 100644 example/filter.sh create mode 100644 test/logger.test.js diff --git a/example/example.js b/example/example.js index 3e3f6a0..036deaf 100644 --- a/example/example.js +++ b/example/example.js @@ -3,7 +3,8 @@ let log = {} class LogTest { constructor(opts) { - log = logger({ + log = logger( + Object.assign({ // pretty: {translateTime:true, colorize:true, levelFirst:true } // options for pino pretty printer // env:'', // 'dev' or 'pro' -- can be use to set/override UCI_ENV environment variable // enForce: false, // only used with .evn. if true will override UCI_ENV if it is set, otherwise no @@ -12,10 +13,10 @@ class LogTest { // logFileName:'test', // if not supplied log filename will be generated from timestamp // below are BASE properties which are optional and are passed to child logger instance and will be part of json log entry // libraryName: 'UCI', // will be logged as name: can be used to identify logs of related packages, can be set via UCI_LOG_NAME env variable - 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: opts.id, // can pass a unique if for easy later search/filtering + 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 // 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 @@ -25,7 +26,8 @@ class LogTest { logPath,instanceCreatedHR,instanceCreated as keys in this object will be merged ------------------*/ // additional: {anotherprop:'test'} - }) + },opts) + ) } logit() { @@ -38,7 +40,8 @@ class LogTest { } } -let test = new LogTest({id:'logtest-via-new'}) +// let test = new LogTest({id:'id-via new instance', pretty:{include:'all'}}) +let test = new LogTest({id:'id-via new instance'}) log.div(`the default log level based on option or UCI_LOG_LEVEL ${log.default}`) test.logit() diff --git a/example/example.log b/example/example.log new file mode 100644 index 0000000..cd1ac6f --- /dev/null +++ b/example/example.log @@ -0,0 +1,18 @@ +{"level":30,"time":1549418336924,"pid":12697,"hostname":"giskard","name":"UCI","logPath":"./example/example.log","appName":"uci-example-logger","repo":"uci-test","package":"@uci/test","file":"src/test.js","class":"Tuci/test","id":"logtest-via-new","instanceCreatedHR":"2019-02-06T01-58-56-919Z","instanceCreated":1549418336923,"runtimeprop":"somevalue","msg":"this is a info level logged message","v":1} +{"level":40,"time":1549418336924,"msg":"this is a warn level logged message","pid":12697,"hostname":"giskard","name":"UCI","logPath":"./example/example.log","appName":"uci-example-logger","repo":"uci-test","package":"@uci/test","file":"src/test.js","class":"Tuci/test","id":"logtest-via-new","instanceCreatedHR":"2019-02-06T01-58-56-919Z","instanceCreated":1549418336923,"v":1} +{"level":50,"time":1549418336924,"msg":"this is a error level logged message","pid":12697,"hostname":"giskard","name":"UCI","logPath":"./example/example.log","appName":"uci-example-logger","repo":"uci-test","package":"@uci/test","file":"src/test.js","class":"Tuci/test","id":"logtest-via-new","instanceCreatedHR":"2019-02-06T01-58-56-919Z","instanceCreated":1549418336923,"v":1} +{"level":60,"time":1549418336924,"msg":"this is a fatal level logged message","pid":12697,"hostname":"giskard","name":"UCI","logPath":"./example/example.log","appName":"uci-example-logger","repo":"uci-test","package":"@uci/test","file":"src/test.js","class":"Tuci/test","id":"logtest-via-new","instanceCreatedHR":"2019-02-06T01-58-56-919Z","instanceCreated":1549418336923,"v":1} +{"level":60,"time":1549418336924,"msg":"this is a fatal level logged message","pid":12697,"hostname":"giskard","name":"UCI","logPath":"./example/example.log","appName":"uci-example-logger","repo":"uci-test","package":"@uci/test","file":"src/test.js","class":"Tuci/test","id":"logtest-via-new","instanceCreatedHR":"2019-02-06T01-58-56-919Z","instanceCreated":1549418336923,"v":1} +{"level":30,"time":1549418336924,"pid":12697,"hostname":"giskard","name":"UCI","logPath":"./example/example.log","appName":"uci-example-logger","repo":"uci-test","package":"@uci/test","file":"src/test.js","class":"Tuci/test","id":"logtest-via-new","instanceCreatedHR":"2019-02-06T01-58-56-919Z","instanceCreated":1549418336923,"runtimeprop":"somevalue","msg":"this is a info level logged message","v":1} +{"level":40,"time":1549418336924,"msg":"this is a warn level logged message","pid":12697,"hostname":"giskard","name":"UCI","logPath":"./example/example.log","appName":"uci-example-logger","repo":"uci-test","package":"@uci/test","file":"src/test.js","class":"Tuci/test","id":"logtest-via-new","instanceCreatedHR":"2019-02-06T01-58-56-919Z","instanceCreated":1549418336923,"v":1} +{"level":50,"time":1549418336924,"msg":"this is a error level logged message","pid":12697,"hostname":"giskard","name":"UCI","logPath":"./example/example.log","appName":"uci-example-logger","repo":"uci-test","package":"@uci/test","file":"src/test.js","class":"Tuci/test","id":"logtest-via-new","instanceCreatedHR":"2019-02-06T01-58-56-919Z","instanceCreated":1549418336923,"v":1} +{"level":60,"time":1549418336924,"msg":"this is a fatal level logged message","pid":12697,"hostname":"giskard","name":"UCI","logPath":"./example/example.log","appName":"uci-example-logger","repo":"uci-test","package":"@uci/test","file":"src/test.js","class":"Tuci/test","id":"logtest-via-new","instanceCreatedHR":"2019-02-06T01-58-56-919Z","instanceCreated":1549418336923,"v":1} +{"level":30,"time":1549418345373,"pid":12734,"hostname":"giskard","name":"UCI","logPath":"./example/example.log","appName":"uci-example-logger","repo":"uci-test","package":"@uci/test","file":"src/test.js","class":"Tuci/test","id":"logtest-via-new","instanceCreatedHR":"2019-02-06T01-59-05-370Z","instanceCreated":1549418345372,"runtimeprop":"somevalue","msg":"this is a info level logged message","v":1} +{"level":40,"time":1549418345373,"msg":"this is a warn level logged message","pid":12734,"hostname":"giskard","name":"UCI","logPath":"./example/example.log","appName":"uci-example-logger","repo":"uci-test","package":"@uci/test","file":"src/test.js","class":"Tuci/test","id":"logtest-via-new","instanceCreatedHR":"2019-02-06T01-59-05-370Z","instanceCreated":1549418345372,"v":1} +{"level":50,"time":1549418345373,"msg":"this is a error level logged message","pid":12734,"hostname":"giskard","name":"UCI","logPath":"./example/example.log","appName":"uci-example-logger","repo":"uci-test","package":"@uci/test","file":"src/test.js","class":"Tuci/test","id":"logtest-via-new","instanceCreatedHR":"2019-02-06T01-59-05-370Z","instanceCreated":1549418345372,"v":1} +{"level":60,"time":1549418345373,"msg":"this is a fatal level logged message","pid":12734,"hostname":"giskard","name":"UCI","logPath":"./example/example.log","appName":"uci-example-logger","repo":"uci-test","package":"@uci/test","file":"src/test.js","class":"Tuci/test","id":"logtest-via-new","instanceCreatedHR":"2019-02-06T01-59-05-370Z","instanceCreated":1549418345372,"v":1} +{"level":60,"time":1549418345373,"msg":"this is a fatal level logged message","pid":12734,"hostname":"giskard","name":"UCI","logPath":"./example/example.log","appName":"uci-example-logger","repo":"uci-test","package":"@uci/test","file":"src/test.js","class":"Tuci/test","id":"logtest-via-new","instanceCreatedHR":"2019-02-06T01-59-05-370Z","instanceCreated":1549418345372,"v":1} +{"level":30,"time":1549418345373,"pid":12734,"hostname":"giskard","name":"UCI","logPath":"./example/example.log","appName":"uci-example-logger","repo":"uci-test","package":"@uci/test","file":"src/test.js","class":"Tuci/test","id":"logtest-via-new","instanceCreatedHR":"2019-02-06T01-59-05-370Z","instanceCreated":1549418345372,"runtimeprop":"somevalue","msg":"this is a info level logged message","v":1} +{"level":40,"time":1549418345373,"msg":"this is a warn level logged message","pid":12734,"hostname":"giskard","name":"UCI","logPath":"./example/example.log","appName":"uci-example-logger","repo":"uci-test","package":"@uci/test","file":"src/test.js","class":"Tuci/test","id":"logtest-via-new","instanceCreatedHR":"2019-02-06T01-59-05-370Z","instanceCreated":1549418345372,"v":1} +{"level":50,"time":1549418345373,"msg":"this is a error level logged message","pid":12734,"hostname":"giskard","name":"UCI","logPath":"./example/example.log","appName":"uci-example-logger","repo":"uci-test","package":"@uci/test","file":"src/test.js","class":"Tuci/test","id":"logtest-via-new","instanceCreatedHR":"2019-02-06T01-59-05-370Z","instanceCreated":1549418345372,"v":1} +{"level":60,"time":1549418345373,"msg":"this is a fatal level logged message","pid":12734,"hostname":"giskard","name":"UCI","logPath":"./example/example.log","appName":"uci-example-logger","repo":"uci-test","package":"@uci/test","file":"src/test.js","class":"Tuci/test","id":"logtest-via-new","instanceCreatedHR":"2019-02-06T01-59-05-370Z","instanceCreated":1549418345372,"v":1} diff --git a/example/filter.sh b/example/filter.sh new file mode 100644 index 0000000..26b9842 --- /dev/null +++ b/example/filter.sh @@ -0,0 +1 @@ +cat uci.log | jq -cs '.[] | select(.test=="filter")' diff --git a/package.json b/package.json index a4b3f6c..8d44f60 100644 --- a/package.json +++ b/package.json @@ -1,19 +1,22 @@ { "name": "@uci-utils/logger", - "version": "0.0.14", + "version": "0.0.15", "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", - "testci": "istanbul cover ./node_modules/.bin/_mocha --report lcovonly -- -R spec --recursive && codecov || true", - "none": "node -r esm example/example", "dev": "UCI_ENV=dev ./node_modules/.bin/nodemon -r esm example/example", - "dev:info": "UCI_ENV=dev UCI_LOG_SEARCH='level==`30`' ./node_modules/.bin/nodemon -r esm example/example", - "dev:fatal": "UCI_ENV=dev UCI_LOG_SEARCH='level==`60`' ./node_modules/.bin/nodemon -r esm example/example", - "json": "UCI_ENV=dev UCI_LOG_JSON=true ./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: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:alt": "UCI_ENV='pro' UCI_LOG_PATH=./example/example.log node -r esm example/example" + "pro:path": "UCI_LOG_PATH=./example/example.log npm run pro" }, "author": "David Kebler", "license": "MIT", @@ -33,16 +36,14 @@ "dependencies": { "env-paths": "^2.2.0", "make-dir": "^3.0.0", - "pino": "^5.12.3", - "pino-pretty": "^2.6.1" + "pino": "^5.13.2", + "pino-pretty": "^3.2.0" }, "devDependencies": { "chai": "^4.2.0", - "codecov": "^3.1.0", - "esm": "^3.1.2", - "istanbul": "^0.4.5", - "mocha": "^5.2.0", - "nodemon": "^1.18.9", + "esm": "^3.2.25", + "mocha": "^6.2.0", + "nodemon": "^1.19.1", "test-console": "^1.1.0" } } diff --git a/src/logger.js b/src/logger.js index 0152c03..89e2e90 100644 --- a/src/logger.js +++ b/src/logger.js @@ -9,14 +9,37 @@ function child (opts) { let pretty = false; let LOG_PATH; let DATE_TIME + const PRETTY_DEFAULTS = {translateTime:true, colorize:true, levelFirst:true } + + let logOpts = { + level:opts.level || process.env.UCI_LOG_LEVEL, + logPath: LOG_PATH, // if logging to file + appName: 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), + class: opts.class || ( (typeof opts.package==='string') ? capitalize(basename(opts.package)) : undefined), + id: opts.id || opts.name || 'none', + instanceCreatedHR:DATE_TIME, + instanceCreated:Date.now() + } + + logOpts = Object.assign(logOpts,opts.additional) + 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') { - pretty = process.env.UCI_LOG_PRETTY || opts.pretty || {translateTime:true, colorize:true, levelFirst: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() } + } DATE_TIME = new Date().toString() LOG_PATH = ( process.env.UCI_ENV.indexOf('pro') > -1 || process.env.UCI_ENV === 'logfile' ) @@ -41,21 +64,6 @@ function child (opts) { LOG_PATH ) - let logOpts = { - level:opts.level || process.env.UCI_LOG_LEVEL, - logPath: LOG_PATH, // if logging to file - appName: 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), - class: opts.class || ( (typeof opts.package==='string') ? capitalize(basename(opts.package)) : undefined), - id: opts.id || opts.name || 'none', - instanceCreatedHR:DATE_TIME, - instanceCreated:Date.now() - } - - logOpts = Object.assign(logOpts,opts.additional) - let child = logger.child(logOpts) child.default = opts.level || process.env.UCI_LOG_LEVEL diff --git a/test/logger.test.js b/test/logger.test.js new file mode 100644 index 0000000..eccecb9 --- /dev/null +++ b/test/logger.test.js @@ -0,0 +1,91 @@ +import logger from '../src/logger' +import { expect } from 'chai' +import { it } from 'mocha' +import { stdout } from 'test-console' +//https://github.com/jamesshore/test-console + +describe('JSON Logging Utility Testing ',async ()=> { + + let log + // let captured = stdout.inspect().output + // let capture = stdout.inspect + // let restore = stdout.inspect().restore + // + class LogTest { + constructor(opts) { + log = logger({ + name: 'test', + id: opts.id, + // file: 'example/example.js', + // class: 'LogTest', + // repo:'test repo' + package:'@uci-utils/test' + }) + // console.log('env',process.env.UCI_ENV) + } + async logit(level,msg,props={}) { + Object.assign(props,{msg:msg}) + log[level](props) + } + } + + let levelName = { + 10:'trace', + 20:'debug', + 30:'info', + 40:'warn', + 50:'error', + 60:'fatal' + } + + let logtest = {} + let inspect = {} + + beforeEach( () => { + // console.log('starting console capture') + inspect = stdout.inspect() + }) + afterEach( () => { + inspect.restore() + // console.log('console.restored') + }) + + + it('check dev output to console' , async function () { + // setup + let msg='test' + let level = 'info' + let moreprops = {} + process.env.UCI_ENV='dev' + logtest = new LogTest({id:'someid'}) + + // create log to stdout + logtest.logit(level,msg,moreprops) + + // test stdout response + let response = inspect.output[0] + expect(response).to.have.string(level.toUpperCase()) && + expect(response).to.have.string(msg) + }) + + it('check json output' , async function () { + // setup + let msg='test' + let level = 'info' + let moreprops = {} + process.env.UCI_ENV='dev' + process.env.UCI_LOG_JSON=true + logtest = new LogTest({id:'someid'}) + + // create log to stdout + logtest.logit(level,msg,moreprops) + + // test stdout response + let response = inspect.output[0] + response = JSON.parse(response) + expect(response.msg).to.equal(msg) && + expect(levelName[response.level]).to.equal(level) + }) + + +})