Implement retry queue

lib/honeybadger/backend/null.rb

@@ -4,12 +4,13 @@ module Honeybadger
   module Backend
     class Null < Base
       class StubbedResponse < Response
-        def initialize
+        def initialize(successful: true)
           super(:stubbed, '{}'.freeze)
+          @success = successful
         end
 
         def success?
-          true
+          @success
         end
       end
 

lib/honeybadger/config/defaults.rb

@@ -335,12 +335,12 @@ class Boolean; end
         type: Boolean
       },
       :'logger.batch_size' => {
-        description: 'Wait until a batch contains this number of logs (or the timeout is reached) before sending.',
+        description: 'Maximum number of logs to send in one batch.',
         default: 20,
         type: Integer
       },
       :'logger.batch_interval' => {
-        description: 'If the log batch is not full and the time (in seconds) since the last batch is up to this, the batch will be sent.',
+        description: 'Send a log batch immediately if it has been this long (in seconds) since the last batch was sent.',
         default: 5,
         type: Integer
       },

lib/honeybadger/logger.rb

@@ -14,7 +14,7 @@ def appender
 
       def log_internal_error(error, action:)
         message = sprintf(
-          "Honeybadger::Logger error action=#{action} class=%s message=%s\n\t%s",
+          "Honeybadger::Logger error during #{action} class=%s message=%s\n\t%s",
           error.class, error.message.dump, Array(error.backtrace).join("\n\t")
         )
         Honeybadger.config.logger.error(message)
@@ -72,17 +72,45 @@ def self.create(**args)
     # Semantic logger's AsyncBatch wrapper will handle batching,
     # and call #batch when the batch is ready to be sent
     class HttpAppender < SemanticLogger::Subscriber
+      MAX_RETRY_BACKLOG = 200.freeze
+
+      def initialize(*)
+        super
+        @retry_queue = []
+      end
+
       def default_formatter
         SemanticLogger::Formatters::Json.new
       end
 
       def batch(logs)
-        # todo Dead-letter queue, retried at intervals + circuit breaker to avoid infinite retry
         payload = logs.map { |log| formatter.call(log, self) }.join("\n")
-        ::Honeybadger.config.backend.notify(:logs, payload)
+        def payload.to_json; self; end # The Server backend calls to_json
+        response = Honeybadger.config.backend.notify(:logs, payload)
+
+        if response.success?
+          retry_previous_failed_requests
+        else
+          @retry_queue << payload
+          @retry_queue.shift if @retry_queue.size > MAX_RETRY_BACKLOG
+        end
       rescue => e
         Honeybadger::Logger.log_internal_error(e, action: :send)
       end
+
+      private
+
+      def retry_previous_failed_requests
+        can_send = true
+        until @retry_queue.empty? || !can_send
+          payload = @retry_queue.shift
+          response = Honeybadger.config.backend.notify(:logs, payload)
+          if !response.success?
+            @retry_queue.unshift(payload)
+            can_send = false
+          end
+        end
+      end
     end
   end
 end

spec/unit/honeybadger/logger_spec.rb

@@ -15,14 +15,17 @@ def received_batches
     Honeybadger::Backend::Test.notifications[:logs]
   end
 
+  def wait_for_other_thread(wait = 0.05)
+    yield
+    sleep wait
+  end
+
   it 'waits until the batch is full before sending messages' do
     Honeybadger.config[:"logger.batch_size"] = 2
     Honeybadger.config[:"logger.batch_interval"] = 60
 
-    Honeybadger.logger.info("A message", some: 'data')
-    sleep 0.05
-    Honeybadger.logger.info("Another message", some: 'data')
-    sleep 0.05
+    wait_for_other_thread { Honeybadger.logger.info("A message", some: 'data') }
+    wait_for_other_thread { Honeybadger.logger.info("Another message", some: 'data') }
     expect(received_batches.size).to eq(1)
 
     logs = received_batches.first.split("\n").map { |log| JSON[log] }
@@ -37,19 +40,40 @@ def received_batches
     Honeybadger.config[:"logger.batch_size"] = 200
     Honeybadger.config[:"logger.batch_interval"] = 0.001
 
-    Honeybadger.logger.info("A message", some: 'data')
-    sleep 0.05
-    Honeybadger.logger.info("Another message", some: 'data')
-    sleep 0.05
+    wait_for_other_thread { Honeybadger.logger.warn("A message", some: 'data') }
+    wait_for_other_thread { Honeybadger.logger.info("Another message", some: 'data') }
 
     expect(received_batches.size).to eq(2)
 
     logs = received_batches.first.split("\n").map { |log| JSON[log] }
     expect(logs.size).to eq(1)
     expect(logs[0]["message"]).to eq("A message")
-    expect(logs[0]["level"]).to eq("info")
+    expect(logs[0]["level"]).to eq("warn")
     expect(logs[0]["payload"]).to eq({"some" => "data"})
   end
 
-  it 'retries a failed batch later'
+  it 'retries a failed batch when another batch succeeds' do
+    Honeybadger.config[:"logger.batch_size"] = 200
+    Honeybadger.config[:"logger.batch_interval"] = 0.001
+
+    backend = Honeybadger::Backend::Test.new(Honeybadger.config)
+    Honeybadger.config[:backend] = backend
+
+    expect(backend).to receive(:notify).twice do
+      Honeybadger::Backend::Null::StubbedResponse.new(successful: false)
+    end
+    wait_for_other_thread { Honeybadger.logger.debug("First - fails") }
+    wait_for_other_thread { Honeybadger.logger.debug("Second - fails") }
+
+    expect(received_batches.size).to eq(0)
+
+    expect(backend).to receive(:notify).exactly(3).times.and_call_original
+    wait_for_other_thread { Honeybadger.logger.error("Third - succeeds") }
+
+    expect(received_batches.size).to eq(3)
+
+    logs = received_batches.flat_map { |batch| batch.split("\n").map { |log| JSON[log] } }
+    expect(logs.size).to eq(3)
+    expect(logs.map { |l| l["message"] }).to eq(["Third - succeeds", "First - fails", "Second - fails"])
+  end
 end