feat(express): record exceptions (open-telemetry#1657)

dynatrace-oss-contrib · Nov 30, 2023 · 4ca1862 · 4ca1862
1 parent 18ae75c
commit 4ca1862
Show file tree

Hide file tree

Showing 4 changed files with 176 additions and 14 deletions.
diff --git 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
@@ -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
@@ -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
@@ -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');
+    });
+  });
 });