fix(audit): keep the row when the actor id is not a UUID

README.md

@@ -10,7 +10,7 @@ Vault42 issues its own tokens and is an OAuth2 *client* of other providers. It i
 | ![Go](https://img.shields.io/badge/Go-1.26.6-00ADD8?style=flat&logo=go&logoColor=white) | ![Vue](https://img.shields.io/badge/Vue-3.5.41-4FC08D?style=flat&logo=vuedotjs&logoColor=white) | ![.NET](https://img.shields.io/badge/.NET-10.0-512BD4?style=flat&logo=dotnet&logoColor=white) | ![License](https://img.shields.io/badge/License-MIT-155724?style=flat&labelColor=000) |
 | ![Go Tests](https://img.shields.io/badge/Tests-4910-155724?style=flat&labelColor=000) | ![Vue Tests](https://img.shields.io/badge/Tests-1305-155724?style=flat&labelColor=000) | ![C# Tests](https://img.shields.io/badge/Tests-264-155724?style=flat&labelColor=000) | ![Total](https://img.shields.io/badge/Total-6479_tests-155724?style=flat&labelColor=000) |
 | ![Go Coverage](https://img.shields.io/badge/Coverage-100.00%25_reachable-155724?style=flat&labelColor=000) | ![Vue Coverage](https://img.shields.io/badge/Coverage-99.76%25-155724?style=flat&labelColor=000) | ![C# Coverage](https://img.shields.io/badge/Coverage-100.00%25-155724?style=flat&labelColor=000) | ![Locales](https://img.shields.io/badge/Locales-38-555?style=flat&labelColor=000) |
-| ![Go Lines](https://img.shields.io/badge/Lines-48129-555?style=flat&labelColor=000) | ![Vue Lines](https://img.shields.io/badge/Lines-6800-555?style=flat&labelColor=000) | ![C# Lines](https://img.shields.io/badge/Lines-2435-555?style=flat&labelColor=000) | ![Standards](https://img.shields.io/badge/Standards-11-555?style=flat&labelColor=000) |
+| ![Go Lines](https://img.shields.io/badge/Lines-48229-555?style=flat&labelColor=000) | ![Vue Lines](https://img.shields.io/badge/Lines-6800-555?style=flat&labelColor=000) | ![C# Lines](https://img.shields.io/badge/Lines-2435-555?style=flat&labelColor=000) | ![Standards](https://img.shields.io/badge/Standards-11-555?style=flat&labelColor=000) |
 | ![Go Deps](https://img.shields.io/badge/Deps-3-555?style=flat&labelColor=000) | ![Vue Deps](https://img.shields.io/badge/Deps-3-555?style=flat&labelColor=000) | ![C# Deps](https://img.shields.io/badge/Deps-6-555?style=flat&labelColor=000) | ![Requirements](https://img.shields.io/badge/Requirements-456-555?style=flat&labelColor=000) |
 | ![Go Transitive Deps](https://img.shields.io/badge/Transitive-15-555?style=flat&labelColor=000) | ![Vue Transitive Deps](https://img.shields.io/badge/Transitive-95-555?style=flat&labelColor=000) | ![C# Transitive Deps](https://img.shields.io/badge/Transitive-26-555?style=flat&labelColor=000) | ![Total Deps](https://img.shields.io/badge/Deps-148_total-555?style=flat&labelColor=000) |
 <!-- /badges -->

docs/badges.json

@@ -9,8 +9,8 @@
   "reachableCoverageNum": 100.00,
   "packages": 43,
   "goFiles": 192,
-  "goLines": 48129,
-  "testFiles": 927,
+  "goLines": 48229,
+  "testFiles": 928,
   "directDeps": 3,
   "transitiveDeps": 15,
   "totalTests": 6479,
@@ -20,7 +20,7 @@
       "tests": 4910,
       "coverage": "100.00% of reachable",
       "coverageNum": 100.00,
-      "lines": 48129,
+      "lines": 48229,
       "deps": 3,
       "transitiveDeps": 15
     },

internal/repository/postgres/audit.go

@@ -3,6 +3,7 @@ package postgres
 import (
 	"context"
 	"fmt"
+	"regexp"
 	"strings"
 	"time"
 
@@ -20,16 +21,114 @@ func NewAuditRepo(db *DB) *AuditRepo {
 	return &AuditRepo{db: db}
 }
 
+// actorHex matches a uuid with its punctuation already removed. The columns
+// render canonically -- 8-4-4-4-12, lower case -- but that is not what the type
+// accepts on input, and the difference is the whole point of this file.
+//
+// PostgreSQL 8.12 accepts upper case, the canonical form wrapped in braces, and
+// hyphens omitted or added after any group of four digits, and normalises every
+// one of them to the same sixteen bytes. So `Guid.ToString("N")` -- .NET's
+// dashless rendering, and therefore the one a .NET relying party is most likely
+// to send -- is a uuid the column already holds, indexes and returns dashed.
+// Testing the caller's *shape* would refuse a value the database accepts.
+var actorHex = regexp.MustCompile(`^[0-9a-fA-F]{32}$`)
+
+// canonicalActorUUID renders an id the uuid type would accept in the form the
+// column returns, and reports false for one it would not.
+//
+// It accepts a little more than PostgreSQL does, because it emits the canonical
+// form rather than the caller's string: a hyphen in a place the server would
+// refuse still leaves 32 hex digits naming a uuid, and what reaches the column
+// is the canonical rendering of it either way. Over-acceptance here cannot
+// produce a value the column rejects, whereas under-acceptance silently detaches
+// a row from its subject, which is the defect this file exists to fix.
+func canonicalActorUUID(id string) (string, bool) {
+	t := strings.TrimSpace(id)
+	if len(t) > 1 && t[0] == '{' && t[len(t)-1] == '}' {
+		t = t[1 : len(t)-1]
+	}
+	t = strings.ToLower(strings.ReplaceAll(t, "-", ""))
+	if !actorHex.MatchString(t) {
+		return "", false
+	}
+	return t[0:8] + "-" + t[8:12] + "-" + t[12:16] + "-" + t[16:20] + "-" + t[20:32], true
+}
+
+// Keys a rejected actor id is kept under. Prefixed so they cannot collide with
+// a key a call site already uses, and named for what they hold.
+const (
+	rawUserIDKey   = "actor_user_id_raw"
+	rawClientIDKey = "actor_client_id_raw"
+)
+
+// actorColumns returns the values the actor columns should carry, moving an id
+// the uuid type cannot hold into metadata instead of losing the whole row.
+//
+// user_id and client_id are UUID in the schema (001) and string in the model,
+// and three call sites pass a value the caller chose: the submitted client_id
+// on a failed client auth, and the asserted subject on /mint and on a service
+// document. A non-UUID there does not produce a row with an odd value in it --
+// there is no row at all. pgx is not what refuses it: chooseParameterFormatCode
+// returns TextFormatCode for any string before the oid is consulted, so the
+// value goes out as text and the server's parser is the acceptor. The caller
+// then discards the error, correctly, because auditing must never block
+// authentication. So
+// the events most worth having are the ones most likely to vanish: a credential
+// spray sends client_id=admin, not a UUID, which is exactly the case the
+// comment above auditClientAuthFailure says the audit exists to catch.
+//
+// This belongs here rather than in audit.Logger. The constraint is the column's,
+// and only this package knows the column. Normalising in the logger would change
+// the shape of every AuditEntry in the process to satisfy a rule that applies at
+// one boundary, and every mock repository in the test suite would keep accepting
+// what the real one rejects -- which is how this survived in the first place.
+//
+// The claimed value is not discarded. It moves into metadata, which is JSONB and
+// takes any string, so the row still records who the caller said they were.
+func actorColumns(e *model.AuditEntry) (userID, clientID string, metadata map[string]interface{}) {
+	userID, clientID, metadata = e.UserID, e.ClientID, e.Metadata
+
+	userOK, clientOK := true, true
+	if userID != "" {
+		userID, userOK = canonicalActorUUID(userID)
+	}
+	if clientID != "" {
+		clientID, clientOK = canonicalActorUUID(clientID)
+	}
+	if userOK && clientOK {
+		return userID, clientID, metadata
+	}
+
+	// Copied, never mutated: the entry belongs to the caller, and a batch retry
+	// must not accumulate keys.
+	out := make(map[string]interface{}, len(metadata)+2)
+	for k, v := range metadata {
+		out[k] = v
+	}
+	// The claim is kept as the caller wrote it, not as anything normalised it:
+	// the point of the key is to record what was asserted.
+	if !userOK {
+		out[rawUserIDKey] = e.UserID
+		userID = ""
+	}
+	if !clientOK {
+		out[rawClientIDKey] = e.ClientID
+		clientID = ""
+	}
+	return userID, clientID, out
+}
+
 // Insert writes a single entry to the audit.audit_log table.
 func (r *AuditRepo) Insert(ctx context.Context, entry *model.AuditEntry) error {
+	auditUserID, auditClientID, auditMetadata := actorColumns(entry)
 	_, err := r.db.Pool.Exec(ctx, `
 		INSERT INTO audit.audit_log (id, timestamp, event_type, user_id, client_id, ip, user_agent, fingerprint_hash, device_id, metadata, risk_score)
 		VALUES ($1, $2, $3, $4, $5, $6, $7, $8, $9, $10, $11)`,
 		entry.ID, entry.Timestamp, entry.EventType,
-		nullStr(entry.UserID), nullStr(entry.ClientID),
+		nullStr(auditUserID), nullStr(auditClientID),
 		nullStr(entry.IP), nullStr(entry.UserAgent),
 		nullStr(entry.FingerprintHash), nullStr(entry.DeviceID),
-		entry.Metadata, entry.RiskScore,
+		auditMetadata, entry.RiskScore,
 	)
 	if err != nil {
 		return fmt.Errorf("insert audit entry: %w", err)
@@ -46,14 +145,15 @@ func (r *AuditRepo) InsertBatch(ctx context.Context, entries []*model.AuditEntry
 	defer func() { _ = tx.Rollback(ctx) }() // rollback after commit is a no-op
 
 	for _, e := range entries {
+		batchUserID, batchClientID, batchMetadata := actorColumns(e)
 		_, err := tx.Exec(ctx, `
 			INSERT INTO audit.audit_log (id, timestamp, event_type, user_id, client_id, ip, user_agent, fingerprint_hash, device_id, metadata, risk_score)
 			VALUES ($1, $2, $3, $4, $5, $6, $7, $8, $9, $10, $11)`,
 			e.ID, e.Timestamp, e.EventType,
-			nullStr(e.UserID), nullStr(e.ClientID),
+			nullStr(batchUserID), nullStr(batchClientID),
 			nullStr(e.IP), nullStr(e.UserAgent),
 			nullStr(e.FingerprintHash), nullStr(e.DeviceID),
-			e.Metadata, e.RiskScore,
+			batchMetadata, e.RiskScore,
 		)
 		if err != nil {
 			return fmt.Errorf("insert audit batch entry: %w", err)

internal/repository/postgres/audit_actor_uuid_test.go

@@ -0,0 +1,207 @@
+package postgres
+
+import (
+	"context"
+	"testing"
+	"time"
+
+	vaultcrypto "github.com/42-v/vault42/internal/crypto"
+	"github.com/42-v/vault42/internal/model"
+)
+
+// The audit actor columns are UUID in the schema and string in Go, and three
+// call sites pass a value the caller chose: the submitted client_id on a failed
+// client auth, and the asserted subject on /mint and on a service document.
+//
+// This is the mechanism behind that, measured against a real PostgreSQL rather
+// than argued: an actor id that is not a UUID does not produce a row with an
+// odd value in it. It produces no row. The caller then discards the error,
+// because auditing is best-effort and must never block authentication, so the
+// event disappears with nothing anywhere recording that it did.
+//
+// Which events? The ones a caller controls. A credential spray sends
+// client_id=admin, not a UUID. That is precisely the case the comment above
+// auditClientAuthFailure says the audit exists to catch.
+//
+// actorColumns is what keeps the row: it blanks the column and moves the
+// claimed value into metadata. It lives in this package, not in audit.Logger,
+// for the reason audit.go gives -- the constraint is the column's.
+//
+// The second half is the other direction, and it is the half only a real
+// PostgreSQL can settle: an id the uuid type accepts must reach the column
+// unblanked, in every rendering the type accepts, and stay findable by the
+// canonical one. That is what makes a shape test the wrong instrument.
+func TestAuditRepo_ANonUUIDActorIsRejectedByTheColumn(t *testing.T) {
+	svcDocRequireContainerRuntime(t)
+	db := svcDocPostgres(t)
+	repo := NewAuditRepo(db)
+	ctx := context.Background()
+
+	id, err := vaultcrypto.RandomUUID()
+	if err != nil {
+		t.Fatalf("uuid: %v", err)
+	}
+
+	// What the call sites used to hand over.
+	poisoned := &model.AuditEntry{
+		ID:        id,
+		Timestamp: time.Now(),
+		EventType: "client_auth",
+		ClientID:  "admin",
+		IP:        "203.0.113.9",
+		Metadata:  map[string]interface{}{"result": "failure", "reason": "unknown_client"},
+	}
+	// Straight at the column, bypassing the repository, because the repository
+	// is what stops this now. If this ever succeeds, the schema changed and
+	// actorColumns is guarding a constraint that no longer exists.
+	_, rawErr := db.Pool.Exec(ctx,
+		`INSERT INTO audit.audit_log (id, timestamp, event_type, client_id) VALUES ($1, $2, $3, $4)`,
+		poisoned.ID, poisoned.Timestamp, poisoned.EventType, "admin")
+	if rawErr == nil {
+		t.Fatal("a non-UUID client_id was accepted by the uuid column; the schema changed " +
+			"and actorColumns is guarding a constraint that no longer exists")
+	}
+	t.Logf("the column refuses it: %v", rawErr)
+
+	// And through the repository it lands, which is the fix.
+	if err := repo.Insert(ctx, poisoned); err != nil {
+		t.Fatalf("the repository did not rescue the row: %v", err)
+	}
+	var rescued string
+	if err := db.Pool.QueryRow(ctx,
+		`SELECT metadata->>'actor_client_id_raw' FROM audit.audit_log WHERE id = $1`,
+		poisoned.ID).Scan(&rescued); err != nil {
+		t.Fatalf("read back the rescued row: %v", err)
+	}
+	if rescued != "admin" {
+		t.Fatalf("metadata actor_client_id_raw = %q, want the value the caller claimed", rescued)
+	}
+
+	// The other direction: a dashless uuid is what .NET's Guid.ToString("N")
+	// produces, mintSubjectRe admits it, and PostgreSQL's uuid parser accepts it
+	// and stores the same sixteen bytes as the dashed form. So the row must keep
+	// its actor, and must still be found by the canonical spelling -- which is
+	// what CountByUser and the Art. 15 export both search by.
+	id2, err := vaultcrypto.RandomUUID()
+	if err != nil {
+		t.Fatalf("uuid: %v", err)
+	}
+	if err := repo.Insert(ctx, &model.AuditEntry{
+		ID:        id2,
+		Timestamp: time.Now(),
+		EventType: "mint",
+		UserID:    "7e2f9a102222400080000000000000ab",
+		IP:        "203.0.113.9",
+		Metadata:  map[string]interface{}{"result": "success"},
+	}); err != nil {
+		t.Fatalf("a dashless uuid was refused: %v", err)
+	}
+
+	var stored string
+	if err := db.Pool.QueryRow(ctx,
+		`SELECT user_id::text FROM audit.audit_log WHERE id = $1`, id2).Scan(&stored); err != nil {
+		t.Fatalf("read back the dashless row: %v", err)
+	}
+	if stored != "7e2f9a10-2222-4000-8000-0000000000ab" {
+		t.Fatalf("user_id = %q, want the canonical rendering of the same uuid. A blank "+
+			"here is the regression: the row is in the table but no longer attributed, "+
+			"and an append-only table cannot be repaired.", stored)
+	}
+
+	n, err := repo.CountByUser(ctx, "7e2f9a10-2222-4000-8000-0000000000ab")
+	if err != nil {
+		t.Fatalf("CountByUser: %v", err)
+	}
+	if n == 0 {
+		t.Fatal("CountByUser found nothing for the canonical spelling of an id that was " +
+			"written dashless, so the subject's own export would miss the row")
+	}
+}
+
+// actorColumns is pure, so it is tested without a container. The behavior that
+// matters is that every rendering the uuid type accepts reaches the column, and
+// that a value it does not accept still leaves a row behind.
+func TestActorColumns(t *testing.T) {
+	const (
+		ok       = "7e2f9a10-2222-4000-8000-0000000000ab"
+		upper    = "7E2F9A10-2222-4000-8000-0000000000AB"
+		dashless = "7e2f9a102222400080000000000000ab"
+		braced   = "{7e2f9a10-2222-4000-8000-0000000000ab}"
+		spaced   = "7e2f9a10-2222-4000-8000-0000000000 ab"
+		short    = "7e2f9a10-2222-4000-8000-0000000000a"
+	)
+	cases := []struct {
+		name, user, client   string
+		wantUser, wantClient string
+		wantUserRaw          bool
+		wantClientRaw        bool
+	}{
+		{"both valid, untouched", ok, ok, ok, ok, false, false},
+		{"both empty", "", "", "", "", false, false},
+		{"a spray's client id", "", "admin", "", "", false, true},
+		{"a legacy mint subject", "legacy-user-77", "", "", "", true, false},
+		{"both bad", "u", "c", "", "", true, true},
+
+		// Every one of these is a uuid the column already holds, indexes, and
+		// returns dashed. A shape test blanked them into metadata, which
+		// detached existing rows from their subject -- and the dashless case is
+		// what .NET writes by default, on the platform this release is for.
+		{"uppercase is canonicalised", upper, "", ok, "", false, false},
+		{"dashless, as Guid.ToString N writes it", dashless, "", ok, "", false, false},
+		{"braced", braced, "", ok, "", false, false},
+		{"either column is canonicalised", dashless, upper, ok, ok, false, false},
+
+		// Acceptance stops at 32 hex digits: a space is not punctuation the
+		// parser skips, and a digit short is not a uuid.
+		{"a space is not punctuation", spaced, "", "", "", true, false},
+		{"one digit short", short, "", "", "", true, false},
+	}
+	for _, tc := range cases {
+		t.Run(tc.name, func(t *testing.T) {
+			e := &model.AuditEntry{
+				UserID: tc.user, ClientID: tc.client,
+				Metadata: map[string]interface{}{"reason": "unknown_client"},
+			}
+			u, c, md := actorColumns(e)
+			if u != tc.wantUser || c != tc.wantClient {
+				t.Fatalf("got user=%q client=%q, want %q/%q", u, c, tc.wantUser, tc.wantClient)
+			}
+			if _, ok := md[rawUserIDKey]; ok != tc.wantUserRaw {
+				t.Errorf("%s present = %v, want %v", rawUserIDKey, ok, tc.wantUserRaw)
+			}
+			if _, ok := md[rawClientIDKey]; ok != tc.wantClientRaw {
+				t.Errorf("%s present = %v, want %v", rawClientIDKey, ok, tc.wantClientRaw)
+			}
+			// A rejected id is kept as the caller wrote it, not as anything
+			// normalised it: the key records what was asserted.
+			if tc.wantUserRaw && md[rawUserIDKey] != tc.user {
+				t.Errorf("%s = %v, want the claimed value %q", rawUserIDKey, md[rawUserIDKey], tc.user)
+			}
+			if tc.wantClientRaw && md[rawClientIDKey] != tc.client {
+				t.Errorf("%s = %v, want the claimed value %q", rawClientIDKey, md[rawClientIDKey], tc.client)
+			}
+			if md["reason"] != "unknown_client" {
+				t.Errorf("the caller's metadata was lost: %v", md)
+			}
+			// The entry belongs to the caller; a batch retry must not accumulate keys.
+			if _, ok := e.Metadata[rawUserIDKey]; ok {
+				t.Error("the caller's map was mutated")
+			}
+			if _, ok := e.Metadata[rawClientIDKey]; ok {
+				t.Error("the caller's map was mutated")
+			}
+		})
+	}
+}
+
+// A nil metadata map on a poisoned entry must still produce a map, not a panic.
+func TestActorColumns_NilMetadata(t *testing.T) {
+	e := &model.AuditEntry{ClientID: "admin"}
+	_, c, md := actorColumns(e)
+	if c != "" {
+		t.Fatalf("client = %q, want blank", c)
+	}
+	if md[rawClientIDKey] != "admin" {
+		t.Fatalf("metadata = %v", md)
+	}
+}

internal/repository/postgres/wire_failure_test.go

@@ -139,7 +139,12 @@ func TestAuditRepo_RefusedCommitLosesTheBatchLoudly(t *testing.T) {
 	)
 
 	err := NewAuditRepo(db).InsertBatch(context.Background(), []*model.AuditEntry{
-		{ID: "a-1", Timestamp: time.Now(), EventType: "login_success", UserID: "u-1"},
+		// A real uuid, because this test is about a refused COMMIT and nothing
+		// else. With a non-uuid actor id, actorColumns moves the value into
+		// metadata, and this harness cannot encode a map -- so the batch would
+		// fail before reaching the commit and the test would pass for the wrong
+		// reason.
+		{ID: "a-1", Timestamp: time.Now(), EventType: "login_success", UserID: "7e2f9a10-2222-4000-8000-0000000000ab"},
 	})
 	if err == nil {
 		t.Fatal("InsertBatch reported the batch written after the commit was refused")