pkg/hooks/exec: Include failed command in hook errors

For example:

  $ cat /etc/containers/oci/hooks.d/test.json
  {
    "version": "1.0.0",
    "hook": {
      "path": "/bin/sh",
      "args": ["sh", "-c", "echo 'oh, noes!' >&2; exit 1"]
    },
    "when": {
      "always": true
    },
    "stages": ["precreate"]
  }
  $ podman run --rm docker.io/library/alpine echo 'successful container'
  error setting up OCI Hooks: executing [sh -c echo 'oh, noes!' >&2; exit 1]: exit status 1

The rendered command isn't in in the right syntax for copy/pasting
into a shell, but it should be enough for the user to be able to
locate the failing hook.  They'll need to know their hook directories,
but with the previous commits requiring explicit hook directories it's
more likely that the caller is aware of them.  And if they run at a
debug level, they can see the lookups in the logs:

  $ podman --log-level=debug --hooks-dir=/etc/containers/oci/hooks.d run --rm docker.io/library/alpine echo 'successful container' 2>&1 | grep -i hook
  time="2018-12-02T22:15:16-08:00" level=debug msg="reading hooks from /etc/containers/oci/hooks.d"
  time="2018-12-02T22:15:16-08:00" level=debug msg="added hook /etc/containers/oci/hooks.d/test.json"
  time="2018-12-02T22:15:16-08:00" level=debug msg="hook test.json matched; adding to stages [precreate]"
  time="2018-12-02T22:15:16-08:00" level=warning msg="container 3695c6ba0cc961918bd3e4a769c52bd08b82afea5cd79e9749e9c7a63b5e7100: precreate hook: executing [sh -c echo 'oh, noes!' >&2; exit 1]: exit status 1"
  time="2018-12-02T22:15:16-08:00" level=error msg="error setting up OCI Hooks: executing [sh -c echo 'oh, noes!' >&2; exit 1]: exit status 1"

Signed-off-by: W. Trevor King <wking@tremily.us>

3 files changed, 11 insertions, 6 deletions

diff --git a/pkg/hooks/exec/exec.go b/pkg/hooks/exec/exec.go
index 94469b1d2..0dd091561 100644
--- a/pkg/hooks/exec/exec.go
+++ b/pkg/hooks/exec/exec.go
@@ -10,6 +10,7 @@ import (
 	"time"
 
 	rspec "github.com/opencontainers/runtime-spec/specs-go"
+	"github.com/pkg/errors"
 )
 
 // DefaultPostKillTimeout is the recommended default post-kill timeout.
@@ -42,7 +43,11 @@ func Run(ctx context.Context, hook *rspec.Hook, state []byte, stdout io.Writer,
 	}
 	exit := make(chan error, 1)
 	go func() {
-		exit <- cmd.Wait()
+		err := cmd.Wait()
+		if err != nil {
+			err = errors.Wrapf(err, "executing %v", cmd.Args)
+		}
+		exit <- err
 	}()
 
 	select {
diff --git a/pkg/hooks/exec/exec_test.go b/pkg/hooks/exec/exec_test.go
index 62e45ff3a..7aac315cb 100644
--- a/pkg/hooks/exec/exec_test.go
+++ b/pkg/hooks/exec/exec_test.go
@@ -163,14 +163,14 @@ func TestRunCancel(t *testing.T) {
 			name:              "context timeout",
 			contextTimeout:    time.Duration(1) * time.Second,
 			expectedStdout:    "waiting\n",
-			expectedHookError: "^signal: killed$",
+			expectedHookError: "^executing \\[sh -c echo waiting; sleep 2; echo done]: signal: killed$",
 			expectedRunError:  context.DeadlineExceeded,
 		},
 		{
 			name:              "hook timeout",
 			hookTimeout:       &one,
 			expectedStdout:    "waiting\n",
-			expectedHookError: "^signal: killed$",
+			expectedHookError: "^executing \\[sh -c echo waiting; sleep 2; echo done]: signal: killed$",
 			expectedRunError:  context.DeadlineExceeded,
 		},
 	} {
@@ -207,7 +207,7 @@ func TestRunKillTimeout(t *testing.T) {
 	}
 	hookErr, err := Run(ctx, hook, []byte("{}"), nil, nil, time.Duration(0))
 	assert.Equal(t, context.DeadlineExceeded, err)
-	assert.Regexp(t, "^(failed to reap process within 0s of the kill signal|signal: killed)$", hookErr)
+	assert.Regexp(t, "^(failed to reap process within 0s of the kill signal|executing \\[sh -c sleep 1]: signal: killed)$", hookErr)
 }
 
 func init() {
diff --git a/pkg/hooks/exec/runtimeconfigfilter_test.go b/pkg/hooks/exec/runtimeconfigfilter_test.go
index b50b1b156..52d590d14 100644
--- a/pkg/hooks/exec/runtimeconfigfilter_test.go
+++ b/pkg/hooks/exec/runtimeconfigfilter_test.go
@@ -194,7 +194,7 @@ func TestRuntimeConfigFilter(t *testing.T) {
 					Path: "rootfs",
 				},
 			},
-			expectedHookError: "^signal: killed$",
+			expectedHookError: "^executing \\[sh -c sleep 2]: signal: killed$",
 			expectedRunError:  context.DeadlineExceeded,
 		},
 		{
@@ -218,7 +218,7 @@ func TestRuntimeConfigFilter(t *testing.T) {
 					Path: "rootfs",
 				},
 			},
-			expectedHookError: "^signal: killed$",
+			expectedHookError: "^executing \\[sh -c sleep 2]: signal: killed$",
 			expectedRunError:  context.DeadlineExceeded,
 		},
 		{