Skip to content

fix: seven shipped defects in console and network observability - #16

Merged
sanketsudake merged 8 commits into
mainfrom
fix/observability-followups
Jul 27, 2026
Merged

fix: seven shipped defects in console and network observability#16
sanketsudake merged 8 commits into
mainfrom
fix/observability-followups

Conversation

@sanketsudake

Copy link
Copy Markdown
Owner

A code review of #13 after it merged found defects that CI and the RFC-scenario tests both passed over. These are live in main, so this is a fix-forward.

Each fix has a regression test proven red first, by stashing the source change and watching it fail.

The two that mattered most

A large binary response body was reported as an empty-but-present body

TruncateText trimmed one byte at a time until the whole string was valid UTF-8 — which only converges when the invalidity sits at the cut boundary. A 100 KB body of 0xFF truncated to "", and the utf8.ValidString guard that exists precisely to skip binary then passed, because "" is valid.

So net --body on a binary response over net_max_body emitted {"response_body": "", "body_truncated": true}, while the same image under the cap correctly said body_unavailable. Identical content, opposite answers, decided by nothing but size.

Validity is now checked on the original payload, and truncation backs off at most utf8.UTFMax-1 bytes instead of rescanning the prefix per byte — the old path burned ~10 ms of quadratic scanning per body, on the daemon's dispatch mutex.

--follow wedged every other command

Streaming dispatch held the daemon's global mutex for its entire window. Measured against the real Serve: a unary call waited 5.000014458s for a live --follow to finish.

RFC-0002 US-2 is literally "watch console output while I exercise the page" — so the feature defeated its own user story. console --follow in one terminal blocked click in another for the whole --timeout.

Streaming dispatch now takes no mutex. The agent deliberately didn't take the "serialise setup, then release" shape I sketched, and I agree with the reasoning: that needs a readiness callback plumbed through chrome.Browser, the stub, *CDP, both daemon halves and the CLI — to serialise two idempotent domain-enable round trips. The mutex exists so multi-step chromedp sequences on one connection don't interleave; a stream isn't that. TestIsStreamMethodCoversEveryStreamingBrowserMethod guards the list against drift.

Two consequences of the same root are fixed with it: the idle timer is now pinged while a stream is alive (a follow longer than the 30-minute window used to be cut silently, EOF, exit 0), and a hung-up client is detected immediately instead of when the daemon next writes.

The review's diagnosis was wrong, and the real bug was bigger

The review said console dropped the pre-attach backlog because Log.entryAdded/javascript was suppressed as a duplicate. Verified empirically against throwaway headless Chrome: Log.enable replayed nothing, and live uncaught exceptions produced no Log.entryAdded/javascript at all — so there was no duplicate to suppress.

The actual cause is in the attach sequence: chromedp issues runtime.Enable(), log.Enable() and network.Enable() before startCapture registers its ListenTarget. The entire backlog, from every source, went on the floor. Registering listeners before chromedp.Run recovers it — and it arrives as Runtime.exceptionThrown, contrary to the review's claim that Runtime doesn't replay.

The source filter is replaced by identity dedupe in a 2s window, so a genuinely recurring error still shows every occurrence.

⚠️ Contract consequence: a --no-daemon read now genuinely sees some history, so buffered: 0 beside a non-empty list would have been incoherent. Both verbs report the real buffered and the note says "partial history" rather than "no retained history". Docs and console --help updated; the VS-10 tests were repurposed rather than deleted.

Redaction gaps

  • Hash-router fragments leaked tokens. https://app/#/callback?access_token=SECRET parsed the name as /callback?access_token, which the anchored regex rejected — so the token was emitted verbatim. That is exactly the OAuth implicit flow the fragment handling was added for.
  • Location: on a 302 was redacted by nothing — not by name (doesn't match) and not by RedactURL (never applied to header values). URL-valued headers now go through RedactURL rather than being withheld wholesale, so a redirect stays diagnosable.
  • Request bodies had no UTF-8 guard at all, so a multipart/form-data image upload became mojibake — precisely what the response-path comment says must not happen.

Bodies are now redacted by default

RFC-0003 only specifies header and URL redaction, so this is a scope decision. The deciding argument is the inconsistency, not the risk in the abstract: ?password=x was already withheld while password=x in a POST body was printed in clear — same secret, opposite answers, decided by nothing but the HTTP method.

Implemented as a structure-preserving rewrite rather than decode/re-encode, because a body cut at the 64 KB cap is no longer parseable and re-encoding would stop the reported payload being the one the page actually sent. Documented limitation: multipart/form-data and other opaque encodings have no field structure to key on and pass through unchanged.

Also

  • Per-tab rings were never released. Set.Forget existed, was tested, and had no non-test caller — ~250 KB retained per tab for the daemon's life. Now released on close, including a browser-level targetDestroyed listener for tabs the user closes, which over a long session is most of them.
  • pending ignored the caller's filter, so a permanently-open SSE stream made every net --url /api/save report pending >= 1 forever. Now scoped to --url/--method/--type/--since; --status/--failed are deliberately excluded, since an in-flight request has no status and including them would make pending a constant zero for exactly the reads asking about an outcome.
  • A quiet --follow emitting zero envelopes is documented, not changed — a terminating summary would be a second envelope shape, and both the skill and session parity depend on one shape per line.

Testing

gofmt, go vet, go test -race ./... clean, including ~108s of live Chrome. The redaction test asserts on the marshalled envelope bytes, not struct fields, so a second unredacted copy riding along in url would still fail it.

sanketsudake and others added 8 commits July 27, 2026 16:16
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) <noreply@anthropic.com>
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) <noreply@anthropic.com>
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) <noreply@anthropic.com>
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) <noreply@anthropic.com>
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) <noreply@anthropic.com>
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) <noreply@anthropic.com>
…contract

`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) <noreply@anthropic.com>
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) <noreply@anthropic.com>
@sanketsudake
sanketsudake merged commit 23e2ff5 into main Jul 27, 2026
4 checks passed
@sanketsudake
sanketsudake deleted the fix/observability-followups branch July 27, 2026 11:46
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant