conceptually rework from tracing requests to routes

docs/Reference/Hooks.md

@@ -852,7 +852,7 @@ 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.route')
     spans.set(request, span)
     done()
   })
@@ -869,15 +869,15 @@ 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:start`: Always fires
+- `tracing:fastify.route:start`: Always fires
   - `{ request: Request, reply: Reply }`
-- `tracing:fastify.request:end`: Always fires
+- `tracing:fastify.route:end`: Always fires
   - `{ request: Request, reply: Reply }`
-- `tracing:fastify.request:asyncStart`: Fires for promise/async handlers
+- `tracing:fastify.route:asyncStart`: Fires for promise/async handlers
   - `{ request: Request, reply: Reply, result: Payload }`
-- `tracing:fastify.request:asyncEnd`: Fires for promise/async handlers
+- `tracing:fastify.route:asyncEnd`: Fires for promise/async handlers
   - `{ request: Request, reply: Reply, result: Payload }`
-- `tracing:fastify.request:error`: Fires when an error occurs
+- `tracing:fastify.route:error`: Fires when an error occurs
   - `{ request: Request, reply: Reply, error: Error }`
 
 The object instance remains the same for all events associated with a given
@@ -893,7 +893,7 @@ 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:start')
+const channel = dc.channel('tracing:fastify.route:start')
 channel.subscribe((msg) => {
   console.log(msg.request, msg.reply)
 })

lib/handleRequest.js

@@ -6,11 +6,10 @@ const { preValidationHookRunner, preHandlerHookRunner } = require('./hooks')
 const wrapThenable = require('./wrapThenable')
 const {
   kReplyIsError,
-  kRouteContext,
-  kReplyOnSend
+  kRouteContext
 } = require('./symbols')
 
-const channels = dc.tracingChannel('fastify.request')
+const channels = dc.tracingChannel('fastify.route')
 
 function handleRequest (err, request, reply) {
   if (reply.sent === true) return
@@ -129,46 +128,50 @@ function validationCompleted (request, reply, validationErr) {
 function preHandlerCallback (err, request, reply) {
   if (reply.sent) return
 
-  const store = { request, reply }
+  const store = { request, reply, async: false }
 
-  reply[kReplyOnSend] = function (payload) {
-    store.result = payload
-  }
+  // change from requet tracing to routing tracing
+  // so we want to add routing info to the store (e.g. path) like method, path pattern "/foo/:fooId", req, reply
+  // ask Matteo if this routing tracing is OK to land or if they walso need req tracing to land
+  // FYI some use "GET /foo/bar" vs "GET" AND "/foo/bar"
 
-  try {
-    if (err != null) {
-      reply[kReplyIsError] = true
-      reply.send(err)
-      store.error = err
-      channels.error.publish(store)
-      return
-    }
+  channels.start.runStores(store, () => {
+    try {
+      if (err != null) {
+        reply[kReplyIsError] = true
+        reply.send(err)
+        store.error = err
+        channels.error.publish(store)
+        return
+      }
 
-    let result
+      let result
 
-    channels.start.publish(store)
+      try {
+        result = request[kRouteContext].handler(request, reply)
+      } catch (err) {
+        store.error = err
+        channels.error.publish(store)
 
-    try {
-      result = request[kRouteContext].handler(request, reply)
-    } catch (err) {
-      store.error = err
-      channels.error.publish(store)
-
-      reply[kReplyIsError] = true
-      reply.send(err)
-      return
-    }
+        reply[kReplyIsError] = true
+        reply.send(err)
+        return
+      }
 
-    if (result !== undefined) {
-      if (result !== null && typeof result.then === 'function') {
-        wrapThenable(result, reply, channels, store)
-      } else {
-        reply.send(result)
+      if (result !== undefined) {
+        if (result !== null && typeof result.then === 'function') {
+          store.async = true
+          wrapThenable(result, reply, store)
+        } else {
+          // start and end should always happen before async start/end
+          store.result = result
+          reply.send(result) // maybe just universally use reply.send and never check response since that's handled here
+        }
       }
+    } finally {
+      channels.end.publish(store)
     }
-  } finally {
-    channels.end.publish(store)
-  }
+  })
 }
 
 module.exports = handleRequest

lib/reply.js

@@ -22,8 +22,7 @@ const {
   kReplyCacheSerializeFns,
   kSchemaController,
   kOptions,
-  kRouteContext,
-  kReplyOnSend
+  kRouteContext
 } = require('./symbols.js')
 const {
   onSendHookRunner,
@@ -67,7 +66,6 @@ function Reply (res, request, log) {
   this[kReplyTrailers] = null
   this[kReplyHasStatusCode] = false
   this[kReplyStartTime] = undefined
-  this[kReplyOnSend] = undefined
   this.log = log
 }
 Reply.props = []
@@ -133,6 +131,7 @@ Reply.prototype.hijack = function () {
 }
 
 Reply.prototype.send = function (payload) {
+  // console.trace('Reply#send()', payload)
   if (this[kReplyIsRunningOnErrorHook] === true) {
     throw new FST_ERR_SEND_INSIDE_ONERR()
   }
@@ -153,8 +152,6 @@ Reply.prototype.send = function (payload) {
     return this
   }
 
-  if (this[kReplyOnSend]) this[kReplyOnSend](payload)
-
   const contentType = this.getHeader('content-type')
   const hasContentType = contentType !== undefined
 
@@ -848,7 +845,6 @@ function buildReply (R) {
     this[kReplyTrailers] = null
     this[kReplyStartTime] = undefined
     this[kReplyEndTime] = undefined
-    this[kReplyOnSend] = undefined
     this.log = log
 
     // eslint-disable-next-line no-var

lib/wrapThenable.js

@@ -5,16 +5,19 @@ const {
   kReplyHijacked
 } = require('./symbols')
 
-function wrapThenable (thenable, reply, channels, store) {
+const dc = require('dc-polyfill')
+const channels = dc.tracingChannel('fastify.route')
+
+function wrapThenable (thenable, reply, store) {
   thenable.then(function (payload) {
-    if (reply[kReplyHijacked] === true) {
-      return
+    if (store) {
+      store.result = payload
+      channels.asyncStart.publish(store)
     }
 
     try {
-      if (channels) {
-        store.result = payload
-        channels.asyncStart.publish(store)
+      if (reply[kReplyHijacked] === true) {
+        return
       }
 
       // this is for async functions that are using reply.send directly
@@ -35,21 +38,35 @@ function wrapThenable (thenable, reply, channels, store) {
         }
       }
     } finally {
-      if (channels) channels.asyncEnd.publish(store)
+      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 {
-      reply.send(err)
-    } catch (err) {
-      reply.send(err)
+      if (reply.sent === true) {
+        reply.log.error({ err }, 'Promise errored, but reply.sent = true was set')
+        return
+      }
+
+      reply[kReplyIsError] = true
+
+      // try-catch allow to re-throw error in error handler for async handler
+      try {
+        reply.send(err)
+      } catch (err) {
+        reply.send(err)
+      }
+    } finally {
+      if (store) {
+        channels.asyncEnd.publish(store)
+      }
     }
   })
 }

test/diagnostics-channel-async-delay-request.test.js

@@ -0,0 +1,80 @@
+'use strict'
+
+const t = require('tap')
+const dc = require('diagnostics_channel')
+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 async events fire in expected order', t => {
+  t.plan(22)
+  let callOrder = 0
+  let firstEncounteredMessage
+
+  dc.subscribe('tracing:fastify.route:start', (msg) => {
+    t.equal(callOrder++, 0)
+    firstEncounteredMessage = msg
+    t.ok(msg.request instanceof Request)
+    t.ok(msg.reply instanceof Reply)
+    t.notOk('result' in msg)
+  })
+
+  dc.subscribe('tracing:fastify.route:end', (msg) => {
+    t.equal(callOrder++, 1)
+    t.ok(msg.request instanceof Request)
+    t.ok(msg.reply instanceof Reply)
+    t.equal(msg, firstEncounteredMessage)
+    t.equal(msg.async, true)
+    t.notOk('result' in msg)
+  })
+
+  dc.subscribe('tracing:fastify.route:asyncStart', (msg) => {
+    t.equal(callOrder++, 2)
+    t.ok(msg.request instanceof Request)
+    t.ok(msg.reply instanceof Reply)
+    t.equal(msg, firstEncounteredMessage)
+    // t.ok('result' in msg)
+    // t.equal(msg.result.hello, 'world')
+  })
+
+  dc.subscribe('tracing:fastify.route:asyncEnd', (msg) => {
+    t.equal(callOrder++, 3)
+    t.ok(msg.request instanceof Request)
+    t.ok(msg.reply instanceof Reply)
+    t.equal(msg, firstEncounteredMessage)
+    t.ok('result' in msg)
+    // t.equal(msg.result.hello, 'world')
+  })
+
+  dc.subscribe('tracing:fastify.route:error', (msg) => {
+    t.fail('should not trigger error channel')
+  })
+
+  const fastify = Fastify()
+  fastify.route({
+    method: 'GET',
+    url: '/',
+    handler: async function (req, reply) {
+      setImmediate(() => reply.send({ hello: 'world' }))
+      return reply
+    }
+  })
+
+  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, 200)
+      t.same(JSON.parse(body), { hello: 'world' })
+    })
+  })
+})

test/diagnostics-channel-async-request.test.js

@@ -14,23 +14,23 @@ test('diagnostics channel async events fire in expected order', t => {
   let callOrder = 0
   let firstEncounteredMessage
 
-  dc.subscribe('tracing:fastify.request:start', (msg) => {
+  dc.subscribe('tracing:fastify.route:start', (msg) => {
     t.equal(callOrder++, 0)
     firstEncounteredMessage = msg
     t.ok(msg.request instanceof Request)
     t.ok(msg.reply instanceof Reply)
     t.notOk('result' in msg)
   })
 
-  dc.subscribe('tracing:fastify.request:end', (msg) => {
+  dc.subscribe('tracing:fastify.route:end', (msg) => {
     t.equal(callOrder++, 1)
     t.ok(msg.request instanceof Request)
     t.ok(msg.reply instanceof Reply)
     t.equal(msg, firstEncounteredMessage)
     t.notOk('result' in msg)
   })
 
-  dc.subscribe('tracing:fastify.request:asyncStart', (msg) => {
+  dc.subscribe('tracing:fastify.route:asyncStart', (msg) => {
     t.equal(callOrder++, 2)
     t.ok(msg.request instanceof Request)
     t.ok(msg.reply instanceof Reply)
@@ -39,7 +39,7 @@ test('diagnostics channel async events fire in expected order', t => {
     t.equal(msg.result.hello, 'world')
   })
 
-  dc.subscribe('tracing:fastify.request:asyncEnd', (msg) => {
+  dc.subscribe('tracing:fastify.route:asyncEnd', (msg) => {
     t.equal(callOrder++, 3)
     t.ok(msg.request instanceof Request)
     t.ok(msg.reply instanceof Reply)
@@ -48,7 +48,7 @@ test('diagnostics channel async events fire in expected order', t => {
     t.equal(msg.result.hello, 'world')
   })
 
-  dc.subscribe('tracing:fastify.request:error', (msg) => {
+  dc.subscribe('tracing:fastify.route:error', (msg) => {
     t.fail('should not trigger error channel')
   })