Merge pull request #16 from rebelopsio/diag/agent-stderr-and-options

chore(agent): log SDK options and capture claude subprocess stderr

Author: rebelopsio

cmd/daily_run.go

@@ -244,6 +244,9 @@ func explainAgentOutcome(res *agent.RunResult, statErr error) error {
 	} else {
 		fmt.Fprintf(&b, "\nagent said: <empty>")
 	}
+	if res.SubprocessStderr != "" {
+		fmt.Fprintf(&b, "\nclaude stderr: %s", truncateText(res.SubprocessStderr, 2000))
+	}
 	return errors.New(b.String())
 }
 

cmd/daily_run_test.go

@@ -491,6 +491,23 @@ func TestRunDaily_AgentTextTruncated(t *testing.T) {
 	assert.Less(t, len(msg), 2000, "error message should be bounded")
 }
 
+// Subprocess stderr captured by the SDK is surfaced in the
+// verification-failure error so the operator can see what claude
+// actually wrote before exiting.
+func TestRunDaily_VerificationErrorIncludesSubprocessStderr(t *testing.T) {
+	deps, gatherer, runtime, _ := fixtureDeps(t)
+	gatherer.issues = []domain.Issue{{Ref: domain.ExternalRef{Provider: "linear", ID: "X"}, Title: "x"}}
+
+	runtime.result = &agent.RunResult{
+		SubprocessStderr: "Error: unknown flag --bogus",
+	}
+
+	_, err := runDaily(context.Background(), deps, dailyOptions{})
+	require.Error(t, err)
+	assert.Contains(t, err.Error(), "claude stderr:")
+	assert.Contains(t, err.Error(), "unknown flag --bogus")
+}
+
 // Turns, duration, and cost from the SDK are surfaced so the operator
 // can tell whether the model was consulted at all when both tool
 // calls and text are empty.

internal/agent/run.go

@@ -4,10 +4,15 @@ import (
 	"context"
 	"errors"
 	"fmt"
+	"io"
+	"sort"
 	"strings"
+	"sync"
 	"time"
 
 	claude "github.com/partio-io/claude-agent-sdk-go"
+
+	"github.com/rebelopsio/archy/internal/config"
 )
 
 // RunRequest describes a single skill execution.
@@ -45,6 +50,10 @@ type RunResult struct {
 	// CostUSD is the model's reported cost for this run, if available.
 	// Zero means unknown.
 	CostUSD float64
+	// SubprocessStderr is everything the claude CLI subprocess wrote
+	// to its stderr during this run, joined newline-per-callback.
+	// Empty when the subprocess produced no stderr output.
+	SubprocessStderr string
 }
 
 // ToolCallRecord is one tool invocation observed during a run.
@@ -85,6 +94,23 @@ func (r *Runtime) Run(ctx context.Context, req RunRequest) (*RunResult, error) {
 	}
 	opts = append(opts, claude.WithAppendSystemPrompt(systemPromptAddition(req)))
 
+	// Capture the claude CLI subprocess's stderr so silent-failure
+	// modes (subprocess exits before consulting the model) surface
+	// the underlying error. The callback fires from the SDK's drain
+	// goroutine, so guard the buffer with a mutex.
+	var (
+		stderrMu  sync.Mutex
+		stderrBuf strings.Builder
+	)
+	opts = append(opts, claude.WithStderrCallback(func(line string) {
+		stderrMu.Lock()
+		defer stderrMu.Unlock()
+		stderrBuf.WriteString(line)
+		stderrBuf.WriteByte('\n')
+	}))
+
+	logSDKInvocation(r.stderrLog, r.cfg, r.opts, opts, req)
+
 	emit := func(ev ProgressEvent) {
 		if req.ProgressFn != nil {
 			req.ProgressFn(ev)
@@ -95,6 +121,14 @@ func (r *Runtime) Run(ctx context.Context, req RunRequest) (*RunResult, error) {
 	emit(ProgressEvent{Kind: ProgressStart, At: start})
 
 	res := &RunResult{}
+	// readStderr returns the captured subprocess output. Called on
+	// every return path so RunResult.SubprocessStderr is always
+	// populated (empty when nothing was written).
+	readStderr := func() string {
+		stderrMu.Lock()
+		defer stderrMu.Unlock()
+		return stderrBuf.String()
+	}
 	pending := make(map[string]*ToolCallRecord) // tool_use_id → in-flight record
 	var assistantText strings.Builder
 	systemSeen := false
@@ -105,6 +139,11 @@ func (r *Runtime) Run(ctx context.Context, req RunRequest) (*RunResult, error) {
 			if ctx.Err() != nil && (errors.Is(err, context.Canceled) || errors.Is(err, context.DeadlineExceeded)) {
 				return nil, fmt.Errorf("agent run canceled: %w", ctx.Err())
 			}
+			// Surface the subprocess stderr alongside the SDK error so
+			// the operator sees what claude actually said before exiting.
+			if s := readStderr(); s != "" {
+				return nil, fmt.Errorf("%w: %v (claude stderr: %s)", ErrRun, err, s)
+			}
 			return nil, fmt.Errorf("%w: %v", ErrRun, err)
 		}
 		if ctx.Err() != nil {
@@ -143,17 +182,47 @@ func (r *Runtime) Run(ctx context.Context, req RunRequest) (*RunResult, error) {
 				emit(ProgressEvent{Kind: ProgressEnd, Message: endMsg, At: time.Now()})
 				res.Text = assistantText.String()
 				res.Duration = time.Since(start)
+				res.SubprocessStderr = readStderr()
 				return res, fmt.Errorf("%w: %s", ErrRun, endMsg)
 			}
 		}
 	}
 
 	res.Text = assistantText.String()
 	res.Duration = time.Since(start)
+	res.SubprocessStderr = readStderr()
 	emit(ProgressEvent{Kind: ProgressEnd, Message: "completed", At: time.Now()})
 	return res, nil
 }
 
+// logSDKInvocation writes a one-time summary of the agent invocation
+// to w. This is the last thing archy controls before subprocess
+// handoff; if claude exits without consulting the model, the answer
+// is almost certainly in what we passed it. Secrets (bearer tokens,
+// auth headers) are never logged.
+func logSDKInvocation(w io.Writer, cfg *config.Config, opts Options, sdkOpts []claude.Option, req RunRequest) {
+	mcpEnabled := []string{}
+	for name, srv := range cfg.MCPServers {
+		if srv.Enabled {
+			mcpEnabled = append(mcpEnabled, name)
+		}
+	}
+	sort.Strings(mcpEnabled)
+
+	_, _ = fmt.Fprintln(w, "archy agent invocation:")
+	_, _ = fmt.Fprintf(w, "  skill=%s\n", req.SkillName)
+	_, _ = fmt.Fprintf(w, "  model=%s\n", cfg.Agent.Model)
+	_, _ = fmt.Fprintf(w, "  max_turns=%d\n", cfg.Agent.MaxTurns)
+	_, _ = fmt.Fprintf(w, "  permission_mode=%s\n", cfg.Agent.PermissionMode)
+	_, _ = fmt.Fprintf(w, "  cwd=%s\n", opts.Cwd)
+	_, _ = fmt.Fprintf(w, "  cli_path=%s\n", opts.CLIPath)
+	_, _ = fmt.Fprintf(w, "  archy_binary=%s\n", opts.ArchyBinaryPath)
+	_, _ = fmt.Fprintf(w, "  sdk_option_count=%d\n", len(sdkOpts))
+	_, _ = fmt.Fprintf(w, "  mcp_servers_enabled=%v\n", mcpEnabled)
+	_, _ = fmt.Fprintf(w, "  skills_project_dir=%s\n", cfg.Skills.ProjectDir)
+	_, _ = fmt.Fprintf(w, "  skills_user_dir=%s\n", cfg.Skills.UserDir)
+}
+
 // systemPromptAddition is the one-line skill-invocation instruction the
 // runtime appends via [claude.WithAppendSystemPrompt]. Skill authors
 // can rely on the agent seeing this exact phrasing.

internal/agent/runtime.go

@@ -3,6 +3,7 @@ package agent
 import (
 	"context"
 	"fmt"
+	"io"
 	"iter"
 	"os"
 	"sync"
@@ -23,6 +24,11 @@ type Runtime struct {
 	// the iter.Seq2 yielded by Stream.
 	runner runner
 
+	// stderrLog is where the agent writes operational diagnostic lines
+	// (SDK invocation summary, subprocess stderr). Defaults to
+	// os.Stderr; tests override with io.Discard or a buffer.
+	stderrLog io.Writer
+
 	// closeOnce guards Close from being called multiple times.
 	closeOnce sync.Once
 }
@@ -75,9 +81,10 @@ func New(opts Options) (*Runtime, error) {
 	}
 
 	return &Runtime{
-		cfg:    opts.Config,
-		opts:   opts,
-		runner: realRunner{},
+		cfg:       opts.Config,
+		opts:      opts,
+		runner:    realRunner{},
+		stderrLog: os.Stderr,
 	}, nil
 }
 

internal/agent/runtime_test.go

@@ -3,6 +3,7 @@ package agent
 import (
 	"context"
 	"errors"
+	"io"
 	"iter"
 	"testing"
 	"time"
@@ -54,6 +55,8 @@ func (f *fakeRunner) run(ctx context.Context, prompt string, opts []claude.Optio
 
 // newTestRuntime returns a Runtime with a baseline-valid config and a
 // substituted fake runner. The caller drives the fakeRunner's messages.
+// stderrLog is replaced with io.Discard to keep test output quiet —
+// the invocation log fires on every Run.
 func newTestRuntime(t *testing.T, fr *fakeRunner) *Runtime {
 	t.Helper()
 	rt, err := New(Options{
@@ -63,6 +66,7 @@ func newTestRuntime(t *testing.T, fr *fakeRunner) *Runtime {
 	})
 	require.NoError(t, err)
 	rt.runner = fr
+	rt.stderrLog = io.Discard
 	return rt
 }