ConcurrentMergeScheduler throws NullPointerException when merge logging is switched on during updateMergeThreads

ConcurrentMergeScheduler.updateMergeThreads builds one log message per call in a StringBuilder. It creates the builder only if its first verbose() check is true and sets it to null otherwise (ConcurrentMergeScheduler.java:353-364 at 5adff78bb168), then calls verbose() again before appending one line per running merge (:391-397) and before logging the message (:437-438). verbose() re-reads infoStream.isEnabled("MS") on every call (MergeScheduler.java:93-95). If merge logging is switched on between the first check and a later one, for example by raising a log level under Lucene's own JavaLoggingInfoStream, the later check dereferences the null builder and the call throws NullPointerException. It is reachable from the public setters setForceMergeMBPerSec, enableAutoIOThrottle and disableAutoIOThrottle and from every merge start and finish. The window is one short call, so it is rare. The shared builder came with LUCENE-6119 (5.0.0); in 4.x each check guarded its own log call, and the same scenario returns normally on 4.10.3 and 4.10.4.

1. setForceMergeMBPerSec stores the value and calls updateMergeThreads() (ConcurrentMergeScheduler.java:199-202); enableAutoIOThrottle (:214-218) and disableAutoIOThrottle (:225-228) do the same. merge() calls it right after newMergeThread.start() (:590-591), runOnMergeFinished in its finally block (:691-697), and merge(CLOSING) at :544-547.
2. Check 1 (:354): if (verbose()) { message = new StringBuilder(); ... } else { message = null; } (:363). Logging is off, so message is null.
3. Merge logging is switched on now.
4. Check 2 (:391, once per running merge thread): if (verbose()) is true, then message.append('\n') (:397): NPE, before that merge's rateLimiter.setMBPerSec(newMBPerSec) (:435); with the switch before the loop, this pass sets no merge's new rate.
5. Check 3 (:437, reached even with no merge thread, as in the repro): if (verbose()) is true, then message(message.toString()) (:438): NPE.

True to false is harmless: the builder exists and is just not logged. Each check on its own follows the documented idiom if (verbose()) { message(...) } (MergeScheduler.java:83-92); the method breaks it by creating its data under one answer and using it under another.

• Who is hit. Applications that install an InfoStream whose isEnabled("MS") answer can change: Lucene's JavaLoggingInfoStream (advertised in MIGRATE.md) or their own logger-backed one, with merge logging switched on while the writer is open. The default NO_OUTPUT (always false) and PrintStreamInfoStream (always true) are not affected.
• Window. The switch must land inside one updateMergeThreads call, a narrow window (its duration was not measured; the method is synchronized, but that only orders the scheduler's own calls, not a Logger.setLevel on another thread); the call runs at every merge start and finish, on close, and in the three setters. A supporting probe with an unmodified JavaLoggingInfoStream and another thread that keeps toggling the "MS" logger's level hit the NPE after 34 setter calls; that toggling rate is not realistic, so it only shows reachability.
• Setter. A loud NPE after the value is stored. With merges running, the merges the loop had not yet reached (all of them if logging switched on before the loop) keep their old rate until the next updateMergeThreads call.
• Merge start. The NPE lands in merge()'s catch (Throwable t) { mergeSource.onMergeFinished(merge); throw t; } (:592-594), which hands back a merge whose thread already runs. A supporting probe then saw a second merge of the same segments registered and a tragic writer close (-ea: AssertionError at IndexWriter._mergeInit; -da: NPE at IndexWriter.closeMergeReaders). A tragic close rolls the writer back (IndexWriter.java:6097-6103), which discards changes since the last commit; that is read from the code, the probe did not check documents. That hand-back is LFV-208's mechanism, with its own root cause and fix site; this bug is one more trigger for it.
• Merge finish. The NPE skips notifyAll() and ends the merge thread through handleMergeException after the merge completed; stalled indexing threads wait at most 250 ms per round (doStall), so nothing hangs.
• Likelihood. No scale or index content is involved, and no public report of it was found since 2015: rare.

TestConcurrentMergeSchedulerVerboseTurnsOn (one method, extends LuceneTestCase, package org.apache.lucene.index of the lucene/core tests). Its InfoStream answers false until armed is set; after that its first answer is false and every later one is true, so the switch lands between updateMergeThreads' first and last check, as a log level raised at that moment would.

It is the hunt's minimal repro with two changes so it compiles in Lucene's build: the writer is closed explicitly instead of in try-with-resources (javac -Werror rejects an unreferenced resource under the [try] lint) and the comment line fits 100 columns. Behaviour is unchanged. Seeds do not matter: this file failed with DEADBEEF, and the hunt's versions of it with DEADBEEF, 5EED0E41, 5EED0D41, 5A5A1E and A0D17E41. As the regression test, the same method fits into TestConcurrentMergeScheduler as is.

cp $REPRO/TestConcurrentMergeSchedulerVerboseTurnsOn.java $LUCENE/lucene/core/src/test/org/apache/lucene/index/
cd $LUCENE && ./gradlew :lucene:core:test --tests org.apache.lucene.index.TestConcurrentMergeSchedulerVerboseTurnsOn -Ptests.seed=DEADBEEF
# assertions off: add -Ptests.asserts=false

# gradle on main 5adff78bb168, -Ptests.seed=DEADBEEF (the same with -Ptests.asserts=false)
TestConcurrentMergeSchedulerVerboseTurnsOn > testLoggingTurnedOnDuringSetForceMergeMBPerSec FAILED
    java.lang.NullPointerException: Cannot invoke "java.lang.StringBuilder.toString()" because "message" is null
        at __randomizedtesting.SeedInfo.seed([DEADBEEF:8F105C7FBB625DBA]:0)
        at org.apache.lucene.index.ConcurrentMergeScheduler.updateMergeThreads(ConcurrentMergeScheduler.java:438)
        at org.apache.lucene.index.ConcurrentMergeScheduler.setForceMergeMBPerSec(ConcurrentMergeScheduler.java:201)
        at org.apache.lucene.index.TestConcurrentMergeSchedulerVerboseTurnsOn.testLoggingTurnedOnDuringSetForceMergeMBPerSec(TestConcurrentMergeSchedulerVerboseTurnsOn.java:51)

# release jars: the same NPE at updateMergeThreads :440 (10.6.0), :439 (10.5.2, 10.0.0), :431 (9.12.3), :407 (8.11.4), :406 (7.7.3, 6.6.6), :370 (5.5.5), :343 (5.0.0)

• Contract. InfoStream.isEnabled is documented only as "returns true if messages are enabled and should be posted to message" (InfoStream.java:53-54). verbose() is documented as "usually used in conjunction with message(String)", with the paired if (verbose()) { message(...) } idiom (MergeScheduler.java:83-92). IndexWriterConfig.setInfoStream(InfoStream) is public and accepts any non-null InfoStream (IndexWriterConfig.java:430).
• Design history. LUCENE-3598 (#4672, 2011) introduced isEnabled for logging that "is enabled or disabled dynamically": "Using this you could enable/disable logging live by e.g. the log4j management console" (Uwe Schindler, in the issue description, answering a request by Shai Erera). Robert Muir supported it because "it makes it possible for someone to turn on/off infostream \"live\" themselves".
• Tests. The 15 isEnabled overrides in Lucene's test sources (14 in lucene/core/src/test, for example TestConcurrentMergeScheduler.java:801-803, and 1 in lucene/test-framework/src/test) and the 4 InfoStreams in the test framework's own code (RandomIndexWriter, BaseMergePolicyTestCase, NullInfoStream, FailOnNonBulkMergesInfoStream) each answer a fixed value per component, so no test switches logging during a call and nothing asserts the current behaviour.
• History. The shared builder came with LUCENE-6119 (#7181, 2015); its 28 comments never discuss it.

The argument (an independent reviewer from another model family, OpenAI GPT-5.6, which reproduced the NPE and agreed on the root cause, still judged it not real, "not a supported Lucene API defect"): InfoStream is @lucene.internal, a "Debugging API" (InfoStream.java:23-28), and so is Lucene's own JavaLoggingInfoStream (JavaLoggingInfoStream.java:30); MergeScheduler is @lucene.experimental. A public setter that takes an internal type does not by itself make a stable contract, and nothing promises support for an isEnabled answer that changes within one call. In #4672 Robert Muir also said implementers "are responsible for their own implementation (if they want to make stuff volatile or synced, good for them)".

Why it does not settle it. Lucene ships JavaLoggingInfoStream and points users to it (MIGRATE.md:1162-1163), and its answer follows Logger.setLevel; live switching is the stated purpose of isEnabled; and an InfoStream cannot keep its answer stable across a call whose start and end it cannot see. Volatile or synchronized state inside the InfoStream does not help a caller that asks twice. What survives: both types are internal, so a maintainer may well call the change a defensive cleanup rather than a bug; the fix is the same.

Option A is the smallest change and keeps the documented idiom per call. B is equivalent in behaviour; C trades the null for extra work or a headless message. None of them changes LFV-208: its fix (do not hand back a merge whose thread already started) is separate and it has other triggers.

At the top of updateMergeThreads, final boolean verbose = verbose();, and if (verbose) at the allocation (:354), the per-thread lines (:391) and the final log call (:437).

+    final boolean verbose = verbose();
     StringBuilder message;
-    if (verbose()) {
+    if (verbose) {
       message = new StringBuilder();
 ...
-      if (verbose()) {
+      if (verbose) {
         long mergeStartNS = merge.mergeStartNS;
 ...
-    if (verbose()) {
+    if (verbose) {
       message(message.toString());

Trade-offs

Logging switched on mid-call starts with the next call, so one updateMergeThreads message is not logged; logging switched off mid-call still logs that call's one message, which today's code would drop. One isEnabled call per invocation instead of N+2 (N = running merges).

What the checks validated

Gradle in a scratch worktree at 5adff78bb168: the repro fails without the fix and passes with it, with assertions on and off; with the fix, TestConcurrentMergeScheduler (21 tests), TestMergeSchedulerExternal (2) and the repro pass (24 of 24) and checkGoogleJavaFormat is clean. The hunt, the independent reproducer and the cross-model reviewer each validated the same change.

Replace the two later if (verbose()) checks with if (message != null).

Trade-offs

Same behaviour as A, including the switch-off case (the builder doubles as the flag); slightly less obvious, because the guard no longer says "is logging on".

What the checks validated

Not run.

Create the StringBuilder unconditionally.

Trade-offs

Avoids the null, but the method then either formats its header on every call with logging off, or logs a message without its header after a mid-call switch. Not recommended.

What the checks validated

Not run.

The audit took the logging idiom that MergeScheduler documents (if (verbose()) { message(...) }) and checked updateMergeThreads, which splits one message across several checks. In updateMergeThreads the buffer is created under the first answer and dereferenced under later, separately read answers, and verbose() re-reads isEnabled("MS") each time, so nothing ties them together.

An executable repro that calls only public methods witnessed it on main with assertions on and off. An independent reproducer, an executed cross-model review (OpenAI GPT-5.6, refute lens), a devil's-advocate verifier and an adjudication then checked it, and a version sweep placed it in LUCENE-6119 (5.0.0).