Li Guo created KAFKA-21035:
------------------------------
Summary: 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
{{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)
