v1/server: Fix deferred metrics timers. (#7671)

The /v1/data endpoint's PUT, PATCH, and DELETE methods all reported
incorrect timer information (zeroed out timers). This was caused by the
Timer.Stop() calls being deferred in those method handlers.

The problem is that the timers do not record a time value until you stop
them. So, when the metrics are reported, all of those timers are still
storing their initial zero values.

The fix was manually calling Timer.Stop() right before metrics collection
on each endpoint, similar to how we handle many other endpoints in the
server.

Signed-off-by: Philip Conrad <philip@chariot-chaser.net>

v1/server/server.go

@@ -1617,7 +1617,6 @@ func (s *Server) v1DataGet(w http.ResponseWriter, r *http.Request) {
 func (s *Server) v1DataPatch(w http.ResponseWriter, r *http.Request) {
 	m := metrics.New()
 	m.Timer(metrics.ServerHandler).Start()
-	defer m.Timer(metrics.ServerHandler).Stop()
 
 	ctx := r.Context()
 	vars := mux.Vars(r)
@@ -1667,6 +1666,8 @@ func (s *Server) v1DataPatch(w http.ResponseWriter, r *http.Request) {
 		return
 	}
 
+	m.Timer(metrics.ServerHandler).Stop()
+
 	if includeMetrics(r) {
 		result := types.DataResponseV1{
 			Metrics: m.All(),
@@ -1841,7 +1842,6 @@ func (s *Server) v1DataPost(w http.ResponseWriter, r *http.Request) {
 func (s *Server) v1DataPut(w http.ResponseWriter, r *http.Request) {
 	m := metrics.New()
 	m.Timer(metrics.ServerHandler).Start()
-	defer m.Timer(metrics.ServerHandler).Stop()
 
 	ctx := r.Context()
 	vars := mux.Vars(r)
@@ -1907,6 +1907,8 @@ func (s *Server) v1DataPut(w http.ResponseWriter, r *http.Request) {
 		return
 	}
 
+	m.Timer(metrics.ServerHandler).Stop()
+
 	if includeMetrics(r) {
 		result := types.DataResponseV1{
 			Metrics: m.All(),
@@ -1921,7 +1923,6 @@ func (s *Server) v1DataPut(w http.ResponseWriter, r *http.Request) {
 func (s *Server) v1DataDelete(w http.ResponseWriter, r *http.Request) {
 	m := metrics.New()
 	m.Timer(metrics.ServerHandler).Start()
-	defer m.Timer(metrics.ServerHandler).Stop()
 
 	ctx := r.Context()
 	vars := mux.Vars(r)
@@ -1961,6 +1962,8 @@ func (s *Server) v1DataDelete(w http.ResponseWriter, r *http.Request) {
 		return
 	}
 
+	m.Timer(metrics.ServerHandler).Stop()
+
 	if includeMetrics(r) {
 		result := types.DataResponseV1{
 			Metrics: m.All(),

v1/server/server_test.go

@@ -3363,7 +3363,7 @@ func TestDataProvenanceMultiBundle(t *testing.T) {
 func TestDataMetricsEval(t *testing.T) {
 	t.Parallel()
 
-	// These tests all use the POST /v1/data API with ?metrics appended.
+	// These tests all use the /v1/data API with ?metrics appended.
 	// We're setting up the disk store because that injects a few extra metrics,
 	// which storage/inmem does not.
 
@@ -3379,7 +3379,7 @@ func TestDataMetricsEval(t *testing.T) {
 		f := newFixtureWithStore(t, disk)
 
 		// Make a request to evaluate `data`
-		testDataMetrics(t, f, "/data?metrics", []string{
+		testDataMetrics(t, f, http.MethodPost, "/data?metrics", "", []string{
 			"counter_server_query_cache_hit",
 			"counter_disk_read_keys",
 			"counter_disk_read_bytes",
@@ -3393,23 +3393,50 @@ func TestDataMetricsEval(t *testing.T) {
 
 		// Repeat previous request, expect to have hit the query cache
 		// so fewer timers should have been reported.
-		testDataMetrics(t, f, "/data?metrics", []string{
+		testDataMetrics(t, f, http.MethodPost, "/data?metrics", "", []string{
 			"counter_server_query_cache_hit",
 			"counter_disk_read_keys",
 			"counter_disk_read_bytes",
+			"timer_disk_read_ns",
+			"timer_rego_external_resolve_ns",
 			"timer_rego_input_parse_ns",
 			"timer_rego_query_eval_ns",
 			"timer_server_handler_ns",
+		})
+
+		// Exercise the PUT, PATCH, and DELETE endpoints.
+		testDataMetrics(t, f, http.MethodPut, "/data/example?metrics", "{}", []string{
+			"counter_disk_read_keys",
+			"counter_disk_written_keys",
+			"timer_disk_commit_ns",
 			"timer_disk_read_ns",
-			"timer_rego_external_resolve_ns",
+			"timer_disk_write_ns",
+			"timer_rego_input_parse_ns",
+			"timer_server_handler_ns",
+		})
+
+		testDataMetrics(t, f, http.MethodPatch, "/data/example?metrics", "[]", []string{
+			"timer_disk_commit_ns",
+			"timer_rego_input_parse_ns",
+			"timer_server_handler_ns",
+		})
+
+		testDataMetrics(t, f, http.MethodDelete, "/data/example?metrics", "{}", []string{
+			"counter_disk_deleted_keys",
+			"counter_disk_read_keys",
+			"counter_disk_read_bytes",
+			"timer_disk_commit_ns",
+			"timer_disk_read_ns",
+			"timer_disk_write_ns",
+			"timer_server_handler_ns",
 		})
 	})
 }
 
-func testDataMetrics(t *testing.T, f *fixture, url string, expected []string) {
+func testDataMetrics(t *testing.T, f *fixture, method string, url string, payload string, expected []string) {
 	t.Helper()
 	f.reset()
-	req := newReqV1(http.MethodPost, url, "")
+	req := newReqV1(method, url, payload)
 	f.server.Handler.ServeHTTP(f.recorder, req)
 
 	var result types.DataResponseV1