internal/store/auditchain_test.go

  1package store
  2
  3import (
  4	"bytes"
  5	"encoding/json"
  6	"fmt"
  7	"log/slog"
  8	"strings"
  9	"sync"
 10	"testing"
 11	"time"
 12)
 13
 14func chainStore(t *testing.T) *Store {
 15	t.Helper()
 16	s := open(t)
 17	if err := s.MigrateUp(); err != nil {
 18		t.Fatal(err)
 19	}
 20	return s
 21}
 22
 23func TestAuditChainIntact(t *testing.T) {
 24	s := chainStore(t)
 25	s.Audit(0, "a", map[string]any{"n": 1})
 26	s.Audit(0, "b", nil)
 27	s.Audit(0, "c", map[string]any{"n": 3})
 28	res, err := s.VerifyAuditChain()
 29	if err != nil {
 30		t.Fatal(err)
 31	}
 32	if res.Rows != 3 || res.BrokenAt != 0 || res.First != 1 || res.Last != 3 || len(res.LastHash) != 64 {
 33		t.Fatalf("%+v", res)
 34	}
 35}
 36
 37// Concurrent writers each read the last hash and insert in one
 38// transaction; none may chain to a predecessor another already took.
 39func TestAuditChainConcurrentWriters(t *testing.T) {
 40	s := chainStore(t)
 41	const writers, each = 8, 25
 42	var wg sync.WaitGroup
 43	for w := range writers {
 44		wg.Add(1)
 45		go func() {
 46			defer wg.Done()
 47			for i := range each {
 48				s.Audit(0, fmt.Sprintf("w%d-%d", w, i), nil)
 49			}
 50		}()
 51	}
 52	wg.Wait()
 53	res, err := s.VerifyAuditChain()
 54	if err != nil {
 55		t.Fatal(err)
 56	}
 57	if res.Rows != writers*each || res.Unchained != 0 || res.BrokenAt != 0 {
 58		t.Fatalf("%+v", res)
 59	}
 60}
 61
 62func TestAuditChainDetectsAnEditedRow(t *testing.T) {
 63	for _, set := range []string{
 64		"action = 'x'",
 65		"created_at = '2020-01-01T00:00:00.000Z'",
 66		`data_json = '{"n":2}'`,
 67		"actor_ref = 7",
 68	} {
 69		t.Run(set, func(t *testing.T) {
 70			s := chainStore(t)
 71			for _, a := range []string{"a", "b", "c"} {
 72				s.Audit(0, a, nil)
 73			}
 74			if _, err := s.DB.Exec("UPDATE audit_log SET " + set + " WHERE id = 2"); err != nil {
 75				t.Fatal(err)
 76			}
 77			res, err := s.VerifyAuditChain()
 78			if err != nil {
 79				t.Fatal(err)
 80			}
 81			if res.BrokenAt != 2 || !strings.Contains(res.Reason, "contents") {
 82				t.Fatalf("%+v", res)
 83			}
 84		})
 85	}
 86}
 87
 88// Blanking the hash of the oldest chained rows would make them read as
 89// rows from before the migration.
 90func TestAuditChainDetectsBlankedHashes(t *testing.T) {
 91	s := chainStore(t)
 92	for _, a := range []string{"a", "b", "c"} {
 93		s.Audit(0, a, nil)
 94	}
 95	if _, err := s.DB.Exec("UPDATE audit_log SET hash = '', action = 'x' WHERE id = 1"); err != nil {
 96		t.Fatal(err)
 97	}
 98	res, err := s.VerifyAuditChain()
 99	if err != nil {
100		t.Fatal(err)
101	}
102	if res.BrokenAt != 2 {
103		t.Fatalf("%+v", res)
104	}
105}
106
107// actor_id is not hashed; it must agree with actor_ref or be NULL.
108func TestAuditChainDetectsAChangedActorID(t *testing.T) {
109	s := chainStore(t)
110	uid, err := s.CreateUser("alice", false)
111	if err != nil {
112		t.Fatal(err)
113	}
114	s.Audit(0, "a", nil)
115	s.Audit(0, "b", nil)
116	if _, err := s.DB.Exec("UPDATE audit_log SET actor_id = ? WHERE id = 2", uid); err != nil {
117		t.Fatal(err)
118	}
119	res, err := s.VerifyAuditChain()
120	if err != nil {
121		t.Fatal(err)
122	}
123	if res.BrokenAt != 2 || !strings.Contains(res.Reason, "actor_id") {
124		t.Fatalf("%+v", res)
125	}
126}
127
128// A clock stepped back leaves created_at out of id order; retention
129// still removes a prefix of the table, so the chain stays intact.
130func TestAuditChainSurvivesRetentionWithClockStep(t *testing.T) {
131	s := chainStore(t)
132	for _, a := range []string{"a", "b", "c", "d"} {
133		s.Audit(0, a, nil)
134	}
135	// Rewrite created_at and the hashes as the rows would have been
136	// written: row 2 stamped after row 3, both older than the cutoff.
137	stamps := map[int64]string{
138		1: "2020-01-01T00:00:00.000Z",
139		2: "2020-01-03T00:00:00.000Z",
140		3: "2020-01-02T00:00:00.000Z",
141		4: "2099-01-01T00:00:00.000Z",
142	}
143	prev := ""
144	for id := int64(1); id <= 4; id++ {
145		var action, data string
146		if err := s.DB.QueryRow("SELECT action, data_json FROM audit_log WHERE id = ?", id).Scan(&action, &data); err != nil {
147			t.Fatal(err)
148		}
149		h := auditHash(prev, id, 0, action, stamps[id], data)
150		if _, err := s.DB.Exec("UPDATE audit_log SET created_at = ?, prev_hash = ?, hash = ? WHERE id = ?",
151			stamps[id], prev, h, id); err != nil {
152			t.Fatal(err)
153		}
154		prev = h
155	}
156	if _, err := s.Sweep(Retention{Audit: time.Hour}, mustTime(t, "2020-01-02T12:00:00.000Z")); err != nil {
157		t.Fatal(err)
158	}
159	res, err := s.VerifyAuditChain()
160	if err != nil {
161		t.Fatal(err)
162	}
163	if res.BrokenAt != 0 || res.First != 4 || res.Rows != 1 {
164		t.Fatalf("%+v", res)
165	}
166}
167
168func mustTime(t *testing.T, v string) time.Time {
169	t.Helper()
170	tm, err := time.Parse(time.RFC3339, v)
171	if err != nil {
172		t.Fatal(err)
173	}
174	return tm
175}
176
177func TestAuditChainDetectsARemovedRow(t *testing.T) {
178	s := chainStore(t)
179	for _, a := range []string{"a", "b", "c"} {
180		s.Audit(0, a, nil)
181	}
182	if _, err := s.DB.Exec("DELETE FROM audit_log WHERE id = 2"); err != nil {
183		t.Fatal(err)
184	}
185	res, err := s.VerifyAuditChain()
186	if err != nil {
187		t.Fatal(err)
188	}
189	if res.BrokenAt != 3 || !strings.Contains(res.Reason, "previous hash") {
190		t.Fatalf("%+v", res)
191	}
192}
193
194// Retention removes the oldest rows, and deleting an account nulls
195// actor_id; neither is tampering.
196func TestAuditChainSurvivesRetentionAndAccountDeletion(t *testing.T) {
197	s := chainStore(t)
198	uid, err := s.CreateUser("alice", false)
199	if err != nil {
200		t.Fatal(err)
201	}
202	s.Audit(0, "a", nil)
203	s.Audit(uid, "b", nil)
204	s.Audit(0, "c", nil)
205	if _, err := s.DB.Exec("DELETE FROM audit_log WHERE id = 1"); err != nil {
206		t.Fatal(err)
207	}
208	if _, err := s.DB.Exec("DELETE FROM users WHERE id = ?", uid); err != nil {
209		t.Fatal(err)
210	}
211	res, err := s.VerifyAuditChain()
212	if err != nil {
213		t.Fatal(err)
214	}
215	if res.BrokenAt != 0 || res.First != 2 || res.Last != 3 {
216		t.Fatalf("%+v", res)
217	}
218}
219
220// Rows written before migration 0064 carry no hash; the chain starts
221// after them, and a hashless row after that start is a break.
222func TestAuditChainLegacyRows(t *testing.T) {
223	s := chainStore(t)
224	if _, err := s.DB.Exec("INSERT INTO audit_log (action) VALUES ('legacy')"); err != nil {
225		t.Fatal(err)
226	}
227	s.Audit(0, "a", nil)
228	res, err := s.VerifyAuditChain()
229	if err != nil {
230		t.Fatal(err)
231	}
232	if res.Unchained != 1 || res.BrokenAt != 0 || res.First != 2 {
233		t.Fatalf("%+v", res)
234	}
235	if _, err := s.DB.Exec("INSERT INTO audit_log (action) VALUES ('injected')"); err != nil {
236		t.Fatal(err)
237	}
238	if res, _ = s.VerifyAuditChain(); res.BrokenAt != 3 {
239		t.Fatalf("hashless row after the chain: %+v", res)
240	}
241}
242
243func TestAuditJournal(t *testing.T) {
244	s := chainStore(t)
245	var buf bytes.Buffer
246	s.AuditJournal = slog.New(slog.NewJSONHandler(&buf, nil))
247	s.Audit(0, "cmd repo create", map[string]any{"argv": []string{"a/b"}})
248	lines := strings.Split(strings.TrimRight(buf.String(), "\n"), "\n")
249	if len(lines) != 1 {
250		t.Fatalf("journal lines %q", lines)
251	}
252	var got map[string]any
253	if err := json.Unmarshal([]byte(lines[0]), &got); err != nil {
254		t.Fatal(err)
255	}
256	var id float64
257	var data, createdAt, hash string
258	if err := s.DB.QueryRow("SELECT id, data_json, created_at, hash FROM audit_log").Scan(&id, &data, &createdAt, &hash); err != nil {
259		t.Fatal(err)
260	}
261	want := map[string]any{
262		"level": "INFO", "msg": "audit", "id": id, "actor": float64(0), "action": "cmd repo create",
263		"data": data, "created_at": createdAt, "hash": hash,
264	}
265	delete(got, "time")
266	if fmt.Sprint(got) != fmt.Sprint(want) {
267		t.Fatalf("journal line %v, want %v", got, want)
268	}
269}