[
https://issues.apache.org/jira/browse/HDDS-16979?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Siyao Meng updated HDDS-16979:
------------------------------
Attachment: TestBugCR5HsyncWaitsForFailedRetryBlock.java
> 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
> Priority: Major
> 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]
