Add log to diego stager error case (#4042)

- Without this log, the stack trace for the underlying error is lost,
  which makes debugging difficult
- Add helper for testing log output. This makes it easier to validate
  the correct information is logged, without having to manually test.

Author: Gerg

lib/cloud_controller/diego/stager.rb

@@ -33,6 +33,11 @@ def send_stage_package_request(staging_details)
       rescue CloudController::Errors::ApiError => e
         raise e
       rescue StandardError => e
+        logger.error('stage.package.error',
+                     package_guid: staging_details.package.guid,
+                     staging_guid: staging_details.staging_guid,
+                     error: e,
+                     backtrace: e.backtrace)
         raise CloudController::Errors::ApiError.new_from_details('StagerError', e)
       end
 

spec/spec_helper.rb

@@ -110,6 +110,7 @@
     rspec_config.include TimeHelpers
     rspec_config.include LinkHelpers
     rspec_config.include BackgroundJobHelpers
+    rspec_config.include LogHelpers
 
     rspec_config.include ServiceBrokerHelpers
     rspec_config.include UserHelpers

spec/support/log_helpers.rb

@@ -0,0 +1,30 @@
+module LogHelpers
+  class TailedLogs
+    def initialize(io_log)
+      @io_log = io_log
+    end
+
+    def read
+      @io_log.string.split("\n").map { |l| Oj.load(l) }
+    end
+  end
+
+  def tail_logs(&block)
+    steno_config_backup = ::Steno.config
+
+    begin
+      io_log = ::StringIO.new
+      io_sink = ::Steno::Sink::IO.new(io_log, codec: ::Steno::Codec::JsonRFC3339.new)
+      ::Steno.init(::Steno::Config.new(
+                     sinks: steno_config_backup.sinks + [io_sink],
+                     codec: steno_config_backup.codec,
+                     context: steno_config_backup.context,
+                     default_log_level: 'all'
+                   ))
+
+      block.yield(TailedLogs.new(io_log))
+    ensure
+      ::Steno.init(steno_config_backup)
+    end
+  end
+end

spec/unit/lib/cloud_controller/diego/stager_spec.rb

@@ -64,20 +64,62 @@ module Diego
         end
 
         context 'when the stage fails' do
-          let(:error) do
-            { error: { id: 'StagingError', message: 'Stager error: staging failed' } }
+          describe 'with an APIError' do
+            let(:error) do
+              { error: { id: 'StagingError', message: 'Stager error: staging failed' } }
+            end
+
+            before do
+              allow(messenger).to receive(:send_stage_request).and_raise(CloudController::Errors::ApiError.new_from_details('StagerError', 'staging failed'))
+            end
+
+            it 'calls the completion handler with the error' do
+              expect do
+                stager.stage(staging_details)
+              end.to raise_error(CloudController::Errors::ApiError)
+              package.reload
+              expect(buildpack_completion_handler).to have_received(:staging_complete).with(error, false)
+            end
           end
 
-          before do
-            allow(messenger).to receive(:send_stage_request).and_raise(CloudController::Errors::ApiError.new_from_details('StagerError', 'staging failed'))
-          end
-
-          it 'calls the completion handler with the error' do
-            expect do
-              stager.stage(staging_details)
-            end.to raise_error(CloudController::Errors::ApiError)
-            package.reload
-            expect(buildpack_completion_handler).to have_received(:staging_complete).with(error, false)
+          describe 'with any other error' do
+            let(:error) do
+              { error: { id: 'StagingError', message: 'Stager error: something is very wrong' } }
+            end
+
+            before do
+              allow(messenger).to receive(:send_stage_request).and_raise(StandardError.new('something is very wrong'))
+            end
+
+            it 'calls the completion handler with the error' do
+              expect do
+                stager.stage(staging_details)
+              end.to raise_error(CloudController::Errors::ApiError)
+              package.reload
+              expect(buildpack_completion_handler).to have_received(:staging_complete).with(error, false)
+            end
+
+            it 'logs the original error, with a stack trace' do
+              tail_logs do |logs|
+                expect do
+                  stager.stage(staging_details)
+                end.to raise_error(CloudController::Errors::ApiError)
+
+                expect(
+                  logs.read.find { |l| l['message'] == 'stage.package.error' }
+                ).to match(
+                  hash_including(
+                    'message' => 'stage.package.error',
+                    'data' => {
+                      'package_guid' => package.guid,
+                      'staging_guid' => build.guid,
+                      'error' => 'something is very wrong',
+                      'backtrace' => array_including(/and_raise/)
+                    }
+                  )
+                )
+              end
+            end
           end
         end
       end