Siyao Meng created HDDS-17668:
---------------------------------
Summary: 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
Reporter: Siyao Meng
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]
