Apply reviewer feedback

- Move complexity and depth calls from `initial_value` to `final_value`
- Log variables as json
- test readability
- code and test structure/styling
- static query analyzers
- call `as_json` on `provided_variables`
- add exception tracking
- Add changelog file
- Call analyzers from LoggerAnalyzer
- Add exception handling

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

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

lib/gitlab/graphql/query_analyzers/logger_analyzer.rb

@@ -4,69 +4,67 @@ module Gitlab
   module Graphql
     module QueryAnalyzers
       class LoggerAnalyzer
-        # Called before initializing the analyzer.
-        # Returns true to run this analyzer, or false to skip it.
+        COMPLEXITY_ANALYZER = GraphQL::Analysis::QueryComplexity.new { |query, complexity_value| complexity_value }
+        DEPTH_ANALYZER = GraphQL::Analysis::QueryDepth.new { |query, depth_value| depth_value }
+
         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)
-          {
-            time_started: Gitlab::Metrics::System.monotonic_time,
+          variables = process_variables(query.provided_variables)
+          default_initial_values(query).merge({
             query_string: query.query_string,
-            variables: process_variables(query.provided_variables),
-            complexity: nil,
-            depth: nil,
-            duration: nil
-          }
+            variables: variables
+          })
+        rescue => e
+          Gitlab::Sentry.track_exception(e)
+          default_initial_values(query)
         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))
-          memo
+          return if memo.nil?
+
+          analyzers = [COMPLEXITY_ANALYZER, DEPTH_ANALYZER]
+          complexity, depth = GraphQL::Analysis.analyze_query(memo[:query], analyzers)
+
+          memo[:depth] = depth
+          memo[:complexity] = complexity
+          memo[:duration] = duration(memo[:time_started]).round(1)
+
+          GraphqlLogger.info(memo.except!(:time_started, :query))
+        rescue => e
+          Gitlab::Sentry.track_exception(e)
         end
 
         private
 
         def process_variables(variables)
-          if variables.respond_to?(:to_unsafe_h)
-            variables.to_unsafe_h
+          if variables.respond_to?(:to_s)
+            variables.to_s
           else
             variables
           end
         end
 
-        def set_complexity(memo)
-          GraphQL::Analysis::QueryComplexity.new do |query, complexity_value|
-            memo[:complexity] = complexity_value
-          end
-          memo
-        end
-
-        def set_depth(memo)
-          GraphQL::Analysis::QueryDepth.new do |query, depth_value|
-            memo[:depth] = depth_value
-          end
-          memo
-        end
-
         def duration(time_started)
           nanoseconds = Gitlab::Metrics::System.monotonic_time - time_started
           nanoseconds * 1000000
         end
+
+        def default_initial_values(query)
+          {
+            time_started: Gitlab::Metrics::System.monotonic_time,
+            query_string: nil,
+            query: query,
+            variables: nil,
+            duration: nil
+          }
+        end
       end
     end
   end

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

@@ -4,22 +4,6 @@ require 'spec_helper'
 
 describe Gitlab::Graphql::QueryAnalyzers::LoggerAnalyzer do
   subject { described_class.new }
-  let(:query_string) { "abc" }
-  let(:provided_variables) { { a: 1, b: 2, c: 3 } }
-  let!(:now) { Gitlab::Metrics::System.monotonic_time }
-  let(:complexity) { 4 }
-  let(:depth) { 2 }
-  let(:initial_values) do
-    { time_started: now,
-      query_string: query_string,
-      variables: provided_variables,
-      complexity: nil,
-      depth: nil,
-      duration: nil }
-  end
-  before do
-    allow(Gitlab::Metrics::System).to receive(:monotonic_time).and_return(now)
-  end
 
   describe '#analyze?' do
     context 'feature flag disabled' do
@@ -27,40 +11,15 @@ describe Gitlab::Graphql::QueryAnalyzers::LoggerAnalyzer do
         stub_feature_flags(graphql_logging: false)
       end
 
-      specify do
+      it 'disables the analyzer' do
         expect(subject.analyze?(anything)).to be_falsey
       end
     end
 
     context 'feature flag enabled by default' do
-      specify do
+      it 'enables the analyzer' do
         expect(subject.analyze?(anything)).to be_truthy
       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

@@ -4,6 +4,7 @@ require 'spec_helper'
 
 describe Gitlab::GraphqlLogger do
   subject { described_class.new('/dev/null') }
+
   let(:now) { Time.now }
 
   it 'builds a logger once' do
@@ -12,4 +13,28 @@ 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: 7
+      }
+
+      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(7)
+    end
+  end
 end

spec/requests/api/graphql/gitlab_schema_spec.rb

@@ -83,23 +83,38 @@ describe 'GitlabSchema configurations' do
     end
   end
 
-  context 'logging' do
-    it 'writes to the GraphQL log' do
-      expect(Gitlab::GraphqlLogger).to receive(:info)
-
+  context 'when IntrospectionQuery' do
+    it 'is not too complex' do
       query = File.read(Rails.root.join('spec/fixtures/api/graphql/introspection.graphql'))
 
       post_graphql(query, current_user: nil)
+
+      expect(graphql_errors).to be_nil
     end
   end
 
-  context 'when IntrospectionQuery' do
-    it 'is not too complex' do
-      query = File.read(Rails.root.join('spec/fixtures/api/graphql/introspection.graphql'))
+  context 'logging' 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: 0,
+        duration: 7
+      }
+
+      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
 
-      expect(graphql_errors).to be_nil
+    it 'logs using `format_message`' do
+      expect_any_instance_of(Gitlab::GraphqlLogger).to receive(:format_message)
+
+      post_graphql(query, current_user: nil)
     end
   end
 end

spec/requests/api/graphql_spec.rb

@@ -17,30 +17,49 @@ describe 'GraphQL' do
   end
 
   context 'logging' do
-    before do
-      expect(Gitlab::GraphqlLogger).to receive(:info).with(expected)
-    end
+    shared_examples 'logging a graphql query' do
+      let(:expected_params) do
+        { query_string: query, variables: variables.to_s, duration: anything, depth: 1, complexity: 1 }
+      end
 
-    context 'with no variables' do
-      let(:expected) do
-        { query_string: query, variables: {}, duration: anything, depth: 0, complexity: 0 }
+      it 'logs a query with the expected params' do
+        expect(Gitlab::GraphqlLogger).to receive(:info).with(expected_params).once
+
+        post_graphql(query, variables: variables)
       end
 
-      it 'logs the query' do
-        post_graphql(query)
+      it 'does not instantiate any query analyzers' do # they are static and re-used
+        expect(GraphQL::Analysis::QueryComplexity).not_to receive(:new)
+        expect(GraphQL::Analysis::QueryDepth).not_to receive(:new)
+
+        2.times { post_graphql(query, variables: variables) }
       end
     end
 
+    context 'with no variables' do
+      let(:variables) { {} }
+
+      it_behaves_like 'logging a graphql query'
+    end
+
     context 'with variables' do
-      let!(:variables) do
-        { foo: "bar" }
+      let(:variables) do
+        { "foo" => "bar" }
       end
-      let(:expected) do
-        { query_string: query, variables: variables, duration: anything, depth: 0, complexity: 0 }
+
+      it_behaves_like 'logging a graphql query'
+    end
+
+    context 'when there is an error in the logger' do
+      before do
+        allow_any_instance_of(Gitlab::Graphql::QueryAnalyzers::LoggerAnalyzer).to receive(:process_variables).and_raise(StandardError.new("oh noes!"))
       end
 
-      it 'logs the query' do
-        post_graphql(query, variables: variables)
+      it 'logs the exception in Sentry and continues with the request' do
+        expect(Gitlab::Sentry).to receive(:track_exception).at_least(1).times
+        expect(Gitlab::GraphqlLogger).to receive(:info)
+
+        post_graphql(query, variables: {})
       end
     end
   end