diff --git a/README.md b/README.md index d8c6d8d..3866ff1 100644 --- a/README.md +++ b/README.md @@ -102,6 +102,7 @@ Default CLI wiring builds and uses: Subprocess runtime note: - subprocesses inherit the parent environment by default, then apply Narratio override values (override values win). +- non-zero subprocess errors include stdout/stderr log paths and a short redacted stderr tail when available to speed diagnosis. Real `polish` stage output paths: diff --git a/architecture.md b/architecture.md index 499e938..c04815d 100644 --- a/architecture.md +++ b/architecture.md @@ -333,9 +333,9 @@ All adapters currently have fake/no-op implementations for tests/scaffold execut - Context cancellation + optional timeout. - Explicit executable/args, working dir, env overrides. - Parent environment inheritance with override merge semantics (override values win). -- Stdout/stderr log file handling. +- Stdout/stderr log file handling (including a shared-stream guard when both logs target the same path). - Exit code and timing capture. -- Actionable error wrapping. +- Actionable error wrapping, including stdout/stderr log paths and a short redacted stderr tail when available. - Atomic file/YAML writers for generated config/log scaffolding. ## 12. Run Control, Locking, Logging, and Long-Running Stages diff --git a/internal/adapters/audita/subprocess_test.go b/internal/adapters/audita/subprocess_test.go index 1c322d5..a4448fc 100644 --- a/internal/adapters/audita/subprocess_test.go +++ b/internal/adapters/audita/subprocess_test.go @@ -181,6 +181,36 @@ func TestSubprocessRunnerUnconfiguredCredentialEnvOmitsCredential(t *testing.T) } } +func TestSubprocessRunnerInheritsParentEnvironment(t *testing.T) { + if runtime.GOOS == "windows" { + t.Skip("helper wrapper script uses /bin/sh") + } + t.Setenv("GO_WANT_AUDITA_HELPER", "1") + t.Setenv("AUDITA_HELPER_MODE", "success") + t.Setenv("AUDITA_INHERITED_MARKER", "inherited-from-parent") + recordPath := filepath.Join(t.TempDir(), "record.json") + t.Setenv("AUDITA_HELPER_RECORD_PATH", recordPath) + + runner := mustAuditaRunner(t, SubprocessRunnerConfig{ + Binary: writeAuditaHelperWrapper(t), + Timeout: mustParseAuditaDuration(t, "2s"), + Modules: []string{"glossary"}, + BaseURL: "https://openrouter.ai/api/v1", + Model: "openrouter/google/gemma-4-31b-it", + Report: false, + LLMAPIKeyEnv: "", + }) + req := auditaReqForTest(t, false) + if _, err := runner.Run(context.Background(), req); err != nil { + t.Fatalf("Run() error = %v", err) + } + + rec := readAuditaHelperRecord(t, recordPath) + if rec.Env["AUDITA_INHERITED_MARKER"] != "inherited-from-parent" { + t.Fatalf("AUDITA_INHERITED_MARKER = %q, want inherited-from-parent", rec.Env["AUDITA_INHERITED_MARKER"]) + } +} + func TestSubprocessRunnerSubprocessFailure(t *testing.T) { if runtime.GOOS == "windows" { t.Skip("helper wrapper script uses /bin/sh") @@ -389,8 +419,9 @@ func TestAuditaSubprocessHelper(t *testing.T) { rec := auditaHelperRecord{ Args: procArgs, Env: map[string]string{ - "AUDITA_LLM_API_KEY": os.Getenv("AUDITA_LLM_API_KEY"), - "AUDITA_LLM_CONCURRENCY": os.Getenv("AUDITA_LLM_CONCURRENCY"), + "AUDITA_LLM_API_KEY": os.Getenv("AUDITA_LLM_API_KEY"), + "AUDITA_LLM_CONCURRENCY": os.Getenv("AUDITA_LLM_CONCURRENCY"), + "AUDITA_INHERITED_MARKER": os.Getenv("AUDITA_INHERITED_MARKER"), }, } data, _ := json.Marshal(rec) diff --git a/internal/adapters/subprocess/run.go b/internal/adapters/subprocess/run.go index 362f874..0f8f9de 100644 --- a/internal/adapters/subprocess/run.go +++ b/internal/adapters/subprocess/run.go @@ -54,23 +54,17 @@ func Run(ctx context.Context, req RunRequest) (RunResult, error) { } defer cancel() - stdoutFile, stdoutWriter, err := logWriter(req.StdoutLogPath) + logs, err := openLogWriters(req.StdoutLogPath, req.StderrLogPath) if err != nil { - return RunResult{}, fmt.Errorf("open stdout log: %w", err) + return RunResult{}, err } - defer closeFile(stdoutFile) - - stderrFile, stderrWriter, err := logWriter(req.StderrLogPath) - if err != nil { - return RunResult{}, fmt.Errorf("open stderr log: %w", err) - } - defer closeFile(stderrFile) + defer logs.Close() cmd := exec.CommandContext(runCtx, req.Executable, req.Args...) cmd.Dir = req.WorkingDir cmd.Env = mergeEnv(os.Environ(), req.EnvOverrides) - cmd.Stdout = stdoutWriter - cmd.Stderr = stderrWriter + cmd.Stdout = logs.Stdout + cmd.Stderr = logs.Stderr started := time.Now().UTC() result := RunResult{ @@ -105,17 +99,20 @@ func Run(ctx context.Context, req RunRequest) (RunResult, error) { return result, nil } + stderrTail := readRedactedTail(req.StderrLogPath, req.EnvOverrides, 2048) + diagnostics := buildDiagnostics(req, result, stderrTail) + if result.TimedOut { - return result, fmt.Errorf("command %q timed out after %s (args=%v)", req.Executable, req.Timeout, req.Args) + return result, fmt.Errorf("command timed out after %s (%s)", req.Timeout, diagnostics) } if result.Canceled { - return result, fmt.Errorf("command %q canceled (args=%v)", req.Executable, req.Args) + return result, fmt.Errorf("command canceled (%s)", diagnostics) } if exitErr, ok := waitErr.(*exec.ExitError); ok { - return result, fmt.Errorf("command %q failed with exit code %d (args=%v): %w", req.Executable, exitErr.ExitCode(), req.Args, waitErr) + return result, fmt.Errorf("command failed with exit code %d (%s): %w", exitErr.ExitCode(), diagnostics, waitErr) } - return result, fmt.Errorf("command %q failed to run (args=%v): %w", req.Executable, req.Args, waitErr) + return result, fmt.Errorf("command failed to run (%s): %w", diagnostics, waitErr) } // WriteYAMLAtomic marshals value as YAML and atomically writes it to path. @@ -175,18 +172,88 @@ func WriteFileAtomic(path string, data []byte, perm os.FileMode) error { return nil } +type logWriters struct { + files []*os.File + Stdout io.Writer + Stderr io.Writer +} + +func (l *logWriters) Close() { + for _, f := range l.files { + _ = f.Close() + } +} + +func openLogWriters(stdoutPath, stderrPath string) (*logWriters, error) { + cleanStdout := cleanLogPath(stdoutPath) + cleanStderr := cleanLogPath(stderrPath) + + // Keep stdout/stderr on the same file descriptor when both paths target + // the same file to avoid descriptor aliasing surprises across runtimes. + if cleanStdout != "" && cleanStdout == cleanStderr { + f, err := openLogFile(cleanStdout) + if err != nil { + return nil, fmt.Errorf("open shared stdout/stderr log %q: %w", cleanStdout, err) + } + return &logWriters{ + files: []*os.File{f}, + Stdout: f, + Stderr: f, + }, nil + } + + stdoutFile, stdoutWriter, err := logWriter(cleanStdout) + if err != nil { + return nil, fmt.Errorf("open stdout log: %w", err) + } + stderrFile, stderrWriter, err := logWriter(cleanStderr) + if err != nil { + closeFile(stdoutFile) + return nil, fmt.Errorf("open stderr log: %w", err) + } + + files := make([]*os.File, 0, 2) + if stdoutFile != nil { + files = append(files, stdoutFile) + } + if stderrFile != nil { + files = append(files, stderrFile) + } + return &logWriters{ + files: files, + Stdout: stdoutWriter, + Stderr: stderrWriter, + }, nil +} + +func cleanLogPath(path string) string { + trimmed := strings.TrimSpace(path) + if trimmed == "" { + return "" + } + return filepath.Clean(trimmed) +} + func logWriter(path string) (*os.File, io.Writer, error) { if strings.TrimSpace(path) == "" { return nil, io.Discard, nil } + f, err := openLogFile(path) + if err != nil { + return nil, nil, err + } + return f, f, nil +} + +func openLogFile(path string) (*os.File, error) { if err := os.MkdirAll(filepath.Dir(path), 0o755); err != nil { - return nil, nil, fmt.Errorf("create log directory for %q: %w", path, err) + return nil, fmt.Errorf("create log directory for %q: %w", path, err) } f, err := os.Create(path) if err != nil { - return nil, nil, fmt.Errorf("open log file %q: %w", path, err) + return nil, fmt.Errorf("open log file %q: %w", path, err) } - return f, f, nil + return f, nil } func closeFile(f *os.File) { @@ -195,6 +262,79 @@ func closeFile(f *os.File) { } } +func buildDiagnostics(req RunRequest, result RunResult, stderrTail string) string { + details := fmt.Sprintf( + "executable=%q args=%v cwd=%q timeout=%s exit_code=%d timed_out=%t canceled=%t stdout_log=%q stderr_log=%q", + req.Executable, + req.Args, + req.WorkingDir, + req.Timeout, + result.ExitCode, + result.TimedOut, + result.Canceled, + req.StdoutLogPath, + req.StderrLogPath, + ) + if strings.TrimSpace(stderrTail) == "" { + return details + } + return details + fmt.Sprintf(" stderr_tail=%q", stderrTail) +} + +func readRedactedTail(path string, envOverrides map[string]string, maxBytes int64) string { + if strings.TrimSpace(path) == "" || maxBytes <= 0 { + return "" + } + f, err := os.Open(path) + if err != nil { + return "" + } + defer f.Close() + + info, err := f.Stat() + if err != nil { + return "" + } + size := info.Size() + start := int64(0) + if size > maxBytes { + start = size - maxBytes + } + if _, err := f.Seek(start, io.SeekStart); err != nil { + return "" + } + data, err := io.ReadAll(f) + if err != nil { + return "" + } + tail := strings.TrimSpace(string(data)) + if tail == "" { + return "" + } + return redactSensitiveTail(tail, envOverrides) +} + +func redactSensitiveTail(tail string, envOverrides map[string]string) string { + out := tail + for k, v := range envOverrides { + if strings.TrimSpace(v) == "" { + continue + } + if looksSensitiveEnvKey(k) { + out = strings.ReplaceAll(out, v, "") + } + } + return out +} + +func looksSensitiveEnvKey(key string) bool { + k := strings.ToUpper(strings.TrimSpace(key)) + return strings.Contains(k, "KEY") || + strings.Contains(k, "TOKEN") || + strings.Contains(k, "SECRET") || + strings.Contains(k, "PASSWORD") +} + func mergeEnv(base []string, overrides map[string]string) []string { if len(overrides) == 0 { return base diff --git a/internal/adapters/subprocess/run_test.go b/internal/adapters/subprocess/run_test.go index 4670111..e47aa0f 100644 --- a/internal/adapters/subprocess/run_test.go +++ b/internal/adapters/subprocess/run_test.go @@ -59,12 +59,17 @@ func TestRunFailureReturnsUsefulError(t *testing.T) { t.Fatalf("os.Executable() error = %v", err) } + dir := t.TempDir() + stdoutPath := filepath.Join(dir, "stdout.log") + stderrPath := filepath.Join(dir, "stderr.log") req := RunRequest{ Executable: exe, Args: []string{"-test.run=TestSubprocessHelper", "--", "fail"}, EnvOverrides: map[string]string{ "GO_WANT_SUBPROCESS_HELPER": "1", }, + StdoutLogPath: stdoutPath, + StderrLogPath: stderrPath, } res, err := Run(context.Background(), req) @@ -80,6 +85,41 @@ func TestRunFailureReturnsUsefulError(t *testing.T) { if !strings.Contains(err.Error(), exe) { t.Fatalf("error = %q, want executable context", err.Error()) } + if !strings.Contains(err.Error(), stdoutPath) || !strings.Contains(err.Error(), stderrPath) { + t.Fatalf("error = %q, want stdout/stderr log paths", err.Error()) + } +} + +func TestRunFailureRedactsSensitiveTail(t *testing.T) { + exe, err := os.Executable() + if err != nil { + t.Fatalf("os.Executable() error = %v", err) + } + + secretValue := "super-secret-value" + dir := t.TempDir() + req := RunRequest{ + Executable: exe, + Args: []string{"-test.run=TestSubprocessHelper", "--", "failsecret"}, + EnvOverrides: map[string]string{ + "GO_WANT_SUBPROCESS_HELPER": "1", + "API_KEY": secretValue, + "SUBPROCESS_HELPER_ENV_KEY": "API_KEY", + }, + StdoutLogPath: filepath.Join(dir, "stdout.log"), + StderrLogPath: filepath.Join(dir, "stderr.log"), + } + + _, err = Run(context.Background(), req) + if err == nil { + t.Fatal("Run() error = nil, want non-nil") + } + if strings.Contains(err.Error(), secretValue) { + t.Fatalf("error leaked secret value: %q", err.Error()) + } + if !strings.Contains(err.Error(), "") { + t.Fatalf("error = %q, want redacted stderr tail marker", err.Error()) + } } func TestRunTimeout(t *testing.T) { @@ -170,6 +210,43 @@ func TestRunEnvOverridesWinOverInheritedValues(t *testing.T) { } } +func TestRunSharedStdoutStderrLogPath(t *testing.T) { + exe, err := os.Executable() + if err != nil { + t.Fatalf("os.Executable() error = %v", err) + } + + dir := t.TempDir() + sharedLogPath := filepath.Join(dir, "shared.log") + req := RunRequest{ + Executable: exe, + Args: []string{"-test.run=TestSubprocessHelper", "--", "success"}, + EnvOverrides: map[string]string{ + "GO_WANT_SUBPROCESS_HELPER": "1", + "SUBPROCESS_HELPER_STDOUT": "shared-out", + "SUBPROCESS_HELPER_STDERR": "shared-err", + }, + StdoutLogPath: sharedLogPath, + StderrLogPath: sharedLogPath, + } + + res, err := Run(context.Background(), req) + if err != nil { + t.Fatalf("Run() error = %v", err) + } + if res.ExitCode != 0 { + t.Fatalf("ExitCode = %d, want 0", res.ExitCode) + } + data, err := os.ReadFile(sharedLogPath) + if err != nil { + t.Fatalf("read shared log: %v", err) + } + text := string(data) + if !strings.Contains(text, "shared-out") || !strings.Contains(text, "shared-err") { + t.Fatalf("shared log = %q, want both stdout and stderr content", text) + } +} + func TestWriteYAMLAtomic(t *testing.T) { dir := t.TempDir() path := filepath.Join(dir, "config.generated.yml") @@ -248,6 +325,10 @@ func TestSubprocessHelper(t *testing.T) { case "fail": _, _ = os.Stderr.WriteString("intentional failure\n") os.Exit(3) + case "failsecret": + key := os.Getenv("SUBPROCESS_HELPER_ENV_KEY") + _, _ = os.Stderr.WriteString("secret:" + os.Getenv(key) + "\n") + os.Exit(4) case "sleep": time.Sleep(500 * time.Millisecond) os.Exit(0)