Merge branch 'fix_graphql_logs_for_multiplex_requests' into 'master'

Fix the GraphQL logs for multiplex queries

See merge request gitlab-org/gitlab!56763

app/controllers/graphql_controller.rb

@@ -146,8 +146,7 @@ class GraphqlController < ApplicationController
   end
 
   def logs
-    RequestStore.store[:graphql_logs].to_h
-                .except(:duration_s, :query_string)
-                .merge(operation_name: params[:operationName])
+    RequestStore.store[:graphql_logs].to_a
+                .map { |log| log.except(:duration_s, :query_string) }
   end
 end

lib/gitlab/graphql/query_analyzers/logger_analyzer.rb

@@ -12,6 +12,7 @@ module Gitlab
         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
           })
@@ -20,8 +21,8 @@ module Gitlab
           default_initial_values(query)
         end
 
-        def call(memo, visit_type, irep_node)
-          RequestStore.store[:graphql_logs] = memo
+        def call(memo, *)
+          memo
         end
 
         def final_value(memo)
@@ -37,6 +38,8 @@ module Gitlab
           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))
         rescue => e
           Gitlab::ErrorTracking.track_and_raise_for_dev_exception(e)

spec/controllers/graphql_controller_spec.rb

@@ -175,22 +175,44 @@ RSpec.describe GraphqlController do
   end
 
   describe '#append_info_to_payload' do
-    let(:graphql_query) { graphql_query_for('project', { 'fullPath' => 'foo' }, %w(id name)) }
-    let(:mock_store) { { graphql_logs: { foo: :bar } } }
+    let(:query_1) { { query: graphql_query_for('project', { 'fullPath' => 'foo' }, %w(id name), 'getProject_1') } }
+    let(:query_2) { { query: graphql_query_for('project', { 'fullPath' => 'bar' }, %w(id), 'getProject_2') } }
+    let(:graphql_queries) { [query_1, query_2] }
     let(:log_payload) { {} }
+    let(:expected_logs) do
+      [
+        {
+          operation_name: 'getProject_1',
+          complexity: 3,
+          depth: 2,
+          used_deprecated_fields: [],
+          used_fields: ['Project.id', 'Project.name', 'Query.project'],
+          variables: '{}'
+        },
+        {
+          operation_name: 'getProject_2',
+          complexity: 2,
+          depth: 2,
+          used_deprecated_fields: [],
+          used_fields: ['Project.id', 'Query.project'],
+          variables: '{}'
+        }
+      ]
+    end
 
     before do
-      allow(RequestStore).to receive(:store).and_return(mock_store)
+      RequestStore.clear!
+
       allow(controller).to receive(:append_info_to_payload).and_wrap_original do |method, *|
         method.call(log_payload)
       end
     end
 
     it 'appends metadata for logging' do
-      post :execute, params: { query: graphql_query, operationName: 'Foo' }
+      post :execute, params: { _json: graphql_queries }
 
       expect(controller).to have_received(:append_info_to_payload)
-      expect(log_payload.dig(:metadata, :graphql)).to eq({ operation_name: 'Foo', foo: :bar })
+      expect(log_payload.dig(:metadata, :graphql)).to match_array(expected_logs)
     end
   end
 end

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

@@ -3,43 +3,46 @@
 require 'spec_helper'
 
 RSpec.describe Gitlab::Graphql::QueryAnalyzers::LoggerAnalyzer do
-  subject { described_class.new }
-
-  describe '#initial_value' do
-    it 'filters out sensitive variables' do
-      doc = GraphQL.parse <<-GRAPHQL
-        mutation createNote($body: String!) {
-          createNote(input: {noteableId: "1", body: $body}) {
-            note {
-              id
-            }
+  let(:initial_value) { analyzer.initial_value(query) }
+  let(:analyzer) { described_class.new }
+  let(:query) { GraphQL::Query.new(GitlabSchema, document: document, context: {}, variables: { body: "some note" }) }
+  let(:document) do
+    GraphQL.parse <<-GRAPHQL
+      mutation createNote($body: String!) {
+        createNote(input: {noteableId: "1", body: $body}) {
+          note {
+            id
           }
         }
-      GRAPHQL
+      }
+    GRAPHQL
+  end
 
-      query = GraphQL::Query.new(GitlabSchema, document: doc, context: {}, variables: { body: "some note" })
+  describe 'variables' do
+    subject { initial_value.fetch(:variables) }
 
-      expect(subject.initial_value(query)[:variables]).to eq('{:body=>"[FILTERED]"}')
-    end
+    it { is_expected.to eq('{:body=>"[FILTERED]"}') }
   end
 
   describe '#final_value' do
     let(:monotonic_time_before) { 42 }
     let(:monotonic_time_after) { 500 }
     let(:monotonic_time_duration) { monotonic_time_after - monotonic_time_before }
+    let(:memo) { initial_value }
+
+    subject(:final_value) { analyzer.final_value(memo) }
+
+    before do
+      RequestStore.store[:graphql_logs] = nil
 
-    it 'returns a duration in seconds' do
       allow(GraphQL::Analysis).to receive(:analyze_query).and_return([4, 2, [[], []]])
       allow(Gitlab::Metrics::System).to receive(:monotonic_time).and_return(monotonic_time_before, monotonic_time_after)
       allow(Gitlab::GraphqlLogger).to receive(:info)
+    end
 
-      expected_duration = monotonic_time_duration
-      memo = subject.initial_value(spy('query'))
-
-      subject.final_value(memo)
-
-      expect(memo).to have_key(:duration_s)
-      expect(memo[:duration_s]).to eq(expected_duration)
+    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])
     end
   end
 end

spec/requests/api/graphql/gitlab_schema_spec.rb

@@ -191,6 +191,7 @@ RSpec.describe 'GitlabSchema configurations' do
         complexity: 181,
         depth: 13,
         duration_s: 7,
+        operation_name: 'IntrospectionQuery',
         used_fields: an_instance_of(Array),
         used_deprecated_fields: an_instance_of(Array)
       }

spec/requests/api/graphql_spec.rb

@@ -13,6 +13,7 @@ RSpec.describe 'GraphQL' do
           query_string: query,
           variables: variables.to_s,
           duration_s: anything,
+          operation_name: nil,
           depth: 1,
           complexity: 1,
           used_fields: ['Query.echo'],

spec/support/helpers/graphql_helpers.rb

@@ -222,9 +222,12 @@ module GraphqlHelpers
     lazy_vals.is_a?(Array) ? lazy_vals.map { |val| sync(val) } : sync(lazy_vals)
   end
 
-  def graphql_query_for(name, args = {}, selection = nil)
+  def graphql_query_for(name, args = {}, selection = nil, operation_name = nil)
     type = GitlabSchema.types['Query'].fields[GraphqlHelpers.fieldnamerize(name)]&.type
-    wrap_query(query_graphql_field(name, args, selection, type))
+    query = wrap_query(query_graphql_field(name, args, selection, type))
+    query = "query #{operation_name}#{query}" if operation_name
+
+    query
   end
 
   def wrap_query(query)