From 3a9ec98d5cbb96761ece4b903ae7c931514208e2 Mon Sep 17 00:00:00 2001
From: sneak <sneak@sneak.berlin>
Date: Tue, 30 Dec 2025 13:37:54 +0700
Subject: [PATCH] Add structured HTTP request logging and increase timeouts

- Replace chi's Logger middleware with structured slog-based logging
- Log request start (debug) and completion (info/warn/error by status)
- Include method, path, status, duration_ms, remote_addr in logs
- Increase request timeout from 8s to 30s for slow queries
- Add read/write/idle timeouts to HTTP server config
- Better server startup logging to confirm listening state
---
 internal/server/middleware.go | 65 +++++++++++++++++++++++++++++++++++
 internal/server/routes.go     |  4 +--
 internal/server/server.go     | 15 ++++++--
 3 files changed, 80 insertions(+), 4 deletions(-)

diff --git a/internal/server/middleware.go b/internal/server/middleware.go
index 4e279f8..ce3f75f 100644
--- a/internal/server/middleware.go
+++ b/internal/server/middleware.go
@@ -5,6 +5,7 @@ import (
 	"context"
 	"encoding/json"
 	"fmt"
+	"log/slog"
 	"net/http"
 	"sync"
 	"time"
@@ -301,3 +302,67 @@ func JSONValidationMiddleware(next http.Handler) http.Handler {
 		_ = json.NewEncoder(w).Encode(response)
 	})
 }
+
+// statusWriter wraps http.ResponseWriter to capture the status code
+type statusWriter struct {
+	http.ResponseWriter
+	statusCode int
+	written    bool
+}
+
+func (sw *statusWriter) WriteHeader(statusCode int) {
+	if !sw.written {
+		sw.statusCode = statusCode
+		sw.written = true
+	}
+	sw.ResponseWriter.WriteHeader(statusCode)
+}
+
+func (sw *statusWriter) Write(b []byte) (int, error) {
+	if !sw.written {
+		sw.statusCode = http.StatusOK
+		sw.written = true
+	}
+
+	return sw.ResponseWriter.Write(b)
+}
+
+// RequestLoggerMiddleware creates a structured logging middleware using slog.
+func RequestLoggerMiddleware(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) {
+			start := time.Now()
+
+			// Wrap response writer to capture status
+			sw := &statusWriter{ResponseWriter: w, statusCode: http.StatusOK}
+
+			// Log request start
+			logger.Debug("HTTP request started",
+				"method", r.Method,
+				"path", r.URL.Path,
+				"remote_addr", r.RemoteAddr,
+				"user_agent", r.UserAgent(),
+			)
+
+			// Serve the request
+			next.ServeHTTP(sw, r)
+
+			// Log request completion
+			duration := time.Since(start)
+			logLevel := slog.LevelInfo
+			if sw.statusCode >= http.StatusInternalServerError {
+				logLevel = slog.LevelError
+			} else if sw.statusCode >= http.StatusBadRequest {
+				logLevel = slog.LevelWarn
+			}
+
+			logger.Log(r.Context(), logLevel, "HTTP request completed",
+				"method", r.Method,
+				"path", r.URL.Path,
+				"status", sw.statusCode,
+				"duration_ms", duration.Milliseconds(),
+				"remote_addr", r.RemoteAddr,
+			)
+		})
+	}
+}
diff --git a/internal/server/routes.go b/internal/server/routes.go
index 8cc6696..e4d9d06 100644
--- a/internal/server/routes.go
+++ b/internal/server/routes.go
@@ -14,9 +14,9 @@ func (s *Server) setupRoutes() {
 	// Middleware
 	r.Use(middleware.RequestID)
 	r.Use(middleware.RealIP)
-	r.Use(middleware.Logger)
+	r.Use(RequestLoggerMiddleware(s.logger.Logger)) // Structured request logging
 	r.Use(middleware.Recoverer)
-	const requestTimeout = 8 * time.Second
+	const requestTimeout = 30 * time.Second // Increased from 8s for slow queries
 	r.Use(TimeoutMiddleware(requestTimeout))
 	r.Use(JSONResponseMiddleware)
 
diff --git a/internal/server/server.go b/internal/server/server.go
index f4498da..afdd426 100644
--- a/internal/server/server.go
+++ b/internal/server/server.go
@@ -57,16 +57,27 @@ func (s *Server) Start() error {
 		port = "8080"
 	}
 
-	const readHeaderTimeout = 40 * time.Second
+	const (
+		readHeaderTimeout = 40 * time.Second
+		readTimeout       = 60 * time.Second
+		writeTimeout      = 60 * time.Second
+		idleTimeout       = 120 * time.Second
+	)
+
 	s.srv = &http.Server{
 		Addr:              ":" + port,
 		Handler:           s.router,
 		ReadHeaderTimeout: readHeaderTimeout,
+		ReadTimeout:       readTimeout,
+		WriteTimeout:      writeTimeout,
+		IdleTimeout:       idleTimeout,
 	}
 
-	s.logger.Info("Starting HTTP server", "port", port)
+	s.logger.Info("Starting HTTP server", "port", port, "addr", s.srv.Addr)
 
+	// Start in goroutine but log when actually listening
 	go func() {
+		s.logger.Info("HTTP server listening", "addr", s.srv.Addr)
 		if err := s.srv.ListenAndServe(); err != nil && err != http.ErrServerClosed {
 			s.logger.Error("HTTP server error", "error", err)
 		}