diff --git a/test/e2e/fixture/applicationsets/utils/cmd.go b/test/e2e/fixture/applicationsets/utils/cmd.go index 866bc72263b09..434e9454d7736 100644 --- a/test/e2e/fixture/applicationsets/utils/cmd.go +++ b/test/e2e/fixture/applicationsets/utils/cmd.go @@ -5,7 +5,7 @@ import ( "os/exec" "strings" - argoexec "github.com/argoproj/pkg/exec" + argoexec "github.com/argoproj/argo-cd/v3/util/exec" ) func Run(workDir, name string, args ...string) (string, error) { diff --git a/test/e2e/fixture/cmd.go b/test/e2e/fixture/cmd.go index ca3af0daf1a2e..1d2e62d45ae41 100644 --- a/test/e2e/fixture/cmd.go +++ b/test/e2e/fixture/cmd.go @@ -5,7 +5,7 @@ import ( "os/exec" "strings" - argoexec "github.com/argoproj/pkg/exec" + argoexec "github.com/argoproj/argo-cd/v3/util/exec" ) func Run(workDir, name string, args ...string) (string, error) { diff --git a/test/fixture/revision_metadata/author.go b/test/fixture/revision_metadata/author.go index d55de82303959..cc83e6c81fd35 100644 --- a/test/fixture/revision_metadata/author.go +++ b/test/fixture/revision_metadata/author.go @@ -4,9 +4,8 @@ import ( "fmt" "strings" - argoexec "github.com/argoproj/pkg/exec" - "github.com/argoproj/argo-cd/v3/util/errors" + argoexec "github.com/argoproj/argo-cd/v3/util/exec" ) var Author string diff --git a/test/manifests_test.go b/test/manifests_test.go index c7a85fd794aad..8b6b7b60e9795 100644 --- a/test/manifests_test.go +++ b/test/manifests_test.go @@ -6,11 +6,11 @@ import ( "path/filepath" "testing" - argoexec "github.com/argoproj/pkg/exec" "github.com/stretchr/testify/assert" "github.com/stretchr/testify/require" "github.com/argoproj/argo-cd/v3/test/fixture/test" + argoexec "github.com/argoproj/argo-cd/v3/util/exec" ) func TestKustomizeVersion(t *testing.T) { diff --git a/util/exec/exec.go b/util/exec/exec.go index 198c04cb482d6..f2aa375300beb 100644 --- a/util/exec/exec.go +++ b/util/exec/exec.go @@ -1,27 +1,34 @@ package exec import ( + "bytes" + "errors" "fmt" "os" "os/exec" "strconv" "strings" + "syscall" "time" "unicode" "github.com/argoproj/gitops-engine/pkg/utils/tracing" - argoexec "github.com/argoproj/pkg/exec" + "github.com/sirupsen/logrus" "github.com/argoproj/argo-cd/v3/util/log" + "github.com/argoproj/argo-cd/v3/util/rand" ) -var timeout time.Duration +var ( + timeout time.Duration + Unredacted = Redact(nil) +) type ExecRunOpts struct { // Redactor redacts tokens from the output Redactor func(text string) string // TimeoutBehavior configures what to do in case of timeout - TimeoutBehavior argoexec.TimeoutBehavior + TimeoutBehavior TimeoutBehavior // SkipErrorLogging determines whether to skip logging of execution errors (rc > 0) SkipErrorLogging bool // CaptureStderr determines whether to capture stderr in addition to stdout @@ -50,7 +57,7 @@ func RunWithRedactor(cmd *exec.Cmd, redactor func(text string) string) (string, } func RunWithExecRunOpts(cmd *exec.Cmd, opts ExecRunOpts) (string, error) { - cmdOpts := argoexec.CmdOpts{Timeout: timeout, Redactor: opts.Redactor, TimeoutBehavior: opts.TimeoutBehavior, SkipErrorLogging: opts.SkipErrorLogging} + cmdOpts := CmdOpts{Timeout: timeout, Redactor: opts.Redactor, TimeoutBehavior: opts.TimeoutBehavior, SkipErrorLogging: opts.SkipErrorLogging} span := tracing.NewLoggingTracer(log.NewLogrusLogger(log.NewWithCurrentConfig())).StartSpan(fmt.Sprintf("exec %v", cmd.Args[0])) span.SetBaggageItem("dir", cmd.Dir) if cmdOpts.Redactor != nil { @@ -59,7 +66,7 @@ func RunWithExecRunOpts(cmd *exec.Cmd, opts ExecRunOpts) (string, error) { span.SetBaggageItem("args", fmt.Sprintf("%v", cmd.Args)) } defer span.Finish() - return argoexec.RunCommandExt(cmd, cmdOpts) + return RunCommandExt(cmd, cmdOpts) } // GetCommandArgsToLog represents the given command in a way that we can copy-and-paste into a terminal @@ -88,3 +95,156 @@ func GetCommandArgsToLog(cmd *exec.Cmd) string { args := strings.Join(argsToLog, " ") return args } + +type CmdError struct { + Args string + Stderr string + Cause error +} + +func (ce *CmdError) Error() string { + res := fmt.Sprintf("`%v` failed %v", ce.Args, ce.Cause) + if ce.Stderr != "" { + res = fmt.Sprintf("%s: %s", res, ce.Stderr) + } + return res +} + +func (ce *CmdError) String() string { + return ce.Error() +} + +func newCmdError(args string, cause error, stderr string) *CmdError { + return &CmdError{Args: args, Stderr: stderr, Cause: cause} +} + +// TimeoutBehavior defines behavior for when the command takes longer than the passed in timeout to exit +// By default, SIGKILL is sent to the process and it is not waited upon +type TimeoutBehavior struct { + // Signal determines the signal to send to the process + Signal syscall.Signal + // ShouldWait determines whether to wait for the command to exit once timeout is reached + ShouldWait bool +} + +type CmdOpts struct { + // Timeout determines how long to wait for the command to exit + Timeout time.Duration + // Redactor redacts tokens from the output + Redactor func(text string) string + // TimeoutBehavior configures what to do in case of timeout + TimeoutBehavior TimeoutBehavior + // SkipErrorLogging defines whether to skip logging of execution errors (rc > 0) + SkipErrorLogging bool + // CaptureStderr defines whether to capture stderr in addition to stdout + CaptureStderr bool +} + +var DefaultCmdOpts = CmdOpts{ + Timeout: time.Duration(0), + Redactor: Unredacted, + TimeoutBehavior: TimeoutBehavior{syscall.SIGKILL, false}, + SkipErrorLogging: false, + CaptureStderr: false, +} + +func Redact(items []string) func(text string) string { + return func(text string) string { + for _, item := range items { + text = strings.ReplaceAll(text, item, "******") + } + return text + } +} + +// RunCommandExt is a convenience function to run/log a command and return/log stderr in an error upon +// failure. +func RunCommandExt(cmd *exec.Cmd, opts CmdOpts) (string, error) { + execId, err := rand.RandHex(5) + if err != nil { + return "", err + } + logCtx := logrus.WithFields(logrus.Fields{"execID": execId}) + + redactor := DefaultCmdOpts.Redactor + if opts.Redactor != nil { + redactor = opts.Redactor + } + + // log in a way we can copy-and-paste into a terminal + args := strings.Join(cmd.Args, " ") + logCtx.WithFields(logrus.Fields{"dir": cmd.Dir}).Info(redactor(args)) + + var stdout bytes.Buffer + var stderr bytes.Buffer + cmd.Stdout = &stdout + cmd.Stderr = &stderr + + start := time.Now() + err = cmd.Start() + if err != nil { + return "", err + } + + done := make(chan error) + go func() { done <- cmd.Wait() }() + + // Start a timer + timeout := DefaultCmdOpts.Timeout + + if opts.Timeout != time.Duration(0) { + timeout = opts.Timeout + } + + var timoutCh <-chan time.Time + if timeout != 0 { + timoutCh = time.NewTimer(timeout).C + } + + timeoutBehavior := DefaultCmdOpts.TimeoutBehavior + if opts.TimeoutBehavior.Signal != syscall.Signal(0) { + timeoutBehavior = opts.TimeoutBehavior + } + + select { + // noinspection ALL + case <-timoutCh: + _ = cmd.Process.Signal(timeoutBehavior.Signal) + if timeoutBehavior.ShouldWait { + <-done + } + output := stdout.String() + if opts.CaptureStderr { + output += stderr.String() + } + logCtx.WithFields(logrus.Fields{"duration": time.Since(start)}).Debug(redactor(output)) + err = newCmdError(redactor(args), fmt.Errorf("timeout after %v", timeout), "") + logCtx.Error(err.Error()) + return strings.TrimSuffix(output, "\n"), err + case err := <-done: + if err != nil { + output := stdout.String() + if opts.CaptureStderr { + output += stderr.String() + } + logCtx.WithFields(logrus.Fields{"duration": time.Since(start)}).Debug(redactor(output)) + err := newCmdError(redactor(args), errors.New(redactor(err.Error())), strings.TrimSpace(redactor(stderr.String()))) + if !opts.SkipErrorLogging { + logCtx.Error(err.Error()) + } + return strings.TrimSuffix(output, "\n"), err + } + } + + output := stdout.String() + if opts.CaptureStderr { + output += stderr.String() + } + logCtx.WithFields(logrus.Fields{"duration": time.Since(start)}).Debug(redactor(output)) + + return strings.TrimSuffix(output, "\n"), nil +} + +func RunCommand(name string, opts CmdOpts, arg ...string) (string, error) { + return RunCommandExt(exec.Command(name, arg...), opts) +} diff --git a/util/exec/exec_norace_test.go b/util/exec/exec_norace_test.go new file mode 100644 index 0000000000000..9c4cbeb728262 --- /dev/null +++ b/util/exec/exec_norace_test.go @@ -0,0 +1,44 @@ +//go:build !race + +package exec + +import ( + "testing" + "time" + + log "github.com/sirupsen/logrus" + "github.com/sirupsen/logrus/hooks/test" + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" +) + +// FIXME: there's a race in RunCommand that causes the test to fail when -race is enabled. The race is in the timeout +// handling, which shares bytes buffers between the exec goroutine and the timeout handler code. +func TestRunCommandTimeout(t *testing.T) { + hook := test.NewGlobal() + log.SetLevel(log.DebugLevel) + defer log.SetLevel(log.InfoLevel) + + output, err := RunCommand("sh", CmdOpts{Timeout: 500 * time.Millisecond}, "-c", "echo hello world && echo my-error >&2 && sleep 2") + assert.Equal(t, "hello world", output) + require.EqualError(t, err, "`sh -c echo hello world && echo my-error >&2 && sleep 2` failed timeout after 500ms") + + assert.Len(t, hook.Entries, 3) + + entry := hook.Entries[0] + assert.Equal(t, log.InfoLevel, entry.Level) + assert.Equal(t, "sh -c echo hello world && echo my-error >&2 && sleep 2", entry.Message) + assert.Contains(t, entry.Data, "dir") + assert.Contains(t, entry.Data, "execID") + + entry = hook.Entries[1] + assert.Equal(t, log.DebugLevel, entry.Level) + assert.Equal(t, "hello world\n", entry.Message) + assert.Contains(t, entry.Data, "duration") + assert.Contains(t, entry.Data, "execID") + + entry = hook.Entries[2] + assert.Equal(t, log.ErrorLevel, entry.Level) + assert.Equal(t, "`sh -c echo hello world && echo my-error >&2 && sleep 2` failed timeout after 500ms", entry.Message) + assert.Contains(t, entry.Data, "execID") +} diff --git a/util/exec/exec_test.go b/util/exec/exec_test.go index c41ee100f55ad..a9c2c368d58ce 100644 --- a/util/exec/exec_test.go +++ b/util/exec/exec_test.go @@ -7,7 +7,8 @@ import ( "testing" "time" - argoexec "github.com/argoproj/pkg/exec" + log "github.com/sirupsen/logrus" + "github.com/sirupsen/logrus/hooks/test" "github.com/stretchr/testify/assert" "github.com/stretchr/testify/require" ) @@ -46,7 +47,7 @@ func TestRunWithExecRunOpts(t *testing.T) { initTimeout() opts := ExecRunOpts{ - TimeoutBehavior: argoexec.TimeoutBehavior{ + TimeoutBehavior: TimeoutBehavior{ Signal: syscall.SIGTERM, ShouldWait: true, }, @@ -86,3 +87,108 @@ func Test_getCommandArgsToLog(t *testing.T) { }) } } + +func TestRunCommand(t *testing.T) { + hook := test.NewGlobal() + log.SetLevel(log.DebugLevel) + defer log.SetLevel(log.InfoLevel) + + message, err := RunCommand("echo", CmdOpts{Redactor: Redact([]string{"world"})}, "hello world") + require.NoError(t, err) + assert.Equal(t, "hello world", message) + + assert.Len(t, hook.Entries, 2) + + entry := hook.Entries[0] + assert.Equal(t, log.InfoLevel, entry.Level) + assert.Equal(t, "echo hello ******", entry.Message) + assert.Contains(t, entry.Data, "dir") + assert.Contains(t, entry.Data, "execID") + + entry = hook.Entries[1] + assert.Equal(t, log.DebugLevel, entry.Level) + assert.Equal(t, "hello ******\n", entry.Message) + assert.Contains(t, entry.Data, "duration") + assert.Contains(t, entry.Data, "execID") +} + +func TestRunCommandSignal(t *testing.T) { + hook := test.NewGlobal() + log.SetLevel(log.DebugLevel) + defer log.SetLevel(log.InfoLevel) + + timeoutBehavior := TimeoutBehavior{Signal: syscall.SIGTERM, ShouldWait: true} + output, err := RunCommand("sh", CmdOpts{Timeout: 200 * time.Millisecond, TimeoutBehavior: timeoutBehavior}, "-c", "trap 'trap - 15 && echo captured && exit' 15 && sleep 2") + assert.Equal(t, "captured", output) + require.EqualError(t, err, "`sh -c trap 'trap - 15 && echo captured && exit' 15 && sleep 2` failed timeout after 200ms") + + assert.Len(t, hook.Entries, 3) +} + +func TestTrimmedOutput(t *testing.T) { + message, err := RunCommand("printf", CmdOpts{}, "hello world") + require.NoError(t, err) + assert.Equal(t, "hello world", message) +} + +func TestRunCommandExitErr(t *testing.T) { + hook := test.NewGlobal() + log.SetLevel(log.DebugLevel) + defer log.SetLevel(log.InfoLevel) + + output, err := RunCommand("sh", CmdOpts{Redactor: Redact([]string{"world"})}, "-c", "echo hello world && echo my-error >&2 && exit 1") + assert.Equal(t, "hello world", output) + require.EqualError(t, err, "`sh -c echo hello ****** && echo my-error >&2 && exit 1` failed exit status 1: my-error") + + assert.Len(t, hook.Entries, 3) + + entry := hook.Entries[0] + assert.Equal(t, log.InfoLevel, entry.Level) + assert.Equal(t, "sh -c echo hello ****** && echo my-error >&2 && exit 1", entry.Message) + assert.Contains(t, entry.Data, "dir") + assert.Contains(t, entry.Data, "execID") + + entry = hook.Entries[1] + assert.Equal(t, log.DebugLevel, entry.Level) + assert.Equal(t, "hello ******\n", entry.Message) + assert.Contains(t, entry.Data, "duration") + assert.Contains(t, entry.Data, "execID") + + entry = hook.Entries[2] + assert.Equal(t, log.ErrorLevel, entry.Level) + assert.Equal(t, "`sh -c echo hello ****** && echo my-error >&2 && exit 1` failed exit status 1: my-error", entry.Message) + assert.Contains(t, entry.Data, "execID") +} + +func TestRunCommandErr(t *testing.T) { + log.SetLevel(log.DebugLevel) + defer log.SetLevel(log.InfoLevel) + + output, err := RunCommand("sh", CmdOpts{Redactor: Redact([]string{"world"})}, "-c", ">&2 echo 'failure'; false") + assert.Empty(t, output) + assert.EqualError(t, err, "`sh -c >&2 echo 'failure'; false` failed exit status 1: failure") +} + +func TestRunInDir(t *testing.T) { + cmd := exec.Command("pwd") + cmd.Dir = "/" + message, err := RunCommandExt(cmd, CmdOpts{}) + require.NoError(t, err) + assert.Equal(t, "/", message) +} + +func TestRedact(t *testing.T) { + assert.Equal(t, "", Redact(nil)("")) + assert.Equal(t, "", Redact([]string{})("")) + assert.Equal(t, "", Redact([]string{"foo"})("")) + assert.Equal(t, "foo", Redact([]string{})("foo")) + assert.Equal(t, "******", Redact([]string{"foo"})("foo")) + assert.Equal(t, "****** ******", Redact([]string{"foo", "bar"})("foo bar")) + assert.Equal(t, "****** ******", Redact([]string{"foo"})("foo foo")) +} + +func TestRunCaptureStderr(t *testing.T) { + output, err := RunCommand("sh", CmdOpts{CaptureStderr: true}, "-c", "echo hello world && echo my-error >&2 && exit 0") + assert.Equal(t, "hello world\nmy-error", output) + assert.NoError(t, err) +} diff --git a/util/git/client.go b/util/git/client.go index 0f5b91d124c1f..2e31d34eb3c2f 100644 --- a/util/git/client.go +++ b/util/git/client.go @@ -18,8 +18,6 @@ import ( "time" "github.com/Masterminds/semver/v3" - - argoexec "github.com/argoproj/pkg/exec" "github.com/bmatcuk/doublestar/v4" "github.com/go-git/go-git/v5" "github.com/go-git/go-git/v5/config" @@ -1014,7 +1012,7 @@ func (m *nativeGitClient) runCmdOutput(cmd *exec.Cmd, ropts runOpts) (string, er } cmd.Env = proxy.UpsertEnv(cmd, m.proxy, m.noProxy) opts := executil.ExecRunOpts{ - TimeoutBehavior: argoexec.TimeoutBehavior{ + TimeoutBehavior: executil.TimeoutBehavior{ Signal: syscall.SIGTERM, ShouldWait: true, }, diff --git a/util/kustomize/kustomize_test.go b/util/kustomize/kustomize_test.go index dbeb027023b3d..40af4c32148db 100644 --- a/util/kustomize/kustomize_test.go +++ b/util/kustomize/kustomize_test.go @@ -7,13 +7,13 @@ import ( "path/filepath" "testing" - "github.com/argoproj/pkg/exec" "github.com/stretchr/testify/assert" "github.com/stretchr/testify/require" "k8s.io/apimachinery/pkg/apis/meta/v1/unstructured" "k8s.io/apimachinery/pkg/util/intstr" "github.com/argoproj/argo-cd/v3/pkg/apis/application/v1alpha1" + "github.com/argoproj/argo-cd/v3/util/exec" "github.com/argoproj/argo-cd/v3/util/git" ) diff --git a/util/rand/rand.go b/util/rand/rand.go index 1e748bf93bb77..82603da176ada 100644 --- a/util/rand/rand.go +++ b/util/rand/rand.go @@ -2,6 +2,7 @@ package rand import ( "crypto/rand" + "encoding/hex" "fmt" "math/big" ) @@ -28,3 +29,12 @@ func StringFromCharset(n int, charset string) (string, error) { } return string(b), nil } + +// RandHex returns a cryptographically-secure pseudo-random alpha-numeric string of a given length +func RandHex(n int) (string, error) { + bytes := make([]byte, n/2+1) // we need one extra letter to discard + if _, err := rand.Read(bytes); err != nil { + return "", err + } + return hex.EncodeToString(bytes)[0:n], nil +} diff --git a/util/rand/rand_test.go b/util/rand/rand_test.go index d696c0e22c8da..09366f8652de8 100644 --- a/util/rand/rand_test.go +++ b/util/rand/rand_test.go @@ -16,3 +16,12 @@ func TestRandString(t *testing.T) { require.NoError(t, err) assert.Len(t, ss, 5) } + +func TestRandHex(t *testing.T) { + ss, err := RandHex(10) + require.NoError(t, err) + assert.Len(t, ss, 10) + ss, err = RandHex(5) + require.NoError(t, err) + assert.Len(t, ss, 5) +}