package audit import ( "database/sql" "errors" "fmt" "net/url" "os" "path/filepath" "strings" "sync" "testing" "time" _ "modernc.org/sqlite" ) type legacyAuditFixtureRow struct { id string timestamp any user any signature any } func createLegacyAuditFixture( t *testing.T, dataDir string, rows []legacyAuditFixtureRow, ) string { t.Helper() auditDir := filepath.Join(dataDir, "audit") if err := os.MkdirAll(auditDir, 0o700); err != nil { t.Fatalf("create legacy audit directory: %v", err) } dbPath := filepath.Join(auditDir, "audit.db") db, err := sql.Open("sqlite", dbPath) if err != nil { t.Fatalf("open legacy audit database: %v", err) } defer db.Close() if _, err := db.Exec(` CREATE TABLE audit_events ( id TEXT PRIMARY KEY, timestamp DATETIME NOT NULL, event_type TEXT NOT NULL, user TEXT, ip TEXT, path TEXT, success INTEGER NOT NULL, details TEXT, signature TEXT, created_at DATETIME DEFAULT CURRENT_TIMESTAMP ); CREATE INDEX idx_audit_timestamp ON audit_events(timestamp); `); err != nil { t.Fatalf("create legacy audit schema: %v", err) } for _, row := range rows { if _, err := db.Exec(` INSERT INTO audit_events (id, timestamp, event_type, user, ip, path, success, details, signature) VALUES (?, ?, 'startup', ?, '127.0.0.1', '/api/audit', 1, 'fixture', ?)`, row.id, row.timestamp, row.user, row.signature, ); err != nil { t.Fatalf("insert legacy row %q: %v", row.id, err) } } return dbPath } func TestSQLiteLoggerMigratesLegacySchemaAndQueryContract(t *testing.T) { dataDir := t.TempDir() now := time.Now().UTC().Truncate(time.Second) old := now.AddDate(0, 0, -120) recent := now.Add(-time.Hour) sameSecond := now.Add(-30 * time.Minute) dbPath := createLegacyAuditFixture(t, dataDir, []legacyAuditFixtureRow{ { id: "legacy-old", timestamp: old.Format("2006-01-02 15:04:05 -0700 MST") + " m=+0.009025344", user: nil, signature: nil, }, {id: "legacy-recent", timestamp: recent, user: "alice", signature: "legacy-signature"}, {id: "same-a", timestamp: sameSecond, user: "alice", signature: "legacy-signature"}, {id: "same-z", timestamp: sameSecond, user: "alice", signature: "legacy-signature"}, }) logger, err := NewSQLiteLogger(SQLiteLoggerConfig{ DataDir: dataDir, CryptoMgr: newMockCryptoManager(), RetentionDays: 30, }) if err != nil { t.Fatalf("migrate legacy logger: %v", err) } start := now.Add(-2 * time.Hour) events, total, err := logger.QueryPage(QueryFilter{ StartTime: &start, User: "alice", Limit: 10, }) if err != nil { t.Fatalf("query migrated page: %v", err) } if total != 3 || len(events) != 3 { t.Fatalf("migrated page = %d events, total %d, want 3/3", len(events), total) } if events[0].ID != "same-z" || events[1].ID != "same-a" || events[2].ID != "legacy-recent" { t.Fatalf("deterministic order = %v", []string{events[0].ID, events[1].ID, events[2].ID}) } var timestampType string var timestampNotNull int rows, err := logger.db.Query(`PRAGMA table_info(audit_events)`) if err != nil { t.Fatalf("read migrated schema: %v", err) } for rows.Next() { var position, primaryKey int var name, columnType string var notNull int var defaultValue any if err := rows.Scan( &position, &name, &columnType, ¬Null, &defaultValue, &primaryKey, ); err != nil { t.Fatalf("scan migrated schema: %v", err) } if name == "timestamp" { timestampType = columnType timestampNotNull = notNull } } if err := rows.Close(); err != nil { t.Fatalf("close schema rows: %v", err) } if timestampType != "INTEGER" || timestampNotNull != 1 { t.Fatalf("timestamp schema = %q/%d, want INTEGER/1", timestampType, timestampNotNull) } var nonInteger int if err := logger.db.QueryRow( `SELECT COUNT(*) FROM audit_events WHERE typeof(timestamp) != 'integer'`, ).Scan(&nonInteger); err != nil { t.Fatalf("count non-integer timestamps: %v", err) } if nonInteger != 0 { t.Fatalf("non-integer timestamps = %d, want 0", nonInteger) } var schemaVersion int if err := logger.db.QueryRow(`SELECT MAX(version) FROM schema_version`).Scan(&schemaVersion); err != nil { t.Fatalf("read schema version: %v", err) } if schemaVersion != auditSchemaVersion { t.Fatalf("schema version = %d, want %d", schemaVersion, auditSchemaVersion) } logger.cleanupOldEvents() oldEvents, err := logger.Query(QueryFilter{ID: "legacy-old"}) if err != nil { t.Fatalf("query retained legacy row: %v", err) } if len(oldEvents) != 0 { t.Fatal("legacy row older than retention window was not removed") } cleanupEvents, err := logger.Query(QueryFilter{EventType: "audit_cleanup", Limit: 1}) if err != nil || len(cleanupEvents) != 1 { t.Fatalf("cleanup event = %d, err %v", len(cleanupEvents), err) } if !logger.VerifySignature(cleanupEvents[0]) { t.Fatal("cleanup event must carry a valid signature") } if err := logger.Close(); err != nil { t.Fatalf("close migrated logger: %v", err) } restarted, err := NewSQLiteLogger(SQLiteLoggerConfig{ DataDir: dataDir, CryptoMgr: newMockCryptoManager(), RetentionDays: 30, }) if err != nil { t.Fatalf("restart migrated logger: %v", err) } defer restarted.Close() if got := restarted.dbPath; got != dbPath { t.Fatalf("restart database path = %q, want %q", got, dbPath) } } func TestSQLiteLoggerEmptyQueryReturnsArrayShape(t *testing.T) { logger, err := NewSQLiteLogger(SQLiteLoggerConfig{ DataDir: t.TempDir(), CryptoMgr: newMockCryptoManager(), }) if err != nil { t.Fatalf("NewSQLiteLogger: %v", err) } defer logger.Close() events, total, err := logger.QueryPage(QueryFilter{Limit: 100}) if err != nil { t.Fatalf("QueryPage: %v", err) } if events == nil || len(events) != 0 || total != 0 { t.Fatalf("empty page = %#v, total %d, want non-nil empty/0", events, total) } } func TestSQLiteLoggerLegacyMigrationRollsBackMalformedRows(t *testing.T) { dataDir := t.TempDir() const sensitiveValue = "customer-secret-invalid-timestamp" dbPath := createLegacyAuditFixture(t, dataDir, []legacyAuditFixtureRow{ {id: "valid", timestamp: time.Now().UTC(), user: "alice", signature: nil}, {id: "invalid", timestamp: sensitiveValue, user: "bob", signature: nil}, }) logger, err := NewSQLiteLogger(SQLiteLoggerConfig{ DataDir: dataDir, CryptoMgr: newMockCryptoManager(), }) if logger != nil || err == nil { t.Fatal("malformed legacy row must fail logger initialization") } if !IsStoreUnavailableError(err) { t.Fatalf("malformed row error must be store unavailable: %v", err) } if strings.Contains(err.Error(), sensitiveValue) { t.Fatalf("malformed row error leaked stored value: %v", err) } db, openErr := sql.Open("sqlite", dbPath) if openErr != nil { t.Fatalf("reopen rolled-back database: %v", openErr) } defer db.Close() var tableType string if err := db.QueryRow(` SELECT type FROM pragma_table_info('audit_events') WHERE name = 'timestamp' `).Scan(&tableType); err != nil { t.Fatalf("read rolled-back schema: %v", err) } if tableType != "DATETIME" { t.Fatalf("migration was partially applied, timestamp type = %q", tableType) } var scratchTables int if err := db.QueryRow(` SELECT COUNT(*) FROM sqlite_master WHERE type = 'table' AND name = 'audit_events_v2' `).Scan(&scratchTables); err != nil { t.Fatalf("check migration scratch table: %v", err) } if scratchTables != 0 { t.Fatal("migration scratch table survived rollback") } } func TestSQLiteLoggerMigratesLargeLegacyHistory(t *testing.T) { dataDir := t.TempDir() const rowCount = auditTimestampMigrationBatchSize*4 + 17 rows := make([]legacyAuditFixtureRow, 0, rowCount) base := time.Date(2025, 1, 1, 0, 0, 0, 0, time.UTC) for i := 0; i < rowCount; i++ { rows = append(rows, legacyAuditFixtureRow{ id: fmt.Sprintf("legacy-%05d", i), timestamp: base.Add(time.Duration(i) * time.Second), user: "operator", signature: nil, }) } createLegacyAuditFixture(t, dataDir, rows) logger, err := NewSQLiteLogger(SQLiteLoggerConfig{ DataDir: dataDir, CryptoMgr: newMockCryptoManager(), RetentionDays: 0, RetentionConfigured: true, }) if err != nil { t.Fatalf("migrate large legacy history: %v", err) } defer logger.Close() events, total, err := logger.QueryPage(QueryFilter{Limit: 100, Offset: rowCount - 100}) if err != nil { t.Fatalf("query deep page: %v", err) } if len(events) != 100 || total != rowCount { t.Fatalf("deep page = %d events, total %d, want 100/%d", len(events), total, rowCount) } } func TestSQLiteLoggerRealBusyLockFailsClosedAndRecovers(t *testing.T) { dataDir := t.TempDir() logger, err := NewSQLiteLogger(SQLiteLoggerConfig{ DataDir: dataDir, CryptoMgr: newMockCryptoManager(), }) if err != nil { t.Fatalf("NewSQLiteLogger: %v", err) } defer logger.Close() if _, err := logger.db.Exec(`PRAGMA busy_timeout = 1`); err != nil { t.Fatalf("set short busy timeout: %v", err) } blockerDSN := logger.dbPath + "?" + url.Values{ "_pragma": []string{"busy_timeout(1)", "journal_mode(WAL)"}, }.Encode() blocker, err := sql.Open("sqlite", blockerDSN) if err != nil { t.Fatalf("open blocking connection: %v", err) } defer blocker.Close() tx, err := blocker.Begin() if err != nil { t.Fatalf("begin blocking transaction: %v", err) } if _, err := tx.Exec(`INSERT INTO audit_config (key, value, updated_at) VALUES ('lock', '1', 1)`); err != nil { t.Fatalf("acquire write lock: %v", err) } previousSleep := auditSQLiteRetrySleep auditSQLiteRetrySleep = func(time.Duration) {} t.Cleanup(func() { auditSQLiteRetrySleep = previousSleep }) event := Event{ID: "busy", Timestamp: time.Now(), EventType: "test", Success: true} err = logger.Record(event) if !IsStoreBusyError(err) { t.Fatalf("write-lock error = %v, want store busy", err) } if err := tx.Rollback(); err != nil { t.Fatalf("release write lock: %v", err) } if err := logger.Record(event); err != nil { t.Fatalf("write did not recover after lock release: %v", err) } } func TestSQLiteLoggerConcurrentPageSnapshots(t *testing.T) { logger, err := NewSQLiteLogger(SQLiteLoggerConfig{ DataDir: t.TempDir(), CryptoMgr: newMockCryptoManager(), }) if err != nil { t.Fatalf("NewSQLiteLogger: %v", err) } defer logger.Close() var writers sync.WaitGroup for writer := 0; writer < 4; writer++ { writer := writer writers.Add(1) go func() { defer writers.Done() for i := 0; i < 50; i++ { _ = logger.Record(Event{ ID: fmt.Sprintf("%d-%03d", writer, i), Timestamp: time.Unix(1_800_000_000+int64(i), 0), EventType: "concurrent", Success: true, }) } }() } for i := 0; i < 40; i++ { events, total, err := logger.QueryPage(QueryFilter{EventType: "concurrent", Limit: 25}) if err != nil { t.Fatalf("concurrent QueryPage: %v", err) } if total < len(events) { t.Fatalf("snapshot total %d smaller than page %d", total, len(events)) } seen := make(map[string]struct{}, len(events)) for _, event := range events { if _, exists := seen[event.ID]; exists { t.Fatalf("duplicate event %q in snapshot page", event.ID) } seen[event.ID] = struct{}{} } } writers.Wait() } func TestSQLiteLoggerOfflineBackupRestore(t *testing.T) { sourceDir := t.TempDir() logger, err := NewSQLiteLogger(SQLiteLoggerConfig{ DataDir: sourceDir, CryptoMgr: newMockCryptoManager(), }) if err != nil { t.Fatalf("NewSQLiteLogger: %v", err) } event := Event{ ID: "backup-event", Timestamp: time.Now().UTC(), EventType: "backup", Success: true, } if err := logger.Record(event); err != nil { t.Fatalf("record backup event: %v", err) } if err := logger.Close(); err != nil { t.Fatalf("close source logger: %v", err) } restoreDir := t.TempDir() restoreAuditDir := filepath.Join(restoreDir, "audit") if err := os.MkdirAll(restoreAuditDir, 0o700); err != nil { t.Fatalf("create restore directory: %v", err) } for _, name := range []string{"audit.db", ".audit-signing.key"} { source := filepath.Join(sourceDir, "audit", name) data, err := os.ReadFile(source) if err != nil { t.Fatalf("read backup member %q: %v", name, err) } if err := os.WriteFile(filepath.Join(restoreAuditDir, name), data, 0o600); err != nil { t.Fatalf("restore backup member %q: %v", name, err) } } restored, err := NewSQLiteLogger(SQLiteLoggerConfig{ DataDir: restoreDir, CryptoMgr: newMockCryptoManager(), }) if err != nil { t.Fatalf("open restored logger: %v", err) } defer restored.Close() events, err := restored.Query(QueryFilter{ID: event.ID}) if err != nil || len(events) != 1 { t.Fatalf("restored events = %d, err %v", len(events), err) } if !restored.VerifySignature(events[0]) { t.Fatal("restored event signature did not verify") } } func TestSQLiteLoggerCorruptStorageFailsUnavailable(t *testing.T) { dataDir := t.TempDir() auditDir := filepath.Join(dataDir, "audit") if err := os.MkdirAll(auditDir, 0o700); err != nil { t.Fatalf("create audit directory: %v", err) } if err := os.WriteFile(filepath.Join(auditDir, "audit.db"), []byte("not a sqlite database"), 0o600); err != nil { t.Fatalf("write corrupt audit database: %v", err) } logger, err := NewSQLiteLogger(SQLiteLoggerConfig{ DataDir: dataDir, CryptoMgr: newMockCryptoManager(), }) if logger != nil || err == nil { t.Fatal("corrupt database must fail logger initialization") } if !IsStoreUnavailableError(err) && !errors.Is(err, os.ErrInvalid) { t.Fatalf("corrupt database error was not unavailable: %v", err) } }