|
8 | 8 | **This file exists because the work had no home.** `bug-857-mirror-attributions-unconfirmed.md` |
9 | 9 | correctly says the honest options are "reproduce and diagnose, or close on their own merits" - but it |
10 | 10 | owns the *attribution* question, not the investigation, so "reproduce and diagnose" has sat as a |
11 | | -sentence nobody could pick up. The field report has been open for months with no reproduction |
12 | | -attempt: a grep of `docs/plans/` and `docs/solutions/` finds nothing targeting it. The only |
13 | | -adjacent record is `unforceable-trigger-commit-lock-timeout-2026-08-07.md`, which is a *test* flake |
14 | | -on the same lock and unrelated to the reporter's scenario. |
| 11 | +sentence nobody could pick up. The field report sat open for months with no reproduction attempt at |
| 12 | +all - **the attempt now exists**, as `CommitResponseTimeoutSoakIT` in the `soak` lane, and its first |
| 13 | +two runs are recorded at the bottom of this note. A grep of `docs/plans/` and `docs/solutions/` still |
| 14 | +finds nothing targeting the report; the only adjacent record is |
| 15 | +`unforceable-trigger-commit-lock-timeout-2026-08-07.md`, which is a *test* flake on the same lock and |
| 16 | +unrelated to the reporter's scenario. |
15 | 17 |
|
16 | 18 | **The filename carries astubbs#177 for history only.** That issue was closed on 2026-09-01 without |
17 | 19 | the reproduction or the closing comment this note asked for; |
@@ -84,6 +86,131 @@ the retry tests, and the chaos suite's `ProgressProbe` plus the new `INSTANCE_ST |
84 | 86 | whether an instance is wedged while it happens. **Do not start a parallel harness** - see |
85 | 87 | `docs/testing.md`. |
86 | 88 |
|
| 89 | +**This section is now a record of the design rather than an outstanding request**: it was built as |
| 90 | +`CommitResponseTimeoutSoakIT`, and what its runs actually measured is the next section. Do not build |
| 91 | +it again. |
| 92 | + |
| 93 | +## The experiment now exists, and its first two runs measured the experiment rather than the defect |
| 94 | + |
| 95 | +`CommitResponseTimeoutSoakIT` (the `soak` lane, `docs/testing.md`) is the reproduction attempt this |
| 96 | +note asked for, built from the astubbs#177 shape above for the reason stated there - it is buildable, |
| 97 | +and it is the cheapest route to the wedged-poller question. **2026-09-07, two runs, 0 timeouts in |
| 98 | +2 x 30 minutes - and neither is a sighting-ledger entry, because in both the assertion could not have |
| 99 | +failed after the first minute.** |
| 100 | + |
| 101 | +Conditions common to both runs, so the numbers are interpretable: |
| 102 | + |
| 103 | +| Term | Value | |
| 104 | +|---|---| |
| 105 | +| Duration | 30 min each (`-Dsoak.duration=PT30M`) | |
| 106 | +| Shape | 1 instance, no churn, `KEY` ordering, `PERIODIC_CONSUMER_SYNC`, 1s commit interval | |
| 107 | +| Scale | 1000 keys over 20 partitions, `maxConcurrency` 14, ~100ms user function | |
| 108 | +| Poisoning | per-record and permanent (a poisoned record throws on every attempt) | |
| 109 | +| Produce | 1000 records every 20s - 90,000 produced per run | |
| 110 | +| Broker | the suite's Testcontainers Kafka on Docker | |
| 111 | +| Machine | maintainer's macOS arm64 workstation | |
| 112 | +| Assertion | exactly one - no `Timeout waiting for commit response`, and no other terminal failure | |
| 113 | + |
| 114 | +| Arm | Seed | Succeeded | Failed | Findings | |
| 115 | +|---|---|---|---|---| |
| 116 | +| `failureFraction` 0.5 (astubbs#177's reporter's) | `3747722682837130843` | 451 | 237,006 | none | |
| 117 | +| `failureFraction` 0.03 | `5055695573431537469` | 2,372 | 81,114 | none | |
| 118 | + |
| 119 | +Run command (the second adds `-Dsoak.failureFraction=0.03`): |
| 120 | + |
| 121 | +``` |
| 122 | +./mvnw -Pci -pl parallel-consumer-core -am verify -DskipUTs=true \ |
| 123 | + -Dincluded.groups=soak -Dexcluded.groups= -Dit.test=CommitResponseTimeoutSoakIT \ |
| 124 | + -Dfailsafe.failIfNoSpecifiedTests=false -Dsoak.duration=PT30M |
| 125 | +``` |
| 126 | + |
| 127 | +### What both runs measured is a total intake stall, not the absence of a timeout |
| 128 | + |
| 129 | +Successes froze - at 451 and at 2,372 - within the first ~60 seconds of each run and **never moved |
| 130 | +again** across the remaining 29 minutes, while the producer kept publishing and the failure count |
| 131 | +climbed at a rate that then held exactly constant. A constant retry rate against a frozen success |
| 132 | +count means no new record is being taken as work at all: the instance has stopped, not merely slowed. |
| 133 | + |
| 134 | +**A stalled instance cannot reach the exception being hunted:** |
| 135 | + |
| 136 | +- only `PartitionState#onSuccess` calls `setDirty`; `onFailure` in the same file is an explicit |
| 137 | + no-op, so a failing record never marks its partition dirty; |
| 138 | +- the control loop gates on `shouldTryCommitNow` in `AbstractParallelEoSStreamProcessor` - |
| 139 | + `isTimeToCommitNow() && wm.isDirty() && !isRebalanceInProgress.get()`; |
| 140 | +- so with no success anywhere, nothing is dirty, no commit request is enqueued, and |
| 141 | + `ConsumerOffsetCommitter#commitAndWait` - the only place `Timeout waiting for commit response` is |
| 142 | + thrown - is never entered. |
| 143 | + |
| 144 | +A green run therefore cannot distinguish "no timeout occurred" from "no commit was attempted". This |
| 145 | +is exactly the `dirty` asymmetry `upstream-tell-809-833-the-hang-is-fixed.md` names for this same |
| 146 | +workload; these runs are the measurement of it rather than evidence about the report. |
| 147 | + |
| 148 | +**Lowering the poisoned fraction does not fix it, and that is a run rather than a guess:** 0.03 bought |
| 149 | +about 1.5 extra bursts and stalled identically, which rules out "too many poisoned keys" and makes the |
| 150 | +fraction the wrong knob. Duration is the wrong knob too - the stall arrives in minute one of thirty. |
| 151 | + |
| 152 | +### What stops intake is not the documented back pressure - and the candidate is named |
| 153 | + |
| 154 | +`PartitionState#updateBlockFromEncodingResult` logs on every transition (`Offset map data too large`, |
| 155 | +`not allow further messages`). **Neither string appears once in either run's log**, so offset-encoding |
| 156 | +back pressure is eliminated. |
| 157 | + |
| 158 | +The untested candidate is the load gate. `WorkManager#isSufficientlyLoaded` compares |
| 159 | +`workable = inShards - parkedForRetry` against `targetAmountOfRecordsInFlight * loadingFactor`, and |
| 160 | +`inShards` counts records queued **behind** a blocked shard head - records that can never be worked - |
| 161 | +while only the failing head itself is `parkedForRetry`. A shard set full of unworkable queued records |
| 162 | +would therefore read as "sufficiently loaded", the broker poller would stay paused, and nothing would |
| 163 | +ever arrive to change it. That is the silent-stall shape the gate's own comment names against |
| 164 | +confluentinc#857. **This is a hypothesis, not a result.** |
| 165 | + |
| 166 | +### What to run next, in order |
| 167 | + |
| 168 | +1. **Re-run either arm with `WorkManager` at DEBUG and read the `isSufficientlyLoaded=` line at the |
| 169 | + moment successes freeze.** It prints its own operands (`inShards`, `parkedForRetry`, the threshold) |
| 170 | + for exactly this purpose. It either confirms or eliminates the load gate, and until it is read the |
| 171 | + other arms are guesswork. One run settles it. |
| 172 | +2. **Per-attempt rather than per-record failure**, so records eventually succeed, the shards drain and |
| 173 | + the instance keeps committing for the whole run. On this evidence it is the only shape that keeps |
| 174 | + the commit path alive indefinitely - promoted from "a different mechanism" to "the first arm that |
| 175 | + can falsify the assertion at all". |
| 176 | +3. **`gtassone`'s configuration from confluentinc#809** - 128 partitions, concurrency 64, user |
| 177 | + function 100ms to minutes, `PERIODIC_CONSUMER_SYNC`. This is astubbs#175's own shape, and the |
| 178 | + scenario does not have it: the workload transcribes the now-closed astubbs#177 report instead, |
| 179 | + whose defect `upstream-tell-809-833-the-hang-is-fixed.md` says is already fixed. |
| 180 | + `upstream-175-sporadic-commit-timeouts.md` no longer nominates it as a *wedge* candidate - see |
| 181 | + the section below - but it remains the closest recorded configuration to the live report, which is |
| 182 | + what this arm buys. |
| 183 | + |
| 184 | +### The stall may be the better lead than the timeout |
| 185 | + |
| 186 | +confluentinc#833's reporter - astubbs#177's, whose shape this scenario transcribes - showed |
| 187 | +`pc_processed_records_total` **flat** across the window in which their timeout fired, which is this |
| 188 | +state, not a busy one. Whoever picks this up should consider whether the reported timeout is a |
| 189 | +*consequence* of an intake stall rather than a peer of it. |
| 190 | + |
| 191 | +### Where the two adjacent notes leave candidate 2, and why that matters to the next arm |
| 192 | + |
| 193 | +The candidate list at the top of this note already reflects both of these. They are repeated here |
| 194 | +because they are what the remaining soak arms are aimed at, and each is owned by the note named: |
| 195 | + |
| 196 | +- **`upstream-tell-809-833-the-hang-is-fixed.md`** - four `astubbs#177` commits landed 2026-08-19 and |
| 197 | + close candidate 1's class outright: the poller now publishes its own death |
| 198 | + (`notifyPollerDied`), waiters are released with its exception, and the message reports the budget it |
| 199 | + actually waited on. astubbs#177's mirror is closed; confluentinc#833 is still open upstream and |
| 200 | + still unanswered, which is why its reporter's shape is still worth running here. |
| 201 | +- **`upstream-175-sporadic-commit-timeouts.md`** - confluentinc#809 is *not* the same defect as |
| 202 | + confluentinc#833 despite the shared message, and its strand-by-strand table now closes its last |
| 203 | + named strand too: **the poll thread alive but wedged - the AB-BA cycle - was fixed by astubbs#29, |
| 204 | + merged 2026-09-02**, and that note records the strand as closed for this report. |
| 205 | + |
| 206 | +So candidate 2 stays the open one, with **no named mechanism left inside it**: the single wedge the |
| 207 | +record ever described has been fixed, so a reproduction on current code would be characterising |
| 208 | +something nobody has yet described. That is what makes the intake stall these runs found the more |
| 209 | +promising lead of the two. The branch `test/177-commit-response-timeout` (unmerged) is further prior |
| 210 | +art: it confirmed the astubbs#100 trigger reproduces when the catch is removed, and records one |
| 211 | +**falsified** experiment (moving `brokerPollSubsystem.supervise()` earlier in `controlLoop()` does not |
| 212 | +help - measured). |
| 213 | + |
87 | 214 | ## Do not |
88 | 215 |
|
89 | 216 | - Do not attach a closing keyword from any PR on present evidence - see |
|
0 commit comments