Document the need for compilation with -parameters when using @SpyBean and @Cacheable with a key expression that uses a parameter name

[mdeinum]

Tested with both Spring Boot 1.5.14 and Spring Boot 2.0.3.

When using @SpyBean to investigate method calls on a bean and a method is annotated with @Cacheable this breaks.

@Service
public class OrderService {

    private final Logger logger = LoggerFactory.getLogger(getClass());

    @Cacheable(value="orders", key = "#id + #key.field1")
    public Order find(String id, PartialKey key) {

        double amount = ThreadLocalRandom.current().nextDouble(1000.00);
        Order order = new Order(id, BigDecimal.valueOf(amount));
        logger.info("Created: {}", order);
        return order;
    }
}

The issue is that when using a custom key, the extension/proxy generated by @SpyBean apparently doesn't have the needed debug information anymore. Switching from named parameters to indexed parameters makes it work again.

Exception:

java.lang.IllegalStateException: Failed to load ApplicationContext
	at org.springframework.test.context.cache.DefaultCacheAwareContextLoaderDelegate.loadContext(DefaultCacheAwareContextLoaderDelegate.java:124) ~[spring-test-4.3.18.RELEASE.jar:4.3.18.RELEASE]
	at org.springframework.test.context.support.DefaultTestContext.getApplicationContext(DefaultTestContext.java:83) ~[spring-test-4.3.18.RELEASE.jar:4.3.18.RELEASE]
	at org.springframework.boot.test.mock.mockito.MockitoTestExecutionListener.postProcessFields(MockitoTestExecutionListener.java:110) ~[spring-boot-test-1.5.14.RELEASE.jar:1.5.14.RELEASE]
	at org.springframework.boot.test.mock.mockito.MockitoTestExecutionListener.injectFields(MockitoTestExecutionListener.java:78) ~[spring-boot-test-1.5.14.RELEASE.jar:1.5.14.RELEASE]
	at org.springframework.boot.test.mock.mockito.MockitoTestExecutionListener.prepareTestInstance(MockitoTestExecutionListener.java:48) ~[spring-boot-test-1.5.14.RELEASE.jar:1.5.14.RELEASE]
	at org.springframework.test.context.TestContextManager.prepareTestInstance(TestContextManager.java:230) ~[spring-test-4.3.18.RELEASE.jar:4.3.18.RELEASE]
	at org.springframework.test.context.junit4.SpringJUnit4ClassRunner.createTest(SpringJUnit4ClassRunner.java:228) [spring-test-4.3.18.RELEASE.jar:4.3.18.RELEASE]
	at org.springframework.test.context.junit4.SpringJUnit4ClassRunner$1.runReflectiveCall(SpringJUnit4ClassRunner.java:287) [spring-test-4.3.18.RELEASE.jar:4.3.18.RELEASE]
	at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12) [junit-4.12.jar:4.12]
	at org.springframework.test.context.junit4.SpringJUnit4ClassRunner.methodBlock(SpringJUnit4ClassRunner.java:289) [spring-test-4.3.18.RELEASE.jar:4.3.18.RELEASE]
	at org.springframework.test.context.junit4.SpringJUnit4ClassRunner.runChild(SpringJUnit4ClassRunner.java:247) [spring-test-4.3.18.RELEASE.jar:4.3.18.RELEASE]
	at org.springframework.test.context.junit4.SpringJUnit4ClassRunner.runChild(SpringJUnit4ClassRunner.java:94) [spring-test-4.3.18.RELEASE.jar:4.3.18.RELEASE]
	at org.junit.runners.ParentRunner$3.run(ParentRunner.java:290) [junit-4.12.jar:4.12]
	at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:71) [junit-4.12.jar:4.12]
	at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:288) [junit-4.12.jar:4.12]
	at org.junit.runners.ParentRunner.access$000(ParentRunner.java:58) [junit-4.12.jar:4.12]
	at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:268) [junit-4.12.jar:4.12]
	at org.springframework.test.context.junit4.statements.RunBeforeTestClassCallbacks.evaluate(RunBeforeTestClassCallbacks.java:61) [spring-test-4.3.18.RELEASE.jar:4.3.18.RELEASE]
	at org.springframework.test.context.junit4.statements.RunAfterTestClassCallbacks.evaluate(RunAfterTestClassCallbacks.java:70) [spring-test-4.3.18.RELEASE.jar:4.3.18.RELEASE]
	at org.junit.runners.ParentRunner.run(ParentRunner.java:363) [junit-4.12.jar:4.12]
	at org.springframework.test.context.junit4.SpringJUnit4ClassRunner.run(SpringJUnit4ClassRunner.java:191) [spring-test-4.3.18.RELEASE.jar:4.3.18.RELEASE]
	at org.junit.runner.JUnitCore.run(JUnitCore.java:137) [junit-4.12.jar:4.12]
	at com.intellij.junit4.JUnit4IdeaTestRunner.startRunnerWithArgs(JUnit4IdeaTestRunner.java:68) [junit-rt.jar:na]
	at com.intellij.rt.execution.junit.IdeaTestRunner$Repeater.startRunnerWithArgs(IdeaTestRunner.java:47) [junit-rt.jar:na]
	at com.intellij.rt.execution.junit.JUnitStarter.prepareStreamsAndStart(JUnitStarter.java:242) [junit-rt.jar:na]
	at com.intellij.rt.execution.junit.JUnitStarter.main(JUnitStarter.java:70) [junit-rt.jar:na]
Caused by: java.lang.IllegalStateException: Failed to execute ApplicationRunner
	at org.springframework.boot.SpringApplication.callRunner(SpringApplication.java:726) ~[spring-boot-1.5.14.RELEASE.jar:1.5.14.RELEASE]
	at org.springframework.boot.SpringApplication.callRunners(SpringApplication.java:713) ~[spring-boot-1.5.14.RELEASE.jar:1.5.14.RELEASE]
	at org.springframework.boot.SpringApplication.afterRefresh(SpringApplication.java:703) ~[spring-boot-1.5.14.RELEASE.jar:1.5.14.RELEASE]
	at org.springframework.boot.SpringApplication.run(SpringApplication.java:304) ~[spring-boot-1.5.14.RELEASE.jar:1.5.14.RELEASE]
	at org.springframework.boot.test.context.SpringBootContextLoader.loadContext(SpringBootContextLoader.java:121) ~[spring-boot-test-1.5.14.RELEASE.jar:1.5.14.RELEASE]
	at org.springframework.test.context.cache.DefaultCacheAwareContextLoaderDelegate.loadContextInternal(DefaultCacheAwareContextLoaderDelegate.java:98) ~[spring-test-4.3.18.RELEASE.jar:4.3.18.RELEASE]
	at org.springframework.test.context.cache.DefaultCacheAwareContextLoaderDelegate.loadContext(DefaultCacheAwareContextLoaderDelegate.java:116) ~[spring-test-4.3.18.RELEASE.jar:4.3.18.RELEASE]
	... 25 common frames omitted
Caused by: org.springframework.expression.spel.SpelEvaluationException: EL1007E: Property or field 'field1' cannot be found on null
	at org.springframework.expression.spel.ast.PropertyOrFieldReference.readProperty(PropertyOrFieldReference.java:225) ~[spring-expression-4.3.18.RELEASE.jar:4.3.18.RELEASE]
	at org.springframework.expression.spel.ast.PropertyOrFieldReference.getValueInternal(PropertyOrFieldReference.java:97) ~[spring-expression-4.3.18.RELEASE.jar:4.3.18.RELEASE]
	at org.springframework.expression.spel.ast.PropertyOrFieldReference.access$000(PropertyOrFieldReference.java:47) ~[spring-expression-4.3.18.RELEASE.jar:4.3.18.RELEASE]
	at org.springframework.expression.spel.ast.PropertyOrFieldReference$AccessorLValue.getValue(PropertyOrFieldReference.java:414) ~[spring-expression-4.3.18.RELEASE.jar:4.3.18.RELEASE]
	at org.springframework.expression.spel.ast.CompoundExpression.getValueInternal(CompoundExpression.java:88) ~[spring-expression-4.3.18.RELEASE.jar:4.3.18.RELEASE]
	at org.springframework.expression.spel.ast.OpPlus.getValueInternal(OpPlus.java:85) ~[spring-expression-4.3.18.RELEASE.jar:4.3.18.RELEASE]
	at org.springframework.expression.spel.ast.SpelNodeImpl.getValue(SpelNodeImpl.java:121) ~[spring-expression-4.3.18.RELEASE.jar:4.3.18.RELEASE]
	at org.springframework.expression.spel.standard.SpelExpression.getValue(SpelExpression.java:262) ~[spring-expression-4.3.18.RELEASE.jar:4.3.18.RELEASE]
	at org.springframework.cache.interceptor.CacheOperationExpressionEvaluator.key(CacheOperationExpressionEvaluator.java:117) ~[spring-context-4.3.18.RELEASE.jar:4.3.18.RELEASE]
	at org.springframework.cache.interceptor.CacheAspectSupport$CacheOperationContext.generateKey(CacheAspectSupport.java:739) ~[spring-context-4.3.18.RELEASE.jar:4.3.18.RELEASE]
	at org.springframework.cache.interceptor.CacheAspectSupport.generateKey(CacheAspectSupport.java:555) ~[spring-context-4.3.18.RELEASE.jar:4.3.18.RELEASE]
	at org.springframework.cache.interceptor.CacheAspectSupport.findCachedItem(CacheAspectSupport.java:499) ~[spring-context-4.3.18.RELEASE.jar:4.3.18.RELEASE]
	at org.springframework.cache.interceptor.CacheAspectSupport.execute(CacheAspectSupport.java:386) ~[spring-context-4.3.18.RELEASE.jar:4.3.18.RELEASE]
	at org.springframework.cache.interceptor.CacheAspectSupport.execute(CacheAspectSupport.java:324) ~[spring-context-4.3.18.RELEASE.jar:4.3.18.RELEASE]
	at org.springframework.cache.interceptor.CacheInterceptor.invoke(CacheInterceptor.java:61) ~[spring-context-4.3.18.RELEASE.jar:4.3.18.RELEASE]
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179) ~[spring-aop-4.3.18.RELEASE.jar:4.3.18.RELEASE]
	at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:671) ~[spring-aop-4.3.18.RELEASE.jar:4.3.18.RELEASE]
	at biz.deinum.cacheablespybeanissue.OrderService$$EnhancerBySpringCGLIB$$b501beda.find(<generated>) ~[classes/:na]
	at biz.deinum.cacheablespybeanissue.CacheableSpybeanIssueApplication.lambda$orders$0(CacheableSpybeanIssueApplication.java:26) ~[classes/:na]
	at org.springframework.boot.SpringApplication.callRunner(SpringApplication.java:723) ~[spring-boot-1.5.14.RELEASE.jar:1.5.14.RELEASE]
	... 31 common frames omitted

Using only the id argument as the cache yield a slightly different exception (but the underlying cause is the same).

java.lang.IllegalStateException: Failed to load ApplicationContext
	at org.springframework.test.context.cache.DefaultCacheAwareContextLoaderDelegate.loadContext(DefaultCacheAwareContextLoaderDelegate.java:124) ~[spring-test-4.3.18.RELEASE.jar:4.3.18.RELEASE]
	at org.springframework.test.context.support.DefaultTestContext.getApplicationContext(DefaultTestContext.java:83) ~[spring-test-4.3.18.RELEASE.jar:4.3.18.RELEASE]
	at org.springframework.boot.test.mock.mockito.MockitoTestExecutionListener.postProcessFields(MockitoTestExecutionListener.java:110) ~[spring-boot-test-1.5.14.RELEASE.jar:1.5.14.RELEASE]
	at org.springframework.boot.test.mock.mockito.MockitoTestExecutionListener.injectFields(MockitoTestExecutionListener.java:78) ~[spring-boot-test-1.5.14.RELEASE.jar:1.5.14.RELEASE]
	at org.springframework.boot.test.mock.mockito.MockitoTestExecutionListener.prepareTestInstance(MockitoTestExecutionListener.java:48) ~[spring-boot-test-1.5.14.RELEASE.jar:1.5.14.RELEASE]
	at org.springframework.test.context.TestContextManager.prepareTestInstance(TestContextManager.java:230) ~[spring-test-4.3.18.RELEASE.jar:4.3.18.RELEASE]
	at org.springframework.test.context.junit4.SpringJUnit4ClassRunner.createTest(SpringJUnit4ClassRunner.java:228) [spring-test-4.3.18.RELEASE.jar:4.3.18.RELEASE]
	at org.springframework.test.context.junit4.SpringJUnit4ClassRunner$1.runReflectiveCall(SpringJUnit4ClassRunner.java:287) [spring-test-4.3.18.RELEASE.jar:4.3.18.RELEASE]
	at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12) [junit-4.12.jar:4.12]
	at org.springframework.test.context.junit4.SpringJUnit4ClassRunner.methodBlock(SpringJUnit4ClassRunner.java:289) [spring-test-4.3.18.RELEASE.jar:4.3.18.RELEASE]
	at org.springframework.test.context.junit4.SpringJUnit4ClassRunner.runChild(SpringJUnit4ClassRunner.java:247) [spring-test-4.3.18.RELEASE.jar:4.3.18.RELEASE]
	at org.springframework.test.context.junit4.SpringJUnit4ClassRunner.runChild(SpringJUnit4ClassRunner.java:94) [spring-test-4.3.18.RELEASE.jar:4.3.18.RELEASE]
	at org.junit.runners.ParentRunner$3.run(ParentRunner.java:290) [junit-4.12.jar:4.12]
	at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:71) [junit-4.12.jar:4.12]
	at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:288) [junit-4.12.jar:4.12]
	at org.junit.runners.ParentRunner.access$000(ParentRunner.java:58) [junit-4.12.jar:4.12]
	at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:268) [junit-4.12.jar:4.12]
	at org.springframework.test.context.junit4.statements.RunBeforeTestClassCallbacks.evaluate(RunBeforeTestClassCallbacks.java:61) [spring-test-4.3.18.RELEASE.jar:4.3.18.RELEASE]
	at org.springframework.test.context.junit4.statements.RunAfterTestClassCallbacks.evaluate(RunAfterTestClassCallbacks.java:70) [spring-test-4.3.18.RELEASE.jar:4.3.18.RELEASE]
	at org.junit.runners.ParentRunner.run(ParentRunner.java:363) [junit-4.12.jar:4.12]
	at org.springframework.test.context.junit4.SpringJUnit4ClassRunner.run(SpringJUnit4ClassRunner.java:191) [spring-test-4.3.18.RELEASE.jar:4.3.18.RELEASE]
	at org.junit.runner.JUnitCore.run(JUnitCore.java:137) [junit-4.12.jar:4.12]
	at com.intellij.junit4.JUnit4IdeaTestRunner.startRunnerWithArgs(JUnit4IdeaTestRunner.java:68) [junit-rt.jar:na]
	at com.intellij.rt.execution.junit.IdeaTestRunner$Repeater.startRunnerWithArgs(IdeaTestRunner.java:47) [junit-rt.jar:na]
	at com.intellij.rt.execution.junit.JUnitStarter.prepareStreamsAndStart(JUnitStarter.java:242) [junit-rt.jar:na]
	at com.intellij.rt.execution.junit.JUnitStarter.main(JUnitStarter.java:70) [junit-rt.jar:na]
Caused by: java.lang.IllegalStateException: Failed to execute ApplicationRunner
	at org.springframework.boot.SpringApplication.callRunner(SpringApplication.java:726) ~[spring-boot-1.5.14.RELEASE.jar:1.5.14.RELEASE]
	at org.springframework.boot.SpringApplication.callRunners(SpringApplication.java:713) ~[spring-boot-1.5.14.RELEASE.jar:1.5.14.RELEASE]
	at org.springframework.boot.SpringApplication.afterRefresh(SpringApplication.java:703) ~[spring-boot-1.5.14.RELEASE.jar:1.5.14.RELEASE]
	at org.springframework.boot.SpringApplication.run(SpringApplication.java:304) ~[spring-boot-1.5.14.RELEASE.jar:1.5.14.RELEASE]
	at org.springframework.boot.test.context.SpringBootContextLoader.loadContext(SpringBootContextLoader.java:121) ~[spring-boot-test-1.5.14.RELEASE.jar:1.5.14.RELEASE]
	at org.springframework.test.context.cache.DefaultCacheAwareContextLoaderDelegate.loadContextInternal(DefaultCacheAwareContextLoaderDelegate.java:98) ~[spring-test-4.3.18.RELEASE.jar:4.3.18.RELEASE]
	at org.springframework.test.context.cache.DefaultCacheAwareContextLoaderDelegate.loadContext(DefaultCacheAwareContextLoaderDelegate.java:116) ~[spring-test-4.3.18.RELEASE.jar:4.3.18.RELEASE]
	... 25 common frames omitted
Caused by: java.lang.IllegalArgumentException: Null key returned for cache operation (maybe you are using named params on classes without debug info?) Builder[public biz.deinum.cacheablespybeanissue.Order biz.deinum.cacheablespybeanissue.OrderService.find(java.lang.String,biz.deinum.cacheablespybeanissue.PartialKey)] caches=[orders] | key='#id' | keyGenerator='' | cacheManager='' | cacheResolver='' | condition='' | unless='' | sync='false'
	at org.springframework.cache.interceptor.CacheAspectSupport.generateKey(CacheAspectSupport.java:558) ~[spring-context-4.3.18.RELEASE.jar:4.3.18.RELEASE]
	at org.springframework.cache.interceptor.CacheAspectSupport.findCachedItem(CacheAspectSupport.java:499) ~[spring-context-4.3.18.RELEASE.jar:4.3.18.RELEASE]
	at org.springframework.cache.interceptor.CacheAspectSupport.execute(CacheAspectSupport.java:386) ~[spring-context-4.3.18.RELEASE.jar:4.3.18.RELEASE]
	at org.springframework.cache.interceptor.CacheAspectSupport.execute(CacheAspectSupport.java:324) ~[spring-context-4.3.18.RELEASE.jar:4.3.18.RELEASE]
	at org.springframework.cache.interceptor.CacheInterceptor.invoke(CacheInterceptor.java:61) ~[spring-context-4.3.18.RELEASE.jar:4.3.18.RELEASE]
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179) ~[spring-aop-4.3.18.RELEASE.jar:4.3.18.RELEASE]
	at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:671) ~[spring-aop-4.3.18.RELEASE.jar:4.3.18.RELEASE]
	at biz.deinum.cacheablespybeanissue.OrderService$$EnhancerBySpringCGLIB$$292a87d8.find(<generated>) ~[classes/:na]
	at biz.deinum.cacheablespybeanissue.CacheableSpybeanIssueApplication.lambda$orders$0(CacheableSpybeanIssueApplication.java:26) ~[classes/:na]
	at org.springframework.boot.SpringApplication.callRunner(SpringApplication.java:723) ~[spring-boot-1.5.14.RELEASE.jar:1.5.14.RELEASE]
	... 31 common frames omitted

Reproduction project has been supplied to the Spring Boot Issues repositories. See spring-attic/spring-boot-issues#79

At some further inspection this looks like an ordering issue. The SpyPostProcessor is a PriorityOrdered and returns the HIGHEST_PRECEDENCE which makes it run very early in the proces. Leading to the CacheInterceptor seeing a OrderService#EnhanchedByMockitoCglib.

Shouldn't it be the last in line, wrapping the actual proxied instance (including the AOP) so that the spy can still record access but the regular behavior is still added (like @Cacheable, @Secured etc). It appears mainly to be an issue with interceptors that also read method arguments using SpEL. Apparently the creation of the Spy first makes the actual bean a proxy which doesn't contain the needed debug information anymore.

[mdeinum]

Doing some further digging it actually appears to be deliberately ordered like that. This was introduced in gh-5837. Which was/is supposed to be the fix to work with Spring AOP, however it doesn't fix the cases in which an interceptor reads information from the method signature (like method arguments).

[wilkinsona]

The debug information that's used by LocalVariableTableParameterNameDiscoverer is lost because the proxy class is generated at runtime so there's no class file available for it to introspect. This applies to both Boot 1.5 (Mockito 1.x which uses CGLib) and Boot 2.0 (Mockito 2.x which uses ByteBuddy).

The debug information that's used by StandardReflectionParameterNameDiscoverer is lost when using Boot 1.5 as CGLib doesn't provide it. It is not lost when using Boot 2.0 as ByteBuddy does provide it as long as the original code is compiled with -parameters. In other words, the problem does not occur with Spring Boot 2.0 as long as the code is compiled with -parameters.

The problem could be avoided altogether if we could get the expression evaluation to use the method on the original object rather than from the spy's proxy but I'm not sure that's possible and it certainly wouldn't be easy to do. As things stand, I'm leaning towards a documentation change that notes that -parameters should be used when combining @SpyBean with @Cacheable and a key expression that uses parameter names.

[mdeinum]

Is there anything in Spring Boot 1.5 preventing us from using Mockito 2? As I'm not really keen on doing a full upgrade to Spring Boot 2 just yet.

[wilkinsona]

No. As noted in the documentation you should be able to use 2.x if you wish. You'll need to override the mockito.version property in order to do so.