Siyao Meng created HDDS-17519:
---------------------------------
Summary: After a long SCM pause the node health checker marks live
datanodes STALE or DEAD, as it skips only one run and misses some pauses
Key: HDDS-17519
URL: https://issues.apache.org/jira/browse/HDDS-17519
Project: Apache Ozone
Issue Type: Bug
Reporter: Siyao Meng
Attachments: MC-4-hold-off-node-health-checks-after-scm-pause.patch,
TestBugMC3PauseInsideHealthCheck.java, TestBugMC4PauseHoldOff.java
h3. Mechanism
HDDS-1454 added {{NodeStateManager.shouldSkipCheck}} so that an SCM pause (GC,
VM suspend, live migration, SIGSTOP) does not mark every datanode stale and
close all pipelines. {{NodeStateManager.run}} skips the health check when the
time since the previous run is at least {{min(stale, dead)}} interval. Three
gaps remain:
# *One skipped run is too short.* After a detected pause the next run comes one
checker interval later ({{ozone.scm.heartbeat.thread.interval}}, 3s), while
datanodes heartbeat every {{hdds.heartbeat.interval}} (30s). A datanode whose
last heartbeat before the pause is older than the stale interval and whose next
heartbeat is processed more than 3s after resume is marked STALE by that run,
and DEAD by the next one if the pause was at least the dead interval. A
heartbeat sent during the pause can be lost: the datanode's call fails after
{{ozone.scm.heartbeat.rpc-timeout}} (5s), the proxy's retry policy only covers
connection setup, and the datanode retries at its next heartbeat.
# *Pauses just under the stale interval are not detected.* A datanode can be up
to one heartbeat interval into its cycle when SCM pauses, so a pause between
the stale interval minus one heartbeat interval and the stale interval (4.5 to
5 min by default) makes it look stale, but is not skipped. The checker task was
due during the pause, so it runs at the moment SCM resumes.
# *The pause check and the deadlines read the clock separately.*
{{shouldSkipCheck}} reads the clock, then {{checkNodesHealth}} reads it again
for the stale and dead deadlines. A pause between the two readings is not
detected and the deadlines are taken from after the pause.
{{scheduleNextHealthCheck}} has a similar window: a pause after the next run is
scheduled but before {{lastHealthCheck}} is read starts the next run at once
with a fresh {{lastHealthCheck}}. These windows are a few statements wide, so
this case is very unlikely in practice.
h3. Trigger
An SCM process that stops for at least the stale interval minus one heartbeat
interval (4.5 min by default), with datanodes running. Gap 1 also needs a
datanode whose first heartbeat after resume is processed more than one checker
interval after resume. By reading the code (not run on a real transport):
* With Kerberos, the SASL handshake cannot complete while SCM is stopped, so
nothing is queued at SCM. The datanode retries the handshake
({{ipc.client.connect.max.retries.on.sasl}}, 5) with a random backoff of up to
5s, so its first heartbeat after resume can come more than 3s later.
* With default SIMPLE authentication a heartbeat written to an accepted
connection stays in SCM's socket buffer and is processed after resume, with
SCM's own clock, so it counts as fresh. Every heartbeat opens a new connection,
because {{ipc.client.connection.maxidletime}} (10s) is shorter than the
heartbeat interval and a timed out call also closes its connection, so each
datanode adds about one entry per heartbeat interval to SCM's accept queue
while SCM is stopped. That queue holds the smaller of
{{ipc.server.listen.queue.size}} (256 by default) and the kernel's
{{net.core.somaxconn}}. Gap 1 is therefore masked for clusters with fewer
datanodes than that, and otherwise only the datanodes whose first connection
during the pause did not fit are exposed; they reconnect on the TCP and IPC
connect retry schedule.
* Gap 2 does not depend on the transport: the run at resume races the
processing of the queued heartbeats. It is the main route with SIMPLE
authentication.
h3. Impact
A STALE transition makes {{StaleNodeHandler}} close every pipeline of the
datanode. A DEAD transition makes {{DeadNodeHandler}} close its containers,
destroy its pipelines, remove its replicas from SCM's container map, notify
ReplicationManager and clear its command queue. The datanode returns to HEALTHY
with its next heartbeat, but none of this is undone. In a cluster wide pause
this hits many datanodes at once, which is the outcome HDDS-1454 set out to
prevent. The DEAD outcome needs a pause of at least the dead interval and more
than two checker intervals (6s) of silence after resume, which was shown only
with heartbeats withheld, not on a real transport. With SIMPLE authentication
the reachable outcome is mainly STALE.
h3. Reproduction
Two self contained classes for {{hadoop-hdds/server-scm}} (target path and
Maven command in each class comment). They run a real SCM from
{{HddsTestUtils.getScm}} with its event queue and the real {{StaleNodeHandler}}
and {{DeadNodeHandler}}. Both pass on unmodified source, which means the defect
is present.
* [^TestBugMC4PauseHoldOff.java] uses the existing
{{SCMNodeManager.pauseHealthCheck}} / {{unpauseHealthCheck}} hook with timing
scaled to the default ratios (checker 100ms, heartbeat 1s, stale 3s, dead 6s).
A heartbeat lost during the pause is modelled by not calling
{{processHeartbeat}}. After a 6.5s pause the check is skipped once, and the
datanode is DEAD when it heartbeats 611ms after resume; its only replica of a
CLOSED container is removed (gap 1). After a 2.5s pause that starts 500ms into
the datanode's heartbeat interval nothing is skipped, and the datanode is STALE
when it heartbeats 606ms after resume (gap 2). A control with the heartbeat
right after the skipped run keeps the datanode HEALTHY and the replica.
* [^TestBugMC3PauseInsideHealthCheck.java] models a pause between the two clock
readings by mocking {{Time.monotonicNow}} on the test thread, so that the
second reading in one {{run}} is later than the first by more than the stale
interval, and calls {{run}} on three datanodes that have just heartbeated. No
check is skipped, all three become STALE and all of their pipelines (five) are
CLOSED (gap 3). The same jump before the run is skipped and changes nothing.
h3. Patch
[^MC-4-hold-off-node-health-checks-after-scm-pause.patch], against
6752db7978761a749a7d42a72a85311818e3d870. It also applies to master at
9118d5a85a3 and on top of the open apache/ozone#11688. It conflicts textually
with the draft apache/ozone#11349 (HDDS-16627), which replaces the
{{Time.monotonicNow}} calls in the same methods with an injected clock, so
whichever lands second needs a small rebase.
{{NodeStateManager.run}} reads the clock once and uses that reading for the
pause check, for the deadlines and as {{lastHealthCheck}}, so a pause anywhere
in a run is part of the gap the next run sees (gap 3). A gap of at least the
stale interval minus one heartbeat interval counts as a pause (gap 2). After a
pause, health checks are skipped for one heartbeat interval plus the heartbeat
RPC timeout (35s by default) instead of for one run, so every live datanode has
had a heartbeat cycle to report to SCM (gap 1). There is no new configuration
and no protocol change.
Recon runs the same checker, but datanodes heartbeat Recon every
{{hdds.heartbeat.recon.interval}} (60s by default), while the patch takes SCM's
heartbeat interval. For Recon the change therefore narrows gaps 1 and 2 without
closing them; the harm there is limited to Recon's own view. Passing the
expected heartbeat interval from the node manager to {{NodeStateManager}} is
the follow up.
What changes for a cluster that never pauses: nothing, as its gaps stay near
the checker interval. After a pause, a datanode that really died is marked
STALE about 35s after resume instead of 3s, and, if the pause was at least the
dead interval, DEAD one checker interval later; otherwise DEAD comes at its
normal time. During the hold off no transition happens at all, so a recovered
datanode also returns to HEALTHY up to 35s later. A single run that itself
takes 4.5 min would now also count as a pause. The INFO line is logged once per
detected pause with the gap and the hold off, instead of "Skipping heartbeat
checks for one iteration." per skipped run.
Covered by {{TestSCMNodeManager.testScmHandleJvmPause}}, now parameterized with
a pause just under and at the stale interval and a heartbeat interval longer
than the checker interval: half a heartbeat interval after resume both
datanodes must still be HEALTHY, and the datanode that does not heartbeat must
still become STALE. And by
{{TestNodeStateManager.testPauseDuringHealthCheckRunDoesNotMarkNodesStale}} for
gap 3. Without the change they fail with "We did not skip any heartbeat
checks", "expected: <2> but was: <0>" and "expected: <HEALTHY> but was:
<STALE>". With it the SCM node package tests pass (177 tests, including
{{node.states}}) and checkstyle is clean. With the patch the gap 1 and gap 2
cases of [^TestBugMC4PauseHoldOff.java] and the inside run case of
[^TestBugMC3PauseInsideHealthCheck.java] fail, because the datanodes stay
HEALTHY; the control cases still pass.
Found by TLA+ model checking and code review of the SCM datanode health checker
and node state paths under HDDS-15926, on commit
6752db7978761a749a7d42a72a85311818e3d870. Checked against HDDS issues and
apache/ozone pull requests for duplicates before filing; the only related issue
is HDDS-1454, which introduced the skip. 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]
