From f6a2b6bf2b923a148792cc141ec4c27b5889c077 Mon Sep 17 00:00:00 2001 From: "W. Trevor King" Date: Mon, 19 Nov 2018 09:22:32 -0800 Subject: hooks: Add pre-create hooks for runtime-config manipulation There's been a lot of discussion over in [1] about how to support the NVIDIA folks and others who want to be able to create devices (possibly after having loaded kernel modules) and bind userspace libraries into the container. Currently that's happening in the middle of runc's create-time mount handling before the container pivots to its new root directory with runc's incorrectly-timed prestart hook trigger [2]. With this commit, we extend hooks with a 'precreate' stage to allow trusted parties to manipulate the config JSON before calling the runtime's 'create'. I'm recycling the existing Hook schema from pkg/hooks for this, because we'll want Timeout for reliability and When to avoid the expense of fork/exec when a given hook does not need to make config changes [3]. [1]: https://github.com/opencontainers/runc/pull/1811 [2]: https://github.com/opencontainers/runc/issues/1710 [3]: https://github.com/containers/libpod/issues/1828#issuecomment-439888059 Signed-off-by: W. Trevor King --- pkg/hooks/exec/runtimeconfigfilter.go | 36 ++++ pkg/hooks/exec/runtimeconfigfilter_test.go | 266 +++++++++++++++++++++++++++++ 2 files changed, 302 insertions(+) create mode 100644 pkg/hooks/exec/runtimeconfigfilter.go create mode 100644 pkg/hooks/exec/runtimeconfigfilter_test.go (limited to 'pkg/hooks/exec') diff --git a/pkg/hooks/exec/runtimeconfigfilter.go b/pkg/hooks/exec/runtimeconfigfilter.go new file mode 100644 index 000000000..b5018a4ad --- /dev/null +++ b/pkg/hooks/exec/runtimeconfigfilter.go @@ -0,0 +1,36 @@ +package exec + +import ( + "bytes" + "context" + "encoding/json" + "time" + + spec "github.com/opencontainers/runtime-spec/specs-go" + "github.com/pkg/errors" + "github.com/sirupsen/logrus" +) + +// RuntimeConfigFilter calls a series of hooks. But instead of +// passing container state on their standard input, +// RuntimeConfigFilter passes the proposed runtime configuration (and +// reads back a possibly-altered form from their standard output). +func RuntimeConfigFilter(ctx context.Context, hooks []spec.Hook, config *spec.Spec, postKillTimeout time.Duration) (hookErr, err error) { + data, err := json.Marshal(config) + for _, hook := range hooks { + var stdout bytes.Buffer + hookErr, err = Run(ctx, &hook, data, &stdout, nil, postKillTimeout) + if err != nil { + return hookErr, err + } + + data = stdout.Bytes() + } + err = json.Unmarshal(data, config) + if err != nil { + logrus.Debugf("invalid JSON from config-filter hooks:\n%s", string(data)) + return nil, errors.Wrap(err, "unmarshal output from config-filter hooks") + } + + return nil, nil +} diff --git a/pkg/hooks/exec/runtimeconfigfilter_test.go b/pkg/hooks/exec/runtimeconfigfilter_test.go new file mode 100644 index 000000000..b50b1b156 --- /dev/null +++ b/pkg/hooks/exec/runtimeconfigfilter_test.go @@ -0,0 +1,266 @@ +package exec + +import ( + "context" + "encoding/json" + "os" + "testing" + "time" + + spec "github.com/opencontainers/runtime-spec/specs-go" + "github.com/pkg/errors" + "github.com/stretchr/testify/assert" +) + +func pointerInt(value int) *int { + return &value +} + +func pointerUInt32(value uint32) *uint32 { + return &value +} + +func pointerFileMode(value os.FileMode) *os.FileMode { + return &value +} + +func TestRuntimeConfigFilter(t *testing.T) { + unexpectedEndOfJSONInput := json.Unmarshal([]byte("{\n"), nil) + + for _, test := range []struct { + name string + contextTimeout time.Duration + hooks []spec.Hook + input *spec.Spec + expected *spec.Spec + expectedHookError string + expectedRunError error + }{ + { + name: "no-op", + hooks: []spec.Hook{ + { + Path: path, + Args: []string{"sh", "-c", "cat"}, + }, + }, + input: &spec.Spec{ + Version: "1.0.0", + Root: &spec.Root{ + Path: "rootfs", + }, + }, + expected: &spec.Spec{ + Version: "1.0.0", + Root: &spec.Root{ + Path: "rootfs", + }, + }, + }, + { + name: "device injection", + hooks: []spec.Hook{ + { + Path: path, + Args: []string{"sh", "-c", `sed 's|\("gid":0}\)|\1,{"path": "/dev/sda","type":"b","major":8,"minor":0,"fileMode":384,"uid":0,"gid":0}|'`}, + }, + }, + input: &spec.Spec{ + Version: "1.0.0", + Root: &spec.Root{ + Path: "rootfs", + }, + Linux: &spec.Linux{ + Devices: []spec.LinuxDevice{ + { + Path: "/dev/fuse", + Type: "c", + Major: 10, + Minor: 229, + FileMode: pointerFileMode(0600), + UID: pointerUInt32(0), + GID: pointerUInt32(0), + }, + }, + }, + }, + expected: &spec.Spec{ + Version: "1.0.0", + Root: &spec.Root{ + Path: "rootfs", + }, + Linux: &spec.Linux{ + Devices: []spec.LinuxDevice{ + { + Path: "/dev/fuse", + Type: "c", + Major: 10, + Minor: 229, + FileMode: pointerFileMode(0600), + UID: pointerUInt32(0), + GID: pointerUInt32(0), + }, + { + Path: "/dev/sda", + Type: "b", + Major: 8, + Minor: 0, + FileMode: pointerFileMode(0600), + UID: pointerUInt32(0), + GID: pointerUInt32(0), + }, + }, + }, + }, + }, + { + name: "chaining", + hooks: []spec.Hook{ + { + Path: path, + Args: []string{"sh", "-c", `sed 's|\("gid":0}\)|\1,{"path": "/dev/sda","type":"b","major":8,"minor":0,"fileMode":384,"uid":0,"gid":0}|'`}, + }, + { + Path: path, + Args: []string{"sh", "-c", `sed 's|/dev/sda|/dev/sdb|'`}, + }, + }, + input: &spec.Spec{ + Version: "1.0.0", + Root: &spec.Root{ + Path: "rootfs", + }, + Linux: &spec.Linux{ + Devices: []spec.LinuxDevice{ + { + Path: "/dev/fuse", + Type: "c", + Major: 10, + Minor: 229, + FileMode: pointerFileMode(0600), + UID: pointerUInt32(0), + GID: pointerUInt32(0), + }, + }, + }, + }, + expected: &spec.Spec{ + Version: "1.0.0", + Root: &spec.Root{ + Path: "rootfs", + }, + Linux: &spec.Linux{ + Devices: []spec.LinuxDevice{ + { + Path: "/dev/fuse", + Type: "c", + Major: 10, + Minor: 229, + FileMode: pointerFileMode(0600), + UID: pointerUInt32(0), + GID: pointerUInt32(0), + }, + { + Path: "/dev/sdb", + Type: "b", + Major: 8, + Minor: 0, + FileMode: pointerFileMode(0600), + UID: pointerUInt32(0), + GID: pointerUInt32(0), + }, + }, + }, + }, + }, + { + name: "context timeout", + contextTimeout: time.Duration(1) * time.Second, + hooks: []spec.Hook{ + { + Path: path, + Args: []string{"sh", "-c", "sleep 2"}, + }, + }, + input: &spec.Spec{ + Version: "1.0.0", + Root: &spec.Root{ + Path: "rootfs", + }, + }, + expected: &spec.Spec{ + Version: "1.0.0", + Root: &spec.Root{ + Path: "rootfs", + }, + }, + expectedHookError: "^signal: killed$", + expectedRunError: context.DeadlineExceeded, + }, + { + name: "hook timeout", + hooks: []spec.Hook{ + { + Path: path, + Args: []string{"sh", "-c", "sleep 2"}, + Timeout: pointerInt(1), + }, + }, + input: &spec.Spec{ + Version: "1.0.0", + Root: &spec.Root{ + Path: "rootfs", + }, + }, + expected: &spec.Spec{ + Version: "1.0.0", + Root: &spec.Root{ + Path: "rootfs", + }, + }, + expectedHookError: "^signal: killed$", + expectedRunError: context.DeadlineExceeded, + }, + { + name: "invalid JSON", + hooks: []spec.Hook{ + { + Path: path, + Args: []string{"sh", "-c", "echo '{'"}, + }, + }, + input: &spec.Spec{ + Version: "1.0.0", + Root: &spec.Root{ + Path: "rootfs", + }, + }, + expected: &spec.Spec{ + Version: "1.0.0", + Root: &spec.Root{ + Path: "rootfs", + }, + }, + expectedRunError: unexpectedEndOfJSONInput, + }, + } { + t.Run(test.name, func(t *testing.T) { + ctx := context.Background() + if test.contextTimeout > 0 { + var cancel context.CancelFunc + ctx, cancel = context.WithTimeout(ctx, test.contextTimeout) + defer cancel() + } + hookErr, err := RuntimeConfigFilter(ctx, test.hooks, test.input, DefaultPostKillTimeout) + assert.Equal(t, test.expectedRunError, errors.Cause(err)) + if test.expectedHookError == "" { + if hookErr != nil { + t.Fatal(hookErr) + } + } else { + assert.Regexp(t, test.expectedHookError, hookErr.Error()) + } + assert.Equal(t, test.expected, test.input) + }) + } +} -- cgit v1.2.3-54-g00ecf From c441d51e058e4a0c531f48f7d7269339e6b2d6a1 Mon Sep 17 00:00:00 2001 From: "W. Trevor King" Date: Mon, 19 Nov 2018 13:36:31 -0800 Subject: hooks/exec/runtimeconfigfilter: Log config changes To make it easier to notice and track down errors (or other surprising behavior) due to precreate hooks. With this commit, the logged messages look like: time="2018-11-19T13:35:18-08:00" level=debug msg="precreate hook 0 made configuration changes: --- Old +++ New @@ -18,3 +18,3 @@ Namespaces: ([]specs.LinuxNamespace) , - Devices: ([]specs.LinuxDevice) (len=1) { + Devices: ([]specs.LinuxDevice) (len=2) { (specs.LinuxDevice) { @@ -24,2 +24,11 @@ Minor: (int64) 229, + FileMode: (*os.FileMode)(-rw-------), + UID: (*uint32)(0), + GID: (*uint32)(0) + }, + (specs.LinuxDevice) { + Path: (string) (len=8) "/dev/sda", + Type: (string) (len=1) "b", + Major: (int64) 8, + Minor: (int64) 0, FileMode: (*os.FileMode)(-rw-------), " time="2018-11-19T13:35:18-08:00" level=debug msg="precreate hook 1 made configuration changes: --- Old +++ New @@ -29,3 +29,3 @@ (specs.LinuxDevice) { - Path: (string) (len=8) "/dev/sda", + Path: (string) (len=8) "/dev/sdb", Type: (string) (len=1) "b", " Ideally those logs would include the container ID, but we don't have access to that down at this level. I'm not sure if it's worth teaching RuntimeConfigFilter to accept a *logrus.Entry (so the caller could use WithFields [1]) or to use a generic logging interface (like go-log [2]). For now, I've left the container ID unlogged here. The spew/difflib implementation is based on stretchr/testify/assert, but I think the ~10 lines I'm borrowing are probably small enough to stay under the "all copies or substantial portions" condition in its MIT license. [1]: https://godoc.org/github.com/sirupsen/logrus#WithFields [2]: https://github.com/go-log/log Signed-off-by: W. Trevor King --- pkg/hooks/exec/runtimeconfigfilter.go | 44 ++++++++++++++++++++++++++++++----- 1 file changed, 38 insertions(+), 6 deletions(-) (limited to 'pkg/hooks/exec') diff --git a/pkg/hooks/exec/runtimeconfigfilter.go b/pkg/hooks/exec/runtimeconfigfilter.go index b5018a4ad..c6971f680 100644 --- a/pkg/hooks/exec/runtimeconfigfilter.go +++ b/pkg/hooks/exec/runtimeconfigfilter.go @@ -4,20 +4,30 @@ import ( "bytes" "context" "encoding/json" + "reflect" "time" + "github.com/davecgh/go-spew/spew" spec "github.com/opencontainers/runtime-spec/specs-go" "github.com/pkg/errors" + "github.com/pmezard/go-difflib/difflib" "github.com/sirupsen/logrus" ) +var spewConfig = spew.ConfigState{ + Indent: " ", + DisablePointerAddresses: true, + DisableCapacities: true, + SortKeys: true, +} + // RuntimeConfigFilter calls a series of hooks. But instead of // passing container state on their standard input, // RuntimeConfigFilter passes the proposed runtime configuration (and // reads back a possibly-altered form from their standard output). func RuntimeConfigFilter(ctx context.Context, hooks []spec.Hook, config *spec.Spec, postKillTimeout time.Duration) (hookErr, err error) { data, err := json.Marshal(config) - for _, hook := range hooks { + for i, hook := range hooks { var stdout bytes.Buffer hookErr, err = Run(ctx, &hook, data, &stdout, nil, postKillTimeout) if err != nil { @@ -25,11 +35,33 @@ func RuntimeConfigFilter(ctx context.Context, hooks []spec.Hook, config *spec.Sp } data = stdout.Bytes() - } - err = json.Unmarshal(data, config) - if err != nil { - logrus.Debugf("invalid JSON from config-filter hooks:\n%s", string(data)) - return nil, errors.Wrap(err, "unmarshal output from config-filter hooks") + var newConfig spec.Spec + err = json.Unmarshal(data, &newConfig) + if err != nil { + logrus.Debugf("invalid JSON from config-filter hook %d:\n%s", i, string(data)) + return nil, errors.Wrapf(err, "unmarshal output from config-filter hook %d", i) + } + + if !reflect.DeepEqual(config, &newConfig) { + old := spewConfig.Sdump(config) + new := spewConfig.Sdump(&newConfig) + diff, err := difflib.GetUnifiedDiffString(difflib.UnifiedDiff{ + A: difflib.SplitLines(old), + B: difflib.SplitLines(new), + FromFile: "Old", + FromDate: "", + ToFile: "New", + ToDate: "", + Context: 1, + }) + if err == nil { + logrus.Debugf("precreate hook %d made configuration changes:\n%s", i, diff) + } else { + logrus.Warnf("precreate hook %d made configuration changes, but we could not compute a diff: %v", i, err) + } + } + + *config = newConfig } return nil, nil -- cgit v1.2.3-54-g00ecf From 99e642d9409aef2fadb21546444d3a6a92604124 Mon Sep 17 00:00:00 2001 From: "W. Trevor King" Date: Sun, 2 Dec 2018 22:09:34 -0800 Subject: 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 --- pkg/hooks/exec/exec.go | 7 ++++++- pkg/hooks/exec/exec_test.go | 6 +++--- pkg/hooks/exec/runtimeconfigfilter_test.go | 4 ++-- 3 files changed, 11 insertions(+), 6 deletions(-) (limited to 'pkg/hooks/exec') 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, }, { -- cgit v1.2.3-54-g00ecf