instrumentation-graphql doesn't work with apollo-server-express and federated schema

[bokjo]

What version of OpenTelemetry are you using?

0.18.0 and 0.17.0?!?

Part of package.json

    "@google-cloud/opentelemetry-cloud-trace-exporter": "^0.8.0",
    "@opentelemetry/api": "^0.18.0",
    "@opentelemetry/core": "^0.18.0",
    "@opentelemetry/exporter-collector": "^0.18.0",
    "@opentelemetry/instrumentation": "^0.17.0",
    "@opentelemetry/instrumentation-graphql": "^0.13.1",
    "@opentelemetry/node": "^0.17.0",
    "@opentelemetry/plugin-express": "^0.13.1",
    "@opentelemetry/plugin-http": "^0.17.0",
    "@opentelemetry/plugin-https": "^0.17.0",
    "@opentelemetry/resources": "^0.18.0",
    "@opentelemetry/tracing": "^0.17.0",
    ...
    "graphql": "^15.5.0",
    "apollo-server": "^2.21.0",
    "apollo-server-express": "^2.21.0",
    "express-graphql": "^0.12.0",

What version of Node are you using?

v14.15.4 (npm v6.14.10)

What did you do?

If possible, provide a recipe for reproducing the error.

Implement tracing with instrumentation-graphql in order to trace GraphQL resolvers running on Apollo Server with generated federated schema

tracing.ts

import * as opentelemetry from "@opentelemetry/api";
import { registerInstrumentations } from "@opentelemetry/instrumentation";
import { GraphQLInstrumentation } from "@opentelemetry/instrumentation-graphql";
import { ConsoleSpanExporter, SimpleSpanProcessor, BatchSpanProcessor } from "@opentelemetry/tracing";
import { NodeTracerProvider } from "@opentelemetry/node";
import { CollectorTraceExporter } from "@opentelemetry/exporter-collector";
import { TraceExporter } from "@google-cloud/opentelemetry-cloud-trace-exporter";

export function initializeTracing(logger) {
  const exporter = new TraceExporter({ logger });
//   const exporter = new CollectorTraceExporter({
//     serviceName: "basic-service-example",
//   });

  const provider = new NodeTracerProvider();

  registerInstrumentations({
    tracerProvider: provider,
    instrumentations: [
      {
        plugins: {
          express: {
            enabled: false,
            path: "@opentelemetry/plugin-express",
          },
          http: {
            enabled: false,
            path: "@opentelemetry/plugin-http",
          },
          https: {
            enabled: false,
            path: "@opentelemetry/plugin-https",
          },
        },
      },
    ],
  });

  const graphQLInstrumentation = new GraphQLInstrumentation({
    // optional params
    // allowValues: true,
    // depth: 5,
    // mergeItems: true,
  });

  graphQLInstrumentation.setTracerProvider(provider); // optional; uses global tracer by default

  graphQLInstrumentation.enable();

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

  //  opentelemetry.trace.initGlobalTracerProvider(provider);
  opentelemetry.trace.setGlobalTracerProvider(provider);
  const gqlTracer = opentelemetry.trace.getTracer("graphql");

  return { gqlTracer, provider };
}

What did you expect to see?

Expected to see the tracing spans (graphql.execute, graphql.resolver...) as in the graphql example here: https://github.com/open-telemetry/opentelemetry-js-contrib/tree/main/examples/graphql

This is an image I took running the example above

What did you see instead?

1. Nothing is happening with all the plugins (express, http...) set to false, no traces are generated and pushed to the exporter of choice...

2. If I explicitly enable the plugins @opentelemetry/plugin-http/s in tracer.ts registerInstrumentations... then I see only the autogenerated HTTP traces with name "HTTP POST" for /graphql...
   (p.s my resolver is using Firebase Auth and I see the HTTP calls that are made to Google Identity Provider... not really useful for now since I need the resolver info and query to understand better the GraphQL flow...)

Additional context

Source code:
main.ts

import { ApolloServer, makeExecutableSchema } from "apollo-server-express";
import * as express from "express";
import { resolvers, typeDefs } from "./schema";
import { buildFederatedSchema } from "@apollo/federation";
import { logger } from "./logger";
import { initializeTracing } from "./tracing";

const { gqlTracer, provider } = initializeTracing(logger);

const app = express();
app.use(express.json());

const schema = buildFederatedSchema({
  typeDefs,
  resolvers,
});

const server = new ApolloServer({
  context: ({ req }) => {
    return { req, gqlTracer };
  },
  schema,
  playground: true,
  introspection: true,
});

const port = process.env.GRAPHQL_SERVER_PORT || 5000;
const path = process.env.GRAPHQL_SERVER_PATH || "/graphql";
const host = process.env.GRAPHQL_SERVER_HOST || "0.0.0.0";

server.applyMiddleware({ app, path });

app.listen({ host, port, path }, () => {
  logger.info(`GraphQL server ready at http://${host}:${port}${path}`);
});

`schema.ts`

```ts
import { gql } from "apollo-server-express";
import { AuthResolver } from "./resolvers";

const auth = new AuthResolver();

export const typeDefs = gql`
  type User {
    uid: String!
    email: String!
    displayName: String!
  }

  type Login {
    test: String
    tes2: String
    user: User
  }

  input LoginInput {
    email: String!
    password: String!
  }

  input RegisterInput {
    email: String!
    password: String!
    displayName: String!
  }

  type Query {
    sayHelloAuth: String
    getUserByEmail(email: String!): User
  }

  type Mutation {
    login(input: LoginInput!): Login
    register(input: RegisterInput!): User
  }
`;

export const resolvers = {
  Query: {
    sayHelloAuth: (parent, args, context, info) => {
      return "Hello World Auth";
    },
    getUserByEmail: async (parent, args, context, info) => await auth.getUserByEmail(parent, args, context, info),
  },

  Mutation: {
    login: async (parent, args, context, info) => await auth.login(parent, args, context, info),
    register: async (parent, args, context, info) => await auth.register(parent, args, context, info),
  },
};

Add any other context about the problem here.
buildFederatedSchema() returns a propper GraphQLSchema object type!

Also tried the same setup for the GraphQL server with vanilla apollo-server and express-graphql, and the outcome is the same...

Calling the GraphQL endpoint directly or through Apollo Federation Gateway yields the same result!

I'm willing to help in any shape and form just will need some guidance in how to properly debug and understand what the instrumentation-qraphql is actually doing under the hood...

[Flarna]

Mixing API/Core 0.18.0 with {{@opentelemetry/instrumentation-graphql}} 0.13.1 wont work. See compatibility-matrix.

The instrumentations/plugins here have been updated to use 0.18.0 just recently (see #371) but there was no release made yet.

OTel API is close to go GA and therefore quite a lot is moving. I assume the modules hosted here are published soon.

[bokjo]

Hello @Flarna

Thanks for the fast reply, was not aware of the compatibility-matrix

Yesterday I was running the graphql => instrumentation-graphql example with API?Core v0.17.0 and today with v0.18.0 and everything seemed fine to me...

I Will try to run my own example with v0.15.0 tho to see whether there will be some change regarding [email protected] as per the matrix.

Kind Regards,
Bojanche S.

[bokjo]

Hello @Flarna

Tested with OTel v0.15.0, the same outcome... no graphql traces were generated

[weyert]

Hello @bokjo

What happens when you move the import { initializeTracing } from "./tracing";-line to the top of the file?
Normally, you need to load the instrumentations before they are used. At least that's my understanding :)

[bokjo]

Hello @bokjo

What happens when you move the import { initializeTracing } from "./tracing";-line to the top of the file?
Normally, you need to load the instrumentations before they are used. At least that's my understanding :)

Hello @weyert

Sorry I forgot to comment and close the issue yesterday evening (after few hours of debugging, at least now I know a bit more about the plugins and APIs from OTel )

Yes that was the reason, I had to import and initialize the tracing first at the top of the main

import { initializeTracing } from "./tracing";
import { logger } from "./logger";
const { gqlTracer, provider } = initializeTracing(logger);
...
// Rest of the imports and code

I understand the chicken and egg thing the hard way with a hint from OTEL_LOG_LEVEL=debug printing the lines below twice...

Some modules (@grpc/grpc-js, express) were already required when their respective plugin was loaded, some plugins might not work. Make sure the SDK is setup before you require in other modules.
Some modules (@grpc/grpc-js) were already required when their respective plugin was loaded, some plugins might not work. Make sure the SDK is setup before you require in other modules.

My bad, I know that all the examples start with require a tracer as a first thing but it didn't cross my mind yesterday...

'use strict';

require('./tracer')('example-express-server');

Don't know if I missed some how to quick start guide but the issue is solved now :)

I Will try to test it today with v0.17.0 and/or v0.18.0

p.s Should I comment and close the issue myself?

[obecny]

@bokjo if all is fine for you please comment and close the issue so that we know it is no longer an issue, thank you

[bokjo]

Issue resolved by importing and initializing the tracing lib. at the top of the main file.