[
https://issues.apache.org/jira/browse/HDDS-17213?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Siyao Meng updated HDDS-17213:
------------------------------
Description:
{code}
Tests run: 2, Failures: 0, Errors: 1, Skipped: 0, Time elapsed: 48.83 s <<<
FAILURE! -- in
org.apache.hadoop.ozone.container.common.statemachine.commandhandler.TestFinalizeBlock
org.apache.hadoop.ozone.container.common.statemachine.commandhandler.TestFinalizeBlock.testFinalizeBlock(boolean)[1]
-- Time elapsed: 27.22 s <<< ERROR!
java.io.IOException: INTERNAL_ERROR
org.apache.hadoop.ozone.om.exceptions.OMException: Unable to allocate a
container to the block of size: 4194304, replicationConfig: RATIS/ONE. Pipeline
2db9369f-7cb9-424c-b62f-3b5563e19053 is not ready in 1000 ms
at
org.apache.hadoop.ozone.client.io.KeyOutputStream.handleWrite(KeyOutputStream.java:285)
...
at
org.apache.hadoop.ozone.client.io.OzoneOutputStream.close(OzoneOutputStream.java:108)
at
org.apache.hadoop.ozone.container.common.statemachine.commandhandler.TestFinalizeBlock.createKey(TestFinalizeBlock.java:271)
at
org.apache.hadoop.ozone.container.common.statemachine.commandhandler.TestFinalizeBlock.testFinalizeBlock(TestFinalizeBlock.java:140)
{code}
h3. Root cause
{{setup}} only waits for SCM to report an OPEN RATIS/ONE pipeline
({{waitForPipelineTobeReady}}). SCM opened it when the datanode reported the
new Ratis group, about 1 s before the group elected a leader and about 1.1 s
before the leader was ready. The test wrote its first key in that window:
* WriteChunk (seq=2) reached the leader before it was ready and was rejected
with {{LeaderNotReadyException}}, so nothing was appended.
* PutBlock (seq=3) arrived just after the leader became ready, so it was
appended (log index 1) and applied. The server side sliding window treats the
rejected seq=2 as processed and does not hold seq=3 back.
* Applying the PutBlock without its WriteChunk failed with "Chunk file not
found", the container was marked UNHEALTHY and the pipeline was closed.
* The client then failed over to a new block, SCM created a new pipeline, and
allocateBlock failed because that pipeline was not ready in 1000 ms.
Ratis orders the processing of async requests, but a retriable rejection of one
request does not stop the next one from being committed. The window exists only
right after leader election, before the leader is ready. The test hits it
because it writes to a pipeline as soon as SCM reports it OPEN.
h3. Fix
In {{setup}}, after the pipeline is OPEN, wait until the datanode's Ratis
division of that pipeline reports {{isLeaderReady()}} (the same check the
leader uses to return {{LeaderNotReadyException}}) before the first write.
- https://github.com/apache/ozone/actions/runs/39532079401/job/119049936627
was:
{code}
Tests run: 2, Failures: 0, Errors: 1, Skipped: 0, Time elapsed: 48.83 s <<<
FAILURE! -- in
org.apache.hadoop.ozone.container.common.statemachine.commandhandler.TestFinalizeBlock
org.apache.hadoop.ozone.container.common.statemachine.commandhandler.TestFinalizeBlock.testFinalizeBlock(boolean)[1]
-- Time elapsed: 27.22 s <<< ERROR!
java.io.IOException: INTERNAL_ERROR
org.apache.hadoop.ozone.om.exceptions.OMException: Unable to allocate a
container to the block of size: 4194304, replicationConfig: RATIS/ONE. Pipeline
2db9369f-7cb9-424c-b62f-3b5563e19053 is not ready in 1000 ms
at
org.apache.hadoop.ozone.client.io.KeyOutputStream.handleWrite(KeyOutputStream.java:285)
...
at
org.apache.hadoop.ozone.client.io.OzoneOutputStream.close(OzoneOutputStream.java:108)
at
org.apache.hadoop.ozone.container.common.statemachine.commandhandler.TestFinalizeBlock.createKey(TestFinalizeBlock.java:271)
at
org.apache.hadoop.ozone.container.common.statemachine.commandhandler.TestFinalizeBlock.testFinalizeBlock(TestFinalizeBlock.java:140)
{code}
h3. Root cause
{{setup}} only waits for SCM to report an OPEN RATIS/ONE pipeline
({{waitForPipelineTobeReady}}). SCM opened it when the datanode reported the
new Ratis group, about 1 s before the group elected a leader and about 1.1 s
before the leader was ready. The test wrote its first key in that window:
* WriteChunk (seq=2) reached the leader before it was ready and got
{{LeaderNotReadyException}}.
* PutBlock (seq=3) arrived after the leader became ready, so it was appended
(log index 1) and applied.
* In Ratis 3.3.1 {{GrpcClientProtocolClient}} completes every pending reply of
the stream with the {{LeaderNotReadyException}} of one reply
({{completeReplyExceptionally}}), so the client treated PutBlock as failed too
and retried both later.
* Applying the PutBlock without its WriteChunk failed with "Chunk file not
found", the container was marked UNHEALTHY and the pipeline was closed.
* The client then failed over to a new block, SCM created a new pipeline, and
allocateBlock failed because that pipeline was not ready in 1000 ms.
The Ratis client behavior is the underlying issue. The test only hits it
because it writes to a pipeline whose leader is not ready yet.
h3. Fix
In {{setup}}, after the pipeline is OPEN, wait until the datanode's Ratis
division of that pipeline reports {{isLeaderReady()}} (the same check the
leader uses to return {{LeaderNotReadyException}}) before the first write.
- https://github.com/apache/ozone/actions/runs/39532079401/job/119049936627
> Intermittent failure in TestFinalizeBlock when the first write races the
> Ratis leader becoming ready
> ----------------------------------------------------------------------------------------------------
>
> Key: HDDS-17213
> URL: https://issues.apache.org/jira/browse/HDDS-17213
> Project: Apache Ozone
> Issue Type: Sub-task
> Components: Ozone Datanode, test
> Reporter: Siyao Meng
> Assignee: Siyao Meng
> Priority: Major
>
> {code}
> Tests run: 2, Failures: 0, Errors: 1, Skipped: 0, Time elapsed: 48.83 s <<<
> FAILURE! -- in
> org.apache.hadoop.ozone.container.common.statemachine.commandhandler.TestFinalizeBlock
> org.apache.hadoop.ozone.container.common.statemachine.commandhandler.TestFinalizeBlock.testFinalizeBlock(boolean)[1]
> -- Time elapsed: 27.22 s <<< ERROR!
> java.io.IOException: INTERNAL_ERROR
> org.apache.hadoop.ozone.om.exceptions.OMException: Unable to allocate a
> container to the block of size: 4194304, replicationConfig: RATIS/ONE.
> Pipeline 2db9369f-7cb9-424c-b62f-3b5563e19053 is not ready in 1000 ms
> at
> org.apache.hadoop.ozone.client.io.KeyOutputStream.handleWrite(KeyOutputStream.java:285)
> ...
> at
> org.apache.hadoop.ozone.client.io.OzoneOutputStream.close(OzoneOutputStream.java:108)
> at
> org.apache.hadoop.ozone.container.common.statemachine.commandhandler.TestFinalizeBlock.createKey(TestFinalizeBlock.java:271)
> at
> org.apache.hadoop.ozone.container.common.statemachine.commandhandler.TestFinalizeBlock.testFinalizeBlock(TestFinalizeBlock.java:140)
> {code}
> h3. Root cause
> {{setup}} only waits for SCM to report an OPEN RATIS/ONE pipeline
> ({{waitForPipelineTobeReady}}). SCM opened it when the datanode reported the
> new Ratis group, about 1 s before the group elected a leader and about 1.1 s
> before the leader was ready. The test wrote its first key in that window:
> * WriteChunk (seq=2) reached the leader before it was ready and was rejected
> with {{LeaderNotReadyException}}, so nothing was appended.
> * PutBlock (seq=3) arrived just after the leader became ready, so it was
> appended (log index 1) and applied. The server side sliding window treats the
> rejected seq=2 as processed and does not hold seq=3 back.
> * Applying the PutBlock without its WriteChunk failed with "Chunk file not
> found", the container was marked UNHEALTHY and the pipeline was closed.
> * The client then failed over to a new block, SCM created a new pipeline, and
> allocateBlock failed because that pipeline was not ready in 1000 ms.
> Ratis orders the processing of async requests, but a retriable rejection of
> one request does not stop the next one from being committed. The window
> exists only right after leader election, before the leader is ready. The test
> hits it because it writes to a pipeline as soon as SCM reports it OPEN.
> h3. Fix
> In {{setup}}, after the pipeline is OPEN, wait until the datanode's Ratis
> division of that pipeline reports {{isLeaderReady()}} (the same check the
> leader uses to return {{LeaderNotReadyException}}) before the first write.
> - https://github.com/apache/ozone/actions/runs/39532079401/job/119049936627
--
This message was sent by Atlassian Jira
(v8.20.10#820010)
---------------------------------------------------------------------
To unsubscribe, e-mail: [email protected]
For additional commands, e-mail: [email protected]
