Implement logger analyzer

- Modify GraphqlLogger to subclass JsonLogger
- Replace the single-line analyser with one that can log all the GraphQL
query related information in one place.
- Implement analyzer behavior with spec

app/graphql/gitlab_schema.rb

@@ -16,7 +16,7 @@ class GitlabSchema < GraphQL::Schema
   use Gitlab::Graphql::Connections
   use Gitlab::Graphql::GenericTracing
 
-  query_analyzer Gitlab::Graphql::QueryAnalyzers::LogQueryComplexity.analyzer
+  query_analyzer Gitlab::Graphql::QueryAnalyzers::LoggerAnalyzer.new
 
   query(Types::QueryType)
 

lib/gitlab/graphql/query_analyzers/log_query_complexity.rb

@@ -1,18 +0,0 @@
-# frozen_string_literal: true
-
-module Gitlab
-  module Graphql
-    module QueryAnalyzers
-      class LogQueryComplexity
-        class << self
-          def analyzer
-            GraphQL::Analysis::QueryComplexity.new do |query, complexity|
-              # temporary until https://gitlab.com/gitlab-org/gitlab-ce/issues/59587
-              GraphqlLogger.info("[Query Complexity] #{complexity}  | admin? #{query.context[:current_user]&.admin?}")
-            end
-          end
-        end
-      end
-    end
-  end
-end

lib/gitlab/graphql/query_analyzers/logger_analyzer.rb

@@ -0,0 +1,65 @@
+# frozen_string_literal: true
+
+module Gitlab
+  module Graphql
+    module QueryAnalyzers
+      class LoggerAnalyzer
+        def initialize
+          @info_hash = {}
+        end
+
+        # Called before initializing the analyzer.
+        # Returns true to run this analyzer, or false to skip it.
+        def analyze?(query)
+          true # unless there's some reason why we wouldn't log?
+        end
+
+        # Called before the visit.
+        # Returns the initial value for `memo`
+        def initial_value(query)
+          {
+            time_started: Time.zone.now,
+            query_string: query.query_string,
+            variables: query.provided_variables
+          }
+        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
+        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"
+          set_complexity
+          set_depth
+          GraphqlLogger.info(memo.except!(:time_started).merge(@info_hash))
+          memo
+        end
+
+        private
+
+        def set_complexity
+          GraphQL::Analysis::QueryComplexity.new do |query, complexity_value|
+            @info_hash[:complexity] = complexity_value
+          end
+        end
+
+        def set_depth
+          GraphQL::Analysis::QueryDepth.new do |query, depth_value|
+            @info_hash[:depth] = depth_value
+          end
+        end
+
+        def duration(time_started)
+          nanoseconds = Time.zone.now - time_started
+          nanoseconds / 1000000
+        end
+      end
+    end
+  end
+end

lib/gitlab/graphql_logger.rb

@@ -1,19 +1,9 @@
 # frozen_string_literal: true
 
 module Gitlab
-  class GraphqlLogger < Gitlab::Logger
+  class GraphqlLogger < Gitlab::JsonLogger
     def self.file_name_noext
       'graphql_json'
     end
-
-    # duration
-    # complexity
-    # depth
-    # sanitized variables (?)
-    # a structured representation of the query (?)
-
-    def format_message(severity, timestamp, progname, msg)
-      "#{timestamp.to_s(:long)}: #{msg}\n"
-    end
   end
 end

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

@@ -0,0 +1,27 @@
+# frozen_string_literal: true
+
+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(:complexity) { 4 }
+  let(:depth) { 2 }
+  let(:expected_hash) do
+    { query_string: query_string,
+      variables: provided_variables,
+      complexity: complexity,
+      depth: depth }
+  end
+
+  it 'assembles a hash' do
+    query = OpenStruct.new(query_string: query_string, provided_variables: provided_variables)
+
+    subject.initial_value(query)
+
+    expect(subject.instance_variable_get("@info_hash")).to eq expected_hash
+  end
+
+end

spec/lib/gitlab/graphql_logger_spec.rb

@@ -1,6 +1,8 @@
+# frozen_string_literal: true
+
 require 'spec_helper'
 
-describe Gitlab::GraphqlLogger, :request_store do
+describe Gitlab::GraphqlLogger do
   subject { described_class.new('/dev/null') }
   let(:now) { Time.now }
 
@@ -10,12 +12,4 @@ describe Gitlab::GraphqlLogger, :request_store do
     subject.info('hello world')
     subject.error('hello again')
   end
-
-  describe '#format_message' do
-    it 'formats properly' do
-      output = subject.format_message('INFO', now, 'test', 'Hello world')
-
-      expect(output).to match(/Hello world/)
-    end
-  end
 end

spec/requests/api/graphql_spec.rb

@@ -16,6 +16,17 @@ describe 'GraphQL' do
     end
   end
 
+  context 'logging' do
+    it 'logs the query' do
+      expected = { query_string: query, variables: {}, duration: anything }
+
+      expect(Gitlab::GraphqlLogger).to receive(:info).with(expected)
+
+      post_graphql(query)
+    end
+
+  end
+
   context 'invalid variables' do
     it 'returns an error' do
       post_graphql(query, variables: "This is not JSON")