[
https://issues.apache.org/jira/browse/KAFKA-8172?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Bharat Kondeti updated KAFKA-8172:
----------------------------------
Description:
Fix to close file handlers before renaming files / directories and open them
back if required
Following are the file renaming scenarios:
* Files are renamed to .deleted so they can be deleted
* .cleaned files are renamed to .swap as part of Log.replaceSegments flow
* .swap files are renamed to original files as part of Log.replaceSegments flow
Following are the folder renaming scenarios:
* When a topic is marked for deletion, folder is renamed
* As part of replacing current logs with future logs in LogManager
In above scenarios, if file handles are not closed, we get file access
violation exception
Idea is to close the logs and file segments before doing a rename and open them
back up if required.
*Segments Deletion Scenario*
[2018-06-01 17:00:07,566] ERROR Error while deleting segments for test4-1 in
dir D:\data\Kafka\kafka-logs (kafka.server.LogDirFailureChannel)
java.nio.file.FileSystemException:
D:\data\Kafka\kafka-logs\test4-1\00000000000000000000.log ->
D:\data\Kafka\kafka-logs\test4-1\00000000000000000000.log.deleted: The process
cannot access the file because it is being used by another process.
at sun.nio.fs.WindowsException.translateToIOException(WindowsException.java:86)
at sun.nio.fs.WindowsException.rethrowAsIOException(WindowsException.java:97)
at sun.nio.fs.WindowsFileCopy.move(WindowsFileCopy.java:387)
at
sun.nio.fs.WindowsFileSystemProvider.move(WindowsFileSystemProvider.java:287)
at java.nio.file.Files.move(Files.java:1395)
at org.apache.kafka.common.utils.Utils.atomicMoveWithFallback(Utils.java:697)
at org.apache.kafka.common.record.FileRecords.renameTo(FileRecords.java:212)
at kafka.log.LogSegment.changeFileSuffixes(LogSegment.scala:415)
at kafka.log.Log.kafka$log$Log$$asyncDeleteSegment(Log.scala:1601)
at kafka.log.Log.kafka$log$Log$$deleteSegment(Log.scala:1588)
at
kafka.log.Log$$anonfun$deleteSegments$1$$anonfun$apply$mcI$sp$1.apply(Log.scala:1170)
at
kafka.log.Log$$anonfun$deleteSegments$1$$anonfun$apply$mcI$sp$1.apply(Log.scala:1170)
at
scala.collection.mutable.ResizableArray$class.foreach(ResizableArray.scala:59)
at scala.collection.mutable.ArrayBuffer.foreach(ArrayBuffer.scala:48)
at kafka.log.Log$$anonfun$deleteSegments$1.apply$mcI$sp(Log.scala:1170)
at kafka.log.Log$$anonfun$deleteSegments$1.apply(Log.scala:1161)
at kafka.log.Log$$anonfun$deleteSegments$1.apply(Log.scala:1161)
at kafka.log.Log.maybeHandleIOException(Log.scala:1678)
at kafka.log.Log.deleteSegments(Log.scala:1161)
at kafka.log.Log.deleteOldSegments(Log.scala:1156)
at kafka.log.Log.deleteRetentionMsBreachedSegments(Log.scala:1228)
at kafka.log.Log.deleteOldSegments(Log.scala:1222)
at kafka.log.LogManager$$anonfun$cleanupLogs$3.apply(LogManager.scala:854)
at kafka.log.LogManager$$anonfun$cleanupLogs$3.apply(LogManager.scala:852)
at
scala.collection.TraversableLike$WithFilter$$anonfun$foreach$1.apply(TraversableLike.scala:733)
at scala.collection.immutable.List.foreach(List.scala:392)
at
scala.collection.TraversableLike$WithFilter.foreach(TraversableLike.scala:732)
at kafka.log.LogManager.cleanupLogs(LogManager.scala:852)
at kafka.log.LogManager$$anonfun$startup$1.apply$mcV$sp(LogManager.scala:385)
at kafka.utils.KafkaScheduler$$anonfun$1.apply$mcV$sp(KafkaScheduler.scala:110)
at kafka.utils.CoreUtils$$anon$1.run(CoreUtils.scala:62)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308)
at
java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180)
at
java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:748)
Suppressed: java.nio.file.FileSystemException:
D:\data\Kafka\kafka-logs\test4-1\00000000000000000000.log ->
D:\data\Kafka\kafka-logs\test4-1\00000000000000000000.log.deleted: The process
cannot access the file because it is being used by another process.
at sun.nio.fs.WindowsException.translateToIOException(WindowsException.java:86)
at sun.nio.fs.WindowsException.rethrowAsIOException(WindowsException.java:97)
at sun.nio.fs.WindowsFileCopy.move(WindowsFileCopy.java:301)
at
sun.nio.fs.WindowsFileSystemProvider.move(WindowsFileSystemProvider.java:287)
at java.nio.file.Files.move(Files.java:1395)
at org.apache.kafka.common.utils.Utils.atomicMoveWithFallback(Utils.java:694)
... 32 more
*Topic deletion scenario*
2018-06-07 15:05:17,805] ERROR Error while renaming dir for test5-1 in log dir
D:\data\Kafka\kafka-logs (kafka.server.LogDirFailureChannel)
java.nio.file.AccessDeniedException: D:\data\Kafka\kafka-logs\test5-1 ->
D:\data\Kafka\kafka-logs\test5-1.87985bad40e441e1a4d08af4541db7ce-delete
at sun.nio.fs.WindowsException.translateToIOException(WindowsException.java:83)
at sun.nio.fs.WindowsException.rethrowAsIOException(WindowsException.java:97)
at sun.nio.fs.WindowsFileCopy.move(WindowsFileCopy.java:387)
at
sun.nio.fs.WindowsFileSystemProvider.move(WindowsFileSystemProvider.java:287)
at java.nio.file.Files.move(Files.java:1395)
at org.apache.kafka.common.utils.Utils.atomicMoveWithFallback(Utils.java:697)
at kafka.log.Log$$anonfun$renameDir$1.apply$mcV$sp(Log.scala:579)
at kafka.log.Log$$anonfun$renameDir$1.apply(Log.scala:577)
at kafka.log.Log$$anonfun$renameDir$1.apply(Log.scala:577)
at kafka.log.Log.maybeHandleIOException(Log.scala:1678)
at kafka.log.Log.renameDir(Log.scala:577)
at kafka.log.LogManager.asyncDelete(LogManager.scala:813)
at kafka.cluster.Partition$$anonfun$delete$1.apply(Partition.scala:240)
at kafka.cluster.Partition$$anonfun$delete$1.apply(Partition.scala:235)
at kafka.utils.CoreUtils$.inLock(CoreUtils.scala:250)
at kafka.utils.CoreUtils$.inWriteLock(CoreUtils.scala:258)
at kafka.cluster.Partition.delete(Partition.scala:235)
at kafka.server.ReplicaManager.stopReplica(ReplicaManager.scala:347)
at
kafka.server.ReplicaManager$$anonfun$stopReplicas$2.apply(ReplicaManager.scala:377)
at
kafka.server.ReplicaManager$$anonfun$stopReplicas$2.apply(ReplicaManager.scala:375)
at scala.collection.Iterator$class.foreach(Iterator.scala:891)
at scala.collection.AbstractIterator.foreach(Iterator.scala:1334)
at scala.collection.IterableLike$class.foreach(IterableLike.scala:72)
at scala.collection.AbstractIterable.foreach(Iterable.scala:54)
at kafka.server.ReplicaManager.stopReplicas(ReplicaManager.scala:375)
at kafka.server.KafkaApis.handleStopReplicaRequest(KafkaApis.scala:198)
at kafka.server.KafkaApis.handle(KafkaApis.scala:109)
at kafka.server.KafkaRequestHandler.run(KafkaRequestHandler.scala:69)
at java.lang.Thread.run(Thread.java:748)
Suppressed: java.nio.file.AccessDeniedException:
D:\data\Kafka\kafka-logs\test5-1 ->
D:\data\Kafka\kafka-logs\test5-1.87985bad40e441e1a4d08af4541db7ce-delete
at sun.nio.fs.WindowsException.translateToIOException(WindowsException.java:83)
at sun.nio.fs.WindowsException.rethrowAsIOException(WindowsException.java:97)
at sun.nio.fs.WindowsFileCopy.move(WindowsFileCopy.java:301)
at
sun.nio.fs.WindowsFileSystemProvider.move(WindowsFileSystemProvider.java:287)
at java.nio.file.Files.move(Files.java:1395)
at org.apache.kafka.common.utils.Utils.atomicMoveWithFallback(Utils.java:694)
... 23 more
*File Compaction Scenario*
[2019-03-11 16:02:00,021] ERROR Error while loading log dir
D:\data\Kafka\kafka-datalogs (kafka.log.LogManager)
java.nio.file.FileSystemException:
D:\data\Kafka\kafka-datalogs\kattesttopic-23\00000000000003505795.log: The
process cannot access the file because it is being used by another process.
at sun.nio.fs.WindowsException.translateToIOException(WindowsException.java:86)
at sun.nio.fs.WindowsException.rethrowAsIOException(WindowsException.java:97)
at sun.nio.fs.WindowsException.rethrowAsIOException(WindowsException.java:102)
at sun.nio.fs.WindowsFileCopy.move(WindowsFileCopy.java:376)
at
sun.nio.fs.WindowsFileSystemProvider.move(WindowsFileSystemProvider.java:287)
at java.nio.file.Files.move(Files.java:1395)
at org.apache.kafka.common.utils.Utils.atomicMoveWithFallback(Utils.java:697)
at org.apache.kafka.common.record.FileRecords.renameTo(FileRecords.java:223)
at kafka.log.LogSegment.changeFileSuffixes(LogSegment.scala:415)
at kafka.log.Log.replaceSegments(Log.scala:1697)
at kafka.log.Log$$anonfun$completeSwapOperations$1.apply(Log.scala:391)
at kafka.log.Log$$anonfun$completeSwapOperations$1.apply(Log.scala:380)
at scala.collection.immutable.Set$Set1.foreach(Set.scala:94)
at kafka.log.Log.completeSwapOperations(Log.scala:380)
at kafka.log.Log.loadSegments(Log.scala:408)
at kafka.log.Log.<init>(Log.scala:216)
at kafka.log.Log$.apply(Log.scala:1788)
at kafka.log.LogManager.kafka$log$LogManager$$loadLog(LogManager.scala:260)
at
kafka.log.LogManager$$anonfun$loadLogs$2$$anonfun$11$$anonfun$apply$15$$anonfun$apply$2.apply$mcV$sp(LogManager.scala:340)
at kafka.utils.CoreUtils$$anon$1.run(CoreUtils.scala:62)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:748)
Suppressed: java.nio.file.AccessDeniedException:
D:\data\Kafka\kafka-datalogs\kattesttopic-23\00000000000003505795.log.swap ->
D:\data\Kafka\kafka-datalogs\kattesttopic-23\00000000000003505795.log
at sun.nio.fs.WindowsException.translateToIOException(WindowsException.java:83)
at sun.nio.fs.WindowsException.rethrowAsIOException(WindowsException.java:97)
at sun.nio.fs.WindowsFileCopy.move(WindowsFileCopy.java:301)
at
sun.nio.fs.WindowsFileSystemProvider.move(WindowsFileSystemProvider.java:287)
at java.nio.file.Files.move(Files.java:1395)
at org.apache.kafka.common.utils.Utils.atomicMoveWithFallback(Utils.java:694)
... 18 more
was:
Fix to close file handlers before renaming files / directories and open them
back if required
Following are the file renaming scenarios:
* Files are renamed to .deleted so they can be deleted
* .cleaned files are renamed to .swap as part of Log.replaceSegments flow
* .swap files are renamed to original files as part of Log.replaceSegments flow
Following are the folder renaming scenarios:
* When a topic is marked for deletion, folder is renamed
* As part of replacing current logs with future logs in LogManager
In above scenarios, if file handles are not closed, we get file access
violation exception
Idea is to close the logs and file segments before doing a rename and open them
back up if required.
*Segments Deletion Scenario*
[2018-06-01 17:00:07,566] ERROR Error while deleting segments for test4-1 in
dir D:\data\Kafka\kafka-logs (kafka.server.LogDirFailureChannel)
java.nio.file.FileSystemException:
D:\data\Kafka\kafka-logs\test4-1\00000000000000000000.log ->
D:\data\Kafka\kafka-logs\test4-1\00000000000000000000.log.deleted: The process
cannot access the file because it is being used by another process.
at sun.nio.fs.WindowsException.translateToIOException(WindowsException.java:86)
at sun.nio.fs.WindowsException.rethrowAsIOException(WindowsException.java:97)
at sun.nio.fs.WindowsFileCopy.move(WindowsFileCopy.java:387)
at
sun.nio.fs.WindowsFileSystemProvider.move(WindowsFileSystemProvider.java:287)
at java.nio.file.Files.move(Files.java:1395)
at org.apache.kafka.common.utils.Utils.atomicMoveWithFallback(Utils.java:697)
at org.apache.kafka.common.record.FileRecords.renameTo(FileRecords.java:212)
at kafka.log.LogSegment.changeFileSuffixes(LogSegment.scala:415)
at kafka.log.Log.kafka$log$Log$$asyncDeleteSegment(Log.scala:1601)
at kafka.log.Log.kafka$log$Log$$deleteSegment(Log.scala:1588)
at
kafka.log.Log$$anonfun$deleteSegments$1$$anonfun$apply$mcI$sp$1.apply(Log.scala:1170)
at
kafka.log.Log$$anonfun$deleteSegments$1$$anonfun$apply$mcI$sp$1.apply(Log.scala:1170)
at
scala.collection.mutable.ResizableArray$class.foreach(ResizableArray.scala:59)
at scala.collection.mutable.ArrayBuffer.foreach(ArrayBuffer.scala:48)
at kafka.log.Log$$anonfun$deleteSegments$1.apply$mcI$sp(Log.scala:1170)
at kafka.log.Log$$anonfun$deleteSegments$1.apply(Log.scala:1161)
at kafka.log.Log$$anonfun$deleteSegments$1.apply(Log.scala:1161)
at kafka.log.Log.maybeHandleIOException(Log.scala:1678)
at kafka.log.Log.deleteSegments(Log.scala:1161)
at kafka.log.Log.deleteOldSegments(Log.scala:1156)
at kafka.log.Log.deleteRetentionMsBreachedSegments(Log.scala:1228)
at kafka.log.Log.deleteOldSegments(Log.scala:1222)
at kafka.log.LogManager$$anonfun$cleanupLogs$3.apply(LogManager.scala:854)
at kafka.log.LogManager$$anonfun$cleanupLogs$3.apply(LogManager.scala:852)
at
scala.collection.TraversableLike$WithFilter$$anonfun$foreach$1.apply(TraversableLike.scala:733)
at scala.collection.immutable.List.foreach(List.scala:392)
at
scala.collection.TraversableLike$WithFilter.foreach(TraversableLike.scala:732)
at kafka.log.LogManager.cleanupLogs(LogManager.scala:852)
at kafka.log.LogManager$$anonfun$startup$1.apply$mcV$sp(LogManager.scala:385)
at kafka.utils.KafkaScheduler$$anonfun$1.apply$mcV$sp(KafkaScheduler.scala:110)
at kafka.utils.CoreUtils$$anon$1.run(CoreUtils.scala:62)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308)
at
java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180)
at
java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:748)
Suppressed: java.nio.file.FileSystemException:
D:\data\Kafka\kafka-logs\test4-1\00000000000000000000.log ->
D:\data\Kafka\kafka-logs\test4-1\00000000000000000000.log.deleted: The process
cannot access the file because it is being used by another process.
at sun.nio.fs.WindowsException.translateToIOException(WindowsException.java:86)
at sun.nio.fs.WindowsException.rethrowAsIOException(WindowsException.java:97)
at sun.nio.fs.WindowsFileCopy.move(WindowsFileCopy.java:301)
at
sun.nio.fs.WindowsFileSystemProvider.move(WindowsFileSystemProvider.java:287)
at java.nio.file.Files.move(Files.java:1395)
at org.apache.kafka.common.utils.Utils.atomicMoveWithFallback(Utils.java:694)
... 32 more
*Topic deletion scenario*
2018-06-07 15:05:17,805] ERROR Error while renaming dir for test5-1 in log dir
D:\data\Kafka\kafka-logs (kafka.server.LogDirFailureChannel)
java.nio.file.AccessDeniedException: D:\data\Kafka\kafka-logs\test5-1 ->
D:\data\Kafka\kafka-logs\test5-1.87985bad40e441e1a4d08af4541db7ce-delete
at sun.nio.fs.WindowsException.translateToIOException(WindowsException.java:83)
at sun.nio.fs.WindowsException.rethrowAsIOException(WindowsException.java:97)
at sun.nio.fs.WindowsFileCopy.move(WindowsFileCopy.java:387)
at
sun.nio.fs.WindowsFileSystemProvider.move(WindowsFileSystemProvider.java:287)
at java.nio.file.Files.move(Files.java:1395)
at org.apache.kafka.common.utils.Utils.atomicMoveWithFallback(Utils.java:697)
at kafka.log.Log$$anonfun$renameDir$1.apply$mcV$sp(Log.scala:579)
at kafka.log.Log$$anonfun$renameDir$1.apply(Log.scala:577)
at kafka.log.Log$$anonfun$renameDir$1.apply(Log.scala:577)
at kafka.log.Log.maybeHandleIOException(Log.scala:1678)
at kafka.log.Log.renameDir(Log.scala:577)
at kafka.log.LogManager.asyncDelete(LogManager.scala:813)
at kafka.cluster.Partition$$anonfun$delete$1.apply(Partition.scala:240)
at kafka.cluster.Partition$$anonfun$delete$1.apply(Partition.scala:235)
at kafka.utils.CoreUtils$.inLock(CoreUtils.scala:250)
at kafka.utils.CoreUtils$.inWriteLock(CoreUtils.scala:258)
at kafka.cluster.Partition.delete(Partition.scala:235)
at kafka.server.ReplicaManager.stopReplica(ReplicaManager.scala:347)
at
kafka.server.ReplicaManager$$anonfun$stopReplicas$2.apply(ReplicaManager.scala:377)
at
kafka.server.ReplicaManager$$anonfun$stopReplicas$2.apply(ReplicaManager.scala:375)
at scala.collection.Iterator$class.foreach(Iterator.scala:891)
at scala.collection.AbstractIterator.foreach(Iterator.scala:1334)
at scala.collection.IterableLike$class.foreach(IterableLike.scala:72)
at scala.collection.AbstractIterable.foreach(Iterable.scala:54)
at kafka.server.ReplicaManager.stopReplicas(ReplicaManager.scala:375)
at kafka.server.KafkaApis.handleStopReplicaRequest(KafkaApis.scala:198)
at kafka.server.KafkaApis.handle(KafkaApis.scala:109)
at kafka.server.KafkaRequestHandler.run(KafkaRequestHandler.scala:69)
at java.lang.Thread.run(Thread.java:748)
Suppressed: java.nio.file.AccessDeniedException:
D:\data\Kafka\kafka-logs\test5-1 ->
D:\data\Kafka\kafka-logs\test5-1.87985bad40e441e1a4d08af4541db7ce-delete
at sun.nio.fs.WindowsException.translateToIOException(WindowsException.java:83)
at sun.nio.fs.WindowsException.rethrowAsIOException(WindowsException.java:97)
at sun.nio.fs.WindowsFileCopy.move(WindowsFileCopy.java:301)
at
sun.nio.fs.WindowsFileSystemProvider.move(WindowsFileSystemProvider.java:287)
at java.nio.file.Files.move(Files.java:1395)
at org.apache.kafka.common.utils.Utils.atomicMoveWithFallback(Utils.java:694)
... 23 more
*File Compaction Scenario*
[2019-03-11 16:02:00,021] ERROR Error while loading log dir
D:\data\Kafka\kafka-datalogs (kafka.log.LogManager)
java.nio.file.FileSystemException:
D:\data\Kafka\kafka-datalogs\kattesttopic-23\00000000000003505795.log: The
process cannot access the file because it is being used by another process.
at sun.nio.fs.WindowsException.translateToIOException(WindowsException.java:86)
at sun.nio.fs.WindowsException.rethrowAsIOException(WindowsException.java:97)
at sun.nio.fs.WindowsException.rethrowAsIOException(WindowsException.java:102)
at sun.nio.fs.WindowsFileCopy.move(WindowsFileCopy.java:376)
at
sun.nio.fs.WindowsFileSystemProvider.move(WindowsFileSystemProvider.java:287)
at java.nio.file.Files.move(Files.java:1395)
at org.apache.kafka.common.utils.Utils.atomicMoveWithFallback(Utils.java:697)
at org.apache.kafka.common.record.FileRecords.renameTo(FileRecords.java:223)
at kafka.log.LogSegment.changeFileSuffixes(LogSegment.scala:415)
at kafka.log.Log.replaceSegments(Log.scala:1697)
at kafka.log.Log$$anonfun$completeSwapOperations$1.apply(Log.scala:391)
at kafka.log.Log$$anonfun$completeSwapOperations$1.apply(Log.scala:380)
at scala.collection.immutable.Set$Set1.foreach(Set.scala:94)
at kafka.log.Log.completeSwapOperations(Log.scala:380)
at kafka.log.Log.loadSegments(Log.scala:408)
at kafka.log.Log.<init>(Log.scala:216)
at kafka.log.Log$.apply(Log.scala:1788)
at kafka.log.LogManager.kafka$log$LogManager$$loadLog(LogManager.scala:260)
at
kafka.log.LogManager$$anonfun$loadLogs$2$$anonfun$11$$anonfun$apply$15$$anonfun$apply$2.apply$mcV$sp(LogManager.scala:340)
at kafka.utils.CoreUtils$$anon$1.run(CoreUtils.scala:62)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:748)
Suppressed: java.nio.file.AccessDeniedException:
D:\data\Kafka\kafka-datalogs\kattesttopic-23\00000000000003505795.log.swap ->
D:\data\Kafka\kafka-datalogs\kattesttopic-23\00000000000003505795.log
at sun.nio.fs.WindowsException.translateToIOException(WindowsException.java:83)
at sun.nio.fs.WindowsException.rethrowAsIOException(WindowsException.java:97)
at sun.nio.fs.WindowsFileCopy.move(WindowsFileCopy.java:301)
at
sun.nio.fs.WindowsFileSystemProvider.move(WindowsFileSystemProvider.java:287)
at java.nio.file.Files.move(Files.java:1395)
at org.apache.kafka.common.utils.Utils.atomicMoveWithFallback(Utils.java:694)
... 18 more
> FileSystemException: The process cannot access the file because it is being
> used by another process
> ---------------------------------------------------------------------------------------------------
>
> Key: KAFKA-8172
> URL: https://issues.apache.org/jira/browse/KAFKA-8172
> Project: Kafka
> Issue Type: Bug
> Components: core
> Affects Versions: 1.1.1, 2.2.0, 2.1.1
> Environment: Windows
> Reporter: Bharat Kondeti
> Priority: Major
> Fix For: 1.1.1, 2.2.0, 2.1.1
>
> Attachments:
> 0001-Fix-to-close-the-handlers-before-renaming-files-and-.patch
>
>
> Fix to close file handlers before renaming files / directories and open them
> back if required
> Following are the file renaming scenarios:
> * Files are renamed to .deleted so they can be deleted
> * .cleaned files are renamed to .swap as part of Log.replaceSegments flow
> * .swap files are renamed to original files as part of Log.replaceSegments
> flow
> Following are the folder renaming scenarios:
> * When a topic is marked for deletion, folder is renamed
> * As part of replacing current logs with future logs in LogManager
> In above scenarios, if file handles are not closed, we get file access
> violation exception
> Idea is to close the logs and file segments before doing a rename and open
> them back up if required.
> *Segments Deletion Scenario*
> [2018-06-01 17:00:07,566] ERROR Error while deleting segments for test4-1 in
> dir D:\data\Kafka\kafka-logs (kafka.server.LogDirFailureChannel)
> java.nio.file.FileSystemException:
> D:\data\Kafka\kafka-logs\test4-1\00000000000000000000.log ->
> D:\data\Kafka\kafka-logs\test4-1\00000000000000000000.log.deleted: The
> process cannot access the file because it is being used by another process.
> at
> sun.nio.fs.WindowsException.translateToIOException(WindowsException.java:86)
> at sun.nio.fs.WindowsException.rethrowAsIOException(WindowsException.java:97)
> at sun.nio.fs.WindowsFileCopy.move(WindowsFileCopy.java:387)
> at
> sun.nio.fs.WindowsFileSystemProvider.move(WindowsFileSystemProvider.java:287)
> at java.nio.file.Files.move(Files.java:1395)
> at org.apache.kafka.common.utils.Utils.atomicMoveWithFallback(Utils.java:697)
> at org.apache.kafka.common.record.FileRecords.renameTo(FileRecords.java:212)
> at kafka.log.LogSegment.changeFileSuffixes(LogSegment.scala:415)
> at kafka.log.Log.kafka$log$Log$$asyncDeleteSegment(Log.scala:1601)
> at kafka.log.Log.kafka$log$Log$$deleteSegment(Log.scala:1588)
> at
> kafka.log.Log$$anonfun$deleteSegments$1$$anonfun$apply$mcI$sp$1.apply(Log.scala:1170)
> at
> kafka.log.Log$$anonfun$deleteSegments$1$$anonfun$apply$mcI$sp$1.apply(Log.scala:1170)
> at
> scala.collection.mutable.ResizableArray$class.foreach(ResizableArray.scala:59)
> at scala.collection.mutable.ArrayBuffer.foreach(ArrayBuffer.scala:48)
> at kafka.log.Log$$anonfun$deleteSegments$1.apply$mcI$sp(Log.scala:1170)
> at kafka.log.Log$$anonfun$deleteSegments$1.apply(Log.scala:1161)
> at kafka.log.Log$$anonfun$deleteSegments$1.apply(Log.scala:1161)
> at kafka.log.Log.maybeHandleIOException(Log.scala:1678)
> at kafka.log.Log.deleteSegments(Log.scala:1161)
> at kafka.log.Log.deleteOldSegments(Log.scala:1156)
> at kafka.log.Log.deleteRetentionMsBreachedSegments(Log.scala:1228)
> at kafka.log.Log.deleteOldSegments(Log.scala:1222)
> at kafka.log.LogManager$$anonfun$cleanupLogs$3.apply(LogManager.scala:854)
> at kafka.log.LogManager$$anonfun$cleanupLogs$3.apply(LogManager.scala:852)
> at
> scala.collection.TraversableLike$WithFilter$$anonfun$foreach$1.apply(TraversableLike.scala:733)
> at scala.collection.immutable.List.foreach(List.scala:392)
> at
> scala.collection.TraversableLike$WithFilter.foreach(TraversableLike.scala:732)
> at kafka.log.LogManager.cleanupLogs(LogManager.scala:852)
> at kafka.log.LogManager$$anonfun$startup$1.apply$mcV$sp(LogManager.scala:385)
> at
> kafka.utils.KafkaScheduler$$anonfun$1.apply$mcV$sp(KafkaScheduler.scala:110)
> at kafka.utils.CoreUtils$$anon$1.run(CoreUtils.scala:62)
> at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
> at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308)
> at
> java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180)
> at
> java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294)
> at
> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
> at
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
> at java.lang.Thread.run(Thread.java:748)
> Suppressed: java.nio.file.FileSystemException:
> D:\data\Kafka\kafka-logs\test4-1\00000000000000000000.log ->
> D:\data\Kafka\kafka-logs\test4-1\00000000000000000000.log.deleted: The
> process cannot access the file because it is being used by another process.
> at
> sun.nio.fs.WindowsException.translateToIOException(WindowsException.java:86)
> at sun.nio.fs.WindowsException.rethrowAsIOException(WindowsException.java:97)
> at sun.nio.fs.WindowsFileCopy.move(WindowsFileCopy.java:301)
> at
> sun.nio.fs.WindowsFileSystemProvider.move(WindowsFileSystemProvider.java:287)
> at java.nio.file.Files.move(Files.java:1395)
> at org.apache.kafka.common.utils.Utils.atomicMoveWithFallback(Utils.java:694)
> ... 32 more
>
> *Topic deletion scenario*
> 2018-06-07 15:05:17,805] ERROR Error while renaming dir for test5-1 in log
> dir D:\data\Kafka\kafka-logs (kafka.server.LogDirFailureChannel)
> java.nio.file.AccessDeniedException: D:\data\Kafka\kafka-logs\test5-1 ->
> D:\data\Kafka\kafka-logs\test5-1.87985bad40e441e1a4d08af4541db7ce-delete
> at
> sun.nio.fs.WindowsException.translateToIOException(WindowsException.java:83)
> at sun.nio.fs.WindowsException.rethrowAsIOException(WindowsException.java:97)
> at sun.nio.fs.WindowsFileCopy.move(WindowsFileCopy.java:387)
> at
> sun.nio.fs.WindowsFileSystemProvider.move(WindowsFileSystemProvider.java:287)
> at java.nio.file.Files.move(Files.java:1395)
> at org.apache.kafka.common.utils.Utils.atomicMoveWithFallback(Utils.java:697)
> at kafka.log.Log$$anonfun$renameDir$1.apply$mcV$sp(Log.scala:579)
> at kafka.log.Log$$anonfun$renameDir$1.apply(Log.scala:577)
> at kafka.log.Log$$anonfun$renameDir$1.apply(Log.scala:577)
> at kafka.log.Log.maybeHandleIOException(Log.scala:1678)
> at kafka.log.Log.renameDir(Log.scala:577)
> at kafka.log.LogManager.asyncDelete(LogManager.scala:813)
> at kafka.cluster.Partition$$anonfun$delete$1.apply(Partition.scala:240)
> at kafka.cluster.Partition$$anonfun$delete$1.apply(Partition.scala:235)
> at kafka.utils.CoreUtils$.inLock(CoreUtils.scala:250)
> at kafka.utils.CoreUtils$.inWriteLock(CoreUtils.scala:258)
> at kafka.cluster.Partition.delete(Partition.scala:235)
> at kafka.server.ReplicaManager.stopReplica(ReplicaManager.scala:347)
> at
> kafka.server.ReplicaManager$$anonfun$stopReplicas$2.apply(ReplicaManager.scala:377)
> at
> kafka.server.ReplicaManager$$anonfun$stopReplicas$2.apply(ReplicaManager.scala:375)
> at scala.collection.Iterator$class.foreach(Iterator.scala:891)
> at scala.collection.AbstractIterator.foreach(Iterator.scala:1334)
> at scala.collection.IterableLike$class.foreach(IterableLike.scala:72)
> at scala.collection.AbstractIterable.foreach(Iterable.scala:54)
> at kafka.server.ReplicaManager.stopReplicas(ReplicaManager.scala:375)
> at kafka.server.KafkaApis.handleStopReplicaRequest(KafkaApis.scala:198)
> at kafka.server.KafkaApis.handle(KafkaApis.scala:109)
> at kafka.server.KafkaRequestHandler.run(KafkaRequestHandler.scala:69)
> at java.lang.Thread.run(Thread.java:748)
> Suppressed: java.nio.file.AccessDeniedException:
> D:\data\Kafka\kafka-logs\test5-1 ->
> D:\data\Kafka\kafka-logs\test5-1.87985bad40e441e1a4d08af4541db7ce-delete
> at
> sun.nio.fs.WindowsException.translateToIOException(WindowsException.java:83)
> at sun.nio.fs.WindowsException.rethrowAsIOException(WindowsException.java:97)
> at sun.nio.fs.WindowsFileCopy.move(WindowsFileCopy.java:301)
> at
> sun.nio.fs.WindowsFileSystemProvider.move(WindowsFileSystemProvider.java:287)
> at java.nio.file.Files.move(Files.java:1395)
> at org.apache.kafka.common.utils.Utils.atomicMoveWithFallback(Utils.java:694)
> ... 23 more
>
> *File Compaction Scenario*
> [2019-03-11 16:02:00,021] ERROR Error while loading log dir
> D:\data\Kafka\kafka-datalogs (kafka.log.LogManager)
> java.nio.file.FileSystemException:
> D:\data\Kafka\kafka-datalogs\kattesttopic-23\00000000000003505795.log: The
> process cannot access the file because it is being used by another process.
> at
> sun.nio.fs.WindowsException.translateToIOException(WindowsException.java:86)
> at sun.nio.fs.WindowsException.rethrowAsIOException(WindowsException.java:97)
> at
> sun.nio.fs.WindowsException.rethrowAsIOException(WindowsException.java:102)
> at sun.nio.fs.WindowsFileCopy.move(WindowsFileCopy.java:376)
> at
> sun.nio.fs.WindowsFileSystemProvider.move(WindowsFileSystemProvider.java:287)
> at java.nio.file.Files.move(Files.java:1395)
> at org.apache.kafka.common.utils.Utils.atomicMoveWithFallback(Utils.java:697)
> at org.apache.kafka.common.record.FileRecords.renameTo(FileRecords.java:223)
> at kafka.log.LogSegment.changeFileSuffixes(LogSegment.scala:415)
> at kafka.log.Log.replaceSegments(Log.scala:1697)
> at kafka.log.Log$$anonfun$completeSwapOperations$1.apply(Log.scala:391)
> at kafka.log.Log$$anonfun$completeSwapOperations$1.apply(Log.scala:380)
> at scala.collection.immutable.Set$Set1.foreach(Set.scala:94)
> at kafka.log.Log.completeSwapOperations(Log.scala:380)
> at kafka.log.Log.loadSegments(Log.scala:408)
> at kafka.log.Log.<init>(Log.scala:216)
> at kafka.log.Log$.apply(Log.scala:1788)
> at kafka.log.LogManager.kafka$log$LogManager$$loadLog(LogManager.scala:260)
> at
> kafka.log.LogManager$$anonfun$loadLogs$2$$anonfun$11$$anonfun$apply$15$$anonfun$apply$2.apply$mcV$sp(LogManager.scala:340)
> at kafka.utils.CoreUtils$$anon$1.run(CoreUtils.scala:62)
> at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
> at java.util.concurrent.FutureTask.run(FutureTask.java:266)
> at
> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
> at
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
> at java.lang.Thread.run(Thread.java:748)
> Suppressed: java.nio.file.AccessDeniedException:
> D:\data\Kafka\kafka-datalogs\kattesttopic-23\00000000000003505795.log.swap ->
> D:\data\Kafka\kafka-datalogs\kattesttopic-23\00000000000003505795.log
> at
> sun.nio.fs.WindowsException.translateToIOException(WindowsException.java:83)
> at sun.nio.fs.WindowsException.rethrowAsIOException(WindowsException.java:97)
> at sun.nio.fs.WindowsFileCopy.move(WindowsFileCopy.java:301)
> at
> sun.nio.fs.WindowsFileSystemProvider.move(WindowsFileSystemProvider.java:287)
> at java.nio.file.Files.move(Files.java:1395)
> at org.apache.kafka.common.utils.Utils.atomicMoveWithFallback(Utils.java:694)
> ... 18 more
>
--
This message was sent by Atlassian JIRA
(v7.6.3#76005)
