Apply reviewer feedback

- Comply doc with guidelines
- Improve tests for readability and completeness
- Separate out phases visually with newlines
- Add `format_message` test
- test readability
- code and test structure/styling
- static query analyzers
- call `as_json` on `provided_variables`
- add exception handling

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

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

doc/administration/logs.md

@@ -290,15 +290,16 @@ It logs information whenever [Rack Attack] registers an abusive request.
 
 ## `graphql_json.log`
 
-Introduced in Gitlab 12.0.
+> [Introduced](https://gitlab.com/gitlab-org/gitlab-ce/issues/59587) in GitLab 12.0.
+
 This file lives in `/var/log/gitlab/gitlab-rails/graphql_json.log` for
 Omnibus GitLab packages or in `/home/git/gitlab/log/graphql_json.log` for
 installations from source.
 
-GraphQL queries are recorded here. For example:
+GraphQL queries are recorded in that file. For example:
 
 ```json
-{"query_string":"query IntrospectionQuery{__schema {queryType { name },mutationType { name }}}...(etc)","variables":{"a":1,"b":2},"complexity":181,"depth":1,"duration":"7ms"}
+{"query_string":"query IntrospectionQuery{__schema {queryType { name },mutationType { name }}}...(etc)","variables":{"a":1,"b":2},"complexity":181,"depth":1,"duration":7}
 ```
 
 ## Reconfigure Logs

lib/gitlab/graphql/query_analyzers/logger_analyzer.rb

@@ -4,18 +4,22 @@ module Gitlab
   module Graphql
     module QueryAnalyzers
       class LoggerAnalyzer
+        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
 
         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,
-            query: query,
-            variables: process_variables(query.provided_variables),
-            duration: nil
-          }
+            variables: variables
+          })
+        rescue => e
+          Gitlab::Sentry.track_exception(e)
+          default_initial_values(query)
         end
 
         def call(memo, visit_type, irep_node)
@@ -23,7 +27,9 @@ module Gitlab
         end
 
         def final_value(memo)
-          analyzers = [complexity_analyzer, depth_analyzer]
+          return if memo.nil?
+
+          analyzers = [COMPLEXITY_ANALYZER, DEPTH_ANALYZER]
           complexity, depth = GraphQL::Analysis.analyze_query(memo[:query], analyzers)
 
           memo[:depth] = depth
@@ -31,34 +37,34 @@ module Gitlab
           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_json)
-            variables.to_json
+          if variables.respond_to?(:to_s)
+            variables.to_s
           else
             variables
           end
         end
 
-        def complexity_analyzer
-          GraphQL::Analysis::QueryComplexity.new do |query, complexity_value|
-            complexity_value
-          end
-        end
-
-        def depth_analyzer
-          GraphQL::Analysis::QueryDepth.new do |query, depth_value|
-            depth_value
-          end
-        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

@@ -5,25 +5,19 @@ require 'spec_helper'
 describe Gitlab::Graphql::QueryAnalyzers::LoggerAnalyzer do
   subject { described_class.new }
 
-  let!(:now) { Gitlab::Metrics::System.monotonic_time }
-
-  before do
-    allow(Gitlab::Metrics::System).to receive(:monotonic_time).and_return(now)
-  end
-
   describe '#analyze?' do
     context 'feature flag disabled' do
       before do
         stub_feature_flags(graphql_logging: false)
       end
 
-      it 'enables the analyzer' 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

spec/lib/gitlab/graphql_logger_spec.rb

@@ -19,15 +19,16 @@ describe Gitlab::GraphqlLogger do
 
     it 'logs a query from JSON' do
       analyzer_memo = {
-          query_string: query,
-          variables: {},
-          complexity: 181,
-          depth: 0,
-          duration: 7
+        query_string: query,
+        variables: {},
+        complexity: 181,
+        depth: 0,
+        duration: 7
       }
+
       output = subject.format_message('INFO', now, 'test', analyzer_memo)
-      data = JSON.parse(output)
 
+      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)

spec/requests/api/graphql/gitlab_schema_spec.rb

@@ -83,31 +83,38 @@ describe 'GitlabSchema configurations' do
     end
   end
 
+  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 'logging' do
     let(:query) { File.read(Rails.root.join('spec/fixtures/api/graphql/introspection.graphql')) }
 
-    it 'logs the query complexity' do
+    it 'logs the query complexity and depth' do
       analyzer_memo = {
-          query_string: query,
-          variables: {},
-          complexity: 181,
-          depth: 0,
-          duration: "7ms"
+        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
-  end
 
-  context 'when IntrospectionQuery' do
-    it 'is not too complex' do
-      query = File.read(Rails.root.join('spec/fixtures/api/graphql/introspection.graphql'))
+    it 'logs using `format_message`' do
+      expect_any_instance_of(Gitlab::GraphqlLogger).to receive(:format_message)
 
       post_graphql(query, current_user: nil)
-
-      expect(graphql_errors).to be_nil
     end
   end
 end

spec/requests/api/graphql_spec.rb

@@ -19,16 +19,21 @@ describe 'GraphQL' do
   context 'logging' do
     shared_examples 'logging a graphql query' do
       let(:expected_params) do
-        { query_string: query, variables: variables.to_json, duration: anything, depth: 1, complexity: 1 }
+        { query_string: query, variables: variables.to_s, duration: anything, depth: 1, complexity: 1 }
       end
 
       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
-    end
 
-    before do
-      expect(Gitlab::GraphqlLogger).to receive(:info).with(expected_params).once
+      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
@@ -44,6 +49,19 @@ describe 'GraphQL' do
 
       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 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
 
   context 'invalid variables' do