Provide guidance and better diagnostics when dependency injection makes a bean ineligible for complete post-processing

[wilkinsona]

Affects: 5.2 (I believe earlier versions are also affected)

When the dependency relationships between beans causes one or more beans to be ineligible for bean post-processing, info messages are logged:

2019-11-26 19:49:45.834  INFO 28828 --- [           main] trationDelegate$BeanPostProcessorChecker : Bean 'playgroundApplication' of type [com.example.playground.PlaygroundApplication$$EnhancerBySpringCGLIB$$6f378901] is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)
2019-11-26 19:49:45.837  INFO 28828 --- [           main] trationDelegate$BeanPostProcessorChecker : Bean 'org.springframework.boot.actuate.autoconfigure.metrics.export.simple.SimpleMetricsExportAutoConfiguration' of type [org.springframework.boot.actuate.autoconfigure.metrics.export.simple.SimpleMetricsExportAutoConfiguration] is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)
2019-11-26 19:49:45.848  INFO 28828 --- [           main] trationDelegate$BeanPostProcessorChecker : Bean 'management.metrics.export.simple-org.springframework.boot.actuate.autoconfigure.metrics.export.simple.SimpleProperties' of type [org.springframework.boot.actuate.autoconfigure.metrics.export.simple.SimpleProperties] is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)
2019-11-26 19:49:45.851  INFO 28828 --- [           main] trationDelegate$BeanPostProcessorChecker : Bean 'simpleConfig' of type [org.springframework.boot.actuate.autoconfigure.metrics.export.simple.SimplePropertiesConfigAdapter] is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)
2019-11-26 19:49:45.853  INFO 28828 --- [           main] trationDelegate$BeanPostProcessorChecker : Bean 'org.springframework.boot.actuate.autoconfigure.metrics.MetricsAutoConfiguration' of type [org.springframework.boot.actuate.autoconfigure.metrics.MetricsAutoConfiguration] is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)
2019-11-26 19:49:45.855  INFO 28828 --- [           main] trationDelegate$BeanPostProcessorChecker : Bean 'micrometerClock' of type [io.micrometer.core.instrument.Clock$1] is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)
2019-11-26 19:49:45.865  INFO 28828 --- [           main] trationDelegate$BeanPostProcessorChecker : Bean 'simpleMeterRegistry' of type [io.micrometer.core.instrument.simple.SimpleMeterRegistry] is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)
2019-11-26 19:49:45.878  INFO 28828 --- [           main] trationDelegate$BeanPostProcessorChecker : Bean 'someAdvisor' of type [org.springframework.aop.support.DefaultPointcutAdvisor] is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)

From what I've seen these messages are often missed or presumed to be unimportant as they're at info level. I wonder if warn level would be more appropriate?

Beyond the level at which the messages are logged, the messages describe the problem but it's difficult to connect them to its cause. In this case, you have to know that AOP relies on proxies, that those proxies are created via a bean post-processor, and that any Advisor beans are injected into the post-processor. This chain of events leads to eager initialization of the advisor and its dependencies.

I wonder if it would be possible to provide better diagnostics at runtime to explain why a bean is not eligible for bean post-processing? I'd also welcome some additions to the reference documentation that draw attention to the dangers of injecting dependencies into bean post-processors and also highlight where bean post-processing is used and the care that must then be taken when defining beans used by those post-processors.

[javolek]

Could somebody here elaborate, why it is even possible to eagerly autowire dependencies into the bean-postprocessor. Wouldn't it be better to instantiate bean-postprocessors in another way or to disallow eager dependency instantiation? As far as I can understand this, the chances are high that something won't work as expected if this happens, while i.e. the autoproxying won't be done - the beans are autowirded without the proxy in between. This may result in somthing like the db-transaction missing on method marked as @transactional or even worse - method security not being applied. Or am I wrong? Is this really such an Issue that doesn't deserve more attention?

[breun]

I recently found literally thousands of info log messages from BeanPostProcessorChecker in the logs of a build. This code base has lots of tests, so also lots of duplicate messages. We had been overlooking these messages for years. I've been able to fix ~95% by now, but once we reach 100% I was hoping to be able to make sure that we never make these mistakes again. As long as BeanPostProcessorChecker only logs an info message, I guess new cases will get overlooked again.

@javolek I agree that it would be great if it would be just not possible for people that create their own BeanPostProcessor beans to make this mistake, but do you have any concrete suggestions on how to achieve this?

As long as it's possible to get this wrong, Instead of an option to log at warn or another level, I'd actually like the option to throw an exception, so we can force ourselves to fix this issue when it's triggered by an integration test.

[wilkinsona]

Very nice! Thanks, @jhoeller.