prometheus output can return partial results if a collect request is made in-between writing multiple batches

[banks]

Bug report

We upgraded some servers to latest deb release in repos.influxdata.com only because that repo does not keep old versions (filing a separate ticket about that).

The latest version seems to fail in a way I can't diagnose, log output is same as before yet the response form the prometheus output metrics endpoint intermittently has a limited set of the actual data.

It seems to be only reporting the last batch of metrics written not all since last scrape.

In the config below the exec input pulls cgroups memory stats for each container running on the host. There are ~3000-4000 distinct metrics returned by it every time and this number is constant with number of containers running.

Relevant telegraf.conf:

/etc/telegraf/telegraf.conf

[agent]
collection_jitter = "3s"
flush_interval = "10s"
flush_jitter = "5s"
interval = "15s"
round_interval = true

/etc/telegraf/telegraf.d/default_inputs.conf

[inputs.cpu]
fieldpass = ["usage_*"]
percpu = false
totalcpu = true
[inputs.disk]
fieldpass = ["free", "total", "used", "inodes_used", "inodes_total"]
ignore_fs = ["tmpfs", "devtmpfs"]
mount_points = ["/", "/data_0", "/data"]
[inputs.diskio]
[inputs.exec]
commands = ["/usr/local/bin/capture_memory_metrics"]
data_format = "influx"
timeout = "15s"
[inputs.mem]
fielddrop = ["*_percent"]
[inputs.net]
interfaces = ["eth0", "bond0", "bond1", "br0"]
[inputs.system]
fieldpass = ["uptime", "load*"]

/etc/telegraf/telegraf.d/default_outputs.conf

[[outputs.prometheus_client]]
listen = ":9126"

System info:

telegraf 1.0.0 (old version 0.13.2)

Steps to reproduce:

(This is assumption, based on the cases that do exhibit it)

1. create an exec input that returns > 1000 metrics
2. run with that input and prometheus output
3. obeserve number of metrics scraped each second on prometheus end point.

Expected behavior:

Shoudl constistenyl see the correct number of metrics. For our case This is what happend when we scrape every second and output number of metrics scraped using 0.13.2:

$ for i in {1..999}; do echo -n "Number of capsules metrics scraped:"; curl 2>/dev/null localhost:9126/metrics | grep -o -P 'capsule_name="[a-z0-9_]+"' | wc -l; sleep 1; done
Number of capsules metrics scraped:3980
Number of capsules metrics scraped:3980
Number of capsules metrics scraped:3980
Number of capsules metrics scraped:3980
Number of capsules metrics scraped:3980
Number of capsules metrics scraped:3980
Number of capsules metrics scraped:3980
Number of capsules metrics scraped:3980

Actual behavior:

After upgrade with 1.0.0 we see:

$ for i in {1..999}; do echo -n "Number of capsules metrics scraped:"; curl 2>/dev/null localhost:9126/metrics | grep -o -P 'capsule_name="[a-z0-9_]+"' | wc -l; sleep 1; done
Number of capsules metrics scraped:1000
Number of capsules metrics scraped:1000
Number of capsules metrics scraped:3
Number of capsules metrics scraped:3
Number of capsules metrics scraped:3
Number of capsules metrics scraped:3
Number of capsules metrics scraped:3
Number of capsules metrics scraped:3
Number of capsules metrics scraped:3
Number of capsules metrics scraped:3
Number of capsules metrics scraped:0
Number of capsules metrics scraped:1000
Number of capsules metrics scraped:1000
Number of capsules metrics scraped:1000
Number of capsules metrics scraped:1000
Number of capsules metrics scraped:1000

This numbers match the log messages about number of metrics in each batch so the bug appears to be that prometheus output is only reporting the last batch of metrics recorded not all since last scrape.

[sparrc]

hi @banks, good sleuthing, but the previous behavior of continuing to report metrics that are not reported anymore was actually a bug that was fixed in 1.0: #1334

my understanding is that this is the intended prometheus behavior.

why? because prometheus endpoints are supposed to work by gathering a set of metrics at the time that the http request is made. If the metrics don't exist at the time that the request is made, then they are not exposed.

I'll re-open this if you can find some documentation that explains otherwise, but my conversations with prometheus devs led me to believe that the 1.0 behavior is the intended behavior.

[banks]

I'm pretty sure this is a bug and not a valid fix for #1334.

I followed that issue too as we were also bitten by that bug on other hosts. In fact 0.13.2 fixed that bug for us - I assume the fix was back-ported from 1.0 branch.

This report is different though:

• the exec script is returning 3980 distinct metrics every invocation - none of the metrics are being removed or going away in the example given
• those are written to the prometheus output in batches of 1000
• previous behaviour was to report all of the metrics reported since last scrape
• current behaviour only reports metrics in last batch
• since 0.13.2 any metrics actually that stopped being reported did indeed stop showing in output for us.

In other words, as of 1.0.0 the prometheus output can't report on more than 1000 distinct metrics. Not only that but the failure mode when you try is random sampling of metrics that drops an unbounded amount of them on the floor.

[banks]

Btw. if there was no intentional backport of the fix for #1334 in 0.13.2 then it's very interesting because we saw it go away.

Sadly it was too long ago to still have data in prometheus to show but I may be able to dig out a graph that showed how we dropped about 25% of our ingested-metrics-per-second over then 30 mins it took to roll out due to the deleted containers' metrics going away as expected.

If that happened without an intentional change in telegraf perhaps it was a prometheus client bug that was fixed in that version or something and in fact the "fix" in 1.0.0 is creating this whole new problem?

Please re-open this, prometheus output is unusable in production on 1.0.0 for anyone who might have more than 1000 metrics on telegraf instance as far as I can see.

[banks]

For the record here:

That was the number of distinct containers we had metrics for over the time we rolled out 0.13.1 -> 0.13.2. I checked and none of the live containers I could find were missing them and all recently-deleted containers had their metrics stop as expected.

I didn't look further and just assumed that #1334 fix had been backported and released. If that's not the case then I think #1334 was not really understanding the correct issue and potentially caused this new one with the "fix".

[sparrc]

I see what you mean, I'll reopen

[sparrc]

I can see exactly what's wrong here, and this should actually be a fairly simple fix, so I'm going to bump it up to 1.0.1

this map: https://github.com/influxdata/telegraf/blob/master/plugins/outputs/prometheus_client/prometheus_client.go#L95 should be getting remade on calls to Collect, not on Write

in the meantime, you should be able to bump up metric_batch_size in the [agent] config section to workaround this: https://github.com/influxdata/telegraf/blob/master/etc/telegraf.conf#L35

[banks]

Sounds exactly like the issue :) Thanks for the quick response.

[banks]

Incidentally my assumption that it was caused by having more metrics than the buffer seems to be wrong.

In process of trying to patch hosts I found one host reporting only 300 metrics and it still showed them inconsistently sometimes being blank and sometimes having all of them even just in the few seconds I observed:

$for i in {1..999}; do echo -n "Number of capsules metrics scraped:"; curl 2>/dev/null localhost:9126/metrics | grep -o -P 'capsule_name="[a-z0-9_]+"' | wc -l; sleep 1; done
Number of capsules metrics scraped:0
Number of capsules metrics scraped:0
Number of capsules metrics scraped:0
Number of capsules metrics scraped:0
Number of capsules metrics scraped:0
Number of capsules metrics scraped:0
Number of capsules metrics scraped:300
Number of capsules metrics scraped:300
Number of capsules metrics scraped:300
Number of capsules metrics scraped:300
Number of capsules metrics scraped:300

After downgrading to 0.13.2 this stopped too. Not sure whether or not that is explained by your find yet... (maybe a timing issue even if writes are not large thatn buffer size?)