diff --git a/README.md b/README.md index 817aa4254..aeee2dffe 100644 --- a/README.md +++ b/README.md @@ -3,15 +3,12 @@ # pino  [![Build Status](https://travis-ci.org/pinojs/pino.svg?branch=master)](https://travis-ci.org/pinojs/pino) [![Coverage Status](https://coveralls.io/repos/github/pinojs/pino/badge.svg?branch=master)](https://coveralls.io/github/pinojs/pino?branch=master) [![TypeScript definitions on DefinitelyTyped](http://definitelytyped.org/badges/standard.svg)](http://definitelytyped.org) [Extremely fast](#benchmarks) node.js logger, inspired by Bunyan. -It also includes a shell utility to pretty-print its log files. - -![cli](demo.png) * [Installation](#install) * [Usage](#usage) * [Benchmarks](#benchmarks) * [API ⇗](docs/API.md) -* [CLI ⇗](docs/cli.md) +* [Pretty Printing ⇗](docs/pretty.md) * [Extreme mode explained ⇗](docs/extreme.md) * [Pino Howtos ⇗](docs/howtos.md) * [Transports with Pino](#transports) @@ -78,6 +75,11 @@ This produces: ``` +If you have the [`pino-pretty`](https://github.com/pinojs/pino-pretty) module +installed then you can make these logs easier to read: + +![pretty demo](pretty-demo.png) + ## Benchmarks @@ -195,7 +197,7 @@ By default, in the browser, ### Browser Options Pino can be passed a `browser` object in the options object, -which can have the following properties: +which can have the following properties: #### `asObject` (Boolean) @@ -247,10 +249,10 @@ var pino = require('pino')({browser: {write: { The serializers provided to `pino` are ignored by default in the browser, including the standard serializers provided with Pino. Since the default destination for log -messages is the console, values such as `Error` objects are enhanced for inspection, +messages is the console, values such as `Error` objects are enhanced for inspection, which they otherwise wouldn't be if the Error serializer was enabled. -We can turn all serializers on, +We can turn all serializers on, ```js var pino = require('pino')({ @@ -274,7 +276,7 @@ var pino = require('pino')({ }) // following will apply myCustomSerializer to the custom property, // but will not apply anotherSerizlier to another key -pino.info({custom: 'a', another: 'b'}) +pino.info({custom: 'a', another: 'b'}) ``` When `serialize` is `true` the standard error serializer is also enabled (see https://github.com/pinojs/pino/blob/master/docs/API.md#stdSerializers). @@ -300,7 +302,7 @@ for how to set child-bound serializers). Unlike server pino the serializers apply to every object passed to the logger method, if the `asObject` option is `true`, this results in the serializers applying to the -first object (as in server pino). +first object (as in server pino). For more info on serializers see https://github.com/pinojs/pino/blob/master/docs/API.md#parameters. @@ -310,23 +312,23 @@ An object with `send` and `level` properties. The `transmit.level` property specifies the minimum level (inclusive) of when the `send` function should be called, if not supplied the `send` function be called based on the main logging `level` -(set via `options.level`, defaulting to `info`). +(set via `options.level`, defaulting to `info`). -The `transmit` object must have a `send` function which will be called after -writing the log message. The `send` function is passed the level of the log -message and a `logEvent` object. +The `transmit` object must have a `send` function which will be called after +writing the log message. The `send` function is passed the level of the log +message and a `logEvent` object. The `logEvent` object is a data structure representing a log message, it represents -the arguments passed to a logger statement, the level -at which they were logged and the heirarchy of child bindings. +the arguments passed to a logger statement, the level +at which they were logged and the heirarchy of child bindings. -The `logEvent` format is structured like so: +The `logEvent` format is structured like so: ```js -{ +{ ts = Number, - messages = Array, - bindings = Array, + messages = Array, + bindings = Array, level: { label = String, value = Number} } ``` @@ -337,21 +339,21 @@ logger method is called. The `messages` array is all arguments passed to logger method, (for instance `logger.info('a', 'b', 'c')` would result in `messages` array `['a', 'b', 'c']`). -The `bindings` array represents each child logger (if any), and the relevant bindings. -For instance given `logger.child({a: 1}).child({b: 2}).info({c: 3})`, the bindings array +The `bindings` array represents each child logger (if any), and the relevant bindings. +For instance given `logger.child({a: 1}).child({b: 2}).info({c: 3})`, the bindings array would hold `[{a: 1}, {b: 2}]` and the `messages` array would be `[{c: 3}]`. The `bindings` are ordered according to their position in the child logger heirarchy, with the lowest index being the top of the heirarchy. By default serializers are not applied to log output in the browser, but they will *always* be -applied to `messages` and `bindings` in the `logEvent` object. This allows us to ensure a consistent +applied to `messages` and `bindings` in the `logEvent` object. This allows us to ensure a consistent format for all values between server and client. -The `level` holds the label (for instance `info`), and the corresponding numerical value -(for instance `30`). This could be important in cases where client side level values and +The `level` holds the label (for instance `info`), and the corresponding numerical value +(for instance `30`). This could be important in cases where client side level values and labels differ from server side. -The point of the `send` function is to remotely record log messages: +The point of the `send` function is to remotely record log messages: ```js var pino = require('pino')({ @@ -367,7 +369,7 @@ var pino = require('pino')({ // numerical value if (logEvent.level.value >= 50) { // covers error and fatal - // send the logEvent somewhere + // send the logEvent somewhere } } } diff --git a/bin.js b/bin.js old mode 100755 new mode 100644 index 62a317999..939b117bc --- a/bin.js +++ b/bin.js @@ -1,59 +1,6 @@ -#! /usr/bin/env node - -'use strict' - -var pretty = require('./pretty') -var fs = require('fs') - -module.exports = pretty - -if (arg('-h') || arg('--help')) { - usage().pipe(process.stdout) -} else if (arg('-v') || arg('--version')) { - console.log(require('./package.json').version) -} else { - process.stdin.pipe(pretty({ - timeTransOnly: arg('-t'), - levelFirst: arg('-l'), - forceColor: arg('-c'), - messageKey: argWithParam('-m'), - dateFormat: argWithParam('--dateFormat'), - errorProps: paramToArray(argWithParam('--errorProps')), - errorLikeObjectKeys: paramToArray(argWithParam('--errorLikeObjectKeys')), - localTime: arg('--localTime') - })).pipe(process.stdout) - if (!process.stdin.isTTY && !fs.fstatSync(process.stdin.fd).isFile()) { - process.once('SIGINT', function noOp () {}) - } -} - -function usage () { - var help = require('path').join(__dirname, 'usage.txt') - return fs.createReadStream(help) -} - -function arg (s) { - return !!~process.argv.indexOf(s) -} - -function argWithParam (s) { - if (!arg(s)) { - return - } - var argIndex = process.argv.indexOf(s) + 1 - var argValue = process.argv.length > argIndex && - process.argv[argIndex] - - if (!argValue) { - throw new Error(s + ' flag provided without a string argument') - } - return argValue -} - -function paramToArray (param) { - if (!param) { - return - } - - return param.split(/\s?,\s?/) -} +#!/usr/bin/env node +console.error( + '`pino` cli has been removed. Use `pino-pretty` cli instead.\n' + + '\nSee: https://github.com/pinojs/pino-pretty' +) +process.exit(1) diff --git a/demo.png b/demo.png deleted file mode 100644 index 9a2663585..000000000 Binary files a/demo.png and /dev/null differ diff --git a/docs/API.md b/docs/API.md index 1b161daa1..24e0302d1 100644 --- a/docs/API.md +++ b/docs/API.md @@ -1,7 +1,6 @@ # Table of Contents + [pino](#constructor) -+ [pino.pretty](#pretty) + [Logger Instance](#logger) * [.pino](#version) * [.child](#child) @@ -73,8 +72,13 @@ * `levelVal` (integer): when defining a custom log level via `level`, set to an integer value to define the new level. Default: `undefined`. * `messageKey` (string): the string key for the 'message' in the JSON object. Default `msg`. - * `prettyPrint` (boolean|object): enables [pino.pretty](#pretty). This is intended for non-production - configurations. This may be set to a configuration object as outlined in [pino.pretty](#pretty). Default: `false`. + * `prettyPrint` (boolean|object): enables pretty printing log logs. This is intended for non-production + configurations. This may be set to a configuration object as outlined in the + [`pino-pretty` documentation](https://github.com/pinojs/pino-pretty). + The options object may additionally contain a `prettifier` property to define + which prettifier module to use. When not present, `prettifier` defaults to + `'pino-pretty'`. Regardless of the value, the specified prettifier module + must be installed as a separate dependency. Default: `false`. * `onTerminated` (function): this function will be invoked during process shutdown when `extreme` is set to `true`. The signature of the function is `onTerminated(eventName, err)`. If you do not specify a function, Pino will invoke `process.exit(0)` when no error has occurred, and `process.exit(1)` otherwise. If you do specify a function, @@ -108,49 +112,6 @@ var logger = pino({ ### Discussion: Returns a new [logger](#logger) instance. - -## .pretty([options]) - -### Parameters: -+ `options` (object): - * `timeTransOnly` (boolean): if set to `true`, it will only covert the unix - timestamp to ISO 8601 date format, and reserialize the JSON (equivalent to `pino -t`). - * `formatter` (function): a custom function to format the line. It's passed 2 arguments, - JSON object log data and an options object - that [exposes utility functions](https://github.com/pinojs/pino/blob/master/pretty.js#L110). - It should return a string value. - * `levelFirst` (boolean): if set to `true`, it will print the name of the log - level as the first field in the log line. Default: `false`. - * `messageKey` (string): the key in the JSON object to use as the highlighted - message. Default: `msg`. - * `forceColor` (boolean): if set to `true`, will add color information to the formatted output - message. Default: `false`. - * `crlf` (boolean): emit `\r\n` instead of `\n`. Default: `false`. - * `errorLikeObjectKeys` (array): error-like objects containing stack traces that should be prettified. Default: `['err', 'error']`. - -### Example: -```js -'use strict' - -var pino = require('pino') -var pretty = pino.pretty() -pretty.pipe(process.stdout) -var log = pino({ - name: 'app', - safe: true -}, pretty) - -log.child({ widget: 'foo' }).info('hello') -log.child({ widget: 'bar' }).warn('hello 2') -``` - -### Discussion: -Provides access to the [CLI](cli.md) log prettifier as an API. - -This can also be enabled via the [constructor](#constructor) by setting the -`prettyPrint` option to either `true` or a configuration object described -in this section. - # Logger diff --git a/docs/cli.md b/docs/cli.md deleted file mode 100644 index 1dafa8a63..000000000 --- a/docs/cli.md +++ /dev/null @@ -1,131 +0,0 @@ -# CLI - -Pino provides a command line interface that can be used to parse Pino log -lines into an easy to read format. - -To use the command line tool, we can install `pino` globally: - -```sh -npm install -g pino -``` - -The pretty-printed output will highlight the message value of the input JSON. By -default, Pino provides this message value at the `msg` key. A custom key can be -specified with `-m `. - -`pino -m fooMessage` will transform this: - -```js -{"pid":14139,"hostname":"MacBook-Pro-3.home","level":30,"fooMessage":"hello world","time":1457537229339,"v":1} -``` - -Into this: - -```sh -[2016-03-09T15:27:09.339Z] INFO (14139 on MacBook-Pro-3.home): hello world -``` - -There are also two transformer flags: - -+ `-t` that converts Epoch timestamps to ISO timestamps. - - ```sh - cat log | pino -t - ``` -+ `-l` that flips the time and level on the standard output. - - ```sh - cat log | pino -l - ``` - -`pino -t` will transform this: - -```js -{"pid":14139,"hostname":"MacBook-Pro-3.home","level":30,"msg":"hello world","time":1457537229339,"v":1} -``` - -Into this: - -```js -{"pid":14139,"hostname":"MacBook-Pro-3.home","level":30,"msg":"hello world","time":"2016-03-09T15:27:09.339Z","v":1} -``` - - -`pino -l` will transform this: - -```sh -[2016-03-09T15:27:09.339Z] INFO (14139 on MacBook-Pro-3.home): hello world -``` - -Into this: - -```sh -INFO [2016-03-09T15:27:09.339Z] (14139 on MacBook-Pro-3.home): hello world -``` -If you would like to enforce the output to be color encoded you can specify the `-c` flag -`cat log | pino -c` will transform this: - -```js -{"pid":14139,"hostname":"MacBook-Pro-3.home","level":30,"fooMessage":"hello world","time":1457537229339,"v":1} -``` - -Into this: - -```sh -[2017-04-25T17:32:09.662Z] INFO (24280 on SP2): hello world -``` - -If an instance of `Error` is logged, Pino adds `"type":"Error"` to the logged JSON. -Thus, when prettifying the output, Pino will transform the JSON: - -```js -{"level":50,"time":1457537229339,"msg":"Error message.","pid":44127,"hostname":"MacBook-Pro-3.home","type":"Error","stack":"Stack of the error","statusCode":500,"dataBaseSpecificError":{"errorType":"some database error type","erroMessage":"some database error message","evenMoreSpecificStuff":{"someErrorRelatedObject":"error"}},"v":1} -``` - -To: - -```sh -ERROR [2016-03-09T15:27:09.339Z] (44127 on MacBook-Pro-3.home): Error message. - Stack of the error -``` - -To log additional properties of `Error` objects, supply the `--errorProps ` flag. - -For example, `pino --errorProps statusCode` will transform: - -```js -{"level":50,"time":1457537229339,"msg":"Error message.","pid":44127,"hostname":"MacBook-Pro-3.home","type":"Error","stack":"Stack of the error","statusCode":500,"dataBaseSpecificError":{"errorType":"some database error type","erroMessage":"some database error message","evenMoreSpecificStuff":{"someErrorRelatedObject":"error"}},"v":1} -``` - -To: - -```sh -ERROR [2016-03-09T15:27:09.339Z] (44127 on MacBook-Pro-3.home): Error message. - Stack of the error -statusCode: 500 -``` - -In order to print all nested properties of `Error` objects, you can use `--errorProps` flag with `*` property. - -Note: you must quote or escape the `*` (asterisk) to avoid shell expansion. - -`pino --errorProps '*'` will transform: - -```js -{"level":50,"time":1457537229339,"msg":"Error message.","pid":44127,"hostname":"MacBook-Pro-3.home","type":"Error","stack":"Stack of the error","statusCode":500,"dataBaseSpecificError":{"errorType":"some database error type","erroMessage":"some database error message","evenMoreSpecificStuff":{"someErrorRelatedObject":"error"}},"v":1} -``` - -To: - -```sh -[2016-03-09T15:27:09.339Z] ERROR (44127 on MacBook-Pro-3.home): Error message. - Stack of the error -statusCode: 500 -dataBaseSpecificError: { - errorType: "some database error type" - erroMessage: "some database error message" - evenMoreSpecificStuff: { - "someErrorRelatedObject": "error" - } -} -``` diff --git a/docs/pretty.md b/docs/pretty.md new file mode 100644 index 000000000..6c165b73a --- /dev/null +++ b/docs/pretty.md @@ -0,0 +1,86 @@ +# Pretty Printing + +By default, Pino log lines are newline delimited JSON (NDJSON). This is perfect +for production usage and long term storage. It's not so great for development +environments. Thus, Pino logs can be prettified by using a Pino prettifier +module like [`pino-pretty`][pp]: + +```sh +$ cat app.log | pino-pretty +``` + +For almost all situations, this is the recommended way to prettify logs. The +programmatic API, described in the next section, is primarily for integration +purposes with other CLI based prettifiers. + +## Prettifier API + +Pino prettifier modules are extra modules that provide a CLI for parsing NDJSON +log lines piped via `stdin` and expose an API which conforms to the Pino +[metadata streams](API.md#metadata) API. + +The API requires modules provide a factory function which returns a prettifier +function. This prettifier function must accept either a string of NDJSON or +a Pino log object. A psuedo-example of such a prettifier is: + +```js +module.exports = function myPrettifier (options) { + // Deal with whatever options are supplied. + return function prettifier (inputData) { + let logObject + if (typeof inputData === 'string') { + const parsedData = someJsonParser(inputData) + logObject = (isPinoLog(parsedData)) ? parsedData : undefined + } else if (isObject(inputData) && isPinoLog(inputData)) { + logObject = inputData + } + if (!logObject) return inputData + // implement prettification + } + + function isObject (input) { + return Object.prototype.toString.apply(input) === '[object Object]' + } + + function isPinoLog (log) { + return log && (log.hasOwnProperty('v') && log.v === 1) + } +} +``` + +The reference implementation of such a module is the [`pino-pretty`][pp] module. +To learn more about creating your own prettifier module, learn from the +`pino-pretty` source code. + +### API Example + +> #### NOTE: +> For general usage, it is highly recommended that you pipe logs into +> the prettifier instead. Prettified logs are not easily parsed and cannot +> be easily investigated at a later date. + +1. Install a prettifier module as a separate dependency, e.g. `npm install --save pino-pretty`. +1. Instantiate the logger with pretty printing enabled: + ```js + const pino = require('pino') + const log = pino({ + prettyPrint: { + levelFirst: true + }, + prettifier: require('pino-pretty') + }) + ``` + Note: the default prettifier module is `pino-pretty`, so the preceeding + example could be: + ```js + const pino = require('pino') + const log = pino({ + prettyPrint: { + levelFirst: true + } + }) + ``` + See the [`pino-pretty` documentation][pp] for more information on the options + that can be passed via `prettyPrint`. + + [pp]: https://github.com/pinojs/pino-pretty diff --git a/lib/tools.js b/lib/tools.js index a14ac02cb..02e56642b 100644 --- a/lib/tools.js +++ b/lib/tools.js @@ -27,6 +27,41 @@ function applyOptions (self, opts) { self._setLevel(opts.level) } +function asMetaWrapper (pretty, dest) { + const parsed = Symbol('parsedChindings') + + if (!dest) { + dest = process.stdout + } else if (!dest.write) { + throw new Error('the destination must be writable') + } + + return { + [Symbol.for('needsMetadata')]: true, + lastLevel: 0, + lastMsg: null, + lastObj: null, + lastLogger: null, + write (chunk) { + var chindings = this.lastLogger[parsed] + + if (!chindings) { + chindings = JSON.parse('{"v":1' + this.lastLogger.chindings + '}') + this.lastLogger[parsed] = chindings + } + + const obj = Object.assign({ + level: this.lastLevel, + msg: this.lastMsg, + time: this.lastTime + }, chindings, this.lastObj) + + const formatted = pretty(obj) + dest.write(formatted) + } + } +} + function defineLevelsProperty (onObject) { Object.defineProperty(onObject, 'levels', { value: { @@ -98,6 +133,7 @@ module.exports = { noop: noop, copy: copy, applyOptions: applyOptions, + asMetaWrapper: asMetaWrapper, defineLevelsProperty: defineLevelsProperty, streamIsBlockable: streamIsBlockable, genLog: genLog diff --git a/package.json b/package.json index 420b5c6b0..086d67d6b 100644 --- a/package.json +++ b/package.json @@ -4,9 +4,6 @@ "description": "super fast, all natural json logger", "main": "pino.js", "browser": "./browser.js", - "bin": { - "pino": "./bin.js" - }, "files": [ "pino.js", "bin.js", @@ -32,6 +29,9 @@ "bench-grandchild": "node benchmarks/runbench grandchild", "bench-conception": "node benchmarks/runbench conception" }, + "bin": { + "pino": "./bin.js" + }, "precommit": "test", "repository": { "type": "git", @@ -64,9 +64,11 @@ "fresh-require": "^1.0.3", "log": "^1.4.0", "loglevel": "^1.6.1", + "pino-pretty": "^1.0.0", "pre-commit": "^1.2.2", "proxyquire": "^2.0.1", "snazzy": "^7.1.1", + "split2": "^2.2.0", "standard": "^11.0.1", "steed": "^1.1.3", "tap": "^11.1.3", @@ -76,13 +78,11 @@ "zuul": "^3.11.1" }, "dependencies": { - "chalk": "^2.3.2", "fast-json-parse": "^1.0.3", "fast-safe-stringify": "^1.2.3", "flatstr": "^1.0.5", "pino-std-serializers": "^2.0.0", "pump": "^3.0.0", - "quick-format-unescaped": "^1.1.2", - "split2": "^2.2.0" + "quick-format-unescaped": "^1.1.2" } } diff --git a/pino.js b/pino.js index 697b15f7e..75e76827d 100644 --- a/pino.js +++ b/pino.js @@ -6,9 +6,7 @@ var stringifySafe = require('fast-safe-stringify') var serializers = require('pino-std-serializers') var fs = require('fs') var util = require('util') -var pump = require('pump') var flatstr = require('flatstr') -var pretty = require('./pretty') var events = require('./lib/events') var levels = require('./lib/levels') var tools = require('./lib/tools') @@ -274,6 +272,18 @@ Object.defineProperty(pinoPrototype, 'isLevelEnabled', { value: isLevelEnabled }) +function getPrettyStream (opts, prettifier) { + if (prettifier && typeof prettifier === 'function') { + return tools.asMetaWrapper(prettifier(opts), process.stdout) + } + try { + var prettyFactory = require('pino-pretty') + return tools.asMetaWrapper(prettyFactory(opts), process.stdout) + } catch (e) { + throw Error('Missing `pino-pretty` module: `pino-pretty` must be installed separately') + } +} + function pino (opts, stream) { var iopts = opts var istream = stream @@ -288,10 +298,7 @@ function pino (opts, stream) { if (!isStdout && iopts.prettyPrint) throw Error('cannot enable pretty print when stream is not process.stdout') if (iopts.prettyPrint) { var prettyOpts = Object.assign({ messageKey: iopts.messageKey }, iopts.prettyPrint) - var pstream = pretty(prettyOpts) - pump(pstream, process.stdout, function (err) { - if (err) instance.emit('error', err) - }) + var pstream = getPrettyStream(prettyOpts, iopts.prettifier) istream = pstream } @@ -400,7 +407,6 @@ Object.defineProperty(module.exports.stdSerializers, 'wrapRespnonseSerializer', }) module.exports.stdTimeFunctions = Object.assign({}, time) -module.exports.pretty = pretty Object.defineProperty( module.exports, 'LOG_VERSION', diff --git a/pretty-demo.png b/pretty-demo.png new file mode 100644 index 000000000..d5f529247 Binary files /dev/null and b/pretty-demo.png differ diff --git a/pretty.js b/pretty.js deleted file mode 100755 index 6d8c2d8d8..000000000 --- a/pretty.js +++ /dev/null @@ -1,328 +0,0 @@ -'use strict' - -var split = require('split2') -var Parse = require('fast-json-parse') -var chalk = require('chalk') - -var levels = { - default: 'USERLVL', - 60: 'FATAL', - 50: 'ERROR', - 40: 'WARN', - 30: 'INFO', - 20: 'DEBUG', - 10: 'TRACE' -} - -var standardKeys = [ - 'pid', - 'hostname', - 'name', - 'level', - 'time', - 'v' -] - -var defaultErrorLikeObjectKeys = [ - 'err', - 'error' -] - -var defaultMessageKey = 'msg' - -function toTimezoneOffset (aMinTimeoffset) { - // +/- minute timeoffset - var tz = aMinTimeoffset || new Date().getTimezoneOffset() - var tmp = Math.abs(tz) - - var offset = _lpadzero(String(Math.floor(tmp / 60)), 2) + ':' + _lpadzero(String(tmp % 60), 2) - return tz > 0 ? '-' + offset : '+' + offset -} - -function _lpadzero (aTarget, aLength, aPadChar) { - var char = aPadChar || '0' - var targetStr = aTarget.toString() - var times = aLength - targetStr.length - var padding = '' - while ((times--) > 0) { - padding += char - } - return padding + targetStr -} - -function withSpaces (value, eol) { - var lines = value.split(/\r?\n/) - for (var i = 1; i < lines.length; i++) { - lines[i] = ' ' + lines[i] - } - return lines.join(eol) -} - -function filter (value, messageKey, eol, errorLikeObjectKeys, excludeStandardKeys) { - errorLikeObjectKeys = errorLikeObjectKeys || [] - - var keys = Object.keys(value) - var filteredKeys = [messageKey] - - if (excludeStandardKeys !== false) { - filteredKeys = filteredKeys.concat(standardKeys) - } - - var result = '' - - for (var i = 0; i < keys.length; i++) { - if (errorLikeObjectKeys.indexOf(keys[i]) !== -1) { - var arrayOfLines = (' ' + keys[i] + ': ' + withSpaces(JSON.stringify(value[keys[i]], null, 2), eol) + eol).split('\n') - - for (var j = 0; j < arrayOfLines.length; j++) { - if (j !== 0) { - result += '\n' - } - - var line = arrayOfLines[j] - - if (/^\s*"stack"/.test(line)) { - var matches = /^(\s*"stack":)\s*"(.*)",?$/.exec(line) - - if (matches) { - if (matches.length === 3) { - var indentSize = /^\s*/.exec(line)[0].length + 4 - var indentation = Array(indentSize + 1).join(' ') - - result += matches[1] + '\n' + indentation + - matches[2].replace(/\\n/g, '\n' + indentation) - } - } else { - result += line - } - } else { - result += line - } - } - } else if (filteredKeys.indexOf(keys[i]) < 0) { - result += ' ' + keys[i] + ': ' + withSpaces(JSON.stringify(value[keys[i]], null, 2), eol) + eol - } - } - - return result -} - -function isPinoLine (line) { - return line && (line.hasOwnProperty('v') && line.v === 1) -} - -function pretty (opts) { - var timeTransOnly = opts && opts.timeTransOnly - var formatter = opts && opts.formatter - var dateFormat = opts && opts.dateFormat - var errorProps = opts && opts.errorProps - var errorLikeObjectKeys = opts && opts.errorLikeObjectKeys - var localTime = opts && opts.localTime - var levelFirst = opts && opts.levelFirst - var messageKey = opts && opts.messageKey - var forceColor = opts && opts.forceColor - var eol = opts && opts.crlf ? '\r\n' : '\n' - - messageKey = messageKey || defaultMessageKey - errorLikeObjectKeys = errorLikeObjectKeys || defaultErrorLikeObjectKeys - - var stream = split(mapLine) - var ctx - var levelColors - - var pipe = stream.pipe - - stream.pipe = function (dest, opts) { - ctx = new chalk.constructor({ - enabled: !!((chalk.supportsColor && dest.isTTY) || forceColor) - }) - - if (forceColor && ctx.level === 0) { - ctx.level = 1 - } - - levelColors = { - default: ctx.white, - 60: ctx.bgRed, - 50: ctx.red, - 40: ctx.yellow, - 30: ctx.green, - 20: ctx.blue, - 10: ctx.grey - } - - return pipe.call(stream, dest, opts) - } - - return stream - - function mapLine (line) { - var parsed = new Parse(line) - var value = parsed.value - - if (parsed.err || !isPinoLine(value)) { - // pass through - return line + eol - } - - if (timeTransOnly) { - value.time = (localTime) - ? asLocalISODate(value.time, dateFormat) - : asISODate(value.time, dateFormat) - return JSON.stringify(value) + eol - } - - line = (levelFirst) - ? asColoredLevel(value) + ' ' + formatTime(value) - : formatTime(value, ' ') + asColoredLevel(value) - - if (formatter) { - return opts.formatter(value, { - prefix: line, - chalk: ctx, - withSpaces: withSpaces, - filter: filter, - formatTime: formatTime, - asColoredText: asColoredText, - asColoredLevel: asColoredLevel - }) + eol - } - - if (value.name || value.pid || value.hostname) { - line += ' (' - - if (value.name) { - line += value.name - } - - if (value.name && value.pid) { - line += '/' + value.pid - } else if (value.pid) { - line += value.pid - } - - if (value.hostname) { - line += ' on ' + value.hostname - } - - line += ')' - } - - line += ': ' - - if (value[messageKey]) { - line += ctx.cyan(value[messageKey]) - } - - line += eol - - if (value.type === 'Error') { - line += ' ' + withSpaces(value.stack, eol) + eol - - var propsForPrint - if (errorProps && errorProps.length > 0) { - // don't need print these props for 'Error' object - var excludedProps = standardKeys.concat([messageKey, 'type', 'stack']) - - if (errorProps[0] === '*') { - // print all value props excluding 'excludedProps' - propsForPrint = Object.keys(value).filter(function (prop) { - return excludedProps.indexOf(prop) < 0 - }) - } else { - // print props from 'errorProps' only - // but exclude 'excludedProps' - propsForPrint = errorProps.filter(function (prop) { - return excludedProps.indexOf(prop) < 0 - }) - } - - for (var i = 0; i < propsForPrint.length; i++) { - var key = propsForPrint[i] - - if (value.hasOwnProperty(key)) { - if (value[key] instanceof Object) { - // call 'filter' with 'excludeStandardKeys' = false - // because nested property might contain property from 'standardKeys' - line += key + ': {' + eol + filter(value[key], '', eol, errorLikeObjectKeys, false) + '}' + eol - } else { - line += key + ': ' + value[key] + eol - } - } - } - } - } else { - line += filter(value, messageKey, eol, errorLikeObjectKeys) - } - - return line - } - - function asISODate (time, dateFormat) { - if (dateFormat) { - return asLocalISODate(time, dateFormat, 0) - } else { - return new Date(time).toISOString() - } - } - - function asLocalISODate (aTime, aFormat, aMinuteTZ) { - var time = aTime - var format = aFormat || 'YYYY-MM-DDThh:mm:ss.SSSTZ' - var date = new Date(time) - // make independent of the system timezone - var tzOffset = (aMinuteTZ === undefined) - ? date.getTimezoneOffset() - : aMinuteTZ - date.setUTCMinutes(date.getUTCMinutes() - tzOffset) - var year = format.indexOf('YYYY') > -1 - ? date.getUTCFullYear() - : date.getUTCFullYear().toString().slice(2, 4) - var month = _lpadzero(date.getUTCMonth() + 1, 2) - var day = _lpadzero(date.getUTCDate(), 2) - var hour = _lpadzero(date.getUTCHours(), 2) - var minute = _lpadzero(date.getUTCMinutes(), 2) - var second = _lpadzero(date.getUTCSeconds(), 2) - var milli = _lpadzero(date.getUTCMilliseconds(), 3) - date.setUTCMinutes(date.getUTCMinutes() + tzOffset) - - return format - .replace(/Y{1,4}/g, year) - .replace(/MM/g, month) - .replace(/DD/g, day) - .replace(/hh/g, hour) - .replace(/mm/g, minute) - .replace(/ss/g, second) - .replace(/SSS/g, milli) - .replace(/TZ/g, toTimezoneOffset(tzOffset)) - } - - function formatTime (value, after) { - after = after || '' - try { - if (!value || !value.time) { - return '' - } else { - return '[' + ((localTime) - ? asLocalISODate(value.time, dateFormat) - : asISODate(value.time, dateFormat)) + ']' + after - } - } catch (_) { - return '' - } - } - - function asColoredLevel (value) { - return asColoredText(value, levelColors.hasOwnProperty(value.level) ? levels[value.level] : levels.default) - } - - function asColoredText (value, text) { - if (levelColors.hasOwnProperty(value.level)) { - return levelColors[value.level](text) - } else { - return levelColors.default(text) - } - } -} - -module.exports = pretty diff --git a/test/crlf.test.js b/test/crlf.test.js index e86a6cd91..735edd03d 100644 --- a/test/crlf.test.js +++ b/test/crlf.test.js @@ -2,7 +2,6 @@ var test = require('tap').test var pino = require('../') -var pretty = require('../pretty') var writer = require('flush-write-stream') function capture () { @@ -35,23 +34,3 @@ test('pino can log CRLF', function (t) { t.ok(/foo[^\n]+\r\n[^\n]+bar[^\n]+\r\n/.test(stream.data)) t.end() }) - -test('pretty can log CRLF', function (t) { - t.plan(1) - var prettier = pretty({ - crlf: true, - formatter: function (data) { - return data.msg - } - }) - - var stream = capture() - prettier.pipe(stream) - - var logger = pino(prettier) - logger.info('foo') - logger.info('bar') - - t.is(stream.data, 'foo\r\nbar\r\n') - t.end() -}) diff --git a/test/fixtures/pretty/prettyFactory.js b/test/fixtures/pretty/prettyFactory.js new file mode 100644 index 000000000..854e1efda --- /dev/null +++ b/test/fixtures/pretty/prettyFactory.js @@ -0,0 +1,6 @@ +global.process = { __proto__: process, pid: 123456 } +Date.now = function () { return 1459875739796 } +require('os').hostname = function () { return 'abcdefghijklmnopqr' } +var pino = require(require.resolve('./../../../')) +var log = pino({prettyPrint: {levelFirst: true}, prettifier: require('pino-pretty')}) +log.info('h') diff --git a/test/pretty.test.js b/test/pretty.test.js index 2933161e6..4e500db4a 100644 --- a/test/pretty.test.js +++ b/test/pretty.test.js @@ -2,398 +2,9 @@ var test = require('tap').test var pino = require('../') -var pretty = require('../pretty') -var os = require('os') var path = require('path') var writeStream = require('flush-write-stream') var fork = require('child_process').fork -var split = require('split2') -var hostname = os.hostname() -var serializers = require('pino-std-serializers') - -test('pino transform prettifies', function (t) { - t.plan(4) - var prettier = pretty() - prettier.pipe(split(function (line) { - t.ok(line.match(/.*hello world$/), 'end of line matches') - t.ok(line.match(/(?!^)INFO.*/), 'includes level') - t.ok(line.indexOf('' + process.pid) > 0, 'includes pid') - t.ok(line.indexOf('' + hostname) > 0, 'includes hostname') - return line - })) - var instance = pino(prettier) - - instance.info('hello world') -}) - -test('pino pretty moves level to start on flag', function (t) { - t.plan(4) - var prettier = pretty({ levelFirst: true }) - prettier.pipe(split(function (line) { - t.ok(line.match(/.*hello world$/), 'end of line matches') - t.ok(line.match(/^INFO.*/), 'level is at start of line') - t.ok(line.indexOf('' + process.pid) > 0, 'includes pid') - t.ok(line.indexOf('' + hostname) > 0, 'includes hostname') - return line - })) - var instance = pino(prettier) - - instance.info('hello world') -}) - -test('pino pretty force color on flag', function (t) { - t.plan(1) - var prettier = pretty({ forceColor: true }) - prettier.pipe(split(function (line) { - t.ok(line.match(/.*\u001b\[32mINFO\u001b\[39m.*\u001b\[36mhello world\u001b\[39m$/), 'color coding information is encoded in the line') - return line - })) - var instance = pino(prettier) - - instance.info('hello world') -}) - -test('pino transform can just parse the dates', function (t) { - t.plan(1) - var prettier = pretty({ timeTransOnly: true }) - prettier.pipe(split(function (line) { - var obj = JSON.parse(line) - t.ok(typeof obj.time === 'string', 'time is a string') - return line - })) - var instance = pino(prettier) - - instance.info('hello world') -}) - -test('pino transform can format with a custom function', function (t) { - t.plan(8) - var prettier = pretty({ formatter: function (line, opts) { - t.ok(opts.prefix.indexOf('INFO') > -1, 'prefix contains level') - t.ok(typeof opts.chalk.white === 'function', 'chalk instance') - t.ok(typeof opts.withSpaces === 'function', 'withSpaces function') - t.ok(typeof opts.filter === 'function', 'filter function') - t.ok(typeof opts.formatTime === 'function', 'formatTime function') - t.ok(typeof opts.asColoredText === 'function', 'asColoredText function') - t.ok(typeof opts.asColoredLevel === 'function', 'asColoredLevel function') - return 'msg: ' + line.msg + ', foo: ' + line.foo - } }) - prettier.pipe(split(function (line) { - t.ok(line === 'msg: hello world, foo: bar', 'line matches') - return line - })) - var instance = pino(prettier) - - instance.info({foo: 'bar'}, 'hello world') -}) - -test('pino transform prettifies Error', function (t) { - var prettier = pretty() - var err = new Error('hello world') - var expected = err.stack.split('\n') - expected.unshift(err.message) - - t.plan(expected.length) - - prettier.pipe(split(function (line) { - t.ok(line.indexOf(expected.shift()) >= 0, 'line matches') - return line - })) - - var instance = pino(prettier) - - instance.info(err) -}) - -function getIndentLevel (str) { - return (/^\s*/.exec(str) || [''])[0].length -} - -test('pino transform prettifies Error in property within errorLikeObjectKeys', function (t) { - var prettier = pretty({ - errorLikeObjectKeys: ['err'] - }) - - var err = new Error('hello world') - var expectedTraces = err.stack.split('\n').slice(1) - - t.plan(expectedTraces.length * 2) - - var i = 0 - var currentTrace = '' - var currentStack = '' - - prettier.pipe(split(function (line) { - if (/^\s*"stack"/.test(line)) { - currentStack = line - } - - if (/^\s*at/.test(line)) { - currentTrace = expectedTraces.shift() - - t.ok(line.indexOf(currentTrace) >= 0, `${i} line matches`) - t.ok(getIndentLevel(line) > getIndentLevel(currentStack), `${i} proper indentation`) - } - i++ - return line - })) - - var instance = pino({ serializers: { err: serializers.err } }, prettier) - - instance.info({ err }) -}) - -test('pino transform prettifies Error in property within errorLikeObjectKeys when stack is not the last property', function (t) { - var prettier = pretty({ - errorLikeObjectKeys: ['err'] - }) - - var err = new Error('hello world') - err.anotherField = 'dummy value' - - var expectedTraces = err.stack.split('\n').slice(1) - - t.plan(expectedTraces.length * 2) - - var i = 0 - var currentTrace = '' - var currentStack = '' - - prettier.pipe(split(function (line) { - if (/^\s*"stack"/.test(line)) { - currentStack = line - } - - if (/^\s*at/.test(line)) { - currentTrace = expectedTraces.shift() - - t.ok(line.indexOf(currentTrace) >= 0, `${i} line matches`) - t.ok(getIndentLevel(line) > getIndentLevel(currentStack), `${i} proper indentation`) - } - i++ - return line - })) - - var instance = pino({ serializers: { err: serializers.err } }, prettier) - - instance.info({ err }) -}) - -test('pino transform preserve output if not valid JSON', function (t) { - t.plan(1) - var prettier = pretty() - var lines = [] - prettier.pipe(split(function (line) { - lines.push(line) - return line - })) - - prettier.write('this is not json\nit\'s just regular output\n') - prettier.end() - - t.deepEqual(lines, ['this is not json', 'it\'s just regular output'], 'preserved lines') -}) - -test('handles missing time', function (t) { - t.plan(1) - var prettier = pretty() - var lines = [] - prettier.pipe(split(function (line) { - lines.push(line) - return line - })) - - prettier.write('{"hello":"world"}') - prettier.end() - - t.deepEqual(lines, ['{"hello":"world"}'], 'preserved lines') -}) - -test('handles missing pid, hostname and name', function (t) { - t.plan(1) - - var prettier = pretty() - prettier.pipe(split(function (line) { - t.ok(line.match(/\[.*\] INFO: hello world/), 'line does not match') - - return line - })) - - var instance = pino({ base: null }, prettier) - - instance.info('hello world') -}) - -test('handles missing pid', function (t) { - t.plan(1) - - var name = 'test' - var msg = 'hello world' - var regex = new RegExp('\\[.*\\] INFO \\(' + name + ' on ' + hostname + '\\): ' + msg) - - var prettier = pretty() - prettier.pipe(split(function (line) { - t.ok(regex.test(line), 'line does not match') - - return line - })) - - var opts = { - base: { - name: name, - hostname: hostname - } - } - var instance = pino(opts, prettier) - - instance.info(msg) -}) - -test('handles missing hostname', function (t) { - t.plan(1) - - var name = 'test' - var msg = 'hello world' - var regex = new RegExp('\\[.*\\] INFO \\(' + name + '/' + process.pid + '\\): ' + msg) - - var prettier = pretty() - prettier.pipe(split(function (line) { - t.ok(regex.test(line), 'line does not match') - - return line - })) - - var opts = { - base: { - name: name, - pid: process.pid - } - } - var instance = pino(opts, prettier) - - instance.info(msg) -}) - -test('handles missing name', function (t) { - t.plan(1) - - var msg = 'hello world' - var regex = new RegExp('\\[.*\\] INFO \\(' + process.pid + ' on ' + hostname + '\\): ' + msg) - - var prettier = pretty() - prettier.pipe(split(function (line) { - t.ok(regex.test(line), 'line does not match') - - return line - })) - - var opts = { - base: { - hostname: hostname, - pid: process.pid - } - } - var instance = pino(opts, prettier) - - instance.info(msg) -}) - -test('pino transform prettifies properties', function (t) { - t.plan(1) - var prettier = pretty() - var first = true - prettier.pipe(split(function (line) { - if (first) { - first = false - } else { - t.equal(line, ' a: "b"', 'prettifies the line') - } - return line - })) - var instance = pino(prettier) - - instance.info({ a: 'b' }, 'hello world') -}) - -test('pino transform prettifies nested properties', function (t) { - t.plan(5) - var expectedLines = [ - undefined, - ' a: {', - ' "b": {', - ' "c": "d"', - ' }', - ' }' - ] - var prettier = pretty() - prettier.pipe(split(function (line) { - var expectedLine = expectedLines.shift() - if (expectedLine !== undefined) { - t.equal(line, expectedLine, 'prettifies the line') - } - })) - var instance = pino(prettier) - instance.info({ a: { b: { c: 'd' } } }, 'hello world') -}) - -test('pino transform treats the name with care', function (t) { - t.plan(1) - var prettier = pretty() - prettier.pipe(split(function (line) { - t.ok(line.match(/\(matteo\/.*$/), 'includes the name') - return line - })) - var instance = pino({ name: 'matteo' }, prettier) - - instance.info('hello world') -}) - -test('handles `null` input', function (t) { - t.plan(1) - var prettier = pretty() - prettier.pipe(split(function (line) { - t.is(line, 'null') - return line - })) - prettier.write('null') - prettier.end() -}) - -test('handles `undefined` input', function (t) { - t.plan(1) - var prettier = pretty() - prettier.pipe(split(function (line) { - t.is(line, 'undefined') - return line - })) - prettier.write('undefined') - prettier.end() -}) - -test('handles `true` input', function (t) { - t.plan(1) - var prettier = pretty() - prettier.pipe(split(function (line) { - t.is(line, 'true') - return line - })) - prettier.write('true') - prettier.end() -}) - -test('accept customLogLevel', function (t) { - t.plan(1) - var prettier = pretty() - - prettier.pipe(split(function (line) { - t.ok(line.indexOf('USERLVL') > 0, 'include custom level') - return line - })) - - var instance = pino({level: 'testCustom', levelVal: 35}, prettier) - - instance.testCustom('test message') -}) test('can be enabled via constructor', function (t) { t.plan(1) @@ -425,22 +36,19 @@ test('can be enabled via constructor with pretty configuration', function (t) { }) }) -test('works without time', function (t) { - t.plan(4) - var prettier = pretty() - prettier.pipe(split(function (line) { - t.ok(line.match(/.*hello world$/), 'end of line matches') - t.ok(line.match(/^INFO.*/), 'includes level') - t.ok(line.indexOf('' + process.pid) > 0, 'includes pid') - t.ok(line.indexOf('' + hostname) > 0, 'includes hostname') - return line - })) +test('can be enabled via constructor with prettifier', function (t) { + t.plan(1) + var actual = '' + var child = fork(path.join(__dirname, 'fixtures', 'pretty', 'prettyFactory.js'), {silent: true}) - var instance = pino({ - timestamp: null - }, prettier) + child.stdout.pipe(writeStream(function (s, enc, cb) { + actual += s + cb() + })) - instance.info('hello world') + child.on('close', function () { + t.notEqual(actual.match(/^INFO.*h/), null) + }) }) test('throws error when enabled with stream specified', function (t) { @@ -456,139 +64,3 @@ test('does not throw error when enabled with stream specified', function (t) { pino({prettyPrint: true}, process.stdout) t.end() }) - -test('pino pretty localTime flag', function (t) { - t.plan(6) - var prettier = pretty({ localTime: true }) - prettier.pipe(split(function (line) { - var localTime = line.slice(line.indexOf('[') + 1, line.indexOf(']')) - var msgTime = line.slice(line.indexOf('>') + 1, line.indexOf('<')) - t.ok(line.match(/.*hello world$/), 'end of line matches') - t.ok(line.match(/(?!^)INFO.*/), 'includes level') - t.ok(line.indexOf('' + process.pid) > 0, 'includes pid') - t.ok(line.indexOf('' + hostname) > 0, 'includes hostname') - t.ok(Date.parse(localTime) > parseInt(msgTime, 10) - 2000, 'local iso time <-> Epoch timestamps match') - t.ok(Date.parse(localTime) < parseInt(msgTime, 10) + 2000, 'local iso time <-> Epoch timestamps match') - return line - })) - var instance = pino(prettier) - - instance.info('>' + Date.now() + '< hello world') -}) - -test('pino pretty dateFormat flag', function (t) { - t.plan(6) - var prettier = pretty({ dateFormat: 'YYYY/MM/DDThh,mm,ss_SSSZ' }) - prettier.pipe(split(function (line) { - var formatDate = line.slice(line.indexOf('[') + 1, line.indexOf(']')) - var msgTime = line.slice(line.indexOf('>') + 1, line.indexOf('<')) - var toISODate = formatDate.replace(/\//g, '-').replace(/,/g, ':').replace(/_/g, '.') - t.ok(line.match(/.*hello world$/), 'end of line matches') - t.ok(line.match(/(?!^)INFO.*/), 'includes level') - t.ok(line.indexOf('' + process.pid) > 0, 'includes pid') - t.ok(line.indexOf('' + hostname) > 0, 'includes hostname') - t.ok(Date.parse(toISODate) > parseInt(msgTime, 10) - 2000, 'custDateFormat <-> Epoch timestamps match') - t.ok(Date.parse(toISODate) < parseInt(msgTime, 10) + 2000, 'custDateFormat <-> Epoch timestamps match') - return line - })) - var instance = pino(prettier) - - instance.info('>' + Date.now() + '< hello world') -}) - -test('pino pretty errorProps flag with certain props', function (t) { - t.plan(3) - var prettier = pretty({ errorProps: ['statusCode', 'originalStack'] }) - - var expectedLines = [ - undefined, - ' error stack', - 'statusCode: 500', - 'originalStack: original stack' - ] - - prettier.pipe(split(function (line) { - var expectedLine = expectedLines.shift() - if (expectedLine !== undefined) { - t.equal(line, expectedLine, 'prettifies the line') - } - })) - - var instance = pino(prettier) - - var error = new Error('error message') - error.stack = 'error stack' - error.statusCode = 500 - error.originalStack = 'original stack' - - instance.error(error) -}) - -test('pino pretty errorProps flag with "*" (print all nested props)', function (t) { - t.plan(9) - var prettier = pretty({ errorProps: ['*'] }) - - var expectedLines = [ - undefined, - ' error stack', - 'statusCode: 500', - 'originalStack: original stack', - 'dataBaseSpecificError: {', - ' erroMessage: "some database error message"', - ' evenMoreSpecificStuff: {', - ' "someErrorRelatedObject": "error"', - ' }', - '}' - ] - - prettier.pipe(split(function (line) { - var expectedLine = expectedLines.shift() - if (expectedLine !== undefined) { - t.equal(line, expectedLine, 'prettifies the line') - } - })) - - var instance = pino(prettier) - - var error = new Error('error message') - error.stack = 'error stack' - error.statusCode = 500 - error.originalStack = 'original stack' - error.dataBaseSpecificError = { - erroMessage: 'some database error message', - evenMoreSpecificStuff: { - someErrorRelatedObject: 'error' - } - } - - instance.error(error) -}) - -test('pino pretty handles errors with a null stack', function (t) { - t.plan(6) - var prettier = pretty() - - var expectedLines = [ - undefined, - ' message: "foo"', - ' stack: null', - undefined, - ' error: {', - ' "message": "foo",', - ' "stack": null', - ' }' - ] - - prettier.pipe(split(function (line) { - var expectedLine = expectedLines.shift() - if (expectedLine !== undefined) { - t.equal(line, expectedLine, 'prettifies the line') - } - })) - - var instance = pino(prettier) - const error = {message: 'foo', stack: null} - const objectWithError = {error: error} - instance.error(error) - instance.error(objectWithError) -}) diff --git a/usage.txt b/usage.txt deleted file mode 100644 index bb2efafb0..000000000 --- a/usage.txt +++ /dev/null @@ -1,26 +0,0 @@ - - Pino - - To prettify logs, simply pipe a log file through pino: - - cat log | pino - - To highlight a string at a key other than 'msg', use -m : - - cat log | pino -m fooMessage - - To convert Epoch timestamps to ISO timestamps use the -t flag - - cat log | pino -t - - To flip level and time/date in standard output use the -l flag - - cat log | pino -l - - Flags - -h | --help Display Help - -v | --version Display Version - -m Highlight the message at the property - -t Convert Epoch timestamps to ISO - -l Flip level and date -