diff --git a/.gitignore b/.gitignore index e920c1671..4cfea1c3c 100644 --- a/.gitignore +++ b/.gitignore @@ -31,3 +31,7 @@ node_modules # Optional REPL history .node_repl_history + +# 0x +.__browserify_string_empty.js +profile-* diff --git a/README.md b/README.md index c1181789d..bc9d4c2fb 100644 --- a/README.md +++ b/README.md @@ -114,6 +114,7 @@ Into this: ## API * pino() + * logger.child() * logger.level * logger.fatal() * logger.error() @@ -153,6 +154,25 @@ var instance = pino({ } ``` + +### logger.child(bindings) + +Creates a child logger, setting all key-value pairs in `bindings` as +properties in the log lines. All serializers will be applied to the +given pair. + +Example: + +```js +logger.child({ a: 'property' }).info('hello child!') +// generates +// {"pid":46497,"hostname":"MacBook-Pro-di-Matteo.local","level":30,"msg":"hello child!","time":1458124707120,"v":0,"a":"property"} +``` + +It leverage the output stream of the parent and +its log level. These settings are immutable and pulled out during the +instantiation of the child logger. + ### logger.level diff --git a/benchmarks/basic.js b/benchmarks/basic.js new file mode 100644 index 000000000..762c7d5aa --- /dev/null +++ b/benchmarks/basic.js @@ -0,0 +1,55 @@ +'use strict' + +var bench = require('fastbench') +var pino = require('../') +var bunyan = require('bunyan') +var bole = require('bole')('bench') +var winston = require('winston') +var fs = require('fs') +var dest = fs.createWriteStream('/dev/null') +var plog = pino(dest) +var max = 10 +var blog = bunyan.createLogger({ + name: 'myapp', + streams: [{ + level: 'trace', + stream: dest + }] +}) + +require('bole').output({ + level: 'info', + stream: dest +}) + +winston.add(winston.transports.File, { filename: '/dev/null' }) +winston.remove(winston.transports.Console) + +var run = bench([ + function benchBunyan (cb) { + for (var i = 0; i < max; i++) { + blog.info('hello world') + } + setImmediate(cb) + }, + function benchWinston (cb) { + for (var i = 0; i < max; i++) { + winston.info('hello world') + } + setImmediate(cb) + }, + function benchBole (cb) { + for (var i = 0; i < max; i++) { + bole.info('hello world') + } + setImmediate(cb) + }, + function benchPino (cb) { + for (var i = 0; i < max; i++) { + plog.info('hello world') + } + setImmediate(cb) + } +], 10000) + +run(run) diff --git a/benchmarks/child.js b/benchmarks/child.js new file mode 100644 index 000000000..f4176cdba --- /dev/null +++ b/benchmarks/child.js @@ -0,0 +1,45 @@ +'use strict' + +var bench = require('fastbench') +var pino = require('../') +var bunyan = require('bunyan') +var bole = require('bole')('bench')('child') +var fs = require('fs') +var dest = fs.createWriteStream('/dev/null') +var plog = pino(dest).child({ a: 'property' }) +var max = 10 +var blog = bunyan.createLogger({ + name: 'myapp', + streams: [{ + level: 'trace', + stream: dest + }] +}).child({ a: 'property' }) + +require('bole').output({ + level: 'info', + stream: dest +}) + +var run = bench([ + function benchBunyanObj (cb) { + for (var i = 0; i < max; i++) { + blog.info({ hello: 'world' }) + } + setImmediate(cb) + }, + function benchPinoChild (cb) { + for (var i = 0; i < max; i++) { + plog.info({ hello: 'world' }) + } + setImmediate(cb) + }, + function benchBoleChild (cb) { + for (var i = 0; i < max; i++) { + bole.info({ hello: 'world' }) + } + setImmediate(cb) + } +], 10000) + +run(run) diff --git a/benchmarks/childCreation.js b/benchmarks/childCreation.js new file mode 100644 index 000000000..1ca85affa --- /dev/null +++ b/benchmarks/childCreation.js @@ -0,0 +1,48 @@ +'use strict' + +var bench = require('fastbench') +var pino = require('../') +var bunyan = require('bunyan') +var bole = require('bole')('bench') +var fs = require('fs') +var dest = fs.createWriteStream('/dev/null') +var plog = pino(dest) +var max = 10 +var blog = bunyan.createLogger({ + name: 'myapp', + streams: [{ + level: 'trace', + stream: dest + }] +}) + +require('bole').output({ + level: 'info', + stream: dest +}) + +var run = bench([ + function benchPinoCreation (cb) { + var child = plog.child({ a: 'property' }) + for (var i = 0; i < max; i++) { + child.info({ hello: 'world' }) + } + setImmediate(cb) + }, + function benchBunyanCreation (cb) { + var child = blog.child({ a: 'property' }) + for (var i = 0; i < max; i++) { + child.info({ hello: 'world' }) + } + setImmediate(cb) + }, + function benchBoleCreation (cb) { + var child = bole('child') + for (var i = 0; i < max; i++) { + child.info({ hello: 'world' }) + } + setImmediate(cb) + } +], 10000) + +run(run) diff --git a/benchmark.js b/benchmarks/object.js similarity index 67% rename from benchmark.js rename to benchmarks/object.js index 60722f722..166355622 100644 --- a/benchmark.js +++ b/benchmarks/object.js @@ -1,7 +1,7 @@ 'use strict' var bench = require('fastbench') -var pino = require('./') +var pino = require('../') var bunyan = require('bunyan') var bole = require('bole')('bench') var winston = require('winston') @@ -26,30 +26,6 @@ winston.add(winston.transports.File, { filename: '/dev/null' }) winston.remove(winston.transports.Console) var run = bench([ - function benchBunyan (cb) { - for (var i = 0; i < max; i++) { - blog.info('hello world') - } - setImmediate(cb) - }, - function benchWinston (cb) { - for (var i = 0; i < max; i++) { - winston.info('hello world') - } - setImmediate(cb) - }, - function benchBole (cb) { - for (var i = 0; i < max; i++) { - bole.info('hello world') - } - setImmediate(cb) - }, - function benchPino (cb) { - for (var i = 0; i < max; i++) { - plog.info('hello world') - } - setImmediate(cb) - }, function benchBunyanObj (cb) { for (var i = 0; i < max; i++) { blog.info({ hello: 'world' }) diff --git a/example.js b/example.js index a0f805bc0..000db35be 100644 --- a/example.js +++ b/example.js @@ -12,3 +12,5 @@ info({ obj: 42, b: 2 }, 'hello world') info({ obj: { aa: 'bbb' } }, 'another') setImmediate(info, 'after setImmediate') error(new Error('an error')) + +pino.child({ a: 'property' }).info('hello child!') diff --git a/pino.js b/pino.js index 2a51fad32..f46b8ffbe 100644 --- a/pino.js +++ b/pino.js @@ -25,7 +25,7 @@ function pino (opts, stream) { var slowtime = opts.slowtime var stringify = opts.safe !== false ? stringifySafe : JSON.stringify var name = opts.name - var level + var level = opts.level var funcs = {} var result = { fatal: null, @@ -36,33 +36,24 @@ function pino (opts, stream) { trace: null } var serializers = opts.serializers || {} + var end = '}\n' for (var key in levels) { funcs[key] = genLogFunction(key) } - Object.defineProperty(result, 'level', { - enumerable: false, - get: function () { - return level - }, - set: function (l) { - level = levels[l] - if (!level) { - throw new Error('unknown level ' + l) + if (opts.meta) { + end = ',' + opts.meta + end + Object.keys(levels).forEach(function (key) { + if (level <= levels[key]) { + result[key] = funcs[key] + } else { + result[key] = noop } - - Object.keys(levels).forEach(function (key) { - if (level <= levels[key]) { - result[key] = funcs[key] - } else { - result[key] = noop - } - }) - } - }) - - result.level = opts.level || 'info' + }) + } else { + setup(result, funcs, level, stream, opts, serializers, stringify) + } return result @@ -113,7 +104,7 @@ function pino (opts, stream) { } } } - return data + '}\n' + return data + end } // returns string json with final brace omitted @@ -129,6 +120,59 @@ function pino (opts, stream) { } } +function setup (result, funcs, level, stream, opts, serializers, stringify) { + var safe = opts.safe + + Object.defineProperty(result, 'level', { + enumerable: false, + get: function () { + return level + }, + set: function (l) { + level = levels[l] + if (!level) { + throw new Error('unknown level ' + l) + } + + Object.keys(levels).forEach(function (key) { + if (level <= levels[key]) { + result[key] = funcs[key] + } else { + result[key] = noop + } + }) + } + }) + + result.level = opts.level || 'info' + result.child = child + + function child (bindings) { + if (!opts) { + throw new Error('missing bindings for child logger') + } + + var data = '' + var value + for (var key in bindings) { + value = bindings[key] + if (bindings.hasOwnProperty(key) && value !== undefined) { + value = serializers[key] ? serializers[key](value) : value + data += '"' + key + '":' + stringify(value) + } + } + + var toPino = { + safe: safe, + meta: data, + level: level, + serializers: serializers + } + + return pino(toPino, stream) + } +} + function noop () {} function mapHttpRequest (req) { diff --git a/test.js b/test.js index 5f29c787c..5d856f39d 100644 --- a/test.js +++ b/test.js @@ -106,6 +106,28 @@ function levelTest (name, level) { instance.level = name instance[name](err) }) + + test('child logger for level ' + name, function (t) { + t.plan(2) + var instance = pino(sink(function (chunk, enc, cb) { + t.ok(new Date(chunk.time) <= new Date(), 'time is greater than Date.now()') + delete chunk.time + t.deepEqual(chunk, { + pid: pid, + hostname: hostname, + level: level, + msg: 'hello world', + hello: 'world', + v: 0 + }) + })) + + instance.level = name + var child = instance.child({ + hello: 'world' + }) + child[name]('hello world') + }) } levelTest('fatal', 60) @@ -415,3 +437,46 @@ test('slowtime', function (t) { instance.info('hello world') }) + +test('http request support via serializer in a child', function (t) { + t.plan(3) + + var originalReq + var instance = pino({ + serializers: { + req: pino.stdSerializers.req + } + }, sink(function (chunk, enc, cb) { + t.ok(new Date(chunk.time) <= new Date(), 'time is greater than Date.now()') + delete chunk.time + t.deepEqual(chunk, { + pid: pid, + hostname: hostname, + level: 30, + msg: 'my request', + v: 0, + req: { + method: originalReq.method, + url: originalReq.url, + headers: originalReq.headers, + remoteAddress: originalReq.connection.remoteAddress, + remotePort: originalReq.connection.remotePort + } + }) + cb() + })) + + var server = http.createServer(function (req, res) { + originalReq = req + var child = instance.child({ req: req }) + child.info('my request') + res.end('hello') + }).listen(function (err) { + t.error(err) + t.teardown(server.close.bind(server)) + + http.get('http://localhost:' + server.address().port, function (res) { + res.resume() + }) + }) +})