[
https://issues.apache.org/jira/browse/KAFKA-15572?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Lucian Ilie updated KAFKA-15572:
--------------------------------
Description:
We are using a Kafka cluster with Zookeeper, deployed on top of Kubernetes,
using banzaicloud/koperator.
We have multiple disks per broker.
We are using Cruise Control remove disk operation in order to aggregate
multiple smaller disks into a single bigger disk.
When we do this, *the flush operation fails apparently randomly with
NoSuchFileException, while alterReplicaLogDirs is executed*. Attached a sample
of logs for the exception and the previous operations taking place.
Will further detail the cause of this issue.
Say we have 3 brokers:
* broker 101 with disks /kafka-logs1/kafka, /kafka-logs2/kafka and a bigger
disk /new-kafka-logs1/kafka
* broker 201 with same disks
* broker 301 with same disks
When Cruise Control executes a remove disk operation, it calls Kafka
"adminClient.alterReplicaLogDirs(replicaAssignment)" with such an assignment as
to move all data from /kafka-logs1/kafka and /kafka-logs2/kafka to
/new-kafka-logs1/kafka.
During the alter log dir operation, future logs are created (to move data from
e.g. "/kafka-logs1/kafka/topic-partition" to
"/new-kafka-logs1/kafka/topic-partition.hash-future"), data is moved and
finally the log dir will be renamed from
"/new-kafka-logs1/kafka/topic-partition.hash-future" to
"/new-kafka-logs1/kafka/topic-partition". This operation is started in
[UnifiedLog.renameDir|https://github.com/apache/kafka/blob/3.4/core/src/main/scala/kafka/log/UnifiedLog.scala#L713]
and is locked using the [UnifiedLog
lock|https://github.com/apache/kafka/blob/3.4/core/src/main/scala/kafka/log/UnifiedLog.scala#L268].
The rename is then delegated to
[LocalLog.renameDir|https://github.com/apache/kafka/blob/3.4/core/src/main/scala/kafka/log/LocalLog.scala#L111-L113].
This is the 1st code part that is involved in the race condition.
Meanwhile, log dirs can be rolled based on known conditions (e.g. getting
full), which will call
[UnifiedLog.roll|https://github.com/apache/kafka/blob/3.4/core/src/main/scala/kafka/log/UnifiedLog.scala#L1547],
which is locked using the [UnifiedLog
lock|https://github.com/apache/kafka/blob/3.4/core/src/main/scala/kafka/log/UnifiedLog.scala#L268].
However, the further delegation to UnifiedLog.flushUptoOffsetExclusive is not
sharing that lock, since it is [done as a scheduled task in a separate
thread|https://github.com/apache/kafka/blob/3.4/core/src/main/scala/kafka/log/UnifiedLog.scala#L1547].
This means that further operations are [not locked at UnifiedLog
level|https://github.com/apache/kafka/blob/3.4/core/src/main/scala/kafka/log/UnifiedLog.scala#L268].
The operation is further delegated to
[LocalLog.flush|https://github.com/apache/kafka/blob/3.4/core/src/main/scala/kafka/log/LocalLog.scala#L177],
which will also try to [flush the log
dir|https://github.com/apache/kafka/blob/3.4/core/src/main/scala/kafka/log/LocalLog.scala#L177].
This is the 2nd code part that is involved in the race condition.
Since the log dir flush does not share the lock with the rename dir operation
(as it is scheduled via the scheduler), the rename dir operation might succeed
in moving the log dir on disk to "topic-partition", but the LocalLog._dir will
remain set to "topic-partition.hash-future", and when the flush will attempt to
flush the "topic-partition.hash-future" directory, it will throw
NoSuchFileException: "topic-partition.hash-future". Basically, [this
line|https://github.com/apache/kafka/blob/3.4/core/src/main/scala/kafka/log/LocalLog.scala#L111]
might succeed, and before [this other
line|https://github.com/apache/kafka/blob/3.4/core/src/main/scala/kafka/log/LocalLog.scala#L111]
is executed, flush tries to [flush the future
dir|https://github.com/apache/kafka/blob/3.4/core/src/main/scala/kafka/log/LocalLog.scala#L177].
We tested a fix with a patch on Kafka 3.4.1, on our clusters and it solved the
issue by synchronizing the flush dir operation. Will reply with a link to a PR.
Note that this bug replicates for every version since 3.0.0, caused by [this
commit|https://github.com/apache/kafka/commit/db3e5e2c0de367ffcfe4078359d6d208ba722581#diff-eeafed82ed6a8600c397b108787fdf31e03191b0a192774a65c127d0d26edc44R2341]
when flush dir was added.
was:
We are using a Kafka cluster with Zookeeper, deployed on top of Kubernetes,
using banzaicloud/koperator.
We have multiple disks per broker.
We are using Cruise Control remove disk operation in order to aggregate
multiple smaller disks into a single bigger disk.
When we do this, *the flush operation fails apparently randomly with
NoSuchFileException, while alterReplicaLogDirs is executed*. Attached a sample
of logs for the exception and the previous operations taking place.
Will further detail the cause of this issue.
Say we have 3 brokers:
* broker 101 with disks /kafka-logs1/kafka, /kafka-logs2/kafka and a bigger
disk /new-kafka-logs1/kafka
* broker 201 with same disks
* broker 301 with same disks
When Cruise Control executes a remove disk operation, it calls Kafka
"adminClient.alterReplicaLogDirs(replicaAssignment)" with such an assignment as
to move all data from /kafka-logs1/kafka and /kafka-logs2/kafka to
/new-kafka-logs1/kafka.
During the alter log dir operation, future logs are created (to move data from
e.g. "/kafka-logs1/kafka/topic-partition" to
"/new-kafka-logs1/kafka/topic-partition.hash-future"), data is moved and
finally the log dir will be renamed from
"/new-kafka-logs1/kafka/topic-partition.hash-future" to
"/new-kafka-logs1/kafka/topic-partition". This operation is started in
[UnifiedLog.renameDir|https://github.com/apache/kafka/blob/3.4/core/src/main/scala/kafka/log/UnifiedLog.scala#L713]
and is locked using the [UnifiedLog
lock|https://github.com/apache/kafka/blob/3.4/core/src/main/scala/kafka/log/UnifiedLog.scala#L268].
The rename is then delegated to
[LocalLog.renameDir|https://github.com/apache/kafka/blob/3.4/core/src/main/scala/kafka/log/LocalLog.scala#L111-L113].
This is the 1st code part that is involved in the race condition.
Meanwhile, log dirs can be rolled based on known conditions (e.g. getting
full), which will call
[UnifiedLog.roll|https://github.com/apache/kafka/blob/3.4/core/src/main/scala/kafka/log/UnifiedLog.scala#L1547],
which is locked using the [UnifiedLog
lock|https://github.com/apache/kafka/blob/3.4/core/src/main/scala/kafka/log/UnifiedLog.scala#L268].
However, the further delegation to UnifiedLog.flushUptoOffsetExclusive is not
sharing that lock, since it is done as a scheduled task in a separate thread.
This means that further operations are [not locked at UnifiedLog
level|https://github.com/apache/kafka/blob/3.4/core/src/main/scala/kafka/log/UnifiedLog.scala#L268].
The operation is further delegated to
[LocalLog.flush|https://github.com/apache/kafka/blob/3.4/core/src/main/scala/kafka/log/LocalLog.scala#L177],
which will also try to [flush the log
dir|https://github.com/apache/kafka/blob/3.4/core/src/main/scala/kafka/log/LocalLog.scala#L177].
This is the 2nd code part that is involved in the race condition.
Since the log dir flush does not share the lock with the rename dir operation
(as it is scheduled via the scheduler), the rename dir operation might succeed
in moving the log dir on disk to "topic-partition", but the LocalLog._dir will
remain set to "topic-partition.hash-future", and when the flush will attempt to
flush the "topic-partition.hash-future" directory, it will throw
NoSuchFileException: "topic-partition.hash-future". Basically, [this
line|https://github.com/apache/kafka/blob/3.4/core/src/main/scala/kafka/log/LocalLog.scala#L111]
might succeed, and before [this other
line|https://github.com/apache/kafka/blob/3.4/core/src/main/scala/kafka/log/LocalLog.scala#L111]
is executed, flush tries to [flush the future
dir|https://github.com/apache/kafka/blob/3.4/core/src/main/scala/kafka/log/LocalLog.scala#L177].
We tested a fix with a patch on Kafka 3.4.1, on our clusters and it solved the
issue by synchronizing the flush dir operation. Will reply with a link to a PR.
Note that this bug replicates for every version since 3.0.0, caused by [this
commit|https://github.com/apache/kafka/commit/db3e5e2c0de367ffcfe4078359d6d208ba722581#diff-eeafed82ed6a8600c397b108787fdf31e03191b0a192774a65c127d0d26edc44R2341]
when flush dir was added.
> Race condition between future log dir roll and replace current with future
> log during alterReplicaLogDirs
> ---------------------------------------------------------------------------------------------------------
>
> Key: KAFKA-15572
> URL: https://issues.apache.org/jira/browse/KAFKA-15572
> Project: Kafka
> Issue Type: Bug
> Components: core
> Affects Versions: 3.3.1, 3.4.1
> Reporter: Lucian Ilie
> Priority: Major
> Attachments: kafka-alter-log-dir-nosuchfileexception.log
>
> Original Estimate: 48h
> Remaining Estimate: 48h
>
> We are using a Kafka cluster with Zookeeper, deployed on top of Kubernetes,
> using banzaicloud/koperator.
> We have multiple disks per broker.
> We are using Cruise Control remove disk operation in order to aggregate
> multiple smaller disks into a single bigger disk.
> When we do this, *the flush operation fails apparently randomly with
> NoSuchFileException, while alterReplicaLogDirs is executed*. Attached a
> sample of logs for the exception and the previous operations taking place.
> Will further detail the cause of this issue.
> Say we have 3 brokers:
> * broker 101 with disks /kafka-logs1/kafka, /kafka-logs2/kafka and a bigger
> disk /new-kafka-logs1/kafka
> * broker 201 with same disks
> * broker 301 with same disks
> When Cruise Control executes a remove disk operation, it calls Kafka
> "adminClient.alterReplicaLogDirs(replicaAssignment)" with such an assignment
> as to move all data from /kafka-logs1/kafka and /kafka-logs2/kafka to
> /new-kafka-logs1/kafka.
> During the alter log dir operation, future logs are created (to move data
> from e.g. "/kafka-logs1/kafka/topic-partition" to
> "/new-kafka-logs1/kafka/topic-partition.hash-future"), data is moved and
> finally the log dir will be renamed from
> "/new-kafka-logs1/kafka/topic-partition.hash-future" to
> "/new-kafka-logs1/kafka/topic-partition". This operation is started in
> [UnifiedLog.renameDir|https://github.com/apache/kafka/blob/3.4/core/src/main/scala/kafka/log/UnifiedLog.scala#L713]
> and is locked using the [UnifiedLog
> lock|https://github.com/apache/kafka/blob/3.4/core/src/main/scala/kafka/log/UnifiedLog.scala#L268].
> The rename is then delegated to
> [LocalLog.renameDir|https://github.com/apache/kafka/blob/3.4/core/src/main/scala/kafka/log/LocalLog.scala#L111-L113].
> This is the 1st code part that is involved in the race condition.
> Meanwhile, log dirs can be rolled based on known conditions (e.g. getting
> full), which will call
> [UnifiedLog.roll|https://github.com/apache/kafka/blob/3.4/core/src/main/scala/kafka/log/UnifiedLog.scala#L1547],
> which is locked using the [UnifiedLog
> lock|https://github.com/apache/kafka/blob/3.4/core/src/main/scala/kafka/log/UnifiedLog.scala#L268].
> However, the further delegation to UnifiedLog.flushUptoOffsetExclusive is
> not sharing that lock, since it is [done as a scheduled task in a separate
> thread|https://github.com/apache/kafka/blob/3.4/core/src/main/scala/kafka/log/UnifiedLog.scala#L1547].
> This means that further operations are [not locked at UnifiedLog
> level|https://github.com/apache/kafka/blob/3.4/core/src/main/scala/kafka/log/UnifiedLog.scala#L268].
> The operation is further delegated to
> [LocalLog.flush|https://github.com/apache/kafka/blob/3.4/core/src/main/scala/kafka/log/LocalLog.scala#L177],
> which will also try to [flush the log
> dir|https://github.com/apache/kafka/blob/3.4/core/src/main/scala/kafka/log/LocalLog.scala#L177].
> This is the 2nd code part that is involved in the race condition.
> Since the log dir flush does not share the lock with the rename dir operation
> (as it is scheduled via the scheduler), the rename dir operation might
> succeed in moving the log dir on disk to "topic-partition", but the
> LocalLog._dir will remain set to "topic-partition.hash-future", and when the
> flush will attempt to flush the "topic-partition.hash-future" directory, it
> will throw NoSuchFileException: "topic-partition.hash-future". Basically,
> [this
> line|https://github.com/apache/kafka/blob/3.4/core/src/main/scala/kafka/log/LocalLog.scala#L111]
> might succeed, and before [this other
> line|https://github.com/apache/kafka/blob/3.4/core/src/main/scala/kafka/log/LocalLog.scala#L111]
> is executed, flush tries to [flush the future
> dir|https://github.com/apache/kafka/blob/3.4/core/src/main/scala/kafka/log/LocalLog.scala#L177].
> We tested a fix with a patch on Kafka 3.4.1, on our clusters and it solved
> the issue by synchronizing the flush dir operation. Will reply with a link to
> a PR.
> Note that this bug replicates for every version since 3.0.0, caused by [this
> commit|https://github.com/apache/kafka/commit/db3e5e2c0de367ffcfe4078359d6d208ba722581#diff-eeafed82ed6a8600c397b108787fdf31e03191b0a192774a65c127d0d26edc44R2341]
> when flush dir was added.
--
This message was sent by Atlassian Jira
(v8.20.10#820010)
