Handle duplicated metrics gracefully

[pnyheim]

Summary:

The exporter remembers metrics by Graphite name. It is possible to get into situations where multiple samples (graphite metrics) result in the same Prometheus metric.

At the moment, this makes the exporter catastrophically fail (return error 500 on /metrics). Instead, it should discard the older sample and use the new sample's value.

Original issue description:

---

We tried using v0.5.0 in our dev env today, upgrading from 0.4.2.
After the upgrade, metrics seem to be dropping out regularly, as can be clearly seen in this grafana dashboard.

So something is definitively wrong here.
There are no changes to the environment or config between 0.4.2 and 0.5.0, and we can not see anything abnormal in the graphite_exporter logfiles.

This looks like a critical bug to us.

It should be noted that we have seen similar behavior before where we had UDP packet drops, but this was resolved by tuning the UDP receive buffer as explained here: https://nav.uninett.no/doc/4.3/howto/tuning_graphite.html

[matthiasr]

Damn!

When this happens, are there scrape errors?
What does the exporter's /metrics endpoint look like when it's working and when not?
Does it log anything?
What does it log with --log-level=debug?

[pnyheim]

Damn!

Indeed.

When this happens, are there scrape errors?

How can I tell if there are scrape errors? I've only looked in the graphite_exporter log file, but did not see anything out of the ordinary. I'll try and look in the prometheus log files tomorrow.

What does the exporter's /metrics endpoint look like when it's working and when not?

Looks normal AFAIKT. Hard to tell if metrics are missing from /metrics though. Will try to look a bit more into it tomorrow as well

Does it log anything?

Nothing out of the ordinary

What does it log with --log-level=debug?

Did not try with the debug flag. Can do that tomorrow as well.

[matthiasr]

How can I tell if there are scrape errors?

On the Prometheus server, the up metric for this target at this time would go to 0. There is additional information on the Targets page of the Prometheus server – when there is an error it's shown next to the target there.

[raypettersen]

[raypettersen]

Also noticed this:

2019/02/28 17:31:22 http: multiple response.WriteHeader calls
2019/02/28 17:31:35 http: multiple response.WriteHeader calls

I've never seen these messages before and I don't know what they mean.

[brian-brazil]

To be clear, those are coming from the exporter, not Prometheus?

[raypettersen]

The log entries are from the exporter (if I understood the question correctly). They came after about 3 hours of runtime.

[brian-brazil]

That's probably a client_golang bug then, @beorn7

https://github.com/prometheus/client_golang/blob/2daed26f633ce23fab5efc02fb3f2e803b3526c3/prometheus/promhttp/http.go#L86

I can see this happening if you have a gzipped response, and then there's a problem encoding a metric family.

[raypettersen]

If there is enough "evidence", then I suggest removing the release for now.
Let me know if I can do anything else for providing more details.

[brian-brazil]

The question is what's causing the underlying error. Could you add some extra logging around that bit of code?

[pnyheim]

I was able to poll the /metrics endpoint regularly for a while - and every once in a while it would return this:

An error has occurred while serving metrics:

2 error(s) occurred:
* collected metric "hikari_Wait" { label:<name:"attribute" value:"mean_rate" > label:<name:"datasource" value:"dsname" > label:<name:"foo" value:"bar" > gauge:<value:0 > } was collected before with the same name and label values
* collected metric "hikari_ConnectionCreation" { label:<name:"attribute" value:"p98" > label:<name:"datasource" value:"dsname2" > label:<name:"foo" value:"bar" > gauge:<value:25 > } was collected before with the same name and label values

I've seen different metric names and labels reported, and different number of errors from time to time

Ideally, this should not be written to the /metrics response, but logged as an error instead.

[brian-brazil]

The error there is expected and correct from an exposition standpoint. The question is what's causing it inside the graphite exporter.

[pnyheim]

Still, some error lines in the logfile when this happens would have been nice.

BTW, I enabling debug level logging, but could not find anything useful in the log.

[matthiasr]

The error happens at scrape time, so the exporter main doesn't have access to the error. Logging from within the library would be good but I don't know what a good interface for this would be. The error you posted is input and mapping dependent. Could you share your mapping configuration, and any inputs that could get mapped to these metric names? I suspect we are keeping something in the exporter keyed on different Graphite metric names that then maps down to the same Prometheus time series.

…

On Thu, Feb 28, 2019, 21:18 Paul Nyheim ***@***.***> wrote: Still, some error lines in the logfile when this happens would have been nice. BTW, I enabling debug level logging, but could not find anything useful in the log. — You are receiving this because you commented. Reply to this email directly, view it on GitHub <#79 (comment)>, or mute the thread <https://github.com/notifications/unsubscribe-auth/AAICBgHOv74zP_6GY1VqT5z1oOdvIAOxks5vSDmDgaJpZM4bWzE8> .