search

charithe / kafka-junit

JUnit rule for spinning up a Kafka broker
Apache License 2.0
105 stars 45 forks source link

Failing JUnits on Windows #25

Open mariankassovic opened 7 years ago

mariankassovic commented 7 years ago

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 commented 7 years ago

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 commented 7 years ago

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 commented 7 years ago

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 commented 6 years ago

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 commented 6 years ago

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 commented 6 years ago

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 commented 5 years ago

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 commented 2 years ago

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 commented 2 years ago

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