From 45860bc807b693d4b7bc9797c37a6337a19c63c4 Mon Sep 17 00:00:00 2001 From: Mark Lapierre Date: Tue, 2 Oct 2018 14:31:39 -0400 Subject: [PATCH] Log page actions Override page object methods to log the actions taken by the methods before or after the action, as appropriate. Allow page object action logging to be turned on via a QA_DEBUG env var. Unlike CHROME_HEADLESS (and the soon to arrive VERBOSE), QA_DEBUG is false by default. QA_DEBUG is used instead of just DEBUG because that enables Selenium debug logging. Mask passwords entered into fields with a QA selector with 'password' in the name. Doesn't mask sensitive data entered into any other field. --- qa/qa.rb | 9 +++ qa/qa/factory/base.rb | 2 +- qa/qa/page/base.rb | 1 + qa/qa/runtime/env.rb | 10 +++- qa/qa/runtime/logger.rb | 23 ++++++++ qa/qa/support/page/logging.rb | 100 +++++++++++++++++++++++++++++++++ qa/spec/factory/base_spec.rb | 12 ++-- qa/spec/page/logging_spec.rb | 88 +++++++++++++++++++++++++++++ qa/spec/runtime/env_spec.rb | 24 ++++++-- qa/spec/runtime/logger_spec.rb | 27 +++++++++ qa/spec/spec_helper.rb | 4 ++ 11 files changed, 287 insertions(+), 13 deletions(-) create mode 100644 qa/qa/runtime/logger.rb create mode 100644 qa/qa/support/page/logging.rb create mode 100644 qa/spec/page/logging_spec.rb create mode 100644 qa/spec/runtime/logger_spec.rb diff --git a/qa/qa.rb b/qa/qa.rb index 7feca22478a..36a37dbb270 100644 --- a/qa/qa.rb +++ b/qa/qa.rb @@ -18,6 +18,7 @@ module QA autoload :Address, 'qa/runtime/address' autoload :Path, 'qa/runtime/path' autoload :Fixtures, 'qa/runtime/fixtures' + autoload :Logger, 'qa/runtime/logger' module API autoload :Client, 'qa/runtime/api/client' @@ -324,6 +325,14 @@ module QA end end end + + # Classes that provide support to other parts of the framework. + # + module Support + module Page + autoload :Logging, 'qa/support/page/logging' + end + end end QA::Runtime::Release.extend_autoloads! diff --git a/qa/qa/factory/base.rb b/qa/qa/factory/base.rb index a8ecac2a1e6..e1dc23d350d 100644 --- a/qa/qa/factory/base.rb +++ b/qa/qa/factory/base.rb @@ -63,7 +63,7 @@ module QA private_class_method :do_fabricate! def self.log_fabrication(method, factory, parents, args) - return yield unless Runtime::Env.verbose? + return yield unless Runtime::Env.debug? start = Time.now prefix = "==#{'=' * parents.size}>" diff --git a/qa/qa/page/base.rb b/qa/qa/page/base.rb index 160ec58cf2c..91e229c4c8c 100644 --- a/qa/qa/page/base.rb +++ b/qa/qa/page/base.rb @@ -5,6 +5,7 @@ require 'capybara/dsl' module QA module Page class Base + prepend Support::Page::Logging if Runtime::Env.debug? include Capybara::DSL include Scenario::Actable extend SingleForwardable diff --git a/qa/qa/runtime/env.rb b/qa/qa/runtime/env.rb index 533ed87453a..c7052a9f300 100644 --- a/qa/qa/runtime/env.rb +++ b/qa/qa/runtime/env.rb @@ -1,3 +1,5 @@ +# frozen_string_literal: true + module QA module Runtime module Env @@ -5,8 +7,12 @@ module QA attr_writer :personal_access_token - def verbose? - enabled?(ENV['VERBOSE'], default: false) + def debug? + enabled?(ENV['QA_DEBUG'], default: false) + end + + def log_destination + ENV['QA_LOG_PATH'] || $stdout end # set to 'false' to have Chrome run visibly instead of headless diff --git a/qa/qa/runtime/logger.rb b/qa/qa/runtime/logger.rb new file mode 100644 index 00000000000..3baa24de0ec --- /dev/null +++ b/qa/qa/runtime/logger.rb @@ -0,0 +1,23 @@ +# frozen_string_literal: true + +require 'logger' + +module QA + module Runtime + module Logger + extend SingleForwardable + + def_delegators :logger, :debug, :info, :error, :warn, :fatal, :unknown + + singleton_class.module_eval do + def logger + return @logger if @logger + + @logger = ::Logger.new Runtime::Env.log_destination + @logger.level = ::Logger::DEBUG + @logger + end + end + end + end +end diff --git a/qa/qa/support/page/logging.rb b/qa/qa/support/page/logging.rb new file mode 100644 index 00000000000..cf5cd3a79f8 --- /dev/null +++ b/qa/qa/support/page/logging.rb @@ -0,0 +1,100 @@ +# frozen_string_literal: true + +module QA + module Support + module Page + module Logging + def refresh + log("refreshing #{current_url}") + + super + end + + def wait(max: 60, time: 0.1, reload: true) + log("with wait: max #{max}; time #{time}; reload #{reload}") + now = Time.now + + element = super + + log("ended wait after #{Time.now - now} seconds") + + element + end + + def scroll_to(selector, text: nil) + msg = "scrolling to :#{selector}" + msg += " with text: #{text}" if text + log(msg) + + super + end + + def asset_exists?(url) + exists = super + + log("asset_exists? #{url} returned #{exists}") + + exists + end + + def find_element(name) + log("finding :#{name}") + + element = super + + log("found :#{name}") if element + + element + end + + def all_elements(name) + log("finding all :#{name}") + + elements = super + + log("found #{elements.size} :#{name}") if elements + + elements + end + + def click_element(name) + log("clicking :#{name}") + + super + end + + def fill_element(name, content) + masked_content = name.to_s.include?('password') ? '*****' : content + + log(%Q(filling :#{name} with "#{masked_content}")) + + super + end + + def has_element?(name) + found = super + + log("has_element? :#{name} returned #{found}") + + found + end + + def within_element(name) + log("within element :#{name}") + + element = super + + log("end within element :#{name}") + + element + end + + private + + def log(msg) + QA::Runtime::Logger.debug(msg) + end + end + end + end +end diff --git a/qa/spec/factory/base_spec.rb b/qa/spec/factory/base_spec.rb index 184802a7903..229f93a1041 100644 --- a/qa/spec/factory/base_spec.rb +++ b/qa/spec/factory/base_spec.rb @@ -35,8 +35,8 @@ describe QA::Factory::Base do end end - it 'does not log the factory and build method when VERBOSE=false' do - stub_env('VERBOSE', 'false') + it 'does not log the factory and build method when QA_DEBUG=false' do + stub_env('QA_DEBUG', 'false') expect(factory).to receive(fabrication_method_used).and_return(product_location) expect { subject.public_send(fabrication_method_called, 'something', factory: factory) } @@ -79,8 +79,8 @@ describe QA::Factory::Base do expect(result).to eq(product) end - it 'logs the factory and build method when VERBOSE=true' do - stub_env('VERBOSE', 'true') + it 'logs the factory and build method when QA_DEBUG=true' do + stub_env('QA_DEBUG', 'true') expect(factory).to receive(:fabricate_via_api!).and_return(product_location) expect { subject.fabricate_via_api!(factory: factory, parents: []) } @@ -106,8 +106,8 @@ describe QA::Factory::Base do expect(result).to eq(product) end - it 'logs the factory and build method when VERBOSE=true' do - stub_env('VERBOSE', 'true') + it 'logs the factory and build method when QA_DEBUG=true' do + stub_env('QA_DEBUG', 'true') expect { subject.fabricate_via_browser_ui!('something', factory: factory, parents: []) } .to output(/==> Built a MyFactory via browser_ui with args \["something"\] in [\d\w\.\-]+/) diff --git a/qa/spec/page/logging_spec.rb b/qa/spec/page/logging_spec.rb new file mode 100644 index 00000000000..9f17de4edbf --- /dev/null +++ b/qa/spec/page/logging_spec.rb @@ -0,0 +1,88 @@ +# frozen_string_literal: true + +require 'capybara/dsl' + +describe QA::Support::Page::Logging do + let(:page) { double().as_null_object } + + before do + allow(Capybara).to receive(:current_session).and_return(page) + allow(page).to receive(:current_url).and_return('http://current-url') + allow(page).to receive(:has_css?).with(any_args).and_return(true) + end + + subject do + Class.new(QA::Page::Base) do + prepend QA::Support::Page::Logging + end.new + end + + it 'logs refresh' do + expect { subject.refresh } + .to output(%r{refreshing http://current-url}).to_stdout_from_any_process + end + + it 'logs wait' do + expect { subject.wait(max: 0) {} } + .to output(/with wait/).to_stdout_from_any_process + expect { subject.wait(max: 0) {} } + .to output(/ended wait after .* seconds$/).to_stdout_from_any_process + end + + it 'logs scroll_to' do + expect { subject.scroll_to(:element) } + .to output(/scrolling to :element/).to_stdout_from_any_process + end + + it 'logs asset_exists?' do + expect { subject.asset_exists?('http://asset-url') } + .to output(%r{asset_exists\? http://asset-url returned false}).to_stdout_from_any_process + end + + it 'logs find_element' do + expect { subject.find_element(:element) } + .to output(/found :element/).to_stdout_from_any_process + end + + it 'logs click_element' do + expect { subject.click_element(:element) } + .to output(/clicking :element/).to_stdout_from_any_process + end + + it 'logs fill_element' do + expect { subject.fill_element(:element, 'foo') } + .to output(/filling :element with "foo"/).to_stdout_from_any_process + end + + it 'logs has_element?' do + expect { subject.has_element?(:element) } + .to output(/has_element\? :element returned true/).to_stdout_from_any_process + end + + it 'logs within_element' do + expect { subject.within_element(:element) } + .to output(/within element :element/).to_stdout_from_any_process + expect { subject.within_element(:element) } + .to output(/end within element :element/).to_stdout_from_any_process + end + + context 'all_elements' do + it 'logs the number of elements found' do + allow(page).to receive(:all).and_return([1, 2]) + + expect { subject.all_elements(:element) } + .to output(/finding all :element/).to_stdout_from_any_process + expect { subject.all_elements(:element) } + .to output(/found 2 :element/).to_stdout_from_any_process + end + + it 'logs 0 if no elements are found' do + allow(page).to receive(:all).and_return([]) + + expect { subject.all_elements(:element) } + .to output(/finding all :element/).to_stdout_from_any_process + expect { subject.all_elements(:element) } + .not_to output(/found 0 :elements/).to_stdout_from_any_process + end + end +end diff --git a/qa/spec/runtime/env_spec.rb b/qa/spec/runtime/env_spec.rb index b5ecf1afb80..c59c415c148 100644 --- a/qa/spec/runtime/env_spec.rb +++ b/qa/spec/runtime/env_spec.rb @@ -1,3 +1,5 @@ +# frozen_string_literal: true + describe QA::Runtime::Env do include Support::StubENV @@ -34,14 +36,14 @@ describe QA::Runtime::Env do end end - describe '.verbose?' do - it_behaves_like 'boolean method', :verbose?, 'VERBOSE', false - end - describe '.signup_disabled?' do it_behaves_like 'boolean method', :signup_disabled?, 'SIGNUP_DISABLED', false end + describe '.debug?' do + it_behaves_like 'boolean method', :debug?, 'QA_DEBUG', false + end + describe '.chrome_headless?' do it_behaves_like 'boolean method', :chrome_headless?, 'CHROME_HEADLESS', true end @@ -166,4 +168,18 @@ describe QA::Runtime::Env do expect { described_class.require_github_access_token! }.not_to raise_error end end + + describe '.log_destination' do + it 'returns $stdout if QA_LOG_PATH is not defined' do + stub_env('QA_LOG_PATH', nil) + + expect(described_class.log_destination).to eq($stdout) + end + + it 'returns the path if QA_LOG_PATH is defined' do + stub_env('QA_LOG_PATH', 'path/to_file') + + expect(described_class.log_destination).to eq('path/to_file') + end + end end diff --git a/qa/spec/runtime/logger_spec.rb b/qa/spec/runtime/logger_spec.rb new file mode 100644 index 00000000000..794e1f9bfe6 --- /dev/null +++ b/qa/spec/runtime/logger_spec.rb @@ -0,0 +1,27 @@ +# frozen_string_literal: true + +describe QA::Runtime::Logger do + it 'logs debug' do + expect { described_class.debug('test') }.to output(/DEBUG -- : test/).to_stdout_from_any_process + end + + it 'logs info' do + expect { described_class.info('test') }.to output(/INFO -- : test/).to_stdout_from_any_process + end + + it 'logs warn' do + expect { described_class.warn('test') }.to output(/WARN -- : test/).to_stdout_from_any_process + end + + it 'logs error' do + expect { described_class.error('test') }.to output(/ERROR -- : test/).to_stdout_from_any_process + end + + it 'logs fatal' do + expect { described_class.fatal('test') }.to output(/FATAL -- : test/).to_stdout_from_any_process + end + + it 'logs unknown' do + expect { described_class.unknown('test') }.to output(/ANY -- : test/).to_stdout_from_any_process + end +end diff --git a/qa/spec/spec_helper.rb b/qa/spec/spec_helper.rb index 8e6613cd688..8e01da01340 100644 --- a/qa/spec/spec_helper.rb +++ b/qa/spec/spec_helper.rb @@ -3,6 +3,10 @@ require_relative '../qa' Dir[::File.join(__dir__, 'support', '**', '*.rb')].each { |f| require f } RSpec.configure do |config| + config.before do |example| + QA::Runtime::Logger.debug("Starting test: #{example.full_description}") if QA::Runtime::Env.debug? + end + config.expect_with :rspec do |expectations| expectations.include_chain_clauses_in_custom_matcher_descriptions = true end