AspectJ around aspect called twice when using a Mockito Spy

[cdalexndr]

Spring Boot 2.2.0.RELEASE

Using @Async returning a Future cannot be canceled if the @Async method is called from a @SpyBean.

From debugging, it seems the @Async aspect is called twice, first before mockito handling method call then after Mockito calls method so the returned Future is invalid.

Sample project: https://github.com/cdalexndr/spring-boot-issue-18771

Just run gradlew test

[cdalexndr]

Same issue with an aspect that requires method to be running at most once per context. It fails because the aspect is called twice (stacked) so the inner call fails.

[wilkinsona]

Thanks for the sample. This appears to be a general problem with spying on an @Async bean when using AspectJ. Assuming that the aspect for @Async has been woven in, the problem can be reproduced with this standalone test:

SomeService spiedService = spy(new SomeService());
assertThat(MockUtil.isSpy(spiedService)).isTrue();
Future<Integer> future = spiedService.asyncMethod();
while (!spiedService.getWorking()) {
    Thread.sleep(100);
}
future.cancel(true);
while (!spiedService.getFinished()) {
    Thread.sleep(100);
}

[wilkinsona]

Here's a complete standalone test class that reproduces the problem when AspectJ's weaver is configured as a Java agent:

package example;

import static org.assertj.core.api.Assertions.assertThat;
import static org.mockito.Mockito.spy;

import java.util.concurrent.CompletableFuture;
import java.util.concurrent.Future;
import java.util.concurrent.atomic.AtomicBoolean;

import org.junit.jupiter.api.Test;
import org.junit.jupiter.api.Timeout;
import org.mockito.internal.util.MockUtil;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.springframework.context.ConfigurableApplicationContext;
import org.springframework.context.annotation.AdviceMode;
import org.springframework.context.annotation.AnnotationConfigApplicationContext;
import org.springframework.context.annotation.Bean;
import org.springframework.context.annotation.Configuration;
import org.springframework.scheduling.annotation.Async;
import org.springframework.scheduling.annotation.EnableAsync;

public class AsyncMethodSpyTests {

    @Test
    @Timeout(10)
    public void test() throws InterruptedException {
        try (ConfigurableApplicationContext context = new AnnotationConfigApplicationContext(TestConfiguration.class)) {            
            SomeService service = context.getBean(SomeService.class);
            SomeService spiedService = spy(service);
            assertThat(MockUtil.isSpy(spiedService)).isTrue();
            Future<Integer> future = spiedService.asyncMethod();
            System.out.println(future);
            while (!spiedService.getWorking()) {
                Thread.sleep(100);
            }
            future.cancel(true);
            while (!spiedService.getFinished()) {
                Thread.sleep( 100 );
            }
        }
    }

    @Configuration
    @EnableAsync(mode = AdviceMode.ASPECTJ)
    static class TestConfiguration {

        @Bean
        public SomeService someService() {
            return new SomeService();
        }

    }

    static class SomeService {

        private static final Logger log = LoggerFactory.getLogger(SomeService.class);

        private AtomicBoolean finished = new AtomicBoolean(false);

        private AtomicBoolean working = new AtomicBoolean(false);

        public boolean getFinished() {
            return finished.get();
        }

        public boolean getWorking() {
            return working.get();
        }

        @Async
        public Future<Integer> asyncMethod() {
            log.info("Working");
            working.set(true);
            try {
                while (!Thread.currentThread().isInterrupted()) {
                    Thread.sleep(100);
                }
            } catch (InterruptedException e) {
                log.info("Interrupted");
            }
            finished.set(true);
            CompletableFuture<Integer> completableFuture = new CompletableFuture<>();
            System.out.println("Returning " + completableFuture);
            return completableFuture;
        }

    }

}

The aspect is called twice, once for the call to the spy and once when the spy is then passing the method call on to the instance that is being spied upon.

I'm not sure if it will be possible to do anything about this, but if it is I think it will need to be done in Framework.

[snicoll]

I've managed to reproduce on a recent Spring Framework version, thanks @wilkinsona for the reduced sample!

I've pushed things here https://github.com/snicoll-scratches/spring-boot-issue-18771 - Updating to Java 17 fails in an interesting way:

org.gradle.api.internal.tasks.testing.TestSuiteExecutionException: Could not complete execution for Gradle Test Executor 2.
    at org.gradle.api.internal.tasks.testing.SuiteTestClassProcessor.stop(SuiteTestClassProcessor.java:64)
    at java.base@17.0.9/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at java.base@17.0.9/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77)
    at java.base@17.0.9/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.base@17.0.9/java.lang.reflect.Method.invoke(Method.java:568)
    at org.gradle.internal.dispatch.ReflectionDispatch.dispatch(ReflectionDispatch.java:36)
    at org.gradle.internal.dispatch.ReflectionDispatch.dispatch(ReflectionDispatch.java:24)
    at org.gradle.internal.dispatch.ContextClassLoaderDispatch.dispatch(ContextClassLoaderDispatch.java:33)
    at org.gradle.internal.dispatch.ProxyDispatchAdapter$DispatchingInvocationHandler.invoke(ProxyDispatchAdapter.java:94)
    at jdk.proxy1/jdk.proxy1.$Proxy2.stop(Unknown Source)
    at org.gradle.api.internal.tasks.testing.worker.TestWorker$3.run(TestWorker.java:193)
    at org.gradle.api.internal.tasks.testing.worker.TestWorker.executeAndMaintainThreadName(TestWorker.java:129)
    at org.gradle.api.internal.tasks.testing.worker.TestWorker.execute(TestWorker.java:100)
    at org.gradle.api.internal.tasks.testing.worker.TestWorker.execute(TestWorker.java:60)
    at org.gradle.process.internal.worker.child.ActionExecutionWorker.execute(ActionExecutionWorker.java:56)
    at org.gradle.process.internal.worker.child.SystemApplicationClassLoaderWorker.call(SystemApplicationClassLoaderWorker.java:113)
    at org.gradle.process.internal.worker.child.SystemApplicationClassLoaderWorker.call(SystemApplicationClassLoaderWorker.java:65)
    at app//worker.org.gradle.process.internal.worker.GradleWorkerMain.run(GradleWorkerMain.java:69)
    at app//worker.org.gradle.process.internal.worker.GradleWorkerMain.main(GradleWorkerMain.java:74)
Caused by: org.junit.platform.commons.JUnitException: TestEngine with ID 'junit-jupiter' failed to discover tests
    at app//org.junit.platform.launcher.core.EngineDiscoveryOrchestrator.discoverEngineRoot(EngineDiscoveryOrchestrator.java:160)
    at app//org.junit.platform.launcher.core.EngineDiscoveryOrchestrator.discoverSafely(EngineDiscoveryOrchestrator.java:134)
    at app//org.junit.platform.launcher.core.EngineDiscoveryOrchestrator.discover(EngineDiscoveryOrchestrator.java:108)
    at app//org.junit.platform.launcher.core.EngineDiscoveryOrchestrator.discover(EngineDiscoveryOrchestrator.java:80)
    at app//org.junit.platform.launcher.core.DefaultLauncher.discover(DefaultLauncher.java:110)
    at app//org.junit.platform.launcher.core.DefaultLauncher.execute(DefaultLauncher.java:86)
    at app//org.junit.platform.launcher.core.DefaultLauncherSession$DelegatingLauncher.execute(DefaultLauncherSession.java:86)
    at org.gradle.api.internal.tasks.testing.junitplatform.JUnitPlatformTestClassProcessor$CollectAllTestClassesExecutor.processAllTestClasses(JUnitPlatformTestClassProcessor.java:118)
    at org.gradle.api.internal.tasks.testing.junitplatform.JUnitPlatformTestClassProcessor$CollectAllTestClassesExecutor.access$000(JUnitPlatformTestClassProcessor.java:93)
    at org.gradle.api.internal.tasks.testing.junitplatform.JUnitPlatformTestClassProcessor.stop(JUnitPlatformTestClassProcessor.java:88)
    at org.gradle.api.internal.tasks.testing.SuiteTestClassProcessor.stop(SuiteTestClassProcessor.java:62)
    ... 18 more
Caused by: org.junit.platform.commons.JUnitException: ClassSelector [className = 'example.AsyncMethodSpyTest$SomeService'] resolution failed
    at app//org.junit.platform.launcher.listeners.discovery.AbortOnFailureLauncherDiscoveryListener.selectorProcessed(AbortOnFailureLauncherDiscoveryListener.java:39)
    at app//org.junit.platform.engine.support.discovery.EngineDiscoveryRequestResolution.resolveCompletely(EngineDiscoveryRequestResolution.java:103)
    at app//org.junit.platform.engine.support.discovery.EngineDiscoveryRequestResolution.run(EngineDiscoveryRequestResolution.java:83)
    at app//org.junit.platform.engine.support.discovery.EngineDiscoveryRequestResolver.resolve(EngineDiscoveryRequestResolver.java:113)
    at app//org.junit.jupiter.engine.discovery.DiscoverySelectorResolver.resolveSelectors(DiscoverySelectorResolver.java:46)
    at app//org.junit.jupiter.engine.JupiterTestEngine.discover(JupiterTestEngine.java:69)
    at app//org.junit.platform.launcher.core.EngineDiscoveryOrchestrator.discoverEngineRoot(EngineDiscoveryOrchestrator.java:152)
    ... 28 more
Caused by: java.lang.NoClassDefFoundError: example/AsyncMethodSpyTest$SomeService$AjcClosure1
    at java.base/java.lang.Class.getDeclaredMethods0(Native Method)
    at java.base/java.lang.Class.privateGetDeclaredMethods(Class.java:3402)
    at java.base/java.lang.Class.privateGetPublicMethods(Class.java:3427)
    at java.base/java.lang.Class.getMethods(Class.java:2019)
    at org.junit.platform.commons.util.ReflectionUtils.getDefaultMethods(ReflectionUtils.java:1521)
    at org.junit.platform.commons.util.ReflectionUtils.getDeclaredMethods(ReflectionUtils.java:1494)
    at org.junit.platform.commons.util.ReflectionUtils.findMethod(ReflectionUtils.java:1343)
    at org.junit.platform.commons.util.ReflectionUtils.isMethodPresent(ReflectionUtils.java:1244)
    at org.junit.jupiter.engine.discovery.predicates.IsTestClassWithTests.hasTestOrTestFactoryOrTestTemplateMethods(IsTestClassWithTests.java:50)
    at org.junit.jupiter.engine.discovery.predicates.IsTestClassWithTests.test(IsTestClassWithTests.java:46)
    at org.junit.jupiter.engine.discovery.ClassSelectorResolver.resolve(ClassSelectorResolver.java:67)
    at org.junit.platform.engine.support.discovery.EngineDiscoveryRequestResolution.lambda$resolve$2(EngineDiscoveryRequestResolution.java:135)
    at java.base/java.util.stream.ReferencePipeline$3$1.accept(ReferencePipeline.java:197)
    at java.base/java.util.ArrayList$ArrayListSpliterator.tryAdvance(ArrayList.java:1602)
    at java.base/java.util.stream.ReferencePipeline.forEachWithCancel(ReferencePipeline.java:129)
    at java.base/java.util.stream.AbstractPipeline.copyIntoWithCancel(AbstractPipeline.java:527)
    at java.base/java.util.stream.AbstractPipeline.copyInto(AbstractPipeline.java:513)
    at java.base/java.util.stream.AbstractPipeline.wrapAndCopyInto(AbstractPipeline.java:499)
    at java.base/java.util.stream.FindOps$FindOp.evaluateSequential(FindOps.java:150)
    at java.base/java.util.stream.AbstractPipeline.evaluate(AbstractPipeline.java:234)
    at java.base/java.util.stream.ReferencePipeline.findFirst(ReferencePipeline.java:647)
    at org.junit.platform.engine.support.discovery.EngineDiscoveryRequestResolution.resolve(EngineDiscoveryRequestResolution.java:189)
    at org.junit.platform.engine.support.discovery.EngineDiscoveryRequestResolution.resolve(EngineDiscoveryRequestResolution.java:126)
    at org.junit.platform.engine.support.discovery.EngineDiscoveryRequestResolution.resolveCompletely(EngineDiscoveryRequestResolution.java:92)
    ... 33 more
Caused by: java.lang.ClassNotFoundException: example.AsyncMethodSpyTest$SomeService$AjcClosure1
    at java.base/jdk.internal.loader.BuiltinClassLoader.loadClass(BuiltinClassLoader.java:641)
    at java.base/jdk.internal.loader.ClassLoaders$AppClassLoader.loadClass(ClassLoaders.java:188)
    at java.base/java.lang.ClassLoader.loadClass(ClassLoader.java:525)
    ... 57 more

[sbrannen]

Updating to Java 17 fails in an interesting way:

What happens if you set the following JUnit configuration parameter (system property) in build.gradle?

test {
    useJUnitPlatform()
    systemProperty("junit.platform.discovery.listener.default", "logging")
    // additional config ...
}

[snicoll]

It was also failing in my IDE but without the JUnit bit so I didn't bother. But thanks for sharing that. Now it fails exactly the same way without the " TestEngine with ID 'junit-jupiter' failed to discover tests" bit.