From 893bc4264c2b48f5960abab42a5a55572fefa746 Mon Sep 17 00:00:00 2001 From: Sanket Sudake Date: Mon, 27 Jul 2026 16:16:22 +0530 Subject: [PATCH 1/8] fix: truncation must not destroy a non-UTF-8 payload MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit TruncateText re-validated the whole prefix after dropping each byte, which only converges when the invalid byte sits at the cut boundary. A payload whose invalid bytes start earlier was trimmed all the way to "" — and the scan was quadratic, ~10ms per 64KB body on the daemon's dispatch path. netFetchBodies then checked the TRUNCATED text for validity, so the "is this text?" answer depended on size: a 10KB image was correctly reported body_unavailable, while the same image at 100KB became `"response_body": ""` with body_truncated set and Available true. Identical content, opposite answers, decided by nothing the caller can see. Truncation now backs off at most one rune's worth of bytes, and the validity check moved onto the ORIGINAL payload where it belongs. Co-Authored-By: Claude Opus 5 (1M context) --- internal/chrome/net.go | 27 +++++++++++---- internal/chrome/net_test.go | 55 +++++++++++++++++++++++++++++- internal/eventbuf/eventbuf.go | 17 +++++++-- internal/eventbuf/eventbuf_test.go | 53 ++++++++++++++++++++++++++++ 4 files changed, 142 insertions(+), 10 deletions(-) diff --git a/internal/chrome/net.go b/internal/chrome/net.go index f83fe87..9e9a333 100644 --- a/internal/chrome/net.go +++ b/internal/chrome/net.go @@ -694,6 +694,25 @@ type netBody struct { Truncated bool } +// netTextBody renders a fetched payload as an envelope body, reporting false +// for anything that is not text. +// +// The validity check is on the ORIGINAL payload, before the cap: checking the +// truncated text instead made the answer depend on SIZE. A 10 KB image was +// (correctly) reported unavailable, while the same image at 100 KB was cut to +// 64 KB — and, before the truncation fix, to "" — which passed the text check +// and was emitted as an empty-but-present body. Identical content, opposite +// answers, decided by nothing the caller can see. +func netTextBody(raw string, maxBody int) (netBody, bool) { + if !utf8.ValidString(raw) { + // A binary payload (an image, a font) is not text and must not be + // smuggled into the envelope as mojibake or as a bogus empty string. + return netBody{}, false + } + text, cut := eventbuf.TruncateText(raw, maxBody) + return netBody{Text: text, Available: true, Truncated: cut}, true +} + // render turns a retained record into the envelope object. // // Header and body keys are ABSENT (not null) unless requested, so the default @@ -917,13 +936,9 @@ func (c *CDP) netFetchBodies(ctx context.Context, id string, recs []netRecord) m if err != nil { return nil // one gone body must not abort the whole read } - text, cut := eventbuf.TruncateText(string(raw), c.netMaxBody) - if !utf8.ValidString(text) { - // A binary payload (an image, a font) is not text and must not be - // smuggled into the envelope as mojibake. - return nil + if b, ok := netTextBody(string(raw), c.netMaxBody); ok { + out[key] = b } - out[key] = netBody{Text: text, Available: true, Truncated: cut} return nil })) } diff --git a/internal/chrome/net_test.go b/internal/chrome/net_test.go index 079e443..d6cc11a 100644 --- a/internal/chrome/net_test.go +++ b/internal/chrome/net_test.go @@ -1,6 +1,7 @@ package chrome import ( + "bytes" "context" "encoding/base64" "encoding/json" @@ -788,6 +789,16 @@ func netFixtures(t *testing.T) (*httptest.Server, string) { w.Header().Set("Content-Type", "text/plain") _, _ = io_WriteString(w, strings.Repeat("A", 8<<10)) }) + // The same binary payload at two sizes, for the size-independence of the + // "this is not text" answer. 100 KB is over the 64 KB body cap; 1 KB is not. + mux.HandleFunc("/api/blob", func(w http.ResponseWriter, r *http.Request) { + n := 100 << 10 + if r.URL.Query().Get("small") != "" { + n = 1 << 10 + } + w.Header().Set("Content-Type", "application/octet-stream") + _, _ = w.Write(bytes.Repeat([]byte{0xff}, n)) + }) mux.HandleFunc("/style.css", func(w http.ResponseWriter, _ *http.Request) { w.Header().Set("Content-Type", "text/css") _, _ = io_WriteString(w, "body{color:#333}") @@ -809,8 +820,10 @@ func netFixtures(t *testing.T) (*httptest.Server, string) { + + `, - srv.URL, srv.URL, srv.URL, srv.URL, srv.URL, srv.URL, srv.URL, deadAddr(t)) + srv.URL, srv.URL, srv.URL, srv.URL, srv.URL, srv.URL, srv.URL, srv.URL, srv.URL, deadAddr(t)) mux.HandleFunc("/page", func(w http.ResponseWriter, _ *http.Request) { w.Header().Set("Content-Type", "text/html") _, _ = io_WriteString(w, page) @@ -1221,6 +1234,46 @@ func TestNetTruncatesAnOversizedBody(t *testing.T) { } } +// Regression: whether a body is text must not depend on its SIZE. +// +// The check used to run on the TRUNCATED text, so a binary payload under the cap +// was correctly reported unavailable while the same payload over the cap was cut +// (to "", before the truncation fix) and emitted as an empty-but-present body +// with body_truncated set. Identical content, opposite answers, decided by +// nothing the caller can see. +func TestNetReportsABinaryBodyAsUnavailableAtEverySize(t *testing.T) { + b := liveChrome(t) + _, page := netFixtures(t) + ctx, cancel := context.WithTimeout(context.Background(), 90*time.Second) + defer cancel() + + id := netLiveTab(ctx, t, b, page) + for _, c := range []struct { + name, button, url string + }{ + {"over the body cap", "#blobbig", "/api/blob"}, + {"under the body cap", "#blobsmall", "/api/blob?small=1"}, + } { + t.Run(c.name, func(t *testing.T) { + if _, err := b.Pointer(ctx, id, c.button, PointerOpts{Action: PointerClick}); err != nil { + t.Fatalf("Click: %v", err) + } + awaitNetDone(ctx, t, b, id, NetCond{URL: c.url}) + _, reqs := awaitNet(ctx, t, b, id, NetOpts{URL: c.url, Body: true, Limit: 10}, netDone(c.url)) + got := findURL(reqs, c.url) + if got == nil { + t.Fatalf("the binary response was not captured: %v", reqs) + } + if got["body_unavailable"] != true { + t.Errorf("a binary body was not marked body_unavailable: %v", got) + } + if got["response_body"] != nil { + t.Errorf("response_body = %q, want null — a binary payload is not text", got["response_body"]) + } + }) + } +} + // VS-9: a wait returns as soon as the request lands, not when --timeout expires. func TestNetWaitReturnsWhenTheRequestCompletes(t *testing.T) { b := liveChrome(t) diff --git a/internal/eventbuf/eventbuf.go b/internal/eventbuf/eventbuf.go index bddbfd5..7c3f67d 100644 --- a/internal/eventbuf/eventbuf.go +++ b/internal/eventbuf/eventbuf.go @@ -394,14 +394,25 @@ func (s *Set[T]) enforceTotal() { // // It is here rather than in a caller because every event-backed verb needs the // same bound (console message text, a network body) and the same subtlety: the -// cut lands on a rune boundary, so a truncated entry is still valid UTF-8 and -// still marshals into the envelope. max <= 0 means no cap. +// cut lands on a rune boundary, so a truncated entry that WAS valid UTF-8 stays +// valid and still marshals into the envelope. max <= 0 means no cap. +// +// It backs off at most utf8.UTFMax-1 bytes — the most a single rune can have on +// the wrong side of the cut — and deliberately no further. Re-validating the +// whole prefix after every byte, as this used to, is quadratic (a 64 KB body +// cost ~10 ms of scanning on the daemon's dispatch path) AND wrong: a payload +// whose invalid bytes start anywhere before the cut never converges, so it was +// trimmed to "". Truncation must not be able to destroy its input. Deciding +// whether the input is text at all is the CALLER's job, on the original bytes. func TruncateText(s string, max int) (string, bool) { if max <= 0 || len(s) <= max { return s, false } cut := s[:max] - for len(cut) > 0 && !utf8.ValidString(cut) { + for n := 0; n < utf8.UTFMax-1 && len(cut) > 0; n++ { + if r, size := utf8.DecodeLastRuneInString(cut); r != utf8.RuneError || size > 1 { + break + } cut = cut[:len(cut)-1] } return cut, true diff --git a/internal/eventbuf/eventbuf_test.go b/internal/eventbuf/eventbuf_test.go index c33450b..7859bb4 100644 --- a/internal/eventbuf/eventbuf_test.go +++ b/internal/eventbuf/eventbuf_test.go @@ -7,6 +7,7 @@ import ( "sync" "testing" "time" + "unicode/utf8" ) // line is a synthetic console-shaped entry: enough structure to exercise level, @@ -398,6 +399,58 @@ func TestTruncateText(t *testing.T) { } } +// Regression: truncation must never DESTROY its input. +// +// Re-validating the whole prefix after dropping a byte only converges when the +// invalid byte is at the cut boundary; a payload whose invalid bytes start +// earlier was trimmed all the way to "" — and a caller that then checked the +// TRUNCATED text for validity saw a perfectly valid empty string and reported a +// 100 KB binary body as an empty-but-present one. Deciding whether the input is +// text belongs to the caller, on the ORIGINAL bytes; truncation only bounds it. +func TestTruncateTextKeepsNonUTF8Payloads(t *testing.T) { + t.Parallel() + const max = 64 << 10 + cases := map[string]string{ + "all invalid": strings.Repeat("\xff", 100<<10), + "valid then invalid": strings.Repeat("a", 60<<10) + strings.Repeat("\xff", 40<<10), + "invalid then valid": strings.Repeat("\xff", 4<<10) + strings.Repeat("a", 100<<10), + "invalid at the cut end": strings.Repeat("a", max-1) + strings.Repeat("\xff", 10<<10), + } + for name, in := range cases { + t.Run(name, func(t *testing.T) { + t.Parallel() + got, cut := TruncateText(in, max) + if !cut { + t.Fatalf("a %d-byte payload was not reported as truncated at max %d", len(in), max) + } + // At most one rune's worth of bytes may be given up to land on a + // boundary. Anything more means the scan ate the payload. + if len(got) < max-(utf8.UTFMax-1) { + t.Errorf("truncation kept %d of %d bytes; it must bound the payload, not destroy it", len(got), max) + } + if !strings.HasPrefix(in, got) { + t.Error("the kept text is not a prefix of the input") + } + }) + } +} + +// A payload that IS valid UTF-8 must still be valid after the cut — that is the +// property the rune-boundary backoff exists for. +func TestTruncateTextKeepsValidTextValid(t *testing.T) { + t.Parallel() + in := strings.Repeat("héllo wörld ", 1000) // multi-byte runes at many offsets + for max := 1; max < 64; max++ { + got, _ := TruncateText(in, max) + if !utf8.ValidString(got) { + t.Fatalf("TruncateText(valid, %d) produced invalid UTF-8: %q", max, got) + } + if len(got) < max-(utf8.UTFMax-1) { + t.Fatalf("TruncateText(valid, %d) kept only %d bytes", max, len(got)) + } + } +} + // The buffer is written from CDP event goroutines and read from the RPC // dispatch, so concurrent Add/Upsert/Query must be safe (run under -race). func TestConcurrentUseIsSafe(t *testing.T) { From 7d9890630c4ef8b625c8783c286514a672bf5faf Mon Sep 17 00:00:00 2001 From: Sanket Sudake Date: Mon, 27 Jul 2026 16:17:53 +0530 Subject: [PATCH 2/8] fix: redact hash-router fragments and URL-valued headers MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit A hash router puts a whole URL in the fragment, so "#/callback?access_token=X" parsed as one parameter whose name is "/callback?access_token" — which the anchored pattern rejects, and the token was emitted verbatim. That is the OAuth implicit flow the fragment handling was added for. Separately, the 302 that ends every OAuth flow carries the code in Location: a name no credential rule matches, holding a value RedactURL was never applied to. Location/Content-Location/Referer values now go through RedactURL, so the destination stays diagnosable and the credential does not. Co-Authored-By: Claude Opus 5 (1M context) --- internal/chrome/net.go | 33 +++++++++++++++-- internal/chrome/net_test.go | 72 ++++++++++++++++++++++++++++++------- 2 files changed, 90 insertions(+), 15 deletions(-) diff --git a/internal/chrome/net.go b/internal/chrome/net.go index 9e9a333..1ae7605 100644 --- a/internal/chrome/net.go +++ b/internal/chrome/net.go @@ -772,6 +772,19 @@ func (r netRecord) render(opts NetOpts, body netBody) map[string]any { return out } +// netURLHeaders are the headers whose VALUE is a URL. Their names carry no hint +// of a credential, so the name-based rules never fire on them — but a 302 to +// "…/callback?code=SECRET" leaks the authorization code just as thoroughly as an +// Authorization header would, and that redirect is how every OAuth flow ends. +// Their values go through RedactURL instead of being withheld wholesale, so a +// redirect stays diagnosable. +var netURLHeaders = map[string]bool{ + "location": true, + "content-location": true, + "referer": true, + "referrer": true, +} + // RedactHeaders returns a copy of h with credential-shaped values replaced. // noRedact returns the map unchanged, which is the ONLY way a live session token // reaches the envelope. @@ -781,8 +794,12 @@ func RedactHeaders(h map[string]string, noRedact bool) map[string]string { } out := make(map[string]string, len(h)) for k, v := range h { - if !noRedact && RedactedHeaderName(k) { + switch { + case noRedact: + case RedactedHeaderName(k): v = NetRedacted + case netURLHeaders[strings.ToLower(strings.TrimSpace(k))]: + v = RedactURL(v) } out[k] = v } @@ -816,7 +833,19 @@ func RedactURL(raw string) string { if hasFrag { // OAuth implicit flows return the token in the fragment, so it gets the // same treatment; a plain "#section" has no "=" and is left alone. - out += "#" + redactParams(frag) + // + // A hash ROUTER puts a whole URL in the fragment + // ("#/callback?access_token=…"), so the fragment gets the same + // path/query split the main URL does. Without it the single parameter + // parsed as the name "/callback?access_token", which the anchored + // pattern rejects — and the token was emitted verbatim, in exactly the + // OAuth-implicit case fragment handling was added for. + fpath, fquery, hasFragQuery := strings.Cut(frag, "?") + if hasFragQuery { + out += "#" + fpath + "?" + redactParams(fquery) + } else { + out += "#" + redactParams(frag) + } } return out } diff --git a/internal/chrome/net_test.go b/internal/chrome/net_test.go index d6cc11a..8b9da21 100644 --- a/internal/chrome/net_test.go +++ b/internal/chrome/net_test.go @@ -331,23 +331,64 @@ func TestRedactHeadersReplacesValuesNotNames(t *testing.T) { } } +// A header whose VALUE is a URL leaks through both rules: its name says nothing +// about credentials, so the name-based redaction never fires, and RedactURL is +// applied to the record's own URL and not to header values. The 302 that ends +// every OAuth flow carries the authorization code in exactly that position. +func TestRedactHeadersRedactsURLValuedHeaders(t *testing.T) { + t.Parallel() + in := map[string]string{ + "Location": "https://app.example/callback?code=SECRETCODE&state=s", + "Referer": "https://app.example/#/cb?access_token=SECRETTOKEN", + "Content-Type": "text/html", + } + got := RedactHeaders(in, false) + for name, v := range got { + if strings.Contains(v, "SECRET") { + t.Errorf("%s = %q — a credential rode along in a URL-valued header", name, v) + } + } + // The redirect must stay diagnosable: only the value is withheld, not the + // destination. + if !strings.HasPrefix(got["Location"], "https://app.example/callback?code=") { + t.Errorf("Location = %q, want the destination preserved", got["Location"]) + } + if !strings.HasSuffix(got["Location"], "&state=s") { + t.Errorf("Location = %q, want the non-credential parameters preserved", got["Location"]) + } + if got["Content-Type"] != "text/html" { + t.Errorf("an ordinary header was rewritten: %q", got["Content-Type"]) + } + if raw := RedactHeaders(in, true); raw["Location"] != in["Location"] { + t.Errorf("--no-redact did not return the real value: %q", raw["Location"]) + } +} + // RFC-0003 open question 2: a token in a query string leaks exactly as badly as // one in a header, and an OAuth implicit flow puts it in the fragment. func TestRedactURL(t *testing.T) { t.Parallel() cases := map[string]struct{ in, want string }{ - "no query": {"https://app.example/api/save", "https://app.example/api/save"}, - "ordinary params": {"https://app.example/s?q=hours&page=2", "https://app.example/s?q=hours&page=2"}, - "access_token": {"https://app.example/cb?access_token=abc123", "https://app.example/cb?access_token=" + NetRedacted}, - "api_key": {"https://maps.example/v1?api_key=k1&z=3", "https://maps.example/v1?api_key=" + NetRedacted + "&z=3"}, - "bare key": {"https://maps.example/v1?key=AIzaSy&x=1", "https://maps.example/v1?key=" + NetRedacted + "&x=1"}, - "signature": {"https://cdn.example/f?sig=deadbeef", "https://cdn.example/f?sig=" + NetRedacted}, - "oauth code": {"https://app.example/cb?code=xyz&state=s", "https://app.example/cb?code=" + NetRedacted + "&state=s"}, - "fragment token": {"https://app.example/cb#access_token=abc&token_type=bearer", "https://app.example/cb#access_token=" + NetRedacted + "&token_type=bearer"}, - "plain fragment": {"https://app.example/doc#section-3", "https://app.example/doc#section-3"}, - "percent-encoded key": {"https://app.example/x?api%5Fkey=zzz", "https://app.example/x?api%5Fkey=" + NetRedacted}, - "case insensitive": {"https://app.example/x?Access_Token=zzz", "https://app.example/x?Access_Token=" + NetRedacted}, - "empty": {"", ""}, + "no query": {"https://app.example/api/save", "https://app.example/api/save"}, + "ordinary params": {"https://app.example/s?q=hours&page=2", "https://app.example/s?q=hours&page=2"}, + "access_token": {"https://app.example/cb?access_token=abc123", "https://app.example/cb?access_token=" + NetRedacted}, + "api_key": {"https://maps.example/v1?api_key=k1&z=3", "https://maps.example/v1?api_key=" + NetRedacted + "&z=3"}, + "bare key": {"https://maps.example/v1?key=AIzaSy&x=1", "https://maps.example/v1?key=" + NetRedacted + "&x=1"}, + "signature": {"https://cdn.example/f?sig=deadbeef", "https://cdn.example/f?sig=" + NetRedacted}, + "oauth code": {"https://app.example/cb?code=xyz&state=s", "https://app.example/cb?code=" + NetRedacted + "&state=s"}, + "fragment token": {"https://app.example/cb#access_token=abc&token_type=bearer", "https://app.example/cb#access_token=" + NetRedacted + "&token_type=bearer"}, + "plain fragment": {"https://app.example/doc#section-3", "https://app.example/doc#section-3"}, + // A hash ROUTER puts a whole URL in the fragment, so the fragment needs + // the same path/query split the main URL gets. Parsed as one parameter + // list, the name reads "/callback?access_token" and the token sails + // through — in exactly the OAuth implicit flow this handling exists for. + "hash router query": {"https://app.example/#/callback?access_token=abc123", "https://app.example/#/callback?access_token=" + NetRedacted}, + "hash router mixed": {"https://app.example/#/cb?state=s&id_token=abc", "https://app.example/#/cb?state=s&id_token=" + NetRedacted}, + "hash router no query": {"https://app.example/#/settings/profile", "https://app.example/#/settings/profile"}, + "hash router harmless": {"https://app.example/#/list?page=2", "https://app.example/#/list?page=2"}, + "percent-encoded key": {"https://app.example/x?api%5Fkey=zzz", "https://app.example/x?api%5Fkey=" + NetRedacted}, + "case insensitive": {"https://app.example/x?Access_Token=zzz", "https://app.example/x?Access_Token=" + NetRedacted}, + "empty": {"", ""}, } for name, c := range cases { t.Run(name, func(t *testing.T) { @@ -378,7 +419,9 @@ func TestRedactionKeepsCredentialsOutOfTheMarshalledEnvelope(t *testing.T) { const cookie = "sid=deadbeefcafe" r := netRecord{ ID: "req-1", Method: "POST", Type: "xhr", - URL: "https://app.example/api/save?access_token=" + secret, + // A hash-router callback: the token is in the fragment's QUERY string, + // which is where an OAuth implicit flow behind a hash router puts it. + URL: "https://app.example/#/callback?access_token=" + secret, HasStatus: true, Status: 200, StatusText: "OK", Finished: true, ReqHeaders: map[string]string{ "Authorization": "Bearer " + secret, @@ -389,6 +432,9 @@ func TestRedactionKeepsCredentialsOutOfTheMarshalledEnvelope(t *testing.T) { RespHeaders: map[string]string{ "Set-Cookie": cookie + "; HttpOnly", "Content-Type": "application/json", + // The redirect that ends an OAuth flow: no credential-shaped name, + // a live credential in the value. + "Location": "https://app.example/done?code=" + secret, }, } env := result.Envelope{ From 370afd4636cae4d2c823f5f06c0392243a91228c Mon Sep 17 00:00:00 2001 From: Sanket Sudake Date: Mon, 27 Jul 2026 16:22:01 +0530 Subject: [PATCH 3/8] fix: guard and redact request/response bodies MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit netPostData was stored raw and rendered straight into the envelope, where json.Marshal turns invalid bytes into U+FFFD — so a multipart image upload under the 64KB cap arrived as mojibake, the exact thing the response path refuses to do. Request bodies now get the same is-this-text guard, reported as request_body_unavailable. Neither body was redacted on any path, so `net --body` on a login POST printed password=... in clear while the SAME credential in ?password=... was withheld: the same secret, opposite answers, decided by nothing but the HTTP method. RFC-0003 US-5 asks for bodies that do not spill tokens into logs by default, so credential-shaped fields in form-encoded and JSON bodies are now redacted, with --no-redact the explicit opt-out. It is a structure-preserving rewrite rather than a decode/re-encode: a body cut at the cap is not parseable any more, and re-encoding would stop the reported payload being the one the page sent. Co-Authored-By: Claude Opus 5 (1M context) --- internal/chrome/net.go | 116 +++++++++++++++++++++++++++++++++--- internal/chrome/net_test.go | 100 ++++++++++++++++++++++++++++++- 2 files changed, 205 insertions(+), 11 deletions(-) diff --git a/internal/chrome/net.go b/internal/chrome/net.go index 1ae7605..62cd0de 100644 --- a/internal/chrome/net.go +++ b/internal/chrome/net.go @@ -136,8 +136,14 @@ type netRecord struct { // RequestBody arrives inline with requestWillBeSent, so retaining it costs // nothing extra and makes US-4 ("what did that button POST?") answerable // after the fact. Response bodies are NOT retained — see netFetchBodies. + // + // RequestBodyBinary marks a payload that is not text (a multipart image + // upload). It is retained as empty rather than raw: json.Marshal replaces + // invalid bytes with U+FFFD, so keeping it would put mojibake in the + // envelope — the exact thing the response path refuses to do. RequestBody string RequestBodyTruncated bool + RequestBodyBinary bool // Finished marks the request as complete (loadingFinished or loadingFailed // arrived). Everything else is `pending`, which is what lets a caller tell @@ -310,7 +316,7 @@ func netApply(ev any, maxBody int, epoch time.Time) (string, func(netRecord, boo req := e.Request ts := netTime(e.Timestamp) raw := netPostData(req) - body, cut := eventbuf.TruncateText(raw, maxBody) + body, cut, binary := netRequestBody(raw, maxBody) typ := netType(e.Type) return key, func(r netRecord, _ bool) netRecord { r.ID = key @@ -320,7 +326,7 @@ func netApply(ev any, maxBody int, epoch time.Time) (string, func(netRecord, boo r.Type = typ } r.ReqHeaders = netHeaders(req.Headers) - r.RequestBody, r.RequestBodyTruncated = body, cut + r.RequestBody, r.RequestBodyTruncated, r.RequestBodyBinary = body, cut, binary r.RequestSize = int64(len(raw)) // A redirect reuses the request id and re-fires this event; keeping // the FIRST start keeps duration_ms the whole chain's cost rather @@ -488,6 +494,24 @@ func netPostData(req *network.Request) string { return b.String() } +// netRequestBody bounds a request body for retention, reporting a payload that +// is not text separately from one that is simply absent. +// +// The retained record feeds json.Marshal, which replaces invalid bytes with +// U+FFFD — so a multipart image upload under the cap would arrive in the +// envelope as mojibake, which is precisely what the response path refuses to +// do. Same rule, same reason, both directions. +func netRequestBody(raw string, maxBody int) (text string, truncated, binary bool) { + if raw == "" { + return "", false, false + } + if !utf8.ValidString(raw) { + return "", false, true + } + text, truncated = eventbuf.TruncateText(raw, maxBody) + return text, truncated, false +} + // NormalizeNetType maps a user-supplied --type onto the documented vocabulary, // reporting whether it is one of them. A few obvious aliases (css, img, ws) are // accepted because they are what people type. @@ -755,11 +779,16 @@ func (r netRecord) render(opts NetOpts, body netBody) map[string]any { if opts.Body { out["request_body"] = nil if r.RequestBody != "" { - out["request_body"] = r.RequestBody + out["request_body"] = RedactBody(r.RequestBody, opts.NoRedact) + } + if r.RequestBodyBinary { + // Same contract as body_unavailable, for the other direction: the + // body existed, and what it held is not something we can show. + out["request_body_unavailable"] = true } out["response_body"] = nil if body.Available { - out["response_body"] = body.Text + out["response_body"] = RedactBody(body.Text, opts.NoRedact) } else { // A body the page has navigated away from is gone, and saying so is // more useful than failing the whole read (VS-14). @@ -862,17 +891,86 @@ func redactParams(q string) string { if !ok { continue } - decoded := name - if u, err := netUnescape(name); err == nil { - decoded = u - } - if netRedactParamRe.MatchString(strings.TrimSpace(decoded)) { + if RedactedParamName(name) { parts[i] = name + "=" + NetRedacted } } return strings.Join(parts, "&") } +// RedactedParamName reports whether a URL parameter or request/response body +// FIELD name is credential-shaped. One predicate for both, because a value is +// no less a secret for having travelled in a POST body than in a query string. +func RedactedParamName(name string) bool { + n := strings.TrimSpace(name) + if u, err := netUnescape(n); err == nil { + n = u + } + return netRedactParamRe.MatchString(n) +} + +// netRedactJSONRe matches one JSON member with a STRING value, capturing the +// member name and the separator so a replacement can keep the document's own +// spacing and escaping. Deliberately a rewrite rather than a decode/re-encode: +// a body that hit the size cap is not parseable JSON any more, and re-encoding +// would reorder members and rewrite escapes, so the reported payload would stop +// being the one the page actually sent. +var netRedactJSONRe = regexp.MustCompile(`"((?:[^"\\]|\\.)*)"(\s*:\s*)"(?:[^"\\]|\\.)*"`) + +// RedactBody withholds the values of credential-shaped fields in a request or +// response body, for the form-encoded and JSON shapes credentials actually +// travel in. noRedact returns the body unchanged. +// +// RFC-0003 specifies redaction for headers and URLs only, so this goes beyond +// it deliberately. The premise of the whole tool is that it drives the user's +// real, logged-in browser: `net --body` on a login POST printed `password=…` in +// clear, while the SAME credential in `?password=…` was withheld — the same +// secret, opposite answers, decided by nothing but the HTTP method. US-5 asks +// for bodies that do "not spill tokens or PII into logs by default", and this +// is what that costs. +// +// A body in any other encoding (multipart/form-data, protobuf, a bare token) is +// passed through: there is no field structure to key on, and guessing would +// either miss or mangle. `--body` remains an explicit opt-in either way. +func RedactBody(body string, noRedact bool) string { + if noRedact || body == "" { + return body + } + switch { + case netLooksJSON(body): + return netRedactJSONRe.ReplaceAllStringFunc(body, func(m string) string { + g := netRedactJSONRe.FindStringSubmatch(m) + if !RedactedParamName(g[1]) { + return m + } + return `"` + g[1] + `"` + g[2] + `"` + NetRedacted + `"` + }) + case netLooksFormEncoded(body): + return redactParams(body) + } + return body +} + +// netLooksJSON reports whether a body is a JSON object or array. +func netLooksJSON(body string) bool { + t := strings.TrimLeft(body, " \t\r\n") + return strings.HasPrefix(t, "{") || strings.HasPrefix(t, "[") +} + +// netLooksFormEncoded reports whether a body is an application/x-www-form- +// urlencoded parameter list, judged on its first field: a name with no +// whitespace or JSON punctuation, followed by "=". The content-type header +// would be a stronger signal, but it is not always sent and this has to hold +// for a truncated body too. +func netLooksFormEncoded(body string) bool { + head, _, _ := strings.Cut(body, "&") + name, _, ok := strings.Cut(head, "=") + if !ok || name == "" { + return false + } + return !strings.ContainsAny(name, " \t\r\n\"'{}[]<>") +} + // netUnescape decodes a percent-encoded parameter name, so "api%5Fkey" is // recognised as api_key rather than sailing past the pattern. func netUnescape(s string) (string, error) { diff --git a/internal/chrome/net_test.go b/internal/chrome/net_test.go index 8b9da21..6ea372f 100644 --- a/internal/chrome/net_test.go +++ b/internal/chrome/net_test.go @@ -406,6 +406,91 @@ func TestRedactURL(t *testing.T) { } } +// Bodies are redacted on the same terms as headers and URLs. RFC-0003 does not +// specify it; the tool drives the user's real logged-in browser, and a password +// is no less a secret for having travelled in a POST body than in a query +// string — which is already withheld. +func TestRedactBody(t *testing.T) { + t.Parallel() + cases := map[string]struct{ in, want string }{ + "form login": { + "username=alice&password=hunter2&remember=1", + "username=alice&password=" + NetRedacted + "&remember=1", + }, + "form ordinary": {"hours=8&project=apollo", "hours=8&project=apollo"}, + "form token": {"grant_type=refresh_token&refresh_token=abc", "grant_type=refresh_token&refresh_token=" + NetRedacted}, + "json login": { + `{"username":"alice","password":"hunter2"}`, + `{"username":"alice","password":"` + NetRedacted + `"}`, + }, + "json spacing preserved": { + `{ "api_key" : "k1", "n" : 3 }`, + `{ "api_key" : "` + NetRedacted + `", "n" : 3 }`, + }, + "json nested": { + `{"auth":{"client_secret":"s3cr3t"},"ok":true}`, + `{"auth":{"client_secret":"` + NetRedacted + `"},"ok":true}`, + }, + "json ordinary": {`{"hours":8,"note":"password reset requested"}`, `{"hours":8,"note":"password reset requested"}`}, + "json array value": {`{"scopes":["token","read"]}`, `{"scopes":["token","read"]}`}, + // A body cut at the cap is no longer parseable JSON; the rewrite still + // has to redact whatever members survived it, which is why this is a + // rewrite and not a decode/re-encode. + "truncated json": { + `{"password":"hunter2","next":"x`, + `{"password":"` + NetRedacted + `","next":"x`, + }, + // Nothing to key on: no field structure, so it passes through. `--body` + // is an explicit opt-in either way. + "opaque body": {"--boundary\r\nContent-Disposition: form-data\r\n", "--boundary\r\nContent-Disposition: form-data\r\n"}, + "empty": {"", ""}, + } + for name, c := range cases { + t.Run(name, func(t *testing.T) { + t.Parallel() + if got := RedactBody(c.in, false); got != c.want { + t.Errorf("RedactBody(%q) = %q, want %q", c.in, got, c.want) + } + // --no-redact is the explicit opt-out, and it must be exact. + if got := RedactBody(c.in, true); got != c.in { + t.Errorf("--no-redact rewrote the body: %q", got) + } + }) + } +} + +// A request body that is not text must be reported as unavailable, not smuggled +// into the envelope: json.Marshal replaces invalid bytes with U+FFFD, so a +// multipart image upload under the cap arrived as mojibake — exactly what the +// response path already refuses to do. +func TestNetRequestBodyRejectsBinary(t *testing.T) { + t.Parallel() + binary := "\x89PNG\r\n\x1a\n" + strings.Repeat("\xff", 512) + b := netFeed(t, 10, willBeSent("r1", "POST", "https://app.example/upload", 0, network.ResourceTypeXHR, nil, binary)) + rec := only(t, b) + if rec.RequestBody != "" { + t.Errorf("RequestBody = %q, want it withheld: it is not text", rec.RequestBody) + } + if !rec.RequestBodyBinary { + t.Fatal("a binary request body was not marked; it would reach the envelope as U+FFFD mojibake") + } + if rec.RequestSize != int64(len(binary)) { + t.Errorf("request_size = %d, want the real %d — the size is knowable even when the bytes are not shown", rec.RequestSize, len(binary)) + } + got := rec.render(NetOpts{Body: true}, netBody{}) + if got["request_body"] != nil { + t.Errorf("request_body = %v, want null", got["request_body"]) + } + if got["request_body_unavailable"] != true { + t.Error("request_body_unavailable is not set; a caller cannot tell a withheld body from an absent one") + } + // And a TEXT body still arrives intact. + b = netFeed(t, 10, willBeSent("r2", "POST", "https://app.example/api", 0, network.ResourceTypeXHR, nil, `{"hours":8}`)) + if rec := only(t, b); rec.RequestBody != `{"hours":8}` || rec.RequestBodyBinary { + t.Errorf("a text body was withheld: %q binary=%v", rec.RequestBody, rec.RequestBodyBinary) + } +} + // THE security regression test. // // It asserts on the MARSHALLED ENVELOPE BYTES, not on a struct field, because @@ -436,13 +521,16 @@ func TestRedactionKeepsCredentialsOutOfTheMarshalledEnvelope(t *testing.T) { // a live credential in the value. "Location": "https://app.example/done?code=" + secret, }, + // A login POST: the credential is in the body, which `--body` prints. + RequestBody: "username=alice&password=" + secret, } env := result.Envelope{ OK: true, Command: "net", Target: &result.TargetInfo{ID: "aa11", Title: "App", URL: "https://app.example/"}, Result: map[string]any{ - "requests": []any{r.render(NetOpts{Headers: true}, netBody{})}, - "count": 1, "buffered": 1, "dropped": 0, "truncated": false, "pending": 0, + "requests": []any{r.render(NetOpts{Headers: true, Body: true}, + netBody{Text: `{"access_token":"` + secret + `"}`, Available: true})}, + "count": 1, "buffered": 1, "dropped": 0, "truncated": false, "pending": 0, }, } raw, err := env.JSON() @@ -465,6 +553,8 @@ func TestRedactionKeepsCredentialsOutOfTheMarshalledEnvelope(t *testing.T) { RequestHeaders map[string]string `json:"request_headers"` ResponseHeaders map[string]string `json:"response_headers"` URL string `json:"url"` + RequestBody string `json:"request_body"` + ResponseBody string `json:"response_body"` } `json:"requests"` } `json:"result"` } @@ -486,6 +576,12 @@ func TestRedactionKeepsCredentialsOutOfTheMarshalledEnvelope(t *testing.T) { if !strings.HasSuffix(got.URL, "access_token="+NetRedacted) { t.Errorf("url = %q, want the access_token value withheld", got.URL) } + if got.RequestBody != "username=alice&password="+NetRedacted { + t.Errorf("request_body = %q, want the password withheld and the rest intact", got.RequestBody) + } + if got.ResponseBody != `{"access_token":"`+NetRedacted+`"}` { + t.Errorf("response_body = %q, want the token withheld and the shape intact", got.ResponseBody) + } // --no-redact is the ONLY path that emits the real value, and it must // actually work — otherwise the flag is a lie and people stop trusting it. From 699e1a80855c68c8cddfe885c7ce9130be891003 Mon Sep 17 00:00:00 2001 From: Sanket Sudake Date: Mon, 27 Jul 2026 16:35:15 +0530 Subject: [PATCH 4/8] fix: capture the pre-attach backlog instead of dropping it MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit chromedp's own attach sequence issues Runtime.enable and Log.enable, and those enables are what flush what the page did before we arrived. startCapture registered its listeners AFTER chromedp.Run — i.e. after the attach — so the entire backlog went on the floor. A daemon attaching to a tab that had already thrown answered `console --only-errors` with an empty list, exit 0, no note: the reader concludes the page is clean. RFC-0002 US-1 exactly inverted. Listeners now go on before the attach, split from the (idempotent) domain enables that follow it. Log.entryAdded with source "javascript" is no longer dropped by source either — that was the second half of the same loss; the console-api arm of that condition was dead code, since log.Source.UnmarshalJSON errors on unknown values and such an event never decodes. Duplicates are suppressed by identity within a short window instead, so one exception reported twice stays one message while a genuinely recurring error stays visible. Consequence: a --no-daemon read now does see some history, so it reports the real `buffered` and its note says "partial" rather than "none" — claiming zero next to a non-empty list would make both numbers useless. Co-Authored-By: Claude Opus 5 (1M context) --- docs/cli-reference.md | 7 +- internal/chrome/cdp.go | 19 ++- internal/chrome/console.go | 182 +++++++++++++++++++++------- internal/chrome/console_test.go | 206 ++++++++++++++++++++++++++++---- internal/chrome/net.go | 41 +++---- internal/chrome/net_test.go | 20 ++-- internal/cli/console.go | 3 +- 7 files changed, 377 insertions(+), 101 deletions(-) diff --git a/docs/cli-reference.md b/docs/cli-reference.md index a019c4b..9f38dd4 100644 --- a/docs/cli-reference.md +++ b/docs/cli-reference.md @@ -382,8 +382,9 @@ Raise `console_buffer`, or read closer to the action. **`--follow`** writes one JSON envelope per line, the same shape `session` streams. It cannot combine with `--fail-on-match`, and it is a usage error inside `session` or a recipe step, where it would break the one-envelope-per-line contract a batch promises. -**`--no-daemon` has no retained history.** -Without the daemon there was no process alive to receive the tab's earlier events, so the read reports `"buffered": 0` and carries a `note` saying so, rather than passing an empty list off as a quiet page. +**`--no-daemon` has only partial history.** +Without the daemon there was no process alive to receive the tab's earlier events, so what appears is whatever Chrome replays when capture is enabled (recent console output and uncaught exceptions it still holds) plus what arrives during the command. +The read carries a `note` saying so, rather than passing a short list off as a full session record. The buffer is bounded by `console_buffer` (messages per tab, default 1000) and `console_max_entry` (per-message text cap, default 8192 bytes); see [Configuration](#configuration). @@ -458,7 +459,7 @@ No match before `--timeout` is `target_timeout` / exit 4. **`--follow`** writes one JSON envelope per **completed** request, the same shape `session` streams. It cannot combine with `--fail-on-match`, and it is a usage error inside `session` or a recipe step. -**`--no-daemon` has no retained history**, exactly as with `console`: the read reports `"buffered": 0` and carries a `note` rather than passing an empty list off as a quiet page. +**`--no-daemon` has only partial history**, exactly as with `console`: enabling the domain surfaces the handful of resources Chrome still holds for the page, never the session, so the read carries a `note` rather than passing a short list off as the whole story. Bad `--status` / `--type` / `--url` regex / `--since` values are `usage` / exit 2, validated before anything connects to Chrome. diff --git a/internal/chrome/cdp.go b/internal/chrome/cdp.go index 96546c6..7a215f2 100644 --- a/internal/chrome/cdp.go +++ b/internal/chrome/cdp.go @@ -323,16 +323,25 @@ func (c *CDP) on(id string) (context.Context, error) { return t.ctx, nil } tctx, cancel := chromedp.NewContext(c.base, chromedp.WithTargetID(cdptarget.ID(id))) + // Event capture starts at ATTACH, not at the first `console`/`net` read: + // the process holding the connection has to already be listening when the + // page logs, or an observability verb can only report what happened after + // somebody thought to look. See listenCapture in console.go. + // + // The listeners go on BEFORE chromedp.Run, which is the attach. chromedp's + // own attach sequence issues Runtime.enable and Log.enable itself, and + // Log.enable is what flushes "the entries collected so far" — so a listener + // registered after the attach misses that flush entirely, and with it the + // ONLY record of anything the page did before we arrived (Runtime.enable + // replays nothing). ListenTarget before Run is supported: the callback is + // held on the context and attached to the target before those enables run. + c.listenCapture(tctx, id) if err := chromedp.Run(tctx); err != nil { // attach once, tied to tctx cancel() return nil, err } c.tabs[id] = tabConn{ctx: tctx, stop: cancel} - // Event capture starts at ATTACH, not at the first `console`/`net` read: - // the process holding the connection has to already be listening when the - // page logs, or an observability verb can only report what happened after - // somebody thought to look. See startCapture in console.go. - c.startCapture(tctx, id) + c.enableCapture(tctx, id) return tctx, nil } diff --git a/internal/chrome/console.go b/internal/chrome/console.go index 95c4c70..a6f3ae7 100644 --- a/internal/chrome/console.go +++ b/internal/chrome/console.go @@ -6,6 +6,7 @@ import ( "fmt" "regexp" "strings" + "sync" "time" cdplog "github.com/chromedp/cdproto/log" @@ -49,11 +50,14 @@ const ( // reader that cannot keep up drops rather than stalls Chrome. consoleStreamBacklog = 256 - // noRetainedHistoryNote is the honest answer when nothing was listening - // before this command started. Reporting an empty list without it would let - // a caller conclude the page was silent. - noRetainedHistoryNote = "no retained history: nothing was listening to this tab before this command started, " + - "so only messages emitted during it can appear. Use the daemon (drop --no-daemon) to retain history, or --follow to watch from here." + // partialHistoryNote is the honest answer when nothing was listening before + // this command started. Some history does arrive — Chrome replays what it + // retained when capture is enabled — but it is Chrome's window, not ours, + // and it is neither complete nor bounded by anything the caller set. Saying + // so is what stops a short list being read as "the page was quiet". + partialHistoryNote = "partial history: nothing was listening to this tab before this command started, so what appears is " + + "whatever Chrome replayed when capture was enabled, plus what arrived during this command. " + + "Use the daemon (drop --no-daemon) to retain everything from the moment it attached, or --follow to watch from here." ) // consoleMessage is one retained console line or uncaught exception. @@ -129,18 +133,38 @@ func (c *CDP) attached(id string) bool { return ok } -// startCapture turns on the CDP event capture for a freshly attached tab. It is -// called from on(), under c.mu, exactly once per tab. +// listenCapture registers every event-capture listener for a tab. It is called +// from on(), under c.mu, exactly once per tab — and BEFORE the attach, so the +// backlog Log.enable flushes during chromedp's own attach sequence is received +// rather than dropped on the floor. // // This is the hook every event-backed verb shares; RFC-0003's network capture -// starts here too. -func (c *CDP) startCapture(tctx context.Context, id string) { - c.startConsoleCapture(tctx, id) - c.startNetCapture(tctx, id) +// and RFC-0011's screencast register here too. +func (c *CDP) listenCapture(tctx context.Context, id string) { + c.listenConsole(tctx, id) + c.listenNet(tctx, id) c.startRecordCapture(tctx, id) } -// startConsoleCapture retains console output and uncaught exceptions for a tab. +// enableCapture turns the CDP domains on after the attach. +// +// It is best-effort and separate from listenCapture for two reasons. Every verb +// attaches, so a target that refuses Runtime/Log/Network (a chrome:// page, say) +// must not have `click` broken by an observability feature it never used — +// Console and Net re-enable at read time and DO report the failure, so the +// honesty is paid for where it is asked for. And chromedp's attach already +// enables all three, so this is the idempotent belt to that braces: it matters +// only when a future chromedp drops one of them. +func (c *CDP) enableCapture(tctx context.Context, id string) { + // Bounded so a wedged target cannot hang the attach; cancelling this child + // never closes the tab (only chromedp's own NewContext contexts do). + ectx, cancel := context.WithTimeout(tctx, 5*time.Second) + defer cancel() + _ = chromedp.Run(ectx, consoleEnable()...) + _ = chromedp.Run(ectx, netEnable(c.netMaxBody)...) +} + +// listenConsole retains console output and uncaught exceptions for a tab. // // It runs at ATTACH, not at the first `console` read, and that is the whole // design: the process holding the connection has to already be listening when @@ -151,28 +175,109 @@ func (c *CDP) startCapture(tctx context.Context, id string) { // as the buffer, rather than on a per-command context whose cancel would take // the subscription with it. It runs on chromedp's event loop, so it only ever // appends to an in-memory buffer and never issues a CDP command. -// -// Enabling the domains is best-effort HERE, because every verb attaches: a -// target that refuses Runtime/Log (a chrome:// page, say) must not have `click` -// broken by a console feature it never used. Console re-enables at read time -// and does report the failure, so the honesty is paid for where it is asked -// for. -func (c *CDP) startConsoleCapture(tctx context.Context, id string) { +func (c *CDP) listenConsole(tctx context.Context, id string) { set := c.consoleBuf() maxEntry := c.consoleMaxEntry + dedup := &consoleDedup{} chromedp.ListenTarget(tctx, func(ev any) { - if m, ok := consoleEvent(ev, maxEntry); ok { - set.Add(id, m) + m, ok := consoleEvent(ev, maxEntry) + if !ok { + return } + if ident, collidable := consoleDedupIdent(ev, m); collidable && !dedup.first(ident, m.TS) { + return + } + set.Add(id, m) }) - // Bounded so a wedged target cannot hang the attach; cancelling this child - // never closes the tab (only chromedp's own NewContext contexts do). The - // error is swallowed HERE because every verb attaches — but Console - // re-enables and does report it, so a tab whose capture cannot start - // answers `cdp_error` rather than a silently empty console. - ectx, cancel := context.WithTimeout(tctx, 5*time.Second) - defer cancel() - _ = chromedp.Run(ectx, consoleEnable()...) +} + +// consoleDedup suppresses a SECOND report of the same message. +// +// Chrome can describe one uncaught exception twice: Runtime.exceptionThrown and +// Log.entryAdded with source "javascript". Suppressing the second by SOURCE, as +// this used to, throws away the pre-attach backlog along with the duplicates — +// Log.enable's replay of "the entries collected so far" is the ONLY record of an +// error that predates the attach, and Runtime.enable replays nothing. A page +// that had already thrown answered `console --only-errors` with an empty list +// and exit 0, which reads as "the page is clean": RFC-0002 US-1 exactly +// inverted. +// +// So duplicates are judged on IDENTITY — what was said, and where — inside a +// short window, and the backlog survives. The window matters: an app that throws +// the same error on every poll is reporting a real repeat, not a duplicate. +type consoleDedup struct { + mu sync.Mutex + recent []consoleSeen +} + +type consoleSeen struct { + ident string + ts time.Time +} + +const ( + // consoleDedupWindow is how close two reports must be to be the same event. + // The two CDP events for one exception are emitted together, so this only + // has to survive event-loop jitter — while staying far below the interval at + // which a genuinely repeating error repeats. + consoleDedupWindow = 2 * time.Second + + // consoleDedupDepth bounds what the dedupe remembers. A burst of distinct + // errors must not push the window's worth of identities out, and a day-long + // session must not accumulate them. + consoleDedupDepth = 64 +) + +// first records a report and reports whether it is the first one for ident +// within the window. +func (d *consoleDedup) first(ident string, ts time.Time) bool { + d.mu.Lock() + defer d.mu.Unlock() + kept := d.recent[:0] + seen := false + for _, e := range d.recent { + if ts.Sub(e.ts).Abs() > consoleDedupWindow { + continue // outside the window: a genuine repeat, not a duplicate + } + if e.ident == ident { + seen = true + } + kept = append(kept, e) + } + d.recent = append(kept, consoleSeen{ident: ident, ts: ts}) + if len(d.recent) > consoleDedupDepth { + d.recent = d.recent[len(d.recent)-consoleDedupDepth:] + } + return !seen +} + +// consoleDedupIdent returns the identity a duplicate is judged on, and whether +// this event is one of the two shapes that can describe the same thing. +// +// Only an uncaught exception can arrive twice, so only those two shapes are +// deduped: a page that logs the same line twice on purpose must still see both. +// The identity is the message text with the noise the two reports differ on +// stripped — Log's entry says "Uncaught TypeError: …" where Runtime's says +// "TypeError: …" — plus the file it came from. Line numbers are deliberately +// NOT part of it: the two domains report them on different bases. +func consoleDedupIdent(ev any, m consoleMessage) (string, bool) { + switch e := ev.(type) { + case *cdpruntime.EventExceptionThrown: + return consoleIdent(m.Text, m.URL), true + case *cdplog.EventEntryAdded: + if e.Entry != nil && e.Entry.Source == cdplog.SourceJavascript { + return consoleIdent(e.Entry.Text, e.Entry.URL), true + } + } + return "", false +} + +// consoleIdent normalises one report of an error to its identity. +func consoleIdent(text, url string) string { + t := strings.TrimSpace(text) + t = strings.TrimPrefix(t, "Uncaught (in promise) ") + t = strings.TrimPrefix(t, "Uncaught ") + return strings.TrimSpace(t) + "\x00" + url } // consoleEnable turns on the domains console capture listens to. Both calls are @@ -199,13 +304,15 @@ func (c *CDP) Console(ctx context.Context, id string, opts ConsoleOpts) (any, er } q := eventbuf.Query[consoleMessage]{Keep: keep, Limit: opts.Limit, Clear: opts.Clear} if fresh { - // Nothing was alive to receive this tab's earlier events. Report what - // arrives now, and say so — an empty list with no note would read as - // "the page was quiet", which is a lie the caller cannot detect. + // Nothing was alive to receive this tab's earlier events, so whatever + // history there is came from Chrome's own replay at enable time. Report + // it — `buffered` is a real count of what is held, not a claim about + // completeness — and carry the note, because a short list with no + // explanation reads as "the page was quiet", which is a lie the caller + // cannot detect. settle(ctx, consoleFreshGrace) res := consoleResult(c.consoleBuf().Query(id, q)) - res["buffered"] = 0 - res["note"] = noRetainedHistoryNote + res["note"] = partialHistoryNote return res, nil } return consoleResult(c.consoleBuf().Query(id, q)), nil @@ -406,13 +513,6 @@ func consoleEvent(ev any, maxEntry int) (consoleMessage, bool) { if en == nil { return consoleMessage{}, false } - // Runtime is the authoritative source for anything the page itself - // said: console-api entries duplicate consoleAPICalled, and javascript - // entries duplicate exceptionThrown (with a worse stack). Dropping them - // here is what keeps `buffered` an honest count of distinct messages. - if en.Source == cdplog.SourceJavascript || string(en.Source) == "console-api" { - return consoleMessage{}, false - } level, ok := NormalizeConsoleLevel(string(en.Level)) if !ok { level = "log" diff --git a/internal/chrome/console_test.go b/internal/chrome/console_test.go index 4733317..319401f 100644 --- a/internal/chrome/console_test.go +++ b/internal/chrome/console_test.go @@ -196,20 +196,23 @@ func TestCapTextBoundsTextAndStack(t *testing.T) { } } -// Log.entryAdded duplicates what Runtime already reports for anything the page -// itself said, so those sources are dropped — otherwise `buffered` double-counts -// every console call and every uncaught error. -func TestConsoleEventSkipsDuplicateLogSources(t *testing.T) { +// A javascript-source Log entry is no longer dropped by SOURCE. That drop threw +// away Log.enable's replay of "the entries collected so far", which is a record +// of what a page did before the connection attached — so a tab that had already +// thrown could answer `console --only-errors` with an empty list and exit 0, +// which reads as "the page is clean". +func TestConsoleEventKeepsEveryLogSource(t *testing.T) { t.Parallel() - for _, src := range []string{"javascript", "console-api"} { - ev := logEntryEvent(src, "error", "Uncaught TypeError: boom") - if _, ok := consoleEvent(ev, DefaultConsoleMaxEntry); ok { - t.Errorf("Log.entryAdded source %q was retained; Runtime is the authoritative source for it", src) - } + m, ok := consoleEvent(logEntryEvent("javascript", "error", "Uncaught TypeError: boom"), DefaultConsoleMaxEntry) + if !ok { + t.Fatal("a javascript log entry was dropped by source; the pre-attach backlog arrives this way") + } + if m.Level != "error" || m.Source != consoleSourceLog || !strings.Contains(m.Text, "TypeError") { + t.Errorf("javascript log entry = %+v", m) } // A browser-level source (a failed subresource, a deprecation) is real - // added value and must survive. - m, ok := consoleEvent(logEntryEvent("network", "error", "Failed to load resource: 404"), DefaultConsoleMaxEntry) + // added value and must survive too. + m, ok = consoleEvent(logEntryEvent("network", "error", "Failed to load resource: 404"), DefaultConsoleMaxEntry) if !ok { t.Fatal("a network log entry was dropped") } @@ -218,6 +221,92 @@ func TestConsoleEventSkipsDuplicateLogSources(t *testing.T) { } } +// Duplicates are suppressed by IDENTITY instead: one uncaught exception that +// Chrome describes twice is one message, but the same error thrown again later +// is two. +func TestConsoleDedupSuppressesOneExceptionReportedTwice(t *testing.T) { + t.Parallel() + const url = "https://app.example/bundle.js" + thrown := &cdpruntime.EventExceptionThrown{ + ExceptionDetails: &cdpruntime.ExceptionDetails{ + URL: url, LineNumber: 41, ColumnNumber: 7, + Exception: &cdpruntime.RemoteObject{Description: "TypeError: x.map is not a function\n at render"}, + }, + } + entry := &cdplog.EventEntryAdded{Entry: &cdplog.Entry{ + Source: cdplog.SourceJavascript, Level: "error", + Text: "Uncaught TypeError: x.map is not a function", URL: url, LineNumber: 41, + }} + other := &cdplog.EventEntryAdded{Entry: &cdplog.Entry{ + Source: cdplog.SourceJavascript, Level: "error", + Text: "Uncaught ReferenceError: nope is not defined", URL: url, + }} + + // Order-independent: whichever of the two arrives first is the report kept. + for _, order := range [][]any{{thrown, entry}, {entry, thrown}} { + d := &consoleDedup{} + at := time.Now() + kept := 0 + for _, ev := range order { + m, _ := consoleEvent(ev, DefaultConsoleMaxEntry) + m.TS = at + ident, collidable := consoleDedupIdent(ev, m) + if !collidable { + t.Fatalf("%T is not treated as a collidable report", ev) + } + if d.first(ident, m.TS) { + kept++ + } + } + if kept != 1 { + t.Errorf("%d of the 2 reports of one exception were kept, want 1", kept) + } + } + + // A DIFFERENT error is never suppressed. + d := &consoleDedup{} + at := time.Now() + for _, ev := range []any{thrown, other} { + m, _ := consoleEvent(ev, DefaultConsoleMaxEntry) + m.TS = at + ident, _ := consoleDedupIdent(ev, m) + if !d.first(ident, m.TS) { + t.Errorf("a distinct error was suppressed as a duplicate: %T", ev) + } + } + + // And the SAME error thrown again later is a real repeat, not a duplicate: + // an app that throws on every poll is reporting something. + d = &consoleDedup{} + m, _ := consoleEvent(thrown, DefaultConsoleMaxEntry) + ident, _ := consoleDedupIdent(thrown, m) + if !d.first(ident, at) { + t.Fatal("the first report was suppressed") + } + if !d.first(ident, at.Add(consoleDedupWindow+time.Second)) { + t.Error("a repeat outside the dedupe window was suppressed; a recurring error must still be visible") + } +} + +// A console.* call is NEVER deduped: a page that logs the same line twice on +// purpose has to see both, and only an uncaught exception can arrive twice. +func TestConsoleDedupIgnoresWhatCannotCollide(t *testing.T) { + t.Parallel() + ev := &cdpruntime.EventConsoleAPICalled{ + Type: cdpruntime.APITypeLog, + Args: []*cdpruntime.RemoteObject{{Type: "string", Value: []byte(`"tick"`)}}, + } + m, _ := consoleEvent(ev, DefaultConsoleMaxEntry) + if _, collidable := consoleDedupIdent(ev, m); collidable { + t.Error("a console.* call was treated as dedupable; repeated logs are real") + } + netEntry := logEntryEvent("network", "error", "Failed to load resource: 404") + nm, _ := consoleEvent(netEntry, DefaultConsoleMaxEntry) + if _, collidable := consoleDedupIdent(netEntry, nm); collidable { + t.Error("a network log entry was treated as dedupable; Runtime never reports it") + } +} + func TestConsoleEventMapsAnException(t *testing.T) { t.Parallel() ev := &cdpruntime.EventExceptionThrown{ @@ -278,6 +367,38 @@ func consoleFixtures(t *testing.T) *httptest.Server { return srv } +// preAttachThrow serves a page that throws an uncaught TypeError and THEN +// signals the returned channel, so a test can attach strictly after the throw +// rather than guessing at a sleep. The throw is in its own script tag: an +// uncaught error ends that script, not the next one. +func preAttachThrow(t *testing.T) (*httptest.Server, <-chan struct{}) { + t.Helper() + thrown := make(chan struct{}, 1) + mux := http.NewServeMux() + mux.HandleFunc("/favicon.ico", func(w http.ResponseWriter, _ *http.Request) { w.WriteHeader(http.StatusNoContent) }) + mux.HandleFunc("/thrown", func(w http.ResponseWriter, _ *http.Request) { + select { + case thrown <- struct{}{}: + default: + } + w.WriteHeader(http.StatusNoContent) + }) + mux.HandleFunc("/late", func(w http.ResponseWriter, _ *http.Request) { + w.Header().Set("Content-Type", "text/html") + fmt.Fprint(w, `Console fixture + + +`) + }) + srv := httptest.NewServer(mux) + t.Cleanup(srv.Close) + return srv, thrown +} + func liveChrome(t *testing.T) *CDP { t.Helper() if testing.Short() { @@ -380,6 +501,49 @@ func TestConsoleCapturesALogEmittedBeforeTheRead(t *testing.T) { } } +// RFC-0002 US-1, the case the verb exists for: the daemon attaches to a tab that +// has ALREADY loaded and thrown. +// +// The capture listeners have to be registered before the attach, because +// chromedp's own attach sequence issues Runtime.enable and Log.enable — and +// those enables are what flush what the page did before we arrived. Registering +// afterwards dropped the whole backlog, so `console --only-errors` returned an +// empty list with exit 0 and no note: the reader concludes the page is clean. +func TestConsoleCapturesAnErrorThrownBeforeTheAttach(t *testing.T) { + b := liveChrome(t) + srv, thrown := preAttachThrow(t) + ctx, cancel := context.WithTimeout(context.Background(), 60*time.Second) + defer cancel() + + // Open creates the tab WITHOUT attaching, so the page throws with nothing + // listening — which is exactly a daemon arriving at an existing tab. + res, err := b.Open(ctx, srv.URL+"/late") + if err != nil { + t.Fatalf("Open: %v", err) + } + id, _ := res["id"].(string) + if id == "" { + t.Fatalf("Open returned no target id: %v", res) + } + select { + case <-thrown: + case <-time.After(30 * time.Second): + t.Fatal("the fixture never reported that it had thrown") + } + if b.attached(id) { + t.Fatal("the tab was already attached; this test has to read a backlog, not a live event") + } + + opts := ConsoleOpts{Levels: []string{"error"}, Limit: 100} // --only-errors + msgs := awaitConsole(ctx, t, b, id, opts, func(m []consoleMessage) bool { + return hasText(m, "TypeError") + }) + if !hasText(msgs, "TypeError") { + t.Fatalf("the error the page threw before we attached was not reported; --only-errors returned %+v.\n"+ + "An empty list here reads as \"the page is clean\", which is the opposite of the truth", msgs) + } +} + // VS-2: an uncaught exception arrives at error level WITH its stack — the field // users need most and the one a marshalling mistake silently drops. func TestConsoleCapturesAnUncaughtExceptionWithAStack(t *testing.T) { @@ -467,10 +631,11 @@ func TestConsoleClearScopesTheReadToOneAction(t *testing.T) { } } -// VS-10: with nothing alive to have received them, earlier messages are absent, -// buffered is 0, and the envelope SAYS so — it must not pass an empty list off -// as a quiet page. -func TestConsoleWithoutRetainedHistoryDoesNotFabricateIt(t *testing.T) { +// VS-10, as amended by the backlog fix: with nothing alive when the page logged, +// the history is whatever Chrome replays at enable time — real, but Chrome's +// window rather than ours. The envelope SAYS so rather than passing it off as a +// full session record, and `buffered` reports what is actually held. +func TestConsoleWithoutRetainedHistorySaysSo(t *testing.T) { b := liveChrome(t) srv := consoleFixtures(t) ctx, cancel := context.WithTimeout(context.Background(), 60*time.Second) @@ -497,15 +662,14 @@ func TestConsoleWithoutRetainedHistoryDoesNotFabricateIt(t *testing.T) { t.Fatalf("Console: %v", err) } m := res.(map[string]any) - if got := m["buffered"]; got != 0 { - t.Errorf("buffered = %v, want 0 — there was no retained history to report", got) - } note, _ := m["note"].(string) if note == "" { - t.Error("no note: an empty message list with no explanation reads as 'the page was quiet', which is a lie the caller cannot detect") + t.Error("no note: a message list with no explanation reads as a full session record, which is a lie the caller cannot detect") } - if msgs := consoleMsgs(t, res); hasText(msgs, "hello from the page") { - t.Errorf("a message emitted before anything was listening was reported anyway: %+v", msgs) + // `buffered` must match what is really held — reporting 0 alongside a + // non-empty list would make both numbers useless. + if got, want := m["buffered"], len(consoleMsgs(t, res)); got.(int) < want { + t.Errorf("buffered = %v but %d messages were returned; the count must describe what is held", got, want) } } diff --git a/internal/chrome/net.go b/internal/chrome/net.go index 62cd0de..e83941d 100644 --- a/internal/chrome/net.go +++ b/internal/chrome/net.go @@ -44,11 +44,15 @@ const ( // reader that cannot keep up drops rather than stalls Chrome. netStreamBacklog = 256 - // netNoRetainedHistoryNote is the honest answer when nothing was listening to - // this tab before the command started. An empty list without it would read as - // "the page made no requests", which is a lie the caller cannot detect. - netNoRetainedHistoryNote = "no retained history: nothing was listening to this tab before this command started, " + - "so only requests made during it can appear. Use the daemon (drop --no-daemon) to retain history, or --follow to watch from here." + // netPartialHistoryNote is the honest answer when nothing was listening to + // this tab before the command started. Some history does arrive — enabling + // the domain makes Chrome describe what it still holds for the page, which + // is a handful of cached resources rather than the session — so a short list + // without this note would read as "the page made these requests and no + // others", which is a lie the caller cannot detect. + netPartialHistoryNote = "partial history: nothing was listening to this tab before this command started, so what appears is " + + "whatever Chrome still held when capture was enabled, plus what arrived during this command. " + + "Use the daemon (drop --no-daemon) to retain everything from the moment it attached, or --follow to watch from here." ) // NetRedacted is the placeholder a redacted header value or URL parameter is @@ -259,18 +263,16 @@ func (c *CDP) configureNetCapture(buffer, maxBody int) { // already holds c.mu. func (c *CDP) netBuf() *eventbuf.Set[netRecord] { return c.net } -// startNetCapture retains the tab's HTTP requests, from ATTACH rather than from -// the first `net` read — the same reason console captures early: the process -// holding the connection has to already be listening when the page makes the -// request, or `net` can only ever report what happened after somebody thought to -// look, which is exactly when it is least useful. +// listenNet retains the tab's HTTP requests, from ATTACH rather than from the +// first `net` read — the same reason console captures early: the process holding +// the connection has to already be listening when the page makes the request, or +// `net` can only ever report what happened after somebody thought to look, which +// is exactly when it is least useful. // // The listener runs on chromedp's event loop and only folds events into an -// in-memory record; it never issues a CDP command. Enabling the domain is -// best-effort here (every verb attaches, and a chrome:// page that refuses -// Network must not break `click`); Net re-enables at read time and DOES report -// the failure, so the honesty is paid for where it is asked for. -func (c *CDP) startNetCapture(tctx context.Context, id string) { +// in-memory record; it never issues a CDP command. Enabling the domain happens +// after the attach, in enableCapture. +func (c *CDP) listenNet(tctx context.Context, id string) { set := c.netBuf() maxBody := c.netMaxBody // Per-tab epoch, so `started_ms` is a small number relative to when this @@ -281,9 +283,6 @@ func (c *CDP) startNetCapture(tctx context.Context, id string) { set.Upsert(id, key, mutate) } }) - ectx, cancel := context.WithTimeout(tctx, 5*time.Second) - defer cancel() - _ = chromedp.Run(ectx, netEnable(maxBody)...) } // netEnable turns on the domain network capture listens to. It is idempotent, so @@ -1014,8 +1013,10 @@ func (c *CDP) Net(ctx context.Context, id string, opts NetOpts) (any, error) { res := c.netBuf().Query(id, q) out := c.netResult(ctx, id, res, pending, opts) if fresh { - out["buffered"] = 0 - out["note"] = netNoRetainedHistoryNote + // `buffered` is a real count of what is held, not a claim about + // completeness; the note is what says the history is Chrome's window + // rather than ours. + out["note"] = netPartialHistoryNote } return out, nil } diff --git a/internal/chrome/net_test.go b/internal/chrome/net_test.go index 6ea372f..568ab3d 100644 --- a/internal/chrome/net_test.go +++ b/internal/chrome/net_test.go @@ -1615,10 +1615,11 @@ func TestNetBodyUnavailableIsMarkedNotErrored(t *testing.T) { } } -// With nothing alive to have received them, earlier requests are absent, -// buffered is 0, and the envelope SAYS so — it must not pass an empty list off -// as a page that made no requests. This is the --no-daemon situation. -func TestNetWithoutRetainedHistoryDoesNotFabricateIt(t *testing.T) { +// With nothing alive when the page loaded, the history is whatever Chrome still +// held when the domain was enabled — a couple of cached resources, never the +// session. The envelope SAYS so rather than passing a short list off as the +// whole story. This is the --no-daemon situation. +func TestNetWithoutRetainedHistorySaysSo(t *testing.T) { b := liveChrome(t) _, page := netFixtures(t) ctx, cancel := context.WithTimeout(context.Background(), 90*time.Second) @@ -1644,15 +1645,14 @@ func TestNetWithoutRetainedHistoryDoesNotFabricateIt(t *testing.T) { t.Fatalf("Net: %v", err) } m := res.(map[string]any) - if got := m["buffered"]; got != 0 { - t.Errorf("buffered = %v, want 0 — there was no retained history to report", got) - } if note, _ := m["note"].(string); note == "" { - t.Error("no note: an empty request list with no explanation reads as 'the page made no requests', " + + t.Error("no note: a request list with no explanation reads as the whole story, " + "which is a lie the caller cannot detect") } - if hasURL(netRequests(t, res), "style.css") { - t.Error("a request made before anything was listening was reported anyway") + // `buffered` must describe what is really held: reporting 0 alongside a + // non-empty list would make both numbers useless. + if got, want := m["buffered"].(int), len(netRequests(t, res)); got < want { + t.Errorf("buffered = %d but %d requests were returned; the count must describe what is held", got, want) } } diff --git a/internal/cli/console.go b/internal/cli/console.go index 43c375f..a52a9d8 100644 --- a/internal/cli/console.go +++ b/internal/cli/console.go @@ -95,7 +95,8 @@ func (a *App) cmdConsole() *cobra.Command { "look for it. The buffer is bounded (config: console_buffer, console_max_entry);\n" + "a nonzero `dropped` in the result means messages were evicted before you read.\n\n" + "With --no-daemon no process was alive to receive earlier events, so the read\n" + - "reports buffered 0 and carries a note saying there is no retained history.\n\n" + + "sees only what Chrome replays when capture is enabled, and carries a note\n" + + "saying the history is partial.\n\n" + " chrome-cdp console --only-errors # what broke\n" + " chrome-cdp console --grep \"\\[Checkout\\]\" --limit 20 # one subsystem\n" + " chrome-cdp console --clear # reset before an action\n" + From 60904db755b9e9d5c76a1f3ee85c060505f2c910 Mon Sep 17 00:00:00 2001 From: Sanket Sudake Date: Mon, 27 Jul 2026 16:39:02 +0530 Subject: [PATCH 5/8] fix: a --follow stream must not wedge every other command streamDispatch ran under the same mutex that serialises unary calls, for the whole --follow window. Measured against the real Serve: with a 3s stream in flight a concurrent unary Console took 2.70s. So `console --follow` in one terminal wedged `click` in another for the client's full --timeout, defeating the user story the feature exists for (RFC-0002 US-2, "watch console output while I exercise the page"). The mutex exists so multi-step chromedp action sequences on one connection do not interleave. A stream is not that: it issues one idempotent domain enable and then only reads event buffers that hold their own locks, with the attach serialised by the CDP object's own mutex. So streaming dispatch now takes no mutex at all, rather than plumbing a readiness callback through the Browser interface, the stub, both daemon halves and the CLI to serialise two enable round trips. Two consequences of the same root, fixed with it. A stream now pings the activity channel, so a --follow longer than the 30-minute idle window no longer has its listener closed mid-stream (the client saw EOF, exit 0, no indication of truncation). And the connection is watched for hangup, so a Ctrl-C'd follow ends at once instead of when the daemon next writes -- which on a quiet page is never. Co-Authored-By: Claude Opus 5 (1M context) --- internal/daemon/daemon.go | 98 ++++++++++++++++++-- internal/daemon/stream_test.go | 164 +++++++++++++++++++++++++++++++++ 2 files changed, 254 insertions(+), 8 deletions(-) diff --git a/internal/daemon/daemon.go b/internal/daemon/daemon.go index a8eea80..a7aef29 100644 --- a/internal/daemon/daemon.go +++ b/internal/daemon/daemon.go @@ -49,6 +49,11 @@ type server struct { activity chan struct{} // activity pings, to reset the idle timer stopCh chan struct{} stopOnce sync.Once + + // pingEvery is how often a live stream reports itself to the idle timer. + // Zero means defaultStreamPing; a test sets it so it can assert on the + // behaviour without waiting out a production interval. + pingEvery time.Duration } func (s *server) stop() { s.stopOnce.Do(func() { close(s.stopCh) }) } @@ -121,20 +126,93 @@ func (s *server) handle(conn net.Conn) { ctx, cancel = context.WithTimeout(ctx, time.Duration(req.TimeoutMs)*time.Millisecond) defer cancel() } - s.mu.Lock() - // A streaming method writes its own responses as they arrive; a unary one - // answers once. Both hold the dispatch mutex for their whole run, exactly - // as a long `wait` already does. - if handled, serr := s.streamDispatch(ctx, conn, req.Method, req.Args); handled { - s.mu.Unlock() + // A STREAMING method runs for the client's whole --follow window, so it must + // NOT hold the mutex that serialises unary calls: holding it made + // `console --follow` in one terminal wedge `click` in another for the full + // timeout, which defeats the user story the feature exists for (RFC-0002 + // US-2, "watch console output WHILE I exercise the page"). + // + // Dropping the mutex here is safe because a stream is not the kind of thing + // the mutex protects. It exists so multi-step chromedp action sequences on + // one connection do not interleave; a stream issues one idempotent domain + // enable, then only reads event buffers that hold their own locks. The + // attach it may trigger is serialised by the CDP object's own mutex, and + // chromedp targets are safe for concurrent use. See streamDispatch. + if isStreamMethod(req.Method) { + ctx, cancel := context.WithCancel(ctx) + defer cancel() + // A --follow stream is the one call that can outlive the idle window, + // and the one that has to notice its client leaving. + go s.pingWhile(ctx) + go watchHangup(ctx, conn, cancel) + _, serr := s.streamDispatch(ctx, conn, req.Method, req.Args) finishStream(conn, serr) return } + s.mu.Lock() res, err := s.dispatch(ctx, req.Method, req.Args) s.mu.Unlock() reply(conn, res, err) } +// defaultStreamPing is how often a live stream reports itself to the idle timer. +// Well under any sane idle window, so a long --follow cannot have the listener +// closed from under it: the client would see EOF, the stream would return nil, +// and the command would exit 0 with no indication it had been cut short. +const defaultStreamPing = 30 * time.Second + +// pingWhile keeps the idle timer alive for as long as a stream is running. The +// timer is otherwise reset only on Accept, which a stream does exactly once. +func (s *server) pingWhile(ctx context.Context) { + every := s.pingEvery + if every <= 0 { + every = defaultStreamPing + } + t := time.NewTicker(every) + defer t.Stop() + for { + select { + case <-ctx.Done(): + return + case <-t.C: + s.ping() + } + } +} + +// watchHangup cancels a stream when its client goes away. +// +// The protocol is one request per connection, so the client never writes again: +// any read that completes means the far end closed. Without this a Ctrl-C'd +// --follow is noticed only when the daemon next WRITES to the socket — which on +// a quiet page is never, so the stream ran for the client's whole TimeoutMs +// after nobody was left to read it. +func watchHangup(ctx context.Context, conn net.Conn, cancel context.CancelFunc) { + defer cancel() + buf := make([]byte, 1) + for { + if _, err := conn.Read(buf); err != nil { + return + } + select { + case <-ctx.Done(): + return + default: + } + } +} + +// isStreamMethod reports whether a method is served by streamDispatch. It is the +// same list, kept next to it deliberately: a method that streams but is not +// named here would take the dispatch mutex for its whole window. +func isStreamMethod(method string) bool { + switch method { + case "ConsoleStream", "NetStream": + return true + } + return false +} + // reply writes a Response for a dispatch result to conn. func reply(conn net.Conn, res any, err error) { resp := Response{} @@ -156,8 +234,12 @@ func reply(conn net.Conn, res any, err error) { // Each emitted value is written as its own Response on the same connection; // finishStream writes the terminator. // -// It reports false for anything that is not a streaming method, so the caller -// falls through to dispatch. +// It runs WITHOUT the dispatch mutex (see handle) and must stay that way: it is +// the only dispatch path whose duration is the caller's choice rather than the +// action's. +// +// It reports false for anything that is not a streaming method; isStreamMethod +// is the same list, and the two must agree. func (s *server) streamDispatch(ctx context.Context, conn net.Conn, method string, args []json.RawMessage) (bool, error) { enc := json.NewEncoder(conn) emit := func(v any) error { diff --git a/internal/daemon/stream_test.go b/internal/daemon/stream_test.go index ca9ef09..27a3910 100644 --- a/internal/daemon/stream_test.go +++ b/internal/daemon/stream_test.go @@ -6,6 +6,7 @@ import ( "net" "os" "path/filepath" + "sync" "testing" "time" @@ -128,6 +129,169 @@ func TestConsoleStreamRPCPropagatesAFailure(t *testing.T) { } } +// blockingStreamBrowser holds a stream open until its context ends, and reports +// when the stream started and stopped — the shape of a real `--follow` on a page +// that says nothing. +type blockingStreamBrowser struct { + chrometest.StubBrowser + started chan struct{} + stopped chan struct{} + once sync.Once +} + +func (b *blockingStreamBrowser) Console(context.Context, string, chrome.ConsoleOpts) (any, error) { + return map[string]any{"messages": []any{}, "count": 0}, nil +} + +func (b *blockingStreamBrowser) ConsoleStream(ctx context.Context, _ string, _ chrome.ConsoleOpts, _ func(any) error) error { + b.once.Do(func() { close(b.started) }) + <-ctx.Done() + close(b.stopped) + return nil +} + +// THE regression test for the streaming mutex. +// +// A --follow stream runs for as long as the caller asked; holding the dispatch +// mutex for that whole window made `console --follow` in one terminal wedge +// `click` in another for the full --timeout. That defeats the literal user story +// the feature exists for (RFC-0002 US-2, "watch console output WHILE I exercise +// the page"), and it is invisible until two terminals are open at once. +func TestAStreamDoesNotBlockUnaryCalls(t *testing.T) { + b := &blockingStreamBrowser{started: make(chan struct{}), stopped: make(chan struct{})} + c := serveBrowser(t, b) + rb := Remote(c) + + streamCtx, cancelStream := context.WithTimeout(context.Background(), 5*time.Second) + defer cancelStream() + done := make(chan error, 1) + go func() { + done <- rb.ConsoleStream(streamCtx, "aa11", chrome.ConsoleOpts{}, func(any) error { return nil }) + }() + + select { + case <-b.started: + case <-time.After(5 * time.Second): + t.Fatal("the stream never reached the browser") + } + + // With the stream in flight, an ordinary read must still be answered + // promptly — it is a different command in a different terminal. + start := time.Now() + ctx, cancel := context.WithTimeout(context.Background(), 4*time.Second) + defer cancel() + if _, err := rb.Console(ctx, "aa11", chrome.ConsoleOpts{}); err != nil { + t.Fatalf("a unary Console during a live stream failed: %v", err) + } + if took := time.Since(start); took > time.Second { + t.Fatalf("a unary call waited %v for a live --follow to finish; "+ + "streaming must not hold the mutex that serialises unary dispatch", took) + } + cancelStream() + <-done +} + +// A Ctrl-C'd --follow must be noticed when the client goes away, not when the +// daemon next writes — which on a quiet page is never, so the stream held on for +// the client's whole TimeoutMs after nobody was left to read it. +func TestAStreamEndsWhenTheClientHangsUp(t *testing.T) { + b := &blockingStreamBrowser{started: make(chan struct{}), stopped: make(chan struct{})} + c := serveBrowser(t, b) + + // Dial by hand: the point is a client that disappears mid-stream, which the + // Remote wrapper has no way to express. + ctx, cancel := context.WithTimeout(context.Background(), 60*time.Second) + defer cancel() + conn, err := c.dial(ctx, "ConsoleStream", []any{"aa11", chrome.ConsoleOpts{}}) + if err != nil { + t.Fatalf("dial: %v", err) + } + select { + case <-b.started: + case <-time.After(5 * time.Second): + t.Fatal("the stream never reached the browser") + } + _ = conn.Close() + + select { + case <-b.stopped: + case <-time.After(5 * time.Second): + t.Fatal("the stream outlived its client: a Ctrl-C'd --follow on a quiet page " + + "would hold the daemon for the client's whole timeout") + } +} + +// A stream must keep the idle timer alive. The timer is otherwise reset only on +// Accept, which a stream does exactly once — so a --follow longer than the idle +// window had the listener closed under it, and the client saw EOF, exit 0, and +// no indication it had been cut short. +func TestALiveStreamHoldsOffTheIdleTimeout(t *testing.T) { + b := &blockingStreamBrowser{started: make(chan struct{}), stopped: make(chan struct{})} + dir, err := os.MkdirTemp("", "cdpd") + if err != nil { + t.Fatal(err) + } + t.Cleanup(func() { _ = os.RemoveAll(dir) }) + sock := filepath.Join(dir, "d.sock") + ln, err := net.Listen("unix", sock) + if err != nil { + t.Fatal(err) + } + t.Cleanup(func() { _ = ln.Close() }) + + s := &server{b: b, activity: make(chan struct{}, 1), stopCh: make(chan struct{}), pingEvery: 50 * time.Millisecond} + pings := make(chan struct{}, 8) + // Stand in for the idle goroutine, so the test asserts on the ping rather + // than on a real 30-minute window. + go func() { + for { + select { + case <-s.activity: + select { + case pings <- struct{}{}: + default: + } + case <-s.stopCh: + return + } + } + }() + go func() { + for { + conn, err := ln.Accept() + if err != nil { + return + } + s.ping() + go s.handle(conn) + } + }() + t.Cleanup(s.stop) + + c := &Client{path: sock} + ctx, cancel := context.WithTimeout(context.Background(), 60*time.Second) + defer cancel() + conn, err := c.dial(ctx, "ConsoleStream", []any{"aa11", chrome.ConsoleOpts{}}) + if err != nil { + t.Fatalf("dial: %v", err) + } + defer conn.Close() + select { + case <-b.started: + case <-time.After(5 * time.Second): + t.Fatal("the stream never reached the browser") + } + <-pings // the Accept ping + + // The stream itself must go on reporting activity. + select { + case <-pings: + case <-time.After(5 * time.Second): + t.Fatal("a live stream never pinged the idle timer; a --follow longer than the idle " + + "window would have its listener closed mid-stream") + } +} + // The unary dispatch must not silently answer for a streaming method — that // would hand the caller an empty result instead of its messages. func TestUnaryDispatchRejectsAStreamingMethod(t *testing.T) { From 56050298fc03a317d378a795690fc0421a3907c9 Mon Sep 17 00:00:00 2001 From: Sanket Sudake Date: Mon, 27 Jul 2026 16:43:28 +0530 Subject: [PATCH 6/8] fix: release a tab's event buffers when the tab goes away MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit eventbuf.Set.Forget existed and was tested but had no non-test caller, and Set.Buffer allocates its ring eagerly — roughly 100KB of network records plus 150KB of console lines per tab. The cross-target total cap bounds ENTRIES, not ring allocations, so a daemon that outlived a thousand opened-and-closed tabs held about a quarter of a gigabyte of empty rings for tabs nobody can read again. forget now releases both rings, and a browser-level targetDestroyed listener covers the other way a tab dies — the user closing it in the UI, which over a long session is most of them. That listener hands off to a goroutine because it runs on the browser event loop, which on() blocks on while holding the same mutex forget takes. Live recordings are deliberately left alone: they release themselves on their own stranded TTL, which is what gives `record stop` a window to collect the frames from a tab that has just closed. Co-Authored-By: Claude Opus 5 (1M context) --- internal/chrome/cdp.go | 6 ++- internal/chrome/tabs.go | 37 ++++++++++++++-- internal/chrome/tabs_test.go | 82 ++++++++++++++++++++++++++++++++++++ 3 files changed, 121 insertions(+), 4 deletions(-) diff --git a/internal/chrome/cdp.go b/internal/chrome/cdp.go index 7a215f2..6365d63 100644 --- a/internal/chrome/cdp.go +++ b/internal/chrome/cdp.go @@ -240,7 +240,11 @@ func startBase(managed bool, alloc context.Context, allocCancel context.CancelFu allocCancel() return nil, &ConnectError{Code: "connection_failed", Message: connectFailMsg(managed, what, err)} } - return newCDP(managed, alloc, allocCancel, base, baseCancel), nil + c := newCDP(managed, alloc, allocCancel, base, baseCancel) + // Release a tab's retained events when the BROWSER destroys it, not only + // when we close it ourselves. See watchClosedTabs. + c.watchClosedTabs() + return c, nil } // connectFailMsg turns a raw allocator/dial failure into an actionable message. diff --git a/internal/chrome/tabs.go b/internal/chrome/tabs.go index de516c2..11f35c6 100644 --- a/internal/chrome/tabs.go +++ b/internal/chrome/tabs.go @@ -285,13 +285,44 @@ func (c *CDP) tabVisible(ctx context.Context, id string) bool { return vs == "visible" } -// forget drops the cached attach for a tab that no longer exists, so a later -// command can't reuse a dead session and the context is released. +// forget drops everything this connection holds for a tab that no longer +// exists, so a later command can't reuse a dead session and the memory is +// released. +// +// The event buffers are the load-bearing half. eventbuf.Set.Buffer allocates its +// ring eagerly — roughly 100 KB of network records plus 150 KB of console lines +// per tab — and the cross-target total cap bounds ENTRIES, not ring allocations. +// A daemon that outlives a thousand opened-and-closed tabs would otherwise hold +// a quarter of a gigabyte of empty rings for tabs that can never be read again. func (c *CDP) forget(id string) { c.mu.Lock() - defer c.mu.Unlock() if t, ok := c.tabs[id]; ok { t.stop() delete(c.tabs, id) } + c.mu.Unlock() + + // A live recording is NOT dropped here: it releases itself on its own + // stranded TTL (see the pump's tctx.Done case), which gives `record stop` + // a window to collect the frames from a tab that has just closed. + c.consoleBuf().Forget(id) + c.netBuf().Forget(id) +} + +// watchClosedTabs releases what this connection holds for a tab the BROWSER +// destroyed — the user closing it in the UI, or the page closing itself. +// +// CloseTabs covers the tabs we close; this covers every other way one goes away, +// which over a long daemon session is most of them. +// +// The listener runs on the browser's event loop, so it must never block: forget +// takes c.mu, which on() holds across an attach that is itself waiting on this +// loop. Handing off to a goroutine keeps that from being a deadlock. +func (c *CDP) watchClosedTabs() { + chromedp.ListenBrowser(c.base, func(ev any) { + if e, ok := ev.(*cdptarget.EventTargetDestroyed); ok { + id := e.TargetID.String() + go c.forget(id) + } + }) } diff --git a/internal/chrome/tabs_test.go b/internal/chrome/tabs_test.go index 958489a..61e96c5 100644 --- a/internal/chrome/tabs_test.go +++ b/internal/chrome/tabs_test.go @@ -151,6 +151,88 @@ func TestCloseTabsLive(t *testing.T) { } } +// hasBuffer reports whether an eventbuf.Set still holds a ring for a target. +func hasBuffer(targets []string, id string) bool { + for _, t := range targets { + if t == id { + return true + } + } + return false +} + +// A tab that goes away must take its retained events with it. +// +// eventbuf.Set.Buffer allocates its ring eagerly — ~100 KB of network records +// plus ~150 KB of console lines per tab — and the cross-target total cap bounds +// entries, not ring allocations. Set.Forget existed and was tested but had no +// non-test caller, so a daemon that outlived a thousand opened-and-closed tabs +// held a quarter of a gigabyte of empty rings for tabs nobody can read again. +// +// Both ways a tab dies are covered: the one we close, and the one the browser +// closes without asking us. +func TestClosingATabReleasesItsBuffersLive(t *testing.T) { + b := liveCDP(t) + srv, _ := tabFixtures(t) + ctx, cancel := context.WithTimeout(context.Background(), 90*time.Second) + defer cancel() + + // (1) A tab we close ourselves. + id := openTab(ctx, t, b, srv.URL+"/p1") + if _, err := b.Navigate(ctx, id, srv.URL+"/p2"); err != nil { // attaching is what starts capture + t.Fatalf("Navigate: %v", err) + } + // A read materialises both rings, which is what a real session does the + // moment anything is logged or requested. + if _, err := b.Console(ctx, id, ConsoleOpts{}); err != nil { + t.Fatalf("Console: %v", err) + } + if _, err := b.Net(ctx, id, NetOpts{}); err != nil { + t.Fatalf("Net: %v", err) + } + if !hasBuffer(b.consoleBuf().Targets(), id) || !hasBuffer(b.netBuf().Targets(), id) { + t.Fatalf("no buffers were created for %s; this test would prove nothing", id) + } + if _, err := b.CloseTabs(ctx, []string{id}); err != nil { + t.Fatalf("CloseTabs: %v", err) + } + if hasBuffer(b.consoleBuf().Targets(), id) { + t.Error("the console ring for a closed tab was retained; its entries can never be read again") + } + if hasBuffer(b.netBuf().Targets(), id) { + t.Error("the network ring for a closed tab was retained") + } + + // (2) A tab the BROWSER destroys — the page closing itself, or the user + // closing it in the UI, which over a long session is most of them. + other := openTab(ctx, t, b, srv.URL+"/p1") + if _, err := b.Navigate(ctx, other, srv.URL+"/p2"); err != nil { + t.Fatalf("Navigate: %v", err) + } + if _, err := b.Console(ctx, other, ConsoleOpts{}); err != nil { + t.Fatalf("Console: %v", err) + } + if _, err := b.Net(ctx, other, NetOpts{}); err != nil { + t.Fatalf("Net: %v", err) + } + if !hasBuffer(b.consoleBuf().Targets(), other) || !hasBuffer(b.netBuf().Targets(), other) { + t.Fatalf("no buffers were created for %s", other) + } + if err := b.closeTarget(ctx, other); err != nil { // the browser closes it; we never call forget + t.Fatalf("closeTarget: %v", err) + } + deadline := time.Now().Add(15 * time.Second) + for hasBuffer(b.consoleBuf().Targets(), other) && time.Now().Before(deadline) { + time.Sleep(100 * time.Millisecond) + } + if hasBuffer(b.consoleBuf().Targets(), other) { + t.Error("a tab destroyed by the browser kept its console ring; only the tabs we close ourselves were released") + } + if hasBuffer(b.netBuf().Targets(), other) { + t.Error("a tab destroyed by the browser kept its network ring") + } +} + // A close that half worked reports both halves — and does not then sit waiting // for the tab it failed to close, which never leaves the list and would burn the // whole awaitGone cap before returning a result already known. From 52938041c68718db2a970905f376eccac91ac7d1 Mon Sep 17 00:00:00 2001 From: Sanket Sudake Date: Mon, 27 Jul 2026 16:53:32 +0530 Subject: [PATCH 7/8] fix: scope `pending` to the caller's filter, and document the follow contract MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit `pending` exists so a caller can tell "nothing matched" from "not finished yet", which only works if it is about what the caller asked about. Counted over the whole buffer, one permanently open SSE stream or long poll — which every real app has — made `net --url /api/save` report pending >= 1 forever, so the signal never went quiet and stopped meaning anything. It now uses the same url/method/type/since filter as the listing. Status and --failed are deliberately dropped from it: an in-flight request has no status, so keeping them would make pending a constant zero for exactly the reads that ask about an outcome. The quiet-`--follow` case is documented rather than changed: a terminating summary would be a second envelope shape for callers to parse, and both the skill and `session` parity depend on one shape per line. Co-Authored-By: Claude Opus 5 (1M context) --- docs/cli-reference.md | 17 +++++++- internal/chrome/net.go | 24 ++++++++++- internal/chrome/net_test.go | 83 ++++++++++++++++++++++++++++++++++++- 3 files changed, 120 insertions(+), 4 deletions(-) diff --git a/docs/cli-reference.md b/docs/cli-reference.md index 9f38dd4..433a575 100644 --- a/docs/cli-reference.md +++ b/docs/cli-reference.md @@ -381,6 +381,9 @@ Raise `console_buffer`, or read closer to the action. **`--follow`** writes one JSON envelope per line, the same shape `session` streams. It cannot combine with `--fail-on-match`, and it is a usage error inside `session` or a recipe step, where it would break the one-envelope-per-line contract a batch promises. +A page that says nothing produces **no output at all** and exits 0 — there is no closing summary, because a terminating envelope would be a second shape for a caller to parse. +Treat empty stdout as "nothing was logged in the window", not as a failure. +A follow does not block other commands: you can drive the page from another terminal while one is running, and a follow longer than the daemon's idle window keeps it alive rather than being cut off mid-stream. **`--no-daemon` has only partial history.** Without the daemon there was no process alive to receive the tab's earlier events, so what appears is whatever Chrome replays when capture is enabled (recent console output and uncaught exceptions it still holds) plus what arrives during the command. @@ -422,6 +425,8 @@ Every filter is applied where the buffer lives, before the result is built, so a The result carries `requests`, `count` (after filtering), `buffered`, `dropped`, `truncated`, and `pending`. **`pending` counts requests that started but have not finished**, so you can tell "nothing matched" from "not finished yet" — an empty listing during a slow save is otherwise indistinguishable from a save that never fired. +It is scoped to the same `--url` / `--method` / `--type` / `--since` filter as the listing, so a permanently open SSE stream or long poll does not make every read look unfinished forever. +`--status` and `--failed` are deliberately *not* applied to it: a request still in flight has no status, so applying them would make `pending` a constant zero for exactly the reads that ask about an outcome. Each request carries `id`, `method`, `url`, `type`, `status`, `status_text`, `started_ms` (milliseconds since capture began on this tab), `duration_ms`, `request_size`, `response_size`, `from_cache`, `failed`, and `error`. `status`, `duration_ms`, and `error` are `null` when they do not exist yet; `failed` means a non-2xx status **or** a network-level failure, so a delivered 500 and a DNS failure both show up under `--failed`. @@ -429,7 +434,8 @@ Each request carries `id`, `method`, `url`, `type`, `status`, `status_text`, `st **Redaction is on by default.** This CLI drives your real, logged-in Chrome, so its buffers hold live session credentials by construction. The values of `authorization`, `cookie`, `set-cookie`, `x-api-key`, `proxy-authorization`, and any header whose name contains `token`, `secret`, or `password` are replaced with `` — the name stays, so a 401 is still diagnosable. -Credential-shaped URL query and fragment parameters (`access_token`, `api_key`, `sig`, `code`, `key`, …) are redacted the same way. +Credential-shaped URL query and fragment parameters (`access_token`, `api_key`, `sig`, `code`, `key`, …) are redacted the same way, including the query string of a hash-router fragment (`#/callback?access_token=…`). +Headers whose value is itself a URL (`location`, `content-location`, `referer`) go through the same URL redaction rather than being withheld wholesale, so the 302 that ends an OAuth flow stays readable without carrying the code. `--no-redact` is the explicit, deliberate opt-out. **Headers and bodies are absent, not null, unless you ask.** @@ -439,8 +445,14 @@ Without `--headers` / `--body` those keys do not appear at all, so a routine lis They are pulled with `Network.getResponseBody` at read time, only when `--body` is passed — buffering every body would multiply the daemon's memory and retain payloads you never asked to see. The consequence: **a body may already be gone** if the page navigated away, or if it is not UTF-8 text. That is reported as `"response_body": null` with `"body_unavailable": true`, and the read still succeeds — a partial answer beats no answer. +Whether a body is text is judged on the payload Chrome delivered, not on what survives the cap, so the same image reports `body_unavailable` at any size. Bodies over `net_max_body` (default 65536 bytes) are cut, with `"body_truncated": true`. -Request bodies arrive inline with the request, so they are retained and available retroactively. +Request bodies arrive inline with the request, so they are retained and available retroactively; a request body that is not text is withheld the same way, as `"request_body": null` with `"request_body_unavailable": true`. + +**Bodies are redacted too.** +Credential-shaped fields in form-encoded and JSON bodies (`password`, `access_token`, `client_secret`, `api_key`, …) are replaced with ``, on requests and responses alike — a password is no less a secret for having travelled in a POST body than in the query string, which is already withheld. +The rest of the payload is reported exactly as sent, including a body the cap already cut. +A body in any other encoding (`multipart/form-data`, protobuf, a bare token) has no field structure to key on and is passed through unchanged, so treat `--body` output from those as sensitive. **`net wait` / `wait --request`** blocks until one specific request completes. @@ -458,6 +470,7 @@ No match before `--timeout` is `target_timeout` / exit 4. **`--follow`** writes one JSON envelope per **completed** request, the same shape `session` streams. It cannot combine with `--fail-on-match`, and it is a usage error inside `session` or a recipe step. +A window in which nothing completed produces **no output at all** and exits 0, exactly as with `console --follow`, and it does not block other commands against the same daemon. **`--no-daemon` has only partial history**, exactly as with `console`: enabling the domain surfaces the handful of resources Chrome still holds for the page, never the session, so the read carries a `note` rather than passing a short list off as the whole story. diff --git a/internal/chrome/net.go b/internal/chrome/net.go index e83941d..5b2f179 100644 --- a/internal/chrome/net.go +++ b/internal/chrome/net.go @@ -710,6 +710,24 @@ func netKeep(opts NetOpts, now time.Time) (func(netRecord) bool, error) { }, nil } +// netPendingKeep is the filter `pending` is counted against: the caller's own +// filter minus its OUTCOME terms. +// +// `pending` exists so a caller can tell "nothing matched" from "not finished +// yet", which only works if it is scoped to what the caller asked about. +// Counting every unfinished request regardless of the filter made a permanently +// open SSE stream or a long poll — which every real app has — report +// `pending >= 1` forever on `net --url /api/save`, so the signal never went +// quiet and stopped meaning anything. +// +// Status and --failed are dropped rather than applied: a request still in flight +// has no status, so keeping them would make `pending` a constant 0 for exactly +// the reads that ask about an outcome. +func netPendingKeep(opts NetOpts, now time.Time) (func(netRecord) bool, error) { + opts.Status, opts.Failed = "", false + return netKeep(opts, now) +} + // netBody is one fetched response body plus why it might be missing. type netBody struct { Text string @@ -996,13 +1014,17 @@ func (c *CDP) Net(ctx context.Context, id string, opts NetOpts) (any, error) { // arrives now, and say so. settle(ctx, netFreshGrace) } + pendingKeep, err := netPendingKeep(opts, time.Now()) + if err != nil { + return nil, err + } // pending is counted in the SAME pass as the filter: Query visits every live // entry exactly once under the buffer's lock, so the count cannot drift from // the matches it is reported alongside. pending := 0 q := eventbuf.Query[netRecord]{ Keep: func(r netRecord) bool { - if !r.Finished { + if !r.Finished && (pendingKeep == nil || pendingKeep(r)) { pending++ } return keep == nil || keep(r) diff --git a/internal/chrome/net_test.go b/internal/chrome/net_test.go index 568ab3d..625e28f 100644 --- a/internal/chrome/net_test.go +++ b/internal/chrome/net_test.go @@ -931,6 +931,21 @@ func netFixtures(t *testing.T) (*httptest.Server, string) { w.Header().Set("Content-Type", "text/plain") _, _ = io_WriteString(w, strings.Repeat("A", 8<<10)) }) + // A request that never completes, standing in for the SSE stream or long + // poll every real app has. Released before the server is closed (cleanups + // run last-registered-first), or Close would block on it forever. + hang := make(chan struct{}) + mux.HandleFunc("/api/hang", func(w http.ResponseWriter, r *http.Request) { + w.Header().Set("Content-Type", "text/event-stream") + w.WriteHeader(http.StatusOK) + if f, ok := w.(http.Flusher); ok { + f.Flush() + } + select { + case <-hang: + case <-r.Context().Done(): + } + }) // The same binary payload at two sizes, for the size-independence of the // "this is not text" answer. 100 KB is over the 64 KB body cap; 1 KB is not. mux.HandleFunc("/api/blob", func(w http.ResponseWriter, r *http.Request) { @@ -951,6 +966,7 @@ func netFixtures(t *testing.T) (*httptest.Server, string) { }) srv := httptest.NewServer(mux) t.Cleanup(srv.Close) + t.Cleanup(func() { close(hang) }) // A page that loads a stylesheet and an image at parse time and exposes the // API calls behind buttons, so a test can scope a read to one action. @@ -964,8 +980,9 @@ func netFixtures(t *testing.T) (*httptest.Server, string) { + `, - srv.URL, srv.URL, srv.URL, srv.URL, srv.URL, srv.URL, srv.URL, srv.URL, srv.URL, deadAddr(t)) + srv.URL, srv.URL, srv.URL, srv.URL, srv.URL, srv.URL, srv.URL, srv.URL, srv.URL, srv.URL, deadAddr(t)) mux.HandleFunc("/page", func(w http.ResponseWriter, _ *http.Request) { w.Header().Set("Content-Type", "text/html") _, _ = io_WriteString(w, page) @@ -1572,6 +1589,70 @@ func TestNetPendingCountsInFlightRequests(t *testing.T) { } } +// `pending` must answer about what the caller ASKED about. Counted over the +// whole buffer, one permanently open SSE stream or long poll — which every real +// app has — made `net --url /api/save` report `pending >= 1` forever, so the +// signal never went quiet and stopped meaning anything. +func TestNetPendingIsScopedToTheFilter(t *testing.T) { + b := liveChrome(t) + _, page := netFixtures(t) + ctx, cancel := context.WithTimeout(context.Background(), 120*time.Second) + defer cancel() + + id := netLiveTab(ctx, t, b, page) + // A request that never finishes, standing in for an SSE stream. + if _, err := b.Pointer(ctx, id, "#hang", PointerOpts{Action: PointerClick}); err != nil { + t.Fatalf("Click: %v", err) + } + // An unrelated request that DOES finish. + if _, err := b.Pointer(ctx, id, "#ok", PointerOpts{Action: PointerClick}); err != nil { + t.Fatalf("Click: %v", err) + } + awaitNetDone(ctx, t, b, id, NetCond{URL: "/api/ok"}) + + // The unfiltered read still sees the hung request — that is VS-13. + res, err := b.Net(ctx, id, NetOpts{Limit: 100}) + if err != nil { + t.Fatalf("Net: %v", err) + } + if n, _ := res.(map[string]any)["pending"].(int); n < 1 { + t.Fatalf("an unfiltered read reported pending %d while a request was hung; VS-13 is broken", n) + } + + // A read scoped to a DIFFERENT endpoint must not inherit it. + res, err = b.Net(ctx, id, NetOpts{URL: "/api/ok", Limit: 100}) + if err != nil { + t.Fatalf("Net: %v", err) + } + if n, _ := res.(map[string]any)["pending"].(int); n != 0 { + t.Errorf("pending = %d for --url /api/ok while only /api/hang was in flight; "+ + "an always-open stream would make every scoped read look unfinished forever", n) + } +} + +// `pending` drops the OUTCOME terms of the filter: a request still in flight has +// no status, so keeping --status or --failed would make pending a constant 0 for +// exactly the reads that ask about an outcome. +func TestNetPendingIgnoresOutcomeFilters(t *testing.T) { + t.Parallel() + inFlight := netRecord{ID: "r1", Method: "POST", URL: "https://app.example/api/save", Type: "xhr"} + other := netRecord{ID: "r2", Method: "GET", URL: "https://app.example/events", Type: "eventsource"} + + keep, err := netPendingKeep(NetOpts{URL: "/api/save", Status: "2xx", Failed: true}, time.Now()) + if err != nil { + t.Fatalf("netPendingKeep: %v", err) + } + if keep == nil { + t.Fatal("a --url filter produced no pending predicate") + } + if !keep(inFlight) { + t.Error("an in-flight request matching --url was excluded from pending by a --status it cannot yet satisfy") + } + if keep(other) { + t.Error("a request the caller did not ask about was counted as pending") + } +} + // VS-14: a body that is gone after a navigation is reported as null WITH the // marker, and the read still succeeds. The invariant is checkable without // forcing Chrome to evict: a null body must never appear unmarked. From 9393589936650bbee68925fabe3c928d76eb9e12 Mon Sep 17 00:00:00 2001 From: Sanket Sudake Date: Mon, 27 Jul 2026 16:56:06 +0530 Subject: [PATCH 8/8] test: guard the streaming-method list against drift A streaming method missing from isStreamMethod is invisible in every stub-backed test and in any single-terminal use: it would take the dispatch mutex for its whole --follow window and block every other command. Reflect over chrome.Browser and require the list to name exactly the methods that take an emit callback, in the same spirit as TestDispatchCoversBrowser. Also corrects comments that named which CDP domain replays a backlog: the observed behaviour is that whichever domain is enabled describes what it still holds, and which one carries a given entry varies by Chrome version. The fix does not depend on that, only on listening before the enables. Co-Authored-By: Claude Opus 5 (1M context) --- internal/chrome/cdp.go | 15 ++++++++------- internal/chrome/console.go | 21 +++++++++++---------- internal/chrome/record.go | 2 +- internal/daemon/coverage_test.go | 22 ++++++++++++++++++++++ 4 files changed, 42 insertions(+), 18 deletions(-) diff --git a/internal/chrome/cdp.go b/internal/chrome/cdp.go index 6365d63..07ef27c 100644 --- a/internal/chrome/cdp.go +++ b/internal/chrome/cdp.go @@ -89,7 +89,7 @@ type CDP struct { // Retained CDP events, per target. The buffers live HERE — on the object // that holds the connection, which in normal use is owned by the daemon — // because a per-command process cannot retain events it was not running to - // receive. Capture starts at attach (see startCapture in console.go), not + // receive. Capture starts at attach (see listenCapture in console.go), not // at the first read. Sized once by configureCapture, before any attach. console *eventbuf.Set[consoleMessage] consoleMaxEntry int @@ -333,12 +333,13 @@ func (c *CDP) on(id string) (context.Context, error) { // somebody thought to look. See listenCapture in console.go. // // The listeners go on BEFORE chromedp.Run, which is the attach. chromedp's - // own attach sequence issues Runtime.enable and Log.enable itself, and - // Log.enable is what flushes "the entries collected so far" — so a listener - // registered after the attach misses that flush entirely, and with it the - // ONLY record of anything the page did before we arrived (Runtime.enable - // replays nothing). ListenTarget before Run is supported: the callback is - // held on the context and attached to the target before those enables run. + // own attach sequence issues Runtime.enable, Log.enable and Network.enable + // itself, and enabling a domain is what makes Chrome describe what it + // already holds for the page — so a listener registered after the attach + // misses that flush entirely, and with it the only record of anything the + // page did before we arrived. ListenTarget before Run is supported: the + // callback is held on the context and attached to the target before those + // enables run. c.listenCapture(tctx, id) if err := chromedp.Run(tctx); err != nil { // attach once, tied to tctx cancel() diff --git a/internal/chrome/console.go b/internal/chrome/console.go index a6f3ae7..82501b1 100644 --- a/internal/chrome/console.go +++ b/internal/chrome/console.go @@ -120,7 +120,7 @@ func (c *CDP) configureCapture(buffer, maxEntry int) { // // It takes no lock, deliberately: the field is written only by newCDP and // configureCapture, both of which run before any tab is attached and therefore -// before any reader exists. Locking here would deadlock instead — startCapture +// before any reader exists. Locking here would deadlock instead — listenCapture // is called from on(), which already holds c.mu. func (c *CDP) consoleBuf() *eventbuf.Set[consoleMessage] { return c.console } @@ -135,8 +135,8 @@ func (c *CDP) attached(id string) bool { // listenCapture registers every event-capture listener for a tab. It is called // from on(), under c.mu, exactly once per tab — and BEFORE the attach, so the -// backlog Log.enable flushes during chromedp's own attach sequence is received -// rather than dropped on the floor. +// backlog the domain enables flush during chromedp's own attach sequence is +// received rather than dropped on the floor. // // This is the hook every event-backed verb shares; RFC-0003's network capture // and RFC-0011's screencast register here too. @@ -195,16 +195,17 @@ func (c *CDP) listenConsole(tctx context.Context, id string) { // // Chrome can describe one uncaught exception twice: Runtime.exceptionThrown and // Log.entryAdded with source "javascript". Suppressing the second by SOURCE, as -// this used to, throws away the pre-attach backlog along with the duplicates — -// Log.enable's replay of "the entries collected so far" is the ONLY record of an -// error that predates the attach, and Runtime.enable replays nothing. A page -// that had already thrown answered `console --only-errors` with an empty list -// and exit 0, which reads as "the page is clean": RFC-0002 US-1 exactly +// this used to, throws the pre-attach backlog away along with the duplicates — +// what a domain replays when it is enabled is the only record of an error that +// predates the attach, and which domain replays it varies by Chrome version. +// A page that had already thrown answered `console --only-errors` with an empty +// list and exit 0, which reads as "the page is clean": RFC-0002 US-1 exactly // inverted. // // So duplicates are judged on IDENTITY — what was said, and where — inside a -// short window, and the backlog survives. The window matters: an app that throws -// the same error on every poll is reporting a real repeat, not a duplicate. +// short window, and every replay survives whichever domain it came from. The +// window matters the other way: an app that throws the same error on every poll +// is reporting a real repeat, not a duplicate. type consoleDedup struct { mu sync.Mutex recent []consoleSeen diff --git a/internal/chrome/record.go b/internal/chrome/record.go index 8f6c462..a417859 100644 --- a/internal/chrome/record.go +++ b/internal/chrome/record.go @@ -216,7 +216,7 @@ func (o RecordOpts) withDefaults(maxFrames int) RecordOpts { } // startRecordCapture registers the screencast listener for a freshly attached -// tab. It is called from startCapture, under c.mu, exactly once per tab. +// tab. It is called from listenCapture, under c.mu, exactly once per tab. // // The listener is registered at ATTACH rather than at `record start` for the // same reason the console's is: chromedp listeners cannot be unregistered, so diff --git a/internal/daemon/coverage_test.go b/internal/daemon/coverage_test.go index 8b99c3c..f5a577b 100644 --- a/internal/daemon/coverage_test.go +++ b/internal/daemon/coverage_test.go @@ -42,3 +42,25 @@ func TestDispatchCoversBrowser(t *testing.T) { } } } + +// TestIsStreamMethodCoversEveryStreamingBrowserMethod fails when a streaming +// Browser method is missing from isStreamMethod. +// +// The consequence of missing one is invisible in every stub-backed test and in +// any single-terminal use: the method would take the dispatch mutex for the +// whole life of the caller's --follow window, so every other command against the +// daemon would block behind it. A streaming method is the one whose last +// parameter is the emit callback, which is exactly why it cannot ride the unary +// one-request/one-response protocol. +func TestIsStreamMethodCoversEveryStreamingBrowserMethod(t *testing.T) { + t.Parallel() + emit := reflect.TypeOf(func(any) error { return nil }) + for m := range reflect.TypeFor[chrome.Browser]().Methods() { + last := m.Type.NumIn() - 1 + streams := last >= 0 && m.Type.In(last) == emit + if got := isStreamMethod(m.Name); got != streams { + t.Errorf("isStreamMethod(%q) = %v, want %v — it must name exactly the methods "+ + "streamDispatch serves, or a stream holds the dispatch mutex for its whole window", m.Name, got, streams) + } + } +}