Siyao Meng created HDDS-17574:
---------------------------------
Summary: Ratis snapshot taken while an OM checkpoint install has
paused the state machine can block the follower's apply thread forever
Key: HDDS-17574
URL: https://issues.apache.org/jira/browse/HDDS-17574
Project: Apache Ozone
Issue Type: Bug
Reporter: Siyao Meng
Attachments: CR-1-fail-flush-wait-while-om-state-machine-paused.patch,
TestBugCR1TakeSnapshotBlocksAfterInstallPause.java
h3. Mechanism
{{OzoneManagerStateMachine.takeSnapshot}} first waits until the applied index
reaches {{lastSkippedIndex}}, calling {{OzoneManagerDoubleBuffer.awaitFlush}}
in a loop. During a checkpoint install, {{OzoneManager.installCheckpoint}}
calls {{OzoneManagerStateMachine.pause}}, which stops that double buffer. Only
its flush thread completes the futures {{awaitFlush}} waits on, and {{unpause}}
replaces the buffer with a new one, so a wait started on the stopped buffer
never returns. The {{isStopped}} check in the loop runs only between waits.
The loop is entered while paused when, after the install read the commit index
and paused, Ratis applies an OM request (rejected while paused, so the applied
index stays) followed by a Raft configuration entry ({{notifyTermIndexUpdated}}
is not gated by the pause and raises {{lastSkippedIndex}}). OM turns Ratis log
metadata entries off, so this is a new leader's first entry, a membership
change, or the priority change {{RatisHelper.transferRatisLeadership}} writes
around an admin leader transfer. Ratis does not know that OM paused itself, so
its {{StateMachineUpdater}} stays running and calls {{takeSnapshot}} from
{{checkAndTakeSnapshot}} after that batch when OM's applied index is at least
{{ozone.om.ratis.snapshot.auto.trigger.threshold}} (enabled by default) past
the last Ratis snapshot. OM's applied index is frozen while paused, so the late
batch cannot cross the threshold itself: the flush that the install waited for
before pausing must already have moved it past the threshold. The updater
checks right after each batch, before the double buffer has flushed it, and
does not check the threshold while idle, so that crossing is first seen after
the late batch. Besides the automatic trigger, an admin snapshot request to the
follower ({{ozone ratis snapshot create}} with {{-peerId}}) reaches the same
call during the pause without any threshold (argued from code, not run).
In releases before HDDS-16275, {{pause}} stops the double buffer without a
final flush and applies during the pause go to the stopped buffer, so the
applied index can lag the skipped index without a late commit (argued from the
code at those tags, not run).
The comment in {{OzoneManager.installSnapshotFromLeader}} assumes the commit
index is fixed during the install. In Ratis 3.3.1 it is not: an append the
follower accepted before the install notification raises the commit index when
its log write completes ({{RaftServerImpl.appendEntriesAsync}} updates it after
the write, without checking the install in progress).
h3. Trigger
# A follower OM accepts appends whose log write is slow, then gets an install
notification.
# Its install downloads the checkpoint, reads the commit index, waits until it
is applied and pauses the state machine.
# The slow write completes, the commit index rises, and the batch Ratis applies
contains an OM request followed by a configuration entry (for example from a
leader transfer).
# OM's applied index, which the flush before the pause advanced, is already
{{ozone.om.ratis.snapshot.auto.trigger.threshold}} past the last Ratis
snapshot, so the check after that batch calls {{takeSnapshot}} on the paused
state machine (or an admin snapshot request arrives).
h3. Impact
* The follower's {{StateMachineUpdater}} thread blocks for good. It is the
thread that applies entries and reloads the state machine after an install, so
the follower OM never applies another entry until it is restarted. Depending on
where the late write leaves its log, it either keeps acknowledging appends
without applying them or refuses every append (argued from code, not run).
* The trigger is rare: it needs a log write that stays pending across the
checkpoint download, plus either a threshold crossing by the last flush before
the pause or an admin snapshot request during the pause.
h3. Reproduction
Two parts, neither of which drives the whole chain in an OM cluster.
* The hang: PASS on unmodified source (the defect is present), 12 s.
[^TestBugCR1TakeSnapshotBlocksAfterInstallPause.java]
({{hadoop-ozone/ozone-manager}}) uses the real {{OzoneManagerStateMachine}},
{{OzoneManagerDoubleBuffer}} and {{OmMetadataManagerImpl}} with a mock
OzoneManager. It calls the state machine in the order Ratis and the install
would: wait for applied index 10 and pause, reject the apply of index 11,
notify index 12 (standing for a configuration entry), take a snapshot. The
snapshot call is still blocked 3 s later, and still blocked 5 s after
{{unpause(20, 1)}}, with the thread waiting in
{{OzoneManagerDoubleBuffer.awaitFlush}}. The late commit of 11 and 12 is
injected by calling the state machine directly. A control without the late
commit shows {{takeSnapshot}} returning at once while paused.
* The late commit on real Ratis: in the reproduction attached to HDDS-17573
(three unmodified Ratis 3.3.1 servers, a follower whose log flush is stalled
once), in one run the follower's commit index rose from 17 to 79 after it had
received the install notification, while the install was in progress.
* That Ratis calls {{takeSnapshot}} in this state is argued from
{{StateMachineUpdater}} (its state stays RUNNING during OM's own pause and
{{checkAndTakeSnapshot}} runs after each applied batch), not run.
h3. Patch
[^CR-1-fail-flush-wait-while-om-state-machine-paused.patch], against
424482eb9cfc4b835e1bf73bcdaa9e7d70df59f0. It also applies to master at
257a71ab277.
{{takeSnapshot}} and {{awaitApplied}} now share one wait helper that fails with
an IOException while the state machine is paused instead of waiting on the
stopped buffer. Ratis catches an IOException from {{takeSnapshot}}, logs it and
goes on, so the updater stays free to apply and reload, and the next snapshot
is taken after unpause. The check and the registration of the wait are done
under the state machine lock that {{pause}} also takes, so a wait registered
before the pause is completed by the flush {{pause}} waits for before it stops
the buffer. A snapshot whose applied index is already caught up is still taken
during a pause as before. Covered by
{{testTakeSnapshotFailsWhilePausedBelowSkippedIndex}} in
{{TestOzoneManagerStateMachine}}, which uses a real double buffer: without the
change the snapshot call times out, with it the call fails with "paused" and,
after unpause, a snapshot is taken at the restored index. The same test checks
that a caught up snapshot is still taken while paused and that {{awaitApplied}}
fails with "paused" while paused. Two existing tests now stub
{{awaitFlushAsync}} instead of {{awaitFlush}}.
Found by code review of the OM and SCM Ratis state machine integration (leader
readiness, snapshot install and log failure handling), as part of the TLA+
verification effort under HDDS-15926, on commit
424482eb9cfc4b835e1bf73bcdaa9e7d70df59f0. 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]
