Issue 4855: fail closed on entry log flush failure - #1
Closed
yangxianjungree wants to merge 233 commits into
Closed
Conversation
### Motivation apache#3837 introduced group flush add responses triggered by journal sync. However, if we skip writing journals, the add responses won't be flushed to the netty channel and the client will receive write entries timeout. ### Changes - Flush the add responses when skipping writing journals - Add tests to cover V2 protocol and skip writing journal cases. (cherry picked from commit 5deadcc)
(cherry picked from commit e440132)
…pache#3888) ### Motivation In checkAllLedgers when the ledger no missing fragments, will miss invoke` lh.closeAsync()` to close ledgerHandler, which cause autorecovery not invoke `unregisterLedgerMetadataListener` to release ledger metadata listeners. Heap memory be used too much and maybe will cause OOM; <img width="1567" alt="image" src="https://user-images.githubusercontent.com/84127069/227937422-1113af68-9bf3-4466-97fa-d9b7cc5d72be.png"> ### Changes 1. Invoke` lh.closeAsync()` when no missing fragments; (cherry picked from commit 164417a)
### Motivation There is a critical CVE-2019-10202 in `org.codehaus.jackson:jackson-mapper-asl` Detailed paths Introduced through: org.apache.distributedlog:dlfs@4.16.0-SNAPSHOT › org.apache.hadoop:hadoop-common@3.3.4 › org.apache.avro:avro@1.7.7 › org.codehaus.jackson:jackson-mapper-asl@1.9.2 Fix: No remediation path available. Introduced through: org.apache.distributedlog:dlfs@4.16.0-SNAPSHOT › org.apache.hadoop:hadoop-common@3.3.4 › com.sun.jersey:jersey-json@1.19 › org.codehaus.jackson:jackson-mapper-asl@1.9.2 Fix: No remediation path available. Introduced through: org.apache.distributedlog:dlfs@4.16.0-SNAPSHOT › org.apache.hadoop:hadoop-common@3.3.4 › com.sun.jersey:jersey-json@1.19 › org.codehaus.jackson:jackson-jaxrs@1.9.2 › org.codehaus.jackson:jackson-mapper-asl@1.9.2 Fix: No remediation path available. Introduced through: org.apache.distributedlog:dlfs@4.16.0-SNAPSHOT › org.apache.hadoop:hadoop-common@3.3.4 › com.sun.jersey:jersey-json@1.19 › org.codehaus.jackson:jackson-xc@1.9.2 › org.codehaus.jackson:jackson-mapper-asl@1.9.2 Fix: No remediation path available. ### Changes Upgrade hadoop-common version from 3.3.4 to 3.3.5 to resolve this CVE (cherry picked from commit 0171a40)
(cherry picked from commit df44920)
Execute clean indexes in finally (apache#3772) (cherry picked from commit 04e572b)
Issue apache#3812 Descriptions of the changes in this PR: Fix bug and one UT for verification ### Motivation Fix the bug ### Changes To avoid the ledger being created twice, add a state check before setting a new state (cherry picked from commit b062e9e)
…active (apache#3881) * Fix forceReadOnly * add unittest --------- Co-authored-by: gavingaozhangmin <gavingaozhangmin@didiglobal.com> (cherry picked from commit a6387d1)
* Return activeLogChannel if new create (cherry picked from commit 5beb894)
### Motivation When one ledger file is broken, `getEntryLogMetadata` will throw an IllegalArgumentException, which is a RuntimeException and won't be caught in the whole garbage collector execution path. The exception will be caught by the thread SafeRunnable and interrupt the garbage collector, leading to those deleted ledgers can't be recycled and the ledger disk usage up. ``` 2023-04-01T00:55:29,497+0000 [GarbageCollectorThread-11-1] INFO org.apache.bookkeeper.bookie.GarbageCollectorThread - Garbage collector thread forced to perform GC before expiry of wait time. 2023-04-01T00:55:29,498+0000 [GarbageCollectorThread-11-1] INFO org.apache.bookkeeper.bookie.GarbageCollectorThread - Extracting entry log meta from entryLogId: 17 2023-04-01T00:55:29,498+0000 [GarbageCollectorThread-11-1] INFO org.apache.bookkeeper.bookie.EntryLogger - Failed to get ledgers map index from: 17.log : Cannot deserialize ledgers map from ledger 9062744587808030975 2023-04-01T00:55:29,553+0000 [GarbageCollectorThread-11-1] ERROR org.apache.bookkeeper.common.util.SafeRunnable - Unexpected throwable caught java.lang.IllegalArgumentException: Negative position at sun.nio.ch.FileChannelImpl.read(FileChannelImpl.java:785) ~[?:?] at org.apache.bookkeeper.bookie.BufferedReadChannel.read(BufferedReadChannel.java:93) ~[org.apache.bookkeeper-bookkeeper-server-4.14.5.jar:4.14.5] at org.apache.bookkeeper.bookie.BufferedReadChannel.read(BufferedReadChannel.java:65) ~[org.apache.bookkeeper-bookkeeper-server-4.14.5.jar:4.14.5] at org.apache.bookkeeper.bookie.EntryLogger.readFromLogChannel(EntryLogger.java:418) ~[org.apache.bookkeeper-bookkeeper-server-4.14.5.jar:4.14.5] at org.apache.bookkeeper.bookie.EntryLogger.scanEntryLog(EntryLogger.java:996) ~[org.apache.bookkeeper-bookkeeper-server-4.14.5.jar:4.14.5] at org.apache.bookkeeper.bookie.EntryLogger.extractEntryLogMetadataByScanning(EntryLogger.java:1136) ~[org.apache.bookkeeper-bookkeeper-server-4.14.5.jar:4.14.5] at org.apache.bookkeeper.bookie.EntryLogger.getEntryLogMetadata(EntryLogger.java:1045) ~[org.apache.bookkeeper-bookkeeper-server-4.14.5.jar:4.14.5] at org.apache.bookkeeper.bookie.GarbageCollectorThread.extractMetaFromEntryLogs(GarbageCollectorThread.java:607) ~[org.apache.bookkeeper-bookkeeper-server-4.14.5.jar:4.14.5] at org.apache.bookkeeper.bookie.GarbageCollectorThread.runWithFlags(GarbageCollectorThread.java:348) ~[org.apache.bookkeeper-bookkeeper-server-4.14.5.jar:4.14.5] at org.apache.bookkeeper.bookie.GarbageCollectorThread.safeRun(GarbageCollectorThread.java:329) ~[org.apache.bookkeeper-bookkeeper-server-4.14.5.jar:4.14.5] at org.apache.bookkeeper.common.util.SafeRunnable.run(SafeRunnable.java:36) ~[org.apache.bookkeeper-bookkeeper-common-4.14.5.jar:4.14.5] at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) ~[?:?] at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:305) ~[?:?] at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:305) ~[?:?] at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) ~[?:?] at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) ~[?:?] at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) ~[io.netty-netty-common-4.1.77.Final.jar:4.1.77.Final] at java.lang.Thread.run(Thread.java:829) ~[?:?] ``` ### Changes Catch the RuntimeException when getting the metadata for each entry log file. (cherry picked from commit 8309b18)
…ache#3903) ### Motivation In EntryLocationIndex#removeOffsetFromDeletedLedgers, if there are no ledgers to delete, the key pair will leak. ### Changes Check the ledgers to deletion Set first, and if the set is not empty, then generate the keys. (cherry picked from commit ceba605)
Descriptions of the changes in this PR: https://github.com/apache/bookkeeper/blob/a6387d191f28a59af72f6613b633d6898980a0b0/bookkeeper-server/src/main/java/org/apache/bookkeeper/bookie/GarbageCollectorThread.java#L487-L517 At line 501, increases getReclaimedSpaceViaDeletes stats. https://github.com/apache/bookkeeper/blob/a6387d191f28a59af72f6613b633d6898980a0b0/bookkeeper-server/src/main/java/org/apache/bookkeeper/bookie/GarbageCollectorThread.java#L734-L767 But at line 755, it didn't increase getReclaimedSpaceViaDeletes stats. (cherry picked from commit cad1436)
* Cleanup CbThreadFactory * checkstyle (cherry picked from commit 912896d)
… on all exception paths (apache#3909) Co-authored-by: lushiji <lushiji@didiglobal.com> (cherry picked from commit f1657ea)
…mon to resolve CVE-2019-10202, CVE-2023-1370 and CVE-2022-45685 (apache#3911) ### Motivation #### [CVE-2019-10202](https://www.cve.org/CVERecord?id=CVE-2019-10202) After upgrading the Hadoop version to 3.3.5, the CVE-2019-10202 still exists. Detailed paths Introduced through: org.apache.distributedlog:dlfs@4.16.0-SNAPSHOT › org.apache.hadoop:hadoop-common@3.3.5 › org.apache.avro:avro@1.7.7 › org.codehaus.jackson:jackson-mapper-asl@1.9.13 #### [CVE-2023-1370](https://www.cve.org/CVERecord?id=CVE-2023-1370) Detailed paths Introduced through: org.apache.distributedlog:dlfs@4.16.0-SNAPSHOT › org.apache.hadoop:hadoop-common@3.3.5 › org.apache.hadoop:hadoop-auth@3.3.5 › net.minidev:json-smart@2.4.7 Fix: No remediation path available. #### [CVE-2022-45685](https://www.cve.org/CVERecord?id=CVE-2022-45685) Detailed paths Introduced through: org.apache.distributedlog:dlfs@4.16.0-SNAPSHOT › org.apache.hadoop:hadoop-common@3.3.5 › com.github.pjfanning:jersey-json@1.20 › org.codehaus.jettison:jettison@1.1 Fix: No remediation path available. After checking the code of package `org.apache.distributedlog.fs`, those classes only use `org.apache.hadoop.conf`, `org.apache.hadoop.fs` and `org.apache.hadoop.util` packages. They don't use any Avro-related, json-smart and jersey-json dependencies. It is safe to remove the those dependencies to resolve the CVE issue. https://github.com/apache/bookkeeper/tree/master/stream/distributedlog/io/dlfs/src/main/java/org/apache/distributedlog/fs ### Changes Exclude the Avro dependency from `hadoop-common` (cherry picked from commit 94e15b3)
…apache#3912) (cherry picked from commit 3a9fe1b)
apache#3913) ### Motivation PerChannelBookieClient completionObjects occupy a lot of heap space and cannot be recycled. The figure below shows that the internal table array of ConcurrentOpenHashMap has used space size=0, but the array length is still 16384, and the memory overhead is 65552bytes.   ConcurrentOpenHashMap default DefaultConcurrencyLevel=16. We have hundreds of bookie nodes. Due to the feature of bookie polling and writing, the client and server have long connection characteristics, which will as a result, the memory usage of about 65552 * 16 * 1776 = 1.74GB cannot be recycled, and the space take up by these tables is all size=0 (The broker's owner topic has drifted to other brokers due to Full GC).  When the throughput of the pulsar cluster increases and the bookie cluster expands, these memory usage will also increase. Coupled with the unreasonable memory usage in other aspects of pulsar that we know, this will cause the pulsar broker to continuously generate full gc. ### Changes I think adding autoShrink to completionObjects can reduce this part of memory usage and reduce the frequency of Full GC. (cherry picked from commit ca33b31)
(cherry picked from commit 35e9da9)
…he#3917) ### Motivation When I decommission one bookie (bk3), one ledger replicate failed and blocked decommission process. This is the auto-recovery log: ``` 2023-03-29T06:29:22,642+0000 [ReplicationWorker] ERROR org.apache.bookkeeper.client.LedgerHandle - ReadEntries exception on ledgerId:904368 firstEntry:14 lastEntry:14 lastAddConfirmed:13 2023-03-29T06:29:22,642+0000 [ReplicationWorker] ERROR org.apache.bookkeeper.replication.ReplicationWorker - Received error: -1 while trying to read entry: 14 of ledger: 904368 in ReplicationWorker 2023-03-29T06:29:22,642+0000 [ReplicationWorker] ERROR org.apache.bookkeeper.replication.ReplicationWorker - Failed to read faulty entries, so giving up replicating ledgerFragment Fragment(LedgerID: 904368, FirstEntryID: 0[0], LastKnownEntryID: 14[14], Host: [betausc1-bk-10.betausc1-bk-headless.o-vaxkx.svc.cluster.local:3181], Closed: true) 2023-03-29T06:29:22,644+0000 [ReplicationWorker] ERROR org.apache.bookkeeper.replication.ReplicationWorker - ReplicationWorker failed to replicate Ledger : 904368 for 6 number of times, so deferring the ledger lock release by 300000 msecs ``` The ledger's metadata: ``` ledgerID: 904368 2023-03-29T06:47:56,511+0000 [main] INFO org.apache.bookkeeper.tools.cli.commands. client.LedgerMetaDataCommand - LedgerMetadata{formatVersion=3, ensembleSize=3, writeQuorumSize=3, ackQuorumSize=2, state=OPEN, digestType=CRC32C, password=base64:, ensembles={0=[bk1:3181, bk2:3181, bk3:3181], 15=[bk1:3181, bk2:3181, bk4:3181]},...} ``` The ledger (904368) has two ensembles, `ensembles={0=[bk1:3181, bk2:3181, bk3:3181], 15=[bk1:3181, bk2:3181, bk4:3181]}`. However, the replication worker got the ledger's LAC is 13, but it got the replication fragment entry range is [0, 14]. When reading entry 14, it failed. ### One question **Why the ensembles created a new ensemble starting with entryId = 15, but the ledger's lastAddConfirm is 13.** This question is related to two parts, one is how the new ensemble was created and the other is how the lastAddConfirm was generated. #### 1. How the new ensemble was created The ensemble change is controlled on the bookie client side. When one entry is ready to send to the bookie server, the bookie client will check whether need to do the ensemble change. https://github.com/apache/bookkeeper/blob/912896deb2e748389e15e74c37539b2ff36302c7/bookkeeper-server/src/main/java/org/apache/bookkeeper/client/PendingAddOp.java#L254 For the above case, when writing entry 15, one bookie is lost, it will trigger the ensemble change and generate the new ensemble: 15=[bk1:3181, bk2:3181, bk4:3181]. However, entry 15 write failed, such as timeout or bookie server rejected the write. For now, entry 14 is written succeed. #### 2. How the lastAddConfirm was generated Due to the ledger being in the `OPEN` state, the ledger handle will send a readLAC request according to the last ensemble to get the ledger's lastAddConfirm. For the above case, the readLAC request will send to bk1, bk2, and bk4. For the `V2` protocol (Pulsar uses the V2 protocol to interact with the BookKeeper cluster), the bookie client put the lastAddConfirm EntryId in the next Entry's metadata. https://github.com/apache/bookkeeper/blob/df4492012cc03682534cbc8dd68dd81163b0c947/bookkeeper-server/src/main/java/org/apache/bookkeeper/proto/checksum/DigestManager.java#L134 When we use the `V2` protocol to open an `OPEN` state ledger to read, it will send a readLastAddConfirm request to the bookie server, and the bookie server gets the last entry of this ledger and return to the client. https://github.com/apache/bookkeeper/blob/df4492012cc03682534cbc8dd68dd81163b0c947/bookkeeper-server/src/main/java/org/apache/bookkeeper/client/ReadLastConfirmedOp.java#L108 However, the bookie client will parse the response entry and get the lastAddConfirm from the entry's metadata. Due to the entry just recording the previous EntryId as the lastAddConfirm, the LedgerHandle got the lastAddConfirm will be the penultimate EntryId of the ledger. For the above case, the bk1 holds the max entry 14, bk2 holds the max entry 14, and bk4 returns NoSuchEntryException, LedgerHandle gets lastAddConfirm will be `14 - 1 = 13`, not 14. When the replicator tries to recover the first ensemble 0=[bk1:3181, bk2:3181, bk3:3181] with entry range [0, 14], reading entry 14 will throw a ReadEntryException due to the lastAddConfirm is 13. https://github.com/apache/bookkeeper/blob/df4492012cc03682534cbc8dd68dd81163b0c947/bookkeeper-server/src/main/java/org/apache/bookkeeper/client/LedgerHandle.java#L685-L690 ### Solution When encountered that case that - The ledger is `OPEN` - The ledger has multiple ensembles - The ledger's last ensemble doesn't have any entries, which means `lastAddConfirm < last ensemble key - 1` We should treat the penultimate segment/ensemble of the ledger as an `OPEN` state instead of a closed state. https://github.com/apache/bookkeeper/blob/df4492012cc03682534cbc8dd68dd81163b0c947/bookkeeper-server/src/main/java/org/apache/bookkeeper/client/LedgerFragment.java#L56-L57 After we treat the segment/ensemble as `OPEN` state, the replicator will close the ledger first and replicate it. (cherry picked from commit eff38e4)
…ache#4607) * Fix the data loss issue that caused by the wrong entry log header --- # Motivation We observed numerous errors in the broker that failed to read the ledger from the bookkeeper; although the ledger metadata still exists, it was unable to read from the bookkeeper. After checking the data, we found the ledger located entry log was deleted by the bookkeeper. We have a data loss issue with the bookkeeper. The entry log file was deleted by the Garbage collector because the entry log file wrote a wrong file header. And there is an example that the shows the header is wrong: ``` Failed to get ledgers map index from: 82.log : Not all ledgers were found in ledgers map index. expected: -1932430239 -- found: 0 -- entryLogId: 82 ``` * Add test
…pache#4504) (cherry picked from commit 07de650)
…ache#4557) [fix] Write stuck due to pending add callback by multiple threads (apache#4557) (cherry picked from commit e47926b)
* fix pendingDeletedLedgers not remove ledger (cherry picked from commit 0df3caf)
…pache#4586) (cherry picked from commit 7fbb8d8)
### Motivation & Changes Upgrade Jetty to 9.4.57.v20241219 to address CVE-2024-6763 Jetty 9.4.57.v20241219 contains backported CVE-2024-6763 fix in jetty/jetty.project#12532 although it's not explicitly mentioned and most security scanners don't yet contain the information that it's been addressed in 9.4.57. More details: * jetty/jetty.project#12630 * https://github.com/jetty/jetty.project/releases/tag/jetty-9.4.57.v20241219 Note: The backport is a partial mitigation and Jetty 9.4.57 will continue to be marked as vulnerable. There's a discussion and explanation here: https://gitlab.eclipse.org/security/cve-assignement/-/issues/25#note_2968611 (cherry picked from commit 99eb63a)
(cherry picked from commit 175e294)
### Motivation We met the GarbageCollectionThread was stopped by some runtime error, but we didn't catch it then, causing the GC to stop. Such as: apache#3901 apache#4544 In our case, the GC stopped because of the OutOfDirectMemoryException then the process stopped and the files can not be deleted. But we didn't see any error logs. This PR enhance the log info when an unhandled error happens. We already have the [PR](apache#4544) fixed that. And another fix in this PR is to change the Exception to the Throwable in the getEntryLogMetadata. Here is the error stack: ``` io.netty.util.internal.OutOfDirectMemoryError: failed to allocate 213909504 byte(s) of direct memory (used: 645922847, max: 858783744) at io.netty.util.internal.PlatformDependent.incrementMemoryCounter(PlatformDependent.java:880) at io.netty.util.internal.PlatformDependent.allocateDirectNoCleaner(PlatformDependent.java:809) at io.netty.buffer.PoolArena$DirectArena.allocateDirect(PoolArena.java:718) at io.netty.buffer.PoolArena$DirectArena.newUnpooledChunk(PoolArena.java:707) at io.netty.buffer.PoolArena.allocateHuge(PoolArena.java:224) at io.netty.buffer.PoolArena.allocate(PoolArena.java:142) at io.netty.buffer.PoolArena.reallocate(PoolArena.java:317) at io.netty.buffer.PooledByteBuf.capacity(PooledByteBuf.java:123) at io.netty.buffer.AbstractByteBuf.ensureWritable0(AbstractByteBuf.java:305) at io.netty.buffer.AbstractByteBuf.ensureWritable(AbstractByteBuf.java:280) at io.netty.buffer.AbstractByteBuf.writeBytes(AbstractByteBuf.java:1103) at org.apache.bookkeeper.bookie.BufferedReadChannel.read(BufferedReadChannel.java:104) at org.apache.bookkeeper.bookie.DefaultEntryLogger.extractEntryLogMetadataFromIndex(DefaultEntryLogger.java:1109) at org.apache.bookkeeper.bookie.DefaultEntryLogger.getEntryLogMetadata(DefaultEntryLogger.java:1060) at org.apache.bookkeeper.bookie.GarbageCollectorThread.extractMetaFromEntryLogs(GarbageCollectorThread.java:678) at org.apache.bookkeeper.bookie.GarbageCollectorThread.runWithFlags(GarbageCollectorThread.java:365) at org.apache.bookkeeper.bookie.GarbageCollectorThread.lambda$triggerGC$4(GarbageCollectorThread.java:268) at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Unknown Source) at java.base/java.util.concurrent.FutureTask.run(Unknown Source) at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(Unknown Source) at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source) at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source) at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) at java.base/java.lang.Thread.run(Unknown Source) ``` You can see it get much more memory used here extractEntryLogMetadataFromIndex(DefaultEntryLogger.java:1109). The reason is that the header has the wrong data of the header, which should already be fixed by apache#4607. Then it reading with a wrong map size which could take a lot of memory. (cherry picked from commit e80d031)
(cherry picked from commit 5870922)
* [fix]BK stay at read_only state even if the disk is empty * correct the javadoc * improve test (cherry picked from commit bde9ff2)
(cherry picked from commit 1a509e4)
|
Bugbot is not enabled for your account, so this pull request was not reviewed. Enable Bugbot in the Cursor dashboard to get automatic reviews on future PRs. |
yangxianjungree
changed the title
Owner
Author
|
Closing this fork-to-fork PR because the fix is now submitted upstream against apache/bookkeeper:branch-4.16 in apache#4860. |
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
20 participants
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
Descriptions of the changes in this PR:
This PR changes entry log flush failure handling so the bookie fails closed when the entry-log write path becomes uncertain. It also adds a real client e2e reproducer for the failure path.
Motivation
Entry-log write, flush, rotation, or allocation failures can leave the bookie in an uncertain state. Continuing to serve after those failures risks silent corruption or inconsistent recovery.
Changes
EntryLogWriteExceptionas the fatal boundary for entry-log-level failures.SyncThread,BookieImpl,DbLedgerStorage,SingleDirectoryDbLedgerStorage, andSortedLedgerStoragestop the bookie on these failures.NoWritableLedgerDirExceptionbehavior unchanged.Master Issue: apache#4855
Tests:
mvn -pl bookkeeper-server -am -Dtest=DbLedgerStorageEntryLogFlushFailureE2ETest -Dsurefire.failIfNoSpecifiedTests=false testmvn -pl bookkeeper-server -am -Dtest=DbLedgerStorageEntryLogFlushFailureE2ETest,BookieImplTest,SyncThreadTest,DbLedgerStorageWriteCacheTest -Dsurefire.failIfNoSpecifiedTests=false test