[
https://issues.apache.org/jira/browse/UNOMI-979?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Serge Huber updated UNOMI-979:
------------------------------
Description:
h2. Summary
Unomi's scheduler runs background jobs across a cluster. Its unit tests fail
intermittently on CI:
passing on one run and failing on the next with no code change in between.
Every failure has to be
investigated before anyone can say whether it is a real defect or noise, and so
far they have
arrived with no diagnostic detail beyond the assertion message.
h2. Observed failures
* {{SchedulerServiceImplTest.testConcurrentLockAcquisition}} -- "Should have
exactly one task executing at a time ==> expected: <1> but was: <2>"
* {{SchedulerServiceImplTest.testMetricsAndHistory}} -- "Should have 2
successful executions ==> expected: <2> but was: <1>"
* {{SchedulerServiceImplTest.testClusteringSupport}} -- "runOnAllNodes task
should execute on every node including non-executors"
* {{SchedulerServiceImplTest.testOneShotRetryBehavior}} -- "Retry delay should
be at least 500ms ==> expected: <true> but was: <false>"
*
{{SchedulerServiceClusterRaceTest.testDualSurvivorRecoverDoesNotDoubleResume}}
-- seen earlier on an unrelated branch, so this predates the current work and
is not confined to one test class.
None of these reproduce locally, including at the runner's core count
({{-XX:ActiveProcessorCount=2}}) under CPU load, and running the whole module
in one JVM rather than
the suites in isolation. CI runs on a 2-vCPU {{ubuntu-latest}} runner.
h2. Hypotheses
Not yet all confirmed; listed so the next investigation has somewhere to start.
* These tests are timing-sensitive by construction -- real sleeps, wall-clock
lock timeouts, periodic tasks, and assertions on state that background threads
keep changing. A slow or contended runner is enough to reorder any of it.
* The shared test harness may leave more scheduler nodes running than a test
intends, with configurations that disagree about lock validity, so tests
interfere with each other through the shared store.
* Some assertions may read exact counts while the periodic task that increments
them is still running.
* Some assertions may check behaviour the scheduler does not actually
guarantee, in which case the test is wrong rather than the code.
* Task state is discovered with search queries, which lag the store by the
index refresh interval. Anything computed from a lagged copy and then written
back could lose an update or fire earlier than intended.
* Fixed sleeps used to wait for asynchronous work are simply too short on a
slow runner.
h2. Notes
Several of these have since been confirmed, and two turned out to be genuine
product defects rather
than test noise. Those fixes, the test-side changes and the supporting evidence
are described in
[PR 855|https://github.com/apache/unomi/pull/855]. This ticket stays open for
the hypotheses that
are still unproven -- notably the retry-delay failure, which has not been
reproduced or explained.
was:
h2. Summary
Unomi's scheduler runs background jobs across a cluster -- purging expired
data, profile
housekeeping, and anything a plugin registers. Its unit tests have been failing
intermittently on
CI: passing on one run and failing on the next with no code change in between.
Intermittent failures are expensive out of proportion to how they look. They
erode trust in the
build, they train people to re-run rather than read, and every one has to be
investigated before
anyone can say whether it is a real defect or noise. In this case the
investigation was worth it:
two of the intermittent failures turned out to be genuine product defects that
the tests were
correctly detecting, not test noise. One of them could cause a scheduled job to
run twice at the
same time on different servers; the other silently under-reported how many
times jobs had
succeeded or failed.
This ticket is deliberately written as a problem report rather than as a single
fix. The causes
turned out to be several unrelated things, PR 855 addresses some of them, one
is still not
understood, one is a design question, and we cannot presently prove there are
no others.
h2. Why this is not just a PR
Three things keep this open beyond the first round of fixes:
* One failure ({{testOneShotRetryBehavior}}, retry delay) has a plausible
mechanism but was never reproduced and is not fixed.
* One "failure" turned out to be a test asserting behaviour the implementation
never promised, which raises a genuine design question about {{runOnAllNodes}}.
* We have no reliable way to reproduce these failures locally, so "the tests
are no longer flaky" is currently not a claim anyone can substantiate. See the
reproduction section below.
h2. Problems found
h3. 1. The test harness ran a hidden extra cluster node with a conflicting
configuration -- FIXED in PR 855
{{SchedulerServiceImplTest.setUp()}} built a scheduler with a 1s lock timeout
and left it polling
for the whole test, while multi-node tests created their own nodes with the 10s
default against the
same store. That is a cluster whose nodes disagree about how long a lock is
valid.
Symptom: {{testConcurrentLockAcquisition}} -- "Should have exactly one task
executing at a time
==> expected: <1> but was: <2>".
This one was detecting a real product defect. A lock's renewal cadence is
derived from its
_owner's_ timeout ({{lockTimeout/3}}), but expiry was judged against the
_observer's_ timeout, so a
node configured shorter than a peer's renewal cadence saw every renewal gap as
a dead lock, marked
the live execution CRASHED, cleared the lock, and a peer re-dispatched the task
while it was still
running. Configuration drift or a rolling upgrade reproduces this in
production. Locks now record
the lease their owner granted themselves and expiry is judged against that.
h3. 2. Task counters and execution history were lost through stale-base
increments -- FIXED in PR 855
Symptom: {{testMetricsAndHistory}} -- "Should have 2 successful executions ==>
expected: <2> but
was: <1>".
Also a real product defect. {{canCommitTerminalTransition()}} loads the
authoritative document by
id but carries only the optimistic-concurrency tokens onto the executing task
instance. Counters
and history stay as the _dispatched_ copy had them, and that copy comes from a
search query which
lags the store by up to the index refresh interval. The compare-and-set then
protects the document
version but not those values, so incrementing a stale base and writing it
succeeds and silently
discards the newer count. Success and failure counts, and the execution history
a UI or operator
reads, were under-reported whenever a dispatch raced the refresh interval -- on
Elasticsearch and
OpenSearch alike, both having real refresh lag.
h3. 3. A test asserted behaviour the implementation does not promise -- test
FIXED in PR 855, design question OPEN
Symptom: {{testClusteringSupport}} -- "runOnAllNodes task should execute on
every node including
non-executors".
{{runOnAllNodes}} as implemented means "any node, including a non-executor, may
run this task": all
nodes share the task's single schedule document, so each period has one
phase-dependent winner and
there is no fairness. The test demanded an execution from all three nodes
within the timeout, which
is a lottery over checker-tick phases. The test now asserts what is actually
promised, and the
regression it was really protecting (non-executor nodes do poll and run these
tasks) is pinned
separately.
Open question: the name promises more than the code delivers. Worth deciding
whether the intended
semantic is per-node execution -- which would need per-node schedule tracking
-- or whether the
current behaviour should be renamed and documented. Probably its own ticket.
h3. 4. Exact execution counts asserted while periodic tasks could still fire --
FIXED in PR 855
Four assertions read a counter after a latch opened, while the periodic task
that increments it was
still running. Whether the next period landed before the assertion was pure
timing. These now stop
the task and wait for it to settle, or assert a lower bound.
h3. 5. An execution arrived sooner than the configured retry delay -- OPEN, not
reproduced
Symptom: {{testOneShotTaskRetryScenarios -> testOneShotRetryBehavior}} --
"Retry delay should be at
least 500ms ==> expected: <true> but was: <false>".
Not fixed and not reproduced. An execution landing sooner than the retry delay
would be a real
contract violation, so the assertion was deliberately left strict rather than
relaxed on a theory.
Suspected mechanism, unproven: the same staleness family as problem 2, on the
dispatch side.
{{prepareForExecution()}} checks due-ness against the task instance it is
handed, so a
search-lagged copy still carrying the already-past pre-retry
{{nextScheduledExecution}} would pass
the due check and execute immediately. Confirming this means deciding whether
the dispatch path
should re-validate due-ness against a fresh read, which interacts with the
checker's
retry-safety-net behaviour that
{{testOneShotRetryRecoveredWhenRetryDispatchIsDropped}} depends on
-- so it is a deliberate design change, not a quick fix.
Interim: the assertion now reports the full gap sequence, execution count and
persistence mode on
failure, so the next occurrence distinguishes a duplicate dispatch (more
executions than expected)
from an early retry schedule (right count, short gap) instead of returning a
bare boolean.
h3. 6. Fixed sleeps used as synchronisation -- FIXED in PR 855
Several tests slept a fixed interval and then asserted that something _had_
happened. That is a bet
on scheduler timing which loaded runners lose. Converted to bounded polls,
Mockito {{timeout()}}
verifies, or latches the test releases. Deliberate quiet windows for _negative_
assertions keep
their sleeps -- a poll cannot confirm that nothing happened, and too short a
window there can only
miss a violation, never fail a healthy run. The distinction is now documented
in the test class.
h3. 7. Failures arrived with no diagnostics -- PARTIALLY FIXED, CI side still
open
{{configureDebugLogging()}} in {{SchedulerServiceImplTest}} was dead code: it
set
{{org.slf4j.simpleLogger.*}} system properties while {{logback-test.xml}} binds
logback, which
ignores them. Every CI failure therefore arrived as a bare assertion message
while the scheduler's
own {{LOCK-DIAG}} tracing -- which records each lock acquisition, renewal,
expiry verdict and
recovery decision -- was discarded.
Removed, and {{-DTEST_LOG_LEVEL=DEBUG}} documented as the real switch. Still
open: CI does not run
with it, so the next intermittent failure will again arrive without traces
unless someone
re-runs by hand. Worth considering DEBUG for the services module on CI, or on a
retry attempt.
h2. Reproduction is currently unreliable -- OPEN
This is the most important open item, because it is what prevents anyone from
substantiating a
claim that the tests are fixed.
CI runs on {{ubuntu-latest}}, a 2-vCPU runner, building the whole module in one
JVM. Attempts to
reproduce locally on a 16-core machine did not succeed, including:
* CPU saturation with background spinners -- contention rises, but the JVM
still sees 16 cores, so GC, JIT and pool sizing stay 16-core shaped and pause
behaviour differs in character, not just frequency.
* {{-XX:ActiveProcessorCount=2}} to match the runner's core count.
* Running the full 806-test module in one JVM rather than the scheduler suites
in isolation.
* Repeated runs combining all of the above.
Neither of the two CI failures reproduced under any of these. The failures were
diagnosed by code
analysis and then pinned with deterministic unit tests, not by reproducing the
race.
The practical consequence: repeated green local runs are weak evidence. A flake
that fires on 5% of
runs survives seven clean runs about 70% of the time. Establishing that the
suite is stable needs
either a soak job that runs the scheduler suites many times on CI hardware, or
the patience to
watch real CI runs over time.
h2. Remaining risk
No claim is made that the causes above are all of them.
{{SchedulerServiceImplTest}} has 39 tests,
most of them timing-dependent, and the class of bug involved (search-lagged
views feeding decisions
that are then compare-and-set) is systemic rather than local. A scheduler flake
in a different
class
({{SchedulerServiceClusterRaceTest.testDualSurvivorRecoverDoesNotDoubleResume}})
was already
observed on CI before this work started, so the problem is not confined to one
test class.
h2. Suggested next steps
* Land PR 855 (problems 1, 2, 3-test, 4, 6, and the diagnostics for 5).
* Watch CI for problem 5 and use the new diagnostics to decide between
duplicate dispatch and early retry schedule.
* Decide the {{runOnAllNodes}} semantic (problem 3) -- likely its own ticket.
* Decide whether the dispatch path should re-validate due-ness against a fresh
read, which is the general form of problems 2 and 5.
* Consider a CI soak job for the scheduler suites, and DEBUG logging on
failure, so future intermittent failures are both detectable and diagnosable.
> Scheduler unit tests fail intermittently on CI
> ----------------------------------------------
>
> Key: UNOMI-979
> URL: https://issues.apache.org/jira/browse/UNOMI-979
> Project: Apache Unomi
> Issue Type: Bug
> Components: unomi(-core)
> Affects Versions: unomi-3.1.0
> Reporter: Serge Huber
> Assignee: Serge Huber
> Priority: Major
> Fix For: unomi-3.1.0
>
> Time Spent: 10m
> Remaining Estimate: 0h
>
> h2. Summary
> Unomi's scheduler runs background jobs across a cluster. Its unit tests fail
> intermittently on CI:
> passing on one run and failing on the next with no code change in between.
> Every failure has to be
> investigated before anyone can say whether it is a real defect or noise, and
> so far they have
> arrived with no diagnostic detail beyond the assertion message.
> h2. Observed failures
> * {{SchedulerServiceImplTest.testConcurrentLockAcquisition}} -- "Should have
> exactly one task executing at a time ==> expected: <1> but was: <2>"
> * {{SchedulerServiceImplTest.testMetricsAndHistory}} -- "Should have 2
> successful executions ==> expected: <2> but was: <1>"
> * {{SchedulerServiceImplTest.testClusteringSupport}} -- "runOnAllNodes task
> should execute on every node including non-executors"
> * {{SchedulerServiceImplTest.testOneShotRetryBehavior}} -- "Retry delay
> should be at least 500ms ==> expected: <true> but was: <false>"
> *
> {{SchedulerServiceClusterRaceTest.testDualSurvivorRecoverDoesNotDoubleResume}}
> -- seen earlier on an unrelated branch, so this predates the current work
> and is not confined to one test class.
> None of these reproduce locally, including at the runner's core count
> ({{-XX:ActiveProcessorCount=2}}) under CPU load, and running the whole module
> in one JVM rather than
> the suites in isolation. CI runs on a 2-vCPU {{ubuntu-latest}} runner.
> h2. Hypotheses
> Not yet all confirmed; listed so the next investigation has somewhere to
> start.
> * These tests are timing-sensitive by construction -- real sleeps, wall-clock
> lock timeouts, periodic tasks, and assertions on state that background
> threads keep changing. A slow or contended runner is enough to reorder any of
> it.
> * The shared test harness may leave more scheduler nodes running than a test
> intends, with configurations that disagree about lock validity, so tests
> interfere with each other through the shared store.
> * Some assertions may read exact counts while the periodic task that
> increments them is still running.
> * Some assertions may check behaviour the scheduler does not actually
> guarantee, in which case the test is wrong rather than the code.
> * Task state is discovered with search queries, which lag the store by the
> index refresh interval. Anything computed from a lagged copy and then written
> back could lose an update or fire earlier than intended.
> * Fixed sleeps used to wait for asynchronous work are simply too short on a
> slow runner.
> h2. Notes
> Several of these have since been confirmed, and two turned out to be genuine
> product defects rather
> than test noise. Those fixes, the test-side changes and the supporting
> evidence are described in
> [PR 855|https://github.com/apache/unomi/pull/855]. This ticket stays open for
> the hypotheses that
> are still unproven -- notably the retry-delay failure, which has not been
> reproduced or explained.
--
This message was sent by Atlassian Jira
(v8.20.10#820010)
