Log run request signature diagnostics

platform/service/control.go

@@ -7,6 +7,7 @@ import (
 	"encoding/hex"
 	"errors"
 	"fmt"
+	"log"
 	"strconv"
 	"strings"
 	"time"
@@ -400,25 +401,30 @@ func (svc *CoreService) AuthorizeRunRequestSignature(request domain.RunRequestSi
 
 	session, err := svc.currentRunSession(request.RunEndpointID, request.SessionToken)
 	if err != nil {
+		logRunSignatureFailure(request, "session_invalid", err)
 		return err
 	}
 	if strings.TrimSpace(request.Signature) == "" && !session.RequireSignedRequests {
 		return nil
 	}
 	if strings.TrimSpace(request.Timestamp) == "" || strings.TrimSpace(request.Nonce) == "" || strings.TrimSpace(request.Signature) == "" {
+		logRunSignatureFailure(request, "missing_signed_header", nil)
 		return runAuthenticationError(true)
 	}
 	unixSeconds, err := strconv.ParseInt(request.Timestamp, 10, 64)
 	if err != nil {
+		logRunSignatureFailure(request, "bad_timestamp", err)
 		return runAuthenticationError(true)
 	}
 	stamp := time.Unix(unixSeconds, 0).UTC()
 	delta := svc.now().Sub(stamp)
 	if delta < -maxRunRequestClockSkew || delta > maxRunRequestClockSkew {
+		logRunSignatureFailure(request, fmt.Sprintf("clock_skew_%dms", delta.Milliseconds()), nil)
 		return runAuthenticationError(true)
 	}
 	session.UsedNonces = activeRunNonces(session.UsedNonces, svc.now().Add(-maxRunRequestClockSkew))
 	if len(request.Nonce) > 128 || runNonceSeen(session.UsedNonces, request.Nonce) || len(session.UsedNonces) >= maxRunRequestNonces {
+		logRunSignatureFailure(request, "nonce_replay_or_limit", nil)
 		return runAuthenticationError(true)
 	}
 	canonical := strings.Join([]string{request.Method, request.Path, request.Timestamp, request.Nonce, request.BodyHash}, "\n")
@@ -427,17 +433,48 @@ func (svc *CoreService) AuthorizeRunRequestSignature(request domain.RunRequestSi
 	expected := hex.EncodeToString(mac.Sum(nil))
 	provided, err := hex.DecodeString(request.Signature)
 	if err != nil || subtle.ConstantTimeCompare([]byte(expected), []byte(hex.EncodeToString(provided))) != 1 {
+		logRunSignatureFailure(request, "signature_mismatch", err)
 		return runAuthenticationError(true)
 	}
 	session.UsedNonces = append(session.UsedNonces, request.Timestamp+":"+request.Nonce)
 	session.UpdatedAt = svc.now()
 	if err := svc.store.RunControlSessions().Update(session); err != nil {
+		logRunSignatureFailure(request, "session_update_failed", err)
 		return err
 	}
 	svc.runSessions[request.RunEndpointID] = session
+	logRunSignatureAccepted(request)
 	return nil
 }
 
+func logRunSignatureAccepted(request domain.RunRequestSignature) {
+	log.Printf("PLATFORM phase=run_signature status=accepted endpoint=%s method=%s path=%s timestamp=%s nonce=%s bodyHash=%s signature=%s", safeLogValue(request.RunEndpointID), safeLogValue(request.Method), safeLogValue(request.Path), safeLogValue(request.Timestamp), shortLogValue(request.Nonce), shortLogValue(request.BodyHash), shortLogValue(request.Signature))
+}
+
+func logRunSignatureFailure(request domain.RunRequestSignature, reason string, err error) {
+	message := ""
+	if err != nil {
+		message = " error=" + safeLogValue(err.Error())
+	}
+	log.Printf("PLATFORM phase=run_signature status=failed reason=%s endpoint=%s method=%s path=%s timestamp=%s nonce=%s bodyHash=%s signature=%s%s", safeLogValue(reason), safeLogValue(request.RunEndpointID), safeLogValue(request.Method), safeLogValue(request.Path), safeLogValue(request.Timestamp), shortLogValue(request.Nonce), shortLogValue(request.BodyHash), shortLogValue(request.Signature), message)
+}
+
+func safeLogValue(value string) string {
+	value = strings.TrimSpace(value)
+	if value == "" {
+		return "-"
+	}
+	return strings.NewReplacer("\n", " ", "\r", " ", "\t", " ").Replace(value)
+}
+
+func shortLogValue(value string) string {
+	value = safeLogValue(value)
+	if value == "-" || len(value) <= 16 {
+		return value
+	}
+	return value[:12] + "..." + value[len(value)-4:]
+}
+
 func activeRunNonces(entries []string, cutoff time.Time) []string {
 	active := make([]string, 0, len(entries))
 	for _, entry := range entries {