apache
KAFKA-1194: Fix renaming open files on Windows
Running Kafka on Windows results in errors relating to renaming files that are locked (still mapped) by running Kafka. This patch unmmap()s and mmap()s a file before and after the actual renameTo() respectively.
Patch should have no effect on Linux.
Hi,
I ran this version just now and am able to crash it with the following configuration (server.properties):
log.segment.bytes=102400 log.retention.bytes= 1024000 log.retention.minutes = 1 log.retention.check.interval.minutes = 1 log.cleanup.policy=compact log.cleaner.min.compaction.lag.ms = 5000 log.roll.ms = 10000
The exception is easily observed when running the "kafka-bombarder" tool which I uploaded in this thread.
I think you elegantly managed the problem which arises on the synchronous flow of the retention mechanism.
Keep in mind that the retention mechanism also has an "asynchronous" counterpart which is being invoked by the internal scheduler.
Here is the exception:
[2019-02-27 13:37:50,595] ERROR Failed to clean up log for bombardedTopic-0 in dir C:\tmp\kafka-logs due to IOException (kafka.server.LogDirFailureChannel) java.nio.file.FileAlreadyExistsException: C:\tmp\kafka-logs\bombardedTopic-0\00000000000000000000.log -> C:\tmp\kafka-logs\bombardedTopic-0\00000000000000000000.log.deleted at sun.nio.fs.WindowsException.translateToIOException(WindowsException.java:81) 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:805) at org.apache.kafka.common.record.FileRecords.renameTo(FileRecords.java:224) at kafka.log.LogSegment.changeFileSuffixes(LogSegment.scala:506) at kafka.log.Log.asyncDeleteSegment(Log.scala:1924) at kafka.log.Log.$anonfun$replaceSegments$6(Log.scala:1987) at kafka.log.Log.$anonfun$replaceSegments$6$adapted(Log.scala:1982) at scala.collection.immutable.List.foreach(List.scala:392) at kafka.log.Log.replaceSegments(Log.scala:1982) at kafka.log.Cleaner.cleanSegments(LogCleaner.scala:580) at kafka.log.Cleaner.$anonfun$doClean$6(LogCleaner.scala:512) at kafka.log.Cleaner.$anonfun$doClean$6$adapted(LogCleaner.scala:511) at scala.collection.immutable.List.foreach(List.scala:392) at kafka.log.Cleaner.doClean(LogCleaner.scala:511) at kafka.log.Cleaner.clean(LogCleaner.scala:489) at kafka.log.LogCleaner$CleanerThread.cleanLog(LogCleaner.scala:350) at kafka.log.LogCleaner$CleanerThread.cleanFilthiestLog(LogCleaner.scala:319) at kafka.log.LogCleaner$CleanerThread.doWork(LogCleaner.scala:300) at kafka.utils.ShutdownableThread.run(ShutdownableThread.scala:82) Suppressed: java.nio.file.AccessDeniedException: C:\tmp\kafka-logs\bombardedTopic-0\00000000000000000000.log -> C:\tmp\kafka-logs\bombardedTopic-0\00000000000000000000.log.deleted 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:802) ... 17 more
I do think your approach is better than the one I've presented thus far. I'll try to keep looking into the issue.
Best regards, Kobi.
Hi Kobi, thanks for reviewing my changes, you seem to know more about this issue than I do.
However, I was not able to reproduce the issue you describe. I set the server.properties, and used the bombarder application as described, even multiple times. I see a lot of log/index/txs files renamed, then after a minute or so deleted successfully.
I am using an almost stock Windows 10, with no antivirals or other background filescanners that I am aware of.
The FileAlreadyExistsException would suggest that the rename is not atomic and two threads want to simultaneously rename the file? Does it do that every time you try, or just sometimes? Could it be a race condition on non-atomic renames? Does it do that on a clean log directory too, or maybe there was already some files there from a previous test?
Thanks @robertbraeutigam,
Have you tried letting the kafka-bombarder app run for several minutes? It will eventually cause the broker to fail (trust me, I can write apps that crash ...).
"The FileAlreadyExistsException would suggest that the rename is not atomic and two threads want to simultaneously rename the file?"
No, not really. It means that one code path led to an open FileChannel for a file, and then another code path leads to a file operation on the same file, while the FileChannel is still open. Or vice versa.
"Does it do that every time you try, or just sometimes?"
Every time.
"Could it be a race condition on non-atomic renames?"
I don't suppose so, but that is just a gut feeling as of now.
"Does it do that on a clean log directory too, or maybe there was already some files there from a previous test?"
Yes.
Best regards, Kobi.
P.S
I am still working on the issue and will update if I have anything new.
@kobihikri In my tests the kafka-bombarder application exits after a couple of seconds on its own. I assumed that is how it is supposed to work. Maybe my combination of os memory (16G) and/or SSD makes the difference.
I will try with a longer running tests using the kafka-producer-perf-test.
And why shouldn't it really? ;-). Please try this version. It is the one I am using. kafka-bombarder.zip
I added some modifications, so I leave both AbstractIndex and FileRecords closed after a rename, and re-open only on demand. This seems to solve the remaining issues, and both the logs and indices seem to rotate as expected. Tests also work.
I have to admit, I still don't understand everything that's going on, a review would be welcome.
With these modifications the server doesn't crash when using the bombarder tool. At least not on file issues. It crashes after several minutes of running with an OutOfMemoryError, which is not nice, but I guess is an unrelated issue.
Hi @robertbraeutigam ,
I just reproduced the server crash, with your latest commit:
[2019-03-03 11:17:28,604] ERROR Failed to clean up log for bombardedTopic-0 in dir C:\tmp\kafka-logs due to IOException (kafka.server.LogDirFailureChannel) java.nio.file.FileAlreadyExistsException: C:\tmp\kafka-logs\bombardedTopic-0\00000000000001267441.log -> C:\tmp\kafka-logs\bombardedTopic-0\00000000000001267441.log.deleted at sun.nio.fs.WindowsException.translateToIOException(WindowsException.java:81) 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:805) at org.apache.kafka.common.record.FileRecords.renameTo(FileRecords.java:253) at kafka.log.LogSegment.changeFileSuffixes(LogSegment.scala:506) at kafka.log.Log.asyncDeleteSegment(Log.scala:1924) at kafka.log.Log.$anonfun$replaceSegments$6(Log.scala:1987) at kafka.log.Log.$anonfun$replaceSegments$6$adapted(Log.scala:1982) at scala.collection.immutable.List.foreach(List.scala:392) at kafka.log.Log.replaceSegments(Log.scala:1982) at kafka.log.Cleaner.cleanSegments(LogCleaner.scala:580) at kafka.log.Cleaner.$anonfun$doClean$6(LogCleaner.scala:512) at kafka.log.Cleaner.$anonfun$doClean$6$adapted(LogCleaner.scala:511) at scala.collection.immutable.List.foreach(List.scala:392) at kafka.log.Cleaner.doClean(LogCleaner.scala:511) at kafka.log.Cleaner.clean(LogCleaner.scala:489) at kafka.log.LogCleaner$CleanerThread.cleanLog(LogCleaner.scala:350) at kafka.log.LogCleaner$CleanerThread.cleanFilthiestLog(LogCleaner.scala:319) at kafka.log.LogCleaner$CleanerThread.doWork(LogCleaner.scala:300) at kafka.utils.ShutdownableThread.run(ShutdownableThread.scala:82) Suppressed: java.nio.file.AccessDeniedException: C:\tmp\kafka-logs\bombardedTopic-0\00000000000001267441.log -> C:\tmp\kafka-logs\bombardedTopic-0\00000000000001267441.log.deleted 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:802) ... 17 more
Best regards, Kobi.
@kobihikri Thanks again for your tests.
I thought I could not reproduce the issue anymore, I had to run the test several times to make it crash (which is progress I guess). In my tests it crashed because the rename apparently run at the same time as the actual delete of the .deleted file.
In the latest commit I synchronize the deleteIfExists() to the same lock as the renameTo() in both FileRecord and AbstractIndex.
After 30 minutes or so testing with the bombarder I could not reproduce the issue anymore.
Thanks @robertbraeutigam, I am testing your fix. Will update here! Your efforts are more than appreciated!
Ok, so this is what I got thus far:
It does seem you nailed the root cause of the problem. Amazing :-). Great approach with elegant, minimal, non-intrusive implementation.
I believe one problem remains to be solved and that is the topic deletion problem. Currently, when trying to delete a topic, you will face a broker shutdown:
[2019-03-06 11:46:18,485] ERROR Error while renaming dir for bombardedTopic-1 in log dir C:\tmp\kafka-logs (kafka.server.LogDirFailureChannel) java.nio.file.AccessDeniedException: C:\tmp\kafka-logs\bombardedTopic-1 -> C:\tmp\kafka-logs\bombardedTopic-1.df85c3b9b14848d9b5f966be50130cf1-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:805) at kafka.log.Log.$anonfun$renameDir$2(Log.scala:761) at scala.runtime.java8.JFunction0$mcV$sp.apply(JFunction0$mcV$sp.java:23) at kafka.log.Log.maybeHandleIOException(Log.scala:2013) at kafka.log.Log.renameDir(Log.scala:759) at kafka.log.LogManager.asyncDelete(LogManager.scala:857) at kafka.cluster.Partition.$anonfun$delete$1(Partition.scala:356) at kafka.utils.CoreUtils$.inLock(CoreUtils.scala:253) at kafka.utils.CoreUtils$.inWriteLock(CoreUtils.scala:261) at kafka.cluster.Partition.delete(Partition.scala:350) at kafka.server.ReplicaManager.stopReplica(ReplicaManager.scala:362) at kafka.server.ReplicaManager.$anonfun$stopReplicas$2(ReplicaManager.scala:392) at scala.collection.Iterator.foreach(Iterator.scala:941) at scala.collection.Iterator.foreach$(Iterator.scala:941) at scala.collection.AbstractIterator.foreach(Iterator.scala:1429) at scala.collection.IterableLike.foreach(IterableLike.scala:74) at scala.collection.IterableLike.foreach$(IterableLike.scala:73) at scala.collection.AbstractIterable.foreach(Iterable.scala:56) at kafka.server.ReplicaManager.stopReplicas(ReplicaManager.scala:390) at kafka.server.KafkaApis.handleStopReplicaRequest(KafkaApis.scala:216) at kafka.server.KafkaApis.handle(KafkaApis.scala:116) at kafka.server.KafkaRequestHandler.run(KafkaRequestHandler.scala:69) at java.lang.Thread.run(Thread.java:748) Suppressed: java.nio.file.AccessDeniedException: C:\tmp\kafka-logs\bombardedTopic-1 -> C:\tmp\kafka-logs\bombardedTopic-1.df85c3b9b14848d9b5f966be50130cf1-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:802) ... 22 more
BTW, If you take a look at my try at solving this issue, you will notice that I've encountered the same issues, at the same order. However, and I'll say it again - I like your approach better than the one I had.
@simplesteph - I think you will find this interesting :-).
@kobihikri Awesome, thanks for testing!
Could we perhaps try to get this patch in first, and then create a ticket for deleting topics and work on that separately?
Not to be too selfish, but our problem is currently that Kafka doesn't run on Windows for long without crashing, it is a blocking issue for us. Deleting a topic just isn't a use-case for us, so that's lower priority.
If this passes tests, and fixes some issues in Windows, that's already really great news.
I don't have a Windows machine to test on unfortunately, but from what you're saying you've fixed the issues. I would be grateful if the problem of topic deletion can be looked at (that's really the last case where files are deleted I believe - you can probably apply the same approach), maybe as part of a separate PR indeed.
cc @ijuma @gwenshap @guozhangwang , from a user acquisition standpoint, having a stable Windows build is really nice. This passes the test suite, so worth looking at IMO.
@robertbraeutigam @simplesteph @ijuma @gwenshap @guozhangwang
Yes, Robert did fix the core of the issue, and have done so without affecting the behavior on linux. I vote for accepting this PR and managing the rest of the file handling (topic deletion) in a different issue and PR.
@robertbraeutigam Thanks :-)
@robertbraeutigam On top of your Pr, I've created a fix for the topic deletion issue. I would like to make sure it passes all unit tests. How were you able to run the unit tests exactly as they ran on the build server, but locally? Could you kindly let me know?
I'm attaching the diff file here, if you want to take a look.
@kobihikri I just ran 'gradle test' for everything (takes about 30 minutes), or 'gradle core:test' and 'gradle client:test' for specific parts. I don't actually know whether that is similar to what the build server does.
Hi All, I am new to Kafka and facing issues while start Kafka server in windows. its similar issues discussing in this thread ( i.e. synchronization issue). hope new build will resolve these issues. kindly notify me, once ready with the updated build. thanks all
I can confirm that the changes @robertbraeutigam did, are fixing the problem in a way, that kafka will not crash. A long-term test, that always crashed reproducible before, did now run (and is still running) successfully.
Hi guys,
Awesome job in getting to the root cause of this problem and helping push a fix for us Windows users. I landed on this page after facing this same issue (running Kafka on Windows 10 and attempting a topic delete). Would you be able to confirm when this fix will be approved/merged?
@kobihikri I tested your change, I think you've got it. Without your change it crashes immediately on delete topic, with your change it seems to rename properly.
@robertbraeutigam That sounds great to me! Thanks for testing. I am actually waiting here for additional approvers to notice this fix.
Hi all, It would be a shame not yo merge this PR, as it really solves a critical problem for windows users. Are we approving this PR?
@kobihikri I don't know what the process is. I had to merge master a while ago and a test failed at that point. I'm pretty sure it's unrelated. I would have to commit something though to trigger a new build.
Hi, thanks for the awesome fix, any ETA on when this will be merged? This is a solution to a show stopper that keeps us poor windows users stuck on a pre-1.0 Kafka.
@robertbraeutigam In order to force a rebuild you can add a comment that has the text "retest this please" see https://cwiki.apache.org/confluence/display/KAFKA/Contributing+Code+Changes
Been running this with great success for a few weeks now on Windows 2012 R2. This really should be merged into the next release.
@robertbraeutigam @kobihikri I've seen both the JDK 8 and JDK 11 build pass in the past few days, but in separate runs. Should this be retested until they both pass in one run?