From f583e90396a0e12f59ccc40a87253bd3cbab564f Mon Sep 17 00:00:00 2001 From: Fabian Holler Date: Thu, 14 Dec 2023 17:27:48 +0100 Subject: [PATCH] exec: refactor command execution - When a command is executed, all it's stdout and stderr output is stored in a buffer in memory. The buffer is used when evaluating the command output and to print it if the command execution should fail. This can be very memory intensive when executed tasks generate a lot of output. To reduce the memory usage: - only store up to 16KB of the beginning and up to 16KB of the end of the output per stdout and stderr for the eventual error message when the command execution fails. The truncated part is marked in the error message. This should be sufficient context to understand failures. This is implemented with a modified copy of the prefisuffixsaver from the os/exec stdlib package. - The Run() function does not store and return the whole output of a command on success anymore. Run() is used to execute the commands of baur tasks. This will reduce the memory usage. - The new RunCombinedOut() stores the stdout output in a buffer. This function is used to run baur internal commands that only generate few output and the output is required for evaluation. - running commands can now be canceled via a passed context. This is not used by anything yet. It will be used to specify timeouts for "baur run". - Cmd now supports to specify an additional io.Writer to stream the stdout and stderr output of a command. This enables efficient processing of larger outputs and will be used in a following Pull-Request, to run "git ls-files" to obtain input file digests. - when the command output is streamed to the terminal (baur run --show-task-output), the stderr output is now colored red, that makes it distinguishable from stdout output - when --show-task-output is not passed to baur run and the execution of a command fails, the stderr and stdout output will now be shown after each other instead of intermixed. This ensures that output of both file descriptors can not become interlaced and result in bogus output. --- internal/command/command_test.go | 5 +- internal/command/root.go | 2 +- internal/command/run.go | 17 +- internal/command/util_test.go | 6 +- internal/exec/command.go | 278 +++++++++++------- internal/exec/command_linux_test.go | 70 +++++ .../exec/{exec_test.go => command_test.go} | 41 ++- internal/exec/pdeathsig_test.go | 7 +- internal/exec/prefisuffixsaver.go | 78 +++++ internal/exec/result.go | 66 +++++ internal/resolve/gosource/goenv.go | 7 +- internal/testutils/gittest/gittest.go | 11 +- internal/vcs/git/git.go | 13 +- internal/vcs/git/git_test.go | 18 +- pkg/baur/inputresolver_test.go | 6 +- pkg/baur/taskrunner.go | 12 +- 16 files changed, 457 insertions(+), 180 deletions(-) create mode 100644 internal/exec/command_linux_test.go rename internal/exec/{exec_test.go => command_test.go} (52%) create mode 100644 internal/exec/prefisuffixsaver.go create mode 100644 internal/exec/result.go diff --git a/internal/command/command_test.go b/internal/command/command_test.go index 1a50def0b..0f2f06406 100644 --- a/internal/command/command_test.go +++ b/internal/command/command_test.go @@ -4,6 +4,7 @@ package command import ( + "context" "encoding/csv" "os" "path/filepath" @@ -167,7 +168,7 @@ func TestRunningPendingTasksChangesStatus(t *testing.T) { gittest.CommitFilesToGit(t, ".") - res, err := exec.Command("git", "rev-parse", "HEAD").ExpectSuccess().Run() + res, err := exec.Command("git", "rev-parse", "HEAD").ExpectSuccess().RunCombinedOut(context.Background()) require.NoError(t, err) commit = strings.TrimSpace(res.StrOutput()) @@ -199,7 +200,7 @@ func TestRunningPendingTasksWithInputStringChangesStatus(t *testing.T) { gittest.CreateRepository(t, ".") gittest.CommitFilesToGit(t, ".") - res, err := exec.Command("git", "rev-parse", "HEAD").ExpectSuccess().Run() + res, err := exec.Command("git", "rev-parse", "HEAD").ExpectSuccess().RunCombinedOut(context.Background()) require.NoError(t, err) commit := strings.TrimSpace(res.StrOutput()) diff --git a/internal/command/root.go b/internal/command/root.go index b0435dea5..1f42f274d 100644 --- a/internal/command/root.go +++ b/internal/command/root.go @@ -38,7 +38,7 @@ var exitFunc = func(code int) { os.Exit(code) } func initSb(_ *cobra.Command, _ []string) { if verboseFlag { log.StdLogger.EnableDebug(verboseFlag) - exec.DefaultDebugfFn = log.StdLogger.Debugf + exec.DefaultLogFn = log.StdLogger.Debugf } if noColorFlag { diff --git a/internal/command/run.go b/internal/command/run.go index 8c23f348f..0a03936b3 100644 --- a/internal/command/run.go +++ b/internal/command/run.go @@ -12,7 +12,6 @@ import ( "github.com/spf13/cobra" "github.com/simplesurance/baur/v3/internal/command/term" - "github.com/simplesurance/baur/v3/internal/exec" "github.com/simplesurance/baur/v3/internal/log" "github.com/simplesurance/baur/v3/internal/routines" "github.com/simplesurance/baur/v3/internal/upload/docker" @@ -155,6 +154,9 @@ func (c *runCmd) run(_ *cobra.Command, args []string) { c.taskRunnerRoutinePool = routines.NewPool(c.taskRunnerGoRoutines) c.taskRunner = baur.NewTaskRunner() + if c.showOutput && !verboseFlag { + c.taskRunner.LogFn = stdout.Printf + } c.dockerClient, err = docker.NewClient(log.StdLogger.Debugf) exitOnErr(err) @@ -190,10 +192,6 @@ func (c *runCmd) run(_ *cobra.Command, args []string) { len(pendingTasks), len(tasks), term.ColoredTaskStatus(baur.TaskStatusExecutionPending)) } - if c.showOutput { - exec.DefaultDebugfFn = stdout.Printf - } - for _, pt := range pendingTasks { // copy the iteration variable, to prevent that its value // changes in the closure to 't' of the next iteration before @@ -287,7 +285,7 @@ func (c *runCmd) runTask(task *baur.Task) (*baur.RunResult, error) { } if result.Result.ExitCode != 0 { - if c.showOutput { + if c.showOutput || verboseFlag { stderr.Printf("%s: execution %s (%s), command exited with code %d\n", term.Highlight(task), statusStrFailed, @@ -297,14 +295,15 @@ func (c *runCmd) runTask(task *baur.Task) (*baur.RunResult, error) { result.ExitCode, ) } else { - stderr.Printf("%s: execution %s (%s), command exited with code %d, output:\n%s\n", + err := result.Result.ExpectSuccess() + stderr.Printf("%s: execution %s (%s): %s\n", term.Highlight(task), statusStrFailed, term.FormatDuration( result.StopTime.Sub(result.StartTime), ), - result.ExitCode, - result.StrOutput()) + err.Error(), + ) } return nil, fmt.Errorf("execution failed with exit code %d", result.ExitCode) diff --git a/internal/command/util_test.go b/internal/command/util_test.go index c56b9ef1d..56f5314cc 100644 --- a/internal/command/util_test.go +++ b/internal/command/util_test.go @@ -60,8 +60,8 @@ func redirectOutputToLogger(t *testing.T) { // parallel running tests log.RedirectToTestingLog(t) - oldExecDebugFfN := exec.DefaultDebugfFn - exec.DefaultDebugfFn = t.Logf + oldExecDebugFfN := exec.DefaultLogFn + exec.DefaultLogFn = t.Logf oldStdout := stdout stdout = term.NewStream(logwriter.New(t, io.Discard)) @@ -69,7 +69,7 @@ func redirectOutputToLogger(t *testing.T) { stderr = term.NewStream(logwriter.New(t, io.Discard)) t.Cleanup(func() { - exec.DefaultDebugfFn = oldExecDebugFfN + exec.DefaultLogFn = oldExecDebugFfN stdout = oldStdout stderr = oldStderr }) diff --git a/internal/exec/command.go b/internal/exec/command.go index ef6e9d387..6b6e5db7e 100644 --- a/internal/exec/command.go +++ b/internal/exec/command.go @@ -1,85 +1,80 @@ -// Package exec runs external commands package exec import ( "bufio" "bytes" + "context" + "errors" "fmt" + "io" "os/exec" "runtime" - "strings" "syscall" -) + "time" -var ( - // DefaultDebugfFn is the default debug print function. - DefaultDebugfFn = func(string, ...interface{}) {} - // DefaultDebugPrefix is the default prefix that is prepended to messages passed to the debugf function. - DefaultDebugPrefix = "exec: " + "github.com/fatih/color" ) -// ExitCodeError is returned from Run() when a command exited with a code != 0. -type ExitCodeError struct { - *Result -} +const defMaxErrOutputBytesPerStream = 16 * 1024 -// Error returns the error description. -func (e ExitCodeError) Error() string { - return fmt.Sprintf("exec: running '%s' in directory '%s' exited with code %d, expected 0, output: '%s'", - e.Command, e.Dir, e.ExitCode, e.Output) -} +type PrintfFn func(format string, a ...any) + +var ( + // DefaultLogFn is the default debug print function. + DefaultLogFn = func(string, ...interface{}) {} + // DefaultLogPrefix is the default prefix that is prepended to messages passed to the debugf function. + DefaultLogPrefix = "exec: " + // DefaultStderrColorFn is the default function that is used to colorize stderr output that is streamed to the log function. + DefaultStderrColorFn = color.New(color.FgRed).SprintFunc() +) -// Cmd represents a command that can be run. type Cmd struct { - path string + name string args []string + dir string env []string - dir string - debugfFn func(format string, v ...interface{}) - debugfPrefix string + stdout io.Writer + stderr io.Writer + + maxStoredErrBytesPerStream int + expectSuccess bool + + logFn PrintfFn + logPrefix string + logFnStderrStreamColorfn func(a ...any) string } -// Command returns a new Cmd struct. -// If name contains no path separators, Command uses LookPath to -// resolve name to a complete path if possible. Otherwise it uses name directly -// as Path. -// By default a command is run in the current working directory. +// Command returns an executable representation of a Command. func Command(name string, arg ...string) *Cmd { return &Cmd{ - path: name, - args: arg, - dir: ".", - debugfFn: DefaultDebugfFn, - debugfPrefix: DefaultDebugPrefix, + name: name, + args: arg, + logPrefix: DefaultLogPrefix, + logFn: DefaultLogFn, + stdout: nil, + stderr: nil, + maxStoredErrBytesPerStream: defMaxErrOutputBytesPerStream, + logFnStderrStreamColorfn: DefaultStderrColorFn, } } -// Directory changes the directory in which the command is executed. -func (c *Cmd) Directory(dir string) *Cmd { - c.dir = dir +// Stdout streams the standard output to w during execution. +func (c *Cmd) Stdout(w io.Writer) *Cmd { + c.stdout = w return c } -// Env specifies the environment variables that the process uses. -// Each element is in the format KEY=VALUE. -func (c *Cmd) Env(env []string) *Cmd { - c.env = env +// Stdout streams the standard error output to w during execution. +func (c *Cmd) Stderr(w io.Writer) *Cmd { + c.stderr = w return c } -// DebugfFunc sets the debug function for the command. It accepts a -// printf-style printf function and call it for every line that the command -// prints to STDOUT and STDERR when it's run. -func (c *Cmd) DebugfFunc(fn func(format string, arg ...interface{})) *Cmd { - c.debugfFn = fn - return c -} - -// DebugfPrefix sets a prefix that is prepended to the message that is passed to the Debugf function. -func (c *Cmd) DebugfPrefix(prefix string) *Cmd { - c.debugfPrefix = prefix +// LogFn sets a Printf-style function as logger. +func (c *Cmd) LogFn(fn PrintfFn) *Cmd { + c.logFn = fn return c } @@ -90,115 +85,178 @@ func (c *Cmd) ExpectSuccess() *Cmd { return c } -func cmdString(cmd *exec.Cmd) string { - // cmd.Args[0] contains the command name, cmd.Path the absolute command path, - // omit cmd.Args[0] from the string - if len(cmd.Args) > 1 { - return fmt.Sprintf("%s %v", cmd.Path, strings.Join(cmd.Args[1:], " ")) - } - - return cmd.Path +// Directory defines the directiory in which the command is executed. +func (c *Cmd) Directory(dir string) *Cmd { + c.dir = dir + return c } -// Result describes the result of a run Cmd. -type Result struct { - Command string - Dir string - Output []byte - ExitCode int +// LogPrefix defines a string that is used as prefix for all messages written via *Cmd.LogFn. +func (c *Cmd) LogPrefix(prefix string) *Cmd { + c.logPrefix = prefix + return c } -// StrOutput returns Result.Output as string. -func (r *Result) StrOutput() string { - return string(r.Output) +// Env defines environment variables that are set during execution. +func (c *Cmd) Env(env []string) *Cmd { + c.env = env + return c } -// ExpectSuccess if the ExitCode in Result is not 0, the function returns an -// ExitCodeError for the execution. -func (r *Result) ExpectSuccess() error { - if r.ExitCode == 0 { - return nil - } - - return ExitCodeError{Result: r} +func (c *Cmd) logf(format string, a ...any) { + c.logFn(c.logPrefix+format, a...) } -func exitCodeFromErr(err error) (int, error) { +func exitCodeFromErr(waitErr error) (exitCode int, err error) { var ee *exec.ExitError var ok bool - if ee, ok = err.(*exec.ExitError); !ok { + if waitErr == nil { return 0, err } + if ee, ok = waitErr.(*exec.ExitError); !ok { + return -1, waitErr + } + if status, ok := ee.Sys().(syscall.WaitStatus); ok { return status.ExitStatus(), nil } - return 0, err + return -1, waitErr +} + +func newMultiWriter(w ...io.Writer) io.Writer { + writers := make([]io.Writer, 0, len(w)) + for _, ww := range w { + if ww != nil && ww != io.Discard { + writers = append(writers, ww) + } + } + return io.MultiWriter(writers...) +} + +func (c *Cmd) startOutputStreamLogging(name string, useColorStderrColorfn bool) (io.Writer, func() error) { + logReader, logWriter := io.Pipe() + scannerTerminated := make(chan struct{}) + + go func() { + sc := bufio.NewScanner(logReader) + // use a bigger buf to make it more unlikely that it will fail because of very long lines + sc.Buffer([]byte{}, 512*1024) + + for sc.Scan() { + if useColorStderrColorfn && c.logFnStderrStreamColorfn != nil { + c.logf(c.logFnStderrStreamColorfn(sc.Text(), "\n")) + } else { + c.logf(sc.Text() + "\n") + } + } + + if err := sc.Err(); err != nil { + _ = logReader.CloseWithError(fmt.Errorf("%s: streaming output failed: %w", name, err)) + } + close(scannerTerminated) + }() + + return logWriter, func() error { + err := logWriter.Close() + <-scannerTerminated + + if err != nil { + return fmt.Errorf("%s: closing output stream failed: %w", name, err) + } + + return nil + } } // Run executes the command. -func (c *Cmd) Run() (*Result, error) { - cmd := exec.Command(c.path, c.args...) +func (c *Cmd) Run(ctx context.Context) (*Result, error) { + cmd := exec.CommandContext(ctx, c.name, c.args...) + cmd.SysProcAttr = defSysProcAttr() + cmd.WaitDelay = time.Minute cmd.Dir = c.dir cmd.Env = c.env - cmd.SysProcAttr = defSysProcAttr() - outReader, err := cmd.StdoutPipe() - if err != nil { - return nil, err + stdoutLogWriterCloseFn := func() error { return nil } + stderrLogWriterCloseFn := func() error { return nil } + var stdoutLogWriter, stderrLogWriter io.Writer + if c.logFn != nil { + stdoutLogWriter, stdoutLogWriterCloseFn = c.startOutputStreamLogging("stdout", false) + stderrLogWriter, stderrLogWriterCloseFn = c.startOutputStreamLogging("stderr", true) } - cmd.Stderr = cmd.Stdout + + // if a write to one of the writers of the MultiWriter fails, the command will fail + stdoutPss := prefixSuffixSaver{N: c.maxStoredErrBytesPerStream} + cmd.Stdout = newMultiWriter(c.stdout, stdoutLogWriter, &stdoutPss) + + stderrPss := prefixSuffixSaver{N: c.maxStoredErrBytesPerStream} + cmd.Stderr = newMultiWriter(c.stderr, stderrLogWriter, &stderrPss) // lock to thread because of: // https://github.com/golang/go/issues/27505#issuecomment-713706104 runtime.LockOSThread() defer runtime.UnlockOSThread() - c.debugfFn(c.debugfPrefix+"running '%s' in directory '%s'\n", cmdString(cmd), cmd.Dir) - err = cmd.Start() + c.logf("running %q in directory %q\n", cmd.String(), cmd.Dir) + + err := cmd.Start() if err != nil { - return nil, err + return nil, errors.Join(err, stdoutLogWriterCloseFn(), stderrLogWriterCloseFn()) } - var outBuf bytes.Buffer - firstline := true - in := bufio.NewScanner(outReader) - for in.Scan() { - c.debugfFn(c.debugfPrefix + in.Text() + "\n") - if firstline { - firstline = false - } else { - outBuf.WriteRune('\n') - } + waitErr := cmd.Wait() + logWriterErr := errors.Join(stdoutLogWriterCloseFn(), stderrLogWriterCloseFn()) - outBuf.Write(in.Bytes()) + if waitErr != nil && ctx.Err() != nil { + return nil, errors.Join(ctx.Err(), waitErr, logWriterErr) } - if err := in.Err(); err != nil { - _ = cmd.Wait() - return nil, err + if logWriterErr != nil { + return nil, errors.Join(logWriterErr, waitErr) } - var exitCode int - waitErr := cmd.Wait() - if exitCode, err = exitCodeFromErr(waitErr); err != nil { - return nil, err + exitCode, exitCodeErr := exitCodeFromErr(waitErr) + if exitCodeErr != nil { + return nil, exitCodeErr } - c.debugfFn(c.debugfPrefix+"command terminated with exitCode: %d\n", exitCode) + c.logf("command terminated with exitCode: %d\n", exitCode) result := Result{ - Command: cmdString(cmd), + Command: cmd.String(), Dir: cmd.Dir, ExitCode: exitCode, - Output: outBuf.Bytes(), + stdout: &stdoutPss, + stderr: &stderrPss, } - if c.expectSuccess && exitCode != 0 { return nil, ExitCodeError{Result: &result} } return &result, nil } + +// RunCombinedOut executes the command and stores the combined stdout and +// stderr output of the process in ResultOut.CombinedOutput. +func (c *Cmd) RunCombinedOut(ctx context.Context) (*ResultOut, error) { + buf := bytes.Buffer{} + + if c.stdout != nil { + return nil, errors.New("Cmd.stdout must be nil") + } + if c.stderr != nil { + return nil, errors.New("Cmd.stderr must be nil") + } + + c.stdout = &buf + c.stderr = c.stdout + + result, err := c.Run(ctx) + if err != nil { + return nil, err + } + + return &ResultOut{Result: result, CombinedOutput: buf.Bytes()}, nil +} diff --git a/internal/exec/command_linux_test.go b/internal/exec/command_linux_test.go new file mode 100644 index 000000000..2ab5cd799 --- /dev/null +++ b/internal/exec/command_linux_test.go @@ -0,0 +1,70 @@ +package exec + +import ( + "context" + "fmt" + "testing" + "time" + + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" +) + +func TestCombinedStderrOutput(t *testing.T) { + ctx := context.Background() + const echoStr = "hello world!" + + res, err := Command("sh", "-c", fmt.Sprintf("echo -n '%s' 1>&2", echoStr)).RunCombinedOut(ctx) + require.NoError(t, err) + + if res.ExitCode != 0 { + t.Fatal(res.ExpectSuccess()) + } + + assert.Equal(t, echoStr, res.StrOutput(), "unexpected output") +} + +func TestStdoutAndStderrIsRecordedOnErr(t *testing.T) { + ctx := context.Background() + const stdoutOutput = "hello stdout" + const stderrOutput = "hello stderr" + + res, err := Command( + "sh", "-c", + fmt.Sprintf("echo -n '%s' 1>&2; echo -n '%s'; exit 1", stderrOutput, stdoutOutput), + ).Run(ctx) + require.NoError(t, err) + require.Error(t, res.ExpectSuccess()) + + assert.Equal(t, stdoutOutput, string(res.stdout.Bytes()), "unexpected stdout output") + assert.Equal(t, stderrOutput, string(res.stderr.Bytes()), "unexpected stderr output") +} + +func TestLongStdoutOutputIsTruncated(t *testing.T) { + const outBytes = 100 * 1024 * 1024 + ctx := context.Background() + + res, err := Command( + "dd", "if=/dev/urandom", "bs=1024", fmt.Sprintf("count=%d", outBytes/1024), + ). + Run(ctx) + require.NoError(t, err) + require.NoError(t, res.ExpectSuccess()) + + assert.GreaterOrEqual(t, len(res.stdout.Bytes()), defMaxErrOutputBytesPerStream) + + // expected size: defMaxErrOutputBytesPerStream for the prefix output + defMaxErrOutputBytesPerStream for the suffix output + some bytes for the information that has been truncated + assert.LessOrEqual(t, len(res.stdout.Bytes()), 2*defMaxErrOutputBytesPerStream+1024) +} + +func TestCancellingRuningCommand(t *testing.T) { + ctx, cancelFn := context.WithTimeout(context.Background(), time.Second) + t.Cleanup(cancelFn) + + _, err := Command("sleep", "5m").Run(ctx) + assert.Error(t, err, "command execution did not fail") //nolint:testifylint + require.Error(t, ctx.Err(), "context err is nil") + assert.ErrorIs(t, err, ctx.Err()) //nolint:testifylint + t.Log(err) + +} diff --git a/internal/exec/exec_test.go b/internal/exec/command_test.go similarity index 52% rename from internal/exec/exec_test.go rename to internal/exec/command_test.go index 6a26eaf1e..d18b58e59 100644 --- a/internal/exec/exec_test.go +++ b/internal/exec/command_test.go @@ -1,28 +1,23 @@ package exec import ( + "context" "fmt" "runtime" "testing" ) -func TestEchoStdout(t *testing.T) { - const echoStr = "hello world!" +func TestCombinedStdoutOutput(t *testing.T) { + ctx := context.Background() + const echoStr = "hello World!" - // Windows returns StrOutput with surrounding quotation marks - var expected string - if runtime.GOOS == "windows" { - expected = fmt.Sprintf("\"%s\"", echoStr) - } else { - expected = echoStr - } - - var res *Result + var res *ResultOut var err error if runtime.GOOS == "windows" { - res, err = Command("cmd", "/C", "echo", echoStr).Run() + res, err = Command("bash", "-c", fmt.Sprintf("echo -n '%s'", echoStr)).RunCombinedOut(ctx) + } else { - res, err = Command("echo", "-n", echoStr).Run() + res, err = Command("echo", "-n", echoStr).RunCombinedOut(ctx) } if err != nil { @@ -30,21 +25,22 @@ func TestEchoStdout(t *testing.T) { } if res.ExitCode != 0 { - t.Fatalf("cmd exited with code %d, expected 0", res.ExitCode) + t.Fatal(res.ExpectSuccess()) } - if res.StrOutput() != expected { - t.Errorf("expected output '%s', got '%s'", expected, res.StrOutput()) + if res.StrOutput() != echoStr { + t.Errorf("expected output '%s', got '%s'", echoStr, res.StrOutput()) } } func TestCommandFails(t *testing.T) { - var res *Result + ctx := context.Background() + var res *ResultOut var err error if runtime.GOOS == "windows" { - res, err = Command("cmd", "/C", "exit", "1").Run() + res, err = Command("cmd", "/C", "exit", "1").RunCombinedOut(ctx) } else { - res, err = Command("false").Run() + res, err = Command("false").RunCombinedOut(ctx) } if err != nil { t.Fatal(err) @@ -54,18 +50,19 @@ func TestCommandFails(t *testing.T) { t.Fatalf("cmd exited with code %d, expected 1", res.ExitCode) } - if len(res.Output) != 0 { + if len(res.CombinedOutput) != 0 { t.Fatalf("expected no output from command but got '%s'", res.StrOutput()) } } func TestExpectSuccess(t *testing.T) { + ctx := context.Background() var res *Result var err error if runtime.GOOS == "windows" { - res, err = Command("cmd", "/C", "exit", "1").ExpectSuccess().Run() + res, err = Command("cmd", "/C", "exit", "1").ExpectSuccess().Run(ctx) } else { - res, err = Command("false").ExpectSuccess().Run() + res, err = Command("false").ExpectSuccess().Run(ctx) } if err == nil { t.Fatal("Command did not return an error") diff --git a/internal/exec/pdeathsig_test.go b/internal/exec/pdeathsig_test.go index 0d08ae2d3..3a1a2a649 100644 --- a/internal/exec/pdeathsig_test.go +++ b/internal/exec/pdeathsig_test.go @@ -4,6 +4,7 @@ package exec import ( "bufio" + "context" "errors" "fmt" "io" @@ -34,7 +35,7 @@ func TestMain(m *testing.M) { } func deathSignalParent() { - DefaultDebugfFn = func(format string, a ...any) { fmt.Printf(format, a...) } + DefaultLogFn = func(format string, a ...any) { fmt.Printf(format, a...) } cmd := Command(os.Args[0]). Env([]string{ @@ -42,7 +43,7 @@ func deathSignalParent() { "BAUR_EXEC_DEATHSIG_TEST_CHILD=1", }) - _, err := cmd.Run() + _, err := cmd.Run(context.Background()) if err != nil { fmt.Printf("parent: executing child process failed: %s\n", err) os.Exit(2) @@ -84,7 +85,7 @@ func TestProcessTerminatesWithParent(t *testing.T) { } t.Logf("read from parent's process stdout: %q", parentStdoutLine) - parentStdoutLine = strings.TrimPrefix(parentStdoutLine, DefaultDebugPrefix) + parentStdoutLine = strings.TrimPrefix(parentStdoutLine, DefaultLogPrefix) if strings.HasPrefix(parentStdoutLine, "running ") { continue diff --git a/internal/exec/prefisuffixsaver.go b/internal/exec/prefisuffixsaver.go new file mode 100644 index 000000000..1b86a7f57 --- /dev/null +++ b/internal/exec/prefisuffixsaver.go @@ -0,0 +1,78 @@ +package exec + +// All code in this file was copied from the os/exec stdlib package. + +import ( + "bytes" + "strconv" +) + +// prefixSuffixSaver is an io.Writer which retains the first N bytes +// and the last N bytes written to it. The Bytes() methods reconstructs +// it with a pretty error message. +type prefixSuffixSaver struct { + N int // max size of prefix or suffix + prefix []byte + suffix []byte // ring buffer once len(suffix) == N + suffixOff int // offset to write into suffix + skipped int64 + + // TODO(bradfitz): we could keep one large []byte and use part of it for + // the prefix, reserve space for the '... Omitting N bytes ...' message, + // then the ring buffer suffix, and just rearrange the ring buffer + // suffix when Bytes() is called, but it doesn't seem worth it for + // now just for error messages. It's only ~64KB anyway. +} + +func (w *prefixSuffixSaver) Write(p []byte) (n int, err error) { + lenp := len(p) + p = w.fill(&w.prefix, p) + + // Only keep the last w.N bytes of suffix data. + if overage := len(p) - w.N; overage > 0 { + p = p[overage:] + w.skipped += int64(overage) + } + p = w.fill(&w.suffix, p) + + // w.suffix is full now if p is non-empty. Overwrite it in a circle. + for len(p) > 0 { // 0, 1, or 2 iterations. + n := copy(w.suffix[w.suffixOff:], p) + p = p[n:] + w.skipped += int64(n) + w.suffixOff += n + if w.suffixOff == w.N { + w.suffixOff = 0 + } + } + return lenp, nil +} + +// fill appends up to len(p) bytes of p to *dst, such that *dst does not +// grow larger than w.N. It returns the un-appended suffix of p. +func (w *prefixSuffixSaver) fill(dst *[]byte, p []byte) (pRemain []byte) { + if remain := w.N - len(*dst); remain > 0 { + add := min(len(p), remain) + *dst = append(*dst, p[:add]...) + p = p[add:] + } + return p +} + +func (w *prefixSuffixSaver) Bytes() []byte { + if w.suffix == nil { + return w.prefix + } + if w.skipped == 0 { + return append(w.prefix, w.suffix...) + } + var buf bytes.Buffer + buf.Grow(len(w.prefix) + len(w.suffix) + 50) + buf.Write(w.prefix) + buf.WriteString("\n... omitting ") + buf.WriteString(strconv.FormatInt(w.skipped, 10)) + buf.WriteString(" bytes ...\n") + buf.Write(w.suffix[w.suffixOff:]) + buf.Write(w.suffix[:w.suffixOff]) + return buf.Bytes() +} diff --git a/internal/exec/result.go b/internal/exec/result.go new file mode 100644 index 000000000..0f630fc27 --- /dev/null +++ b/internal/exec/result.go @@ -0,0 +1,66 @@ +package exec + +import ( + "fmt" + "strings" +) + +// ExitCodeError is returned from Run() when a command exited with a code != 0. +type ExitCodeError struct { + *Result +} + +// Error returns the error description. +func (e ExitCodeError) Error() string { + var result strings.Builder + var stdoutExists bool + + result.WriteString(fmt.Sprintf("command exited with code %d, output:\n", e.ExitCode)) + + if b := e.stdout.Bytes(); len(b) > 0 { + result.WriteString("### stdout ###\n") + result.WriteString(strings.TrimSpace(string(b))) + result.WriteRune('\n') + stdoutExists = true + } + + if b := e.stderr.Bytes(); len(b) > 0 { + if stdoutExists { + result.WriteRune('\n') + } + result.WriteString("### stderr ###\n") + result.WriteString(strings.TrimSpace(string(b))) + result.WriteRune('\n') + } + + return result.String() +} + +// Result describes the result of a run Cmd. +type Result struct { + Command string + Dir string + ExitCode int + + stdout *prefixSuffixSaver + stderr *prefixSuffixSaver +} + +// ExpectSuccess if the ExitCode in Result is not 0, the function returns an +// ExitCodeError for the execution. +func (r *Result) ExpectSuccess() error { + if r.ExitCode == 0 { + return nil + } + + return ExitCodeError{Result: r} +} + +type ResultOut struct { + *Result + CombinedOutput []byte +} + +func (r *ResultOut) StrOutput() string { + return string(r.CombinedOutput) +} diff --git a/internal/resolve/gosource/goenv.go b/internal/resolve/gosource/goenv.go index ed1d9464a..7d160a4eb 100644 --- a/internal/resolve/gosource/goenv.go +++ b/internal/resolve/gosource/goenv.go @@ -1,6 +1,7 @@ package gosource import ( + "context" "encoding/json" "fmt" "path/filepath" @@ -19,13 +20,13 @@ type goEnv struct { func getGoEnv(env []string) (*goEnv, error) { var result goEnv - res, err := exec.Command("go", "env", "-json").Env(env).ExpectSuccess().Run() + res, err := exec.Command("go", "env", "-json").Env(env).ExpectSuccess().RunCombinedOut(context.TODO()) if err != nil { return nil, err } - if err := json.Unmarshal(res.Output, &result); err != nil { - return nil, fmt.Errorf("converting %q to json failed: %w", string(res.Output), err) + if err := json.Unmarshal(res.CombinedOutput, &result); err != nil { + return nil, fmt.Errorf("converting %q to json failed: %w", string(res.CombinedOutput), err) } if result.GoModCache == "" { diff --git a/internal/testutils/gittest/gittest.go b/internal/testutils/gittest/gittest.go index 09b1ef772..1a7f0e8f4 100644 --- a/internal/testutils/gittest/gittest.go +++ b/internal/testutils/gittest/gittest.go @@ -1,6 +1,7 @@ package gittest import ( + "context" "os" "path/filepath" "testing" @@ -38,31 +39,31 @@ func CommitFilesToGit(t *testing.T, directory string) []string { _, err = exec.Command("git", append([]string{"add"}, files...)...). Directory(directory). ExpectSuccess(). - Run() + Run(context.Background()) require.NoError(t, err) _, err = exec.Command("git", "commit", "-a", "-m", "baur commit"). Directory(directory). ExpectSuccess(). - Run() + Run(context.Background()) require.NoError(t, err) return files } func Clone(t *testing.T, directory, gitURL, commit string) { - _, err := exec.Command("git", "clone", gitURL, directory).ExpectSuccess().Run() + _, err := exec.Command("git", "clone", gitURL, directory).ExpectSuccess().Run(context.Background()) require.NoError(t, err) if commit == "" { return } - _, err = exec.Command("git", "checkout", commit).Directory(directory).ExpectSuccess().Run() + _, err = exec.Command("git", "checkout", commit).Directory(directory).ExpectSuccess().Run(context.Background()) require.NoError(t, err) } func CreateRepository(t *testing.T, directory string) { - _, err := exec.Command("git", "init", ".").Directory(directory).ExpectSuccess().Run() + _, err := exec.Command("git", "init", ".").Directory(directory).ExpectSuccess().Run(context.Background()) require.NoError(t, err) } diff --git a/internal/vcs/git/git.go b/internal/vcs/git/git.go index faca13bce..4d74b2ec3 100644 --- a/internal/vcs/git/git.go +++ b/internal/vcs/git/git.go @@ -4,6 +4,7 @@ package git import ( "bufio" "bytes" + "context" "errors" "fmt" "os" @@ -44,7 +45,7 @@ func IsGitDir(dir string) (bool, error) { return false, err } - result, err := exec.Command("git", "rev-parse", "--git-dir").Directory(dir).Run() + result, err := exec.Command("git", "rev-parse", "--git-dir").Directory(dir).RunCombinedOut(context.TODO()) if err != nil { return false, err } @@ -64,7 +65,7 @@ func IsGitDir(dir string) (bool, error) { // CommitID return the commit id of HEAD by running git rev-parse in the passed // directory func CommitID(dir string) (string, error) { - res, err := exec.Command("git", "rev-parse", "HEAD").Directory(dir).ExpectSuccess().Run() + res, err := exec.Command("git", "rev-parse", "HEAD").Directory(dir).ExpectSuccess().RunCombinedOut(context.TODO()) if err != nil { return "", err } @@ -80,12 +81,12 @@ func CommitID(dir string) (string, error) { // WorktreeIsDirty returns true if the repository contains modified files, // untracked files are considered, files in .gitignore are ignored func WorktreeIsDirty(dir string) (bool, error) { - res, err := exec.Command("git", "status", "-s").Directory(dir).ExpectSuccess().Run() + res, err := exec.Command("git", "status", "-s").Directory(dir).ExpectSuccess().RunCombinedOut(context.TODO()) if err != nil { return false, err } - if len(res.Output) == 0 { + if len(res.CombinedOutput) == 0 { return false, nil } @@ -102,12 +103,12 @@ func UntrackedFiles(dir string) ([]string, error) { cmdResult, err := exec. Command("git", "status", "--porcelain", "--untracked-files=all", "--ignored"). - Directory(dir).ExpectSuccess().Run() + Directory(dir).ExpectSuccess().RunCombinedOut((context.TODO())) if err != nil { return nil, err } - scanner := bufio.NewScanner(bytes.NewReader(cmdResult.Output)) + scanner := bufio.NewScanner(bytes.NewReader(cmdResult.CombinedOutput)) for scanner.Scan() { var relPath string diff --git a/internal/vcs/git/git_test.go b/internal/vcs/git/git_test.go index 213b588f6..a7d5b92f9 100644 --- a/internal/vcs/git/git_test.go +++ b/internal/vcs/git/git_test.go @@ -17,10 +17,10 @@ func TestUntrackedFilesIncludesGitIgnoredFiles(t *testing.T) { const ignoredFileName = "f2" log.RedirectToTestingLog(t) - oldExecDebugFfN := exec.DefaultDebugfFn - exec.DefaultDebugfFn = t.Logf + oldExecDebugFfN := exec.DefaultLogFn + exec.DefaultLogFn = t.Logf t.Cleanup(func() { - exec.DefaultDebugfFn = oldExecDebugFfN + exec.DefaultLogFn = oldExecDebugFfN }) tempDir := t.TempDir() @@ -46,10 +46,10 @@ func TestUntrackedFilesIncludesFilesInSubdirs(t *testing.T) { untrackedFilepathInSubdir := filepath.Join("a", "b", "c", "f4") log.RedirectToTestingLog(t) - oldExecDebugFfN := exec.DefaultDebugfFn - exec.DefaultDebugfFn = t.Logf + oldExecDebugFfN := exec.DefaultLogFn + exec.DefaultLogFn = t.Logf t.Cleanup(func() { - exec.DefaultDebugfFn = oldExecDebugFfN + exec.DefaultLogFn = oldExecDebugFfN }) tempDir := t.TempDir() @@ -85,10 +85,10 @@ func TestUntrackedFilesDoesNotContainTrackedFile(t *testing.T) { const trackedFilename = "f1" log.RedirectToTestingLog(t) - oldExecDebugFfN := exec.DefaultDebugfFn - exec.DefaultDebugfFn = t.Logf + oldExecDebugFfN := exec.DefaultLogFn + exec.DefaultLogFn = t.Logf t.Cleanup(func() { - exec.DefaultDebugfFn = oldExecDebugFfN + exec.DefaultLogFn = oldExecDebugFfN }) tempDir := t.TempDir() diff --git a/pkg/baur/inputresolver_test.go b/pkg/baur/inputresolver_test.go index ec33def5f..89c1c4791 100644 --- a/pkg/baur/inputresolver_test.go +++ b/pkg/baur/inputresolver_test.go @@ -336,10 +336,10 @@ func TestPathsAfterMissingOptionalOneAreNotIgnored(t *testing.T) { func TestResolverIgnoredGitUntrackedFiles(t *testing.T) { log.RedirectToTestingLog(t) - oldExecDebugFfN := exec.DefaultDebugfFn - exec.DefaultDebugfFn = t.Logf + oldExecDebugFfN := exec.DefaultLogFn + exec.DefaultLogFn = t.Logf t.Cleanup(func() { - exec.DefaultDebugfFn = oldExecDebugFfN + exec.DefaultLogFn = oldExecDebugFfN }) gitDir := t.TempDir() diff --git a/pkg/baur/taskrunner.go b/pkg/baur/taskrunner.go index 94c3ae104..970e70519 100644 --- a/pkg/baur/taskrunner.go +++ b/pkg/baur/taskrunner.go @@ -1,6 +1,7 @@ package baur import ( + "context" "errors" "fmt" "sync/atomic" @@ -17,10 +18,13 @@ var ErrTaskRunSkipped = errors.New("task run skipped") // TaskRunner executes the command of a task. type TaskRunner struct { skipEnabled uint32 // must be accessed via atomic operations + LogFn exec.PrintfFn } func NewTaskRunner() *TaskRunner { - return &TaskRunner{} + return &TaskRunner{ + LogFn: exec.DefaultLogFn, + } } // RunResult represents the results of a task run. @@ -39,11 +43,11 @@ func (t *TaskRunner) Run(task *Task) (*RunResult, error) { return nil, ErrTaskRunSkipped } - // TODO: rework exec, stream the output instead of storing all in memory execResult, err := exec.Command(task.Command[0], task.Command[1:]...). Directory(task.Directory). - DebugfPrefix(color.YellowString(fmt.Sprintf("%s: ", task))). - Run() + LogPrefix(color.YellowString(fmt.Sprintf("%s: ", task))). + LogFn(t.LogFn). + Run(context.TODO()) if err != nil { return nil, err }