Skip to content

Commit

Permalink
feat!: use req.log on audit plugin
Browse files Browse the repository at this point in the history 
So it's consistent with other plugins, and to allow child loggers
attached to req to be used on audit.
  • Loading branch information
@mmarchini
mmarchini committed Jan 17, 2023
1 parent 2053ef6 commit 528ecbc
Show file tree
Hide file tree
Showing 3 changed files with 44 additions and 56 deletions.
22 changes: 11 additions & 11 deletions lib/plugins/audit.js
View file
Original file line number Diff line number Diff line change
Expand Up @@ -260,16 +260,6 @@ function auditLogger(opts) {

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

var log = opts.log.child(
{
audit: true,
component: opts.event
},
{
serializers: serializers
}
);

function audit(req, res, route, err) {
var latency = res.get('Response-Time');

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

if (printLog) {
const origLog = (req && req.log) || opts.log;
if (printLog && origLog) {
const log = origLog.child(
{
audit: true,
component: opts.event
},
{
serializers: serializers
}
);
switch (opts.event) {
case 'after':
log.info(obj, 'handled: %d', res.statusCode);
Expand Down
61 changes: 24 additions & 37 deletions test/plugins/audit.test.js
View file
Original file line number Diff line number Diff line change
Expand Up @@ -22,16 +22,18 @@ var TOLERATED_MICROSECONDS = MILLISECOND_IN_MICROSECONDS;
var SERVER;
var CLIENT;
var PORT;
let LOG_BUFFER;

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

describe('audit logger', function() {
beforeEach(function(done) {
LOG_BUFFER = new StreamRecorder();
SERVER = restify.createServer({
dtrace: helper.dtrace,
log: helper.getLog('server')
log: helper.getLog('server', LOG_BUFFER, 'info')
});

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

it('audit logger should print log by default', function(done) {
var logBuffer = new StreamRecorder();
var collectLog;
SERVER.on(
'after',
restify.plugins.auditLogger({
log: pino({ name: 'audit' }, logBuffer),
log: pino({ name: 'audit' }),
server: SERVER,
event: 'after'
})
Expand All @@ -76,7 +77,7 @@ describe('audit logger', function() {
SERVER.get('/auditrecords', function(req, res, next) {
// strip log records of req/res as they will cause
// serialization issues.
var data = logBuffer.records.map(function(record) {
var data = LOG_BUFFER.records.map(function(record) {
return lodash.omit(record, 'req', 'res');
}, []);
res.send(200, data);
Expand Down Expand Up @@ -149,13 +150,10 @@ describe('audit logger', function() {
});

it('test custom serializers', function(done) {
// capture the log record
var buffer = new StreamRecorder();

SERVER.once(
'after',
restify.plugins.auditLogger({
log: pino({ name: 'audit' }, buffer),
log: pino({ name: 'audit' }),
event: 'after',
serializers: {
req: function(req) {
Expand All @@ -174,7 +172,7 @@ describe('audit logger', function() {
});

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

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

SERVER.once(
'after',
restify.plugins.auditLogger({
log: pino({ name: 'audit' }, buffer),
log: pino({ name: 'audit' }),
event: 'after'
})
);
Expand All @@ -211,12 +207,12 @@ describe('audit logger', function() {
});

SERVER.on('after', function() {
var record = buffer.records && buffer.records[0];
var record = LOG_BUFFER.records && LOG_BUFFER.records[0];

// check timers
assert.ok(record, 'no log records');
assert.equal(
buffer.records.length,
LOG_BUFFER.records.length,
1,
'should only have 1 log record'
);
Expand Down Expand Up @@ -255,14 +251,12 @@ describe('audit logger', function() {
it('should log anonymous handler timers', function(done) {
this.timeout(5000);

// capture the log record
var buffer = new StreamRecorder();
var WAIT_IN_MILLISECONDS = 1000;

SERVER.once(
'after',
restify.plugins.auditLogger({
log: pino({ name: 'audit' }, buffer),
log: pino({ name: 'audit' }),
event: 'after'
})
);
Expand Down Expand Up @@ -301,10 +295,10 @@ describe('audit logger', function() {

SERVER.on('after', function() {
// check timers
var record = buffer.records && buffer.records[0];
var record = LOG_BUFFER.records && LOG_BUFFER.records[0];
assert.ok(record, 'no log records');
assert.equal(
buffer.records.length,
LOG_BUFFER.records.length,
1,
'should only have 1 log record'
);
Expand Down Expand Up @@ -372,13 +366,12 @@ describe('audit logger', function() {

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

SERVER.once(
'after',
restify.plugins.auditLogger({
log: pino({ name: 'audit' }, buffer),
log: pino({ name: 'audit' }),
event: 'after'
})
);
Expand All @@ -399,12 +392,12 @@ describe('audit logger', function() {
});

SERVER.on('after', function() {
var record = buffer.records && buffer.records[0];
var record = LOG_BUFFER.records && LOG_BUFFER.records[0];

// check timers
assert.ok(record, 'no log records');
assert.equal(
buffer.records.length,
LOG_BUFFER.records.length,
1,
'should only have 1 log record'
);
Expand All @@ -429,13 +422,10 @@ describe('audit logger', function() {
});

it('restify-GH-812 audit logger has query params string', function(done) {
// capture the log record
var buffer = new StreamRecorder();

SERVER.once(
'after',
restify.plugins.auditLogger({
log: pino({ name: 'audit' }, buffer),
log: pino({ name: 'audit' }),
event: 'after'
})
);
Expand All @@ -447,13 +437,13 @@ describe('audit logger', function() {

SERVER.on('after', function() {
// check timers
assert.ok(buffer.records[0], 'no log records');
assert.ok(LOG_BUFFER.records[0], 'no log records');
assert.equal(
buffer.records.length,
LOG_BUFFER.records.length,
1,
'should only have 1 log record'
);
assert.ok(buffer.records[0].req.query, 'a=1&b=2');
assert.ok(LOG_BUFFER.records[0].req.query, 'a=1&b=2');
done();
});

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

it('restify-GH-812 audit logger has query params obj', function(done) {
// capture the log record using a buffer.
var buffer = new StreamRecorder();

SERVER.once(
'after',
restify.plugins.auditLogger({
log: pino({ name: 'audit' }, buffer),
log: pino({ name: 'audit' }),
event: 'after'
})
);
Expand All @@ -484,13 +471,13 @@ describe('audit logger', function() {

SERVER.on('after', function() {
// check timers
assert.ok(buffer.records[0], 'no log records');
assert.ok(LOG_BUFFER.records[0], 'no log records');
assert.equal(
buffer.records.length,
LOG_BUFFER.records.length,
1,
'should only have 1 log record'
);
assert.deepEqual(buffer.records[0].req.query, {
assert.deepEqual(LOG_BUFFER.records[0].req.query, {
a: '1',
b: '2'
});
Expand Down
17 changes: 9 additions & 8 deletions test/server.test.js
View file
Original file line number Diff line number Diff line change
Expand Up @@ -4,10 +4,10 @@
/* eslint-disable func-names */

var assert = require('assert-plus');
var pino = require('pino');
var childprocess = require('child_process');
var http = require('http');

var pino = require('pino');
var errors = require('restify-errors');
var restifyClients = require('restify-clients');
var uuid = require('uuid');
Expand All @@ -32,6 +32,7 @@ var PORT = process.env.UNIT_TEST_PORT || 0;
var CLIENT;
var FAST_CLIENT;
var SERVER;
let LOG_BUFFER;

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

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

before(function(cb) {
try {
LOG_BUFFER = new StreamRecorder();
SERVER = restify.createServer({
dtrace: helper.dtrace,
handleUncaughtExceptions: true,
log: helper.getLog('server'),
log: helper.getLog('server', LOG_BUFFER, 'info'),
version: ['2.0.0', '0.5.4', '1.4.3'],
ignoreTrailingSlash: true
});
Expand Down Expand Up @@ -1327,11 +1329,10 @@ test(
]);

// set up audit logs
var buffer = new StreamRecorder();
SERVER.on(
'after',
restify.plugins.auditLogger({
log: pino({ name: 'audit' }, buffer),
log: pino({ name: 'audit' }),
event: 'after'
})
);
Expand All @@ -1343,15 +1344,15 @@ test(
t.equal(err.name, 'RequestCloseError');

// check records
t.ok(buffer.records[0], 'no log records');
t.ok(LOG_BUFFER.records[0], 'no log records');
t.equal(
buffer.records.length,
LOG_BUFFER.records.length,
1,
'should only have 1 log record'
);

// check timers
var handlers = Object.keys(buffer.records[0].req.timers);
var handlers = Object.keys(LOG_BUFFER.records[0].req.timers);
t.equal(handlers.length, 2, 'should only have 2 req timers');
t.equal(
handlers[0],
Expand Down Expand Up @@ -1380,7 +1381,7 @@ test(
// reset numCount
numCount = 0;
//reset stream-recorder
buffer.flushRecords();
LOG_BUFFER.flushRecords();

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

0 comments on commit 528ecbc

Please sign in to comment.