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