diff --git a/logger.js b/logger.js index 4cb7931..9de1f61 100644 --- a/logger.js +++ b/logger.js @@ -5,6 +5,7 @@ const serializers = require('pino-std-serializers') const getCallerFile = require('get-caller-file') const URL = require('fast-url-parser') const startTime = Symbol('startTime') +const reqObject = Symbol('reqObject') function pinoLogger (opts, stream) { if (opts && opts._writableState) { @@ -86,7 +87,7 @@ function pinoLogger (opts, stream) { this.removeListener('error', onResFinished) this.removeListener('finish', onResFinished) - const log = this.log + let log = this.log const responseTime = Date.now() - this[startTime] const level = getLogLevelFromCustomLogLevel(customLogLevel, useLevel, this, err) @@ -94,6 +95,14 @@ function pinoLogger (opts, stream) { return } + const req = this[reqObject] + const res = this + + const customPropBindings = (typeof customProps === 'function') ? customProps(req, res) : customProps + if (customPropBindings) { + log = this.log.child(customPropBindings) + } + if (err || this.err || this.statusCode >= 500) { const error = err || this.err || new Error('failed with status code ' + this.statusCode) @@ -128,6 +137,8 @@ function pinoLogger (opts, stream) { req.log = quietReqLogger ? log : fullReqLogger res[startTime] = res[startTime] || Date.now() + // carry request to be executed when response is finished + res[reqObject] = req if (autoLogging) { if (autoLoggingIgnorePaths.length) { @@ -157,7 +168,7 @@ function pinoLogger (opts, stream) { if (shouldLogSuccess) { if (receivedMessage !== undefined) { const level = getLogLevelFromCustomLogLevel(customLogLevel, useLevel, res, undefined, req) - log[level]({}, receivedMessage(req, res)) + req.log[level](receivedMessage(req, res)) } res.on('finish', onResFinished) diff --git a/test/test.js b/test/test.js index 6cc0f46..62bd4c8 100644 --- a/test/test.js +++ b/test/test.js @@ -982,6 +982,74 @@ test('uses old custom request properties interface to log additional attributes' }) }) +test('uses custom request properties to log additional attributes when response provided', function (t) { + const dest = split(JSON.parse) + function customPropsHandler (req, res) { + if (req && res) { + return { + key1: 'value1', + key2: res.statusCode + } + } + } + const logger = pinoHttp({ + reqCustomProps: customPropsHandler + }, dest) + + setup(t, logger, function (err, server) { + t.error(err) + doGet(server, ERROR_URL) + }) + + dest.on('data', function (line) { + t.equal(line.key1, 'value1') + t.equal(line.key2, 500) + t.end() + }) +}) + +test('uses custom request properties and a receivedMessage callback and the properties are set on the receivedMessage', function (t) { + const dest = split(JSON.parse) + const message = DEFAULT_REQUEST_RECEIVED_MSG + const logger = pinoHttp({ + customReceivedMessage: function (_req, _res) { + return message + }, + reqCustomProps: (req, res) => { + return { + key1: 'value1', + key2: res.statusCode + } + } + }, dest) + + setup(t, logger, function (err, server) { + t.error(err) + doGet(server, ERROR_URL) + }) + + let calls = 0 + dest.on('data', function (line) { + calls++ + if (line.msg === message) { + t.equal(line.key1, 'value1') + t.equal(line.key2, 200) + t.equal(line.req.url, ERROR_URL) + t.ok(line.req, 'req is defined') + t.notOk(line.res, 'res is not defined yet') + } else if (line.msg === DEFAULT_REQUEST_ERROR_MSG) { + t.equal(line.key1, 'value1') + t.equal(line.key2, 500) + t.equal(line.req.url, ERROR_URL) + t.ok(line.req, 'req is defined') + t.ok(line.res, 'res is defined') + } + if (calls === 2) { + t.end() + } + }) +}) + test('uses custom request properties to log additional attributes; custom props is an object instead of callback', function (t) { const dest = split(JSON.parse) const logger = pinoHttp({