[
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 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.
was:
A scheduler 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 configured
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 running — the task runs twice.
Reproduced deterministically (1s-timeout observer vs 10s-timeout workers;
`LOCK-DIAG` traces show the
watchdog's crash-mark at a 2.9s lock age followed by a second node dispatching
while the first still
executes). In production the same double execution follows from configuration
drift between nodes or
a rolling upgrade that changes `lockTimeout`.
This was also the root cause of the sporadic scheduler CI failures on loaded
runners:
- `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
10s-timeout test nodes —
i.e. exactly the divergent configuration above, plus over-asserting tests; see
below).
### The fix
Record the lease with the lock: `ScheduledTask.lockLeaseMillis`, stamped from
the owner's timeout on
every acquire and renewal, cleared on release. `isLockExpired()` judges against
the recorded lease.
Compatibility: documents written before lease recording (or with a corrupt
negative lease) carry no
usable lease and fall back to the observer's timeout — the exact pre-change
behaviour — so mixed
clusters and existing locks behave identically. ES and OpenSearch
`scheduledTask` mappings gain the
field. `ScheduledTask` is now annotated
`@JsonIgnoreProperties(ignoreUnknown=true)` so an older node
can still read task documents written by a newer one during a rolling upgrade
(Jackson's default
rejects the first unknown field — a latent break for ANY future field addition,
not just this one).
`startLockRenewal` now warns when `lockTimeout` is at or below the minimum
renewal interval — the one
configuration where a node cannot keep its own lease alive.
Same-config clusters (every normal deployment) are bit-for-bit unchanged: lease
== every observer's
timeout. Recovery of genuinely dead nodes still works and is now driven by the
dead owner's lease —
faster than before when the dead node ran a short timeout.
### Test hardening (same PR, second commit)
- `setUp()` scheduler now uses the production-default lock timeout; multi-node
tests that don't use it stop it first.
- `testClusteringSupport` no longer demands one `runOnAllNodes` task execute on
all three nodes — not a property the
implementation promises (all nodes share the task's single schedule document;
each period has one phase-dependent
winner; no fairness). The regression it protected — non-executor nodes poll
and run `runOnAllNodes` tasks — is pinned
deterministically in a new single-node test.
- Exact execution counts on still-firing periodic tasks → cancel-and-quiesce or
lower bounds.
- `Thread.sleep` policy applied and documented: positive assertions never wait
on fixed sleeps (bounded polls /
Mockito `timeout()` / test-released latches); deliberate quiet windows for
negative assertions keep their sleeps.
- Dead `configureDebugLogging()` removed (logback ignores slf4j-simple
properties); `-DTEST_LOG_LEVEL=DEBUG` documented.
### Validation
- New end-to-end regression tests are mutation-validated: the steal test fails
with the expiry logic reverted
("expected: <RUNNING> but was: <CRASHED>"); the serialization forward-compat
test fails without the annotation
(`UnrecognizedPropertyException`).
- Four scheduler suites (125 tests) run repeatedly under ~2.5× CPU
oversubscription — the protocol that reproduced
both original CI failures on demand — seven consecutive green runs.
- Full `services` module: 805 tests green; ES/OS core, `rest`, `itests` compile
clean.
### Follow-up worth its own ticket
`runOnAllNodes` semantics: as implemented it means "any node, including
non-executors, may run the task" (single 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/documenting.
> Scheduled tasks can run twice at the same time when cluster nodes disagree on
> the lock timeout
> ----------------------------------------------------------------------------------------------
>
> Key: UNOMI-979
> URL: https://issues.apache.org/jira/browse/UNOMI-979
> Project: Apache Unomi
> Issue Type: Improvement
> 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)
