🐛 fix: emit all config-loading logs in correct JSON format from the start (#16)
## 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>
This commit was merged in pull request #16.
This commit is contained in:
@@ -4,7 +4,8 @@
|
||||
# This script starts the server in the background and provides control functions
|
||||
|
||||
# Configuration
|
||||
PROJECT_DIR="/Users/gabrielradureau/Work/Vibe/dance-lessons-coach"
|
||||
SCRIPTS_DIR=$(dirname "$(realpath "${BASH_SOURCE[0]}")")
|
||||
PROJECT_DIR=$(dirname "$SCRIPTS_DIR")
|
||||
SERVER_CMD="go run ./cmd/server"
|
||||
LOG_FILE="server.log"
|
||||
PID_FILE="server.pid"
|
||||
|
||||
@@ -7,7 +7,8 @@
|
||||
set -e
|
||||
|
||||
# Configuration
|
||||
PROJECT_DIR="/Users/gabrielradureau/Work/Vibe/dance-lessons-coach"
|
||||
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"
|
||||
@@ -59,11 +60,40 @@ echo "Response: $GREET_NAME_RESPONSE"
|
||||
echo ""
|
||||
echo "Stopping server gracefully..."
|
||||
|
||||
# Test readiness during shutdown (in background)
|
||||
(curl -s http://localhost:8080/api/ready > /dev/null 2>&1 &)
|
||||
# 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
|
||||
|
||||
$SERVER_CMD stop
|
||||
sleep 3
|
||||
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..."
|
||||
@@ -201,6 +231,12 @@ 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
|
||||
|
||||
@@ -9,7 +9,8 @@ echo -e "\033[1;34m=== dance-lessons-coach OpenTelemetry Test ===\033[0m"
|
||||
echo ""
|
||||
|
||||
# Configuration
|
||||
PROJECT_DIR="/Users/gabrielradureau/Work/Vibe/dance-lessons-coach"
|
||||
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"
|
||||
|
||||
Reference in New Issue
Block a user