Enhances git command tracing

git/operations.go

@@ -16,9 +16,15 @@ import (
 	"github.com/pkg/errors"
 )
 
-// If true, every git invocation will be echoed to stdout
+// If true, every git invocation will be echoed to stdout (with the exception of those added to `exemptedTraceCommands`)
 const trace = false
 
+// Whilst debugging or developing, you may wish to filter certain git commands out of the logs when tracing is on.
+var exemptedTraceCommands = []string{
+	// To filter out a certain git subcommand add it here, e.g.:
+	// "config",
+}
+
 // Env vars that are allowed to be inherited from the os
 var allowedEnvVars = []string{"http_proxy", "https_proxy", "no_proxy", "HOME", "GNUPGHOME"}
 
@@ -276,15 +282,37 @@ func changed(ctx context.Context, workingDir, ref string, subPaths []string) ([]
 	return splitList(out.String()), nil
 }
 
-func execGitCmd(ctx context.Context, args []string, config gitCmdConfig) error {
-	if trace {
-		print("TRACE: git")
-		for _, arg := range args {
-			print(` "`, arg, `"`)
+// traceGitCommand returns a log line that can be useful when debugging and developing git activity
+func traceGitCommand(args []string, config gitCmdConfig, stdout string, stderr string) string {
+	for _, exemptedCommand := range exemptedTraceCommands {
+		if exemptedCommand == args[0] {
+			return ""
 		}
-		println()
 	}
 
+	prepare := func(input string) string {
+		output := strings.Trim(input, "\x00")
+		output = strings.TrimSuffix(output, "\n")
+		output = strings.Replace(output, "\n", "\\n", -1)
+		return output
+	}
+
+	command := `git ` + strings.Join(args, " ")
+	out := prepare(stdout)
+	err := prepare(stderr)
+
+	return fmt.Sprintf(
+		"TRACE: command=%q out=%q err=%q dir=%q env=%q",
+		command,
+		out,
+		err,
+		config.dir,
+		strings.Join(config.env, ","),
+	)
+}
+
+// execGitCmd runs a `git` command with the supplied arguments.
+func execGitCmd(ctx context.Context, args []string, config gitCmdConfig) error {
 	c := exec.CommandContext(ctx, "git", args...)
 
 	if config.dir != "" {
@@ -298,13 +326,27 @@ func execGitCmd(ctx context.Context, args []string, config gitCmdConfig) error {
 	errOut := &bytes.Buffer{}
 	c.Stderr = errOut
 
+	traceStdout := &bytes.Buffer{}
+	traceStderr := &bytes.Buffer{}
+	if trace {
+		c.Stdout = io.MultiWriter(c.Stdout, traceStdout)
+		c.Stderr = io.MultiWriter(c.Stderr, traceStderr)
+	}
+
 	err := c.Run()
 	if err != nil {
 		msg := findErrorMessage(errOut)
 		if msg != "" {
 			err = errors.New(msg)
 		}
 	}
+
+	if trace {
+		if traceCommand := traceGitCommand(args, config, traceStdout.String(), traceStderr.String()); traceCommand != "" {
+			println(traceCommand)
+		}
+	}
+
 	if ctx.Err() == context.DeadlineExceeded {
 		return errors.Wrap(ctx.Err(), fmt.Sprintf("running git command: %s %v", "git", args))
 	} else if ctx.Err() == context.Canceled {

git/operations_test.go

@@ -9,6 +9,7 @@ import (
 	"path/filepath"
 	"testing"
 
+	"github.com/stretchr/testify/assert"
 	"github.com/weaveworks/flux/cluster/kubernetes/testfiles"
 )
 
@@ -287,3 +288,91 @@ func updateDirAndCommit(dir, subdir string, filesUpdated map[string]string) erro
 	}
 	return nil
 }
+
+func TestTraceGitCommand(t *testing.T) {
+	type input struct {
+		args   []string
+		config gitCmdConfig
+		out    string
+		err    string
+	}
+	examples := []struct {
+		name     string
+		input    input
+		expected string
+		actual   string
+	}{
+		{
+			name: "git clone",
+			input: input{
+				args: []string{
+					"clone",
+					"--branch",
+					"master",
+					"/tmp/flux-gitclone239583443",
+					"/tmp/flux-working628880789",
+				},
+				config: gitCmdConfig{
+					dir: "/tmp/flux-working628880789",
+				},
+			},
+			expected: `TRACE: command="git clone --branch master /tmp/flux-gitclone239583443 /tmp/flux-working628880789" out="" err="" dir="/tmp/flux-working628880789" env=""`,
+		},
+		{
+			name: "git rev-list",
+			input: input{
+				args: []string{
+					"rev-list",
+					"--max-count",
+					"1",
+					"flux-sync",
+					"--",
+				},
+				out: "b9d6a543acf8085ff6bed23fac17f8dc71bfcb66",
+				config: gitCmdConfig{
+					dir: "/tmp/flux-gitclone239583443",
+				},
+			},
+			expected: `TRACE: command="git rev-list --max-count 1 flux-sync --" out="b9d6a543acf8085ff6bed23fac17f8dc71bfcb66" err="" dir="/tmp/flux-gitclone239583443" env=""`,
+		},
+		{
+			name: "git config email",
+			input: input{
+				args: []string{
+					"config",
+					"user.email",
+					"support@weave.works",
+				},
+				config: gitCmdConfig{
+					dir: "/tmp/flux-working056923691",
+				},
+			},
+			expected: `TRACE: command="git config user.email support@weave.works" out="" err="" dir="/tmp/flux-working056923691" env=""`,
+		},
+		{
+			name: "git notes",
+			input: input{
+				args: []string{
+					"notes",
+					"--ref",
+					"flux",
+					"get-ref",
+				},
+				config: gitCmdConfig{
+					dir: "/tmp/flux-working647148942",
+				},
+				out: "refs/notes/flux",
+			},
+			expected: `TRACE: command="git notes --ref flux get-ref" out="refs/notes/flux" err="" dir="/tmp/flux-working647148942" env=""`,
+		},
+	}
+	for _, example := range examples {
+		actual := traceGitCommand(
+			example.input.args,
+			example.input.config,
+			example.input.out,
+			example.input.err,
+		)
+		assert.Equal(t, example.expected, actual)
+	}
+}