| 1 | package callstest |
| 2 | |
| 3 | import ( |
| 4 | "bytes" |
| 5 | "context" |
| 6 | "encoding/json" |
| 7 | "fmt" |
| 8 | "io" |
| 9 | "log/slog" |
| 10 | "net/http" |
| 11 | "regexp" |
| 12 | "strings" |
| 13 | "sync" |
| 14 | "testing" |
| 15 | "time" |
| 16 | |
| 17 | "amadan.net/oficina/calls/internal/calls" |
| 18 | "amadan.net/oficina/calls/protocol" |
| 19 | ) |
| 20 | |
| 21 | // Spec §15.26: quality and problem reports. These tests hold the ruling's |
| 22 | // lines: what is logged, under which tags, and what never is; who may |
| 23 | // report, and for how long; the bounds; the kill switch. |
| 24 | |
| 25 | const ( |
| 26 | reportA = "paul@example.com" |
| 27 | reportB = "ana@example.com" |
| 28 | reportTitle = "Quarterly secrets review" |
| 29 | ) |
| 30 | |
| 31 | // syncBuffer is a log sink a stream goroutine and the test can share. |
| 32 | type syncBuffer struct { |
| 33 | mu sync.Mutex |
| 34 | buf bytes.Buffer |
| 35 | } |
| 36 | |
| 37 | func (b *syncBuffer) Write(p []byte) (int, error) { |
| 38 | b.mu.Lock() |
| 39 | defer b.mu.Unlock() |
| 40 | return b.buf.Write(p) |
| 41 | } |
| 42 | |
| 43 | func (b *syncBuffer) String() string { |
| 44 | b.mu.Lock() |
| 45 | defer b.mu.Unlock() |
| 46 | return b.buf.String() |
| 47 | } |
| 48 | |
| 49 | // lines are the JSON lines whose msg is msg. |
| 50 | func (b *syncBuffer) lines(t *testing.T, msg string) []map[string]any { |
| 51 | t.Helper() |
| 52 | var out []map[string]any |
| 53 | for _, line := range strings.Split(b.String(), "\n") { |
| 54 | if strings.TrimSpace(line) == "" { |
| 55 | continue |
| 56 | } |
| 57 | var m map[string]any |
| 58 | if err := json.Unmarshal([]byte(line), &m); err != nil { |
| 59 | t.Fatalf("a report line is not JSON: %v\n%s", err, line) |
| 60 | } |
| 61 | if m["msg"] == msg { |
| 62 | out = append(out, m) |
| 63 | } |
| 64 | } |
| 65 | return out |
| 66 | } |
| 67 | |
| 68 | // reportRig is a meeting with two members in it, each joined, each |
| 69 | // holding its report token; reports go to `reports` as JSON, as the |
| 70 | // deployed main writes them, and everything else the app logs goes to |
| 71 | // `app`. |
| 72 | type reportRig struct { |
| 73 | x *harness |
| 74 | sqid string |
| 75 | a, b *client |
| 76 | sa, sb *sseReader |
| 77 | peerA, peerB string |
| 78 | tokA, tokB string |
| 79 | reports *syncBuffer |
| 80 | app *syncBuffer |
| 81 | } |
| 82 | |
| 83 | func newReportRig(t *testing.T, quality string) *reportRig { |
| 84 | t.Helper() |
| 85 | reports, app := &syncBuffer{}, &syncBuffer{} |
| 86 | x := newHarnessWith(t, calls.EnvDevelopment, slog.New(slog.NewTextHandler(app, &slog.HandlerOptions{Level: slog.LevelDebug})), func(c *calls.Config) { |
| 87 | c.ReportLogger = slog.New(slog.NewJSONHandler(reports, nil)) |
| 88 | c.QualityReports = quality |
| 89 | }, reportA, reportB) |
| 90 | a := newMemberBrowser(t, x, reportA) |
| 91 | sqid, _ := createMeeting(t, a, reportTitle, "") |
| 92 | b := newMemberBrowser(t, x, reportB) |
| 93 | r := &reportRig{x: x, sqid: sqid, a: a, b: b, reports: reports, app: app} |
| 94 | r.sa, r.peerA, r.tokA = r.enter(t, a) |
| 95 | r.sb, r.peerB, r.tokB = r.enter(t, b) |
| 96 | t.Cleanup(func() { r.sa.close(); r.sb.close() }) |
| 97 | return r |
| 98 | } |
| 99 | |
| 100 | // enter opens a stream, reads the hello's peer and report token, and |
| 101 | // joins. |
| 102 | func (r *reportRig) enter(t *testing.T, c *client) (*sseReader, string, string) { |
| 103 | t.Helper() |
| 104 | s := c.stream("/m/" + r.sqid + "/stream") |
| 105 | peer, token := helloReport(t, s) |
| 106 | if resp, _ := c.signal(r.sqid, peer, `{"type":"join"}`); resp.StatusCode != http.StatusOK { |
| 107 | t.Fatalf("join: %d", resp.StatusCode) |
| 108 | } |
| 109 | return s, peer, token |
| 110 | } |
| 111 | |
| 112 | func helloReport(t *testing.T, s *sseReader) (peer, token string) { |
| 113 | t.Helper() |
| 114 | name, data, ok := s.next(2 * time.Second) |
| 115 | if !ok || name != "hello" { |
| 116 | t.Fatalf("first event is %q, want hello", name) |
| 117 | } |
| 118 | var body struct{ Peer, Report string } |
| 119 | if err := json.Unmarshal(data, &body); err != nil { |
| 120 | t.Fatal(err) |
| 121 | } |
| 122 | if !regexp.MustCompile(`^[0-9a-f]{32}$`).MatchString(body.Report) { |
| 123 | t.Fatalf("hello carries no report token: %s", data) |
| 124 | } |
| 125 | return body.Peer, body.Report |
| 126 | } |
| 127 | |
| 128 | // report POSTs body to /m/{sqid}/{kind} with token. |
| 129 | func (c *client) report(sqid, kind, token string, body []byte) (*http.Response, []byte) { |
| 130 | c.t.Helper() |
| 131 | ctx, cancel := context.WithTimeout(context.Background(), 2*time.Second) |
| 132 | defer cancel() |
| 133 | req, err := http.NewRequestWithContext(ctx, http.MethodPost, c.x.server().URL+"/m/"+sqid+"/"+kind, bytes.NewReader(body)) |
| 134 | if err != nil { |
| 135 | c.t.Fatal(err) |
| 136 | } |
| 137 | for _, ck := range c.cookies { |
| 138 | req.AddCookie(ck) |
| 139 | } |
| 140 | req.Header.Set("Content-Type", "application/json") |
| 141 | req.Header.Set("Origin", testOrigin) |
| 142 | if token != "" { |
| 143 | req.Header.Set("X-Calls-Report", token) |
| 144 | } |
| 145 | resp, err := c.x.server().Client().Do(req) |
| 146 | if err != nil { |
| 147 | c.t.Fatalf("POST %s: %v", kind, err) |
| 148 | } |
| 149 | b, _ := io.ReadAll(resp.Body) |
| 150 | resp.Body.Close() |
| 151 | return resp, b |
| 152 | } |
| 153 | |
| 154 | func num(v float64) *float64 { return &v } |
| 155 | |
| 156 | // sampleQuality is an honest report about one remote peer. |
| 157 | func sampleQuality(remote string) protocol.QualityReport { |
| 158 | return protocol.QualityReport{ |
| 159 | V: 1, Seconds: num(30), |
| 160 | Client: protocol.ReportClient{App: "mac", Version: "0.4.9", OS: "macos", OSVersion: "26.0.1"}, |
| 161 | Devices: &protocol.Devices{Input: "bluetooth", Output: "built-in"}, |
| 162 | Events: &protocol.CallEvents{Reconnecting: num(1), ReconnectingSeconds: num(4.2)}, |
| 163 | Peers: []protocol.PeerQuality{{ |
| 164 | Peer: protocol.PeerID(remote), |
| 165 | Path: &protocol.Path{Local: "srflx", Remote: "relay", Protocol: "udp"}, |
| 166 | RTT: num(48.25), |
| 167 | Out: &protocol.Outbound{ |
| 168 | Audio: &protocol.OutStream{Kbps: num(32), Packets: num(1500), Lost: num(3), RTT: num(50), Jitter: num(4)}, |
| 169 | Video: &protocol.OutStream{Kbps: num(900), Limit: "bandwidth", Width: num(1280), Height: num(720), FPS: num(30)}, |
| 170 | }, |
| 171 | In: &protocol.Inbound{ |
| 172 | Audio: &protocol.InAudio{Packets: num(1490), Lost: num(10), Concealed: num(4800), Samples: num(1440000), JitterBufferMs: num(62)}, |
| 173 | Video: &protocol.InVideo{Packets: num(2700), Lost: num(300), Freezes: num(2), FreezeSeconds: num(1.5), Decoded: num(890), Dropped: num(4), Width: num(640), Height: num(360), FPS: num(29.7)}, |
| 174 | }, |
| 175 | Events: &protocol.PeerEvents{CantHearSeconds: num(2), NoSound: true}, |
| 176 | }}, |
| 177 | } |
| 178 | } |
| 179 | |
| 180 | // forbidden is everything the ruling says a report line never carries: |
| 181 | // the meeting, the people, their addresses and names, the peer ids that |
| 182 | // the signalling log names, and the report tokens. |
| 183 | func (r *reportRig) forbidden() []string { |
| 184 | return []string{r.sqid, reportTitle, reportA, reportB, "example.com", r.peerA, r.peerB, r.tokA, r.tokB} |
| 185 | } |
| 186 | |
| 187 | func (r *reportRig) assertClean(t *testing.T) { |
| 188 | t.Helper() |
| 189 | raw := r.reports.String() |
| 190 | for _, f := range r.forbidden() { |
| 191 | if strings.Contains(raw, f) { |
| 192 | t.Errorf("the report log contains %q:\n%s", f, raw) |
| 193 | } |
| 194 | } |
| 195 | } |
| 196 | |
| 197 | func TestQualityReportsShareACallTagAndNameNothing(t *testing.T) { |
| 198 | r := newReportRig(t, "") |
| 199 | resp, _ := r.a.report(r.sqid, "quality", r.tokA, mustJSON(t, sampleQuality(r.peerB))) |
| 200 | if resp.StatusCode != http.StatusAccepted { |
| 201 | t.Fatalf("A's report: %d, want 202", resp.StatusCode) |
| 202 | } |
| 203 | resp, _ = r.b.report(r.sqid, "quality", r.tokB, mustJSON(t, sampleQuality(r.peerA))) |
| 204 | if resp.StatusCode != http.StatusAccepted { |
| 205 | t.Fatalf("B's report: %d, want 202", resp.StatusCode) |
| 206 | } |
| 207 | lines := r.reports.lines(t, "calls: quality") |
| 208 | if len(lines) != 2 { |
| 209 | t.Fatalf("%d quality lines, want 2:\n%s", len(lines), r.reports.String()) |
| 210 | } |
| 211 | a, b := lines[0], lines[1] |
| 212 | tag := regexp.MustCompile(`^[a-z2-7]{16}$`) |
| 213 | for _, k := range []string{"call", "peer"} { |
| 214 | for _, l := range lines { |
| 215 | if s, _ := l[k].(string); !tag.MatchString(s) { |
| 216 | t.Fatalf("%s tag %v is not a random tag", k, l[k]) |
| 217 | } |
| 218 | } |
| 219 | } |
| 220 | if a["call"] != b["call"] { |
| 221 | t.Errorf("one call, two call tags: %v and %v", a["call"], b["call"]) |
| 222 | } |
| 223 | if a["peer"] == b["peer"] { |
| 224 | t.Errorf("two participations, one peer tag %v", a["peer"]) |
| 225 | } |
| 226 | // A's report names B by B's tag, never B's id. |
| 227 | rep := a["report"].(map[string]any) |
| 228 | peers := rep["peers"].([]any) |
| 229 | if got := peers[0].(map[string]any)["peer"]; got != b["peer"] { |
| 230 | t.Errorf("A's report names its peer %v, want B's tag %v", got, b["peer"]) |
| 231 | } |
| 232 | // The line's shape: what carlos logs --field can filter on, at the |
| 233 | // top, and the rest under report. |
| 234 | for k, want := range map[string]any{"level": "INFO", "app": "mac", "version": "0.4.9", "os": "macos", "osVersion": "26.0.1", |
| 235 | "final": false, "seconds": 30.0, "remotes": 1.0, "relay": true, "maxLossPct": 10.0, "maxRtt": 50.0, "freezes": 2.0, "reconnecting": 1.0} { |
| 236 | if a[k] != want { |
| 237 | t.Errorf("line[%q] = %v (%T), want %v", k, a[k], a[k], want) |
| 238 | } |
| 239 | } |
| 240 | if got := peers[0].(map[string]any)["rtt"]; got != 48.3 { |
| 241 | t.Errorf("rtt %v, want rounded to a tenth (48.3)", got) |
| 242 | } |
| 243 | if _, ok := rep["client"]; ok { |
| 244 | t.Error("the client is logged twice: at the top and under report") |
| 245 | } |
| 246 | r.assertClean(t) |
| 247 | // And the app's own log says nothing about an accepted report. |
| 248 | if strings.Contains(r.app.String(), "quality") { |
| 249 | t.Errorf("the app log mentions a quality report:\n%s", r.app.String()) |
| 250 | } |
| 251 | } |
| 252 | |
| 253 | func TestQualityReportSchemaIsStrict(t *testing.T) { |
| 254 | r := newReportRig(t, "") |
| 255 | base := func() map[string]any { |
| 256 | var m map[string]any |
| 257 | _ = json.Unmarshal(mustJSON(t, sampleQuality(r.peerB)), &m) |
| 258 | return m |
| 259 | } |
| 260 | peer0 := func(m map[string]any) map[string]any { return m["peers"].([]any)[0].(map[string]any) } |
| 261 | cases := map[string]func(m map[string]any){ |
| 262 | "version 2": func(m map[string]any) { m["v"] = 2 }, |
| 263 | "no seconds": func(m map[string]any) { delete(m, "seconds") }, |
| 264 | "zero seconds": func(m map[string]any) { m["seconds"] = 0 }, |
| 265 | "an hour": func(m map[string]any) { m["seconds"] = 3600 }, |
| 266 | "unknown app": func(m map[string]any) { m["client"].(map[string]any)["app"] = "android" }, |
| 267 | "no app": func(m map[string]any) { delete(m["client"].(map[string]any), "app") }, |
| 268 | "a version with a space": func(m map[string]any) { m["client"].(map[string]any)["version"] = "0.4 beta" }, |
| 269 | "a user agent": func(m map[string]any) { m["client"].(map[string]any)["osVersion"] = "Mozilla/5.0" }, |
| 270 | "a device's name": func(m map[string]any) { m["devices"].(map[string]any)["input"] = "Paul's AirPods Pro" }, |
| 271 | "a string for a number": func(m map[string]any) { peer0(m)["rtt"] = "48" }, |
| 272 | "a negative count": func(m map[string]any) { peer0(m)["in"].(map[string]any)["audio"].(map[string]any)["lost"] = -1 }, |
| 273 | "a huge count": func(m map[string]any) { peer0(m)["in"].(map[string]any)["audio"].(map[string]any)["samples"] = 1e12 }, |
| 274 | "a minute's rtt and more": func(m map[string]any) { |
| 275 | peer0(m)["rtt"] = 600001 |
| 276 | }, |
| 277 | "an address for a path": func(m map[string]any) { peer0(m)["path"].(map[string]any)["local"] = "192.168.1.4" }, |
| 278 | "an unknown limit": func(m map[string]any) { |
| 279 | peer0(m)["out"].(map[string]any)["video"].(map[string]any)["limit"] = "thermal" |
| 280 | }, |
| 281 | "a name for a peer": func(m map[string]any) { peer0(m)["peer"] = "Ana" }, |
| 282 | "the same peer twice": func(m map[string]any) { m["peers"] = append(m["peers"].([]any), peer0(m)) }, |
| 283 | "a peer list for a room": func(m map[string]any) { m["peers"] = "everyone" }, |
| 284 | "five peers": func(m map[string]any) { |
| 285 | var ps []any |
| 286 | for i := 0; i <= protocol.MaxQualityPeers; i++ { |
| 287 | ps = append(ps, map[string]any{"peer": fmt.Sprintf("%032x", i)}) |
| 288 | } |
| 289 | m["peers"] = ps |
| 290 | }, |
| 291 | } |
| 292 | for name, spoil := range cases { |
| 293 | m := base() |
| 294 | spoil(m) |
| 295 | r.x.advance(10 * time.Second) // one report's budget each |
| 296 | resp, _ := r.a.report(r.sqid, "quality", r.tokA, mustJSON(t, m)) |
| 297 | if resp.StatusCode != http.StatusBadRequest { |
| 298 | t.Errorf("%s: %d, want 400", name, resp.StatusCode) |
| 299 | } |
| 300 | } |
| 301 | if n := len(r.reports.lines(t, "calls: quality")); n != 0 { |
| 302 | t.Fatalf("%d refused reports were logged", n) |
| 303 | } |
| 304 | |
| 305 | // A member the schema does not name is tolerated, and not logged: |
| 306 | // a newer client's field, or anything a client should never send. |
| 307 | m := base() |
| 308 | m["name"] = "Paul Campbell" |
| 309 | m["client"].(map[string]any)["device"] = "Paul's MacBook Pro" |
| 310 | peer0(m)["address"] = "203.0.113.9" |
| 311 | peer0(m)["out"].(map[string]any)["audio"].(map[string]any)["codec"] = "opus" |
| 312 | r.x.advance(10 * time.Second) |
| 313 | if resp, _ := r.a.report(r.sqid, "quality", r.tokA, mustJSON(t, m)); resp.StatusCode != http.StatusAccepted { |
| 314 | t.Fatalf("unknown members: %d, want 202", resp.StatusCode) |
| 315 | } |
| 316 | raw := r.reports.String() |
| 317 | for _, f := range []string{"Paul Campbell", "MacBook", "203.0.113.9", "codec", "opus"} { |
| 318 | if strings.Contains(raw, f) { |
| 319 | t.Errorf("an unknown member reached the log: %q", f) |
| 320 | } |
| 321 | } |
| 322 | |
| 323 | // Past 16 KB the body is not read. |
| 324 | big := base() |
| 325 | big["padding"] = strings.Repeat("x", protocol.MaxQualityBody) |
| 326 | r.x.advance(10 * time.Second) |
| 327 | if resp, _ := r.a.report(r.sqid, "quality", r.tokA, mustJSON(t, big)); resp.StatusCode != http.StatusRequestEntityTooLarge { |
| 328 | t.Errorf("a 16 KB report: %d, want 413", resp.StatusCode) |
| 329 | } |
| 330 | r.assertClean(t) |
| 331 | } |
| 332 | |
| 333 | // The longest report the schema allows, every number at its ceiling and |
| 334 | // every peer present, still fits in one platform log line: the platform |
| 335 | // keeps 8 KB of a line and truncates the rest. |
| 336 | func TestTheLargestQualityLineFitsThePlatformsLine(t *testing.T) { |
| 337 | r := newReportRig(t, "") |
| 338 | big := func() *float64 { return num(123456789.1) } |
| 339 | ms := func() *float64 { return num(599999.9) } |
| 340 | out := func() *protocol.OutStream { |
| 341 | return &protocol.OutStream{Kbps: num(999999.9), Packets: big(), Lost: big(), RTT: ms(), Jitter: ms(), Limit: "bandwidth", |
| 342 | Width: num(16384), Height: num(16384), FPS: num(240), Keyframes: big(), Rebuilds: big(), Reshares: big(), Failures: big()} |
| 343 | } |
| 344 | in := func() *protocol.InVideo { |
| 345 | return &protocol.InVideo{Kbps: num(999999.9), Packets: big(), Lost: big(), Jitter: ms(), Freezes: big(), FreezeSeconds: num(599.9), |
| 346 | Decoded: big(), Dropped: big(), Width: num(16384), Height: num(16384), FPS: num(240), Reattaches: big()} |
| 347 | } |
| 348 | q := sampleQuality(r.peerB) |
| 349 | q.Peers = nil |
| 350 | for i := 0; i < protocol.MaxQualityPeers; i++ { |
| 351 | q.Peers = append(q.Peers, protocol.PeerQuality{ |
| 352 | Peer: protocol.PeerID(fmt.Sprintf("%032x", i)), |
| 353 | Path: &protocol.Path{Local: "unknown", Remote: "unknown", Protocol: "unknown"}, RTT: ms(), |
| 354 | Out: &protocol.Outbound{Audio: out(), Video: out(), Screen: out()}, |
| 355 | In: &protocol.Inbound{ |
| 356 | Audio: &protocol.InAudio{Kbps: num(999999.9), Packets: big(), Lost: big(), Jitter: ms(), Samples: big(), Concealed: big(), Inserted: big(), Removed: big(), JitterBufferMs: ms()}, |
| 357 | Video: in(), Screen: in(), |
| 358 | }, |
| 359 | Events: &protocol.PeerEvents{Reconnecting: big(), ReconnectingSeconds: num(599.9), CantHearSeconds: num(599.9), |
| 360 | NoSound: true, NoSoundFromUs: true, AudioBlocked: true, ScreenStalled: true}, |
| 361 | }) |
| 362 | } |
| 363 | if resp, _ := r.a.report(r.sqid, "quality", r.tokA, mustJSON(t, q)); resp.StatusCode != http.StatusAccepted { |
| 364 | t.Fatalf("the largest report: %d", resp.StatusCode) |
| 365 | } |
| 366 | line := strings.TrimSpace(r.reports.String()) |
| 367 | if n := len(line); n > 8192 { |
| 368 | t.Fatalf("the largest quality line is %d bytes; the platform keeps 8192", n) |
| 369 | } |
| 370 | } |
| 371 | |
| 372 | func TestQualityReportsAreAuthorizedByTheTokenTheSessionAndTheRoom(t *testing.T) { |
| 373 | r := newReportRig(t, "") |
| 374 | body := mustJSON(t, sampleQuality(r.peerB)) |
| 375 | other, _ := createMeeting(t, r.a, "another", "") |
| 376 | for name, try := range map[string]func() *http.Response{ |
| 377 | // Signed out never reaches the handler: the session middleware |
| 378 | // refuses it first, which is a refusal all the same. |
| 379 | "no token": func() *http.Response { resp, _ := r.a.report(r.sqid, "quality", "", body); return resp }, |
| 380 | "a made-up token": func() *http.Response { |
| 381 | resp, _ := r.a.report(r.sqid, "quality", strings.Repeat("0", 32), body) |
| 382 | return resp |
| 383 | }, |
| 384 | "a token not hex": func() *http.Response { resp, _ := r.a.report(r.sqid, "quality", "Paul", body); return resp }, |
| 385 | "B's token from A": func() *http.Response { resp, _ := r.a.report(r.sqid, "quality", r.tokB, body); return resp }, |
| 386 | "another room": func() *http.Response { resp, _ := r.a.report(other, "quality", r.tokA, body); return resp }, |
| 387 | "a room id not a room": func() *http.Response { resp, _ := r.a.report("not-a-room", "quality", r.tokA, body); return resp }, |
| 388 | "signed out": func() *http.Response { |
| 389 | c := r.x.browser(t) |
| 390 | resp, _ := c.report(r.sqid, "quality", r.tokA, body) |
| 391 | return resp |
| 392 | }, |
| 393 | } { |
| 394 | resp := try() |
| 395 | want := http.StatusNotFound |
| 396 | if name == "signed out" { |
| 397 | want = http.StatusForbidden |
| 398 | } |
| 399 | if resp.StatusCode != want { |
| 400 | t.Errorf("%s: %d, want %d", name, resp.StatusCode, want) |
| 401 | } |
| 402 | } |
| 403 | if n := len(r.reports.lines(t, "calls: quality")); n != 0 { |
| 404 | t.Fatalf("%d unauthorized reports were logged", n) |
| 405 | } |
| 406 | } |
| 407 | |
| 408 | func TestReportsOutliveTheParticipationByTenMinutes(t *testing.T) { |
| 409 | r := newReportRig(t, "") |
| 410 | if resp, _ := r.a.signal(r.sqid, r.peerA, `{"type":"leave"}`); resp.StatusCode != http.StatusOK { |
| 411 | t.Fatalf("leave: %d", resp.StatusCode) |
| 412 | } |
| 413 | final := sampleQuality(r.peerB) |
| 414 | final.Final = true |
| 415 | if resp, _ := r.a.report(r.sqid, "quality", r.tokA, mustJSON(t, final)); resp.StatusCode != http.StatusAccepted { |
| 416 | t.Fatalf("the final report after leave: %d, want 202", resp.StatusCode) |
| 417 | } |
| 418 | r.x.advance(9 * time.Minute) |
| 419 | resp, body := r.a.report(r.sqid, "problem", r.tokA, mustJSON(t, protocol.ProblemReport{Note: "it went quiet", Client: protocol.ReportClient{App: "web"}})) |
| 420 | if resp.StatusCode != http.StatusOK { |
| 421 | t.Fatalf("a problem report nine minutes after leaving: %d %s", resp.StatusCode, body) |
| 422 | } |
| 423 | lines := r.reports.lines(t, "calls: problem report") |
| 424 | if len(lines) != 1 || lines[0]["live"] != false { |
| 425 | t.Fatalf("problem lines %v, want one with live=false", lines) |
| 426 | } |
| 427 | r.x.advance(2 * time.Minute) |
| 428 | resp, _ = r.a.report(r.sqid, "problem", r.tokA, mustJSON(t, protocol.ProblemReport{Client: protocol.ReportClient{App: "web"}})) |
| 429 | if resp.StatusCode != http.StatusNotFound { |
| 430 | t.Fatalf("eleven minutes after leaving: %d, want 404", resp.StatusCode) |
| 431 | } |
| 432 | // The ended meeting: B's token keeps working for the window too. |
| 433 | if rec := r.a.post("/meetings/"+r.sqid+"/end", nil); rec.Code != http.StatusSeeOther { |
| 434 | t.Fatalf("end: %d", rec.Code) |
| 435 | } |
| 436 | if resp, _ := r.b.report(r.sqid, "quality", r.tokB, mustJSON(t, final)); resp.StatusCode != http.StatusAccepted { |
| 437 | t.Fatalf("a final report from an ended meeting: %d, want 202", resp.StatusCode) |
| 438 | } |
| 439 | r.assertClean(t) |
| 440 | } |
| 441 | |
| 442 | func TestAResumeKeepsTheTokenAndAnEmptyRoomStartsANewCall(t *testing.T) { |
| 443 | r := newReportRig(t, "") |
| 444 | // A resumed stream's hello carries the same token. |
| 445 | r.sa.close() |
| 446 | s := r.a.stream("/m/" + r.sqid + "/stream?peer=" + r.peerA) |
| 447 | peer, token := helloReport(t, s) |
| 448 | if peer != r.peerA || token != r.tokA { |
| 449 | t.Fatalf("resume: peer %s token %s, want the same participation's", peer, token) |
| 450 | } |
| 451 | s.close() |
| 452 | callOf := func(c *client, token, remote string) string { |
| 453 | t.Helper() |
| 454 | if resp, _ := c.report(r.sqid, "quality", token, mustJSON(t, sampleQuality(remote))); resp.StatusCode != http.StatusAccepted { |
| 455 | t.Fatalf("report: %d", resp.StatusCode) |
| 456 | } |
| 457 | lines := r.reports.lines(t, "calls: quality") |
| 458 | return lines[len(lines)-1]["call"].(string) |
| 459 | } |
| 460 | first := callOf(r.a, r.tokA, r.peerB) |
| 461 | for _, x := range []struct { |
| 462 | c *client |
| 463 | peer string |
| 464 | }{{r.a, r.peerA}, {r.b, r.peerB}} { |
| 465 | if resp, _ := x.c.signal(r.sqid, x.peer, `{"type":"leave"}`); resp.StatusCode != http.StatusOK { |
| 466 | t.Fatalf("leave: %d", resp.StatusCode) |
| 467 | } |
| 468 | } |
| 469 | r.sb.close() |
| 470 | // Everyone has gone: the next person in starts a new call. |
| 471 | _, peerA2, tokA2 := r.enter(t, r.a) |
| 472 | second := callOf(r.a, tokA2, peerA2) |
| 473 | if first == second { |
| 474 | t.Fatalf("an empty room's next call kept the call tag %s", first) |
| 475 | } |
| 476 | // The old token still reports under the old call. |
| 477 | if got := callOf(r.a, r.tokA, r.peerB); got != first { |
| 478 | t.Fatalf("the first call's token reports under %s, want %s", got, first) |
| 479 | } |
| 480 | } |
| 481 | |
| 482 | func TestReportRateLimits(t *testing.T) { |
| 483 | r := newReportRig(t, "") |
| 484 | body := mustJSON(t, sampleQuality(r.peerB)) |
| 485 | for i := 0; i < 6; i++ { |
| 486 | if resp, _ := r.a.report(r.sqid, "quality", r.tokA, body); resp.StatusCode != http.StatusAccepted { |
| 487 | t.Fatalf("quality report %d: %d, want 202 (burst six)", i+1, resp.StatusCode) |
| 488 | } |
| 489 | } |
| 490 | resp, _ := r.a.report(r.sqid, "quality", r.tokA, body) |
| 491 | if resp.StatusCode != http.StatusTooManyRequests || resp.Header.Get("Retry-After") == "" { |
| 492 | t.Fatalf("the seventh at once: %d (Retry-After %q), want 429 with Retry-After", resp.StatusCode, resp.Header.Get("Retry-After")) |
| 493 | } |
| 494 | // Per participation: B's budget is its own. |
| 495 | if resp, _ := r.b.report(r.sqid, "quality", r.tokB, mustJSON(t, sampleQuality(r.peerA))); resp.StatusCode != http.StatusAccepted { |
| 496 | t.Fatalf("B, after A spent its budget: %d", resp.StatusCode) |
| 497 | } |
| 498 | r.x.advance(10 * time.Second) |
| 499 | if resp, _ := r.a.report(r.sqid, "quality", r.tokA, body); resp.StatusCode != http.StatusAccepted { |
| 500 | t.Fatalf("ten seconds later: %d, want 202", resp.StatusCode) |
| 501 | } |
| 502 | |
| 503 | problem := mustJSON(t, protocol.ProblemReport{Note: "x", Client: protocol.ReportClient{App: "web"}}) |
| 504 | for i := 0; i < 3; i++ { |
| 505 | if resp, _ := r.a.report(r.sqid, "problem", r.tokA, problem); resp.StatusCode != http.StatusOK { |
| 506 | t.Fatalf("problem report %d: %d", i+1, resp.StatusCode) |
| 507 | } |
| 508 | } |
| 509 | if resp, _ := r.a.report(r.sqid, "problem", r.tokA, problem); resp.StatusCode != http.StatusTooManyRequests { |
| 510 | t.Fatalf("the fourth problem report at once: %d, want 429", resp.StatusCode) |
| 511 | } |
| 512 | } |
| 513 | |
| 514 | func TestTheKillSwitchAnswers204AndLogsNothing(t *testing.T) { |
| 515 | r := newReportRig(t, "off") |
| 516 | for _, token := range []string{r.tokA, ""} { |
| 517 | resp, _ := r.a.report(r.sqid, "quality", token, mustJSON(t, sampleQuality(r.peerB))) |
| 518 | if resp.StatusCode != http.StatusNoContent { |
| 519 | t.Fatalf("quality reports off (token %q): %d, want 204", token, resp.StatusCode) |
| 520 | } |
| 521 | } |
| 522 | if n := len(r.reports.lines(t, "calls: quality")); n != 0 { |
| 523 | t.Fatalf("%d quality lines with reports off", n) |
| 524 | } |
| 525 | // "Report a problem" is a person asking; it is not switched off. |
| 526 | if resp, _ := r.a.report(r.sqid, "problem", r.tokA, mustJSON(t, protocol.ProblemReport{Client: protocol.ReportClient{App: "web"}})); resp.StatusCode != http.StatusOK { |
| 527 | t.Fatalf("a problem report with quality reports off: %d, want 200", resp.StatusCode) |
| 528 | } |
| 529 | if !strings.Contains(r.app.String(), "quality reports off") { |
| 530 | t.Error("boot did not say quality reports are off") |
| 531 | } |
| 532 | } |
| 533 | |
| 534 | func TestAProblemReportIsLoggedUnderItsReferenceAndScrubbed(t *testing.T) { |
| 535 | r := newReportRig(t, "") |
| 536 | // What a client sends: people as "peer" and six characters of their |
| 537 | // id, and here also the full id and the meeting's address, which a |
| 538 | // client could have in a log line it did not write. |
| 539 | var diag strings.Builder |
| 540 | diag.WriteString("Calls web diagnostics\n## Call\n") |
| 541 | fmt.Fprintf(&diag, "peer %s: connection connected\nopened %s/m/%s\nfull id %s\n", r.peerB[:6], testOrigin, r.sqid, r.peerB) |
| 542 | for diag.Len() < 20_000 { |
| 543 | diag.WriteString("12:00:00.000 screen from " + r.peerB[:6] + " stalled here: \"packets\" <+0> — no packets arriving\n") |
| 544 | } |
| 545 | note := "Ana's video froze at 15:40 — " + strings.Repeat("é", 900) |
| 546 | resp, body := r.a.report(r.sqid, "problem", r.tokA, mustJSON(t, protocol.ProblemReport{ |
| 547 | Note: note, Diagnostics: diag.String(), |
| 548 | Client: protocol.ReportClient{App: "web", Version: "de04e2d", Browser: "chrome", BrowserVersion: "141.0", OS: "macos", OSVersion: "10.15.7"}, |
| 549 | })) |
| 550 | if resp.StatusCode != http.StatusOK { |
| 551 | t.Fatalf("problem: %d %s", resp.StatusCode, body) |
| 552 | } |
| 553 | var receipt protocol.ProblemReceipt |
| 554 | if err := json.Unmarshal(body, &receipt); err != nil || !regexp.MustCompile(`^[0-9A-HJKMNP-TV-Z]{8}$`).MatchString(receipt.Ref) { |
| 555 | t.Fatalf("receipt %s: want an eight-character reference", body) |
| 556 | } |
| 557 | heads := r.reports.lines(t, "calls: problem report") |
| 558 | if len(heads) != 1 { |
| 559 | t.Fatalf("%d problem report lines, want 1", len(heads)) |
| 560 | } |
| 561 | head := heads[0] |
| 562 | if head["ref"] != receipt.Ref || head["note"] != note || head["level"] != "WARN" || head["live"] != true || head["browser"] != "chrome" { |
| 563 | t.Fatalf("head line %v", head) |
| 564 | } |
| 565 | parts := r.reports.lines(t, "calls: problem report diagnostics") |
| 566 | if len(parts) < 3 || float64(len(parts)) != head["parts"] { |
| 567 | t.Fatalf("%d diagnostics lines, head says %v; want 20 KB in several", len(parts), head["parts"]) |
| 568 | } |
| 569 | var joined strings.Builder |
| 570 | for i, p := range parts { |
| 571 | if p["ref"] != receipt.Ref || p["part"] != float64(i+1) || p["of"] != float64(len(parts)) || p["call"] != head["call"] || p["peer"] != head["peer"] { |
| 572 | t.Fatalf("part %d: %v", i+1, p) |
| 573 | } |
| 574 | joined.WriteString(p["text"].(string)) |
| 575 | } |
| 576 | for _, line := range strings.Split(r.reports.String(), "\n") { |
| 577 | if len(line) > 8192 { |
| 578 | t.Fatalf("a report line of %d bytes; the platform keeps 8192", len(line)) |
| 579 | } |
| 580 | } |
| 581 | // B appears under B's tag, and the meeting as [meeting]. |
| 582 | var tagB string |
| 583 | if resp, _ := r.b.report(r.sqid, "quality", r.tokB, mustJSON(t, sampleQuality(r.peerA))); resp.StatusCode == http.StatusAccepted { |
| 584 | ls := r.reports.lines(t, "calls: quality") |
| 585 | tagB = ls[len(ls)-1]["peer"].(string) |
| 586 | } |
| 587 | text := joined.String() |
| 588 | if !strings.Contains(text, "peer peer:"+tagB+": connection connected") || !strings.Contains(text, "full id peer:"+tagB) || !strings.Contains(text, "/m/[meeting]") { |
| 589 | t.Fatalf("diagnostics not scrubbed to tags:\n%.400s", text) |
| 590 | } |
| 591 | if len(text) < 20_000 { |
| 592 | t.Fatalf("the diagnostics came back %d bytes, want all of them", len(text)) |
| 593 | } |
| 594 | r.assertClean(t) |
| 595 | |
| 596 | // The bounds: a note over a thousand characters, a body over 64 KB. |
| 597 | if resp, _ := r.a.report(r.sqid, "problem", r.tokA, mustJSON(t, protocol.ProblemReport{Note: strings.Repeat("a", 1001), Client: protocol.ReportClient{App: "web"}})); resp.StatusCode != http.StatusBadRequest { |
| 598 | t.Errorf("a 1,001-character note: %d, want 400", resp.StatusCode) |
| 599 | } |
| 600 | if resp, _ := r.a.report(r.sqid, "problem", r.tokA, mustJSON(t, protocol.ProblemReport{Diagnostics: strings.Repeat("a", 65<<10), Client: protocol.ReportClient{App: "web"}})); resp.StatusCode != http.StatusRequestEntityTooLarge { |
| 601 | t.Errorf("65 KB of diagnostics: %d, want 413", resp.StatusCode) |
| 602 | } |
| 603 | } |
| 604 | |
amadan