From 9bf9dd80229b72986f6654786afea10f97a4057f Mon Sep 17 00:00:00 2001 From: Joe Haines Date: Wed, 18 Aug 2021 12:14:50 +0100 Subject: [PATCH 1/4] Refactor logging tests to use a real Logger --- spec/configuration_spec.rb | 125 +++++++++++++------------------------ 1 file changed, 43 insertions(+), 82 deletions(-) diff --git a/spec/configuration_spec.rb b/spec/configuration_spec.rb index fc81b84a..598a9099 100644 --- a/spec/configuration_spec.rb +++ b/spec/configuration_spec.rb @@ -246,40 +246,21 @@ end describe "logger" do - class TestLogger - attr_accessor :logs - - def initialize - @logs = [] - end - - def log(level, name, &block) - message = block.call - @logs << { - :level => level, - :name => name, - :message => message - } + before do + @output = StringIO.new + @formatter = proc do |severity, _datetime, progname, message| + "#{progname} #{severity}: #{message}" end - def info(name, &block) - log('info', name, &block) - end + logger = Logger.new(@output) + logger.formatter = @formatter - def warn(name, &block) - log('warning', name, &block) - end - - def debug(name, &block) - log('debug', name, &block) - end + Bugsnag.configuration.logger = logger end - before do - @logger = TestLogger.new - Bugsnag.configure do |bugsnag| - bugsnag.logger = @logger - end + def output_lines + @output.rewind # always read from the start of output + @output.readlines.map(&:chomp) # old rubies don't support `readlines(chomp: true)` end context "using configure" do @@ -287,35 +268,31 @@ def debug(name, &block) Bugsnag.configuration.api_key = nil Bugsnag.instance_variable_set("@key_warning", nil) ENV['BUGSNAG_API_KEY'] = nil - expect(@logger.logs.size).to eq(0) + expect(output_lines).to be_empty end context "API key is not specified" do it "skips logging a warning if validate_api_key is false" do Bugsnag.configure(false) - expect(@logger.logs.size).to eq(0) + expect(output_lines).to be_empty end it "logs a warning by default" do Bugsnag.configure - expect(@logger.logs.size).to eq(1) - log = @logger.logs.first - expect(log).to eq({ - :level => "warning", - :name => "[Bugsnag]", - :message => "No valid API key has been set, notifications will not be sent" - }) + + expect(output_lines.length).to be(1) + expect(output_lines.first).to eq( + '[Bugsnag] WARN: No valid API key has been set, notifications will not be sent' + ) end it "logs a warning if validate_api_key is true" do Bugsnag.configure(true) - expect(@logger.logs.size).to eq(1) - log = @logger.logs.first - expect(log).to eq({ - :level => "warning", - :name => "[Bugsnag]", - :message => "No valid API key has been set, notifications will not be sent" - }) + + expect(output_lines.length).to be(1) + expect(output_lines.first).to eq( + '[Bugsnag] WARN: No valid API key has been set, notifications will not be sent' + ) end end @@ -324,64 +301,48 @@ def debug(name, &block) Bugsnag.configure do |config| config.api_key = 'd57a2472bd130ac0ab0f52715bbdc600' end - expect(@logger.logs.size).to eq(0) + + expect(output_lines).to be_empty end it "logs a warning if the configured API key is invalid" do Bugsnag.configure do |config| config.api_key = 'WARNING: not a real key' end - expect(@logger.logs.size).to eq(1) - log = @logger.logs.first - expect(log).to eq({ - :level => "warning", - :name => "[Bugsnag]", - :message => "No valid API key has been set, notifications will not be sent" - }) + + expect(output_lines.length).to be(1) + expect(output_lines.first).to eq( + '[Bugsnag] WARN: No valid API key has been set, notifications will not be sent' + ) end end end it "should log info messages to the set logger" do - expect(@logger.logs.size).to eq(0) + expect(output_lines).to be_empty + Bugsnag.configuration.info("Info message") - expect(@logger.logs.size).to eq(1) - log = @logger.logs.first - expect(log).to eq({ - :level => "info", - :name => "[Bugsnag]", - :message => "Info message" - }) + + expect(output_lines.length).to be(1) + expect(output_lines.first).to eq('[Bugsnag] INFO: Info message') end it "should log warning messages to the set logger" do - expect(@logger.logs.size).to eq(0) + expect(output_lines).to be_empty + Bugsnag.configuration.warn("Warning message") - expect(@logger.logs.size).to eq(1) - log = @logger.logs.first - expect(log).to eq({ - :level => "warning", - :name => "[Bugsnag]", - :message => "Warning message" - }) + + expect(output_lines.length).to be(1) + expect(output_lines.first).to eq('[Bugsnag] WARN: Warning message') end it "should log debug messages to the set logger" do - expect(@logger.logs.size).to eq(0) + expect(output_lines).to be_empty + Bugsnag.configuration.debug("Debug message") - expect(@logger.logs.size).to eq(1) - log = @logger.logs.first - expect(log).to eq({ - :level => "debug", - :name => "[Bugsnag]", - :message => "Debug message" - }) - end - after do - Bugsnag.configure do |bugsnag| - bugsnag.logger = Logger.new(StringIO.new) - end + expect(output_lines.length).to be(1) + expect(output_lines.first).to eq('[Bugsnag] DEBUG: Debug message') end end From 7b4b57c46bdc9c6b085327b07bf4cc4e96083047 Mon Sep 17 00:00:00 2001 From: Joe Haines Date: Wed, 18 Aug 2021 12:15:49 +0100 Subject: [PATCH 2/4] Add Configuration#error to log error messages --- lib/bugsnag/configuration.rb | 12 ++++++++++-- spec/configuration_spec.rb | 9 +++++++++ 2 files changed, 19 insertions(+), 2 deletions(-) diff --git a/lib/bugsnag/configuration.rb b/lib/bugsnag/configuration.rb index 9594f75a..5c90227a 100644 --- a/lib/bugsnag/configuration.rb +++ b/lib/bugsnag/configuration.rb @@ -392,15 +392,23 @@ def info(message) ## # Logs a warning level message # - # @param (see info) + # @param message [String, #to_s] The message to log def warn(message) logger.warn(PROG_NAME) { message } end + ## + # Logs an error level message + # + # @param message [String, #to_s] The message to log + def error(message) + logger.error(PROG_NAME) { message } + end + ## # Logs a debug level message # - # @param (see info) + # @param message [String, #to_s] The message to log def debug(message) logger.debug(PROG_NAME) { message } end diff --git a/spec/configuration_spec.rb b/spec/configuration_spec.rb index 598a9099..cabe2f61 100644 --- a/spec/configuration_spec.rb +++ b/spec/configuration_spec.rb @@ -336,6 +336,15 @@ def output_lines expect(output_lines.first).to eq('[Bugsnag] WARN: Warning message') end + it "should log error messages to the set logger" do + expect(output_lines).to be_empty + + Bugsnag.configuration.error("Error message") + + expect(output_lines.length).to be(1) + expect(output_lines.first).to eq('[Bugsnag] ERROR: Error message') + end + it "should log debug messages to the set logger" do expect(output_lines).to be_empty From 52f67e73460195194f93d43d8cd806ed4c4cf8d2 Mon Sep 17 00:00:00 2001 From: Joe Haines Date: Wed, 18 Aug 2021 12:16:11 +0100 Subject: [PATCH 3/4] Log delivery failures at error level This should help to differentiate errors that prevent things from being delivered from errors that we can continue from, e.g. errors raised in middleware --- lib/bugsnag/delivery/synchronous.rb | 4 ++-- lib/bugsnag/delivery/thread_queue.rb | 4 ++-- 2 files changed, 4 insertions(+), 4 deletions(-) diff --git a/lib/bugsnag/delivery/synchronous.rb b/lib/bugsnag/delivery/synchronous.rb index b5444ce5..b0da7fde 100644 --- a/lib/bugsnag/delivery/synchronous.rb +++ b/lib/bugsnag/delivery/synchronous.rb @@ -18,8 +18,8 @@ def deliver(url, body, configuration, options={}) # KLUDGE: Since we don't re-raise http exceptions, this breaks rspec raise if e.class.to_s == "RSpec::Expectations::ExpectationNotMetError" - configuration.warn("Notification to #{url} failed, #{e.inspect}") - configuration.warn(e.backtrace) + configuration.error("Unable to send information to Bugsnag (#{url}), #{e.inspect}") + configuration.error(e.backtrace) end end diff --git a/lib/bugsnag/delivery/thread_queue.rb b/lib/bugsnag/delivery/thread_queue.rb index 50423ced..2b82b221 100644 --- a/lib/bugsnag/delivery/thread_queue.rb +++ b/lib/bugsnag/delivery/thread_queue.rb @@ -31,8 +31,8 @@ def serialize_and_deliver(url, get_payload, configuration, options={}) begin payload = get_payload.call rescue StandardError => e - configuration.warn("Notification to #{url} failed, #{e.inspect}") - configuration.warn(e.backtrace) + configuration.error("Unable to send information to Bugsnag (#{url}), #{e.inspect}") + configuration.error(e.backtrace) end Synchronous.deliver(url, payload, configuration, options) unless payload.nil? From 693a6662b4a294ce9013641938a2985fde2481f6 Mon Sep 17 00:00:00 2001 From: Joe Haines Date: Wed, 18 Aug 2021 12:18:50 +0100 Subject: [PATCH 4/4] Update changelog --- CHANGELOG.md | 2 ++ 1 file changed, 2 insertions(+) diff --git a/CHANGELOG.md b/CHANGELOG.md index 5f138728..737d0307 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -7,6 +7,8 @@ Changelog * Sessions will now be delivered every 10 seconds, instead of every 30 seconds | [#680](https://github.com/bugsnag/bugsnag-ruby/pull/680) +* Log errors that prevent delivery at `ERROR` level + | [#681](https://github.com/bugsnag/bugsnag-ruby/pull/681) ### Fixes