Merge branch '331697-tracer-2-logger-tracer' into 'master'

Step 2- Add Graphql LoggerTracer to handle GraphqlLogger writing

See merge request gitlab-org/gitlab!72790

app/controllers/graphql_controller.rb

@@ -188,6 +188,5 @@ class GraphqlController < ApplicationController
 
   def logs
     RequestStore.store[:graphql_logs].to_a
-                .map { |log| log.except(:duration_s, :query_string) }
   end
 end

app/graphql/gitlab_schema.rb

@@ -10,11 +10,15 @@ class GitlabSchema < GraphQL::Schema
   DEFAULT_MAX_DEPTH = 15
   AUTHENTICATED_MAX_DEPTH = 20
 
+  # Tracers (order is important)
+  use Gitlab::Graphql::Tracers::LoggerTracer
+  use Gitlab::Graphql::GenericTracing # Old tracer which will be removed eventually
+  use Gitlab::Graphql::Tracers::TimerTracer
+
   use GraphQL::Subscriptions::ActionCableSubscriptions
   use GraphQL::Pagination::Connections
   use BatchLoader::GraphQL
   use Gitlab::Graphql::Pagination::Connections
-  use Gitlab::Graphql::GenericTracing
   use Gitlab::Graphql::Timeout, max_seconds: Gitlab.config.gitlab.graphql_timeout
 
   query_analyzer Gitlab::Graphql::QueryAnalyzers::LoggerAnalyzer.new

lib/gitlab/graphql/query_analyzers/logger_analyzer.rb

@@ -10,15 +10,10 @@ module Gitlab
         ALL_ANALYZERS = [COMPLEXITY_ANALYZER, DEPTH_ANALYZER, FIELD_USAGE_ANALYZER].freeze
 
         def initial_value(query)
-          variables = process_variables(query.provided_variables)
-          default_initial_values(query).merge({
-            operation_name: query.operation_name,
-            query_string: query.query_string,
-            variables: variables
-          })
-        rescue StandardError => e
-          Gitlab::ErrorTracking.track_and_raise_for_dev_exception(e)
-          default_initial_values(query)
+          {
+            time_started: Gitlab::Metrics::System.monotonic_time,
+            query: query
+          }
         end
 
         def call(memo, *)
@@ -28,25 +23,42 @@ module Gitlab
         def final_value(memo)
           return if memo.nil?
 
-          complexity, depth, field_usages = GraphQL::Analysis.analyze_query(memo[:query], ALL_ANALYZERS)
+          query = memo[:query]
+          complexity, depth, field_usages = GraphQL::Analysis.analyze_query(query, ALL_ANALYZERS)
 
           memo[:depth] = depth
           memo[:complexity] = complexity
           # This duration is not the execution time of the
           # query but the execution time of the analyzer.
-          memo[:duration_s] = duration(memo[:time_started]).round(1)
+          memo[:duration_s] = duration(memo[:time_started])
           memo[:used_fields] = field_usages.first
           memo[:used_deprecated_fields] = field_usages.second
 
-          RequestStore.store[:graphql_logs] ||= []
-          RequestStore.store[:graphql_logs] << memo
-          GraphqlLogger.info(memo.except!(:time_started, :query))
+          push_to_request_store(memo)
+
+          # This gl_analysis is included in the tracer log
+          query.context[:gl_analysis] = memo.except!(:time_started, :query)
         rescue StandardError => e
           Gitlab::ErrorTracking.track_and_raise_for_dev_exception(e)
         end
 
         private
 
+        def push_to_request_store(memo)
+          query = memo[:query]
+
+          # TODO: This RequestStore management is used to handle setting request wide metadata
+          # to improve preexisting logging. We should handle this either with ApplicationContext
+          # or in a separate tracer.
+          # https://gitlab.com/gitlab-org/gitlab/-/issues/343802
+
+          RequestStore.store[:graphql_logs] ||= []
+          RequestStore.store[:graphql_logs] << memo.except(:time_started, :duration_s, :query).merge({
+            variables: process_variables(query.provided_variables),
+            operation_name: query.operation_name
+          })
+        end
+
         def process_variables(variables)
           filtered_variables = filter_sensitive_variables(variables)
 
@@ -66,16 +78,6 @@ module Gitlab
         def duration(time_started)
           Gitlab::Metrics::System.monotonic_time - time_started
         end
-
-        def default_initial_values(query)
-          {
-            time_started: Gitlab::Metrics::System.monotonic_time,
-            query_string: nil,
-            query: query,
-            variables: nil,
-            duration_s: nil
-          }
-        end
       end
     end
   end

lib/gitlab/graphql/tracers/logger_tracer.rb

+# frozen_string_literal: true
+
+module Gitlab
+  module Graphql
+    module Tracers
+      # This tracer writes logs for certain trace events.
+      # It reads duration metadata written by TimerTracer.
+      class LoggerTracer
+        def self.use(schema)
+          schema.tracer(self.new)
+        end
+
+        def trace(key, data)
+          result = yield
+
+          case key
+          when "execute_query"
+            log_execute_query(**data)
+          end
+
+          result
+        end
+
+        private
+
+        def log_execute_query(query: nil, duration_s: 0)
+          # execute_query should always have :query, but we're just being defensive
+          return unless query
+
+          analysis_info = query.context[:gl_analysis]&.transform_keys { |key| "query_analysis.#{key}" }
+          info = {
+            trace_type: 'execute_query',
+            query_fingerprint: query.fingerprint,
+            duration_s: duration_s,
+            operation_name: query.operation_name,
+            operation_fingerprint: query.operation_fingerprint,
+            is_mutation: query.mutation?,
+            variables: clean_variables(query.provided_variables),
+            query_string: query.query_string
+          }
+
+          info.merge!(::Gitlab::ApplicationContext.current)
+          info.merge!(analysis_info) if analysis_info
+
+          ::Gitlab::GraphqlLogger.info(info)
+        end
+
+        def query_variables_for_logging(query)
+          clean_variables(query.provided_variables)
+        end
+
+        def clean_variables(variables)
+          ActiveSupport::ParameterFilter
+            .new(::Rails.application.config.filter_parameters)
+            .filter(variables)
+        end
+      end
+    end
+  end
+end

lib/gitlab/graphql/tracers/timer_tracer.rb

+# frozen_string_literal: true
+
+module Gitlab
+  module Graphql
+    module Tracers
+      # This graphql-ruby tracer records duration for trace events and merges
+      # the duration into the trace event's metadata. This way, separate tracers
+      # can all use the same duration information.
+      #
+      # NOTE: TimerTracer should be applied last **after** other tracers, so
+      # that it runs first (similar to function composition)
+      class TimerTracer
+        def self.use(schema)
+          schema.tracer(self.new)
+        end
+
+        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
+        end
+      end
+    end
+  end
+end

lib/gitlab/graphql/variables.rb

@@ -24,8 +24,13 @@ module Gitlab
           else
             {}
           end
-        when Hash, ActionController::Parameters
+        when Hash
           ambiguous_param
+        when ActionController::Parameters
+          # We can and have to trust the "Parameters" because `graphql-ruby` handles this hash safely
+          # Also, `graphql-ruby` uses hash-specific methods, for example `size`:
+          # https://sourcegraph.com/github.com/rmosolgo/graphql-ruby@61232b03412df6685406fc46c414e11d3f447817/-/blob/lib/graphql/query.rb?L304
+          ambiguous_param.to_unsafe_h
         when nil
           {}
         else

spec/lib/gitlab/graphql/query_analyzers/logger_analyzer_spec.rb

@@ -18,12 +18,6 @@ RSpec.describe Gitlab::Graphql::QueryAnalyzers::LoggerAnalyzer do
     GRAPHQL
   end
 
-  describe 'variables' do
-    subject { initial_value.fetch(:variables) }
-
-    it { is_expected.to eq('{:body=>"[FILTERED]"}') }
-  end
-
   describe '#final_value' do
     let(:monotonic_time_before) { 42 }
     let(:monotonic_time_after) { 500 }
@@ -42,7 +36,14 @@ RSpec.describe Gitlab::Graphql::QueryAnalyzers::LoggerAnalyzer do
 
     it 'inserts duration in seconds to memo and sets request store' do
       expect { final_value }.to change { memo[:duration_s] }.to(monotonic_time_duration)
-                            .and change { RequestStore.store[:graphql_logs] }.to([memo])
+                            .and change { RequestStore.store[:graphql_logs] }.to([{
+                              complexity: 4,
+                              depth: 2,
+                              operation_name: query.operation_name,
+                              used_deprecated_fields: [],
+                              used_fields: [],
+                              variables: { body: "[FILTERED]" }.to_s
+                            }])
     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"
+
+RSpec.describe Gitlab::Graphql::Tracers::LoggerTracer do
+  let(:dummy_schema) do
+    Class.new(GraphQL::Schema) do
+      # LoggerTracer depends on TimerTracer
+      use Gitlab::Graphql::Tracers::LoggerTracer
+      use Gitlab::Graphql::Tracers::TimerTracer
+
+      query_analyzer Gitlab::Graphql::QueryAnalyzers::LoggerAnalyzer.new
+
+      query Graphql::FakeQueryType
+    end
+  end
+
+  around do |example|
+    Gitlab::ApplicationContext.with_context(caller_id: 'caller_a', feature_category: 'feature_a') do
+      example.run
+    end
+  end
+
+  it "logs every query", :aggregate_failures do
+    variables = { name: "Ada Lovelace" }
+    query_string = 'query fooOperation($name: String) { helloWorld(message: $name) }'
+
+    # Build an actual query so we don't have to hardocde the "fingerprint" calculations
+    query = GraphQL::Query.new(dummy_schema, query_string, variables: variables)
+
+    expect(::Gitlab::GraphqlLogger).to receive(:info).with({
+      "correlation_id" => anything,
+      "meta.caller_id" => "caller_a",
+      "meta.feature_category" => "feature_a",
+      "query_analysis.duration_s" => kind_of(Numeric),
+      "query_analysis.complexity" => 1,
+      "query_analysis.depth" => 1,
+      "query_analysis.used_deprecated_fields" => [],
+      "query_analysis.used_fields" => ["FakeQuery.helloWorld"],
+      duration_s: be > 0,
+      is_mutation: false,
+      operation_fingerprint: query.operation_fingerprint,
+      operation_name: 'fooOperation',
+      query_fingerprint: query.fingerprint,
+      query_string: query_string,
+      trace_type: "execute_query",
+      variables: variables
+    })
+
+    dummy_schema.execute(query_string, variables: variables)
+  end
+end

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

+# frozen_string_literal: true
+require "fast_spec_helper"
+require "support/graphql/fake_tracer"
+require "support/graphql/fake_query_type"
+
+RSpec.describe Gitlab::Graphql::Tracers::TimerTracer do
+  let(:expected_duration) { 5 }
+  let(:tracer_spy) { spy('tracer_spy') }
+  let(:dummy_schema) do
+    schema = Class.new(GraphQL::Schema) do
+      use Gitlab::Graphql::Tracers::TimerTracer
+
+      query Graphql::FakeQueryType
+    end
+
+    schema.tracer(Graphql::FakeTracer.new(lambda { |*args| tracer_spy.trace(*args) }))
+
+    schema
+  end
+
+  before do
+    current_time = 0
+    allow(Gitlab::Metrics::System).to receive(:monotonic_time) do
+      current_time += expected_duration
+    end
+  end
+
+  it "adds duration_s to the trace metadata", :aggregate_failures do
+    query_string = "query fooOperation { helloWorld }"
+
+    dummy_schema.execute(query_string)
+
+    # "parse" and "execute_query" are just arbitrary trace events
+    expect(tracer_spy).to have_received(:trace).with("parse", {
+      duration_s: expected_duration,
+      query_string: query_string
+    })
+    expect(tracer_spy).to have_received(:trace).with("execute_query", {
+      # greater than expected duration because other calls made to `.monotonic_time` are outside our control
+      duration_s: be >= expected_duration,
+      query: instance_of(GraphQL::Query)
+    })
+  end
+end

spec/requests/api/graphql/gitlab_schema_spec.rb

@@ -190,19 +190,18 @@ RSpec.describe 'GitlabSchema configurations' do
     let(:query) { File.read(Rails.root.join('spec/fixtures/api/graphql/introspection.graphql')) }
 
     it 'logs the query complexity and depth' do
-      analyzer_memo = {
-        query_string: query,
-        variables: {}.to_s,
-        complexity: 181,
-        depth: 13,
-        duration_s: 7,
-        operation_name: 'IntrospectionQuery',
-        used_fields: an_instance_of(Array),
-        used_deprecated_fields: an_instance_of(Array)
-      }
-
       expect_any_instance_of(Gitlab::Graphql::QueryAnalyzers::LoggerAnalyzer).to receive(:duration).and_return(7)
-      expect(Gitlab::GraphqlLogger).to receive(:info).with(analyzer_memo)
+
+      expect(Gitlab::GraphqlLogger).to receive(:info).with(
+        hash_including(
+          trace_type: 'execute_query',
+          "query_analysis.duration_s" => 7,
+          "query_analysis.complexity" => 181,
+          "query_analysis.depth" => 13,
+          "query_analysis.used_deprecated_fields" => an_instance_of(Array),
+          "query_analysis.used_fields" => an_instance_of(Array)
+        )
+      )
 
       post_graphql(query, current_user: nil)
     end

spec/requests/api/graphql_spec.rb

@@ -12,21 +12,33 @@ RSpec.describe 'GraphQL' do
 
   describe 'logging' do
     shared_examples 'logging a graphql query' do
-      let(:expected_params) do
+      let(:expected_execute_query_log) do
         {
-          query_string: query,
-          variables: variables.to_s,
-          duration_s: anything,
+          "correlation_id" => kind_of(String),
+          "meta.caller_id" => "GraphqlController#execute",
+          "meta.client_id" => kind_of(String),
+          "meta.feature_category" => "not_owned",
+          "meta.remote_ip" => kind_of(String),
+          "query_analysis.duration_s" => kind_of(Numeric),
+          "query_analysis.depth" => 1,
+          "query_analysis.complexity" => 1,
+          "query_analysis.used_fields" => ['Query.echo'],
+          "query_analysis.used_deprecated_fields" => [],
+          # query_fingerprint starts with operation name
+          query_fingerprint: %r{^anonymous\/},
+          duration_s: kind_of(Numeric),
+          trace_type: 'execute_query',
           operation_name: nil,
-          depth: 1,
-          complexity: 1,
-          used_fields: ['Query.echo'],
-          used_deprecated_fields: []
+          # operation_fingerprint starts with operation name
+          operation_fingerprint: %r{^anonymous\/},
+          is_mutation: false,
+          variables: variables,
+          query_string: query
         }
       end
 
       it 'logs a query with the expected params' do
-        expect(Gitlab::GraphqlLogger).to receive(:info).with(expected_params).once
+        expect(Gitlab::GraphqlLogger).to receive(:info).with(expected_execute_query_log).once
 
         post_graphql(query, variables: variables)
       end

spec/support/graphql/fake_query_type.rb

+# frozen_string_literal: true
+
+module Graphql
+  class FakeQueryType < Types::BaseObject
+    graphql_name 'FakeQuery'
+
+    field :hello_world, String, null: true do
+      argument :message, String, required: false
+    end
+
+    def hello_world(message: "world")
+      "Hello #{message}!"
+    end
+  end
+end

spec/support/graphql/fake_tracer.rb

+# frozen_string_literal: true
+
+module Graphql
+  class FakeTracer
+    def initialize(trace_callback)
+      @trace_callback = trace_callback
+    end
+
+    def trace(*args)
+      @trace_callback.call(*args)
+
+      yield
+    end
+  end
+end