Merge pull request #36 from YASSERRMD/phase_3

phase 3: structured logging (slog) & X-Request-ID middleware

Author: YASSERRMD

cmd/siqlah/main.go

@@ -8,7 +8,7 @@ import (
 	"encoding/hex"
 	"flag"
 	"fmt"
-	"log"
+	"log/slog"
 	"net/http"
 	"os"
 	"os/signal"
@@ -63,6 +63,8 @@ func main() {
 
 	_, _ = *oidcClientID, *oidcIssuer // surfaced for future integration
 
+	slog.SetDefault(slog.New(slog.NewJSONHandler(os.Stdout, &slog.HandlerOptions{Level: slog.LevelInfo})))
+
 	printBanner()
 
 	// Load or generate the operator keypair.
@@ -71,31 +73,33 @@ func main() {
 	if *operatorKeyHex != "" {
 		privBytes, err := hex.DecodeString(*operatorKeyHex)
 		if err != nil || len(privBytes) != ed25519.PrivateKeySize {
-			log.Fatalf("invalid --operator-key: must be %d-byte hex", ed25519.PrivateKeySize)
+			slog.Error("invalid --operator-key", "expected_bytes", ed25519.PrivateKeySize)
+			os.Exit(1)
 		}
 		operatorPriv = ed25519.PrivateKey(privBytes)
 		operatorPub = operatorPriv.Public().(ed25519.PublicKey)
 	} else {
 		var err error
 		operatorPub, operatorPriv, err = ed25519.GenerateKey(rand.Reader)
 		if err != nil {
-			log.Fatalf("generate operator key: %v", err)
+			slog.Error("generate operator key", "error", err)
+			os.Exit(1)
 		}
-		log.Printf("generated operator key (ephemeral — set --operator-key to persist)")
+		slog.Warn("generated ephemeral operator key — set --operator-key to persist across restarts")
 	}
-	log.Printf("operator public key: %s", hex.EncodeToString(operatorPub))
+	slog.Info("operator key loaded", "public_key", hex.EncodeToString(operatorPub))
 
 	// Wire the signing backend.
 	var receiptSigner signing.Signer
 	switch *signingBackend {
 	case "fulcio":
-		log.Printf("signing backend: fulcio (keyless) — OIDC issuer: %s", *oidcIssuer)
+		slog.Info("signing backend: fulcio (keyless)", "oidc_issuer", *oidcIssuer)
 		receiptSigner = signing.NewFulcioSigner(signing.FulcioOptions{
 			FulcioURL: *fulcioURL,
 			RekorURL:  *rekorURL,
 		})
 	default:
-		log.Printf("signing backend: ed25519")
+		slog.Info("signing backend: ed25519")
 		receiptSigner = signing.NewEd25519Signer(operatorPriv)
 	}
 	_ = receiptSigner // passed to API in future integration
@@ -108,17 +112,19 @@ func main() {
 	var builder interface{ BuildAndSign() (*store.Checkpoint, error) }
 
 	if *logBackend == "tessera" {
-		log.Printf("using Tessera backend at %s", *tesseraPath)
+		slog.Info("using Tessera backend", "path", *tesseraPath)
 		ts, err := store.NewTesseraStore(ctx, *dbPath, *tesseraPath, *tesseraLogName, operatorPriv)
 		if err != nil {
-			log.Fatalf("open tessera store: %v", err)
+			slog.Error("open tessera store", "error", err)
+			os.Exit(1)
 		}
 		st = ts
 		builder = checkpoint.NewTesseraBuilder(st, operatorPriv, *maxBatch)
 	} else {
 		sqlite, err := store.Open(*dbPath)
 		if err != nil {
-			log.Fatalf("open store: %v", err)
+			slog.Error("open store", "error", err)
+			os.Exit(1)
 		}
 		st = sqlite
 		builder = checkpoint.NewBuilder(st, operatorPriv, *maxBatch)
@@ -151,9 +157,9 @@ func main() {
 			case <-ticker.C:
 				cp, err := builder.BuildAndSign()
 				if err != nil {
-					log.Printf("batcher: build checkpoint: %v", err)
+					slog.Error("batcher: build checkpoint failed", "error", err)
 				} else if cp != nil {
-					log.Printf("batcher: checkpoint %d built (tree_size=%d)", cp.ID, cp.TreeSize)
+					slog.Info("batcher: checkpoint built", "id", cp.ID, "tree_size", cp.TreeSize)
 				}
 			}
 		}
@@ -163,11 +169,12 @@ func main() {
 	if *rekorAnchor {
 		ra, err := anchor.NewRekorAnchor(*rekorURL)
 		if err != nil {
-			log.Fatalf("create rekor anchor: %v", err)
+			slog.Error("create rekor anchor", "error", err)
+			os.Exit(1)
 		}
 		sched := anchor.NewAnchorScheduler(ra, st, *rekorInterval)
 		go sched.Run(ctx)
-		log.Printf("rekor anchoring enabled: %s every %s", *rekorURL, *rekorInterval)
+		slog.Info("rekor anchoring enabled", "url", *rekorURL, "interval", *rekorInterval)
 	}
 
 	// Optionally start discrepancy monitor.
@@ -199,18 +206,19 @@ func main() {
 	signal.Notify(sigCh, syscall.SIGINT, syscall.SIGTERM)
 	go func() {
 		<-sigCh
-		log.Println("shutting down...")
+		slog.Info("shutting down...")
 		cancel()
 		shutCtx, shutCancel := context.WithTimeout(context.Background(), 10*time.Second)
 		defer shutCancel()
 		if err := httpSrv.Shutdown(shutCtx); err != nil {
-			log.Printf("shutdown: %v", err)
+			slog.Error("graceful shutdown error", "error", err)
 		}
 	}()
 
-	log.Printf("siqlah %s (%s) listening on %s", version, commitSHA, *addr)
+	slog.Info("siqlah listening", "version", version, "commit", commitSHA, "addr", *addr)
 	if err := httpSrv.ListenAndServe(); err != nil && err != http.ErrServerClosed {
-		log.Fatalf("listen: %v", err)
+		slog.Error("listen failed", "error", err)
+		os.Exit(1)
 	}
 }
 
@@ -223,12 +231,12 @@ func parseWitnesses(s string) map[string]ed25519.PublicKey {
 	for _, pair := range strings.Split(s, ",") {
 		parts := strings.SplitN(strings.TrimSpace(pair), "=", 2)
 		if len(parts) != 2 {
-			log.Printf("warning: invalid witness pair %q, expected id=pubhex", pair)
+			slog.Warn("invalid witness pair, expected id=pubhex", "pair", pair)
 			continue
 		}
 		b, err := hex.DecodeString(parts[1])
 		if err != nil || len(b) != ed25519.PublicKeySize {
-			log.Printf("warning: invalid witness pubkey for %q", parts[0])
+			slog.Warn("invalid witness pubkey", "id", parts[0])
 			continue
 		}
 		out[parts[0]] = ed25519.PublicKey(b)

internal/api/ingest.go

@@ -5,7 +5,7 @@ import (
 	"encoding/hex"
 	"encoding/json"
 	"errors"
-	"log"
+	"log/slog"
 	"net/http"
 	"strconv"
 	"time"
@@ -208,7 +208,7 @@ func (s *Server) populateModelIdentity(r *vur.Receipt, bundleJSON string) {
 		bundleJSON, _ = model.ParseBundleFromPEM(bundleJSON)
 		id, err := model.VerifyModelIdentity(bundleJSON, r.Model, model.VerifyOptions{})
 		if err != nil {
-			log.Printf("OMS bundle verification failed for model %q: %v", r.Model, err)
+			slog.Warn("OMS bundle verification failed", "model", r.Model, "error", err)
 			return
 		}
 		r.ModelSignerIdentity = id.SignerIdentity

internal/api/server.go

@@ -1,9 +1,12 @@
 package api
 
 import (
+	"context"
 	"crypto/ed25519"
+	"crypto/rand"
+	"encoding/hex"
 	"encoding/json"
-	"log"
+	"log/slog"
 	"net/http"
 	"time"
 
@@ -15,6 +18,10 @@ import (
 	"github.com/yasserrmd/siqlah/pkg/vur"
 )
 
+type contextKey string
+
+const requestIDKey contextKey = "request_id"
+
 // Server is the HTTP API server for siqlah.
 type Server struct {
 	store           store.Store
@@ -147,18 +154,40 @@ func (s *Server) Routes() *http.ServeMux {
 	return mux
 }
 
-// Handler returns the root handler with logging and CORS middleware applied.
+// Handler returns the root handler with request-ID, logging, and CORS middleware applied.
 func (s *Server) Handler() http.Handler {
-	return corsMiddleware(loggingMiddleware(s.Routes()))
+	return corsMiddleware(requestIDMiddleware(loggingMiddleware(s.Routes())))
+}
+
+// requestIDMiddleware attaches a unique X-Request-ID to each request context and response header.
+func requestIDMiddleware(next http.Handler) http.Handler {
+	return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
+		id := r.Header.Get("X-Request-ID")
+		if id == "" {
+			var buf [8]byte
+			_, _ = rand.Read(buf[:])
+			id = hex.EncodeToString(buf[:])
+		}
+		w.Header().Set("X-Request-ID", id)
+		ctx := context.WithValue(r.Context(), requestIDKey, id)
+		next.ServeHTTP(w, r.WithContext(ctx))
+	})
 }
 
-// loggingMiddleware logs each request method, path, and duration.
+// loggingMiddleware logs each request method, path, status code, and duration using slog.
 func loggingMiddleware(next http.Handler) http.Handler {
 	return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
 		start := time.Now()
 		rw := &responseWriter{ResponseWriter: w, code: http.StatusOK}
 		next.ServeHTTP(rw, r)
-		log.Printf("%s %s %d %s", r.Method, r.URL.Path, rw.code, time.Since(start))
+		reqID, _ := r.Context().Value(requestIDKey).(string)
+		slog.Info("request",
+			"method", r.Method,
+			"path", r.URL.Path,
+			"status", rw.code,
+			"duration_ms", time.Since(start).Milliseconds(),
+			"request_id", reqID,
+		)
 	})
 }
 
@@ -167,7 +196,7 @@ func corsMiddleware(next http.Handler) http.Handler {
 	return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
 		w.Header().Set("Access-Control-Allow-Origin", "*")
 		w.Header().Set("Access-Control-Allow-Methods", "GET, POST, OPTIONS")
-		w.Header().Set("Access-Control-Allow-Headers", "Content-Type, Authorization")
+		w.Header().Set("Access-Control-Allow-Headers", "Content-Type, Authorization, X-Request-ID")
 		if r.Method == http.MethodOptions {
 			w.WriteHeader(http.StatusNoContent)
 			return