yangxianjungree opened a new issue, #4855:
URL: https://github.com/apache/bookkeeper/issues/4855

   
   **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:
   
   <img width="2443" height="764" alt="Image" 
src="https://github.com/user-attachments/assets/030d575f-eceb-4079-ba88-e024a0ff88b3";
 />
   
   ***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.


-- 
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.

To unsubscribe, e-mail: [email protected]

For queries about this service, please contact Infrastructure at:
[email protected]

Reply via email to