diff options
-rw-r--r-- | changelogs/unreleased/59587-add-graphql-logging.yml | 5 | ||||
-rw-r--r-- | lib/gitlab/graphql/query_analyzers/logger_analyzer.rb | 28 | ||||
-rw-r--r-- | spec/lib/gitlab/graphql/query_analyzers/logger_analyzer_spec.rb | 25 | ||||
-rw-r--r-- | spec/lib/gitlab/graphql_logger_spec.rb | 22 | ||||
-rw-r--r-- | spec/requests/api/graphql/gitlab_schema_spec.rb | 16 | ||||
-rw-r--r-- | spec/requests/api/graphql_spec.rb | 6 |
6 files changed, 51 insertions, 51 deletions
diff --git a/changelogs/unreleased/59587-add-graphql-logging.yml b/changelogs/unreleased/59587-add-graphql-logging.yml new file mode 100644 index 00000000000..43c65ca0a56 --- /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: Charlie Ablett +type: other diff --git a/lib/gitlab/graphql/query_analyzers/logger_analyzer.rb b/lib/gitlab/graphql/query_analyzers/logger_analyzer.rb index e229e66849b..1e49c894ecb 100644 --- a/lib/gitlab/graphql/query_analyzers/logger_analyzer.rb +++ b/lib/gitlab/graphql/query_analyzers/logger_analyzer.rb @@ -4,35 +4,27 @@ module Gitlab module Graphql module QueryAnalyzers class LoggerAnalyzer - # Called before initializing the analyzer. - # Returns true to run this analyzer, or false to skip it. def analyze?(query) Feature.enabled?(:graphql_logging, default_enabled: true) end - # Called before the visit. - # Returns the initial value for `memo` 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, variables: process_variables(query.provided_variables), - complexity: nil, - depth: nil, + complexity: complexity, + depth: depth, duration: nil } 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 = set_complexity(memo) - set_depth(memo) + 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" GraphqlLogger.info(memo.except!(:time_started)) @@ -49,18 +41,16 @@ module Gitlab end end - def set_complexity(memo) + def complexity_analyzer GraphQL::Analysis::QueryComplexity.new do |query, complexity_value| - memo[:complexity] = complexity_value + complexity_value end - memo end - def set_depth(memo) + def depth_analyzer GraphQL::Analysis::QueryDepth.new do |query, depth_value| - memo[:depth] = depth_value + depth_value end - memo end def duration(time_started) 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 a975af1cda2..4491c1cfa65 100644 --- a/spec/lib/gitlab/graphql/query_analyzers/logger_analyzer_spec.rb +++ b/spec/lib/gitlab/graphql/query_analyzers/logger_analyzer_spec.rb @@ -38,29 +38,4 @@ describe Gitlab::Graphql::QueryAnalyzers::LoggerAnalyzer do end end end - - describe '#initial_value' do - it 'assembles a hash with initial values' do - query = OpenStruct.new(query_string: query_string, provided_variables: provided_variables) - - expect(subject.initial_value(query)).to eq initial_values - end - end - - describe '#call' do - before do - # some statements to fudge the complexity and depth - end - - it 'sets the complexity and depth' do - expected_hash = { time_started: now, - query_string: query_string, - variables: provided_variables, - complexity: nil, - depth: depth, - duration: complexity } - - expect(subject.call(initial_values, nil, nil)).to eq expected_hash - end - end end diff --git a/spec/lib/gitlab/graphql_logger_spec.rb b/spec/lib/gitlab/graphql_logger_spec.rb index aeeed0b2ca1..4157bb86f1c 100644 --- a/spec/lib/gitlab/graphql_logger_spec.rb +++ b/spec/lib/gitlab/graphql_logger_spec.rb @@ -12,4 +12,26 @@ describe Gitlab::GraphqlLogger do 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: "7ms" + } + 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("7ms") + end + end end diff --git a/spec/requests/api/graphql/gitlab_schema_spec.rb b/spec/requests/api/graphql/gitlab_schema_spec.rb index dcce8c1dbad..510dec5edb2 100644 --- a/spec/requests/api/graphql/gitlab_schema_spec.rb +++ b/spec/requests/api/graphql/gitlab_schema_spec.rb @@ -84,10 +84,18 @@ describe 'GitlabSchema configurations' do end context 'logging' do - it 'writes to the GraphQL log' do - expect(Gitlab::GraphqlLogger).to receive(:info) - - query = File.read(Rails.root.join('spec/fixtures/api/graphql/introspection.graphql')) + let(:query) { File.read(Rails.root.join('spec/fixtures/api/graphql/introspection.graphql')) } + + it 'logs the query complexity' do + analyzer_memo = { + query_string: query, + variables: {}, + complexity: 181, + depth: 0, + duration: "7ms" + } + 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 diff --git a/spec/requests/api/graphql_spec.rb b/spec/requests/api/graphql_spec.rb index 036dfa41952..ebf223127b5 100644 --- a/spec/requests/api/graphql_spec.rb +++ b/spec/requests/api/graphql_spec.rb @@ -23,7 +23,7 @@ describe 'GraphQL' do context 'with no variables' do let(:expected) do - { query_string: query, variables: {}, duration: anything, depth: 0, complexity: 0 } + { query_string: query, variables: {}, duration: anything, depth: 1, complexity: 1 } end it 'logs the query' do @@ -33,10 +33,10 @@ describe 'GraphQL' do context 'with variables' do let!(:variables) do - { foo: "bar" } + { "foo" => "bar" } end let(:expected) do - { query_string: query, variables: variables, duration: anything, depth: 0, complexity: 0 } + { query_string: query, variables: variables, duration: anything, depth: 1, complexity: 1 } end it 'logs the query' do |