improve metrics and test them (#21)

Add a new result category for bad_request. This is used for requests
that are past the end of the log, and so are an error but not an error
that we are responsible for (that is, equivalent to a 400 error).

go.mod

@@ -29,6 +29,7 @@ require (
 	github.com/aws/smithy-go v1.14.2 // indirect
 	github.com/beorn7/perks v1.0.1 // indirect
 	github.com/cespare/xxhash/v2 v2.2.0 // indirect
+	github.com/davecgh/go-spew v1.1.1 // indirect
 	github.com/golang/protobuf v1.5.3 // indirect
 	github.com/matttproud/golang_protobuf_extensions v1.0.4 // indirect
 	github.com/prometheus/client_model v0.3.0 // indirect

go.sum

@@ -40,6 +40,7 @@ github.com/cespare/xxhash/v2 v2.2.0 h1:DC2CZ1Ep5Y4k3ZQ899DldepgrayRUGE6BBZ/cd9Cj
 github.com/cespare/xxhash/v2 v2.2.0/go.mod h1:VGX0DQ3Q6kWi7AoAeZDth3/j3BFtOZR5XLFGgcrjCOs=
 github.com/davecgh/go-spew v1.1.0/go.mod h1:J7Y8YcW2NihsgmVo/mv3lAwl/skON4iLHjSsI+c5H38=
 github.com/davecgh/go-spew v1.1.1 h1:vj9j/u1bqnvCEfJOwUhtlOARqs3+rkHYY13jYWTU97c=
+github.com/davecgh/go-spew v1.1.1/go.mod h1:J7Y8YcW2NihsgmVo/mv3lAwl/skON4iLHjSsI+c5H38=
 github.com/fxamacker/cbor/v2 v2.5.0 h1:oHsG0V/Q6E/wqTS2O1Cozzsy69nqCiguo5Q1a1ADivE=
 github.com/fxamacker/cbor/v2 v2.5.0/go.mod h1:TA1xS00nchWmaBnEIxPSE5oHLuJBAVvqrtAnWBwBCVo=
 github.com/golang/protobuf v1.2.0/go.mod h1:6lQm79b+lXiMfvg/cZm0SGofjICqVBUtrP5yJMmIC1U=

integration_test.go

@@ -22,6 +22,7 @@ import (
 	"github.com/aws/aws-sdk-go-v2/credentials"
 	"github.com/aws/aws-sdk-go-v2/service/s3"
 	"github.com/prometheus/client_golang/prometheus"
+	"github.com/prometheus/client_golang/prometheus/testutil"
 	"golang.org/x/sync/singleflight"
 )
 
@@ -139,20 +140,7 @@ func TestIntegration(t *testing.T) {
 		t.Fatal(err)
 	}
 
-	ctile := tileCachingHandler{
-		logURL:   server.URL,
-		tileSize: 3,
-
-		s3Service: s3Service,
-		s3Prefix:  "test",
-		s3Bucket:  "bucket",
-
-		cacheGroup: &singleflight.Group{},
-
-		requestsMetric:     prometheus.NewCounterVec(prometheus.CounterOpts{}, []string{"result", "source"}),
-		partialTiles:       prometheus.NewCounter(prometheus.CounterOpts{}),
-		singleFlightShared: prometheus.NewCounter(prometheus.CounterOpts{}),
-	}
+	ctile := makeTCH(server.URL, s3Service)
 
 	// Invalid URL; should be passed through to backend and 400
 	resp := getResp(ctile, "/foo")
@@ -190,13 +178,20 @@ func TestIntegration(t *testing.T) {
 		t.Errorf("expected 2 entries got %d", len(twoEntriesA.Entries))
 	}
 
+	successes := testutil.ToFloat64(ctile.requestsMetric.WithLabelValues("success", "ct_log_get"))
+	if successes != 1 {
+		t.Errorf("expected 1 success from ct_log_get, got %g", successes)
+	}
+	ctile.requestsMetric.Reset()
+
 	// Same query again; should come from S3 this time.
 	twoEntriesB, headers, err := getAndParseResp(t, ctile, "/ct/v1/get-entries?start=3&end=4")
 	if err != nil {
 		t.Error(err)
 	}
 
 	expectHeader(t, headers, "X-Source", "S3")
+	expectAndResetMetric(t, ctile.requestsMetric, 1, "success", "s3_get")
 
 	if len(twoEntriesB.Entries) != 2 {
 		t.Errorf("expected 2 entries got %d", len(twoEntriesB.Entries))
@@ -215,6 +210,7 @@ func TestIntegration(t *testing.T) {
 	}
 
 	expectHeader(t, headers, "X-Source", "S3")
+	expectAndResetMetric(t, ctile.requestsMetric, 1, "success", "s3_get")
 
 	if len(oneEntry.Entries) != 1 {
 		t.Errorf("expected 1 entry got %d", len(oneEntry.Entries))
@@ -227,6 +223,7 @@ func TestIntegration(t *testing.T) {
 	}
 
 	expectHeader(t, headers, "X-Source", "CT log")
+	expectAndResetMetric(t, ctile.requestsMetric, 1, "success", "ct_log_get")
 
 	_, headers, err = getAndParseResp(t, ctile, "/ct/v1/get-entries?start=9&end=11")
 	if err != nil {
@@ -236,6 +233,7 @@ func TestIntegration(t *testing.T) {
 	// This should still come from the CT log rather than from S3, even though it was
 	// requested twice in a row.
 	expectHeader(t, headers, "X-Source", "CT log")
+	expectAndResetMetric(t, ctile.requestsMetric, 1, "success", "ct_log_get")
 
 	// Tiles fetched past the end of the log will get a 400 from our test CT log; ctile
 	// should pass that through, along with the body.
@@ -247,6 +245,7 @@ func TestIntegration(t *testing.T) {
 	if !strings.Contains(string(body), testLogSaysPastTheEnd) {
 		t.Errorf("expected response to contain %q got %q", testLogSaysPastTheEnd, body)
 	}
+	expectAndResetMetric(t, ctile.requestsMetric, 1, "bad_request", "ct_log_get")
 
 	// A request where the _tile_ starts inside the log but the requested `start` value is
 	// outside the log. In this case ctile synthesizes a 400.
@@ -259,6 +258,20 @@ func TestIntegration(t *testing.T) {
 	if !strings.Contains(string(body), pastTheEnd) {
 		t.Errorf("expected response to contain %q got %q", pastTheEnd, body)
 	}
+	expectAndResetMetric(t, ctile.requestsMetric, 1, "bad_request", "past_the_end_partial_tile")
+
+	// simulate a down backend
+	errorCTLog := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
+		w.WriteHeader(http.StatusInternalServerError)
+	}))
+	defer server.Close()
+
+	erroringCTile := makeTCH(errorCTLog.URL, s3Service)
+	resp = getResp(erroringCTile, "/ct/v1/get-entries?start=0&end=1")
+	if resp.StatusCode != 500 {
+		t.Errorf("expected 500 got %d", resp.StatusCode)
+	}
+	expectAndResetMetric(t, erroringCTile.requestsMetric, 1, "error", "ct_log_get")
 }
 
 func getResp(ctile tileCachingHandler, url string) *http.Response {
@@ -288,3 +301,28 @@ func expectHeader(t *testing.T, headers http.Header, key, expected string) {
 		t.Errorf("header %q: expected %q got %q", key, expected, headers.Get(key))
 	}
 }
+
+func expectAndResetMetric(t *testing.T, metric *prometheus.CounterVec, expected float64, labels ...string) {
+	value := testutil.ToFloat64(metric.WithLabelValues(labels...))
+	if value != expected {
+		t.Errorf("expected Prometheus counter value of %g got %g with labels %s", expected, value, labels)
+	}
+	metric.Reset()
+}
+
+func makeTCH(url string, s3Service *s3.Client) tileCachingHandler {
+	return tileCachingHandler{
+		logURL:   url,
+		tileSize: 3,
+
+		s3Service: s3Service,
+		s3Prefix:  "test",
+		s3Bucket:  "bucket",
+
+		cacheGroup: &singleflight.Group{},
+
+		requestsMetric:     prometheus.NewCounterVec(prometheus.CounterOpts{Help: "foo", Name: "ctile_requests"}, []string{"result", "source"}),
+		partialTiles:       prometheus.NewCounter(prometheus.CounterOpts{Name: "ctile_partial_tiles"}),
+		singleFlightShared: prometheus.NewCounter(prometheus.CounterOpts{Name: "ctile_singleflight_shared"}),
+	}
+}

main.go

@@ -322,7 +322,9 @@ func (tch *tileCachingHandler) ServeHTTP(w http.ResponseWriter, r *http.Request)
 	contents, err = contents.trimForDisplay(start, end, tile)
 	if err != nil {
 		if errors.As(err, &pastTheEndError{}) {
-			tch.requestsMetric.WithLabelValues("error", "ct_log_past_end").Inc()
+			tch.requestsMetric.WithLabelValues("bad_request", "past_the_end_partial_tile").Inc()
+		} else {
+			tch.requestsMetric.WithLabelValues("error", "internal_inconsistency").Inc()
 		}
 		w.WriteHeader(http.StatusBadRequest)
 		fmt.Fprintln(w, err)
@@ -393,7 +395,14 @@ func (tch *tileCachingHandler) getAndCacheTileUncollapsed(ctx context.Context, t
 
 	contents, err = getTileFromBackend(ctx, tile)
 	if err != nil {
-		tch.requestsMetric.WithLabelValues("error", "ct_log_get").Inc()
+		var statusCodeErr statusCodeError
+		// Requests for tiles past the end of the log will get a 400 from CTFE, so report those
+		// separately.
+		if errors.As(err, &statusCodeErr) && statusCodeErr.statusCode == http.StatusBadRequest {
+			tch.requestsMetric.WithLabelValues("bad_request", "ct_log_get").Inc()
+		} else {
+			tch.requestsMetric.WithLabelValues("error", "ct_log_get").Inc()
+		}
 		return nil, sourceCTLog, fmt.Errorf("error reading tile from backend: %w", err)
 	}