From a163449a28d0e5095f810874c0fa98a4e9b033fd Mon Sep 17 00:00:00 2001 From: sneak Date: Thu, 1 Jan 2026 06:06:20 -0800 Subject: [PATCH] Improve request logging and make health check lightweight - Log slow requests (>1s) at WARNING level with slow=true flag - Log request timeouts at WARNING level in TimeoutMiddleware - Replace heavy GetStatsContext with lightweight Ping in health check - Add Ping method to database interface (SELECT 1) --- internal/database/database.go | 11 +++++++++++ internal/database/interface.go | 1 + internal/routewatch/app_integration_test.go | 5 +++++ internal/server/handlers.go | 7 +++---- internal/server/middleware.go | 17 ++++++++++++++++- internal/server/routes.go | 2 +- 6 files changed, 37 insertions(+), 6 deletions(-) diff --git a/internal/database/database.go b/internal/database/database.go index 833b98d..1896d1b 100644 --- a/internal/database/database.go +++ b/internal/database/database.go @@ -1997,3 +1997,14 @@ func (d *Database) Checkpoint(ctx context.Context) error { return nil } + +// Ping checks if the database connection is alive with a lightweight query. +func (d *Database) Ping(ctx context.Context) error { + var result int + err := d.db.QueryRowContext(ctx, "SELECT 1").Scan(&result) + if err != nil { + return fmt.Errorf("database ping failed: %w", err) + } + + return nil +} diff --git a/internal/database/interface.go b/internal/database/interface.go index 5cd6050..7f3f8e9 100644 --- a/internal/database/interface.go +++ b/internal/database/interface.go @@ -88,6 +88,7 @@ type Store interface { Vacuum(ctx context.Context) error Analyze(ctx context.Context) error Checkpoint(ctx context.Context) error + Ping(ctx context.Context) error } // Ensure Database implements Store diff --git a/internal/routewatch/app_integration_test.go b/internal/routewatch/app_integration_test.go index 097872e..619210d 100644 --- a/internal/routewatch/app_integration_test.go +++ b/internal/routewatch/app_integration_test.go @@ -420,6 +420,11 @@ func (m *mockStore) Checkpoint(ctx context.Context) error { return nil } +// Ping mock implementation +func (m *mockStore) Ping(ctx context.Context) error { + return nil +} + func TestRouteWatchLiveFeed(t *testing.T) { // Create mock database diff --git a/internal/server/handlers.go b/internal/server/handlers.go index 9aab1b1..9ca8195 100644 --- a/internal/server/handlers.go +++ b/internal/server/handlers.go @@ -37,6 +37,7 @@ type HealthCheckResponse struct { // handleHealthCheck returns a handler that performs health checks. // Returns 200 if healthy, 503 if any check fails. +// Uses lightweight checks to avoid timeout issues under load. func (s *Server) handleHealthCheck() http.HandlerFunc { return func(w http.ResponseWriter, r *http.Request) { ctx, cancel := context.WithTimeout(r.Context(), healthCheckTimeout) @@ -45,13 +46,11 @@ func (s *Server) handleHealthCheck() http.HandlerFunc { checks := make(map[string]string) healthy := true - // Check database connectivity - dbStats, err := s.db.GetStatsContext(ctx) + // Check database connectivity with lightweight ping + err := s.db.Ping(ctx) if err != nil { checks["database"] = "error: " + err.Error() healthy = false - } else if dbStats.ASNs == 0 && dbStats.Prefixes == 0 { - checks["database"] = "warning: empty database" } else { checks["database"] = "ok" } diff --git a/internal/server/middleware.go b/internal/server/middleware.go index ce3f75f..dd61ee8 100644 --- a/internal/server/middleware.go +++ b/internal/server/middleware.go @@ -168,7 +168,7 @@ func (tw *timeoutWriter) markWritten() { // The timeout parameter specifies the maximum duration allowed for request processing. // The returned middleware handles panics from the wrapped handler by re-panicking // after cleanup, and prevents concurrent writes to the response after timeout occurs. -func TimeoutMiddleware(timeout time.Duration) func(http.Handler) http.Handler { +func TimeoutMiddleware(timeout time.Duration, logger *slog.Logger) func(http.Handler) http.Handler { return func(next http.Handler) http.Handler { return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { startTime := time.Now() @@ -204,6 +204,14 @@ func TimeoutMiddleware(timeout time.Duration) func(http.Handler) http.Handler { tw.markWritten() // Prevent the handler from writing after timeout execTime := time.Since(startTime) + // Log the timeout as a warning + logger.Warn("Request timeout", + "method", r.Method, + "path", r.URL.Path, + "duration_ms", execTime.Milliseconds(), + "remote_addr", r.RemoteAddr, + ) + // Write directly to the underlying writer since we've marked tw as written // This is safe because markWritten() prevents the handler from writing tw.mu.Lock() @@ -350,10 +358,16 @@ func RequestLoggerMiddleware(logger *slog.Logger) func(http.Handler) http.Handle // Log request completion duration := time.Since(start) logLevel := slog.LevelInfo + + // Slow query threshold (1 second) + const slowQueryThreshold = 1 * time.Second + if sw.statusCode >= http.StatusInternalServerError { logLevel = slog.LevelError } else if sw.statusCode >= http.StatusBadRequest { logLevel = slog.LevelWarn + } else if duration >= slowQueryThreshold { + logLevel = slog.LevelWarn } logger.Log(r.Context(), logLevel, "HTTP request completed", @@ -362,6 +376,7 @@ func RequestLoggerMiddleware(logger *slog.Logger) func(http.Handler) http.Handle "status", sw.statusCode, "duration_ms", duration.Milliseconds(), "remote_addr", r.RemoteAddr, + "slow", duration >= slowQueryThreshold, ) }) } diff --git a/internal/server/routes.go b/internal/server/routes.go index fceab5c..cde3293 100644 --- a/internal/server/routes.go +++ b/internal/server/routes.go @@ -17,7 +17,7 @@ func (s *Server) setupRoutes() { r.Use(RequestLoggerMiddleware(s.logger.Logger)) // Structured request logging r.Use(middleware.Recoverer) const requestTimeout = 30 * time.Second // Increased from 8s for slow queries - r.Use(TimeoutMiddleware(requestTimeout)) + r.Use(TimeoutMiddleware(requestTimeout, s.logger.Logger)) r.Use(JSONResponseMiddleware) // Routes