Skip to content

fix(donkey): fix two flaky donkey tests (IRT-1788) - #193

Merged
dsvanstedt merged 4 commits into
bridgelink_developmentfrom
feature/IRT-1788-donkey-flaky-tests
Aug 13, 2026
Merged

dsvanstedt merged 4 commits into
bridgelink_developmentfrom
feature/IRT-1788-donkey-flaky-tests

Conversation

@dsvanstedt

@dsvanstedt dsvanstedt commented Aug 13, 2026

Copy link
Copy Markdown
Collaborator

Summary

Fixes the two flaky donkey tests tracked in IRT-1788. Both are test-harness defects — no product
code changes, no product impact. They matter because IRT-1539 made unit tests gate the build, so
they were reddening PRs for unrelated changes.

1. ChannelTests.testContentRemoval — Derby row-lock deadlock in setup

TestUtils.deleteChannelStatistics issued a raw DELETE FROM D_MS<localChannelId> while the
Statistics Updater thread (DonkeyStatisticsUpdater, 1000 ms tick, alive for the whole test class)
was issuing UPDATE D_MS<localChannelId> for the same channel. Derby detected the row-lock cycle
and rolled one of the two transactions back, failing whichever test was in setup.

Reading that code turned up a second failure vector on the same root cause — nothing coordinates
harness cleanup with the updater thread. A flush landing after the DELETE finds no rows to update,
so JdbcDao.updateStatistics falls through to insertChannelStatistics and re-creates the rows with
the previous test's counts, while the in-memory statistics the harness cleared still read zero. That
breaks the DB-vs-memory assertions in DonkeyDaoTests and ChannelControllerTests. Not observed in
the wild, but it is the same defect, so it is fixed here too.

deleteChannelStatistics now:

  1. takes the updater's pending deltas for that channel away from it before deleting, so the
    updater has nothing to write back. DonkeyStatisticsUpdater keeps them in a private field and
    exposes no pause or flush, so the field is read reflectively and the public
    Statistics.remove(channelId) is called on it. Test-harness-only; if the field is ever renamed,
    the harness logs one warning and falls back to the previous behavior instead of breaking. Safe at
    every call site because all of them reset statistics before generating the traffic they assert
    on;
  2. retries the DELETE on a transient lock failure — 4 attempts, 150/400/900 ms backoff (unequal
    and not multiples of the 1000 ms tick, so a retry cannot stay phase-locked to it). Exact SQLState
    allowlist (40001, 40XL1, 40XL2, 40P01, 55P03) plus a message fallback, walking both
    getCause() and getNextException(). Deliberately not a "40" prefix match: Derby's class 40
    also contains 40XC0 and 40XD*, which are not contention. Every retry and repeat reports an
    IRT-1788 line to stdout as well as the logger, so the contention stays searchable in a CI
    build log rather than disappearing — log4j2 is not configured for donkey's ant test runs
    (log4j2-test.properties lands in test_classes/conf, not the classpath root, and no target sets
    log4j2.configurationFile), so a logger-only warning is invisible there;
  3. repeats until neither store holds anything for the channel, bounded at three attempts. This
    is not padding: after a successful flush the updater re-applies the negated snapshot to its
    pending map, so a flush committing between the discard and the DELETE re-creates the rows and
    repopulates the pending deltas after the discard already ran. Deleting the rows then leaves a
    negated snapshot pending, which the next tick inserts as negative counts — and a single verifying
    COUNT(*) cannot see it, because at that moment the rows genuinely are gone. Each repeat is
    driven by observed state, never a timer, so the happy path is unchanged.

The in-memory remove stays after the DELETE and deliberately not in a finally: the database and
the in-memory statistics have to be cleared together or not at all, since tests assert they agree.
For the same reason initChannel's catch (DonkeyDaoException) was not widened to
catch (SQLException) — that one-liner would turn a loud setup error into a confusing wrong-value
assertion 20 lines later.

2. ConnectorTests.testPollConnector — wall-clock equality assertion

The test slept 6800 ms and asserted exactly 7 polls. The ticket attributed the failures to the 7th
poll not finishing inside its 800 ms margin; that contributes, but the dominant mechanism is
different: Quartz anchors an interval trigger at midnight, not at channel.start()
(TriggerFactory.createDailyInterval), and pollOnStart is false, so polls fire on absolute
whole-second boundaries. A 6800 ms window contains 7 of those boundaries only when it starts at least
200 ms into a second — so ~20% of runs returned 6 on a completely idle machine. No margin tuning
fixes that.

The test now waits for the polls instead of timing them: a counting subclass of TestPollConnector
inside ConnectorTests counts completed polls on a CountDownLatch (the pattern already used by
CountDownJob in PollConnectorJobTests), and the test asserts that 7 polls completed within a
generous timeout, that they took at least 6 x pollingFrequency — so a regression that ignores the
polling interval still fails — and that every poll produced exactly one processed message. The stale
javadoc (still describing 500 ms / 3250 ms) and the incorrect "polls fire at t=0, 1000, …" comment
are corrected.

No edit to TestChannel.java, so no overlap with #191.

3. Ignore per-database test report output

**/junit-reports and friends did not cover the -postgres / -derby / -mysql variants that
ant test-run-<db>-db writes, because gitignore patterns match whole path components. Added glob
siblings for all four report dirs, plus the temp junit<n>.properties /
junitvmwatcher<n>.properties files ant's forked <junit> task leaks into donkey/ when a fork is
killed.

Verification

A single green run proves nothing for either of these, so everything below is A/B with prebuilt
class trees alternated run by run
, so machine-load drift hits both arms equally. No two suites ran
concurrently and nothing was recompiled mid-campaign (the harness verifies both).

Statistics race — scratch reproducer (not committed): traffic flows continuously while the reset
is hammered (deadlock arm), then a few messages are sent, statistics are reset, and D_MS is read
back past one updater tick (resurrection arm).

before after
deadlocks 4 / 12000 reset attempts 0 / 12000
stale statistics left after a reset 48 / 48 resets 0 / 48

The failures are byte-for-byte the ticket's exception — SQLTransactionRollbackException, cycle
ROW, D_MS1, (1,7), DELETE FROM D_MS1 waiting on the updater's UPDATE D_MS1 SET RECEIVED = CASE WHEN ....

Poll test — interleaved A/B on PostgreSQL, 8 pairs: 8/8 failed before with
expected:<7> but was:<6>, 8/8 passed after, each reaching 7 polls in ~8.2 s (so the
>= 6 x frequency floor passes with margin rather than by luck). Note the rate here was 100%, not
the 1-in-4 in the ticket — same mechanism, this machine simply lands in the losing phase window
consistently.

ChannelTests at class level — 10 pairs interleaved with Derby lock-timeout amplification
(-Dderby.locks.waitTimeout=1): 10/10 green in both arms, so this arm produced no signal and is
reported as inconclusive rather than as evidence. Per-run duration was unchanged (25-27 s both arms),
which does confirm the fix costs nothing.

Retry and repeat layers, exercised deliberately — the reproducer reports resets that fail, and
a successful retry throws nothing, so it cannot distinguish "no contention" from "retried and
recovered". Both paths were therefore driven directly. With a competing transaction holding row locks
on D_MS:
retry-then-succeed under a 1.5 s blocker (passed, 1283 ms), bounded give-up that throws rather than
silently continuing when the blocker outlasts the retry budget (passed), and 9 classification cases
including a DonkeyDaoException-wrapped cause, a getNextException()-only chain, and a
self-referential chain (all passed). With a thread continuously repopulating the updater, the repeat
loop fires three times and then gives up with a warning in 20 ms, without throwing or hanging.

Those checks caught two real defects in earlier versions of this change, both fixed here: ArrayDeque
rejects nulls, so an unchained non-lock SQLException produced an NPE instead of a clean
classification; and the contention warnings were logger-only, i.e. invisible in exactly the CI logs
the PR claimed they would be searchable in.

Full suites, one at a time: ant test-run (Derby, what CI runs) and ant test-run-postgres-db
151 tests, 0 failures, 0 errors on both, re-run after the review fixes, with no contention events
reported during either run. No tests added or removed. Both databases clean afterwards, no stray
containers or processes.

Residual risk

The resurrection window shrinks from up to a full updater tick (~1000 ms) to the microseconds between
the updater's dao.commit() returning and its negated-snapshot re-apply — the only interleaving where
the harness can observe both stores empty while a flush is still pending. Closing that completely
needs a real quiesce/flushNow API on DonkeyStatisticsUpdater: product code, which this PR
deliberately avoids per the ticket's framing. The reflective field access is the price of keeping the
fix test-side; it is guarded and degrades to a warning if the field is ever renamed.

Review note: the poll test's elapsed-time assertion bounds the polling frequency from below only — it
catches polls firing faster than configured or the interval being ignored, not polls firing slower. An
upper bound is deliberately omitted: PollConnectorJob silently drops a fire whose predecessor is
still running, so any bound loose enough to be stable on a loaded machine would be too loose to catch
a real regression, and it would reintroduce the wall-clock flakiness this ticket is about.

…ter (IRT-1788)

TestUtils.deleteChannelStatistics issued a raw DELETE FROM D_MS<localChannelId>
while the Statistics Updater thread was issuing UPDATE D_MS<localChannelId> for
the same channel. Derby detected the row-lock cycle and rolled one of the two
transactions back, failing whichever test happened to be in setup - about 1 run
in 8 of ChannelTests in isolation. Since IRT-1539 made tests gate the build,
that reddened unrelated PRs.

The same lack of coordination has a second consequence: a flush landing after
the DELETE finds no rows to update, so JdbcDao.updateStatistics falls through to
insertChannelStatistics and re-creates the rows with the previous test's counts
while the in-memory statistics read zero, which breaks the database-versus-memory
assertions in DonkeyDaoTests and ChannelControllerTests.

deleteChannelStatistics now takes the updater's pending deltas for the channel
away from it before deleting, so there is nothing left to write back; retries the
delete on a transient lock failure as a backstop for a flush already in flight;
and verifies the rows are gone, repairing once if they are not. Every retry and
repair logs a warning so the contention stays visible in CI logs.

Measured with a scratch reproducer alternating prebuilt class trees run by run:
deadlocks 4/12000 delete attempts before the change, 0/12000 after; stale
statistics after a reset 48/48 before, 0/48 after. Full donkey suite: 151 tests,
0 failures on both Derby and PostgreSQL.

The pending deltas are reached reflectively because DonkeyStatisticsUpdater keeps
them private and exposes no pause or flush. That keeps the fix in the test
harness rather than changing product code; if the field is ever renamed the
harness logs a warning and falls back to its previous behavior.
…em (IRT-1788)

The test slept 6800 ms and asserted exactly 7 polls, failing roughly 1 run in 4
on PostgreSQL. The ticket attributed this to the 7th poll not finishing inside
its 800 ms margin, which contributes, but the dominant mechanism is different:
Quartz anchors an interval trigger at midnight rather than at channel.start()
(TriggerFactory.createDailyInterval) and pollOnStart is false, so polls fire on
absolute whole-second boundaries. A 6800 ms window contains 7 of those boundaries
only when it starts at least 200 ms into a second, so the assertion could fail on
a completely idle machine and no margin tuning would fix it.

The test now counts completed polls on a latch, mirroring the CountDownJob
pattern in PollConnectorJobTests, and waits for them with a generous timeout. It
still asserts that the polling frequency is honored, by requiring the 7 polls to
take at least 6 x the frequency, and that every poll produced exactly one
processed message. The count is read after stop(), which waits for any in-flight
poll, and is not compared against the expected count directly because a further
poll can fire between the latch opening and stop() completing.

The counting connector is a private subclass inside ConnectorTests so that
TestChannel is left alone, avoiding a conflict with the open IRT-1655 PR.

Interleaved A/B on PostgreSQL, alternating prebuilt class trees run by run:
8/8 runs failed with "expected:<7> but was:<6>" before the change, 8/8 passed
after, each reaching 7 polls in about 8.2 s.

The javadoc still described 500 ms and 3250 ms, and the inline comment claimed
polls fire at t=0, 1000, 2000 and so on; both are corrected.
ant test-run-<db>-db writes junit-reports-<dbtype>, junit-html-<dbtype>,
jacoco-html-<dbtype> and code-coverage-reports-<dbtype>, but gitignore patterns
match whole path components, so the existing entries for the base directories did
not cover them and they littered git status after any local run against a
non-default database. Also ignore the junit<n>.properties and
junitvmwatcher<n>.properties files ant's forked junit task leaves in the module
directory when a forked JVM is killed.
…ion (IRT-1788)

Review of the first pass found a hole in the reset. After a successful flush the
Statistics Updater re-applies the negated snapshot to its pending map, so a flush
committing between the discard and the DELETE both re-creates the rows and
repopulates the pending deltas - the latter after the discard has already run.
Deleting the rows then left a negated snapshot pending, which the next tick
inserted as negative counts, and the single verifying COUNT(*) could not see it
because the rows really were gone at that moment.

The reset now repeats while either store still holds something for the channel,
bounded at three attempts. Every repeat is driven by observed state rather than by
a timer, so the happy path is unchanged: run times stay at 27-28 s per reproducer
run. Verified by driving it directly with a thread continuously repopulating the
updater - the loop repeats, then gives up with a warning, in 20 ms without
throwing or hanging.

Contention events now go to stdout as well as the logger. log4j2 is not configured
for donkey's ant test runs: log4j2-test.properties is copied to test_classes/conf
rather than the classpath root and no target sets log4j2.configurationFile, so the
entire suite log contains no log4j2 output and a logger-only warning would have
been invisible in CI - the one place it needs to be searchable if statistics
contention ever returns. Confirmed visible with no log4j2 configuration.

Also corrected the comment on the poll test's elapsed-time assertion, which
overstated what it catches: it bounds the polling frequency from below only. An
upper bound is deliberately not added because PollConnectorJob silently drops a
fire whose predecessor is still running, so any bound loose enough to be stable on
a loaded machine would be too loose to catch a regression, and would reintroduce
the wall-clock flakiness this ticket is about.

Full suite after the change: 151 tests, 0 failures on both Derby and PostgreSQL,
with no contention events logged during either run.
@dsvanstedt
dsvanstedt merged commit 8eb8fd6 into bridgelink_development Aug 13, 2026
1 check passed
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant