[
https://issues.apache.org/jira/browse/HDDS-16398?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Andrey Yarovoy updated HDDS-16398:
----------------------------------
Description:
{{org.apache.hadoop.hdds.scm.storage.TestCommitWatcher#testReleaseBuffersOnException}}
fails intermittently in CI. The failure occurs during test setup — while
waiting on the _first_ {{putBlock}} response ({{{}future1.get(){}}} at
{{{}TestCommitWatcher.java:262{}}}), before the test reaches the datanode
shutdowns that exercise the behavior actually under test.
*Stack trace*
{code:java}
[ERROR] Tests run: 2, Failures: 0, Errors: 1, Skipped: 0, Time elapsed: 57.76 s
<<< FAILURE! -- in org.apache.hadoop.hdds.scm.storage.TestCommitWatcher
[ERROR]
org.apache.hadoop.hdds.scm.storage.TestCommitWatcher.testReleaseBuffersOnException
-- Time elapsed: 32.75 s <<< ERROR!
java.util.concurrent.ExecutionException:
org.apache.ratis.protocol.exceptions.AlreadyClosedException:
SlidingWindow$Client:client-B2BDCC4ECA19->RAFT is closed.
at
java.base/java.util.concurrent.CompletableFuture.wrapInExecutionException(CompletableFuture.java:345)
at
java.base/java.util.concurrent.CompletableFuture.reportGet(CompletableFuture.java:440)
at
java.base/java.util.concurrent.CompletableFuture.get(CompletableFuture.java:2094)
at
org.apache.hadoop.hdds.scm.storage.TestCommitWatcher.testReleaseBuffersOnException(TestCommitWatcher.java:262)
at java.base/java.lang.reflect.Method.invoke(Method.java:565)
at
java.base/java.util.concurrent.ForkJoinTask.doExec(ForkJoinTask.java:511)
at
java.base/java.util.concurrent.ForkJoinPool$WorkQueue.topLevelExec(ForkJoinPool.java:1450)
at
java.base/java.util.concurrent.ForkJoinPool.runWorker(ForkJoinPool.java:2019)
at
java.base/java.util.concurrent.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:187)
Caused by: org.apache.ratis.protocol.exceptions.AlreadyClosedException:
SlidingWindow$Client:client-B2BDCC4ECA19->RAFT is closed.
at
org.apache.ratis.util.SlidingWindow$Client.alreadyClosed(SlidingWindow.java:409)
at
org.apache.ratis.util.SlidingWindow$Client.fail(SlidingWindow.java:397)
at
org.apache.ratis.client.impl.OrderedAsync.failAllAsyncRequests(OrderedAsync.java:155)
at
org.apache.ratis.client.impl.OrderedAsync.handleException(OrderedAsync.java:239)
at
org.apache.ratis.client.impl.OrderedAsync.lambda$sendRequestWithRetry$7(OrderedAsync.java:217)
at
java.base/java.util.concurrent.CompletableFuture.uniExceptionally(CompletableFuture.java:1011)
at
java.base/java.util.concurrent.CompletableFuture$UniExceptionally.tryFire(CompletableFuture.java:995)
at
java.base/java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:531)
at
java.base/java.util.concurrent.CompletableFuture.completeExceptionally(CompletableFuture.java:2221)
at
org.apache.ratis.grpc.client.GrpcClientProtocolClient$AsyncStreamObservers.completeReplyExceptionally(GrpcClientProtocolClient.java:383)
at
org.apache.ratis.grpc.client.GrpcClientProtocolClient$AsyncStreamObservers.access$000(GrpcClientProtocolClient.java:289)
at
org.apache.ratis.grpc.client.GrpcClientProtocolClient$AsyncStreamObservers$1.onNext(GrpcClientProtocolClient.java:303)
at
org.apache.ratis.grpc.client.GrpcClientProtocolClient$AsyncStreamObservers$1.onNext(GrpcClientProtocolClient.java:294)
at
org.apache.ratis.thirdparty.io.grpc.stub.ClientCalls$StreamObserverToCallListenerAdapter.onMessage(ClientCalls.java:568)
at
org.apache.ratis.thirdparty.io.grpc.ForwardingClientCallListener.onMessage(ForwardingClientCallListener.java:33)
at
org.apache.ratis.thirdparty.io.grpc.internal.ClientCallImpl$ClientStreamListenerImpl$1MessagesAvailable.runInternal(ClientCallImpl.java:662)
at
org.apache.ratis.thirdparty.io.grpc.internal.ClientCallImpl$ClientStreamListenerImpl$1MessagesAvailable.runInContext(ClientCallImpl.java:649)
at
org.apache.ratis.thirdparty.io.grpc.internal.ContextRunnable.run(ContextRunnable.java:37)
at
org.apache.ratis.thirdparty.io.grpc.internal.SerializingExecutor.run(SerializingExecutor.java:133)
at
java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1090)
at
java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:614)
at java.base/java.lang.Thread.run(Thread.java:1474)
Caused by: org.apache.ratis.protocol.exceptions.RaftRetryFailureException:
Failed
RaftClientRequest:client-B2BDCC4ECA19->d62e25aa-d69c-443b-9022-60783a301ea7@group-99887BE5BE56,
cid=29, seq=1*, Watch(0), null for 3 attempts with
RequestTypeDependentRetryPolicy{WRITE->ExceptionDependentRetry(maxAttempts=2147483647;
defaultPolicy=MultipleLinearRandomRetry[6x5s];
map={org.apache.ratis.protocol.exceptions.GroupMismatchException->NoRetry,
org.apache.ratis.protocol.exceptions.NotReplicatedException->NoRetry,
org.apache.ratis.protocol.exceptions.ResourceUnavailableException->org.apache.ratis.retry.ExponentialBackoffRetry@21857b0b,
org.apache.ratis.protocol.exceptions.StateMachineException->NoRetry,
org.apache.ratis.protocol.exceptions.TimeoutIOException->org.apache.ratis.retry.ExponentialBackoffRetry@21857b0b}),
WATCH->ExceptionDependentRetry(maxAttempts=2147483647;
defaultPolicy=MultipleLinearRandomRetry[6x5s];
map={org.apache.ratis.protocol.exceptions.GroupMismatchException->NoRetry,
org.apache.ratis.protocol.exceptions.NotReplicatedException->NoRetry,
org.apache.ratis.protocol.exceptions.ResourceUnavailableException->org.apache.ratis.retry.ExponentialBackoffRetry@21857b0b,
org.apache.ratis.protocol.exceptions.StateMachineException->NoRetry,
org.apache.ratis.protocol.exceptions.TimeoutIOException->NoRetry})}
at
org.apache.ratis.client.impl.RaftClientImpl.noMoreRetries(RaftClientImpl.java:352)
... 19 more
Caused by: org.apache.ratis.protocol.exceptions.NotLeaderException: Server
d62e25aa-d69c-443b-9022-60783a301ea7@group-99887BE5BE56 is not the leader,
suggested leader is: 59f5747a-5169-40f0-9097-bc9a10c4738d|127.0.0.1:15071
at
org.apache.ratis.client.impl.ClientProtoUtils.toRaftClientReply(ClientProtoUtils.java:402)
at
org.apache.ratis.grpc.client.GrpcClientProtocolClient$AsyncStreamObservers$1.onNext(GrpcClientProtocolClient.java:299)
... 10 more *Root cause*
The test allocates a fresh RATIS THREE pipeline and immediately issues async
write/putBlock commands:
{code}
ContainerWithPipeline container = storageContainerLocationClient
.allocateContainer(RATIS, THREE, OZONE); Pipeline pipeline =
container.getPipeline(); ... ratisClient.sendCommandAsync(writeChunkRequest);
XceiverClientReply reply = ratisClient.sendCommandAsync(putBlockRequest);
\{code}
{{cluster.waitForClusterToBeReady()}} (called in {{{}@BeforeEach{}}}) waits for
datanode registration and SCM readiness, but does *not* guarantee that the
newly-allocated Ratis group has completed leader election. When the write lands
on a node that is not yet the leader, Ratis returns {{{}NotLeaderException{}}}.
Under the aggressive per-test retry policy (short watch timeout, limited
attempts), the request exhausts its retries and the client is closed, surfacing
as {{AlreadyClosedException}} from {{{}future1.get(){}}}.
This is a timing/leader-election race in test setup, not a product defect in
the commit-watch path.
*Reproducibility*
Intermittent. Timing-dependent; does not reproduce reliably. This test has a
long history of the same class of flakiness — see related issues below
(HDDS-9766 reports the identical {{AlreadyClosedException}} signature).
*Suggested fix*
Wait for the allocated pipeline to have an elected leader before issuing writes
— e.g., block on pipeline readiness / leader election
({{{}XceiverClientRatis.watchForCommit{}}} on the leader, or a
{{{}waitForPipelineReady{}}}-style helper) after {{allocateContainer}} and
before the first {{{}sendCommandAsync{}}}, so setup no longer races election.
Apply the same guard to {{{}testReleaseBuffers{}}}, which shares the pattern.
was:
{{org.apache.hadoop.hdds.scm.storage.TestCommitWatcher#testReleaseBuffersOnException}}
fails intermittently in CI. The failure occurs during test setup — while
waiting on the _first_ {{putBlock}} response ({{{}future1.get(){}}} at
{{{}TestCommitWatcher.java:262{}}}), before the test reaches the datanode
shutdowns that exercise the behavior actually under test.
*Stack trace*
{code} java.util.concurrent.ExecutionException:
org.apache.ratis.protocol.exceptions.AlreadyClosedException:
SlidingWindow$Client:client-B2BDCC4ECA19->RAFT is closed. at
java.base/java.util.concurrent.CompletableFuture.get(CompletableFuture.java:2094)
at
org.apache.hadoop.hdds.scm.storage.TestCommitWatcher.testReleaseBuffersOnException(TestCommitWatcher.java:262)
Caused by: org.apache.ratis.protocol.exceptions.AlreadyClosedException:
SlidingWindow$Client:client-... is closed. at
org.apache.ratis.util.SlidingWindow$Client.alreadyClosed(SlidingWindow.java:409)
... Caused by: org.apache.ratis.protocol.exceptions.RaftRetryFailureException:
Failed RaftClientRequest: client-...->d62e25aa-...@group-..., cid=29, seq=1*,
Watch(0), null for 3 attempts with RequestTypeDependentRetryPolicy\{ ... } at
org.apache.ratis.client.impl.RaftClientImpl.noMoreRetries(RaftClientImpl.java:352)
Caused by: org.apache.ratis.protocol.exceptions.NotLeaderException: Server
d62e25aa-... is not the leader, suggested leader is:
59f5747a-...|127.0.0.1:15071 at
org.apache.ratis.client.impl.ClientProtoUtils.toRaftClientReply(ClientProtoUtils.java:402)
\{code}
*Root cause*
The test allocates a fresh RATIS THREE pipeline and immediately issues async
write/putBlock commands:
{code} ContainerWithPipeline container = storageContainerLocationClient
.allocateContainer(RATIS, THREE, OZONE); Pipeline pipeline =
container.getPipeline(); ... ratisClient.sendCommandAsync(writeChunkRequest);
XceiverClientReply reply = ratisClient.sendCommandAsync(putBlockRequest);
\{code}
{{cluster.waitForClusterToBeReady()}} (called in {{{}@BeforeEach{}}}) waits for
datanode registration and SCM readiness, but does *not* guarantee that the
newly-allocated Ratis group has completed leader election. When the write lands
on a node that is not yet the leader, Ratis returns {{{}NotLeaderException{}}}.
Under the aggressive per-test retry policy (short watch timeout, limited
attempts), the request exhausts its retries and the client is closed, surfacing
as {{AlreadyClosedException}} from {{{}future1.get(){}}}.
This is a timing/leader-election race in test setup, not a product defect in
the commit-watch path.
*Reproducibility*
Intermittent. Timing-dependent; does not reproduce reliably. This test has a
long history of the same class of flakiness — see related issues below
(HDDS-9766 reports the identical {{AlreadyClosedException}} signature).
*Suggested fix*
Wait for the allocated pipeline to have an elected leader before issuing writes
— e.g., block on pipeline readiness / leader election
({{{}XceiverClientRatis.watchForCommit{}}} on the leader, or a
{{{}waitForPipelineReady{}}}-style helper) after {{allocateContainer}} and
before the first {{{}sendCommandAsync{}}}, so setup no longer races election.
Apply the same guard to {{{}testReleaseBuffers{}}}, which shares the pattern.
> TestCommitWatcher#testReleaseBuffersOnException intermittently fails with
> AlreadyClosedException (NotLeaderException on freshly-allocated pipeline)
> ---------------------------------------------------------------------------------------------------------------------------------------------------
>
> Key: HDDS-16398
> URL: https://issues.apache.org/jira/browse/HDDS-16398
> Project: Apache Ozone
> Issue Type: Bug
> Components: SCM Client
> Reporter: Andrey Yarovoy
> Assignee: Andrey Yarovoy
> Priority: Major
> Labels: pull-request-available
>
> {{org.apache.hadoop.hdds.scm.storage.TestCommitWatcher#testReleaseBuffersOnException}}
> fails intermittently in CI. The failure occurs during test setup — while
> waiting on the _first_ {{putBlock}} response ({{{}future1.get(){}}} at
> {{{}TestCommitWatcher.java:262{}}}), before the test reaches the datanode
> shutdowns that exercise the behavior actually under test.
> *Stack trace*
> {code:java}
> [ERROR] Tests run: 2, Failures: 0, Errors: 1, Skipped: 0, Time elapsed: 57.76
> s <<< FAILURE! -- in org.apache.hadoop.hdds.scm.storage.TestCommitWatcher
> [ERROR]
> org.apache.hadoop.hdds.scm.storage.TestCommitWatcher.testReleaseBuffersOnException
> -- Time elapsed: 32.75 s <<< ERROR!
> java.util.concurrent.ExecutionException:
> org.apache.ratis.protocol.exceptions.AlreadyClosedException:
> SlidingWindow$Client:client-B2BDCC4ECA19->RAFT is closed.
> at
> java.base/java.util.concurrent.CompletableFuture.wrapInExecutionException(CompletableFuture.java:345)
> at
> java.base/java.util.concurrent.CompletableFuture.reportGet(CompletableFuture.java:440)
> at
> java.base/java.util.concurrent.CompletableFuture.get(CompletableFuture.java:2094)
> at
> org.apache.hadoop.hdds.scm.storage.TestCommitWatcher.testReleaseBuffersOnException(TestCommitWatcher.java:262)
> at java.base/java.lang.reflect.Method.invoke(Method.java:565)
> at
> java.base/java.util.concurrent.ForkJoinTask.doExec(ForkJoinTask.java:511)
> at
> java.base/java.util.concurrent.ForkJoinPool$WorkQueue.topLevelExec(ForkJoinPool.java:1450)
> at
> java.base/java.util.concurrent.ForkJoinPool.runWorker(ForkJoinPool.java:2019)
> at
> java.base/java.util.concurrent.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:187)
> Caused by: org.apache.ratis.protocol.exceptions.AlreadyClosedException:
> SlidingWindow$Client:client-B2BDCC4ECA19->RAFT is closed.
> at
> org.apache.ratis.util.SlidingWindow$Client.alreadyClosed(SlidingWindow.java:409)
> at
> org.apache.ratis.util.SlidingWindow$Client.fail(SlidingWindow.java:397)
> at
> org.apache.ratis.client.impl.OrderedAsync.failAllAsyncRequests(OrderedAsync.java:155)
> at
> org.apache.ratis.client.impl.OrderedAsync.handleException(OrderedAsync.java:239)
> at
> org.apache.ratis.client.impl.OrderedAsync.lambda$sendRequestWithRetry$7(OrderedAsync.java:217)
> at
> java.base/java.util.concurrent.CompletableFuture.uniExceptionally(CompletableFuture.java:1011)
> at
> java.base/java.util.concurrent.CompletableFuture$UniExceptionally.tryFire(CompletableFuture.java:995)
> at
> java.base/java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:531)
> at
> java.base/java.util.concurrent.CompletableFuture.completeExceptionally(CompletableFuture.java:2221)
> at
> org.apache.ratis.grpc.client.GrpcClientProtocolClient$AsyncStreamObservers.completeReplyExceptionally(GrpcClientProtocolClient.java:383)
> at
> org.apache.ratis.grpc.client.GrpcClientProtocolClient$AsyncStreamObservers.access$000(GrpcClientProtocolClient.java:289)
> at
> org.apache.ratis.grpc.client.GrpcClientProtocolClient$AsyncStreamObservers$1.onNext(GrpcClientProtocolClient.java:303)
> at
> org.apache.ratis.grpc.client.GrpcClientProtocolClient$AsyncStreamObservers$1.onNext(GrpcClientProtocolClient.java:294)
> at
> org.apache.ratis.thirdparty.io.grpc.stub.ClientCalls$StreamObserverToCallListenerAdapter.onMessage(ClientCalls.java:568)
> at
> org.apache.ratis.thirdparty.io.grpc.ForwardingClientCallListener.onMessage(ForwardingClientCallListener.java:33)
> at
> org.apache.ratis.thirdparty.io.grpc.internal.ClientCallImpl$ClientStreamListenerImpl$1MessagesAvailable.runInternal(ClientCallImpl.java:662)
> at
> org.apache.ratis.thirdparty.io.grpc.internal.ClientCallImpl$ClientStreamListenerImpl$1MessagesAvailable.runInContext(ClientCallImpl.java:649)
> at
> org.apache.ratis.thirdparty.io.grpc.internal.ContextRunnable.run(ContextRunnable.java:37)
> at
> org.apache.ratis.thirdparty.io.grpc.internal.SerializingExecutor.run(SerializingExecutor.java:133)
> at
> java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1090)
> at
> java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:614)
> at java.base/java.lang.Thread.run(Thread.java:1474)
> Caused by: org.apache.ratis.protocol.exceptions.RaftRetryFailureException:
> Failed
> RaftClientRequest:client-B2BDCC4ECA19->d62e25aa-d69c-443b-9022-60783a301ea7@group-99887BE5BE56,
> cid=29, seq=1*, Watch(0), null for 3 attempts with
> RequestTypeDependentRetryPolicy{WRITE->ExceptionDependentRetry(maxAttempts=2147483647;
> defaultPolicy=MultipleLinearRandomRetry[6x5s];
> map={org.apache.ratis.protocol.exceptions.GroupMismatchException->NoRetry,
> org.apache.ratis.protocol.exceptions.NotReplicatedException->NoRetry,
> org.apache.ratis.protocol.exceptions.ResourceUnavailableException->org.apache.ratis.retry.ExponentialBackoffRetry@21857b0b,
> org.apache.ratis.protocol.exceptions.StateMachineException->NoRetry,
> org.apache.ratis.protocol.exceptions.TimeoutIOException->org.apache.ratis.retry.ExponentialBackoffRetry@21857b0b}),
> WATCH->ExceptionDependentRetry(maxAttempts=2147483647;
> defaultPolicy=MultipleLinearRandomRetry[6x5s];
> map={org.apache.ratis.protocol.exceptions.GroupMismatchException->NoRetry,
> org.apache.ratis.protocol.exceptions.NotReplicatedException->NoRetry,
> org.apache.ratis.protocol.exceptions.ResourceUnavailableException->org.apache.ratis.retry.ExponentialBackoffRetry@21857b0b,
> org.apache.ratis.protocol.exceptions.StateMachineException->NoRetry,
> org.apache.ratis.protocol.exceptions.TimeoutIOException->NoRetry})}
> at
> org.apache.ratis.client.impl.RaftClientImpl.noMoreRetries(RaftClientImpl.java:352)
> ... 19 more
> Caused by: org.apache.ratis.protocol.exceptions.NotLeaderException: Server
> d62e25aa-d69c-443b-9022-60783a301ea7@group-99887BE5BE56 is not the leader,
> suggested leader is: 59f5747a-5169-40f0-9097-bc9a10c4738d|127.0.0.1:15071
> at
> org.apache.ratis.client.impl.ClientProtoUtils.toRaftClientReply(ClientProtoUtils.java:402)
> at
> org.apache.ratis.grpc.client.GrpcClientProtocolClient$AsyncStreamObservers$1.onNext(GrpcClientProtocolClient.java:299)
> ... 10 more *Root cause*
> The test allocates a fresh RATIS THREE pipeline and immediately issues async
> write/putBlock commands:
> {code}
> ContainerWithPipeline container = storageContainerLocationClient
> .allocateContainer(RATIS, THREE, OZONE); Pipeline pipeline =
> container.getPipeline(); ... ratisClient.sendCommandAsync(writeChunkRequest);
> XceiverClientReply reply = ratisClient.sendCommandAsync(putBlockRequest);
> \{code}
> {{cluster.waitForClusterToBeReady()}} (called in {{{}@BeforeEach{}}}) waits
> for datanode registration and SCM readiness, but does *not* guarantee that
> the newly-allocated Ratis group has completed leader election. When the write
> lands on a node that is not yet the leader, Ratis returns
> {{{}NotLeaderException{}}}. Under the aggressive per-test retry policy (short
> watch timeout, limited attempts), the request exhausts its retries and the
> client is closed, surfacing as {{AlreadyClosedException}} from
> {{{}future1.get(){}}}.
> This is a timing/leader-election race in test setup, not a product defect in
> the commit-watch path.
> *Reproducibility*
> Intermittent. Timing-dependent; does not reproduce reliably. This test has a
> long history of the same class of flakiness — see related issues below
> (HDDS-9766 reports the identical {{AlreadyClosedException}} signature).
> *Suggested fix*
> Wait for the allocated pipeline to have an elected leader before issuing
> writes — e.g., block on pipeline readiness / leader election
> ({{{}XceiverClientRatis.watchForCommit{}}} on the leader, or a
> {{{}waitForPipelineReady{}}}-style helper) after {{allocateContainer}} and
> before the first {{{}sendCommandAsync{}}}, so setup no longer races election.
> Apply the same guard to {{{}testReleaseBuffers{}}}, which shares the pattern.
--
This message was sent by Atlassian Jira
(v8.20.10#820010)
---------------------------------------------------------------------
To unsubscribe, e-mail: [email protected]
For additional commands, e-mail: [email protected]
