Skip to content

T-1365 Give up sending after maxFlushTime when the application stops - #35

Merged
PetrHeinz merged 12 commits into
mainfrom
claude/max-flush-time
Sep 29, 2026
Merged

PetrHeinz merged 12 commits into
mainfrom
claude/max-flush-time

Conversation

@PetrHeinz

@PetrHeinz PetrHeinz commented Sep 29, 2026 •

Copy link
Copy Markdown
Member

Builds on #34, whose shutdown hook this bounds.

Since the shutdown hook from #31, an endpoint that cannot be reached holds the JVM's exit: every queued batch goes through all six attempts, and each attempt waits for the connect timeout twice (callHttpURLConnection connects once in connect() and again when it writes). Measured end to end with 0.3.8 against a black-holed address: 62 seconds for one batch with the default 5 second connect timeout, 41 seconds for three batches at a 1 second connect timeout. A JVM whose main returned while a full batch was being sent waited even before running any shutdown hook, because the flush threads started when a batch fills up are not daemon threads.

  • New maxFlushTime setting, the name logback's own AsyncAppender uses for the same thing, default 30000 ms like logtail-python's flush_timeout. stop() and the shutdown hook leave sending the queue to a daemon thread and wait for it for at most that long, which is also how AsyncAppender stops its worker. The wait ends on time whatever holds the request: an endpoint that cannot be reached, a read or connect timeout set to 0, a connection that stopped taking data (writing to a socket has no timeout), a name server that does not answer. A black-holed endpoint now holds the exit for 30 seconds whatever is queued. As with AsyncAppender, which hands the value to Thread.join(), 0 means no limit.
  • Logs that could not be sent in time are dropped ("Dropped N logs that could not be sent within maxFlushTime"): the thread left behind stops after its request in progress instead of retrying on, which matters when logback is stopped without the JVM exiting, as in a redeploy.
  • An interrupt pending on the thread that calls stop() does not skip the flush. It is put back for the caller afterwards.
  • stop() now marks the appender stopped before sending the queue, as AsyncAppender.stop() does, so the wait for a flush in progress no longer keeps it accepting events.
  • The flush threads started when a batch fills up are daemon threads like the scheduled sender, so they no longer keep the JVM alive; the shutdown hook sends what they leave behind.

The first commit only adds LogtailAppenderMaxFlushTimeTest and is expected to fail on CI: stop() against a local socket that accepts connections but never answers must return within 3 seconds with maxFlushTime set to 1 second, and a child JVM that fills a batch against that socket and returns from main must exit within 10 seconds.

The third commit adds tests for 0 meaning no limit (stop() must keep waiting for a flush in progress) and for the 30 second default, and is expected to fail on CI as well; the fourth makes them pass.

The time limit first worked by cutting the timeouts of the flush's requests down to the time left. The fifth commit adds tests for what that could not cover and is expected to fail on CI: stop() must give up on a request without a read timeout and on an endpoint that stopped taking data (it kept waiting in both), and it must send the queue when called on an interrupted thread (nothing was sent). The sixth commit replaces the mechanism with the daemon thread. Measured with it: stop() returns after 1.0 second with maxFlushTime set to 1 second in both of those cases, with the connect timeout set to 0 against a black-holed address and with a name server that takes 8 seconds to answer; a JVM with 3,500 lines queued for a black-holed address exits after 30.5 seconds at the default and after 2.5 seconds with maxFlushTime set to 2 seconds.

Main is merged in since #34 went in. That merge kept flushQueue() as #34 added it next to this branch's version, which did not compile; the last commit drops the leftover.

🤖 Generated with Claude Code

PetrHeinz and others added 8 commits September 29, 2026 10:58
Spring Boot and Quarkus keep logging while they shut down and stop logback
at the very end. Since 0.3.8 the appender's own JVM shutdown hook stops the
appender as soon as the JVM starts shutting down, so those lines are
rejected. FrameworkApp reproduces that in a child JVM.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
The shutdown hook now only sends what is queued, after waiting for a flush in
progress, instead of stopping the appender. Lines logged afterwards by the
application's own shutdown are queued as usual and sent when the framework
(or logback's <shutdownHook>) stops logback.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
stop() must give up after maxFlushTime, and a JVM whose flush hangs on the
endpoint must still exit once main returns.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
stop() and the shutdown hook wait at most maxFlushTime (default 10 s) for a
flush in progress, clamp request timeouts and retry pauses to what is left,
and drop what they could not send once it is up. Flush threads started by a
full batch are daemon threads now, so they no longer keep a JVM whose main
returned alive while they retry.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
As for logback's AsyncAppender, which hands maxFlushTime to Thread.join,
0 must mean no limit rather than dropping everything at once. The default
becomes 30 seconds, like logtail-python's flush_timeout.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
30 seconds matches logtail-python's flush_timeout. 0 now waits for as long as
the flush takes, like logback's AsyncAppender, instead of dropping the queue
at once.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
stop() must give up after maxFlushTime on a request without a read timeout
and on an endpoint that stopped taking data, and it must still send the queue
when it is called on an interrupted thread.

Also pins that logs not sent in time are dropped once the request in progress
is over, and no longer expects the queue to be empty the moment stop() gives
up.

Co-Authored-By: Claude Fable 5.1 <noreply@anthropic.com>
stop() and the shutdown hook no longer send the queue themselves with
timeouts cut down to the time left. They start a daemon thread for it and
join it for maxFlushTime, as logback's AsyncAppender does with its worker, so
the wait ends on time whatever holds the request: a read or connect timeout
set to 0, a socket that stopped taking data, a name server that does not
answer. An interrupt pending on the calling thread no longer skips the flush.

The thread left behind drops what is queued once its request in progress is
over, instead of retrying on.

Co-Authored-By: Claude Fable 5.1 <noreply@anthropic.com>
@PetrHeinz
PetrHeinz marked this pull request as ready for review September 29, 2026 12:10
Base automatically changed from claude/shutdown-hook-flush-only to main September 29, 2026 12:13
PetrHeinz and others added 4 commits September 29, 2026 14:13
Merging main brought in flushQueue() as #34 added it, next to the version
this branch replaces it with, and the class did not compile.

Co-Authored-By: Claude Fable 5.1 <noreply@anthropic.com>
@PetrHeinz
PetrHeinz merged commit e95a6b3 into main Sep 29, 2026
6 checks passed
@PetrHeinz
PetrHeinz deleted the claude/max-flush-time branch September 29, 2026 12:21
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