diff --git a/docs/guides/8to9guide.md b/docs/guides/8to9guide.md index ef8e2505c..0893bf9c5 100644 --- a/docs/guides/8to9guide.md +++ b/docs/guides/8to9guide.md @@ -5,7 +5,7 @@ permalink: /docs/8to9/ ## Introduction -restify `9.x` comes with `async/await` support! +Restify `9.x` comes with `async/await` support, `pino` and more! ## Breaking Changes @@ -94,3 +94,18 @@ server.use(async (req, res, next) => { }); }); ```` + +### Remove `RequestCaptureStream` + +Removes `RequestCaptureStream` from Restify core. + +### Use `Pino` as default logger (removes dependency on `Bunyan`) + +[Pino](https://github.com/pinojs/pino) is well maintained, performance-focused, +compatible API. It does have a few key differences from `Bunyan`: + +- As a performance optimization, it stores bindings a single serialized `string`, +while `Bunyan` stores them as object keys; +- It uses a `setter` to set the log level, `Bunyan` uses a method; +- It only accepts one stream. If you need the multi-stream functionality, you +must use [pino-multistream](https://github.com/pinojs/pino-multi-stream). diff --git a/docs/guides/client.md b/docs/guides/client.md index e8b16b29c..6b6f6d937 100644 --- a/docs/guides/client.md +++ b/docs/guides/client.md @@ -120,7 +120,7 @@ Options: |dtrace|Object|node-dtrace-provider handle| |gzip|Object|Will compress data when sent using `content-encoding: gzip`| |headers|Object|HTTP headers to set in all requests| -|log|Object|[bunyan](https://github.com/trentm/node-bunyan) instance| +|log|Object|[pino](https://github.com/pinojs/pino) instance| |retry|Object|options to provide to node-retry;"false" disables retry; defaults to 4 retries| |signRequest|Function|synchronous callback for interposing headers before request is sent| |url|String|Fully-qualified URL to connect to| diff --git a/examples/dtrace/demo.js b/examples/dtrace/demo.js index 9e4c54616..ff8b42e22 100644 --- a/examples/dtrace/demo.js +++ b/examples/dtrace/demo.js @@ -69,7 +69,7 @@ // 512 | 0 var restify = require('../../lib'); -var Logger = require('bunyan'); +var Logger = require('pino'); ///--- Globals @@ -80,8 +80,7 @@ var NAME = 'exampleapp'; var log = new Logger({ name: NAME, level: 'trace', - service: NAME, - serializers: restify.bunyan.serializers + base: { service: NAME } }); var server = restify.createServer({ diff --git a/examples/http2/http2.js b/examples/http2/http2.js index 9491335fa..51b28a204 100644 --- a/examples/http2/http2.js +++ b/examples/http2/http2.js @@ -1,6 +1,6 @@ var path = require('path'); var fs = require('fs'); -var bunyan = require('bunyan'); +var pino = require('pino'); var restify = require('../../lib'); var srv = restify.createServer({ @@ -21,10 +21,10 @@ srv.on( restify.plugins.auditLogger({ event: 'after', body: true, - log: bunyan.createLogger({ - name: 'audit', - stream: process.stdout - }) + log: pino( + { name: 'audit' }, + process.stdout + ) }) ); diff --git a/examples/spdy/spdy.js b/examples/spdy/spdy.js index aa0d28651..c02f0964a 100644 --- a/examples/spdy/spdy.js +++ b/examples/spdy/spdy.js @@ -1,6 +1,6 @@ var path = require('path'); var fs = require('fs'); -var bunyan = require('bunyan'); +var pino = require('pino'); var restify = require('../../lib'); var srv = restify.createServer({ @@ -21,10 +21,7 @@ srv.on( restify.plugins.auditLogger({ event: 'after', body: true, - log: bunyan.createLogger({ - name: 'audit', - stream: process.stdout - }) + log: pino({name: 'audit'}) }) ); diff --git a/examples/todoapp/README.md b/examples/todoapp/README.md index b36865882..71891747c 100644 --- a/examples/todoapp/README.md +++ b/examples/todoapp/README.md @@ -37,20 +37,20 @@ First, this has a `package.json`, so you'll need to run `npm install` in the directory. Once you've done that, to get started _and_ see audit logs on your terminal, run it like this: - $ node main.js 2>&1 | bunyan + $ node main.js 2>&1 | npx pino-pretty If you want to see all the built in restify tracing: - $ node main.js -vv 2>&1 | bunyan + $ node main.js -vv 2>&1 | npx pino-pretty By default, this program writes to a directory in `/tmp`, but you can override with a `-d` option. Additionally, by default it does not require authentication, but you can require that with: - $ node main.js -u admin -z secret 2>&1 | bunyan + $ node main.js -u admin -z secret 2>&1 | npx pino-pretty -Lastly, re: the `2>&1 | bunyan` bit. In production, you assuredly would *not* -want to pipe to the [bunyan](https://github.com/trentm/node-bunyan) CLI, but +Lastly, re: the `2>&1 | npx pino-pretty` bit. In production, you assuredly would *not* +want to pipe to the [pino-pretty](https://github.com/pinojs/pino-pretty) CLI, but rather capture the audit records in their raw form, so they would be easy to post process and perform analytics on. Like all UNIX programs should, this example writes "informational" messages to `stderr`, and `audit` records to @@ -61,7 +61,7 @@ stdout. It's up to you to redirect them as appropriate. Let's get the full magilla (i.e., with auth) running: - $ node main.js -u admin -z secret 2>&1 | bunyan + $ node main.js -u admin -z secret 2>&1 | npx pino-pretty Also, before we go any further, install the [json](https://github.com/trentm/json) tool as all the examples below use that. diff --git a/examples/todoapp/lib/server.js b/examples/todoapp/lib/server.js index 53a7a1c71..f8843aa64 100644 --- a/examples/todoapp/lib/server.js +++ b/examples/todoapp/lib/server.js @@ -5,7 +5,7 @@ var path = require('path'); var util = require('util'); var assert = require('assert-plus'); -var bunyan = require('bunyan'); +var pino = require('pino'); var restify = require('restify'); var errors = require('restify-errors'); @@ -326,7 +326,7 @@ function createServer(options) { // Handles annoying user agents (curl) server.pre(restify.pre.userAgentConnection()); - // Set a per request bunyan logger (with requestid filled in) + // Set a per request pino logger (with requestid filled in) server.use(restify.requestLogger()); // Allow 5 requests/second by IP, and burst to 10 @@ -422,11 +422,7 @@ function createServer(options) { 'after', restify.auditLogger({ body: true, - log: bunyan.createLogger({ - level: 'info', - name: 'todoapp-audit', - stream: process.stdout - }) + log: pino({ level: 'info', name: 'todoapp-audit' }) }) ); } diff --git a/examples/todoapp/main.js b/examples/todoapp/main.js index 8abaf5678..ccdbe2e08 100644 --- a/examples/todoapp/main.js +++ b/examples/todoapp/main.js @@ -3,7 +3,7 @@ var fs = require('fs'); var path = require('path'); -var bunyan = require('bunyan'); +var pino = require('pino'); var getopt = require('posix-getopt'); var restify = require('restify'); @@ -13,32 +13,7 @@ var todo = require('./lib'); var NAME = 'todoapp'; -// In true UNIX fashion, debug messages go to stderr, and audit records go -// to stdout, so you can split them as you like in the shell -var LOG = bunyan.createLogger({ - name: NAME, - streams: [ - { - level: process.env.LOG_LEVEL || 'info', - stream: process.stderr - }, - { - // This ensures that if we get a WARN or above all debug records - // related to that request are spewed to stderr - makes it nice - // filter out debug messages in prod, but still dump on user - // errors so you can debug problems - level: 'debug', - type: 'raw', - stream: new restify.bunyan.RequestCaptureStream({ - level: bunyan.WARN, - maxRecords: 100, - maxRequestIds: 1000, - stream: process.stderr - }) - } - ], - serializers: restify.bunyan.serializers -}); +var LOG = pino({ name: NAME }); ///--- Helpers @@ -49,7 +24,7 @@ var LOG = bunyan.createLogger({ * the 'verbose' or '-v' option afflicts the log level, repeatedly. So you * can run something like: * - * node main.js -p 80 -vv 2>&1 | bunyan + * node main.js -p 80 -vv 2>&1 | npx pino-pretty * * And the log level will be set to TRACE. */ @@ -79,9 +54,9 @@ function parseOptions() { case 'v': // Allows us to set -vvv -> this little hackery // just ensures that we're never < TRACE - LOG.level(Math.max(bunyan.TRACE, LOG.level() - 10)); + LOG.level(Math.max(pino.levels.values.trace, LOG.level - 10)); - if (LOG.level() <= bunyan.DEBUG) { + if (LOG.level <= pino.levels.values.debug) { LOG = LOG.child({ src: true }); } break; diff --git a/examples/todoapp/package.json b/examples/todoapp/package.json index 6bf9764b6..ccdec4ec7 100644 --- a/examples/todoapp/package.json +++ b/examples/todoapp/package.json @@ -5,16 +5,17 @@ "main": "main.js", "dependencies": { "assert-plus": "0.2.0", - "bunyan": "1.8.13", + "pino": "^6.3.2", "posix-getopt": "1.2.0", - "restify-errors": "^3.1.0", + "restify-errors": "^4.0.0", "restify": "^4.0.3" }, "devDependencies": { - "nodeunit": "0.9.1" + "nodeunit": "0.9.1", + "pino-pretty": "^4.0.0" }, "scripts": { - "start": "node main.js 2>&1 | bunyan", + "start": "node main.js 2>&1 | pino-pretty", "test": "nodeunit test" }, "author": "Mark Cavage", diff --git a/examples/todoapp/test/todo.test.js b/examples/todoapp/test/todo.test.js index 4fe6b6340..380887fa8 100644 --- a/examples/todoapp/test/todo.test.js +++ b/examples/todoapp/test/todo.test.js @@ -2,7 +2,7 @@ var fs = require('fs'); -var bunyan = require('bunyan'); +var pino = require('pino'); var restify = require('restify'); var todo = require('../lib'); @@ -17,11 +17,9 @@ var SOCK = '/tmp/.todo_sock'; ///--- Tests exports.setup = function(t) { - var log = bunyan.createLogger({ + var log = pino({ name: 'todo_unit_test', - level: process.env.LOG_LEVEL || 'info', - serializers: restify.bunyan.serializers, - stream: process.stdout + level: process.env.LOG_LEVEL || 'info' }); fs.mkdir(DIR, function(err) { diff --git a/lib/bunyan_helper.js b/lib/bunyan_helper.js deleted file mode 100644 index 9c44546ff..000000000 --- a/lib/bunyan_helper.js +++ /dev/null @@ -1,299 +0,0 @@ -// Copyright 2012 Mark Cavage, Inc. All rights reserved. - -'use strict'; - -var Stream = require('stream').Stream; -var util = require('util'); - -var assert = require('assert-plus'); -var bunyan = require('bunyan'); -var LRU = require('lru-cache'); -var uuid = require('uuid'); - -///--- Globals - -var sprintf = util.format; -var DEFAULT_REQ_ID = uuid.v4(); -var STR_FMT = '[object %s]'; - -///--- Helpers - -/** - * Appends streams - * - * @private - * @function appendStream - * @param {Stream} streams - the stream to append to - * @param {Stream} s - the stream to append - * @returns {undefined} no return value - */ -function appendStream(streams, s) { - assert.arrayOfObject(streams, 'streams'); - assert.object(s, 'stream'); - - if (s instanceof Stream) { - streams.push({ - raw: false, - stream: s - }); - } else { - assert.optionalBool(s.raw, 'stream.raw'); - assert.object(s.stream, 'stream.stream'); - streams.push(s); - } -} - -///--- API -/** - * A Bunyan stream to capture records in a ring buffer and only pass through - * on a higher-level record. E.g. buffer up all records but only dump when - * getting a WARN or above. - * - * @public - * @class - * @param {Object} opts - contains the parameters: - * @param {Object} opts.stream - The stream to which to write when - * dumping captured records. - * One of `stream` - * or `streams` must be specified. - * @param {Array} opts.streams - One of `stream` or `streams` must be - * specified. - * @param {Number | String} opts.level - The level at which to trigger dumping - * captured records. Defaults to - * bunyan.WARN. - * @param {Number} opts.maxRecords - Number of records to capture. Default - * 100. - * @param {Number} opts.maxRequestIds - Number of simultaneous request id - * capturing buckets to maintain. Default - * 1000. - * @param {Boolean} opts.dumpDefault - If true, then dump captured records on - * the *default* request id when dumping. - * I.e. dump records logged without - * "req_id" field. Default false. - */ -function RequestCaptureStream(opts) { - assert.object(opts, 'options'); - assert.optionalObject(opts.stream, 'options.stream'); - assert.optionalArrayOfObject(opts.streams, 'options.streams'); - assert.optionalNumber(opts.level, 'options.level'); - assert.optionalNumber(opts.maxRecords, 'options.maxRecords'); - assert.optionalNumber(opts.maxRequestIds, 'options.maxRequestIds'); - assert.optionalBool(opts.dumpDefault, 'options.dumpDefault'); - - var self = this; - Stream.call(this); - - this.level = opts.level ? bunyan.resolveLevel(opts.level) : bunyan.WARN; - this.limit = opts.maxRecords || 100; - this.maxRequestIds = opts.maxRequestIds || 1000; - // eslint-disable-next-line new-cap - // need to initialize using `new` - this.requestMap = new LRU({ - max: self.maxRequestIds - }); - this.dumpDefault = opts.dumpDefault; - - this._offset = -1; - this._rings = []; - - this.streams = []; - - if (opts.stream) { - appendStream(this.streams, opts.stream); - } - - if (opts.streams) { - opts.streams.forEach(appendStream.bind(null, this.streams)); - } - - this.haveNonRawStreams = false; - - for (var i = 0; i < this.streams.length; i++) { - if (!this.streams[i].raw) { - this.haveNonRawStreams = true; - break; - } - } -} -util.inherits(RequestCaptureStream, Stream); - -/** - * Write to the stream - * - * @public - * @function write - * @param {Object} record - a bunyan log record - * @returns {undefined} no return value - */ -RequestCaptureStream.prototype.write = function write(record) { - var req_id = record.req_id || DEFAULT_REQ_ID; - var ring; - var self = this; - - if (!(ring = this.requestMap.get(req_id))) { - if (++this._offset > this.maxRequestIds) { - this._offset = 0; - } - - if (this._rings.length <= this._offset) { - this._rings.push( - new bunyan.RingBuffer({ - limit: self.limit - }) - ); - } - - ring = this._rings[this._offset]; - ring.records.length = 0; - this.requestMap.set(req_id, ring); - } - - assert.ok(ring, 'no ring found'); - - // write the record to the ring. - ring.write(record); - // triger dumping of all the records - if (record.level >= this.level) { - var i, r, ser; - - for (i = 0; i < ring.records.length; i++) { - r = ring.records[i]; - - if (this.haveNonRawStreams) { - ser = JSON.stringify(r, bunyan.safeCycles()) + '\n'; - } - self.streams.forEach(function forEach(s) { - s.stream.write(s.raw ? r : ser); - }); - } - ring.records.length = 0; - - if (this.dumpDefault) { - var defaultRing = self.requestMap.get(DEFAULT_REQ_ID); - - for (i = 0; i < defaultRing.records.length; i++) { - r = defaultRing.records[i]; - - if (this.haveNonRawStreams) { - ser = JSON.stringify(r, bunyan.safeCycles()) + '\n'; - } - self.streams.forEach(function forEach(s) { - s.stream.write(s.raw ? r : ser); - }); - } - defaultRing.records.length = 0; - } - } -}; - -/** - * toString() serialization - * - * @public - * @function toString - * @returns {String} stringified instance - */ -RequestCaptureStream.prototype.toString = function toString() { - return sprintf( - STR_FMT, - this.constructor.name, - this.level, - this.limit, - this.maxRequestIds - ); -}; - -///--- Serializers - -var SERIALIZERS = { - err: bunyan.stdSerializers.err, - req: bunyan.stdSerializers.req, - res: bunyan.stdSerializers.res, - client_req: clientReq, - client_res: clientRes -}; - -/** - * A request serializer. returns a stripped down object for logging. - * - * @private - * @function clientReq - * @param {Object} req - the request object - * @returns {Object} serialized req - */ -function clientReq(req) { - if (!req) { - return req; - } - - var host; - - try { - host = req.host.split(':')[0]; - } catch (e) { - host = false; - } - - return { - method: req ? req.method : false, - url: req ? req.path : false, - address: host, - port: req ? req.port : false, - headers: req ? req.headers : false - }; -} - -/** - * A response serializer. returns a stripped down object for logging. - * - * @private - * @function clientRes - * @param {Object} res - the response object - * @returns {Object} serialized response - */ -function clientRes(res) { - if (!res || !res.statusCode) { - return res; - } - - return { - statusCode: res.statusCode, - headers: res.headers - }; -} - -/** - * Create a bunyan logger. - * - * @public - * @function createLogger - * @param {String} name - of the logger - * @returns {Object} bunyan logger - */ -function createLogger(name) { - return bunyan.createLogger({ - name: name, - serializers: SERIALIZERS, - streams: [ - { - level: 'warn', - stream: process.stderr - }, - { - level: 'debug', - type: 'raw', - stream: new RequestCaptureStream({ - stream: process.stderr - }) - } - ] - }); -} - -///--- Exports - -module.exports = { - RequestCaptureStream: RequestCaptureStream, - serializers: SERIALIZERS, - createLogger: createLogger -}; diff --git a/lib/index.js b/lib/index.js index 3d80edb1f..a4a168e33 100644 --- a/lib/index.js +++ b/lib/index.js @@ -5,7 +5,7 @@ var assert = require('assert-plus'); var errors = require('restify-errors'); -var bunyan = require('./bunyan_helper'); +var pino = require('pino'); var Router = require('./router'); var Server = require('./server'); var shallowCopy = require('./utils').shallowCopy; @@ -22,8 +22,8 @@ var InternalError = errors.InternalError; * @param {String} [options.name="restify"] - Name of the server. * @param {Boolean} [options.dtrace=false] - enable DTrace support * @param {Router} [options.router=new Router(opts)] - Router - * @param {Object} [options.log=bunyan.createLogger(options.name || "restify")] - * - [bunyan](https://github.com/trentm/node-bunyan) instance. + * @param {Object} [options.log=pino({name:options.name || "restify"})] + * - [pino](https://github.com/pinojs/pino) instance. * @param {String} [options.url] - Once listen() is called, this will be filled * in with where the server is running. * @param {String|Buffer} [options.certificate] - If you want to create an HTTPS @@ -35,7 +35,7 @@ var InternalError = errors.InternalError; * @param {Boolean} [options.handleUncaughtExceptions=false] - When true restify * will use a domain to catch and respond to any uncaught * exceptions that occur in it's handler stack. - * [bunyan](https://github.com/trentm/node-bunyan) instance. + * [pino](https://github.com/pinojs/pino) instance. * response header, default is `restify`. Pass empty string to unset the header. * Comes with significant negative performance impact. * @param {Object} [options.spdy] - Any options accepted by @@ -80,7 +80,7 @@ function createServer(options) { // empty string should override default value. opts.name = opts.hasOwnProperty('name') ? opts.name : 'restify'; - opts.log = opts.log || bunyan.createLogger(opts.name || 'restify'); + opts.log = opts.log || pino({ name: opts.name || 'restify' }); opts.router = opts.router || new Router(opts); server = new Server(opts); @@ -109,7 +109,7 @@ function createServer(options) { ///--- Exports -module.exports.bunyan = bunyan; +module.exports.logger = pino; module.exports.createServer = createServer; module.exports.formatters = require('./formatters'); module.exports.plugins = require('./plugins'); diff --git a/lib/plugins/audit.js b/lib/plugins/audit.js index 38a30d4c4..a7be5bc55 100644 --- a/lib/plugins/audit.js +++ b/lib/plugins/audit.js @@ -3,7 +3,7 @@ 'use strict'; var assert = require('assert-plus'); -var bunyan = require('bunyan'); +var pino = require('pino'); var HttpError = require('restify-errors').HttpError; var errors = require('restify-errors'); var hrTimeDurationInMs = require('./utils/hrTimeDurationInMs'); @@ -61,10 +61,10 @@ function getResponseHeaders(res) { * * * server.on('after', restify.plugins.auditLogger({ - * log: bunyan.createLogger({ - * name: 'audit', - * stream: process.stdout - * }), + * log: pino( + * {name: 'audit'}, + * process.stdout + * ), * event: 'after', * server: SERVER, * logMetrics : logBuffer, @@ -73,7 +73,7 @@ function getResponseHeaders(res) { * * @example * - * You pass in the auditor a bunyan logger, optionally server object, + * You pass in the auditor a pino logger, optionally server object, * Ringbuffer and a flag printLog indicate if log needs to be print out at info * level or not. By default, without specify printLog flag, it will write out * record lookling like this: @@ -103,7 +103,7 @@ function getResponseHeaders(res) { * "trailers": {}, * "version": "*", * "timers": { - * "bunyan": 52, + * "requestLogger": 52, * "saveAction": 8, * "reqResTracker": 213, * "addContext": 8, @@ -199,7 +199,7 @@ function auditLogger(opts) { if (typeof printLog === 'undefined') { printLog = true; } - var errSerializer = bunyan.stdSerializers.err; + var errSerializer = pino.stdSerializers.err; // don't break legacy use, where there was no top level opts.serializer if (opts.log.serializers && opts.log.serializers.err) { diff --git a/lib/plugins/index.js b/lib/plugins/index.js index 5fe1e0694..b820d7a38 100644 --- a/lib/plugins/index.js +++ b/lib/plugins/index.js @@ -24,7 +24,7 @@ module.exports = { queryParser: require('./query'), metrics: require('./metrics'), requestExpiry: require('./requestExpiry'), - requestLogger: require('./bunyan'), + requestLogger: require('./requestLogger'), serveStatic: require('./static'), serveStaticFiles: require('./staticFiles'), throttle: require('./throttle'), diff --git a/lib/plugins/bunyan.js b/lib/plugins/requestLogger.js similarity index 94% rename from lib/plugins/bunyan.js rename to lib/plugins/requestLogger.js index 7d4f854c8..401c4d8f2 100644 --- a/lib/plugins/bunyan.js +++ b/lib/plugins/requestLogger.js @@ -9,7 +9,7 @@ var shallowCopy = require('./utils/shallowCopy'); ///--- API /** - * Sets up a child [bunyan](https://github.com/trentm/node-bunyan) logger with + * Sets up a child [logger](https://github.com/pinojs/pino) logger with * the current request id filled in, along with any other parameters you define. * * You can pass in no options to this, in which case only the request id will be @@ -52,7 +52,7 @@ function requestLogger(options) { var headersToCopy = opts.headers || []; - return function bunyan(req, res, next) { + return function logger(req, res, next) { if (!req.log && !opts.log) { next(); return; diff --git a/lib/server.js b/lib/server.js index 65ab4869e..a180a08ae 100644 --- a/lib/server.js +++ b/lib/server.js @@ -47,7 +47,7 @@ var sprintf = util.format; * @param {String} options.name - Name of the server. * @param {Boolean} [options.dtrace=false] - enable DTrace support * @param {Router} options.router - Router - * @param {Object} options.log - [bunyan](https://github.com/trentm/node-bunyan) + * @param {Object} options.log - [pino](https://github.com/pinojs/pino) * instance. * @param {String} [options.url] - Once listen() is called, this will be filled * in with where the server is running. @@ -61,7 +61,7 @@ var sprintf = util.format; * will use a domain to catch and respond to any uncaught * exceptions that occur in it's handler stack. * Comes with significant negative performance impact. - * [bunyan](https://github.com/trentm/node-bunyan) instance. + * [pino](https://github.com/pinojs/pino) instance. * response header, default is `restify`. Pass empty string to unset the header. * @param {Object} [options.spdy] - Any options accepted by * [node-spdy](https://github.com/indutny/node-spdy). diff --git a/package.json b/package.json index e4e1ae20b..1fd525fb2 100644 --- a/package.json +++ b/package.json @@ -94,7 +94,6 @@ }, "dependencies": { "assert-plus": "^1.0.0", - "bunyan": "^1.8.12", "csv": "^5.1.1", "escape-regexp-component": "^1.0.2", "ewma": "^2.0.1", @@ -107,6 +106,7 @@ "negotiator": "^0.6.2", "once": "^1.4.0", "pidusage": "^2.0.17", + "pino": "^6.3.2", "qs": "^6.7.0", "restify-errors": "^8.0.2", "semver": "^6.1.1", diff --git a/test/lib/helper.js b/test/lib/helper.js index 53f6adb5f..7efb95236 100644 --- a/test/lib/helper.js +++ b/test/lib/helper.js @@ -9,11 +9,9 @@ var domain = require('domain'); -var bunyan = require('bunyan'); +var pino = require('pino'); var once = require('once'); -var restify = require('../../lib'); - ///--- Exports module.exports = { @@ -74,13 +72,14 @@ module.exports = { }, getLog: function(name, streams, level) { - return bunyan.createLogger({ - level: process.env.LOG_LEVEL || level || 'fatal', - name: name || process.argv[1], - streams: streams || [{ stream: process.stdout }], - src: true, - serializers: restify.bunyan.serializers - }); + return pino( + { + level: process.env.LOG_LEVEL || level || 'fatal', + name: name || process.argv[1], + serializers: pino.stdSerializers + }, + streams || process.stdout + ); }, get dtrace() { diff --git a/test/lib/streamRecorder.js b/test/lib/streamRecorder.js new file mode 100644 index 000000000..2147ef2f5 --- /dev/null +++ b/test/lib/streamRecorder.js @@ -0,0 +1,23 @@ +'use strict'; + +const stream = require('stream'); + +class StreamRecorder extends stream.Writable { + constructor(options) { + options = options || {}; + super(options); + this.flushRecords(); + } + + _write(chunk, encoding, callback) { + const record = JSON.parse(chunk.toString()); + this.records.push(record); + callback(); + } + + flushRecords() { + this.records = []; + } +} + +module.exports = StreamRecorder; diff --git a/test/plugins/audit.test.js b/test/plugins/audit.test.js index e39e4be7f..0d949be12 100644 --- a/test/plugins/audit.test.js +++ b/test/plugins/audit.test.js @@ -6,13 +6,14 @@ var PassThrough = require('stream').PassThrough; // external requires var assert = require('chai').assert; -var bunyan = require('bunyan'); +var pino = require('pino'); var lodash = require('lodash'); var restify = require('../../lib/index.js'); var restifyClients = require('restify-clients'); // local files var helper = require('../lib/helper'); +var StreamRecorder = require('../lib/streamRecorder'); var vasync = require('vasync'); // local globals @@ -51,22 +52,12 @@ describe('audit logger', function() { }); it('audit logger should print log by default', function(done) { - var logBuffer = new bunyan.RingBuffer({ - limit: 1000 - }); + var logBuffer = new StreamRecorder(); var collectLog; SERVER.on( 'after', restify.plugins.auditLogger({ - log: bunyan.createLogger({ - name: 'audit', - streams: [ - { - level: 'info', - stream: process.stdout - } - ] - }), + log: pino({ name: 'audit' }, logBuffer), server: SERVER, event: 'after' }) @@ -126,15 +117,7 @@ describe('audit logger', function() { SERVER.once( 'after', restify.plugins.auditLogger({ - log: bunyan.createLogger({ - name: 'audit', - streams: [ - { - level: 'info', - stream: process.stdout - } - ] - }), + log: pino({ name: 'audit' }), server: SERVER, event: 'after' }) @@ -166,22 +149,13 @@ describe('audit logger', function() { }); it('test custom serializers', function(done) { - // Dirty hack to capture the log record using a ring buffer. - var ringbuffer = new bunyan.RingBuffer({ limit: 1 }); + // capture the log record + var buffer = new StreamRecorder(); SERVER.once( 'after', restify.plugins.auditLogger({ - log: bunyan.createLogger({ - name: 'audit', - streams: [ - { - level: 'info', - type: 'raw', - stream: ringbuffer - } - ] - }), + log: pino({ name: 'audit' }, buffer), event: 'after', serializers: { req: function(req) { @@ -200,7 +174,7 @@ describe('audit logger', function() { }); SERVER.on('after', function() { - var record = ringbuffer.records && ringbuffer.records[0]; + var record = buffer.records && buffer.records[0]; assert.equal(record.req.fooReq, 'barReq'); assert.equal(record.res.fooRes, 'barRes'); done(); @@ -212,23 +186,14 @@ describe('audit logger', function() { }); it('should log handler timers', function(done) { - // Dirty hack to capture the log record using a ring buffer. - var ringbuffer = new bunyan.RingBuffer({ limit: 1 }); + // capture the log record + var buffer = new StreamRecorder(); var WAIT_IN_MILLISECONDS = 1100; SERVER.once( 'after', restify.plugins.auditLogger({ - log: bunyan.createLogger({ - name: 'audit', - streams: [ - { - level: 'info', - type: 'raw', - stream: ringbuffer - } - ] - }), + log: pino({ name: 'audit' }, buffer), event: 'after' }) ); @@ -246,12 +211,12 @@ describe('audit logger', function() { }); SERVER.on('after', function() { - var record = ringbuffer.records && ringbuffer.records[0]; + var record = buffer.records && buffer.records[0]; // check timers assert.ok(record, 'no log records'); assert.equal( - ringbuffer.records.length, + buffer.records.length, 1, 'should only have 1 log record' ); @@ -290,23 +255,14 @@ describe('audit logger', function() { it('should log anonymous handler timers', function(done) { this.timeout(5000); - // Dirty hack to capture the log record using a ring buffer. - var ringbuffer = new bunyan.RingBuffer({ limit: 1 }); + // capture the log record + var buffer = new StreamRecorder(); var WAIT_IN_MILLISECONDS = 1000; SERVER.once( 'after', restify.plugins.auditLogger({ - log: bunyan.createLogger({ - name: 'audit', - streams: [ - { - level: 'info', - type: 'raw', - stream: ringbuffer - } - ] - }), + log: pino({ name: 'audit' }, buffer), event: 'after' }) ); @@ -345,10 +301,10 @@ describe('audit logger', function() { SERVER.on('after', function() { // check timers - var record = ringbuffer.records && ringbuffer.records[0]; + var record = buffer.records && buffer.records[0]; assert.ok(record, 'no log records'); assert.equal( - ringbuffer.records.length, + buffer.records.length, 1, 'should only have 1 log record' ); @@ -415,23 +371,14 @@ describe('audit logger', function() { }); it('restify-GH-1435 should accumulate log handler timers', function(done) { - // Dirty hack to capture the log record using a ring buffer. - var ringbuffer = new bunyan.RingBuffer({ limit: 1 }); + // capture the log record + var buffer = new StreamRecorder(); var WAIT_IN_MILLISECONDS = 1100; SERVER.once( 'after', restify.plugins.auditLogger({ - log: bunyan.createLogger({ - name: 'audit', - streams: [ - { - level: 'info', - type: 'raw', - stream: ringbuffer - } - ] - }), + log: pino({ name: 'audit' }, buffer), event: 'after' }) ); @@ -452,12 +399,12 @@ describe('audit logger', function() { }); SERVER.on('after', function() { - var record = ringbuffer.records && ringbuffer.records[0]; + var record = buffer.records && buffer.records[0]; // check timers assert.ok(record, 'no log records'); assert.equal( - ringbuffer.records.length, + buffer.records.length, 1, 'should only have 1 log record' ); @@ -482,22 +429,13 @@ describe('audit logger', function() { }); it('restify-GH-812 audit logger has query params string', function(done) { - // Dirty hack to capture the log record using a ring buffer. - var ringbuffer = new bunyan.RingBuffer({ limit: 1 }); + // capture the log record + var buffer = new StreamRecorder(); SERVER.once( 'after', restify.plugins.auditLogger({ - log: bunyan.createLogger({ - name: 'audit', - streams: [ - { - level: 'info', - type: 'raw', - stream: ringbuffer - } - ] - }), + log: pino({ name: 'audit' }, buffer), event: 'after' }) ); @@ -509,13 +447,13 @@ describe('audit logger', function() { SERVER.on('after', function() { // check timers - assert.ok(ringbuffer.records[0], 'no log records'); + assert.ok(buffer.records[0], 'no log records'); assert.equal( - ringbuffer.records.length, + buffer.records.length, 1, 'should only have 1 log record' ); - assert.ok(ringbuffer.records[0].req.query, 'a=1&b=2'); + assert.ok(buffer.records[0].req.query, 'a=1&b=2'); done(); }); @@ -525,22 +463,13 @@ describe('audit logger', function() { }); it('restify-GH-812 audit logger has query params obj', function(done) { - // Dirty hack to capture the log record using a ring buffer. - var ringbuffer = new bunyan.RingBuffer({ limit: 1 }); + // capture the log record using a buffer. + var buffer = new StreamRecorder(); SERVER.once( 'after', restify.plugins.auditLogger({ - log: bunyan.createLogger({ - name: 'audit', - streams: [ - { - level: 'info', - type: 'raw', - stream: ringbuffer - } - ] - }), + log: pino({ name: 'audit' }, buffer), event: 'after' }) ); @@ -555,13 +484,13 @@ describe('audit logger', function() { SERVER.on('after', function() { // check timers - assert.ok(ringbuffer.records[0], 'no log records'); + assert.ok(buffer.records[0], 'no log records'); assert.equal( - ringbuffer.records.length, + buffer.records.length, 1, 'should only have 1 log record' ); - assert.deepEqual(ringbuffer.records[0].req.query, { + assert.deepEqual(buffer.records[0].req.query, { a: '1', b: '2' }); @@ -579,15 +508,7 @@ describe('audit logger', function() { SERVER.once( 'pre', restify.plugins.auditLogger({ - log: bunyan.createLogger({ - name: 'audit', - streams: [ - { - level: 'info', - stream: ptStream - } - ] - }), + log: pino({ name: 'audit' }, ptStream), event: 'pre' }) ); @@ -620,15 +541,7 @@ describe('audit logger', function() { SERVER.once( 'routed', restify.plugins.auditLogger({ - log: bunyan.createLogger({ - name: 'audit', - streams: [ - { - level: 'info', - stream: ptStream - } - ] - }), + log: pino({ name: 'audit' }, ptStream), event: 'routed' }) ); @@ -659,15 +572,7 @@ describe('audit logger', function() { SERVER.once( 'after', restify.plugins.auditLogger({ - log: bunyan.createLogger({ - name: 'audit', - streams: [ - { - level: 'info', - stream: process.stdout - } - ] - }), + log: pino({ name: 'audit' }), context: function(req, res, route, err) { return { qs: req.getQuery() @@ -704,15 +609,7 @@ describe('audit logger', function() { SERVER.once( 'after', restify.plugins.auditLogger({ - log: bunyan.createLogger({ - name: 'audit', - streams: [ - { - level: 'info', - stream: process.stdout - } - ] - }), + log: pino({ name: 'audit' }), server: SERVER, event: 'after' }) diff --git a/test/plugins/plugins.test.js b/test/plugins/plugins.test.js index fa5ae698e..c837c6e4c 100644 --- a/test/plugins/plugins.test.js +++ b/test/plugins/plugins.test.js @@ -4,6 +4,7 @@ /* eslint-disable func-names */ // external requires +var pino = require('pino'); var assert = require('chai').assert; var restify = require('../../lib/index.js'); var restifyClients = require('restify-clients'); @@ -76,8 +77,9 @@ describe('all other plugins', function() { SERVER.use(restify.plugins.requestLogger({ headers: headers })); SERVER.get(getPath, function(req, res, next) { - assert.equal(req.log.fields[key], 'foo-for-eva'); - assert.equal(req.log.fields.hasOwnProperty(badKey), false); + var childings = req.log[pino.symbols.chindingsSym]; + assert.match(childings, /"x-request-uuid":"foo-for-eva"/); + assert.notMatch(childings, /x-foo-bar/); res.send(); next(); }); diff --git a/test/server.test.js b/test/server.test.js index c2bc3decc..f176f84a6 100644 --- a/test/server.test.js +++ b/test/server.test.js @@ -4,10 +4,9 @@ /* eslint-disable func-names */ var assert = require('assert-plus'); -var bunyan = require('bunyan'); +var pino = require('pino'); var childprocess = require('child_process'); var http = require('http'); -var stream = require('stream'); var errors = require('restify-errors'); var restifyClients = require('restify-clients'); @@ -20,6 +19,7 @@ if (require.cache[__dirname + '/lib/helper.js']) { delete require.cache[__dirname + '/lib/helper.js']; } var helper = require('./lib/helper.js'); +var StreamRecorder = require('./lib/streamRecorder'); ///--- Globals @@ -1519,20 +1519,11 @@ test( ]); // set up audit logs - var ringbuffer = new bunyan.RingBuffer({ limit: 1 }); + var buffer = new StreamRecorder(); SERVER.on( 'after', restify.plugins.auditLogger({ - log: bunyan.createLogger({ - name: 'audit', - streams: [ - { - level: 'info', - type: 'raw', - stream: ringbuffer - } - ] - }), + log: pino({ name: 'audit' }, buffer), event: 'after' }) ); @@ -1544,18 +1535,15 @@ test( t.equal(err.name, 'RequestCloseError'); // check records - t.ok(ringbuffer.records[0], 'no log records'); + t.ok(buffer.records[0], 'no log records'); t.equal( - ringbuffer.records.length, + buffer.records.length, 1, 'should only have 1 log record' ); - // TODO: fix this after plugin is fixed to use - // req.connectionState() - // t.equal(ringbuffer.records[0].req.clientClosed, true); // check timers - var handlers = Object.keys(ringbuffer.records[0].req.timers); + var handlers = Object.keys(buffer.records[0].req.timers); t.equal(handlers.length, 2, 'should only have 2 req timers'); t.equal( handlers[0], @@ -1583,6 +1571,8 @@ test( // reset numCount numCount = 0; + //reset stream-recorder + buffer.flushRecords(); FAST_CLIENT.get('/audit?v=2', function(err2, req2, res2, data2) { t.ok(err2); @@ -1669,47 +1659,6 @@ test('GH-667 returning error in error handler should not do anything', function( }); }); -test('GH-958 RCS does not write triggering record', function(t) { - var passThrough = new stream.PassThrough(); - var count = 1; - // we would expect to get 3 logging statements - passThrough.on('data', function(chunk) { - var obj = JSON.parse(chunk.toString()); - t.equal(obj.msg, count.toString()); - - if (count === 3) { - t.end(); - } - count++; - }); - - SERVER.log = helper.getLog('server', [ - { - level: bunyan.DEBUG, - type: 'raw', - stream: new restify.bunyan.RequestCaptureStream({ - level: bunyan.WARN, - stream: passThrough - }) - } - ]); - - SERVER.use(restify.plugins.requestLogger()); - - SERVER.get('/rcs', function(req, res, next) { - req.log.debug('1'); - req.log.info('2'); - req.log.error('3'); - res.send(); - next(); - }); - - CLIENT.get('/rcs', function(err, _, res) { - t.ifError(err); - t.equal(res.statusCode, 200); - }); -}); - test('GH-1024 disable uncaughtException handler', function(t) { // With uncaughtException handling disabled, the node process will abort, // so testing of this feature must occur in a separate node process. diff --git a/tools/docsBuild.js b/tools/docsBuild.js index 96a630af4..76a0a96bf 100644 --- a/tools/docsBuild.js +++ b/tools/docsBuild.js @@ -55,7 +55,7 @@ var docsConfig = [ path.join(__dirname, LIB_PATH, 'plugins/query.js'), path.join(__dirname, LIB_PATH, 'plugins/jsonp.js'), path.join(__dirname, LIB_PATH, 'plugins/bodyParser.js'), - path.join(__dirname, LIB_PATH, 'plugins/bunyan.js'), + path.join(__dirname, LIB_PATH, 'plugins/requestLogger.js'), path.join(__dirname, LIB_PATH, 'plugins/gzip.js'), path.join(__dirname, LIB_PATH, 'plugins/static.js'), path.join(__dirname, LIB_PATH, 'plugins/staticFiles.js'),