[KAFKA-8172] FileSystemException: The process cannot access the file because it is being used by another process

• Type: Bug
• Status: Patch Available
• Priority: Major
• Resolution: Unresolved
• Affects Version/s: 1.1.1, 2.2.0, 2.1.1
• Fix Version/s: 1.1.1, 2.2.0, 2.1.1
• Component/s: core
• Environment: Windows
• Flags: Patch, Important
• Assignee: Unassigned
• Reporter: Bharat Kondeti
• Created: 28/Mar/19 19:44
• Updated: 28/Feb/21 23:41

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

 

Issue Links

• duplicates: KAFKA-6983 Error while deleting segments - The process cannot access the file because it is being used by another process
• duplicates: KAFKA-7020 Error when deleting topic with access denied exception
• duplicates: KAFKA-8099 java.nio.file.AccessDeniedException: .swap renamed to .log failed
• relates to: KAFKA-9458 Kafka crashed in windows environment
• links to: GitHub Pull Request #6517
• links to: https://github.com/apache/kafka/pull/6517