Log page actionsml-qa-logging

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.

11 files changed, 287 insertions, 13 deletions

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