diff --git a/internal/execution/supervisor/adapter_file.go b/internal/execution/supervisor/adapter_file.go index 7917f47..7e2a978 100644 --- a/internal/execution/supervisor/adapter_file.go +++ b/internal/execution/supervisor/adapter_file.go @@ -1,12 +1,10 @@ package supervisor import ( - "bytes" "context" "encoding/json" "errors" "fmt" - "io" "os" "path" "sync" @@ -164,15 +162,15 @@ func (a *fileAdapter) Send( ) // create the worker with modified args and env - worker, err := a.workerFactory(startParams) + childWorker, err := a.workerFactory(startParams) if err != nil { return nil, fmt.Errorf("error creating worker: %w", err) } // store worker for later use - a.worker = worker + a.worker = childWorker - pipe, err := worker.ReadPipe() + pipe, err := childWorker.ReadPipe() if err != nil { return nil, fmt.Errorf("error getting read pipe: %w", err) } @@ -183,26 +181,19 @@ func (a *fileAdapter) Send( go func() { defer stdoutWg.Done() - // capture stdout - var buf bytes.Buffer - _, err := io.Copy(&buf, pipe) - if err != nil && err != io.EOF { - a.log.Warn("failed to read from stdout", - zap.String("data", buf.String()), - zap.Error(err), - ) + if err := worker.LogPipe(a.log, "stdout", pipe); err != nil { + a.log.Warn("failed to read from stdout", zap.Error(err)) } - a.log.Debug("stdout", zap.String("data", buf.String())) }() - if err := worker.Start(ctx); err != nil { + if err := childWorker.Start(ctx); err != nil { return nil, fmt.Errorf("error starting process: %w", err) } stdoutWg.Wait() // wait for worker to terminate (find another way to read res earlier?) - exitEvent, err := worker.Wait(ctx) + exitEvent, err := childWorker.Wait(ctx) if err != nil { return nil, fmt.Errorf("error waiting for process: %w", err) } diff --git a/internal/execution/supervisor/adapter_rpc.go b/internal/execution/supervisor/adapter_rpc.go index 837c5c3..1e338fd 100644 --- a/internal/execution/supervisor/adapter_rpc.go +++ b/internal/execution/supervisor/adapter_rpc.go @@ -116,15 +116,18 @@ func (a *rpcAdapter) Start( params.Env = buildEnv(params.Env, a.config) // create the worker - worker, err := a.workerFactory(params) + childWorker, err := a.workerFactory(params) if err != nil { return fmt.Errorf("error creating worker: %w", err) } - a.worker = worker + a.worker = childWorker - // initialize the stdio pipe if the transport is "stdio" if a.config.Transport == StdioTransport { + // stdout/stdin are claimed as the literal JSON-RPC channel for this + // transport, so they must not be logged directly - doing so would + // corrupt the protocol framing. only stderr is available as a + // diagnostic channel here (handled by the worker itself). stdio, err := a.worker.DuplexPipe() if err != nil { return fmt.Errorf("error creating duplex pipe: %w", err) @@ -134,11 +137,25 @@ func (a *rpcAdapter) Start( a.stdioPipe = &headerPrefixPipe{stdio: stdio} // TODO: close pipe? + } else { + // for all other transports, stdout isn't used as a protocol + // channel, so forward it to the logger instead of letting it + // go to /dev/null. + stdout, err := a.worker.ReadPipe() + if err != nil { + return fmt.Errorf("error creating read pipe: %w", err) + } + + go func() { + if err := worker.LogPipe(a.log, "stdout", stdout); err != nil { + a.log.Debug("failed to read from stdout", zap.Error(err)) + } + }() } // for rpc, we can already start the worker, as we do not need to pass // any additional, message-specific data to the worker via arguments - if err := worker.Start(ctx); err != nil { + if err := childWorker.Start(ctx); err != nil { return fmt.Errorf("error starting worker: %w", err) } diff --git a/internal/execution/worker/worker.go b/internal/execution/worker/worker.go index 86c6070..926985f 100644 --- a/internal/execution/worker/worker.go +++ b/internal/execution/worker/worker.go @@ -1,6 +1,7 @@ package worker import ( + "bufio" "bytes" "context" "errors" @@ -193,14 +194,17 @@ func (w *ProcessWorker) Start(ctx context.Context) error { close(w.done) }() - // read from stderr in a separate goroutine + // read from stderr in a separate goroutine. every line is forwarded to + // the logger as it arrives, while the raw bytes are also accumulated + // into w.stderr (via the tee) for the exit-event summary below. w.stderrWg.Add(1) go func() { defer w.stderrWg.Done() - // read from stderr and save it for later use // TODO: use some prefix / suffix reader as stderr could get big big - _, err := io.Copy(&w.stderr, stderrPipe) + tee := io.TeeReader(stderrPipe, &w.stderr) + + err := LogPipe(w.log, "stderr", tee) if errors.Is(err, io.EOF) { w.log.Debug("stderr EOF") return @@ -352,6 +356,20 @@ func getExitEvent(err error, stderr string) ExitEvent { } } +// LogPipe reads newline-delimited data from r and forwards each line to +// log at debug level, tagged with the given stream name (e.g. "stdout" or +// "stderr"). It blocks until r is exhausted or a read error occurs, and +// returns that error (nil on a clean EOF, matching io.Copy semantics). +func LogPipe(log *zap.Logger, stream string, r io.Reader) error { + scanner := bufio.NewScanner(r) + + for scanner.Scan() { + log.Debug(stream, zap.String("line", scanner.Text())) + } + + return scanner.Err() +} + // MARK: - Pipes // ReadPipe returns a `io.ReadCloser` that can be used to read