Merge branch 'bvl-ensure-graphql-duration-log' into 'master'

Log durations for failing GraphQL-queries

See merge request gitlab-org/gitlab!74801

lib/gitlab/graphql/tracers/logger_tracer.rb

@@ -11,19 +11,20 @@ module Gitlab
         end
 
         def trace(key, data)
-          result = yield
-
+          yield
+        rescue StandardError => e
+          data[:exception] = e
+          raise e
+        ensure
           case key
           when "execute_query"
             log_execute_query(**data)
           end
-
-          result
         end
 
         private
 
-        def log_execute_query(query: nil, duration_s: 0)
+        def log_execute_query(query: nil, duration_s: 0, exception: nil)
           # execute_query should always have :query, but we're just being defensive
           return unless query
 
@@ -39,6 +40,8 @@ module Gitlab
             query_string: query.query_string
           }
 
+          Gitlab::ExceptionLogFormatter.format!(exception, info)
+
           info.merge!(::Gitlab::ApplicationContext.current)
           info.merge!(analysis_info) if analysis_info
 

lib/gitlab/graphql/tracers/timer_tracer.rb

@@ -17,13 +17,9 @@ module Gitlab
         def trace(key, data)
           start_time = Gitlab::Metrics::System.monotonic_time
 
-          result = yield
-
-          duration_s = Gitlab::Metrics::System.monotonic_time - start_time
-
-          data[:duration_s] = duration_s
-
-          result
+          yield
+        ensure
+          data[:duration_s] = Gitlab::Metrics::System.monotonic_time - start_time
         end
       end
     end

spec/lib/gitlab/graphql/tracers/logger_tracer_spec.rb

 # frozen_string_literal: true
-require "fast_spec_helper"
-require "support/graphql/fake_query_type"
+require "spec_helper"
 
 RSpec.describe Gitlab::Graphql::Tracers::LoggerTracer do
   let(:dummy_schema) do
@@ -49,4 +48,15 @@ RSpec.describe Gitlab::Graphql::Tracers::LoggerTracer do
 
     dummy_schema.execute(query_string, variables: variables)
   end
+
+  it 'logs exceptions for breaking queries' do
+    query_string = "query fooOperation { breakingField }"
+
+    expect(::Gitlab::GraphqlLogger).to receive(:info).with(a_hash_including({
+      'exception.message' => 'This field is supposed to break',
+      'exception.class' => 'RuntimeError'
+    }))
+
+    expect { dummy_schema.execute(query_string) }.to raise_error(/This field is supposed to break/)
+  end
 end

spec/lib/gitlab/graphql/tracers/metrics_tracer_spec.rb

 # frozen_string_literal: true
 
-require 'fast_spec_helper'
+require 'spec_helper'
 require 'rspec-parameterized'
 require "support/graphql/fake_query_type"
 
@@ -36,7 +36,7 @@ RSpec.describe Gitlab::Graphql::Tracers::MetricsTracer do
     end
 
     with_them do
-      it 'increments sli' do
+      it 'increments apdex sli' do
         # Trigger initialization
         fake_schema
 
@@ -56,5 +56,13 @@ RSpec.describe Gitlab::Graphql::Tracers::MetricsTracer do
         fake_schema.execute("query lorem { helloWorld }")
       end
     end
+
+    it "does not record apdex for failing queries" do
+      query_string = "query fooOperation { breakingField }"
+
+      expect(Gitlab::Metrics::RailsSlis.graphql_query_apdex).not_to receive(:increment)
+
+      expect { fake_schema.execute(query_string) }.to raise_error(/This field is supposed to break/)
+    end
   end
 end

spec/lib/gitlab/graphql/tracers/timer_tracer_spec.rb

@@ -20,6 +20,7 @@ RSpec.describe Gitlab::Graphql::Tracers::TimerTracer do
 
   before do
     current_time = 0
+    allow(tracer_spy).to receive(:trace)
     allow(Gitlab::Metrics::System).to receive(:monotonic_time) do
       current_time += expected_duration
     end
@@ -30,6 +31,18 @@ RSpec.describe Gitlab::Graphql::Tracers::TimerTracer do
 
     dummy_schema.execute(query_string)
 
+    expect_to_have_traced(tracer_spy, expected_duration, query_string)
+  end
+
+  it "adds a duration_s even if the query failed" do
+    query_string = "query fooOperation { breakingField }"
+
+    expect { dummy_schema.execute(query_string) }.to raise_error(/This field is supposed to break/)
+
+    expect_to_have_traced(tracer_spy, expected_duration, query_string)
+  end
+
+  def expect_to_have_traced(tracer_spy, expected_duration, query_string)
     # "parse" and "execute_query" are just arbitrary trace events
     expect(tracer_spy).to have_received(:trace).with("parse", {
       duration_s: expected_duration,

spec/support/graphql/fake_query_type.rb

 # frozen_string_literal: true
+require 'graphql'
 
 module Graphql
-  class FakeQueryType < Types::BaseObject
+  class FakeQueryType < ::GraphQL::Schema::Object
     graphql_name 'FakeQuery'
 
     field :hello_world, String, null: true do
       argument :message, String, required: false
     end
 
+    field :breaking_field, String, null: true
+
     def hello_world(message: "world")
       "Hello #{message}!"
     end
+
+    def breaking_field
+      raise "This field is supposed to break"
+    end
   end
 end