Clean up logging (#2216)

CHANGELOG.md

@@ -2,9 +2,9 @@
 
 ### Features
 
-- Enable backpressure handling by default [#2185](https://github.com/getsentry/sentry-ruby/pull/2185)
+- Add backpressure handling for transactions [#2185](https://github.com/getsentry/sentry-ruby/pull/2185)
 
-    The SDK can now dynamically downsamples transactions to reduce backpressure in high
+    The SDK can now dynamically downsample transactions to reduce backpressure in high
     throughput systems. It starts a new `BackpressureMonitor` thread to perform some health checks
     which decide to downsample (halved each time) in 10 second intervals till the system
     is healthy again.
@@ -34,8 +34,8 @@
       config.cron.default_timezone = 'America/New_York'
     end
     ```
-
-- Pick up config.cron.default_timezone from Rails config ([#2213](https://github.com/getsentry/sentry-ruby/pull/2213))
+- Clean up logging [#2216](https://github.com/getsentry/sentry-ruby/pull/2216)
+- Pick up config.cron.default_timezone from Rails config [#2213](https://github.com/getsentry/sentry-ruby/pull/2213)
 
 ## 5.15.2
 

sentry-ruby/lib/sentry/client.rb

@@ -57,7 +57,7 @@ def capture_event(event, scope, hint = {})
       event = scope.apply_to_event(event, hint)
 
       if event.nil?
-        log_info("Discarded event because one of the event processors returned nil")
+        log_debug("Discarded event because one of the event processors returned nil")
         transport.record_lost_event(:event_processor, event_type)
         return
       end
@@ -156,7 +156,7 @@ def send_event(event, hint = nil)
         event = configuration.before_send.call(event, hint)
 
         if event.nil?
-          log_info("Discarded event because before_send returned nil")
+          log_debug("Discarded event because before_send returned nil")
           transport.record_lost_event(:before_send, 'event')
           return
         end
@@ -166,7 +166,7 @@ def send_event(event, hint = nil)
         event = configuration.before_send_transaction.call(event, hint)
 
         if event.nil?
-          log_info("Discarded event because before_send_transaction returned nil")
+          log_debug("Discarded event because before_send_transaction returned nil")
           transport.record_lost_event(:before_send, 'transaction')
           return
         end
@@ -177,11 +177,7 @@ def send_event(event, hint = nil)
 
       event
     rescue => e
-      loggable_event_type = event_type.capitalize
-      log_error("#{loggable_event_type} sending failed", e, debug: configuration.debug)
-
-      event_info = Event.get_log_message(event.to_hash)
-      log_info("Unreported #{loggable_event_type}: #{event_info}")
+      log_error("Event sending failed", e, debug: configuration.debug)
       transport.record_lost_event(:network_error, event_type)
       raise
     end

sentry-ruby/lib/sentry/configuration.rb

@@ -474,7 +474,7 @@ def traces_sample_rate=(traces_sample_rate)
 
     def profiles_sample_rate=(profiles_sample_rate)
       raise ArgumentError, "profiles_sample_rate must be a Numeric or nil" unless is_numeric_or_nil?(profiles_sample_rate)
-      log_info("Please make sure to include the 'stackprof' gem in your Gemfile to use Profiling with Sentry.") unless defined?(StackProf)
+      log_warn("Please make sure to include the 'stackprof' gem in your Gemfile to use Profiling with Sentry.") unless defined?(StackProf)
       @profiles_sample_rate = profiles_sample_rate
     end
 

sentry-ruby/lib/sentry/event.rb

@@ -76,34 +76,6 @@ def initialize(configuration:, integration_meta: nil, message: nil)
       @message = (message || "").byteslice(0..MAX_MESSAGE_SIZE_IN_BYTES)
     end
 
-    class << self
-      # @!visibility private
-      def get_log_message(event_hash)
-        message = event_hash[:message] || event_hash['message']
-
-        return message unless message.nil? || message.empty?
-
-        message = get_message_from_exception(event_hash)
-
-        return message unless message.nil? || message.empty?
-
-        message = event_hash[:transaction] || event_hash["transaction"]
-
-        return message unless message.nil? || message.empty?
-
-        '<no message value>'
-      end
-
-      # @!visibility private
-      def get_message_from_exception(event_hash)
-        if exception = event_hash.dig(:exception, :values, 0)
-          "#{exception[:type]}: #{exception[:value]}"
-        elsif exception = event_hash.dig("exception", "values", 0)
-          "#{exception["type"]}: #{exception["value"]}"
-        end
-      end
-    end
-
     # @deprecated This method will be removed in v5.0.0. Please just use Sentry.configuration
     # @return [Configuration]
     def configuration

sentry-ruby/lib/sentry/transport.rb

@@ -75,7 +75,7 @@ def serialize_envelope(envelope)
         result, oversized = item.serialize
 
         if oversized
-          log_info("Envelope item [#{item.type}] is still oversized after size reduction: {#{item.size_breakdown}}")
+          log_debug("Envelope item [#{item.type}] is still oversized after size reduction: {#{item.size_breakdown}}")
 
           next
         end
@@ -208,7 +208,7 @@ def fetch_pending_client_report(force: false)
     def reject_rate_limited_items(envelope)
       envelope.items.reject! do |item|
         if is_rate_limited?(item.type)
-          log_info("[Transport] Envelope item [#{item.type}] not sent: rate limiting")
+          log_debug("[Transport] Envelope item [#{item.type}] not sent: rate limiting")
           record_lost_event(:ratelimit_backoff, item.type)
 
           true

sentry-ruby/lib/sentry/transport/http_transport.rb

@@ -53,18 +53,14 @@ def send_data(data)
       end
 
       if response.code.match?(/\A2\d{2}/)
-        if has_rate_limited_header?(response)
-          handle_rate_limited_response(response)
-        end
+        handle_rate_limited_response(response) if has_rate_limited_header?(response)
+      elsif response.code == "429"
+        log_debug("the server responded with status 429")
+        handle_rate_limited_response(response)
       else
         error_info = "the server responded with status #{response.code}"
-
-        if response.code == "429"
-          handle_rate_limited_response(response)
-        else
-          error_info += "\nbody: #{response.body}"
-          error_info += " Error in headers is: #{response['x-sentry-error']}" if response['x-sentry-error']
-        end
+        error_info += "\nbody: #{response.body}"
+        error_info += " Error in headers is: #{response['x-sentry-error']}" if response['x-sentry-error']
 
         raise Sentry::ExternalError, error_info
       end

sentry-ruby/spec/sentry/client/event_sending_spec.rb

@@ -362,7 +362,6 @@
 
           expect(subject.transport).to have_recorded_lost_event(:network_error, 'event')
           expect(string_io.string).to match(/Event sending failed: Failed to open TCP connection/)
-          expect(string_io.string).to match(/Unreported Event: Test message/)
           expect(string_io.string).to match(/Event capturing failed: Failed to open TCP connection/)
         end
 
@@ -372,7 +371,6 @@
           expect(subject.capture_event(event, scope)).to be_nil
 
           expect(string_io.string).to match(/Event sending failed: TypeError/)
-          expect(string_io.string).to match(/Unreported Event: Test message/)
         end
       end
 
@@ -387,7 +385,6 @@
 
           expect(subject.transport).to have_recorded_lost_event(:network_error, 'event')
           expect(string_io.string).to match(/Event sending failed: Failed to open TCP connection/)
-          expect(string_io.string).to match(/Unreported Event: Test message/)
         end
 
         it "swallows and logs errors caused by the user (like in before_send)" do
@@ -397,7 +394,6 @@
           sleep(0.2)
 
           expect(string_io.string).to match(/Event sending failed: TypeError/)
-          expect(string_io.string).to match(/Unreported Event: Test message/)
         end
       end
 
@@ -432,7 +428,6 @@
           end.to raise_error(Sentry::ExternalError)
 
           expect(string_io.string).to match(/Event sending failed: Failed to open TCP connection/)
-          expect(string_io.string).to match(/Unreported Event: Test message/)
         end
       end
 
@@ -449,7 +444,6 @@
           end.to raise_error(TypeError)
 
           expect(string_io.string).to match(/Event sending failed: TypeError/)
-          expect(string_io.string).to match(/Unreported Event: Test message/)
         end
 
         context "with config.debug = true" do

sentry-ruby/spec/sentry/client_spec.rb

@@ -246,8 +246,9 @@ def detailed_message(*)
         end
 
         event = subject.event_from_exception(NonStringMessageError.new)
+        hash = event.to_hash
         expect(event).to be_a(Sentry::ErrorEvent)
-        expect(Sentry::Event.get_message_from_exception(event.to_hash)).to match("NonStringMessageError: {:foo=>\"bar\"}")
+        expect(hash[:exception][:values][0][:value]).to eq("{:foo=>\"bar\"}")
       end
     end
 
@@ -282,7 +283,9 @@ def detailed_message(*)
     it 'returns an event' do
       event = subject.event_from_exception(ZeroDivisionError.new("divided by 0"))
       expect(event).to be_a(Sentry::ErrorEvent)
-      expect(Sentry::Event.get_message_from_exception(event.to_hash)).to match("ZeroDivisionError: divided by 0")
+      hash = event.to_hash
+      expect(hash[:exception][:values][0][:type]).to match("ZeroDivisionError")
+      expect(hash[:exception][:values][0][:value]).to match("divided by 0")
     end
 
     context 'for a nested exception type' do

sentry-ruby/spec/sentry/event_spec.rb

@@ -185,59 +185,4 @@
       expect(json["extra"]['anonymous_module']).not_to be_a(Class)
     end
   end
-
-  describe ".get_log_message" do
-    let(:client) do
-      Sentry::Client.new(configuration)
-    end
-
-    let(:hub) do
-      Sentry::Hub.new(client, Sentry::Scope.new)
-    end
-
-    context "with adnormal event" do
-      subject do
-        Sentry::Event.new(configuration: configuration)
-      end
-
-      it "returns placeholder message" do
-        expect(described_class.get_log_message(subject.to_hash)).to eq('<no message value>')
-        expect(described_class.get_log_message(subject.to_json_compatible)).to eq('<no message value>')
-      end
-    end
-    context "with transaction event" do
-      let(:transaction) do
-        Sentry::Transaction.new(name: "test transaction", op: "sql.active_record", hub: hub, sampled: true)
-      end
-
-      subject do
-        client.event_from_transaction(transaction)
-      end
-
-      it "returns the transaction's name" do
-        expect(described_class.get_log_message(subject.to_hash)).to eq("test transaction")
-        expect(described_class.get_log_message(subject.to_json_compatible)).to eq("test transaction")
-      end
-    end
-    context "with exception event" do
-      subject do
-        client.event_from_exception(Exception.new("error!"))
-      end
-
-      it "returns the exception's message" do
-        expect(described_class.get_log_message(subject.to_hash)).to include("Exception: error!")
-        expect(described_class.get_log_message(subject.to_json_compatible)).to match("Exception: error!")
-      end
-    end
-    context "with message event" do
-      subject do
-        client.event_from_message("test")
-      end
-
-      it "returns the event's message" do
-        expect(described_class.get_log_message(subject.to_hash)).to eq("test")
-        expect(described_class.get_log_message(subject.to_json_compatible)).to eq("test")
-      end
-    end
-  end
 end

sentry-ruby/spec/sentry/transport/http_transport_rate_limiting_spec.rb

@@ -5,12 +5,13 @@
   include_context "with request mock"
 
   before do
-    perform_basic_setup
+    perform_basic_setup do |config|
+      config.logger = Logger.new(string_io)
+    end
   end
 
-  let(:configuration) do
-    Sentry.configuration
-  end
+  let(:string_io) { StringIO.new }
+  let(:configuration) { Sentry.configuration }
   let(:client) { Sentry.get_current_client }
   let(:data) do
     subject.envelope_from_event(client.event_from_message("foobarbaz").to_hash).to_s
@@ -252,9 +253,8 @@ def send_data_and_verify_response(time)
 
       it_behaves_like "rate limiting headers handling" do
         def send_data_and_verify_response(time)
-          Timecop.freeze(time) do
-            expect { subject.send_data(data) }.to raise_error(Sentry::ExternalError, /the server responded with status 429/)
-          end
+          Timecop.freeze(time) { subject.send_data(data) }
+          expect(string_io.string).to match(/the server responded with status 429/)
         end
       end
 
@@ -266,9 +266,8 @@ def send_data_and_verify_response(time)
         it "adds default limits" do
           now = Time.now
 
-          Timecop.freeze(now) do
-            expect { subject.send_data(data) }.to raise_error(Sentry::ExternalError, /the server responded with status 429/)
-          end
+          Timecop.freeze(now) { subject.send_data(data) }
+          expect(string_io.string).to match(/the server responded with status 429/)
           expect(subject.rate_limits).to eq({ nil => now + 60 })
         end
       end

sentry-sidekiq/spec/sentry/sidekiq/error_handler_spec.rb

@@ -40,7 +40,8 @@
     end
 
     event = transport.events.last.to_hash
-    expect(Sentry::Event.get_message_from_exception(event)).to match("RuntimeError: Uhoh!")
+    expect(event[:exception][:values][0][:type]).to eq("RuntimeError")
+    expect(event[:exception][:values][0][:value]).to match("Uhoh!")
     expect(event[:transaction]).to eq "Sidekiq/startup"
   end
 

sentry-sidekiq/spec/sentry/sidekiq_spec.rb

@@ -54,7 +54,8 @@
 
     event = transport.events.last.to_hash
     expect(event[:sdk]).to eq({ name: "sentry.ruby.sidekiq", version: described_class::VERSION })
-    expect(Sentry::Event.get_message_from_exception(event)).to match("RuntimeError: I'm sad!")
+    expect(event[:exception][:values][0][:type]).to eq("RuntimeError")
+    expect(event[:exception][:values][0][:value]).to match("I'm sad!")
   end
 
   it "doesn't store the private `_config` context", skip: !WITH_SIDEKIQ_7 do