Failing JUnits on Windows

[mariankassovic]

Running JUnit EphemeralKafkaBrokerTest on Windows is failing:

11:08:19.131 [onPool-worker-1] WARN     k.server.BrokerMetadataCheckpoint - No meta.properties file under dir C:\Users\KASSOV~1.MAR\AppData\Local\Temp\kafka_junit2358289997418960258\meta.properties
11:08:19.764 [onPool-worker-1] WARN     k.server.BrokerMetadataCheckpoint - No meta.properties file under dir C:\Users\KASSOV~1.MAR\AppData\Local\Temp\kafka_junit2358289997418960258\meta.properties
11:08:19.961 [d | kafka-junit] WARN  o.apache.kafka.clients.NetworkClient - Error while fetching metadata with correlation id 1 : {test-topic=LEADER_NOT_AVAILABLE}
11:08:20.096 [d | kafka-junit] WARN  o.apache.kafka.clients.NetworkClient - Error while fetching metadata with correlation id 3 : {test-topic=LEADER_NOT_AVAILABLE}
11:08:23.019 [main           ] ERROR     c.g.c.kafka.EphemeralKafkaBroker - Failed to clean-up Kafka
java.nio.file.FileSystemException: C:\Users\KASSOV~1.MAR\AppData\Local\Temp\kafka_junit2358289997418960258\test-topic-0\00000000000000000000.timeindex: The process cannot access the file because it is being used by another process.
	at sun.nio.fs.WindowsException.translateToIOException(Unknown Source)
	at sun.nio.fs.WindowsException.rethrowAsIOException(Unknown Source)
	at sun.nio.fs.WindowsException.rethrowAsIOException(Unknown Source)
	at sun.nio.fs.WindowsFileSystemProvider.implDelete(Unknown Source)
	at sun.nio.fs.AbstractFileSystemProvider.deleteIfExists(Unknown Source)
	at java.nio.file.Files.deleteIfExists(Unknown Source)
	at com.github.charithe.kafka.EphemeralKafkaBroker$1.visitFile(EphemeralKafkaBroker.java:171)
	at com.github.charithe.kafka.EphemeralKafkaBroker$1.visitFile(EphemeralKafkaBroker.java:1)
	at java.nio.file.Files.walkFileTree(Unknown Source)
	at java.nio.file.Files.walkFileTree(Unknown Source)
	at com.github.charithe.kafka.EphemeralKafkaBroker.stopBroker(EphemeralKafkaBroker.java:168)
	at com.github.charithe.kafka.EphemeralKafkaBroker.stop(EphemeralKafkaBroker.java:147)
	at com.github.charithe.kafka.EphemeralKafkaBrokerTest.testReadAndWrite(EphemeralKafkaBrokerTest.java:112)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(Unknown Source)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)
	at java.lang.reflect.Method.invoke(Unknown Source)
	at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50)
	at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
	at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:47)
	at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
	at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:325)
	at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:78)
	at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:57)
	at org.junit.runners.ParentRunner$3.run(ParentRunner.java:290)
	at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:71)
	at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:288)
	at org.junit.runners.ParentRunner.access$000(ParentRunner.java:58)
	at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:268)
	at org.junit.runners.ParentRunner.run(ParentRunner.java:363)
	at org.eclipse.jdt.internal.junit4.runner.JUnit4TestReference.run(JUnit4TestReference.java:86)
	at org.eclipse.jdt.internal.junit.runner.TestExecution.run(TestExecution.java:38)
	at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.runTests(RemoteTestRunner.java:459)
	at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.runTests(RemoteTestRunner.java:678)
	at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.run(RemoteTestRunner.java:382)
	at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.main(RemoteTestRunner.java:192)
11:08:23.563 [main           ] ERROR             kafka.server.KafkaServer - Fatal error during KafkaServer shutdown.
java.lang.IllegalStateException: Kafka server is still starting up, cannot shut down!
	at kafka.server.KafkaServer.shutdown(KafkaServer.scala:575)
	at kafka.server.KafkaServerStartable.shutdown(KafkaServerStartable.scala:51)
	at com.github.charithe.kafka.EphemeralKafkaBroker.stopBroker(EphemeralKafkaBroker.java:158)
	at com.github.charithe.kafka.EphemeralKafkaBroker.stop(EphemeralKafkaBroker.java:147)
	at com.github.charithe.kafka.EphemeralKafkaBrokerTest.testStartAndStop(EphemeralKafkaBrokerTest.java:68)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(Unknown Source)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)
	at java.lang.reflect.Method.invoke(Unknown Source)
	at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50)
	at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
	at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:47)
	at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
	at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:325)
	at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:78)
	at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:57)
	at org.junit.runners.ParentRunner$3.run(ParentRunner.java:290)
	at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:71)
	at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:288)
	at org.junit.runners.ParentRunner.access$000(ParentRunner.java:58)
	at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:268)
	at org.junit.runners.ParentRunner.run(ParentRunner.java:363)
	at org.eclipse.jdt.internal.junit4.runner.JUnit4TestReference.run(JUnit4TestReference.java:86)
	at org.eclipse.jdt.internal.junit.runner.TestExecution.run(TestExecution.java:38)
	at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.runTests(RemoteTestRunner.java:459)
	at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.runTests(RemoteTestRunner.java:678)
	at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.run(RemoteTestRunner.java:382)
	at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.main(RemoteTestRunner.java:192)

There has to be some issue with statitcs since next run ends differenly

11:12:32.587 [onPool-worker-1] WARN     k.server.BrokerMetadataCheckpoint - No meta.properties file under dir C:\Users\KASSOV~1.MAR\AppData\Local\Temp\kafka_junit3765302414122141202\meta.properties
11:12:33.143 [onPool-worker-1] WARN     k.server.BrokerMetadataCheckpoint - No meta.properties file under dir C:\Users\KASSOV~1.MAR\AppData\Local\Temp\kafka_junit3765302414122141202\meta.properties
11:12:33.413 [d | kafka-junit] WARN  o.apache.kafka.clients.NetworkClient - Error while fetching metadata with correlation id 1 : {test-topic=LEADER_NOT_AVAILABLE}
11:12:33.565 [d | kafka-junit] WARN  o.apache.kafka.clients.NetworkClient - Error while fetching metadata with correlation id 3 : {test-topic=LEADER_NOT_AVAILABLE}
11:12:34.751 [onPool-worker-1] WARN     k.server.BrokerMetadataCheckpoint - No meta.properties file under dir C:\Users\KASSOV~1.MAR\AppData\Local\Temp\kafka_junit4699908709488809068\meta.properties
11:12:34.822 [main           ] ERROR             kafka.server.KafkaServer - [Kafka Server 1], Fatal error during KafkaServer shutdown.
java.lang.IllegalStateException: Kafka server is still starting up, cannot shut down!
	at kafka.server.KafkaServer.shutdown(KafkaServer.scala:575)
	at kafka.server.KafkaServerStartable.shutdown(KafkaServerStartable.scala:51)

This might not be obvious on Linux platform. I suppose that there is some resource leak that keeps directory file handle open.

[charithe]

Thanks for reporting the issue. Unfortunately I can't provide support for the Windows platform. If you know how to fix the problem, please send a PR and I'll be happy to accept it.

[mariankassovic]

I have only a small improvement - add awaitShutdown() call in EphemeralKafkaBroker method stopBroker before trying to delete Kafka log directory.

  private void stopBroker() {
        try {
            if (kafkaServer != null) {
                LOGGER.info("Shutting down Kafka Server");
                kafkaServer.shutdown();
                kafkaServer.awaitShutdown();
            }

Unfortunately it does not solve the problem completely, since it looks like Kafka does not close topic properly on shutdown :-( Tests run green, but temp folder clean-up is failing...

[charithe]

Yes, I remember reading that Windows creates exclusive locks on files whereas Unix-like systems don't. This is probably something to do with that. I'll mark this as up-for-grabs so that someone with knowledge of Windows (and access to a Windows machine) can pick it up and work on it.

[eximius313]

I'm also suffering from this:

2018-03-22 13:36:28.080 ERROR 5828 --- [       Thread-8] org.apache.kafka.test.TestUtils          : Error deleting C:\Users\X\AppData\Local\Temp\kafka-5223924343707963804

java.nio.file.FileSystemException: C:\Users\X\AppData\Local\Temp\kafka-5223924343707963804\version-2\log.1: The process cannot access the file because it is being used by another process.

	at sun.nio.fs.WindowsException.translateToIOException(WindowsException.java:86) ~[na:1.8.0_144]
	at sun.nio.fs.WindowsException.rethrowAsIOException(WindowsException.java:97) ~[na:1.8.0_144]
	at sun.nio.fs.WindowsException.rethrowAsIOException(WindowsException.java:102) ~[na:1.8.0_144]
	at sun.nio.fs.WindowsFileSystemProvider.implDelete(WindowsFileSystemProvider.java:269) ~[na:1.8.0_144]
	at sun.nio.fs.AbstractFileSystemProvider.delete(AbstractFileSystemProvider.java:103) ~[na:1.8.0_144]
	at java.nio.file.Files.delete(Files.java:1126) ~[na:1.8.0_144]
	at org.apache.kafka.common.utils.Utils$1.visitFile(Utils.java:630) ~[kafka-clients-1.0.1.jar:na]
	at org.apache.kafka.common.utils.Utils$1.visitFile(Utils.java:619) ~[kafka-clients-1.0.1.jar:na]
	at java.nio.file.Files.walkFileTree(Files.java:2670) ~[na:1.8.0_144]
	at java.nio.file.Files.walkFileTree(Files.java:2742) ~[na:1.8.0_144]
	at org.apache.kafka.common.utils.Utils.delete(Utils.java:619) ~[kafka-clients-1.0.1.jar:na]
	at org.apache.kafka.test.TestUtils$1.run(TestUtils.java:184) ~[kafka-clients-1.0.1-test.jar:na]

2018-03-22 13:36:28.091 ERROR 5828 --- [      Thread-11] org.apache.kafka.test.TestUtils          : Error deleting C:\Users\X\AppData\Local\Temp\kafka-5049848438722543295

java.nio.file.FileSystemException: C:\Users\X\AppData\Local\Temp\kafka-5049848438722543295\version-2\log.1: The process cannot access the file because it is being used by another process.

	at sun.nio.fs.WindowsException.translateToIOException(WindowsException.java:86) ~[na:1.8.0_144]
	at sun.nio.fs.WindowsException.rethrowAsIOException(WindowsException.java:97) ~[na:1.8.0_144]
	at sun.nio.fs.WindowsException.rethrowAsIOException(WindowsException.java:102) ~[na:1.8.0_144]
	at sun.nio.fs.WindowsFileSystemProvider.implDelete(WindowsFileSystemProvider.java:269) ~[na:1.8.0_144]
	at sun.nio.fs.AbstractFileSystemProvider.delete(AbstractFileSystemProvider.java:103) ~[na:1.8.0_144]
	at java.nio.file.Files.delete(Files.java:1126) ~[na:1.8.0_144]
	at org.apache.kafka.common.utils.Utils$1.visitFile(Utils.java:630) ~[kafka-clients-1.0.1.jar:na]
	at org.apache.kafka.common.utils.Utils$1.visitFile(Utils.java:619) ~[kafka-clients-1.0.1.jar:na]
	at java.nio.file.Files.walkFileTree(Files.java:2670) ~[na:1.8.0_144]
	at java.nio.file.Files.walkFileTree(Files.java:2742) ~[na:1.8.0_144]
	at org.apache.kafka.common.utils.Utils.delete(Utils.java:619) ~[kafka-clients-1.0.1.jar:na]
	at org.apache.kafka.test.TestUtils$1.run(TestUtils.java:184) ~[kafka-clients-1.0.1-test.jar:na]

[carlislefox]

Also experiencing this issue

2018-04-03 15:56:25.652 ERROR 4816 --- [ Thread-4] org.apache.kafka.test.TestUtils : Error deleting C:\Users\stewalia\AppData\Local\Temp\kafka-7101259950782722212

java.nio.file.FileSystemException: C:\Users\stewalia\AppData\Local\Temp\kafka-7101259950782722212\product-0\00000000000000000000.index: 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.WindowsFileSystemProvider.implDelete(WindowsFileSystemProvider.java:269)
    at sun.nio.fs.AbstractFileSystemProvider.delete(AbstractFileSystemProvider.java:103)
    at java.nio.file.Files.delete(Files.java:1126)
    at org.apache.kafka.common.utils.Utils$2.visitFile(Utils.java:591)
    at org.apache.kafka.common.utils.Utils$2.visitFile(Utils.java:580)
    at java.nio.file.Files.walkFileTree(Files.java:2670)
    at java.nio.file.Files.walkFileTree(Files.java:2742)
    at org.apache.kafka.common.utils.Utils.delete(Utils.java:580)
    at org.apache.kafka.test.TestUtils$1.run(TestUtils.java:182)

[cyriljoui]

Hi

We were facing the same issue.
However it is a no blocking issue (in our case), the real issue may when we use Helper.produceStrings

in this.produce() ... it should be better to call .get() to be sure that message was really produced (sync)

public <K, V> void produce(String topic, KafkaProducer<K, V> producer, Map<K, V> data) {
    data.forEach((k, v) -> {
        producer.send(new ProducerRecord(topic, k, v));
    });
    producer.flush();
}

    protected <K, V> void produce(String topic, KafkaProducer<K, V> producer, Map<K, V> data) {
        data.forEach((k, v) -> {
            try {
                producer.send(new ProducerRecord(topic, k, v)).get();
            } catch (InterruptedException e) {
               throw new RuntimeException(e);
            } catch (ExecutionException e) {
                throw new RuntimeException(e);
            }
        });
        producer.flush();
    }

Could you please give more details about how do you implement your tests? which methods, classes do you use to consume / produce messages?

[silaev]

faced the same issue, as a workaround added the following to a Gradle clean task:

import org.apache.tools.ant.taskdefs.condition.Os

clean {
    if (Os.isFamily(Os.FAMILY_WINDOWS)) {
        def tempDir = System.getProperties().getProperty("java.io.tmpdir")
        def ft = fileTree(tempDir) {
            include 'kafka-*'
            exclude 'kafka-logs'
        }
        ft.visit {
            FileVisitDetails fvd ->
                println "deleted kafka temp folder: " + tempDir + fvd.name
                delete fvd.file
        }
    }
} 

[mjiderhamn]

This problem prevents me from upgrading as well. My error message is slightly different however

ERROR kafka.server.BrokerMetadataCheckpoint - Failed to write meta.properties due to
java.nio.file.AccessDeniedException: C:\Users\Maji\AppData\Local\Temp\kafka_junit16787608145441309316

[mjiderhamn]

At least in my case, the issue seems to be with Kafka itself https://issues.apache.org/jira/browse/KAFKA-13390 = apache/kafka#11426