[
https://issues.apache.org/jira/browse/KAFKA-21035?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=18111836#comment-18111836
]
Li Guo commented on KAFKA-21035:
--------------------------------
Fix is up for review: [https://github.com/apache/kafka/pull/23368]
It keeps the move failure as the primary exception and attaches the fsync
failure as suppressed, same as Utils.closeAll. Two unit tests cover the masked
case and the fsync-fails-after-a-successful-move case. I also ran the broker
scenario above against trunk and the fix: trunk logs the parent-dir fsync
error, the fix logs the failed rename with the fsync error suppressed
> Utils.atomicMoveWithFallback masks the move failure when the parent directory
> flush also fails
> ----------------------------------------------------------------------------------------------
>
> Key: KAFKA-21035
> URL: https://issues.apache.org/jira/browse/KAFKA-21035
> Project: Kafka
> Issue Type: Bug
> Components: clients, core
> Affects Versions: 4.3.1
> Reporter: Li Guo
> Priority: Minor
>
> {{Utils.atomicMoveWithFallback}} fsyncs the parent directory of {{target}} in
> a {{finally}} block. If the move fails and the fsync fails too, the fsync
> exception replaces the move exception with nothing suppressed. Which file
> failed to move, and why, is lost.
> {code:java}
> // clients/src/main/java/org/apache/kafka/common/utils/Utils.java (logging
> elided)
> try {
> Files.move(source, target, ATOMIC_MOVE);
> } catch (IOException outer) {
> try {
> Files.move(source, target, REPLACE_EXISTING);
> } catch (IOException inner) {
> inner.addSuppressed(outer);
> throw inner; // discarded if flushDir below
> throws
> }
> } finally {
> if (needFlushParentDir) {
> flushDir(target.toAbsolutePath().normalize().getParent());
> }
> }
> {code}
> h3. Reproduce (clients jar only)
> Save this as {{Repro.java}} in an extracted Kafka distribution:
> {code:java}
> import java.nio.file.*;
> import org.apache.kafka.common.utils.Utils;
> public class Repro {
> public static void main(String[] args) throws Exception {
> Path dir = Files.createTempDirectory("repro");
> try {
> Utils.atomicMoveWithFallback(dir.resolve("missing-src"),
> dir.resolve("missing-dir/target"), true);
> } catch (Exception e) {
> System.out.println("thrown: " + e);
> System.out.println("suppressed: " +
> java.util.Arrays.toString(e.getSuppressed()));
> }
> }
> }
> {code}
> {noformat}
> javac -proc:none -cp "libs/*" Repro.java && java -cp "libs/*:." Repro
> {noformat}
> Output (4.3.1 and trunk):
> {noformat}
> thrown: java.nio.file.NoSuchFileException:
> /tmp/repro1272131299401924814/missing-dir
> suppressed: []
> {noformat}
> Nothing points at {{missing-src}}. Expected:
> {noformat}
> thrown: java.nio.file.NoSuchFileException:
> /tmp/repro4632013055863457313/missing-src
> suppressed: [java.nio.file.NoSuchFileException:
> /tmp/repro4632013055863457313/missing-src ->
> /tmp/repro4632013055863457313/missing-dir/target,
> java.nio.file.NoSuchFileException: /tmp/repro4632013055863457313/missing-dir]
> {noformat}
> Primary and first suppressed are the two move failures, exactly as thrown
> today when the fsync succeeds. The second suppressed is the fsync failure.
> h3. Effect on a broker
> Every caller with the flush enabled is affected: {{CheckpointFile}},
> {{PartitionMetadataFile}}, {{PropertiesUtils}} (meta.properties),
> {{FileQuorumStateStore}}, {{FileRawSnapshotWriter}}, {{LocalLog.renameDir}},
> Streams {{OffsetCheckpoint}}. When a log directory fails, the masked
> exception is what {{LogDirFailureChannel}} logs while taking it offline.
> Single-node KRaft broker, {{log.dirs=/data/a,/data/b}}, {{metadata.log.dir}}
> outside both. Add these to {{server.properties}} and restart, so the periodic
> checkpoint tasks do not take the directory offline first with a different
> error:
> {noformat}
> log.initial.task.delay.ms=86400000
> replica.high.watermark.checkpoint.interval.ms=86400000
> log.cleaner.backoff.ms=86400000
> {noformat}
> Then:
> {noformat}
> bin/kafka-topics.sh --bootstrap-server localhost:9092 --create --topic e2e
> --partitions 1 --replication-factor 1
> bin/kafka-producer-perf-test.sh --topic e2e --num-records 200 --record-size
> 512 --throughput -1 --producer-props bootstrap.servers=localhost:9092
> ls -d /data/*/e2e-0 # pick the log dir that holds e2e-0, here
> /data/a
> mv /data/a /data/a.gone
> bin/kafka-topics.sh --bootstrap-server localhost:9092 --delete --topic e2e
> {noformat}
> Within a second the broker log (trunk) shows:
> {noformat}
> ERROR Error while renaming dir for e2e-0 in log dir /data/a
> (org.apache.kafka.storage.internals.log.LogDirFailureChannel)
> java.nio.file.NoSuchFileException: /data/a
> ...
> at org.apache.kafka.common.utils.Utils.flushDir(Utils.java:969)
> at
> org.apache.kafka.common.utils.Utils.atomicMoveWithFallback(Utils.java:955)
> at
> org.apache.kafka.storage.internals.log.LocalLog.lambda$renameDir$1(LocalLog.java:204)
> ...
> {noformat}
> No {{Suppressed:}} line, and nothing in the ERROR names the rename of
> {{/data/a/e2e-0}}. The only trace of it is the WARN that {{Utils}} logs for
> the first, atomic attempt. The fallback attempt's failure is gone.
> h3. Fix
> Catch the flush failure in the {{finally}}. If a move exception is in flight,
> add the flush failure to it as suppressed and rethrow the move exception, as
> {{Utils.closeAll}} does. Otherwise rethrow the flush failure.
--
This message was sent by Atlassian Jira
(v8.20.10#820010)
