[
https://issues.apache.org/jira/browse/HBASE-30468?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Jose Luis López updated HBASE-30468:
------------------------------------
Description:
After HBASE-30265, {{TestProcDispatcher.testRetryLimitOnConnClosedErrors}} is
still flaky (passes on rerun):
{noformat}
AssertionFailedError: Waiting timed out after [60,000] msec
at
...TestProcDispatcher.testRetryLimitOnConnClosedErrors(TestProcDispatcher.java:141)
{noformat}
Seen in HBase Nightly master
[#1501|https://ci-hbase.apache.org/job/HBase%20Nightly/job/master/1501/],
[#1506|https://ci-hbase.apache.org/job/HBase%20Nightly/job/master/1506/],
[#1508|https://ci-hbase.apache.org/job/HBase%20Nightly/job/master/1508/],
[#1509|https://ci-hbase.apache.org/job/HBase%20Nightly/job/master/1509/],
[#1510|https://ci-hbase.apache.org/job/HBase%20Nightly/job/master/1510/] (JDK
17 and 21), and in ~15% of JDK 17 PR precommit runs (e.g.
[37446446948|https://github.com/apache/hbase/actions/runs/37446446948],
[37489643917|https://github.com/apache/hbase/actions/runs/37489643917],
[37475000411|https://github.com/apache/hbase/actions/runs/37475000411]).
h3. Cause
The error injection works: in every failed attempt both ServerCrashProcedures
(SCPs) are scheduled and finish successfully. The problem is how the test looks
for them. It searches {{getMasterProcedureExecutor().getProcedures()}}, but a
finished SCP doesn't wait for a client ack ({{shouldWaitClientAck()}} returns
false), so the next {{CompletedProcedureCleaner}} run evicts it. The cleaner
runs every 30s, so a finished SCP stays in the list for only 0-30s.
If a cleaner run happens after the SCPs finish but before the test's next poll,
the test never sees an SCP and times out. Example from nightly #1510: SCPs
finished 16:44:39.4, cleaner ran 16:44:40.3, first poll 16:44:41.7.
Setting {{hbase.procedure.cleaner.interval=1000}} in the test makes it fail
every time. With default settings, a local loop failed 6/39 runs: exactly the
runs where a cleaner run fell in that window.
h3. Fix (test only)
Count SCPs with the master's SCP submitted counter
({{getMasterMetrics().getServerCrashProcMetrics().getSubmittedCounter()}}),
read before injecting errors, instead of searching the procedure list. The
counter is not affected by eviction. With this change the test passed 39/39
runs, including 6 where a cleaner run fell in that window.
was:
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.
> 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
> Priority: Major
>
> After HBASE-30265, {{TestProcDispatcher.testRetryLimitOnConnClosedErrors}} is
> still flaky (passes on rerun):
> {noformat}
> AssertionFailedError: Waiting timed out after [60,000] msec
> at
> ...TestProcDispatcher.testRetryLimitOnConnClosedErrors(TestProcDispatcher.java:141)
> {noformat}
> Seen in HBase Nightly master
> [#1501|https://ci-hbase.apache.org/job/HBase%20Nightly/job/master/1501/],
> [#1506|https://ci-hbase.apache.org/job/HBase%20Nightly/job/master/1506/],
> [#1508|https://ci-hbase.apache.org/job/HBase%20Nightly/job/master/1508/],
> [#1509|https://ci-hbase.apache.org/job/HBase%20Nightly/job/master/1509/],
> [#1510|https://ci-hbase.apache.org/job/HBase%20Nightly/job/master/1510/] (JDK
> 17 and 21), and in ~15% of JDK 17 PR precommit runs (e.g.
> [37446446948|https://github.com/apache/hbase/actions/runs/37446446948],
> [37489643917|https://github.com/apache/hbase/actions/runs/37489643917],
> [37475000411|https://github.com/apache/hbase/actions/runs/37475000411]).
> h3. Cause
> The error injection works: in every failed attempt both ServerCrashProcedures
> (SCPs) are scheduled and finish successfully. The problem is how the test
> looks for them. It searches {{getMasterProcedureExecutor().getProcedures()}},
> but a finished SCP doesn't wait for a client ack ({{shouldWaitClientAck()}}
> returns false), so the next {{CompletedProcedureCleaner}} run evicts it. The
> cleaner runs every 30s, so a finished SCP stays in the list for only 0-30s.
> If a cleaner run happens after the SCPs finish but before the test's next
> poll, the test never sees an SCP and times out. Example from nightly #1510:
> SCPs finished 16:44:39.4, cleaner ran 16:44:40.3, first poll 16:44:41.7.
> Setting {{hbase.procedure.cleaner.interval=1000}} in the test makes it fail
> every time. With default settings, a local loop failed 6/39 runs: exactly the
> runs where a cleaner run fell in that window.
> h3. Fix (test only)
> Count SCPs with the master's SCP submitted counter
> ({{getMasterMetrics().getServerCrashProcMetrics().getSubmittedCounter()}}),
> read before injecting errors, instead of searching the procedure list. The
> counter is not affected by eviction. With this change the test passed 39/39
> runs, including 6 where a cleaner run fell in that window.
--
This message was sent by Atlassian Jira
(v8.20.10#820010)
