diff --git a/app/graphql/gitlab_schema.rb b/app/graphql/gitlab_schema.rb index a63f45f231c6aea0451deb4fe255452a1ad91397..f8ad6bee21b2f7be8ebff3dcdf660ad3cfbfc4dc 100644 --- a/app/graphql/gitlab_schema.rb +++ b/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) diff --git a/changelogs/unreleased/59587-add-graphql-logging.yml b/changelogs/unreleased/59587-add-graphql-logging.yml new file mode 100644 index 0000000000000000000000000000000000000000..74c2a734f37c2fb2e318bee3bd4c9e15e5e12a9f --- /dev/null +++ b/changelogs/unreleased/59587-add-graphql-logging.yml @@ -0,0 +1,5 @@ +--- +title: Add dedicated logging for GraphQL queries +merge_request: 27885 +author: +type: other diff --git a/doc/administration/logs.md b/doc/administration/logs.md index a7e57e44e86a116056dc72c3255c4f7070d456cd..ac41f9177ddeb98cce56f16eeeff1e192eaa3422 100644 --- a/doc/administration/logs.md +++ b/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 diff --git a/lib/gitlab/graphql/query_analyzers/log_query_complexity.rb b/lib/gitlab/graphql/query_analyzers/log_query_complexity.rb deleted file mode 100644 index 95db130dbfc68abb6d652de44ce9a859334d5f57..0000000000000000000000000000000000000000 --- a/lib/gitlab/graphql/query_analyzers/log_query_complexity.rb +++ /dev/null @@ -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 - Rails.logger.info("[GraphQL Query Complexity] #{complexity} | admin? #{query.context[:current_user]&.admin?}") - end - end - end - end - end - end -end diff --git a/lib/gitlab/graphql/query_analyzers/logger_analyzer.rb b/lib/gitlab/graphql/query_analyzers/logger_analyzer.rb new file mode 100644 index 0000000000000000000000000000000000000000..01b55a1667f5da239bf7c709a7e2a5492932ea20 --- /dev/null +++ b/lib/gitlab/graphql/query_analyzers/logger_analyzer.rb @@ -0,0 +1,71 @@ +# 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 diff --git a/lib/gitlab/graphql_logger.rb b/lib/gitlab/graphql_logger.rb new file mode 100644 index 0000000000000000000000000000000000000000..43d917908b6a6b3bd5cd8d29c1b9cf442ef3a4bd --- /dev/null +++ b/lib/gitlab/graphql_logger.rb @@ -0,0 +1,9 @@ +# frozen_string_literal: true + +module Gitlab + class GraphqlLogger < Gitlab::JsonLogger + def self.file_name_noext + 'graphql_json' + end + end +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 new file mode 100644 index 0000000000000000000000000000000000000000..66033736e01ba1b38e69c119651e2161f01ae36c --- /dev/null +++ b/spec/lib/gitlab/graphql/query_analyzers/logger_analyzer_spec.rb @@ -0,0 +1,25 @@ +# 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 diff --git a/spec/lib/gitlab/graphql_logger_spec.rb b/spec/lib/gitlab/graphql_logger_spec.rb new file mode 100644 index 0000000000000000000000000000000000000000..4977f98b83e8806454674fe8a5b21612564d6ada --- /dev/null +++ b/spec/lib/gitlab/graphql_logger_spec.rb @@ -0,0 +1,40 @@ +# 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 diff --git a/spec/requests/api/graphql/gitlab_schema_spec.rb b/spec/requests/api/graphql/gitlab_schema_spec.rb index 9beea2e259404311cc7d89b0b74adb2cf00effc1..b6ca924639984e58d4da334d1ddfb2b3ca94478f 100644 --- a/spec/requests/api/graphql/gitlab_schema_spec.rb +++ b/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 diff --git a/spec/requests/api/graphql_spec.rb b/spec/requests/api/graphql_spec.rb index cca87c16f27c79eb25f41a424691bd585fce3a34..656d6f8b50b0ff839eaa93e28a05299b74b2f508 100644 --- a/spec/requests/api/graphql_spec.rb +++ b/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")