fix(plugin-express): fix double span end #908

packages/opentelemetry-plugin-express/README.md

@@ -45,6 +45,10 @@ const provider = new NodeTracerProvider();
 
 See [examples/express](https://github.com/open-telemetry/opentelemetry-js/tree/master/examples/express) for a short example.
 
+### Caveats
+
+Because of the way express works, it's hard to correctly compute the time taken by asynchronous middlewares and request handlers. For this reason, the time you'll see reported for asynchronous middlewares and request handlers will only represent the synchronous execution time, and **not** any asynchronous work.
+
 ### Express Plugin Options
 
 Express plugin has few options available to choose from. You can set the following:

packages/opentelemetry-plugin-express/src/express.ts

@@ -14,7 +14,7 @@
  * limitations under the License.
  */
 
-import { BasePlugin } from '@opentelemetry/core';
+import { BasePlugin, hrTime } from '@opentelemetry/core';
 import { Attributes } from '@opentelemetry/api';
 import * as express from 'express';
 import * as core from 'express-serve-static-core';
@@ -30,12 +30,7 @@ import {
   ExpressPluginConfig,
   ExpressLayerType,
 } from './types';
-import {
-  getLayerMetadata,
-  storeLayerPath,
-  patchEnd,
-  isLayerIgnored,
-} from './utils';
+import { getLayerMetadata, storeLayerPath, isLayerIgnored } from './utils';
 import { VERSION } from './version';
 
 /**
@@ -190,26 +185,40 @@ export class ExpressPlugin extends BasePlugin<typeof express> {
         const span = plugin._tracer.startSpan(metadata.name, {
           attributes: Object.assign(attributes, metadata.attributes),
         });
+        const startTime = hrTime();
+        let spanHasEnded: boolean = false;
+        // If we found anything that isnt a middleware, there no point of measuring
+        // stheir time ince they dont have callback.
+        if (
+          metadata.attributes[AttributeNames.EXPRESS_TYPE] !==
+          ExpressLayerType.MIDDLEWARE
+        ) {
+          span.end(startTime);
+          spanHasEnded = true;
+        }
         // verify we have a callback
-        let callbackIdx = Array.from(arguments).findIndex(
-          arg => typeof arg === 'function'
-        );
-        let callbackHasBeenCalled = false;
+        const args = Array.from(arguments);
+        const callbackIdx = args.findIndex(arg => typeof arg === 'function');
         if (callbackIdx >= 0) {
           arguments[callbackIdx] = function() {
-            callbackHasBeenCalled = true;
+            if (spanHasEnded === false) {
+              span.end();
+              spanHasEnded = true;
+            }
             if (!(req.route && arguments[0] instanceof Error)) {
               (req[_LAYERS_STORE_PROPERTY] as string[]).pop();
             }
-            return patchEnd(span, plugin._tracer.bind(next))();
+            const callback = args[callbackIdx] as Function;
+            return plugin._tracer.bind(callback).apply(this, arguments);
           };
         }
         const result = original.apply(this, arguments);
-        // if the layer return a response, the callback will never
-        // be called, so we need to manually close the span
-        if (callbackHasBeenCalled === false) {
-          span.end();
-        }
+        // If the callback is never called, we need to close the span.
+        setImmediate(() => {
+          if (spanHasEnded === false) {
+            span.end(startTime);
+          }
+        }).unref();
         return result;
       };
     });

packages/opentelemetry-plugin-express/src/utils.ts

@@ -14,7 +14,7 @@
  * limitations under the License.
  */
 
-import { CanonicalCode, Span, Attributes } from '@opentelemetry/api';
+import { Attributes } from '@opentelemetry/api';
 import {
   ExpressLayer,
   AttributeNames,
@@ -67,7 +67,7 @@ export const getLayerMetadata = (
         [AttributeNames.EXPRESS_NAME]: layerPath ?? 'request handler',
         [AttributeNames.EXPRESS_TYPE]: ExpressLayerType.REQUEST_HANDLER,
       },
-      name: 'request handler',
+      name: `request handler${layer.path ? ` - ${layerPath}` : ''}`,
     };
   } else {
     return {
@@ -80,29 +80,6 @@ export const getLayerMetadata = (
   }
 };
 
-/**
- * Ends a created span.
- * @param span The created span to end.
- * @param resultHandler A callback function.
- */
-export const patchEnd = (span: Span, resultHandler: Function): Function => {
-  return function patchedEnd(this: {}, ...args: unknown[]) {
-    const error = args[0];
-    if (error instanceof Error) {
-      span.setStatus({
-        code: CanonicalCode.INTERNAL,
-        message: error.message,
-      });
-    } else {
-      span.setStatus({
-        code: CanonicalCode.OK,
-      });
-    }
-    span.end();
-    return resultHandler.apply(this, args);
-  };
-};
-
 /**
  * Check whether the given obj match pattern
  * @param constant e.g URL of request

packages/opentelemetry-plugin-express/src/version.ts

@@ -15,4 +15,4 @@
  */
 
 // this is autogenerated file, see scripts/version-update.js
-export const VERSION = '0.6.1';
+export const VERSION = '0.6.3';

packages/opentelemetry-plugin-express/test/express.test.ts

@@ -81,7 +81,7 @@ describe('Express Plugin', () => {
       const app = express();
       app.use(express.json());
       app.use(function customMiddleware(req, res, next) {
-        for (let i = 0; i < 1000; i++) {
+        for (let i = 0; i < 1000000; i++) {
           continue;
         }
         return next();