From 1f37aed1c917260eefda63a18d3a9af91c4a1abb Mon Sep 17 00:00:00 2001 From: charlieablett Date: Tue, 30 Apr 2019 20:30:15 +1200 Subject: New logfile for graphql queries Specify dedicated logfile and logger class for GraphQL queries. Move complexity analyzer to a dedicated class. --- spec/lib/gitlab/graphql_logger_spec.rb | 21 +++++++++++++++++++++ 1 file changed, 21 insertions(+) create mode 100644 spec/lib/gitlab/graphql_logger_spec.rb (limited to 'spec/lib') diff --git a/spec/lib/gitlab/graphql_logger_spec.rb b/spec/lib/gitlab/graphql_logger_spec.rb new file mode 100644 index 00000000000..51c77181927 --- /dev/null +++ b/spec/lib/gitlab/graphql_logger_spec.rb @@ -0,0 +1,21 @@ +require 'spec_helper' + +describe Gitlab::GraphqlLogger, :request_store 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 + + describe '#format_message' do + it 'formats properly' do + output = subject.format_message('INFO', now, 'test', 'Hello world') + + expect(output).to match(/Hello world/) + end + end +end -- cgit v1.2.3 From 2c011cb5b452409db7fe1c810f1ad7440a6cedce Mon Sep 17 00:00:00 2001 From: charlieablett Date: Thu, 2 May 2019 12:16:49 +1200 Subject: Implement logger analyzer - Modify GraphqlLogger to subclass JsonLogger - Replace the single-line analyser with one that can log all the GraphQL query related information in one place. - Implement analyzer behavior with spec --- .../query_analyzers/logger_analyzer_spec.rb | 27 ++++++++++++++++++++++ spec/lib/gitlab/graphql_logger_spec.rb | 12 +++------- 2 files changed, 30 insertions(+), 9 deletions(-) create mode 100644 spec/lib/gitlab/graphql/query_analyzers/logger_analyzer_spec.rb (limited to 'spec/lib') 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 00000000000..53a1d7f8e42 --- /dev/null +++ b/spec/lib/gitlab/graphql/query_analyzers/logger_analyzer_spec.rb @@ -0,0 +1,27 @@ +# frozen_string_literal: true + +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(:complexity) { 4 } + let(:depth) { 2 } + let(:expected_hash) do + { query_string: query_string, + variables: provided_variables, + complexity: complexity, + depth: depth } + end + + it 'assembles a hash' do + query = OpenStruct.new(query_string: query_string, provided_variables: provided_variables) + + subject.initial_value(query) + + expect(subject.instance_variable_get("@info_hash")).to eq expected_hash + end + +end diff --git a/spec/lib/gitlab/graphql_logger_spec.rb b/spec/lib/gitlab/graphql_logger_spec.rb index 51c77181927..aeeed0b2ca1 100644 --- a/spec/lib/gitlab/graphql_logger_spec.rb +++ b/spec/lib/gitlab/graphql_logger_spec.rb @@ -1,6 +1,8 @@ +# frozen_string_literal: true + require 'spec_helper' -describe Gitlab::GraphqlLogger, :request_store do +describe Gitlab::GraphqlLogger do subject { described_class.new('/dev/null') } let(:now) { Time.now } @@ -10,12 +12,4 @@ describe Gitlab::GraphqlLogger, :request_store do subject.info('hello world') subject.error('hello again') end - - describe '#format_message' do - it 'formats properly' do - output = subject.format_message('INFO', now, 'test', 'Hello world') - - expect(output).to match(/Hello world/) - end - end end -- cgit v1.2.3 From 2a1006416748950805294793f1bc8d6fa7435eea Mon Sep 17 00:00:00 2001 From: charlieablett Date: Thu, 2 May 2019 19:09:10 +1200 Subject: Restructure complexity analyzer Remove instance variables for class re-use, test individual methods, use `monotonic_time` --- .../query_analyzers/logger_analyzer_spec.rb | 40 +++++++++++++++++----- 1 file changed, 31 insertions(+), 9 deletions(-) (limited to 'spec/lib') 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 53a1d7f8e42..f85a3a206b1 100644 --- a/spec/lib/gitlab/graphql/query_analyzers/logger_analyzer_spec.rb +++ b/spec/lib/gitlab/graphql/query_analyzers/logger_analyzer_spec.rb @@ -7,21 +7,43 @@ 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(:expected_hash) do - { query_string: query_string, + let(:initial_values) do + { time_started: now, + query_string: query_string, variables: provided_variables, - complexity: complexity, - depth: depth } + complexity: nil, + depth: nil, + duration: nil } + end + before do + allow(Gitlab::Metrics::System).to receive(:monotonic_time).and_return(now) end - it 'assembles a hash' do - query = OpenStruct.new(query_string: query_string, provided_variables: provided_variables) - - subject.initial_value(query) + 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.instance_variable_get("@info_hash")).to eq expected_hash + 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 -- cgit v1.2.3 From b94a17e00efc89187aefd24d388e36584cd11784 Mon Sep 17 00:00:00 2001 From: charlieablett Date: Tue, 21 May 2019 10:30:11 +1200 Subject: Add GraphQL logging feature flag --- .../graphql/query_analyzers/logger_analyzer_spec.rb | 19 ++++++++++++++++++- 1 file changed, 18 insertions(+), 1 deletion(-) (limited to 'spec/lib') 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 f85a3a206b1..a975af1cda2 100644 --- a/spec/lib/gitlab/graphql/query_analyzers/logger_analyzer_spec.rb +++ b/spec/lib/gitlab/graphql/query_analyzers/logger_analyzer_spec.rb @@ -3,7 +3,6 @@ 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 } } @@ -22,6 +21,24 @@ describe Gitlab::Graphql::QueryAnalyzers::LoggerAnalyzer 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 + + specify do + expect(subject.analyze?(anything)).to be_falsey + end + end + + context 'feature flag enabled by default' do + specify do + expect(subject.analyze?(anything)).to be_truthy + 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) -- cgit v1.2.3 From 184a5120dc764d33cece108fbc85b0ec96f7c050 Mon Sep 17 00:00:00 2001 From: charlieablett Date: Wed, 22 May 2019 17:13:06 +1200 Subject: Call analyzers from LoggerAnalyzer - Add changelog file - Fix failing tests --- .../query_analyzers/logger_analyzer_spec.rb | 25 ---------------------- spec/lib/gitlab/graphql_logger_spec.rb | 22 +++++++++++++++++++ 2 files changed, 22 insertions(+), 25 deletions(-) (limited to 'spec/lib') 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 -- cgit v1.2.3 From 5f0c230a18b677bd4ec6a4a54085775b0c69a498 Mon Sep 17 00:00:00 2001 From: charlieablett Date: Fri, 24 May 2019 09:29:19 +1200 Subject: 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 --- .../graphql/query_analyzers/logger_analyzer_spec.rb | 16 +++------------- spec/lib/gitlab/graphql_logger_spec.rb | 6 ++++-- 2 files changed, 7 insertions(+), 15 deletions(-) (limited to 'spec/lib') 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 -- cgit v1.2.3 From 699532232ca27e6079c553261e0ab1d17317472a Mon Sep 17 00:00:00 2001 From: charlie ablett Date: Thu, 23 May 2019 22:43:47 +0000 Subject: 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 --- .../gitlab/graphql/query_analyzers/logger_analyzer_spec.rb | 10 ++-------- spec/lib/gitlab/graphql_logger_spec.rb | 13 +++++++------ 2 files changed, 9 insertions(+), 14 deletions(-) (limited to 'spec/lib') 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) + 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) -- cgit v1.2.3