Replace read/write lock in JarResource to avoid virtual threads pinning #42139

mariofusco · 2024-07-25T13:16:25Z

This pull request fixes the race condition present in this commit that, because of it, had to be reverted.

/cc @geoand @gsmet @franz1981 @jedla97 @michalvavrik

Fixes: #42067

The nature of the fix is described at #42139 (review)

mariofusco · 2024-07-25T13:24:14Z

...nt-projects/bootstrap/runner/src/main/java/io/quarkus/bootstrap/runner/JarFileReference.java

+
+    private static JarFileReference asyncLoadAcquiredJarFile(JarResource jarResource) {
+        CompletableFuture<JarFileReference> newJarRefFuture = new CompletableFuture<>();
+        CompletableFuture<JarFileReference> existingJarRefFuture = null;


The introduction of this variable is the actual fix. The old algorithm wrongly reused the newJarFileRef one. This means that in the unfortunate case when a thread was about to close the old jar, but before setting the AtomicReference to null, another thread could fail the compareAndSet(null) check here, take at the end of the loop from the AtomicReference the old and no longer valid CompletableFuture and in subsequent loop (after that the close finally managed to set the AtomicReference to null) mistakenly set it back into the same AtomicReference.

jedla97 · 2024-07-25T14:10:28Z

@famod can you check as well if it's fixed on your end? As you encounter that problem as well.

I'll will check it on our side but it's always good to have second confirmation.

geoand · 2024-07-25T14:15:36Z

Thanks for the fix @mariofusco !

@jedla97 thanks for signing up to test the fix! Hopefully @famod can do so as well

jedla97 · 2024-07-25T21:13:41Z

@mariofusco Big thanks for the fix as I believe it was hard to find it. I tested it (run two reproducer multiple times) and the race condition didn't appear. So from my POV the original issue is fixed (hopefully we won't see any different 🙏 ).

franz1981 · 2024-07-26T05:13:28Z

It would be great if there is a test which reproduce it too, with the changes to fix

famod · 2024-07-26T22:53:54Z

Sorry, I am unable to test this ATM. On my work machine, I'm getting a puzzling dependency resolution issue while building, it's related to gradle-tooling.

mariofusco · 2024-07-29T14:15:43Z

It would be great if there is a test which reproduce it too, with the changes to fix

I did a few more checks on this fix and also added a proper unit test. The unit test reproduces exactly the same situation that caused the IllegalStateException in the former version of this class loader as I described it here. Of course, being a race condition, the test is not deterministic and it fails with the older version extremely seldomly. However it's descriptive of the problem and I'm afraid it will be impossible to make it reproducible in a more reliable way.

@geoand @franz1981 the pull request has been already rebased and squashed as usual, so it should be ready to be merged. Please let me know if this is enough or you see any room for further improvements.

franz1981

LGTM well done as usual Mario!

geoand

Thanks a lot!

mariofusco · 2024-07-30T07:28:47Z

Failing Jobs

Status Name Step Failures Logs Raw logs Build scan
✖ JVM Tests - JDK 17 Build Failures Logs Raw logs 🔍
✖ JVM Tests - JDK 17 Windows Build Failures Logs Raw logs 🔍

These failures are caused by the fact that I compiled the minimal jars that I used for this test with Java 21, so they cannot be loaded with Java 17.

java.lang.UnsupportedClassVersionError: org/simple/SimplePojo1 has been compiled by a more recent version of the Java Runtime (class file version 65.0), this version of the Java Runtime only recognizes class file versions up to 61.0

I will recompile those jars with Java 17 and replace them in this pull request immediately.

add test format test recompile test jars with jdk17

mariofusco · 2024-07-30T08:04:32Z

I will recompile those jars with Java 17 and replace them in this pull request immediately.

Done.

quarkus-bot · 2024-07-30T14:22:23Z

Status for workflow `Quarkus CI`

This is the status report for running Quarkus CI on commit 0c479ce.

Failing Jobs

Status	Name	Step	Failures	Logs	Raw logs	Build scan
✔️	Native Tests - Messaging1		Failures	Logs	Raw logs	🚧

Full information is available in the Build summary check run.

Failures

⚙️ Native Tests - Messaging1 #

📦 integration-tests/kafka-avro-apicurio2

✖ io.quarkus.it.kafka.KafkaAvroIT.testApicurioAvroConsumer - History - More details - Source on GitHub

java.lang.RuntimeException: 
java.lang.RuntimeException: io.quarkus.builder.BuildException: Build failure: Build failed due to errors
	[error]: Build step io.quarkus.kafka.client.deployment.DevServicesKafkaProcessor#startKafkaDevService threw an exception: java.lang.RuntimeException: org.testcontainers.containers.ContainerFetchException: Can't get Docker image: RemoteDockerImage(imageName=docker.io/vectorized/redpanda:v24.1.2, imagePullPolicy=DefaultPullPolicy(), imageNameSubstitutor=org.testcontainers.utility.ImageNameSubstitutor$LogWrappedImageNameSubstitutor@74c1204d)
	at io.quarkus.kafka.client.deployment.DevServicesKafkaProcessor.startKafkaDevService(DevServicesKafkaProcessor.java:105)
	at java.base/java.lang.invoke.MethodHandle.invokeWithArguments(MethodHandle.java:732)
	at io.quarkus.deployment.ExtensionLoader$3.execute(ExtensionLoader.java:854)
	at io.quarkus.builder.BuildContext.run(BuildContext.java:256)
	at org.jboss.threads.ContextHandler$1.runWith(ContextHandler.java:18...

✖ io.quarkus.it.kafka.KafkaAvroIT.testApicurioAvroProducer - History - More details - Source on GitHub

java.lang.RuntimeException: 
java.lang.RuntimeException: io.quarkus.builder.BuildException: Build failure: Build failed due to errors
	[error]: Build step io.quarkus.kafka.client.deployment.DevServicesKafkaProcessor#startKafkaDevService threw an exception: java.lang.RuntimeException: org.testcontainers.containers.ContainerFetchException: Can't get Docker image: RemoteDockerImage(imageName=docker.io/vectorized/redpanda:v24.1.2, imagePullPolicy=DefaultPullPolicy(), imageNameSubstitutor=org.testcontainers.utility.ImageNameSubstitutor$LogWrappedImageNameSubstitutor@66eb61f4)
	at io.quarkus.kafka.client.deployment.DevServicesKafkaProcessor.startKafkaDevService(DevServicesKafkaProcessor.java:105)
	at java.base/java.lang.invoke.MethodHandle.invokeWithArguments(MethodHandle.java:732)
	at io.quarkus.deployment.ExtensionLoader$3.execute(ExtensionLoader.java:854)
	at io.quarkus.builder.BuildContext.run(BuildContext.java:256)
	at org.jboss.threads.ContextHandler$1.runWith(ContextHandler.java:18...

✖ io.quarkus.it.kafka.KafkaAvroIT.testConfluentAvroConsumer - History - More details - Source on GitHub

java.lang.RuntimeException: 
java.lang.RuntimeException: io.quarkus.builder.BuildException: Build failure: Build failed due to errors
	[error]: Build step io.quarkus.kafka.client.deployment.DevServicesKafkaProcessor#startKafkaDevService threw an exception: java.lang.RuntimeException: org.testcontainers.containers.ContainerFetchException: Can't get Docker image: RemoteDockerImage(imageName=docker.io/vectorized/redpanda:v24.1.2, imagePullPolicy=DefaultPullPolicy(), imageNameSubstitutor=org.testcontainers.utility.ImageNameSubstitutor$LogWrappedImageNameSubstitutor@563e520)
	at io.quarkus.kafka.client.deployment.DevServicesKafkaProcessor.startKafkaDevService(DevServicesKafkaProcessor.java:105)
	at java.base/java.lang.invoke.MethodHandle.invokeWithArguments(MethodHandle.java:732)
	at io.quarkus.deployment.ExtensionLoader$3.execute(ExtensionLoader.java:854)
	at io.quarkus.builder.BuildContext.run(BuildContext.java:256)
	at org.jboss.threads.ContextHandler$1.runWith(ContextHandler.java:18)...

✖ io.quarkus.it.kafka.KafkaAvroIT.testConfluentAvroProducer - History - More details - Source on GitHub

java.lang.RuntimeException: 
java.lang.RuntimeException: io.quarkus.builder.BuildException: Build failure: Build failed due to errors
	[error]: Build step io.quarkus.kafka.client.deployment.DevServicesKafkaProcessor#startKafkaDevService threw an exception: java.lang.RuntimeException: org.testcontainers.containers.ContainerFetchException: Can't get Docker image: RemoteDockerImage(imageName=docker.io/vectorized/redpanda:v24.1.2, imagePullPolicy=DefaultPullPolicy(), imageNameSubstitutor=org.testcontainers.utility.ImageNameSubstitutor$LogWrappedImageNameSubstitutor@171be7de)
	at io.quarkus.kafka.client.deployment.DevServicesKafkaProcessor.startKafkaDevService(DevServicesKafkaProcessor.java:105)
	at java.base/java.lang.invoke.MethodHandle.invokeWithArguments(MethodHandle.java:732)
	at io.quarkus.deployment.ExtensionLoader$3.execute(ExtensionLoader.java:854)
	at io.quarkus.builder.BuildContext.run(BuildContext.java:256)
	at org.jboss.threads.ContextHandler$1.runWith(ContextHandler.java:18...

✖ io.quarkus.it.kafka.KafkaAvroIT.testUrls - History - More details - Source on GitHub

java.lang.RuntimeException: 
java.lang.RuntimeException: io.quarkus.builder.BuildException: Build failure: Build failed due to errors
	[error]: Build step io.quarkus.kafka.client.deployment.DevServicesKafkaProcessor#startKafkaDevService threw an exception: java.lang.RuntimeException: org.testcontainers.containers.ContainerFetchException: Can't get Docker image: RemoteDockerImage(imageName=docker.io/vectorized/redpanda:v24.1.2, imagePullPolicy=DefaultPullPolicy(), imageNameSubstitutor=org.testcontainers.utility.ImageNameSubstitutor$LogWrappedImageNameSubstitutor@1717cdcc)
	at io.quarkus.kafka.client.deployment.DevServicesKafkaProcessor.startKafkaDevService(DevServicesKafkaProcessor.java:105)
	at java.base/java.lang.invoke.MethodHandle.invokeWithArguments(MethodHandle.java:732)
	at io.quarkus.deployment.ExtensionLoader$3.execute(ExtensionLoader.java:854)
	at io.quarkus.builder.BuildContext.run(BuildContext.java:256)
	at org.jboss.threads.ContextHandler$1.runWith(ContextHandler.java:18...

Flaky tests - Develocity

⚙️ JVM Tests - JDK 21

📦 integration-tests/opentelemetry

✖ io.quarkus.it.opentelemetry.OpenTelemetryInjectionsTest.testOTelInjections - History

Condition with Lambda expression in io.quarkus.it.opentelemetry.OpenTelemetryInjectionsTest was not fulfilled within 5 seconds. - org.awaitility.core.ConditionTimeoutException

org.awaitility.core.ConditionTimeoutException: Condition with Lambda expression in io.quarkus.it.opentelemetry.OpenTelemetryInjectionsTest was not fulfilled within 5 seconds.
	at org.awaitility.core.ConditionAwaiter.await(ConditionAwaiter.java:167)
	at org.awaitility.core.CallableCondition.await(CallableCondition.java:78)
	at org.awaitility.core.CallableCondition.await(CallableCondition.java:26)
	at org.awaitility.core.ConditionFactory.until(ConditionFactory.java:1006)
	at org.awaitility.core.ConditionFactory.until(ConditionFactory.java:975)
	at io.quarkus.it.opentelemetry.OpenTelemetryInjectionsTest.reset(OpenTelemetryInjectionsTest.java:26)
	at java.base/java.lang.reflect.Method.invoke(Method.java:580)

mariofusco · 2024-07-31T07:44:58Z

Is this ready to be merged? Since the 3.13.0 is already out there shouldn't be any reason to hold it, right?

geoand · 2024-07-31T07:47:54Z

Correct

geoand · 2024-07-31T07:48:23Z

Let's keep an eye out on weird failures as we did with the previous iteration.

mariofusco · 2024-07-31T07:50:20Z

Let's keep an eye out on weird failures as we did with the previous iteration.

Thank you for merging. Sure, please ping me as soon as you will notice something wrong.

geoand · 2024-07-31T07:54:46Z

Will do! Thanks again for tackling this!

If anything comes up, it will be by QE running their testsuite over the next few days. Otherwise if there is an issue, reports from users will start coming in when 3.14.0.CR1 is released.

quarkus-bot bot added the area/devtools Issues/PR related to maven, gradle, platform and cli tooling/plugins label Jul 25, 2024

mariofusco commented Jul 25, 2024

View reviewed changes

mariofusco mentioned this pull request Jul 25, 2024

App with Infinispan fails after changes in JarFileReference that rarely results in illegal state after changes on ReadWriteLock #42067

Closed