Skip to content

DeadLetterQueueWriter: regression in 9.4.2 — oldestSegmentPath() refactor from File.length() to Files.size() introduces TOCTOU race causing permanent writer failure and pipeline blackout #19377

Description

@sankalp-ops

Hello All,

I believe I have found a bug in our logstash configuration after upgrading from 9.0.8 to 9.4.2 about a month back. The details are given below. Please check!!

Component: Dead Letter Queue / logstash-core

Affected version: 9.4.2

Last known good version: 9.0.8


Summary

A refactor in 9.4.2 replaced File.length() with Files.size() in DeadLetterQueueUtils.oldestSegmentPath(). File.length()
returns 0 silently when a file is missing; Files.size() throws NoSuchFileException. This introduced a TOCTOU race
condition between the DLQ reader (which deletes consumed segments when clean_consumed: true) and the writer's
scheduledFlushCheck thread, causing a permanent writer failure and complete pipeline blackout requiring manual
intervention.


Root cause

In DeadLetterQueueUtils.java, oldestSegmentPath() was refactored between 9.0.8 and 9.4.2:

9.0.8 (safe):
// In updateOldestSegmentReference():
listSegmentPathsSortedBySegmentId(this.queuePath)
.filter(p -> p.toFile().length() > 1) // File.length() returns 0 on missing file — no exception
.findFirst();

9.4.2 (regression):
// In DeadLetterQueueUtils.oldestSegmentPath():
for (Path p : stream) {
int id = extractSegmentId(p);
if (id < oldestId) {
if (minFileSize > 0 && Files.size(p) <= minFileSize) { // throws NoSuchFileException if file deleted
continue;
}
oldestId = id;
oldest = p;
}
}

When the DLQ reader deletes a .log segment between DirectoryStream listing it and Files.size() being called on it,
NoSuchFileException is thrown. This is the race window.

Note: readTimestampOfLastEventInSegment() already correctly wraps Files.size() in a NoSuchFileException catch (added in
PR #15233). The same protection was not applied to oldestSegmentPath().


Failure cascade

The race manifests in two distinct call sites within scheduledFlushCheck():

Call site A (fatal) — inside finalizeSegment():
scheduledFlushCheck()
→ finalizeSegment(ONLY_IF_STALE)
→ currentWriter.close() // .tmp FileChannel closed
→ sealSegment(N) // .tmp renamed to N.log ✓
→ updateOldestSegmentReference() // ← race hits HERE
→ oldestSegmentPath()
→ Files.size(N.log) // reader deleted N.log — throws NoSuchFileException
[nextWriter() NEVER REACHED] // currentWriter left permanently closed
← exception propagates out of finalizeSegment
← caught by scheduledFlushCheck catch block — swallowed

Every subsequent tick:
scheduledFlushCheck()
→ finalizeSegment()
→ sealSegment(N) // N.log.tmp already renamed — throws NoSuchFileException
← permanent loop, nextWriter() never reached

Concurrent DLQ write on closed writer:
writeEntry() → currentWriter.writeEvent() → ClosedChannelException
→ AbstractDeadLetterQueueWriterExt.doWrite() wraps as IllegalStateException
→ opensearch plugin retrying_submit catch block expects IOException — IllegalStateException bypasses it
→ propagates to WorkerLoop → infinite retry storm → complete pipeline blackout

Call site B (harmless) — standalone call after finalizeSegment() returns:
scheduledFlushCheck()
→ finalizeSegment() // completes successfully, nextWriter() already called
→ updateOldestSegmentReference() // ← race hits HERE (standalone call)
← exception caught and swallowed — new writer already in place, no impact


Evidence from production

Two independent production Kubernetes clusters, both upgraded from 9.0.8 → 9.4.2 on the same date:

  • Cluster A: Zero "Unable to finalize segment" errors for 8 months on 9.0.8. Errors begin within days of upgrading to
    9.4.2. One cascade caused a 64-hour complete log pipeline blackout requiring manual intervention (delete DLQ segment
    file + pod restart).
  • Cluster B: Zero errors through the entire pre-upgrade period on 9.0.8. Errors begin within days of upgrading to 9.4.2.
    Five cascade events in the first month post-upgrade across multiple StatefulSet pods, with durations ranging from 58
    minutes to 33 hours.

All confirmed cascade stack traces show:
java.nio.file.NoSuchFileException: /path/to/dlq/pipeline_id/N.log
at org.logstash.common.io.DeadLetterQueueUtils.oldestSegmentPath(DeadLetterQueueUtils.java:87)
at org.logstash.common.io.DeadLetterQueueWriter.updateOldestSegmentReference(DeadLetterQueueWriter.java:624)
at org.logstash.common.io.DeadLetterQueueWriter.finalizeSegment(DeadLetterQueueWriter.java:740)
at org.logstash.common.io.DeadLetterQueueWriter.scheduledFlushCheck(DeadLetterQueueWriter.java:705)

The IllegalStateException cascade log:
[ERROR][logstash.outputs.opensearch][pipeline_name] Encountered an unexpected error submitting
a bulk request, will retry {message: "java.nio.channels.ClosedChannelException",
exception: Java::JavaLang::IllegalStateException, backtrace: [
"org.logstash.common.AbstractDeadLetterQueueWriterExt$PluginDeadLetterQueueWriterExt.doWrite(AbstractDeadLetterQueueWr
iterExt.java:204)",
...

Configuration: clean_consumed: true, retain.age: 3d, Logstash 9.4.2.


Proposed fix

Wrap Files.size() in oldestSegmentPath() with a NoSuchFileException catch, mirroring the existing fix in
readTimestampOfLastEventInSegment():

static Optional oldestSegmentPath(Path path, long minFileSize) throws IOException {
Path oldest = null;
int oldestId = Integer.MAX_VALUE;
try (DirectoryStream stream = Files.newDirectoryStream(path, "*.log")) {
for (Path p : stream) {
int id = extractSegmentId(p);
if (id < oldestId) {
if (minFileSize > 0) {
long size;
try {
size = Files.size(p);
} catch (NoSuchFileException e) {
continue; // file deleted by reader between listing and size check
}
if (size <= minFileSize) {
continue;
}
}
oldestId = id;
oldest = p;
}
}
}
return Optional.ofNullable(oldest);
}


Workaround

Set clean_consumed: false and reduce retain.age to a short period (e.g. 1d). This eliminates the only external deleter
of .log segments, closing the race window entirely. Age retention runs under the writer's ReentrantLock and cannot race
with oldestSegmentPath().


References

  • PR Fix DeadLetterQueueWriter unable to finalize segment error #15233 — applied NoSuchFileException catch to readTimestampOfLastEventInSegment() but not to oldestSegmentPath()
  • AbstractDeadLetterQueueWriterExt.java:204 — doWrite() wraps IOException as IllegalStateException, bypassing the
    opensearch plugin's retry catch block

Metadata

Metadata

Assignees

Type

No type

Projects

No projects

Milestone

No milestone

Relationships

None yet

Development

No branches or pull requests

Issue actions