diff --git a/lib/feature_flags.js b/lib/feature_flags.js index 9d8b920f67..242dd45098 100644 --- a/lib/feature_flags.js +++ b/lib/feature_flags.js @@ -7,13 +7,14 @@ // unreleased flags gating an active feature exports.prerelease = { - express5: false, await_support: true, - promise_segments: false, - reverse_naming_rules: false, - fastify_instrumentation: false, certificate_bundle: false, + express5: false, + fastify_instrumentation: false, new_promise_tracking: false, + promise_segments: false, + reverse_naming_rules: false, + undici_instrumentation: false, unresolved_promise_cleanup: true } diff --git a/lib/instrumentation/core/http-outbound.js b/lib/instrumentation/core/http-outbound.js index c6b6696000..8d545bf914 100644 --- a/lib/instrumentation/core/http-outbound.js +++ b/lib/instrumentation/core/http-outbound.js @@ -96,7 +96,7 @@ module.exports = function instrumentOutbound(agent, opts, makeRequest) { } else if (agent.config.cross_application_tracer.enabled) { cat.addCatHeaders(agent.config, transaction, outboundHeaders) } else { - logger.trace('CAT disabled, not adding headers!') + logger.trace('Both DT and CAT are disabled, not adding headers!') } if (Array.isArray(opts.headers)) { diff --git a/lib/instrumentation/undici.js b/lib/instrumentation/undici.js new file mode 100644 index 0000000000..181316ac89 --- /dev/null +++ b/lib/instrumentation/undici.js @@ -0,0 +1,254 @@ +/* + * Copyright 2021 New Relic Corporation. All rights reserved. + * SPDX-License-Identifier: Apache-2.0 + */ + +'use strict' + +const cat = require('../util/cat') +const recordExternal = require('../metrics/recorders/http_external') +const logger = require('../logger').child({ component: 'undici' }) +const NAMES = require('../metrics/names') +const NEWRELIC_SYNTHETICS_HEADER = 'x-newrelic-synthetics' +const SYMBOLS = { + SEGMENT: Symbol('__NR_segment'), + PARENT_SEGMENT: Symbol('__NR_parent_segment') +} + +let diagnosticsChannel = null +try { + diagnosticsChannel = require('diagnostics_channel') +} catch (e) { + // quick check to see if module exists + // module was not added until v15.x +} + +module.exports = function addUndiciChannels(agent, undici, modName, shim) { + if (!diagnosticsChannel || !agent.config.feature_flag.undici_instrumentation) { + logger.warn( + 'diagnostics_channel or feature_flag.undici_instrumentation = false. Skipping undici instrumentation.' + ) + return + } + + /** + * This event occurs after the Undici Request is created + * We will check current segment for opaque and also attach + * relevant headers to outgoing http request + * + * @param {Object} params + * @param {Object} params.request undici request object + */ + diagnosticsChannel.channel('undici:request:create').subscribe(({ request }) => { + const parent = shim.getSegment() + request[SYMBOLS.PARENT_SEGMENT] = parent + if (!parent || (parent && parent.opaque)) { + logger.trace( + 'Not capturing data for outbound request (%s) because parent segment opaque (%s)', + request.path, + parent.name + ) + + return + } + + const transaction = parent.transaction + const outboundHeaders = Object.create(null) + if (agent.config.encoding_key && transaction.syntheticsHeader) { + outboundHeaders[NEWRELIC_SYNTHETICS_HEADER] = transaction.syntheticsHeader + } + + if (agent.config.distributed_tracing.enabled) { + transaction.insertDistributedTraceHeaders(outboundHeaders) + } else if (agent.config.cross_application_tracer.enabled) { + cat.addCatHeaders(agent.config, transaction, outboundHeaders) + } else { + logger.trace('Both DT and CAT are disabled, not adding headers!') + } + + // eslint-disable-next-line guard-for-in + for (const key in outboundHeaders) { + request.addHeader(key, outboundHeaders[key]) + } + }) + + /** + * This event occurs right before the data is written to the socket. + * Undici has some abstracted headers that are only created at this time, one + * is the `host` header which we need to name the Undici segment. So in this + * handler we create, start and set the segment active, name it, and + * attach the url/procedure/request.parameters + * + * @param {Object} params + * @param {Object} params.request undicie request object + * @param {TLSSocket | net.Socket} socket active socket connection + * + */ + diagnosticsChannel.channel('undici:client:sendHeaders').subscribe(({ request, socket }) => { + const parentSegment = request[SYMBOLS.PARENT_SEGMENT] + if (!parentSegment || (parentSegment && parentSegment.opaque)) { + return + } + + const port = socket.remotePort + const isHttps = socket.servername + let urlString + if (isHttps) { + urlString = `https://${socket.servername}` + urlString += port === 443 ? request.path : `:${port}${request.path}` + } else { + urlString = `http://${socket._host}` + urlString += port === 80 ? request.path : `:${port}${request.path}` + } + + const url = new URL(urlString) + + const name = NAMES.EXTERNAL.PREFIX + url.host + url.pathname + const segment = shim.createSegment( + name, + recordExternal(url.host, 'undici'), + request[SYMBOLS.PARENT_SEGMENT] + ) + segment.start() + shim.setActiveSegment(segment) + segment.addAttribute('url', `${url.protocol}//${url.host}${url.pathname}`) + + url.searchParams.forEach((value, key) => { + segment.addSpanAttribute(`request.parameters.${key}`, value) + }) + segment.addAttribute('procedure', request.method || 'GET') + request[SYMBOLS.SEGMENT] = segment + }) + + /** + * This event occurs after the response headers have been received. + * We will add the relevant http response attributes to active segment. + * Also add CAT specific keys to active segment. + * + * @param {Object} params + * @param {Object} params.request undici request object + * @param {Object} params.response { statusCode, headers, statusText } + */ + diagnosticsChannel.channel('undici:request:headers').subscribe(({ request, response }) => { + const activeSegment = request[SYMBOLS.SEGMENT] + if (!activeSegment) { + return + } + + activeSegment.addSpanAttribute('http.statusCode', response.statusCode) + activeSegment.addSpanAttribute('http.statusText', response.statusText) + + if ( + agent.config.cross_application_tracer.enabled && + !agent.config.distributed_tracing.enabled + ) { + try { + const { appData } = cat.extractCatHeaders(response.headers) + const decodedAppData = cat.parseAppData(agent.config, appData) + const attrs = activeSegment.getAttributes() + const url = new URL(attrs.url) + cat.assignCatToSegment(decodedAppData, activeSegment, url.host) + } catch (err) { + logger.warn(err, 'Cannot add CAT data to segment') + } + } + }) + + /** + * This event occurs after the response body has been received. + * We will end the active segment and set the active back to parent before request + * @param {Object} params.request undici request object + */ + diagnosticsChannel.channel('undici:request:trailers').subscribe(({ request }) => { + endAndRestoreSegment(request) + }) + + /** + * This event occurs right before the request emits an error. + * We will end the active segment and set the active back to parent before request. + * We will also log errors to NR + * + * Note: This event occurs before the error handler so we will always log it for now. + */ + diagnosticsChannel.channel('undici:request:error').subscribe(({ request, error }) => { + endAndRestoreSegment(request, error) + }) + + /** + * This event occurs before creating connection to socket. + * We will create and start a segment for the `undici.Client.connect` + * + * @param {Object} params + * @param {Function} params.connector function to connect to socket + */ + diagnosticsChannel.channel('undici:client:beforeConnect').subscribe(({ connector }) => { + const parent = shim.getSegment() + const segment = shim.createSegment('undici.Client.connect') + connector[SYMBOLS.SEGMENT] = segment + connector[SYMBOLS.PARENT_SEGMENT] = parent + segment.start() + shim.setActiveSegment(segment) + }) + + /** + * This event occurs when the socket connection has been made. + * We will end the segment for the `undici.Client.connect` and restores parent + * to before connect + * + * @param {Object} params + * @param {Function} params.connector function to connect to socket + */ + diagnosticsChannel.channel('undici:client:connected').subscribe(({ connector }) => { + endAndRestoreSegment(connector) + }) + + /** + * This event occurs when connection to socket fails. + * We will end segment for the `undici.Client.connect` and restore parent + * to before connect. It will also attach the error to the transaction + * + * @param {Object} params + * @param {Function} params.connector function to connect to socket + */ + diagnosticsChannel.channel('undici:client:connectError').subscribe(({ connector, error }) => { + endAndRestoreSegment(connector, error) + }) + + /** + * Gets the active and parent from given ctx(request, client connector) + * and ends active and restores parent to active. If an error exists + * it will add the error to the transaction + * + * @param {Object} ctx request or client connector + * @param {Error} error + */ + function endAndRestoreSegment(ctx, error) { + const activeSegment = ctx[SYMBOLS.SEGMENT] + const parentSegment = ctx[SYMBOLS.PARENT_SEGMENT] + if (activeSegment) { + activeSegment.end() + + if (error) { + handleError(activeSegment, error) + } + + if (parentSegment) { + shim.setActiveSegment(parentSegment) + } + } + } + + /** + * Adds the error to the active transaction + * + * @param {TraceSegment} activeSegment + * @param {Error} error + */ + function handleError(activeSegment, error) { + logger.trace(error, 'Captured outbound error on behalf of the user.') + const tx = activeSegment.transaction + shim.agent.errors.add(tx, error) + } +} + +module.exports.SYMBOLS = SYMBOLS diff --git a/lib/instrumentations.js b/lib/instrumentations.js index 7316b34c72..c5044e56eb 100644 --- a/lib/instrumentations.js +++ b/lib/instrumentations.js @@ -31,6 +31,7 @@ module.exports = function instrumentations() { 'redis': { type: MODULE_TYPE.DATASTORE }, 'restify': { type: MODULE_TYPE.WEB_FRAMEWORK }, 'superagent': { module: '@newrelic/superagent' }, + 'undici': { type: MODULE_TYPE.TRANSACTION }, 'oracle': { type: null }, 'vision': { type: MODULE_TYPE.WEB_FRAMEWORK }, 'when': { type: null } diff --git a/test/unit/feature_flag.test.js b/test/unit/feature_flag.test.js index be4e0dc063..adb4bbced4 100644 --- a/test/unit/feature_flag.test.js +++ b/test/unit/feature_flag.test.js @@ -37,7 +37,8 @@ const used = [ 'fastify_instrumentation', 'certificate_bundle', 'new_promise_tracking', - 'unresolved_promise_cleanup' + 'unresolved_promise_cleanup', + 'undici_instrumentation' ] describe('feature flags', function () { diff --git a/test/unit/instrumentation/undici.test.js b/test/unit/instrumentation/undici.test.js new file mode 100644 index 0000000000..a5bd18e356 --- /dev/null +++ b/test/unit/instrumentation/undici.test.js @@ -0,0 +1,425 @@ +/* + * Copyright 2021 New Relic Corporation. All rights reserved. + * SPDX-License-Identifier: Apache-2.0 + */ + +'use strict' + +const tap = require('tap') +const sinon = require('sinon') +const semver = require('semver') +const proxyquire = require('proxyquire') +const helper = require('../../lib/agent_helper') +const TransactionShim = require('../../../lib/shim/transaction-shim') +const { DESTINATIONS } = require('../../../lib/config/attribute-filter') +const hashes = require('../../../lib/util/hashes') + +// diagnostics_channel only exists in Node 15+ +// but we only support even versions so check before running tests +const shouldSkip = semver.satisfies(process.version, '<16') + +tap.test('undici instrumentation', { skip: shouldSkip }, function (t) { + let agent + let loggerMock + let undiciInstrumentation + let channels + let shim + let SYMBOLS + let sandbox + + t.autoend() + + t.before(function () { + sandbox = sinon.createSandbox() + const diagnosticsChannel = require('diagnostics_channel') + channels = { + create: diagnosticsChannel.channel('undici:request:create'), + sendHeaders: diagnosticsChannel.channel('undici:client:sendHeaders'), + headers: diagnosticsChannel.channel('undici:request:headers'), + send: diagnosticsChannel.channel('undici:request:trailers'), + error: diagnosticsChannel.channel('undici:request:error'), + beforeConnect: diagnosticsChannel.channel('undici:client:beforeConnect'), + connected: diagnosticsChannel.channel('undici:client:connected'), + connectError: diagnosticsChannel.channel('undici:client:connectError') + } + agent = helper.loadMockedAgent() + agent.config.distributed_tracing.enabled = false + agent.config.cross_application_tracer.enabled = false + agent.config.feature_flag = { + undici_instrumentation: true + } + shim = new TransactionShim(agent, 'undici') + loggerMock = require('../mocks/logger')(sandbox) + undiciInstrumentation = proxyquire('../../../lib/instrumentation/undici', { + '../logger': { + child: sandbox.stub().callsFake(() => loggerMock) + } + }) + undiciInstrumentation(agent, 'undici', 'undici', shim) + SYMBOLS = undiciInstrumentation.SYMBOLS + }) + + function afterEach() { + sandbox.resetHistory() + agent.config.distributed_tracing.enabled = false + agent.config.cross_application_tracer.enabled = false + helper.unloadAgent(agent) + } + + t.test('should log warning if feature flag is not enabled', function (t) { + agent.config.feature_flag.undici_instrumentation = false + undiciInstrumentation(agent) + t.same(loggerMock.warn.args[0], [ + 'diagnostics_channel or feature_flag.undici_instrumentation = false. Skipping undici instrumentation.' + ]) + t.end() + }) + + t.test('request:create', function (t) { + t.autoend() + t.afterEach(afterEach) + + t.test('should not add headers when segment is opaque', function (t) { + helper.runInTransaction(agent, function (tx) { + const segment = tx.trace.add('parent') + segment.opaque = true + segment.start() + shim.setActiveSegment(segment) + channels.create.publish({ request: { path: '/foo' } }) + t.ok(loggerMock.trace.callCount, 1) + t.same(loggerMock.trace.args[0], [ + 'Not capturing data for outbound request (%s) because parent segment opaque (%s)', + '/foo', + 'parent' + ]) + t.end() + }) + }) + + t.test('should add synthetics header when it exists on transaction', function (t) { + agent.config.encoding_key = 'encKey' + helper.runInTransaction(agent, function (tx) { + tx.syntheticsHeader = 'synthHeader' + const request = { + addHeader: sandbox.stub(), + path: '/foo-2' + } + channels.create.publish({ request }) + t.ok(request[SYMBOLS.PARENT_SEGMENT]) + t.equal(request.addHeader.callCount, 1) + t.same(request.addHeader.args[0], ['x-newrelic-synthetics', 'synthHeader']) + t.end() + }) + }) + + t.test('should add DT headers when `distributed_tracing` is enabled', function (t) { + agent.config.distributed_tracing.enabled = true + helper.runInTransaction(agent, function () { + const addHeader = sandbox.stub() + channels.create.publish({ request: { path: '/foo-2', addHeader } }) + t.equal(addHeader.callCount, 2) + t.equal(addHeader.args[0][0], 'traceparent') + t.match(addHeader.args[0][1], /^[\w\d\-]{55}$/) + t.same(addHeader.args[1], ['newrelic', '']) + t.end() + }) + }) + + t.test('should add CAT headers when `cross_application_tracer` is enabled', function (t) { + agent.config.cross_application_tracer.enabled = true + helper.runInTransaction(agent, function () { + const addHeader = sandbox.stub() + channels.create.publish({ request: { path: '/foo-2', addHeader } }) + t.equal(addHeader.callCount, 1) + t.equal(addHeader.args[0][0], 'X-NewRelic-Transaction') + t.match(addHeader.args[0][1], /^[\w\d/-]{60,80}={0,2}$/) + t.end() + }) + }) + }) + + t.test('client:sendHeaders', function (t) { + t.autoend() + t.afterEach(afterEach) + + t.test('should not create segment is parent segment is opaque', function (t) { + helper.runInTransaction(agent, function () { + const before = shim.getSegment() + const request = {} + request[SYMBOLS.PARENT_SEGMENT] = { opaque: true } + channels.sendHeaders.publish({ request }) + const after = shim.getSegment() + t.same(before, after) + t.end() + }) + }) + + t.test('should name segment with appropriate attrs based on request.path', function (t) { + helper.runInTransaction(agent, function () { + const socket = { + remotePort: 443, + servername: 'unittesting.com' + } + const request = { + method: 'POST', + path: '/foo?a=b&c=d' + } + request[SYMBOLS.PARENT_SEGMENT] = shim.createSegment('parent') + channels.sendHeaders.publish({ request, socket }) + t.ok(request[SYMBOLS.SEGMENT]) + const segment = shim.getSegment() + t.equal(segment.name, 'External/unittesting.com/foo') + const attrs = segment.attributes.get(DESTINATIONS.SPAN_EVENT) + t.equal(attrs.url, 'https://unittesting.com/foo') + t.equal(attrs.procedure, 'POST') + t.equal(attrs['request.parameters.a'], 'b') + t.equal(attrs['request.parameters.c'], 'd') + t.end() + }) + }) + + t.test('should use proper url if http', function (t) { + helper.runInTransaction(agent, function () { + const socket = { + remotePort: 80, + _host: 'unittesting.com' + } + const request = { + method: 'POST', + path: '/http' + } + request[SYMBOLS.PARENT_SEGMENT] = shim.createSegment('parent') + channels.sendHeaders.publish({ request, socket }) + const segment = shim.getSegment() + t.equal(segment.name, 'External/unittesting.com/http') + const attrs = segment.attributes.get(DESTINATIONS.SPAN_EVENT) + t.equal(attrs.url, 'http://unittesting.com/http') + t.end() + }) + }) + + t.test('should use port in https if not 443', function (t) { + helper.runInTransaction(agent, function () { + const socket = { + remotePort: 9999, + servername: 'unittesting.com' + } + const request = { + method: 'POST', + path: '/port-https' + } + request[SYMBOLS.PARENT_SEGMENT] = shim.createSegment('parent') + channels.sendHeaders.publish({ request, socket }) + const segment = shim.getSegment() + t.equal(segment.name, 'External/unittesting.com:9999/port-https') + const attrs = segment.attributes.get(DESTINATIONS.SPAN_EVENT) + t.equal(attrs.url, 'https://unittesting.com:9999/port-https') + t.end() + }) + }) + + t.test('should use port in http if not 80', function (t) { + helper.runInTransaction(agent, function () { + const socket = { + remotePort: 8080, + _host: 'unittesting.com' + } + const request = { + method: 'POST', + path: '/port-http' + } + request[SYMBOLS.PARENT_SEGMENT] = shim.createSegment('parent') + channels.sendHeaders.publish({ request, socket }) + const segment = shim.getSegment() + t.equal(segment.name, 'External/unittesting.com:8080/port-http') + const attrs = segment.attributes.get(DESTINATIONS.SPAN_EVENT) + t.equal(attrs.url, 'http://unittesting.com:8080/port-http') + t.end() + }) + }) + }) + + t.test('request:headers', function (t) { + t.autoend() + t.afterEach(afterEach) + + t.test('should not add span attrs when there is not an active segment', function (t) { + helper.runInTransaction(agent, function () { + channels.headers.publish({ request: {} }) + const segment = shim.getSegment() + const attrs = segment.getAttributes() + t.same(Object.keys(attrs), []) + t.end() + }) + }) + + t.test('should add statusCode and statusText from response', function (t) { + helper.runInTransaction(agent, function () { + const segment = shim.createSegment('active') + const request = { + [SYMBOLS.SEGMENT]: segment + } + const response = { + statusCode: 200, + statusText: 'OK' + } + channels.headers.publish({ request, response }) + const attrs = segment.attributes.get(DESTINATIONS.SPAN_EVENT) + t.equal(attrs['http.statusCode'], 200) + t.equal(attrs['http.statusText'], 'OK') + t.end() + }) + }) + + t.test('should rename segment based on CAT data', function (t) { + agent.config.cross_application_tracer.enabled = true + agent.config.encoding_key = 'testing-key' + agent.config.trusted_account_ids = [111] + helper.runInTransaction(agent, function () { + const segment = shim.createSegment('active') + segment.addAttribute('url', 'https://www.unittesting.com/path') + const request = { + [SYMBOLS.SEGMENT]: segment + } + const response = { + headers: { + 'x-newrelic-app-data': hashes.obfuscateNameUsingKey( + JSON.stringify(['111#456', 'abc', 0, 0, -1, 'xyz']), + agent.config.encoding_key + ) + }, + statusCode: 200, + statusText: 'OK' + } + channels.headers.publish({ request, response }) + t.equal(segment.name, 'ExternalTransaction/www.unittesting.com/111#456/abc') + t.end() + }) + }) + }) + + t.test('request:trailers', function (t) { + t.autoend() + t.afterEach(afterEach) + + t.test('should end current segment and restore to parent', function (t) { + helper.runInTransaction(agent, function () { + const parentSegment = shim.createSegment('parent') + const segment = shim.createSegment('active') + shim.setActiveSegment(segment) + const request = { + [SYMBOLS.PARENT_SEGMENT]: parentSegment, + [SYMBOLS.SEGMENT]: segment + } + channels.send.publish({ request }) + t.equal(segment.timer.state, 3, 'previous active segment timer should be stopped') + t.same(parentSegment, shim.getSegment(), 'parentSegment should now the active') + t.end() + }) + }) + }) + + t.test('request:error', function (t) { + t.autoend() + t.afterEach(afterEach) + + t.test( + 'should end current segment and restore to parent and add error to active transaction', + function (t) { + helper.runInTransaction(agent, function (tx) { + sandbox.stub(tx.agent.errors, 'add') + const parentSegment = shim.createSegment('parent') + const segment = shim.createSegment('active') + shim.setActiveSegment(segment) + const error = new Error('request failed') + const request = { + [SYMBOLS.PARENT_SEGMENT]: parentSegment, + [SYMBOLS.SEGMENT]: segment + } + channels.error.publish({ request, error }) + t.equal(segment.timer.state, 3, 'previous active segment timer should be stopped') + t.same(parentSegment, shim.getSegment(), 'parentSegment should now the active') + t.same(loggerMock.trace.args[0], [ + error, + 'Captured outbound error on behalf of the user.' + ]) + t.same(tx.agent.errors.add.args[0], [tx, error]) + tx.agent.errors.add.restore() + t.end() + }) + } + ) + }) + + t.test('client:beforeConnect', function (t) { + t.autoend() + t.afterEach(afterEach) + + t.test('should add a segment for the undici.Client.connect', function (t) { + helper.runInTransaction(agent, function () { + const parentSegment = shim.createSegment('parent') + shim.setActiveSegment(parentSegment) + const connector = {} + channels.beforeConnect.publish({ connector }) + t.ok(connector[SYMBOLS.SEGMENT]) + t.ok(connector[SYMBOLS.PARENT_SEGMENT]) + const segment = shim.getSegment() + t.equal(segment.name, 'undici.Client.connect') + t.end() + }) + }) + }) + + t.test('client:connected', function (t) { + t.autoend() + t.afterEach(afterEach) + + t.test('should end current segment and restore to parent', function (t) { + helper.runInTransaction(agent, function () { + const parentSegment = shim.createSegment('parent') + const segment = shim.createSegment('active') + shim.setActiveSegment(segment) + const connector = { + [SYMBOLS.PARENT_SEGMENT]: parentSegment, + [SYMBOLS.SEGMENT]: segment + } + channels.connected.publish({ connector }) + t.equal(segment.timer.state, 3, 'previous active segment timer should be stopped') + t.same(parentSegment, shim.getSegment(), 'parentSegment should now the active') + t.end() + }) + }) + }) + + t.test('client:connectError', function (t) { + t.autoend() + t.afterEach(afterEach) + + t.test( + 'should end current segment and restore to parent and add error to active transaction', + function (t) { + helper.runInTransaction(agent, function (tx) { + sandbox.stub(tx.agent.errors, 'add') + const parentSegment = shim.createSegment('parent') + const segment = shim.createSegment('active') + shim.setActiveSegment(segment) + const error = new Error('failed to create socket connection') + const connector = { + [SYMBOLS.PARENT_SEGMENT]: parentSegment, + [SYMBOLS.SEGMENT]: segment + } + channels.connectError.publish({ connector, error }) + t.equal(segment.timer.state, 3, 'previous active segment timer should be stopped') + t.same(parentSegment, shim.getSegment(), 'parentSegment should now the active') + t.same(loggerMock.trace.args[0], [ + error, + 'Captured outbound error on behalf of the user.' + ]) + t.same(tx.agent.errors.add.args[0], [tx, error]) + tx.agent.errors.add.restore() + t.end() + }) + } + ) + }) +})