From 918b83d7afb687728909cb7d9faf0d5a158ffb60 Mon Sep 17 00:00:00 2001 From: Neel Shah Date: Thu, 4 Jan 2024 14:22:41 +0100 Subject: [PATCH] Clean up logging (#2216) --- CHANGELOG.md | 8 +-- sentry-ruby/lib/sentry/client.rb | 12 ++-- sentry-ruby/lib/sentry/configuration.rb | 2 +- sentry-ruby/lib/sentry/event.rb | 28 ---------- sentry-ruby/lib/sentry/transport.rb | 4 +- .../lib/sentry/transport/http_transport.rb | 16 ++---- .../spec/sentry/client/event_sending_spec.rb | 6 -- sentry-ruby/spec/sentry/client_spec.rb | 7 ++- sentry-ruby/spec/sentry/event_spec.rb | 55 ------------------- .../http_transport_rate_limiting_spec.rb | 19 +++---- .../spec/sentry/sidekiq/error_handler_spec.rb | 3 +- sentry-sidekiq/spec/sentry/sidekiq_spec.rb | 3 +- 12 files changed, 35 insertions(+), 128 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 4207eec59..97812b522 100644 --- a/CHANGELOG.md +++ b/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 diff --git a/sentry-ruby/lib/sentry/client.rb b/sentry-ruby/lib/sentry/client.rb index 8c6691202..6d3a04865 100644 --- a/sentry-ruby/lib/sentry/client.rb +++ b/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 diff --git a/sentry-ruby/lib/sentry/configuration.rb b/sentry-ruby/lib/sentry/configuration.rb index 5bfda3f64..1cc2b761b 100644 --- a/sentry-ruby/lib/sentry/configuration.rb +++ b/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 diff --git a/sentry-ruby/lib/sentry/event.rb b/sentry-ruby/lib/sentry/event.rb index b9f8a58e6..5016ea545 100644 --- a/sentry-ruby/lib/sentry/event.rb +++ b/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? - - '' - 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 diff --git a/sentry-ruby/lib/sentry/transport.rb b/sentry-ruby/lib/sentry/transport.rb index 2c3b1ca47..bab781ec1 100644 --- a/sentry-ruby/lib/sentry/transport.rb +++ b/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 diff --git a/sentry-ruby/lib/sentry/transport/http_transport.rb b/sentry-ruby/lib/sentry/transport/http_transport.rb index 270f05d4f..4a9ee620f 100644 --- a/sentry-ruby/lib/sentry/transport/http_transport.rb +++ b/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 diff --git a/sentry-ruby/spec/sentry/client/event_sending_spec.rb b/sentry-ruby/spec/sentry/client/event_sending_spec.rb index fe7aad6bd..26d9cd9d3 100644 --- a/sentry-ruby/spec/sentry/client/event_sending_spec.rb +++ b/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 diff --git a/sentry-ruby/spec/sentry/client_spec.rb b/sentry-ruby/spec/sentry/client_spec.rb index 91eeeceee..0e644381b 100644 --- a/sentry-ruby/spec/sentry/client_spec.rb +++ b/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 diff --git a/sentry-ruby/spec/sentry/event_spec.rb b/sentry-ruby/spec/sentry/event_spec.rb index 10c4b448c..fbeadd5ed 100644 --- a/sentry-ruby/spec/sentry/event_spec.rb +++ b/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('') - expect(described_class.get_log_message(subject.to_json_compatible)).to eq('') - 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 diff --git a/sentry-ruby/spec/sentry/transport/http_transport_rate_limiting_spec.rb b/sentry-ruby/spec/sentry/transport/http_transport_rate_limiting_spec.rb index 0814355d8..452b233d2 100644 --- a/sentry-ruby/spec/sentry/transport/http_transport_rate_limiting_spec.rb +++ b/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 diff --git a/sentry-sidekiq/spec/sentry/sidekiq/error_handler_spec.rb b/sentry-sidekiq/spec/sentry/sidekiq/error_handler_spec.rb index 09e79b68b..15053609e 100644 --- a/sentry-sidekiq/spec/sentry/sidekiq/error_handler_spec.rb +++ b/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 diff --git a/sentry-sidekiq/spec/sentry/sidekiq_spec.rb b/sentry-sidekiq/spec/sentry/sidekiq_spec.rb index fe4c7bca7..2e7cfb99a 100644 --- a/sentry-sidekiq/spec/sentry/sidekiq_spec.rb +++ b/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