[
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 for several
independent reasons (was: Scheduled tasks can run twice at the same time when
cluster nodes disagree on the lock timeout)
> Scheduler unit tests fail intermittently on CI for several independent reasons
> ------------------------------------------------------------------------------
>
> 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 runs background jobs on a schedule -- purging expired data, profile
> housekeeping, and
> anything a plugin registers. In a cluster each job is meant to run on exactly
> one server at a
> time. We found that two servers can end up running the same job
> simultaneously. The work is then
> done twice: wasted capacity, data processed twice, and two servers writing
> results that can
> conflict.
> The cause is servers disagreeing about how long a job's claim stays valid. A
> server that claims a
> job keeps renewing the claim while it works, on a schedule derived from its
> own configured
> timeout. Other servers, however, decided whether that claim was still alive
> using *their own*
> timeout. A server configured with a shorter timeout than its peer concluded
> the job had died in
> the gap between two renewals, took the job away, and a second server started
> it while the first
> was still running. Servers can end up with different timeouts through a
> configuration mistake, or
> temporarily during a rolling upgrade.
> The fix: whoever claims a job now records how long it intends to hold the
> claim, and every other
> server honours that recorded duration instead of substituting its own
> opinion. Clusters where all
> servers share the same configuration -- the normal case -- behave exactly as
> before.
> The same disagreement existed in the unit-test setup, where it was the root
> cause of scheduler
> tests failing intermittently on busy CI machines. Those tests are fixed here
> too.
> h2. Technical detail
> A task lock's renewal cadence is derived from its *owner's* configured lock
> timeout
> ({{lockTimeout/3}}, see {{TaskExecutionManager#startLockRenewal}}), but
> {{TaskLockManager#isLockExpired}} judged expiry against the *observer's*
> timeout. Any node whose
> timeout is shorter than a peer's renewal cadence therefore sees every renewal
> gap as an expired
> lock: its recovery pass marks the live execution CRASHED, clears the lock,
> and the next peer tick
> re-dispatches the task while the original execution is still in flight.
> Reproduced deterministically with a 1s-timeout observer against 10s-timeout
> workers. The
> {{LOCK-DIAG}} traces show the observer crash-marking a lock 2.9s into its
> owner's 3.3s renewal
> interval, the owner's own re-dispatch correctly rejected by the
> duplicate-dispatch guard, and then
> a second worker dispatching while the first is still executing.
> This was also the root cause of the sporadic CI failures:
> * {{SchedulerServiceImplTest.testConcurrentLockAcquisition}} -- "Should have
> exactly one task executing at a time ==> expected: <1> but was: <2>"
> * {{SchedulerServiceImplTest.testClusteringSupport}} -- "runOnAllNodes task
> should execute on every node including non-executors"
> The test harness's {{setUp()}} scheduler ran with a 1s timeout alongside test
> nodes using the 10s
> default, and kept polling in the background for the whole test -- exactly the
> divergent
> configuration above.
> h2. The fix
> Locks now record the lease their owner granted itself:
> {{ScheduledTask.lockLeaseMillis}}, stamped
> from the owner's timeout on every acquire and every renewal, cleared on
> release.
> {{isLockExpired()}} judges against that recorded lease.
> Supporting changes:
> * Documents with no usable lease -- written before this change, or carrying a
> corrupt negative value -- fall back to the observer's timeout, which is the
> exact pre-change behaviour.
> * An implausibly large lease is honoured rather than overridden: the owner
> declared it, and stealing a lock early is precisely what causes double
> execution.
> * {{ScheduledTask}} is annotated
> {{@JsonIgnoreProperties(ignoreUnknown=true)}}. Jackson's default rejects the
> first unrecognized field, so during a rolling upgrade an older node would
> otherwise lose the ability to read *any* task document a newer node had
> written -- a latent break for any future field addition, not just this one.
> * {{startLockRenewal()}} now warns when the configured lock timeout is at or
> below the minimum renewal interval, the one configuration where a node cannot
> keep its own lease alive and peers may legitimately recover its live work.
> * Elasticsearch and OpenSearch {{scheduledTask}} mappings gain the
> {{lockLeaseMillis}} field.
> h2. Compatibility and blast radius
> * Same-configuration clusters: no behavioural change at all -- the recorded
> lease equals every observer's timeout, so expiry decisions are identical.
> * Existing locks and mixed-version clusters: no lease recorded, so the
> observer-timeout fallback applies and behaviour matches the current release.
> * Crash recovery of genuinely dead nodes still works, and is now driven by
> the dead owner's lease. Where the dead node ran a short timeout, recovery is
> *faster* than before, because peers no longer wait out their own longer
> opinion.
> h2. Test hardening
> * The {{setUp()}} scheduler uses the production-default lock timeout, and the
> multi-node tests that do not use it stop it first (following the existing
> {{testNodeFailure}} pattern).
> * {{testClusteringSupport}} no longer requires that one {{runOnAllNodes}}
> task execute on all three nodes. That is not a property the implementation
> promises: all nodes share the task's single schedule document, so each period
> has one phase-dependent winner and there is no fairness. The regression it
> was really protecting -- non-executor nodes must poll and run
> {{runOnAllNodes}} tasks -- is now pinned deterministically in a test where
> the non-executor is the only node.
> * Exact execution counts asserted while a periodic task could still fire now
> cancel-and-quiesce first, or assert a lower bound.
> * {{Thread.sleep}} policy, applied and documented in the class javadoc:
> positive assertions never wait on a fixed sleep (bounded polls, Mockito
> {{timeout()}} verifies, or latches the test releases); deliberate quiet
> windows for *negative* assertions keep their sleeps, since a poll cannot
> confirm that nothing happened and too short a window can only miss a
> violation, never fail a healthy run.
> * {{configureDebugLogging()}} was dead code -- it set slf4j-simple properties
> while {{logback-test.xml}} binds logback. Removed, and
> {{-DTEST_LOG_LEVEL=DEBUG}} documented instead, so the next CI failure arrives
> with {{LOCK-DIAG}} traces rather than a bare assertion message.
> h2. Validation
> * Both load-bearing changes are mutation-validated: the divergent-timeout
> regression test fails with the expiry logic reverted ("expected: <RUNNING>
> but was: <CRASHED>"), and the serialization forward-compatibility test fails
> without the annotation ({{UnrecognizedPropertyException}}).
> * Unit coverage exercises lease stamping on all three acquire paths,
> re-stamping on renewal after a runtime timeout change, clearing on release,
> both override directions, the legacy and corrupt-value fallbacks, boundary
> equality, and overflow; plus the persistence format through both real store
> read paths.
> * End-to-end: a divergently-configured observer cannot recover a live renewed
> lock, and a patient survivor does recover a dead owner's task as soon as the
> owner's lease expires.
> * The four scheduler suites (125 tests) were run repeatedly under roughly
> 2.5x CPU oversubscription -- the protocol that reproduced both original CI
> failures on demand -- with seven consecutive green runs after these changes.
> * Full {{services}} module: 805 tests green. Elasticsearch and OpenSearch
> core module tests green; {{rest}} and {{itests}} compile clean.
> h2. Follow-up worth its own ticket
> {{runOnAllNodes}} as implemented means "any node, including a non-executor,
> may run this task"
> (one shared schedule, one winner per period), not "each node runs it every
> period" as the name
> suggests. Worth deciding which semantic is intended, and either implementing
> per-node schedules or
> renaming and documenting the current one.
--
This message was sent by Atlassian Jira
(v8.20.10#820010)
