Siyao Meng created HDDS-16979:
---------------------------------
Summary: hsync or flush on a Ratis key never returns when the
block that takes over a failed block's data fails as well
Key: HDDS-16979
URL: https://issues.apache.org/jira/browse/HDDS-16979
Project: Apache Ozone
Issue Type: Bug
Reporter: Siyao Meng
Attachments: CR-5-do-not-wait-for-failed-retry-block-in-hsync.patch,
TestBugCR5HsyncWaitsForFailedRetryBlock.java
h3. Mechanism
Since HDDS-11239 (2.0.0) the block that {{KeyOutputStream.handleRetry}}
allocates to take over the buffered data of a failed block is created in retry
handling mode ({{isHandlingRetry}}). {{KeyOutputStream.handleFlushOrClose}} and
{{writeToOutputStream}} call {{BlockOutputStreamEntry.waitForRetryHandling}} on
the current block, which awaits a condition as long as the flag is set. The
flag is cleared in one place only: {{KeyOutputStream.handleException}} calls
{{finishRetryHandling}} on the block that is current when the last pending call
on the faulty block has been handled.
If the retry block fails too (the rewrite of the buffered data fails, or its
stream cannot be created), the nested handling replaces it with a third block,
and it is the third block whose flag is cleared. The second block keeps its
flag for good. {{handleFlushOrClose}} reads the current block before it takes
the write lock. An {{hsync}} or {{flush}} that read the second block while it
was current, and then waited for the lock held by the failure handling, finds
the flag set and waits for a signal that is never sent for this block.
{{write}} and {{close}} pick the block with the write lock held, so they only
see the block that survived, and are not affected as the waiting call.
h3. Trigger
# {{ozone.client.hbase.enhancements.allowed=true}} and
{{ozone.client.key.write.concurrency}} other than 1 (run with -1), so that
calls on one key stream can overlap. Run with {{ozone.fs.hsync.enabled=true}};
with it false {{hsync}} and {{hflush}} run as {{flush}} and wait the same way
(run).
# A block of a Ratis key fails, and the block allocated for the retry fails as
well. Run with a write failure on the retry block, with a retry block whose
stream cannot be created, and with every block failing.
# A second {{hsync}} or {{flush}} on the same stream starts while the first
failure is being handled and after the retry block was allocated. A call that
was already in progress on the failed block takes the exception path, and a
call that has to write first waits in {{write}} and then sees the surviving
block. Neither is affected.
With the default concurrency of 1 the request semaphore keeps a second
{{flush}} or {{hsync}} out while the first is being handled (code reading).
The two failures in a row were produced with mock datanodes and, on a mini
cluster, by answering the writes of the first two blocks with
{{CLOSED_CONTAINER_IO}} through the client side test hook
{{XceiverClientManager.enableErrorInjection}} (the datanodes themselves were
healthy). Which cluster events produce them in practice (for example one
datanode outage that hits both pipelines, or a client that lost all datanodes)
is argued, not run.
Without any pause in the test, on unmodified source: with mock datanodes, three
{{hsync}} and one {{flush}} started together with two blocks failing left calls
hanging in 10 of 100 rounds. On a mini cluster, four {{hsync}} threads that are
independent of the writer and pause up to 150 ms between calls, with a retry
block that takes 100 ms to fail, had a thread hang in 4 of 4 rounds (none in 10
rounds with the patch). Not hit, in 20 rounds each that were run once in review
and not repeated: threads that each write and then {{hsync}}, and {{hsync}}
threads that pause at most 5 ms, which are all already waiting on the first
block before the retry block exists.
h3. Impact
* The second call never returns. There is no exception and no timeout, and only
an interrupt ends the wait ({{InterruptedIOException}}).
* {{close}} from another thread returns and the key is complete, but the
{{hsync}} thread stays parked. When the waiting call is
{{OzoneOutputStream.flush}}, it holds the monitor of the stream, so {{close}}
blocks behind it and the key is not committed.
* When every block fails, the first caller gets "Retry request failed. retries
get failed due to exceeded maximum allowed retries number: 5" and the stream is
closed. The second caller still waits instead of failing.
* HBase WAL sync threads call {{hsync}} on one stream independently of the
thread that appends, which is the kind of caller that gets into the window, so
there each occurrence would cost a sync thread. Not run with HBase. HDDS-11374
(open) reports a WAL sync that got {{InterruptedIOException}} from
{{handleFlushOrClose}} on a build with HDDS-11239 and unlimited concurrency. In
today's code that exception can only come from this wait, but whether the
thread was stuck there cannot be told from that report.
* No committed data is affected.
Stack of the second caller, from the mini cluster run:
{noformat}
org.apache.hadoop.ozone.client.io.BlockOutputStreamEntry.waitForRetryHandling(BlockOutputStreamEntry.java:135)
org.apache.hadoop.ozone.client.io.KeyOutputStream.lambda$handleFlushOrClose$5(KeyOutputStream.java:579)
org.apache.hadoop.ozone.client.io.KeyOutputStream.doInWriteLock(KeyOutputStream.java:252)
org.apache.hadoop.ozone.client.io.KeyOutputStream.handleFlushOrClose(KeyOutputStream.java:579)
org.apache.hadoop.ozone.client.io.KeyOutputStream.hsync(KeyOutputStream.java:542)
org.apache.hadoop.ozone.client.io.OzoneOutputStream.hsync(OzoneOutputStream.java:127)
org.apache.hadoop.fs.ozone.OzoneFSOutputStream.hsync(OzoneFSOutputStream.java:74)
{noformat}
h3. Reproduction
PASS, deterministic, unmodified source.
[^TestBugCR5HsyncWaitsForFailedRetryBlock.java] ({{hadoop-ozone/client}}, about
one second) drives the unmodified write path through {{OzoneBucket.createKey}}
and {{OzoneOutputStream}} with mock datanodes. A subclass of
{{MockXceiverClientFactory}} makes the requests of the failing blocks fail and
pauses the first caller when it creates the stream of the retry block, until
the second caller is blocked on the write lock. No fixed sleeps. Cases:
{{hsync}} as the second caller (stays parked after {{close}} returned and the
key was read back, released by an interrupt), {{flush}} as the second caller
({{close}} blocked behind it), and every block failing (stream closed, second
caller still parked). A control in which the retry block is healthy returns for
both callers. A passing test means the defect is present.
The mini cluster run (5 datanodes, two {{FSDataOutputStream.hsync}} threads,
error injection as described above) showed the same stack and is not attached.
h3. Patch
[^CR-5-do-not-wait-for-failed-retry-block-in-hsync.patch], against
031e76aa2c9a60b67185390b5b33499cbbb82e43. It also applies to master at
5181ff8ae81.
{{BlockOutputStreamEntry.waitForRetryHandling}} now waits only while the block
is in retry handling mode and is still the current block, and tells the caller
when the block was given up. {{KeyOutputStream.handleFlushOrClose}} then starts
over with the block that replaced it. A call released this way fails with
"Stream is closed" if the stream was closed in the meantime. The condition
depends on the state of the block pool only, so it holds for every way the
failure handling can end, including exceptions. Nothing changes for a block
that is not in retry handling mode.
Covered by {{testHsyncWhenBlockHandlingRetryFails}} in the existing
{{TestKeyOutputStream}}, with one, two and all blocks failing. Without the
change the last two cases fail on a timeout of the second {{hsync}} (20 of 20
runs each) and the first passes. With it all three pass (200 of 200 runs each),
all tests of {{hadoop-ozone/client}} (162) and {{TestHSync}} on a mini cluster
(42) pass and checkstyle is clean. With the patch the three hang cases of the
reproduction fail, because the second caller returns; the control still passes.
On the mini cluster both {{hsync}} calls return and the file reads back, or the
second fails with "Stream is closed" when every block fails.
The patch is independent of HDDS-16975 and applies before or after its patch.
Found by code review of the Ratis key write path while validating fixes from
the TLA+ verification effort under HDDS-15926, on commit
031e76aa2c9a60b67185390b5b33499cbbb82e43. Checked against HDDS issues and
apache/ozone pull requests for duplicates before filing. The attached patch is
a proposal for review. Generated with Specula (Claude Opus 5.5).
--
This message was sent by Atlassian Jira
(v8.20.10#820010)
---------------------------------------------------------------------
To unsubscribe, e-mail: [email protected]
For additional commands, e-mail: [email protected]
