diff --git a/internal/tools/perforce.go b/internal/tools/perforce.go index b458834..4f7b1f3 100644 --- a/internal/tools/perforce.go +++ b/internal/tools/perforce.go @@ -156,11 +156,7 @@ func (p *Perforce) run(ctx context.Context, maxBytes int, args ...string) ([]map cmd.Stdout, cmd.Stderr = &stdout, &stderr if err := cmd.Run(); err != nil { - msg := strings.TrimSpace(stderr.String()) - if msg == "" { - msg = err.Error() - } - return nil, stdout.Len(), fmt.Errorf("perforce: %s", firstLine(msg)) + return nil, stdout.Len(), fmt.Errorf("perforce: %s", failureDetail(stdout.Bytes(), stderr.String(), err)) } if maxBytes > 0 && stdout.Len() > maxBytes { return nil, stdout.Len(), fmt.Errorf("perforce: response exceeded max_bytes") @@ -203,6 +199,89 @@ func str(m map[string]any, k string) string { return "" } +// failureDetail extracts the most specific description available for a failed +// p4 invocation. +// +// Under -Mj the p4 client writes its error records to STDOUT as JSON, not to +// stderr. Reading stderr alone therefore left every tool failure reported as +// the bare wait-status text - "perforce: exit status 1" - with no indication of +// what actually went wrong. That cost four diagnoses before it was fixed: a +// missing trust file and an expired ticket on 2026-09-08, and the two failures +// in the 2026-09-14 Pilot Light replay, including changelist 118, whose cause +// is still unknown for exactly this reason. +// +// Precedence is most-specific-first: an error record from p4 itself, then +// stderr (which still carries connection-level failures the client never got +// far enough to report as a record), then the process wait status, which is +// always available and always useless on its own. +func failureDetail(stdout []byte, stderr string, runErr error) string { + if msg := firstErrorRecord(stdout); msg != "" { + return msg + } + if msg := strings.TrimSpace(stderr); msg != "" { + return firstLine(msg) + } + return firstLine(runErr.Error()) +} + +// firstErrorRecord returns the `data` field of the first -Mj record reporting a +// failure, or "" if there is none. +// +// A -Mj stream is one JSON object per record, and a failed command can emit +// several - p4 reports each error separately, and an error stream may also +// carry successful records before it. Records are identified by their +// "generic" and "severity" fields; anything at severity 3 (failed) or above is +// an error, and a record carrying `data` with no severity at all is treated as +// one too, since p4 is not perfectly consistent about emitting severity and the +// text is what the caller needs either way. +// +// Malformed or truncated JSON is not an error here: the decoder stops at the +// first record it cannot read and whatever was found before that still stands. +// This runs on a path that is ALREADY failing, so it must never panic or +// introduce a second failure on top of the first. +func firstErrorRecord(stdout []byte) string { + dec := json.NewDecoder(bytes.NewReader(stdout)) + for { + var m map[string]any + if err := dec.Decode(&m); err != nil { + return "" + } + + data := strings.TrimSpace(str(m, "data")) + if data == "" { + continue + } + + if severity, ok := numField(m, "severity"); ok { + if severity >= p4SeverityFailed { + return firstLine(data) + } + continue + } + + return firstLine(data) + } +} + +// p4's own severity scale: 0 empty, 1 info, 2 warning, 3 failed, 4 fatal. +const p4SeverityFailed = 3 + +// numField reads a field p4 may render as either a JSON number or a quoted +// string ("3" and 3 both occur across versions and record types). +func numField(m map[string]any, k string) (float64, bool) { + switch v := m[k].(type) { + case float64: + return v, true + case string: + n, err := strconv.ParseFloat(strings.TrimSpace(v), 64) + if err != nil { + return 0, false + } + return n, true + } + return 0, false +} + func firstLine(s string) string { if i := strings.IndexByte(s, '\n'); i >= 0 { return s[:i] diff --git a/internal/tools/perforce_error_test.go b/internal/tools/perforce_error_test.go new file mode 100644 index 0000000..de1d5bc --- /dev/null +++ b/internal/tools/perforce_error_test.go @@ -0,0 +1,107 @@ +package tools + +import ( + "errors" + "testing" +) + +// Under -Mj the p4 client writes its error records to stdout as JSON, not to +// stderr. Reading stderr alone left every tool failure reported as the bare +// wait status, "perforce: exit status 1" (issue #9). These records are captured +// from real p4 output. +func TestFailureDetail(t *testing.T) { + const ( + expiredTicket = `{"data":"Your session has expired, please login again.\n","generic":13,"severity":3,"code":"error"}` + "\n" + missingTrust = `{"data":"The authenticity of '10.0.0.4:1666' can't be established,\nthis may be your first attempt to connect to this P4PORT.\n","generic":38,"severity":3,"code":"error"}` + "\n" + ) + + tests := []struct { + name string + stdout string + stderr string + runErr error + want string + }{ + { + name: "an error record on stdout is preferred over the wait status", + stdout: expiredTicket, + runErr: errors.New("exit status 1"), + want: "Your session has expired, please login again.", + }, + { + name: "a multi-line record is reported by its first line", + stdout: missingTrust, + runErr: errors.New("exit status 1"), + want: "The authenticity of '10.0.0.4:1666' can't be established,", + }, + { + // A failing command can emit informational records before the error. + name: "an error record later in the stream is still found", + stdout: `{"data":"//depot/art/tex.png#1 - opened for add\n","generic":0,"severity":0,"code":"info"}` + "\n" + + `{"data":"Submit aborted -- fix problems then use 'p4 submit -c 42'.\n","generic":38,"severity":3,"code":"error"}` + "\n", + runErr: errors.New("exit status 1"), + want: "Submit aborted -- fix problems then use 'p4 submit -c 42'.", + }, + { + // An info-severity record is not a failure description; falling back + // to stderr beats reporting "opened for add" as the cause. + name: "informational records alone do not masquerade as the error", + stdout: `{"data":"//depot/art/tex.png#1 - opened for add\n","generic":0,"severity":0,"code":"info"}` + "\n", + stderr: "Connect to server failed; check $P4PORT.", + runErr: errors.New("exit status 1"), + want: "Connect to server failed; check $P4PORT.", + }, + { + // Some p4 versions render severity as a quoted string. + name: "severity is read whether p4 renders it as a number or a string", + stdout: `{"data":"Access for user 'ryan' has not been enabled by 'p4 protect'.\n","severity":"3","code":"error"}` + "\n", + runErr: errors.New("exit status 1"), + want: "Access for user 'ryan' has not been enabled by 'p4 protect'.", + }, + { + // Connection-level failures never get far enough to produce a record. + name: "stderr is used when stdout carries no record", + stderr: "Perforce client error:\n\tConnect to server failed", + runErr: errors.New("exit status 1"), + want: "Perforce client error:", + }, + { + name: "the wait status is the last resort, not the first", + runErr: errors.New("exit status 1"), + want: "exit status 1", + }, + { + // This runs on a path that is already failing; it must never turn + // one failure into two. + name: "truncated JSON degrades to stderr rather than panicking", + stdout: `{"data":"Your session has exp`, + stderr: "something went wrong", + runErr: errors.New("exit status 1"), + want: "something went wrong", + }, + { + name: "a record with no data field is skipped", + stdout: `{"generic":38,"severity":3,"code":"error"}` + "\n", + stderr: "fallback", + runErr: errors.New("exit status 1"), + want: "fallback", + }, + { + // p4 is not perfectly consistent about emitting severity; the text + // is what the caller needs either way. + name: "a data record with no severity is treated as the error", + stdout: `{"data":"Client 'bsg-cp-01' unknown - use 'client' command to create it.\n"}` + "\n", + runErr: errors.New("exit status 1"), + want: "Client 'bsg-cp-01' unknown - use 'client' command to create it.", + }, + } + + for _, tc := range tests { + t.Run(tc.name, func(t *testing.T) { + got := failureDetail([]byte(tc.stdout), tc.stderr, tc.runErr) + if got != tc.want { + t.Errorf("failureDetail()\n got: %q\nwant: %q", got, tc.want) + } + }) + } +}