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

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]

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)
+			}
+		})
+	}
+}