From 528ecbcec5d70c458749bdd4c4cc3f9e06ab69a2 Mon Sep 17 00:00:00 2001 From: Mary Marchini Date: Thu, 12 Jan 2023 15:49:03 -0800 Subject: [PATCH] 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. --- lib/plugins/audit.js | 22 +++++++------- test/plugins/audit.test.js | 61 +++++++++++++++----------------------- test/server.test.js | 17 ++++++----- 3 files changed, 44 insertions(+), 56 deletions(-) diff --git a/lib/plugins/audit.js b/lib/plugins/audit.js index 2fb726cb8..c0c0b8879 100644 --- a/lib/plugins/audit.js +++ b/lib/plugins/audit.js @@ -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'); @@ -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); diff --git a/test/plugins/audit.test.js b/test/plugins/audit.test.js index 0d949be12..a8499e460 100644 --- a/test/plugins/audit.test.js +++ b/test/plugins/audit.test.js @@ -22,6 +22,7 @@ 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); @@ -29,9 +30,10 @@ function assertIsAtLeastWithTolerate(num1, num2, tolerate, msg) { 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() { @@ -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' }) @@ -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); @@ -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) { @@ -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(); @@ -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' }) ); @@ -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' ); @@ -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' }) ); @@ -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' ); @@ -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' }) ); @@ -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' ); @@ -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' }) ); @@ -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(); }); @@ -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' }) ); @@ -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' }); diff --git a/test/server.test.js b/test/server.test.js index 291f6616a..2ae6b0445 100644 --- a/test/server.test.js +++ b/test/server.test.js @@ -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'); @@ -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]; @@ -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 }); @@ -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' }) ); @@ -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], @@ -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);