diff --git a/lib/instrumentation/restify.js b/lib/instrumentation/restify.js index 5cb8698c6a..37546b3008 100644 --- a/lib/instrumentation/restify.js +++ b/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 }) } } diff --git a/lib/util/logger.js b/lib/util/logger.js index faec2648f3..f49e9452b5 100644 --- a/lib/util/logger.js +++ b/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) { diff --git a/test/versioned/restify/restify-post-7/async-handlers.tap.js b/test/versioned/restify/restify-post-7/async-handlers.tap.js new file mode 100644 index 0000000000..ee6729ade7 --- /dev/null +++ b/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() + }) + }) + }) +}) diff --git a/test/versioned/restify/restify-post-7/capture-params.tap.js b/test/versioned/restify/restify-post-7/capture-params.tap.js index 33b224201d..0af0df5977 100644 --- a/test/versioned/restify/restify-post-7/capture-params.tap.js +++ b/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() }) }) diff --git a/test/versioned/restify/restify-post-7/common.js b/test/versioned/restify/restify-post-7/common.js new file mode 100644 index 0000000000..5e07ee1ef3 --- /dev/null +++ b/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) + }) +} diff --git a/test/versioned/restify/restify-post-7/package.json b/test/versioned/restify/restify-post-7/package.json index 4bde0301c6..3c44ace13e 100644 --- a/test/versioned/restify/restify-post-7/package.json +++ b/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", diff --git a/test/versioned/restify/restify-post-7/transaction-naming.tap.js b/test/versioned/restify/restify-post-7/transaction-naming.tap.js index cded783b1a..83817aec33 100644 --- a/test/versioned/restify/restify-post-7/transaction-naming.tap.js +++ b/test/versioned/restify/restify-post-7/transaction-naming.tap.js @@ -8,6 +8,7 @@ const helper = require('../../../lib/agent_helper') const tap = require('tap') const semver = require('semver') +const { runTest } = require('./common') tap.test('Restify transaction naming', (t) => { t.autoend() @@ -44,7 +45,7 @@ tap.test('Restify transaction naming', (t) => { next() }) - runTest({ t, endpoint: '/path1', expectedName: 'GET//path1' }) + runTest({ agent, server, t, endpoint: '/path1', expectedName: 'GET//path1' }) }) t.test('transaction name with async response middleware', (t) => { @@ -67,6 +68,8 @@ tap.test('Restify transaction naming', (t) => { }) runTest({ + agent, + server, t, endpoint: '/path1', expectedName: 'GET//path1', @@ -94,6 +97,8 @@ tap.test('Restify transaction naming', (t) => { }) runTest({ + agent, + server, t, endpoint: '/path1', expectedName: 'GET//path1', @@ -124,6 +129,8 @@ tap.test('Restify transaction naming', (t) => { }) runTest({ + agent, + server, t, endpoint: '/path1', expectedName: 'GET//path1', @@ -147,6 +154,8 @@ tap.test('Restify transaction naming', (t) => { }) runTest({ + agent, + server, t, endpoint: '/path1', expectedName: 'GET//path1', @@ -163,7 +172,14 @@ tap.test('Restify transaction naming', (t) => { next() }) - runTest({ t, endpoint: '/foobar', prefix: 'Nodejs', expectedName: 'GET/(not found)' }) + runTest({ + agent, + server, + t, + endpoint: '/foobar', + prefix: 'Nodejs', + expectedName: 'GET/(not found)' + }) }) t.test('transaction name contains trailing slash', (t) => { @@ -175,7 +191,7 @@ tap.test('Restify transaction naming', (t) => { next() }) - runTest({ t, endpoint: '/path/', expectedName: 'GET//path/' }) + runTest({ agent, server, t, endpoint: '/path/', expectedName: 'GET//path/' }) }) t.test('transaction name does not contain trailing slash', (t) => { @@ -187,7 +203,7 @@ tap.test('Restify transaction naming', (t) => { next() }) - runTest({ t, endpoint: '/path', expectedName: 'GET//path' }) + runTest({ agent, server, t, endpoint: '/path', expectedName: 'GET//path' }) }) t.test('transaction name with route that has multiple handlers', (t) => { @@ -206,7 +222,7 @@ tap.test('Restify transaction naming', (t) => { } ) - runTest({ t, endpoint: '/path1', expectedName: 'GET//path1' }) + runTest({ agent, server, t, endpoint: '/path1', expectedName: 'GET//path1' }) }) t.test('transaction name with middleware', (t) => { @@ -222,7 +238,7 @@ tap.test('Restify transaction naming', (t) => { next() }) - runTest({ t, endpoint: '/path1', expectedName: 'GET//path1' }) + runTest({ agent, server, t, endpoint: '/path1', expectedName: 'GET//path1' }) }) t.test('with error', (t) => { @@ -234,7 +250,7 @@ tap.test('Restify transaction naming', (t) => { next(new errors.InternalServerError('foobar')) }) - runTest({ t, endpoint: '/path1', expectedName: 'GET//path1' }) + runTest({ agent, server, t, endpoint: '/path1', expectedName: 'GET//path1' }) }) t.test('with error while out of context', (t) => { @@ -248,7 +264,7 @@ tap.test('Restify transaction naming', (t) => { }) }) - runTest({ t, endpoint: '/path1', expectedName: 'GET//path1' }) + runTest({ agent, server, t, endpoint: '/path1', expectedName: 'GET//path1' }) }) t.test('when using a route variable', (t) => { @@ -260,7 +276,7 @@ tap.test('Restify transaction naming', (t) => { next() }) - runTest({ t, endpoint: '/foo/fizz', expectedName: 'GET//foo/:bar' }) + runTest({ agent, server, t, endpoint: '/foo/fizz', expectedName: 'GET//foo/:bar' }) }) t.test('when using a regular expression in path', (t) => { @@ -272,7 +288,7 @@ tap.test('Restify transaction naming', (t) => { next() }) - runTest({ t, endpoint: '/foo/bar', expectedName: 'GET//foo/*' }) + runTest({ agent, server, t, endpoint: '/foo/bar', expectedName: 'GET//foo/*' }) }) t.test('when next is called after transaction state loss', (t) => { @@ -296,7 +312,7 @@ tap.test('Restify transaction naming', (t) => { next() }) - runTest({ t, endpoint: '/path1', expectedName: 'GET//path1' }) + runTest({ agent, server, t, endpoint: '/path1', expectedName: 'GET//path1' }) }) t.test('responding after transaction state loss', (t) => { @@ -310,7 +326,7 @@ tap.test('Restify transaction naming', (t) => { }) }) - runTest({ t, endpoint: '/path1', expectedName: 'GET//path1' }) + runTest({ agent, server, t, endpoint: '/path1', expectedName: 'GET//path1' }) }) t.test('responding with just a status code', (t) => { @@ -321,7 +337,7 @@ tap.test('Restify transaction naming', (t) => { next() }) - runTest({ t, endpoint: '/path1', expectedName: 'GET//path1' }) + runTest({ agent, server, t, endpoint: '/path1', expectedName: 'GET//path1' }) }) t.test('responding with just a status code after state loss', (t) => { @@ -334,32 +350,6 @@ tap.test('Restify transaction naming', (t) => { }) }) - runTest({ t, endpoint: '/path1', expectedName: 'GET//path1' }) + runTest({ agent, server, t, endpoint: '/path1', expectedName: 'GET//path1' }) }) - - /** - * @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] - */ - function runTest(cfg) { - const t = cfg.t - const endpoint = cfg.endpoint - const prefix = cfg.prefix || 'Restify' - const expectedName = `WebTransaction/${prefix}/${cfg.expectedName}` - - agent.on('transactionFinished', (tx) => { - t.equal(tx.name, expectedName, 'should have correct name') - ;(cfg.cb && cfg.cb()) || t.end() - }) - - server.listen(() => { - const port = server.address().port - helper.makeGetRequest(`http://localhost:${port}${endpoint}`, cfg.requestOpts || null) - }) - } })