Skip to content

Continuation-Local set in express middleware lost inside resolvers #2042

@magicaltrip

Description

@magicaltrip

Hello,
I have an issue using continuation local storage with apollo-server-express.

Why do I need continuation local storage?
I am using Zipkin for instrumenting requests and I need to see the whole tree of requests derived from a Graphl query.

What am I doing?
I use zipkin-instrumentation-express and zipkin-instrumentation-fetch in most express-based services and the context is stored in continuation-local-storage (I am using cls-hooked) and retrieved again successfully. So the parent traces are kept along downstream requests.

What is failing?
The problem is that the first request to the API loses context (no variable saved in continuation local is seen in the resolvers) and I cannot see the tree of requests generated from this first call.

Example
Example code is based on the basic example provided in apollo-server-express:

const { ApolloServer, gql } = require("apollo-server-express");
const zipkinMiddleware = require("zipkin-instrumentation-express")
  .expressMiddleware;
const wrapFetch = require("zipkin-instrumentation-fetch");
const fetch = require("node-fetch");
const tracer = require("./tracer");

// Construct a schema, using GraphQL schema language
const typeDefs = gql`
  type Query {
    hello: [String]
  }
`;

// Provide resolver functions for your schema fields
const resolvers = {
  Query: {
    hello: () => {
      return getData(fetchFromGraphql)
    }
  }
}

function getData(fetcher) {
  return Promise.all([
    fetcher("http://localhost:4000/hello?timeout=200").then(res => res.text()),
    fetcher("http://localhost:4000/hello?timeout=300").then(res => res.text()),
    fetcher("http://localhost:4000/hello?timeout=400").then(res => res.text()),
  ])
}

const fetchFromBasic = wrapFetch(fetch, {
  tracer: tracer("Basic")
})
const fetchFromGraphql  = wrapFetch(fetch, {
  tracer: tracer("Graphql")
})

const server = new ApolloServer({ typeDefs, resolvers })
const app = express()

app.get("/basic", zipkinMiddleware({
  tracer: tracer("Basic")
}), async (req, res) => {
  const data =  await getData(fetchFromBasic)
  res.send(data)
});


app.get("/hello", zipkinMiddleware({
  tracer: tracer("Hello")
}), (req, res) => {
  setTimeout(() => res.send("Hello"), Number(req.query.timeout || 500));
});

app.use(
  "/graphql",
  zipkinMiddleware({
    tracer: tracer("Graphql")
  })
);
server.applyMiddleware({ app });

app.listen({ port: 4000 }, () =>
  console.log(`🚀 Server ready at http://localhost:4000${server.graphqlPath}`)
);

When calling /basic or querying "hello" in the graphql playground I would expect to see the same traces, but this is what I see in Zipkin:
screen shot 2018-11-29 at 16 36 40

Request to basic has 4 spans (parent and 3 requests) but requests to graphql do not group the request.
As I said the reason is that the continuation-local is not kept inside the resolvers, and therefore the fetch wrapper cannot access then and creates new spans without parent id.

I tried with the default continuation-local-storage and the cls-hooked without success.
I tried both in mi machine with Node v11 and in Docker with Node v9.4 with same result.

I also tried creating namespaces and simple middleware just setting variables in the context and I got the same result.

I know there is tracing for apollo-server but I cannot see the downstream requests. And I also saw the extensions, but I could not find a way to wrap the resolve calls in order to set the right context.

Metadata

Metadata

Assignees

No one assigned

    Labels

    No labels
    No labels

    Type

    No type

    Projects

    No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions