Skip to content
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

Collector already registered that provides name: cache_request_total #2399

Closed
carbotaniuman opened this issue Jan 11, 2021 · 13 comments
Closed
Labels
bug A general bug registry: prometheus A Prometheus Registry related issue
Milestone

Comments

@carbotaniuman
Copy link

carbotaniuman commented Jan 11, 2021

app_1         | java.lang.IllegalArgumentException: Collector already registered that provides name: cache_request_total
app_1         |         at io.prometheus.client.CollectorRegistry.register(CollectorRegistry.java:54)
app_1         |         at io.prometheus.client.Collector.register(Collector.java:139)
app_1         |         at io.micrometer.prometheus.PrometheusMeterRegistry.lambda$applyToCollector$16(PrometheusMeterRegistry.java:410)
app_1         |         at java.base/java.util.concurrent.ConcurrentHashMap.compute(Unknown Source)
app_1         |         at io.micrometer.prometheus.PrometheusMeterRegistry.applyToCollector(PrometheusMeterRegistry.java:406)
app_1         |         at io.micrometer.prometheus.PrometheusMeterRegistry.newCounter(PrometheusMeterRegistry.java:109)
app_1         |         at io.micrometer.core.instrument.MeterRegistry.lambda$registerMeterIfNecessary$5(MeterRegistry.java:561)
app_1         |         at io.micrometer.core.instrument.MeterRegistry.getOrCreateMeter(MeterRegistry.java:614)
app_1         |         at io.micrometer.core.instrument.MeterRegistry.registerMeterIfNecessary(MeterRegistry.java:568)
app_1         |         at io.micrometer.core.instrument.MeterRegistry.registerMeterIfNecessary(MeterRegistry.java:561)
app_1         |         at io.micrometer.core.instrument.MeterRegistry.counter(MeterRegistry.java:284)
app_1         |         at io.micrometer.core.instrument.Counter$Builder.register(Counter.java:128)
app_1         |         at io.micrometer.core.instrument.MeterRegistry.counter(MeterRegistry.java:391)
app_1         |         at io.micrometer.core.instrument.MeterRegistry.counter(MeterRegistry.java:402)

Running micrometer 1.6.2. I just initialized a bunch of counters with different labels.

In constructor of application,

registry.counter("cache.request", "type", "MISS").count()
registry.counter("cache.request", "type", "HIT").count()
@shakuzen shakuzen added the registry: prometheus A Prometheus Registry related issue label Jan 12, 2021
@shakuzen
Copy link
Member

Could you provide a minimal sample project to reproduce this issue so we can more easily investigate and ensure any fix is working properly for your use case? I tried to reproduce this but was not able.

class GitHub2399Test {

    MeterRegistry registry = new PrometheusMeterRegistry(PrometheusConfig.DEFAULT);

    @Test
    void collectorAlreadyRegistered() {
        registry.counter("cache.request", "type", "MISS").count();
        registry.counter("cache.request", "type", "HIT").count();
    }
}

@shakuzen shakuzen added the waiting for feedback We need additional information before we can continue label Jan 12, 2021
@dreamershl
Copy link

dreamershl commented Jan 12, 2021

I have similar case when I try to register the same name timer with different tags.

the reason is because when 2 same name timer with different tags, the PrometheusMeterRegistry::applyToCollector() will remove the record from the collectorMap. But it won't unregister it from the registry. So 3rd time will always encounter the exception

image

@tkesling
Copy link

tkesling commented Jan 20, 2021

We are having the same issue and looking for a work around or fix.

Here is class that we used to reproduce the issue.

public class MeterTest {
	
	private PrometheusMeterRegistry registry;

	public MeterTest() 
	{
		registry = new PrometheusMeterRegistry(PrometheusConfig.DEFAULT);
		Metrics.addRegistry(registry);
	}
	
	
	public static void main(String[] args) {

		MeterTest mt = new MeterTest();
		mt.addMeters();
		mt.scrape();
	}

	public void addMeters()
	{
		
		String metricsPrefix = "metertest";

		Timer.Sample ts1 = Timer.start(Metrics.globalRegistry);
		ts1.stop(Metrics.globalRegistry.timer(
				String.format("%s.%s", metricsPrefix, "service.request"), 
				"service", "PrsnlService", 
				"method", "read",
				"result", "Success"));
		
		Timer.Sample ts2 = Timer.start(Metrics.globalRegistry);
		ts2.stop(Metrics.globalRegistry.timer(
			String.format("%s.%s", metricsPrefix, "service.request"), 
			"service", "SurgeonRegistryService", 
			"method", "query",
			"result", "Success"));
		
		Timer.Sample ts3 = Timer.start(Metrics.globalRegistry);
		ts3.stop(Metrics.globalRegistry.timer(
				String.format("%s.%s", metricsPrefix, "service.request"), 
				"service", "SurgeonService", 
				"method", "read",
				"inRegistry", "True",
				"result", "Success"));
		
		Timer.Sample ts4 = Timer.start(Metrics.globalRegistry);
		ts4.stop(Metrics.globalRegistry.timer(
				String.format("%s.%s", metricsPrefix, "service.request"), 
				"service", "ScheduledSurgeryService", 
				"method", "queryByNPI",
				"douUser", "True",
				"result", "Success"));
		
		Timer.Sample ts5 = Timer.start(Metrics.globalRegistry);
		ts5.stop(Metrics.globalRegistry.timer(
				String.format("%s.%s", metricsPrefix, "service.request"), 
				"service", "SurgerySurveyService", 
				"method", "queryByCaseNumber",
				"result", "Success"));
	}
	
	public void scrape()
	{
		System.out.println(registry.scrape());
	}
}

This is the stacktrace:

Exception in thread "main" java.lang.IllegalArgumentException: Collector already registered that provides name: metertest_service_request_seconds_count
	at io.prometheus.client.CollectorRegistry.register(CollectorRegistry.java:54)
	at io.prometheus.client.Collector.register(Collector.java:139)
	at io.micrometer.prometheus.PrometheusMeterRegistry.lambda$applyToCollector$16(PrometheusMeterRegistry.java:410)
	at io.micrometer.prometheus.PrometheusMeterRegistry$$Lambda$46/0000000010AEE8F0.apply(Unknown Source)
	at java.util.concurrent.ConcurrentHashMap.compute(ConcurrentHashMap.java:1864)
	at io.micrometer.prometheus.PrometheusMeterRegistry.applyToCollector(PrometheusMeterRegistry.java:406)
	at io.micrometer.prometheus.PrometheusMeterRegistry.newTimer(PrometheusMeterRegistry.java:200)
	at io.micrometer.core.instrument.MeterRegistry.lambda$timer$2(MeterRegistry.java:310)
	at io.micrometer.core.instrument.MeterRegistry$$Lambda$35/0000000010AE0BB0.apply(Unknown Source)
	at io.micrometer.core.instrument.MeterRegistry.getOrCreateMeter(MeterRegistry.java:614)
	at io.micrometer.core.instrument.MeterRegistry.registerMeterIfNecessary(MeterRegistry.java:568)
	at io.micrometer.core.instrument.MeterRegistry.timer(MeterRegistry.java:308)
	at io.micrometer.core.instrument.Timer$Builder.register(Timer.java:400)
	at io.micrometer.core.instrument.composite.CompositeTimer.registerNewMeter(CompositeTimer.java:140)
	at io.micrometer.core.instrument.composite.CompositeTimer.registerNewMeter(CompositeTimer.java:31)
	at io.micrometer.core.instrument.composite.AbstractCompositeMeter.add(AbstractCompositeMeter.java:66)
	at io.micrometer.core.instrument.composite.CompositeMeterRegistry$$Lambda$38/000000001004B000.accept(Unknown Source)
	at java.lang.Iterable.forEach(Iterable.java:86)
	at java.util.Collections$SetFromMap.forEach(Collections.java:5541)
	at io.micrometer.core.instrument.composite.CompositeMeterRegistry.lambda$new$0(CompositeMeterRegistry.java:65)
	at io.micrometer.core.instrument.composite.CompositeMeterRegistry$$Lambda$37/0000000010AE3DD0.run(Unknown Source)
	at io.micrometer.core.instrument.composite.CompositeMeterRegistry.lock(CompositeMeterRegistry.java:184)
	at io.micrometer.core.instrument.composite.CompositeMeterRegistry.lambda$new$1(CompositeMeterRegistry.java:65)
	at io.micrometer.core.instrument.composite.CompositeMeterRegistry$$Lambda$29/0000000010ADED10.accept(Unknown Source)
	at io.micrometer.core.instrument.MeterRegistry.getOrCreateMeter(MeterRegistry.java:624)
	at io.micrometer.core.instrument.MeterRegistry.registerMeterIfNecessary(MeterRegistry.java:568)
	at io.micrometer.core.instrument.MeterRegistry.timer(MeterRegistry.java:308)
	at io.micrometer.core.instrument.Timer$Builder.register(Timer.java:400)
	at io.micrometer.core.instrument.MeterRegistry.timer(MeterRegistry.java:435)
	at io.micrometer.core.instrument.MeterRegistry.timer(MeterRegistry.java:446)
	at org.emory.meter.test.MeterTest.addMeters(MeterTest.java:54)
	at org.emory.meter.test.MeterTest.main(MeterTest.java:22)

@shakuzen shakuzen added bug A general bug and removed waiting for feedback We need additional information before we can continue labels Jan 21, 2021
@shakuzen shakuzen added this to the 1.6.4 milestone Jan 21, 2021
@shakuzen
Copy link
Member

This should be "fixed" in the latest snapshots for 1.6.4-SNAPSHOT. I say "fixed" because you won't get an exception anymore, but I don't think the additional metrics with different labels will end up in the scrape endpoint either right now based on my limited testing. We'll look at making that happen in a separate issue.

@fzyzcjy
Copy link

fzyzcjy commented Feb 4, 2021

Hi, how can I use the 1.6.4-SNAPSHOT in maven? Thanks

@phxql
Copy link

phxql commented Feb 9, 2021

I have an application which registers a timer with the same tags (keys are the same, values differ), which is triggering this bug under load. So it doesn't seem to only appear when the tags are different. I'll try to come up with a reproducer.

@phxql
Copy link

phxql commented Feb 9, 2021

Ah, it could be that the application has some MeterFilters and that they alter the tag structure somehow.

@eddified
Copy link

We are also seeing this issue. Stack trace in our case is as follows:

Caused by: java.lang.IllegalArgumentException: Collector already registered that provides name: profile_writer_data_entity_size_count
	at io.prometheus.client.CollectorRegistry.register(CollectorRegistry.java:54)
	at io.prometheus.client.Collector.register(Collector.java:139)
	at io.micrometer.prometheus.PrometheusMeterRegistry.lambda$applyToCollector$16(PrometheusMeterRegistry.java:410)
	at java.util.concurrent.ConcurrentHashMap.compute(ConcurrentHashMap.java:1853)
	at io.micrometer.prometheus.PrometheusMeterRegistry.applyToCollector(PrometheusMeterRegistry.java:406)
	at io.micrometer.prometheus.PrometheusMeterRegistry.newDistributionSummary(PrometheusMeterRegistry.java:120)
	at io.micrometer.core.instrument.MeterRegistry.lambda$summary$3(MeterRegistry.java:323)
	at io.micrometer.core.instrument.MeterRegistry.getOrCreateMeter(MeterRegistry.java:614)
	at io.micrometer.core.instrument.MeterRegistry.registerMeterIfNecessary(MeterRegistry.java:568)
	at io.micrometer.core.instrument.MeterRegistry.summary(MeterRegistry.java:322)
	at io.micrometer.core.instrument.DistributionSummary$Builder.register(DistributionSummary.java:379)
	at io.micrometer.core.instrument.composite.CompositeDistributionSummary.registerNewMeter(CompositeDistributionSummary.java:82)
	at io.micrometer.core.instrument.composite.CompositeDistributionSummary.registerNewMeter(CompositeDistributionSummary.java:25)
	at io.micrometer.core.instrument.composite.AbstractCompositeMeter.add(AbstractCompositeMeter.java:66)
	at java.lang.Iterable.forEach(Iterable.java:75)
	at java.util.Collections$SetFromMap.forEach(Collections.java:5530)
	at io.micrometer.core.instrument.composite.CompositeMeterRegistry.lambda$new$0(CompositeMeterRegistry.java:65)
	at io.micrometer.core.instrument.composite.CompositeMeterRegistry.lock(CompositeMeterRegistry.java:184)
	at io.micrometer.core.instrument.composite.CompositeMeterRegistry.lambda$new$1(CompositeMeterRegistry.java:65)
	at io.micrometer.core.instrument.MeterRegistry.getOrCreateMeter(MeterRegistry.java:624)
	at io.micrometer.core.instrument.MeterRegistry.registerMeterIfNecessary(MeterRegistry.java:568)
	at io.micrometer.core.instrument.MeterRegistry.summary(MeterRegistry.java:322)
	at io.micrometer.core.instrument.DistributionSummary$Builder.register(DistributionSummary.java:379)

Notes about our case: we are using tags as well, and because the tag values are variable, we are always calling register (to create a DistributionSummary object), just before we call record().
In other words we do not save the builder, nor the DistributionSummary object:

DistributionSummary.builder(id)
        .publishPercentiles(DEFAULT_PERCENTILES)
        .publishPercentileHistogram()
        .tags(tags)
        .register(meterRegistry)
        .record(length);

We could save the builder up to just before the tags() call, but just haven't tried that yet.

The interesting thing about this is that I can't reproduce locally in a simple test, even when varying the tags. It only occurs in a more interesting environment (such as production). Can the root cause be due to Spring Boot reloading the context? (As a Spring Boot newbie, I'm probably way off here, but I read some things about how Spring sometimes automatically reloads the context? 🤷 Maybe something that is causing the micrometer cache to be cleared, but not the native prometheus library cache [prometheus simpleclient] to be cleared?)

@shakuzen
Copy link
Member

Hi, how can I use the 1.6.4-SNAPSHOT in maven?

See the section of the README titled "Snapshot builds". In short, add a maven snapshot repository with url https://repo.spring.io/libs-snapshot to your build.

We could save the builder up to just before the tags() call, but just haven't tried that yet.

Builder instances are mutable, so that would not likely be what you want. Calling register should be fine, since its behavior is to create (if not already existing) or retrieve (if already existing) the meter.

@frankgh
Copy link

frankgh commented Feb 24, 2021

@shakuzen we faced the original issue and we are now using version 1.6.4 which no longer throws the exception, but we now are seeing the issue that you mention in your comment above additional metrics with different labels will end up in the scrape endpoint either right now based on my limited testing. Is there any workaround for this new issue?

@shakuzen
Copy link
Member

Is there any workaround for this new issue?

It's not really a new issue. Metrics with the same name but a different set of labels has never shown up in the prometheus scrape endpoint due to the limitation imposed by the Prometheus Java client that we depend on. Not throwing the exception by default was only getting rid of the error; not changing the limitation. We recently reopened #877 to explore the possibility of working around that limitation, but just noting again, it's a limitation that has always existed for the Prometheus registry.

@frankgh
Copy link

frankgh commented Mar 1, 2021

@shakuzen thanks for the information, we are able to work around the issue with this info. Thanks!

@tonymurphy
Copy link

Had problem using 1.7.2 version, when I created a registry in a test class using following code:
MeterRegistry meterRegistry = new PrometheusMeterRegistry(PrometheusConfig.DEFAULT, CollectorRegistry.defaultRegistry, Clock.SYSTEM);
I changed to:
MeterRegistry meterRegistry = new PrometheusMeterRegistry(PrometheusConfig.DEFAULT);
which resolved the issue

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug A general bug registry: prometheus A Prometheus Registry related issue
Projects
None yet
Development

No branches or pull requests

9 participants