apache / apache/bookkeeper

DefaultEntryLogger can publish stale entry locations after BufferedChannel partial flush failure

Open
#4,855 1 comment 0 reactions 0 assignees View on GitHub
type/bug
Dominant language
Java
Stars
2k
Forks
976
Avg merge
6d 15h
Merged PRs (30d)
7

Description

**BUG REPORT**

***Describe the bug***

In a BookKeeper 4.16.7 based deployment using `DbLedgerStorage` and `DefaultEntryLogger`, we observed an entrylog where the entry bytes are still physically present and mostly parseable, but both the RocksDB location index and the entrylog header `ledgersMapOffset` point to positions that are consistently too early by the same offset.

The suspected code-level issue is in `BufferedChannel`. `BufferedChannel.write()` can call `flush()` before updating its logical `position`. If `flush()` advances the underlying `FileChannel` position and then throws `IOException`, the physical file position has moved forward but `BufferedChannel.position` has not. The channel is not marked failed, so later writes can continue using the same stale logical position.

Relevant code shape:

```java
// BufferedChannel.write(...)
writeBuffer.writeBytes(...);
if (!writeBuffer.isWritable()) {
flush();
}
position += copied;
```

```java
// BufferedChannel.flush(...)
ByteBuffer toWrite = writeBuffer.internalNioBuffer(0, writeBuffer.writerIndex());
do {
fileChannel.write(toWrite);
} while (toWrite.hasRemaining());
writeBuffer.clear();
writeBufferStartPosition.set(fileChannel.position());
```

If `fileChannel.write(toWrite)` performs a partial local write and then throws, `writeBuffer.clear()` and `writeBufferStartPosition.set(...)` are skipped, and the caller in `write()` also skips `position += copied`.

This can affect the main entrylog writer in two places:

```java
// EntryLogManagerBase.addEntry(...)
logChannel.write(sizeBuffer);
long pos = logChannel.position(); // used as the entry body location
logChannel.write(entry);
return (logChannel.getLogId() << 32L) | pos;
```

```java
// BufferedLogChannel.appendLedgersMap(...)
long ledgerMapOffset = this.position();
write(serializedMap);
super.flush();
fileChannel.write(mapInfo, LEDGERS_MAP_OFFSET_POSITION);
```

So the same stale logical position can be published as:

1. entry locations in RocksDB, and
2. the entrylog header `ledgersMapOffset`.

This makes acknowledged entries unreadable even though their bytes may still exist later in the same entrylog file.

***To Reproduce***

A full production reproduction is hard because it requires a partial local write followed by an `IOException` at a specific point. However, the bad state is reachable with a small fault-injected `FileChannel`.

A reproducer-only PR is available to demonstrate the issue on the BookKeeper test path:

```text
https://github.com/apache/bookkeeper/pull/4854
```

Steps:

1. Check out `branch-4.16`.
2. Apply the reproducer from PR #4854.
3. Run:

```bash
mvn -pl bookkeeper-server -Dtest=org.apache.bookkeeper.bookie.BufferedChannelTest test
```

4. The reproducer injects a `FileChannel` that writes part of the buffer, advances its physical position, then throws `IOException` during `BufferedChannel.flush()`.
5. `testPositionCanLagFileChannelAfterPartialFlushFailure` shows that after the exception, `FileChannel.position()` can be ahead of `BufferedChannel.position()`, and a later write can still succeed on the same channel.
6. `testLedgersMapHeaderUsesStalePositionAfterPartialFlushFailure` shows that `BufferedLogChannel.appendLedgersMap()` can write a stale `ledgersMapOffset` to the entrylog header after that drift.

The tests currently assert the reachable bad state. After a fix, these tests should be rewritten to assert fail-closed behavior instead.

***Expected behavior***

After an `IOException` from a write path where the local writer state is no longer trustworthy, BookKeeper should fail closed instead of continuing to reuse the same entrylog writer.

At minimum:

1. `BufferedChannel` should enter a failed state after `write()`, `flush()`, or `forceWrite()` fails with `IOException`.
2. A failed `BufferedChannel` should reject subsequent `write()`, `flush()`, `forceWrite()`, and `appendLedgersMap()` attempts.
3. `EntryLogger.addEntry()` should not return a location after the underlying log channel has failed.
4. `appendLedgersMap()` should not publish a header pointing to a stale logical position.
5. The direct positioned header write in `appendLedgersMap()` should use full-write semantics and failure handling, because `FileChannel.write(ByteBuffer, position)` is not guaranteed to write all bytes in one call.
6. The main entrylog writer failure should be propagated out of `DbLedgerStorage` / `SyncThread` instead of being only logged and then continuing to accept writes.

For the main entrylog writer, this likely needs fatal/fail-stop handling for the affected bookie process. Continuing to accept writes can persist stale entry locations into RocksDB. Compaction entrylog failures may need a different policy: abort compaction and keep the source entrylog, rather than immediately shutting down the bookie.

***Screenshots***

Physical vs logical position drift diagram:

Image

***Additional context***

Production evidence from the corrupted entrylog:

```text
BookKeeper version: 4.16.7 based deployment
Ledger storage: DbLedgerStorage
Entry logger: DefaultEntryLogger + BufferedChannel
Entrylog file: 855.log
EntryLogId: 2133 decimal / 0x855 hex
writeBufferBytes: 65536
flushEntrylogBytes: 268435456
```

The same delta appears independently in the ledgers map header and in RocksDB entry locations:

```text
delta = 34553

header.ledgersMapOffset = 1073741388
real ledgers map start = 1073775941
delta = 34553

L15069 actual body position - RocksDB indexed position = 34553
```

The delta also matches the 64 KiB write-buffer boundary at the corruption point:

```text
L240727/E17719 sizeStart = 30979
L240727/E17719 bodyStart = 30983
writeBufferBytes = 65536

65536 - 30983 = 34553
```

Physical entry parsing shows that the file becomes a continuous valid physical entry chain again at the 64 KiB boundary:

```text
65536 L38854/E11622 size=11309 next=76849
76849 L38854/E11623 size=24693 next=101546
101546 L38854/E11624 size=19210 next=120760
120760 L38854/E11625 size=32121 next=152885
...
1073770033 L39095/E6725 size=5904 next=1073775941
1073775941 real ledgers map start
```

Independent scan result:

```text
chain_65536_to_map_count = 411693
chain break count = 0
last entry next = 1073775941
```

For ledger `15069`, every RocksDB location in entrylog `2133` becomes valid after adding the same delta:

```text
total_index_rows_log2133 = 569
ok_after_plus_34553 = 569
bad_count = 0
```

Samples:

| entry | RocksDB index body pos | actual body pos | actual sizeStart | size | lid | eid | lac | delta |
| --- | ---: | ---: | ---: | ---: | ---: | ---: | ---: | ---: |
| E0 | 1025196194 | 1025230747 | 1025230743 | 41 | 15069 | 0 | -1 | 34553 |
| E2 | 1025196239 | 1025230792 | 1025230788 | 41 | 15069 | 2 | 1 | 34553 |
| E4 | 1025196284 | 1025230837 | 1025230833 | 41 | 15069 | 4 | 3 | 34553 |

Additional validation:

```text
569 / 569 L15069 entries pass BK V3 + CRC32C validation after +34553.
sum(4 + size) for L15069 = 26164.
The real ledgers map records L15069 TotalSize = 26164.
```

The real ledgers map is also internally consistent with the file size:

```text
real map start = 1073775941
map size = 3236 = 20 + 16 * 201
map bytes = 3240 = 4 + 3236
file size = 1073779181

1073775941 + 3240 = 1073779181
```

Two independent verification passes checked the same evidence:

1. One pass independently confirmed the big-endian header parsing, real ledgers map offset, L15069 CRC32C validation, and `sum(4 + size) = 26164`.
2. Another pass independently mmap-scanned the file and confirmed `65536..1073775941` is a continuous physical entry chain, with `delta_buffer = delta_map = 34553`.

This issue is about the BookKeeper write-path failure mode and fail-closed behavior. It is not a request for corrupted-data repair tooling.

Contributor guide

Open the contributing guide

Research direction

Start with BufferedChannel and run bookkeeper-server's BufferedChannelTest, including the reproducer cases described in the issue. Then trace EntryLogManagerBase.addEntry, BufferedLogChannel.appendLedgersMap, and the DbLedgerStorage/SyncThread failure path. Done means failed writers reject further operations, stale locations and headers are not published, and main-writer versus compaction failure handling is tested.

Written by the indexing model from the issue text.

Assessment

Tech stack
java
Domain
backend, distributed-systems
Issue type
Bug
Difficulty
5/5
Estimated time
Over a week
Activity status
Quiet
Clarity
Mostly clear
Newbie friendliness
35/100

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.