metrics: Record request metrics on HTTP errors

[tgeoghegan]

If the error returned by the wrapped handler is a Caddy.HandlerError, that indicates a problem that still yielded a successful HTTP transaction, so it makes sense to observe request duration and size metrics for it.

See mholt/caddy-ratelimit#35 for some context.

[CLAassistant]

All committers have signed the CLA.

[tgeoghegan]

I've empirically verified that this works in my application's test setup. However, I'd be happier if I could add a test in metrics_test.go. The difficulty is that it's not at all obvious how to verify that the expected metrics were recorded, since prometheus.HistogramVec and the like don't expose a way to read metrics values. We could rig up a metrics scrape endpoint in this test, though then we'd have to drag in code for parsing Prometheus metrics (maybe that's already somewhere in Caddy), or we could wire up a shim or mock around prometheus.HistogramVec that lets us verify that expected metrics are observed. I'm open to suggestions from the maintainers.

[tgeoghegan]

I factored the metrics observations out into a closure so that the error path, here, can provide the status code from the HandlerError. But there could also be an HTTP status in the response recorder that's used to determine status in the success case, so we could use that, too, and then have a single path on which metrics are observed. But I'm not sure if all wrapped handlers that return a HandlerError will necessarily have written a status into wrec, nor am I sure what we should do if the status in wrec disagrees with that in the HandlerError.

[mholt]

Thanks for this PR. Good questions; I'll bring this to @hairyhenderson 's attention since he knows more about this (but is also very busy I understand).

[tgeoghegan]

Thanks Matt! Fortunately xcaddy makes it easy for us to build a Caddy image from our fork of Caddy itself as well as modules, so we aren't blocked on having this merged or released.

[francislavoie]

LGTM. Pretty clear-cut change, it's just copying existing logic and making it also apply to the error branch. I think this is pretty safe.

[hairyhenderson]

Thanks for working on this @tgeoghegan!

As far as testing, you can use the github.com/prometheus/client_golang/prometheus/testutil package. For making sure histograms look like they should, I usually use testutil.GatherAndCompare and compare the text for a given set of metric names.

Something like:

	expected := `
	# TYPE caddy_http_request_size_bytes histogram
	# HELP caddy_http_request_size_bytes Total size of the request. Includes body
	caddy_http_request_size_bytes_bucket{code="200",handler="bar",method="GET",server="UNKNOWN",le="256"} 1
	caddy_http_request_size_bytes_bucket{code="200",handler="bar",method="GET",server="UNKNOWN",le="1024"} 1
	caddy_http_request_size_bytes_bucket{code="200",handler="bar",method="GET",server="UNKNOWN",le="4096"} 1
	caddy_http_request_size_bytes_bucket{code="200",handler="bar",method="GET",server="UNKNOWN",le="16384"} 1
	caddy_http_request_size_bytes_bucket{code="200",handler="bar",method="GET",server="UNKNOWN",le="65536"} 1
	caddy_http_request_size_bytes_bucket{code="200",handler="bar",method="GET",server="UNKNOWN",le="262144"} 1
	caddy_http_request_size_bytes_bucket{code="200",handler="bar",method="GET",server="UNKNOWN",le="1.048576e+06"} 1
	caddy_http_request_size_bytes_bucket{code="200",handler="bar",method="GET",server="UNKNOWN",le="4.194304e+06"} 1
	caddy_http_request_size_bytes_bucket{code="200",handler="bar",method="GET",server="UNKNOWN",le="+Inf"} 1
	caddy_http_request_size_bytes_sum{code="200",handler="bar",method="GET",server="UNKNOWN"} 23
	caddy_http_request_size_bytes_count{code="200",handler="bar",method="GET",server="UNKNOWN"} 1
	`
	err := testutil.GatherAndCompare(prometheus.DefaultGatherer, strings.NewReader(expected),
		"caddy_http_request_size_bytes",
	)
	if err != nil {
		t.Errorf("Received unexpected error: %s", err)
	}

[tgeoghegan]

Thanks for that excellent tip, @hairyhenderson. I should have looked into the prometheus/testutil package, which I now see was already used in metrics_test.go.

[mholt]

Cool -- thanks Dave. Anything else with this, or is it good to go?

[hairyhenderson]

LGTM - thanks for this, @tgeoghegan!

[tgeoghegan]

Thanks all for the thoughtful review!

[mholt]

Thank you for the contribution and everyone for helping with review!