feat: Added instrumentation for Restify async handlers (#1910)

lib/instrumentation/restify.js

@@ -55,12 +55,20 @@ module.exports = function initialize(agent, restify, moduleName, shim) {
         if (shim.isWrapped(middleware)) {
           return middleware
         }
-        return shim.recordMiddleware(middleware, {
+        const spec = {
           matchArity: true,
           route,
           req: shim.FIRST,
           next: shim.LAST
-        })
+        }
+
+        const wrappedMw = shim.recordMiddleware(middleware, spec)
+        if (middleware.constructor.name === 'AsyncFunction') {
+          return async function asyncShim() {
+            return wrappedMw.apply(this, arguments)
+          }
+        }
+        return wrappedMw
       }
     })
 
@@ -70,11 +78,18 @@ module.exports = function initialize(agent, restify, moduleName, shim) {
       if (shim.isWrapped(middleware)) {
         return middleware
       }
-      return shim.recordMiddleware(middleware, {
+      const spec = {
         matchArity: true,
         req: shim.FIRST,
         next: shim.LAST
-      })
+      }
+      const wrappedMw = shim.recordMiddleware(middleware, spec)
+      if (middleware.constructor.name === 'AsyncFunction') {
+        return async function asyncShim() {
+          return wrappedMw.apply(this, arguments)
+        }
+      }
+      return wrappedMw
     })
   }
 }

lib/util/logger.js

@@ -261,7 +261,7 @@ Logger.prototype.write = function write(level, args, extra) {
     data = stringify(entry) + '\n'
   } catch (err) {
     // eslint-disable-line no-unused-vars
-    this.debug('Unabled to stringify log message')
+    this.debug('Unable to stringify log message')
   }
 
   if (this.reading) {

test/versioned/restify/restify-post-7/async-handlers.tap.js

@@ -0,0 +1,180 @@
+/*
+ * Copyright 2020 New Relic Corporation. All rights reserved.
+ * SPDX-License-Identifier: Apache-2.0
+ */
+
+'use strict'
+
+const tap = require('tap')
+
+const helper = require('../../../lib/agent_helper')
+const { assertMetrics } = require('../../../lib/metrics_helper')
+const { runTest } = require('./common')
+
+const simulateAsyncWork = async () => {
+  const delay = Math.floor(Math.random() * 100)
+  await new Promise((resolve) => setTimeout(resolve, delay))
+  return delay
+}
+
+tap.test('Restify with async handlers should work the same as with sync', (t) => {
+  t.autoend()
+
+  let agent = null
+  let restify = null
+  let server = null
+
+  t.beforeEach(() => {
+    agent = helper.instrumentMockedAgent()
+
+    restify = require('restify')
+    server = restify.createServer()
+  })
+
+  t.afterEach(() => {
+    return new Promise((resolve) => {
+      helper.unloadAgent(agent)
+      if (server) {
+        server.close(resolve)
+      } else {
+        resolve()
+      }
+    })
+  })
+
+  /* very similar synchronous tests are in transaction-naming */
+
+  t.test('transaction name for single async route', (t) => {
+    t.plan(1)
+
+    server.get('/path1', async (req, res) => {
+      res.send()
+    })
+
+    runTest({ agent, server, t, endpoint: '/path1', expectedName: 'GET//path1' })
+  })
+
+  t.test('transaction name for async route with sync middleware', (t) => {
+    t.plan(1)
+
+    server.use((req, res, next) => {
+      next()
+    })
+    server.get('/path1', async (req, res) => {
+      res.send()
+    })
+
+    runTest({ agent, server, t, endpoint: '/path1', expectedName: 'GET//path1' })
+  })
+
+  t.test('transaction name for async route with async middleware', (t) => {
+    t.plan(1)
+
+    server.use(async (req) => {
+      req.test = await simulateAsyncWork()
+    })
+    server.get('/path1', async (req, res) => {
+      res.send()
+    })
+
+    runTest({ agent, server, t, endpoint: '/path1', expectedName: 'GET//path1' })
+  })
+
+  t.test('transaction name for async route with multiple async middleware', (t) => {
+    t.plan(4)
+
+    server.use(async (req) => {
+      t.pass('should enter first `use` middleware')
+      req.test = await simulateAsyncWork()
+    })
+    // eslint-disable-next-line no-unused-vars
+    server.use(async (req) => {
+      t.pass('should enter second `use` middleware')
+      req.test2 = await simulateAsyncWork()
+    })
+    server.get('/path1', async (req, res) => {
+      t.pass('should enter route handler')
+      res.send()
+    })
+
+    runTest({ agent, server, t, endpoint: '/path1', expectedName: 'GET//path1' })
+  })
+})
+
+tap.test('Restify metrics for async handlers', (t) => {
+  t.autoend()
+
+  let agent = null
+  let restify = null
+  t.beforeEach(() => {
+    agent = helper.instrumentMockedAgent()
+
+    restify = require('restify')
+  })
+
+  t.afterEach(() => {
+    helper.unloadAgent(agent)
+  })
+
+  t.test('should generate middleware metrics for async handlers', (t) => {
+    // Metrics for this transaction with the right name.
+    const expectedMiddlewareMetrics = [
+      [{ name: 'WebTransaction/Restify/GET//foo/:bar' }],
+      [{ name: 'WebTransactionTotalTime/Restify/GET//foo/:bar' }],
+      [{ name: 'Apdex/Restify/GET//foo/:bar' }],
+
+      // Unscoped middleware metrics.
+      [{ name: 'Nodejs/Middleware/Restify/middleware//' }],
+      [{ name: 'Nodejs/Middleware/Restify/middleware2//' }],
+      [{ name: 'Nodejs/Middleware/Restify/handler//foo/:bar' }],
+
+      // Scoped middleware metrics.
+      [
+        {
+          name: 'Nodejs/Middleware/Restify/middleware//',
+          scope: 'WebTransaction/Restify/GET//foo/:bar'
+        }
+      ],
+      [
+        {
+          name: 'Nodejs/Middleware/Restify/middleware2//',
+          scope: 'WebTransaction/Restify/GET//foo/:bar'
+        }
+      ],
+      [
+        {
+          name: 'Nodejs/Middleware/Restify/handler//foo/:bar',
+          scope: 'WebTransaction/Restify/GET//foo/:bar'
+        }
+      ]
+    ]
+
+    const server = restify.createServer()
+    t.teardown(() => server.close())
+
+    server.use(async function middleware() {
+      t.ok(agent.getTransaction(), 'should be in transaction context')
+    })
+
+    server.use(async function middleware2() {
+      t.ok(agent.getTransaction(), 'should be in transaction context')
+    })
+
+    server.get('/foo/:bar', async function handler(req, res) {
+      t.ok(agent.getTransaction(), 'should be in transaction context')
+      res.send({ message: 'done' })
+    })
+
+    server.listen(0, function () {
+      const port = server.address().port
+      const url = `http://localhost:${port}/foo/bar`
+
+      helper.makeGetRequest(url, function (error) {
+        t.error(error)
+
+        assertMetrics(agent.metrics, expectedMiddlewareMetrics, false, false)
+        t.end()
+      })
+    })
+  })
+})

test/versioned/restify/restify-post-7/capture-params.tap.js

@@ -61,7 +61,7 @@ test('Restify capture params introspection', function (t) {
       port = server.address().port
       helper.makeGetRequest('http://localhost:' + port + '/test', function (error, res, body) {
         t.equal(res.statusCode, 200, 'nothing exploded')
-        t.same(body, { status: 'ok' }, 'got expected respose')
+        t.same(body, { status: 'ok' }, 'got expected response')
         t.end()
       })
     })

test/versioned/restify/restify-post-7/common.js

@@ -0,0 +1,35 @@
+/*
+ * Copyright 2023 New Relic Corporation. All rights reserved.
+ * SPDX-License-Identifier: Apache-2.0
+ */
+
+'use strict'
+const common = module.exports
+const helper = require('../../../lib/agent_helper')
+
+/**
+ * @param {object} cfg
+ * @property {object} cfg.t
+ * @property {string} cfg.endpoint
+ * @property {string} [cfg.prefix='Restify']
+ * @property {string} cfg.expectedName
+ * @property {Function} [cfg.cb=t.end]
+ * @property {object} [cfg.requestOpts=null]
+ * @property {object} cfg.agent
+ * @property {object} cfg.server
+ */
+common.runTest = function runTest(cfg) {
+  const { t, endpoint, agent, prefix = 'Restify', requestOpts = null, server } = cfg
+  let { expectedName } = cfg
+  expectedName = `WebTransaction/${prefix}/${expectedName}`
+
+  agent.on('transactionFinished', (tx) => {
+    t.equal(tx.name, expectedName, 'should have correct name')
+    t.end()
+  })
+
+  server.listen(() => {
+    const port = server.address().port
+    helper.makeGetRequest(`http://localhost:${port}${endpoint}`, requestOpts)
+  })
+}

test/versioned/restify/restify-post-7/package.json

@@ -32,6 +32,7 @@
         "restify-errors": "6.1"
       },
       "files": [
+        "async-handlers.tap.js",
         "capture-params.tap.js",
         "ignoring.tap.js",
         "restify.tap.js",