diff --git a/.gitignore b/.gitignore index cd0280472..f52119848 100644 --- a/.gitignore +++ b/.gitignore @@ -7,3 +7,5 @@ node_modules/ # built CircleCI configs .circleci/processed-config.yml + +.DS_Store diff --git a/lib/apollo-federation/entities_field.rb b/lib/apollo-federation/entities_field.rb index ea0ac870f..caab8ff74 100644 --- a/lib/apollo-federation/entities_field.rb +++ b/lib/apollo-federation/entities_field.rb @@ -2,7 +2,6 @@ require 'graphql' require 'apollo-federation/any' -require 'apollo-federation/entity_type_resolution_extension' module ApolloFederation module EntitiesField @@ -23,7 +22,6 @@ def define_entities_field(possible_entities) field(:_entities, [entity_type, null: true], null: false) do argument :representations, [Any], required: true - extension(EntityTypeResolutionExtension) end end end @@ -47,7 +45,14 @@ def _entities(representations:) result = reference end - [type, result] + context.schema.after_lazy(result) do |resolved_value| + # TODO: This isn't 100% correct: if (for some reason) 2 different resolve_reference calls + # return the same object, it might not have the right type + # Right now, apollo-federation just adds a __typename property to the result, + # but I don't really like the idea of modifying the resolved object + context[resolved_value] = type + resolved_value + end end end end diff --git a/lib/apollo-federation/entity_type_resolution_extension.rb b/lib/apollo-federation/entity_type_resolution_extension.rb deleted file mode 100644 index 6852b1bde..000000000 --- a/lib/apollo-federation/entity_type_resolution_extension.rb +++ /dev/null @@ -1,16 +0,0 @@ -# frozen_string_literal: true - -class EntityTypeResolutionExtension < GraphQL::Schema::FieldExtension - def after_resolve(value:, context:, **_rest) - value.map do |type, result| - context.schema.after_lazy(result) do |resolved_value| - # TODO: This isn't 100% correct: if (for some reason) 2 different resolve_reference calls - # return the same object, it might not have the right type - # Right now, apollo-federation just adds a __typename property to the result, - # but I don't really like the idea of modifying the resolved object - context[resolved_value] = type - resolved_value - end - end - end -end diff --git a/lib/apollo-federation/tracing.rb b/lib/apollo-federation/tracing.rb index af656498b..5ad776a57 100644 --- a/lib/apollo-federation/tracing.rb +++ b/lib/apollo-federation/tracing.rb @@ -27,6 +27,8 @@ def attach_trace_to_result(result) return result unless result.context[:tracing_enabled] trace = result.context.namespace(KEY) + # TODO: If there are errors during query validation, that could also cause a missing + # start_time raise NotInstalledError unless trace[:start_time] result['errors']&.each do |error| diff --git a/lib/apollo-federation/tracing/tracer.rb b/lib/apollo-federation/tracing/tracer.rb index 773062c53..a64581cce 100644 --- a/lib/apollo-federation/tracing/tracer.rb +++ b/lib/apollo-federation/tracing/tracer.rb @@ -159,17 +159,27 @@ def self.execute_field_lazy(data, &block) end_time_nanos = Process.clock_gettime(Process::CLOCK_MONOTONIC, :nanosecond) - # interpreter runtime + # legacy runtime if data.include?(:context) - context = data.fetch(:context) path = context.path - else # legacy runtime - context = data.fetch(:query).context + field = context.field + else # interpreter runtime path = data.fetch(:path) + field = data.fetch(:field) end trace = context.namespace(ApolloFederation::Tracing::KEY) + # When a field is resolved with an array of lazy values, the interpreter fires an + # `execute_field` for the resolution of the field and then a `execute_field_lazy` event for + # each lazy value in the array. Since the path here will contain an index (indicating which + # lazy value we're executing: e.g. ['arrayOfLazies', 0]), we won't have a node for the path. + # We only care about the end of the parent field (e.g. ['arrayOfLazies']), so we get the + # node for that path. What ends up happening is we update the end_time for the parent node + # for each of the lazy values. The last one that's executed becomes the final end time. + if field.type.list? && path.last.is_a?(Integer) + path = path[0...-1] + end node = trace[:node_map].node_for_path(path) node.end_time = end_time_nanos - trace[:start_time_nanos] diff --git a/spec/apollo-federation/tracing_spec.rb b/spec/apollo-federation/tracing_spec.rb index 8018f10e3..966abe7a8 100644 --- a/spec/apollo-federation/tracing_spec.rb +++ b/spec/apollo-federation/tracing_spec.rb @@ -54,6 +54,13 @@ def test end end + def trace(query) + result = schema.execute(query, context: { tracing_enabled: true }) + described_class.attach_trace_to_result(result) + + ApolloFederation::Tracing::Trace.decode(Base64.decode64(result[:extensions][:ftv1])) + end + describe 'building the trace tree' do let(:schema) do grandchild_obj = Class.new(GraphQL::Schema::Object) do @@ -88,10 +95,15 @@ def child graphql_name 'Query' field :parent, parent_obj, null: false + field :strings, [String], null: false def parent { id: 'parent' } end + + def strings + ['hello', 'goodbye'] + end end Class.new(base_schema) do @@ -100,101 +112,139 @@ def parent end it 'records timing for children' do - result = schema.execute( - '{ parent { id, child { id, grandchild { id } } } }', - context: { tracing_enabled: true }, - ) - described_class.attach_trace_to_result(result) + query = '{ parent { id, child { id, grandchild { id } } } }' + expect(trace(query)).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: 13, + root: { + child: [{ + response_name: 'parent', + type: 'Parent!', + start_time: 1, + end_time: 2, + parent_type: 'Query', + child: [{ + response_name: 'id', + type: 'String!', + start_time: 3, + end_time: 4, + parent_type: 'Parent', + }, { + response_name: 'child', + type: 'Child!', + start_time: 5, + end_time: 6, + parent_type: 'Parent', + child: [{ + response_name: 'id', + type: 'String!', + start_time: 7, + end_time: 8, + parent_type: 'Child', + }, { + response_name: 'grandchild', + type: 'Grandchild!', + start_time: 9, + end_time: 10, + parent_type: 'Child', + child: [{ + response_name: 'id', + type: 'String!', + start_time: 11, + end_time: 12, + parent_type: 'Grandchild', + }], + },], + },], + }], + }, + )) + end - trace = ApolloFederation::Tracing::Trace.decode(Base64.decode64(result[:extensions][:ftv1])) - 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: 13, - root: { - child: [{ - response_name: 'parent', - type: 'Parent!', - start_time: 1, - end_time: 2, - parent_type: 'Query', - child: [{ - response_name: 'id', - type: 'String!', - start_time: 3, - end_time: 4, - parent_type: 'Parent', - }, { - response_name: 'child', - type: 'Child!', - start_time: 5, - end_time: 6, - parent_type: 'Parent', - child: [{ - response_name: 'id', - type: 'String!', - start_time: 7, - end_time: 8, - parent_type: 'Child', - }, { - response_name: 'grandchild', - type: 'Grandchild!', - start_time: 9, - end_time: 10, - parent_type: 'Child', - child: [{ - response_name: 'id', - type: 'String!', - start_time: 11, - end_time: 12, - parent_type: 'Grandchild', - }], - },], - },], - }], - }, - )) + it 'works for scalar arrays' do + expect(trace('{ strings }')).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: 3, + root: { + child: [{ + response_name: 'strings', + type: '[String!]!', + start_time: 1, + end_time: 2, + parent_type: 'Query', + }], + }, + ) end end class Lazy - def lazy_method - 'lazy_value' + def initialize(value = 'lazy_value') + @value = value end + + attr_reader :value end describe 'lazy values' do let(:schema) do + item_obj = Class.new(GraphQL::Schema::Object) do + graphql_name 'Item' + + field :id, String, null: false + end + query_obj = Class.new(GraphQL::Schema::Object) do graphql_name 'Query' - field :test, String, null: false + field :lazy_scalar, String, null: false + field :array_of_lazy_scalars, [String], null: false + field :lazy_array_of_scalars, [String], null: false + field :lazy_array_of_lazy_scalars, [String], null: false + field :array_of_lazy_objects, [item_obj], null: false + field :lazy_array_of_objects, [item_obj], null: false - def test + def lazy_scalar Lazy.new end + + def array_of_lazy_scalars + [Lazy.new('hi'), Lazy.new('bye')] + end + + def lazy_array_of_scalars + Lazy.new(['hi', 'bye']) + end + + def lazy_array_of_lazy_scalars + Lazy.new([Lazy.new('hi'), Lazy.new('bye')]) + end + + def array_of_lazy_objects + [Lazy.new(id: '123'), Lazy.new(id: '456')] + end + + def lazy_array_of_objects + Lazy.new([{ id: '123' }, { id: '456' }]) + end end Class.new(base_schema) do query query_obj - lazy_resolve(Lazy, :lazy_method) + lazy_resolve(Lazy, :value) 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( + expect(trace('{ lazyScalar }')).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', + response_name: 'lazyScalar', type: 'String!', start_time: 1, # This is the only discrepancy between a normal field and a lazy field. @@ -207,6 +257,168 @@ def test }, ) end + + it 'works with an array of lazy scalars' do + expect(trace('{ arrayOfLazyScalars }')).to eq ApolloFederation::Tracing::Trace.new( + start_time: { seconds: 1_564_920_001, nanos: 0 }, + end_time: { seconds: 1_564_920_002, nanos: 0 }, + # The old runtime and the interpreter handle arrays of lazy objects differently. + # The old runtime doesn't trigger the `execute_field_lazy` tracer event, so we have to + # use the (inaccurate) end times from the `execute_field` event. + duration_ns: schema.interpreter? ? 5 : 3, + root: { + child: [{ + response_name: 'arrayOfLazyScalars', + type: '[String!]!', + start_time: 1, + end_time: schema.interpreter? ? 4 : 2, + parent_type: 'Query', + }], + }, + ) + end + + it 'works with a lazy array of scalars' do + expect(trace('{ lazyArrayOfScalars }')).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: 'lazyArrayOfScalars', + type: '[String!]!', + start_time: 1, + end_time: 3, + parent_type: 'Query', + }], + }, + ) + end + + it 'works with a lazy array of lazy scalars' do + expect(trace('{ lazyArrayOfLazyScalars }')).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: schema.interpreter? ? 6 : 4, + root: { + child: [{ + response_name: 'lazyArrayOfLazyScalars', + type: '[String!]!', + start_time: 1, + end_time: schema.interpreter? ? 5 : 3, + parent_type: 'Query', + }], + }, + ) + end + + it 'works with array of lazy objects' do + expect(trace('{ arrayOfLazyObjects { id } }')).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: schema.interpreter? ? 9 : 7, + root: { + child: [{ + response_name: 'arrayOfLazyObjects', + type: '[Item!]!', + start_time: 1, + end_time: schema.interpreter? ? 6 : 2, + parent_type: 'Query', + child: [ + { + index: 0, + child: [{ + response_name: 'id', + type: 'String!', + start_time: schema.interpreter? ? 4 : 3, + end_time: schema.interpreter? ? 5 : 4, + parent_type: 'Item', + }], + }, + { + index: 1, + child: [{ + response_name: 'id', + type: 'String!', + start_time: schema.interpreter? ? 7 : 5, + end_time: schema.interpreter? ? 8 : 6, + parent_type: 'Item', + }], + }, + ], + }], + }, + ) + end + + it 'works with a lazy array of objects' do + expect(trace('{ lazyArrayOfObjects { id } }')).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: 8, + root: { + child: [{ + response_name: 'lazyArrayOfObjects', + type: '[Item!]!', + start_time: 1, + end_time: 3, + parent_type: 'Query', + child: [ + { + index: 0, + child: [{ + response_name: 'id', + type: 'String!', + start_time: 4, + end_time: 5, + parent_type: 'Item', + }], + }, + { + index: 1, + child: [{ + response_name: 'id', + type: 'String!', + start_time: 6, + end_time: 7, + parent_type: 'Item', + }], + }, + ], + }], + }, + ) + end + + it 'works with multiple lazy fields' do + query = '{ lazyScalar arrayOfLazyScalars lazyArrayOfScalars }' + expect(trace(query)).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: schema.interpreter? ? 11 : 9, + root: { + child: [{ + response_name: 'lazyScalar', + type: 'String!', + start_time: 1, + end_time: 7, + parent_type: 'Query', + }, { + response_name: 'arrayOfLazyScalars', + type: '[String!]!', + start_time: 3, + end_time: schema.interpreter? ? 10 : 4, + parent_type: 'Query', + }, { + response_name: 'lazyArrayOfScalars', + type: '[String!]!', + start_time: 5, + end_time: 8, + parent_type: 'Query', + },], + }, + ) + end end describe 'indices and errors' do @@ -239,14 +451,8 @@ def items end end - let(:trace) do - result = schema.execute('{ items { id, name } }', context: { tracing_enabled: true }) - described_class.attach_trace_to_result(result) - ApolloFederation::Tracing::Trace.decode(Base64.decode64(result[:extensions][:ftv1])) - end - - it 'records index instead of response_name for items in arrays' do - expect(trace).to eq( + it 'records index instead of response_name for objects in arrays' do + expect(trace('{ items { id, name } }')).to eq( ApolloFederation::Tracing::Trace.new( start_time: { seconds: 1_564_920_001, nanos: 0 }, end_time: { seconds: 1_564_920_002, nanos: 0 },