Dd-trace-js: GraphQL Plugin Not Reporting Spans

[icirellik]

Describe the bug

TLDR: I think I found the line causing the problem. Skip to Potential Resolution.

I was trying to instrument our application using the dd-trace graphql plugin and noticed that anytime it was enabled our entire applications api tracing would stop working. The application works exceptionally when only the express and http plugins are loaded. The configuration that caused tracing to stop working is below.:

import tracer from "dd-trace"

function init() {
  tracer.init({
    service: "azul",
    hostname: "localhost",
    plugins: false,
    logger: { debug, error },
  })
  tracer.use("express", {
    service: "azul",
    headers: ["User-Agent", "X-User-ID"],
  })
  tracer.use("http", {
    service: "azul.http-client",
  })
  tracer.use("graphql", {
    service: "azul.graphql",
  })
}

If the graphql plugin is removed it starts working again.

Potential Resolution

After digging into the issue I discovered what I believe that the root cause. When I comment out the following line tracing starts working again and includes all the graphql traces.

https://github.com/DataDog/dd-trace-js/blob/f1204494de67121145adc10dfa0ea463b50aa080/packages/datadog-plugin-graphql/src/index.js#L58

A few lines above, you can see that startSpan is called. I believe that this in combination with the early exit is the issue. When it exits early it leaves an open span that finish will not be called for. It wasn't obvious at first that this would be an issue. That comment on the line makes it appear that this would work as expected.

As I continued to dig I discovered that the exporter, the method that eventually sends the spans to the DataDog Agent would never be called. It was being blocked because the started and finished span length would never be equal once of the spans that were never finished.

https://github.com/DataDog/dd-trace-js/blob/f1204494de67121145adc10dfa0ea463b50aa080/packages/dd-trace/src/span_processor.js#L14

There are a couple potential solutions here and I'd be willing to PR if desired. There either needs to be a way to abort a span or just don't create the span until we know it will be needed.

Related Issues

I think this issue is related to the following:

• https://github.com/DataDog/dd-trace-js/issues/706

Environment

• Operation system: macOS, Linux
• Node version: 10.20.1
• Tracer version: 0.20.3
• Agent version: datadog/agent:latest

[rochdev]

Thanks for the thorough investigation!

There either needs to be a way to abort a span or just don't create the span until we know it will be needed.

I'm actually not sure if the span should be aborted, or if it should always be finished but without the document tags when not available. Even if the returned document doesn't have an operation in its definition, the parsing still occurred and it might make sense to report this timing as a span. Said that, I think simply moving finish to a finally block could resolve the issue and guarantee that it's always called.

There are a couple potential solutions here and I'd be willing to PR if desired.

I should be able to get this fixed pretty quickly if you prefer, but otherwise definitely feel free to open a PR :) Just jet me know so that we're not duplicating work.

[icirellik]

Moving it the finally block makes perfect sense. I wasn't sure under what conditions a span should start and end. Sounds like you'll be able to get it fixed quicker than me, I'll just leave it to you.

[meiamsome]

Hi, I was just experiencing a similar issue, in that case whenever parse was being used to parse a schema (or fragments without an OperationDefinition node) then this will fail. The PR #960 worked in that code base when applied as well.

Of particular interest when using this in a standard GraphQL server, it would appear that sending valid GraphQL documents that are not Operations (e.g. just fragments). would result in hitting this condition, and so all such requests would not be correctly reported in DataDog.

[rochdev]

Fixed in 0.21.0. Thanks for the PR @icirellik !

[MadRabbit]

hmm, i think i'm having this one too. i'm on 0.24 and latest express-graphql + graphql. the only span i see is the graphql.parse, there is nothing underneath it