From 752fa0fac19b75839c6328b63870faec6e804abe Mon Sep 17 00:00:00 2001 From: Petr Heinz Date: Thu, 1 Oct 2026 18:51:59 +0200 Subject: [PATCH 01/14] Add failing tests for fork safety and Logger#flush After a fork, the child keeps the queues it inherited, so the lines the parent buffered before forking are sent by the parent and again by every child. A child that leaves with exit! loses its lines, and there is no Logger#flush to call first. HTTP#flush waits 20 seconds for an outlet thread that never runs with flush_continuously: false, and delivers nothing. The fork tests run logtail in a separate Ruby process against a local ingesting server and skip where fork isn't available. Co-Authored-By: Claude Opus 5.5 --- spec/logtail/log_devices/http_fork_spec.rb | 56 +++++++++++++++ spec/logtail/log_devices/http_spec.rb | 29 ++++++++ spec/logtail/logger_spec.rb | 24 +++++++ spec/spec_helper.rb | 1 + spec/support/processes.rb | 82 ++++++++++++++++++++++ 5 files changed, 192 insertions(+) create mode 100644 spec/logtail/log_devices/http_fork_spec.rb create mode 100644 spec/support/processes.rb diff --git a/spec/logtail/log_devices/http_fork_spec.rb b/spec/logtail/log_devices/http_fork_spec.rb new file mode 100644 index 0000000..4bb7c5b --- /dev/null +++ b/spec/logtail/log_devices/http_fork_spec.rb @@ -0,0 +1,56 @@ +require "spec_helper" + +# Forking servers and job runners (Puma, Unicorn, Resque) fork after the app logged. These run +# logtail in a real process that forks, and count what reaches a local ingesting server. +describe Logtail::LogDevices::HTTP, "after a fork" do + let(:ingest) { LocalIngestServer.new } + + before do + skip "needs fork" if !Process.respond_to?(:fork) || RUBY_ENGINE == "truffleruby" + end + + after { ingest.stop } + + it "delivers the lines the parent logged before forking once, not once per process" do + result = run_ruby(<<-RUBY) + require "logtail" + logger = Logtail::Logger.new(Logtail::LogDevices::HTTP.new("token", flush_interval: 60, #{ingest.device_options})) + logger.info("parent line before the fork") + 2.times.map { |n| fork { logger.info("child line " + n.to_s) } }.each { |pid| Process.wait(pid) } + RUBY + + expect(result.status).to be_success, result.stderr + expect(ingest.messages).to contain_exactly("parent line before the fork", "child line 0", "child line 1") + end + + it "delivers the lines a forked child logs" do + result = run_ruby(<<-RUBY) + require "logtail" + logger = Logtail::Logger.new(Logtail::LogDevices::HTTP.new("token", flush_interval: 60, #{ingest.device_options})) + Process.wait(fork { 3.times { |n| logger.info("child line " + n.to_s) } }) + logger.info("parent line after the fork") + RUBY + + expect(result.status).to be_success, result.stderr + expect(ingest.messages).to contain_exactly("child line 0", "child line 1", "child line 2", "parent line after the fork") + end + + it "delivers a child's lines when it calls flush before leaving with exit!, which skips at_exit hooks" do + result = run_ruby(<<-RUBY) + require "logtail" + logger = Logtail::Logger.new(Logtail::LogDevices::HTTP.new("token", flush_interval: 60, #{ingest.device_options})) + logger.info("parent line") + Process.wait(fork do + begin + logger.info("child line") + logger.flush + ensure + exit!(0) # the way Resque ends a job's process + end + end) + RUBY + + expect(result.status).to be_success, result.stderr + expect(ingest.messages).to contain_exactly("parent line", "child line") + end +end diff --git a/spec/logtail/log_devices/http_spec.rb b/spec/logtail/log_devices/http_spec.rb index 2f6ac4e..7e72b11 100755 --- a/spec/logtail/log_devices/http_spec.rb +++ b/spec/logtail/log_devices/http_spec.rb @@ -84,6 +84,35 @@ http.send(:flush) http.close end + + it "delivers in the calling thread when no outlet thread runs" do + messages = [] + stub = stub_request(:post, "https://in.logs.betterstack.com/").with do |request| + messages.concat(MessagePack.unpack(Zlib::Inflate.inflate(request.body)).map { |line| line["message"] }) + end + http = described_class.new("MYKEY", flush_continuously: false) + http.write(Logtail::LogEntry.new("INFO", time, nil, "test log message 1", nil, nil)) + http.write(Logtail::LogEntry.new("INFO", time, nil, "test log message 2", nil, nil)) + + http.flush + + expect(stub).to have_been_requested.once + expect(messages).to eq(["test log message 1", "test log message 2"]) + http.close + end + + it "waits about 5 seconds at most for the outlet thread to deliver" do + allow_any_instance_of(Net::HTTP).to receive(:request) { sleep } # Better Stack never answers + http = described_class.new("MYKEY") + http.write(Logtail::LogEntry.new("INFO", time, nil, "test log message", nil, nil)) + + flushing = Process.clock_gettime(Process::CLOCK_MONOTONIC) + http.flush + expect(Process.clock_gettime(Process::CLOCK_MONOTONIC) - flushing).to be_between(4, 7) + + http.instance_variable_get(:@flush_thread).kill.join + http.instance_variable_get(:@request_outlet_thread).kill.join + end end # Testing a private method because it helps break down our tests diff --git a/spec/logtail/logger_spec.rb b/spec/logtail/logger_spec.rb index 25748cf..043468a 100755 --- a/spec/logtail/logger_spec.rb +++ b/spec/logtail/logger_spec.rb @@ -197,6 +197,30 @@ end end + describe "#flush" do + let(:device) { Logtail::LogDevices::HTTP.new("my_source_token") } + let(:extra_device) { Logtail::LogDevices::HTTP.new("my_source_token") } + let(:logger) { Logtail::Logger.new(device, extra_device) } + + it "flushes the log devices, so that what was logged is delivered" do + expect(device).to receive(:flush) + expect(extra_device).to receive(:flush) + logger.flush + end + + it "returns right away when Rails flushes it after every request" do + # Stands in for ActiveSupport::LogSubscriber.flush_all!, which calls Rails.logger.flush + log_subscriber = Module.new do + def self.flush_all!(logger) + logger.flush + end + end + expect(device).not_to receive(:flush) + expect(extra_device).not_to receive(:flush) + log_subscriber.flush_all!(logger) + end + end + describe "#formatter=" do it "should not allow changing the formatter when the device is HTTP" do http_device = Logtail::LogDevices::HTTP.new("source_token") diff --git a/spec/spec_helper.rb b/spec/spec_helper.rb index a16418e..36a96a7 100644 --- a/spec/spec_helper.rb +++ b/spec/spec_helper.rb @@ -12,6 +12,7 @@ require File.join(File.dirname(__FILE__), 'support', 'timecop') require File.join(File.dirname(__FILE__), 'support', 'webmock') require File.join(File.dirname(__FILE__), 'support', 'logtail') +require File.join(File.dirname(__FILE__), 'support', 'processes') RSpec::Support::ObjectFormatter.default_instance.max_formatted_output_length = 5_000 diff --git a/spec/support/processes.rb b/spec/support/processes.rb new file mode 100644 index 0000000..15332fe --- /dev/null +++ b/spec/support/processes.rb @@ -0,0 +1,82 @@ +require "msgpack" +require "rbconfig" +require "socket" +require "tmpdir" +require "zlib" + +# A local stand-in for the Better Stack ingesting host, for tests that run logtail in a separate +# process: it answers every request with 202 and records the message of every line it receives. +class LocalIngestServer + def initialize + @server = TCPServer.new("127.0.0.1", 0) + @messages = [] + @lock = Mutex.new + @connections = [] + @thread = Thread.new do + loop { @connections << Thread.new(@server.accept) { |socket| serve(socket) } } + end + end + + # The options for Logtail::LogDevices::HTTP.new that deliver to this server, as Ruby code. + def device_options + %(ingesting_host: "127.0.0.1", ingesting_port: #{@server.addr[1]}, ingesting_scheme: "http") + end + + def messages + @lock.synchronize { @messages.dup } + end + + def stop + @thread.kill.join + @connections.each { |connection| connection.kill.join } + @server.close + end + + private + + def serve(socket) + while socket.gets + headers = {} + while (header = socket.gets) && header != "\r\n" + name, value = header.split(":", 2) + headers[name.downcase] = value.strip + end + lines = MessagePack.unpack(Zlib::Inflate.inflate(socket.read(headers["content-length"].to_i))) + @lock.synchronize { @messages.concat(lines.map { |line| line["message"] }) } + socket.write("HTTP/1.1 202 Accepted\r\nContent-Length: 0\r\n\r\n") + end + rescue IOError, SystemCallError + ensure + socket.close + end +end + +module ProcessHelpers + ProcessResult = Struct.new(:stdout, :stderr, :status) + + # Runs the Ruby script in a new process with logtail from lib/ and waits for it to exit, at + # most `timeout` seconds (generous: TruffleRuby starts slowly on CI). + def run_ruby(script, timeout: 120) + Dir.mktmpdir do |dir| + File.write(File.join(dir, "script.rb"), script) + lib = File.expand_path("../../lib", __dir__) + pid = Process.spawn(RbConfig.ruby, "-I", lib, File.join(dir, "script.rb"), + out: File.join(dir, "stdout"), err: File.join(dir, "stderr")) + deadline = Process.clock_gettime(Process::CLOCK_MONOTONIC) + timeout + status = nil + until (status = Process.waitpid2(pid, Process::WNOHANG)) + if Process.clock_gettime(Process::CLOCK_MONOTONIC) > deadline + Process.kill("KILL", pid) + Process.wait(pid) + raise "The Ruby process didn't exit within #{timeout} seconds:\n#{File.read(File.join(dir, "stderr"))}" + end + sleep 0.05 + end + ProcessResult.new(File.read(File.join(dir, "stdout")), File.read(File.join(dir, "stderr")), status[1]) + end + end +end + +RSpec.configure do |config| + config.include ProcessHelpers +end From 79c02685f7c1c3328aded5942a33ea8724c3b31e Mon Sep 17 00:00:00 2001 From: Petr Heinz Date: Thu, 1 Oct 2026 18:56:33 +0200 Subject: [PATCH 02/14] Read the lines of a synchronous flush once per request in its test WebMock runs a stub's `with` block again when have_been_requested checks it, so the test recorded every line twice. The response block runs once per request. 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 7e72b11..75298e9 100755 --- a/spec/logtail/log_devices/http_spec.rb +++ b/spec/logtail/log_devices/http_spec.rb @@ -87,8 +87,9 @@ it "delivers in the calling thread when no outlet thread runs" do messages = [] - stub = stub_request(:post, "https://in.logs.betterstack.com/").with do |request| + stub = stub_request(:post, "https://in.logs.betterstack.com/").to_return do |request| messages.concat(MessagePack.unpack(Zlib::Inflate.inflate(request.body)).map { |line| line["message"] }) + { status: 202 } end http = described_class.new("MYKEY", flush_continuously: false) http.write(Logtail::LogEntry.new("INFO", time, nil, "test log message 1", nil, nil)) From 10e1b052bd8d7dfa674cdca5b31bcf1eb29cb2b9 Mon Sep 17 00:00:00 2001 From: Petr Heinz Date: Thu, 1 Oct 2026 18:56:33 +0200 Subject: [PATCH 03/14] Start over in forked processes, and add Logger#flush After a fork the HTTP device kept the queues it inherited and restarted its threads, so each child sent the lines the parent had buffered before forking, which the parent sent as well. - The device remembers the pid that owns its queues and threads. When another process writes, flushes or closes it, it starts over there with empty queues and no threads; they start when the child logs. A plain Process.pid check, so it works on Ruby 2.5 and TruffleRuby. - Logger#flush flushes the logger's devices. HTTP#flush waits about 5 seconds for the outlet thread (it was 20), and when no outlet thread runs (flush_continuously: false, a child that hasn't logged) it delivers in the calling thread with 2-second timeouts. - Rails calls Rails.logger.flush after every request (ActiveSupport::LogSubscriber.flush_all!), so that call returns right away instead of waiting for delivery. Co-Authored-By: Claude Opus 5.5 --- lib/logtail/log_devices/http.rb | 72 +++++++++++++++++++++++++++++++-- lib/logtail/logger.rb | 15 +++++++ 2 files changed, 83 insertions(+), 4 deletions(-) diff --git a/lib/logtail/log_devices/http.rb b/lib/logtail/log_devices/http.rb index eeb6c7a..c3dbd32 100755 --- a/lib/logtail/log_devices/http.rb +++ b/lib/logtail/log_devices/http.rb @@ -24,6 +24,7 @@ class HTTP USER_AGENT = "Logtail Ruby/#{Logtail::VERSION} (HTTP)".freeze INITIAL_RECONNECT_WAIT = 1 # second MAX_RECONNECT_WAIT = 30 # seconds + SYNCHRONOUS_DELIVERY_TIMEOUT = 2 # seconds, to connect and to read the response # Instantiates a new HTTP log device that can be passed to {Logtail::Logger#initialize}. # @@ -81,6 +82,9 @@ def initialize(source_token, options = {}) @flush_continuously = options[:flush_continuously] != false @flush_interval = options[:flush_interval] || 2 # 2 seconds @requests_per_conn = options[:requests_per_conn] || 2_500 + # The process that owns the queues and threads, see {#reset_if_forked} + @pid = Process.pid + @fork_lock = Mutex.new @msg_queue = FlushableDroppingSizedQueue.new(@batch_size) @request_queue = options[:request_queue] || FlushableDroppingSizedQueue.new(25) @successive_error_count = 0 @@ -94,6 +98,7 @@ def initialize(source_token, options = {}) # of this. Hence the `@request_queue`. def write(msg) return unless Logtail.config.send_to_better_stack?(msg) + reset_if_forked @msg_queue.enq(msg) @@ -111,11 +116,18 @@ def write(msg) end # Flush all log messages in the buffer synchronously. This method will not return - # until delivery of the messages has been successful. If you want to flush + # until delivery of the messages has been successful, or about 5 seconds have passed. + # When no outlet thread runs (`flush_continuously: false`, or a forked child that hasn't + # logged yet), the messages are delivered in the calling thread. If you want to flush # asynchronously see {#flush_async}. def flush + reset_if_forked flush_async - wait_on_request_queue + if @request_outlet_thread && @request_outlet_thread.alive? + wait_on_request_queue + else + deliver_synchronously + end true end @@ -200,6 +212,26 @@ def ensure_flush_threads_are_started end end + # The queues and threads belong to the process that created them. After a fork, the + # parent still delivers the lines it buffered, so a child that kept them would send them + # again, and the parent's threads don't run in the child. The child starts over with + # empty queues and starts its own threads once it logs. + def reset_if_forked + return if @pid == Process.pid + + @fork_lock.synchronize do + return if @pid == Process.pid + + @msg_queue = FlushableDroppingSizedQueue.new(@batch_size) + # The request queue can be a SizedQueue passed as the :request_queue option + @request_queue.respond_to?(:flush) ? @request_queue.flush : @request_queue.clear + @flush_thread = @request_outlet_thread = nil + @requests_in_flight = 0 + @reconnect_wait = INITIAL_RECONNECT_WAIT + @pid = Process.pid + end + end + # Builds an HTTP request based on the current messages queued. def build_request(msgs) path = '/' @@ -241,11 +273,43 @@ def flush_async end end + # Delivers the requests on the request queue in the calling thread, for when no outlet + # thread does. Returns whether all of them were delivered; errors only go to the debug log. + def deliver_synchronously + http = nil + while @request_queue.size > 0 && (request_attempt = @request_queue.deq) + http ||= start_synchronous_connection + @last_resp = http.request(request_attempt.request) + end + true + rescue => e + Logtail::Config.instance.debug { "Synchronous delivery failed: #{e.message}" } + false + ensure + http.finish if http && http.started? + end + + # Connects with short timeouts. While Ruby shuts down it refuses new threads, and + # Net::HTTP (before Ruby 4.0) needs one to time out connecting, so then it connects + # without a timeout, but only to a host that has answered before. + def start_synchronous_connection + http = build_http + http.open_timeout = http.read_timeout = SYNCHRONOUS_DELIVERY_TIMEOUT + begin + http.start + rescue ThreadError + raise if @last_resp.nil? + http.open_timeout = nil + http.start + end + http + end + # Waits on the request queue. This is used in {#flush} to ensure # the log data has been delivered before returning. def wait_on_request_queue - # Wait 20 seconds - 40.times do |i| + # Wait 5 seconds + 10.times do |i| if @request_queue.size == 0 && @requests_in_flight == 0 Logtail::Config.instance.debug { "Request queue is empty and no requests are in flight, finish waiting" } return true diff --git a/lib/logtail/logger.rb b/lib/logtail/logger.rb index c2dc67f..35ac59f 100755 --- a/lib/logtail/logger.rb +++ b/lib/logtail/logger.rb @@ -216,6 +216,21 @@ def level=(value) super end + # Delivers what was logged so far before it returns, waiting about 5 seconds at most with + # the HTTP log device. Call it before a process ends with `exit!`, which skips the at_exit + # hook that delivers the rest, as Resque's forked job processes do. + # + # Rails calls `flush` on Rails.logger after every request (ActiveSupport::LogSubscriber.flush_all!). + # Waiting there would hold up every request, so that call returns right away and the lines + # are delivered in the background as usual. + def flush + return true if caller_locations(1, 10).any? { |location| location.base_label == "flush_all!" } + + @logdev.dev.flush if @logdev && @logdev.dev.respond_to?(:flush) + @extra_loggers.each { |logger| logger.flush if logger.respond_to?(:flush) } + true + end + # @private def with_context(context, &block) Logtail::CurrentContext.with(context, &block) From d3df7583f35e9adbafcce3d451ad6e5187225781 Mon Sep 17 00:00:00 2001 From: Petr Heinz Date: Thu, 1 Oct 2026 19:04:38 +0200 Subject: [PATCH 04/14] Pass the requests to deliver_synchronously flush takes the queued requests off the request queue and hands them over, so the helper only sends what it's given and can also send lines that never went through the request queue. It's the same helper as in the fast-shutdown PR, which sends lines written after close with it. Co-Authored-By: Claude Opus 5.5 --- lib/logtail/log_devices/http.rb | 46 ++++++++++++++++++--------------- 1 file changed, 25 insertions(+), 21 deletions(-) diff --git a/lib/logtail/log_devices/http.rb b/lib/logtail/log_devices/http.rb index c3dbd32..1d58686 100755 --- a/lib/logtail/log_devices/http.rb +++ b/lib/logtail/log_devices/http.rb @@ -126,7 +126,7 @@ def flush if @request_outlet_thread && @request_outlet_thread.alive? wait_on_request_queue else - deliver_synchronously + deliver_synchronously(dequeue_requests) end true end @@ -232,6 +232,16 @@ def reset_if_forked end end + # Takes the queued requests off the request queue, for {#flush} when no outlet thread + # runs. It checks the size first because a SizedQueue (see :request_queue) blocks when empty. + def dequeue_requests + requests = [] + while @request_queue.size > 0 && (request_attempt = @request_queue.deq) + requests << request_attempt.request + end + requests + end + # Builds an HTTP request based on the current messages queued. def build_request(msgs) path = '/' @@ -273,36 +283,30 @@ def flush_async end end - # Delivers the requests on the request queue in the calling thread, for when no outlet - # thread does. Returns whether all of them were delivered; errors only go to the debug log. - def deliver_synchronously - http = nil - while @request_queue.size > 0 && (request_attempt = @request_queue.deq) - http ||= start_synchronous_connection - @last_resp = http.request(request_attempt.request) - end - true - rescue => e - Logtail::Config.instance.debug { "Synchronous delivery failed: #{e.message}" } - false - ensure - http.finish if http && http.started? - end + # Sends the requests in the calling thread, for when no outlet thread delivers them. + # Returns whether all of them were sent; errors only go to the debug log. + def deliver_synchronously(requests) + return true if requests.empty? - # Connects with short timeouts. While Ruby shuts down it refuses new threads, and - # Net::HTTP (before Ruby 4.0) needs one to time out connecting, so then it connects - # without a timeout, but only to a host that has answered before. - def start_synchronous_connection http = build_http http.open_timeout = http.read_timeout = SYNCHRONOUS_DELIVERY_TIMEOUT begin http.start rescue ThreadError + # While Ruby shuts down it refuses new threads, and Net::HTTP (before Ruby 4.0) needs + # one to time out connecting. Then it connects without a timeout, but only to a host + # that has answered before. raise if @last_resp.nil? http.open_timeout = nil http.start end - http + requests.each { |request| @last_resp = http.request(request) } + true + rescue => e + Logtail::Config.instance.debug { "Synchronous delivery failed: #{e.message}" } + false + ensure + http.finish if http && http.started? end # Waits on the request queue. This is used in {#flush} to ensure From 4215aa48d0b7f709d0d167a804f1cdc8d9ef0fad Mon Sep 17 00:00:00 2001 From: Petr Heinz Date: Thu, 1 Oct 2026 19:12:27 +0200 Subject: [PATCH 05/14] Test that a forked child that hasn't logged exits right away Before the fix, such a child closed the device at exit with the parent's buffered lines in its queue and no outlet thread to deliver them, and waited 20 seconds (checked against main: 20.07 s), like the idle cluster workers the red-team saw hang at shutdown. Co-Authored-By: Claude Opus 5.5 --- spec/logtail/log_devices/http_fork_spec.rb | 14 ++++++++++++++ 1 file changed, 14 insertions(+) diff --git a/spec/logtail/log_devices/http_fork_spec.rb b/spec/logtail/log_devices/http_fork_spec.rb index 4bb7c5b..644a42f 100644 --- a/spec/logtail/log_devices/http_fork_spec.rb +++ b/spec/logtail/log_devices/http_fork_spec.rb @@ -35,6 +35,20 @@ expect(ingest.messages).to contain_exactly("child line 0", "child line 1", "child line 2", "parent line after the fork") end + it "lets a child that hasn't logged exit right away, without waiting on the parent's lines" do + result = run_ruby(<<-RUBY) + require "logtail" + logger = Logtail::Logger.new(Logtail::LogDevices::HTTP.new("token", flush_interval: 60, #{ingest.device_options})) + logger.info("parent line before the fork") + forking = Process.clock_gettime(Process::CLOCK_MONOTONIC) + Process.wait(fork {}) + puts Process.clock_gettime(Process::CLOCK_MONOTONIC) - forking + RUBY + + expect(result.stdout.to_f).to be < 5 + expect(ingest.messages).to eq(["parent line before the fork"]) + end + it "delivers a child's lines when it calls flush before leaving with exit!, which skips at_exit hooks" do result = run_ruby(<<-RUBY) require "logtail" From e3be6de0ecbfecbe5e5e16eabd004d5fe1206281 Mon Sep 17 00:00:00 2001 From: Petr Heinz Date: Thu, 1 Oct 2026 19:30:14 +0200 Subject: [PATCH 06/14] Add a failing test for flush raising WebMock's error A synchronous flush only rescued StandardError, so an error outside it, like the one WebMock refuses connections with, escaped flush, and close at exit, and could turn a passing test suite's exit status into a failure. Co-Authored-By: Claude Opus 5.5 --- spec/logtail/log_devices/http_spec.rb | 9 +++++++++ 1 file changed, 9 insertions(+) diff --git a/spec/logtail/log_devices/http_spec.rb b/spec/logtail/log_devices/http_spec.rb index 75298e9..e400e35 100755 --- a/spec/logtail/log_devices/http_spec.rb +++ b/spec/logtail/log_devices/http_spec.rb @@ -102,6 +102,15 @@ http.close end + it "doesn't raise when delivering in the calling thread fails, whatever the error" do + http = described_class.new("MYKEY", flush_continuously: false) + http.write(Logtail::LogEntry.new("INFO", time, nil, "test log message", nil, nil)) + + # WebMock refuses to connect with an error that isn't a StandardError + expect { http.flush }.not_to raise_error + http.close + end + it "waits about 5 seconds at most for the outlet thread to deliver" do allow_any_instance_of(Net::HTTP).to receive(:request) { sleep } # Better Stack never answers http = described_class.new("MYKEY") From b88adcc1ce15876ec3e05cde00d261c402e1a57b Mon Sep 17 00:00:00 2001 From: Petr Heinz Date: Thu, 1 Oct 2026 19:30:14 +0200 Subject: [PATCH 07/14] Keep any error of a synchronous delivery out of the caller deliver_synchronously now rescues every Exception but signals and only writes it to the debug log, so logging can't raise into the app or fail an exit. Interrupt and other signals are raised as before. The helper stays the same as in the fast-shutdown PR. Co-Authored-By: Claude Opus 5.5 --- lib/logtail/log_devices/http.rb | 7 +++++-- 1 file changed, 5 insertions(+), 2 deletions(-) diff --git a/lib/logtail/log_devices/http.rb b/lib/logtail/log_devices/http.rb index 1d58686..dd600dc 100755 --- a/lib/logtail/log_devices/http.rb +++ b/lib/logtail/log_devices/http.rb @@ -284,7 +284,8 @@ def flush_async end # Sends the requests in the calling thread, for when no outlet thread delivers them. - # Returns whether all of them were sent; errors only go to the debug log. + # Returns whether all of them were sent. Errors only go to the debug log, also those that + # aren't StandardErrors (WebMock refuses to connect with one); signals are raised as usual. def deliver_synchronously(requests) return true if requests.empty? @@ -302,7 +303,9 @@ def deliver_synchronously(requests) end requests.each { |request| @last_resp = http.request(request) } true - rescue => e + rescue SignalException + raise + rescue Exception => e Logtail::Config.instance.debug { "Synchronous delivery failed: #{e.message}" } false ensure From 01699d1de87df1b41a28afed0584756c72b943f9 Mon Sep 17 00:00:00 2001 From: Petr Heinz Date: Fri, 2 Oct 2026 08:28:18 +0200 Subject: [PATCH 08/14] Add a failing test for a warning about @last_resp with warnings on When Net::HTTP can't start the thread that times out connecting, as while Ruby shuts down, deliver_synchronously checks @last_resp before anything set it, and Ruby 2.7 and older warn about that with -w. The test fails on the Ruby 2.5 to 2.7 jobs only, newer Rubies don't warn about this. Co-Authored-By: Claude Opus 5.5 --- spec/logtail/log_devices/http_spec.rb | 18 ++++++++++++++++++ 1 file changed, 18 insertions(+) diff --git a/spec/logtail/log_devices/http_spec.rb b/spec/logtail/log_devices/http_spec.rb index e400e35..f1466c7 100755 --- a/spec/logtail/log_devices/http_spec.rb +++ b/spec/logtail/log_devices/http_spec.rb @@ -111,6 +111,24 @@ http.close end + it "doesn't warn about @last_resp when it can't connect while Ruby shuts down, with warnings on" do + # Ruby 2.7 and older warn about an instance variable that is read before it's set + result = run_ruby(<<-RUBY) + $VERBOSE = true + require "logtail" + # Like Net::HTTP before Ruby 4.0 while Ruby shuts down: it can't start the thread that + # times out connecting + Net::HTTP.prepend(Module.new { def start(*); raise ThreadError, "can't alloc thread"; end }) + http = Logtail::LogDevices::HTTP.new("token", flush_continuously: false, ingesting_host: "127.0.0.1", ingesting_port: 1, ingesting_scheme: "http") + logger = Logtail::Logger.new(http) + logger.info("line") + logger.flush + RUBY + + expect(result.status).to be_success, result.stderr + expect(result.stderr).not_to include("@last_resp not initialized") + end + it "waits about 5 seconds at most for the outlet thread to deliver" do allow_any_instance_of(Net::HTTP).to receive(:request) { sleep } # Better Stack never answers http = described_class.new("MYKEY") From 012109151b2cc854252c3677cdd6b3e44b35c9ee Mon Sep 17 00:00:00 2001 From: Petr Heinz Date: Fri, 2 Oct 2026 08:28:48 +0200 Subject: [PATCH 09/14] Set @last_resp in initialize So Ruby 2.7 and older no longer warn that deliver_synchronously reads it before it's set. #58 sets it on the same line. Co-Authored-By: Claude Opus 5.5 --- lib/logtail/log_devices/http.rb | 1 + 1 file changed, 1 insertion(+) diff --git a/lib/logtail/log_devices/http.rb b/lib/logtail/log_devices/http.rb index dd600dc..6d3f269 100755 --- a/lib/logtail/log_devices/http.rb +++ b/lib/logtail/log_devices/http.rb @@ -89,6 +89,7 @@ def initialize(source_token, options = {}) @request_queue = options[:request_queue] || FlushableDroppingSizedQueue.new(25) @successive_error_count = 0 @requests_in_flight = 0 + @last_resp = nil @reconnect_wait = INITIAL_RECONNECT_WAIT end From e9b9c7a602c4c6cdb6fe2d6c521a0fa28dbb6f93 Mon Sep 17 00:00:00 2001 From: Petr Heinz Date: Fri, 2 Oct 2026 11:27:59 +0200 Subject: [PATCH 10/14] Test the flush shortcut with ActiveSupport's real LogSubscriber.flush_all! The test of the shortcut defined its own flush_all!, so an ActiveSupport that moves or renames the call would only show up as requests waiting for delivery. These run ActiveSupport's flush_all! in a subprocess, with a Logtail::Logger alone, in TaggedLogging and, from ActiveSupport 7.1, in a BroadcastLogger, against an ingesting host that holds its answers: flush_all! has to return within a second without delivering, where waiting would take 5 seconds, and flushing the same logger directly has to deliver. The Gemfile gets the same lines as in #53, so the two merge cleanly. Co-Authored-By: Claude Opus 5.5 --- Gemfile | 3 + spec/logtail/logger_flush_all_spec.rb | 82 +++++++++++++++++++++++++++ 2 files changed, 85 insertions(+) create mode 100644 spec/logtail/logger_flush_all_spec.rb diff --git a/Gemfile b/Gemfile index 0613134..40e12ed 100644 --- a/Gemfile +++ b/Gemfile @@ -9,3 +9,6 @@ gem "rake", "~> 13.0" gem "rspec", "~> 3.0" gem "base64" if RUBY_VERSION >= "3.4.0" + +# spec/logtail/json_encoding_spec.rb checks the JSON with ActiveSupport loaded +gem "activesupport" diff --git a/spec/logtail/logger_flush_all_spec.rb b/spec/logtail/logger_flush_all_spec.rb new file mode 100644 index 0000000..2d698ca --- /dev/null +++ b/spec/logtail/logger_flush_all_spec.rb @@ -0,0 +1,82 @@ +require "spec_helper" + +# Rails flushes Rails.logger after every request (Rails::Rack::Logger calls +# ActiveSupport::LogSubscriber.flush_all!), and Logger#flush returns right away for that call +# instead of waiting for delivery. These run ActiveSupport's real flush_all! in another process, so +# an ActiveSupport that calls flush differently fails here. The ingesting host holds its answers +# until the direct flush, so a flush_all! that waited for delivery would take 5 seconds. +describe Logtail::Logger, "#flush called by ActiveSupport::LogSubscriber.flush_all!" do + { + "a Logtail::Logger" => "logger", + "a Logtail::Logger in ActiveSupport::TaggedLogging" => "ActiveSupport::TaggedLogging.new(logger)", + "a Logtail::Logger in an ActiveSupport::BroadcastLogger, as Rails 7.1 and later wrap it" => + "ActiveSupport::BroadcastLogger.new(logger)", + "a Logtail::Logger in ActiveSupport::TaggedLogging in an ActiveSupport::BroadcastLogger" => + "ActiveSupport::BroadcastLogger.new(ActiveSupport::TaggedLogging.new(logger))" + }.each do |description, rails_logger| + it "returns right away for #{description}, and flushing it directly delivers" do + if rails_logger.include?("BroadcastLogger") && Gem.loaded_specs["activesupport"].version < Gem::Version.new("7.1") + skip "ActiveSupport::BroadcastLogger was added in ActiveSupport 7.1" + end + + result = run_ruby(<<-RUBY) + require "logger" # ActiveSupport 6.1 needs it loaded first since concurrent-ruby 1.3.5 + require "active_support" + require "active_support/log_subscriber" + require "active_support/tagged_logging" + require "json" + require "logtail" + + # The ingesting host keeps the lines of every request, but answers only once `answering` is set + delivered = [] + answering = false + server = TCPServer.new("127.0.0.1", 0) + Thread.new do + loop do + Thread.new(server.accept) do |socket| + while socket.gets + length = 0 + while (header = socket.gets) != "\\r\\n" + length = header.split(":")[1].to_i if header.downcase.start_with?("content-length:") + end + delivered.concat(MessagePack.unpack(Zlib::Inflate.inflate(socket.read(length))).map { |line| line["message"] }) + sleep 0.01 until answering + socket.write("HTTP/1.1 202 Accepted\\r\\nContent-Length: 0\\r\\n\\r\\n") + end + end + end + end + + # Logs a line for every request, like Rails' ActionController::LogSubscriber + class RequestLogSubscriber < ActiveSupport::LogSubscriber + def request(event) + info(event.payload[:message]) + end + end + RequestLogSubscriber.attach_to(:app) + + logger = Logtail::Logger.new(Logtail::LogDevices::HTTP.new("token", flush_interval: 60, + ingesting_host: "127.0.0.1", ingesting_port: server.addr[1], ingesting_scheme: "http")) + ActiveSupport::LogSubscriber.logger = #{rails_logger} + ActiveSupport::Notifications.instrument("request.app", message: "Completed 200 OK") + + flushing = Process.clock_gettime(Process::CLOCK_MONOTONIC) + ActiveSupport::LogSubscriber.flush_all! + flush_all_seconds = Process.clock_gettime(Process::CLOCK_MONOTONIC) - flushing + delivered_by_flush_all = delivered.dup + + answering = true + ActiveSupport::LogSubscriber.logger.flush + puts JSON.generate("flush_all_seconds" => flush_all_seconds, "delivered_by_flush_all" => delivered_by_flush_all, + "delivered_by_flush" => delivered.drop(delivered_by_flush_all.size)) + RUBY + + expect(result.status).to be_success, result.stderr + expect(JSON.parse(result.stdout)).to match( + "flush_all_seconds" => a_value < 1, + "delivered_by_flush_all" => [], + "delivered_by_flush" => ["Completed 200 OK"] + ) + end + end +end From 3b995ad30b613545cdcd0b12d9c5e0d159a2fe25 Mon Sep 17 00:00:00 2001 From: Petr Heinz Date: Fri, 2 Oct 2026 11:30:34 +0200 Subject: [PATCH 11/14] Add a failing test for flush delivering to a host that answers in 3 seconds When no outlet thread runs, flush delivers the queued requests in the calling thread. With the 2 second timeout a host that takes 3 seconds to answer fails the first request, and the one after it is dropped. This fails until the timeout is raised to 5 seconds. Co-Authored-By: Claude Opus 5.5 --- spec/logtail/log_devices/http_spec.rb | 30 +++++++++++++++++++++++++++ 1 file changed, 30 insertions(+) diff --git a/spec/logtail/log_devices/http_spec.rb b/spec/logtail/log_devices/http_spec.rb index f1466c7..fe40bcf 100755 --- a/spec/logtail/log_devices/http_spec.rb +++ b/spec/logtail/log_devices/http_spec.rb @@ -141,6 +141,36 @@ http.instance_variable_get(:@flush_thread).kill.join http.instance_variable_get(:@request_outlet_thread).kill.join end + + it "waits up to 5 seconds for a slow host when it delivers in the calling thread" do + # Takes 3 seconds to answer each request + slow_ingest = Class.new(LocalIngestServer) do + private + + def serve(socket) + def socket.write(*) + sleep 3 + super + end + super + end + end.new + result = run_ruby(<<-RUBY) + require "logtail" + # A request per line, which flush delivers as no outlet thread runs + http = Logtail::LogDevices::HTTP.new("token", flush_continuously: false, batch_size: 1, #{slow_ingest.device_options}) + logger = Logtail::Logger.new(http) + logger.info("first line") + logger.info("second line") + logger.flush + RUBY + + # A request that times out would drop the one after it + expect(result.status).to be_success, result.stderr + expect(slow_ingest.messages).to contain_exactly("first line", "second line") + ensure + slow_ingest.stop if slow_ingest + end end # Testing a private method because it helps break down our tests From 970f2c3ad966e9797f24e39a53f6697e40085e72 Mon Sep 17 00:00:00 2001 From: Petr Heinz Date: Fri, 2 Oct 2026 11:32:34 +0200 Subject: [PATCH 12/14] Give synchronous deliveries 5 seconds to connect and to get a response 2 seconds left little room for a slow network. 5 seconds matches how long flush waits for the outlet thread. #58 changes the same line the same way, so the two still merge cleanly. Co-Authored-By: Claude Opus 5.5 --- lib/logtail/log_devices/http.rb | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/lib/logtail/log_devices/http.rb b/lib/logtail/log_devices/http.rb index 6d3f269..baedec3 100755 --- a/lib/logtail/log_devices/http.rb +++ b/lib/logtail/log_devices/http.rb @@ -24,7 +24,7 @@ class HTTP USER_AGENT = "Logtail Ruby/#{Logtail::VERSION} (HTTP)".freeze INITIAL_RECONNECT_WAIT = 1 # second MAX_RECONNECT_WAIT = 30 # seconds - SYNCHRONOUS_DELIVERY_TIMEOUT = 2 # seconds, to connect and to read the response + SYNCHRONOUS_DELIVERY_TIMEOUT = 5 # seconds, to connect and to read the response # Instantiates a new HTTP log device that can be passed to {Logtail::Logger#initialize}. # From 18645706f53e404ac0f78c1f5e4aa307d08221d8 Mon Sep 17 00:00:00 2001 From: Petr Heinz Date: Fri, 2 Oct 2026 13:37:32 +0200 Subject: [PATCH 13/14] Add a failing test for a forked child whose parent closed the device With #58 merged, a device that was closed delivers each line on its own, and a forked child keeps the parent's closed state. So when the parent closes the device before forking, every line the child logs goes out as its own request. The local ingest server in the specs now records how many lines each request held. Co-Authored-By: Claude Opus 5.5 --- spec/logtail/log_devices/http_fork_spec.rb | 15 +++++++++++++++ spec/support/processes.rb | 13 +++++++++++-- 2 files changed, 26 insertions(+), 2 deletions(-) diff --git a/spec/logtail/log_devices/http_fork_spec.rb b/spec/logtail/log_devices/http_fork_spec.rb index 644a42f..da47dee 100644 --- a/spec/logtail/log_devices/http_fork_spec.rb +++ b/spec/logtail/log_devices/http_fork_spec.rb @@ -49,6 +49,21 @@ expect(ingest.messages).to eq(["parent line before the fork"]) end + it "batches a child's lines as usual when the parent closed the device before forking" do + result = run_ruby(<<-RUBY) + require "logtail" + logger = Logtail::Logger.new(Logtail::LogDevices::HTTP.new("token", flush_interval: 60, #{ingest.device_options})) + logger.info("parent line") + logger.close + Process.wait(fork { 3.times { |n| logger.info("child line " + n.to_s) } }) + RUBY + + expect(result.status).to be_success, result.stderr + expect(ingest.messages).to contain_exactly("parent line", "child line 0", "child line 1", "child line 2") + # Lines written after close are each delivered on their own, see Logtail::LogDevices::HTTP#write + expect(ingest.batch_sizes).to eq([1, 3]) + end + it "delivers a child's lines when it calls flush before leaving with exit!, which skips at_exit hooks" do result = run_ruby(<<-RUBY) require "logtail" diff --git a/spec/support/processes.rb b/spec/support/processes.rb index 15332fe..994ef21 100644 --- a/spec/support/processes.rb +++ b/spec/support/processes.rb @@ -5,11 +5,13 @@ require "zlib" # A local stand-in for the Better Stack ingesting host, for tests that run logtail in a separate -# process: it answers every request with 202 and records the message of every line it receives. +# process: it answers every request with 202 and records the message of every line it receives, +# and how many lines each request held. class LocalIngestServer def initialize @server = TCPServer.new("127.0.0.1", 0) @messages = [] + @batch_sizes = [] @lock = Mutex.new @connections = [] @thread = Thread.new do @@ -26,6 +28,10 @@ def messages @lock.synchronize { @messages.dup } end + def batch_sizes + @lock.synchronize { @batch_sizes.dup } + end + def stop @thread.kill.join @connections.each { |connection| connection.kill.join } @@ -42,7 +48,10 @@ def serve(socket) headers[name.downcase] = value.strip end lines = MessagePack.unpack(Zlib::Inflate.inflate(socket.read(headers["content-length"].to_i))) - @lock.synchronize { @messages.concat(lines.map { |line| line["message"] }) } + @lock.synchronize do + @messages.concat(lines.map { |line| line["message"] }) + @batch_sizes << lines.size + end socket.write("HTTP/1.1 202 Accepted\r\nContent-Length: 0\r\n\r\n") end rescue IOError, SystemCallError From c90b8dcb66d10838aa3645a79bf07a7e06e6b120 Mon Sep 17 00:00:00 2001 From: Petr Heinz Date: Fri, 2 Oct 2026 13:38:24 +0200 Subject: [PATCH 14/14] Open a device in a forked child that the parent closed reset_if_forked now also clears the closed state (and the failed late delivery), and close calls it first: the early return for a closed device otherwise skipped the reset, so a child's close of a device the parent had closed did nothing. Co-Authored-By: Claude Opus 5.5 --- lib/logtail/log_devices/http.rb | 5 ++++- 1 file changed, 4 insertions(+), 1 deletion(-) diff --git a/lib/logtail/log_devices/http.rb b/lib/logtail/log_devices/http.rb index 7a82482..926ab1e 100755 --- a/lib/logtail/log_devices/http.rb +++ b/lib/logtail/log_devices/http.rb @@ -155,6 +155,7 @@ def flush # Closes the log device, cleans up, and attempts one last delivery. Closing it again does # nothing; lines written after it are delivered right away (see {#write}). def close + reset_if_forked return if @closed @closed = true @@ -240,7 +241,8 @@ def ensure_flush_threads_are_started # The queues and threads belong to the process that created them. After a fork, the # parent still delivers the lines it buffered, so a child that kept them would send them # again, and the parent's threads don't run in the child. The child starts over with - # empty queues and starts its own threads once it logs. + # empty queues and starts its own threads once it logs, also when the parent closed the + # device before forking. def reset_if_forked return if @pid == Process.pid @@ -253,6 +255,7 @@ def reset_if_forked @flush_thread = @request_outlet_thread = nil @requests_in_flight = 0 @reconnect_wait = INITIAL_RECONNECT_WAIT + @closed = @late_delivery_failed = false @pid = Process.pid end end