Skip to content

Commit 528ecbc

Browse files
mmarchinimmarchini
committed
feat!: use req.log on audit plugin
So it's consistent with other plugins, and to allow child loggers attached to req to be used on audit.
1 parent 2053ef6 commit 528ecbc

3 files changed

Lines changed: 44 additions & 56 deletions

File tree

‎lib/plugins/audit.js‎

Lines changed: 11 additions & 11 deletions
Original file line numberDiff line numberDiff line change
@@ -260,16 +260,6 @@ function auditLogger(opts) {
260260

261261
var serializers = Object.assign({}, DEFAULT_SERIALIZERS, opts.serializers);
262262

263-
var log = opts.log.child(
264-
{
265-
audit: true,
266-
component: opts.event
267-
},
268-
{
269-
serializers: serializers
270-
}
271-
);
272-
273263
function audit(req, res, route, err) {
274264
var latency = res.get('Response-Time');
275265

@@ -295,7 +285,17 @@ function auditLogger(opts) {
295285
obj.context = opts.context(req, res, route, err);
296286
}
297287

298-
if (printLog) {
288+
const origLog = (req && req.log) || opts.log;
289+
if (printLog && origLog) {
290+
const log = origLog.child(
291+
{
292+
audit: true,
293+
component: opts.event
294+
},
295+
{
296+
serializers: serializers
297+
}
298+
);
299299
switch (opts.event) {
300300
case 'after':
301301
log.info(obj, 'handled: %d', res.statusCode);

‎test/plugins/audit.test.js‎

Lines changed: 24 additions & 37 deletions
Original file line numberDiff line numberDiff line change
@@ -22,16 +22,18 @@ var TOLERATED_MICROSECONDS = MILLISECOND_IN_MICROSECONDS;
2222
var SERVER;
2323
var CLIENT;
2424
var PORT;
25+
let LOG_BUFFER;
2526

2627
function assertIsAtLeastWithTolerate(num1, num2, tolerate, msg) {
2728
assert.isAtLeast(num1, num2 - tolerate, msg + 'should be >= ' + num2);
2829
}
2930

3031
describe('audit logger', function() {
3132
beforeEach(function(done) {
33+
LOG_BUFFER = new StreamRecorder();
3234
SERVER = restify.createServer({
3335
dtrace: helper.dtrace,
34-
log: helper.getLog('server')
36+
log: helper.getLog('server', LOG_BUFFER, 'info')
3537
});
3638

3739
SERVER.listen(0, '127.0.0.1', function() {
@@ -52,12 +54,11 @@ describe('audit logger', function() {
5254
});
5355

5456
it('audit logger should print log by default', function(done) {
55-
var logBuffer = new StreamRecorder();
5657
var collectLog;
5758
SERVER.on(
5859
'after',
5960
restify.plugins.auditLogger({
60-
log: pino({ name: 'audit' }, logBuffer),
61+
log: pino({ name: 'audit' }),
6162
server: SERVER,
6263
event: 'after'
6364
})
@@ -76,7 +77,7 @@ describe('audit logger', function() {
7677
SERVER.get('/auditrecords', function(req, res, next) {
7778
// strip log records of req/res as they will cause
7879
// serialization issues.
79-
var data = logBuffer.records.map(function(record) {
80+
var data = LOG_BUFFER.records.map(function(record) {
8081
return lodash.omit(record, 'req', 'res');
8182
}, []);
8283
res.send(200, data);
@@ -149,13 +150,10 @@ describe('audit logger', function() {
149150
});
150151

151152
it('test custom serializers', function(done) {
152-
// capture the log record
153-
var buffer = new StreamRecorder();
154-
155153
SERVER.once(
156154
'after',
157155
restify.plugins.auditLogger({
158-
log: pino({ name: 'audit' }, buffer),
156+
log: pino({ name: 'audit' }),
159157
event: 'after',
160158
serializers: {
161159
req: function(req) {
@@ -174,7 +172,7 @@ describe('audit logger', function() {
174172
});
175173

176174
SERVER.on('after', function() {
177-
var record = buffer.records && buffer.records[0];
175+
var record = LOG_BUFFER.records && LOG_BUFFER.records[0];
178176
assert.equal(record.req.fooReq, 'barReq');
179177
assert.equal(record.res.fooRes, 'barRes');
180178
done();
@@ -186,14 +184,12 @@ describe('audit logger', function() {
186184
});
187185

188186
it('should log handler timers', function(done) {
189-
// capture the log record
190-
var buffer = new StreamRecorder();
191187
var WAIT_IN_MILLISECONDS = 1100;
192188

193189
SERVER.once(
194190
'after',
195191
restify.plugins.auditLogger({
196-
log: pino({ name: 'audit' }, buffer),
192+
log: pino({ name: 'audit' }),
197193
event: 'after'
198194
})
199195
);
@@ -211,12 +207,12 @@ describe('audit logger', function() {
211207
});
212208

213209
SERVER.on('after', function() {
214-
var record = buffer.records && buffer.records[0];
210+
var record = LOG_BUFFER.records && LOG_BUFFER.records[0];
215211

216212
// check timers
217213
assert.ok(record, 'no log records');
218214
assert.equal(
219-
buffer.records.length,
215+
LOG_BUFFER.records.length,
220216
1,
221217
'should only have 1 log record'
222218
);
@@ -255,14 +251,12 @@ describe('audit logger', function() {
255251
it('should log anonymous handler timers', function(done) {
256252
this.timeout(5000);
257253

258-
// capture the log record
259-
var buffer = new StreamRecorder();
260254
var WAIT_IN_MILLISECONDS = 1000;
261255

262256
SERVER.once(
263257
'after',
264258
restify.plugins.auditLogger({
265-
log: pino({ name: 'audit' }, buffer),
259+
log: pino({ name: 'audit' }),
266260
event: 'after'
267261
})
268262
);
@@ -301,10 +295,10 @@ describe('audit logger', function() {
301295

302296
SERVER.on('after', function() {
303297
// check timers
304-
var record = buffer.records && buffer.records[0];
298+
var record = LOG_BUFFER.records && LOG_BUFFER.records[0];
305299
assert.ok(record, 'no log records');
306300
assert.equal(
307-
buffer.records.length,
301+
LOG_BUFFER.records.length,
308302
1,
309303
'should only have 1 log record'
310304
);
@@ -372,13 +366,12 @@ describe('audit logger', function() {
372366

373367
it('restify-GH-1435 should accumulate log handler timers', function(done) {
374368
// capture the log record
375-
var buffer = new StreamRecorder();
376369
var WAIT_IN_MILLISECONDS = 1100;
377370

378371
SERVER.once(
379372
'after',
380373
restify.plugins.auditLogger({
381-
log: pino({ name: 'audit' }, buffer),
374+
log: pino({ name: 'audit' }),
382375
event: 'after'
383376
})
384377
);
@@ -399,12 +392,12 @@ describe('audit logger', function() {
399392
});
400393

401394
SERVER.on('after', function() {
402-
var record = buffer.records && buffer.records[0];
395+
var record = LOG_BUFFER.records && LOG_BUFFER.records[0];
403396

404397
// check timers
405398
assert.ok(record, 'no log records');
406399
assert.equal(
407-
buffer.records.length,
400+
LOG_BUFFER.records.length,
408401
1,
409402
'should only have 1 log record'
410403
);
@@ -429,13 +422,10 @@ describe('audit logger', function() {
429422
});
430423

431424
it('restify-GH-812 audit logger has query params string', function(done) {
432-
// capture the log record
433-
var buffer = new StreamRecorder();
434-
435425
SERVER.once(
436426
'after',
437427
restify.plugins.auditLogger({
438-
log: pino({ name: 'audit' }, buffer),
428+
log: pino({ name: 'audit' }),
439429
event: 'after'
440430
})
441431
);
@@ -447,13 +437,13 @@ describe('audit logger', function() {
447437

448438
SERVER.on('after', function() {
449439
// check timers
450-
assert.ok(buffer.records[0], 'no log records');
440+
assert.ok(LOG_BUFFER.records[0], 'no log records');
451441
assert.equal(
452-
buffer.records.length,
442+
LOG_BUFFER.records.length,
453443
1,
454444
'should only have 1 log record'
455445
);
456-
assert.ok(buffer.records[0].req.query, 'a=1&b=2');
446+
assert.ok(LOG_BUFFER.records[0].req.query, 'a=1&b=2');
457447
done();
458448
});
459449

@@ -463,13 +453,10 @@ describe('audit logger', function() {
463453
});
464454

465455
it('restify-GH-812 audit logger has query params obj', function(done) {
466-
// capture the log record using a buffer.
467-
var buffer = new StreamRecorder();
468-
469456
SERVER.once(
470457
'after',
471458
restify.plugins.auditLogger({
472-
log: pino({ name: 'audit' }, buffer),
459+
log: pino({ name: 'audit' }),
473460
event: 'after'
474461
})
475462
);
@@ -484,13 +471,13 @@ describe('audit logger', function() {
484471

485472
SERVER.on('after', function() {
486473
// check timers
487-
assert.ok(buffer.records[0], 'no log records');
474+
assert.ok(LOG_BUFFER.records[0], 'no log records');
488475
assert.equal(
489-
buffer.records.length,
476+
LOG_BUFFER.records.length,
490477
1,
491478
'should only have 1 log record'
492479
);
493-
assert.deepEqual(buffer.records[0].req.query, {
480+
assert.deepEqual(LOG_BUFFER.records[0].req.query, {
494481
a: '1',
495482
b: '2'
496483
});

‎test/server.test.js‎

Lines changed: 9 additions & 8 deletions
Original file line numberDiff line numberDiff line change
@@ -4,10 +4,10 @@
44
/* eslint-disable func-names */
55

66
var assert = require('assert-plus');
7-
var pino = require('pino');
87
var childprocess = require('child_process');
98
var http = require('http');
109

10+
var pino = require('pino');
1111
var errors = require('restify-errors');
1212
var restifyClients = require('restify-clients');
1313
var uuid = require('uuid');
@@ -32,6 +32,7 @@ var PORT = process.env.UNIT_TEST_PORT || 0;
3232
var CLIENT;
3333
var FAST_CLIENT;
3434
var SERVER;
35+
let LOG_BUFFER;
3536

3637
var NODE_MAJOR_VERSION = process.versions.node.split('.')[0];
3738

@@ -43,10 +44,11 @@ if (SKIP_IP_V6) {
4344

4445
before(function(cb) {
4546
try {
47+
LOG_BUFFER = new StreamRecorder();
4648
SERVER = restify.createServer({
4749
dtrace: helper.dtrace,
4850
handleUncaughtExceptions: true,
49-
log: helper.getLog('server'),
51+
log: helper.getLog('server', LOG_BUFFER, 'info'),
5052
version: ['2.0.0', '0.5.4', '1.4.3'],
5153
ignoreTrailingSlash: true
5254
});
@@ -1327,11 +1329,10 @@ test(
13271329
]);
13281330

13291331
// set up audit logs
1330-
var buffer = new StreamRecorder();
13311332
SERVER.on(
13321333
'after',
13331334
restify.plugins.auditLogger({
1334-
log: pino({ name: 'audit' }, buffer),
1335+
log: pino({ name: 'audit' }),
13351336
event: 'after'
13361337
})
13371338
);
@@ -1343,15 +1344,15 @@ test(
13431344
t.equal(err.name, 'RequestCloseError');
13441345

13451346
// check records
1346-
t.ok(buffer.records[0], 'no log records');
1347+
t.ok(LOG_BUFFER.records[0], 'no log records');
13471348
t.equal(
1348-
buffer.records.length,
1349+
LOG_BUFFER.records.length,
13491350
1,
13501351
'should only have 1 log record'
13511352
);
13521353

13531354
// check timers
1354-
var handlers = Object.keys(buffer.records[0].req.timers);
1355+
var handlers = Object.keys(LOG_BUFFER.records[0].req.timers);
13551356
t.equal(handlers.length, 2, 'should only have 2 req timers');
13561357
t.equal(
13571358
handlers[0],
@@ -1380,7 +1381,7 @@ test(
13801381
// reset numCount
13811382
numCount = 0;
13821383
//reset stream-recorder
1383-
buffer.flushRecords();
1384+
LOG_BUFFER.flushRecords();
13841385

13851386
FAST_CLIENT.get('/audit?v=2', function(err2, req2, res2, data2) {
13861387
t.ok(err2);

0 commit comments

Comments
 (0)