From 18ae75c6004d66744ee99be68469843372c19d1e Mon Sep 17 00:00:00 2001 From: Trent Mick Date: Wed, 29 Nov 2023 10:19:44 -0800 Subject: [PATCH 1/2] fix(instrumentation-fastify): fix span attributes and avoid FSTDEP017 FastifyDeprecation warning for 404 request (#1763) For a 404 `request.routeOptions.url` is undefined. Since fastify@4.10.0 when routeOptions was added, we shouldn't fallback to the deprecated request.routerPath. This also corrects the assumption that the handler name is "bound ..." in all cases. E.g. for a 404 it is Fastify's core "basic404" internal function. Also add a test that Fastify instrumentation works for ESM usage. Fixes: https://github.com/open-telemetry/opentelemetry-js-contrib/issues/1757 Co-authored-by: Marc Pichler --- package-lock.json | 18 +++++ .../.tav.yml | 6 +- .../package.json | 3 + .../src/instrumentation.ts | 16 +++-- .../test/fixtures/use-fastify.mjs | 54 +++++++++++++++ .../test/instrumentation.test.ts | 66 +++++++++++++++++-- 6 files changed, 151 insertions(+), 12 deletions(-) create mode 100644 plugins/node/opentelemetry-instrumentation-fastify/test/fixtures/use-fastify.mjs diff --git a/package-lock.json b/package-lock.json index 61fdc62e2d..9e8125ce7a 100644 --- a/package-lock.json +++ b/package-lock.json @@ -34977,16 +34977,19 @@ "@fastify/express": "^2.0.2", "@opentelemetry/api": "^1.3.0", "@opentelemetry/context-async-hooks": "^1.8.0", + "@opentelemetry/contrib-test-utils": "^0.35.0", "@opentelemetry/instrumentation-http": "^0.45.1", "@opentelemetry/sdk-trace-base": "^1.8.0", "@opentelemetry/sdk-trace-node": "^1.8.0", "@types/express": "4.17.18", "@types/mocha": "7.0.2", "@types/node": "18.15.3", + "@types/semver": "7.5.5", "fastify": "4.18.0", "mocha": "7.2.0", "nyc": "15.1.0", "rimraf": "5.0.5", + "semver": "^7.5.4", "test-all-versions": "5.0.1", "ts-mocha": "10.0.0", "typescript": "4.4.4" @@ -35010,6 +35013,12 @@ "integrity": "sha512-p6ua9zBxz5otCmbpb5D3U4B5Nanw6Pk3PPyX05xnxbB/fRv71N7CPmORg7uAD5P70T0xmx1pzAx/FUfa5X+3cw==", "dev": true }, + "plugins/node/opentelemetry-instrumentation-fastify/node_modules/@types/semver": { + "version": "7.5.5", + "resolved": "https://registry.npmjs.org/@types/semver/-/semver-7.5.5.tgz", + "integrity": "sha512-+d+WYC1BxJ6yVOgUgzK8gWvp5qF8ssV5r4nsDcZWKRWcDQLQ619tvWAxJQYGgBrO1MnLJC7a5GtiYsAoQ47dJg==", + "dev": true + }, "plugins/node/opentelemetry-instrumentation-generic-pool": { "name": "@opentelemetry/instrumentation-generic-pool", "version": "0.32.4", @@ -43443,6 +43452,7 @@ "@fastify/express": "^2.0.2", "@opentelemetry/api": "^1.3.0", "@opentelemetry/context-async-hooks": "^1.8.0", + "@opentelemetry/contrib-test-utils": "^0.35.0", "@opentelemetry/core": "^1.8.0", "@opentelemetry/instrumentation": "^0.45.1", "@opentelemetry/instrumentation-http": "^0.45.1", @@ -43452,10 +43462,12 @@ "@types/express": "4.17.18", "@types/mocha": "7.0.2", "@types/node": "18.15.3", + "@types/semver": "7.5.5", "fastify": "4.18.0", "mocha": "7.2.0", "nyc": "15.1.0", "rimraf": "5.0.5", + "semver": "^7.5.4", "test-all-versions": "5.0.1", "ts-mocha": "10.0.0", "typescript": "4.4.4" @@ -43472,6 +43484,12 @@ "resolved": "https://registry.npmjs.org/@types/node/-/node-18.15.3.tgz", "integrity": "sha512-p6ua9zBxz5otCmbpb5D3U4B5Nanw6Pk3PPyX05xnxbB/fRv71N7CPmORg7uAD5P70T0xmx1pzAx/FUfa5X+3cw==", "dev": true + }, + "@types/semver": { + "version": "7.5.5", + "resolved": "https://registry.npmjs.org/@types/semver/-/semver-7.5.5.tgz", + "integrity": "sha512-+d+WYC1BxJ6yVOgUgzK8gWvp5qF8ssV5r4nsDcZWKRWcDQLQ619tvWAxJQYGgBrO1MnLJC7a5GtiYsAoQ47dJg==", + "dev": true } } }, diff --git a/plugins/node/opentelemetry-instrumentation-fastify/.tav.yml b/plugins/node/opentelemetry-instrumentation-fastify/.tav.yml index d20da709a9..48410d0903 100644 --- a/plugins/node/opentelemetry-instrumentation-fastify/.tav.yml +++ b/plugins/node/opentelemetry-instrumentation-fastify/.tav.yml @@ -1,5 +1,9 @@ "fastify": - - versions: "4.23.2" + # Sanity check the first 4.x release, instead of all releases, plus recent + # releases. + - versions: "4.0.0 || >=4.24.3 <5" commands: npm run test + +# Fastify versions after 4.18.0 require a typescript greater than 4.4.4. "typescript": - versions: "4.7.4" diff --git a/plugins/node/opentelemetry-instrumentation-fastify/package.json b/plugins/node/opentelemetry-instrumentation-fastify/package.json index c65828d8bc..a0c12a1418 100644 --- a/plugins/node/opentelemetry-instrumentation-fastify/package.json +++ b/plugins/node/opentelemetry-instrumentation-fastify/package.json @@ -46,16 +46,19 @@ "@fastify/express": "^2.0.2", "@opentelemetry/api": "^1.3.0", "@opentelemetry/context-async-hooks": "^1.8.0", + "@opentelemetry/contrib-test-utils": "^0.35.0", "@opentelemetry/instrumentation-http": "^0.45.1", "@opentelemetry/sdk-trace-base": "^1.8.0", "@opentelemetry/sdk-trace-node": "^1.8.0", "@types/express": "4.17.18", "@types/mocha": "7.0.2", "@types/node": "18.15.3", + "@types/semver": "7.5.5", "fastify": "4.18.0", "mocha": "7.2.0", "nyc": "15.1.0", "rimraf": "5.0.5", + "semver": "^7.5.4", "test-all-versions": "5.0.1", "ts-mocha": "10.0.0", "typescript": "4.4.4" diff --git a/plugins/node/opentelemetry-instrumentation-fastify/src/instrumentation.ts b/plugins/node/opentelemetry-instrumentation-fastify/src/instrumentation.ts index e410b93bad..dacc257e97 100644 --- a/plugins/node/opentelemetry-instrumentation-fastify/src/instrumentation.ts +++ b/plugins/node/opentelemetry-instrumentation-fastify/src/instrumentation.ts @@ -96,8 +96,9 @@ export class FastifyInstrumentation extends InstrumentationBase { const anyRequest = request as any; const rpcMetadata = getRPCMetadata(context.active()); - const routeName = - anyRequest.routeOptions?.config?.url || request.routerPath; + const routeName = anyRequest.routeOptions + ? anyRequest.routeOptions.url // since fastify@4.10.0 + : request.routerPath; if (routeName && rpcMetadata?.type === RPCType.HTTP) { rpcMetadata.route = routeName; } @@ -265,9 +266,11 @@ export class FastifyInstrumentation extends InstrumentationBase { const anyRequest = request as any; const handler = - anyRequest.routeOptions?.handler || anyRequest.context?.handler || {}; + anyRequest.routeOptions?.handler || anyRequest.context?.handler; - const handlerName = handler?.name.substr(6); + const handlerName = handler?.name.startsWith('bound ') + ? handler.name.substr(6) + : handler?.name; const spanName = `${FastifyNames.REQUEST_HANDLER} - ${ handlerName || this.pluginName || ANONYMOUS_NAME }`; @@ -275,8 +278,9 @@ export class FastifyInstrumentation extends InstrumentationBase { const spanAttributes: SpanAttributes = { [AttributeNames.PLUGIN_NAME]: this.pluginName, [AttributeNames.FASTIFY_TYPE]: FastifyTypes.REQUEST_HANDLER, - [SemanticAttributes.HTTP_ROUTE]: - anyRequest.routeOptions?.config?.url || request.routerPath, + [SemanticAttributes.HTTP_ROUTE]: anyRequest.routeOptions + ? anyRequest.routeOptions.url // since fastify@4.10.0 + : request.routerPath, }; if (handlerName) { spanAttributes[AttributeNames.FASTIFY_NAME] = handlerName; diff --git a/plugins/node/opentelemetry-instrumentation-fastify/test/fixtures/use-fastify.mjs b/plugins/node/opentelemetry-instrumentation-fastify/test/fixtures/use-fastify.mjs new file mode 100644 index 0000000000..a0d81bcc38 --- /dev/null +++ b/plugins/node/opentelemetry-instrumentation-fastify/test/fixtures/use-fastify.mjs @@ -0,0 +1,54 @@ +/* + * Copyright The OpenTelemetry Authors + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * https://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +// Use fastify from an ES module: +// node --experimental-loader=@opentelemetry/instrumentation/hook.mjs use-fastify.mjs + +import { trace } from '@opentelemetry/api'; +import { createTestNodeSdk } from '@opentelemetry/contrib-test-utils'; + +import { FastifyInstrumentation } from '../../build/src/index.js'; + +const sdk = createTestNodeSdk({ + serviceName: 'use-fastify', + instrumentations: [ + new FastifyInstrumentation() + ] +}) +sdk.start(); + +import Fastify from 'fastify'; +import http from 'http'; + +// Start a fastify server. +const app = Fastify(); +app.get('/a-route', function aRoute(_request, reply) { + reply.send({ hello: 'world' }); +}) +const addr = await app.listen({ port: 0 }); + +// Make a single request to it. +await new Promise(resolve => { + http.get(addr + '/a-route', (res) => { + res.resume(); + res.on('end', () => { + resolve(); + }); + }) +}) + +await app.close(); +await sdk.shutdown(); diff --git a/plugins/node/opentelemetry-instrumentation-fastify/test/instrumentation.test.ts b/plugins/node/opentelemetry-instrumentation-fastify/test/instrumentation.test.ts index 2efccaf724..3c0f541b06 100644 --- a/plugins/node/opentelemetry-instrumentation-fastify/test/instrumentation.test.ts +++ b/plugins/node/opentelemetry-instrumentation-fastify/test/instrumentation.test.ts @@ -25,6 +25,12 @@ import { SimpleSpanProcessor, } from '@opentelemetry/sdk-trace-base'; import { Span } from '@opentelemetry/api'; +import { + getPackageVersion, + runTestFixture, + TestCollector, +} from '@opentelemetry/contrib-test-utils'; +import * as semver from 'semver'; import * as http from 'http'; import { HttpInstrumentation } from '@opentelemetry/instrumentation-http'; import { AttributeNames, FastifyInstrumentation } from '../src'; @@ -32,6 +38,8 @@ import { FastifyRequestInfo } from '../src/types'; const URL = require('url').URL; +const fastifyVersion = getPackageVersion('fastify'); + const httpRequest = { get: (options: http.ClientRequestArgs | string) => { return new Promise((resolve, reject) => { @@ -183,6 +191,23 @@ describe('fastify', () => { assert.strictEqual(span.parentSpanId, baseSpan.spanContext().spanId); }); + it('should generate span for 404 request', async () => { + await startServer(); + await httpRequest.get(`http://localhost:${PORT}/no-such-route`); + + const spans = memoryExporter.getFinishedSpans(); + assert.strictEqual(spans.length, 5); + const span = spans[2]; + assert.deepStrictEqual(span.attributes, { + 'fastify.name': 'basic404', + 'fastify.type': 'request_handler', + 'plugin.name': 'fastify -> @fastify/express', + }); + assert.strictEqual(span.name, 'request handler - basic404'); + const baseSpan = spans[1]; + assert.strictEqual(span.parentSpanId, baseSpan.spanContext().spanId); + }); + describe('when subsystem is registered', () => { beforeEach(async () => { httpInstrumentation.enable(); @@ -424,12 +449,17 @@ describe('fastify', () => { await startServer(); }); - it('preClose is not instrumented', async () => { - app.addHook('preClose', () => { - assertRootContextActive(); - }); + it('preClose is not instrumented', async function () { + // 'preClose' was added in fastify@4.16.0. + if (semver.lt(fastifyVersion, '4.16.0')) { + this.skip(); + } else { + app.addHook('preClose', () => { + assertRootContextActive(); + }); - await startServer(); + await startServer(); + } }); it('onClose is not instrumented', async () => { @@ -507,4 +537,30 @@ describe('fastify', () => { }); }); }); + + it('should work with ESM usage', async () => { + await runTestFixture({ + cwd: __dirname, + argv: ['fixtures/use-fastify.mjs'], + env: { + NODE_OPTIONS: + '--experimental-loader=@opentelemetry/instrumentation/hook.mjs', + NODE_NO_WARNINGS: '1', + }, + checkResult: (err, stdout, stderr) => { + assert.ifError(err); + }, + checkCollector: (collector: TestCollector) => { + const spans = collector.sortedSpans; + assert.strictEqual(spans.length, 1); + assert.strictEqual(spans[0].name, 'request handler - aRoute'); + assert.strictEqual( + spans[0].attributes.filter(a => a.key === 'plugin.name')[0]?.value + ?.stringValue, + 'fastify', + 'attribute plugin.name' + ); + }, + }); + }); }); From 4ca18626610c0ee3da38807da82c753b8763af95 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Rapha=C3=ABl=20Th=C3=A9riault?= <113933910+raphael-theriault-swi@users.noreply.github.com> Date: Thu, 30 Nov 2023 14:42:07 -0800 Subject: [PATCH 2/2] feat(express): record exceptions (#1657) --- .../src/instrumentation.ts | 64 ++++++++++--- .../src/utils.ts | 13 +++ .../test/express.test.ts | 90 ++++++++++++++++++- .../test/utils.test.ts | 23 +++++ 4 files changed, 176 insertions(+), 14 deletions(-) diff --git a/plugins/node/opentelemetry-instrumentation-express/src/instrumentation.ts b/plugins/node/opentelemetry-instrumentation-express/src/instrumentation.ts index c476649750..61d91b55e6 100644 --- a/plugins/node/opentelemetry-instrumentation-express/src/instrumentation.ts +++ b/plugins/node/opentelemetry-instrumentation-express/src/instrumentation.ts @@ -15,12 +15,23 @@ */ import { getRPCMetadata, RPCType } from '@opentelemetry/core'; -import { trace, context, diag, SpanAttributes } from '@opentelemetry/api'; +import { + trace, + context, + diag, + SpanAttributes, + SpanStatusCode, +} from '@opentelemetry/api'; import type * as express from 'express'; import { ExpressInstrumentationConfig, ExpressRequestInfo } from './types'; import { ExpressLayerType } from './enums/ExpressLayerType'; import { AttributeNames } from './enums/AttributeNames'; -import { getLayerMetadata, storeLayerPath, isLayerIgnored } from './utils'; +import { + asErrorAndMessage, + getLayerMetadata, + isLayerIgnored, + storeLayerPath, +} from './utils'; import { VERSION } from './version'; import { InstrumentationBase, @@ -176,6 +187,7 @@ export class ExpressInstrumentation extends InstrumentationBase< layer[kLayerPatched] = true; this._wrap(layer, 'handle', (original: Function) => { + // TODO: instrument error handlers if (original.length === 4) return original; return function ( this: ExpressLayer, @@ -262,29 +274,55 @@ export class ExpressInstrumentation extends InstrumentationBase< const callbackIdx = args.findIndex(arg => typeof arg === 'function'); if (callbackIdx >= 0) { arguments[callbackIdx] = function () { + // express considers anything but an empty value, "route" or "router" + // passed to its callback to be an error + const maybeError = arguments[0]; + const isError = ![undefined, null, 'route', 'router'].includes( + maybeError + ); + if (isError) { + const [error, message] = asErrorAndMessage(maybeError); + span.recordException(error); + span.setStatus({ + code: SpanStatusCode.ERROR, + message, + }); + } + if (spanHasEnded === false) { spanHasEnded = true; req.res?.removeListener('finish', onResponseFinish); span.end(); } - if (!(req.route && arguments[0] instanceof Error)) { + if (!(req.route && isError)) { (req[_LAYERS_STORE_PROPERTY] as string[]).pop(); } const callback = args[callbackIdx] as Function; return callback.apply(this, arguments); }; } - const result = original.apply(this, arguments); - /** - * At this point if the callback wasn't called, that means either the - * layer is asynchronous (so it will call the callback later on) or that - * the layer directly end the http response, so we'll hook into the "finish" - * event to handle the later case. - */ - if (!spanHasEnded) { - res.once('finish', onResponseFinish); + + try { + return original.apply(this, arguments); + } catch (anyError) { + const [error, message] = asErrorAndMessage(anyError); + span.recordException(error); + span.setStatus({ + code: SpanStatusCode.ERROR, + message, + }); + throw anyError; + } finally { + /** + * At this point if the callback wasn't called, that means either the + * layer is asynchronous (so it will call the callback later on) or that + * the layer directly end the http response, so we'll hook into the "finish" + * event to handle the later case. + */ + if (!spanHasEnded) { + res.once('finish', onResponseFinish); + } } - return result; }; }); } diff --git a/plugins/node/opentelemetry-instrumentation-express/src/utils.ts b/plugins/node/opentelemetry-instrumentation-express/src/utils.ts index d272434422..f543104e49 100644 --- a/plugins/node/opentelemetry-instrumentation-express/src/utils.ts +++ b/plugins/node/opentelemetry-instrumentation-express/src/utils.ts @@ -132,3 +132,16 @@ export const isLayerIgnored = ( return false; }; + +/** + * Converts a user-provided error value into an error and error message pair + * + * @param error - User-provided error value + * @returns Both an Error or string representation of the value and an error message + */ +export const asErrorAndMessage = ( + error: unknown +): [error: string | Error, message: string] => + error instanceof Error + ? [error, error.message] + : [String(error), String(error)]; diff --git a/plugins/node/opentelemetry-instrumentation-express/test/express.test.ts b/plugins/node/opentelemetry-instrumentation-express/test/express.test.ts index 64d6631409..80c0251815 100644 --- a/plugins/node/opentelemetry-instrumentation-express/test/express.test.ts +++ b/plugins/node/opentelemetry-instrumentation-express/test/express.test.ts @@ -14,7 +14,7 @@ * limitations under the License. */ -import { context, trace } from '@opentelemetry/api'; +import { SpanStatusCode, context, trace } from '@opentelemetry/api'; import { NodeTracerProvider } from '@opentelemetry/sdk-trace-node'; import { AsyncHooksContextManager } from '@opentelemetry/context-async-hooks'; import { @@ -255,6 +255,94 @@ describe('ExpressInstrumentation', () => { ); }); + it('captures sync middleware errors', async () => { + const rootSpan = tracer.startSpan('rootSpan'); + let finishListenerCount: number | undefined; + const httpServer = await serverWithMiddleware(tracer, rootSpan, app => { + app.use((req, res, next) => { + res.on('finish', () => { + finishListenerCount = res.listenerCount('finish'); + }); + next(); + }); + + const errorMiddleware: express.RequestHandler = (req, res, next) => { + throw new Error('message'); + }; + app.use(errorMiddleware); + }); + server = httpServer.server; + port = httpServer.port; + assert.strictEqual(memoryExporter.getFinishedSpans().length, 0); + + await context.with( + trace.setSpan(context.active(), rootSpan), + async () => { + await httpRequest.get(`http://localhost:${port}/toto/tata`); + rootSpan.end(); + assert.strictEqual(finishListenerCount, 3); + + const errorSpan = memoryExporter + .getFinishedSpans() + .find(span => span.name.includes('errorMiddleware')); + assert.notStrictEqual(errorSpan, undefined); + + assert.deepStrictEqual(errorSpan!.status, { + code: SpanStatusCode.ERROR, + message: 'message', + }); + assert.notStrictEqual( + errorSpan!.events.find(event => event.name === 'exception'), + undefined + ); + } + ); + }); + + it('captures async middleware errors', async () => { + const rootSpan = tracer.startSpan('rootSpan'); + let finishListenerCount: number | undefined; + const httpServer = await serverWithMiddleware(tracer, rootSpan, app => { + app.use((req, res, next) => { + res.on('finish', () => { + finishListenerCount = res.listenerCount('finish'); + }); + next(); + }); + + const errorMiddleware: express.RequestHandler = (req, res, next) => { + setTimeout(() => next(new Error('message')), 10); + }; + app.use(errorMiddleware); + }); + server = httpServer.server; + port = httpServer.port; + assert.strictEqual(memoryExporter.getFinishedSpans().length, 0); + + await context.with( + trace.setSpan(context.active(), rootSpan), + async () => { + await httpRequest.get(`http://localhost:${port}/toto/tata`); + rootSpan.end(); + assert.strictEqual(finishListenerCount, 2); + + const errorSpan = memoryExporter + .getFinishedSpans() + .find(span => span.name.includes('errorMiddleware')); + assert.notStrictEqual(errorSpan, undefined); + + assert.deepStrictEqual(errorSpan!.status, { + code: SpanStatusCode.ERROR, + message: 'message', + }); + assert.notStrictEqual( + errorSpan!.events.find(event => event.name === 'exception'), + undefined + ); + } + ); + }); + it('should not create span because there are no parent', async () => { const app = express(); app.use(express.json()); diff --git a/plugins/node/opentelemetry-instrumentation-express/test/utils.test.ts b/plugins/node/opentelemetry-instrumentation-express/test/utils.test.ts index e85a677af1..fc927a9b7f 100644 --- a/plugins/node/opentelemetry-instrumentation-express/test/utils.test.ts +++ b/plugins/node/opentelemetry-instrumentation-express/test/utils.test.ts @@ -142,4 +142,27 @@ describe('Utils', () => { ); }); }); + + describe('asErrorAndMessage', () => { + it('should special case Error instances', () => { + const input = new Error('message'); + const [error, message] = utils.asErrorAndMessage(input); + assert.strictEqual(error, input); + assert.strictEqual(message, 'message'); + }); + + it('should pass strings as-is', () => { + const input = 'error'; + const [error, message] = utils.asErrorAndMessage(input); + assert.strictEqual(error, input); + assert.strictEqual(message, input); + }); + + it('should stringify other types', () => { + const input = 2; + const [error, message] = utils.asErrorAndMessage(input); + assert.strictEqual(error, '2'); + assert.strictEqual(message, '2'); + }); + }); });