Express plugin does not work correctly when automatic loading of all plugins is disabled

[elen4]

Expected behaviour

When disabling automatic loading of all plugins and enabling only the express one, full traces (express.request and express.middleware spans) should still be created on incoming web requests.
Example:

Encoding trace: [{"trace_id":"4099d8328517f41f","span_id":"4099d8328517f41f","parent_id":"0000000000000000","name":"express.request","resource":"GET /","error":0,"meta":{"service":"dd-trace-express-plugin","version":"0.0.1","runtime-id":"c6f9ef2b-6966-40db-abd0-ef31bf62190e","http.url":"http://localhost:3500/","http.method":"GET","span.kind":"server","http.route":"/","http.status_code":"304","language":"javascript"},"metrics":{"_dd.agent_psr":1,"_dd.measured":1,"_sampling_priority_v1":1},"start":1655143338501038000,"duration":10841064,"service":"dd-trace-express-plugin","type":"web"},{"trace_id":"4099d8328517f41f","span_id":"2e63f0262cf3867c","parent_id":"4099d8328517f41f","name":"express.middleware","resource":"query","error":0,"meta":{"service":"dd-trace-express-plugin","version":"0.0.1","runtime-id":"c6f9ef2b-6966-40db-abd0-ef31bf62190e","language":"javascript"},"metrics":{"_sampling_priority_v1":1},"start":1655143338503605200,"duration":743164,"service":"dd-trace-express-plugin"},{"trace_id":"4099d8328517f41f","span_id":"476a7933e84da646","parent_id":"4099d8328517f41f","name":"express.middleware","resource":"expressInit","error":0,"meta":{"service":"dd-trace-express-plugin","version":"0.0.1","runtime-id":"c6f9ef2b-6966-40db-abd0-ef31bf62190e","language":"javascript"},"metrics":{"_sampling_priority_v1":1},"start":1655143338504606700,"duration":618896,"service":"dd-trace-express-plugin"},{"trace_id":"4099d8328517f41f","span_id":"3b425a5d2a9bfed2","parent_id":"4099d8328517f41f","name":"express.middleware","resource":"jsonParser","error":0,"meta":{"service":"dd-trace-express-plugin","version":"0.0.1","runtime-id":"c6f9ef2b-6966-40db-abd0-ef31bf62190e","language":"javascript"},"metrics":{"_sampling_priority_v1":1},"start":1655143338505478100,"duration":436523,"service":"dd-trace-express-plugin"},{"trace_id":"4099d8328517f41f","span_id":"4f8890da60dd77c5","parent_id":"4099d8328517f41f","name":"express.middleware","resource":"urlencodedParser","error":0,"meta":{"service":"dd-trace-express-plugin","version":"0.0.1","runtime-id":"c6f9ef2b-6966-40db-abd0-ef31bf62190e","language":"javascript"},"metrics":{"_sampling_priority_v1":1},"start":1655143338505971000,"duration":374512,"service":"dd-trace-express-plugin"},{"trace_id":"4099d8328517f41f","span_id":"069fa72efcd45bba","parent_id":"4099d8328517f41f","name":"express.middleware","resource":"bound dispatch","error":0,"meta":{"service":"dd-trace-express-plugin","version":"0.0.1","runtime-id":"c6f9ef2b-6966-40db-abd0-ef31bf62190e","language":"javascript"},"metrics":{"_sampling_priority_v1":1},"start":1655143338506747400,"duration":4236084,"service":"dd-trace-express-plugin"},{"trace_id":"4099d8328517f41f","span_id":"0c275cfc2ab7c776","parent_id":"069fa72efcd45bba","name":"express.middleware","resource":"<anonymous>","error":0,"meta":{"service":"dd-trace-express-plugin","version":"0.0.1","runtime-id":"c6f9ef2b-6966-40db-abd0-ef31bf62190e","language":"javascript"},"metrics":{"_sampling_priority_v1":1},"start":1655143338506919400,"duration":4052734,"service":"dd-trace-express-plugin"}]

Actual behaviour

Since version 2.7.0, we see no express.request span, only some "separated" middleware spans:

Encoding trace: [{"trace_id":"10775d8ac72e32a2","span_id":"10775d8ac72e32a2","parent_id":"0000000000000000","name":"express.middleware","resource":"query","error":0,"meta":{"service":"dd-trace-express-plugin","version":"0.0.1","runtime-id":"e04f6625-ebc6-4c90-a9fa-06417e09add9","language":"javascript"},"metrics":{"_dd.agent_psr":1,"_sampling_priority_v1":1},"start":1655143835344031200,"duration":707031,"service":"dd-trace-express-plugin"}]

Encoding trace: [{"trace_id":"10775d8ac72e32a2","span_id":"1779e611e06b6e78","parent_id":"10775d8ac72e32a2","name":"express.middleware","resource":"expressInit","error":0,"meta":{"service":"dd-trace-express-plugin","version":"0.0.1","runtime-id":"e04f6625-ebc6-4c90-a9fa-06417e09add9","language":"javascript"},"metrics":{"_sampling_priority_v1":1},"start":1655143835354699500,"duration":187256,"service":"dd-trace-express-plugin"}]

Encoding trace: [{"trace_id":"10775d8ac72e32a2","span_id":"3486abbf44526463","parent_id":"1779e611e06b6e78","name":"express.middleware","resource":"jsonParser","error":0,"meta":{"service":"dd-trace-express-plugin","version":"0.0.1","runtime-id":"e04f6625-ebc6-4c90-a9fa-06417e09add9","language":"javascript"},"metrics":{"_sampling_priority_v1":1},"start":1655143835356179500,"duration":325439,"service":"dd-trace-express-plugin"}]

Encoding trace: [{"trace_id":"10775d8ac72e32a2","span_id":"400e4d0ccc0c69a4","parent_id":"3486abbf44526463","name":"express.middleware","resource":"urlencodedParser","error":0,"meta":{"service":"dd-trace-express-plugin","version":"0.0.1","runtime-id":"e04f6625-ebc6-4c90-a9fa-06417e09add9","language":"javascript"},"metrics":{"_sampling_priority_v1":1},"start":1655143835359934700,"duration":104004,"service":"dd-trace-express-plugin"}]

Steps to reproduce

I created a project to reproduce the issue here.
Starting the project with

yarn install
DD_TRACE_DEBUG=true yarn run start

and hitting http://localhost:3500 I see the behaviour described above. I see the expected behaviour when setting plugin: true here or downgrading dd-trace version to 2.6.0 here.

Environment

• Operation system: macOS Monterey 12.4
• Node.js version: 16.5.0
• Tracer version: multiple
• Agent version:
• Relevant library versions:

[rochdev]

The express integration requires the http integration to be enabled to work properly. The fact that the middleware spans are still there anyway is definitely an oversight, but enabling the http integration would fix the issue. It's possible to enable only the server integration and not the client one with tracer.use('http', { client: false }). Generally speaking, we do not recommend disabling all plugins outside of debugging as it can have unintended side-effects like in this case.

[rochdev]

Closing as a solution was provided above. Please feel free to re-open if that doesn't work for your use case.

[susannakosic]

Hi @rochdev,
I believe I am stepping into this issue as well.
When upgrading from dd-trace@2.6 to 2.7 dd-trace express hook seems to stop working.

package.json

"dd-trace": "2.6.0",
"serverless-plugin-datadog": "^5.1.0",
"express": "4.18.2",
"engines": {
   "node": "^16",
    "npm": "please-use-yarn",
   "yarn": "^1"
},

app.ts
import './helpers/datadogTracer.init';

datadogTracer.init.ts

import tracer from 'dd-trace';
if (process.env.NODE_ENV !== 'test') {
  tracer.init();
  tracer.use('express', {
    hooks: {
      request: (span, req: RequestWithTraceContext) => {
        console.log(`express hook running`);  // This stops working when upgrading from 2.6 to 2.7
        span.addTags({
          context: flattenObject(req.traceContext),
        });
        const httpRoute = req.baseUrl + req.route.path;
        span.setTag('http.route', httpRoute);
      },
    },
    service: `xxx-api-${process.env.STAGE}-app`,
  });
}

[rochdev]

@susannakosic Did you upgrade to 2.7 only to isolate the version for debugging purpose? Do you have the same issue with 2.44?

[susannakosic]

@rochdev yes, I m upgrading from 1.x and I' ve spent some time trying to figure out at what point express integration breaks.

In 2.44 express plugin does not seem to work either.
Additionally I can see that in this version traces don't contain any 'express.middleware' span, while in 2.7 those appear even though 'express.request' span is missing.

[susannakosic]

@rochdev - I ve open #3502 and included a sample repo so that you can reproduce the issue.