httpError (http.go:306)

[AlanQin1024]

{"duration":9708394250,"level":"info","msg":"Metrics updated","time":"2019-10-30T11:57:42+08:00"}
2019/10/30 11:57:42 http: superfluous response.WriteHeader call from github.com/prometheus/client_golang/prometheus/promhttp.httpError (http.go:306)

[beorn7]

Could you provide a bit more context? I can only guess from what you have provided. In particular, which version of this repo did you use? (#634 might be of relevance. If that's not in the code you were running, it would explain the message.)

[beorn7]

Closing for lack of follow-up. I'll re-open once more information is provided.

[cameronkerrnz]

I have been encountering this today using snmp_exporter

snmp_exporter[26979]: level=info ts=2019-12-18T11:14:56.238Z caller=main.go:141 msg="Starting snmp_exporter" version="(version=0.16.1, branch=HEAD, revision=4b2bb401378cf40c409aba91ab25189be5670183)"
snmp_exporter[26979]: level=info ts=2019-12-18T11:14:56.238Z caller=main.go:142 msg="Build context" (gogo1.13.5,userroot@89bd31baeb1f,date20191210-15:23:21)=(MISSING)
snmp_exporter[26979]: level=info ts=2019-12-18T11:14:56.245Z caller=main.go:235 msg="Listening on address" address=:9116

snmp_exporter[26979]: 2019/12/19 00:24:05 http: superfluous response.WriteHeader call from github.com/prometheus/client_golang/prometheus/promhttp.httpError (http.go:344)

The version of snmp_exporter is v0.16.1, the current 'latest' release (https://github.com/prometheus/snmp_exporter/releases/tag/v0.16.1)

The WriteHeader is logged not infrequently, and I think it correlates with context exception deadlines being reported by Prometheus

I'm not aware of this behaviour with its previous version (v0.15.0), but I could have easily missed it.

It's possible that it may be the result of a timeout? I think some of the scrapes (eg. a little over 2s) may be taking a bit longer than permitted by default, but I haven't reviewed the timeout configuration yet.

[cameronkerrnz]

I can further confirm that I didn't see this behaviour with v0.15.0 of snmp_exporter.

In terms of client_golang, this would be a difference of v1.0.0 to v1.2.1

prometheus/snmp_exporter@c37906a#diff-37aff102a57d3d7b797f152915a6dc16

There were other changes in snmp_exporter that might have factored into this, including switching to go_kit for logging.

[beorn7]

Thanks for the report. That will hopefully help to hunt down where this is happening.

[woodsaj]

The HTTP error handling in promhttp looks like a flawed design to me.
There are 3 error handling modes. HTTPErrorOnError, ContinueOnError and PanicOnError

The continueOnError and PanicOnError both make sense and should work as intended.

However, HTTPErrorOnError doesnt make sense.
This mode is described as

// Serve an HTTP status code 500 upon the first error
// encountered. Report the error message in the body.

The problem is that this handling mode is being used for errors that can happen after data has already been sent to clients. The HTTP status code is written to clients before any data. So if a response is partially written to the client, then an error occurs, you cant change the status code. In these situations, the only thing you can do is log the error.

The superfluous response.WriteHeader calls are almost certainly being caused by clients disconnecting before metrics have been gathered or while the response is being written. This will result in attempts to write to the client to fail.

The easiest way to check if the client has disconnected is check if req.Context().Err() != nil

[beorn7]

As hinted in the doc comment of promhttp.httpError, this behavior is deliberate. However, when I wrote this long ago, I assumed http.Error would detect the case of a header already written and not try to write the header again. But actually looking an the source proves that it does not. :-/

So yeah, I think @woodsaj nailed it. I'll work on a fix that makes sure that promhttp.httpError is only ever called if nothing else has been written. And I'll advertise the shortcomings of HTTPErrorOnError in a doc comment that is actually for an exported type.

Many thanks.

[beorn7]

#724 should have fixed this. I'll close this tentatively…
v1.5.1 being cut.