feat: emit diagnostics_channel upon handling request

docs/Reference/Hooks.md

@@ -829,18 +829,17 @@ consider creating a custom [Plugin](./Plugins.md) instead.
 ## Diagnostics Channel Hooks
 
 > **Note:** The `diagnostics_channel` is currently experimental on Node.js, so
-> its API is subject to change even in semver-patch releases of Node.js. For
-> versions of Node.js supported by Fastify where `diagnostics_channel` is
-> unavailable, the hook will use the
-> [polyfill](https://www.npmjs.com/package/diagnostics_channel) if it is
-> available. Otherwise, this feature will not be present.
-
-Currently, one
-[`diagnostics_channel`](https://nodejs.org/api/diagnostics_channel.html) publish
-event, `'fastify.initialization'`, happens at initialization time. The Fastify
-instance is passed into the hook as a property of the object passed in. At this
-point, the instance can be interacted with to add hooks, plugins, routes, or any
-other sort of modification.
+> its API is subject to change even in semver-patch releases of Node.js. As some
+> versions of Node.js are supported by Fastify where `diagnostics_channel` is
+> unavailable, or with an incomplete feature set, the hook uses the
+> [dc-polyfill](https://www.npmjs.com/package/dc-polyfill) package to provide a
+> polyfill.
+
+One [`diagnostics_channel`](https://nodejs.org/api/diagnostics_channel.html)
+publish event, `'fastify.initialization'`, happens at initialization time. The
+Fastify instance is passed into the hook as a property of the object passed in.
+At this point, the instance can be interacted with to add hooks, plugins,
+routes, or any other sort of modification.
 
 For example, a tracing package might do something like the following (which is,
 of course, a simplification). This would be in a file loaded in the
@@ -849,13 +848,13 @@ tools first" fashion.
 
 ```js
 const tracer = /* retrieved from elsewhere in the package */
-const dc = require('node:diagnostics_channel')
+const dc = require('node:diagnostics_channel') // or require('dc-polyfill')
 const channel = dc.channel('fastify.initialization')
 const spans = new WeakMap()
 
 channel.subscribe(function ({ fastify }) {
   fastify.addHook('onRequest', (request, reply, done) => {
-    const span = tracer.startSpan('fastify.request')
+    const span = tracer.startSpan('fastify.request.handler')
     spans.set(request, span)
     done()
   })
@@ -867,3 +866,38 @@ channel.subscribe(function ({ fastify }) {
   })
 })
 ```
+
+Five other events are published on a per-request basis following the
+[Tracing Channel](https://nodejs.org/api/diagnostics_channel.html#class-tracingchannel)
+nomenclature. The list of the channel names and the event they receive is:
+
+- `tracing:fastify.request.handler:start`: Always fires
+  - `{ request: Request, reply: Reply, route: { url, method } }`
+- `tracing:fastify.request.handler:end`: Always fires
+  - `{ request: Request, reply: Reply, route: { url, method }, async: Bool }`
+- `tracing:fastify.request.handler:asyncStart`: Fires for promise/async handlers
+  - `{ request: Request, reply: Reply, route: { url, method } }`
+- `tracing:fastify.request.handler:asyncEnd`: Fires for promise/async handlers
+  - `{ request: Request, reply: Reply, route: { url, method } }`
+- `tracing:fastify.request.handler:error`: Fires when an error occurs
+  - `{ request: Request, reply: Reply, route: { url, method }, error: Error }`
+
+The object instance remains the same for all events associated with a given
+request. All payloads include a `request` and `reply` property which are an
+instance of Fastify's `Request` and `Reply` instances. They also include a
+`route` property which is an object with the matched `url` pattern (e.g.
+`/collection/:id`) and the `method` HTTP method (e.g. `GET`). The `:start` and
+`:end` events always fire for requests. If a request handler is an `async`
+function or one that returns a `Promise` then the `:asyncStart` and `:asyncEnd`
+events also fire. Finally, the `:error` event contains an `error` property
+associated with the request's failure.
+
+These events can be received like so:
+
+```js
+const dc = require('node:diagnostics_channel') // or require('dc-polyfill')
+const channel = dc.channel('tracing:fastify.request.handler:start')
+channel.subscribe((msg) => {
+  console.log(msg.request, msg.reply)
+})
+```

fastify.js

@@ -4,6 +4,7 @@ const VERSION = '5.0.0-dev'
 
 const Avvio = require('avvio')
 const http = require('node:http')
+const diagnostics = require('dc-polyfill')
 let lightMyRequest
 
 const {
@@ -77,6 +78,8 @@ const {
 
 const { buildErrorHandler } = require('./lib/error-handler.js')
 
+const initChannel = diagnostics.channel('fastify.initialization')
+
 function defaultBuildPrettyMeta (route) {
   // return a shallow copy of route's sanitized context
 
@@ -540,15 +543,8 @@ function fastify (options) {
   // Delay configuring clientError handler so that it can access fastify state.
   server.on('clientError', options.clientErrorHandler.bind(fastify))
 
-  try {
-    const dc = require('node:diagnostics_channel')
-    const initChannel = dc.channel('fastify.initialization')
-    if (initChannel.hasSubscribers) {
-      initChannel.publish({ fastify })
-    }
-  } catch (e) {
-    // This only happens if `diagnostics_channel` isn't available, i.e. earlier
-    // versions of Node.js. In that event, we don't care, so ignore the error.
+  if (initChannel.hasSubscribers) {
+    initChannel.publish({ fastify })
   }
 
   // Older nodejs versions may not have asyncDispose

lib/handleRequest.js

@@ -1,14 +1,18 @@
 'use strict'
 
 const { bodylessMethods, bodyMethods } = require('./httpMethods')
+const diagnostics = require('dc-polyfill')
 const { validate: validateSchema } = require('./validation')
 const { preValidationHookRunner, preHandlerHookRunner } = require('./hooks')
 const wrapThenable = require('./wrapThenable')
 const {
   kReplyIsError,
-  kRouteContext
+  kRouteContext,
+  kFourOhFourContext
 } = require('./symbols')
 
+const channels = diagnostics.tracingChannel('fastify.request.handler')
+
 function handleRequest (err, request, reply) {
   if (reply.sent === true) return
   if (err != null) {
@@ -119,30 +123,72 @@ function validationCompleted (request, reply, validationErr) {
 function preHandlerCallback (err, request, reply) {
   if (reply.sent) return
 
-  if (err != null) {
-    reply[kReplyIsError] = true
-    reply.send(err)
-    return
+  const context = request[kRouteContext]
+
+  if (!tcHasSubscribers() || context[kFourOhFourContext] === null) {
+    preHandlerCallbackInner(err, request, reply)
+  } else {
+    const store = {
+      request,
+      reply,
+      async: false,
+      route: {
+        url: context.config.url,
+        method: context.config.method
+      }
+    }
+    channels.start.runStores(store, preHandlerCallbackInner, undefined, err, request, reply, store)
   }
+}
 
-  let result
+function preHandlerCallbackInner (err, request, reply, store) {
+  const context = request[kRouteContext]
 
   try {
-    result = request[kRouteContext].handler(request, reply)
-  } catch (err) {
-    reply[kReplyIsError] = true
-    reply.send(err)
-    return
-  }
+    if (err != null) {
+      reply[kReplyIsError] = true
+      reply.send(err)
+      if (store) {
+        store.error = err
+        channels.error.publish(store)
+      }
+      return
+    }
 
-  if (result !== undefined) {
-    if (result !== null && typeof result.then === 'function') {
-      wrapThenable(result, reply)
-    } else {
-      reply.send(result)
+    let result
+
+    try {
+      result = context.handler(request, reply)
+    } catch (err) {
+      if (store) {
+        store.error = err
+        channels.error.publish(store)
+      }
+
+      reply[kReplyIsError] = true
+      reply.send(err)
+      return
+    }
+
+    if (result !== undefined) {
+      if (result !== null && typeof result.then === 'function') {
+        wrapThenable(result, reply, store)
+      } else {
+        reply.send(result)
+      }
     }
+  } finally {
+    if (store) channels.end.publish(store)
   }
 }
 
+function tcHasSubscribers () {
+  return channels.start.hasSubscribers ||
+    channels.end.hasSubscribers ||
+    channels.asyncStart.hasSubscribers ||
+    channels.asyncEnd.hasSubscribers ||
+    channels.error.hasSubscribers
+}
+
 module.exports = handleRequest
 module.exports[Symbol.for('internals')] = { handler, preHandlerCallback }

lib/wrapThenable.js

@@ -5,44 +5,68 @@ const {
   kReplyHijacked
 } = require('./symbols')
 
-function wrapThenable (thenable, reply) {
+const diagnostics = require('dc-polyfill')
+const channels = diagnostics.tracingChannel('fastify.request.handler')
+
+function wrapThenable (thenable, reply, store) {
+  if (store) store.async = true
   thenable.then(function (payload) {
     if (reply[kReplyHijacked] === true) {
       return
     }
 
-    // this is for async functions that are using reply.send directly
-    //
-    // since wrap-thenable will be called when using reply.send directly
-    // without actual return. the response can be sent already or
-    // the request may be terminated during the reply. in this situation,
-    // it require an extra checking of request.aborted to see whether
-    // the request is killed by client.
-    if (payload !== undefined || (reply.sent === false && reply.raw.headersSent === false && reply.request.raw.aborted === false)) {
-      // we use a try-catch internally to avoid adding a catch to another
-      // promise, increase promise perf by 10%
-      try {
-        reply.send(payload)
-      } catch (err) {
-        reply[kReplyIsError] = true
-        reply.send(err)
+    if (store) {
+      channels.asyncStart.publish(store)
+    }
+
+    try {
+      // this is for async functions that are using reply.send directly
+      //
+      // since wrap-thenable will be called when using reply.send directly
+      // without actual return. the response can be sent already or
+      // the request may be terminated during the reply. in this situation,
+      // it require an extra checking of request.aborted to see whether
+      // the request is killed by client.
+      if (payload !== undefined || (reply.sent === false && reply.raw.headersSent === false && reply.request.raw.aborted === false)) {
+        // we use a try-catch internally to avoid adding a catch to another
+        // promise, increase promise perf by 10%
+        try {
+          reply.send(payload)
+        } catch (err) {
+          reply[kReplyIsError] = true
+          reply.send(err)
+        }
+      }
+    } finally {
+      if (store) {
+        channels.asyncEnd.publish(store)
       }
     }
   }, function (err) {
-    if (reply.sent === true) {
-      reply.log.error({ err }, 'Promise errored, but reply.sent = true was set')
-      return
+    if (store) {
+      store.error = err
+      channels.error.publish(store) // note that error happens before asyncStart
+      channels.asyncStart.publish(store)
     }
 
-    reply[kReplyIsError] = true
-
-    // try-catch allow to re-throw error in error handler for async handler
     try {
+      if (reply.sent === true) {
+        reply.log.error({ err }, 'Promise errored, but reply.sent = true was set')
+        return
+      }
+
+      reply[kReplyIsError] = true
+
       reply.send(err)
       // The following should not happen
       /* c8 ignore next 3 */
     } catch (err) {
+      // try-catch allow to re-throw error in error handler for async handler
       reply.send(err)
+    } finally {
+      if (store) {
+        channels.asyncEnd.publish(store)
+      }
     }
   })
 }

package.json

@@ -206,6 +206,7 @@
     "@fastify/fast-json-stringify-compiler": "^4.3.0",
     "abstract-logging": "^2.0.1",
     "avvio": "^8.3.0",
+    "dc-polyfill": "^0.1.4",
     "fast-content-type-parse": "^1.1.0",
     "fast-json-stringify": "^5.14.1",
     "find-my-way": "^8.1.0",

test/diagnostics-channel/404.test.js

@@ -0,0 +1,57 @@
+'use strict'
+
+const t = require('tap')
+const diagnostics = require('dc-polyfill')
+const test = t.test
+const sget = require('simple-get').concat
+const Fastify = require('../..')
+const { getServerUrl } = require('../helper')
+const Request = require('../../lib/request')
+const Reply = require('../../lib/reply')
+
+test('diagnostics channel sync events fire in expected order', t => {
+  t.plan(9)
+  let callOrder = 0
+  let firstEncounteredMessage
+
+  diagnostics.subscribe('tracing:fastify.request.handler:start', (msg) => {
+    t.equal(callOrder++, 0)
+    firstEncounteredMessage = msg
+    t.ok(msg.request instanceof Request)
+    t.ok(msg.reply instanceof Reply)
+  })
+
+  diagnostics.subscribe('tracing:fastify.request.handler:end', (msg) => {
+    t.ok(msg.request instanceof Request)
+    t.ok(msg.reply instanceof Reply)
+    t.equal(callOrder++, 1)
+    t.equal(msg, firstEncounteredMessage)
+  })
+
+  diagnostics.subscribe('tracing:fastify.request.handler:error', (msg) => {
+    t.fail('should not trigger error channel')
+  })
+
+  const fastify = Fastify()
+  fastify.route({
+    method: 'GET',
+    url: '/',
+    handler: function (req, reply) {
+      reply.callNotFound()
+    }
+  })
+
+  fastify.listen({ port: 0 }, function (err) {
+    if (err) t.error(err)
+
+    t.teardown(() => { fastify.close() })
+
+    sget({
+      method: 'GET',
+      url: getServerUrl(fastify) + '/'
+    }, (err, response, body) => {
+      t.error(err)
+      t.equal(response.statusCode, 404)
+    })
+  })
+})