Extending CachingConfigurerSupport results in at least one log message about not being eligible for full post-processing

[wilkinsona]

Affects: 5.3.x

This was originally reported in a Spring Boot issue. While diagnosing the problem, I observed that even when a CachingConfigurerSupport has no dependencies, a log message about being ineligible for full post-processing is still logged. I discussed this with @snicoll and he asked me to raise an issue.

This minimal Boot app can be used to reproduce the problem:

$ ./gradlew bootRun

> Task :bootRun

  .   ____          _            __ _ _
 /\\ / ___'_ __ _ _(_)_ __  __ _ \ \ \ \
( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \
 \\/  ___)| |_)| | | | | || (_| |  ) ) ) )
  '  |____| .__|_| |_|_| |_\__, | / / / /
 =========|_|==============|___/=/_/_/_/
 :: Spring Boot ::                (v2.5.7)

2021-11-30 13:06:48.868  INFO 46167 --- [           main] c.e.d.CachingPostProcessingApplication   : Starting CachingPostProcessingApplication using Java 1.8.0_302 on wilkinsona-a01.vmware.com with PID 46167 (/Users/awilkinson/dev/workspaces/spring-projects/spring-boot/2.6.x/caching-post-processing/build/classes/java/main started by awilkinson in /Users/awilkinson/dev/workspaces/spring-projects/spring-boot/2.6.x/caching-post-processing)
2021-11-30 13:06:48.869  INFO 46167 --- [           main] c.e.d.CachingPostProcessingApplication   : No active profile set, falling back to default profiles: default
2021-11-30 13:06:49.214  INFO 46167 --- [           main] trationDelegate$BeanPostProcessorChecker : Bean 'cachingPostProcessingApplication.CachingConfig' of type [com.example.demo.CachingPostProcessingApplication$CachingConfig$$EnhancerBySpringCGLIB$$4121c366] is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)
2021-11-30 13:06:49.372  INFO 46167 --- [           main] c.e.d.CachingPostProcessingApplication   : Started CachingPostProcessingApplication in 0.719 seconds (JVM running for 0.962)

BUILD SUCCESSFUL in 1s
4 actionable tasks: 4 executed

Note the third INFO message:

2021-11-30 13:06:49.214  INFO 46167 --- [           main] trationDelegate$BeanPostProcessorChecker : Bean 'cachingPostProcessingApplication.CachingConfig' of type [com.example.demo.CachingPostProcessingApplication$CachingConfig$$EnhancerBySpringCGLIB$$4121c366] is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)

[snicoll]

This should probably require a bit more investigation but I believe this might need to move to Spring Boot. An application that doesn't use the auto-configuration doesn't exhibit this issue, something like:

@Configuration
public class CacheContext {

	public static void main(String[] args) {
		new AnnotationConfigApplicationContext(CacheContext.class);
	}

	@Bean
	CacheManager cacheManager() {
		return new SimpleCacheManager();
	}


	@Configuration
	@EnableCaching
	static class Caching extends CachingConfigurerSupport {

	}
}

17:29:19.587 [main] DEBUG org.springframework.context.annotation.AnnotationConfigApplicationContext - Refreshing org.springframework.context.annotation.AnnotationConfigApplicationContext@2a40cd94
17:29:19.599 [main] DEBUG org.springframework.beans.factory.support.DefaultListableBeanFactory - Creating shared instance of singleton bean 'org.springframework.context.annotation.internalConfigurationAnnotationProcessor'
17:29:19.767 [main] DEBUG org.springframework.beans.factory.support.DefaultListableBeanFactory - Creating shared instance of singleton bean 'org.springframework.context.event.internalEventListenerProcessor'
17:29:19.768 [main] DEBUG org.springframework.beans.factory.support.DefaultListableBeanFactory - Creating shared instance of singleton bean 'org.springframework.context.event.internalEventListenerFactory'
17:29:19.769 [main] DEBUG org.springframework.beans.factory.support.DefaultListableBeanFactory - Creating shared instance of singleton bean 'org.springframework.context.annotation.internalAutowiredAnnotationProcessor'
17:29:19.770 [main] DEBUG org.springframework.beans.factory.support.DefaultListableBeanFactory - Creating shared instance of singleton bean 'org.springframework.context.annotation.internalCommonAnnotationProcessor'
17:29:19.774 [main] DEBUG org.springframework.beans.factory.support.DefaultListableBeanFactory - Creating shared instance of singleton bean 'org.springframework.context.annotation.internalPersistenceAnnotationProcessor'
17:29:19.774 [main] DEBUG org.springframework.beans.factory.support.DefaultListableBeanFactory - Creating shared instance of singleton bean 'org.springframework.aop.config.internalAutoProxyCreator'
17:29:19.876 [main] DEBUG org.springframework.beans.factory.support.DefaultListableBeanFactory - Creating shared instance of singleton bean 'cacheContext'
17:29:19.878 [main] DEBUG org.springframework.beans.factory.support.DefaultListableBeanFactory - Creating shared instance of singleton bean 'org.springframework.cache.config.internalCacheAdvisor'
17:29:19.879 [main] DEBUG org.springframework.beans.factory.support.DefaultListableBeanFactory - Creating shared instance of singleton bean 'org.springframework.cache.annotation.ProxyCachingConfiguration'
17:29:19.890 [main] DEBUG org.springframework.beans.factory.support.DefaultListableBeanFactory - Creating shared instance of singleton bean 'io.spring.CacheContext$Caching'
17:29:19.896 [main] DEBUG org.springframework.beans.factory.support.DefaultListableBeanFactory - Creating shared instance of singleton bean 'cacheOperationSource'
17:29:19.901 [main] DEBUG org.springframework.beans.factory.support.DefaultListableBeanFactory - Creating shared instance of singleton bean 'cacheInterceptor'
17:29:19.901 [main] DEBUG org.springframework.beans.factory.support.DefaultListableBeanFactory - Autowiring by type from bean name 'cacheInterceptor' via factory method to bean named 'cacheOperationSource'
17:29:19.908 [main] DEBUG org.springframework.beans.factory.support.DefaultListableBeanFactory - Autowiring by type from bean name 'org.springframework.cache.config.internalCacheAdvisor' via factory method to bean named 'cacheOperationSource'
17:29:19.908 [main] DEBUG org.springframework.beans.factory.support.DefaultListableBeanFactory - Autowiring by type from bean name 'org.springframework.cache.config.internalCacheAdvisor' via factory method to bean named 'cacheInterceptor'
17:29:19.919 [main] DEBUG org.springframework.beans.factory.support.DefaultListableBeanFactory - Creating shared instance of singleton bean 'cacheManager'

[wilkinsona]

@snicoll You need a BPP to trigger the problem. This'll do it without Boot:

package com.example.demo;

import org.springframework.beans.factory.config.BeanPostProcessor;
import org.springframework.cache.CacheManager;
import org.springframework.cache.annotation.CachingConfigurerSupport;
import org.springframework.cache.annotation.EnableCaching;
import org.springframework.cache.support.SimpleCacheManager;
import org.springframework.context.annotation.AnnotationConfigApplicationContext;
import org.springframework.context.annotation.Bean;
import org.springframework.context.annotation.Configuration;

@Configuration
public class CacheContext {

	public static void main(String[] args) {
		new AnnotationConfigApplicationContext(CacheContext.class);
	}
	
	@Bean
	static BeanPostProcessor someBeanPostProcessor() {
		return new BeanPostProcessor() {
			
		};
	}
	
	@Bean
	CacheManager cacheManager() {
		return new SimpleCacheManager();
	}
	
	@Configuration
	@EnableCaching
	static class CachingConfig extends CachingConfigurerSupport {
		
	}

}

16:51:55.720 [main] DEBUG org.springframework.context.annotation.AnnotationConfigApplicationContext - Refreshing org.springframework.context.annotation.AnnotationConfigApplicationContext@5eb5c224
16:51:55.733 [main] DEBUG org.springframework.beans.factory.support.DefaultListableBeanFactory - Creating shared instance of singleton bean 'org.springframework.context.annotation.internalConfigurationAnnotationProcessor'
16:51:55.851 [main] DEBUG org.springframework.beans.factory.support.DefaultListableBeanFactory - Creating shared instance of singleton bean 'org.springframework.context.event.internalEventListenerProcessor'
16:51:55.852 [main] DEBUG org.springframework.beans.factory.support.DefaultListableBeanFactory - Creating shared instance of singleton bean 'org.springframework.context.event.internalEventListenerFactory'
16:51:55.853 [main] DEBUG org.springframework.beans.factory.support.DefaultListableBeanFactory - Creating shared instance of singleton bean 'org.springframework.context.annotation.internalAutowiredAnnotationProcessor'
16:51:55.854 [main] DEBUG org.springframework.beans.factory.support.DefaultListableBeanFactory - Creating shared instance of singleton bean 'org.springframework.context.annotation.internalCommonAnnotationProcessor'
16:51:55.857 [main] DEBUG org.springframework.beans.factory.support.DefaultListableBeanFactory - Creating shared instance of singleton bean 'org.springframework.aop.config.internalAutoProxyCreator'
16:51:55.893 [main] DEBUG org.springframework.beans.factory.support.DefaultListableBeanFactory - Creating shared instance of singleton bean 'someBeanPostProcessor'
16:51:55.895 [main] DEBUG org.springframework.beans.factory.support.DefaultListableBeanFactory - Creating shared instance of singleton bean 'org.springframework.cache.config.internalCacheAdvisor'
16:51:55.895 [main] DEBUG org.springframework.beans.factory.support.DefaultListableBeanFactory - Creating shared instance of singleton bean 'org.springframework.cache.annotation.ProxyCachingConfiguration'
16:51:55.901 [main] DEBUG org.springframework.beans.factory.support.DefaultListableBeanFactory - Creating shared instance of singleton bean 'com.example.demo.CacheContext$CachingConfig'
16:51:55.902 [main] INFO org.springframework.context.support.PostProcessorRegistrationDelegate$BeanPostProcessorChecker - Bean 'com.example.demo.CacheContext$CachingConfig' of type [com.example.demo.CacheContext$CachingConfig$$EnhancerBySpringCGLIB$$5115ee57] is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)
16:51:55.906 [main] DEBUG org.springframework.beans.factory.support.DefaultListableBeanFactory - Creating shared instance of singleton bean 'cacheOperationSource'
16:51:55.910 [main] DEBUG org.springframework.beans.factory.support.DefaultListableBeanFactory - Creating shared instance of singleton bean 'cacheInterceptor'
16:51:55.911 [main] DEBUG org.springframework.beans.factory.support.DefaultListableBeanFactory - Autowiring by type from bean name 'cacheInterceptor' via factory method to bean named 'cacheOperationSource'
16:51:55.917 [main] DEBUG org.springframework.beans.factory.support.DefaultListableBeanFactory - Autowiring by type from bean name 'org.springframework.cache.config.internalCacheAdvisor' via factory method to bean named 'cacheOperationSource'
16:51:55.917 [main] DEBUG org.springframework.beans.factory.support.DefaultListableBeanFactory - Autowiring by type from bean name 'org.springframework.cache.config.internalCacheAdvisor' via factory method to bean named 'cacheInterceptor'
16:51:55.928 [main] DEBUG org.springframework.beans.factory.support.DefaultListableBeanFactory - Creating shared instance of singleton bean 'cacheContext'
16:51:55.930 [main] DEBUG org.springframework.beans.factory.support.DefaultListableBeanFactory - Creating shared instance of singleton bean 'cacheManager'

[snicoll]

Sorry, 🤦

[wilkinsona]

Not at all. I only know that because I made the same mistake earlier. I should have shared what I had learned when I opened the issue.

[ThanksForAllTheFish]

sorry to bother, is there any news on this? currently we are blocked from upgrading since some of our monitoring relies on metrics now gone due to this issue

[snicoll]

@ThanksForAllTheFish no problem. I haven't got the time to look at it but I don't understand why that is blocking you from upgrading based on this specific issue in the core framework. Spring Boot 2.5 and Spring Boot 2.6 uses the same spring framework version so something else must have changed to trigger the error.

@wilkinsona also provided a number of hints to fix the problem without having to wait for a fix here, see spring-projects/spring-boot#28840 (comment)

[ThanksForAllTheFish]

@snicoll thanks for your feedback. I did not fully understand the issue and managed to fix the configuration on our side (replacing bean post processor)

[snicoll]

AbstractCachingConfiguration has a setConfigurers that does a lookup by type on CachingConfigurer. Async support has a similar arrangement so it probably is affected by the same problem. I'll have to check what we can do about this.