Jose Luis López created HBASE-30468:
---------------------------------------
Summary: TestProcDispatcher.testRetryLimitOnConnClosedErrors still
flaky: finished SCPs are evicted before the test checks for them
Key: HBASE-30468
URL: https://issues.apache.org/jira/browse/HBASE-30468
Project: HBase
Issue Type: Bug
Components: test
Affects Versions: 4.0.0-alpha-1
Reporter: Jose Luis López
h3. Symptom
After HBASE-30265, {{TestProcDispatcher.testRetryLimitOnConnClosedErrors}}
still fails intermittently and
passes on the surefire rerun:
{noformat}
org.opentest4j.AssertionFailedError: Waiting timed out after [60,000] msec
at
org.apache.hadoop.hbase.util.TestProcDispatcher.testRetryLimitOnConnClosedErrors(TestProcDispatcher.java:141)
{noformat}
Every poll of the first {{waitFor}} logs {{Num of SCPs: 0}}.
h3. Occurrences
HBase Nightly master (all failed once, then passed on rerun):
* [#1501|https://ci-hbase.apache.org/job/HBase%20Nightly/job/master/1501/]
jdk17-hadoop3 (2026-09-16)
* [#1506|https://ci-hbase.apache.org/job/HBase%20Nightly/job/master/1506/]
jdk17-hadoop3 (2026-09-25)
* [#1508|https://ci-hbase.apache.org/job/HBase%20Nightly/job/master/1508/]
jdk17-hadoop3 (2026-10-01)
* [#1509|https://ci-hbase.apache.org/job/HBase%20Nightly/job/master/1509/]
jdk21-hadoop3 (2026-10-03)
* [#1510|https://ci-hbase.apache.org/job/HBase%20Nightly/job/master/1510/]
jdk21-hadoop3 (2026-10-07)
PR precommit (Yetus JDK17 Hadoop3 Unit Check on GitHub Actions), on PRs
unrelated to this test:
3 flaky out of 20 runs that still have artifacts (~15%); 0 of 12 on the
JDK11/JDK8 branch-2.x checks.
* [run 37446446948|https://github.com/apache/hbase/actions/runs/37446446948]
(PR #8584, HBASE-30335)
* [run 37489643917|https://github.com/apache/hbase/actions/runs/37489643917]
(PR #8744, HBASE-30461)
* [run 37475000411|https://github.com/apache/hbase/actions/runs/37475000411]
(PR #8742, HBASE-30463; branch on an older master, so the line is 143)
h3. Root cause
Error injection works. In every failed attempt the logs show two "Scheduling
server crash" events and
both ServerCrashProcedures (SCPs) finishing with SUCCESS. What fails is how the
test detects them.
The test checks {{getMasterProcedureExecutor().getProcedures()}} for a
{{ServerCrashProcedure}}. That
list holds running procedures plus *retained* completed ones.
{{ServerCrashProcedure#shouldWaitClientAck}}
returns false, so {{ProcedureExecutor#rootProcedureFinished}} sets its
client-ack time to 0 and the
next {{CompletedProcedureCleaner}} run (every 30s,
{{hbase.procedure.cleaner.interval}}) evicts it.
A finished SCP therefore stays visible for only 0-30s, depending on the
cleaner's phase.
If a cleaner tick falls between the SCPs finishing and the test's next look at
the procedure list,
the SCPs are gone and the condition can never become true. Two windows were
observed:
# *Before the first poll.* The test's synchronous {{Admin#move}} calls keep
retrying with client backoff
("region is currently in transition") while the SCPs run, so the first poll
comes 0.5-10s after
the SCPs finish. Timelines (last SCP finished -> cleaner tick -> first poll):
#* nightly #1501: 17:03:51.889 -> 17:03:51.892 -> 17:03:52.471
#* nightly #1506: 13:29:00.8 -> 13:29:07.2 -> 13:29:10.98
#* nightly #1508: 17:07:49.6 -> 17:07:50.3 -> 17:07:50.365
#* nightly #1509: 16:01:35.8 -> 16:01:42.0 -> 16:01:46.0 (the rerun polled at
16:03:13.8, before the 16:03:18 tick, and passed)
#* nightly #1510: 16:44:39.4 -> 16:44:40.3 -> 16:44:41.7
# *Between two polls.* In run 37475000411 the test was already polling and had
seen {{Num of SCPs: 2}}.
Both SCPs finished at 17:04:30.511/30.541, the cleaner ticked at 17:04:31.040,
and the next poll
(17:04:31.095) saw 0 SCPs, with the procedure list down from 32 to 5 entries.
h3. Reproduction
* Deterministic: set {{hbase.procedure.cleaner.interval=1000}} in
{{setUpBeforeClass}}; the test fails
every time with the same signature.
* Statistical, default config, local JDK 17, original and fixed test alternated
in fresh JVMs:
the original failed 6/39 (15.4%, 95% CI 7.2-29.7%); the fixed version failed
0/39 (Fisher p ~ 0.025).
In every run, whether a cleaner tick fell between the last SCP finishing and
the first poll
predicted the original's outcome exactly: 6/6 such runs failed, 0/33 others
failed. The fixed
version passed all 6 runs where that happened.
h3. Proposed fix (test only)
Detect that an SCP was submitted with the master's monotonic SCP counter
instead of scanning
{{getProcedures()}}: sample
{{master.getMasterMetrics().getServerCrashProcMetrics().getSubmittedCounter()}}
before injecting errors, and wait until it has increased. The counter is not
affected by procedure
eviction, so it covers both windows above. The other {{waitFor}} conditions
(region count unchanged,
all listed procedures SUCCESS) and the hbck check are unchanged.
There is no product bug: evicting finished SCPs quickly is intended, since
nothing waits on their
result. Note that anything outside the master that uses the procedure list to
confirm a server
crash was handled (scripts, dashboards, the Procedures UI) has the same blind
spot; the
{{serverCrash}} master metrics or the master log are the reliable sources.
--
This message was sent by Atlassian Jira
(v8.20.10#820010)
