GraphQL throws TypeError: Cannot read property 'startToken' of undefined

[Multiply]

What version of OpenTelemetry are you using?

0.12.1-alpha.7

What version of Node are you using?

14.10.0

What did you do?

Followed the GraphQL example, and applied it to our project.

What did you expect to see?

I expected that my requests to our GraphQL server would work as before (and perhaps with slightly added delay due to tracing).

What did you see instead?

{
  "errors": [
    {
      "message": "Cannot read property 'startToken' of undefined",
      "locations": [
        {
          "line": 3,
          "column": 5
        }
      ],
      "path": [
        "infoItem",
        "title"
      ],
      "extensions": {
        "code": "INTERNAL_SERVER_ERROR",
        "exception": {
          "stacktrace": [
            "TypeError: Cannot read property 'startToken' of undefined",
            "    at getSourceFromLocation (/Users/multiply/work/graph-api/node_modules/@opentelemetry/instrumentation-graphql/src/utils.ts:229:5)",
            "    at addSpanSource (/Users/multiply/work/graph-api/node_modules/@opentelemetry/instrumentation-graphql/src/utils.ts:47:18)",
            "    at createResolverSpan (/Users/multiply/work/graph-api/node_modules/@opentelemetry/instrumentation-graphql/src/utils.ts:113:5)",
            "    at createFieldIfNotExists (/Users/multiply/work/graph-api/node_modules/@opentelemetry/instrumentation-graphql/src/utils.ts:71:13)",
            "    at wrappedFieldResolver (/Users/multiply/work/graph-api/node_modules/@opentelemetry/instrumentation-graphql/src/utils.ts:355:6)",
            "    at field.resolve (/Users/multiply/work/graph-api/node_modules/graphql-extensions/src/index.ts:274:18)",
            "    at field.resolve (/Users/multiply/work/graph-api/node_modules/apollo-server-core/src/utils/schemaInstrumentation.ts:103:18)",
            "    at resolveFieldValueOrError (/Users/multiply/work/graph-api/node_modules/graphql/execution/execute.js:502:18)",
            "    at resolveField (/Users/multiply/work/graph-api/node_modules/graphql/execution/execute.js:460:16)",
            "    at executeFields (/Users/multiply/work/graph-api/node_modules/graphql/execution/execute.js:297:18)"
          ]
        }
      }
    },
    {
      "message": "Cannot read property 'startToken' of undefined",
      "locations": [
        {
          "line": 4,
          "column": 5
        }
      ],
      "path": [
        "infoItem",
        "section"
      ],
      "extensions": {
        "code": "INTERNAL_SERVER_ERROR",
        "exception": {
          "stacktrace": [
            "TypeError: Cannot read property 'startToken' of undefined",
            "    at getSourceFromLocation (/Users/multiply/work/graph-api/node_modules/@opentelemetry/instrumentation-graphql/src/utils.ts:229:5)",
            "    at addSpanSource (/Users/multiply/work/graph-api/node_modules/@opentelemetry/instrumentation-graphql/src/utils.ts:47:18)",
            "    at createResolverSpan (/Users/multiply/work/graph-api/node_modules/@opentelemetry/instrumentation-graphql/src/utils.ts:113:5)",
            "    at createFieldIfNotExists (/Users/multiply/work/graph-api/node_modules/@opentelemetry/instrumentation-graphql/src/utils.ts:71:13)",
            "    at wrappedFieldResolver (/Users/multiply/work/graph-api/node_modules/@opentelemetry/instrumentation-graphql/src/utils.ts:355:6)",
            "    at field.resolve (/Users/multiply/work/graph-api/node_modules/graphql-extensions/src/index.ts:274:18)",
            "    at field.resolve (/Users/multiply/work/graph-api/node_modules/apollo-server-core/src/utils/schemaInstrumentation.ts:103:18)",
            "    at resolveFieldValueOrError (/Users/multiply/work/graph-api/node_modules/graphql/execution/execute.js:502:18)",
            "    at resolveField (/Users/multiply/work/graph-api/node_modules/graphql/execution/execute.js:460:16)",
            "    at executeFields (/Users/multiply/work/graph-api/node_modules/graphql/execution/execute.js:297:18)"
          ]
        }
      }
    }
  ],
  "data": {
    "infoItem": {
      "title": null,
      "section": null
    }
  }
}

Additional context

1. We're using Apollo Server

2. We're also using federation

3. loc can be undefined in the following bit of code:
   

   opentelemetry-js-contrib/plugins/node/opentelemetry-instrumentation-graphql/src/utils.ts

   Line 226 in 4de41c8

   if (loc.startToken) {

   
   I fixed it locally by adding the following code before checking for startToken:

   if (!loc) {
       return source;
   }
   

4. If it matters at least the first field type that fails, seems to be of type Document, when debugging further up the callstack

[obecny]

@Multiply please provide how can I reproduce it.

[Multiply]

@obecny I'll see if I can make a tiny reproducible example for you.

[gitelr]

Here's a hack of a repro I threw together as I've bumped up against this issue as well. I'm not sure it's an issue with the instrumentation or how Apollo federation composing it's calls to graphql execute. Regardless, this seems to work for me:

Set up a sample federation example:

git clone https://github.com/patrick91/apollo-federation-local-services.git
cd apollo-federation-local-services/
npm install
npm install @opentelemetry/api @opentelemetry/instrumentation-graphql @opentelemetry/tracing @opentelemetry/node @opentelemetry/exporter-collector
node server.js

Test via curl:

curl -s -X POST  -H "content-type: application/json; charset=utf-8" --data '{"operationName":null,"variables":{},"query":"{continents {code,name}}"}' http://localhost:4000/graphql | jq

That should return:

{
  "data": {
    "continents": [
      {
        "code": "AF",
        "name": "Africa"
      },
      {
        "code": "AN",
        "name": "Antarctica"
      },
      {
        "code": "AS",
        "name": "Asia"
      },
      {
        "code": "EU",
        "name": "Europe"
      },
      {
        "code": "NA",
        "name": "North America"
      },
      {
        "code": "OC",
        "name": "Oceania"
      },
      {
        "code": "SA",
        "name": "South America"
      }
    ]
  }
}

To repro the error, prepend the following:

const opentelemetry = require('@opentelemetry/api');
const { GraphQLInstrumentation } = require('@opentelemetry/instrumentation-graphql');

const { ConsoleSpanExporter, SimpleSpanProcessor } = require('@opentelemetry/tracing');
const { NodeTracerProvider } = require('@opentelemetry/node');
const { CollectorTraceExporter } = require('@opentelemetry/exporter-collector');

const exporter = new CollectorTraceExporter({ serviceName: 'countries' });
const provider = new NodeTracerProvider({
    plugins: {
      http: { enabled: false, path: '@opentelemetry/plugin-http' },
      https: { enabled: false, path: '@opentelemetry/plugin-https' },
      express: { enabled: false, path: '@opentelemetry/plugin-express' },
    },
});

const graphQLInstrumentation = new GraphQLInstrumentation({});
graphQLInstrumentation.setTracerProvider(provider);
graphQLInstrumentation.enable();

provider.addSpanProcessor(new SimpleSpanProcessor(new ConsoleSpanExporter()));

to the top of server.js (before anything else).

Then run server.js:

node server.js

And hit the local service again via curl:

curl -s -X POST  -H "content-type: application/json; charset=utf-8" --data '{"operationName":null,"variables":{},"query":"{continents {code,name}}"}' http://localhost:4000/graphql | jq

Which now returns:

{
  "data": null
}

The null is because the exception the original report cites is caught but not surfaced.

This comes down to @apollo/gateway executeQueryPlan.executeQueryPlan function calling graphql.execute with an explict document structure that lacks the loc attribute (see node_modules/@apollo/gateway/src/executeQueryPlan.ts around line 81). Adding in the loc attribute either from the requestContext or operationContext also resolves the issue, but I'm not familiar enough with either graphql or apollo implementation to know if either of those are correct or if patching the instrumentation is the correct answer.

In my casual testing, both solutions produced pretty similar output in Zipkin but nothing about my testing was particularly scientific.

[obecny]

thx @gitelr will check it soon

[davendu]

EDIT:

No, ignoring spans without document.loc is NOT a right way. Federation still needs additional support.

---

Hi @obecny @gitelr

The same issue can be reproduced on my program. Only applications with both a build-in federation gateway and a LocalDataSource will be affected. So, a better (or worse) workaround to this problem is split gateway and microservices into different node applications, and stop instrumentation on the gateway (which applies to our architecture).

I think the re-execute on gateway-js/src/executeQueryPlan.ts:81 may not need document.loc attribute, since the resolvers for all fields have already been called at this time, and this re-execute seems only for lexical reasons. So maybe allowing spans without document.loc is reasonable.

Here is a example from our application, and you can see this second execution happens after all real resolvers are called (in the first execution).

[MollardMichael]

I'm getting this error with api v 1.0.1 and graphql intrumentation 0.23.0

[richard77]

Any update on this issue?
We're facing the same issue.

[richard77]

Possible solution:
https://github.com/apollographql/federation/pull/836/files#diff-78d9cdce9772008eebb17d78e4d4ea82cc446bb7ed0cf32b31963b766a7f496dR26-R51
Documentation states that federate should not have the instrumentation-graphql as pacakge

[obecny]

this should be fixed now -> #619
Updated also the example to use the federation too for easier verification of the fix.