Uploaded image for project: 'Kafka'
  1. Kafka
  2. KAFKA-8172

FileSystemException: The process cannot access the file because it is being used by another process

    Details

    • 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
    • Labels:
      None
    • Environment:
      Windows
    • Flags:
      Patch, Important

      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

       

        Attachments

          Issue Links

            Activity

              People

              • Assignee:
                Unassigned
                Reporter:
                kondetibharat Bharat Kondeti
              • Votes:
                2 Vote for this issue
                Watchers:
                4 Start watching this issue

                Dates

                • Created:
                  Updated: