fix(tracing): properly handle parsing and validation errors (#102)

* fix(tracing): properly handle parsing and validation errors (#101) * fix(tracing): properly handle parsing and validation errors * style: fix linter errors * style: fix linter errors * chore(release): 1.1.4-beta.1 [skip ci] ## [1.1.4-beta.1](v1.1.3...v1.1.4-beta.1) (2020-09-21) ### Bug Fixes * **tracing:** properly handle parsing and validation errors ([#101](#101)) ([6cf8202](6cf8202)) Co-authored-by: semantic-release-bot <[email protected]>
Gusto · Sep 25, 2020 · a1c2a41 · a1c2a41
1 parent 5b5ef60
commit a1c2a41
Show file tree

Hide file tree

Showing 11 changed files with 120 additions and 71 deletions.
diff --git a/.circleci/config.yml b/.circleci/config.yml
@@ -108,9 +108,6 @@ workflows:
             parameters:
               appraisal: ["graphql-1.9", "graphql-1.10", "graphql-1.11"]
       - release:
-          filters:
-            branches:
-              only: master
           requires:
             - gusto/ruby-lint
             - ruby-test

diff --git a/.rubocop.yml b/.rubocop.yml
@@ -43,6 +43,8 @@ Metrics/BlockLength:
   Enabled: false
 Metrics/MethodLength:
   Enabled: false
+Metrics/ModuleLength:
+  Enabled: false
 Metrics/ParameterLists:
   Max: 5
   CountKeywordArgs: false

diff --git a/CHANGELOG.md b/CHANGELOG.md
@@ -1,3 +1,10 @@
+## [1.1.4-beta.1](https://github.com/Gusto/apollo-federation-ruby/compare/v1.1.3...v1.1.4-beta.1) (2020-09-21)
+
+
+### Bug Fixes
+
+* **tracing:** properly handle parsing and validation errors ([#101](https://github.com/Gusto/apollo-federation-ruby/issues/101)) ([6cf8202](https://github.com/Gusto/apollo-federation-ruby/commit/6cf820281dd85bd358c6bf4c176b9a73a9280d54))
+
 ## [1.1.3](https://github.com/Gusto/apollo-federation-ruby/compare/v1.1.2...v1.1.3) (2020-07-16)
 
 

diff --git a/Gemfile.lock b/Gemfile.lock
@@ -1,7 +1,7 @@
 PATH
   remote: .
   specs:
-    apollo-federation (1.1.3)
+    apollo-federation (1.1.4.beta.1)
       google-protobuf (~> 3.7)
       graphql (>= 1.9.8)
 
@@ -41,7 +41,7 @@ GEM
     debase-ruby_core_source (0.10.9)
     diff-lcs (1.3)
     erubi (1.9.0)
-    google-protobuf (3.12.2)
+    google-protobuf (3.12.2-x86_64-linux)
     graphql (1.10.10)
     i18n (1.8.2)
       concurrent-ruby (~> 1.0)

diff --git a/README.md b/README.md
@@ -175,14 +175,6 @@ To support [federated tracing](https://www.apollographql.com/docs/apollo-server/
       # ...
     end
     ```
-3. Change your controller to attach the traces to the response:
-    ```ruby
-    def execute
-      # ...
-      result = YourSchema.execute(query, ...)
-      render json: ApolloFederation::Tracing.attach_trace_to_result(result)
-    end
-    ```
 
 ## Known Issues and Limitations
  - Only works with class-based schemas, the legacy `.define` API will not be supported

diff --git a/gemfiles/graphql_1.10.gemfile.lock b/gemfiles/graphql_1.10.gemfile.lock
@@ -1,7 +1,7 @@
 PATH
   remote: ..
   specs:
-    apollo-federation (1.1.3)
+    apollo-federation (1.1.4.beta.1)
       google-protobuf (~> 3.7)
       graphql (>= 1.9.8)
 
@@ -41,7 +41,7 @@ GEM
     debase-ruby_core_source (0.10.9)
     diff-lcs (1.3)
     erubi (1.9.0)
-    google-protobuf (3.12.2)
+    google-protobuf (3.13.0)
     graphql (1.10.10)
     i18n (1.8.3)
       concurrent-ruby (~> 1.0)

diff --git a/gemfiles/graphql_1.9.gemfile.lock b/gemfiles/graphql_1.9.gemfile.lock
@@ -1,7 +1,7 @@
 PATH
   remote: ..
   specs:
-    apollo-federation (1.1.3)
+    apollo-federation (1.1.4.beta.1)
       google-protobuf (~> 3.7)
       graphql (>= 1.9.8)
 
@@ -41,7 +41,7 @@ GEM
     debase-ruby_core_source (0.10.9)
     diff-lcs (1.3)
     erubi (1.9.0)
-    google-protobuf (3.12.2)
+    google-protobuf (3.13.0)
     graphql (1.9.8)
     i18n (1.8.3)
       concurrent-ruby (~> 1.0)

diff --git a/lib/apollo-federation/tracing.rb b/lib/apollo-federation/tracing.rb
@@ -4,14 +4,6 @@ module ApolloFederation
   module Tracing
     KEY = :ftv1
     DEBUG_KEY = "#{KEY}_debug".to_sym
-    class NotInstalledError < StandardError
-      MESSAGE = 'Apollo Federation Tracing not installed. \
-Add `use ApolloFederation::Tracing` to your schema.'
-
-      def message
-        MESSAGE
-      end
-    end
 
     module_function
 
@@ -23,37 +15,10 @@ def should_add_traces(headers)
       headers && headers['apollo-federation-include-trace'] == KEY.to_s
     end
 
-    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|
-        trace[:node_map].add_error(error)
-      end
-
-      proto = ApolloFederation::Tracing::Trace.new(
-        start_time: to_proto_timestamp(trace[:start_time]),
-        end_time: to_proto_timestamp(trace[:end_time]),
-        duration_ns: trace[:end_time_nanos] - trace[:start_time_nanos],
-        root: trace[:node_map].root,
-      )
-
-      result[:extensions] ||= {}
-      result[:extensions][KEY] = Base64.encode64(proto.class.encode(proto))
-
-      if result.context[:debug_tracing]
-        result[:extensions][DEBUG_KEY] = proto.to_h
-      end
-
-      result.to_h
-    end
-
-    def to_proto_timestamp(time)
-      Google::Protobuf::Timestamp.new(seconds: time.to_i, nanos: time.nsec)
+    # @deprecated There is no need to call this method. Traces are added to the result automatically
+    def attach_trace_to_result(_result)
+      warn '[DEPRECATION] `attach_trace_to_result` is deprecated. There is no need to call it, as '\
+        'traces are added to the result automatically'
     end
   end
 end
diff --git a/lib/apollo-federation/tracing/tracer.rb b/lib/apollo-federation/tracing/tracer.rb
@@ -35,15 +35,15 @@ module ApolloFederation
   module Tracing
     module Tracer
       # store string constants to avoid creating new strings for each call to .trace
-      EXECUTE_QUERY = 'execute_query'
+      EXECUTE_MULTIPLEX = 'execute_multiplex'
       EXECUTE_QUERY_LAZY = 'execute_query_lazy'
       EXECUTE_FIELD = 'execute_field'
       EXECUTE_FIELD_LAZY = 'execute_field_lazy'
 
       def self.trace(key, data, &block)
         case key
-        when EXECUTE_QUERY
-          execute_query(data, &block)
+        when EXECUTE_MULTIPLEX
+          execute_multiplex(data, &block)
         when EXECUTE_QUERY_LAZY
           execute_query_lazy(data, &block)
         when EXECUTE_FIELD
@@ -55,19 +55,26 @@ def self.trace(key, data, &block)
         end
       end
 
-      # Step 1:
-      # Create a trace hash on the query context and record start times.
-      def self.execute_query(data, &block)
-        query = data.fetch(:query)
-        return block.call unless query.context && query.context[:tracing_enabled]
+      def self.execute_multiplex(data, &block)
+        # Step 1:
+        # Create a trace hash on each query's context and record start times.
+        data.fetch(:multiplex).queries.each { |query| start_trace(query) }
+
+        results = block.call
+
+        # Step 5
+        # Attach the trace to the 'extensions' key of each result
+        results.map { |result| attach_trace_to_result(result) }
+      end
+
+      def self.start_trace(query)
+        return unless query.context && query.context[:tracing_enabled]
 
         query.context.namespace(ApolloFederation::Tracing::KEY).merge!(
           start_time: Time.now.utc,
           start_time_nanos: Process.clock_gettime(Process::CLOCK_MONOTONIC, :nanosecond),
           node_map: NodeMap.new,
         )
-
-        block.call
       end
 
       # Step 4:
@@ -188,6 +195,37 @@ def self.execute_field_lazy(data, &block)
         result
       end
       # rubocop:enable Metrics/CyclomaticComplexity, Metrics/PerceivedComplexity
+
+      def self.attach_trace_to_result(result)
+        return result unless result.context[:tracing_enabled]
+
+        trace = result.context.namespace(ApolloFederation::Tracing::KEY)
+
+        result['errors']&.each do |error|
+          trace[:node_map].add_error(error)
+        end
+
+        proto = ApolloFederation::Tracing::Trace.new(
+          start_time: to_proto_timestamp(trace[:start_time]),
+          end_time: to_proto_timestamp(trace[:end_time]),
+          duration_ns: trace[:end_time_nanos] - trace[:start_time_nanos],
+          root: trace[:node_map].root,
+        )
+
+        result[:extensions] ||= {}
+        result[:extensions][ApolloFederation::Tracing::KEY] =
+          Base64.encode64(proto.class.encode(proto))
+
+        if result.context[:debug_tracing]
+          result[:extensions][ApolloFederation::Tracing::DEBUG_KEY] = proto.to_h
+        end
+
+        result
+      end
+
+      def self.to_proto_timestamp(time)
+        Google::Protobuf::Timestamp.new(seconds: time.to_i, nanos: time.nsec)
+      end
     end
   end
 end
diff --git a/lib/apollo-federation/version.rb b/lib/apollo-federation/version.rb
@@ -1,5 +1,5 @@
 # frozen_string_literal: true
 
 module ApolloFederation
-  VERSION = '1.1.3'
+  VERSION = '1.1.4.beta.1'
 end
diff --git a/spec/apollo-federation/tracing_spec.rb b/spec/apollo-federation/tracing_spec.rb
@@ -37,26 +37,22 @@ def test
 
       it 'does not add tracing extension by default' do
         result = schema.execute('{ test }')
-        described_class.attach_trace_to_result(result)
         expect(result[:extensions]).to be_nil
       end
 
       it 'adds the extensions.ftv1 when the context has tracing_enabled: true' do
         result = schema.execute('{ test }', context: { tracing_enabled: true })
-        described_class.attach_trace_to_result(result)
         expect(result[:extensions][:ftv1]).not_to be_nil
       end
 
       it 'adds debugging info when the context has debug_tracing: true' do
         result = schema.execute('{ test }', context: { tracing_enabled: true, debug_tracing: true })
-        described_class.attach_trace_to_result(result)
         expect(result[:extensions][:ftv1_debug]).not_to be_nil
       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
@@ -511,6 +507,58 @@ def items
           ),
         )
       end
+
+      context 'when there is a parsing error' do
+        it 'properly captures the error' 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 },
+              duration_ns: 1,
+              root: {
+                child: [],
+                error: [{
+                  message: 'Unexpected end of document',
+                  location: [],
+                  json: {
+                    message: 'Unexpected end of document',
+                    locations: [],
+                  }.to_json,
+                }],
+              },
+            ),
+          )
+        end
+      end
+
+      context 'when there is a validation error' do
+        it 'properly captures the error' do
+          expect(trace('{ nonExistant }')).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: 1,
+              root: {
+                child: [],
+                error: [{
+                  message: "Field 'nonExistant' doesn't exist on type 'Query'",
+                  location: [{ line: 1, column: 3 }],
+                  json: {
+                    message: "Field 'nonExistant' doesn't exist on type 'Query'",
+                    locations: [{ line: 1, column: 3 }],
+                    path: ['query', 'nonExistant'],
+                    extensions: {
+                      code: 'undefinedField',
+                      typeName: 'Query',
+                      fieldName: 'nonExistant',
+                    },
+                  }.to_json,
+                }],
+              },
+            ),
+          )
+        end
+      end
     end
   end