GraphQL dataloaders not compatible with opentelemetry tracing plugin

[stevecrozz]

Ruby 2.7.3p183 (2021-04-05 revision 6847ee089d) [x86_64-darwin20]
GraphQL Gem Version: 2.0.13

Options enable_platform_field and enable_platform_authorized are not compatible with GraphQL gem's own fiber based dataloaders. Turning on these options while using the built-in dataloaders results in missing data and logs like:

ERROR -- : OpenTelemetry error: calls to detach should match corresponding calls to attach.
ERROR -- : OpenTelemetry error: calls to detach should match corresponding calls to attach.
ERROR -- : OpenTelemetry error: calls to detach should match corresponding calls to attach.
ERROR -- : OpenTelemetry error: calls to detach should match corresponding calls to attach.
ERROR -- : OpenTelemetry error: calls to detach should match corresponding calls to attach.
ERROR -- : OpenTelemetry error: calls to detach should match corresponding calls to attach.

I'm assuming this has to do with the way these data loaders work. Somehow, this appeared to be working fine while using NewRelic tracing and it was able to capture traces with details on field hops and authorizations. Removing the dataloaders fixes this problem, but we need them to prevent N+1 query issues.

# field method
def team
  dataloader.with(Sources::Record, Team).load(object.team_id)
end

# authorized? method
def self.authorized?(object, context)
  can_access_team?(context.dataloader.with(Sources::Record, Team).load(object.team_id))
end

[jphenow]

Nice call out that NewRelic's works. Seeing similar logs on our end - though it seems to work a decent amount of the time? Haven't nailed down where/when we miss things due to this issue. Did a little preliminary looking:

1. Here's the graphql tracing base-class https://github.com/rmosolgo/graphql-ruby/blob/master/lib/graphql/tracing/platform_tracing.rb
2. here's NewRelic's graphql tracer: https://github.com/rmosolgo/graphql-ruby/blob/master/lib/graphql/tracing/new_relic_tracing.rb
3. here's OTEL's: https://github.com/open-telemetry/opentelemetry-ruby-contrib/blob/main/instrumentation/graphql/lib/opentelemetry/instrumentation/graphql/tracers/graphql_tracer.rb

There are some decisions around transaction-name that seem like it could be a red herring? Unsure. Seems more likely that the way their tracing works is slightly different from how OTEL's span implementation works. For more reference, here's NR tracer vs OTEL tracing in Ruby:

1. OTEL: https://opentelemetry.io/docs/instrumentation/ruby/manual/#creating-new-spans
2. New Relic: https://github.com/newrelic/newrelic-ruby-agent/blob/fb7e49b5a89c58cf3ea074a2b6ee7c9922e316b9/lib/new_relic/agent/method_tracer.rb#L71

[stevecrozz]

I've done a bit of investigation into this and its maybe less than perfectly clear how this should work. Take an overly simplified GraphQL query with following structure, mid-execution:

- Teams (resolved)
  - Team1 (resolved)
    - Players
      - Player1 (paused dataloader fiber, pushed to the span stack, not yet popped)
      - Player2 (paused dataloader fiber, pushed to the span stack, not yet popped)
  - Team2 (resolved)
    - Players
      - Player3 (paused dataloader fiber, pushed to the span stack, not yet popped)
      - Player4 (running fiber)

This above is the picture of what I think is happening. The fibers eventually unpause but the generated span structure is all wrong and by the time we unpause the fibers, the first one runs and it wants to pop the wrong span because so many other fibers have added to the span stack.

Just thinking out loud here:
What I'd like have happen for the above example is somehow report time spent fetching the players for a team. NewRelic reports this as 'GraphQL/Team/Player' (not a specific team or player) and I believe provides aggregate info only (sum).

What we probably don't want is to push a new span onto the stack for every single Team/Player combination and I think that's what enable_platform_field is doing. So instead of pushing and popping 4 spans in the above example, I'd like instead to push a single Team/Player span within the overall graphql execution context. I'm an OTEL beginner, but it seems like too much to report every single graph node hop as a span. There could be thousands and thousands of them and they could be deeply nested.

Maybe @rmosolgo can correct me where I'm wrong or provide some ideas on how we could better gain observability via OTEL.

[jphenow]

One thing worth calling out at the moment: We're having this issue and using dataloaders but have not gotten to tinker with our fiber scheduling at all for this.

What are you using for scheduling?

[stevecrozz]

We're on Ruby 2.7 so I believe we are not able to use fiber schedulers.

[plantfansam]

@arielvalentin and I just poked around at this for a bit in the Ruby SIG (some notes). We at least have a hypothesis about what's going on (caveat: my knowledge of Fibers is pretty weak, so I might be way off-base here).

Some background: the Ruby OpenTelemetry API uses a Fiber-local array to keep track of the current and previous OpenTelemetry Contexts. When you attach a context, you receive a token that should be used when detaching from the context — this token is just the size of the Fiber-local context array after a new context has been pushed to it. If you try to detach a context with a token that's a different size than the current, Fiber-local stack, you see errors like those posted above.

Now to the ruby-graphql gem: it looks like when it spawns fibers, it copies references to all of the spawning fiber's Fiber-local variables onto the spawned fiber. I think this means that each spawned fiber will have a pointer to the same context stack (rather than a duplicate of the context stack). If that's true, then multiple, concurrently-executing fibers from the GraphQL gem would push and pop to the same context stack, which would lead to the errors shown above.

Not exactly sure where that leaves us, but @fbogsany might have some thoughts, here.

[github-actions]

👋 This issue has been marked as stale because it has been open with no activity. You can: comment on the issue or remove the stale label to hold stale off for a while, add the keep label to hold stale off permanently, or do nothing. If you do nothing this issue will be closed eventually by the stale bot.

[zacheryph]

I'd like to revive this issue. Are there any work arounds for this?

[rmosolgo]

👋 @zacheryph I'm definitely interested in good opentelemetry support. I recently rewrote the other tracers (whose code is in GraphQL-Ruby) to do better with fiber stops and starts. Could you open a new issue here or on GraphQL-Ruby describing what you tried and what happened when you tried it, and ping me on that new issue? Then I'll take a look and see what can be done to improve compat.

[zacheryph]

@rmosolgo I'll keep this ticket going since @arielvalentin was nice enough to re-open it. What I am seeing is for graphql requests, it produces a lot of root span / traces vs everything being within the actual requests trace. For normal requests, I get an expected trace with everything that happened within. For GraphQL, all traces end at analyze_query, and I'm left with a ton of separate traces, a large amount of execute_field traces (i have enable_platform_field: true set for testing)

I should note versions for this stuff huh as I know we're running an older GraphQL version in production, I updated locally to make sure it wasn't any of that nonsense

• Rails: v7.0.8.7
• OTel (all the base gems should be latest unless locked by.. something)
• OTel GraphQL 0.29.0
• GraphQL 2.5.5
• GraphQL Pro 1.29.5 (Though I have removed and gotten same results)

UPDATE: When I disable Data Loaders everything appears as expected within a single trace

UPDATE 2: This issue affects GraphQL::Dataloader and GraphQL::Dataloader::AsyncDataloader

These are root spans (is_root in Honeycomb, which is short for trace.parent_id does-not-exist.) As you can see a single trace for the actual POST request, with a bunch of other spans that should be contained within the request.

Here is the trace for the actual request. Now it doesn't matter what trace I look at (for any graphql request) they all end at analyze_query. The duration is (I'm assuming) correct as everything after the analyze is still being accounted for, the span [parent] tracking just gets lost and nothing is properly contained within the actual requests trace.