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
This commit is contained in:
Jeffrey Paul 2025-12-30 13:37:54 +07:00
parent 0ae89c33db
commit 3a9ec98d5c
3 changed files with 80 additions and 4 deletions

View File

@ -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,
)
})
}
}

View File

@ -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)

View File

@ -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)
}