Call analyzers from LoggerAnalyzer

- Add changelog file
- Fix failing tests

changelogs/unreleased/59587-add-graphql-logging.yml

+---
+title: Add dedicated logging for GraphQL queries
+merge_request: 27885
+author: Charlie Ablett
+type: other

lib/gitlab/graphql/query_analyzers/logger_analyzer.rb

@@ -4,35 +4,27 @@ module Gitlab
   module Graphql
     module QueryAnalyzers
       class LoggerAnalyzer
-        # Called before initializing the analyzer.
-        # Returns true to run this analyzer, or false to skip it.
         def analyze?(query)
           Feature.enabled?(:graphql_logging, default_enabled: true)
         end
 
-        # Called before the visit.
-        # Returns the initial value for `memo`
         def initial_value(query)
+          analyzers = [complexity_analyzer, depth_analyzer]
+          complexity, depth = GraphQL::Analysis.analyze_query(query, analyzers)
           {
             time_started: Gitlab::Metrics::System.monotonic_time,
             query_string: query.query_string,
             variables: process_variables(query.provided_variables),
-            complexity: nil,
-            depth: nil,
+            complexity: complexity,
+            depth: depth,
             duration: nil
           }
         end
 
-        # This is like the `reduce` callback.
-        # The return value is passed to the next call as `memo`
         def call(memo, visit_type, irep_node)
-          memo = set_complexity(memo)
-          set_depth(memo)
+          memo
         end
 
-        # Called when we're done the whole visit.
-        # The return value may be a GraphQL::AnalysisError (or an array of them).
-        # Or, you can use this hook to write to a log, etc
         def final_value(memo)
           memo[:duration] = "#{duration(memo[:time_started]).round(1)}ms"
           GraphqlLogger.info(memo.except!(:time_started))
@@ -49,18 +41,16 @@ module Gitlab
           end
         end
 
-        def set_complexity(memo)
+        def complexity_analyzer
           GraphQL::Analysis::QueryComplexity.new do |query, complexity_value|
-            memo[:complexity] = complexity_value
+            complexity_value
           end
-          memo
         end
 
-        def set_depth(memo)
+        def depth_analyzer
           GraphQL::Analysis::QueryDepth.new do |query, depth_value|
-            memo[:depth] = depth_value
+            depth_value
           end
-          memo
         end
 
         def duration(time_started)

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

@@ -38,29 +38,4 @@ describe Gitlab::Graphql::QueryAnalyzers::LoggerAnalyzer do
       end
     end
   end
-
-  describe '#initial_value' do
-    it 'assembles a hash with initial values' do
-      query = OpenStruct.new(query_string: query_string, provided_variables: provided_variables)
-
-      expect(subject.initial_value(query)).to eq initial_values
-    end
-  end
-
-  describe '#call' do
-    before do
-      # some statements to fudge the complexity and depth
-    end
-
-    it 'sets the complexity and depth' do
-      expected_hash = { time_started: now,
-                        query_string: query_string,
-                        variables: provided_variables,
-                        complexity: nil,
-                        depth: depth,
-                        duration: complexity }
-
-      expect(subject.call(initial_values, nil, nil)).to eq expected_hash
-    end
-  end
 end

spec/lib/gitlab/graphql_logger_spec.rb

@@ -12,4 +12,26 @@ describe Gitlab::GraphqlLogger do
     subject.info('hello world')
     subject.error('hello again')
   end
+
+  context 'logging a GraphQL query' do
+    let(:query) { File.read(Rails.root.join('spec/fixtures/api/graphql/introspection.graphql')) }
+    it 'logs a query from JSON' do
+      analyzer_memo = {
+          query_string: query,
+          variables: {},
+          complexity: 181,
+          depth: 0,
+          duration: "7ms"
+      }
+      output = subject.format_message('INFO', now, 'test', analyzer_memo)
+      data = JSON.parse(output)
+
+      expect(data['severity']).to eq('INFO')
+      expect(data['time']).to eq(now.utc.iso8601(3))
+      expect(data['complexity']).to eq(181)
+      expect(data['variables']).to eq({})
+      expect(data['depth']).to eq(0)
+      expect(data['duration']).to eq("7ms")
+    end
+  end
 end

spec/requests/api/graphql/gitlab_schema_spec.rb

@@ -84,10 +84,18 @@ describe 'GitlabSchema configurations' do
   end
 
   context 'logging' do
-    it 'writes to the GraphQL log' do
-      expect(Gitlab::GraphqlLogger).to receive(:info)
-
-      query = File.read(Rails.root.join('spec/fixtures/api/graphql/introspection.graphql'))
+    let(:query) { File.read(Rails.root.join('spec/fixtures/api/graphql/introspection.graphql')) }
+
+    it 'logs the query complexity' do
+      analyzer_memo = {
+          query_string: query,
+          variables: {},
+          complexity: 181,
+          depth: 0,
+          duration: "7ms"
+      }
+      expect_any_instance_of(Gitlab::Graphql::QueryAnalyzers::LoggerAnalyzer).to receive(:duration).and_return(7)
+      expect(Gitlab::GraphqlLogger).to receive(:info).with(analyzer_memo)
 
       post_graphql(query, current_user: nil)
     end

spec/requests/api/graphql_spec.rb

@@ -23,7 +23,7 @@ describe 'GraphQL' do
 
     context 'with no variables' do
       let(:expected) do
-        { query_string: query, variables: {}, duration: anything, depth: 0, complexity: 0 }
+        { query_string: query, variables: {}, duration: anything, depth: 1, complexity: 1 }
       end
 
       it 'logs the query' do
@@ -33,10 +33,10 @@ describe 'GraphQL' do
 
     context 'with variables' do
       let!(:variables) do
-        { foo: "bar" }
+        { "foo" => "bar" }
       end
       let(:expected) do
-        { query_string: query, variables: variables, duration: anything, depth: 0, complexity: 0 }
+        { query_string: query, variables: variables, duration: anything, depth: 1, complexity: 1 }
       end
 
       it 'logs the query' do