Skip to content

fix(perforce): read p4 error records from stdout, not stderr (#9) - #11

Merged
ryanlitalien merged 1 commit into
mainfrom
fix/9-p4-error-records-on-stdout
Sep 15, 2026
Merged

ryanlitalien merged 1 commit into
mainfrom
fix/9-p4-error-records-on-stdout

Conversation

@ryanlitalien

Copy link
Copy Markdown
Member

Closes #9.

The bug

Under -Mj the p4 client writes its error records to stdout as JSON. run() read firstLine(stderr) - empty in that mode - and fell back to the process wait status, so every p4 tool failure surfaced as the bare string perforce: exit status 1 with no indication of what went wrong.

It has now cost four diagnoses: a missing trust file and an expired ticket on 2026-09-08 (the report on #9), and both failures in the 2026-09-14 Pilot Light replay. Changelist 118 is the live one - it is deterministic, reproduces with the connector idle and the command budget untouched, and its cause is still unknown because there is nothing to go on but an exit status.

The fix

failureDetail picks the most specific description available, most-specific first:

  1. the first -Mj error record on stdout (severity >= 3, p4's "failed"),
  2. stderr, which still carries connection-level failures the client never got far enough to report as a record,
  3. the wait status - always available, always useless on its own.

Details that are easy to get wrong and are covered by tests:

  • Informational records are skipped. A failing command can emit successful records before the error, so //depot/art/tex.png#1 - opened for add must never be reported as the cause.
  • An error later in the stream is still found, rather than only reading the first record.
  • severity is read whether p4 renders it as a number or a quoted string. Both occur across versions and record types.
  • A data record with no severity at all is treated as the error. p4 is not consistent about emitting it, and the text is what the caller needs either way.
  • Malformed or truncated JSON degrades to stderr rather than failing. This runs on a path that is already failing and must never turn one failure into two.
  • Multi-line records report their first line, matching the existing behaviour.

Audit log

No change was needed. session.go:399 already passes the tool error's text to finish's detail argument, so the real message now reaches the local audit log on its own.

Worth being explicit about what this does and does not change for the caller: the broker still receives only the stable tool_error token. The detail can carry LAN specifics - p4 stderr with a server host:port - and stays on the studio's box by design. So diagnosing changelist 118 after this ships means reading /data/connector/audit-YYYY-MM-DD.log on bsg-cp-01, not Sentry or the Rails side. That boundary is deliberate and this PR does not move it.

Release

This is a prerequisite for the rest of the v0.3.0 work (ButterStack/butter_stack#1904 steps 3 and 4: raise the P-class defaults, and truncate on max_bytes instead of erroring). Fixing it first means the re-sync of changelist 118 produces a usable error if it still fails, rather than needing a second release to find out why.

Note for anyone following a link here: ButterStack/butter_stack#1904 and #1902 both cite this bug as "#1630", which is wrong - butter_stack#1630 is the connector daemon bring-up issue. This is the real one.

Tests

go test ./... green; go vet ./... clean; gofmt clean. Ten cases in internal/tools/perforce_error_test.go, built from real p4 -Mj output.

Under -Mj the p4 client writes its error records to STDOUT as JSON. run()
read firstLine(stderr), which is empty in that mode, and fell back to the
process wait status - so every p4 tool failure surfaced as the bare string
"perforce: exit status 1" with no indication of what went wrong.

That has now cost four diagnoses: a missing trust file and an expired
ticket on 2026-09-08, and both failures in the 2026-09-14 Pilot Light
replay. Changelist 118's cause is still unknown for exactly this reason -
it is deterministic and reproduces with the connector idle, and there is
nothing to go on but the exit status.

failureDetail picks the most specific description available, in order:

  1. the first -Mj error record on stdout (severity >= 3, p4's "failed"),
  2. stderr, which still carries connection-level failures the client
     never got far enough to report as a record,
  3. the wait status, always available and always useless alone.

Informational records are skipped rather than reported as the cause, so a
"opened for add" line never masquerades as the failure. severity is read
whether p4 renders it as a number or a quoted string, since both occur. A
record carrying data with no severity at all is treated as the error: p4 is
not consistent about emitting it and the text is what the caller needs
either way.

Malformed or truncated JSON degrades to stderr rather than failing. This
runs on a path that is already failing and must never turn one failure into
two.

No change was needed on the audit side: session.go already passes the tool
error's text to finish's detail argument, so the real message now reaches
the local audit log on its own. The broker still receives only the stable
tool_error token - the detail can carry LAN specifics (a server host:port)
and stays on the studio's box by design.
@ryanlitalien
ryanlitalien merged commit 4d495ad into main Sep 15, 2026
1 check passed
@ryanlitalien
ryanlitalien deleted the fix/9-p4-error-records-on-stdout branch September 15, 2026 15:52
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.

p4 tool errors are reported as 'exit status 1' because -Mj error records go to stdout

1 participant