(PDK-465) Improve output from spec_prep/spec_clean failures

lib/pdk/tests/unit.rb

@@ -8,8 +8,24 @@ module Test
     class Unit
       def self.cmd(_tests, opts = {})
         # TODO: test selection
-        rake_task = opts.key?(:parallel) ? 'parallel_spec' : 'spec'
-        [File.join(PDK::Util.module_root, 'bin', 'rake'), rake_task]
+        opts.key?(:parallel) ? 'parallel_spec' : 'spec'
+      end
+
+      def self.rake_bin
+        @rake ||= File.join(PDK::Util.module_root, 'bin', 'rake')
+      end
+
+      def self.rake(task, spinner_text, environment = {})
+        argv = [rake_bin, task]
+        argv.unshift('ruby') if Gem.win_platform?
+
+        command = PDK::CLI::Exec::Command.new(*argv).tap do |c|
+          c.context = :module
+          c.add_spinner(spinner_text)
+          c.environment = environment
+        end
+
+        command.execute!
       end
 
       def self.parallel_with_no_tests?(ran_in_parallel, json_result, result)
@@ -18,25 +34,41 @@ def self.parallel_with_no_tests?(ran_in_parallel, json_result, result)
           result[:stderr].strip =~ %r{Pass files or folders to run$}
       end
 
-      def self.invoke(report, options = {})
-        PDK::Util::Bundler.ensure_bundle!
-        PDK::Util::Bundler.ensure_binstubs!('rake')
+      def self.print_failure(result, exception)
+        $stderr.puts ''
+        result[:stdout].each_line { |line| $stderr.puts line.rstrip } unless result[:stdout].nil?
+        result[:stderr].each_line { |line| $stderr.puts line.rstrip } unless result[:stderr].nil?
+        $stderr.puts ''
+        raise PDK::CLI::FatalError, exception
+      end
 
-        tests = options.fetch(:tests)
+      def self.tear_down
+        result = rake('spec_clean', _('Cleaning up after running unit tests.'))
 
-        cmd_argv = cmd(tests, options)
-        cmd_argv.unshift('ruby') if Gem.win_platform?
+        return if result[:exit_code].zero?
 
-        command = PDK::CLI::Exec::Command.new(*cmd_argv).tap do |c|
-          c.context = :module
-          spinner_msg = options.key?(:parallel) ? _('Running unit tests in parallel.') : _('Running unit tests.')
-          c.add_spinner(spinner_msg)
-          c.environment['CI_SPEC_OPTIONS'] = '--format j'
-        end
+        PDK.logger.error(_('The spec_clean rake task failed with the following error(s):'))
+        print_failure(result, _('Failed to clean up after running unit tests'))
+      end
+
+      def self.setup
+        result = rake('spec_prep', _('Preparing to run the unit tests.'))
+
+        return if result[:exit_code].zero?
+
+        PDK.logger.error(_('The spec_prep rake task failed with the following error(s):'))
+        print_failure(result, _('Failed to prepare to run the unit tests.'))
+      end
+
+      def self.invoke(report, options = {})
+        PDK::Util::Bundler.ensure_bundle!
+        PDK::Util::Bundler.ensure_binstubs!('rake')
 
-        PDK.logger.debug(_('Running %{cmd}') % { cmd: command.argv.join(' ') })
+        setup
 
-        result = command.execute!
+        tests = options.fetch(:tests)
+        spinner_msg = options.key?(:parallel) ? _('Running unit tests in parallel.') : _('Running unit tests.')
+        result = rake(cmd(tests, options), spinner_msg, 'CI_SPEC_OPTIONS' => '--format j')
 
         json_result = if options.key?(:parallel)
                         PDK::Util.find_all_json_in(result[:stdout])
@@ -56,6 +88,8 @@ def self.invoke(report, options = {})
         parse_output(report, json_result)
 
         result[:exit_code]
+      ensure
+        tear_down
       end
 
       def self.parse_output(report, json_data)

spec/acceptance/test_unit_spec.rb

@@ -12,16 +12,20 @@
 
     describe command('pdk test unit') do
       its(:exit_status) { is_expected.to eq(0) }
+      its(:stderr) { is_expected.to match(%r{preparing to run the unit tests}i) }
       its(:stderr) { is_expected.to match(%r{running unit tests}i) }
       its(:stderr) { is_expected.to match(%r{no examples found}i) }
       its(:stderr) { is_expected.to match(%r{evaluated 0 tests}i) }
+      its(:stderr) { is_expected.to match(%r{cleaning up after running unit tests}i) }
     end
 
     describe command('pdk test unit --parallel') do
       its(:exit_status) { is_expected.to eq(0) }
+      its(:stderr) { is_expected.to match(%r{preparing to run the unit tests}i) }
       its(:stderr) { is_expected.to match(%r{running unit tests in parallel}i) }
       its(:stderr) { is_expected.to match(%r{no examples found}i) }
       its(:stderr) { is_expected.to match(%r{evaluated 0 tests}i) }
+      its(:stderr) { is_expected.to match(%r{cleaning up after running unit tests}i) }
     end
   end
 
@@ -57,12 +61,16 @@
 
     describe command('pdk test unit') do
       its(:exit_status) { is_expected.to eq(0) }
+      its(:stderr) { is_expected.to match(%r{preparing to run the unit tests}i) }
       its(:stderr) { is_expected.to match(%r{running unit tests.*5 tests.*0 failures}im) }
+      its(:stderr) { is_expected.to match(%r{cleaning up after running unit tests}i) }
     end
 
     describe command('pdk test unit --parallel') do
       its(:exit_status) { is_expected.to eq(0) }
+      its(:stderr) { is_expected.to match(%r{preparing to run the unit tests}i) }
       its(:stderr) { is_expected.to match(%r{running unit tests in parallel.*5 tests.*0 failures}im) }
+      its(:stderr) { is_expected.to match(%r{cleaning up after running unit tests}i) }
     end
   end
 
@@ -199,4 +207,24 @@
       its(:stderr) { is_expected.to match(%r{running unit tests in parallel.*10 tests.*0 failures}im) }
     end
   end
+
+  context 'when there is a problem setting up the fixtures' do
+    include_context 'in a new module', 'bad_fixtures'
+
+    before(:all) do
+      File.open('.fixtures.yml', 'w') do |f|
+        f.puts 'fixtures:'
+        f.puts '  repositories:'
+        f.puts '    "not_exist": "https://localhost/this/does/not/exist"'
+      end
+    end
+
+    describe command('pdk test unit') do
+      its(:exit_status) { is_expected.not_to eq(0) }
+      its(:stderr) { is_expected.to match(%r{preparing to run the unit tests}i) }
+      its(:stderr) { is_expected.to match(%r{Failed to clone git repository https://localhost/this/does/not/exist}) }
+      its(:stderr) { is_expected.not_to match(%r{Running unit tests\.}) }
+      its(:stderr) { is_expected.to match(%r{cleaning up after running unit tests}i) }
+    end
+  end
 end

spec/unit/pdk/test/unit_spec.rb

@@ -6,6 +6,16 @@
     expect(described_class.methods(false)).to include(:invoke)
   end
 
+  describe '.rake_bin' do
+    subject { described_class.rake_bin }
+
+    before(:each) do
+      allow(PDK::Util).to receive(:module_root).and_return('/path/to/module')
+    end
+
+    it { is_expected.to eq(File.join('/path/to/module', 'bin', 'rake')) }
+  end
+
   describe '.parallel_with_no_tests?' do
     context 'when not parallel' do
       it 'is false' do
@@ -19,6 +29,70 @@
     end
   end
 
+  describe '.setup' do
+    before(:each) do
+      mock_result = { stdout: 'some output', stderr: 'some error', exit_code: exit_code }
+      allow(described_class).to receive(:rake).with('spec_prep', any_args).and_return(mock_result)
+    end
+
+    context 'when the rake task succeeds' do
+      let(:exit_code) { 0 }
+
+      it 'does not raise an error' do
+        expect {
+          described_class.setup
+        }.not_to raise_error
+      end
+    end
+
+    context 'when the rake task fails' do
+      let(:exit_code) { 1 }
+
+      it 'prints the output of the command to STDERR and raises a FatalError' do
+        expect($stderr).to receive(:puts).with('').twice
+        expect($stderr).to receive(:puts).with('some output')
+        expect($stderr).to receive(:puts).with('some error')
+        expect(logger).to receive(:error).with(a_string_matching(%r{spec_prep rake task failed}))
+
+        expect {
+          described_class.setup
+        }.to raise_error(PDK::CLI::FatalError, %r{failed to prepare to run the unit tests}i)
+      end
+    end
+  end
+
+  describe '.tear_down' do
+    before(:each) do
+      mock_result = { stdout: 'some output', stderr: 'some error', exit_code: exit_code }
+      allow(described_class).to receive(:rake).with('spec_clean', any_args).and_return(mock_result)
+    end
+
+    context 'when the rake task succeeds' do
+      let(:exit_code) { 0 }
+
+      it 'does not raise an error' do
+        expect {
+          described_class.tear_down
+        }.not_to raise_error
+      end
+    end
+
+    context 'when the rake task fails' do
+      let(:exit_code) { 1 }
+
+      it 'prints the output of the command to STDERR and raises a FatalError' do
+        expect($stderr).to receive(:puts).with('').twice
+        expect($stderr).to receive(:puts).with('some output')
+        expect($stderr).to receive(:puts).with('some error')
+        expect(logger).to receive(:error).with(a_string_matching(%r{spec_clean rake task failed}))
+
+        expect {
+          described_class.tear_down
+        }.to raise_error(PDK::CLI::FatalError, %r{failed to clean up after running unit tests}i)
+      end
+    end
+  end
+
   describe '.merge_json_results' do
     let(:duration) { 55 }
     let(:results) do
@@ -68,15 +142,15 @@
       it 'uses the parallel_spec rake task' do
         cmd = described_class.cmd(nil, parallel: true)
 
-        expect(cmd.join('/')).to match(%r{bin/rake/parallel_spec})
+        expect(cmd).to eq('parallel_spec')
       end
     end
 
     context 'when run without the parallel option' do
       it 'uses the spec rake task' do
         cmd = described_class.cmd(nil)
 
-        expect(cmd.join('/')).to match(%r{bin/rake/spec})
+        expect(cmd).to eq('spec')
       end
     end
   end
@@ -171,6 +245,8 @@
       allow(PDK::Util::Bundler).to receive(:ensure_bundle!)
       allow(PDK::Util::Bundler).to receive(:ensure_binstubs!)
       allow(PDK::Util).to receive(:module_root).and_return('/path/to/module')
+      allow(described_class).to receive(:setup)
+      allow(described_class).to receive(:tear_down)
       allow_any_instance_of(PDK::CLI::Exec::Command).to receive(:execute!).and_return(stdout: rspec_json_output, exit_code: -1)
       allow(described_class).to receive(:parse_output)
     end