Implement structured logging and enhance middleware with context-aware logging

cmd/start.go

@@ -1,11 +1,14 @@
 package cmd
 
 import (
-	"log"
+	"context"
+	"log/slog"
+	"net"
 	"net/http"
 	"time"
 
 	"git.coopcloud.tech/wiki-cafe/member-console/internal/auth"
+	"git.coopcloud.tech/wiki-cafe/member-console/internal/logging"
 	"git.coopcloud.tech/wiki-cafe/member-console/internal/middleware"
 	"github.com/spf13/cobra"
 	"github.com/spf13/viper"
@@ -20,8 +23,18 @@ var startCmd = &cobra.Command{
 	The server listens on port 8080 by default, unless a different port is specified using the --port flag.`,
 	Args: cobra.NoArgs,
 	Run: func(cmd *cobra.Command, args []string) {
-		// Retrieve the port value from Viper
+		// Create base context for the application
+		ctx := context.Background()
+
+		// Retrieve the configuration values from Viper
 		port := viper.GetString("port")
+		env := viper.GetString("env")
+
+		// Set up structured logging
+		logger := logging.SetupLogger(env)
+
+		// Store logger in context
+		ctx = logging.WithContext(ctx, logger)
 
 		// Create a new HTTP request router
 		httpRequestRouter := http.NewServeMux()
@@ -29,7 +42,8 @@ var startCmd = &cobra.Command{
 		// Set up authentication
 		authConfig, err := auth.Setup()
 		if err != nil {
-			log.Fatalf("Failed to set up authentication: %v", err)
+			logger.Error("failed to set up authentication", slog.Any("error", err))
+			return
 		}
 
 		// Register auth handlers
@@ -42,7 +56,7 @@ var startCmd = &cobra.Command{
 			middleware.RequestID(),                       // Generate a unique request ID
 			middleware.MaxBodySize(1024*1024),            // 1MB size limit
 			middleware.SecureHeaders,                     // Set secure headers
-			middleware.Logging,                           // Log requests
+			middleware.Logging,                           // Log requests with structured logging
 			authConfig.Middleware(),                      // OIDC authentication middleware
 		)
 
@@ -53,13 +67,23 @@ var startCmd = &cobra.Command{
 			ReadTimeout:    2 * time.Second,
 			WriteTimeout:   4 * time.Second,
 			IdleTimeout:    8 * time.Second,
-			MaxHeaderBytes: 1024 * 1024, // 1MB
+			MaxHeaderBytes: 1024 * 1024,                                         // 1MB
+			BaseContext:    func(_ net.Listener) context.Context { return ctx }, // Pass base context to all requests
 		}
 
 		// Serve the components directory
 		httpRequestRouter.Handle("/", http.FileServer(http.Dir("./components")))
-		log.Println("Starting server on port", port)
-		log.Fatal(server.ListenAndServe())
+
+		// Log server startup with structured logging
+		logger.Info("starting server",
+			slog.String("port", port),
+			slog.String("environment", env),
+			slog.String("address", "http://localhost:"+port))
+
+		// Start server and log any errors
+		if err := server.ListenAndServe(); err != nil {
+			logger.Error("server error", slog.Any("error", err))
+		}
 	},
 }
 

internal/logging/logging.go

@@ -0,0 +1,85 @@
+package logging
+
+import (
+	"context"
+	"fmt"
+	"log/slog"
+	"os"
+	"time"
+)
+
+// loggerKey is the context key for logger values
+type loggerKey struct{}
+
+// AppLogger is the application-wide logger instance
+var AppLogger *slog.Logger
+
+// SetupLogger initializes the structured logger based on environment settings
+func SetupLogger(env string) *slog.Logger {
+	// Determine log level
+	logLevel := slog.LevelInfo
+	if levelStr := os.Getenv("LOG_LEVEL"); levelStr != "" {
+		if err := logLevel.UnmarshalText([]byte(levelStr)); err != nil {
+			panic(fmt.Sprintf("invalid log level: %s", levelStr))
+		}
+	}
+
+	var handler slog.Handler
+
+	// Configure handler based on environment
+	if env == "development" {
+		// In development, use text output with source information if in debug mode
+		opts := &slog.HandlerOptions{
+			Level:     logLevel,
+			AddSource: logLevel == slog.LevelDebug,
+			ReplaceAttr: func(groups []string, a slog.Attr) slog.Attr {
+				// Format time for better readability in dev mode
+				if a.Key == slog.TimeKey {
+					if t, ok := a.Value.Any().(time.Time); ok {
+						return slog.String(slog.TimeKey, t.Format(time.RFC3339))
+					}
+				}
+				return a
+			},
+		}
+		handler = slog.NewTextHandler(os.Stdout, opts)
+	} else {
+		// In production, use JSON output
+		handler = slog.NewJSONHandler(os.Stdout, &slog.HandlerOptions{
+			Level: logLevel,
+		})
+	}
+
+	// Create and set the default logger
+	logger := slog.New(handler)
+	slog.SetDefault(logger)
+	AppLogger = logger
+
+	logger.Info("logger initialized",
+		slog.String("environment", env),
+		slog.String("level", logLevel.String()))
+
+	return logger
+}
+
+// FromContext retrieves a logger from the given context
+// If no logger exists in the context, returns the default logger
+func FromContext(ctx context.Context) *slog.Logger {
+	if ctx == nil {
+		return AppLogger
+	}
+	if logger, ok := ctx.Value(loggerKey{}).(*slog.Logger); ok {
+		return logger
+	}
+	return AppLogger
+}
+
+// WithContext stores a logger in the given context
+func WithContext(ctx context.Context, logger *slog.Logger) context.Context {
+	return context.WithValue(ctx, loggerKey{}, logger)
+}
+
+// WithValues returns a new logger with additional context values
+func WithValues(logger *slog.Logger, attrs ...any) *slog.Logger {
+	return logger.With(attrs...)
+}

internal/middleware/logging.go

@@ -1,9 +1,11 @@
 package middleware
 
 import (
-	"log"
+	"log/slog"
 	"net/http"
 	"time"
+
+	"git.coopcloud.tech/wiki-cafe/member-console/internal/logging"
 )
 
 type wrappedWriter struct {
@@ -16,21 +18,48 @@ func (w *wrappedWriter) WriteHeader(statusCode int) {
 	w.statusCode = statusCode
 }
 
-// Logging is a middleware function that logs the request method, URL path, and status code
+// Logging is a middleware function that logs requests with structured logging
 func Logging(next http.Handler) http.Handler {
 	return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
 		start := time.Now()
 
+		// Prepare wrapped writer to capture status code
 		wrapped := &wrappedWriter{
 			ResponseWriter: w,
 			statusCode:     http.StatusOK,
 		}
 
-		// Get request ID from header (set by RequestID middleware)
-		requestID := r.Header.Get(RequestIDHeader)
-		
+		// Get request ID from context
+		requestID := GetRequestID(r.Context())
+
+		// Get logger from the application and add request information
+		logger := logging.FromContext(r.Context())
+		reqLogger := logging.WithValues(logger,
+			slog.String("request_id", requestID),
+			slog.String("method", r.Method),
+			slog.String("path", r.URL.Path),
+			slog.String("remote_ip", r.RemoteAddr),
+			slog.String("user_agent", r.UserAgent()),
+		)
+
+		// Store the request-specific logger in context
+		ctx := logging.WithContext(r.Context(), reqLogger)
+		r = r.WithContext(ctx)
+
+		// Log request start if in debug mode
+		reqLogger.Debug("request started")
+
+		// Process the request with updated context
 		next.ServeHTTP(wrapped, r)
 
-		log.Printf("[%s] %d %s %s %v", requestID, wrapped.statusCode, r.Method, r.URL.Path, time.Since(start))
+		// Calculate duration
+		duration := time.Since(start)
+
+		// Log request completion with status and duration
+		reqLogger.Info("request completed",
+			slog.Int("status", wrapped.statusCode),
+			slog.Duration("duration", duration),
+			slog.String("duration_human", duration.String()),
+		)
 	})
-}
+}

internal/middleware/recover.go

@@ -1,27 +1,40 @@
 package middleware
 
 import (
-	"log"
+	"log/slog"
 	"net/http"
 	"runtime/debug"
+
+	"git.coopcloud.tech/wiki-cafe/member-console/internal/logging"
 )
 
-// Recovery middleware to catch panics, log them, and return a 500 error
+// Recovery middleware catches panics and logs them with structured logging
 func Recovery() Middleware {
 	return func(next http.Handler) http.Handler {
 		return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
 			defer func() {
 				if err := recover(); err != nil {
-					// Log the stack trace
-					log.Printf("PANIC: %v\n%s", err, debug.Stack())
-					
-					// Return a 500 Internal Server Error response
-					w.WriteHeader(http.StatusInternalServerError)
-					w.Write([]byte("Internal Server Error"))
+					// Get logger from context
+					logger := logging.FromContext(r.Context())
+
+					// Get request ID from context
+					requestID := GetRequestID(r.Context())
+
+					// Log the panic with stack trace
+					logger.Error("panic recovered",
+						slog.String("request_id", requestID),
+						slog.String("method", r.Method),
+						slog.String("path", r.URL.Path),
+						slog.Any("error", err),
+						slog.String("stack", string(debug.Stack())),
+					)
+
+					// Return 500 Internal Server Error to the client
+					http.Error(w, http.StatusText(http.StatusInternalServerError), http.StatusInternalServerError)
 				}
 			}()
-			
+
 			next.ServeHTTP(w, r)
 		})
 	}
-}
+}

internal/middleware/requestid.go

@@ -2,16 +2,15 @@ package middleware
 
 import (
 	"context"
-	"log"
 	"net/http"
 
 	"github.com/google/uuid"
 )
 
-// RequestIDKey is the context key for the request ID
+// requestIDKey is the context key for request ID
 type requestIDKey struct{}
 
-// RequestIDHeader is the header key for the request ID
+// RequestIDHeader is the HTTP header for request ID
 const RequestIDHeader = "X-Request-ID"
 
 // RequestID middleware generates a unique ID for each request
@@ -21,30 +20,26 @@ func RequestID() Middleware {
 			// Check if request already has an ID
 			requestID := r.Header.Get(RequestIDHeader)
 			if requestID == "" {
-				// Generate a new UUID if none exists
+				// Generate a new UUID for the request if not present
 				requestID = uuid.New().String()
 			}
 
-			// Add the request ID to the response headers
+			// Add request ID to response headers
 			w.Header().Set(RequestIDHeader, requestID)
 
-			// Store the request ID in the request context
+			// Store request ID in context
 			ctx := context.WithValue(r.Context(), requestIDKey{}, requestID)
 
-			// Log the request with its ID
-			log.Printf("[%s] %s %s", requestID, r.Method, r.URL.Path)
-
-			// Call the next handler with the updated context
+			// Call next handler with updated context
 			next.ServeHTTP(w, r.WithContext(ctx))
 		})
 	}
 }
 
-// GetRequestID retrieves the request ID from the context
+// GetRequestID retrieves the request ID from context
 func GetRequestID(ctx context.Context) string {
-	id, ok := ctx.Value(requestIDKey{}).(string)
-	if !ok {
-		return ""
+	if id, ok := ctx.Value(requestIDKey{}).(string); ok {
+		return id
 	}
-	return id
-}
+	return ""
+}