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.

Author: Fabian Holler

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

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 {

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)

internal/command/util_test.go

@@ -60,16 +60,16 @@ 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))
 	oldStderr := stderr
 	stderr = term.NewStream(logwriter.New(t, io.Discard))
 
 	t.Cleanup(func() {
-		exec.DefaultDebugfFn = oldExecDebugFfN
+		exec.DefaultLogFn = oldExecDebugFfN
 		stdout = oldStdout
 		stderr = oldStderr
 	})