plugin-express: end() called more than once on async handlers

[kellycampbell]

What version of OpenTelemetry are you using?

0.9.0

plugin-express 0.8.0

What version of Node are you using?

12.18.1

What did you do?

Use express.static, or an async handler like a database lookup.

Modified examples/express/server.js with the following:

diff --git a/examples/express/server.js b/examples/express/server.js
index 93cc2ca..960fe56 100644
--- a/examples/express/server.js
+++ b/examples/express/server.js
@@ -6,6 +6,7 @@ const tracer = require('./tracer')('example-express-server');
 // Require in rest of modules
 const express = require('express');
 const axios = require('axios').default;
+const path = require('path');
 
 // Setup express
 const app = express();
@@ -18,7 +19,9 @@ const getCrudController = () => {
   router.get('/', (req, res) => res.send(resources));
   router.post('/', (req, res) => {
     resources.push(req.body);
-    return res.status(201).send(req.body);
+    setTimeout(() => {
+      res.status(201).send(req.body);
+    }, 10);
   });
   return router;
 };
@@ -35,6 +38,8 @@ const authMiddleware = (req, res, next) => {
 async function setupRoutes() {
   app.use(express.json());
 
+  app.use(express.static(path.resolve(__dirname, "static")));
+
   app.get('/run_test', async (req, res) => {
     const createdCat = await axios.post(`http://localhost:${PORT}/cats`, {
       name: 'Tom',

What did you expect to see?

No errors in the console.

What did you see instead?

Can not execute the operation on ended Span {traceId: 9f5d0387252f1a3d06d0e65cb4b690ee, spanId: 7a4f169ce42367d6}
You can only call end() on a span once.
Can not execute the operation on ended Span {traceId: 286e8be1b14600409880d60206959991, spanId: e46cea1d0722cb41}
You can only call end() on a span once.

Additional context

Related to open-telemetry/opentelemetry-js#910

One fix that removes the symptoms but I'm not sure if it's the correct solution since it may not trace the work done in the async part of the handler is to add spanHasEnded = true; to the setImmediate at the end of _applyPatch:

  setImmediate(() => {
      if (spanHasEnded === false) {
          span.end(startTime);
+         spanHasEnded = true;
      }
  }).unref();

[dyladan]

@vmarchaud can you take a look at this?

[daudtacto]

@kellycampbell @dyladan I am facing the same issue. Did you find an alternate solution to avoid this one?

[vmarchaud]

Sorry for some reason i didn't saw this issue (thanks for the tag on gitter @daudtacto), i will look into this. Note that those are only "warnings", it doesn't impact performance nor can crash your app

[rhummelmose]

What is the status on this issue?

[vmarchaud]

@rhummelmose It has been merged but not yet published

[rhummelmose]

@vmarchaud Cool, I'll try to install from master 👍

[vmarchaud]

This has been released in v0.11.0