From 1848a866566b3151c1e7ffe3640766d9ecf7dff6 Mon Sep 17 00:00:00 2001 From: Samuele Salvatico Date: Mon, 29 Apr 2024 09:35:55 +0200 Subject: [PATCH 1/7] fix(error-handler): check for kDisableRequestLogging before logging --- lib/error-handler.js | 39 ++++++++++++++++++++++++--------------- 1 file changed, 24 insertions(+), 15 deletions(-) diff --git a/lib/error-handler.js b/lib/error-handler.js index 53f52631bb..958b511e42 100644 --- a/lib/error-handler.js +++ b/lib/error-handler.js @@ -7,7 +7,8 @@ const { kReplyNextErrorHandler, kReplyIsRunningOnErrorHook, kReplyHasStatusCode, - kRouteContext + kRouteContext, + kDisableRequestLogging } = require('./symbols.js') const { @@ -35,10 +36,12 @@ function handleError (reply, error, cb) { try { reply.raw.writeHead(reply.raw.statusCode, reply[kReplyHeaders]) } catch (error) { - reply.log.warn( - { req: reply.request, res: reply, err: error }, - error && error.message - ) + if (!reply[kDisableRequestLogging]) { + reply.log.warn( + { req: reply.request, res: reply, err: error }, + error && error.message + ) + } reply.raw.writeHead(reply.raw.statusCode) } reply.raw.end(payload) @@ -79,15 +82,19 @@ function defaultErrorHandler (error, request, reply) { reply.code(statusCode >= 400 ? statusCode : 500) } if (reply.statusCode < 500) { - reply.log.info( - { res: reply, err: error }, - error && error.message - ) + if (!reply[kDisableRequestLogging]) { + reply.log.info( + { res: reply, err: error }, + error && error.message + ) + } } else { - reply.log.error( - { req: request, res: reply, err: error }, - error && error.message - ) + if (!reply[kDisableRequestLogging]) { + reply.log.error( + { req: request, res: reply, err: error }, + error && error.message + ) + } } reply.send(error) } @@ -112,8 +119,10 @@ function fallbackErrorHandler (error, reply, cb) { statusCode: { value: statusCode } })) } catch (err) { - // error is always FST_ERR_SCH_SERIALIZATION_BUILD because this is called from route/compileSchemasForSerialization - reply.log.error({ err, statusCode: res.statusCode }, 'The serializer for the given status code failed') + if (!reply[kDisableRequestLogging]) { + // error is always FST_ERR_SCH_SERIALIZATION_BUILD because this is called from route/compileSchemasForSerialization + reply.log.error({ err, statusCode: res.statusCode }, 'The serializer for the given status code failed') + } reply.code(500) payload = serializeError(new FST_ERR_FAILED_ERROR_SERIALIZATION(err.message, error.message)) } From ee1826557dc3df0f7644ffe5336d8ac1d711b81a Mon Sep 17 00:00:00 2001 From: Samuele Salvatico Date: Mon, 29 Apr 2024 11:31:28 +0200 Subject: [PATCH 2/7] fix(error-handler): updated tests --- lib/error-handler.js | 8 +++---- test/logger/logging.test.js | 42 ++++++++++++++++++++++++++++++------- 2 files changed, 38 insertions(+), 12 deletions(-) diff --git a/lib/error-handler.js b/lib/error-handler.js index 958b511e42..0b9dbdbb99 100644 --- a/lib/error-handler.js +++ b/lib/error-handler.js @@ -36,7 +36,7 @@ function handleError (reply, error, cb) { try { reply.raw.writeHead(reply.raw.statusCode, reply[kReplyHeaders]) } catch (error) { - if (!reply[kDisableRequestLogging]) { + if (!reply.log[kDisableRequestLogging]) { reply.log.warn( { req: reply.request, res: reply, err: error }, error && error.message @@ -82,14 +82,14 @@ function defaultErrorHandler (error, request, reply) { reply.code(statusCode >= 400 ? statusCode : 500) } if (reply.statusCode < 500) { - if (!reply[kDisableRequestLogging]) { + if (!reply.log[kDisableRequestLogging]) { reply.log.info( { res: reply, err: error }, error && error.message ) } } else { - if (!reply[kDisableRequestLogging]) { + if (!reply.log[kDisableRequestLogging]) { reply.log.error( { req: request, res: reply, err: error }, error && error.message @@ -119,7 +119,7 @@ function fallbackErrorHandler (error, reply, cb) { statusCode: { value: statusCode } })) } catch (err) { - if (!reply[kDisableRequestLogging]) { + if (!reply.log[kDisableRequestLogging]) { // error is always FST_ERR_SCH_SERIALIZATION_BUILD because this is called from route/compileSchemasForSerialization reply.log.error({ err, statusCode: res.statusCode }, 'The serializer for the given status code failed') } diff --git a/test/logger/logging.test.js b/test/logger/logging.test.js index da4945ed9b..613f260cb7 100644 --- a/test/logger/logging.test.js +++ b/test/logger/logging.test.js @@ -17,7 +17,7 @@ t.test('logging', (t) => { let localhost let localhostForURL - t.plan(12) + t.plan(13) t.before(async function () { [localhost, localhostForURL] = await helper.getLoopbackHost() @@ -253,7 +253,7 @@ t.test('logging', (t) => { }) t.test('should not log incoming request and outgoing response when disabled', async (t) => { - t.plan(3) + t.plan(1) const stream = split(JSON.parse) const fastify = Fastify({ disableRequestLogging: true, logger: { level: 'info', stream } }) t.teardown(fastify.close.bind(fastify)) @@ -266,12 +266,6 @@ t.test('logging', (t) => { await fastify.inject({ method: 'GET', url: '/500' }) - { - const [line] = await once(stream, 'data') - t.ok(line.reqId, 'reqId is defined') - t.equal(line.msg, '500 error', 'message is set') - } - // no more readable data t.equal(stream.readableLength, 0) }) @@ -403,4 +397,36 @@ t.test('logging', (t) => { if (lines.length === 0) break } }) + + t.test('should not log the error if request logging is disabled', async (t) => { + t.plan(3) + + const stream = split(JSON.parse) + const fastify = Fastify({ + logger: { + stream, + level: 'info' + }, + disableRequestLogging: true + }) + t.teardown(fastify.close.bind(fastify)) + + fastify.get('/error', function (req, reply) { + t.ok(req.log) + reply.send(new Error('a generic error')) + }) + + await fastify.ready() + await fastify.listen({ port: 0, host: localhost }) + + await request(`http://${localhostForURL}:` + fastify.server.address().port + '/error') + + { + const [line] = await once(stream, 'data') + t.equal(line.msg, `Server listening at http://[::1]:${fastify.server.address().port}`, 'message is set') + } + + // no more readable data + t.equal(stream.readableLength, 0) + }) }) From dc3cb90b409b31e3ed913dea78524963eb19009a Mon Sep 17 00:00:00 2001 From: Samuele Salvatico Date: Tue, 30 Apr 2024 08:49:53 +0200 Subject: [PATCH 3/7] fix(fourOhfour): check for logging disabled before log 404 --- lib/fourOhFour.js | 7 +++++-- 1 file changed, 5 insertions(+), 2 deletions(-) diff --git a/lib/fourOhFour.js b/lib/fourOhFour.js index da12232ec1..937888ea01 100644 --- a/lib/fourOhFour.js +++ b/lib/fourOhFour.js @@ -11,7 +11,8 @@ const { kFourOhFourLevelInstance, kFourOhFourContext, kHooks, - kErrorHandler + kErrorHandler, + kDisableRequestLogging } = require('./symbols.js') const { lifecycleHooks } = require('./hooks') const { buildErrorHandler } = require('./error-handler.js') @@ -49,7 +50,9 @@ function fourOhFour (options) { function basic404 (request, reply) { const { url, method } = request.raw const message = `Route ${method}:${url} not found` - request.log.info(message) + if (!request.log[kDisableRequestLogging]) { + request.log.info(message) + } reply.code(404).send({ message, error: 'Not Found', From 1b8c72b5ea2c4419a52667ef52bb2e4fc0622484 Mon Sep 17 00:00:00 2001 From: Samuele Salvatico Date: Tue, 30 Apr 2024 09:20:14 +0200 Subject: [PATCH 4/7] fix(fourOhfour): managed disableRequestLogging --- lib/fourOhFour.js | 7 +++---- test/logger/logging.test.js | 10 ++-------- 2 files changed, 5 insertions(+), 12 deletions(-) diff --git a/lib/fourOhFour.js b/lib/fourOhFour.js index 937888ea01..de0575475b 100644 --- a/lib/fourOhFour.js +++ b/lib/fourOhFour.js @@ -11,8 +11,7 @@ const { kFourOhFourLevelInstance, kFourOhFourContext, kHooks, - kErrorHandler, - kDisableRequestLogging + kErrorHandler } = require('./symbols.js') const { lifecycleHooks } = require('./hooks') const { buildErrorHandler } = require('./error-handler.js') @@ -30,7 +29,7 @@ const { getGenReqId } = require('./reqIdGenFactory.js') * kFourOhFourContext: the context in the reply object where the handler will be executed */ function fourOhFour (options) { - const { logger } = options + const { logger, disableRequestLogging } = options // 404 router, used for handling encapsulated 404 handlers const router = FindMyWay({ onBadUrl: createOnBadUrl(), defaultRoute: fourOhFourFallBack }) @@ -50,7 +49,7 @@ function fourOhFour (options) { function basic404 (request, reply) { const { url, method } = request.raw const message = `Route ${method}:${url} not found` - if (!request.log[kDisableRequestLogging]) { + if (!disableRequestLogging) { request.log.info(message) } reply.code(404).send({ diff --git a/test/logger/logging.test.js b/test/logger/logging.test.js index 613f260cb7..1e34da7ef4 100644 --- a/test/logger/logging.test.js +++ b/test/logger/logging.test.js @@ -270,8 +270,8 @@ t.test('logging', (t) => { t.equal(stream.readableLength, 0) }) - t.test('should not log incoming request and outgoing response for 404 onBadUrl when disabled', async (t) => { - t.plan(3) + t.test('should not log incoming request, outgoing response and route not found for 404 onBadUrl when disabled', async (t) => { + t.plan(1) const stream = split(JSON.parse) const fastify = Fastify({ disableRequestLogging: true, logger: { level: 'info', stream } }) t.teardown(fastify.close.bind(fastify)) @@ -280,12 +280,6 @@ t.test('logging', (t) => { await fastify.inject({ method: 'GET', url: '/%c0' }) - { - const [line] = await once(stream, 'data') - t.ok(line.reqId, 'reqId is defined') - t.equal(line.msg, 'Route GET:/%c0 not found', 'message is set') - } - // no more readable data t.equal(stream.readableLength, 0) }) From bdf952d2c9f8763583247703584784b04748c650 Mon Sep 17 00:00:00 2001 From: Samuele Salvatico Date: Thu, 2 May 2024 09:20:04 +0200 Subject: [PATCH 5/7] fixed test for server listening message --- test/logger/logging.test.js | 5 +++-- 1 file changed, 3 insertions(+), 2 deletions(-) diff --git a/test/logger/logging.test.js b/test/logger/logging.test.js index 1e34da7ef4..517b514468 100644 --- a/test/logger/logging.test.js +++ b/test/logger/logging.test.js @@ -393,7 +393,7 @@ t.test('logging', (t) => { }) t.test('should not log the error if request logging is disabled', async (t) => { - t.plan(3) + t.plan(4) const stream = split(JSON.parse) const fastify = Fastify({ @@ -417,7 +417,8 @@ t.test('logging', (t) => { { const [line] = await once(stream, 'data') - t.equal(line.msg, `Server listening at http://[::1]:${fastify.server.address().port}`, 'message is set') + t.type(line.msg, 'string') + t.ok(line.msg.startsWith('Server listening at'), 'message is set') } // no more readable data From 2d5765c76cdbd5a76d19c6d750532df107afc224 Mon Sep 17 00:00:00 2001 From: Samuele Salvatico Date: Thu, 2 May 2024 09:56:35 +0200 Subject: [PATCH 6/7] Updated docs related to disableRequestLogging --- docs/Reference/Server.md | 12 +++++++++--- 1 file changed, 9 insertions(+), 3 deletions(-) diff --git a/docs/Reference/Server.md b/docs/Reference/Server.md index 2be8393d7d..8b9357a428 100644 --- a/docs/Reference/Server.md +++ b/docs/Reference/Server.md @@ -385,9 +385,15 @@ been sent. By setting this option to `true`, these log messages will be disabled. This allows for more flexible request start and end logging by attaching custom `onRequest` and `onResponse` hooks. -Please note that this option will also disable an error log written by the -default `onResponse` hook on reply callback errors. Other log messages -emitted by Fastify will stay enabled, like deprecation warnings and messages +The other log entries that will be disabled are: +- an error log written by the default `onResponse` hook on reply callback errors +- the error and info logs written by the `defaultErrorHandler` +on error management +- the info log written by the `fourOhFour` handler when a +not existent route is requested + +Other log messages emitted by Fastify will stay enabled, +like deprecation warnings and messages emitted when requests are received while the server is closing. ```js From 4fcb3be6cdaff190aa11d4369624cd4130ed3422 Mon Sep 17 00:00:00 2001 From: Samuele Salvatico Date: Thu, 2 May 2024 13:58:18 +0200 Subject: [PATCH 7/7] fixed typo in docs --- docs/Reference/Server.md | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/docs/Reference/Server.md b/docs/Reference/Server.md index 8b9357a428..1283f41d8c 100644 --- a/docs/Reference/Server.md +++ b/docs/Reference/Server.md @@ -390,7 +390,7 @@ The other log entries that will be disabled are: - the error and info logs written by the `defaultErrorHandler` on error management - the info log written by the `fourOhFour` handler when a -not existent route is requested +non existent route is requested Other log messages emitted by Fastify will stay enabled, like deprecation warnings and messages