`with_labels` doesn't seem to work

[onlynone]

When I create a new Counter object from another by using the Prometheus::Client::Metric#with_labels method, it seems like the new Counter uses a different store from the original, so its metrics are never reported (say to the push client). And if I try to register the new Counter with the registry, I get an error because the original Counter is already registered with that name.

#!/usr/bin/env ruby

require 'cgi'
require 'prometheus/client'
require 'prometheus/client/counter'
require 'prometheus/client/push'

counter1 = Prometheus::Client::Counter.new(
  :with_labels_counter,
  docstring: "with_labels counter",
  labels: [:foo]
)

counter1.increment(labels: {foo: "bar"})
counter1.increment(labels: {foo: "baz"})
counter1.increment(labels: {foo: "bat"})

counter2 = counter1.with_labels(foo: "bar")

counter2.increment

# I would expect this to print: [2.0, 1.0, 1.0]
# but it prints: [1.0, 1.0, 1.0]
puts "The counter values:"
puts ['bar', 'baz', 'bat'].map{|foo| counter1.get(labels: { foo: foo })}.inspect
puts ""

registry = Prometheus::Client.registry
registry.register(counter1)

push = Prometheus::Client::Push.new('with_labels_job', 'with_labels_instance')

push.add(registry)

resp = Net::HTTP.get_response(URI(push.gateway) + "metrics")

# I would expect the following to print:
#
# push_failure_time_seconds{instance="with_labels_instance",job="with_labels_job"} 0
# push_time_seconds{instance="with_labels_instance",job="with_labels_job"} 1.6208445893150244e+09
# # HELP with_labels_counter with_labels counter
# # TYPE with_labels_counter counter
# with_labels_counter{foo="bar",instance="with_labels_instance",job="with_labels_job"} 2
# with_labels_counter{foo="bat",instance="with_labels_instance",job="with_labels_job"} 1
# with_labels_counter{foo="baz",instance="with_labels_instance",job="with_labels_job"} 1
#
# But it prints:
#
# push_failure_time_seconds{instance="with_labels_instance",job="with_labels_job"} 0
# push_time_seconds{instance="with_labels_instance",job="with_labels_job"} 1.6208445893150244e+09
# # HELP with_labels_counter with_labels counter
# # TYPE with_labels_counter counter
# with_labels_counter{foo="bar",instance="with_labels_instance",job="with_labels_job"} 1
# with_labels_counter{foo="bat",instance="with_labels_instance",job="with_labels_job"} 1
# with_labels_counter{foo="baz",instance="with_labels_instance",job="with_labels_job"} 1
puts "What the push gateway has after the first push:"
puts resp.body.split("\n").select{|l| l.match(/with_labels/)}
puts ""

# Since the metrics recorded with counter2 aren't being stored with counter1,
# then I'd hope registering counter2 with the registry would at least work
#
# but it results in:
#
# with_labels_counter has already been registered(Prometheus::Client::Registry::AlreadyRegisteredError)
begin
  registry.register(counter2)
rescue Prometheus::Client::Registry::AlreadyRegisteredError
  puts "Can't register counter2"
  puts ""
end

# So maybe I could create a separate registry for counter2 and add that to my
# push gateway separately

registry2 = Prometheus::Client::Registry.new
registry2.register(counter2)

push.add(registry2)

resp = Net::HTTP.get_response(URI(push.gateway) + "metrics")

# I would expect the following to print:
#
# push_failure_time_seconds{instance="with_labels_instance",job="with_labels_job"} 0
# push_time_seconds{instance="with_labels_instance",job="with_labels_job"} 1.6208457827718859e+09
# # HELP with_labels_counter with_labels counter
# # TYPE with_labels_counter counter
# with_labels_counter{foo="bar",instance="with_labels_instance",job="with_labels_job"} 2
# with_labels_counter{foo="bat",instance="with_labels_instance",job="with_labels_job"} 1
# with_labels_counter{foo="baz",instance="with_labels_instance",job="with_labels_job"} 1
#
# But it clobbers the other labels and prints:
#
# push_failure_time_seconds{instance="with_labels_instance",job="with_labels_job"} 0
# push_time_seconds{instance="with_labels_instance",job="with_labels_job"} 1.6208457827718859e+09
# # HELP with_labels_counter with_labels counter
# # TYPE with_labels_counter counter
# with_labels_counter{foo="bar",instance="with_labels_instance",job="with_labels_job"} 1
puts "What the push gateway has after the second push:"
puts resp.body.split("\n").select{|l| l.match(/with_labels/)}
puts ""

Should the implementation of push_labels possibly be changed to something like:

      def with_labels(labels)
        metric = self.class.new(name,
                       docstring: docstring,
                       labels: @labels,
                       preset_labels: preset_labels.merge(labels),
                       store_settings: @store_settings)
        metric.instance_variable_set(:@store, @store)
        return metric
      end

[dmagliola]

Hello,
Thank you for the detailed report!

You are right, this is a bug.
We never caught this because in all our apps we use the DirectFileStore, and with that store, this works as intended.
And somehow, we don't actually have any tests for with_labels!

If you add these two lines to the beginning of your script:

require 'prometheus/client/data_stores/direct_file_store'
Prometheus::Client.config.data_store = Prometheus::Client::DataStores::DirectFileStore.new(dir: "/tmp/prom")

then you get exactly the output that you are expecting.

This works because you end up with two separate "data stores" (which is a bug), but they're both backed by the same file (and even if they weren't, marshalling the registry reads all files and aggregates them)

Now, to be clear, I'm not suggesting this as a solution, I'm just acknowledging that this is indeed a problem.

I'd like to take a bit of time to look into what's the best way to solve this. I'm not thrilled about instance_variable_set, but I also don't want that store as a parameter in the constructor, so we may need to drastically change how with_labels works...

@Sinjo do you have any thoughts on this?

[onlynone]

I'm not thrilled about instance_variable_set

Me neither, it was just a simple work-around that I found that worked. Maybe a better solution is to have a new class: MetricWithLabels whose constructor takes an existing Metric and a hash of default labels. It proxies most calls to its internal @metric instance variable, except for one related to getting the default labels, which it overrides like so:

class MetricWithLabels
  def initialize(metric, default_labels)
    @metric = metric
    @default_labels = default_labels
  end

  def get_default_labels
    super.merge(@default_labels)
  end

  def method_missing(*args, **kwargs)
    @metric.__send__(*args, **kwargs)
  end
end

And then with_labels could be defined like:

      def with_labels(labels)
        MetricWithLabels.new(self, labels)
      end

But I saw there were some intracacies around label validation and things like that which this doesn't cover. Another alternative might be to have a store registry that is indexed on metric name, when you create a new metric with the same name, you get the same store.

[Sinjo]

@Sinjo do you have any thoughts on this?

Not got a tonne of ideas for a cleaner approach to setting the store on the new metric instance. The one thing that comes to mind is that we could have a protected method to set it, which is a little cleaner than instance_variable_set and still avoids exposing the potential footgun outside of our classes.

Will keep thinking!

[onlynone]

This works because you end up with two separate "data stores" (which is a bug), but they're both backed by the same file (and even if they weren't, marshalling the registry reads all files and aggregates them)

I'm a little confused by this. So, one bug is that with_labels creates a separate metric backed by a different store. A second bug is that with DirectFileStore, these separate store objects end up writing to the same file. And then is there a third bug that the registry object reads all DirectFileStore files and aggregates them?

What I mean by this is that if I create two totally separate metrics (i.e. not through .with_labels) with the same names (or maybe they don't even need to be the same?), and they're both backed by DirectFileStore, but they're registered with different registries, would one registry get the data from both stores/metrics?

[dmagliola]

Hmmmm, well the three statements you described at the top are true, but I wouldn't say that's 3 bugs...

So, one bug is that with_labels creates a separate metric backed by a different store.

This is a bug.

A second bug is that with DirectFileStore, these separate store objects end up writing to the same file.

This is somewhere in between. I think this happens to work on our tests, but it'd be easy to write a test that breaks it (if the two separate stores pointing to the same file each add a new, different labelset), so yeah, with_labels is broken, we need to fix that.

And then is there a third bug that the registry object reads all DirectFileStore files and aggregates them?

This is a potentially unexpected side-effect if you do declare two metrics with the same name, which is not something we explicitly contemplated. But it's definitely not a bug. Effectively "declaring two separate metrics with the same name in different registries" is what you do in a multi-process environment, which is why we need to read all the files and aggregate them. We wouldn't have a way of knowing the difference between "the metrics in another process" and "a second metric in this same process".

That said, doing that will also easily break the files, so if at all possible, don't do that.

But these are good points, and you've made me realize that "multiple registries" is a lot less well-supported than I thought it was (because I never contemplated having 2 separate metrics with the same name, which a single registry doesn't let you do), as opposed to adding the same metric to both registries.

I will document this better.

Now, crucially, is this something you need to do?

[onlynone]

Now, crucially, is this something you need to do?

No, it's not something I need to do. And I'll probably be using the file stores going forward. I just wanted to be able to wrap my head around how all the relationships work between metrics, stores, registries, and (push) clients. And to be able to understand the edge-cases so I know what to expect.

[dmagliola]

Working on this right now. Turns out, the reason we didn't catch this is not what I thought...
We simply don't have tests at all for observing values with with_labels.
We do call it to make sure it sets those labels, and gets us past the "required labels" validations, which is why I didn't notice this in coverage, but we do not at all look at what happens to the observed values after calling it.

My bad, i'm fixing that now.

I just wanted to be able to wrap my head around how all the relationships work

This is absolutely fair, I just wanted to check whether that's what you were doing, or whether you actually had that use case, which was a bit worrying given how our client works.

[dmagliola]

This bug is now fixed in PR #227.
Once that gets reviewed and merged, I'll cut a 2.1.1 cherry-picking it out of master.
Thank you for reporting this!!