Skip to content

gc events lies to a machine reader three ways: --since discards a timed-out page walk, a comma --type exits 0 with no records and no stderr, and the --json deprecation notice corrupts stdout JSONL (gc-378x4) - #174

Merged
zook-bot merged 2 commits into
mainfrom
polecat/gc-378x4
Sep 4, 2026

Conversation

@zook-bot

@zook-bot zook-bot commented Sep 4, 2026

Copy link
Copy Markdown

Summary

gc events had three ways to hand a machine reader an empty answer that looked
like a real one. All three were measured live in loomington on 2026-09-03, and
each is fixed with a regression guard that fails against origin/main.

--since threw away a walk it ran out of time for. doEvents built one
30s context and fetchCityEvents drained the entire window under it, 500
events per page. A page cost 0.18s at the head of the log and ~3.7s deep in
the walk, so a 24h window never fit — and on the deadline the walk returned
nil, discarding every page it had already fetched. Thirty seconds of
successful fetching printed nothing.

It now returns the pages it read, paired with an error naming the oldest seq
and timestamp it reached. doEvents prints those events to stdout, writes the
coverage boundary to stderr, and exits non-zero, so a caller can tell a window
it searched from one it never reached. The city drain also gets a budget sized
for a page walk instead of for a single request; the supervisor list issues one
request whatever the filters say, so it keeps the 30s hang guard (pinned by its
own test). The same --since 24h that returned nothing now returns 41,000
events over 10.5h with the boundary stated.

A comma-separated --type matched nothing, silently. Both filters that
read the value compare one exact string — filterCityEvents tests
item.Type != typeFilter, and the API's EventListInput.Type is a scalar
query param — so --type=a,b,c matched no event, the server minted no
next_cursor, and the command exited 0 with no records and an empty stderr.
That is indistinguishable from "none of those events occurred", which is
precisely the question a coverage query is asking. It is now rejected in
RunE, beside the existing --after rejection, so list, watch and follow all
get it.

The --json deprecation notice was written to stdout. MarkDeprecated
makes pflag buffer the notice into cobra's flagErrorBuf; ParseFlags drains
it through Command.PrintOutOrStderr, and cmd/gc/main.go points that
writer at stdout. The notice landed as line 1 of a stream this command
documents as JSON Lines, where wc -l counts it as an event and jq fails on
it. MarkHidden makes the no-op flag the silent no-op it claims to be.
TestEventsJSONFlagIsSilentNoOp could not catch this — it never called
cmd.SetOut, so the notice escaped to the process stderr rather than the
buffer it asserts on. It wires both writers now and checks that every stdout
line parses as JSON.

Checked and not a defect, recorded so the next reader need not re-check:
--limit is already rejected as an unknown flag with exit 1. The "single junk
line" attributed to it in the originating report is the --json notice above,
seen on a command line that also carried --json.

docs/reference/events.md gains the --type cardinality rule and a Window
Coverage section stating that a --since count is a floor and that callers
distinguishing "none occurred" from "not fully read" must check exit status.

The pre-commit hook could not run on this host for any diff: it exports
GOTOOLCHAIN, GOROOT_VAL then resolves to the toolchain root, and
TEST_ENV's env -i forwards GOROOT without GOTOOLCHAIN, so check-docs
drives a 1.26.6 GOROOT with the 1.27.0 go on PATH. It reproduces on a clean
tree at origin/main; commented on gc-m7rp0, which owns that root cause. This
commit therefore used --no-verify after each gate was run by hand: gofmt
clean, go build and go vet clean, every cmd_events test passing, the
hook's own scoped lint (LINT_CHANGED_SCOPE=staged --new-from-rev=HEAD --whole-files) reporting 0 issues, and check-docs passing under a coherent
toolchain.

Reported as tk-0bltj in the gc-toolkit ledger; filed here as gc-378x4
because the defect is in this repo and a tk- bead cannot route to this rig's
refinery.

Dispatch — what this work was asked to do

Symptom (re-measured 2026-09-03 in loomington, all three confirmed live)

gc events --json                 -> 500 records, exit 0
gc events --since 24h            -> 0 records, exit 1, 30.9s wall
  stderr: request failed: Get ".../events?cursor=...&limit=500&since=24h":
          context deadline exceeded

gc events --since=24h --type=session.woke,session.stopped,session.crashed
                                 -> 0 records, exit 0, EMPTY STDERR
gc events --since=2m  --type=session.woke
                                 -> 3 records, exit 0

gc events --json --type=session.woke
  stdout line 1: "Flag --json has been deprecated, output is always JSONL..."

Filed from gc-toolkit tk-0bltj, which reported the first symptom. The store
boundary is why this bead exists: the defect is in this repo, tk-0bltj is in
the gc-toolkit ledger, and a tk- bead cannot be routed to this rig's refinery.

Three distinct defects

1. --since discards a walk it ran out of time for.
doEvents (cmd/gc/cmd_events.go) builds ONE 30s context and hands it to
fetchCityEvents, which — only when --since is set — drains the whole window
at cityEventsPageLimit (500) per page. One page measured 0.18s / 1.1MB / 8.6
minutes of history, so a 24h window is ~167 pages and does not fit in 30s. When
the deadline fires mid-walk, fetchCityEvents returns nil, err: every page
already fetched is thrown away. 30 seconds of successful fetching prints
nothing.

2. A comma-separated --type silently matches nothing.
--type is one exact string on both sides — client filterCityEvents compares
item.Type != typeFilter, and the API's EventListInput.Type is a scalar
query:"type". --type=a,b,c therefore matches no event, and the server mints
no next_cursor, so the CLI exits 0 with zero records and an empty stderr. This
is the false-clean shape tk-0bltj was filed about: a caller cannot tell "no such
events occurred" from "that query could never match". It reproduces with or
without --since.

3. The --json deprecation notice is written to STDOUT.
MarkDeprecated makes pflag buffer the notice into cobra's flagErrorBuf;
ParseFlags drains it through c.Print -> OutOrStderr(), and
cmd/gc/main.go:405 does root.SetOut(stdout). The notice lands as line 1 of
a stream documented as JSON Lines, so wc -l counts it as an event and jq
fails on it. TestEventsJSONFlagIsSilentNoOp does not catch this: it never
calls cmd.SetOut, so in-test the notice escapes to the real os.Stderr
instead of the buffer it asserts on.

Not defects (checked, so the next reader does not re-check)

  • --limit is correctly rejected: gc: unknown flag: --limit, exit 1. The
    "single junk line" tk-0bltj attributes to --limit is defect 3 above,
    observed on a command line that also carried --json.
  • The server's since filter works. The client walk is what fails.

Fix

  1. fetchCityEvents returns the pages it did fetch when the walk is cut short,
    with an error naming the coverage boundary; doEvents prints those events,
    warns on stderr, and exits non-zero. A coverage query must be able to state
    how far it actually looked.
  2. Reject a --type value containing a comma, next to the existing
    --after/--after-cursor rejection, so list, watch and follow are all
    covered. Same reasoning already recorded there: reject rather than silently
    ignore.
  3. Replace MarkDeprecated("json") with MarkHidden("json") so the no-op flag
    is actually silent and stdout stays pure JSONL; strengthen
    TestEventsJSONFlagIsSilentNoOp to wire cmd.SetOut so it can see the
    regression.

Refinery handoff

  • Issue: gc-378x4
  • Source branch: polecat/gc-378x4
  • Target: main
  • Gates codex signed off pre-open at 73859001; PR opened green.

zook-bot and others added 2 commits September 4, 2026 01:32
…ed-out page walk, a comma --type exits 0 with nothing, and the --json notice corrupts stdout JSONL (gc-378x4)

Measured in loomington 2026-09-03, all three live:

  gc events --since 24h                0 records, exit 1, 30.9s wall
  gc events --since=24h --type=a,b,c   0 records, exit 0, EMPTY stderr
  gc events --json --type=session.woke stdout line 1 is the deprecation notice

--since: doEvents built one 30s context and fetchCityEvents drained the whole
window under it at 500 events per page. A page cost 0.18s at the head and
~3.7s deep in the walk, so a 24h window never fit; on the deadline the walk
returned nil and every page it had already fetched was discarded. It now
returns what it read, paired with an error naming the oldest seq and timestamp
it reached, and doEvents prints those events, writes the boundary to stderr
and exits non-zero. The city drain also gets a budget sized for a walk rather
than for one request; the supervisor list issues a single request whatever the
filters say, so it keeps the 30s guard. That same 24h ask now yields 41000
events over 10.5h with the boundary named, where it yielded nothing.

--type: both filters that read it compare one exact string -- filterCityEvents
tests item.Type != typeFilter, and the API's EventListInput.Type is a scalar
query param -- so a comma list matches no event and the server mints no
next_cursor. Rejected in RunE beside the existing --after rejection, which
covers list, watch and follow.

--json: MarkDeprecated makes pflag buffer a notice that cobra drains through
Command.Print -> OutOrStderr, and cmd/gc/main.go points that writer at stdout,
so it landed as line 1 of a stream documented as JSON Lines. MarkHidden keeps
the flag the silent no-op it claims to be. TestEventsJSONFlagIsSilentNoOp
could not catch this because it never wired cmd.SetOut; it does now.

Checked and not a defect, so the next reader need not: --limit is already
rejected as an unknown flag. The junk line attributed to it upstream is the
--json notice above.

docs/reference/events.md gains the --type cardinality rule and a Window
Coverage section: a --since count is a floor, and a caller separating "none
occurred" from "not fully read" has to check exit status. engdocs listed "No
event retention or rotation. The JSONL file grows without bound" under Known
Limitations; rotation is enabled by default and size-triggered, and nothing
bounds the active log by time, which is why the reachable window varies with
how fast the city emits.

Reported as tk-0bltj in the gc-toolkit ledger.

Claude-Session: https://claude.ai/code/session_01GDAdvz2wt3D7h4hUoqzqPH
The Known Limitations note claimed gc events visibility tracks the active
file's emission rate (a busy city holds minutes, a quiet one days). The list
paths read the active file plus every retained sibling archive: List ->
ReadFiltered, and ListInFlight -> ReadFilteredWithInFlight for a segment
still mid-rotation (fetchEventPageAscending -> listWithInFlight). A query
therefore reaches the whole retained history, not just the active file.

Rotation is size-triggered and only sets how much history the active file
alone holds; how far back a query reaches is governed by archive retention
(archive_retain_age, which keeps all archives when empty via
reapExpiredArchives). Separate the two in the note accordingly.

Addresses the pre-open signoff finding on gc-8au8k (review of
polecat/gc-378x4). Pre-commit hook skipped: gc-m7rp0 makes it fail on this
host for any diff; docsync gate run by hand under a coherent toolchain (ok).

Claude-Session: https://claude.ai/code/session_0173HfdLWDyFjw1ukmH5BdaN
@zook-bot

zook-bot commented Sep 4, 2026

Copy link
Copy Markdown
Author

Pre-open signoff (comment-only — not an approval):

VERDICT: approve
Reviewed branch: polecat/gc-378x4
Reviewed base: main
Reviewed commit: 7385900

Scope checked: Read the full three-dot diff from origin/main to 7385900 across cmd/gc/cmd_events.go, cmd/gc/cmd_events_test.go, docs/reference/events.md, and engdocs/architecture/event-bus.md. Checked anchor bead gc-378x4, review bead gc-qcu53, prior request-changes reviews gc-mp0qv and gc-8au8k, and the rework notes on gc-5zqvk and gc-ytmkf. Checked newEventsCmd, validateEventsType, doEvents, cityEventsListBudget, fetchCityEvents, fetchCityEventsAfterSeq, fetchSupervisorEvents, filterCityEvents, streamCityEvents, streamSupervisorEvents, the Huma city and supervisor event-list input/handler paths, generated event-list query params, FileRecorder.List/ListInFlight, ReadFiltered, ReadFilteredWithInFlight, rotation retention defaults, docs/reference events guidance, engdocs event-bus retention wording, the API control-plane/Huma docs, TESTING.md, the gascity-docs review rules, and the pack work-quality and learning-exemplar fragments. This is pre-open, so there is no PR page to review. I did not run the full project matrix or dashboard checks; the diff does not touch internal/api, OpenAPI, dashboard code, or generated dashboard types.

Findings: none.

Filed: none.

Verification: At the reviewed commit in detached worktree /tmp/gc-review-gc-qcu53.4qaZPE, an initial isolated-cache go test -json ./cmd/gc -run 'Test(Events|DoEvents|FetchCityEvents|CityEvents|SupervisorEvents)' -count=1 failed before test execution with disk quota exceeded while writing Go build/vet artifacts under /tmp. Retried with the existing shared Go build cache: the same JSON test selection passed with 74 passed tests and 0 failed tests, and go test ./cmd/gc -run 'Test(Events|DoEvents|FetchCityEvents|CityEvents|SupervisorEvents)' -count=1 passed. make check-docs passed. go run ./cmd/genschema produced no git diff.

Anchor: gc-378x4 — check.codex @ 7385900

@zook-bot
zook-bot merged commit 4623bf1 into main Sep 4, 2026
83 of 89 checks passed
zook-bot added a commit that referenced this pull request Sep 17, 2026
…ed-out page walk, a comma --type exits 0 with no records and no stderr, and the --json deprecation notice corrupts stdout JSONL (gc-378x4) (#174)

* gc events lies to a machine reader three ways: --since discards a timed-out page walk, a comma --type exits 0 with nothing, and the --json notice corrupts stdout JSONL (gc-378x4)

Measured in loomington 2026-09-03, all three live:

  gc events --since 24h                0 records, exit 1, 30.9s wall
  gc events --since=24h --type=a,b,c   0 records, exit 0, EMPTY stderr
  gc events --json --type=session.woke stdout line 1 is the deprecation notice

--since: doEvents built one 30s context and fetchCityEvents drained the whole
window under it at 500 events per page. A page cost 0.18s at the head and
~3.7s deep in the walk, so a 24h window never fit; on the deadline the walk
returned nil and every page it had already fetched was discarded. It now
returns what it read, paired with an error naming the oldest seq and timestamp
it reached, and doEvents prints those events, writes the boundary to stderr
and exits non-zero. The city drain also gets a budget sized for a walk rather
than for one request; the supervisor list issues a single request whatever the
filters say, so it keeps the 30s guard. That same 24h ask now yields 41000
events over 10.5h with the boundary named, where it yielded nothing.

--type: both filters that read it compare one exact string -- filterCityEvents
tests item.Type != typeFilter, and the API's EventListInput.Type is a scalar
query param -- so a comma list matches no event and the server mints no
next_cursor. Rejected in RunE beside the existing --after rejection, which
covers list, watch and follow.

--json: MarkDeprecated makes pflag buffer a notice that cobra drains through
Command.Print -> OutOrStderr, and cmd/gc/main.go points that writer at stdout,
so it landed as line 1 of a stream documented as JSON Lines. MarkHidden keeps
the flag the silent no-op it claims to be. TestEventsJSONFlagIsSilentNoOp
could not catch this because it never wired cmd.SetOut; it does now.

Checked and not a defect, so the next reader need not: --limit is already
rejected as an unknown flag. The junk line attributed to it upstream is the
--json notice above.

docs/reference/events.md gains the --type cardinality rule and a Window
Coverage section: a --since count is a floor, and a caller separating "none
occurred" from "not fully read" has to check exit status. engdocs listed "No
event retention or rotation. The JSONL file grows without bound" under Known
Limitations; rotation is enabled by default and size-triggered, and nothing
bounds the active log by time, which is why the reachable window varies with
how fast the city emits.

Reported as tk-0bltj in the gc-toolkit ledger.

Claude-Session: https://claude.ai/code/session_01GDAdvz2wt3D7h4hUoqzqPH

* docs(event-bus): correct gc events retention/visibility note (gc-ytmkf)

The Known Limitations note claimed gc events visibility tracks the active
file's emission rate (a busy city holds minutes, a quiet one days). The list
paths read the active file plus every retained sibling archive: List ->
ReadFiltered, and ListInFlight -> ReadFilteredWithInFlight for a segment
still mid-rotation (fetchEventPageAscending -> listWithInFlight). A query
therefore reaches the whole retained history, not just the active file.

Rotation is size-triggered and only sets how much history the active file
alone holds; how far back a query reaches is governed by archive retention
(archive_retain_age, which keeps all archives when empty via
reapExpiredArchives). Separate the two in the note accordingly.

Addresses the pre-open signoff finding on gc-8au8k (review of
polecat/gc-378x4). Pre-commit hook skipped: gc-m7rp0 makes it fail on this
host for any diff; docsync gate run by hand under a coherent toolchain (ok).

Claude-Session: https://claude.ai/code/session_0173HfdLWDyFjw1ukmH5BdaN

---------

Co-authored-by: refinery costing <refinery@local>
zook-bot added a commit that referenced this pull request Sep 17, 2026
…ed-out page walk, a comma --type exits 0 with no records and no stderr, and the --json deprecation notice corrupts stdout JSONL (gc-378x4) (#174)

* gc events lies to a machine reader three ways: --since discards a timed-out page walk, a comma --type exits 0 with nothing, and the --json notice corrupts stdout JSONL (gc-378x4)

Measured in loomington 2026-09-03, all three live:

  gc events --since 24h                0 records, exit 1, 30.9s wall
  gc events --since=24h --type=a,b,c   0 records, exit 0, EMPTY stderr
  gc events --json --type=session.woke stdout line 1 is the deprecation notice

--since: doEvents built one 30s context and fetchCityEvents drained the whole
window under it at 500 events per page. A page cost 0.18s at the head and
~3.7s deep in the walk, so a 24h window never fit; on the deadline the walk
returned nil and every page it had already fetched was discarded. It now
returns what it read, paired with an error naming the oldest seq and timestamp
it reached, and doEvents prints those events, writes the boundary to stderr
and exits non-zero. The city drain also gets a budget sized for a walk rather
than for one request; the supervisor list issues a single request whatever the
filters say, so it keeps the 30s guard. That same 24h ask now yields 41000
events over 10.5h with the boundary named, where it yielded nothing.

--type: both filters that read it compare one exact string -- filterCityEvents
tests item.Type != typeFilter, and the API's EventListInput.Type is a scalar
query param -- so a comma list matches no event and the server mints no
next_cursor. Rejected in RunE beside the existing --after rejection, which
covers list, watch and follow.

--json: MarkDeprecated makes pflag buffer a notice that cobra drains through
Command.Print -> OutOrStderr, and cmd/gc/main.go points that writer at stdout,
so it landed as line 1 of a stream documented as JSON Lines. MarkHidden keeps
the flag the silent no-op it claims to be. TestEventsJSONFlagIsSilentNoOp
could not catch this because it never wired cmd.SetOut; it does now.

Checked and not a defect, so the next reader need not: --limit is already
rejected as an unknown flag. The junk line attributed to it upstream is the
--json notice above.

docs/reference/events.md gains the --type cardinality rule and a Window
Coverage section: a --since count is a floor, and a caller separating "none
occurred" from "not fully read" has to check exit status. engdocs listed "No
event retention or rotation. The JSONL file grows without bound" under Known
Limitations; rotation is enabled by default and size-triggered, and nothing
bounds the active log by time, which is why the reachable window varies with
how fast the city emits.

Reported as tk-0bltj in the gc-toolkit ledger.

Claude-Session: https://claude.ai/code/session_01GDAdvz2wt3D7h4hUoqzqPH

* docs(event-bus): correct gc events retention/visibility note (gc-ytmkf)

The Known Limitations note claimed gc events visibility tracks the active
file's emission rate (a busy city holds minutes, a quiet one days). The list
paths read the active file plus every retained sibling archive: List ->
ReadFiltered, and ListInFlight -> ReadFilteredWithInFlight for a segment
still mid-rotation (fetchEventPageAscending -> listWithInFlight). A query
therefore reaches the whole retained history, not just the active file.

Rotation is size-triggered and only sets how much history the active file
alone holds; how far back a query reaches is governed by archive retention
(archive_retain_age, which keeps all archives when empty via
reapExpiredArchives). Separate the two in the note accordingly.

Addresses the pre-open signoff finding on gc-8au8k (review of
polecat/gc-378x4). Pre-commit hook skipped: gc-m7rp0 makes it fail on this
host for any diff; docsync gate run by hand under a coherent toolchain (ok).

Claude-Session: https://claude.ai/code/session_0173HfdLWDyFjw1ukmH5BdaN

---------

Co-authored-by: refinery costing <refinery@local>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant