Repository navigation
test(soak) astubbs#175: re-run on v0.6.0.0 with the intake latch held open finds no commit-response timeout - #518
Conversation
…inds no commit-response timeout Records three arms of CommitResponseTimeoutSoakIT on the released code (v0.6.0.0 plus two docs commits, 2e6f13e) in the scenario's Calibration status and in docs/inflight/bug-177-commit-response-timeout-unreproduced.md. No product or test code changes - the record is the deliverable. The question since #471: does a BARE "Timeout waiting for commit response" - the poller wedged but alive, the one mechanism nobody has characterised - ever appear on the released code when the workload is arranged so the intake gate does not latch and commits keep happening for the whole soak. #471's two 30-minute runs could not answer it: the retry-forever poison latched the record-intake gate inside the first minute and no commit was attempted after that, which #487 measured and #497 made loud. Common to all arms: seed 3747722682837130843, failureFraction 0.5, PERIODIC_CONSUMER_SYNC at 1s, 1000 keys over 20 partitions, maxConcurrency 14, 100ms user function, 1000 records every 20s, retry-forever; Testcontainers confluentinc/cp-kafka:7.9.0 on Docker; a Linux x86_64 workstation with every JVM pinned to 8 processors; no other Maven JVM on the box at the start of any arm; -Dpc.loadgate.log.level=info and -Dsoak.progressInterval=PT30S. Commit activity was read from the broker's __consumer_offsets with the broker's own formatter, because every commit-path line in the product is DEBUG. Arm A - control, unchanged, 6 minutes. The latch reproduces on the released code to the number: succeeded frozen at 451 from the first 30s sample, the #497 WARN 13.2s after the banner (inShards=549 parkedForRetry=140 workable=409 vs 42, pausedPartitions=20), every partition paused at all 11 samples, failed 49,710 (138/s). The broker saw 8 commit instants, all inside the first 7.3s, and none in the remaining 5m50s. Load average 2.93 -> 1.54. Arm B - 30 minutes, -Dsoak.messageBufferSize=20000, KEY, everything else the reporter's. No findings. The gate held open for 7m06s (loaded=false, zero paused partitions, at every sample to inShards=20,103), then latched at inShards=20993 vs target(14)*loadingFactor(1429)=20006 and stayed latched for the remaining 22m54s - so the #487 arm-3 value buys about seven minutes of this producer, not thirty, because under KEY nearly everything produced is held. But the assertion had already stopped being falsifiable at 3m06s, four minutes before the latch, and the gate is not why: successes went 680, 784, 869, 884, 893, 895, 897 and froze with the gate open, and the broker's last commit landed 185.7s after the first (27 commit instants). Under KEY each key retires records until its first poisoned one and never again, so permanent poison bounds successes by the key space, and dirty is derived from completions, so once successes stop commitAndWait is never entered. No buffer size changes that under KEY. Succeeded 897, failed 250,067 (139/s). Load average 1.17 -> 0.13. Arm C - 30 minutes, -Dsoak.messageBufferSize=100000 -Dsoak.ordering=UNORDERED: the only combination of the existing knobs that holds both conditions. UNORDERED lifts the head-of-line bound so healthy records keep retiring; 100,000 clears the ~90,000 a thirty-minute producer can have held. Both held for the whole run: loaded=false and zero paused partitions at all 59 samples, inShards peaking at 51,949 against 100,002, no WARN, no back-pressure line; succeeded 37,641 and still rising at the end, failed 213,533 (119/s); a commit in every one of the thirty minutes - 619 commit instants, the last 1794.8s after the first, offset-map metadata growing to 768 base64 chars per partition. No findings: no bare timeout, no poller death, no thread dump written. Load average 0.12 -> 1.46. What it establishes, as a rate under conditions: on v0.6.0.0, one instance, a quiet box, zero bare commit-response timeouts and zero poller deaths across 654 acknowledged commit instants, 619 of them in thirty minutes of a continuously exercised commit path. One run at one shape; it says the shape did not reproduce once, not that it cannot. What it does not establish: anything about #175's own configuration (128 partitions, concurrency 64, a user function of minutes - still unrun), a loaded box, a rebalance, more than one instance, durations past thirty minutes, or KEY ordering with the commit path alive - which on this evidence needs the per-attempt-failure arm rather than a buffer size. Arm C departs from #177's reporter's ordering deliberately, and says so in both records. No new knobs were added: -Dsoak.duration, -Dsoak.messageBufferSize and -Dsoak.ordering already existed. The only thing genuinely missing from the harness - evidence that commits were being attempted - was taken from the broker rather than by adding a log line, and the command is recorded in the javadoc so the next run can do the same. Co-Authored-By: Claude Fable 5.1 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_019XS64Xttx4vF5datYh7fmk
|
@claude review this |
|
Claude finished @astubbs's task in 2m 52s —— View job Review
Scope confirmed: every changed line in Cross-checked the numbers for internal consistency (the PR's own bar for a soak record) rather than taking them on faith:
Minor, non-blocking observation: the note's Content-wise, this is a well-instrumented negative result: it states plainly what it establishes (zero bare timeouts across 654 broker-observed commit instants on v0.6.0.0, one box, one run) and, more usefully, what it explicitly does not (#175's own 128-partition/concurrency-64 shape, a loaded box, rebalances, multi-instance, KEY ordering with a live commit path). Arm B's diagnosis - that under No issues found that would block merge. |
Dependency Review✅ No vulnerabilities or license issues or OpenSSF Scorecard issues found.Scanned FilesNone |
✅ Duplicate Code ReportTwo engines run in parallel for cross-validation. Each has its own thresholds tuned to its baseline - the real safety net is the per-engine "max increase vs base" check. ✅ PMD CPD
No new clones introduced by this PR. ✅ jscpd (language-agnostic)
No new clones introduced by this PR. Powered by astubbs/duplicate-code-cross-check |
…at carried the telling says so confluentinc#809 got its reply with the soak rerun on the released code (#518), #175 its corrected Fork status, and #44 the correction to its attribution of 809 and 833 to #100. That was the whole of upstream-tell-809-833-the-hang-is-fixed.md, which the earlier audit missed because its wording differed; its three items now say done with links, it is linked from the release-response note, and the two boxes are ticked. Co-Authored-By: Claude Fable 5.1 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_019XS64Xttx4vF5datYh7fmk
Codecov Report✅ All modified and coverable lines are covered by tests. Additional details and impacted files@@ Coverage Diff @@
## master #518 +/- ##
============================================
+ Coverage 82.68% 83.32% +0.63%
- Complexity 1596 1602 +6
============================================
Files 96 96
Lines 5475 5475
Branches 554 554
============================================
+ Hits 4527 4562 +35
+ Misses 751 718 -33
+ Partials 197 195 -2
Flags with carried forward coverage won't be shown. Click here to find out more. ☔ View full report in Codecov by Harness. 🚀 New features to boost your workflow:
|
🟢 Throughput — OKThis branch measured about 3% faster than master, on the one test this measures. That is INSIDE this test's own run-to-run spread of about 17%, so read it as a reading and not as a result - re-running the same commit moves it by about as much.
Allowable range 🟢 ≥ 0.70 · 🟡 0.50–0.70 (about a 30% loss) · 🔴 < 0.50 (about a 50% loss) What the numbers mean, and what they cannot tell youThe one that gets misread. Why a shape and not a rate. A rate depends on which runner you drew. A shape does not: every test here processes a fixed number of records, so a runner twice as slow doubles the subject and the controls together and leaves their ratio alone. That is the whole trick, and it is why the reported rate is shown last and labelled as this machine only. Reading the comparison. By conservation, not by correction. Every test in this lane processes a fixed number of records, so within one run the ratio of one test's time to another's is invariant under machine speed — a runner twice as slow doubles both terms and leaves the ratio alone. There is no machine-index correction to be wrong, because nothing needed correcting. Per-method times, not class times. A class time is Reference is the median of 10 recent What this still cannot do. It removes machine-to-machine variance. It does not remove this test's own run-to-run variance, measured at about 30% on a single unchanged commit while its controls stayed within 5%. That is a property of the test, not of the comparison, and no arithmetic here can touch it — which is why the reference is a median and the bounds are deliberately coarse. 🟡 means look at this; only 🔴 is outside the measured spread. Runs used: 2e6f13e, e6a429d, 8730ff0, 12ba9c7, c1c8e5e, 78ec881, c9b01c5, 43ed239, b1a6dbd, a37d148 Updated for |
|
…te-up, and the ranking note drops its v6 gate Two more retirements the v6 sweep left behind, both decided with the owner on 2026-09-18. upstream-tell-809-833-the-hang-is-fixed.md had all three of its tellings done and its own vetted line said it was kept only for the corrected diagnosis. That diagnosis had no durable home: the role-holder-dies write-up covers the close path, not the commit-response seam. It now lives in docs/solutions/logic-errors/the-only-producer-of-commit-responses-died-so-every-waiter-reported-a-timeout-2026-09-18.md: the mechanism (the broker-poll thread is the only producer of commit responses), the inference the note first got wrong (#100 removed one route; the class closed when #177 published the death), the message that lied about its own budget, the dirty asymmetry a reproduction has to respect, and who was told. Every citer moves with it: two inflight notes, the response tracker, and the CommitResponseTimeoutSoakIT javadoc. #518 edits neither of those javadoc lines, so the two branches merge cleanly in either order. process-candidate-ranking.md carried "What gates v6, as the sweep read it" - a dated reading of a release that has since shipped. It is a git-show pointer now, like the decisions section before it; "Ready picks" stays, because it is the note's live purpose. release-0.6.0.0.md is deliberately NOT retired: the owner's call is to keep it for a while, since v6 was a special release and the register carries signal nothing else does. Revisit after #517 merges. Co-Authored-By: Claude Fable 5.1 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_019XS64Xttx4vF5datYh7fmk
1 participant
Description
Records three arms of CommitResponseTimeoutSoakIT on the released code (v0.6.0.0 plus two docs commits, 2e6f13e) in the scenario's Calibration status and in docs/inflight/bug-177-commit-response-timeout-unreproduced.md. No product or test code changes - the record is the deliverable.
The question since #471: does a BARE "Timeout waiting for commit response" - the poller wedged but alive, the one mechanism nobody has characterised - ever appear on the released code when the workload is arranged so the intake gate does not latch and commits keep happening for the whole soak. #471's two 30-minute runs could not answer it: the retry-forever poison latched the record-intake gate inside the first minute and no commit was attempted after that, which #487 measured and #497 made loud.
Common to all arms: seed 3747722682837130843, failureFraction 0.5, PERIODIC_CONSUMER_SYNC at 1s, 1000 keys over 20 partitions, maxConcurrency 14, 100ms user function, 1000 records every 20s, retry-forever; Testcontainers confluentinc/cp-kafka:7.9.0 on Docker; a Linux x86_64 workstation with every JVM pinned to 8 processors; no other Maven JVM on the box at the start of any arm; -Dpc.loadgate.log.level=info and -Dsoak.progressInterval=PT30S. Commit activity was read from the broker's __consumer_offsets with the broker's own formatter, because every commit-path line in the product is DEBUG.
Arm A - control, unchanged, 6 minutes. The latch reproduces on the released code to the number: succeeded frozen at 451 from the first 30s sample, the #497 WARN 13.2s after the banner (inShards=549 parkedForRetry=140 workable=409 vs 42, pausedPartitions=20), every partition paused at all 11 samples, failed 49,710 (138/s). The broker saw 8 commit instants, all inside the first 7.3s, and none in the remaining 5m50s. Load average 2.93 -> 1.54.
Arm B - 30 minutes, -Dsoak.messageBufferSize=20000, KEY, everything else the reporter's. No findings. The gate held open for 7m06s (loaded=false, zero paused partitions, at every sample to inShards=20,103), then latched at inShards=20993 vs target(14)*loadingFactor(1429)=20006 and stayed latched for the remaining 22m54s - so the #487 arm-3 value buys about seven minutes of this producer, not thirty, because under KEY nearly everything produced is held. But the assertion had already stopped being falsifiable at 3m06s, four minutes before the latch, and the gate is not why: successes went 680, 784, 869, 884, 893, 895, 897 and froze with the gate open, and the broker's last commit landed 185.7s after the first (27 commit instants). Under KEY each key retires records until its first poisoned one and never again, so permanent poison bounds successes by the key space, and dirty is derived from completions, so once successes stop commitAndWait is never entered. No buffer size changes that under KEY. Succeeded 897, failed 250,067 (139/s). Load average 1.17 -> 0.13.
Arm C - 30 minutes, -Dsoak.messageBufferSize=100000 -Dsoak.ordering=UNORDERED: the only combination of the existing knobs that holds both conditions. UNORDERED lifts the head-of-line bound so healthy records keep retiring; 100,000 clears the ~90,000 a thirty-minute producer can have held. Both held for the whole run: loaded=false and zero paused partitions at all 59 samples, inShards peaking at 51,949 against 100,002, no WARN, no back-pressure line; succeeded 37,641 and still rising at the end, failed 213,533 (119/s); a commit in every one of the thirty minutes - 619 commit instants, the last 1794.8s after the first, offset-map metadata growing to 768 base64 chars per partition. No findings: no bare timeout, no poller death, no thread dump written. Load average 0.12 -> 1.46.
What it establishes, as a rate under conditions: on v0.6.0.0, one instance, a quiet box, zero bare commit-response timeouts and zero poller deaths across 654 acknowledged commit instants, 619 of them in thirty minutes of a continuously exercised commit path. One run at one shape; it says the shape did not reproduce once, not that it cannot.
What it does not establish: anything about #175's own configuration (128 partitions, concurrency 64, a user function of minutes - still unrun), a loaded box, a rebalance, more than one instance, durations past thirty minutes, or KEY ordering with the commit path alive - which on this evidence needs the per-attempt-failure arm rather than a buffer size. Arm C departs from #177's reporter's ordering deliberately, and says so in both records.
No new knobs were added: -Dsoak.duration, -Dsoak.messageBufferSize and -Dsoak.ordering already existed. The only thing genuinely missing from the harness - evidence that commits were being attempted - was taken from the broker rather than by adding a log line, and the command is recorded in the javadoc so the next run can do the same.
Tracker: #175 (confluentinc#809).
Checklist
docs/inflight/bug-177-commit-response-timeout-unreproduced.mddocs/features/- N/A - a soak record, no capabilitydocs/inflight/working note (pr-/branch-) started at the PR's first commit - N/A - one commit recording three runs; the note it updates is the working notece-simplifyandce-code-reviewlocally - N/A - docs only;bin/check-all.shpasses🤖 Generated with Claude Code
https://claude.ai/code/session_019XS64Xttx4vF5datYh7fmk