[
https://issues.apache.org/jira/browse/HDDS-17673?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Siyao Meng updated HDDS-17673:
------------------------------
Affects Version/s: 2.2.1
2.0.0
1.4.0
2.1.2
1.1.0
0.5.0
1.0.0
1.2.1
1.2.0
2.1.0
1.4.1
2.1.1
2.2.2
1.3.0
2.2.0
> WriteChunk appended after its container's CloseContainer commits with no data
> on the leader, so a lagging follower makes it close the pipeline
> ----------------------------------------------------------------------------------------------------------------------------------------------
>
> Key: HDDS-17673
> URL: https://issues.apache.org/jira/browse/HDDS-17673
> Project: Apache Ozone
> Issue Type: Bug
> Affects Versions: 0.5.0, 1.0.0, 1.1.0, 1.2.0, 1.3.0, 1.2.1, 1.4.0, 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: Minor
> Attachments: TestBugCR4LaggingFollowerReread.java
>
>
> h3. Mechanism
> {{ContainerStateMachine.startTransaction}} checks that the container is open,
> but the entry only gets its log index later, in
> {{RaftServerImpl.appendTransaction}}. {{CloseContainerCommandHandler}} marks
> the container CLOSING and submits a CloseContainer through Raft, and that
> entry can be appended between the check and the append of a WriteChunk. The
> WriteChunk then follows the CloseContainer in the log. If its data stage on
> the leader runs after the CloseContainer was applied, {{KeyValueHandler}}
> returns CLOSED_CONTAINER_IO, which
> {{ContainerStateMachine.handleCommandResult}} treats as success, so the entry
> commits although the leader wrote none of its bytes.
> With {{hdds.datanode.wait.on.all.followers=false}} (the default) the leader
> drops the entry from {{stateMachineDataCache}} when it applies it. A follower
> that does not have the entry yet is then served by
> {{ContainerStateMachine.readStateMachineData}}, which reads the chunk range
> back from the leader's block file. That read fails ("Unexpected read size"),
> the leader marks its state machine unhealthy and the pipeline is closed. The
> follower never receives the entry.
> CHUNK_FILE_INCONSISTENCY, the other result tolerated in the data stage, does
> not add a separate case: it marks the replica UNHEALTHY and the apply of the
> same WriteChunk then fails with CONTAINER_UNHEALTHY, which closes the
> pipeline anyway.
> h3. Trigger
> # A RATIS/THREE pipeline where one follower is behind (for example stopped or
> restarting) while the leader and the other follower commit.
> # A client WriteChunk passes the leader's {{startTransaction}} check while
> the container is OPEN.
> # Before that WriteChunk is appended, SCM's close command reaches the leader
> and the CloseContainer is appended.
> # The leader runs the WriteChunk's data stage only after the CloseContainer
> has been committed and applied. If it runs while the container is still
> CLOSING, the bytes are written and nothing goes wrong.
> # The lagging follower comes back and needs the WriteChunk.
> The first window is short. The second needs the chunk writer thread on the
> leader to be backlogged for longer than the CloseContainer takes to commit
> and apply, which a busy disk can cause (argued, not measured). On top of that
> a follower has to be behind at the same time, so this is a rare race.
> h3. Impact
> * The leader's state machine goes unhealthy and the pipeline is closed.
> Writes to every other open container on the pipeline fail and clients have to
> continue on another pipeline.
> * The lagging follower does not catch up through Raft. Its replica is closed
> with the pipeline and repaired by replication.
> * No data is lost and no wrong data is served: the CloseContainer precedes
> the WriteChunk on every replica, so the WriteChunk and any later PutBlock for
> that container fail at apply on every replica.
> h3. Reproduction
> [^TestBugCR4LaggingFollowerReread.java] ({{hadoop-ozone/integration-test}}),
> unmodified source. One mini cluster with three datanodes, one follower
> stopped while the race happens and restarted afterwards. The only timing
> control is Ratis' {{CodeInjectionForTesting}} hook at
> {{RaftServerImpl.appendTransaction}}, which holds one WriteChunk after
> {{startTransaction}} while a real SCM close command is processed by the
> leader. A passing test means the defect is present; it passed in every run.
> Example output on the unfixed code (indexes, counts and the exact client
> error vary per run):
> {noformat}
> W1 result=CLOSED_CONTAINER_IO, leader block file length=1024, leader
> healthy=true, leader applied=10
> ReadStateMachine failed. cmd ReadChunk logIndex 9 msg : Unexpected read size.
> expected: 1024, actual: -1 Container Result: CONTAINER_INTERNAL_ERROR
> pipeline Action CLOSE on pipeline Pipeline-...Reason : Unexpected read size.
> expected: 1024, actual: -1
> Pipeline Pipeline-... moved to CLOSED state
> after follower restart: leader healthy=false, read failures=1, follower
> applied=3 of 10
> write to the other open container on the same pipeline:
> java.util.concurrent.ExecutionException:
> org.apache.ratis.protocol.exceptions.RaftRetryFailureException: ...
> {noformat}
> The read failure is logged thousands of times per run because the leader
> keeps retrying the follower. The follower's applied index stays below the
> leader's (or reads as -1 when its division has not started yet), and the
> write to the other container fails with {{RaftRetryFailureException}} or a
> timeout, depending on the run.
> h3. Suggested fix
> Re-check the container state of a WriteChunk in
> {{ContainerStateMachine.preAppendTransaction}}, which Ratis calls on the
> leader under the log lock right before the entry gets its index, and reject
> it with a {{StateMachineException}} ({{leaderShouldStepDown=false}}) wrapping
> {{ContainerNotOpenException}} if the container is no longer open. Since the
> CloseContainer is submitted only after the container is marked CLOSING, a
> WriteChunk can then no longer follow it in the log, and the client sees the
> same error as for a rejection in {{startTransaction}}. With this change
> applied locally, the reproduction above fails at its first assertion: the
> held WriteChunk is rejected, the follower catches up and the pipeline stays
> open.
> This depends on RATIS-2722, fixed in Ratis 3.4.0, which is not released yet.
> Ratis 3.3.1, used by Ozone today, does not release the leader's pending write
> quota for a request rejected in {{preAppendTransaction}}, so on 3.3.1 enough
> rejections in one leader term would leave the leader refusing all writes. The
> change should land together with or after the upgrade to Ratis 3.4.0.
> Related: HDDS-1753 and HDDS-11955 hit the same re-read failure in
> {{readStateMachineData}} for a lagging follower, with a different cause (the
> block was deleted by a later entry).
> Found by code review of the datanode container state machine apply and block
> commit paths, as part of the TLA+ verification effort under HDDS-15926, on
> commit ec5ed5f7ea0e4b406aee53aae4906616819cba2b. Checked against HDDS issues
> and apache/ozone pull requests for duplicates before filing. 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]
