GraphQL plugin: not waiting for promises in execute and resolve steps

[xavier-kairn]

Hello!

I am running into a little span/timing issue/question with the graphql plugin. From what I explored a bit, it feels like the promises in the execute and resolve steps are not thened, which leads to the timings and the spans confusing me a bit.

What version of OpenTelemetry are you using?

Using the GraphQL example: https://github.com/open-telemetry/opentelemetry-js-contrib/tree/master/examples/graphql

What version of Node are you using?

v12.19.0

What did you do?

I followed the example's installation and serve guidelines, went to the http://localhost:4000/graphql endpoint and played the following query:

query {
  authors {
    id
    name
    description
  }
}

The author.description field uses a Promise for its resolution, which is of interest to me for this issue 😉

What did you expect to see?

The call takes about 600ms according to my browser, most of which happens in the execute and also resolve steps. I was expecting to see a trace along the lines of:

In this trace, the execute span "includes" the resolve spans, and the timings look consistent with what my browser reports.

What did you see instead?

The current version of the example pushes the following trace:

The call that issued that trace took ~350ms according to the browser, and only ~45ms according to the trace. In addition, in the trace above, it looks like some resolve steps happen after the execute step, others during.

Additional context

It feels like the execute and resolve patches do not handle promises, making the spans look shorter than the actual execution.

The first screenshot was taken by playing a bit with the current implementation of @opentelemetry/instrumentation-graphql:

These lines:

• https://github.com/open-telemetry/opentelemetry-js-contrib/blob/master/plugins/node/opentelemetry-instrumentation-graphql/src/graphql.ts#L223 (for the execute step)
• https://github.com/open-telemetry/opentelemetry-js-contrib/blob/master/plugins/node/opentelemetry-instrumentation-graphql/src/utils.ts#L369 (for the resolve step)

were replaced by:

Promise.resolve(res)
  .then(() => endSpan(span, err)) // or field.span
  .catch((error) => endSpan(span, error)); // or field.span

I also found that the pg plugin handles promises that way: https://github.com/open-telemetry/opentelemetry-js-contrib/blob/master/plugins/node/opentelemetry-plugin-pg/src/pg.ts#L136-L155, which lead me to believe the graphql plugin could/should do something similar 😇

Let me know if you need any further information, I'll be happy to help/PR my updates.

[xavier-kairn]

Hi @obecny!

I have finally had the time to check the new version: it works perfectly for the resolve spans! 🎉 Thanks for looking into it!

However, since the execute step is still using the old safeExecuteInTheMiddle, it still suffers the issue. Maybe we should reopen this issue until it is fixed?

I went ahead and tried to find a fix, which I pushed there: xavier-kairn@0f3bd9e. The if is needed because the execution introspection query when starting the apollo-server expects it to be synchronous. npm run server:apollo in the example folder does not work without it (though there might be other queries that need to be sync and not wrapped in a Promise).

I saw you merged the safeExecuteInTheMiddle in the non-contrib repository, hence another option for this one could be to move the if and potential then around this line, in case such if does not belong in the main implementation.

To be noted that the test do not pass on my commit due to the span indices being incorrect again. If this commit can be of interest to you, I can fix the tests and push again on my fork 😊