[
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)
Set {{hbase.procedure.cleaner.interval}} in the test to 20 minutes, longer than
the LargeTests timeout (13 minutes), so the {{CompletedProcedureCleaner}} never
evicts finished SCPs while the test runs. The cleaner's first run happens one
full interval after the master starts, so it cannot run during the test. A
comment in the test explains the reason.
The first version of the PR counted SCPs with the master's SCP submitted
counter instead; following review it was simplified to this configuration
change. With this change {{TestProcDispatcher}} passes locally.
was:
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.
> Flaky TestProcDispatcher.testRetryLimitOnConnClosedErrors: 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: 3.0.0, 4.0.0-alpha-1, 2.5.16, 2.6.7
> Reporter: Jose Luis López
> Priority: Major
> Labels: pull-request-available
>
> 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)
> Set {{hbase.procedure.cleaner.interval}} in the test to 20 minutes, longer
> than the LargeTests timeout (13 minutes), so the
> {{CompletedProcedureCleaner}} never evicts finished SCPs while the test runs.
> The cleaner's first run happens one full interval after the master starts, so
> it cannot run during the test. A comment in the test explains the reason.
> The first version of the PR counted SCPs with the master's SCP submitted
> counter instead; following review it was simplified to this configuration
> change. With this change {{TestProcDispatcher}} passes locally.
--
This message was sent by Atlassian Jira
(v8.20.10#820010)
