Move complexity/depth to `final_value`

Tidy tests according to reviewer comments.
Move complexity and depth calls from `initial_value` to `final_value`
Log variables as json

4 files changed, 33 insertions, 38 deletions

diff --git a/lib/gitlab/graphql/query_analyzers/logger_analyzer.rb b/lib/gitlab/graphql/query_analyzers/logger_analyzer.rb
index 1e49c894ecb..8119d232124 100644
--- a/lib/gitlab/graphql/query_analyzers/logger_analyzer.rb
+++ b/lib/gitlab/graphql/query_analyzers/logger_analyzer.rb
@@ -9,14 +9,11 @@ module Gitlab
         end
 
         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,
+            query: query,
             variables: process_variables(query.provided_variables),
-            complexity: complexity,
-            depth: depth,
             duration: nil
           }
         end
@@ -26,16 +23,21 @@ module Gitlab
         end
 
         def final_value(memo)
-          memo[:duration] = "#{duration(memo[:time_started]).round(1)}ms"
-          GraphqlLogger.info(memo.except!(:time_started))
-          memo
+          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))
         end
 
         private
 
         def process_variables(variables)
-          if variables.respond_to?(:to_unsafe_h)
-            variables.to_unsafe_h
+          if variables.respond_to?(:to_json)
+            variables.to_json
           else
             variables
           end
diff --git a/spec/lib/gitlab/graphql/query_analyzers/logger_analyzer_spec.rb b/spec/lib/gitlab/graphql/query_analyzers/logger_analyzer_spec.rb
index 4491c1cfa65..cbf35c1095a 100644
--- a/spec/lib/gitlab/graphql/query_analyzers/logger_analyzer_spec.rb
+++ b/spec/lib/gitlab/graphql/query_analyzers/logger_analyzer_spec.rb
@@ -4,19 +4,9 @@ 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
@@ -27,7 +17,7 @@ describe Gitlab::Graphql::QueryAnalyzers::LoggerAnalyzer do
         stub_feature_flags(graphql_logging: false)
       end
 
-      specify do
+      it 'enables the analyzer' do
         expect(subject.analyze?(anything)).to be_falsey
       end
     end
diff --git a/spec/lib/gitlab/graphql_logger_spec.rb b/spec/lib/gitlab/graphql_logger_spec.rb
index 4157bb86f1c..c8d4dac2153 100644
--- a/spec/lib/gitlab/graphql_logger_spec.rb
+++ b/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
@@ -15,13 +16,14 @@ describe Gitlab::GraphqlLogger do
 
   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"
+          duration: 7
       }
       output = subject.format_message('INFO', now, 'test', analyzer_memo)
       data = JSON.parse(output)
@@ -31,7 +33,7 @@ describe Gitlab::GraphqlLogger do
       expect(data['complexity']).to eq(181)
       expect(data['variables']).to eq({})
       expect(data['depth']).to eq(0)
-      expect(data['duration']).to eq("7ms")
+      expect(data['duration']).to eq(7)
     end
   end
 end
diff --git a/spec/requests/api/graphql_spec.rb b/spec/requests/api/graphql_spec.rb
index ebf223127b5..abc24fc0fe8 100644
--- a/spec/requests/api/graphql_spec.rb
+++ b/spec/requests/api/graphql_spec.rb
@@ -17,31 +17,32 @@ describe 'GraphQL' do
   end
 
   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 }
+      end
+
+      it 'logs a query with the expected params' do
+        post_graphql(query, variables: variables)
+      end
+    end
+
     before do
-      expect(Gitlab::GraphqlLogger).to receive(:info).with(expected)
+      expect(Gitlab::GraphqlLogger).to receive(:info).with(expected_params).once
     end
 
     context 'with no variables' do
-      let(:expected) do
-        { query_string: query, variables: {}, duration: anything, depth: 1, complexity: 1 }
-      end
+      let(:variables) { {} }
 
-      it 'logs the query' do
-        post_graphql(query)
-      end
+      it_behaves_like 'logging a graphql query'
     end
 
     context 'with variables' do
-      let!(:variables) do
+      let(:variables) do
         { "foo" => "bar" }
       end
-      let(:expected) do
-        { query_string: query, variables: variables, duration: anything, depth: 1, complexity: 1 }
-      end
 
-      it 'logs the query' do
-        post_graphql(query, variables: variables)
-      end
+      it_behaves_like 'logging a graphql query'
     end
   end