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.

5 files changed, 145 insertions, 10 deletions

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