An Error while IndexWriter logs a flush stall strands the buffer being flushed, so the writer hangs instead of closing itself

When a per-thread buffer (DWPT) is full, DocumentsWriterFlushControl.checkOutForFlush hands it over for flushing: it adds it to flushingWriters and checks it out of the pool, and only then, in its finally, calls updateStallState(). That method asks the InfoStream isEnabled("DWFC") and, when the stall state changes, formats and logs "now stalling flushes ..." or "done stalling flushes ...". If that logging throws, the throw replaces return perThread: no caller receives the buffer, nothing flushes or aborts it, and it stays in flushingWriters. waitForFlush() waits, with no timeout, until that set is empty, and it is called by the writer's tragic rollback after an Error, by rollback() and by close(). So after an OutOfMemoryError on the stall message the indexing thread blocks forever inside the self-close the IndexWriter javadoc promises, and after an unchecked exception close() and rollback() hang. It needs the InfoStream, which is off by default, and a logging call that throws just as a stall starts, so it is rare. The logging got into that finally with a 2016 log-noise cleanup (614b45d2dff4, first released in 6.2.0); every release since is affected. Updating the stall state before the hand-off fixes it at the single-buffer hand-offs and changes nothing when no exception is thrown; the full-flush loop in markForFullFlush needs more.

1. Hand-off first, logging second. DocumentsWriterFlushControl.checkOutForFlush (DocumentsWriterFlushControl.java:409-424): in a try it calls addFlushingDWPT(perThread) (flushingWriters.add, :426-430), numPending-- and perThreadPool.checkout(perThread), then return perThread; its finally calls updateStallState() (:422).
2. The logging. updateStallState() (:307-348) computes stall = (activeBytes + flushBytes) > limit && activeBytes < limit && !closed (:318, limit = twice the RAM buffer, :106-111). If infoStream.isEnabled("DWFC") (:320) and the stall state changes, it builds a String.format message and calls infoStream.message("DW", ...) (:321-343); only then stallControl.updateStalled(stall) (:346).
3. A throw loses the only reference. The throw replaces return perThread, so checkout (:268), doAfterDocument (:245) and DocumentsWriter.updateDocuments (DocumentsWriter.java:434) never receive the buffer. It is in flushingWriters and out of the pool. abortPendingFlushes (:681-710) aborts only the flush-queue and blocked entries, and DocumentsWriter.abort (DocumentsWriter.java:218-224) only buffers still in the pool, so nothing removes it; only doAfterFlush (:290-303) would.
4. Every wait for running flushes waits forever. waitForFlush() (:350-358) is an untimed wait() while flushingWriters is not empty. Only an interrupt ends it.
   • After an Error, IndexWriter.updateDocuments records the tragedy and calls maybeCloseOnTragicEvent() (IndexWriter.java:1632-1639), which runs rollbackInternal() (:6098-6106), then docWriter.abort() (:2635), which waits at DocumentsWriter.java:226.
   • After an unchecked exception, the writer stays open. close() waits in flushAllThreads (DocumentsWriter.java:690), rollback() in abort (:226). If the stall had just started, the stranded bytes keep it on, so the next addDocument loops in DocumentsWriter.preUpdate (DocumentsWriter.java:389-396) on waitIfStalled(). The stall flag itself is set by the second updateStallState() call, in doAfterDocument's finally (:246-248), which the one-shot InfoStream no longer throws from; the hangs in the self-close, close() and rollback() do not depend on it.
5. The same throw without a hand-off is handled. Thrown from the same updateStallState() call, reached from doAfterDocument's finally when no buffer is checked out, the Error closes the writer and an exception leaves it usable (verifier's control passes with assertions on and off). The hang comes from the order of the hand-off.

Minimal test: RAM buffer 0.001 MB, so the stall limit is 2,097 bytes; one document with one term makes a buffer of 68,112 bytes (about 67 KB; the log line rounds it to 0.1 MB). The diagnostic copy of the test captures the line that throws: "now stalling flushes: netBytes: 0.1 MB flushBytes: 0.1 MB fullFlush: false", thrown at updateStallState:323 inside checkOutForFlush:422. addDocument is still blocked after 10 s, in waitForFlush:353 under DocumentsWriter.abort:226 and IndexWriter.maybeCloseOnTragicEvent:6104.

• doAfterDocument's finally (:246-248) calls updateStallState() after checkout returned a buffer. Verifier made isEnabled throw there: it hangs, also with only checkOutForFlush fixed (executed).
• markForFullFlush (:580-606), the start of every full flush (commit(), flush(), NRT reopen, close()), checks the pool's buffers out one by one (checkOutForFlush at :590). It keeps them in a local list and moves them into the flush queue only after the loop (:614). A throw inside the loop strands every buffer already checked out, so a full flush can create the stranded state itself (executed by the fact check: two buffers, a live setRAMBufferSizeMB so that the stall starts at the second checkout, one IllegalStateException inside commit(); both buffers stranded, close() hangs).
• nextPendingFlush polls the flush queue and then calls updateStallState() (:444-448), by reading.
• checkoutLargestNonPendingWriter has a finally after checkout (:785-790), by reading.

• Who. Applications that turn on IndexWriter's InfoStream (IndexWriterConfig.setInfoStream; a new config takes InfoStream.getDefault(), which is NO_OUTPUT unless the application replaces it process-wide with InfoStream.setDefault), for example setInfoStream(System.out) while debugging, or JavaLoggingInfoStream, which MIGRATE.md mentions for logging IndexWriter events through java.util.logging. Servers that forward the InfoStream into their logging belong here while it is on.
• When. A logging call must throw while a buffer is being handed over for flushing. The "now stalling flushes" line is logged only when a stall starts, and here the stall must start at the hand-off: the bytes being flushed plus the active bytes pass twice the RAM buffer while the active bytes stay below it (DocumentsWriterFlushControl.java:318). With default settings that takes one buffer larger than twice the RAM buffer (a very large document; verifier used one 120,000-term document with a 1 MB buffer), or, by reading, flushing that falls behind several indexing threads. With the default 16 MB buffer and one indexing thread no stall starts: 60,828 small documents and 4 flushes logged no "now stalling flushes" (executed by the fact check). The minimal test's 0.001 MB buffer makes its first buffer (68,112 bytes) pass the 2,097-byte stall limit at once. The test injects the OutOfMemoryError from message(); in production it could be an OutOfMemoryError while Lucene formats the line under heap pressure (by reading, not executed) or a logger that throws. A throw from isEnabled("DWFC") needs no stall, since it is asked on every call, but an isEnabled() that throws is contrived.
• What breaks. After an Error the indexing call never returns, instead of the writer closing itself, and the writer keeps its write lock while the call is blocked (executed by the fact check: a second IndexWriter on the same directory fails with LockObtainFailedException). After an exception, close(), rollback(), commit() and an NRT reopen hang (the last two executed by the fact check, in flushAllThreads), and if a stall had started, so does every later addDocument. Only an interrupt ends a wait. In the Error case one interrupt ends it and the rollback's cleanup releases the write lock; an interrupted close() falls back to the rollback and waits again, so it needs two interrupts (executed by the fact check).
• Not shown. Damage to committed data. By reading, the stranded buffer's documents, which were not committed, are never written.
• How likely. Rare: the InfoStream is off by default, the stock PrintStreamInfoStream does not throw, and no report of this hang was found since 2016.

The test sits in org.apache.lucene.index only for placement next to TestIndexWriterExceptions; it uses public API only (IndexWriterConfig, InfoStream, ByteBuffersDirectory) and pins the default codec. It throws from message() on the stall message, not from isEnabled(). By reading, a real allocation failure while Lucene formats that message would be thrown from the same statement (DocumentsWriterFlushControl.java:323-330); that variant was not executed.

On main the blocked thread is still there when the test ends, so the test runner adds its standard suite-level ThreadLeakError: not a second symptom, it prints the blocked thread's stack (the waitForFlush location) and then interrupts it, which ends the thread.

Regression test: this same test. It passes with either fix and fits in TestIndexWriterExceptions next to testOutOfMemoryErrorCausesCloseToFail.

cp $REPRO/TestErrorInStallMessageClosesWriter.java $LUCENE/lucene/core/src/test/org/apache/lucene/index/
cd $LUCENE && ./gradlew :lucene:core:test --tests TestErrorInStallMessageClosesWriter -Ptests.seed=DEADBEEF
# the same result with -Ptests.asserts=false

# gradle, stock 645d4fe14a20, -Ptests.seed=DEADBEEF (assertions on; the same with -Ptests.asserts=false)
TestErrorInStallMessageClosesWriter > testOutOfMemoryErrorWhileLoggingStallClosesWriter FAILED
    java.lang.AssertionError: addDocument should rethrow the Error, but is still blocked
        at org.apache.lucene.index.TestErrorInStallMessageClosesWriter.testOutOfMemoryErrorWhileLoggingStallClosesWriter(TestErrorInStallMessageClosesWriter.java:72)

TestErrorInStallMessageClosesWriter > executionError FAILED
    com.carrotsearch.randomizedtesting.ThreadLeakError: 1 thread leaked from SUITE scope at org.apache.lucene.index.TestErrorInStallMessageClosesWriter:
       1) Thread[id=21, name=Thread-3, state=WAITING, group=TGRP-TestErrorInStallMessageClosesWriter]
            at java.base/java.lang.Object.wait(Object.java:351)
            at org.apache.lucene.index.DocumentsWriterFlushControl.waitForFlush(DocumentsWriterFlushControl.java:353)
            at org.apache.lucene.index.DocumentsWriter.abort(DocumentsWriter.java:226)
            at org.apache.lucene.index.IndexWriter.rollbackInternalNoCommit(IndexWriter.java:2635)
            at org.apache.lucene.index.IndexWriter.rollbackInternal(IndexWriter.java:2590)
            at org.apache.lucene.index.IndexWriter.maybeCloseOnTragicEvent(IndexWriter.java:6104)
            at org.apache.lucene.index.IndexWriter.updateDocuments(IndexWriter.java:1639)
            at org.apache.lucene.index.IndexWriter.updateDocument(IndexWriter.java:1913)
            at org.apache.lucene.index.IndexWriter.addDocument(IndexWriter.java:1492)
2 tests completed, 2 failed

# where it throws (a diagnostic copy that prints the stack inside message(), main, assertions on)
message = now stalling flushes: netBytes: 0.1 MB flushBytes: 0.1 MB fullFlush: false
  at DocumentsWriterFlushControl.updateStallState(DocumentsWriterFlushControl.java:323)
  at DocumentsWriterFlushControl.checkOutForFlush(DocumentsWriterFlushControl.java:422)
  at DocumentsWriterFlushControl.checkout(DocumentsWriterFlushControl.java:268)
  at DocumentsWriterFlushControl.doAfterDocument(DocumentsWriterFlushControl.java:245)

# 10.6.0 release jars, assertions off: the same failure (waitForFlush:351 <- DocumentsWriter.abort:227)
# with either fix: 1 test, 0 failures, assertions on and off

• The contract. IndexWriter class javadoc (IndexWriter.java:162-165): "if you hit an Error, or disaster strikes during a checkpoint then IndexWriter will close itself ... Any subsequent calls will throw an AlreadyClosedException." The thread that hit the Error blocks inside that self-close forever. That is the strong contract. The close() and rollback() javadocs (:1341-1361, :2566-2574) promise no time bound (close() "may be a costly operation"), but neither describes an indefinite wait.
• Maintainers name the self-close as the defense against OOM. rmuir on #13275 (2024-04-05): "This is why indexwriter closes itself on oom." On #13277 ("IndexWriter: Treat java.lang.Error as tragedy", merged 2024-04-24): "user can plug into low-level lucene apis such as Directory, Codec, etc, but the same rules apply".
• Lucene's tests inject this kind of fault and expect recovery, at other sites. In TestIndexWriterExceptions, testOutOfMemoryErrorCausesCloseToFail (LUCENE-1429, :1110-1147) and testOutOfMemoryErrorRollback (:1149-1200) throw OutOfMemoryError from InfoStream.message on "now flush at close" and "startFullFlush"; testExceptionDuringRollback (:1980-2052) and testOnlyRollbackOnceOnException (:2195-2235) throw RuntimeException from it during rollback. None throws at this hand-off. IndexWriter.onTragicEvent guards its own logging with catch (Throwable t) { tragedy.addSuppressed(t); } (IndexWriter.java:6075-6083).
• The same throw elsewhere is handled. Verifier's control throws the same isEnabled("DWFC") from the same updateStallState() call when no buffer is being handed over: the Error closes the writer, an exception leaves it usable (pass, assertions on and off).
• How the call got there. 614b45d2dff4 (2016, "reduce IW.infoStream noise when stalling ...") moved the stall logging from the waiting thread, which holds no buffer (LUCENE-6209), into updateStallState(), which the hand-off already called in its finally.
• Precedent. #5345 (LUCENE-4277, 2012): a flush-pending buffer left behind in the flush queue (by a full-flush race) made abort hang in waitForFlush; fixed as a bug by pruning such buffers in abort. #6053 (LUCENE-4989, 2013): an exception that skipped doAfterFlush; fixed with a finally.

The refute reviewer and the intended-lens reviewer (both OpenAI GPT-5.6, reading only) built the case for "not a bug": InfoStream is a @lucene.internal "Debugging API" (InfoStream.java:22-29) with no promise that IndexWriter survives a throwing implementation; an isEnabled() that throws is contrived, since the stock implementations never do; and rmuir on #13275 said "Can't make java code more complicated to deal with issues like this, if the jvm is broke then it's broke." The refute reviewer concluded not real (medium); the intended-lens reviewer rated the argument moderate and its verdict uncertain (low). A maintainer may also cite rmuir's #13277 comment (2024-04-11), whose bullets include "these are Errors IndexWriter is hitting from lucene apis, not application code", since an InfoStream is application code; the next bullet ("user can plug into low-level lucene apis such as Directory, Codec, etc, but the same rules apply") partly answers it.

Why it fails: the minimal test throws from message() on Lucene's own String.format line, not from isEnabled(); nothing documents that an InfoStream must not throw, and setInfoStream is public; the same #13275 thread names the self-close as the defense against OOM, and the self-close is what hangs; Lucene's tests inject the same kind of fault at other InfoStream sites and expect recovery; and the fix only reorders existing calls. The intended-lens reviewer listed most of these points itself. The unchecked-exception variant is the weaker half; maintainers may call it hardening. Verdict: not intended, a defect (adjudication: confirmed, medium confidence).

Two fixes were validated in a scratch worktree of 645d4fe14a20. Both move the logging ahead of the hand-off. That is equivalent when nothing throws: the hand-off changes none of the inputs of the stall decision (activeBytes, flushBytes, closed). Then a throw from the InfoStream leaves the buffer being handed off flush-pending in the pool, where the rollback or the next flush finds it. Neither covers the full-flush loop in markForFullFlush (DocumentsWriterFlushControl.java:580-606): a throw at a later buffer's stall update, now before its hand-off, still strands the buffers that earlier iterations already handed off into the loop's local list, which are in flushingWriters but not yet in the flush queue. Executed by the fact check with the recommended fix shadowed: after commit() threw, one buffer stayed in the pool, the other was stranded, and close() still hung in waitForFlush. A possible extension, not validated: queue each checked-out buffer right after its checkout, or update the stall state once after flushQueue.addAll (:614-615) instead of inside the loop. Two other directions are listed but were not run.

One file, DocumentsWriterFlushControl.java, +15/-15 (fix-handoff.diff): (1) checkOutForFlush calls updateStallState() first and then hands the buffer over, with no try/finally; (2) nextPendingFlush calls it before flushQueue.poll() instead of after; (3) updateStallState() tests stall != stallControl.anyStalledThreads() (a volatile read) before infoStream.isEnabled("DWFC"). With (1) and (2), a stall change caused by a hand-off is logged before the buffer is registered; with (3), the later calls in the finally blocks of doAfterDocument and checkoutLargestNonPendingWriter make no InfoStream call after a hand-off that succeeded and already updated the state under the same lock (they still do when the state did change, e.g. after the pre-hand-off update threw).

    // Update the stall state (which may log) before the hand-off: the hand-off does not change
    // activeBytes or flushBytes, and a throw from the InfoStream must not strand a DWPT that is
    // already in flushingWriters but was never returned to a caller.
    updateStallState();
    addFlushingDWPT(perThread);
    numPending--; // write access synced
    boolean checkedOut = perThreadPool.checkout(perThread);
    assert checkedOut;
    return perThread;

Trade-offs

Three small edits instead of one, all in one class; no lock, no new state, and one InfoStream call fewer per updateStallState() when nothing changes. Edits (2) and (3) are justified by reading: no executed test throws at nextPendingFlush (reached during a full flush) or at the isEnabled call in doAfterDocument's finally under this fix (verifier's test for the latter needs isEnabled to be called there, which the fix removes). Not covered: markForFullFlush's loop (executed by the fact check: close() still hangs). The fix does not make IndexWriter tolerate an InfoStream that always throws; it only keeps a throw from stranding a buffer at the single-buffer hand-offs. Not examined: a throw from the "done stalling flushes" line in doAfterFlush, where the buffer has already left flushingWriters. Applies to upstream main 2f424fd428da with patch (offset 11 lines, one hunk with fuzz 2; dry run recorded).

What the checks validated

• Stock: the minimal test fails with assertions on and off.
• With the fix: the minimal test passes with assertions on and off; addDocument rethrows the Error and the writer is closed.
• Closest suites with the fix (assertions on, seed DEADBEEF): TestIndexWriterExceptions (40 tests, including the InfoStream OutOfMemoryError tests), TestIndexWriterExceptions2, TestFlushByRamOrCountsPolicy, TestDocumentsWriterStallControl, TestIndexWriterWithThreads, TestIndexWriterThreadsToSegments, TestIndexWriter, TestInfoStream, TestIndexWriterDelete, TestIndexWriterCommit: 10 classes, 230 tests, 0 failures, 13 skipped.
• :lucene:core:checkGoogleJavaFormat, ecjLintMain and forbiddenApisMain pass.
• Verifier's 7-test class with this fix (standalone runner, the patched class shadowed over the main jars, assertions off): the four stall-message tests (the Error closes the writer; close(), rollback() and the next addDocument return after an exception) and the no-throw control pass. Its two isEnabled tests fail only their precondition "isEnabled was reached in checkOutForFlush", because the fix no longer asks the InfoStream there unless the stall state changes.
• Not run: nightly tests, benchmarks.

Edit (1) alone, +9/-9 (fix-move-checkout.diff): updateStallState() before addFlushingDWPT and the checkout in checkOutForFlush.

Trade-offs

Smallest change and covers the executed trigger at the hand-off, but not the other sites: with it, an isEnabled throw in doAfterDocument's finally after the checkout still hangs (executed by the independent reproduction), and nextPendingFlush's poll-then-update keeps the same order (by reading). Like the recommended fix, it leaves markForFullFlush's loop open (the loop calls the same checkOutForFlush).

What the checks validated

• The minimal test passes with assertions on and off (same gradle run; closest suites not re-run for this option).
• Earlier: the independent reproduction's 7-test class passes 7 of 7 on main a9779ef3c193 with this patch (the Errors close the writer; close(), rollback() and the next addDocument return after the exceptions).

Keep the order, but catch a throw after the checkout and give the buffer back: remove it from flushingWriters (or abort it through doAfterFlush), notify waiters, then rethrow.

Trade-offs

More code on the indexing hot path, and every caller that receives a buffer and then calls updateStallState() needs it, markForFullFlush's loop included; at the single-buffer hand-offs the reorder reaches the same state with less code.

Make updateStallState() ignore failures of its own log calls.

Trade-offs

It would hide an OutOfMemoryError, while IndexWriter's policy (#13277) is to treat an Error as a tragedy and close the writer.

Method: bounded-exhaustive single-fault injection, then code reading (the hunt's "semi-formal" tier).

• A hunt unit studies error handlers and errors raised through public callbacks. Its sweep ran the real lucene-core jar with a 24-operation script and SerialMergeScheduler, and threw one OutOfMemoryError at the k-th InfoStream.isEnabled call, for every k of the 1,052 calls.
• 12 runs, all at DocumentsWriterFlushControl.updateStallState, hung in DocumentsWriter.abort -> waitForFlush during the tragic rollback. The sweep's message() pass could not reach the site, because the stall message is logged only when the stall state changes.
• Code reading explained the hang (the hand-off registers the buffer before the logging call) and gave a 2-test public-API JUnit. A verifier then wrote an independent test that throws from message() on the stall line, and the minimal test keeps only that Error case with one document.