Merge branch '59587-add-graphql-logging' into 'master'

Add logging to GraphQL

Closes #59587

See merge request gitlab-org/gitlab-ce!27885

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)
 

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

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

doc/administration/logs.md

@@ -288,6 +288,20 @@ installations from source.
 
 It logs information whenever [Rack Attack] registers an abusive request.
 
+## `graphql_json.log`
+
+> [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 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":7}
+```
+
 ## Reconfigure Logs
 
 Reconfigure log files live in `/var/log/gitlab/reconfigure` for Omnibus GitLab

lib/gitlab/graphql/query_analyzers/log_query_complexity.rb

-# 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
-              Rails.logger.info("[GraphQL Query Complexity] #{complexity}  | admin? #{query.context[:current_user]&.admin?}")
-            end
-          end
-        end
-      end
-    end
-  end
-end

lib/gitlab/graphql/query_analyzers/logger_analyzer.rb

+# frozen_string_literal: true
+
+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)
+          variables = process_variables(query.provided_variables)
+          default_initial_values(query).merge({
+            query_string: query.query_string,
+            variables: variables
+          })
+        rescue => e
+          Gitlab::Sentry.track_exception(e)
+          default_initial_values(query)
+        end
+
+        def call(memo, visit_type, irep_node)
+          memo
+        end
+
+        def final_value(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_s)
+            variables.to_s
+          else
+            variables
+          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
+end

lib/gitlab/graphql_logger.rb

+# frozen_string_literal: true
+
+module Gitlab
+  class GraphqlLogger < Gitlab::JsonLogger
+    def self.file_name_noext
+      'graphql_json'
+    end
+  end
+end

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

+# frozen_string_literal: true
+
+require 'spec_helper'
+
+describe Gitlab::Graphql::QueryAnalyzers::LoggerAnalyzer do
+  subject { described_class.new }
+
+  describe '#analyze?' do
+    context 'feature flag disabled' do
+      before do
+        stub_feature_flags(graphql_logging: false)
+      end
+
+      it 'disables the analyzer' do
+        expect(subject.analyze?(anything)).to be_falsey
+      end
+    end
+
+    context 'feature flag enabled by default' do
+      it 'enables the analyzer' do
+        expect(subject.analyze?(anything)).to be_truthy
+      end
+    end
+  end
+end

spec/lib/gitlab/graphql_logger_spec.rb

+# frozen_string_literal: true
+
+require 'spec_helper'
+
+describe Gitlab::GraphqlLogger do
+  subject { described_class.new('/dev/null') }
+
+  let(:now) { Time.now }
+
+  it 'builds a logger once' do
+    expect(::Logger).to receive(:new).and_call_original
+
+    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

@@ -111,4 +111,29 @@ describe 'GitlabSchema configurations' do
       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 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
+
+    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

@@ -16,6 +16,54 @@ describe 'GraphQL' do
     end
   end
 
+  context 'logging' do
+    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
+
+      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 '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" }
+      end
+
+      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
     it 'returns an error' do
       post_graphql(query, variables: "This is not JSON")