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

[chengchen]

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?

[wilkinsona]

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

1. Bean post-processors are being registered
2. meterRegistryPostProcessor is being created
3. meterRegistryPostProcessor is, itself, being post-processed, in this case to see if it needs to be proxied for AOP.
4. AOP candidate advisors are being created
5. Spring Retry's RetryConfiguration is being created as it's a an advisor
6. RetryListeners are being injected into RetryConfiguration
7. retryStatsListener is being created as it's a RetryListener. It needs retryStatsRepository
8. simpleMeterRegistry is being created so it can be injected into retryStatsRepository
9. 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

[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.

[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.

[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?

[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.

[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.

[wilkinsona]

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

[robertpanzer]

Thanks, that's even better! 👍