Regression in 2.5.12: `execute_query_lazy` no longer called on legacy tracer when dataloader plugin used

[myronmarston]

Describe the bug

Starting in 2.5.12, when a legacy tracer is used on a schema that also uses the GraphQL::Dataloader plugin, execute_query_lazy isn't called on the tracer.

Concretely, this causes exceptions for projects which also use the apollo-federation gem with tracing enabled.

Versions

graphql version: 2.5.12 and above rails (or other framework): N/A other applicable versions (graphql-batch, etc): N/A

GraphQL schema

Doesn't matter, but here's the one I'm using for the reproduction script below:

type Query {
  foo: Int
}

GraphQL query

Doesn't matter, but here's the query I'm using in the reproduction script below:

query { __typename }

Steps to reproduce

Put this script in a file:

require "bundler/inline"

gemfile do
  source "https://rubygems.org"
  gem "graphql", ENV.fetch("GRAPHQL_VERSION")
end

require "graphql"

class Application
  def initialize
    @schema = ::GraphQL::Schema.from_definition("type Query { foo: Int }", using: {::GraphQL::Dataloader => {}})
    @schema.tracer(Tracer)
  end

  def execute_query(query_string)
    ::GraphQL::Query.new(@schema, query_string).result
  end

  class Tracer
    def self.trace(key, metadata)
      puts "trace #{key}"
      yield
    end
  end
end

app = Application.new
result = app.execute_query("query { __typename }").to_h

puts "=" * 80
puts result

Then run it with GRAPHQL_VERSION=x.y.z ruby graphql_bug.rb to observe the behavior of different versions.

Expected behavior

I expect all trace events to fire like they do on 2.5.11:

$ GRAPHQL_VERSION=2.5.11 ruby graphql_bug.rb
`Schema.tracer(Application::Tracer)` is deprecated; use module-based `trace_with` instead. See: https://graphql-ruby.org/queries/tracing.html
  graphql_bug.rb:18:in 'Application#initialize'
trace execute_multiplex
trace analyze_multiplex
trace parse
trace validate
trace analyze_query
trace execute_query
trace authorized
trace authorized
trace execute_field
trace execute_query_lazy
================================================================================
{"data" => {"__typename" => "Query"}}

Actual behavior

The execute_query_lazy trace event does not fire on 2.5.12:

$ GRAPHQL_VERSION=2.5.12 ruby graphql_bug.rb
`Schema.tracer(Application::Tracer)` is deprecated; use module-based `trace_with` instead. See: https://graphql-ruby.org/queries/tracing.html
  graphql_bug.rb:18:in 'Application#initialize'
trace execute_multiplex
trace analyze_multiplex
trace parse
trace validate
trace analyze_query
trace execute_query
trace authorized
trace authorized
trace execute_field
================================================================================
{"data" => {"__typename" => "Query"}}

2.5.13 and 2.5.14 exhibit the same behavior.

Additional context

git bisect reveals commit 5ba154a5613d4069c0b1d169c505caab96b0769d (from #5422) as the culprit. Specifically, I think the removal of the call to multiplex.current_trace.execute_query_lazy from interpreter.rb causes this bug:

https://github.com/rmosolgo/graphql-ruby/commit/5ba154a5613d4069c0b1d169c505caab96b0769d#diff-c5478ea34f91a1b8e9084add8c080a3fba29e442515429c1d33ef2fa58131112L96

[rmosolgo]

Hey, sorry about this incompatibility and thanks for the detailed report and analysis!

The runtime data loading flow is different than it was after that PR, since lazy resolution happens inside Dataloader. But it might be possible to retain compatibility by either:

• Somehow calling that trace method around the multiplex.dataloader.run which remained above the deletion you linked
• Or ... adding a no-op trace call (passing an empty block), so at least the event happened, even if there as nothing inside it.

It might also be worth investigating that gem to see about its use of execute_query_lazy. One reason I felt comfortable removing this is that there's no guarantee that a query will have a lazy part. Even if you're using GraphQL-Batch, there might be no lazy part if all the data is null, or if the query encounters errors. A better place for end-of-operation cleanup code is execute_multiplex, after the yield.

Let me know what you think of those ideas -- I can take a look at one of them soon, or feel free to give it a try if you want!

[myronmarston]

It might also be worth investigating that gem to see about its use of execute_query_lazy.

Here's what it's doing:

https://github.com/Gusto/apollo-federation-ruby/blob/v3.10.3/lib/apollo-federation/tracing/tracer.rb#L122-L148

Essentially it's just recording end_time and end_time_nanos. Later on it reads those fields in attach_trace_to_result:

https://github.com/Gusto/apollo-federation-ruby/blob/v3.10.3/lib/apollo-federation/tracing/tracer.rb#L262-L263

If end_time or end_time_nanos haven't been populated on trace, that code will raise a NoMethodError as it'll call some methods on nil.

A better place for end-of-operation cleanup code is execute_multiplex, after the yield.

Ideally, that gem would migrate to the new tracer API--there's been an open issue about that for awhile.