Dd-trace-js: Tracer breaking GraphQL subscriptions

[alizhdanov]

I'm getting an error Cannot redefine property: _datadog_span in graphql subscriptions results. Usually, the first result is successful, but the second one throwing this error. After that subscription not receiving any updates.

Any idea what might cause it?

I'm using apollo-server + dd-trace

apollo-server: 2.1.0
dd-trace: 0.8.0
node: 10.12.0

[rochdev]

It looks like this would happen if graphql.execute() is called multiple times on the same document. The current implementation assumes this cannot happen, but it seems the assumption was incorrect.

Does this happen only for subscriptions?

[alizhdanov]

Yes, only subscriptions.

[hkjorgensen]

Can confirm this bug!

It also happens on queries. I can execute the first operation successfully, but all other operations fail with the following error message:

TypeError: Cannot redefine property: _datadog_span
  at Function.defineProperty (<anonymous>)
  at addOperationSpan (/app/node_modules/dd-trace/src/plugins/graphql.js:224:10)
  at Object.executeWithTrace (/app/node_modules/dd-trace/src/plugins/graphql.js:26:7)
  at /app/node_modules/apollo-server-core/dist/requestPipeline.js:195:36

It can be fixed by restarting the server, rinse, repeat.

Dependencies

| name | version |
| :- | :- |
| dd-trace | 0.8.0 |
| graphql | 14.1.1 |
| apollo-server | 2.4.0 |
| apollo-server-micro | 2.4.0 |

[rochdev]

I am unable to reproduce the issue. Can you share a snippet of a minimal server that reproduces the issue?

[hkjorgensen]

@rochdev thanks for your message. Maybe this snippet can help you. It's our dd-trace setup code that's executed before anything else is required, etc.

const ddTrace = require("dd-trace");

const config = {
  hostname: process.env.APM_HOST,
  port: process.env.APM_PORT,
};

const createTracer = (hostname = config.hostname, port = config.port) => {
  const tracer = ddTrace.init({
    hostname,
    plugins: false,
    port,
    service: "app-graph",
  });

  tracer.use("http", { service: "app-graph-http" });
  tracer.use("graphql", { service: "app-graph-graphql" });

  return tracer;
};

module.exports = createTracer();

[rochdev]

@hkjorgensen Thanks for the snippet! However, what I'm looking for is the actual server code to replicate the issue. Can you provide a minimal snippet that shows how to reproduce the issue with graphql or apollo-server? This will allow me to set up a test case, understand what the issue is, and provide a fix in the next patch release.

[hkjorgensen]

@rochdev I was trying to gently dance around the core of your initial request 😂

I have to peel the layers off our GraphQL gateway, I'll try to isolate it tomorrow.

[hkjorgensen]

@rochdev here is a minimal setup that breaks:

package.json

{
  "private": true,
  "name": "foobar-graph",
  "version": "1.0.0",
  "scripts": {
    "start": "micro-dev src/index.js"
  },
  "dependencies": {
    "apollo-server-micro": "2.4.0",
    "dd-trace": "0.8.0",
    "graphql": "14.1.1",
    "micro": "9.3.3",
    "micro-dev": "3.0.0",
    "microrouter": "3.1.3"
  },
  "engines": {
    "node": "10.15.0"
  }
}

src/index.js

const ddTrace = require("dd-trace");

const config = {
  hostname: process.env.APM_HOST,
  port: process.env.APM_PORT,
};

const createTracer = (hostname = config.hostname, port = config.port) => {
  const tracer = ddTrace.init({
    hostname,
    plugins: false,
    port,
    service: "foobar-graph",
  });

  tracer.use("http", { service: "foobar-graph-http" });
  tracer.use("graphql", { service: "foobar-graph-graphql" });

  return tracer;
};

createTracer();

const { ApolloServer, gql } = require("apollo-server-micro");

const typeDefs = gql`
  type Query {
    sayHello: String
  }
`;

const resolvers = {
  Query: {
    sayHello() {
      return "Hello World!";
    },
  },
};

const apolloServer = new ApolloServer({ typeDefs, resolvers });
const { router, get, post } = require("microrouter");

const GRAPHQL_MOUNT_PATH = "/foobar/graphql";

const graphqlHandler = apolloServer.createHandler({
  path: GRAPHQL_MOUNT_PATH,
});

module.exports = router(
  post(GRAPHQL_MOUNT_PATH, graphqlHandler),
  get(GRAPHQL_MOUNT_PATH, graphqlHandler)
);

Start the server

npm start

Goto http://localhost:3000/foobar/graphql

Execute the following query one time via the "play" button:

query {
  sayHello
}

Result:

{
  "data": {
    "sayHello": "Hello World!"
  }
}

Execute the same query again via the "play" button:

{
  "error": {
    "errors": [
      {
        "message": "Cannot redefine property: _datadog_span",
        "extensions": {
          "code": "INTERNAL_SERVER_ERROR",
          "exception": {
            "stacktrace": [
              "TypeError: Cannot redefine property: _datadog_span",
              "    at Function.defineProperty (<anonymous>)",
              "    at addOperationSpan (/Users/xyz/Code/foobar-graph/node_modules/dd-trace/src/plugins/graphql.js:224:10)",
              "    at Object.executeWithTrace (/Users/xyz/Code/foobar-graph/node_modules/dd-trace/src/plugins/graphql.js:26:7)",
              "    at /Users/xyz/Code/foobar-graph/node_modules/apollo-server-core/dist/requestPipeline.js:195:36",
              "    at Generator.next (<anonymous>)",
              "    at /Users/xyz/Code/foobar-graph/node_modules/apollo-server-core/dist/requestPipeline.js:7:71",
              "    at new Promise (<anonymous>)",
              "    at __awaiter (/Users/xyz/Code/foobar-graph/node_modules/apollo-server-core/dist/requestPipeline.js:3:12)",
              "    at execute (/Users/xyz/Code/foobar-graph/node_modules/apollo-server-core/dist/requestPipeline.js:179:20)",
              "    at Object.<anonymous> (/Users/xyz/Code/foobar-graph/node_modules/apollo-server-core/dist/requestPipeline.js:133:35)"
            ]
          }
        }
      }
    ]
  }
}

[rochdev]

Thanks @hkjorgensen! Looking into it now.

[thalkz]

I'm having the exact same issue with subscriptions, but queries and mutations work just fine (even with multiple calls)

[rochdev]

A fix is on its way, but it will be in v0.9.0 because it's a breaking change as it relies on the new scope manager that is only available in v0.9.0. I'll try to publish a beta release in the next couple days.

[hkjorgensen]

@rochdev thanks for the quick response, do you have a guestimate when v0.9.0 will be released?

[rochdev]

@hkjorgensen v0.9.0 is scheduled for GA probably around end of next week. I'll try to have a beta release out today.

[adigarg]

Hi, this is affecting us as well, could we get an ETA on the beta release please? Thank you very much!

[rochdev]

Sorry for the radio silence these last few days. We realized that this was actually caused by the way we were instrumenting GraphQL, so we decided to actually rewrite it from the ground up according to the Apollo Engine Reporting format.

You can try the new version in 0.9.0-beta.6. Because we changed what data is captured, this was released as a "major" version. If you are using the scope manager, it was also rewritten in this version, so you should migrate to the new scope manager of which you can find the API here.

Please let me know if you encounter any issues updating or with the new format, and of course also if it fixes this issue completely. There will be a few follow up betas in the next couple days after which we plan to officially release 0.9.0.

[adigarg]

Hi @rochdev, we don't use scoping and just use ddtrace and all the default plugins with opentracing. With the 0.9.0-beta.6 all our issues have been fixed. Thank you for the quick turnaround.

[rochdev]

Fixed in 0.9.0