| 1 | package calls |
| 2 | |
| 3 | import ( |
| 4 | "bytes" |
| 5 | "context" |
| 6 | "io" |
| 7 | "log/slog" |
| 8 | "path/filepath" |
| 9 | "strings" |
| 10 | "sync" |
| 11 | "testing" |
| 12 | |
| 13 | "amadan.net/rastrillo/rastrillo/db" |
| 14 | ) |
| 15 | |
| 16 | // openRelayTestDB is a fresh temp database for the app-level relay |
| 17 | // wiring tests below: build() and NewForTest need a real *db.DB, not |
| 18 | // the bare Config resolve() takes. |
| 19 | func openRelayTestDB(t *testing.T, logger *slog.Logger) *db.DB { |
| 20 | t.Helper() |
| 21 | d, err := db.Open(filepath.Join(t.TempDir(), "relay.db"), logger) |
| 22 | if err != nil { |
| 23 | t.Fatal(err) |
| 24 | } |
| 25 | t.Cleanup(func() { d.Close() }) |
| 26 | return d |
| 27 | } |
| 28 | |
| 29 | // TestSetRelayFlipsRelayConfigured is the with-relay path through |
| 30 | // build: nothing before this exercised SetRelay at all — the config |
| 31 | // package tests only ever checked resolved.relayConfigured, which |
| 32 | // build() never reads back through the app's own atomic. |
| 33 | func TestSetRelayFlipsRelayConfigured(t *testing.T) { |
| 34 | cfg := minimalConfig(t) |
| 35 | cfg.Env = EnvDevelopment |
| 36 | d := openRelayTestDB(t, slog.New(slog.NewTextHandler(io.Discard, nil))) |
| 37 | _, ctl, err := NewForTest(d, cfg) |
| 38 | if err != nil { |
| 39 | t.Fatal(err) |
| 40 | } |
| 41 | t.Cleanup(ctl.ShutdownForTest) // stops the sign-in mail worker |
| 42 | if ctl.a.relayConfigured() { |
| 43 | t.Fatal("expected no relay at boot") |
| 44 | } |
| 45 | if err := ctl.SetRelay(relayVector(t)); err != nil { |
| 46 | t.Fatal(err) |
| 47 | } |
| 48 | if !ctl.a.relayConfigured() || len(ctl.a.relayRegions()) != 1 { |
| 49 | t.Fatalf("SetRelay did not flip relayConfigured: configured=%v regions=%d", ctl.a.relayConfigured(), len(ctl.a.relayRegions())) |
| 50 | } |
| 51 | } |
| 52 | |
| 53 | // TestBuildLogsOneINFOLineWithTheRegionCountAndNotTheKey: build()'s own |
| 54 | // INFO line was untested — make ci passed with a hardcoded Floor and no |
| 55 | // assertion on the log at all, so a mutation that dropped the line, or |
| 56 | // one that logged the raw contract instead of its length, would have |
| 57 | // survived. |
| 58 | func TestBuildLogsOneINFOLineWithTheRegionCountAndNotTheKey(t *testing.T) { |
| 59 | var buf bytes.Buffer |
| 60 | rec := newRecordingHandler(slog.NewTextHandler(&buf, nil)) |
| 61 | logger := slog.New(rec) |
| 62 | cfg := minimalConfig(t) |
| 63 | cfg.Logger = logger |
| 64 | cfg.Relay = relayVector(t) |
| 65 | d := openRelayTestDB(t, logger) |
| 66 | _, a, err := buildForTest(t, d, cfg) |
| 67 | if err != nil { |
| 68 | t.Fatal(err) |
| 69 | } |
| 70 | // The INFO line alone does not prove build() ever stored the parsed |
| 71 | // contract into the app's own atomic — a log call that ran and a |
| 72 | // Store call that didn't would still print this line. Assert both. |
| 73 | if !a.relayConfigured() || len(a.relayRegions()) != 1 { |
| 74 | t.Fatalf("build did not store the parsed relay: configured=%v regions=%d", a.relayConfigured(), len(a.relayRegions())) |
| 75 | } |
| 76 | // Records, not substrings. A substring search says nothing about how |
| 77 | // many lines there were, what level they were at, or what else they |
| 78 | // carried: two identical lines, a WARN, or a line that also logged a |
| 79 | // decoded region would all have passed (Codex S3-6). |
| 80 | var configured []slog.Record |
| 81 | for _, r := range rec.records() { |
| 82 | if r.Message == "calls: relay configured" { |
| 83 | configured = append(configured, r) |
| 84 | } |
| 85 | } |
| 86 | if len(configured) != 1 { |
| 87 | t.Fatalf("want exactly one \"calls: relay configured\" record, got %d:\n%s", len(configured), buf.String()) |
| 88 | } |
| 89 | got := configured[0] |
| 90 | if got.Level != slog.LevelInfo { |
| 91 | t.Fatalf("the relay line is %s, not INFO", got.Level) |
| 92 | } |
| 93 | // A slice, not a map: a map collapses two attributes that share a |
| 94 | // key, so `regions=1, regions=<the whole contract>` would have read |
| 95 | // as one attribute and passed (Codex S3-11). And the value is |
| 96 | // checked as an int64, not as its rendering, so a string "1" is not |
| 97 | // mistaken for the count. |
| 98 | attrs := recordAttrs(got) |
| 99 | if len(attrs) != 1 { |
| 100 | t.Fatalf("want exactly one attribute on the relay line, got %d: %v", len(attrs), attrs) |
| 101 | } |
| 102 | if attrs[0].Key != "regions" { |
| 103 | t.Fatalf("the one attribute is %q, not regions", attrs[0].Key) |
| 104 | } |
| 105 | if attrs[0].Value.Kind() != slog.KindInt64 || attrs[0].Value.Int64() != 1 { |
| 106 | t.Fatalf("regions is %v (%s), want the int64 1", attrs[0].Value, attrs[0].Value.Kind()) |
| 107 | } |
| 108 | if log := buf.String(); strings.Contains(log, "uMhwW4P") { |
| 109 | t.Fatal("the relay key reached the log") |
| 110 | } |
| 111 | } |
| 112 | |
| 113 | // recordingHandler keeps every record whole so a test can ask how many |
| 114 | // there were, at what level, and with which attributes — the three |
| 115 | // questions a rendered line cannot answer. It forwards to a real |
| 116 | // handler as well, so a failure can still print what was written. |
| 117 | // |
| 118 | // The store is shared with every handler derived from this one, and the |
| 119 | // attributes and groups bound along the way are kept and replayed onto |
| 120 | // each record. Without both, a logger reached through WithAttrs wrote |
| 121 | // into a store nobody read, and the attributes it was carrying were |
| 122 | // invisible to the assertions — so a line that logged the decoded |
| 123 | // contract through a bound attribute would have passed a test whose |
| 124 | // name says it cannot (Codex S3-11). |
| 125 | type recordingHandler struct { |
| 126 | inner slog.Handler |
| 127 | store *recordStore |
| 128 | bound []slog.Attr |
| 129 | groups []string |
| 130 | } |
| 131 | |
| 132 | type recordStore struct { |
| 133 | mu sync.Mutex |
| 134 | kept []slog.Record |
| 135 | } |
| 136 | |
| 137 | func newRecordingHandler(inner slog.Handler) *recordingHandler { |
| 138 | return &recordingHandler{inner: inner, store: &recordStore{}} |
| 139 | } |
| 140 | |
| 141 | func (h *recordingHandler) Enabled(ctx context.Context, l slog.Level) bool { |
| 142 | return h.inner.Enabled(ctx, l) |
| 143 | } |
| 144 | |
| 145 | func (h *recordingHandler) Handle(ctx context.Context, r slog.Record) error { |
| 146 | kept := r.Clone() |
| 147 | if len(h.bound) > 0 { |
| 148 | // Bound attributes belong to the record as much as the ones the |
| 149 | // call site passed: they are what a reader of the line sees. |
| 150 | front := slog.NewRecord(r.Time, r.Level, r.Message, r.PC) |
| 151 | front.AddAttrs(h.bound...) |
| 152 | r.Attrs(func(a slog.Attr) bool { |
| 153 | front.AddAttrs(a) |
| 154 | return true |
| 155 | }) |
| 156 | kept = front |
| 157 | } |
| 158 | if len(h.groups) > 0 { |
| 159 | // A grouped record is not the shape this test is about, and |
| 160 | // pretending otherwise would hide it: keep it whole and let the |
| 161 | // count assertion speak. |
| 162 | kept.AddAttrs(slog.String("__groups", strings.Join(h.groups, "."))) |
| 163 | } |
| 164 | h.store.mu.Lock() |
| 165 | h.store.kept = append(h.store.kept, kept) |
| 166 | h.store.mu.Unlock() |
| 167 | return h.inner.Handle(ctx, r) |
| 168 | } |
| 169 | |
| 170 | func (h *recordingHandler) WithAttrs(as []slog.Attr) slog.Handler { |
| 171 | return &recordingHandler{ |
| 172 | inner: h.inner.WithAttrs(as), |
| 173 | store: h.store, |
| 174 | bound: append(append([]slog.Attr(nil), h.bound...), as...), |
| 175 | groups: h.groups, |
| 176 | } |
| 177 | } |
| 178 | |
| 179 | func (h *recordingHandler) WithGroup(name string) slog.Handler { |
| 180 | return &recordingHandler{ |
| 181 | inner: h.inner.WithGroup(name), |
| 182 | store: h.store, |
| 183 | bound: h.bound, |
| 184 | groups: append(append([]string(nil), h.groups...), name), |
| 185 | } |
| 186 | } |
| 187 | |
| 188 | func (h *recordingHandler) records() []slog.Record { |
| 189 | h.store.mu.Lock() |
| 190 | defer h.store.mu.Unlock() |
| 191 | return append([]slog.Record(nil), h.store.kept...) |
| 192 | } |
| 193 | |
| 194 | // recordAttrs is a record's attributes in order, duplicates and all. |
| 195 | func recordAttrs(r slog.Record) []slog.Attr { |
| 196 | var out []slog.Attr |
| 197 | r.Attrs(func(a slog.Attr) bool { |
| 198 | out = append(out, a) |
| 199 | return true |
| 200 | }) |
| 201 | return out |
| 202 | } |
| 203 | |
| 204 | // TestTheRecordingHandlerSeesWhatALoggerCarries is a test of the test: |
| 205 | // the assertions above are only worth their names if the handler under |
| 206 | // them keeps duplicate keys apart and carries bound attributes through. |
| 207 | func TestTheRecordingHandlerSeesWhatALoggerCarries(t *testing.T) { |
| 208 | rec := newRecordingHandler(slog.NewTextHandler(io.Discard, nil)) |
| 209 | base := slog.New(rec) |
| 210 | base.Info("plain", "regions", 1, "regions", 2) |
| 211 | slog.New(rec).With("bound", "yes").Info("derived", "regions", 1) |
| 212 | |
| 213 | got := rec.records() |
| 214 | if len(got) != 2 { |
| 215 | t.Fatalf("want both records in one store, got %d", len(got)) |
| 216 | } |
| 217 | if attrs := recordAttrs(got[0]); len(attrs) != 2 { |
| 218 | t.Fatalf("duplicate keys were collapsed: %v", attrs) |
| 219 | } |
| 220 | attrs := recordAttrs(got[1]) |
| 221 | if len(attrs) != 2 || attrs[0].Key != "bound" { |
| 222 | t.Fatalf("a bound attribute did not reach the record: %v", attrs) |
| 223 | } |
| 224 | } |
| 225 | |
| 226 | // TestSetRelayIsTypeConsistentWithBuildsInitialStore: build() stores a |
| 227 | // nil []relay.Region into a.relay when no relay is configured, and |
| 228 | // SetRelay later stores a real []relay.Region into the same |
| 229 | // atomic.Value. atomic.Value panics on a Store whose concrete type |
| 230 | // disagrees with an earlier one, so swapping to a real slice and back |
| 231 | // to empty here without a panic is the proof the two call sites agree. |
| 232 | func TestSetRelayIsTypeConsistentWithBuildsInitialStore(t *testing.T) { |
| 233 | cfg := minimalConfig(t) |
| 234 | cfg.Env = EnvDevelopment |
| 235 | d := openRelayTestDB(t, slog.New(slog.NewTextHandler(io.Discard, nil))) |
| 236 | _, ctl, err := NewForTest(d, cfg) |
| 237 | if err != nil { |
| 238 | t.Fatal(err) |
| 239 | } |
| 240 | t.Cleanup(ctl.ShutdownForTest) // stops the sign-in mail worker |
| 241 | if err := ctl.SetRelay(relayVector(t)); err != nil { |
| 242 | t.Fatal(err) |
| 243 | } |
| 244 | if !ctl.a.relayConfigured() { |
| 245 | t.Fatal("SetRelay did not take effect") |
| 246 | } |
| 247 | if err := ctl.SetRelay(""); err != nil { |
| 248 | t.Fatal(err) |
| 249 | } |
| 250 | if ctl.a.relayConfigured() { |
| 251 | t.Fatal(`SetRelay("") did not clear the relay`) |
| 252 | } |
| 253 | } |
| 254 | |
| 255 | // TestSetRelayOfAMalformedValueLeavesRegionsUnchanged: SetRelay parses |
| 256 | // before it stores, so a malformed value must return the error and |
| 257 | // leave whatever was there before untouched — never a half-applied |
| 258 | // swap. |
| 259 | func TestSetRelayOfAMalformedValueLeavesRegionsUnchanged(t *testing.T) { |
| 260 | cfg := minimalConfig(t) |
| 261 | cfg.Env = EnvDevelopment |
| 262 | d := openRelayTestDB(t, slog.New(slog.NewTextHandler(io.Discard, nil))) |
| 263 | _, ctl, err := NewForTest(d, cfg) |
| 264 | if err != nil { |
| 265 | t.Fatal(err) |
| 266 | } |
| 267 | t.Cleanup(ctl.ShutdownForTest) // stops the sign-in mail worker |
| 268 | if err := ctl.SetRelay(relayVector(t)); err != nil { |
| 269 | t.Fatal(err) |
| 270 | } |
| 271 | before := ctl.a.relayRegions() |
| 272 | if err := ctl.SetRelay("%%%not-base64"); err == nil { |
| 273 | t.Fatal("want an error") |
| 274 | } |
| 275 | after := ctl.a.relayRegions() |
| 276 | if len(after) != len(before) || len(after) == 0 || after[0].Region != before[0].Region { |
| 277 | t.Fatalf("a malformed SetRelay mutated the regions: before len=%d after len=%d", len(before), len(after)) |
| 278 | } |
| 279 | } |
| 280 | |
amadan