diff --git a/CHANGELOG.md b/CHANGELOG.md index 3ff75bc..c3a00d4 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -9,6 +9,7 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 ### Added - new fields params in `url` field in incoming request and request completed logs +- add additional information to response logs ## v4.0.0 - 2021-04-20 diff --git a/docs/logging.md b/docs/logging.md index e36f2ff..cd6f0de 100644 --- a/docs/logging.md +++ b/docs/logging.md @@ -3,3 +3,24 @@ The library generates logs following [Mia-Platform logging guidelines](https://docs.mia-platform.eu/docs/development_suite/monitoring-dashboard/dev_ops_guide/log). For a json schema example check [test log schema file](../tests/log.schema.json) + +## Additional information to response logs + +It is possible to add custom information to request completed logs. +In your handler, or in a hook (before the onResponse hook which write the response log), you could add to the fastify reply object an `additionalRequestCompletedLogInfo` field. +This field must be an object, and will be added to the request completed log. + +For example: + +```js +fastify.post('/items/:itemId', { + onRequest: function (req, reply, done) { + reply.additionalRequestCompletedLogInfo = { + custom: 'property', + } + done() + } +}, function handler(request, reply) { + reply.send({ created: 'true' }) +}) +``` diff --git a/lib/custom-logger.js b/lib/custom-logger.js index 6b55e7b..4e4bea1 100644 --- a/lib/custom-logger.js +++ b/lib/custom-logger.js @@ -71,8 +71,9 @@ function logIncomingRequest(req, reply, next) { function logRequestCompleted(req, reply, next) { const { method, url, headers, params } = req - const { statusCode } = reply + const { statusCode, additionalRequestCompletedLogInfo } = reply req.log.info({ + ...additionalRequestCompletedLogInfo, http: { request: { method, diff --git a/tests/launch-fastify.test.js b/tests/launch-fastify.test.js index 86e666a..07aecfa 100644 --- a/tests/launch-fastify.test.js +++ b/tests/launch-fastify.test.js @@ -347,6 +347,97 @@ test('Test custom serializers', t => { await fastifyInstance.close() }) + t.test('fields values - with custom properties on response log', async assert => { + assert.plan(20) + const stream = split(JSON.parse) + + stream.once('data', () => { + stream.once('data', postIncomingRequestLog => { + assert.equal(postIncomingRequestLog.reqId, '34') + assert.equal(postIncomingRequestLog.level, 10) + assert.notOk(postIncomingRequestLog.req) + assert.strictSame(postIncomingRequestLog.http, { + request: { + method: 'POST', + userAgent: { original: 'lightMyRequest' }, + }, + }) + assert.strictSame(postIncomingRequestLog.url, { path: '/items/my-item', params: { itemId: 'my-item' } }) + assert.strictSame(postIncomingRequestLog.host, { hostname: 'testHost', forwardedHostame: 'testForwardedHost', ip: 'testIp' }) + + stream.once('data', postRequestCompletedLog => { + assert.equal(postRequestCompletedLog.reqId, '34') + assert.equal(postRequestCompletedLog.level, 30) + assert.notOk(postRequestCompletedLog.res) + assert.ok(postRequestCompletedLog.responseTime) + assert.strictSame(postRequestCompletedLog.http, { + request: { + method: 'POST', + userAgent: { original: 'lightMyRequest' }, + }, + response: { + statusCode: 200, + body: { bytes: 18 }, + }, + }) + assert.strictSame(postRequestCompletedLog.url, { path: '/items/my-item', params: { itemId: 'my-item' } }) + assert.strictSame(postRequestCompletedLog.host, { hostname: 'testHost', forwardedHost: 'testForwardedHost', ip: 'testIp' }) + assert.strictSame(postRequestCompletedLog.custom, 'property') + + stream.once('data', getIncomingRequestLog => { + assert.equal(getIncomingRequestLog.reqId, '35') + + stream.once('data', getRequestCompletedLog => { + assert.equal(getIncomingRequestLog.reqId, '35') + assert.ok(getRequestCompletedLog.responseTime) + assert.strictSame(getRequestCompletedLog.http, { + request: { + method: 'GET', + userAgent: { original: 'lightMyRequest' }, + }, + response: { + statusCode: 200, + body: { bytes: 13 }, + }, + }) + assert.strictSame(getRequestCompletedLog.url, { path: '/items/my-item', params: { itemId: 'my-item' } }) + assert.strictSame(getRequestCompletedLog.custom, undefined) + + assert.end() + }) + }) + }) + }) + }) + + const fastifyInstance = await launch('./tests/modules/correct-module', { + logLevel: 'trace', + stream, + }) + await fastifyInstance.inject({ + method: 'POST', + url: '/items/my-item', + headers: { + 'x-forwarded-for': 'testIp', + 'host': 'testHost:3000', + 'x-forwarded-host': 'testForwardedHost', + 'x-request-id': '34', + }, + }) + await fastifyInstance.inject({ + method: 'GET', + url: '/items/my-item', + headers: { + 'x-forwarded-for': 'testIp', + 'host': 'testHost:3000', + 'x-forwarded-host': 'testForwardedHost', + 'x-request-id': '35', + }, + }) + + await fastifyInstance.close() + }) + t.end() }) diff --git a/tests/modules/correct-module.js b/tests/modules/correct-module.js index 0607f6c..9c52653 100644 --- a/tests/modules/correct-module.js +++ b/tests/modules/correct-module.js @@ -36,6 +36,13 @@ module.exports = async function plugin(fastify, config) { fastify.get('/items/:itemId', function emptyContentLength(request, reply) { reply.send({ config }) }) + fastify.post('/items/:itemId', function handler(request, reply) { + reply.additionalRequestCompletedLogInfo = { + custom: 'property', + } + + reply.send({ created: 'true' }) + }) } module.exports.options = {