quarkus: OverlappingFileLockException in JaCoCo when using offline instrumentation due to duplicate shutdown hooks (classloading issue)

Describe the bug We are trying to implement test coverage measurement as described here: https://quarkus.io/guides/tests-with-coverage#instrumenting-the-classes-instead

For the most part this is working, but we are seeing this exception at the end of the surefire/test executions in some of our Maven modules:

java.nio.channels.OverlappingFileLockException
        at java.base/sun.nio.ch.FileLockTable.checkList(FileLockTable.java:229)
        at java.base/sun.nio.ch.FileLockTable.add(FileLockTable.java:123)
        at java.base/sun.nio.ch.FileChannelImpl.lock(FileChannelImpl.java:1109)
        at java.base/java.nio.channels.FileChannel.lock(FileChannel.java:1063)
        at org.jacoco.agent.rt.internal_43f5073.output.FileOutput.openFile(FileOutput.java:70)
        at org.jacoco.agent.rt.internal_43f5073.output.FileOutput.writeExecutionData(FileOutput.java:54)
        at org.jacoco.agent.rt.internal_43f5073.Agent.shutdown(Agent.java:145)
        at org.jacoco.agent.rt.internal_43f5073.Agent$1.run(Agent.java:58)

After we stumbled upon https://github.com/jacoco/jacoco/issues/331#issuecomment-122827449, I debugged this and indeed in some cases the JaCoCo Agent ShutdownHook is registered twice, most likely because some of our instrumented classes are loaded from different classloaders (by Quarkus).

In one case the first Agent.getInstance() call stack looks like this:

Runtime.addShutdownHook(Thread) line: 213	
Agent.getInstance(AgentOptions) line: 55	
Offline.getRuntimeData() line: 39	
Offline.getProbes(long, String, int) line: 60	
SharedConfigSourceProvider.$jacocoInit(MethodHandles$Lookup, String, Class) line: not available	
404458571.invokeStaticInit(Object, Object, Object, Object) line: not available	
DelegatingMethodHandle$Holder.reinvoke_L(Object, Object, Object, Object) line: not available	
1131710157.invoke_MT(Object, Object, Object, Object, Object) line: not available	
BootstrapMethodInvoker.invoke(MethodHandle, MethodHandles$Lookup, String, Object) line: 204	
BootstrapMethodInvoker.invoke(Class<T>, MethodHandle, String, Object, Object, Class<?>) line: 90	
ConstantBootstraps.makeConstant(MethodHandle, String, Class<?>, Object, Class<?>) line: 67	
MethodHandleNatives.linkDynamicConstantImpl(Class<?>, MethodHandle, String, Class<?>, Object) line: 314	
MethodHandleNatives.linkDynamicConstant(Object, int, Object, Object, Object, Object) line: 306	
SharedConfigSourceProvider.<clinit>() line: 38	
NativeConstructorAccessorImpl.newInstance0(Constructor<?>, Object[]) line: not available [native method]	
NativeConstructorAccessorImpl.newInstance(Object[]) line: 62	
DelegatingConstructorAccessorImpl.newInstance(Object[]) line: 45	
Constructor<T>.newInstance(Object...) line: 490	
ServiceLoader$ProviderImpl<S>.newInstance() line: 779	
ServiceLoader$ProviderImpl<S>.get() line: 721	
ServiceLoader$3.next() line: 1394	
ServiceLoader<S>(Iterable<T>).forEach(Consumer<? super T>) line: 74	
SmallRyeConfigBuilder.discoverSources() line: 79	
SmallRyeConfigBuilder.build() line: 175	
ExtensionLoader.loadStepsFrom(ClassLoader, Properties, LaunchMode, Consumer<ConfigBuilder>) line: 192	
ExtensionLoader.loadStepsFrom(ClassLoader, LaunchMode, Consumer<ConfigBuilder>) line: 135	
QuarkusAugmentor.run() line: 101	
AugmentActionImpl.runAugment(boolean, Set<String>, ClassLoader, Class<BuildItem>...) line: 245	
AugmentActionImpl.createInitialRuntimeApplication() line: 130	
AugmentActionImpl.createInitialRuntimeApplication() line: 52	
QuarkusTestExtension.doJavaStart(ExtensionContext) line: 140

Notes:

• SharedConfigSourceProvider is a custom ConfigSourceProvider we had to implement because we have multiple application*.yaml files in multiple modules
• trace is truncated, I can post the full one if required

The second Agent.getInstance() call stack looks like this:

Runtime.addShutdownHook(Thread) line: 213	
Agent.getInstance(AgentOptions) line: 55	
Offline.getRuntimeData() line: 39	
Offline.getProbes(long, String, int) line: 60	
SharedConfigSourceProvider.$jacocoInit(MethodHandles$Lookup, String, Class) line: not available	
404458571.invokeStaticInit(Object, Object, Object, Object) line: not available	
DelegatingMethodHandle$Holder.reinvoke_L(Object, Object, Object, Object) line: not available	
1131710157.invoke_MT(Object, Object, Object, Object, Object) line: not available	
BootstrapMethodInvoker.invoke(MethodHandle, MethodHandles$Lookup, String, Object) line: 204	
BootstrapMethodInvoker.invoke(Class<T>, MethodHandle, String, Object, Object, Class<?>) line: 90	
ConstantBootstraps.makeConstant(MethodHandle, String, Class<?>, Object, Class<?>) line: 67	
MethodHandleNatives.linkDynamicConstantImpl(Class<?>, MethodHandle, String, Class<?>, Object) line: 314	
MethodHandleNatives.linkDynamicConstant(Object, int, Object, Object, Object, Object) line: 306	
SharedConfigSourceProvider.<clinit>() line: 38	
NativeConstructorAccessorImpl.newInstance0(Constructor<?>, Object[]) line: not available [native method]	
NativeConstructorAccessorImpl.newInstance(Object[]) line: 62	
DelegatingConstructorAccessorImpl.newInstance(Object[]) line: 45	
Constructor<T>.newInstance(Object...) line: 490	
ServiceLoader$ProviderImpl<S>.newInstance() line: 779	
ServiceLoader$ProviderImpl<S>.get() line: 721	
ServiceLoader$3.next() line: 1394	
ServiceLoader<S>(Iterable<T>).forEach(Consumer<? super T>) line: 74	
SmallRyeConfigBuilder.discoverSources() line: 79	
SmallRyeConfigBuilder.build() line: 175	
Config.<clinit>() line: 16096	
ApplicationImpl.<clinit>() line: 213	
Class<T>.forName0(String, boolean, ClassLoader, Class<?>) line: not available [native method]	
Class<T>.forName(String, boolean, ClassLoader) line: 398	
StartupActionImpl.run(String...) line: 161	
QuarkusTestExtension.doJavaStart(ExtensionContext) line: 151

It seems our SharedConfigSourceProvider is loaded a second time by a different classloader and therefore Agent.singleton is null (not initialized yet). In this case there is only a single QuarkusTest in the respective module, no other test is present.

In another case the first Agent.getInstance() is triggered by a non-QuarkusTest (vanilla Junit5 Jupiter test) and the call stack looks like this:

Runtime.addShutdownHook(Thread) line: 213	
Agent.getInstance(AgentOptions) line: 55	
Offline.getRuntimeData() line: 39	
Offline.getProbes(long, String, int) line: 60	
ConfigurationContext.$jacocoInit(MethodHandles$Lookup, String, Class) line: not available	
DirectMethodHandle$Holder.invokeStatic(Object, Object, Object, Object) line: not available	
DelegatingMethodHandle$Holder.reinvoke_L(Object, Object, Object, Object) line: not available	
366252104.invoke_MT(Object, Object, Object, Object, Object) line: not available	
BootstrapMethodInvoker.invoke(MethodHandle, MethodHandles$Lookup, String, Object) line: 204	
BootstrapMethodInvoker.invoke(Class<T>, MethodHandle, String, Object, Object, Class<?>) line: 90	
ConstantBootstraps.makeConstant(MethodHandle, String, Class<?>, Object, Class<?>) line: 67	
MethodHandleNatives.linkDynamicConstantImpl(Class<?>, MethodHandle, String, Class<?>, Object) line: 314	
MethodHandleNatives.linkDynamicConstant(Object, int, Object, Object, Object, Object) line: 306	
<unknown receiving type>(ConfigurationContext).<init>(Map<Class<Annotation>,Annotation>, Class<?>, Class<?>, String, CallModifier) line: 44	
ConfigurationContextTest.doBefore() line: 34

Notes:

• ConfigurationContext is one of our classes
• ConfigurationContextTest.doBefore() is a @BeforeAll method
• trace is truncated, I can post the full one if required

After this non-QuarkusTest there is a QuarkustTest which triggers another “initial” Agent.getInstance() invocation through ArC:

Runtime.addShutdownHook(Thread) line: 213	
Agent.getInstance(AgentOptions) line: 55	
Offline.getRuntimeData() line: 39	
Offline.getProbes(long, String, int) line: 60	
SoapClientAccessorBuilder.$jacocoInit(MethodHandles$Lookup, String, Class) line: not available	
789998945.invokeStaticInit(Object, Object, Object, Object) line: not available	
DelegatingMethodHandle$Holder.reinvoke_L(Object, Object, Object, Object) line: not available	
366252104.invoke_MT(Object, Object, Object, Object, Object) line: not available	
BootstrapMethodInvoker.invoke(MethodHandle, MethodHandles$Lookup, String, Object) line: 204	
BootstrapMethodInvoker.invoke(Class<T>, MethodHandle, String, Object, Object, Class<?>) line: 90	
ConstantBootstraps.makeConstant(MethodHandle, String, Class<?>, Object, Class<?>) line: 67	
MethodHandleNatives.linkDynamicConstantImpl(Class<?>, MethodHandle, String, Class<?>, Object) line: 314	
MethodHandleNatives.linkDynamicConstant(Object, int, Object, Object, Object, Object) line: 306	
SoapClientAccessorBuilder.<clinit>() line: 85	
Class<T>.forName0(String, boolean, ClassLoader, Class<?>) line: not available [native method]	
Class<T>.forName(String, boolean, ClassLoader) line: 398	
SoapClientAccessorBuilder_Bean.<init>() line: 543	
Default_ComponentsProvider.addBeans1(Map) line: 117	
Default_ComponentsProvider.getComponents() line: 38	
ArcContainerImpl.<init>() line: 106	
Arc.initialize() line: 20	
ArcRecorder.getContainer(ShutdownContext) line: 35	
ArcProcessor$generateResources11.deploy_0(StartupContext, Object[]) line: 72	
ArcProcessor$generateResources11.deploy(StartupContext) line: 36	
ApplicationImpl.<clinit>() line: 275	
Class<T>.forName0(String, boolean, ClassLoader, Class<?>) line: not available [native method]	
Class<T>.forName(String, boolean, ClassLoader) line: 398	
StartupActionImpl.run(String...) line: 161	
QuarkusTestExtension.doJavaStart(ExtensionContext) line: 151

Note: SoapClientAccessorBuilder is one of our classes.

This can all be debugged by adding a breakpoint to Runtime.addShutdownHook() plus mvn ... -Dmaven.surefire.debug.

Expected behavior Quarkus classloading should not interfere with JaCoCo coverage via offline instrumentation.

Actual behavior Duplicate JaCoCo Shutdownhook registrations seem to be caused by Quarkus classloading mechanisms, causing OverlappingFileLockExceptions to be logged that leave the user uncertain whether the coverage data can be trusted.

To Reproduce Steps to reproduce the behavior for the ConfigSourceProvider case:

1. Clone https://github.com/famod/quarkus-issue-9837.git This is basically https://github.com/quarkusio/quarkus-quickstarts/tree/1.5.0.Final/tests-with-coverage-quickstart with a no-op ConfigSourceProvider.
2. Switch to branch ConfigSourceProvider
3. mvn clean verify should yield:

   [INFO] --- maven-surefire-plugin:2.22.1:test (integration-tests) @ tests-with-coverage-quickstart ---
   [INFO]
   [INFO] -------------------------------------------------------
   [INFO]  T E S T S
   [INFO] -------------------------------------------------------
   [INFO] Running org.acme.testcoverage.GreetingResourceTest
   ::: SomeConfigSourceProvider.getConfigSources() called
   ::: SomeConfigSourceProvider.getConfigSources() called
   ::: SomeConfigSourceProvider.getConfigSources() called
   2020-06-07 17:20:27,662 INFO  [io.quarkus] (main) Quarkus 1.5.0.Final on JVM started in 1.447s. Listening on: http://0.0.0.0:8081
   2020-06-07 17:20:27,664 INFO  [io.quarkus] (main) Profile test activated.
   2020-06-07 17:20:27,664 INFO  [io.quarkus] (main) Installed features: [cdi, resteasy]
   [INFO] Tests run: 2, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 4.075 s - in org.acme.testcoverage.GreetingResourceTest
   2020-06-07 17:20:28,639 INFO  [io.quarkus] (main) Quarkus stopped in 0.022s
   java.nio.channels.OverlappingFileLockException
           at java.base/sun.nio.ch.FileLockTable.checkList(FileLockTable.java:229)
           at java.base/sun.nio.ch.FileLockTable.add(FileLockTable.java:123)
           at java.base/sun.nio.ch.FileChannelImpl.lock(FileChannelImpl.java:1109)
           at java.base/java.nio.channels.FileChannel.lock(FileChannel.java:1063)
           at org.jacoco.agent.rt.internal_035b120.output.FileOutput.openFile(FileOutput.java:69)
           at org.jacoco.agent.rt.internal_035b120.output.FileOutput.writeExecutionData(FileOutput.java:53)
           at org.jacoco.agent.rt.internal_035b120.Agent.shutdown(Agent.java:137)
           at org.jacoco.agent.rt.internal_035b120.Agent$1.run(Agent.java:54)
   [INFO]
   [INFO] Results:
   [INFO]
   [INFO] Tests run: 2, Failures: 0, Errors: 0, Skipped: 0
   

I can also try to create a reproducer for the other case, if needed.

Configuration n/a

Environment (please complete the following information):

• Output of uname -a or ver: MINGW64_NT-10.0-18363 W4DEUMSY9003463 3.0.7-338.x86_64 2019-11-21 23:07 UTC x86_64 Msys
• Output of java -version:

  openjdk version "11.0.7" 2020-04-14
  OpenJDK Runtime Environment AdoptOpenJDK (build 11.0.7+10)
  OpenJDK 64-Bit Server VM AdoptOpenJDK (build 11.0.7+10, mixed mode)
  

• GraalVM version (if different from Java): n/a
• Quarkus version or git rev: 1.4.2.Final & 1.5.0.Final
• Build tool (ie. output of mvnw --version or gradlew --version): Apache Maven 3.6.3

Additional context This might be more of an interoperability issue between Quarkus and JaCoCo than a “classical” Quarkus-only bug, but since JaCoCo offline instumentation is “officially” documented in the Quarkus docs this should work without issues.

The classes indirectly causing the duplicate hooks can be excluded from JaCoCo instrumentation, but then they will (obviously) have 0% coverage in the report. In one we case we did do so, though, because the “offending” class was a QuarkusTestResourceLifecycleManager from a test support module which should be ignored anyway.