Skip to content

Update metrics documentation to note the benefits of using a MeterBinder when registering a metric that relies on other beans #19557

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Closed
waschmittel opened this issue Jan 7, 2020 · 21 comments
Assignees
Labels
type: documentation A documentation update
Milestone

Comments

@waschmittel
Copy link

waschmittel commented Jan 7, 2020

We use Micrometer in our Spring Boot applications.

When shutting down our applications we sometimes get WARN log messages with Exceptions that say:

Failed to apply the value function for the gauge (...)

All of these value functions fail because some part of the application is already shut down. For example, we have a metric that's based on a Spring Data Repository, so we get

org.springframework.beans.factory.BeanCreationNotAllowedException: Error creating bean with name 'entityManagerFactory': Singleton bean creation not allowed while singletons of this factory are in destruction (Do not request a bean from a BeanFactory in a destroy method implementation!)

I assume this would be avoidable if publishing of Metrics is stopped by calling MeterRegistry.clear() and PushMeterRegistry.stop() when the shutdown begins.

(We are using Datadog, which apparently implements PushMeterRegistry)

@spring-projects-issues spring-projects-issues added the status: waiting-for-triage An issue we've not yet triaged label Jan 7, 2020
@mbhave
Copy link
Contributor

mbhave commented Jan 9, 2020

This was fixed in #12006 but #12121 removed the need to declare the destroy method explicitly. The tests written in #12006 are still green so I would think the stop methods are called when necessary.

@waschmittel Could you provide a small sample with steps on how to reproduce the issue?

@mbhave mbhave added the status: waiting-for-feedback We need additional information before we can continue label Jan 9, 2020
@spring-projects-issues
Copy link
Collaborator

If you would like us to look at this issue, please provide the requested information. If the information is not provided within the next 7 days this issue will be closed.

@spring-projects-issues spring-projects-issues added the status: feedback-reminder We've sent a reminder that we need additional information before we can continue label Jan 16, 2020
@waschmittel
Copy link
Author

waschmittel commented Jan 20, 2020

Tried to reproduce ... the first thing Datadog's PushMeterRegistry does when close() is called, is calling publish().

So this seems to be a Datadog bug after all.

@waschmittel
Copy link
Author

waschmittel commented Jan 20, 2020

Oh wait ... PushMeterRegistry is a part of micrometer (in io.micrometer.core.instrument.push)

So PushMeterRegistry's close() looks like this:

    @Override
    public void close() {
        if (config.enabled()) {
            publishSafely();
        }
        stop();
        super.close();
    }

And publishSafely looks like this:

    private void publishSafely() {
        try {
            publish();
        } catch (Throwable e) {
            logger.warn("Unexpected exception thrown while publishing metrics for " + this.getClass().getSimpleName(), e);
        }
    }

So Micrometer apparently expects metrics to still be extractable when close() is called.

So I guess Spring should handle a PushMeterRegistry differently from a Non-Push MeterRegistry - Although I assume it would be difficult to call close() while the context is still fully available.

So I can can probably my metrics to handle the Exceptions that occur while the context is already being closed, but I would prefer a generic solution for this issue, of course.

@waschmittel waschmittel reopened this Jan 20, 2020
@spring-projects-issues spring-projects-issues added status: feedback-provided Feedback has been provided and removed status: waiting-for-feedback We need additional information before we can continue status: feedback-reminder We've sent a reminder that we need additional information before we can continue labels Jan 20, 2020
@snicoll
Copy link
Member

snicoll commented Jan 20, 2020

So Micrometer apparently expects metrics to still be extractable when close() is called.

@waschmittel I think the intention is to let the registry publish metrics "safely" (as the method name states) before closing it. The problem is that other parts of the infrastructure may have already been closed when the registry itself is closed. Perhaps the error message is misleading and can be refined (but that would have to be dealt in Micrometer itself).

Paging @shakuzen for insights.

@waschmittel
Copy link
Author

Or Spring could do something to make config.enabled() false before calling close() (if possible - I have no idea).
Although I think this is surprising behavior by Micrometer to do a last publish when closing.

@snicoll
Copy link
Member

snicoll commented Jan 20, 2020

Or Spring could do something to make config.enabled() false before calling close()

Why would we do that? I'd rather understand the intention of Micrometer rather than trying to force it to do something different. Doing something different may be the right call after all but there is no reason it should be specific to a spring app.

@arijitdeb1
Copy link

arijitdeb1 commented Feb 24, 2020

Hi team,

Any resolution to this issue as me too having the same concern and need some explanation to put up. Thanks in advance.

@snicoll
Copy link
Member

snicoll commented Feb 24, 2020

@arijitdeb1 I pinged @shakuzen for feedback and we need to follow-up. Thanks for the nudge, I've flagged this one for team attention.

@snicoll snicoll added the for: team-attention An issue we'd like other members of the team to review label Feb 24, 2020
@wilkinsona wilkinsona added status: blocked An issue that's blocked on an external project change and removed status: feedback-provided Feedback has been provided for: team-attention An issue we'd like other members of the team to review labels Mar 4, 2020
@wilkinsona
Copy link
Member

We might be able to do something with SmartLifecycle and phases so that the meter registries are stopped before other beans. Before investigating that approach, we'd still like to get some feedback from @shakuzen.

@shakuzen
Copy link
Member

shakuzen commented Mar 5, 2020

Sorry for not responding before. The intention of calling publish on close is to do a final publish so any changes in metrics between the previous publish (possibly never for a short-lived application) and the registry being closed are not lost.

We might be able to do something with SmartLifecycle and phases so that the meter registries are stopped before other beans.

If that is possible, it sounds like the route to go. If that could be achieved, I would expect there won't be any exceptions thrown on the final publish (unless exceptions are being thrown on other publishes for some reason).

@wilkinsona
Copy link
Member

Thinking some more about SmartLifecycle, that could only really help with an auto-configured PushMeterRegistry. Once a user has configured their own, I don't think it would then be reasonable for Boot to meddle with its lifecycle.

I think a more natural way to fix this would be via dependency relationships between the various beans that are involved. In this context, it's interesting that Spring Data is apparently triggering bean creation. That suggests that the bean in question isn't being injected and, therefore, that the container probably doesn't have a depends on relationship between the repository and the bean.

@waschmittel I think we're back to needing a sample, please. I'd like to understand exactly what's happening in terms of the bean that are involved in getting the gauge's value and the dependency relationships that are in play when the application context is being closed.

@wilkinsona wilkinsona added status: waiting-for-feedback We need additional information before we can continue and removed status: blocked An issue that's blocked on an external project change labels Mar 5, 2020
@spring-projects-issues
Copy link
Collaborator

If you would like us to look at this issue, please provide the requested information. If the information is not provided within the next 7 days this issue will be closed.

@spring-projects-issues spring-projects-issues added the status: feedback-reminder We've sent a reminder that we need additional information before we can continue label Mar 12, 2020
@waschmittel
Copy link
Author

I was unpexcedly busy this week, but I will try to set up a sample project that reproduces this next week.

@spring-projects-issues spring-projects-issues added the status: feedback-provided Feedback has been provided label Mar 13, 2020
@spring-projects-issues spring-projects-issues removed status: waiting-for-feedback We need additional information before we can continue status: feedback-reminder We've sent a reminder that we need additional information before we can continue labels Mar 13, 2020
@snicoll snicoll added status: waiting-for-feedback We need additional information before we can continue and removed status: feedback-provided Feedback has been provided labels Mar 13, 2020
@waschmittel
Copy link
Author

Please take a look at https://github.com/waschmittel/spring-boot-19557 that reproduces this @wilkinsona

@spring-projects-issues spring-projects-issues added status: feedback-provided Feedback has been provided and removed status: waiting-for-feedback We need additional information before we can continue labels Mar 20, 2020
@wilkinsona
Copy link
Member

wilkinsona commented Mar 24, 2020

Thanks for the sample, @waschmittel. I've reproduced the problem. Here's the full stack trace of the failure:

org.springframework.beans.factory.BeanCreationNotAllowedException: Error creating bean with name 'entityManagerFactory': Singleton bean creation not allowed while singletons of this factory are in destruction (Do not request a bean from a BeanFactory in a destroy method implementation!)
	at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.getSingleton(DefaultSingletonBeanRegistry.java:208) ~[spring-beans-5.2.4.RELEASE.jar:5.2.4.RELEASE]
	at org.springframework.beans.factory.support.AbstractBeanFactory.doGetBean(AbstractBeanFactory.java:321) ~[spring-beans-5.2.4.RELEASE.jar:5.2.4.RELEASE]
	at org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:202) ~[spring-beans-5.2.4.RELEASE.jar:5.2.4.RELEASE]
	at org.springframework.beans.factory.support.DefaultListableBeanFactory.getBeansOfType(DefaultListableBeanFactory.java:617) ~[spring-beans-5.2.4.RELEASE.jar:5.2.4.RELEASE]
	at org.springframework.beans.factory.BeanFactoryUtils.beansOfTypeIncludingAncestors(BeanFactoryUtils.java:378) ~[spring-beans-5.2.4.RELEASE.jar:5.2.4.RELEASE]
	at org.springframework.dao.support.PersistenceExceptionTranslationInterceptor.detectPersistenceExceptionTranslators(PersistenceExceptionTranslationInterceptor.java:168) ~[spring-tx-5.2.4.RELEASE.jar:5.2.4.RELEASE]
	at org.springframework.dao.support.PersistenceExceptionTranslationInterceptor.invoke(PersistenceExceptionTranslationInterceptor.java:150) ~[spring-tx-5.2.4.RELEASE.jar:5.2.4.RELEASE]
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186) ~[spring-aop-5.2.4.RELEASE.jar:5.2.4.RELEASE]
	at org.springframework.data.jpa.repository.support.CrudMethodMetadataPostProcessor$CrudMethodMetadataPopulatingMethodInterceptor.invoke(CrudMethodMetadataPostProcessor.java:178) ~[spring-data-jpa-2.2.5.RELEASE.jar:2.2.5.RELEASE]
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186) ~[spring-aop-5.2.4.RELEASE.jar:5.2.4.RELEASE]
	at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:95) ~[spring-aop-5.2.4.RELEASE.jar:5.2.4.RELEASE]
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186) ~[spring-aop-5.2.4.RELEASE.jar:5.2.4.RELEASE]
	at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:212) ~[spring-aop-5.2.4.RELEASE.jar:5.2.4.RELEASE]
	at com.sun.proxy.$Proxy101.count(Unknown Source) ~[na:na]
	at io.micrometer.core.instrument.Gauge.lambda$builder$0(Gauge.java:58) ~[micrometer-core-1.3.5.jar:1.3.5]
	at io.micrometer.core.instrument.StrongReferenceGaugeFunction.applyAsDouble(StrongReferenceGaugeFunction.java:47) ~[micrometer-core-1.3.5.jar:1.3.5]
	at io.micrometer.core.instrument.internal.DefaultGauge.value(DefaultGauge.java:54) ~[micrometer-core-1.3.5.jar:1.3.5]
	at io.micrometer.core.instrument.Measurement.getValue(Measurement.java:39) ~[micrometer-core-1.3.5.jar:1.3.5]
	at io.micrometer.datadog.DatadogMeterRegistry.lambda$writeMeter$12(DatadogMeterRegistry.java:210) ~[micrometer-registry-datadog-1.3.5.jar:1.3.5]
	at java.base/java.util.stream.ReferencePipeline$3$1.accept(ReferencePipeline.java:195) ~[na:na]
	at java.base/java.util.Collections$2.tryAdvance(Collections.java:4745) ~[na:na]
	at java.base/java.util.Collections$2.forEachRemaining(Collections.java:4753) ~[na:na]
	at java.base/java.util.stream.AbstractPipeline.copyInto(AbstractPipeline.java:484) ~[na:na]
	at java.base/java.util.stream.AbstractPipeline.wrapAndCopyInto(AbstractPipeline.java:474) ~[na:na]
	at java.base/java.util.stream.ForEachOps$ForEachOp.evaluateSequential(ForEachOps.java:150) ~[na:na]
	at java.base/java.util.stream.ForEachOps$ForEachOp$OfRef.evaluateSequential(ForEachOps.java:173) ~[na:na]
	at java.base/java.util.stream.AbstractPipeline.evaluate(AbstractPipeline.java:234) ~[na:na]
	at java.base/java.util.stream.ReferencePipeline.forEach(ReferencePipeline.java:497) ~[na:na]
	at java.base/java.util.stream.ReferencePipeline$7$1.accept(ReferencePipeline.java:274) ~[na:na]
	at java.base/java.util.ArrayList$SubList$2.forEachRemaining(ArrayList.java:1510) ~[na:na]
	at java.base/java.util.stream.AbstractPipeline.copyInto(AbstractPipeline.java:484) ~[na:na]
	at java.base/java.util.stream.AbstractPipeline.wrapAndCopyInto(AbstractPipeline.java:474) ~[na:na]
	at java.base/java.util.stream.ReduceOps$ReduceOp.evaluateSequential(ReduceOps.java:913) ~[na:na]
	at java.base/java.util.stream.AbstractPipeline.evaluate(AbstractPipeline.java:234) ~[na:na]
	at java.base/java.util.stream.ReferencePipeline.collect(ReferencePipeline.java:578) ~[na:na]
	at io.micrometer.datadog.DatadogMeterRegistry.publish(DatadogMeterRegistry.java:134) ~[micrometer-registry-datadog-1.3.5.jar:1.3.5]
	at io.micrometer.core.instrument.push.PushMeterRegistry.publishSafely(PushMeterRegistry.java:48) ~[micrometer-core-1.3.5.jar:1.3.5]
	at io.micrometer.core.instrument.push.PushMeterRegistry.close(PushMeterRegistry.java:83) ~[micrometer-core-1.3.5.jar:1.3.5]
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:na]
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[na:na]
	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:na]
	at java.base/java.lang.reflect.Method.invoke(Method.java:566) ~[na:na]
	at org.springframework.beans.factory.support.DisposableBeanAdapter.invokeCustomDestroyMethod(DisposableBeanAdapter.java:339) ~[spring-beans-5.2.4.RELEASE.jar:5.2.4.RELEASE]
	at org.springframework.beans.factory.support.DisposableBeanAdapter.destroy(DisposableBeanAdapter.java:273) ~[spring-beans-5.2.4.RELEASE.jar:5.2.4.RELEASE]
	at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.destroyBean(DefaultSingletonBeanRegistry.java:571) ~[spring-beans-5.2.4.RELEASE.jar:5.2.4.RELEASE]
	at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.destroySingleton(DefaultSingletonBeanRegistry.java:543) ~[spring-beans-5.2.4.RELEASE.jar:5.2.4.RELEASE]
	at org.springframework.beans.factory.support.DefaultListableBeanFactory.destroySingleton(DefaultListableBeanFactory.java:1072) ~[spring-beans-5.2.4.RELEASE.jar:5.2.4.RELEASE]
	at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.destroySingletons(DefaultSingletonBeanRegistry.java:504) ~[spring-beans-5.2.4.RELEASE.jar:5.2.4.RELEASE]
	at org.springframework.beans.factory.support.DefaultListableBeanFactory.destroySingletons(DefaultListableBeanFactory.java:1065) ~[spring-beans-5.2.4.RELEASE.jar:5.2.4.RELEASE]
	at org.springframework.context.support.AbstractApplicationContext.destroyBeans(AbstractApplicationContext.java:1060) ~[spring-context-5.2.4.RELEASE.jar:5.2.4.RELEASE]
	at org.springframework.context.support.AbstractApplicationContext.doClose(AbstractApplicationContext.java:1029) ~[spring-context-5.2.4.RELEASE.jar:5.2.4.RELEASE]
	at org.springframework.context.support.AbstractApplicationContext.close(AbstractApplicationContext.java:978) ~[spring-context-5.2.4.RELEASE.jar:5.2.4.RELEASE]
	at org.springframework.boot.SpringApplication.handleRunFailure(SpringApplication.java:803) ~[spring-boot-2.2.5.RELEASE.jar:2.2.5.RELEASE]
	at org.springframework.boot.SpringApplication.run(SpringApplication.java:325) ~[spring-boot-2.2.5.RELEASE.jar:2.2.5.RELEASE]
	at org.springframework.boot.SpringApplication.run(SpringApplication.java:1226) ~[spring-boot-2.2.5.RELEASE.jar:2.2.5.RELEASE]
	at org.springframework.boot.SpringApplication.run(SpringApplication.java:1215) ~[spring-boot-2.2.5.RELEASE.jar:2.2.5.RELEASE]
	at com.example.demo.DemoApplication.main(DemoApplication.java:10) ~[classes/:na]

A bean lookup is being performed to determine the persistence exception translator to use. The exception that has triggered this is due to an attempt to start a transaction when the entity manager factory has been closed.

@wilkinsona
Copy link
Member

You can avoid the problem by adding the following @Bean definition to the sample:

@Bean
static AbstractDependsOnBeanFactoryPostProcessor entityManagerFactoryMeterRegistryDependency() {
    return new AbstractDependsOnBeanFactoryPostProcessor(DatadogMeterRegistry.class, EntityManagerFactory.class) {};
}

This ensures that the meter registry is closed before the EntityManagerFactory. I'm now investigating if it's possible for us to establish this relationship automatically.

@wilkinsona
Copy link
Member

wilkinsona commented Mar 24, 2020

On closer inspection, the lack of dependency relationships between the various beans that are involved is due to how the Gauge is being registered:

@Bean
public Gauge queueSize(MeterRegistry registry, QueueItemRepository repository) {
    return Gauge.builder("queueSize", repository::count).register(registry);
}

The registration is being performed as a side-effect of the queueSize bean being created. This happens towards the end of the startup processing, by which time the disposal ordering of the meter registry and the entity manager factory have already been established.

Switching to use a MeterBinder to register the gauge fixes the problem. All MeterBinder beans are created and invoked when the MeterRegistry is being created. This allows the dependency relationship between the MeterBinder and the EntityManagerFactory to be established.

In short, there's no need for the workaround above if the gauge is registered using a MeterBinder instead of relying on a side-effect of bean creation:

diff --git a/src/main/java/com/example/demo/MetricsConfig.java b/src/main/java/com/example/demo/MetricsConfig.java
index d3e77a2..04020ea 100644
--- a/src/main/java/com/example/demo/MetricsConfig.java
+++ b/src/main/java/com/example/demo/MetricsConfig.java
@@ -1,16 +1,20 @@
 package com.example.demo;
 
-import io.micrometer.core.instrument.Gauge;
-import io.micrometer.core.instrument.MeterRegistry;
 import org.springframework.context.annotation.Bean;
 import org.springframework.context.annotation.Configuration;
 
+import io.micrometer.core.instrument.Gauge;
+import io.micrometer.core.instrument.MeterRegistry;
+import io.micrometer.core.instrument.binder.MeterBinder;
+
 @Configuration
 public class MetricsConfig {
-    @Bean
-    public Gauge queueSize(MeterRegistry registry, QueueItemRepository repository) {
 
-        return Gauge.builder("queueSize", repository::count).register(registry);
+    @Bean
+    public MeterBinder queueMeterBinder(QueueItemRepository repository) {
+        return (registry) -> {
+            Gauge.builder("queueSize", repository::count).register(registry);
+        };
     }
 
 }

We should update the documentation to recommend broader use of a MeterBinder, particularly when the metric being registered is backed by other beans that are involved in the application context's lifecycle.

@wilkinsona wilkinsona added type: documentation A documentation update and removed status: feedback-provided Feedback has been provided status: waiting-for-triage An issue we've not yet triaged labels Mar 24, 2020
@wilkinsona wilkinsona added this to the 2.2.x milestone Mar 24, 2020
@wilkinsona wilkinsona changed the title Spring should (probably) call MeterRegistry.clear() and PushMeterRegistry.stop() on shutdown Update metrics documentation to note the benefits of using a MeterBinder when registering a metric that relies on other beans Mar 24, 2020
@wilkinsona wilkinsona self-assigned this Jul 28, 2020
@wilkinsona wilkinsona modified the milestones: 2.2.x, 2.2.10 Jul 28, 2020
@wojciechkedziora
Copy link

wojciechkedziora commented Nov 6, 2023

Hi @wilkinsona - after upgrading to the latest spring-boot 3.1.5 we've spot similar issue. I've reproduced it using the same project from previous comment - you can check it: https://github.com/wojciechkedziora/spring-boot-3-19557 (changes: spring boot version + MeterBinder solution from your previous comment). Applying short-term solution from this post obviously resolves the issue. Could you take a look? Thanks

@wilkinsona
Copy link
Member

Thanks, @wojciechkedziora. I've reproduced the problem with your updated sample and can see that things have changed since 2.2. I'm not yet sure of the cause of that, but it may be due to #30636. Please open a new issue so that we can investigate further.

@wojciechkedziora
Copy link

@wilkinsona Thanks for your answer. I've created new issue - #38240.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
type: documentation A documentation update
Projects
None yet
Development

No branches or pull requests

8 participants