feat: log requests refused before processing starts (fastify#4600)

Fastify can reject requests outright before any of the normal request processing begins right now: an unsupported HTTP version, or if the server is currently closing and `return503OnClosing` is true. Before this change, these requests wouldn't appear in the logs at all, which can make debugging them kind of confusing.

This change adds a log message for these requests, so that they can be found by operators and a strange looking status code can be explained more easily.

Author: airhorns

docs/Reference/Server.md

@@ -382,7 +382,9 @@ fastify.addHook('onResponse', (req, reply, done) => {
 ```
 
 Please note that this setting will also disable an error log written by the
-default `onResponse` hook on reply callback errors.
+default `onResponse` hook on reply callback errors. Other log messages 
+emitted by Fastify will stay enabled, like deprecation warnings and messages
+emitted when requests are received while the server is closing.
 
 ### `serverFactory`
 <a id="custom-http-server"></a>

lib/route.js

@@ -394,8 +394,25 @@ function buildRouting (options) {
 
   // HTTP request entry point, the routing has already been executed
   function routeHandler (req, res, params, context, query) {
+    const id = genReqId(req)
+
+    const loggerBinding = {
+      [requestIdLogLabel]: id
+    }
+
+    const loggerOpts = {
+      level: context.logLevel
+    }
+
+    if (context.logSerializers) {
+      loggerOpts.serializers = context.logSerializers
+    }
+    const childLogger = logger.child(loggerBinding, loggerOpts)
+    childLogger[kDisableRequestLogging] = disableRequestLogging
+
     // TODO: The check here should be removed once https://github.com/nodejs/node/issues/43115 resolve in core.
     if (!validateHTTPVersion(req.httpVersion)) {
+      childLogger.info({ res: { statusCode: 505 } }, 'request aborted - invalid HTTP version')
       const message = '{"error":"HTTP Version Not Supported","message":"HTTP Version Not Supported","statusCode":505}'
       const headers = {
         'Content-Type': 'application/json',
@@ -424,6 +441,7 @@ function buildRouting (options) {
         }
         res.writeHead(503, headers)
         res.end('{"error":"Service Unavailable","message":"Service Unavailable","statusCode":503}')
+        childLogger.info({ res: { statusCode: 503 } }, 'request aborted - refusing to accept new requests as server is closing')
         return
       }
     }
@@ -445,22 +463,6 @@ function buildRouting (options) {
       req.headers[kRequestAcceptVersion] = undefined
     }
 
-    const id = genReqId(req)
-
-    const loggerBinding = {
-      [requestIdLogLabel]: id
-    }
-
-    const loggerOpts = {
-      level: context.logLevel
-    }
-
-    if (context.logSerializers) {
-      loggerOpts.serializers = context.logSerializers
-    }
-    const childLogger = logger.child(loggerBinding, loggerOpts)
-    childLogger[kDisableRequestLogging] = disableRequestLogging
-
     const request = new context.Request(id, params, req, query, childLogger, context)
     const reply = new context.Reply(res, request, childLogger)
 

test/close.test.js

@@ -7,6 +7,7 @@ const test = t.test
 const Fastify = require('..')
 const { Client } = require('undici')
 const semver = require('semver')
+const split = require('split2')
 
 test('close callback', t => {
   t.plan(4)
@@ -303,6 +304,40 @@ t.test('Current opened connection should not accept new incoming connections', t
   })
 })
 
+t.test('rejected incoming connections should be logged', t => {
+  t.plan(2)
+  const stream = split(JSON.parse)
+  const fastify = Fastify({
+    forceCloseConnections: false,
+    logger: {
+      stream,
+      level: 'info'
+    }
+  })
+
+  const messages = []
+  stream.on('data', message => {
+    messages.push(message)
+  })
+  fastify.get('/', (req, reply) => {
+    fastify.close()
+    setTimeout(() => {
+      reply.send({ hello: 'world' })
+    }, 250)
+  })
+
+  fastify.listen({ port: 0 }, err => {
+    t.error(err)
+    const instance = new Client('http://localhost:' + fastify.server.address().port)
+    // initial request to trigger close
+    instance.request({ path: '/', method: 'GET' })
+    // subsequent request should be rejected
+    instance.request({ path: '/', method: 'GET' }).then(() => {
+      t.ok(messages.find(message => message.msg.includes('request aborted')))
+    })
+  })
+})
+
 test('Cannot be reopened the closed server without listen callback', async t => {
   t.plan(2)
   const fastify = Fastify()