Add utilities for more control over how shell commands are logged

PiperOrigin-RevId: 566788600
Change-Id: Ief80a5d98aae5c711047d350566aef4d58ab385d

cmd/go/appengine/main.go

@@ -91,15 +91,15 @@ func appEngineInDeps(deps []string) bool {
 }
 
 func allDeps(ctx *gcp.Context) ([]string, error) {
-	result, err := ctx.Exec([]string{"go", "list", "-e", "-f", `{{join .Deps "\n"}}`, "./..."}, gcp.WithUserAttribution)
+	result, err := ctx.Exec([]string{"go", "list", "-e", "-f", `{{join .Deps "\n"}}`, "./..."}, gcp.WithUserAttribution, gcp.WithLogOutput(false))
 	if err != nil {
 		return nil, err
 	}
 	return strings.Fields(result.Stdout), nil
 }
 
 func directDeps(ctx *gcp.Context) ([]string, error) {
-	result, err := ctx.Exec([]string{"go", "list", "-e", "-f", `{{join .Imports "\n" }}`, "./..."}, gcp.WithUserAttribution)
+	result, err := ctx.Exec([]string{"go", "list", "-e", "-f", `{{join .Imports "\n" }}`, "./..."}, gcp.WithUserAttribution, gcp.WithLogOutput(false))
 	if err != nil {
 		return nil, err
 	}

cmd/go/functions_framework/main.go

@@ -186,7 +186,7 @@ func createMainGoMod(ctx *gcp.Context, fn fnInfo) error {
 		if err := cloudfunctions.AssertFrameworkInjectionAllowed(); err != nil {
 			return err
 		}
-		if _, err := ctx.Exec([]string{"go", "mod", "edit", "-require", fmt.Sprintf("%s@%s", functionsFrameworkModule, functionsFrameworkVersion)}, gcp.WithWorkDir(fn.Source)); err != nil {
+		if _, err := ctx.Exec([]string{"go", "mod", "edit", "-require", fmt.Sprintf("%s@%s", functionsFrameworkModule, functionsFrameworkVersion)}, gcp.WithWorkDir(fn.Source), gcp.WithLogCommand(true)); err != nil {
 			return err
 		}
 		version = functionsFrameworkVersion

pkg/gcpbuildpack/exec.go

@@ -45,9 +45,11 @@ type execParams struct {
 	dir string
 	env []string
 
-	userAttribution bool
-	userTiming      bool
-	messageProducer MessageProducer
+	userAttribution    bool
+	userTiming         bool
+	messageProducer    MessageProducer
+	logCommandOverride *bool
+	logOutputOverride  *bool
 }
 
 // ExecOption configures Exec functions.
@@ -85,6 +87,22 @@ func WithMessageProducer(mp MessageProducer) ExecOption {
 	}
 }
 
+// WithLogCommand logs or silences the shell command itself from being printed. This takes
+// precedence over any other options.
+func WithLogCommand(shouldLog bool) ExecOption {
+	return func(o *execParams) {
+		o.logCommandOverride = &shouldLog
+	}
+}
+
+// WithLogOutput logs or silences the shell command's output from being printed. This takes
+// precedence over any other options.
+func WithLogOutput(shouldLog bool) ExecOption {
+	return func(o *execParams) {
+		o.logOutputOverride = &shouldLog
+	}
+}
+
 // WithCombinedTail keeps the tail of the combined stdout/stderr for the error message.
 var WithCombinedTail = WithMessageProducer(KeepCombinedTail)
 
@@ -146,34 +164,37 @@ func (ctx *Context) configuredExec(params execParams) (*ExecResult, error) {
 		return nil, fmt.Errorf("empty command provided")
 	}
 
-	shouldLog := true
+	defaultShouldLog := true
 	if !params.userAttribution && !ctx.debug {
 		// For "system" commands, we will only log if the debug flag is present.
-		shouldLog = false
-	}
-
-	optionalLogf := func(format string, args ...interface{}) {
-		if !shouldLog {
-			return
-		}
-		ctx.Logf(format, args...)
+		defaultShouldLog = false
 	}
 
 	readableCmd := strings.Join(params.cmd, " ")
 	if len(params.env) > 0 {
 		env := strings.Join(params.env, " ")
 		readableCmd = fmt.Sprintf("%s (%s)", readableCmd, env)
 	}
-	optionalLogf(divider)
-	optionalLogf("Running %q", readableCmd)
+
+	logCmd := defaultShouldLog
+	if params.logCommandOverride != nil {
+		logCmd = *params.logCommandOverride
+	}
+	if logCmd {
+		ctx.Logf(divider)
+		ctx.Logf("Running %q", readableCmd)
+	}
 
 	status := buildererror.StatusInternal
 	defer func(start time.Time) {
 		truncated := readableCmd
 		if len(truncated) > 60 {
 			truncated = truncated[:60] + "..."
 		}
-		optionalLogf("Done %q (%v)", truncated, time.Since(start))
+
+		if logCmd {
+			ctx.Logf("Done %q (%v)", truncated, time.Since(start))
+		}
 		ctx.Span(ctx.createSpanName(params.cmd), start, status)
 	}(time.Now())
 
@@ -188,8 +209,12 @@ func (ctx *Context) configuredExec(params execParams) (*ExecResult, error) {
 		ecmd.Env = append(append(ecmd.Env, os.Environ()...), params.env...)
 	}
 
+	logOutput := defaultShouldLog
+	if params.logOutputOverride != nil {
+		logOutput = *params.logOutputOverride
+	}
 	var outb, errb bytes.Buffer
-	combinedb := lockingBuffer{log: shouldLog}
+	combinedb := lockingBuffer{ctx: ctx, log: logOutput}
 	ecmd.Stdout = io.MultiWriter(&outb, &combinedb)
 	ecmd.Stderr = io.MultiWriter(&errb, &combinedb)
 
@@ -233,13 +258,14 @@ type lockingBuffer struct {
 
 	// log tells the buffer to also log the output to stderr.
 	log bool
+	ctx *Context
 }
 
 func (lb *lockingBuffer) Write(p []byte) (int, error) {
 	lb.Lock()
 	defer lb.Unlock()
 	if lb.log {
-		os.Stderr.Write(p)
+		lb.ctx.Logf(string(p))
 	}
 	return lb.buf.Write(p)
 }

pkg/gcpbuildpack/exec_test.go

@@ -15,17 +15,19 @@
 package gcpbuildpack
 
 import (
+	"bytes"
 	"io/ioutil"
+	"log"
 	"os"
 	"path/filepath"
-	"reflect"
 	"regexp"
 	"runtime"
 	"strings"
 	"testing"
 	"time"
 
 	"github.com/GoogleCloudPlatform/buildpacks/pkg/buildererror"
+	"github.com/google/go-cmp/cmp"
 )
 
 func TestExecEmitsSpan(t *testing.T) {
@@ -416,6 +418,7 @@ func TestExec(t *testing.T) {
 		wantUserTiming  bool
 		wantMinUserDur  time.Duration
 		wantUserFailure bool
+		wantLogged      []string
 	}{
 		{
 			name:           "nil cmd",
@@ -441,6 +444,9 @@ func TestExec(t *testing.T) {
 			wantResult:     &ExecResult{},
 			wantUserTiming: true,
 			wantMinUserDur: 500 * time.Millisecond,
+			wantLogged: []string{
+				`Running "sleep .5"`,
+			},
 		},
 		{
 			name:           "successful cmd with user timing attribution",
@@ -459,6 +465,9 @@ func TestExec(t *testing.T) {
 			wantUserTiming:  true,
 			wantMinUserDur:  500 * time.Millisecond,
 			wantUserFailure: true,
+			wantLogged: []string{
+				`Running "bash -c sleep .5; exit 99"`,
+			},
 		},
 		{
 			name:           "failing cmd with user timing attribution",
@@ -482,6 +491,10 @@ func TestExec(t *testing.T) {
 			wantErr:         true,
 			wantUserTiming:  true,
 			wantUserFailure: true,
+			wantLogged: []string{
+				`Running "cat /tmp/does-not-exist-123456"`,
+				"No such file or directory",
+			},
 		},
 		{
 			name:       "WithEnv",
@@ -535,6 +548,39 @@ func TestExec(t *testing.T) {
 			wantErrMessage: "foo...",
 			wantResult:     &ExecResult{ExitCode: 99, Stderr: "foo------", Combined: "foo------"},
 		},
+		{
+			name:       "WithLogCommand true overrides system attribution",
+			cmd:        []string{"bash", "-c", "echo foo------"},
+			opts:       []ExecOption{WithLogCommand(true)},
+			wantResult: &ExecResult{ExitCode: 0, Stdout: "foo------", Combined: "foo------"},
+			wantLogged: []string{
+				`Running "bash -c echo foo------"`,
+			},
+		},
+		{
+			name:           "WithLogOutput true overrides system attribution",
+			cmd:            []string{"cat", "/tmp/does-not-exist-123456"},
+			opts:           []ExecOption{WithLogOutput(true)},
+			wantErrMessage: "...ory", // Last few characters of message below due to maxMessageBytes setting in main test below.
+			wantResult: &ExecResult{
+				ExitCode: 1,
+				Stderr:   "cat: /tmp/does-not-exist-123456: No such file or directory",
+				Combined: "cat: /tmp/does-not-exist-123456: No such file or directory",
+			},
+			wantErr: true,
+			wantLogged: []string{
+				"No such file or directory",
+			},
+		},
+		{
+			// These don't have to be used together, but it's easier to test when both are on.
+			name:           "WithLogCommand false WithLogOutput false overrides user attribution",
+			cmd:            []string{"sleep", ".5"},
+			opts:           []ExecOption{WithUserAttribution, WithLogCommand(false), WithLogOutput(false)},
+			wantResult:     &ExecResult{},
+			wantUserTiming: true,
+			wantMinUserDur: 500 * time.Millisecond,
+		},
 	}
 
 	for _, tc := range testCases {
@@ -544,15 +590,17 @@ func TestExec(t *testing.T) {
 			defer func() {
 				maxMessageBytes = oldMaxMessageBytes
 			}()
-			ctx := NewContext()
+			// Capture stderr for test
+			buf := new(bytes.Buffer)
+			logger := log.New(buf, "", 0)
+			ctx := NewContext(WithLogger(logger))
 
 			result, err := ctx.execWithErrCastToBuildError(tc.cmd, tc.opts...)
-
 			if got, want := err != nil, tc.wantErr; got != want {
 				t.Errorf("got error %t want error %t", got, want)
 			}
-			if !reflect.DeepEqual(result, tc.wantResult) {
-				t.Errorf("incorrect result got %#v want %#v", result, tc.wantResult)
+			if diff := cmp.Diff(tc.wantResult, result); diff != "" {
+				t.Errorf("Exec() mismatch (-want +got):\n%s", diff)
 			}
 
 			if tc.wantUserTiming && ctx.stats.user < tc.wantMinUserDur {
@@ -562,6 +610,17 @@ func TestExec(t *testing.T) {
 				t.Error("got user timing > 0, want user timing 0")
 			}
 
+			gotOut := buf.String()
+			if tc.wantLogged == nil && gotOut != "" {
+				t.Errorf("expected Exec() to be silent, but got logs: %s", gotOut)
+			}
+
+			for _, want := range tc.wantLogged {
+				if !strings.Contains(gotOut, want) {
+					t.Errorf("Exec() missing expected logs, got logs: %s\nshould contain: %q", gotOut, want)
+				}
+			}
+
 			if tc.wantErr {
 				if tc.wantUserFailure {
 					if err.Status == buildererror.StatusInternal {