Add helper for nicely logging Kubernetes objects

This adds a "wrapper" to a Zap encoder designed to nicely log Kubernetes
objects when in non-development mode.  When in development mode, we
still log the entire object.

Author: DirectXMan12

pkg/runtime/log/log.go

@@ -19,33 +19,26 @@ limitations under the License.
 package log
 
 import (
+	"fmt"
 	"io"
-	"log"
+	"os"
 	"time"
 
 	"github.com/go-logr/logr"
 	"github.com/go-logr/zapr"
 	"go.uber.org/zap"
+	"go.uber.org/zap/buffer"
 	"go.uber.org/zap/zapcore"
+	"k8s.io/apimachinery/pkg/api/meta"
+	"k8s.io/apimachinery/pkg/runtime"
 )
 
 // ZapLogger is a Logger implementation.
 // If development is true, a Zap development config will be used
 // (stacktraces on warnings, no sampling), otherwise a Zap production
 // config will be used (stacktraces on errors, sampling).
 func ZapLogger(development bool) logr.Logger {
-	var zapLog *zap.Logger
-	var err error
-	if development {
-		zapLogCfg := zap.NewDevelopmentConfig()
-		zapLog, err = zapLogCfg.Build(zap.AddCallerSkip(1))
-	} else {
-		zapLogCfg := zap.NewProductionConfig()
-		zapLog, err = zapLogCfg.Build(zap.AddCallerSkip(1))
-	}
-	// who watches the watchmen?
-	fatalIfErr(err, log.Fatalf)
-	return zapr.NewLogger(zapLog)
+	return ZapLoggerTo(os.Stderr, development)
 }
 
 // ZapLoggerTo returns a new Logger implementation using Zap which logs
@@ -73,15 +66,87 @@ func ZapLoggerTo(destWriter io.Writer, development bool) logr.Logger {
 			}))
 	}
 	opts = append(opts, zap.AddCallerSkip(1), zap.ErrorOutput(sink))
-	log := zap.New(zapcore.NewCore(enc, sink, lvl))
+	log := zap.New(zapcore.NewCore(&KubeAwareEncoder{Encoder: enc, Verbose: development}, sink, lvl))
 	log = log.WithOptions(opts...)
 	return zapr.NewLogger(log)
 }
 
-func fatalIfErr(err error, f func(format string, v ...interface{})) {
+// KubeAwareEncoder is a Kubernetes-aware Zap Encoder.
+// Instead of trying to force Kubernetes objects to implement
+// ObjectMarshaller, we just implement a wrapper around a normal
+// ObjectMarshaller that checks for Kubernetes objects.
+type KubeAwareEncoder struct {
+	// Encoder is the zapcore.Encoder that this encoder delegates to
+	zapcore.Encoder
+
+	// Verbose controls whether or not the full object is printed.
+	// If false, only name, namespace, api version, and kind are printed.
+	// Otherwise, the full object is logged.
+	Verbose bool
+}
+
+// kubeObjectWrapper is a zapcore.ObjectMarshaller for Kubernetes objects.
+type kubeObjectWrapper struct {
+	obj runtime.Object
+	key string
+}
+
+func (w kubeObjectWrapper) MarshalLogObject(enc zapcore.ObjectEncoder) error {
+	// TODO(directxman12): log kind and apiversion if not set explicitly (common case)
+	// -- needs an a scheme to convert to the GVK.
+	gvk := w.obj.GetObjectKind().GroupVersionKind()
+	if gvk.Version != "" {
+		enc.AddString("apiVersion", gvk.GroupVersion().String())
+		enc.AddString("kind", gvk.Kind)
+	}
+
+	objMeta, err := meta.Accessor(w.obj)
 	if err != nil {
-		f("unable to construct the logger: %v", err)
+		return fmt.Errorf("got runtime.Object without object metadata: %v", w.obj)
+	}
+
+	ns := objMeta.GetNamespace()
+	if ns != "" {
+		enc.AddString("namespace", ns)
 	}
+	enc.AddString("name", objMeta.GetName())
+
+	return nil
+}
+
+// NB(directxman12): can't just override AddReflected, since the encoder calls AddReflected on itself directly
+
+func (k *KubeAwareEncoder) Clone() zapcore.Encoder {
+	return &KubeAwareEncoder{
+		Encoder: k.Encoder.Clone(),
+	}
+}
+
+func (k *KubeAwareEncoder) EncodeEntry(entry zapcore.Entry, fields []zapcore.Field) (*buffer.Buffer, error) {
+	if k.Verbose {
+		// Kubernetes objects implement fmt.Stringer, so if we
+		// want verbose output, just delegate to that.
+		return k.Encoder.EncodeEntry(entry, fields)
+	}
+
+	for i, field := range fields {
+		// intercept stringer fields that happen to be Kubernetes runtime.Object values
+		// (Kubernetes runtime.Objects commonly implement String, apparently)
+		if field.Type == zapcore.StringerType {
+			obj, isObj := field.Interface.(runtime.Object)
+			if !isObj {
+				continue
+			}
+			// TODO(directxman12): is it more performant to do extract the gvk, name, and namespace lazily?
+			fields[i] = zapcore.Field{
+				Type:      zapcore.ObjectMarshalerType,
+				Key:       field.Key,
+				Interface: kubeObjectWrapper{obj: obj},
+			}
+		}
+	}
+
+	return k.Encoder.EncodeEntry(entry, fields)
 }
 
 // SetLogger sets a concrete logging implementation for all deferred Loggers.

pkg/runtime/log/log_test.go

@@ -17,14 +17,24 @@ limitations under the License.
 package log
 
 import (
+	"bytes"
+	"encoding/json"
 	"fmt"
 	"io/ioutil"
 
 	"github.com/go-logr/logr"
 	. "github.com/onsi/ginkgo"
 	. "github.com/onsi/gomega"
+	kapi "k8s.io/api/core/v1"
 )
 
+// testStringer is a fmt.Stringer
+type testStringer struct{}
+
+func (testStringer) String() string {
+	return "value"
+}
+
 // fakeSyncWriter is a fake zap.SyncerWriter that lets us test if sync was called
 type fakeSyncWriter bool
 
@@ -249,6 +259,76 @@ var _ = Describe("runtime log", func() {
 				Expect(ZapLoggerTo(ioutil.Discard, true)).NotTo(BeNil())
 			})
 		})
+
+		Context("when logging kubernetes objects", func() {
+			var logOut *bytes.Buffer
+			var logger logr.Logger
+
+			BeforeEach(func() {
+				logOut = new(bytes.Buffer)
+				By("setting up the logger")
+				// use production settings (false) to get just json output
+				logger = ZapLoggerTo(logOut, false)
+			})
+
+			It("should log a standard namespaced Kubernetes object name and namespace", func() {
+				pod := &kapi.Pod{}
+				pod.Name = "some-pod"
+				pod.Namespace = "some-ns"
+				logger.Info("here's a kubernetes object", "thing", pod)
+
+				outRaw := logOut.Bytes()
+				res := map[string]interface{}{}
+				Expect(json.Unmarshal(outRaw, &res)).To(Succeed())
+
+				Expect(res).To(HaveKeyWithValue("thing", map[string]interface{}{
+					"name":      pod.Name,
+					"namespace": pod.Namespace,
+				}))
+			})
+
+			It("should work fine with normal stringers", func() {
+				logger.Info("here's a non-kubernetes stringer", "thing", testStringer{})
+				outRaw := logOut.Bytes()
+				res := map[string]interface{}{}
+				Expect(json.Unmarshal(outRaw, &res)).To(Succeed())
+
+				Expect(res).To(HaveKeyWithValue("thing", "value"))
+			})
+
+			It("should log a standard non-namespaced Kubernetes object name", func() {
+				node := &kapi.Node{}
+				node.Name = "some-node"
+				logger.Info("here's a kubernetes object", "thing", node)
+
+				outRaw := logOut.Bytes()
+				res := map[string]interface{}{}
+				Expect(json.Unmarshal(outRaw, &res)).To(Succeed())
+
+				Expect(res).To(HaveKeyWithValue("thing", map[string]interface{}{
+					"name": node.Name,
+				}))
+			})
+
+			It("should log a standard Kubernetes object's kind, if set", func() {
+				node := &kapi.Node{}
+				node.Name = "some-node"
+				node.APIVersion = "v1"
+				node.Kind = "Node"
+				logger.Info("here's a kubernetes object", "thing", node)
+
+				outRaw := logOut.Bytes()
+				res := map[string]interface{}{}
+				Expect(json.Unmarshal(outRaw, &res)).To(Succeed())
+
+				Expect(res).To(HaveKeyWithValue("thing", map[string]interface{}{
+					"name":       node.Name,
+					"apiVersion": "v1",
+					"kind":       "Node",
+				}))
+
+			})
+		})
 	})
 
 	Describe("fataliferr", func() {
@@ -270,5 +350,4 @@ var _ = Describe("runtime log", func() {
 			Expect(called).To(BeTrue())
 		})
 	})
-
 })