Grpc Server QuarkusIntegrationTest fail #18706

xabe · 2021-07-15T06:24:52Z

Describe the bug

I'm not completely sure if this is a bug.

I have a project that I am using quarkus with grpc server that bump to the latest version (2.0.2.Final), the run mvn clean install -Pnative, the test it fails with the error

[ERROR] com.xabe.quarkus.grpc.infrastructure.controller.CarGrpcControllerIT.givenACarIdWhenInvokeGetNavigateCarThenReturnErrorStream  Time elapsed: 0.009 s  <<< ERROR!
java.lang.IllegalStateException: Unable to determine the status of the running process. See the above logs for details

Expected behavior

I expected that executing mvn clean install -Pnative the test will pass without errors

Actual behavior

The build fails with the error:

2021-07-15 08:02:07,953 INFO  [com.xab.qua.grp.App] (main) Running main method
2021-07-15 08:02:12,982 DEBUG [io.qua.ver.cor.run.VertxCoreRecorder] (main) Vert.x Cache configured to: /var/folders/g_/j0pkgddx7zg53q2m_vgz141h0000gn/T/vertx-cache/2054993830346340011
2021-07-15 08:02:12,983 DEBUG [io.qua.ver.cor.run.VertxCoreRecorder] (main) Vertx has Native Transport Enabled: false
2021-07-15 08:02:12,984 DEBUG [io.qua.grp.run.GrpcServerRecorder] (vert.x-eventloop-thread-0) Registered gRPC service 'grpc.health.v1.Health'
2021-07-15 08:02:12,984 DEBUG [io.qua.grp.run.GrpcServerRecorder] (vert.x-eventloop-thread-0) Registered gRPC service 'com.xabe.CarEndPoint'
2021-07-15 08:02:12,984 INFO  [io.qua.grp.run.GrpcServerRecorder] (vert.x-eventloop-thread-0) Registering gRPC reflection service
2021-07-15 08:02:12,984 DEBUG [io.qua.grp.run.GrpcServerRecorder] (vert.x-eventloop-thread-0) Starting gRPC Server on 0.0.0.0:6566  [SSL enabled: false]...
2021-07-15 08:02:12,986 INFO  [io.qua.grp.run.GrpcServerRecorder] (vert.x-eventloop-thread-1) gRPC Server started on 0.0.0.0:6566 [SSL enabled: false]
2021-07-15 08:02:12,986 INFO  [ApplicationLifeCycle] (main) The application is starting with profile test
2021-07-15 08:02:12,988 INFO  [io.quarkus] (main) quarkus-grpc 1.0-SNAPSHOT native (powered by Quarkus 2.0.2.Final) started in 0.027s. Listening on: http://0.0.0.0:8009
2021-07-15 08:02:12,988 INFO  [io.quarkus] (main) Profile test activated.
2021-07-15 08:02:12,988 INFO  [io.quarkus] (main) Installed features: [cdi, config-yaml, grpc-server, resteasy-mutiny, smallrye-context-propagation, vertx]
[ERROR] Tests run: 4, Failures: 0, Errors: 1, Skipped: 3, Time elapsed: 11.894 s <<< FAILURE! - in com.xabe.quarkus.grpc.infrastructure.controller.CarGrpcControllerIT
[ERROR] com.xabe.quarkus.grpc.infrastructure.controller.CarGrpcControllerIT.givenACarIdWhenInvokeGetNavigateCarThenReturnErrorStream  Time elapsed: 0.009 s  <<< ERROR!
java.lang.IllegalStateException: Unable to determine the status of the running process. See the above logs for details

How to Reproduce?

Link to a project

Steps to reproduce the behavior:

cd quarkus-grpc
mvn clean install -Pnative

Output of `uname -a` or `ver`

Darwin Kernel Version 20.5.0: Sat May 8 05:10:33 PDT 2021; root:xnu-7195.121.3~9/RELEASE_X86_64

Output of `java -version`

openjdk version "11.0.10" 2021-01-19

GraalVM version (if different from Java)

OpenJDK Runtime Environment GraalVM CE 21.0.0 (build 11.0.10+8-jvmci-21.0-b06) OpenJDK 64-Bit Server VM GraalVM CE 21.0.0 (build 11.0.10+8-jvmci-21.0-b06, mixed mode, sharing)

Quarkus version or git rev

2.0.2.Final

Build tool (ie. output of `mvnw --version` or `gradlew --version`)

Java version: 11.0.10, vendor: GraalVM Community, runtime: /Users/chabir/.sdkman/candidates/java/21.0.0.r11-grl Default locale: es_ES, platform encoding: UTF-8 OS name: "mac os x", version: "10.16", arch: "x86_64", family: "mac"

Additional information

Before it worked without problems with version 1.9.2.Final

The text was updated successfully, but these errors were encountered:

quarkus-bot · 2021-07-15T06:24:54Z

/cc @cescoffier, @geoand, @michalszynkiewicz

geoand · 2021-07-15T06:41:09Z

When I ran mvn clean verify -Dnative on your quarkus-grpc project everything worked as expected.

xabe · 2021-07-15T09:45:06Z

Hi @geoand

when i launch the tests it

OpenJDK 64-Bit Server VM warning: Sharing is only supported for boot loader classes because bootstrap classpath has been appended
Executing [/Users/chabir/workspace-idea/grpc/quarkus-grpc/target/quarkus-grpc-1.0-SNAPSHOT-runner, -Dquarkus.http.port=8009, -Dquarkus.http.ssl-port=8444, -Dtest.url=http://localhost:8009, -Dquarkus.log.file.path=/Users/chabir/workspace-idea/grpc/quarkus-grpc/target/quarkus.log, -Dquarkus.log.file.enable=true, -Dquarkus.profile=test]
2021-07-15 09:52:01,964 INFO  [com.xab.qua.grp.App] (main) Running main method
2021-07-15 09:52:06,999 DEBUG [io.qua.ver.cor.run.VertxCoreRecorder] (main) Vert.x Cache configured to: /var/folders/g_/j0pkgddx7zg53q2m_vgz141h0000gn/T/vertx-cache/2694100486362871975
2021-07-15 09:52:07,000 DEBUG [io.qua.ver.cor.run.VertxCoreRecorder] (main) Vertx has Native Transport Enabled: false
2021-07-15 09:52:07,001 DEBUG [io.qua.grp.run.GrpcServerRecorder] (vert.x-eventloop-thread-0) Registered gRPC service 'grpc.health.v1.Health'
2021-07-15 09:52:07,001 DEBUG [io.qua.grp.run.GrpcServerRecorder] (vert.x-eventloop-thread-0) Registered gRPC service 'com.xabe.CarEndPoint'
2021-07-15 09:52:07,001 INFO  [io.qua.grp.run.GrpcServerRecorder] (vert.x-eventloop-thread-0) Registering gRPC reflection service
2021-07-15 09:52:07,001 DEBUG [io.qua.grp.run.GrpcServerRecorder] (vert.x-eventloop-thread-0) Starting gRPC Server on 0.0.0.0:6566  [SSL enabled: false]...
2021-07-15 09:52:07,003 INFO  [io.qua.grp.run.GrpcServerRecorder] (vert.x-eventloop-thread-1) gRPC Server started on 0.0.0.0:6566 [SSL enabled: false]
2021-07-15 09:52:07,004 INFO  [ApplicationLifeCycle] (main) The application is starting with profile test
2021-07-15 09:52:07,005 INFO  [io.quarkus] (main) quarkus-grpc 1.0-SNAPSHOT native (powered by Quarkus 2.0.2.Final) started in 0.034s. Listening on: http://0.0.0.0:8009
2021-07-15 09:52:07,005 INFO  [io.quarkus] (main) Profile test activated. 
2021-07-15 09:52:07,005 INFO  [io.quarkus] (main) Installed features: [cdi, config-yaml, grpc-server, resteasy-mutiny, smallrye-context-propagation, vertx]

java.lang.RuntimeException: java.lang.IllegalStateException: Unable to determine the status of the running process. See the above logs for details

	at io.quarkus.test.junit.QuarkusIntegrationTestExtension.throwBootFailureException(QuarkusIntegrationTestExtension.java:225)
	at io.quarkus.test.junit.QuarkusIntegrationTestExtension.beforeEach(QuarkusIntegrationTestExtension.java:55)
	at org.junit.jupiter.engine.descriptor.TestMethodTestDescriptor.lambda$invokeBeforeEachCallbacks$1(TestMethodTestDescriptor.java:159)
	at org.junit.jupiter.engine.descriptor.TestMethodTestDescriptor.lambda$invokeBeforeMethodsOrCallbacksUntilExceptionOccurs$5(TestMethodTestDescriptor.java:195)
	at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
	at org.junit.jupiter.engine.descriptor.TestMethodTestDescriptor.invokeBeforeMethodsOrCallbacksUntilExceptionOccurs(TestMethodTestDescriptor.java:195)
	at org.junit.jupiter.engine.descriptor.TestMethodTestDescriptor.invokeBeforeEachCallbacks(TestMethodTestDescriptor.java:158)
	at org.junit.jupiter.engine.descriptor.TestMethodTestDescriptor.execute(TestMethodTestDescriptor.java:125)
	at org.junit.jupiter.engine.descriptor.TestMethodTestDescriptor.execute(TestMethodTestDescriptor.java:65)
	at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$5(NodeTestTask.java:139)
	at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
	at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$7(NodeTestTask.java:129)
	at org.junit.platform.engine.support.hierarchical.Node.around(Node.java:137)
	at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$8(NodeTestTask.java:127)
	at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
	at org.junit.platform.engine.support.hierarchical.NodeTestTask.executeRecursively(NodeTestTask.java:126)
	at org.junit.platform.engine.support.hierarchical.NodeTestTask.execute(NodeTestTask.java:84)
	at java.base/java.util.ArrayList.forEach(ArrayList.java:1541)
	at org.junit.platform.engine.support.hierarchical.SameThreadHierarchicalTestExecutorService.invokeAll(SameThreadHierarchicalTestExecutorService.java:38)
	at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$5(NodeTestTask.java:143)
	at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
	at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$7(NodeTestTask.java:129)
	at org.junit.platform.engine.support.hierarchical.Node.around(Node.java:137)
	at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$8(NodeTestTask.java:127)
	at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
	at org.junit.platform.engine.support.hierarchical.NodeTestTask.executeRecursively(NodeTestTask.java:126)
	at org.junit.platform.engine.support.hierarchical.NodeTestTask.execute(NodeTestTask.java:84)
	at java.base/java.util.ArrayList.forEach(ArrayList.java:1541)
	at org.junit.platform.engine.support.hierarchical.SameThreadHierarchicalTestExecutorService.invokeAll(SameThreadHierarchicalTestExecutorService.java:38)
	at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$5(NodeTestTask.java:143)
	at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
	at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$7(NodeTestTask.java:129)
	at org.junit.platform.engine.support.hierarchical.Node.around(Node.java:137)
	at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$8(NodeTestTask.java:127)
	at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
	at org.junit.platform.engine.support.hierarchical.NodeTestTask.executeRecursively(NodeTestTask.java:126)
	at org.junit.platform.engine.support.hierarchical.NodeTestTask.execute(NodeTestTask.java:84)
	at org.junit.platform.engine.support.hierarchical.SameThreadHierarchicalTestExecutorService.submit(SameThreadHierarchicalTestExecutorService.java:32)
	at org.junit.platform.engine.support.hierarchical.HierarchicalTestExecutor.execute(HierarchicalTestExecutor.java:57)
	at org.junit.platform.engine.support.hierarchical.HierarchicalTestEngine.execute(HierarchicalTestEngine.java:51)
	at org.junit.platform.launcher.core.EngineExecutionOrchestrator.execute(EngineExecutionOrchestrator.java:108)
	at org.junit.platform.launcher.core.EngineExecutionOrchestrator.execute(EngineExecutionOrchestrator.java:88)
	at org.junit.platform.launcher.core.EngineExecutionOrchestrator.lambda$execute$0(EngineExecutionOrchestrator.java:54)
	at org.junit.platform.launcher.core.EngineExecutionOrchestrator.withInterceptedStreams(EngineExecutionOrchestrator.java:67)
	at org.junit.platform.launcher.core.EngineExecutionOrchestrator.execute(EngineExecutionOrchestrator.java:52)
	at org.junit.platform.launcher.core.DefaultLauncher.execute(DefaultLauncher.java:96)
	at org.junit.platform.launcher.core.DefaultLauncher.execute(DefaultLauncher.java:75)
	at com.intellij.junit5.JUnit5IdeaTestRunner.startRunnerWithArgs(JUnit5IdeaTestRunner.java:71)
	at com.intellij.rt.junit.IdeaTestRunner$Repeater.startRunnerWithArgs(IdeaTestRunner.java:33)
	at com.intellij.rt.junit.JUnitStarter.prepareStreamsAndStart(JUnitStarter.java:221)
	at com.intellij.rt.junit.JUnitStarter.main(JUnitStarter.java:54)
Caused by: java.lang.IllegalStateException: Unable to determine the status of the running process. See the above logs for details
	at io.quarkus.test.common.LauncherUtil.waitForCapturedListeningData(LauncherUtil.java:74)
	at io.quarkus.test.common.NativeImageLauncher.start(NativeImageLauncher.java:118)
	at io.quarkus.test.junit.IntegrationTestUtil.startLauncher(IntegrationTestUtil.java:132)
	at io.quarkus.test.junit.QuarkusIntegrationTestExtension.doProcessStart(QuarkusIntegrationTestExtension.java:193)
	at io.quarkus.test.junit.QuarkusIntegrationTestExtension.ensureStarted(QuarkusIntegrationTestExtension.java:92)
	at io.quarkus.test.junit.QuarkusIntegrationTestExtension.beforeAll(QuarkusIntegrationTestExtension.java:64)
	at org.junit.jupiter.engine.descriptor.ClassBasedTestDescriptor.lambda$invokeBeforeAllCallbacks$8(ClassBasedTestDescriptor.java:368)
	at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
	at org.junit.jupiter.engine.descriptor.ClassBasedTestDescriptor.invokeBeforeAllCallbacks(ClassBasedTestDescriptor.java:368)
	at org.junit.jupiter.engine.descriptor.ClassBasedTestDescriptor.before(ClassBasedTestDescriptor.java:192)
	at org.junit.jupiter.engine.descriptor.ClassBasedTestDescriptor.before(ClassBasedTestDescriptor.java:78)
	at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$5(NodeTestTask.java:136)
	... 31 more

In mode debug test pass without errors

geoand · 2021-07-15T11:08:20Z

Does the failure happen every time?

Also, could you paste the contents of /Users/chabir/workspace-idea/grpc/quarkus-grpc/target/quarkus.log when the failure occurs?

xabe · 2021-07-16T07:40:29Z

Hi @geoand

Yes, here log

2021-07-15 09:52:01,964 macbook-pro-de-chabir NativeImageGeneratorRunner$JDK9Plus[75427] INFO  [com.xab.qua.grp.App] (main) Running main method
2021-07-15 09:52:06,999 macbook-pro-de-chabir NativeImageGeneratorRunner$JDK9Plus[75427] DEBUG [io.qua.ver.cor.run.VertxCoreRecorder] (main) Vert.x Cache configured to: /var/folders/g_/j0pkgddx7zg53q2m_vgz141h0000gn/T/vertx-cache/2694100486362871975
2021-07-15 09:52:07,000 macbook-pro-de-chabir NativeImageGeneratorRunner$JDK9Plus[75427] DEBUG [io.qua.ver.cor.run.VertxCoreRecorder] (main) Vertx has Native Transport Enabled: false
2021-07-15 09:52:07,001 macbook-pro-de-chabir NativeImageGeneratorRunner$JDK9Plus[75427] DEBUG [io.qua.grp.run.GrpcServerRecorder] (vert.x-eventloop-thread-0) Registered gRPC service 'grpc.health.v1.Health'
2021-07-15 09:52:07,001 macbook-pro-de-chabir NativeImageGeneratorRunner$JDK9Plus[75427] DEBUG [io.qua.grp.run.GrpcServerRecorder] (vert.x-eventloop-thread-0) Registered gRPC service 'com.xabe.CarEndPoint'
2021-07-15 09:52:07,001 macbook-pro-de-chabir NativeImageGeneratorRunner$JDK9Plus[75427] INFO  [io.qua.grp.run.GrpcServerRecorder] (vert.x-eventloop-thread-0) Registering gRPC reflection service
2021-07-15 09:52:07,001 macbook-pro-de-chabir NativeImageGeneratorRunner$JDK9Plus[75427] DEBUG [io.qua.grp.run.GrpcServerRecorder] (vert.x-eventloop-thread-0) Starting gRPC Server on 0.0.0.0:6566  [SSL enabled: false]...
2021-07-15 09:52:07,003 macbook-pro-de-chabir NativeImageGeneratorRunner$JDK9Plus[75427] INFO  [io.qua.grp.run.GrpcServerRecorder] (vert.x-eventloop-thread-1) gRPC Server started on 0.0.0.0:6566 [SSL enabled: false]
2021-07-15 09:52:07,004 macbook-pro-de-chabir NativeImageGeneratorRunner$JDK9Plus[75427] INFO  [ApplicationLifeCycle] (main) The application is starting with profile test
2021-07-15 09:52:07,005 macbook-pro-de-chabir NativeImageGeneratorRunner$JDK9Plus[75427] INFO  [io.quarkus] (main) quarkus-grpc 1.0-SNAPSHOT native (powered by Quarkus 2.0.2.Final) started in 0.034s. Listening on: http://0.0.0.0:8009
2021-07-15 09:52:07,005 macbook-pro-de-chabir NativeImageGeneratorRunner$JDK9Plus[75427] INFO  [io.quarkus] (main) Profile test activated. 
2021-07-15 09:52:07,005 macbook-pro-de-chabir NativeImageGeneratorRunner$JDK9Plus[75427] INFO  [io.quarkus] (main) Installed features: [cdi, config-yaml, grpc-server, resteasy-mutiny, smallrye-context-propagation, vertx]
2021-07-15 09:52:11,973 macbook-pro-de-chabir NativeImageGeneratorRunner$JDK9Plus[75427] DEBUG [io.qua.grp.run.GrpcServerRecorder] (vert.x-eventloop-thread-0) gRPC Server stopped
2021-07-15 09:52:11,975 macbook-pro-de-chabir NativeImageGeneratorRunner$JDK9Plus[75427] INFO  [io.quarkus] (Shutdown thread) quarkus-grpc stopped in 0.004s

xabe · 2021-07-16T08:20:37Z

Hi @geoand

I am investigating the problem because the native tests are not executed, I think the problem is in the method:

LauncherUtil.waitForCapturedListeningData

I have implemented my custom NativeImageStartedNotifier (sleep 3 seconds), test pass without errors

Executing [/Users/chabir/workspace-idea/grpc/quarkus-grpc/target/quarkus-grpc-1.0-SNAPSHOT-runner, -Dquarkus.http.port=8009, -Dquarkus.http.ssl-port=8444, -Dtest.url=http://localhost:8009, -Dquarkus.log.file.path=/Users/chabir/workspace-idea/grpc/quarkus-grpc/target/quarkus.log, -Dquarkus.log.file.enable=true, -Dquarkus.profile=test]
Custom Native Image Started Notifier
2021-07-16 09:59:56,180 INFO  [com.xab.qua.grp.App] (main) Running main method
2021-07-16 10:00:01,241 DEBUG [io.qua.ver.cor.run.VertxCoreRecorder] (main) Vert.x Cache configured to: /var/folders/g_/j0pkgddx7zg53q2m_vgz141h0000gn/T/vertx-cache/8957596241096061161
2021-07-16 10:00:01,243 DEBUG [io.qua.ver.cor.run.VertxCoreRecorder] (main) Vertx has Native Transport Enabled: false
2021-07-16 10:00:01,249 DEBUG [io.qua.grp.run.GrpcServerRecorder] (vert.x-eventloop-thread-0) Registered gRPC service 'grpc.health.v1.Health'
2021-07-16 10:00:01,250 DEBUG [io.qua.grp.run.GrpcServerRecorder] (vert.x-eventloop-thread-0) Registered gRPC service 'com.xabe.CarEndPoint'
2021-07-16 10:00:01,250 INFO  [io.qua.grp.run.GrpcServerRecorder] (vert.x-eventloop-thread-0) Registering gRPC reflection service
2021-07-16 10:00:01,250 DEBUG [io.qua.grp.run.GrpcServerRecorder] (vert.x-eventloop-thread-0) Starting gRPC Server on 0.0.0.0:6566  [SSL enabled: false]...
2021-07-16 10:00:01,258 INFO  [io.qua.grp.run.GrpcServerRecorder] (vert.x-eventloop-thread-1) gRPC Server started on 0.0.0.0:6566 [SSL enabled: false]
2021-07-16 10:00:01,259 INFO  [ApplicationLifeCycle] (main) The application is starting with profile test
2021-07-16 10:00:01,266 INFO  [io.quarkus] (main) quarkus-grpc 1.0-SNAPSHOT native (powered by Quarkus 2.0.2.Final) started in 0.077s. Listening on: http://0.0.0.0:8009
2021-07-16 10:00:01,266 INFO  [io.quarkus] (main) Profile test activated. 
2021-07-16 10:00:01,267 INFO  [io.quarkus] (main) Installed features: [cdi, config-yaml, grpc-server, resteasy-mutiny, smallrye-context-propagation, vertx]

I think that in the method it has wrong is the fixed value of 10 seconds in the variable signal, Shouldn't that be the value of waitTimeSeconds?

   static ListeningAddress waitForCapturedListeningData(Process quarkusProcess, Path logFile, long waitTimeSeconds) {
        CountDownLatch signal = new CountDownLatch(1);
        AtomicReference<ListeningAddress> resultReference = new AtomicReference<>();
        CaptureListeningDataReader captureListeningDataReader = new CaptureListeningDataReader(logFile,
                Duration.ofSeconds(waitTimeSeconds), signal, resultReference);
        new Thread(captureListeningDataReader, "capture-listening-data").start();
        try {
            signal.await(10, TimeUnit.SECONDS);
            ListeningAddress result = resultReference.get();
            if (result != null) {
                return result;
            }
            destroyProcess(quarkusProcess);
            throw new IllegalStateException(
                    "Unable to determine the status of the running process. See the above logs for details");
        } catch (InterruptedException e) {
            throw new RuntimeException("Interrupted while waiting to capture listening process port and protocol");
        }
    }```

geoand · 2021-07-16T09:51:33Z

Indeed, that has already been fixed in 2.1.0.CR1 (see https://github.com/quarkusio/quarkus/blob/2.1.0.CR1/test-framework/common/src/main/java/io/quarkus/test/common/LauncherUtil.java#L71).

Mind giving that version a try?

xabe · 2021-07-16T15:32:57Z

Hi @geoand

I have same error

INFO] Running com.xabe.quarkus.grpc.infrastructure.controller.CarGrpcControllerIT
Executing [/Users/chabir/workspace-idea/grpc/quarkus-grpc/target/quarkus-grpc-1.0-SNAPSHOT-runner, -Dquarkus.http.port=8009, -Dquarkus.http.ssl-port=8444, -Dtest.url=http://localhost:8009, -Dquarkus.log.file.path=/Users/chabir/workspace-idea/grpc/quarkus-grpc/target/quarkus.log, -Dquarkus.log.file.enable=true, -Dquarkus.profile=test]
2021-07-16 13:13:48,818 INFO  [com.xab.qua.grp.App] (main) Running main method
2021-07-16 13:13:53,851 DEBUG [io.qua.ver.cor.run.VertxCoreRecorder] (main) Vert.x Cache configured to: /var/folders/g_/j0pkgddx7zg53q2m_vgz141h0000gn/T/vertx-cache/2887154751665162719
2021-07-16 13:13:53,852 DEBUG [io.qua.ver.cor.run.VertxCoreRecorder] (main) Vertx has Native Transport Enabled: false
2021-07-16 13:13:53,853 DEBUG [io.qua.grp.run.GrpcServerRecorder] (vert.x-eventloop-thread-0) Registered gRPC service 'grpc.health.v1.Health'
2021-07-16 13:13:53,853 DEBUG [io.qua.grp.run.GrpcServerRecorder] (vert.x-eventloop-thread-0) Registered gRPC service 'com.xabe.CarEndPoint'
2021-07-16 13:13:53,853 INFO  [io.qua.grp.run.GrpcServerRecorder] (vert.x-eventloop-thread-0) Registering gRPC reflection service
2021-07-16 13:13:53,853 DEBUG [io.qua.grp.run.GrpcServerRecorder] (vert.x-eventloop-thread-0) Starting gRPC Server on 0.0.0.0:6566  [SSL enabled: false]...
2021-07-16 13:13:53,855 INFO  [io.qua.grp.run.GrpcServerRecorder] (vert.x-eventloop-thread-1) gRPC Server started on 0.0.0.0:6566 [SSL enabled: false]
2021-07-16 13:13:53,856 INFO  [ApplicationLifeCycle] (main) The application is starting with profile test
2021-07-16 13:13:53,857 INFO  [io.quarkus] (main) quarkus-grpc 1.0-SNAPSHOT native (powered by Quarkus 2.1.0.CR1) started in 0.031s. Listening on: http://0.0.0.0:8009
2021-07-16 13:13:53,857 INFO  [io.quarkus] (main) Profile test activated.
2021-07-16 13:13:53,857 INFO  [io.quarkus] (main) Installed features: [cdi, config-yaml, grpc-server, resteasy-mutiny, smallrye-context-propagation, vertx]
[ERROR] Tests run: 4, Failures: 0, Errors: 1, Skipped: 3, Time elapsed: 63.745 s <<< FAILURE! - in com.xabe.quarkus.grpc.infrastructure.controller.CarGrpcControllerIT
[ERROR] com.xabe.quarkus.grpc.infrastructure.controller.CarGrpcControllerIT.givenACarIdWhenInvokeGetNavigateCarThenReturnErrorStream  Time elapsed: 0.011 s  <<< ERROR!
java.lang.RuntimeException: java.lang.IllegalStateException: Unable to determine the status of the running process. See the above logs for details
Caused by: java.lang.IllegalStateException: Unable to determine the status of the running process. See the above logs for details

It's a race condition issue, now the error is because the log file does not exist

https://github.com/quarkusio/quarkus/blob/2.1.0.CR1/test-framework/common/src/main/java/io/quarkus/test/common/LauncherUtil.java#L194

Here is an error trace missing when the log file is not found

https://github.com/quarkusio/quarkus/blob/2.1.0.CR1/test-framework/common/src/main/java/io/quarkus/test/common/LauncherUtil.java#L242

Wouldn't it be better here to increase the time to 500ms?, Have more time to ensure that the log file exists

geoand · 2021-07-16T15:48:27Z

Are you sure that is what happening?
That sleep is in a loop that tries 25 times before bailing out

xabe · 2021-07-16T21:23:58Z

Hi @geoand

it's weird but here it link video, the problem that the native boot process takes several seconds before write in file log

geoand · 2021-07-17T06:47:54Z

What happens if you simply run:

/Users/chabir/workspace-idea/grpc/quarkus-grpc/target/quarkus-grpc-1.0-SNAPSHOT-runner -Dquarkus.http.port=8009 -Dquarkus.http.ssl-port=8444 -Dtest.url=http://localhost:8009 -Dquarkus.log.file.path=/Users/chabir/workspace-idea/grpc/quarkus-grpc/target/quarkus.log -Dquarkus.log.file.enable=true -Dquarkus.profile=test

after the test has failed? Is the log file created?

xabe · 2021-07-17T07:04:48Z

Hi @geoand

Yes, create file log, when I put a debug and break point it test pass without errors.

2021-07-16 22:56:09,220 macbook-pro-de-chabir NativeImageGeneratorRunner$JDK9Plus[97529] INFO  [com.xab.qua.grp.App] (main) Running main method
2021-07-16 22:56:14,247 macbook-pro-de-chabir NativeImageGeneratorRunner$JDK9Plus[97529] DEBUG [io.qua.ver.cor.run.VertxCoreRecorder] (main) Vert.x Cache configured to: /var/folders/g_/j0pkgddx7zg53q2m_vgz141h0000gn/T/vertx-cache/2664654344072547754
2021-07-16 22:56:14,248 macbook-pro-de-chabir NativeImageGeneratorRunner$JDK9Plus[97529] DEBUG [io.qua.ver.cor.run.VertxCoreRecorder] (main) Vertx has Native Transport Enabled: false
2021-07-16 22:56:14,249 macbook-pro-de-chabir NativeImageGeneratorRunner$JDK9Plus[97529] DEBUG [io.qua.grp.run.GrpcServerRecorder] (vert.x-eventloop-thread-0) Registered gRPC service 'grpc.health.v1.Health'
2021-07-16 22:56:14,249 macbook-pro-de-chabir NativeImageGeneratorRunner$JDK9Plus[97529] DEBUG [io.qua.grp.run.GrpcServerRecorder] (vert.x-eventloop-thread-0) Registered gRPC service 'com.xabe.CarEndPoint'
2021-07-16 22:56:14,249 macbook-pro-de-chabir NativeImageGeneratorRunner$JDK9Plus[97529] INFO  [io.qua.grp.run.GrpcServerRecorder] (vert.x-eventloop-thread-0) Registering gRPC reflection service
2021-07-16 22:56:14,249 macbook-pro-de-chabir NativeImageGeneratorRunner$JDK9Plus[97529] DEBUG [io.qua.grp.run.GrpcServerRecorder] (vert.x-eventloop-thread-0) Starting gRPC Server on 0.0.0.0:6566  [SSL enabled: false]...
2021-07-16 22:56:14,252 macbook-pro-de-chabir NativeImageGeneratorRunner$JDK9Plus[97529] INFO  [io.qua.grp.run.GrpcServerRecorder] (vert.x-eventloop-thread-1) gRPC Server started on 0.0.0.0:6566 [SSL enabled: false]
2021-07-16 22:56:14,253 macbook-pro-de-chabir NativeImageGeneratorRunner$JDK9Plus[97529] INFO  [ApplicationLifeCycle] (main) The application is starting with profile test
2021-07-16 22:56:14,255 macbook-pro-de-chabir NativeImageGeneratorRunner$JDK9Plus[97529] INFO  [io.quarkus] (main) quarkus-grpc 1.0-SNAPSHOT native (powered by Quarkus 2.1.0.CR1) started in 0.030s. Listening on: http://0.0.0.0:8009
2021-07-16 22:56:14,255 macbook-pro-de-chabir NativeImageGeneratorRunner$JDK9Plus[97529] INFO  [io.quarkus] (main) Profile test activated. 
2021-07-16 22:56:14,255 macbook-pro-de-chabir NativeImageGeneratorRunner$JDK9Plus[97529] INFO  [io.quarkus] (main) Installed features: [cdi, config-yaml, grpc-server, resteasy-mutiny, smallrye-context-propagation, vertx]
2021-07-16 22:56:23,535 macbook-pro-de-chabir NativeImageGeneratorRunner$JDK9Plus[97529] DEBUG [io.qua.grp.run.GrpcServerRecorder] (vert.x-eventloop-thread-0) gRPC Server stopped
2021-07-16 22:56:23,536 macbook-pro-de-chabir NativeImageGeneratorRunner$JDK9Plus[97529] INFO  [io.quarkus] (Shutdown thread) quarkus-grpc stopped in 0.002s

geoand · 2021-07-17T07:06:42Z

I'll increase the timeout and hopefully that will fix the issue

gsmet · 2021-07-21T11:53:39Z

@geoand did you do it in the end?

geoand · 2021-07-21T11:55:37Z

Good think you mentioned it!

I did in #18758.

So I'll close this. Please reopen if the issue persists with 2.1.0.Final

xabe · 2021-07-30T07:43:34Z

@geoand it worked

Thanks for the help

geoand · 2021-07-30T07:44:34Z

👍🏼

xabe added the kind/bug Something isn't working label Jul 15, 2021

quarkus-bot bot added area/grpc gRPC area/testing labels Jul 15, 2021

geoand closed this as completed Jul 21, 2021

geoand added this to the 2.1.0.Final milestone Jul 21, 2021

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Grpc Server QuarkusIntegrationTest fail #18706

Grpc Server QuarkusIntegrationTest fail #18706

xabe commented Jul 15, 2021 •

edited

Loading

quarkus-bot bot commented Jul 15, 2021

geoand commented Jul 15, 2021

xabe commented Jul 15, 2021

geoand commented Jul 15, 2021

xabe commented Jul 16, 2021

xabe commented Jul 16, 2021

geoand commented Jul 16, 2021

xabe commented Jul 16, 2021

geoand commented Jul 16, 2021

xabe commented Jul 16, 2021

geoand commented Jul 17, 2021

xabe commented Jul 17, 2021

geoand commented Jul 17, 2021

gsmet commented Jul 21, 2021

geoand commented Jul 21, 2021

xabe commented Jul 30, 2021

geoand commented Jul 30, 2021

Grpc Server QuarkusIntegrationTest fail #18706

Grpc Server QuarkusIntegrationTest fail #18706

Comments

xabe commented Jul 15, 2021 • edited Loading

Describe the bug

Expected behavior

Actual behavior

How to Reproduce?

Output of uname -a or ver

Output of java -version

GraalVM version (if different from Java)

Quarkus version or git rev

Build tool (ie. output of mvnw --version or gradlew --version)

Additional information

quarkus-bot bot commented Jul 15, 2021

geoand commented Jul 15, 2021

xabe commented Jul 15, 2021

geoand commented Jul 15, 2021

xabe commented Jul 16, 2021

xabe commented Jul 16, 2021

geoand commented Jul 16, 2021

xabe commented Jul 16, 2021

geoand commented Jul 16, 2021

xabe commented Jul 16, 2021

geoand commented Jul 17, 2021

xabe commented Jul 17, 2021

geoand commented Jul 17, 2021

gsmet commented Jul 21, 2021

geoand commented Jul 21, 2021

xabe commented Jul 30, 2021

geoand commented Jul 30, 2021

xabe commented Jul 15, 2021 •

edited

Loading

Output of `uname -a` or `ver`

Output of `java -version`

Build tool (ie. output of `mvnw --version` or `gradlew --version`)