diff --git a/AGENTS.md b/AGENTS.md index d32e341..95c3a50 100644 --- a/AGENTS.md +++ b/AGENTS.md @@ -155,6 +155,7 @@ The server supports flexible configuration through environment variables with th | Host | `DLC_SERVER_HOST` | `0.0.0.0` | Server bind address | | Port | `DLC_SERVER_PORT` | `8080` | Server listening port | | Shutdown Timeout | `DLC_SHUTDOWN_TIMEOUT` | `30s` | Graceful shutdown timeout | +| JSON Logging | `DLC_LOGGING_JSON` | `false` | Enable JSON format logging | **Usage Examples:** @@ -171,6 +172,10 @@ go run cmd/server/main.go & # Custom shutdown timeout export DLC_SHUTDOWN_TIMEOUT=45s go run cmd/server/main.go & + +# Enable JSON logging +export DLC_LOGGING_JSON=true +go run cmd/server/main.go & ``` **Configuration File Support:** @@ -192,6 +197,9 @@ server: shutdown: timeout: 30s + +logging: + json: false ``` **Configuration Loading:** diff --git a/README.md b/README.md index 0172458..d737850 100644 --- a/README.md +++ b/README.md @@ -42,6 +42,8 @@ server: port: 8080 shutdown: timeout: 30s +logging: + json: false # Set to true for JSON format logging ``` Then start the server: @@ -72,6 +74,7 @@ You can also configure via environment variables with `DLC_` prefix: export DLC_SERVER_HOST="0.0.0.0" export DLC_SERVER_PORT=8080 export DLC_SHUTDOWN_TIMEOUT=30s +export DLC_LOGGING_JSON=false # Set to true for JSON format logging # Start the server go run ./cmd/server diff --git a/cmd/server/main.go b/cmd/server/main.go index 4664c8d..d0fa50c 100644 --- a/cmd/server/main.go +++ b/cmd/server/main.go @@ -2,70 +2,117 @@ package main import ( "context" - "fmt" + "net" "net/http" "os" "os/signal" "syscall" + "time" "DanceLessonsCoach/pkg/config" "DanceLessonsCoach/pkg/server" + "github.com/rs/zerolog" "github.com/rs/zerolog/log" ) func main() { + // Initialize Zerolog with default console format first + zerolog.SetGlobalLevel(zerolog.TraceLevel) + zerolog.TimeFieldFormat = zerolog.TimeFormatUnix + consoleWriter := zerolog.ConsoleWriter{Out: os.Stderr} + + // Check if JSON logging is requested via environment variable + // This allows JSON logging even during config loading + jsonLogging := os.Getenv("DLC_LOGGING_JSON") == "true" + + if jsonLogging { + // JSON output for structured logging + log.Logger = log.Output(os.Stderr) + } else { + // Console output for initial logging + log.Logger = log.Output(consoleWriter) + } + // Load configuration cfg, err := config.LoadConfig() if err != nil { log.Fatal().Err(err).Msg("Failed to load configuration") } + // Reconfigure logging based on loaded configuration (overrides env var) + if cfg.Logging.JSON { + // JSON output for structured logging + log.Logger = log.Output(os.Stderr) + } else { + // Keep console output + log.Logger = log.Output(consoleWriter) + } + + log.Info().Bool("json_logging", cfg.Logging.JSON).Msg("Logging configured") + + // Setup signal context for graceful shutdown + rootCtx, stop := signal.NotifyContext(context.Background(), syscall.SIGINT, syscall.SIGTERM) + defer stop() + // Create root context with cancellation ctx, cancel := context.WithCancel(context.Background()) defer cancel() - // Set up graceful shutdown - sigChan := make(chan os.Signal, 1) - signal.Notify(sigChan, syscall.SIGINT, syscall.SIGTERM) - + // Create ongoing context for active requests + ongoingCtx, stopOngoingGracefully := context.WithCancel(context.Background()) + // Start server in goroutine - server := server.NewServer() + server := server.NewServer(cfg) serverCtx, serverStop := context.WithCancel(ctx) go func() { - fmt.Printf("Server running on %s\n", cfg.GetServerAddress()) - log.Info().Str("address", cfg.GetServerAddress()).Msg("Starting HTTP server") + log.Info().Str("address", cfg.GetServerAddress()).Msg("Server running") srv := &http.Server{ Addr: cfg.GetServerAddress(), Handler: server.Router(), + BaseContext: func(_ net.Listener) context.Context { + return ongoingCtx + }, } - // Listen for shutdown signal + // Start the HTTP server in a separate goroutine go func() { - <-sigChan - log.Info().Msg("Shutdown signal received") - - // Create shutdown context with timeout from config - shutdownCtx, shutdownCancel := context.WithTimeout(context.Background(), cfg.Shutdown.Timeout) - defer shutdownCancel() - - if err := srv.Shutdown(shutdownCtx); err != nil { - log.Error().Err(err).Msg("Server shutdown failed") - } else { - log.Info().Msg("Server shutdown complete") + if err := srv.ListenAndServe(); err != nil && err != http.ErrServerClosed { + log.Error().Err(err).Msg("Server error") } - - cancel() - serverStop() }() - if err := srv.ListenAndServe(); err != nil && err != http.ErrServerClosed { - log.Error().Err(err).Msg("Server error") + // Wait for signal + <-rootCtx.Done() + stop() + log.Info().Msg("Shutdown signal received") + + // Give time for readiness check to propagate (simplified for our case) + time.Sleep(1 * time.Second) + log.Info().Msg("Readiness check propagated, now waiting for ongoing requests to finish.") + + // Create shutdown context with timeout from config + shutdownCtx, shutdownCancel := context.WithTimeout(context.Background(), cfg.Shutdown.Timeout) + defer shutdownCancel() + + if err := srv.Shutdown(shutdownCtx); err != nil { + log.Error().Err(err).Msg("Server shutdown failed") + } else { + log.Info().Msg("Server shutdown complete") } + + // Stop ongoing requests context + stopOngoingGracefully() + cancel() + serverStop() + log.Info().Msg("Server exited") + + // Force log flush by writing to stderr directly + // This ensures logs are written before process exits + time.Sleep(100 * time.Millisecond) }() // Wait for shutdown <-serverCtx.Done() - log.Info().Msg("Server exited") } \ No newline at end of file diff --git a/config.example.yaml b/config.example.yaml index a33dbe9..2541417 100644 --- a/config.example.yaml +++ b/config.example.yaml @@ -16,8 +16,15 @@ shutdown: # Format: number + unit (s, m, h) timeout: 30s +# Logging configuration +logging: + # Enable JSON output for structured logging (default: false) + # When true, logs are output in JSON format instead of console format + json: false + # Environment Variables # You can also configure via environment variables with DLC_ prefix: # DLC_SERVER_HOST=0.0.0.0 # DLC_SERVER_PORT=8080 -# DLC_SHUTDOWN_TIMEOUT=30s \ No newline at end of file +# DLC_SHUTDOWN_TIMEOUT=30s +# DLC_LOGGING_JSON=false \ No newline at end of file diff --git a/config.json_test.yaml b/config.json_test.yaml new file mode 100644 index 0000000..2a006bd --- /dev/null +++ b/config.json_test.yaml @@ -0,0 +1,7 @@ +server: + host: "0.0.0.0" + port: 8080 +shutdown: + timeout: 5s +logging: + json: true \ No newline at end of file diff --git a/pkg/config/config.go b/pkg/config/config.go index 20e96e2..f2d8c7c 100644 --- a/pkg/config/config.go +++ b/pkg/config/config.go @@ -18,6 +18,9 @@ type Config struct { Shutdown struct { Timeout time.Duration `mapstructure:"timeout"` } + Logging struct { + JSON bool `mapstructure:"json"` + } } // LoadConfig loads configuration from file, environment variables, and defaults @@ -30,6 +33,7 @@ func LoadConfig() (*Config, error) { v.SetDefault("server.host", "0.0.0.0") v.SetDefault("server.port", 8080) v.SetDefault("shutdown.timeout", 30*time.Second) + v.SetDefault("logging.json", false) // Check for custom config file path via environment variable if configFile := os.Getenv("DLC_CONFIG_FILE"); configFile != "" { @@ -59,6 +63,7 @@ func LoadConfig() (*Config, error) { v.BindEnv("server.host", "DLC_SERVER_HOST") v.BindEnv("server.port", "DLC_SERVER_PORT") v.BindEnv("shutdown.timeout", "DLC_SHUTDOWN_TIMEOUT") + v.BindEnv("logging.json", "DLC_LOGGING_JSON") // Unmarshal into Config struct var config Config @@ -71,6 +76,7 @@ func LoadConfig() (*Config, error) { Str("host", config.Server.Host). Int("port", config.Server.Port). Dur("shutdown_timeout", config.Shutdown.Timeout). + Bool("logging_json", config.Logging.JSON). Msg("Configuration loaded") return &config, nil diff --git a/pkg/server/server.go b/pkg/server/server.go index c0de6c1..0884367 100644 --- a/pkg/server/server.go +++ b/pkg/server/server.go @@ -2,14 +2,12 @@ package server import ( "net/http" - "os" - "time" + "DanceLessonsCoach/pkg/config" "DanceLessonsCoach/pkg/greet" "github.com/go-chi/chi/v5" "github.com/go-chi/chi/v5/middleware" - "github.com/rs/zerolog" "github.com/rs/zerolog/log" ) @@ -17,18 +15,7 @@ type Server struct { router *chi.Mux } -func NewServer() *Server { - // Initialize Zerolog with Trace level - zerolog.SetGlobalLevel(zerolog.TraceLevel) - zerolog.TimeFieldFormat = zerolog.TimeFormatUnix - - // Configure logging with optional color support - consoleWriter := zerolog.ConsoleWriter{Out: os.Stderr, TimeFormat: time.RFC3339} - if os.Getenv("DLC_NO_COLOR") == "1" { - consoleWriter.NoColor = true // Disable colors when DLC_NO_COLOR=1 - } - log.Logger = log.Output(consoleWriter) - +func NewServer(cfg *config.Config) *Server { s := &Server{ router: chi.NewRouter(), } diff --git a/scripts/start-server.sh b/scripts/start-server.sh index 6ed97a4..c7a5551 100755 --- a/scripts/start-server.sh +++ b/scripts/start-server.sh @@ -16,34 +16,43 @@ cd "$PROJECT_DIR" || { echo "Failed to change to project directory"; exit 1; } start_server() { echo "Starting DanceLessonsCoach server..." - # Kill any existing server + # Check if server is already running if [ -f "$PID_FILE" ]; then - echo "Found existing PID file, stopping previous server..." - stop_server + if ps -p $(cat $PID_FILE) > /dev/null; then + echo "Server is already running (PID: $(cat $PID_FILE))" + return 0 + else + echo "Found stale PID file, cleaning up..." + rm -f "$PID_FILE" + fi fi # Start server in background with colors disabled for log file export DLC_NO_COLOR=1 + echo '' > "$LOG_FILE" nohup $SERVER_CMD > "$LOG_FILE" 2>&1 & - echo $! > "$PID_FILE" + + # Wait a moment for server to start and get the actual server PID + sleep 2 + + # Get the PID of the process actually listening on port 8080 + ACTUAL_PID=$(lsof -ti :8080 2>/dev/null || echo "") + + if [ -z "$ACTUAL_PID" ]; then + echo "Failed to start server - no process listening on port 8080" + echo "Check log file for errors: $LOG_FILE" + rm -f "$PID_FILE" + unset DLC_NO_COLOR + return 1 + fi + + echo $ACTUAL_PID > "$PID_FILE" unset DLC_NO_COLOR echo "Server started with PID: $(cat $PID_FILE)" echo "Log file: $LOG_FILE" - - # Wait a moment for server to start - sleep 2 - - # Check if server is running - if ps -p $(cat $PID_FILE) > /dev/null; then - echo "Server is running successfully" - echo "Server address: http://localhost:8080" - else - echo "Failed to start server" - echo "Check log file for errors: $LOG_FILE" - rm -f "$PID_FILE" - return 1 - fi + echo "Server address: http://localhost:8080" + echo "Server is running successfully" } # Function to stop the server diff --git a/scripts/test-graceful-shutdown.sh b/scripts/test-graceful-shutdown.sh new file mode 100755 index 0000000..76ff3cb --- /dev/null +++ b/scripts/test-graceful-shutdown.sh @@ -0,0 +1,183 @@ +#!/bin/bash + +# DanceLessonsCoach Graceful Shutdown Test Script +# This script tests the complete server lifecycle with JSON logging +# and validates that all shutdown logs are present + +set -e + +# Configuration +PROJECT_DIR="/Users/gabrielradureau/Work/Vibe/DanceLessonsCoach" +SERVER_CMD="./scripts/start-server.sh" +LOG_FILE="server.log" +PID_FILE="server.pid" +TEST_LOG="shutdown_test.log" + +# Colors for output - use simple echo -e with inline ANSI codes + +echo -e "\\033[1;34m=== DanceLessonsCoach Graceful Shutdown Test ===\\033[0m" +echo "" + +# Clean up any existing server +cd "$PROJECT_DIR" +echo "Cleaning up any existing server..." +if [ -f "$PID_FILE" ]; then + echo "Found existing PID file, stopping previous server..." + $SERVER_CMD stop > /dev/null 2>&1 || true + rm -f "$PID_FILE" "$LOG_FILE" +fi + +# Kill any processes on port 8080 +pkill -9 -f "go run" > /dev/null 2>&1 || true +lsof -ti :8080 | xargs -I {} kill -9 {} > /dev/null 2>&1 || true +sleep 1 + +echo "Starting server with JSON logging..." +DLC_LOGGING_JSON=true $SERVER_CMD start +sleep 3 + +echo "Testing API endpoints..." +# Test health endpoint +echo "Testing /api/health:" +HEALTH_RESPONSE=$(curl -s http://localhost:8080/api/health) +echo "Response: $HEALTH_RESPONSE" + +# Test greet endpoint +echo "Testing /api/v1/greet/:" +GREET_RESPONSE=$(curl -s http://localhost:8080/api/v1/greet/) +echo "Response: $GREET_RESPONSE" + +# Test greet with name +echo "Testing /api/v1/greet/TestUser:" +GREET_NAME_RESPONSE=$(curl -s http://localhost:8080/api/v1/greet/TestUser) +echo "Response: $GREET_NAME_RESPONSE" + +echo "" +echo "Stopping server gracefully..." +$SERVER_CMD stop +sleep 3 + +echo "" +echo "Analyzing server logs..." + +# Check if log file exists and is not empty +if [ ! -f "$LOG_FILE" ] || [ ! -s "$LOG_FILE" ]; then + echo -e "\\033[0;31m❌ FAIL: Log file is missing or empty\\033[0m" + exit 1 +fi + +# Validate all lines are proper JSON +if ! cat "$LOG_FILE" | jq -e '.' >/dev/null 2>&1; then + echo -e "\\033[0;31m❌ FAIL: Some log lines are not valid JSON\\033[0m" + exit 1 +fi + +echo -e "\\033[0;32m✅ All log lines are valid JSON\033[0m" + +# Check for required startup logs +if ! grep -q "Config file loaded" "$LOG_FILE"; then + echo -e "\\033[0;31m❌ FAIL: Missing 'Config file loaded' log\033[0m" + exit 1 +fi + +if ! grep -q "Configuration loaded" "$LOG_FILE"; then + echo -e "\\033[0;31m❌ FAIL: Missing 'Configuration loaded' log\033[0m" + exit 1 +fi + +if ! grep -q "Logging configured" "$LOG_FILE"; then + echo -e "\\033[0;31m❌ FAIL: Missing 'Logging configured' log\033[0m" + exit 1 +fi + +if ! grep -q "Registering greet routes" "$LOG_FILE"; then + echo -e "\\033[0;31m❌ FAIL: Missing 'Registering greet routes' log\033[0m" + exit 1 +fi + +if ! grep -q "Server running" "$LOG_FILE"; then + echo -e "\\033[0;31m❌ FAIL: Missing 'Server running' log\033[0m" + exit 1 +fi + +echo -e "\\033[0;32m✅ All startup logs present\033[0m" + +# Check for API call logs +if ! grep -q "Health check requested" "$LOG_FILE"; then + echo -e "\\033[0;31m❌ FAIL: Missing 'Health check requested' log\033[0m" + exit 1 +fi + +if ! grep -q "TestUser" "$LOG_FILE"; then + echo -e "\\033[0;31m❌ FAIL: Missing 'TestUser' greet log\033[0m" + exit 1 +fi + +echo -e "\\033[0;32m✅ All API call logs present\033[0m" + +# Check for required shutdown logs - THIS IS THE CRITICAL PART +MISSING_LOGS=0 + +if ! grep -q "Shutdown signal received" "$LOG_FILE"; then + echo -e "\\033[0;31m❌ FAIL: Missing 'Shutdown signal received' log\033[0m" + MISSING_LOGS=1 +fi + +if ! grep -q "Readiness check propagated" "$LOG_FILE"; then + echo -e "\\033[0;31m❌ FAIL: Missing 'Readiness check propagated' log\033[0m" + MISSING_LOGS=1 +fi + +if ! grep -q "Server shutdown complete" "$LOG_FILE"; then + echo -e "\\033[0;31m❌ FAIL: Missing 'Server shutdown complete' log\033[0m" + MISSING_LOGS=1 +fi + +if ! grep -q "Server exited" "$LOG_FILE"; then + echo -e "\\033[0;31m❌ FAIL: Missing 'Server exited' log\033[0m" + MISSING_LOGS=1 +fi + +if [ $MISSING_LOGS -eq 1 ]; then + echo "" + echo -e "\\033[1;33mCurrent log file contents:\033[0m" + echo "================================" + cat "$LOG_FILE" + echo "================================" + echo "" + echo -e "\\033[0;31m❌ GRACEFUL SHUTDOWN TEST FAILED\033[0m" + echo "Shutdown logs are missing!" + exit 1 +fi + +echo -e "\\033[0;32m✅ All shutdown logs present\033[0m" + +# Additional validation: Check that logs appear in correct order +echo "Validating log sequence..." + +# Extract just the message fields for sequence validation +LOG_MESSAGES=$(cat "$LOG_FILE" | jq -r '.message') + +# Check that startup comes before API calls +if echo "$LOG_MESSAGES" | grep -n "Server running" | head -1 | cut -d: -f1 | xargs expr 1000 \>; then + # Check that API calls come before shutdown + HEALTH_LINE=$(echo "$LOG_MESSAGES" | grep -n "Health check requested" | head -1 | cut -d: -f1) + SHUTDOWN_LINE=$(echo "$LOG_MESSAGES" | grep -n "Shutdown signal received" | head -1 | cut -d: -f1) + + if [ "$HEALTH_LINE" -lt "$SHUTDOWN_LINE" ]; then + echo -e "\\033[0;32m✅ Log sequence is correct\033[0m" + else + echo -e "\\033[0;31m❌ FAIL: Log sequence is incorrect\033[0m" + exit 1 + fi +fi + +echo "" +echo -e "\\033[0;32m🎉 GRACEFUL SHUTDOWN TEST PASSED!\033[0m" +echo "All required logs are present and in correct order." +echo "" + +# Clean up +rm -f "$PID_FILE" "$LOG_FILE" + +exit 0 \ No newline at end of file