Answer 504, not 408, when a request outlasts its time limit (closes #70)

The hand-written time limit middleware answered 408 and wrote that
answer from its own goroutine while the handler could still be writing.
It is replaced by chi's middleware.Timeout, placed after
JSONResponseMiddleware so its 504 is not lost behind a 200.

When a handler's database read or other lookup fails, it asks
deadlinePassed whether the request's time limit passed and, if so,
answers 504 instead of its 500 or 404. JSONValidationMiddleware answers
504 with the JSON error body when the limit has passed and the handler
wrote nothing. status.json and /api/v1/stats answer 504 when their
4-second database read runs out.

Model: opus-5-5

internal/metrics/metrics.go

@@ -60,17 +60,22 @@ func New() *Tracker {
 	}
 }
 
-// SetConnected updates the connection status
+// SetConnected updates the connection status. Every connection after the
+// first counts one reconnect.
 func (t *Tracker) SetConnected(connected bool) {
-	wasConnected := t.isConnected.Swap(connected)
-	if connected {
-		t.mu.Lock()
-		t.connectedSince = time.Now()
-		t.mu.Unlock()
-		// Increment reconnect count (but not for the initial connection)
-		if wasConnected || t.reconnectCount.Load() > 0 {
-			t.reconnectCount.Add(1)
-		}
+	t.isConnected.Store(connected)
+	if !connected {
+		return
+	}
+
+	t.mu.Lock()
+	// connectedSince is zero until the first connection.
+	connectedBefore := !t.connectedSince.IsZero()
+	t.connectedSince = time.Now()
+	t.mu.Unlock()
+
+	if connectedBefore {
+		t.reconnectCount.Add(1)
 	}
 }
 

internal/metrics/metrics_test.go

@@ -0,0 +1,21 @@
+package metrics
+
+import "testing"
+
+// TestReconnectCount connects three times with a disconnect between each, the
+// way the streamer does, and expects every connection after the first to count
+// one reconnect.
+func TestReconnectCount(t *testing.T) {
+	tracker := New()
+
+	tracker.SetConnected(true)
+	tracker.SetConnected(false)
+	tracker.SetConnected(true)
+	tracker.SetConnected(false)
+	tracker.SetConnected(true)
+
+	const wantReconnects = 2
+	if got := tracker.GetReconnectCount(); got != wantReconnects {
+		t.Fatalf("reconnect count = %d, want %d", got, wantReconnects)
+	}
+}

internal/server/handlers.go

@@ -205,7 +205,11 @@ func (s *Server) handleStatusJSON() http.HandlerFunc {
 			return
 		case err := <-errChan:
 			s.logger.Error("Failed to get database stats", "error", err)
-			writeJSONError(w, http.StatusInternalServerError, err.Error())
+			if deadlinePassed(ctx) {
+				writeJSONError(w, http.StatusGatewayTimeout, requestTimeoutMessage)
+			} else {
+				writeJSONError(w, http.StatusInternalServerError, err.Error())
+			}
 
 			return
 		case dbStats = <-statsChan:
@@ -419,7 +423,11 @@ func (s *Server) handleStats() http.HandlerFunc {
 			return
 		case err := <-errChan:
 			s.logger.Error("Failed to get database stats", "error", err)
-			writeJSONError(w, http.StatusInternalServerError, err.Error())
+			if deadlinePassed(ctx) {
+				writeJSONError(w, http.StatusGatewayTimeout, requestTimeoutMessage)
+			} else {
+				writeJSONError(w, http.StatusInternalServerError, err.Error())
+			}
 
 			return
 		case dbStats = <-statsChan:
@@ -622,6 +630,13 @@ func (s *Server) handleIPInfo() http.HandlerFunc {
 			}
 		}
 
+		// The time limit passed while resolving host names.
+		if deadlinePassed(ctx) {
+			writeJSONError(w, http.StatusGatewayTimeout, requestTimeoutMessage)
+
+			return
+		}
+
 		if len(ipsToLookup) == 0 {
 			writeJSONError(w, http.StatusBadRequest, "No valid IPs or hostnames provided")
 
@@ -664,6 +679,13 @@ func (s *Server) handleIPInfo() http.HandlerFunc {
 			}
 		}
 
+		// The time limit passed while looking up the IPs.
+		if deadlinePassed(ctx) {
+			writeJSONError(w, http.StatusGatewayTimeout, requestTimeoutMessage)
+
+			return
+		}
+
 		// Return response (even if no results, include errors)
 		if len(response.Results) == 0 && len(response.Errors) > 0 {
 			writeJSONError(w, http.StatusNotFound, "No routes found: "+response.Errors[0])
@@ -703,9 +725,12 @@ func (s *Server) handleASDetailJSON() http.HandlerFunc {
 
 		asInfo, prefixes, err := s.db.GetASDetailsContext(r.Context(), asn)
 		if err != nil {
-			if errors.Is(err, database.ErrNoRoute) {
+			switch {
+			case errors.Is(err, database.ErrNoRoute):
 				writeJSONError(w, http.StatusNotFound, err.Error())
-			} else {
+			case deadlinePassed(r.Context()):
+				writeJSONError(w, http.StatusGatewayTimeout, requestTimeoutMessage)
+			default:
 				writeJSONError(w, http.StatusInternalServerError, err.Error())
 			}
 
@@ -754,9 +779,12 @@ func (s *Server) handlePrefixDetailJSON() http.HandlerFunc {
 
 		routes, err := s.db.GetPrefixDetailsContext(r.Context(), prefix)
 		if err != nil {
-			if errors.Is(err, database.ErrNoRoute) {
+			switch {
+			case errors.Is(err, database.ErrNoRoute):
 				writeJSONError(w, http.StatusNotFound, err.Error())
-			} else {
+			case deadlinePassed(r.Context()):
+				writeJSONError(w, http.StatusGatewayTimeout, requestTimeoutMessage)
+			default:
 				writeJSONError(w, http.StatusInternalServerError, err.Error())
 			}
 
@@ -796,9 +824,12 @@ func (s *Server) handleASDetail() http.HandlerFunc {
 
 		asInfo, prefixes, err := s.db.GetASDetailsContext(r.Context(), asn)
 		if err != nil {
-			if errors.Is(err, database.ErrNoRoute) {
+			switch {
+			case errors.Is(err, database.ErrNoRoute):
 				http.Error(w, "AS not found", http.StatusNotFound)
-			} else {
+			case deadlinePassed(r.Context()):
+				http.Error(w, requestTimeoutMessage, http.StatusGatewayTimeout)
+			default:
 				s.logger.Error("Failed to get AS details", "error", err)
 				http.Error(w, "Internal server error", http.StatusInternalServerError)
 			}
@@ -918,9 +949,12 @@ func (s *Server) handlePrefixDetail() http.HandlerFunc {
 
 		routes, err := s.db.GetPrefixDetailsContext(r.Context(), prefix)
 		if err != nil {
-			if errors.Is(err, database.ErrNoRoute) {
+			switch {
+			case errors.Is(err, database.ErrNoRoute):
 				http.Error(w, "Prefix not found", http.StatusNotFound)
-			} else {
+			case deadlinePassed(r.Context()):
+				http.Error(w, requestTimeoutMessage, http.StatusGatewayTimeout)
+			default:
 				s.logger.Error("Failed to get prefix details", "error", err)
 				http.Error(w, "Internal server error", http.StatusInternalServerError)
 			}
@@ -1074,8 +1108,12 @@ func (s *Server) handlePrefixLength() http.HandlerFunc {
 		const maxPrefixes = 500
 		prefixes, err := s.db.GetRandomPrefixesByLengthContext(r.Context(), maskLength, ipVersion, maxPrefixes)
 		if err != nil {
-			s.logger.Error("Failed to get prefixes by length", "error", err)
-			http.Error(w, "Internal server error", http.StatusInternalServerError)
+			if deadlinePassed(r.Context()) {
+				http.Error(w, requestTimeoutMessage, http.StatusGatewayTimeout)
+			} else {
+				s.logger.Error("Failed to get prefixes by length", "error", err)
+				http.Error(w, "Internal server error", http.StatusInternalServerError)
+			}
 
 			return
 		}
@@ -1165,8 +1203,12 @@ func (s *Server) handlePrefixLength6() http.HandlerFunc {
 		const maxPrefixes = 500
 		prefixes, err := s.db.GetRandomPrefixesByLengthContext(r.Context(), maskLength, ipVersion, maxPrefixes)
 		if err != nil {
-			s.logger.Error("Failed to get prefixes by length", "error", err)
-			http.Error(w, "Internal server error", http.StatusInternalServerError)
+			if deadlinePassed(r.Context()) {
+				http.Error(w, requestTimeoutMessage, http.StatusGatewayTimeout)
+			} else {
+				s.logger.Error("Failed to get prefixes by length", "error", err)
+				http.Error(w, "Internal server error", http.StatusInternalServerError)
+			}
 
 			return
 		}

internal/server/handlers_test.go

@@ -221,6 +221,85 @@ func TestStatsHandlersAnswer504WhenDatabaseReadRunsOut(t *testing.T) {
 	}
 }
 
+// slowDB embeds database.Store (left nil) and overrides the reads the routes
+// in TestRoutesAnswer504WhenDatabaseReadIsCutOff make. Each read waits until
+// its context ends and returns the context's error, as a slow database read
+// cut off by a time limit does.
+type slowDB struct {
+	database.Store
+}
+
+func (slowDB) GetStatsContext(ctx context.Context) (database.Stats, error) {
+	<-ctx.Done()
+
+	return database.Stats{}, ctx.Err()
+}
+
+func (slowDB) GetIPInfoContext(ctx context.Context, _ string) (*database.IPInfo, error) {
+	<-ctx.Done()
+
+	return nil, ctx.Err()
+}
+
+func (slowDB) GetASDetailsContext(ctx context.Context, _ int) (*database.ASN, []database.LiveRoute, error) {
+	<-ctx.Done()
+
+	return nil, nil, ctx.Err()
+}
+
+func (slowDB) GetPrefixDetailsContext(ctx context.Context, _ string) ([]database.LiveRoute, error) {
+	<-ctx.Done()
+
+	return nil, ctx.Err()
+}
+
+func (slowDB) GetRandomPrefixesByLengthContext(ctx context.Context, _, _, _ int) ([]database.LiveRoute, error) {
+	<-ctx.Done()
+
+	return nil, ctx.Err()
+}
+
+// TestRoutesAnswer504WhenDatabaseReadIsCutOff sends a request through the
+// server's router for each route that reads the database, with a store whose
+// reads fail when the request's time limit passes. Each route answers 504, the
+// JSON routes with the JSON error body. Before the fix they answered 408 or,
+// when the handler wrote first, its own error: 500, or 404 on the IP lookups.
+// The health check is left out: it answers 503 when its own 2-second ping runs
+// out.
+func TestRoutesAnswer504WhenDatabaseReadIsCutOff(t *testing.T) {
+	s := New(slowDB{}, streamer.New(logger.New(), metrics.New()), logger.New(), &config.Config{})
+
+	tests := []struct {
+		path         string
+		wantJSONBody bool
+	}{
+		{path: "/as/64500"},
+		{path: "/prefix/192.0.2.0/24"},
+		{path: "/prefixlength/24"},
+		{path: "/prefixlength6/48"},
+		{path: "/status.json", wantJSONBody: true},
+		{path: "/ip/192.0.2.1", wantJSONBody: true},
+		{path: "/api/v1/stats", wantJSONBody: true},
+		{path: "/api/v1/ip/192.0.2.1", wantJSONBody: true},
+		{path: "/api/v1/as/64500", wantJSONBody: true},
+		{path: "/api/v1/prefix/192.0.2.0/24", wantJSONBody: true},
+	}
+
+	for _, tt := range tests {
+		ctx, cancel := context.WithTimeout(context.Background(), shortRequestDeadline)
+		rec := httptest.NewRecorder()
+		s.router.ServeHTTP(rec, httptest.NewRequest(http.MethodGet, tt.path, nil).WithContext(ctx))
+		cancel()
+
+		if rec.Code != http.StatusGatewayTimeout {
+			t.Errorf("%s: status %d, want %d; body %s", tt.path, rec.Code, http.StatusGatewayTimeout, rec.Body)
+		}
+		if tt.wantJSONBody {
+			checkJSONErrorCode(t, tt.path, rec, http.StatusGatewayTimeout)
+		}
+	}
+}
+
 // checkJSONErrorCode checks that rec holds the JSON error body with the given
 // code.
 func checkJSONErrorCode(t *testing.T, name string, rec *httptest.ResponseRecorder, want int) {

internal/server/middleware.go

@@ -113,6 +113,13 @@ func JSONResponseMiddleware(next http.Handler) http.Handler {
 // requestTimeoutMessage is the error message sent with 504 Gateway Timeout.
 const requestTimeoutMessage = "Request timeout"
 
+// deadlinePassed reports whether ctx ended because its deadline passed. When
+// a handler's database read or other lookup fails, it uses this to tell a
+// request cut off by its time limit, which answers 504, from other failures.
+func deadlinePassed(ctx context.Context) bool {
+	return errors.Is(ctx.Err(), context.DeadlineExceeded)
+}
+
 // JSONValidationMiddleware is an HTTP middleware that validates JSON API responses.
 // It ensures that responses with Content-Type "application/json" contain valid JSON.
 //
@@ -169,7 +176,7 @@ func JSONValidationMiddleware(next http.Handler) http.Handler {
 		if statusCode == http.StatusOK {
 			statusCode = http.StatusInternalServerError
 		}
-		if errors.Is(r.Context().Err(), context.DeadlineExceeded) {
+		if deadlinePassed(r.Context()) {
 			statusCode = http.StatusGatewayTimeout
 		}
 		w.WriteHeader(statusCode)