[SDK-811] Log the internal error's class and message (#1030)

lib/rollbar/notifier.rb

@@ -542,9 +542,8 @@ def report_internal_error(exception, original_error = nil)
       return if skip_reporting_internal_error(exception)
 
       failsafe_message = ''
-      log_error(
-        '[Rollbar] Reporting internal error encountered while sending data to Rollbar.'
-      )
+      log_error('[Rollbar] Reporting internal error encountered while sending data to ' \
+                "Rollbar: #{internal_error_details(exception, original_error)}")
 
       configuration.execute_hook(:on_report_internal_error, exception)
 
@@ -561,6 +560,28 @@ def report_internal_error(exception, original_error = nil)
       log_error(item ? "[Rollbar] Item: #{item}" : "[Rollbar] Exception: #{exception}")
     end
 
+    # Describes the internal error, and the error that was being reported when it
+    # happened, so the log line is useful on its own.
+    def internal_error_details(exception, original_error)
+      details = describe_exception(exception)
+      original_exception = original_error && original_error[:exception]
+      if original_exception
+        details += " (while reporting #{describe_exception(original_exception)})"
+      end
+
+      details
+    end
+
+    # Falls back to the class name for each exception separately, so a broken
+    # #message on one of them doesn't drop the description of the other.
+    # SystemStackError is rescued too: report_with_rescue catches it while building
+    # the payload, and calling the same #message again here would raise it again.
+    def describe_exception(exception)
+      exception_info(exception)
+    rescue StandardError, SystemStackError
+      exception.class.name.to_s
+    end
+
     def skip_reporting_internal_error(exception)
       return true if configuration.ignore_internal_errors == true
 
@@ -831,21 +852,23 @@ def failsafe_reason(message, exception)
     end
 
     def failsafe_exception_reason(message, exception)
+      "#{exception_info(exception)}: #{message}"
+    rescue StandardError
+      log_error('[Rollbar] Error building failsafe exception message')
+      ''
+    end
+
+    def exception_info(exception)
       backtrace = exception.backtrace || []
       nearest_frame = backtrace[0]
 
-      exception_info = exception.class.name
+      info = exception.class.name
       # #to_s and #message defaults to class.to_s.
       # Add message only if add valuable info.
-      if exception.message != exception.class.to_s
-        exception_info += %[: "#{exception.message}"]
-      end
-      exception_info += " in #{nearest_frame}" if nearest_frame
+      info += %[: "#{exception.message}"] if exception.message != exception.class.to_s
+      info += " in #{nearest_frame}" if nearest_frame
 
-      "#{exception_info}: #{message}"
-    rescue StandardError
-      log_error('[Rollbar] Error building failsafe exception message')
-      ''
+      info
     end
 
     def failsafe_body(reason)

spec/rollbar_spec.rb

@@ -2015,6 +2015,118 @@ def backtrace
         notifier.send(:report_internal_error, e)
       end
     end
+
+    # https://github.com/rollbar/rollbar-gem/issues/1030
+    context 'logging the internal error' do
+      let(:logger_mock) { double('Rails.logger').as_null_object }
+      let(:log_prefix) do
+        '[Rollbar] Reporting internal error encountered while sending data to Rollbar: '
+      end
+
+      before do
+        Rollbar.configure { |config| config.logger = logger_mock }
+        allow(logger_mock).to receive(:error)
+      end
+
+      context 'when building the item for the original exception fails' do
+        let(:original_exception) do
+          begin
+            raise StandardError, 'connection lost'
+          rescue StandardError => e
+            e
+          end
+        end
+
+        before do
+          # Stands in for anything that breaks while Rollbar builds the payload,
+          # e.g. a rollbar_context that queries a database in the middle of a failover.
+          def original_exception.rollbar_context
+            raise 'database unavailable'
+          end
+        end
+
+        it 'logs the internal error and the original error on the same line' do
+          expect(Rollbar.error(original_exception)).to eq('error')
+
+          expect(logger_mock).to have_received(:error).with(
+            a_string_matching(
+              /\A#{Regexp.escape(log_prefix)}RuntimeError: "database unavailable" in .+ \(while reporting StandardError: "connection lost" in .+\)\z/ # rubocop:disable Layout/LineLength
+            )
+          ).once
+        end
+      end
+
+      context 'when the original exception has a #message that raises' do
+        let(:original_exception) { StandardError.new }
+
+        before do
+          def original_exception.message
+            raise 'broken message'
+          end
+        end
+
+        it 'still logs the internal error in full' do
+          expect(Rollbar.error(original_exception)).to eq('error')
+
+          expect(logger_mock).to have_received(:error).with(
+            a_string_matching(
+              /\A#{Regexp.escape(log_prefix)}RuntimeError: "broken message" in .+ \(while reporting StandardError\)\z/ # rubocop:disable Layout/LineLength
+            )
+          ).once
+        end
+      end
+
+      context 'when the original exception has a #message that overflows the stack' do
+        let(:original_exception) { StandardError.new }
+
+        before do
+          def original_exception.message
+            message
+          end
+        end
+
+        it 'does not raise into the caller and logs the internal error' do
+          expect(Rollbar.error(original_exception)).to eq('error')
+
+          expect(logger_mock).to have_received(:error).with(
+            a_string_matching(
+              /\A#{Regexp.escape(log_prefix)}SystemStackError: "stack level too deep" in .+ \(while reporting StandardError\)\z/ # rubocop:disable Layout/LineLength
+            )
+          ).once
+        end
+      end
+
+      context 'without an original error' do
+        it 'logs the class, message and nearest frame of the internal error' do
+          begin
+            1 / 0
+          rescue ZeroDivisionError => e
+            notifier.send(:report_internal_error, e)
+          end
+
+          expect(logger_mock).to have_received(:error).with(
+            "#{log_prefix}ZeroDivisionError: \"divided by 0\" in #{e.backtrace[0]}"
+          )
+        end
+      end
+
+      context 'when describing the internal error fails' do
+        let(:exception) { StandardError.new }
+
+        before do
+          def exception.message
+            raise 'broken message'
+          end
+        end
+
+        it 'still logs the class of the internal error' do
+          notifier.send(:report_internal_error, exception)
+
+          expect(logger_mock).to have_received(:error)
+            .with("#{log_prefix}StandardError")
+        end
+      end
+    end
   end
 
   context 'send_failsafe' do