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) <nil>,
  -  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 <wking@tremily.us>

1 files changed, 38 insertions, 6 deletions

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