[ 
https://issues.apache.org/jira/browse/KAFKA-17727?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
 ]

David Jacot updated KAFKA-17727:
--------------------------------
    Fix Version/s: 4.1.0
                       (was: 4.0.0)

> Log dirs marked as offline incorrectly due to race conditions on segment 
> delete
> -------------------------------------------------------------------------------
>
>                 Key: KAFKA-17727
>                 URL: https://issues.apache.org/jira/browse/KAFKA-17727
>             Project: Kafka
>          Issue Type: Bug
>          Components: core
>    Affects Versions: 3.5.2
>            Reporter: Luciano Sabença
>            Assignee: Gaurav Narula
>            Priority: Major
>             Fix For: 4.1.0
>
>
> We are using a kafka cluster deployed on-premise. The brokers are JBOD with 
> around 5/6 disks per broker. When running a intra broker rebalance (ie moving 
> partitions between the log dirs) triggered by cruise-control, some nodes had 
> a log dir marked as offline. When we looked closed the disk was normal and 
> with a broker restart the log dir became online again. 
> Investigating the issue, it's seems very similar to KAFKA-15391 and, 
> specially, with KAFKA-15572. The main difference on the logs between the 
> issue we encountered and the one described at KAFKA-15572 is that there the 
> exception that marked the log dir as offline was a 
> `java.nio.file.NoSuchFileException`. In our case, we had a 
> `java.nio.channels.ClosedChannelException`:
> {noformat}
> [2024-10-03 09:48:04,704] ERROR Error while flushing log for mytopic-20 in 
> dir /data/0/kafka with offset 844857727 (exclusive) and recovery point 
> 844857727 (org.apache.kafka.storage.internals.log.LogDirFailureChannel)
> java.nio.channels.ClosedChannelException
> at java.base/sun.nio.ch.FileChannelImpl.ensureOpen(FileChannelImpl.java:150)
> at java.base/sun.nio.ch.FileChannelImpl.force(FileChannelImpl.java:452)
> at org.apache.kafka.common.record.FileRecords.flush(FileRecords.java:197)
> at kafka.log.LogSegment.$anonfun$flush$1(LogSegment.scala:471)
> at kafka.log.LogSegment.$anonfun$flush$1$adapted(LogSegment.scala:470)
> at com.yammer.metrics.core.Timer.time(Timer.java:91)
> at kafka.log.LogSegment.flush(LogSegment.scala:470)
> at kafka.log.LocalLog.$anonfun$flush$1(LocalLog.scala:174)
> at kafka.log.LocalLog.$anonfun$flush$1$adapted(LocalLog.scala:174)
> at scala.collection.IterableOnceOps.foreach(IterableOnce.scala:575)
> at scala.collection.IterableOnceOps.foreach$(IterableOnce.scala:573)
> at scala.collection.AbstractIterable.foreach(Iterable.scala:933)
> at kafka.log.LocalLog.flush(LocalLog.scala:174)
> at kafka.log.UnifiedLog.$anonfun$flush$2(UnifiedLog.scala:1537)
> at kafka.log.UnifiedLog.flush(UnifiedLog.scala:1724)
> at kafka.log.UnifiedLog.flushUptoOffsetExclusive(UnifiedLog.scala:1518)
> at kafka.log.UnifiedLog.$anonfun$roll$1(UnifiedLog.scala:1499)
> at 
> org.apache.kafka.server.util.KafkaScheduler.lambda$schedule$1(KafkaScheduler.java:150)
> at 
> java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
> at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
> at 
> java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304)
> at 
> java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
> at 
> java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
> at java.base/java.lang.Thread.run(Thread.java:829){noformat}
> Investigating kafka code, I believe the root cause is very similar to the one 
> KAFKA-15572(https://issues.apache.org/jira/browse/KAFKA-15572). In our case, 
> we can see via logs that LogManager.scala was able to replace the old log 
> with the new one: 
> {noformat}
> [2024-10-03 09:47:06,349] INFO Attempting to replace current log 
> Log(dir=/data/0/kafka/mytopic-20, topicId=jl0IzzqWSHedIunbTLziYg, 
> topic=mytopic, partition=20, highWatermark=844861246, 
> lastStableOffset=844861246, logStartOffset=842164116, logEndOffset=844861247) 
> with 
> Log(dir=/data/5/kafka/mytopic-20.9fa1dfec1c4a4045b8806565eced19bd-future, 
> topicId=jl0IzzqWSHedIunbTLziYg, topic=mytopic, partition=20, 
> highWatermark=844861246, lastStableOffset=844861246, 
> logStartOffset=842164116, logEndOffset=844861247) for mytopic-20 
> (kafka.log.LogManager)
> INFO Cleaning for partition mytopic-20 is resumed (kafka.log.LogManager)
> [2024-10-03 09:47:06,364] INFO The current replica is successfully replaced 
> with the future replica for mytopic-20 (kafka.log.LogManager){noformat}
> During this process, it closes the old log ([LogManager.scala#L1125|#L1125]) 
> and schedule if it to be deleted.  Something triggers 
> [UnifiedLog.roll|#L1499] and anything that triggers flush after that for this 
> segment will eventually call _LocalLog.flush_ which will try to close each 
> segment to flush 
> [[LocalLog.scala#L174|https://github.com/apache/kafka/blob/8f0b0b0d0466632b47c355489e7c9440f3e4c0f5/core/src/main/scala/kafka/log/LocalLog.scala#L174).]
>  Here, however, the segment is already closed and thus the exception. It's 
> not clear to me what triggers the roll. In theory the old log was already 
> replaced and the only thing remaining for this old segments it to be deleted. 
> As this is a high volume topic, however, it's not surprising to have segments 
> rolling frequently. 



--
This message was sent by Atlassian Jira
(v8.20.10#820010)

Reply via email to