[
https://issues.apache.org/jira/browse/HDDS-17674?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Siyao Meng updated HDDS-17674:
------------------------------
Attachment: CR-12-close-raft-division-asynchronously-on-write-failure.patch
> Datanode closes the Raft division on the Ratis thread that called write(), so
> after a write timeout the close hangs and the replica stays CLOSING
> -------------------------------------------------------------------------------------------------------------------------------------------------
>
> Key: HDDS-17674
> URL: https://issues.apache.org/jira/browse/HDDS-17674
> Project: Apache Ozone
> Issue Type: Bug
> Reporter: Siyao Meng
> Priority: Major
> Attachments:
> CR-12-close-raft-division-asynchronously-on-write-failure.patch,
> TestBugCR12ClosedDivisionStaysActive.java
>
>
> h3. Mechanism
> HDDS-15443 added {{ContainerStateMachine.closeServer}}, which {{write()}}
> calls when writing state machine data fails. It calls
> {{RaftServer.Division.close()}} on the thread that completes the failed
> future. When {{write()}} fails synchronously, that is the Ratis thread that
> called {{write()}}: on the write timeout ({{validateLongRunningWrite}}),
> {{writeStateMachineData}} returns an already failed future and
> {{whenComplete}} runs {{closeServer}} inline. On a leader this is a
> {{clientExecutor}} thread (observed); on a follower it is a
> {{serverExecutor}} thread ({{RaftServerImpl.appendLog}}, read only).
> In Ratis 3.3.1 {{RaftServerImpl.close()}} ends with
> {{ConcurrentUtils.shutdownAndWait(clientExecutor)}} and
> {{shutdownAndWait(serverExecutor)}}, which wait up to
> {{TimeDuration.ONE_DAY}} for the executor to terminate. The calling thread
> belongs to that executor, so the close waits for itself for a day, with the
> division in CLOSING. {{RaftServerImpl.groupRemove}} waits on
> {{closeFinishedLatch}} for that close, so {{notifyGroupRemove}} does not run
> and {{XceiverServerRatis.activePipelines}} keeps the group.
> {{XceiverServerRatis.isExist}} therefore stays true.
> h3. Trigger
> # A WriteChunk on a Ratis pipeline stays pending longer than
> {{hdds.container.ratis.statemachine.write.wait.interval}} (10 minutes by
> default, for example a stalled disk) while another WriteChunk arrives.
> # {{validateLongRunningWrite}} throws and {{closeServer}} runs inline on the
> Ratis thread.
> Other synchronous failures of {{writeStateMachineData}} take the same path
> (read only). When the chunk write itself fails, {{closeServer}} usually runs
> on a chunk executor thread, which {{close()}} does not wait for.
> h3. Impact
> What happens next depends on whether the in-flight WriteChunk, cancelled by
> the timeout, fails or completes:
> * If it fails, its log entry reaches {{notifyLogFailed}} and SCM closes the
> pipeline and the container. On the datanode {{CloseContainerCommandHandler}}
> sees {{isExist}} true and submits the close through the dead group, which
> fails with {{ServerNotReadyException}} and later {{GroupMismatchException}}.
> ClosePipeline blocks in {{groupRemove}}. The replica, and the container in
> SCM, stay CLOSING. Observed: 19 failed close attempts in 90 seconds.
> * If it completes, nothing tells SCM: the only failed entry is the timed out
> one, and its log task is never created because its constructor is the frame
> stuck in {{closeServer}}. Observed: no pipeline action, ClosePipeline or
> CloseContainer in 90 seconds, {{isExist}} true.
> * The datanode runs ClosePipeline commands on a single thread
> ({{DatanodeStateMachine}}), so while it waits in {{groupRemove}} every other
> ClosePipeline on that datanode queues behind it (read from code, not run).
> * The state clears when the one day wait in {{shutdownAndWait}} expires or
> the datanode restarts (read from the Ratis source, not run).
> Only master is affected; HDDS-15443 is not in a release.
> h3. Reproduction
> [^TestBugCR12ClosedDivisionStaysActive.java]
> ({{hadoop-ozone/integration-test}}) starts a MiniOzoneCluster with one
> datanode and a RATIS/ONE pipeline, sets
> {{hdds.container.ratis.statemachine.write.wait.interval}} to 1us as a stand
> in for a stalled disk, writes one small key to create an OPEN container, then
> writes a multi chunk key so that a second WriteChunk trips the timeout. It
> then expects the replica to be QUASI_CLOSED and {{isExist}} to be false
> within 90 seconds. Public client writes and a real config key only, no source
> change. Which branch a run takes is not under the test's control; most runs
> took the first one.
> Without the fix it failed in both runs with {{pipeline ... of the closed
> division is still reported as existing}}; one run took each branch, and the
> first branch run ended with {{isExist=true replica=CLOSING
> scmPipeline=REMOVED scmContainer=CLOSING}}. With the fix it passed in every
> run that started (three with the asynchronous close alone, one with the
> attached patch), ending with {{isExist=false replica=QUASI_CLOSED
> scmPipeline=REMOVED scmContainer=QUASI_CLOSED}}; all took the first branch.
> To check the second branch with the patch I forced it in a scratch copy only
> (the timeout cancels without interrupting, and each chunk write first waits
> 1.5 seconds without being interruptible, so the in-flight write completes).
> With just the asynchronous close the reproduction ended {{isExist=true
> replica=OPEN scmPipeline=OPEN scmContainer=OPEN}}: closing the division stops
> the Raft log worker before it runs the failed entry's log task, so
> {{notifyLogFailed}} never runs. With the attached patch it ended
> {{isExist=false replica=QUASI_CLOSED scmPipeline=REMOVED
> scmContainer=QUASI_CLOSED}}.
> h3. Suggested fix
> The patch runs the close on another thread, which removes the self wait, and
> reports the failure to SCM from there. Two alternatives were considered and
> not used: removing the group from {{activePipelines}} in {{closeServer}} (or
> checking the division in {{isExist}}) would make ClosePipeline skip
> {{removeGroup}} and leave the hang in place; a quasi close fallback in
> {{CloseContainerCommandHandler}} on {{ServerNotReadyException}} would also
> fire while a healthy division is starting.
> h3. Patch
> [^CR-12-close-raft-division-asynchronously-on-write-failure.patch], against
> ec5ed5f7ea0e4b406aee53aae4906616819cba2b. It also applies to master at
> 7294fc2da18.
> {{closeServer}} still logs and counts the failure on the calling thread. It
> then runs, with {{CompletableFuture.runAsync}},
> {{XceiverServerRatis.handleNodeLogFailure}} (the pipeline action
> {{notifyLogFailed}} would send; it is idempotent, so the normal log failure
> path is unaffected) followed by {{getDivision(groupId).close()}}. This is the
> same idiom {{ContainerStateMachine.notifyServerShutdown}} uses to leave the
> Ratis thread before work that waits for the group to close. The close then
> finishes in about 3 seconds (the log worker's own shutdown wait),
> ClosePipeline removes the group, and {{notifyGroupRemove}} removes it from
> {{activePipelines}} and quasi closes its containers. Writes that do not fail
> are unaffected.
> The close runs on the common pool, so a stall that closes many divisions at
> once keeps several common pool threads busy for a few seconds each. No
> existing executor fits: the chunk executors and the container op executor of
> {{ContainerStateMachine}} can be stuck behind the stalled disk, and the
> latter is shut down by this very close. A small dedicated executor is the
> alternative if that is preferred. The patch drops {{e.addSuppressed(t)}} for
> a failed close, because by then {{e}} has been handed to Ratis; the close
> failure is still logged.
> Covered by {{ContainerStateMachineTests#testWriteTimout}} (leader and
> follower), extended to assert that {{close()}} does not run on the thread
> that called {{write()}} and that {{handleNodeLogFailure}} is called for each
> failed write. On the unmodified code it fails at the thread assertion; with
> only the asynchronous close it fails at the {{handleNodeLogFailure}} check.
> With the patch the two state machine suites,
> {{TestCloseContainerCommandHandler}} and {{TestClosePipelineCommandHandler}}
> pass (40 tests), {{TestClientRetryContainerStateMachineFailures}} passes (5
> tests) and checkstyle is clean.
> 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. 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]
