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

@@ -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!

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}>"

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

qa/qa/runtime/env.rb

+# 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

qa/qa/runtime/logger.rb

+# 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

qa/qa/support/page/logging.rb

+# 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

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\.\-]+/)

qa/spec/page/logging_spec.rb

+# 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

qa/spec/runtime/env_spec.rb

+# 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

qa/spec/runtime/logger_spec.rb

+# 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

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