fix(donkey): fix two flaky donkey tests (IRT-1788) - #193
Merged
dsvanstedt merged 4 commits intoAug 13, 2026
Merged
Conversation
…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.
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
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 setupTestUtils.deleteChannelStatisticsissued a rawDELETE FROM D_MS<localChannelId>while theStatistics 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 cycleand 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.updateStatisticsfalls through toinsertChannelStatisticsand re-creates the rows withthe previous test's counts, while the in-memory statistics the harness cleared still read zero. That
breaks the DB-vs-memory assertions in
DonkeyDaoTestsandChannelControllerTests. Not observed inthe wild, but it is the same defect, so it is fixed here too.
deleteChannelStatisticsnow:updater has nothing to write back.
DonkeyStatisticsUpdaterkeeps them in a private field andexposes 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;
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 bothgetCause()andgetNextException(). Deliberately not a"40"prefix match: Derby's class 40also contains
40XC0and40XD*, which are not contention. Every retry and repeat reports anIRT-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.propertieslands intest_classes/conf, not the classpath root, and no target setslog4j2.configurationFile), so a logger-only warning is invisible there;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 isdriven by observed state, never a timer, so the happy path is unchanged.
The in-memory
removestays after the DELETE and deliberately not in afinally: the database andthe in-memory statistics have to be cleared together or not at all, since tests assert they agree.
For the same reason
initChannel'scatch (DonkeyDaoException)was not widened tocatch (SQLException)— that one-liner would turn a loud setup error into a confusing wrong-valueassertion 20 lines later.
2.
ConnectorTests.testPollConnector— wall-clock equality assertionThe 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), andpollOnStartis false, so polls fire on absolutewhole-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
TestPollConnectorinside
ConnectorTestscounts completed polls on aCountDownLatch(the pattern already used byCountDownJobinPollConnectorJobTests), and the test asserts that 7 polls completed within agenerous timeout, that they took at least
6 x pollingFrequency— so a regression that ignores thepolling 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-reportsand friends did not cover the-postgres/-derby/-mysqlvariants thatant test-run-<db>-dbwrites, because gitignore patterns match whole path components. Added globsiblings for all four report dirs, plus the temp
junit<n>.properties/junitvmwatcher<n>.propertiesfiles ant's forked<junit>task leaks intodonkey/when a fork iskilled.
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_MSis readback past one updater tick (resurrection arm).
The failures are byte-for-byte the ticket's exception —
SQLTransactionRollbackException, cycleROW, D_MS1, (1,7),DELETE FROM D_MS1waiting on the updater'sUPDATE 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 frequencyfloor passes with margin rather than by luck). Note the rate here was 100%, notthe 1-in-4 in the ticket — same mechanism, this machine simply lands in the losing phase window
consistently.
ChannelTestsat 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 isreported 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, agetNextException()-only chain, and aself-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:
ArrayDequerejects nulls, so an unchained non-lock
SQLExceptionproduced an NPE instead of a cleanclassification; 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) andant 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 wherethe harness can observe both stores empty while a flush is still pending. Closing that completely
needs a real quiesce/
flushNowAPI onDonkeyStatisticsUpdater: product code, which this PRdeliberately 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:
PollConnectorJobsilently drops a fire whose predecessor isstill 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.