Gabriel Radureau
c17fb4f9b4
## Summary Closes #15 When `logging.json: true` (or `DLC_LOGGING_JSON=true`), the logger was unconditionally initialised to console/text format at the top of `LoadConfig()`, so early log lines — most visibly **"Config file loaded"** — were always written as human-readable text regardless of configuration. ## Root cause Classic chicken-and-egg: the format flag lives inside the config that is being loaded. The format-switch block only ran *after* `v.Unmarshal()`, too late for the config-file log. ## Changes ### `pkg/config/config.go` - Add `peekJSONLogging()`: resolves the JSON flag **before** any log is emitted by (1) checking `DLC_LOGGING_JSON` directly via `os.Getenv`, then (2) doing a minimal throwaway Viper pre-read of the config file for the `logging.json` key. This mirrors Viper's own priority order without parsing the full config twice. - Apply the resolved format immediately and emit **"Logging configured"** as the very first log line. - Remove the now-redundant format-switch block that ran after `Unmarshal()`. ### `scripts/start-server.sh`, `test-graceful-shutdown.sh`, `test-opentelemetry.sh` - Replace hardcoded `PROJECT_DIR` path with a dynamic `SCRIPTS_DIR=$(dirname $(realpath ${BASH_SOURCE[0]}))` derivation so scripts work from any worktree or clone location. ## Test plan - [x] `go test ./pkg/...` — all pass - [x] `scripts/test-graceful-shutdown.sh` — all JSON valid, all startup logs present - [x] Manual smoke test: first line is `{"level":"info",...,"message":"Logging configured"}`, every line is valid JSON Reviewed-on: #16 Co-authored-by: Gabriel Radureau <arcodange@gmail.com> Co-committed-by: Gabriel Radureau <arcodange@gmail.com>
246 lines
7.5 KiB
Bash
Executable File
246 lines
7.5 KiB
Bash
Executable File
#!/bin/bash
|
|
|
|
# dance-lessons-coach 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
|
|
SCRIPTS_DIR=$(dirname "$(realpath "${BASH_SOURCE[0]}")")
|
|
PROJECT_DIR=$(dirname "$SCRIPTS_DIR")
|
|
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=== dance-lessons-coach 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 readiness endpoint
|
|
echo "Testing /api/ready:"
|
|
READY_RESPONSE=$(curl -s http://localhost:8080/api/ready)
|
|
echo "Response: $READY_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..."
|
|
|
|
# Send SIGTERM once and probe /api/ready during the 1-second propagation window
|
|
# the server holds open (pkg/server/server.go: time.Sleep(1s) after readiness
|
|
# cancel). Previously the curl fired *before* the signal — it always saw "ready".
|
|
# We also avoid calling "$SERVER_CMD stop" afterwards because that would send a
|
|
# second SIGTERM: after signal.NotifyContext is done, the default handler kicks in
|
|
# and the process terminates with a non-JSON "signal: terminated" on stderr.
|
|
SERVER_PID=$(cat "$PID_FILE" 2>/dev/null || echo "")
|
|
if [[ -z "$SERVER_PID" ]]; then
|
|
echo -e "\033[0;31m❌ FAIL: PID file not found\033[0m"
|
|
exit 1
|
|
fi
|
|
|
|
kill -TERM "$SERVER_PID"
|
|
# Brief yield so the signal handler runs and CancelableContext.Cancel() fires
|
|
sleep 0.2
|
|
READY_DURING_SHUTDOWN=$(curl -s -w "\n[HTTP %{http_code}]" http://localhost:8080/api/ready 2>&1 || echo "[connection refused]")
|
|
echo "Readiness during shutdown: $READY_DURING_SHUTDOWN"
|
|
|
|
# Wait for the process to exit cleanly (up to 30s) without sending another signal
|
|
echo "Waiting for server to exit..."
|
|
for i in {1..30}; do
|
|
if ! ps -p "$SERVER_PID" > /dev/null 2>&1; then
|
|
echo "Server stopped successfully"
|
|
rm -f "$PID_FILE"
|
|
break
|
|
fi
|
|
sleep 1
|
|
done
|
|
if ps -p "$SERVER_PID" > /dev/null 2>&1; then
|
|
echo -e "\033[0;31m❌ FAIL: Server did not stop within 30s\033[0m"
|
|
kill -9 "$SERVER_PID" 2>/dev/null || true
|
|
exit 1
|
|
fi
|
|
sleep 0.5
|
|
|
|
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 readiness logs
|
|
if ! grep -q "Readiness check: ready" "$LOG_FILE"; then
|
|
echo -e "\033[0;31m❌ FAIL: Missing 'Readiness check: ready' log\033[0m"
|
|
exit 1
|
|
fi
|
|
|
|
if ! grep -q "Readiness check: not ready" "$LOG_FILE"; then
|
|
echo -e "\033[0;31m❌ FAIL: Missing 'Readiness check: not ready' log\033[0m"
|
|
exit 1
|
|
fi
|
|
|
|
echo -e "\033[0;32m✅ All readiness 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 set to false" "$LOG_FILE"; then
|
|
echo -e "\033[0;31m❌ FAIL: Missing 'Readiness set to false' 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 "Current log file contents:"
|
|
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 ""
|
|
echo "📋 Full server log:"
|
|
echo "==============================="
|
|
cat "$LOG_FILE" | jq -r '"[\(.level | ascii_upcase)] \(.time | tostring) — \(.message)"'
|
|
echo "==============================="
|
|
echo ""
|
|
|
|
# Clean up
|
|
rm -f "$PID_FILE" "$LOG_FILE"
|
|
|
|
exit 0
|