fix(express): span name if middleware on nested router is used (#2682)

Author: RigoTamas

plugins/node/opentelemetry-instrumentation-express/src/instrumentation.ts

@@ -171,7 +171,7 @@ export class ExpressInstrumentation extends InstrumentationBase<ExpressInstrumen
         req: PatchedRequest,
         res: express.Response
       ) {
-        storeLayerPath(req, layerPath);
+        const { isLayerPathStored } = storeLayerPath(req, layerPath);
         const route = (req[_LAYERS_STORE_PROPERTY] as string[])
           .filter(path => path !== '/' && path !== '/*')
           .join('')
@@ -280,7 +280,7 @@ export class ExpressInstrumentation extends InstrumentationBase<ExpressInstrumen
               req.res?.removeListener('finish', onResponseFinish);
               span.end();
             }
-            if (!(req.route && isError)) {
+            if (!(req.route && isError) && isLayerPathStored) {
               (req[_LAYERS_STORE_PROPERTY] as string[]).pop();
             }
             const callback = args[callbackIdx] as Function;

plugins/node/opentelemetry-instrumentation-express/src/utils.ts

@@ -33,15 +33,21 @@ import {
  * @param request The request where
  * @param [value] the value to push into the array
  */
-export const storeLayerPath = (request: PatchedRequest, value?: string) => {
+export const storeLayerPath = (
+  request: PatchedRequest,
+  value?: string
+): { isLayerPathStored: boolean } => {
   if (Array.isArray(request[_LAYERS_STORE_PROPERTY]) === false) {
     Object.defineProperty(request, _LAYERS_STORE_PROPERTY, {
       enumerable: false,
       value: [],
     });
   }
-  if (value === undefined) return;
+  if (value === undefined) return { isLayerPathStored: false };
+
   (request[_LAYERS_STORE_PROPERTY] as string[]).push(value);
+
+  return { isLayerPathStored: true };
 };
 
 /**

plugins/node/opentelemetry-instrumentation-express/test/express.test.ts

@@ -709,15 +709,18 @@ describe('ExpressInstrumentation', () => {
         assert.strictEqual(spans[5].name, 'router - /api/user/:id');
         assert.strictEqual(spans[5].kind, testUtils.OtlpSpanKind.INTERNAL);
         assert.strictEqual(spans[5].parentSpanId, spans[1].spanId);
-        assert.strictEqual(spans[6].name, 'router - /:postId');
+        assert.strictEqual(spans[6].name, 'router - /api/user/:id/posts');
         assert.strictEqual(spans[6].kind, testUtils.OtlpSpanKind.INTERNAL);
         assert.strictEqual(spans[6].parentSpanId, spans[1].spanId);
+        assert.strictEqual(spans[7].name, 'middleware - simpleMiddleware2');
+        assert.strictEqual(spans[7].kind, testUtils.OtlpSpanKind.INTERNAL);
+        assert.strictEqual(spans[7].parentSpanId, spans[1].spanId);
         assert.strictEqual(
-          spans[7].name,
+          spans[8].name,
           'request handler - /api/user/:id/posts/:postId'
         );
-        assert.strictEqual(spans[7].kind, testUtils.OtlpSpanKind.INTERNAL);
-        assert.strictEqual(spans[7].parentSpanId, spans[1].spanId);
+        assert.strictEqual(spans[8].kind, testUtils.OtlpSpanKind.INTERNAL);
+        assert.strictEqual(spans[8].parentSpanId, spans[1].spanId);
       },
     });
   });

plugins/node/opentelemetry-instrumentation-express/test/fixtures/use-express-nested-router.mjs

@@ -46,6 +46,14 @@ app.use(async function simpleMiddleware(req, res, next) {
 
 const userRouter = express.Router();
 const postsRouter = express.Router();
+postsRouter.use(async function simpleMiddleware2(req, res, next) {
+  // Wait a short delay to ensure this "middleware - ..." span clearly starts
+  // before the "router - ..." span. The test rely on a start-time-based sort
+  // of the produced spans. If they start in the same millisecond, then tests
+  // can be flaky.
+  await promisify(setTimeout)(10);
+  next();
+});
 
 postsRouter.get('/:postId', (req, res, next) => {
   res.json({ hello: 'yes' });
@@ -74,7 +82,7 @@ await new Promise(resolve => {
     res.on('end', data => {
       resolve(data);
     });
-  })
+  });
 });
 
 await new Promise(resolve => server.close(resolve));