FIXUP: add comments explaining the tracer execution order and add a t…

…est to cover lazy fields

will squash later

Gemfile.lock

@@ -2,6 +2,7 @@ PATH
   remote: .
   specs:
     apollo-federation (0.3.2)
+      google-protobuf
       graphql
 
 GEM
@@ -33,8 +34,8 @@ GEM
     crass (1.0.4)
     diff-lcs (1.3)
     erubi (1.8.0)
-    graphql (1.9.11)
-    google-protobuf (3.9.0)
+    google-protobuf (3.9.1)
+    graphql (1.9.12)
     i18n (1.6.0)
       concurrent-ruby (~> 1.0)
     jaro_winkler (1.5.3)

lib/apollo-federation/tracing/tracer.rb

@@ -1,5 +1,39 @@
 # frozen_string_literal: true
 
+=begin
+
+  Trace events are nested and fire in this order
+  for a simple single-field query like `{ foo }`:
+
+  <execute_multiplex>
+    <lex></lex>
+    <parse></parse>
+    <validate></validate>
+    <analyze_multiplex>
+      <analyze_query></analyze_query>
+    </analyze_multiplex>
+
+    <execute_query>
+      <execute_field></execute_field>
+    </execute_query>
+
+    <execute_query_lazy>
+
+      # `execute_field_lazy` fires *only* when the field is lazy
+      # (https://graphql-ruby.org/schema/lazy_execution.html)
+      # so if it fires we should overwrite the ending times recorded
+      # in `execute_field` to capture the total execution time.
+
+      <execute_field_lazy></execute_field_lazy>
+
+    </execute_query_lazy>
+
+    # `execute_query_lazy` *always* fires, so it's a
+    # safe place to capture ending times of the full query.
+
+  </execute_multiplex>
+=end
+
 module ApolloFederation
   module Tracing
     module Tracer

spec/apollo-federation/tracing_spec.rb

@@ -162,6 +162,58 @@ def parent
     end
   end
 
+  class Lazy
+    def lazy_method
+      'lazy_value'
+    end
+  end
+
+  describe 'lazy values' do
+    let(:schema) do
+      query_obj = Class.new(GraphQL::Schema::Object) do
+        graphql_name 'Query'
+
+        field :test, String, null: false
+
+        def test
+          Lazy.new
+        end
+      end
+
+      Class.new(base_schema) do
+        query query_obj
+        lazy_resolve(Lazy, :lazy_method)
+      end
+    end
+
+    let(:trace) do
+      result = schema.execute('{ test }', context: { tracing_enabled: true })
+      described_class.attach_trace_to_result(result)
+      ApolloFederation::Tracing::Trace.decode(Base64.decode64(result[:extensions][:ftv1]))
+    end
+
+    it 'works with lazy values' do
+      expect(trace).to eq ApolloFederation::Tracing::Trace.new(
+        start_time: { seconds: 1_564_920_001, nanos: 0 },
+        end_time: { seconds: 1_564_920_002, nanos: 0 },
+        duration_ns: 4,
+        root: {
+          child: [{
+            response_name: 'test',
+            type: 'String!',
+            start_time: 1,
+            # This is the only discrepancy between a normal field and a lazy field.
+            # The fake clock incremented once at the end of the `execute_field` step,
+            # and again at the end of the `execute_field_lazy` step, so we record the
+            # end time as being two nanoseconds after the start time instead of one.
+            end_time: 3,
+            parent_type: 'Query',
+          }]
+        }
+      )
+    end
+  end
+
   describe 'indices and errors' do
     let(:schema) do
       item_obj = Class.new(GraphQL::Schema::Object) do