Skip to content

Commit 2f5bf87

Browse files
ghermetoghermeto
authoredJul 11, 2020
Prefer Pino logger over Bunyan (#1841)
BREAKING CHANGE: removes `RequestCaptureStream` and replaces `Bunyan` with `Pino`
·
v11.2.0v9.0.0-rc.1
1 parent 12be9e2 commit 2f5bf87

23 files changed

+154
-602
lines changed
 

‎docs/guides/8to9guide.md

+16-1
Original file line numberDiff line numberDiff line change
@@ -5,7 +5,7 @@ permalink: /docs/8to9/
55

66
## Introduction
77

8-
restify `9.x` comes with `async/await` support!
8+
Restify `9.x` comes with `async/await` support, `pino` and more!
99

1010
## Breaking Changes
1111

@@ -94,3 +94,18 @@ server.use(async (req, res, next) => {
9494
});
9595
});
9696
````
97+
98+
### Remove `RequestCaptureStream`
99+
100+
Removes `RequestCaptureStream` from Restify core.
101+
102+
### Use `Pino` as default logger (removes dependency on `Bunyan`)
103+
104+
[Pino](https://github.com/pinojs/pino) is well maintained, performance-focused,
105+
compatible API. It does have a few key differences from `Bunyan`:
106+
107+
- As a performance optimization, it stores bindings a single serialized `string`,
108+
while `Bunyan` stores them as object keys;
109+
- It uses a `setter` to set the log level, `Bunyan` uses a method;
110+
- It only accepts one stream. If you need the multi-stream functionality, you
111+
must use [pino-multistream](https://github.com/pinojs/pino-multi-stream).

‎docs/guides/client.md

+1-1
Original file line numberDiff line numberDiff line change
@@ -120,7 +120,7 @@ Options:
120120
|dtrace|Object|node-dtrace-provider handle|
121121
|gzip|Object|Will compress data when sent using `content-encoding: gzip`|
122122
|headers|Object|HTTP headers to set in all requests|
123-
|log|Object|[bunyan](https://github.com/trentm/node-bunyan) instance|
123+
|log|Object|[pino](https://github.com/pinojs/pino) instance|
124124
|retry|Object|options to provide to node-retry;"false" disables retry; defaults to 4 retries|
125125
|signRequest|Function|synchronous callback for interposing headers before request is sent|
126126
|url|String|Fully-qualified URL to connect to|

‎examples/dtrace/demo.js

+2-3
Original file line numberDiff line numberDiff line change
@@ -69,7 +69,7 @@
6969
// 512 | 0
7070

7171
var restify = require('../../lib');
72-
var Logger = require('bunyan');
72+
var Logger = require('pino');
7373

7474
///--- Globals
7575

@@ -80,8 +80,7 @@ var NAME = 'exampleapp';
8080
var log = new Logger({
8181
name: NAME,
8282
level: 'trace',
83-
service: NAME,
84-
serializers: restify.bunyan.serializers
83+
base: { service: NAME }
8584
});
8685

8786
var server = restify.createServer({

‎examples/http2/http2.js

+5-5
Original file line numberDiff line numberDiff line change
@@ -1,6 +1,6 @@
11
var path = require('path');
22
var fs = require('fs');
3-
var bunyan = require('bunyan');
3+
var pino = require('pino');
44
var restify = require('../../lib');
55

66
var srv = restify.createServer({
@@ -21,10 +21,10 @@ srv.on(
2121
restify.plugins.auditLogger({
2222
event: 'after',
2323
body: true,
24-
log: bunyan.createLogger({
25-
name: 'audit',
26-
stream: process.stdout
27-
})
24+
log: pino(
25+
{ name: 'audit' },
26+
process.stdout
27+
)
2828
})
2929
);
3030

‎examples/spdy/spdy.js

+2-5
Original file line numberDiff line numberDiff line change
@@ -1,6 +1,6 @@
11
var path = require('path');
22
var fs = require('fs');
3-
var bunyan = require('bunyan');
3+
var pino = require('pino');
44
var restify = require('../../lib');
55

66
var srv = restify.createServer({
@@ -21,10 +21,7 @@ srv.on(
2121
restify.plugins.auditLogger({
2222
event: 'after',
2323
body: true,
24-
log: bunyan.createLogger({
25-
name: 'audit',
26-
stream: process.stdout
27-
})
24+
log: pino({name: 'audit'})
2825
})
2926
);
3027

‎examples/todoapp/README.md

+6-6
Original file line numberDiff line numberDiff line change
@@ -37,20 +37,20 @@ First, this has a `package.json`, so you'll need to run `npm install` in the
3737
directory. Once you've done that, to get started _and_ see audit logs on your
3838
terminal, run it like this:
3939

40-
$ node main.js 2>&1 | bunyan
40+
$ node main.js 2>&1 | npx pino-pretty
4141

4242
If you want to see all the built in restify tracing:
4343

44-
$ node main.js -vv 2>&1 | bunyan
44+
$ node main.js -vv 2>&1 | npx pino-pretty
4545

4646
By default, this program writes to a directory in `/tmp`, but you can override
4747
with a `-d` option. Additionally, by default it does not require
4848
authentication, but you can require that with:
4949

50-
$ node main.js -u admin -z secret 2>&1 | bunyan
50+
$ node main.js -u admin -z secret 2>&1 | npx pino-pretty
5151

52-
Lastly, re: the `2>&1 | bunyan` bit. In production, you assuredly would *not*
53-
want to pipe to the [bunyan](https://github.com/trentm/node-bunyan) CLI, but
52+
Lastly, re: the `2>&1 | npx pino-pretty` bit. In production, you assuredly would *not*
53+
want to pipe to the [pino-pretty](https://github.com/pinojs/pino-pretty) CLI, but
5454
rather capture the audit records in their raw form, so they would be easy to
5555
post process and perform analytics on. Like all UNIX programs should, this
5656
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.
6161

6262
Let's get the full magilla (i.e., with auth) running:
6363

64-
$ node main.js -u admin -z secret 2>&1 | bunyan
64+
$ node main.js -u admin -z secret 2>&1 | npx pino-pretty
6565

6666
Also, before we go any further, install the
6767
[json](https://github.com/trentm/json) tool as all the examples below use that.

‎examples/todoapp/lib/server.js

+3-7
Original file line numberDiff line numberDiff line change
@@ -5,7 +5,7 @@ var path = require('path');
55
var util = require('util');
66

77
var assert = require('assert-plus');
8-
var bunyan = require('bunyan');
8+
var pino = require('pino');
99
var restify = require('restify');
1010
var errors = require('restify-errors');
1111

@@ -326,7 +326,7 @@ function createServer(options) {
326326
// Handles annoying user agents (curl)
327327
server.pre(restify.pre.userAgentConnection());
328328

329-
// Set a per request bunyan logger (with requestid filled in)
329+
// Set a per request pino logger (with requestid filled in)
330330
server.use(restify.requestLogger());
331331

332332
// Allow 5 requests/second by IP, and burst to 10
@@ -422,11 +422,7 @@ function createServer(options) {
422422
'after',
423423
restify.auditLogger({
424424
body: true,
425-
log: bunyan.createLogger({
426-
level: 'info',
427-
name: 'todoapp-audit',
428-
stream: process.stdout
429-
})
425+
log: pino({ level: 'info', name: 'todoapp-audit' })
430426
})
431427
);
432428
}

‎examples/todoapp/main.js

+5-30
Original file line numberDiff line numberDiff line change
@@ -3,7 +3,7 @@
33
var fs = require('fs');
44
var path = require('path');
55

6-
var bunyan = require('bunyan');
6+
var pino = require('pino');
77
var getopt = require('posix-getopt');
88
var restify = require('restify');
99

@@ -13,32 +13,7 @@ var todo = require('./lib');
1313

1414
var NAME = 'todoapp';
1515

16-
// In true UNIX fashion, debug messages go to stderr, and audit records go
17-
// to stdout, so you can split them as you like in the shell
18-
var LOG = bunyan.createLogger({
19-
name: NAME,
20-
streams: [
21-
{
22-
level: process.env.LOG_LEVEL || 'info',
23-
stream: process.stderr
24-
},
25-
{
26-
// This ensures that if we get a WARN or above all debug records
27-
// related to that request are spewed to stderr - makes it nice
28-
// filter out debug messages in prod, but still dump on user
29-
// errors so you can debug problems
30-
level: 'debug',
31-
type: 'raw',
32-
stream: new restify.bunyan.RequestCaptureStream({
33-
level: bunyan.WARN,
34-
maxRecords: 100,
35-
maxRequestIds: 1000,
36-
stream: process.stderr
37-
})
38-
}
39-
],
40-
serializers: restify.bunyan.serializers
41-
});
16+
var LOG = pino({ name: NAME });
4217

4318
///--- Helpers
4419

@@ -49,7 +24,7 @@ var LOG = bunyan.createLogger({
4924
* the 'verbose' or '-v' option afflicts the log level, repeatedly. So you
5025
* can run something like:
5126
*
52-
* node main.js -p 80 -vv 2>&1 | bunyan
27+
* node main.js -p 80 -vv 2>&1 | npx pino-pretty
5328
*
5429
* And the log level will be set to TRACE.
5530
*/
@@ -79,9 +54,9 @@ function parseOptions() {
7954
case 'v':
8055
// Allows us to set -vvv -> this little hackery
8156
// just ensures that we're never < TRACE
82-
LOG.level(Math.max(bunyan.TRACE, LOG.level() - 10));
57+
LOG.level(Math.max(pino.levels.values.trace, LOG.level - 10));
8358

84-
if (LOG.level() <= bunyan.DEBUG) {
59+
if (LOG.level <= pino.levels.values.debug) {
8560
LOG = LOG.child({ src: true });
8661
}
8762
break;

‎examples/todoapp/package.json

+5-4
Original file line numberDiff line numberDiff line change
@@ -5,16 +5,17 @@
55
"main": "main.js",
66
"dependencies": {
77
"assert-plus": "0.2.0",
8-
"bunyan": "1.8.13",
8+
"pino": "^6.3.2",
99
"posix-getopt": "1.2.0",
10-
"restify-errors": "^3.1.0",
10+
"restify-errors": "^4.0.0",
1111
"restify": "^4.0.3"
1212
},
1313
"devDependencies": {
14-
"nodeunit": "0.9.1"
14+
"nodeunit": "0.9.1",
15+
"pino-pretty": "^4.0.0"
1516
},
1617
"scripts": {
17-
"start": "node main.js 2>&1 | bunyan",
18+
"start": "node main.js 2>&1 | pino-pretty",
1819
"test": "nodeunit test"
1920
},
2021
"author": "Mark Cavage",

‎examples/todoapp/test/todo.test.js

+3-5
Original file line numberDiff line numberDiff line change
@@ -2,7 +2,7 @@
22

33
var fs = require('fs');
44

5-
var bunyan = require('bunyan');
5+
var pino = require('pino');
66
var restify = require('restify');
77

88
var todo = require('../lib');
@@ -17,11 +17,9 @@ var SOCK = '/tmp/.todo_sock';
1717
///--- Tests
1818

1919
exports.setup = function(t) {
20-
var log = bunyan.createLogger({
20+
var log = pino({
2121
name: 'todo_unit_test',
22-
level: process.env.LOG_LEVEL || 'info',
23-
serializers: restify.bunyan.serializers,
24-
stream: process.stdout
22+
level: process.env.LOG_LEVEL || 'info'
2523
});
2624

2725
fs.mkdir(DIR, function(err) {

‎lib/bunyan_helper.js

-299
This file was deleted.

‎lib/index.js

+6-6
Original file line numberDiff line numberDiff line change
@@ -5,7 +5,7 @@
55
var assert = require('assert-plus');
66
var errors = require('restify-errors');
77

8-
var bunyan = require('./bunyan_helper');
8+
var pino = require('pino');
99
var Router = require('./router');
1010
var Server = require('./server');
1111
var shallowCopy = require('./utils').shallowCopy;
@@ -22,8 +22,8 @@ var InternalError = errors.InternalError;
2222
* @param {String} [options.name="restify"] - Name of the server.
2323
* @param {Boolean} [options.dtrace=false] - enable DTrace support
2424
* @param {Router} [options.router=new Router(opts)] - Router
25-
* @param {Object} [options.log=bunyan.createLogger(options.name || "restify")]
26-
* - [bunyan](https://github.com/trentm/node-bunyan) instance.
25+
* @param {Object} [options.log=pino({name:options.name || "restify"})]
26+
* - [pino](https://github.com/pinojs/pino) instance.
2727
* @param {String} [options.url] - Once listen() is called, this will be filled
2828
* in with where the server is running.
2929
* @param {String|Buffer} [options.certificate] - If you want to create an HTTPS
@@ -35,7 +35,7 @@ var InternalError = errors.InternalError;
3535
* @param {Boolean} [options.handleUncaughtExceptions=false] - When true restify
3636
* will use a domain to catch and respond to any uncaught
3737
* exceptions that occur in it's handler stack.
38-
* [bunyan](https://github.com/trentm/node-bunyan) instance.
38+
* [pino](https://github.com/pinojs/pino) instance.
3939
* response header, default is `restify`. Pass empty string to unset the header.
4040
* Comes with significant negative performance impact.
4141
* @param {Object} [options.spdy] - Any options accepted by
@@ -80,7 +80,7 @@ function createServer(options) {
8080

8181
// empty string should override default value.
8282
opts.name = opts.hasOwnProperty('name') ? opts.name : 'restify';
83-
opts.log = opts.log || bunyan.createLogger(opts.name || 'restify');
83+
opts.log = opts.log || pino({ name: opts.name || 'restify' });
8484
opts.router = opts.router || new Router(opts);
8585

8686
server = new Server(opts);
@@ -109,7 +109,7 @@ function createServer(options) {
109109

110110
///--- Exports
111111

112-
module.exports.bunyan = bunyan;
112+
module.exports.logger = pino;
113113
module.exports.createServer = createServer;
114114
module.exports.formatters = require('./formatters');
115115
module.exports.plugins = require('./plugins');

‎lib/plugins/audit.js

+8-8
Original file line numberDiff line numberDiff line change
@@ -3,7 +3,7 @@
33
'use strict';
44

55
var assert = require('assert-plus');
6-
var bunyan = require('bunyan');
6+
var pino = require('pino');
77
var HttpError = require('restify-errors').HttpError;
88
var errors = require('restify-errors');
99
var hrTimeDurationInMs = require('./utils/hrTimeDurationInMs');
@@ -61,10 +61,10 @@ function getResponseHeaders(res) {
6161
* </caption>
6262
*
6363
* server.on('after', restify.plugins.auditLogger({
64-
* log: bunyan.createLogger({
65-
* name: 'audit',
66-
* stream: process.stdout
67-
* }),
64+
* log: pino(
65+
* {name: 'audit'},
66+
* process.stdout
67+
* ),
6868
* event: 'after',
6969
* server: SERVER,
7070
* logMetrics : logBuffer,
@@ -73,7 +73,7 @@ function getResponseHeaders(res) {
7373
*
7474
* @example
7575
* <caption>
76-
* You pass in the auditor a bunyan logger, optionally server object,
76+
* You pass in the auditor a pino logger, optionally server object,
7777
* Ringbuffer and a flag printLog indicate if log needs to be print out at info
7878
* level or not. By default, without specify printLog flag, it will write out
7979
* record lookling like this:
@@ -103,7 +103,7 @@ function getResponseHeaders(res) {
103103
* "trailers": {},
104104
* "version": "*",
105105
* "timers": {
106-
* "bunyan": 52,
106+
* "requestLogger": 52,
107107
* "saveAction": 8,
108108
* "reqResTracker": 213,
109109
* "addContext": 8,
@@ -199,7 +199,7 @@ function auditLogger(opts) {
199199
if (typeof printLog === 'undefined') {
200200
printLog = true;
201201
}
202-
var errSerializer = bunyan.stdSerializers.err;
202+
var errSerializer = pino.stdSerializers.err;
203203

204204
// don't break legacy use, where there was no top level opts.serializer
205205
if (opts.log.serializers && opts.log.serializers.err) {

‎lib/plugins/index.js

+1-1
Original file line numberDiff line numberDiff line change
@@ -24,7 +24,7 @@ module.exports = {
2424
queryParser: require('./query'),
2525
metrics: require('./metrics'),
2626
requestExpiry: require('./requestExpiry'),
27-
requestLogger: require('./bunyan'),
27+
requestLogger: require('./requestLogger'),
2828
serveStatic: require('./static'),
2929
serveStaticFiles: require('./staticFiles'),
3030
throttle: require('./throttle'),

‎lib/plugins/bunyan.js ‎lib/plugins/requestLogger.js

+2-2
Original file line numberDiff line numberDiff line change
@@ -9,7 +9,7 @@ var shallowCopy = require('./utils/shallowCopy');
99
///--- API
1010

1111
/**
12-
* Sets up a child [bunyan](https://github.com/trentm/node-bunyan) logger with
12+
* Sets up a child [logger](https://github.com/pinojs/pino) logger with
1313
* the current request id filled in, along with any other parameters you define.
1414
*
1515
* You can pass in no options to this, in which case only the request id will be
@@ -52,7 +52,7 @@ function requestLogger(options) {
5252

5353
var headersToCopy = opts.headers || [];
5454

55-
return function bunyan(req, res, next) {
55+
return function logger(req, res, next) {
5656
if (!req.log && !opts.log) {
5757
next();
5858
return;

‎lib/server.js

+2-2
Original file line numberDiff line numberDiff line change
@@ -47,7 +47,7 @@ var sprintf = util.format;
4747
* @param {String} options.name - Name of the server.
4848
* @param {Boolean} [options.dtrace=false] - enable DTrace support
4949
* @param {Router} options.router - Router
50-
* @param {Object} options.log - [bunyan](https://github.com/trentm/node-bunyan)
50+
* @param {Object} options.log - [pino](https://github.com/pinojs/pino)
5151
* instance.
5252
* @param {String} [options.url] - Once listen() is called, this will be filled
5353
* in with where the server is running.
@@ -61,7 +61,7 @@ var sprintf = util.format;
6161
* will use a domain to catch and respond to any uncaught
6262
* exceptions that occur in it's handler stack.
6363
* Comes with significant negative performance impact.
64-
* [bunyan](https://github.com/trentm/node-bunyan) instance.
64+
* [pino](https://github.com/pinojs/pino) instance.
6565
* response header, default is `restify`. Pass empty string to unset the header.
6666
* @param {Object} [options.spdy] - Any options accepted by
6767
* [node-spdy](https://github.com/indutny/node-spdy).

‎package.json

+1-1
Original file line numberDiff line numberDiff line change
@@ -94,7 +94,6 @@
9494
},
9595
"dependencies": {
9696
"assert-plus": "^1.0.0",
97-
"bunyan": "^1.8.12",
9897
"csv": "^5.1.1",
9998
"escape-regexp-component": "^1.0.2",
10099
"ewma": "^2.0.1",
@@ -107,6 +106,7 @@
107106
"negotiator": "^0.6.2",
108107
"once": "^1.4.0",
109108
"pidusage": "^2.0.17",
109+
"pino": "^6.3.2",
110110
"qs": "^6.7.0",
111111
"restify-errors": "^8.0.2",
112112
"semver": "^6.1.1",

‎test/lib/helper.js

+9-10
Original file line numberDiff line numberDiff line change
@@ -9,11 +9,9 @@
99

1010
var domain = require('domain');
1111

12-
var bunyan = require('bunyan');
12+
var pino = require('pino');
1313
var once = require('once');
1414

15-
var restify = require('../../lib');
16-
1715
///--- Exports
1816

1917
module.exports = {
@@ -74,13 +72,14 @@ module.exports = {
7472
},
7573

7674
getLog: function(name, streams, level) {
77-
return bunyan.createLogger({
78-
level: process.env.LOG_LEVEL || level || 'fatal',
79-
name: name || process.argv[1],
80-
streams: streams || [{ stream: process.stdout }],
81-
src: true,
82-
serializers: restify.bunyan.serializers
83-
});
75+
return pino(
76+
{
77+
level: process.env.LOG_LEVEL || level || 'fatal',
78+
name: name || process.argv[1],
79+
serializers: pino.stdSerializers
80+
},
81+
streams || process.stdout
82+
);
8483
},
8584

8685
get dtrace() {

‎test/lib/streamRecorder.js

+23
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,23 @@
1+
'use strict';
2+
3+
const stream = require('stream');
4+
5+
class StreamRecorder extends stream.Writable {
6+
constructor(options) {
7+
options = options || {};
8+
super(options);
9+
this.flushRecords();
10+
}
11+
12+
_write(chunk, encoding, callback) {
13+
const record = JSON.parse(chunk.toString());
14+
this.records.push(record);
15+
callback();
16+
}
17+
18+
flushRecords() {
19+
this.records = [];
20+
}
21+
}
22+
23+
module.exports = StreamRecorder;

‎test/plugins/audit.test.js

+40-143
Original file line numberDiff line numberDiff line change
@@ -6,13 +6,14 @@ var PassThrough = require('stream').PassThrough;
66

77
// external requires
88
var assert = require('chai').assert;
9-
var bunyan = require('bunyan');
9+
var pino = require('pino');
1010
var lodash = require('lodash');
1111
var restify = require('../../lib/index.js');
1212
var restifyClients = require('restify-clients');
1313

1414
// local files
1515
var helper = require('../lib/helper');
16+
var StreamRecorder = require('../lib/streamRecorder');
1617
var vasync = require('vasync');
1718

1819
// local globals
@@ -51,22 +52,12 @@ describe('audit logger', function() {
5152
});
5253

5354
it('audit logger should print log by default', function(done) {
54-
var logBuffer = new bunyan.RingBuffer({
55-
limit: 1000
56-
});
55+
var logBuffer = new StreamRecorder();
5756
var collectLog;
5857
SERVER.on(
5958
'after',
6059
restify.plugins.auditLogger({
61-
log: bunyan.createLogger({
62-
name: 'audit',
63-
streams: [
64-
{
65-
level: 'info',
66-
stream: process.stdout
67-
}
68-
]
69-
}),
60+
log: pino({ name: 'audit' }, logBuffer),
7061
server: SERVER,
7162
event: 'after'
7263
})
@@ -126,15 +117,7 @@ describe('audit logger', function() {
126117
SERVER.once(
127118
'after',
128119
restify.plugins.auditLogger({
129-
log: bunyan.createLogger({
130-
name: 'audit',
131-
streams: [
132-
{
133-
level: 'info',
134-
stream: process.stdout
135-
}
136-
]
137-
}),
120+
log: pino({ name: 'audit' }),
138121
server: SERVER,
139122
event: 'after'
140123
})
@@ -166,22 +149,13 @@ describe('audit logger', function() {
166149
});
167150

168151
it('test custom serializers', function(done) {
169-
// Dirty hack to capture the log record using a ring buffer.
170-
var ringbuffer = new bunyan.RingBuffer({ limit: 1 });
152+
// capture the log record
153+
var buffer = new StreamRecorder();
171154

172155
SERVER.once(
173156
'after',
174157
restify.plugins.auditLogger({
175-
log: bunyan.createLogger({
176-
name: 'audit',
177-
streams: [
178-
{
179-
level: 'info',
180-
type: 'raw',
181-
stream: ringbuffer
182-
}
183-
]
184-
}),
158+
log: pino({ name: 'audit' }, buffer),
185159
event: 'after',
186160
serializers: {
187161
req: function(req) {
@@ -200,7 +174,7 @@ describe('audit logger', function() {
200174
});
201175

202176
SERVER.on('after', function() {
203-
var record = ringbuffer.records && ringbuffer.records[0];
177+
var record = buffer.records && buffer.records[0];
204178
assert.equal(record.req.fooReq, 'barReq');
205179
assert.equal(record.res.fooRes, 'barRes');
206180
done();
@@ -212,23 +186,14 @@ describe('audit logger', function() {
212186
});
213187

214188
it('should log handler timers', function(done) {
215-
// Dirty hack to capture the log record using a ring buffer.
216-
var ringbuffer = new bunyan.RingBuffer({ limit: 1 });
189+
// capture the log record
190+
var buffer = new StreamRecorder();
217191
var WAIT_IN_MILLISECONDS = 1100;
218192

219193
SERVER.once(
220194
'after',
221195
restify.plugins.auditLogger({
222-
log: bunyan.createLogger({
223-
name: 'audit',
224-
streams: [
225-
{
226-
level: 'info',
227-
type: 'raw',
228-
stream: ringbuffer
229-
}
230-
]
231-
}),
196+
log: pino({ name: 'audit' }, buffer),
232197
event: 'after'
233198
})
234199
);
@@ -246,12 +211,12 @@ describe('audit logger', function() {
246211
});
247212

248213
SERVER.on('after', function() {
249-
var record = ringbuffer.records && ringbuffer.records[0];
214+
var record = buffer.records && buffer.records[0];
250215

251216
// check timers
252217
assert.ok(record, 'no log records');
253218
assert.equal(
254-
ringbuffer.records.length,
219+
buffer.records.length,
255220
1,
256221
'should only have 1 log record'
257222
);
@@ -290,23 +255,14 @@ describe('audit logger', function() {
290255
it('should log anonymous handler timers', function(done) {
291256
this.timeout(5000);
292257

293-
// Dirty hack to capture the log record using a ring buffer.
294-
var ringbuffer = new bunyan.RingBuffer({ limit: 1 });
258+
// capture the log record
259+
var buffer = new StreamRecorder();
295260
var WAIT_IN_MILLISECONDS = 1000;
296261

297262
SERVER.once(
298263
'after',
299264
restify.plugins.auditLogger({
300-
log: bunyan.createLogger({
301-
name: 'audit',
302-
streams: [
303-
{
304-
level: 'info',
305-
type: 'raw',
306-
stream: ringbuffer
307-
}
308-
]
309-
}),
265+
log: pino({ name: 'audit' }, buffer),
310266
event: 'after'
311267
})
312268
);
@@ -345,10 +301,10 @@ describe('audit logger', function() {
345301

346302
SERVER.on('after', function() {
347303
// check timers
348-
var record = ringbuffer.records && ringbuffer.records[0];
304+
var record = buffer.records && buffer.records[0];
349305
assert.ok(record, 'no log records');
350306
assert.equal(
351-
ringbuffer.records.length,
307+
buffer.records.length,
352308
1,
353309
'should only have 1 log record'
354310
);
@@ -415,23 +371,14 @@ describe('audit logger', function() {
415371
});
416372

417373
it('restify-GH-1435 should accumulate log handler timers', function(done) {
418-
// Dirty hack to capture the log record using a ring buffer.
419-
var ringbuffer = new bunyan.RingBuffer({ limit: 1 });
374+
// capture the log record
375+
var buffer = new StreamRecorder();
420376
var WAIT_IN_MILLISECONDS = 1100;
421377

422378
SERVER.once(
423379
'after',
424380
restify.plugins.auditLogger({
425-
log: bunyan.createLogger({
426-
name: 'audit',
427-
streams: [
428-
{
429-
level: 'info',
430-
type: 'raw',
431-
stream: ringbuffer
432-
}
433-
]
434-
}),
381+
log: pino({ name: 'audit' }, buffer),
435382
event: 'after'
436383
})
437384
);
@@ -452,12 +399,12 @@ describe('audit logger', function() {
452399
});
453400

454401
SERVER.on('after', function() {
455-
var record = ringbuffer.records && ringbuffer.records[0];
402+
var record = buffer.records && buffer.records[0];
456403

457404
// check timers
458405
assert.ok(record, 'no log records');
459406
assert.equal(
460-
ringbuffer.records.length,
407+
buffer.records.length,
461408
1,
462409
'should only have 1 log record'
463410
);
@@ -482,22 +429,13 @@ describe('audit logger', function() {
482429
});
483430

484431
it('restify-GH-812 audit logger has query params string', function(done) {
485-
// Dirty hack to capture the log record using a ring buffer.
486-
var ringbuffer = new bunyan.RingBuffer({ limit: 1 });
432+
// capture the log record
433+
var buffer = new StreamRecorder();
487434

488435
SERVER.once(
489436
'after',
490437
restify.plugins.auditLogger({
491-
log: bunyan.createLogger({
492-
name: 'audit',
493-
streams: [
494-
{
495-
level: 'info',
496-
type: 'raw',
497-
stream: ringbuffer
498-
}
499-
]
500-
}),
438+
log: pino({ name: 'audit' }, buffer),
501439
event: 'after'
502440
})
503441
);
@@ -509,13 +447,13 @@ describe('audit logger', function() {
509447

510448
SERVER.on('after', function() {
511449
// check timers
512-
assert.ok(ringbuffer.records[0], 'no log records');
450+
assert.ok(buffer.records[0], 'no log records');
513451
assert.equal(
514-
ringbuffer.records.length,
452+
buffer.records.length,
515453
1,
516454
'should only have 1 log record'
517455
);
518-
assert.ok(ringbuffer.records[0].req.query, 'a=1&b=2');
456+
assert.ok(buffer.records[0].req.query, 'a=1&b=2');
519457
done();
520458
});
521459

@@ -525,22 +463,13 @@ describe('audit logger', function() {
525463
});
526464

527465
it('restify-GH-812 audit logger has query params obj', function(done) {
528-
// Dirty hack to capture the log record using a ring buffer.
529-
var ringbuffer = new bunyan.RingBuffer({ limit: 1 });
466+
// capture the log record using a buffer.
467+
var buffer = new StreamRecorder();
530468

531469
SERVER.once(
532470
'after',
533471
restify.plugins.auditLogger({
534-
log: bunyan.createLogger({
535-
name: 'audit',
536-
streams: [
537-
{
538-
level: 'info',
539-
type: 'raw',
540-
stream: ringbuffer
541-
}
542-
]
543-
}),
472+
log: pino({ name: 'audit' }, buffer),
544473
event: 'after'
545474
})
546475
);
@@ -555,13 +484,13 @@ describe('audit logger', function() {
555484

556485
SERVER.on('after', function() {
557486
// check timers
558-
assert.ok(ringbuffer.records[0], 'no log records');
487+
assert.ok(buffer.records[0], 'no log records');
559488
assert.equal(
560-
ringbuffer.records.length,
489+
buffer.records.length,
561490
1,
562491
'should only have 1 log record'
563492
);
564-
assert.deepEqual(ringbuffer.records[0].req.query, {
493+
assert.deepEqual(buffer.records[0].req.query, {
565494
a: '1',
566495
b: '2'
567496
});
@@ -579,15 +508,7 @@ describe('audit logger', function() {
579508
SERVER.once(
580509
'pre',
581510
restify.plugins.auditLogger({
582-
log: bunyan.createLogger({
583-
name: 'audit',
584-
streams: [
585-
{
586-
level: 'info',
587-
stream: ptStream
588-
}
589-
]
590-
}),
511+
log: pino({ name: 'audit' }, ptStream),
591512
event: 'pre'
592513
})
593514
);
@@ -620,15 +541,7 @@ describe('audit logger', function() {
620541
SERVER.once(
621542
'routed',
622543
restify.plugins.auditLogger({
623-
log: bunyan.createLogger({
624-
name: 'audit',
625-
streams: [
626-
{
627-
level: 'info',
628-
stream: ptStream
629-
}
630-
]
631-
}),
544+
log: pino({ name: 'audit' }, ptStream),
632545
event: 'routed'
633546
})
634547
);
@@ -659,15 +572,7 @@ describe('audit logger', function() {
659572
SERVER.once(
660573
'after',
661574
restify.plugins.auditLogger({
662-
log: bunyan.createLogger({
663-
name: 'audit',
664-
streams: [
665-
{
666-
level: 'info',
667-
stream: process.stdout
668-
}
669-
]
670-
}),
575+
log: pino({ name: 'audit' }),
671576
context: function(req, res, route, err) {
672577
return {
673578
qs: req.getQuery()
@@ -704,15 +609,7 @@ describe('audit logger', function() {
704609
SERVER.once(
705610
'after',
706611
restify.plugins.auditLogger({
707-
log: bunyan.createLogger({
708-
name: 'audit',
709-
streams: [
710-
{
711-
level: 'info',
712-
stream: process.stdout
713-
}
714-
]
715-
}),
612+
log: pino({ name: 'audit' }),
716613
server: SERVER,
717614
event: 'after'
718615
})

‎test/plugins/plugins.test.js

+4-2
Original file line numberDiff line numberDiff line change
@@ -4,6 +4,7 @@
44
/* eslint-disable func-names */
55

66
// external requires
7+
var pino = require('pino');
78
var assert = require('chai').assert;
89
var restify = require('../../lib/index.js');
910
var restifyClients = require('restify-clients');
@@ -76,8 +77,9 @@ describe('all other plugins', function() {
7677

7778
SERVER.use(restify.plugins.requestLogger({ headers: headers }));
7879
SERVER.get(getPath, function(req, res, next) {
79-
assert.equal(req.log.fields[key], 'foo-for-eva');
80-
assert.equal(req.log.fields.hasOwnProperty(badKey), false);
80+
var childings = req.log[pino.symbols.chindingsSym];
81+
assert.match(childings, /"x-request-uuid":"foo-for-eva"/);
82+
assert.notMatch(childings, /x-foo-bar/);
8183
res.send();
8284
next();
8385
});

‎test/server.test.js

+9-60
Original file line numberDiff line numberDiff line change
@@ -4,10 +4,9 @@
44
/* eslint-disable func-names */
55

66
var assert = require('assert-plus');
7-
var bunyan = require('bunyan');
7+
var pino = require('pino');
88
var childprocess = require('child_process');
99
var http = require('http');
10-
var stream = require('stream');
1110

1211
var errors = require('restify-errors');
1312
var restifyClients = require('restify-clients');
@@ -20,6 +19,7 @@ if (require.cache[__dirname + '/lib/helper.js']) {
2019
delete require.cache[__dirname + '/lib/helper.js'];
2120
}
2221
var helper = require('./lib/helper.js');
22+
var StreamRecorder = require('./lib/streamRecorder');
2323

2424
///--- Globals
2525

@@ -1519,20 +1519,11 @@ test(
15191519
]);
15201520

15211521
// set up audit logs
1522-
var ringbuffer = new bunyan.RingBuffer({ limit: 1 });
1522+
var buffer = new StreamRecorder();
15231523
SERVER.on(
15241524
'after',
15251525
restify.plugins.auditLogger({
1526-
log: bunyan.createLogger({
1527-
name: 'audit',
1528-
streams: [
1529-
{
1530-
level: 'info',
1531-
type: 'raw',
1532-
stream: ringbuffer
1533-
}
1534-
]
1535-
}),
1526+
log: pino({ name: 'audit' }, buffer),
15361527
event: 'after'
15371528
})
15381529
);
@@ -1544,18 +1535,15 @@ test(
15441535
t.equal(err.name, 'RequestCloseError');
15451536

15461537
// check records
1547-
t.ok(ringbuffer.records[0], 'no log records');
1538+
t.ok(buffer.records[0], 'no log records');
15481539
t.equal(
1549-
ringbuffer.records.length,
1540+
buffer.records.length,
15501541
1,
15511542
'should only have 1 log record'
15521543
);
1553-
// TODO: fix this after plugin is fixed to use
1554-
// req.connectionState()
1555-
// t.equal(ringbuffer.records[0].req.clientClosed, true);
15561544

15571545
// check timers
1558-
var handlers = Object.keys(ringbuffer.records[0].req.timers);
1546+
var handlers = Object.keys(buffer.records[0].req.timers);
15591547
t.equal(handlers.length, 2, 'should only have 2 req timers');
15601548
t.equal(
15611549
handlers[0],
@@ -1583,6 +1571,8 @@ test(
15831571

15841572
// reset numCount
15851573
numCount = 0;
1574+
//reset stream-recorder
1575+
buffer.flushRecords();
15861576

15871577
FAST_CLIENT.get('/audit?v=2', function(err2, req2, res2, data2) {
15881578
t.ok(err2);
@@ -1669,47 +1659,6 @@ test('GH-667 returning error in error handler should not do anything', function(
16691659
});
16701660
});
16711661

1672-
test('GH-958 RCS does not write triggering record', function(t) {
1673-
var passThrough = new stream.PassThrough();
1674-
var count = 1;
1675-
// we would expect to get 3 logging statements
1676-
passThrough.on('data', function(chunk) {
1677-
var obj = JSON.parse(chunk.toString());
1678-
t.equal(obj.msg, count.toString());
1679-
1680-
if (count === 3) {
1681-
t.end();
1682-
}
1683-
count++;
1684-
});
1685-
1686-
SERVER.log = helper.getLog('server', [
1687-
{
1688-
level: bunyan.DEBUG,
1689-
type: 'raw',
1690-
stream: new restify.bunyan.RequestCaptureStream({
1691-
level: bunyan.WARN,
1692-
stream: passThrough
1693-
})
1694-
}
1695-
]);
1696-
1697-
SERVER.use(restify.plugins.requestLogger());
1698-
1699-
SERVER.get('/rcs', function(req, res, next) {
1700-
req.log.debug('1');
1701-
req.log.info('2');
1702-
req.log.error('3');
1703-
res.send();
1704-
next();
1705-
});
1706-
1707-
CLIENT.get('/rcs', function(err, _, res) {
1708-
t.ifError(err);
1709-
t.equal(res.statusCode, 200);
1710-
});
1711-
});
1712-
17131662
test('GH-1024 disable uncaughtException handler', function(t) {
17141663
// With uncaughtException handling disabled, the node process will abort,
17151664
// so testing of this feature must occur in a separate node process.

‎tools/docsBuild.js

+1-1
Original file line numberDiff line numberDiff line change
@@ -55,7 +55,7 @@ var docsConfig = [
5555
path.join(__dirname, LIB_PATH, 'plugins/query.js'),
5656
path.join(__dirname, LIB_PATH, 'plugins/jsonp.js'),
5757
path.join(__dirname, LIB_PATH, 'plugins/bodyParser.js'),
58-
path.join(__dirname, LIB_PATH, 'plugins/bunyan.js'),
58+
path.join(__dirname, LIB_PATH, 'plugins/requestLogger.js'),
5959
path.join(__dirname, LIB_PATH, 'plugins/gzip.js'),
6060
path.join(__dirname, LIB_PATH, 'plugins/static.js'),
6161
path.join(__dirname, LIB_PATH, 'plugins/staticFiles.js'),

0 commit comments

Comments
 (0)
Please sign in to comment.