Skip to content

Keep forked processes from resending the parent's log lines, and add Logger#flush - #57

Merged
PetrHeinz merged 15 commits into
mainfrom
claude/fork-safety
Oct 2, 2026
Merged

PetrHeinz merged 15 commits into
mainfrom
claude/fork-safety

Conversation

@PetrHeinz

@PetrHeinz PetrHeinz commented Oct 1, 2026 •

Copy link
Copy Markdown
Member

After a fork, the HTTP device keeps the queues it inherited and only restarts its dead threads (write → ensure_flush_threads_are_started), so every child sends the lines the parent buffered before forking, and the parent sends them as well. The red-team saw each pre-fork line arrive 3 times with Puma preload_app! and 2 workers, and 5 times with 4; logger.reopen doesn't help. A child that ends with exit!, as Resque's job processes do, skips the at_exit hooks and loses its lines, and there was no Logger#flush to call first. An idle worker that exits with the parent's lines in its queue waited 20 seconds for an outlet thread it never started. HTTP#flush waited those 20 seconds with flush_continuously: false too, and delivered nothing.

  • The device remembers the pid that owns its queues and threads. When another process writes, flushes or closes it, it starts over in that process: empty queues, no threads, and the threads start when the child first logs. It's a plain Process.pid check, so it works on Ruby 2.5 and needs no Process._fork hook. A lock keeps two threads of a new child from resetting it twice.
  • Logtail::Logger#flush flushes the logger's devices, extra loggers included. On the HTTP device it waits until the buffered lines are delivered, about 5 seconds at most (it was 20).
  • When no outlet thread runs, with flush_continuously: false or in a child that hasn't logged yet, flush delivers in the calling thread, with 5-second connect and read timeouts.

Behaviour and compatibility:

  • Rails calls Rails.logger.flush after every request (ActiveSupport::LogSubscriber.flush_all!, in every Rails from 5.0 to 8.1). Waiting for delivery there would hold up every request, and on Rails 7.0 and older it would delay the response itself, so Logger#flush returns right away when flush_all! calls it. That is what the call did before, when the logger had no flush (ActiveSupport::TaggedLogging#flush only calls super when there is one). The background thread delivers those lines as usual. Checked with ActiveSupport 5.0, 7.1 and 8.1, through TaggedLogging and BroadcastLogger.
  • flush and close wait about 5 seconds for the outlet thread instead of 20, so a backlog that takes longer to deliver at exit is cut off sooner.
  • A synchronous delivery counts any HTTP response as delivered, like the outlet does today. Its errors only go to the Logtail::Config debug log, also those outside StandardError (WebMock refuses connections with one, so a test suite with WebMock and a real HTTP device would otherwise fail at exit); signals such as Interrupt are raised as usual.
  • The process tests start Ruby subprocesses with RbConfig.ruby -Ilib against a local TCP server on an ephemeral port. The fork tests skip where fork isn't available, TruffleRuby included.

Locally, with the red-team's fork.rb (50 lines before forking 3 children that log 100 lines each, then 100 more in the parent) against a local fake ingest: main delivered 600 rows, the 50 pre-fork lines 4 times each, and this branch 450 rows, each once, on Ruby 2.7, 3.0 and 3.4, with and without reopen. An idle child took 20.1 s to exit on main and no measurable time here.

#58 (fast, quiet shutdown) also changes http.rb. Both PRs add the same deliver_synchronously(requests) helper, SYNCHRONOUS_DELIVERY_TIMEOUT and spec/support/processes.rb, and otherwise touch different lines, so they merge cleanly in either order; a local merge of both branches passes the suite on Ruby 2.7, 3.0, 3.2 and 3.4.

Follow-up after the E2E run of the release candidate (two more commits, the first one only a test, red on the Ruby 2.5 to 2.7 jobs): when Net::HTTP can't start the thread that times out connecting, as while Ruby shuts down, deliver_synchronously reads @last_resp before anything set it, and Ruby 2.7 and older warn about that with -w. It's set in initialize now, on the same line as in #58, so the two still merge cleanly.

Follow-up (e9b9c7a): spec/logtail/logger_flush_all_spec.rb runs ActiveSupport's real LogSubscriber.flush_all! in a subprocess. It covers a Logtail::Logger on its own, in TaggedLogging and, from ActiveSupport 7.1, in a BroadcastLogger, against a local host that holds its answers. flush_all! has to return within a second without delivering, where waiting would take 5 seconds, and a direct flush of the same logger has to deliver. An ActiveSupport that moves or renames the call now fails CI instead of holding up every request; with the shortcut disabled, every example fails. CI resolves ActiveSupport 6.1 on Ruby 2.5 and 2.6, where the BroadcastLogger examples are pending, 7.1 on 2.7 and 3.0, 7.2 on 3.1 and 8.1 on the others, TruffleRuby included. The Gemfile gets the same activesupport lines as #53, so the two merge cleanly.

Follow-up (3b995ad test, red on every job, then 970f2c3): synchronous deliveries now wait up to 5 seconds to connect and 5 seconds for the response (SYNCHRONOUS_DELIVERY_TIMEOUT, previously 2), Petr's choice, on the same line as in #58. The test has flush deliver two requests in the calling thread to a host that answers after 3 seconds; with 2 seconds the first one timed out and the second was dropped.

Targets the logtail 0.1.21 patch release. No dependencies on the other open PRs.

The first commit only adds the tests and is expected to fail on CI. The next one fixes how one of those tests reads WebMock requests, then come the fix, a commit that passes the requests to the helper shared with #58, and a test for the idle child, which fails against main (20.07 s). The next two add a failing test and the fix for an error outside StandardError escaping a synchronous delivery, and the follow-ups above come last.

🤖 Generated with Claude Code

PetrHeinz and others added 5 commits October 1, 2026 18:51
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 <noreply@anthropic.com>
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 <noreply@anthropic.com>
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 <noreply@anthropic.com>
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 <noreply@anthropic.com>
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 <noreply@anthropic.com>
PetrHeinz and others added 4 commits October 1, 2026 19:30
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 <noreply@anthropic.com>
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 <noreply@anthropic.com>
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 <noreply@anthropic.com>
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 <noreply@anthropic.com>
@PetrHeinz
PetrHeinz marked this pull request as ready for review October 2, 2026 09:10
PetrHeinz and others added 6 commits October 2, 2026 11:27
…_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 <noreply@anthropic.com>
…econds

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 <noreply@anthropic.com>
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 <noreply@anthropic.com>
Conflict in spec/logtail/logger_spec.rb: #51's describe "#unknown" and this
branch's describe "#flush" were added at the same place. Both are kept,
#unknown first.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
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 <noreply@anthropic.com>
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 <noreply@anthropic.com>
@PetrHeinz
PetrHeinz merged commit 4004e77 into main Oct 2, 2026
12 checks passed
@PetrHeinz
PetrHeinz deleted the claude/fork-safety branch October 2, 2026 11:43
PetrHeinz added a commit that referenced this pull request Oct 2, 2026
Conflicts in lib/logtail/log_devices/http.rb, both sides kept:
- require block: #54's require "set" and this branch's require "time"
- constants after MAX_RECONNECT_WAIT: this branch's MAX_RETRY_AFTER,
  REPORTED_REJECTIONS and REPORTED_REJECTIONS_LOCK, then
  SYNCHRONOUS_DELIVERY_TIMEOUT from #57/#58

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
PetrHeinz added a commit that referenced this pull request Oct 2, 2026
…ivery

With #57 and #58 merged, a delivery in the calling thread (flush without an
outlet thread, lines written after close or during shutdown) counts any
HTTP response as delivered. So a batch rejected with 401 or 403 isn't
reported, and lines written after close keep going out after a 429 or 5xx.
Three of the four new examples fail for that. The fourth, a batch answered
with 408, 429 or 5xx is neither retried nor reported, passes already and
keeps the fix from reporting those statuses as rejected.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant