eric/narratio
1
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases 15 Wiki Activity

Hardened subprocess stdio wiring and failure diagnostics

Browse Source
This commit is contained in:
Eric Rakestraw
2026-05-04 12:37:20 -05:00
parent 4550987bc0
commit 4a593f9dcb
5 changed files with 275 additions and 22 deletions
Download Patch File Download Diff File Expand all files Collapse all files

1
README.md
View File

@@ -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:

4
architecture.md
View File

@@ -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

35
internal/adapters/audita/subprocess_test.go
View File

@@ -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)

176
internal/adapters/subprocess/run.go
View File

@@ -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, "<redacted>")
}
}
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

81
internal/adapters/subprocess/run_test.go
View File

@@ -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(), "<redacted>") {
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)