Quarkus not properly shutting down results in native image trace agent log being truncated

[JohT]

Describe the bug

When adding the native image trace agent to integration tests to trace reflection usage, the resulting JSON file ends abruptly without the closing part and is therefore corrupt. Everything works fine with version 3.1.3.Final. The problem only occurs with version 3.2.0.CR1 and above.

Expected behavior

The integration test should be shutdown in a clean way so that the native image trace agent JSON output file is flushed.

Actual behavior

After running mvn verify --activate-profiles native-image-agent-trace locally or in the pipeline on my repository showcase-quarkus-eventsourcing, the generated JSON is corrupt (not closed correctly) and the very last lines look e.g. like this:

{"caller_class":"java.lang.invoke.InnerClassLambdaMetafactory$1", "args":[], "function":"getDeclaredConstructors", "tracer":"reflect", "class":"io.smallrye.openapi.api.OpenApiConfig$$Lambda$1757/0x00000008014abf70"},
{"caller_class":"java.lang.invoke.InnerClassLambdaMetafactory", "result":"true", "args":[[]], "declaring_class":"io.smallrye.openapi.api.OpenApiConfig$$Lambda$1757/0x00000008014abf70", "function":"invokeConstructor", "tracer":"reflect", "class":"io.smallrye.openapi.api.OpenApiConfig$$Lambda$1757/0x00000008014abf70"},
{"caller_class":"java.lang.invoke.InnerClassLambdaMetafactory$1", "args":[], "function":"getDeclaredConstructors", "tracer":"reflect", "class":"io.smallrye.openapi.api.OpenApiConfig$$Lambda$1758/0x00000008014ac190"},
{"caller_class":"java.lang.invoke.InnerClassLambdaMetafactory", "result":"true", "args":[[]], "declaring_class":"io.smallrye.openapi.api.OpenApiConfig$$Lambda$1758/0x00000008014ac190", "function":"invokeConstructor", "tracer":"reflect", "class":"io.smallrye.openapi.api.OpenApiConfig$$L

Trying to process the corrupt JSON file locally with $GRAALVM_HOME/bin/native-image-configure generate --trace-input=target/native-image-agent-trace.json or in the pipeline leads to an expected error like this:

com.oracle.svm.core.util.json.JSONParserException: line 23493 column 286 Missing close quote
        at org.graalvm.nativeimage.builder/com.oracle.svm.core.util.json.JSONParser.error(JSONParser.java:377)
        at org.graalvm.nativeimage.builder/com.oracle.svm.core.util.json.JSONParser.parseString(JSONParser.java:221)

I suspect that the JVM for testing is shutdown without waiting for files to be flushed or something like that. But that's just an idea. Don't know if this could be....

Everything is working fine with quarkus 3.1.3.Final. The change seems to had been introduced with 3.2.0.CR1:
3.1.3.Final...3.2.0.CR1

How to Reproduce?

Reproducer with detailed description: JohT/showcase-quarkus-eventsourcing#247

Output of uname -a or ver

Darwin...RELEASE_ARM64_T8101 arm64

Output of java -version

OpenJDK 64-Bit Server VM Temurin-17.0.7+7 (build 17.0.7+7, mixed mode)

Quarkus version or git rev

3.2.0.CR1

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

Apache Maven 3.9.6 (bc0240f3c744dd6b6ec2920b3cd08dcc295161ae)

Additional information

No response

[quarkus-bot]

/cc @brunobat (tracing), @radcortez (tracing), @zakkak (native-image)

[zakkak]

cc @galderz due to your recent work in #36826

[galderz]

Can you try with the latest Quarkus version combined the latest GraalVM CE version (either JDK 17 or the JDK 21)?

Also, to avoid confusion, the work in #36826 is ongoing and not yet fully fledged. Having said that, I've not seen any such truncation in my experiments.

[JohT]

I tried it with

• Oracle GraalVM 17.0.9+11.1
• quarkus.platform.version=3.6.3
• quarkus.plugin.version=3.6.4

and got the same result:
https://github.com/JohT/showcase-quarkus-eventsourcing/actions/runs/7345345113/job/19998376066?pr=252

$GRAALVM_HOME/bin/native-image-configure generate --trace-input=target/native-image-agent-trace.json --output-dir=target/native-image-agent-trace-configs --caller-filter-file=native-image-caller-filter-rules.json

failed with

org.graalvm.util.json.JSONParserException: line 24979 column 377 Expected : but found eof
	at jdk.internal.vm.compiler/org.graalvm.util.json.JSONParser.error(JSONParser.java:389)
	at jdk.internal.vm.compiler/org.graalvm.util.json.JSONParser.expectedError(JSONParser.java:465)
	at jdk.internal.vm.compiler/org.graalvm.util.json.JSONParser.expectColon(JSONParser.java:163)

0_native-image-build (17).txt

[galderz]

Thanks for trying that @JohT. I've replicated the issue locally and I'm looking into it.

[galderz]

I suspect that the JVM for testing is shutdown without waiting for files to be flushed or something like that. But that's just an idea. Don't know if this could be....

Let's start by saying that the theory ^ might be on the right track. After trying different things out I've noticed that when the test works fine, Quarkus shutsdown appropiately, e.g.

2024-01-11 12:50:59,835 m22 quarkus-run.jar[22990] INFO  [org.axo.eve.TrackingEventProcessor] (Shutdown thread) Processor 'io.github.joht.showcase.quarkuseventsourcing.domain.model.account' awaiting termination...
2024-01-11 12:51:00,381 m22 quarkus-run.jar[22990] INFO  [org.axo.eve.TrackingEventProcessor] (EventProcessor[io.github.joht.showcase.quarkuseventsourcing.domain.model.account]-0) Released claim
2024-01-11 12:51:00,382 m22 quarkus-run.jar[22990] INFO  [org.axo.eve.TrackingEventProcessor] (EventProcessor[io.github.joht.showcase.quarkuseventsourcing.domain.model.account]-0) Worker for segment Segment[0/0] stopped.
2024-01-11 12:51:00,645 m22 quarkus-run.jar[22990] INFO  [org.axo.eve.TrackingEventProcessor] (EventProcessor[query.model.nickname]-1) Released claim
2024-01-11 12:51:00,646 m22 quarkus-run.jar[22990] INFO  [org.axo.eve.TrackingEventProcessor] (EventProcessor[query.model.nickname]-1) Worker for segment Segment[0/0] stopped.
2024-01-11 12:51:00,677 m22 quarkus-run.jar[22990] INFO  [io.quarkus] (Shutdown thread) showcase-quarkus-eventsourcing stopped in 0.935s

But from Quarkus 3.2.0.CR1 onwards it doesn't with the last line in the log being:

2024-01-11 12:43:09,263 m22 quarkus-run.jar[22770] INFO  [org.axo.eve.TrackingEventProcessor] (main) Processor 'io.github.joht.showcase.quarkuseventsourcing.domain.model.account' awaiting termination...

I've verified that latest main still has this issue, and the issue is irrespective of the GraalVM version used. Since this is a Java process running with an agent, GraalVM's impact is limited to the agent library in used.

So, the question then is about what causes Quarkus to stop? Is it the GraalVM native agent? The answer is no, GraalVM native agent has no impact here. So, if we remove the agent parameters, the Quarkus log still shows the abrupt shutdown:

2024-01-11 12:56:27,448 m22 quarkus-run.jar[23184] INFO  [org.axo.eve.TrackingEventProcessor] (main) Processor 'io.github.joht.showcase.quarkuseventsourcing.domain.model.account' awaiting termination...

So at this point this issue is no longer GraalVM related and hence I need to unassign myself from this issue. The native image agent trace log being truncated is the result of the Quarkus JVM process not shutting down properly.

@geoandri @gsmet Who can take over this issue?