From 699532232ca27e6079c553261e0ab1d17317472a Mon Sep 17 00:00:00 2001 From: charlie ablett Date: Thu, 23 May 2019 22:43:47 +0000 Subject: [PATCH] Apply reviewer feedback - Comply doc with guidelines - Improve tests for readability and completeness - Separate out phases visually with newlines - Add `format_message` test - test readability - code and test structure/styling - static query analyzers - call `as_json` on `provided_variables` - add exception handling --- .../unreleased/59587-add-graphql-logging.yml | 2 +- doc/administration/logs.md | 7 +-- .../query_analyzers/logger_analyzer.rb | 48 +++++++++++-------- .../query_analyzers/logger_analyzer_spec.rb | 10 +--- spec/lib/gitlab/graphql_logger_spec.rb | 15 +++--- .../api/graphql/gitlab_schema_spec.rb | 43 ++++++++++------- spec/requests/api/graphql_spec.rb | 26 ++++++++-- 7 files changed, 89 insertions(+), 62 deletions(-) diff --git a/changelogs/unreleased/59587-add-graphql-logging.yml b/changelogs/unreleased/59587-add-graphql-logging.yml index 43c65ca0a56..74c2a734f37 100644 --- a/changelogs/unreleased/59587-add-graphql-logging.yml +++ b/changelogs/unreleased/59587-add-graphql-logging.yml @@ -1,5 +1,5 @@ --- title: Add dedicated logging for GraphQL queries merge_request: 27885 -author: Charlie Ablett +author: type: other diff --git a/doc/administration/logs.md b/doc/administration/logs.md index 87460eb6fd2..ac41f9177dd 100644 --- a/doc/administration/logs.md +++ b/doc/administration/logs.md @@ -290,15 +290,16 @@ It logs information whenever [Rack Attack] registers an abusive request. ## `graphql_json.log` -Introduced in Gitlab 12.0. +> [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 here. For example: +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":"7ms"} +{"query_string":"query IntrospectionQuery{__schema {queryType { name },mutationType { name }}}...(etc)","variables":{"a":1,"b":2},"complexity":181,"depth":1,"duration":7} ``` ## Reconfigure Logs diff --git a/lib/gitlab/graphql/query_analyzers/logger_analyzer.rb b/lib/gitlab/graphql/query_analyzers/logger_analyzer.rb index 8119d232124..01b55a1667f 100644 --- a/lib/gitlab/graphql/query_analyzers/logger_analyzer.rb +++ b/lib/gitlab/graphql/query_analyzers/logger_analyzer.rb @@ -4,18 +4,22 @@ 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) - { - time_started: Gitlab::Metrics::System.monotonic_time, + variables = process_variables(query.provided_variables) + default_initial_values(query).merge({ query_string: query.query_string, - query: query, - variables: process_variables(query.provided_variables), - duration: nil - } + variables: variables + }) + rescue => e + Gitlab::Sentry.track_exception(e) + default_initial_values(query) end def call(memo, visit_type, irep_node) @@ -23,7 +27,9 @@ module Gitlab end def final_value(memo) - analyzers = [complexity_analyzer, depth_analyzer] + return if memo.nil? + + analyzers = [COMPLEXITY_ANALYZER, DEPTH_ANALYZER] complexity, depth = GraphQL::Analysis.analyze_query(memo[:query], analyzers) memo[:depth] = depth @@ -31,34 +37,34 @@ module Gitlab 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_json) - variables.to_json + if variables.respond_to?(:to_s) + variables.to_s else variables end end - def complexity_analyzer - GraphQL::Analysis::QueryComplexity.new do |query, complexity_value| - complexity_value - end - end - - def depth_analyzer - GraphQL::Analysis::QueryDepth.new do |query, depth_value| - depth_value - 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 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 cbf35c1095a..66033736e01 100644 --- a/spec/lib/gitlab/graphql/query_analyzers/logger_analyzer_spec.rb +++ b/spec/lib/gitlab/graphql/query_analyzers/logger_analyzer_spec.rb @@ -5,25 +5,19 @@ require 'spec_helper' describe Gitlab::Graphql::QueryAnalyzers::LoggerAnalyzer do subject { described_class.new } - let!(:now) { Gitlab::Metrics::System.monotonic_time } - - before do - allow(Gitlab::Metrics::System).to receive(:monotonic_time).and_return(now) - end - describe '#analyze?' do context 'feature flag disabled' do before do stub_feature_flags(graphql_logging: false) end - it 'enables the analyzer' do + it 'disables the analyzer' do expect(subject.analyze?(anything)).to be_falsey end end context 'feature flag enabled by default' do - specify do + it 'enables the analyzer' do expect(subject.analyze?(anything)).to be_truthy end end diff --git a/spec/lib/gitlab/graphql_logger_spec.rb b/spec/lib/gitlab/graphql_logger_spec.rb index c8d4dac2153..4977f98b83e 100644 --- a/spec/lib/gitlab/graphql_logger_spec.rb +++ b/spec/lib/gitlab/graphql_logger_spec.rb @@ -19,15 +19,16 @@ describe Gitlab::GraphqlLogger do it 'logs a query from JSON' do analyzer_memo = { - query_string: query, - variables: {}, - complexity: 181, - depth: 0, - duration: 7 + query_string: query, + variables: {}, + complexity: 181, + depth: 0, + duration: 7 } - output = subject.format_message('INFO', now, 'test', analyzer_memo) - data = JSON.parse(output) + 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) diff --git a/spec/requests/api/graphql/gitlab_schema_spec.rb b/spec/requests/api/graphql/gitlab_schema_spec.rb index 510dec5edb2..1017e409f6c 100644 --- a/spec/requests/api/graphql/gitlab_schema_spec.rb +++ b/spec/requests/api/graphql/gitlab_schema_spec.rb @@ -83,24 +83,6 @@ describe 'GitlabSchema configurations' do end end - context 'logging' do - 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 - end - context 'when IntrospectionQuery' do it 'is not too complex' do query = File.read(Rails.root.join('spec/fixtures/api/graphql/introspection.graphql')) @@ -110,4 +92,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 abc24fc0fe8..656d6f8b50b 100644 --- a/spec/requests/api/graphql_spec.rb +++ b/spec/requests/api/graphql_spec.rb @@ -19,16 +19,21 @@ describe 'GraphQL' do 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 } + { 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 - end - before do - expect(Gitlab::GraphqlLogger).to receive(:info).with(expected_params).once + 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 @@ -44,6 +49,19 @@ describe 'GraphQL' do 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