HDDS-16398. Fix intermittent AlreadyClosedException in TestCommitWatcher - #11227
yandrey321 wants to merge 5 commits into
Conversation
chihsuan
left a comment
There was a problem hiding this comment.
Thanks for looking into this flaky test! @yandrey321 Could you share the CI log of the failure you investigated? The Jira stack trace is truncated.
Would it also be worth running the intermittent-test-check workflow on your branch to confirm it's stable?
Small nit: the code snippets in the description could use ``` fences so they render properly. Thanks!
here is the link to the failed CI: https://github.com/yandrey321/ozone/actions/runs/34395742534/job/102619847831 I saw multiple CI runs with the same signature. |
chihsuan
left a comment
There was a problem hiding this comment.
here is the link to the failed CI: https://github.com/yandrey321/ozone/actions/runs/34395742534/job/102619847831
Thanks for the link! @yandrey321 I ran the intermittent-test-check on your branch and it still failed 3 times: https://github.com/chihsuan/ozone/actions/runs/34612123189
The failures have different signatures, so I suspect the root cause is different and there may be multiple issues. Could you take a look?
|
chihsuan
left a comment
There was a problem hiding this comment.
Thanks! @yandrey321 I checked the datanode logs from my earlier intermittent run, and I'm not sure the current fix addresses the actual failure. Please see inline comments. Would it be worth running intermittent-test-check on the new head as well?
| OzoneTestHelper.createPipelineOnDatanode(pipeline, cluster); | ||
| ratisClient.sendCommandAsync( | ||
| ContainerTestHelper.getCreateContainerRequest(containerId, pipeline)) | ||
| .getResponse().get(); |
There was a problem hiding this comment.
I wonder if leader election is really the cause here. In the DN logs from my run, the second WriteChunk failed with CHUNK_FILE_INCONSISTENCY after the first PutBlock closed the block file. The container was then marked UNHEALTHY, followed by pipeline closure. Would using a different blockID per iteration avoid this?
| // A pipeline only opens once it is healthy, which requires an elected Ratis | ||
| // leader; otherwise the first write can race leader election and fail with | ||
| // NotLeaderException -> RaftRetryFailureException -> AlreadyClosedException. | ||
| cluster.waitForPipelineTobeReady(HddsProtos.ReplicationFactor.THREE, 60000); |
There was a problem hiding this comment.
Do we still need this wait? I noticed allocateContainer only picks pipelines already in OPEN state, and OPEN already implies a reported leader, so this may not add any guarantee.
| // pipeline datanodes and commit a CreateContainer synchronously. | ||
| // Otherwise the first write races leader election and can fail with | ||
| // NotLeaderException -> RaftRetryFailureException -> AlreadyClosedException. | ||
| OzoneTestHelper.createPipelineOnDatanode(pipeline, cluster); |
There was a problem hiding this comment.
nit: Could we drop createPipelineOnDatanode here? The groups should already exist for an OPEN pipeline, so these calls normally just hit duplicate-group errors that the helper swallows. Same for line 246.
| try (XceiverClientSpi xceiverClient = mgr.acquireClient(pipeline)) { | ||
| assertEquals(1, xceiverClient.getRefcount()); | ||
| XceiverClientRatis ratisClient = assertInstanceOf(XceiverClientRatis.class, xceiverClient); | ||
| // Ensure the freshly-allocated pipeline has an elected Ratis leader |
There was a problem hiding this comment.
nit: Could we trim this comment and keep the explanation in one place? The same explanation appears here, at line 241, and in init(), and the exception chain is already in the PR description.
chihsuan
left a comment
There was a problem hiding this comment.
Hi @yandrey321, the new head looks much better, with intermittent-test-check going from 3 failures to 1 of 100. https://github.com/chihsuan/ozone/actions/runs/36010552048/job/107671428630
The remaining one failed at the new CreateContainer call, with a LeaderNotReadyException right after leader election.
14:27:06,273 155c2039@group-C61D84748144: change Leader from null to 155c2039
14:27:06,404 LeaderNotReadyException: 155c2039@group-C61D84748144 is in LEADER state but not ready yet.
14:27:20,214 NotLeaderException: Server aab42b7f@group-C61D84748144 is not the leader, suggested leader is: 155c2039
RaftRetryFailureException: ... for 3 attempts
TestCommitWatcher.testReleaseBuffersOnException:241 » AlreadyClosedException: ... RAFT is closed.
Could we wait for the leader to be ready before the first write?
What changes were proposed in this pull request?
TestCommitWatcherfails intermittently in CI, in both test methods:Root cause
PipelineReportHandler.setPipelineLeaderIdonlyever sets
leaderId, from a datanode report riding the heartbeat — 10s here. It is never absent(RATIS
OPENrequiresPipeline.isHealthy()⇒leaderId != null) but can name a datanode that hasstopped leading, and
XceiverClientRatis.connect()feeds it tosetLeaderId(...)unvalidated.async()call instantiatesOrderedAsync, which sendsWatch(0)"to establish the connection" as seq=1 of the shared->RAFTwindow; the test's own first request becomes seq=2, parked, never reaching the wire.Watch(0)getsNotLeaderException, and WATCHretries are capped by
watchRequestTimeout, lowered 30s → 10s here — the stack's "3 attempts".SlidingWindow.Client.fail(1, e)fails the parkedrequest with
AlreadyClosedExceptionand latches the window closed.A harness problem, not a product defect: production keeps
watchRequestTimeoutat 30s, and on thisfailure the Ozone client discards the pipeline and retries elsewhere.
Fix
A new
allocateContainerWithElectedLeader()helper re-reads the container from SCM until the pipelinerecord names a leader and that datanode reports itself as the current Raft leader; the client is then
acquired on that refreshed pipeline.
This addresses step 1, the only step the test controls: given a current hint the dummy watch reaches the
real leader and steps 2-4 never fire.
isRatisLeaderis the load-bearing half, distinguishing currentfrom reported at some point;
getLeaderId() != nullonly keepsgetLeaderNode()off its closest-nodefallback; re-reading is needed because
allocateContainer'sContainerWithPipelineis a snapshot whoseleaderIdnever updates. (waitForPipelineTobeReadyis no substitute — it waits for some pipeline toreach
OPEN.) Exposure narrows from the ~10s heartbeat window to the gap between check and first request;closing it entirely would mean weakening the timeouts the test exists to exercise.
Also here, unrelated to the flake: each loop iteration now uses a distinct
BlockIDinstead ofwriting two different chunks to one blockID and offset (
CHUNK_FILE_INCONSISTENCY, tolerated underHDDS-11239). Hygiene only.
Generated-by: Claude Code (Claude Opus 5)
What is the link to the Apache JIRA
https://issues.apache.org/jira/browse/HDDS-16398
How was this patch tested?
CI: