diff --git a/CONCEPTS.md b/CONCEPTS.md index da371bba3..6135f2022 100644 --- a/CONCEPTS.md +++ b/CONCEPTS.md @@ -36,6 +36,16 @@ parallel. This is how the project gets concurrency without adding partitions. Records handed to the worker pool and not yet resolved as succeeded or failed. Distinct from records merely fetched: in-flight work is what a commit must wait for, and what a shutdown must drain. +**Commit frontier** +The offset a partition would resume from if consumption restarted — the highest offset committed for +it. It is *exclusive*: it names the next record expected to be polled, not the last one completed. + +The frontier advances only across a contiguous run of completed records, so a completed record sitting +above an in-flight one does not move it. A partition can therefore have most of its work done and still +be committing its starting offset. That property is also what makes the frontier the thing worth +asserting about a commit: which intermediate offsets a partition commits on the way there depends on +when the periodic commit happens to fire, but where it ends up does not. + ## Transactional commit **Produce lock** @@ -83,6 +93,16 @@ A test that awaits a consequence whose precondition it cannot guarantee will occ load-tightness flake: the margin is not too small, the awaited event may simply never happen in some interleavings, so no timeout is long enough to make the test reliable. +**Tick-path assertion** +A test assertion that pins the intermediate observations a system passed through on its way to a settled +state, rather than pinning the settled state itself. Because those intermediates are only captured when +a periodic action happens to fire, the assertion's truth is a property of the machine's speed rather +than of the code under test — green on an idle box, red under load, with both readings correct. + +Distinct from a load-tightness flake and an unforceable trigger: no deadline is too tight, and no +awaited event is missing. The awaited condition is one of several legitimate outcomes, and once a +different one has occurred it can never become true, so the wait always expires in full. + **Ambient probe** The always-on recorder attached to broker integration tests, which annotates a failure with consumer-group progress evidence so the contention-versus-product-bug question is answered before @@ -96,3 +116,7 @@ test in question — a short, low-volume test cannot trip them, and a clean read a real deadline missed under contention, and an unforceable trigger is an awaited event that never occurred. All three present as the same expired await, and the whole diagnostic difficulty of this area is telling them apart. +- **A tick-path assertion presents as that same expired await, and is the fourth member of the + confusion.** It is told apart by asking whether what the test actually saw is *also correct*: the + other three all mean the expected thing did not happen, while a tick-path assertion means something + equally valid happened instead. diff --git a/bin/todo-index.sh b/bin/todo-index.sh index bca4e6ce4..e4c9e0f3d 100755 --- a/bin/todo-index.sh +++ b/bin/todo-index.sh @@ -124,17 +124,13 @@ count_markers() { } generate() { - local count - count=$(count_markers) - cat < assertThat(highestCommitFor(tp)).hasValue(expected)); +} +``` + +`verificationWaitDelay` is two commit intervals - the same budget the deleted `never()` form had. This restores +the settle without reintroducing the tick-path sensitivity the frontier change removed. Do it with the hoist +above, not separately. + +## `CompletionCeiling`'s overflow guard is stricter than `Duration` needs + +The guard tests whether `units * ceilingNanos` overflows a long, but the value produced is +`units * ceiling / gatingUnits`, and `Duration.multipliedBy` is `BigDecimal`-based. So it rejects knob values +whose *result* is perfectly representable, and blames the operator: `-Dvolume.messages=100000000` against the +120s site throws `"size ... is too large to scale a PT2M ceiling - check the knob"` for a valid 12,000s +deadline. The documented rungs (400k, 2M, 10M) all sit well under it, so nothing configured today trips it - +roughly 15x headroom above the largest. + +Guard the operation that can actually overflow (catch `ArithmeticException` around the `Duration` arithmetic +and rethrow with the same friendly message) rather than a nanosecond proxy. Also add a positive-`ceilingAtGating` +check: `Duration.ZERO` currently divides by zero *inside* the guard meant to prevent raw arithmetic errors. +`CompletionCeilingTest` pins only the far side of the boundary, so the false-rejection band is untested. + +## `CompletionCeilingTest` does not mirror the one inverted call site + +The test's own javadoc says it "mirrors the real call sites, so a change to any of their constants breaks here +first", and it pins three of four. The one it skips is `TransactionAndCommitModeTest.timeoutFor`, the only site +whose arguments are inverted - `completionCeiling(GATING_CONCURRENCY, threads, defaultTimeout)` - because more +threads must *shorten*, not lengthen. That inversion is exactly where an argument-order slip is invisible, and +it is the site whose hand-rolled predecessor was provably wrong. Add the fourth mirror, including a rung case. + +## Inherit: the audit is a dated record and has drifted + +`docs/test-hardening/inactive-tests-audit-2026-08-08.md` records +`grep -c "^- \[ \]" docs/quarantined-tests.md # 0`; that returns **3** today, because the registry gained +entries after 2026-08-08. Left as-is deliberately - a dated record's claims are not rewritten, only references +that no longer resolve (`docs/citations.md`). Re-run its reproduction commands rather than trusting the +numbers, and read the date first. + +A reviewer also flagged that the corrections made to that audit were written **into** the dated file rather +than into a new dated audit, so it now carries later conclusions under an earlier date. Worth a decision if +that file is edited again. diff --git a/docs/inflight/test-required-perf-lane-scope.md b/docs/inflight/test-required-perf-lane-scope.md new file mode 100644 index 000000000..44935548c --- /dev/null +++ b/docs/inflight/test-required-perf-lane-scope.md @@ -0,0 +1,46 @@ +# What belongs in the required Performance Tests lane + +`bin/performance-test.sh` is the "Performance Tests" leg of `maven.yml` - **a required check on every PR**, +`ubuntu-latest`, `timeout-minutes: 60`, and no retry (`AGENTS.md`: a flake fails the build, deliberately). +Anything `@Tag("performance")` therefore blocks merges. Two questions about that scope are open. + +## Decided: the 40,000-message rung stays automatic + +`LoadTest.asyncConsumeAndProcessAtVolume` runs there at `HIGH_VOLUME_TOTAL` (40,000), ten times the gating +volume, on a class listed at **1/20, undiagnosed** in the load-tightness flake family +([`test-load-tightness-flakes.md`](test-load-tightness-flakes.md)) at its *gating* volume. + +Measured before leaving it automatic, per the `AGENTS.md` rule to separate contention from a real +concurrency bug: on an uncontended broker it ran **5/5 green at ~52s against a derived 600s ceiling**. So the +code is fine at this volume and nowhere near its deadline. It then passed the real CI lane on first run. +Left automatic on that evidence. + +## Open: the lane pulls in a Postgres container nothing there uses + +`LoadTest extends DbTest`, and `DbTest` starts a `PostgreSQLContainer` in a **static initialiser**. Tagging +one method `performance` is enough to class-load it, so from astubbs#264 onward the required lane starts and +holds a database that no test in it reads or writes - `asyncConsumeAndProcess`'s only DB call is commented +out. `DbTest` is itself listed at **2/20** in the same flake family, for "postgres container start under +contention". + +So the lane inherited a known-flaky container start, and its memory, to run a test that never touches a +database. Options: + +1. **Move the volume case to a class extending `BrokerIntegrationTest`** rather than `DbTest`, leaving the + DB-shaped tests behind. Cleanest; no test in `LoadTest` appears to need Postgres. +2. **Make `DbTest`'s container lazy** (behind an accessor rather than a static initialiser) so class loading + alone does not pay for it. Helps every DB-shaped test, not just this one. +3. **Leave it** and watch, as with the volume decision. + +Related, and worth deciding together: the lane declares no `forkCount`, so all four `@Tag("performance")` +classes run in **one fork**, sharing one heap and the static broker. They run *sequentially* - `-Pci` sets +`parallel-tests=false`, and failsafe's `` element is not read by the JUnit Platform provider at +all - so this is a heap-and-wall-clock question, not a concurrency one. The gating integration lane already +forks (`-DforkCount=4 -DreuseForks=true`); this lane never got that treatment. + +## Watch: `-Dload.total` moves the gating tests too + +`LoadTest.total` and `asyncConsumeAndProcessAtVolume` read the **same** property. Reaching the documented top +rung with `-Dload.total=400000` also raises the two untagged gating tests to 400,000, each with a derived +100-minute ceiling against a 60-minute job cap. Fine when run deliberately outside CI; a trap if anyone puts +that flag in a lane. diff --git a/docs/inflight/test-untracked-ci-flakes.md b/docs/inflight/test-untracked-ci-flakes.md index 2fd53dd66..164554906 100644 --- a/docs/inflight/test-untracked-ci-flakes.md +++ b/docs/inflight/test-untracked-ci-flakes.md @@ -5,25 +5,18 @@ and Unit lanes). 8 of 45 runs carried markers. None of these tests appear in any The retry that hid them is gone - that half is done and written up in [`docs/solutions/workflow-issues/ci-retries-hid-flakes-from-the-ledger-2026-08-07.md`](../solutions/workflow-issues/ci-retries-hid-flakes-from-the-ledger-2026-08-07.md), -which also has the scan method. What is open is the three tests themselves. +which also has the scan method. What is open is the tests themselves - two of the scan's three, plus +one met later. The scan's third, +`ParallelEoSStreamProcessorTest.queuedMessagesNotProcessedOrCommittedIfSubmittedDuringShutdown` +(3/45), is fixed and gone from this ledger: astubbs#260 established the extra commit was correct +product behaviour and the assertion was wrong, so no product change was needed. | Test | Rate | Why it is worth attention | |---|---|---| | `OffsetEncodingBackPressureTest.backPressureShouldPreventTooManyMessagesBeingQueuedForProcessing` | 4/45 | The most frequent. UNDIAGNOSED but quarantined by explicit rule-1 exception - see below. Backpressure area - compare `vacuous-await-condition-brokerpoller-backpressure-2026-07-31.md`, a *different* class in the same area, so rule it in or out rather than assuming | -| `ParallelEoSStreamProcessorTest.queuedMessagesNotProcessedOrCommittedIfSubmittedDuringShutdown` | 3/45 | **A regression** - see below | | `PCMetricsTest.metricsRegisterBinding` | 2 seen | Second sighting, mechanism known, quarantined (owner astubbs#265) - see below | | `ProducerManagerTest.producedRecordsCantBeInTransactionWithoutItsOffsetDirect` | 1 seen (2026-08-12) | Not from the original scan - found while babysitting astubbs#287. Mechanism known and owned (astubbs#262), quarantined - see below | -**Start with the regression.** astubbs#101 fixed this exact test as "the shutdown-commit flake that -was aborting PIT", and it is back. It has the best starting position of the three: a known prior fix -to diff against, and a documented consequence - -`docs/plans/2026-08-03-001-investigate-transactional-commit-flake.md` §1 records that instability in -this test made the PIT mutation lane report *suite stability* rather than mutation coverage. While it -flakes, a green PIT lane means less than it appears to. - -Failures surface as `AbstractParallelEoSStreamProcessorTestBase.assertCommits`, so the assertion -helper is where the message comes from, not necessarily where the cause is. - **Classify before touching any of them** - the same rule that governs the load-tightness family next door, and for the same reason: two of that family turned out to be real product bugs, and the third was neither tight nor a stall but a test that could not force its own trigger. diff --git a/docs/refactoring.md b/docs/refactoring.md index 578d74b02..812092ee7 100644 --- a/docs/refactoring.md +++ b/docs/refactoring.md @@ -325,33 +325,41 @@ Only the items needing a decision are listed here - do not restate the inventory **Outright defects, cheap to fix:** -- **`@Timeout(60000L)` means 16h40m, not 60s** - in `MockConsumerEarlyCloseTest`, - `MockConsumerSaslAuthenticationTest` and `MockConsumerCommitTimeoutTest`. JUnit 5's `@Timeout` - defaults to seconds. This is not cosmetic: `MockConsumerEarlyCloseTest.mockConsumer` has **no - assertion at all** - the timeout *is* its assertion - so it currently cannot fail by hanging within - any realistic CI budget. Everywhere else in the tree writes it correctly. - **`assumeWorkingCodec` is not an assumption** - it is `return !encodingsThatFail.contains(encoding)`. Five `OffsetEncoding` values run `OffsetEncodingTests.ensureEncodingGracefullyWorksWhenOffsetsAreVeryLargeAndNotSequential` - with most assertions branched around and **report green rather than skipped**. Rename it to - `isWorkingCodec`, or convert the sites to real per-value assumptions so the skips appear in the - report. + with most assertions branched around and **report green rather than skipped**. Of the enum's 12 + values, **3 run the full positive assertion path** - 4 are dropped by the real assumption, 5 are + branched around. Rename it to `isWorkingCodec`, or convert the sites to real per-value assumptions + so the skips appear in the report. **Same test, second problem:** it asserts + `doesNotContain(2500L)`, and 2500 is never a record offset there - so that assertion passes for a + working codec and a broken one alike. Delete it or re-target it at an offset the test produces. - **`OffsetEncodingTests` imports JUnit 4's `org.junit.Assume` in a Jupiter test.** No pom declares JUnit 4 - it arrives transitively via testcontainers, and works only because the Jupiter engine reflectively recognises JUnit 4's assumption exception when it happens to be on the classpath. The day it falls off, that skip becomes a hard failure for four enum values. One-line fix to `org.junit.jupiter.api.Assumptions`. -- **`MultiInstanceHighVolumeTest` underscore typo** - `30_000_00` is 3M, not 30M. +- **`MultiInstanceHighVolumeTest` underscore misgrouping** - `30_000_00`. Read once as a typo that + lost a zero off 30M; it is not. History shows the value was **reduced from `10_000_000`** and the + intended value is **3,000,000**, which is what the literal already evaluates to. Regrouping it to + `3_000_000` is **byte-identical at runtime** - a legibility fix, nothing more. Raising the volume + is a separate and larger question, blocked by a **hard-coded 60-second `waitAtMost`** in the same + method. **Coverage decisions:** -- **`ParallelEoSStreamProcessorTest.processInKeyOrder`** (`@Disabled`, no reason recorded) - the one - real gap in the audit. Key ordering is well covered at the shard layer by `WorkManagerTest`, but - nothing asserts end-to-end, per-`CommitMode`, that offset *commits* respect key-order blocking - across partitions. Re-enabling means reconciling it with the commit semantics `c1fefbc64` - introduced in 2020 - which is what disabled it. +- **`ParallelEoSStreamProcessorTest.processInKeyOrder`** (`@Disabled`, no message on the annotation) - + the one real gap in the audit. Key ordering is well covered at the shard layer by `WorkManagerTest`, + but nothing asserts end-to-end, per-`CommitMode`, that offset *commits* respect key-order blocking + across partitions. `TransactionAndCommitModeTest`'s KEY arm does not close it: it produces **30,000 + unique keys for 30,000 records**, so there is one record per shard and nothing ever blocks on a key. + **The cause is settled**: the abandoned branch `origin/bugs/turn-on-commit-tests` @ `009bb7122` is a + single commit deleting exactly this `@Disabled` and the next one, titled *"…which were dibbled when + the offset map feature was added"*. Re-enabling means reconciling the test with the commit semantics + `c1fefbc64` introduced in 2020 - **and that branch shows removing the annotation alone was tried and + abandoned at WIP**, so budget for the reconciliation. - **`ParallelEoSStreamProcessorTest.offsetsAreNeverCommittedForMessagesStillInFlightLong`** - same - commit, same reconciliation. Its siblings cover the invariant at lower volume; the deeper - in-flight interleaving is not covered elsewhere. + commit, same branch, same reconciliation. Its siblings cover the invariant at lower volume; the + deeper in-flight interleaving is not covered elsewhere. - **`closeWithoutRunningShouldBeEventBasedFast` never measures "fast"** - add the timing assertion from the test three lines above it, which already does `time(...)` + `assertThat(...).isLessThan(...)`. - **Assertions commented out, implying coverage that does not exist** - @@ -362,16 +370,71 @@ Only the items needing a decision are listed here - do not restate the inventory ran, cannot pass), `sanity/StreamTest.test` (commented-out `@Test` over an infinite stream), `SampleTestingFailsafePluginInclusionCore` (empty body), `JavaEnvTest.checkJavaEnvironment` (`log.error` dump on every run). -- **`LargeVolumeInMemoryTests` runs 500 messages, not 1,000,000** - the 1M line is commented out - directly above, `git blame`d to 2020 and untouched since. Previously recorded as fixed by - astubbs#49; that PR never touched the file. The restore-to-1M commit and the OOM diagnostics from running it - live on `origin/refactor/test-hardening` - **salvage both before deleting that branch**. -- **Kneecapped volumes still undecided** - `VeryLargeMessageVolumeTest` (1M vs 2M), `LoadTest` (4K vs - commented alternatives), `TransactionAndCommitModeTest.numThreads` (64 vs 1000) and `.roundsAllowed` - (10, with a TODO). The last two likely mask real issues rather than being tuning choices. - -Not listed as work: `largeNumberOfInstances` is owned by open PR astubbs#29, and `ProgressBarTest.width` -is a deliberate manual check. +- **`LargeVolumeInMemoryTests` runs 500 messages, not 1,000,000 - and restoring it is real work, not + a value change.** The 1M line is commented out directly above, `git blame`d to 2020 and untouched + since. Previously recorded as fixed by astubbs#49; that PR never touched the file. **The OOM + diagnostics are now salvaged** into + [`docs/test-hardening/large-volume-in-memory-tests-oom-diagnostics-2026-04-22.md`](test-hardening/large-volume-in-memory-tests-oom-diagnostics-2026-04-22.md) + (they existed only on `origin/refactor/test-hardening`, which is on the safe-to-delete list). They + show 1M producing `java.lang.OutOfMemoryError: Java heap space` in the PC close path. Anyone + picking this up needs **three changes, not one**: + 1. **Stop retaining the producer history.** The test asserts + `producerSpy.history().hasSize(quantityOfMessagesToProduce)`, which forces every one of the 1M + produced records to be held live for the whole run. Replace it with a counter (and, if + ordering still needs checking, a small sampling buffer) so the assertion survives without the + retention. + 2. **Raise the 30-second latch timeout *and actually check it*.** It is + `allMessagesConsumedLatch.await(defaultTimeoutSeconds, SECONDS)` and **the boolean return is + discarded**, so a timeout reads as a pass on the way to whatever fails next. Fix both + together - raising a timeout whose result is ignored achieves nothing. Note + `defaultTimeoutSeconds` is a shared static on `AbstractParallelEoSStreamProcessorTestBase` + (30s, used tree-wide), so this wants a test-local value, not a bump to the shared constant. + 3. **Size the heap.** The diagnostics estimate **2-4GB**; surefire/failsafe defaults are far + below that. Set it explicitly, with a comment saying why. + - **Budget it x3.** This is a `@ParameterizedTest` over three `CommitMode`s, so both the runtime + and the peak memory cost are per-run times three - the heap figure is per fork, but the wall + clock is not. +- **Should `TransactionAndCommitModeTest` tolerate any round without progress?** The test carried + `// todo rounds should be 1? progress should always be made` next to a `roundsAllowed` variable + that was assigned and never read - `ProgressTracker` is built with null rounds, and it rejects + being given both a round count and a timeout, so the rounds mechanism was structurally off. The + dead variable is gone; the question it was attached to is real and unanswered, so it lives here + now. Deciding it means choosing whether progress-per-round or total duration is the right + liveness signal for this test. +- **The one deleted stub worth writing: `userSucceedsButProduceToBrokerFails`.** Ten test stubs were + deleted rather than implemented by upstream `confluentinc#493`, and audit §4 classifies all ten. + Nine need no test work (see below). This one does: the produce-failure path is reachable, but only + the `InvalidPidMappingException` special case is covered, by + `ParallelEoSStreamProcessorTest.closePCWhenInvalidPidMappingException`. **The general + produce-failure path, and its consequence - the offset is not committed and the work is retried - + are untested.** +- **Three deleted stubs are missing *features*, not missing tests** - record them as issues, never as + test debt. `poisonPillGoesToDeadLetterQueue`: PC has no dead-letter-queue concept and never has + (zero DLQ occurrences in any `src/main/java`); tracked as astubbs#149, and already the + most-demanded missing feature in `docs/inflight/next-candidates.md`. `maxPerPartition` and + `maxPerTopic`: no per-partition or per-topic in-flight limit exists - `ParallelConsumerOptions` has + only the global `maxConcurrency`, and `ShardKey` never keys by topic. Nearest tracked: astubbs#160 + and astubbs#236. **They were written as a trio with `maxOverall`, and only the global scope was + ever built** - it is `WorkManagerTest.maxInFlight` today. Neither adjacent issue is literally a + scoped in-flight cap, so if that debt should be visible it is **one new issue about scoped + concurrency limits**, not two test methods. +- **Volumes checked and found not to need changing** (recorded so nobody re-flags them): + `VeryLargeMessageVolumeTest` was never reduced - it went `1_000_000` to `100_0000`, the same + number, to `1_000_000`, and the `2_000_000` was only ever an aspirational comment. + `TransactionAndCommitModeTest.numThreads = 64` was an *increase* for stability, not a reduction. + `LoadTest` stays at 4,000: it is untagged, so it runs in the gating lane, and it is already a + listed member of the load-tightness flake family at that volume. + +Not listed as work: `largeNumberOfInstances` is owned by open PR astubbs#29. The three +`@Timeout(60000L)` annotations (`MockConsumerEarlyCloseTest`, `MockConsumerSaslAuthenticationTest`, +`MockConsumerCommitTimeoutTest`) are owned by open PR astubbs#206, which replaces them with +`@Timeout(120)` on a shared `MockConsumerTestBase` and adds the assertion +`MockConsumerEarlyCloseTest` was missing - and **`@Timeout(60)` would have been wrong**, because two +of those tests wait 45s and 50s internally, so it would have raced them rather than fixing them. +`ProgressBarTest.width` is a deliberate manual check. Five of the ten deleted stubs (§4 of the audit) +are already covered by named enabled tests, and `truncationOnCommit` is obsolete - on-commit +truncation is structurally unreachable, and the truncation that does exist happens on the bootstrap +poll and is covered by `PartitionStateCommittedOffsetTest`. A generated `docs/INACTIVE_TESTS.md` with a `--check` gate (the `bin/todo-index.sh` shape) was considered and **deliberately not built**: the previous audit was lost to invisibility, not drift, and diff --git a/docs/solutions/test-flakiness/assert-the-commit-frontier-not-the-tick-path.md b/docs/solutions/test-flakiness/assert-the-commit-frontier-not-the-tick-path.md new file mode 100644 index 000000000..f7a69c5f9 --- /dev/null +++ b/docs/solutions/test-flakiness/assert-the-commit-frontier-not-the-tick-path.md @@ -0,0 +1,382 @@ +--- +title: "Assert the commit frontier, not the path of ticks that reached it" +date: 2026-08-13 +category: test-flakiness +module: parallel-consumer-core +problem_type: test_failure +component: testing_framework +severity: medium +symptoms: + - "`processInKeyOrder(CommitMode)[1]` red on CI, green on 3 consecutive local `-Pci` runs of the same commit" + - "ConditionTimeoutException on `assertCommitLists`: actual `{...-0=[1, 3], ...-1=[4]}` vs expected `[...-0=[3], ...-1=[4]]`" + - "The extra offset is a legitimate intermediate commit, not a wrong one - both readings are correct" + - "Only one of three `CommitMode` parameters fails, and it is the slowest one" + - "The await burns its full 30s: once the tick has landed, the condition is permanently false" +root_cause: async_timing +resolution_type: test_fix +status: "Fix committed as `e8c9bb12` on `test/inactive-test-remediation` (astubbs#264), UNMERGED as of 2026-08-13. Nothing enforces the rule; it is convention plus the helper's javadoc." +applies_when: + - Writing or reviewing any assertion over a PC commit history in a core unit test + - Re-enabling a long-dark test and rewriting its commit expectations from scratch + - A test is green across repeated local runs but red on a loaded CI runner for only some parameters +related_components: + - testing + - development_workflow +tags: + - flaky-tests + - commit-offsets + - assertion-design + - key-ordering + - awaitility + - ci + - compounding-gap +related_prs: + - "astubbs#264 - re-enables `processInKeyOrder` (`dbbfd62c`) and carries the fix (`e8c9bb12`); OPEN" + - "astubbs#260 - merged as `c42cd322`; the same defect class days earlier, written down only in a commit message and two javadocs" + - "astubbs#263 - landed the audit that predicted this failure class" + - "astubbs#101 - fixed this same assertion family once before, for the opposite symptom" +related: + - "docs/solutions/test-flakiness/vacuous-await-condition-brokerpoller-backpressure-2026-07-31.md - sibling rule, opposite direction: an await that tests nothing" + - "docs/solutions/test-flakiness/unforceable-trigger-commit-lock-timeout-2026-08-07.md - sibling rule: a test awaiting a trigger it cannot force" + - "docs/test-hardening/inactive-tests-audit-2026-08-08.md - section 1.2 predicted exactly this class of assertion failure" + - "docs/inflight/test-untracked-ci-flakes.md - holds the parent rule this one specialises" +--- + +# Assert the commit frontier, not the path of ticks that reached it + +A commit assertion may only name **where a partition ended up**. The sequence or set of offsets it +passed through on the way there is a function of where the periodic commit tick happened to fall, and +a test that pins it is asserting the speed of the machine it runs on. + +This is the second instance of that rule in a week. The first, astubbs#260 (merged as `c42cd322`), +stated the principle correctly but only in the javadoc of the two helpers it patched, scoped to +*repeat* commits. The rule did not travel, and the next test hit the same class of defect in a +different shape. That failure to generalise is why this record exists - see **The compounding +failure** below. + +## Problem + +`processInKeyOrder` had been `@Disabled` since 2020 (upstream `c1fefbc64`). It was re-enabled and +rewritten on astubbs#264 in `dbbfd62c`, which replaced its flattened `assertCommits` expectations with +per-partition `assertCommitLists` calls pinning the exact set of offsets committed for each partition. + +It passed three consecutive local runs under `-Pci` and went red on the first CI run of that commit. +The library was right; the assertion was wrong. + +## Symptoms + +CI run 31654978866, job 94307427273 ("Unit Tests" leg): + +``` +[ERROR] bz.stub.parallelconsumer.ParallelEoSStreamProcessorTest.processInKeyOrder(CommitMode)[1] -- Time elapsed: 40.35 s <<< ERROR! +org.awaitility.core.ConditionTimeoutException: +Assertion condition ... [Which offsets are committed and in the expected order] +Expecting actual: + {input-0.31588349109546965-0=[1, 3], input-0.31588349109546965-1=[4]} +to contain exactly (and in same order): + [input-0.31588349109546965-0=[3], input-0.31588349109546965-1=[4]] +``` + +One red test out of 345 - and note Surefire's own summary is `Failures: 0, Errors: 1`, because an +Awaitility timeout arrives as an uncaught exception rather than an assertion failure. Grepping a job log +for "Failures: 0" is not evidence that the leg was green. + +Param `[1]` is the first constant of `ParallelConsumerOptions.CommitMode` +(JUnit's invocation index is 1-based), which is `PERIODIC_TRANSACTIONAL_PRODUCER` - by its own javadoc +"the slowest of the options" (grep `slowest of the options` in `ParallelConsumerOptions`). + +That is a speed correlation, not a routing one. Unlike `assertCommits`, **`assertCommitLists` is +equally strict in both branches**: `AbstractParallelEoSStreamProcessorTestBase#assertCommitLists` sends +the transactional and consumer branches into the same `KafkaTestUtils#assertCommitLists`, which ends in +`containsExactlyEntriesOf`. The mode did not select a stricter code path; it just left a wider window +open. + +The 30s bound is `defaultTimeoutSeconds` in the test base (grep `defaultTimeoutSeconds = 30`), so the +40.35s elapsed is the await burning its full budget on a condition that had already become permanently +false - not a slow system, and not something a larger timeout would rescue. + +## Both readings were correct + +The relevant records, all created through `KafkaTestUtils#makeRecord` (grep `offset++` - one **global** +offset counter, not one per partition): + +| Offset | Partition | Key | Role | +|---|---|---|---| +| 0 | 0 | `key-0` | `primeFirstRecord`, locked | +| 1 | 0 | `key-0` | `sendSecondRecord`, unlocked early but blocked behind 0 by key order | +| 2 | 0 | `key-1` | independent key, completes early | +| 3 | 0 | `key-1` | locked | +| 4-8 | 1 | `key-2`, `key-3` x3, `key-4` | the partition-1 scenario | + +At the failing checkpoint, record 0 has just been unlocked. Completing 0 frees 1 (same key), and 2 was +already done, so the run 0-2 becomes contiguous and partition 0's frontier moves to 3. + +Whether `1` also appears in the history depends on nothing but the tick: + +- Commit tick falls **between** 0 completing and 1-2 completing: PC commits `1` ("record 0 done, resume + at 1"), then later `3`. History `[1, 3]`. +- The whole run 0-2 completes **inside** one tick: only `3` is ever committed. History `[3]`. + +Both are correct. A fast, idle box closes that window; a loaded CI runner opens it. The assertion was a +statement about wall-clock tick placement wearing a correctness assertion's clothes. + +(Aside for anyone grepping the test: the surviving comment reads "0, 1 and 2 are all key-1 on partition +0". The mechanism it describes is right; the key attribution is loose - 0 and 1 are `key-0` from +`primeFirstRecord`/`sendSecondRecord`, and 2 is the first `key-1` record.) + +### The offsets are exclusive, which is why it is 3 and not 2 + +`PartitionState#getOffsetToCommit` returns `getOffsetHighestSequentialSucceeded() + 1`, described as +"Next offset expected to be polled, upon freshly connecting to a broker". Finishing records 0, 1 and 2 +therefore commits **3**, not 2. A committed offset says where to resume, not which record was last +done. Half of what `dbbfd62c` had to fix in this test's original expectations was that same confusion. + +### Why partition 1 sits at 4 before doing any work + +Partition 1's first record is offset 4 because record creation uses that one global counter. Its +bootstrap commit of `4` is a **starting point, not progress** - and the flattened +`AbstractParallelEoSStreamProcessorTestBase#assertCommits` cannot tell the difference, because it only +trims a genesis of `0` (grep `trimGenesis` and `KafkaTestUtils#trimAllGenesisOffset`). That is why this +test asserts per-partition at all. + +## What Didn't Work + +**Three green consecutive local runs under `-Pci`.** This was real verification - it is the standard +this repo holds, and it was met before the commit was pushed. It still could not have found this +defect, and the honest lesson is not "run it more times". + +The trigger is *machine speed*, and the local box is fast and idle. Every local run closed the tick +window the same way, so repetition on one machine sampled the same point in the space over and over. A +defect whose discriminator is the environment is structurally invisible to repetition within one +environment. + +That is a genuine boundary case for local verification rather than a contradiction of it. Local runs +are still the gate; what they cannot do is *probe a timing window*. When an assertion's truth depends on +where a periodic tick falls, the only instruments that help are (a) reasoning about whether an +intermediate state is reachable at all, and (b) deliberately perturbing the timing - loading the box, or +latching the race open the way astubbs#260's regression test does. Reaching for a fourth run is reaching +for a machine that will keep agreeing with itself. + +**Prior art that would not have helped either.** astubbs#260's `collapseRepeatedCommits` was already in +the tree and merged when this failed. It collapses a *repeat* of the immediately preceding commit; `[1, +3]` is two distinct offsets, so it passes straight through (session history). Fixing the class narrowly +had already been tried; that is the point of the next section. + +## Solution + +Commit `e8c9bb12` (on `test/inactive-test-remediation`, **unmerged** as of writing - astubbs#264 is +open). It adds one private helper to `ParallelEoSStreamProcessorTest` and routes every post-completion +checkpoint through it: + +```java +private void awaitFrontier(int partition, long expected) { + var tp = new TopicPartition(INPUT_TOPIC, partition); + await().timeout(defaultTimeout) + .untilAsserted(() -> assertThat(highestCommitFor(tp)) + .as("committed offset frontier for partition %s", partition) + .hasValue(expected)); +} + +private Optional highestCommitFor(TopicPartition tp) { + return getCommitHistory().stream() + .map(groupHistory -> groupHistory.get(CONSUMER_GROUP_ID)) + .filter(Objects::nonNull) + .map(partitionCommits -> partitionCommits.get(tp)) + .filter(Objects::nonNull) + .map(OffsetAndMetadata::offset) + .max(Comparator.naturalOrder()); +} +``` + +The checkpoints become: + +```java +-await().timeout(defaultTimeout).untilAsserted(() -> assertCommitLists(of(of(3), of(4)))); ++awaitFrontier(0, 3); ++awaitFrontier(1, 4); +``` + +and likewise for the three later ones, ending at `awaitFrontier(1, 9)` / `awaitFrontier(0, 4)`. + +`getCommitHistory` in the test base already dispatches on commit mode (producer +`consumerGroupOffsetsHistory()` versus `consumerSpy.getCommitHistoryWithGroupId()`), so the helper is +mode-agnostic by construction. + +**The first checkpoint deliberately keeps `assertCommitLists`:** + +```java +await().timeout(defaultTimeout).untilAsserted(() -> assertCommitLists(of(of(), of(4)))); +``` + +Nothing has completed on partition 0 there, so no intermediate value is reachable and the exact-set +form is stable. The rule is not "never assert exactly". + +## Why This Works + +`max([1, 3]) == 3`. The frontier is invariant under which intermediate offsets the ticks happened to +capture, so this specific failure cannot recur *by construction* rather than by timing luck. + +**It does not weaken the test.** The frontier only moves when work completes contiguously +(`getOffsetHighestSequentialSucceeded`, javadoc: "the offset one below the lowest incomplete offset"), +so a partition that advanced past in-flight work still fails. The invariant `processInKeyOrder` exists +for survives intact: partition 1 will not move past its base offset 4 while `key-2`'s record 4 is in +flight even though 5, 6 and 8 have completed, and when 4 finishes it jumps to **7, not 9**, because 8 is +complete but not contiguous. + +Mutation-checked rather than trusted for being green: per `e8c9bb12`'s message, asserting that partition +1 reaches 9 instead of 7 at that checkpoint - the exact claim that it advanced past in-flight work - +reds all three commit modes. + +Each checkpoint also re-asserts the *stationary* partition (`awaitFrontier(0, 4)` while partition 1 +moves), so an over-advance is caught at the moment it would happen, not only at the end. + +**What is given up, stated plainly.** The audit that scoped this re-enable calls this test's +end-to-end, multi-partition, per-`CommitMode` commit assertion the one real coverage gap it found +(`docs/test-hardening/inactive-tests-audit-2026-08-08.md`, section 1.2). The frontier form keeps all of +that - per-partition resume points, per commit mode, across partitions, under key-order blocking. What +it gives up is the intermediate commit *sequence*, which was never a property of the system under test. +This is a deliberate narrowing, not an accidental weakening. + +**One honest limitation.** `highestCommitFor` takes a max, so - like the consumer-side branch of +`assertCommits`, which carries the same caveat in its comment - it cannot see a committed offset going +*backwards* after the frontier has been reached. Detecting that stays with +`KafkaTestUtils#assertCommits`, where the history is a single ordered stream. + +## The compounding failure: astubbs#260 fixed this class and the rule stayed in a javadoc + +Days earlier, astubbs#260 (merged as `c42cd322`) diagnosed the same class of defect in +`queuedMessagesNotProcessedOrCommittedIfSubmittedDuringShutdown`, flaking as `[1, 1, 2]` where +`[1, 2]` was expected (at a rate of 3/45 CI runs, per that commit's message). PC re-commits the same base offset when a completing record cannot advance +the frontier, so the fix made the comparison tolerant: `KafkaTestUtils#collapseRepeatedCommits` was +introduced, keyed on the partition and applied before the genesis trim, and +`awaitForCommitExact(int partition, int offset)` moved to `atLeastOnce()`. + +That work **did** state the general rule, twice. From `collapseRepeatedCommits`'s javadoc: + +> how many such commits occur depends on where the wall-clock commit ticks fall, so it is not something +> a test can assert on + +and from `awaitForCommitExact(int, int)`'s: + +> Requiring exactly one turns a wait into an assertion about where the wall-clock commit ticks happened +> to fall. + +Both are correct and both are narrow. Each is bound to *repeat commits of the same offset*, and each +lives in the javadoc of the helper that handles repeats - a place you only read if you are already +holding that helper. `git grep` across `docs/solutions/` finds no learning doc for astubbs#260 at all: +the reasoning existed in a commit message and two code comments, and nowhere a future author would meet +it before writing a new assertion. + +So the tolerance built was for repeats, and the trap that fired next was **an extra distinct +intermediate offset on the way to the same frontier**. Every mechanism astubbs#260 built passes it +straight through: + +- `collapseRepeatedCommits` collapses only a repeat of the *immediately preceding* commit for that + partition, so `1` then `3` is untouched. +- `assertCommitLists` already ignored repeats independently, by collecting each partition's offsets into + a `HashSet` (grep `partitionToCommittedOffsets`). A distinct offset is simply a new set element. + +The narrowness is structural, not an oversight in one helper. And this test had already been fixed once +before for a *third* shape of the same family: astubbs#101 addressed the mirror-image symptom, a commit +that never happened (session history). Three point-fixes to one assertion family is the signal that the +family, not the instance, is what needed writing down. + +The generalisation was available at the time and cost one sentence: **never assert the sequence or set +of commits, only where they ended up.** Written somewhere a reviewer would meet it, it would have caught +this test at review, because the rewritten `assertCommitLists` expectations violate it on their face. + +This is also a specialisation of a rule the repo had already stated elsewhere and equally locally - "do +not compare two moving values; await a quiescent state, then read both", recorded inside one row of +`docs/inflight/test-untracked-ci-flakes.md`. A commit history is a moving value; the frontier is the +quiescent reading of it. + +## Prevention + +**The rule.** Assert the frontier - the highest committed offset for a partition, i.e. where consumption +would resume. Assert an exact set or sequence only at a checkpoint where **no intermediate state is +reachable**, which in practice means no record has completed since the last checkpoint. + +**Reach for these:** + +```java +// Best: the frontier per partition, invariant under tick placement. +awaitFrontier(0, 3); + +// A wait for one partition reaching one offset; atLeastOnce, deliberately. +// See its javadoc for why exactly-one would be an assertion about tick timing. +awaitForCommitExact(partition, offset); + +// Set-wise across the flattened history; tolerates repeat commits via collapseRepeatedCommits. +assertCommits(of(3, 4)); + +// Exact per-partition sets are FINE where nothing has completed yet: +await().timeout(defaultTimeout).untilAsserted(() -> assertCommitLists(of(of(), of(4)))); +``` + +**Avoid this:** + +```java +// An exact per-partition set at a checkpoint where completion has already occurred. +// [1, 3] and [3] are both correct; which one you get is the tick. +await().timeout(defaultTimeout).untilAsserted(() -> assertCommitLists(of(of(3), of(4)))); +``` + +**Review checklist for any new commit assertion:** + +1. Has any record completed since the previous checkpoint? If yes, an intermediate commit is reachable + and the exact-set form is a timing assertion. Use the frontier. +2. Is the expected value the *exclusive* offset (`highestSequentialSucceeded + 1`)? Finishing 0-2 + commits `3`. +3. Is any expected value actually a partition's **base offset** rather than progress? Records are + numbered by a global counter, and the flattened helper only trims a genesis of `0`. +4. Green locally is not evidence here. Ask instead: *is there a tick placement that makes this assertion + false?* If you can name one, the assertion is already wrong. + +**The remainder, swept.** The strict call sites left standing after astubbs#260 and astubbs#264 were +checked against the rule rather than left as a prediction. **None is exposed**, and the reason gives +the criterion in its sharpest form: + +> The exact form is only unsafe where a partition can pass through a **non-genesis intermediate +> frontier** that the expected value omits. That needs three or more records on one partition +> completing such that the frontier advances in *two* steps between checkpoints. + +- `assertCommitLists(of(` - the four sites outside `processInKeyOrder` are all two-records-per-partition + scenarios. Partition 0 goes base-`0` (trimmed as genesis) straight to its next frontier, and partition + 1's expected values `{2}`, `{2,3}`, `{2,3,4}` *are* the successive frontiers, so no omitted + intermediate exists to be caught out by. +- `awaitForCommitExact(int)` - the single-argument overload, documented as staying strict "because it + asserts the whole commit list". Its two-argument sibling was relaxed by astubbs#260; this one was not, + and does not need to be: every call site commits a single record (`VertxTest` twice, and + `ParallelEoSStreamProcessorTest` at offsets 0, 2 and 1), and the only value between base and frontier + is the genesis `0` that `assertCommits` trims. + +`processInKeyOrder` was the only site with the three-record shape - partition 0 holding offsets 0, 1 +and 2, with 2 completing before 0 - which is exactly why it was the only one that failed. Relaxing the +others would have cost assertion strength for no defect. + +**And the meta-rule that produced this document:** when a fix is justified by a general principle, write +the principle where the next person will meet it, not only in the javadoc of the helper that implements +the narrow case. astubbs#260's reasoning was excellent and reached exactly one call site's worth of +future readers. + +## Related + +- Fix: `e8c9bb12`, on astubbs#264 (OPEN, branch `test/inactive-test-remediation`) - unmerged as of this + writing. The re-enable that introduced the defect is `dbbfd62c`, same PR. Both SHAs are branch-local + and will not survive a squash merge; astubbs#264 is the durable reference, and the branch is the place + to grep for `awaitFrontier` if they no longer resolve. +- The earlier instance of this class: astubbs#260, merged as `c42cd322`. The earlier-still instance on + this same test family: astubbs#101. +- Failing run: 31654978866, job 94307427273 ("Unit Tests"). +- The test was dark from upstream `c1fefbc64` (2020) until `dbbfd62c`. +- `docs/test-hardening/inactive-tests-audit-2026-08-08.md` section 1.2 predicted this: "the test asserts + exact commit sets, which is precisely the class of assertion that commit rewrote everywhere else in + the file". Read it as the prediction that came true, not as a doc needing repair. +- Same family, different mechanism: + [`unforceable-trigger-commit-lock-timeout-2026-08-07.md`](unforceable-trigger-commit-lock-timeout-2026-08-07.md) + and + [`vacuous-await-condition-brokerpoller-backpressure-2026-07-31.md`](vacuous-await-condition-brokerpoller-backpressure-2026-07-31.md) + - an await that tests nothing, versus an await that tests the machine. +- Not a load-tightness flake, and worth ruling out explicitly: there is no margin to widen. Once the tick + has landed the condition is permanently false, so the await always burns its full budget. Compare + [`parallel-integration-tests-flaky-under-concurrency-2026-07-28.md`](parallel-integration-tests-flaky-under-concurrency-2026-07-28.md). diff --git a/docs/test-hardening/inactive-tests-audit-2026-08-08.md b/docs/test-hardening/inactive-tests-audit-2026-08-08.md index 262a03a4e..5aac57b89 100644 --- a/docs/test-hardening/inactive-tests-audit-2026-08-08.md +++ b/docs/test-hardening/inactive-tests-audit-2026-08-08.md @@ -4,7 +4,18 @@ **Scope:** every test on `master` that does not run, does not assert, or was never written. **Supersedes:** `disabled-and-weakened-tests-audit-2026-04-22.md`, which existed only on the unmerged branch `refactor/test-hardening`. All of its findings are carried across below, and the -two it got wrong are corrected with commit evidence. Nothing of it remains only on that branch. +ones it got wrong are corrected with commit evidence. Nothing of it remains only on that branch - +its companion `large-volume-in-memory-tests-oom-diagnostics-2026-04-22.md` is salvaged verbatim +alongside this file. + +**Corrected 2026-08-08** against a second research pass. Nine claims in the first draft were refuted +or under-evidenced and are now restated with their evidence: the disabling cause for §1.1/§1.2, the +ownership and correct value of the `@Timeout` fix (§9.1), the `30_000_00` reading and +`VeryLargeMessageVolumeTest`'s volume and `roundsAllowed` (§8.1), which tests the performance +exclusion actually covers (§8.4), the codec arithmetic and a second vacuous assertion (§5.1), the +thinness of the KEY cross-product arm (§1.2), and the whole of §4. Where a correction reverses an +earlier conclusion, the earlier conclusion is stated too - a reader who saw the first draft needs to +know which claim was withdrawn, not just what the current one is. This is a point-in-time record, not a generated index. Every number states the command that reproduces it, so a future reader re-derives a count instead of rebuilding the analysis. Findings @@ -18,10 +29,10 @@ are keyed by class and method, never by line number - the predecessor's line num | Question | Answer | |---|---| | **How many tests are disabled?** | **5** test methods. Not 7 - see the grep correction below. | -| **Why is each disabled?** | **1 of 5 says.** `ProgressBarTest.width` carries `@Disabled("For reference sanity only")`. The other four record no reason anywhere: no annotation message, no comment, and a disabling commit that never names the test. | +| **Why is each disabled?** | **1 of 5 documents itself in the annotation.** `ProgressBarTest.width` carries `@Disabled("For reference sanity only")`. The other four carry no message and no comment - but the *cause* of two of them is now settled by evidence off to one side: the abandoned branch `origin/bugs/turn-on-commit-tests` names it (see §1.1). So "4 of 5 undocumented" is still true of the annotations; it is no longer true that the reason is unknown. | | **How many tests are empty?** | **1** - `SampleTestingFailsafePluginInclusionCore.test`, body `{ }`. | | **How many are placeholders?** | **4** - one trivially-false stub, one whose name promises what its body never does, one abandoned mid-write, one diagnostic that cannot fail. | -| **Tests you intended to write?** | **10 were deleted rather than written**, by upstream `confluentinc#493`. Neither follow-up that would have restored them (`confluentinc#494`, `confluentinc#496`) ever merged. | +| **Tests you intended to write?** | **10 stubs were deleted rather than written**, by upstream `confluentinc#493`. Checked against current source, **only 1 is real work**: 5 are already covered by named enabled tests, 3 describe features that have never existed, and 1 is obsolete. See §4 - the "ten missing tests" reading is wrong. | Two further categories nobody asked about, because an annotation grep cannot see them and they are the ones that actually mislead: @@ -129,15 +140,34 @@ every method beneath it, not one. Worth remembering if that ever changes. - **Annotation message:** none. - **Disabled by:** `c1fefbc64`, Antony Stubbs, 2020-08-27, *"Create and commit offset map"*. -- **Reason:** **none recorded.** The commit body never names the test. What can be said from - evidence: the same diff rewrites commit expectations across neighbouring tests in the file (e.g. - `assertCommits(of(1), ...)` → `assertCommits(of(0, 2), ...)`), and the commit's own bullets claim - "Stabilise tests" and "Faster, more reliable tests". Offset coalescing changed what gets committed, - and this test was parked rather than reworked. **That is inference from the commit's stated goals, - not a stated reason.** +- **Reason: the offset map feature changed what gets committed.** Not recorded at the annotation, but + recorded by the same author on an abandoned branch, and that settles it. + + **`origin/bugs/turn-on-commit-tests` @ `009bb7122`** (Antony Stubbs, committed 2020-11-23) is a + **single commit whose entire diff is the deletion of exactly these two `@Disabled` lines** - one + file, two lines removed, nothing else - with the message: + + > *"WIP! Turn back on offset commit tests which were dibbled when the offset map feature was + > added"* + + That is a contemporaneous statement from the disabling author naming the cause ("dibbled" for + "disabled"), and it identifies both tests as one act. The supporting signal in the disabling commit + agrees: the same diff rewrites commit expectations across neighbouring tests in the file (e.g. + `assertCommits(of(1), ...)` → `assertCommits(of(0, 2), ...)`). Offset coalescing changed what gets + committed, and this test was parked rather than reworked. +- **Somebody already tried the cheap route and abandoned it.** The branch is titled `WIP!` and never + became a PR. Deleting the two annotations is evidently not sufficient - the tests have to be + reconciled with the commit semantics the offset map introduced. Anyone re-enabling these should + expect to do that work, not just remove an annotation. +- **Read the dates off `%cd`, not `%ad`, for this branch.** Its *author* date is 2020-05-20, which + predates the tests themselves and would make the branch impossible; its *commit* date is + 2020-11-23 and its parent `00a6a9ed` is on master at that date, which is after the 2020-08-27 + disable. The author date is stale metadata carried through a rewrite, and taking it at face value + inverts the causality. - **History:** introduced enabled 2020-05-27 alongside its `Simplest` and `Short` siblings. Ran green for three months. -- **Confidence:** high on attribution, low-to-medium on reason. +- **Confidence:** high on attribution. **High on reason** - a same-author, single-purpose commit that + names the feature responsible. - **Covered elsewhere?** Partly. `...Simplest` and `...Short` are both enabled and cover the same invariant at lower volume; `Short` asserts the final coalesced offset. What `Long` uniquely covers - six records, deeper in-flight interleaving - is not covered elsewhere. @@ -146,11 +176,14 @@ every method beneath it, not one. Worth remembering if that ever changes. - **Annotation message:** none. - **Disabled by:** `c1fefbc64` - **the same commit as 1.1**. Both disables landed together. -- **Reason:** **none recorded**, same as 1.1. The test asserts exact commit sets, which is precisely - the class of assertion that commit rewrote everywhere else in the file. +- **Reason: the same one, on the same evidence.** `origin/bugs/turn-on-commit-tests` @ `009bb7122` + deletes *this* `@Disabled` and 1.1's, in one two-line diff, under *"…which were dibbled when the + offset map feature was added"*. See §1.1 for the full quote. Consistent with the mechanism: the + test asserts exact commit sets, which is precisely the class of assertion that commit rewrote + everywhere else in the file. - **History:** introduced enabled by `17196170a` (2020-05-29, *"Ordered parallel message processing by key"*), substantially reworked by `565230cd5` (2020-06-04). Ran green for three months. -- **Confidence:** high on attribution, low-to-medium on reason. +- **Confidence:** high on attribution. **High on reason**, on the branch evidence in §1.1. - **Covered elsewhere?** **Substantially, yes** - key ordering is not uncovered. Enabled coverage includes `WorkManagerTest.orderedByKeyParallel`, `WorkManagerTest.highVolumeKeyOrder` (parameterised 1..1000 over 100 keys), `ParallelEoSStreamProcessorTest.processInKeyOrderWorkNotReturnedDoesntBreakCommits`, @@ -162,6 +195,14 @@ every method beneath it, not one. Worth remembering if that ever changes. including KEY**, end-to-end against a real broker. That is real coverage and this audit should not undersell it. + **But its KEY arm is thinner than "asserts only counts" already implies.** The test produces + **30,000 unique keys** for 30,000 records - one record per key. Under `KEY` ordering the shard key + is the record key, so that is one record per shard: **no two records ever contend for the same + shard, and nothing ever blocks on a key.** The KEY cell of the cross-product therefore exercises + shard *creation* at scale, not the ordering guarantee that KEY exists to provide. Key-order + blocking is the behaviour `processInKeyOrder` was written to assert, and this test cannot observe + it even in principle. + **What is genuinely lost, after accounting for all of that:** the end-to-end, multi-partition, per-`CommitMode` assertion that offset *commits* respect key-order blocking across partitions. `WorkManagerTest` covers the shard and dispatch layer, not the commit layer. The cartesian tests @@ -194,13 +235,14 @@ every method beneath it, not one. Worth remembering if that ever changes. - **Covered elsewhere?** No. Non-200 handling is untested in the vertx module. The nearest real test in the file, `testHttp`, asserts `statusCode()` is 200 on the happy path only. - This is a **deletion candidate, not a re-enablement candidate** - there is nothing here to restore. + *The stub is not worth keeping; the gap it names is worth writing. See §11.* ### 1.4 `MultiInstanceRebalanceTest.largeNumberOfInstances` - **Annotation message:** none; the javadoc carries the only prose. - **Created and disabled by:** `53052f512`, Antony Stubbs, authored 2022-02-09, *"fix: Concurrency - and State improvements"* - the squash of upstream confluentinc#190. Javadoc, `@Disabled`, `@Test` - and the whole method arrive in one hunk - **born disabled**, never enabled on master. + and State improvements"* - the squash of upstream confluentinc#190. Javadoc, `@Disabled`, `@Test` and the whole method arrive in one + hunk - **born disabled**, never enabled on master. - **Reason: runtime cost, not failure.** Two independent lines of evidence. Its javadoc, written by the same commit, says *"This test takes some time, but seems required in order to expose some race conditions without syntehticly creatign them"* - no failure is claimed. And it was authored as part @@ -231,8 +273,8 @@ every method beneath it, not one. Worth remembering if that ever changes. | Test | Real coverage lost? | Reason recorded? | |---|---|---| -| `offsetsAreNeverCommitted…Long` | yes, partial | no | -| `processInKeyOrder` | yes, one specific gap | no | +| `offsetsAreNeverCommitted…Long` | yes, partial | not at the annotation - offset map, per `origin/bugs/turn-on-commit-tests` | +| `processInKeyOrder` | yes, one specific gap | same commit, same evidence | | `handleHttpResponseCodes` | no - never worked | no | | `largeNumberOfInstances` | yes, but owned by `astubbs#29` | cost, via javadoc | | `ProgressBarTest.width` | no - not a behaviour test | yes | @@ -309,30 +351,110 @@ grep -rniE "UnsupportedOperationException|not implemented|notImplemented|\bNYI\b --- -## 4. Tests intended but never written +## 4. Tests intended but never written - and what each one is actually worth + +**10 stubs were deleted rather than implemented.** An earlier draft of this section presented all +ten as lost intent - ten tests the suite ought to have and does not. **That framing is wrong**, and +it is wrong in the direction that generates busywork: it invites someone to write ten tests, five of +which already exist under other names and three of which cannot be written at all. + +Each stub was checked against **current** `src/main` and against the enabled suite. The dispositions: + +| Disposition | Count | What it means | +|---|---|---| +| **Write it** | **1** | Real reachable behaviour, genuinely uncovered | +| **Already covered** | **5** | An enabled test does this today, under a different name | +| **Feature does not exist** | **3** | Nothing to test - these are issues, not tests | +| **Obsolete** | **1** | The invariant is now structurally unreachable; a test would be vacuous | + +They came out in upstream `confluentinc#493` - *"minor: tests: Removes empty/not implemented tests"*, +merged 2022-12-07 as `544593edd`. + +### Write it (1) -**10 were deleted rather than implemented**, and the intent survives only in git history and an -unmerged branch. +**`ParallelEoSStreamProcessorTest.userSucceedsButProduceToBrokerFails`.** The produce-failure path +**exists and is reachable** in current main: the user function succeeds, the subsequent produce to +the broker fails, and the record must not be committed. The only part of it under test today is one +special case - `closePCWhenInvalidPidMappingException` covers `InvalidPidMappingException` +specifically. **The general produce-failure path, and its consequence (the offset is not committed +and the work is retried), are uncovered.** This is the one stub that names real work. -Upstream `confluentinc#493` - *"minor: tests: Removes empty/not implemented tests"*, merged 2022-12-07 -as `544593edd` - removed ten test methods: +### Already covered (5) - by these tests -| Test | What it was | +Naming the covering test for each, so the claim is checkable rather than asserted. + +| Stub | Covered today by | |---|---| -| `ParallelEoSStreamProcessorTest.avro` | Five-line comment spec (*"send three messages - 0,1,2 / finish processing 1 / make sure no offsets are committed / finish 0 / make sure offset 1, not 0 is committed"*) then `assertThat(false).isTrue()` | -| `ParallelEoSStreamProcessorTest.poisonPillGoesToDeadLetterQueue` | dead-letter-queue behaviour | -| `ParallelEoSStreamProcessorTest.userSucceedsButProduceToBrokerFails` | partial-failure path | -| `ParallelEoSStreamProcessorTest.failingMessagesDontBreakCommitOrders` | failure vs commit ordering | -| `ParallelEoSStreamProcessorTest.failingMessagesThatAreRetriedDontBreakProcessingOrders` | retry vs processing ordering | -| `ParallelEoSStreamProcessorTest.messagesCanBeProcessedOptionallyPartitionOffsetOrder` | optional partition-offset ordering | -| `ParallelEoSStreamProcessorTest.ifTooManyMessagesAreInFlightDontPollBrokerForMore` | in-flight backpressure | -| `WorkManagerOffsetMapCodecManagerTest.truncationOnCommit` | `@Disabled("TODO: Blocker: Not implemented yet")` | -| `WorkManagerTest.maxPerPartition` | empty body | -| `WorkManagerTest.maxPerTopic` | empty body | - -The six middle rows matter most. Dead-letter queues, retry ordering and in-flight backpressure are -core library behaviours, and the only surviving record that tests for them were *wanted* is this -deletion diff. +| `avro` | `ParallelEoSStreamProcessorTest.offsetsAreNeverCommittedForMessagesStillInFlightSimplest` | +| `failingMessagesDontBreakCommitOrders` | `CloseAndOpenOffsetTest.offsetsOpenClose`, plus `ParallelEoSStreamProcessorTest.failingActionNothingCommitted` and `.processInKeyOrderWorkNotReturnedDoesntBreakCommits` | +| `failingMessagesThatAreRetriedDontBreakProcessingOrders` | `WorkManagerTest.testOrderedAndDelayed` and `.testUnorderedAndDelayed`, `ShardManagerTest.retryQueueOrdering`, integration `RetriesTest` | +| `messagesCanBeProcessedOptionallyPartitionOffsetOrder` | `PartitionOrderProcessingTest` and the `@EnumSource` methods in `WorkManagerTest` - ~12 classes exercise `ProcessingOrder.PARTITION` | +| `ifTooManyMessagesAreInFlightDontPollBrokerForMore` | `BrokerPollerBackpressureTest.brokerPollPausedWhenBlockedInFlightFillsBuffer` | + +Three of these deserve their detail: + +- **`avro`** - its five-line comment spec (*"send three messages - 0,1,2 / finish processing 1 / make + sure no offsets are committed / finish 0 / make sure offset 1, not 0 is committed"*) is + **verbatim what `offsetsAreNeverCommittedForMessagesStillInFlightSimplest` does today**. Nothing is + missing. Separately, and worth stating because the name is the misleading part: **the *name* + refers to Avro support, which has never existed in PC in any form.** Parallel Consumer is + serde-agnostic by design - it hands the user their `ConsumerRecord` and takes no position on how + the value was serialised. There is no Avro feature to test and there never was one planned; + the body was always about offset commit ordering. +- **`failingMessagesDontBreakCommitOrders`** - `CloseAndOpenOffsetTest.offsetsOpenClose` is a + stronger test than the stub described: it throws for values 2 and 4, closes **without draining**, + reopens, and asserts both the replay set and the commit order - **parameterised over every + `OffsetEncoding`**. +- **`ifTooManyMessagesAreInFlightDontPollBrokerForMore`** - + `brokerPollPausedWhenBlockedInFlightFillsBuffer` is a near-verbatim match for the stub's name. + +### Feature does not exist (3) - these are issues, not tests + +No test can be written for these, because there is nothing to call. Writing them means building a +feature first, and each already has a home in the tracker. + +- **`poisonPillGoesToDeadLetterQueue`** - **parallel-consumer has no dead-letter-queue concept and + never has.** Zero occurrences of dead-letter or DLQ in any `src/main/java` in the tree. Tracked as + **astubbs#149** (mirroring `confluentinc#310`), and `docs/inflight/next-candidates.md` already + ranks DLQ as **the most-demanded missing feature**. The stub is a 2020-era vote for that feature, + not a test debt. +- **`maxPerPartition`** - **no per-partition in-flight limit exists.** `ParallelConsumerOptions` has + only the global `maxConcurrency`. Nearest tracked issue: **astubbs#160**. +- **`maxPerTopic`** - **no topic-scoped concept exists at all.** `ShardKey` keys by `TopicPartition`, + or by key + `TopicPartition` - topic is never a unit of accounting. Nearest tracked issue: + **astubbs#236**. + +**The detail that makes the last two legible:** they were written as a **trio** with `maxOverall` - +limits at three scopes, global, per-partition, per-topic. **Only the global scope was ever built.** +It is `WorkManagerTest.maxInFlight` today, and it passes. So the two surviving empty bodies are not +two forgotten tests; they are the unbuilt two-thirds of one design, and the built third is tested. + +Neither astubbs#160 nor astubbs#236 is *literally* a per-scope in-flight cap. If that debt should be +visible in the tracker on its own terms, it is **one new issue about scoped concurrency limits** - +not two test methods. + +### Obsolete (1) + +**`WorkManagerOffsetMapCodecManagerTest.truncationOnCommit`** (it carried +`@Disabled("TODO: Blocker: Not implemented yet")`). **On-commit truncation is structurally +unreachable now**, so the test it describes could only ever be vacuous: + +- `PartitionState.onOffsetCommitSuccess` sets the last committed offset and marks the partition + clean. That is all it does. +- `incompleteOffsets` **by construction holds only incomplete offsets**, and the committed offset is + **the lowest incomplete one**. There is nothing tracked below it to discard. The truncation the + stub wanted has no operand. +- **Truncation that does exist happens on the bootstrap poll instead** - + `PartitionState.maybeTruncateBelowOrAbove`, reached from `maybeTruncateOrPruneTrackedOffsets` when + the first polled batch arrives. It is covered by `PartitionStateCommittedOffsetTest.compactedTopic`, + `.committedOffsetLower` and `.bootstrapPollOffsetHigherDueToRetentionOrCompaction`. + +The production javadoc on `PartitionStateManager.onOffsetCommitSuccess` still described the old +truncation, and referenced a `partitionOffsetHighWaterMarks` field that no longer exists. It is +corrected on this branch (javadoc only, no behaviour change) so the next reader is not sent looking +for a truncation that was removed years ago. + +### The restoration attempt was partial too **Neither follow-up merged.** `confluentinc#494` (*"Reenables disabled tests, to be fixed"*) and `confluentinc#496` are both named in the deleting commit's own body. The branch behind the latter, @@ -341,11 +463,13 @@ removed empty tests, to be implemented"*, and a third that adds the stubs. At it the 10** carry `throw new NotImplementedException()` (`avro`, `maxPerPartition`, `maxPerTopic`). Six return unchanged - still `@Disabled`, still empty or `assertThat(false).isTrue()` - and `truncationOnCommit` returns *without* its `@Disabled` while keeping `assertThat(true).isFalse()`, -which would have made it a hard red. So even the restoration was partial. No PR for that branch -exists on the fork. +which would have made it a hard red. No PR for that branch exists on the fork. -So the honest answer is: the *removal* half landed; the *implementing* half never did, and the -record of what was wanted now lives one `git show` away from being lost. +Read against the dispositions above, that branch would have restored one useful stub +(`userSucceedsButProduceToBrokerFails`, unchanged and still empty), three that cannot be +implemented, and one that would have gone straight to red. **The removal was the correct half to +land.** What was worth keeping was not the stubs - it was the record of *what was wanted*, which is +this section. Two more standing intentions, not deleted but never fulfilled: @@ -372,9 +496,24 @@ return !encodingsThatFail.contains(encoding); So for `BitSet`, `BitSetCompressed`, `BitSetV2`, `RunLength` and `RunLengthCompressed`, `ensureEncodingGracefullyWorksWhenOffsetsAreVeryLargeAndNotSequential` **runs to green with most of -its assertions branched around, and reports as a pass rather than a skip.** A test that looks like it -covers all codecs, reports that it covers all codecs, and materially checks about half of them. The -`assume*` name is what conceals it. +its assertions branched around, and reports as a pass rather than a skip.** The `assume*` name is +what conceals it. + +**The arithmetic is worse than "about half".** `OffsetEncoding` has **12** values. On any run: + +- **4** are dropped before the body by the real assumption in §5.2, and at least report as skipped. +- **5** reach the body but are branched around by `assumeWorkingCodec`, and report as **passes**. +- **3** run the full positive assertion path. + +So a test whose report says "12 passed or skipped, nothing failed" is materially exercising **3 of +12** encodings. That is the number to quote, not "half". + +**A second vacuous assertion lives in the same test.** Alongside the branched sites, the test asserts +`doesNotContain(2500L)` - and **2500 is never a record offset anywhere in that test**. The assertion +holds for a codec that works and for a codec that is completely broken, because the value it +excludes was never a candidate in the first place. It is not branched around and it is not skipped; +it simply cannot fail. Deleting it loses nothing; replacing it with an offset the test actually +produces is what would make it a check. **5.2 Assumption aborts - 5 tests, one site each.** All sit inside `@ParameterizedTest` methods, so they drop parameter *values* rather than whole tests, and the drop is invisible unless you read the report @@ -407,7 +546,7 @@ misclassifies badly in both directions. | `ReactorTest.publishOn`, `.subscribeOn` | same shape | | `JavaEnvTest.checkJavaEnvironment` | one `log.error` (also 3.4) | | `ParallelEoSStreamProcessorTest.closeWithoutRunningShouldBeEventBasedFast` | name/body mismatch (also 3.2) | -| `MockConsumerEarlyCloseTest.mockConsumer` | 70-line hang test; the class `@Timeout` is the only check - **and it is broken, see section 8** | +| `MockConsumerEarlyCloseTest.mockConsumer` | 70-line hang test; the class `@Timeout` is the only check - **and it is broken, see 9.1. Both halves are fixed by open PR astubbs#206** | | `ShardKeyTest.nullKey` | throws-only NPE regression guard | | `InterruptionTests.waitOnZeroCausesInfiniteWait` | `@Timeout(1, SECONDS)` is the check | | `WorkManagerOffsetMapCodecManagerTest.runLengthEncodingCompression` | helper verified to only log | @@ -450,8 +589,10 @@ misclassifies badly in both directions. ### Which of the 15 matter -Genuinely worth fixing: `closeWithoutRunningShouldBeEventBasedFast`, `stringVsByteVsBitSetEncoding`, -`MockConsumerEarlyCloseTest.mockConsumer` (via the timeout bug in section 8). +Genuinely worth fixing: `closeWithoutRunningShouldBeEventBasedFast`, `stringVsByteVsBitSetEncoding`. +`MockConsumerEarlyCloseTest.mockConsumer` belongs on that list too, but is **already owned by open PR +astubbs#206**, which both fixes its timeout (9.1) and gives it a real assertion - so it is not work +for anyone else. Defensible as they stand: the four `MutinyTest`/`ReactorTest` library scratchpads (they catch API breakage by throwing on upgrade), `ShardKeyTest.nullKey` (a throws-only NPE guard - its javadoc names @@ -489,14 +630,40 @@ copy holds nothing this document lacks. **They are recorded, not fixed.** ### 8.1 Kneecapped volumes +*Whether each commented-out value here was ever live - and what that makes it - is answered per site +in §11.* + | Location | Issue | Status | |---|---|---| -| `LargeVolumeInMemoryTests` | 500 vs 1,000,000 messages | **Open.** Still `int quantityOfMessagesToProduce = 500;` with `// 1_000_000` commented above it, `git blame`d to `565230cd5a` (2020-06-04) and untouched since. The predecessor listed this as fixed by astubbs#49, but carried a caveat - *"Check whether this fix has been merged to master before flagging again"* - and it had not: astubbs#49 never touched the file. The restore-to-1M commit exists only on `refactor/test-hardening`. | -| `MultiInstanceHighVolumeTest` | `30_000_00` - an underscore typo giving 3M, not 30M | **Open. A real defect, not a judgement call.** | -| `VeryLargeMessageVolumeTest` | 1M vs 2M | Open - decide and clean up | -| `LoadTest` | 4K vs several commented-out alternatives | Open - dead code | -| `TransactionAndCommitModeTest.numThreads` | 64 vs 1000 | Open - document or fix | -| `TransactionAndCommitModeTest.roundsAllowed` | 10, with a TODO | Open - likely masks a real issue | +| `LargeVolumeInMemoryTests` | 500 vs 1,000,000 messages | **Open.** Still `int quantityOfMessagesToProduce = 500;` with `// 1_000_000` commented above it, `git blame`d to `565230cd5a` (2020-06-04) and untouched since. The predecessor listed this as fixed by astubbs#49, but carried a caveat - *"Check whether this fix has been merged to master before flagging again"* - and it had not: astubbs#49 never touched the file. The restore-to-1M commit exists only on `refactor/test-hardening`; the **OOM diagnostics from running it are now salvaged** into [`large-volume-in-memory-tests-oom-diagnostics-2026-04-22.md`](large-volume-in-memory-tests-oom-diagnostics-2026-04-22.md) in this directory, and show 1M failing with `OutOfMemoryError` in the close path. **Restoring 1M is not a value change** - see `docs/refactoring.md`. | +| `MultiInstanceHighVolumeTest` | `30_000_00` - misgrouped underscores | **Legibility only, not a value defect.** See below. | +| `VeryLargeMessageVolumeTest` | 1M vs a `2_000_000` comment | **Not kneecapped - withdrawn.** See below. | +| `LoadTest` | 4K vs several commented-out alternatives | Open - dead code, but 4,000 is the *right* value. See §8.4. | +| `TransactionAndCommitModeTest.numThreads` | 64 vs 1000 | Open - document or fix. Note 64 was an *increase* for stability, not a reduction. | +| `TransactionAndCommitModeTest.roundsAllowed` | 10, with a TODO | **Dead code - masks nothing.** See below. | + +**`30_000_00` is not a 30M typo.** The predecessor read it as an underscore slip that lost a zero +off 30,000,000. Git history says otherwise: the line was **reduced from `10_000_000`**, and the old +value was kept as the comment directly above it. The intended value is **3,000,000** - which is what +the misgrouped literal already evaluates to. So: + +- The fix is **underscore regrouping only** (`30_000_00` → `3_000_000`). Java ignores underscores in + numeric literals, so the change is **byte-identical at runtime** - no test behaviour moves. +- **Raising it is blocked by something else in the same method:** a hard-coded 60-second + `waitAtMost`. Any larger volume has to clear that wait on a CI runner, so "put the zero back" is + not a one-token change and is not what the history asks for anyway. + +**`VeryLargeMessageVolumeTest` was never kneecapped, and this entry is withdrawn.** Its history is +`1_000_000` → `100_0000` → `1_000_000`. The middle value is **the same number**, differently +grouped - not a reduction. The `2_000_000` the predecessor compared against was **always an +aspirational comment**, never a live value that something took away. There is no restore to perform. + +**`roundsAllowed` masks nothing.** It was **assigned and never read** - dead from the moment it was +written. `ProgressTracker` in this test is constructed with **null rounds**, and it **throws if given +both a round count and a timeout**, so the rounds mechanism was structurally unreachable rather than +set too loose. Removing the variable changes no behaviour. The `// todo rounds should be 1? progress +should always be made` question attached to it is a genuine open design question about the test's +liveness signal, and it is triaged in `docs/refactoring.md` - but it is not a masked failure. ### 8.2 Weak and commented-out assertions @@ -518,24 +685,54 @@ occurrences whose byte offset falls inside a comment region. Three raw hits; two `TestConventionRules` and `QuarantineRegistryScriptTest`). **It agrees with the predecessor's count of 1.** -### 8.4 Tag-based exclusions - not a problem +*Provenance for this one, and for the §8.1 and §8.2 commented-out lines: §11.* + +### 8.4 Tag-based exclusions - correct, but they cover fewer tests than §8.1 implies -`@Tag("performance")` is excluded from default builds via `excluded.groups` in `pom.xml`, covering -`LargeVolumeInMemoryTests`, `MultiInstanceHighVolumeTest` and `VeryLargeMessageVolumeTest`. They run -in the PR performance suite. This is correct behaviour and is recorded only so nobody re-flags it. +`@Tag("performance")` is excluded from default builds via `excluded.groups` in `pom.xml`. That is +correct behaviour and is recorded only so nobody re-flags it. What matters is **which** of the §8.1 +tests it actually covers, because the volume entries read as though they are all safely parked in a +non-gating lane. They are not. + +| Test | Tag | Lane | +|---|---|---| +| `LargeVolumeInMemoryTests` | `@Tag("performance")` | excluded from default; PR performance suite | +| `MultiInstanceHighVolumeTest` | `@Tag("performance")` | excluded from default; PR performance suite | +| `VeryLargeMessageVolumeTest` | `@Tag("performance")` | excluded from default; PR performance suite | +| **`LoadTest`** | **none** | **the gating integration lane** | +| **`TransactionAndCommitModeTest`** | **`@Tag("transactions")`** | not the performance lane | + +Two corrections follow, and both change what may be done to those tests: + +- **`LoadTest` carries no tag at all, so it runs in the gating integration lane on every PR** - and + it is a **listed member of the load-tightness flake family** recorded in + `docs/inflight/test-load-tightness-flakes.md`, *at its current 4,000*. Raising its volume is not a + free cleanup of commented-out alternatives: it would push a known-tight, already-flaky, **gating** + test harder. 4,000 is the value that family was tuned to. Leave it. +- **`TransactionAndCommitModeTest` is `@Tag("transactions")`, not `@Tag("performance")`.** Whatever + its `numThreads` and volume are doing, it is not doing them behind the performance exclusion, so + the "it only runs in the perf suite" reasoning does not apply to it either. ### 8.5 Where the predecessor was wrong -Two of its conclusions are **refuted** by the git history, which it did not consult - it recorded -its reasons as *suspected*, attributed none of them to a commit, and noted an intent to +Two of its **disabling-reason** conclusions are refuted by the git history, which it did not consult - +it recorded its reasons as *suspected*, attributed none of them to a commit, and noted an intent to `git blame` that it never carried out: | It said | Actually | |---|---| -| `…Long` was "probably disabled due to flakiness on slow CI" | Disabled by `c1fefbc64`, an offset-map/commit-semantics change. No flakiness evidence exists anywhere. | -| `processInKeyOrder` was "probably flaky or the feature had bugs when it was written" | Disabled by **the same commit**, in the same hunk pattern, on the same day. | - -Both refutations rest on the same evidence: `Simplest`, `Short` and `Long` were all introduced +| `…Long` was "probably disabled due to flakiness on slow CI" | Disabled by `c1fefbc64`, an offset-map/commit-semantics change - and `origin/bugs/turn-on-commit-tests` names the offset map as the cause in the author's own words (§1.1). No flakiness evidence exists anywhere. | +| `processInKeyOrder` was "probably flaky or the feature had bugs when it was written" | Disabled by **the same commit**, in the same hunk pattern, on the same day, and un-disabled by the same one-commit branch. | + +Three further conclusions of the predecessor's are refuted in §8.1 rather than here, because they are +volume findings rather than disabling-reason findings: `30_000_00` is **not** a 30M typo (the value +was reduced from 10M and 3M is intended), `VeryLargeMessageVolumeTest` was **never** kneecapped +(`1_000_000` → `100_0000` is the same number), and `roundsAllowed` masks **nothing** (it is dead +code). None of the three was a careless claim - each is what the source looks like from the outside. +They were settled by reading history rather than the current file, which is the method §8.5 exists to +recommend. + +Both disabling-reason refutations rest on the same evidence: `Simplest`, `Short` and `Long` were all introduced together by `61f4c0e41` on 2020-05-27 and ran green for three months, so nothing about their history suggests flakiness. It is worth stating plainly that the predecessor did **not** claim `Short` superseded `Long` - that was a hypothesis raised while investigating, and the history refutes it, but @@ -567,7 +764,19 @@ tree is written correctly (`@Timeout(60)`, `@Timeout(120)`, `@Timeout(value = 3, so these three are the outliers, and the `L` suffix is the tell that the author was thinking in milliseconds. -**Highest value-to-effort fix in this document.** +**Already owned - do not fix this here.** Open PR **astubbs#206** deletes all three annotations and +replaces them with a single `@Timeout(120)` on a shared `MockConsumerTestBase` (`@Timeout` is +`@Inherited`), with a comment naming the seconds-vs-milliseconds bug. That PR also adds the missing +assertion to `MockConsumerEarlyCloseTest`, which is the other half of the problem this finding +describes. + +**And `@Timeout(60)` would have been the wrong repair.** An earlier draft of this document called +the one-token `60000L → 60` change the highest value-to-effort fix available. It is not a safe +change: **two of these tests carry internal Awaitility budgets of 45s and 50s**, so a 60-second +method timeout leaves 10-15 seconds of headroom and races the very waits the tests exist to perform +on a loaded runner. Measured runtimes are ~5s, ~10s and ~25s. **120 is the correct value**, and +arriving at it required measuring the tests rather than reading the annotation. A cheap-looking fix +that turns a no-op timeout into a flake is worse than the no-op. **9.2 `OffsetEncodingTests` uses JUnit 4's `org.junit.Assume` inside a Jupiter test, and it works only by accident of the classpath.** No pom declares JUnit 4 (`junit.version` is 5.14.4); it arrives @@ -589,7 +798,9 @@ this is the finding most likely to mislead someone reading a green test report. **9.4 Wall-clock burned by a test that cannot fail.** `MockConsumerEarlyCloseTest.mockConsumer` sleeps 5 seconds unconditionally and asserts nothing - so with 9.1's broken timeout, that is ~5 seconds per run spent on a test with no way to fail except by throwing. (`ProgressBarTest.width` -sleeps 10 seconds by construction but is `@Disabled`, so it costs nothing.) +sleeps 10 seconds by construction but is `@Disabled`, so it costs nothing.) The assertion half of +this is fixed by astubbs#206; the unconditional sleep is not, and remains fair game once that PR +lands. --- @@ -600,16 +811,17 @@ them is started here. **Trivial and safe:** -1. `@Timeout(60000L)` → `@Timeout(60)` in the three classes (9.1). Restores a real check to an - assertion-free test. -2. Delete `VertxTest.handleHttpResponseCodes` - never ran, cannot pass, tests nothing (1.3). -3. Delete `StreamTest.test`'s commented-out method (8.3). -4. Fix the `30_000_00` underscore typo (8.1). +1. Delete `VertxTest.handleHttpResponseCodes` - never ran, cannot pass, tests nothing (1.3). +2. Delete `StreamTest.test`'s commented-out method (8.3). +3. Regroup `30_000_00` to `3_000_000` (8.1). **Cosmetic only** - Java ignores underscores, so this is + byte-identical at runtime. It is a legibility fix, not the value fix an earlier draft claimed. **Honesty fixes:** -5. Rename `assumeWorkingCodec` to `isWorkingCodec`, or convert its call sites to real per-value +4. Rename `assumeWorkingCodec` to `isWorkingCodec`, or convert its call sites to real per-value assumptions so the skips appear in the report (5.1). +5. Delete or re-target the vacuous `doesNotContain(2500L)` assertion in the same test - 2500 is never + a record offset there, so it passes for a working codec and a broken one alike (5.1). 6. Point `OffsetEncodingTests` at `org.junit.jupiter.api.Assumptions` (9.2). 7. Add the timing assertion to `closeWithoutRunningShouldBeEventBasedFast`, copying the idiom from the test just above it (3.2). @@ -617,18 +829,37 @@ them is started here. **Needs a decision:** 8. `processInKeyOrder` (1.2) - the end-to-end key-order commit assertion is the one real coverage - gap. Re-enabling means reconciling it with the commit semantics `c1fefbc64` introduced. -9. `offsetsAreNeverCommitted…Long` (1.1) - same commit, same reconciliation. + gap. Re-enabling means reconciling it with the commit semantics the offset map introduced in + `c1fefbc64` - and note that `origin/bugs/turn-on-commit-tests` shows deleting the annotation alone + was tried and abandoned at WIP, so budget for the reconciliation. +9. `offsetsAreNeverCommitted…Long` (1.1) - same commit, same branch, same reconciliation. 10. `stringVsByteVsBitSetEncoding` (3.3) and `MultiTopicTest.assertCommit` (8.2) - restore the comparison/assertion, or delete it. Leaving it implies coverage that does not exist. 11. `LargeVolumeInMemoryTests` runs 500 messages where 1,000,000 is commented out (8.1). Previously - believed fixed; it is not. The restore-to-1M work exists on `refactor/test-hardening` along with - OOM diagnostics from running it - salvage both before that branch is deleted. -12. The remaining kneecapped volumes (8.1) - decide the intended value and record why. + believed fixed; it is not. **This is not a one-line value change** - see + `large-volume-in-memory-tests-oom-diagnostics-2026-04-22.md`, salvaged alongside this document, + for the `OutOfMemoryError` it produces in the close path and the 2-4GB estimate. Scoped as real + work in `docs/refactoring.md`. +12. `userSucceedsButProduceToBrokerFails` (4) - the one deleted stub that names uncovered, reachable + behaviour. Write it, or record a decision not to. **Already owned - do not touch:** - `largeNumberOfInstances` (1.4). PR `astubbs#29` carries the `@Tag("performance")` change. +- The three `@Timeout(60000L)` annotations (9.1). PR `astubbs#206` replaces them with `@Timeout(120)` + on a shared base, and adds the missing assertion to `MockConsumerEarlyCloseTest`. **`@Timeout(60)` + would have been wrong** - two of the tests wait 45s and 50s internally. + +**Not work at all** - recorded so nobody opens a ticket for them: + +- Eight of the ten deleted stubs (§4): five are covered by named enabled tests, three describe + features that do not exist (tracked as astubbs#149, astubbs#160, astubbs#236), and `truncationOnCommit` is + obsolete because on-commit truncation is structurally unreachable. +- `VeryLargeMessageVolumeTest`'s volume (8.1) - it was never reduced. +- `LoadTest`'s 4,000 (8.4) - it is untagged, gating, and a listed member of the load-tightness flake + family at exactly that value. +- `roundsAllowed` (8.1) - dead code, not a mask. The design question attached to it lives in + `docs/refactoring.md`. **Deliberately not built:** a generated `docs/INACTIVE_TESTS.md` with a `--check` staleness gate, modelled on `bin/todo-index.sh`. It is consistent with repo convention and worth revisiting, but it @@ -638,3 +869,58 @@ included. Per repo convention, triage for these lives in `docs/refactoring.md`, not here. This document is the inventory and the evidence. + +--- + +## 11. Addendum, 2026-08-12: what the commented-out lines were, and which of them this audit traced + +The 2026-08-08 findings above stand as written. This section adds the one question none of them +asked: **was the commented-out line ever live?** Nine review threads on astubbs#264 objected to the +deletions that acted on §8.1-§8.3, all saying the same thing - the commented-out code was there for +a reason. Answering that question per site shows they are right about some of it, and shows why. + +**A line that was never live is more likely to be a record of a manual run, not less.** Uncommenting +a rung, running it, and commenting it back leaves no trace in git; the parked state is all that +survives. So a born-commented ladder *is* the procedure - it is the only place the volumes someone +actually exercised are written down. A superseded live value is the opposite: the history already +holds it, and the comment is residue. + +| Line | Ever live? | Provenance | What it is | +|---|---|---|---| +| `MultiInstanceHighVolumeTest` `//10_000_000` | **Yes** | Live at `04cd4d81` (2020-12-14); commented at `ad3636a5` (2021-07-02) when reduced to 3M | Residue. §8.1 traced this correctly. | +| `StreamTest` `//@Test` | No | Born commented at `61f4c0e4` (2020-05-27) | Scratchpad, never wired in. §8.3 correct. | +| `VeryLargeMessageVolumeTest` `//2_000_000` | No | Added at `2b0ab66b` (2020-11-27), in the same edit that lowered the live value | Aspiration. §8.1 identified this correctly - *"always an aspirational comment"*. The deletion commit `e67d8b89` called it "stale", which is not what §8.1 said. | +| `LoadTest` `8_000_0 / 4_000_00 / 4_000_0 / 8` | No | All four born commented in one commit, `af1fa5de` (2020-06-17), beside the live `4_000` | An authored range, 8 to 400,000, written in one sitting. §8.1 called it "dead code" without tracing it. `8` is a debug-fast setting, not a volume rung. | +| `TransactionAndCommitModeTest` `2 / 100 / 1000` | No | Born commented at `2b0ab66b` (2020-11-27) beside live `numThreads = 16` | A concurrency ladder bracketing the live value. §8.1 said *"document or fix"*; `e67d8b89` did neither and deleted it. | + +**One rung does not survive its own test, and running it is what showed that.** `LoadTest`'s `8` was +parked as a fast-iteration setting, but it could never have executed: the key range is derived as +`volume / 100`, so eight records produced zero keys and `publishMessages` threw +`IndexOutOfBoundsException` on the first send. That is true of `af1fa5de` as authored, not a later +rot. So "born commented means someone ran it by hand" holds for the three volume rungs and fails for +this one - provenance narrows the question, it does not answer it, and only executing the rung +settles it. The floor added in `setupTestData` makes the setting work as intended rather than +deleting it a second time. + +Reproduce any row with: + +```bash +git log --all -p -S'' -- '' # introduced, and whether as a comment +git log -p ^ -- '' # the file's own lineage on this branch +``` + +**§1.3's verdict on `VertxTest.handleHttpResponseCodes` is right about the stub and silent about the +gap.** There is nothing in `assertThat(true).isFalse()` to restore. But §1.3 also records that +non-2xx handling is untested and that `testHttp` asserts 200 on the happy path only - and in +`VertxParallelEoSStreamProcessor`, `send.onSuccess` calls `wc.onUserFunctionSuccess()`. A Vert.x +`WebClient` future succeeds on any HTTP response and fails only on transport errors, so a 5xx +appears to mark the work succeeded. That is a coverage gap the stub was named for, and it is worth +writing even though the stub was not worth keeping. + +Recovery of the born-commented procedures, and characterization of the Vert.x behaviour, were planned +in `docs/plans/2026-08-12-001-test-recover-manual-test-procedures-plan.md`. That work has since +landed in astubbs#264, and the plan was deleted with it per the `AGENTS.md` lifecycle rule; read it +at `git show a69cd348:docs/plans/2026-08-12-001-test-recover-manual-test-procedures-plan.md`. The +recovered rungs now live in the tests themselves - `LoadTest.RECOVERED_VOLUMES`, the concurrency +ladder in `TransactionAndCommitModeTest`, the environment dump in `AmbientProbeExtension`, and the +Vert.x 5xx characterization in `VertxTest`. diff --git a/docs/test-hardening/large-volume-in-memory-tests-oom-diagnostics-2026-04-22.md b/docs/test-hardening/large-volume-in-memory-tests-oom-diagnostics-2026-04-22.md new file mode 100644 index 000000000..e8c4584fb --- /dev/null +++ b/docs/test-hardening/large-volume-in-memory-tests-oom-diagnostics-2026-04-22.md @@ -0,0 +1,138 @@ +> **Salvaged 2026-08-08 - unmodified below this line.** +> +> This document existed **only** on the unmerged branch `origin/refactor/test-hardening`, recovered +> with `git show 16ce9727:docs/test-hardening/large-volume-in-memory-tests-oom-diagnostics-2026-04-22.md`. +> That branch is on the safe-to-delete list, and this was the **only copy** of the measurements +> showing that restoring `LargeVolumeInMemoryTests` to 1,000,000 messages produces +> `java.lang.OutOfMemoryError: Java heap space` in the close path. Deleting the branch would have +> deleted the evidence, and the next person to try the "one-line" restore would have rediscovered +> the OOM from scratch. +> +> It is reproduced **verbatim**, including its own dating, branch references and open questions, so +> it can be trusted as a primary record rather than a paraphrase. Read its `## Related` section with +> that in mind: it refers to branch state as of 2026-04-22, and the predecessor audit it cites +> (`disabled-and-weakened-tests-audit-2026-04-22.md`) is superseded by +> `inactive-tests-audit-2026-08-08.md` in this directory. Its §2.1 reference maps to §8.1 there. +> +> **What has changed since it was written:** the 500-message kneecap it describes is still in place +> on master - astubbs#49 never touched the file, contrary to what the predecessor audit recorded. The +> work this document scopes is triaged in `docs/refactoring.md`. + +--- + +# `LargeVolumeInMemoryTests` - OOM at 1M messages + +**Date observed:** 2026-04-22 +**Branch:** `fix/ci-kafka-matrix` (astubbs#49) at that time +**Context:** Restoring `quantityOfMessagesToProduce` from 500 to 1,000,000 messages caused an `OutOfMemoryError: Java heap space` on GitHub Actions `ubuntu-latest` runners. + +## Symptom + +Test hangs/crashes with OOM while closing `ParallelEoSStreamProcessor` after processing 1M messages. The OOM surfaces in the `BrokerPollSystem` close path. + +## Stack Trace + +``` +23:09.107 WARN [pc-control] (AbstractParallelEoSStreamProcessor.java:733)#innerDoClose failed to close brokerPollSubsystem during close sequence +java.util.concurrent.ExecutionException: java.lang.OutOfMemoryError: Java heap space + at java.base/java.util.concurrent.FutureTask.report(FutureTask.java:122) ~[na:na] + at java.base/java.util.concurrent.FutureTask.get(FutureTask.java:205) ~[na:na] + at bz.stub.parallelconsumer.internal.BrokerPollSystem.closeAndWait(BrokerPollSystem.java:278) ~[parallel-consumer-core-0.6.0.0-SNAPSHOT.jar:na] + at bz.stub.parallelconsumer.internal.AbstractParallelEoSStreamProcessor.innerDoClose(AbstractParallelEoSStreamProcessor.java:731) ~[parallel-consumer-core-0.6.0.0-SNAPSHOT.jar:na] + at bz.stub.parallelconsumer.internal.AbstractParallelEoSStreamProcessor.doClose(AbstractParallelEoSStreamProcessor.java:658) ~[parallel-consumer-core-0.6.0.0-SNAPSHOT.jar:na] + at bz.stub.parallelconsumer.internal.AbstractParallelEoSStreamProcessor.lambda$supervisorLoop$9(AbstractParallelEoSStreamProcessor.java:855) ~[parallel-consumer-core-0.6.0.0-SNAPSHOT.jar:na] + at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264) ~[na:na] + at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136) ~[na:na] + at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635) ~[na:na] + at java.base/java.lang.Thread.run(Thread.java:840) ~[na:na] +Caused by: java.lang.OutOfMemoryError: Java heap space + +23:15.099 WARN [pc-control] (PCMetrics.java:206)#close Trying to close PCMetrics instance that is already closed. +23:15.099 ERROR [pc-control] (AbstractParallelEoSStreamProcessor.java:668)#doClose PC closed due to error: java.lang.RuntimeException: Error from poll control thread: Error in BrokerPollSystem system. +``` + +## Location + +`parallel-consumer-core/src/test-integration/java/bz/stub/parallelconsumer/integrationTests/LargeVolumeInMemoryTests.java:62` + +```java +int quantityOfMessagesToProduce = 1_000_000; // OOMs on ubuntu-latest with default heap +``` + +(Originally this line was `int quantityOfMessagesToProduce = 500;` with the `1_000_000` version commented out. Restoring to 1M caused this failure.) + +## What the Test Actually Does + +- Creates a `MockConsumer` (in-memory - hence "InMemory" in the test name) +- Calls `ktu.generateRecords(1_000_000)` to create 1M `ConsumerRecord` objects in a List +- Sends all of them to `consumerSpy` via `ktu.send(consumerSpy, records)` +- Runs `parallelConsumer.pollAndProduceMany` with 1M `CountDownLatch` counts +- Waits for all to be consumed +- Asserts `producerSpy.history().hasSize(quantityOfMessagesToProduce)` - i.e., all 1M producer records are retained + +## Why It Runs Out of Memory + +The test accumulates everything in memory: + +1. **1M `ConsumerRecord` objects** - each with key + value strings, topic, partition, offset, headers, timestamp. Rough estimate: ~200-400 bytes each = **200-400 MB**. +2. **1M mocked `ProducerRecord` objects** - accumulated in `producerSpy.history()` for the final size assertion. Similar footprint = **200-400 MB**. +3. **1M latch decrements** through `allMessagesConsumedLatch` + bookkeeping in `ParallelEoSStreamProcessor`. +4. Plus all the internal state PC tracks per in-flight message (WorkContainer, offset encoding, etc.) + +GitHub Actions `ubuntu-latest` runners have ~7GB RAM but surefire default heap is typically 256-512MB. The test likely needs 2-4 GB. + +The OOM manifests during `close()` because that's when PC tries to drain the remaining work mailbox, which is still holding references to everything. + +## Suggested Fixes (for the triage agent) + +### Option A: Increase heap for the test + +Simplest. Add JVM args to the CI profile or test-specific config: + +```xml +-Xmx3g +``` + +**Risk:** Hides resource issues; test may still be tight on 2GB runners. Check what JVM heap is allocated to other runners for parity. + +### Option B: Stream, don't accumulate + +The test currently asserts on `producerSpy.history().size()`. That forces retention of every produced record. Change to a counter or running hash: + +```java +// Replace: List> history (1M entries) +// With: AtomicLong producedCount + small sampling buffer for ordering checks +``` + +**Risk:** Changes test semantics - need to decide what invariants must be checked and reduce to just those. + +### Option C: Reduce volume + +Pick a smaller number that still exercises the same code paths. Probably 100k-500k. + +**Risk:** Reduces coverage; conflicts with the intent of "Large Volume" in the test name. + +### Option D: Break into streaming batches + +Run the test in chunks of e.g. 100k and assert between batches, releasing references. More test complexity but preserves volume. + +**Risk:** More maintenance; test structure becomes harder to read. + +## Recommendation + +Start with **Option A** (bump heap to 2-3GB just for this test class via a failsafe ``). If it still OOMs or is too slow, fall back to **Option B** (switch size assertion to a counter) which is probably the "correct" fix. + +Do not silently drop back to 500 messages - that was the original kneecap and the whole point of restoring it is to have a real volume test. + +## Related + +- Commit that restored the volume: the cherry-picked `test: restore LargeVolumeInMemoryTests to 1M messages` on this branch +- Original kneecap predates the audit - see `disabled-and-weakened-tests-audit-2026-04-22.md` section 2.1 +- Test class has `@Tag("performance")` so this only runs in the performance suite job, not regular PR builds + +## Verification When Fixed + +1. Test passes on `ubuntu-latest` GitHub runner (standard hosted, ~7GB RAM) in the PR performance suite job +2. Test passes 3 runs in a row (no flake) +3. Runtime documented - under 10 minutes is ideal for PR builds +4. If Option A was chosen: the heap setting is documented with a comment explaining why diff --git a/docs/todo-index.md b/docs/todo-index.md index fcbe19166..bc5178d85 100644 --- a/docs/todo-index.md +++ b/docs/todo-index.md @@ -3,8 +3,7 @@ **Generated file - do not edit by hand.** Regenerate with `bin/todo-index.sh` (`bin/todo-index.sh --check` fails if this file is stale). -Every `TODO` / `FIXME` / `XXX` marker in the tracked tree, grouped by module. **87 marker(s)** at -the time of generation. +Every `TODO` / `FIXME` / `XXX` marker in the tracked tree, grouped by module. ## Prioritised? See the refactoring backlog @@ -28,6 +27,11 @@ grep -rn "check legacy is recursive" A line number would be wrong within a day and would drag this file into every unrelated diff. The marker's own text is stable until someone edits the marker. +For the same reason this file carries no marker **count**: it would be a second, drifting statement +of something the list below already says exactly, and the two would disagree the moment either moved. +Count the entries if you need a number. `bin/todo-index.sh` prints one to the console when it runs, +where it cannot go stale. + ## How to use this Markers here are *not* a backlog - most are notes-to-self left next to the code they concern, and @@ -184,7 +188,6 @@ that line, leave it in the code - it will show up here. **`parallel-consumer-core/src/test-integration/java/bz/stub/parallelconsumer/integrationTests/TransactionAndCommitModeTest.java`** -- todo rounds should be 1? progress should always be made - todo performance: tighten up progress check (<2) **`parallel-consumer-core/src/test-integration/java/bz/stub/parallelconsumer/integrationTests/TransactionMarkersTest.java`** @@ -209,7 +212,6 @@ that line, leave it in the code - it will show up here. - awaitForSomeLoopCycles(50); // async commit can be slow - todo change this to event based - awaitForSomeLoopCycles(3); // async commit can be slow - todo change this to event based - awaitForSomeLoopCycles(3); // async commit can be slow - todo change this to event based -- verify(producerSpy, after(verificationWaitDelay).never()).commitTransaction(); // todo remove all wait nevers in favour of triggers as it slows down test **`parallel-consumer-core/src/test/java/bz/stub/parallelconsumer/internal/utils/KafkaTestUtils.java`** diff --git a/parallel-consumer-core/src/main/java/bz/stub/parallelconsumer/state/PartitionStateManager.java b/parallel-consumer-core/src/main/java/bz/stub/parallelconsumer/state/PartitionStateManager.java index 181f4d4ac..4a0b12832 100644 --- a/parallel-consumer-core/src/main/java/bz/stub/parallelconsumer/state/PartitionStateManager.java +++ b/parallel-consumer-core/src/main/java/bz/stub/parallelconsumer/state/PartitionStateManager.java @@ -207,14 +207,25 @@ public void onPartitionsLost(Collection partitions) { } /** - * Truncate our tracked offsets as a commit was successful, so the low water mark rises, and we dont' need to track - * as much anymore. + * Records that a commit succeeded, for each partition that was committed. *

- * When commits are made to broker, we can throw away all the individually tracked offsets before the committed - * offset. + * Per partition, this delegates to {@link PartitionState#onOffsetCommitSuccess}, which stores the newly committed + * offset as the partition's last committed offset and marks the partition clean (unless its state changed again + * while the commit was in flight, in which case it stays dirty and will be committed again). + *

+ * No offsets are discarded here. Earlier versions of this javadoc described truncating tracked offsets below + * the committed offset once a commit landed. That does not happen, and cannot: {@link PartitionState} tracks only + * incomplete offsets, and the offset committed is the lowest incomplete one - so there is nothing below it + * left to throw away. + *

+ * Truncation of tracked state does still exist, but it happens on the bootstrap poll rather than on commit - + * see {@link PartitionState}'s {@code maybeTruncateBelowOrAbove}, reached from its + * {@code maybeTruncateOrPruneTrackedOffsets}. That is where records removed by retention or compaction, or a + * committed offset raised externally, get reconciled against the offsets we track. + * + * @param committed the offsets just successfully committed to the broker, by partition */ public void onOffsetCommitSuccess(Map committed) { - // partitionOffsetHighWaterMarks this will get overwritten in due course committed.forEach((tp, meta) -> { var partition = getPartitionState(tp); partition.onOffsetCommitSuccess(meta); diff --git a/parallel-consumer-core/src/test-integration/java/bz/stub/parallelconsumer/integrationTests/AmbientProbeExtension.java b/parallel-consumer-core/src/test-integration/java/bz/stub/parallelconsumer/integrationTests/AmbientProbeExtension.java index 61f19beb0..5924738f8 100644 --- a/parallel-consumer-core/src/test-integration/java/bz/stub/parallelconsumer/integrationTests/AmbientProbeExtension.java +++ b/parallel-consumer-core/src/test-integration/java/bz/stub/parallelconsumer/integrationTests/AmbientProbeExtension.java @@ -17,8 +17,14 @@ import java.util.ArrayList; import java.util.Comparator; import java.util.List; +import java.util.Locale; +import java.util.TreeMap; +import java.util.concurrent.atomic.AtomicBoolean; +import java.util.regex.Pattern; import java.util.stream.Collectors; +import static java.util.stream.Collectors.toMap; + /** * Ambient "flight recorder" for every broker integration test: runs {@link ProgressProbe} in * observer mode in the background so that when a test fails or times out, the generic Awaitility @@ -198,10 +204,91 @@ public static String buildAutopsy(ExtensionContext context, ProgressProbe probe, sb.append(" - ").append(line).append('\n'); } } + appendEnvironment(sb); sb.append("=== END AMBIENT PROBE AUTOPSY ==="); return sb.toString(); } + /** + * Emitted on the first autopsy in each JVM, and pointed at thereafter rather than repeating a few + * hundred lines per failing test. Note "each JVM", not each CI run: the integration lane forks + * several JVMs, so a run can carry one dump per fork, each attached to whichever test failed + * first there. That is the cost of not repeating it; the alternative buries the probe findings + * the autopsy exists for. + *

+ * This is what {@code JavaEnvTest} was doing by hand. Its javadoc said so - "used to + * manually inspect the java environment at runtime, particularly useful for CI + * environments" - and it was deleted in {@code cadf4c95} for asserting nothing, which was + * true and beside the point: it was a diagnostic, not a test, and deleting it removed the tool + * without automating what the tool was for. The autopsy is where a reader already looks when a + * broker integration test fails, per {@code AGENTS.md}, so the information now arrives there + * without anyone remembering to go and get it. + */ + private static void appendEnvironment(StringBuilder sb) { + if (!ENVIRONMENT_DUMPED.compareAndSet(false, true)) { + sb.append("environment: dumped in this JVM's first autopsy\n"); + return; + } + sb.append("environment (once per JVM):\n"); + new TreeMap<>(System.getProperties().entrySet().stream() + .collect(toMap(e -> String.valueOf(e.getKey()), e -> String.valueOf(e.getValue()), (a, b) -> a))) + .forEach((key, value) -> sb.append(" ").append(key).append('=') + .append(redact(key, value)).append('\n')); + } + + /** + * The autopsy prints straight to CI logs, which anyone with access to the Actions run can read, so a property + * whose NAME reads like a credential has its value masked. Nothing in this repo passes a secret as {@code -D} + * today - this stops a future one from being dumped rather than fixing a present leak. + *

+ * Masking by name rather than filtering to an allowlist of known-interesting prefixes is deliberate: an + * allowlist silently drops the next knob somebody adds, which is precisely when the dump is wanted, and it + * would need hand-maintaining against a set the code cannot derive. The key is always printed, so the reader + * still sees the property was set - only the value is withheld. + */ + private static String redact(String key, String value) { + String lower = key.toLowerCase(Locale.ROOT); + for (String marker : SECRET_KEY_MARKERS) { + if (lower.contains(marker)) { + return "***"; + } + } + if (value != null && SECRET_IN_VALUE.matcher(value).find()) { + return "*** (value matched a credential pattern)"; + } + return value == null ? "null" : value.replace("\n", "\\n").replace("\r", "\\r"); + } + + private static final String[] SECRET_KEY_MARKERS = + {"password", "passwd", "pwd", "passphrase", "secret", "token", "credential", + "apikey", "api.key", "accesskey", "access.key", "privatekey", "private.key"}; + + /** + * Matching the key name alone leaves the more likely leak wide open: people name a property for what it + * configures, not for the fact that a credential happens to be inside it. A JDBC URL + * ({@code ...?user=svc&password=hunter2}) or a URL with userinfo ({@code https://user:tok3n@host/x}) sails + * past every marker above, because {@code test.db.url} contains none of them. + *

+ * So the value is scanned too, for embedded {@code key=value} credential pairs and for URL userinfo. This + * is a denylist and denylists fail open, which is the wrong direction for a masking control - but the + * alternative here is an allowlist of interesting properties, which fails the diagnostic instead, and the + * dump exists to be complete. Two overlapping checks narrow the gap without capping what can be reported. + */ + private static final Pattern SECRET_IN_VALUE = Pattern.compile( + "(?i)(password|passwd|passphrase|secret|token|credential|api[._-]?key)\\s*[=:]\\s*\\S" + + "|://[^/@\\s]+:[^/@\\s]+@"); + + /** + * Public for unit testing only - see {@link #isDisabled(ExtensionContext)}. Resets the + * once-per-run guard between tests of {@link #buildAutopsy}; production code never calls it, + * because the guard is the point. + */ + public static void resetEnvironmentDumpForTest() { + ENVIRONMENT_DUMPED.set(false); + } + + private static final AtomicBoolean ENVIRONMENT_DUMPED = new AtomicBoolean(); + private static String describe(Throwable cause) { if (cause == null) { return "(no cause reported)"; diff --git a/parallel-consumer-core/src/test-integration/java/bz/stub/parallelconsumer/integrationTests/BrokerIntegrationTest.java b/parallel-consumer-core/src/test-integration/java/bz/stub/parallelconsumer/integrationTests/BrokerIntegrationTest.java index df750080c..accf742d7 100644 --- a/parallel-consumer-core/src/test-integration/java/bz/stub/parallelconsumer/integrationTests/BrokerIntegrationTest.java +++ b/parallel-consumer-core/src/test-integration/java/bz/stub/parallelconsumer/integrationTests/BrokerIntegrationTest.java @@ -61,6 +61,11 @@ public abstract class BrokerIntegrationTest { int numPartitions = 1; int partitionNumber = 0; + /** @see CompletionCeiling#completionCeiling(long, long, Duration) */ + public static Duration completionCeiling(long units, long gatingUnits, Duration ceilingAtGating) { + return CompletionCeiling.completionCeiling(units, gatingUnits, ceilingAtGating); + } + @Getter String topic; diff --git a/parallel-consumer-core/src/test-integration/java/bz/stub/parallelconsumer/integrationTests/CompletionCeiling.java b/parallel-consumer-core/src/test-integration/java/bz/stub/parallelconsumer/integrationTests/CompletionCeiling.java new file mode 100644 index 000000000..1e25e4ad9 --- /dev/null +++ b/parallel-consumer-core/src/test-integration/java/bz/stub/parallelconsumer/integrationTests/CompletionCeiling.java @@ -0,0 +1,60 @@ +package bz.stub.parallelconsumer.integrationTests; + +/*- + * Copyright (C) 2026 Antony Stubbs and contributors + */ + +import java.time.Duration; + +/** + * How long a run at a given size is allowed to take, given the deadline its gating size has always + * had. + *

+ * This exists because a hard-coded deadline is how a volume knob quietly stops working. Every volume + * alternative recovered on this branch had been parked as a comment beside a live value, and at each + * site the deadline stayed fixed while the volume above it moved - so the higher setting could not + * pass no matter how healthy the run was, and was eventually deleted as dead. + * {@code MultiInstanceHighVolumeTest} says so in its own history: the volume was reduced because + * "the 60s wait below cannot be met at higher volumes". + *

+ * It lives here, apart from {@link BrokerIntegrationTest}, so it can be unit tested. That class + * initialises a {@code KafkaContainer} in a static field, so naming it from the unit suite would + * start a container to test three lines of arithmetic. + */ +public final class CompletionCeiling { + + private CompletionCeiling() { + } + + /** + * Returns exactly {@code ceilingAtGating} at the gating size, so a test's default deadline is + * unchanged, and never returns less - raising the size never shortens the deadline. + *

+ * It is a ceiling, not a throughput assertion. Proving a rate is what the performance suite is + * for; this only has to stop the deadline being the thing that fails a healthy run. + *

+ * The scaling is linear in size, which assumes cost per unit is roughly flat. Where it is not - + * if batching amortises better at high volume - the ceiling is looser than it needs to be at the + * top of a ladder. That is the safe direction for a ceiling, but it does mean a slow-down + * regression has more room to hide at the highest rungs than at the gating one. + * + * @throws IllegalArgumentException if {@code gatingUnits} is not positive, or if the scaled + * deadline would overflow {@link Duration} - both of which mean + * a misconfigured knob rather than a slow run, and are worth + * saying so rather than surfacing as arithmetic from + * {@code java.time} internals. + */ + public static Duration completionCeiling(long units, long gatingUnits, Duration ceilingAtGating) { + if (gatingUnits <= 0) { + throw new IllegalArgumentException("gatingUnits must be positive, was " + gatingUnits); + } + long safeUnits = Math.max(1, units); + long nanosAtGating = ceilingAtGating.toNanos(); + if (safeUnits > Long.MAX_VALUE / nanosAtGating) { + throw new IllegalArgumentException( + "size " + units + " is too large to scale a " + ceilingAtGating + " ceiling - check the knob"); + } + Duration scaled = ceilingAtGating.multipliedBy(safeUnits).dividedBy(gatingUnits); + return scaled.compareTo(ceilingAtGating) > 0 ? scaled : ceilingAtGating; + } +} diff --git a/parallel-consumer-core/src/test-integration/java/bz/stub/parallelconsumer/integrationTests/LoadTest.java b/parallel-consumer-core/src/test-integration/java/bz/stub/parallelconsumer/integrationTests/LoadTest.java index 271a170cd..9b3acc1a0 100644 --- a/parallel-consumer-core/src/test-integration/java/bz/stub/parallelconsumer/integrationTests/LoadTest.java +++ b/parallel-consumer-core/src/test-integration/java/bz/stub/parallelconsumer/integrationTests/LoadTest.java @@ -19,10 +19,12 @@ import org.apache.kafka.clients.producer.ProducerRecord; import org.apache.kafka.clients.producer.RecordMetadata; import org.assertj.core.util.Lists; +import org.junit.jupiter.api.Tag; import org.junit.jupiter.api.Test; import org.testcontainers.junit.jupiter.Testcontainers; import pl.tlinkowski.unij.api.UniLists; +import java.time.Duration; import java.util.*; import java.util.concurrent.Executors; import java.util.concurrent.Future; @@ -43,23 +45,69 @@ @Slf4j public class LoadTest extends DbTest { - // static int total = 8_000_0; -// static int total = 4_000_00; -// static int total = 4_000_0; - static int total = 4_000; -// static int total = 8; + /** + * The gating volume. Untagged, so this runs in the gating integration lane, and it is a listed + * member of the load-tightness flake family at exactly this volume + * (docs/inflight/test-load-tightness-flakes.md). Classify before raising it - that family is + * where the confluentinc#857 deadlock was hiding. + */ + static final int GATING_TOTAL = 4_000; + + /** + * The range this test was actually run at by hand. Authored in {@code af1fa5de} (2020-06-17) as + * four commented-out alternatives beside the live value, and deleted in {@code e67d8b89} on the + * grounds that they were dead - but none of them was ever live, so the ladder was the only + * record of which volumes anyone had exercised. Reachable now without editing the file: + * + * 

./mvnw verify -Pci -Dload.total=400000
+ * + * Run that top rung outside the CI lanes, or raise their job timeout first. The deadline is derived, so + * {@code ceilingFor(400_000)} scales the gating 60s by 100 to 100 minutes, while both lanes that + * run this suite cap at 60 - {@code maven.yml}'s performance leg and {@code pr-highcpu-fast-feedback.yml}. + * Inside either, a genuinely hung run - the exact failure the deadline exists to catch - is killed by the + * runner 40 minutes before the ceiling fires, turning a diagnostic {@code ConditionTimeoutException} into + * an ambiguous cancelled job. + *

+ * The same commit also parked {@code 8}, which is not a volume rung at all - it is the + * fast-iteration setting for working on this harness itself, and it was deleted as though it + * were one of the volumes. It is {@code -Dload.total=8}, and it works now: as parked it could + * never have run, because the key range is derived as {@code volume / 100} and eight records + * gave zero keys. {@link #setupTestData} floors that at one. + *

+ * Property convention is {@code .}, matching the existing {@code chaos.seed} and + * {@code ambient.probe}. + */ + static final int[] RECOVERED_VOLUMES = {40_000, 80_000, 400_000}; + + /** + * The volume the high-volume case runs at when the performance lane selects it. The smallest + * recovered rung, so the lane gets a genuine high-volume run without a multi-hour default. + */ + static final int HIGH_VOLUME_TOTAL = RECOVERED_VOLUMES[0]; + + static int total = Integer.getInteger("load.total", GATING_TOTAL); + + /** The deadline the gating volume has always had. */ + private static final Duration GATING_CEILING = ofSeconds(60); + + private static Duration ceilingFor(int volume) { + return completionCeiling(volume, GATING_TOTAL, GATING_CEILING); + } @SneakyThrows - public void setupTestData() { + public void setupTestData(int volume) { setupTopic(); - publishMessages(total / 100, total, topic); + // One key per hundred records, but never zero. Below 100 records the original `volume / 100` + // produced an empty key list and publishMessages threw IndexOutOfBounds on the first send - + // which is why the parked `8` could not have run as written, in af1fa5de or since. + publishMessages(Math.max(1, volume / 100), volume, topic); } @SneakyThrows @Test void timedNormalKafkaConsumerTest() { - setupTestData(); + setupTestData(total); // subscribe in advance, it can be a few seconds getKcu().getConsumer().subscribe(UniLists.of(topic)); @@ -70,7 +118,49 @@ void timedNormalKafkaConsumerTest() { @SneakyThrows @Test void asyncConsumeAndProcess() { - setupTestData(); + asyncConsumeAndProcess(total); + } + + /** + * The same scenario at one of the {@link #RECOVERED_VOLUMES}. Tagged, so the gating lane never + * runs it and the default excluded groups keep it out; reach the top of the recovered range by + * adding {@code -Dload.total=400000}. + *

+ * The tag is not opt-in, though: {@code bin/performance-test.sh} passes + * {@code -Dincluded.groups=performance}, and that script is the "Performance Tests" leg of + * {@code maven.yml} - a required check on every PR - so this case runs automatically there at + * {@link #HIGH_VOLUME_TOTAL}, ten times the gating volume, with no retry. {@code LoadTest} is a + * listed member of the load-tightness flake family at the gating volume + * (docs/inflight/test-load-tightness-flakes.md, 1/20, undiagnosed). + *

+ * Measured before leaving it automatic, per the {@code AGENTS.md} rule to separate + * test-infra contention from a genuine concurrency bug rather than tuning a deadline: given an + * uncontended broker, this case ran 5/5 green at 40,000, each in ~52s against its derived + * ceiling of 600s. So the code is not the problem at this volume, and it is nowhere near the + * deadline - by that rule, failures in this family are contention. + *

+ * Which leaves what the measurement could not clear: the performance lane does not give it a + * JVM of its own. Failsafe declares no {@code forkCount}, so all four {@code @Tag("performance")} + * classes run in one fork, sharing one heap and the static {@code BrokerIntegrationTest.kafkaContainer} - + * and, because this class extends {@code DbTest}, a Postgres container that none of its tests use. + *

+ * They run sequentially in that fork, not concurrently: {@code -Pci} sets + * {@code parallel-tests=false}, and failsafe's {@code } element is not read by the JUnit + * Platform provider at all. So if this case flakes, reach for heap accumulated across the four classes + * under {@code reuseForks}, container start-up, or the lane's 60-minute cap - not for broker + * contention between concurrent tests, which cannot occur here. The gating integration lane forks + * ({@code -DforkCount=4 -DreuseForks=true}) and would give each class its own broker; this lane does not. + */ + @SneakyThrows + @Test + @Tag("performance") + void asyncConsumeAndProcessAtVolume() { + asyncConsumeAndProcess(Integer.getInteger("load.total", HIGH_VOLUME_TOTAL)); + } + + @SneakyThrows + private void asyncConsumeAndProcess(int volume) { + setupTestData(volume); KafkaConsumer newConsumer = getKcu().createNewConsumer(); // @@ -88,7 +178,7 @@ void asyncConsumeAndProcess() { AtomicInteger msgCount = new AtomicInteger(0); - ProgressBar pb = ProgressBarUtils.getNewMessagesBar(log, total); + ProgressBar pb = ProgressBarUtils.getNewMessagesBar(log, volume); try (pb) { async.poll(r -> { @@ -102,10 +192,10 @@ void asyncConsumeAndProcess() { }); // keep checking how many message's we've processed - await().atMost(ofSeconds(60)).until(() -> { + await().atMost(ceilingFor(volume)).until(() -> { // log.debug("msg count: {}", msgCount.get()); pb.stepTo(msgCount.get()); - return msgCount.get() >= total; + return msgCount.get() >= volume; }); } async.close(); @@ -151,7 +241,7 @@ private void readRecordsPlainConsumer(int total, String topic) { }); try (pb) { - await().atMost(ofSeconds(60)).untilAsserted(() -> { + await().atMost(ceilingFor(total)).untilAsserted(() -> { assertThat(count).hasValue(total); }); } diff --git a/parallel-consumer-core/src/test-integration/java/bz/stub/parallelconsumer/integrationTests/MultiInstanceHighVolumeTest.java b/parallel-consumer-core/src/test-integration/java/bz/stub/parallelconsumer/integrationTests/MultiInstanceHighVolumeTest.java index a1df539a1..9ab59e78d 100644 --- a/parallel-consumer-core/src/test-integration/java/bz/stub/parallelconsumer/integrationTests/MultiInstanceHighVolumeTest.java +++ b/parallel-consumer-core/src/test-integration/java/bz/stub/parallelconsumer/integrationTests/MultiInstanceHighVolumeTest.java @@ -21,6 +21,7 @@ import org.junit.jupiter.api.Tag; import org.junit.jupiter.api.Test; +import java.time.Duration; import java.util.ArrayList; import java.util.Collections; import java.util.List; @@ -50,6 +51,38 @@ class MultiInstanceHighVolumeTest extends BrokerIntegrationTest ProcessingOrder order = ProcessingOrder.KEY; + static final int GATING_VOLUME = 3_000_000; + + /** + * The volume this test runs at. Unlike the other recovered sites, the {@code //10_000_000} that + * sat above this line was live - at {@code 04cd4d81} (2020-12-14) - and was commented + * out at {@code ad3636a5} (2021-07-02) when the value was reduced. Git holds that history, so + * the comment was residue and stays deleted. + *

+ * What was not residue is the reason for the reduction. The wait below was hard-coded at 60 + * seconds, so the higher volume could not be met regardless of whether the run was healthy - + * the volume was lowered to fit a deadline rather than because 10M was wrong. With the deadline + * scaling, the original volume is reachable again: + * + * 

bin/performance-test.sh -Dmultiinstance.messages=10000000
+ * + * Through the script, not a bare {@code ./mvnw verify -Pci}: this class is {@code @Tag("performance")} and + * the default {@code excluded.groups} is {@code performance,chaos,quarantined}, so a plain run deselects the + * very test the property configures - and exits BUILD SUCCESS having run nothing. Exclusion also beats + * inclusion, so {@code -Dincluded.groups=performance} alone is not enough either; the script passes both + * that and {@code -Dexcluded.groups=}, which is why the CI lane works. + */ + private static int volume() { + return Integer.getInteger("multiinstance.messages", GATING_VOLUME); + } + + /** The deadline this test has always had at its own volume. */ + private static final Duration GATING_CEILING = ofSeconds(60); + + private static Duration ceilingFor(int messages) { + return completionCeiling(messages, GATING_VOLUME, GATING_CEILING); + } + // todo multi commit mode, multi partition count, multi instance count? 2,3,10,100? more instances than partitions, more partitions than instances @SneakyThrows @Test @@ -57,8 +90,7 @@ void multiInstance() { numPartitions = 12; String inputTopicName = setupTopic(this.getClass().getSimpleName() + "-input"); -// int expectedMessageCount = 10_000_000; - int expectedMessageCount = 30_000_00; + int expectedMessageCount = volume(); log.info("Producing {} messages before starting test", expectedMessageCount); List expectedKeys = getKcu().produceMessages(inputTopicName, expectedMessageCount); @@ -83,7 +115,7 @@ void multiInstance() { "(expected: {} commit: {} order: {} max poll: {})", expectedMessageCount, commitMode, order, maxPoll); try { - waitAtMost(ofSeconds(60)) + waitAtMost(ceilingFor(expectedMessageCount)) // dynamic reason support still waiting https://github.com/awaitility/awaitility/pull/193#issuecomment-873116199 // .failFast( () -> pcThree.getFailureCause(), () -> pcThree.isClosedOrFailed()) // requires https://github.com/awaitility/awaitility/issues/178#issuecomment-734769761 .failFast("PC died - check logs", () -> pcThree.isClosedOrFailed()) // requires https://github.com/awaitility/awaitility/issues/178#issuecomment-734769761 diff --git a/parallel-consumer-core/src/test-integration/java/bz/stub/parallelconsumer/integrationTests/SampleTestingFailsafePluginInclusionCore.java b/parallel-consumer-core/src/test-integration/java/bz/stub/parallelconsumer/integrationTests/SampleTestingFailsafePluginInclusionCore.java deleted file mode 100644 index cd6339537..000000000 --- a/parallel-consumer-core/src/test-integration/java/bz/stub/parallelconsumer/integrationTests/SampleTestingFailsafePluginInclusionCore.java +++ /dev/null @@ -1,14 +0,0 @@ -package bz.stub.parallelconsumer.integrationTests; - -/*- - * Copyright (C) 2020-2021 Confluent, Inc. - * Modifications Copyright (C) 2026 Antony Stubbs and contributors - */ - -import org.junit.jupiter.api.Test; - -public class SampleTestingFailsafePluginInclusionCore { - @Test - public void test() { - } -} diff --git a/parallel-consumer-core/src/test-integration/java/bz/stub/parallelconsumer/integrationTests/TransactionAndCommitModeTest.java b/parallel-consumer-core/src/test-integration/java/bz/stub/parallelconsumer/integrationTests/TransactionAndCommitModeTest.java index 232cd297f..27d82fd79 100644 --- a/parallel-consumer-core/src/test-integration/java/bz/stub/parallelconsumer/integrationTests/TransactionAndCommitModeTest.java +++ b/parallel-consumer-core/src/test-integration/java/bz/stub/parallelconsumer/integrationTests/TransactionAndCommitModeTest.java @@ -35,6 +35,7 @@ import org.junitpioneer.jupiter.cartesian.ArgumentSets; import org.junitpioneer.jupiter.cartesian.CartesianTest; +import java.time.Duration; import java.util.*; import java.util.concurrent.Future; import java.util.concurrent.atomic.AtomicInteger; @@ -120,6 +121,46 @@ private void runTest(int maxPoll, CommitMode commitMode, ProcessingOrder order) runTest(maxPoll, commitMode, order, expectedMessageCount); } + /** + * The concurrency this test runs at. 64 is the gating value, and it was an increase for + * stability, not a reduction. + *

+ * The ladder around it - {@code 2}, {@code 100}, {@code 1000} - arrived already commented in + * {@code 2b0ab66b} (2020-11-27) beside the live {@code numThreads = 16}, and was deleted in + * {@code e67d8b89}. None of those values was ever live, so the ladder was the only record of the + * concurrencies anyone had run this matrix at. Reach them without editing the file: + * + * 

./mvnw verify -Pci -Dtransactions.concurrency=2
+ * + * The low rung is the interesting one: it is where an ordering assumption that high concurrency + * was papering over would show up. + */ + private static int concurrency() { + return Integer.getInteger("transactions.concurrency", GATING_CONCURRENCY); + } + + static final int GATING_CONCURRENCY = 64; + + /** + * Scales the shared {@link bz.stub.parallelconsumer.AbstractParallelEoSStreamProcessorTestBase#defaultTimeout} + * by how far below the gating concurrency this run is, because the same message count takes + * proportionally longer with fewer threads. Without this the ladder's low rungs would be + * selectable but guaranteed to time out - reachable in name only. + *

+ * At the gating concurrency the multiplier is exactly one, so the default run's deadline is + * unchanged. Raising concurrency never shortens it. + */ + private static Duration timeoutFor(int threads) { + // Scaling is CompletionCeiling's job, not this file's: the units are gating-concurrency's worth of work + // spread over `threads`, so fewer threads scales the deadline up, and more floors it at the baseline - + // the same "raising concurrency never shortens it" guarantee, for free. + // + // Doing it by hand truncated, and worst exactly where the ladder is meant to be used: at 40 threads + // `GATING_CONCURRENCY / threads` is 64/40 = *1* in integer division, so that rung got no scaling at all + // against a true ratio of 1.6 - a 30s deadline where 48s was owed (defaultTimeout is 30s, not 60). + return completionCeiling(GATING_CONCURRENCY, threads, defaultTimeout); + } + @SneakyThrows private void runTest(int maxPoll, CommitMode commitMode, ProcessingOrder order, int expectedCount) { String inputName = setupTopic(this.getClass().getSimpleName() + "-input-" + RandomUtils.nextInt()); @@ -162,16 +203,12 @@ private void runTest(int maxPoll, CommitMode commitMode, ProcessingOrder order, KafkaConsumer newConsumer = getKcu().createNewConsumer(true, consumerProps); // increased PC concurrency - improves test stability and performance. - int numThreads = 64; -// int numThreads = 1000; + int numThreads = concurrency(); var pc = new ParallelEoSStreamProcessor(ParallelConsumerOptions.builder() .ordering(order) .consumer(newConsumer) .producer(newProducer) .commitMode(commitMode) -// .numberOfThreads(1000) -// .numberOfThreads(100) -// .numberOfThreads(2) .maxConcurrency(numThreads) .build()); pc.subscribe(of(inputName)); @@ -207,21 +244,15 @@ private void runTest(int maxPoll, CommitMode commitMode, ProcessingOrder order, // wait for all pre-produced messages to be processed and produced Assertions.useRepresentation(new TrimListRepresentation()); - // todo rounds should be 1? progress should always be made - int roundsAllowed = 10; -// roundsAllowed = 200; -// if (commitMode.equals(CONSUMER_SYNC)) { -// roundsAllowed = 3; // sync consumer commits can take time // fails -//// roundsAllowed = 5; // sync consumer commits can take time // fails -//// roundsAllowed = 10; // sync consumer commits can take time // fails -//// roundsAllowed = 12; // sync consumer commits can take time // // works with no logging -// } - - ProgressTracker progressTracker = new ProgressTracker(processedCount, null, defaultTimeout); + // Rounds are deliberately not used here: ProgressTracker rejects being given both a round + // count and a timeout, and this test tracks by duration. The open question of whether any + // round without progress should be tolerated is recorded in docs/refactoring.md. + Duration deadline = timeoutFor(numThreads); + ProgressTracker progressTracker = new ProgressTracker(processedCount, null, deadline); var failureMessage = msg("All keys sent to input-topic should be processed and produced, within time (expected: {} commit: {} order: {} max poll: {})", expectedMessageCount, commitMode, order, maxPoll); try { - waitAtMost(defaultTimeout) + waitAtMost(deadline) // dynamic reason support still waiting // https://github.com/awaitility/awaitility/pull/193#issuecomment-873116199 // https://github.com/confluentinc/parallel-consumer/issues/199 diff --git a/parallel-consumer-core/src/test-integration/java/bz/stub/parallelconsumer/integrationTests/VeryLargeMessageVolumeTest.java b/parallel-consumer-core/src/test-integration/java/bz/stub/parallelconsumer/integrationTests/VeryLargeMessageVolumeTest.java index de2c23c04..d7417e85a 100644 --- a/parallel-consumer-core/src/test-integration/java/bz/stub/parallelconsumer/integrationTests/VeryLargeMessageVolumeTest.java +++ b/parallel-consumer-core/src/test-integration/java/bz/stub/parallelconsumer/integrationTests/VeryLargeMessageVolumeTest.java @@ -29,6 +29,7 @@ import org.junit.jupiter.api.Tag; import org.junit.jupiter.api.Test; +import java.time.Duration; import java.util.*; import java.util.concurrent.Future; import java.util.concurrent.atomic.AtomicInteger; @@ -80,6 +81,38 @@ void shouldNotThrowBitSetTooLongException() { runTest(HIGH_MAX_POLL_RECORDS_CONFIG, CommitMode.PERIODIC_CONSUMER_ASYNCHRONOUS, ProcessingOrder.KEY); } + static final long GATING_VOLUME = 1_000_000; + + /** + * The volume this test runs at. Its history is {@code 1_000_000} -> {@code 100_0000} -> + * {@code 1_000_000}: the middle value is the same number differently grouped, so this test was + * never kneecapped, and the audit withdrew that claim. + *

+ * The {@code 2_000_000} beside it was different. It was added in {@code 2b0ab66b} (2020-11-27) + * in the same edit that lowered the live value, so it was never live either - it is an + * aspiration, someone recording the volume they wanted this test to reach. {@code e67d8b89} + * deleted it as stale, which is not what the audit found. Reach it with: + * + * 

bin/performance-test.sh -Dvolume.messages=2000000
+ * + * Through the script, not {@code -Dincluded.groups=performance} alone: exclusion beats inclusion in JUnit + * Platform, and the default {@code excluded.groups} already contains {@code performance}, so the include on + * its own selects nothing and the run exits BUILD SUCCESS having tested nothing. The script passes + * {@code -Dexcluded.groups=} as well. + * + * If it does not pass, the diagnosis is the deliverable - not a lowered rung. + */ + private static long volume() { + return Long.getLong("volume.messages", GATING_VOLUME); + } + + /** The deadline this test has always had at its own volume. */ + private static final Duration GATING_CEILING = ofSeconds(120); + + private static Duration ceilingFor(long messages) { + return completionCeiling(messages, GATING_VOLUME, GATING_CEILING); + } + @SneakyThrows private void runTest(int maxPoll, CommitMode commitMode, ProcessingOrder order) { String inputName = setupTopic(this.getClass().getSimpleName() + "-input-" + RandomUtils.nextInt()); @@ -87,8 +120,7 @@ private void runTest(int maxPoll, CommitMode commitMode, ProcessingOrder order) // pre-produce messages to input-topic List expectedKeys = new ArrayList<>(); -// int expectedMessageCount = 2_000_000; - long expectedMessageCount = 1_000_000; + long expectedMessageCount = volume(); log.info("Producing {} messages before starting test", expectedMessageCount); List> sends = new ArrayList<>(); try (Producer kafkaProducer = getKcu().createNewProducer(false)) { @@ -169,7 +201,7 @@ private void runTest(int maxPoll, CommitMode commitMode, ProcessingOrder order) var failureMessage = StringUtils.msg("All keys sent to input-topic should be processed and produced, within time (expected: {} commit: {} order: {} max poll: {})", expectedMessageCount, commitMode, order, maxPoll); try { - waitAtMost(ofSeconds(120)) + waitAtMost(ceilingFor(expectedMessageCount)) // dynamic reason support still waiting https://github.com/awaitility/awaitility/pull/193#issuecomment-873116199 .failFast("PC died - check logs", pc::isClosedOrFailed) //, () -> pc.getFailureCause()) // requires https://github.com/awaitility/awaitility/issues/178#issuecomment-734769761 diff --git a/parallel-consumer-core/src/test/java/bz/stub/parallelconsumer/AbstractParallelEoSStreamProcessorTestBase.java b/parallel-consumer-core/src/test/java/bz/stub/parallelconsumer/AbstractParallelEoSStreamProcessorTestBase.java index b196faa1c..b3585a1b3 100644 --- a/parallel-consumer-core/src/test/java/bz/stub/parallelconsumer/AbstractParallelEoSStreamProcessorTestBase.java +++ b/parallel-consumer-core/src/test/java/bz/stub/parallelconsumer/AbstractParallelEoSStreamProcessorTestBase.java @@ -348,30 +348,6 @@ protected void awaitForCommitExact(int offset) { .untilAsserted(() -> assertCommits(of(offset))); } - /** - * Waits until the given offset has been committed for the given partition. - *

- * "Exact" refers to the offset map, not the number of commits: PC legitimately re-commits the same base - * offset when a record completes that cannot advance it (see - * {@link KafkaTestUtils#collapseRepeatedCommits(List, List)}), so this waits for at least one matching commit - * rather than requiring exactly one. Requiring exactly one turns a wait into an assertion about where the - * wall-clock commit ticks happened to fall. - *

- * Note the asymmetry with the single-argument {@link #awaitForCommitExact(int)}, which stays strict - * because it asserts the whole commit list rather than verifying one interaction. - */ - protected void awaitForCommitExact(int partition, int offset) { - log.debug("Waiting for EXACTLY commit offset {} on partition {}", offset, partition); - var expectedOffset = new OffsetAndMetadata(offset, ""); - TopicPartition partitionNumber = new TopicPartition(INPUT_TOPIC, partition); - var expectedOffsetMap = UniMaps.of(partitionNumber, expectedOffset); - verify(producerSpy, timeout(defaultTimeoutMs) - .atLeastOnce()) - .sendOffsetsToTransaction( - argThat((offsetMap) -> offsetMap.equals(expectedOffsetMap)), - any(ConsumerGroupMetadata.class)); - } - public void assertCommitsContains(List offsets) { List commits = getCommitHistoryFlattened(); assertThat(commits).containsAll(offsets); diff --git a/parallel-consumer-core/src/test/java/bz/stub/parallelconsumer/AmbientProbeExtensionTest.java b/parallel-consumer-core/src/test/java/bz/stub/parallelconsumer/AmbientProbeExtensionTest.java index 5916805ca..45051ebb6 100644 --- a/parallel-consumer-core/src/test/java/bz/stub/parallelconsumer/AmbientProbeExtensionTest.java +++ b/parallel-consumer-core/src/test/java/bz/stub/parallelconsumer/AmbientProbeExtensionTest.java @@ -16,6 +16,7 @@ import org.junit.jupiter.api.Test; import org.junit.jupiter.api.extension.ExtensionContext; import org.junitpioneer.jupiter.ClearSystemProperty; +import org.junit.jupiter.api.parallel.ResourceLock; import org.junitpioneer.jupiter.SetSystemProperty; import org.slf4j.LoggerFactory; @@ -51,6 +52,15 @@ */ class AmbientProbeExtensionTest { + /** + * Every {@link AmbientProbeExtension#buildAutopsy} call mutates the same static once-per-JVM + * environment-dump guard, whether or not the test cares about the dump - the first caller wins it + * and every later one gets the "already dumped" line. This module runs JUnit thread-parallel + * outside {@code -Pci}, so any two of them that are not serialised can red each other. Hold this + * lock on every test that calls {@code buildAutopsy}, not just the two asserting on the dump. + */ + private static final String ENVIRONMENT_DUMP_LOCK = "ambient-probe-environment-dump"; + // --- fixtures for the isDisabled() matrix --- static class PlainFixture { @@ -111,9 +121,104 @@ void disabledByMethodLevelAnnotation() { assertThat(AmbientProbeExtension.isDisabled(contextFor(MethodOptOutFixture.class, "optedOutMethod"))).isTrue(); } + // --- environment dump (what JavaEnvTest used to do by hand) --- + + /** Asserts on the guard itself, so it resets it first - see {@link #ENVIRONMENT_DUMP_LOCK}. */ + @Test + @ResourceLock(ENVIRONMENT_DUMP_LOCK) + void autopsyCarriesTheEnvironmentDumpOncePerRun() { + AmbientProbeExtension.resetEnvironmentDumpForTest(); + var probe = observerProbe(); + var context = contextFor(PlainFixture.class, "plainMethod"); + + String first = AmbientProbeExtension.buildAutopsy(context, probe, new AssertionError("first failure")); + String second = AmbientProbeExtension.buildAutopsy(context, probe, new AssertionError("second failure")); + + // the first autopsy of a run carries the dump + assertThat(first).contains("environment (once per JVM):"); + assertThat(first).contains("java.version="); + // a second failing test does not repeat a few hundred lines + assertThat(second).contains("environment: dumped in this JVM's first autopsy"); + assertThat(second).doesNotContain("environment (once per JVM):"); + } + + @Test + @ResourceLock(ENVIRONMENT_DUMP_LOCK) + @SetSystemProperty(key = "ambient.probe.test.multiline", value = "alpha\nbeta") + void environmentDumpEscapesNewlinesSoOneLinePerProperty() { + AmbientProbeExtension.resetEnvironmentDumpForTest(); + + String autopsy = AmbientProbeExtension.buildAutopsy( + contextFor(PlainFixture.class, "plainMethod"), observerProbe(), new AssertionError("x")); + + assertThat(autopsy).contains("ambient.probe.test.multiline=alpha\\nbeta"); + } + + /** + * The autopsy goes straight to CI logs, so a property whose name reads like a credential is masked - while the + * key itself still prints, because knowing it was set is the diagnostic. + */ + @Test + @ResourceLock(ENVIRONMENT_DUMP_LOCK) + @SetSystemProperty(key = "ambient.probe.test.password", value = "hunter2") + @SetSystemProperty(key = "ambient.probe.test.plain", value = "not-a-secret") + void environmentDumpMasksValuesOfCredentialLookingKeys() { + AmbientProbeExtension.resetEnvironmentDumpForTest(); + + String autopsy = AmbientProbeExtension.buildAutopsy( + contextFor(PlainFixture.class, "plainMethod"), observerProbe(), new AssertionError("x")); + + assertThat(autopsy).contains("ambient.probe.test.password=***"); + assertThat(autopsy).doesNotContain("hunter2"); + // an ordinary knob is untouched - the masking is by key name, not a blanket filter + assertThat(autopsy).contains("ambient.probe.test.plain=not-a-secret"); + } + + /** + * The likelier leak: people name a property for what it configures, so the credential rides in the VALUE + * under a key that announces nothing. Matching key names alone would print these verbatim. + */ + @Test + @ResourceLock(ENVIRONMENT_DUMP_LOCK) + @SetSystemProperty(key = "ambient.probe.test.db.url", value = "jdbc:postgresql://h/db?user=svc&password=hunter2") + @SetSystemProperty(key = "ambient.probe.test.hook", value = "https://user:tok3n@hooks.example.com/x") + @SetSystemProperty(key = "ambient.probe.test.gpg.passphrase", value = "correct-horse") + void environmentDumpMasksCredentialsCarriedInsideValues() { + AmbientProbeExtension.resetEnvironmentDumpForTest(); + + String autopsy = AmbientProbeExtension.buildAutopsy( + contextFor(PlainFixture.class, "plainMethod"), observerProbe(), new AssertionError("x")); + + // embedded key=value credential, and URL userinfo - neither key contains a secret marker + assertThat(autopsy).doesNotContain("hunter2"); + assertThat(autopsy).doesNotContain("tok3n"); + // gpg.passphrase is a real Maven release flag, and "passphrase" is not "password" + assertThat(autopsy).doesNotContain("correct-horse"); + // the keys still print - knowing the property was set is the diagnostic + assertThat(autopsy).contains("ambient.probe.test.db.url="); + assertThat(autopsy).contains("ambient.probe.test.hook="); + } + + /** + * The masking must not eat the dump it protects. {@code java.library.path} is why {@code pat} was rejected + * as a key marker - it would have masked every path property on the JVM. + */ + @Test + @ResourceLock(ENVIRONMENT_DUMP_LOCK) + void environmentDumpDoesNotOverMaskOrdinaryProperties() { + AmbientProbeExtension.resetEnvironmentDumpForTest(); + + String autopsy = AmbientProbeExtension.buildAutopsy( + contextFor(PlainFixture.class, "plainMethod"), observerProbe(), new AssertionError("x")); + + assertThat(autopsy).contains("java.version=" + System.getProperty("java.version")); + assertThat(autopsy).contains("java.library.path=" + System.getProperty("java.library.path")); + } + // --- autopsy rendering --- @Test + @ResourceLock(ENVIRONMENT_DUMP_LOCK) void autopsyReportsProbeCleanWhenNothingObserved() { var probe = observerProbe(); @@ -127,6 +232,7 @@ void autopsyReportsProbeCleanWhenNothingObserved() { } @Test + @ResourceLock(ENVIRONMENT_DUMP_LOCK) void autopsyListsViolationsWithCount() { var probe = observerProbe(); probe.getViolations().add("ZOMBIE_MEMBER/REBALANCE_BLOCKED: synthetic dwell violation"); @@ -142,6 +248,7 @@ void autopsyListsViolationsWithCount() { } @Test + @ResourceLock(ENVIRONMENT_DUMP_LOCK) void autopsyShowsFrozenPartitionDetailWhenNoViolationCrossedBounds() { var probe = observerProbe(); var tp = new TopicPartition("in-topic", 12); diff --git a/parallel-consumer-core/src/test/java/bz/stub/parallelconsumer/CompletionCeilingTest.java b/parallel-consumer-core/src/test/java/bz/stub/parallelconsumer/CompletionCeilingTest.java new file mode 100644 index 000000000..1622b4cf8 --- /dev/null +++ b/parallel-consumer-core/src/test/java/bz/stub/parallelconsumer/CompletionCeilingTest.java @@ -0,0 +1,72 @@ +package bz.stub.parallelconsumer; + +/*- + * Copyright (C) 2026 Antony Stubbs and contributors + */ + +import bz.stub.parallelconsumer.integrationTests.CompletionCeiling; +import org.junit.jupiter.api.Test; + +import java.time.Duration; + +import static com.google.common.truth.Truth.assertThat; +import static java.time.Duration.ofSeconds; +import static org.assertj.core.api.Assertions.assertThatThrownBy; + +/** + * The whole contract of the scaling ceiling is "the gating size keeps exactly the deadline it always + * had". That claim is what makes it safe to put in front of four integration tests, and until now it + * was only ever checked by running those tests - each of which needs Docker and minutes. This pins it + * in milliseconds. + *

+ * It also pins the case that motivated the helper: {@code LoadTest}'s original inline formula agreed + * with its documented anchor at the gating value and diverged above it, which is precisely the shape + * of error a gating-value-only check cannot see. + */ +class CompletionCeilingTest { + + /** Mirrors the real call sites, so a change to any of their constants breaks here first. */ + @Test + void eachSiteKeepsTheDeadlineItAlwaysHadAtItsOwnGatingSize() { + assertThat(ceiling(4_000, 4_000, ofSeconds(60))).isEqualTo(ofSeconds(60)); // LoadTest + assertThat(ceiling(1_000_000, 1_000_000, ofSeconds(120))).isEqualTo(ofSeconds(120)); // VeryLargeMessageVolume + assertThat(ceiling(3_000_000, 3_000_000, ofSeconds(60))).isEqualTo(ofSeconds(60)); // MultiInstanceHighVolume + } + + @Test + void scalesProportionallyAboveTheGatingSize() { + assertThat(ceiling(400_000, 4_000, ofSeconds(60))).isEqualTo(ofSeconds(6_000)); + assertThat(ceiling(2_000_000, 1_000_000, ofSeconds(120))).isEqualTo(ofSeconds(240)); + assertThat(ceiling(10_000_000, 3_000_000, ofSeconds(60))).isEqualTo(ofSeconds(200)); + } + + @Test + void neverReturnsLessThanTheGatingDeadline() { + // below the gating size the run is smaller, but the deadline is a ceiling and does not tighten + assertThat(ceiling(8, 4_000, ofSeconds(60))).isEqualTo(ofSeconds(60)); + assertThat(ceiling(1, 4_000, ofSeconds(60))).isEqualTo(ofSeconds(60)); + assertThat(ceiling(0, 4_000, ofSeconds(60))).isEqualTo(ofSeconds(60)); + } + + @Test + void rejectsAMisconfiguredKnobRatherThanFailingAsArithmetic() { + assertThatThrownBy(() -> ceiling(4_000, 0, ofSeconds(60))) + .isInstanceOf(IllegalArgumentException.class) + .hasMessageContaining("gatingUnits"); + + // a mistyped -Dvolume.messages with extra digits would otherwise surface as a + // Duration overflow from java.time internals, which reads like an environment fault + assertThatThrownBy(() -> ceiling(Long.MAX_VALUE / 1_000, 1_000_000, ofSeconds(120))) + .isInstanceOf(IllegalArgumentException.class) + .hasMessageContaining("too large"); + } + + /** + * Deliberately names {@link CompletionCeiling} and never {@code BrokerIntegrationTest}: the + * latter initialises a Kafka container in a static field, so routing through it would start + * Docker to test arithmetic - the exact cost this class was split out to avoid. + */ + private static Duration ceiling(long units, long gatingUnits, Duration ceilingAtGating) { + return CompletionCeiling.completionCeiling(units, gatingUnits, ceilingAtGating); + } +} diff --git a/parallel-consumer-core/src/test/java/bz/stub/parallelconsumer/ParallelEoSStreamProcessorTest.java b/parallel-consumer-core/src/test/java/bz/stub/parallelconsumer/ParallelEoSStreamProcessorTest.java index e32ff0475..16e70b7b7 100644 --- a/parallel-consumer-core/src/test/java/bz/stub/parallelconsumer/ParallelEoSStreamProcessorTest.java +++ b/parallel-consumer-core/src/test/java/bz/stub/parallelconsumer/ParallelEoSStreamProcessorTest.java @@ -14,13 +14,13 @@ import lombok.extern.slf4j.Slf4j; import org.apache.kafka.clients.consumer.*; import org.apache.kafka.clients.producer.ProducerRecord; +import org.apache.kafka.common.TopicPartition; import org.apache.kafka.common.errors.InvalidPidMappingException; import org.apache.kafka.common.serialization.Deserializer; import org.apache.kafka.common.serialization.Serdes; import org.assertj.core.api.Assertions; import org.assertj.core.api.Assumptions; import org.junit.jupiter.api.BeforeEach; -import org.junit.jupiter.api.Disabled; import org.junit.jupiter.api.Test; import org.junit.jupiter.api.Timeout; import org.junit.jupiter.params.ParameterizedTest; @@ -36,6 +36,7 @@ import java.util.concurrent.ConcurrentLinkedQueue; import java.util.concurrent.CountDownLatch; import java.util.concurrent.atomic.AtomicBoolean; +import java.util.concurrent.atomic.AtomicInteger; import java.util.concurrent.atomic.AtomicLong; import java.util.function.Function; @@ -74,6 +75,39 @@ public void setupData() { primeFirstRecord(); } + /** + * Waits until one partition's committed offset frontier - the highest offset committed for it, i.e. where + * consumption would resume - reaches exactly {@code expected}. + *

+ * Asserted instead of the exact set of that partition's commits because which intermediate offsets appear + * depends on where the wall-clock commit ticks fall relative to work completing, not on anything the test is + * about. A slow runner legitimately shows partition 0 at {@code [1, 3]} where a fast one shows {@code [3]}, + * because 1 means "record 0 done, resume at 1" - correct, and nothing to do with ordering. This is the same + * trap {@code astubbs#260} fixed by collapsing repeat commits inside {@code assertCommits}, in a different + * shape: there the repeat, here an extra intermediate step on the way to the same frontier. + *

+ * The frontier is the invariant worth guarding, and it is a real one: it can only move when work completes + * contiguously, so a partition that advanced past in-flight work would fail this - which is exactly what + * {@link #processInKeyOrder} exists to catch. + */ + private void awaitFrontier(int partition, long expected) { + var tp = new TopicPartition(INPUT_TOPIC, partition); + await().timeout(defaultTimeout) + .untilAsserted(() -> assertThat(highestCommitFor(tp)) + .as("committed offset frontier for partition %s", partition) + .hasValue(expected)); + } + + private Optional highestCommitFor(TopicPartition tp) { + return getCommitHistory().stream() + .map(groupHistory -> groupHistory.get(CONSUMER_GROUP_ID)) + .filter(Objects::nonNull) + .map(partitionCommits -> partitionCommits.get(tp)) + .filter(Objects::nonNull) + .map(OffsetAndMetadata::offset) + .max(Comparator.naturalOrder()); + } + @ParameterizedTest() @EnumSource(CommitMode.class) @SneakyThrows @@ -433,7 +467,6 @@ void offsetsAreNeverCommittedForMessagesStillInFlightShort(CommitMode commitMode assertCommits(of(2), "Only one of the two offsets committed, as they were coalesced for efficiency")); } - @Disabled @ParameterizedTest() @EnumSource(CommitMode.class) void offsetsAreNeverCommittedForMessagesStillInFlightLong(CommitMode commitMode) { @@ -469,8 +502,10 @@ void offsetsAreNeverCommittedForMessagesStillInFlightLong(CommitMode commitMode) awaitForSomeLoopCycles(1); - // make sure no offsets are committed - verify(producerSpy, after(verificationWaitDelay).never()).commitTransaction(); + // Nothing may be committed beyond the base offset: 0 is still in flight, so 1 completing cannot + // advance the contiguous frontier. assertCommits trims the genesis commit, so "no progress" is the + // empty set - PC re-committing the base offset is not progress and is expected. + assertCommits(of(), "1 completed but 0 is still in flight, so the frontier cannot move"); // finish 2 releaseAndWait(locks, 2); @@ -478,40 +513,36 @@ void offsetsAreNeverCommittedForMessagesStillInFlightLong(CommitMode commitMode) // awaitForSomeLoopCycles(1); - // make sure no offsets are committed - verify(producerSpy, after(verificationWaitDelay).never()).commitTransaction(); + // still blocked by 0 + assertCommits(of(), "2 completed too, but 0 still blocks the frontier"); // finish 0 releaseAndWait(locks, 0); awaitForOneLoopCycle(); - // make sure offset 2, not 0 or 1 is committed - verify(producerSpy, after(verificationWaitDelay).times(1)).commitTransaction(); - var maps = producerSpy.consumerGroupOffsetsHistory(); - assertThat(maps).hasSize(1); - OffsetAndMetadata offsets = maps.get(0).get(CONSUMER_GROUP_ID).get(toTopicPartition(firstRecord)); - assertThat(offsets.offset()).isEqualTo(2); + // 0, 1 and 2 are now contiguously complete, so the frontier jumps straight to 3 - the next offset to + // consume. It is 3 and not 2 because a committed offset is exclusive: it names where to resume, not + // the last record done. + // + // Asserted as the FRONTIER, not as the whole commit history, for the same reason processInKeyOrder is - + // and this test is where that reason was proven twice. Every record here is on partition 0, and which + // intermediate offsets the commit ticks happen to capture on the way to a frontier is timing, not + // behaviour: releasing 4 and 5 together does not guarantee they coalesce into one advance, and + // completing 0 does not guarantee 1 and 2 are drained before the next tick. MEASURED on this branch - + // the exact-history form failed 3 of 10 runs, as [1, 3] where [3] was expected and [3, 4, 5, 6] where + // [3, 4, 6] was, in two different commit modes. Both are correct PC behaviour. + awaitFrontier(0, 3); // finish 3 releaseAndWait(locks, 3); - // 3 committed - verify(producerSpy, after(verificationWaitDelay).times(2)).commitTransaction(); - maps = producerSpy.consumerGroupOffsetsHistory(); - assertThat(maps).hasSize(2); - offsets = maps.get(1).get(CONSUMER_GROUP_ID).get(toTopicPartition(firstRecord)); - assertThat(offsets.offset()).isEqualTo(3); + awaitFrontier(0, 4); // finish 4,5 releaseAndWait(locks, of(4, 5)); - // 5 committed - verify(producerSpy, after(verificationWaitDelay).atLeast(3)).commitTransaction(); - maps = producerSpy.consumerGroupOffsetsHistory(); - assertThat(maps).hasSizeGreaterThanOrEqualTo(3); - offsets = maps.get(2).get(CONSUMER_GROUP_ID).get(toTopicPartition(firstRecord)); - assertThat(offsets.offset()).isEqualTo(5); - assertCommits(of(2, 3, 5)); + // both complete, so the frontier ends at 6 - whether that took one commit or two is not this test's + awaitFrontier(0, 6); // close parallelConsumer.close(); @@ -660,7 +691,6 @@ void testVoidPollMethod(CommitMode commitMode) { @ParameterizedTest() @EnumSource(CommitMode.class) @SneakyThrows - @Disabled public void processInKeyOrder(CommitMode commitMode) { setupParallelConsumerInstance(ParallelConsumerOptions.builder() .commitMode(commitMode) @@ -748,31 +778,47 @@ public void processInKeyOrder(CommitMode commitMode) { .as("blocked by 0 (1 shouldn't be run until 0 is complete, due to key order processing)") .isFalse(); - // make sure no offsets are committed - assertCommits(of()); + // No "nothing is committed yet" check here. Record 8 is unlocked at test start and completes at once, + // marking partition 1 dirty, so whether its bootstrap commit at 4 has landed by this line is a race with + // the 100ms commit tick - and the awaited per-partition assertion below expects that very commit to + // exist. Asserting its absence here would be asserting how fast the tick was. // finish 2 process clear, but commit blocked by 0 log.debug("Unlocking 2..."); msg2Lock.countDown(); - awaitForSomeLoopCycles(2); - assertThat(processedState.get(2)).isTrue(); - - - // still nothing - 0 blocks 1 and 2 (partition 0) - verify(producerSpy, after(verificationWaitDelay).never()).commitTransaction(); // todo remove all wait nevers in favour of triggers as it slows down test + // Awaited, not point-checked: processedState is written by the worker thread after it wakes from the + // latch, and the control loop can turn twice before that worker is scheduled. Same pattern as records + // 5 and 6 below. MEASURED - the point check failed 1 of 10 runs under PERIODIC_CONSUMER_ASYNCHRONOUS. + awaitUntilTrue(() -> processedState.get(2)); + assertThat(processedState.get(2)).as("2 is not blocked by 0 - different key").isTrue(); + + + // Still nothing has advanced on partition 0 - 0 is in flight and blocks its key. Partition 1 has by now + // emitted its bootstrap commit at 4, which is ITS base offset (record creation uses a global offset + // counter, so partition 1's records start at 4) - a starting point, not progress. Asserted per-partition + // from here on, because the flattened assertCommits only trims a genesis of 0 and so would read + // partition 1's 4 as if it were progress. awaitForOneLoopCycle(); - assertCommits(of()); + await().timeout(defaultTimeout).untilAsserted(() -> assertCommitLists(of(of(), of(4)))); // finish 0 - releases pending (1,2) log.debug("Unlocking 0..."); msg0Lock.countDown(); - // 0 gets comitted by itself - awaitForCommitExact(0, 0); - - // make sure offset 0 is committed. 1 is now free to be processed (same key as 0), which as 2 was processed previously, frees up offset 2 to commit - awaitForCommitExact(0, 2); - assertCommits(of(0, 2)); + // On partition 0, offsets 0 and 1 are both key-0 (primeFirstRecord / sendSecondRecord), so 1 was blocked + // by 0; offset 2 is key-1 and so completed independently when it was unlocked. Completing 0 therefore + // frees 1, and with 2 already done the whole run 0-2 becomes contiguous - partition 0 resumes at 3, not + // at 2, because a committed offset says where to resume, not which record was last done. + // + // From here the assertions are on the FRONTIER (highest committed offset per partition), not on the exact + // set of commits. Which intermediate offsets appear depends on where the wall-clock commit ticks fall + // relative to work completing: a slow runner legitimately shows partition 0 at [1, 3] where a fast one + // shows [3], because 1 means "record 0 done, resume at 1". That is correct behaviour and nothing to do + // with ordering, so asserting the exact set asserts tick timing - the same trap astubbs#260 fixed by + // collapsing repeat commits inside assertCommits. MEASURED: this test passed locally and failed in CI + // on exactly that difference. + awaitFrontier(0, 3); + awaitFrontier(1, 4); // unlock 3 - should get committed log.debug("Unlocking 3..."); @@ -784,8 +830,9 @@ public void processInKeyOrder(CommitMode commitMode) { awaitUntilTrue(() -> processedState.get(5)); assertThat(processedState.get(5)).as("5 should processed").isTrue(); - awaitForCommitExact(0, 3); - assertCommits(of(0, 2, 3)); + // partition 0 advances to 4; partition 1 cannot move while 4 is in flight, even though 5 and 6 are done + awaitFrontier(0, 4); + awaitFrontier(1, 4); // unlock 4 - clears 5 for offset commit - 7 not processed yet (5,6,7 same key), 8 was never locked log.debug("Unlocking 4..."); @@ -795,18 +842,22 @@ public void processInKeyOrder(CommitMode commitMode) { awaitUntilTrue(() -> processedState.get(6)); assertThat(processedState.get(6)).as("6 should processed").isTrue(); - // 5 and 6 finished, same key, coalesced commit to 6 + // THE INVARIANT THIS TEST EXISTS FOR: partition 1 would not advance past its base offset 4 while key-2's + // record 4 was in flight, even though 5, 6 and 8 had completed. Now that 4 is done it jumps to 7 - not to + // 9 - because 8 is complete but not contiguous, so it cannot be resumed past. awaitForSomeLoopCycles(1); - awaitForCommitExact(1, 6); - assertCommits(of(0, 2, 3, 6)); + awaitFrontier(0, 4); + awaitFrontier(1, 7); // unlock 7 (same key as 6), unblocks 8 for commit assertThat(processedState.get(7)).isFalse(); assertThat(processedState.get(8)).isTrue(); // releaseAndWait(locks, 7); - awaitForCommitExact(1, 8); - assertCommits(of(0, 2, 3, 6, 8)); + + // 7 completing makes 7 and 8 contiguous, so partition 1 finally resumes at 9 + awaitFrontier(0, 4); + awaitFrontier(1, 9); } /** @@ -1098,6 +1149,49 @@ void produceMessageFlow(CommitMode commitMode) { assertThat(producerSpy.history()).hasSize(1); } + /** + * The produce half of {@link #produceMessageFlow}: the user function succeeds, and the produce that follows it + * fails. Nothing covered this before - the audit records it as a path that exists, is reachable, and has no + * test - so a regression that swallowed a produce failure and committed anyway would have gone unnoticed. + *

+ * What is asserted is the consequence, not the throw: the offset does not advance, and the record is + * retried. A produce failure is not a delivered result, so the work is not done. + *

+ * No producer-callback-thread variant here. That asymmetry is owned by open astubbs#261, and it is + * unreachable in this harness anyway: the base class gives every test one auto-completing {@code MockProducer} + * that invokes callbacks on the calling thread, so there is no I/O thread to raise from. + */ + @ParameterizedTest() + @EnumSource(CommitMode.class) + void userSucceedsButProduceToBrokerFails(CommitMode commitMode) { + setupParallelConsumerInstance(commitMode); + + var userFunctionRan = new AtomicInteger(); + + // fail every produce, so the record can never complete + doThrow(new FakeRuntimeException("Fake produce failure")) + .when(producerSpy).send(any(ProducerRecord.class), any()); + + parallelConsumer.pollAndProduce((ignore) -> { + userFunctionRan.incrementAndGet(); + return new ProducerRecord<>("Hello", "there"); + }); + + // the user function is retried, which is only possible if the produce failure failed the work + await().untilAsserted(() -> + assertThat(userFunctionRan.get()) + .as("user function retried after the produce failed") + .isGreaterThan(1)); + + parallelConsumer.requestCommitAsap(); + awaitForSomeLoopCycles(2); + + // and the offset never advances - the record is not done just because the user function returned + assertCommits(of(), "a failed produce must not commit the record's offset"); + + parallelConsumer.close(); + } + /** * Explicit check for situation where thread size is much larger than key set size. *

diff --git a/parallel-consumer-core/src/test/java/bz/stub/parallelconsumer/internal/utils/JavaEnvTest.java b/parallel-consumer-core/src/test/java/bz/stub/parallelconsumer/internal/utils/JavaEnvTest.java deleted file mode 100644 index 241c4fa31..000000000 --- a/parallel-consumer-core/src/test/java/bz/stub/parallelconsumer/internal/utils/JavaEnvTest.java +++ /dev/null @@ -1,23 +0,0 @@ -package bz.stub.parallelconsumer.internal.utils; - -/*- - * Copyright (C) 2020-2021 Confluent, Inc. - * Modifications Copyright (C) 2026 Antony Stubbs and contributors - */ - -import lombok.extern.slf4j.Slf4j; -import org.junit.jupiter.api.Test; - -import static bz.stub.parallelconsumer.internal.utils.StringTestUtils.pretty; - -@Slf4j -class JavaEnvTest { - - /** - * Used to manually inspect the java environment at runtime - particularly useful for CI environments - */ - @Test - void checkJavaEnvironment() { - log.error("Java all env: {}", pretty(System.getProperties().entrySet())); - } -} diff --git a/parallel-consumer-core/src/test/java/bz/stub/parallelconsumer/internal/utils/StringTestUtils.java b/parallel-consumer-core/src/test/java/bz/stub/parallelconsumer/internal/utils/StringTestUtils.java deleted file mode 100644 index 0510150aa..000000000 --- a/parallel-consumer-core/src/test/java/bz/stub/parallelconsumer/internal/utils/StringTestUtils.java +++ /dev/null @@ -1,19 +0,0 @@ -package bz.stub.parallelconsumer.internal.utils; - -/*- - * Copyright (C) 2020-2021 Confluent, Inc. - * Modifications Copyright (C) 2026 Antony Stubbs and contributors - */ - -import lombok.experimental.UtilityClass; -import org.assertj.core.presentation.StandardRepresentation; - -@UtilityClass -public class StringTestUtils { - - public static final StandardRepresentation STANDARD_REPRESENTATION = new StandardRepresentation(); - - public static String pretty(Object properties) { - return STANDARD_REPRESENTATION.toStringOf(properties); - } -} diff --git a/parallel-consumer-core/src/test/java/bz/stub/parallelconsumer/offsets/OffsetEncodingTests.java b/parallel-consumer-core/src/test/java/bz/stub/parallelconsumer/offsets/OffsetEncodingTests.java index f796094eb..f84bd58ee 100644 --- a/parallel-consumer-core/src/test/java/bz/stub/parallelconsumer/offsets/OffsetEncodingTests.java +++ b/parallel-consumer-core/src/test/java/bz/stub/parallelconsumer/offsets/OffsetEncodingTests.java @@ -12,6 +12,7 @@ import bz.stub.parallelconsumer.internal.EpochAndRecordsMap; import bz.stub.parallelconsumer.internal.PCModule; import bz.stub.parallelconsumer.internal.PCModuleTestEnv; +import bz.stub.parallelconsumer.state.PartitionState; import bz.stub.parallelconsumer.state.WorkContainer; import bz.stub.parallelconsumer.state.WorkManager; import lombok.SneakyThrows; @@ -35,18 +36,47 @@ import static bz.stub.parallelconsumer.ManagedTruth.assertTruth; import static bz.stub.parallelconsumer.offsets.OffsetEncoding.*; import static org.assertj.core.api.Assertions.assertThat; -import static org.hamcrest.Matchers.in; -import static org.hamcrest.Matchers.not; -import static org.junit.Assume.assumeThat; +import static org.assertj.core.api.Assumptions.assumeThat; import static org.junit.jupiter.api.parallel.ResourceAccessMode.READ; import static org.junit.jupiter.api.parallel.ResourceAccessMode.READ_WRITE; -import static pl.tlinkowski.unij.api.UniLists.of; @Slf4j public class OffsetEncodingTests extends ParallelEoSStreamProcessorTestBase { PCModuleTestEnv module = new PCModuleTestEnv(); + /** + * The {@link OffsetEncoding}s that cannot represent the scenario built by + * {@link #ensureEncodingGracefullyWorksWhenOffsetsAreVeryLargeAndNotSequential} - a highest succeeded offset of + * 72,770 with a long unbroken run of incompletes underneath it - and so fall back instead of round tripping. Two + * distinct mechanisms put codecs in this list: + *

    + *
  • v1 short overflow - {@link OffsetEncoding#BitSet}, {@link OffsetEncoding#BitSetCompressed}, + * {@link OffsetEncoding#RunLength} and {@link OffsetEncoding#RunLengthCompressed} encode their length (bitset + * bit count / run length) as a {@code short}, so they cannot express anything past {@link Short#MAX_VALUE} + * (32,767). The encoders detect the overflow while encoding and drop themselves from the candidate set: the + * bitset limit is the {@code Short.MAX_VALUE} guard in {@link BitSetEncoder}'s {@code initV1}, and the + * run-length limit is {@code MathUtils.toShortExact} throwing {@code RunLengthV1EncodingNotSupported} out of + * {@link RunLengthEncoder#serialise()}. Note it is neither {@link BitSetEncoder#MAX_LENGTH_ENCODABLE}, which + * is {@code Integer.MAX_VALUE} and is consulted only on the v2 path, nor {@link OffsetRunLength}, which is + * the decode side and carries no overflow detection at all - raising either would leave these codecs + * overflowing at 32,767 exactly as before.
    • + *
  • metadata size - {@link OffsetEncoding#BitSetV2} encodes the length as an int, so it does not + * overflow, but uncompressed it needs one bit per offset in the range and the resulting payload exceeds + * {@link OffsetMapCodecManager#DefaultMaxMetadataSize} (4096 bytes), so it is rejected when the payload is + * written.
    • + *
+ * In both cases the forced codec produces nothing, no offset map is committed, and the reloaded partition state + * falls back to what the bare committed offset alone can tell it. + *

+ * This is the single source of truth for that set - {@link #isWorkingCodec(OffsetEncoding)} and the degraded + * branches of the test both read it, rather than each restating the list. + */ + private static final List CODECS_THAT_DEGRADE = UniLists.of( + BitSet, BitSetCompressed, RunLength, RunLengthCompressed, // v1 short overflow + BitSetV2 // too large for the metadata payload uncompressed + ); + @Test void runLengthDeserialise() { var sb = ByteBuffer.allocate(3); @@ -179,9 +209,9 @@ void verifyEncodingWithNextExpectedBelowWatermark() { // depends on OffsetMapCodecManager#DefaultMaxMetadataSize @ResourceLock(value = OffsetSimultaneousEncoder.COMPRESSION_FORCED_RESOURCE_LOCK, mode = READ_WRITE) void ensureEncodingGracefullyWorksWhenOffsetsAreVeryLargeAndNotSequential(OffsetEncoding encoding) { - assumeThat("Codec skipped, not applicable", encoding, - not(in(of(ByteArray, ByteArrayCompressed, KafkaStreams, KafkaStreamsV2)))); // byte array not currently used - var encodingsThatFail = UniLists.of(BitSet, BitSetCompressed, BitSetV2, RunLength, RunLengthCompressed); + assumeThat(encoding) + .as("Codec skipped, not applicable") // byte array not currently used + .isNotIn(ByteArray, ByteArrayCompressed, KafkaStreams, KafkaStreamsV2); // todo don't use static public accessors to change things - makes parallel testing harder and is smelly OffsetMapCodecManager.forcedCodec = Optional.of(encoding); @@ -269,8 +299,14 @@ void ensureEncodingGracefullyWorksWhenOffsetsAreVeryLargeAndNotSequential(Offset var committed = consumerSpy.committed(UniSets.of(tp)).get(tp); assertThat(committed.offset()).isEqualTo(FIRST_COMMITTED_OFFSET); - if (assumeWorkingCodec(encoding, encodingsThatFail)) { + if (isWorkingCodec(encoding)) { assertThat(committed.metadata()).isNotBlank(); + } else { + // Degraded: the forced codec produced no encoding at all, so there is no offset map to attach - + // the commit carries the bare offset and an empty metadata string. See CODECS_THAT_DEGRADE. + assertThat(committed.metadata()) + .as("a degraded codec commits the bare offset with no offset map") + .isEmpty(); } } @@ -286,9 +322,13 @@ void ensureEncodingGracefullyWorksWhenOffsetsAreVeryLargeAndNotSequential(Offset var pm = newWm.getPm(); var partitionState = pm.getPartitionState(tp); - if (assumeWorkingCodec(encoding, encodingsThatFail)) { + if (isWorkingCodec(encoding)) { // check state reloaded ok from consumer assertTruth(partitionState).getOffsetHighestSucceeded().isEqualTo(highestSucceeded); + } else { + // Degraded: with no offset map in the metadata there is nothing to reload, so the fresh state knows + // only what the bare committed offset implies, and has not yet seen any record. + assertDegradedReloadedState(partitionState, FIRST_COMMITTED_OFFSET, FIRST_COMMITTED_OFFSET - 1); } // @@ -301,13 +341,10 @@ void ensureEncodingGracefullyWorksWhenOffsetsAreVeryLargeAndNotSequential(Offset EpochAndRecordsMap epochAndRecordsMap = new EpochAndRecordsMap<>(testRecordsWithBaseCommittedRecordRemoved, newWm.getPm()); newWm.registerWork(epochAndRecordsMap); - if (assumeWorkingCodec(encoding, encodingsThatFail)) { + // Asserted once: nothing between here and the work retrieval below mutates partitionState, so a second + // and third copy of these same checks would re-verify state that cannot have changed. + if (isWorkingCodec(encoding)) { // check state reloaded ok from consumer - assertTruth(partitionState).getOffsetHighestSucceeded().isEqualTo(highestSucceeded); - } - - // - if (assumeWorkingCodec(encoding, encodingsThatFail)) { assertTruth(partitionState).getOffsetHighestSequentialSucceeded().isEqualTo(FIRST_SUCCEEDED_OFFSET); assertTruth(partitionState).getOffsetHighestSucceeded().isEqualTo(highestSucceeded); @@ -317,50 +354,40 @@ void ensureEncodingGracefullyWorksWhenOffsetsAreVeryLargeAndNotSequential(Offset var incompletes = partitionState.getIncompleteOffsetsBelowHighestSucceeded(); Truth.assertThat(incompletes).containsExactlyElementsIn(expected); + } else { + // Degraded: re-polling the records lifts the highest *seen* offset back to the true high water mark, + // but which of them had succeeded lived only in the offset map that was never committed, so the + // highest *succeeded* offset stays where the bare committed offset left it. + assertDegradedReloadedState(partitionState, FIRST_COMMITTED_OFFSET, highestSucceeded); } // check record is marked as incomplete var anIncompleteRecord = records.get(3); assertThat(partitionState.isRecordPreviouslyCompleted(anIncompleteRecord)).isFalse(); - // check state - { - if (assumeWorkingCodec(encoding, encodingsThatFail)) { - long offsetHighestSequentialSucceeded = partitionState.getOffsetHighestSequentialSucceeded(); - assertThat(offsetHighestSequentialSucceeded).isEqualTo(0); - - long offsetHighestSucceeded = partitionState.getOffsetHighestSucceeded(); - assertThat(offsetHighestSucceeded).isEqualTo(highestSucceeded); - - long offsetHighestSeen = partitionState.getOffsetHighestSeen(); - assertThat(offsetHighestSeen).isEqualTo(highestSucceeded); - - var incompletes = partitionState.getIncompleteOffsetsBelowHighestSucceeded(); - Truth.assertThat(incompletes).containsExactlyElementsIn(expected); - - assertThat(partitionState.isRecordPreviouslyCompleted(anIncompleteRecord)).isFalse(); - } - } - var workRetrieved = newWm.getWorkIfAvailable(); var workRetrievedOffsets = workRetrieved.stream().map(WorkContainer::offset).collect(Collectors.toList()); assertTruth(workRetrieved).isNotEmpty(); - switch (encoding) { - case BitSet, BitSetCompressed, // BitSetV1 both get a short overflow due to the length being too long - BitSetV2, // BitSetv2 uncompressed is too large to fit in metadata payload - RunLength, RunLengthCompressed // RunLength V1 max runlength is Short.MAX_VALUE - -> { - assertThat(workRetrievedOffsets).doesNotContain(2500L); - assertThat(workRetrievedOffsets).doesNotContainSequence(expected); - } - default -> { - Truth.assertWithMessage("Contains only incomplete records") - .that(workRetrievedOffsets) - .containsExactlyElementsIn(expected) - .inOrder(); - } + if (isWorkingCodec(encoding)) { + Truth.assertWithMessage("Contains only incomplete records") + .that(workRetrievedOffsets) + .containsExactlyElementsIn(expected) + .inOrder(); + } else { + // Degraded: no offset map survived, so the records that had already succeeded above the committed + // offset (69, 25,000 and the highest succeeded) come back as work. Nothing is lost - work is repeated. + var everyRecordFromTheCommittedOffsetUp = records.stream() + .map(ConsumerRecord::offset) + .filter(offset -> offset >= FIRST_COMMITTED_OFFSET) + .collect(Collectors.toList()); + // Pinning the exact ordered contents already determines everything else about this list - a further + // doesNotContainSequence(expected) could not fail unless the assertion above had already failed. + Truth.assertWithMessage("Degraded codec redelivers every record from the committed offset up, including the ones that had succeeded") + .that(workRetrievedOffsets) + .containsExactlyElementsIn(everyRecordFromTheCommittedOffsetUp) + .inOrder(); } } @@ -368,10 +395,35 @@ void ensureEncodingGracefullyWorksWhenOffsetsAreVeryLargeAndNotSequential(Offset } /** - * A {@link OffsetEncoding} that works in this test scenario + * Whether the given {@link OffsetEncoding} can fully represent this test's scenario, i.e. is not one of + * {@link #CODECS_THAT_DEGRADE}. This is a plain predicate, not a JUnit assumption - both branches are asserted. + */ + private boolean isWorkingCodec(OffsetEncoding encoding) { + return !CODECS_THAT_DEGRADE.contains(encoding); + } + + /** + * The state one of {@link #CODECS_THAT_DEGRADE} leaves behind after a rebalance: because no offset map was + * committed, everything above the committed offset was forgotten. The highest succeeded (and so also the highest + * *sequentially* succeeded) offset can only be one below the committed offset, and no incompletes are known. The + * highest *seen* offset is the one thing that recovers, and only once the records have been polled again. + * + * @param committedOffset the bare offset that was committed - all the reloaded state has to go on + * @param expectedHighestSeen {@code committedOffset - 1} before the records are re-registered, the true high water + * mark afterwards */ - private boolean assumeWorkingCodec(OffsetEncoding encoding, List encodingsThatFail) { - return !encodingsThatFail.contains(encoding); + private void assertDegradedReloadedState(PartitionState partitionState, + long committedOffset, + long expectedHighestSeen) { + long lastKnownSucceeded = committedOffset - 1; + assertTruth(partitionState).getOffsetHighestSucceeded().isEqualTo(lastKnownSucceeded); + assertTruth(partitionState).getOffsetHighestSequentialSucceeded().isEqualTo(lastKnownSucceeded); + assertThat(partitionState.getOffsetHighestSeen()) + .as("highest seen offset") + .isEqualTo(expectedHighestSeen); + Truth.assertWithMessage("no incompletes are known - the offset map that recorded them was never committed") + .that(partitionState.getIncompleteOffsetsBelowHighestSucceeded()) + .isEmpty(); } /** diff --git a/parallel-consumer-core/src/test/java/bz/stub/parallelconsumer/sanity/StreamTest.java b/parallel-consumer-core/src/test/java/bz/stub/parallelconsumer/sanity/StreamTest.java index 2322a7e96..135b83c49 100644 --- a/parallel-consumer-core/src/test/java/bz/stub/parallelconsumer/sanity/StreamTest.java +++ b/parallel-consumer-core/src/test/java/bz/stub/parallelconsumer/sanity/StreamTest.java @@ -23,14 +23,6 @@ @Slf4j public class StreamTest { - // @Test - public void test() { - Stream s = Stream.generate(() -> Math.random()); - s.forEach(x -> { - log.info(x.toString()); - }); - } - @Test public void testStreamSpliterators() { int max = 10; diff --git a/parallel-consumer-examples/parallel-consumer-example-metrics/src/test/java/bz/stub/parallelconsumer/examples/metrics/integrationTests/CoreAppMetricsIntegrationTest.java b/parallel-consumer-examples/parallel-consumer-example-metrics/src/test/java/bz/stub/parallelconsumer/examples/metrics/integrationTests/CoreAppMetricsIntegrationTest.java index 0c0699855..250416ec8 100644 --- a/parallel-consumer-examples/parallel-consumer-example-metrics/src/test/java/bz/stub/parallelconsumer/examples/metrics/integrationTests/CoreAppMetricsIntegrationTest.java +++ b/parallel-consumer-examples/parallel-consumer-example-metrics/src/test/java/bz/stub/parallelconsumer/examples/metrics/integrationTests/CoreAppMetricsIntegrationTest.java @@ -14,7 +14,6 @@ import org.apache.kafka.clients.consumer.ConsumerRecord; import org.apache.kafka.clients.consumer.OffsetResetStrategy; import org.awaitility.Awaitility; -import org.junit.Assert; import org.junit.jupiter.api.Test; import org.mockito.Mockito; import org.testcontainers.junit.jupiter.Container; @@ -28,6 +27,7 @@ import java.util.Map; import java.util.Set; +import static org.assertj.core.api.Assertions.assertThat; import static org.mockito.Mockito.when; @Slf4j @@ -57,7 +57,7 @@ void testMetrics() { Awaitility.await().pollDelay(Duration.ofSeconds(1)).untilAsserted(() -> { final var metrics = getPrometheusMetrics(); - Assert.assertTrue(metrics.containsAll(expectedMetrics)); + assertThat(metrics).containsAll(expectedMetrics); }); coreApp.close(); @@ -69,7 +69,7 @@ private Set getPrometheusMetrics() { final var url = new URL(String.format("%s/api/v1/metadata", PROMETHEUS_CONTAINER.getPrometheusEndpoint())); HttpURLConnection conn = (HttpURLConnection) url.openConnection(); - Assert.assertEquals(conn.getResponseCode(), 200); + assertThat(conn.getResponseCode()).as("Prometheus metadata endpoint response code").isEqualTo(200); final Map jsonBody = mapper.readValue(new BufferedInputStream(conn.getInputStream()), Map.class); return ((Map) jsonBody.get("data")).keySet(); diff --git a/parallel-consumer-vertx/src/main/java/bz/stub/parallelconsumer/vertx/VertxParallelEoSStreamProcessor.java b/parallel-consumer-vertx/src/main/java/bz/stub/parallelconsumer/vertx/VertxParallelEoSStreamProcessor.java index 140784cd4..a9276893b 100644 --- a/parallel-consumer-vertx/src/main/java/bz/stub/parallelconsumer/vertx/VertxParallelEoSStreamProcessor.java +++ b/parallel-consumer-vertx/src/main/java/bz/stub/parallelconsumer/vertx/VertxParallelEoSStreamProcessor.java @@ -41,6 +41,22 @@ import static bz.stub.parallelconsumer.internal.UserFunctions.carefullyRun; +/** + * HTTP status codes are the caller's concern, not this library's. A Vert.x {@code WebClient} + * future completes successfully for any response that arrives, whatever its status, and fails only + * when the request does not complete at all - connection refused, timeout, TLS failure. This engine + * treats that future's outcome as the work's outcome, so a delivered 4xx or 5xx marks the record + * processed and its offset is committed, while a transport failure marks it failed and the + * record is retried. + *

+ * That is deliberate, and it matches how parallel-consumer treats the rest of the user's domain: it + * hands you the tools and takes no position on what counts as a business failure. To make a status + * code retryable, say so in your own function - attach a Vert.x + * {@code ResponsePredicate} to the request, or inspect the response and throw. + *

+ * Both halves of this boundary are pinned by {@code VertxTest.serverErrorStatusStillCommits} and + * {@code VertxTest.transportFailureIsDistinctFromANonSuccessStatus}, so it cannot change silently. + */ @Slf4j public class VertxParallelEoSStreamProcessor extends ExternalEngine implements VertxParallelStreamProcessor { diff --git a/parallel-consumer-vertx/src/test/java/bz/stub/parallelconsumer/vertx/VertxTest.java b/parallel-consumer-vertx/src/test/java/bz/stub/parallelconsumer/vertx/VertxTest.java index 33655dfeb..59e8086ea 100644 --- a/parallel-consumer-vertx/src/test/java/bz/stub/parallelconsumer/vertx/VertxTest.java +++ b/parallel-consumer-vertx/src/test/java/bz/stub/parallelconsumer/vertx/VertxTest.java @@ -6,6 +6,7 @@ */ import com.github.tomakehurst.wiremock.WireMockServer; +import com.github.tomakehurst.wiremock.client.WireMock; import bz.stub.parallelconsumer.internal.utils.WireMockUtils; import bz.stub.parallelconsumer.PollContext; import bz.stub.parallelconsumer.vertx.VertxParallelEoSStreamProcessor.RequestInfo; @@ -24,7 +25,6 @@ import org.assertj.core.api.Assertions; import org.junit.jupiter.api.AfterEach; import org.junit.jupiter.api.BeforeEach; -import org.junit.jupiter.api.Disabled; import org.junit.jupiter.api.Test; import org.junit.jupiter.api.extension.ExtendWith; import org.junit.jupiter.api.parallel.Isolated; @@ -196,18 +196,85 @@ void testHttp() { assertThat(res).extracting(x -> x.result().bodyAsString()).contains(WireMockUtils.stubResponse); } + /** + * Characterizes what a non-2xx status does, which nothing asserted before. The stub + * {@code VertxTest.handleHttpResponseCodes} was named for this and was deleted in + * {@code cadf4c95} - correctly, its body was {@code assertThat(true).isFalse()} behind + * {@code @Disabled} and it had never run green. The gap it named was real: audit §1.3 records + * that non-2xx handling is untested and that the nearest test asserts 200 on the happy path + * only. + *

+ * A Vert.x {@code WebClient} future completes successfully for any HTTP response and + * fails only on transport errors, and + * {@code VertxParallelEoSStreamProcessor}'s {@code send.onSuccess} calls + * {@code onUserFunctionSuccess}. So a 500 is a delivered response, not a processing failure, + * and the offset commits. + *

+ * That is a contract, not a bug: parallel-consumer takes no position on status codes, the same + * way it takes no position on how a value was serialised. A user who wants a 5xx retried says + * so - with a response predicate, or by throwing from their own function. This test exists so + * that contract fails loudly if it ever changes silently. + */ + @SneakyThrows + @Test + void serverErrorStatusStillCommits() { + stubServer.stubFor(WireMock.get(WireMock.urlPathEqualTo("/server-error")) + .willReturn(WireMock.aResponse().withStatus(500).withBody("boom"))); + + var latch = new CountDownLatch(1); + vertxAsync.addVertxOnCompleteHook(latch::countDown); + + var futureStream = vertxAsync.vertxHttpRequestStream((webClient, rec) -> { + RequestInfo reqInfo = getGoodHost(); + return webClient.get(reqInfo.getPort(), reqInfo.getHost(), "/server-error"); + }); + + awaitLatch(latch); + + var res = getResults(futureStream); + assertThat(res).hasSize(1).doesNotContainNull(); + // the future succeeded - the response was delivered, so nothing failed as far as vertx is concerned + assertThat(res).extracting(AsyncResult::cause).containsOnlyNulls(); + assertThat(res).extracting(x -> x.result().statusCode()).containsOnly(500); + + // and the work is treated as done: the offset commits + awaitForCommitExact(1); + } + + /** + * The other side of the boundary in {@link #serverErrorStatusStillCommits}, and the reason that + * contract is defensible: a transport failure - nothing delivered - does fail the future. The + * distinction is what a user needs in order to decide where to put their own error handling. + */ + @SneakyThrows + @Test + void transportFailureIsDistinctFromANonSuccessStatus() { + var latch = new CountDownLatch(1); + vertxAsync.addVertxOnCompleteHook(latch::countDown); + + var futureStream = vertxAsync.vertxHttpRequestStream((webClient, rec) -> { + RequestInfo unreachable = getBadRequest(); + return webClient.get(unreachable.getPort(), unreachable.getHost(), unreachable.getContextPath()); + }); + + awaitLatch(latch); + + var res = getResults(futureStream); + assertThat(res).hasSize(1).doesNotContainNull(); + assertThat(res).extracting(AsyncResult::cause).doesNotContainNull(); + + // the half that makes this a contrast rather than a second success case: nothing commits, so + // the record is retried. Asserting only that the future failed would leave the boundary + // half-stated - and the boundary is the whole point of the pair. + assertCommits(of()); + } + private List>> getResults( Stream> futureStream) { var collect = futureStream.map(JStreamVertxParallelEoSStreamProcessor.VertxCPResult::getAsr).collect(Collectors.toList()); return blockingGetResults(collect); } - @Test - @Disabled - void handleHttpResponseCodes() { - assertThat(true).isFalse(); - } - @SneakyThrows private List> blockingGetResults(List> collect) { List> list = new ArrayList<>(); diff --git a/pom.xml b/pom.xml index 47326369f..1ac9c13ff 100644 --- a/pom.xml +++ b/pom.xml @@ -910,9 +910,17 @@ ${skipTests} ${skipITs} methods - + ${included.groups} ${excluded.groups}