[
https://issues.apache.org/jira/browse/UNOMI-979?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Serge Huber updated UNOMI-979:
------------------------------
Summary: Scheduler unit tests fail intermittently on CI (was: Scheduler
unit tests fail intermittently on CI for several independent reasons)
> 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 -- 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.
--
This message was sent by Atlassian Jira
(v8.20.10#820010)
