Merge pull request #237 from DirectXMan12/refactor/logging-audit

✨ Ensure logging is uniform

Gopkg.toml

@@ -13,13 +13,18 @@
 #  limitations under the License.
 
 # Packages required by users
+# NB(directxman12): be very careful how you word these --
+# dep considers them as a dependency on the package you list
+# meaning that if there's a main.go in the root package
+# (like in apiextensions-apiserver), you'll pull it's deps in.
 required = ["sigs.k8s.io/testing_frameworks/integration",
             "k8s.io/client-go/plugin/pkg/client/auth",
             "github.com/spf13/pflag",
             "github.com/emicklei/go-restful",
             "github.com/go-openapi/spec",
             "k8s.io/kube-openapi/pkg/common",
-            "k8s.io/apiextensions-apiserver",
+            "k8s.io/apiextensions-apiserver/pkg/apis/apiextensions/v1beta1",
+            "k8s.io/apiextensions-apiserver/pkg/client/clientset/clientset",
             "github.com/prometheus/client_golang/prometheus",
             ]
 

TMP-LOGGING.md

@@ -0,0 +1,166 @@
+Logging Guidelines
+==================
+
+controller-runtime uses a kind of logging called *structured logging*. If
+you've used a library like Zap or logrus before, you'll be familiar with
+the concepts we use.  If you've only used a logging library like the "log"
+package (in the Go standard library) or "glog" (in Kubernetes), you'll
+need to adjust how you think about logging a bit.
+
+### Getting Started With Structured Logging
+
+With structured logging, we associate a *constant* log message with some
+variable key-value pairs.  For instance, suppose we wanted to log that we
+were starting reconciliation on a pod.  In the Go standard libary logger,
+we might write:
+
+```go
+log.Printf("starting reconciliation for pod %s/%s", podNamespace, podName)
+```
+
+In controller-runtime, we'd instead write:
+
+```go
+logger.Info("starting reconciliation", "pod", req.NamespacedNamed)
+```
+
+or even write
+
+```go
+func (r *Reconciler) Reconcile(req reconcile.Request) (reconcile.Response, error) {
+    logger := logger.WithValues("pod", req.NamespacedName)
+    // do some stuff
+    logger.Info("starting reconcilation")
+}
+```
+
+Notice how we've broken out the information that we want to convey into
+a constant message (`"starting reconciliation"`) and some key-value pairs
+that convey variable information (`"pod", req.NamespacedName`).  We've
+there-by added "structure" to our logs, which makes them easier to save
+and search later, as well as correlate with metrics and events.
+
+All of controller-runtime's logging is done via
+[logr](https://github.com/go-logr/logr), a generic interface for
+structured logging.  You can use whichever logging library you want to
+implement the actual mechanics of the logging.  controller-runtime
+provides some helpers to make it easy to use
+[Zap](https://go.uber.org/zap) as the implementation.
+
+You can configure the logging implementation using
+`"sigs.k8s.io/controller-runtime/pkg/runtime/log".SetLogger`.  That
+package also contains the convinience functions for setting up Zap.
+
+You can get a handle to the the "root" logger using
+`"sigs.k8s.io/controller-runtime/pkg/runtime/log".Log`, and can then call
+`WithName` to create individual named loggers.  You can call `WithName`
+repeatedly to chain names together:
+
+```go
+logger := log.Log.WithName("controller").WithName("replicaset")
+// in reconile...
+logger = logger.WithValues("replicaset", req.NamespacedName)
+// later on in reconcile...
+logger.Info("doing things with pods", "pod", newPod)
+```
+
+As seen above, you can also call `WithValue` to create a new sub-logger
+that always attaches some key-value pairs to a logger.
+
+Finally, you can use `V(1)` to mark a particular log line as "debug" logs:
+
+```go
+logger.V(1).Info("this is particularly verbose!", "state of the world",
+allKubernetesObjectsEverywhere)
+```
+
+While it's possible to use higher log levels, it's reccomended that you
+stick with `V(1)` or V(0)` (which is equivalent to not specifying `V`),
+and then filter later based on key-value pairs or messages; different
+numbers tend to lose meaning easily over time, and you'll be left
+wondering why particular logs lines are at `V(5)` instead of `V(7)`.
+
+## Logging errors
+
+Errors should *always* be logged with `log.Error`, which allows logr
+implementations to provide special handling of errors (for instance,
+providing stack traces in debug mode).
+
+It's acceptible to log call `log.Error` with a nil error object.  This
+conveys that an error occurred in some capacity, but that no actual
+`error` object was involved.
+
+## Logging messages
+
+- Don't put variable content in your messages -- use key-value pairs for
+  that. Never use `fmt.Sprintf` in your message.
+
+- Try to match the terminology in your messages with your key-value pairs
+  -- for instance, if you have a key-value pairs `api version`, use the
+  term `APIVersion` instead of `GroupVersion` in your message.
+
+## Logging Kubernetes Objects
+
+Kubernetes objects should be logged directly, like `log.Info("this is
+a Kubernetes object", "pod", somePod)`.  controller-runtime provides
+a special encoder for Zap that will transform Kubernetes objects into
+`name, namespace, apiVersion, kind` objects, when available and not in
+development mode.  Other logr implementations should implement similar
+logic.
+
+## Logging Structured Values (Key-Value pairs)
+
+- Use lower-case, space separated keys.  For example `object` for objects,
+  `api version` for `APIVersion`
+
+- Be consistent across your application, and with controller-runtime when
+  possible.
+
+- Try to be brief but descriptive.
+
+- Match terminology in keys with terminology in the message.
+
+- Be careful logging non-Kubernetes objects verbatim if they're very
+  large.
+
+### Groups, Versions, and Kinds
+
+- Kinds should not be logged alone (they're meanless alone).  Use
+  a `GroupKind` object to log them instead, or a `GroupVersionKind` when
+  version is relevant.
+
+- If you need to log an API version string, use `api version` as the key
+  (formatted as with a `GroupVersion`, or as recieved directly from API
+  discovery).
+
+### Objects and Types
+
+- If code works with a generic Kubernetes `runtime.Object`, use the
+  `object` key.  For specific objects, prefer the resource name as the key
+  (e.g. `pod` for `v1.Pod` objects).
+
+- For non-Kubernetes objects, the `object` key may also be used, if you
+  accept a generic interface.
+
+- When logging a raw type, log it using the `type` key, with a value of
+  `fmt.Sprintf("%T", typ)`
+
+- If there's specific context around a type, the key may be more specific,
+  but should end with `type` -- for instance, `OwnerType` should be logged
+  as `owner` in the context of `log.Error(err, "Could not get ObjectKinds
+  for OwnerType", `owner type`, fmt.Sprintf("%T"))`.  When possible, favor
+  communicating kind instead.
+
+### Multiple things
+
+- When logging multiple things, simply pluralize the key.
+
+### controller-runtime Specifics
+
+- Reconcile requests should be logged as `request`, although normal code
+  should favor logging the key.
+
+- Reconcile keys should be logged as with the same key as if you were
+  logging the object directly (e.g. `log.Info("reconciling pod", "pod",
+  req.NamespacedName)`).  This ends up having a similar effect to logging
+  the object directly.

pkg/client/fake/client.go

@@ -59,7 +59,7 @@ func NewFakeClientWithScheme(clientScheme *runtime.Scheme, initObjs ...runtime.O
 	for _, obj := range initObjs {
 		err := tracker.Add(obj)
 		if err != nil {
-			log.Error(err, "failed to add object", "object", obj)
+			log.Error(err, "failed to add object to fake client", "object", obj)
 			os.Exit(1)
 			return nil
 		}

pkg/handler/enqueue.go

@@ -36,7 +36,7 @@ type EnqueueRequestForObject struct{}
 // Create implements EventHandler
 func (e *EnqueueRequestForObject) Create(evt event.CreateEvent, q workqueue.RateLimitingInterface) {
 	if evt.Meta == nil {
-		enqueueLog.Error(nil, "CreateEvent received with no metadata", "CreateEvent", evt)
+		enqueueLog.Error(nil, "CreateEvent received with no metadata", "event", evt)
 		return
 	}
 	q.Add(reconcile.Request{NamespacedName: types.NamespacedName{
@@ -53,7 +53,7 @@ func (e *EnqueueRequestForObject) Update(evt event.UpdateEvent, q workqueue.Rate
 			Namespace: evt.MetaOld.GetNamespace(),
 		}})
 	} else {
-		enqueueLog.Error(nil, "UpdateEvent received with no old metadata", "UpdateEvent", evt)
+		enqueueLog.Error(nil, "UpdateEvent received with no old metadata", "event", evt)
 	}
 
 	if evt.MetaNew != nil {
@@ -62,14 +62,14 @@ func (e *EnqueueRequestForObject) Update(evt event.UpdateEvent, q workqueue.Rate
 			Namespace: evt.MetaNew.GetNamespace(),
 		}})
 	} else {
-		enqueueLog.Error(nil, "UpdateEvent received with no new metadata", "UpdateEvent", evt)
+		enqueueLog.Error(nil, "UpdateEvent received with no new metadata", "event", evt)
 	}
 }
 
 // Delete implements EventHandler
 func (e *EnqueueRequestForObject) Delete(evt event.DeleteEvent, q workqueue.RateLimitingInterface) {
 	if evt.Meta == nil {
-		enqueueLog.Error(nil, "DeleteEvent received with no metadata", "DeleteEvent", evt)
+		enqueueLog.Error(nil, "DeleteEvent received with no metadata", "event", evt)
 		return
 	}
 	q.Add(reconcile.Request{NamespacedName: types.NamespacedName{
@@ -81,7 +81,7 @@ func (e *EnqueueRequestForObject) Delete(evt event.DeleteEvent, q workqueue.Rate
 // Generic implements EventHandler
 func (e *EnqueueRequestForObject) Generic(evt event.GenericEvent, q workqueue.RateLimitingInterface) {
 	if evt.Meta == nil {
-		enqueueLog.Error(nil, "GenericEvent received with no metadata", "GenericEvent", evt)
+		enqueueLog.Error(nil, "GenericEvent received with no metadata", "event", evt)
 		return
 	}
 	q.Add(reconcile.Request{NamespacedName: types.NamespacedName{

pkg/handler/enqueue_owner.go

@@ -90,13 +90,13 @@ func (e *EnqueueRequestForOwner) parseOwnerTypeGroupKind(scheme *runtime.Scheme)
 	// Get the kinds of the type
 	kinds, _, err := scheme.ObjectKinds(e.OwnerType)
 	if err != nil {
-		log.Error(err, "Could not get ObjectKinds for OwnerType", "OwnerType", e.OwnerType)
+		log.Error(err, "Could not get ObjectKinds for OwnerType", "owner type", fmt.Sprintf("%T", e.OwnerType))
 		return err
 	}
 	// Expect only 1 kind.  If there is more than one kind this is probably an edge case such as ListOptions.
 	if len(kinds) != 1 {
 		err := fmt.Errorf("Expected exactly 1 kind for OwnerType %T, but found %s kinds", e.OwnerType, kinds)
-		log.Error(err, "", "OwnerType", e.OwnerType, "Kinds", kinds)
+		log.Error(nil, "Expected exactly 1 kind for OwnerType", "owner type", fmt.Sprintf("%T", e.OwnerType), "kinds", kinds)
 		return err
 
 	}
@@ -115,8 +115,8 @@ func (e *EnqueueRequestForOwner) getOwnerReconcileRequest(object metav1.Object)
 		// Parse the Group out of the OwnerReference to compare it to what was parsed out of the requested OwnerType
 		refGV, err := schema.ParseGroupVersion(ref.APIVersion)
 		if err != nil {
-			log.Error(err, "Could not parse OwnerReference GroupVersion",
-				"OwnerReference", ref.APIVersion)
+			log.Error(err, "Could not parse OwnerReference APIVersion",
+				"api version", ref.APIVersion)
 			return nil
 		}
 

pkg/internal/admission/http.go

@@ -42,7 +42,7 @@ func (h httpHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) {
 	// verify the content type is accurate
 	contentType := r.Header.Get("Content-Type")
 	if contentType != "application/json" {
-		log.Error(nil, "invalid content type, expected application/json", "context type", contentType)
+		log.Error(nil, "invalid content type, expected application/json", "content type", contentType)
 		return
 	}
 

pkg/internal/controller/controller.go

@@ -118,7 +118,7 @@ func (c *Controller) Watch(src source.Source, evthdler handler.EventHandler, prc
 		}
 	}
 
-	log.Info("Starting EventSource", "Controller", c.Name, "Source", src)
+	log.Info("Starting EventSource", "controller", c.Name, "source", src)
 	return src.Start(evthdler, c.Queue, prct...)
 }
 
@@ -131,7 +131,7 @@ func (c *Controller) Start(stop <-chan struct{}) error {
 	defer c.Queue.ShutDown()
 
 	// Start the SharedIndexInformer factories to begin populating the SharedIndexInformer caches
-	log.Info("Starting Controller", "Controller", c.Name)
+	log.Info("Starting Controller", "controller", c.Name)
 
 	// Wait for the caches to be synced before starting workers
 	if c.WaitForCacheSync == nil {
@@ -141,7 +141,7 @@ func (c *Controller) Start(stop <-chan struct{}) error {
 		// This code is unreachable right now since WaitForCacheSync will never return an error
 		// Leaving it here because that could happen in the future
 		err := fmt.Errorf("failed to wait for %s caches to sync", c.Name)
-		log.Error(err, "Could not wait for Cache to sync", "Controller", c.Name)
+		log.Error(err, "Could not wait for Cache to sync", "controller", c.Name)
 		c.mu.Unlock()
 		return err
 	}
@@ -151,7 +151,7 @@ func (c *Controller) Start(stop <-chan struct{}) error {
 	}
 
 	// Launch workers to process resources
-	log.Info("Starting workers", "Controller", c.Name, "WorkerCount", c.MaxConcurrentReconciles)
+	log.Info("Starting workers", "controller", c.Name, "worker count", c.MaxConcurrentReconciles)
 	for i := 0; i < c.MaxConcurrentReconciles; i++ {
 		// Process work items
 		go wait.Until(func() {
@@ -164,7 +164,7 @@ func (c *Controller) Start(stop <-chan struct{}) error {
 	c.mu.Unlock()
 
 	<-stop
-	log.Info("Stopping workers", "Controller", c.Name)
+	log.Info("Stopping workers", "controller", c.Name)
 	return nil
 }
 
@@ -203,7 +203,7 @@ func (c *Controller) processNextWorkItem() bool {
 		// process a work item that is invalid.
 		c.Queue.Forget(obj)
 		log.Error(nil, "Queue item was not a Request",
-			"Controller", c.Name, "Type", fmt.Sprintf("%T", obj), "Value", obj)
+			"controller", c.Name, "type", fmt.Sprintf("%T", obj), "value", obj)
 		// Return true, don't take a break
 		return true
 	}
@@ -212,7 +212,7 @@ func (c *Controller) processNextWorkItem() bool {
 	// resource to be synced.
 	if result, err := c.Do.Reconcile(req); err != nil {
 		c.Queue.AddRateLimited(req)
-		log.Error(err, "Reconciler error", "Controller", c.Name, "Request", req)
+		log.Error(err, "Reconciler error", "controller", c.Name, "request", req)
 		ctrlmetrics.ReconcileErrors.WithLabelValues(c.Name).Inc()
 
 		return false
@@ -229,7 +229,7 @@ func (c *Controller) processNextWorkItem() bool {
 	c.Queue.Forget(obj)
 
 	// TODO(directxman12): What does 1 mean?  Do we want level constants?  Do we want levels at all?
-	log.V(1).Info("Successfully Reconciled", "Controller", c.Name, "Request", req)
+	log.V(1).Info("Successfully Reconciled", "controller", c.Name, "request", req)
 
 	// Return true, don't take a break
 	return true

pkg/predicate/predicate.go

@@ -96,19 +96,19 @@ type ResourceVersionChangedPredicate struct {
 // Update implements default UpdateEvent filter for validating resource version change
 func (ResourceVersionChangedPredicate) Update(e event.UpdateEvent) bool {
 	if e.MetaOld == nil {
-		log.Error(nil, "UpdateEvent has no old metadata", "UpdateEvent", e)
+		log.Error(nil, "UpdateEvent has no old metadata", "event", e)
 		return false
 	}
 	if e.ObjectOld == nil {
-		log.Error(nil, "GenericEvent has no old runtime object to update", "GenericEvent", e)
+		log.Error(nil, "GenericEvent has no old runtime object to update", "event", e)
 		return false
 	}
 	if e.ObjectNew == nil {
-		log.Error(nil, "GenericEvent has no new runtime object for update", "GenericEvent", e)
+		log.Error(nil, "GenericEvent has no new runtime object for update", "event", e)
 		return false
 	}
 	if e.MetaNew == nil {
-		log.Error(nil, "UpdateEvent has no new metadata", "UpdateEvent", e)
+		log.Error(nil, "UpdateEvent has no new metadata", "event", e)
 		return false
 	}
 	if e.MetaNew.GetResourceVersion() == e.MetaOld.GetResourceVersion() {