[
https://issues.apache.org/jira/browse/HDDS-17668?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Siyao Meng updated HDDS-17668:
------------------------------
Attachment: TestBugMC2OutOfOrderPutBlockHandlers.java
> PutBlock reply handlers of a Ratis BlockOutputStream can run out of order, so
> close() can commit wrong data and OM can get an older bcsId
> -----------------------------------------------------------------------------------------------------------------------------------------
>
> Key: HDDS-17668
> URL: https://issues.apache.org/jira/browse/HDDS-17668
> Project: Apache Ozone
> Issue Type: Bug
> Affects Versions: 2.0.0, 1.4.1, 2.1.0, 2.2.0, 2.1.1, 2.1.2, 2.2.1, 2.2.2
> Reporter: Siyao Meng
> Priority: Critical
> Attachments: MC-2-handle-putblock-replies-in-order.patch,
> TestBugMC1BcsIdGoesBack.java, TestBugMC2OutOfOrderPutBlockHandlers.java
>
>
> h3. Mechanism
> {{BlockOutputStream.executePutBlock}} handles each PutBlock reply with
> {{thenApplyAsync(..., responseExecutor)}}, and so does
> {{writeChunkToContainer}} for a WriteChunk that carries a piggybacked
> PutBlock. Since HDDS-10384 (1.4.1) {{responseExecutor}} is the
> {{writeExecutor}} of {{RpcClient}}, shared by all streams of the client: a
> {{ThreadPoolExecutor}} with core size 1, no maximum and a
> {{SynchronousQueue}}, so a handler gets a new thread whenever no thread is
> idle. Before 1.4.1 each stream had its own single thread executor, which kept
> its handlers in order. The Ratis client completes the reply futures of one
> client in arrival order ({{SlidingWindow.Client.receiveReply}}), but when the
> replies of PutBlock 1 and PutBlock 2 arrive close together the two handlers
> run on two threads and nothing orders them. Nothing else serializes them
> either: the handlers do not take the stream lock.
> A handler does two things that assume it runs after the handlers of the
> earlier PutBlocks:
> * {{handleSuccessfulPutBlock}} sets the block ID, including the bcsId, from
> the reply with {{blockID.set(responseBlockID)}}. If the handler of PutBlock 1
> runs last, the bcsId goes back to the one of PutBlock 1.
> {{BlockOutputStreamEntry.close}} then sends that bcsId to OM with the full
> block length.
> * It registers the PutBlock's buffers in {{CommitWatcher}} under its log
> index, and the watch chained on it releases every registered index up to the
> index the watch returns ({{AbstractCommitWatcher.adjustBuffers}}). If the
> handler and watch of PutBlock 2 run before the handler of PutBlock 1, only
> the buffers of PutBlock 2 are released and {{totalAckDataLength}} counts data
> that is not the start of the block. If the block now fails (for example
> {{CLOSED_CONTAINER_IO}} because SCM closed the container) before the handler
> of PutBlock 1 runs, that handler fails in {{validateResponse}} on the stored
> exception and never registers its buffers, although the datanode applied
> PutBlock 1. {{KeyOutputStream.handleExceptionInternal}} then records the
> acknowledged length (the size of PutBlock 2's data) as the length of the
> failed block and rewrites the buffers still allocated, which hold PutBlock
> 1's data, to a new block.
> The TODO in {{CommitWatcher.releaseBuffers}} ("When there are concurrent
> watchForCommits, there's no guarantee of the order of execution") points at
> the same ordering gap.
> h3. Trigger
> Two PutBlocks of one block whose replies arrive close together, which is
> normal for asynchronous writes where several PutBlocks are in flight, and a
> thread schedule in which the handler of the later one runs first.
> * Older bcsId at OM: nothing else is needed.
> * Wrong data committed: in addition, a later request on the same block must
> fail, and its handler must run before the handler of PutBlock 1. That is most
> likely when the failing reply arrives in the same burst, for example when SCM
> closes the container between PutBlock 2 and the next request. This was only
> reproduced with the handler order controlled.
> h3. Impact
> * *close() succeeds and the key holds wrong data.* With 1 MB buffers and two
> 1 MB writes ('A' then 'B'), the container closed before the PutBlock sent by
> {{close()}}, and the handler of PutBlock 1 started last: {{close()}} returns
> normally, OM commits two 1 MB blocks (the first in the old container, the
> second the rewritten 'A' buffer) and the key reads back as 'A' x 2097152. The
> 'B' megabyte is lost. The in order control with the same container close
> reads back correctly. [^TestBugMC2OutOfOrderPutBlockHandlers.java]
> * *OM records an older bcsId with the full length.* Same writes without a
> failure: OM gets bcsId 1 (PutBlock 1) instead of 2 for a block of 2 MB.
> [^TestBugMC1BcsIdGoesBack.java] A replica that has applied PutBlock 1 but not
> yet PutBlock 2 then passes {{BlockUtils.verifyBCSId}} and the block bcsId
> check in {{BlockManagerImpl.getBlock}} and serves the shorter block, where
> the correct bcsId would make it answer with an error ({{UNKNOWN_BCSID}} or
> {{BCSID_MISMATCH}}) so that the reader moves to the next replica. In a three
> datanode mini cluster run with a test only hook that holds PutBlock apply on
> one follower, stopping the leader made the read of the key fail with
> "Inconsistent read" while an up to date replica was alive; a control key in
> the same container read fine. The key had been committed with bcsId 2 while
> the container bcsId on the leader was 6. The hook only delays apply, not Raft
> commit, so it stands in for a slow follower. With the patch the same run
> commits bcsId 6, equal to the container bcsId on the leader, and the read
> moves on to the up to date replica and succeeds. This run needs a hook in
> production code, so it is not attached.
> * By code reading, not run: data acknowledged by {{hsync()}} is exposed in
> the same way, because {{hsync()}} waits only for the latest PutBlock and its
> watch, not for the handlers of earlier PutBlocks.
> h3. Reproduction
> The two attached classes are self contained (target path and Maven command in
> each class comment). They drive the real {{OzoneClient}}, {{RpcClient}},
> {{KeyOutputStream}}, {{RatisBlockOutputStream}} and {{CommitWatcher}} over
> the existing client test mocks ({{MockOmTransport}},
> {{MockXceiverClientFactory}}), with a scripted datanode that gives PutBlocks
> increasing log indexes, completes their replies in log order and returns the
> log index as bcsId. The only timing control is an executor that replaces the
> private {{RpcClient.writeExecutor}} field by reflection: it runs each handler
> on its own thread and starts the handler of PutBlock 1 last. Everything else
> goes through the public client API. Each class has an in order control case.
> On unmodified source the out of order cases fail ({{expected: "A x 1048576, B
> x 1048576" but was: "A x 2097152"}} and {{bcsId committed to OM expected: 2L
> but was: 1L}}) and the controls pass; with the patch all cases pass. They
> show that the order is reachable and what follows from it, not how often it
> happens.
> h3. Patch
> [^MC-2-handle-putblock-replies-in-order.patch], against
> ec5ed5f7ea0e4b406aee53aae4906616819cba2b. It also applies to master at
> b683fd3f294.
> Each PutBlock reply handler (including a WriteChunk with a piggybacked
> PutBlock) now runs with {{thenCombineAsync}} on a future that completes when
> the handler of the previous PutBlock of the stream has finished, successfully
> or not, so the handlers of one stream run in the order the PutBlocks were
> sent. The executor and its thread reuse stay as they are. This fixes both
> symptoms at the cause: the bcsId only moves forward, and the registered
> buffers are always the prefix of the PutBlocks handled so far, so the
> acknowledged length is always a prefix of the block. A WriteChunk reply
> handler also waits for the handler of the PutBlock sent before it, so a later
> error can no longer overtake the success of an earlier PutBlock.
> {{ECBlockOutputStream}} overrides {{executePutBlock}} and never piggybacks,
> so EC writes are unchanged. The piggybacked WriteChunk plus PutBlock path
> ({{ozone.client.stream.putblock.piggybacking}}, off by default) gets the same
> change and is covered by code reading only; no test runs it. The replies of
> one stream arrive in order and the handlers do no I/O, so the added wait is
> at most the run time of the previous handler; no throughput change is
> expected, but this was not benchmarked. One behaviour change: {{hsync()}} and
> a write that waits for a full buffer now return only after the handlers of
> all earlier PutBlocks have run, not only the latest one.
> A forward only bcsId update in {{handleSuccessfulPutBlock}} would fix only
> the bcsId symptom. Making {{CommitWatcher}} release only a contiguous prefix
> would need the expected log indexes before the replies arrive and would still
> leave the bcsId symptom.
> Two cases in the existing {{TestBlockOutputStreamCorrectness}}, with an
> executor that holds the handlers and runs the most recent one first:
> {{testBcsIdOfLatestPutBlockWhenReplyHandlersRunLate}} and
> {{testUnackedBuffersFollowAckedLengthWhenReplyHandlersRunLate}}. Without the
> change they fail ("expected: 10L but was: 5L", and the unacknowledged buffers
> after 1048576 acknowledged bytes hold the first megabyte instead of the
> following data); with it they pass. The unit tests of {{hdds-client}} and
> {{ozone-client}} and the mini cluster suites {{TestBlockOutputStream}},
> {{TestBlockOutputStreamWithFailures}}, {{TestCommitWatcher}},
> {{TestWatchForCommit}}, {{TestFailureHandlingByClient}},
> {{TestFailureHandlingByClientFlushDelay}},
> {{TestOzoneClientRetriesOnExceptions}},
> {{TestOzoneClientRetriesOnExceptionFlushDelay}},
> {{TestMultiBlockWritesWithDnFailures}},
> {{TestCloseContainerHandlingByClient}} and {{TestHSync}} pass, and checkstyle
> is clean.
> Found by TLA+ model checking and code review of the Ozone client Ratis block
> write and failure handling paths under HDDS-15926, on commit
> ec5ed5f7ea0e4b406aee53aae4906616819cba2b. Checked against HDDS issues and
> apache/ozone pull requests for duplicates before filing. Related but not
> duplicates: HDDS-6139 (resolved, {{totalAckDataLength}} in the streaming
> write path), HDDS-16262 (resolved, cleanup races in
> {{AbstractCommitWatcher}}), HDDS-17648 / #11890 (open, a watch that never
> completes after the client is closed) and HDDS-15271 (open, the reader
> preferring replicas that cover the block bcsId). The attached patch is a
> proposal for review. Generated with Specula (Claude Opus 5.5).
--
This message was sent by Atlassian Jira
(v10.3.26#10030026)
---------------------------------------------------------------------
To unsubscribe, e-mail: [email protected]
For additional commands, e-mail: [email protected]
