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/kube_helpers.go

@@ -0,0 +1,129 @@
+/*
+Copyright 2018 The Kubernetes Authors.
+
+Licensed under the Apache License, Version 2.0 (the "License");
+you may not use this file except in compliance with the License.
+You may obtain a copy of the License at
+
+    http://www.apache.org/licenses/LICENSE-2.0
+
+Unless required by applicable law or agreed to in writing, software
+distributed under the License is distributed on an "AS IS" BASIS,
+WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+See the License for the specific language governing permissions and
+limitations under the License.
+*/
+
+// Package log contains utilities for fetching a new logger
+// when one is not already available.
+package log
+
+import (
+	"fmt"
+
+	"go.uber.org/zap/buffer"
+	"go.uber.org/zap/zapcore"
+	"k8s.io/apimachinery/pkg/api/meta"
+	"k8s.io/apimachinery/pkg/runtime"
+	"k8s.io/apimachinery/pkg/types"
+)
+
+// 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
+}
+
+// namespacedNameWrapper is a zapcore.ObjectMarshaler for Kubernetes NamespacedName
+type namespacedNameWrapper struct {
+	types.NamespacedName
+}
+
+func (w namespacedNameWrapper) MarshalLogObject(enc zapcore.ObjectEncoder) error {
+	if w.Namespace != "" {
+		enc.AddString("namespace", w.Namespace)
+	}
+
+	enc.AddString("name", w.Name)
+
+	return nil
+}
+
+// kubeObjectWrapper is a zapcore.ObjectMarshaler for Kubernetes objects.
+type kubeObjectWrapper struct {
+	obj runtime.Object
+}
+
+// MarshalLogObject implements zapcore.ObjectMarshaler
+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 {
+		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
+
+// Clone implements zapcore.Encoder
+func (k *KubeAwareEncoder) Clone() zapcore.Encoder {
+	return &KubeAwareEncoder{
+		Encoder: k.Encoder.Clone(),
+	}
+}
+
+// EncodeEntry implements zapcore.Encoder
+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 or
+		// types.NamespacedName values (Kubernetes runtime.Objects commonly
+		// implement String, apparently).
+		if field.Type == zapcore.StringerType {
+			switch val := field.Interface.(type) {
+			case runtime.Object:
+				fields[i] = zapcore.Field{
+					Type:      zapcore.ObjectMarshalerType,
+					Key:       field.Key,
+					Interface: kubeObjectWrapper{obj: val},
+				}
+			case types.NamespacedName:
+				fields[i] = zapcore.Field{
+					Type:      zapcore.ObjectMarshalerType,
+					Key:       field.Key,
+					Interface: namespacedNameWrapper{NamespacedName: val},
+				}
+			}
+		}
+	}
+
+	return k.Encoder.EncodeEntry(entry, fields)
+}

pkg/runtime/log/log.go

@@ -20,7 +20,7 @@ package log
 
 import (
 	"io"
-	"log"
+	"os"
 	"time"
 
 	"github.com/go-logr/logr"
@@ -34,18 +34,7 @@ import (
 // (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,17 +62,11 @@ 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{})) {
-	if err != nil {
-		f("unable to construct the logger: %v", err)
-	}
-}
-
 // SetLogger sets a concrete logging implementation for all deferred Loggers.
 func SetLogger(l logr.Logger) {
 	Log.Fulfill(l)

pkg/runtime/log/log_test.go

@@ -17,14 +17,24 @@ limitations under the License.
 package log
 
 import (
-	"fmt"
+	"bytes"
+	"encoding/json"
 	"io/ioutil"
 
 	"github.com/go-logr/logr"
 	. "github.com/onsi/ginkgo"
 	. "github.com/onsi/gomega"
+	kapi "k8s.io/api/core/v1"
+	"k8s.io/apimachinery/pkg/types"
 )
 
+// 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,26 +259,101 @@ var _ = Describe("runtime log", func() {
 				Expect(ZapLoggerTo(ioutil.Discard, true)).NotTo(BeNil())
 			})
 		})
-	})
 
-	Describe("fataliferr", func() {
-		It("should not call the fn if there is not an error", func() {
-			called := false
-			fn := func(format string, v ...interface{}) {
-				called = true
-			}
-			fatalIfErr(nil, fn)
-			Expect(called).To(BeFalse())
-		})
+		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 call the fn if there is an error", func() {
-			called := false
-			fn := func(format string, v ...interface{}) {
-				called = true
-			}
-			fatalIfErr(fmt.Errorf("error"), fn)
-			Expect(called).To(BeTrue())
+			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",
+				}))
+			})
+
+			It("should log a standard non-namespaced NamespacedName name", func() {
+				name := types.NamespacedName{Name: "some-node"}
+				logger.Info("here's a kubernetes object", "thing", name)
+
+				outRaw := logOut.Bytes()
+				res := map[string]interface{}{}
+				Expect(json.Unmarshal(outRaw, &res)).To(Succeed())
+
+				Expect(res).To(HaveKeyWithValue("thing", map[string]interface{}{
+					"name": name.Name,
+				}))
+			})
+
+			It("should log a standard namespaced NamespacedName name and namespace", func() {
+				name := types.NamespacedName{Name: "some-pod", Namespace: "some-ns"}
+				logger.Info("here's a kubernetes object", "thing", name)
+
+				outRaw := logOut.Bytes()
+				res := map[string]interface{}{}
+				Expect(json.Unmarshal(outRaw, &res)).To(Succeed())
+
+				Expect(res).To(HaveKeyWithValue("thing", map[string]interface{}{
+					"name":      name.Name,
+					"namespace": name.Namespace,
+				}))
+			})
 		})
 	})
-
 })