Auto-flush log events when adding and fix flush

Author: solnic

sentry-ruby/lib/sentry/log_event_buffer.rb

@@ -3,6 +3,11 @@
 require "sentry/threaded_periodic_worker"
 
 module Sentry
+  # LogEventBuffer buffers log events and sends them to Sentry in a single envelope.
+  #
+  # This is used internally by the `Sentry::Client`.
+  #
+  # @!visibility private
   class LogEventBuffer < ThreadedPeriodicWorker
     FLUSH_INTERVAL = 5 # seconds
     DEFAULT_MAX_EVENTS = 100
@@ -30,13 +35,11 @@ def start
 
     def flush
       @mutex.synchronize do
-        return unless size >= @max_events
+        return if empty?
 
         log_debug("[LogEventBuffer] flushing #{size} log events")
 
-        @client.send_envelope(to_envelope)
-
-        @pending_events.clear
+        send_events
       end
 
       log_debug("[LogEventBuffer] flushed #{size} log events")
@@ -50,6 +53,7 @@ def add_event(event)
 
       @mutex.synchronize do
         @pending_events << event
+        send_events if size >= @max_events
       end
 
       self
@@ -65,6 +69,11 @@ def size
 
     private
 
+    def send_events
+      @client.send_envelope(to_envelope)
+      @pending_events.clear
+    end
+
     def to_envelope
       envelope = Envelope.new(
         event_id: SecureRandom.uuid.delete("-"),

sentry-ruby/spec/sentry/log_event_buffer_spec.rb

@@ -7,12 +7,20 @@
 
   let(:string_io) { StringIO.new }
   let(:logger) { ::Logger.new(string_io) }
+  let(:client) { double(Sentry::Client) }
+  let(:log_event) do
+    Sentry::LogEvent.new(
+      configuration: Sentry.configuration,
+      level: :info,
+      body: "Test message"
+    )
+  end
 
   before do
     perform_basic_setup do |config|
       config.sdk_logger = logger
       config.background_worker_threads = 0
-      config.max_log_events = 3
+      config.max_log_events = max_log_events
     end
 
     Sentry.background_worker = Sentry::BackgroundWorker.new(Sentry.configuration)
@@ -22,17 +30,8 @@
     Sentry.background_worker = Class.new { def shutdown; end; }.new
   end
 
-  let(:client) { Sentry.get_current_client }
-  let(:transport) { client.transport }
-
   describe "#add_event" do
-    let(:log_event) do
-      Sentry::LogEvent.new(
-        configuration: Sentry.configuration,
-        level: :info,
-        body: "Test message"
-      )
-    end
+    let(:max_log_events) { 3 }
 
     it "does nothing when there are no pending events" do
       expect(client).not_to receive(:capture_envelope)
@@ -43,38 +42,36 @@
     end
 
     it "does nothing when the number of events is less than max_events " do
-      2.times { log_event_buffer.add_event(log_event) }
+      expect(client).to_not receive(:send_envelope)
 
-      log_event_buffer.flush
-
-      expect(sentry_envelopes.size).to be(0)
+      2.times { log_event_buffer.add_event(log_event) }
     end
 
-    it "sends pending events to the client" do
-      3.times { log_event_buffer.add_event(log_event) }
-
-      log_event_buffer.flush
+    it "auto-flushes pending events to the client when the number of events reaches max_events" do
+      expect(client).to receive(:send_envelope)
 
-      expect(sentry_envelopes.size).to be(1)
+      3.times { log_event_buffer.add_event(log_event) }
 
       expect(log_event_buffer).to be_empty
     end
+  end
 
-    it "thread-safely handles concurrent access", skip: RUBY_ENGINE == "jruby" do
-      expect(client).to receive(:send_envelope) do |_envelope|
-        sleep 0.1
-      end
+  describe "multi-threaded access" do
+    let(:max_log_events) { 30 }
 
-      threads = 100.times.map do
-        (1..50).to_a.sample.times { log_event_buffer.add_event(log_event) }
+    it "thread-safely handles concurrent access" do
+      expect(client).to receive(:send_envelope).exactly(3).times
 
+      threads = 3.times.map do
         Thread.new do
-          log_event_buffer.flush
+          (20..30).to_a.sample.times { log_event_buffer.add_event(log_event) }
         end
       end
 
       threads.each(&:join)
 
+      log_event_buffer.flush
+
       expect(log_event_buffer).to be_empty
     end
   end

sentry-ruby/spec/sentry/structured_logger_spec.rb

@@ -21,111 +21,79 @@
       end
     end
 
-    let(:logs) do
-      Sentry.get_current_client.log_event_buffer.pending_events
-    end
-
     ["info", "warn", "error", "fatal"].each do |level|
       describe "##{level}" do
         it "logs using default logger and LogEvent logger with extra attributes" do
           payload = { user_id: 123, action: "create" }
 
           Sentry.logger.public_send(level, "Hello World", payload)
 
-          expect(logs).to_not be_empty
+          expect(sentry_logs).to_not be_empty
 
-          log_event = logs.last
+          log_event = sentry_logs.last
 
-          expect(log_event.type).to eql("log")
-          expect(log_event.level).to eql(level.to_sym)
-          expect(log_event.body).to eql("Hello World")
-          expect(log_event.attributes).to include(payload)
+          expect(log_event[:level]).to eql(level)
+          expect(log_event[:body]).to eql("Hello World")
+          expect(log_event[:attributes]).to include({ user_id: { value: 123, type: "integer" } })
+          expect(log_event[:attributes]).to include({ action: { value: "create", type: "string" } })
         end
 
         it "logs with template parameters" do
           Sentry.logger.public_send(level, "Hello %s it is %s", ["Jane", "Monday"])
 
-          expect(logs).to_not be_empty
-
-          log_event = logs.last
-          log_hash = log_event.to_hash
-
-          expect(log_event.type).to eql("log")
-          expect(log_event.level).to eql(level.to_sym)
-          expect(log_event.body).to eql("Hello %s it is %s")
+          expect(sentry_logs).to_not be_empty
 
-          expect(log_hash[:body]).to eql("Hello Jane it is Monday")
+          log_event = sentry_logs.last
 
-          attributes = log_hash[:attributes]
-
-          expect(attributes["sentry.message.template"]).to eql({ value: "Hello %s it is %s", type: "string" })
-          expect(attributes["sentry.message.parameters.0"]).to eql({ value: "Jane", type: "string" })
-          expect(attributes["sentry.message.parameters.1"]).to eql({ value: "Monday", type: "string" })
+          expect(log_event[:level]).to eql(level)
+          expect(log_event[:body]).to eql("Hello Jane it is Monday")
+          expect(log_event[:attributes]["sentry.message.template"]).to eql({ value: "Hello %s it is %s", type: "string" })
+          expect(log_event[:attributes]["sentry.message.parameters.0"]).to eql({ value: "Jane", type: "string" })
+          expect(log_event[:attributes]["sentry.message.parameters.1"]).to eql({ value: "Monday", type: "string" })
         end
 
         it "logs with template parameters and extra attributres" do
           Sentry.logger.public_send(level, "Hello %s it is %s", ["Jane", "Monday"], extra: 312)
 
-          expect(logs).to_not be_empty
-
-          log_event = logs.last
-          log_hash = log_event.to_hash
-
-          expect(log_event.type).to eql("log")
-          expect(log_event.level).to eql(level.to_sym)
-          expect(log_event.body).to eql("Hello %s it is %s")
+          expect(sentry_logs).to_not be_empty
 
-          expect(log_hash[:body]).to eql("Hello Jane it is Monday")
+          log_event = sentry_logs.last
 
-          attributes = log_hash[:attributes]
-
-          expect(attributes[:extra]).to eql({ value: 312, type: "integer" })
-          expect(attributes["sentry.message.template"]).to eql({ value: "Hello %s it is %s", type: "string" })
-          expect(attributes["sentry.message.parameters.0"]).to eql({ value: "Jane", type: "string" })
-          expect(attributes["sentry.message.parameters.1"]).to eql({ value: "Monday", type: "string" })
+          expect(log_event[:level]).to eql(level)
+          expect(log_event[:body]).to eql("Hello Jane it is Monday")
+          expect(log_event[:attributes][:extra]).to eql({ value: 312, type: "integer" })
+          expect(log_event[:attributes]["sentry.message.template"]).to eql({ value: "Hello %s it is %s", type: "string" })
+          expect(log_event[:attributes]["sentry.message.parameters.0"]).to eql({ value: "Jane", type: "string" })
+          expect(log_event[:attributes]["sentry.message.parameters.1"]).to eql({ value: "Monday", type: "string" })
         end
 
         it "logs with hash-based template parameters" do
           Sentry.logger.public_send(level, "Hello %{name}, it is %{day}", name: "Jane", day: "Monday")
 
-          expect(logs).to_not be_empty
-
-          log_event = logs.last
-          log_hash = log_event.to_hash
-
-          expect(log_event.type).to eql("log")
-          expect(log_event.level).to eql(level.to_sym)
-          expect(log_event.body).to eql("Hello %{name}, it is %{day}")
-
-          expect(log_hash[:body]).to eql("Hello Jane, it is Monday")
+          expect(sentry_logs).to_not be_empty
 
-          attributes = log_hash[:attributes]
+          log_event = sentry_logs.last
 
-          expect(attributes["sentry.message.template"]).to eql({ value: "Hello %{name}, it is %{day}", type: "string" })
-          expect(attributes["sentry.message.parameters.name"]).to eql({ value: "Jane", type: "string" })
-          expect(attributes["sentry.message.parameters.day"]).to eql({ value: "Monday", type: "string" })
+          expect(log_event[:level]).to eql(level)
+          expect(log_event[:body]).to eql("Hello Jane, it is Monday")
+          expect(log_event[:attributes]["sentry.message.template"]).to eql({ value: "Hello %{name}, it is %{day}", type: "string" })
+          expect(log_event[:attributes]["sentry.message.parameters.name"]).to eql({ value: "Jane", type: "string" })
+          expect(log_event[:attributes]["sentry.message.parameters.day"]).to eql({ value: "Monday", type: "string" })
         end
 
         it "logs with hash-based template parameters and extra attributes" do
           Sentry.logger.public_send(level, "Hello %{name}, it is %{day}", name: "Jane", day: "Monday", user_id: 123)
 
-          expect(logs).to_not be_empty
-
-          log_event = logs.last
-          log_hash = log_event.to_hash
-
-          expect(log_event.type).to eql("log")
-          expect(log_event.level).to eql(level.to_sym)
-          expect(log_event.body).to eql("Hello %{name}, it is %{day}")
-
-          expect(log_hash[:body]).to eql("Hello Jane, it is Monday")
+          expect(sentry_logs).to_not be_empty
 
-          attributes = log_hash[:attributes]
+          log_event = sentry_logs.last
 
-          expect(attributes[:user_id]).to eql({ value: 123, type: "integer" })
-          expect(attributes["sentry.message.template"]).to eql({ value: "Hello %{name}, it is %{day}", type: "string" })
-          expect(attributes["sentry.message.parameters.name"]).to eql({ value: "Jane", type: "string" })
-          expect(attributes["sentry.message.parameters.day"]).to eql({ value: "Monday", type: "string" })
+          expect(log_event[:level]).to eql(level)
+          expect(log_event[:body]).to eql("Hello Jane, it is Monday")
+          expect(log_event[:attributes][:user_id]).to eql({ value: 123, type: "integer" })
+          expect(log_event[:attributes]["sentry.message.template"]).to eql({ value: "Hello %{name}, it is %{day}", type: "string" })
+          expect(log_event[:attributes]["sentry.message.parameters.name"]).to eql({ value: "Jane", type: "string" })
+          expect(log_event[:attributes]["sentry.message.parameters.day"]).to eql({ value: "Monday", type: "string" })
         end
       end
     end