SpringBoot Spring Retry causes RetryListener beans to be initialised early, making them and their dependencies ineligible for post-processing

Hello,

I have encountered a case where I would like to send retry metrics to MeterRegistry with the help of StatisticsListener. Basically, I tried to decorate the existing DefaultStatisticsRepository and use it in StatisticsListener. The affected version is 2.1.5.RELEASE.

But unfortunately, registering this StatisticsListener initialize the MeterRegistry way earlier than the MeterRegistryPostProcessor manages to post-process the MeterRegistry, which results in missing certain metrics like jvm memory, jvm threads, etc...

I prepared a simple project to illustrate this issue: https://github.com/chengchen/metrics-example/blob/master/src/main/java/com/chengchen/metricsexample/MetricsExampleApplication.java If you try to call /actuator/metrics, you will not see all the missing metrics that I mentioned. If you remove these 2 beans, metrics will work again.

In my opinion, it's not up to the user to know that StatisticsListener will trigger early initialization of its dependent beans (in this case MeterRegistry), probably some fix could be in the MeterRegistryPostProcessor level?

Comment From: wilkinsona

Thanks for the sample. Here's what's happening:

Bean post-processors are being registered
meterRegistryPostProcessor is being created
meterRegistryPostProcessor is, itself, being post-processed, in this case to see if it needs to be proxied for AOP.
AOP candidate advisors are being created
Spring Retry's RetryConfiguration is being created as it's a an advisor
RetryListeners are being injected into RetryConfiguration
retryStatsListener is being created as it's a RetryListener. It needs retryStatsRepository
simpleMeterRegistry is being created so it can be injected into retryStatsRepository
retryStatsRepository is being created so it can be injected into retryStatsListener

In this sequence of events, it's step 8 that is causing the problem.

Here are the info messages that record the beans the have been initialised too early to be eligible for post-processing:

2019-05-28 08:24:57.426  INFO 14140 --- [           main] trationDelegate$BeanPostProcessorChecker : Bean 'metricsExampleApplication' of type [com.chengchen.metricsexample.MetricsExampleApplication$$EnhancerBySpringCGLIB$$9789dce4] is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)
2019-05-28 08:24:57.429  INFO 14140 --- [           main] trationDelegate$BeanPostProcessorChecker : Bean 'org.springframework.boot.actuate.autoconfigure.metrics.export.simple.SimpleMetricsExportAutoConfiguration' of type [org.springframework.boot.actuate.autoconfigure.metrics.export.simple.SimpleMetricsExportAutoConfiguration$$EnhancerBySpringCGLIB$$aec3cec8] is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)
2019-05-28 08:24:57.437  INFO 14140 --- [           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-05-28 08:24:57.440  INFO 14140 --- [           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-05-28 08:24:57.441  INFO 14140 --- [           main] trationDelegate$BeanPostProcessorChecker : Bean 'org.springframework.boot.actuate.autoconfigure.metrics.MetricsAutoConfiguration' of type [org.springframework.boot.actuate.autoconfigure.metrics.MetricsAutoConfiguration$$EnhancerBySpringCGLIB$$65af7788] is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)
2019-05-28 08:24:57.443  INFO 14140 --- [           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-05-28 08:24:57.455  INFO 14140 --- [           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-05-28 08:24:57.459  INFO 14140 --- [           main] trationDelegate$BeanPostProcessorChecker : Bean 'retryStatsRepository' of type [com.chengchen.metricsexample.MeteredStatisticsRepository] is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)
2019-05-28 08:24:57.460  INFO 14140 --- [           main] trationDelegate$BeanPostProcessorChecker : Bean 'retryStatsListener' of type [org.springframework.retry.stats.StatisticsListener] is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)
2019-05-28 08:24:57.466  INFO 14140 --- [           main] trationDelegate$BeanPostProcessorChecker : Bean 'org.springframework.retry.annotation.RetryConfiguration' of type [org.springframework.retry.annotation.RetryConfiguration$$EnhancerBySpringCGLIB$$fef374e] is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)

it's not up to the user to know that StatisticsListener will trigger early initialization of its dependent beans (in this case MeterRegistry)

I agree. AOP advice that retrieves beans from the context (RetryListener instances in this case) can be problematic as it results in those beans' dependency graphs being initialised during bean post-processor registration.

probably some fix could be in the MeterRegistryPostProcessor level

We can't fix this in MeterRegistryPostProcessor is its code is not involved in the sequence of events described above. Even if we could, it would be a point solution for a wider problem.

I think this problem needs to be addressed in Spring Retry. In the meantime, you can work around the problem and minimise the number of beans the are ineligible for post-processing by making both retryStatsListener and retryStatsRepository static and making the injection of StatisticsRepository @Lazy:

@Bean
static StatisticsListener retryStatsListener(@Lazy StatisticsRepository statisticsRepository) {
    return new StatisticsListener(statisticsRepository);
}

@Bean
static StatisticsRepository retryStatsRepository(MeterRegistry registry) {
    return new MeteredStatisticsRepository(new DefaultStatisticsRepository(), registry);
}

Can you please open a Spring Retry issue and comment here with a link to it?

/cc @dsyer

Comment From: chengchen

@wilkinsona Thanks a lot! I agree with your analysis, I will take a look at Spring Retry part. And I am aware that the workaround is easy to do in this case, but here we are ignoring some metrics silently in this case which was a bit annoying for me.

Comment From: wilkinsona

we are ignoring some metrics silently in this case which was a bit annoying for me.

While it's certainly annoying, it doesn't happen silently. As shown above, there are 10 info log messages for early initialisation that suggest something isn't right and 6 of them are for metrics-related beans.

Comment From: robertpanzer

@wilkinsona I was just stumbling over this myself and I tried adding the above 2 methods to my SpringBootApplication, and I see in the debugger that they are called, but still the metrics are not registered:

021-10-20T09:18:25,402 INFO  [main] o.s.c.s.PostProcessorRegistrationDelegate$BeanPostProcessorChecker [PostProcessorRegistrationDelegate.java:335]: Bean 'org.springframework.security.access.expression.method.DefaultMethodSecurityExpressionHandler@51e94b7d' of type [org.springframework.security.access.expression.method.DefaultMethodSecurityExpressionHandler] is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)
2021-10-20T09:18:25,418 INFO  [main] o.s.c.s.PostProcessorRegistrationDelegate$BeanPostProcessorChecker [PostProcessorRegistrationDelegate.java:335]: Bean 'methodSecurityMetadataSource' of type [org.springframework.security.access.method.DelegatingMethodSecurityMetadataSource] is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)
2021-10-20T09:18:25,504 INFO  [main] o.s.c.s.PostProcessorRegistrationDelegate$BeanPostProcessorChecker [PostProcessorRegistrationDelegate.java:335]: Bean 'org.springframework.boot.actuate.autoconfigure.metrics.export.prometheus.PrometheusMetricsExportAutoConfiguration' of type [org.springframework.boot.actuate.autoconfigure.metrics.export.prometheus.PrometheusMetricsExportAutoConfiguration] is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)
2021-10-20T09:18:25,533 INFO  [main] o.s.c.s.PostProcessorRegistrationDelegate$BeanPostProcessorChecker [PostProcessorRegistrationDelegate.java:335]: Bean 'management.metrics.export.prometheus-org.springframework.boot.actuate.autoconfigure.metrics.export.prometheus.PrometheusProperties' of type [org.springframework.boot.actuate.autoconfigure.metrics.export.prometheus.PrometheusProperties] is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)
2021-10-20T09:18:25,541 INFO  [main] o.s.c.s.PostProcessorRegistrationDelegate$BeanPostProcessorChecker [PostProcessorRegistrationDelegate.java:335]: Bean 'prometheusConfig' of type [org.springframework.boot.actuate.autoconfigure.metrics.export.prometheus.PrometheusPropertiesConfigAdapter] is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)
2021-10-20T09:18:25,558 INFO  [main] o.s.c.s.PostProcessorRegistrationDelegate$BeanPostProcessorChecker [PostProcessorRegistrationDelegate.java:335]: Bean 'collectorRegistry' of type [io.prometheus.client.CollectorRegistry] is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)
2021-10-20T09:18:25,567 INFO  [main] o.s.c.s.PostProcessorRegistrationDelegate$BeanPostProcessorChecker [PostProcessorRegistrationDelegate.java:335]: 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)
2021-10-20T09:18:25,571 INFO  [main] o.s.c.s.PostProcessorRegistrationDelegate$BeanPostProcessorChecker [PostProcessorRegistrationDelegate.java:335]: 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)
2021-10-20T09:18:25,601 INFO  [main] o.s.c.s.PostProcessorRegistrationDelegate$BeanPostProcessorChecker [PostProcessorRegistrationDelegate.java:335]: Bean 'prometheusMeterRegistry' of type [io.micrometer.prometheus.PrometheusMeterRegistry] is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)
2021-10-20T09:18:25,617 INFO  [main] o.s.c.s.PostProcessorRegistrationDelegate$BeanPostProcessorChecker [PostProcessorRegistrationDelegate.java:335]: Bean 'gitOpsRetryListener' of type [com.foo.FooRetryListener] is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)
2021-10-20T09:18:25,622 INFO  [main] o.s.c.s.PostProcessorRegistrationDelegate$BeanPostProcessorChecker [PostProcessorRegistrationDelegate.java:335]: Bean 'retryStatsListener' of type [org.springframework.retry.stats.StatisticsListener] is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)
2021-10-20T09:18:25,639 INFO  [main] o.s.c.s.PostProcessorRegistrationDelegate$BeanPostProcessorChecker [PostProcessorRegistrationDelegate.java:335]: Bean 'org.springframework.retry.annotation.RetryConfiguration' of type [org.springframework.retry.annotation.RetryConfiguration$$EnhancerBySpringCGLIB$$c53fcdcf] is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)
2021-10-20T09:18:25,698 INFO  [main] o.s.c.s.PostProcessorRegistrationDelegate$BeanPostProcessorChecker [PostProcessorRegistrationDelegate.java:335]: Bean 'org.springframework.cloud.autoconfigure.ConfigurationPropertiesRebinderAutoConfiguration' of type [org.springframework.cloud.autoconfigure.ConfigurationPropertiesRebinderAutoConfiguration$$EnhancerBySpringCGLIB$$eb9638a7] is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)

I am on Spring Boot 2.3.9. Is there anything else I can do to fix this?

Comment From: wilkinsona

@robertpanzer Spring Retry may not be the (only) cause of eager initialization. I can't tell from that list of eagerly-initialised beans. If you can reproduce the problem in a minimal app, please open a new issue and we can take a look. If you want to try to diagnose the problem yourself, I'd place a breakpoint in the @Bean method for one of the eagerly initialized beans and look through the stack to see which bean is triggering it.

Comment From: robertpanzer

Thanks, that helped. It was my RetryListener that somehow triggered this problem too. I wasn't able to work around this by make this a lazy bean, instead I am getting the MeterRegistry from the ConfigurableListableBeanFactory when the RetryListener is invoked at runtime. Not beautiful but seems to do the trick.

I guess I need to learn more and better understand in detail how the bean construction and injection works in Spring.

Comment From: wilkinsona

Rather than using the bean factory, you could inject an ObjectProvider<MeterRegistry> and delay calling it until the RetryListener is invoked.

Comment From: robertpanzer

Thanks, that's even better! 👍