(fix): fix loop on batch event processor (#224)

* fix loop

* sleep for flush interval only if no items

* block on the pop

* hang on poll if we have gotten two nil items after sleep.

* cleanup rubocop lint

* add logging

* sleep interval in seconds

* cleanup lint errors

* make sleep interval a double.

* get tests passing

* refactor to only sleep a portion of the max nil count.  When max nil count is reached, the timer will also have been reached and it will flush.  then hang on poll.

* fix lint errors

* take out longer sleep

* fix lint

* allow for flush interval to pass, if there have been no entries, flush and then hang on pop

* remove sleep

* added comments

* add a debug log for successful event sent

* fix tests to expect a log event

Author: thomaszurkan-optimizely

lib/optimizely/event/batch_event_processor.rb

@@ -31,6 +31,7 @@ class BatchEventProcessor < EventProcessor
     DEFAULT_BATCH_INTERVAL = 30_000 # interval in milliseconds
     DEFAULT_QUEUE_CAPACITY = 1000
     DEFAULT_TIMEOUT_INTERVAL = 5 # interval in seconds
+    MAX_NIL_COUNT = 3
 
     FLUSH_SIGNAL = 'FLUSH_SIGNAL'
     SHUTDOWN_SIGNAL = 'SHUTDOWN_SIGNAL'
@@ -107,16 +108,32 @@ def stop!
     private
 
     def run
+      # if we receive a number of item nils that reach MAX_NIL_COUNT,
+      # then we hang on the pop via setting use_pop to false
+      @nil_count = 0
+      # hang on pop if true
+      @use_pop = false
       loop do
-        flush_queue! if Helpers::DateTimeUtils.create_timestamp > @flushing_interval_deadline
+        if Helpers::DateTimeUtils.create_timestamp >= @flushing_interval_deadline
+          @logger.log(Logger::DEBUG, 'Deadline exceeded flushing current batch.')
+          flush_queue!
+          @flushing_interval_deadline = Helpers::DateTimeUtils.create_timestamp + @flush_interval
+          @use_pop = true if @nil_count > MAX_NIL_COUNT
+        end
 
-        item = @event_queue.pop if @event_queue.length.positive?
+        item = @event_queue.pop if @event_queue.length.positive? || @use_pop
 
         if item.nil?
-          sleep(0.05)
+          # when nil count is greater than MAX_NIL_COUNT, we hang on the pop until there is an item available.
+          # this avoids to much spinning of the loop.
+          @nil_count += 1
           next
         end
 
+        # reset nil_count and use_pop if we have received an item.
+        @nil_count = 0
+        @use_pop = false
+
         if item == SHUTDOWN_SIGNAL
           @logger.log(Logger::DEBUG, 'Received shutdown signal.')
           break

lib/optimizely/event_dispatcher.rb

@@ -59,6 +59,8 @@ def dispatch_event(event)
       when 500...600
         @logger.log(Logger::ERROR, error_msg)
         @error_handler.handle_error(HTTPCallError.new("HTTP Server Error: #{response.code}"))
+      else
+        @logger.log(Logger::DEBUG, 'event successfully sent with response code ' + response.code.to_s)
       end
     rescue Timeout::Error => e
       @logger.log(Logger::ERROR, "Request Timed out. Error: #{e}")

spec/event/batch_event_processor_spec.rb

@@ -62,7 +62,7 @@
 
     @event_processor.process(conversion_event)
     # flush interval is set to 100ms. Wait for 300ms and assert that event is dispatched.
-    sleep 0.3
+    sleep 1
 
     expect(@event_dispatcher).to have_received(:dispatch_event).with(log_event).once
     expect(@notification_center).to have_received(:send_notifications).with(
@@ -153,7 +153,6 @@
 
     expect(@event_dispatcher).to have_received(:dispatch_event).with(log_event).once
     expect(spy_logger).to have_received(:log).with(Logger::DEBUG, 'Revisions mismatched: Flushing current batch.').once
-    expect(spy_logger).not_to have_received(:log).with(Logger::DEBUG, 'Deadline exceeded flushing current batch.')
   end
 
   it 'should flush on mismatch project id' do

spec/event_dispatcher_spec.rb

@@ -146,9 +146,9 @@
 
     response = @customized_event_dispatcher.dispatch_event(event)
 
-    expect(response).to be_nil
-    expect(spy_logger).not_to have_received(:log)
-    expect(error_handler).not_to have_received(:handle_error)
+    expect(response).to have_received(:log)
+    expect(spy_logger).to have_received(:log)
+    expect(error_handler).to_not have_received(:handle_error)
   end
 
   it 'should do nothing on response with status code 600' do
@@ -157,8 +157,8 @@
 
     response = @customized_event_dispatcher.dispatch_event(event)
 
-    expect(response).to be_nil
-    expect(spy_logger).not_to have_received(:log)
+    expect(response).to have_received(:log)
+    expect(spy_logger).to have_received(:log)
     expect(error_handler).not_to have_received(:handle_error)
   end
 end