From 02a7cda4a112d003460aa4045b809e32e0795023 Mon Sep 17 00:00:00 2001 From: Petr Heinz Date: Wed, 30 Sep 2026 19:56:05 +0200 Subject: [PATCH 1/3] Add failing tests: reconnect backoff after a refused connection The HTTP device's outlet thread reconnects immediately after a refused or dropped connection, which spins a CPU core at thousands of connection attempts per second while the ingesting host is unreachable. These tests pin the intended behaviour: - after each failed connection the outlet waits 1, 2, 4, 8, 16, then 30 seconds before reconnecting; - a request failing on an open connection waits the same way and is still dropped after 3 attempts; - a delivered request starts the wait over at 1 second; - close stops the outlet at once while it waits. A config spec pins that reading the unset debug logger does not warn under ruby -w (Ruby before 3.0), which the outlet does on every attempt. Co-Authored-By: Claude Opus 5.5 --- spec/logtail/config_spec.rb | 16 ++++++ spec/logtail/log_devices/http_spec.rb | 80 +++++++++++++++++++++++++++ 2 files changed, 96 insertions(+) create mode 100644 spec/logtail/config_spec.rb diff --git a/spec/logtail/config_spec.rb b/spec/logtail/config_spec.rb new file mode 100644 index 0000000..ad4a9c0 --- /dev/null +++ b/spec/logtail/config_spec.rb @@ -0,0 +1,16 @@ +require "spec_helper" + +describe Logtail::Config do + describe "#debug_logger" do + # Ruby before 3.0 warns under `ruby -w` when an unset instance variable is read, and the + # HTTP device reads the debug logger on every connection attempt. + it "can be read before it is set without an uninitialized instance variable warning" do + config = described_class.send(:new) + verbose, $VERBOSE = $VERBOSE, true + + expect { config.debug_logger }.not_to output.to_stderr + ensure + $VERBOSE = verbose + end + end +end diff --git a/spec/logtail/log_devices/http_spec.rb b/spec/logtail/log_devices/http_spec.rb index 9ae0743..4d3bc03 100755 --- a/spec/logtail/log_devices/http_spec.rb +++ b/spec/logtail/log_devices/http_spec.rb @@ -148,6 +148,86 @@ http.close end + + context "when connecting or delivering fails" do + # Raised from the stubs below to leave the outlet's endless loop. It is not a + # StandardError, so the outlet's own `rescue => e` lets it through. + let(:stop_outlet) { Class.new(Exception) } + let(:http_device) { described_class.new("MYKEY", flush_continuously: false, requests_per_conn: 1) } + let(:request_queue) { http_device.instance_variable_get(:@request_queue) } + let(:waits) { [] } + + before do + allow(http_device).to receive(:sleep) { |seconds| waits << seconds } + end + + it "waits before reconnecting, twice as long after every refused connection, up to 30 seconds" do + connection_attempts = 0 + allow_any_instance_of(Net::HTTP).to receive(:start) do + connection_attempts += 1 + raise stop_outlet if connection_attempts > 7 + raise Errno::ECONNREFUSED + end + + expect { http_device.send(:request_outlet) }.to raise_error(stop_outlet) + expect(waits).to eq([1, 2, 4, 8, 16, 30, 30]) + end + + it "waits the same way when a request fails on an open connection, and still drops it after 3 attempts" do + request_queue.enq(Logtail::LogDevices::HTTP::RequestAttempt.new(Net::HTTP::Post.new("/"))) + request_attempts = 0 + allow_any_instance_of(Net::HTTP).to receive(:request) do + request_attempts += 1 + raise Errno::ECONNRESET + end + allow(http_device).to receive(:sleep) do |seconds| + waits << seconds + raise stop_outlet if waits.size == 3 + end + + expect { http_device.send(:request_outlet) }.to raise_error(stop_outlet) + expect(waits).to eq([1, 2, 4]) + expect(request_attempts).to eq(3) + expect(request_queue.size).to eq(0) + end + + it "starts over at 1 second once a request is delivered" do + request_queue.enq(Logtail::LogDevices::HTTP::RequestAttempt.new(Net::HTTP::Post.new("/"))) + connection = double("connection", request: double("response", code: "202")) + connections = [:refused, :refused, :delivers, :refused, :refused] + allow_any_instance_of(Net::HTTP).to receive(:start) do |_http, &block| + case connections.shift + when :refused then raise Errno::ECONNREFUSED + when :delivers then block.call(connection) + else raise stop_outlet + end + end + + expect { http_device.send(:request_outlet) }.to raise_error(stop_outlet) + expect(waits).to eq([1, 2, 1, 2]) + end + end + + it "lets close stop the outlet while it waits to reconnect" do + connection_attempts = 0 + allow_any_instance_of(Net::HTTP).to receive(:start) do + connection_attempts += 1 + raise Errno::ECONNREFUSED + end + http_device = described_class.new("MYKEY") + http_device.send(:ensure_flush_threads_are_started) + outlet = http_device.instance_variable_get(:@request_outlet_thread) + 100.times do + break if connection_attempts > 0 && outlet.status == "sleep" + sleep 0.01 + end + + closing = Process.clock_gettime(Process::CLOCK_MONOTONIC) + http_device.close + expect(Process.clock_gettime(Process::CLOCK_MONOTONIC) - closing).to be < 0.5 + expect(outlet).not_to be_alive + expect(connection_attempts).to eq(1) + end end describe "#deliver_requests" do From e95393180d1b80a00b577cc5f949b7cd4c5099bb Mon Sep 17 00:00:00 2001 From: Petr Heinz Date: Wed, 30 Sep 2026 19:58:07 +0200 Subject: [PATCH 2/3] Back off between failed connection attempts in the HTTP outlet When the ingesting host refused or dropped the connection, the outlet thread reconnected at once, in a busy loop: thousands of connection attempts per second on one CPU core for as long as the host stayed unreachable. The outlet now waits before reconnecting after a failed connection, be it an exception from Net::HTTP#start or a request that failed on an open connection (deliver_requests returning false): 1 second, doubling on every consecutive failure up to 30 seconds. A delivered request starts the wait over at 1 second. Requests are still re-queued and dropped after 3 attempts. close kills the outlet thread, which interrupts the sleep, so it does not wait for the backoff. Logtail::Config initialises @debug_logger to nil, so reading the unset debug logger, which the outlet does on every attempt, no longer warns under ruby -w on Ruby before 3.0. Co-Authored-By: Claude Opus 5.5 --- lib/logtail/config.rb | 4 ++++ lib/logtail/log_devices/http.rb | 18 ++++++++++++++++-- 2 files changed, 20 insertions(+), 2 deletions(-) diff --git a/lib/logtail/config.rb b/lib/logtail/config.rb index 4e75a97..1736522 100755 --- a/lib/logtail/config.rb +++ b/lib/logtail/config.rb @@ -32,6 +32,10 @@ def call(severity, timestamp, progname, msg) attr_writer :http_body_limit + def initialize + @debug_logger = nil + end + # Whether a particular {Logtail::LogEntry} should be sent to Better Stack def send_to_better_stack?(log_entry) !@better_stack_filters&.any? { |blocker| blocker.call(log_entry) } diff --git a/lib/logtail/log_devices/http.rb b/lib/logtail/log_devices/http.rb index 48b6edf..eeb6c7a 100755 --- a/lib/logtail/log_devices/http.rb +++ b/lib/logtail/log_devices/http.rb @@ -22,6 +22,8 @@ class HTTP DEFAULT_INGESTING_SCHEME = "https".freeze CONTENT_TYPE = "application/msgpack".freeze USER_AGENT = "Logtail Ruby/#{Logtail::VERSION} (HTTP)".freeze + INITIAL_RECONNECT_WAIT = 1 # second + MAX_RECONNECT_WAIT = 30 # seconds # Instantiates a new HTTP log device that can be passed to {Logtail::Logger#initialize}. # @@ -83,6 +85,7 @@ def initialize(source_token, options = {}) @request_queue = options[:request_queue] || FlushableDroppingSizedQueue.new(25) @successive_error_count = 0 @requests_in_flight = 0 + @reconnect_wait = INITIAL_RECONNECT_WAIT end # Write a new log line message to the buffer, and flush asynchronously if the @@ -298,15 +301,19 @@ def build_http http end - # Creates a loop that processes the `@request_queue` on an interval. + # Creates a loop that processes the `@request_queue` on an interval. After a failed + # connection it waits before reconnecting, twice as long after every consecutive + # failure up to {MAX_RECONNECT_WAIT}, so an unreachable host is not retried in a busy + # loop. A delivered request starts the wait over (see {#deliver_requests}). def request_outlet loop do http = build_http + connection_healthy = false begin Logtail::Config.instance.debug { "Starting HTTP connection" } - http.start do |conn| + connection_healthy = http.start do |conn| deliver_requests(conn) end rescue => e @@ -315,6 +322,12 @@ def request_outlet Logtail::Config.instance.debug { "Finishing HTTP connection" } http.finish if http.started? end + + next if connection_healthy + + Logtail::Config.instance.debug { "Reconnecting in #{@reconnect_wait} seconds" } + sleep(@reconnect_wait) + @reconnect_wait = [@reconnect_wait * 2, MAX_RECONNECT_WAIT].min end end @@ -360,6 +373,7 @@ def deliver_requests(conn) num_reqs += 1 @last_resp = resp + @reconnect_wait = INITIAL_RECONNECT_WAIT Logtail::Config.instance.debug do if resp.code == "202" From 2bd7a738e6b0522770fb4150fb8b78740fd9b96a Mon Sep 17 00:00:00 2001 From: Petr Heinz Date: Wed, 30 Sep 2026 20:00:17 +0200 Subject: [PATCH 3/3] Give the close spec up to 5 s for the outlet's first attempt A cold TruffleRuby can take a while to run the new thread's first connection attempt; the 1 s poll left little headroom on CI. Co-Authored-By: Claude Opus 5.5 --- spec/logtail/log_devices/http_spec.rb | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/spec/logtail/log_devices/http_spec.rb b/spec/logtail/log_devices/http_spec.rb index 4d3bc03..2f6ac4e 100755 --- a/spec/logtail/log_devices/http_spec.rb +++ b/spec/logtail/log_devices/http_spec.rb @@ -217,7 +217,8 @@ http_device = described_class.new("MYKEY") http_device.send(:ensure_flush_threads_are_started) outlet = http_device.instance_variable_get(:@request_outlet_thread) - 100.times do + # Up to 5 seconds for the thread's first attempt, which is slow on a cold TruffleRuby. + 500.times do break if connection_attempts > 0 && outlet.status == "sleep" sleep 0.01 end