From 3f55a8455369f1141999f1f1d1333a1b47465154 Mon Sep 17 00:00:00 2001 From: Brian Palmer Date: Thu, 11 Dec 2014 10:41:05 -0700 Subject: [PATCH 1/4] implement timed backoff on server failures This is based on raven-python's implementation, with some tweaks for ruby idioms. With this commit, if we don't send, we only log the event id. I'd like to extend this to log the entire event, along with also logging the entire event when a sending failure occurs. --- lib/raven/client.rb | 59 +++++++++++++++++++++++++++++++-- sentry-raven.gemspec | 2 ++ spec/raven/client_state_spec.rb | 51 ++++++++++++++++++++++++++++ spec/raven/integration_spec.rb | 15 +++++++++ 4 files changed, 125 insertions(+), 2 deletions(-) create mode 100644 spec/raven/client_state_spec.rb diff --git a/lib/raven/client.rb b/lib/raven/client.rb index a540cc75e..0e45a20fe 100644 --- a/lib/raven/client.rb +++ b/lib/raven/client.rb @@ -19,6 +19,7 @@ class Client def initialize(configuration) @configuration = configuration @processors = configuration.processors.map { |v| v.new(self) } + @state = ClientState.new end def send(event) @@ -29,6 +30,12 @@ def send(event) # Set the project ID correctly event.project = self.configuration.project_id + + if !@state.should_try? + Raven.logger.error "Not sending event #{event.id} due to previous failure" + return + end + Raven.logger.debug "Sending event #{event.id} to Sentry" content_type, encoded_data = encode(event) @@ -36,11 +43,12 @@ def send(event) transport.send(generate_auth_header, encoded_data, :content_type => content_type) rescue => e - Raven.logger.error "Unable to record event with remote Sentry server (#{e.class} - #{e.message})" - e.backtrace[0..10].each { |line| Raven.logger.error(line) } + failed_send(e) return end + successful_send() + event end @@ -100,5 +108,52 @@ def strict_encode64(string) end end + def successful_send + @state.success() + end + + def failed_send(e) + @state.failure() + Raven.logger.error "Unable to record event with remote Sentry server (#{e.class} - #{e.message})" + e.backtrace[0..10].each { |line| Raven.logger.error(line) } + end + + end + + class ClientState + def initialize + reset + end + + def should_try? + return true if @status == :online + + interval = @retry_after || [@retry_number, 6].min ** 2 + return true if Time.now - @last_check >= interval + + false + end + + def failure(retry_after = nil) + @status = :error + @retry_number += 1 + @last_check = Time.now + @retry_after = retry_after + end + + def success + reset + end + + def reset + @status = :online + @retry_number = 0 + @last_check = nil + @retry_after = nil + end + + def failed? + @status == :error + end end end diff --git a/sentry-raven.gemspec b/sentry-raven.gemspec index 1ff166327..8b9b34b30 100644 --- a/sentry-raven.gemspec +++ b/sentry-raven.gemspec @@ -23,4 +23,6 @@ Gem::Specification.new do |gem| gem.add_development_dependency "coveralls" gem.add_development_dependency "rest-client", "< 1.7.0" if RUBY_VERSION == '1.8.7' gem.add_development_dependency "rest-client" if RUBY_VERSION > '1.8.7' + gem.add_development_dependency "timecop", "0.6.1" if RUBY_VERSION == '1.8.7' + gem.add_development_dependency "timecop" if RUBY_VERSION > '1.8.7' end diff --git a/spec/raven/client_state_spec.rb b/spec/raven/client_state_spec.rb new file mode 100644 index 000000000..8eda7df7b --- /dev/null +++ b/spec/raven/client_state_spec.rb @@ -0,0 +1,51 @@ +require 'spec_helper' +require 'timecop' + +describe Raven::ClientState do + let(:state) { Raven::ClientState.new } + + it 'should try when online' do + expect(state.should_try?).to eq(true) + end + + it 'should not try with a new error' do + state.failure() + expect(state.should_try?).to eq(false) + end + + it 'should try again after time passes' do + Timecop.freeze(-10) { state.failure() } + expect(state.should_try?).to eq(true) + end + + it 'should try again after success' do + state.failure() + state.success() + expect(state.should_try?).to eq(true) + end + + it 'should try again after retry_after' do + Timecop.freeze(-1) { state.failure(1) } + expect(state.should_try?).to eq(true) + end + + it 'should exponentially backoff' do + Timecop.freeze do + state.failure() + Timecop.travel(1) + expect(state.should_try?).to eq(true) + + state.failure() + Timecop.travel(3) + expect(state.should_try?).to eq(false) + Timecop.travel(1) + expect(state.should_try?).to eq(true) + + state.failure() + Timecop.travel(8) + expect(state.should_try?).to eq(false) + Timecop.travel(1) + expect(state.should_try?).to eq(true) + end + end +end diff --git a/spec/raven/integration_spec.rb b/spec/raven/integration_spec.rb index db299fc14..867a5ff0a 100644 --- a/spec/raven/integration_spec.rb +++ b/spec/raven/integration_spec.rb @@ -58,4 +58,19 @@ stubs.verify_stubbed_calls end + + example "timed backoff should prevent sends" do + Raven.configure do |config| + config.server = 'http://12345:67890@sentry.localdomain/sentry/42' + config.environments = ["test"] + config.current_environment = "test" + config.http_adapter = [:test, nil] + end + + expect_any_instance_of(Raven::Transports::HTTP).to receive(:send).exactly(1).times.and_raise(Faraday::Error::ConnectionFailed, "conn failed") + expect { Raven.capture_exception(build_exception) }.not_to raise_error + + expect(Raven.logger).to receive(:error).exactly(1).times + expect { Raven.capture_exception(build_exception) }.not_to raise_error + end end From 0d60029adce88285fd53b71b70a2d797c7322465 Mon Sep 17 00:00:00 2001 From: Brian Palmer Date: Thu, 11 Dec 2014 12:08:23 -0700 Subject: [PATCH 2/4] log event message on send failure or skip --- lib/raven/client.rb | 11 ++++++++--- 1 file changed, 8 insertions(+), 3 deletions(-) diff --git a/lib/raven/client.rb b/lib/raven/client.rb index 0e45a20fe..ba1f0b269 100644 --- a/lib/raven/client.rb +++ b/lib/raven/client.rb @@ -32,7 +32,7 @@ def send(event) event.project = self.configuration.project_id if !@state.should_try? - Raven.logger.error "Not sending event #{event.id} due to previous failure" + Raven.logger.error("Not sending event due to previous failure(s): #{get_log_message(event)}") return end @@ -43,7 +43,7 @@ def send(event) transport.send(generate_auth_header, encoded_data, :content_type => content_type) rescue => e - failed_send(e) + failed_send(e, event) return end @@ -74,6 +74,10 @@ def encode(event) end end + def get_log_message(event) + (event && event.message) || '' + end + def transport @transport ||= case self.configuration.scheme @@ -112,10 +116,11 @@ def successful_send @state.success() end - def failed_send(e) + def failed_send(e, event) @state.failure() Raven.logger.error "Unable to record event with remote Sentry server (#{e.class} - #{e.message})" e.backtrace[0..10].each { |line| Raven.logger.error(line) } + Raven.logger.error("Failed to submit event: #{get_log_message(event)}") end end From e01c9b90d98a06b4ae855ce59fb9e64c91ac0a7d Mon Sep 17 00:00:00 2001 From: Brian Palmer Date: Thu, 11 Dec 2014 15:35:28 -0700 Subject: [PATCH 3/4] add a little breathing room to the timing in the specs Using timecop to freeze at the *precise* moment where the condition changes can cause problems due to rounding error. --- spec/raven/client_state_spec.rb | 8 ++++---- 1 file changed, 4 insertions(+), 4 deletions(-) diff --git a/spec/raven/client_state_spec.rb b/spec/raven/client_state_spec.rb index 8eda7df7b..7368e022e 100644 --- a/spec/raven/client_state_spec.rb +++ b/spec/raven/client_state_spec.rb @@ -25,26 +25,26 @@ end it 'should try again after retry_after' do - Timecop.freeze(-1) { state.failure(1) } + Timecop.freeze(-2) { state.failure(1) } expect(state.should_try?).to eq(true) end it 'should exponentially backoff' do Timecop.freeze do state.failure() - Timecop.travel(1) + Timecop.travel(2) expect(state.should_try?).to eq(true) state.failure() Timecop.travel(3) expect(state.should_try?).to eq(false) - Timecop.travel(1) + Timecop.travel(2) expect(state.should_try?).to eq(true) state.failure() Timecop.travel(8) expect(state.should_try?).to eq(false) - Timecop.travel(1) + Timecop.travel(2) expect(state.should_try?).to eq(true) end end From 3c3a111fe81e9a3a9a7811e6458f5e47567f114a Mon Sep 17 00:00:00 2001 From: Brian Palmer Date: Fri, 12 Dec 2014 13:53:09 -0700 Subject: [PATCH 4/4] style tweak: remove parens from method calls with no args --- lib/raven/client.rb | 6 +++--- spec/raven/client_state_spec.rb | 14 +++++++------- spec/raven/integrations/rack_spec.rb | 2 +- 3 files changed, 11 insertions(+), 11 deletions(-) diff --git a/lib/raven/client.rb b/lib/raven/client.rb index ba1f0b269..5c0def91b 100644 --- a/lib/raven/client.rb +++ b/lib/raven/client.rb @@ -47,7 +47,7 @@ def send(event) return end - successful_send() + successful_send event end @@ -113,11 +113,11 @@ def strict_encode64(string) end def successful_send - @state.success() + @state.success end def failed_send(e, event) - @state.failure() + @state.failure Raven.logger.error "Unable to record event with remote Sentry server (#{e.class} - #{e.message})" e.backtrace[0..10].each { |line| Raven.logger.error(line) } Raven.logger.error("Failed to submit event: #{get_log_message(event)}") diff --git a/spec/raven/client_state_spec.rb b/spec/raven/client_state_spec.rb index 7368e022e..25ea4ed1f 100644 --- a/spec/raven/client_state_spec.rb +++ b/spec/raven/client_state_spec.rb @@ -9,18 +9,18 @@ end it 'should not try with a new error' do - state.failure() + state.failure expect(state.should_try?).to eq(false) end it 'should try again after time passes' do - Timecop.freeze(-10) { state.failure() } + Timecop.freeze(-10) { state.failure } expect(state.should_try?).to eq(true) end it 'should try again after success' do - state.failure() - state.success() + state.failure + state.success expect(state.should_try?).to eq(true) end @@ -31,17 +31,17 @@ it 'should exponentially backoff' do Timecop.freeze do - state.failure() + state.failure Timecop.travel(2) expect(state.should_try?).to eq(true) - state.failure() + state.failure Timecop.travel(3) expect(state.should_try?).to eq(false) Timecop.travel(2) expect(state.should_try?).to eq(true) - state.failure() + state.failure Timecop.travel(8) expect(state.should_try?).to eq(false) Timecop.travel(2) diff --git a/spec/raven/integrations/rack_spec.rb b/spec/raven/integrations/rack_spec.rb index 7be3642ea..a39eb4f59 100644 --- a/spec/raven/integrations/rack_spec.rb +++ b/spec/raven/integrations/rack_spec.rb @@ -60,7 +60,7 @@ it 'should allow empty rack env in rspec tests' do env = {} # the rack env is empty when running rails/rspec tests Raven.rack_context(env) - expect { Raven.capture_exception(build_exception()) }.not_to raise_error + expect { Raven.capture_exception(build_exception) }.not_to raise_error end it 'should bind request context' do